トップ 最新 追記

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 はない

ので注意が必要である。

Tags: Ruby Rack

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


2020-05-24 [長年日記]

_ RailsのApplicationController::RoutingErrorがたまらなくうざい

いやまぁ書いた通りなんだけど、ApplicationController::RoutingError の backtrace って全然役に立たないし、邪魔じゃないですか。できればこのエラーだけ backtrace をオフにできたらステキだなと思ったのでその辺の対処方法をまとめてみた。

この「RoutingErrorのログが邪魔問題」の解決方法は主に以下のような3つくらいのパターンがあるっぽい。

  1. routing で丸ごとキャッチしてしまってそもそも RoutingError が起きないようにして手動で 404 を返す
  2. Logger を差し替えてなかったことにする、DebugExceptions そのものを使わないようにする
  3. DebugExceptions の中でゴニョゴニョする

RoutingErrorが起きないようにroutes.rbで全部拾う

1 の方法については Stack Overflow や Qiita なんかにたくさん記事や回答がある。あるんだけど、ちょっとイマイチっぽい、みたいなニュアンス。

個人的にも想定外のリクエストがあってエラーが起きたという事実について情報量をコントロールしたいとは思うものの、すべて正常な処理で 404 が返っただけになってしまうのはちょっと意図と違うなという気がする。

Loggerやrack middlewareを差し替えてもみ消す

2 の方法はなかなか見つからないんだけど、例えば

stve/silencer: Easily suppress the Rails logger

みたいなやつ。

もっと大胆に DebugExceptions middleware を無効にしちゃうとか、 3 と組み合わせて自分で動的に Logger を差し替えちゃうという方法も Stack Overflow で見かけたが、middleware や Logger を全部差し替えたりするのは差し替え処理と差し替えた Logger ( middleware ) そのものが正しく動作するか検証しなくちゃいけないので重たいなーという印象。

そもそもエラーは起きているがそれが記録されないのは 1 よりもさらにイマイチな気がする。

DebugExceptions middleware + interceptorで好きなようにする

3 の方法については 2 の方法が見つかってあれこれコードを読んでいて自分で気がついたんだけど、実は DebugExceptions には interceptor という仕組みがあるのでそれが使える。

この方法を採用している事例は探した限り見つからなかったんだけど、結構使えるテクだと思うので紹介しておく。対象バージョンは

  • Rails 6.0.0

で、DebugExceptions は ActionDispatch の中の middleware で、rake middleware すると真ん中辺りに出てくるんじゃないかと思う。

この middleware のコードを追うと以下のように ActionDispatch::DebugExceptions.call の中で、事前に register された interceptor が次々に呼ばれることが分かる。interceptor には request と exception が渡ってくる。

module ActionDispatch
  # This middleware is responsible for logging exceptions and
  # showing a debugging page in case the request is local.
  class DebugExceptions
    cattr_reader :interceptors, instance_accessor: false, default: []

    def self.register_interceptor(object = nil, &block)
      interceptor = object || block
      interceptors << interceptor
    end

...

    def call(env)
      ...
    rescue Exception => exception
      invoke_interceptors(request, exception)
      raise exception unless request.show_exceptions?
      render_exception(request, exception)
    end

...

     def invoke_interceptors(request, exception)
       backtrace_cleaner = request.get_header("action_dispatch.backtrace_cleaner")
       wrapper = ExceptionWrapper.new(backtrace_cleaner, exception)

       @interceptors.each do |interceptor|
         interceptor.call(request, exception)
       rescue Exception
         log_error(request, wrapper)
       end
     end

ということで独自の interceptor を作ってその中で ActionController::RoutingError かどうか判別して何らかの加工を加えるなり処理を行うなどするとよさそう。

具体的には request オブジェクトを書き換えたり exception オブジェクトを書き換えると backtrace は無視するといったことが可能で、そのうえで必要な情報は独自にログに落とすとかどこかエラー収集の仕組みに投げるようなコードを書けばよいと思う。

Tags: Ruby Rack Rails

2020-05-31 [長年日記]

_ GFMのコードブロック対応のmarkdown変換コマンドとしてmarkedを使ってみることにした

Marked.js Documentation

別にハイライトされる必要はなくて、単に GitHub 用に言語名を埋め込んでいるとか、そういう部分に対応していればヨシ!

blockquote class="twitter-tweet">

https://t.co/K2SFka28zN これkramdownよりマシっぽい。

— wtnabe, yet another yak shaver (@wtnabe) May 31, 2020

とりあえずkramdownよりはパッとコマンド叩いた時の結果は良好。

Tags: Markdown Node