Re: [squid-users] 2.7.Stable6 httpReadReply: Excess data

On Tue, 16 Jun 2009 15:25:05 -0700 (PDT), Quin Guin <quinguin_at_yahoo.com>
wrote:
> Hi,
>
> I am in the need of some assistance in looking into a high number of
> "httpReadReply: Excess data " entries around 3000 cache.log entries per
> day per SQUID server. The httpReadReply: Excess data from "GET
> http://xxxxxx" this is happening on many sites from my reading it is in
> most cases it is an issue with the content site/server.

The server supplying Squid dis one of two things:

1) sent a request/reply with Content-Length: N, then pushed more than N
bytes of data into Squid.

2) sent a request/reply with unknown Content-Length: followed some time
later by the HTTP byte sequence for end-of-object. Which was in turn
followed by even more bytes of data.

Both of these are an old signs of malware overflow attacks. Squid will
respond by unconditionally closing the link to that server.

> I am a bit
> concerned that Is this a sign of of memory or disk issue because from
the
> cache manager things look to be running well. I also do see some other
> errors and I have included the below with more information on my setup.
> The "urlParse: Illegal character in hostname
> 'www.google-%20analytics.com'" is just annoying adn if anyone has away
to
> fix it beside blocking it I would appreciate any ideas on that.

This is another issue, possibly the cause of the above. The HTTP headers
being received by squid are mangled beyond repair. The client sending the
request is severely broken.

If possible please get a binary dump of the stream going into squid. NP:
tcpdump requires -s65535 option to grab it all. From that you should be
able to see exactly how the headers are broken.

>
> I am starting to see latency and I have a 3 node cluster of SQUID
servers
> setup as standard reverse proxies.

Latency is kind of to be expected of many connections are failing with
these errors and being aborted incomplete.

>
> Cache.log entries:
>
> 2009/06/16 21:21:43| httpReadReply: Excess data from "GET
> http://www.myyearbook.com/apps/home"
> 2009/06/16 21:22:03| clientTryParseRequest: FD 14 (10.22.0.64:40881)
> Invalid Request
> 2009/06/16 21:22:04| clientTryParseRequest: FD 49 (10.22.0.63:40894)
> Invalid Request
> 2009/06/16 21:22:06| clientTryParseRequest: FD 36 (10.22.0.63:40938)
> Invalid Request
> 2009/06/16 21:22:21| clientTryParseRequest: FD 290 (10.22.0.65:41114)
> Invalid Request
> 2009/06/16 21:22:21| clientTryParseRequest: FD 415 (10.22.0.65:41124)
> Invalid Request
> 2009/06/16 21:22:22| clientTryParseRequest: FD 361 (10.22.0.63:41168)
> Invalid Request
> 2009/06/16 21:22:35| clientTryParseRequest: FD 109 (10.22.0.64:41418)
> Invalid Request
> 2009/06/16 21:22:35| clientTryParseRequest: FD 129 (10.22.0.63:41431)
> Invalid Request
> 2009/06/16 21:22:36| clientTryParseRequest: FD 477 (10.22.0.65:41458)
> Invalid Request
> 2009/06/16 21:22:50| clientTryParseRequest: FD 356 (10.22.0.63:41707)
> Invalid Request
> 2009/06/16 21:22:51| clientTryParseRequest: FD 180 (10.22.0.64:41719)
> Invalid Request
> 2009/06/16 21:22:51| clientTryParseRequest: FD 197 (10.22.0.63:41744)
> Invalid Request
> 2009/06/16 21:23:01| clientTryParseRequest: FD 49 (10.22.0.64:41875)
> Invalid Request
> 2009/06/16 21:23:01| clientTryParseRequest: FD 104 (10.22.0.63:41887)
> Invalid Request
> 2009/06/16 21:23:02| clientTryParseRequest: FD 399 (10.22.0.64:41921)
> Invalid Request
> 2009/06/16 21:23:03| httpReadReply: Excess data from "GET
> http://www.myyearbook.com/apps/home"
> 2009/06/16 21:23:04| httpReadReply: Excess data from "GET
> http://www.myyearbook.com/apps/home"
> 2009/06/16 21:23:21| clientTryParseRequest: FD 117 (10.22.0.63:42346)
> Invalid Request
> 2009/06/16 21:23:21| clientTryParseRequest: FD 457 (10.22.0.65:42394)
> Invalid Request
> 2009/06/16 21:23:22| clientTryParseRequest: FD 328 (10.22.0.63:42458)
> Invalid Request
> 2009/06/16 21:23:23| urlParse: Illegal character in hostname
> 'www.google-%20analytics.com'

