最近碰到一起网络故障，有代表意义，记录下过程

故障现象

客户系统频繁报调用超时，检查后端服务提供方日志，并没有发现服务调用异常情况，服务调用时长都控制在5S以内。

故障分析

分析调用方日志，由于我们在sdk里面提供了uuid作为requestid，调用方的异常日志都记录了该字段。我们通过该字段去查后端服务的日志，在日志中并没有发现该requestid。也就是会说，请求并没有调用到后端服务，问题应该出现在网络上。

由于网络环境比较复杂，中间有防火墙和F5以及多层交换设备，我们先是在客户端进行了简单的抓包。

通过异常日志中的requestid，在捕获包中查找（通过tcp contains过滤），结果却找不到对应的数据包，也就是说请求并没有发出去，怀疑tcp连接应该是没有建立。

继续分析，发现网络中存在大量的syn包重传，下面截取了一个典型的例子： wireshark sack

可以看到，tcp进行了5次syn包重传（linux默认），花了60多秒的时间，而调用方的服务调用超时设置的是60秒，也就是说连接没有建立，请求直接超时了。这也就解释了为什么在后台服务提供方的日志中并没有发现对应的requestid。

检查调用方和服务提供方网络，并没有发现明显的异常，为什么偏偏只丢syn包呢？接下来又在F5端和服务提供方网络进行抓包分析，发现异常。

先来看看F5的包：

