rails/reset_session のバグ?

(1901d) 更新

公開メモ

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

上記 500 の再現手順は???

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

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

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

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

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

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

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

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

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

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

とりあえず回避策

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

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

上の 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 処理の流れが見える。

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

セッションをクリアしてみた

LANG:console
$ rake tmp:sessions:clear

良くならなかった。orz

yaml_db を抜いてみる

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

LANG:console
$ sudo script/plugin remove yaml_db

良くならなかった。orz

なんかこのエラー、見覚えがあるような

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

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

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

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

違いました orz

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 の問題とは別の話なので、 無かったことにして下さい。(誰に頼んでるんだ?!)

コメント




Rails のバージョンが・・・

[アプロ] (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 でした。 -- [武内(管理人)]
  • Rails 2.3.11 なら、問題なく動作すると思います。私が本日、redmine-1.2.0にアップデートしましたが、特に問題は置きませんでしたし -- [アプロ]
  • セッション情報がおかしくなってしまっているのかも知れませんね。さっき調べたときにセッションをクリアしてみろ、と書かれたコメントがあったので、試してみようかと思います。 -- [武内(管理人)]
  • rake tmp:cache:clear クリアして、Apacheの再起動では? -- [アプロ]
  • はい、やってみました。が、私の見立て違いで問題は全然別の所でした。アプロさんのおっしゃるとおり、アップグレード手順を逐一踏んでいなかったせいでおかしなコードを紛れ込ませてしまっていました。残念。 -- [武内(管理人)]
  • 前半のエラーはどうなんでしょうね。他でも報告されているので、私だけの問題ではないような。コードを見るだけでも問題起きそうな感じがひしひしとしますし・・・ -- [武内(管理人)]

Counter: 14194 (from 2010/06/03), today: 2, yesterday: 0