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.
It doesn't look like a bug. The operation takes time to restore connectivity to storage and scan the domains list if we had stuck operation before. That's the nature of timeout.
We fail the old getDomainsList and then you get the new answer. The last operation failure finished only after timeout that takes here more than a minute.
I don't think its related to how long you have waited before running getStorageDomainsList, the time changes if you need to wait for old operations to end and the storage response.
Comment 5Eduardo Warszawski
2012-11-03 22:02:06 UTC
The ~two minutes:
Thread-5240::DEBUG::2012-10-28 15:45:19,151::misc::1053::SamplingMethod::(__call__) Returning last result
Thread-5240::DEBUG::2012-10-28 15:45:21,177::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
# > 1min whithout logs?
Dummy-5046::DEBUG::2012-10-28 15:45:19,972::__init__::1164::Storage.Misc.excCmd::(_log) 'dd if=/rhev/data-center/7455040b-1fe6-4434-95a4-57cab522d76e/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
Dummy-5046::DEBUG::2012-10-28 15:45:20,047::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0318764 s, 32.1 MB/s\n'; <rc> = 0
Thread-5240::DEBUG::2012-10-28 15:45:21,177::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
Thread-5240::DEBUG::2012-10-28 15:45:21,253::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
*** This bug has been marked as a duplicate of bug 865034 ***
Comment 6Eduardo Warszawski
2012-11-04 10:08:46 UTC
This is the corect one:
# ~1 min gap
Thread-5240::DEBUG::2012-10-28 15:45:21,588::lvm::379::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
Thread-5240::INFO::2012-10-28 15:46:21,596::logUtils::39::dispatcher::(wrapper) Run and protect: getStorageDomainsList, Return response: {'domlist': ['8f81428c-612d-4f01-a834-aa7fff4e9485']}
Created attachment 634534 [details] ## Logs vdsm Description of problem: getStorageDomainsList command takes more then 60 sec, if DC have a broken connection to NFS storage Version-Release number of selected component (if applicable): RHEVM 3.1 - SI22 RHEVM: rhevm-3.1.0-22.el6ev.noarch VDSM: vdsm-4.9.6-39.0.el6_3.x86_64 LIBVIRT: libvirt-0.9.10-21.el6_3.5.x86_64 QEMU & KVM: qemu-kvm-rhev-0.12.1.2-2.295.el6_3.2.x86_64 SANLOCK: sanlock-2.3-4.el6_3.x86_64 How reproducible: 100% Steps to Reproduce: 1. Create iSCSI DC with 2 hosts, with one iSCSI SD, Export NFS (or ISO NFS) domain 2. Block (via iptables) connection to Export NFS – for simulation broken connection to Export NFS (or ISO NFS) domain 3. Run “vdsClient -s 0 getStorageDomainsList “ command Actual results: [root@cougar08 ~]# time vdsClient -s 0 getStorageDomainsList 8f81428c-612d-4f01-a834-aa7fff4e9485 real 1m2.653s user 0m0.100s sys 0m0.022s If we wait less than 5 min, and restore connection to Export NFS, and run again “getStorageDomainsList”, we will get a reasonable response time, see below: [root@cougar08 ~]# time vdsClient -s 0 getStorageDomainsList 8f81428c-612d-4f01-a834-aa7fff4e9485 27fedd2e-d04e-4a16-a9f7-714f2931e6d3 real 0m2.646s user 0m0.093s sys 0m0.029s but if we wait a couple of hours, and restore connection to Export NFS, the respond be again more than 60 sec. Expected results: Command “vdsClient -s 0 getStorageDomainsList ” should run less than 60 seconds, much less reasonable time Additional info: With broken connection: # egrep Thread-5240 less /var/log/vdsm/vdsm.log | less -S /var/log/vdsm/vdsm.log:Thread-5240::DEBUG::2012-10-28 15:45:19,116::BindingXMLRPC::171::vds::(wrapper) [10.35.160.137] /var/log/vdsm/vdsm.log:Thread-5240::DEBUG::2012-10-28 15:45:19,116::task::588::TaskManager.Task::(_updateState) Task=`4818df65-4c8a-4d4e-ab7c-b4d044dd750f`::moving from state init -> sta /var/log/vdsm/vdsm.log:Thread-5240::INFO::2012-10-28 15:45:19,117::logUtils::37::dispatcher::(wrapper) Run and protect: getStorageDomainsList(spUUID='00000000-0000-0000-0000-000000000000 /var/log/vdsm/vdsm.log:Thread-5240::DEBUG::2012-10-28 15:45:19,117::misc::1043::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage) /var/log/vdsm/vdsm.log:Thread-5240::DEBUG::2012-10-28 15:45:19,118::misc::1045::SamplingMethod::(__call__) Got in to sampling method /var/log/vdsm/vdsm.log:Thread-5240::DEBUG::2012-10-28 15:45:19,118::misc::1043::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan) /var/log/vdsm/vdsm.log:Thread-5240::DEBUG::2012-10-28 15:45:19,118::misc::1045::SamplingMethod::(__call__) Got in to sampling method /var/log/vdsm/vdsm.log:Thread-5240::DEBUG::2012-10-28 15:45:19,119::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None) /var/log/vdsm/vdsm.log:Thread-5240::DEBUG::2012-10-28 15:45:19,151::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0 /var/log/vdsm/vdsm.log:Thread-5240::DEBUG::2012-10-28 15:45:19,151::misc::1053::SamplingMethod::(__call__) Returning last result /var/log/vdsm/vdsm.log:MainProcess|Thread-5240::DEBUG::2012-10-28 15:45:19,153::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/dd of=/sys/class/scsi_host/host0/scan' (cwd None) /var/log/vdsm/vdsm.log:MainProcess|Thread-5240::DEBUG::2012-10-28 15:45:19,156::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/dd of=/sys/class/scsi_host/host1/scan' (cwd None) /var/log/vdsm/vdsm.log:MainProcess|Thread-5240::DEBUG::2012-10-28 15:45:19,159::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/dd of=/sys/class/scsi_host/host2/scan' (cwd None) /var/log/vdsm/vdsm.log:MainProcess|Thread-5240::DEBUG::2012-10-28 15:45:19,162::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/dd of=/sys/class/scsi_host/host3/scan' (cwd None) /var/log/vdsm/vdsm.log:MainProcess|Thread-5240::DEBUG::2012-10-28 15:45:19,165::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/dd of=/sys/class/scsi_host/host4/scan' (cwd None) /var/log/vdsm/vdsm.log:MainProcess|Thread-5240::DEBUG::2012-10-28 15:45:19,168::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/dd of=/sys/class/scsi_host/host5/scan' (cwd None) /var/log/vdsm/vdsm.log:MainProcess|Thread-5240::DEBUG::2012-10-28 15:45:19,170::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/dd of=/sys/class/scsi_host/host6/scan' (cwd None) /var/log/vdsm/vdsm.log:MainProcess|Thread-5240::DEBUG::2012-10-28 15:45:19,173::iscsi::376::Storage.ISCSI::(forceIScsiScan) Performing SCSI scan, this will take up to 30 seconds /var/log/vdsm/vdsm.log:Thread-5240::DEBUG::2012-10-28 15:45:21,177::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/multipath' (cwd None) /var/log/vdsm/vdsm.log:Thread-5240::DEBUG::2012-10-28 15:45:21,253::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0 /var/log/vdsm/vdsm.log:Thread-5240::DEBUG::2012-10-28 15:45:21,258::lvm::460::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex /var/log/vdsm/vdsm.log:Thread-5240::DEBUG::2012-10-28 15:45:21,258::lvm::462::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex /var/log/vdsm/vdsm.log:Thread-5240::DEBUG::2012-10-28 15:45:21,259::lvm::472::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex /var/log/vdsm/vdsm.log:Thread-5240::DEBUG::2012-10-28 15:45:21,259::lvm::474::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex /var/log/vdsm/vdsm.log:Thread-5240::DEBUG::2012-10-28 15:45:21,260::lvm::493::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex /var/log/vdsm/vdsm.log:Thread-5240::DEBUG::2012-10-28 15:45:21,260::lvm::495::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex /var/log/vdsm/vdsm.log:Thread-5240::DEBUG::2012-10-28 15:45:21,260::misc::1053::SamplingMethod::(__call__) Returning last result /var/log/vdsm/vdsm.log:Thread-5240::DEBUG::2012-10-28 15:45:21,261::lvm::352::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex /var/log/vdsm/vdsm.log:Thread-5240::DEBUG::2012-10-28 15:45:21,263::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/lvm vgs --config " devices { preferred_names = [\\ /var/log/vdsm/vdsm.log:Thread-5240::DEBUG::2012-10-28 15:45:21,586::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0 /var/log/vdsm/vdsm.log:Thread-5240::DEBUG::2012-10-28 15:45:21,588::lvm::379::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex /var/log/vdsm/vdsm.log:Thread-5240::INFO::2012-10-28 15:46:21,596::logUtils::39::dispatcher::(wrapper) Run and protect: getStorageDomainsList, Return response: {'domlist': ['8f81428c-612 /var/log/vdsm/vdsm.log:Thread-5240::DEBUG::2012-10-28 15:46:21,597::task::1172::TaskManager.Task::(prepare) Task=`4818df65-4c8a-4d4e-ab7c-b4d044dd750f`::finished: {'domlist': ['8f81428c- /var/log/vdsm/vdsm.log:Thread-5240::DEBUG::2012-10-28 15:46:21,597::task::588::TaskManager.Task::(_updateState) Task=`4818df65-4c8a-4d4e-ab7c-b4d044dd750f`::moving from state preparing - /var/log/vdsm/vdsm.log:Thread-5240::DEBUG::2012-10-28 15:46:21,597::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} /var/log/vdsm/vdsm.log:Thread-5240::DEBUG::2012-10-28 15:46:21,598::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} /var/log/vdsm/vdsm.log:Thread-5240::DEBUG::2012-10-28 15:46:21,598::task::978::TaskManager.Task::(_decref) Task=`4818df65-4c8a-4d4e-ab7c-b4d044dd750f`::ref 0 aborting False Without broken connection # egrep Thread-5466 less /var/log/vdsm/vdsm.log | less -S /var/log/vdsm/vdsm.log:Thread-5466::DEBUG::2012-10-28 15:49:54,538::BindingXMLRPC::171::vds::(wrapper) [10.35.160.137] /var/log/vdsm/vdsm.log:Thread-5466::DEBUG::2012-10-28 15:49:54,538::task::588::TaskManager.Task::(_updateState) Task=`2bea6ecb-fa41-4850-a309-83e0bf589ed5`::moving from state init -> sta /var/log/vdsm/vdsm.log:Thread-5466::INFO::2012-10-28 15:49:54,539::logUtils::37::dispatcher::(wrapper) Run and protect: getStorageDomainsList(spUUID='00000000-0000-0000-0000-000000000000 /var/log/vdsm/vdsm.log:Thread-5466::DEBUG::2012-10-28 15:49:54,539::misc::1043::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage) /var/log/vdsm/vdsm.log:Thread-5466::DEBUG::2012-10-28 15:49:54,540::misc::1045::SamplingMethod::(__call__) Got in to sampling method /var/log/vdsm/vdsm.log:Thread-5466::DEBUG::2012-10-28 15:49:54,540::misc::1043::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan) /var/log/vdsm/vdsm.log:Thread-5466::DEBUG::2012-10-28 15:49:54,540::misc::1045::SamplingMethod::(__call__) Got in to sampling method /var/log/vdsm/vdsm.log:Thread-5466::DEBUG::2012-10-28 15:49:54,541::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None) /var/log/vdsm/vdsm.log:Thread-5466::DEBUG::2012-10-28 15:49:54,572::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0 /var/log/vdsm/vdsm.log:Thread-5466::DEBUG::2012-10-28 15:49:54,572::misc::1053::SamplingMethod::(__call__) Returning last result /var/log/vdsm/vdsm.log:MainProcess|Thread-5466::DEBUG::2012-10-28 15:49:54,574::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/dd of=/sys/class/scsi_host/host0/scan' (cwd None) /var/log/vdsm/vdsm.log:MainProcess|Thread-5466::DEBUG::2012-10-28 15:49:54,577::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/dd of=/sys/class/scsi_host/host1/scan' (cwd None) /var/log/vdsm/vdsm.log:MainProcess|Thread-5466::DEBUG::2012-10-28 15:49:54,580::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/dd of=/sys/class/scsi_host/host2/scan' (cwd None) /var/log/vdsm/vdsm.log:MainProcess|Thread-5466::DEBUG::2012-10-28 15:49:54,583::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/dd of=/sys/class/scsi_host/host3/scan' (cwd None) /var/log/vdsm/vdsm.log:MainProcess|Thread-5466::DEBUG::2012-10-28 15:49:54,586::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/dd of=/sys/class/scsi_host/host4/scan' (cwd None) /var/log/vdsm/vdsm.log:MainProcess|Thread-5466::DEBUG::2012-10-28 15:49:54,588::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/dd of=/sys/class/scsi_host/host5/scan' (cwd None) /var/log/vdsm/vdsm.log:MainProcess|Thread-5466::DEBUG::2012-10-28 15:49:54,591::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/dd of=/sys/class/scsi_host/host6/scan' (cwd None) /var/log/vdsm/vdsm.log:MainProcess|Thread-5466::DEBUG::2012-10-28 15:49:54,594::iscsi::376::Storage.ISCSI::(forceIScsiScan) Performing SCSI scan, this will take up to 30 seconds /var/log/vdsm/vdsm.log:Thread-5466::DEBUG::2012-10-28 15:49:56,598::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/multipath' (cwd None) /var/log/vdsm/vdsm.log:Thread-5466::DEBUG::2012-10-28 15:49:56,680::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0 /var/log/vdsm/vdsm.log:Thread-5466::DEBUG::2012-10-28 15:49:56,681::lvm::460::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex /var/log/vdsm/vdsm.log:Thread-5466::DEBUG::2012-10-28 15:49:56,681::lvm::462::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex /var/log/vdsm/vdsm.log:Thread-5466::DEBUG::2012-10-28 15:49:56,681::lvm::472::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex /var/log/vdsm/vdsm.log:Thread-5466::DEBUG::2012-10-28 15:49:56,682::lvm::474::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex /var/log/vdsm/vdsm.log:Thread-5466::DEBUG::2012-10-28 15:49:56,682::lvm::493::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex /var/log/vdsm/vdsm.log:Thread-5466::DEBUG::2012-10-28 15:49:56,683::lvm::495::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex /var/log/vdsm/vdsm.log:Thread-5466::DEBUG::2012-10-28 15:49:56,683::misc::1053::SamplingMethod::(__call__) Returning last result /var/log/vdsm/vdsm.log:Thread-5466::DEBUG::2012-10-28 15:49:56,683::lvm::352::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex /var/log/vdsm/vdsm.log:Thread-5466::DEBUG::2012-10-28 15:49:56,686::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/lvm vgs --config " devices { preferred_names = [\\ /var/log/vdsm/vdsm.log:Thread-5466::DEBUG::2012-10-28 15:49:56,996::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0 /var/log/vdsm/vdsm.log:Thread-5466::DEBUG::2012-10-28 15:49:56,998::lvm::379::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex /var/log/vdsm/vdsm.log:Thread-5466::INFO::2012-10-28 15:49:57,007::logUtils::39::dispatcher::(wrapper) Run and protect: getStorageDomainsList, Return response: {'domlist': ['8f81428c-612 /var/log/vdsm/vdsm.log:Thread-5466::DEBUG::2012-10-28 15:49:57,008::task::1172::TaskManager.Task::(prepare) Task=`2bea6ecb-fa41-4850-a309-83e0bf589ed5`::finished: {'domlist': ['8f81428c- /var/log/vdsm/vdsm.log:Thread-5466::DEBUG::2012-10-28 15:49:57,008::task::588::TaskManager.Task::(_updateState) Task=`2bea6ecb-fa41-4850-a309-83e0bf589ed5`::moving from state preparing - /var/log/vdsm/vdsm.log:Thread-5466::DEBUG::2012-10-28 15:49:57,009::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} /var/log/vdsm/vdsm.log:Thread-5466::DEBUG::2012-10-28 15:49:57,009::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} /var/log/vdsm/vdsm.log:Thread-5466::DEBUG::2012-10-28 15:49:57,009::task::978::TaskManager.Task::(_decref) Task=`2bea6ecb-fa41-4850-a309-83e0bf589ed5`::ref 0 aborting False