Bug 920220 - [backend] SpmStopVDSCommand didn't stop SPM in VDSM
Summary: [backend] SpmStopVDSCommand didn't stop SPM in VDSM
Keywords:
Status: CLOSED DUPLICATE of bug 918588
Alias: None
Product: Red Hat Enterprise Virtualization Manager
Classification: Red Hat
Component: ovirt-engine
Version: 3.2.0
Hardware: All
OS: Linux
unspecified
high
Target Milestone: ---
: 3.2.0
Assignee: Liron Aravot
QA Contact: Jakub Libosvar
URL:
Whiteboard: storage
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2013-03-11 15:31 UTC by Jakub Libosvar
Modified: 2016-02-10 17:42 UTC (History)
9 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2013-03-13 14:06:03 UTC
oVirt Team: Storage
Target Upstream Version:


Attachments (Terms of Use)
logs (3.33 MB, application/x-bzip)
2013-03-11 15:31 UTC, Jakub Libosvar
no flags Details

Description Jakub Libosvar 2013-03-11 15:31:40 UTC
Created attachment 708470 [details]
logs

Description of problem:
There was one storage domain in DC, one host. Deactivate domain was called but failed with Operation not allowed while SPM is active

Cause is that there was no spmStop in vdsm before disconnectStoragePool

Engine:
2013-03-11 16:45:32,723 INFO  [org.ovirt.engine.core.bll.storage.DeactivateStorageDomainCommand] (ajp-/127.0.0.1:8702-6) [5c1908b6] Lock Acquired to object EngineLock [exclusiveLocks= key: 6969f79a-8f74-415c-b2f7-784d050df2f1 value: POOL
key: 469060ca-251e-4b92-932e-5efc1e55e6ad value: STORAGE
, sharedLocks= ]
2013-03-11 16:45:32,758 INFO  [org.ovirt.engine.core.bll.storage.DeactivateStorageDomainCommand] (ajp-/127.0.0.1:8702-6) [5c1908b6] Running command: DeactivateStorageDomainCommand internal: false. Entities affected :  ID: 469060ca-251e-4b92-932e-5efc1e55e6ad Type: Storage
2013-03-11 16:45:32,803 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.DeactivateStorageDomainVDSCommand] (ajp-/127.0.0.1:8702-6) [5c1908b6] START, DeactivateStorageDomainVDSCommand( storagePoolId = 6969f79a-8f74-415c-b2f7-784d050df2f1, ignoreFailoverLimit = false, compatabilityVersion = null, storageDomainId = 469060ca-251e-4b92-932e-5efc1e55e6ad, masterDomainId = 00000000-0000-0000-0000-000000000000, masterVersion = 1), log id: 789c60f6
2013-03-11 16:45:32,844 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.DeactivateStorageDomainVDSCommand] (ajp-/127.0.0.1:8702-6) [5c1908b6] FINISH, DeactivateStorageDomainVDSCommand, log id: 789c60f6
2013-03-11 16:45:32,845 INFO  [org.ovirt.engine.core.bll.storage.DeactivateStorageDomainCommand] (ajp-/127.0.0.1:8702-6) [5c1908b6] Lock freed to object EngineLock [exclusiveLocks= key: 6969f79a-8f74-415c-b2f7-784d050df2f1 value: POOL
key: 469060ca-251e-4b92-932e-5efc1e55e6ad value: STORAGE
, sharedLocks= ]
2013-03-11 16:45:32,848 INFO  [org.ovirt.engine.core.bll.storage.AfterDeactivateSingleAsyncOperation] (pool-3-thread-49) [5c1908b6] After deactivate treatment vds: 10.35.160.61,pool dc_nfs_upgrade_30_32
2013-03-11 16:45:32,850 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.SpmStopOnIrsVDSCommand] (ajp-/127.0.0.1:8702-6) [5c1908b6] START, SpmStopOnIrsVDSCommand( storagePoolId = 6969f79a-8f74-415c-b2f7-784d050df2f1, ignoreFailoverLimit = false, compatabilityVersion = null), log id: 2c78a683
2013-03-11 16:45:32,851 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.ResetIrsVDSCommand] (ajp-/127.0.0.1:8702-6) [5c1908b6] START, ResetIrsVDSCommand( storagePoolId = 6969f79a-8f74-415c-b2f7-784d050df2f1, ignoreFailoverLimit = false, compatabilityVersion = null, vdsId = 9c3b2ae4-1c2d-41af-ac7f-0ec49fc992f5, ignoreStopFailed = false), log id: 24fbf944
2013-03-11 16:45:32,855 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStopVDSCommand] (ajp-/127.0.0.1:8702-6) [5c1908b6] START, SpmStopVDSCommand(HostName = 10.35.160.61, HostId = 9c3b2ae4-1c2d-41af-ac7f-0ec49fc992f5, storagePoolId = 6969f79a-8f74-415c-b2f7-784d050df2f1), log id: 46cfbead
2013-03-11 16:45:32,903 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStopVDSCommand] (ajp-/127.0.0.1:8702-6) [5c1908b6] FINISH, SpmStopVDSCommand, log id: 46cfbead
2013-03-11 16:45:32,903 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.ResetIrsVDSCommand] (ajp-/127.0.0.1:8702-6) [5c1908b6] FINISH, ResetIrsVDSCommand, log id: 24fbf944
2013-03-11 16:45:32,903 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.SpmStopOnIrsVDSCommand] (ajp-/127.0.0.1:8702-6) [5c1908b6] FINISH, SpmStopOnIrsVDSCommand, log id: 2c78a683
2013-03-11 16:45:32,906 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.DisconnectStoragePoolVDSCommand] (ajp-/127.0.0.1:8702-6) [5c1908b6] START, DisconnectStoragePoolVDSCommand(HostName = 10.35.160.61, HostId = 9c3b2ae4-1c2d-41af-ac7f-0ec49fc992f5, storagePoolId = 6969f79a-8f74-415c-b2f7-784d050df2f1, vds_spm_id = 1), log id: 4e3eb463

