I have reinstalled my test environment have come across an old error,
see BZ 988299, Bad volume specification {u'index': 0,.
At the end of that BZ there is mentioning of a problem with '_' in the
name of the volume and a patch is mentioned but the code has since been
change quite a bit and I can't find if that still applies. It look like
it doesn't because I have a gluster volume with the name gv_ovirt_data01
and it look like it gets translated to gv__ovirt__data01 and then I
can't start any VMs :-(
Weird thing, I CAN import VMs from the export domain to this gluster domain.
Regards,
Joop
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
2015-12-14 11:55:38,101 INFO [org.ovirt.engine.core.bll.RunVmCommand]
(ajp--127.0.0.1-8702-5) [7bde72f7] Lock Acquired to object EngineLock
[exclusiveLocks= key: 4838abf2-bf06-4a58-a648-bdb9bee93bf1 value: VM
, sharedLocks= ]
2015-12-14 11:55:38,130 INFO
[org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand]
(ajp--127.0.0.1-8702-5) [7bde72f7] START, IsVmDuringInitiatingVDSCommand( vmId
= 4838abf2-bf06-4a58-a648-bdb9bee93bf1), log id: 67e72d31
2015-12-14 11:55:38,130 INFO
[org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand]
(ajp--127.0.0.1-8702-5) [7bde72f7] FINISH, IsVmDuringInitiatingVDSCommand,
return: false, log id: 67e72d31
2015-12-14 11:55:38,184 INFO [org.ovirt.engine.core.bll.RunVmCommand]
(org.ovirt.thread.pool-8-thread-50) [7bde72f7] Running command: RunVmCommand
internal: false. Entities affected : ID: 4838abf2-bf06-4a58-a648-bdb9bee93bf1
Type: VMAction group VM_BASIC_OPERATIONS with role type USER
2015-12-14 11:55:38,202 INFO
[org.ovirt.engine.core.bll.scheduling.policyunits.HaReservationWeightPolicyUnit]
(org.ovirt.thread.pool-8-thread-50) [7bde72f7] Started HA reservation scoring
method
2015-12-14 11:55:38,211 INFO
[org.ovirt.engine.core.vdsbroker.UpdateVmDynamicDataVDSCommand]
(org.ovirt.thread.pool-8-thread-50) [7bde72f7] START,
UpdateVmDynamicDataVDSCommand(HostName = host02, HostId =
fe25f719-42ed-4632-9985-1188c96d39a3,
vmDynamic=org.ovirt.engine.core.common.businessentities.VmDynamic@3d49e0b3),
log id: 6fd712b3
2015-12-14 11:55:38,217 INFO
[org.ovirt.engine.core.vdsbroker.UpdateVmDynamicDataVDSCommand]
(org.ovirt.thread.pool-8-thread-50) [7bde72f7] FINISH,
UpdateVmDynamicDataVDSCommand, log id: 6fd712b3
2015-12-14 11:55:38,221 INFO
[org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand]
(org.ovirt.thread.pool-8-thread-50) [7bde72f7] START,
CreateVmVDSCommand(HostName = host02, HostId =
fe25f719-42ed-4632-9985-1188c96d39a3,
vmId=4838abf2-bf06-4a58-a648-bdb9bee93bf1, vm=VM [testvm]), log id: 2ab47984
2015-12-14 11:55:38,223 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand]
(org.ovirt.thread.pool-8-thread-50) [7bde72f7] START, CreateVDSCommand(HostName
= host02, HostId = fe25f719-42ed-4632-9985-1188c96d39a3,
vmId=4838abf2-bf06-4a58-a648-bdb9bee93bf1, vm=VM [testvm]), log id: f7bfeb3
2015-12-14 11:55:38,234 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand]
(org.ovirt.thread.pool-8-thread-50) [7bde72f7]
org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand
kvmEnable=true,keyboardLayout=en-us,nice=0,displayNetwork=ovirtmgmt,copyPasteEnable=true,timeOffset=0,transparentHugePages=true,vmId=4838abf2-bf06-4a58-a648-bdb9bee93bf1,acpiEnable=true,custom={},spiceSslCipherSuite=DEFAULT,memSize=1024,smp=1,emulatedMachine=rhel6.5.0,vmType=kvm,memGuaranteedSize=1024,display=qxl,smartcardEnable=false,bootMenuEnable=false,spiceSecureChannels=smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard,smpCoresPerSocket=1,maxVCpus=16,devices=[{address={bus=0x00,
domain=0x0000, type=pci, slot=0x02, function=0x0}, specParams={vram=32768,
heads=1}, device=qxl, type=video,
deviceId=910e0167-f86e-484d-a780-80b63ce05705}, {shared=false, iface=ide,
index=2, specParams={path=}, path=, device=cdrom, type=disk, readonly=true,
deviceId=8082b51e-33fb-44fb-aa90-2e06f6a7fdb5}, {shared=false, index=0,
volumeID=9e189687-6118-4b28-ac36-e97063655af2, propagateErrors=off, format=raw,
type=disk, iface=virtio, bootOrder=1,
domainID=f7453ce7-3aca-4ee3-98c3-827ce3e001d6,
imageID=8cc2e445-649b-48c3-a182-970e80b49458, specParams={}, optional=false,
device=disk, poolID=00000002-0002-0002-0002-000000000247, readonly=false,
deviceId=8cc2e445-649b-48c3-a182-970e80b49458}, {address={bus=0x00,
domain=0x0000, type=pci, slot=0x05, function=0x0}, specParams={model=virtio},
device=memballoon, type=balloon,
deviceId=97758edf-a87f-4996-ae98-ac71b9c798f0}, {index=0, model=virtio-scsi,
address={bus=0x00, domain=0x0000, type=pci, slot=0x03, function=0x0},
specParams={}, device=scsi, type=controller,
deviceId=2a707f91-a310-49c2-98aa-08f97851dd49}, {address={bus=0x00,
domain=0x0000, type=pci, slot=0x04, function=0x0}, specParams={},
device=virtio-serial, type=controller,
deviceId=6721e2f4-5284-49e2-8732-a0757e19f8f9}],vmName=testvm,cpuType=Conroe,fileTransferEnable=true
2015-12-14 11:55:38,262 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand]
(org.ovirt.thread.pool-8-thread-50) [7bde72f7] FINISH, CreateVDSCommand, log
id: f7bfeb3
2015-12-14 11:55:38,276 INFO
[org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand]
(org.ovirt.thread.pool-8-thread-50) [7bde72f7] FINISH, CreateVmVDSCommand,
return: WaitForLaunch, log id: 2ab47984
2015-12-14 11:55:38,276 INFO [org.ovirt.engine.core.bll.RunVmCommand]
(org.ovirt.thread.pool-8-thread-50) [7bde72f7] Lock freed to object EngineLock
[exclusiveLocks= key: 4838abf2-bf06-4a58-a648-bdb9bee93bf1 value: VM
, sharedLocks= ]
2015-12-14 11:55:38,284 INFO
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(org.ovirt.thread.pool-8-thread-50) [7bde72f7] Correlation ID: 7bde72f7, Job
ID: 3217926f-3acd-485c-a4ac-2cd896575c73, Call Stack: null, Custom Event ID:
-1, Message: VM testvm was started by [email protected] (Host: host02).
2015-12-14 11:55:38,786 INFO
[org.ovirt.engine.core.vdsbroker.gluster.GlusterServersListVDSCommand]
(DefaultQuartzScheduler_Worker-21) [6e6c852] START,
GlusterServersListVDSCommand(HostName = st02, HostId =
99573e36-5b61-4d30-bd6a-f93cc0efec5f), log id: 373e1770
2015-12-14 11:55:38,840 INFO
[org.ovirt.engine.core.vdsbroker.gluster.GlusterServersListVDSCommand]
(DefaultQuartzScheduler_Worker-21) [6e6c852] FINISH,
GlusterServersListVDSCommand, return: [172.29.0.2:CONNECTED,
st01.nieuwland.nl:CONNECTED], log id: 373e1770
2015-12-14 11:55:38,842 INFO
[org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand]
(DefaultQuartzScheduler_Worker-21) [6e6c852] START,
GlusterVolumesListVDSCommand(HostName = st02, HostId =
99573e36-5b61-4d30-bd6a-f93cc0efec5f), log id: ad9f9fc
2015-12-14 11:55:38,883 INFO
[org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand]
(DefaultQuartzScheduler_Worker-21) [6e6c852] FINISH,
GlusterVolumesListVDSCommand, return:
{8fe3aab4-970c-4900-92d7-9a46f4b7c7a2=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@5e8a322f,
a7eaf706-c9ac-46b1-8be5-d4d948cd07c3=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@58886438},
log id: ad9f9fc
2015-12-14 11:55:40,912 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand]
(DefaultQuartzScheduler_Worker-69) START, DestroyVDSCommand(HostName = host02,
HostId = fe25f719-42ed-4632-9985-1188c96d39a3,
vmId=4838abf2-bf06-4a58-a648-bdb9bee93bf1, force=false, secondsToWait=0,
gracefully=false, reason=), log id: 7ec84ae7
2015-12-14 11:55:40,926 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand]
(DefaultQuartzScheduler_Worker-69) FINISH, DestroyVDSCommand, log id: 7ec84ae7
2015-12-14 11:55:40,943 ERROR
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(DefaultQuartzScheduler_Worker-69) Correlation ID: null, Call Stack: null,
Custom Event ID: -1, Message: VM testvm is down with error. Exit message: 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'}.
2015-12-14 11:55:40,944 INFO
[org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo]
(DefaultQuartzScheduler_Worker-69) Running on vds during rerun failed vm: null
2015-12-14 11:55:40,945 INFO
[org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo]
(DefaultQuartzScheduler_Worker-69) VM testvm
(4838abf2-bf06-4a58-a648-bdb9bee93bf1) is running in db and not running in VDS
host02
2015-12-14 11:55:41,002 ERROR
[org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo]
(DefaultQuartzScheduler_Worker-69) Rerun vm
4838abf2-bf06-4a58-a648-bdb9bee93bf1. Called from vds host02
2015-12-14 11:55:41,051 WARN
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(org.ovirt.thread.pool-8-thread-20) Correlation ID: 7bde72f7, Job ID:
3217926f-3acd-485c-a4ac-2cd896575c73, Call Stack: null, Custom Event ID: -1,
Message: Failed to run VM testvm on Host host02.
2015-12-14 11:55:41,069 INFO [org.ovirt.engine.core.bll.RunVmCommand]
(org.ovirt.thread.pool-8-thread-20) Lock Acquired to object EngineLock
[exclusiveLocks= key: 4838abf2-bf06-4a58-a648-bdb9bee93bf1 value: VM
, sharedLocks= ]
2015-12-14 11:55:41,083 INFO
[org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand]
(org.ovirt.thread.pool-8-thread-20) START, IsVmDuringInitiatingVDSCommand( vmId
= 4838abf2-bf06-4a58-a648-bdb9bee93bf1), log id: 6cb8c954
2015-12-14 11:55:41,083 INFO
[org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand]
(org.ovirt.thread.pool-8-thread-20) FINISH, IsVmDuringInitiatingVDSCommand,
return: false, log id: 6cb8c954
2015-12-14 11:55:41,118 INFO [org.ovirt.engine.core.bll.RunVmCommand]
(org.ovirt.thread.pool-8-thread-20) Running command: RunVmCommand internal:
false. Entities affected : ID: 4838abf2-bf06-4a58-a648-bdb9bee93bf1 Type:
VMAction group VM_BASIC_OPERATIONS with role type USER
2015-12-14 11:55:41,145 INFO
[org.ovirt.engine.core.vdsbroker.UpdateVmDynamicDataVDSCommand]
(org.ovirt.thread.pool-8-thread-20) START,
UpdateVmDynamicDataVDSCommand(HostName = host01, HostId =
1e2fd070-6c19-4ff2-9c53-166182408125,
vmDynamic=org.ovirt.engine.core.common.businessentities.VmDynamic@6e2c7808),
log id: 4b3f4d2a
2015-12-14 11:55:41,151 INFO
[org.ovirt.engine.core.vdsbroker.UpdateVmDynamicDataVDSCommand]
(org.ovirt.thread.pool-8-thread-20) FINISH, UpdateVmDynamicDataVDSCommand, log
id: 4b3f4d2a
2015-12-14 11:55:41,155 INFO
[org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand]
(org.ovirt.thread.pool-8-thread-20) START, CreateVmVDSCommand(HostName =
host01, HostId = 1e2fd070-6c19-4ff2-9c53-166182408125,
vmId=4838abf2-bf06-4a58-a648-bdb9bee93bf1, vm=VM [testvm]), log id: 68a032ea
2015-12-14 11:55:41,159 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand]
(org.ovirt.thread.pool-8-thread-20) START, CreateVDSCommand(HostName = host01,
HostId = 1e2fd070-6c19-4ff2-9c53-166182408125,
vmId=4838abf2-bf06-4a58-a648-bdb9bee93bf1, vm=VM [testvm]), log id: 3eadf87d
2015-12-14 11:55:41,171 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand]
(org.ovirt.thread.pool-8-thread-20)
org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand
kvmEnable=true,keyboardLayout=en-us,nice=0,displayNetwork=ovirtmgmt,copyPasteEnable=true,timeOffset=0,transparentHugePages=true,vmId=4838abf2-bf06-4a58-a648-bdb9bee93bf1,acpiEnable=true,custom={},spiceSslCipherSuite=DEFAULT,memSize=1024,smp=1,emulatedMachine=rhel6.5.0,vmType=kvm,memGuaranteedSize=1024,display=qxl,smartcardEnable=false,bootMenuEnable=false,spiceSecureChannels=smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard,smpCoresPerSocket=1,maxVCpus=16,devices=[{address={bus=0x00,
domain=0x0000, type=pci, slot=0x02, function=0x0}, specParams={vram=32768,
heads=1}, device=qxl, type=video,
deviceId=910e0167-f86e-484d-a780-80b63ce05705}, {shared=false, iface=ide,
index=2, specParams={path=}, path=, device=cdrom, type=disk, readonly=true,
deviceId=8082b51e-33fb-44fb-aa90-2e06f6a7fdb5}, {shared=false, index=0,
volumeID=9e189687-6118-4b28-ac36-e97063655af2, propagateErrors=off, format=raw,
type=disk, iface=virtio, bootOrder=1,
domainID=f7453ce7-3aca-4ee3-98c3-827ce3e001d6,
imageID=8cc2e445-649b-48c3-a182-970e80b49458, specParams={}, optional=false,
device=disk, poolID=00000002-0002-0002-0002-000000000247, readonly=false,
deviceId=8cc2e445-649b-48c3-a182-970e80b49458}, {address={bus=0x00,
domain=0x0000, type=pci, slot=0x05, function=0x0}, specParams={model=virtio},
device=memballoon, type=balloon,
deviceId=97758edf-a87f-4996-ae98-ac71b9c798f0}, {index=0, model=virtio-scsi,
address={bus=0x00, domain=0x0000, type=pci, slot=0x03, function=0x0},
specParams={}, device=scsi, type=controller,
deviceId=2a707f91-a310-49c2-98aa-08f97851dd49}, {address={bus=0x00,
domain=0x0000, type=pci, slot=0x04, function=0x0}, specParams={},
device=virtio-serial, type=controller,
deviceId=6721e2f4-5284-49e2-8732-a0757e19f8f9}],vmName=testvm,cpuType=Conroe,fileTransferEnable=true
2015-12-14 11:55:41,200 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand]
(org.ovirt.thread.pool-8-thread-20) FINISH, CreateVDSCommand, log id: 3eadf87d
2015-12-14 11:55:41,218 INFO
[org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand]
(org.ovirt.thread.pool-8-thread-20) FINISH, CreateVmVDSCommand, return:
WaitForLaunch, log id: 68a032ea
2015-12-14 11:55:41,218 INFO [org.ovirt.engine.core.bll.RunVmCommand]
(org.ovirt.thread.pool-8-thread-20) Lock freed to object EngineLock
[exclusiveLocks= key: 4838abf2-bf06-4a58-a648-bdb9bee93bf1 value: VM
, sharedLocks= ]
2015-12-14 11:55:41,226 INFO
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(org.ovirt.thread.pool-8-thread-20) Correlation ID: 7bde72f7, Job ID:
3217926f-3acd-485c-a4ac-2cd896575c73, Call Stack: null, Custom Event ID: -1,
Message: VM testvm was started by [email protected] (Host: host01).
2015-12-14 11:55:41,634 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand]
(DefaultQuartzScheduler_Worker-54) [692ccc0e] START, DestroyVDSCommand(HostName
= host01, HostId = 1e2fd070-6c19-4ff2-9c53-166182408125,
vmId=4838abf2-bf06-4a58-a648-bdb9bee93bf1, force=false, secondsToWait=0,
gracefully=false, reason=), log id: 3393a722
2015-12-14 11:55:41,646 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand]
(DefaultQuartzScheduler_Worker-54) [692ccc0e] FINISH, DestroyVDSCommand, log
id: 3393a722
2015-12-14 11:55:41,660 ERROR
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(DefaultQuartzScheduler_Worker-54) [692ccc0e] Correlation ID: null, Call Stack:
null, Custom Event ID: -1, Message: VM testvm is down with error. Exit message:
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'}.
2015-12-14 11:55:41,661 INFO
[org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo]
(DefaultQuartzScheduler_Worker-54) [692ccc0e] Running on vds during rerun
failed vm: null
2015-12-14 11:55:41,662 INFO
[org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo]
(DefaultQuartzScheduler_Worker-54) [692ccc0e] VM testvm
(4838abf2-bf06-4a58-a648-bdb9bee93bf1) is running in db and not running in VDS
host01
2015-12-14 11:55:41,678 ERROR
[org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo]
(DefaultQuartzScheduler_Worker-54) [692ccc0e] Rerun vm
4838abf2-bf06-4a58-a648-bdb9bee93bf1. Called from vds host01
2015-12-14 11:55:41,693 WARN
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(org.ovirt.thread.pool-8-thread-28) [692ccc0e] Correlation ID: 7bde72f7, Job
ID: 3217926f-3acd-485c-a4ac-2cd896575c73, Call Stack: null, Custom Event ID:
-1, Message: Failed to run VM testvm on Host host01.
2015-12-14 11:55:41,711 INFO [org.ovirt.engine.core.bll.RunVmCommand]
(org.ovirt.thread.pool-8-thread-28) [692ccc0e] Lock Acquired to object
EngineLock [exclusiveLocks= key: 4838abf2-bf06-4a58-a648-bdb9bee93bf1 value: VM
, sharedLocks= ]
2015-12-14 11:55:41,723 INFO
[org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand]
(org.ovirt.thread.pool-8-thread-28) [692ccc0e] START,
IsVmDuringInitiatingVDSCommand( vmId = 4838abf2-bf06-4a58-a648-bdb9bee93bf1),
log id: 6d44d7c8
2015-12-14 11:55:41,724 INFO
[org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand]
(org.ovirt.thread.pool-8-thread-28) [692ccc0e] FINISH,
IsVmDuringInitiatingVDSCommand, return: false, log id: 6d44d7c8
2015-12-14 11:55:41,728 WARN [org.ovirt.engine.core.bll.RunVmCommand]
(org.ovirt.thread.pool-8-thread-28) [692ccc0e] CanDoAction of action RunVm
failed for user [email protected]. Reasons:
VAR__ACTION__RUN,VAR__TYPE__VM,VAR__ACTION__RUN,VAR__TYPE__VM,VAR__ACTION__RUN,VAR__TYPE__VM,VAR__ACTION__RUN,VAR__TYPE__VM,SCHEDULING_NO_HOSTS
2015-12-14 11:55:41,728 INFO [org.ovirt.engine.core.bll.RunVmCommand]
(org.ovirt.thread.pool-8-thread-28) [692ccc0e] Lock freed to object EngineLock
[exclusiveLocks= key: 4838abf2-bf06-4a58-a648-bdb9bee93bf1 value: VM
, sharedLocks= ]
2015-12-14 11:55:41,751 ERROR
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(org.ovirt.thread.pool-8-thread-28) [692ccc0e] Correlation ID: 7bde72f7, Job
ID: 3217926f-3acd-485c-a4ac-2cd896575c73, Call Stack: null, Custom Event ID:
-1, Message: Failed to run VM testvm (User: [email protected]).
2015-12-14 11:55:41,755 INFO [org.ovirt.engine.core.bll.ProcessDownVmCommand]
(org.ovirt.thread.pool-8-thread-32) [563c7809] Running command:
ProcessDownVmCommand internal: true.
2015-12-14 11:55:43,898 INFO
[org.ovirt.engine.core.vdsbroker.gluster.GlusterServersListVDSCommand]
(DefaultQuartzScheduler_Worker-1) [693e9073] START,
GlusterServersListVDSCommand(HostName = st02, HostId =
99573e36-5b61-4d30-bd6a-f93cc0efec5f), log id: 6720b1c3
2015-12-14 11:55:43,952 INFO
[org.ovirt.engine.core.vdsbroker.gluster.GlusterServersListVDSCommand]
(DefaultQuartzScheduler_Worker-1) [693e9073] FINISH,
GlusterServersListVDSCommand, return: [172.29.0.2:CONNECTED,
st01.nieuwland.nl:CONNECTED], log id: 6720b1c3
2015-12-14 11:55:43,954 INFO
[org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand]
(DefaultQuartzScheduler_Worker-1) [693e9073] START,
GlusterVolumesListVDSCommand(HostName = st02, HostId =
99573e36-5b61-4d30-bd6a-f93cc0efec5f), log id: 6ded0e45
2015-12-14 11:55:43,995 INFO
[org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand]
(DefaultQuartzScheduler_Worker-1) [693e9073] FINISH,
GlusterVolumesListVDSCommand, return:
{8fe3aab4-970c-4900-92d7-9a46f4b7c7a2=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@bc7b5c31,
a7eaf706-c9ac-46b1-8be5-d4d948cd07c3=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@ce6dfd19},
log id: 6ded0e45
2015-12-14 11:55:49,010 INFO
[org.ovirt.engine.core.vdsbroker.gluster.GlusterServersListVDSCommand]
(DefaultQuartzScheduler_Worker-82) START, GlusterServersListVDSCommand(HostName
= st02, HostId = 99573e36-5b61-4d30-bd6a-f93cc0efec5f), log id: 596513fa
2015-12-14 11:55:49,065 INFO
[org.ovirt.engine.core.vdsbroker.gluster.GlusterServersListVDSCommand]
(DefaultQuartzScheduler_Worker-82) FINISH, GlusterServersListVDSCommand,
return: [172.29.0.2:CONNECTED, st01.nieuwland.nl:CONNECTED], log id: 596513fa
2015-12-14 11:55:49,068 INFO
[org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand]
(DefaultQuartzScheduler_Worker-82) START, GlusterVolumesListVDSCommand(HostName
= st02, HostId = 99573e36-5b61-4d30-bd6a-f93cc0efec5f), log id: 4d6d6f47
2015-12-14 11:55:49,108 INFO
[org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand]
(DefaultQuartzScheduler_Worker-82) FINISH, GlusterVolumesListVDSCommand,
return:
{8fe3aab4-970c-4900-92d7-9a46f4b7c7a2=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@d91291a9,
a7eaf706-c9ac-46b1-8be5-d4d948cd07c3=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@964c0762},
log id: 4d6d6f47
_______________________________________________
Users mailing list
[email protected]
http://lists.ovirt.org/mailman/listinfo/users
