Created attachment 1671373 [details] engine and vdsm logs Description of problem: Occured in automation and manually reproduced via RESTAPI. Via wedadmin same operation worked. Same automation ran endless times on 4.3.9 builds(no 0day) and no issues were seen. Adding ISCSI storage domain via RESTAPI fails with the following Errors: Engine log: 020-03-18 20:26:29,426+02 WARN [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateStorageDomainVDSCommand] (default task-17) [25a05818] Unexpected return value: Status [code=616, message=Volume Group metadata i sn't as expected: "reason=Expected one metadata pv in vg: 0bb1b02b-6186-44b5-b065-4084f290baa5, vg pvs: [Stub(name=u'/dev/mapper/360002ac0000000000000002300021f6b', stale=True)]"] 2020-03-18 20:26:29,427+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateStorageDomainVDSCommand] (default task-17) [25a05818] Failed in 'CreateStorageDomainVDS' method 2020-03-18 20:26:29,427+02 WARN [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateStorageDomainVDSCommand] (default task-17) [25a05818] Unexpected return value: Status [code=616, message=Volume Group metadata isn't as expected: "reason=Expected one metadata pv in vg: 0bb1b02b-6186-44b5-b065-4084f290baa5, vg pvs: [Stub(name=u'/dev/mapper/360002ac0000000000000002300021f6b', stale=True)]"] 2020-03-18 20:26:29,454+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-17) [25a05818] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), VDSM host_mixed_1 command CreateStorageDomainVDS failed: Volume Group metadata isn't as expected: "reason=Expected one metadata pv in vg: 0bb1b02b-6186-44b5-b065-4084f290baa5, vg pvs: [Stub(name=u'/dev/mapper/360002ac0000000000000002300021f6b', stale=True)]" 2020-03-18 20:26:29,455+02 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateStorageDomainVDSCommand] (default task-17) [25a05818] Command 'org.ovirt.engine.core.vdsbroker.vdsbroker.CreateStorageDomainVDSCommand' return value 'StatusOnlyReturn [status=Status [code=616, message=Volume Group metadata isn't as expected: "reason=Expected one metadata pv in vg: 0bb1b02b-6186-44b5-b065-4084f290baa5, vg pvs: [Stub(name=u'/dev/mapper/360002ac0000000000000002300021f6b', stale=True)]"]]' 2020-03-18 20:26:29,455+02 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateStorageDomainVDSCommand] (default task-17) [25a05818] HostName = host_mixed_1 2020-03-18 20:26:29,456+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateStorageDomainVDSCommand] (default task-17) [25a05818] Command 'CreateStorageDomainVDSCommand(HostName = host_mixed_1, CreateStorageDomainVDSCommandParameters:{hostId='60d7c088-570b-4f6b-94ae-0057f552d3af', storageDomain='StorageDomainStatic:{name='iscsi_1', id='0bb1b02b-6186-44b5-b065-4084f290baa5'}', args='UwGYx4-8mox-lYcw-TOdR-9DTs-Wszb-VlK0Fb'})' execution failed: VDSGenericException: VDSErrorException: Failed to CreateStorageDomainVDS, error = Volume Group metadata isn't as expected: "reason=Expected one metadata pv in vg: 0bb1b02b-6186-44b5-b065-4084f290baa5, vg pvs: [Stub(name=u'/dev/mapper/360002ac0000000000000002300021f6b', stale=True)]", code = 616 2020-03-18 20:26:29,456+02 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateStorageDomainVDSCommand] (default task-17) [25a05818] FINISH, CreateStorageDomainVDSCommand, return: , log id: 15f91a93 2020-03-18 20:26:29,456+02 ERROR [org.ovirt.engine.core.bll.storage.domain.AddSANStorageDomainCommand] (default task-17) [25a05818] Command 'org.ovirt.engine.core.bll.storage.domain.AddSANStorageDomainCommand' failed: EngineException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed to CreateStorageDomainVDS, error = Volume Group metadata isn't as expected: "reason=Expected one metadata pv in vg: 0bb1b02b-6186-44b5-b065-4084f290baa5, vg pvs: [Stub(name=u'/dev/mapper/360002ac0000000000000002300021f6b', stale=True)]", code = 616 (Failed with error unexpected and code 16) 2020-03-18 20:26:29,484+02 INFO [org.ovirt.engine.core.bll.CommandCompensator] (default task-17) [25a05818] Command [id=ccc7c21a-cc1f-43e6-907a-d248817a1815]: Compensating NEW_ENTITY_ID of org.ovirt.engine.core.common.businessentities.profiles.DiskProfile; snapshot: 6cd197bb-371f-4a53-b4c3-36d571d99277. 2020-03-18 20:26:29,497+02 INFO [org.ovirt.engine.core.bll.CommandCompensator] (default task-17) [25a05818] Command [id=ccc7c21a-cc1f-43e6-907a-d248817a1815]: Compensating NEW_ENTITY_ID of org.ovirt.engine.core.common.businessentities.StorageDomainDynamic; snapshot: 0bb1b02b-6186-44b5-b065-4084f290baa5. 2020-03-18 20:26:29,506+02 INFO [org.ovirt.engine.core.bll.CommandCompensator] (default task-17) [25a05818] Command [id=ccc7c21a-cc1f-43e6-907a-d248817a1815]: Compensating NEW_ENTITY_ID of org.ovirt.engine.core.common.businessentities.StorageDomainStatic; snapshot: 0bb1b02b-6186-44b5-b065-4084f290baa5. 2020-03-18 20:26:29,566+02 ERROR [org.ovirt.engine.core.bll.storage.domain.AddSANStorageDomainCommand] (default task-17) [25a05818] Transaction rolled-back for command 'org.ovirt.engine.core.bll.storage.domain.: VDSM log: 2020-03-18 20:26:29,399+0200 ERROR (jsonrpc/0) [storage.LVM] Reloading PVs failed: pvs=['/dev/mapper/360002ac0000000000000002300021f6b'] rc=5 out=[' qnWHVd-iM8L-Zh1q-2maC-YqZK-3WNP-VUb5Wh|/dev/mapper/360002ac0000000000000002300021f6b|160658620416|0bb1b02b-6186-44b5-b065-4084f290baa5|UwGYx4-8mox-lYcw-TOdR-9DTs-Wszb-VlK0Fb|150994944|1197|0|2|161061273600|2'] err=[' Read-only locking type set. Write locks are prohibited.', ' Recovery of standalone physical volumes failed.', ' Cannot process standalone physical volumes', ' Read-only locking type set. Write locks are prohibited.', ' Recovery of standalone physical volumes failed.', ' Cannot process standalone physical volumes', ' Read-only locking type set. Write locks are prohibited.', ' Recovery of standalone physical volumes failed.', ' Cannot process standalone physical volumes'] (lvm:504) 2020-03-18 20:26:29,399+0200 INFO (jsonrpc/0) [vdsm.api] FINISH createStorageDomain error=Volume Group metadata isn't as expected: "reason=Expected one metadata pv in vg: 0bb1b02b-6186-44b5-b065-4084f290baa5, vg pvs: [Stub(name=u'/dev/mapper/360002ac0000000000000002300021f6b', stale=True)]" from=::ffff:10.35.161.182,46348, flow_id=25a05818, task_id=da7ad873-9879-45d4-964c-d0f6b68bf9a9 (api:52) 2020-03-18 20:26:29,400+0200 ERROR (jsonrpc/0) [storage.TaskManager.Task] (Task='da7ad873-9879-45d4-964c-d0f6b68bf9a9') 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 createStorageDomain File "/usr/lib/python2.7/site-packages/vdsm/common/api.py", line 50, in method ret = func(*args, **kwargs) File "/usr/lib/python2.7/site-packages/vdsm/storage/hsm.py", line 2626, in createStorageDomain max_hosts=max_hosts) File "/usr/lib/python2.7/site-packages/vdsm/storage/blockSD.py", line 1146, in create device=lvm.getVgMetadataPv(vgName), File "/usr/lib/python2.7/site-packages/vdsm/storage/lvm.py", line 1771, in getVgMetadataPv (vgName, pvs)) UnexpectedVolumeGroupMetadata: Volume Group metadata isn't as expected: "reason=Expected one metadata pv in vg: 0bb1b02b-6186-44b5-b065-4084f290baa5, vg pvs: [Stub(name=u'/dev/mapper/360002ac0000000000000002300021f6b', stale=True)]" 2020-03-18 20:26:29,400+0200 INFO (jsonrpc/0) [storage.TaskManager.Task] (Task='da7ad873-9879-45d4-964c-d0f6b68bf9a9') aborting: Task is aborted: 'Volume Group metadata isn\'t as expected: "reason=Expected one metadata pv in vg: 0bb1b02b-6186-44b5-b065-4084f290baa5, vg pvs: [Stub(name=u\'/dev/mapper/360002ac0000000000000002300021f6b\', stale=True)]"' - code 616 (task:1181) 2020-03-18 20:26:29,400+0200 ERROR (jsonrpc/0) [storage.Dispatcher] FINISH createStorageDomain error=Volume Group metadata isn't as expected: "reason=Expected one metadata pv in vg: 0bb1b02b-6186-44b5-b065-4084f290baa5, vg pvs: [Stub(name=u'/dev/mapper/360002ac0000000000000002300021f6b', stale=True)]" (dispatcher:83) 2020-03-18 20:26:29,401+0200 INFO (jsonrpc/0) [jsonrpc.JsonRpcServer] RPC call StorageDomain.create failed (error 616) in 2.75 seconds (__init__:312) Version-Release number of selected component (if applicable): rhv-4.3.9-7 (0day build) ovirt-engine 4.3.9.4-11.el7 vdsm-4.30.43-1.el7ev.x86_64 How reproducible: Happens multiple times via automation/RESTAPI Steps to Reproduce: 1.Add ISCSI SD via REST: RestAPI request used: URL: https://storage-ge-02.scl.lab.tlv.redhat.com/ovirt-engine/api/storagedomains Method: POST Body: <storage_domain> <name>iscsi_2</name> <storage> <logical_units> <logical_unit id="360002ac0000000000000002400021f6b"> <address>3par-iscsi-1.scl.lab.tlv.redhat.com</address> <port>3260</port> <target>iqn.2000-05.com.3pardata:20210002ac021f6b</target> </logical_unit> </logical_units> <override_luns>true</override_luns> <type>iscsi</type> </storage> <storage_format>v5</storage_format> <type>data</type> <host> <name>host_mixed_2</name> </host> </storage_domain> Actual results: add ISCSI fails. REST response: <?xml version="1.0" encoding="UTF-8" standalone="yes"?> <fault> <detail>[Unexpected exception]</detail> <reason>Operation Failed</reason> </fault> Expected results: Additional info:
Seens that lvm on this host does not support pvs command with locking_type=4. Which lvm version is used?
[root@storage-ge2-vdsm2 ~]# rpm -qa|grep lvm lvm2-libs-2.02.186-7.el7.x86_64 libblockdev-lvm-2.18-5.el7.x86_64 llvm-private-7.0.1-1.el7.x86_64 udisks2-lvm2-2.8.4-1.el7.x86_64 lvm2-2.02.186-7.el7.x86_64 looks likes fit for BZ #1809660 is not complete/work properly: [root@storage-ge2-vdsm2 ~]# /sbin/lvm pvs --config 'global { locking_type=4 prioritise_write_locks=1 wait_for_locks=1 use_lvmetad=0 }' --select 'pv_name = /dev/mapper/360002ac0000000000000002400021f6b' Read-only locking type set. Write locks are prohibited. Recovery of standalone physical volumes failed. Cannot process standalone physical volumes Read-only locking type set. Write locks are prohibited. Recovery of standalone physical volumes failed. Cannot process standalone physical volumes Read-only locking type set. Write locks are prohibited. Recovery of standalone physical volumes failed. Cannot process standalone physical volumes PV VG Fmt Attr PSize PFree /dev/mapper/360002ac0000000000000002400021f6b 4f68437d-4af1-4249-9a8c-3052031d9715 lvm2 a-- 149,62g 149,62g [root@storage-ge2-vdsm2 ~]# echo $? 5 [root@storage-ge2-vdsm2 ~]# /sbin/lvm pvs --config 'global { locking_type=1 prioritise_write_locks=1 wait_for_locks=1 use_lvmetad=0 }' --select 'pv_name = /dev/mapper/360002ac0000000000000002400021f6b' PV VG Fmt Attr PSize PFree /dev/mapper/360002ac0000000000000002400021f6b 4f68437d-4af1-4249-9a8c-3052031d9715 lvm2 a-- 149,62g 149,62g [root@storage-ge2-vdsm2 ~]# echo $? 0
Marian, (In reply to Vojtech Juranek from comment #2) > [root@storage-ge2-vdsm2 ~]# rpm -qa|grep lvm > lvm2-2.02.186-7.el7.x86_64 This is not the correct version. We need: lvm2-2.02.186-7.el7_8.1 If we can install vdsm with this version our requirement is not correct.
somehow the intended dependency check for lvm2 >= 2.02.186-7.el7_8.1 doesn't work. But that doesn't change the fact that you should be running with a different package. MAke sure you have lvm2-2.02.186-7.el7_8.1 and retest. Thanks
(In reply to Michal Skrivanek from comment #5) > somehow the intended dependency check for lvm2 >= 2.02.186-7.el7_8.1 doesn't > work. But that doesn't change the fact that you should be running with a > different package. MAke sure you have lvm2-2.02.186-7.el7_8.1 and retest. > Thanks Me and Shir retested this scenario on 2 ENV's which we saw the issue after installing the correct LVM(lvm2-2.02.186-7.el7_8.1) manually and the issue was not seen. Closing the bug.
MAnual deployment from RHEL7.7 has failed over iSCSI: [ ERROR ] Error: Fault reason is "Operation Failed". Fault detail is "[Unexpected exception]". HTTP response code is 400. [ ERROR ] fatal: [localhost]: FAILED! => {"changed": false, "msg": "Fault reason is \"Operation Failed\". Fault detail is \"[Unexpected exception]\". HTTP response code is 400."} Components were used: rhvm-appliance.x86_64 2:4.3-20200317.0.el7 @rhv-4.3.9 rhevm-appliance.noarch 1:4.0.20170307.0-1.el7ev rhvm-appliance.noarch 2:4.2-20190416.1.el7 rhel-7-server-rhv-mgmt-agent-x86-rhv-4.3 lvm2-2.02.185-2.el7_7.2.x86_64 ovirt-hosted-engine-ha-2.3.6-1.el7ev.noarch ovirt-hosted-engine-setup-2.3.13-1.el7ev.noarch Linux 3.10.0-1062.18.1.el7.x86_64 #1 SMP Wed Feb 12 14:08:31 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux Red Hat Enterprise Linux Server release 7.7 (Maipo)
VDSM log looks like just the same: 2020-03-19 16:23:14,298+0200 ERROR (jsonrpc/4) [storage.LVM] Reloading PVs failed: pvs=['/dev/mapper/20024f40058540497 '] rc=5 out=[' ceQxOW-kUxY-JV3s-9UcN-8aBO-cfWA-casK6R|/dev/mapper/20024f40058540497|214345711616|10ad9cc0-f477-4fbf-8 2b0-f35989212785|Chh8Pw-4OSP-UdGu-av0a-8hgr-3cPn-c1DBEg|135266304|1597|0|2|214748364800|2'] err=[' Read-only locking type set. Write locks are prohibited.', ' Recovery of standalone physical volumes failed.', ' Cannot process standal one physical volumes', ' Read-only locking type set. Write locks are prohibited.', ' Recovery of standalone physical volumes failed.', ' Cannot process standalone physical volumes', ' Read-only locking type set. Write locks are proh ibited.', ' Recovery of standalone physical volumes failed.', ' Cannot process standalone physical volumes'] (lvm:50 4) 2020-03-19 16:23:14,298+0200 INFO (jsonrpc/4) [vdsm.api] FINISH createStorageDomain error=Volume Group metadata isn't as expected: "reason=Expected one metadata pv in vg: 10ad9cc0-f477-4fbf-82b0-f35989212785, vg pvs: [Stub(name=u'/dev/ mapper/20024f40058540497', stale=True)]" from=::ffff:192.168.1.167,41338, flow_id=79c44727, task_id=2948cc7c-818e-4fd5 -a398-c47bf3d09aab (api:52) 2020-03-19 16:23:14,298+0200 ERROR (jsonrpc/4) [storage.TaskManager.Task] (Task='2948cc7c-818e-4fd5-a398-c47bf3d09aab' ) 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 createStorageDomain File "/usr/lib/python2.7/site-packages/vdsm/common/api.py", line 50, in method ret = func(*args, **kwargs) File "/usr/lib/python2.7/site-packages/vdsm/storage/hsm.py", line 2626, in createStorageDomain max_hosts=max_hosts) File "/usr/lib/python2.7/site-packages/vdsm/storage/blockSD.py", line 1146, in create device=lvm.getVgMetadataPv(vgName), File "/usr/lib/python2.7/site-packages/vdsm/storage/lvm.py", line 1771, in getVgMetadataPv (vgName, pvs)) UnexpectedVolumeGroupMetadata: Volume Group metadata isn't as expected: "reason=Expected one metadata pv in vg: 10ad9c c0-f477-4fbf-82b0-f35989212785, vg pvs: [Stub(name=u'/dev/mapper/20024f40058540497', stale=True)]" 2020-03-19 16:23:14,299+0200 INFO (jsonrpc/4) [storage.TaskManager.Task] (Task='2948cc7c-818e-4fd5-a398-c47bf3d09aab' ) aborting: Task is aborted: 'Volume Group metadata isn\'t as expected: "reason=Expected one metadata pv in vg: 10ad9cc0-f477-4fbf-82b0-f35989212785, vg pvs: [Stub(name=u\'/dev/mapper/20024f40058540497\', stale=True)]"' - code 616 (task:1181) 2020-03-19 16:23:14,299+0200 ERROR (jsonrpc/4) [storage.Dispatcher] FINISH createStorageDomain error=Volume Group metadata isn't as expected: "reason=Expected one metadata pv in vg: 10ad9cc0-f477-4fbf-82b0-f35989212785, vg pvs: [Stub(name=u'/dev/mapper/20024f40058540497', stale=True)]" (dispatcher:83) 2020-03-19 16:23:14,299+0200 INFO (jsonrpc/4) [jsonrpc.JsonRpcServer] RPC call StorageDomain.create failed (error 616) in 2.78 seconds (__init__:312)
(In reply to Nikolai Sednev from comment #10) > MAnual deployment from RHEL7.7 has failed over iSCSI: > > [ ERROR ] Error: Fault reason is "Operation Failed". Fault detail is > "[Unexpected exception]". HTTP response code is 400. > [ ERROR ] fatal: [localhost]: FAILED! => {"changed": false, "msg": "Fault > reason is \"Operation Failed\". Fault detail is \"[Unexpected exception]\". > HTTP response code is 400."} > > Components were used: > > rhvm-appliance.x86_64 2:4.3-20200317.0.el7 @rhv-4.3.9 > > rhevm-appliance.noarch 1:4.0.20170307.0-1.el7ev > rhvm-appliance.noarch 2:4.2-20190416.1.el7 > rhel-7-server-rhv-mgmt-agent-x86-rhv-4.3 > lvm2-2.02.185-2.el7_7.2.x86_64 Wrong lvm2 rpm version, you need lvm2-2.02.186-7.el7_8.1 for rhel.
If we don't care about versions lets simplify the spec and remove all version requirements. If we do care abut the requirement, it should be correct and we should fix this bug.
The issue using lvm version without epoch. This requirement should work: Requires: lvm2 >= 7:2.02.186-7.el7_8.1
we may respin to pick up rhvh updates, but we're not waiting on this to get in.
verified on vdsm-python-4.30.44-1.el7ev.noarch vdsm-api-4.30.44-1.el7ev.noarch [root@lynx25 ~]# rpm -qa | grep lvm2 lvm2-2.02.186-7.el7_8.1.x86_64
This bugzilla is included in oVirt 4.3.9 release, published on March 20th 2020. Since the problem described in this bug report should be resolved in oVirt 4.3.9 release, it has been closed with a resolution of CURRENT RELEASE. If the solution does not work for you, please open a new bug report.