140994 689.875661 10.24.20.249 → 10.24.20.26  TCP 0 0 0.000000000 0 29200 57011 → 8080 [SYN] Seq=0 Win=29200 Len=0 MSS=1460 SACK_PERM=1 TSval=3135523389 TSecr=0 WS=128
144871 719.924532  10.24.20.26 → 10.24.20.249 TCP 1 887 30.048871000 0 220 [TCP ACKed unseen segment] 8080 → 57011 [FIN, ACK] Seq=1 Ack=887 Win=220 Len=0 TSval=2612910209 TSecr=3135523404
144872 719.924548  10.24.20.51 → 10.24.18.13  TCP 1 1 0.000000000 0 220 8080 → 57011 [FIN, ACK] Seq=1 Ack=1 Win=220 Len=0 TSval=2612910209 TSecr=3135523404
144877 719.963860  10.24.18.13 → 10.24.20.51  TCP 1 2 0.039312000 0 625 57011 → 8080 [ACK] Seq=1 Ack=2 Win=625 Len=0 TSval=3135553478 TSecr=2612910209
144878 719.963869 10.24.20.249 → 10.24.20.26  TCP 887 2 0.039337000 0 80000 [TCP Previous segment not captured] 57011 → 8080 [ACK] Seq=887 Ack=2 Win=80000 Len=0 TSval=3135553478 TSecr=2612910209
148017 741.416886  10.24.18.13 → 10.24.20.51  TCP 1 2 21.453026000 0 625 57011 → 8080 [FIN, ACK] Seq=1 Ack=2 Win=625 Len=0 TSval=3135574931 TSecr=2612910209
148018 741.416892 10.24.20.249 → 10.24.20.26  TCP 887 2 21.453023000 0 80000 57011 → 8080 [FIN, ACK] Seq=887 Ack=2 Win=80000 Len=0 TSval=3135574931 TSecr=2612910209
148021 741.417014  10.24.20.26 → 10.24.20.249 TCP 2 888 0.000122000 0 220 [TCP ACKed unseen segment] 8080 → 57011 [ACK] Seq=2 Ack=888 Win=220 Len=0 TSval=2612931702 TSecr=3135574931
148022 741.417047  10.24.20.51 → 10.24.18.13  TCP 2 2 0.000161000 0 220 8080 → 57011 [ACK] Seq=2 Ack=2 Win=220 Len=0 TSval=2612931702 TSecr=3135574931
150058 750.708540 10.24.20.249 → 10.24.20.26  TCP 0 0 0.000000000 0 29200 [TCP Port numbers reused] 57011 → 8080 [SYN] Seq=0 Win=29200 Len=0 MSS=1460 SACK_PERM=1 TSval=3134415069 TSecr=0 WS=128
150136 751.711154  10.24.18.14 → 10.24.20.51  TCP 0 0 0.000000000 0 29200 57011 → 8080 [SYN] Seq=0 Win=29200 Len=0 MSS=1460 SACK_PERM=1 TSval=3134416072 TSecr=0 WS=128
150137 751.711159 10.24.20.249 → 10.24.20.26  TCP 0 0 1.002619000 0 29200 [TCP Retransmission] 57011 → 8080 [SYN] Seq=0 Win=29200 Len=0 MSS=1460 SACK_PERM=1 TSval=3134416072 TSecr=0 WS=128
150545 753.715177  10.24.18.14 → 10.24.20.51  TCP 0 0 2.004023000 0 29200 [TCP Retransmission] 57011 → 8080 [SYN] Seq=0 Win=29200 Len=0 MSS=1460 SACK_PERM=1 TSval=3134418076 TSecr=0 WS=128
150546 753.715187 10.24.20.249 → 10.24.20.26  TCP 0 0 2.004028000 0 29200 [TCP Retransmission] 57011 → 8080 [SYN] Seq=0 Win=29200 Len=0 MSS=1460 SACK_PERM=1 TSval=3134418076 TSecr=0 WS=128
151292 757.719161  10.24.18.14 → 10.24.20.51  TCP 0 0 4.003984000 0 29200 [TCP Retransmission] 57011 → 8080 [SYN] Seq=0 Win=29200 Len=0 MSS=1460 SACK_PERM=1 TSval=3134422080 TSecr=0 WS=128
151293 757.719183 10.24.20.249 → 10.24.20.26  TCP 0 0 4.003996000 0 29200 [TCP Retransmission] 57011 → 8080 [SYN] Seq=0 Win=29200 Len=0 MSS=1460 SACK_PERM=1 TSval=3134422080 TSecr=0 WS=128
152398 765.735191  10.24.18.14 → 10.24.20.51  TCP 0 0 8.016030000 0 29200 [TCP Retransmission] 57011 → 8080 [SYN] Seq=0 Win=29200 Len=0 MSS=1460 SACK_PERM=1 TSval=3134430096 TSecr=0 WS=128
152399 765.735201 10.24.20.249 → 10.24.20.26  TCP 0 0 8.016018000 0 29200 [TCP Retransmission] 57011 → 8080 [SYN] Seq=0 Win=29200 Len=0 MSS=1460 SACK_PERM=1 TSval=3134430096 TSecr=0 WS=128
158405 781.783166  10.24.18.14 → 10.24.20.51  TCP 0 0 16.047975000 0 29200 [TCP Retransmission] 57011 → 8080 [SYN] Seq=0 Win=29200 Len=0 MSS=1460 SACK_PERM=1 TSval=3134446144 TSecr=0 WS=128
158406 781.783177 10.24.20.249 → 10.24.20.26  TCP 0 0 16.047976000 0 29200 [TCP Retransmission] 57011 → 8080 [SYN] Seq=0 Win=29200 Len=0 MSS=1460 SACK_PERM=1 TSval=3134446144 TSecr=0 WS=128
175385 881.982585  10.24.20.51 → 10.107.209.51 TCP 1 1 0.000000000 0 229 8080 → 57011 [FIN, ACK] Seq=1 Ack=1 Win=229 Len=0 TSval=2613072267 TSecr=333623407
175394 882.059551 10.107.209.51 → 10.24.20.51  TCP 1 2 0.076966000 0 5988 57011 → 8080 [ACK] Seq=1 Ack=2 Win=5988 Len=0 TSval=333653945 TSecr=2613072267

249代表F5地址，26是服务提供方服务器地址，上面信息显示，F5重用了端口（包150058）和26进行连接，连发了5个syn包，看起来是丢包了。

但是我们来看看服务提供方包：

