概要
Serverless Frameworkを利用して、API Gateway、Lambda、SQSなどを利用したシステムを運用していました。
ある日、AWSのコンソールを確認すると、今月の請求額が普段の1000倍になっていました。
詳細を確認すると、特定のLambdaが何度も実行されており、LambdaとデータソースであるDynamoDBの料金が大きくなっていました。
慌てて修正したのですが、何が原因なのかわかりにくかったので、知見として共有します。
先に結論から言ってしまうとSQSのvisibility timeoutの設定が適切にされていないのが原因でした。
構成図
API GatewayからHTTPSのリクエストを受け取って、Lambdaを実行しています。
SQSを経由して別のLambdaを非同期で実行するという比較的シンプルな構成です。
実際はDynamoDBが永続層として存在していますが、今回の事象では不要なため省略しています。
サンプルプロジェクト
今回の成果物は以下のリポジトリで確認できます。
プロジェクトの作成
npx serverless
# プロジェクトテンプレートの選択が出たので
# AWS - Node.js - Starter を選択します。
# ※ AWS - Node.js - SQS Worker を選択したら、該当の現象が発生しない対策がすでにされていたので、避けています。
作成されるのはindex.jsとserverless.ymlのみのシンプルな構成です
module.exports.handler = async (event) => {
return {
statusCode: 200,
body: JSON.stringify(
{
message: 'Go Serverless v3.0! Your function executed successfully!',
input: event,
},
null,
2
),
};
};
service: aws-node-project
frameworkVersion: '3'
provider:
name: aws
runtime: nodejs18.x
functions:
function1:
handler: index.handler
SQSの追加
SQS周りの処理を追加します。
なお、コードは aws-node-sqs-worker のtemplateで作成されるものを参考にしています。
必要なものをインストールします。package.jsonが無かったら、 npm init -y で作成しておいてください。
npm i -D serverless
npm i aws-sdk
index.jsは
- API Gatewayから呼び出して、SQSに処理を渡すproducer
- SQSから呼び出すconsumer
の2つのLambdaを作成します。
consumerは処理時間が実際には数分になるものでしたが、今回は再現が目的なので、3秒程度で終了となるように setTimeout の処理を入れています。
index.js
const { SQSClient, SendMessageCommand } = require("@aws-sdk/client-sqs");
const sqs = new SQSClient();
// apiGateWayから呼び出す処理
const producer = async (event) => {
let statusCode = 200;
let message;
if (!event.body) {
return {
statusCode: 400,
body: JSON.stringify({
message: "No body was found",
}),
};
}
try {
await sqs.send(new SendMessageCommand({
QueueUrl: process.env.QUEUE_URL,
MessageBody: event.body,
MessageAttributes: {
AttributeName: {
StringValue: "Attribute Value",
DataType: "String",
},
},
}));
message = "Message accepted!";
} catch (error) {
console.log(error);
message = error;
statusCode = 500;
}
return {
statusCode,
body: JSON.stringify({
message,
}),
};
};
// SQS経由で呼び出す処理
const consumer = async (event) => {
for (const record of event.Records) {
const messageAttributes = record.messageAttributes;
console.log(
"Message Attribute: ",
messageAttributes.AttributeName.stringValue
);
console.log("Message Body: ", record.body);
}
return new Promise((resolve, reject) => {
setTimeout(() => {
console.log("end");
resolve();
}, 3000);
})
};
module.exports = {
producer,
consumer,
};
setverless.ymlはSQSの権限の許可とSQSのリソースを作成しています。
SQSはエラー再現のために、VisibilityTimeoutを短めに設定しています。
serverless.yml
service: aws-node-project
frameworkVersion: '3'
provider:
name: aws
runtime: nodejs18.x
region: ap-northeast-1
# SQSを利用するのでIAM roleの設定
iam:
role:
statements:
- Effect: Allow
Action: ['sqs:*']
Resource: 'arn:aws:sqs:ap-northeast-1:*:*'
functions:
producer:
handler: index.producer
events:
- httpApi:
method: post
path: /produce
environment:
QUEUE_URL: !Ref sampleQueue
consumer:
handler: index.consumer
events:
# SQSの設定
- sqs:
arn: !GetAtt [sampleQueue, Arn]
# SQSの作成
resources:
Resources:
sampleQueue:
Type: 'AWS::SQS::Queue'
Properties:
QueueName: 'sampleQuene'
# エラー再現のため設定
VisibilityTimeout: 1
デプロイして動作確認
AWSにデプロイします。
npx serverless deploy --stage stg
完了すると、標準出力のendpointに実行できるURLがでるので、それを利用して、処理を呼び出します。
Deploying aws-node-project to stage stg (ap-northeast-1)
✔ Service deployed to stack aws-node-project-stg (190s)
endpoint: POST - https://xxxx.execute-api.ap-northeast-1.amazonaws.com/produce
functions:
producer: aws-node-project-stg-producer (16 MB)
consumer: aws-node-project-stg-consumer (16 MB)
Monitor all your API routes with Serverless Console: run "serverless --console"
curl -X POST https://xxxx.execute-api.ap-northeast-1.amazonaws.com/produce -d test
API GatewayからproducerのLambdaが実行されて、SQS経由でconsumerが実行される想定だと思います。
リクエストは1回のみなので、すべての処理が1回ずつ実行されていることが期待値になると思います。
※ SQSはFIFOキューではないので、consumerは複数回実行される可能性があります。
CloudWatch Logsから結果を確認します。
producerは1回のみ呼び出されているのですが、consumerは1秒おきに実行されていました。
確認した時点では120回実行されていました。
以下はconsumerのログです。
しばらく実行されっぱなしになると思うので、検証後はSQSのコンソールからキューの中身をクリアしています。
timestamp message
1692358277 START RequestId: ee70663b-8430-5fe5-bc12-3b62dc8576b9 Version: $LATEST
1692358278 START RequestId: 35e7c66d-33fb-53f7-90b1-9b346b4c3be1 Version: $LATEST
1692358279 START RequestId: 33a6c0ba-6893-5d95-94a6-9de3302913c5 Version: $LATEST
1692358280 START RequestId: ce422a45-5218-593c-8a4b-771c0ade5e5f Version: $LATEST
1692358281 START RequestId: 497a7814-cc02-5781-8f0f-254d94b4aa59 Version: $LATEST
1692358282 START RequestId: ab04e049-4d8a-57e6-b62c-bd101542d085 Version: $LATEST
1692358283 START RequestId: 3dc31182-7571-56f9-bdc5-4cdb2dc84c18 Version: $LATEST
1692358284 START RequestId: 8c5c7541-3006-5d0f-8f23-281868cf0383 Version: $LATEST
1692358285 START RequestId: 9e6270b7-d1f1-5748-8866-2dee893dfda9 Version: $LATEST
1692358286 START RequestId: 74cd2afd-f9f5-5dc0-8172-77a4a1398018 Version: $LATEST
1692358287 START RequestId: 7d5167e5-703e-56b6-90df-3abc28f498e6 Version: $LATEST
1692358288 START RequestId: d77b8206-530d-5be9-bc3a-df5f0bc0e108 Version: $LATEST
1692358289 START RequestId: e1735da6-409d-5c81-9e37-00ff184da660 Version: $LATEST
1692358290 START RequestId: 643bfdbc-2e83-5f9c-8125-a0e57652a8e1 Version: $LATEST
1692358291 START RequestId: 741c680d-9f1f-5f49-a946-3554c7cfb291 Version: $LATEST
1692358293 START RequestId: 36f987f5-31af-5d79-b087-daac6965aa1a Version: $LATEST
1692358294 START RequestId: 6dc2c147-1bfd-5780-8af8-9c1e43291a58 Version: $LATEST
1692358295 START RequestId: d22d9121-f29f-5d44-898d-cc78aa5223c8 Version: $LATEST
1692358296 START RequestId: 9a4ba1a1-9bab-5193-b535-fcf8c37a11f1 Version: $LATEST
※ CloudWatch Logsからダウンロードしたデータを修正しています。
原因
今回は設定をいじっているのでわかりやすいと思いますが、SQSにはvisibility timeout(可視性タイムアウト)という項目があります。
簡単に言ってしまえば、visibility timeoutの時間内にLambdaが終了しないと、Lambdaが再度実行されます。
サンプルのコードではLambdaの処理終了が3秒なのに対して、SQSのvisibility timeoutが1秒に設定されています。
SQSのvisibility timeoutである1秒が経過しても、Lambdaが終了していないため、約1秒後にLambdaが再度実行されます。
サンプルコードでは1秒ごとにLambdaが繰り返し実行されるようになっています。
1回のみの実行かつ、途中で停止したので120回の実行で済みましたが、MessageRetentionPeriodで設定している期間(デフォルトは4日)はリトライを繰り返すので、今回の例では 60(秒) * 60(分) * 24(時間) * 4(日) = 345,600回実行されることになります。
請求が1000倍になっていた時には、該当のLambdaが数十回実行されており、visibility timeoutがデフォルトの30秒になっていたのですが、Lambdaの処理自体に3分くらいかかるものだったので、30秒おきに処理が追加されていました。
Lambdaの同時実行はデフォルトで1000まで許容してしまうので、同時に数百のリクエストが実行されっぱなしになっていました。
今回作成したサンプルのソースコードででは、Lambdaが2つとSQSが1つのシンプルな構成であるため、検知はそれほど難しくないかもしれませんが、それぞれの数が増えてきて、それぞれのLambdaのタイムアウトに合わせてvisibility timeoutを設定する必要があると考えると、設定ミスが気が付きにくい項目だと感じました。
visibility timeoutの挙動を調べてみる
SQS → Lambdaの連携がどのように実現されているかを見ていきます。
標準キューの場合、Lambda はロングポーリングを使用して、キューがアクティブになるまでキューをポーリングします。メッセージが利用可能な場合、Lambda は、関数を 5 回同時に呼び出すことで、一度に 5 つのバッチの処理を開始します。
ここで出ているLambdaは我々が作成した関数ではなく、Lambda内部で動いている処理のことになります。
内部的にはPollerというフリートが動作しているようです[1] [2]
費用的には全然小さいので、気にすることはありませんが、SQSのメッセージを連続的にポーリングするため、APIのコールに対して費用がかかっています。[3]
LambdaのPollerがSQSのメッセージを受信すると、メッセージ自体の削除をするのではなく、visibility timeoutの時間だけ他の処理から取得できないようにします。
Lambdaで作成した関数が正常に終了すると、LambdaのPollerがSQSのメッセージを削除します。
そのため、Lambdaの実行時間 > SQSのvisibility timeoutとなると、Lambdaが実行している間にSQSのメッセージが再び受信できる状態になり、再度Lambdaの関数が実行されます。
サンプルコードでは以下のような流れになっていると想定されます。
- SQSに値を入れる(visibility timeoutは1秒)
- Lambdaがメッセージを受信して関数を実行する(実行に3秒)
- Lambdaでは引き継きポーリングしているが値は入っていない
- Lambdaがメッセージを受信してから1秒後にvisibility timeoutになるので、Lambdaが受信できる状態になる
- Lambdaがメッセージを受信して関数を実行する
- 以下繰り返し
初めに実行したLambdaが3秒後に終了するので、その時点でSQSから削除されるかなと思ったのですが、実際に動作確認をしたときは、少なくとも2分は繰り返し実行されているように見えました。
Lambdaの関数が完了後にSQSから削除する処理は動いていると思うのですが、何故削除されないのかは解決できなかったので、わかる人がいれば教えてください。。
Lambdaが実行後にSQSからは削除されないのはDeleteMessage の仕様でした。
DeleteMessageではReceiptHandleという値を渡す必要があるのですが、この値はSQSのメッセージIDとは異なる値を使っていて、送信の時に発行される値のようです。ここが一致していないと削除ができないため、繰り返し実行されていたようです。[4]
The ReceiptHandle is associated with a specific instance of receiving a message. If you receive a message more than once, the ReceiptHandle is different each time you receive a message. When you use the DeleteMessage action, you must provide the most recently received ReceiptHandle for the message (otherwise, the request succeeds, but the message will not be deleted).
修正方法
SQSとLambdaについて記載しているドキュメントには、Lambdaのタイムアウトの6倍の値に設定しましょうとの記載があります。
関数がレコードの各バッチを処理する時間を取るため、ソースキューの可視性タイムアウトは、関数に設定したタイムアウトの少なくとも 6 倍に設定してください。追加の時間は、関数が前のバッチの処理中にスロットリングされた場合に、Lambda が再試行することを可能にします。
Visibility TimeoutをLambdaのタイムアウトより長くすればOKなので、serverless.ymlのSQSで設定している Visibility Timeout の項目をLambdaのタイムアウトより長くすればOKです。
CDKの場合
検証はしていないのですが、CDKではSQSのvisibility timeoutよりLambdaのタイムアウトが長い場合は、エラーになるようです。
わざわざ考えて設定するのは面倒なので、自動的に設定してくれるとありがたいですね。
Serverless Frameworkの場合
今回の記事を書くにあたっての検証で知ったのですが、初回のテンプレートで aws-node-sqs-worker を選択した場合に利用している serverless-lift というpluginではvisibility timeoutがLambdaのタイムアウトの6倍に設定されるようになっていました。
CDKのConstructsのような感じでSQSのように利用用途がある程度決まっているリソースについては、プラグインを利用したほうが確実に対応できそうです。
The SQS "Visibility Timeout" setting is configured per AWS recommendations (more details)
後片付け
利用したリソースはすべて削除しておきます。
npx serverless remove --stage dev
余談
AWS Budgetを設定して、想定外の料金になったときにはメールが送信されるように設定していたのですが、メールアドレスをtypoしていたせいで検知が遅れました。
メールアドレスを正しいものに変更したのはもちろんのことですが、追加でSNS経由でAWS Chatbotを使って、Slackでの通知をできるようにしました。
Slack通知のほうがテストが簡単にできたので、値が間違っている等のミスは起こりずらいのかなと思います。ただし、チャンネル名の変更やチャンネルのアーカイブ等でエラーになる可能性があるので、メールアドレスの通知も残しています。
構築自体はこちらの記事を参考に行いました。
We're hiring!
最後までお読みいただきありがとうございます。
現在DELTA では一緒に働いてくださる仲間を大募集中です！
ご興味をお持ちいただけましたら、お気軽にフォームからご連絡ください。
DELTAは、ベンチャースタートアップなどの成長企業向けに、ソフトウェア・プロダクト開発や技術選定支援などの技術支援事業を提供しています。 また、成長企業向けに様々な事業支援を提供するSEVENRICH GROUPに属して、グループ内の事業会社や、出資先の支援もおこなっています。
Discussion
メッセージ削除のためにはメッセージ受信時に受け取った ReceiptHandle パラメーターが必要なのですが、Timeout するとその ReceiptHandle が無効化してしまうためですね。
SQS の DeleteMessage API に説明ありますよ。
ありがとうございます。加筆します！