[Users] Migration failed (previous migrations succeded)

This is a multi-part message in MIME format. ------=_NextPartTM-000-16e476a9-dc0a-459b-91a5-33c52e66e68f Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: quoted-printable Hello,=0A= =0A= we did some migration tests this day and all of a sudden the migration=0A= failed. That particular VM was moved around several times that day without= =0A= any problems. During the migration the VM was running a download.=0A= =0A= The logs are attached. If you need more, do not hesitate to ask.=0A= =0A= Thanks in advance.=0A= =0A= Markus=0A= =0A= **************************=0A= web log:=0A= =0A= 2014-Jan-30, 16:17 Migration failed due to Error: Migration not in progress= (VM: Win7x64_Master, Source: colovn02, Destination: colovn04).=0A= 2014-Jan-30, 16:11 Migration started (VM: Win7x64_Master, Source: colovn02,= Destination: colovn04, User: hil1).=0A= 2014-Jan-30, 16:10 Migration completed (VM: Win7x64_Master, Source: colovn0= 4, Destination: colovn02, Duration: 52 sec).=0A= 2014-Jan-30, 16:05 Migration started (VM: Win7x64_Master, Source: colovn04,= Destination: colovn02, User: hil1).=0A= 2014-Jan-30, 16:04 Migration completed (VM: Win7x64_Master, Source: colovn0= 3, Destination: colovn04, Duration: 24 sec).=0A= 2014-Jan-30, 16:01 Migration started (VM: Win7x64_Master, Source: colovn03,= Destination: colovn04, User: hil1).=0A= =0A= **************************=0A= Engine=0A= =0A= 2014-01-30 16:17:31,871 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRun= TimeInfo] (DefaultQuartzScheduler_Worker-97) RefreshVmList vm id ce64f528-9= 981-4ec6-a172-9d70a00a34cd status =3D Paused on vds colovn04 ignoring it in= the refresh until migration is done=0A= 2014-01-30 16:17:34,955 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRun= TimeInfo] (DefaultQuartzScheduler_Worker-96) RefreshVmList vm id ce64f528-9= 981-4ec6-a172-9d70a00a34cd status =3D Paused on vds colovn04 ignoring it in= the refresh until migration is done=0A= 2014-01-30 16:17:38,067 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRun= TimeInfo] (DefaultQuartzScheduler_Worker-2) RefreshVmList vm id ce64f528-99= 81-4ec6-a172-9d70a00a34cd status =3D Paused on vds colovn04 ignoring it in = the refresh until migration is done=0A= 2014-01-30 16:17:41,147 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRun= TimeInfo] (DefaultQuartzScheduler_Worker-100) RefreshVmList vm id ce64f528-= 9981-4ec6-a172-9d70a00a34cd status =3D Paused on vds colovn04 ignoring it i= n the refresh until migration is done=0A= 2014-01-30 16:17:44,268 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRun= TimeInfo] (DefaultQuartzScheduler_Worker-88) RefreshVmList vm id ce64f528-9= 981-4ec6-a172-9d70a00a34cd status =3D Paused on vds colovn04 ignoring it in= the refresh until migration is done=0A= 2014-01-30 16:17:46,440 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRun= TimeInfo] (DefaultQuartzScheduler_Worker-13) VM Win7x64_Master ce64f528-998= 1-4ec6-a172-9d70a00a34cd moved from MigratingFrom --> Up=0A= 2014-01-30 16:17:46,444 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRun= TimeInfo] (DefaultQuartzScheduler_Worker-13) Adding VM ce64f528-9981-4ec6-a= 172-9d70a00a34cd to re-run list=0A= 2014-01-30 16:17:46,456 ERROR [org.ovirt.engine.core.vdsbroker.VdsUpdateRun= TimeInfo] (DefaultQuartzScheduler_Worker-13) Rerun vm ce64f528-9981-4ec6-a1= 72-9d70a00a34cd. Called from vds colovn02=0A= 2014-01-30 16:17:46,475 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.Mi= grateStatusVDSCommand] (pool-6-thread-48) START, MigrateStatusVDSCommand(Ho= stName =3D colovn02, HostId =3D 1303e86e-cd91-406b-8a27-e75ef0a9defb, vmId= =3Dce64f528-9981-4ec6-a172-9d70a00a34cd), log id: 91bccfb=0A= 2014-01-30 16:17:46,485 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.Mi= grateStatusVDSCommand] (pool-6-thread-48) Failed in MigrateStatusVDS method= =0A= 2014-01-30 16:17:46,488 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.Mi= grateStatusVDSCommand] (pool-6-thread-48) Error code MIGRATION_CANCEL_ERROR= and error message VDSGenericException: VDSErrorException: Failed to Migrat= eStatusVDS, error =3D Migration canceled=0A= 2014-01-30 16:17:46,492 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.Mi= grateStatusVDSCommand] (pool-6-thread-48) Command org.ovirt.engine.core.vds= broker.vdsbroker.MigrateStatusVDSCommand return value=0A= StatusOnlyReturnForXmlRpc [mStatus=3DStatusForXmlRpc [mCode=3D47, mMessage= =3DMigration canceled]]=0A= 2014-01-30 16:17:46,495 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.Mi= grateStatusVDSCommand] (pool-6-thread-48) HostName =3D colovn02=0A= 2014-01-30 16:17:46,508 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.Mi= grateStatusVDSCommand] (pool-6-thread-48) Command MigrateStatusVDS executio= n failed. Exception: VDSErrorException: VDSGenericException: VDSErrorExcept= ion: Failed to MigrateStatusVDS, error =3D Migration canceled=0A= 2014-01-30 16:17:46,511 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.Mi= grateStatusVDSCommand] (pool-6-thread-48) FINISH, MigrateStatusVDSCommand, = log id: 91bccfb=0A= 2014-01-30 16:17:46,522 INFO [org.ovirt.engine.core.dal.dbbroker.auditlogh= andling.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).=0A= 2014-01-30 16:18:27,016 INFO [org.ovirt.engine.core.bll.MigrateVmToServerC= ommand] (ajp--127.0.0.1-8702-2) [5fed7321] Failed to Acquire Lock to object= EngineLock [exclusiveLocks=3D key: ce64f528-9981-4ec6-a172-9d70a00a34cd va= lue: VM=0A= , sharedLocks=3D ]=0A= 2014-01-30 16:18:27,020 WARN [org.ovirt.engine.core.bll.MigrateVmToServerC= ommand] (ajp--127.0.0.1-8702-2) [5fed7321] CanDoAction of action MigrateVmT= oServer failed. Reasons:VAR__ACTION__MIGRATE,VAR__TYPE__VM,ACTION_TYPE_FAIL= ED_VM_IS_BEING_MIGRATED,$VmName Win7x64_Master=0A= 2014-01-30 16:18:56,318 INFO [org.ovirt.engine.core.bll.MigrateVmToServerC= ommand] (ajp--127.0.0.1-8702-12) [4b6f62e9] Failed to Acquire Lock to objec= t EngineLock [exclusiveLocks=3D key: ce64f528-9981-4ec6-a172-9d70a00a34cd v= alue: VM=0A= =0A= **************************=0A= vdsm_source:=0A= =0A= Thread-290096::DEBUG::2014-01-30 16:17:04,874::task::1168::TaskManager.Task= ::(prepare) Task=3D`d313ee92-9094-49ad-8850-fbb6df383a22`::finished: {'2c51= d320-88ce-4f23-8215-e15f55f66906': {'delay': '0.000176962', 'lastCheck': '1= .8', 'code': 0, 'valid': True, 'version': 3}, '965ca3b6-4f9c-4e81-b6e8-5ed4= a9e58545': {'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}, '6= 3041fa9-e093-4b44-b36f-f39f16d3974f': {'delay': '0.000179083', 'lastCheck':= '7.1', 'code': 0, 'valid': True, 'version': 0}, '272ec473-6041-42ee-bd1a-7= 32789dd18d4': {'delay': '0.000224103', 'lastCheck': '6.3', 'code': 0, 'vali= d': True, 'version': 3}}=0A= Thread-290096::DEBUG::2014-01-30 16:17:04,874::task::579::TaskManager.Task:= :(_updateState) Task=3D`d313ee92-9094-49ad-8850-fbb6df383a22`::moving from = state preparing -> state finished=0A= Thread-290096::DEBUG::2014-01-30 16:17:04,874::resourceManager::939::Resour= ceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}=0A= Thread-290096::DEBUG::2014-01-30 16:17:04,874::resourceManager::976::Resour= ceManager.Owner::(cancelAll) Owner.cancelAll requests {}=0A= Thread-290096::DEBUG::2014-01-30 16:17:04,874::task::974::TaskManager.Task:= :(_decref) Task=3D`d313ee92-9094-49ad-8850-fbb6df383a22`::ref 0 aborting Fa= lse=0A= Thread-289929::WARNING::2014-01-30 16:17:05,585::vm::800::vm.Vm::(run) vmId= =3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Migration stalling: dataRemainin= g (24MiB) > smallest_dataRemaining (9MiB). Refer to RHBZ#919201.=0A= Thread-289929::INFO::2014-01-30 16:17:05,585::vm::812::vm.Vm::(run) vmId=3D= `ce64f528-9981-4ec6-a172-9d70a00a34cd`::Migration Progress: 360 seconds ela= psed, 99% of data processed, 99% of mem processed=0A= Thread-26::DEBUG::2014-01-30 16:17:06,907::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-26::DEBUG::2014-01-30 16:17:06,913::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.000192548 s, 2.9 MB/s\n'; <rc> =3D 0=0A= Thread-27::DEBUG::2014-01-30 16:17:07,394::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-27::DEBUG::2014-01-30 16:17:07,400::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n357 b= ytes (357 B) copied, 0.000213713 s, 1.7 MB/s\n'; <rc> =3D 0=0A= Thread-33::DEBUG::2014-01-30 16:17:07,771::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-33::DEBUG::2014-01-30 16:17:07,778::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n363 b= ytes (363 B) copied, 0.000190935 s, 1.9 MB/s\n'; <rc> =3D 0=0A= Thread-38::DEBUG::2014-01-30 16:17:08,586::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-38::DEBUG::2014-01-30 16:17:08,593::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.000184154 s, 3.0 MB/s\n'; <rc> =3D 0=0A= Thread-25::DEBUG::2014-01-30 16:17:13,044::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-25::DEBUG::2014-01-30 16:17:13,050::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n645 b= ytes (645 B) copied, 0.00017907 s, 3.6 MB/s\n'; <rc> =3D 0=0A= Thread-289929::WARNING::2014-01-30 16:17:15,586::vm::800::vm.Vm::(run) vmId= =3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Migration stalling: dataRemainin= g (16MiB) > smallest_dataRemaining (9MiB). Refer to RHBZ#919201.=0A= Thread-289929::INFO::2014-01-30 16:17:15,587::vm::812::vm.Vm::(run) vmId=3D= `ce64f528-9981-4ec6-a172-9d70a00a34cd`::Migration Progress: 370 seconds ela= psed, 99% of data processed, 99% of mem processed=0A= Thread-26::DEBUG::2014-01-30 16:17:16,923::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-26::DEBUG::2014-01-30 16:17:16,929::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.000248981 s, 2.2 MB/s\n'; <rc> =3D 0=0A= Thread-27::DEBUG::2014-01-30 16:17:17,412::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-27::DEBUG::2014-01-30 16:17:17,418::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n357 b= ytes (357 B) copied, 0.000252188 s, 1.4 MB/s\n'; <rc> =3D 0=0A= Thread-33::DEBUG::2014-01-30 16:17:17,789::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-33::DEBUG::2014-01-30 16:17:17,796::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n363 b= ytes (363 B) copied, 0.000203099 s, 1.8 MB/s\n'; <rc> =3D 0=0A= Thread-38::DEBUG::2014-01-30 16:17:18,604::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-38::DEBUG::2014-01-30 16:17:18,611::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.000177334 s, 3.1 MB/s\n'; <rc> =3D 0=0A= Thread-290102::DEBUG::2014-01-30 16:17:20,057::task::579::TaskManager.Task:= :(_updateState) Task=3D`0d381417-48c8-4035-99e5-01f34f55f98c`::moving from = state init -> state preparing=0A= Thread-290102::INFO::2014-01-30 16:17:20,057::logUtils::44::dispatcher::(wr= apper) Run and protect: repoStats(options=3DNone)=0A= Thread-290102::INFO::2014-01-30 16:17:20,058::logUtils::47::dispatcher::(wr= apper) Run and protect: repoStats, Return response: {'2c51d320-88ce-4f23-82= 15-e15f55f66906': {'delay': '0.00017907', 'lastCheck': '7.0', 'code': 0, 'v= alid': 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', 'lastC= heck': '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': {'de= lay': '0.000177334', 'lastCheck': '1.4', 'code': 0, 'valid': True, 'version= ': 3}}=0A= Thread-290102::DEBUG::2014-01-30 16:17:20,058::task::1168::TaskManager.Task= ::(prepare) Task=3D`0d381417-48c8-4035-99e5-01f34f55f98c`::finished: {'2c51= d320-88ce-4f23-8215-e15f55f66906': {'delay': '0.00017907', 'lastCheck': '7.= 0', 'code': 0, 'valid': True, 'version': 3}, '965ca3b6-4f9c-4e81-b6e8-5ed4a= 9e58545': {'delay': '0.000248981', 'lastCheck': '3.1', 'code': 0, 'valid': = True, 'version': 3}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'delay': '0.0= 00252188', 'lastCheck': '2.6', 'code': 0, 'valid': True, 'version': 0}, '63= 041fa9-e093-4b44-b36f-f39f16d3974f': {'delay': '0.000203099', 'lastCheck': = '2.3', 'code': 0, 'valid': True, 'version': 0}, '272ec473-6041-42ee-bd1a-73= 2789dd18d4': {'delay': '0.000177334', 'lastCheck': '1.4', 'code': 0, 'valid= ': True, 'version': 3}}=0A= Thread-290102::DEBUG::2014-01-30 16:17:20,058::task::579::TaskManager.Task:= :(_updateState) Task=3D`0d381417-48c8-4035-99e5-01f34f55f98c`::moving from = state preparing -> state finished=0A= Thread-290102::DEBUG::2014-01-30 16:17:20,058::resourceManager::939::Resour= ceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}=0A= Thread-290102::DEBUG::2014-01-30 16:17:20,058::resourceManager::976::Resour= ceManager.Owner::(cancelAll) Owner.cancelAll requests {}=0A= Thread-290102::DEBUG::2014-01-30 16:17:20,059::task::974::TaskManager.Task:= :(_decref) Task=3D`0d381417-48c8-4035-99e5-01f34f55f98c`::ref 0 aborting Fa= lse=0A= Thread-289906::DEBUG::2014-01-30 16:17:22,908::task::579::TaskManager.Task:= :(_updateState) Task=3D`308ddd49-b5c0-43a5-93fc-ccfd6220eb28`::moving from = state init -> state preparing=0A= Thread-289906::INFO::2014-01-30 16:17:22,909::logUtils::44::dispatcher::(wr= apper) Run and protect: getVolumeSize(sdUUID=3D'965ca3b6-4f9c-4e81-b6e8-5ed= 4a9e58545', spUUID=3D'94ed7a19-fade-4bd6-83f2-2cbb2f730b95', imgUUID=3D'1b2= 3ac73-0748-49cd-94b6-11555e35be81', volUUID=3D'5156a43b-c9dc-40fa-a9b7-a35b= 7f22f0eb', options=3DNone)=0A= Thread-289906::INFO::2014-01-30 16:17:22,911::logUtils::47::dispatcher::(wr= apper) Run and protect: getVolumeSize, Return response: {'truesize': '17700= 114432', 'apparentsize': '21474836480'}=0A= Thread-289906::DEBUG::2014-01-30 16:17:22,911::task::1168::TaskManager.Task= ::(prepare) Task=3D`308ddd49-b5c0-43a5-93fc-ccfd6220eb28`::finished: {'true= size': '17700114432', 'apparentsize': '21474836480'}=0A= Thread-289906::DEBUG::2014-01-30 16:17:22,911::task::579::TaskManager.Task:= :(_updateState) Task=3D`308ddd49-b5c0-43a5-93fc-ccfd6220eb28`::moving from = state preparing -> state finished=0A= Thread-289906::DEBUG::2014-01-30 16:17:22,911::resourceManager::939::Resour= ceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}=0A= Thread-289906::DEBUG::2014-01-30 16:17:22,912::resourceManager::976::Resour= ceManager.Owner::(cancelAll) Owner.cancelAll requests {}=0A= Thread-289906::DEBUG::2014-01-30 16:17:22,912::task::974::TaskManager.Task:= :(_decref) Task=3D`308ddd49-b5c0-43a5-93fc-ccfd6220eb28`::ref 0 aborting Fa= lse=0A= Thread-25::DEBUG::2014-01-30 16:17:23,063::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-25::DEBUG::2014-01-30 16:17:23,069::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n645 b= ytes (645 B) copied, 0.000189592 s, 3.4 MB/s\n'; <rc> =3D 0=0A= VM Channels Listener::DEBUG::2014-01-30 16:17:23,109::vmChannels::91::vds::= (_handle_timeouts) Timeout on fileno 105.=0A= Thread-289929::WARNING::2014-01-30 16:17:25,588::vm::800::vm.Vm::(run) vmId= =3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Migration stalling: dataRemainin= g (15MiB) > smallest_dataRemaining (9MiB). Refer to RHBZ#919201.=0A= Thread-289929::INFO::2014-01-30 16:17:25,588::vm::812::vm.Vm::(run) vmId=3D= `ce64f528-9981-4ec6-a172-9d70a00a34cd`::Migration Progress: 380 seconds ela= psed, 99% of data processed, 99% of mem processed=0A= Thread-26::DEBUG::2014-01-30 16:17:26,940::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-26::DEBUG::2014-01-30 16:17:26,947::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.00019559 s, 2.8 MB/s\n'; <rc> =3D 0=0A= Thread-27::DEBUG::2014-01-30 16:17:27,430::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-27::DEBUG::2014-01-30 16:17:27,439::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n357 b= ytes (357 B) copied, 0.00317489 s, 112 kB/s\n'; <rc> =3D 0=0A= Thread-33::DEBUG::2014-01-30 16:17:27,808::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-33::DEBUG::2014-01-30 16:17:27,815::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n363 b= ytes (363 B) copied, 0.000189549 s, 1.9 MB/s\n'; <rc> =3D 0=0A= Thread-38::DEBUG::2014-01-30 16:17:28,621::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-38::DEBUG::2014-01-30 16:17:28,632::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.00469703 s, 119 kB/s\n'; <rc> =3D 0=0A= Thread-25::DEBUG::2014-01-30 16:17:33,081::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-25::DEBUG::2014-01-30 16:17:33,087::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n645 b= ytes (645 B) copied, 0.000191272 s, 3.4 MB/s\n'; <rc> =3D 0=0A= Thread-290108::DEBUG::2014-01-30 16:17:35,257::task::579::TaskManager.Task:= :(_updateState) Task=3D`c598fcf4-774b-4420-af70-090d43cd58b5`::moving from = state init -> state preparing=0A= Thread-290108::INFO::2014-01-30 16:17:35,257::logUtils::44::dispatcher::(wr= apper) Run and protect: repoStats(options=3DNone)=0A= Thread-290108::INFO::2014-01-30 16:17:35,257::logUtils::47::dispatcher::(wr= apper) Run and protect: repoStats, Return response: {'2c51d320-88ce-4f23-82= 15-e15f55f66906': {'delay': '0.000191272', 'lastCheck': '2.2', 'code': 0, '= valid': True, 'version': 3}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'dela= y': '0.00019559', 'lastCheck': '8.3', 'code': 0, 'valid': True, 'version': = 3}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'delay': '0.00317489', 'lastCh= eck': '7.8', 'code': 0, 'valid': True, 'version': 0}, '63041fa9-e093-4b44-b= 36f-f39f16d3974f': {'delay': '0.000189549', 'lastCheck': '7.4', 'code': 0, = 'valid': True, 'version': 0}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'del= ay': '0.00469703', 'lastCheck': '6.6', 'code': 0, 'valid': True, 'version':= 3}}=0A= Thread-290108::DEBUG::2014-01-30 16:17:35,258::task::1168::TaskManager.Task= ::(prepare) Task=3D`c598fcf4-774b-4420-af70-090d43cd58b5`::finished: {'2c51= d320-88ce-4f23-8215-e15f55f66906': {'delay': '0.000191272', 'lastCheck': '2= .2', 'code': 0, 'valid': True, 'version': 3}, '965ca3b6-4f9c-4e81-b6e8-5ed4= a9e58545': {'delay': '0.00019559', 'lastCheck': '8.3', 'code': 0, 'valid': = True, 'version': 3}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'delay': '0.0= 0317489', 'lastCheck': '7.8', 'code': 0, 'valid': True, 'version': 0}, '630= 41fa9-e093-4b44-b36f-f39f16d3974f': {'delay': '0.000189549', 'lastCheck': '= 7.4', 'code': 0, 'valid': True, 'version': 0}, '272ec473-6041-42ee-bd1a-732= 789dd18d4': {'delay': '0.00469703', 'lastCheck': '6.6', 'code': 0, 'valid':= True, 'version': 3}}=0A= Thread-290108::DEBUG::2014-01-30 16:17:35,258::task::579::TaskManager.Task:= :(_updateState) Task=3D`c598fcf4-774b-4420-af70-090d43cd58b5`::moving from = state preparing -> state finished=0A= Thread-290108::DEBUG::2014-01-30 16:17:35,258::resourceManager::939::Resour= ceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}=0A= Thread-290108::DEBUG::2014-01-30 16:17:35,258::resourceManager::976::Resour= ceManager.Owner::(cancelAll) Owner.cancelAll requests {}=0A= Thread-290108::DEBUG::2014-01-30 16:17:35,258::task::974::TaskManager.Task:= :(_decref) Task=3D`c598fcf4-774b-4420-af70-090d43cd58b5`::ref 0 aborting Fa= lse=0A= Thread-289929::WARNING::2014-01-30 16:17:35,590::vm::800::vm.Vm::(run) vmId= =3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Migration stalling: dataRemainin= g (33MiB) > smallest_dataRemaining (9MiB). Refer to RHBZ#919201.=0A= Thread-289929::INFO::2014-01-30 16:17:35,590::vm::812::vm.Vm::(run) vmId=3D= `ce64f528-9981-4ec6-a172-9d70a00a34cd`::Migration Progress: 390 seconds ela= psed, 99% of data processed, 99% of mem processed=0A= Thread-26::DEBUG::2014-01-30 16:17:36,959::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-26::DEBUG::2014-01-30 16:17:36,966::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.000212972 s, 2.6 MB/s\n'; <rc> =3D 0=0A= Thread-27::DEBUG::2014-01-30 16:17:37,450::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-27::DEBUG::2014-01-30 16:17:37,457::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n357 b= ytes (357 B) copied, 0.000199826 s, 1.8 MB/s\n'; <rc> =3D 0=0A= Thread-33::DEBUG::2014-01-30 16:17:37,826::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-33::DEBUG::2014-01-30 16:17:37,833::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n363 b= ytes (363 B) copied, 0.000200537 s, 1.8 MB/s\n'; <rc> =3D 0=0A= Thread-38::DEBUG::2014-01-30 16:17:38,644::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-38::DEBUG::2014-01-30 16:17:38,650::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.000206259 s, 2.7 MB/s\n'; <rc> =3D 0=0A= Thread-25::DEBUG::2014-01-30 16:17:43,099::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-25::DEBUG::2014-01-30 16:17:43,105::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n645 b= ytes (645 B) copied, 0.000187228 s, 3.4 MB/s\n'; <rc> =3D 0=0A= Thread-289929::WARNING::2014-01-30 16:17:45,592::vm::789::vm.Vm::(run) vmId= =3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Migration is stuck: Hasn't progr= essed in 300.055635929 seconds. Aborting.=0A= Thread-289929::DEBUG::2014-01-30 16:17:45,594::vm::815::vm.Vm::(stop) vmId= =3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::stopping migration monitor threa= d=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:45,918::vm::4840::vm.Vm::(_onLibv= irtLifecycleEvent) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::event Res= umed detail 1 opaque None=0A= Thread-289927::DEBUG::2014-01-30 16:17:45,920::libvirtconnection::108::libv= irtconnection::(wrapper) Unknown libvirterror: ecode: 78 edom: 10 level: 2 = message: Operation abgebrochen: Migrations-Job: abgebrochen durch Client=0A= Thread-289927::DEBUG::2014-01-30 16:17:45,920::vm::745::vm.Vm::(cancel) vmI= d=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::canceling migration downtime th= read=0A= Thread-289927::DEBUG::2014-01-30 16:17:45,920::vm::815::vm.Vm::(stop) vmId= =3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::stopping migration monitor threa= d=0A= Thread-289927::ERROR::2014-01-30 16:17:45,920::vm::238::vm.Vm::(_recover) v= mId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Operation abgebrochen: Migrat= ions-Job: abgebrochen durch Client=0A= Thread-289927::ERROR::2014-01-30 16:17:45,949::vm::337::vm.Vm::(run) vmId= =3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Failed to migrate=0A= Traceback (most recent call last):=0A= File "/usr/share/vdsm/vm.py", line 323, in run=0A= self._startUnderlyingMigration()=0A= File "/usr/share/vdsm/vm.py", line 400, in _startUnderlyingMigration=0A= None, maxBandwidth)=0A= File "/usr/share/vdsm/vm.py", line 838, in f=0A= ret =3D attr(*args, **kwargs)=0A= File "/usr/lib64/python2.7/site-packages/vdsm/libvirtconnection.py", line= 76, in wrapper=0A= ret =3D f(*args, **kwargs)=0A= File "/usr/lib64/python2.7/site-packages/libvirt.py", line 1274, in migra= teToURI2=0A= if ret =3D=3D -1: raise libvirtError ('virDomainMigrateToURI2() failed'= , dom=3Dself)=0A= libvirtError: Operation abgebrochen: Migrations-Job: abgebrochen durch Clie= nt=0A= Thread-26::DEBUG::2014-01-30 16:17:46,976::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-26::DEBUG::2014-01-30 16:17:46,982::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.000163843 s, 3.4 MB/s\n'; <rc> =3D 0=0A= Thread-290114::DEBUG::2014-01-30 16:17:47,444::BindingXMLRPC::974::vds::(wr= apper) client [192.168.11.2]::call vmGetStats with ('ce64f528-9981-4ec6-a17= 2-9d70a00a34cd',) {}=0A= Thread-290114::DEBUG::2014-01-30 16:17:47,445::BindingXMLRPC::981::vds::(wr= apper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 's= tatsList': [{'status': 'Up', 'username': 'Unknown', 'memUsage': '0', 'acpiE= nable': 'true', 'guestFQDN': '', 'pid': '14467', 'displayIp': '192.168.11.4= 2', 'displayPort': '-1', 'session': 'Unknown', 'displaySecurePort': u'5900'= , 'timeOffset': '0', 'hash': '3172497814970917300', 'balloonInfo': {'balloo= n_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-9= 981-4ec6-a172-9d70a00a34cd', 'displayType': 'qxl', 'cpuUser': '35.99', 'dis= ks': {u'hdc': {'readLatency': '0', 'apparentsize': '0', 'writeLatency': '0'= , 'flushLatency': '0', 'readRate': '0.00', 'truesize': '0', 'writeRate': '0= .00'}, u'sda': {'readLatency': '0', 'apparentsize': '21474836480', 'writeLa= tency': '2110228', 'imageID': '1b23ac73-0748-49cd-94b6-11555e35be81', 'flus= hLatency': '0', 'readRate': '0.00', 'truesize': '17700114432', 'writeRate':= '1640924.26'}}, 'monitorResponse': '0', 'statsAge': '0.49', 'elapsedTime':= '1235', 'vmType': 'kvm', 'cpuSys': '35.99', 'appsList': [], 'guestIPs': ''= }]}=0A= Thread-27::DEBUG::2014-01-30 16:17:47,468::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-27::DEBUG::2014-01-30 16:17:47,474::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n357 b= ytes (357 B) copied, 0.000176178 s, 2.0 MB/s\n'; <rc> =3D 0=0A= Thread-290115::DEBUG::2014-01-30 16:17:47,493::BindingXMLRPC::974::vds::(wr= apper) client [192.168.11.2]::call vmGetMigrationStatus with ('ce64f528-998= 1-4ec6-a172-9d70a00a34cd',) {}=0A= Thread-290115::DEBUG::2014-01-30 16:17:47,493::BindingXMLRPC::981::vds::(wr= apper) return vmGetMigrationStatus with {'status': {'message': 'Migration c= anceled', 'code': 47}, 'progress': 99}=0A= Thread-33::DEBUG::2014-01-30 16:17:47,845::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-33::DEBUG::2014-01-30 16:17:47,851::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n363 b= ytes (363 B) copied, 0.000191543 s, 1.9 MB/s\n'; <rc> =3D 0=0A= Thread-38::DEBUG::2014-01-30 16:17:48,662::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-38::DEBUG::2014-01-30 16:17:48,668::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.000225105 s, 2.5 MB/s\n'; <rc> =3D 0=0A= Thread-290116::DEBUG::2014-01-30 16:17:50,490::task::579::TaskManager.Task:= :(_updateState) Task=3D`cd241aee-e845-4143-bfe3-01383c65e90e`::moving from = state init -> state preparing=0A= Thread-290116::INFO::2014-01-30 16:17:50,490::logUtils::44::dispatcher::(wr= apper) Run and protect: repoStats(options=3DNone)=0A= =0A= **************************=0A= vdsm_target:=0A= =0A= Thread-285228::DEBUG::2014-01-30 16:17:07,460::vm::684::vm.Vm::(_getDiskLat= ency) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk hdc latency not a= vailable=0A= Thread-285228::DEBUG::2014-01-30 16:17:07,460::vm::684::vm.Vm::(_getDiskLat= ency) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk sda latency not a= vailable=0A= Thread-285228::DEBUG::2014-01-30 16:17:07,461::BindingXMLRPC::981::vds::(wr= apper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 's= tatsList': [{'status': 'Paused', 'username': 'Unknown', 'memUsage': '0', 'a= cpiEnable': 'true', 'guestFQDN': '', 'pid': '7671', 'displayIp': '192.168.1= 1.44', 'displayPort': '-1', 'session': 'Unknown', 'displaySecurePort': u'59= 00', 'timeOffset': '0', 'hash': '7219603903902024642', 'balloonInfo': {'bal= loon_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': 'ce64f52= 8-9981-4ec6-a172-9d70a00a34cd', 'displayType': 'qxl', 'cpuUser': '0.38', 'd= isks': {u'hdc': {'truesize': '0', 'apparentsize': '0'}, u'sda': {'truesize'= : '17700114432', 'apparentsize': '21474836480', 'imageID': '1b23ac73-0748-4= 9cd-94b6-11555e35be81'}}, 'monitorResponse': '0', 'statsAge': '0.44', 'elap= sedTime': '1212', 'vmType': 'kvm', 'cpuSys': '2.07', 'appsList': [], 'guest= IPs': ''}]}=0A= Thread-40::DEBUG::2014-01-30 16:17:07,811::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-40::DEBUG::2014-01-30 16:17:07,818::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n645 b= ytes (645 B) copied, 0.000160605 s, 4.0 MB/s\n'; <rc> =3D 0=0A= Thread-42::DEBUG::2014-01-30 16:17:08,363::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-42::DEBUG::2014-01-30 16:17:08,369::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n357 b= ytes (357 B) copied, 0.000144136 s, 2.5 MB/s\n'; <rc> =3D 0=0A= Thread-47::DEBUG::2014-01-30 16:17:10,080::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-47::DEBUG::2014-01-30 16:17:10,086::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n363 b= ytes (363 B) copied, 0.000213518 s, 1.7 MB/s\n'; <rc> =3D 0=0A= Thread-285230::DEBUG::2014-01-30 16:17:10,569::BindingXMLRPC::974::vds::(wr= apper) client [192.168.11.2]::call vmGetStats with ('ce64f528-9981-4ec6-a17= 2-9d70a00a34cd',) {}=0A= Thread-285230::DEBUG::2014-01-30 16:17:10,569::vm::645::vm.Vm::(_getDiskSta= ts) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk hdc stats not avail= able=0A= Thread-285230::DEBUG::2014-01-30 16:17:10,569::vm::645::vm.Vm::(_getDiskSta= ts) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk sda stats not avail= able=0A= Thread-285230::DEBUG::2014-01-30 16:17:10,569::vm::684::vm.Vm::(_getDiskLat= ency) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk hdc latency not a= vailable=0A= Thread-285230::DEBUG::2014-01-30 16:17:10,570::vm::684::vm.Vm::(_getDiskLat= ency) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk sda latency not a= vailable=0A= Thread-285230::DEBUG::2014-01-30 16:17:10,571::BindingXMLRPC::981::vds::(wr= apper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 's= tatsList': [{'status': 'Paused', 'username': 'Unknown', 'memUsage': '0', 'a= cpiEnable': 'true', 'guestFQDN': '', 'pid': '7671', 'displayIp': '192.168.1= 1.44', 'displayPort': '-1', 'session': 'Unknown', 'displaySecurePort': u'59= 00', 'timeOffset': '0', 'hash': '7219603903902024642', 'balloonInfo': {'bal= loon_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': 'ce64f52= 8-9981-4ec6-a172-9d70a00a34cd', 'displayType': 'qxl', 'cpuUser': '0.38', 'd= isks': {u'hdc': {'truesize': '0', 'apparentsize': '0'}, u'sda': {'truesize'= : '17700114432', 'apparentsize': '21474836480', 'imageID': '1b23ac73-0748-4= 9cd-94b6-11555e35be81'}}, 'monitorResponse': '0', 'statsAge': '1.55', 'elap= sedTime': '1215', 'vmType': 'kvm', 'cpuSys': '2.07', 'appsList': [], 'guest= IPs': ''}]}=0A= Thread-41::DEBUG::2014-01-30 16:17:11,570::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-41::DEBUG::2014-01-30 16:17:11,577::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.000211434 s, 2.6 MB/s\n'; <rc> =3D 0=0A= Thread-285232::DEBUG::2014-01-30 16:17:13,656::BindingXMLRPC::974::vds::(wr= apper) client [192.168.11.2]::call vmGetStats with ('ce64f528-9981-4ec6-a17= 2-9d70a00a34cd',) {}=0A= Thread-285232::DEBUG::2014-01-30 16:17:13,656::vm::645::vm.Vm::(_getDiskSta= ts) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk hdc stats not avail= able=0A= Thread-285232::DEBUG::2014-01-30 16:17:13,657::vm::645::vm.Vm::(_getDiskSta= ts) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk sda stats not avail= able=0A= Thread-285232::DEBUG::2014-01-30 16:17:13,657::vm::684::vm.Vm::(_getDiskLat= ency) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk hdc latency not a= vailable=0A= Thread-285232::DEBUG::2014-01-30 16:17:13,657::vm::684::vm.Vm::(_getDiskLat= ency) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk sda latency not a= vailable=0A= Thread-285232::DEBUG::2014-01-30 16:17:13,658::BindingXMLRPC::981::vds::(wr= apper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 's= tatsList': [{'status': 'Paused', 'username': 'Unknown', 'memUsage': '0', 'a= cpiEnable': 'true', 'guestFQDN': '', 'pid': '7671', 'displayIp': '192.168.1= 1.44', 'displayPort': '-1', 'session': 'Unknown', 'displaySecurePort': u'59= 00', 'timeOffset': '0', 'hash': '7219603903902024642', 'balloonInfo': {'bal= loon_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': 'ce64f52= 8-9981-4ec6-a172-9d70a00a34cd', 'displayType': 'qxl', 'cpuUser': '0.38', 'd= isks': {u'hdc': {'truesize': '0', 'apparentsize': '0'}, u'sda': {'truesize'= : '17700114432', 'apparentsize': '21474836480', 'imageID': '1b23ac73-0748-4= 9cd-94b6-11555e35be81'}}, 'monitorResponse': '0', 'statsAge': '0.63', 'elap= sedTime': '1218', 'vmType': 'kvm', 'cpuSys': '2.07', 'appsList': [], 'guest= IPs': ''}]}=0A= Thread-52::DEBUG::2014-01-30 16:17:14,494::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-52::DEBUG::2014-01-30 16:17:14,501::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.000228157 s, 2.4 MB/s\n'; <rc> =3D 0=0A= Thread-285233::DEBUG::2014-01-30 16:17:16,719::task::579::TaskManager.Task:= :(_updateState) Task=3D`3b433b6a-d9ed-4edc-adcc-b9994ba7877a`::moving from = state init -> state preparing=0A= Thread-285233::INFO::2014-01-30 16:17:16,720::logUtils::44::dispatcher::(wr= apper) Run and protect: repoStats(options=3DNone)=0A= Thread-285233::INFO::2014-01-30 16:17:16,720::logUtils::47::dispatcher::(wr= apper) Run and protect: repoStats, Return response: {'2c51d320-88ce-4f23-82= 15-e15f55f66906': {'delay': '0.000160605', 'lastCheck': '8.9', 'code': 0, '= valid': True, 'version': 3}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'dela= y': '0.000211434', 'lastCheck': '5.1', 'code': 0, 'valid': True, 'version':= 3}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'delay': '0.000144136', 'last= Check': '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': {'d= elay': '0.000228157', 'lastCheck': '2.2', 'code': 0, 'valid': True, 'versio= n': 3}}=0A= Thread-285233::DEBUG::2014-01-30 16:17:16,720::task::1168::TaskManager.Task= ::(prepare) Task=3D`3b433b6a-d9ed-4edc-adcc-b9994ba7877a`::finished: {'2c51= d320-88ce-4f23-8215-e15f55f66906': {'delay': '0.000160605', 'lastCheck': '8= .9', 'code': 0, 'valid': True, 'version': 3}, '965ca3b6-4f9c-4e81-b6e8-5ed4= a9e58545': {'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}, '6= 3041fa9-e093-4b44-b36f-f39f16d3974f': {'delay': '0.000213518', 'lastCheck':= '6.6', 'code': 0, 'valid': True, 'version': 0}, '272ec473-6041-42ee-bd1a-7= 32789dd18d4': {'delay': '0.000228157', 'lastCheck': '2.2', 'code': 0, 'vali= d': True, 'version': 3}}=0A= Thread-285233::DEBUG::2014-01-30 16:17:16,720::task::579::TaskManager.Task:= :(_updateState) Task=3D`3b433b6a-d9ed-4edc-adcc-b9994ba7877a`::moving from = state preparing -> state finished=0A= Thread-285233::DEBUG::2014-01-30 16:17:16,720::resourceManager::939::Resour= ceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}=0A= Thread-285233::DEBUG::2014-01-30 16:17:16,721::resourceManager::976::Resour= ceManager.Owner::(cancelAll) Owner.cancelAll requests {}=0A= Thread-285233::DEBUG::2014-01-30 16:17:16,721::task::974::TaskManager.Task:= :(_decref) Task=3D`3b433b6a-d9ed-4edc-adcc-b9994ba7877a`::ref 0 aborting Fa= lse=0A= Thread-285234::DEBUG::2014-01-30 16:17:16,733::vm::645::vm.Vm::(_getDiskSta= ts) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk hdc stats not avail= able=0A= Thread-285234::DEBUG::2014-01-30 16:17:16,733::vm::645::vm.Vm::(_getDiskSta= ts) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk sda stats not avail= able=0A= Thread-285234::DEBUG::2014-01-30 16:17:16,733::vm::684::vm.Vm::(_getDiskLat= ency) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk hdc latency not a= vailable=0A= Thread-285234::DEBUG::2014-01-30 16:17:16,733::vm::684::vm.Vm::(_getDiskLat= ency) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk sda latency not a= vailable=0A= Thread-40::DEBUG::2014-01-30 16:17:17,821::domainMonitor::182::Storage.Doma= inMonitorThread::(_monitorDomain) Refreshing domain 2c51d320-88ce-4f23-8215= -e15f55f66906=0A= Thread-40::DEBUG::2014-01-30 16:17:17,834::fileSD::154::Storage.StorageDoma= in::(__init__) Reading domain in path /rhev/data-center/mnt/10.10.30.253:_v= ar_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906=0A= Thread-40::DEBUG::2014-01-30 16:17:17,835::persistentDict::192::Storage.Per= sistentDict::(__init__) Created a persistent dict with FileMetadataRW backe= nd=0A= Thread-40::DEBUG::2014-01-30 16:17:17,842::persistentDict::234::Storage.Per= sistentDict::(refresh) read lines (FileMetadataRW)=3D['CLASS=3DData', 'DESC= RIPTION=3Dcolnas03_IB', 'IOOPTIMEOUTSEC=3D10', 'LEASERETRIES=3D3', 'LEASETI= MESEC=3D60', 'LOCKPOLICY=3D', 'LOCKRENEWALINTERVALSEC=3D5', 'MASTER_VERSION= =3D3', 'POOL_DESCRIPTION=3DCollogia', 'POOL_DOMAINS=3D272ec473-6041-42ee-bd= 1a-732789dd18d4:Active,965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545:Active,2c51d320= -88ce-4f23-8215-e15f55f66906:Active,63041fa9-e093-4b44-b36f-f39f16d3974f:Ac= tive,bff3a2be-fdd9-4e37-b416-fa4ef7fafba2:Active', 'POOL_SPM_ID=3D2', 'POOL= _SPM_LVER=3D33', 'POOL_UUID=3D94ed7a19-fade-4bd6-83f2-2cbb2f730b95', 'REMOT= E_PATH=3D10.10.30.253:/var/nas3/OVirtIB', 'ROLE=3DMaster', 'SDUUID=3D2c51d3= 20-88ce-4f23-8215-e15f55f66906', 'TYPE=3DNFS', 'VERSION=3D3', '_SHA_CKSUM= =3D75ca15b219476f472d87a8c375650d35eabb8d16']=0A= Thread-40::DEBUG::2014-01-30 16:17:17,843::fileSD::572::Storage.StorageDoma= in::(imageGarbageCollector) Removing remnants of deleted images []=0A= Thread-40::INFO::2014-01-30 16:17:17,844::sd::374::Storage.StorageDomain::(= _registerResourceNamespaces) Resource namespace 2c51d320-88ce-4f23-8215-e15= f55f66906_imageNS already registered=0A= Thread-40::INFO::2014-01-30 16:17:17,844::sd::382::Storage.StorageDomain::(= _registerResourceNamespaces) Resource namespace 2c51d320-88ce-4f23-8215-e15= f55f66906_volumeNS already registered=0A= Thread-40::DEBUG::2014-01-30 16:17:17,854::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-40::DEBUG::2014-01-30 16:17:17,860::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n645 b= ytes (645 B) copied, 0.000216469 s, 3.0 MB/s\n'; <rc> =3D 0=0A= Thread-42::DEBUG::2014-01-30 16:17:18,381::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-42::DEBUG::2014-01-30 16:17:18,387::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n357 b= ytes (357 B) copied, 0.000243463 s, 1.5 MB/s\n'; <rc> =3D 0=0A= Thread-285241::DEBUG::2014-01-30 16:17:19,814::BindingXMLRPC::974::vds::(wr= apper) client [192.168.11.2]::call vmGetStats with ('ce64f528-9981-4ec6-a17= 2-9d70a00a34cd',) {}=0A= Thread-285241::DEBUG::2014-01-30 16:17:19,815::vm::645::vm.Vm::(_getDiskSta= ts) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk hdc stats not avail= able=0A= Thread-285241::DEBUG::2014-01-30 16:17:19,815::vm::645::vm.Vm::(_getDiskSta= ts) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk sda stats not avail= able=0A= Thread-285241::DEBUG::2014-01-30 16:17:19,815::vm::684::vm.Vm::(_getDiskLat= ency) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk hdc latency not a= vailable=0A= Thread-285241::DEBUG::2014-01-30 16:17:19,815::vm::684::vm.Vm::(_getDiskLat= ency) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk sda latency not a= vailable=0A= Thread-285241::DEBUG::2014-01-30 16:17:19,816::BindingXMLRPC::981::vds::(wr= apper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 's= tatsList': [{'status': 'Paused', 'username': 'Unknown', 'memUsage': '0', 'a= cpiEnable': 'true', 'guestFQDN': '', 'pid': '7671', 'displayIp': '192.168.1= 1.44', 'displayPort': '-1', 'session': 'Unknown', 'displaySecurePort': u'59= 00', 'timeOffset': '0', 'hash': '7219603903902024642', 'balloonInfo': {'bal= loon_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': 'ce64f52= 8-9981-4ec6-a172-9d70a00a34cd', 'displayType': 'qxl', 'cpuUser': '0.44', 'd= isks': {u'hdc': {'truesize': '0', 'apparentsize': '0'}, u'sda': {'truesize'= : '17700114432', 'apparentsize': '21474836480', 'imageID': '1b23ac73-0748-4= 9cd-94b6-11555e35be81'}}, 'monitorResponse': '0', 'statsAge': '0.78', 'elap= sedTime': '1224', 'vmType': 'kvm', 'cpuSys': '1.93', 'appsList': [], 'guest= IPs': ''}]}=0A= VM Channels Listener::DEBUG::2014-01-30 16:17:20,026::vmChannels::91::vds::= (_handle_timeouts) Timeout on fileno 98.=0A= Thread-47::DEBUG::2014-01-30 16:17:20,096::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-47::DEBUG::2014-01-30 16:17:20,103::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n363 b= ytes (363 B) copied, 0.00022031 s, 1.6 MB/s\n'; <rc> =3D 0=0A= Thread-41::DEBUG::2014-01-30 16:17:21,589::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-41::DEBUG::2014-01-30 16:17:21,596::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.0002126 s, 2.6 MB/s\n'; <rc> =3D 0=0A= Thread-285243::DEBUG::2014-01-30 16:17:22,928::BindingXMLRPC::974::vds::(wr= apper) client [192.168.11.2]::call vmGetStats with ('ce64f528-9981-4ec6-a17= 2-9d70a00a34cd',) {}=0A= Thread-285243::DEBUG::2014-01-30 16:17:22,928::vm::645::vm.Vm::(_getDiskSta= ts) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk hdc stats not avail= able=0A= Thread-285243::DEBUG::2014-01-30 16:17:22,928::vm::645::vm.Vm::(_getDiskSta= ts) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk sda stats not avail= able=0A= Thread-285243::DEBUG::2014-01-30 16:17:22,928::vm::684::vm.Vm::(_getDiskLat= ency) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk hdc latency not a= vailable=0A= Thread-285243::DEBUG::2014-01-30 16:17:22,929::vm::684::vm.Vm::(_getDiskLat= ency) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk sda latency not a= vailable=0A= Thread-285243::DEBUG::2014-01-30 16:17:22,930::BindingXMLRPC::981::vds::(wr= apper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 's= tatsList': [{'status': 'Paused', 'username': 'Unknown', 'memUsage': '0', 'a= cpiEnable': 'true', 'guestFQDN': '', 'pid': '7671', 'displayIp': '192.168.1= 1.44', 'displayPort': '-1', 'session': 'Unknown', 'displaySecurePort': u'59= 00', 'timeOffset': '0', 'hash': '7219603903902024642', 'balloonInfo': {'bal= loon_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': 'ce64f52= 8-9981-4ec6-a172-9d70a00a34cd', 'displayType': 'qxl', 'cpuUser': '0.44', 'd= isks': {u'hdc': {'truesize': '0', 'apparentsize': '0'}, u'sda': {'truesize'= : '17700114432', 'apparentsize': '21474836480', 'imageID': '1b23ac73-0748-4= 9cd-94b6-11555e35be81'}}, 'monitorResponse': '0', 'statsAge': '1.88', 'elap= sedTime': '1227', 'vmType': 'kvm', 'cpuSys': '1.93', 'appsList': [], 'guest= IPs': ''}]}=0A= Thread-52::DEBUG::2014-01-30 16:17:24,512::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-52::DEBUG::2014-01-30 16:17:24,519::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.000195213 s, 2.9 MB/s\n'; <rc> =3D 0=0A= Thread-285245::DEBUG::2014-01-30 16:17:26,006::BindingXMLRPC::974::vds::(wr= apper) client [192.168.11.2]::call vmGetStats with ('ce64f528-9981-4ec6-a17= 2-9d70a00a34cd',) {}=0A= Thread-285245::DEBUG::2014-01-30 16:17:26,006::vm::645::vm.Vm::(_getDiskSta= ts) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk hdc stats not avail= able=0A= Thread-285245::DEBUG::2014-01-30 16:17:26,006::vm::645::vm.Vm::(_getDiskSta= ts) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk sda stats not avail= able=0A= Thread-285245::DEBUG::2014-01-30 16:17:26,007::vm::684::vm.Vm::(_getDiskLat= ency) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk hdc latency not a= vailable=0A= Thread-285245::DEBUG::2014-01-30 16:17:26,007::vm::684::vm.Vm::(_getDiskLat= ency) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk sda latency not a= vailable=0A= Thread-285245::DEBUG::2014-01-30 16:17:26,008::BindingXMLRPC::981::vds::(wr= apper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 's= tatsList': [{'status': 'Paused', 'username': 'Unknown', 'memUsage': '0', 'a= cpiEnable': 'true', 'guestFQDN': '', 'pid': '7671', 'displayIp': '192.168.1= 1.44', 'displayPort': '-1', 'session': 'Unknown', 'displaySecurePort': u'59= 00', 'timeOffset': '0', 'hash': '7219603903902024642', 'balloonInfo': {'bal= loon_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': 'ce64f52= 8-9981-4ec6-a172-9d70a00a34cd', 'displayType': 'qxl', 'cpuUser': '0.44', 'd= isks': {u'hdc': {'truesize': '0', 'apparentsize': '0'}, u'sda': {'truesize'= : '17700114432', 'apparentsize': '21474836480', 'imageID': '1b23ac73-0748-4= 9cd-94b6-11555e35be81'}}, 'monitorResponse': '0', 'statsAge': '0.95', 'elap= sedTime': '1230', 'vmType': 'kvm', 'cpuSys': '1.93', 'appsList': [], 'guest= IPs': ''}]}=0A= Thread-40::DEBUG::2014-01-30 16:17:27,875::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-40::DEBUG::2014-01-30 16:17:27,881::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n645 b= ytes (645 B) copied, 0.000195778 s, 3.3 MB/s\n'; <rc> =3D 0=0A= Thread-42::DEBUG::2014-01-30 16:17:28,399::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-42::DEBUG::2014-01-30 16:17:28,406::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n357 b= ytes (357 B) copied, 0.00021875 s, 1.6 MB/s\n'; <rc> =3D 0=0A= Thread-285247::DEBUG::2014-01-30 16:17:29,119::BindingXMLRPC::974::vds::(wr= apper) client [192.168.11.2]::call vmGetStats with ('ce64f528-9981-4ec6-a17= 2-9d70a00a34cd',) {}=0A= Thread-285247::DEBUG::2014-01-30 16:17:29,119::vm::645::vm.Vm::(_getDiskSta= ts) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk hdc stats not avail= able=0A= Thread-285247::DEBUG::2014-01-30 16:17:29,119::vm::645::vm.Vm::(_getDiskSta= ts) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk sda stats not avail= able=0A= Thread-285247::DEBUG::2014-01-30 16:17:29,119::vm::684::vm.Vm::(_getDiskLat= ency) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk hdc latency not a= vailable=0A= Thread-285247::DEBUG::2014-01-30 16:17:29,120::vm::684::vm.Vm::(_getDiskLat= ency) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk sda latency not a= vailable=0A= Thread-285247::DEBUG::2014-01-30 16:17:29,121::BindingXMLRPC::981::vds::(wr= apper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 's= tatsList': [{'status': 'Paused', 'username': 'Unknown', 'memUsage': '0', 'a= cpiEnable': 'true', 'guestFQDN': '', 'pid': '7671', 'displayIp': '192.168.1= 1.44', 'displayPort': '-1', 'session': 'Unknown', 'displaySecurePort': u'59= 00', 'timeOffset': '0', 'hash': '7219603903902024642', 'balloonInfo': {'bal= loon_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': 'ce64f52= 8-9981-4ec6-a172-9d70a00a34cd', 'displayType': 'qxl', 'cpuUser': '0.44', 'd= isks': {u'hdc': {'truesize': '0', 'apparentsize': '0'}, u'sda': {'truesize'= : '17700114432', 'apparentsize': '21474836480', 'imageID': '1b23ac73-0748-4= 9cd-94b6-11555e35be81'}}, 'monitorResponse': '0', 'statsAge': '0.07', 'elap= sedTime': '1233', 'vmType': 'kvm', 'cpuSys': '1.93', 'appsList': [], 'guest= IPs': ''}]}=0A= VM Channels Listener::ERROR::2014-01-30 16:17:29,729::vmChannels::53::vds::= (_handle_event) Received 00000019 on fileno 98=0A= VM Channels Listener::DEBUG::2014-01-30 16:17:29,729::vmChannels::128::vds:= :(_handle_unconnected) Trying to connect fileno 98.=0A= VM Channels Listener::DEBUG::2014-01-30 16:17:29,730::guestIF::147::vm.Vm::= (_connect) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Attempting connec= tion to /var/lib/libvirt/qemu/channels/ce64f528-9981-4ec6-a172-9d70a00a34cd= .com.redhat.rhevm.vdsm=0A= VM Channels Listener::DEBUG::2014-01-30 16:17:29,730::guestIF::158::vm.Vm::= (_connect) vmId=3D`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=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,770::vm::4840::vm.Vm::(_onLibv= irtLifecycleEvent) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::event Sto= pped detail 5 opaque None=0A= libvirtEventLoop::INFO::2014-01-30 16:17:29,770::vm::2166::vm.Vm::(_onQemuD= eath) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::underlying process dis= connected=0A= libvirtEventLoop::INFO::2014-01-30 16:17:29,770::vm::4320::vm.Vm::(releaseV= m) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Release VM resources=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,775::libvirtconnection::108::l= ibvirtconnection::(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)=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,776::sampling::292::vm.Vm::(st= op) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Stop statistics collecti= on=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,776::vmChannels::205::vds::(un= register) Delete fileno 98 from listener.=0A= Thread-285161::DEBUG::2014-01-30 16:17:29,776::sampling::323::vm.Vm::(run) = vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Stats thread finished=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,777::libvirtconnection::108::l= ibvirtconnection::(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)=0A= libvirtEventLoop::WARNING::2014-01-30 16:17:29,777::clientIF::362::vds::(te= ardownVolumePath) Drive is not a vdsm image: VOLWM_CHUNK_MB:1024 VOLWM_CHUN= K_REPLICATE_MULT:2 VOLWM_FREE_PCT:50 _blockDev:False _checkIoTuneCategories= :<bound method Drive._checkIoTuneCategories of <vm.Drive object at 0x7f3560= 03bb90>> _customize:<bound method Drive._customize of <vm.Drive object at 0= x7f356003bb90>> _deviceXML:<disk device=3D"cdrom" type=3D"file">=0A= <driver name=3D"qemu" type=3D"raw"/>=0A= <source startupPolicy=3D"optional"/>=0A= <target bus=3D"ide" dev=3D"hdc"/>=0A= <readonly/>=0A= <serial/>=0A= <alias name=3D"ide0-1-0"/>=0A= <address bus=3D"1" controller=3D"0" target=3D"0" type=3D"drive" unit= =3D"0"/>=0A= </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>> addres= s:{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': 'tru= e', 'displaySecurePort': u'5900', 'timeOffset': '0', 'cpuType': 'Nehalem', = 'smp': '2', 'custom': {'device_aff6efaa-b33b-4385-a311-0c770cf56cf2device_3= 073f208-c700-4b39-99f1-56c33e884c78device_0c7f4f0b-98d4-4a1a-934e-6210ecabd= 3e9device_50fb5c9c-d9b3-4422-b216-3ff71ac6d774device_bb8234b4-44d4-4086-906= c-744b572ddbd9': 'VmDevice {vmId=3Dce64f528-9981-4ec6-a172-9d70a00a34cd, de= viceId=3Dbb8234b4-44d4-4086-906c-744b572ddbd9, device=3Dspicevmc, type=3DCH= ANNEL, bootOrder=3D0, specParams=3D{}, address=3D{port=3D3, bus=3D0, contro= ller=3D0, type=3Dvirtio-serial}, managed=3Dfalse, plugged=3Dtrue, readOnly= =3Dfalse, deviceAlias=3Dchannel2, customProperties=3D{}, snapshotId=3Dnull}= ', 'device_aff6efaa-b33b-4385-a311-0c770cf56cf2device_3073f208-c700-4b39-99= f1-56c33e884c78': 'VmDevice {vmId=3Dce64f528-9981-4ec6-a172-9d70a00a34cd, d= eviceId=3D3073f208-c700-4b39-99f1-56c33e884c78, device=3Dvirtio-serial, typ= e=3DCONTROLLER, bootOrder=3D0, specParams=3D{}, address=3D{bus=3D0x00, doma= in=3D0x0000, type=3Dpci, slot=3D0x06, function=3D0x0}, managed=3Dfalse, plu= gged=3Dtrue, readOnly=3Dfalse, deviceAlias=3Dvirtio-serial0, customProperti= es=3D{}, snapshotId=3Dnull}', 'device_aff6efaa-b33b-4385-a311-0c770cf56cf2d= evice_3073f208-c700-4b39-99f1-56c33e884c78device_0c7f4f0b-98d4-4a1a-934e-62= 10ecabd3e9device_50fb5c9c-d9b3-4422-b216-3ff71ac6d774': 'VmDevice {vmId=3Dc= e64f528-9981-4ec6-a172-9d70a00a34cd, deviceId=3D50fb5c9c-d9b3-4422-b216-3ff= 71ac6d774, device=3Dunix, type=3DCHANNEL, bootOrder=3D0, specParams=3D{}, a= ddress=3D{port=3D2, bus=3D0, controller=3D0, type=3Dvirtio-serial}, managed= =3Dfalse, plugged=3Dtrue, readOnly=3Dfalse, deviceAlias=3Dchannel1, customP= roperties=3D{}, snapshotId=3Dnull}', 'sap_agent': 'false', 'device_aff6efaa= -b33b-4385-a311-0c770cf56cf2': 'VmDevice {vmId=3Dce64f528-9981-4ec6-a172-9d= 70a00a34cd, deviceId=3Daff6efaa-b33b-4385-a311-0c770cf56cf2, device=3Dide, = type=3DCONTROLLER, bootOrder=3D0, specParams=3D{}, address=3D{bus=3D0x00, d= omain=3D0x0000, type=3Dpci, slot=3D0x01, function=3D0x1}, managed=3Dfalse, = plugged=3Dtrue, readOnly=3Dfalse, deviceAlias=3Dide0, customProperties=3D{}= , snapshotId=3Dnull}', 'device_aff6efaa-b33b-4385-a311-0c770cf56cf2device_3= 073f208-c700-4b39-99f1-56c33e884c78device_0c7f4f0b-98d4-4a1a-934e-6210ecabd= 3e9': 'VmDevice {vmId=3Dce64f528-9981-4ec6-a172-9d70a00a34cd, deviceId=3D0c= 7f4f0b-98d4-4a1a-934e-6210ecabd3e9, device=3Dunix, type=3DCHANNEL, bootOrde= r=3D0, specParams=3D{}, address=3D{port=3D1, bus=3D0, controller=3D0, type= =3Dvirtio-serial}, managed=3Dfalse, plugged=3Dtrue, readOnly=3Dfalse, devic= eAlias=3Dchannel0, customProperties=3D{}, snapshotId=3Dnull}'}, 'vmType': '= kvm', 'spiceSslCipherSuite': 'DEFAULT', 'memSize': 2048, 'vmName': 'Win7x64= _Master', 'nice': '0', 'clientIp': '', 'vmId': 'ce64f528-9981-4ec6-a172-9d7= 0a00a34cd', 'displayIp': '192.168.11.44', 'keyboardLayout': 'de', 'displayP= ort': '-1', 'smartcardEnable': 'false', 'spiceSecureChannels': 'smain,sinpu= ts,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', 'nicModel': 'r= tl8139,pv', 'smpCoresPerSocket': '2', 'kvmEnable': 'true', 'displayNetwork'= : 'ovirtmgmt', 'devices': [{'device': 'unix', 'alias': 'channel0', 'type': = 'channel', 'address': {'bus': '0', 'controller': '0', 'type': 'virtio-seria= l', 'port': '1'}}, {'device': 'unix', 'alias': 'channel1', 'type': 'channel= ', 'address': {'bus': '0', 'controller': '0', 'type': 'virtio-serial', 'por= t': '2'}}, {'device': 'spicevmc', 'alias': 'channel2', 'type': 'channel', '= address': {'bus': '0', 'controller': '0', 'type': 'virtio-serial', 'port': = '3'}}, {'specParams': {}, 'alias': u'scsi0', 'deviceId': '294da3e7-42c8-487= 2-918c-cafa13cec438', 'address': {u'slot': u'0x04', u'bus': u'0x00', u'doma= in': u'0x0000', u'type': u'pci', u'function': u'0x0'}, 'device': 'scsi', 'm= odel': 'virtio-scsi', 'type': 'controller'}, {'device': 'usb', 'alias': u'u= sb0', 'type': 'controller', 'address': {u'slot': u'0x01', u'bus': u'0x00', = u'domain': u'0x0000', u'type': u'pci', u'function': u'0x2'}}, {'device': 'i= de', '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': 'contro= ller', '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-889d4= 9672122', 'address': {'slot': '0x02', 'bus': '0x00', 'domain': '0x0000', 't= ype': 'pci', 'function': '0x0'}, 'device': 'qxl', 'type': 'video'}, {'nicMo= del': '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's= lot': u'0x03', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'fu= nction': u'0x0'}, 'device': 'bridge', 'type': 'interface', 'name': u'vnet0'= }, {'index': '2', 'iface': 'ide', 'name': u'hdc', 'alias': u'ide0-1-0', 'sp= ecParams': {'path': ''}, 'readonly': 'True', 'deviceId': '6aad5e48-613b-48d= b-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'controll= er': 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': 'Fals= e', 'shared': 'false', 'truesize': '17698430976', 'type': 'disk', 'domainID= ': '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545', 'volumeInfo': {'domainID': '965c= a3b6-4f9c-4e81-b6e8-5ed4a9e58545', 'volType': 'path', 'leaseOffset': 0, 'pa= th': '/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e= 81-b6e8-5ed4a9e58545/images/1b23ac73-0748-49cd-94b6-11555e35be81/5156a43b-c= 9dc-40fa-a9b7-a35b7f22f0eb', 'volumeID': '5156a43b-c9dc-40fa-a9b7-a35b7f22f= 0eb', 'leasePath': '/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/96= 5ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/images/1b23ac73-0748-49cd-94b6-11555e35b= e81/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', 'devi= ce': 'disk', 'path': '/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/= 965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/images/1b23ac73-0748-49cd-94b6-11555e3= 5be81/5156a43b-c9dc-40fa-a9b7-a35b7f22f0eb', 'propagateErrors': 'off', 'opt= ional': 'false', 'name': u'sda', 'bootOrder': u'1', 'volumeID': '5156a43b-c= 9dc-40fa-a9b7-a35b7f22f0eb', 'alias': u'scsi0-0-0-0', 'volumeChain': [{'dom= ainID': '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545', 'volType': 'path', 'leaseOf= fset': 0, 'path': '/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965= ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/images/1b23ac73-0748-49cd-94b6-11555e35be= 81/5156a43b-c9dc-40fa-a9b7-a35b7f22f0eb', 'volumeID': '5156a43b-c9dc-40fa-a= 9b7-a35b7f22f0eb', 'leasePath': '/rhev/data-center/mnt/10.10.30.251:_var_na= s1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/images/1b23ac73-0748-49cd-9= 4b6-11555e35be81/5156a43b-c9dc-40fa-a9b7-a35b7f22f0eb.lease', 'imageID': '1= b23ac73-0748-49cd-94b6-11555e35be81'}]}, {'specParams': {}, 'alias': 'sound= 0', '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-a2= 2e-f74c2b6412f4', 'address': {'slot': '0x07', 'bus': '0x00', 'domain': '0x0= 000', 'type': 'pci', 'function': '0x0'}, 'device': 'memballoon', 'type': 'b= alloon'}], 'status': 'Paused', 'display': 'qxl'} createXmlElem:<bound metho= d Drive.createXmlElem of <vm.Drive object at 0x7f356003bb90>> device:cdrom = deviceId:6aad5e48-613b-48db-838a-fc923fb0cdd7 drv:raw extSharedState:none g= etLeasesXML:<bound method Drive.getLeasesXML of <vm.Drive object at 0x7f356= 003bb90>> getNextVolumeSize:<bound method Drive.getNextVolumeSize of <vm.Dr= ive object at 0x7f356003bb90>> getXML:<bound method Drive.getXML of <vm.Dri= ve object at 0x7f356003bb90>> hasVolumeLeases:False iface:ide index:2 isDis= kReplicationInProgress:<bound method Drive.isDiskReplicationInProgress of <= vm.Drive object at 0x7f356003bb90>> isVdsmImage:<bound method Drive.isVdsmI= mage of <vm.Drive object at 0x7f356003bb90>> log:<logUtils.SimpleLogAdapter= object at 0x7f356002ef90> name:hdc networkDev:False path: readonly:True re= qsize:0 serial: shared:false specParams:{'path': ''} truesize:0 type:cdrom = volExtensionChunk:1024 watermarkLimit:536870912=0A= Traceback (most recent call last):=0A= File "/usr/share/vdsm/clientIF.py", line 356, in teardownVolumePath=0A= res =3D self.irs.teardownImage(drive['domainID'],=0A= File "/usr/share/vdsm/vm.py", line 1389, in __getitem__=0A= raise KeyError(key)=0A= KeyError: 'domainID'=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,779::task::579::TaskManager.Ta= sk::(_updateState) Task=3D`b2f2b540-29c7-436f-b28a-e3fa961e9ddd`::moving fr= om state init -> state preparing=0A= libvirtEventLoop::INFO::2014-01-30 16:17:29,779::logUtils::44::dispatcher::= (wrapper) Run and protect: teardownImage(sdUUID=3D'965ca3b6-4f9c-4e81-b6e8-= 5ed4a9e58545', spUUID=3D'94ed7a19-fade-4bd6-83f2-2cbb2f730b95', imgUUID=3D'= 1b23ac73-0748-49cd-94b6-11555e35be81', volUUID=3DNone)=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,780::resourceManager::197::Res= ourceManager.Request::(__init__) ResName=3D`Storage.965ca3b6-4f9c-4e81-b6e8= -5ed4a9e58545`ReqID=3D`ce6ba549-acf2-49fa-8b36-2194b81606a5`::Request was m= ade in '/usr/share/vdsm/storage/hsm.py' line '3283' at 'teardownImage'=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,780::resourceManager::541::Res= ourceManager::(registerResource) Trying to register resource 'Storage.965ca= 3b6-4f9c-4e81-b6e8-5ed4a9e58545' for lock type 'shared'=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,780::resourceManager::600::Res= ourceManager::(registerResource) Resource 'Storage.965ca3b6-4f9c-4e81-b6e8-= 5ed4a9e58545' is free. Now locking as 'shared' (1 active user)=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,780::resourceManager::237::Res= ourceManager.Request::(grant) ResName=3D`Storage.965ca3b6-4f9c-4e81-b6e8-5e= d4a9e58545`ReqID=3D`ce6ba549-acf2-49fa-8b36-2194b81606a5`::Granted request= =0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,780::task::811::TaskManager.Ta= sk::(resourceAcquired) Task=3D`b2f2b540-29c7-436f-b28a-e3fa961e9ddd`::_reso= urcesAcquired: Storage.965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545 (shared)=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,781::task::974::TaskManager.Ta= sk::(_decref) Task=3D`b2f2b540-29c7-436f-b28a-e3fa961e9ddd`::ref 1 aborting= False=0A= libvirtEventLoop::INFO::2014-01-30 16:17:29,781::logUtils::47::dispatcher::= (wrapper) Run and protect: teardownImage, Return response: None=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,781::task::1168::TaskManager.T= ask::(prepare) Task=3D`b2f2b540-29c7-436f-b28a-e3fa961e9ddd`::finished: Non= e=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,781::task::579::TaskManager.Ta= sk::(_updateState) Task=3D`b2f2b540-29c7-436f-b28a-e3fa961e9ddd`::moving fr= om state preparing -> state finished=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,781::resourceManager::939::Res= ourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'S= torage.965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': < ResourceRef 'Storage.965ca3= b6-4f9c-4e81-b6e8-5ed4a9e58545', isValid: 'True' obj: 'None'>}=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,781::resourceManager::976::Res= ourceManager.Owner::(cancelAll) Owner.cancelAll requests {}=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,782::resourceManager::615::Res= ourceManager::(releaseResource) Trying to release resource 'Storage.965ca3b= 6-4f9c-4e81-b6e8-5ed4a9e58545'=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,782::resourceManager::634::Res= ourceManager::(releaseResource) Released resource 'Storage.965ca3b6-4f9c-4e= 81-b6e8-5ed4a9e58545' (0 active users)=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,782::resourceManager::640::Res= ourceManager::(releaseResource) Resource 'Storage.965ca3b6-4f9c-4e81-b6e8-5= ed4a9e58545' is free, finding out if anyone is waiting for it.=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,782::resourceManager::648::Res= ourceManager::(releaseResource) No one is waiting for resource 'Storage.965= ca3b6-4f9c-4e81-b6e8-5ed4a9e58545', Clearing records.=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,782::task::974::TaskManager.Ta= sk::(_decref) Task=3D`b2f2b540-29c7-436f-b28a-e3fa961e9ddd`::ref 0 aborting= False=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,783::task::579::TaskManager.Ta= sk::(_updateState) Task=3D`889a75b9-0702-40d3-99da-f7994e33c40c`::moving fr= om state init -> state preparing=0A= libvirtEventLoop::INFO::2014-01-30 16:17:29,783::logUtils::44::dispatcher::= (wrapper) Run and protect: inappropriateDevices(thiefId=3D'ce64f528-9981-4e= c6-a172-9d70a00a34cd')=0A= libvirtEventLoop::INFO::2014-01-30 16:17:29,783::logUtils::47::dispatcher::= (wrapper) Run and protect: inappropriateDevices, Return response: None=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,784::task::1168::TaskManager.T= ask::(prepare) Task=3D`889a75b9-0702-40d3-99da-f7994e33c40c`::finished: Non= e=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,784::task::579::TaskManager.Ta= sk::(_updateState) Task=3D`889a75b9-0702-40d3-99da-f7994e33c40c`::moving fr= om state preparing -> state finished=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,784::resourceManager::939::Res= ourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}= =0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,784::resourceManager::976::Res= ourceManager.Owner::(cancelAll) Owner.cancelAll requests {}=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,784::task::974::TaskManager.Ta= sk::(_decref) Task=3D`889a75b9-0702-40d3-99da-f7994e33c40c`::ref 0 aborting= False=0A= Thread-285248::DEBUG::2014-01-30 16:17:29,787::BindingXMLRPC::974::vds::(wr= apper) client [192.168.11.42]::call vmDestroy with ('ce64f528-9981-4ec6-a17= 2-9d70a00a34cd',) {}=0A= Thread-285248::INFO::2014-01-30 16:17:29,787::API::318::vds::(destroy) vmCo= ntainerLock acquired by vm ce64f528-9981-4ec6-a172-9d70a00a34cd=0A= Thread-285248::DEBUG::2014-01-30 16:17:29,787::vm::4374::vm.Vm::(destroy) v= mId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::destroy Called=0A= Thread-285248::DEBUG::2014-01-30 16:17:29,788::vm::4368::vm.Vm::(deleteVm) = vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Total desktops after destroy= of ce64f528-9981-4ec6-a172-9d70a00a34cd is 0=0A= Thread-285248::DEBUG::2014-01-30 16:17:29,788::BindingXMLRPC::981::vds::(wr= apper) return vmDestroy with {'status': {'message': 'Machine destroyed', 'c= ode': 0}}=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,792::libvirtconnection::108::l= ibvirtconnection::(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)=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,792::vm::2577::vm.Vm::(setDown= Status) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Changed state to Dow= n: Lost connection with qemu process=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,792::sampling::292::vm.Vm::(st= op) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Stop statistics collecti= on=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,793::libvirtconnection::108::l= ibvirtconnection::(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)=0A= Thread-47::DEBUG::2014-01-30 16:17:30,113::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-47::DEBUG::2014-01-30 16:17:30,120::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n363 b= ytes (363 B) copied, 0.000169437 s, 2.1 MB/s\n'; <rc> =3D 0=0A= VM Channels Listener::DEBUG::2014-01-30 16:17:30,731::vmChannels::112::vds:= :(_do_del_channels) fileno 98 was removed from listener.=0A= Thread-41::DEBUG::2014-01-30 16:17:31,606::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-41::DEBUG::2014-01-30 16:17:31,612::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.000246606 s, 2.3 MB/s\n'; <rc> =3D 0=0A= Thread-285249::DEBUG::2014-01-30 16:17:32,200::task::579::TaskManager.Task:= :(_updateState) Task=3D`e44ca35a-0638-43b2-99b7-85790a96f8a2`::moving from = state init -> state preparing=0A= Thread-285249::INFO::2014-01-30 16:17:32,200::logUtils::44::dispatcher::(wr= apper) Run and protect: repoStats(options=3DNone)=0A= Thread-285249::INFO::2014-01-30 16:17:32,201::logUtils::47::dispatcher::(wr= apper) Run and protect: repoStats, Return response: {'2c51d320-88ce-4f23-82= 15-e15f55f66906': {'delay': '0.000195778', 'lastCheck': '4.3', 'code': 0, '= valid': True, 'version': 3}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'dela= y': '0.000246606', 'lastCheck': '0.6', 'code': 0, 'valid': True, 'version':= 3}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'delay': '0.00021875', 'lastC= heck': '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': {'de= lay': '0.000195213', 'lastCheck': '7.7', 'code': 0, 'valid': True, 'version= ': 3}}=0A= Thread-285249::DEBUG::2014-01-30 16:17:32,201::task::1168::TaskManager.Task= ::(prepare) Task=3D`e44ca35a-0638-43b2-99b7-85790a96f8a2`::finished: {'2c51= d320-88ce-4f23-8215-e15f55f66906': {'delay': '0.000195778', 'lastCheck': '4= .3', 'code': 0, 'valid': True, 'version': 3}, '965ca3b6-4f9c-4e81-b6e8-5ed4= a9e58545': {'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}, '63= 041fa9-e093-4b44-b36f-f39f16d3974f': {'delay': '0.000169437', 'lastCheck': = '2.1', 'code': 0, 'valid': True, 'version': 0}, '272ec473-6041-42ee-bd1a-73= 2789dd18d4': {'delay': '0.000195213', 'lastCheck': '7.7', 'code': 0, 'valid= ': True, 'version': 3}}=0A= Thread-285249::DEBUG::2014-01-30 16:17:32,201::task::579::TaskManager.Task:= :(_updateState) Task=3D`e44ca35a-0638-43b2-99b7-85790a96f8a2`::moving from = state preparing -> state finished=0A= Thread-285249::DEBUG::2014-01-30 16:17:32,201::resourceManager::939::Resour= ceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}=0A= Thread-285249::DEBUG::2014-01-30 16:17:32,201::resourceManager::976::Resour= ceManager.Owner::(cancelAll) Owner.cancelAll requests {}=0A= Thread-285249::DEBUG::2014-01-30 16:17:32,201::task::974::TaskManager.Task:= :(_decref) Task=3D`e44ca35a-0638-43b2-99b7-85790a96f8a2`::ref 0 aborting Fa= lse=0A= Thread-52::DEBUG::2014-01-30 16:17:34,531::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-52::DEBUG::2014-01-30 16:17:34,538::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.000202672 s, 2.7 MB/s\n'; <rc> =3D 0=0A= Thread-40::DEBUG::2014-01-30 16:17:37,893::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-40::DEBUG::2014-01-30 16:17:37,899::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n645 b= ytes (645 B) copied, 0.000200736 s, 3.2 MB/s\n'; <rc> =3D 0=0A= Thread-42::DEBUG::2014-01-30 16:17:38,418::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-42::DEBUG::2014-01-30 16:17:38,423::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n357 b= ytes (357 B) copied, 0.000239232 s, 1.5 MB/s\n'; <rc> =3D 0=0A= Thread-47::DEBUG::2014-01-30 16:17:40,132::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-47::DEBUG::2014-01-30 16:17:40,137::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n363 b= ytes (363 B) copied, 0.000199954 s, 1.8 MB/s\n'; <rc> =3D 0=0A= Thread-41::DEBUG::2014-01-30 16:17:41,622::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-41::DEBUG::2014-01-30 16:17:41,628::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.000177973 s, 3.1 MB/s\n'; <rc> =3D 0=0A= Thread-52::DEBUG::2014-01-30 16:17:44,549::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-52::DEBUG::2014-01-30 16:17:44,555::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.000217367 s, 2.6 MB/s\n'; <rc> =3D 0=0A= Thread-285255::DEBUG::2014-01-30 16:17:47,564::task::579::TaskManager.Task:= :(_updateState) Task=3D`feb38342-e432-4cdf-afc4-39582ee67c68`::moving from = state init -> state preparing=0A= Thread-285255::INFO::2014-01-30 16:17:47,564::logUtils::44::dispatcher::(wr= apper) Run and protect: repoStats(options=3DNone)=0A= Thread-285255::INFO::2014-01-30 16:17:47,564::logUtils::47::dispatcher::(wr= apper) Run and protect: repoStats, Return response: {'2c51d320-88ce-4f23-82= 15-e15f55f66906': {'delay': '0.000200736', 'lastCheck': '9.7', 'code': 0, '= valid': True, 'version': 3}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'dela= y': '0.000177973', 'lastCheck': '5.9', 'code': 0, 'valid': True, 'version':= 3}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'delay': '0.000239232', 'last= Check': '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': {'d= elay': '0.000217367', 'lastCheck': '3.0', 'code': 0, 'valid': True, 'versio= n': 3}}=0A= Thread-285255::DEBUG::2014-01-30 16:17:47,564::task::1168::TaskManager.Task= ::(prepare) Task=3D`feb38342-e432-4cdf-afc4-39582ee67c68`::finished: {'2c51= d320-88ce-4f23-8215-e15f55f66906': {'delay': '0.000200736', 'lastCheck': '9= .7', 'code': 0, 'valid': True, 'version': 3}, '965ca3b6-4f9c-4e81-b6e8-5ed4= a9e58545': {'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}, '6= 3041fa9-e093-4b44-b36f-f39f16d3974f': {'delay': '0.000199954', 'lastCheck':= '7.4', 'code': 0, 'valid': True, 'version': 0}, '272ec473-6041-42ee-bd1a-7= 32789dd18d4': {'delay': '0.000217367', 'lastCheck': '3.0', 'code': 0, 'vali= d': True, 'version': 3}}=0A= Thread-285255::DEBUG::2014-01-30 16:17:47,565::task::579::TaskManager.Task:= :(_updateState) Task=3D`feb38342-e432-4cdf-afc4-39582ee67c68`::moving from = state preparing -> state finished=0A= Thread-285255::DEBUG::2014-01-30 16:17:47,565::resourceManager::939::Resour= ceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}=0A= Thread-285255::DEBUG::2014-01-30 16:17:47,565::resourceManager::976::Resour= ceManager.Owner::(cancelAll) Owner.cancelAll requests {}=0A= Thread-285255::DEBUG::2014-01-30 16:17:47,565::task::974::TaskManager.Task:= :(_decref) Task=3D`feb38342-e432-4cdf-afc4-39582ee67c68`::ref 0 aborting Fa= lse=0A= Thread-40::DEBUG::2014-01-30 16:17:47,913::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-40::DEBUG::2014-01-30 16:17:47,919::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n645 b= ytes (645 B) copied, 0.000156636 s, 4.1 MB/s\n'; <rc> =3D 0=0A= Thread-42::DEBUG::2014-01-30 16:17:48,435::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-42::DEBUG::2014-01-30 16:17:48,440::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n357 b= ytes (357 B) copied, 0.000219512 s, 1.6 MB/s\n'; <rc> =3D 0=0A= Thread-47::DEBUG::2014-01-30 16:17:50,153::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-47::DEBUG::2014-01-30 16:17:50,158::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n363 b= ytes (363 B) copied, 0.000129306 s, 2.8 MB/s\n'; <rc> =3D 0=0A= Thread-41::DEBUG::2014-01-30 16:17:51,639::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-41::DEBUG::2014-01-30 16:17:51,645::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.000299809 s, 1.9 MB/s\n'; <rc> =3D 0=0A= Thread-52::DEBUG::2014-01-30 16:17:54,565::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-52::DEBUG::2014-01-30 16:17:54,571::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.00023204 s, 2.4 MB/s\n'; <rc> =3D 0=0A= Thread-40::DEBUG::2014-01-30 16:17:57,934::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-40::DEBUG::2014-01-30 16:17:57,940::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n645 b= ytes (645 B) copied, 0.000197083 s, 3.3 MB/s\n'; <rc> =3D 0=0A= Thread-42::DEBUG::2014-01-30 16:17:58,453::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-42::DEBUG::2014-01-30 16:17:58,458::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n357 b= ytes (357 B) copied, 0.000150387 s, 2.4 MB/s\n'; <rc> =3D 0=0A= Thread-47::DEBUG::2014-01-30 16:18:00,168::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-47::DEBUG::2014-01-30 16:18:00,174::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n363 b= ytes (363 B) copied, 0.000222782 s, 1.6 MB/s\n'; <rc> =3D 0=0A= Thread-41::DEBUG::2014-01-30 16:18:01,655::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-41::DEBUG::2014-01-30 16:18:01,661::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.000197351 s, 2.8 MB/s\n'; <rc> =3D 0=0A= Thread-285261::DEBUG::2014-01-30 16:18:02,942::task::579::TaskManager.Task:= :(_updateState) Task=3D`5683bb8f-2158-4c8f-a263-46b6e7a086da`::moving from = state init -> state preparing=0A= Thread-285261::INFO::2014-01-30 16:18:02,943::logUtils::44::dispatcher::(wr= apper) Run and protect: repoStats(options=3DNone)=0A= Thread-285261::INFO::2014-01-30 16:18:02,943::logUtils::47::dispatcher::(wr= apper) Run and protect: repoStats, Return response: {'2c51d320-88ce-4f23-82= 15-e15f55f66906': {'delay': '0.000197083', 'lastCheck': '5.0', 'code': 0, '= valid': True, 'version': 3}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'dela= y': '0.000197351', 'lastCheck': '1.3', 'code': 0, 'valid': True, 'version':= 3}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'delay': '0.000150387', 'last= Check': '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': {'d= elay': '0.00023204', 'lastCheck': '8.4', 'code': 0, 'valid': True, 'version= ': 3}}=0A= Thread-285261::DEBUG::2014-01-30 16:18:02,943::task::1168::TaskManager.Task= ::(prepare) Task=3D`5683bb8f-2158-4c8f-a263-46b6e7a086da`::finished: {'2c51= d320-88ce-4f23-8215-e15f55f66906': {'delay': '0.000197083', 'lastCheck': '5= .0', 'code': 0, 'valid': True, 'version': 3}, '965ca3b6-4f9c-4e81-b6e8-5ed4= a9e58545': {'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}, '6= 3041fa9-e093-4b44-b36f-f39f16d3974f': {'delay': '0.000222782', 'lastCheck':= '2.8', 'code': 0, 'valid': True, 'version': 0}, '272ec473-6041-42ee-bd1a-7= 32789dd18d4': {'delay': '0.00023204', 'lastCheck': '8.4', 'code': 0, 'valid= ': True, 'version': 3}}=0A= Thread-285261::DEBUG::2014-01-30 16:18:02,944::task::579::TaskManager.Task:= :(_updateState) Task=3D`5683bb8f-2158-4c8f-a263-46b6e7a086da`::moving from = state preparing -> state finished=0A= Thread-285261::DEBUG::2014-01-30 16:18:02,944::resourceManager::939::Resour= ceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}=0A= Thread-285261::DEBUG::2014-01-30 16:18:02,944::resourceManager::976::Resour= ceManager.Owner::(cancelAll) Owner.cancelAll requests {}=0A= Thread-285261::DEBUG::2014-01-30 16:18:02,944::task::974::TaskManager.Task:= :(_decref) Task=3D`5683bb8f-2158-4c8f-a263-46b6e7a086da`::ref 0 aborting Fa= lse=0A= Thread-52::DEBUG::2014-01-30 16:18:04,581::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-52::DEBUG::2014-01-30 16:18:04,588::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.000218219 s, 2.6 MB/s\n'; <rc> =3D 0=0A= Thread-40::DEBUG::2014-01-30 16:18:07,953::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-40::DEBUG::2014-01-30 16:18:07,959::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n645 b= ytes (645 B) copied, 0.00019818 s, 3.3 MB/s\n'; <rc> =3D 0=0A= Thread-42::DEBUG::2014-01-30 16:18:08,470::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-42::DEBUG::2014-01-30 16:18:08,475::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n357 b= ytes (357 B) copied, 0.000178019 s, 2.0 MB/s\n'; <rc> =3D 0=0A= Thread-47::DEBUG::2014-01-30 16:18:10,186::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-47::DEBUG::2014-01-30 16:18:10,192::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n363 b= ytes (363 B) copied, 0.000189951 s, 1.9 MB/s\n'; <rc> =3D 0=0A= Thread-41::DEBUG::2014-01-30 16:18:11,671::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-41::DEBUG::2014-01-30 16:18:11,677::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.000247616 s, 2.2 MB/s\n'; <rc> =3D 0=0A= Thread-52::DEBUG::2014-01-30 16:18:14,598::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-52::DEBUG::2014-01-30 16:18:14,604::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.000208255 s, 2.7 MB/s\n'; <rc> =3D 0=0A= Thread-40::DEBUG::2014-01-30 16:18:17,974::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-40::DEBUG::2014-01-30 16:18:17,979::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n645 b= ytes (645 B) copied, 0.000217282 s, 3.0 MB/s\n'; <rc> =3D 0=0A= Thread-285267::DEBUG::2014-01-30 16:18:18,464::task::579::TaskManager.Task:= :(_updateState) Task=3D`1e0fc684-6d0b-4694-996c-728b66ae9fc2`::moving from = state init -> state preparing=0A= Thread-285267::INFO::2014-01-30 16:18:18,465::logUtils::44::dispatcher::(wr= apper) Run and protect: repoStats(options=3DNone)=0A= Thread-285267::INFO::2014-01-30 16:18:18,465::logUtils::47::dispatcher::(wr= apper) Run and protect: repoStats, Return response: {'2c51d320-88ce-4f23-82= 15-e15f55f66906': {'delay': '0.000217282', 'lastCheck': '0.5', 'code': 0, '= valid': True, 'version': 3}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'dela= y': '0.000247616', 'lastCheck': '6.8', 'code': 0, 'valid': True, 'version':= 3}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'delay': '0.000178019', 'last= Check': '10.0', 'code': 0, 'valid': True, 'version': 0}, '63041fa9-e093-4b4= 4-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, 'versi= on': 3}}=0A= ------=_NextPartTM-000-16e476a9-dc0a-459b-91a5-33c52e66e68f Content-Type: text/plain; name="InterScan_Disclaimer.txt" Content-Transfer-Encoding: 7bit Content-Disposition: attachment; filename="InterScan_Disclaimer.txt" **************************************************************************** Diese E-Mail enthält vertrauliche und/oder rechtlich geschützte Informationen. Wenn Sie nicht der richtige Adressat sind oder diese E-Mail irrtümlich erhalten haben, informieren Sie bitte sofort den Absender und vernichten Sie diese Mail. Das unerlaubte Kopieren sowie die unbefugte Weitergabe dieser Mail ist nicht gestattet. Über das Internet versandte E-Mails können unter fremden Namen erstellt oder manipuliert werden. Deshalb ist diese als E-Mail verschickte Nachricht keine rechtsverbindliche Willenserklärung. Collogia Unternehmensberatung AG Ubierring 11 D-50678 Köln Vorstand: Kadir Akin Dr. Michael Höhnerbach Vorsitzender des Aufsichtsrates: Hans Kristian Langva Registergericht: Amtsgericht Köln Registernummer: HRB 52 497 This e-mail may contain confidential and/or privileged information. If you are not the intended recipient (or have received this e-mail in error) please notify the sender immediately and destroy this e-mail. Any unauthorized copying, disclosure or distribution of the material in this e-mail is strictly forbidden. e-mails sent over the internet may have been written under a wrong name or been manipulated. That is why this message sent as an e-mail is not a legally binding declaration of intention. Collogia Unternehmensberatung AG Ubierring 11 D-50678 Köln executive board: Kadir Akin Dr. Michael Höhnerbach President of the supervisory board: Hans Kristian Langva Registry office: district court Cologne Register number: HRB 52 497 **************************************************************************** ------=_NextPartTM-000-16e476a9-dc0a-459b-91a5-33c52e66e68f--