Re: Squid3 BodyReader changes
Hi Alex, Alex Rousskov wrote: I have committed your change, simplified virgin body buffer maintenance (in hope to minimize the number of similar bugs), and probably fixed a bug with handling of post-preview 204 replies. Yes I know. I am watching the branch for changes and additions... The above was done many days ago, but I also wanted to sync with HEAD before asking you to test again. Since I am not able to do that because of stale CVS locks, I suggest that you try the squid3-icap branch before I sync with HEAD. Yes, I am using it and test it. I did not see any problem. All thinks looks OK Regards, Christos
Re: Squid3 BodyReader changes
On Tue, 2007-02-20 at 12:22 +0200, Tsantilas Christos wrote: > So yes I believe it is the same bug, but I thing the problem begins > because the state.writing is not updated correctly ... Right, but the state is not updated correctly because of the bug you have fixed. I have committed your change, simplified virgin body buffer maintenance (in hope to minimize the number of similar bugs), and probably fixed a bug with handling of post-preview 204 replies. The above was done many days ago, but I also wanted to sync with HEAD before asking you to test again. Since I am not able to do that because of stale CVS locks, I suggest that you try the squid3-icap branch before I sync with HEAD. Thank you, Alex.
Re: Squid3 BodyReader changes
Alex Rousskov wrote: 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. Actually what I am seeing using wireshark is the: .. 0\r\n\r\n(squid client) ICAP/1.0 100 Continue (icap server responce) 0\r\n\r\n(squid client) So yes I believe it is the same bug, but I thing the problem begins because the state.writing is not updated correctly ... BTW, do you use manual testing for this or do you have an automated collection of test cases? I am using manual testing. Sometimes I am modifying my icap server to simulate cases. I think it will be good if I spend some time to write some test cases using perl Regards, Christos
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 - 1.1.2.21 > +++ ICAPModXact.cc 17 Feb 2007 16:32:40 - > @@ -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(14
Re: Squid3 BodyReader changes
Hi Alex, 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 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 - 1.1.2.21 +++ ICAPModXact.cc 17 Feb 2007 16:32:40 - @@ -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 } } 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
Re: Squid3 BodyReader changes
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. 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 sendin
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
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 icapx33
Re: Squid3 BodyReader changes
On Wed, Feb 14, 2007, Alex Rousskov wrote: > Hi there, > > I have committed the BodyPipe changes described below (with a few > modifications) to the squid3-icap branch. Using the new BodyPipe class, > I was able to eliminate many ICAP-related classes and code complexities, > not to mention a few memory leaks and bugs. Nice work! Its good to see some more Squid-3 work. Adrian
Re: Squid3 BodyReader changes
Hi there, I have committed the BodyPipe changes described below (with a few modifications) to the squid3-icap branch. Using the new BodyPipe class, I was able to eliminate many ICAP-related classes and code complexities, not to mention a few memory leaks and bugs. I will be working on a few remaning XXXs next week, but please test the current code if you can, especially if you are using ICAP. **WARNING** The committed changes are significant and probably introduce new bugs! The code passed some Web Polygraph and manual surfing tests, with and without ICAP. FTP-specific changes are untested, but the old code probably did not work well with ICAP either. Please test and submit bug reports. Thank you, Alex. On Tue, 2007-01-30 at 14:33 -0700, Alex Rousskov wrote: > Folks, > > Executive summary: I am trying to fix several bugs and complaints > related to your favorite class, the BodyReader. The changes I would like > to make are significant, so I decided to post them here first. Please > see the attached BodyPipe.h sketch. I will proceed with these changes > unless there are violent objections or better ideas. The email below > documents my concerns and explains the rationale behind BodyPipe. > > > Current state: The BodyReader class does not seem to read a body. It > helps to move the body content from the body producer to the consumer. > The class is essentially a collection of loosely coupled function > pointers with protected and bare data attached to them. The class calls > consumer-side functions on behalf of the producer (or vice versa), while > updating the body size state. BodyReader refcounting was meant to > communicate abort conditions. > > Here are a few related/intermingled reasons behind BodyPipe, the > replacement design I am implementing (see the attached sketch). > > A) The reason I want to get away from the current "lose ends" approach > with function pointers is to provide a more clear, easier to follow > implementation (IMO). I want classes like ConnStateData or > ICAPClientReqmodPrecache to inherit from BodyProducer and just implement > the two or three required methods. No wrappers or bare data pointers at > the high level, where all the changes and enhancements are > taking place. > > B) The reason I want explicit provider and consumer pointers inside > BodyPipe is to be able to abort either side if the other side is having > trouble. The current idea of using refcounting to abort something does > not and cannot work (if there are two refcounted pointers, the second > pointer will not know that the first has been set to NULL). I also want > joint ownership of the BodyReader so that the producer and the consumer > know that they must clear/detach themselves before forgetting about the > pipe. Refcounting will just help to destroy the abandoned pipe. > > C1) The reason I want asynchronous calls is to separate producer from > consumer and break the call-me-back-while-I-am-calling-you loops. I > believe that at least the abortedSize assertion (bug #1862) is > caused, in part, by such loops. > > C2) Another reason for separating producer and consumer is to allow the > producer to disconnect when done, leaving a functional object (with the > remaining/last body bytes) behind. This situation happens when, for > example, an ICAP transaction is finished but the HttpStateData is still > writing the body to the origin server. > > Again, please take a look at the attached sketch. > > > I have seen this before: While sketching the design, I realized that > what I want is very similar to MsgPipe, a class used by ICAP-related > code to shovel HTTP messages between Squid core and an ICAP transaction. > If you look at MsgPipe.cc and ignore the low-level debugging macros, you > will see that there is virtually nothing there. The class simply > converts notifications from one pipe end to events and then calls the > other end when the event fires. > > I do not plan on reusing MsgPipe itself because its simple design does > not allow one object to be the end of two pipes -- there would be no way > to know which pipe the messages are coming from. I do not want to > complicate MsgPipe and its users to support multi-pipe ends. I think it > would be better to have a very similar but distinct BodyPipe class, with > method names specific to the problem at hand and extra code to handle > body size calculations. The design duplication will be there, but code > duplication should be negligible. > > I am worried that I see every problem as a nail though, which is > another motivation for this message. Again, if you have better ideas on > how to fix BodyReader-related problems, please stop me and contribute! > > Thank you, > > Alex. >
Re: Squid3 BodyReader changes
On Tue, Jan 30, 2007, Alex Rousskov wrote: > Folks, > > Executive summary: I am trying to fix several bugs and complaints > related to your favorite class, the BodyReader. The changes I would like > to make are significant, so I decided to post them here first. Please > see the attached BodyPipe.h sketch. I will proceed with these changes > unless there are violent objections or better ideas. The email below > documents my concerns and explains the rationale behind BodyPipe. Aha! Well, I won't pretend to understand too much here, and I don't know much about the squid-3 codebase as it stands (still!). One thing that I think should get quite a bit of attention for similar ref-count-related reasons is the whole Forward class and how its changed to a refcounted type. This also introduced a whole heap of bugs, most of which have finally been fixed. I think the big one to fix there is the zero-sized-reply bug which has to do with timed out persistent connections. There's a bugzilla bug about it. This kinda stuff is going to keep popping up until those interested in pushing forward Squid-3 development get together and sort out what the heck is going on with all the refcounted types. (Personally, I think the best thing to do here is to plan out rewrites of complete chunks of the codebase, starting in squid-3 with the client-side code. With much more time spent in design and discusson before we slash forward.) Other than that, sounds good to me. I can't immediately see how it'd fit into the current client side code as my head is stuck in storage manager stuff for squid-2 but I'll eventually need to give the client-side a whole lot of attention. My 2c, Adrian
