深入分析HTTP状态码502（nginx+php-fpm）

gdrocket

　　我们的一个web项目，由于新上城市增多，导致访问量增大，DB压力增大，作为提供接口的业务方，最近被下游反馈大量请求“502”。
　　502，bad gateway，一般都是upstream（这里就是php）出错，对于php，造成502的原因常见的就是脚本执行超过timeout设置时间，或者timeout设置过大，导致php进程长时间不能被释放，没有空闲worker进程来接客。
　　我们的项目就是php执行时间设置过短导致的，对于这种情况，可以先适当增大php的执行时间，先保证清除502，优化的事情毕竟要花更多的时间。
　　控制php执行时间的选项有两个，在php.ini中 max_execution_time 和php-fpm中 request_terminate_timeout，其中 request_terminate_timeout 可以覆盖 max_execution_time，所以如果不想改全局的php.ini，那只改php-fpm的配置就可以了。
　　下边我就来详细的分析一下为什么php脚本执行超出设置时间会导致nginx返回502。
　　先来布景，让问题复现：
　　nginx和php分别只启动一个worker，方便追踪。
　　php-fpm的request_terminate_timeout设置为3S。
　　测试脚本test.php
　　

(20);　　

echo 'ok';　　

　　go go go：
　　在浏览器访问www.v.com/test.php，3S后如期出现...404？？？what？？？

　　出师不利啊，赶紧看看nginx的配置文件

　　这个location配置是当发生5xx错误时跳转到一个好看点的界面，但是我在/usr/share/nginx/html下并没有50x.html这个文件。所以搞了个404出来。这不是很影响我判断问题的准确性？直接注释掉！再次访问，等待3S，终于'正常'的界面出来了。

　　环境好了，下边就上套路，按照web问题的排查套路走一遍，先看看错误日志吧：
　　nginx:

　　报错都是 recv() failed (104: Connection reset by peer。
　　recv时失败了，连接被重置了。为啥连接被重置了？难道一言不合。
　　我们在看看php-fpm的错误日志：
　　（注意php-fpm中php_admin_value[error_log]选项指定php的错误日志，会覆盖php.ini中的。但是这里不是看php的错误，而是看php-fpm的错误。php-fpm的错误日志由php-fpm.conf中的error_log选项指定。）

　　每一次请求都是产生2个WARNING和1个NOTICE：
　　WARNING：脚本执行超时了，终止了。
　　WARNING：子进程收到SIGTERM信号退出了。
　　NOTICE：启了一个新的子进程（因为我设置的pm.min_spare_servers = 1）
　　看来如果php的worker进程执行超时，不仅终止脚本执行，而且worker进程也会退出。看来nginx的报错连接被重置是因为php的worker进程退出了（在TCP连接中一方如果断掉的话会发送RST给另一方）
　　通过日志已经可以知道php脚本执行超时，worker子进程退出，导致nginx报错Connection reset by peer，下边我们通过strace来看看php和nginx的情况：
　　php：

　　1.accept一个nginx的连接请求（socket，bind，listen都在master中完成 ），可以看到nginx的端口是47039，从FD0中读取数据，就是从标准输入中，这个是fast-cgi协议规定的。accept之后的已连接描述符是3。
　　2.从FD3中读取nginx传递过来的数据，fastcgi协议格式，接收了856字节。为什么read5次呢？
　　因为fastcgi协议数据包是8字节对齐，由包头和包体组成。并且都是会先发一个request数据包，包含一些请求ID，版本，typpe等信息（包头包体各占8字节），再发一个params数据包，传递get参数和环境变量（包头8字节，包体变长），最后发送一个没有包体只有包头的params数据包，表示参数发送结束（包头8字节）。所以前3个read用来读出request包的包头和包体，还有params包的包头，第四个read是读取真正的数据，最后一个read是读取最后一个params包的包头。所以nginx传递的数据应该是8+8+8+856+8=896字节（和下边nginx的传输bytes能对应上）。注意如果是post方式，还会发送stdin数据包。
　　3.设置休眠20S，就是php程序中的sleep(20)，之后由于进程被终止了，所以后边就没啦。strace程序也退出啦。
　　nginx：

　　1.accept到浏览器的请求，可以看到浏览器端的端口是56434，IP是192.168.1.105，已建立连接的FD是3。
　　2.从FD3中接收数据，HTTP协议。
　　3.创建一个socket，FD21，用于和php建立连接。
　　4.连接到FD21，可以看到连接的是本机的9000端口，这里nginx和php-fpm使用IP socket连接方式，nginx和php-fpm部署在一台机器上可以考虑unix domain socket。
　　5.向FD21写入数据，fast-cgi协议格式，我们看到写入的长度是896，和上边的php接收的长度是对应的。
　　6.recvfrom函数从FD21中返回 ECONNRESET (Connection reset by peer)
　　7.向FD9中写入错误信息，可以推断FD9就是nginx错误日志的文件描述符。
　　8.关闭和FD21的连接。
　　9.向FD3写入502 Bad Gateway，就是返回给浏览器的信息。
　　10.向FD8写入一条访问日志，可以推断FD8就是nginx访问日志的文件描述符。
　　来验证一下nginx访问日志和错误日志的推断。可以看到的确是FD8，FD9，并处于写入模式。

　　那么在这个过程中整个网络包的传输我们不妨也看一下：
　　通过tcpdump抓包，用神器看比较方便。
　　因为只想看nginx和php的通讯，在上边又知道nginx的端口是47039，可以通过tcp.srcport==47039过滤出对应的包。

　　可以看到nginx和php-fpm数据交互的过程：47039->9000建立三次握手，接着向9000发送数据，9000回复ACK，3S后9000回复RST。没毛病。
　　注意：
　　SYN，FIN各占一个序列号
　　ACK，RST不占序列号（28，29两个包的reqnum和acknum都是相同的）
　　序列号是每一字节加1（29包发送896字节，同时29包seq为4219146879，30包的ack为4219147775，正好相差896）
　　RST不需要回复。