🐾
tracer - ECSタスクのイベントとログを時系列で fujiwara-ware advent calendar 2024 day 5

2024/12/05に公開
AWS
この記事は fujiwara-ware advent calendar 2024 の5日目です。

 tracer とはhttps://github.com/fujiwara/tracer
tracer は、Amazon ECS のタスク(task)のイベントとログを時系列で出力するためのツールです。
開発の経緯は以下のエントリに書いています。
https://techblog.kayac.com/ecs-task-tracer
早速ですが Amazon ECS をお使いの皆様、何か新しく起動したい ECS タスクがあって、タスク定義を書き起こして(もしくはマネージメントコンソールで定義して)、一発で起動に成功できますか？？
……なかなかこれが難しいんですよね。
ということで、とある ECS タスクに関連するイベントとログを全部時系列で出力するツールを書きました。どうぞご利用ください。

 使い方$ tracer クラスタ名 タスクID
クラスタ名とタスクIDを指定すると、そのタスクに関連するイベントとログを時系列で出力します。

イベントは ECS タスクの状態遷移、ログはそのタスクが CloudWatch Logs に出力したログです。
以下が実際の出力例です。時刻、イベントの種類、ログメッセージが表示されます。
$ 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:22.342+09:00	SERVICE	(service nginx-local) was unable to place a task. Reason: Capacity is unavailable at this time. Please try again later or in a different availability zone. For more information, see the Troubleshooting section of the Amazon ECS Developer Guide.
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: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)
タスクが起動してから終了するまでに起きた出来事が時系列で把握できるため、特にタスクの実行が失敗した場合、その原因を探るのに非常に便利です。

 ecspresso, ecsta との関連tracer は ecspresso や ecsta にライブラリとして組み込まれています。
ecspresso tasks --trace, ecsta trace というコマンドで、これらのツールから tracer コマンドを実行したのと同じ結果を得ることができます。
https://zenn.dev/fujiwara/articles/fujiwara-ware-2024-ecspresso
https://zenn.dev/fujiwara/articles/fujiwara-ware-2024-ecsta

 Lambda として実行するtracer は、そのバイナリを Lambda カスタムランタイムの bootstrap として配置することで、Lambda 関数として動作させることもできます。
そしてその Lambda を EventBridge のルールによって起動すると、ECS タスクのイベントを自動的にトレースすることができます。
詳細はREADMEを参照してください
このように自動化しておけば、いつタスクが異常終了した場合でも原因を収集することができるため、トラブルシューティングに役立つでしょう。

 関連エントリと喜びの声https://zenn.dev/quiver/articles/d645d5ca8612d6
https://x.com/aereal/status/1756163071603867964
tracer とは

使い方

ecspresso, ecsta との関連

Lambda として実行する

関連エントリと喜びの声

Discussion
