Re: Squid3 BodyReader changes

On Sat, 2007-02-17 at 19:00 +0200, Tsantilas Christos wrote:
> Still exist problems in preview transaction between icap server and
> squid. There are cases in which the squid-icap does not send the "0;
> ieof" sequence if all the http response body fits in the preview data
> but sends the 0\r\n\r\n. After that gets the "100 continue" icap
> response but it stops the icap transaction becouse it fails in
> ICAPModXact::handle100Continue function in the Must exception:
> Must(state.writing == State::writingPaused);
> The state.writing here is equal to State::writingPreview

According to your trace, Squid actually sent two last-chunks for the
Preview, but it is probably the same bug.

> The following solves the problem for me (but maybe makes other
> problems). It is in function moveRequestChunk in file ICAPModXacct.cc:
>
> diff -u -r1.1.2.21 ICAPModXact.cc
> --- ICAPModXact.cc 14 Feb 2007 22:52:30 -0000 1.1.2.21
> +++ ICAPModXact.cc 17 Feb 2007 16:32:40 -0000
> @@ -304,7 +304,8 @@
> // if there is no active virginWriteClaim,
> // then there is no body left to write,
> // so we must have written everything
> - const bool wroteEof = !virginWriteClaim.active();
> + const bool wroteEof = !virginWriteClaim.active() ||
> + (virgin.body_pipe->productionEnded() &&
> claimSize(virginWriteClaim) <= 0);
> preview.wrote(chunkSize, wroteEof); // even if wrote nothing
> }
> }

The above change makes sense. The new condition is actually identical to
calling the doneWithClaim() method.

While reviewing your log and patch, I also noticed that the claimSize()
method does not take into account that the buffer claim may be limited
by the preview size.

IMO, the right thing to do is to rename claimSize to match its code.
Moreover, I believe I have over-engineered the entire "claim" concept.
We do not need to maintain the size of the "claim". Knowing the writing
and sending offsets is sufficient!

Finally, I suspect we should not abandon backup commitments when
receiving a 100 Continue response to our Preview if we promised to allow
204s outside of Preview.

I am streamlining and polishing related code and will commit all changes
soon.

BTW, do you use manual testing for this or do you have an automated
collection of test cases?

Thank you,

Alex.

