[squid-users] ICAP-Error: ICAP_ERR_GONE (noteInitiatorAborted: Initiator gone before ICAP transaction ended)

Hi

Running squid 3.3.4 as an icap-client:

Sometimes, I got on our ICAP-server (runs on the same box as squid)
errors like: "ERROR write error: Connection reset by peer"

On the squid-side, I enabled "debug_options 93,4". In case of the
error above, I have the following output in the cache.log:

2013/06/21 09:46:31.755 kid4| AccessCheck.cc(96) check: start checking
2013/06/21 09:46:31.755 kid4| AccessCheck.cc(118) checkCandidates: has 1 rules
2013/06/21 09:46:31.755 kid4| AccessCheck.cc(184) callBack: 0xaf35a0*2
2013/06/21 09:46:31.755 kid4| client_side_request.cc(865)
noteAdaptationAclCheckDone: 0xf34848 adaptationAclCheckDone called
2013/06/21 09:46:31.755 kid4| Launcher.cc(43) launchXaction: launching
first xaction #1
2013/06/21 09:46:31.755 kid4| Xaction.cc(52) Xaction:
Adaptation::Icap::ModXact constructed, this=0x75e51b8 [icapxjob69293]
2013/06/21 09:46:31.755 kid4| ServiceRep.cc(116) getConnection: got
connection: local=127.0.0.1:50493 remote=127.0.0.1:1344 FD 25 flags=1
2013/06/21 09:46:31.755 kid4| AsyncCall.cc(18) AsyncCall: The
AsyncCall Adaptation::Icap::Xaction::noteCommConnected constructed,
this=0x79495e0 [call649456]
2013/06/21 09:46:31.755 kid4| AsyncCall.cc(85) ScheduleCall:
Xaction.cc(127) will call
Adaptation::Icap::Xaction::noteCommConnected(local=127.0.0.1:50493
remote=127.0.0.1:1344 FD 25 flags=1, data=0x75e51b8) [call649456]
2013/06/21 09:46:31.755 kid4| AsyncCallQueue.cc(51) fireNext: entering
Adaptation::Icap::Xaction::noteCommConnected(local=127.0.0.1:50493
remote=127.0.0.1:1344 FD 25 flags=1, data=0x75e51b8)
2013/06/21 09:46:31.755 kid4| AsyncCall.cc(30) make: make call
Adaptation::Icap::Xaction::noteCommConnected [call649456]
2013/06/21 09:46:31.755 kid4| AsyncJob.cc(117) callStart:
Adaptation::Icap::ModXact status in: [FD 25;rw(1)P(0)G/R job69293]
2013/06/21 09:46:31.755 kid4| AsyncCall.cc(18) AsyncCall: The
AsyncCall Adaptation::Icap::Xaction::noteCommRead constructed,
this=0xc23770 [call649459]
2013/06/21 09:46:31.755 kid4| AsyncCall.cc(18) AsyncCall: The
AsyncCall Adaptation::Icap::Xaction::noteCommWrote constructed,
this=0x790be70 [call649461]
2013/06/21 09:46:31.755 kid4| AsyncJob.cc(146) callEnd:
Adaptation::Icap::ModXact status out: [FD 25wr;rw(2)G/RP(ieof)
job69293]
2013/06/21 09:46:31.755 kid4| AsyncCallQueue.cc(53) fireNext: leaving
Adaptation::Icap::Xaction::noteCommConnected(local=127.0.0.1:50493
remote=127.0.0.1:1344 FD 25 flags=1, data=0x75e51b8)
2013/06/21 09:46:31.756 kid4| AsyncCall.cc(85) ScheduleCall:
IoCallback.cc(127) will call
Adaptation::Icap::Xaction::noteCommWrote(local=127.0.0.1:50493
remote=127.0.0.1:1344 FD 25 flags=1, data=0x75e51b8) [call649461]
2013/06/21 09:46:31.756 kid4| AsyncCallQueue.cc(51) fireNext: entering
Adaptation::Icap::Xaction::noteCommWrote(local=127.0.0.1:50493
remote=127.0.0.1:1344 FD 25 flags=1, data=0x75e51b8)
2013/06/21 09:46:31.756 kid4| AsyncCall.cc(30) make: make call
Adaptation::Icap::Xaction::noteCommWrote [call649461]
2013/06/21 09:46:31.756 kid4| AsyncJob.cc(117) callStart:
Adaptation::Icap::ModXact status in: [FD 25wr;rw(2)G/RP(ieof)
job69293]
2013/06/21 09:46:31.756 kid4| AsyncJob.cc(146) callEnd:
Adaptation::Icap::ModXact status out: [FD 25r;rG/RwP(ieof) job69293]
2013/06/21 09:46:31.756 kid4| AsyncCallQueue.cc(53) fireNext: leaving
Adaptation::Icap::Xaction::noteCommWrote(local=127.0.0.1:50493
remote=127.0.0.1:1344 FD 25 flags=1, data=0x75e51b8)
2013/06/21 09:46:31.756 kid4| AsyncJob.cc(49) deleteThis:
ConnStateData will NOT delete in-call job, reason:
ConnStateData::connStateClosed
2013/06/21 09:46:31.756 kid4| Xaction.cc(488) noteInitiatorAborted:
Initiator gone before ICAP transaction ended
2013/06/21 09:46:31.756 kid4| Xaction.cc(503) setOutcome: ICAP_ERR_GONE
2013/06/21 09:46:31.756 kid4| AsyncCall.cc(48) cancel: will not call
Adaptation::Icap::Xaction::noteCommRead [call649459] because
comm_read_cancel
2013/06/21 09:46:31.756 kid4| AsyncCall.cc(48) cancel: will not call
Adaptation::Icap::Xaction::noteCommRead [call649459] also because
comm_read_cancel
2013/06/21 09:46:31.756 kid4| ServiceRep.cc(131) putConnection:
RST-closing [FD 25;rG/RwP(ieof)S job69293]
2013/06/21 09:46:31.756 kid4| Xaction.cc(60) ~Xaction:
Adaptation::Icap::ModXact destructed, this=0x75e51b8 [icapxjob69293]

For me, the following lines seems curious:
2013/06/21 09:46:31.756 kid4| Xaction.cc(488) noteInitiatorAborted:
Initiator gone before ICAP transaction ended
2013/06/21 09:46:31.756 kid4| Xaction.cc(503) setOutcome: ICAP_ERR_GONE

In the access.log, the error behaves like this:
[Fri Jun 21 09:46:31 2013].756 0 10.xx.xx.xx NONE_ABORTED/000 0
GET http://www9.dict.cc/img/amtop1.gif USER HIER_NONE/- -

The behaviour seems not to be reproducable. But it occurs n-times a
hour. I also tried with set "icap_persistent_connections off". But
this results in the same manner.

Any hints/solutions for this?
Kind regards,
Tom
Received on Fri Jun 21 2013 - 08:05:48 MDT