解Bug之路:一次调用外网服务概率性失败问题的排查

和外部联调一直是令人困扰的问题,尤其是一些基础环境配置导致的问题。笔者在一次偶然情况下解决了一个调用外网服务概率性失败的问题。在此将排查过程发出来,希望读者遇到此问题的时候,能够知道如何入手。

起因

笔者的新系统上线,需要PE执行操作。但是负责操作的PE确和另一个开发在互相纠缠,让笔者等了半个小时之久。本着加速系统上线的想法,就想着能不能帮他们快速处理掉问题,好让笔者早点发完回去coding。

一打听,这个问题竟然扯了3个月之久,问题现象如下:

file

每个client都会以将近1/2的概率失败,而且报错都为:

file

着手排查

和appserver开发以及对应的PE交流发现,appserver和nginx之间是短连接,由于是socketTimeOutException,于是能够排除appserver和nginx建立连接之间的问题。去nginx上排查日志,发现一个奇异的现象,如下图所示:

file

所有的appserver都是调用一台nginx一直成功,而调用另一台nginx大概率失败。而两台nginx机器的配置一模一样,还有一个奇怪的点是,只有在调用出问题的对端服务器时才会失败,其它业务没有任何影响,如下图所示:

file

由于这两个诡异的现象导致开发和PE争执不下,按照第一个现象一台nginx好一台nginx报错那么第二台nginx有问题是合理的推断,所以开发要求换nginx。

按照第二个现象,只有调用这个业务才会出错,其它业务没有问题,那么肯定是对端业务服务器的问题,PE觉得应该不是nginx的锅。

争执了半天后,初步拟定方案就是扩容nginx看看效果。笔者觉得这个方案并不靠谱,盲目的扩容可能会引起反效果。还是先抓包看看情况吧。

抓包

其实笔者觉得nginx作为这么通用的组件不应该出现问题,问题应该出现在对端服务器上。而根据对端开发反应,他自己curl没问题,并现场在他自己的服务器上做了N次curl也没有任何问题(由于这个问题僵持不下,他被派到我们公司来协助排查)。

于是找网工在防火墙外抓包,抓包结果如下:

时间点 源ip 目的ip 协议 info
2019-07-25 16:45:41 20.1.1.1 30.1.1.1 tcp 58850->443[SYN]
2019-07-25 16:45:42 20.1.1.1 30.1.1.1 tcp [TCP Retransmission]58850->443[SYN]
2019-07-25 16:45:44 20.1.1.1 30.1.1.1 tcp [TCP Retransmission]58850->443[SYN]

由于appserver端设置的ReadTimeOut超时时间是3s,所以在2次syn重传后,对端就已经报错。

如下图所示:

file

(注:nginx所在linux服务器设置的tcp_syn_retries是2)

抓包结果分析

从抓包得出的数据来看,第二台nginx发送syn包给对端服务,对端服务没有任何响应,导致了nginx2创建连接超时,进而导致了appserver端的ReadTimeOut超时(appserver对nginx是短连接)。

按照正常推论,应该是防火墙外到对端服务的SYN丢失了。而阿里云作为一个非常稳定的服务商,应该不可能出现如此大概率的丢失现象。而从对端服务器用的是非常成熟的SpringBoot来看,也不应该出现这种bug。那么最有可能的就是对端服务器本身的设置有问题。

登陆对端服务器进行排查

由于对方的开发来到了现场,于是笔者就直接用他的电脑登录了服务所在的阿里云服务器。首先看了下dmesg,如下图所示,有一堆报错:

file

感觉有点关联,但是仅靠这个信息无法定位问题。紧接着,笔者运行了下netstat -s:

file

这条命令给出了非常关键的信息,翻译过来就是有16990个被动连接由于时间戳(time stamp)而拒绝!查了下资料发现这是由于设置了

file

在NAT情况下将会导致这个被动拒绝连接的问题。而为解决上面的dmesg日志,网上给出的解决方案就是设置tcp_tw_recycle=1而tcp_timestamps默认就是1,同时我们的客户端调用也是从NAT出去的,符合了这个问题的所有特征。于是笔者尝试着将他们的tcp_timestamps设为0。

file

又做了几十次调用,再也没有任何报错了!

linux源码分析

问题虽然解决了,但是笔者想从源码层面看一看这个问题到底是怎么回事,于是就开始研究对应的源码(基于linux-2.6.32源码)。由于问题是发生在nginx与对端服务器第一次握手(即发送第一个syn)的时候,于是我们主要跟踪下这一处的相关源码:

