消失的502请求日志：uvicorn默认配置引发的小概率必现事件

2025-01-04 本文已影响0人 FesonX

起因

客户反馈接口在每天有几次 502 请求，经查发现比例是 0.01%，数十万请求中有几十个，每天都会出现。

排查

所在接口可以简化为客户端-负载均衡-服务器架构

要确定 502 是谁发的，按顺序分析：服务器[业务代码 > 框架代码] > 负载均衡 > 云服务，
这里使用 K8s 部署，后端服务器为 uvicorn + FastAPI。

日志，谁发的 502 请求——实操

请求日志中心——分析请求分布和特征

云服务厂商一般会提供负载均衡请求日志解析，可以在这里看到异常请求的分布和特征信息。

在这次调查中，502 请求特征如下：

请求体较小，都不是文件上传
请求响应体均为 0
请求时长有长有短

至少可以排除请求过大导致的 502 问题。

如果业务侧单独上报自己的请求日志，可以交叉查看异常日志。
也是在这里，发现只有 Nginx 层有 502 日志，业务侧的请求日志并没有。

这是否证明请求没有发到业务侧的服务器呢？不一定。

K8s 容器日志——请求前后发生了什么

容器日志是原始日志，可以针对性查看负载均衡或者容器的输出。

错误日志

# 负载均衡 warning 日志
kubectl -n kube-system logs nginx-ingress-controller-xxx | grep -E ^[WE]
# 负载均衡错误日志
kubectl -n kube-system logs nginx-ingress-controller-xxx | grep error

退出日志

当容器异常重启，可以看前一次退出的日志。

kubectl  -n your-ns logs server-xxx --previous

但容器没有重启=服务没重启吗？看了启动参数发现不熟悉负载均衡 + 多容器的模式的同事，将 unicorn 这类服务管理框架的 worker 数设置 >1，也就是说容器内存在多个 worker，有 worker 重启容器也无法感知。

将 worker 数统一设置为1，没有看到重启，现在可以排除了。

请求上下文

kubectl -n kube-system logs nginx-ingress-xxx | grep -C 10  "/path/to/api/" | grep -C 5 " 502"

到这里，可以看到出错的关键信息是上游关闭了连接，导致 502 发出。Nginx 显示上游状态 502，但真的是上游发的的吗？

nginx-ingress-xxx  | 2025/01/02 03:12:54 [error] 30#30: *1 upstream prematurely closed connection while reading upstream, client: 172.19.0.1, server: , request: "POST /path/to/api/ HTTP/1.0", upstream: "http://api:8000/path/to/api/", host: "localhost"

请求跟踪——请求走到哪一步

在 Nginx 日志的请求 ID 可以配置在请求头中，往上游传递，请求正常执行则可以在请求头中获取到，遗憾的是我的同事也没看到 502 请求关联的请求 ID 在上游出现。

proxy_set_header_X-Request-Id: $req_id
```a


## 谁能发 502 请求——理论
现在已经走到死胡同了吗？前面提到的关键日志还没用。
一般可能认为 Nginx 只是个反向代理或者负载均衡，不会去修改 HTTP 状态码，然而在 NGINX 的源码中却明确写着：**当上游关闭连接时，会发送 502 请求。**
```C
# ... ngx_http_upstream.c
if (upstream->read->eof) {
    ngx_log_error(NGX_LOG_ERR, upstream->log, 0,
                    "upstream prematurely closed connection");

    ngx_http_upstream_finalize_request(r, u,
                                        NGX_HTTP_BAD_GATEWAY);
    return;
}
# ...

查阅 MDN 文档，可以知道，在遵循设计规范的情况下，502 响应码只能由代理或网关发出，表示收到上游服务的无效响应。

The HTTP 502 Bad Gateway server error response status code indicates that a server was acting as a gateway or proxy and that it received an invalid response from the upstream server.

根据前面的排查顺序，列出所有层能发的异常请求：

业务代码

500：一般是业务代码异常未捕获错误
502: 代码未检出，无法发出
503: 资源不足，无法接收并发请求

框架代码

同上

上层基础设施

500: Nginx 自身错误，例如连接数过少
502: 原因复杂，包括请求体过大、上游关闭连接、无法连接上游等
499: 客户端主动关闭连接，这也是为什么有时候负载均衡的请求数不等于上游请求数。

答案近在眼前

至此，已经确定 502 请求就是 NGINX 发出的，不是代码问题，范围介于负载均衡和框架之间。

检索前面的日志，虽然搜索引擎指向的大部分是 PHP 框架的 KeepAlive 问题，但 Python 会不会也有同样的问题呢？

