Note: This bug is displayed in read-only format because
the product is no longer active in Red Hat Bugzilla.
RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.
Created attachment 643492[details]
vdsm and engine logs
Version:
vdsm-4.9.6-41.0.el6_3.x86_64 (si24)
How to reproduce:
Make ~120 iscsi luns visible to your host and create iscsi storage domain from one of them.
How reproducible:
Reproduced plenty of times during creation of few storage domains using a python-sdk script.
Description of the problem:
getDeviceList takes ~5 minutes when 121 luns are visible to the host, that makes createStorageDomain fail on timeout.
# time vdsClient -s 0 getDeviceList
...
...
real 5m22.029s
user 0m0.262s
sys 0m0.019s
It seems that the operation that takes the most of the time is pvcreate with --test flag:
Thread-6059::DEBUG::2012-11-12 12:21:24,949::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/lvm pvcreate --config " devices ....... --test ........
Thread-6059::DEBUG::2012-11-12 12:26:34,327::__init__::1164::Storage.Misc.excCmd::(_log) FAILED: <err> = ' Writing physical volume data to disk "/dev/mapper/36006016012823000e8774155112ce211"\n Writing physical volume data to disk "/dev/mapper/36006016012823000c8a2fd90112ce211"\n Writing physical volume data to disk "/dev/mapper/36006016012823000e4774155112ce211"\n Writing physical volume data to disk "/dev/mapper/360060160128230009643b168112ce211"\n Writing physical volume data to disk "/dev/mapper/36006016012823000a071237c112ce211"\n Writing physical volume data to disk "/dev/mapper/36006016012823000600e8975112ce211"\n Can\'t initialize physical volume "/dev/mapper/36006016012823000cae04ba6c52ce211" of volume group "d5597a53-7cba-429b-9d2d-7e260b251a0b" without -ff\n .......
From engine.log
===============
2012-11-12 12:21:12,394 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.ValidateStorageServerConnectionVDSCommand] (ajp-/127.0.0.1:8702-13) [767cca78] START, ValidateStorageServerConnectionVDSCommand(HostName = puma05, HostId = 1b279f74
-2bfe-11e2-9d66-2fb7f043202d, storagePoolId = 00000000-0000-0000-0000-000000000000, storageType = ISCSI, connectionList = [{ id: null, connection: 10.35.160.107, iqn: iqn.1992-04.com.emc:cx.ckm00121000438.b7, vfsType: null, mountOptions:
null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };]), log id: 513bc3a7
2012-11-12 12:21:12,426 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.ValidateStorageServerConnectionVDSCommand] (ajp-/127.0.0.1:8702-13) [767cca78] FINISH, ValidateStorageServerConnectionVDSCommand, return: {00000000-0000-0000-0000-0
00000000000=0}, log id: 513bc3a7
2012-11-12 12:21:12,442 INFO [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] (ajp-/127.0.0.1:8702-13) [767cca78] Running command: ConnectStorageToVdsCommand internal: false. Entities affected : ID: aaa00000-0000-0000-000
0-123456789aaa Type: System
2012-11-12 12:21:12,444 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (ajp-/127.0.0.1:8702-13) [767cca78] START, ConnectStorageServerVDSCommand(HostName = puma05, HostId = 1b279f74-2bfe-11e2-9d66-2fb7f0
43202d, storagePoolId = 00000000-0000-0000-0000-000000000000, storageType = ISCSI, connectionList = [{ id: null, connection: 10.35.160.107, iqn: iqn.1992-04.com.emc:cx.ckm00121000438.b7, vfsType: null, mountOptions: null, nfsVersion: nul
l, nfsRetrans: null, nfsTimeo: null };]), log id: 5d0ecc0e
2012-11-12 12:21:12,513 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (ajp-/127.0.0.1:8702-13) [767cca78] FINISH, ConnectStorageServerVDSCommand, return: {00000000-0000-0000-0000-000000000000=0}, log id
: 5d0ecc0e
2012-11-12 12:21:12,530 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetDeviceListVDSCommand] (ajp-/127.0.0.1:8702-13) START, GetDeviceListVDSCommand(HostName = puma05, HostId = 1b279f74-2bfe-11e2-9d66-2fb7f043202d, storageType=ISCSI
), log id: 194fef9
2012-11-12 12:24:12,532 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand] (ajp-/127.0.0.1:8702-13) XML RPC error in command GetDeviceListVDS ( HostName = puma05 ), the error was: java.util.concurrent.TimeoutException, Ti
meoutException:
2012-11-12 12:24:12,532 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetDeviceListVDSCommand] (ajp-/127.0.0.1:8702-13) FINISH, GetDeviceListVDSCommand, log id: 194fef9
2012-11-12 12:24:12,532 ERROR [org.ovirt.engine.core.bll.storage.GetDeviceListQuery] (ajp-/127.0.0.1:8702-13) Query GetDeviceListQuery failed. Exception message is VdcBLLException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSNetworkException: VDSNetworkException:
2012-11-12 12:24:12,532 ERROR [org.ovirt.engine.api.restapi.resource.AbstractBackendResource] (ajp-/127.0.0.1:8702-13) Operation Failed: Network error during communication with the Host.
Response to python-sdk
======================
status: 400
reason: Bad Request
detail: Network error during communication with the Host.
Comment 5Eduardo Warszawski
2012-11-15 08:10:14 UTC
Thread-4399::DEBUG::2012-11-12 12:24:28,487::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/lvm vgs
Thread-4399::DEBUG::2012-11-12 12:24:29,168::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-6203::DEBUG::2012-11-12 12:24:27,159::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/lvm pvcreate
Thread-6203::DEBUG::2012-11-12 12:28:26,683::__init__::1164::Storage.Misc.excCmd::(_log) FAILED: <err> = ' Writing physical volume data to disk
But pvcreate --test on 200 volumes takes only a few seconds:
real 0m2.692s
user 0m0.089s
sys 0m0.322s
The issue with the bug setup is there are a lot of failed LUNs.
Operations in such volumes take a long time and the addition of failures produces the long return time of the operation.
Since getDeviceList is the 1st op on the new set of LUNs, failing this operation directs the user to sanitize the setup before start real work on it.
Created attachment 643492 [details] vdsm and engine logs Version: vdsm-4.9.6-41.0.el6_3.x86_64 (si24) How to reproduce: Make ~120 iscsi luns visible to your host and create iscsi storage domain from one of them. How reproducible: Reproduced plenty of times during creation of few storage domains using a python-sdk script. Description of the problem: getDeviceList takes ~5 minutes when 121 luns are visible to the host, that makes createStorageDomain fail on timeout. # time vdsClient -s 0 getDeviceList ... ... real 5m22.029s user 0m0.262s sys 0m0.019s It seems that the operation that takes the most of the time is pvcreate with --test flag: Thread-6059::DEBUG::2012-11-12 12:21:24,949::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/lvm pvcreate --config " devices ....... --test ........ Thread-6059::DEBUG::2012-11-12 12:26:34,327::__init__::1164::Storage.Misc.excCmd::(_log) FAILED: <err> = ' Writing physical volume data to disk "/dev/mapper/36006016012823000e8774155112ce211"\n Writing physical volume data to disk "/dev/mapper/36006016012823000c8a2fd90112ce211"\n Writing physical volume data to disk "/dev/mapper/36006016012823000e4774155112ce211"\n Writing physical volume data to disk "/dev/mapper/360060160128230009643b168112ce211"\n Writing physical volume data to disk "/dev/mapper/36006016012823000a071237c112ce211"\n Writing physical volume data to disk "/dev/mapper/36006016012823000600e8975112ce211"\n Can\'t initialize physical volume "/dev/mapper/36006016012823000cae04ba6c52ce211" of volume group "d5597a53-7cba-429b-9d2d-7e260b251a0b" without -ff\n ....... From engine.log =============== 2012-11-12 12:21:12,394 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.ValidateStorageServerConnectionVDSCommand] (ajp-/127.0.0.1:8702-13) [767cca78] START, ValidateStorageServerConnectionVDSCommand(HostName = puma05, HostId = 1b279f74 -2bfe-11e2-9d66-2fb7f043202d, storagePoolId = 00000000-0000-0000-0000-000000000000, storageType = ISCSI, connectionList = [{ id: null, connection: 10.35.160.107, iqn: iqn.1992-04.com.emc:cx.ckm00121000438.b7, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };]), log id: 513bc3a7 2012-11-12 12:21:12,426 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.ValidateStorageServerConnectionVDSCommand] (ajp-/127.0.0.1:8702-13) [767cca78] FINISH, ValidateStorageServerConnectionVDSCommand, return: {00000000-0000-0000-0000-0 00000000000=0}, log id: 513bc3a7 2012-11-12 12:21:12,442 INFO [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] (ajp-/127.0.0.1:8702-13) [767cca78] Running command: ConnectStorageToVdsCommand internal: false. Entities affected : ID: aaa00000-0000-0000-000 0-123456789aaa Type: System 2012-11-12 12:21:12,444 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (ajp-/127.0.0.1:8702-13) [767cca78] START, ConnectStorageServerVDSCommand(HostName = puma05, HostId = 1b279f74-2bfe-11e2-9d66-2fb7f0 43202d, storagePoolId = 00000000-0000-0000-0000-000000000000, storageType = ISCSI, connectionList = [{ id: null, connection: 10.35.160.107, iqn: iqn.1992-04.com.emc:cx.ckm00121000438.b7, vfsType: null, mountOptions: null, nfsVersion: nul l, nfsRetrans: null, nfsTimeo: null };]), log id: 5d0ecc0e 2012-11-12 12:21:12,513 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (ajp-/127.0.0.1:8702-13) [767cca78] FINISH, ConnectStorageServerVDSCommand, return: {00000000-0000-0000-0000-000000000000=0}, log id : 5d0ecc0e 2012-11-12 12:21:12,530 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetDeviceListVDSCommand] (ajp-/127.0.0.1:8702-13) START, GetDeviceListVDSCommand(HostName = puma05, HostId = 1b279f74-2bfe-11e2-9d66-2fb7f043202d, storageType=ISCSI ), log id: 194fef9 2012-11-12 12:24:12,532 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand] (ajp-/127.0.0.1:8702-13) XML RPC error in command GetDeviceListVDS ( HostName = puma05 ), the error was: java.util.concurrent.TimeoutException, Ti meoutException: 2012-11-12 12:24:12,532 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetDeviceListVDSCommand] (ajp-/127.0.0.1:8702-13) FINISH, GetDeviceListVDSCommand, log id: 194fef9 2012-11-12 12:24:12,532 ERROR [org.ovirt.engine.core.bll.storage.GetDeviceListQuery] (ajp-/127.0.0.1:8702-13) Query GetDeviceListQuery failed. Exception message is VdcBLLException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSNetworkException: VDSNetworkException: 2012-11-12 12:24:12,532 ERROR [org.ovirt.engine.api.restapi.resource.AbstractBackendResource] (ajp-/127.0.0.1:8702-13) Operation Failed: Network error during communication with the Host. Response to python-sdk ====================== status: 400 reason: Bad Request detail: Network error during communication with the Host.