文档章节

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

无毁的湖光-Al
 无毁的湖光-Al
发布于 2019/10/21 10:14
字数 2538
阅读 2.5K
收藏 23

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

前言

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

起因

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


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

java.net.SocketTimeoutException: Read timed out

着手排查

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


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


由于这两个诡异的现象导致开发和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重传后,对端就已经报错。如下图所示:
(注:nginx所在linux服务器设置的tcp_syn_retries是2)

抓包结果分析

从抓包得出的数据来看,第二台nginx发送syn包给对端服务,对端服务没有任何响应,导致了nginx2创建连接超时,进而导致了appserver端的ReadTimeOut超时(appserver对nginx是短连接)。
按照正常推论,应该是防火墙外到对端服务的SYN丢失了。而阿里云作为一个非常稳定的服务商,应该不可能出现如此大概率的丢失现象。而从对端服务器用的是非常成熟的SpringBoot来看,也不应该出现这种bug。那么最有可能的就是对端服务器本身的设置有问题。

登陆对端服务器进行排查

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

dmesg:
__ratelimit: 33491 callbacks suppressed
TCP: time wait bucket table overflow
TCP: time wait bucket table overflow
TCP: time wait bucket table overflow
......

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

netstat -s
......
16990 passive connections rejected because of time stamp 
......

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

tcp_timestamps == 1 && tcp_tw_recycle == 1

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

echo '0' > /proc/sys/net/ipv4/tcp_timestamps
 or
echo '0' > /proc/sys/net/ipv4/tcp_tw_recycle

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

linux源码分析

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

// 三次握手第一个SYN kernel走的分支
tcp_v4_do_rcv
	|->tcp_v4_hnd_req
	|->tcp_rcv_state_process
		/** case TCP_LISTEN && th->syn */
		|->conn_request(tcp_v4_conn_request)

关于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:

int tcp_v4_conn_request(struct sock *sk, struct sk_buff *skb){
	......
	drop_and_release:
		dst_release(dst);
	drop_and_free:
		reqsk_free(req);
	drop:
		return 0;
}

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

int tcp_rcv_state_process(struct sock *sk, struct sk_buff *skb,
			  struct tcphdr *th, unsigned len)
{
	......
	// 由于tcp_v4_conn_request所以不走下列分枝
	if (icsk->icsk_af_ops->conn_request(sk, skb) < 0)
		return 1
	// 所以此处也返回0
	kfree_skb(skb);
	return 0;
}
// 再跳回tcp_v4_do_rcv
int tcp_v4_do_rcv(struct sock *sk, struct sk_buff *skb)
{
	// 由于tcp_rcv_state_process这边返回的是0,所以不走reset的逻辑
	if (tcp_rcv_state_process(sk, skb, tcp_hdr(skb), skb->len)) {
		rsk = sk;
		goto reset;
	}
	// 走到这边之后,不发送reset包,不给对端任何响应
	TCP_CHECK_TIMER(sk);
	return 0;
}

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

和问题表象一一验证

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

由于tcp的时间戳是指的并不是当前本机用date命令给出的时间戳。这个时间戳的计算规则就在这里不展开了,只需要知道每台机器的时间戳都不相同即可(而且相差可能极大)。由于我们调用对端采用的是NAT,所以两台nginx在对端服务器看来是同一个ip,那么这两台的时间戳发送到对端服务器的时候就会混乱。nginx1的时间戳比nginx2的时间戳大,所以在一分钟之内,只要出现nginx1的连接请求(短连接),那么之后的nginx2的连接请求就会一直被丢弃。如下图所示:

为什么对端自测一直正常

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

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

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

总结

由于当前ip地址紧缺和DNS报文大小的限制(512字节),大部分网络架构都是采用NAT的方式去和外部交互,所以设置了tcp_tw_recycle为1基本都会出现问题。一般这种问题需要对tcp协议有一定的了解才能够顺藤摸瓜找到最终的根源。

原文链接

https://my.oschina.net/alchemystar/blog/3119992

© 著作权归作者所有

无毁的湖光-Al

无毁的湖光-Al

粉丝 480
博文 32
码字总数 57890
作品 0
浦东
后端工程师
私信 提问
加载中

评论(40)

