Bug 1088974

related thread in vdsm error.log

Thread-255002::DEBUG::2014-04-17 16:33:50,666::BindingXMLRPC::167::vds::(wrapper) client [10.0.0.11]
Thread-255002::DEBUG::2014-04-17 16:33:50,667::task::579::TaskManager.Task::(_updateState) Task=`065e1d60-f777-4d0d-9eae-cfd4f13e357d`::moving from state init -> state preparing
Thread-255002::INFO::2014-04-17 16:33:50,667::logUtils::44::dispatcher::(wrapper) Run and protect: getStorageDomainInfo(sdUUID='b784393a-f5ce-4cb0-8b6d-4055bb9158b5', options=None)
Thread-255002::INFO::2014-04-17 16:33:50,667::blockSD::828::Storage.StorageDomain::(validate) sdUUID=b784393a-f5ce-4cb0-8b6d-4055bb9158b5
Thread-255002::DEBUG::2014-04-17 16:33:50,668::lvm::309::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm vgck --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 wr
ite_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/1IET_00010001|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }
  backup {  retain_min = 50  retain_days = 0 } " b784393a-f5ce-4cb0-8b6d-4055bb9158b5' (cwd None)
Dummy-46::DEBUG::2014-04-17 16:33:50,802::storage_mailbox::733::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/207affff-2b56-4078-9414-439054bcbb70/mastersd/dom_md/inbox iflag=direct,fullblock
 count=1 bs=1024000' (cwd None)
Thread-255002::DEBUG::2014-04-17 16:33:50,861::lvm::309::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
Thread-255002::DEBUG::2014-04-17 16:33:50,865::lvm::516::OperationMutex::(_invalidatevgs) Operation 'lvm invalidate operation' got the operation mutex
Thread-255002::DEBUG::2014-04-17 16:33:50,867::lvm::518::OperationMutex::(_invalidatevgs) Operation 'lvm invalidate operation' released the operation mutex
Thread-255002::DEBUG::2014-04-17 16:33:50,870::lvm::526::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-255002::DEBUG::2014-04-17 16:33:50,872::lvm::538::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-255002::DEBUG::2014-04-17 16:33:50,874::lvm::386::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
Thread-255002::DEBUG::2014-04-17 16:33:50,882::lvm::309::Storage.Misc.excCmd::(cmd) '/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 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/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 | --ignoreskippedcluster -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free,lv_count,pv_count,pv_name b784393a-f5ce-4cb0-8b6d-4055bb9158b5' (cwd None)
Dummy-46::DEBUG::2014-04-17 16:33:50,950::storage_mailbox::733::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0399343 s, 25.6 MB/s\n'; <rc> = 0
Thread-255002::DEBUG::2014-04-17 16:33:51,066::lvm::309::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
Thread-255002::DEBUG::2014-04-17 16:33:51,069::lvm::428::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
Thread-255002::DEBUG::2014-04-17 16:33:51,069::persistentDict::234::Storage.PersistentDict::(refresh) read lines (VGTagMetadataRW)=['DESCRIPTION=111gb', 'LOCKPOLICY=', 'VERSION=3', 'TYPE=ISCSI', 'LOGBLKSIZE=512', 'LEASERETRIES=3', 'VGUUID=6vAOD7-dG1r-QEuP-SKp0-H31d-Qozv-QO25jX', 'LOCKRENEWALINTERVALSEC=5', 'PHYBLKSIZE=512', 'SDUUID=b784393a-f5ce-4cb0-8b6d-4055bb9158b5', u'PV0=pv:1IET_00010001,uuid:917cOt-vxn9-5gdd-gc6k-hoB0-F9eu-TJIOkz,pestart:0,pecount:885,mapoffset:0', 'CLASS=Data', 'LEASETIMESEC=60', 'IOOPTIMEOUTSEC=10', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=jekader', 'ROLE=Master', 'POOL_UUID=207affff-2b56-4078-9414-439054bcbb70', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=37', u'POOL_DOMAINS=61726b62-e6d0-4b36-83de-1fa24a3899e5:Active,b784393a-f5ce-4cb0-8b6d-4055bb9158b5:Active', '_SHA_CKSUM=276b99ce1ad9f3da59c8844a68990d463e75cb2f']
Thread-255002::DEBUG::2014-04-17 16:33:51,071::resourceManager::197::ResourceManager.Request::(__init__) ResName=`Storage.b784393a-f5ce-4cb0-8b6d-4055bb9158b5`ReqID=`e9b701bd-c3f5-4c2e-bb8d-30bb8a1e941a`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2759' at 'getStorageDomainInfo'
Thread-255002::DEBUG::2014-04-17 16:33:51,071::resourceManager::541::ResourceManager::(registerResource) Trying to register resource 'Storage.b784393a-f5ce-4cb0-8b6d-4055bb9158b5' for lock type 'shared'
Thread-255002::DEBUG::2014-04-17 16:33:51,071::resourceManager::600::ResourceManager::(registerResource) Resource 'Storage.b784393a-f5ce-4cb0-8b6d-4055bb9158b5' is free. Now locking as 'shared' (1 active user)
Thread-255002::DEBUG::2014-04-17 16:33:51,072::resourceManager::237::ResourceManager.Request::(grant) ResName=`Storage.b784393a-f5ce-4cb0-8b6d-4055bb9158b5`ReqID=`e9b701bd-c3f5-4c2e-bb8d-30bb8a1e941a`::Granted request
Thread-255002::DEBUG::2014-04-17 16:33:51,072::task::811::TaskManager.Task::(resourceAcquired) Task=`065e1d60-f777-4d0d-9eae-cfd4f13e357d`::_resourcesAcquired: Storage.b784393a-f5ce-4cb0-8b6d-4055bb9158b5 (shared)
Thread-255002::DEBUG::2014-04-17 16:33:51,072::task::974::TaskManager.Task::(_decref) Task=`065e1d60-f777-4d0d-9eae-cfd4f13e357d`::ref 1 aborting False
Thread-255002::ERROR::2014-04-17 16:33:51,074::task::850::TaskManager.Task::(_setError) Task=`065e1d60-f777-4d0d-9eae-cfd4f13e357d`::Unexpected error
Traceback (most recent call last):
 File "/usr/share/vdsm/storage/task.py", line 857, in _run
    return fn(*args, **kargs)
  File "/usr/share/vdsm/logUtils.py", line 45, in wrapper
    res = f(*args, **kwargs)
  File "/usr/share/vdsm/storage/hsm.py", line 2778, in getStorageDomainInfo
    info[key] = poolInfo['info'][key]
