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

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
Received on Thu Oct 08 2009 - 23:35:46 MDT