Re: Squid3 BodyReader changes

On Wed, 2007-02-14 at 13:19 -0700, Alex Rousskov wrote:
> 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.

My suspicion was correct. The untested fix has been committed to
squid3-icap. Squid should now append ieof extension to the last chunk
whenever Preview contains the entire body.

Please try again.

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 - 15:56:35 MST