Created attachment 558818 [details]
Engine, vdsm logs

Description of problem:
If something is wrong with ISO domain, ISO domain cannot be dactivated. This causes SPM failover in backend every time when something is read from the domain.

Version-Release number of selected component (if applicable):
ovirt-engine-3.0.0_0001-1.4.fc16.x86_64
vdsm-4.9.3.2-0.fc16.x86_64

How reproducible:
Always

Steps to Reproduce:
1. Change permissions on storage within exported iso directory (e.g. 000)
  
Actual results:
ISO domain stays in Active status and causes SPM failover every time domain is read

Expected results:
ISO domain goes Inactive

Additional info:
Thread-6673::DEBUG::2012-02-01 13:00:57,253::clientIF::261::Storage.Dispatcher.Protect::(wrapper) [10.34.63.26]
Thread-6673::DEBUG::2012-02-01 13:00:57,254::task::588::TaskManager.Task::(_updateState) Task=`18aa6518-7ce5-47b8-8230-0cbcf8e93140`::moving from state init -> state preparing
Thread-6673::INFO::2012-02-01 13:00:57,254::logUtils::37::dispatcher::(wrapper) Run and protect: deactivateStorageDomain(sdUUID='0ce26a62-d3d5-4179-989b-17b9dcbbd0a2', spUUID='206cfac0-ed3b-43f2-b213-c216ed8e1c5b', msdUUID='00000000-0000-0000-0000-000000000000', masterVersion=1, options=None)
Thread-6673::DEBUG::2012-02-01 13:00:57,255::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.206cfac0-ed3b-43f2-b213-c216ed8e1c5b`ReqID=`bb494fbd-e367-4496-a3b0-4e23d8ad6aef`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '892' at 'deactivateStorageDomain'
Thread-6673::DEBUG::2012-02-01 13:00:57,256::resourceManager::483::ResourceManager::(registerResource) Trying to register resource 'Storage.206cfac0-ed3b-43f2-b213-c216ed8e1c5b' for lock type 'exclusive'
Thread-6673::DEBUG::2012-02-01 13:00:57,256::resourceManager::525::ResourceManager::(registerResource) Resource 'Storage.206cfac0-ed3b-43f2-b213-c216ed8e1c5b' is free. Now locking as 'exclusive' (1 active user)
Thread-6673::DEBUG::2012-02-01 13:00:57,256::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.206cfac0-ed3b-43f2-b213-c216ed8e1c5b`ReqID=`bb494fbd-e367-4496-a3b0-4e23d8ad6aef`::Granted request
Thread-6673::DEBUG::2012-02-01 13:00:57,257::task::819::TaskManager.Task::(resourceAcquired) Task=`18aa6518-7ce5-47b8-8230-0cbcf8e93140`::_resourcesAcquired: Storage.206cfac0-ed3b-43f2-b213-c216ed8e1c5b (exclusive)
Thread-6673::DEBUG::2012-02-01 13:00:57,257::task::980::TaskManager.Task::(_decref) Task=`18aa6518-7ce5-47b8-8230-0cbcf8e93140`::ref 1 aborting False
Thread-6673::DEBUG::2012-02-01 13:00:57,258::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.0ce26a62-d3d5-4179-989b-17b9dcbbd0a2`ReqID=`4def574f-2d4c-4334-9317-620b92da4489`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '893' at 'deactivateStorageDomain'
Thread-6673::DEBUG::2012-02-01 13:00:57,258::resourceManager::483::ResourceManager::(registerResource) Trying to register resource 'Storage.0ce26a62-d3d5-4179-989b-17b9dcbbd0a2' for lock type 'exclusive'
Thread-6673::DEBUG::2012-02-01 13:00:57,259::resourceManager::525::ResourceManager::(registerResource) Resource 'Storage.0ce26a62-d3d5-4179-989b-17b9dcbbd0a2' is free. Now locking as 'exclusive' (1 active user)
Thread-6673::DEBUG::2012-02-01 13:00:57,259::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.0ce26a62-d3d5-4179-989b-17b9dcbbd0a2`ReqID=`4def574f-2d4c-4334-9317-620b92da4489`::Granted request
Thread-6673::DEBUG::2012-02-01 13:00:57,261::task::819::TaskManager.Task::(resourceAcquired) Task=`18aa6518-7ce5-47b8-8230-0cbcf8e93140`::_resourcesAcquired: Storage.0ce26a62-d3d5-4179-989b-17b9dcbbd0a2 (exclusive)
Thread-6673::DEBUG::2012-02-01 13:00:57,261::task::980::TaskManager.Task::(_decref) Task=`18aa6518-7ce5-47b8-8230-0cbcf8e93140`::ref 1 aborting False
Thread-6673::INFO::2012-02-01 13:00:57,261::sp::1020::Storage.StoragePool::(deactivateSD) sdUUID=0ce26a62-d3d5-4179-989b-17b9dcbbd0a2 spUUID=206cfac0-ed3b-43f2-b213-c216ed8e1c5b new_msdUUID=00000000-0000-0000-0000-000000000000
Thread-6673::INFO::2012-02-01 13:00:57,262::fileSD::195::Storage.StorageDomain::(validate) sdUUID=0ce26a62-d3d5-4179-989b-17b9dcbbd0a2
Thread-6673::DEBUG::2012-02-01 13:00:57,262::persistentDict::216::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=[]
Thread-6673::WARNING::2012-02-01 13:00:57,263::persistentDict::238::Storage.PersistentDict::(refresh) data has no embedded checksum - trust it as it is
Thread-6673::ERROR::2012-02-01 13:00:57,263::task::855::TaskManager.Task::(_setError) Task=`18aa6518-7ce5-47b8-8230-0cbcf8e93140`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 863, in _run
    return fn(*args, **kargs)
  File "/usr/share/vdsm/logUtils.py", line 38, in wrapper
    res = f(*args, **kwargs)
  File "/usr/share/vdsm/storage/hsm.py", line 895, in deactivateStorageDomain
    pool.deactivateSD(sdUUID, msdUUID, masterVersion)
  File "/usr/share/vdsm/storage/securable.py", line 80, in wrapper
    return f(*args, **kwargs)
  File "/usr/share/vdsm/storage/sp.py", line 1043, in deactivateSD
    elif dom.isBackup():
  File "/usr/share/vdsm/storage/sd.py", line 662, in isBackup
    return self.getMetaParam(DMDK_CLASS) == BACKUP_DOMAIN
  File "/usr/share/vdsm/storage/sd.py", line 616, in getMetaParam
    return self._metadata[key]
  File "/usr/share/vdsm/storage/persistentDict.py", line 75, in __getitem__
    return dec(self._dict[key])
  File "/usr/share/vdsm/storage/persistentDict.py", line 185, in __getitem__
    raise KeyError(key)
