Re: [squid-users] Leaking ICAP connections

On Mon, 18 Oct 2010, Amos Jeffries wrote:

> Sounds a lot to me like some rare response from ICAP which confuses Squid
> about the reply size.

This is possible. Although shouldn't Squid time out ICAP requests (and
close the connection) if the response takes too long to complete?

> Or a persistent connection race leaking FD.

By "persistent connection race" you mean the ICAP server closing the
connection when squid is trying to use it? This is definately not what is
happenning - my ICAP server never tries to close the connection
(http://bugs.squid-cache.org/show_bug.cgi?id=2980 suggests it would be
unsafe to try and do so) and the connections are still in the established
state (according to both netstat and the ICAP server itself). It seems as
though Squid just decides to stop using the connection but doesn't
actually shut it down.

Unfortunately I'm way too unfamiliar with the internal structure of squid
to attach a debugger to the process and look to see what it thinks the
ICAP connections are doing.

> Pity it's so rare, the fix is likely to require a trace of the ICAP
> server response headers.

This is possibly something I can help with. I added debugging code to the
ICAP server to maintain a short in-memory buffer of the last few data
written to the socket so that I could attach gdb to the process and dump
it.

The result was:
ICAP/1.0 204 No modifications needed\r\nDate: Thu, 23 Sep 2010 08:56:37
+0000\r\nService: Iceni Webfilter\r\nISTag:
SHA1:dff441bfae699b4007b3c5f29ab\r\nEncapsulated:
null-body=0\r\n\r\nICAP/1.0 204 No modifications needed\r\nDate: Thu, 23
Sep 2010 08:56:37 +0000\r\nService: Iceni Webfilter\r\nISTag:
SHA1:dff441bfae699b4007b3c5f29ab\r\nEncapsulated:
null-body=0\r\n\r\nICAP/1.0 204 No modifications needed\r\nDate: Thu, 23
Sep 2010 08:56:37 +0000\r\nService: Iceni Webfilter\r\nISTag:
SHA1:dff441bfae699b4007b3c5f29ab\r\nEncapsulated:
null-body=0\r\n\r\nICAP/1.0 204 No modifications needed\r\nDate: Thu, 23
Sep 2010 08:56:37 +0000\r\nService: Iceni Webfilter\r\nISTag:
SHA1:dff441bfae699b4007b3c5f29ab\r\nEncapsulated:
null-body=0\r\n\r\nICAP/1.0 204 No modifications needed\r\nDate: Thu, 23
Sep 2010 08:56:38 +0000\r\nService: Iceni Webfilter\r\nISTag:
SHA1:dff441bfae699b4007b3c5f29ab\r\nEncapsulated:
null-body=0\r\n\r\nICAP/1.0 204 No modifications needed\r\nDate: Thu, 23
Sep 2010 08:56:38 +0000\r\nService: Iceni Webfilter\r\nISTag:
SHA1:dff441bfae699b4007b3c5f29ab\r\nEncapsulated:
null-body=0\r\n\r\nICAP/1.0 204 No modifications needed\r\nDate: Thu, 23
Sep 2010 08:56:38 +0000\r\nService: Iceni Webfilter\r\nISTag:
SHA1:dff441bfae699b4007b3c5f29ab\r\nEncapsulated: null-body=0\r\n\r\n

I can't see anything wrong with these headers. The last chunk of data
received by the ICAP server was:

f0\r\n\304\324\315\216\2330\020\000\340\373>\005\227%\255\224%\343?\fTho}\200\366\330V\025\204\t\270\313\217\vN\233\250\332w\257\215vW!\240H\221\252f\016\366`\214\261?\214\217"\370\204?\3678\230\340\363\266W\332\004][wY\361nEh$(\243$\226R\362\325\372\316\263\361\'\307]\327c\3421X{\331\316`\237x\241\313U\223\2258$\336\227\261\333\330\325{K]T=\356\022o\365us\314\332b\300\254\337V\217X\244\3047x0i\331e\346\236B\327\332"WO\350\017\346\2501\035\306a}\325\224\337\367}\235\252!\320\252}r\035\202m\327\334\323\217\272\352LgkJ\200\330\252\301\302\225:\327j\353\232\200\210\340\207.\375A\017\312`Z\366\231\252\'C\370:e\360\262\266\327\260o\262\023\255\214\321\311f\243\032\376`\366y\340f\215\r\n0\r\n\r\n

This looks like the end of a correctly terminated ICAP request, but there
isn't much more I can tell from it.

I will attempt to capture further data

-- 
  - Steve
    xmpp:steve@nexusuk.org   sip:steve@nexusuk.org   http://www.nexusuk.org/
      Servatis a periculum, servatis a maleficum - Whisper, Evanescence