Bug 1088974 - vdsClient: Error in storage domain action
Summary: vdsClient: Error in storage domain action
Keywords:
Status: CLOSED DUPLICATE of bug 1084970
Alias: None
Product: Red Hat Enterprise Virtualization Manager
Classification: Red Hat
Component: vdsm
Version: 3.3.0
Hardware: Unspecified
OS: Unspecified
unspecified
medium
Target Milestone: ---
: 3.4.0
Assignee: Yoav Kleinberger
QA Contact: Aharon Canan
URL:
Whiteboard: storage
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2014-04-17 14:38 UTC by Evgheni Dereveanchin
Modified: 2019-04-28 09:59 UTC (History)
5 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2014-04-21 15:12:06 UTC
oVirt Team: Storage
Target Upstream Version:


Attachments (Terms of Use)

Description Evgheni Dereveanchin 2014-04-17 14:38:26 UTC
Description of problem:
When attempting to display storage domain information, an error is displayed. The storage domain is in fact active and operational.

Version-Release number of selected component (if applicable):
vdsm-cli-4.13.2-0.13.el6ev.noarch
vdsm-4.13.2-0.13.el6ev.x86_64

Steps to Reproduce:
1. list storage doamins on a hypervisor:
# vdsClient -s 0 getStorageDomainsList
b784393a-f5ce-4cb0-8b6d-4055bb9158b5
61726b62-e6d0-4b36-83de-1fa24a3899e5

2. try to get information about a storage domain:
# vdsClient -s 0 getStorageDomainInfo b784393a-f5ce-4cb0-8b6d-4055bb9158b

Actual results:
# vdsClient -s 0 getStorageDomainInfo b784393a-f5ce-4cb0-8b6d-4055bb9158b5
Error in storage domain action: ('sdUUID=b784393a-f5ce-4cb0-8b6d-4055bb9158b5',)

Expected results:
# vdsClient -s 0 getStorageDomainInfo 61726b62-e6d0-4b36-83de-1fa24a3899e5
        uuid = 61726b62-e6d0-4b36-83de-1fa24a3899e5
        pool = ['207affff-2b56-4078-9414-439054bcbb70']
        lver = -1
        version = 0
        role = Regular
        remotePath = test.lan:/var/lib/exports/iso
        spm_id = -1
        type = NFS
        class = Iso
        master_ver = 0
        name = ISO_DOMAIN

Comment 1 Evgheni Dereveanchin 2014-04-17 14:40:10 UTC
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'

Comment 2 Allon Mureinik 2014-04-21 15:12:06 UTC
Yoav/Federico, didn't you already solve a similar issue>?

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

Comment 3 Allon Mureinik 2014-04-21 15:13:16 UTC
(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


Note You need to log in before you can comment on or make changes to this bug.