Re: [squid-users] Truncated requests in cache.log

So Henrik,

can we say the problem is inside the proxy (nic, os, squid)? what can we
exclude?

Dario

Henrik Nordstrom-5 wrote:
>
> tor 2009-10-08 klockan 08:10 -0700 skrev dtinazzi_at_gmail.com:
>
>> Here are the access.log related entries, filtered from the others:
>>
>> Thu Oct 8 15:57:25 2009 220 xx.xx.xx.xx TCP_MISS/302 1059 GET
>> http://profile.live.com/connect/?wa=wsignin1.0&sa=XXXXXXXX -
>> DIRECT/64.4.24.246 text/html
>> Thu Oct 8 15:57:28 2009 1 xx.xx.xx.xx TCP_DENIED/400 4095 NONE
>> error:unsupported-request-method - NONE/- text/html
>>
>> And finally the cache.log entry:
>>
>> 2009/10/08 15:57:28| parseHttpRequest: Unsupported method
>> '79.4/connect/?wa=wsignin1.0&sa=XXXXXXXX'
>> 2009/10/08 15:57:28| clientTryParseRequest: FD 24 (xx.xx.xx.xx:13374)
>> Invalid Request
>
> Thanks for your packet capture and relevant log details.
>
> Very odd indeed. It's the first very request on that connection, and do
> start with GET ... at a first glance it looks like the request is fine..
>
> But there is some packet reordering in the packet capture due to the
> first data packet being lost and later retransmitted, and looking closer
> the sequence numbers do not to add up, with the data packets having
> their sequence number shifted a little backwards which explains the
> malformed requests. It's not the request as such which is malformed,
> it's the TCP connection it's sent over which is malformed.
>
> Annotated tcpdump of the client->proxy traffic only:
>
> % tcpdump -r traffic.pcap -S -nn src port 13374
> # Initial SYN
> 15:57:25.852818 IP XX.XX.XX.XX.13374 > YY.YY.YY.YY.3128: S
> 2682058283:2682058283(0) win 65535 <mss 1260,nop,wscale
> 2,nop,nop,timestamp 0 0,nop,nop,sackOK>
> # ACK to the SYN from Squid server
> 15:57:25.853260 IP XX.XX.XX.XX.13374 > YY.YY.YY.YY.3128: . ack 1693416331
> win 36500
> # [here the first data packet is missing]
> # Second data packet
> 15:57:25.855823 IP XX.XX.XX.XX.13374 > YY.YY.YY.YY.3128: .
> 2682059544:2682060804(1260) ack 1693416331 win 36500
> # First data packet retransmitted some seconds later
> 15:57:28.827500 IP XX.XX.XX.XX.13374 > YY.YY.YY.YY.3128: .
> 2682058266:2682059544(1278) ack 1693416331 win 36500
> # Third data packet
> 15:57:28.828277 IP XX.XX.XX.XX.13374 > YY.YY.YY.YY.3128: P
> 2682060804:2682061068(264) ack 1693416331 win 36500
> # Acks of error message from Squid
> 15:57:28.829968 IP XX.XX.XX.XX.13374 > YY.YY.YY.YY.3128: . ack 1693417946
> win 36500
> 15:57:28.832581 IP XX.XX.XX.XX.13374 > YY.YY.YY.YY.3128: . ack 1693420427
> win 36500
> # And all done..
> 15:57:28.844279 IP XX.XX.XX.XX.13374 > YY.YY.YY.YY.3128: F
> 2682061068:2682061068(0) ack 1693420427 win 36500
>
>
> sorting the data packets in expected order and zooming in on the
> sequence numbers:
>
> SYN: 2682058283:2682058283(0)
> 1: 2682058266:2682059544(1278)
> 2: 2682059544:2682060804(1260)
> 3: 2682060804:2682061068(264)
> FIN: 2682061068:2682061068(0)
>
> This does not add up. The sequence number of the first data packet is
> wrong. Should have been 2682058284 (SYN + 1), not 2682058266. That's a
> difference of 18 characters, which also matches exactly what Squid saw..
> Due to the bad sequence numbering the first 18 characters thrown away by
> the server TCP stack and is not given to Squid. Sent with a location 18
> characters before the logical start of the TCP connections.
>
> GET http://94.84.179.4/connect/?wa=wsign...
>
> minus the first 18 gives
>
> 79.4/connect/?wa=wsign...
>
> Honestly it's even surprising the server TCP stack at all accepted the
> traffic. Would have expected it to reject the traffic with a TCP RST
> when seeing the bad sequence number of the first data packet. But maybe
> getting data with sequence numbers before the SYN is so unexpected that
> it doesn't even react on the impossibility of that sequence number.
>
> Regards
> Henrik
>
>
>

-- 
View this message in context: http://www.nabble.com/Truncated-requests-in-cache.log-tp25577796p25818378.html
Sent from the Squid - Users mailing list archive at Nabble.com.