代理到 Node/Express 上游时不常见的 NGINX 错误/超时（连接到上游时上游超时）

Posted 2023-02-27

【中文标题】代理到 Node/Express 上游时不常见的 NGINX 错误/超时（连接到上游时上游超时）

【英文标题】：Infrequent NGINX Errors/Timeouts when proxying to a Node/Express upstream (upstream timed out while connecting to upstream)

【发布时间】：2018-02-07 15:56:56

【问题描述】：

我们部署了一个 Express Web API，它在通过 nginx 代理的 EC2 ubuntu 服务器上运行，获得了不错但仍然相对较少的流量（平均每秒大约 10 个请求）。每隔一段时间，请求就会挂起，如果客户端等待的时间足够长，则会将包含以下内容的一行输出到 NGINX 错误日志：

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

我已经尝试过建议的解决方案here，但似乎没有效果。据我们所知，这种情况每分钟只会发生 1-3 次，但我只是离开了这些日志。如果客户端在请求超时之前刷新页面或导航离开，则似乎没有记录。

错误信息显然表明连接到上游服务器有问题，但为什么这种情况很少发生？ URL 中也绝对没有导致此问题的模式，并且据我所知，被代理的应用程序仍然可用。这是我们 NGINX 配置的一个想法：

user www-data;
worker_processes 4;
pid /run/nginx.pid;
events 
worker_connections 10000;

worker_rlimit_nofile 25000;

http 
sendfile on;
tcp_nopush on;
tcp_nodelay on;
keepalive_timeout 65;
types_hash_max_size 2048;
client_max_body_size 15M;
include /etc/nginx/mime.types;
include /etc/nginx/conf.d/ *.conf; //Added space before star because so formatting was turning it into a comment


include /etc/nginx/sites-enabled/ *;
default_type application/octet-stream;

log_format nginx_json ' "timestamp": "$time_local", '
                      ' "request_ip": "$remote_addr", '
                      ' "request_user": "$remote_user", '
                      ' "request_bytes_sent": "$bytes_sent", '
                      ' "response_status": "$status", '
                      ' "request": "$request", '
                      ' "request_method": "$request_method", '
                      ' "http_referrer": "$http_referer", '
                      ' "http_user_agent": "$http_user_agent", '
                      ' "request_id": "$request_id", '
                      ' "server_name": "$server_name",'
                      ' "response_time": "$upstream_response_time" ';

access_log /var/log/nginx/access.log nginx_json;
error_log /var/log/nginx/error.log;

gzip on;
gzip_disable "msie6";
ssl_prefer_server_ciphers on;
ssl_session_cache shared:SSL:10m;
ssl_ciphers "EECDH+AESGCM:EDH+AESGCM:ECDHE-RSA-AES128-GCM-SHA256:AES256+EECDH:DHE-RSA-AES128-GCM-SHA256:AES256+EDH:ECDHE-RSA-AES256-GCM-SHA384:DHE-RSA-AES256-GCM-SHA384:ECDHE-RSA-AES256-SHA384:ECDHE-RSA-AES128-SHA256:ECDHE-RSA-AES256-SHA:ECDHE-RSA-AES128-SHA:DHE-RSA-AES256-SHA256:DHE-RSA-AES128-SHA256:DHE-RSA-AES256-SHA:DHE-RSA-AES128-SHA:ECDHE-RSA-DES-CBC3-SHA:EDH-RSA-DES-CBC3-SHA:AES256-GCM-SHA384:AES128-GCM-SHA256:AES256-SHA256:AES128-SHA256:AES256-SHA:AES128-SHA:DES-CBC3-SHA:HIGH:!aNULL:!eNULL:!EXPORT:!DES:!MD5:!PSK:!RC4";
ssl_protocols TLSv1 TLSv1.1 TLSv1.2;
ssl_dhparam /etc/ssl/certs/dhparam.pem;

resolver 127.0.0.1 valid=30s;

