NoHttpResponseException: xxx failed to respond 问题分析

问题

HttpClient偶尔报NoHttpResponseException: xxx failed to respond

feign.RetryableException: xxx:80 failed to respond executing POST http://xx

复现方法

google得知,这个只会在服务器端keep-alive刚好过期的时间我们进行访问才能大概率复现,方法如下:

wireshark进行抓包得出底层服务器的keep-alive时间

写一段程序,用于探测底层服务器的keep-alive:


image.png

开启wireshark进行抓包,执行程序直到下图出现即可停止

image.png

重点看左下角的红色框,时间相差65秒左右,没错从而可以得知底层服务器的keep-alive 是 65秒,也就是当一个连接socket 65秒内没有数据交互,底层服务器就会认为这个连接可以关闭了,因此才会在3分36秒进行挥手操作发送一个FIN包,这时我们稍微改造一下这个程序,如下:


image.png

相比第一个,有两个改动

加了一个循环
每次调用的间隔改成和底层服务器相同的65秒
我们清空wireshark,运行该程序抓包,结果如下:


image.png

问题分析

image.png

红色框1:前3个请求是建立连接的过程,三次握手,接着4个请求就是client和server的数据交互,着重看最后四个请求
9012 -> 59233 [FIN, ACK]:服务器主动进行关闭,给client发送了FIN包
59233 -> 9012 [ACK]:client进行回应ACK包
69233 -> 9012 [FIN, ACK]:按照四次挥手原则,client发现目前数据已经发送完毕了,因此也发出FIN包
9012 -> 59233 [RST]:服务器直接返回一个RST
红色框2:同2
红色框3:前面的7个步骤都是相同的,建立连接,数据交互,区别唯独在于绿色框
9012 -> 59233 POST /hy/json: client认为服务器端可用,因此给服务器发送数据
9012 -> 59233 [FIN, ACK]:服务器认为此连接已经失效,因为超过了65的keep-alive时间,主动进行关闭,给client发送了FIN包
59233 -> 9012 [ACK]:client进行回应ACK包
69233 -> 9012 [FIN, ACK]:按照四次挥手原则,client发现目前数据已经发送完毕了,因此也发出FIN包
9012 -> 59233 [RST]:服务器直接返回一个RST 通过Seq=188,可判断这条是给【9012 -> 59233 POST /hy/json】这个请求回的
9012 -> 59233 [RST]:服务器直接返回一个RST 通过Seq=189,可判断这条是给【69233 -> 9012 [FIN, ACK]】回的
9012 -> 59233 [RST]:服务器直接返回一个RST 通过Seq=189,同6
通过分析抓包数据,得出结果是,当client客户端认为这条Socket连接有用,这时服务器端却认为该Socket连接无用,并主动关闭,就会报错,属于临界值没有处理好的

这时有人就说了,为什么前两次就没有问题呢,原因是HttpClient会进行连接过期是否可用的检查,那么也就能理解这是httpclient的一个bug,即使httpclient有做这么一件事情,但是由于网络I/O原因,导致httpclient认为一个关闭了的连接是有效的,才报了这个错误。

HttpClient为什么会复用一个已经被关闭的连接

开启debug日志


image.png

通过仔细分析HttpClient打印的debug日志,可发现左边正常交互日志 打印了一串 "end of stream" 后进行了连接的重新建立, connection established ,而右边错误日志打印了一串 "[read] I/O error: Read timed out" 后没有进行连接的重新建立,因此就报错了

那么可以通过打印 "[read] I/O error: Read timed out"日志的上下文日志缩小 排查代码的范围,上文日志 Connection request,下文日志 Connection leased,进行代码定位

image.png
image.png

基本上定位到了PooingHttpClientConnectionManager.java这个类,那么进行代码跟踪吧

image.png

追踪到了 AbstractConnPool.java类,那么这段代码什么意思呢,这个就是进行连接是否能够复用的检查代码

对validateAfterInactivity进行判断,这个是服务器keep-alive的值

leasedEntry.getUpdated() + validateAfterInactivity <= System.currentTimeMillis():如果连接的最后一次使用时间 + 服务器keep-alive的时间 小于等于当前时间,那么就认为该连接可能已经失效了
!validate(leasedEntry): 因此会进行连接是否失效的检查
跟进去看看

image.png

最终找到"end of stream" and "[read] I/O error: Read timed out" 打印的地方
然后回到如下图代码:

image.png

可以看到

当bytesRead 值为 -1 时,返回true,那么HttpClient就会认为该连接失效了,不能够复用,并进行清理操作,
当抛出异常是ShockTimeoutException时会返回false, 那么HttpClient就会认为该连接可复用

解决方案

禁用HttpClient的连接复用(有点扯淡)
重试方案:http请求使用重发机制,捕获NohttpResponseException的异常,重新发送请求,重发3次后还是失败才停止
根据keep Alive时间,调整validateAfterInactivity小于keepAlive Time,但这种方法依旧不能避免同时关闭
系统主动检查每个连接的空闲时间,并提前自动关闭连接,避免服务端主动断开
推荐使用重试方案

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

推荐阅读更多精彩内容