序:
最近在做医疗相关的数据应用,知道治病要找到病因,才好对症下药,因为不同的病因,有可能引发相同的病症。而从症状入手确定病因,却也是最直接最常用的一个种诊断手法,但不能浮于表面现象,还要深入排查寻找病根才能真正根除疾病。

概述:
开始以为是 protect_from_forgery 引发的问题,但实际却是cgi接口的问题。由于“症状”只有在特定环境才会发生,在本地开发模式无法重现错误,更不用说调试,这才是最麻烦的地方。有BUG不怕,怕的是找不到BUG在哪。

正文:
具体“症状”表现为:
在production server中,有时在进行登录或表单提交操作时会出现异常提示:
ActionController::InvalidAuthenticityToken

异常抛出在:
/usr/local/lib/ruby/gems/1.8/gems/actionpack-2.3.4/lib/action_controller/request_forgery_protection.rb:79:in `verify_authenticity_token'


出错后刷新几次或者点击别的页面再重新提交问题消失不再出现。

因为只是简单的表单提交操作,因此并不是常见的ajax引发的InvalidAuthenticityToken 问题。即使把本地开发环境(apache+passenger,或者单个mongrel by script/server)切换到production 模式,并把production的数据在本地导入,都无法重现问题,似乎只在production server的运行环境(nginx + mongrel cluster)中才会出现。

要debug,肯定要找出bug所在,找出bug之前,就要确定bug出现的条件(现场重现)。

这个现象不是每次访问都出现,感觉像是“随机”出现,一时抓不到明确的规律。

不断测试后来发现问题出现的共通特点:是在本地提及了代码后,然后执行服务器自动更新命令(服务器自动更新代码、数据迁移、最后重启web server)后才出现的。再一步测试,确认了是重启web server后才出现问题,“随机”之谜破解。

有时按Ctrl+F5 强制刷新后问题消失,开始以为是浏览器的自动填充表单中的authenticity_token 导致的,但测试所有浏览器后(FF3,CHROME,IE8,SeaMonkey)都有同样现象。

反复测试,终于找出了问题重现的步骤:

1. 打开一个show 页面
2. 重启mongrel server
3. 在show页面进入编辑页面
4. 提交表单
5. 出现错误后,后退到编辑页,刷新(直接F5,或者Ctrl+F5强制刷新)后再提交,则不会出现报错
(或者在第4步中,刷新两次后再提交表单,则不会出现错误)

问题得以重现!接下来就可以开始debug了,但这情况debug有点麻烦。

多次查看HTML的源码,发现authenticity_token的值并没有变动(authenticity_token  这个值不是每次请求后都改变,而是在seesion的生命周期内有效)。

只好在test server(与production server完全一样的运行环境:nginx + mongrel cluster)中进行跟踪。
因为没办法确定bug的确切引发因数,也没办法使用debugger触发断点,只好插入logger来跟踪数据:
最接近异常的地方是 verified_request? 方法,因此在application_controller 中覆盖它并插入跟踪代码:

def verified_request?
logger.info("form_authenticity_token=#{form_authenticity_token}")
logger.info("params_token:#{params[request_forgery_protection_token]}")
logger.info("params:#{params.inspect}")

!protect_against_forgery?     ||
request.method == :get      ||
request.xhr?                ||
!verifiable_request_format? ||
form_authenticity_token == params[request_forgery_protection_token]
end

在verified_request?插入日志跟踪发现,重启mongrel后,提交的数据中POST的数据为空(params中只有记录到从 URL中获取到的数据如controller,action,而没有所提交的form数据),自然就无法通过 form_authenticity_token == params[request_forgery_protection_token] 这步判断。

这时推测原因可能是 mongrel进程 重启后,与nginx失去联系(虽然通讯端口不变),提交的数据由nginx接收到,但没有全部转发给mongrel (POST的数据丢失)

但查看nginx的日志时,却发现是有记录到post数据的长度(长度等于在Firebug中发送出去的数据长度),因此确定nginx是有接收到post的数据,但没有转发给mongrel(或者mongrel接收出错?)

至此,可以排除了是由 authenticity_token 相关代码导致的问题,而是nginx和mongrel的通信问题导致了问题出现,因此才无法在本地重现问题。

知道关键部分所在,很快就能google到相关的问题 :
“   After you restart a Mongrel server the first request will always fail to have the correct HTTP request body. The reason for this is the override of CGI#initialize_query method by ActionController in the cgi_ext/query_extension.rb file.“

解决倒是简单:
“but the solution is easy: just require action_controller/cgi_ext.rb when ActionController loads.“

这里有该问题详细的讲解。

最终使用的解决方案是:
添加启动补丁:
config/initializers/rails_patch.rb

内容为:
require 'action_controller/cgi_ext' if Rails::version == '2.3.4'

问题解决!(该问题会在Rails 2.3.5 中解决)