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

解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