GoのWebアプリケーションでステータスコード499を記録する
この記事は、Go 4 Advent Calendar 2020の16日目の記事です。
さて、ある日、Goで書かれたHTTP APIサーバーのdeployをしたところ、急に500エラーの発生率が上がったことがありました。しかし幸いにもユーザー影響は出ていません。どうしたのでしょうか？
ALBログの調査
このシステムはAWSのApplication Load Balancer(ALB)からプロキシされていますが、エラーリクエストに対応するALBのログを調べるとステータスコード460が記録されていました。460を調べると以下のように書いてあります。
The load balancer received a request from a client, but the client closed the connection with the load balancer before the idle timeout period elapsed.
https://docs.aws.amazon.com/elasticloadbalancing/latest/application/load-balancer-troubleshooting.html
「ははぁ、これはNginxの499だな」とピンときました。サーバーがレスポンスを返す前に、クライアントが接続を切ってしまっている。例えば、スマートフォンが地下鉄など電波の届かないところに急に入ってレスポンスを受け取る前に切れてしまう等です。だからユーザー影響は出ていなかったのでした。
ところで、何故ALBはNginxと同様にクライアント断を499にしなかったのだろうと思ってしまいます。確かに499自体もそもそもは独自httpステータスコードではあるのですが、昨今4xx系のステータスコードも空きが減ってきているので、あまり独自ステータスコードを増やすのはお行儀が良くないのではないかと。ALBのエラー画面などは以前はNginxぽい感じでしたし、かなりNginxを意識して作られたサービスだと思うので余計にそう思います。
500エラーの原因判明
閑話休題。このシステムが500を返すのは、ハンドルできないerrorが上位に上がってきた場合なのですが、エラーログを確認すると果たして"context canceled"というログが記録されていました。つまり、contextのキャンセルエラーが伝播されてきて、それがハンドリングできていなかったということです。
このシステムでは、http handler内部でメインの処理に req.Context() を受け渡しています。近年GoでWebアプリケーションを書く場合には一般的なプラクティスでしょう。
ではこの req.Context() がキャンセルされるのはどの様な場合でしょうか？もちろんちゃんと公式ドキュメントに書かれています。
For incoming server requests, the context is canceled when the client's connection closes, the request is canceled (with HTTP/2), or when the ServeHTTP method returns.
https://golang.org/pkg/net/http/#Request.Context
クライアントが接続を切ったか、ハンドラーが終了したときにキャンセルされると書いてあります。今回の場合はハンドラー内部でキャンセルエラーを受け取っているため、クライアントが接続を切ったと考えると良さそうです。ALBに460が記録されているという事実とも合致します。
つまり、クライアントの接続断が起因でcontextがキャンセルされ、ハンドラー内部の処理もキャンセルされて、エラーが上がってきたというわけです。
実際、当該deployには、処理の内部でcontextを引き回せてない部分をちゃんと引き回すようにする修正が入っていました。それが原因でした。
解決方法
ユーザー影響は出ていないとは言え、この様なときに500エラーを返しっぱなし、正確に言うとクライアントには返っていないので記録しっぱなしにしておくのは、オペレーションの観点からもよろしくありません。ここは、Nginxに倣って、499を記録することにしましょう。
参考のため再掲: https://httpstatuses.com/499
errors.Is(err, context.Canceled) とチェックをしてその場合に、499を返せばよいと思うかも知れませんが、そう単純ではありません。処理内部で内部で context.WithCancel が使われるなどして、そのキャンセルエラーが上がってくる可能性があるためです。つまり、context.Canceledであっても必ずしもreq.Context() 自体がキャンセルされたとは限らないのです。
req.Context() がキャンセルされたかどうかを判断するためには、req.Context()が完了しているかどうかを判定すればよいでしょう。以下のように select と default を使うと良さそうです。リクエストが完了していない場合はdefaultに入るため、その下の処理に流れていきます。
select {
case <-req.Context().Done():
w.WriteHeader(499)
return
default:
}
まとめると、メインの処理が返してきたerrorをハンドリングして、必要な場合に499を記録するコードは以下のようになるでしょう。
const httpStatusClientClosedRequest = 499
func(w http.ResponseWriter, req *http.Request) {
if err := mainProcess(req.Context()); err != nil {
if errors.Is(err, context.Canceled) {
select {
case <-req.Context().Done():
w.WriteHeader(httpStatusClientClosedRequest)
return
default:
}
}
http.Error(w, "Internal Server Error!", http.StatusInternalServerError)
return
}
...
}
これで、500エラーが出なくなったためアラートも収まり、安心して眠れるようになりました。めでたしめでたし。
採用情報
ということで、スマートリモコンNature RemoなどのIoT製品を開発している、Natureでは、このように細かい割れ窓も素早く察知し、詰めをしっかり実装できるエンジニアを募集しています。興味のある方はぜひご応募ください。