Re: [squid-users] Help: ICAP problem

evan gozali wrote:
> Hi, my name is Evan. I'm currently trying to connect an open source ICAP server Poesia 3.5 with Squid 3.0 STABLE4. While testing, I meet a problem when opening url http://marc.info/?l=squid=dev&r=1&w=2. The problem seems to me like when Squid sent the RESPMOD message, Squid didn't send the Http-body to the ICAP-server. Here is the log (ICAP-part only)
>

Please do not use Squid 3.0 earlier that STABLE7.
http://www.squid-cache.org/Advisories/SQUID-2008_1.txt

> *********************************************************
> 2008/08/13 13:52:19.755| ICAPAccessCheck constructed for RESPMOD PRECACHE
> 2008/08/13 13:52:19.755| ICAPAccessCheck::check
> 2008/08/13 13:52:19.755| ICAP/ICAPConfig.cc(277) looking for the first matching service in class class_req
> 2008/08/13 13:52:19.755| ICAP/ICAPConfig.cc(329) found no matching services in class class_req
> 2008/08/13 13:52:19.755| ICAP/ICAPConfig.cc(277) looking for the first matching service in class class_resp
> 2008/08/13 13:52:19.755| ICAPOptions url /?l=squid-dev&r=1&w=2 matches no Transfer-Preview extensions
> 2008/08/13 13:52:19.755| ICAPOptions url /?l=squid-dev&r=1&w=2 matches no Transfer-Complete extensions
> 2008/08/13 13:52:19.755| ICAPOptions url /?l=squid-dev&r=1&w=2 matches no Transfer-Ignore extensions
> 2008/08/13 13:52:19.755| ICAPOptions url /?l=squid-dev&r=1&w=2 matches no extensions; using default: Transfer-Complete
> 2008/08/13 13:52:19.755| ICAP/ICAPConfig.cc(315) found first matching service in class class_resp: service_resp
> 2008/08/13 13:52:19.755| ICAPAccessCheck::check: class 'class_resp' has candidate service 'service_resp'
> 2008/08/13 13:52:19.755| ICAPAccessCheckCallbackWrapper: answer=1
> 2008/08/13 13:52:19.755| ICAPAccessCheckCallbackWrapper matchedClass = class_resp
> 2008/08/13 13:52:19.768| ICAPAccessCheckCallbackEvent
> 2008/08/13 13:52:19.768| ICAPAccessCheck::do_callback
> 2008/08/13 13:52:19.768| ICAPAccessCheck::do_callback matchedClass = class_resp
> 2008/08/13 13:52:19.768| ICAP/ICAPConfig.cc(277) looking for the first matching up service in class class_resp
> 2008/08/13 13:52:19.768| ICAPOptions url /?l=squid-dev&r=1&w=2 matches no Transfer-Preview extensions
> 2008/08/13 13:52:19.769| ICAPOptions url /?l=squid-dev&r=1&w=2 matches no Transfer-Complete extensions
> 2008/08/13 13:52:19.769| ICAPOptions url /?l=squid-dev&r=1&w=2 matches no Transfer-Ignore extensions
> 2008/08/13 13:52:19.769| ICAPOptions url /?l=squid-dev&r=1&w=2 matches no extensions; using default: Transfer-Complete
> 2008/08/13 13:52:19.769| ICAP/ICAPConfig.cc(315) found first matching up service in class class_resp: service_resp
> 2008/08/13 13:52:19.769| ICAP/ICAPConfig.cc(262) do_callback: with service icap://127.0.0.1:1344/respmod
> 2008/08/13 13:52:19.769| Server.cc(414) will send virgin reply body to 0x85e0fd0*2; size: -1
> 2008/08/13 13:52:19.769| ICAP/AsyncJob.cc(14) will call AsyncJob::noteStart(0x85b42bc)
> 2008/08/13 13:52:19.780| entering AsyncJob::noteStart(0x85b42bc)
> 2008/08/13 13:52:19.780| ICAPModXactLauncher::noteStart called
> 2008/08/13 13:52:19.780| ICAP/ICAPLauncher.cc(35) launching xaction #1
> 2008/08/13 13:52:19.780| ICAPModXact constructed, this=0x85b8358 [icapx39]
> 2008/08/13 13:52:19.781| ICAPModXact initialized. [R/ icapx39]
> 2008/08/13 13:52:19.781| ICAP/AsyncJob.cc(14) will call AsyncJob::noteStart(0x85b8358)
> 2008/08/13 13:52:19.781| ICAPModXactLauncher::noteStart ended
> 2008/08/13 13:52:19.781| exiting AsyncJob::noteStart(0x85b42bc)
> 2008/08/13 13:52:19.792| entering AsyncJob::noteStart(0x85b8358)
> 2008/08/13 13:52:19.792| ICAPModXact::noteStart called [R/ icapx39]
> 2008/08/13 13:52:19.793| ICAPModXact expects virgin body from 0x85e0fd0*4; size: -1
> 2008/08/13 13:52:19.793| ICAP/ICAPModXact.cc(1232) preview disabled by squid.conf
> 2008/08/13 13:52:19.793| ICAPModXact becomes final [Rw(1)/ icapx39]
> 2008/08/13 13:52:19.793| ICAPModXact remains final [Rw(1)/ icapx39]
> 2008/08/13 13:52:19.793| ICAPModXact opens connection to 127.0.0.1:1344
> 2008/08/13 13:52:19.793| ICAPModXact::noteStart ended [FD 16;Rrw(1)/ icapx39]
> 2008/08/13 13:52:19.793| exiting AsyncJob::noteStart(0x85b8358)
> 2008/08/13 13:52:19.793| ICAPModXact::noteCommConnected called [FD 16;Rrw(1)/ icapx39]
> 2008/08/13 13:52:19.793| ICAPModXact ICAP will write [FD 16r;Rrw(1)/ icapx39]:
> RESPMOD icap://127.0.0.1:1344/respmod ICAP/1.0
> Host: 127.0.0.1:1344
> Date: Wed, 13 Aug 2008 06:52:19 GMT
> Encapsulated: req-hdr=0, res-hdr=456, res-body=659
> X-Client-IP: 167.205.34.163
>
> GET http://marc.info/?l=squid-dev&r=1&w=2 HTTP/1.1
> Host: marc.info
> User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8.1.1) Gecko/20061204 Firefox/2.0.0.1
> Accept: application/x-shockwave-flash,text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5
> Accept-Language: en-us,en;q=0.5
> Accept-Encoding: gzip,deflate
> Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
> Proxy-Connection: keep-alive
>
> HTTP/1.1 200 OK
> Date: Wed, 13 Aug 2008 06:52:29 GMT
> Server: Apache
> Last-Modified: Wed Aug 13 06:52:29 2008
> Expires: Wed Aug 13 07:52:29 2008
> Cache-Control: max-age=3600
> Content-Type: text/html;
>
>
> 2008/08/13 13:52:19.793| ICAPModXact::noteCommConnected ended [FD 16wr;Rrw(2)/ icapx39]
> 2008/08/13 13:52:19.793| ICAPModXact::noteMoreBodyDataAvailable called [FD 16wr;Rrw(2)/ icapx39]
> 2008/08/13 13:52:19.793| ICAP/ICAPModXact.cc(182) checking whether to write more [FD 16wr;Rrw(2)/ icapx39]
> 2008/08/13 13:52:19.793| ICAPModXact::noteMoreBodyDataAvailable ended [FD 16wr;Rrw(2)/ icapx39]
> 2008/08/13 13:52:19.793| ICAPModXact::noteCommWrote called [FD 16wr;Rrw(2)/ icapx39]
> 2008/08/13 13:52:19.793| ICAP/ICAPModXact.cc(154) Wrote 849 bytes
> 2008/08/13 13:52:19.793| ICAP/ICAPModXact.cc(182) checking whether to write more [FD 16r;Rrw(5)/ icapx39]
> 2008/08/13 13:52:19.793| ICAP/ICAPModXact.cc(260) will write up to 276 bytes of prime virgin body
> 2008/08/13 13:52:19.793| ICAP/ICAPModXact.cc(271) will write 276-byte chunk of prime virgin body
> 2008/08/13 13:52:19.793| consumption guards: 00
> 2008/08/13 13:52:19.793| ICAP/ICAPModXact.cc(383) max virgin consumption offset=276 acts 10 consumed=0 from [0<=276<=? 276+1771 pipe0x85e0fd0 prod0x85dce14
> cons0x85b83b4]
> 2008/08/13 13:52:19.793| ICAP/ICAPModXact.cc(395) consuming 276 out of 276 virgin body bytes
> 2008/08/13 13:52:19.793| ICAP/ICAPModXact.cc(296) will write 283 raw bytes of prime virgin body
> 2008/08/13 13:52:19.793| ICAPModXact::noteCommWrote ended [FD 16wr;Rrw(5)/ icapx39]
> 2008/08/13 13:52:19.793| ICAPModXact::noteCommWrote called [FD 16wr;Rrw(5)/ icapx39]
> 2008/08/13 13:52:19.793| ICAP/ICAPModXact.cc(154) Wrote 283 bytes
> 2008/08/13 13:52:19.793| ICAP/ICAPModXact.cc(182) checking whether to write more [FD 16r;Rrw(5)/ icapx39]
> 2008/08/13 13:52:19.793| ICAP/ICAPModXact.cc(260) will write up to 0 bytes of prime virgin body
> 2008/08/13 13:52:19.793| ICAPModXact has no writable prime virgin body content
> 2008/08/13 13:52:19.793| ICAP/ICAPModXact.cc(296) will write 0 raw bytes of prime virgin body
> 2008/08/13 13:52:19.793| ICAPModXact::noteCommWrote ended [FD 16r;Rrw(5)/ icapx39]
> ********************************************************
>
> And the log from ICAP-server is like the following:
> ********************************************************
> Aug 13, 2008 1:52:19 PM [Thread-32] FINE: Received HTTP response headers
> ...........
> Aug 13, 2008 2:07:19 PM [Thread-32] FINE: releasing 15
> ********************************************************
>
> I see that the ICAP server didn't receive the http body from Squid. Is it a problem in Squid or not? And i noticed too that the HTTP response header from the website didn't contain "Content-length" header. Can it be a problem?
> Thanks for the reply.
>

Might be a problem. Retry with current Squid.
If the problem persists, file a bug report with new data.

Amos

-- 
Please use Squid 2.7.STABLE3 or 3.0.STABLE8