Created attachment 1434321 [details]
engine log

Description of problem:
During automation Tier2 run on hosted engine environment, reaching storage connection's TP we detach & remove all ISCSI storage domains in order to remove all ISCSI connections before starting all tests.

When we tried to deactivate SD 'iscsi_2' operation failed with the following Errors & Exception:

From Engine log you can see 'syncAction_daa1a241-9' showing what occured:
2018-05-05 14:46:17,020+03 INFO  [org.ovirt.engine.core.bll.storage.domain.DeactivateStorageDomainWithOvfUpdateCommand] (default task-41) [storagedomains_syncAction_daa1a241-9] Lock Acquired to object 'EngineLoc
k:{exclusiveLocks='[ede0cd00-aeba-40c6-9ffc-e4d469ca1d5b=STORAGE]', sharedLocks='[d1d01ef4-4f0c-11e8-a408-00163e7be007=POOL]'}'
2018-05-05 14:46:17,128+03 INFO  [org.ovirt.engine.core.bll.storage.domain.DeactivateStorageDomainWithOvfUpdateCommand] (default task-41) [storagedomains_syncAction_daa1a241-9] Running command: DeactivateStorage
DomainWithOvfUpdateCommand internal: false. Entities affected :  ID: ede0cd00-aeba-40c6-9ffc-e4d469ca1d5b Type: StorageAction group MANIPULATE_STORAGE_DOMAIN with role type ADMIN
2018-05-05 14:46:17,189+03 INFO  [org.ovirt.engine.core.bll.storage.domain.UpdateOvfStoreForStorageDomainCommand] (default task-41) [storagedomains_syncAction_daa1a241-9] Running command: UpdateOvfStoreForStorag
eDomainCommand internal: true. Entities affected :  ID: ede0cd00-aeba-40c6-9ffc-e4d469ca1d5b Type: StorageAction group MANIPULATE_STORAGE_DOMAIN with role type ADMIN
2018-05-05 14:46:17,198+03 INFO  [org.ovirt.engine.core.bll.storage.ovfstore.ProcessOvfUpdateForStoragePoolCommand] (default task-41) [4fd366b9] Running command: ProcessOvfUpdateForStoragePoolCommand internal: t
rue. Entities affected :  ID: d1d01ef4-4f0c-11e8-a408-00163e7be007 Type: StoragePool
2018-05-05 14:46:17,210+03 INFO  [org.ovirt.engine.core.bll.storage.ovfstore.ProcessOvfUpdateForStoragePoolCommand] (default task-41) [4fd366b9] Attempting to update VM OVFs in Data Center 'golden_env_mixed'
2018-05-05 14:46:17,350+03 WARN  [org.ovirt.engine.core.vdsbroker.builder.vminfo.VmInfoBuildUtils] (default task-41) [4fd366b9] No host NUMA nodes found for vm HostedEngine (1d7f6b2b-3657-4780-8275-b249e63a5a81)
2018-05-05 14:46:17,357+03 ERROR [org.ovirt.engine.core.bll.storage.ovfstore.ProcessOvfUpdateForStoragePoolCommand] (default task-41) [4fd366b9] Command 'org.ovirt.engine.core.bll.storage.ovfstore.ProcessOvfUpda
teForStoragePoolCommand' failed: null
2018-05-05 14:46:17,357+03 ERROR [org.ovirt.engine.core.bll.storage.ovfstore.ProcessOvfUpdateForStoragePoolCommand] (default task-41) [4fd366b9] Exception: java.lang.NullPointerException
        at org.ovirt.engine.core.vdsbroker.builder.vminfo.LibvirtVmXmlBuilder.writeInterface(LibvirtVmXmlBuilder.java:2045) [vdsbroker.jar:]
        at org.ovirt.engine.core.vdsbroker.builder.vminfo.LibvirtVmXmlBuilder.lambda$writeInterfaces$24(LibvirtVmXmlBuilder.java:1096) [vdsbroker.jar:]
        at java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:184) [rt.jar:1.8.0_171]
        at java.util.stream.SortedOps$SizedRefSortingSink.end(SortedOps.java:352) [rt.jar:1.8.0_171]
        at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:482) [rt.jar:1.8.0_171]
        at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:471) [rt.jar:1.8.0_171]
        at java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:151) [rt.jar:1.8.0_171]
        at java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:174) [rt.jar:1.8.0_171]
        at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234) [rt.jar:1.8.0_171]
……………………………………………………………………………………………..
……………………………………………………………………………………………..
……………………………………………………………………………………………..

        at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:104)
        at io.undertow.server.Connectors.executeRootHandler(Connectors.java:330)
        at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:812)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [rt.jar:1.8.0_171]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [rt.jar:1.8.0_171]
        at java.lang.Thread.run(Thread.java:748) [rt.jar:1.8.0_171]

