Re: [squid-users] Squid 3.0rc1 and ICAP: squid quits using ICAP

On Thu, 2007-10-11 at 15:41 -0500, Guy Helmer wrote:

> I am seeing a problem with Squid 3.0rc1 (installed from the FreeBSD
> port) when my icap server implementation responds to an ICAP REQMOD
> request with an HTTP 302 response. This situation seems to work OK with
> Squid 2.6. On Squid 3.0rc1, squid closes the connection to my icap
> server and quits responding to requests from my web browser. In
> ICAPModXact::decideOnParsingBody(), it seems an ICAP response with a
> null-body encapsulation isn't handled (resulting in the "not expecting a
> body" message in the log below); do I need to generate a res-body
> instead, and if so, am I violating an RFC that I should look at?

Guy,

        The problem seems to be outside of the ICAP transaction implementation
itself. Based on your logs, the transaction seems to do the right thing
but something in the core does not like the lack of the response body.

Your HTTP 302 response is violating an RFC 2616 SHOULD (Section 10.3.3):

> Unless the request method was HEAD, the entity of the
> response SHOULD contain a short hypertext note with a hyperlink to
> the new URI(s).

but that violation alone is not a good enough excuse for Squid to fail.

Your ICAP response is kind of violating RFC 2616 rules about message
bodies (Section 4.4), but that is debatable. In HTTP context, the length
of your HTTP message body would be determined by the HTTP server closing
the connection. In ICAP context, there is no HTTP server. Your ICAP
headers tell Squid there is no body but your HTTP headers tell Squid
there should be one...

I am not sure why Squid stops using your ICAP server after the
problematic response. If it stops after a few failures and informs you
that it stopped using the service in cache.log, then you can tweak the
threshold using squid.conf icap_* options. Otherwise, it could be a bug.

I would suggest the following:

        1) File a Squid bug report with the full debugging log (not just
        the ICAP part). If you cannot collect a full debugging log,
        enable full debugging of sections 33,11,17,93 at least. If you
        cannot post the log in the report, email it to me.
        
        2) Add a body or a "Content-Length: 0" header to your embedded
        HTTP 302 response. It may not help with this specific bug, but
        it is the right thing to do for several reasons.
        
        3) Gather more information about Squid not using your ICAP
        server after the failure and file a separate bug report if
        needed.

Thank you,

Alex.

