Amazon ECS タスクのイベントとログを時系列で出す tracer を作った

AdventCalendar2021 sre

SREチームの藤原です。KAYAC Advent Calendar 2021 4日目の記事です。

早速ですが Amazon ECS をお使いの皆様、何か新しく起動したい ECS タスクがあって、タスク定義を書き起こして(もしくはマネージメントコンソールで定義して)、一発で起動に成功できますか？？

……なかなかこれが難しいんですよね。

ということで、とある ECS タスクに関連するイベントとログを全部時系列で出力するツールを書きました。どうぞご利用ください。

github.com

以下はそこに至るまでの背景です。

ECS タスクが立たない。なぜだ！

自分は Amazon ECS を業務で使い始めて早4年になります。新規プロダクトはもちろん、かつて EC2 で動いていたワークロードもほぼ全て ECS に移行しました。

ECS デプロイツール ecspresso の開発者でもあるため、日々機能アップデートには目を通し、SDK の差分は diff をみて確認する程度のユーザーです。つまり利用者としてはそこそこ ECS には詳しいほうだと自負しているのですが……すんなり立ちませんねタスク。

タスクが立たない理由はいろいろあります。たとえば…

  • IAM ロールがない / Assume できない
  • コンテナイメージが (ない | 権限がない | pullするネットワーク経路がない)
  • Secrets (SSM / SecretsManager) が (ない | 権限がない | pullするネットワーク経路がない)
  • CloudWatch ロググループがない
  • networkmode=awsvpc の場合、subnet / securityGroup がおかしい
  • ALB target group の定義とコンテナの定義 (port)があっていない
  • ALB の定義がないのにサービスに HealthCheckGracePeriodSeconds が定義されている

などなど、実際にコンテナが起動する前に引っかかる原因だけでもいくつも沸いてきます。

ちなみにこれらの原因で起動できないことを検出するために、ecspresso では verify という機能を作りました。大変便利ですので是非ご利用下さい。

zenn.dev

さて、これらの問題を乗り越えて ECS タスクが起動しても、起動したタスク内でコンテナのプロセスが死亡したら essential container であればタスクは即停止されますし、ロードバランサーと組み合わせる場合はヘルスチェックに正常に応答できなければ、タスクは無慈悲にも殺されてしまいます。

タスクが生きていれば ECS Exec で乗り込んで調査もできますが、死んでしまうとそれもできません。

というわけで、はじめて作るタスク定義をもとに、タスクが安定して起動するまでにこぎつけるのは意外と大変なのです。(そんなの楽勝だよ、って方は是非一緒に働かせて下さい。ご応募はこちらまで )

ECS タスクが落ちた原因を探りたい

タスクが落ちた理由を探るのにこれまでは、マネージメントコンソールでクラスタを開き、上手く起動できずに落ちたタスクを特定し、理由を「停止理由」などから探り、タブを切り替えつつ CloudWatch Logs に出力されたログを目視し…という作業をしていました。ダルいですね。

あまりにダルいので、これらの情報を時系列で全部並べて表示したら捗るのでは? と思いつきました。

  • タスクに関連するイベント(作成、起動開始、pull開始と停止、停止開始、停止完了など)
  • タスク内のコンテナが CloudWatch Logs に出力したログ
  • (ECS サービスから起動されたタスクの場合) サービスのイベントログ

github.com/fujiwara/tracer

github.com

同様のものが既に世の中にあるような気はしましたが、金曜夜の晩酌のお供にさっくりと作りました。

tracer は ECS クラスタ名とタスクIDを引数に取り、タスクの一生をテキストで一気に表示してくれます。

以下は実行例です。

表示はタブ区切りで、1カラム目が時刻、2カラム目が情報のソース(SERVICE, TASK, CONTAINER:コンテナ名)、3カラム目がログとなっています。

サービスからタスクが作成され、イメージがpullされてコンテナが起動し、ヘルスチェックが行われてコンテナがアクセスログを出力し、ロードバランサーからdrainしてSIGTERMが送られてコンテナとタスクが終了する、という一連の流れが一気通貫で見られて便利ですね！

