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@xxxxxxxxx: > >> 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.