Vdsm:
Thread-2179::INFO::2013-03-11 16:45:32,268::logUtils::39::dispatcher::(wrapper) Run and protect: disconnectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': '79b049f2-560b-491a-b6e7-51ec551c7a97'}]}
Thread-2182::INFO::2013-03-11 16:45:32,819::logUtils::37::dispatcher::(wrapper) Run and protect: deactivateStorageDomain(sdUUID='469060ca-251e-4b92-932e-5efc1e55e6ad', spUUID='6969f79a-8f74-415c-b2f7-784d050df2f1', msdUUID='00000000-0000-0000-0000-000000000000', masterVersion=1, options=None)
Thread-2182::INFO::2013-03-11 16:45:32,825::logUtils::39::dispatcher::(wrapper) Run and protect: deactivateStorageDomain, Return response: None
Thread-2185::INFO::2013-03-11 16:45:33,023::logUtils::37::dispatcher::(wrapper) Run and protect: disconnectStoragePool(spUUID='6969f79a-8f74-415c-b2f7-784d050df2f1', hostID=1, scsiKey='6969f79a-8f74-415c-b2f7-784d050df2f1', remove=False, options=None)
Thread-2185::ERROR::2013-03-11 16:45:33,023::task::833::TaskManager.Task::(_setError) Task=`6bbd02fa-8b9f-458f-9f25-c20402941f19`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 840, 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 1011, in disconnectStoragePool
    self.validateNotSPM(spUUID)
  File "/usr/share/vdsm/storage/hsm.py", line 308, in validateNotSPM
    raise se.IsSpm(spUUID)
IsSpm: Operation not allowed while SPM is active: ('6969f79a-8f74-415c-b2f7-784d050df2f1',)


