akippaでバックエンドのリードエンジニアをしている村上です。

「進撃の巨人」のアニメ、つい先日に完結編が放送されましたね。
主人公エレンの「一匹残らず駆逐してやる！」というセリフにあやかって、今回は、最近私が取り組んでいたプログラムエラーのリアルタイムでの検知と、そこで検知したエラーの駆逐活動を通じて改めて考えさせられた事についてつらつらと書きたいと思います。

何を検知すべきか？

プロダクトを開発・運用・保守されている方であれば、AWSのCloudWatch等、様々なサービスやメトリクスを用いて、なんらかの監視やら検知をされている事かと思いますが、皆さんは何を監視されているでしょうか。
私がakippaに入社当時は、主にEC2インスタンスの以下の3つが監視対象とされていました。

• CPU使用率

• メモリ使用率

• ディスク容量

EC2で運用する以上、ディスク容量は、枯渇するとたちまち動かなくなりますので、今でも大事なメトリクスかと思います。(数年前ですが、日曜日に枯渇した事が検知され、慌ててショッピングモールから帰宅してディスク整理した事があります ^^; )
ただ、CPU使用率やメモリ使用率は、この警告が一回ポンっと上がったからと言って、それが続くわけでなければ「あーまたかー。なんかアクセスが多かったのかなー？」という感じで、たちまちオオカミ少年アラームと化してしまっている、という事はないでしょうか。
CPU使用率やメモリ使用率は、90%を超えても正常動作している可能性は充分あります。
有名な書籍である「入門 監視」にも同じような事が書かれています。

この書籍は色々な事が書かれてますが、ユーザーに直接影響が出ているかどうかという観点で監視対象とすると良いと書かれていた事の一つに

• HTTPレスポンスステータスコード500系エラー

上記を監視対象とすると良い、という事が書かれています。
HTTP500エラーが1度でも起こったという事は、まさにユーザーにエラーが表示されて何か問題が起こったという事になります。
何年前だったかにこの書籍を読んで、すぐにakippaにもHTTP500エラーの検知については仕込みました。
AWSで運用されているのであればCloudWatch Alarmにサクッと追加できますので、もしまだ検知対象としていないという事であれば、是非検討してみてください。
では、次に500系エラーを検知した後の行動についてです。

HTTP500エラーはどこで起きているのか？

実際にHTTP500エラーを検知したら、次はどこで起きているのかを調べる必要がありますね。
akippaでは、ALBのアクセスログをS3に保存する設定をしていて、そのS3のログをAthenaでSQLライクで調べる事ができるようにしています。(以下記事参照)

これはこれで便利なのですが、500エラーを検知してから、AWSコンソールに入り、Athenaで該当時間の500エラーがあったリクエストがどれなのか…っていうのをなんとか調べて、どのリクエスト、どのサーバで起きたエラーかわかった！となったら次は、なぜ500エラーになったのかを、実際にエラーが起こったサーバのアプリケーションログを探しにいって、これまた不要な情報もいっぱい書かれたログの中から、該当時間辺りの行までいって、やっとエラー発生時のスタックトレースの内容にたどり着く…という現状でした。

HTTP500エラーはいつ検知すべきか？

上述の通りの運用では、CloudWatch経由で検知するので、実際に500エラーが起こってから検知するまでに、若干のタイムラグが発生してしまっていました。
また、エラー内容を調べるのに手間も掛かるので、エラーが頻発していないときや多忙なとき等は、どうしても調査が後回しになりがちでした。
この状態だと、プロダクトチームが検知する前に、CSや利用部門からの問い合わせで動き出すなんて事もあり、迷惑を掛けてしまっていることも良くないと思っていました。
HTTP500エラーはいつ検知すべきか？
もはや古い決めゼリフですが「今でしょ！」です。
やり方はどうあれ、500エラーを発生したタイミングで、速やかに検知し、またどこでエラーが起こったのかも速やかにわかるようにする。
という事に取り組みました。

リアルタイムでのエラー検知

akippaでは、PHPのLaravelフレームワークを利用しています。(他の古いフレームワークを使ったプロダクトも依然大活躍中ですが)
Laravelでは、以下のファイルにて、アプリケーションが投げるほぼすべての例外を受ける事ができます。
app/Exceptions/Handler.php
githubでLaravelの複数バージョンのソースを見たところ、見た中では全てのバージョンで上記のファイルは存在しているようでしたので、Laravel使っていれば大体同じでしょう。
細かいカスタマイズ内容は割愛しますが、akippaの場合、ここの処理をカスタマイズして、例外発生時は、例外のスタックトレースをSlack通知させるという事をしました。
プロダクトに直接手を入れるのではなく、別のサービスを活用してやった方がかっこいいとは思うのですが、手っ取り早く目的を達せられる手段だと判断して、この手法にしました。
先日からこの運用を開始して、実に多くのエラーを検知し、また、それに対する修正も行う事を継続的に行っております。
で、ここで検知したエラーの対応をしていて、僕が改めて考えさせられたエラーハンドリングに関する注意点をいくつか挙げたいと思います。
当たり前やろっていう内容ばかりかもしれませんが、意外と忘れがちなんじゃないかと思い、自戒の思いも込めて！

エラーハンドリングに関する注意点

不要なログ出力は避ける

こんなコードをたまに見かけないでしょうか。

try {
    $service->send();
} catch (Exception $e) {
    // 例外発生時、特に何もする事はないので、とりあえずログには残す
    \Log::error($e->getMessage());
}

