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

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

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

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