Thread-3203800::DEBUG::2012-04-26 10:14:14,216::task::588::TaskManager.Task::(_updateState) Task=`ce3ebc36-94c2-44ac-ad56-c95fe2d82513`::moving from state preparing -> state finished
Thread-3203800::DEBUG::2012-04-26 10:14:14,217::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-3203800::DEBUG::2012-04-26 10:14:14,217::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-3203800::DEBUG::2012-04-26 10:14:14,218::task::980::TaskManager.Task::(_decref) Task=`ce3ebc36-94c2-44ac-ad56-c95fe2d82513`::ref 0 aborting False
Thread-3203801::DEBUG::2012-04-26 10:14:14,242::libvirtvm::232::vm.Vm::(_getDiskStats) vmId=`a1f01689-240a-40b8-8719-1a9c815f5642`::Disk hdc stats not available
Thread-3203801::DEBUG::2012-04-26 10:14:14,243::libvirtvm::261::vm.Vm::(_getDiskLatency) vmId=`a1f01689-240a-40b8-8719-1a9c815f5642`::Disk hda latency not available
Thread-3203801::DEBUG::2012-04-26 10:14:14,244::libvirtvm::261::vm.Vm::(_getDiskLatency) vmId=`a1f01689-240a-40b8-8719-1a9c815f5642`::Disk hdc latency not available
Thread-3203801::DEBUG::2012-04-26 10:14:14,245::libvirtvm::232::vm.Vm::(_getDiskStats) vmId=`f73f17a8-a418-4318-af0e-2cea18ab597a`::Disk hdc stats not available
Thread-3203801::DEBUG::2012-04-26 10:14:14,246::libvirtvm::261::vm.Vm::(_getDiskLatency) vmId=`f73f17a8-a418-4318-af0e-2cea18ab597a`::Disk vda latency not available
Thread-3203801::DEBUG::2012-04-26 10:14:14,246::libvirtvm::261::vm.Vm::(_getDiskLatency) vmId=`f73f17a8-a418-4318-af0e-2cea18ab597a`::Disk hdc latency not available
Thread-3203806::DEBUG::2012-04-26 10:14:23,709::clientIF::76::vds::(wrapper) [172.30.0.229]::call migrate with ({'src': '172.30.0.232', 'dst': '172.30.0.231:54321', 'vmId': 'f73f17a8-a418-4318-af0e-2cea18ab597a', 'method': 'online'},) {}
Thread-3203806::DEBUG::2012-04-26 10:14:23,710::clientIF::379::vds::(migrate) {'src': '172.30.0.232', 'dst': '172.30.0.231:54321', 'vmId': 'f73f17a8-a418-4318-af0e-2cea18ab597a', 'method': 'online'}
Thread-3203807::DEBUG::2012-04-26 10:14:23,712::vm::116::vm.Vm::(_setupVdsConnection) vmId=`f73f17a8-a418-4318-af0e-2cea18ab597a`::Destination server is: 172.30.0.231:54321
Thread-3203806::DEBUG::2012-04-26 10:14:23,712::clientIF::81::vds::(wrapper) return migrate with {'status': {'message': 'Migration process starting', 'code': 0}}
Thread-3203807::DEBUG::2012-04-26 10:14:23,713::vm::118::vm.Vm::(_setupVdsConnection) vmId=`f73f17a8-a418-4318-af0e-2cea18ab597a`::Initiating connection with destination
Thread-3203807::DEBUG::2012-04-26 10:14:23,737::libvirtvm::232::vm.Vm::(_getDiskStats) vmId=`f73f17a8-a418-4318-af0e-2cea18ab597a`::Disk hdc stats not available
Thread-3203807::DEBUG::2012-04-26 10:14:23,737::libvirtvm::261::vm.Vm::(_getDiskLatency) vmId=`f73f17a8-a418-4318-af0e-2cea18ab597a`::Disk vda latency not available
Thread-3203807::DEBUG::2012-04-26 10:14:23,738::libvirtvm::261::vm.Vm::(_getDiskLatency) vmId=`f73f17a8-a418-4318-af0e-2cea18ab597a`::Disk hdc latency not available
Thread-3203807::DEBUG::2012-04-26 10:14:23,742::vm::164::vm.Vm::(_prepareGuest) vmId=`f73f17a8-a418-4318-af0e-2cea18ab597a`::migration Process begins
Thread-3203807::DEBUG::2012-04-26 10:14:23,749::vm::211::vm.Vm::(run) vmId=`f73f17a8-a418-4318-af0e-2cea18ab597a`::migration semaphore acquired
Thread-3203807::DEBUG::2012-04-26 10:14:23,977::libvirtvm::419::vm.Vm::(_startUnderlyingMigration) vmId=`f73f17a8-a418-4318-af0e-2cea18ab597a`::starting migration to qemu+tls://172.30.0.231/system
Thread-3203808::DEBUG::2012-04-26 10:14:23,978::libvirtvm::317::vm.Vm::(run) vmId=`f73f17a8-a418-4318-af0e-2cea18ab597a`::migration downtime thread started
Thread-3203809::DEBUG::2012-04-26 10:14:23,979::libvirtvm::345::vm.Vm::(run) vmId=`f73f17a8-a418-4318-af0e-2cea18ab597a`::starting migration monitor thread
Thread-3203807::DEBUG::2012-04-26 10:14:23,998::libvirtvm::332::vm.Vm::(cancel) vmId=`f73f17a8-a418-4318-af0e-2cea18ab597a`::canceling migration downtime thread
Thread-3203807::DEBUG::2012-04-26 10:14:23,999::libvirtvm::382::vm.Vm::(stop) vmId=`f73f17a8-a418-4318-af0e-2cea18ab597a`::stopping migration monitor thread
Thread-3203808::DEBUG::2012-04-26 10:14:23,999::libvirtvm::329::vm.Vm::(run) vmId=`f73f17a8-a418-4318-af0e-2cea18ab597a`::migration downtime thread exiting
Thread-3203807::ERROR::2012-04-26 10:14:24,001::vm::170::vm.Vm::(_recover) vmId=`f73f17a8-a418-4318-af0e-2cea18ab597a`::operation failed: Failed to connect to remote libvirt URI qemu+tls://172.30.0.231/system
Thread-3203807::ERROR::2012-04-26 10:14:24,119::vm::234::vm.Vm::(run) vmId=`f73f17a8-a418-4318-af0e-2cea18ab597a`::Traceback (most recent call last):
  File "/usr/share/vdsm/vm.py", line 217, in run
  File "/usr/share/vdsm/libvirtvm.py", line 443, in _startUnderlyingMigration
  File "/usr/share/vdsm/libvirtvm.py", line 483, in f
  File "/usr/share/vdsm/libvirtconnection.py", line 79, in wrapper
  File "/usr/lib64/python2.7/site-packages/libvirt.py", line 971, in migrateToURI2