$ tracer default 834a5628bef14f2dbb81c7bc0b272160
2021-12-03T11:06:21.633+09:00   TASK    Created
2021-12-03T11:06:21.664+09:00   SERVICE (service nginx-local) has started 1 tasks: (task 834a5628bef14f2dbb81c7bc0b272160).
2021-12-03T11:06:24.906+09:00   TASK    Connected
2021-12-03T11:06:39.602+09:00   TASK    Pull started
2021-12-03T11:06:46.366+09:00   TASK    Pull stopped
2021-12-03T11:06:46.746+09:00   CONTAINER:nginx /docker-entrypoint.sh: /docker-entrypoint.d/ is not empty, will attempt to perform configuration
2021-12-03T11:06:46.746+09:00   CONTAINER:nginx /docker-entrypoint.sh: Looking for shell scripts in /docker-entrypoint.d/
2021-12-03T11:06:46.746+09:00   CONTAINER:nginx /docker-entrypoint.sh: Launching /docker-entrypoint.d/10-listen-on-ipv6-by-default.sh
2021-12-03T11:06:46.758+09:00   CONTAINER:nginx 10-listen-on-ipv6-by-default.sh: info: Getting the checksum of /etc/nginx/conf.d/default.conf
2021-12-03T11:06:46.762+09:00   CONTAINER:nginx 10-listen-on-ipv6-by-default.sh: info: Enabled listen on IPv6 in /etc/nginx/conf.d/default.conf
2021-12-03T11:06:46.762+09:00   CONTAINER:nginx /docker-entrypoint.sh: Launching /docker-entrypoint.d/20-envsubst-on-templates.sh
2021-12-03T11:06:46.768+09:00   TASK    Started
2021-12-03T11:06:46.820+09:00   CONTAINER:nginx /docker-entrypoint.sh: Launching /docker-entrypoint.d/30-tune-worker-processes.sh
2021-12-03T11:06:46.832+09:00   CONTAINER:nginx 2021/12/03 02:06:46 [notice] 1#1: using the "epoll" event method
2021-12-03T11:06:46.832+09:00   CONTAINER:nginx 2021/12/03 02:06:46 [notice] 1#1: nginx/1.21.4
2021-12-03T11:06:46.832+09:00   CONTAINER:nginx 2021/12/03 02:06:46 [notice] 1#1: built by gcc 10.2.1 20210110 (Debian 10.2.1-6) 
2021-12-03T11:06:46.832+09:00   CONTAINER:nginx 2021/12/03 02:06:46 [notice] 1#1: OS: Linux 4.14.248-189.473.amzn2.aarch64
2021-12-03T11:06:46.832+09:00   CONTAINER:nginx 2021/12/03 02:06:46 [notice] 1#1: getrlimit(RLIMIT_NOFILE): 1024:4096
2021-12-03T11:06:46.832+09:00   CONTAINER:nginx /docker-entrypoint.sh: Configuration complete; ready for start up
2021-12-03T11:06:46.832+09:00   CONTAINER:nginx 2021/12/03 02:06:46 [notice] 1#1: start worker processes
2021-12-03T11:06:46.837+09:00   CONTAINER:nginx 2021/12/03 02:06:46 [notice] 1#1: start worker process 37
2021-12-03T11:06:46.837+09:00   CONTAINER:nginx 2021/12/03 02:06:46 [notice] 1#1: start worker process 38
2021-12-03T11:21:36.818+09:00   CONTAINER:nginx 10.3.1.18 - - [03/Dec/2021:02:21:36 +0000] "GET / HTTP/1.1" 200 615 "-" "ELB-HealthChecker/2.0" "-"
2021-12-03T11:21:36.836+09:00   CONTAINER:nginx 10.3.3.10 - - [03/Dec/2021:02:21:36 +0000] "GET / HTTP/1.1" 200 615 "-" "ELB-HealthChecker/2.0" "-"
2021-12-03T11:21:46.819+09:00   CONTAINER:nginx 10.3.1.18 - - [03/Dec/2021:02:21:46 +0000] "GET / HTTP/1.1" 200 615 "-" "ELB-HealthChecker/2.0" "-"
2021-12-03T11:21:46.837+09:00   CONTAINER:nginx 10.3.3.10 - - [03/Dec/2021:02:21:46 +0000] "GET / HTTP/1.1" 200 615 "-" "ELB-HealthChecker/2.0" "-"
2021-12-03T11:21:56.820+09:00   CONTAINER:nginx 10.3.1.18 - - [03/Dec/2021:02:21:56 +0000] "GET / HTTP/1.1" 200 615 "-" "ELB-HealthChecker/2.0" "-"
2021-12-03T11:21:56.839+09:00   CONTAINER:nginx 10.3.3.10 - - [03/Dec/2021:02:21:56 +0000] "GET / HTTP/1.1" 200 615 "-" "ELB-HealthChecker/2.0" "-"
2021-12-03T11:22:06.821+09:00   CONTAINER:nginx 10.3.1.18 - - [03/Dec/2021:02:22:06 +0000] "GET / HTTP/1.1" 200 615 "-" "ELB-HealthChecker/2.0" "-"
2021-12-03T11:22:06.840+09:00   CONTAINER:nginx 10.3.3.10 - - [03/Dec/2021:02:22:06 +0000] "GET / HTTP/1.1" 200 615 "-" "ELB-HealthChecker/2.0" "-"
2021-12-03T11:22:16.821+09:00   CONTAINER:nginx 10.3.1.18 - - [03/Dec/2021:02:22:16 +0000] "GET / HTTP/1.1" 200 615 "-" "ELB-HealthChecker/2.0" "-"
2021-12-03T11:22:16.841+09:00   CONTAINER:nginx 10.3.3.10 - - [03/Dec/2021:02:22:16 +0000] "GET / HTTP/1.1" 200 615 "-" "ELB-HealthChecker/2.0" "-"
2021-12-03T11:22:19.833+09:00   SERVICE (service nginx-local) deregistered 1 targets in (target-group arn:aws:elasticloadbalancing:ap-northeast-1:314472643515:targetgroup/alpha/6a301850702273d9)
2021-12-03T11:22:19.834+09:00   SERVICE (service nginx-local) has begun draining connections on 1 tasks.
2021-12-03T11:22:26.822+09:00   CONTAINER:nginx 10.3.1.18 - - [03/Dec/2021:02:22:26 +0000] "GET / HTTP/1.1" 200 615 "-" "ELB-HealthChecker/2.0" "-"
2021-12-03T11:22:26.842+09:00   CONTAINER:nginx 10.3.3.10 - - [03/Dec/2021:02:22:26 +0000] "GET / HTTP/1.1" 200 615 "-" "ELB-HealthChecker/2.0" "-"
2021-12-03T11:22:28.910+09:00   TASK    Stopping
2021-12-03T11:22:28.910+09:00   TASK    StoppedReason:Scaling activity initiated by (deployment ecs-svc/8709920613704280865)
2021-12-03T11:22:28.910+09:00   TASK    StoppedCode:ServiceSchedulerInitiated
2021-12-03T11:22:28.938+09:00   SERVICE (service nginx-local) has stopped 1 running tasks: (task 834a5628bef14f2dbb81c7bc0b272160).
2021-12-03T11:22:29.244+09:00   CONTAINER:nginx 2021/12/03 02:22:29 [notice] 1#1: signal 15 (SIGTERM) received, exiting
2021-12-03T11:22:29.245+09:00   CONTAINER:nginx 2021/12/03 02:22:29 [notice] 37#37: exiting
2021-12-03T11:22:29.245+09:00   CONTAINER:nginx 2021/12/03 02:22:29 [notice] 37#37: exit
2021-12-03T11:22:29.245+09:00   CONTAINER:nginx 2021/12/03 02:22:29 [notice] 38#38: exiting
2021-12-03T11:22:29.245+09:00   CONTAINER:nginx 2021/12/03 02:22:29 [notice] 38#38: exit
2021-12-03T11:22:29.294+09:00   CONTAINER:nginx 2021/12/03 02:22:29 [notice] 1#1: signal 14 (SIGALRM) received
2021-12-03T11:22:29.328+09:00   CONTAINER:nginx 2021/12/03 02:22:29 [notice] 1#1: signal 17 (SIGCHLD) received from 37
2021-12-03T11:22:29.328+09:00   CONTAINER:nginx 2021/12/03 02:22:29 [notice] 1#1: worker process 37 exited with code 0
2021-12-03T11:22:29.328+09:00   CONTAINER:nginx 2021/12/03 02:22:29 [notice] 1#1: signal 29 (SIGIO) received
2021-12-03T11:22:29.329+09:00   CONTAINER:nginx 2021/12/03 02:22:29 [notice] 1#1: signal 17 (SIGCHLD) received from 38
2021-12-03T11:22:29.329+09:00   CONTAINER:nginx 2021/12/03 02:22:29 [notice] 1#1: worker process 38 exited with code 0
2021-12-03T11:22:29.329+09:00   CONTAINER:nginx 2021/12/03 02:22:29 [notice] 1#1: exit
2021-12-03T11:22:38.224+09:00   SERVICE (service nginx-local) has reached a steady state.
2021-12-03T11:22:40.527+09:00   TASK    Execution stopped
2021-12-03T11:23:04.873+09:00   TASK    Stopped
2021-12-03T11:23:04.873+09:00   CONTAINER:nginx STOPPED (exit code: 0)

