什么可能导致重复logging由Rails创build?

我们注意到很多重复的logging正在我们的数据库的各种表格中创build,但是为什么会发生这种情况。 有趣的是,虽然logging是重复的(甚至到created_at邮票!),在我们的用户表上,每个logging上的密码salt和hash是不同的 – 这导致我相信Rails以某种方式运行事务/保存操作两次。 显然,我们不是在应用程序代码中调用save或多次create

数据库中保存的每条logging似乎都没有发生这种重复,而且我们似乎还无法推断出一种模式。 在User模型上也有validates_uniqueness_ofvalidation(虽然不是表格上唯一的键值;我们需要清理所有重复项目才能做到这一点) – 所以如果一个logging已经存在,Rails应该自行停止,如果这些请求同时触发,这是一个竞争条件。

我们目前在我们的应用程序服务器(当前是2个)上运行Rails 3.2.2后面的Passenger 3.0.11 / nginx,并且有一个中央的nginx web服务器,它将请求上传到应用程序服务器。 难道这个设置不知何故导致进程被复制或什么? 重要的是请求没有被locking到一个上游服务器上(例如,如果有一个用户请求包含静态内容的页面,比如图像,则可以使用一个或两个应用服务器)? (我觉得这是抓住吸pipe,但我想涵盖所有可能性)

还有什么可能导致这种情况发生?

更新:作为一个例子,今天创build了一个有重复logging的用户。 两者都有2012-03-28 16:48:11created_at标记,除了hashed_passwordsalt之外的所有列都是相同的。 从请求日志中,我可以看到以下内容:

应用服务器1:

 Started POST "/en/apply/create_user" for 1.2.3.4 at 2012-03-28 12:47:19 -0400 [2012-03-28 12:47:19] INFO : Processing by ApplyController#create_user as HTML [2012-03-28 12:47:20] INFO : Rendered apply/new_user.html.erb within layouts/template (192.8ms) Started POST "/en/apply/create_user" for 1.2.3.4 at 2012-03-28 12:48:10 -0400 [2012-03-28 12:48:10] INFO : Processing by ApplyController#create_user as HTML [2012-03-28 12:48:11] INFO : Redirected to apply/initialize_job_application/3517 [2012-03-28 12:48:11] INFO : /app/controllers/apply_controller.rb:263:in `block (2 levels) in create_user' 

应用服务器2:

 Started POST "/en/apply/create_user" for 1.2.3.4 at 2012-03-28 12:48:10 -0400 [2012-03-28 12:48:10] INFO : Processing by ApplyController#create_user as HTML 

networking服务器:

 1.2.3.4 - - [28/Mar/2012:12:48:10 -0400] "POST /en/apply/create_user HTTP/1.1" 499 0 "en/apply/create_user" "Mozilla/5.0 (compatible; MSIE 9.0; Windows NT 6.1; Win64; x64; Trident/5.0)" "-" 1.2.3.4 - - [28/Mar/2012:12:48:11 -0400] "POST /en/apply/create_user HTTP/1.1" 302 147 "en/apply/create_user" "Mozilla/5.0 (compatible; MSIE 9.0; Windows NT 6.1; Win64; x64; Trident/5.0)" "-" 

所以创build操作被命中了三次(可能是第一次由于错误返回到表单),并且每个服务器上至less一次。 后两者都被networking服务器注册为单独的请求,但是第一个获得状态码499 Client Closed Request (根据维基百科的一个nginx扩展),第二个获得了预期的302 。 499会造成这里的问题吗?

想到两种可能性。

当用作负载平衡器时,第一个是Nginx的一个奇怪的(而不是RFC)行为。 它会重试任何失败的请求对下一个后端。 RFC只允许安全的方法(如GETHEAD )。 这样做的结果是,如果你的nginx认为某个请求因为某种原因失败了,可能是它被重新发送到下一个服务器。 如果两台服务器都完成了它们的交易,那么你有一个重复记录。 从您的网络服务器日志(以及Nginx使用的499状态代码来表示用户单击浏览器中止)来看,这看起来是最可能的原因。

第二种可能性是你的用户双击发送按钮。 在合适的时间,他们的浏览器几乎可以同时发送两个完整的请求。

为了确保你的用户记录是唯一的,你应该在你的数据库上创建唯一的索引。 这些都是实际上确保的(尽管与ActiveRecord检查相比,错误信息更糟)。因此,您应该始终在数据库模式和模型上定义唯一性约束。

另外,你可以考虑用更符合的负载均衡器替换你的前端nginx。 我推荐haproxy 。

这看起来像是一个竞赛条件。 确保在请求之间锁定。 很容易发生一个或两个请求被复制。 在没有交易的情况下交换物品也会发生同样的情况,所以请确保您的请求之间没有竞争。