rack-timeoutの情報を引き出すのは難しいけどobeserversがあって工夫の余地はある

rack-timeoutはasyncな挙動を許さないので情報を引き出すのが難しい

NewRelic など agent 方式のものでは可能だったはず¹なので、agent をサクッと作れる人は作ればいいんだけど、そうじゃない場合どうなっているのか、という話。

例えば Rails と rack-timeout を組み合わせる場合、他のエラーと同じように

rescue_from で timeout エラーを拾って処理を行いたい

と思うかもしれない。結論から言うとエラーを拾って処理を kick することは可能だが、

rack-timeout 自身が Thread 丸ごと全部 kill しようとするので async な logger などは期待通りに動作しない

という挙動になる。

The Oldest Bug in Ruby: Why Rack::Timeout Might Hose Your Server - DZone Performance

参考記事は 2017年のものだが、Ruby 2.6.x + Rails 6.0.x でも同じ動作だったので、"バグ"は直っていないっぽい。まぁ timeout で全処理をキャンセルするのが目的なので仕方ないっちゃ仕方ないんだけど。

rack-timeout自身がobserversを提供してくれている

どうにも情報が引き出せなかったのであれこれ rack-timeout のドキュメントを読んでいたら observers というものがあることを知った。

rack-timeout/observers.md at master · sharpstone/rack-timeout

• Rack::Timeout.register_state_change_observer に名前と Proc オブジェクトを与える
• Proc オブジェクトには rack env が渡ってくる
• Proc オブジェクトは state change のたびに呼ばれる
• state change は lifecycle のページに書かれている以下の5パターン。rack-timeout をそのまま使っていると log にこれらの情報が出力されているはず。
  • expired ( error )
  • ready ( info )
  • active ( debug )
  • timed_out ( error )
  • completed ( info )

see expired (ERROR): the request is considered too old and is skipped entirely. This happens when X-Request-Start is present and older than wait_timeout. When in this state, Rack::Timeout::RequestExpiryError is raised. See earlier discussion about the wait_overtime setting, too. ready (INFO): this is the state a request is in right before it's passed down the middleware chain. Once it's being pr

これらのうち実際に何かしたいとなった時に利用するのは timed_out のタイミングだろう。timeout の情報は rack env の 'rack-timeout.info' という key に Struct として収められているので、observer 全体では以下のような形になる。

Rack::Timeout.register_state_change_observer(:a_unique_name) do |env|
  if env['rack-timeout.info'].status == :timed_out
    ..
  end
end

とは言えあくまで取得できる情報は簡素なもので、設定してあった時間と実際に計測した時間くらいのものである。どの URI にアクセスした結果 timeout が起きたかといったことすら分からない。

その辺は

• Rails の作る rack env オブジェクトの中身に精通していないといけない
• 例外そのものを拾うことはできないので backtrace はない

ので注意が必要である。