Re: [squid-users] trying to track down a bug

Henrik Nordstrom wrote:
> On Mon, 10 Jan 2005, Robert Borkowski wrote:
>
>> A wget in a loop retrieving the main page of our site will
>> occasionally take just under 15 minutes to complete the retrieval.
>> Normally it takes 0.02 seconds.
>
>
> A related note: The default timeout waiting for data from the server is
> 15 minutes. (read_timeout).
>
>> When I look at the access.log for that retrieval and work back to the
>> time the request was placed I often find that some client out on the
>> internet had issued a request with a no-cache header resulting in
>> TCP_CLIENT_REFRESH_MISS for the main page.
>
>
> Which will cause all clients to join this request to your server. If
> this requests takes a long time to complete then all clients will
> experience this delay.
>
>> The Age + the time to retrieve the object = the read_timeout in
>> squid.conf. I changed it to 9 minutes on one server and started seeing
>> wget fail with 8+ instead of 14+ minutes.
>
>
> Ok, so your server is not finishing the page properly to Squid.
>
>> The object is transferred quickly, but the connection stays open until
>> some timer in squid elapses (read_timeout) and only then squid closes
>> the connection.
>
>
> Most likely there is some bytes at the end missing.
>
> You can try working around it by setting "server_persistent_connections
> off" in squid.conf, but I would recommend identifying exacly what is
> going wrong first.
>
> A good step on the way is to save a packet trace of the failing server
> request
>
> tcpdump -s 1600 -w traffic.out -i any host ip.of.your.web.server
>
> then analyze this with ngrep / ethereal etc to try to figure out why the
> response never finishes proper.
>
> Regards
> Henrik
>
>

Well, I captured a failed server request. Looks like apache finishes
sending the object, sends a FIN to close the connection, squid acks the
FIN, but never sends its own FIN. 16 seconds later apache sends an RST.

In client_side.c, at the end of onnStateFree there is a block of code
that is ifdefined _SQUID_LINUX_, and is commented:
/* prevent those nasty RST packets */

What is the intent of that block of code, and should there be an
equivalent block of code in httpStateFree in http.c?

I've attached an extract of the access.log which shows the request which
triggered the refresh, my own test request which was delayed by about 15
minutes, and another request off the internet for the same object which
was also delayed.

The curious bit about those access.log entries is that the client which
requested a refresh took 23 minutes to transfer 18KB, and the object it
was retrieving is about 50KB.

When squid is retrieving an object for a client, does it close the
connection with the origin server if the client is still in the process
of retrieving the object from squid?

-- 
Robert Borkowski

