Re: Squid3 BodyReader changes

On Wed, 2007-02-14 at 21:17 +0200, Tsantilas Christos wrote:
> Hi Alex,
> I try some test's. It is not so bad, but I saw that there are problems.
> After surfing the web for a while the icap-client of squid failed and
> the squid returned an error page to the web browser (ICAP protocoll
> error .... ICAP server is not reachable ......)
> The icap client sends an respmod request with preview data and after
> the the server responds with 100 Continue the squid closes the connection.
> I have the same error on some sites (e.g freshmeat.net) using c-icap
> icap server. I compiled squid using gcc 4.1.2.
> I did not have enough time to look more on it. I will try to find time
> next days for tests and debuging.....

Nice logs, thank you.

It looks like Squid is sending a 43 byte preview of a 43 byte body and
does not expect 100 Continue because there is nothing to continue with.

I suspect Squid should have sent ieof but I need to read the RFC and to
think about it. We can also make Squid more robust and send a
last-chunk even if the ICAP server should not have sent 100 Continue.

Thank you,

Alex.

> My squid logs are:
> 2007/02/14 20:21:19.587| ICAPModXact should offer 43-byte preview
> (service wanted 1024)
> 2007/02/14 20:21:19.587| ICAPModXact ICAP will write [FD
> 13r;Rrw(1)P(43)B/ icapx338]:
> RESPMOD icap://192.168.1.4:1344/srv_clamav ICAP/1.0
> Host: 192.168.1.4:1344
> Date: Wed, 14 Feb 2007 18:21:19 GMT
> Encapsulated: req-hdr=0, res-hdr=597, res-body=821
> Preview: 43
> Allow: 204
>
> GET
> http://ads.in.gr/adlog.php?bannerid=815&clientid=224&zoneid=119&source=251&block=0&capping=0&cb=993fc456072f1bc18ea9ab8de58b1da9
> HTTP/1.1
> Host: ads.in.gr
> User-Agent: Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.8.1)
> Gecko/20061023 SUSE/2.0-30 Firefox/2.0
> Accept: image/png,*/*;q=0.5
> Accept-Language: el,en-us;q=0.7,en;q=0.3
> Accept-Encoding: gzip,deflate
> Accept-Charset: ISO-8859-7,utf-8;q=0.7,*;q=0.7
> Keep-Alive: 300
> Proxy-Connection: keep-alive
> Referer: http://www.in.gr/news/category.asp?lngDtrID=251
> Via: 1.0 fortune.home.chtsanti.net (C-ICAP/120207 Clamav/Antivirus service )
>
> HTTP/1.1 200 OK
> Date: Wed, 14 Feb 2007 18:19:51 GMT
> Server: Apache
> X-Powered-By: PHP/4.4.4
> Pragma: no-cache
> Cache-Control: private, max-age=0, no-cache
> Content-Length: 43
> Connection: close
> Content-Type: image/gif
>
>
> 2007/02/14 20:21:19.587| ICAPModXact::noteCommConnected ended [FD
> 13wr;Rrw(2)P(43)B/ icapx338]
> 2007/02/14 20:21:19.588| ICAPModXact::noteCommWrote called [FD
> 13wr;Rrw(2)P(43)B/ icapx338]
> 2007/02/14 20:21:19.588| ICAP/ICAPModXact.cc(149) Wrote 1014 bytes
> 2007/02/14 20:21:19.588| ICAP/ICAPModXact.cc(177) checking whether to
> write more [FD 13r;Rrw(3)P(43)B/ icapx338]
> 2007/02/14 20:21:19.588| ICAP/ICAPModXact.cc(216) will write Preview
> body from 0x8525f40*2 [FD 13r;Rrw(3)P(43)B/ icapx338]
> 2007/02/14 20:21:19.588| ICAP/ICAPModXact.cc(255) will write up to 43
> bytes of preview body
> 2007/02/14 20:21:19.588| ICAP/ICAPModXact.cc(266) will write 43-byte
> chunk of preview body
> 2007/02/14 20:21:19.588| ICAP/ICAPModXact.cc(278) will write last-chunk
> of preview body
> 2007/02/14 20:21:19.588| ICAP/ICAPModXact.cc(283) will write 54 raw
> bytes of preview body
> 2007/02/14 20:21:19.588| ICAPModXact wrote entire Preview body [FD
> 13wr;Rrw(3)B/P icapx338]
> 2007/02/14 20:21:19.588| ICAPModXact::noteCommWrote ended [FD
> 13wr;Rrw(4)B/P icapx338]
> 2007/02/14 20:21:19.588| ICAPModXact::noteCommWrote called [FD
> 13wr;Rrw(4)B/P icapx338]
> 2007/02/14 20:21:19.589| ICAP/ICAPModXact.cc(149) Wrote 54 bytes
> 2007/02/14 20:21:19.589| ICAP/ICAPModXact.cc(177) checking whether to
> write more [FD 13r;Rrw(4)B/P icapx338]
> 2007/02/14 20:21:19.589| ICAPModXact::noteCommWrote ended [FD
> 13r;Rrw(4)B/P icapx338]
> 2007/02/14 20:21:19.599| ICAP/ICAPXaction.cc(58) 0x84d8ac8 read returned 25
> 2007/02/14 20:21:19.599| ICAPModXact::noteCommRead called [FD
> 13r;Rrw(4)B/P icapx338]
> 2007/02/14 20:21:19.599| ICAP/ICAPXaction.cc(328) read 25 bytes
> 2007/02/14 20:21:19.599| ICAP/ICAPModXact.cc(548) have 25 bytes to parse
> [FD 13;Rrw(4)B/P icapx338]
> 2007/02/14 20:21:19.599| ICAP/ICAPModXact.cc(549)
> ICAP/1.0 100 Continue
>
>
> 2007/02/14 20:21:19.599| ICAP/ICAPModXact.cc(577) parse ICAP headers
> 2007/02/14 20:21:19.599| ICAP/ICAPModXact.cc(780) have 25 head bytes to
> parse; state: 0
> 2007/02/14 20:21:19.600| HttpMsg::parse success (25 bytes) near
> 'ICAP/1.0 100 Continue
>
> '
> 2007/02/14 20:21:19.600| ICAP/ICAPModXact.cc(792) parse success, consume
> 25 bytes, return true
> 2007/02/14 20:21:19.600| ICAP/ICAPModXact.cc(177) checking whether to
> write more [FD 13;Rrw(5)B/P icapx338]
> 2007/02/14 20:21:19.600| ICAPModXact::noteCommRead caught an exception:
> virginWriteClaim.active() [FD 13;Rrw(5)B/P icapx338]
> 2007/02/14 20:21:19.600| ICAPModXact will stop, reason: exception
> 2007/02/14 20:21:19.600| ICAPModXact::noteCommRead ends xaction [FD
> 13;Rrw(5)B/StoppedP icapx338]
> 2007/02/14 20:21:19.600| ICAP/ICAPModXact.cc(943) swan sings [FD
> 13;Rrw(5)B/StoppedP icapx338]
> 2007/02/14 20:21:19.600| ICAP/ICAPModXact.cc(946) swan sings for
> exception [FD 13;Rrw(5)B/StoppedP icapx338]
> 2007/02/14 20:21:19.600| ICAP/ICAPModXact.cc(947) will call
> ICAPInitiator::noteIcapHeadersAborted(0x8521d10)
> 2007/02/14 20:21:19.600| ICAP/ICAPModXact.cc(412) will no longer write
> [FD 13;Rrw(5)B/StoppedP icapx338]
> 2007/02/14 20:21:19.601| ICAPModXact will no longer backup [FD
> 13;RrB/StoppedwP icapx338]
> 2007/02/14 20:21:19.601| ICAP/ICAPModXact.cc(376) consuming 43 out of 43
> virgin body bytes
> 2007/02/14 20:21:19.601| ICAPModXact will not start sending [FD
> 13;Rr/StoppedwP icapx338]
> 2007/02/14 20:21:19.601| ICAP/ICAPModXact.cc(541) will stop consuming
> [FD 13;Rr/StoppedwPS icapx338]
> 2007/02/14 20:21:19.601| ICAP/ICAPXaction.cc(174) closing pconn [FD
> 13;r/StoppedRwPS icapx338]
> 2007/02/14 20:21:19.601| ICAP/ICAPXaction.cc(429) swan sang
> [/StoppedRwPS icapx338]
> 2007/02/14 20:21:19.601| ICAP/ICAPXaction.cc(489)
> ICAPModXact::noteCommRead ended 0x84d8ac8
> 2007/02/14 20:21:19.623| entering
> ICAPInitiator::noteIcapHeadersAborted(0x8521d10)
> 2007/02/14 20:21:19.624| ICAPModXact destructed, this=0x84d8ac8 [icapx338]
> 2007/02/14 20:21:19.624| Server.cc(464) handleIcapAborted; entry empty: 1
> 2007/02/14 20:21:19.624| Server.cc(470) creating ICAP error entry after
> ICAP failure
> 2007/02/14 20:21:19.624| Server.cc(478) bailing after ICAP failure
> 2007/02/14 20:21:19.624| Server.cc(333) cleaning ICAP
> 2007/02/14 20:21:19.624| http.cc(1302) closing HTTP server FD -1 this
> 0x8521d10
> 2007/02/14 20:21:19.624| Server.cc(112) transaction done
> 2007/02/14 20:21:19.624| http.cc(151) HttpStateData 0x8521d10 destroyed;
> FD -1
> 2007/02/14 20:21:19.625| Server.cc(333) cleaning ICAP
> 2007/02/14 20:21:19.625| exiting
> ICAPInitiator::noteIcapHeadersAborted(0x8521d10)
> ...............................
>
Received on Wed Feb 14 2007 - 13:22:13 MST