年少爱追梦
年少爱追梦
每周上来学习网络知识,就靠博主的文章了
无毁的湖光-Al
无毁的湖光-Al 博主
多谢^_^
西邮余文乐
西邮余文乐
太强了,菊花哥
无毁的湖光-Al
无毁的湖光-Al 博主
说得好
e
exseed
无毁的湖光-Al
无毁的湖光-Al 博主
:)
JPer
JPer
学习到了,还是的有很深厚的基础才行;
无毁的湖光-Al
无毁的湖光-Al 博主
多谢^_^
问天知地
问天知地
如此精确总结问题,老板前世修来的福报!膜拜学习学习👍
无毁的湖光-Al
无毁的湖光-Al 博主
:)
问天知地
问天知地
朋友,你精彩的总结让我破戒了。这是我第一次在开源中国的评论👍
无毁的湖光-Al
无毁的湖光-Al 博主
荣幸^_^
鲁鲁托马西
对面要哭,他很快就会发现大量堆积time_wait连接
无毁的湖光-Al
无毁的湖光-Al 博主
不会的,time_wait的mini_sock在内核中占用内存比起正常sock来说非常小。所以只是time_wait看上去多而已,不会影响运行。总比调用失败的好。
鲁鲁托马西
根据你给的信息,他这个满了呢:time wait bucket
无毁的湖光-Al
无毁的湖光-Al 博主
这个是报错是溢出丢弃了,连mini_sock都不创建了,所以不影响内存的使用,进而服务稳定。如果不想看到这个报错,配置tcp_max_tw_buckets = 262100
鲁鲁托马西
端口会不会被占着不能用?
无毁的湖光-Al
无毁的湖光-Al 博主
会,核心问题得看下为何有这么多time_wait,是不是有某个服务器疯狂在和这个time_wait的服务器建短链接。
鲁鲁托马西
回复 @无毁的湖光-Al : 所以问题没定位出来,直接改配置,那哥们也没说什么吗?
无毁的湖光-Al
无毁的湖光-Al 博主
回复 @鲁鲁托马西 : 主要解决我们这边调不通的问题,对端服务器让对端自己去调整。如果你看下kernel就会明白,这个time_wait过多影响不大,可能对端开发也无所谓。
鲁鲁托马西
回复 @无毁的湖光-Al : 端口不能复用,还是要想想
鲁鲁托马西
回复 @无毁的湖光-Al : tw_reuse 这个参数的效果怎么样,它是根据什么进行复用的?
无毁的湖光-Al
无毁的湖光-Al 博主
回复 @鲁鲁托马西 : 如果在短链接tps高到在time_wait时间段内用完端口号的情况下,可以(1)设置ip_local_port_range(2)在(发起主动关闭端)设置tw_reuse(3)用lb后面跟多台server平均负载。但是tw_recycle是万万不能开启的。
无毁的湖光-Al
无毁的湖光-Al 博主
回复 @鲁鲁托马西 : tw_reuse是在主动发起关闭的那端去reuse tw_wait的sock。有效的方式仅仅在A主动连接B,同时A主动关闭和B的连接情况下,设置A服务器的tw_reuse才有效果。
鲁鲁托马西
回复 @无毁的湖光-Al : 复用的时候,要怎么避免新连接不被上次连接还在网络中传输的包影响到?
无毁的湖光-Al
无毁的湖光-Al 博主
回复 @鲁鲁托马西 : 用tcp_timestamps辅助判断呗(前提是tcp_timestamps必须严格单调递增),本文中走NAT过来的tcp数据包无法满足这个条件。
鲁鲁托马西
回复 @无毁的湖光-Al : 所以又绕回来了,你列的三个方式: 1 ip port range已经开到最大; 2 tw_reuse 根据消息的timestamp判断,如果消息时间大于连接时间,丢包,这个行为比快速回收好一点,但是不是很可靠; 3 加机器,那问题就推到lb上面了,lb同时是客户端和服务端,这些参数怎么配
无毁的湖光-Al
无毁的湖光-Al 博主
回复 @鲁鲁托马西 : 首先你得明白你的time_wait过多的缘由。如果确实是真实流量过高。 在前提是lb主动关闭的情况下,lb(得是个四层or七层负载,lvs这种三层的不行)配置tcp_tw_reuse=1同时tw_recycle必须设置为0,否则会出现本文的问题。 在web服务器上(RealServer)也设置tcp_tw_reuse=1(聊胜于无). 但是如果是web服务器(RealServer主动关闭连接),设置tw_reuse=1(聊胜于无)。然后需要看下为何web服务器主动关闭,,是否是处理请求后直接调用了close(socket),修改源代码,把 连接的关闭动作交给client端。然后写一个定时任务,在web服务器上定期检测过期无流量的socket,手动调用close,然后让调用方配置tw_reuse=1。 因为这种短链接处理完双方都立即close的现象会造成双方都是time_wait的状态(见tcpip状态转移图,同时关闭的现象),所以让client端先关闭是种比较好的做法,同时定时检测又会避免服务器端close_wait过多。
鲁鲁托马西
回复 @无毁的湖光-Al : 太长不看,这个问题,其实我想说的是,应该由对面定位为什么会出现time_wait过多,很可能他们需要修改程序走长连接协议。直接改配置有点凶。
无毁的湖光-Al
无毁的湖光-Al 博主
回复 @鲁鲁托马西 : 你可以耐心看下,说不定对你有帮助。长连接协议的修改我也建议过,不过修改这个参数okay后,他们就再无动静了。50%的失败率已经是相当严重了,直接改配置能先让这个服务好起来还是可取的。
鲁鲁托马西
回复 @无毁的湖光-Al : 可能我们的风格不一样,基于风险考虑,我会建议你们用一台nginx,等改完长连接后再说。
无毁的湖光-Al
无毁的湖光-Al 博主
回复 @鲁鲁托马西 : 物理机由于内存故障磁盘问题等导致维护频率较高,甚至有无任何预警物理机直接宕机的现象,单台nginx在运维上是不可接受的。物理机问题概率会比流量大到端口不可用概率高,所以选择了先改参数,至于他们改不改长链接何时上线就看他们自己了。
h
hsmOsChina
一直关注博主的文章。
哪个老板能有博主这样的员工,真是前世修来的福报。
无毁的湖光-Al
无毁的湖光-Al 博主
😀过奖了😆
海绵宝宝a
海绵宝宝a
最麻烦的就是通过日志分析出来的配置错误,大的系统更是如此,根据代码分析出配置问题都要哭了!!
无毁的湖光-Al
无毁的湖光-Al 博主
所以需要各种辅助命令提供靠谱的信息
无毁的湖光-Al
无毁的湖光-Al 博主
😎
h
hsmOsChina
只有像博主这样的大牛才能游刃有余地解决这类问题。
enable_irq和enable_irq_wake的正确使用姿势

