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?
Thanks in advance for any help,
Guy Helmer
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)
