记录由客户端http请求原因引起的5xx响应问题排查过程

看到 http 状态码 5xx，很多开发者第一感觉就是服务端的问题，其实并不全是。下面我遇到的问题就是一个例外。

问题描述

最近在为反向代理 nginx 配置 auth_request 后，出现了请求504错误。

504状态码是HTTP协议中的一种服务器错误状态码。当客户端向服务器发送请求并在一段时间内未收到服务器的有效响应时，就会返回504状态码。它表示服务器作为网关或代理，正在等待上游服务器返回响应，但在超时时间内未收到响应。

问题排查

1 排查nginx日志

查看 nginx 的错误日志，确实记录了504的错误记录，一起的还有另外一条 subrequest 的110 connection time out。

[error] 10641#10641: *2282366 upstream timed out (110: Connection timed out) while reading response header from upstream, request: "POST /test/?route=/ HTTP/1.1", subrequest: "/auth", upstream: "http://xxxxxxxxx/auth"
[error] 10641#10641: *2282366 auth request unexpected status: 504 while sending to client,request: "POST /test/?route=/ HTTP/1.1"

直觉看来就是subrequest请求的服务，没有正常工作造成请求没有响应。

然而当直接使用 curl 请求subrequest 请求的地址时，服务却是正常相应的。

2 排查subrequest请求的服务的日志

排查subrequest请求的服务的日志时候，发现了408的状态码。

"GET /nginx/?route=/ 408

408状态码是HTTP协议中的一个客户端错误状态码。它表示请求超时，即客户端发送的请求在服务器预设的等待时间内没有得到响应。服务器可以在响应中包含一个Retry-After头字段，指示客户端在多长时间之后可以重试请求。

这里可以肯定的是，subrequest,请求有问题。但是错误信息就这么多，仅通过日志无法排查出问题的原因。

3 既然日志无法定位问题，就tcpdump + wireshark来看看这个subrequest

日志中无法看出具体问题，就通过网络抓包工具，看看这次subrequest到底请求了什么？

tcpdump 抓取网络包

tcpdump -i interfacename port xxx -w capture.pcap

将上面的包使用wireshark导入，定位到有问题的stream，然后follow stream.
分析这次网络请求的过程如下：

11~13帧是tcp的三次握手
14号帧是客户端发送了请求
15号帧服务端响应了内容长度为0的确认信息
然后等待了10秒
16~18号帧就是tcp的四次挥手过程

在这里插入图片描述
问题出在哪里？为什么中间等待了10秒？

10秒是客户端请求的超时配置，超过10秒后，客户端自己断开，从上面的挥手过程，和 408的状态码可以看出来。

在查看请求的具体信息时，见下图，发现了请求头Content-length: 153,这个有点意外，因为这个通常是在响应头中的数据。
在这里插入图片描述
既然怀疑这里，就将这个请求生成curl命令，直接在命令行中请求，确实会卡住，直到请求超时。

curl -XGET -vvv -H 'Content-length:153' 'http://127.0.0.1:8028/auth/'
Note: Unnecessary use of -X or --request, GET is already inferred.
* Expire in 0 ms for 6 (transfer 0x55e12cc5b110)
*   Trying 127.0.0.1...
* TCP_NODELAY set
* Expire in 200 ms for 4 (transfer 0x55e12cc5b110)
* Connected to 127.0.0.1 (127.0.0.1) port 8028 (#0)
> GET /auth/ HTTP/1.1
> Host: 127.0.0.1:8028
> Accept: */*
> Content-length:153
>
* Empty reply from server
* Connection #0 to host 127.0.0.1 left intact

移除上面的Content-length后，重新请求，直接就返回了结果。
看来问题就是请求头中的：Content-length引起的。