JsonRpc (StompReactor)::DEBUG::2015-12-14 11:55:26,487::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-12-14 11:55:26,488::__init__::506::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-1285::DEBUG::2015-12-14 11:55:26,491::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
JsonRpc (StompReactor)::DEBUG::2015-12-14 11:55:29,499::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-12-14 11:55:29,501::__init__::506::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-1286::DEBUG::2015-12-14 11:55:29,504::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
JsonRpc (StompReactor)::DEBUG::2015-12-14 11:55:32,512::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-12-14 11:55:32,514::__init__::506::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-1287::DEBUG::2015-12-14 11:55:32,517::task::592::Storage.TaskManager.Task::(_updateState) Task=`79726805-eec0-4719-b758-51749f067295`::moving from state init -> state preparing
Thread-1287::INFO::2015-12-14 11:55:32,517::logUtils::48::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-1287::INFO::2015-12-14 11:55:32,518::logUtils::51::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'f7453ce7-3aca-4ee3-98c3-827ce3e001d6': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000659959', 'lastCheck': '6.5', 'valid': True}, u'4b083e6a-d588-4735-bf50-833033c24e6b': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000797126', 'lastCheck': '6.5', 'valid': True}, u'6d00b190-a3a8-4e75-b718-4ba680d7a228': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000403222', 'lastCheck': '6.7', 'valid': True}}
Thread-1287::DEBUG::2015-12-14 11:55:32,518::task::1188::Storage.TaskManager.Task::(prepare) Task=`79726805-eec0-4719-b758-51749f067295`::finished: {u'f7453ce7-3aca-4ee3-98c3-827ce3e001d6': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000659959', 'lastCheck': '6.5', 'valid': True}, u'4b083e6a-d588-4735-bf50-833033c24e6b': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000797126', 'lastCheck': '6.5', 'valid': True}, u'6d00b190-a3a8-4e75-b718-4ba680d7a228': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000403222', 'lastCheck': '6.7', 'valid': True}}
Thread-1287::DEBUG::2015-12-14 11:55:32,518::task::592::Storage.TaskManager.Task::(_updateState) Task=`79726805-eec0-4719-b758-51749f067295`::moving from state preparing -> state finished
Thread-1287::DEBUG::2015-12-14 11:55:32,518::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-1287::DEBUG::2015-12-14 11:55:32,518::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-1287::DEBUG::2015-12-14 11:55:32,519::task::990::Storage.TaskManager.Task::(_decref) Task=`79726805-eec0-4719-b758-51749f067295`::ref 0 aborting False
Thread-1287::DEBUG::2015-12-14 11:55:32,521::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
JsonRpc (StompReactor)::DEBUG::2015-12-14 11:55:32,537::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-12-14 11:55:32,539::__init__::506::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-1288::DEBUG::2015-12-14 11:55:32,541::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
JsonRpc (StompReactor)::DEBUG::2015-12-14 11:55:35,596::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-12-14 11:55:35,598::__init__::506::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-1289::DEBUG::2015-12-14 11:55:35,600::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
ioprocess communication (15961)::DEBUG::2015-12-14 11:55:35,830::__init__::411::IOProcess::(_processLogs) Queuing request (slotsLeft=20)
ioprocess communication (15961)::DEBUG::2015-12-14 11:55:35,831::__init__::411::IOProcess::(_processLogs) (531) Start request for method 'statvfs' (waitTime=54)
ioprocess communication (15961)::DEBUG::2015-12-14 11:55:35,831::__init__::411::IOProcess::(_processLogs) (531) Finished request for method 'statvfs' (runTime=409)
ioprocess communication (15961)::DEBUG::2015-12-14 11:55:35,831::__init__::411::IOProcess::(_processLogs) (531) Dequeuing request (slotsLeft=21)
Thread-33::DEBUG::2015-12-14 11:55:35,832::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/shadow.nieuwland.nl:_export_ovirt/6d00b190-a3a8-4e75-b718-4ba680d7a228/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-33::DEBUG::2015-12-14 11:55:35,843::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n318 bytes (318 B) copied, 0.000462124 s, 688 kB/s\n'; <rc> = 0
ioprocess communication (15961)::DEBUG::2015-12-14 11:55:35,845::__init__::411::IOProcess::(_processLogs) Queuing request (slotsLeft=20)
ioprocess communication (15961)::DEBUG::2015-12-14 11:55:35,845::__init__::411::IOProcess::(_processLogs) (532) Start request for method 'statvfs' (waitTime=39)
ioprocess communication (15961)::DEBUG::2015-12-14 11:55:35,846::__init__::411::IOProcess::(_processLogs) (532) Finished request for method 'statvfs' (runTime=307)
ioprocess communication (15961)::DEBUG::2015-12-14 11:55:35,848::__init__::411::IOProcess::(_processLogs) (532) Dequeuing request (slotsLeft=21)
ioprocess communication (15948)::DEBUG::2015-12-14 11:55:35,973::__init__::411::IOProcess::(_processLogs) Queuing request (slotsLeft=20)
ioprocess communication (15948)::DEBUG::2015-12-14 11:55:35,973::__init__::411::IOProcess::(_processLogs) (531) Start request for method 'statvfs' (waitTime=27)
ioprocess communication (15948)::DEBUG::2015-12-14 11:55:35,974::__init__::411::IOProcess::(_processLogs) (531) Finished request for method 'statvfs' (runTime=1108)
ioprocess communication (15948)::DEBUG::2015-12-14 11:55:35,975::__init__::411::IOProcess::(_processLogs) (531) Dequeuing request (slotsLeft=21)
Thread-32::DEBUG::2015-12-14 11:55:35,975::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/st01.nieuwland.nl:_gv__ovirt__iso01/4b083e6a-d588-4735-bf50-833033c24e6b/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:35,987::__init__::411::IOProcess::(_processLogs) Queuing request (slotsLeft=20)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:35,989::__init__::411::IOProcess::(_processLogs) (1320) Start request for method 'statvfs' (waitTime=59)
Thread-32::DEBUG::2015-12-14 11:55:35,990::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n336 bytes (336 B) copied, 0.000688764 s, 488 kB/s\n'; <rc> = 0
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:35,992::__init__::411::IOProcess::(_processLogs) (1320) Finished request for method 'statvfs' (runTime=2150)
Thread-31::DEBUG::2015-12-14 11:55:35,995::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/glusterSD/st01.nieuwland.nl:gv__ovirt__data01/f7453ce7-3aca-4ee3-98c3-827ce3e001d6/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:35,996::__init__::411::IOProcess::(_processLogs) (1320) Dequeuing request (slotsLeft=21)
ioprocess communication (15948)::DEBUG::2015-12-14 11:55:35,997::__init__::411::IOProcess::(_processLogs) Queuing request (slotsLeft=20)
ioprocess communication (15948)::DEBUG::2015-12-14 11:55:36,011::__init__::411::IOProcess::(_processLogs) (532) Start request for method 'statvfs' (waitTime=34)
ioprocess communication (15948)::DEBUG::2015-12-14 11:55:36,011::__init__::411::IOProcess::(_processLogs) (532) Finished request for method 'statvfs' (runTime=1075)
ioprocess communication (15948)::DEBUG::2015-12-14 11:55:36,011::__init__::411::IOProcess::(_processLogs) (532) Dequeuing request (slotsLeft=21)
Thread-31::DEBUG::2015-12-14 11:55:36,014::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n474 bytes (474 B) copied, 0.000669847 s, 708 kB/s\n'; <rc> = 0
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:36,016::__init__::411::IOProcess::(_processLogs) Queuing request (slotsLeft=20)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:36,016::__init__::411::IOProcess::(_processLogs) (1321) Start request for method 'statvfs' (waitTime=48)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:36,017::__init__::411::IOProcess::(_processLogs) (1321) Finished request for method 'statvfs' (runTime=527)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:36,018::__init__::411::IOProcess::(_processLogs) (1321) Dequeuing request (slotsLeft=21)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:36,019::__init__::411::IOProcess::(_processLogs) Queuing request (slotsLeft=20)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:36,019::__init__::411::IOProcess::(_processLogs) (1322) Start request for method 'access' (waitTime=227)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:36,020::__init__::411::IOProcess::(_processLogs) (1322) Finished request for method 'access' (runTime=714)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:36,021::__init__::411::IOProcess::(_processLogs) (1322) Dequeuing request (slotsLeft=21)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:36,021::__init__::411::IOProcess::(_processLogs) Queuing request (slotsLeft=20)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:36,022::__init__::411::IOProcess::(_processLogs) (1323) Start request for method 'access' (waitTime=227)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:36,023::__init__::411::IOProcess::(_processLogs) (1323) Finished request for method 'access' (runTime=684)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:36,024::__init__::411::IOProcess::(_processLogs) (1323) Dequeuing request (slotsLeft=21)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:36,024::__init__::411::IOProcess::(_processLogs) Queuing request (slotsLeft=20)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:36,024::__init__::411::IOProcess::(_processLogs) (1324) Start request for method 'access' (waitTime=22)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:36,025::__init__::411::IOProcess::(_processLogs) (1324) Finished request for method 'access' (runTime=677)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:36,026::__init__::411::IOProcess::(_processLogs) (1324) Dequeuing request (slotsLeft=21)
JsonRpc (StompReactor)::DEBUG::2015-12-14 11:55:38,609::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-12-14 11:55:38,611::__init__::506::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-1290::DEBUG::2015-12-14 11:55:38,614::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
JsonRpc (StompReactor)::DEBUG::2015-12-14 11:55:41,179::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
Thread-1291::DEBUG::2015-12-14 11:55:41,181::__init__::469::jsonrpc.JsonRpcServer::(_serveRequest) Calling 'VM.create' in bridge with {u'vmParams': {u'acpiEnable': u'true', u'emulatedMachine': u'rhel6.5.0', u'vmId': u'4838abf2-bf06-4a58-a648-bdb9bee93bf1', u'memGuaranteedSize': 1024, u'transparentHugePages': u'true', u'spiceSslCipherSuite': u'DEFAULT', u'cpuType': u'Conroe', u'smp': u'1', u'custom': {}, u'vmType': u'kvm', u'memSize': 1024, u'smpCoresPerSocket': u'1', u'vmName': u'testvm', u'nice': u'0', u'bootMenuEnable': u'false', u'copyPasteEnable': u'true', u'smartcardEnable': u'false', u'fileTransferEnable': u'true', u'keyboardLayout': u'en-us', u'kvmEnable': u'true', u'displayNetwork': u'ovirtmgmt', u'devices': [{u'device': u'qxl', u'specParams': {u'vram': u'32768', u'heads': u'1'}, u'type': u'video', u'deviceId': u'910e0167-f86e-484d-a780-80b63ce05705', u'address': {u'slot': u'0x02', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}}, {u'index': u'2', u'iface': u'ide', u'specParams': {u'path': u''}, u'readonly': u'true', u'deviceId': u'8082b51e-33fb-44fb-aa90-2e06f6a7fdb5', u'path': u'', u'device': u'cdrom', u'shared': u'false', u'type': u'disk'}, {u'index': 0, u'iface': u'virtio', u'format': u'raw', u'bootOrder': u'1', u'volumeID': u'9e189687-6118-4b28-ac36-e97063655af2', u'imageID': u'8cc2e445-649b-48c3-a182-970e80b49458', u'specParams': {}, u'readonly': u'false', u'domainID': u'f7453ce7-3aca-4ee3-98c3-827ce3e001d6', u'optional': u'false', u'deviceId': u'8cc2e445-649b-48c3-a182-970e80b49458', u'poolID': u'00000002-0002-0002-0002-000000000247', u'device': u'disk', u'shared': u'false', u'propagateErrors': u'off', u'type': u'disk'}, {u'device': u'memballoon', u'specParams': {u'model': u'virtio'}, u'type': u'balloon', u'deviceId': u'97758edf-a87f-4996-ae98-ac71b9c798f0', u'address': {u'slot': u'0x05', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}}, {u'index': u'0', u'specParams': {}, u'deviceId': u'2a707f91-a310-49c2-98aa-08f97851dd49', u'address': {u'slot': u'0x03', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, u'device': u'scsi', u'model': u'virtio-scsi', u'type': u'controller'}, {u'device': u'virtio-serial', u'specParams': {}, u'type': u'controller', u'deviceId': u'6721e2f4-5284-49e2-8732-a0757e19f8f9', u'address': {u'slot': u'0x04', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}}], u'timeOffset': u'0', u'maxVCpus': u'16', u'spiceSecureChannels': u'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', u'display': u'qxl'}, u'vmID': u'4838abf2-bf06-4a58-a648-bdb9bee93bf1'}
JsonRpcServer::DEBUG::2015-12-14 11:55:41,181::__init__::506::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-1292::DEBUG::2015-12-14 11:55:41,189::vm::1632::vm.Vm::(_startUnderlyingVm) vmId=`4838abf2-bf06-4a58-a648-bdb9bee93bf1`::Start
Thread-1292::INFO::2015-12-14 11:55:41,192::vm::2652::vm.Vm::(_run) vmId=`4838abf2-bf06-4a58-a648-bdb9bee93bf1`::VM wrapper has started
Thread-1291::DEBUG::2015-12-14 11:55:41,195::__init__::500::jsonrpc.JsonRpcServer::(_serveRequest) Return 'VM.create' in bridge with {u'acpiEnable': u'true', u'emulatedMachine': u'rhel6.5.0', u'vmId': u'4838abf2-bf06-4a58-a648-bdb9bee93bf1', u'memGuaranteedSize': 1024, u'transparentHugePages': u'true', 'displaySecurePort': '-1', u'spiceSslCipherSuite': u'DEFAULT', u'cpuType': u'Conroe', u'smp': u'1', u'smartcardEnable': u'false', u'custom': {}, u'vmType': u'kvm', u'memSize': 1024, u'smpCoresPerSocket': u'1', u'vmName': u'testvm', u'nice': u'0', 'status': 'WaitForLaunch', u'bootMenuEnable': u'false', 'pid': '0', u'copyPasteEnable': u'true', 'displayIp': '192.168.216.153', 'displayPort': '-1', 'guestDiskMapping': {}, 'clientIp': '', u'fileTransferEnable': u'true', 'nicModel': 'rtl8139,pv', u'keyboardLayout': u'en-us', u'kvmEnable': u'true', u'displayNetwork': u'ovirtmgmt', u'devices': [{u'specParams': {u'vram': u'32768', u'heads': u'1'}, 'deviceType': u'video', u'deviceId': u'910e0167-f86e-484d-a780-80b63ce05705', u'address': {u'slot': u'0x02', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, u'device': u'qxl', u'type': u'video'}, {u'index': u'2', u'iface': u'ide', u'specParams': {u'path': u''}, u'readonly': u'true', 'deviceType': u'disk', u'deviceId': u'8082b51e-33fb-44fb-aa90-2e06f6a7fdb5', u'shared': u'false', u'device': u'cdrom', u'path': u'', u'type': u'disk'}, {u'index': 0, u'iface': u'virtio', u'type': u'disk', u'format': u'raw', u'bootOrder': u'1', u'volumeID': u'9e189687-6118-4b28-ac36-e97063655af2', u'imageID': u'8cc2e445-649b-48c3-a182-970e80b49458', u'specParams': {}, u'readonly': u'false', u'domainID': u'f7453ce7-3aca-4ee3-98c3-827ce3e001d6', 'deviceType': u'disk', u'deviceId': u'8cc2e445-649b-48c3-a182-970e80b49458', u'poolID': u'00000002-0002-0002-0002-000000000247', u'device': u'disk', u'shared': u'false', u'propagateErrors': u'off', u'optional': u'false'}, {u'specParams': {u'model': u'virtio'}, 'deviceType': u'balloon', u'deviceId': u'97758edf-a87f-4996-ae98-ac71b9c798f0', u'address': {u'slot': u'0x05', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, u'device': u'memballoon', u'type': u'balloon'}, {u'index': u'0', u'specParams': {}, 'deviceType': u'controller', u'deviceId': u'2a707f91-a310-49c2-98aa-08f97851dd49', u'address': {u'slot': u'0x03', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, u'device': u'scsi', u'model': u'virtio-scsi', u'type': u'controller'}, {u'specParams': {}, 'deviceType': u'controller', u'deviceId': u'6721e2f4-5284-49e2-8732-a0757e19f8f9', u'address': {u'slot': u'0x04', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, u'device': u'virtio-serial', u'type': u'controller'}], u'timeOffset': u'0', u'maxVCpus': u'16', u'spiceSecureChannels': u'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', u'display': u'qxl'}
Thread-1292::DEBUG::2015-12-14 11:55:41,196::task::592::Storage.TaskManager.Task::(_updateState) Task=`f7193281-ef98-4191-8dee-92d4ef59499c`::moving from state init -> state preparing
Thread-1291::DEBUG::2015-12-14 11:55:41,198::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
Thread-1292::INFO::2015-12-14 11:55:41,198::logUtils::48::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID=u'f7453ce7-3aca-4ee3-98c3-827ce3e001d6', spUUID=u'00000002-0002-0002-0002-000000000247', imgUUID=u'8cc2e445-649b-48c3-a182-970e80b49458', volUUID=u'9e189687-6118-4b28-ac36-e97063655af2', options=None)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,203::__init__::411::IOProcess::(_processLogs) Queuing request (slotsLeft=20)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,203::__init__::411::IOProcess::(_processLogs) (1325) Start request for method 'stat' (waitTime=87)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,209::__init__::411::IOProcess::(_processLogs) (1325) Finished request for method 'stat' (runTime=6552)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,210::__init__::411::IOProcess::(_processLogs) (1325) Dequeuing request (slotsLeft=21)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,212::__init__::411::IOProcess::(_processLogs) Queuing request (slotsLeft=20)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,212::__init__::411::IOProcess::(_processLogs) (1326) Start request for method 'stat' (waitTime=233)
Thread-1292::INFO::2015-12-14 11:55:41,213::logUtils::51::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '4096', 'apparentsize': '10737418240'}
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,212::__init__::411::IOProcess::(_processLogs) (1326) Finished request for method 'stat' (runTime=27)
Thread-1292::DEBUG::2015-12-14 11:55:41,214::task::1188::Storage.TaskManager.Task::(prepare) Task=`f7193281-ef98-4191-8dee-92d4ef59499c`::finished: {'truesize': '4096', 'apparentsize': '10737418240'}
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,215::__init__::411::IOProcess::(_processLogs) (1326) Dequeuing request (slotsLeft=21)
Thread-1292::DEBUG::2015-12-14 11:55:41,216::task::592::Storage.TaskManager.Task::(_updateState) Task=`f7193281-ef98-4191-8dee-92d4ef59499c`::moving from state preparing -> state finished
Thread-1292::DEBUG::2015-12-14 11:55:41,217::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-1292::DEBUG::2015-12-14 11:55:41,217::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-1292::DEBUG::2015-12-14 11:55:41,217::task::990::Storage.TaskManager.Task::(_decref) Task=`f7193281-ef98-4191-8dee-92d4ef59499c`::ref 0 aborting False
Thread-1292::INFO::2015-12-14 11:55:41,217::clientIF::322::vds::(prepareVolumePath) prepared volume path: 
Thread-1292::DEBUG::2015-12-14 11:55:41,218::task::592::Storage.TaskManager.Task::(_updateState) Task=`20ff7805-dfdb-4a78-80a4-585006202371`::moving from state init -> state preparing
Thread-1292::INFO::2015-12-14 11:55:41,218::logUtils::48::dispatcher::(wrapper) Run and protect: prepareImage(sdUUID=u'f7453ce7-3aca-4ee3-98c3-827ce3e001d6', spUUID=u'00000002-0002-0002-0002-000000000247', imgUUID=u'8cc2e445-649b-48c3-a182-970e80b49458', leafUUID=u'9e189687-6118-4b28-ac36-e97063655af2')
Thread-1292::DEBUG::2015-12-14 11:55:41,218::resourceManager::198::Storage.ResourceManager.Request::(__init__) ResName=`Storage.f7453ce7-3aca-4ee3-98c3-827ce3e001d6`ReqID=`30d841eb-bfa4-4813-b200-baf92b57bd57`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3208' at 'prepareImage'
Thread-1292::DEBUG::2015-12-14 11:55:41,219::resourceManager::542::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.f7453ce7-3aca-4ee3-98c3-827ce3e001d6' for lock type 'shared'
Thread-1292::DEBUG::2015-12-14 11:55:41,219::resourceManager::601::Storage.ResourceManager::(registerResource) Resource 'Storage.f7453ce7-3aca-4ee3-98c3-827ce3e001d6' is free. Now locking as 'shared' (1 active user)
Thread-1292::DEBUG::2015-12-14 11:55:41,219::resourceManager::238::Storage.ResourceManager.Request::(grant) ResName=`Storage.f7453ce7-3aca-4ee3-98c3-827ce3e001d6`ReqID=`30d841eb-bfa4-4813-b200-baf92b57bd57`::Granted request
Thread-1292::DEBUG::2015-12-14 11:55:41,220::task::824::Storage.TaskManager.Task::(resourceAcquired) Task=`20ff7805-dfdb-4a78-80a4-585006202371`::_resourcesAcquired: Storage.f7453ce7-3aca-4ee3-98c3-827ce3e001d6 (shared)
Thread-1292::DEBUG::2015-12-14 11:55:41,220::task::990::Storage.TaskManager.Task::(_decref) Task=`20ff7805-dfdb-4a78-80a4-585006202371`::ref 1 aborting False
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,220::__init__::411::IOProcess::(_processLogs) Queuing request (slotsLeft=20)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,221::__init__::411::IOProcess::(_processLogs) (1327) Start request for method 'glob' (waitTime=310)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,241::__init__::411::IOProcess::(_processLogs) (1327) Finished request for method 'glob' (runTime=20268)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,241::__init__::411::IOProcess::(_processLogs) (1327) Dequeuing request (slotsLeft=21)
Thread-1292::DEBUG::2015-12-14 11:55:41,242::fileSD::499::Storage.StorageDomain::(activateVolumes) Fixing permissions on /rhev/data-center/mnt/glusterSD/st01.nieuwland.nl:gv__ovirt__data01/f7453ce7-3aca-4ee3-98c3-827ce3e001d6/images/8cc2e445-649b-48c3-a182-970e80b49458/9e189687-6118-4b28-ac36-e97063655af2
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,243::__init__::411::IOProcess::(_processLogs) Queuing request (slotsLeft=20)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,243::__init__::411::IOProcess::(_processLogs) (1328) Start request for method 'stat' (waitTime=31)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,244::__init__::411::IOProcess::(_processLogs) (1328) Finished request for method 'stat' (runTime=416)
Thread-1292::DEBUG::2015-12-14 11:55:41,244::fileUtils::142::Storage.fileUtils::(createdir) Creating directory: /var/run/vdsm/storage/f7453ce7-3aca-4ee3-98c3-827ce3e001d6
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,245::__init__::411::IOProcess::(_processLogs) (1328) Dequeuing request (slotsLeft=21)
Thread-1292::WARNING::2015-12-14 11:55:41,245::fileUtils::149::Storage.fileUtils::(createdir) Dir /var/run/vdsm/storage/f7453ce7-3aca-4ee3-98c3-827ce3e001d6 already exists
Thread-1292::DEBUG::2015-12-14 11:55:41,247::fileSD::474::Storage.StorageDomain::(createImageLinks) Creating symlink from /rhev/data-center/mnt/glusterSD/st01.nieuwland.nl:gv__ovirt__data01/f7453ce7-3aca-4ee3-98c3-827ce3e001d6/images/8cc2e445-649b-48c3-a182-970e80b49458 to /var/run/vdsm/storage/f7453ce7-3aca-4ee3-98c3-827ce3e001d6/8cc2e445-649b-48c3-a182-970e80b49458
Thread-1292::DEBUG::2015-12-14 11:55:41,247::fileSD::479::Storage.StorageDomain::(createImageLinks) img run dir already exists: /var/run/vdsm/storage/f7453ce7-3aca-4ee3-98c3-827ce3e001d6/8cc2e445-649b-48c3-a182-970e80b49458
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,248::__init__::411::IOProcess::(_processLogs) Queuing request (slotsLeft=20)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,249::__init__::411::IOProcess::(_processLogs) (1329) Start request for method 'stat' (waitTime=26)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,250::__init__::411::IOProcess::(_processLogs) (1329) Finished request for method 'stat' (runTime=18)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,250::__init__::411::IOProcess::(_processLogs) (1329) Dequeuing request (slotsLeft=21)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,250::__init__::411::IOProcess::(_processLogs) Queuing request (slotsLeft=20)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,251::__init__::411::IOProcess::(_processLogs) (1330) Start request for method 'access' (waitTime=25)
Thread-1292::DEBUG::2015-12-14 11:55:41,251::fileVolume::529::Storage.Volume::(validateVolumePath) validate path for 9e189687-6118-4b28-ac36-e97063655af2
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,252::__init__::411::IOProcess::(_processLogs) (1330) Finished request for method 'access' (runTime=14)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,253::__init__::411::IOProcess::(_processLogs) (1330) Dequeuing request (slotsLeft=21)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,254::__init__::411::IOProcess::(_processLogs) Queuing request (slotsLeft=20)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,254::__init__::411::IOProcess::(_processLogs) (1331) Start request for method 'access' (waitTime=25)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,255::__init__::411::IOProcess::(_processLogs) (1331) Finished request for method 'access' (runTime=13)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,256::__init__::411::IOProcess::(_processLogs) (1331) Dequeuing request (slotsLeft=21)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,256::__init__::411::IOProcess::(_processLogs) Queuing request (slotsLeft=20)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,256::__init__::411::IOProcess::(_processLogs) (1332) Start request for method 'access' (waitTime=37)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,258::__init__::411::IOProcess::(_processLogs) (1332) Finished request for method 'access' (runTime=11)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,258::__init__::411::IOProcess::(_processLogs) (1332) Dequeuing request (slotsLeft=21)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,258::__init__::411::IOProcess::(_processLogs) Queuing request (slotsLeft=20)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,259::__init__::411::IOProcess::(_processLogs) (1333) Start request for method 'stat' (waitTime=24)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,260::__init__::411::IOProcess::(_processLogs) (1333) Finished request for method 'stat' (runTime=17)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,260::__init__::411::IOProcess::(_processLogs) (1333) Dequeuing request (slotsLeft=21)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,260::__init__::411::IOProcess::(_processLogs) Queuing request (slotsLeft=20)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,261::__init__::411::IOProcess::(_processLogs) (1334) Start request for method 'access' (waitTime=24)
Thread-1292::DEBUG::2015-12-14 11:55:41,261::fileVolume::529::Storage.Volume::(validateVolumePath) validate path for 9e189687-6118-4b28-ac36-e97063655af2
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,262::__init__::411::IOProcess::(_processLogs) (1334) Finished request for method 'access' (runTime=10)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,263::__init__::411::IOProcess::(_processLogs) (1334) Dequeuing request (slotsLeft=21)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,264::__init__::411::IOProcess::(_processLogs) Queuing request (slotsLeft=20)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,264::__init__::411::IOProcess::(_processLogs) (1335) Start request for method 'access' (waitTime=25)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,266::__init__::411::IOProcess::(_processLogs) (1335) Finished request for method 'access' (runTime=11)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,266::__init__::411::IOProcess::(_processLogs) (1335) Dequeuing request (slotsLeft=21)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,267::__init__::411::IOProcess::(_processLogs) Queuing request (slotsLeft=20)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,267::__init__::411::IOProcess::(_processLogs) (1336) Start request for method 'access' (waitTime=25)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,268::__init__::411::IOProcess::(_processLogs) (1336) Finished request for method 'access' (runTime=11)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:41,269::__init__::411::IOProcess::(_processLogs) (1336) Dequeuing request (slotsLeft=21)
Thread-1292::ERROR::2015-12-14 11:55:41,295::task::863::Storage.TaskManager.Task::(_setError) Task=`20ff7805-dfdb-4a78-80a4-585006202371`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 870, in _run
    return fn(*args, **kargs)
  File "/usr/share/vdsm/logUtils.py", line 49, in wrapper
    res = f(*args, **kwargs)
  File "/usr/share/vdsm/storage/hsm.py", line 3242, in prepareImage
    leafInfo = dom.produceVolume(imgUUID, leafUUID).getVmVolumeInfo()
  File "/usr/share/vdsm/storage/glusterVolume.py", line 35, in getVmVolumeInfo
    volTrans = VOLUME_TRANS_MAP[volInfo[volname]['transportType'][0]]
KeyError: u'gv__ovirt__data01'
Thread-1292::DEBUG::2015-12-14 11:55:41,296::task::882::Storage.TaskManager.Task::(_run) Task=`20ff7805-dfdb-4a78-80a4-585006202371`::Task._run: 20ff7805-dfdb-4a78-80a4-585006202371 (u'f7453ce7-3aca-4ee3-98c3-827ce3e001d6', u'00000002-0002-0002-0002-000000000247', u'8cc2e445-649b-48c3-a182-970e80b49458', u'9e189687-6118-4b28-ac36-e97063655af2') {} failed - stopping task
Thread-1292::DEBUG::2015-12-14 11:55:41,296::task::1214::Storage.TaskManager.Task::(stop) Task=`20ff7805-dfdb-4a78-80a4-585006202371`::stopping in state preparing (force False)
Thread-1292::DEBUG::2015-12-14 11:55:41,296::task::990::Storage.TaskManager.Task::(_decref) Task=`20ff7805-dfdb-4a78-80a4-585006202371`::ref 1 aborting True
Thread-1292::INFO::2015-12-14 11:55:41,296::task::1168::Storage.TaskManager.Task::(prepare) Task=`20ff7805-dfdb-4a78-80a4-585006202371`::aborting: Task is aborted: u"u'gv__ovirt__data01'" - code 100
Thread-1292::DEBUG::2015-12-14 11:55:41,296::task::1173::Storage.TaskManager.Task::(prepare) Task=`20ff7805-dfdb-4a78-80a4-585006202371`::Prepare: aborted: u'gv__ovirt__data01'
Thread-1292::DEBUG::2015-12-14 11:55:41,296::task::990::Storage.TaskManager.Task::(_decref) Task=`20ff7805-dfdb-4a78-80a4-585006202371`::ref 0 aborting True
Thread-1292::DEBUG::2015-12-14 11:55:41,297::task::925::Storage.TaskManager.Task::(_doAbort) Task=`20ff7805-dfdb-4a78-80a4-585006202371`::Task._doAbort: force False
Thread-1292::DEBUG::2015-12-14 11:55:41,297::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-1292::DEBUG::2015-12-14 11:55:41,297::task::592::Storage.TaskManager.Task::(_updateState) Task=`20ff7805-dfdb-4a78-80a4-585006202371`::moving from state preparing -> state aborting
Thread-1292::DEBUG::2015-12-14 11:55:41,297::task::547::Storage.TaskManager.Task::(__state_aborting) Task=`20ff7805-dfdb-4a78-80a4-585006202371`::_aborting: recover policy none
Thread-1292::DEBUG::2015-12-14 11:55:41,297::task::592::Storage.TaskManager.Task::(_updateState) Task=`20ff7805-dfdb-4a78-80a4-585006202371`::moving from state aborting -> state failed
Thread-1292::DEBUG::2015-12-14 11:55:41,297::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {u'Storage.f7453ce7-3aca-4ee3-98c3-827ce3e001d6': < ResourceRef 'Storage.f7453ce7-3aca-4ee3-98c3-827ce3e001d6', isValid: 'True' obj: 'None'>}
Thread-1292::DEBUG::2015-12-14 11:55:41,298::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-1292::DEBUG::2015-12-14 11:55:41,298::resourceManager::616::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.f7453ce7-3aca-4ee3-98c3-827ce3e001d6'
Thread-1292::DEBUG::2015-12-14 11:55:41,298::resourceManager::635::Storage.ResourceManager::(releaseResource) Released resource 'Storage.f7453ce7-3aca-4ee3-98c3-827ce3e001d6' (0 active users)
Thread-1292::DEBUG::2015-12-14 11:55:41,298::resourceManager::641::Storage.ResourceManager::(releaseResource) Resource 'Storage.f7453ce7-3aca-4ee3-98c3-827ce3e001d6' is free, finding out if anyone is waiting for it.
Thread-1292::DEBUG::2015-12-14 11:55:41,298::resourceManager::649::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.f7453ce7-3aca-4ee3-98c3-827ce3e001d6', Clearing records.
Thread-1292::ERROR::2015-12-14 11:55:41,299::dispatcher::79::Storage.Dispatcher::(wrapper) u'gv__ovirt__data01'
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/dispatcher.py", line 71, in wrapper
    result = ctask.prepare(func, *args, **kwargs)
  File "/usr/share/vdsm/storage/task.py", line 103, in wrapper
    return m(self, *a, **kw)
  File "/usr/share/vdsm/storage/task.py", line 1176, in prepare
    raise self.error
KeyError: u'gv__ovirt__data01'
Thread-1292::ERROR::2015-12-14 11:55:41,299::vm::1690::vm.Vm::(_startUnderlyingVm) vmId=`4838abf2-bf06-4a58-a648-bdb9bee93bf1`::The vm start process failed
Traceback (most recent call last):
  File "/usr/share/vdsm/virt/vm.py", line 1638, in _startUnderlyingVm
    self._run()
  File "/usr/share/vdsm/virt/vm.py", line 2661, in _run
    self.preparePaths(devices[DISK_DEVICES])
  File "/usr/share/vdsm/virt/vm.py", line 1711, in preparePaths
    drive['path'] = self.cif.prepareVolumePath(drive, self.id)
  File "/usr/share/vdsm/clientIF.py", line 264, in prepareVolumePath
    raise vm.VolumeError(drive)
VolumeError: Bad volume specification {u'index': 0, u'iface': u'virtio', u'type': u'disk', u'format': u'raw', u'bootOrder': u'1', u'volumeID': u'9e189687-6118-4b28-ac36-e97063655af2', 'apparentsize': '10737418240', u'imageID': u'8cc2e445-649b-48c3-a182-970e80b49458', u'specParams': {}, u'readonly': u'false', u'domainID': u'f7453ce7-3aca-4ee3-98c3-827ce3e001d6', 'reqsize': '0', u'deviceId': u'8cc2e445-649b-48c3-a182-970e80b49458', 'truesize': '4096', u'poolID': u'00000002-0002-0002-0002-000000000247', u'device': u'disk', u'shared': u'false', u'propagateErrors': u'off', u'optional': u'false'}
Thread-1292::DEBUG::2015-12-14 11:55:41,301::vm::2200::vm.Vm::(setDownStatus) vmId=`4838abf2-bf06-4a58-a648-bdb9bee93bf1`::Changed state to Down: Bad volume specification {u'index': 0, u'iface': u'virtio', u'type': u'disk', u'format': u'raw', u'bootOrder': u'1', u'volumeID': u'9e189687-6118-4b28-ac36-e97063655af2', 'apparentsize': '10737418240', u'imageID': u'8cc2e445-649b-48c3-a182-970e80b49458', u'specParams': {}, u'readonly': u'false', u'domainID': u'f7453ce7-3aca-4ee3-98c3-827ce3e001d6', 'reqsize': '0', u'deviceId': u'8cc2e445-649b-48c3-a182-970e80b49458', 'truesize': '4096', u'poolID': u'00000002-0002-0002-0002-000000000247', u'device': u'disk', u'shared': u'false', u'propagateErrors': u'off', u'optional': u'false'} (code=1)
Thread-1292::DEBUG::2015-12-14 11:55:41,301::vmchannels::213::vds::(unregister) Delete fileno 37 from listener.
JsonRpc (StompReactor)::DEBUG::2015-12-14 11:55:41,622::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-12-14 11:55:41,623::__init__::506::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-1294::DEBUG::2015-12-14 11:55:41,627::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
JsonRpc (StompReactor)::DEBUG::2015-12-14 11:55:41,629::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-12-14 11:55:41,631::__init__::506::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-1295::DEBUG::2015-12-14 11:55:41,633::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
JsonRpc (StompReactor)::DEBUG::2015-12-14 11:55:41,638::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-12-14 11:55:41,640::__init__::506::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-1296::DEBUG::2015-12-14 11:55:41,640::__init__::469::jsonrpc.JsonRpcServer::(_serveRequest) Calling 'VM.destroy' in bridge with {u'vmID': u'4838abf2-bf06-4a58-a648-bdb9bee93bf1'}
Thread-1296::INFO::2015-12-14 11:55:41,642::API::332::vds::(destroy) vmContainerLock acquired by vm 4838abf2-bf06-4a58-a648-bdb9bee93bf1
Thread-1296::DEBUG::2015-12-14 11:55:41,642::vm::4415::vm.Vm::(destroy) vmId=`4838abf2-bf06-4a58-a648-bdb9bee93bf1`::destroy Called
Thread-1296::INFO::2015-12-14 11:55:41,642::vm::4344::vm.Vm::(releaseVm) vmId=`4838abf2-bf06-4a58-a648-bdb9bee93bf1`::Release VM resources
Thread-1296::WARNING::2015-12-14 11:55:41,642::vm::1321::vm.Vm::(_set_lastStatus) vmId=`4838abf2-bf06-4a58-a648-bdb9bee93bf1`::trying to set state to Powering down when already Down
Thread-1296::WARNING::2015-12-14 11:55:41,643::utils::140::root::(rmFile) File: /var/lib/libvirt/qemu/channels/4838abf2-bf06-4a58-a648-bdb9bee93bf1.com.redhat.rhevm.vdsm already removed
Thread-1296::WARNING::2015-12-14 11:55:41,643::utils::140::root::(rmFile) File: /var/lib/libvirt/qemu/channels/4838abf2-bf06-4a58-a648-bdb9bee93bf1.org.qemu.guest_agent.0 already removed
Thread-1296::DEBUG::2015-12-14 11:55:41,644::task::592::Storage.TaskManager.Task::(_updateState) Task=`d18c6e20-29d0-4a73-b2d3-910986e19d89`::moving from state init -> state preparing
Thread-1296::INFO::2015-12-14 11:55:41,644::logUtils::48::dispatcher::(wrapper) Run and protect: inappropriateDevices(thiefId=u'4838abf2-bf06-4a58-a648-bdb9bee93bf1')
Thread-1296::INFO::2015-12-14 11:55:41,646::logUtils::51::dispatcher::(wrapper) Run and protect: inappropriateDevices, Return response: None
Thread-1296::DEBUG::2015-12-14 11:55:41,646::task::1188::Storage.TaskManager.Task::(prepare) Task=`d18c6e20-29d0-4a73-b2d3-910986e19d89`::finished: None
Thread-1296::DEBUG::2015-12-14 11:55:41,647::task::592::Storage.TaskManager.Task::(_updateState) Task=`d18c6e20-29d0-4a73-b2d3-910986e19d89`::moving from state preparing -> state finished
Thread-1296::DEBUG::2015-12-14 11:55:41,647::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-1296::DEBUG::2015-12-14 11:55:41,647::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-1296::DEBUG::2015-12-14 11:55:41,647::task::990::Storage.TaskManager.Task::(_decref) Task=`d18c6e20-29d0-4a73-b2d3-910986e19d89`::ref 0 aborting False
Thread-1296::DEBUG::2015-12-14 11:55:41,647::vm::4409::vm.Vm::(deleteVm) vmId=`4838abf2-bf06-4a58-a648-bdb9bee93bf1`::Total desktops after destroy of 4838abf2-bf06-4a58-a648-bdb9bee93bf1 is 0
Thread-1296::DEBUG::2015-12-14 11:55:41,648::__init__::500::jsonrpc.JsonRpcServer::(_serveRequest) Return 'VM.destroy' in bridge with True
Thread-1296::DEBUG::2015-12-14 11:55:41,648::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
VM Channels Listener::DEBUG::2015-12-14 11:55:42,165::vmchannels::121::vds::(_do_del_channels) fileno 37 was removed from listener.
JsonRpc (StompReactor)::DEBUG::2015-12-14 11:55:44,685::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-12-14 11:55:44,687::__init__::506::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-1297::DEBUG::2015-12-14 11:55:44,689::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
ioprocess communication (15961)::DEBUG::2015-12-14 11:55:45,849::__init__::411::IOProcess::(_processLogs) Queuing request (slotsLeft=20)
ioprocess communication (15961)::DEBUG::2015-12-14 11:55:45,849::__init__::411::IOProcess::(_processLogs) (533) Start request for method 'statvfs' (waitTime=29)
ioprocess communication (15961)::DEBUG::2015-12-14 11:55:45,850::__init__::411::IOProcess::(_processLogs) (533) Finished request for method 'statvfs' (runTime=572)
ioprocess communication (15961)::DEBUG::2015-12-14 11:55:45,852::__init__::411::IOProcess::(_processLogs) (533) Dequeuing request (slotsLeft=21)
Thread-33::DEBUG::2015-12-14 11:55:45,852::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/shadow.nieuwland.nl:_export_ovirt/6d00b190-a3a8-4e75-b718-4ba680d7a228/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-33::DEBUG::2015-12-14 11:55:45,865::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n318 bytes (318 B) copied, 0.000476613 s, 667 kB/s\n'; <rc> = 0
ioprocess communication (15961)::DEBUG::2015-12-14 11:55:45,867::__init__::411::IOProcess::(_processLogs) Queuing request (slotsLeft=20)
ioprocess communication (15961)::DEBUG::2015-12-14 11:55:45,867::__init__::411::IOProcess::(_processLogs) (534) Start request for method 'statvfs' (waitTime=77)
ioprocess communication (15961)::DEBUG::2015-12-14 11:55:45,869::__init__::411::IOProcess::(_processLogs) (534) Finished request for method 'statvfs' (runTime=306)
ioprocess communication (15961)::DEBUG::2015-12-14 11:55:45,869::__init__::411::IOProcess::(_processLogs) (534) Dequeuing request (slotsLeft=21)
ioprocess communication (15948)::DEBUG::2015-12-14 11:55:46,015::__init__::411::IOProcess::(_processLogs) Queuing request (slotsLeft=20)
ioprocess communication (15948)::DEBUG::2015-12-14 11:55:46,016::__init__::411::IOProcess::(_processLogs) (533) Start request for method 'statvfs' (waitTime=30)
ioprocess communication (15948)::DEBUG::2015-12-14 11:55:46,017::__init__::411::IOProcess::(_processLogs) (533) Finished request for method 'statvfs' (runTime=1578)
ioprocess communication (15948)::DEBUG::2015-12-14 11:55:46,017::__init__::411::IOProcess::(_processLogs) (533) Dequeuing request (slotsLeft=21)
Thread-32::DEBUG::2015-12-14 11:55:46,018::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/st01.nieuwland.nl:_gv__ovirt__iso01/4b083e6a-d588-4735-bf50-833033c24e6b/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:46,030::__init__::411::IOProcess::(_processLogs) Queuing request (slotsLeft=20)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:46,032::__init__::411::IOProcess::(_processLogs) (1337) Start request for method 'statvfs' (waitTime=88)
Thread-32::DEBUG::2015-12-14 11:55:46,032::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n336 bytes (336 B) copied, 0.000744153 s, 452 kB/s\n'; <rc> = 0
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:46,035::__init__::411::IOProcess::(_processLogs) (1337) Finished request for method 'statvfs' (runTime=2768)
Thread-31::DEBUG::2015-12-14 11:55:46,038::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/glusterSD/st01.nieuwland.nl:gv__ovirt__data01/f7453ce7-3aca-4ee3-98c3-827ce3e001d6/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:46,039::__init__::411::IOProcess::(_processLogs) (1337) Dequeuing request (slotsLeft=21)
ioprocess communication (15948)::DEBUG::2015-12-14 11:55:46,040::__init__::411::IOProcess::(_processLogs) Queuing request (slotsLeft=20)
ioprocess communication (15948)::DEBUG::2015-12-14 11:55:46,053::__init__::411::IOProcess::(_processLogs) (534) Start request for method 'statvfs' (waitTime=27)
ioprocess communication (15948)::DEBUG::2015-12-14 11:55:46,053::__init__::411::IOProcess::(_processLogs) (534) Finished request for method 'statvfs' (runTime=1146)
ioprocess communication (15948)::DEBUG::2015-12-14 11:55:46,054::__init__::411::IOProcess::(_processLogs) (534) Dequeuing request (slotsLeft=21)
Thread-31::DEBUG::2015-12-14 11:55:46,056::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n474 bytes (474 B) copied, 0.0006351 s, 746 kB/s\n'; <rc> = 0
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:46,058::__init__::411::IOProcess::(_processLogs) Queuing request (slotsLeft=20)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:46,058::__init__::411::IOProcess::(_processLogs) (1338) Start request for method 'statvfs' (waitTime=50)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:46,058::__init__::411::IOProcess::(_processLogs) (1338) Finished request for method 'statvfs' (runTime=673)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:46,059::__init__::411::IOProcess::(_processLogs) (1338) Dequeuing request (slotsLeft=21)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:46,061::__init__::411::IOProcess::(_processLogs) Queuing request (slotsLeft=20)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:46,061::__init__::411::IOProcess::(_processLogs) (1339) Start request for method 'access' (waitTime=267)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:46,062::__init__::411::IOProcess::(_processLogs) (1339) Finished request for method 'access' (runTime=712)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:46,063::__init__::411::IOProcess::(_processLogs) (1339) Dequeuing request (slotsLeft=21)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:46,064::__init__::411::IOProcess::(_processLogs) Queuing request (slotsLeft=20)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:46,064::__init__::411::IOProcess::(_processLogs) (1340) Start request for method 'access' (waitTime=22)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:46,065::__init__::411::IOProcess::(_processLogs) (1340) Finished request for method 'access' (runTime=647)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:46,065::__init__::411::IOProcess::(_processLogs) (1340) Dequeuing request (slotsLeft=21)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:46,066::__init__::411::IOProcess::(_processLogs) Queuing request (slotsLeft=20)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:46,066::__init__::411::IOProcess::(_processLogs) (1341) Start request for method 'access' (waitTime=22)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:46,067::__init__::411::IOProcess::(_processLogs) (1341) Finished request for method 'access' (runTime=666)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:46,067::__init__::411::IOProcess::(_processLogs) (1341) Dequeuing request (slotsLeft=21)
JsonRpc (StompReactor)::DEBUG::2015-12-14 11:55:47,698::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-12-14 11:55:47,699::__init__::506::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-1298::DEBUG::2015-12-14 11:55:47,703::task::592::Storage.TaskManager.Task::(_updateState) Task=`801a81f9-e903-4e83-9c31-09d5fe460642`::moving from state init -> state preparing
Thread-1298::INFO::2015-12-14 11:55:47,703::logUtils::48::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-1298::INFO::2015-12-14 11:55:47,703::logUtils::51::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'f7453ce7-3aca-4ee3-98c3-827ce3e001d6': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.0006351', 'lastCheck': '1.6', 'valid': True}, u'4b083e6a-d588-4735-bf50-833033c24e6b': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000744153', 'lastCheck': '1.6', 'valid': True}, u'6d00b190-a3a8-4e75-b718-4ba680d7a228': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000476613', 'lastCheck': '1.8', 'valid': True}}
Thread-1298::DEBUG::2015-12-14 11:55:47,703::task::1188::Storage.TaskManager.Task::(prepare) Task=`801a81f9-e903-4e83-9c31-09d5fe460642`::finished: {u'f7453ce7-3aca-4ee3-98c3-827ce3e001d6': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.0006351', 'lastCheck': '1.6', 'valid': True}, u'4b083e6a-d588-4735-bf50-833033c24e6b': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000744153', 'lastCheck': '1.6', 'valid': True}, u'6d00b190-a3a8-4e75-b718-4ba680d7a228': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000476613', 'lastCheck': '1.8', 'valid': True}}
Thread-1298::DEBUG::2015-12-14 11:55:47,704::task::592::Storage.TaskManager.Task::(_updateState) Task=`801a81f9-e903-4e83-9c31-09d5fe460642`::moving from state preparing -> state finished
Thread-1298::DEBUG::2015-12-14 11:55:47,704::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-1298::DEBUG::2015-12-14 11:55:47,704::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-1298::DEBUG::2015-12-14 11:55:47,704::task::990::Storage.TaskManager.Task::(_decref) Task=`801a81f9-e903-4e83-9c31-09d5fe460642`::ref 0 aborting False
Thread-1298::DEBUG::2015-12-14 11:55:47,706::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
JsonRpc (StompReactor)::DEBUG::2015-12-14 11:55:47,721::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-12-14 11:55:47,723::__init__::506::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-1299::DEBUG::2015-12-14 11:55:47,725::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
JsonRpc (StompReactor)::DEBUG::2015-12-14 11:55:50,779::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-12-14 11:55:50,781::__init__::506::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-1300::DEBUG::2015-12-14 11:55:50,784::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
JsonRpc (StompReactor)::DEBUG::2015-12-14 11:55:53,793::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-12-14 11:55:53,794::__init__::506::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-1301::DEBUG::2015-12-14 11:55:53,797::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
ioprocess communication (15961)::DEBUG::2015-12-14 11:55:55,870::__init__::411::IOProcess::(_processLogs) Queuing request (slotsLeft=20)
ioprocess communication (15961)::DEBUG::2015-12-14 11:55:55,870::__init__::411::IOProcess::(_processLogs) (535) Start request for method 'statvfs' (waitTime=53)
ioprocess communication (15961)::DEBUG::2015-12-14 11:55:55,871::__init__::411::IOProcess::(_processLogs) (535) Finished request for method 'statvfs' (runTime=901)
ioprocess communication (15961)::DEBUG::2015-12-14 11:55:55,872::__init__::411::IOProcess::(_processLogs) (535) Dequeuing request (slotsLeft=21)
Thread-33::DEBUG::2015-12-14 11:55:55,873::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/shadow.nieuwland.nl:_export_ovirt/6d00b190-a3a8-4e75-b718-4ba680d7a228/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-33::DEBUG::2015-12-14 11:55:55,886::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n318 bytes (318 B) copied, 0.000311779 s, 1.0 MB/s\n'; <rc> = 0
ioprocess communication (15961)::DEBUG::2015-12-14 11:55:55,887::__init__::411::IOProcess::(_processLogs) Queuing request (slotsLeft=20)
ioprocess communication (15961)::DEBUG::2015-12-14 11:55:55,889::__init__::411::IOProcess::(_processLogs) (536) Start request for method 'statvfs' (waitTime=58)
ioprocess communication (15961)::DEBUG::2015-12-14 11:55:55,890::__init__::411::IOProcess::(_processLogs) (536) Finished request for method 'statvfs' (runTime=332)
ioprocess communication (15961)::DEBUG::2015-12-14 11:55:55,890::__init__::411::IOProcess::(_processLogs) (536) Dequeuing request (slotsLeft=21)
ioprocess communication (15948)::DEBUG::2015-12-14 11:55:56,058::__init__::411::IOProcess::(_processLogs) Queuing request (slotsLeft=20)
ioprocess communication (15948)::DEBUG::2015-12-14 11:55:56,058::__init__::411::IOProcess::(_processLogs) (535) Start request for method 'statvfs' (waitTime=30)
ioprocess communication (15948)::DEBUG::2015-12-14 11:55:56,060::__init__::411::IOProcess::(_processLogs) (535) Finished request for method 'statvfs' (runTime=2393)
ioprocess communication (15948)::DEBUG::2015-12-14 11:55:56,060::__init__::411::IOProcess::(_processLogs) (535) Dequeuing request (slotsLeft=21)
Thread-32::DEBUG::2015-12-14 11:55:56,061::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/st01.nieuwland.nl:_gv__ovirt__iso01/4b083e6a-d588-4735-bf50-833033c24e6b/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:56,073::__init__::411::IOProcess::(_processLogs) Queuing request (slotsLeft=20)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:56,074::__init__::411::IOProcess::(_processLogs) (1342) Start request for method 'statvfs' (waitTime=59)
Thread-32::DEBUG::2015-12-14 11:55:56,074::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n336 bytes (336 B) copied, 0.00102867 s, 327 kB/s\n'; <rc> = 0
ioprocess communication (15948)::DEBUG::2015-12-14 11:55:56,075::__init__::411::IOProcess::(_processLogs) Queuing request (slotsLeft=20)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:56,076::__init__::411::IOProcess::(_processLogs) (1342) Finished request for method 'statvfs' (runTime=2355)
ioprocess communication (15948)::DEBUG::2015-12-14 11:55:56,076::__init__::411::IOProcess::(_processLogs) (536) Start request for method 'statvfs' (waitTime=32)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:56,077::__init__::411::IOProcess::(_processLogs) (1342) Dequeuing request (slotsLeft=21)
ioprocess communication (15948)::DEBUG::2015-12-14 11:55:56,077::__init__::411::IOProcess::(_processLogs) (536) Finished request for method 'statvfs' (runTime=1022)
ioprocess communication (15948)::DEBUG::2015-12-14 11:55:56,079::__init__::411::IOProcess::(_processLogs) (536) Dequeuing request (slotsLeft=21)
Thread-31::DEBUG::2015-12-14 11:55:56,080::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/glusterSD/st01.nieuwland.nl:gv__ovirt__data01/f7453ce7-3aca-4ee3-98c3-827ce3e001d6/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-31::DEBUG::2015-12-14 11:55:56,096::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n474 bytes (474 B) copied, 0.000647777 s, 732 kB/s\n'; <rc> = 0
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:56,098::__init__::411::IOProcess::(_processLogs) Queuing request (slotsLeft=20)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:56,098::__init__::411::IOProcess::(_processLogs) (1343) Start request for method 'statvfs' (waitTime=76)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:56,099::__init__::411::IOProcess::(_processLogs) (1343) Finished request for method 'statvfs' (runTime=537)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:56,100::__init__::411::IOProcess::(_processLogs) (1343) Dequeuing request (slotsLeft=21)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:56,100::__init__::411::IOProcess::(_processLogs) Queuing request (slotsLeft=20)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:56,101::__init__::411::IOProcess::(_processLogs) (1344) Start request for method 'access' (waitTime=34)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:56,101::__init__::411::IOProcess::(_processLogs) (1344) Finished request for method 'access' (runTime=732)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:56,102::__init__::411::IOProcess::(_processLogs) (1344) Dequeuing request (slotsLeft=21)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:56,103::__init__::411::IOProcess::(_processLogs) Queuing request (slotsLeft=20)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:56,103::__init__::411::IOProcess::(_processLogs) (1345) Start request for method 'access' (waitTime=43)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:56,104::__init__::411::IOProcess::(_processLogs) (1345) Finished request for method 'access' (runTime=700)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:56,104::__init__::411::IOProcess::(_processLogs) (1345) Dequeuing request (slotsLeft=21)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:56,105::__init__::411::IOProcess::(_processLogs) Queuing request (slotsLeft=20)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:56,105::__init__::411::IOProcess::(_processLogs) (1346) Start request for method 'access' (waitTime=33)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:56,105::__init__::411::IOProcess::(_processLogs) (1346) Finished request for method 'access' (runTime=650)
ioprocess communication (15885)::DEBUG::2015-12-14 11:55:56,106::__init__::411::IOProcess::(_processLogs) (1346) Dequeuing request (slotsLeft=21)
JsonRpc (StompReactor)::DEBUG::2015-12-14 11:55:56,805::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-12-14 11:55:56,806::__init__::506::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-1302::DEBUG::2015-12-14 11:55:56,809::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
JsonRpc (StompReactor)::DEBUG::2015-12-14 11:55:59,818::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-12-14 11:55:59,820::__init__::506::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-1303::DEBUG::2015-12-14 11:55:59,822::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
JsonRpc (StompReactor)::DEBUG::2015-12-14 11:56:02,830::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-12-14 11:56:02,832::__init__::506::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-1304::DEBUG::2015-12-14 11:56:02,836::task::592::Storage.TaskManager.Task::(_updateState) Task=`11beaebe-30f9-44ba-98a1-0c96eb0d7549`::moving from state init -> state preparing
Thread-1304::INFO::2015-12-14 11:56:02,836::logUtils::48::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-1304::INFO::2015-12-14 11:56:02,836::logUtils::51::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'f7453ce7-3aca-4ee3-98c3-827ce3e001d6': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000647777', 'lastCheck': '6.7', 'valid': True}, u'4b083e6a-d588-4735-bf50-833033c24e6b': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.00102867', 'lastCheck': '6.7', 'valid': True}, u'6d00b190-a3a8-4e75-b718-4ba680d7a228': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000311779', 'lastCheck': '6.9', 'valid': True}}
Thread-1304::DEBUG::2015-12-14 11:56:02,837::task::1188::Storage.TaskManager.Task::(prepare) Task=`11beaebe-30f9-44ba-98a1-0c96eb0d7549`::finished: {u'f7453ce7-3aca-4ee3-98c3-827ce3e001d6': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000647777', 'lastCheck': '6.7', 'valid': True}, u'4b083e6a-d588-4735-bf50-833033c24e6b': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.00102867', 'lastCheck': '6.7', 'valid': True}, u'6d00b190-a3a8-4e75-b718-4ba680d7a228': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000311779', 'lastCheck': '6.9', 'valid': True}}
Thread-1304::DEBUG::2015-12-14 11:56:02,837::task::592::Storage.TaskManager.Task::(_updateState) Task=`11beaebe-30f9-44ba-98a1-0c96eb0d7549`::moving from state preparing -> state finished
Thread-1304::DEBUG::2015-12-14 11:56:02,837::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-1304::DEBUG::2015-12-14 11:56:02,837::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-1304::DEBUG::2015-12-14 11:56:02,837::task::990::Storage.TaskManager.Task::(_decref) Task=`11beaebe-30f9-44ba-98a1-0c96eb0d7549`::ref 0 aborting False
Thread-1304::DEBUG::2015-12-14 11:56:02,839::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
JsonRpc (StompReactor)::DEBUG::2015-12-14 11:56:02,853::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-12-14 11:56:02,854::__init__::506::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-1305::DEBUG::2015-12-14 11:56:02,856::stompReactor::163::yajsonrpc.StompServer::(send) Sending response