2009/10/01 16:11:50| Starting Squid Cache version 3.1.0.14 for ia64-unknown-linux-gnu...
2009/10/01 16:11:50| chdir: /usr/local/proxy-test/squid31/var/cache: (2) No such file or directory
2009/10/01 16:11:50.412| Config.cc(91) finalize: Found 1 service configs.
2009/10/01 16:11:50.412| AsyncJob of type Adaptation::Icap::ServiceRep constructed, this=0x60000000004a52e8 [async1]
2009/10/01 16:11:50.412| Service.cc(12) Service: creating adaptation service testresp
2009/10/01 16:11:50.412| Config.cc(105) finalize: Created 1 message adaptation services.
2009/10/01 16:11:50.412| Adaptation support is on
2009/10/01 16:11:50.412| Config.cc(117) FinalizeEach: Initialized 1 message adaptation services
2009/10/01 16:11:50.412| ServiceGroups.cc(78) finalize: finalized adaptation set: testresponse
2009/10/01 16:11:50.412| Config.cc(117) FinalizeEach: Initialized 1 message adaptation service groups
2009/10/01 16:11:50.412| Config.cc(117) FinalizeEach: Initialized 1 message adaptation access rules
2009/10/01 16:11:55.889| AsyncJob of type ConnStateData constructed, this=0x60000000004a9610 [async2]
2009/10/01 16:11:55.889| AsyncJob of type ClientHttpRequest constructed, this=0x60000000004b1d28 [async3]
2009/10/01 16:11:55.890| AsyncJob of type AccessCheck constructed, this=0x60000000004ec2c8 [async4]
2009/10/01 16:11:55.890| HttpRequest.cc(387) icapHistory: made 0x60000000004f0290*1 for 0x6000000000483a00
2009/10/01 16:11:55.890| History.cc(74) start: start ACL level=1 time=0 0x60000000004f0290
2009/10/01 16:11:55.890| AccessCheck.cc(49) AccessCheck: AccessCheck constructed for REQMOD PRECACHE
2009/10/01 16:11:55.890| The AsyncCall AsyncJob::noteStart constructed, this=0x60000000004f0380 [call17]
2009/10/01 16:11:55.890| AsyncJob.cc(18) will call AsyncJob::noteStart() [call17]
2009/10/01 16:11:55.890| entering AsyncJob::noteStart()
2009/10/01 16:11:55.890| AsyncCall.cc(32) make: make call AsyncJob::noteStart [call17]
2009/10/01 16:11:55.890| AccessCheck status in: [ job4]
2009/10/01 16:11:55.890| AccessCheck.cc(74) check: start checking
2009/10/01 16:11:55.890| AccessCheck.cc(188) isCandidate: checking candidacy of 1, group testresponse
2009/10/01 16:11:55.890| ServiceGroups.cc(126) findService: testresponse serves another location
2009/10/01 16:11:55.890| AccessCheck.cc(198) isCandidate: testresponse ignores
2009/10/01 16:11:55.890| AccessCheck.cc(96) checkCandidates: has 0 rules
2009/10/01 16:11:55.890| AccessCheck.cc(111) checkCandidates: NO candidates left
2009/10/01 16:11:55.890| AccessCheck.cc(155) callBack: NULL
2009/10/01 16:11:55.890| client_side_request.cc(636) adaptationAclCheckDone: 0x60000000004e3fa8 adaptationAclCheckDone called
2009/10/01 16:11:55.891| AccessCheck will stop, reason: done
2009/10/01 16:11:55.891| AsyncJob::noteStart() ends job [Stopped, reason:done job4]
2009/10/01 16:11:55.891| History.cc(86) stop: stop ACL level=1 time=0+1 0x60000000004f0290
2009/10/01 16:11:55.891| AsyncJob.cc(140) callEnd: AsyncJob::noteStart() ended 0x60000000004ec2c8
2009/10/01 16:11:55.891| leaving AsyncJob::noteStart()
2009/10/01 16:11:55.892| AsyncJob of type HttpStateData constructed, this=0x6000000000509558 [async5]
2009/10/01 16:11:55.894| AsyncJob of type AccessCheck constructed, this=0x60000000004ec2c8 [async6]
2009/10/01 16:11:55.894| History.cc(74) start: start ACL level=1 time=1 0x60000000004f0290
2009/10/01 16:11:55.894| AccessCheck.cc(49) AccessCheck: AccessCheck constructed for RESPMOD PRECACHE
2009/10/01 16:11:55.894| The AsyncCall AsyncJob::noteStart constructed, this=0x6000000000504ed0 [call28]
2009/10/01 16:11:55.894| AsyncJob.cc(18) will call AsyncJob::noteStart() [call28]
2009/10/01 16:11:55.894| entering AsyncJob::noteStart()
2009/10/01 16:11:55.894| AsyncCall.cc(32) make: make call AsyncJob::noteStart [call28]
2009/10/01 16:11:55.894| AccessCheck status in: [ job6]
2009/10/01 16:11:55.894| AccessCheck.cc(74) check: start checking
2009/10/01 16:11:55.894| AccessCheck.cc(188) isCandidate: checking candidacy of 1, group testresponse
2009/10/01 16:11:55.894| ServiceGroups.cc(134) findService: testresponse checks service at 0
2009/10/01 16:11:55.894| ServiceGroups.cc(144) findService: testresponse has matching service at 0
2009/10/01 16:11:55.894| AccessCheck.cc(198) isCandidate: testresponse wants
2009/10/01 16:11:55.894| AccessCheck.cc(80) check: check: rule '1' is a candidate
2009/10/01 16:11:55.894| AccessCheck.cc(96) checkCandidates: has 1 rules
2009/10/01 16:11:55.894| AccessCheck.cc(119) AccessCheckCallbackWrapper: callback answer=1
2009/10/01 16:11:55.894| AccessCheck.cc(134) noteAnswer: 1 answer=1
2009/10/01 16:11:55.894| AccessCheck.cc(171) topGroup: top group for 1 is 0x60000000001bcbf0*2
2009/10/01 16:11:55.894| AccessCheck.cc(155) callBack: 0x60000000001bcbf0*2
2009/10/01 16:11:55.894| Server.cc(526) startAdaptation: will send virgin reply body to 0x600000000050f1c8*2; size: 50
2009/10/01 16:11:55.894| AsyncJob of type Iterator constructed, this=0x6000000000513410 [async7]
2009/10/01 16:11:55.894| The AsyncCall AsyncJob::noteStart constructed, this=0x600000000050f0f0 [call29]
2009/10/01 16:11:55.894| AsyncJob.cc(18) will call AsyncJob::noteStart() [call29]
2009/10/01 16:11:55.894| AccessCheck will stop, reason: done
2009/10/01 16:11:55.895| AsyncJob::noteStart() ends job [Stopped, reason:done job6]
2009/10/01 16:11:55.895| History.cc(86) stop: stop ACL level=1 time=1+0 0x60000000004f0290
2009/10/01 16:11:55.895| AsyncJob.cc(140) callEnd: AsyncJob::noteStart() ended 0x60000000004ec2c8
2009/10/01 16:11:55.895| leaving AsyncJob::noteStart()
2009/10/01 16:11:55.895| entering AsyncJob::noteStart()
2009/10/01 16:11:55.895| AsyncCall.cc(32) make: make call AsyncJob::noteStart [call29]
2009/10/01 16:11:55.895| Iterator status in: [ job7]
2009/10/01 16:11:55.895| ServiceGroups.cc(134) findService: testresponse checks service at 0
2009/10/01 16:11:55.895| ServiceGroups.cc(144) findService: testresponse has matching service at 0
2009/10/01 16:11:55.895| Iterator.cc(49) step: #1 plan: testresponse[0..1]
2009/10/01 16:11:55.895| Iterator.cc(69) step: using adaptation service: testresp
2009/10/01 16:11:55.895| AsyncJob of type Adaptation::Icap::ModXactLauncher constructed, this=0x6000000000517488 [async8]
2009/10/01 16:11:55.895| History.cc(74) start: start ICAPModXactLauncher level=1 time=1 0x60000000004f0290
2009/10/01 16:11:55.895| The AsyncCall AsyncJob::noteStart constructed, this=0x60000000005132d0 [call32]
2009/10/01 16:11:55.895| AsyncJob.cc(18) will call AsyncJob::noteStart() [call32]
2009/10/01 16:11:55.895| Iterator status out: [ job7]
2009/10/01 16:11:55.895| leaving AsyncJob::noteStart()
2009/10/01 16:11:55.895| entering AsyncJob::noteStart()
2009/10/01 16:11:55.895| AsyncCall.cc(32) make: make call AsyncJob::noteStart [call32]
2009/10/01 16:11:55.895| Adaptation::Icap::ModXactLauncher status in: [ job8]
2009/10/01 16:11:55.895| Launcher.cc(42) launchXaction: launching first xaction #1
2009/10/01 16:11:55.895| AsyncJob of type Adaptation::Icap::ModXact constructed, this=0x600000000051bc00 [async9]
2009/10/01 16:11:55.895| Adaptation::Icap::ModXact constructed, this=0x600000000051b648 [icapx9]
2009/10/01 16:11:55.895| ModXact.cc(70) ModXact: initialized. [RG/ icapx9]
2009/10/01 16:11:55.895| Adaptation::Icap::ModXact from now on cannot be repeated because over icap_retry_limit [RG/ icapx9]
2009/10/01 16:11:55.895| The AsyncCall AsyncJob::noteStart constructed, this=0x600000000050f0f0 [call33]
2009/10/01 16:11:55.895| AsyncJob.cc(18) will call AsyncJob::noteStart() [call33]
2009/10/01 16:11:55.895| Adaptation::Icap::ModXactLauncher status out: [ job8]
2009/10/01 16:11:55.895| leaving AsyncJob::noteStart()
2009/10/01 16:11:55.895| entering AsyncJob::noteStart()
2009/10/01 16:11:55.895| AsyncCall.cc(32) make: make call AsyncJob::noteStart [call33]
2009/10/01 16:11:55.896| Adaptation::Icap::ModXact status in: [RG/ icapx9]
2009/10/01 16:11:55.896| ModXact.cc(1522) estimateVirginBody: expects virgin body from 0x600000000050f1c8*3; size: 50
2009/10/01 16:11:55.896| ModXact.cc(98) waitForService: will wait for the ICAP service [RG/ icapx9]
2009/10/01 16:11:55.896| The AsyncCall Adaptation::Icap::ModXact::noteServiceReady constructed, this=0x6000000000527640 [call36]
2009/10/01 16:11:55.896| ServiceRep.cc(201) callWhenReady: Adaptation::Icap::Service is asked to call Adaptation::Icap::ModXact::noteServiceReady() when ready [down,!opt]
2009/10/01 16:11:55.896| ServiceRep.cc(358) startGettingOptions: will get new options [down,!opt]
2009/10/01 16:11:55.896| AsyncJob of type Adaptation::Icap::OptXactLauncher constructed, this=0x6000000000527a30 [async10]
2009/10/01 16:11:55.896| The AsyncCall AsyncJob::noteStart constructed, this=0x600000000051b580 [call37]
2009/10/01 16:11:55.896| AsyncJob.cc(18) will call AsyncJob::noteStart() [call37]
2009/10/01 16:11:55.896| Adaptation::Icap::ModXact status out: [URG/ icapx9]
2009/10/01 16:11:55.896| leaving AsyncJob::noteStart()
2009/10/01 16:11:55.896| ModXact.cc(178) writeMore: checking whether to write more [URG/ icapx9]
2009/10/01 16:11:55.896| ModXact.cc(178) writeMore: checking whether to write more [URG/ icapx9]
2009/10/01 16:11:55.896| entering AsyncJob::noteStart()
2009/10/01 16:11:55.896| AsyncCall.cc(32) make: make call AsyncJob::noteStart [call37]
2009/10/01 16:11:55.896| Adaptation::Icap::OptXactLauncher status in: [ job10]
2009/10/01 16:11:55.896| Launcher.cc(42) launchXaction: launching first xaction #1
2009/10/01 16:11:55.896| AsyncJob of type Adaptation::Icap::OptXact constructed, this=0x600000000052c128 [async11]
2009/10/01 16:11:55.896| Adaptation::Icap::OptXact constructed, this=0x600000000052bc28 [icapx11]
2009/10/01 16:11:55.896| Adaptation::Icap::OptXact from now on cannot be repeated because over icap_retry_limit [/ icapx11]
2009/10/01 16:11:55.896| The AsyncCall AsyncJob::noteStart constructed, this=0x60000000005132d0 [call38]
2009/10/01 16:11:55.896| AsyncJob.cc(18) will call AsyncJob::noteStart() [call38]
2009/10/01 16:11:55.896| Adaptation::Icap::OptXactLauncher status out: [ job10]
2009/10/01 16:11:55.896| leaving AsyncJob::noteStart()
2009/10/01 16:11:55.896| entering AsyncJob::noteStart()
2009/10/01 16:11:55.896| AsyncCall.cc(32) make: make call AsyncJob::noteStart [call38]
2009/10/01 16:11:55.896| Adaptation::Icap::OptXact status in: [/ icapx11]
2009/10/01 16:11:55.896| Adaptation::Icap::OptXact from now on cannot be retried  [/ icapx11]
2009/10/01 16:11:55.896| Adaptation::Icap::OptXact opens connection to vmtest2.srn.sandia.gov:1344
2009/10/01 16:11:55.896| The AsyncCall Adaptation::Icap::Xaction::noteCommTimedout constructed, this=0x6000000000527920 [call39]
2009/10/01 16:11:55.897| The AsyncCall Adaptation::Icap::Xaction::noteCommClosed constructed, this=0x6000000000536c20 [call40]
2009/10/01 16:11:55.897| The AsyncCall Adaptation::Icap::Xaction::noteCommConnected constructed, this=0x6000000000536cb0 [call41]
2009/10/01 16:11:55.897| commConnectStart: FD 12, cb 0x6000000000536cb0*1, vmtest2.srn.sandia.gov:1344
2009/10/01 16:11:55.897| Adaptation::Icap::OptXact status out: [FD 12;/ icapx11]
2009/10/01 16:11:55.897| leaving AsyncJob::noteStart()
2009/10/01 16:11:55.897| comm.cc(927) will call Adaptation::Icap::Xaction::noteCommConnected(FD 12, data=0x600000000052bc28, ) [call41]
2009/10/01 16:11:55.897| entering Adaptation::Icap::Xaction::noteCommConnected(FD 12, data=0x600000000052bc28, )
2009/10/01 16:11:55.897| AsyncCall.cc(32) make: make call Adaptation::Icap::Xaction::noteCommConnected [call41]
2009/10/01 16:11:55.897| Adaptation::Icap::OptXact status in: [FD 12;/ icapx11]
2009/10/01 16:11:55.897| The AsyncCall Adaptation::Icap::Xaction::noteCommRead constructed, this=0x6000000000527920 [call43]
2009/10/01 16:11:55.897| The AsyncCall Adaptation::Icap::Xaction::noteCommTimedout constructed, this=0x6000000000536d60 [call44]
2009/10/01 16:11:55.898| AsyncJob.cc(218) dial: Adaptation::Icap::Xaction::noteCommConnected threw exception: icapRequest->parse(&buf, true, &status) > 0
2009/10/01 16:11:55.898| Xaction.cc(437) setOutcome: ICAP_ERR_OTHER
2009/10/01 16:11:55.898| Adaptation::Icap::OptXact will stop, reason: exception
2009/10/01 16:11:55.898| Adaptation::Icap::Xaction::noteCommConnected(FD 12, data=0x600000000052bc28, ) ends job [FD 12r;/ icapx11]
2009/10/01 16:11:55.898| Xaction.cc(173) closeConnection: not reusing pconn due to pending I/O [FD 12;/ icapx11]
2009/10/01 16:11:55.898| Xaction.cc(188) closeConnection: closing pconn [FD 12;/ icapx11]
2009/10/01 16:11:55.898| Initiate.cc(48) swanSong: swan sings [/ icapx11]
2009/10/01 16:11:55.898| Initiate.cc(55) swanSong: swan sang [/ icapx11]
2009/10/01 16:11:55.898| Adaptation::Icap::OptXact destructed, this=0x600000000052bc28 [icapx11]
2009/10/01 16:11:55.898| AsyncJob.cc(140) callEnd: Adaptation::Icap::Xaction::noteCommConnected(FD 12, data=0x600000000052bc28, ) ended 0x600000000052c128
2009/10/01 16:11:55.898| leaving Adaptation::Icap::Xaction::noteCommConnected(FD 12, data=0x600000000052bc28, )
2009/10/01 16:11:55.898| Launcher.cc(81) noteXactAbort: theXaction:0x600000000052bc28 launches: 1
2009/10/01 16:11:55.898| Launcher.cc(123) canRepeat: 0
2009/10/01 16:11:55.898| Launcher.cc(91) noteXactAbort: cannot retry or repeat a failed transaction
2009/10/01 16:11:55.898| The AsyncCall Initiator::noteAdaptationQueryAbort constructed, this=0x600000000050f0f0 [call48]
2009/10/01 16:11:55.898| Initiate.cc(79) will call Initiator::noteAdaptationQueryAbort(0) [call48]
2009/10/01 16:11:55.898| Adaptation::Icap::Launcher::noteXactAbort(retriable:0, repeatable:0) ends job [ job10]
2009/10/01 16:11:55.898| Initiate.cc(48) swanSong: swan sings [ job10]
2009/10/01 16:11:55.898| Initiate.cc(55) swanSong: swan sang [ job10]
2009/10/01 16:11:55.898| AsyncJob.cc(140) callEnd: Adaptation::Icap::Launcher::noteXactAbort(retriable:0, repeatable:0) ended 0x6000000000527a30
2009/10/01 16:11:55.898| entering Initiator::noteAdaptationQueryAbort(0)
2009/10/01 16:11:55.898| AsyncCall.cc(32) make: make call Initiator::noteAdaptationQueryAbort [call48]
2009/10/01 16:11:55.898| Adaptation::Icap::ServiceRep status in:[down,!opt,fetch]
2009/10/01 16:11:55.898| ServiceRep.cc(340) noteAdaptationQueryAbort: failed to fetch options [down,!opt]
2009/10/01 16:11:55.898| ServiceRep.cc(234) changeOptions: changes options from 0 to 0 [down,!opt]
2009/10/01 16:11:55.898| essential ICAP service is down after an options fetch failure: icap://vmtest2.srn.sandia.gov/nopres [down,!opt]
2009/10/01 16:11:55.899| ServiceRep.cc(349) handleNewOptions: got new options and is now [down,!opt]
2009/10/01 16:11:55.899| ServiceRep.cc(381) scheduleUpdate: raw OPTIONS fetch at 1254435295 or in 180 sec
2009/10/01 16:11:55.899| ServiceRep.cc(383) scheduleUpdate: last fetched at 1254435115 or 0 sec ago
2009/10/01 16:11:55.899| ServiceRep.cc(396) scheduleUpdate: will fetch OPTIONS in 180 sec
2009/10/01 16:11:55.899| ServiceRep.cc(222) scheduleNotification: will notify 1 clients
2009/10/01 16:11:55.899| The AsyncCall Adaptation::Icap::ServiceRep::noteTimeToNotify constructed, this=0x60000000005132d0 [call49]
2009/10/01 16:11:55.899| ServiceRep.cc(223) will call Adaptation::Icap::ServiceRep::noteTimeToNotify() [call49]
2009/10/01 16:11:55.899| Adaptation::Icap::ServiceRep status out:[down,!opt]
2009/10/01 16:11:55.899| leaving Initiator::noteAdaptationQueryAbort(0)
2009/10/01 16:11:55.899| entering Adaptation::Icap::ServiceRep::noteTimeToNotify()
2009/10/01 16:11:55.899| AsyncCall.cc(32) make: make call Adaptation::Icap::ServiceRep::noteTimeToNotify [call49]
2009/10/01 16:11:55.899| Adaptation::Icap::ServiceRep status in:[down,!opt]
2009/10/01 16:11:55.899| ServiceRep.cc(181) noteTimeToNotify: notifies 1 clients [down,!opt,notif]
2009/10/01 16:11:55.899| ServiceRep.cc(189) will call Adaptation::Icap::ModXact::noteServiceReady() [call36]
2009/10/01 16:11:55.899| Adaptation::Icap::ServiceRep status out:[down,!opt]
2009/10/01 16:11:55.899| leaving Adaptation::Icap::ServiceRep::noteTimeToNotify()
2009/10/01 16:11:55.899| entering Adaptation::Icap::ModXact::noteServiceReady()
2009/10/01 16:11:55.899| AsyncCall.cc(32) make: make call Adaptation::Icap::ModXact::noteServiceReady [call36]
2009/10/01 16:11:55.899| Adaptation::Icap::ModXact status in: [URG/ icapx9]
2009/10/01 16:11:55.899| Adaptation::Icap::ModXact from now on cannot be retried  [RG/ icapx9]
2009/10/01 16:11:55.899| Adaptation::Icap::ModXact still cannot be repeated because ICAP service is unusable [RG/ icapx9]
2009/10/01 16:11:55.899| AsyncJob.cc(218) dial: Adaptation::Icap::ModXact::noteServiceReady threw exception: ICAP service is unusable
2009/10/01 16:11:55.899| Xaction.cc(437) setOutcome: ICAP_ERR_OTHER
2009/10/01 16:11:55.899| Adaptation::Icap::ModXact will stop, reason: exception
2009/10/01 16:11:55.899| Adaptation::Icap::ModXact::noteServiceReady() ends job [RG/ icapx9]
2009/10/01 16:11:55.899| ModXact.cc(1093) swanSong: swan sings [RG/ icapx9]
2009/10/01 16:11:55.899| ModXact.cc(441) stopWriting: will no longer write [RG/ icapx9]
2009/10/01 16:11:55.899| ModXact.cc(359) virginConsume: consumption guards: 00001
2009/10/01 16:11:55.899| ModXact.cc(378) virginConsume: postponing consumption from  [0<=50<=50 50+1997 pipe0x600000000050f1c8 cons0x600000000051bb50]
2009/10/01 16:11:55.899| ModXact.cc(548) stopSending: Enter stop sending 
2009/10/01 16:11:55.899| ModXact.cc(551) stopSending: Proceed with stop sending 
2009/10/01 16:11:55.899| ModXact.cc(563) stopSending: will not start sending [RG/w icapx9]
2009/10/01 16:11:55.900| ModXact.cc(578) checkConsuming: will stop consuming [RG/wS icapx9]
2009/10/01 16:11:55.900| History.cc(95) processingTime:  current total: 5 0x60000000004f0290
2009/10/01 16:11:55.900| Initiate.cc(48) swanSong: swan sings [G/RwS icapx9]
2009/10/01 16:11:55.900| Initiate.cc(55) swanSong: swan sang [G/RwS icapx9]
2009/10/01 16:11:55.900| Adaptation::Icap::ModXact destructed, this=0x600000000051b648 [icapx9]
2009/10/01 16:11:55.900| AsyncJob.cc(140) callEnd: Adaptation::Icap::ModXact::noteServiceReady() ended 0x600000000051bc00
2009/10/01 16:11:55.900| leaving Adaptation::Icap::ModXact::noteServiceReady()
2009/10/01 16:11:55.900| Launcher.cc(81) noteXactAbort: theXaction:0x600000000051b648 launches: 1
2009/10/01 16:11:55.900| Launcher.cc(123) canRepeat: 0
2009/10/01 16:11:55.900| Launcher.cc(91) noteXactAbort: cannot retry or repeat a failed transaction
2009/10/01 16:11:55.900| The AsyncCall Initiator::noteAdaptationQueryAbort constructed, this=0x60000000005132d0 [call51]
2009/10/01 16:11:55.900| Initiate.cc(79) will call Initiator::noteAdaptationQueryAbort(0) [call51]
2009/10/01 16:11:55.900| Adaptation::Icap::Launcher::noteXactAbort(retriable:0, repeatable:0) ends job [ job8]
2009/10/01 16:11:55.900| ModXact.cc(1698) swanSong: swan sings
2009/10/01 16:11:55.900| History.cc(86) stop: stop ICAPModXactLauncher level=1 time=1+5 0x60000000004f0290
2009/10/01 16:11:55.900| Initiate.cc(48) swanSong: swan sings [ job8]
2009/10/01 16:11:55.900| Initiate.cc(55) swanSong: swan sang [ job8]
2009/10/01 16:11:55.900| AsyncJob.cc(140) callEnd: Adaptation::Icap::Launcher::noteXactAbort(retriable:0, repeatable:0) ended 0x6000000000517488
2009/10/01 16:11:55.900| entering Initiator::noteAdaptationQueryAbort(0)
2009/10/01 16:11:55.900| AsyncCall.cc(32) make: make call Initiator::noteAdaptationQueryAbort [call51]
2009/10/01 16:11:55.900| Iterator status in: [ job7]
2009/10/01 16:11:55.900| Iterator.cc(111) noteAdaptationQueryAbort: final: 0 plan: testresponse[0..1]
2009/10/01 16:11:55.900| ServiceGroups.cc(171) findService: testresponse has no matching services
2009/10/01 16:11:55.900| The AsyncCall Initiator::noteAdaptationQueryAbort constructed, this=0x6000000000527640 [call52]
2009/10/01 16:11:55.900| Initiate.cc(79) will call Initiator::noteAdaptationQueryAbort(1) [call52]
2009/10/01 16:11:55.900| Iterator will stop, reason: group failure
2009/10/01 16:11:55.900| Initiator::noteAdaptationQueryAbort(0) ends job [Stopped, reason:group failure job7]
2009/10/01 16:11:55.900| Initiate.cc(48) swanSong: swan sings [Stopped, reason:group failure job7]
2009/10/01 16:11:55.900| Initiate.cc(55) swanSong: swan sang [Stopped, reason:group failure job7]
2009/10/01 16:11:55.900| AsyncJob.cc(140) callEnd: Initiator::noteAdaptationQueryAbort(0) ended 0x6000000000513410
2009/10/01 16:11:55.900| leaving Initiator::noteAdaptationQueryAbort(0)
2009/10/01 16:11:55.900| entering Initiator::noteAdaptationQueryAbort(1)
2009/10/01 16:11:55.900| AsyncCall.cc(32) make: make call Initiator::noteAdaptationQueryAbort [call52]
2009/10/01 16:11:55.900| HttpStateData status in: [ job5]
2009/10/01 16:11:55.901| HttpStateData will NOT delete in-call job, reason: HttpStateData::abortTransaction
2009/10/01 16:11:55.901| Initiator::noteAdaptationQueryAbort(1) ends job [Stopped, reason:HttpStateData::abortTransaction job5]
2009/10/01 16:11:55.901| AsyncJob.cc(140) callEnd: Initiator::noteAdaptationQueryAbort(1) ended 0x6000000000509558
2009/10/01 16:11:55.901| leaving Initiator::noteAdaptationQueryAbort(1)
2009/10/01 16:11:55.901| ConnStateData will NOT delete in-call job, reason: ConnStateData::connStateClosed
2009/10/01 16:11:55.901| ConnStateData::connStateClosed(FD 11, data=0x60000000004a9488) ends job [Stopped, reason:ConnStateData::connStateClosed job2]
2009/10/01 16:11:55.901| History.cc(95) processingTime:  current total: 6 0x60000000004f0290
2009/10/01 16:11:55.901| AsyncJob.cc(140) callEnd: ConnStateData::connStateClosed(FD 11, data=0x60000000004a9488) ended 0x60000000004a9610
2009/10/01 16:11:55.916| AsyncJob of type ConnStateData constructed, this=0x60000000004a9610 [async12]
2009/10/01 16:11:55.916| AsyncJob of type ClientHttpRequest constructed, this=0x60000000004b1d28 [async13]
2009/10/01 16:11:55.917| AsyncJob of type AccessCheck constructed, this=0x60000000004ec2c8 [async14]
2009/10/01 16:11:55.917| HttpRequest.cc(387) icapHistory: made 0x60000000004f0290*1 for 0x6000000000483a00
2009/10/01 16:11:55.917| History.cc(74) start: start ACL level=1 time=0 0x60000000004f0290
2009/10/01 16:11:55.917| AccessCheck.cc(49) AccessCheck: AccessCheck constructed for REQMOD PRECACHE
2009/10/01 16:11:55.917| The AsyncCall AsyncJob::noteStart constructed, this=0x600000000051b580 [call61]
2009/10/01 16:11:55.917| AsyncJob.cc(18) will call AsyncJob::noteStart() [call61]
2009/10/01 16:11:55.917| entering AsyncJob::noteStart()
2009/10/01 16:11:55.917| AsyncCall.cc(32) make: make call AsyncJob::noteStart [call61]
2009/10/01 16:11:55.917| AccessCheck status in: [ job14]
2009/10/01 16:11:55.917| AccessCheck.cc(74) check: start checking
2009/10/01 16:11:55.917| AccessCheck.cc(188) isCandidate: checking candidacy of 1, group testresponse
2009/10/01 16:11:55.917| ServiceGroups.cc(126) findService: testresponse serves another location
2009/10/01 16:11:55.917| AccessCheck.cc(198) isCandidate: testresponse ignores
2009/10/01 16:11:55.917| AccessCheck.cc(96) checkCandidates: has 0 rules
2009/10/01 16:11:55.917| AccessCheck.cc(111) checkCandidates: NO candidates left
2009/10/01 16:11:55.917| AccessCheck.cc(155) callBack: NULL
2009/10/01 16:11:55.917| client_side_request.cc(636) adaptationAclCheckDone: 0x60000000004e3fa8 adaptationAclCheckDone called
2009/10/01 16:11:55.917| AccessCheck will stop, reason: done
2009/10/01 16:11:55.917| AsyncJob::noteStart() ends job [Stopped, reason:done job14]
2009/10/01 16:11:55.917| History.cc(86) stop: stop ACL level=1 time=0+0 0x60000000004f0290
2009/10/01 16:11:55.917| AsyncJob.cc(140) callEnd: AsyncJob::noteStart() ended 0x60000000004ec2c8
2009/10/01 16:11:55.917| leaving AsyncJob::noteStart()
2009/10/01 16:11:56.066| AsyncJob of type HttpStateData constructed, this=0x6000000000509558 [async15]
2009/10/01 16:11:56.118| AsyncJob of type AccessCheck constructed, this=0x60000000004ec2c8 [async16]
2009/10/01 16:11:56.118| History.cc(74) start: start ACL level=1 time=0 0x60000000004f0290
2009/10/01 16:11:56.118| AccessCheck.cc(49) AccessCheck: AccessCheck constructed for RESPMOD PRECACHE
2009/10/01 16:11:56.118| The AsyncCall AsyncJob::noteStart constructed, this=0x600000000052bb90 [call72]
2009/10/01 16:11:56.118| AsyncJob.cc(18) will call AsyncJob::noteStart() [call72]
2009/10/01 16:11:56.118| entering AsyncJob::noteStart()
2009/10/01 16:11:56.118| AsyncCall.cc(32) make: make call AsyncJob::noteStart [call72]
2009/10/01 16:11:56.118| AccessCheck status in: [ job16]
2009/10/01 16:11:56.118| AccessCheck.cc(74) check: start checking
2009/10/01 16:11:56.118| AccessCheck.cc(188) isCandidate: checking candidacy of 1, group testresponse
2009/10/01 16:11:56.118| ServiceGroups.cc(134) findService: testresponse checks service at 0
2009/10/01 16:11:56.119| ServiceGroups.cc(159) findService: testresponse searches for best essential service from 0
2009/10/01 16:11:56.119| ServiceGroups.cc(166) findService: testresponse has best essential service at 0
2009/10/01 16:11:56.119| AccessCheck.cc(198) isCandidate: testresponse wants
2009/10/01 16:11:56.119| AccessCheck.cc(80) check: check: rule '1' is a candidate
2009/10/01 16:11:56.119| AccessCheck.cc(96) checkCandidates: has 1 rules
2009/10/01 16:11:56.119| AccessCheck.cc(119) AccessCheckCallbackWrapper: callback answer=1
2009/10/01 16:11:56.119| AccessCheck.cc(134) noteAnswer: 1 answer=1
2009/10/01 16:11:56.119| AccessCheck.cc(171) topGroup: top group for 1 is 0x60000000001bcbf0*2
2009/10/01 16:11:56.119| AccessCheck.cc(155) callBack: 0x60000000001bcbf0*2
2009/10/01 16:11:56.119| Server.cc(526) startAdaptation: will send virgin reply body to 0x600000000050f1c8*2; size: 12716
2009/10/01 16:11:56.119| AsyncJob of type Iterator constructed, this=0x6000000000513410 [async17]
2009/10/01 16:11:56.119| The AsyncCall AsyncJob::noteStart constructed, this=0x600000000051b580 [call73]
2009/10/01 16:11:56.119| AsyncJob.cc(18) will call AsyncJob::noteStart() [call73]
2009/10/01 16:11:56.119| AccessCheck will stop, reason: done
2009/10/01 16:11:56.119| AsyncJob::noteStart() ends job [Stopped, reason:done job16]
2009/10/01 16:11:56.119| History.cc(86) stop: stop ACL level=1 time=0+0 0x60000000004f0290
2009/10/01 16:11:56.119| AsyncJob.cc(140) callEnd: AsyncJob::noteStart() ended 0x60000000004ec2c8
2009/10/01 16:11:56.119| leaving AsyncJob::noteStart()
2009/10/01 16:11:56.119| entering AsyncJob::noteStart()
2009/10/01 16:11:56.119| AsyncCall.cc(32) make: make call AsyncJob::noteStart [call73]
2009/10/01 16:11:56.119| Iterator status in: [ job17]
2009/10/01 16:11:56.119| ServiceGroups.cc(134) findService: testresponse checks service at 0
2009/10/01 16:11:56.119| ServiceGroups.cc(159) findService: testresponse searches for best essential service from 0
2009/10/01 16:11:56.119| ServiceGroups.cc(166) findService: testresponse has best essential service at 0
2009/10/01 16:11:56.119| Iterator.cc(49) step: #1 plan: testresponse[0..1]
2009/10/01 16:11:56.119| Iterator.cc(69) step: using adaptation service: testresp
2009/10/01 16:11:56.119| AsyncJob of type Adaptation::Icap::ModXactLauncher constructed, this=0x6000000000517488 [async18]
2009/10/01 16:11:56.119| History.cc(74) start: start ICAPModXactLauncher level=1 time=0 0x60000000004f0290
2009/10/01 16:11:56.119| The AsyncCall AsyncJob::noteStart constructed, this=0x600000000052bb90 [call75]
2009/10/01 16:11:56.119| AsyncJob.cc(18) will call AsyncJob::noteStart() [call75]
2009/10/01 16:11:56.119| Iterator status out: [ job17]
2009/10/01 16:11:56.119| leaving AsyncJob::noteStart()
2009/10/01 16:11:56.119| entering AsyncJob::noteStart()
2009/10/01 16:11:56.120| AsyncCall.cc(32) make: make call AsyncJob::noteStart [call75]
2009/10/01 16:11:56.120| Adaptation::Icap::ModXactLauncher status in: [ job18]
2009/10/01 16:11:56.120| Launcher.cc(42) launchXaction: launching first xaction #1
2009/10/01 16:11:56.120| AsyncJob of type Adaptation::Icap::ModXact constructed, this=0x600000000051bc00 [async19]
2009/10/01 16:11:56.120| Adaptation::Icap::ModXact constructed, this=0x600000000051b648 [icapx19]
2009/10/01 16:11:56.120| ModXact.cc(70) ModXact: initialized. [RG/ icapx19]
2009/10/01 16:11:56.120| Adaptation::Icap::ModXact from now on cannot be repeated because over icap_retry_limit [RG/ icapx19]
2009/10/01 16:11:56.120| The AsyncCall AsyncJob::noteStart constructed, this=0x600000000051b580 [call76]
2009/10/01 16:11:56.120| AsyncJob.cc(18) will call AsyncJob::noteStart() [call76]
2009/10/01 16:11:56.120| Adaptation::Icap::ModXactLauncher status out: [ job18]
2009/10/01 16:11:56.120| leaving AsyncJob::noteStart()
2009/10/01 16:11:56.120| entering AsyncJob::noteStart()
2009/10/01 16:11:56.120| AsyncCall.cc(32) make: make call AsyncJob::noteStart [call76]
2009/10/01 16:11:56.120| Adaptation::Icap::ModXact status in: [RG/ icapx19]
2009/10/01 16:11:56.120| ModXact.cc(1522) estimateVirginBody: expects virgin body from 0x600000000050f1c8*4; size: 12716
2009/10/01 16:11:56.120| ModXact.cc(98) waitForService: will wait for the ICAP service [RG/ icapx19]
2009/10/01 16:11:56.120| The AsyncCall Adaptation::Icap::ModXact::noteServiceReady constructed, this=0x600000000052bb90 [call78]
2009/10/01 16:11:56.120| ServiceRep.cc(201) callWhenReady: Adaptation::Icap::Service is asked to call Adaptation::Icap::ModXact::noteServiceReady() when ready [down,!opt]
2009/10/01 16:11:56.120| AsyncJob.cc(218) dial: AsyncJob::noteStart threw exception: !broken()
2009/10/01 16:11:56.120| Xaction.cc(437) setOutcome: ICAP_ERR_OTHER
2009/10/01 16:11:56.120| Adaptation::Icap::ModXact will stop, reason: exception
2009/10/01 16:11:56.120| AsyncJob::noteStart() ends job [URG/ icapx19]
2009/10/01 16:11:56.120| ModXact.cc(1093) swanSong: swan sings [URG/ icapx19]
2009/10/01 16:11:56.120| ModXact.cc(441) stopWriting: will no longer write [URG/ icapx19]
2009/10/01 16:11:56.120| ModXact.cc(359) virginConsume: consumption guards: 01001
2009/10/01 16:11:56.120| ModXact.cc(548) stopSending: Enter stop sending 
2009/10/01 16:11:56.120| ModXact.cc(551) stopSending: Proceed with stop sending 
2009/10/01 16:11:56.120| ModXact.cc(563) stopSending: will not start sending [URG/w icapx19]
2009/10/01 16:11:56.121| ModXact.cc(578) checkConsuming: will stop consuming [URG/wS icapx19]
2009/10/01 16:11:56.121| History.cc(95) processingTime:  current total: 1 0x60000000004f0290
2009/10/01 16:11:56.121| Initiate.cc(48) swanSong: swan sings [UG/RwS icapx19]
2009/10/01 16:11:56.121| Initiate.cc(55) swanSong: swan sang [UG/RwS icapx19]
2009/10/01 16:11:56.121| Adaptation::Icap::ModXact destructed, this=0x600000000051b648 [icapx19]
2009/10/01 16:11:56.121| AsyncJob.cc(140) callEnd: AsyncJob::noteStart() ended 0x600000000051bc00
2009/10/01 16:11:56.121| leaving AsyncJob::noteStart()
2009/10/01 16:11:56.121| Launcher.cc(81) noteXactAbort: theXaction:0x600000000051b648 launches: 1
2009/10/01 16:11:56.121| Launcher.cc(42) launchXaction: launching retry xaction #2
2009/10/01 16:11:56.121| AsyncJob of type Adaptation::Icap::ModXact constructed, this=0x600000000051bc00 [async20]
2009/10/01 16:11:56.121| Adaptation::Icap::ModXact constructed, this=0x600000000051b648 [icapx20]
2009/10/01 16:11:56.121| ModXact.cc(70) ModXact: initialized. [RG/ icapx20]
2009/10/01 16:11:56.121| Adaptation::Icap::ModXact from now on cannot be retried  [RG/ icapx20]
2009/10/01 16:11:56.121| Adaptation::Icap::ModXact from now on cannot be repeated because over icap_retry_limit [RG/ icapx20]
2009/10/01 16:11:56.121| The AsyncCall AsyncJob::noteStart constructed, this=0x600000000052bb90 [call80]
2009/10/01 16:11:56.121| AsyncJob.cc(18) will call AsyncJob::noteStart() [call80]
2009/10/01 16:11:56.121| entering AsyncJob::noteStart()
2009/10/01 16:11:56.121| AsyncCall.cc(32) make: make call AsyncJob::noteStart [call80]
2009/10/01 16:11:56.121| Adaptation::Icap::ModXact status in: [RG/ icapx20]
2009/10/01 16:11:56.121| ModXact.cc(1522) estimateVirginBody: expects virgin body from 0x600000000050f1c8*4; size: 12716
2009/10/01 16:11:56.121| ModXact.cc(98) waitForService: will wait for the ICAP service [RG/ icapx20]
2009/10/01 16:11:56.121| The AsyncCall Adaptation::Icap::ModXact::noteServiceReady constructed, this=0x60000000004ad480 [call82]
2009/10/01 16:11:56.121| ServiceRep.cc(201) callWhenReady: Adaptation::Icap::Service is asked to call Adaptation::Icap::ModXact::noteServiceReady() when ready [down,!opt]
2009/10/01 16:11:56.121| AsyncJob.cc(218) dial: AsyncJob::noteStart threw exception: !broken()
2009/10/01 16:11:56.121| Xaction.cc(437) setOutcome: ICAP_ERR_OTHER
2009/10/01 16:11:56.121| Adaptation::Icap::ModXact will stop, reason: exception
2009/10/01 16:11:56.121| AsyncJob::noteStart() ends job [URG/ icapx20]
2009/10/01 16:11:56.121| ModXact.cc(1093) swanSong: swan sings [URG/ icapx20]
2009/10/01 16:11:56.122| ModXact.cc(441) stopWriting: will no longer write [URG/ icapx20]
2009/10/01 16:11:56.122| ModXact.cc(359) virginConsume: consumption guards: 00001
2009/10/01 16:11:56.122| ModXact.cc(378) virginConsume: postponing consumption from  [0<=1673<=12716 1673+374 pipe0x600000000050f1c8 prod0x6000000000509480 cons0x600000000051bb50]
2009/10/01 16:11:56.122| ModXact.cc(548) stopSending: Enter stop sending 
2009/10/01 16:11:56.122| ModXact.cc(551) stopSending: Proceed with stop sending 
2009/10/01 16:11:56.122| ModXact.cc(563) stopSending: will not start sending [URG/w icapx20]
2009/10/01 16:11:56.122| ModXact.cc(578) checkConsuming: will stop consuming [URG/wS icapx20]
2009/10/01 16:11:56.122| History.cc(95) processingTime:  current total: 2 0x60000000004f0290
2009/10/01 16:11:56.122| Initiate.cc(48) swanSong: swan sings [UG/RwS icapx20]
2009/10/01 16:11:56.122| Initiate.cc(55) swanSong: swan sang [UG/RwS icapx20]
2009/10/01 16:11:56.122| Adaptation::Icap::ModXact destructed, this=0x600000000051b648 [icapx20]
2009/10/01 16:11:56.122| AsyncJob.cc(140) callEnd: AsyncJob::noteStart() ended 0x600000000051bc00
2009/10/01 16:11:56.122| leaving AsyncJob::noteStart()
2009/10/01 16:11:56.122| Launcher.cc(81) noteXactAbort: theXaction:0x600000000051b648 launches: 2
2009/10/01 16:11:56.122| Launcher.cc(123) canRepeat: 0
2009/10/01 16:11:56.122| Launcher.cc(91) noteXactAbort: cannot retry or repeat a failed transaction
2009/10/01 16:11:56.122| The AsyncCall Initiator::noteAdaptationQueryAbort constructed, this=0x60000000004ad480 [call84]
2009/10/01 16:11:56.122| Initiate.cc(79) will call Initiator::noteAdaptationQueryAbort(0) [call84]
2009/10/01 16:11:56.122| Adaptation::Icap::Launcher::noteXactAbort(retriable:0, repeatable:0) ends job [ job18]
2009/10/01 16:11:56.122| ModXact.cc(1698) swanSong: swan sings
2009/10/01 16:11:56.122| History.cc(86) stop: stop ICAPModXactLauncher level=1 time=0+2 0x60000000004f0290
2009/10/01 16:11:56.122| Initiate.cc(48) swanSong: swan sings [ job18]
2009/10/01 16:11:56.122| Initiate.cc(55) swanSong: swan sang [ job18]
2009/10/01 16:11:56.122| AsyncJob.cc(140) callEnd: Adaptation::Icap::Launcher::noteXactAbort(retriable:0, repeatable:0) ended 0x6000000000517488
2009/10/01 16:11:56.122| entering Initiator::noteAdaptationQueryAbort(0)
2009/10/01 16:11:56.122| AsyncCall.cc(32) make: make call Initiator::noteAdaptationQueryAbort [call84]
2009/10/01 16:11:56.122| Iterator status in: [ job17]
2009/10/01 16:11:56.122| Iterator.cc(111) noteAdaptationQueryAbort: final: 0 plan: testresponse[0..1]
2009/10/01 16:11:56.122| ServiceGroups.cc(171) findService: testresponse has no matching services
2009/10/01 16:11:56.122| The AsyncCall Initiator::noteAdaptationQueryAbort constructed, this=0x600000000052bb90 [call85]
2009/10/01 16:11:56.122| Initiate.cc(79) will call Initiator::noteAdaptationQueryAbort(1) [call85]
2009/10/01 16:11:56.122| Iterator will stop, reason: group failure
2009/10/01 16:11:56.122| Initiator::noteAdaptationQueryAbort(0) ends job [Stopped, reason:group failure job17]
2009/10/01 16:11:56.123| Initiate.cc(48) swanSong: swan sings [Stopped, reason:group failure job17]
2009/10/01 16:11:56.123| Initiate.cc(55) swanSong: swan sang [Stopped, reason:group failure job17]
2009/10/01 16:11:56.123| AsyncJob.cc(140) callEnd: Initiator::noteAdaptationQueryAbort(0) ended 0x6000000000513410
2009/10/01 16:11:56.123| leaving Initiator::noteAdaptationQueryAbort(0)
2009/10/01 16:11:56.123| entering Initiator::noteAdaptationQueryAbort(1)
2009/10/01 16:11:56.123| AsyncCall.cc(32) make: make call Initiator::noteAdaptationQueryAbort [call85]
2009/10/01 16:11:56.123| HttpStateData status in: [ job15]
2009/10/01 16:11:56.123| HttpStateData status out: [ job15]
2009/10/01 16:11:56.123| leaving Initiator::noteAdaptationQueryAbort(1)
2009/10/01 16:11:56.123| HttpStateData will NOT delete in-call job, reason: HttpStateData::httpStateConnClosed
2009/10/01 16:11:56.123| httpStateData::httpStateConnClosed(FD 12, data=0x6000000000509478) ends job [Stopped, reason:HttpStateData::httpStateConnClosed job15]
2009/10/01 16:11:56.123| AsyncJob.cc(140) callEnd: httpStateData::httpStateConnClosed(FD 12, data=0x6000000000509478) ended 0x6000000000509558
2009/10/01 16:11:56.123| ConnStateData will NOT delete in-call job, reason: ConnStateData::connStateClosed
2009/10/01 16:11:56.123| ConnStateData::connStateClosed(FD 11, data=0x60000000004a9488) ends job [Stopped, reason:ConnStateData::connStateClosed job12]
2009/10/01 16:11:56.123| History.cc(95) processingTime:  current total: 2 0x60000000004f0290
2009/10/01 16:11:56.124| AsyncJob.cc(140) callEnd: ConnStateData::connStateClosed(FD 11, data=0x60000000004a9488) ended 0x60000000004a9610