β

nginx 502 和 504 超时演示

Storm Spirit 578 阅读

最近线上 nginx 遇到了一些较难排查的 502 和 504 错误,顺便了解了一下 nginx 的相关配置。我发现网上很多介绍 nginx 超时配置只是列了这几个配置的含义和数值,并没有解释什么原因会触发哪个配置。因此趁这个机会演示一下,如何让 nginx 符合预期正确出现 502 和 504。

502 和 504 的解释

在 http status 的 定义 中:

502 的错误原因是 Bad Gateway,一般是由于上游服务的故障引起的;而 504 则是 nginx 访问上游服务超时,二者完全是两个意思。但在某些情况下,上游服务的超时(触发 tcp reset)也可能引发 502,我们会在之后详述。

演示环境

你需要 3 个逻辑组件:nginx 服务器,php-fpm,client 访问客户端。3 个组件可以在同一台机器中,我用的是 docker 来配置 PHP 和 nginx 环境,在宿主机上访问。如果你很熟悉这 3 个组件,这部分可以跳过。用 docker 来做各种测试和实验非常方便,这里就不展开了。docker-compose 的配置参考了这篇 文章 。我的 docker composer 文件如下:

version: '3'
services:
  web:
    image: nginx:alpine
    ports:
      - "8080:80"
    volumes:
      - ./code:/code
      - ./nginx/site.conf:/etc/nginx/conf.d/site.conf
    depends_on:
      - php
  php:
    image: php:7.1-fpm-alpine
    volumes:
      - ./code:/code
      - ./php/php-fpm.conf:/usr/local/etc/php-fpm.conf

使用的镜像都是基于 alpine 制作的,非常小巧:

REPOSITORY  TAG               SIZE
php         7.1-fpm-alpin     69.5MB
nginx       alpine            18.6MB

nginx 的配置:

server {
  index index.php index.html;
  server_name php-docker.local;
  error_log  /var/log/nginx/error.log;
  access_log /var/log/nginx/access.log;
  root /code;

  location ~ \.php$ {
    try_files $uri =404;
    fastcgi_split_path_info ^(.+\.php)(/.+)$;
    fastcgi_pass 127.0.0.1:9000;
    fastcgi_index index.php;
    include fastcgi_params;
    fastcgi_param SCRIPT_FILENAME $document_root$fastcgi_script_name;
    fastcgi_param PATH_INFO $fastcgi_path_info;
    fastcgi_connect_timeout 5s;
    fastcgi_read_timeout 8s;
    fastcgi_send_timeout 10s;
  }
}

php-fpm 的配置

