発生した障害
Railsのapiサーバーのstagingサーバーでもデプロイ時の自動テストもちゃんと動くのに、productionでは動かないという一番困るエラーがおきました。新たに追加したAPIだけが動かないのです！
環境差分が引き起こした問題のトラブルシューティング
今回のケースはローカルのテストもstagingのテストも、自動テストも通っているので環境差分でなにかまずい事が起きていることが明白です。
環境差分の場合、概ね3つのケースが考えられます。
- 環境変数やその他、環境に注入している環境依存の値がおかしい
- DBのmigrationがproductionとstagingとlocalで一致していない、テーブルの設定に差異がある
- 間に挟まっているミドルウェア（LB,nginx,redis...etc)
が多いです。
1つ目はそのままですね、環境毎に変えたい値を入れるための値が環境変数なので。（私は環境変数はグローバル変数と同じだと思っているので別で管理したい派ですが手軽なのでついつい増えがち）
今回はAPI、1つだけが動かず、環境変数も利用していないのでこいつには該当しません。
2つ目のDBに関しては、migrationに差分があるケースと、tableのdefaultのcharsetやcollationがlatinになっていて検索結果が一致しないなど。今回はそういう類のエラーではないのでこいつじゃない。
つまり
3つ目のミドルウェアに違いない。
とたどり着きました、というのは嘘で、既にRails側にログが出力されていことから薄々通信がどこかで止まっているな？と思っていました。なんならエラーの内容がRailsが出すエラーじゃなかったのでどいつだ？このエラーを出しているのは？！っとなっておりました。
吐いていたエラーがこちら。
<?xml version="1.0" encoding="utf-8"?>
<!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Strict//EN" "http://www.w3.org/TR/xhtml1/DTD/xhtml1-strict.dtd">
<html>
<head>
<title>503 first byte timeout</title>
</head>
<body>
<h1>Error 503 first byte timeout</h1>
<p>first byte timeout</p>
<h3>Guru Mediation:</h3>
<p>Details: cache-3xxxx2-TYO 1yyyy31 xxzzzz74</p>
<hr>
<p>Varnish cache server</p>
</body>
</html>
Varnish cache serverだと！
実は本番とstagingで違うミドルウェアが使われていた
cashe serverなんて使っていたかしら？うーん？と考えてみるとそういえば本番だけ
fastly
が入っていました。でも何でエラーを返しているんだろう？？timeout errorってことはなにか処理が重いのかな？と思い、APIの中の処理を本番環境で実行してみます。
すると本番だけ異常に遅いSQLが1つ見つかりました。indexが効いていないせいでおそおそSQLが。そのSQLが20秒近くかかっており、インフラ担当にfastlyのtimeoutの設定どのぐらいにしている？と聞くと15秒...こいつじゃん。
結局ミドルウェアじゃなかった
ミドルウェアはちゃんと仕様通りにエラーを出していただけで原因じゃなかった。原因は遅すぎるSQLでした。Index貼り直して解決。
オチをまとめると、ミドルウェアがRailsにログを出させないせいでSQLが遅すぎて死んでいるということに気づくのが遅れたということでした。たまにはリアルな障害対応を書いてみようと思い記しました。 #屍踏んでけ