gdrocket 发表于 2017-12-23 09:57:21

深入分析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
  

(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选项指定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不需要回复。
页: [1]
查看完整版本: 深入分析HTTP状态码502(nginx+php-fpm)