終了しないコンテナがシグナルを受け取っているかstraceで確認してみた

この記事はNE開発ブログ/開幕連続投稿企画の27日目の記事です。

昨今、クラウドネイティブなプロダクトではGraceful shutdownのためにアプリケーションの中でシグナルハンドリングをする機会も多いのではないでしょうか。

そんなシグナルについて、送信されたはずのシグナルが行方不明になるという経験をした折に追跡してみた体験談を共有します。

はじまり

ある日、AWS ECS上で動いているアプリケーションをみていると、デプロイでの入れ替わり時に古い方のタスクのコンテナが異常終了していることに気づきました。
これまでは、StopSignalとしてSIGTERMが送信されると正常終了していたものが、終了出来ずにタイムアウト後のSIGKILLによって異常終了していたのです。

ECS Agentの異常でないかの確認に同一のコンテナをローカルで実行してみても、docker stopでコンテナが終了せずタイムアウト後にSIGKILLによって強制終了挙動が再現できました。
コンテナイメージ自体に問題がありそうです。

StopSignalはどこへ消えたのでしょう？

問題のコンテナ

問題のコンテナはPHPアプリケーションのコンテナです。

このコンテナは、Webアプリケーションサーバ、バッチサーバの2つの用途で使っていました。
WebはApache＋PHPモジュールをサービスとして実行、バッチはPHPコマンドによるファイル実行となるように起動コマンドを変えて動かしています。
このバッチサーバ側でのみ今回の問題が起きました。

そして事象の前後でアプリケーションコンテナのペースイメージの変更がありました。
自分でミドルウェアを盛り込んだイメージから、必要なミドルウェアがインストール済みのPublicイメージに変更していました。

もう少し切り分ける

新旧コンテナについて、ECS上で動いているものについてpsでプロセスを確認しても同じPHPスクリプトが実行されていました。
アプリケーション内でSIGTERMを握り潰している可能性は低そうです。
試しにコマンドとしてワンライナーのコードを渡し実行してみてもやはり同じように新しいコンテナはStopSignalを無視する挙動です。

before-実行

#十分な時間カウントアップするスクリプト実行
$ docker run --rm -it --init ne/app:old php -r 'for($i=0;$i<1200;$i=$i+1){sleep(1);echo $i;};'

before-停止

$ docker stop xxxxxxxxx
#-> 正常終了

after-実行

#十分な時間カウントアップするスクリプト実行
$ docker run --rm -it --init ne/app:new php -r 'for($i=0;$i<1200;$i=$i+1){sleep(1);echo $i;};'

after-停止

$ docker stop xxxxxxxxx
#-> timeout -> sigkill -> 異常終了

PHPまで届いていないのであれば、どこまでSIGTERMは伝わったのでしょう？

straceで見てみる

straceコマンドを使うとシステムコールを追跡できます。シグナルの動きも確認できますので、これを使ってSIGTERMを受信したプロセスを確認してみます。

なお、Dockerでは何も意識せずインストール、実行しようとしてもエラーが出ます。
Operation not permitted とあるように制限によって権限が不足しているためです。

root@4d33ec175618:/# apt-get update && apt-get install strace
root@4d33ec175618:/# strace -fvttTyy -s 1024 -p 1
strace: attach: ptrace(PTRACE_SEIZE, 1): Operation not permitted

実行できるようにするにはcap_addとsecurity_optの設定を加えて実行します。
ref. https://qiita.com/koemu/items/547e6e8d0043b815279e

$ docker run -it --cap-add SYS_PTRACE --security-opt seccomp:unconfined --init ne/app:new php -r 'for($i=0;$i<1200;$i=$i+1){sleep(1);echo $i;};'

改めてコンテナを起動して、別プロセスでstraceを実行（docker exec）しながら、コンテナを停止（docker stop)してみた結果、次のようになりました。
この例では最初にStopSignalを受け取るPID 1のプロセスに絞っています。