file

关于tcp_timestamps的代码就在tcp_v4_conn_request里面,我们继续追踪(以下代码忽略了其它不必要的逻辑):

int tcp_v4_conn_request(struct sock *sk, struct sk_buff *skb)
{
    ......
    /* VJ's idea. We save last timestamp seen
     * from the destination in peer table, when entering
     * state TIME-WAIT, and check against it before
     * accepting new connection request.
     * 注释大意为:
     * 我们在进入TIME_WAIT状态的时候将最后的时间戳记录到peer tables中,
     * 然后在新的连接请求进来的时候检查这个时间戳
     */
     // 在tcp_timestamps和tcp_tw_recycle开启的情况下
    if (tmp_opt.saw_tstamp &&
        tcp_death_row.sysctl_tw_recycle &&
        (dst = inet_csk_route_req(sk, req)) != NULL &&
        (peer = rt_get_peer((struct rtable *)dst)) != NULL &&
        peer->v4daddr == saddr) {
        /** TCP_PAWS_MSL== 60 */
        /** TCP_PAWS_WINDOW ==1 */
        // 以下都是针对同一个对端ip
        // tcp_ts_stamp 对端ip的连接进入time_wait状态后记录的本机时间戳   
        // 当前时间在上一次进入time_wait记录的实际戳后的一分钟之内
        if (get_seconds() < peer->tcp_ts_stamp + TCP_PAWS_MSL &&
        // tcp_ts 最近接收的那个数据包的时间戳(对端带过来的)
        // 对端当前请求带过来的时间戳小于上次记录的进入time_wait状态后记录的对端时间戳
            (s32)(peer->tcp_ts - req->ts_recent) >
                        TCP_PAWS_WINDOW) {
            // 增加被动连接拒绝的统计信息
            NET_INC_STATS_BH(sock_net(sk), LINUX_MIB_PAWSPASSIVEREJECTED);
            // 进入丢弃和释放阶段
            goto drop_and_release;
        }
    }   
    ......
}

上述代码的核心意思即是在tcp_timestamps和tcp_tw_recycle开启的情况下,同样ip的连接,在上个连接进入time_wait状态的一分钟内,如果有新的连接进来,而且新的连接的时间戳小于上个进入time_wait状态的最后一个包的时间戳,则将这个syn丢弃,进入drop_and_release。

我们继续跟踪drop_and_release:

file

我们继续看下如果tcp_v4_conn_request返回0的话,系统是什么表现:

file

从源码的跟踪可以看出,出现此种情况直接丢弃对应的syn包,对端无法获得任何响应从而进行syn重传,这点和抓包结果一致。

和问题表象一一验证

为什么会出现一台nginx一直okay,一台nginx失败的情况?

由于tcp的时间戳是指的并不是当前本机用date命令给出的时间戳。这个时间戳的计算规则就在这里不展开了,只需要知道每台机器的时间戳都不相同即可(而且相差可能极大)。

由于我们调用对端采用的是NAT,所以两台nginx在对端服务器看来是同一个ip,那么这两台的时间戳发送到对端服务器的时候就会混乱。nginx1的时间戳比nginx2的时间戳大,所以在一分钟之内,只要出现nginx1的连接请求(短连接),那么之后的nginx2的连接请求就会一直被丢弃。

如下图所示:

file

为什么对端自测一直正常?

因为本机调用本机的时时间戳是一台机器(本机)上的,所以不会出现混乱。

为什么nginx2调用其它服务是正常的?

因为其它外部服务所在服务器并没有开启tcp_tw_recycle。这个问题事实上将tcp_tw_recycle置为0也可以解决。另外,高版本的linux内核已经去掉了tcp_tw_recycle这个参数。

总结

由于当前ip地址紧缺和DNS报文大小的限制(512字节),大部分网络架构都是采用NAT的方式去和外部交互,所以设置了tcp_tw_recycle为1基本都会出现问题。

一般这种问题需要对tcp协议有一定的了解才能够顺藤摸瓜找到最终的根源。

原文链接:

https://blog.51cto.com/14528283/2445157

​文源网络,仅供学习之用,如有侵权,联系删除。

我将优质的技术文章和经验总结都汇集在了我的公众号【Java圈子】里,为方便大家学习,还整理了一套学习资料,免费提供给热爱Java的同学! 更有学习交流群,多交流问题才能更快进步~

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

推荐阅读更多精彩内容