Rails Rails + Puma 线程死掉了没有报错么?

IChou · 2016年07月05日 · 最后由 xworm 回复于 2016年07月05日 · 3575 次阅读

先容我描述一下这个场景:

这是一个微信公众号项目,大部分时间,它还是讲道理的,看上去老老实实,勤勤恳恳的。但是,冷不防你准备下班或者睡觉的时候,微信报警群里就会跳出来一条报警:

XXX 公众号在微信服务器请求后 5s 内没有响应

然后你屁颠屁颠的去查 Rails 日志,擦咧,没有报错,也基本没有超过 5s 的请求。去 OneApm 上去看,报错率 0%,顿时感觉日了🐶了

就在你还没找到问题是什么的时候,这个时候,第二条报警又来了。。吓得我立马重启服务,终于世界安静了

但是哪儿出错了依旧没找到。


背景交代结束,下面是正文

是问题终归要解决,Rails 里查不出问题,就往下一层走,先去看看 nginx,果然有收获

2016/07/04 22:05:58 [error] 32398#0: *18194461 upstream prematurely closed connection while reading response header from upstream, client: ***.207.54.75, server: **.cn, request: "POST /robot?signature=1dd244608fe34b**650c3497185d33d60cd12cfe&timestamp=1467641156&nonce=443071359&openid=***FPt3ibC_ujlPjUF5Y79SwRkEw HTTP/1.0", upstream: "http://**.168.***.86:10081/robot?signature=1dd244608fe34b**650c3497185d33d60cd12cfe&timestamp=1467641156&nonce=443071359&openid=***FPt3ibC_ujlPjUF5Y79SwRkEw", host: "**.cn"

upstream 非正常提前退出,好,现在拿着这个请求去 Rails 的日志中查

# grep 64d3bb21-af3b-46c3-af98-5056a64e7088 log/production.log

I, [2016-07-04T22:05:56.714306 #11883]  INFO -- : [64d3bb21-af3b-46c3-af98-5056a64e7088] Started POST "/robot?signature=1dd244608fe34b**650c3497185d33d60cd12cfe&timestamp=1467641156&nonce=443071359&openid=***FPt3ibC_ujlPjUF5Y79SwRkEw" for 140.207.54.75 at 2016-07-04 22:05:56 +0800
I, [2016-07-04T22:05:56.718092 #11883]  INFO -- : [64d3bb21-af3b-46c3-af98-5056a64e7088] Processing by RespondersController#create as XML
I, [2016-07-04T22:05:56.718229 #11883]  INFO -- : [64d3bb21-af3b-46c3-af98-5056a64e7088]   Parameters: {"signature"=>"1dd244608fe34b**650c3497185d33d60cd12cfe", "timestamp"=>"1467641156", "nonce"=>"443071359", "openid"=>"***FPt3ibC_ujlPjUF5Y79SwRkEw"}
W, [2016-07-04T22:05:56.721179 #11883]  WARN -- : [64d3bb21-af3b-46c3-af98-5056a64e7088] Request Info:  event   click btn_search    By User:    ***FPt3ibC_ujlPjUF5Y79SwRkEw

发现这个请求跟平时的日志比,少了类似这样的一行

I, [2016-07-05T10:59:45.049711 #9389]  INFO -- : [e026d1c6-bb33-48ff-ad76-fac910f2bbdb] Completed 200 OK in 4ms (Views: 0.1ms | ActiveRecord: 0.0ms)

也就是说,这个请求没有被执行完,就中断了,nginx 收到后端处理异常退出的信号,就抛出了上面的错误

由于应用是用 puma 在跑,rails 某个请求没执行完突然中断了,应该是由于某些原因导致这个线程死掉了吧,打开 puma 的日志一看,哭了

[8553] ! Terminating timed out worker: 22146
[8553] - Worker 3 (pid: 7459) booted, phase: 0
[8553] ! Terminating timed out worker: 22181
[8553] - Worker 0 (pid: 7457) booted, phase: 0
[8553] - Worker 1 (pid: 7495) booted, phase: 0

连个时间戳都没有,也没有报错(这个可能是我配置的问题,请先忽略)

下面,就是想要请教各位的问题了

  • puma 中某个请求死掉,在 Rails 和 puma 的日志里面都不会有标志性的体现,如果不去对比着 nginx 的日志查,根本就不知道这种情况的存在。是否有什么方法配置 puma ,让这种情况发生的时候,记录在日志中,以方便观测或预警

  • 这种情况下希望 Rails 自己去输出错误日志,我觉得已经不太可能了,毕竟线程已死。那么,我要如何去定位问题究竟是在哪一个环节上触发的呢?在代码里加入大量的 debug logger 可行,但是有点 low,这种情况的线上触发概率还是很低的

  • 通过排查请求处理时间 大于 5s 的 nginx 日志,我还发现一种更奇怪的现象:请求没执行完,死掉了,但是连 nginx 都没有收到信号,也没有错误日志。由于微信自己对于 5s 没有回应的请求会主动发送 499,中断 Nginx 的处理,不然估计 nginx 会对这个请求挂起到超时,大面积出现的话,那不是连 nginx 都被拖跨了

已经开始去查找相关资料,感觉我是不是碰到个疑难杂症, 如果哪位 大大 知道什么思路,还望提点

upstream prematurely closed connection while reading response header from upstream

看起来像是网络请求的超时时间大于了 Puma 的超时时间,导致网络请求还在处于 Wait 状态的时候 Puma / Nginx 放弃了连接

#1 楼 @huacnlee 嗯,是超时了。微信公众号服务的集群中有机器不支持 SSLv3,导致请求多次重试并超时 如果是触发了 Puma 的超时,Puma 放弃了连接并发送了中止信号,好像能说过去,需要试着记录一下 puma 的详细日志来看看

PS: puma 就一个 worker_timeout 参数,好像设置了,应用照样可以跑很久。对于 puma 限定超时这个东西也表示知识储备捉鸡啊

和我遇到的问题一样,我也是微信公众号,nginx+puma 跑两天就挂掉了,还以为是线程安全的问题,换了 unicorn 一直没有出现问题

如果是使用的 UNIX Sockets 时 puma 会过早放弃超时连接,建议使用 TCP

@kikyous unicorn 你是不是有个

unicorn/oob_gc unicorn/worker_killer

这玩意会自动重启 unicorn worker

#3 楼 @kikyous 一开始我遇到另一个问题的时候怀疑过线程安全问题 但是后来基本排出了,微信有时候会把同一个动作推送两次,导致出现类似线程不安全的假象

我这边现在并不会导致服务挂掉,不过经常 puma 平滑重启的时候,进程重启了,请求却进不来。 推测是我最后提到的那种情况产生了僵死的线程,导致资源没能完全释放,这种时候就需要先 stop 再 start

这个问题已经找到,我启用了 preload_app! ,和 phased restart 有冲突

Note that preload_app can’t be used with phased restart, since phased restart kills and restarts workers one-by-one, and preload_app is all about copying the code of master into the workers.

#4 楼 @xxqfamous 就是使用的 TCP 啊

需要 登录 后方可回复, 如果你还没有账号请 注册新账号