avatar
@bangbang93

又拍云bug导致post请求源站抛出500时会处理成504

4/27/2017, 8:24:53 PM

0x00 发现

这次故障是在厂里生产环境发现的,表现为:

  1. 接口遇到错误时服务器抛出500错误,但是前端迟迟拿不到响应
  2. 前段pending很久之后拿到cdn返回的504错误

0x01 分析

最初是认为后端对500的响应处理有问题,但是这个问题仅在生产环境上可复现,测试环境和本地开发均能够正常的返回500。
由于项目的历史原因,并没有完善的access log可以查看,所以先发布了一版带access log的版本观察,日志也显示线上环境能够正常返回500状态码,nginx日志也证实了这一点

后来检查服务器日志的时候发现,一旦请求发生了500错误,请求都会被重复一次,而如果请求是GET,那么重复一次的请求能够正常处理,如果是POST,则会挂起很久后nginx打出499的同时前端拿到504。

查到这里,已经基本能够确定是又拍云的锅了,但是客服不知道是没有理解还是什么原因,依旧让我自查应用,那就只好拿出点更有说服力的证据了。

0x02 抓包

在服务器上抓包后发现,截图中的第94个包是又拍发来的HTTP请求头部,96是body,服务器在第135个包返回了500响应,紧接着又拍云又开始了一次ack,建立了一个新的tcp连接并且于第201个包发来了一个HTTP请求头部,并且这个请求的x-request-id和94号包完全一样,其余内容也一模一样。包括了"content-length"头,但是接下来,却没有发来body,直到56秒后发来了FIN包,关闭了tcp连接,nginx打出499,前端拿到504。

0x03 无限等待的nginx

那么故障也很明确了,首先是又拍云不知道什么原因会重复一次500请求,并且重复的请求不会携带body,但是会携带"content-length"头,导致nginx一直在等待对方发送body,而又拍云等到超时也没有发送出body,并且主动关闭了连接,于是这个请求不会被nginx发送给后端服务器,所以后端服务的日志里看不到这个请求。

知道这个问题后又做了几个实验

  1. 在另一个账号上写了上图的php文件
  2. GET请求和POST但是没有body的请求会重复一次请求后返回500
  3. POST带body的请求会504

也就是说就是重复请求,却又不会发送body导致的这个问题,重新联系客服后又联系了认识的又拍云的开发谈心

0x04 修复

截止写完这篇文章的时候,又拍云已经回复修复了这个问题,我测试也正常了,抛出的500错误,既不会被重复请求,也不会返回504了