136316 654.713264 10.24.20.249 → 10.24.20.26  TCP 0 0 0.000000000 0 29200 57011 → 8080 [SYN] Seq=0 Win=29200 Len=0 MSS=1460 SACK_PERM=1 TSval=3135523389 TSecr=0 WS=128
136317 654.713292  10.24.20.26 → 10.24.20.249 TCP 0 1 0.000028000 0 28960 8080 → 57011 [SYN, ACK] Seq=0 Ack=1 Win=28960 Len=0 MSS=1460 SACK_PERM=1 TSval=2612880161 TSecr=3135523389 WS=128
136318 654.713558 10.24.20.249 → 10.24.20.26  TCP 1 1 0.000266000 0 29312 57011 → 8080 [ACK] Seq=1 Ack=1 Win=29312 Len=0 TSval=3135523390 TSecr=2612880161
136319 654.713747 10.24.20.249 → 10.24.20.26  HTTP 1 1 0.000189000 182 29312 POST /default/WSWorkItemManagerService?wsdl HTTP/1.1
136320 654.713759  10.24.20.26 → 10.24.20.249 TCP 1 183 0.000012000 0 28800 8080 → 57011 [ACK] Seq=1 Ack=183 Win=28800 Len=0 TSval=2612880161 TSecr=3135523390
136321 654.713814 10.24.20.249 → 10.24.20.26  HTTP 183 1 0.000055000 704 29312 Continuation
136322 654.713824  10.24.20.26 → 10.24.20.249 TCP 1 887 0.000010000 0 28160 8080 → 57011 [ACK] Seq=1 Ack=887 Win=28160 Len=0 TSval=2612880161 TSecr=3135523390
136323 654.727617  10.24.20.26 → 10.24.20.249 HTTP 1 887 0.013793000 8192 28160 HTTP/1.1 200 OK [Unreassembled Packet]
136324 654.727706  10.24.20.26 → 10.24.20.249 HTTP 8193 887 0.000089000 5792 28160 Continuation
136325 654.727915 10.24.20.249 → 10.24.20.26  TCP 887 8193 0.000209000 0 45696 57011 → 8080 [ACK] Seq=887 Ack=8193 Win=45696 Len=0 TSval=3135523404 TSecr=2612880175
136326 654.727928  10.24.20.26 → 10.24.20.249 HTTP 13985 887 0.000013000 11386 28160 Continuation
136327 654.728040 10.24.20.249 → 10.24.20.26  TCP 887 11089 0.000112000 0 51456 57011 → 8080 [ACK] Seq=887 Ack=11089 Win=51456 Len=0 TSval=3135523404 TSecr=2612880175
136328 654.728049 10.24.20.249 → 10.24.20.26  TCP 887 11089 0.000009000 0 54272 [TCP Window Update] 57011 → 8080 [ACK] Seq=887 Ack=11089 Win=54272 Len=0 TSval=3135523404 TSecr=2612880175 SLE=12537 SRE=13985
136329 654.728056 10.24.20.249 → 10.24.20.26  TCP 887 13985 0.000007000 0 57216 57011 → 8080 [ACK] Seq=887 Ack=13985 Win=57216 Len=0 TSval=3135523404 TSecr=2612880175
136330 654.728202 10.24.20.249 → 10.24.20.26  TCP 887 25371 0.000146000 0 80000 57011 → 8080 [ACK] Seq=887 Ack=25371 Win=80000 Len=0 TSval=3135523404 TSecr=2612880175
142165 684.762029  10.24.20.26 → 10.24.20.249 TCP 25371 887 30.033827000 0 28160 8080 → 57011 [FIN, ACK] Seq=25371 Ack=887 Win=28160 Len=0 TSval=2612910209 TSecr=3135523404
142174 684.801477 10.24.20.249 → 10.24.20.26  TCP 887 25372 0.039448000 0 80000 57011 → 8080 [ACK] Seq=887 Ack=25372 Win=80000 Len=0 TSval=3135553478 TSecr=2612910209
146703 706.254510 10.24.20.249 → 10.24.20.26  TCP 887 25372 21.453033000 0 80000 57011 → 8080 [FIN, ACK] Seq=887 Ack=25372 Win=80000 Len=0 TSval=3135574931 TSecr=2612910209
146704 706.254518  10.24.20.26 → 10.24.20.249 TCP 25372 888 0.000008000 0 28160 8080 → 57011 [ACK] Seq=25372 Ack=888 Win=28160 Len=0 TSval=2612931702 TSecr=3135574931
148567 715.546271 10.24.20.249 → 10.24.20.26  TCP 0 0 0.000000000 0 29200 [TCP Port numbers reused] 57011 → 8080 [SYN] Seq=0 Win=29200 Len=0 MSS=1460 SACK_PERM=1 TSval=3134415069 TSecr=0 WS=128
148568 715.546299  10.24.20.26 → 10.24.20.249 TCP 1 3942326266 0.000028000 0 220 8080 → 57011 [ACK] Seq=1 Ack=3942326266 Win=220 Len=0 TSval=2612940994 TSecr=3135574931
148672 716.548784 10.24.20.249 → 10.24.20.26  TCP 0 0 1.002485000 0 29200 [TCP Retransmission] 57011 → 8080 [SYN] Seq=0 Win=29200 Len=0 MSS=1460 SACK_PERM=1 TSval=3134416072 TSecr=0 WS=128
148673 716.548800  10.24.20.26 → 10.24.20.249 TCP 1 3942326266 0.000016000 0 220 [TCP Dup ACK 148568#1] 8080 → 57011 [ACK] Seq=1 Ack=3942326266 Win=220 Len=0 TSval=2612941996 TSecr=3135574931
149153 718.552810 10.24.20.249 → 10.24.20.26  TCP 0 0 2.004010000 0 29200 [TCP Retransmission] 57011 → 8080 [SYN] Seq=0 Win=29200 Len=0 MSS=1460 SACK_PERM=1 TSval=3134418076 TSecr=0 WS=128
149154 718.552831  10.24.20.26 → 10.24.20.249 TCP 1 3942326266 0.000021000 0 220 [TCP Dup ACK 148568#2] 8080 → 57011 [ACK] Seq=1 Ack=3942326266 Win=220 Len=0 TSval=2612944000 TSecr=3135574931
150128 722.556839 10.24.20.249 → 10.24.20.26  TCP 0 0 4.004008000 0 29200 [TCP Retransmission] 57011 → 8080 [SYN] Seq=0 Win=29200 Len=0 MSS=1460 SACK_PERM=1 TSval=3134422080 TSecr=0 WS=128
150129 722.556858  10.24.20.26 → 10.24.20.249 TCP 1 3942326266 0.000019000 0 220 [TCP Dup ACK 148568#3] 8080 → 57011 [ACK] Seq=1 Ack=3942326266 Win=220 Len=0 TSval=2612948004 TSecr=3135574931
151923 730.572850 10.24.20.249 → 10.24.20.26  TCP 0 0 8.015992000 0 29200 [TCP Retransmission] 57011 → 8080 [SYN] Seq=0 Win=29200 Len=0 MSS=1460 SACK_PERM=1 TSval=3134430096 TSecr=0 WS=128
151924 730.572871  10.24.20.26 → 10.24.20.249 TCP 1 3942326266 0.000021000 0 220 [TCP Dup ACK 148568#4] 8080 → 57011 [ACK] Seq=1 Ack=3942326266 Win=220 Len=0 TSval=2612956020 TSecr=3135574931
155688 746.620837 10.24.20.249 → 10.24.20.26  TCP 0 0 16.047966000 0 29200 [TCP Retransmission] 57011 → 8080 [SYN] Seq=0 Win=29200 Len=0 MSS=1460 SACK_PERM=1 TSval=3134446144 TSecr=0 WS=128
155689 746.620857  10.24.20.26 → 10.24.20.249 TCP 1 3942326266 0.000020000 0 220 [TCP Dup ACK 148568#5] 8080 → 57011 [ACK] Seq=1 Ack=3942326266 Win=220 Len=0 TSval=2612972068 TSecr=3135574931

tcp连接正常终止在包（142165，142174，146703，146704），接下来249在9秒之后，重用了同样的端口向26发起连接（包148567），26接收到syn包之后，回了一个ack包？不是一个syn/ack包？而且ack number = 3942326266

其实容易理解，由于26是active close一方，当连接终止之后，依然处于time_wait状态，这个时候，249重用了端口进行新的连接，可是这个连接在26上依然存在（处于time_wait状态），看到249发过来的syn包，和自己目前连接的sequence number一比，发现比自己目前的sequence number小，直接回一个ACK包告诉对方你给我发什么乱七八糟的东西，我期待下一个包的sequence number是3942326266，然后默默的把249发过来的SYN包扔掉了。。。

解决思路

tcp连接的time_wait状态是用来保护连接的，linux把这个值写死在代码中（TCP_TIMEWAIT_LEN=60秒），除非自己编译源代码修改（不建议缩短这个值，容易导致连接损坏，或者连接关闭不完全）

在本系统中，由于服务提供方（26）设置的线程keepalive时间为30S，30S之后，会主动断开连接，连接就会进入time_wait状态；客户端连接被释放之后，很快用这个端口再次发起连接，导致了连接无法建立正常，我们简单的把keepalive参数设置为不超时，暂时缓解了该问题。

后续

由于系统中，前端和后端调用量很大，中间的F5很容易导致类似问题，优化方向参考：

增加客户端的可用端口数量(net.ipv4.ip_local_port_range)
增加F5的出口ip数量，缓解端口问题
增加服务端的server监听ip，缓解端口重用问题
修改调用端代码，重用tcp连接

参考

TCP连接的状态变化参考下图：