[global]
include=etc/php-fpm.d/*.conf
request_terminate_timeout=3s

代码放在 github

关键参数

在这个演示中,PHP 的关键参数有两个,一个是 PHP 脚本的 max_execution_time,这个配置在php.ini中;另一个是 php-fpm 的 request_terminate_timeout,在php-fpm.conf中。当以 php-fpm 提供服务时,request_terminate_timeout 设置会覆盖 max_execution_time 的设置,因此我们这里只测试 request_terminate_timeout。

request_terminate_timeout 的意思是 php-fpm 接受的请求的超时时间,超过这个时间 php-fpm 会 kill 掉执行脚本的 worker 进程。

nginx的关键参数是 fastcgi 相关的 timeout,即:fastcgi_connect_timeout,fastcgi_read_timeout,fastcgi_send_timeout。

这几个 nginx 参数的主语都是 nginx,所以 fastcgi_connect_timeout 的意思是 nginx 连接到 fastcgi 的超时时间,fastcgi_read_timeout 是 nginx 读取 fastcgi 的内容的超时时间,fastcgi_send_timeout 是 nginx 发送内容到 fastcgi 的超时时间。

演示过程

首先启动 nginx 和 PHP:

docker-compose up

在 code 文件夹下添加一个 index.php 文件:

<?php
sleep(70);
echo 'hello world';

上游服务主动 reset

访问 php-docker.local:8080/index.php,报错 502 bad gateway。而且是在 3s 之后报的错,说明触发了 request_terminate_timeout 设置,php-fpm 关闭了连接。

通过观察 ps aux | grep php 可以发现,php-fpm 是通过杀掉超时的进程来解决进程超时问题的(pid 每次有一个会变化,说明一个进程杀掉了,并启动了另一个进程。这和 php-fpm 的进程池设定有关,你的设定未必会重新启动一个新的进程)。

/var/www/html # ps aux | grep php
 root       0:00 php-fpm: master process (/usr/local/etc/php-fpm.conf)
 www-data   0:00 php-fpm: pool www
 www-data   0:00 php-fpm: pool www
/var/www/html # ps aux | grep php
 root       0:00 php-fpm: master process (/usr/local/etc/php-fpm.conf)
 www-data   0:00 php-fpm: pool www
 www-data   0:00 php-fpm: pool www
/var/www/html # ps aux | grep php
 root       0:00 php-fpm: master process (/usr/local/etc/php-fpm.conf)
 www-data   0:00 php-fpm: pool www
 www-data   0:00 php-fpm: pool www

在这种情况下,nginx 日志中的错误是:

recv() failed (104: Connection reset by peer) while reading response header from upstream

即连接被服务端(PHP)reset 了,也就很好理解了。

注意,在这种情况下,php-fpm 的日志中也会记录的:

php_1  | [18-Jul-2018 16:33:42] WARNING: [pool www] child 5, script '/code/index.php' (request: "GET /index.php") execution timed out (3.040130 sec), terminating
php_1  | [18-Jul-2018 16:33:42] WARNING: [pool www] child 5 exited on signal 15 (SIGTERM) after 30.035736 seconds from start
php_1  | [18-Jul-2018 16:33:42] NOTICE: [pool www] child 8 started

这也是可以发现问题的一个地方。

nginx 读取上游服务超时

删掉 request_terminate_timeout 配置,重启应用:

docker-compose down && docker-compose up

此时,PHP 脚本将要执行 70s,肯定超过 nginx 设置的超时时间,get 一下发现确实如此,8s 之后抛出 504 Gateway Time-out 错误,nginx 日志是:

upstream timed out (110: Operation timed out) while reading response header from upstream

说明触发了 fastcgi_read_timeout 设置。

关闭上游服务

关掉 PHP 服务:

docker-composer stop php

PHP 服务停掉之后第一次访问,得到 504 错误,错误是:

upstream timed out (110: Operation timed out) while connecting to upstream

超时时间为 fastcgi_connect_timeout 的设置。说明这个时候 tcp 连接还在,但是尝试连接的时候失败了。

再次访问,得到 502 错误,错误是:

connect() failed (113: Host is unreachable) while connecting to upstream

502 的原因很容易理解,上游服务挂了,同时因为之前访问的时候发现连接不上就把连接断掉了,再次连接的时候便无法找到 host 了。

我曾怀疑第一次访问 504 是由于 keepalive。但我停掉 PHP 之后隔了好久才发第一个请求,仍然是这个结果。

如果将 nginx fastcgi_pass 配置为 127.0.0.1:9000(本地没有这个端口),则马上就会抛出 502 错误,错误为:

connect() failed (111: Connection refused) while connecting to upstream

登入 nginx 服务,使用 tcpdump 监控 9000 上的通信:

tcpdump -i eth0 -nnA tcp port 9000
# 如果你的 PHP 在本地,eth0 应该改成 lo

我们发现,当 PHP 关闭之后第一次访问,nginx 会尝试向 PHP 发起若干次 TCP SYN 请求,但 PHP 显然不会响应,这个时候 nginx 就返回了 504。第二次访问的时候 nginx 根本不会发起任何请求,直接 502 了 1 。如果我们这个时候执行nginx -t会发现,nginx 已经认为配置文件有问题了:nginx: configuration file /etc/nginx/nginx.conf test failed。

换一种配置

这篇文章 提到,我们之前的 nginx 配置并不合理 2 ,我们重新设置 nginx:

server {
  index index.php index.html;
  server_name php-docker.local;
  error_log  /var/log/nginx/error.log;
  access_log /var/log/nginx/access.log;
  root /code;
  resolver 127.0.0.11;  # here
  location ~ \.php$ {
    set $upstream php:9000; # here
    try_files $uri =404;
    fastcgi_split_path_info ^(.+\.php)(/.+)$;
    fastcgi_pass $upstream;  # here
    fastcgi_index index.php;
    include fastcgi_params;
    fastcgi_param SCRIPT_FILENAME $document_root$fastcgi_script_name;
    fastcgi_param PATH_INFO $fastcgi_path_info;
    fastcgi_connect_timeout 5s;
    fastcgi_read_timeout 8s;
    fastcgi_send_timeout 10s;
  }
}

其中 127.0.0.11 是 docker 的内网 dns resolver。该配置动态指定 fastcgi pass,所以 nginx 不会检查该连接能否建立起来。

按照这个配置启动,先访问 index.php 建立连接,然后关闭 PHP,表现为:

在 keepalive 期间,抛出 504 错误,超时时间为 fastcgi_connect_timeout,错误是:

upstream timed out (110: Operation timed out) while connecting to upstream

keepalive 断线之后,抛出 502 错误,超时时间不定,错误是:

connect() failed (113: Host is unreachable) while connecting to upstream

按照 这篇文章 所说,这种配置 nginx 不会认为有问题,执行nginx -t确实如此。在 一段时间 内,每次请求 nginx 都会向 upstream 发送 SYN,这段时间的状态码都是 504,之后再访问就不再发 TCP 包,状态码也变成 502。

其他

除此之外,PHP 脚本还有一个超时时间的设置:max_execution_time。它是限制 PHP 脚本的执行时间,但这个时间不会计算系统调用(比如 sleep,io,等)。因为该原因导致 PHP 杀掉进程时,会抛出 fatal error,而 php-fpm 不会有 fatal error。

这里实验使用的是 PHP 的 fastcgi 工作方式,如果是 nginx 通过代理的方式连接上游服务的话,fastcgi_connect_timeout,fastcgi_read_timeout,fastcgi_send_timeout 都需要替换成对应的 proxy_connect_timeout,proxy_read_timeout,proxy_send_timeout。

结论

504 的原因比较简单,一般都是上游服务的执行时间超过了 nginx 的等待时间,这种情况是由于上游服务的业务太过耗时导致的,或者连接到上游服务器超时。从上面的实验来看,后者的原因比较难以追踪,因为这种情况下连接是存在的,但是却连不上,好在这种 504 一般都会在一段时间后转为 502。

502 的原因是由于上游服务器的故障,比如停机,进程被杀死,上游服务 reset 了连接,进程僵死等各种原因。在 nginx 的日志中我们能够发现 502 错误的具体原因,分别为:104: Connection reset by peer,113: Host is unreachable,111: Connection refused。

有一些细节上的差别和 nginx 的工作原理有关,这部分尚未深挖。

  1. 按理说,既然 nginx 已经知道 PHP 不可达,不去发 TCP 请求了,那么应该立即 502 才是。实验中发现,这种情况下的 502 有 3s 左右的延时,不知何故。

  2. 这篇文章 表明,我们之前的设置中,如果 PHP 没有先启动起来,那么 nginx 也是启动不起来的,这种设置并不合理:nginx 的一台上游服务有问题,结果 nginx 就无法提供服务了。但这和我们的演示关系不大,因此并没有在正文中过多描述。

作者:Storm Spirit
这是我的中文博客,记录自己在技术、生活等方面的一些感想。博客叫 Storm Spirit, 因为我特别喜欢 Dota 里蓝猫这个英雄,可惜玩得不好…… 希望自己能够通过博客,得到成长。
原文地址:nginx 502 和 504 超时演示, 感谢原作者分享。

发表评论