この記事は エムスリー Advent Calendar 2020 の11日目の記事です。
こんにちは、エンジニアリンググループ マルチデバイスチームの大和です。
気づけば12月も半ばで2020年の終わりをそろそろ感じる時期になってきました。
今年一年間で様々なプロダクトをリリースし活躍された方もいれば、本番環境で問題が発生しヒヤッとした方もいらっしゃると思います。
この記事では、厄払いとして私が起こした本番障害とその対応について紹介していきます。
ポストモーテムとは
ポストモーテムとは、 incident、その影響、軽減または解決するために実行されたaction、根本原因、および再発を防ぐためのactionの記録 であり、
Googleが公開した Site Reliability Engineering と呼ばれる書籍によって広まったといわれています (15章 Postmortem Culture: Learning from Failureより引用)。
この記事では厳密な意味とは異なりますが、問題が発生した際に記録として残すエンジニア向けのドキュメントの意味で使用します。
私が所属するチームでは、Confluence上に 障害の記録 という形で記録する形をとっています。
Slack上のチャットやJIRAチケットを経由して原因となった修正をリンクするようにしており、後から見た人がどのような経緯で問題が起こり、
どのような修正により解決したかについて追える形で記録するようにしています。*1
障害の振り返り
- nginxの設定ミスによるデプロイ失敗
- 検証環境と本番環境の差分によるデプロイ失敗
それぞれ紹介していきます。
1. nginxの設定ミスによるデプロイ失敗
あらまし
ECS上でnginxがproxyする構成 (reverse proxy) のWebサーバがあり、proxy先はECS Service Discoveryで名前解決していました。 そのproxyの設定は次のようになっています:
proxy_pass http://api.local:8080;
これでWebサーバは動作していましたが、デプロイ時に問題が発生します (一部改変)。
2020/09/29 09:40:02 [error] 31#31: *1203 no live upstreams while connecting to upstream, client: 192.168.0.1, server: localhost, request: "GET /foo/bar HTTP/1.1", upstream: "http://api.local/foo/bar", host: "api.example.com"
原因および解決
ヘルスチェックも時間経過で502や503になりアクセスできない状況になっていましたが、nginxのECS Taskを再デプロイすることで復旧しました。
hostの api.local はECS Service Discoveryにより新しいIPアドレスに名前解決されるはずですが、なぜアクセス不能になってしまったのでしょうか？
それは proxy_pass をそのまま使用した場合、 起動時に名前解決したIPアドレスがそのまま使用される ためでした。
これを回避するためにはリンク先の記事でも解説されていますが、変数に格納することで解決できます:
set $upstream_server api.local:8080; proxy_pass http://$upstream_server;
表面上は動いているように見えても実は問題があるケースとして、各アプリケーションやAWSのサービスがどのように動作しているかを把握することの重要性を示す一件でした。
なお、参考記事にもある resolver の valid の設定については、ECS Service Discoveryで設定されるTTLが十分短い (10s) ことを確認したので入れませんでした。
2. 検証環境と本番環境の差分によるデプロイ失敗
あらまし
Spring Bootで組まれたWebサーバがあり、 Flyway でDBのmigration管理をしていました。 migrationは起動時に行われ、新しいversionがあった場合に適用される形になっています。
いつも通りに開発を行い検証環境にデプロイした後、QAが済んだので本番環境にデプロイしようとしたときのことです。 デプロイスクリプトを実行して出力を確認していたところ、途中でエラーを吐いて止まってしまいました。 その時のエラーがこちらです (一部改変):
Migration V50__add_foo_project.sql failed ------------------------------------------------ SQL State : 23505 Error Code : 0 Message : ERROR: duplicate key value violates unique constraint "team_pkey" Detail: Key (id)=(3) already exists. Location : db/migration/V50__add_foo_project.sql
こちらは書いてあるとおり、アプリケーションの起動時に新しいSQLファイルが有るためdata migrationが行われましたが、IDが被ってしまい失敗したログでした。
ここでは新たに id=3 のマスタを追加することが目的でした。
問題なのがFlywayによるmigrationは起動時に行われるため、失敗してしまうとアプリケーションの起動にも失敗してしまうことです。
原因および解決
直接的な原因は id=3 のマスタが本番環境のみに存在することでした。
もちろん検証環境で動作することは確認済みで、本番環境と検証環境に差分が出ないように運用することで本番環境での動作を担保していました。
ではなぜ環境のずれが起こってしまったのでしょうか。
それは過去に運用を変更した際の確認不足が原因でした。 数年前、今回起こった問題とは別のマスタがUIでの操作により本番環境と検証環境で差分が発生する問題が起こっていました。 これを解決するためにマスタはUIでの操作で変更できないようにし、Flywayで管理するようにしました。 しかし、問題が発生した部分について重点的に確認していたため、ほとんど更新されない (数年に一度程度の) マスタについて確認が取れていませんでした。
幸いにもアプリケーションはローリングデプロイしていたので、複数台あるうちの一台のみが停止するだけで済みサービス停止までは至りませんでした。
デプロイの失敗を確認後、本番環境から id=3 のrowを削除することで検証環境と揃えて再びデプロイすることで動作するようになりました。
再発防止のためには、最初からマスタの管理について差分が出ないような手段で運用すること、運用を変更する場合には既にずれてしまったマスタがなかったか確認することが必要だと考えます。
まとめ
私が今年やらかしてしまったものについて2件紹介しました。 来年以降同じことを繰り返さず、将来発生しうる障害を未然に防げるように努力していきます。
最後になりますが、この記事は 本番環境でやらかしちゃった人 Advent Calendar 2020 をリスペクトしています。*2
みなさんの知見を共有することで短期間でもサービスを利用できない人を一人でも減らし、便利な世の中になるように貢献していきましょう！
We are hiring!
障害をできる限り発生させないようにする仕組みづくりを一緒に行ってくれる方を募集しています！
話を聞いてみたいと思われた方は、以下のリンクよりカジュアル面談を申し込んでいただけるとうれしいです。
