Rack Middleware たちがどのように呼ばれるかを見てみよう（e.g. Sinatra）

Time to Read

3分

`Sinatra::Base.middleware`

そもそも、 Sinatra::Base を継承したクラスには、クラスメソッドとして Sinatra::Base.middleware が用意されており、明示的に Sinatra::Base.use で利用を宣言したミドルウェアはそこから一覧を取得できる。

+ (Object) middleware

ところが、 Sinatra アプリケーションが実際に Rack でホストされ、アクセスされる際には、 use で宣言していないミドルウェアもたくさん呼ばれるわけで。その全貌が知りたい場合。むろん、 Rails、Ramaze、Camping といった Rack に対応したフレームワークならば同じような方法で「中を覗く」ことが可能なはず。

`set_trace_func` を使ってみる

Kernel#set_trace_func は profile.rb （pure Ruby 製らしい）などにも使われる便利メソッド。

Ruby で debug する7つの方法（真ん中あたり）
settracefunc について

などに詳しい。

これを用いて、各クラスのトレーサとして

  set_trace_func(lambda { |event, file, line, id, binding, klass|
    if event =~ /call|return/ && id.to_s == "call" && klass != Proc
      logger.info "#{klass}#call is called! as #{event}"
    end  
  })

のように仕込んでみる。

event が、 (c-)call / (c-)return であり、
id （＝メソッド名）が、 “call” であり、
Proc#call でない

場合に、ログを吐き出させてみる、ということ。 Rack Middleware/Rack Application であれば、アクセスがあった際に必ず call が呼ばれる（Decorator パターンの一種）ので、こうすれば呼ばれるタイミングを追いかけられるであろう、という狙い。

Classic Sinatra の場合

app.rb:

# coding: utf-8
require 'sinatra'
require 'logger'
 
# set :logger, Logger.new($stderr) だと
# set_trace_func で呼ぶときにスタックが深くなりすぎるのか、返ってこないぞ
def logger
  @logger ||= Logger.new($stderr)
end
 
get '/' do
  "Hi, sinatra"
end
 
set_trace_func(lambda { |event, file, line, id, binding, klass|
  if event =~ /call|return/ && id.to_s == "call" && klass != Proc
    logger.info "#{klass}#call is called! as #{event}"
  end  
})