root@8431074a4b68:/# strace -fvttTyy -s 1024 -p 1
strace: Process 1 attached
16:05:56.927099 wait4(-1, 0xfffff344f83c, WNOHANG, NULL) = 0 <0.000027>
16:05:56.927242 rt_sigtimedwait(~[ILL TRAP ABRT BUS FPE SEGV TTIN TTOU SYS RTMIN RT_1], 0xfffff344f7c0, {tv_sec=1, tv_nsec=0}, 8) = -1 EAGAIN (Resource temporarily unavailable) <1.001614>
16:05:57.929161 wait4(-1, 0xfffff344f83c, WNOHANG, NULL) = 0 <0.000098>
###################
## ここで外からdocker stop
###################
16:05:57.929354 rt_sigtimedwait(~[ILL TRAP ABRT BUS FPE SEGV TTIN TTOU SYS RTMIN RT_1], {si_signo=SIGWINCH, si_code=SI_USER, si_pid=0, si_uid=0}, {tv_sec=1, tv_nsec=0}, 8) = 28 (SIGWINCH) <0.106604>
16:05:58.036139 kill(6, SIGWINCH)       = 0 <0.000016>
16:05:58.036239 wait4(-1, 0xfffff344f83c, WNOHANG, NULL) = 0 <0.000011>
16:05:58.036302 rt_sigtimedwait(~[ILL TRAP ABRT BUS FPE SEGV TTIN TTOU SYS RTMIN RT_1], 0xfffff344f7c0, {tv_sec=1, tv_nsec=0}, 8) = -1 EAGAIN (Resource temporarily unavailable) <1.000595>
16:05:59.037243 wait4(-1, 0xfffff344f83c, WNOHANG, NULL) = 0 <0.000030>
16:05:59.037394 rt_sigtimedwait(~[ILL TRAP ABRT BUS FPE SEGV TTIN TTOU SYS RTMIN RT_1], 0xfffff344f7c0, {tv_sec=1, tv_nsec=0}, 8) = -1 EAGAIN (Resource temporarily unavailable) <1.004164>
略

16:05:57.929354 rt_sigtimedwait(~[ILL TRAP ABRT BUS FPE SEGV TTIN TTOU SYS RTMIN RT_1], {si_signo=SIGWINCH, si_code=SI_USER, si_pid=0, si_uid=0}, {tv_sec=1, tv_nsec=0}, 8) = 28 (SIGWINCH) <0.106604>
16:05:58.036139 kill(6, SIGWINCH) = 0 <0.000016>

ここでSIGWICHをキャッチしていることが確認できます。

解明

どうやらdocker stopによってSIGWINCHが送信されているようです。
docker stopの際に送信されるStopSignalはイメージごとにカスタム可能です。
イメージに設定されたStopSignalを確認してみます。

$ docker image inspect ne/app:new

[
    {
        "Id": "sha256:xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx",
        "RepoTags": [
            "ne/app:new"
        ],
        "Created": "2023-04-26T14:50:53.246771717Z",
	## 略 ##
        "Config": {
            ## 略 ##
            "StopSignal": "SIGWINCH",
            ## 略 ##
        },
	## 略 ##
    }
]

StopSignalがデフォルトのSIGTERMではなくSIGWINCHになっていることがわかります。
PHPスクリプトはSIGWINCHに対して終了するものになっていなかったため、StopSignalが無視され強制終了する事態となっていたのです。

straceによって無事シグナルの行方を解明できました。

余談：どうしてこうなった？

今回のコンテナは、Webアプリケーションが主用途です。
そのため、Apacheがインストールされたイメージをベースにしていました。

Apacheは仕様として、SIGWINCHによってGraceful shutdownします。
https://httpd.apache.org/docs/2.4/stopping.html#gracefulstop
そのため、Apacheの起動が前提となっているイメージではStopSignalをSIGWINCHに変更していることが多いです。
https://github.com/docker-library/php/blob/master/8.2/bullseye/apache/Dockerfile#L284

同様に、nginxやphp-fpmはSIGQUITでGraceful shutdownする仕様になっています。
http://nginx.org/en/docs/control.html
https://github.com/php/php-src/blob/17baa87faddc2550def3ae7314236826bc1b1398/sapi/fpm/php-fpm.8.in#L163
そのため、イメージのStopSignalはSIGQUITに変更されています。
https://github.com/nginxinc/docker-nginx/blob/master/Dockerfile-debian.template#L107
https://github.com/docker-library/php/blob/master/8.2/bullseye/fpm/Dockerfile#L274

Web、バッチの2つの用途で使っていたコンテナで、バッチでのみ現象が起こった理由もこのためです。
Webの方はSIGWINCHを受け取った後、ApacheがGraceful shutdownしていたのです。

旧コンテナは、LinuxディストリビューションのイメージにApacheもPHPも自分でインストールした、オンプレ環境を極力再現したイメージを使っていました。
この時はStopSignalをデフォルトのままにしていて、WebもバッチもSIGTERMにより終了していたのです。
Graceful shutdownをあまり意識できていませんでした。
そこに、ベースイメージの変更によりある意味正しい姿になったことで、考慮漏れが顕在化したような形です。

おわり

straceコマンドでシグナルを確認してみたお話でした。
Graceful shutdownを意識するのであれば、PID 1で動くアプリケーションごとにどんなシグナルをハンドルするのかきちんと整理して、その仕様に合わせたコンテナのコンフィギュレーションをするように心がけたいですね。