Thread-6673::DEBUG::2012-02-01 13:00:57,264::task::874::TaskManager.Task::(_run) Task=`18aa6518-7ce5-47b8-8230-0cbcf8e93140`::Task._run: 18aa6518-7ce5-47b8-8230-0cbcf8e93140 ('0ce26a62-d3d5-4179-989b-17b9dcbbd0a2', '206cfac0-ed3b-43f2-b213-c216ed8e1c5b', '00000000-0000-0000-0000-000000000000', 1) {} failed - stopping task
Thread-6673::DEBUG::2012-02-01 13:00:57,264::task::1201::TaskManager.Task::(stop) Task=`18aa6518-7ce5-47b8-8230-0cbcf8e93140`::stopping in state preparing (force False)
Thread-6673::DEBUG::2012-02-01 13:00:57,265::task::980::TaskManager.Task::(_decref) Task=`18aa6518-7ce5-47b8-8230-0cbcf8e93140`::ref 1 aborting True
Thread-6673::INFO::2012-02-01 13:00:57,265::task::1159::TaskManager.Task::(prepare) Task=`18aa6518-7ce5-47b8-8230-0cbcf8e93140`::aborting: Task is aborted: "'CLASS'" - code 100
Thread-6673::DEBUG::2012-02-01 13:00:57,265::task::1164::TaskManager.Task::(prepare) Task=`18aa6518-7ce5-47b8-8230-0cbcf8e93140`::Prepare: aborted: 'CLASS'
Thread-6673::DEBUG::2012-02-01 13:00:57,266::task::980::TaskManager.Task::(_decref) Task=`18aa6518-7ce5-47b8-8230-0cbcf8e93140`::ref 0 aborting True
Thread-6673::DEBUG::2012-02-01 13:00:57,266::task::915::TaskManager.Task::(_doAbort) Task=`18aa6518-7ce5-47b8-8230-0cbcf8e93140`::Task._doAbort: force False
Thread-6673::DEBUG::2012-02-01 13:00:57,267::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-6673::DEBUG::2012-02-01 13:00:57,267::task::588::TaskManager.Task::(_updateState) Task=`18aa6518-7ce5-47b8-8230-0cbcf8e93140`::moving from state preparing -> state aborting
Thread-6673::DEBUG::2012-02-01 13:00:57,267::task::537::TaskManager.Task::(__state_aborting) Task=`18aa6518-7ce5-47b8-8230-0cbcf8e93140`::_aborting: recover policy none
Thread-6673::DEBUG::2012-02-01 13:00:57,268::task::588::TaskManager.Task::(_updateState) Task=`18aa6518-7ce5-47b8-8230-0cbcf8e93140`::moving from state aborting -> state failed
Thread-6673::DEBUG::2012-02-01 13:00:57,268::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.206cfac0-ed3b-43f2-b213-c216ed8e1c5b': < ResourceRef 'Storage.206cfac0-ed3b-43f2-b213-c216ed8e1c5b', isValid: 'True' obj: 'None'>, 'Storage.0ce26a62-d3d5-4179-989b-17b9dcbbd0a2': < ResourceRef 'Storage.0ce26a62-d3d5-4179-989b-17b9dcbbd0a2', isValid: 'True' obj: 'None'>}
Thread-6673::DEBUG::2012-02-01 13:00:57,269::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-6673::DEBUG::2012-02-01 13:00:57,269::resourceManager::535::ResourceManager::(releaseResource) Trying to release resource 'Storage.206cfac0-ed3b-43f2-b213-c216ed8e1c5b'
Thread-6673::DEBUG::2012-02-01 13:00:57,269::resourceManager::550::ResourceManager::(releaseResource) Released resource 'Storage.206cfac0-ed3b-43f2-b213-c216ed8e1c5b' (0 active users)
Thread-6673::DEBUG::2012-02-01 13:00:57,270::resourceManager::555::ResourceManager::(releaseResource) Resource 'Storage.206cfac0-ed3b-43f2-b213-c216ed8e1c5b' is free, finding out if anyone is waiting for it.
Thread-6673::DEBUG::2012-02-01 13:00:57,270::resourceManager::562::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.206cfac0-ed3b-43f2-b213-c216ed8e1c5b', Clearing records.
Thread-6673::DEBUG::2012-02-01 13:00:57,270::resourceManager::535::ResourceManager::(releaseResource) Trying to release resource 'Storage.0ce26a62-d3d5-4179-989b-17b9dcbbd0a2'
Thread-6673::DEBUG::2012-02-01 13:00:57,270::resourceManager::550::ResourceManager::(releaseResource) Released resource 'Storage.0ce26a62-d3d5-4179-989b-17b9dcbbd0a2' (0 active users)
Thread-6673::DEBUG::2012-02-01 13:00:57,271::resourceManager::555::ResourceManager::(releaseResource) Resource 'Storage.0ce26a62-d3d5-4179-989b-17b9dcbbd0a2' is free, finding out if anyone is waiting for it.
Thread-6673::DEBUG::2012-02-01 13:00:57,271::resourceManager::562::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.0ce26a62-d3d5-4179-989b-17b9dcbbd0a2', Clearing records.
Thread-6673::ERROR::2012-02-01 13:00:57,271::dispatcher::93::Storage.Dispatcher.Protect::(run) 'CLASS'
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/dispatcher.py", line 85, in run
    result = ctask.prepare(self.func, *args, **kwargs)
  File "/usr/share/vdsm/storage/task.py", line 1166, in prepare
    raise self.error
KeyError: 'CLASS'