rails/reset_session のバグ？ の履歴(No.3)

急に Redmine にログインできなくなりました†

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

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 がそのまま入っていますので、 そちらが動いているはずです。

設定ミスも一因でした†

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

原因を探る†

ログにあるエラー行の 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 という関数を呼んでいる。

そりゃだめだ。

解決案†

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 したせいかもしれないので、しばらく様子見）

ちょっとよく分からないエラーが継続†

関係あるのか無いのか分からないので、とりあえずここに続けてみる。
（結局関係ありませんでしたが、わざわざ独立させるほどの内容にはならなかったので、 このままここに置いておきます。こちらの問題は 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

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

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

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?

LANG:console
$ rake tmp:sessions:clear

LANG:console
$ sudo script/plugin remove yaml_db

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)

コメント†