Bug 1814979 - [4.3.9-0day] Vdsm lvm2 requirement is not effective, installing vdsm succeeds when required package is missing
Summary: [4.3.9-0day] Vdsm lvm2 requirement is not effective, installing vdsm succeeds...
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: vdsm
Classification: oVirt
Component: Core
Version: 4.30.43
Hardware: Unspecified
OS: Unspecified
unspecified
medium
Target Milestone: ovirt-4.3.9-1
: ---
Assignee: Amit Bawer
QA Contact: Lukas Svaty
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2020-03-19 08:54 UTC by Avihai
Modified: 2020-04-06 06:53 UTC (History)
7 users (show)

Fixed In Version: vdsm-4.30.44-1.el7ev
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2020-04-06 06:53:17 UTC
oVirt Team: Storage
Embargoed:


Attachments (Terms of Use)
engine and vdsm logs (810.26 KB, application/gzip)
2020-03-19 08:54 UTC, Avihai
no flags Details


Links
System ID Private Priority Status Summary Last Updated
oVirt gerrit 107764 0 ovirt-4.3 MERGED spec: Include epoch in lvm2 requirement for rhel 2020-12-23 18:43:48 UTC
oVirt gerrit 107805 0 master MERGED spec: Include epoch in requirement 2020-12-23 18:43:48 UTC
oVirt gerrit 107822 0 ovirt-4.3 MERGED spec: Add epoch to the centos minimal lvm2 requirement 2020-12-23 18:43:16 UTC

Description Avihai 2020-03-19 08:54:36 UTC
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:

Comment 1 Nir Soffer 2020-03-19 10:17:07 UTC
Seens that lvm on this host does not support pvs command with locking_type=4.

Which lvm version is used?

Comment 2 Vojtech Juranek 2020-03-19 10:27:31 UTC
[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

Comment 3 Nir Soffer 2020-03-19 10:39:17 UTC
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.

Comment 5 Michal Skrivanek 2020-03-19 11:01:13 UTC
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

Comment 9 Avihai 2020-03-19 14:27:13 UTC
(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.

Comment 10 Nikolai Sednev 2020-03-19 14:30:37 UTC
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)

Comment 11 Nikolai Sednev 2020-03-19 14:42:19 UTC
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)

Comment 12 Amit Bawer 2020-03-19 14:49:33 UTC
(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.

Comment 16 Nir Soffer 2020-03-19 15:25:16 UTC
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.

Comment 18 Nir Soffer 2020-03-21 01:25:24 UTC
The issue using lvm version without epoch. This requirement should work:

    Requires: lvm2 >= 7:2.02.186-7.el7_8.1

Comment 19 Michal Skrivanek 2020-03-23 12:35:41 UTC
we may respin to pick up rhvh updates, but we're not waiting on this to get in.

Comment 20 Avihai 2020-03-30 08:52:40 UTC
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

Comment 21 Sandro Bonazzola 2020-04-06 06:53:17 UTC
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.


Note You need to log in before you can comment on or make changes to this bug.