[squid-users] parseHttpRequest/urlParse/failure ratio/hit-only-mode errors

From: Darren Spruell <[email protected]>
Date: Mon, 12 Apr 2004 12:19:47 -0600

Hi,

We maintain a pair of squid-2.5.STABLE4 caches on Gentoo Linux. They are
identical in configuration and have been installed from Gentoo's Portage
tree. We brought them up one at a time, the first one about 3 weeks ago,
the second one about a week ago. Currently we have services failed over
to the first one exclusively because of problems that happen when the
second server is activated.

We are using squidGuard-1.2.0-r1 (also from Portage) for our
redirect_program and use it to block access to sites that are not on a
whitelist that we maintain. For sites that don't match, the users are
redirected to a simple HTTP error page on the 1st server. We run 'squid
-k reconfigure' every hour to reload this list of whitelist sites.

It seems that every hour when we reload the cache, that error conditions
occur on this second proxy. Here are entries from cache.log during one
such occurance:

2004/04/10 13:01:01| Restarting Squid Cache (version 2.5.STABLE4)...
2004/04/10 13:01:01| FD 31 Closing HTTP connection
2004/04/10 13:01:01| FD 32 Closing ICP connection
2004/04/10 13:01:01| FD 38 Closing SNMP socket
2004/04/10 13:01:01| Closing unlinkd pipe on FD 33
2004/04/10 13:01:01| User-Agent logging is disabled.
2004/04/10 13:01:01| Referer logging is disabled.
2004/04/10 13:01:01| DNS Socket created at 0.0.0.0, port 32854, FD 6
2004/04/10 13:01:01| Adding nameserver 127.0.0.1 from /etc/resolv.conf
2004/04/10 13:01:01| Adding nameserver 10.5.1.11 from /etc/resolv.conf
2004/04/10 13:01:01| helperOpenServers: Starting 20 'squidGuard' processes
2004/04/10 13:01:01| Unlinkd pipe opened on FD 33
2004/04/10 13:01:01| Accepting HTTP connections at 0.0.0.0, port 8080,
FD 31.
2004/04/10 13:01:01| Accepting ICP messages at 0.0.0.0, port 3130, FD 32.
2004/04/10 13:01:01| HTCP Disabled.
2004/04/10 13:01:01| Accepting SNMP messages on port 3401, FD 38.
2004/04/10 13:01:01| WCCP Disabled.
2004/04/10 13:01:01| Configuring Sibling 10.5.1.11/8080/3130
2004/04/10 13:01:01| Loaded Icons.
2004/04/10 13:01:01| Ready to serve requests.
2004/04/10 13:01:18| Failure Ratio at 1.01
2004/04/10 13:01:18| Going into hit-only-mode for 5 minutes...
2004/04/10 13:04:23| urlParse: Illegal character in hostname
'<html><head><title>deniedbyproxy</title></head>'
2004/04/10 13:04:23| urlParse: Illegal character in hostname
'<html><head><title>deniedbyproxy</title></head>'
2004/04/10 13:04:24| urlParse: Illegal character in hostname
'<html><head><title>deniedbyproxy</title></head>'
2004/04/10 13:04:25| urlParse: Illegal character in hostname
'<html><head><title>deniedbyproxy</title></head>'
2004/04/10 13:04:25| urlParse: Illegal character in hostname
'<html><head><title>deniedbyproxy</title></head>'
[...]

As this is happening, the users on this proxy begin to see pages
suddenly redirected to the whitelist error page - the one they are
redirected to when the site they are requesting is not on the whitelist.
This starts to appear for *any* page they visit, even the allowed sites.

Shortly after this happens, the cache shuts down and reloads itself:

2004/04/10 13:11:18| Failure Ratio at 2.83
2004/04/10 13:11:18| Going into hit-only-mode for 5 minutes...
2004/04/10 13:16:18| Failure Ratio at 2.44
2004/04/10 13:16:18| Going into hit-only-mode for 5 minutes...
2004/04/10 13:21:18| Failure Ratio at 1.47
2004/04/10 13:21:18| Going into hit-only-mode for 5 minutes...
2004/04/10 13:25:10| Preparing for shutdown after 302834 requests
[...]
2004/04/10 13:25:42| Squid Cache (Version 2.5.STABLE4): Exiting normally.
2004/04/10 13:25:44| Starting Squid Cache version 2.5.STABLE4 for
i686-pc-linux-gnu...
2004/04/10 13:25:44| Process ID 16189
2004/04/10 13:25:44| With 1024 file descriptors available

Another error we've seen is this (immediately after another reload):

2004/04/10 15:01:01| Ready to serve requests.
2004/04/10 15:01:03| parseHttpRequest: Unsupported method 'Pragma:'
2004/04/10 15:01:03| clientReadRequest: FD 69 Invalid Request
2004/04/10 15:01:05| parseHttpRequest: Unsupported method 'Pragma:'
2004/04/10 15:01:05| clientReadRequest: FD 58 Invalid Request
2004/04/10 15:01:07| parseHttpRequest: Unsupported method 'Pragma:'
2004/04/10 15:01:07| clientReadRequest: FD 42 Invalid Request

It's almost as if clients are passing HTML instead of URLs as the request.

So we're now left stumped as to what might cause this. It seems that in
our troubleshooting we found that if we restart the cache it will run
fine again until the next reload. Between the functioning and
non-functioning servers, the squid.conf files are identical, as are the
squidGuard.conf files. The only immediate difference I can see is that
when diffing the squidGuard .db files, they show up slightly different.
I suspected initially that they just may be different because they are
compiled binary files and the machines might make them differently.

We do suspect that the number of file descriptors (1024) is too small
for this cache's load and would like to set it higher. Might this cause
the errors we are seeing?

More detailed logs are available at the following URL:

http://ganymede.sento.com/squidlogs/cache.log

-- 
Darren Spruell
Received on Mon Apr 12 2004 - 11:26:22 MDT

This archive was generated by hypermail pre-2.1.9 : Fri Apr 30 2004 - 12:00:02 MDT