Hint: %20 (aka whitespace) is not a part of the google domain name.

> 2009/06/16 21:23:25| httpReadReply: Excess data from "GET
>
http://sugg.search.yahoo.net/sg/?output=fxjsonp&nresults=10&command=horny%20granies"
> 2009/06/16 21:23:45| clientTryParseRequest: FD 544 (10.22.0.65:42839)
> Invalid Request
> 2009/06/16 21:23:46| clientTryParseRequest: FD 228 (10.22.0.64:42852)
> Invalid Request
> 2009/06/16 21:23:47| clientTryParseRequest: FD 54 (10.22.0.64:42874)
> Invalid Request
> 2009/06/16 21:23:49| urlParse: Illegal character in hostname
> 'www.google-%20analytics.com'
> 2009/06/16 21:24:03| clientTryParseRequest: FD 35 (10.22.0.63:43094)
> Invalid Request
>
> Squid Cache: Version 2.7.STABLE6-20090511
> configure options: '--prefix=/usr/local/squid-2.7.STABLE6-20090511'
> '--enable-epoll' '--with-pthreads' '--enable-snmp'
> '--enable-storeio=ufs,aufs,coss' '-with-large-files'
> '--enable-large-cache-files' '--enable-follow-x-forwarded-for'
> '--with-maxfd=16384' '--disable-dependency-tracking'
> '--disable-ident-lookups' '--enable-removal-policies=heap,lru'
> '--disable-wccp' 'CFLAGS=-fPIE -Os -g -pipe -fsigned-char -O2 -g -pipe
> -m64' 'LDFLAGS=-pie'
>
>
> Connection information for squid:
> Number of clients accessing cache: 9
> Number of HTTP requests received: 431867579
> Number of ICP messages received: 0
> Number of ICP messages sent: 0
> Number of queued ICP replies: 0
> Request failure ratio: 0.00
> Average HTTP requests per minute since start: 14133.0
> Average ICP messages per minute since start: 0.0
> Select loop called: 1303826448 times, 1.406 ms avg
> Cache information for squid:
> Request Hit Ratios: 5min: 59.2%, 60min: 60.8%
> Byte Hit Ratios: 5min: 65.7%, 60min: 65.5%
> Request Memory Hit Ratios: 5min: 27.0%, 60min: 26.9%
> Request Disk Hit Ratios: 5min: 61.1%, 60min: 61.4%
> Storage Swap size: 207997068 KB
> Storage Mem size: 262592 KB
> Mean Object Size: 19.94 KB
> Requests given to unlinkd: 0
> Median Service Times (seconds) 5 min 60 min:
> HTTP Requests (All): 0.01745 0.01469
> Cache Misses: 0.10281 0.10857
> Cache Hits: 0.00000 0.00000
> Near Hits: 0.07825 0.08729
> Not-Modified Replies: 0.00000 0.00000
> DNS Lookups: 0.00000 0.00000
> ICP Queries: 0.00000 0.00000
> Resource usage for squid:
> UP Time: 1833447.687 seconds
> CPU Time: 183352.730 seconds
> CPU Usage: 10.00%
> CPU Usage, 5 minute avg: 14.15%
> CPU Usage, 60 minute avg: 13.85%
>
>
> Thanks,
>
> Quin

HTH
Amos
Received on Wed Jun 17 2009 - 00:48:33 MDT