この記事はAWS LambdaとServerless #1 Advent Calendar 2019
の21日目の記事です。
はじめに
API Gatewayと組み合わせてのAPIサービング、SQSトリガーからのジョブ、DynamoDBの更新をフックにした処理など、いろいろな活躍をしてくれるLambdaですが、API Gatewayからのレスポンスが返ってこないな、テストが終わらない？、という状況になったことはありませんか?
今回は私が開発中に出会った、いろんな意味でLambdaやLambdaを使った処理が終了していない、終了していないように見えるパターンについて紹介します。
- Postgresへの接続
- Postgresへ接続したFunctionのテスト
- DynamoDBトリガーのLambdaでの例外によるリトライ
Serverless FrameworkでNode.js + TypeScriptで検証しています。
1. Postgressへの接続
サンプルコード
pgクライアントを利用してPostgresにアクセスし、selectをします。以下のようなコードです。
import { Client } from "pg";
export const connectToRDB = async (_event, context, callback) => {
const pgClient = new Client({
host: process.env.DB_HOST,
user: process.env.DB_USER,
password: process.env.DB_PASSWORD,
database: "postgres"
});
await pgClient.connect();
const res = await pgClient.query("SELECT current_timestamp");
console.info("res", res.rows);
await callback(null, {
statusCode: 200,
body: JSON.stringify({
message: JSON.stringify(res.rows)
})
});
};
エラーとログ
API Gateway接続し、APIを提供するようにしたうえでcurlでアクセスすると、しばらくレスポンスをまった後にInternal Server Errorのメッセージが返ってきます。
Lambdaがエラーになったようです。
% curl https://XXXXXXXX.execute-api.ap-northeast-1.amazonaws.com/dev/connect-to-rdb [10:39:49]
{"message": "Internal server error"}
CloudWatch LogでLambdaのログを確認します。
INFO res [ { current_timestamp: 2019-12-20T01:53:46.263Z } ]
とあるようにDBへの接続は正常に行われ、結果を取得できています。しかし以下の行が出力されています。
REPORT RequestId: 88a162b3-7b8f-4cdb-bf72-f7531ee9d29e Duration: 6006.19 ms Billed Duration: 6000 ms Memory Size: 1024 MB Max Memory Used: 75 MB Init Duration: 138.46 ms
6000msecはServerless Frameworkがデフォルトでセットするタイムアウト時間なので、処理がタイムアウトしていると考えられます。
ログ出力したselect結果は出力されていますが、Lambdaの実行が6000msecかかっており、タイムアウトしている様子です。
原因
この挙動は Node.js の AWS Lambda 関数ハンドラー のドキュメントを読むとヒントが得られます。
非同期以外の関数の場合は、イベントループが空になるか、関数がタイムアウトするまで、関数の実行が継続されます。
このうちの"イベントループが空になる"が満たせていないためにタイムアウトになっていないと考えられます。ライブラリ内部までは検証できていないのですが、Postgresとのコネクションの維持のためになんらかのイベントループが内部で起こっているのでは、と考えられます。
対策
ドキュメントにもある通り、context.callbackWaitsForEmptyEventLoop = false をセットします。
export const connectToRDB = async (_event, context, callback) => {
context.callbackWaitsForEmptyEventLoop = false; // <- ここを追加!
const pgClient = new Client({
host: process.env.DB_HOST,
user: process.env.DB_USER,
password: process.env.DB_PASSWORD,
database: "postgres"
});
await pgClient.connect();
const res = await pgClient.query("SELECT current_timestamp");
console.info("res", res.rows);
await callback(null, {
statusCode: 200,
body: JSON.stringify({
message: JSON.stringify(res.rows)
})
});
};
これで想定通りにレスポンスがかえるようになりました 
% curl https://XXXXXX.execute-api.ap-northeast-1.amazonaws.com/dev/connect-to-rdb [10:53:24]
{"message":"[{\"current_timestamp\":\"2019-12-20T01:53:46.263Z\"}]"}
実行時間も数十msecに収まっています。
2. Postgresへ接続したFunctionのテスト
(これはもはやLambdaというよりもNode.jsなのですが...)
サンプルコード
先のPostgresのケースをjestでテストします。テストケースを以下のように書きました。200ステータスが返されるのをチェックするだけのテストです。
import { connectToRDB } from "../handler";
const context = require("aws-lambda-mock-context");
const ctx = context();
beforeEach(async () => {
const currentEnv = process.env;
process.env = {
...currentEnv,
DB_HOST: "YOUR_DB_HOST",
DB_PORT: "YOUR_DB_PORT",
DB_USER: "YOUR_DB_USER",
DB_PASSWORD: "YOUR_DB_PASSWORD"
};
});
test("connectToRDB", async () => {
const callback = (error, response) => {
expect(error).toBe(null);
expect(response.statusCode).toBe(200);
};
await connectToRDB({}, ctx, callback);
});
問題
テストを実行します。テストは正常にパスするのですが、jestが実行したままcrtl + cするまで止まりません。
% npx jest [10:57:30]
ts-jest[config] (WARN) TypeScript diagnostics (customize using `[jest-config].globals.ts-jest.diagnostics` option):
message TS151001: If you have issues related to imports, you should consider setting `esModuleInterop` to `true` in your TypeScript configuration file (usually `tsconfig.json`). See https://blogs.msdn.microsoft.com/typescript/2018/01/31/announcing-typescript-2-7/#easier-ecmascript-module-interoperability for more information.
PASS __tests__/handler.ts
✓ connectToRDB (339ms)
console.info handler.ts:34
res [ { current_timestamp: 2019-12-20T01:58:07.049Z } ]
----------|----------|----------|----------|----------|-------------------|
File | % Stmts | % Branch | % Funcs | % Lines | Uncovered Line #s |
----------|----------|----------|----------|----------|-------------------|
All files | 0 | 0 | 0 | 0 | |
----------|----------|----------|----------|----------|-------------------|
Test Suites: 1 passed, 1 total
Tests: 1 passed, 1 total
Snapshots: 0 total
Time: 6.716s
Ran all test suites.
Jest did not exit one second after the test run has completed.
This usually means that there are asynchronous operations that weren't stopped in your tests. Consider running Jest with `--detectOpenHandles` to troubleshoot this issue.
原因
ログの最終行にサジェストされているとおりに --detectOpenHandles optionをつけて再度実行すると、やはりPostgresへの接続関連でイベントハンドラが残っていることがわかります。
% npx jest --detectOpenHandles [11:21:26]
ts-jest[config] (WARN) TypeScript diagnostics (customize using `[jest-config].globals.ts-jest.diagnostics` option):
message TS151001: If you have issues related to imports, you should consider setting `esModuleInterop` to `true` in your TypeScript configuration file (usually `tsconfig.json`). See https://blogs.msdn.microsoft.com/typescript/2018/01/31/announcing-typescript-2-7/#easier-ecmascript-module-interoperability for more information.
PASS __tests__/handler.ts
✓ connectToRDB (141ms)
console.info handler.ts:34
res [ { current_timestamp: 2019-12-20T02:21:33.556Z } ]
----------|----------|----------|----------|----------|-------------------|
File | % Stmts | % Branch | % Funcs | % Lines | Uncovered Line #s |
----------|----------|----------|----------|----------|-------------------|
All files | 0 | 0 | 0 | 0 | |
----------|----------|----------|----------|----------|-------------------|
Test Suites: 1 passed, 1 total
Tests: 1 passed, 1 total
Snapshots: 0 total
Time: 2.721s, estimated 5s
Ran all test suites.
Jest has detected the following 1 open handle potentially keeping Jest from exiting:
● TCPWRAP
30 | database: "postgres"
31 | });
> 32 | await pgClient.connect();
| ^
33 | const res = await pgClient.query("SELECT current_timestamp");
34 | console.info("res", res.rows);
35 | await callback(null, {
at Connection.Object.<anonymous>.Connection.connect (node_modules/pg/lib/connection.js:54:17)
at Client.Object.<anonymous>.Client._connect (node_modules/pg/lib/client.js:99:9)
at _Promise (node_modules/pg/lib/client.js:290:10)
at Client.Object.<anonymous>.Client.connect (node_modules/pg/lib/client.js:289:10)
at Object.<anonymous>.exports.connectToRDB (handler.ts:32:18)
at Object.<anonymous>.test (__tests__/handler.ts:22:9)
^C
対策
これを強制的に終了させるために --forceExit optionをつけて再度実行します。これで crtl + c で強制終了せずにテストが完了します
% npx jest --detectOpenHandles --forceExit [11:25:12] ts-jest[config] (WARN) TypeScript diagnostics (customize using `[jest-config].globals.ts-jest.diagnostics` option):
message TS151001: If you have issues related to imports, you should consider setting `esModuleInterop` to `true` in your TypeScript configuration file (usually `tsconfig.json`). See https://blogs.msdn.microsoft.com/typescript/2018/01/31/announcing-typescript-2-7/#easier-ecmascript-module-interoperability for more information.
PASS __tests__/handler.ts
✓ connectToRDB (375ms)
console.info handler.ts:34
res [ { current_timestamp: 2019-12-20T02:25:45.770Z } ]
----------|----------|----------|----------|----------|-------------------|
File | % Stmts | % Branch | % Funcs | % Lines | Uncovered Line #s |
----------|----------|----------|----------|----------|-------------------|
All files | 0 | 0 | 0 | 0 | |
----------|----------|----------|----------|----------|-------------------|
Test Suites: 1 passed, 1 total
Tests: 1 passed, 1 total
Snapshots: 0 total
Time: 7.667s
Ran all test suites.
Jest has detected the following 1 open handle potentially keeping Jest from exiting:
● TCPWRAP
30 | database: "postgres"
31 | });
> 32 | await pgClient.connect();
| ^
33 | const res = await pgClient.query("SELECT current_timestamp");
34 | console.info("res", res.rows);
35 | await callback(null, {
at Connection.Object.<anonymous>.Connection.connect (node_modules/pg/lib/connection.js:54:17)
at Client.Object.<anonymous>.Client._connect (node_modules/pg/lib/client.js:99:9)
at _Promise (node_modules/pg/lib/client.js:290:10)
at Client.Object.<anonymous>.Client.connect (node_modules/pg/lib/client.js:289:10)
at Object.<anonymous>.exports.connectToRDB (handler.ts:32:18)
at Object.<anonymous>.test (__tests__/handler.ts:22:9)
3. DynamoDBトリガーのLambdaでの例外によるリトライ
サンプルコード
DynamoDBのデータ作成、更新イベントをトリガーにLambdaを起動するパターンで、Lambdaがエラー終了するパターンを用意します。
export const dynamoTriggered: Handler = async (
event: DynamoDBStreamEvent,
_context: Context,
_callback: Callback
) => {
console.info("event.Records", event.Records);
throw new Error("Uncuaght Error!");
console.info("SUCCESS");
return {
statusCode: 200,
body: JSON.stringify({
message: event.Records
})
};
};
問題
CloudWatch LogからLambdaのログを見ると、失敗したeventIDと同じIDで定期的にLambdaが再実行されており、リトライされている気配を感じます。アプリケーション的には想定外のエラーなので、リトライされてもエラーが出続けるため、これを抑制したいと思います。
原因
ドキュメントを探していくと、以下に行き当たりました。
ストリームから読み取るイベントソースマッピングは、項目のバッチ全てに対して再試行を実施します。繰り返されるエラーは、そのエラーが解決されるか、項目が期限切れになるまで、影響を受けるシャードの処理を妨げます。停止しているシャードを検出するには、Iterator Age メトリクスをモニターすることができます。
ストリームはS3、SQS、DynamoDB etc.. それぞれの仕様による、ということだと思うので、DynamoDBについて調べます。
DynamoDB ストリーム を使用したテーブルアクティビティのキャプチャ > DynamoDB ストリーム のデータ保持期限
DynamoDB ストリーム 内のすべてのデータは、24 時間保持されます。特定のテーブルの直近 24 時間のアクティビティを取得して分析できます。ただし、24 時間を超えたデータはすぐにトリミング (削除) される可能性があります。
テーブルのストリームを無効にした場合、ストリーム内のデータは 24 時間読み込み可能な状態になります。この時間が経過すると、データは期限切れになり、ストリームレコードは自動的に削除されます。既存のストリームを手動で削除するためのメカニズムはありません。保持期限 (24 時間) が切れ、すべてのストリームレコードが削除されるまで待つ必要があります
対策
ストリーム内のデータは24時間維持され、自動的に削除されますが明示的に削除する方法はない、ということで、ストリームを止めることによってLambdaの再実行を抑制することは難しそうです。
Lambdaでの処理全体をtry-catchで囲んで、Lambdaとしては常に正常終了するようにし、エラー通知ツールなどで別途エラーを検知して対応する、というのが現実解、ということになるでしょうか。
補足
このストリームの期限については、最近DynamoDBのアップデートがありました。まだ実際に試せてないのですが、リトライ回数やストリームデータの保持期限をセットできるようなので、適切にリトライを制御することもできそうです。
AWS Lambda Supports Failure-Handling Features for Kinesis and DynamoDB Event Sources