KeyError: 'info'
Thread-255002::DEBUG::2014-04-17 16:33:51,075::task::869::TaskManager.Task::(_run) Task=`065e1d60-f777-4d0d-9eae-cfd4f13e357d`::Task._run: 065e1d60-f777-4d0d-9eae-cfd4f13e357d ('b784393a-f5ce-4cb0-8b6d-4055bb9158b5',) {} failed - stopping task
Thread-255002::DEBUG::2014-04-17 16:33:51,075::task::1194::TaskManager.Task::(stop) Task=`065e1d60-f777-4d0d-9eae-cfd4f13e357d`::stopping in state preparing (force False)
Thread-255002::DEBUG::2014-04-17 16:33:51,075::task::974::TaskManager.Task::(_decref) Task=`065e1d60-f777-4d0d-9eae-cfd4f13e357d`::ref 1 aborting True
Thread-255002::INFO::2014-04-17 16:33:51,076::task::1151::TaskManager.Task::(prepare) Task=`065e1d60-f777-4d0d-9eae-cfd4f13e357d`::aborting: Task is aborted: u"'info'" - code 100
Thread-255002::DEBUG::2014-04-17 16:33:51,076::task::1156::TaskManager.Task::(prepare) Task=`065e1d60-f777-4d0d-9eae-cfd4f13e357d`::Prepare: aborted: 'info'
Thread-255002::DEBUG::2014-04-17 16:33:51,076::task::974::TaskManager.Task::(_decref) Task=`065e1d60-f777-4d0d-9eae-cfd4f13e357d`::ref 0 aborting True
Thread-255002::DEBUG::2014-04-17 16:33:51,076::task::909::TaskManager.Task::(_doAbort) Task=`065e1d60-f777-4d0d-9eae-cfd4f13e357d`::Task._doAbort: force False
Thread-255002::DEBUG::2014-04-17 16:33:51,077::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-255002::DEBUG::2014-04-17 16:33:51,077::task::579::TaskManager.Task::(_updateState) Task=`065e1d60-f777-4d0d-9eae-cfd4f13e357d`::moving from state preparing -> state aborting
Thread-255002::DEBUG::2014-04-17 16:33:51,077::task::534::TaskManager.Task::(__state_aborting) Task=`065e1d60-f777-4d0d-9eae-cfd4f13e357d`::_aborting: recover policy none
Thread-255002::DEBUG::2014-04-17 16:33:51,077::task::579::TaskManager.Task::(_updateState) Task=`065e1d60-f777-4d0d-9eae-cfd4f13e357d`::moving from state aborting -> state failed
Thread-255002::DEBUG::2014-04-17 16:33:51,078::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.b784393a-f5ce-4cb0-8b6d-4055bb9158b5': < ResourceRef 'Storage.b784393a-f5ce-4cb0-8b6d-4055bb9158b5', isValid: 'True' obj: 'None'>}
Thread-255002::DEBUG::2014-04-17 16:33:51,078::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-255002::DEBUG::2014-04-17 16:33:51,078::resourceManager::615::ResourceManager::(releaseResource) Trying to release resource 'Storage.b784393a-f5ce-4cb0-8b6d-4055bb9158b5'
Thread-255002::DEBUG::2014-04-17 16:33:51,079::resourceManager::634::ResourceManager::(releaseResource) Released resource 'Storage.b784393a-f5ce-4cb0-8b6d-4055bb9158b5' (0 active users)
Thread-255002::DEBUG::2014-04-17 16:33:51,079::resourceManager::640::ResourceManager::(releaseResource) Resource 'Storage.b784393a-f5ce-4cb0-8b6d-4055bb9158b5' is free, finding out if anyone is waiting for it.
Thread-255002::DEBUG::2014-04-17 16:33:51,079::resourceManager::648::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.b784393a-f5ce-4cb0-8b6d-4055bb9158b5', Clearing records.
Thread-255002::ERROR::2014-04-17 16:33:51,079::dispatcher::70::Storage.Dispatcher.Protect::(run) 'info'
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/dispatcher.py", line 62, in run
    result = ctask.prepare(self.func, *args, **kwargs)
  File "/usr/share/vdsm/storage/task.py", line 1159, in prepare
    raise self.error
KeyError: 'info'

Yoav/Federico, didn't you already solve a similar issue>?

*** This bug has been marked as a duplicate of bug 1084970 ***

(In reply to Allon Mureinik from comment #2)
> Yoav/Federico, didn't you already solve a similar issue>?
Yoav/Federico, feel free to ignore the question - started typing it and then found the dup myself.
This is clearly the same issue as bug 1084970