Note: This bug is displayed in read-only format because the product is no longer active in Red Hat Bugzilla.

Bug 1768735

Summary:

[rhv-4.4.0-4] - Adding ISCSI storage domains Failes with error VolumeGroupCreateError and code 502 - TypeError: devicemapper_removeMapping() missing 1 required positional argument: 'deviceName'

Product:

[oVirt] ovirt-engine

Reporter:

Avihai <aefrat>

Component:

BLL.Storage

Assignee:

Vojtech Juranek <vjuranek>

Status:

CLOSED CURRENTRELEASE

QA Contact:

Evelina Shames <eshames>

Severity:

urgent

Docs Contact:

Priority:

unspecified

Version:

4.4.0

CC:

bugs, vjuranek

Target Milestone:

ovirt-4.4.0

Flags:

pm-rhel: ovirt-4.4+

Target Release:

---

Hardware:

Unspecified

OS:

Unspecified

Whiteboard:

Fixed In Version:

Doc Type:

No Doc Update

Doc Text:

Story Points:

---

Clone Of:

Environment:

Last Closed:

2020-05-20 20:02:36 UTC

Type:

Bug

Regression:

---

Mount Type:

---

Documentation:

---

CRM:

Verified Versions:

Category:

---

oVirt Team:

Storage

RHEL 7.3 requirements from Atomic Host:

Cloudforms Team:

---

Target Upstream Version:

Embargoed:

Attachments:

Description	Flags
engine and vdsm logs	none

Description Avihai 2019-11-05 07:26:14 UTC

Created attachment 1632855 [details]
engine and vdsm logs

Description of problem:
Via webadmin/RESTAPI add a new ISCSI storage doamin and see it fail with the following errors:

