はじめに

こんにちは、データ推進室の成です。現在はソフトウェアエンジニアとして、社内向けの Web アプリケーションの保守と開発に携わっています。

一切のバグを発生させずにソフトウェアを作成することは難しく、日々多くの問題に遭遇します。この記事では、2024 年に解決した問題の中でも、特に印象深かったものについて紹介したいと思います。

※ この記事内のログ・コマンドは一部情報を編集しています。

本記事は、データ推進室 Advent Calendar 2024 12日目の記事です

突然失敗する ECS のデプロイ

2023-2024 年にかけて、私が所属するチームでは開発環境とデプロイメントの効率化というテーマに取り組んでいました。

当時は以下のようなデプロイパイプラインとなっていました。

staging ブランチへマージされると DRONE 上で Docker build と push が実行され、ECS のタスクが更新されます。

Release が作成された場合もほぼ同様ですが、ステージング環境へのデプロイが成功した後に、本番環境へのデプロイが行われます。

ある程度の自動化や、キャッシュの利用などは実現されていましたが、マルチステージビルドを用いたビルド時間の短縮や Github Actions への移行などが課題としてあり、これらの実現に向けて改善を行っていました。

そんなある日、リリース作業中に ECS へのデプロイが失敗しタスクが更新されない問題が発生しました。 詳細を確認したところ、ECS のヘルスチェックに失敗し、以下のようなログが記録されていました。

level=info time=2023-11-27T04:44:06Z msg="Essential container stopped; updating task desired status to stopped" knownStatus="STOPPED" desiredStatus="STOPPED" task="xxxxxxxx" container="yyyyyyy"
level=info time=2023-11-27T04:44:06Z msg="Sending state change to ECS" eventType="task" eventData="TaskChange: xxxxxx/yyyyyyyyyyy -> STOPPED, Known Sent: RUNNING, PullStartedAt: 2023-11-27 04:44:04.86681428 +0000 UTC m=+11108.402653801, PullStoppedAt: 2023-11-27 04:44:05.029062545 +0000 UTC m=+11108.564902035, ExecutionStoppedAt: 2023-11-27 04:44:06.20105531 +0000 UTC m=+11109.736894791, xxxxxx/yyyyyyyyy zzzzz -> STOPPED, Exit 0, , Ports [{80 49584 0.0.0.0 0} {80 49584 :: 0}], Known Sent: RUNNING] sent: false"

Essential container stopped; updating task desired status to stoppedと記録されており、コンテナが起動直後に終了していました。

リリースの内容はコンテナの起動に関連するものではなく、テスト・レビューの段階では問題は発生していませんでした。

ログから有力な情報を得ることができなかったため、本番環境への影響はなかったものの、急遽リリースを中止し、ロールバック作業を行いました。原因については思い当たるところはなかったものの、後日再度同じ内容でリリースを試みたところ、無事成功したことから、偶発的に発生した可能性が高いと判断し、様子を見ることとなりました。

問題を再現してみる(1)

残念ながら、この問題は再発してしまいました。

発生頻度は高くはなかったものの、問題が発生するたびに、半自動化されたデプロイパイプラインを手動でやり直すのは極めてストレスです。

また、問題の解消には手動の操作が必要でした。ヒューマンエラーのリスクが高まり、デプロイにかかる時間も増加します。加えて、リリース作業のたびにもしかしたら失敗するかも…?と考えながらデプロイしなければいけない状況は好ましくありません。

この厄介な問題を解消するために、本格的に調査に取り組むことにしました。

まずはデプロイが失敗する状況の絞り込みからです。

実際にデプロイが失敗したケースを分析した結果、以下のパターンがあることがわかりました。

1. master ブランチへのマージをトリガーとする、 ステージングへのデプロイ時には失敗することがある。
2. 1 の失敗後に、staging ブランチへのマージをトリガーとする、ステージング環境へのデプロイには成功する。
3. 一度 staging ブランチへのマージをトリガーとしてデプロイすれば、1 も成功するようになる。
4. ステージング環境へのデプロイのみ失敗し、本番環境へのデプロイには成功する。

どうやら、デプロイ元のブランチとデプロイ先の環境に関連がありそうです。

