Hi all,
does anybody have an idea how to address this? There is also a side effect that I cannot change SPM (“Error while executing action: Cannot force select SPM. The Storage Pool has running tasks.“).
All the best,
Oliver
Von: Albl, Oliver
Gesendet: Mittwoch, 13. Juni 2018 12:32
An: users@ovirt.org
Betreff: Failed to update VMs/Templates OVF data
Hi,
I have a FC storage domain reporting the following messages every hour:
VDSM command SetVolumeDescriptionVDS failed: Could not acquire resource. Probably resource factory threw an exception.: ()
Failed to update OVF disks cb04b55c-10fb-46fe-b9de-
3c133a94e6a5, OVF data isn't updated on those OVF stores (Data Center VMTEST, Storage Domain VMHOST_LUN_62). Failed to update VMs/Templates OVF data for Storage Domain VMHOST_LUN_62 in Data Center VMTEST.
Trying to manually update OVF results in “Error while executing action UpdateOvfStoreForStorageDomain
: Internal Engine Error”
I run oVirt 4.2.3.5-1.el7.centos on CentOS 7.5 (3.10.0-862.3.2.el7.x86_64) with vdsm-4.20.27.1-1.el7.centos.
x86_64
Engine log:
2018-06-13 12:15:35,649+02 WARN [org.ovirt.engine.core.dal.
job.ExecutionMessageDirector] (default task-12) [092d8f27-c0a4-4d78-a8cb- f4738aff71e6] The message key ' UpdateOvfStoreForStorageDomain ' is missing from 'bundles/ExecutionMessages' 2018-06-13 12:15:35,655+02 INFO [org.ovirt.engine.core.bll.
storage.domain. UpdateOvfStoreForStorageDomain Command] (default task-12) [092d8f27-c0a4-4d78-a8cb- f4738aff71e6] Lock Acquired to object 'EngineLock:{exclusiveLocks='[ 3edb5295-3797-4cd0-9b43- f46ec1ee7b14=OVF_UPDATE, 373efd46-8aea-4d0e-96cc- 1da0debf72d0=STORAGE]', sharedLocks=''}' 2018-06-13 12:15:35,660+02 INFO [org.ovirt.engine.core.bll.
storage.domain. UpdateOvfStoreForStorageDomain Command] (default task-12) [092d8f27-c0a4-4d78-a8cb- f4738aff71e6] Running command: UpdateOvfStoreForStorageDomain Command internal: false. Entities affected : ID: 373efd46-8aea-4d0e-96cc- 1da0debf72d0 Type: StorageAction group MANIPULATE_STORAGE_DOMAIN with role type ADMIN 2018-06-13 12:15:35,670+02 INFO [org.ovirt.engine.core.bll.
storage.ovfstore. ProcessOvfUpdateForStoragePool Command] (default task-12) [4fd5b59a] Running command: ProcessOvfUpdateForStoragePool Command internal: true. Entities affected : ID: 3edb5295-3797-4cd0-9b43- f46ec1ee7b14 Type: StoragePool 2018-06-13 12:15:35,674+02 INFO [org.ovirt.engine.core.bll.
storage.ovfstore. ProcessOvfUpdateForStoragePool Command] (default task-12) [4fd5b59a] Attempting to update VM OVFs in Data Center 'VMTEST' 2018-06-13 12:15:35,678+02 INFO [org.ovirt.engine.core.bll.
storage.ovfstore. ProcessOvfUpdateForStoragePool Command] (default task-12) [4fd5b59a] Successfully updated VM OVFs in Data Center 'VMTEST' 2018-06-13 12:15:35,678+02 INFO [org.ovirt.engine.core.bll.
storage.ovfstore. ProcessOvfUpdateForStoragePool Command] (default task-12) [4fd5b59a] Attempting to update template OVFs in Data Center 'VMTEST' 2018-06-13 12:15:35,678+02 INFO [org.ovirt.engine.core.bll.
storage.ovfstore. ProcessOvfUpdateForStoragePool Command] (default task-12) [4fd5b59a] Successfully updated templates OVFs in Data Center 'VMTEST' 2018-06-13 12:15:35,678+02 INFO [org.ovirt.engine.core.bll.
storage.ovfstore. ProcessOvfUpdateForStoragePool Command] (default task-12) [4fd5b59a] Attempting to remove unneeded template/vm OVFs in Data Center 'VMTEST' 2018-06-13 12:15:35,680+02 INFO [org.ovirt.engine.core.bll.
storage.ovfstore. ProcessOvfUpdateForStoragePool Command] (default task-12) [4fd5b59a] Successfully removed unneeded template/vm OVFs in Data Center 'VMTEST' 2018-06-13 12:15:35,684+02 INFO [org.ovirt.engine.core.bll.
storage.ovfstore. ProcessOvfUpdateForStoragePool Command] (default task-12) [4fd5b59a] Lock freed to object 'EngineLock:{exclusiveLocks='[ 3edb5295-3797-4cd0-9b43- f46ec1ee7b14=OVF_UPDATE, 373efd46-8aea-4d0e-96cc- 1da0debf72d0=STORAGE]', sharedLocks=''}' 2018-06-13 12:15:35,704+02 INFO [org.ovirt.engine.core.bll.
storage.ovfstore. ProcessOvfUpdateForStorageDoma inCommand] (default task-12) [24485c23] Lock Acquired to object 'EngineLock:{exclusiveLocks='[ ]', sharedLocks='[3edb5295-3797- 4cd0-9b43-f46ec1ee7b14=OVF_ UPDATE]'}' 2018-06-13 12:15:35,714+02 INFO [org.ovirt.engine.core.bll.
storage.ovfstore. ProcessOvfUpdateForStorageDoma inCommand] (default task-12) [24485c23] Running command: ProcessOvfUpdateForStorageDoma inCommand internal: true. Entities affected : ID: 373efd46-8aea-4d0e-96cc- 1da0debf72d0 Type: StorageAction group MANIPULATE_STORAGE_DOMAIN with role type ADMIN 2018-06-13 12:15:35,724+02 INFO [org.ovirt.engine.core.
vdsbroker.irsbroker. SetVolumeDescriptionVDSCommand ] (default task-12) [24485c23] START, SetVolumeDescriptionVDSCommand ( SetVolumeDescriptionVDSCommand Parameters:{storagePoolId=' 3edb5295-3797-4cd0-9b43- f46ec1ee7b14', ignoreFailoverLimit='false', storageDomainId='373efd46- 8aea-4d0e-96cc-1da0debf72d0', imageGroupId='cb04b55c-10fb- 46fe-b9de-3c133a94e6a5', imageId='a1e7554d-530c-4c07- a4b5-459a1c509e39'}), log id: 747d674f 2018-06-13 12:15:35,724+02 INFO [org.ovirt.engine.core.
vdsbroker.irsbroker. SetVolumeDescriptionVDSCommand ] (default task-12) [24485c23] -- executeIrsBrokerCommand: calling 'setVolumeDescription', parameters: 2018-06-13 12:15:35,724+02 INFO [org.ovirt.engine.core.
vdsbroker.irsbroker. SetVolumeDescriptionVDSCommand ] (default task-12) [24485c23] ++ spUUID=3edb5295-3797-4cd0- 9b43-f46ec1ee7b14 2018-06-13 12:15:35,724+02 INFO [org.ovirt.engine.core.
vdsbroker.irsbroker. SetVolumeDescriptionVDSCommand ] (default task-12) [24485c23] ++ sdUUID=373efd46-8aea-4d0e- 96cc-1da0debf72d0 2018-06-13 12:15:35,724+02 INFO [org.ovirt.engine.core.
vdsbroker.irsbroker. SetVolumeDescriptionVDSCommand ] (default task-12) [24485c23] ++ imageGroupGUID=cb04b55c-10fb- 46fe-b9de-3c133a94e6a5 2018-06-13 12:15:35,724+02 INFO [org.ovirt.engine.core.
vdsbroker.irsbroker. SetVolumeDescriptionVDSCommand ] (default task-12) [24485c23] ++ volUUID=a1e7554d-530c-4c07- a4b5-459a1c509e39 2018-06-13 12:15:35,724+02 INFO [org.ovirt.engine.core.
vdsbroker.irsbroker. SetVolumeDescriptionVDSCommand ] (default task-12) [24485c23] ++ description={"Updated":false," Last Updated":"Thu May 24 12:02:22 CEST 2018","Storage Domains":[{"uuid":"373efd46- 8aea-4d0e-96cc-1da0debf72d0"}] ,"Disk Description":"OVF_STORE"} 2018-06-13 12:15:35,827+02 ERROR [org.ovirt.engine.core.
vdsbroker.irsbroker. SetVolumeDescriptionVDSCommand ] (default task-12) [24485c23] Failed in 'SetVolumeDescriptionVDS' method 2018-06-13 12:15:35,831+02 ERROR [org.ovirt.engine.core.dal.
dbbroker.auditloghandling. AuditLogDirector] (default task-12) [24485c23] EVENT_ID: IRS_BROKER_COMMAND_FAILURE(10, 803), VDSM command SetVolumeDescriptionVDS failed: Could not acquire resource. Probably resource factory threw an exception.: () 2018-06-13 12:15:35,831+02 ERROR [org.ovirt.engine.core.
vdsbroker.irsbroker. SetVolumeDescriptionVDSCommand ] (default task-12) [24485c23] Command ' SetVolumeDescriptionVDSCommand ( SetVolumeDescriptionVDSCommand Parameters:{storagePoolId=' 3edb5295-3797-4cd0-9b43- f46ec1ee7b14', ignoreFailoverLimit='false', storageDomainId='373efd46- 8aea-4d0e-96cc-1da0debf72d0', imageGroupId='cb04b55c-10fb- 46fe-b9de-3c133a94e6a5', imageId='a1e7554d-530c-4c07- a4b5-459a1c509e39'})' execution failed: IRSGenericException: IRSErrorException: Failed to SetVolumeDescriptionVDS, error = Could not acquire resource. Probably resource factory threw an exception.: (), code = 855 2018-06-13 12:15:35,831+02 INFO [org.ovirt.engine.core.
vdsbroker.irsbroker. SetVolumeDescriptionVDSCommand ] (default task-12) [24485c23] FINISH, SetVolumeDescriptionVDSCommand , log id: 747d674f 2018-06-13 12:15:35,831+02 WARN [org.ovirt.engine.core.bll.
storage.ovfstore. ProcessOvfUpdateForStorageDoma inCommand] (default task-12) [24485c23] failed to update domain '373efd46-8aea-4d0e-96cc- 1da0debf72d0' ovf store disk 'cb04b55c-10fb-46fe-b9de- 3c133a94e6a5' 2018-06-13 12:15:35,834+02 WARN [org.ovirt.engine.core.dal.
dbbroker.auditloghandling. AuditLogDirector] (default task-12) [24485c23] EVENT_ID: UPDATE_FOR_OVF_STORES_FAILED( 1,016), Failed to update OVF disks cb04b55c-10fb-46fe-b9de- 3c133a94e6a5, OVF data isn't updated on those OVF stores (Data Center VMTEST, Storage Domain HOST_LUN_62). 2018-06-13 12:15:35,843+02 WARN [org.ovirt.engine.core.dal.
dbbroker.auditloghandling. AuditLogDirector] (default task-12) [24485c23] EVENT_ID: UPDATE_OVF_FOR_STORAGE_DOMAIN_ FAILED(190), Failed to update VMs/Templates OVF data for Storage Domain VMHOST_LUN_62 in Data Center VMTEST. 2018-06-13 12:15:35,846+02 INFO [org.ovirt.engine.core.bll.
storage.ovfstore. ProcessOvfUpdateForStorageDoma inCommand] (default task-12) [24485c23] Lock freed to object 'EngineLock:{exclusiveLocks='[ ]', sharedLocks='[3edb5295-3797- 4cd0-9b43-f46ec1ee7b14=OVF_ UPDATE]'}' 2018-06-13 12:15:36,031+02 INFO [org.ovirt.engine.core.bll.
SerialChildCommandsExecutionCa llback] (EE-ManagedThreadFactory- engineScheduled-Thread-60) [24485c23] Command ' ProcessOvfUpdateForStorageDoma in' id: 'a887910e-39a1-4120-a29b- 76741ade8bf6' child commands '[]' executions were completed, status 'SUCCEEDED' 2018-06-13 12:15:37,052+02 INFO [org.ovirt.engine.core.bll.
storage.ovfstore. ProcessOvfUpdateForStorageDoma inCommand] (EE-ManagedThreadFactory- engineScheduled-Thread-31) [24485c23] Ending command 'org.ovirt.engine.core.bll. storage.ovfstore. ProcessOvfUpdateForStorageDoma inCommand' successfully. 2018-06-13 12:15:37,059+02 INFO [org.ovirt.engine.core.dal.
dbbroker.auditloghandling. AuditLogDirector] (EE-ManagedThreadFactory- engineScheduled-Thread-31) [24485c23] EVENT_ID: USER_UPDATE_OVF_STORE(199), OVF_STORE for domain VMHOST_LUN_62 was updated by <user>@>domain>@<DOMAIN>- authz.
vdsm.log
2018-06-13 12:15:35,727+0200 INFO (jsonrpc/7) [vdsm.api] START setVolumeDescription(sdUUID=u'
373efd46-8aea-4d0e-96cc- 1da0debf72d0', spUUID=u'3edb5295-3797-4cd0- 9b43-f46ec1ee7b14', imgUUID=u'cb04b55c-10fb-46fe- b9de-3c133a94e6a5', volUU ID=u'a1e7554d-530c-4c07-a4b5- 459a1c509e39', description=u'{"Updated": false,"Last Updated":"Thu May 24 12:02:22 CEST 2018","Storage Domains":[{"uuid":"373efd46- 8aea-4d0e-96cc-1da0debf72d0"}] ,"Disk Description":"OVF_STORE"}', options=Non e) from=::ffff:<IP>,54686, flow_id=24485c23, task_id=70941873-0296-4ed0- 94c8-b51290cd6963 (api:46) 2018-06-13 12:15:35,825+0200 WARN (jsonrpc/7) [storage.ResourceManager] Resource factory failed to create resource '01_img_373efd46-8aea-4d0e-
96cc-1da0debf72d0.cb04b55c- 10fb-46fe-b9de-3c133a94e6a5'. Canceling request. (resourceManager :543) Traceback (most recent call last):
File "/usr/lib/python2.7/site-
packages/vdsm/storage/ resourceManager.py", line 539, in registerResource obj = namespaceObj.factory.
createResource(name, lockType) File "/usr/lib/python2.7/site-
packages/vdsm/storage/ resourceFactories.py", line 193, in createResource lockType)
File "/usr/lib/python2.7/site-
packages/vdsm/storage/ resourceFactories.py", line 122, in __getResourceCandidatesList imgUUID=resourceName)
File "/usr/lib/python2.7/site-
packages/vdsm/storage/image. py", line 206, in getChain if len(uuidlist) == 1 and srcVol.isShared():
File "/usr/lib/python2.7/site-
packages/vdsm/storage/volume. py", line 1434, in isShared return self._manifest.isShared()
File "/usr/lib/python2.7/site-
packages/vdsm/storage/volume. py", line 141, in isShared return self.getVolType() == sc.type2name(sc.SHARED_VOL)
File "/usr/lib/python2.7/site-
packages/vdsm/storage/volume. py", line 134, in getVolType self.voltype = self.getMetaParam(sc.VOLTYPE)
File "/usr/lib/python2.7/site-
packages/vdsm/storage/volume. py", line 118, in getMetaParam meta = self.getMetadata()
File "/usr/lib/python2.7/site-
packages/vdsm/storage/ blockVolume.py", line 112, in getMetadata md = VolumeMetadata.from_lines(
lines) File "/usr/lib/python2.7/site-
packages/vdsm/storage/ volumemetadata.py", line 103, in from_lines "Missing metadata key: %s: found: %s" % (e, md))
MetaDataKeyNotFoundError: Meta Data key not found error: ("Missing metadata key: 'DOMAIN': found: {}",)
2018-06-13 12:15:35,825+0200 WARN (jsonrpc/7) [storage.ResourceManager.
Request] (ResName='01_img_373efd46- 8aea-4d0e-96cc-1da0debf72d0. cb04b55c-10fb-46fe-b9de- 3c133a94e6a5', ReqID='dc9ebbc2-5cfa-447d- b2be-40ed2cf81992') Tried to cancel a processed request (resourceManager:187) 2018-06-13 12:15:35,825+0200 INFO (jsonrpc/7) [vdsm.api] FINISH setVolumeDescription error=Could not acquire resource. Probably resource factory threw an exception.: () from=::ffff:<IP>,54686, flow_id=24485c23, task_id=70941873 -0296-4ed0-94c8-b51290cd6963 (api:50)
2018-06-13 12:15:35,825+0200 ERROR (jsonrpc/7) [storage.TaskManager.Task] (Task='70941873-0296-4ed0-
94c8-b51290cd6963') Unexpected error (task:875) Traceback (most recent call last):
File "/usr/lib/python2.7/site-
packages/vdsm/storage/task.py" , line 882, in _run return fn(*args, **kargs)
File "<string>", line 2, in setVolumeDescription
File "/usr/lib/python2.7/site-
packages/vdsm/common/api.py", line 48, in method ret = func(*args, **kwargs)
File "/usr/lib/python2.7/site-
packages/vdsm/storage/hsm.py", line 1294, in setVolumeDescription pool.setVolumeDescription(
sdUUID, imgUUID, volUUID, description) File "/usr/lib/python2.7/site-
packages/vdsm/storage/ securable.py", line 79, in wrapper return method(self, *args, **kwargs)
File "/usr/lib/python2.7/site-
packages/vdsm/storage/sp.py", line 2011, in setVolumeDescription with rm.acquireResource(img_ns, imgUUID, rm.EXCLUSIVE):
File "/usr/lib/python2.7/site-
packages/vdsm/storage/ resourceManager.py", line 1025, in acquireResource return _manager.acquireResource(
namespace, name, lockType, timeout=timeout) File "/usr/lib/python2.7/site-
packages/vdsm/storage/ resourceManager.py", line 475, in acquireResource raise se.ResourceAcqusitionFailed()
ResourceAcqusitionFailed: Could not acquire resource. Probably resource factory threw an exception.: ()
2018-06-13 12:15:35,826+0200 INFO (jsonrpc/7) [storage.TaskManager.Task] (Task='70941873-0296-4ed0-
94c8-b51290cd6963') aborting: Task is aborted: u'Could not acquire resource. Probably resource factory threw an exception.: ()' - code 100 (task:1181) 2018-06-13 12:15:35,826+0200 ERROR (jsonrpc/7) [storage.Dispatcher] FINISH setVolumeDescription error=Could not acquire resource. Probably resource factory threw an exception.: () (dispatcher:82)
2018-06-13 12:15:35,826+0200 INFO (jsonrpc/7) [jsonrpc.JsonRpcServer] RPC call Volume.setDescription failed (error 855) in 0.10 seconds (__init__:573)
2018-06-13 12:15:38,953+0200 INFO (jsonrpc/5) [api.host] START getAllVmStats() from=::ffff:<IP>,54666 (api:46)
2018-06-13 12:15:38,956+0200 INFO (jsonrpc/5) [api.host] FINISH getAllVmStats return={'status': {'message': 'Done', 'code': 0}, 'statsList': (suppressed)} from=::ffff:<IP>,54666 (api:52)
2018-06-13 12:15:38,957+0200 INFO (jsonrpc/5) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.01 seconds (__init__:573)
2018-06-13 12:15:39,406+0200 INFO (jsonrpc/4) [vdsm.api] START getSpmStatus(spUUID=u'
3edb5295-3797-4cd0-9b43- f46ec1ee7b14', options=None) from=::ffff:<IP>,54666, task_id=eabfe183-dfb0-4982- b7ea-beacca74aeef (api:46) 2018-06-13 12:15:39,410+0200 INFO (jsonrpc/4) [vdsm.api] FINISH getSpmStatus return={'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 20L}} from=::ffff:<IP>,54666, task_id=eabfe183-dfb0-4982-
b7ea-beacca74aeef (api:52) 2018-06-13 12:15:39,410+0200 INFO (jsonrpc/4) [jsonrpc.JsonRpcServer] RPC call StoragePool.getSpmStatus succeeded in 0.01 seconds (__init__:573)
2018-06-13 12:15:39,416+0200 INFO (jsonrpc/1) [vdsm.api] START getStoragePoolInfo(spUUID=u'
3edb5295-3797-4cd0-9b43- f46ec1ee7b14', options=None) from=::ffff:<IP>,54686, task_id=b2003a6f-dd74-47ab- b4f0-95ffb54dc51d (api:46) 2018-06-13 12:15:39,420+0200 INFO (jsonrpc/1) [vdsm.api] FINISH getStoragePoolInfo return={'info': {'name': 'No Description', 'isoprefix': '', 'pool_status': 'connected', 'lver': 20L, 'domains': u'373efd46-8aea-4d0e-96cc-
1da0debf72d0: Active,9ed4b0d2-c555-4b27- 8f88-75c47a99ad98:Attached, efd78d36-c395-4e9a-a46e- 6059fa53756d:Active,3675435e- 851e-4236-81da-fce1cc027238: Active', 'master_uuid': 'efd78d36-c395-4e9a-a46e- 6059fa53756d', 'version': '4', 'spm_id': 2, 'type': 'FCP', 'master_ver': 12}, 'dominfo': {u'373efd46-8aea-4d0e-96cc- 1da0debf72d0': {'status': u'Active', 'diskfree': '8722541707264', 'isoprefix': '', 'alerts': [], 'disktotal': '8795690369024', 'version': 4}, u'9ed4b0d2-c555-4b27-8f88-75c 47a99ad98': {'status': u'Attached', 'isoprefix': '', 'alerts': []}, u'efd78d36-c395-4e9a-a46e- 6059fa53756d': {'status': u'Active', 'diskfree': '8718783610880', 'isoprefix': '', 'alerts': [], 'disktotal': '8795690369024', 'version': 4}, u'3675435e-851e-4236-81da- fce1cc027238': {'status': u'Active', 'diskfree': '8713280684032', 'isoprefix': '', 'alerts': [], 'disktotal': '8795690369024', 'version': 4}}} from=::ffff:<IP>,54686, task_id=b2003a6f-dd74-47ab- b4f0-95 ffb54dc51d (api:52) 2018-06-13 12:15:39,421+0200 INFO (jsonrpc/1) [jsonrpc.JsonRpcServer] RPC call StoragePool.getInfo succeeded in 0.01 seconds (__init__:573)
All the best,
Oliver
_______________________________________________
Users mailing list -- users@ovirt.org
To unsubscribe send an email to users-leave@ovirt.org
Privacy Statement: https://www.ovirt.org/site/privacy-policy/
oVirt Code of Conduct: https://www.ovirt.org/community/about/community- guidelines/
List Archives: https://lists.ovirt.org/archives/list/users@ovirt.org/ message/ MRBMUKOZ7VTP52I2SRPMBMCW375CXS 5A/