近期,我遭遇了一件颇为蹊跷的事情。具体而言,一个 HTTP 请求明明已经处理完毕,然而服务端却迟迟不返回响应,最终致使客户端请求超时……尽管最后我通过二分法定位到了问题所在,但其中涉及的原理着实值得深入探究并总结沉淀。
一个有去无回的请求
如下图所示,客户端将请求发送至采用 Gin 框架搭建的 Golang HTTP 服务。在服务端,业务逻辑代码已然执行完毕,可始终没有向请求方返回数据,最终造成请求超时。
我们可以看到,借助在服务端设置断点进行调试,程序已经执行到了业务代码的最后一步。
此时,我首先怀疑是不是存在 defer
函数影响了响应返回。于是我仔细排查代码,并未发现疑似的 defer
函数,这个猜测可以排除。
接着,我猜测会不会是某些公共的钩子函数在作祟。通过单步调试,我发现程序最终进入了 Gin 框架的代码部分,经过进一步分析,这个可能性也被排除。
随后,我怀疑是不是 Gin 框架本身存在 BUG。我继续进行单步调试,结果发现程序走到了 Golang 的内部代码,经过仔细查看,这个猜测同样不成立。
关键在于,不论是业务代码、Gin框架、Golang源代码都没有进入到任何异常逻辑,也没有报错
…历史的经验告诉我们,一般来说是 请求体 出现了问题
按照先少后多的原则,对请求体进行删减
curl -X POST "http://127.0.0.1:80/test/" -H "Content-Length: 504" -H "Content-Type: application/json" -H "Host: 127.0.0.212" -H "User-Agent: Http" -H "X-Forwarded-For: 127.175.66.27" -H "Language: zh-CN" -H "Timestamp: 1732803011" -d {
"stringTest": "demo1",
"StartTime": 1732662000000,
"EndTime": 1732748400000,
"TimeType": "houe",
"numberTest": 0001,
"Action": "helloworld",
"Id": "1234567890"
}
最后发现:
问题出现在 Content-Length 这里,去掉就好了,那这里为什么有问题?
经对比,发现 Context-Length 与请求真实长度不一致,由于这个请求是从另一个请求借鉴而来,所以Header里面复用了之前的Content-Length
而如果Content-Length的长度大于body真实的长度,会发生什么呢?
我们问下AI
简单来说,导致服务端认为还有数据没有上报过来,所以一直在等待接收,从而导致超时
这里在请求的时候先去掉Content-Length,使用一些成熟的请求工具(比如jmeter)会自动计算并进行添加,这样就不会出现这个问题了
深入探究代码逻辑
表面上看,问题似乎并不复杂,但我们不妨深入剖析一番。
其一,为何业务代码会直接执行,而不是等待所有数据接收完毕后再启动执行呢?
其二,这一问题究竟是由 Gin 框架引起的,还是 Golang 自身的问题,亦或是更深层次的系统因素所致呢?
其三,在实际开发中,出于安全等多方面的考量,我们常常需要对收到的请求进行二次封装。若要对当前问题进行修改,在哪个层面进行操作会更为合适呢?
带着这几个问题,我开始仔细研读相关代码。
第一个可能的地方——Gin框架
这里首先看看AI能不能找到?
看来Gin对于这样标准的工作都为委托给了Golang的net/http库
第二个可能的地方——Golang的net/http库
还是先看看AI能不能找到?
AI给出了三个线索文件,去看一下
首先找到了一个疑似点
上图文件在transfer.go文件里面的525行,这里是对length进行了操作,仔细走查发现,其实这里只是为了确认Content-Length值有效性
再然后看下
上图文件在transfer.go文件里面的568行,这里是把读取body的值做一个限制,即用Content-Length进行限制
这里是关键
因为这里基本上确定了要读取的长度,而body比Content-Length小的话,是读不完的
再往下
上图文件在server.go的2009行,上图中是调用业务代码,这里也就解释了为什么业务代码会执行,即问题一
但问题点出现在2015行,看名字就知道这里是要确定request是否要处理完成
上图文件在server.go的1661行,经测试正常的请求会快速跳过1661行代码,但body比Content-Length小的话,会一直停在这里
看上面的两个图就会知道,基本上在网络IO那里等待接收数据,这里代码已经走到底层网络,不是HTTP了,那啥时候读取body的呢,也就是transfer.go文件里面的568行的reader的内容,因为这里的length设置的不对,答案在下图
比较意外的是并不是在writeBody方法里面,而是在writeHeader方法里面,因为这里需要对部分body进行丢弃,就提前读取了body,从而一直没有读取完毕
结论
1. 为何业务代码会先执行,而非等待所有数据接收完毕后再执行?
在 Gin 框架中,程序会先执行 server.go
的第 2009 行,随后再执行第 2015 行。这意味着,框架会先执行业务代码,之后才会判断请求(request)是否接收完毕。不过,在极端场景下,这种处理方式是否会引发问题,目前尚不确定。
2. 问题究竟是由 Gin 框架、Golang 还是更底层因素导致的?
实际上,Gin 框架在这个问题中只是起到了推波助澜的作用。问题的本质在于,读取的请求体(body)大小未达到 Content - Length
所指定的长度,从而导致网络输入输出(IO)操作一直处于等待状态。
3. 出于安全等因素考虑,对请求进行二次封装时,在哪个层面修改更为合适?
若需要对请求进行二次封装,可以在 Gin 框架的业务代码中对请求体(body)以及对应的 Content - Length
进行修改,然后重新发起一次重定向请求即可。
收工
另外,给大家分享一个小知识:并非所有的请求都需要添加 Content-Length
字段。若采用分块传输编码(Chunked transfer encoding),只需添加 Transfer-Encoding
字段即可。
需要特别留意的是,Transfer-Encoding
和 Content-Length
这两个字段是相互排斥的。当它们同时出现在请求头中时,浏览器会以 Transfer-Encoding
为准进行处理。在 Go 语言里,程序会从请求头中移除这两个字段的信息,然后分别设置 TransferEncoding
和 ContentLength
属性。
具体可以参考net/http源码
// srs/net/http/transfer.go
// parseTransferEncoding sets t.Chunked based on the Transfer-Encoding header.
func (t *transferReader) parseTransferEncoding() error {
raw, present := t.Header["Transfer-Encoding"]
if !present {
return nil
}
delete(t.Header, "Transfer-Encoding")
// Issue 12785; ignore Transfer-Encoding on HTTP/1.0 requests.
if !t.protoAtLeast(1, 1) {
return nil
}
// Like nginx, we only support a single Transfer-Encoding header field, and
// only if set to "chunked". This is one of the most security sensitive
// surfaces in HTTP/1.1 due to the risk of request smuggling, so we keep it
// strict and simple.
if len(raw) != 1 {
return &unsupportedTEError{fmt.Sprintf("too many transfer encodings: %q", raw)}
}
if !ascii.EqualFold(textproto.TrimString(raw[0]), "chunked") {
return &unsupportedTEError{fmt.Sprintf("unsupported transfer encoding: %q", raw[0])}
}
// RFC 7230 3.3.2 says "A sender MUST NOT send a Content-Length header field
// in any message that contains a Transfer-Encoding header field."
//
// but also: "If a message is received with both a Transfer-Encoding and a
// Content-Length header field, the Transfer-Encoding overrides the
// Content-Length. Such a message might indicate an attempt to perform
// request smuggling (Section 9.5) or response splitting (Section 9.4) and
// ought to be handled as an error. A sender MUST remove the received
// Content-Length field prior to forwarding such a message downstream."
//
// Reportedly, these appear in the wild.
delete(t.Header, "Content-Length")
t.Chunked = true
return nil
}
...
// Unify output
switch rr := msg.(type) {
case *Request:
rr.Body = t.Body
rr.ContentLength = t.ContentLength
if t.Chunked {
rr.TransferEncoding = []string{"chunked"}
}
rr.Close = t.Close
rr.Trailer = t.Trailer
case *Response:
rr.Body = t.Body
rr.ContentLength = t.ContentLength
if t.Chunked {
rr.TransferEncoding = []string{"chunked"}
}
rr.Close = t.Close
rr.Trailer = t.Trail