デフォルトでは、タスクの起動前後1分、タスクの停止前後1分のログを出力するようになっています。-duration というオプションでこの時間幅は変更できます。

コンテナで実行するコマンドを誤ってエラーで終了した場合の例は次のようになります。一目で分かりますね。

$ tracer default 9f654c76cde14c7c85cf54dce087658a
2021-12-04T09:03:01.504+09:00   TASK    Created
2021-12-04T09:03:05.375+09:00   TASK    Connected
2021-12-04T09:03:17.878+09:00   TASK    Pull started
2021-12-04T09:03:25.285+09:00   TASK    Pull stopped
2021-12-04T09:03:25.927+09:00   CONTAINER:nginx /docker-entrypoint.sh: /docker-entrypoint.d/ is not empty, will attempt to perform configuration
2021-12-04T09:03:25.928+09:00   CONTAINER:nginx /docker-entrypoint.sh: Looking for shell scripts in /docker-entrypoint.d/
2021-12-04T09:03:25.929+09:00   CONTAINER:nginx /docker-entrypoint.sh: Launching /docker-entrypoint.d/10-listen-on-ipv6-by-default.sh
2021-12-04T09:03:25.935+09:00   CONTAINER:nginx 10-listen-on-ipv6-by-default.sh: info: Getting the checksum of /etc/nginx/conf.d/default.conf
2021-12-04T09:03:25.945+09:00   CONTAINER:nginx 10-listen-on-ipv6-by-default.sh: info: Enabled listen on IPv6 in /etc/nginx/conf.d/default.conf
2021-12-04T09:03:25.945+09:00   CONTAINER:nginx /docker-entrypoint.sh: Launching /docker-entrypoint.d/20-envsubst-on-templates.sh
2021-12-04T09:03:25.951+09:00   CONTAINER:nginx /docker-entrypoint.sh: Launching /docker-entrypoint.d/30-tune-worker-processes.sh
2021-12-04T09:03:25.951+09:00   CONTAINER:nginx /docker-entrypoint.sh: Configuration complete; ready for start up
2021-12-04T09:03:25.954+09:00   CONTAINER:nginx nginx: invalid option: "x"
2021-12-04T09:03:25.990+09:00   TASK    Execution stopped
2021-12-04T09:03:26.006+09:00   TASK    Started
2021-12-04T09:03:36.060+09:00   TASK    Stopping
2021-12-04T09:03:36.060+09:00   TASK    StoppedReason:Essential container in task exited
2021-12-04T09:03:36.060+09:00   TASK    StoppedCode:EssentialContainerExited
2021-12-04T09:03:49.533+09:00   TASK    Stopped
2021-12-04T09:03:49.533+09:00   CONTAINER:nginx STOPPED (exit code: 1)

第一引数の ECS クラスタ名だけを指定すると、そのクラスタで実行している(直近で停止したものを含む)タスクを一覧で表示します。これで上手く起動できなかったタスクを見つけて、IDを指定して詳細を得る、というのが便利かと思います。

$ tracer default
283facc8dd7a48648ef85a8bea5625e5    app:41  RUNNING RUNNING 2021-12-03T14:03:05+09:00   service:app EC2
477d92754f104870a9a248a2244b3044    app:41  RUNNING RUNNING 2021-12-01T14:04:15+09:00   service:app EC2
68a6932ce5f9458e838bfae8fd9abd2e    proxy:4 RUNNING RUNNING 2021-07-07T10:08:53+09:00   service:proxy   FARGATE

まとめ

  • Amazon ECS タスクが起動できない原因にはいろいろあって調査が面倒です
  • タスクにまつわるイベントとログを一発表示してくれる tracer https://github.com/fujiwara/tracer というツールを作りました
  • どうぞご利用ください

カヤックでは ECS に限らずクラウド技術に強いエンジニアも募集しています！