Attachment 696172 Details for Bug 910014 – vdsm log after a failed live migration

vdsm log after a failed live migration

vdsm-failed-live-migrate.log (text/x-log), 40.37 KB, created by Matthew Davis on 2013-02-11 16:07:45 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Matthew Davis

Created: 2013-02-11 16:07:45 UTC

Size: 40.37 KB

patch

obsolete

>Thread-63016::DEBUG::2013-02-07 09:41:30,630::task::588::TaskManager.Task::(_updateState) Task=`53aaaa02-087d-4571-8193-d04230f5875d`::moving from state init -> state preparing
>Thread-63016::INFO::2013-02-07 09:41:30,631::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-63016::INFO::2013-02-07 09:41:30,631::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'b77c0314-88e8-45e0-bad7-eb76fab05979': {'delay': '0.00153994560242', 'lastCheck': '9.1', 'code': 0, 'valid': True}, u'8e3975e8-fe95-4833-a245-228f0bf0c9ec': {'delay': '0.0104949474335', 'lastCheck': '4.2', 'code': 0, 'valid': True}, u'1ef3e2fc-eac0-4bf3-b604-fbc4d972be83': {'delay': '0.00163388252258', 'lastCheck': '9.1', 'code': 0, 'valid': True}}
>Thread-63016::DEBUG::2013-02-07 09:41:30,631::task::1172::TaskManager.Task::(prepare) Task=`53aaaa02-087d-4571-8193-d04230f5875d`::finished: {u'b77c0314-88e8-45e0-bad7-eb76fab05979': {'delay': '0.00153994560242', 'lastCheck': '9.1', 'code': 0, 'valid': True}, u'8e3975e8-fe95-4833-a245-228f0bf0c9ec': {'delay': '0.0104949474335', 'lastCheck': '4.2', 'code': 0, 'valid': True}, u'1ef3e2fc-eac0-4bf3-b604-fbc4d972be83': {'delay': '0.00163388252258', 'lastCheck': '9.1', 'code': 0, 'valid': True}}
>Thread-63016::DEBUG::2013-02-07 09:41:30,632::task::588::TaskManager.Task::(_updateState) Task=`53aaaa02-087d-4571-8193-d04230f5875d`::moving from state preparing -> state finished
>Thread-63016::DEBUG::2013-02-07 09:41:30,632::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-63016::DEBUG::2013-02-07 09:41:30,632::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-63016::DEBUG::2013-02-07 09:41:30,633::task::978::TaskManager.Task::(_decref) Task=`53aaaa02-087d-4571-8193-d04230f5875d`::ref 0 aborting False
>Thread-63018::DEBUG::2013-02-07 09:41:32,824::task::588::TaskManager.Task::(_updateState) Task=`4afe2fd4-b87a-4b96-bb37-986fbe88e167`::moving from state init -> state preparing
>Thread-63018::INFO::2013-02-07 09:41:32,824::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-63018::INFO::2013-02-07 09:41:32,824::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'b77c0314-88e8-45e0-bad7-eb76fab05979': {'delay': '0.00166606903076', 'lastCheck': '1.3', 'code': 0, 'valid': True}, u'8e3975e8-fe95-4833-a245-228f0bf0c9ec': {'delay': '0.0104949474335', 'lastCheck': '6.4', 'code': 0, 'valid': True}, u'1ef3e2fc-eac0-4bf3-b604-fbc4d972be83': {'delay': '0.00123691558838', 'lastCheck': '1.3', 'code': 0, 'valid': True}}
>Thread-63018::DEBUG::2013-02-07 09:41:32,825::task::1172::TaskManager.Task::(prepare) Task=`4afe2fd4-b87a-4b96-bb37-986fbe88e167`::finished: {u'b77c0314-88e8-45e0-bad7-eb76fab05979': {'delay': '0.00166606903076', 'lastCheck': '1.3', 'code': 0, 'valid': True}, u'8e3975e8-fe95-4833-a245-228f0bf0c9ec': {'delay': '0.0104949474335', 'lastCheck': '6.4', 'code': 0, 'valid': True}, u'1ef3e2fc-eac0-4bf3-b604-fbc4d972be83': {'delay': '0.00123691558838', 'lastCheck': '1.3', 'code': 0, 'valid': True}}
>Thread-63018::DEBUG::2013-02-07 09:41:32,825::task::588::TaskManager.Task::(_updateState) Task=`4afe2fd4-b87a-4b96-bb37-986fbe88e167`::moving from state preparing -> state finished
>Thread-63018::DEBUG::2013-02-07 09:41:32,825::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-63018::DEBUG::2013-02-07 09:41:32,826::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-63018::DEBUG::2013-02-07 09:41:32,826::task::978::TaskManager.Task::(_decref) Task=`4afe2fd4-b87a-4b96-bb37-986fbe88e167`::ref 0 aborting False
>Thread-63020::DEBUG::2013-02-07 09:41:33,573::BindingXMLRPC::894::vds::(wrapper) client [10.11.164.20]::call vmMigrate with ({'src': '10.11.164.25', 'dst': '10.11.164.21:54321', 'vmId': '0b688f6d-d36e-4ea3-aa78-a6e90357b89a', 'method': 'online'},) {} flowID [2c2ff7e3]
>Thread-63020::DEBUG::2013-02-07 09:41:33,574::API::421::vds::(migrate) {'src': '10.11.164.25', 'dst': '10.11.164.21:54321', 'vmId': '0b688f6d-d36e-4ea3-aa78-a6e90357b89a', 'method': 'online'}
>Thread-63021::DEBUG::2013-02-07 09:41:33,574::vm::125::vm.Vm::(_setupVdsConnection) vmId=`0b688f6d-d36e-4ea3-aa78-a6e90357b89a`::Destination server is: 10.11.164.21:54321
>Thread-63020::DEBUG::2013-02-07 09:41:33,575::BindingXMLRPC::900::vds::(wrapper) return vmMigrate with {'status': {'message': 'Migration process starting', 'code': 0}}
>Thread-63021::DEBUG::2013-02-07 09:41:33,575::vm::127::vm.Vm::(_setupVdsConnection) vmId=`0b688f6d-d36e-4ea3-aa78-a6e90357b89a`::Initiating connection with destination
>Thread-63021::DEBUG::2013-02-07 09:41:33,624::libvirtvm::267::vm.Vm::(_getDiskStats) vmId=`0b688f6d-d36e-4ea3-aa78-a6e90357b89a`::Disk hdc stats not available
>Thread-63021::DEBUG::2013-02-07 09:41:33,630::vm::175::vm.Vm::(_prepareGuest) vmId=`0b688f6d-d36e-4ea3-aa78-a6e90357b89a`::migration Process begins
>Thread-63021::DEBUG::2013-02-07 09:41:33,646::vm::239::vm.Vm::(run) vmId=`0b688f6d-d36e-4ea3-aa78-a6e90357b89a`::migration semaphore acquired
>Thread-63021::DEBUG::2013-02-07 09:41:33,776::libvirtvm::454::vm.Vm::(_startUnderlyingMigration) vmId=`0b688f6d-d36e-4ea3-aa78-a6e90357b89a`::starting migration to qemu+tls://10.11.164.21/system
>Thread-63022::DEBUG::2013-02-07 09:41:33,777::libvirtvm::352::vm.Vm::(run) vmId=`0b688f6d-d36e-4ea3-aa78-a6e90357b89a`::migration downtime thread started
>Thread-63023::DEBUG::2013-02-07 09:41:33,777::libvirtvm::380::vm.Vm::(run) vmId=`0b688f6d-d36e-4ea3-aa78-a6e90357b89a`::starting migration monitor thread
>Thread-63021::DEBUG::2013-02-07 09:41:34,169::libvirtvm::367::vm.Vm::(cancel) vmId=`0b688f6d-d36e-4ea3-aa78-a6e90357b89a`::canceling migration downtime thread
>Thread-63021::DEBUG::2013-02-07 09:41:34,169::libvirtvm::417::vm.Vm::(stop) vmId=`0b688f6d-d36e-4ea3-aa78-a6e90357b89a`::stopping migration monitor thread
>Thread-63022::DEBUG::2013-02-07 09:41:34,170::libvirtvm::364::vm.Vm::(run) vmId=`0b688f6d-d36e-4ea3-aa78-a6e90357b89a`::migration downtime thread exiting
>Thread-63021::ERROR::2013-02-07 09:41:34,171::vm::181::vm.Vm::(_recover) vmId=`0b688f6d-d36e-4ea3-aa78-a6e90357b89a`::Unable to allow access for disk path /rhev/data-center/febc6480-1174-11e2-afbe-001b78ce0d40/8e3975e8-fe95-4833-a245-228f0bf0c9ec/images/0c8c5954-2076-4911-bdfe-fd407b95dbed/76cec859-0f78-4fed-b357-8f1eaade7a46: No such file or directory
>Thread-63021::ERROR::2013-02-07 09:41:34,276::vm::262::vm.Vm::(run) vmId=`0b688f6d-d36e-4ea3-aa78-a6e90357b89a`::Failed to migrate
>Traceback (most recent call last):
>  File "/usr/share/vdsm/vm.py", line 245, in run
>    self._startUnderlyingMigration()
>  File "/usr/share/vdsm/libvirtvm.py", line 478, in _startUnderlyingMigration
>    None, maxBandwidth)
>  File "/usr/share/vdsm/libvirtvm.py", line 518, in f
>    ret = attr(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/vdsm/libvirtconnection.py", line 83, in wrapper
>    ret = f(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 1103, in migrateToURI2
>    if ret == -1: raise libvirtError ('virDomainMigrateToURI2() failed', dom=self)
>libvirtError: Unable to allow access for disk path /rhev/data-center/febc6480-1174-11e2-afbe-001b78ce0d40/8e3975e8-fe95-4833-a245-228f0bf0c9ec/images/0c8c5954-2076-4911-bdfe-fd407b95dbed/76cec859-0f78-4fed-b357-8f1eaade7a46: No such file or directory
>Thread-63024::DEBUG::2013-02-07 09:41:34,928::task::588::TaskManager.Task::(_updateState) Task=`3fd7d3ac-570f-450c-b5d1-1509017498b1`::moving from state init -> state preparing
>Thread-63024::INFO::2013-02-07 09:41:34,928::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-63024::INFO::2013-02-07 09:41:34,929::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'b77c0314-88e8-45e0-bad7-eb76fab05979': {'delay': '0.00166606903076', 'lastCheck': '3.4', 'code': 0, 'valid': True}, u'8e3975e8-fe95-4833-a245-228f0bf0c9ec': {'delay': '0.0104949474335', 'lastCheck': '8.5', 'code': 0, 'valid': True}, u'1ef3e2fc-eac0-4bf3-b604-fbc4d972be83': {'delay': '0.00123691558838', 'lastCheck': '3.4', 'code': 0, 'valid': True}}
>Thread-63024::DEBUG::2013-02-07 09:41:34,929::task::1172::TaskManager.Task::(prepare) Task=`3fd7d3ac-570f-450c-b5d1-1509017498b1`::finished: {u'b77c0314-88e8-45e0-bad7-eb76fab05979': {'delay': '0.00166606903076', 'lastCheck': '3.4', 'code': 0, 'valid': True}, u'8e3975e8-fe95-4833-a245-228f0bf0c9ec': {'delay': '0.0104949474335', 'lastCheck': '8.5', 'code': 0, 'valid': True}, u'1ef3e2fc-eac0-4bf3-b604-fbc4d972be83': {'delay': '0.00123691558838', 'lastCheck': '3.4', 'code': 0, 'valid': True}}
>Thread-63024::DEBUG::2013-02-07 09:41:34,929::task::588::TaskManager.Task::(_updateState) Task=`3fd7d3ac-570f-450c-b5d1-1509017498b1`::moving from state preparing -> state finished
>Thread-63024::DEBUG::2013-02-07 09:41:34,930::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-63024::DEBUG::2013-02-07 09:41:34,930::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-63024::DEBUG::2013-02-07 09:41:34,930::task::978::TaskManager.Task::(_decref) Task=`3fd7d3ac-570f-450c-b5d1-1509017498b1`::ref 0 aborting False
>Thread-63025::DEBUG::2013-02-07 09:41:34,943::libvirtvm::267::vm.Vm::(_getDiskStats) vmId=`ad448438-4645-4bfd-86ad-016720b48937`::Disk hdc stats not available
>Thread-63025::DEBUG::2013-02-07 09:41:34,944::libvirtvm::267::vm.Vm::(_getDiskStats) vmId=`0b688f6d-d36e-4ea3-aa78-a6e90357b89a`::Disk hdc stats not available
>Thread-63026::DEBUG::2013-02-07 09:41:35,091::BindingXMLRPC::894::vds::(wrapper) client [10.11.164.20]::call vmGetMigrationStatus with ('0b688f6d-d36e-4ea3-aa78-a6e90357b89a',) {}
>Thread-63026::DEBUG::2013-02-07 09:41:35,091::BindingXMLRPC::900::vds::(wrapper) return vmGetMigrationStatus with {'status': {'message': 'Fatal error during migration', 'code': 12}}
>Thread-63027::DEBUG::2013-02-07 09:41:35,356::BindingXMLRPC::894::vds::(wrapper) client [10.11.164.20]::call vmMigrate with ({'src': '10.11.164.25', 'dst': '10.11.164.26:54321', 'vmId': '0b688f6d-d36e-4ea3-aa78-a6e90357b89a', 'method': 'online'},) {}
>Thread-63027::DEBUG::2013-02-07 09:41:35,356::API::421::vds::(migrate) {'src': '10.11.164.25', 'dst': '10.11.164.26:54321', 'vmId': '0b688f6d-d36e-4ea3-aa78-a6e90357b89a', 'method': 'online'}
>Thread-63028::DEBUG::2013-02-07 09:41:35,357::vm::125::vm.Vm::(_setupVdsConnection) vmId=`0b688f6d-d36e-4ea3-aa78-a6e90357b89a`::Destination server is: 10.11.164.26:54321
>Thread-63027::DEBUG::2013-02-07 09:41:35,357::BindingXMLRPC::900::vds::(wrapper) return vmMigrate with {'status': {'message': 'Migration process starting', 'code': 0}}
>Thread-63028::DEBUG::2013-02-07 09:41:35,357::vm::127::vm.Vm::(_setupVdsConnection) vmId=`0b688f6d-d36e-4ea3-aa78-a6e90357b89a`::Initiating connection with destination
>Thread-63028::DEBUG::2013-02-07 09:41:35,405::libvirtvm::267::vm.Vm::(_getDiskStats) vmId=`0b688f6d-d36e-4ea3-aa78-a6e90357b89a`::Disk hdc stats not available
>Thread-63028::DEBUG::2013-02-07 09:41:35,412::vm::175::vm.Vm::(_prepareGuest) vmId=`0b688f6d-d36e-4ea3-aa78-a6e90357b89a`::migration Process begins
>Thread-63028::DEBUG::2013-02-07 09:41:35,427::vm::239::vm.Vm::(run) vmId=`0b688f6d-d36e-4ea3-aa78-a6e90357b89a`::migration semaphore acquired
>Thread-63028::DEBUG::2013-02-07 09:41:35,552::libvirtvm::454::vm.Vm::(_startUnderlyingMigration) vmId=`0b688f6d-d36e-4ea3-aa78-a6e90357b89a`::starting migration to qemu+tls://10.11.164.26/system
>Thread-63029::DEBUG::2013-02-07 09:41:35,552::libvirtvm::352::vm.Vm::(run) vmId=`0b688f6d-d36e-4ea3-aa78-a6e90357b89a`::migration downtime thread started
>Thread-63030::DEBUG::2013-02-07 09:41:35,553::libvirtvm::380::vm.Vm::(run) vmId=`0b688f6d-d36e-4ea3-aa78-a6e90357b89a`::starting migration monitor thread
>Thread-63028::DEBUG::2013-02-07 09:41:35,903::libvirtvm::367::vm.Vm::(cancel) vmId=`0b688f6d-d36e-4ea3-aa78-a6e90357b89a`::canceling migration downtime thread
>Thread-63028::DEBUG::2013-02-07 09:41:35,903::libvirtvm::417::vm.Vm::(stop) vmId=`0b688f6d-d36e-4ea3-aa78-a6e90357b89a`::stopping migration monitor thread
>Thread-63029::DEBUG::2013-02-07 09:41:35,904::libvirtvm::364::vm.Vm::(run) vmId=`0b688f6d-d36e-4ea3-aa78-a6e90357b89a`::migration downtime thread exiting
>Thread-63028::ERROR::2013-02-07 09:41:35,904::vm::181::vm.Vm::(_recover) vmId=`0b688f6d-d36e-4ea3-aa78-a6e90357b89a`::Unable to allow access for disk path /rhev/data-center/febc6480-1174-11e2-afbe-001b78ce0d40/8e3975e8-fe95-4833-a245-228f0bf0c9ec/images/0c8c5954-2076-4911-bdfe-fd407b95dbed/76cec859-0f78-4fed-b357-8f1eaade7a46: No such file or directory
>Thread-63028::ERROR::2013-02-07 09:41:36,013::vm::262::vm.Vm::(run) vmId=`0b688f6d-d36e-4ea3-aa78-a6e90357b89a`::Failed to migrate
>Traceback (most recent call last):
>  File "/usr/share/vdsm/vm.py", line 245, in run
>    self._startUnderlyingMigration()
>  File "/usr/share/vdsm/libvirtvm.py", line 478, in _startUnderlyingMigration
>    None, maxBandwidth)
>  File "/usr/share/vdsm/libvirtvm.py", line 518, in f
>    ret = attr(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/vdsm/libvirtconnection.py", line 83, in wrapper
>    ret = f(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 1103, in migrateToURI2
>    if ret == -1: raise libvirtError ('virDomainMigrateToURI2() failed', dom=self)
>libvirtError: Unable to allow access for disk path /rhev/data-center/febc6480-1174-11e2-afbe-001b78ce0d40/8e3975e8-fe95-4833-a245-228f0bf0c9ec/images/0c8c5954-2076-4911-bdfe-fd407b95dbed/76cec859-0f78-4fed-b357-8f1eaade7a46: No such file or directory
>Thread-35::DEBUG::2013-02-07 09:41:36,390::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/dd iflag=direct if=/dev/8e3975e8-fe95-4833-a245-228f0bf0c9ec/metadata bs=4096 count=1' (cwd None)
>Thread-35::DEBUG::2013-02-07 09:41:36,399::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000549631 s, 7.5 MB/s\n'; <rc> = 0
>Thread-63031::DEBUG::2013-02-07 09:41:37,061::task::588::TaskManager.Task::(_updateState) Task=`e2034c20-6291-478a-823b-c33d2b451194`::moving from state init -> state preparing
>Thread-63031::INFO::2013-02-07 09:41:37,061::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-63031::INFO::2013-02-07 09:41:37,062::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'b77c0314-88e8-45e0-bad7-eb76fab05979': {'delay': '0.00166606903076', 'lastCheck': '5.6', 'code': 0, 'valid': True}, u'8e3975e8-fe95-4833-a245-228f0bf0c9ec': {'delay': '0.0102298259735', 'lastCheck': '0.7', 'code': 0, 'valid': True}, u'1ef3e2fc-eac0-4bf3-b604-fbc4d972be83': {'delay': '0.00123691558838', 'lastCheck': '5.6', 'code': 0, 'valid': True}}
>Thread-63031::DEBUG::2013-02-07 09:41:37,062::task::1172::TaskManager.Task::(prepare) Task=`e2034c20-6291-478a-823b-c33d2b451194`::finished: {u'b77c0314-88e8-45e0-bad7-eb76fab05979': {'delay': '0.00166606903076', 'lastCheck': '5.6', 'code': 0, 'valid': True}, u'8e3975e8-fe95-4833-a245-228f0bf0c9ec': {'delay': '0.0102298259735', 'lastCheck': '0.7', 'code': 0, 'valid': True}, u'1ef3e2fc-eac0-4bf3-b604-fbc4d972be83': {'delay': '0.00123691558838', 'lastCheck': '5.6', 'code': 0, 'valid': True}}
>Thread-63031::DEBUG::2013-02-07 09:41:37,062::task::588::TaskManager.Task::(_updateState) Task=`e2034c20-6291-478a-823b-c33d2b451194`::moving from state preparing -> state finished
>Thread-63031::DEBUG::2013-02-07 09:41:37,063::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-63031::DEBUG::2013-02-07 09:41:37,063::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-63031::DEBUG::2013-02-07 09:41:37,063::task::978::TaskManager.Task::(_decref) Task=`e2034c20-6291-478a-823b-c33d2b451194`::ref 0 aborting False
>Thread-63033::DEBUG::2013-02-07 09:41:37,083::BindingXMLRPC::894::vds::(wrapper) client [10.11.164.20]::call vmGetStats with ('0b688f6d-d36e-4ea3-aa78-a6e90357b89a',) {}
>Thread-63033::DEBUG::2013-02-07 09:41:37,084::libvirtvm::267::vm.Vm::(_getDiskStats) vmId=`0b688f6d-d36e-4ea3-aa78-a6e90357b89a`::Disk hdc stats not available
>Thread-63033::DEBUG::2013-02-07 09:41:37,084::BindingXMLRPC::900::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'username': u'None', 'memUsage': '18', 'acpiEnable': 'true', 'pid': '29654', 'session': 'Unknown', 'netIfaces': [{u'inet6': [u'fe80::21a:4aff:fe0b:a401', u'2620:52:0:ba4:21a:4aff:fe0b:a401'], u'hw': u'00:1a:4a:0b:a4:01', u'inet': [u'10.11.164.48'], u'name': u'eth0'}, {u'inet6': [u'fe80::21a:4aff:fe0b:a410', u'2620:52:0:ba4:21a:4aff:fe0b:a410'], u'hw': u'00:1a:4a:0b:a4:10', u'inet': [u'172.31.103.48'], u'name': u'eth3'}], 'timeOffset': '-18000', 'pauseCode': 'NOERR', 'disksUsage': [{u'path': u'/', u'total': '8455118848', u'used': '4787027968', u'fs': u'ext4'}, {u'path': u'/proc/bus/usb', u'total': '0', u'used': '0', u'fs': u'usbfs'}, {u'path': u'/boot', u'total': '203097088', u'used': '49517568', u'fs': u'ext4'}], 'network': {u'vnet0': {'macAddr': '00:1a:4a:0b:a4:01', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}, u'vnet1': {'macAddr': '00:1a:4a:0b:a4:10', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet1'}}, 'displayType': 'qxl', 'guestName': u'monitor.rdu.salab.redhat.com', 'boot': 'c', 'elapsedTime': '150707', 'vmType': 'kvm', 'cpuSys': '0.33', 'appsList': [u'kernel-2.6.32-279.el6', u'kernel-2.6.32-279.9.1.el6', u'rhev-agent-2.3.16-7.el6_2'], 'guestOs': u'2.6.32-279.9.1.el6.x86_64', 'nice': '', 'status': 'Running', 'hash': '7528553597511519692', 'vmId': '0b688f6d-d36e-4ea3-aa78-a6e90357b89a', 'displayIp': '0', 'displayPort': u'5900', 'clientIp': '', 'kvmEnable': 'true', 'disks': {u'vda': {'readLatency': '820019', 'apparentsize': '32212254720', 'writeLatency': '5531779', 'imageID': '0c8c5954-2076-4911-bdfe-fd407b95dbed', 'flushLatency': '569773', 'readRate': '3930.33', 'truesize': '32212254720', 'writeRate': '336788.82'}, u'hdc': {'flushLatency': '0', 'readLatency': '0', 'writeLatency': '0'}}, 'monitorResponse': '0', 'statsAge': '0.98', 'cpuUser': '0.91', 'cpuIdle': '98.76', 'lastLogin': 1360185798.2073569, 'guestIPs': u'10.11.164.48 172.31.103.48', 'displaySecurePort': u'5901'}]}
>Thread-63034::DEBUG::2013-02-07 09:41:37,176::BindingXMLRPC::894::vds::(wrapper) client [10.11.164.20]::call vmGetMigrationStatus with ('0b688f6d-d36e-4ea3-aa78-a6e90357b89a',) {}
>Thread-63034::DEBUG::2013-02-07 09:41:37,176::BindingXMLRPC::900::vds::(wrapper) return vmGetMigrationStatus with {'status': {'message': 'Fatal error during migration', 'code': 12}}
>Thread-63035::DEBUG::2013-02-07 09:41:37,360::BindingXMLRPC::894::vds::(wrapper) client [10.11.164.20]::call vmMigrate with ({'src': '10.11.164.25', 'dst': '10.11.164.24:54321', 'vmId': '0b688f6d-d36e-4ea3-aa78-a6e90357b89a', 'method': 'online'},) {}
>Thread-63035::DEBUG::2013-02-07 09:41:37,361::API::421::vds::(migrate) {'src': '10.11.164.25', 'dst': '10.11.164.24:54321', 'vmId': '0b688f6d-d36e-4ea3-aa78-a6e90357b89a', 'method': 'online'}
>Thread-63036::DEBUG::2013-02-07 09:41:37,361::vm::125::vm.Vm::(_setupVdsConnection) vmId=`0b688f6d-d36e-4ea3-aa78-a6e90357b89a`::Destination server is: 10.11.164.24:54321
>Thread-63035::DEBUG::2013-02-07 09:41:37,362::BindingXMLRPC::900::vds::(wrapper) return vmMigrate with {'status': {'message': 'Migration process starting', 'code': 0}}
>Thread-63036::DEBUG::2013-02-07 09:41:37,362::vm::127::vm.Vm::(_setupVdsConnection) vmId=`0b688f6d-d36e-4ea3-aa78-a6e90357b89a`::Initiating connection with destination
>Thread-63036::DEBUG::2013-02-07 09:41:37,412::libvirtvm::267::vm.Vm::(_getDiskStats) vmId=`0b688f6d-d36e-4ea3-aa78-a6e90357b89a`::Disk hdc stats not available
>Thread-63036::DEBUG::2013-02-07 09:41:37,418::vm::175::vm.Vm::(_prepareGuest) vmId=`0b688f6d-d36e-4ea3-aa78-a6e90357b89a`::migration Process begins
>Thread-63036::DEBUG::2013-02-07 09:41:37,433::vm::239::vm.Vm::(run) vmId=`0b688f6d-d36e-4ea3-aa78-a6e90357b89a`::migration semaphore acquired
>Thread-63036::DEBUG::2013-02-07 09:41:37,529::libvirtvm::454::vm.Vm::(_startUnderlyingMigration) vmId=`0b688f6d-d36e-4ea3-aa78-a6e90357b89a`::starting migration to qemu+tls://10.11.164.24/system
>Thread-63037::DEBUG::2013-02-07 09:41:37,529::libvirtvm::352::vm.Vm::(run) vmId=`0b688f6d-d36e-4ea3-aa78-a6e90357b89a`::migration downtime thread started
>Thread-63038::DEBUG::2013-02-07 09:41:37,530::libvirtvm::380::vm.Vm::(run) vmId=`0b688f6d-d36e-4ea3-aa78-a6e90357b89a`::starting migration monitor thread
>Thread-63036::DEBUG::2013-02-07 09:41:37,896::libvirtvm::367::vm.Vm::(cancel) vmId=`0b688f6d-d36e-4ea3-aa78-a6e90357b89a`::canceling migration downtime thread
>Thread-63036::DEBUG::2013-02-07 09:41:37,896::libvirtvm::417::vm.Vm::(stop) vmId=`0b688f6d-d36e-4ea3-aa78-a6e90357b89a`::stopping migration monitor thread
>Thread-63037::DEBUG::2013-02-07 09:41:37,897::libvirtvm::364::vm.Vm::(run) vmId=`0b688f6d-d36e-4ea3-aa78-a6e90357b89a`::migration downtime thread exiting
>Thread-63036::ERROR::2013-02-07 09:41:37,897::vm::181::vm.Vm::(_recover) vmId=`0b688f6d-d36e-4ea3-aa78-a6e90357b89a`::Unable to allow access for disk path /rhev/data-center/febc6480-1174-11e2-afbe-001b78ce0d40/8e3975e8-fe95-4833-a245-228f0bf0c9ec/images/0c8c5954-2076-4911-bdfe-fd407b95dbed/76cec859-0f78-4fed-b357-8f1eaade7a46: No such file or directory
>Thread-63036::ERROR::2013-02-07 09:41:38,010::vm::262::vm.Vm::(run) vmId=`0b688f6d-d36e-4ea3-aa78-a6e90357b89a`::Failed to migrate
>Traceback (most recent call last):
>  File "/usr/share/vdsm/vm.py", line 245, in run
>    self._startUnderlyingMigration()
>  File "/usr/share/vdsm/libvirtvm.py", line 478, in _startUnderlyingMigration
>    None, maxBandwidth)
>  File "/usr/share/vdsm/libvirtvm.py", line 518, in f
>    ret = attr(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/vdsm/libvirtconnection.py", line 83, in wrapper
>    ret = f(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 1103, in migrateToURI2
>    if ret == -1: raise libvirtError ('virDomainMigrateToURI2() failed', dom=self)
>libvirtError: Unable to allow access for disk path /rhev/data-center/febc6480-1174-11e2-afbe-001b78ce0d40/8e3975e8-fe95-4833-a245-228f0bf0c9ec/images/0c8c5954-2076-4911-bdfe-fd407b95dbed/76cec859-0f78-4fed-b357-8f1eaade7a46: No such file or directory
>Thread-63039::DEBUG::2013-02-07 09:41:39,176::task::588::TaskManager.Task::(_updateState) Task=`a81adb98-5024-431c-95da-239607ce3e74`::moving from state init -> state preparing
>Thread-63039::INFO::2013-02-07 09:41:39,176::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-63039::INFO::2013-02-07 09:41:39,177::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'b77c0314-88e8-45e0-bad7-eb76fab05979': {'delay': '0.00166606903076', 'lastCheck': '7.7', 'code': 0, 'valid': True}, u'8e3975e8-fe95-4833-a245-228f0bf0c9ec': {'delay': '0.0102298259735', 'lastCheck': '2.8', 'code': 0, 'valid': True}, u'1ef3e2fc-eac0-4bf3-b604-fbc4d972be83': {'delay': '0.00123691558838', 'lastCheck': '7.7', 'code': 0, 'valid': True}}
>Thread-63039::DEBUG::2013-02-07 09:41:39,177::task::1172::TaskManager.Task::(prepare) Task=`a81adb98-5024-431c-95da-239607ce3e74`::finished: {u'b77c0314-88e8-45e0-bad7-eb76fab05979': {'delay': '0.00166606903076', 'lastCheck': '7.7', 'code': 0, 'valid': True}, u'8e3975e8-fe95-4833-a245-228f0bf0c9ec': {'delay': '0.0102298259735', 'lastCheck': '2.8', 'code': 0, 'valid': True}, u'1ef3e2fc-eac0-4bf3-b604-fbc4d972be83': {'delay': '0.00123691558838', 'lastCheck': '7.7', 'code': 0, 'valid': True}}
>Thread-63039::DEBUG::2013-02-07 09:41:39,177::task::588::TaskManager.Task::(_updateState) Task=`a81adb98-5024-431c-95da-239607ce3e74`::moving from state preparing -> state finished
>Thread-63039::DEBUG::2013-02-07 09:41:39,178::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-63039::DEBUG::2013-02-07 09:41:39,178::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-63039::DEBUG::2013-02-07 09:41:39,178::task::978::TaskManager.Task::(_decref) Task=`a81adb98-5024-431c-95da-239607ce3e74`::ref 0 aborting False
>Thread-63041::DEBUG::2013-02-07 09:41:39,198::BindingXMLRPC::894::vds::(wrapper) client [10.11.164.20]::call vmGetStats with ('0b688f6d-d36e-4ea3-aa78-a6e90357b89a',) {}
>Thread-63041::DEBUG::2013-02-07 09:41:39,199::libvirtvm::267::vm.Vm::(_getDiskStats) vmId=`0b688f6d-d36e-4ea3-aa78-a6e90357b89a`::Disk hdc stats not available
>Thread-63041::DEBUG::2013-02-07 09:41:39,199::BindingXMLRPC::900::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'username': u'None', 'memUsage': '18', 'acpiEnable': 'true', 'pid': '29654', 'session': 'Unknown', 'netIfaces': [{u'inet6': [u'fe80::21a:4aff:fe0b:a401', u'2620:52:0:ba4:21a:4aff:fe0b:a401'], u'hw': u'00:1a:4a:0b:a4:01', u'inet': [u'10.11.164.48'], u'name': u'eth0'}, {u'inet6': [u'fe80::21a:4aff:fe0b:a410', u'2620:52:0:ba4:21a:4aff:fe0b:a410'], u'hw': u'00:1a:4a:0b:a4:10', u'inet': [u'172.31.103.48'], u'name': u'eth3'}], 'timeOffset': '-18000', 'pauseCode': 'NOERR', 'disksUsage': [{u'path': u'/', u'total': '8455118848', u'used': '4787027968', u'fs': u'ext4'}, {u'path': u'/proc/bus/usb', u'total': '0', u'used': '0', u'fs': u'usbfs'}, {u'path': u'/boot', u'total': '203097088', u'used': '49517568', u'fs': u'ext4'}], 'network': {u'vnet0': {'macAddr': '00:1a:4a:0b:a4:01', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}, u'vnet1': {'macAddr': '00:1a:4a:0b:a4:10', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet1'}}, 'displayType': 'qxl', 'guestName': u'monitor.rdu.salab.redhat.com', 'boot': 'c', 'elapsedTime': '150709', 'vmType': 'kvm', 'cpuSys': '0.33', 'appsList': [u'kernel-2.6.32-279.el6', u'kernel-2.6.32-279.9.1.el6', u'rhev-agent-2.3.16-7.el6_2'], 'guestOs': u'2.6.32-279.9.1.el6.x86_64', 'nice': '', 'status': 'Running', 'hash': '7528553597511519692', 'vmId': '0b688f6d-d36e-4ea3-aa78-a6e90357b89a', 'displayIp': '0', 'displayPort': u'5900', 'clientIp': '', 'kvmEnable': 'true', 'disks': {u'vda': {'readLatency': '820019', 'apparentsize': '32212254720', 'writeLatency': '5531779', 'imageID': '0c8c5954-2076-4911-bdfe-fd407b95dbed', 'flushLatency': '569773', 'readRate': '3930.33', 'truesize': '32212254720', 'writeRate': '336788.82'}, u'hdc': {'flushLatency': '0', 'readLatency': '0', 'writeLatency': '0'}}, 'monitorResponse': '0', 'statsAge': '1.10', 'cpuUser': '0.91', 'cpuIdle': '98.76', 'lastLogin': 1360185798.2073569, 'guestIPs': u'10.11.164.48 172.31.103.48', 'displaySecurePort': u'5901'}]}
>Thread-63042::DEBUG::2013-02-07 09:41:39,285::BindingXMLRPC::894::vds::(wrapper) client [10.11.164.20]::call vmGetMigrationStatus with ('0b688f6d-d36e-4ea3-aa78-a6e90357b89a',) {}
>Thread-63042::DEBUG::2013-02-07 09:41:39,286::BindingXMLRPC::900::vds::(wrapper) return vmGetMigrationStatus with {'status': {'message': 'Fatal error during migration', 'code': 12}}
>Thread-63043::DEBUG::2013-02-07 09:41:41,290::task::588::TaskManager.Task::(_updateState) Task=`380bde40-db2b-4236-a662-779105b1b179`::moving from state init -> state preparing
>Thread-63043::INFO::2013-02-07 09:41:41,291::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-63043::INFO::2013-02-07 09:41:41,291::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'b77c0314-88e8-45e0-bad7-eb76fab05979': {'delay': '0.00166606903076', 'lastCheck': '9.8', 'code': 0, 'valid': True}, u'8e3975e8-fe95-4833-a245-228f0bf0c9ec': {'delay': '0.0102298259735', 'lastCheck': '4.9', 'code': 0, 'valid': True}, u'1ef3e2fc-eac0-4bf3-b604-fbc4d972be83': {'delay': '0.00123691558838', 'lastCheck': '9.8', 'code': 0, 'valid': True}}
>Thread-63043::DEBUG::2013-02-07 09:41:41,291::task::1172::TaskManager.Task::(prepare) Task=`380bde40-db2b-4236-a662-779105b1b179`::finished: {u'b77c0314-88e8-45e0-bad7-eb76fab05979': {'delay': '0.00166606903076', 'lastCheck': '9.8', 'code': 0, 'valid': True}, u'8e3975e8-fe95-4833-a245-228f0bf0c9ec': {'delay': '0.0102298259735', 'lastCheck': '4.9', 'code': 0, 'valid': True}, u'1ef3e2fc-eac0-4bf3-b604-fbc4d972be83': {'delay': '0.00123691558838', 'lastCheck': '9.8', 'code': 0, 'valid': True}}
>Thread-63043::DEBUG::2013-02-07 09:41:41,292::task::588::TaskManager.Task::(_updateState) Task=`380bde40-db2b-4236-a662-779105b1b179`::moving from state preparing -> state finished
>Thread-63043::DEBUG::2013-02-07 09:41:41,292::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-63043::DEBUG::2013-02-07 09:41:41,292::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-63043::DEBUG::2013-02-07 09:41:41,292::task::978::TaskManager.Task::(_decref) Task=`380bde40-db2b-4236-a662-779105b1b179`::ref 0 aborting False
>Thread-34::DEBUG::2013-02-07 09:41:41,500::domainMonitor::170::Storage.DomainMonitorThread::(_monitorDomain) Refreshing domain b77c0314-88e8-45e0-bad7-eb76fab05979
>Thread-34::DEBUG::2013-02-07 09:41:41,500::lvm::353::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>Thread-34::DEBUG::2013-02-07 09:41:41,501::__init__::1164::Storage.Misc.excCmd::(_log) u'/usr/bin/sudo -n /sbin/lvm vgs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ \\"a%1IET_00010001%\\", \\"r%.*%\\" ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free b77c0314-88e8-45e0-bad7-eb76fab05979' (cwd None)
>Thread-36::DEBUG::2013-02-07 09:41:41,501::domainMonitor::170::Storage.DomainMonitorThread::(_monitorDomain) Refreshing domain 1ef3e2fc-eac0-4bf3-b604-fbc4d972be83
>Thread-36::DEBUG::2013-02-07 09:41:41,509::lvm::353::OperationMutex::(_reloadvgs) Got the operational mutex
>Thread-36::DEBUG::2013-02-07 09:41:41,510::__init__::1164::Storage.Misc.excCmd::(_log) u'/usr/bin/sudo -n /sbin/lvm vgs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ \\"a%1IET_00010001%\\", \\"r%.*%\\" ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free 1ef3e2fc-eac0-4bf3-b604-fbc4d972be83' (cwd None)
>Thread-36::DEBUG::2013-02-07 09:41:41,662::__init__::1164::Storage.Misc.excCmd::(_log) FAILED: <err> = '  Volume group "1ef3e2fc-eac0-4bf3-b604-fbc4d972be83" not found\n'; <rc> = 5
>Thread-34::DEBUG::2013-02-07 09:41:41,662::__init__::1164::Storage.Misc.excCmd::(_log) FAILED: <err> = '  Volume group "b77c0314-88e8-45e0-bad7-eb76fab05979" not found\n'; <rc> = 5
>Thread-36::WARNING::2013-02-07 09:41:41,665::lvm::357::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] ['  Volume group "1ef3e2fc-eac0-4bf3-b604-fbc4d972be83" not found']
>Thread-34::WARNING::2013-02-07 09:41:41,665::lvm::357::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] ['  Volume group "b77c0314-88e8-45e0-bad7-eb76fab05979" not found']
>Thread-34::DEBUG::2013-02-07 09:41:41,666::lvm::380::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>Thread-36::DEBUG::2013-02-07 09:41:41,675::fileSD::124::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/storage2.rdu.salab.redhat.com:_rhev-export/1ef3e2fc-eac0-4bf3-b604-fbc4d972be83
>Thread-36::DEBUG::2013-02-07 09:41:41,675::persistentDict::185::Storage.PersistentDict::(__init__) Created a persistant dict with FileMetadataRW backend
>Thread-34::DEBUG::2013-02-07 09:41:41,678::fileSD::124::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/rhevm.rdu.salab.redhat.com:_rhev-iso/b77c0314-88e8-45e0-bad7-eb76fab05979
>Thread-34::DEBUG::2013-02-07 09:41:41,678::persistentDict::185::Storage.PersistentDict::(__init__) Created a persistant dict with FileMetadataRW backend
>Thread-36::DEBUG::2013-02-07 09:41:41,679::persistentDict::226::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Backup', 'DESCRIPTION=RHEV-EXPORT', 'IOOPTIMEOUTSEC=1', 'LEASERETRIES=3', 'LEASETIMESEC=5', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=0', 'POOL_UUID=febc6480-1174-11e2-afbe-001b78ce0d40', 'REMOTE_PATH=storage2.rdu.salab.redhat.com:/rhev-export', 'ROLE=Regular', 'SDUUID=1ef3e2fc-eac0-4bf3-b604-fbc4d972be83', 'TYPE=NFS', 'VERSION=0', '_SHA_CKSUM=79b3b5ae464c44df798100be94bab34ef860b905']
>Thread-34::DEBUG::2013-02-07 09:41:41,681::persistentDict::226::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Iso', 'DESCRIPTION=RHEV-ISO', 'IOOPTIMEOUTSEC=1', 'LEASERETRIES=3', 'LEASETIMESEC=5', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=0', 'POOL_UUID=febc6480-1174-11e2-afbe-001b78ce0d40', 'REMOTE_PATH=rhevm.rdu.salab.redhat.com:/rhev-iso', 'ROLE=Regular', 'SDUUID=b77c0314-88e8-45e0-bad7-eb76fab05979', 'TYPE=NFS', 'VERSION=0', '_SHA_CKSUM=fd1f3d3ac4fca17b58e207e7b2dc5171fc1127af']
>Thread-36::DEBUG::2013-02-07 09:41:41,681::fileSD::447::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images []
>Thread-36::WARNING::2013-02-07 09:41:41,682::sd::321::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 1ef3e2fc-eac0-4bf3-b604-fbc4d972be83_imageNS already registered
>Thread-36::WARNING::2013-02-07 09:41:41,682::sd::327::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 1ef3e2fc-eac0-4bf3-b604-fbc4d972be83_volumeNS already registered
>Thread-34::DEBUG::2013-02-07 09:41:41,683::fileSD::447::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images []
>Thread-34::WARNING::2013-02-07 09:41:41,683::sd::321::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace b77c0314-88e8-45e0-bad7-eb76fab05979_imageNS already registered
>Thread-34::WARNING::2013-02-07 09:41:41,684::sd::327::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace b77c0314-88e8-45e0-bad7-eb76fab05979_volumeNS already registered
>Thread-63053::DEBUG::2013-02-07 09:41:43,354::task::588::TaskManager.Task::(_updateState) Task=`d1483667-6cea-4615-bc2b-2ed4bfcb78c0`::moving from state init -> state preparing
>Thread-63053::INFO::2013-02-07 09:41:43,355::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-63053::INFO::2013-02-07 09:41:43,355::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'b77c0314-88e8-45e0-bad7-eb76fab05979': {'delay': '0.000838994979858', 'lastCheck': '1.7', 'code': 0, 'valid': True}, u'8e3975e8-fe95-4833-a245-228f0bf0c9ec': {'delay': '0.0102298259735', 'lastCheck': '7.0', 'code': 0, 'valid': True}, u'1ef3e2fc-eac0-4bf3-b604-fbc4d972be83': {'delay': '0.0011088848114', 'lastCheck': '1.7', 'code': 0, 'valid': True}}
>Thread-63053::DEBUG::2013-02-07 09:41:43,355::task::1172::TaskManager.Task::(prepare) Task=`d1483667-6cea-4615-bc2b-2ed4bfcb78c0`::finished: {u'b77c0314-88e8-45e0-bad7-eb76fab05979': {'delay': '0.000838994979858', 'lastCheck': '1.7', 'code': 0, 'valid': True}, u'8e3975e8-fe95-4833-a245-228f0bf0c9ec': {'delay': '0.0102298259735', 'lastCheck': '7.0', 'code': 0, 'valid': True}, u'1ef3e2fc-eac0-4bf3-b604-fbc4d972be83': {'delay': '0.0011088848114', 'lastCheck': '1.7', 'code': 0, 'valid': True}}
>Thread-63053::DEBUG::2013-02-07 09:41:43,356::task::588::TaskManager.Task::(_updateState) Task=`d1483667-6cea-4615-bc2b-2ed4bfcb78c0`::moving from state preparing -> state finished
>Thread-63053::DEBUG::2013-02-07 09:41:43,356::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-63053::DEBUG::2013-02-07 09:41:43,356::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-63053::DEBUG::2013-02-07 09:41:43,357::task::978::TaskManager.Task::(_decref) Task=`d1483667-6cea-4615-bc2b-2ed4bfcb78c0`::ref 0 aborting False
>Thread-63055::DEBUG::2013-02-07 09:41:45,418::task::588::TaskManager.Task::(_updateState) Task=`fde95f1f-b647-400a-99f9-dded45f210e0`::moving from state init -> state preparing
>Thread-63055::INFO::2013-02-07 09:41:45,418::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-63055::INFO::2013-02-07 09:41:45,419::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'b77c0314-88e8-45e0-bad7-eb76fab05979': {'delay': '0.000838994979858', 'lastCheck': '3.7', 'code': 0, 'valid': True}, u'8e3975e8-fe95-4833-a245-228f0bf0c9ec': {'delay': '0.0102298259735', 'lastCheck': '9.0', 'code': 0, 'valid': True}, u'1ef3e2fc-eac0-4bf3-b604-fbc4d972be83': {'delay': '0.0011088848114', 'lastCheck': '3.7', 'code': 0, 'valid': True}}
>Thread-63055::DEBUG::2013-02-07 09:41:45,419::task::1172::TaskManager.Task::(prepare) Task=`fde95f1f-b647-400a-99f9-dded45f210e0`::finished: {u'b77c0314-88e8-45e0-bad7-eb76fab05979': {'delay': '0.000838994979858', 'lastCheck': '3.7', 'code': 0, 'valid': True}, u'8e3975e8-fe95-4833-a245-228f0bf0c9ec': {'delay': '0.0102298259735', 'lastCheck': '9.0', 'code': 0, 'valid': True}, u'1ef3e2fc-eac0-4bf3-b604-fbc4d972be83': {'delay': '0.0011088848114', 'lastCheck': '3.7', 'code': 0, 'valid': True}}
>Thread-63055::DEBUG::2013-02-07 09:41:45,419::task::588::TaskManager.Task::(_updateState) Task=`fde95f1f-b647-400a-99f9-dded45f210e0`::moving from state preparing -> state finished
>Thread-63055::DEBUG::2013-02-07 09:41:45,420::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-63055::DEBUG::2013-02-07 09:41:45,420::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-63055::DEBUG::2013-02-07 09:41:45,420::task::978::TaskManager.Task::(_decref) Task=`fde95f1f-b647-400a-99f9-dded45f210e0`::ref 0 aborting False
>Thread-63056::DEBUG::2013-02-07 09:41:45,451::libvirtvm::267::vm.Vm::(_getDiskStats) vmId=`ad448438-4645-4bfd-86ad-016720b48937`::Disk hdc stats not available
>Thread-63056::DEBUG::2013-02-07 09:41:45,452::libvirtvm::267::vm.Vm::(_getDiskStats) vmId=`0b688f6d-d36e-4ea3-aa78-a6e90357b89a`::Disk hdc stats not available
>Thread-35::DEBUG::2013-02-07 09:41:46,402::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/dd iflag=direct if=/dev/8e3975e8-fe95-4833-a245-228f0bf0c9ec/metadata bs=4096 count=1' (cwd None)
>Thread-35::DEBUG::2013-02-07 09:41:46,412::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000742434 s, 5.5 MB/s\n'; <rc> = 0
>Thread-63057::DEBUG::2013-02-07 09:41:47,685::task::588::TaskManager.Task::(_updateState) Task=`ec7c2518-8931-4b2f-b68b-f6478aae7802`::moving from state init -> state preparing
>Thread-63057::INFO::2013-02-07 09:41:47,685::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-63057::INFO::2013-02-07 09:41:47,686::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'b77c0314-88e8-45e0-bad7-eb76fab05979': {'delay': '0.000838994979858', 'lastCheck': '6.0', 'code': 0, 'valid': True}, u'8e3975e8-fe95-4833-a245-228f0bf0c9ec': {'delay': '0.0100810527802', 'lastCheck': '1.3', 'code': 0, 'valid': True}, u'1ef3e2fc-eac0-4bf3-b604-fbc4d972be83': {'delay': '0.0011088848114', 'lastCheck': '6.0', 'code': 0, 'valid': True}}
>Thread-63057::DEBUG::2013-02-07 09:41:47,686::task::1172::TaskManager.Task::(prepare) Task=`ec7c2518-8931-4b2f-b68b-f6478aae7802`::finished: {u'b77c0314-88e8-45e0-bad7-eb76fab05979': {'delay': '0.000838994979858', 'lastCheck': '6.0', 'code': 0, 'valid': True}, u'8e3975e8-fe95-4833-a245-228f0bf0c9ec': {'delay': '0.0100810527802', 'lastCheck': '1.3', 'code': 0, 'valid': True}, u'1ef3e2fc-eac0-4bf3-b604-fbc4d972be83': {'delay': '0.0011088848114', 'lastCheck': '6.0', 'code': 0, 'valid': True}}
>Thread-63057::DEBUG::2013-02-07 09:41:47,686::task::588::TaskManager.Task::(_updateState) Task=`ec7c2518-8931-4b2f-b68b-f6478aae7802`::moving from state preparing -> state finished
>Thread-63057::DEBUG::2013-02-07 09:41:47,686::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-63057::DEBUG::2013-02-07 09:41:47,687::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-63057::DEBUG::2013-02-07 09:41:47,687::task::978::TaskManager.Task::(_decref) Task=`ec7c2518-8931-4b2f-b68b-f6478aae7802`::ref 0 aborting False

Actions: View

Attachments on bug 910014: 696172 | 696811 | 696812