gunicornの [CRITICAL] WORKER TIMEOUT で本当の原因がわからなくなる問題

GKE上で動かしているgunicornアプリケーションで、特に負荷が高いわけでもないのに、突然

 [CRITICAL] WORKER TIMEOUT (pid:667)

というログを出しまくって止まってしまうことが発生していた。

いつなるかわからないのでしばらく見守っていたけど、原因を調べることにした。

gunicornのタイムアウトはconfファイルで設定している。

gunicorn_conf.py

worker_class = "gevent"
proxy_protocol = True
x_forwarded_for_header = "X-Real-IP"
bind = ":80"
# reload = True
timeout = 5
graceful_timeout = 5
# loglevel="debug"

Dockefileでは下記のように実行

CMD ["gunicorn", "-c", "gunicorn_conf.py", "arms:app"]

エラーが発生したときには、ログには上記の [CRITICAL] WORKER TIMEOUT が連発するだけで、エラーの原因がわからないなーと思っていたけど考えれば当たり前で、アプリ内の処理は特に時間がかかっているだけなので、エラーとは認識できない。

そのため、これから下記の対策を行う。

1. タイムアウトが発生しそうなところ（DBとかRedis等外部への接続する関数） にすべて短めのタイムアウトをつける
2. gunicornのタイムアウトは1でエラーが発生できるようにちょっと長めにする

タイムアウトは以前記事にも書いたtimeout-decoratorを使う。

uyamazak.hatenablog.com

そして、本番公開を行ったけど、いつ起こるかわからないのでしばらく様子見。

現時点の仮説としてはおそらくRedisへの接続でたまに時間がかかってしまうのと予想している。

アクセスの負荷とはあまり関係ないので、GKEでRedisのpodが移動したりでネットワークがつながらなくなっている可能性も。

その際は待っても解決しないので、PODごと落として、再起動させる必要があるかも。