现象
业务中有个场景，接收到 HTTP 请求之后，根据条件可能修改某些参数，转发请求，拿到结果之后稍作修改写到 ServletResponse 中。
起初发现有的请求会返回 HTTP code 502，但是多次复现之后发现经过转发的请求都会导致502，构造参数直接访问相应的机器却能够正确返回。
背景
我们的应用容器是 tomcat，但是出问题的请求进入的原始机器和转发后访问的机器稍有不同，问题机器在 tomcat 前，同服务器还有个 nginx ，所以有同事认为是这个多出来的 nginx 做了什么导致出错。但是直觉上感觉不太可能，因为 nginx 作为一个标准组件，不会无故做这样的拦截，一定是应用代码有什么问题。
过程
这里定义如下：
server A，本机有 nginx ；
server B，本机无 nginx。
通过 cURL 访问，能进一步将问题范围缩小。
curl 'http://0.0.0.0:80/path?param=a' -H 'Host: www.xxx.com'
直接访问 server A，构造参数让请求不进行转发，此时能拿到正确的返回结果，HTTP code 200.
直接访问 server B，也不进行转发，此时也能拿到正确的结果。
问题在于转发的时候，server A 转发到 server B，之后再返回给用户，就一定会 502.
进一步加业务日志之后可以发现，转发到 server B 的请求，在 server B 上的返回是正确的，HTTP code 200, body 也是正确的。
Empty reply
再构造一个会进行转发的请求，观察 cURL 的输出，发现如下：
* Empty reply from server
* Connection #0 to host www.xxx.com left intact
curl: (52) Empty reply from server
同时看到 nginx 的 access log 如下：
"GET /index.jsp HTTP/1.1" 200 0 "-" "curl/7.54.0" "-"
看 nginx 的 log-format，200 是 http status code，后面的 0 是 body_bytes_sent, 也就是说 cURL 接收到的 body size 为 0.
于是开始怀疑，拿到请求转发的 response 之后，往回写的时候出了什么问题导致 body 没有写。
但是实际看了代码之后，确认已经往response.getOutputStream() 中写入了 body，外层的 try-catch 也没有捕捉到异常，没看到日志。
难不成 outputStream 里的数据还会被 tomcat 丢弃？
invalid chunked response
翻了下 nginx 的 error log，发现这个记录：
[error] 18604#0: *9 upstream sent invalid chunked response while reading upstream, client: 127.0.0.1, server: localhost, request: "GET /index.jsp HTTP/1.1", upstream: "http://127.0.0.1:8080/index.jsp", host: "localhost"
日志中的 IP / host 信息都是本地模拟出来的，但是错误信息是一致的。
于是就很有意思了，意思是 upstream 给 nginx 返回了一个 invalid chunked response，也就是说 tomcat 回写给 nginx 的数据分块是无效的。
tcpdump chunked data
只能靠 cURL 发请求来判断两端的请求、响应数据，不够判定出问题的环节，即使加上日志也还不够。最好能够拿到 tomcat 返回给 nginx 的数据。想到了用 tcpdump，直接抓取问题机器的 tcp 数据，然后本地用 wireshark 分析。
命令如下：
tcpdump -vvv -i any 'port 8080 or port 80' -w request_to_80
意思是监听所有网卡（any）的数据，并且指定 来源或者目标端口是 80 或者 8080 ，保存到文件
这里有两个注意点：
- 需要注意权限问题，可能需要 sudo 权限或者直接用 root 用户
- 指定 any 网卡，
- 一般 80 端口没有问题，请求从 80 端口进入，响应从 80 端口发出
- 但是 nginx 和本机 tomcat 的数据通信是不经过外部网络的，走的是虚拟网卡 loopback
端口的问题可以在本机实验，比如观察到开发用的机器上需要监听这两个网口：
en0
lo0
dump 下来，wireshark 通过 "Follow TCP Stream" 就能看到 HTTP 请求的响应数据
发现 tomcat 返回给 nginx 的数据类似如下：
GET /info?custom=12121 HTTP/1.0
Host: www.xxx.com
Connection: close
User-Agent: curl/7.54.0
Accept: */*
Cookie: xxx=yyy;
HTTP/1.1 200 OK
Set-Cookie: xxx=yyy
Transfer-Encoding: chunked
Connection: close
Vary: Accept-Encoding
Content-Language: zh-CN
Expires: Thu, 01 Jan 1970 00:00:00 GMT
Content-Type: application/json;charset=UTF-8
Date: Wed, 23 May 2018 06:55:42 GMT
Connection: close
{"code":200,"data":{...}}
乍一看没什么问题，再看正常返回 200 的请求：
ET /info?custom=12121 HTTP/1.1
Host: wwx.xxx.com
User-Agent: curl/7.54.0
Accept: */*
Cookie: xxx=yyy;
HTTP/1.1 200 OK
Set-Cookie: xxx=yyy
Transfer-Encoding: chunked
Connection: keep-alive
Keep-Alive: timeout=5
Vary: Accept-Encoding
Content-Language: zh-CN
Expires: Thu, 01 Jan 1970 00:00:00 GMT
Content-Type: application/json;charset=UTF-8
Transfer-Encoding: chunked
Date: Wed, 23 May 2018 06:55:07 GMT
526
{"code":200,"data":{...}}
0
再次看了异常请求的 header 和 body 之后，发现异常请求的 body 开头没有数字。
查看这个 header 的作用及传输分块的示例之后，发现确实有问题：header 中指定了 chunked，但是 body 并没有分块？结合正常的请求来看，按照正确的格式将数据分块之后是能被 nginx 接受并处理的。
那么接下来的疑问就是？为什么拿回来的数据，本来应该是分块的，但是被解开了？
为什么正常的响应一定是分块的？因为如果不分块，header 中不会被中间某个组件加 Transfer-Encoding: chunked这个头。
接下来就是分析：请求返回过程中，谁对 response body 中的内容做了解分块操作。
HttpClient chunk
转发的过程是使用 HttpClient 发起了一个新的 http 请求，拿到结果之后将 response copy 到 servletResponse 中，查看 copy response 的那部分代码，没有发现问题。
于是怀疑起了 tomcat 和 HttpClient，先看 HttpClient。
思路就是看 HttpClient 请求回来之后到输出之前有没有 dechunk
写了个简单的测试用例，拿到结果之后输出：
String str = EntityUtils.toString(response.getEntity());
果然是明文，没有分块。
看源码，来自：httpclient 4.3.2：
实际处理流程，正向
org.apache.http.protocol.HttpRequestExecutor#doSendRequest
—> org.apache.http.impl.AbstractHttpClientConnection#receiveResponseEntity
—> org.apache.http.impl.entity.EntityDeserializer#deserialize
—> org.apache.http.impl.entity.EntityDeserializer#doDeserialize
// 准备 inputStream 的时候会判断是否分块
org.apache.http.impl.entity.LaxContentLengthStrategy#determineLength
// 可以看到：header 中出现 Transfer-Encoding: chunked 的时候就会处理分块
org.apache.http.impl.io.ChunkedInputStream#read(byte[], int, int) // 具体的，ChunkedInputStream 会处理 CRLF 分隔符和chunk大小，重载了 read 方法，也就是实际读取 stream 的时候就会读到一个 de-chunked 过的 buffer 数据
解决方案
最后是将 Transfer-Encoding: chunked这个头从 response 中去掉，又后续流程中的 nginx 决定是否去做分块。在业务代码里也就是不做分块，也不提供错误信息，之前的 response 被 nginx 认为无效也是因为 header 暗示说分块，但是实际的 body 没有分块导致的。
总结
这个问题隐藏确实比较深，前前后后排查了很长时间，从发现问题，到怀疑应用部署结构，到怀疑 nginx ，走了不少弯路。但是收获也是巨大的，对 tcpdump 的应用，以及 HTTP 标准中的某些细节，HttpClient 对标准的实现，都有了一定的了解。尤其 tcpdump，有了这个工具，拦截到原始的 tcp 报文数据，排查问题就有了铁证，剩下的就是怎么根据标准解读协议了。
网友评论