Railsはアクセスをどう処理しているのか(1)

このエントリーをはてなブックマークに追加

ふと、Railsのコントローラーに書いたコードがが実行されるまでに、 何が起きているのか気になったので、全部追ってみようと思います。

まだ全部追い切れてないですが、思った以上に長くなったのでとりあえずメモとして出 してみます。
一部Rails力やRuby力が足りなくて追い切れない部分がありますが(´･_･`)

##準備

rails g controller Trace index
      create  app/controllers/trace_controller.rb
       route  get "trace/index"
      invoke  erb
      create    app/views/trace
      create    app/views/trace/index.html.erb
      invoke  test_unit
      create    test/controllers/trace_controller_test.rb
      invoke  helper
      create    app/helpers/trace_helper.rb
      invoke    test_unit
      create      test/helpers/trace_helper_test.rb
      invoke  assets
      invoke    coffee
      create      app/assets/javascripts/trace.js.coffee
      invoke    scss
      create      app/assets/stylesheets/trace.css.scss

というコントローラーを作り、

class TraceController < ApplicationController
  def index
    caller().each{ |line| p line}
  end
end

というtraceを用意し、ここにアクセスしてみました。

出力されたログは以下のようになりました。(見にくかったので、GEMまでのパスはGEM_FILE_PATHとしてます)

Started GET "/trace/index" for 127.0.0.1 at 2013-11-02 20:22:17 +0900
Processing by TraceController#index as HTML
"/GEMLIFE_PATH/actionpack-4.0.1/lib/action_controller/metal/implicit_render.rb:4:in `send_action'"
"/GEMLIFE_PATH/actionpack-4.0.1/lib/abstract_controller/base.rb:189:in `process_action'"
"/GEMLIFE_PATH/actionpack-4.0.1/lib/action_controller/metal/rendering.rb:10:in `process_action'"
"/GEMLIFE_PATH/actionpack-4.0.1/lib/abstract_controller/callbacks.rb:18:in `block in process_action'"
"/GEMLIFE_PATH/activesupport-4.0.1/lib/active_support/callbacks.rb:403:in `_run__2108733439165396685__process_action__callbacks'"
"/GEMLIFE_PATH/activesupport-4.0.1/lib/active_support/callbacks.rb:80:in `run_callbacks'"
"/GEMLIFE_PATH/actionpack-4.0.1/lib/abstract_controller/callbacks.rb:17:in `process_action'"
"/GEMLIFE_PATH/actionpack-4.0.1/lib/action_controller/metal/rescue.rb:29:in `process_action'"
"/GEMLIFE_PATH/actionpack-4.0.1/lib/action_controller/metal/instrumentation.rb:31:in `block in process_action'"
"/GEMLIFE_PATH/activesupport-4.0.1/lib/active_support/notifications.rb:159:in `block in instrument'"
"/GEMLIFE_PATH/activesupport-4.0.1/lib/active_support/notifications/instrumenter.rb:20:in `instrument'"
"/GEMLIFE_PATH/activesupport-4.0.1/lib/active_support/notifications.rb:159:in `instrument'"
"/GEMLIFE_PATH/actionpack-4.0.1/lib/action_controller/metal/instrumentation.rb:30:in `process_action'"
"/GEMLIFE_PATH/actionpack-4.0.1/lib/action_controller/metal/params_wrapper.rb:245:in `process_action'"
"/GEMLIFE_PATH/activerecord-4.0.1/lib/active_record/railties/controller_runtime.rb:18:in `process_action'"
"/GEMLIFE_PATH/actionpack-4.0.1/lib/abstract_controller/base.rb:136:in `process'"
"/GEMLIFE_PATH/actionpack-4.0.1/lib/abstract_controller/rendering.rb:44:in `process'"
"/GEMLIFE_PATH/actionpack-4.0.1/lib/action_controller/metal.rb:195:in `dispatch'"
"/GEMLIFE_PATH/actionpack-4.0.1/lib/action_controller/metal/rack_delegation.rb:13:in `dispatch'"
"/GEMLIFE_PATH/actionpack-4.0.1/lib/action_controller/metal.rb:231:in `block in action'"
"/GEMLIFE_PATH/actionpack-4.0.1/lib/action_dispatch/routing/route_set.rb:80:in `call'"
"/GEMLIFE_PATH/actionpack-4.0.1/lib/action_dispatch/routing/route_set.rb:80:in `dispatch'"
"/GEMLIFE_PATH/actionpack-4.0.1/lib/action_dispatch/routing/route_set.rb:48:in `call'"
"/GEMLIFE_PATH/actionpack-4.0.1/lib/action_dispatch/journey/router.rb:71:in `block in call'"
"/GEMLIFE_PATH/actionpack-4.0.1/lib/action_dispatch/journey/router.rb:59:in `each'"
"/GEMLIFE_PATH/actionpack-4.0.1/lib/action_dispatch/journey/router.rb:59:in `call'"
"/GEMLIFE_PATH/actionpack-4.0.1/lib/action_dispatch/routing/route_set.rb:680:in `call'"
"/GEMLIFE_PATH/rack-1.5.2/lib/rack/etag.rb:23:in `call'"
"/GEMLIFE_PATH/rack-1.5.2/lib/rack/conditionalget.rb:25:in `call'"
"/GEMLIFE_PATH/rack-1.5.2/lib/rack/head.rb:11:in `call'"
"/GEMLIFE_PATH/actionpack-4.0.1/lib/action_dispatch/middleware/params_parser.rb:27:in `call'"
"/GEMLIFE_PATH/actionpack-4.0.1/lib/action_dispatch/middleware/flash.rb:241:in `call'"
"/GEMLIFE_PATH/rack-1.5.2/lib/rack/session/abstract/id.rb:225:in `context'"
"/GEMLIFE_PATH/rack-1.5.2/lib/rack/session/abstract/id.rb:220:in `call'"
"/GEMLIFE_PATH/actionpack-4.0.1/lib/action_dispatch/middleware/cookies.rb:486:in `call'"
"/GEMLIFE_PATH/activerecord-4.0.1/lib/active_record/query_cache.rb:36:in `call'"
"/GEMLIFE_PATH/activerecord-4.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:626:in `call'"
"/GEMLIFE_PATH/activerecord-4.0.1/lib/active_record/migration.rb:369:in `call'"
"/GEMLIFE_PATH/actionpack-4.0.1/lib/action_dispatch/middleware/callbacks.rb:29:in `block in call'"
"/GEMLIFE_PATH/activesupport-4.0.1/lib/active_support/callbacks.rb:373:in `_run__4335260606468341692__call__callbacks'"
"/GEMLIFE_PATH/activesupport-4.0.1/lib/active_support/callbacks.rb:80:in `run_callbacks'"
"/GEMLIFE_PATH/actionpack-4.0.1/lib/action_dispatch/middleware/callbacks.rb:27:in `call'"
"/GEMLIFE_PATH/actionpack-4.0.1/lib/action_dispatch/middleware/reloader.rb:64:in `call'"
"/GEMLIFE_PATH/actionpack-4.0.1/lib/action_dispatch/middleware/remote_ip.rb:76:in `call'"
"/GEMLIFE_PATH/actionpack-4.0.1/lib/action_dispatch/middleware/debug_exceptions.rb:17:in `call'"
"/GEMLIFE_PATH/actionpack-4.0.1/lib/action_dispatch/middleware/show_exceptions.rb:30:in `call'"
"/GEMLIFE_PATH/railties-4.0.1/lib/rails/rack/logger.rb:38:in `call_app'"
"/GEMLIFE_PATH/railties-4.0.1/lib/rails/rack/logger.rb:20:in `block in call'"
"/GEMLIFE_PATH/activesupport-4.0.1/lib/active_support/tagged_logging.rb:67:in `block in tagged'"
"/GEMLIFE_PATH/activesupport-4.0.1/lib/active_support/tagged_logging.rb:25:in `tagged'"
"/GEMLIFE_PATH/activesupport-4.0.1/lib/active_support/tagged_logging.rb:67:in `tagged'"
"/GEMLIFE_PATH/railties-4.0.1/lib/rails/rack/logger.rb:20:in `call'"
"/GEMLIFE_PATH/actionpack-4.0.1/lib/action_dispatch/middleware/request_id.rb:21:in `call'"
"/GEMLIFE_PATH/rack-1.5.2/lib/rack/methodoverride.rb:21:in `call'"
"/GEMLIFE_PATH/rack-1.5.2/lib/rack/runtime.rb:17:in `call'"
"/GEMLIFE_PATH/activesupport-4.0.1/lib/active_support/cache/strategy/local_cache.rb:83:in `call'"
"/GEMLIFE_PATH/rack-1.5.2/lib/rack/lock.rb:17:in `call'"
"/GEMLIFE_PATH/actionpack-4.0.1/lib/action_dispatch/middleware/static.rb:64:in `call'"
"/GEMLIFE_PATH/rack-1.5.2/lib/rack/sendfile.rb:112:in `call'"
"/GEMLIFE_PATH/railties-4.0.1/lib/rails/engine.rb:511:in `call'"
"/GEMLIFE_PATH/railties-4.0.1/lib/rails/application.rb:97:in `call'"
"/GEMLIFE_PATH/rack-1.5.2/lib/rack/lock.rb:17:in `call'"
"/GEMLIFE_PATH/rack-1.5.2/lib/rack/content_length.rb:14:in `call'"
"/GEMLIFE_PATH/rack-1.5.2/lib/rack/handler/webrick.rb:60:in `service'"
"/RUBY_PATH/webrick/httpserver.rb:138:in `service'"
"/RUBY_PATH/webrick/httpserver.rb:94:in `run'"
"/RUBY_PATH/webrick/server.rb:295:in `block in start_thread'"
  Rendered trace/index.html.erb within layouts/application (0.9ms)
Completed 200 OK in 94ms (Views: 61.8ms | ActiveRecord: 0.0ms)

恐ろしい量(´･_･`)
とりあえず、こんな感じで動いてるんだなーというイメージをつかむ程度の理解度で、
ゆるふわに読んでいきたいと思います。

##コードをざっと見たところ

下の階層にenvを渡して[status, headers, body]の三つを受け取り、それを返す関数がほとんど。
関数によってenvに変更を加えたり、戻り値の三つを加工したりとやってること自体はまちまちです。

ただ、各処理は本当に単一の処理だけをして次に処理を渡しており、
ifかswitchがせいぜい一つぐらい、全体も20行程度の関数であることが多い印象です。

##Railsのコードを読む 上のログはスタックの上から順に出力しているはずなので、
実際の処理は下から上に向かって行われます。

###"/RUBY_PATH/webrick/server.rb:295:in `block in start_thread’"
名前の通りThread.startしてるだけ。

###"/RUBY_PATH/webrick/httpserver.rb:94:in `run’"
名前の通りひたすらループしている。
リクエストを受け取って後述のserviceを呼び出し、その後返答を送信する処理を行う。

また、各種エラーが起こった場合もそれをキャッチし、エラーだということを送信している模様。

###"/RUBY_PATH/webrick/httpserver.rb:138:in `service’"
実際に処理をするところっぽい。
search_servletにパスを渡し、どんな返答を返すべきなのかを探して、そこに処理を渡している。

###"/GEMLIFE_PATH/rack-1.5.2/lib/rack/handler/webrick.rb:60:in `service’"
名前の通りwebrickから直接値を渡され、処理するところ。
webrickからはreqとresという値を受け取っている。

ハッシュであるreq.meta_varsを元に、必要な値が入ってなければ初期値を入れている。
以降の処理はほとんどがこのハッシュを受け渡して処理を行っている。

また、処理した後に結果を受け取り、引数のresに入れている。

###"/GEMLIFE_PATH/rack-1.5.2/lib/rack/content_length.rb:14:in `call’" 次の処理を読んで、帰ってきた結果にBODYが含まれているなら、
ヘッダーにContent-Lengthを計算して追加している。

###"/GEMLIFE_PATH/rack-1.5.2/lib/rack/lock.rb:17:in `call’" Mutex使ってロックをかけているだけみたい

###"/GEMLIFE_PATH/railties-4.0.1/lib/rails/application.rb:97:in `call’" rackから呼び出されるためだけに存在するやつっぽい。
引数を少しいじってる程度

###"/GEMLIFE_PATH/railties-4.0.1/lib/rails/engine.rb:511:in `call’" ‘action_dispatch.routes’というキーで、ActionDispatch::Routing::RouteSetを追加している。
また、SCRIPT_NAMEが存在する場合には、
ROUTES_オブジェクトID_SCRIPT_NAMEという名前で、同じ値をコピーして代入している。

###"/GEMLIFE_PATH/rack-1.5.2/lib/rack/sendfile.rb:112:in `call’" より下の階層に処理をさせた後ファイル送信の場合にヘッダーの書き換えを行っている。

###"/GEMLIFE_PATH/actionpack-4.0.1/lib/action_dispatch/middleware/static.rb:64:in `call’" REQUEST_METHODがGETかHEADの時に、ルートからのパスを調べ、
ファイルとして存在している場合には否かをチェックして、
ある場合にはRack::Fileのcallを呼んでその結果を返している。
たぶんRailsに処理させず、ファイルを読んで返してるだけかと。
無い場合は特に何もせず下の階層を呼んでいる。

###"/GEMLIFE_PATH/rack-1.5.2/lib/rack/lock.rb:17:in `call’" mutexを使ってロックをかけているだけっぽい。
また、下の階層を呼んで得られたbodyに対して、BodyProxyに処理させた結果と入れ替えている。

###"/GEMLIFE_PATH/activesupport-4.0.1/lib/active_support/cache/strategy/local_cache.rb:83:in `call’" LocalCacheRegistryにLocalStoreオブジェクトを初期化してセットしてる。
コメントによると、簡単なメモリキャッシュに使うらしい。

###"/GEMLIFE_PATH/rack-1.5.2/lib/rack/runtime.rb:17:in `call’" X-Runtimeヘッダに、ここから下の処理にかかった時間をセットしている。

###"/GEMLIFE_PATH/rack-1.5.2/lib/rack/methodoverride.rb:21:in `call’" POSTメソッドだった場合に、METHOD_OVERRIDE_PARAM_KEYやHTTP_METHOD_OVERRIDE_HEADERを見て、
登録されているメソッド名GET HEAD PUT POST DELETE OPTIONS PATCHだったらそれと入れ替えている。
おそらく、PUTとかを実装していないブラウザで、POSTに特別な種類のデータを入れてPUTとして扱うための対応。

###"/GEMLIFE_PATH/actionpack-4.0.1/lib/action_dispatch/middleware/request_id.rb:21:in `call’" あるならばHTTP_X_REQUEST_IDの値か、無いならばSecureRandom.uuidの結果を、
action_dispatch.request_idとして設定している。
たぶんリクエストを一意に識別したいんだと思う。
また、ヘッダのX-Request-Idにもその価を入れている。

###"/GEMLIFE_PATH/railties-4.0.1/lib/rails/rack/logger.rb:20:in `call’" 事前に設定されたタグごとに処理をしているみたい。

###"/GEMLIFE_PATH/activesupport-4.0.1/lib/active_support/tagged_logging.rb:67:in tagged'"](https://github.com/rails/rails/blob/v4.0.1/activesupport/lib/active_support/tagged_logging.rb#L67) ###["/GEMLIFE_PATH/activesupport-4.0.1/lib/active_support/tagged_logging.rb:25:in tagged’" ###["/GEMLIFE_PATH/activesupport-4.0.1/lib/active_support/tagged_logging.rb:67:in block in tagged'"](https://github.com/rails/rails/blob/v4.0.1/activesupport/lib/active_support/tagged_logging.rb#L67) この辺ちょっと何やってるかわからない(´･_･)
なんか引数で与えられたタグに処理してるっぽいけど、Ruby力が低くて読み取れない (´・ω・｀)

###"/GEMLIFE_PATH/railties-4.0.1/lib/rails/rack/logger.rb:20:in `block in call’" ４つ上のところと同じ箇所。
上で用意したloggerにブロックで次の処理を呼ぶように指定しているため、
ブロックを渡す相手の初期化→ブロック内の実行と、二回同じ箇所にくる。

###"/GEMLIFE_PATH/railties-4.0.1/lib/rails/rack/logger.rb:38:in `call_app’" Debugの場合はログ出力にスペースを二つ挟んでいる。
その後、ActiveSupport::Nortificationsを使い、‘request.action_dispatch’という名前で、requestを通知している。
ここでリクエスト直後に処理を挟むようなライブラリを呼び出しているとか？

###"/GEMLIFE_PATH/actionpack-4.0.1/lib/action_dispatch/middleware/show_exceptions.rb:30:in `call’" 基本何もしないけど、ここより下の階層から例外が投げられた場合に、
例外用のレスポンスを作成して返している。

###"/GEMLIFE_PATH/actionpack-4.0.1/lib/action_dispatch/middleware/debug_exceptions.rb:17:in `call’" ヘッダにX-Cascadeがpassと設定されている場合、もしくは任意の他のエラーが起きた場合に、
エラーレスポンスを作成している。

###"/GEMLIFE_PATH/actionpack-4.0.1/lib/action_dispatch/middleware/remote_ip.rb:76:in `call’" action_dispatch.remote_ipにアクセスしてきたIPアドレスを保存している。
保存はGetIpクラスで行われており、calculate_ipメソッドを実行することで、
アクセスしてきたIPアドレスを計算している。
そのため、IPアドレスが必要ない場合は計算が行われない。
どうやら、GetIpクラスの中でかなり巨大な正規表現を用いてIPアドレスを計算しているらしく、
そこの処理が重いため、必要が無ければ計算しないand計算したらメモするようにしているみたい。
(この正規表現を使っているみたいhttps://gist.github.com/gazay/1289635)

###"/GEMLIFE_PATH/actionpack-4.0.1/lib/action_dispatch/middleware/reloader.rb:64:in `call’" コールバックとして設定されたprepareとcleanupを処理の最初と最後に呼んでいる。

###"/GEMLIFE_PATH/actionpack-4.0.1/lib/action_dispatch/middleware/callbacks.rb:27:in `call’"

コールバックとして登録された関数に、より下の処理を実行するようにブロックで渡し、
ブロック内で例外が出た場合にその例外を返す。 何でわざわざこんな回りくどい例外の拾い方をしてるのかな？
一応、ブロック内で例外が発生したとしても、コールバック関数はそのまま処理が実行され、
その後再び同じ例外をなげる事になるんだけれどこれが目的？

###"/GEMLIFE_PATH/activesupport-4.0.1/lib/active_support/callbacks.rb:80:in run_callbacks'"](https://github.com/rails/rails/blob/v4.0.1/activesupport/lib/active_support/callbacks.rb#L80) ###["/GEMLIFE_PATH/activesupport-4.0.1/lib/active_support/callbacks.rb:373:in _run__4335260606468341692__call__callbacks’" 与えられたシンボル(イベント名？)からコールバック先を見つけ、それに対して引数のブロックを渡している？
なんかEVALしてクラスを作ってたりしてて、ちょっと意味不明なことやってる(´･_･`)

###"/GEMLIFE_PATH/actionpack-4.0.1/lib/action_dispatch/middleware/callbacks.rb:29:in `block in call’" 三つ上の位置から渡されたブロック内部。
下の処理を呼んでるだけ。

##続く ここまではRails以前のいろんな処理が多かったですが、
ここから先はActiveRecordが現れ始め、いかにもRails本体の動きっぽい感じがします。
が、長くなりすぎたのでいったん切ります。