2018-05-05 14:46:17,385+03 INFO  [org.ovirt.engine.core.bll.storage.ovfstore.ProcessOvfUpdateForStoragePoolCommand] (default task-41) [4fd366b9] Lock freed to object 'EngineLock:{exclusiveLocks='[ede0cd00-aeba-4
0c6-9ffc-e4d469ca1d5b=STORAGE]', sharedLocks='[d1d01ef4-4f0c-11e8-a408-00163e7be007=POOL]'}'
2018-05-05 14:46:17,442+03 INFO  [org.ovirt.engine.core.bll.CommandCompensator] (default task-41) [storagedomains_syncAction_daa1a241-9] Command [id=d2104976-7be0-4a34-a1f8-3dacb6b8e7e8]: Compensating CHANGED_ST
ATUS_ONLY of org.ovirt.engine.core.common.businessentities.StoragePoolIsoMap; snapshot: EntityStatusSnapshot:{id='StoragePoolIsoMapId:{storagePoolId='d1d01ef4-4f0c-11e8-a408-00163e7be007', storageId='ede0cd00-ae
ba-40c6-9ffc-e4d469ca1d5b'}', status='Unknown'}.
2018-05-05 14:46:17,463+03 WARN  [org.ovirt.engine.core.bll.lock.InMemoryLockManager] (default task-41) [storagedomains_syncAction_daa1a241-9] Trying to release a shared lock for key: 'd1d01ef4-4f0c-11e8-a408-00163e7be007POOL' , but lock does not exist
2018-05-05 14:46:17,463+03 WARN  [org.ovirt.engine.core.bll.lock.InMemoryLockManager] (default task-41) [storagedomains_syncAction_daa1a241-9] Trying to release exclusive lock which does not exist, lock key: 'ede0cd00-aeba-40c6-9ffc-e4d469ca1d5bSTORAGE'
2018-05-05 14:46:17,463+03 INFO  [org.ovirt.engine.core.bll.storage.domain.DeactivateStorageDomainWithOvfUpdateCommand] (default task-41) [storagedomains_syncAction_daa1a241-9] Lock freed to object 'EngineLock:{exclusiveLocks='[ede0cd00-aeba-40c6-9ffc-e4d469ca1d5b=STORAGE]', sharedLocks='[d1d01ef4-4f0c-11e8-a408-00163e7be007=POOL]'}'
2018-05-05 14:46:17,464+03 ERROR [org.ovirt.engine.api.restapi.resource.AbstractBackendResource] (default task-41) [] Operation Failed: [Internal Engine Error]
2018-05-05 14:46:17,574+03 INFO  [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-79) [storagedomains_syncAction_daa1a241-9] Command 'DeactivateStorageDomainWithOvfUpdate' id: 'd2104976-7be0-4a34-a1f8-3dacb6b8e7e8' child commands '[109ea62e-7cd1-4924-a106-55a04e221651]' executions were completed, status 'FAILED'
2018-05-05 14:46:18,593+03 ERROR [org.ovirt.engine.core.bll.storage.domain.DeactivateStorageDomainWithOvfUpdateCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-77) [storagedomains_syncAction_daa1a241-9] Ending command 'org.ovirt.engine.core.bll.storage.domain.DeactivateStorageDomainWithOvfUpdateCommand' with failure.
2018-05-05 14:46:18,605+03 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-77) [storagedomains_syncAction_daa1a241-9] EVENT_ID: USER_DEACTIVATE_STORAGE_DOMAIN_FAILED(969), Failed to deactivate Storage Domain iscsi_2 (Data Center golden_env_mixed).
2018-05-05 14:46:18,608+03 WARN  [org.ovirt.engine.core.bll.lock.InMemoryLockManager] (EE-ManagedThreadFactory-engineScheduled-Thread-77) [storagedomains_syncAction_daa1a241-9] Trying to release a shared lock for key: 'd1d01ef4-4f0c-11e8-a408-00163e7be007POOL' , but lock does not exist
2018-05-05 14:46:18,608+03 WARN  [org.ovirt.engine.core.bll.lock.InMemoryLockManager] (EE-ManagedThreadFactory-engineScheduled-Thread-77) [storagedomains_syncAction_daa1a241-9] Trying to release exclusive lock which does not exist, lock key: 'ede0cd00-aeba-40c6-9ffc-e4d469ca1d5bSTORAGE'
2018-05-05 14:46:18,608+03 INFO  [org.ovirt.engine.core.bll.storage.domain.DeactivateStorageDomainWithOvfUpdateCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-77) [storagedomains_syncAction_daa1a241-9] Lock freed to object 'EngineLock:{exclusiveLocks='[ede0cd00-aeba-40c6-9ffc-e4d469ca1d5b=STORAGE]', sharedLocks='[d1d01ef4-4f0c-11e8-a408-00163e7be007=POOL]'}'



Version-Release number of selected component (if applicable):
ovirt-engine-4.2.3.4-0.1.el7.noarch
vdsm-4.20.27.1-1.el7ev.x86_64


How reproducible:
Happened once on a during Tier2 Starting storage connections TP.

Steps to Reproduce:
Not straightforward, Tier2 ran a lot of prior tests that could have caused this issue. the final trigger to this issue was deactivating iscsi_2 storage domain.

Issue occurred in the Setup phase of storage connection TP that deactivate's & removes all ISCSI SD's (iscsi_0,iscsi_1,iscsi_2)

Actual results:
Deactivation failed with Internal Engine Error and NPE exception - [ProcessOvfUpdateForStoragePoolCommand] (default task-41) [4fd366b9] Exception: java.lang.NullPointerException

Expected results:


Additional info: