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

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

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

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

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 都被拖跨了

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

共收到 7 条回复

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 啊

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