Engine:
2019-11-05 09:22:03,233+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVGVDSCommand] (default task-114) [635a0212] START, CreateVGVDSCommand(HostName = host_mixed_2, CreateVGVDSCommandParameters:{hos
tId='2cddb970-871b-42d9-bdd2-026621118c48', storageDomainId='5ef4a19a-be98-44d3-b1dc-d929b10f4a8d', deviceList='[360002ac0000000000000001a00021f6b]', force='true'}), log id: 1b4530cd
2019-11-05 09:22:03,274+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVGVDSCommand] (default task-114) [635a0212] Failed in 'CreateVGVDS' method
2019-11-05 09:22:03,283+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-114) [635a0212] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), VDSM host_mixed_2 command Crea
teVGVDS failed: Cannot create Volume Group: "vgname=5ef4a19a-be98-44d3-b1dc-d929b10f4a8d, devname=['360002ac0000000000000001a00021f6b']"
2019-11-05 09:22:03,283+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVGVDSCommand] (default task-114) [635a0212] Command 'org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVGVDSCommand' return value 
'OneUuidReturn:{status='Status [code=502, message=Cannot create Volume Group: "vgname=5ef4a19a-be98-44d3-b1dc-d929b10f4a8d, devname=['360002ac0000000000000001a00021f6b']"]'}'
2019-11-05 09:22:03,283+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVGVDSCommand] (default task-114) [635a0212] HostName = host_mixed_2
2019-11-05 09:22:03,284+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVGVDSCommand] (default task-114) [635a0212] Command 'CreateVGVDSCommand(HostName = host_mixed_2, CreateVGVDSCommandParameters:{h
ostId='2cddb970-871b-42d9-bdd2-026621118c48', storageDomainId='5ef4a19a-be98-44d3-b1dc-d929b10f4a8d', deviceList='[360002ac0000000000000001a00021f6b]', force='true'})' execution failed: VDSGenericException: VDSErrorException: Failed to CreateVGVDS, error = Cannot create Volume Group: "vgname=5ef4a19a-be98-44d3-b1dc-d929b10f4a8d, devname=['360002ac0000000000000001a00021f6b']", code = 502
2019-11-05 09:22:03,284+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVGVDSCommand] (default task-114) [635a0212] FINISH, CreateVGVDSCommand, return: , log id: 1b4530cd
2019-11-05 09:22:03,284+02 ERROR [org.ovirt.engine.core.bll.storage.domain.AddSANStorageDomainCommand] (default task-114) [635a0212] Command 'org.ovirt.engine.core.bll.storage.domain.AddSANStorageDomainCommand' failed: EngineException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed to CreateVGVDS, error = Cannot create Volume Group: "vgname=5ef4a19a-be98-44d3-b1dc-d929b10f4a8d, devname=['360002ac0000000000000001a00021f6b']", code = 502 (Failed with error VolumeGroupCreateError and code 502)
2019-11-05 09:22:03,288+02 INFO  [org.ovirt.engine.core.bll.CommandCompensator] (default task-114) [635a0212] Command [id=5f47acfb-beec-4f43-a3eb-23612354891d]: Compensating NEW_ENTITY_ID of org.ovirt.engine.core.common.businessentities.profiles.DiskProfile; snapshot: dfb11d4b-05bb-4324-baf2-325e2da64419.
2019-11-05 09:22:03,294+02 INFO  [org.ovirt.engine.core.bll.CommandCompensator] (default task-114) [635a0212] Command [id=5f47acfb-beec-4f43-a3eb-23612354891d]: Compensating NEW_ENTITY_ID of org.ovirt.engine.core.common.businessentities.StorageDomainDynamic; snapshot: 5ef4a19a-be98-44d3-b1dc-d929b10f4a8d.
2019-11-05 09:22:03,296+02 INFO  [org.ovirt.engine.core.bll.CommandCompensator] (default task-114) [635a0212] Command [id=5f47acfb-beec-4f43-a3eb-23612354891d]: Compensating NEW_ENTITY_ID of org.ovirt.engine.core.common.businessentities.StorageDomainStatic; snapshot: 5ef4a19a-be98-44d3-b1dc-d929b10f4a8d.
2019-11-05 09:22:03,321+02 ERROR [org.ovirt.engine.core.bll.storage.domain.AddSANStorageDomainCommand] (default task-114) [635a0212] Transaction rolled-back for command 'org.ovirt.engine.core.bll.storage.domain.AddSANStorageDomainCommand'.
2019-11-05 09:22:03,331+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-114) [635a0212] EVENT_ID: USER_ADD_STORAGE_DOMAIN_FAILED(957), Failed to add Storage Domain sd_test1. (User: admin@internal-authz)
2019-11-05 09:22:03,338+02 ERROR [org.ovirt.engine.api.restapi.resource.AbstractBackendResource] (default task-114) [] Operation Failed: [Cannot create Volume Group]
2019-11-05 09:22:03,346+02 INFO  [org.ovirt.engine.core.bll.aaa.LogoutSessionCommand] (default task-114) [534abd2c] Running command: LogoutSessionCommand internal: false.