之所以讨论这个问题,是因为在调试距感休眠唤醒中遇到概率性唤不醒系统的bug,排查发现是因为对这两个接口的使用存在盲区,记录下过程,便于日后查询。 1.背景 在android7.1+linux3.10上调试...

DerrickOwen
2019/07/02
9
0
记一次一个枚举引发线上事故风暴

背景 在2018年8月15号下午6点左右突然有一个调用我们服务的业务方告知我们大量调用出现异常失败或超时,并不停的出现一个未设置结束日志的错误。 问题定位 收到相关的信息后,我立即展开问题排...

朝向远方
2018/08/16
0
0
解Bug之路-记一次JVM堆外内存泄露Bug的查找(学习转载,经典文章)

解Bug之路-记一次JVM堆外内存泄露Bug的查找 前言 JVM的堆外内存泄露的定位一直是个比较棘手的问题。此次的Bug查找从堆内内存的泄露反推出堆外内存,同时对物理内存的使用做了定量的分析,从而...

小海bug
2019/03/12
282
0
阿里消息中间件ONS消息重复问题和事物问题(三)

产生的原因:网络不可达问题。 网络超时之后我们可以做的只有两件事,1 停止(回滚,但对于系统来说影响特别大) 2 继续(另发送到别的服务消费端) 一般我们采用第二种处理方式,但是要经过...

哲别0
2018/03/26
189
0
Dubbo集群容错和负载均衡

0、基础知识 Dubbo是什么? Dubbo是一个分布式服务框架,致力于提供高性能和透明化的RPC远程服务调用方案,以及SOA服务治理方案。 其核心部分包含: 远程通讯: 提供对多种基于长连接的NIO框架...

Idea
2018/01/15
177
0

没有更多内容

加载失败,请刷新页面

加载更多

2019 年 Google 编程之夏活动报告

本文首发于: Jenkins 中文社区 原文链接 作者:Martin d'Anjou,Jeff Pearce,Oleg Nenashev,Marky Jackson 译者:s1mple_zj 2019 年 Google 编程之夏活动报告 主要介绍了 GSoC 2019 活动的...

Jenkins中文社区
3分钟前
0
0
Spring Batch 在默认情况下的任务执行

在默认情况,如果你对 Spring Batch 不进行配置的话。 Spring Batch 将会对所有存在的作业(Job)进行执行。 考察项目:https://github.com/cwiki-us-spring/cwiki-us-spring-batch-examples...

honeymoose
今天
47
0
OSChina 周三乱弹 —— 提高不了工作效率和脸有关系

Osc乱弹歌单(2020)请戳(这里) 【今日歌曲】 @薛定谔的兄弟 :分享洛神有语创建的歌单「我喜欢的音乐」: 1 《夏令时记录(piano.ver)》- ゆめこ 手机党少年们想听歌,请使劲儿戳(这里) ...

小小编辑
今天
67
2
List的一波操作

public static void main(String[] args) { List<Entity> list = new ArrayList<>(); list.add(new Entity(1)); list.add(new Entity(2)); list.add(new Entity(3)); ......

那个猩猩很亮
今天
75
0
Spring基础

主要用于service层; 轻量级java开发框架; 各层 web层:struts,spring-MVC service层:spring dao层:hibernate,mybatis , jdbcTemplate --> spring-data Spring核心:控制反转IOC 切面编...

七宝1
今天
30
0

没有更多内容

加载失败,请刷新页面

加载更多

返回顶部
顶部