[Users] Migration failed (previous migrations succeded)
Markus Stockhausen
stockhausen at collogia.de
Thu Jan 30 17:05:04 UTC 2014
Hello,
we did some migration tests this day and all of a sudden the migration
failed. That particular VM was moved around several times that day without
any problems. During the migration the VM was running a download.
The logs are attached. If you need more, do not hesitate to ask.
Thanks in advance.
Markus
**************************
web log:
2014-Jan-30, 16:17 Migration failed due to Error: Migration not in progress (VM: Win7x64_Master, Source: colovn02, Destination: colovn04).
2014-Jan-30, 16:11 Migration started (VM: Win7x64_Master, Source: colovn02, Destination: colovn04, User: hil1).
2014-Jan-30, 16:10 Migration completed (VM: Win7x64_Master, Source: colovn04, Destination: colovn02, Duration: 52 sec).
2014-Jan-30, 16:05 Migration started (VM: Win7x64_Master, Source: colovn04, Destination: colovn02, User: hil1).
2014-Jan-30, 16:04 Migration completed (VM: Win7x64_Master, Source: colovn03, Destination: colovn04, Duration: 24 sec).
2014-Jan-30, 16:01 Migration started (VM: Win7x64_Master, Source: colovn03, Destination: colovn04, User: hil1).
**************************
Engine
2014-01-30 16:17:31,871 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-97) RefreshVmList vm id ce64f528-9981-4ec6-a172-9d70a00a34cd status = Paused on vds colovn04 ignoring it in the refresh until migration is done
2014-01-30 16:17:34,955 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-96) RefreshVmList vm id ce64f528-9981-4ec6-a172-9d70a00a34cd status = Paused on vds colovn04 ignoring it in the refresh until migration is done
2014-01-30 16:17:38,067 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-2) RefreshVmList vm id ce64f528-9981-4ec6-a172-9d70a00a34cd status = Paused on vds colovn04 ignoring it in the refresh until migration is done
2014-01-30 16:17:41,147 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-100) RefreshVmList vm id ce64f528-9981-4ec6-a172-9d70a00a34cd status = Paused on vds colovn04 ignoring it in the refresh until migration is done
2014-01-30 16:17:44,268 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-88) RefreshVmList vm id ce64f528-9981-4ec6-a172-9d70a00a34cd status = Paused on vds colovn04 ignoring it in the refresh until migration is done
2014-01-30 16:17:46,440 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-13) VM Win7x64_Master ce64f528-9981-4ec6-a172-9d70a00a34cd moved from MigratingFrom --> Up
2014-01-30 16:17:46,444 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-13) Adding VM ce64f528-9981-4ec6-a172-9d70a00a34cd to re-run list
2014-01-30 16:17:46,456 ERROR [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-13) Rerun vm ce64f528-9981-4ec6-a172-9d70a00a34cd. Called from vds colovn02
2014-01-30 16:17:46,475 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateStatusVDSCommand] (pool-6-thread-48) START, MigrateStatusVDSCommand(HostName = colovn02, HostId = 1303e86e-cd91-406b-8a27-e75ef0a9defb, vmId=ce64f528-9981-4ec6-a172-9d70a00a34cd), log id: 91bccfb
2014-01-30 16:17:46,485 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateStatusVDSCommand] (pool-6-thread-48) Failed in MigrateStatusVDS method
2014-01-30 16:17:46,488 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateStatusVDSCommand] (pool-6-thread-48) Error code MIGRATION_CANCEL_ERROR and error message VDSGenericException: VDSErrorException: Failed to MigrateStatusVDS, error = Migration canceled
2014-01-30 16:17:46,492 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateStatusVDSCommand] (pool-6-thread-48) Command org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateStatusVDSCommand return value
StatusOnlyReturnForXmlRpc [mStatus=StatusForXmlRpc [mCode=47, mMessage=Migration canceled]]
2014-01-30 16:17:46,495 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateStatusVDSCommand] (pool-6-thread-48) HostName = colovn02
2014-01-30 16:17:46,508 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateStatusVDSCommand] (pool-6-thread-48) Command MigrateStatusVDS execution failed. Exception: VDSErrorException: VDSGenericException: VDSErrorException: Failed to MigrateStatusVDS, error = Migration canceled
2014-01-30 16:17:46,511 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateStatusVDSCommand] (pool-6-thread-48) FINISH, MigrateStatusVDSCommand, log id: 91bccfb
2014-01-30 16:17:46,522 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (pool-6-thread-48) Correlation ID: 71aa9786, Job ID: 4f805590-135a-49a6-871a-91389ae99d9a, Call Stack: null, Custom Event ID: -1, Message: Migration failed due to Error: Migration not in progress (VM: Win7x64_Master, Source: colovn02, Destination: colovn04).
2014-01-30 16:18:27,016 INFO [org.ovirt.engine.core.bll.MigrateVmToServerCommand] (ajp--127.0.0.1-8702-2) [5fed7321] Failed to Acquire Lock to object EngineLock [exclusiveLocks= key: ce64f528-9981-4ec6-a172-9d70a00a34cd value: VM
, sharedLocks= ]
2014-01-30 16:18:27,020 WARN [org.ovirt.engine.core.bll.MigrateVmToServerCommand] (ajp--127.0.0.1-8702-2) [5fed7321] CanDoAction of action MigrateVmToServer failed. Reasons:VAR__ACTION__MIGRATE,VAR__TYPE__VM,ACTION_TYPE_FAILED_VM_IS_BEING_MIGRATED,$VmName Win7x64_Master
2014-01-30 16:18:56,318 INFO [org.ovirt.engine.core.bll.MigrateVmToServerCommand] (ajp--127.0.0.1-8702-12) [4b6f62e9] Failed to Acquire Lock to object EngineLock [exclusiveLocks= key: ce64f528-9981-4ec6-a172-9d70a00a34cd value: VM
**************************
vdsm_source:
Thread-290096::DEBUG::2014-01-30 16:17:04,874::task::1168::TaskManager.Task::(prepare) Task=`d313ee92-9094-49ad-8850-fbb6df383a22`::finished: {'2c51d320-88ce-4f23-8215-e15f55f66906': {'delay': '0.000176962', 'lastCheck': '1.8', 'code': 0, 'valid': True, 'version': 3}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'delay': '0.000154703', 'lastCheck': '8.0', 'code': 0, 'valid': True, 'version': 3}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'delay': '0.000147093', 'lastCheck': '7.5', 'code': 0, 'valid': True, 'version': 0}, '63041fa9-e093-4b44-b36f-f39f16d3974f': {'delay': '0.000179083', 'lastCheck': '7.1', 'code': 0, 'valid': True, 'version': 0}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'delay': '0.000224103', 'lastCheck': '6.3', 'code': 0, 'valid': True, 'version': 3}}
Thread-290096::DEBUG::2014-01-30 16:17:04,874::task::579::TaskManager.Task::(_updateState) Task=`d313ee92-9094-49ad-8850-fbb6df383a22`::moving from state preparing -> state finished
Thread-290096::DEBUG::2014-01-30 16:17:04,874::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-290096::DEBUG::2014-01-30 16:17:04,874::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-290096::DEBUG::2014-01-30 16:17:04,874::task::974::TaskManager.Task::(_decref) Task=`d313ee92-9094-49ad-8850-fbb6df383a22`::ref 0 aborting False
Thread-289929::WARNING::2014-01-30 16:17:05,585::vm::800::vm.Vm::(run) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Migration stalling: dataRemaining (24MiB) > smallest_dataRemaining (9MiB). Refer to RHBZ#919201.
Thread-289929::INFO::2014-01-30 16:17:05,585::vm::812::vm.Vm::(run) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Migration Progress: 360 seconds elapsed, 99% of data processed, 99% of mem processed
Thread-26::DEBUG::2014-01-30 16:17:06,907::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-26::DEBUG::2014-01-30 16:17:06,913::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000192548 s, 2.9 MB/s\n'; <rc> = 0
Thread-27::DEBUG::2014-01-30 16:17:07,394::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-27::DEBUG::2014-01-30 16:17:07,400::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n357 bytes (357 B) copied, 0.000213713 s, 1.7 MB/s\n'; <rc> = 0
Thread-33::DEBUG::2014-01-30 16:17:07,771::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-33::DEBUG::2014-01-30 16:17:07,778::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n363 bytes (363 B) copied, 0.000190935 s, 1.9 MB/s\n'; <rc> = 0
Thread-38::DEBUG::2014-01-30 16:17:08,586::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-38::DEBUG::2014-01-30 16:17:08,593::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000184154 s, 3.0 MB/s\n'; <rc> = 0
Thread-25::DEBUG::2014-01-30 16:17:13,044::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-25::DEBUG::2014-01-30 16:17:13,050::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n645 bytes (645 B) copied, 0.00017907 s, 3.6 MB/s\n'; <rc> = 0
Thread-289929::WARNING::2014-01-30 16:17:15,586::vm::800::vm.Vm::(run) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Migration stalling: dataRemaining (16MiB) > smallest_dataRemaining (9MiB). Refer to RHBZ#919201.
Thread-289929::INFO::2014-01-30 16:17:15,587::vm::812::vm.Vm::(run) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Migration Progress: 370 seconds elapsed, 99% of data processed, 99% of mem processed
Thread-26::DEBUG::2014-01-30 16:17:16,923::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-26::DEBUG::2014-01-30 16:17:16,929::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000248981 s, 2.2 MB/s\n'; <rc> = 0
Thread-27::DEBUG::2014-01-30 16:17:17,412::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-27::DEBUG::2014-01-30 16:17:17,418::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n357 bytes (357 B) copied, 0.000252188 s, 1.4 MB/s\n'; <rc> = 0
Thread-33::DEBUG::2014-01-30 16:17:17,789::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-33::DEBUG::2014-01-30 16:17:17,796::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n363 bytes (363 B) copied, 0.000203099 s, 1.8 MB/s\n'; <rc> = 0
Thread-38::DEBUG::2014-01-30 16:17:18,604::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-38::DEBUG::2014-01-30 16:17:18,611::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000177334 s, 3.1 MB/s\n'; <rc> = 0
Thread-290102::DEBUG::2014-01-30 16:17:20,057::task::579::TaskManager.Task::(_updateState) Task=`0d381417-48c8-4035-99e5-01f34f55f98c`::moving from state init -> state preparing
Thread-290102::INFO::2014-01-30 16:17:20,057::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-290102::INFO::2014-01-30 16:17:20,058::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'2c51d320-88ce-4f23-8215-e15f55f66906': {'delay': '0.00017907', 'lastCheck': '7.0', 'code': 0, 'valid': True, 'version': 3}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'delay': '0.000248981', 'lastCheck': '3.1', 'code': 0, 'valid': True, 'version': 3}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'delay': '0.000252188', 'lastCheck': '2.6', 'code': 0, 'valid': True, 'version': 0}, '63041fa9-e093-4b44-b36f-f39f16d3974f': {'delay': '0.000203099', 'lastCheck': '2.3', 'code': 0, 'valid': True, 'version': 0}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'delay': '0.000177334', 'lastCheck': '1.4', 'code': 0, 'valid': True, 'version': 3}}
Thread-290102::DEBUG::2014-01-30 16:17:20,058::task::1168::TaskManager.Task::(prepare) Task=`0d381417-48c8-4035-99e5-01f34f55f98c`::finished: {'2c51d320-88ce-4f23-8215-e15f55f66906': {'delay': '0.00017907', 'lastCheck': '7.0', 'code': 0, 'valid': True, 'version': 3}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'delay': '0.000248981', 'lastCheck': '3.1', 'code': 0, 'valid': True, 'version': 3}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'delay': '0.000252188', 'lastCheck': '2.6', 'code': 0, 'valid': True, 'version': 0}, '63041fa9-e093-4b44-b36f-f39f16d3974f': {'delay': '0.000203099', 'lastCheck': '2.3', 'code': 0, 'valid': True, 'version': 0}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'delay': '0.000177334', 'lastCheck': '1.4', 'code': 0, 'valid': True, 'version': 3}}
Thread-290102::DEBUG::2014-01-30 16:17:20,058::task::579::TaskManager.Task::(_updateState) Task=`0d381417-48c8-4035-99e5-01f34f55f98c`::moving from state preparing -> state finished
Thread-290102::DEBUG::2014-01-30 16:17:20,058::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-290102::DEBUG::2014-01-30 16:17:20,058::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-290102::DEBUG::2014-01-30 16:17:20,059::task::974::TaskManager.Task::(_decref) Task=`0d381417-48c8-4035-99e5-01f34f55f98c`::ref 0 aborting False
Thread-289906::DEBUG::2014-01-30 16:17:22,908::task::579::TaskManager.Task::(_updateState) Task=`308ddd49-b5c0-43a5-93fc-ccfd6220eb28`::moving from state init -> state preparing
Thread-289906::INFO::2014-01-30 16:17:22,909::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545', spUUID='94ed7a19-fade-4bd6-83f2-2cbb2f730b95', imgUUID='1b23ac73-0748-49cd-94b6-11555e35be81', volUUID='5156a43b-c9dc-40fa-a9b7-a35b7f22f0eb', options=None)
Thread-289906::INFO::2014-01-30 16:17:22,911::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '17700114432', 'apparentsize': '21474836480'}
Thread-289906::DEBUG::2014-01-30 16:17:22,911::task::1168::TaskManager.Task::(prepare) Task=`308ddd49-b5c0-43a5-93fc-ccfd6220eb28`::finished: {'truesize': '17700114432', 'apparentsize': '21474836480'}
Thread-289906::DEBUG::2014-01-30 16:17:22,911::task::579::TaskManager.Task::(_updateState) Task=`308ddd49-b5c0-43a5-93fc-ccfd6220eb28`::moving from state preparing -> state finished
Thread-289906::DEBUG::2014-01-30 16:17:22,911::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-289906::DEBUG::2014-01-30 16:17:22,912::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-289906::DEBUG::2014-01-30 16:17:22,912::task::974::TaskManager.Task::(_decref) Task=`308ddd49-b5c0-43a5-93fc-ccfd6220eb28`::ref 0 aborting False
Thread-25::DEBUG::2014-01-30 16:17:23,063::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-25::DEBUG::2014-01-30 16:17:23,069::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n645 bytes (645 B) copied, 0.000189592 s, 3.4 MB/s\n'; <rc> = 0
VM Channels Listener::DEBUG::2014-01-30 16:17:23,109::vmChannels::91::vds::(_handle_timeouts) Timeout on fileno 105.
Thread-289929::WARNING::2014-01-30 16:17:25,588::vm::800::vm.Vm::(run) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Migration stalling: dataRemaining (15MiB) > smallest_dataRemaining (9MiB). Refer to RHBZ#919201.
Thread-289929::INFO::2014-01-30 16:17:25,588::vm::812::vm.Vm::(run) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Migration Progress: 380 seconds elapsed, 99% of data processed, 99% of mem processed
Thread-26::DEBUG::2014-01-30 16:17:26,940::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-26::DEBUG::2014-01-30 16:17:26,947::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.00019559 s, 2.8 MB/s\n'; <rc> = 0
Thread-27::DEBUG::2014-01-30 16:17:27,430::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-27::DEBUG::2014-01-30 16:17:27,439::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n357 bytes (357 B) copied, 0.00317489 s, 112 kB/s\n'; <rc> = 0
Thread-33::DEBUG::2014-01-30 16:17:27,808::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-33::DEBUG::2014-01-30 16:17:27,815::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n363 bytes (363 B) copied, 0.000189549 s, 1.9 MB/s\n'; <rc> = 0
Thread-38::DEBUG::2014-01-30 16:17:28,621::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-38::DEBUG::2014-01-30 16:17:28,632::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.00469703 s, 119 kB/s\n'; <rc> = 0
Thread-25::DEBUG::2014-01-30 16:17:33,081::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-25::DEBUG::2014-01-30 16:17:33,087::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n645 bytes (645 B) copied, 0.000191272 s, 3.4 MB/s\n'; <rc> = 0
Thread-290108::DEBUG::2014-01-30 16:17:35,257::task::579::TaskManager.Task::(_updateState) Task=`c598fcf4-774b-4420-af70-090d43cd58b5`::moving from state init -> state preparing
Thread-290108::INFO::2014-01-30 16:17:35,257::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-290108::INFO::2014-01-30 16:17:35,257::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'2c51d320-88ce-4f23-8215-e15f55f66906': {'delay': '0.000191272', 'lastCheck': '2.2', 'code': 0, 'valid': True, 'version': 3}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'delay': '0.00019559', 'lastCheck': '8.3', 'code': 0, 'valid': True, 'version': 3}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'delay': '0.00317489', 'lastCheck': '7.8', 'code': 0, 'valid': True, 'version': 0}, '63041fa9-e093-4b44-b36f-f39f16d3974f': {'delay': '0.000189549', 'lastCheck': '7.4', 'code': 0, 'valid': True, 'version': 0}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'delay': '0.00469703', 'lastCheck': '6.6', 'code': 0, 'valid': True, 'version': 3}}
Thread-290108::DEBUG::2014-01-30 16:17:35,258::task::1168::TaskManager.Task::(prepare) Task=`c598fcf4-774b-4420-af70-090d43cd58b5`::finished: {'2c51d320-88ce-4f23-8215-e15f55f66906': {'delay': '0.000191272', 'lastCheck': '2.2', 'code': 0, 'valid': True, 'version': 3}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'delay': '0.00019559', 'lastCheck': '8.3', 'code': 0, 'valid': True, 'version': 3}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'delay': '0.00317489', 'lastCheck': '7.8', 'code': 0, 'valid': True, 'version': 0}, '63041fa9-e093-4b44-b36f-f39f16d3974f': {'delay': '0.000189549', 'lastCheck': '7.4', 'code': 0, 'valid': True, 'version': 0}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'delay': '0.00469703', 'lastCheck': '6.6', 'code': 0, 'valid': True, 'version': 3}}
Thread-290108::DEBUG::2014-01-30 16:17:35,258::task::579::TaskManager.Task::(_updateState) Task=`c598fcf4-774b-4420-af70-090d43cd58b5`::moving from state preparing -> state finished
Thread-290108::DEBUG::2014-01-30 16:17:35,258::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-290108::DEBUG::2014-01-30 16:17:35,258::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-290108::DEBUG::2014-01-30 16:17:35,258::task::974::TaskManager.Task::(_decref) Task=`c598fcf4-774b-4420-af70-090d43cd58b5`::ref 0 aborting False
Thread-289929::WARNING::2014-01-30 16:17:35,590::vm::800::vm.Vm::(run) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Migration stalling: dataRemaining (33MiB) > smallest_dataRemaining (9MiB). Refer to RHBZ#919201.
Thread-289929::INFO::2014-01-30 16:17:35,590::vm::812::vm.Vm::(run) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Migration Progress: 390 seconds elapsed, 99% of data processed, 99% of mem processed
Thread-26::DEBUG::2014-01-30 16:17:36,959::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-26::DEBUG::2014-01-30 16:17:36,966::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000212972 s, 2.6 MB/s\n'; <rc> = 0
Thread-27::DEBUG::2014-01-30 16:17:37,450::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-27::DEBUG::2014-01-30 16:17:37,457::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n357 bytes (357 B) copied, 0.000199826 s, 1.8 MB/s\n'; <rc> = 0
Thread-33::DEBUG::2014-01-30 16:17:37,826::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-33::DEBUG::2014-01-30 16:17:37,833::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n363 bytes (363 B) copied, 0.000200537 s, 1.8 MB/s\n'; <rc> = 0
Thread-38::DEBUG::2014-01-30 16:17:38,644::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-38::DEBUG::2014-01-30 16:17:38,650::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000206259 s, 2.7 MB/s\n'; <rc> = 0
Thread-25::DEBUG::2014-01-30 16:17:43,099::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-25::DEBUG::2014-01-30 16:17:43,105::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n645 bytes (645 B) copied, 0.000187228 s, 3.4 MB/s\n'; <rc> = 0
Thread-289929::WARNING::2014-01-30 16:17:45,592::vm::789::vm.Vm::(run) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Migration is stuck: Hasn't progressed in 300.055635929 seconds. Aborting.
Thread-289929::DEBUG::2014-01-30 16:17:45,594::vm::815::vm.Vm::(stop) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::stopping migration monitor thread
libvirtEventLoop::DEBUG::2014-01-30 16:17:45,918::vm::4840::vm.Vm::(_onLibvirtLifecycleEvent) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::event Resumed detail 1 opaque None
Thread-289927::DEBUG::2014-01-30 16:17:45,920::libvirtconnection::108::libvirtconnection::(wrapper) Unknown libvirterror: ecode: 78 edom: 10 level: 2 message: Operation abgebrochen: Migrations-Job: abgebrochen durch Client
Thread-289927::DEBUG::2014-01-30 16:17:45,920::vm::745::vm.Vm::(cancel) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::canceling migration downtime thread
Thread-289927::DEBUG::2014-01-30 16:17:45,920::vm::815::vm.Vm::(stop) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::stopping migration monitor thread
Thread-289927::ERROR::2014-01-30 16:17:45,920::vm::238::vm.Vm::(_recover) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Operation abgebrochen: Migrations-Job: abgebrochen durch Client
Thread-289927::ERROR::2014-01-30 16:17:45,949::vm::337::vm.Vm::(run) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Failed to migrate
Traceback (most recent call last):
File "/usr/share/vdsm/vm.py", line 323, in run
self._startUnderlyingMigration()
File "/usr/share/vdsm/vm.py", line 400, in _startUnderlyingMigration
None, maxBandwidth)
File "/usr/share/vdsm/vm.py", line 838, in f
ret = attr(*args, **kwargs)
File "/usr/lib64/python2.7/site-packages/vdsm/libvirtconnection.py", line 76, in wrapper
ret = f(*args, **kwargs)
File "/usr/lib64/python2.7/site-packages/libvirt.py", line 1274, in migrateToURI2
if ret == -1: raise libvirtError ('virDomainMigrateToURI2() failed', dom=self)
libvirtError: Operation abgebrochen: Migrations-Job: abgebrochen durch Client
Thread-26::DEBUG::2014-01-30 16:17:46,976::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-26::DEBUG::2014-01-30 16:17:46,982::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000163843 s, 3.4 MB/s\n'; <rc> = 0
Thread-290114::DEBUG::2014-01-30 16:17:47,444::BindingXMLRPC::974::vds::(wrapper) client [192.168.11.2]::call vmGetStats with ('ce64f528-9981-4ec6-a172-9d70a00a34cd',) {}
Thread-290114::DEBUG::2014-01-30 16:17:47,445::BindingXMLRPC::981::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Up', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'guestFQDN': '', 'pid': '14467', 'displayIp': '192.168.11.42', 'displayPort': '-1', 'session': 'Unknown', 'displaySecurePort': u'5900', 'timeOffset': '0', 'hash': '3172497814970917300', 'balloonInfo': {'balloon_max': '2097152', 'balloon_target': '2097152', 'balloon_cur': '2097152', 'balloon_min': '2097152'}, 'clientIp': '', 'kvmEnable': 'true', 'network': {u'vnet0': {'macAddr': '00:1a:4a:ee:d3:4a', 'rxDropped': '605', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '1.4', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': 'ce64f528-9981-4ec6-a172-9d70a00a34cd', 'displayType': 'qxl', 'cpuUser': '35.99', 'disks': {u'hdc': {'readLatency': '0', 'apparentsize': '0', 'writeLatency': '0', 'flushLatency': '0', 'readRate': '0.00', 'truesize': '0', 'writeRate': '0.00'}, u'sda': {'readLatency': '0', 'apparentsize': '21474836480', 'writeLatency': '2110228', 'imageID': '1b23ac73-0748-49cd-94b6-11555e35be81', 'flushLatency': '0', 'readRate': '0.00', 'truesize': '17700114432', 'writeRate': '1640924.26'}}, 'monitorResponse': '0', 'statsAge': '0.49', 'elapsedTime': '1235', 'vmType': 'kvm', 'cpuSys': '35.99', 'appsList': [], 'guestIPs': ''}]}
Thread-27::DEBUG::2014-01-30 16:17:47,468::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-27::DEBUG::2014-01-30 16:17:47,474::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n357 bytes (357 B) copied, 0.000176178 s, 2.0 MB/s\n'; <rc> = 0
Thread-290115::DEBUG::2014-01-30 16:17:47,493::BindingXMLRPC::974::vds::(wrapper) client [192.168.11.2]::call vmGetMigrationStatus with ('ce64f528-9981-4ec6-a172-9d70a00a34cd',) {}
Thread-290115::DEBUG::2014-01-30 16:17:47,493::BindingXMLRPC::981::vds::(wrapper) return vmGetMigrationStatus with {'status': {'message': 'Migration canceled', 'code': 47}, 'progress': 99}
Thread-33::DEBUG::2014-01-30 16:17:47,845::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-33::DEBUG::2014-01-30 16:17:47,851::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n363 bytes (363 B) copied, 0.000191543 s, 1.9 MB/s\n'; <rc> = 0
Thread-38::DEBUG::2014-01-30 16:17:48,662::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-38::DEBUG::2014-01-30 16:17:48,668::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000225105 s, 2.5 MB/s\n'; <rc> = 0
Thread-290116::DEBUG::2014-01-30 16:17:50,490::task::579::TaskManager.Task::(_updateState) Task=`cd241aee-e845-4143-bfe3-01383c65e90e`::moving from state init -> state preparing
Thread-290116::INFO::2014-01-30 16:17:50,490::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
**************************
vdsm_target:
Thread-285228::DEBUG::2014-01-30 16:17:07,460::vm::684::vm.Vm::(_getDiskLatency) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk hdc latency not available
Thread-285228::DEBUG::2014-01-30 16:17:07,460::vm::684::vm.Vm::(_getDiskLatency) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk sda latency not available
Thread-285228::DEBUG::2014-01-30 16:17:07,461::BindingXMLRPC::981::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Paused', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'guestFQDN': '', 'pid': '7671', 'displayIp': '192.168.11.44', 'displayPort': '-1', 'session': 'Unknown', 'displaySecurePort': u'5900', 'timeOffset': '0', 'hash': '7219603903902024642', 'balloonInfo': {'balloon_max': '2097152', 'balloon_target': '2097152', 'balloon_cur': '2097152', 'balloon_min': '2097152'}, 'clientIp': '', 'kvmEnable': 'true', 'network': {u'vnet0': {'macAddr': '00:1a:4a:ee:d3:4a', 'rxDropped': '867', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': 'ce64f528-9981-4ec6-a172-9d70a00a34cd', 'displayType': 'qxl', 'cpuUser': '0.38', 'disks': {u'hdc': {'truesize': '0', 'apparentsize': '0'}, u'sda': {'truesize': '17700114432', 'apparentsize': '21474836480', 'imageID': '1b23ac73-0748-49cd-94b6-11555e35be81'}}, 'monitorResponse': '0', 'statsAge': '0.44', 'elapsedTime': '1212', 'vmType': 'kvm', 'cpuSys': '2.07', 'appsList': [], 'guestIPs': ''}]}
Thread-40::DEBUG::2014-01-30 16:17:07,811::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-40::DEBUG::2014-01-30 16:17:07,818::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n645 bytes (645 B) copied, 0.000160605 s, 4.0 MB/s\n'; <rc> = 0
Thread-42::DEBUG::2014-01-30 16:17:08,363::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-42::DEBUG::2014-01-30 16:17:08,369::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n357 bytes (357 B) copied, 0.000144136 s, 2.5 MB/s\n'; <rc> = 0
Thread-47::DEBUG::2014-01-30 16:17:10,080::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-47::DEBUG::2014-01-30 16:17:10,086::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n363 bytes (363 B) copied, 0.000213518 s, 1.7 MB/s\n'; <rc> = 0
Thread-285230::DEBUG::2014-01-30 16:17:10,569::BindingXMLRPC::974::vds::(wrapper) client [192.168.11.2]::call vmGetStats with ('ce64f528-9981-4ec6-a172-9d70a00a34cd',) {}
Thread-285230::DEBUG::2014-01-30 16:17:10,569::vm::645::vm.Vm::(_getDiskStats) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk hdc stats not available
Thread-285230::DEBUG::2014-01-30 16:17:10,569::vm::645::vm.Vm::(_getDiskStats) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk sda stats not available
Thread-285230::DEBUG::2014-01-30 16:17:10,569::vm::684::vm.Vm::(_getDiskLatency) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk hdc latency not available
Thread-285230::DEBUG::2014-01-30 16:17:10,570::vm::684::vm.Vm::(_getDiskLatency) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk sda latency not available
Thread-285230::DEBUG::2014-01-30 16:17:10,571::BindingXMLRPC::981::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Paused', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'guestFQDN': '', 'pid': '7671', 'displayIp': '192.168.11.44', 'displayPort': '-1', 'session': 'Unknown', 'displaySecurePort': u'5900', 'timeOffset': '0', 'hash': '7219603903902024642', 'balloonInfo': {'balloon_max': '2097152', 'balloon_target': '2097152', 'balloon_cur': '2097152', 'balloon_min': '2097152'}, 'clientIp': '', 'kvmEnable': 'true', 'network': {u'vnet0': {'macAddr': '00:1a:4a:ee:d3:4a', 'rxDropped': '887', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': 'ce64f528-9981-4ec6-a172-9d70a00a34cd', 'displayType': 'qxl', 'cpuUser': '0.38', 'disks': {u'hdc': {'truesize': '0', 'apparentsize': '0'}, u'sda': {'truesize': '17700114432', 'apparentsize': '21474836480', 'imageID': '1b23ac73-0748-49cd-94b6-11555e35be81'}}, 'monitorResponse': '0', 'statsAge': '1.55', 'elapsedTime': '1215', 'vmType': 'kvm', 'cpuSys': '2.07', 'appsList': [], 'guestIPs': ''}]}
Thread-41::DEBUG::2014-01-30 16:17:11,570::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-41::DEBUG::2014-01-30 16:17:11,577::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000211434 s, 2.6 MB/s\n'; <rc> = 0
Thread-285232::DEBUG::2014-01-30 16:17:13,656::BindingXMLRPC::974::vds::(wrapper) client [192.168.11.2]::call vmGetStats with ('ce64f528-9981-4ec6-a172-9d70a00a34cd',) {}
Thread-285232::DEBUG::2014-01-30 16:17:13,656::vm::645::vm.Vm::(_getDiskStats) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk hdc stats not available
Thread-285232::DEBUG::2014-01-30 16:17:13,657::vm::645::vm.Vm::(_getDiskStats) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk sda stats not available
Thread-285232::DEBUG::2014-01-30 16:17:13,657::vm::684::vm.Vm::(_getDiskLatency) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk hdc latency not available
Thread-285232::DEBUG::2014-01-30 16:17:13,657::vm::684::vm.Vm::(_getDiskLatency) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk sda latency not available
Thread-285232::DEBUG::2014-01-30 16:17:13,658::BindingXMLRPC::981::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Paused', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'guestFQDN': '', 'pid': '7671', 'displayIp': '192.168.11.44', 'displayPort': '-1', 'session': 'Unknown', 'displaySecurePort': u'5900', 'timeOffset': '0', 'hash': '7219603903902024642', 'balloonInfo': {'balloon_max': '2097152', 'balloon_target': '2097152', 'balloon_cur': '2097152', 'balloon_min': '2097152'}, 'clientIp': '', 'kvmEnable': 'true', 'network': {u'vnet0': {'macAddr': '00:1a:4a:ee:d3:4a', 'rxDropped': '887', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': 'ce64f528-9981-4ec6-a172-9d70a00a34cd', 'displayType': 'qxl', 'cpuUser': '0.38', 'disks': {u'hdc': {'truesize': '0', 'apparentsize': '0'}, u'sda': {'truesize': '17700114432', 'apparentsize': '21474836480', 'imageID': '1b23ac73-0748-49cd-94b6-11555e35be81'}}, 'monitorResponse': '0', 'statsAge': '0.63', 'elapsedTime': '1218', 'vmType': 'kvm', 'cpuSys': '2.07', 'appsList': [], 'guestIPs': ''}]}
Thread-52::DEBUG::2014-01-30 16:17:14,494::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-52::DEBUG::2014-01-30 16:17:14,501::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000228157 s, 2.4 MB/s\n'; <rc> = 0
Thread-285233::DEBUG::2014-01-30 16:17:16,719::task::579::TaskManager.Task::(_updateState) Task=`3b433b6a-d9ed-4edc-adcc-b9994ba7877a`::moving from state init -> state preparing
Thread-285233::INFO::2014-01-30 16:17:16,720::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-285233::INFO::2014-01-30 16:17:16,720::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'2c51d320-88ce-4f23-8215-e15f55f66906': {'delay': '0.000160605', 'lastCheck': '8.9', 'code': 0, 'valid': True, 'version': 3}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'delay': '0.000211434', 'lastCheck': '5.1', 'code': 0, 'valid': True, 'version': 3}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'delay': '0.000144136', 'lastCheck': '8.3', 'code': 0, 'valid': True, 'version': 0}, '63041fa9-e093-4b44-b36f-f39f16d3974f': {'delay': '0.000213518', 'lastCheck': '6.6', 'code': 0, 'valid': True, 'version': 0}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'delay': '0.000228157', 'lastCheck': '2.2', 'code': 0, 'valid': True, 'version': 3}}
Thread-285233::DEBUG::2014-01-30 16:17:16,720::task::1168::TaskManager.Task::(prepare) Task=`3b433b6a-d9ed-4edc-adcc-b9994ba7877a`::finished: {'2c51d320-88ce-4f23-8215-e15f55f66906': {'delay': '0.000160605', 'lastCheck': '8.9', 'code': 0, 'valid': True, 'version': 3}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'delay': '0.000211434', 'lastCheck': '5.1', 'code': 0, 'valid': True, 'version': 3}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'delay': '0.000144136', 'lastCheck': '8.3', 'code': 0, 'valid': True, 'version': 0}, '63041fa9-e093-4b44-b36f-f39f16d3974f': {'delay': '0.000213518', 'lastCheck': '6.6', 'code': 0, 'valid': True, 'version': 0}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'delay': '0.000228157', 'lastCheck': '2.2', 'code': 0, 'valid': True, 'version': 3}}
Thread-285233::DEBUG::2014-01-30 16:17:16,720::task::579::TaskManager.Task::(_updateState) Task=`3b433b6a-d9ed-4edc-adcc-b9994ba7877a`::moving from state preparing -> state finished
Thread-285233::DEBUG::2014-01-30 16:17:16,720::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-285233::DEBUG::2014-01-30 16:17:16,721::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-285233::DEBUG::2014-01-30 16:17:16,721::task::974::TaskManager.Task::(_decref) Task=`3b433b6a-d9ed-4edc-adcc-b9994ba7877a`::ref 0 aborting False
Thread-285234::DEBUG::2014-01-30 16:17:16,733::vm::645::vm.Vm::(_getDiskStats) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk hdc stats not available
Thread-285234::DEBUG::2014-01-30 16:17:16,733::vm::645::vm.Vm::(_getDiskStats) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk sda stats not available
Thread-285234::DEBUG::2014-01-30 16:17:16,733::vm::684::vm.Vm::(_getDiskLatency) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk hdc latency not available
Thread-285234::DEBUG::2014-01-30 16:17:16,733::vm::684::vm.Vm::(_getDiskLatency) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk sda latency not available
Thread-40::DEBUG::2014-01-30 16:17:17,821::domainMonitor::182::Storage.DomainMonitorThread::(_monitorDomain) Refreshing domain 2c51d320-88ce-4f23-8215-e15f55f66906
Thread-40::DEBUG::2014-01-30 16:17:17,834::fileSD::154::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906
Thread-40::DEBUG::2014-01-30 16:17:17,835::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend
Thread-40::DEBUG::2014-01-30 16:17:17,842::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=colnas03_IB', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=3', 'POOL_DESCRIPTION=Collogia', 'POOL_DOMAINS=272ec473-6041-42ee-bd1a-732789dd18d4:Active,965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545:Active,2c51d320-88ce-4f23-8215-e15f55f66906:Active,63041fa9-e093-4b44-b36f-f39f16d3974f:Active,bff3a2be-fdd9-4e37-b416-fa4ef7fafba2:Active', 'POOL_SPM_ID=2', 'POOL_SPM_LVER=33', 'POOL_UUID=94ed7a19-fade-4bd6-83f2-2cbb2f730b95', 'REMOTE_PATH=10.10.30.253:/var/nas3/OVirtIB', 'ROLE=Master', 'SDUUID=2c51d320-88ce-4f23-8215-e15f55f66906', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=75ca15b219476f472d87a8c375650d35eabb8d16']
Thread-40::DEBUG::2014-01-30 16:17:17,843::fileSD::572::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images []
Thread-40::INFO::2014-01-30 16:17:17,844::sd::374::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 2c51d320-88ce-4f23-8215-e15f55f66906_imageNS already registered
Thread-40::INFO::2014-01-30 16:17:17,844::sd::382::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 2c51d320-88ce-4f23-8215-e15f55f66906_volumeNS already registered
Thread-40::DEBUG::2014-01-30 16:17:17,854::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-40::DEBUG::2014-01-30 16:17:17,860::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n645 bytes (645 B) copied, 0.000216469 s, 3.0 MB/s\n'; <rc> = 0
Thread-42::DEBUG::2014-01-30 16:17:18,381::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-42::DEBUG::2014-01-30 16:17:18,387::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n357 bytes (357 B) copied, 0.000243463 s, 1.5 MB/s\n'; <rc> = 0
Thread-285241::DEBUG::2014-01-30 16:17:19,814::BindingXMLRPC::974::vds::(wrapper) client [192.168.11.2]::call vmGetStats with ('ce64f528-9981-4ec6-a172-9d70a00a34cd',) {}
Thread-285241::DEBUG::2014-01-30 16:17:19,815::vm::645::vm.Vm::(_getDiskStats) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk hdc stats not available
Thread-285241::DEBUG::2014-01-30 16:17:19,815::vm::645::vm.Vm::(_getDiskStats) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk sda stats not available
Thread-285241::DEBUG::2014-01-30 16:17:19,815::vm::684::vm.Vm::(_getDiskLatency) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk hdc latency not available
Thread-285241::DEBUG::2014-01-30 16:17:19,815::vm::684::vm.Vm::(_getDiskLatency) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk sda latency not available
Thread-285241::DEBUG::2014-01-30 16:17:19,816::BindingXMLRPC::981::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Paused', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'guestFQDN': '', 'pid': '7671', 'displayIp': '192.168.11.44', 'displayPort': '-1', 'session': 'Unknown', 'displaySecurePort': u'5900', 'timeOffset': '0', 'hash': '7219603903902024642', 'balloonInfo': {'balloon_max': '2097152', 'balloon_target': '2097152', 'balloon_cur': '2097152', 'balloon_min': '2097152'}, 'clientIp': '', 'kvmEnable': 'true', 'network': {u'vnet0': {'macAddr': '00:1a:4a:ee:d3:4a', 'rxDropped': '909', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': 'ce64f528-9981-4ec6-a172-9d70a00a34cd', 'displayType': 'qxl', 'cpuUser': '0.44', 'disks': {u'hdc': {'truesize': '0', 'apparentsize': '0'}, u'sda': {'truesize': '17700114432', 'apparentsize': '21474836480', 'imageID': '1b23ac73-0748-49cd-94b6-11555e35be81'}}, 'monitorResponse': '0', 'statsAge': '0.78', 'elapsedTime': '1224', 'vmType': 'kvm', 'cpuSys': '1.93', 'appsList': [], 'guestIPs': ''}]}
VM Channels Listener::DEBUG::2014-01-30 16:17:20,026::vmChannels::91::vds::(_handle_timeouts) Timeout on fileno 98.
Thread-47::DEBUG::2014-01-30 16:17:20,096::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-47::DEBUG::2014-01-30 16:17:20,103::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n363 bytes (363 B) copied, 0.00022031 s, 1.6 MB/s\n'; <rc> = 0
Thread-41::DEBUG::2014-01-30 16:17:21,589::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-41::DEBUG::2014-01-30 16:17:21,596::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.0002126 s, 2.6 MB/s\n'; <rc> = 0
Thread-285243::DEBUG::2014-01-30 16:17:22,928::BindingXMLRPC::974::vds::(wrapper) client [192.168.11.2]::call vmGetStats with ('ce64f528-9981-4ec6-a172-9d70a00a34cd',) {}
Thread-285243::DEBUG::2014-01-30 16:17:22,928::vm::645::vm.Vm::(_getDiskStats) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk hdc stats not available
Thread-285243::DEBUG::2014-01-30 16:17:22,928::vm::645::vm.Vm::(_getDiskStats) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk sda stats not available
Thread-285243::DEBUG::2014-01-30 16:17:22,928::vm::684::vm.Vm::(_getDiskLatency) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk hdc latency not available
Thread-285243::DEBUG::2014-01-30 16:17:22,929::vm::684::vm.Vm::(_getDiskLatency) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk sda latency not available
Thread-285243::DEBUG::2014-01-30 16:17:22,930::BindingXMLRPC::981::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Paused', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'guestFQDN': '', 'pid': '7671', 'displayIp': '192.168.11.44', 'displayPort': '-1', 'session': 'Unknown', 'displaySecurePort': u'5900', 'timeOffset': '0', 'hash': '7219603903902024642', 'balloonInfo': {'balloon_max': '2097152', 'balloon_target': '2097152', 'balloon_cur': '2097152', 'balloon_min': '2097152'}, 'clientIp': '', 'kvmEnable': 'true', 'network': {u'vnet0': {'macAddr': '00:1a:4a:ee:d3:4a', 'rxDropped': '909', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': 'ce64f528-9981-4ec6-a172-9d70a00a34cd', 'displayType': 'qxl', 'cpuUser': '0.44', 'disks': {u'hdc': {'truesize': '0', 'apparentsize': '0'}, u'sda': {'truesize': '17700114432', 'apparentsize': '21474836480', 'imageID': '1b23ac73-0748-49cd-94b6-11555e35be81'}}, 'monitorResponse': '0', 'statsAge': '1.88', 'elapsedTime': '1227', 'vmType': 'kvm', 'cpuSys': '1.93', 'appsList': [], 'guestIPs': ''}]}
Thread-52::DEBUG::2014-01-30 16:17:24,512::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-52::DEBUG::2014-01-30 16:17:24,519::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000195213 s, 2.9 MB/s\n'; <rc> = 0
Thread-285245::DEBUG::2014-01-30 16:17:26,006::BindingXMLRPC::974::vds::(wrapper) client [192.168.11.2]::call vmGetStats with ('ce64f528-9981-4ec6-a172-9d70a00a34cd',) {}
Thread-285245::DEBUG::2014-01-30 16:17:26,006::vm::645::vm.Vm::(_getDiskStats) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk hdc stats not available
Thread-285245::DEBUG::2014-01-30 16:17:26,006::vm::645::vm.Vm::(_getDiskStats) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk sda stats not available
Thread-285245::DEBUG::2014-01-30 16:17:26,007::vm::684::vm.Vm::(_getDiskLatency) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk hdc latency not available
Thread-285245::DEBUG::2014-01-30 16:17:26,007::vm::684::vm.Vm::(_getDiskLatency) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk sda latency not available
Thread-285245::DEBUG::2014-01-30 16:17:26,008::BindingXMLRPC::981::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Paused', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'guestFQDN': '', 'pid': '7671', 'displayIp': '192.168.11.44', 'displayPort': '-1', 'session': 'Unknown', 'displaySecurePort': u'5900', 'timeOffset': '0', 'hash': '7219603903902024642', 'balloonInfo': {'balloon_max': '2097152', 'balloon_target': '2097152', 'balloon_cur': '2097152', 'balloon_min': '2097152'}, 'clientIp': '', 'kvmEnable': 'true', 'network': {u'vnet0': {'macAddr': '00:1a:4a:ee:d3:4a', 'rxDropped': '929', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': 'ce64f528-9981-4ec6-a172-9d70a00a34cd', 'displayType': 'qxl', 'cpuUser': '0.44', 'disks': {u'hdc': {'truesize': '0', 'apparentsize': '0'}, u'sda': {'truesize': '17700114432', 'apparentsize': '21474836480', 'imageID': '1b23ac73-0748-49cd-94b6-11555e35be81'}}, 'monitorResponse': '0', 'statsAge': '0.95', 'elapsedTime': '1230', 'vmType': 'kvm', 'cpuSys': '1.93', 'appsList': [], 'guestIPs': ''}]}
Thread-40::DEBUG::2014-01-30 16:17:27,875::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-40::DEBUG::2014-01-30 16:17:27,881::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n645 bytes (645 B) copied, 0.000195778 s, 3.3 MB/s\n'; <rc> = 0
Thread-42::DEBUG::2014-01-30 16:17:28,399::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-42::DEBUG::2014-01-30 16:17:28,406::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n357 bytes (357 B) copied, 0.00021875 s, 1.6 MB/s\n'; <rc> = 0
Thread-285247::DEBUG::2014-01-30 16:17:29,119::BindingXMLRPC::974::vds::(wrapper) client [192.168.11.2]::call vmGetStats with ('ce64f528-9981-4ec6-a172-9d70a00a34cd',) {}
Thread-285247::DEBUG::2014-01-30 16:17:29,119::vm::645::vm.Vm::(_getDiskStats) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk hdc stats not available
Thread-285247::DEBUG::2014-01-30 16:17:29,119::vm::645::vm.Vm::(_getDiskStats) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk sda stats not available
Thread-285247::DEBUG::2014-01-30 16:17:29,119::vm::684::vm.Vm::(_getDiskLatency) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk hdc latency not available
Thread-285247::DEBUG::2014-01-30 16:17:29,120::vm::684::vm.Vm::(_getDiskLatency) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk sda latency not available
Thread-285247::DEBUG::2014-01-30 16:17:29,121::BindingXMLRPC::981::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Paused', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'guestFQDN': '', 'pid': '7671', 'displayIp': '192.168.11.44', 'displayPort': '-1', 'session': 'Unknown', 'displaySecurePort': u'5900', 'timeOffset': '0', 'hash': '7219603903902024642', 'balloonInfo': {'balloon_max': '2097152', 'balloon_target': '2097152', 'balloon_cur': '2097152', 'balloon_min': '2097152'}, 'clientIp': '', 'kvmEnable': 'true', 'network': {u'vnet0': {'macAddr': '00:1a:4a:ee:d3:4a', 'rxDropped': '946', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': 'ce64f528-9981-4ec6-a172-9d70a00a34cd', 'displayType': 'qxl', 'cpuUser': '0.44', 'disks': {u'hdc': {'truesize': '0', 'apparentsize': '0'}, u'sda': {'truesize': '17700114432', 'apparentsize': '21474836480', 'imageID': '1b23ac73-0748-49cd-94b6-11555e35be81'}}, 'monitorResponse': '0', 'statsAge': '0.07', 'elapsedTime': '1233', 'vmType': 'kvm', 'cpuSys': '1.93', 'appsList': [], 'guestIPs': ''}]}
VM Channels Listener::ERROR::2014-01-30 16:17:29,729::vmChannels::53::vds::(_handle_event) Received 00000019 on fileno 98
VM Channels Listener::DEBUG::2014-01-30 16:17:29,729::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 98.
VM Channels Listener::DEBUG::2014-01-30 16:17:29,730::guestIF::147::vm.Vm::(_connect) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Attempting connection to /var/lib/libvirt/qemu/channels/ce64f528-9981-4ec6-a172-9d70a00a34cd.com.redhat.rhevm.vdsm
VM Channels Listener::DEBUG::2014-01-30 16:17:29,730::guestIF::158::vm.Vm::(_connect) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Failed to connect to /var/lib/libvirt/qemu/channels/ce64f528-9981-4ec6-a172-9d70a00a34cd.com.redhat.rhevm.vdsm with 111
libvirtEventLoop::DEBUG::2014-01-30 16:17:29,770::vm::4840::vm.Vm::(_onLibvirtLifecycleEvent) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::event Stopped detail 5 opaque None
libvirtEventLoop::INFO::2014-01-30 16:17:29,770::vm::2166::vm.Vm::(_onQemuDeath) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::underlying process disconnected
libvirtEventLoop::INFO::2014-01-30 16:17:29,770::vm::4320::vm.Vm::(releaseVm) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Release VM resources
libvirtEventLoop::DEBUG::2014-01-30 16:17:29,775::libvirtconnection::108::libvirtconnection::(wrapper) Unknown libvirterror: ecode: 42 edom: 10 level: 2 message: Domain nicht gefunden: Keine Domain mit ?bereinstimmender UUID 'ce64f528-9981-4ec6-a172-9d70a00a34cd' (Win7x64_Master)
libvirtEventLoop::DEBUG::2014-01-30 16:17:29,776::sampling::292::vm.Vm::(stop) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Stop statistics collection
libvirtEventLoop::DEBUG::2014-01-30 16:17:29,776::vmChannels::205::vds::(unregister) Delete fileno 98 from listener.
Thread-285161::DEBUG::2014-01-30 16:17:29,776::sampling::323::vm.Vm::(run) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Stats thread finished
libvirtEventLoop::DEBUG::2014-01-30 16:17:29,777::libvirtconnection::108::libvirtconnection::(wrapper) Unknown libvirterror: ecode: 42 edom: 10 level: 2 message: Domain nicht gefunden: Keine Domain mit ?bereinstimmender UUID 'ce64f528-9981-4ec6-a172-9d70a00a34cd' (Win7x64_Master)
libvirtEventLoop::WARNING::2014-01-30 16:17:29,777::clientIF::362::vds::(teardownVolumePath) Drive is not a vdsm image: VOLWM_CHUNK_MB:1024 VOLWM_CHUNK_REPLICATE_MULT:2 VOLWM_FREE_PCT:50 _blockDev:False _checkIoTuneCategories:<bound method Drive._checkIoTuneCategories of <vm.Drive object at 0x7f356003bb90>> _customize:<bound method Drive._customize of <vm.Drive object at 0x7f356003bb90>> _deviceXML:<disk device="cdrom" type="file">
<driver name="qemu" type="raw"/>
<source startupPolicy="optional"/>
<target bus="ide" dev="hdc"/>
<readonly/>
<serial/>
<alias name="ide0-1-0"/>
<address bus="1" controller="0" target="0" type="drive" unit="0"/>
</disk> _makeName:<bound method Drive._makeName of <vm.Drive object at 0x7f356003bb90>> _setExtSharedState:<bound method Drive._setExtSharedState of <vm.Drive object at 0x7f356003bb90>> _validateIoTuneParams:<bound method Drive._validateIoTuneParams of <vm.Drive object at 0x7f356003bb90>> address:{u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'} alias:ide0-1-0 apparentsize:0 blockDev:False cache:none conf:{'acpiEnable': 'true', 'emulatedMachine': 'pc-1.0', 'afterMigrationStatus': '', 'pid': '7671', 'memGuaranteedSize': 2048, 'transparentHugePages': 'true', 'displaySecurePort': u'5900', 'timeOffset': '0', 'cpuType': 'Nehalem', 'smp': '2', 'custom': {'device_aff6efaa-b33b-4385-a311-0c770cf56cf2device_3073f208-c700-4b39-99f1-56c33e884c78device_0c7f4f0b-98d4-4a1a-934e-6210ecabd3e9device_50fb5c9c-d9b3-4422-b216-3ff71ac6d774device_bb8234b4-44d4-4086-906c-744b572ddbd9': 'VmDevice {vmId=ce64f528-9981-4ec6-a172-9d70a00a34cd, deviceId=bb8234b4-44d4-4086-906c-744b572ddbd9, device=spicevmc, type=CHANNEL, bootOrder=0, specParams={}, address={port=3, bus=0, controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false, deviceAlias=channel2, customProperties={}, snapshotId=null}', 'device_aff6efaa-b33b-4385-a311-0c770cf56cf2device_3073f208-c700-4b39-99f1-56c33e884c78': 'VmDevice {vmId=ce64f528-9981-4ec6-a172-9d70a00a34cd, deviceId=3073f208-c700-4b39-99f1-56c33e884c78, device=virtio-serial, type=CONTROLLER, bootOrder=0, specParams={}, address={bus=0x00, domain=0x0000, type=pci, slot=0x06, function=0x0}, managed=false, plugged=true, readOnly=false, deviceAlias=virtio-serial0, customProperties={}, snapshotId=null}', 'device_aff6efaa-b33b-4385-a311-0c770cf56cf2device_3073f208-c700-4b39-99f1-56c33e884c78device_0c7f4f0b-98d4-4a1a-934e-6210ecabd3e9device_50fb5c9c-d9b3-4422-b216-3ff71ac6d774': 'VmDevice {vmId=ce64f528-9981-4ec6-a172-9d70a00a34cd, deviceId=50fb5c9c-d9b3-4422-b216-3ff71ac6d774, device=unix, type=CHANNEL, bootOrder=0, specParams={}, address={port=2, bus=0, controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false, deviceAlias=channel1, customProperties={}, snapshotId=null}', 'sap_agent': 'false', 'device_aff6efaa-b33b-4385-a311-0c770cf56cf2': 'VmDevice {vmId=ce64f528-9981-4ec6-a172-9d70a00a34cd, deviceId=aff6efaa-b33b-4385-a311-0c770cf56cf2, device=ide, type=CONTROLLER, bootOrder=0, specParams={}, address={bus=0x00, domain=0x0000, type=pci, slot=0x01, function=0x1}, managed=false, plugged=true, readOnly=false, deviceAlias=ide0, customProperties={}, snapshotId=null}', 'device_aff6efaa-b33b-4385-a311-0c770cf56cf2device_3073f208-c700-4b39-99f1-56c33e884c78device_0c7f4f0b-98d4-4a1a-934e-6210ecabd3e9': 'VmDevice {vmId=ce64f528-9981-4ec6-a172-9d70a00a34cd, deviceId=0c7f4f0b-98d4-4a1a-934e-6210ecabd3e9, device=unix, type=CHANNEL, bootOrder=0, specParams={}, address={port=1, bus=0, controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false, deviceAlias=channel0, customProperties={}, snapshotId=null}'}, 'vmType': 'kvm', 'spiceSslCipherSuite': 'DEFAULT', 'memSize': 2048, 'vmName': 'Win7x64_Master', 'nice': '0', 'clientIp': '', 'vmId': 'ce64f528-9981-4ec6-a172-9d70a00a34cd', 'displayIp': '192.168.11.44', 'keyboardLayout': 'de', 'displayPort': '-1', 'smartcardEnable': 'false', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', 'nicModel': 'rtl8139,pv', 'smpCoresPerSocket': '2', 'kvmEnable': 'true', 'displayNetwork': 'ovirtmgmt', 'devices': [{'device': 'unix', 'alias': 'channel0', 'type': 'channel', 'address': {'bus': '0', 'controller': '0', 'type': 'virtio-serial', 'port': '1'}}, {'device': 'unix', 'alias': 'channel1', 'type': 'channel', 'address': {'bus': '0', 'controller': '0', 'type': 'virtio-serial', 'port': '2'}}, {'device': 'spicevmc', 'alias': 'channel2', 'type': 'channel', 'address': {'bus': '0', 'controller': '0', 'type': 'virtio-serial', 'port': '3'}}, {'specParams': {}, 'alias': u'scsi0', 'deviceId': '294da3e7-42c8-4872-918c-cafa13cec438', 'address': {u'slot': u'0x04', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, 'device': 'scsi', 'model': 'virtio-scsi', 'type': 'controller'}, {'device': 'usb', 'alias': u'usb0', 'type': 'controller', 'address': {u'slot': u'0x01', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x2'}}, {'device': 'ide', 'alias': u'ide0', 'type': 'controller', 'address': {u'slot': u'0x01', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x1'}}, {'device': 'virtio-serial', 'alias': u'virtio-serial0', 'type': 'controller', 'address': {u'slot': u'0x06', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}}, {'specParams': {'vram': '32768', 'heads': '1'}, 'alias': 'video0', 'deviceId': '14faa0f4-9b5f-4997-bcdb-889d49672122', 'address': {'slot': '0x02', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'qxl', 'type': 'video'}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:ee:d3:4a', 'linkActive': True, 'network': 'ovirtmgmt', 'specParams': {}, 'filter': 'vdsm-no-mac-spoofing', 'alias': u'net0', 'deviceId': '0109b881-8911-40ef-9e19-ad0d8daf5917', 'address': {u'slot': u'0x03', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, 'device': 'bridge', 'type': 'interface', 'name': u'vnet0'}, {'index': '2', 'iface': 'ide', 'name': u'hdc', 'alias': u'ide0-1-0', 'specParams': {'path': ''}, 'readonly': 'True', 'deviceId': '6aad5e48-613b-48db-838a-fc923fb0cdd7', 'address': {u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}, 'device': 'cdrom', 'shared': 'false', 'path': '', 'type': 'disk'}, {'address': {u'bus': u'0', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}, 'reqsize': '0', 'index': 0, 'iface': 'scsi', 'apparentsize': '21474836480', 'specParams': {}, 'imageID': '1b23ac73-0748-49cd-94b6-11555e35be81', 'readonly': 'False', 'shared': 'false', 'truesize': '17698430976', 'type': 'disk', 'domainID': '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545', 'volumeInfo': {'domainID': '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545', 'volType': 'path', 'leaseOffset': 0, 'path': '/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/images/1b23ac73-0748-49cd-94b6-11555e35be81/5156a43b-c9dc-40fa-a9b7-a35b7f22f0eb', 'volumeID': '5156a43b-c9dc-40fa-a9b7-a35b7f22f0eb', 'leasePath': '/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/images/1b23ac73-0748-49cd-94b6-11555e35be81/5156a43b-c9dc-40fa-a9b7-a35b7f22f0eb.lease', 'imageID': '1b23ac73-0748-49cd-94b6-11555e35be81'}, 'format': 'raw', 'deviceId': '1b23ac73-0748-49cd-94b6-11555e35be81', 'poolID': '94ed7a19-fade-4bd6-83f2-2cbb2f730b95', 'device': 'disk', 'path': '/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/images/1b23ac73-0748-49cd-94b6-11555e35be81/5156a43b-c9dc-40fa-a9b7-a35b7f22f0eb', 'propagateErrors': 'off', 'optional': 'false', 'name': u'sda', 'bootOrder': u'1', 'volumeID': '5156a43b-c9dc-40fa-a9b7-a35b7f22f0eb', 'alias': u'scsi0-0-0-0', 'volumeChain': [{'domainID': '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545', 'volType': 'path', 'leaseOffset': 0, 'path': '/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/images/1b23ac73-0748-49cd-94b6-11555e35be81/5156a43b-c9dc-40fa-a9b7-a35b7f22f0eb', 'volumeID': '5156a43b-c9dc-40fa-a9b7-a35b7f22f0eb', 'leasePath': '/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/images/1b23ac73-0748-49cd-94b6-11555e35be81/5156a43b-c9dc-40fa-a9b7-a35b7f22f0eb.lease', 'imageID': '1b23ac73-0748-49cd-94b6-11555e35be81'}]}, {'specParams': {}, 'alias': 'sound0', 'deviceId': '38b39d1b-7573-4112-b04f-669402652413', 'address': {'slot': '0x05', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'ich6', 'type': 'sound'}, {'target': 2097152, 'specParams': {'model': 'virtio'}, 'alias': 'balloon0', 'deviceId': '7c9ed232-f54e-4382-a22e-f74c2b6412f4', 'address': {'slot': '0x07', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'memballoon', 'type': 'balloon'}], 'status': 'Paused', 'display': 'qxl'} createXmlElem:<bound method Drive.createXmlElem of <vm.Drive object at 0x7f356003bb90>> device:cdrom deviceId:6aad5e48-613b-48db-838a-fc923fb0cdd7 drv:raw extSharedState:none getLeasesXML:<bound method Drive.getLeasesXML of <vm.Drive object at 0x7f356003bb90>> getNextVolumeSize:<bound method Drive.getNextVolumeSize of <vm.Drive object at 0x7f356003bb90>> getXML:<bound method Drive.getXML of <vm.Drive object at 0x7f356003bb90>> hasVolumeLeases:False iface:ide index:2 isDiskReplicationInProgress:<bound method Drive.isDiskReplicationInProgress of <vm.Drive object at 0x7f356003bb90>> isVdsmImage:<bound method Drive.isVdsmImage of <vm.Drive object at 0x7f356003bb90>> log:<logUtils.SimpleLogAdapter object at 0x7f356002ef90> name:hdc networkDev:False path: readonly:True reqsize:0 serial: shared:false specParams:{'path': ''} truesize:0 type:cdrom volExtensionChunk:1024 watermarkLimit:536870912
Traceback (most recent call last):
File "/usr/share/vdsm/clientIF.py", line 356, in teardownVolumePath
res = self.irs.teardownImage(drive['domainID'],
File "/usr/share/vdsm/vm.py", line 1389, in __getitem__
raise KeyError(key)
KeyError: 'domainID'
libvirtEventLoop::DEBUG::2014-01-30 16:17:29,779::task::579::TaskManager.Task::(_updateState) Task=`b2f2b540-29c7-436f-b28a-e3fa961e9ddd`::moving from state init -> state preparing
libvirtEventLoop::INFO::2014-01-30 16:17:29,779::logUtils::44::dispatcher::(wrapper) Run and protect: teardownImage(sdUUID='965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545', spUUID='94ed7a19-fade-4bd6-83f2-2cbb2f730b95', imgUUID='1b23ac73-0748-49cd-94b6-11555e35be81', volUUID=None)
libvirtEventLoop::DEBUG::2014-01-30 16:17:29,780::resourceManager::197::ResourceManager.Request::(__init__) ResName=`Storage.965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545`ReqID=`ce6ba549-acf2-49fa-8b36-2194b81606a5`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3283' at 'teardownImage'
libvirtEventLoop::DEBUG::2014-01-30 16:17:29,780::resourceManager::541::ResourceManager::(registerResource) Trying to register resource 'Storage.965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545' for lock type 'shared'
libvirtEventLoop::DEBUG::2014-01-30 16:17:29,780::resourceManager::600::ResourceManager::(registerResource) Resource 'Storage.965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545' is free. Now locking as 'shared' (1 active user)
libvirtEventLoop::DEBUG::2014-01-30 16:17:29,780::resourceManager::237::ResourceManager.Request::(grant) ResName=`Storage.965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545`ReqID=`ce6ba549-acf2-49fa-8b36-2194b81606a5`::Granted request
libvirtEventLoop::DEBUG::2014-01-30 16:17:29,780::task::811::TaskManager.Task::(resourceAcquired) Task=`b2f2b540-29c7-436f-b28a-e3fa961e9ddd`::_resourcesAcquired: Storage.965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545 (shared)
libvirtEventLoop::DEBUG::2014-01-30 16:17:29,781::task::974::TaskManager.Task::(_decref) Task=`b2f2b540-29c7-436f-b28a-e3fa961e9ddd`::ref 1 aborting False
libvirtEventLoop::INFO::2014-01-30 16:17:29,781::logUtils::47::dispatcher::(wrapper) Run and protect: teardownImage, Return response: None
libvirtEventLoop::DEBUG::2014-01-30 16:17:29,781::task::1168::TaskManager.Task::(prepare) Task=`b2f2b540-29c7-436f-b28a-e3fa961e9ddd`::finished: None
libvirtEventLoop::DEBUG::2014-01-30 16:17:29,781::task::579::TaskManager.Task::(_updateState) Task=`b2f2b540-29c7-436f-b28a-e3fa961e9ddd`::moving from state preparing -> state finished
libvirtEventLoop::DEBUG::2014-01-30 16:17:29,781::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': < ResourceRef 'Storage.965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545', isValid: 'True' obj: 'None'>}
libvirtEventLoop::DEBUG::2014-01-30 16:17:29,781::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
libvirtEventLoop::DEBUG::2014-01-30 16:17:29,782::resourceManager::615::ResourceManager::(releaseResource) Trying to release resource 'Storage.965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545'
libvirtEventLoop::DEBUG::2014-01-30 16:17:29,782::resourceManager::634::ResourceManager::(releaseResource) Released resource 'Storage.965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545' (0 active users)
libvirtEventLoop::DEBUG::2014-01-30 16:17:29,782::resourceManager::640::ResourceManager::(releaseResource) Resource 'Storage.965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545' is free, finding out if anyone is waiting for it.
libvirtEventLoop::DEBUG::2014-01-30 16:17:29,782::resourceManager::648::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545', Clearing records.
libvirtEventLoop::DEBUG::2014-01-30 16:17:29,782::task::974::TaskManager.Task::(_decref) Task=`b2f2b540-29c7-436f-b28a-e3fa961e9ddd`::ref 0 aborting False
libvirtEventLoop::DEBUG::2014-01-30 16:17:29,783::task::579::TaskManager.Task::(_updateState) Task=`889a75b9-0702-40d3-99da-f7994e33c40c`::moving from state init -> state preparing
libvirtEventLoop::INFO::2014-01-30 16:17:29,783::logUtils::44::dispatcher::(wrapper) Run and protect: inappropriateDevices(thiefId='ce64f528-9981-4ec6-a172-9d70a00a34cd')
libvirtEventLoop::INFO::2014-01-30 16:17:29,783::logUtils::47::dispatcher::(wrapper) Run and protect: inappropriateDevices, Return response: None
libvirtEventLoop::DEBUG::2014-01-30 16:17:29,784::task::1168::TaskManager.Task::(prepare) Task=`889a75b9-0702-40d3-99da-f7994e33c40c`::finished: None
libvirtEventLoop::DEBUG::2014-01-30 16:17:29,784::task::579::TaskManager.Task::(_updateState) Task=`889a75b9-0702-40d3-99da-f7994e33c40c`::moving from state preparing -> state finished
libvirtEventLoop::DEBUG::2014-01-30 16:17:29,784::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
libvirtEventLoop::DEBUG::2014-01-30 16:17:29,784::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
libvirtEventLoop::DEBUG::2014-01-30 16:17:29,784::task::974::TaskManager.Task::(_decref) Task=`889a75b9-0702-40d3-99da-f7994e33c40c`::ref 0 aborting False
Thread-285248::DEBUG::2014-01-30 16:17:29,787::BindingXMLRPC::974::vds::(wrapper) client [192.168.11.42]::call vmDestroy with ('ce64f528-9981-4ec6-a172-9d70a00a34cd',) {}
Thread-285248::INFO::2014-01-30 16:17:29,787::API::318::vds::(destroy) vmContainerLock acquired by vm ce64f528-9981-4ec6-a172-9d70a00a34cd
Thread-285248::DEBUG::2014-01-30 16:17:29,787::vm::4374::vm.Vm::(destroy) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::destroy Called
Thread-285248::DEBUG::2014-01-30 16:17:29,788::vm::4368::vm.Vm::(deleteVm) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Total desktops after destroy of ce64f528-9981-4ec6-a172-9d70a00a34cd is 0
Thread-285248::DEBUG::2014-01-30 16:17:29,788::BindingXMLRPC::981::vds::(wrapper) return vmDestroy with {'status': {'message': 'Machine destroyed', 'code': 0}}
libvirtEventLoop::DEBUG::2014-01-30 16:17:29,792::libvirtconnection::108::libvirtconnection::(wrapper) Unknown libvirterror: ecode: 42 edom: 10 level: 2 message: Domain nicht gefunden: Keine Domain mit ?bereinstimmender UUID 'ce64f528-9981-4ec6-a172-9d70a00a34cd' (Win7x64_Master)
libvirtEventLoop::DEBUG::2014-01-30 16:17:29,792::vm::2577::vm.Vm::(setDownStatus) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Changed state to Down: Lost connection with qemu process
libvirtEventLoop::DEBUG::2014-01-30 16:17:29,792::sampling::292::vm.Vm::(stop) vmId=`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Stop statistics collection
libvirtEventLoop::DEBUG::2014-01-30 16:17:29,793::libvirtconnection::108::libvirtconnection::(wrapper) Unknown libvirterror: ecode: 42 edom: 10 level: 2 message: Domain nicht gefunden: Keine Domain mit ?bereinstimmender UUID 'ce64f528-9981-4ec6-a172-9d70a00a34cd' (Win7x64_Master)
Thread-47::DEBUG::2014-01-30 16:17:30,113::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-47::DEBUG::2014-01-30 16:17:30,120::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n363 bytes (363 B) copied, 0.000169437 s, 2.1 MB/s\n'; <rc> = 0
VM Channels Listener::DEBUG::2014-01-30 16:17:30,731::vmChannels::112::vds::(_do_del_channels) fileno 98 was removed from listener.
Thread-41::DEBUG::2014-01-30 16:17:31,606::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-41::DEBUG::2014-01-30 16:17:31,612::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000246606 s, 2.3 MB/s\n'; <rc> = 0
Thread-285249::DEBUG::2014-01-30 16:17:32,200::task::579::TaskManager.Task::(_updateState) Task=`e44ca35a-0638-43b2-99b7-85790a96f8a2`::moving from state init -> state preparing
Thread-285249::INFO::2014-01-30 16:17:32,200::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-285249::INFO::2014-01-30 16:17:32,201::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'2c51d320-88ce-4f23-8215-e15f55f66906': {'delay': '0.000195778', 'lastCheck': '4.3', 'code': 0, 'valid': True, 'version': 3}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'delay': '0.000246606', 'lastCheck': '0.6', 'code': 0, 'valid': True, 'version': 3}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'delay': '0.00021875', 'lastCheck': '3.8', 'code': 0, 'valid': True, 'version': 0}, '63041fa9-e093-4b44-b36f-f39f16d3974f': {'delay': '0.000169437', 'lastCheck': '2.1', 'code': 0, 'valid': True, 'version': 0}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'delay': '0.000195213', 'lastCheck': '7.7', 'code': 0, 'valid': True, 'version': 3}}
Thread-285249::DEBUG::2014-01-30 16:17:32,201::task::1168::TaskManager.Task::(prepare) Task=`e44ca35a-0638-43b2-99b7-85790a96f8a2`::finished: {'2c51d320-88ce-4f23-8215-e15f55f66906': {'delay': '0.000195778', 'lastCheck': '4.3', 'code': 0, 'valid': True, 'version': 3}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'delay': '0.000246606', 'lastCheck': '0.6', 'code': 0, 'valid': True, 'version': 3}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'delay': '0.00021875', 'lastCheck': '3.8', 'code': 0, 'valid': True, 'version': 0}, '63041fa9-e093-4b44-b36f-f39f16d3974f': {'delay': '0.000169437', 'lastCheck': '2.1', 'code': 0, 'valid': True, 'version': 0}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'delay': '0.000195213', 'lastCheck': '7.7', 'code': 0, 'valid': True, 'version': 3}}
Thread-285249::DEBUG::2014-01-30 16:17:32,201::task::579::TaskManager.Task::(_updateState) Task=`e44ca35a-0638-43b2-99b7-85790a96f8a2`::moving from state preparing -> state finished
Thread-285249::DEBUG::2014-01-30 16:17:32,201::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-285249::DEBUG::2014-01-30 16:17:32,201::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-285249::DEBUG::2014-01-30 16:17:32,201::task::974::TaskManager.Task::(_decref) Task=`e44ca35a-0638-43b2-99b7-85790a96f8a2`::ref 0 aborting False
Thread-52::DEBUG::2014-01-30 16:17:34,531::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-52::DEBUG::2014-01-30 16:17:34,538::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000202672 s, 2.7 MB/s\n'; <rc> = 0
Thread-40::DEBUG::2014-01-30 16:17:37,893::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-40::DEBUG::2014-01-30 16:17:37,899::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n645 bytes (645 B) copied, 0.000200736 s, 3.2 MB/s\n'; <rc> = 0
Thread-42::DEBUG::2014-01-30 16:17:38,418::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-42::DEBUG::2014-01-30 16:17:38,423::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n357 bytes (357 B) copied, 0.000239232 s, 1.5 MB/s\n'; <rc> = 0
Thread-47::DEBUG::2014-01-30 16:17:40,132::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-47::DEBUG::2014-01-30 16:17:40,137::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n363 bytes (363 B) copied, 0.000199954 s, 1.8 MB/s\n'; <rc> = 0
Thread-41::DEBUG::2014-01-30 16:17:41,622::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-41::DEBUG::2014-01-30 16:17:41,628::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000177973 s, 3.1 MB/s\n'; <rc> = 0
Thread-52::DEBUG::2014-01-30 16:17:44,549::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-52::DEBUG::2014-01-30 16:17:44,555::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000217367 s, 2.6 MB/s\n'; <rc> = 0
Thread-285255::DEBUG::2014-01-30 16:17:47,564::task::579::TaskManager.Task::(_updateState) Task=`feb38342-e432-4cdf-afc4-39582ee67c68`::moving from state init -> state preparing
Thread-285255::INFO::2014-01-30 16:17:47,564::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-285255::INFO::2014-01-30 16:17:47,564::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'2c51d320-88ce-4f23-8215-e15f55f66906': {'delay': '0.000200736', 'lastCheck': '9.7', 'code': 0, 'valid': True, 'version': 3}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'delay': '0.000177973', 'lastCheck': '5.9', 'code': 0, 'valid': True, 'version': 3}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'delay': '0.000239232', 'lastCheck': '9.1', 'code': 0, 'valid': True, 'version': 0}, '63041fa9-e093-4b44-b36f-f39f16d3974f': {'delay': '0.000199954', 'lastCheck': '7.4', 'code': 0, 'valid': True, 'version': 0}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'delay': '0.000217367', 'lastCheck': '3.0', 'code': 0, 'valid': True, 'version': 3}}
Thread-285255::DEBUG::2014-01-30 16:17:47,564::task::1168::TaskManager.Task::(prepare) Task=`feb38342-e432-4cdf-afc4-39582ee67c68`::finished: {'2c51d320-88ce-4f23-8215-e15f55f66906': {'delay': '0.000200736', 'lastCheck': '9.7', 'code': 0, 'valid': True, 'version': 3}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'delay': '0.000177973', 'lastCheck': '5.9', 'code': 0, 'valid': True, 'version': 3}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'delay': '0.000239232', 'lastCheck': '9.1', 'code': 0, 'valid': True, 'version': 0}, '63041fa9-e093-4b44-b36f-f39f16d3974f': {'delay': '0.000199954', 'lastCheck': '7.4', 'code': 0, 'valid': True, 'version': 0}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'delay': '0.000217367', 'lastCheck': '3.0', 'code': 0, 'valid': True, 'version': 3}}
Thread-285255::DEBUG::2014-01-30 16:17:47,565::task::579::TaskManager.Task::(_updateState) Task=`feb38342-e432-4cdf-afc4-39582ee67c68`::moving from state preparing -> state finished
Thread-285255::DEBUG::2014-01-30 16:17:47,565::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-285255::DEBUG::2014-01-30 16:17:47,565::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-285255::DEBUG::2014-01-30 16:17:47,565::task::974::TaskManager.Task::(_decref) Task=`feb38342-e432-4cdf-afc4-39582ee67c68`::ref 0 aborting False
Thread-40::DEBUG::2014-01-30 16:17:47,913::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-40::DEBUG::2014-01-30 16:17:47,919::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n645 bytes (645 B) copied, 0.000156636 s, 4.1 MB/s\n'; <rc> = 0
Thread-42::DEBUG::2014-01-30 16:17:48,435::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-42::DEBUG::2014-01-30 16:17:48,440::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n357 bytes (357 B) copied, 0.000219512 s, 1.6 MB/s\n'; <rc> = 0
Thread-47::DEBUG::2014-01-30 16:17:50,153::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-47::DEBUG::2014-01-30 16:17:50,158::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n363 bytes (363 B) copied, 0.000129306 s, 2.8 MB/s\n'; <rc> = 0
Thread-41::DEBUG::2014-01-30 16:17:51,639::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-41::DEBUG::2014-01-30 16:17:51,645::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000299809 s, 1.9 MB/s\n'; <rc> = 0
Thread-52::DEBUG::2014-01-30 16:17:54,565::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-52::DEBUG::2014-01-30 16:17:54,571::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.00023204 s, 2.4 MB/s\n'; <rc> = 0
Thread-40::DEBUG::2014-01-30 16:17:57,934::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-40::DEBUG::2014-01-30 16:17:57,940::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n645 bytes (645 B) copied, 0.000197083 s, 3.3 MB/s\n'; <rc> = 0
Thread-42::DEBUG::2014-01-30 16:17:58,453::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-42::DEBUG::2014-01-30 16:17:58,458::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n357 bytes (357 B) copied, 0.000150387 s, 2.4 MB/s\n'; <rc> = 0
Thread-47::DEBUG::2014-01-30 16:18:00,168::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-47::DEBUG::2014-01-30 16:18:00,174::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n363 bytes (363 B) copied, 0.000222782 s, 1.6 MB/s\n'; <rc> = 0
Thread-41::DEBUG::2014-01-30 16:18:01,655::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-41::DEBUG::2014-01-30 16:18:01,661::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000197351 s, 2.8 MB/s\n'; <rc> = 0
Thread-285261::DEBUG::2014-01-30 16:18:02,942::task::579::TaskManager.Task::(_updateState) Task=`5683bb8f-2158-4c8f-a263-46b6e7a086da`::moving from state init -> state preparing
Thread-285261::INFO::2014-01-30 16:18:02,943::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-285261::INFO::2014-01-30 16:18:02,943::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'2c51d320-88ce-4f23-8215-e15f55f66906': {'delay': '0.000197083', 'lastCheck': '5.0', 'code': 0, 'valid': True, 'version': 3}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'delay': '0.000197351', 'lastCheck': '1.3', 'code': 0, 'valid': True, 'version': 3}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'delay': '0.000150387', 'lastCheck': '4.5', 'code': 0, 'valid': True, 'version': 0}, '63041fa9-e093-4b44-b36f-f39f16d3974f': {'delay': '0.000222782', 'lastCheck': '2.8', 'code': 0, 'valid': True, 'version': 0}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'delay': '0.00023204', 'lastCheck': '8.4', 'code': 0, 'valid': True, 'version': 3}}
Thread-285261::DEBUG::2014-01-30 16:18:02,943::task::1168::TaskManager.Task::(prepare) Task=`5683bb8f-2158-4c8f-a263-46b6e7a086da`::finished: {'2c51d320-88ce-4f23-8215-e15f55f66906': {'delay': '0.000197083', 'lastCheck': '5.0', 'code': 0, 'valid': True, 'version': 3}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'delay': '0.000197351', 'lastCheck': '1.3', 'code': 0, 'valid': True, 'version': 3}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'delay': '0.000150387', 'lastCheck': '4.5', 'code': 0, 'valid': True, 'version': 0}, '63041fa9-e093-4b44-b36f-f39f16d3974f': {'delay': '0.000222782', 'lastCheck': '2.8', 'code': 0, 'valid': True, 'version': 0}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'delay': '0.00023204', 'lastCheck': '8.4', 'code': 0, 'valid': True, 'version': 3}}
Thread-285261::DEBUG::2014-01-30 16:18:02,944::task::579::TaskManager.Task::(_updateState) Task=`5683bb8f-2158-4c8f-a263-46b6e7a086da`::moving from state preparing -> state finished
Thread-285261::DEBUG::2014-01-30 16:18:02,944::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-285261::DEBUG::2014-01-30 16:18:02,944::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-285261::DEBUG::2014-01-30 16:18:02,944::task::974::TaskManager.Task::(_decref) Task=`5683bb8f-2158-4c8f-a263-46b6e7a086da`::ref 0 aborting False
Thread-52::DEBUG::2014-01-30 16:18:04,581::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-52::DEBUG::2014-01-30 16:18:04,588::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000218219 s, 2.6 MB/s\n'; <rc> = 0
Thread-40::DEBUG::2014-01-30 16:18:07,953::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-40::DEBUG::2014-01-30 16:18:07,959::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n645 bytes (645 B) copied, 0.00019818 s, 3.3 MB/s\n'; <rc> = 0
Thread-42::DEBUG::2014-01-30 16:18:08,470::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-42::DEBUG::2014-01-30 16:18:08,475::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n357 bytes (357 B) copied, 0.000178019 s, 2.0 MB/s\n'; <rc> = 0
Thread-47::DEBUG::2014-01-30 16:18:10,186::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-47::DEBUG::2014-01-30 16:18:10,192::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n363 bytes (363 B) copied, 0.000189951 s, 1.9 MB/s\n'; <rc> = 0
Thread-41::DEBUG::2014-01-30 16:18:11,671::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-41::DEBUG::2014-01-30 16:18:11,677::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000247616 s, 2.2 MB/s\n'; <rc> = 0
Thread-52::DEBUG::2014-01-30 16:18:14,598::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-52::DEBUG::2014-01-30 16:18:14,604::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000208255 s, 2.7 MB/s\n'; <rc> = 0
Thread-40::DEBUG::2014-01-30 16:18:17,974::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-40::DEBUG::2014-01-30 16:18:17,979::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n645 bytes (645 B) copied, 0.000217282 s, 3.0 MB/s\n'; <rc> = 0
Thread-285267::DEBUG::2014-01-30 16:18:18,464::task::579::TaskManager.Task::(_updateState) Task=`1e0fc684-6d0b-4694-996c-728b66ae9fc2`::moving from state init -> state preparing
Thread-285267::INFO::2014-01-30 16:18:18,465::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-285267::INFO::2014-01-30 16:18:18,465::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'2c51d320-88ce-4f23-8215-e15f55f66906': {'delay': '0.000217282', 'lastCheck': '0.5', 'code': 0, 'valid': True, 'version': 3}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'delay': '0.000247616', 'lastCheck': '6.8', 'code': 0, 'valid': True, 'version': 3}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'delay': '0.000178019', 'lastCheck': '10.0', 'code': 0, 'valid': True, 'version': 0}, '63041fa9-e093-4b44-b36f-f39f16d3974f': {'delay': '0.000189951', 'lastCheck': '8.3', 'code': 0, 'valid': True, 'version': 0}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'delay': '0.000208255', 'lastCheck': '3.9', 'code': 0, 'valid': True, 'version': 3}}
-------------- next part --------------
An embedded and charset-unspecified text was scrubbed...
Name: InterScan_Disclaimer.txt
URL: <http://lists.ovirt.org/pipermail/users/attachments/20140130/bb6f76fe/attachment-0001.txt>
More information about the Users
mailing list