はじめに
本番環境でやらかしちゃった人 Advent Calendar 2021 に懺悔の意味も含めて投稿させていただきます。@kyntkです。
思い出すだけで、今でもあの時が鮮明に思い出されて心臓が締め付けられる思いをするので正直書くのも辛かったのですが、二度と惨劇を繰り返さないためにということで書きます。
現在の所属はQiita株式会社ですが、この事故は今の会社ではない時に起きたものですので、Qiitaとは一切関係ありません。
ちなみに、Qiita株式会社もカレンダーを作っているので、よろしければこちらも合わせて見てみてください。
やりたかったのは、ただLambdaの関数名を変えること
事故はLambdaの名前を変えた時に発生しました。Lambda関数の管理はserverless frameworkを使っていました。実際の変更差分としては、たった1行だけだったと思います。
まさか、それがあんな事故につながるなんて想像していませんでした...
サービスの概要
サービスの概要としては簡略化すると以下の感じです。
ユーザー登録データが何らかの処理の後にDynamoDBに保存され、そのストリームを受けてLambdaをキックし、後続処理を実行します。その後はユーザーやクライアント、コールセンターへの処理が行われていました。
今回変更を加えたLambdaはイベントの処理を少しする程度で、大したことはしていませんでした。
Lambdaの名前変更
さて、今回はこのLambdaの関数名を変えることになりました。
しかし、実は Lambda関数の名前を変えることはできません!!!
serverless (裏側ではCloudFormation) の変更自体は名前を変更したように見えますが、実際はLambdaが削除され、新規関数を作ることになるのです。 (たしかリリース時はdeployコマンド一発でうまく行かず、ごにょごにょした気もします)
とはいえ、このオペレーションの時にこのことは知っていました。
実際、staging環境もあるのですが、削除と作成を行い、何も問題が起きないことは検証できました。
削除 → 作成ということで一時的にLambdaが使えなくなる可能性も想定されましたが、リトライされることも検証できたので、ある程度の停止は許容されていました。
Lambdaのリトライについて
Lamdbaのリトライの仕組みは呼び出し方によって異なります。
例えば非同期呼び出しでは、2回の再試行をしてくれます。
そして、DynamoDBストリームを使うとストリームの期限切れになるまで再試行を繰り返してくれます。
イベントソースマッピング － ストリームから読み取るイベントソースマッピングは、項目のバッチ全てに対して再試行を実施します。繰り返されるエラーは、そのエラーが解決されるか、項目が期限切れになるまで、影響を受けるシャードの処理を妨げます。
そのため、同時にLambdaが存在する時間さえなければ、問題ないだろうと思っていました。
しかし悲劇は起こった
リリースが完了し、ユーザー登録の検証をしている時に、それは気づきました｡
ユーザー登録は問題なくでき、何もエラーは飛んでいませんでした。
検証では、申し込まれたデータを確認するために、後続処理で保存を行う、RDSのデータを確認していました。
しかし、先程登録したデータが見つかりません。だいたいLimit 10でも取れば入ってくるものなので、入ってこないのはおかしいなと思いました。
再度更新しても見つかりません。
｢ん???｣
｢というか、さっきと最新のデータ違わない???｣
よくよく見てみると、取得したデータは全てが1秒以内にインサートされたものでした。そうです。1秒以内にとてつもない量のインサートが走っていた ため検証のデータが見つからなかったのです。
このあたりで、なんかやらかしたことに気づきました。
とはいえ、E2Eテストもあるので、たまたまそのタイミングで走っていてそのデータかな?と思ったのですが、テストフラグがたっておらず、データもテストデータではなさそうなものばかりでした。
地獄の時間
他のメンバーへは即座に状況報告をしたのですが、｢名前を変えたらとてつもない量のデータが入ってきた｣ということしか分かっておらず､そうしている間にもデータが各所へ送信されていることが見えていました。
処理を止めるにしても Ctrl-Cボタンのようなものはありません。
また、プログラムのリバートをしても全く治る気がしなかったので、完全に手も足も出ない状況でした。
いわば、rm -rf /を押してしまって、ただ高速に死に近づいているのを見ているような、
終わりの見えない底なし沼にハマっていくような、
富士山の頂上で登山ルートに対して落石ボタンを押してしまって落石が落石を生んでいるような感覚でした。
とにかく出血を止めようと、Lambdaの停止を検討したタイミングで、急にデータのインサートは止まりました。
振り返ってみるとたった1,2分のことでしたが、永遠にも感じる時間でした。
惨劇はなぜおこってしまったのか
各所に報告と収束対応をしながら挿入されたデータを調査したところ、過去1日程度の間で登録されたデータと一致していることが判明しました。
さて、ここで怪しそうなのはDynamoDBストリームです。
ストリームレコードは 24 時間後に自動的に削除されます。
なるほど、DynamoDBストリームは24時間保持されるので、インサートされたデータの期間と一致します。
新規Lambdaが構築されたことで、この残っていた24時間分のストリームの内容が一気に実行されたようです。
さらに振り返って
今回の事故が起きた原因として、 Lambdaの後続処理の冪等性 に問題がありました。後続処理で一度実施済みかどうかを判断するなど、Lambdaがリトライされた時にも問題ないようにしておく必要がありました。
こちらにあるように、
関数にエラーが発生していない場合でも、イベントソースマッピングがキューから同じ項目を 2 回受け取る可能性があります。
と、そもそものイベントソースマッピングの仕様としてエラーが起きなくても同じ処理が2回起きうる状況でした。
それまでは再試行が頻発していなかったので問題になっていませんでしたが、発生していた可能性もあります。
また後から分かったのですが、stagingでのリリース前の検証も行ってはいたのですが、staging環境ではDynamoDBに24時間以内に登録されたデータがなかったため、事前に問題発見をするのは難しかったです。
二度と惨劇を起こさないためにどうしたのか
- 非同期のイベントベースのシステムは、再実行されても冪等性を保つように設計する
もともとの地雷があったとはいえ、その引き金がたった1行の名前変更のリリースということで、ここまで想定するのは当時は難しかったです。
ですが、変更の大小と障害の大小は関係ないということが身にしみて分かったので、いかなる変更でも気を緩めないようにし、惨劇を繰り返さないように対策していきます。