Lambdaのログ出力にオススメしたいNode.jsのライブラリ DAZN Lambda Powertools

DAZN Lambda PowertoolsでNode.js製Lambdaのログ出力をラクチンに

#Node.js

#サーバーレス

#AWS Lambda

#AWS

岩田智哉

2020.01.07

この記事は公開されてから1年以上経過しています。情報が古い可能性がありますので、ご注意ください。

CX事業本部@大阪の岩田です。

先日のブログでPythonのライブラリLambda Powertoolsについてご紹介しました。今日はNode.jsのLambda向けに色々な便利機能を提供してくれるDAZN Lambda Powertoolsについてご紹介します。

環境

今回利用した環境です

ランタイム: Node.js 12.x
dazn-lambda-powertools-layer: 1.15.6

DAZN Lambda Powertoolsとは？

Node.jsで利用できるAWS Lambda用のミドルウェアを集めたライブラリです。GitHubのリポジトリはこちらです。

https://github.com/getndazn/dazn-lambda-powertools

概要についてはREADMEに貼られている以下の画像を見て頂くのが分かり良いですが、

構造化ログ(JSONログ)の出力
複数のLambdaを横断的につなげるためのIDの付与、パース
ログのサンプリング
タイムアウトのログ出力

といった機能を持っています。

Lambdaを使ってシステムを構築すると、自然とマイクロサービスなアーキテクチャに寄っていきます。マイクロサービスなアーキテクチャでは1つの機能に対して複数のLambdaが起動することが多く、複数のLambdaのログを横断的につなぐために、リクエストIDのような項目をログに残しておかないと、有事の調査が難しくなります。DAZN Lambda Powertoolsを利用すると、複数Lambda間で自動的にx-correlation-idという属性値を取り回してくれるようになり、開発者はビジネスロジックの実装に集中できるようになります。

やってみる

実際にやってみましょう。DAZN Lambda PowertoolsはSAR(AWS Serverless Application Repository)で公開されているので、まずは以下のリンクからデプロイしてしまいましょう。

DAZN Lambda Powertools

デプロイが完了するとNode.js8.10とNode.js 10.xと互換性のあるLambdaレイヤーが作成されます。記事執筆時点では「互換性のあるランタイム」にNode.js 12.xが設定されていませんでしたが、今回試した範囲ではNode.js 12.xでも問題なく正常に動作していました。

ログの出力

これでDAZN Lambda Powertoolsを利用する準備が整いました。簡単にログの出力を試してみましょう。

普通にログを出力する

まずは普通のログ出力からです。以下のコードを実行します。

const Log = require('@dazn/lambda-powertools-logger')

exports.handler = async (event) => {
  
    Log.info('Hello from Lambda');
    
    // TODO implement
    const response = {
        statusCode: 200,
        body: JSON.stringify('Hello from Lambda!'),
    };
    return response;
};

上記のコード実行後にCloudWatch Logsに出力されたログです。

2020-01-06T05:45:16.955Z	44a1424e-051e-4d2c-bfbb-5740a1940b4c	INFO	
{
    "message": "Hello from Lambda",
    "awsRegion": "ap-northeast-1",
    "functionName": "lambda-powertools-nodejs",
    "functionVersion": "$LATEST",
    "functionMemorySize": "128",
    "level": 30,
    "sLevel": "INFO"
}

functionVersion等の項目が自動的に付与されつつ、JSON形式でログが出力されています。

ログに出力する項目を追加する

今度は自分で項目を追加してみましょう。ログ出力メソッドの第2引数にオブジェクトを渡すことで出力項目を追加できます。

Log.info('Hello from Lambda', {attr1: 'val1', attr2: 'val2'});

CloudWatch Logsに出力されたログです。

2020-01-06T05:46:02.771Z	efe26c8b-007c-42c3-9a95-09752f81cd60	INFO	
{
    "message": "Hello from Lambda",
    "attr1": "val1",
    "attr2": "val2",
    "awsRegion": "ap-northeast-1",
    "functionName": "lambda-powertools-nodejs",
    "functionVersion": "$LATEST",
    "functionMemorySize": "128",
    "level": 30,
    "sLevel": "INFO"
}

自分で追加したattr1,attr2がログに出力されています。

ログのメッセージにJSONを出力する

今度はログのメッセージにJSONを出力してみましょう。普通にログ出力メソッドの引数にオブジェクトを渡してやればOKです。

Log.info(event);

CloudWatch Logsに出力されたログです。

2020-01-06T05:48:01.805Z	cbc53e9b-2937-4c7a-8965-36e39716d9ed	INFO	
{
    "message": {
        "key1": "value1",
        "key2": "value2",
        "key3": "value3"
    },
    "awsRegion": "ap-northeast-1",
    "functionName": "lambda-powertools-nodejs",
    "functionVersion": "$LATEST",
    "functionMemorySize": "128",
    "level": 30,
    "sLevel": "INFO"
}

Lambdaのテストイベントに設定したkey1,key2,key3がログに出力されています。

例外発生時のログ出力

最後に例外発生時のログも試してみましょう。errorの第2引数にキャッチした例外のオブジェクトを渡してやります。

try {
	throw new Error('some error');
} catch (e) {
	Log.error('some error raised', e);
}

CloudWatch Logsに出力されたログです。

