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_at_treenet.co.nz>
To: juris.krumins_at_ctco.lv
Cc: squid-users_at_squid-cache.org
Subject: Re: [squid-users] 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_at_ctco.lv>
> Reply-to: juris.krumins_at_ctco.lv
> To: squid-users_at_squid-cache.org
> Subject: [squid-users] 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.
>
>
>
Received on Wed Aug 19 2009 - 13:35:01 MDT
This archive was generated by hypermail 2.2.0 : Thu Aug 20 2009 - 12:00:04 MDT