Hello Amos and squid test or trunk readers, I hate to keep banging on this issue but from the squid wiki I have learned how to turn on the squid selective debug_options: (1,6 3,6 93,6). I now have much more manageable debug logging but I still don't understand everything. It appears squid is talking to the ICAP server but it also appears the issue is with the ICAP server and not with Squid. I have the simplest ICAP service vector defined (echo). The debug output appears below somewhat lengthy but I'm not experienced enough to truncate the output without loss of information. Clearly, Squid discovers the target ICAP service but both the ICAP logs (not included) and the Squid logs state the target service is not available. Yet, if I use the ICAP client the service clearly is available. Since I have squid built from the source is there any opportunity to study that part of the squid (dot).c source files that are communicating with the ICAP surver in an attempt to see what the ICA
P server is not getting to reply with the right service from ICAP? Any and all suggestions welcomed. 8) David.
**********************************************************************
2009/02/21 11:41:28| Accepting transparently proxied HTTP connections at 0.0.0.0, port 3128, FD 19.
2009/02/21 11:41:28| Ready to serve requests.
2009/02/21 11:41:37.740| ICAPAccessCheck constructed for REQMOD PRECACHE
2009/02/21 11:41:37.740| ICAPAccessCheck::check
2009/02/21 11:41:37.740| ICAP/ICAPConfig.cc(318) found first matching service in class class_echo: service_echo
2009/02/21 11:41:37.740| ICAPAccessCheck::check: class 'class_echo' has candidate service 'service_echo'
2009/02/21 11:41:37.740| ICAPAccessCheckCallbackWrapper: answer=1
2009/02/21 11:41:37.740| ICAPAccessCheckCallbackWrapper matchedClass = class_echo
2009/02/21 11:41:37.748| ICAPAccessCheckCallbackEvent
2009/02/21 11:41:37.748| ICAPAccessCheck::do_callback
2009/02/21 11:41:37.748| ICAPAccessCheck::do_callback matchedClass = class_echo
2009/02/21 11:41:37.748| ICAP/ICAPConfig.cc(311) cannot skip an essential down service
2009/02/21 11:41:37.748| ICAP/ICAPConfig.cc(318) found first matching down-but-essential service in class class_echo: service_echo
2009/02/21 11:41:37.748| ICAP/ICAPConfig.cc(265) do_callback: with service icap://192.168.1.1:1344/srv_echo
2009/02/21 11:41:37.748| client_side_request.cc(504) 0x9228b98 icapAclCheckDone called
2009/02/21 11:41:37.749| ICAP/AsyncJob.cc(14) will call AsyncJob::noteStart(0x9234fc8)
2009/02/21 11:41:37.760| entering AsyncJob::noteStart(0x9234fc8)
2009/02/21 11:41:37.760| ICAPModXactLauncher::noteStart called
2009/02/21 11:41:37.760| ICAP/ICAPLauncher.cc(35) launching xaction #1
2009/02/21 11:41:37.760| ICAPModXact constructed, this=0x92390c8 [icapx1]
2009/02/21 11:41:37.760| ICAP/AsyncJob.cc(14) will call AsyncJob::noteStart(0x92390c8)
2009/02/21 11:41:37.760| ICAPModXactLauncher::noteStart ended
2009/02/21 11:41:37.760| exiting AsyncJob::noteStart(0x9234fc8)
2009/02/21 11:41:37.772| entering AsyncJob::noteStart(0x92390c8)
2009/02/21 11:41:37.772| ICAPModXact::noteStart called [R/ icapx1]
2009/02/21 11:41:37.772| ICAPModXact expects virgin body from 0x9224a98*3; size: 118
2009/02/21 11:41:37.772| ICAP/ICAPServiceRep.cc(308) ICAPService is asked to call 0x92390c8 when ready [down,!opt]
2009/02/21 11:41:37.772| ICAPService will get new options [down,!opt]
2009/02/21 11:41:37.773| ICAP/AsyncJob.cc(14) will call AsyncJob::noteStart(0x923d298)
2009/02/21 11:41:37.773| ICAPModXact::noteStart ended [UR/ icapx1]
2009/02/21 11:41:37.773| exiting AsyncJob::noteStart(0x92390c8)
2009/02/21 11:41:37.784| ICAPModXact::noteMoreBodyDataAvailable called [UR/ icapx1]
2009/02/21 11:41:37.784| ICAP/ICAPModXact.cc(182) checking whether to write more [UR/ icapx1]
2009/02/21 11:41:37.784| ICAPModXact::noteMoreBodyDataAvailable ended [UR/ icapx1]
2009/02/21 11:41:37.784| ICAPModXact::noteBodyProductionEnded called [UR/ icapx1]
2009/02/21 11:41:37.784| ICAP/ICAPModXact.cc(182) checking whether to write more [UR/ icapx1]
2009/02/21 11:41:37.784| ICAPModXact::noteBodyProductionEnded ended [UR/ icapx1]
2009/02/21 11:41:37.784| entering AsyncJob::noteStart(0x923d298)
2009/02/21 11:41:37.784| ICAPOptXactLauncher::noteStart called
2009/02/21 11:41:37.784| ICAP/ICAPLauncher.cc(35) launching xaction #1
2009/02/21 11:41:37.785| ICAPOptXact constructed, this=0x92413a8 [icapx2]
2009/02/21 11:41:37.785| ICAP/AsyncJob.cc(14) will call AsyncJob::noteStart(0x92413a8)
2009/02/21 11:41:37.785| ICAPOptXactLauncher::noteStart ended
2009/02/21 11:41:37.785| exiting AsyncJob::noteStart(0x923d298)
2009/02/21 11:41:37.796| entering AsyncJob::noteStart(0x92413a8)
2009/02/21 11:41:37.796| ICAPOptXact::noteStart called [/ icapx2]
2009/02/21 11:41:37.796| ICAPOptXact becomes final [/ icapx2]
2009/02/21 11:41:37.796| ICAPOptXact opens connection to 192.168.1.1:1344
2009/02/21 11:41:37.797| ICAPOptXact::noteStart ended [FD 21;/ icapx2]
2009/02/21 11:41:37.797| exiting AsyncJob::noteStart(0x92413a8)
2009/02/21 11:41:37.797| ICAPOptXact::noteCommConnected called [FD 21;/ icapx2]
2009/02/21 11:41:37.797| ICAPOptXact::noteCommConnected ended [FD 21wr;/ icapx2]
2009/02/21 11:41:37.797| ICAPOptXact::noteCommWrote called [FD 21wr;/ icapx2]
2009/02/21 11:41:37.797| ICAPOptXact::noteCommWrote ended [FD 21r;/ icapx2]
2009/02/21 11:41:37.797| ICAP/ICAPXaction.cc(59) 0x92413a8 read returned 34
2009/02/21 11:41:37.797| ICAPOptXact::noteCommRead called [FD 21r;/ icapx2]
2009/02/21 11:41:37.797| ICAP/ICAPXaction.cc(339) read 34 bytes
2009/02/21 11:41:37.797| ICAPOptXact remains final [FD 21;/ icapx2]
2009/02/21 11:41:37.797| ICAP/ICAPOptXact.cc(71) have 34 bytes to parse [FD 21;/ icapx2]
2009/02/21 11:41:37.797| ICAP/ICAPOptXact.cc(72)
ICAP/1.0 404 Service not found
2009/02/21 11:41:37.797| ICAP/ICAPXaction.cc(377) have 34 head bytes to parse
2009/02/21 11:41:37.797| ICAP/ICAPInitiate.cc(176) will call 0x923d2b4->ICAPInitiator::noteIcapAnswer(0x91c48b8)
2009/02/21 11:41:37.797| ICAPOptXact::noteCommRead ends job [FD 21;/ icapx2]
2009/02/21 11:41:37.798| ICAP/ICAPXaction.cc(169) not reusing pconn due to pending I/O [FD 21;/ icapx2]
2009/02/21 11:41:37.798| ICAP/ICAPXaction.cc(179) closing pconn [FD 21;/ icapx2]
2009/02/21 11:41:37.798| ICAP/ICAPInitiate.cc(82) swan sings [/ icapx2]
2009/02/21 11:41:37.798| ICAP/ICAPInitiate.cc(89) swan sang [/ icapx2]
2009/02/21 11:41:37.798| ICAPOptXact destructed, this=0x92413a8 [icapx2]
2009/02/21 11:41:37.798| ICAP/AsyncJob.cc(106) ICAPOptXact::noteCommRead ended 0x92413a8
2009/02/21 11:41:37.808| entering 0x923d2b4->ICAPInitiator::noteIcapAnswer(0x91c48b8)
2009/02/21 11:41:37.808| ICAPOptXactLauncher::noteIcapAnswer called
2009/02/21 11:41:37.808| ICAP/ICAPInitiate.cc(176) will call 0x8f7e5a0->ICAPInitiator::noteIcapAnswer(0x91c48b8)
2009/02/21 11:41:37.808| ICAPOptXactLauncher::noteIcapAnswer ends job
2009/02/21 11:41:37.808| ICAP/ICAPInitiate.cc(82) swan sings
2009/02/21 11:41:37.808| ICAP/ICAPInitiate.cc(89) swan sang
2009/02/21 11:41:37.808| ICAP/AsyncJob.cc(106) ICAPOptXactLauncher::noteIcapAnswer ended 0x923d298
2009/02/21 11:41:37.809| exiting 0x923d2b4->ICAPInitiator::noteIcapAnswer(0x91c48b8)
2009/02/21 11:41:37.820| entering 0x8f7e5a0->ICAPInitiator::noteIcapAnswer(0x91c48b8)
2009/02/21 11:41:37.820| ICAPService is interpreting new options [down,!opt]
2009/02/21 11:41:37.820| ICAPOptions::cfgIntHeader Max-Connections: -1
2009/02/21 11:41:37.820| ICAPOptions::cfgIntHeader Options-TTL: -1
2009/02/21 11:41:37.820| ICAPOptions::cfgIntHeader Preview: -1
2009/02/21 11:41:37.820| ICAPOptions::cfgTransferList: no Transfer-Preview extensions
2009/02/21 11:41:37.820| ICAPOptions::cfgTransferList: no Transfer-Ignore extensions
2009/02/21 11:41:37.820| ICAPOptions::cfgTransferList: no Transfer-Complete extensions
2009/02/21 11:41:37.820| WARNING: Squid got an invalid ICAP OPTIONS response from service icap://192.168.1.1:1344/srv_echo; error: unsupported status code of OPTIONS response
2009/02/21 11:41:37.820| essential ICAP service is down after an options fetch failure: icap://192.168.1.1:1344/srv_echo [down,!valid]
2009/02/21 11:41:37.821| ICAPService got new options and is now [down,!valid]
2009/02/21 11:41:37.821| ICAPService will fetch OPTIONS in 180 sec
2009/02/21 11:41:37.821| exiting 0x8f7e5a0->ICAPInitiator::noteIcapAnswer(0x91c48b8)
2009/02/21 11:41:37.832| ICAPModXact::noteServiceReady called [UR/ icapx1]
2009/02/21 11:41:37.832| ICAPModXact becomes final [R/ icapx1]
2009/02/21 11:41:37.832| ICAPModXact::noteServiceReady caught an exception: ICAP service is unusable [R/ icapx1]
2009/02/21 11:41:37.832| ICAPModXact will stop, reason: exception
2009/02/21 11:41:37.833| ICAPModXact::noteServiceReady ends job [R/ icapx1]
2009/02/21 11:41:37.833| ICAP/ICAPModXact.cc(1062) swan sings [R/ icapx1]
2009/02/21 11:41:37.833| ICAP/ICAPInitiate.cc(237) will call 0x9234fe4->ICAPInitiator::noteIcapQueryAbort(1)
2009/02/21 11:41:37.833| ICAP/ICAPInitiate.cc(82) swan sings [/RwS icapx1]
2009/02/21 11:41:37.833| ICAP/ICAPInitiate.cc(89) swan sang [/RwS icapx1]
2009/02/21 11:41:37.833| ICAPModXact destructed, this=0x92390c8 [icapx1]
2009/02/21 11:41:37.833| ICAP/AsyncJob.cc(106) ICAPModXact::noteServiceReady ended 0x92390c8
2009/02/21 11:41:37.844| entering 0x9234fe4->ICAPInitiator::noteIcapQueryAbort(1)
2009/02/21 11:41:37.844| ICAPModXactLauncher::noteQueryAbort called
2009/02/21 11:41:37.844| ICAP/ICAPLauncher.cc(76) cannot retry the failed ICAP xaction; tries: 1; final: 1
2009/02/21 11:41:37.844| ICAPModXactLauncher::noteQueryAbort ends job
2009/02/21 11:41:37.844| ICAP/ICAPInitiate.cc(237) will call 0x9219648->ICAPInitiator::noteIcapQueryAbort(1)
2009/02/21 11:41:37.844| ICAP/ICAPInitiate.cc(82) swan sings
2009/02/21 11:41:37.844| ICAP/ICAPInitiate.cc(89) swan sang
2009/02/21 11:41:37.844| ICAP/AsyncJob.cc(106) ICAPModXactLauncher::noteQueryAbort ended 0x9234fc8
2009/02/21 11:41:37.845| exiting 0x9234fe4->ICAPInitiator::noteIcapQueryAbort(1)
2009/02/21 11:41:37.856| entering 0x9219648->ICAPInitiator::noteIcapQueryAbort(1)
2009/02/21 11:41:37.857| exiting 0x9219648->ICAPInitiator::noteIcapQueryAbort(1)
2009/02/21 11:44:37.834| ICAPService performs a regular options update [down,!valid]
2009/02/21 11:44:37.834| ICAPService will get new options [down,!valid]
2009/02/21 11:44:37.834| ICAP/AsyncJob.cc(14) will call AsyncJob::noteStart(0x923d298)
2009/02/21 11:44:37.846| entering AsyncJob::noteStart(0x923d298)
2009/02/21 11:44:37.846| ICAPOptXactLauncher::noteStart called
2009/02/21 11:44:37.846| ICAP/ICAPLauncher.cc(35) launching xaction #1
2009/02/21 11:44:37.846| ICAPOptXact constructed, this=0x92413a8 [icapx3]
2009/02/21 11:44:37.846| ICAP/AsyncJob.cc(14) will call AsyncJob::noteStart(0x92413a8)
2009/02/21 11:44:37.846| ICAPOptXactLauncher::noteStart ended
2009/02/21 11:44:37.846| exiting AsyncJob::noteStart(0x923d298)
2009/02/21 11:44:37.858| entering AsyncJob::noteStart(0x92413a8)
2009/02/21 11:44:37.858| ICAPOptXact::noteStart called [/ icapx3]
2009/02/21 11:44:37.858| ICAPOptXact becomes final [/ icapx3]
2009/02/21 11:44:37.858| ICAPOptXact opens connection to 192.168.1.1:1344
2009/02/21 11:44:37.858| ICAPOptXact::noteStart ended [FD 18;/ icapx3]
2009/02/21 11:44:37.858| exiting AsyncJob::noteStart(0x92413a8)
2009/02/21 11:44:37.858| ICAPOptXact::noteCommConnected called [FD 18;/ icapx3]
2009/02/21 11:44:37.858| ICAPOptXact::noteCommConnected ended [FD 18wr;/ icapx3]
2009/02/21 11:44:37.858| ICAPOptXact::noteCommWrote called [FD 18wr;/ icapx3]
2009/02/21 11:44:37.858| ICAPOptXact::noteCommWrote ended [FD 18r;/ icapx3]
2009/02/21 11:44:37.858| ICAP/ICAPXaction.cc(59) 0x92413a8 read returned 34
2009/02/21 11:44:37.859| ICAPOptXact::noteCommRead called [FD 18r;/ icapx3]
2009/02/21 11:44:37.859| ICAP/ICAPXaction.cc(339) read 34 bytes
2009/02/21 11:44:37.859| ICAPOptXact remains final [FD 18;/ icapx3]
2009/02/21 11:44:37.859| ICAP/ICAPOptXact.cc(71) have 34 bytes to parse [FD 18;/ icapx3]
2009/02/21 11:44:37.859| ICAP/ICAPOptXact.cc(72)
ICAP/1.0 404 Service not found
**********************************************************************
Amos Jeffries wrote ..
> david_at_davidwbrown.name wrote:
> > Hello Amos, this is a resend. I can connect with telnet mail.treenetnz.co.nz
> 25 but sending the mail using the SMTPd bounces or fails.
>
> Don't worry, sending to squid-users will get to me.
>
>
> > Hello Amos and all readers, thanks for the speedy and informative reply. 2.7.STABLE6
> will not configure with --enable-icap-client and 3.0.STABLE13 makes and installs
> OK but won't accept anything on the gateway. The squid.conf is default except for
> debug_options set to ALL,3. The error condition follows with a snippet from: cache.log.
> Please advise, David.
> >
>
> 2.7 has no ICAP support. It was new in 3.0.
>
>
> The error page you got was due to receiving non-proxied request (ie
> intercepted, or reverse proxy request).
>
> Since you say squid.conf is the default, then that is likely your
> problem. Squid needs to be configured specially to handle unusual requests.
>
> see whichever of these apply to your intended situation:
> http://wiki.squid-cache.org/ConfigExamples/Reverse/BasicAccelerator
> http://wiki.squid-cache.org/ConfigExamples/Intercept
>
>
> > *************************************************************
> >
> > ERROR
> > The requested URL could not be retrieved
> >
> > The following error was encountered while trying to retrieve the URL: /
> >
> > Invalid URL
> >
> > Some aspect of the requested URL is incorrect.
> >
> > Some possible problems are:
> <snip>
> > Missing or incorrect access protocol (should be "http://" or similar)
> > *
> >
> > Missing hostname
>
> <snip>
>
> >
> > Amos Jeffries wrote ..
> >> david_at_davidwbrown.name wrote:
> >>> Hello squid users, I have read the ICAP RFC but I cannot see a way to devise
> >> a ICAP query to the Squid server to extract ICAP information. It appears the
> squid
> >> 3.0.STABLE13 does not communicate with my ICAP server what-so-ever. I have run
> >> ./squid -N -X and the output shows all ICAP tags recognized including service
> vector
> >> points: echo, url_check, etc. This is a harsh way to test as I have to shutdown
> >> squid on my gateway just to do a test. Is there a real-time method to test Squid
> >> for ICAP communications using the squidclient? I can telnet to the ICAP server
> >> and get a response but I can't do the same connecting to squid. Please advise,
> >> David.
> >>
> >> Ouch. Heres a few debugging tips I use to debug squid on a production
> >> gateway:
> >>
> >> - build a _second_ instance of squid in a semi-jail, listening on
> >> different ports, etc than the live squid. This allows you to run tests
> >> on the secondary instance under the same conditions as live, but without
> >> affecting the main flow.
> >>
> >> - use reload/reconfigure to action new configurations as much as
> >> possible. Restart is overkill on many changes.
> >>
>
>
> Amos
> --
> Please be using
> Current Stable Squid 2.7.STABLE6 or 3.0.STABLE13
> Current Beta Squid 3.1.0.5
Received on Sat Feb 21 2009 - 23:28:39 MST
This archive was generated by hypermail 2.2.0 : Sun Feb 22 2009 - 12:00:01 MST