In VDSM log I see:
2019-11-05 09:22:03,237+0200 INFO  (jsonrpc/1) [vdsm.api] START createVG(vgname='5ef4a19a-be98-44d3-b1dc-d929b10f4a8d', devlist=['360002ac0000000000000001a00021f6b'], force=True, options=None) from=::ffff:10.35
.161.118,37586, flow_id=635a0212, task_id=5f40a8ad-200f-4581-9dbc-b203563f9778 (api:48)
2019-11-05 09:22:03,263+0200 INFO  (jsonrpc/1) [vdsm.api] FINISH createVG error=devicemapper_removeMapping() missing 1 required positional argument: 'deviceName' from=::ffff:10.35.161.118,37586, flow_id=635a021
2, task_id=5f40a8ad-200f-4581-9dbc-b203563f9778 (api:52)
2019-11-05 09:22:03,265+0200 ERROR (jsonrpc/1) [storage.TaskManager.Task] (Task='5f40a8ad-200f-4581-9dbc-b203563f9778') Unexpected error (task:889)
Traceback (most recent call last):
  File "/usr/lib/python3.6/site-packages/vdsm/storage/task.py", line 896, in _run
    return fn(*args, **kargs)
  File "<decorator-gen-95>", line 2, in createVG
  File "/usr/lib/python3.6/site-packages/vdsm/common/api.py", line 50, in method
    ret = func(*args, **kwargs)
  File "/usr/lib/python3.6/site-packages/vdsm/storage/hsm.py", line 2147, in createVG
    force=force)
  File "/usr/lib/python3.6/site-packages/vdsm/storage/lvm.py", line 1143, in createVG
    _initpvs(pvs, metadataSize, force)
  File "/usr/lib/python3.6/site-packages/vdsm/storage/lvm.py", line 881, in _initpvs
    _initpvs_removeHolders()
  File "/usr/lib/python3.6/site-packages/vdsm/storage/lvm.py", line 871, in _initpvs_removeHolders
    os.path.basename(device))
  File "/usr/lib/python3.6/site-packages/vdsm/storage/devicemapper.py", line 163, in removeMappingsHoldingDevice
    removeMapping(getDevName(holder))
  File "/usr/lib/python3.6/site-packages/vdsm/storage/devicemapper.py", line 135, in removeMapping
    return supervdsm.getProxy().devicemapper_removeMapping()
  File "/usr/lib/python3.6/site-packages/vdsm/common/supervdsm.py", line 56, in __call__
    return callMethod()
  File "/usr/lib/python3.6/site-packages/vdsm/common/supervdsm.py", line 54, in <lambda>
    **kwargs)
  File "<string>", line 2, in devicemapper_removeMapping
  File "/usr/lib64/python3.6/multiprocessing/managers.py", line 772, in _callmethod
    raise convert_to_error(kind, result)
TypeError: devicemapper_removeMapping() missing 1 required positional argument: 'deviceName'
2019-11-05 09:22:03,265+0200 ERROR (jsonrpc/1) [storage.Dispatcher] FINISH createVG error=devicemapper_removeMapping() missing 1 required positional argument: 'deviceName' (dispatcher:87)
Traceback (most recent call last):
  File "/usr/lib/python3.6/site-packages/vdsm/storage/dispatcher.py", line 74, in wrapper
    result = ctask.prepare(func, *args, **kwargs)
  File "/usr/lib/python3.6/site-packages/vdsm/storage/task.py", line 110, in wrapper
    return m(self, *a, **kw)
  File "/usr/lib/python3.6/site-packages/vdsm/storage/task.py", line 1208, in prepare
    raise self.error
  File "/usr/lib/python3.6/site-packages/vdsm/storage/task.py", line 896, in _run
    return fn(*args, **kargs)
  File "<decorator-gen-95>", line 2, in createVG
  File "/usr/lib/python3.6/site-packages/vdsm/common/api.py", line 50, in method
    ret = func(*args, **kwargs)
  File "/usr/lib/python3.6/site-packages/vdsm/storage/hsm.py", line 2147, in createVG
    force=force)
  File "/usr/lib/python3.6/site-packages/vdsm/storage/lvm.py", line 1143, in createVG
    _initpvs(pvs, metadataSize, force)
  File "/usr/lib/python3.6/site-packages/vdsm/storage/lvm.py", line 881, in _initpvs
    _initpvs_removeHolders()
  File "/usr/lib/python3.6/site-packages/vdsm/storage/lvm.py", line 871, in _initpvs_removeHolders
    os.path.basename(device))
  File "/usr/lib/python3.6/site-packages/vdsm/storage/devicemapper.py", line 163, in removeMappingsHoldingDevice
    removeMapping(getDevName(holder))
  File "/usr/lib/python3.6/site-packages/vdsm/storage/devicemapper.py", line 135, in removeMapping
    return supervdsm.getProxy().devicemapper_removeMapping()
  File "/usr/lib/python3.6/site-packages/vdsm/common/supervdsm.py", line 56, in __call__
    return callMethod()
  File "/usr/lib/python3.6/site-packages/vdsm/common/supervdsm.py", line 54, in <lambda>
    **kwargs)
  File "<string>", line 2, in devicemapper_removeMapping
  File "/usr/lib64/python3.6/multiprocessing/managers.py", line 772, in _callmethod
    raise convert_to_error(kind, result)
TypeError: devicemapper_removeMapping() missing 1 required positional argument: 'deviceName'