server 
 listen 80;
 server_name a.mysite.com;
 return 301 https://$server_name$request_uri;


 server 
     listen 443 ssl;
     server_name a.mysite.com;
     add_header Strict-Transport-Security "max-age=31536000";
     add_header Cache-Control no-cache;
     location /api 
         proxy_pass http://1.2.3.4:3001;
         proxy_set_header Host $host;
         proxy_set_header X-Request-Id $request_id;
         proxy_set_header Connection "";
         proxy_http_version 1.1;
     
     location /ui2 
         set $uiHost https://abc.cloudfront.net/ui2/index.html?v=1503438694163;
         proxy_pass $uiHost;
     
     location / 
         set $uiHost https://abc.cloudfront.net/ui/index.html?v=1504012942606;
         proxy_pass $uiHost;
     
     ssl_certificate /path/to/certificate;
     ssl_certificate_key /path/to/certificate/key;
 

底部的服务器块针对多个子域重复，/api 路径通常指向不同端口上的同一服务器。一个子域获得了大部分流量。上游服务器（示例中为 1.2.3.4）配置了 EC2 安全组，仅允许来自 NGINX 服务器的访问。显然，错误消息表明运行 Express 应用程序的上游服务器可能有问题，但我们的日志中没有任何内容表明正在发生这种情况。

最后需要注意的几点：

我最近将worker_connections 从 768 增加到 10000，这似乎使问题发生的频率稍微降低了一些。但是，我们从未达到任何接近连接限制的地方，并且连接正在关闭。 在此增加之后，每次在 NGINX 上执行 reload 时，我们在大约 10 分钟内不会收到任何这些错误。这是我认为 NGINX 是罪魁祸首的主要原因，但我不是专家。 我在谷歌搜索时确实在某处看到了以前的帖子，proxy_set_header Host $host; 语句可能导致了这种情况，这对我来说没有多大意义，但值得思考。我还没有测试过删除它。 带有 express 应用程序的 API 服务器似乎始终运行正常，据我们所知，该服务器的负载并不重 Cloudfront 代理上不会出现此问题

有人对进一步调查的内容有任何明显或想法吗？真的可以在这里使用一些帮助，因为我们很迷茫。

更新： 我按照建议在日志中添加了一些额外的变量，并且能够将错误与访问日志相关联。以下是相关变量：

    "offset": 64270628,
    "response_status": "504",
    "upstream_header_time": "60.001",
    "input_type": "log",
    "source": "/var/log/nginx/access.log",
    "request_method": "GET",
    "http_user_agent": "Mozilla/5.0 (Windows NT 6.1; WOW64; Trident/7.0; rv:11.0) like Gecko",
    "@timestamp": "2017-08-30T15:29:15.981Z",
    "upstream_connect_time": "60.001",
    "request_user": "-",
    "response_time": "60.001",
    "request_bytes_sent": "345",
    "request_id": "90a41e2224cc4b2c1d3c23d544b9146c",
    "timestamp": "30/Aug/2017:15:29:15 +0000"
  

【问题讨论】：

带有 $upstream_connect_time 和 $upstream_header_time 等变量的扩展 access_log 格式会提供一些信息

@Anatoly 我将此添加到我们的日志中，并且能够成功地将错误日志与访问日志匹配。该请求似乎确实已超时。我在上面添加了一些可能相关的变量

在上面的日志中，TCP 连接需要 60 秒，这是关键。返回错误时，您有多少处于 TIME_WAIT 状态的连接？

@Anatoly 在发生此错误时平均大约有 600-800 个处于 timewait 中（有关 ss 输出，请参见下文）。但是，我已经看到该错误发生在流量较少的时期。我确实找到了this guide，其中有一些我可以尝试的 sysctl 更改。 TCP: 889 (estab 223, closed 655, orphaned 3, synrecv 0, timewait 655/0), ports 0

nodejs服务器是否以集群方式部署，机器的CPU数量是多少？我想弄清楚 express 的单个实例是否是这里的瓶颈。我过去也见过类似的案例。

【参考方案1】：

在我的案例中，我遇到了完全相同的问题，并且在私有子网中使用 NGINX 反向代理和与之关联的 NAT 网关。

问题在于为 NGINX 实例分配的可用连接数（在 NAT 网关上设置）不够，并且没有自动缩放。

这不是 NGINX 的问题，也不是 NGINX 背后的后端 API。

对于 GCP，此设置可在 CloudNAT 控制台中修改。 具体请参考this answer。