10:58 a.m.
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(a)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.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
4:02 p.m.
New subject: Failed to update VMs/Templates OVF data, cannot change SPM
Can you please attach engine.log and vdsm.log?
On Tue, Jun 19, 2018 at 6:58 PM, Albl, Oliver <Oliver.Albl(a)fabasoft.com>
wrote:
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(a)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.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
_______________________________________________
Users mailing list -- users(a)ovirt.org
To unsubscribe send an email to users-leave(a)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/MRBMUKOZ7VTP52I2SRPMBMCW375CXS5A/
4:38 p.m.
New subject: Failed to update VMs/Templates OVF data, cannot change SPM
On Wed, Jun 20, 2018 at 12:11 AM Elad Ben Aharon <ebenahar(a)redhat.com>
wrote:
Can you please attach engine.log and vdsm.log?
On Tue, Jun 19, 2018 at 6:58 PM, Albl, Oliver <Oliver.Albl(a)fabasoft.com>
wrote:
> 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(a)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.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: {}",)
>
This means the volume metadata is missing a required key: "DOMAIN".
Can you share the output of:
lvs -o vg_name,lv_name,tags | grep a1e7554d-530c-4c07-a4b5-459a1c509e39
There should a tag named MD_N - N is an integer. Once you find it,
we would like to see the metadata at offset N * 512 in the metadata volume.
You can extract it like this:
dd if=/dev/vgname/metadata bs=512 skip=N
Nir
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(a)ovirt.org
> To unsubscribe send an email to users-leave(a)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/MRBMUKOZ7VT...
>
>
_______________________________________________
Users mailing list -- users(a)ovirt.org
To unsubscribe send an email to users-leave(a)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/6XG4IFPYXAI...
2:33 a.m.
New subject: Failed to update VMs/Templates OVF data, cannot change SPM
Hi Nir,
I identified the reason for the failing OVF updates on the initial VG – metadata was
affected by blkdiscard tests in scope of
https://bugzilla.redhat.com/show_bug.cgi?id=1562369
However, the OVF updates are failing on other installations as well (on 2 out of 40
storage domains). Here is the output of your commands:
# lvs -o vg_name,lv_name,tags | grep 3ad1987a-8b7d-426d-9d51-4a78cb0a888f
3ad1987a-8b7d-426d-9d51-4a78cb0a888f 212d644c-0155-4999-9df9-72bacfc7f141
IU_0ebefe5e-9053-4bf1-bdfd-fdb26579c179,MD_4,PU_00000000-0000-0000-0000-000000000000
3ad1987a-8b7d-426d-9d51-4a78cb0a888f 94f519de-bc19-4557-82c4-86bbcfc5dd2f
IU_60d9eec7-951f-4594-ae99-7d31318ee3a9,MD_5,PU_00000000-0000-0000-0000-000000000000
3ad1987a-8b7d-426d-9d51-4a78cb0a888f ids
3ad1987a-8b7d-426d-9d51-4a78cb0a888f inbox
3ad1987a-8b7d-426d-9d51-4a78cb0a888f leases
3ad1987a-8b7d-426d-9d51-4a78cb0a888f master
3ad1987a-8b7d-426d-9d51-4a78cb0a888f metadata
3ad1987a-8b7d-426d-9d51-4a78cb0a888f outbox
3ad1987a-8b7d-426d-9d51-4a78cb0a888f xleases
# for i in 4 5; do
dd if=/dev/3ad1987a-8b7d-426d-9d51-4a78cb0a888f/metadata bs=512 count=1 skip=$i
of=metadata.$i
done
1+0 records in
1+0 records out
512 bytes (512 B) copied, 0.00121297 s, 422 kB/s
1+0 records in
1+0 records out
512 bytes (512 B) copied, 0.000735026 s, 697 kB/s
# file metadata.*
metadata.4: data
metadata.5: ASCII text
# cat metadata.5
DOMAIN=3ad1987a-8b7d-426d-9d51-4a78cb0a888f
CTIME=1520597691
FORMAT=RAW
DISKTYPE=OVFS
LEGALITY=LEGAL
SIZE=262144
VOLTYPE=LEAF
DESCRIPTION={"Updated":true,"Size":4669440,"Last
Updated":"Fri Jun 08 09:51:18 CEST 2018","Storage
Domains":[{"uuid":"3ad1987a-8b7d-426d-9d51-4a78cb0a888f"}],"Disk
Description":"OVF_STORE"}
IMAGE=60d9eec7-951f-4594-ae99-7d31318ee3a9
PUUID=00000000-0000-0000-0000-000000000000
MTIME=0
POOL_UUID=
TYPE=PREALLOCATED
GEN=0
EOF
# od -c metadata.4
0000000 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0
*
0001000
vdsm.log from manual OVF update test:
2018-06-20 09:28:27,840+0200 INFO (jsonrpc/7) [vdsm.api] START
setVolumeDescription(sdUUID=u'3ad1987a-8b7d-426d-9d51-4a78cb0a888f',
spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3',
imgUUID=u'0ebefe5e-9053-4bf1-bdfd-fdb26579c179',
volUUID=u'212d644c-0155-4999-9df9-72bacfc7f141',
description=u'{"Updated":false,"Last Updated":"Fri Jun 08
09:51:18 CEST 2018","Storage
Domains":[{"uuid":"3ad1987a-8b7d-426d-9d51-4a78cb0a888f"}],"Disk
Description":"OVF_STORE"}', options=None) from=::ffff:<IP>,51790,
flow_id=7e4edb74, task_id=5f1fda67-a073-419a-bba5-9bf680c0e5d5 (api:46)
2018-06-20 09:28:28,072+0200 WARN (jsonrpc/7) [storage.ResourceManager] Resource factory
failed to create resource
'01_img_3ad1987a-8b7d-426d-9d51-4a78cb0a888f.0ebefe5e-9053-4bf1-bdfd-fdb26579c179'.
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-20 09:28:28,072+0200 WARN (jsonrpc/7) [storage.ResourceManager.Request]
(ResName='01_img_3ad1987a-8b7d-426d-9d51-4a78cb0a888f.0ebefe5e-9053-4bf1-bdfd-fdb26579c179',
ReqID='10c95223-f349-4ac3-ab2f-7a5f3d1c7749') Tried to cancel a processed request
(resourceManager:187)
2018-06-20 09:28:28,073+0200 INFO (jsonrpc/7) [vdsm.api] FINISH setVolumeDescription
error=Could not acquire resource. Probably resource factory threw an exception.: ()
from=::ffff:<IP>,51790, flow_id=7e4edb74,
task_id=5f1fda67-a073-419a-bba5-9bf680c0e5d5 (api:50)
2018-06-20 09:28:28,073+0200 ERROR (jsonrpc/7) [storage.TaskManager.Task]
(Task='5f1fda67-a073-419a-bba5-9bf680c0e5d5') 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-20 09:28:28,073+0200 INFO (jsonrpc/7) [storage.TaskManager.Task]
(Task='5f1fda67-a073-419a-bba5-9bf680c0e5d5') aborting: Task is aborted:
u'Could not acquire resource. Probably resource factory threw an exception.: ()' -
code 100 (task:1181)
2018-06-20 09:28:28,073+0200 ERROR (jsonrpc/7) [storage.Dispatcher] FINISH
setVolumeDescription error=Could not acquire resource. Probably resource factory threw an
exception.: () (dispatcher:82)
I worked around the SPM problem by running engine-setup (neither vds-client
Host/StoragePool *Task*, async_task_entries or taskcleaner.sh showed any tasks).
All the best,
Oliver
Von: Nir Soffer <nsoffer(a)redhat.com>
Gesendet: Dienstag, 19. Juni 2018 23:39
An: Elad Ben Aharon <ebenahar(a)redhat.com>
Cc: users(a)ovirt.org; Albl, Oliver <Oliver.Albl(a)fabasoft.com>
Betreff: [ovirt-users] Re: Failed to update VMs/Templates OVF data, cannot change SPM
On Wed, Jun 20, 2018 at 12:11 AM Elad Ben Aharon
<ebenahar@redhat.com<mailto:ebenahar@redhat.com>> wrote:
Can you please attach engine.log and vdsm.log?
On Tue, Jun 19, 2018 at 6:58 PM, Albl, Oliver
<Oliver.Albl@fabasoft.com<mailto:Oliver.Albl@fabasoft.com>> wrote:
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<mailto: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.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: {}",)
This means the volume metadata is missing a required key: "DOMAIN".
Can you share the output of:
lvs -o vg_name,lv_name,tags | grep a1e7554d-530c-4c07-a4b5-459a1c509e39
There should a tag named MD_N - N is an integer. Once you find it,
we would like to see the metadata at offset N * 512 in the metadata volume.
You can extract it like this:
dd if=/dev/vgname/metadata bs=512 skip=N
Nir
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<mailto:users@ovirt.org>
To unsubscribe send an email to
users-leave@ovirt.org<mailto: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/MRBMUKOZ7VT...
_______________________________________________
Users mailing list -- users@ovirt.org<mailto:users@ovirt.org>
To unsubscribe send an email to
users-leave@ovirt.org<mailto: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/6XG4IFPYXAI...
3 a.m.
New subject: Failed to update VMs/Templates OVF data, cannot change SPM
On Wed, Jun 20, 2018 at 10:33 AM Bruckner, Simone <
simone.bruckner(a)fabasoft.com> wrote:
Hi Nir,
I identified the reason for the failing OVF updates on the initial VG –
metadata was affected by blkdiscard tests in scope of
https://bugzilla.redhat.com/show_bug.cgi?id=1562369
However, the OVF updates are failing on other installations as well (on 2
out of 40 storage domains). Here is the output of your commands:
# lvs -o vg_name,lv_name,tags | grep 3ad1987a-8b7d-426d-9d51-4a78cb0a888f
3ad1987a-8b7d-426d-9d51-4a78cb0a888f
212d644c-0155-4999-9df9-72bacfc7f141
IU_0ebefe5e-9053-4bf1-bdfd-fdb26579c179,MD_4,PU_00000000-0000-0000-0000-000000000000
3ad1987a-8b7d-426d-9d51-4a78cb0a888f
94f519de-bc19-4557-82c4-86bbcfc5dd2f
IU_60d9eec7-951f-4594-ae99-7d31318ee3a9,MD_5,PU_00000000-0000-0000-0000-000000000000
3ad1987a-8b7d-426d-9d51-4a78cb0a888f ids
3ad1987a-8b7d-426d-9d51-4a78cb0a888f inbox
3ad1987a-8b7d-426d-9d51-4a78cb0a888f leases
3ad1987a-8b7d-426d-9d51-4a78cb0a888f master
3ad1987a-8b7d-426d-9d51-4a78cb0a888f metadata
3ad1987a-8b7d-426d-9d51-4a78cb0a888f outbox
3ad1987a-8b7d-426d-9d51-4a78cb0a888f xleases
Looks good
# for i in 4 5; do
dd if=/dev/3ad1987a-8b7d-426d-9d51-4a78cb0a888f/metadata bs=512 count=1
skip=$i of=metadata.$i
done
1+0 records in
1+0 records out
512 bytes (512 B) copied, 0.00121297 s, 422 kB/s
1+0 records in
1+0 records out
512 bytes (512 B) copied, 0.000735026 s, 697 kB/s
# file metadata.*
metadata.4: data
metadata.5: ASCII text
# cat metadata.5
DOMAIN=3ad1987a-8b7d-426d-9d51-4a78cb0a888f
CTIME=1520597691
FORMAT=RAW
DISKTYPE=OVFS
LEGALITY=LEGAL
SIZE=262144
VOLTYPE=LEAF
DESCRIPTION={"Updated":true,"Size":4669440,"Last
Updated":"Fri Jun 08
09:51:18 CEST 2018","Storage
Domains":[{"uuid":"3ad1987a-8b7d-426d-9d51-4a78cb0a888f"}],"Disk
Description":"OVF_STORE"}
IMAGE=60d9eec7-951f-4594-ae99-7d31318ee3a9
PUUID=00000000-0000-0000-0000-000000000000
MTIME=0
POOL_UUID=
TYPE=PREALLOCATED
GEN=0
EOF
Looks good
# od -c metadata.4
0000000 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0
*
0001000
There is no metada in this volume. This will fail every time when we try to
store something
into this volume.
I wonder how the metadata was deleted, maybe there was some error when the
volume
was created?
Can you file a bug for this, and attach vdsm.log from the point this storage
domain was created until the error started?
An important date seems Fri Jun 08 09:51:18 CEST 2018 - at this date the
volume
metadata was updated in the last time.
For recovering this volume, you can write valid metadata to the same offset
using dd.
Basically it is the same as the metadata of the other ovf storage
(metadata.5)
the only changes needed are:
DESCRIPTION={"Updated":false,"Size":0,"Last
Updated":"Fri Jun 08 09:51:18
CEST 2018","Storage
Domains":[{"uuid":"3ad1987a-8b7d-426d-9d51-4a78cb0a888f"}],"Disk
Description":"OVF_STORE"}
IMAGE=0ebefe5e-9053-4bf1-bdfd-fdb26579c179
I took the image uuid from the IU_ tag in lvs output.
Make sure the size of the metadata file is less then 512 bytes, otherwise
you will overwrite and corrupt the metadata of the next volume.
To write the metadata you should use:
# makes your metadata file aligned to sector size
truncate -s 512 fixed-metadata.txt
# write exactly one sector
dd if=fixed-metadata.txt of=/dev/vgname/metadata seek=4 count=1 bs=512
oflag=direct conv=fsync
After this change, engine should be able to use this volume again.
vdsm.log from manual OVF update test:
2018-06-20 09:28:27,840+0200 INFO (jsonrpc/7) [vdsm.api] START
setVolumeDescription(sdUUID=u'3ad1987a-8b7d-426d-9d51-4a78cb0a888f',
spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3',
imgUUID=u'0ebefe5e-9053-4bf1-bdfd-fdb26579c179',
volUUID=u'212d644c-0155-4999-9df9-72bacfc7f141',
description=u'{"Updated":false,"Last Updated":"Fri Jun 08
09:51:18 CEST
2018","Storage
Domains":[{"uuid":"3ad1987a-8b7d-426d-9d51-4a78cb0a888f"}],"Disk
Description":"OVF_STORE"}', options=None)
from=::ffff:<IP>,51790,
flow_id=7e4edb74, task_id=5f1fda67-a073-419a-bba5-9bf680c0e5d5 (api:46)
2018-06-20 09:28:28,072+0200 WARN (jsonrpc/7) [storage.ResourceManager]
Resource factory failed to create resource
'01_img_3ad1987a-8b7d-426d-9d51-4a78cb0a888f.0ebefe5e-9053-4bf1-bdfd-fdb26579c179'.
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-20 09:28:28,072+0200 WARN (jsonrpc/7)
[storage.ResourceManager.Request]
(ResName='01_img_3ad1987a-8b7d-426d-9d51-4a78cb0a888f.0ebefe5e-9053-4bf1-bdfd-fdb26579c179',
ReqID='10c95223-f349-4ac3-ab2f-7a5f3d1c7749') Tried to cancel a processed
request (resourceManager:187)
2018-06-20 09:28:28,073+0200 INFO (jsonrpc/7) [vdsm.api] FINISH
setVolumeDescription error=Could not acquire resource. Probably resource
factory threw an exception.: () from=::ffff:<IP>,51790, flow_id=7e4edb74,
task_id=5f1fda67-a073-419a-bba5-9bf680c0e5d5 (api:50)
2018-06-20 09:28:28,073+0200 ERROR (jsonrpc/7) [storage.TaskManager.Task]
(Task='5f1fda67-a073-419a-bba5-9bf680c0e5d5') 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-20 09:28:28,073+0200 INFO (jsonrpc/7) [storage.TaskManager.Task]
(Task='5f1fda67-a073-419a-bba5-9bf680c0e5d5') aborting: Task is aborted:
u'Could not acquire resource. Probably resource factory threw an
exception.: ()' - code 100 (task:1181)
2018-06-20 09:28:28,073+0200 ERROR (jsonrpc/7) [storage.Dispatcher] FINISH
setVolumeDescription error=Could not acquire resource. Probably resource
factory threw an exception.: () (dispatcher:82)
I worked around the SPM problem by running engine-setup (neither
vds-client Host/StoragePool *Task*, async_task_entries or taskcleaner.sh
showed any tasks).
All the best,
Oliver
*Von:* Nir Soffer <nsoffer(a)redhat.com>
*Gesendet:* Dienstag, 19. Juni 2018 23:39
*An:* Elad Ben Aharon <ebenahar(a)redhat.com>
*Cc:* users(a)ovirt.org; Albl, Oliver <Oliver.Albl(a)fabasoft.com>
*Betreff:* [ovirt-users] Re: Failed to update VMs/Templates OVF data,
cannot change SPM
On Wed, Jun 20, 2018 at 12:11 AM Elad Ben Aharon <ebenahar(a)redhat.com>
wrote:
Can you please attach engine.log and vdsm.log?
On Tue, Jun 19, 2018 at 6:58 PM, Albl, Oliver <Oliver.Albl(a)fabasoft.com>
wrote:
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(a)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.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: {}",)
This means the volume metadata is missing a required key: "DOMAIN".
Can you share the output of:
lvs -o vg_name,lv_name,tags | grep a1e7554d-530c-4c07-a4b5-459a1c509e39
There should a tag named MD_N - N is an integer. Once you find it,
we would like to see the metadata at offset N * 512 in the metadata volume.
You can extract it like this:
dd if=/dev/vgname/metadata bs=512 skip=N
Nir
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(a)ovirt.org
To unsubscribe send an email to users-leave(a)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/MRBMUKOZ7VT...
_______________________________________________
Users mailing list -- users(a)ovirt.org
To unsubscribe send an email to users-leave(a)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/6XG4IFPYXAI...
4:17 a.m.
New subject: Failed to update VMs/Templates OVF data, cannot change SPM
Nir,
thank you! I could successfully recover the corrupt metadata blocks on all affected
storage domains!
Affected storage domains were created between January and March this year, accessed by 40
hosts in parallel with changing SPMs…unfortunately matching vdsm logs are not available
anymore. I could privide a vsdm.log backup from SPM showing the first occurrence (+15
minutes prior the error).
All the best,
Oliver
Von: Nir Soffer <nsoffer(a)redhat.com>
Gesendet: Mittwoch, 20. Juni 2018 10:01
An: Bruckner, Simone <simone.bruckner(a)fabasoft.com>
Cc: users(a)ovirt.org
Betreff: [ovirt-users] Re: Failed to update VMs/Templates OVF data, cannot change SPM
On Wed, Jun 20, 2018 at 10:33 AM Bruckner, Simone
<simone.bruckner@fabasoft.com<mailto:simone.bruckner@fabasoft.com>> wrote:
Hi Nir,
I identified the reason for the failing OVF updates on the initial VG – metadata was
affected by blkdiscard tests in scope of
https://bugzilla.redhat.com/show_bug.cgi?id=1562369
However, the OVF updates are failing on other installations as well (on 2 out of 40
storage domains). Here is the output of your commands:
# lvs -o vg_name,lv_name,tags | grep 3ad1987a-8b7d-426d-9d51-4a78cb0a888f
3ad1987a-8b7d-426d-9d51-4a78cb0a888f 212d644c-0155-4999-9df9-72bacfc7f141
IU_0ebefe5e-9053-4bf1-bdfd-fdb26579c179,MD_4,PU_00000000-0000-0000-0000-000000000000
3ad1987a-8b7d-426d-9d51-4a78cb0a888f 94f519de-bc19-4557-82c4-86bbcfc5dd2f
IU_60d9eec7-951f-4594-ae99-7d31318ee3a9,MD_5,PU_00000000-0000-0000-0000-000000000000
3ad1987a-8b7d-426d-9d51-4a78cb0a888f ids
3ad1987a-8b7d-426d-9d51-4a78cb0a888f inbox
3ad1987a-8b7d-426d-9d51-4a78cb0a888f leases
3ad1987a-8b7d-426d-9d51-4a78cb0a888f master
3ad1987a-8b7d-426d-9d51-4a78cb0a888f metadata
3ad1987a-8b7d-426d-9d51-4a78cb0a888f outbox
3ad1987a-8b7d-426d-9d51-4a78cb0a888f xleases
Looks good
# for i in 4 5; do
dd if=/dev/3ad1987a-8b7d-426d-9d51-4a78cb0a888f/metadata bs=512 count=1 skip=$i
of=metadata.$i
done
1+0 records in
1+0 records out
512 bytes (512 B) copied, 0.00121297 s, 422 kB/s
1+0 records in
1+0 records out
512 bytes (512 B) copied, 0.000735026 s, 697 kB/s
# file metadata.*
metadata.4: data
metadata.5: ASCII text
# cat metadata.5
DOMAIN=3ad1987a-8b7d-426d-9d51-4a78cb0a888f
CTIME=1520597691
FORMAT=RAW
DISKTYPE=OVFS
LEGALITY=LEGAL
SIZE=262144
VOLTYPE=LEAF
DESCRIPTION={"Updated":true,"Size":4669440,"Last
Updated":"Fri Jun 08 09:51:18 CEST 2018","Storage
Domains":[{"uuid":"3ad1987a-8b7d-426d-9d51-4a78cb0a888f"}],"Disk
Description":"OVF_STORE"}
IMAGE=60d9eec7-951f-4594-ae99-7d31318ee3a9
PUUID=00000000-0000-0000-0000-000000000000
MTIME=0
POOL_UUID=
TYPE=PREALLOCATED
GEN=0
EOF
Looks good
# od -c metadata.4
0000000 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0
*
0001000
There is no metada in this volume. This will fail every time when we try to store
something
into this volume.
I wonder how the metadata was deleted, maybe there was some error when the volume
was created?
Can you file a bug for this, and attach vdsm.log from the point this storage
domain was created until the error started?
An important date seems Fri Jun 08 09:51:18 CEST 2018 - at this date the volume
metadata was updated in the last time.
For recovering this volume, you can write valid metadata to the same offset
using dd.
Basically it is the same as the metadata of the other ovf storage (metadata.5)
the only changes needed are:
DESCRIPTION={"Updated":false,"Size":0,"Last
Updated":"Fri Jun 08 09:51:18 CEST 2018","Storage
Domains":[{"uuid":"3ad1987a-8b7d-426d-9d51-4a78cb0a888f"}],"Disk
Description":"OVF_STORE"}
IMAGE=0ebefe5e-9053-4bf1-bdfd-fdb26579c179
I took the image uuid from the IU_ tag in lvs output.
Make sure the size of the metadata file is less then 512 bytes, otherwise
you will overwrite and corrupt the metadata of the next volume.
To write the metadata you should use:
# makes your metadata file aligned to sector size
truncate -s 512 fixed-metadata.txt
# write exactly one sector
dd if=fixed-metadata.txt of=/dev/vgname/metadata seek=4 count=1 bs=512 oflag=direct
conv=fsync
After this change, engine should be able to use this volume again.
vdsm.log from manual OVF update test:
2018-06-20 09:28:27,840+0200 INFO (jsonrpc/7) [vdsm.api] START
setVolumeDescription(sdUUID=u'3ad1987a-8b7d-426d-9d51-4a78cb0a888f',
spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3',
imgUUID=u'0ebefe5e-9053-4bf1-bdfd-fdb26579c179',
volUUID=u'212d644c-0155-4999-9df9-72bacfc7f141',
description=u'{"Updated":false,"Last Updated":"Fri Jun 08
09:51:18 CEST 2018","Storage
Domains":[{"uuid":"3ad1987a-8b7d-426d-9d51-4a78cb0a888f"}],"Disk
Description":"OVF_STORE"}', options=None) from=::ffff:<IP>,51790,
flow_id=7e4edb74, task_id=5f1fda67-a073-419a-bba5-9bf680c0e5d5 (api:46)
2018-06-20 09:28:28,072+0200 WARN (jsonrpc/7) [storage.ResourceManager] Resource factory
failed to create resource
'01_img_3ad1987a-8b7d-426d-9d51-4a78cb0a888f.0ebefe5e-9053-4bf1-bdfd-fdb26579c179'.
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-20 09:28:28,072+0200 WARN (jsonrpc/7) [storage.ResourceManager.Request]
(ResName='01_img_3ad1987a-8b7d-426d-9d51-4a78cb0a888f.0ebefe5e-9053-4bf1-bdfd-fdb26579c179',
ReqID='10c95223-f349-4ac3-ab2f-7a5f3d1c7749') Tried to cancel a processed request
(resourceManager:187)
2018-06-20 09:28:28,073+0200 INFO (jsonrpc/7) [vdsm.api] FINISH setVolumeDescription
error=Could not acquire resource. Probably resource factory threw an exception.: ()
from=::ffff:<IP>,51790, flow_id=7e4edb74,
task_id=5f1fda67-a073-419a-bba5-9bf680c0e5d5 (api:50)
2018-06-20 09:28:28,073+0200 ERROR (jsonrpc/7) [storage.TaskManager.Task]
(Task='5f1fda67-a073-419a-bba5-9bf680c0e5d5') 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-20 09:28:28,073+0200 INFO (jsonrpc/7) [storage.TaskManager.Task]
(Task='5f1fda67-a073-419a-bba5-9bf680c0e5d5') aborting: Task is aborted:
u'Could not acquire resource. Probably resource factory threw an exception.: ()' -
code 100 (task:1181)
2018-06-20 09:28:28,073+0200 ERROR (jsonrpc/7) [storage.Dispatcher] FINISH
setVolumeDescription error=Could not acquire resource. Probably resource factory threw an
exception.: () (dispatcher:82)
I worked around the SPM problem by running engine-setup (neither vds-client
Host/StoragePool *Task*, async_task_entries or taskcleaner.sh showed any tasks).
All the best,
Oliver
Von: Nir Soffer <nsoffer@redhat.com<mailto:nsoffer@redhat.com>>
Gesendet: Dienstag, 19. Juni 2018 23:39
An: Elad Ben Aharon <ebenahar@redhat.com<mailto:ebenahar@redhat.com>>
Cc: users@ovirt.org<mailto:users@ovirt.org>; Albl, Oliver
<Oliver.Albl@fabasoft.com<mailto:Oliver.Albl@fabasoft.com>>
Betreff: [ovirt-users] Re: Failed to update VMs/Templates OVF data, cannot change SPM
On Wed, Jun 20, 2018 at 12:11 AM Elad Ben Aharon
<ebenahar@redhat.com<mailto:ebenahar@redhat.com>> wrote:
Can you please attach engine.log and vdsm.log?
On Tue, Jun 19, 2018 at 6:58 PM, Albl, Oliver
<Oliver.Albl@fabasoft.com<mailto:Oliver.Albl@fabasoft.com>> wrote:
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<mailto: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.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: {}",)
This means the volume metadata is missing a required key: "DOMAIN".
Can you share the output of:
lvs -o vg_name,lv_name,tags | grep a1e7554d-530c-4c07-a4b5-459a1c509e39
There should a tag named MD_N - N is an integer. Once you find it,
we would like to see the metadata at offset N * 512 in the metadata volume.
You can extract it like this:
dd if=/dev/vgname/metadata bs=512 skip=N
Nir
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<mailto:users@ovirt.org>
To unsubscribe send an email to
users-leave@ovirt.org<mailto: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/MRBMUKOZ7VT...
_______________________________________________
Users mailing list -- users@ovirt.org<mailto:users@ovirt.org>
To unsubscribe send an email to
users-leave@ovirt.org<mailto: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/6XG4IFPYXAI...
1:33 p.m.
New subject: Failed to update VMs/Templates OVF data, cannot change SPM
On Wed, Jun 20, 2018 at 12:17 PM Albl, Oliver <Oliver.Albl(a)fabasoft.com>
wrote:
Nir,
thank you! I could successfully recover the corrupt metadata blocks on
all affected storage domains!
Affected storage domains were created between January and March this year,
accessed by 40 hosts in parallel with changing SPMs…unfortunately matching
vdsm logs are not available anymore. I could privide a vsdm.log backup from
SPM showing the first occurrence (+15 minutes prior the error).
These logs may be useful to understand why the metadata was wiped.
Please file a bug and attach these logs.
Nir
All the best,
Oliver
*Von:* Nir Soffer <nsoffer(a)redhat.com>
*Gesendet:* Mittwoch, 20. Juni 2018 10:01
*An:* Bruckner, Simone <simone.bruckner(a)fabasoft.com>
*Cc:* users(a)ovirt.org
*Betreff:* [ovirt-users] Re: Failed to update VMs/Templates OVF data,
cannot change SPM
On Wed, Jun 20, 2018 at 10:33 AM Bruckner, Simone <
simone.bruckner(a)fabasoft.com> wrote:
Hi Nir,
I identified the reason for the failing OVF updates on the initial VG –
metadata was affected by blkdiscard tests in scope of
https://bugzilla.redhat.com/show_bug.cgi?id=1562369
However, the OVF updates are failing on other installations as well (on 2
out of 40 storage domains). Here is the output of your commands:
# lvs -o vg_name,lv_name,tags | grep 3ad1987a-8b7d-426d-9d51-4a78cb0a888f
3ad1987a-8b7d-426d-9d51-4a78cb0a888f
212d644c-0155-4999-9df9-72bacfc7f141
IU_0ebefe5e-9053-4bf1-bdfd-fdb26579c179,MD_4,PU_00000000-0000-0000-0000-000000000000
3ad1987a-8b7d-426d-9d51-4a78cb0a888f
94f519de-bc19-4557-82c4-86bbcfc5dd2f
IU_60d9eec7-951f-4594-ae99-7d31318ee3a9,MD_5,PU_00000000-0000-0000-0000-000000000000
3ad1987a-8b7d-426d-9d51-4a78cb0a888f ids
3ad1987a-8b7d-426d-9d51-4a78cb0a888f inbox
3ad1987a-8b7d-426d-9d51-4a78cb0a888f leases
3ad1987a-8b7d-426d-9d51-4a78cb0a888f master
3ad1987a-8b7d-426d-9d51-4a78cb0a888f metadata
3ad1987a-8b7d-426d-9d51-4a78cb0a888f outbox
3ad1987a-8b7d-426d-9d51-4a78cb0a888f xleases
Looks good
# for i in 4 5; do
dd if=/dev/3ad1987a-8b7d-426d-9d51-4a78cb0a888f/metadata bs=512 count=1
skip=$i of=metadata.$i
done
1+0 records in
1+0 records out
512 bytes (512 B) copied, 0.00121297 s, 422 kB/s
1+0 records in
1+0 records out
512 bytes (512 B) copied, 0.000735026 s, 697 kB/s
# file metadata.*
metadata.4: data
metadata.5: ASCII text
# cat metadata.5
DOMAIN=3ad1987a-8b7d-426d-9d51-4a78cb0a888f
CTIME=1520597691
FORMAT=RAW
DISKTYPE=OVFS
LEGALITY=LEGAL
SIZE=262144
VOLTYPE=LEAF
DESCRIPTION={"Updated":true,"Size":4669440,"Last
Updated":"Fri Jun 08
09:51:18 CEST 2018","Storage
Domains":[{"uuid":"3ad1987a-8b7d-426d-9d51-4a78cb0a888f"}],"Disk
Description":"OVF_STORE"}
IMAGE=60d9eec7-951f-4594-ae99-7d31318ee3a9
PUUID=00000000-0000-0000-0000-000000000000
MTIME=0
POOL_UUID=
TYPE=PREALLOCATED
GEN=0
EOF
Looks good
# od -c metadata.4
0000000 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0
*
0001000
There is no metada in this volume. This will fail every time when we try
to store something
into this volume.
I wonder how the metadata was deleted, maybe there was some error when
the volume
was created?
Can you file a bug for this, and attach vdsm.log from the point this
storage
domain was created until the error started?
An important date seems Fri Jun 08 09:51:18 CEST 2018 - at this date the
volume
metadata was updated in the last time.
For recovering this volume, you can write valid metadata to the same offset
using dd.
Basically it is the same as the metadata of the other ovf storage
(metadata.5)
the only changes needed are:
DESCRIPTION={"Updated":false,"Size":0,"Last
Updated":"Fri Jun 08 09:51:18
CEST 2018","Storage
Domains":[{"uuid":"3ad1987a-8b7d-426d-9d51-4a78cb0a888f"}],"Disk
Description":"OVF_STORE"}
IMAGE=0ebefe5e-9053-4bf1-bdfd-fdb26579c179
I took the image uuid from the IU_ tag in lvs output.
Make sure the size of the metadata file is less then 512 bytes, otherwise
you will overwrite and corrupt the metadata of the next volume.
To write the metadata you should use:
# makes your metadata file aligned to sector size
truncate -s 512 fixed-metadata.txt
# write exactly one sector
dd if=fixed-metadata.txt of=/dev/vgname/metadata seek=4 count=1 bs=512
oflag=direct conv=fsync
After this change, engine should be able to use this volume again.
vdsm.log from manual OVF update test:
2018-06-20 09:28:27,840+0200 INFO (jsonrpc/7) [vdsm.api] START
setVolumeDescription(sdUUID=u'3ad1987a-8b7d-426d-9d51-4a78cb0a888f',
spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3',
imgUUID=u'0ebefe5e-9053-4bf1-bdfd-fdb26579c179',
volUUID=u'212d644c-0155-4999-9df9-72bacfc7f141',
description=u'{"Updated":false,"Last Updated":"Fri Jun 08
09:51:18 CEST
2018","Storage
Domains":[{"uuid":"3ad1987a-8b7d-426d-9d51-4a78cb0a888f"}],"Disk
Description":"OVF_STORE"}', options=None)
from=::ffff:<IP>,51790,
flow_id=7e4edb74, task_id=5f1fda67-a073-419a-bba5-9bf680c0e5d5 (api:46)
2018-06-20 09:28:28,072+0200 WARN (jsonrpc/7) [storage.ResourceManager]
Resource factory failed to create resource
'01_img_3ad1987a-8b7d-426d-9d51-4a78cb0a888f.0ebefe5e-9053-4bf1-bdfd-fdb26579c179'.
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-20 09:28:28,072+0200 WARN (jsonrpc/7)
[storage.ResourceManager.Request]
(ResName='01_img_3ad1987a-8b7d-426d-9d51-4a78cb0a888f.0ebefe5e-9053-4bf1-bdfd-fdb26579c179',
ReqID='10c95223-f349-4ac3-ab2f-7a5f3d1c7749') Tried to cancel a processed
request (resourceManager:187)
2018-06-20 09:28:28,073+0200 INFO (jsonrpc/7) [vdsm.api] FINISH
setVolumeDescription error=Could not acquire resource. Probably resource
factory threw an exception.: () from=::ffff:<IP>,51790, flow_id=7e4edb74,
task_id=5f1fda67-a073-419a-bba5-9bf680c0e5d5 (api:50)
2018-06-20 09:28:28,073+0200 ERROR (jsonrpc/7) [storage.TaskManager.Task]
(Task='5f1fda67-a073-419a-bba5-9bf680c0e5d5') 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-20 09:28:28,073+0200 INFO (jsonrpc/7) [storage.TaskManager.Task]
(Task='5f1fda67-a073-419a-bba5-9bf680c0e5d5') aborting: Task is aborted:
u'Could not acquire resource. Probably resource factory threw an
exception.: ()' - code 100 (task:1181)
2018-06-20 09:28:28,073+0200 ERROR (jsonrpc/7) [storage.Dispatcher] FINISH
setVolumeDescription error=Could not acquire resource. Probably resource
factory threw an exception.: () (dispatcher:82)
I worked around the SPM problem by running engine-setup (neither
vds-client Host/StoragePool *Task*, async_task_entries or taskcleaner.sh
showed any tasks).
All the best,
Oliver
*Von:* Nir Soffer <nsoffer(a)redhat.com>
*Gesendet:* Dienstag, 19. Juni 2018 23:39
*An:* Elad Ben Aharon <ebenahar(a)redhat.com>
*Cc:* users(a)ovirt.org; Albl, Oliver <Oliver.Albl(a)fabasoft.com>
*Betreff:* [ovirt-users] Re: Failed to update VMs/Templates OVF data,
cannot change SPM
On Wed, Jun 20, 2018 at 12:11 AM Elad Ben Aharon <ebenahar(a)redhat.com>
wrote:
Can you please attach engine.log and vdsm.log?
On Tue, Jun 19, 2018 at 6:58 PM, Albl, Oliver <Oliver.Albl(a)fabasoft.com>
wrote:
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(a)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.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: {}",)
This means the volume metadata is missing a required key: "DOMAIN".
Can you share the output of:
lvs -o vg_name,lv_name,tags | grep a1e7554d-530c-4c07-a4b5-459a1c509e39
There should a tag named MD_N - N is an integer. Once you find it,
we would like to see the metadata at offset N * 512 in the metadata volume.
You can extract it like this:
dd if=/dev/vgname/metadata bs=512 skip=N
Nir
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(a)ovirt.org
To unsubscribe send an email to users-leave(a)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/MRBMUKOZ7VT...
_______________________________________________
Users mailing list -- users(a)ovirt.org
To unsubscribe send an email to users-leave(a)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/6XG4IFPYXAI...
9:35 a.m.
New subject: Failed to update VMs/Templates OVF data, cannot change SPM
Hi Nir,
here is the link: https://bugzilla.redhat.com/show_bug.cgi?id=1593766
All the best,
Oliver
Von: Nir Soffer <nsoffer(a)redhat.com>
Gesendet: Mittwoch, 20. Juni 2018 20:33
An: Albl, Oliver <Oliver.Albl(a)fabasoft.com>
Cc: users(a)ovirt.org
Betreff: [ovirt-users] Re: Failed to update VMs/Templates OVF data, cannot change SPM
On Wed, Jun 20, 2018 at 12:17 PM Albl, Oliver
<Oliver.Albl@fabasoft.com<mailto:Oliver.Albl@fabasoft.com>> wrote:
Nir,
thank you! I could successfully recover the corrupt metadata blocks on all affected
storage domains!
Affected storage domains were created between January and March this year, accessed by 40
hosts in parallel with changing SPMs…unfortunately matching vdsm logs are not available
anymore. I could privide a vsdm.log backup from SPM showing the first occurrence (+15
minutes prior the error).
These logs may be useful to understand why the metadata was wiped.
Please file a bug and attach these logs.
Nir
All the best,
Oliver
Von: Nir Soffer <nsoffer@redhat.com<mailto:nsoffer@redhat.com>>
Gesendet: Mittwoch, 20. Juni 2018 10:01
An: Bruckner, Simone
<simone.bruckner@fabasoft.com<mailto:simone.bruckner@fabasoft.com>>
Cc: users@ovirt.org<mailto:users@ovirt.org>
Betreff: [ovirt-users] Re: Failed to update VMs/Templates OVF data, cannot change SPM
On Wed, Jun 20, 2018 at 10:33 AM Bruckner, Simone
<simone.bruckner@fabasoft.com<mailto:simone.bruckner@fabasoft.com>> wrote:
Hi Nir,
I identified the reason for the failing OVF updates on the initial VG – metadata was
affected by blkdiscard tests in scope of
https://bugzilla.redhat.com/show_bug.cgi?id=1562369
However, the OVF updates are failing on other installations as well (on 2 out of 40
storage domains). Here is the output of your commands:
# lvs -o vg_name,lv_name,tags | grep 3ad1987a-8b7d-426d-9d51-4a78cb0a888f
3ad1987a-8b7d-426d-9d51-4a78cb0a888f 212d644c-0155-4999-9df9-72bacfc7f141
IU_0ebefe5e-9053-4bf1-bdfd-fdb26579c179,MD_4,PU_00000000-0000-0000-0000-000000000000
3ad1987a-8b7d-426d-9d51-4a78cb0a888f 94f519de-bc19-4557-82c4-86bbcfc5dd2f
IU_60d9eec7-951f-4594-ae99-7d31318ee3a9,MD_5,PU_00000000-0000-0000-0000-000000000000
3ad1987a-8b7d-426d-9d51-4a78cb0a888f ids
3ad1987a-8b7d-426d-9d51-4a78cb0a888f inbox
3ad1987a-8b7d-426d-9d51-4a78cb0a888f leases
3ad1987a-8b7d-426d-9d51-4a78cb0a888f master
3ad1987a-8b7d-426d-9d51-4a78cb0a888f metadata
3ad1987a-8b7d-426d-9d51-4a78cb0a888f outbox
3ad1987a-8b7d-426d-9d51-4a78cb0a888f xleases
Looks good
# for i in 4 5; do
dd if=/dev/3ad1987a-8b7d-426d-9d51-4a78cb0a888f/metadata bs=512 count=1 skip=$i
of=metadata.$i
done
1+0 records in
1+0 records out
512 bytes (512 B) copied, 0.00121297 s, 422 kB/s
1+0 records in
1+0 records out
512 bytes (512 B) copied, 0.000735026 s, 697 kB/s
# file metadata.*
metadata.4: data
metadata.5: ASCII text
# cat metadata.5
DOMAIN=3ad1987a-8b7d-426d-9d51-4a78cb0a888f
CTIME=1520597691
FORMAT=RAW
DISKTYPE=OVFS
LEGALITY=LEGAL
SIZE=262144
VOLTYPE=LEAF
DESCRIPTION={"Updated":true,"Size":4669440,"Last
Updated":"Fri Jun 08 09:51:18 CEST 2018","Storage
Domains":[{"uuid":"3ad1987a-8b7d-426d-9d51-4a78cb0a888f"}],"Disk
Description":"OVF_STORE"}
IMAGE=60d9eec7-951f-4594-ae99-7d31318ee3a9
PUUID=00000000-0000-0000-0000-000000000000
MTIME=0
POOL_UUID=
TYPE=PREALLOCATED
GEN=0
EOF
Looks good
# od -c metadata.4
0000000 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0
*
0001000
There is no metada in this volume. This will fail every time when we try to store
something
into this volume.
I wonder how the metadata was deleted, maybe there was some error when the volume
was created?
Can you file a bug for this, and attach vdsm.log from the point this storage
domain was created until the error started?
An important date seems Fri Jun 08 09:51:18 CEST 2018 - at this date the volume
metadata was updated in the last time.
For recovering this volume, you can write valid metadata to the same offset
using dd.
Basically it is the same as the metadata of the other ovf storage (metadata.5)
the only changes needed are:
DESCRIPTION={"Updated":false,"Size":0,"Last
Updated":"Fri Jun 08 09:51:18 CEST 2018","Storage
Domains":[{"uuid":"3ad1987a-8b7d-426d-9d51-4a78cb0a888f"}],"Disk
Description":"OVF_STORE"}
IMAGE=0ebefe5e-9053-4bf1-bdfd-fdb26579c179
I took the image uuid from the IU_ tag in lvs output.
Make sure the size of the metadata file is less then 512 bytes, otherwise
you will overwrite and corrupt the metadata of the next volume.
To write the metadata you should use:
# makes your metadata file aligned to sector size
truncate -s 512 fixed-metadata.txt
# write exactly one sector
dd if=fixed-metadata.txt of=/dev/vgname/metadata seek=4 count=1 bs=512 oflag=direct
conv=fsync
After this change, engine should be able to use this volume again.
vdsm.log from manual OVF update test:
2018-06-20 09:28:27,840+0200 INFO (jsonrpc/7) [vdsm.api] START
setVolumeDescription(sdUUID=u'3ad1987a-8b7d-426d-9d51-4a78cb0a888f',
spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3',
imgUUID=u'0ebefe5e-9053-4bf1-bdfd-fdb26579c179',
volUUID=u'212d644c-0155-4999-9df9-72bacfc7f141',
description=u'{"Updated":false,"Last Updated":"Fri Jun 08
09:51:18 CEST 2018","Storage
Domains":[{"uuid":"3ad1987a-8b7d-426d-9d51-4a78cb0a888f"}],"Disk
Description":"OVF_STORE"}', options=None) from=::ffff:<IP>,51790,
flow_id=7e4edb74, task_id=5f1fda67-a073-419a-bba5-9bf680c0e5d5 (api:46)
2018-06-20 09:28:28,072+0200 WARN (jsonrpc/7) [storage.ResourceManager] Resource factory
failed to create resource
'01_img_3ad1987a-8b7d-426d-9d51-4a78cb0a888f.0ebefe5e-9053-4bf1-bdfd-fdb26579c179'.
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-20 09:28:28,072+0200 WARN (jsonrpc/7) [storage.ResourceManager.Request]
(ResName='01_img_3ad1987a-8b7d-426d-9d51-4a78cb0a888f.0ebefe5e-9053-4bf1-bdfd-fdb26579c179',
ReqID='10c95223-f349-4ac3-ab2f-7a5f3d1c7749') Tried to cancel a processed request
(resourceManager:187)
2018-06-20 09:28:28,073+0200 INFO (jsonrpc/7) [vdsm.api] FINISH setVolumeDescription
error=Could not acquire resource. Probably resource factory threw an exception.: ()
from=::ffff:<IP>,51790, flow_id=7e4edb74,
task_id=5f1fda67-a073-419a-bba5-9bf680c0e5d5 (api:50)
2018-06-20 09:28:28,073+0200 ERROR (jsonrpc/7) [storage.TaskManager.Task]
(Task='5f1fda67-a073-419a-bba5-9bf680c0e5d5') 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-20 09:28:28,073+0200 INFO (jsonrpc/7) [storage.TaskManager.Task]
(Task='5f1fda67-a073-419a-bba5-9bf680c0e5d5') aborting: Task is aborted:
u'Could not acquire resource. Probably resource factory threw an exception.: ()' -
code 100 (task:1181)
2018-06-20 09:28:28,073+0200 ERROR (jsonrpc/7) [storage.Dispatcher] FINISH
setVolumeDescription error=Could not acquire resource. Probably resource factory threw an
exception.: () (dispatcher:82)
I worked around the SPM problem by running engine-setup (neither vds-client
Host/StoragePool *Task*, async_task_entries or taskcleaner.sh showed any tasks).
All the best,
Oliver
Von: Nir Soffer <nsoffer@redhat.com<mailto:nsoffer@redhat.com>>
Gesendet: Dienstag, 19. Juni 2018 23:39
An: Elad Ben Aharon <ebenahar@redhat.com<mailto:ebenahar@redhat.com>>
Cc: users@ovirt.org<mailto:users@ovirt.org>; Albl, Oliver
<Oliver.Albl@fabasoft.com<mailto:Oliver.Albl@fabasoft.com>>
Betreff: [ovirt-users] Re: Failed to update VMs/Templates OVF data, cannot change SPM
On Wed, Jun 20, 2018 at 12:11 AM Elad Ben Aharon
<ebenahar@redhat.com<mailto:ebenahar@redhat.com>> wrote:
Can you please attach engine.log and vdsm.log?
On Tue, Jun 19, 2018 at 6:58 PM, Albl, Oliver
<Oliver.Albl@fabasoft.com<mailto:Oliver.Albl@fabasoft.com>> wrote:
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<mailto: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.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: {}",)
This means the volume metadata is missing a required key: "DOMAIN".
Can you share the output of:
lvs -o vg_name,lv_name,tags | grep a1e7554d-530c-4c07-a4b5-459a1c509e39
There should a tag named MD_N - N is an integer. Once you find it,
we would like to see the metadata at offset N * 512 in the metadata volume.
You can extract it like this:
dd if=/dev/vgname/metadata bs=512 skip=N
Nir
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<mailto:users@ovirt.org>
To unsubscribe send an email to
users-leave@ovirt.org<mailto: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/MRBMUKOZ7VT...
_______________________________________________
Users mailing list -- users@ovirt.org<mailto:users@ovirt.org>
To unsubscribe send an email to
users-leave@ovirt.org<mailto: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/6XG4IFPYXAI...
2329
days inactive
2331
days old
7 comments
4 participants
participants (4)
-
Albl, Oliver -
Bruckner, Simone -
Elad Ben Aharon -
Nir Soffer