>
> I am also sending my squid log data (sorry for the long mail):
>
> 2007/02/17 18:45:27.929| ICAP/ICAPModXact.cc(377) consuming 195 out of
> 195 virgin body bytes
> 2007/02/17 18:45:27.929| ICAPModXact will not start sending [FD
> 12007/02/17 18:45:27.919| ICAPModXact should offer 1024-byte preview
> (service wanted 1024)
> 2007/02/17 18:45:27.919| ICAPModXact ICAP will write [FD
> 13r;Rrw(1)P(1024)B/ icapx6]:
> RESPMOD icap://192.168.1.4:1344/srv_clamav ICAP/1.0
> Host: 192.168.1.4:1344
> Date: Sat, 17 Feb 2007 16:45:27 GMT
> Encapsulated: req-hdr=0, res-hdr=518, res-body=883
> Preview: 1024
>
> GET http://www.google.com/ HTTP/1.1
> Host: www.google.com
> 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:
> text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,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
> Via: 1.0 fortune.home.chtsanti.net (C-ICAP/120207 Clamav/Antivirus service )
>
> HTTP/1.0 302 Moved Temporarily
> Location: http://www.google.gr/
> Cache-Control: private
> Set-Cookie:
> PREF=ID=3bd23962963cb32c:TM=1171730638:LM=1171730638:S=cwcpju2ceoF4GUEV;
> expires=Sun, 17-Jan-2038 19:14:07 GMT; path=/; domain=.google.com
> Content-Type: text/html
> Server: GWS/2.1
> Content-Encoding: gzip
> Date: Sat, 17 Feb 2007 16:43:58 GMT
> Connection: Close
>
>
> 2007/02/17 18:45:27.919| ICAPModXact::noteCommConnected ended [FD
> 13wr;Rrw(2)P(1024)B/ icapx6]
> 2007/02/17 18:45:27.920| ICAPModXact::noteCommWrote called [FD
> 13wr;Rrw(2)P(1024)B/ icapx6]
> 2007/02/17 18:45:27.920| ICAP/ICAPModXact.cc(149) Wrote 1066 bytes
> 2007/02/17 18:45:27.920| ICAP/ICAPModXact.cc(177) checking whether to
> write more [FD 13r;Rrw(3)P(1024)B/ icapx6]
> 2007/02/17 18:45:27.920| ICAP/ICAPModXact.cc(216) will write Preview
> body from 0x850dc00*2 [FD 13r;Rrw(3)P(1024)B/ icapx6]
> 2007/02/17 18:45:27.920| ICAP/ICAPModXact.cc(255) will write up to 195
> bytes of preview body
> 2007/02/17 18:45:27.920| ICAP/ICAPModXact.cc(266) will write 195-byte
> chunk of preview body
> 2007/02/17 18:45:27.920| ICAP/ICAPModXact.cc(278) will write last-chunk
> of preview body
> 2007/02/17 18:45:27.920| ICAP/ICAPModXact.cc(283) will write 206 raw
> bytes of preview body
> 2007/02/17 18:45:27.920| ICAPModXact::noteCommWrote ended [FD
> 13wr;Rrw(3)P(829)B/ icapx6]
> 2007/02/17 18:45:27.920| ICAPModXact::noteCommWrote called [FD
> 13wr;Rrw(3)P(829)B/ icapx6]
> 2007/02/17 18:45:27.920| ICAP/ICAPModXact.cc(149) Wrote 206 bytes
> 2007/02/17 18:45:27.920| ICAP/ICAPModXact.cc(177) checking whether to
> write more [FD 13r;Rrw(3)P(829)B/ icapx6]
> 2007/02/17 18:45:27.921| ICAP/ICAPModXact.cc(216) will write Preview
> body from 0x850dc00*2 [FD 13r;Rrw(3)P(829)B/ icapx6]
> 2007/02/17 18:45:27.921| ICAP/ICAPModXact.cc(255) will write up to 195
> bytes of preview body
> 2007/02/17 18:45:27.921| ICAPModXact has no writable preview body content
> 2007/02/17 18:45:27.921| ICAP/ICAPModXact.cc(278) will write last-chunk
> of preview body
> 2007/02/17 18:45:27.921| ICAP/ICAPModXact.cc(283) will write 5 raw bytes
> of preview body
> 2007/02/17 18:45:27.921| ICAPModXact::noteCommWrote ended [FD
> 13wr;Rrw(3)P(829)B/ icapx6]
> 2007/02/17 18:45:27.927| ICAP/ICAPXaction.cc(58) 0x84d8a28 read returned 25
> 2007/02/17 18:45:27.927| ICAPModXact::noteCommRead called [FD
> 13wr;Rrw(3)P(829)B/ icapx6]
> 2007/02/17 18:45:27.928| ICAP/ICAPXaction.cc(328) read 25 bytes
> 2007/02/17 18:45:27.928| ICAP/ICAPModXact.cc(549) have 25 bytes to parse
> [FD 13w;Rrw(3)P(829)B/ icapx6]
> 2007/02/17 18:45:27.928| ICAP/ICAPModXact.cc(550)
> ICAP/1.0 100 Continue
>
>
> 2007/02/17 18:45:27.928| ICAP/ICAPModXact.cc(578) parse ICAP headers
> 2007/02/17 18:45:27.928| ICAP/ICAPModXact.cc(781) have 25 head bytes to
> parse; state: 0
> 2007/02/17 18:45:27.928| HttpMsg::parse success (25 bytes) near
> 'ICAP/1.0 100 Continue
>
> '
> 2007/02/17 18:45:27.928| ICAP/ICAPModXact.cc(793) parse success, consume
> 25 bytes, return true
> 2007/02/17 18:45:27.928| ICAPModXact::noteCommRead caught an exception:
> state.writing == State::writingPaused [FD 13w;Rrw(3)P(829)B/ icapx6]
> 2007/02/17 18:45:27.928| ICAPModXact will stop, reason: exception
> 2007/02/17 18:45:27.929| ICAPModXact::noteCommRead ends xaction [FD
> 13w;Rrw(3)P(829)B/Stopped icapx6]
> 2007/02/17 18:45:27.929| ICAP/ICAPModXact.cc(944) swan sings [FD
> 13w;Rrw(3)P(829)B/Stopped icapx6]
> 2007/02/17 18:45:27.929| ICAP/ICAPModXact.cc(947) swan sings for
> exception [FD 13w;Rrw(3)P(829)B/Stopped icapx6]
> 2007/02/17 18:45:27.929| ICAP/ICAPModXact.cc(948) will call
> ICAPInitiator::noteIcapHeadersAborted(0x8505ba8)
> 2007/02/17 18:45:27.929| ICAP/ICAPModXact.cc(403) will NOT wait for the
> last write [FD 13w;Rrw(3)P(829)B/Stopped icapx6]
> 2007/02/17 18:45:27.929| ICAP/ICAPModXact.cc(413) will no longer write
> [FD 13w;Rrw(3)P(829)B/Stopped icapx6]
> 2007/02/17 18:45:27.929| ICAPModXact will no longer backup [FD
> 13w;RrP(829)B/Stoppedw icapx6]
Received on Mon Feb 19 2007 - 22:50:47 MST