[ovirt-users] Failed to update VMs/Templates OVF data

Wednesday, 13 June 2018

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.UpdateOvfStoreForStorageDomainCommand] (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.UpdateOvfStoreForStorageDomainCommand] (default
task-12) [092d8f27-c0a4-4d78-a8cb-f4738aff71e6] Running command:
UpdateOvfStoreForStorageDomainCommand 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.ProcessOvfUpdateForStoragePoolCommand]
(default task-12) [4fd5b59a] Running command: ProcessOvfUpdateForStoragePoolCommand
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.ProcessOvfUpdateForStoragePoolCommand]
(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.ProcessOvfUpdateForStoragePoolCommand]
(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.ProcessOvfUpdateForStoragePoolCommand]
(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.ProcessOvfUpdateForStoragePoolCommand]
(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.ProcessOvfUpdateForStoragePoolCommand]
(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.ProcessOvfUpdateForStoragePoolCommand]
(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.ProcessOvfUpdateForStoragePoolCommand]
(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.ProcessOvfUpdateForStorageDomainCommand]
(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.ProcessOvfUpdateForStorageDomainCommand]
(default task-12) [24485c23] Running command: ProcessOvfUpdateForStorageDomainCommand
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(
SetVolumeDescriptionVDSCommandParameters:{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(
SetVolumeDescriptionVDSCommandParameters:{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.ProcessOvfUpdateForStorageDomainCommand]
(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.ProcessOvfUpdateForStorageDomainCommand]
(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.SerialChildCommandsExecutionCallback]
(EE-ManagedThreadFactory-engineScheduled-Thread-60) [24485c23] Command
'ProcessOvfUpdateForStorageDomain' 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.ProcessOvfUpdateForStorageDomainCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-31) [24485c23] Ending command
'org.ovirt.engine.core.bll.storage.ovfstore.ProcessOvfUpdateForStorageDomainCommand'
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

2024

2023

2022

2021

2020

2019

2018

2017

2016

2015

2014

2013

2012

2011

[ovirt-users] Failed to update VMs/Templates OVF data