確かに当時、Dockerfile では、デプロイ元とデプロイ先に表すDRON_BRANCHとRAILS_ENVという環境変数を使用しています。したがって、これらが異なれば、Docker イメージのビルド時の挙動がわずかに変わります。

しかし、これによって生じるのはキャッシュ使用有無のみなはずです。デプロイが失敗していた理由の直接的な原因　Essential container stopped; updating task desired status to stoppedとも結びつきません。

残念ながら、Docker イメージのビルド時のログからもヒントを得られず、手動で環境変数を入れ替えてビルドしてみるものの問題は再現しなかったため、別のアプローチを試すことにしました。

問題を再現してみる(2)

ログや状況から問題の原因を推定することは難しそうです。そこで、問題が発生した際の Docker イメージ（web:failed）を取得し、問題が発生しなかったものと比較して調査することとしました。

Docker イメージを起動してみます

❯ docker run -it --rm web:failed
> # exit 0

再現できました。docker runで起動した場合、CMD命令で指定したプロセスが起動します。CMD ではentrypoint.shというシェルを起動しているため、entrypoint.shが起動する時に問題が起こっていそうです。

少なくとも、Docker イメージに問題の原因があると考えて良さそうです。

内部で何が起こっているかを確認するため--entrypointオプションでbashを起動し、手動でentrypoint.shを起動してみます。

❯ docker run -it --rm --entrypoint bash web:failed
root@4325a336df68:/ sh entrypoint.sh
[init][hogehoge]||applying \`whenever --update-crontab\`..

…問題なく起動しました。驚くべきことに、docker runで起動すると直ちに終了するのに対し、手動でentrypoint.shを起動すると正常に起動します。

どちらも同じ Dockerfile から生成されたイメージであることを考えると、奇妙な挙動です。しかし、原因は間違いなくこの２つの差分にありそうです。

docker inspectコマンドを用いて、デプロイが成功した Docker イメージと比較してみます。

❯ docker inspect web/ok --format='{{.Config.Cmd}}'
[./entrypoint.sh]

❯ docker inspect web/failed  --format='{{.Config.Cmd}}'
[/bin/sh -c '#(nop)  EXPOSE 80']

ようやくバグが特定できました。

Docker イメージ の CMD が意図しないものになっていたようです。このバグによって、ECSへのデプロイが失敗していたのです。

原因の特定

バグは判明したので、問題が再発しないように修正する必要があります。

問題が発生していたイメージとそうでないイメージの両方で同じ Dockerfile を使用していることを考えると、CMD の命令が書き換わってしまうバグ自体は、Docker 側の挙動にヒントがありそうです。

そうであれば、私たち以外にも問題に遭遇している可能性があるはずです。

実際にこの推測は正しく、似たような問題が スタック・オーバーフロー と Github 上の issue に報告されていました。

どちらも解決策まで明示されていないものの、キャッシュが原因でランダムに問題が発生することが記述されています。

実際に

• 実際にマルチステージビルドを用いて Dockerfile を改修した後から、問題が再現するようになったこと
• 問題が発生するパターンでは、キャッシュが利用されること
• stagingブランチを経由することで、CMDのレイヤーがキャッシュされなくなること

など、スタック・オーバーフローや GitHub 上の issue で報告されている問題と近い状況にありました。

GitHub 上の issue でも述べられていますが、CMD 命令を Dockerfile の末尾に記述することで（＝キャッシュが利用されないようにする）、解決できそうです。

実際にこのアプローチを採用し 修正のためのPR を作成しました。幸いにも、現在まで問題は再発していません。

まとめ

この記事では、私が所属するチームで遭遇したデプロイが失敗する問題について紹介しました。

問題自体は、ECS へのデプロイ中にタスクが終了することで発覚しましたが、原因は、Docker イメージに意図しない CMD 命令が混入したことにありました。

問題の原因が思いもよらないところにあったことで、私が遭遇した問題の中でも特に印象深く残っています。 また、インターネット上の先人が同様の問題を共有してくれたおかげで、解消までの道のりを大幅に短縮できた例だったと思います。

普段のデータ推進室の記事とは少し毛色が異なりますが、アドベントカレンダーということもあり、誰かの役に立つかもしれないと思い執筆に取り組んでみました。

最後までお読みいただきありがとうございました。

ソフトウェアエンジニア

成 泰鏞

リクルート入社2年目。困ったことがあると走って解決することが多いです。