> Here is the ICAP configuration I'm using in squid.conf:
> icap_enable on
> icap_send_client_ip on
> icap_service ca_service reqmod_precache 0 icap://192.168.1.238:1344/ca
> icap_service url_service reqmod_precache 0 icap://192.168.1.238:1344/urls
> icap_class ca_class ca_service
> icap_class url_class url_service
> acl ca_post method POST
> icap_access ca_class allow ca_post
> icap_access url_class allow !ca_post
>
> Here are the debugging log messages from cache.log - after the last
> messages in this log snippet, squid stops responding to my web browser's
> requests:
>
> 2007/10/11 15:26:28.091| ICAPAccessCheck constructed for RESPMOD PRECACHE
> 2007/10/11 15:26:28.091| ICAPAccessCheck::check
> 2007/10/11 15:26:28.091| ICAP/ICAPConfig.cc(277) looking for the first
> matching service in class ca_class
> 2007/10/11 15:26:28.091| ICAP/ICAPConfig.cc(329) found no matching
> services in class ca_class
> 2007/10/11 15:26:28.091| ICAP/ICAPConfig.cc(277) looking for the first
> matching service in class url_class
> 2007/10/11 15:26:28.091| ICAP/ICAPConfig.cc(329) found no matching
> services in class url_class
> 2007/10/11 15:26:28.091| ICAPAccessCheck::check: NO candidates or
> matches found
> 2007/10/11 15:26:28.091| ICAPAccessCheckCallbackWrapper: answer=1
> 2007/10/11 15:26:28.102| ICAPAccessCheckCallbackEvent
> 2007/10/11 15:26:28.103| ICAPAccessCheck::do_callback
> 2007/10/11 15:26:28.103| ICAP/ICAPConfig.cc(266) do_callback: no
> 2007/10/11 15:26:28.216| ICAPAccessCheck constructed for REQMOD PRECACHE
> 2007/10/11 15:26:28.216| ICAPAccessCheck::check
> 2007/10/11 15:26:28.216| ICAP/ICAPConfig.cc(277) looking for the first
> matching service in class ca_class
> 2007/10/11 15:26:28.216| ICAP/ICAPConfig.cc(315) found first matching
> service in class ca_class: ca_service
> 2007/10/11 15:26:28.216| ICAPAccessCheck::check: class 'ca_class' has
> candidate service 'ca_service'
> 2007/10/11 15:26:28.216| ICAP/ICAPConfig.cc(277) looking for the first
> matching service in class url_class
> 2007/10/11 15:26:28.217| ICAPOptions url
> /search?sourceid=navclient-ff&features=Rank&client=navclient-auto-ff&googleip=P;72.14.223.147;1567982&ch=89ff7dc65&q=info:http%3A%2F%2Fwww.networkworld.com%2Fnews%2F2007%2F101007-california-state-site-cant-shake.html%3Fpage%3D2
> matches no Transfer-Preview extensions
> 2007/10/11 15:26:28.217| ICAPOptions url
> /search?sourceid=navclient-ff&features=Rank&client=navclient-auto-ff&googleip=P;72.14.223.147;1567982&ch=89ff7dc65&q=info:http%3A%2F%2Fwww.networkworld.com%2Fnews%2F2007%2F101007-california-state-site-cant-shake.html%3Fpage%3D2
> matches no Transfer-Complete extensions
> 2007/10/11 15:26:28.217| ICAPOptions url
> /search?sourceid=navclient-ff&features=Rank&client=navclient-auto-ff&googleip=P;72.14.223.147;1567982&ch=89ff7dc65&q=info:http%3A%2F%2Fwww.networkworld.com%2Fnews%2F2007%2F101007-california-state-site-cant-shake.html%3Fpage%3D2
> matches no Transfer-Ignore extensions
> 2007/10/11 15:26:28.217| ICAPOptions url
> /search?sourceid=navclient-ff&features=Rank&client=navclient-auto-ff&googleip=P;72.14.223.147;1567982&ch=89ff7dc65&q=info:http%3A%2F%2Fwww.networkworld.com%2Fnews%2F2007%2F101007-california-state-site-cant-shake.html%3Fpage%3D2
> matches no extensions; using default: Transfer-Complete
> 2007/10/11 15:26:28.217| ICAP/ICAPConfig.cc(315) found first matching
> service in class url_class: url_service
> 2007/10/11 15:26:28.217| ICAPAccessCheck::check: class 'url_class' has
> candidate service 'url_service'
> 2007/10/11 15:26:28.217| ICAPAccessCheckCallbackWrapper: answer=0
> 2007/10/11 15:26:28.217| ICAPAccessCheckCallbackWrapper matchedClass =
> ca_class
> 2007/10/11 15:26:28.217| ICAPAccessCheckCallbackWrapper: answer=1
> 2007/10/11 15:26:28.217| ICAPAccessCheckCallbackWrapper matchedClass =
> url_class
> 2007/10/11 15:26:28.228| ICAPAccessCheckCallbackEvent
> 2007/10/11 15:26:28.228| ICAPAccessCheck::do_callback
> 2007/10/11 15:26:28.228| ICAPAccessCheck::do_callback matchedClass =
> url_class
> 2007/10/11 15:26:28.228| ICAP/ICAPConfig.cc(277) looking for the first
> matching up service in class url_class
> 2007/10/11 15:26:28.228| ICAPOptions url
> /search?sourceid=navclient-ff&features=Rank&client=navclient-auto-ff&googleip=P;72.14.223.147;1567982&ch=89ff7dc65&q=info:http%3A%2F%2Fwww.networkworld.com%2Fnews%2F2007%2F101007-california-state-site-cant-shake.html%3Fpage%3D2
> matches no Transfer-Preview extensions
> 2007/10/11 15:26:28.228| ICAPOptions url
> /search?sourceid=navclient-ff&features=Rank&client=navclient-auto-ff&googleip=P;72.14.223.147;1567982&ch=89ff7dc65&q=info:http%3A%2F%2Fwww.networkworld.com%2Fnews%2F2007%2F101007-california-state-site-cant-shake.html%3Fpage%3D2
> matches no Transfer-Complete extensions
> 2007/10/11 15:26:28.228| ICAPOptions url
> /search?sourceid=navclient-ff&features=Rank&client=navclient-auto-ff&googleip=P;72.14.223.147;1567982&ch=89ff7dc65&q=info:http%3A%2F%2Fwww.networkworld.com%2Fnews%2F2007%2F101007-california-state-site-cant-shake.html%3Fpage%3D2
> matches no Transfer-Ignore extensions
> 2007/10/11 15:26:28.228| ICAPOptions url
> /search?sourceid=navclient-ff&features=Rank&client=navclient-auto-ff&googleip=P;72.14.223.147;1567982&ch=89ff7dc65&q=info:http%3A%2F%2Fwww.networkworld.com%2Fnews%2F2007%2F101007-california-state-site-cant-shake.html%3Fpage%3D2
> matches no extensions; using default: Transfer-Complete
> 2007/10/11 15:26:28.228| ICAP/ICAPConfig.cc(315) found first matching up
> service in class url_class: url_service
> 2007/10/11 15:26:28.228| ICAP/ICAPConfig.cc(262) do_callback: with
> service icap://192.168.1.238:1344/urls
> 2007/10/11 15:26:28.229| client_side_request.cc(504) 0x80275d298
> icapAclCheckDone called
> 2007/10/11 15:26:28.229| ICAP/AsyncJob.cc(14) will call
> AsyncJob::noteStart(0x8027ab098)
> 2007/10/11 15:26:28.240| entering AsyncJob::noteStart(0x8027ab098)
> 2007/10/11 15:26:28.241| ICAPModXactLauncher::noteStart called
> 2007/10/11 15:26:28.241| ICAP/ICAPLauncher.cc(35) launching xaction #1
> 2007/10/11 15:26:28.241| ICAPModXact constructed, this=0x8027af188
> [icapx314]
> 2007/10/11 15:26:28.241| ICAPModXact initialized. [/R icapx314]
> 2007/10/11 15:26:28.241| ICAP/AsyncJob.cc(14) will call
> AsyncJob::noteStart(0x8027af188)
> 2007/10/11 15:26:28.242| ICAPModXactLauncher::noteStart ended
> 2007/10/11 15:26:28.242| exiting AsyncJob::noteStart(0x8027ab098)
> 2007/10/11 15:26:28.253| entering AsyncJob::noteStart(0x8027af188)
> 2007/10/11 15:26:28.254| ICAPModXact::noteStart called [/R icapx314]
> 2007/10/11 15:26:28.255| ICAPModXact does not expect virgin body
> 2007/10/11 15:26:28.255| ICAPModXact should not offer preview for
> /search?sourceid=navclient-ff&features=Rank&client=navclient-auto-ff&googleip=P;72.14.223.147;1567982&ch=89ff7dc65&q=info:http%3A%2F%2Fwww.networkworld.com%2Fnews%2F2007%2F101007-california-state-site-cant-shake.html%3Fpage%3D2
> 2007/10/11 15:26:28.255| ICAP/ICAPXaction.cc(113) reused pconn FD 18
> 2007/10/11 15:26:28.255| ICAPModXact::noteStart ended [FD 18;rw(1)/R
> icapx314]
> 2007/10/11 15:26:28.255| exiting AsyncJob::noteStart(0x8027af188)
> 2007/10/11 15:26:28.266| ICAPXaction::reusedConnection
> 2007/10/11 15:26:28.267| ICAPModXact::noteCommConnected called [FD
> 18;rw(1)/R icapx314]
> 2007/10/11 15:26:28.267| ICAP/ICAPModXact.cc(1135) will allow 204s
> outside of preview
> 2007/10/11 15:26:28.268| ICAPModXact::noteCommConnected ended [FD
> 18wr;rw(2)/R icapx314]
> 2007/10/11 15:26:28.268| ICAPModXact::noteCommWrote called [FD
> 18wr;rw(2)/R icapx314]
> 2007/10/11 15:26:28.268| ICAP/ICAPModXact.cc(154) Wrote 1546 bytes
> 2007/10/11 15:26:28.268| ICAP/ICAPModXact.cc(434) will no longer write
> [FD 18r;rw(2)/R icapx314]
> 2007/10/11 15:26:28.268| ICAPModXact::noteCommWrote ended [FD 18r;r/Rw
> icapx314]
> 2007/10/11 15:26:28.269| ICAP/ICAPXaction.cc(59) 0x8027af188 read
> returned 623
> 2007/10/11 15:26:28.269| ICAPModXact::noteCommRead called [FD 18r;r/Rw
> icapx314]
> 2007/10/11 15:26:28.269| ICAP/ICAPXaction.cc(339) read 623 bytes
> 2007/10/11 15:26:28.269| ICAPModXact becomes final [FD 18;r/Rw icapx314]
> 2007/10/11 15:26:28.269| ICAP/ICAPModXact.cc(574) have 623 bytes to
> parse [FD 18;r/Rw icapx314]
> 2007/10/11 15:26:28.269| ICAP/ICAPModXact.cc(575)
> ICAP/1.0 200 OK
> Date: Thu, 11 Oct 2007 20:26:28 GMT
> Encapsulated: res-hdr=0, null-body=473
> Service: Palisade Systems PacketSure ICAP Server 1.0
>
> HTTP/1.1 302 Moved
> Location:
> http://www.palisadesys.com/block-ps.html?type=URL&desc=Category%3DSearchEngines
> Server: Palisade Systems PacketSure ICAP Server 1.0
> Date: Thu, 11 Oct 2007 20:26:28 GMT
> Referer:
> http://toolbarqueries.google.com/search?sourceid=navclient-ff&features=Rank&client=navclient-auto-ff&googleip=P;72.14.223.147;1567982&ch=89ff7dc65&q=info:http%3A%2F%2Fwww.networkworld.com%2Fnews%2F2007%2F101007-california-state-site-cant-shake.html%3Fpage%3D2
>
>
> 2007/10/11 15:26:28.269| ICAP/ICAPModXact.cc(653) parse ICAP headers
> 2007/10/11 15:26:28.269| ICAP/ICAPModXact.cc(882) have 623 head bytes to
> parse; state: 0
> 2007/10/11 15:26:28.270| ICAP/ICAPModXact.cc(894) parse success, consume
> 150 bytes, return true
> 2007/10/11 15:26:28.270| ICAP/ICAPModXact.cc(658) parse HTTP headers
> 2007/10/11 15:26:28.270| ICAP/ICAPModXact.cc(882) have 473 head bytes to
> parse; state: 1
> 2007/10/11 15:26:28.270| ICAP/ICAPModXact.cc(894) parse success, consume
> 473 bytes, return true
> 2007/10/11 15:26:28.270| ICAP/ICAPModXact.cc(926) not expecting a body
> 2007/10/11 15:26:28.270| ICAPModXact will no longer parse [FD
> 18;rp(1)S(2)/Rw icapx314]
> 2007/10/11 15:26:28.270| ICAPModXact will no longer send [FD
> 18;S(2)/Rwrp icapx314]
> 2007/10/11 15:26:28.270| ICAP/ICAPInitiate.cc(176) will call
> 0x8027ab0d0->ICAPInitiator::noteIcapAnswer(0x8029f4f20)
> 2007/10/11 15:26:28.270| ICAP/ICAPModXact.cc(474) returning from
> readMore because reader or doneReading()
> 2007/10/11 15:26:28.270| ICAP/ICAPXaction.cc(285) ICAPModXact done with
> I/O [FD 18;/RwrpS icapx314]
> 2007/10/11 15:26:28.270| ICAP/ICAPXaction.cc(174) pushing pconn [FD
> 18;/RwrpS icapx314]
> 2007/10/11 15:26:28.270| ICAPModXact remains final [FD 18;/RwrpS icapx314]
> 2007/10/11 15:26:28.270| ICAPModXact::noteCommRead ends job [/RwrpS
> icapx314]
> 2007/10/11 15:26:28.270| ICAP/ICAPModXact.cc(1062) swan sings [/RwrpS
> icapx314]
> 2007/10/11 15:26:28.271| ICAP/ICAPInitiate.cc(82) swan sings [/RwrpS
> icapx314]
> 2007/10/11 15:26:28.271| ICAP/ICAPInitiate.cc(89) swan sang [/RwrpS
> icapx314]
> 2007/10/11 15:26:28.271| ICAPModXact destructed, this=0x8027af188 [icapx314]
> 2007/10/11 15:26:28.271| ICAP/AsyncJob.cc(106) ICAPModXact::noteCommRead
> ended 0x8027af188
> 2007/10/11 15:26:28.282| entering
> 0x8027ab0d0->ICAPInitiator::noteIcapAnswer(0x8029f4f20)
> 2007/10/11 15:26:28.282| ICAPModXactLauncher::noteIcapAnswer called
> 2007/10/11 15:26:28.282| ICAP/ICAPInitiate.cc(176) will call
> 0x802703218->ICAPInitiator::noteIcapAnswer(0x8029f4f20)
> 2007/10/11 15:26:28.282| ICAPModXactLauncher::noteIcapAnswer ends job
> 2007/10/11 15:26:28.282| ICAP/ICAPInitiate.cc(82) swan sings
> 2007/10/11 15:26:28.282| ICAP/ICAPInitiate.cc(89) swan sang
> 2007/10/11 15:26:28.282| ICAP/AsyncJob.cc(106)
> ICAPModXactLauncher::noteIcapAnswer ended 0x8027ab098
> 2007/10/11 15:26:28.282| exiting
> 0x8027ab0d0->ICAPInitiator::noteIcapAnswer(0x8029f4f20)
> 2007/10/11 15:26:28.293| entering
> 0x802703218->ICAPInitiator::noteIcapAnswer(0x8029f4f20)
> 2007/10/11 15:26:28.294| exiting
> 0x802703218->ICAPInitiator::noteIcapAnswer(0x8029f4f20)
>
Received on Fri Oct 12 2007 - 10:33:16 MDT