運用していたAPI Serverが気づいたら異常終了するようになっていた話

f:id:nanakookada:20210325165934p:plain — 運用していたAPI Serverが気づいたら異常終了するようになっていた話

はじめに

今回は運用していたAPI Serverが気づいたら異常終了するようになっており、原因の特定と対策をした話をしようと思います。

発生していた障害

今回発生していた障害の詳細は以下になります。

ECS上で運用していたAPI Serverが異常終了するようになっていた
- タスクの終了ステータスを監視するスクリプトを動かし始めたタイミングで発覚
- ExitCode 2 でタスクが終了している
異常終了は発生する日としない日がある
- 同一の日に複数回発生はしていない
異常終了が発生するのは12時から13時の間
タスク数は2で起動していたが、2つのタスクが同日に異常終了することはなかった
異常終了する直前のメトリクスに通常時と異なる箇所は見られなかった

外形監視はしていたのですが、タスクの終了ステータスは監視していなかったため発見が遅れました。また、発見が遅れたためどの変更が原因でいつから異常終了するようになっていたのかがわからない状態でした。

原因調査

調査1 : コードの更新

まず最初にExitCode 2でタスクが終了していることからpanicが発生しているのではないかと考えました。
今回異常終了していたAPI Serverは、同一のdocker imageを使用し、環境変数によって内部向け・外部向けを変更する構成になっており、外部向けの方でのみ異常終了は発生していました。
外部向けのAPI Serverに関しては、自動デプロイの対象になっておらず直近でデプロイも行われていなかったため、内部向けAPI Serverと差分が発生している状態でした。
差分が発生し、外部向けAPI Serverでのみ異常終了が発生していたため、差分に原因があるのではないかと考え差分をなくすためにデプロイを実施しました。
しかし、差分がなくなった状態でも状況に変化はなく、外部向けAPI Serverでのみ異常終了は発生し続けました。

調査2 : アクセスに起因したものではないか

調査1にて内部向けとの差分をなくしても状況に変化がなかったで、次は特定のリクエストによって発生しているのではないかと考えました。
API Serverではアクセスログを出力していたのですが、このアクセスログはレスポンスを返すタイミングで出力していたため、処理の途中で異常終了してしまった場合にはログは出力されていません。
そこで、調査のために処理の途中でも適宜ログを出力するようにして、処理途中で異常終了した場合にもどんなリクエストが来ていたかわかるよう変更を加えました。
しかし、異常終了が発生した後にログを確認したところ、該当の時間に処理を行っているログは出力されていませんでした。

調査3 : システム系を疑う

調査2によって、リクエストによって発生しているわけではないことがわかったので、API Serverのコード以外の要素で異常終了する理由がないかと考え調査を続けていました。異常終了が発生するのは12時から13時の間だけのため、この時間帯に何かしらの処理が動いて、それが原因なのではないかと考えました。
API Serverのコンテナが動いているインスタンスにて該当の時間帯に動いている処理を確認したところ、ログローテートの処理がありました。
ログローテートの設定は下記のようになっていました。

{
    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>で対象のコンテナをしぼっています。
調査1にて記載していますが、異常終了していたAPI Serverは同一のdocker imageを使用し、環境変数で内部向け・外部向けを変更するようになっています。
そのため、内部向けと外部向けのAPI Serverが同一のインスタンスに存在した場合、実際にはログローテートをしていない方のAPI Serverにもシグナルが送られるようになっていました。
どちらのAPI ServerでもSIGHUPをハンドリングするようになっている場合には問題はないのですが、外向けのAPI ServerではSIGHUPのハンドリングをするようになっていませんでした。
確認のため、検証環境にて外向けのAPI Serverに対してSIGHUPシグナルを送ってみると異常終了することが確認できました。

行った対応

原因の特定ができたので、対応策を考えます。
今回候補に上がった対応策は下記の3つになります。 - 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が終了していたという情報と障害が発生していた時間から原因を想像して、対処をすることができました。
対応後にチーム内にて簡単に振り返りを実施してみたところ、トレースを実施することでより詳しい情報が取得でき、原因の特定がスムーズにできたのではないかという意見がありました。
トレースする対象としてはシステムコール・パケット・ブロックIO等が考えられます。
今回の障害の場合、システムコールをトレースしてみればSIGHUPが送られて来ていたことがわかったはずです。

実際にシステムコールをトレースしてみた例を下記に示します。
今回障害が発生していたAPI ServerはGoで記述したものをdocker上で動かしており、dockerを動かしているホスト及びAPI Serverが起動しているコンテナ内に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を動かす方法については、下記のサイトを参考にさせていただきました。

https://qiita.com/minamijoyo/items/9dd59109e9fe1a35f888

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が送られてきていることがわかり、調査をスムーズに進めることができたと思いました。
しかし、トレースを実施すると何かしらオーバヘッド等が発生するため、なるべくなら検証環境などで不具合を再現し、その環境でトレースを行うことが望ましいです。ですが、今回のように再現が困難な場合にはオーバーヘッドが発生することを考慮にいれ、本番環境でトレースを行うことも１つの方法としてあったと思います。

さいごに

今回は実際に起こった障害の事例を元にどういったことを考え調べていったのかについて話しました。障害の調査をする時には、想像力を働かせて色々な原因を考えて一つ一つ確認していくことになると思います。その時今回のように気づくのが遅れてしまうと、考えうる原因が増え対応の時間が長引くだけでなく難易度もあがってしまいます。こうならないためにも、適切な監視を設定することが大事だと改めて感じることができました。
今回のような失敗談を記事にすることで、みなさんの障害調査の時の手助けや監視設定を見直すきっかけになれば幸いです。

every Tech Blog

株式会社エブリーのTech Blogです。