2020-01-06T05:49:29.250Z	b289c0ad-ab23-4da5-9492-9458746efb4a	INFO	
{
    "message": "some error raised",
    "errorName": "Error",
    "errorMessage": "some error",
    "stackTrace": "Error: some error\n    at Runtime.exports.handler (/var/task/index.js:6:12)\n    at Runtime.handleOnce (/var/runtime/Runtime.js:66:25)",
    "awsRegion": "ap-northeast-1",
    "functionName": "lambda-powertools-nodejs",
    "functionVersion": "$LATEST",
    "functionMemorySize": "128",
    "level": 50,
    "sLevel": "ERROR"
}

スタックトレース等の情報が出力されていることが分かります。

複数のLambdaを横断するログを分析する

続いてDAZN Lambda Powertoolsの特徴でもある複数のLambdaを横断するログの分析を試してみます。こんな感じのシステムをシミュレーションしてみます。

Lambda1がLambda2を非同期呼び出し
Lambda2がDynamoDBに書き込み
DynamoDBストリームからLambda3が起動する

この一連の流れを横断的に分析してみます。

まずLambda1のソースコードです

const Lambda = require('@dazn/lambda-powertools-lambda-client');
const Log = require('@dazn/lambda-powertools-logger');
const wrap = require('@dazn/lambda-powertools-pattern-basic');

exports.handler = wrap(async (event, context) => {

    Log.info('start lambda 1');
    const invokeAsyncReq = {
        FunctionName: 'dazn-lambda-powertools-2',
        InvokeArgs: JSON.stringify({ message: 'hello lambda' })
    }

    await Lambda.invokeAsync(invokeAsyncReq).promise()
});

ポイントが2つあります。

まずhandlerの処理を@dazn/lambda-powertools-pattern-basicから読み込んだモジュールでwrapします。 @dazn/lambda-powertools-pattern-basicというパッケージに「よくある処理」のセットが事前に用意されています。このパッケージからexportされている処理でLambdaのhandlerをwrapすることで、複数のLambda間で情報を受け渡すための諸々の処理が自動で付与されます。

次に普通のAWS SDKのクライアントではなく、@dazn/lambda-powertools-lambda-clientから読み込んだLambdaのクライアントを利用します。 @dazn/lambda-powertools-lambda-clientはAWS SDKのLambdaクライアントのラッパーとして振る舞い、eventデータに複数のLambda間で情報を受け渡すための諸々の情報をセットしてくれます。

続いてLambda2のソースコードです。事前にDynamoDBストリームを有効化した適当なテーブルを用意しておいて下さい。この例ではIdというパーティションキーを持つdazn-lambda-powertoolsを事前に作成しています。

const DynamoDB = require('@dazn/lambda-powertools-dynamodb-client');
const Log = require('@dazn/lambda-powertools-logger');
const wrap = require('@dazn/lambda-powertools-pattern-basic')

exports.handler = wrap(async (event, context) => {

    Log.info('start lambda 2');
    await DynamoDB.put({
      TableName: 'dazn-lambda-powertools',
      Item: {
        Id: '1',
        attr1: 'some val1',
        attr2: 'some val2',
      }
    }).promise();
});

Lambda1と同様に@dazn/lambda-powertools-pattern-basicから読み込んだ処理でhandlerをwrapしつつ、DynamoDBのクライアントを@dazn/lambda-powertools-dynamodb-clientに置き換えます。

最後にLambda3のソースコードです。Lambda2から書き込んだテーブルのストリームから起動するように設定して下さい。

const Log = require('@dazn/lambda-powertools-logger');
const wrap  = require('@dazn/lambda-powertools-pattern-basic')

exports.handler = wrap(async (event, context) => {

    const events = context.parsedDynamoDbEvents;
    events.forEach(evt => {
        evt.logger.info('lambda 3 process record');
    });
});

Lambda1と同様に@dazn/lambda-powertools-pattern-basicから読み込んだ処理でhandlerをwrapしつつ、context.parsedDynamoDbEventsの結果をイベントデータとして利用するのがポイントです。

準備ができたら適当なテストイベントからLambda1を実行します。実行後にDynamoDBのテーブルを確認すると、以下のようなアイテムがPutされていることが確認できます。

{
  "__context__": {
    "awsRequestId": "ad7d8292-d051-4fe0-a55e-f7c7c68a481b",
    "call-chain-length": 2,
    "debug-log-enabled": "false",
    "x-correlation-id": "c6f5143c-297e-4662-8a68-9b38dc64e8d5"
  },
  "attr1": "some val1",
  "attr2": "some val2",
  "Id": "1"
}

__context__という属性にDAZN Lambda Powertoolsが利用する諸々の属性が入っていることが分かります。

DynamoDBのアイテムから確認できたx-correlation-idを指定し、CloudWatch Logs Insightsから以下のクエリを実行してみましょう。

fields @timestamp, `x-correlation-id`, `awsRequestId`, `call-chain-length`,`message`
| filter `x-correlation-id` = "<DynamoDBに登録されていたx-correlation-id>"
| sort `call-chain-length`

関連する３つのLambdaのログをまとめて抽出できました！！

まとめ

DAZN Lambda Powertoolsの紹介でした。DAZN Lambda Powertoolsは今回紹介していない機能以外にもDataDogとの連携を容易にするための機能や、機密情報をログに出力しないようにマスクする機能など、様々な機能を兼ね備えています。皆さんも一度試してみてはいかがでしょうか？