2009/10/02 08:15:55| Starting Squid Cache version 3.1.0.14 for ia64-unknown-linux-gnu...
2009/10/02 08:15:55| chdir: /usr/local/proxy-test/squid31/var/cache: (2) No such file or directory
2009/10/02 08:15:55.315| Config.cc(91) finalize: Found 1 service configs.
2009/10/02 08:15:55.315| AsyncJob of type Adaptation::Icap::ServiceRep constructed, this=0x60000000004a52d8 [async1]
2009/10/02 08:15:55.315| Service.cc(12) Service: creating adaptation service testresp
2009/10/02 08:15:55.316| Config.cc(105) finalize: Created 1 message adaptation services.
2009/10/02 08:15:55.316| Adaptation support is on
2009/10/02 08:15:55.316| Config.cc(117) FinalizeEach: Initialized 1 message adaptation services
2009/10/02 08:15:55.316| ServiceGroups.cc(78) finalize: finalized adaptation set: testresponse
2009/10/02 08:15:55.316| Config.cc(117) FinalizeEach: Initialized 1 message adaptation service groups
2009/10/02 08:15:55.316| Config.cc(117) FinalizeEach: Initialized 1 message adaptation access rules
2009/10/02 08:16:02.275| AsyncJob of type ConnStateData constructed, this=0x60000000004a9600 [async2]
2009/10/02 08:16:02.276| AsyncJob of type ClientHttpRequest constructed, this=0x60000000004b1d18 [async3]
2009/10/02 08:16:02.276| AsyncJob of type AccessCheck constructed, this=0x60000000004ec308 [async4]
2009/10/02 08:16:02.276| HttpRequest.cc(387) icapHistory: made 0x60000000004f02b0*1 for 0x60000000004839f0
2009/10/02 08:16:02.276| History.cc(74) start: start ACL level=1 time=0 0x60000000004f02b0
2009/10/02 08:16:02.276| AccessCheck.cc(49) AccessCheck: AccessCheck constructed for REQMOD PRECACHE
2009/10/02 08:16:02.277| The AsyncCall AsyncJob::noteStart constructed, this=0x60000000004f03a0 [call18]
2009/10/02 08:16:02.277| AsyncJob.cc(18) will call AsyncJob::noteStart() [call18]
2009/10/02 08:16:02.277| entering AsyncJob::noteStart()
2009/10/02 08:16:02.277| AsyncCall.cc(32) make: make call AsyncJob::noteStart [call18]
2009/10/02 08:16:02.277| AccessCheck status in: [ job4]
2009/10/02 08:16:02.277| AccessCheck.cc(74) check: start checking
2009/10/02 08:16:02.277| AccessCheck.cc(188) isCandidate: checking candidacy of 1, group testresponse
2009/10/02 08:16:02.277| ServiceGroups.cc(126) findService: testresponse serves another location
2009/10/02 08:16:02.277| AccessCheck.cc(198) isCandidate: testresponse ignores
2009/10/02 08:16:02.277| AccessCheck.cc(96) checkCandidates: has 0 rules
2009/10/02 08:16:02.277| AccessCheck.cc(111) checkCandidates: NO candidates left
2009/10/02 08:16:02.277| AccessCheck.cc(155) callBack: NULL
2009/10/02 08:16:02.277| client_side_request.cc(636) adaptationAclCheckDone: 0x60000000004e3fa8 adaptationAclCheckDone called
2009/10/02 08:16:02.277| AccessCheck will stop, reason: done
2009/10/02 08:16:02.277| AsyncJob::noteStart() ends job [Stopped, reason:done job4]
2009/10/02 08:16:02.278| History.cc(86) stop: stop ACL level=1 time=0+1 0x60000000004f02b0
2009/10/02 08:16:02.278| AsyncJob.cc(140) callEnd: AsyncJob::noteStart() ended 0x60000000004ec308
2009/10/02 08:16:02.278| leaving AsyncJob::noteStart()
2009/10/02 08:16:02.310| AsyncJob of type HttpStateData constructed, this=0x6000000000509558 [async5]
2009/10/02 08:16:02.352| AsyncJob of type AccessCheck constructed, this=0x60000000004ec308 [async6]
2009/10/02 08:16:02.352| History.cc(74) start: start ACL level=1 time=1 0x60000000004f02b0
2009/10/02 08:16:02.352| AccessCheck.cc(49) AccessCheck: AccessCheck constructed for RESPMOD PRECACHE
2009/10/02 08:16:02.352| The AsyncCall AsyncJob::noteStart constructed, this=0x6000000000500b90 [call30]
2009/10/02 08:16:02.352| AsyncJob.cc(18) will call AsyncJob::noteStart() [call30]
2009/10/02 08:16:02.353| entering AsyncJob::noteStart()
2009/10/02 08:16:02.353| AsyncCall.cc(32) make: make call AsyncJob::noteStart [call30]
2009/10/02 08:16:02.353| AccessCheck status in: [ job6]
2009/10/02 08:16:02.353| AccessCheck.cc(74) check: start checking
2009/10/02 08:16:02.353| AccessCheck.cc(188) isCandidate: checking candidacy of 1, group testresponse
2009/10/02 08:16:02.353| ServiceGroups.cc(134) findService: testresponse checks service at 0
2009/10/02 08:16:02.353| ServiceGroups.cc(144) findService: testresponse has matching service at 0
2009/10/02 08:16:02.353| AccessCheck.cc(198) isCandidate: testresponse wants
2009/10/02 08:16:02.353| AccessCheck.cc(80) check: check: rule '1' is a candidate
2009/10/02 08:16:02.353| AccessCheck.cc(96) checkCandidates: has 1 rules
2009/10/02 08:16:02.353| AccessCheck.cc(119) AccessCheckCallbackWrapper: callback answer=1
2009/10/02 08:16:02.353| AccessCheck.cc(134) noteAnswer: 1 answer=1
2009/10/02 08:16:02.353| AccessCheck.cc(171) topGroup: top group for 1 is 0x60000000001bcbf0*2
2009/10/02 08:16:02.353| AccessCheck.cc(155) callBack: 0x60000000001bcbf0*2
2009/10/02 08:16:02.353| Server.cc(526) startAdaptation: will send virgin reply body to 0x600000000050f1c8*2; size: 4264
2009/10/02 08:16:02.353| AsyncJob of type Iterator constructed, this=0x6000000000513410 [async7]
2009/10/02 08:16:02.353| The AsyncCall AsyncJob::noteStart constructed, this=0x600000000050f0f0 [call31]
2009/10/02 08:16:02.353| AsyncJob.cc(18) will call AsyncJob::noteStart() [call31]
2009/10/02 08:16:02.353| AccessCheck will stop, reason: done
2009/10/02 08:16:02.353| AsyncJob::noteStart() ends job [Stopped, reason:done job6]
2009/10/02 08:16:02.353| History.cc(86) stop: stop ACL level=1 time=1+0 0x60000000004f02b0
2009/10/02 08:16:02.353| AsyncJob.cc(140) callEnd: AsyncJob::noteStart() ended 0x60000000004ec308
2009/10/02 08:16:02.353| leaving AsyncJob::noteStart()
2009/10/02 08:16:02.353| entering AsyncJob::noteStart()
2009/10/02 08:16:02.353| AsyncCall.cc(32) make: make call AsyncJob::noteStart [call31]
2009/10/02 08:16:02.353| Iterator status in: [ job7]
2009/10/02 08:16:02.353| ServiceGroups.cc(134) findService: testresponse checks service at 0
2009/10/02 08:16:02.353| ServiceGroups.cc(144) findService: testresponse has matching service at 0
2009/10/02 08:16:02.353| Iterator.cc(49) step: #1 plan: testresponse[0..1]
2009/10/02 08:16:02.354| Iterator.cc(69) step: using adaptation service: testresp
2009/10/02 08:16:02.354| AsyncJob of type Adaptation::Icap::ModXactLauncher constructed, this=0x60000000005176a8 [async8]
2009/10/02 08:16:02.354| History.cc(74) start: start ICAPModXactLauncher level=1 time=1 0x60000000004f02b0
2009/10/02 08:16:02.354| The AsyncCall AsyncJob::noteStart constructed, this=0x6000000000500b90 [call33]
2009/10/02 08:16:02.354| AsyncJob.cc(18) will call AsyncJob::noteStart() [call33]
2009/10/02 08:16:02.354| Iterator status out: [ job7]
2009/10/02 08:16:02.354| leaving AsyncJob::noteStart()
2009/10/02 08:16:02.354| entering AsyncJob::noteStart()
2009/10/02 08:16:02.354| AsyncCall.cc(32) make: make call AsyncJob::noteStart [call33]
2009/10/02 08:16:02.354| Adaptation::Icap::ModXactLauncher status in: [ job8]
2009/10/02 08:16:02.354| Launcher.cc(42) launchXaction: launching first xaction #1
2009/10/02 08:16:02.354| AsyncJob of type Adaptation::Icap::ModXact constructed, this=0x600000000051be20 [async9]
2009/10/02 08:16:02.354| Adaptation::Icap::ModXact constructed, this=0x600000000051b868 [icapx9]
2009/10/02 08:16:02.354| ModXact.cc(70) ModXact: initialized. [RG/ icapx9]
2009/10/02 08:16:02.354| Adaptation::Icap::ModXact from now on cannot be repeated because over icap_retry_limit [RG/ icapx9]
2009/10/02 08:16:02.354| The AsyncCall AsyncJob::noteStart constructed, this=0x600000000050f0f0 [call34]
2009/10/02 08:16:02.354| AsyncJob.cc(18) will call AsyncJob::noteStart() [call34]
2009/10/02 08:16:02.354| Adaptation::Icap::ModXactLauncher status out: [ job8]
2009/10/02 08:16:02.354| leaving AsyncJob::noteStart()
2009/10/02 08:16:02.354| entering AsyncJob::noteStart()
2009/10/02 08:16:02.354| AsyncCall.cc(32) make: make call AsyncJob::noteStart [call34]
2009/10/02 08:16:02.354| Adaptation::Icap::ModXact status in: [RG/ icapx9]
2009/10/02 08:16:02.354| ModXact.cc(1522) estimateVirginBody: expects virgin body from 0x600000000050f1c8*4; size: 4264
2009/10/02 08:16:02.354| ModXact.cc(98) waitForService: will wait for the ICAP service [RG/ icapx9]
2009/10/02 08:16:02.354| The AsyncCall Adaptation::Icap::ModXact::noteServiceReady constructed, this=0x60000000005175a0 [call36]
2009/10/02 08:16:02.354| ServiceRep.cc(201) callWhenReady: Adaptation::Icap::Service is asked to call Adaptation::Icap::ModXact::noteServiceReady() when ready [down,!opt]
2009/10/02 08:16:02.354| ServiceRep.cc(358) startGettingOptions: will get new options [down,!opt]
2009/10/02 08:16:02.355| AsyncJob of type Adaptation::Icap::OptXactLauncher constructed, this=0x6000000000527bd0 [async10]
2009/10/02 08:16:02.355| The AsyncCall AsyncJob::noteStart constructed, this=0x600000000051b7a0 [call37]
2009/10/02 08:16:02.355| AsyncJob.cc(18) will call AsyncJob::noteStart() [call37]
2009/10/02 08:16:02.355| Adaptation::Icap::ModXact status out: [URG/ icapx9]
2009/10/02 08:16:02.355| leaving AsyncJob::noteStart()
2009/10/02 08:16:02.355| ModXact.cc(178) writeMore: checking whether to write more [URG/ icapx9]
2009/10/02 08:16:02.355| entering AsyncJob::noteStart()
2009/10/02 08:16:02.355| AsyncCall.cc(32) make: make call AsyncJob::noteStart [call37]
2009/10/02 08:16:02.355| Adaptation::Icap::OptXactLauncher status in: [ job10]
2009/10/02 08:16:02.355| Launcher.cc(42) launchXaction: launching first xaction #1
2009/10/02 08:16:02.355| AsyncJob of type Adaptation::Icap::OptXact constructed, this=0x600000000052c2c8 [async11]
2009/10/02 08:16:02.355| Adaptation::Icap::OptXact constructed, this=0x600000000052bdc8 [icapx11]
2009/10/02 08:16:02.355| Adaptation::Icap::OptXact from now on cannot be repeated because over icap_retry_limit [/ icapx11]
2009/10/02 08:16:02.355| The AsyncCall AsyncJob::noteStart constructed, this=0x6000000000500b90 [call38]
2009/10/02 08:16:02.355| AsyncJob.cc(18) will call AsyncJob::noteStart() [call38]
2009/10/02 08:16:02.355| Adaptation::Icap::OptXactLauncher status out: [ job10]
2009/10/02 08:16:02.355| leaving AsyncJob::noteStart()
2009/10/02 08:16:02.355| entering AsyncJob::noteStart()
2009/10/02 08:16:02.355| AsyncCall.cc(32) make: make call AsyncJob::noteStart [call38]
2009/10/02 08:16:02.355| Adaptation::Icap::OptXact status in: [/ icapx11]
2009/10/02 08:16:02.355| Adaptation::Icap::OptXact from now on cannot be retried  [/ icapx11]
2009/10/02 08:16:02.355| Adaptation::Icap::OptXact opens connection to vmtest2.srn.sandia.gov:1344
2009/10/02 08:16:02.355| The AsyncCall Adaptation::Icap::Xaction::noteCommTimedout constructed, this=0x6000000000527ac0 [call39]
2009/10/02 08:16:02.355| The AsyncCall Adaptation::Icap::Xaction::noteCommClosed constructed, this=0x6000000000536dc0 [call40]
2009/10/02 08:16:02.356| The AsyncCall Adaptation::Icap::Xaction::noteCommConnected constructed, this=0x6000000000536e50 [call41]
2009/10/02 08:16:02.356| commConnectStart: FD 15, cb 0x6000000000536e50*1, vmtest2.srn.sandia.gov:1344
2009/10/02 08:16:02.356| Adaptation::Icap::OptXact status out: [FD 15;/ icapx11]
2009/10/02 08:16:02.356| leaving AsyncJob::noteStart()
2009/10/02 08:16:02.356| ModXact.cc(178) writeMore: checking whether to write more [URG/ icapx9]
2009/10/02 08:16:02.358| comm.cc(927) will call Adaptation::Icap::Xaction::noteCommConnected(FD 15, data=0x600000000052bdc8, lookup_wait=1) [call41]
2009/10/02 08:16:02.358| entering Adaptation::Icap::Xaction::noteCommConnected(FD 15, data=0x600000000052bdc8, lookup_wait=1)
2009/10/02 08:16:02.358| AsyncCall.cc(32) make: make call Adaptation::Icap::Xaction::noteCommConnected [call41]
2009/10/02 08:16:02.358| Adaptation::Icap::OptXact status in: [FD 15;/ icapx11]
2009/10/02 08:16:02.358| The AsyncCall Adaptation::Icap::Xaction::noteCommRead constructed, this=0x6000000000527ac0 [call45]
2009/10/02 08:16:02.358| The AsyncCall Adaptation::Icap::Xaction::noteCommTimedout constructed, this=0x6000000000500b90 [call46]
2009/10/02 08:16:02.358| AsyncJob.cc(218) dial: Adaptation::Icap::Xaction::noteCommConnected threw exception: icapRequest->parse(&buf, true, &status) > 0
2009/10/02 08:16:02.358| Xaction.cc(437) setOutcome: ICAP_ERR_OTHER
2009/10/02 08:16:02.358| Adaptation::Icap::OptXact will stop, reason: exception
2009/10/02 08:16:02.358| Adaptation::Icap::Xaction::noteCommConnected(FD 15, data=0x600000000052bdc8, lookup_wait=1) ends job [FD 15r;/ icapx11]
2009/10/02 08:16:02.359| Xaction.cc(173) closeConnection: not reusing pconn due to pending I/O [FD 15;/ icapx11]
2009/10/02 08:16:02.359| Xaction.cc(188) closeConnection: closing pconn [FD 15;/ icapx11]
2009/10/02 08:16:02.359| Initiate.cc(48) swanSong: swan sings [/ icapx11]
2009/10/02 08:16:02.359| Initiate.cc(55) swanSong: swan sang [/ icapx11]
2009/10/02 08:16:02.359| Adaptation::Icap::OptXact destructed, this=0x600000000052bdc8 [icapx11]
2009/10/02 08:16:02.359| AsyncJob.cc(140) callEnd: Adaptation::Icap::Xaction::noteCommConnected(FD 15, data=0x600000000052bdc8, lookup_wait=1) ended 0x600000000052c2c8
2009/10/02 08:16:02.359| leaving Adaptation::Icap::Xaction::noteCommConnected(FD 15, data=0x600000000052bdc8, lookup_wait=1)
2009/10/02 08:16:02.359| Launcher.cc(81) noteXactAbort: theXaction:0x600000000052bdc8 launches: 1
2009/10/02 08:16:02.359| Launcher.cc(123) canRepeat: 0
2009/10/02 08:16:02.359| Launcher.cc(91) noteXactAbort: cannot retry or repeat a failed transaction
2009/10/02 08:16:02.359| The AsyncCall Initiator::noteAdaptationQueryAbort constructed, this=0x600000000051b7a0 [call50]
2009/10/02 08:16:02.359| Initiate.cc(79) will call Initiator::noteAdaptationQueryAbort(0) [call50]
2009/10/02 08:16:02.359| Adaptation::Icap::Launcher::noteXactAbort(retriable:0, repeatable:0) ends job [ job10]
2009/10/02 08:16:02.359| Initiate.cc(48) swanSong: swan sings [ job10]
2009/10/02 08:16:02.359| Initiate.cc(55) swanSong: swan sang [ job10]
2009/10/02 08:16:02.359| AsyncJob.cc(140) callEnd: Adaptation::Icap::Launcher::noteXactAbort(retriable:0, repeatable:0) ended 0x6000000000527bd0
2009/10/02 08:16:02.359| entering Initiator::noteAdaptationQueryAbort(0)
2009/10/02 08:16:02.359| AsyncCall.cc(32) make: make call Initiator::noteAdaptationQueryAbort [call50]
2009/10/02 08:16:02.359| Adaptation::Icap::ServiceRep status in:[down,!opt,fetch]
2009/10/02 08:16:02.359| ServiceRep.cc(340) noteAdaptationQueryAbort: failed to fetch options [down,!opt]
2009/10/02 08:16:02.359| ServiceRep.cc(234) changeOptions: changes options from 0 to 0 [down,!opt]
2009/10/02 08:16:02.359| essential ICAP service is down after an options fetch failure: icap://vmtest2.srn.sandia.gov/nopres [down,!opt]
2009/10/02 08:16:02.359| ServiceRep.cc(349) handleNewOptions: got new options and is now [down,!opt]
2009/10/02 08:16:02.359| ServiceRep.cc(381) scheduleUpdate: raw OPTIONS fetch at 1254493142 or in 180 sec
2009/10/02 08:16:02.359| ServiceRep.cc(383) scheduleUpdate: last fetched at 1254492962 or 0 sec ago
2009/10/02 08:16:02.359| ServiceRep.cc(396) scheduleUpdate: will fetch OPTIONS in 180 sec
2009/10/02 08:16:02.360| ServiceRep.cc(222) scheduleNotification: will notify 1 clients
2009/10/02 08:16:02.360| The AsyncCall Adaptation::Icap::ServiceRep::noteTimeToNotify constructed, this=0x6000000000500b90 [call51]
2009/10/02 08:16:02.360| ServiceRep.cc(223) will call Adaptation::Icap::ServiceRep::noteTimeToNotify() [call51]
2009/10/02 08:16:02.360| Adaptation::Icap::ServiceRep status out:[down,!opt]
2009/10/02 08:16:02.360| leaving Initiator::noteAdaptationQueryAbort(0)
2009/10/02 08:16:02.360| entering Adaptation::Icap::ServiceRep::noteTimeToNotify()
2009/10/02 08:16:02.360| AsyncCall.cc(32) make: make call Adaptation::Icap::ServiceRep::noteTimeToNotify [call51]
2009/10/02 08:16:02.360| Adaptation::Icap::ServiceRep status in:[down,!opt]
2009/10/02 08:16:02.360| ServiceRep.cc(181) noteTimeToNotify: notifies 1 clients [down,!opt,notif]
2009/10/02 08:16:02.360| ServiceRep.cc(189) will call Adaptation::Icap::ModXact::noteServiceReady() [call36]
2009/10/02 08:16:02.360| Adaptation::Icap::ServiceRep status out:[down,!opt]
2009/10/02 08:16:02.360| leaving Adaptation::Icap::ServiceRep::noteTimeToNotify()
2009/10/02 08:16:02.360| entering Adaptation::Icap::ModXact::noteServiceReady()
2009/10/02 08:16:02.360| AsyncCall.cc(32) make: make call Adaptation::Icap::ModXact::noteServiceReady [call36]
2009/10/02 08:16:02.360| Adaptation::Icap::ModXact status in: [URG/ icapx9]
2009/10/02 08:16:02.360| Adaptation::Icap::ModXact from now on cannot be retried  [RG/ icapx9]
2009/10/02 08:16:02.360| Adaptation::Icap::ModXact still cannot be repeated because ICAP service is unusable [RG/ icapx9]
2009/10/02 08:16:02.360| AsyncJob.cc(218) dial: Adaptation::Icap::ModXact::noteServiceReady threw exception: ICAP service is unusable
2009/10/02 08:16:02.360| Xaction.cc(437) setOutcome: ICAP_ERR_OTHER
2009/10/02 08:16:02.360| Adaptation::Icap::ModXact will stop, reason: exception
2009/10/02 08:16:02.360| Adaptation::Icap::ModXact::noteServiceReady() ends job [RG/ icapx9]
2009/10/02 08:16:02.360| ModXact.cc(1093) swanSong: swan sings [RG/ icapx9]
2009/10/02 08:16:02.360| ModXact.cc(441) stopWriting: will no longer write [RG/ icapx9]
2009/10/02 08:16:02.360| ModXact.cc(359) virginConsume: consumption guards: 00001
2009/10/02 08:16:02.360| ModXact.cc(378) virginConsume: postponing consumption from  [0<=2507<=4264 2507+1588 pipe0x600000000050f1c8 prod0x6000000000509480 cons0x600000000051bd70]
2009/10/02 08:16:02.360| ModXact.cc(548) stopSending: Enter stop sending 
2009/10/02 08:16:02.360| ModXact.cc(551) stopSending: Proceed with stop sending 
2009/10/02 08:16:02.360| ModXact.cc(563) stopSending: will not start sending [RG/w icapx9]
2009/10/02 08:16:02.360| ModXact.cc(578) checkConsuming: will stop consuming [RG/wS icapx9]
2009/10/02 08:16:02.361| History.cc(95) processingTime:  current total: 7 0x60000000004f02b0
2009/10/02 08:16:02.361| Initiate.cc(48) swanSong: swan sings [G/RwS icapx9]
2009/10/02 08:16:02.361| Initiate.cc(55) swanSong: swan sang [G/RwS icapx9]
2009/10/02 08:16:02.361| Adaptation::Icap::ModXact destructed, this=0x600000000051b868 [icapx9]
2009/10/02 08:16:02.361| AsyncJob.cc(140) callEnd: Adaptation::Icap::ModXact::noteServiceReady() ended 0x600000000051be20
2009/10/02 08:16:02.361| leaving Adaptation::Icap::ModXact::noteServiceReady()
2009/10/02 08:16:02.361| Launcher.cc(81) noteXactAbort: theXaction:0x600000000051b868 launches: 1
2009/10/02 08:16:02.361| Launcher.cc(123) canRepeat: 0
2009/10/02 08:16:02.361| Launcher.cc(91) noteXactAbort: cannot retry or repeat a failed transaction
2009/10/02 08:16:02.361| The AsyncCall Initiator::noteAdaptationQueryAbort constructed, this=0x600000000051b7a0 [call53]
2009/10/02 08:16:02.361| Initiate.cc(79) will call Initiator::noteAdaptationQueryAbort(0) [call53]
2009/10/02 08:16:02.361| Adaptation::Icap::Launcher::noteXactAbort(retriable:0, repeatable:0) ends job [ job8]
2009/10/02 08:16:02.361| ModXact.cc(1698) swanSong: swan sings
2009/10/02 08:16:02.361| History.cc(86) stop: stop ICAPModXactLauncher level=1 time=1+7 0x60000000004f02b0
2009/10/02 08:16:02.361| Initiate.cc(48) swanSong: swan sings [ job8]
2009/10/02 08:16:02.361| Initiate.cc(55) swanSong: swan sang [ job8]
2009/10/02 08:16:02.361| AsyncJob.cc(140) callEnd: Adaptation::Icap::Launcher::noteXactAbort(retriable:0, repeatable:0) ended 0x60000000005176a8
2009/10/02 08:16:02.361| entering Initiator::noteAdaptationQueryAbort(0)
2009/10/02 08:16:02.361| AsyncCall.cc(32) make: make call Initiator::noteAdaptationQueryAbort [call53]
2009/10/02 08:16:02.361| Iterator status in: [ job7]
2009/10/02 08:16:02.361| Iterator.cc(111) noteAdaptationQueryAbort: final: 0 plan: testresponse[0..1]
2009/10/02 08:16:02.361| ServiceGroups.cc(171) findService: testresponse has no matching services
2009/10/02 08:16:02.361| The AsyncCall Initiator::noteAdaptationQueryAbort constructed, this=0x60000000005175a0 [call54]
2009/10/02 08:16:02.361| Initiate.cc(79) will call Initiator::noteAdaptationQueryAbort(1) [call54]
2009/10/02 08:16:02.361| Iterator will stop, reason: group failure
2009/10/02 08:16:02.361| Initiator::noteAdaptationQueryAbort(0) ends job [Stopped, reason:group failure job7]
2009/10/02 08:16:02.361| Initiate.cc(48) swanSong: swan sings [Stopped, reason:group failure job7]
2009/10/02 08:16:02.361| Initiate.cc(55) swanSong: swan sang [Stopped, reason:group failure job7]
2009/10/02 08:16:02.361| AsyncJob.cc(140) callEnd: Initiator::noteAdaptationQueryAbort(0) ended 0x6000000000513410
2009/10/02 08:16:02.361| leaving Initiator::noteAdaptationQueryAbort(0)
2009/10/02 08:16:02.361| entering Initiator::noteAdaptationQueryAbort(1)
2009/10/02 08:16:02.361| AsyncCall.cc(32) make: make call Initiator::noteAdaptationQueryAbort [call54]
2009/10/02 08:16:02.362| HttpStateData status in: [ job5]
2009/10/02 08:16:02.362| HttpStateData status out: [ job5]
2009/10/02 08:16:02.362| leaving Initiator::noteAdaptationQueryAbort(1)
2009/10/02 08:16:02.362| HttpStateData will NOT delete in-call job, reason: HttpStateData::httpStateConnClosed
2009/10/02 08:16:02.362| httpStateData::httpStateConnClosed(FD 12, data=0x6000000000509478) ends job [Stopped, reason:HttpStateData::httpStateConnClosed job5]
2009/10/02 08:16:02.362| AsyncJob.cc(140) callEnd: httpStateData::httpStateConnClosed(FD 12, data=0x6000000000509478) ended 0x6000000000509558
2009/10/02 08:16:02.362| ConnStateData will NOT delete in-call job, reason: ConnStateData::connStateClosed
2009/10/02 08:16:02.362| ConnStateData::connStateClosed(FD 11, data=0x60000000004a9478) ends job [Stopped, reason:ConnStateData::connStateClosed job2]
2009/10/02 08:16:02.362| History.cc(95) processingTime:  current total: 8 0x60000000004f02b0
2009/10/02 08:16:02.363| AsyncJob.cc(140) callEnd: ConnStateData::connStateClosed(FD 11, data=0x60000000004a9478) ended 0x60000000004a9600
2009/10/02 08:16:02.375| AsyncJob of type ConnStateData constructed, this=0x60000000004a9600 [async12]
2009/10/02 08:16:03.021| AsyncJob of type ClientHttpRequest constructed, this=0x60000000004b1d18 [async13]
2009/10/02 08:16:03.021| AsyncJob of type AccessCheck constructed, this=0x60000000004ec308 [async14]
2009/10/02 08:16:03.021| HttpRequest.cc(387) icapHistory: made 0x60000000004f02b0*1 for 0x60000000004839f0
2009/10/02 08:16:03.021| History.cc(74) start: start ACL level=1 time=0 0x60000000004f02b0
2009/10/02 08:16:03.021| AccessCheck.cc(49) AccessCheck: AccessCheck constructed for REQMOD PRECACHE
2009/10/02 08:16:03.021| The AsyncCall AsyncJob::noteStart constructed, this=0x60000000004ad470 [call65]
2009/10/02 08:16:03.021| AsyncJob.cc(18) will call AsyncJob::noteStart() [call65]
2009/10/02 08:16:03.021| entering AsyncJob::noteStart()
2009/10/02 08:16:03.021| AsyncCall.cc(32) make: make call AsyncJob::noteStart [call65]
2009/10/02 08:16:03.021| AccessCheck status in: [ job14]
2009/10/02 08:16:03.021| AccessCheck.cc(74) check: start checking
2009/10/02 08:16:03.021| AccessCheck.cc(188) isCandidate: checking candidacy of 1, group testresponse
2009/10/02 08:16:03.021| ServiceGroups.cc(126) findService: testresponse serves another location
2009/10/02 08:16:03.021| AccessCheck.cc(198) isCandidate: testresponse ignores
2009/10/02 08:16:03.021| AccessCheck.cc(96) checkCandidates: has 0 rules
2009/10/02 08:16:03.021| AccessCheck.cc(111) checkCandidates: NO candidates left
2009/10/02 08:16:03.021| AccessCheck.cc(155) callBack: NULL
2009/10/02 08:16:03.021| client_side_request.cc(636) adaptationAclCheckDone: 0x60000000004e3fa8 adaptationAclCheckDone called
2009/10/02 08:16:03.022| AccessCheck will stop, reason: done
2009/10/02 08:16:03.022| AsyncJob::noteStart() ends job [Stopped, reason:done job14]
2009/10/02 08:16:03.022| History.cc(86) stop: stop ACL level=1 time=0+0 0x60000000004f02b0
2009/10/02 08:16:03.022| AsyncJob.cc(140) callEnd: AsyncJob::noteStart() ended 0x60000000004ec308
2009/10/02 08:16:03.022| leaving AsyncJob::noteStart()
2009/10/02 08:16:03.192| AsyncJob of type HttpStateData constructed, this=0x6000000000509558 [async15]
2009/10/02 08:16:03.295| AsyncJob of type AccessCheck constructed, this=0x60000000004ec308 [async16]
2009/10/02 08:16:03.295| History.cc(74) start: start ACL level=1 time=0 0x60000000004f02b0
2009/10/02 08:16:03.295| AccessCheck.cc(49) AccessCheck: AccessCheck constructed for RESPMOD PRECACHE
2009/10/02 08:16:03.295| The AsyncCall AsyncJob::noteStart constructed, this=0x60000000004ad470 [call77]
2009/10/02 08:16:03.295| AsyncJob.cc(18) will call AsyncJob::noteStart() [call77]
2009/10/02 08:16:03.295| entering AsyncJob::noteStart()
2009/10/02 08:16:03.295| AsyncCall.cc(32) make: make call AsyncJob::noteStart [call77]
2009/10/02 08:16:03.295| AccessCheck status in: [ job16]
2009/10/02 08:16:03.295| AccessCheck.cc(74) check: start checking
2009/10/02 08:16:03.296| AccessCheck.cc(188) isCandidate: checking candidacy of 1, group testresponse
2009/10/02 08:16:03.296| ServiceGroups.cc(134) findService: testresponse checks service at 0
2009/10/02 08:16:03.296| ServiceGroups.cc(159) findService: testresponse searches for best essential service from 0
2009/10/02 08:16:03.296| ServiceGroups.cc(166) findService: testresponse has best essential service at 0
2009/10/02 08:16:03.296| AccessCheck.cc(198) isCandidate: testresponse wants
2009/10/02 08:16:03.296| AccessCheck.cc(80) check: check: rule '1' is a candidate
2009/10/02 08:16:03.296| AccessCheck.cc(96) checkCandidates: has 1 rules
2009/10/02 08:16:03.296| AccessCheck.cc(119) AccessCheckCallbackWrapper: callback answer=1
2009/10/02 08:16:03.296| AccessCheck.cc(134) noteAnswer: 1 answer=1
2009/10/02 08:16:03.296| AccessCheck.cc(171) topGroup: top group for 1 is 0x60000000001bcbf0*2
2009/10/02 08:16:03.296| AccessCheck.cc(155) callBack: 0x60000000001bcbf0*2
2009/10/02 08:16:03.296| Server.cc(526) startAdaptation: will send virgin reply body to 0x600000000050f1c8*2; size: 12716
2009/10/02 08:16:03.296| AsyncJob of type Iterator constructed, this=0x6000000000513410 [async17]
2009/10/02 08:16:03.296| The AsyncCall AsyncJob::noteStart constructed, this=0x600000000052bc20 [call78]
2009/10/02 08:16:03.296| AsyncJob.cc(18) will call AsyncJob::noteStart() [call78]
2009/10/02 08:16:03.296| AccessCheck will stop, reason: done
2009/10/02 08:16:03.296| AsyncJob::noteStart() ends job [Stopped, reason:done job16]
2009/10/02 08:16:03.296| History.cc(86) stop: stop ACL level=1 time=0+0 0x60000000004f02b0
2009/10/02 08:16:03.296| AsyncJob.cc(140) callEnd: AsyncJob::noteStart() ended 0x60000000004ec308
2009/10/02 08:16:03.296| leaving AsyncJob::noteStart()
2009/10/02 08:16:03.296| entering AsyncJob::noteStart()
2009/10/02 08:16:03.296| AsyncCall.cc(32) make: make call AsyncJob::noteStart [call78]
2009/10/02 08:16:03.296| Iterator status in: [ job17]
2009/10/02 08:16:03.296| ServiceGroups.cc(134) findService: testresponse checks service at 0
2009/10/02 08:16:03.296| ServiceGroups.cc(159) findService: testresponse searches for best essential service from 0
2009/10/02 08:16:03.296| ServiceGroups.cc(166) findService: testresponse has best essential service at 0
2009/10/02 08:16:03.296| Iterator.cc(49) step: #1 plan: testresponse[0..1]
2009/10/02 08:16:03.296| Iterator.cc(69) step: using adaptation service: testresp
2009/10/02 08:16:03.296| AsyncJob of type Adaptation::Icap::ModXactLauncher constructed, this=0x60000000005176a8 [async18]
2009/10/02 08:16:03.296| History.cc(74) start: start ICAPModXactLauncher level=1 time=0 0x60000000004f02b0
2009/10/02 08:16:03.296| The AsyncCall AsyncJob::noteStart constructed, this=0x60000000004ad470 [call80]
2009/10/02 08:16:03.297| AsyncJob.cc(18) will call AsyncJob::noteStart() [call80]
2009/10/02 08:16:03.297| Iterator status out: [ job17]
2009/10/02 08:16:03.297| leaving AsyncJob::noteStart()
2009/10/02 08:16:03.297| entering AsyncJob::noteStart()
2009/10/02 08:16:03.297| AsyncCall.cc(32) make: make call AsyncJob::noteStart [call80]
2009/10/02 08:16:03.297| Adaptation::Icap::ModXactLauncher status in: [ job18]
2009/10/02 08:16:03.297| Launcher.cc(42) launchXaction: launching first xaction #1
2009/10/02 08:16:03.297| AsyncJob of type Adaptation::Icap::ModXact constructed, this=0x600000000051be20 [async19]
2009/10/02 08:16:03.297| Adaptation::Icap::ModXact constructed, this=0x600000000051b868 [icapx19]
2009/10/02 08:16:03.297| ModXact.cc(70) ModXact: initialized. [RG/ icapx19]
2009/10/02 08:16:03.297| Adaptation::Icap::ModXact from now on cannot be repeated because over icap_retry_limit [RG/ icapx19]
2009/10/02 08:16:03.297| The AsyncCall AsyncJob::noteStart constructed, this=0x600000000052bc20 [call81]
2009/10/02 08:16:03.297| AsyncJob.cc(18) will call AsyncJob::noteStart() [call81]
2009/10/02 08:16:03.297| Adaptation::Icap::ModXactLauncher status out: [ job18]
2009/10/02 08:16:03.297| leaving AsyncJob::noteStart()
2009/10/02 08:16:03.297| entering AsyncJob::noteStart()
2009/10/02 08:16:03.297| AsyncCall.cc(32) make: make call AsyncJob::noteStart [call81]
2009/10/02 08:16:03.297| Adaptation::Icap::ModXact status in: [RG/ icapx19]
2009/10/02 08:16:03.297| ModXact.cc(1522) estimateVirginBody: expects virgin body from 0x600000000050f1c8*4; size: 12716
2009/10/02 08:16:03.297| ModXact.cc(98) waitForService: will wait for the ICAP service [RG/ icapx19]
2009/10/02 08:16:03.297| The AsyncCall Adaptation::Icap::ModXact::noteServiceReady constructed, this=0x6000000000504e70 [call83]
2009/10/02 08:16:03.297| ServiceRep.cc(201) callWhenReady: Adaptation::Icap::Service is asked to call Adaptation::Icap::ModXact::noteServiceReady() when ready [down,!opt]
2009/10/02 08:16:03.297| AsyncJob.cc(218) dial: AsyncJob::noteStart threw exception: !broken()
2009/10/02 08:16:03.298| Xaction.cc(437) setOutcome: ICAP_ERR_OTHER
2009/10/02 08:16:03.298| Adaptation::Icap::ModXact will stop, reason: exception
2009/10/02 08:16:03.298| AsyncJob::noteStart() ends job [URG/ icapx19]
2009/10/02 08:16:03.298| ModXact.cc(1093) swanSong: swan sings [URG/ icapx19]
2009/10/02 08:16:03.298| ModXact.cc(441) stopWriting: will no longer write [URG/ icapx19]
2009/10/02 08:16:03.298| ModXact.cc(359) virginConsume: consumption guards: 01001
2009/10/02 08:16:03.298| ModXact.cc(548) stopSending: Enter stop sending 
2009/10/02 08:16:03.298| ModXact.cc(551) stopSending: Proceed with stop sending 
2009/10/02 08:16:03.298| ModXact.cc(563) stopSending: will not start sending [URG/w icapx19]
2009/10/02 08:16:03.298| ModXact.cc(578) checkConsuming: will stop consuming [URG/wS icapx19]
2009/10/02 08:16:03.298| History.cc(95) processingTime:  current total: 1 0x60000000004f02b0
2009/10/02 08:16:03.298| Initiate.cc(48) swanSong: swan sings [UG/RwS icapx19]
2009/10/02 08:16:03.298| Initiate.cc(55) swanSong: swan sang [UG/RwS icapx19]
2009/10/02 08:16:03.298| Adaptation::Icap::ModXact destructed, this=0x600000000051b868 [icapx19]
2009/10/02 08:16:03.298| AsyncJob.cc(140) callEnd: AsyncJob::noteStart() ended 0x600000000051be20
2009/10/02 08:16:03.298| leaving AsyncJob::noteStart()
2009/10/02 08:16:03.298| Launcher.cc(81) noteXactAbort: theXaction:0x600000000051b868 launches: 1
2009/10/02 08:16:03.298| Launcher.cc(42) launchXaction: launching retry xaction #2
2009/10/02 08:16:03.298| AsyncJob of type Adaptation::Icap::ModXact constructed, this=0x600000000051be20 [async20]
2009/10/02 08:16:03.298| Adaptation::Icap::ModXact constructed, this=0x600000000051b868 [icapx20]
2009/10/02 08:16:03.298| ModXact.cc(70) ModXact: initialized. [RG/ icapx20]
2009/10/02 08:16:03.298| Adaptation::Icap::ModXact from now on cannot be retried  [RG/ icapx20]
2009/10/02 08:16:03.298| Adaptation::Icap::ModXact from now on cannot be repeated because over icap_retry_limit [RG/ icapx20]
2009/10/02 08:16:03.298| The AsyncCall AsyncJob::noteStart constructed, this=0x60000000004ad470 [call85]
2009/10/02 08:16:03.298| AsyncJob.cc(18) will call AsyncJob::noteStart() [call85]
2009/10/02 08:16:03.298| entering AsyncJob::noteStart()
2009/10/02 08:16:03.298| AsyncCall.cc(32) make: make call AsyncJob::noteStart [call85]
2009/10/02 08:16:03.298| Adaptation::Icap::ModXact status in: [RG/ icapx20]
2009/10/02 08:16:03.298| ModXact.cc(1522) estimateVirginBody: expects virgin body from 0x600000000050f1c8*4; size: 12716
2009/10/02 08:16:03.298| ModXact.cc(98) waitForService: will wait for the ICAP service [RG/ icapx20]
2009/10/02 08:16:03.298| The AsyncCall Adaptation::Icap::ModXact::noteServiceReady constructed, this=0x6000000000504e70 [call87]
2009/10/02 08:16:03.299| ServiceRep.cc(201) callWhenReady: Adaptation::Icap::Service is asked to call Adaptation::Icap::ModXact::noteServiceReady() when ready [down,!opt]
2009/10/02 08:16:03.299| AsyncJob.cc(218) dial: AsyncJob::noteStart threw exception: !broken()
2009/10/02 08:16:03.299| Xaction.cc(437) setOutcome: ICAP_ERR_OTHER
2009/10/02 08:16:03.299| Adaptation::Icap::ModXact will stop, reason: exception
2009/10/02 08:16:03.299| AsyncJob::noteStart() ends job [URG/ icapx20]
2009/10/02 08:16:03.299| ModXact.cc(1093) swanSong: swan sings [URG/ icapx20]
2009/10/02 08:16:03.299| ModXact.cc(441) stopWriting: will no longer write [URG/ icapx20]
2009/10/02 08:16:03.299| ModXact.cc(359) virginConsume: consumption guards: 00001
2009/10/02 08:16:03.299| ModXact.cc(378) virginConsume: postponing consumption from  [0<=1074<=12716 1074+973 pipe0x600000000050f1c8 prod0x6000000000509480 cons0x600000000051bd70]
2009/10/02 08:16:03.299| ModXact.cc(548) stopSending: Enter stop sending 
2009/10/02 08:16:03.299| ModXact.cc(551) stopSending: Proceed with stop sending 
2009/10/02 08:16:03.299| ModXact.cc(563) stopSending: will not start sending [URG/w icapx20]
2009/10/02 08:16:03.299| ModXact.cc(578) checkConsuming: will stop consuming [URG/wS icapx20]
2009/10/02 08:16:03.299| History.cc(95) processingTime:  current total: 2 0x60000000004f02b0
2009/10/02 08:16:03.299| Initiate.cc(48) swanSong: swan sings [UG/RwS icapx20]
2009/10/02 08:16:03.299| Initiate.cc(55) swanSong: swan sang [UG/RwS icapx20]
2009/10/02 08:16:03.299| Adaptation::Icap::ModXact destructed, this=0x600000000051b868 [icapx20]
2009/10/02 08:16:03.299| AsyncJob.cc(140) callEnd: AsyncJob::noteStart() ended 0x600000000051be20
2009/10/02 08:16:03.299| leaving AsyncJob::noteStart()
2009/10/02 08:16:03.299| Launcher.cc(81) noteXactAbort: theXaction:0x600000000051b868 launches: 2
2009/10/02 08:16:03.299| Launcher.cc(123) canRepeat: 0
2009/10/02 08:16:03.299| Launcher.cc(91) noteXactAbort: cannot retry or repeat a failed transaction
2009/10/02 08:16:03.299| The AsyncCall Initiator::noteAdaptationQueryAbort constructed, this=0x60000000004ad470 [call89]
2009/10/02 08:16:03.299| Initiate.cc(79) will call Initiator::noteAdaptationQueryAbort(0) [call89]
2009/10/02 08:16:03.299| Adaptation::Icap::Launcher::noteXactAbort(retriable:0, repeatable:0) ends job [ job18]
2009/10/02 08:16:03.299| ModXact.cc(1698) swanSong: swan sings
2009/10/02 08:16:03.299| History.cc(86) stop: stop ICAPModXactLauncher level=1 time=0+2 0x60000000004f02b0
2009/10/02 08:16:03.299| Initiate.cc(48) swanSong: swan sings [ job18]
2009/10/02 08:16:03.300| Initiate.cc(55) swanSong: swan sang [ job18]
2009/10/02 08:16:03.300| AsyncJob.cc(140) callEnd: Adaptation::Icap::Launcher::noteXactAbort(retriable:0, repeatable:0) ended 0x60000000005176a8
2009/10/02 08:16:03.300| entering Initiator::noteAdaptationQueryAbort(0)
2009/10/02 08:16:03.300| AsyncCall.cc(32) make: make call Initiator::noteAdaptationQueryAbort [call89]
2009/10/02 08:16:03.300| Iterator status in: [ job17]
2009/10/02 08:16:03.300| Iterator.cc(111) noteAdaptationQueryAbort: final: 0 plan: testresponse[0..1]
2009/10/02 08:16:03.300| ServiceGroups.cc(171) findService: testresponse has no matching services
2009/10/02 08:16:03.300| The AsyncCall Initiator::noteAdaptationQueryAbort constructed, this=0x600000000052bc20 [call90]
2009/10/02 08:16:03.300| Initiate.cc(79) will call Initiator::noteAdaptationQueryAbort(1) [call90]
2009/10/02 08:16:03.300| Iterator will stop, reason: group failure
2009/10/02 08:16:03.300| Initiator::noteAdaptationQueryAbort(0) ends job [Stopped, reason:group failure job17]
2009/10/02 08:16:03.300| Initiate.cc(48) swanSong: swan sings [Stopped, reason:group failure job17]
2009/10/02 08:16:03.300| Initiate.cc(55) swanSong: swan sang [Stopped, reason:group failure job17]
2009/10/02 08:16:03.300| AsyncJob.cc(140) callEnd: Initiator::noteAdaptationQueryAbort(0) ended 0x6000000000513410
2009/10/02 08:16:03.300| leaving Initiator::noteAdaptationQueryAbort(0)
2009/10/02 08:16:03.300| entering Initiator::noteAdaptationQueryAbort(1)
2009/10/02 08:16:03.300| AsyncCall.cc(32) make: make call Initiator::noteAdaptationQueryAbort [call90]
2009/10/02 08:16:03.300| HttpStateData status in: [ job15]
2009/10/02 08:16:03.300| HttpStateData status out: [ job15]
2009/10/02 08:16:03.300| leaving Initiator::noteAdaptationQueryAbort(1)
2009/10/02 08:16:03.300| HttpStateData will NOT delete in-call job, reason: HttpStateData::httpStateConnClosed
2009/10/02 08:16:03.300| httpStateData::httpStateConnClosed(FD 12, data=0x6000000000509478) ends job [Stopped, reason:HttpStateData::httpStateConnClosed job15]
2009/10/02 08:16:03.300| AsyncJob.cc(140) callEnd: httpStateData::httpStateConnClosed(FD 12, data=0x6000000000509478) ended 0x6000000000509558
2009/10/02 08:16:03.301| ConnStateData will NOT delete in-call job, reason: ConnStateData::connStateClosed
2009/10/02 08:16:03.301| ConnStateData::connStateClosed(FD 11, data=0x60000000004a9478) ends job [Stopped, reason:ConnStateData::connStateClosed job12]
2009/10/02 08:16:03.301| History.cc(95) processingTime:  current total: 2 0x60000000004f02b0
2009/10/02 08:16:03.301| AsyncJob.cc(140) callEnd: ConnStateData::connStateClosed(FD 11, data=0x60000000004a9478) ended 0x60000000004a9600