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