$ ruby app.rb
#...
I, [2011-12-01T11:34:01.840720 #18769]  INFO -- : Method#call is called! as c-call
I, [2011-12-01T11:34:01.842057 #18769]  INFO -- : Sinatra::Base#call is called! as call
I, [2011-12-01T11:34:01.895310 #18769]  INFO -- : Sinatra::ShowExceptions#call is called! as call
I, [2011-12-01T11:34:01.895440 #18769]  INFO -- : Rack::MethodOverride#call is called! as call
I, [2011-12-01T11:34:01.895499 #18769]  INFO -- : Rack::Head#call is called! as call
I, [2011-12-01T11:34:01.895552 #18769]  INFO -- : Rack::CommonLogger#call is called! as call
I, [2011-12-01T11:34:01.895621 #18769]  INFO -- : Rack::Logger#call is called! as call
I, [2011-12-01T11:34:01.895822 #18769]  INFO -- : Rack::Protection::XSSHeader#call is called! as call
I, [2011-12-01T11:34:01.895880 #18769]  INFO -- : Rack::Protection::Base#call is called! as call
I, [2011-12-01T11:34:01.895950 #18769]  INFO -- : Rack::Protection::JsonCsrf#call is called! as call
I, [2011-12-01T11:34:01.896004 #18769]  INFO -- : Rack::Protection::PathTraversal#call is called! as call
I, [2011-12-01T11:34:01.896142 #18769]  INFO -- : Rack::Protection::XSSHeader#call is called! as call
I, [2011-12-01T11:34:01.896200 #18769]  INFO -- : Sinatra::Base#call is called! as call
I, [2011-12-01T11:34:01.909294 #18769]  INFO -- : Method#call is called! as c-call
I, [2011-12-01T11:34:01.909442 #18769]  INFO -- : Method#call is called! as c-return
I, [2011-12-01T11:34:01.912051 #18769]  INFO -- : Sinatra::Base#call is called! as return
I, [2011-12-01T11:34:01.912186 #18769]  INFO -- : Rack::Protection::XSSHeader#call is called! as return
I, [2011-12-01T11:34:01.912266 #18769]  INFO -- : Rack::Protection::PathTraversal#call is called! as return
I, [2011-12-01T11:34:01.912362 #18769]  INFO -- : Rack::Protection::JsonCsrf#call is called! as return
I, [2011-12-01T11:34:01.912425 #18769]  INFO -- : Rack::Protection::Base#call is called! as return
I, [2011-12-01T11:34:01.912534 #18769]  INFO -- : Rack::Protection::XSSHeader#call is called! as return
I, [2011-12-01T11:34:01.912597 #18769]  INFO -- : Rack::Logger#call is called! as return
I, [2011-12-01T11:34:01.912876 #18769]  INFO -- : Rack::CommonLogger#call is called! as return
I, [2011-12-01T11:34:01.912950 #18769]  INFO -- : Rack::Head#call is called! as return
I, [2011-12-01T11:34:01.913013 #18769]  INFO -- : Rack::MethodOverride#call is called! as return
I, [2011-12-01T11:34:01.913078 #18769]  INFO -- : Sinatra::ShowExceptions#call is called! as return
I, [2011-12-01T11:34:01.913152 #18769]  INFO -- : Sinatra::Base#call is called! as return
I, [2011-12-01T11:34:01.913228 #18769]  INFO -- : Method#call is called! as c-return
I, [2011-12-01T11:34:01.913537 #18769]  INFO -- : Method#call is called! as c-call
127.0.0.1 - - [01/Dec/2011 11:34:01] "GET / HTTP/1.1" 200 11 0.0189
I, [2011-12-01T11:34:01.914770 #18769]  INFO -- : Method#call is called! as c-return

このように、真ん中を Method#call として、きれいに対称になっているのが分かると思う。

Sinatra(::Application) は何もしなくともでいろんな Rack Middleware を通しているし、ちゃんと Rack::Protection も有効になっていることも分かる。これは、 Sinatra::Base は、実は new されるとき、 Rack::Builder でラップされて、様々なミドルウェアがデフォルトで適用されるためだ。

Padrino の場合

config/boot.rb の Padrino.after_load フック:

##
# Add your after load hooks here
#
Padrino.after_load do
  set_trace_func(lambda { |event, file, line, id, binding, klass|
    if event =~ /call|return/ && id.to_s == "call" && klass != Proc
      logger.info "#{klass}#call is called! as #{event}"
    end  
  })
end

app/app.rb:

class CatchCall < Padrino::Application
  register Padrino::Rendering
  register Padrino::Mailer
  register Padrino::Helpers
 
  enable :sessions
 
  # add "/" page
  controllers do
    get :index do
      "hello, Padrino"
    end
  end
  #...
end

$ padrino start
#...
   INFO - Padrino::Router#call is called! as call
   INFO - Sinatra::Base#call is called! as call
   INFO - Rack::Session::Abstract::ID#call is called! as call
   INFO - Sinatra::ShowExceptions#call is called! as call
   INFO - Padrino::Logger::Rack#call is called! as call
   INFO - Padrino::Reloader::Rack#call is called! as call
   INFO - Rack::MethodOverride#call is called! as call
   INFO - Rack::Head#call is called! as call
   INFO - Sinatra::Base#call is called! as call
   INFO - HttpRouter#call is called! as call
   INFO - Method#call is called! as c-call
   INFO - Method#call is called! as c-return
   INFO - HttpRouter#call is called! as return
   INFO - Sinatra::Base#call is called! as return
   INFO - Rack::Head#call is called! as return
   INFO - Rack::MethodOverride#call is called! as return
   INFO - Padrino::Reloader::Rack#call is called! as return
  DEBUG -      GET (0.0846ms) / - 200 OK
   INFO - Padrino::Logger::Rack#call is called! as return
   INFO - Sinatra::ShowExceptions#call is called! as return
   INFO - Rack::Session::Abstract::ID#call is called! as return
   INFO - Sinatra::Base#call is called! as return
   INFO - Padrino::Router#call is called! as return

Padrino では、独自拡張として Padrino::Logger::Rack、Padrino::Reloader::Rack が有効になっていること、そして影の立役者である HttpRouter の呼び出しがインジェクトされていること、などが分かる。

なにより、実は Padrino では、デフォルトでは Rack::Protection::* が無効になっている こと（0.10.5 の段階では）に注意したい。利用したい場合、明示的に

1
2
3

class CatchCall < Padrino::Application
  enable :protection
end

とすればよい。

で、たとえば、

class CatchCall < Padrino::Application
  class PassThru0
    def initialize(app)
      @app = app
    end
 
    def call(env)
      @app.call(env)
    end
  end
 
  class PassThru1 < PassThru0
    def call(env)
      # don't traverse method finder tree
      @app.call(env)
    end
  end
 
  class PassThru2 < PassThru1
    def call(env)
      @app.call(env)
    end
  end
 
  use PassThru0
  use PassThru1
  use PassThru2
  #...
end

などとしてみると、

   INFO - Padrino::Router#call is called! as call
   INFO - Sinatra::Base#call is called! as call
   INFO - Rack::Session::Abstract::ID#call is called! as call
   INFO - Sinatra::ShowExceptions#call is called! as call
   INFO - Padrino::Logger::Rack#call is called! as call
   INFO - Padrino::Reloader::Rack#call is called! as call
   INFO - Rack::MethodOverride#call is called! as call
   INFO - Rack::Head#call is called! as call
   INFO - CatchCall::PassThru0#call is called! as call
   INFO - CatchCall::PassThru1#call is called! as call
   INFO - CatchCall::PassThru2#call is called! as call
   INFO - Sinatra::Base#call is called! as call
   INFO - HttpRouter#call is called! as call
   INFO - Method#call is called! as c-call
   INFO - Method#call is called! as c-return
   INFO - HttpRouter#call is called! as return
   INFO - Sinatra::Base#call is called! as return
   INFO - CatchCall::PassThru2#call is called! as return
   INFO - CatchCall::PassThru1#call is called! as return
   INFO - CatchCall::PassThru0#call is called! as return
   INFO - Rack::Head#call is called! as return
   INFO - Rack::MethodOverride#call is called! as return
   INFO - Padrino::Reloader::Rack#call is called! as return
  DEBUG -      GET (0.1143ms) / - 200 OK
   INFO - Padrino::Logger::Rack#call is called! as return
   INFO - Sinatra::ShowExceptions#call is called! as return
   INFO - Rack::Session::Abstract::ID#call is called! as return
   INFO - Sinatra::Base#call is called! as return
   INFO - Padrino::Router#call is called! as return

宣言したミドルウェアの呼び出しは、この位置に、この順番で挿入されるんだな、ということが分かる。

あるいは、 Rack::Auth::Basic などを使ってみて、どういう風に呼ばれるか、返ってくるかを観察するのも面白いかも知れない。

＊　＊　＊

以上、 Rack Middleware を自作、デバッグする際の参考になれば幸い。

＃ Ruby Advent 何とかのネタはこっちにしようかとも思っていたんだけれど、より濃厚な方を選びました。ま、どっちにせよ僕ばかり得する感じですが……

この記事を読んだ方におすすめの他の記事:

This entry was posted on 2011年12月4日, 12:12 PM and is filed under Padrino, Rack, Ruby, Sinatra. You can follow any responses to this entry through RSS 2.0. You can leave a response, or trackback from your own site.

blog.udzura.jp

Got on the Weird Rails