libvirtError: operation failed: Failed to connect to remote libvirt URI qemu+tls://172.30.0.231/system

Thread-3203810::DEBUG::2012-04-26 10:14:24,415::task::588::TaskManager.Task::(_updateState) Task=`ce192aac-27ff-48bc-bef4-451d3e4aad48`::moving from state init -> state preparing
Thread-3203810::INFO::2012-04-26 10:14:24,416::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-3203810::INFO::2012-04-26 10:14:24,417::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00173997879028', 'lastCheck': 1335477130.119629, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00190806388855', 'lastCheck': 1335477130.122188, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00839805603027', 'lastCheck': 1335477130.117298, 'code': 0, 'valid': True}}
Thread-3203810::DEBUG::2012-04-26 10:14:24,417::task::1174::TaskManager.Task::(prepare) Task=`ce192aac-27ff-48bc-bef4-451d3e4aad48`::finished: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00173997879028', 'lastCheck': 1335477130.119629, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00190806388855', 'lastCheck': 1335477130.122188, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00839805603027', 'lastCheck': 1335477130.117298, 'code': 0, 'valid': True}}
Thread-3203810::DEBUG::2012-04-26 10:14:24,418::task::588::TaskManager.Task::(_updateState) Task=`ce192aac-27ff-48bc-bef4-451d3e4aad48`::moving from state preparing -> state finished
Thread-3203810::DEBUG::2012-04-26 10:14:24,419::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-3203810::DEBUG::2012-04-26 10:14:24,420::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-3203810::DEBUG::2012-04-26 10:14:24,420::task::980::TaskManager.Task::(_decref) Task=`ce192aac-27ff-48bc-bef4-451d3e4aad48`::ref 0 aborting False
Thread-3203811::DEBUG::2012-04-26 10:14:24,440::libvirtvm::232::vm.Vm::(_getDiskStats) vmId=`a1f01689-240a-40b8-8719-1a9c815f5642`::Disk hdc stats not available
Thread-3203811::DEBUG::2012-04-26 10:14:24,441::libvirtvm::261::vm.Vm::(_getDiskLatency) vmId=`a1f01689-240a-40b8-8719-1a9c815f5642`::Disk hda latency not available
Thread-3203811::DEBUG::2012-04-26 10:14:24,441::libvirtvm::261::vm.Vm::(_getDiskLatency) vmId=`a1f01689-240a-40b8-8719-1a9c815f5642`::Disk hdc latency not available
Thread-3203811::DEBUG::2012-04-26 10:14:24,443::libvirtvm::232::vm.Vm::(_getDiskStats) vmId=`f73f17a8-a418-4318-af0e-2cea18ab597a`::Disk hdc stats not available
Thread-3203811::DEBUG::2012-04-26 10:14:24,443::libvirtvm::261::vm.Vm::(_getDiskLatency) vmId=`f73f17a8-a418-4318-af0e-2cea18ab597a`::Disk vda latency not available
Thread-3203811::DEBUG::2012-04-26 10:14:24,444::libvirtvm::261::vm.Vm::(_getDiskLatency) vmId=`f73f17a8-a418-4318-af0e-2cea18ab597a`::Disk hdc latency not available
Thread-3203812::DEBUG::2012-04-26 10:14:24,528::clientIF::76::vds::(wrapper) [172.30.0.229]::call migrateStatus with ('f73f17a8-a418-4318-af0e-2cea18ab597a',) {}
Thread-3203812::DEBUG::2012-04-26 10:14:24,529::clientIF::81::vds::(wrapper) return migrateStatus with {'status': {'message': 'Fatal error during migration', 'code': 12}}
Thread-3203817::DEBUG::2012-04-26 10:14:34,617::task::588::TaskManager.Task::(_updateState) Task=`ee082137-e3f0-4755-a549-65407f551eea`::moving from state init -> state preparing
Thread-3203817::INFO::2012-04-26 10:14:34,618::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-3203817::INFO::2012-04-26 10:14:34,619::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00173997879028', 'lastCheck': 1335477130.119629, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00190806388855', 'lastCheck': 1335477130.122188, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00839805603027', 'lastCheck': 1335477130.117298, 'code': 0, 'valid': True}}
Thread-3203817::DEBUG::2012-04-26 10:14:34,619::task::1174::TaskManager.Task::(prepare) Task=`ee082137-e3f0-4755-a549-65407f551eea`::finished: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00173997879028', 'lastCheck': 1335477130.119629, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00190806388855', 'lastCheck': 1335477130.122188, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00839805603027', 'lastCheck': 1335477130.117298, 'code': 0, 'valid': True}}
Thread-3203817::DEBUG::2012-04-26 10:14:34,620::task::588::TaskManager.Task::(_updateState) Task=`ee082137-e3f0-4755-a549-65407f551eea`::moving from state preparing -> state finished
Thread-3203817::DEBUG::2012-04-26 10:14:34,621::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-3203817::DEBUG::2012-04-26 10:14:34,622::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-3203817::DEBUG::2012-04-26 10:14:34,622::task::980::TaskManager.Task::(_decref) Task=`ee082137-e3f0-4755-a549-65407f551eea`::ref 0 aborting False
Thread-3203818::DEBUG::2012-04-26 10:14:34,644::libvirtvm::232::vm.Vm::(_getDiskStats) vmId=`a1f01689-240a-40b8-8719-1a9c815f5642`::Disk hdc stats not available
Thread-3203818::DEBUG::2012-04-26 10:14:34,645::libvirtvm::261::vm.Vm::(_getDiskLatency) vmId=`a1f01689-240a-40b8-8719-1a9c815f5642`::Disk hda latency not available
Thread-3203818::DEBUG::2012-04-26 10:14:34,646::libvirtvm::261::vm.Vm::(_getDiskLatency) vmId=`a1f01689-240a-40b8-8719-1a9c815f5642`::Disk hdc latency not available
Thread-3203818::DEBUG::2012-04-26 10:14:34,647::libvirtvm::232::vm.Vm::(_getDiskStats) vmId=`f73f17a8-a418-4318-af0e-2cea18ab597a`::Disk hdc stats not available
Thread-3203818::DEBUG::2012-04-26 10:14:34,648::libvirtvm::261::vm.Vm::(_getDiskLatency) vmId=`f73f17a8-a418-4318-af0e-2cea18ab597a`::Disk vda latency not available
Thread-3203818::DEBUG::2012-04-26 10:14:34,648::libvirtvm::261::vm.Vm::(_getDiskLatency) vmId=`f73f17a8-a418-4318-af0e-2cea18ab597a`::Disk hdc latency not available
Thread-3203823::DEBUG::2012-04-26 10:14:44,833::task::588::TaskManager.Task::(_updateState) Task=`22a3d000-1122-497c-91d1-ca032ae2b799`::moving from state init -> state preparing
Thread-3203823::INFO::2012-04-26 10:14:44,834::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-3203823::INFO::2012-04-26 10:14:44,835::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00173997879028', 'lastCheck': 1335477130.119629, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00190806388855', 'lastCheck': 1335477130.122188, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00839805603027', 'lastCheck': 1335477130.117298, 'code': 0, 'valid': True}}
Thread-3203823::DEBUG::2012-04-26 10:14:44,836::task::1174::TaskManager.Task::(prepare) Task=`22a3d000-1122-497c-91d1-ca032ae2b799`::finished: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00173997879028', 'lastCheck': 1335477130.119629, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00190806388855', 'lastCheck': 1335477130.122188, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00839805603027', 'lastCheck': 1335477130.117298, 'code': 0, 'valid': True}}
Thread-3203823::DEBUG::2012-04-26 10:14:44,837::task::588::TaskManager.Task::(_updateState) Task=`22a3d000-1122-497c-91d1-ca032ae2b799`::moving from state preparing -> state finished
Thread-3203823::DEBUG::2012-04-26 10:14:44,838::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-3203823::DEBUG::2012-04-26 10:14:44,838::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-3203823::DEBUG::2012-04-26 10:14:44,839::task::980::TaskManager.Task::(_decref) Task=`22a3d000-1122-497c-91d1-ca032ae2b799`::ref 0 aborting False
Thread-3203824::DEBUG::2012-04-26 10:14:44,862::libvirtvm::232::vm.Vm::(_getDiskStats) vmId=`a1f01689-240a-40b8-8719-1a9c815f5642`::Disk hdc stats not available
Thread-3203824::DEBUG::2012-04-26 10:14:44,863::libvirtvm::261::vm.Vm::(_getDiskLatency) vmId=`a1f01689-240a-40b8-8719-1a9c815f5642`::Disk hda latency not available
Thread-3203824::DEBUG::2012-04-26 10:14:44,864::libvirtvm::261::vm.Vm::(_getDiskLatency) vmId=`a1f01689-240a-40b8-8719-1a9c815f5642`::Disk hdc latency not available
Thread-3203824::DEBUG::2012-04-26 10:14:44,865::libvirtvm::232::vm.Vm::(_getDiskStats) vmId=`f73f17a8-a418-4318-af0e-2cea18ab597a`::Disk hdc stats not available
Thread-3203824::DEBUG::2012-04-26 10:14:44,866::libvirtvm::261::vm.Vm::(_getDiskLatency) vmId=`f73f17a8-a418-4318-af0e-2cea18ab597a`::Disk vda latency not available
Thread-3203824::DEBUG::2012-04-26 10:14:44,866::libvirtvm::261::vm.Vm::(_getDiskLatency) vmId=`f73f17a8-a418-4318-af0e-2cea18ab597a`::Disk hdc latency not available
Thread-3203829::DEBUG::2012-04-26 10:14:55,029::task::588::TaskManager.Task::(_updateState) Task=`59edf306-8af3-410e-b13f-493510719325`::moving from state init -> state preparing
Thread-3203829::INFO::2012-04-26 10:14:55,030::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-3203829::INFO::2012-04-26 10:14:55,031::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00173997879028', 'lastCheck': 1335477130.119629, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00190806388855', 'lastCheck': 1335477130.122188, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00839805603027', 'lastCheck': 1335477130.117298, 'code': 0, 'valid': True}}
Thread-3203829::DEBUG::2012-04-26 10:14:55,032::task::1174::TaskManager.Task::(prepare) Task=`59edf306-8af3-410e-b13f-493510719325`::finished: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00173997879028', 'lastCheck': 1335477130.119629, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00190806388855', 'lastCheck': 1335477130.122188, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00839805603027', 'lastCheck': 1335477130.117298, 'code': 0, 'valid': True}}
Thread-3203829::DEBUG::2012-04-26 10:14:55,032::task::588::TaskManager.Task::(_updateState) Task=`59edf306-8af3-410e-b13f-493510719325`::moving from state preparing -> state finished
Thread-3203829::DEBUG::2012-04-26 10:14:55,033::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-3203829::DEBUG::2012-04-26 10:14:55,034::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-3203829::DEBUG::2012-04-26 10:14:55,034::task::980::TaskManager.Task::(_decref) Task=`59edf306-8af3-410e-b13f-493510719325`::ref 0 aborting False
Thread-3203830::DEBUG::2012-04-26 10:14:55,054::libvirtvm::232::vm.Vm::(_getDiskStats) vmId=`a1f01689-240a-40b8-8719-1a9c815f5642`::Disk hdc stats not available
Thread-3203830::DEBUG::2012-04-26 10:14:55,055::libvirtvm::261::vm.Vm::(_getDiskLatency) vmId=`a1f01689-240a-40b8-8719-1a9c815f5642`::Disk hda latency not available
Thread-3203830::DEBUG::2012-04-26 10:14:55,055::libvirtvm::261::vm.Vm::(_getDiskLatency) vmId=`a1f01689-240a-40b8-8719-1a9c815f5642`::Disk hdc latency not available
Thread-3203830::DEBUG::2012-04-26 10:14:55,056::libvirtvm::232::vm.Vm::(_getDiskStats) vmId=`f73f17a8-a418-4318-af0e-2cea18ab597a`::Disk hdc stats not available
Thread-3203830::DEBUG::2012-04-26 10:14:55,057::libvirtvm::261::vm.Vm::(_getDiskLatency) vmId=`f73f17a8-a418-4318-af0e-2cea18ab597a`::Disk vda latency not available
Thread-3203830::DEBUG::2012-04-26 10:14:55,058::libvirtvm::261::vm.Vm::(_getDiskLatency) vmId=`f73f17a8-a418-4318-af0e-2cea18ab597a`::Disk hdc latency not available