On Mon, Dec 23, 2013 at 4:47 PM, Stuart MacDonald <stuartm.cod...@gmail.com>wrote:
> I took some time last Fri to see what was 180 seconds prior to the FIN > packet in the trace (this is the 1.7.14 failure): > 289223 259.418521000 10.222.3.88 10.14.10.32 HTTP 1434 > Continuation or non-HTTP traffic > 289224 259.418583000 10.14.10.32 10.222.3.88 TCP 54 > 60442 > http [ACK] Seq=2151 Ack=358465616 Win=1280 Len=0 > 289225 259.649415000 10.222.3.88 10.14.10.32 HTTP 1334 > [TCP Window Full] Continuation or non-HTTP traffic > 289226 259.855605000 10.14.10.32 10.222.3.88 TCP 54 [TCP > ZeroWindow] 60442 > http [ACK] Seq=2151 Ack=358466896 Win=0 Len=0 > 289227 259.868018000 10.222.3.88 10.14.10.32 HTTP 1334 > [TCP Window Full] [TCP Retransmission] Continuation or non-HTTP traffic > 289228 *REF* 10.14.10.32 10.222.3.88 TCP 66 [TCP > ZeroWindow] 60442 > http [ACK] Seq=2151 Ack=358466896 Win=0 Len=0 > SLE=358465616 SRE=358466896 > 289229 0.383858000 10.14.10.32 10.222.3.88 TCP 54 [TCP > Window Update] 60442 > http [ACK] Seq=2151 Ack=358466896 Win=2062848 Len=0 > 289230 0.398005000 10.222.3.88 10.14.10.32 HTTP 1434 > Continuation or non-HTTP traffic > which yields > 444658 178.073895000 10.222.3.88 10.14.10.32 HTTP 1434 > Continuation or non-HTTP traffic > 444659 178.073944000 10.14.10.32 10.222.3.88 TCP 54 > 60442 > http [ACK] Seq=2151 Ack=550721697 Win=542208 Len=0 > 444660 179.906931000 10.14.10.32 10.222.3.88 TCP 54 [TCP > Window Update] 60442 > http [ACK] Seq=2151 Ack=550721697 Win=1966336 Len=0 > 444661 180.152119000 10.14.10.32 10.222.3.88 TCP 54 > 60442 > http [FIN, ACK] Seq=2151 Ack=550721697 Win=1966336 Len=0 > 444662 180.165529000 10.222.3.88 10.14.10.32 TCP 60 http > > 60442 [ACK] Seq=550721697 Ack=2152 Win=10240 Len=0 > > If the time ref is set at (wireshark-)packet 289227 then the FIN packet > would be at 179.something elapsed. There are a lot of TCP zero windows in > the trace though, that one isn't special AFAICT. There's plenty before and > after it. > > If someone can let me know what the default for http-timeout is for > 1.8.5/ra_serf, I'll do the same check in this morning's failure and see > what's there. > Some googling <http://mail-archives.apache.org/mod_mbox/subversion-commits/201211.mbox/%3c20121120183435.0e86a2388...@eris.apache.org%3E>reveals that the default timeout is likely to be 600 seconds. Let's see what we have there (this is the 1.8.5 failure): 708 25.462185000 10.222.3.88 10.14.10.85 TCP 1434 [TCP segment of a reassembled PDU] 709 25.462580000 10.14.10.85 10.222.3.88 TCP 54 9415 > http [ACK] Seq=2713 Ack=753855 Win=1280 Len=0 710 25.707269000 10.222.3.88 10.14.10.85 TCP 1334 [TCP Window Full] [TCP segment of a reassembled PDU] 711 25.907229000 10.14.10.85 10.222.3.88 TCP 54 [TCP ZeroWindow] 9415 > http [ACK] Seq=2713 Ack=755135 Win=0 Len=0 712 *REF* 10.14.10.85 10.222.3.88 TCP 54 [TCP Window Update] 9415 > http [ACK] Seq=2713 Ack=755135 Win=3328 Len=0 713 0.013860000 10.222.3.88 10.14.10.85 TCP 1434 [TCP segment of a reassembled PDU] which yields 496958 599.344977000 10.222.3.88 10.14.10.85 HTTP 1434 Continuation or non-HTTP traffic 496959 599.345056000 10.14.10.85 10.222.3.88 TCP 54 9415 > http [ACK] Seq=2713 Ack=612899776 Win=1760768 Len=0 496960 599.345098000 10.14.10.85 10.222.3.88 TCP 54 [TCP Window Update] 9415 > http [ACK] Seq=2713 Ack=612899776 Win=1762048 Len=0 496961 600.011551000 10.14.10.85 10.222.3.88 TCP 54 9415 > http [FIN, ACK] Seq=2713 Ack=612899776 Win=1762048 Len=0 496962 600.025110000 10.222.3.88 10.14.10.85 TCP 60 http > 9415 [ACK] Seq=612899776 Ack=2714 Win=12288 Len=0 So that's interesting that it's also at a TCP zero window, but like the 1.7.14 failure, there's nothing special about that one; there are several before it and many after it. >From 2013-12-17, 1.7.13 (WANdisco again), http-timeout=180, ra_neon: 380006 238.310421000 10.222.3.88 10.14.10.32 HTTP 1434 Continuation or non-HTTP traffic 380007 238.310501000 10.14.10.32 10.222.3.88 TCP 54 12926 > http [ACK] Seq=2151 Ack=464948988 Win=1280 Len=0 380008 *REF* 10.222.3.88 10.14.10.32 HTTP 1334 [TCP Window Full] Continuation or non-HTTP traffic 380009 0.200088000 10.14.10.32 10.222.3.88 TCP 54 [TCP ZeroWindow] 12926 > http [ACK] Seq=2151 Ack=464950268 Win=0 Len=0 380010 0.456070000 10.222.3.88 10.14.10.32 TCP 60 [TCP Keep-Alive] http > 12926 [ACK] Seq=464950267 Ack=2151 Win=10240 Len=0 380011 0.456130000 10.14.10.32 10.222.3.88 TCP 54 [TCP ZeroWindow] 12926 > http [ACK] Seq=2151 Ack=464950268 Win=0 Len=0 380012 0.953776000 10.222.3.88 10.14.10.32 TCP 60 [TCP Keep-Alive] http > 12926 [ACK] Seq=464950267 Ack=2151 Win=10240 Len=0 380013 0.953813000 10.14.10.32 10.222.3.88 TCP 54 [TCP ZeroWindow] 12926 > http [ACK] Seq=2151 Ack=464950268 Win=0 Len=0 380014 1.935785000 10.222.3.88 10.14.10.32 TCP 60 [TCP Keep-Alive] http > 12926 [ACK] Seq=464950267 Ack=2151 Win=10240 Len=0 380015 1.935818000 10.14.10.32 10.222.3.88 TCP 54 [TCP ZeroWindow] 12926 > http [ACK] Seq=2151 Ack=464950268 Win=0 Len=0 380016 2.018723000 10.14.10.32 10.222.3.88 TCP 54 [TCP Window Update] 12926 > http [ACK] Seq=2151 Ack=464950268 Win=2472960 Len=0 380017 2.032298000 10.222.3.88 10.14.10.32 HTTP 1434 Continuation or non-HTTP traffic which yields 444920 179.032704000 10.222.3.88 10.14.10.32 HTTP 1434 Continuation or non-HTTP traffic 444921 179.032758000 10.14.10.32 10.222.3.88 TCP 54 12926 > http [ACK] Seq=2151 Ack=545077309 Win=198656 Len=0 444922 179.889276000 10.14.10.32 10.222.3.88 TCP 54 [TCP Window Update] 12926 > http [ACK] Seq=2151 Ack=545077309 Win=905216 Len=0 444923 180.088824000 10.14.10.32 10.222.3.88 TCP 54 12926 > http [FIN, ACK] Seq=2151 Ack=545077309 Win=905216 Len=0 444924 180.103081000 10.222.3.88 10.14.10.32 TCP 60 http > 12926 [ACK] Seq=545077309 Ack=2152 Win=10240 Len=0 >From 2013-12-16, same as 2013-12-17: 178168 140.424974000 10.222.3.88 10.14.10.32 HTTP 1434 Continuation or non-HTTP traffic 178169 140.425010000 10.14.10.32 10.222.3.88 TCP 54 33813 > http [ACK] Seq=2151 Ack=220218202 Win=1280 Len=0 178170 140.658514000 10.222.3.88 10.14.10.32 HTTP 1334 [TCP Window Full] Continuation or non-HTTP traffic 178171 140.858753000 10.14.10.32 10.222.3.88 TCP 54 [TCP ZeroWindow] 33813 > http [ACK] Seq=2151 Ack=220219482 Win=0 Len=0 178172 141.119647000 10.222.3.88 10.14.10.32 TCP 60 [TCP Keep-Alive] http > 33813 [ACK] Seq=220219481 Ack=2151 Win=10240 Len=0 178173 141.119690000 10.14.10.32 10.222.3.88 TCP 54 [TCP ZeroWindow] 33813 > http [ACK] Seq=2151 Ack=220219482 Win=0 Len=0 178174 141.627353000 10.222.3.88 10.14.10.32 TCP 60 [TCP Keep-Alive] http > 33813 [ACK] Seq=220219481 Ack=2151 Win=10240 Len=0 178175 141.627385000 10.14.10.32 10.222.3.88 TCP 54 [TCP ZeroWindow] 33813 > http [ACK] Seq=2151 Ack=220219482 Win=0 Len=0 178176 142.628795000 10.222.3.88 10.14.10.32 TCP 60 [TCP Keep-Alive] http > 33813 [ACK] Seq=220219481 Ack=2151 Win=10240 Len=0 178177 142.628839000 10.14.10.32 10.222.3.88 TCP 54 [TCP ZeroWindow] 33813 > http [ACK] Seq=2151 Ack=220219482 Win=0 Len=0 178178 144.619506000 10.222.3.88 10.14.10.32 TCP 60 [TCP Keep-Alive] http > 33813 [ACK] Seq=220219481 Ack=2151 Win=10240 Len=0 178179 144.619574000 10.14.10.32 10.222.3.88 TCP 54 [TCP ZeroWindow] 33813 > http [ACK] Seq=2151 Ack=220219482 Win=0 Len=0 178180 148.585393000 10.222.3.88 10.14.10.32 TCP 60 [TCP Keep-Alive] http > 33813 [ACK] Seq=220219481 Ack=2151 Win=10240 Len=0 178181 148.585447000 10.14.10.32 10.222.3.88 TCP 54 [TCP ZeroWindow] 33813 > http [ACK] Seq=2151 Ack=220219482 Win=0 Len=0 178182 156.502765000 10.222.3.88 10.14.10.32 TCP 60 [TCP Keep-Alive] http > 33813 [ACK] Seq=220219481 Ack=2151 Win=10240 Len=0 178183 *REF* 10.14.10.32 10.222.3.88 TCP 54 [TCP ZeroWindow] 33813 > http [ACK] Seq=2151 Ack=220219482 Win=0 Len=0 178184 15.821813000 10.222.3.88 10.14.10.32 TCP 60 [TCP Keep-Alive] http > 33813 [ACK] Seq=220219481 Ack=2151 Win=10240 Len=0 178185 15.821845000 10.14.10.32 10.222.3.88 TCP 54 [TCP ZeroWindow] 33813 > http [ACK] Seq=2151 Ack=220219482 Win=0 Len=0 178186 43.448451000 10.14.10.32 10.222.3.88 TCP 54 [TCP Window Update] 33813 > http [ACK] Seq=2151 Ack=220219482 Win=2856448 Len=0 178187 43.461842000 10.222.3.88 10.14.10.32 HTTP 1434 Continuation or non-HTTP traffic which yields 291476 173.722084000 10.222.3.88 10.14.10.32 HTTP 1434 Continuation or non-HTTP traffic 291477 173.722125000 10.14.10.32 10.222.3.88 TCP 54 33813 > http [ACK] Seq=2151 Ack=361058243 Win=52224 Len=0 291478 178.322196000 10.14.10.32 10.222.3.88 TCP 54 [TCP Window Update] 33813 > http [ACK] Seq=2151 Ack=361058243 Win=1489664 Len=0 291479 178.364417000 10.14.10.32 10.222.3.88 TCP 54 [TCP Window Update] 33813 > http [ACK] Seq=2151 Ack=361058243 Win=3042816 Len=0 291480 180.974205000 10.14.10.32 10.222.3.88 TCP 54 33813 > http [FIN, ACK] Seq=2151 Ack=361058243 Win=3042816 Len=0 291481 180.988706000 10.222.3.88 10.14.10.32 TCP 60 http > 33813 [ACK] Seq=361058243 Ack=2152 Win=10240 Len=0 Nice to see the exponential backoff at work during the TCP zero window. Maybe this is a red herring. I do find it unusual that all the http timeout start points seem to be during TCP zero windows. ...Stu
