【发布时间】：2014-07-20 05:48:41
【问题描述】：
我的 Ruby on Rails 应用程序正在使用 Devise 来管理它的用户登录等。
我目前在使用密码重置功能时遇到问题。我已经让它在我们的本地环境中运行得很好，但是在生产服务器（在 Heroku 上）它失败了。
如果用户忘记密码，可以重置密码，系统会发送电子邮件，其中包含点击重置密码的链接。
单击此链接后，他们将成功进入该站点并要求输入新密码，然后进行确认。问题是一旦他们保存了这个密码，应用程序就会失败并显示标准的“应用程序错误 - 应用程序中发生错误并且您的页面无法加载”
查看heroku日志我可以看到以下内容
2014-05-30T12:38:15.373355+00:00 app[web.1]: Started PUT "/users/password" for xx.xxx.xxx.xxx at 2014-05-30 12:38:15 +0000
2014-05-30T12:38:15.377511+00:00 app[web.1]: Processing by Devise::PasswordsController#update as HTML
2014-05-30T12:38:15.377577+00:00 app[web.1]: Parameters: {"utf8"=>"???", "authenticity_token"=>"3NjJhk3HcIgIkWy8hlmizOVTX5Wx3N9RgHmxwK5Evrg=", "user"=>{"reset_password_token"=>"[FILTERED]", "password"=>"[FILTERED]", "password_confirmation"=>"[FILTERED]"}, "commit"=>"Change my password"}
2014-05-30T12:38:31.727191+00:00 app[web.1]: E, [2014-05-30T12:38:31.726292 #2] ERROR -- : worker=0 PID:5 timeout (16s > 15s), killing
2014-05-30T12:38:31.797612+00:00 app[web.1]: E, [2014-05-30T12:38:31.797478 #2] ERROR -- : reaped #<Process::Status: pid 5 SIGKILL (signal
9)> worker=0
2014-05-30T12:38:31.800988+00:00 heroku[router]: at=error code=H13 desc="Connection closed without response" method=POST path=/users/password host=horsepip.com request_id=27d37c84-544f-4fe5-a12d-a7384dfb60c5 fwd="xx.xxx.xxx.xxx" dyno=web.1 connect=1ms service=16425ms status=503 bytes=0
2014-05-30T12:38:31.986995+00:00 heroku[router]: at=info method=GET path=/favicon.ico host=horsepip.com request_id=91e0f2a7-284a-4c85-a9e2-af3d404f1151 fwd="xx.xxx.xxx.xxx" dyno=web.1 connect=0ms service=2ms status=200 bytes=196
2014-05-30T12:38:32.312878+00:00 app[web.1]: I, [2014-05-30T12:38:32.312200 #1109] INFO -- : worker=0 ready
我可以确定的是服务器工作者正在崩溃，并且查找其中一些错误我发现它们可能与 Unicorn Gem（我们正在使用的）有关
我们目前使用的是基本的 Heroku 包，因为我们的生产服务器目前使用的人并不多，但简单的密码重置肯定不会让工作人员崩溃吗？
我尝试通过设置页面更改用户密码，用户在该页面输入当前密码，然后输入新密码，这样可以很好地保存，没有任何问题。
有其他人对此有任何问题吗？
在调试模式下更新日志
2014-05-30T13:30:29.393026+00:00 app[web.1]: Processing by Devise::PasswordsController#update as HTML
2014-05-30T13:30:29.393096+00:00 app[web.1]: Parameters: {"utf8"=>"???", "authenticity_token"=>"oj1WtMp7zU+5MRiCjdk47NeEwJYyZkB7w+FcTvgD1ik=", "user"=>{"reset_password_token"=>"[FILTERED]", "password"=>"[FILTERED]", "password_confirmation"=>"[FILTERED]"}, "commit"=>"Change my password"}
2014-05-30T13:30:29.389774+00:00 app[web.1]: Started PUT "/users/password" for xx.xxx.xx.xxx at 2014-05-30 13:30:29 +0000
2014-05-30T13:30:30.045362+00:00 app[web.1]: ←[1m←[36mUser Load (2.4ms)←[0m ←[1mSELECT "users".* FROM "users" WHERE "users"."reset_password_token" = '0da2c26faa8c7a6a2935abf55b857590fdfc4b8bbb8ee90bfd5ad35c04f9e3ae' ORDER BY "users"."id" ASC LIMIT 1←[0m
2014-05-30T13:30:30.136894+00:00 app[web.1]: ←[1m←[36mSQL (1.7ms)←[0m ←[1mUPDATE "users" SET "encrypted_password" = $1, "reset_password_sent_at" = $2, "reset_password_token" = $3, "updated_at" = $4 WHERE "users"."id" = 1←[0m [["encrypted_password", "$2a$10$d2zQ6yuEb17QK2WtHmRk/ufQRhun1RO2ILJ16NJkL90T2JzbxciAq"], ["reset_password_sent_at", nil], ["reset_password_token", nil], ["updated_at", "2014-05-30 13:30:30.130959"]]
2014-05-30T13:30:30.130271+00:00 app[web.1]: ←[1m←[35m (1.4ms)←[0m BEGIN
2014-05-30T13:30:39.112542+00:00 app[web.1]: ←[1m←[35m (6.9ms)←[0m COMMIT
2014-05-30T13:30:39.159501+00:00 app[web.1]: ←[1m←[35mSQL (5.3ms)←[0m UPDATE "users" SET "current_sign_in_at" = $1, "last_sign_in_at" = $2, "reset_password_token" = $3, "sign_in_count" = $4, "updated_at" = $5 WHERE "users"."id" = 1 [["current_sign_in_at", "2014-05-30 13:30:39.133511"], ["last_sign_in_at", "2014-05-30 12:39:44.631269"], ["reset_password_token", "rZPXQ3r8D2easJmjzBox"], ["sign_in_count", 19], ["updated_at", "2014-05-30 13:30:39.147892"]]
2014-05-30T13:30:39.145115+00:00 app[web.1]: ←[1m←[36m (5.0ms)←[0m ←[1mBEGIN←[0m
2014-05-30T13:30:45.857557+00:00 app[web.1]: E, [2014-05-30T13:30:45.857376 #2] ERROR -- : worker=1 PID:8 timeout (16s > 15s), killing
2014-05-30T13:30:45.983703+00:00 app[web.1]: I, [2014-05-30T13:30:45.983379 #310] INFO -- : worker=1 ready
2014-05-30T13:30:45.915630+00:00 app[web.1]: E, [2014-05-30T13:30:45.915530 #2] ERROR -- : reaped #<Process::Status: pid 8 SIGKILL (signal 9)> worker=1
2014-05-30T13:30:45.917905+00:00 heroku[router]: at=error code=H13 desc="Connection closed without response" method=POST path=/users/password host=xxxxx.com request_id=d7fb6561-950a-4dcb-8852-52c259985c99 fwd="78.16.33.137" dyno=web.1 connect=0ms service=16526ms status=503 bytes=0
【问题讨论】：
-
您可以为服务器运行控制台实例并跟踪暂存/开发日志吗？然后你应该得到一些应用级的日志记录。
-
啊是的好主意，我会试试看我能找到什么
-
如果您仍然无法摆脱它，请在此处发布输出。
-
我将日志模式更改为调试，因为 Heroku 将所有日志文件合并在一起，但它并没有真正给我更多信息，输出在上面
-
惊人的 9 秒。 13:30:30 的 BEGIN 和 13:30:39 的 COMMIT 之间的延迟（中间什么都没有，这看起来很奇怪）。然后下一个 BEGIN 是在 13:30:39，系统在 6 秒后放弃并杀死工作人员，因为请求花费了超过 15 秒。问题是，为什么 BEGIN 和 COMMIT 之间会有这样的延迟？这是否发生在任何其他请求上？ （如果不是很奇怪。）其他请求是否很慢但没有那么慢，因此因为它们只有一个 BEGIN..COMMIT 就可以解决这个问题吗？无论如何，数据库或与之交互的东西看起来很奇怪。
标签： ruby-on-rails ruby heroku devise