异常现场
- 影响问题
- 因客户端恶意请求，引发后端框架直接关闭连接，导致Nginx对后端检测误判为异常，下线 upstream 影响正常业务请求。
- 访问日志
[31/Mar/2022:10:00:05 +0800] "GET /vod/live HTTP/1.1" 502 552 1206 "https://map.sina.com" "Mozilla/5.0 (Windows NT 6.1; WOW64) Appl
eWebKit/537.36 (KHTML, like Gecko) Chrome/68.0.3440.106 Safari/537.36" upserver_online 502 0.000 0.001 news.baidu.com " "1.2.3.4"日志大致说明：
已对日志敏感信息处理(URI、Host、upstream、客户端IP)。
- 请求时间: [31/Mar/2022:10:00:05 +0800]
- 请求方式: GET
- 请求URI: /vod/live
- 请求协议: HTTP/1.1
- 响应状态码: 502
- 响应大小: 552 字节
- 请求大小: 1206 字节
- Referer: https://map.sina.com
- Uer-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64) Appl
eWebKit/537.36 (KHTML, like Gecko) Chrome/68.0.3440.106 Safari/537.36 - Upstream: upserver_online
- Upstream响应状态码: 502
- upstream_response_time: 0.000
- request_time: 0.001
- Host: news.baidu.com
- 客户端IP: 1.2.3.4
大致可以知道后端异常导致 502 ；
接下来查看 error_log , 等级: error
2022/03/31 10:00:05 [error] 38243#0: *50216349623 no live upstreams while connecting to upstream, client: 1.2.3.4, server: news.baidu/com, request: "GET /vod/live HTTP/1.1", upstream: "http://upserver_online/vod/live", host: "news.baidu.com", referrer: "https://map.sina.com"大致可以知道此时 Nginx 认为检测不到存活的后端；
但 /api/ URI 的 api_server 检测正常，请求正常。
现有配置
upstream api_server {
server 10.23.44.55:12311;
server 10.23.43.55:12311;
}
upstream upserver_online {
server 10.23.51.1:22013;
server 10.23.55.30:12311;
}
server {
listen 80;
listen 443 ssl;
server_name news.baidu.com ;
charset utf-8;
access_log logs/$http_host.access.main.log main;
error_log logs/news.baidu.com.error.crit.log error;
ssl_certificate keys/server.cer;
ssl_certificate_key keys/server.key;
ssl_session_timeout 5m;
ssl_prefer_server_ciphers on;
add_header Strict-Transport-Security "max-age=31536000";
location /api/ {
proxy_redirect off;
proxy_set_header Host $host;
proxy_set_header X-Real-IP $remote_addr;
proxy_set_header X-Real-Port $remote_port;
proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
proxy_pass http://api_server;
}
location / {
proxy_redirect off;
proxy_set_header Host $host;
proxy_set_header X-Real-IP $clientRealIp;
proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
proxy_set_header X-Real-Port $remote_port;
proxy_pass http://upserver_online;
}
}排查过程
首先进行常规网络检查，登陆机器 telnet upstream 对应端口，并 curl upstream ，确认后端一切正常，但为什么 Nginx 会检查失败？
于是尝试将 location / 中的 proxy_pass upserver_online 写死为 10.23.51.20:12311
location / {
...
proxy_pass http://10.23.51.1:22013;
}该 upstream 请求大部分恢复，access_log 但仍有少量 502 ，且集中客户端IP，遂进行抓包查看。
Nginx: 172.17.10.123
Upstream: 10.23.51.1:22013
- 与服务端(upstream)建连成功
- 向服务端发送数据成功，有 ACK 应答
- 在 ACK 应答后，服务端读取请求内容，Cookie 中包含特殊字符
- 服务端框架抛出异常，无数据响应，走断连流程，关闭连接
- 造成 “upstream prematurely closed connection while reading response header from upstream”
对应后端存在异常日志
初步判定为疑似客户端恶意请求，而非正常业务请求。
尝试复现
后端为Nginx并 return 444
...
location /error_broken {
return 444;
}
...无法复现，抓包无法体现建连过程
后端为简单 socket 服务，并对请求直接关闭连接
#!/usr/bin/python3
# -*- coding: UTF-8 -*-
import socket
sock = socket.socket()
sock.bind(("0.0.0.0", 8800)) # 绑定监听的IP地址与端口8800
sock.listen(5) # 设置最大监听数
while True:
conn, addr = sock.accept()
data = conn.recv(1024)
print(data) # 打印查看请求头与请求体
# 必须以HTTP响应头的格式返回数据，否则浏览器无法正常解析
# 同时注意send的数据不能是str字符串，必须是bytes，否则会报错。
# conn.send(b'HTTP/1.1 200 OK\r\n\r\n <h1>7.27 Response!</h1>')
# 不做内容响应，直接断开连接
conn.close()- 得以复现，在建连成功后，没有响应数据，走正常关闭连接流程
原因分析
造成 502 的原因
服务后端框架直接关闭连接，导致 Nginx 认为后端服务不可用，且健康检查默认为 1 次失败，冷却时间 10 秒，同时因为频繁夹杂异常请求，最终导致影响正常请求。
502时，日志为 upstream_server 名称，而非 server IP 的原因
当 upstream 为多个 server 时，所有后端检测不可用时 ( default:
max_fails=1,fail_timeout=10) Nginx 就会认为后端 502，在日志输出就会变成 upstram_server 名称，例如:upserver_online 502；如果 upstream 只有一个 server 时，在后端 502 时，仍为
upstream_server_IP: Port格式，例如:192.168.1.2:1234 502。
解决方式
- 临时方法
异常期间写死 proxy_pass 为 upstream_server_IP 即可
- 长远方案
让后端服务正常处理异常情况，例如响应400，而非直接关闭连接。
遗留问题
为什么当 upstream server 数量为 1 且状态 502 或其他异常情况时，日志记录的是具体 upstream server IP；
但当数量大于 1 时，是 upstream server 名称？
待深入源码分析。
相关文档
http://nginx.org/en/docs/http/ngx_http_upstream_module.html#server