Version-Release number of selected component (if applicable):
rhevm-3.2.0-10.10.beta1.el6ev.noarch
vdsm-4.10.2-10.0.el6ev.x86_64

How reproducible:
Not sure

Steps to Reproduce:
1. Deactivate last storage domain
2.
3.
  
Actual results:


Expected results:


Additional info:
DC was created as 3.0 at around 16:31:33, NFS v1 domain was attached and then DC was upgraded to 3.2 and NFS domain to v3.

Attaching whole test log

Comment 6 Ayal Baron 2013-03-13 09:49:41 UTC
Liron, we need to understand why spmStop wasn't sent to vdsm.

Comment 7 Liron Aravot 2013-03-13 13:52:10 UTC
seems like spmStop wasn't sent because there were tasks

Thread-2184::DEBUG::2013-03-11 16:45:32,887::task::1151::TaskManager.Task::(prepare) Task=`fda2214f-30ed-480c-be23-e93cc2a03f95`::finished: {'allTasksStatus': {'fa917046-91b
7-49c3-93ca-825dafcf4473': {'code': 0, 'message': u'1 jobs completed successfully', 'taskState': 'finished', 'taskResult': 'success', 'taskID': 'fa917046-91b7-49c3-93ca-825d
afcf4473'}}}
Thread-2184::DEBUG::2013-03-11 16:45:32,887::task::568::TaskManager.Task::(_updateState) Task=`fda2214f-30ed-480c-be23-e93cc2a03f95`::moving from state preparing -> state fi
nished
Thread-2184::DEBUG::2013-03-11 16:45:32,888::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-2184::DEBUG::2013-03-11 16:45:32,888::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-2184::DEBUG::2013-03-11 16:45:32,888::task::957::TaskManager.Task::(_decref) Task=`fda2214f-30ed-480c-be23-e93cc2a03f95`::ref 0 aborting False
Thread-2185::DEBUG::2013-03-11 16:45:32,929::BindingXMLRPC::161::vds::(wrapper) [10.35.161.50]
Thread-2185::DEBUG::2013-03-11 16:45:33,023::task::568::TaskManager.Task::(_updateState) Task=`6bbd02fa-8b9f-458f-9f25-c20402941f19`::moving from state init -> state prepari
ng
Thread-2185::INFO::2013-03-11 16:45:33,023::logUtils::37::dispatcher::(wrapper) Run and protect: disconnectStoragePool(spUUID='6969f79a-8f74-415c-b2f7-784d050df2f1', hostID=
1, scsiKey='6969f79a-8f74-415c-b2f7-784d050df2f1', remove=False, options=None)
Thread-2185::ERROR::2013-03-11 16:45:33,023::task::833::TaskManager.Task::(_setError) Task=`6bbd02fa-8b9f-458f-9f25-c20402941f19`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 840, 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 1011, in disconnectStoragePool
    self.validateNotSPM(spUUID)
  File "/usr/share/vdsm/storage/hsm.py", line 308, in validateNotSPM
    raise se.IsSpm(spUUID)
IsSpm: Operation not allowed while SPM is active: ('6969f79a-8f74-415c-b2f7-784d050df2f1',)
Thread-2185::DEBUG::2013-03-11 16:45:33,024::task::852::TaskManager.Task::(_run) Task=`6bbd02fa-8b9f-458f-9f25-c20402941f19`::Task._run: 6bbd02fa-8b9f-458f-9f25-c20402941f19
 ('6969f79a-8f74-415c-b2f7-784d050df2f1', 1, '6969f79a-8f74-415c-b2f7-784d050df2f1', False) {} failed - stopping task
Thread-2185::DEBUG::2013-03-11 16:45:33,024::task::1177::TaskManager.Task::(stop) Task=`6bbd02fa-8b9f-458f-9f25-c20402941f19`::stopping in state preparing (force False)


Jakub, can you try again?

Comment 8 Jakub Libosvar 2013-03-13 14:06:03 UTC
The cause is same as in bug 918588.

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


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