こんにちは、山下です。
ログにリクエスト単位のIDが設定されていると、不具合発生時にリクエストID単位でログをフィルタリングできるので調査に役立ちますよね！ AWS Lambda+Node.jsで上記を実現する方法を検討したので共有します。
この記事の内容は以前検証した以下の記事が元になっています。一読いただけると大変嬉しいです。（実はこの記事を書くため検証した内容だったりします。）
AWS Lambda+Node.jsのコンテナ並列起動（同期・非同期）・コンテナ再利用の動作検証 | グランドリーム
検証コードはGitHubにUPしておきましたので、ご自由にお試しください。
nori3tsu/lambda-logger-example
Node.jsでリクエスト単位にIDを設定することの難しさ
例えばRailsの場合、以下のような処理を組み込むことで、リクエスト単位に任意の情報をタグ付けすることができます。
# config/application.rb
# config.logger = ActiveSupport::TaggedLogging.new(Logger.new(STDOUT))
Rails.logger.tagged('BCX') { logger.info 'Stuff' } # Logs "[BCX] Stuff"
Rails.logger.tagged('BCX', "Jason") { logger.info 'Stuff' } # Logs "[BCX] [Jason] Stuff"
Rails.logger.tagged('BCX') { logger.tagged('Jason') { logger.info 'Stuff' } } # Logs "[BCX] [Jason] Stuff"
参考: ActiveSupport::TaggedLogging
Rails.loggerはクラスインスタンスアクセスですが、Railsではリクエスト中に1スレッドを占有しているため、スレッドID単位(Thread Context)に情報を保存しておけばリクエスト中同じ情報を参照することができます。
一方、Node.jsはシングルスレッドのためThread Contextはグローバルオブジェクトと同義であり、リクエスト中にも非同期処理のたびに複数のリクエスト間でコンテキストが切り替わるため、同じことを実現しようとするとなかなか難しいです。
Node.jsのAsync Hooksを使った解決策
解決策として、Node.jsの機能であるAsync Hooksを利用する方法があります。
引用: Async Hooksを使ってリクエストごとに一意なIDをログに出力する | Developers.IO
Async Hooksとは、非同期処理のライフサイクルにフックを仕掛ける機能のことです。非同期処理が実行されると、非同期リソースというリソースが生成されます。ライフサイクルはその非同期リソースのイベントで、init（初期化時）, before（コールバック実行前）, after（コールバック実行後）, destroy（破棄後）の4つがあります。この4つのイベントで任意のコードを実行することができます。また非同期リソースには、自身のIDと、呼び出し元の非同期リソースのIDがセットされています。また、本記事では取り扱いませんが、Embedder APIを用いることで、ライフサイクルイベントを任意のタイミングで実行することもできます。
Async Hooksを利用して、呼び出し元の非同期リソースIDを元にコンテキストを切り替え続けることで、リクエスト中に同じ情報を参照することができます。
先ほどのクラスメソッドさんの記事を読んでいただければわかりますが、少し複雑な実装が必要です。
Expressのライブラリexpress-http-contextではこの処理を抽象化したcls-hookedを利用しています。とてもシンプルな実装になっているので読んでみましょう。
引用: express-http-context/index.js at master · skonves/express-http-context
'use strict';
const cls = require('cls-hooked');
const nsid = 'a6a29a6f-6747-4b5f-b99f-07ee96e32f88';
const ns = cls.createNamespace(nsid);
// 1. リクエスト単位でclass-hookedのNamespaceに非同期IDを保存する
function middleware(req, res, next) {
ns.run(() => next());
}
// 2. 非同期IDを元にデータを設定
// ※ ns.run してない場合は ns.active が falseになる
function set(key, value) {
if (ns && ns.active) {
return ns.set(key, value);
}
}
// 2. 非同期IDを元にデータを取得
// ※ ns.run してない場合は ns.active が falseになる
function get(key) {
if (ns && ns.active) {
return ns.get(key);
}
}
module.exports = {
middleware,
get: get,
set: set,
ns: ns
};
Expressのmiddlewareに(1)を設定することで、リクエスト前に非同期IDが保存され、リクエスト単位に情報を保存できるようになっていますね。
AWS Lambda+Node.jsの実装
それでは、AWS Lambda+Node.jsで実装していきましょう。実装を先にお見せします。
Logger実装:
import _ from 'lodash';
import pino from 'pino';
const _loggers = [pino({ level: process.env.LOG_LEVEL })];
const getLoggers = () => {
return _loggers;
};
export const tagged = async (tags: Record, func: () => T) => {
const loggers = getLoggers();
try {
loggers.push(currentLogger().child(tags));
return await func();
} finally {
loggers.pop();
}
};
const currentLogger = (): pino.Logger => {
return _.last(getLoggers())!;
};
export const logger = currentLogger;
お気づきになられたでしょうか。。Async Hooksもcls-hookedも使ってないですね。
実はLambdaは1実行で1プロセスを占有するため、Node.js単体で必要なAsync Hooksなどを利用したコンテキスト分離の考え方は不要で、グローバルオブジェクトを利用するだけで実現できるんですね。
以下の記事で詳細に検証していますので、是非ご覧ください。
AWS Lambda+Node.jsのコンテナ並列起動（同期・非同期）・コンテナ再利用の動作検証 | グランドリーム
AWS Lambdaにデプロイして試す
では、GitHubにUPしているサンプルコードで、実際にLambdaをデプロイして試してみましょう。
nori3tsu/lambda-logger-example
以下、Lambdaハンドラーの実装を抜粋します。
import { APIGatewayProxyHandler } from 'aws-lambda';
import 'source-map-support/register';
import { tagged, logger } from './logger';
import * as uuid from 'uuid';
export const hello: APIGatewayProxyHandler = async (_event, _context) => {
return tagged({id: uuid.v4()}, async () => {
logger().info('hello')
await new Promise((resolve) => setTimeout(resolve, 1000))
logger().info('world!')
return {
statusCode: 200,
body: JSON.stringify({}, null, 2),
};
})
}
コード一式をAWSにデプロイします。
$ git clone git@github.com:nori3tsu/lambda-logger-example.git
$ cd lambda-logger-example
$ sls deploy
service: lambda-logger-example
stage: dev
region: us-east-1
stack: lambda-logger-example-dev
resources: 11
api keys:
None
endpoints:
GET - https://3cv4g9cnwb.execute-api.us-east-1.amazonaws.com/dev/hello
functions:
hello: lambda-logger-example-dev-hello
layers:
None
Serverless: Run the "serverless" command to setup monitoring, troubleshooting and testing.
作成されたエンドポイントにリクエストを投げます。
$ curl -i https://3cv4g9cnwb.execute-api.us-east-1.amazonaws.com/dev/hello
HTTP/2 200
content-type: application/json
content-length: 2
date: Sat, 12 Sep 2020 01:18:01 GMT
x-amzn-requestid: 23e8a16b-b874-428c-a8e6-8fa1b612dba7
x-amz-apigw-id: Suo3aGxBoAMFQGw=
x-amzn-trace-id: Root=1-5f5c21c8-071def3b52042a20ab7e6eed;Sampled=0
x-cache: Miss from cloudfront
via: 1.1 d653c211343f4b2370c41baf3b65bed6.cloudfront.net (CloudFront)
x-amz-cf-pop: NRT57-C2
x-amz-cf-id: BPC2MrRuiv1dn215G2s27cVWSVqAGSUHRPP5wvl-vZ7IMO9bzbdpVQ==
{}
ログを確認するとリクエストIDが設定されていることがわかりますね！
{
"level": 30,
"time": 1599873480974,
"pid": 7,
"hostname": "169.254.56.141",
"id": "76b0e625-4a86-4f42-af4e-ded47ea11adb",
"msg": "hello"
}
{
"level": 30,
"time": 1599873481974,
"pid": 7,
"hostname": "169.254.56.141",
"id": "76b0e625-4a86-4f42-af4e-ded47ea11adb",
"msg": "world!"
}
おわりに
Node.jsでリクエスト単位にIDを設定する方法とAWS Lambdaのプロセス構造を整理した上で、AWS+Node.jsでリクエスト単位でログを記録する方法を検討・実装しました。
このコードはまだ本番にUPしてないので実験段階ですが、万が一、前提条件のLambdaのプロセス構造の理解が誤っていた場合でも、Async Hooksを利用した方法に切り替えれば同様のことを実現することができます。
皆さんも是非試してみてください。
こんにちは、山下です。
ログにリクエスト単位のIDが設定されていると、不具合発生時にリクエストID単位でログをフィルタリングできるので調査に役立ちますよね！ AWS Lambda+Node.jsで上記を実現する方法を検討したので共有します。
この記事の内容は以前検証した以下の記事が元になっています。一読いただけると大変嬉しいです。（実はこの記事を書くため検証した内容だったりします。）
AWS Lambda+Node.jsのコンテナ並列起動（同期・非同期）・コンテナ再利用の動作検証 | グランドリーム
検証コードはGitHubにUPしておきましたので、ご自由にお試しください。
nori3tsu/lambda-logger-example
Node.jsでリクエスト単位にIDを設定することの難しさ
例えばRailsの場合、以下のような処理を組み込むことで、リクエスト単位に任意の情報をタグ付けすることができます。
# config/application.rb
# config.logger = ActiveSupport::TaggedLogging.new(Logger.new(STDOUT))
Rails.logger.tagged('BCX') { logger.info 'Stuff' } # Logs "[BCX] Stuff"
Rails.logger.tagged('BCX', "Jason") { logger.info 'Stuff' } # Logs "[BCX] [Jason] Stuff"
Rails.logger.tagged('BCX') { logger.tagged('Jason') { logger.info 'Stuff' } } # Logs "[BCX] [Jason] Stuff"
参考: ActiveSupport::TaggedLogging
Rails.loggerはクラスインスタンスアクセスですが、Railsではリクエスト中に1スレッドを占有しているため、スレッドID単位(Thread Context)に情報を保存しておけばリクエスト中同じ情報を参照することができます。
一方、Node.jsはシングルスレッドのためThread Contextはグローバルオブジェクトと同義であり、リクエスト中にも非同期処理のたびに複数のリクエスト間でコンテキストが切り替わるため、同じことを実現しようとするとなかなか難しいです。
Node.jsのAsync Hooksを使った解決策
解決策として、Node.jsの機能であるAsync Hooksを利用する方法があります。
引用: Async Hooksを使ってリクエストごとに一意なIDをログに出力する | Developers.IO
Async Hooksとは、非同期処理のライフサイクルにフックを仕掛ける機能のことです。非同期処理が実行されると、非同期リソースというリソースが生成されます。ライフサイクルはその非同期リソースのイベントで、init（初期化時）, before（コールバック実行前）, after（コールバック実行後）, destroy（破棄後）の4つがあります。この4つのイベントで任意のコードを実行することができます。また非同期リソースには、自身のIDと、呼び出し元の非同期リソースのIDがセットされています。また、本記事では取り扱いませんが、Embedder APIを用いることで、ライフサイクルイベントを任意のタイミングで実行することもできます。
Async Hooksを利用して、呼び出し元の非同期リソースIDを元にコンテキストを切り替え続けることで、リクエスト中に同じ情報を参照することができます。
先ほどのクラスメソッドさんの記事を読んでいただければわかりますが、少し複雑な実装が必要です。
Expressのライブラリexpress-http-contextではこの処理を抽象化したcls-hookedを利用しています。とてもシンプルな実装になっているので読んでみましょう。
引用: express-http-context/index.js at master · skonves/express-http-context
'use strict';
const cls = require('cls-hooked');
const nsid = 'a6a29a6f-6747-4b5f-b99f-07ee96e32f88';
const ns = cls.createNamespace(nsid);
// 1. リクエスト単位でclass-hookedのNamespaceに非同期IDを保存する
function middleware(req, res, next) {
ns.run(() => next());
}
// 2. 非同期IDを元にデータを設定
// ※ ns.run してない場合は ns.active が falseになる
function set(key, value) {
if (ns && ns.active) {
return ns.set(key, value);
}
}
// 2. 非同期IDを元にデータを取得
// ※ ns.run してない場合は ns.active が falseになる
function get(key) {
if (ns && ns.active) {
return ns.get(key);
}
}
module.exports = {
middleware,
get: get,
set: set,
ns: ns
};
Expressのmiddlewareに(1)を設定することで、リクエスト前に非同期IDが保存され、リクエスト単位に情報を保存できるようになっていますね。
AWS Lambda+Node.jsの実装
それでは、AWS Lambda+Node.jsで実装していきましょう。実装を先にお見せします。
Logger実装:
import _ from 'lodash';
import pino from 'pino';
const _loggers = [pino({ level: process.env.LOG_LEVEL })];
const getLoggers = () => {
return _loggers;
};
export const tagged = async (tags: Record, func: () => T) => {
const loggers = getLoggers();
try {
loggers.push(currentLogger().child(tags));
return await func();
} finally {
loggers.pop();
}
};
const currentLogger = (): pino.Logger => {
return _.last(getLoggers())!;
};
export const logger = currentLogger;
お気づきになられたでしょうか。。Async Hooksもcls-hookedも使ってないですね。
実はLambdaは1実行で1プロセスを占有するため、Node.js単体で必要なAsync Hooksなどを利用したコンテキスト分離の考え方は不要で、グローバルオブジェクトを利用するだけで実現できるんですね。
以下の記事で詳細に検証していますので、是非ご覧ください。
AWS Lambda+Node.jsのコンテナ並列起動（同期・非同期）・コンテナ再利用の動作検証 | グランドリーム
AWS Lambdaにデプロイして試す
では、GitHubにUPしているサンプルコードで、実際にLambdaをデプロイして試してみましょう。
nori3tsu/lambda-logger-example
以下、Lambdaハンドラーの実装を抜粋します。
import { APIGatewayProxyHandler } from 'aws-lambda';
import 'source-map-support/register';
import { tagged, logger } from './logger';
import * as uuid from 'uuid';
export const hello: APIGatewayProxyHandler = async (_event, _context) => {
return tagged({id: uuid.v4()}, async () => {
logger().info('hello')
await new Promise((resolve) => setTimeout(resolve, 1000))
logger().info('world!')
return {
statusCode: 200,
body: JSON.stringify({}, null, 2),
};
})
}
コード一式をAWSにデプロイします。
$ git clone git@github.com:nori3tsu/lambda-logger-example.git
$ cd lambda-logger-example
$ sls deploy
service: lambda-logger-example
stage: dev
region: us-east-1
stack: lambda-logger-example-dev
resources: 11
api keys:
None
endpoints:
GET - https://3cv4g9cnwb.execute-api.us-east-1.amazonaws.com/dev/hello
functions:
hello: lambda-logger-example-dev-hello
layers:
None
Serverless: Run the "serverless" command to setup monitoring, troubleshooting and testing.
作成されたエンドポイントにリクエストを投げます。
$ curl -i https://3cv4g9cnwb.execute-api.us-east-1.amazonaws.com/dev/hello
HTTP/2 200
content-type: application/json
content-length: 2
date: Sat, 12 Sep 2020 01:18:01 GMT
x-amzn-requestid: 23e8a16b-b874-428c-a8e6-8fa1b612dba7
x-amz-apigw-id: Suo3aGxBoAMFQGw=
x-amzn-trace-id: Root=1-5f5c21c8-071def3b52042a20ab7e6eed;Sampled=0
x-cache: Miss from cloudfront
via: 1.1 d653c211343f4b2370c41baf3b65bed6.cloudfront.net (CloudFront)
x-amz-cf-pop: NRT57-C2
x-amz-cf-id: BPC2MrRuiv1dn215G2s27cVWSVqAGSUHRPP5wvl-vZ7IMO9bzbdpVQ==
{}
ログを確認するとリクエストIDが設定されていることがわかりますね！
{
"level": 30,
"time": 1599873480974,
"pid": 7,
"hostname": "169.254.56.141",
"id": "76b0e625-4a86-4f42-af4e-ded47ea11adb",
"msg": "hello"
}
{
"level": 30,
"time": 1599873481974,
"pid": 7,
"hostname": "169.254.56.141",
"id": "76b0e625-4a86-4f42-af4e-ded47ea11adb",
"msg": "world!"
}
おわりに
Node.jsでリクエスト単位にIDを設定する方法とAWS Lambdaのプロセス構造を整理した上で、AWS+Node.jsでリクエスト単位でログを記録する方法を検討・実装しました。
このコードはまだ本番にUPしてないので実験段階ですが、万が一、前提条件のLambdaのプロセス構造の理解が誤っていた場合でも、Async Hooksを利用した方法に切り替えれば同様のことを実現することができます。
皆さんも是非試してみてください。