supervdsm log:
MainProcess|jsonrpc/1::ERROR::2019-11-05 09:22:03,262::supervdsm_server::96::SuperVdsm.ServerCallback::(wrapper) Error in devicemapper_removeMapping
Traceback (most recent call last):
  File "/usr/lib/python3.6/site-packages/vdsm/supervdsm_server.py", line 94, in wrapper
    res = func(*args, **kwargs)
TypeError: devicemapper_removeMapping() missing 1 required positional argument: 'deviceName'



Version-Release number of selected component (if applicable):
rhv-4.4.0-4 (http://bob.eng.lab.tlv.redhat.com/builds/4.4/rhv-4.4.0-4/)

ovirt-engine-4.4.0-0.4.master.el7.noarch
vdsm-4.40.0-127.gitc628cce.el8ev.x86_64
python3-libvirt-5.0.0-5.module+el8.0.1+3755+6782b0ed.x86_64
qemu-kvm-3.1.0-30.module+el8.0.1+3755+6782b0ed.x86_64

How reproducible:
100%

Steps to Reproduce:
1.Create ISCSI storage domain via webadmin


Actual results:
Adding storage domain fails 

Expected results:


Additional info:
REST request:

Method: POST
URL:  https://storage-ge-04.scl.lab.tlv.redhat.com/ovirt-engine/api/storagedomains

Headers:
Content-Type - application/xml

Body:
<storage_domain>
    <name>sd_test1</name>
    <storage>
        <logical_units>
            <logical_unit id="360002ac0000000000000001a00021f6b">
                <address>10.35.146.1</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_1</name>
    </host>
</storage_domain>

Comment 1 Vojtech Juranek 2019-11-05 09:56:48 UTC

requested LUN is in use and DM probably failed to remove mapping to this LUN:

360002ac0000000000000001a00021f6b                                                   253:4    0   50G  0 mpath 
├─a52c5f80--536c--4d3f--a581--682038fd80ed-metadata                                 253:14   0  128M  0 lvm   
├─a52c5f80--536c--4d3f--a581--682038fd80ed-outbox                                   253:19   0  128M  0 lvm   
├─a52c5f80--536c--4d3f--a581--682038fd80ed-xleases                                  253:23   0    1G  0 lvm   
├─a52c5f80--536c--4d3f--a581--682038fd80ed-leases                                   253:27   0    2G  0 lvm   
├─a52c5f80--536c--4d3f--a581--682038fd80ed-ids                                      253:31   0  128M  0 lvm   
├─a52c5f80--536c--4d3f--a581--682038fd80ed-inbox                                    253:35   0  128M  0 lvm   
├─a52c5f80--536c--4d3f--a581--682038fd80ed-master                                   253:39   0    1G  0 lvm   
├─a52c5f80--536c--4d3f--a581--682038fd80ed-4dfea443--be0e--4760--8671--d3d27a319a16 253:43   0  128M  0 lvm   
└─a52c5f80--536c--4d3f--a581--682038fd80ed-a93ae40a--78fe--418f--bab1--601079bf1b5c 253:47   0  128M  0 lvm

will need to reproduce it to debug further.

Comment 2 Vojtech Juranek 2019-11-06 11:35:59 UTC

I can confirm it's vdsm bug. After fix seems to be working:

curl --insecure --request POST --header "Accept: application/xml" --header "Content-Type: application/xml" --user "***" https://storage-ge-04.scl.lab.tlv.redhat.com/ovirt-engine/api/storagedomains --data '<storage_domain>
>     <name>sd_test1</name>
>     <storage>
>         <logical_units>
>             <logical_unit id="360002ac0000000000000001a00021f6b">
>                 <address>10.35.146.1</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_1</name>
>     </host>
> </storage_domain>'
<?xml version="1.0" encoding="UTF-8" standalone="yes"?>
<storage_domain href="/ovirt-engine/api/storagedomains/e9e2fa04-c08f-4cc9-9074-0b52b834554d" id="e9e2fa04-c08f-4cc9-9074-0b52b834554d">
    <actions>
        <link href="/ovirt-engine/api/storagedomains/e9e2fa04-c08f-4cc9-9074-0b52b834554d/isattached" rel="isattached"/>
        <link href="/ovirt-engine/api/storagedomains/e9e2fa04-c08f-4cc9-9074-0b52b834554d/refreshluns" rel="refreshluns"/>
        <link href="/ovirt-engine/api/storagedomains/e9e2fa04-c08f-4cc9-9074-0b52b834554d/reduceluns" rel="reduceluns"/>
        <link href="/ovirt-engine/api/storagedomains/e9e2fa04-c08f-4cc9-9074-0b52b834554d/updateovfstore" rel="updateovfstore"/>
    </actions>
    <name>sd_test1</name>
    <description></description>
    <comment></comment>
    <link href="/ovirt-engine/api/storagedomains/e9e2fa04-c08f-4cc9-9074-0b52b834554d/diskprofiles" rel="diskprofiles"/>
    <link href="/ovirt-engine/api/storagedomains/e9e2fa04-c08f-4cc9-9074-0b52b834554d/disks" rel="disks"/>
    <link href="/ovirt-engine/api/storagedomains/e9e2fa04-c08f-4cc9-9074-0b52b834554d/templates" rel="templates"/>
    <link href="/ovirt-engine/api/storagedomains/e9e2fa04-c08f-4cc9-9074-0b52b834554d/vms" rel="vms"/>
    <link href="/ovirt-engine/api/storagedomains/e9e2fa04-c08f-4cc9-9074-0b52b834554d/disksnapshots" rel="disksnapshots"/>
    <link href="/ovirt-engine/api/storagedomains/e9e2fa04-c08f-4cc9-9074-0b52b834554d/storageconnections" rel="storageconnections"/>
    <link href="/ovirt-engine/api/storagedomains/e9e2fa04-c08f-4cc9-9074-0b52b834554d/permissions" rel="permissions"/>
    <available>48318382080</available>
    <backup>false</backup>
    <block_size>512</block_size>
    <committed>0</committed>
    <critical_space_action_blocker>5</critical_space_action_blocker>
    <discard_after_delete>false</discard_after_delete>
    <external_status>ok</external_status>
    <master>false</master>
    <status>unknown</status>
    <storage>
        <type>iscsi</type>
        <volume_group id="XFVexi-8xqt-lWqs-uOn5-ippb-Nmr4-if7uAv">
            <logical_units>
                <logical_unit id="360002ac0000000000000001a00021f6b">
                    <address>10.35.146.1</address>
                    <discard_max_size>33554432</discard_max_size>
                    <discard_zeroes_data>false</discard_zeroes_data>
                    <lun_mapping>4</lun_mapping>
                    <paths>0</paths>
                    <port>3260</port>
                    <portal>10.35.146.1:3260,21</portal>
                    <product_id>VV</product_id>
                    <serial>S3PARdataVV_CZ3836C3RB</serial>
                    <size>53687091200</size>
                    <storage_domain_id>e9e2fa04-c08f-4cc9-9074-0b52b834554d</storage_domain_id>
                    <target>iqn.2000-05.com.3pardata:20210002ac021f6b</target>
                    <vendor_id>3PARdata</vendor_id>
                    <volume_group_id>XFVexi-8xqt-lWqs-uOn5-ippb-Nmr4-if7uAv</volume_group_id>
                </logical_unit>
            </logical_units>
        </volume_group>
    </storage>
    <storage_format>v5</storage_format>
    <supports_discard>true</supports_discard>
    <supports_discard_zeroes_data>false</supports_discard_zeroes_data>
    <type>data</type>
    <used>4294967296</used>
    <warning_low_space_indicator>10</warning_low_space_indicator>
    <wipe_after_delete>false</wipe_after_delete>
</storage_domain>

Comment 3 Evelina Shames 2019-12-23 10:15:38 UTC

Verified on:
4.4.0-0.13.master.el7

Comment 4 Sandro Bonazzola 2020-05-20 20:02:36 UTC

This bugzilla is included in oVirt 4.4.0 release, published on May 20th 2020.

Since the problem described in this bug report should be
resolved in oVirt 4.4.0 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.