[squid-users] Help: ICAP problem

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)

*********************************************************
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.

      
Received on Wed Aug 13 2008 - 08:18:52 MDT