nginx 502 和 504 超時演示

lufeihaidao發表於2019-03-03
Nginx

原連結

最近線上 nginx 遇到了一些較難排查的 502 和 504 錯誤，順便了解了一下 nginx 的相關配置。我發現網上很多介紹 nginx 超時配置只是列了這幾個配置的含義和數值，並沒有解釋什麼原因會觸發哪個配置。因此趁這個機會演示一下，如何讓 nginx 符合預期正確出現 502 和 504。

502 和 504 的解釋

在 http status 的 定義 中：

  • 502 Bad Gateway: The server was acting as a gateway or proxy and received an invalid response from the upstream server.
  • 504: he server was acting as a gateway or proxy and did not receive a timely response from the upstream server.

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
    1 root       0:00 php-fpm: master process (/usr/local/etc/php-fpm.conf)
    6 www-data   0:00 php-fpm: pool www
    7 www-data   0:00 php-fpm: pool www
/var/www/html # ps aux | grep php
    1 root       0:00 php-fpm: master process (/usr/local/etc/php-fpm.conf)
    7 www-data   0:00 php-fpm: pool www
   17 www-data   0:00 php-fpm: pool www
/var/www/html # ps aux | grep php
    1 root       0:00 php-fpm: master process (/usr/local/etc/php-fpm.conf)
   17 www-data   0:00 php-fpm: pool www
   20 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 了[^2]。如果我們這個時候執行nginx -t會發現，nginx 已經認為配置檔案有問題了：nginx: configuration file /etc/nginx/nginx.conf test failed。

換一種配置

這篇文章 提到，我們之前的 nginx 配置並不合理[^1]，我們重新設定 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]: 這篇文章 表明，我們之前的設定中，如果 PHP 沒有先啟動起來，那麼 nginx 也是啟動不起來的，這種設定並不合理：nginx 的一臺上游服務有問題，結果 nginx 就無法提供服務了。但這和我們的演示關係不大，因此並沒有在正文中過多描述。

[^2]: 按理說，既然 nginx 已經知道 PHP 不可達，不去發 TCP 請求了，那麼應該立即 502 才是。實驗中發現，這種情況下的 502 有 3s 左右的延時，不知何故。

相關文章