Rails, Unicorn, Nginxには標準でリクエストをタイムアウトさせる仕組みがあるが、Railsのログ（production.log）にはそのことが出力されない。
これでは困るので、タイムアウト時にログにそのことが出力されるようにする。
補足
Unicorn（unicorn.log）のログとNginxのログ（error.log）にはタイムアウトのエラーが出力されます。
先に結論： rack-timeout gemを使えばRailsでのタイムアウトとそのログ出力を実現できる
gem 'rack-timeout'
rack-timeout gemを入れていれば、development.log（またはproduction.log）に下記のようなログが出力される。docs
source=rack-timeout id=ed53930b-062f-43a6-abd4-395c2169d800 timeout=15000ms service=1001ms state=active
source=rack-timeout id=ed53930b-062f-43a6-abd4-395c2169d800 timeout=15000ms service=2005ms state=active
source=rack-timeout id=ed53930b-062f-43a6-abd4-395c2169d800 timeout=15000ms service=3002ms state=active
...
# タイムアウトの時間を過ぎた場合の例外
Rack::Timeout::RequestTimeoutException
そして、指定のタイムアウトをすぎると、Rack::Timeout::RequestTimeoutExceptionがraiseされる。
タイムアウト後に処理を入れたい場合は、上記の例外をApplicationControllerの中でrescueすればよい。
注意
既にタイムアウトした後なので、ここで複雑な処理をすることは避けるべきです
rescue_from Rack::Timeout::RequestTimeoutException do |e|
if request.xhr?
render json: {error: 'Timeout'}, status: :request_timeout
else
render plain: 'Timeout', status: :request_timeout
end
end
注意1
rack-timeout gemに指定するタイムアウト（デフォルトでは15秒）をUnicornやNginxのタイムアウトより短くしないと、タイムアウトのログは出力されません
注意2
タイムアウト処理は「実行時間が長すぎるリクエスト」に対するその場しのぎの解決策です。根本的にこの問題を解決するには、原因を特定し、コードのリファクタリングを行う必要があります。docs
Rails, Unicorn, Nginxでのタイムアウトの設定
UnicornとNginxはconfでタイムアウトを設定できます。
Unicornのタイムアウト
timeout 25
Nginxのタイムアウト
※Nginxの場合はproxy_read_timeout以外にも多数の種類のタイムアウトを設定できます
proxy_read_timeout 30;
Railsのタイムアウト
標準では、Railsにはリクエストをタイムアウトさせる仕組みはありません。特に何もしていないなら、UnicornやNginxでタイムアウトしてしまいます。
タイムアウトするだけなら特に問題はないです。しかし、その時のプロセスの終了方法に問題があります。
E, [2019-03-11T06:34:24.637107 #5886] ERROR -- : worker=0 PID:4508 timeout (31s > 30s), killing
E, [2019-03-11T06:34:24.643616 #5886] ERROR -- : reaped #<Process::Status: pid 4508 SIGKILL (signal 9)> worker=0
上記のように、UnicornではタイムアウトするとSIGKILLでワーカー（≒ Rails）を終了させてしまいます。強制終了されてしまうため、Rails側でそのことを知る方法がありません。
さらに、loggerがflushしないまま終了するため、強制終了されたリクエストがログに出力されることもありません。しかし、ちゃんと解決策はあって、rack-timeout gemを使うことでタイムアウトのハンドリングとログ出力をすることができます。
補足
Unicornにリクエストをタイムアウトされた時は、Nginxのerror.logに下記のようなログが出力されます。
2019/03/11 06:35:16 [error] 15059#0: *23754195 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 000.000.000.000, server: example.com, request: "GET /path/to/html HTTP/1.1", upstream: "http://unix:/tmp/unicorn.sock/path/to/html", host: "example.com", referrer: "https://example.com/
注意
KILLシグナルをRuby側で処理することはできますが、適切にハンドリングしないと「終了できないプロセス」になってしまうため注意が必要です。
Signal.trap 'INT' do
puts 'intercept INT and stop ..'
end
rack-timeout gemがやっていること
他の方が解説してくれている。解説記事
ここにも簡単に書くと、アプリケーションのメインスレッドとは別にタイムアウト用のスレッドを作り、そこで秒数をカウントする。指定の秒数を過ぎたら、タイムアウトの例外を発生させる。
Rubyにも標準でタイムアウトの仕組み（Timeout.timeout）があるが、これを使っていない理由は、秒数のカウントと段階的なログ出力のためだと思われる。
rack-timeout gemを入れさえすれば、これ以降はリクエストのタイムアウトがログに出力されるようになる。
source=rack-timeout id=ed53930b-062f-43a6-abd4-395c2169d800 timeout=15000ms service=1001ms state=active
source=rack-timeout id=ed53930b-062f-43a6-abd4-395c2169d800 timeout=15000ms service=2005ms state=active
source=rack-timeout id=ed53930b-062f-43a6-abd4-395c2169d800 timeout=15000ms service=3002ms state=active
...
# タイムアウトの時間を過ぎた場合の例外
Rack::Timeout::RequestTimeoutException
注意
rack-timeoutがハンドリングしたタイムアウトしかログに出力されません。このためには、UnicornとNginxのタイムアウトをrack-timeoutの値よりも大きくする必要があります。
Nginxのタイムアウト > Unicornのタイムアウト > rack-timeoutのタイムアウト
タイムアウト処理全般の注意点
タイムアウト処理は強制終了を伴うため、下記のような処理には注意が必要です。タイムアウトのタイミングによっては、リソースが開放されなくなる可能性があります。
begin
do_something
ensure
do_anything
# ここでタイムアウトしてしまうとリソースが開放されない
release_resource
end
注意
rack-timeoutを使うかどうかに関係なく、どんな場合にでも起きうる問題を挙げています
参考リンク
Rack::Timeout::RequestTimeoutException の仕組み