Here is trace log from squid-3.1.0.13. The behavior is the same. Adaptation::Icap::Xaction::noteCommRead throwing exception, looks like because of loosing connection with ICAP server (as far as I can understand this situation). 2009/08/19 16:22:32.355| The AsyncCall BodyConsumer::noteMoreBodyDataAvailable constructed, this=0xa4da558 [call16010482] 2009/08/19 16:22:32.355| BodyPipe.cc(387) will call BodyConsumer::noteMoreBodyDataAvailable(0xa477a50*4) [call16010482] 2009/08/19 16:22:32.355| persistentConnStatus: FD 12 eof=0 2009/08/19 16:22:32.355| persistentConnStatus: content_length=4658399232 2009/08/19 16:22:32.355| persistentConnStatus: flags.headers_parsed=1 2009/08/19 16:22:32.355| persistentConnStatus: clen=4658399232 2009/08/19 16:22:32.355| persistentConnStatus: body_bytes_read=-2147457804 content_length=4658399232 2009/08/19 16:22:32.355| processReplyBody: INCOMPLETE_MSG 2009/08/19 16:22:32.356| comm.cc(1185) commSetTimeout: FD 12 timeout 900 2009/08/19 16:22:32.356| The AsyncCall HttpStateData::readReply constructed, this=0xa4da5b0 [call16010483] 2009/08/19 16:22:32.356| comm_read, queueing read for FD 12; asynCall 0xa4da5b0*1 2009/08/19 16:22:32.356| HttpStateData status out: [ job11] 2009/08/19 16:22:32.356| leaving HttpStateData::readReply(FD 12, data=0xa473410, size=2046, buf=0xa211a18) 2009/08/19 16:22:32.356| entering Adaptation::Icap::Xaction::noteCommRead(FD 11, errno=104, flag=-1, data=0xa44415c, size=0, buf=0xb7c21008) 2009/08/19 16:22:32.356| AsyncCall.cc(32) make: make call Adaptation::Icap::Xaction::noteCommRead [call16010418] 2009/08/19 16:22:32.356| Adaptation::Icap::ModXact status in: [FD 11wr;Rrw(5)p(2)S(2)/P icapx15] 2009/08/19 16:22:32.356| Xaction.cc:346: exception: io.flag == COMM_OK 2009/08/19 16:22:32.356| AsyncJob.cc(218) dial: Adaptation::Icap::Xaction::noteCommRead threw exception: io.flag == COMM_OK 2009/08/19 16:22:32.356| Xaction.cc(435) setOutcome: Warning: reseting outcome: from ICAP_MOD to ICAP_ERR_OTHER 2009/08/19 16:22:32.356| Adaptation::Icap::ModXact will stop, reason: exception 2009/08/19 16:22:32.356| Adaptation::Icap::Xaction::noteCommRead(FD 11, errno=104, flag=-1, data=0xa44415c, size=0, buf=0xb7c21008) ends job [FD 11w;Rrw(5)p( 2)S(2)/P icapx15] 2009/08/19 16:22:32.356| ModXact.cc(1094) swanSong: swan sings [FD 11w;Rrw(5)p(2)S(2)/P icapx15] 2009/08/19 16:22:32.356| ModXact.cc(431) stopWriting: will NOT wait for the last write [FD 11w;Rrw(5)p(2)S(2)/P icapx15] 2009/08/19 16:22:32.356| ModXact.cc(442) stopWriting: will no longer write [FD 11w;Rrw(5)p(2)S(2)/P icapx15] 2009/08/19 16:22:32.356| BodyPipe.cc(350) postConsume: consumed 2046 bytes [2147509492<=2147509492<=4658399232 0+65535 pipe0xa477a50 prod0xa473414 cons0xa444 540] 2009/08/19 16:22:32.356| The AsyncCall BodyProducer::noteMoreBodySpaceAvailable constructed, this=0xa4cca10 [call16010484] 2009/08/19 16:22:32.356| BodyPipe.cc(356) will call BodyProducer::noteMoreBodySpaceAvailable(0xa477a50*5) [call16010484] 2009/08/19 16:22:32.356| Adaptation::Icap::ModXact still cannot be repeated because consumed content [FD 11w;Rrw(5)p(2)S(2)/P icapx15] 2009/08/19 16:22:32.356| ModXact.cc(579) checkConsuming: will stop consuming [FD 11w;Rrp(2)S(2)/wP icapx15] 2009/08/19 16:22:32.356| BodyPipe.cc(117) stopConsumingFrom: 0xa444540 will not consume from 0xa477a50*5 2009/08/19 16:22:32.356| BodyPipe.cc(252) clearConsumer: clearing consumer [2147509492<=2147509492<=4658399232 0+65535 pipe0xa477a50 prod0xa473414 cons0xa444 540] 2009/08/19 16:22:32.356| The AsyncCall BodyProducer::noteBodyConsumerAborted constructed, this=0xa4d8ac8 [call16010485] 2009/08/19 16:22:32.356| BodyPipe.cc(259) will call BodyProducer::noteBodyConsumerAborted(0xa477a50*6) [call16010485] 2009/08/19 16:22:32.356| ModXact.cc(549) stopSending: Enter stop sending 2009/08/19 16:22:32.356| ModXact.cc(552) stopSending: Proceed with stop sending 2009/08/19 16:22:32.356| ModXact.cc(555) stopSending: will no longer send [FD 11w;rp(2)S(2)/RwP icapx15] -----Original Message----- From: Amos Jeffries <squid3@xxxxxxxxxxxxx> To: juris.krumins@xxxxxxx Cc: squid-users@xxxxxxxxxxxxxxx Subject: Re: Failed download files larger that 2GB through proxy with ICAP. Date: Thu, 20 Aug 2009 00:22:58 +1200 Juris Krumins wrote: > Tested with squid3S18 and squid3.1.0.13. The same behavior. > 2GB is exactly the 32-bit file limit. IIRC there was something about clamAV being limited in the file sizes it can handle. The trace you provide seems to confirm that, Squid is hitting a 2GB limit in the ICAP server which throws an ICAP error back at Squid. Then Squid detects a second IO error (disconnected client?) when it attempts to bypass ICAP and send on the 2GB it has so far. Can you provide a full log trace from 3.1 please? the code is vastly different and may be easier to see whats going on. Amos > -----Original Message----- > From: Juris Krumins <juris.krumins@xxxxxxx> > Reply-to: juris.krumins@xxxxxxx > To: squid-users@xxxxxxxxxxxxxxx > Subject: Failed download files larger that 2GB through > proxy with ICAP. > Date: Tue, 18 Aug 2009 17:03:26 +0300 > > Experiencing strange problem with squid+icap+clam. > Downloading files, larger than 2GB failed. Turning on squid debugging > figure out following: > > > 2009/08/18 12:17:26.420| comm_calliocallback: 0 > 2009/08/18 12:17:26.420| comm_calliocallback: 0 > 2009/08/18 12:17:26.420| commio_call_callback: called for 16 > 2009/08/18 12:17:26.420| httpReadReply: FD 16: len 2046. > 2009/08/18 12:17:26.420| BodyPipe.cc(240) added 2046 bytes > [2147525963<=2147530055<=4658399232 4092+61443 pipe0x9e20390 > prod0x9e1bd8c cons0x9df6984] > 2009/08/18 12:17:26.420| BodyPipe.cc(256) will call > BodyPipe::tellMoreBodyDataAvailable(0x9e20390) > 2009/08/18 12:17:26.420| event.cc(315) schedule: Adding > 'BodyPipe::tellMoreBodyDataAvailable', in 0.00 seconds > 2009/08/18 12:17:26.420| persistentConnStatus: FD 16 eof=0 > 2009/08/18 12:17:26.420| persistentConnStatus: content_length=4658399232 > 2009/08/18 12:17:26.420| persistentConnStatus: flags.headers_parsed=1 > 2009/08/18 12:17:26.420| persistentConnStatus: clen=4658399232 > 2009/08/18 12:17:26.420| persistentConnStatus: > body_bytes_read=-2147437241 content_length=4658399232 > 2009/08/18 12:17:26.420| processReplyBody: INCOMPLETE_MSG > 2009/08/18 12:17:26.420| commSetTimeout: FD 16 timeout 900 > 2009/08/18 12:17:26.420| comm_read, queueing read for FD 16 > 2009/08/18 12:17:26.420| commio_call_callback: called for 15 > 2009/08/18 12:17:26.420| ICAP/ICAPXaction.cc(59) 0x9df6928 read returned > 0 > 2009/08/18 12:17:26.420| ICAPModXact::noteCommRead called [FD > 15wr;Rrw(5)p(2)S(2)/P icapx6] > 2009/08/18 12:17:26.420| ICAP/ICAPXaction.cc:334: exception: commStatus > == COMM_OK > 2009/08/18 12:17:26.421| ICAPModXact::noteCommRead caught an exception: > commStatus == COMM_OK [FD 15w;Rrw(5)p(2)S(2)/P icapx6] > 2009/08/18 12:17:26.421| ICAPModXact will stop, reason: exception > 2009/08/18 12:17:26.421| ICAPModXact::noteCommRead ends job [FD > 15w;Rrw(5)p(2)S(2)/P icapx6] > 2009/08/18 12:17:26.421| ICAP/ICAPModXact.cc(1062) swan sings [FD > 15w;Rrw(5)p(2)S(2)/P icapx6] > 2009/08/18 12:17:26.421| ICAP/ICAPModXact.cc(423) will NOT wait for the > last write [FD 15w;Rrw(5)p(2)S(2)/P icapx6] > 2009/08/18 12:17:26.421| ICAP/ICAPModXact.cc(434) will no longer write > [FD 15w;Rrw(5)p(2)S(2)/P icapx6] > 2009/08/18 12:17:26.421| BodyPipe.cc(231) consumed 4092 bytes > [2147530055<=2147530055<=4658399232 0+65535 pipe0x9e20390 prod0x9e1bd8c > cons0x9df6984] > 2009/08/18 12:17:26.421| BodyPipe.cc(233) will call > BodyPipe::tellMoreBodySpaceAvailable(0x9e20390) > 2009/08/18 12:17:26.421| event.cc(315) schedule: Adding > 'BodyPipe::tellMoreBodySpaceAvailable', in 0.00 seconds > 2009/08/18 12:17:26.421| ICAP/ICAPModXact.cc(567) will stop consuming > [FD 15w;Rrp(2)S(2)/wP icapx6] > 2009/08/18 12:17:26.421| BodyPipe.cc(20) 0x9df6984 will not consume from > 0x9e20390*3 > 2009/08/18 12:17:26.421| BodyPipe.cc(153) clearing consumer > [2147530055<=2147530055<=4658399232 0+65535 pipe0x9e20390 prod0x9e1bd8c > cons0x9df6984] > 2009/08/18 12:17:26.421| BodyPipe.cc(157) will call > BodyPipe::tellBodyConsumerAborted(0x9e20390) > 2009/08/18 12:17:26.421| event.cc(315) schedule: Adding > 'BodyPipe::tellBodyConsumerAborted', in 0.00 seconds > 2009/08/18 12:17:26.421| ICAPModXact will no longer send [FD > 15w;rp(2)S(2)/RwP icapx6] > 2009/08/18 12:17:26.421| BodyPipe.cc(11) 0x9df6980 will not produce for > 0x9e203ec*3; atEof: 0 > 2009/08/18 12:17:26.421| BodyPipe.cc(89) clearing BodyPipe producer > [2147483647<=2147483647<=? 0+65535 pipe0x9e203ec prod0x9df6980 > cons0x9e1bd90] > 2009/08/18 12:17:26.421| BodyPipe.cc(268) will call > BodyPipe::tellBodyProducerAborted(0x9e203ec) > 2009/08/18 12:17:26.421| event.cc(315) schedule: Adding > 'BodyPipe::tellBodyProducerAborted', in 0.00 seconds > 2009/08/18 12:17:26.421| cleaning hdr: 0x9d9df98 owner: 3 > 2009/08/18 12:17:26.421| cleaning hdr: 0x9d9df98 owner: 3 > 2009/08/18 12:17:26.421| ICAP/ICAPXaction.cc(179) closing pconn [FD > 15w;rp(2)/RwPS icapx6] > 2009/08/18 12:17:26.421| comm_close: FD 15 > 2009/08/18 12:17:26.421| commSetTimeout: FD 15 timeout -1 > > > As we ca see I'm having exception, which are handled by > ICAPModXact::noteCommRead method. Seems like this exception caught in > Must(commStatus == COMM_OK); (334: ICAPXaction.cc) > > Does anybody have experienced something similar and know how to solve > this ? > > Btw I'm using squid with following configuration options: > > Squid Cache: Version 3.0.STABLE17 > configure options: '--prefix=/opt/squid3S17p1' '--enable-icap-client' > '--enable-large-cache-files' '--enable-storeio=ufs aufs diskd' > '--enable-disk-io=Blocking AIO DiskDaemon DiskThreads' '--enable-snmp' > '--with-large-files' '--with-large-cache-files' > '--with-filedescriptors=16384' > > Any ideas/comments would be appreciated. > > Thank you. > > >
