深入分析HTTP状态码502(nginx+php-fpm)

我们的一个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

sleep(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不需要回复。