rails/reset_session のバグ? のバックアップソース(No.4)

更新

[[公開メモ]]

#contents

* 急に Redmine にログインできなくなりました [#h1b600fc]

ログインしようとすると、

 Internal error
 
 An error occurred on the page you were trying to access.
 If you continue to experience problems please contact your Redmine administrator for assistance.
 
 If you are the Redmine administrator, check your log files for details about the error.
 
 Back

と言われる。

log/production.log を見ると、

 Processing AccountController#login [POST]
   Parameters: {"action"=>"login", "authenticity_token"=>"[FILTERED]", 
   "username"=>"[FILTERED]", "controller"=>"account", "password"=>"[FILTERED]", 
   "login"=>"ログイン »"}
 
 NoMethodError (undefined method `destroy' for {}:Hash):
   app/controllers/application_controller.rb:89:in `logged_user='
   app/controllers/account_controller.rb:203:in `successful_authentication'
   app/controllers/account_controller.rb:155:in `password_authentication'
   app/controllers/account_controller.rb:142:in `authenticate_user'
   app/controllers/account_controller.rb:30:in `login'
   /var/www/redmine/dispatch.fcgi:26

となっている。

http://www.redmine.org/boards/2/topics/23419

これと同じ症状だ。

ちなみに、こちらの環境は

 LANG:console
 $ pwd
 (...)/redmine-1.2.0
 $ script/console
 Loading development environment (Rails 2.3.11)
 >>

(追記)すみません、さっきまで書かれていた内容ではバージョンの確認の仕方が悪かったです。orz~
システムには Debian のパッケージとしてインストールされた Rails 2.3.5 が入っているけれど、
ローカルには Redmine 1.2.0 に同梱された Rails 2.3.11 がそのまま入っていますので、
そちらが動いているはずです。

* 設定ミスも一因でした [#r9ba1412]

(さらに追記)このページの後半にあるように、
エラーの原因の一端は私の設定ミスにあることが分かりました。
ただ、500 になる直接の原因は Rails の request.rb にある 
reset_session なのではないかという疑惑は払拭できずにいます。

* 原因を探る [#u6692c8e]

ログにあるエラー行の app/controllers/application_controller.rb:89 を見ると

 LANG:ruby
   # Sets the logged in user
   def logged_user=(user)
 >   reset_session
     if user && user.is_a?(User)
       User.current = user
       session[:user_id] = user.id
     else
       User.current = User.anonymous
     end
   end

reset_session の行を指している。

ん?destroy なんて無いんですけれど・・・

仕方がないので grep

 LANG:console
 $ grep reset_session app/*/* app/*/*/* app/*/*/*/*
 app/controllers/application_controller.rb:    reset_session

ここしかない。

ということは、

 LANG:console
 $ grep reset_session vendor/*/*/*/*/*
 vendor/rails/actionpack/lib/action_controller/base.rb:  # or you can remove the entire session with +reset_session+.
 vendor/rails/actionpack/lib/action_controller/base.rb:      def reset_session #:doc:
 vendor/rails/actionpack/lib/action_controller/base.rb:        request.reset_session
 vendor/rails/actionpack/lib/action_controller/flash.rb:        alias_method_chain :reset_session,  :flash
 vendor/rails/actionpack/lib/action_controller/flash.rb:        def reset_session_with_flash
 vendor/rails/actionpack/lib/action_controller/flash.rb:          reset_session_without_flash
 vendor/rails/actionpack/lib/action_controller/request.rb:    def reset_session
 vendor/rails/actionpack/lib/action_controller/request_forgery_protection.rb:        reset_session
 vendor/rails/actionpack/lib/action_controller/test_process.rb:    def reset_session
 vendor/rails/actionpack/lib/action_controller/test_process.rb:      reset_session_id
 vendor/rails/actionpack/lib/action_controller/test_process.rb:      reset_session_id
 vendor/rails/actionpack/lib/action_controller/test_process.rb:    def reset_session_id
 vendor/rails/actionpack/test/activerecord/active_record_store_test.rb:    def call_reset_session
 vendor/rails/actionpack/test/activerecord/active_record_store_test.rb:      reset_session
 vendor/rails/actionpack/test/activerecord/active_record_store_test.rb:      get '/call_reset_session'
 vendor/rails/actionpack/test/activerecord/active_record_store_test.rb:      get '/call_reset_session'
 vendor/rails/actionpack/test/controller/flash_test.rb:    def use_flash_after_reset_session
 vendor/rails/actionpack/test/controller/flash_test.rb:      reset_session
 vendor/rails/actionpack/test/controller/flash_test.rb:  def test_flash_after_reset_session
 vendor/rails/actionpack/test/controller/flash_test.rb:    get :use_flash_after_reset_session
 vendor/rails/actionpack/test/controller/test_test.rb:      reset_session
 vendor/rails/actionpack/test/controller/test_test.rb:  def test_session_is_cleared_from_controller_after_reset_session
 vendor/rails/actionpack/test/controller/test_test.rb:  def test_session_is_cleared_from_response_after_reset_session
 vendor/rails/actionpack/test/controller/test_test.rb:  def test_session_is_cleared_from_request_after_reset_session

ruby のデバッグってこういう感じだっけ・・・ orz

で、発見したのがこれ。

vendor/rails/actionpack/lib/action_controller/request.rb
 LANG:ruby
    def reset_session
      session.destroy if session
      self.session = {}
    end

reset する際に Hash を代入してるのに、
再度リセットする際に Hash が持っていない 
destroy という関数を呼んでいる。

そりゃだめだ。

* 解決案 [#l648aa22]

session.destroy の行を

 LANG:ruby
      session.destroy if session and session.respond_to?(:destroy)

としたらどうかしら?

念のため、
 LANG:console
 $ grep session.destroy vendor/*/*/*/*/*
 vendor/rails/actionpack/lib/action_controller/request.rb:      session.destroy if session and session.respond_to?(:destroy)

うん、同様のコードは他には無いみたい。

ということで、ものすごい monkey patch だけど、これで一応動いているみたい?

(apache を restart したせいかもしれないので、しばらく様子見)

** 上記 500 の再現手順は??? [#jfb739d0]

実は、様子見をしていたところ、下記のとおりまだ不具合が残っていて、
そちらは私の設定ミスによるものでした。

そこで残る疑問は、上記 500 エラーの原因が Rails にあるのか、
私の設定ミスから生じた下記のエラーにあるのか、と言う話。

下記エラーの症状からすると期限の切れたセッションがあると 500 
エラーになりそう?

具体的にはブラウザから送られる Cookie の _redmine_session 
に不正な値が入っていて、なおかつ Rails オリジナルのコードだと 
500 になるんじゃないかと。。。

あれ?試したところ 500 は出ないみたい。

下記の設定ミスがない限り、Redmine から Rails を使う分には 500 
は出ないのかも。

とはいえ、reset_session を2回連続で呼ぶと 500 
というのもおかしな仕様な気がするので、
Rails としては改善の余地が・・・ないんでしょうか?(弱気)

* ちょっとよく分からないエラーが継続 [#y755d51e]

関係あるのか無いのか分からないので、とりあえずここに続けてみる。~
(結局関係ありませんでしたが、わざわざ独立させるほどの内容にはならなかったので、
このままここに置いておきます。こちらの問題は Rails 導入時の私の設定ミスでした。)

症状としては、Wiki ページへのリンクをクリックした際など、
非常に頻繁に強制ログアウトされてしまう、というもの。

log/production.log を見る。

 LANG:console
 $ less log/production.log
 Processing WikiController#show [GET]
   Parameters: {"back_url"=>"http://...", "project_id"=>"[FILTERED]", "action"=>"show", "id"=>"[FILTERED]", "controller"=>"wiki"}
 Redirected to http://...
 Filter chain halted as [:check_if_login_required] rendered_or_redirected.
 Completed in 7ms (DB: 1) | 302 Found [http://...]
 
 
 Processing AccountController#login [GET]
   Parameters: {"back_url"=>"http://...", "action"=>"login", "controller"=>"account"}
 Rendering template within layouts/base
 Rendering account/login
 Completed in 19ms (View: 14, DB: 1) | 200 OK [http://...]

check_if_login_required ではねられてるらしい。

 LANG:console
 $ grep check_if_login_required app/*/*
 app/controllers/account_controller.rb:  # prevents login action to be filtered by check_if_login_required application scope filter
 app/controllers/account_controller.rb:  skip_before_filter :check_if_login_required
 app/controllers/application_controller.rb:  before_filter :user_setup, :check_if_login_required, :set_localization
 app/controllers/application_controller.rb:  def check_if_login_required

これかな?

app/controllers/application_controller.rb
 LANG:ruby
  # check if login is globally required to access the application
  def check_if_login_required
    # no check needed if user is already logged in
    return true if User.current.logged?
    require_login if Setting.login_required?
  end

たぶん User.current.logged? が true になってくれないのがおかしい。

app/models/user.rb
 LANG:ruby
 class User < Principal
   def self.current
     @current_user ||= User.anonymous
   end
  
   def logged?
     true
   end
 
 class AnonymousUser < User
   def logged?; false end

ふむふむ。

 LANG:console
 $ grep -E "current +=" app/*/*
 app/controllers/application_controller.rb:    User.current = find_current_user
 app/controllers/application_controller.rb:      User.current = user
 app/controllers/application_controller.rb:      User.current = User.anonymous
 app/controllers/mail_handler_controller.rb:    User.current = nil
 app/controllers/sys_controller.rb:    User.current = nil
 app/helpers/application_helper.rb:        current = root
 app/helpers/application_helper.rb:          current = level
 app/models/mail_handler.rb:    User.current = @user
 app/models/wiki_page.rb:    current = content
 app/models/wiki_page.rb:      current = current.previous

app/controllers/application_controller.rb
 LANG:ruby
  before_filter :user_setup, :check_if_login_required, :set_localization
 
  def user_setup
    # Check the settings cache for each request
    Setting.check_cache
    # Find the current user
    User.current = find_current_user
  end
 
  # Sets the logged in user
  def logged_user=(user)
    reset_session
    if user && user.is_a?(User)
      User.current = user
      session[:user_id] = user.id
    else
      User.current = User.anonymous
    end
  end

 LANG:console
 $ grep -E "logged_user *=" app/*/*
 app/controllers/account_controller.rb:          self.logged_user = @user
 app/controllers/account_controller.rb:      self.logged_user = nil
 app/controllers/account_controller.rb:    self.logged_user = user
 app/controllers/account_controller.rb:      self.logged_user = user

つまり、find_current_user を読めと。

 LANG:ruby(linenumber)
  # Returns the current user or nil if no user is logged in
  # and starts a session if needed
  def find_current_user
 >  if session[:user_id]
      # existing session
      (User.active.find(session[:user_id]) rescue nil)
    elsif cookies[:autologin] && Setting.autologin?
      # auto-login feature starts a new session
      user = User.try_to_autologin(cookies[:autologin])
      session[:user_id] = user.id if user
      user
    elsif params[:format] == 'atom' && params[:key] && accept_key_auth_actions.include?(params[:action])
      # RSS key authentication does not start a session
      User.find_by_rss_key(params[:key])
    elsif Setting.rest_api_enabled? && api_request?
      if (key = api_key_from_request) && accept_key_auth_actions.include?(params[:action])
        # Use API key
        User.find_by_api_key(key)
      else
        # HTTP Basic, either username/password or API key/random
        authenticate_with_http_basic do |username, password|
          User.try_to_login(username, password) || User.find_by_api_key(username)
        end
      end
    end
  end

本来なら印を付けた4行目が true にならないとおかしい。

やっぱりセッションが切れてる感じだ。

** とりあえず回避策 [#d7d202af]

ああ、何でさっきまで症状に気付いていなかったかが分かった。

ログイン時に「ログインを維持」チェックを付けておくと問題が発生しないのか。

上の find_current_user の4行目で if session[:user_id] が false になっても、
7行目の elsif cookies[:autologin] && Setting.autologin? が効くのでログイン状態を保てると。

 LANG:console
 $ grep -i -E "autologin" app/*/*
 app/controllers/account_controller.rb:      cookies.delete :autologin
 app/controllers/account_controller.rb:      Token.delete_all(["user_id = ? AND action = ?", User.current.id, 'autologin'])
 app/controllers/account_controller.rb:    # generate a key and set cookie if autologin
 app/controllers/account_controller.rb:    if params[:autologin] && Setting.autologin?
 app/controllers/account_controller.rb:      set_autologin_cookie(user)
 app/controllers/account_controller.rb:  def set_autologin_cookie(user)
 app/controllers/account_controller.rb:    token = Token.create(:user => user, :action => 'autologin')
 app/controllers/account_controller.rb:    cookie_name = Redmine::Configuration['autologin_cookie_name'] || 'autologin'
 app/controllers/account_controller.rb:      :path => (Redmine::Configuration['autologin_cookie_path'] || '/'),
 app/controllers/account_controller.rb:      :secure => (Redmine::Configuration['autologin_cookie_secure'] ? true : false),
 app/controllers/application_controller.rb:    elsif cookies[:autologin] && Setting.autologin?
 app/controllers/application_controller.rb:      user = User.try_to_autologin(cookies[:autologin])
 app/models/user.rb:  # Returns the user who matches the given autologin +key+ or nil
 app/models/user.rb:  def self.try_to_autologin(key)
 app/models/user.rb:    tokens = Token.find_all_by_action_and_value('autologin', key)
 app/models/user.rb:      if (token.created_on > Setting.autologin.to_i.day.ago) && token.user && token.user.active?

ざっとだけれど auto_login 処理の流れが見える。

んー、これで満足しておくかなあ・・・

** セッションをクリアしてみた [#c1dbf177]

 LANG:console
 $ rake tmp:sessions:clear

良くならなかった。orz

** yaml_db を抜いてみる [#oc83e44d]

データ移行のために入れてたプラグイン yaml_db を抜いてみた。

 LANG:console
 $ sudo script/plugin remove yaml_db

良くならなかった。orz

** なんかこのエラー、見覚えがあるような [#k80374ae]

このエラーが、何枚か画像を貼った Wiki ページで特に頻繁に起きることを考えると、
セッション情報を読み出すときにファイルロックが取れずにエラーになってる可能性が考えられる。

Redmine の Wiki ページに貼った画像ファイルは Rails 経由で送出されるので、
以前バックエンドが sqlite だった時には同時アクセスに耐えられず、
常に何枚か 500 になっていた。

それを回避するために sqlite => mysql の以降をした経緯がある。

たぶん、session 情報もそうなんじゃないか、という話。

** 違いました orz [#vd551fac]

session に関する記述を探して config/environment.rb を見ていて気付きました。

アップグレードの際、何も考えずに下記ページの【おまけ】を入れたのが間違いでした(><

http://hajimete-ruby.jugem.jp/?eid=27

複数起動した Rails プロセスごとに異なる secret が生成されてしまったため、
異なるプロセスに繋がった際にはじかれていた、というお粗末な結果。

上記コードを入れた当初は autologin が on になっていたので、
その問題に気付きませんでした。

この問題は、アプロさんのおっしゃるとおり
http://redmine.jp/guide/RedmineUpgrade/
に忠実に作業をしていれば発生しなかったバグなのだと思います。

 LANG:console
 $ rake generate_session_store

の手順を抜かした上、エラーメッセージを頼りに場当たり的な(間違った)
対処をしてしまったと。

 LANG:console
 A key is required to write a cookie containing the session data. Use 
 config.action_controller.session = { :key => "_myapp_session", 
 :secret => "some secret phrase" } in config/environment.rb (ArgumentError)

のエラーから "rake generate_session_store" は思い浮かばないわけで orz

「rake generate_session_store してよ〜」 っていうエラーメッセージを
出してくれればいいのに! とぼやいても後の祭り・・・

この後半の話は、恐らく前半の reset_session の問題とは別の話なので、
無かったことにして下さい。(誰に頼んでるんだ?!)

* コメント [#lcdc419b]

#article_kcaptcha
**GSetkmHLQFkdXpV [#aeb1ebb2]
>[Marlie] (2011-10-21 (金) 22:23:46)~
~
Woot, I will creatnliy put this to good use!~

//

#comment_kcaptcha

**Rails のバージョンが・・・ [#rc8eb31c]
>[アプロ] (2011-06-07 (火) 19:46:21)~
~
Rails 2.3.11 ぢゃないとダメれす~
redmine-1.2.0 は、Rails 2.3.11 なんです~
詳しくはここです↓~
http://redmine.jp/redmine_today/2011/06/01/redmine-1_2_0-released/~

//
- すみません。バージョンの確認の仕方が悪かったです。Debian パッケージとしてシステムに導入されているは 2.3.5 ですが、ローカルに導入されているのは Redmine の tar ボールに同梱されていた 2.3.11 でした。 -- [武内(管理人)] &new{2011-06-07 (火) 19:57:48};
- Rails 2.3.11 なら、問題なく動作すると思います。私が本日、redmine-1.2.0にアップデートしましたが、特に問題は置きませんでしたし -- [アプロ] &new{2011-06-07 (火) 20:01:52};
- セッション情報がおかしくなってしまっているのかも知れませんね。さっき調べたときにセッションをクリアしてみろ、と書かれたコメントがあったので、試してみようかと思います。 -- [武内(管理人)] &new{2011-06-07 (火) 20:07:30};
- rake tmp:cache:clear クリアして、Apacheの再起動では? -- [アプロ] &new{2011-06-07 (火) 20:17:43};
- はい、やってみました。が、私の見立て違いで問題は全然別の所でした。アプロさんのおっしゃるとおり、アップグレード手順を逐一踏んでいなかったせいでおかしなコードを紛れ込ませてしまっていました。残念。 -- [武内(管理人)] &new{2011-06-07 (火) 20:33:13};
- 前半のエラーはどうなんでしょうね。他でも報告されているので、私だけの問題ではないような。コードを見るだけでも問題起きそうな感じがひしひしとしますし・・・ -- [武内(管理人)] &new{2011-06-07 (火) 20:34:49};

#comment_kcaptcha

Counter: 19073 (from 2010/06/03), today: 1, yesterday: 0