Railsでタイムアウトのエラーをログに出力する方法

Rails, Unicorn, Nginxには標準でリクエストをタイムアウトさせる仕組みがあるが、Railsのログ（production.log）にはそのことが出力されない。

これでは困るので、タイムアウト時にログにそのことが出力されるようにする。





**補足**
Unicorn（unicorn.log）のログとNginxのログ（error.log）にはタイムアウトのエラーが出力されます。






## 先に結論： rack-timeout gemを使えばRailsでのタイムアウトとそのログ出力を実現できる



```ruby:Gemfile
gem 'rack-timeout'
```

rack-timeout gemを入れていれば、development.log（またはproduction.log）に下記のようなログが出力される。[docs](https://github.com/heroku/rack-timeout/blob/master/doc/logging.md)

```text:log
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すればよい。

**注意**
既にタイムアウトした後なので、ここで複雑な処理をすることは避けるべきです

```ruby:application_controller.rb
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](https://github.com/heroku/rack-timeout)




## Rails, Unicorn, Nginxでのタイムアウトの設定

UnicornとNginxはconfでタイムアウトを設定できます。

### Unicornのタイムアウト

[Github](https://github.com/defunkt/unicorn/blob/master/examples/unicorn.conf.rb#L32)

```
timeout 25
```

### Nginxのタイムアウト

[docs](http://nginx.org/en/docs/http/ngx_http_proxy_module.html#proxy_read_timeout)

※Nginxの場合はproxy_read_timeout以外にも多数の種類のタイムアウトを設定できます

```
proxy_read_timeout 30;
```



### Railsのタイムアウト

標準では、Railsにはリクエストをタイムアウトさせる仕組みはありません。特に何もしていないなら、UnicornやNginxでタイムアウトしてしまいます。

タイムアウトするだけなら特に問題はないです。しかし、その時のプロセスの終了方法に問題があります。

```text:unicorn.log
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に下記のようなログが出力されます。

```text: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側で処理することはできますが、適切にハンドリングしないと「終了できないプロセス」になってしまうため注意が必要です。


```ruby
Signal.trap 'INT' do
  puts 'intercept INT and stop ..'
end
```




## rack-timeout gemがやっていること

他の方が解説してくれている。[解説記事](https://blog.s4ichi.com/entry/2018/02/02/011812)

ここにも簡単に書くと、アプリケーションのメインスレッドとは別にタイムアウト用のスレッドを作り、そこで秒数をカウントする。指定の秒数を過ぎたら、タイムアウトの例外を発生させる。

Rubyにも標準でタイムアウトの仕組み（Timeout.timeout）があるが、これを使っていない理由は、秒数のカウントと段階的なログ出力のためだと思われる。

rack-timeout gemを入れさえすれば、これ以降はリクエストのタイムアウトがログに出力されるようになる。


```text:log
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 gem](https://github.com/heroku/rack-timeout)

[Rack::Timeout::RequestTimeoutException の仕組み](https://blog.s4ichi.com/entry/2018/02/02/011812)

[unicornのタイムアウト時にもRailsのログをちゃんと出力させる](https://blog.mirakui.com/entry/2012/02/19/how-to-flush-rails-logger-if-unicorn-timeout)

[rack-timeout と rackアプリケーション](http://blog.jiikko.com/105)