业务侧使用的是 uvicorn 这个相对新的框架，最终我在 Gunicorn 这个更成熟的框架文档中找到了蛛丝马迹：
当你将 Gunicorn 部署在负载均衡后面，设置一个更高的 KeepAlive 值是有必要的。

Command line: --keep-alive INT
Default: 2

The number of seconds to wait for requests on a Keep-Alive connection.
Generally set in the 1-5 seconds range for servers with direct connection to the client (e.g. when you don’t have separate load balancer).

When Gunicorn is deployed behind a load balancer, it often makes sense to set this to a higher value.

回过头再来看这张架构图。

当没有负载均衡时，虽然有 KeepAlive，但连接不复用（因为连接四元组几乎一直变）响应结束时，uvicorn 设置定时器，到钟连接关闭。
当有负载均衡，上游服务将和负载均衡建立长连接，客户端（一般）继续与负载均衡建立短链接。

负载均衡有自己的 KeepAlive 参数，在所使用的云服务默认为 900s，而 uvicorn、Gunicorn 的默认时长均在 5s 以下，这会有什么问题？

当上游 KeepAlive 较短，请求结束时连接被负载均衡重新复用，就有可能出现请求发给上游即因框架自己的定时任务所关闭，进而请求中断，NGINX 返回 502。

在阿里云的文档中则明确给出建议：

Ingress Controller默认使用HTTP1.1请求访问后端服务，且默认开启长连接，请确认配置的后端长连接的连接空闲超时时间大于Ingress Controller的连接空闲超时时间（默认900s）。

将服务启动参数 KeepAlive 调高后，502 请求确实不再。

总结

复盘这次调查，一是对状态码的理解不够透彻，二是对基础架构的原理不够清楚，还有一个是缺乏对日志的敏感度。

当拿到关键日志时已经可以借助搜索引擎找到答案，却在 LLM 时代的当下第一时间询问 GPT 得到错误的二手资料(它给我指向的是 NGINX proxy_timeout 之类的配置)。

工作上虽然有很多问题待解决，但真正从未被其他人解决的问题几乎为0，LLM 时代更要小心求证复杂答案的真实性。

后续

你可能还会问，连接使用的过程中，uvicorn 无法感知到连接是否中断吗？

在 uvicorn 的源码中事件是先设置再传给触发器，而不是连接本身的状态直接被触发器感知。

实际测试发现，手动关闭连接 uvicorn 无法感知，设置事件则立刻会看到报错。

不过，只有在响应发出阶段，中断连接才会触发 NGINX 502，这也进一步使得出现的概率降低。感兴趣可以复制代码测试。

app/
   Dockerfile
   main.py
nginx/
   nginx.conf
docker-compose.yml

nginx.conf

worker_processes auto;
events {
    # Decrease connections, you will get 500
    worker_connections 100;
}

http {
    error_log /var/log/nginx/error.log debug;
    upstream backend {
        server app:8000;
    }

    server {
        listen 80;

        location / {
            proxy_pass http://backend;
            proxy_http_version 1.1;
            proxy_set_header Connection "";
            proxy_set_header Host $host;

            # Increase Keep-Alive timeout for upstream
            keepalive_timeout 10s;  
    }
}
}

main.py

import http
import random
import socket
from fastapi import FastAPI, Response
import time
import asyncio
import h11
from uvicorn.protocols.http.h11_impl import H11Protocol, RequestResponseCycle
from uvicorn._types import (
    ASGISendEvent,
    HTTPResponseBodyEvent,
    HTTPResponseStartEvent,
    HTTPRequestEvent,
    ASGIReceiveEvent,
)
from typing import cast
from uvicorn.protocols.http.flow_control import (
    CLOSE_HEADER,
)

from uvicorn.protocols.utils import (
    get_client_addr,
    get_path_with_query_string,
)

def _get_status_phrase(status_code: int) -> bytes:
    try:
        return http.HTTPStatus(status_code).phrase.encode()
    except ValueError:
        return b""

STATUS_PHRASES = {
    status_code: _get_status_phrase(status_code) for status_code in range(100, 600)
}