例外発生時に特に何もする事はない、という事はあるかもしれません。
例えば、アクセス解析等の外部サービスに情報を送る処理があるが、その送信処理でエラーとなっても致命的ではないから、後続処理は続行させるとか？まあ、それはよいでしょう。
ただ、ここで出力したログは一体、誰が、いつ見るんでしょうか。
このコードを書かれたご本人(或いはチーム)が責任持ってログを見る習慣があるのならば良いと思いますが、そうでないなら、このエラーが発生しても、誰も気が付きません。
ここでログを出したとして、いつ、誰が見るかな？って想像をしながらログ出力処理を書くのがよいのではないかなと思います。
余計なログ出力はログファイルへのノイズとなり、他のエラー調査の邪魔になるので、把握しなくていいエラーなら、いっその事ログ出力しない方がいいかなと思います。
ちなみに、不要なログ出力は避けた方がよいと思ってますが、必要なログはどんどん出力したらいいと思います！

例外を握りつぶさない

今回のエラー対応をしていて、以下のようなコードがありました

try {
    $useCase->execute();
} catch (\Exception $e) {
    throw new \Exception('エラーが発生しました。操作をやり直してください。');
}

多分、プログラムエラーの内容をユーザーが見る画面に出したくなかったのかなと思いますが、これの問題は、エラー発生時にSlack通知されたものの、スタックトレースには、catch句内でthrow newしているExceptionの情報が書かれているだけなので、catchしたExceptionの情報はどこにも残っていないという事態になっています。
このような例外の握り潰しは、本当に起こった問題の調査を妨げます。
上記のような場合は、次に書きますが、エラー内容が画面に出ないように別のところで対応しておくのが大前提として、そもそもcatchしないか、catchするにしても元の例外内容はログに残すなどするべきかなと思います。

エラーの詳細内容をそのまま画面に出さない

先程軽く触れましたが、プログラムのエラーの内容がそのままユーザーが見る画面に出てくるのはセキュリティ上よくありません。
徳丸本とも言われる以下書籍等、色んなところで言われている事なので、理由等々割愛しますが。

詳細なエラー内容はログに残し、ユーザーが見るエラー画面には「エラーが発生しました」「再実行してください」「問い合わせください」等、ユーザーさんに取ってほしい行動やその他汎用的な表現にする事が望ましいでしょう。
akippaでは、実に最近まで、フロントサイトで起こったエラーがそのまま画面に出る状態になってました…。修正済みです！

HTTPレスポンスステータスコードを意識する

今回の記事冒頭で、HTTP500エラーを監視すると言いましたが、例えば以下のコードを例にしてみます。

try {
    $data = $parking->find($request->parking_id);
} catch (ParkingNotFoundException $e) {
    throw new \Exception('駐車場が見つかりませんでした');
}

上記は、リクエストされたIDの駐車場を検索した結果、見つからない場合はExceptionをスローするというコードです。
これが、ユーザーさんが直接URLを手入力するなどで存在しない駐車場のIDが普通にリクエストされる場合があるとします。
この場合、普通のExceptionをスローすると、HTTPレスポンスステータスコードとしては、500エラーになってしまいます。(実装によりますが。)
500エラーを検知し始めると、このように、検知しなくてもよい例外をたくさん検知する事がありました。
上記のような場合は、LaravelであればNotFoundHttpExceptionをスローするなど、ステータスコード404となるようにしておく事が良いでしょう。
ご自身でエラーハンドル処理を書く場合、HTTPレスポンスステータスコードとしては何を返すのが正しいのか！？は、きちんと考えるべきかなと思います。
クライアントのリクエスト起因で起こるものは400系、サーバやシステム側のエラーとすべきなら500系。
400系の中でも、見つからないのか、権限の問題なのか、なんなのか？っていうのを考えて、適切なコードを設定しましょう。
400系エラーは、クライアント側のURL直接入力等で通常に起こり得るものがほとんどで、検知しても取れる対応がほぼ無いし、エラーとしている事が実装として正しいわけなので、検知不要と考えています。
そのエラーは、検知するべきものかどうか？でも500系とするか400系とするかの判断軸になるかと思います。

リアルタイムで検知するようにしてよかったこと

エラー発生をリアルタイムで検知するようにした事で、エラーが発生したタイミングで、誰よりも早く(正確には、そのエラーに遭遇したユーザーさんの次ですが)知る事ができるので、関係者や責任者に対して、問い合わせがある前に先行して連絡や相談する等の先手を打つ事ができます。
何か問題があったら、誰かが何か言ってくるだろう…という姿勢では、プロダクトへの信頼を失ってしまったり、対応が後手になってあたふたする等もあるでしょう。

あと、実際にどれぐらいのエラーが発生しているのか？を、感覚ではなく実際に知る事ができたので、発生していたエラーは実は大した事ない問題でなかったな、とか、意外とエラー起きてないんだな、とかを肌で感じる事ができました。
もしかしたら致命的な問題が見つかっていたかもしれませんが、そういうのがあったら、尚の事良かったと感じた事でしょう。
開発中のテストで見つからなかった不具合がもしあっても、エラーが生じた時点ですぐに検知する事ができるという安心感も得られます。

また、上述したようなエラーハンドリングについて、改めて考えさせられる良いきっかけになりました。

という事で、akippaのプロダクトで起こる様々な500エラーたちよ。
一匹残らず、駆逐してやる！