rails/reset_session のバグ? の履歴(No.2)
更新急に 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 $ rails --version Rails 2.3.5 $ 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の再起動では? -- [アプロ]
- はい、やってみました。が、私の見立て違いで問題は全然別の所でした。アプロさんのおっしゃるとおり、アップグレード手順を逐一踏んでいなかったせいでおかしなコードを紛れ込ませてしまっていました。残念。 -- [武内(管理人)]
- 前半のエラーはどうなんでしょうね。他でも報告されているので、私だけの問題ではないような。コードを見るだけでも問題起きそうな感じがひしひしとしますし・・・ -- [武内(管理人)]