12:31:39.818098 10.5.0.123.47505 > 10.5.0.31.80: S 1857612042:1857612042(0) win 5840 <mss 1460,sackOK,timestamp 898222053 0,nop,wscale 0> (DF)
12:31:39.821379 10.5.0.31.80 > 10.5.0.123.47505: S 2576687301:2576687301(0) ack 1857612043 win 5792 <mss 1460,sackOK,timestamp 1075551246 898222053,nop,wscale 0> (DF)
12:31:39.821416 10.5.0.123.47505 > 10.5.0.31.80: . ack 1 win 5840 <nop,nop,timestamp 898222054 1075551246> (DF)
12:31:39.821607 10.5.0.123.47505 > 10.5.0.31.80: P 1:453(452) ack 1 win 5840 <nop,nop,timestamp 898222054 1075551246> (DF)
12:31:39.824444 10.5.0.31.80 > 10.5.0.123.47505: . ack 453 win 6432 <nop,nop,timestamp 1075551246 898222054> (DF)
12:31:40.323088 10.5.0.31.80 > 10.5.0.123.47505: . 1:1449(1448) ack 453 win 6432 <nop,nop,timestamp 1075551296 898222054> (DF)
12:31:40.323133 10.5.0.123.47505 > 10.5.0.31.80: . ack 1449 win 8688 <nop,nop,timestamp 898222104 1075551296> (DF)
12:31:40.323221 10.5.0.31.80 > 10.5.0.123.47505: . 1449:2897(1448) ack 453 win 6432 <nop,nop,timestamp 1075551296 898222054> (DF)
12:31:40.323269 10.5.0.123.47505 > 10.5.0.31.80: . ack 2897 win 11584 <nop,nop,timestamp 898222104 1075551296> (DF)
12:31:40.325017 10.5.0.31.80 > 10.5.0.123.47505: . 2897:4345(1448) ack 453 win 6432 <nop,nop,timestamp 1075551296 898222104> (DF)
12:31:40.325099 10.5.0.123.47505 > 10.5.0.31.80: . ack 4345 win 14480 <nop,nop,timestamp 898222104 1075551296> (DF)
12:31:40.325136 10.5.0.31.80 > 10.5.0.123.47505: . 4345:5793(1448) ack 453 win 6432 <nop,nop,timestamp 1075551296 898222104> (DF)
12:31:40.325214 10.5.0.123.47505 > 10.5.0.31.80: . ack 5793 win 17376 <nop,nop,timestamp 898222104 1075551296> (DF)
12:31:40.325254 10.5.0.31.80 > 10.5.0.123.47505: P 5793:7241(1448) ack 453 win 6432 <nop,nop,timestamp 1075551296 898222104> (DF)
12:31:40.325292 10.5.0.123.47505 > 10.5.0.31.80: . ack 7241 win 20272 <nop,nop,timestamp 898222104 1075551296> (DF)
12:31:40.327409 10.5.0.31.80 > 10.5.0.123.47505: . 7241:8689(1448) ack 453 win 6432 <nop,nop,timestamp 1075551297 898222104> (DF)
12:31:40.327449 10.5.0.123.47505 > 10.5.0.31.80: . ack 8689 win 23168 <nop,nop,timestamp 898222104 1075551297> (DF)
12:31:40.327532 10.5.0.31.80 > 10.5.0.123.47505: . 8689:10137(1448) ack 453 win 6432 <nop,nop,timestamp 1075551297 898222104> (DF)
12:31:40.327556 10.5.0.123.47505 > 10.5.0.31.80: . ack 10137 win 26064 <nop,nop,timestamp 898222104 1075551297> (DF)
12:31:40.327661 10.5.0.31.80 > 10.5.0.123.47505: P 10137:11585(1448) ack 453 win 6432 <nop,nop,timestamp 1075551297 898222104> (DF)
12:31:40.327683 10.5.0.123.47505 > 10.5.0.31.80: . ack 11585 win 28960 <nop,nop,timestamp 898222104 1075551297> (DF)
12:31:40.327784 10.5.0.31.80 > 10.5.0.123.47505: P 11585:13033(1448) ack 453 win 6432 <nop,nop,timestamp 1075551297 898222104> (DF)
12:31:40.327808 10.5.0.123.47505 > 10.5.0.31.80: . ack 13033 win 31856 <nop,nop,timestamp 898222104 1075551297> (DF)
12:31:40.328231 10.5.0.31.80 > 10.5.0.123.47505: . 13033:14481(1448) ack 453 win 6432 <nop,nop,timestamp 1075551297 898222104> (DF)
12:31:40.328285 10.5.0.123.47505 > 10.5.0.31.80: . ack 14481 win 34752 <nop,nop,timestamp 898222104 1075551297> (DF)
12:31:40.328350 10.5.0.31.80 > 10.5.0.123.47505: . 14481:15929(1448) ack 453 win 6432 <nop,nop,timestamp 1075551297 898222104> (DF)
12:31:40.328383 10.5.0.123.47505 > 10.5.0.31.80: . ack 15929 win 37648 <nop,nop,timestamp 898222104 1075551297> (DF)
12:31:40.329664 10.5.0.31.80 > 10.5.0.123.47505: . 15929:17377(1448) ack 453 win 6432 <nop,nop,timestamp 1075551297 898222104> (DF)
12:31:40.329694 10.5.0.123.47505 > 10.5.0.31.80: . ack 17377 win 40544 <nop,nop,timestamp 898222104 1075551297> (DF)
12:31:40.329805 10.5.0.31.80 > 10.5.0.123.47505: P 17377:18825(1448) ack 453 win 6432 <nop,nop,timestamp 1075551297 898222104> (DF)
12:31:40.329850 10.5.0.123.47505 > 10.5.0.31.80: . ack 18825 win 43440 <nop,nop,timestamp 898222104 1075551297> (DF)
12:31:40.330444 10.5.0.31.80 > 10.5.0.123.47505: . 18825:20273(1448) ack 453 win 6432 <nop,nop,timestamp 1075551297 898222104> (DF)
12:31:40.330469 10.5.0.123.47505 > 10.5.0.31.80: . ack 20273 win 46336 <nop,nop,timestamp 898222105 1075551297> (DF)
12:31:40.330470 10.5.0.31.80 > 10.5.0.123.47505: P 20273:20481(208) ack 453 win 6432 <nop,nop,timestamp 1075551297 898222104> (DF)
12:31:40.330499 10.5.0.123.47505 > 10.5.0.31.80: . ack 20481 win 46336 <nop,nop,timestamp 898222105 1075551297> (DF)
12:31:40.330592 10.5.0.31.80 > 10.5.0.123.47505: . 20481:21929(1448) ack 453 win 6432 <nop,nop,timestamp 1075551297 898222104> (DF)
12:31:40.330624 10.5.0.123.47505 > 10.5.0.31.80: . ack 21929 win 49232 <nop,nop,timestamp 898222105 1075551297> (DF)
12:31:40.330722 10.5.0.31.80 > 10.5.0.123.47505: . 21929:23377(1448) ack 453 win 6432 <nop,nop,timestamp 1075551297 898222104> (DF)
12:31:40.330745 10.5.0.123.47505 > 10.5.0.31.80: . ack 23377 win 52128 <nop,nop,timestamp 898222105 1075551297> (DF)
12:31:40.331038 10.5.0.31.80 > 10.5.0.123.47505: . 23377:24825(1448) ack 453 win 6432 <nop,nop,timestamp 1075551297 898222104> (DF)
12:31:40.331066 10.5.0.123.47505 > 10.5.0.31.80: . ack 24825 win 55024 <nop,nop,timestamp 898222105 1075551297> (DF)
12:31:40.331167 10.5.0.31.80 > 10.5.0.123.47505: . 24825:26273(1448) ack 453 win 6432 <nop,nop,timestamp 1075551297 898222104> (DF)
12:31:40.331195 10.5.0.123.47505 > 10.5.0.31.80: . ack 26273 win 57920 <nop,nop,timestamp 898222105 1075551297> (DF)
12:31:40.331295 10.5.0.31.80 > 10.5.0.123.47505: . 26273:27721(1448) ack 453 win 6432 <nop,nop,timestamp 1075551297 898222104> (DF)
12:31:40.331311 10.5.0.123.47505 > 10.5.0.31.80: . ack 27721 win 60816 <nop,nop,timestamp 898222105 1075551297> (DF)
12:31:40.331814 10.5.0.31.80 > 10.5.0.123.47505: . 27721:29169(1448) ack 453 win 6432 <nop,nop,timestamp 1075551297 898222104> (DF)
12:31:40.331839 10.5.0.123.47505 > 10.5.0.31.80: . ack 29169 win 63712 <nop,nop,timestamp 898222105 1075551297> (DF)
12:31:40.332556 10.5.0.31.80 > 10.5.0.123.47505: . 29169:30617(1448) ack 453 win 6432 <nop,nop,timestamp 1075551297 898222104> (DF)
12:31:40.332702 10.5.0.31.80 > 10.5.0.123.47505: . 30617:32065(1448) ack 453 win 6432 <nop,nop,timestamp 1075551297 898222104> (DF)
12:31:40.332824 10.5.0.31.80 > 10.5.0.123.47505: . 32065:33513(1448) ack 453 win 6432 <nop,nop,timestamp 1075551297 898222104> (DF)
12:31:40.332946 10.5.0.31.80 > 10.5.0.123.47505: P 33513:34961(1448) ack 453 win 6432 <nop,nop,timestamp 1075551297 898222104> (DF)
12:31:40.333769 10.5.0.31.80 > 10.5.0.123.47505: . 34961:36409(1448) ack 453 win 6432 <nop,nop,timestamp 1075551297 898222105> (DF)
12:31:40.333813 10.5.0.31.80 > 10.5.0.123.47505: P 36409:36865(456) ack 453 win 6432 <nop,nop,timestamp 1075551297 898222105> (DF)
12:31:40.333982 10.5.0.31.80 > 10.5.0.123.47505: . 36865:38313(1448) ack 453 win 6432 <nop,nop,timestamp 1075551297 898222105> (DF)
12:31:40.334127 10.5.0.31.80 > 10.5.0.123.47505: . 38313:39761(1448) ack 453 win 6432 <nop,nop,timestamp 1075551297 898222105> (DF)
12:31:40.334251 10.5.0.31.80 > 10.5.0.123.47505: . 39761:41209(1448) ack 453 win 6432 <nop,nop,timestamp 1075551297 898222105> (DF)
12:31:40.334375 10.5.0.31.80 > 10.5.0.123.47505: . 41209:42657(1448) ack 453 win 6432 <nop,nop,timestamp 1075551297 898222105> (DF)
12:31:40.334507 10.5.0.31.80 > 10.5.0.123.47505: . 42657:44105(1448) ack 453 win 6432 <nop,nop,timestamp 1075551297 898222105> (DF)
12:31:40.334629 10.5.0.31.80 > 10.5.0.123.47505: . 44105:45553(1448) ack 453 win 6432 <nop,nop,timestamp 1075551297 898222105> (DF)
12:31:40.334752 10.5.0.31.80 > 10.5.0.123.47505: . 45553:47001(1448) ack 453 win 6432 <nop,nop,timestamp 1075551297 898222105> (DF)
12:31:40.335075 10.5.0.31.80 > 10.5.0.123.47505: . 47001:48449(1448) ack 453 win 6432 <nop,nop,timestamp 1075551297 898222105> (DF)
12:31:40.335199 10.5.0.31.80 > 10.5.0.123.47505: . 48449:49897(1448) ack 453 win 6432 <nop,nop,timestamp 1075551297 898222105> (DF)
12:31:40.335236 10.5.0.31.80 > 10.5.0.123.47505: FP 49897:50294(397) ack 453 win 6432 <nop,nop,timestamp 1075551297 898222105> (DF)
12:31:40.369919 10.5.0.123.47505 > 10.5.0.31.80: . ack 50295 win 43440 <nop,nop,timestamp 898222109 1075551297> (DF)
12:31:56.783609 10.5.0.31.80 > 10.5.0.123.47505: R 50295:50295(0) ack 453 win 0

1105552001.015 890805 xx.xxx.167.23 TCP_HIT/200 50146 GET http://xxxxxxxxxxx/ - NONE/- "-" "-" "Wget/1.8.1" "-"
1105552001.015 894696 xx.xx.4.1 TCP_IMS_HIT/200 50145 GET http://xxxxxxxxxxx/ - NONE/- "-" "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; .NET CLR 1.1.4322)" "-"
1105552475.004 1375189 xxx.xx.32.34 TCP_CLIENT_REFRESH_MISS/200 18355 GET http://xxxxxxxxxxx/ - DIRECT/10.5.0.31 "-" "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; .NET CLR 1.1.4322)" "-"
Received on Wed Jan 12 2005 - 16:19:35 MST