2020-05-23

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

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

NewRelic など agent 方式のものでは可能だったはず1なので、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 はない

ので注意が必要である。

  1. 最近使っていないのでどうだったか覚えていない 

About

例によって個人のなんちゃらです

Recent Posts

Categories

Tool 日々 Web Biz Net Apple MS ことば News Unix howto Food PHP Movie Edu Community Book Security Text TV Perl Ruby Music Pdoc 生き方 RDoc ViewCVS CVS Rsync Disk Mail FreeBSD Cygwin PDF Photo Zebedee Debian OSX Comic Cron Sysadmin Font Analog iCal Sunbird DNS Linux Wiki Emacs Thunderbird Sitecopy Terminal Drawing tDiary AppleScript Life Money Omni PukiWiki Xen XREA Zsh Screen CASL Firefox Fink zsh haXe Ecmascript PATH_INFO SQLite PEAR Lighttpd FastCGI Subversion au prototype.js jsUnit Apache Trac Template Java Rhino Mochikit Feed Bloglines CSS del.icio.us SBS qwikWeb gettext Ajax JSDoc Rails HTML CHM EPWING NDTP EB IE CLI ck ThinkPad Toy WSH RFC readline rlwrap ImageMagick epeg Frenzy sysprep Ubuntu MeCab DTP ERD DBMS eclipse Eclipse Awk RD Diigo XAMPP RubyGems PHPDoc iCab DOM YAML Camino Geekmonkey w3m Scheme Gauche Lisp JSAN Google VMware DSL SLAX Safari Markdown Textile IRC Jabber Fastladder MacPorts LLSpirit CPAN Mozilla Twitter OpenFL Rswatch ITS NTP GUI Pragger Yapra XML Mobile Git Study JSON VirtualBox Samba Pear Growl Mercurial Rack Capistrano Rake Win RSS Mechanize Sitemaps Android JavaScript Python RTM OOo iPod Yahoo Unicode Github iTunes God SBM friendfeed Friendfeed HokuUn Sinatra TDD Test Project Evernote iPad Geohash Location Map Search Simplenote Image WebKit RSpec Phone CSV WiMAX USB Chrome RubyKaigi RubyKaigi2011 Space CoffeeScript Nokogiri Hpricot Rubygems jQuery Node GTD CI UX Design VCS Kanazawa.rb Kindle Amazon Agile Vagrant Chef Windows Composer Dotenv PaaS Itamae SaaS Docker Swagger Grape WebAPI Microservices OmniAuth HTTP 分析基盤 CDN Terraform IaaS HCL Webpack Vue.js BigQuery Middleman CMS AWS PNG Laravel Selenium OAuth OpenAPI GitHub UML GCP TypeScript SQL Hanami Develop Document Jekyll