async def receive(self) -> "ASGIReceiveEvent":
    # --------
    # Reproduce Code begin
    # --------
    ## Not working
    # self.logger.warning("Close connection, Simulating a 502 error")
    # self.transport.close()
    # --------
    # Reproduce Code end
    # --------

    if self.waiting_for_100_continue and not self.transport.is_closing():
        headers: list[tuple[str, str]] = []
        event = h11.InformationalResponse(
            status_code=100, headers=headers, reason="Continue"
        )
        output = self.conn.send(event=event)
        self.transport.write(output)
        self.waiting_for_100_continue = False

    if not self.disconnected and not self.response_complete:
        self.flow.resume_reading()
        await self.message_event.wait()
        self.message_event.clear()

    if self.disconnected or self.response_complete:
        return {"type": "http.disconnect"}

    message: "HTTPRequestEvent" = {
        "type": "http.request",
        "body": self.body,
        "more_body": self.more_body,
    }
    self.body = b""
    return message

async def send(self, message: "ASGISendEvent") -> None:

    message_type = message["type"]

    if self.flow.write_paused and not self.disconnected:
        await self.flow.drain()

    if self.disconnected:
        return

    if not self.response_started:
        # 触发点
        # --------
        # Reproduce Code begin
        # --------
        # self.logger.warning("Close connection, Simulating a 502 error")
        # self.transport.close()
        # --------
        # Reproduce Code end
        # --------

        # Sending response status line and headers
        if message_type != "http.response.start":
            msg = "Expected ASGI message 'http.response.start', but got '%s'."
            raise RuntimeError(msg % message_type)
        message = cast("HTTPResponseStartEvent", message)

        self.response_started = True
        self.waiting_for_100_continue = False

        status = message["status"]
        headers = self.default_headers + list(message.get("headers", []))

        if CLOSE_HEADER in self.scope["headers"] and CLOSE_HEADER not in headers:
            headers = headers + [CLOSE_HEADER]

        if self.access_log:
            self.access_logger.info(
                '%s - "%s %s HTTP/%s" %d',
                get_client_addr(self.scope),
                self.scope["method"],
                get_path_with_query_string(self.scope),
                self.scope["http_version"],
                status,
            )

        # Write response status line and headers
        reason = STATUS_PHRASES[status]
        response = h11.Response(status_code=status, headers=headers, reason=reason)
        output = self.conn.send(event=response)
        self.transport.write(output)

    elif not self.response_complete:
        # 触发点2
        # --------
        # Reproduce Code begin
        # --------
        # self.logger.warning("Close connection, Simulating a 502 error")
        # self.transport.close()
        # --------
        # Reproduce Code end
        # --------

        # Sending response body
        if message_type != "http.response.body":
            msg = "Expected ASGI message 'http.response.body', but got '%s'."
            raise RuntimeError(msg % message_type)
        message = cast("HTTPResponseBodyEvent", message)

        body = message.get("body", b"")
        more_body = message.get("more_body", False)

        # Write response body
        data = b"" if self.scope["method"] == "HEAD" else body
        output = self.conn.send(event=h11.Data(data=data))
        self.transport.write(output)

        # Handle response completion
        if not more_body:
            self.response_complete = True
            self.message_event.set()
            output = self.conn.send(event=h11.EndOfMessage())
            self.transport.write(output)

    else:
        # Response already sent
        msg = "Unexpected ASGI message '%s' sent, after response already completed."
        raise RuntimeError(msg % message_type)

    if self.response_complete:
        # 不会触发
        # --------
        # Connection close here is not working
        # --------
        # self.logger.warning("Close connection, Simulating a 502 error")
        # self.transport.close()

        if self.conn.our_state is h11.MUST_CLOSE or not self.keep_alive:
            self.conn.send(event=h11.ConnectionClosed())
            self.transport.close()
        self.on_response()

# overwrite send, simulte 502 error
# 未生效，未触发
RequestResponseCycle.receive = receive
# 可以触发
RequestResponseCycle.send = send

app = FastAPI()

@app.get("/")
async def read_root():
    await asyncio.sleep(random.randint(0,1))
    return {"message": "Hello, World!"}

@app.get("/sleep")
async def slow_response():
    await asyncio.sleep(5)  # Simulate a delay
    return {"message": "Slow Response"}

@app.get("/sync-sleep")
async def unstable_endpoint(response: Response):
    # Usually 504
    time.sleep(5)
    return {"message": "ok"}

docker-compose.yml: 启动 docker-compose up --build

version: "3.9"
services:
  app:
    build:
      context: .
      dockerfile: ./app/Dockerfile
    ports:
      - "8000:8000"
  nginx:
    image: nginx:latest
    volumes:
      - ./nginx/nginx.conf:/etc/nginx/nginx.conf:ro
    ports:
      - "80:80"
    depends_on:
      - app
```![spacexcode-coverview-057@2x.png](https://img.haomeiwen.com/i5530017/7fbc4dd35dfbcf54.png?imageMogr2/auto-orient/strip%7CimageView2/2/w/1240)