诡异的502问题

现象

业务中有个场景,接收到 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 报文数据,排查问题就有了铁证,剩下的就是怎么根据标准解读协议了。

©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 213,014评论 6 492
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 90,796评论 3 386
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 158,484评论 0 348
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 56,830评论 1 285
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 65,946评论 6 386
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 50,114评论 1 292
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 39,182评论 3 412
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 37,927评论 0 268
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 44,369评论 1 303
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 36,678评论 2 327
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 38,832评论 1 341
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 34,533评论 4 335
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 40,166评论 3 317
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 30,885评论 0 21
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 32,128评论 1 267
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 46,659评论 2 362
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 43,738评论 2 351

推荐阅读更多精彩内容

  • Spring Cloud为开发人员提供了快速构建分布式系统中一些常见模式的工具(例如配置管理,服务发现,断路器,智...
    卡卡罗2017阅读 134,639评论 18 139
  • 第一章 Nginx简介 Nginx是什么 没有听过Nginx?那么一定听过它的“同行”Apache吧!Ngi...
    JokerW阅读 32,653评论 24 1,002
  • 大多数 Nginx 新手都会频繁遇到这样一个困惑,那就是当同一个location配置块使用了多个 Nginx 模块...
    SkTj阅读 7,633评论 0 12
  • 用户界面的设计很容易出现一团乱。这是因为在整个项目中你可以从某个样式开始,而以另一个样式收尾。不管你是专业导向设计...
    Jessie阅读 3,723评论 1 46
  • GCD 概念 GCD 全称Grand Central Dispatch,是一套C语言API,提供了⼀种新的方法来进...
    痴人会说梦阅读 276评论 0 0