運用していたAPI Serverが気づいたら異常終了するようになっていた話
はじめに
今回は運用していたAPI Serverが気づいたら異常終了するようになっており、原因の特定と対策をした話をしようと思います。
発生していた障害
今回発生していた障害の詳細は以下になります。
ECS上で運用していたAPI Serverが異常終了するようになっていた
タスクの終了ステータスを監視するスクリプトを動かし始めたタイミングで発覚
ExitCode 2 でタスクが終了している
異常終了は発生する日としない日がある
異常終了が発生するのは12時から13時の間
タスク数は2で起動していたが、2つのタスクが同日に異常終了することはなかった
異常終了する直前のメトリクスに通常時と異なる箇所は見られなかった
外形監視はしていたのですが、タスクの終了ステータスは監視していなかったため発見が遅れました。
また、発見が遅れたためどの変更が原因でいつから異常終了するようになっていたのかがわからない状態でした。
原因調査
調査1 : コードの更新
まず最初にExitCode 2でタスクが終了していることからpanicが発生しているのではないかと考えました。
調査2 : アクセスに起因したものではないか
調査1にて内部向けとの差分をなくしても状況に変化がなかったで、次は特定のリクエストによって発生しているのではないかと考えました。
調査3 : システム系を疑う
調査2によって、リクエストによって発生しているわけではないことがわかったので、API Serverのコード以外の要素で異常終了する理由がないかと考え調査を続けていました。
異常終了が発生するのは12時から13時の間だけのため、この時間帯に何かしらの処理が動いて、それが原因なのではないかと考えました。
{
missingok
notifempty
compress
delaycompress
daily
rotate 7
postrotate
docker container kill -s HUP `docker ps | grep <image-name> | awk '{print $1}'` 2> /dev/null || true
endscript
sharedscripts
}
ログローテート後に、ログの出力先ファイルを変更するために条件に合致するコンテナに対してSIGHUPシグナルを送っていました。
ここではシグナルを送る先としてgrep <image-name>で対象のコンテナをしぼっています。SIGHUPをハンドリングするようになっている場合には問題はないのですが、外向けのAPI ServerではSIGHUPのハンドリングをするようになっていませんでした。SIGHUPシグナルを送ってみると異常終了することが確認できました。
行った対応
原因の特定ができたので、対応策を考えます。SIGHUPを送る先の抽出条件を修正する
- 内向けと外向けのimage名を分離する
- シグナルをハンドリングする
本来でしたら3つすべて実施したほうがいいのですが、 まずは応急処置として実装工数が一番少なく済むと判断した、シグナルハンドリングの修正を行うことにしました。
DELISH KITCHENではGoでAPI Serverの実装を行っており、Goではシグナルハンドリングos/signageパッケージに定義されているIgnoreメソッドを使えばできます。https://golang.org/pkg/os/signal/#Ignore
signal.Ignore(syscall.SIGHUP)
上記の対応を実施したあと、検証環境にて外向けのAPI ServerにSIGHUPを送ったところ問題なく稼働し続けていることが確認できました。
振り返り
今回はExitCode 2でAPI Serverが終了していたという情報と障害が発生していた時間から原因を想像して、対処をすることができました。SIGHUPが送られて来ていたことがわかったはずです。
実際にシステムコールをトレースしてみた例を下記に示します。straceがインストールされていないため、PID名前空間を共有したコンテナを起動し、起動したコンテナ内でstraceを実行しています。
echo -e 'FROM alpine\nRUN apk add --no-cache strace' \
| docker build -t debug -f - . \
&& docker run -it --rm --pid container:<containe_id> --cap-add sys_ptrace debug strace -fp 1
docekrで動かしているコンテナに対して、別のコンテナからstraceを動かす方法については、下記のサイトを参考にさせていただきました。
straceをした状態でSIGHUPを受信するした時のログは下記になります。
[pid 6] nanosleep({tv_sec=0, tv_nsec=20000}, <unfinished ...>
[pid 13] <... futex resumed>) = 0
[pid 13] futex(0xc000211d48, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 6] <... nanosleep resumed>NULL) = 0
[pid 6] futex(0x17c4e78, FUTEX_WAIT_PRIVATE, 0, {tv_sec=59, tv_nsec=137259289} <unfinished ...>
[pid 10] <... epoll_pwait resumed>[], 128, 1, NULL, 0) = 0
[pid 10] epoll_pwait(3, [], 128, 0, NULL, 2) = 0
[pid 10] epoll_pwait(3, <unfinished ...>
[pid 1] <... futex resumed>) = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
[pid 1] --- SIGHUP {si_signo=SIGHUP, si_code=SI_USER, si_pid=0, si_uid=0} ---
[pid 1] futex(0x17efbc0, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 10] <... epoll_pwait resumed>[{EPOLLIN, {u32=4118929128, u64=140509679050472}}], 128, 59136, NULL, 0) = 1
[pid 10] futex(0x17c4e78, FUTEX_WAKE_PRIVATE, 1) = 1
[pid 6] <... futex resumed>) = 0
障害が起こっているAPI Serverに対してstraceを実行し上記のようなログがでていることを確認できていれば、どこからかSIGHUPが送られてきていることがわかり、調査をスムーズに進めることができたと思いました。
さいごに
今回は実際に起こった障害の事例を元にどういったことを考え調べていったのかについて話しました。
障害の調査をする時には、想像力を働かせて色々な原因を考えて一つ一つ確認していくことになると思います。
その時今回のように気づくのが遅れてしまうと、考えうる原因が増え対応の時間が長引くだけでなく難易度もあがってしまいます。
こうならないためにも、適切な監視を設定することが大事だと改めて感じることができました。
