On Mon, Dec 23, 2013 at 4:47 PM, Stuart MacDonald
<stuartm.coding_at_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.0E86A23888E3@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
Received on 2013-12-23 23:41:06 CET