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.
Bug 1958932 - [RHEL9 udisks2] dbus.exceptions.DBusException: org.freedesktop.UDisks2.Error.Failed: Login failed: initiator reported error
Summary: [RHEL9 udisks2] dbus.exceptions.DBusException: org.freedesktop.UDisks2.Error....
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 9
Classification: Red Hat
Component: udisks2
Version: 9.0
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: beta
: ---
Assignee: Tomáš Bžatek
QA Contact: guazhang@redhat.com
URL:
Whiteboard:
Depends On: 1967959
Blocks:
TreeView+ depends on / blocked
 
Reported: 2021-05-10 12:50 UTC by guazhang@redhat.com
Modified: 2023-05-09 08:14 UTC (History)
0 users

Fixed In Version: udisks2-2.9.4-7.el9
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2023-05-09 07:28:54 UTC
Type: Bug
Target Upstream Version:
Embargoed:

Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Product Errata RHBA-2023:2173 0 None None None 2023-05-09 07:29:03 UTC

Description guazhang@redhat.com 2021-05-10 12:50:08 UTC 
Description of problem:
RHEL9 udisks2 regression found errors that udisks2 login iSCSI login failed due to authorization failure

Version-Release number of selected component (if applicable):
RHEL-9.0.0-20210504.5 BaseOS x86_64

How reproducible:


Steps to Reproduce:
1.  python3 src/tests/dbus-tests/run_tests.py -s test_30_iscsi.UdisksISCSITest.test_login_chap_auth
2.
3.

[root@storageqe-59 udisks-2.9.2]# python3 src/tests/dbus-tests/run_tests.py -s test_30_iscsi.UdisksISCSITest.test_login_chap_auth
Configuration restored from src/tests/dbus-tests/targetcli_config.json
Not spawning own process: testing the system installed instance.
test_login_chap_auth (test_30_iscsi.UdisksISCSITest) ... ERROR

======================================================================
ERROR: test_login_chap_auth (test_30_iscsi.UdisksISCSITest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/root/rpmbuild/BUILD/udisks-2.9.2/src/tests/dbus-tests/test_30_iscsi.py", line 147, in test_login_chap_auth
    manager.Login(iqn, tpg, host, port, iface, options,
  File "/usr/lib64/python3.9/site-packages/dbus/proxies.py", line 141, in __call__
    return self._connection.call_blocking(self._named_service,
  File "/root/rpmbuild/BUILD/udisks-2.9.2/src/tests/dbus-tests/udiskstestcase.py", line 41, in call_long
    return call(*args, **kwargs)
  File "/usr/lib64/python3.9/site-packages/dbus/connection.py", line 652, in call_blocking
    reply_message = self.send_message_with_reply_and_block(
dbus.exceptions.DBusException: org.freedesktop.UDisks2.Error.Failed: Login failed: initiator reported error (24 - iSCSI login failed due to authorization failure)

----------------------------------------------------------------------
Ran 1 test in 0.187s

FAILED (errors=1)
All configuration cleared
[root@storageqe-59 udisks-2.9.2]# 


[root@storageqe-59 udisks-2.9.2]# python3 src/tests/dbus-tests/run_tests.py -s test_30_iscsi.UdisksISCSITest.test_login_mutual_auth
Configuration restored from src/tests/dbus-tests/targetcli_config.json
Not spawning own process: testing the system installed instance.
test_login_mutual_auth (test_30_iscsi.UdisksISCSITest) ... ERROR

======================================================================
ERROR: test_login_mutual_auth (test_30_iscsi.UdisksISCSITest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/root/rpmbuild/BUILD/udisks-2.9.2/src/tests/dbus-tests/test_30_iscsi.py", line 195, in test_login_mutual_auth
    manager.Login(iqn, tpg, host, port, iface, options,
  File "/usr/lib64/python3.9/site-packages/dbus/proxies.py", line 141, in __call__
    return self._connection.call_blocking(self._named_service,
  File "/root/rpmbuild/BUILD/udisks-2.9.2/src/tests/dbus-tests/udiskstestcase.py", line 41, in call_long
    return call(*args, **kwargs)
  File "/usr/lib64/python3.9/site-packages/dbus/connection.py", line 652, in call_blocking
    reply_message = self.send_message_with_reply_and_block(
dbus.exceptions.DBusException: org.freedesktop.UDisks2.Error.Failed: Login failed: initiator reported error (24 - iSCSI login failed due to authorization failure)

----------------------------------------------------------------------
Ran 1 test in 0.192s

FAILED (errors=1)
All configuration cleared
[root@storageqe-59 udisks-2.9.2]# 





and hit lvmcache error once


ERROR: test_40_cache (test_20_LVM.UdisksLVMTest)
Basic LVM cache test
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/root/rpmbuild/BUILD/udisks-2.9.2/src/tests/dbus-tests/test_20_LVM.py", line 332, in test_40_cache
    lv.CacheAttach('udisks_test_cache_lv', self.no_options, dbus_interface=self.iface_prefix + '.LogicalVolume')
  File "/usr/lib64/python3.9/site-packages/dbus/proxies.py", line 72, in __call__
    return self._proxy_method(*args, **keywords)
  File "/usr/lib64/python3.9/site-packages/dbus/proxies.py", line 141, in __call__
    return self._connection.call_blocking(self._named_service,
  File "/root/rpmbuild/BUILD/udisks-2.9.2/src/tests/dbus-tests/udiskstestcase.py", line 41, in call_long
    return call(*args, **kwargs)
  File "/usr/lib64/python3.9/site-packages/dbus/connection.py", line 652, in call_blocking
    reply_message = self.send_message_with_reply_and_block(
dbus.exceptions.DBusException: org.freedesktop.UDisks2.Error.Failed: Error converting volume: Process reported exit code 5:   WARNING: Converting udisks_test_cache_vg/udisks_test_cache_lv to cache pool's data volume with metadata wiping.
  THIS WILL DESTROY CONTENT OF LOGICAL VOLUME (filesystem etc.)
  Volume group "udisks_test_cache_vg" has insufficient free space (0 extents): 2 required.
  LV udisks_test_cache_vg/udisks_test_cache_lv_cdata could not be converted to a cache pool.

https://beaker-archive.host.prod.eng.bos.redhat.com/beaker-logs/2021/05/53530/5353078/9960944/125714888/taskout.log
Comment 1 Tomáš Bžatek 2021-05-10 13:03:15 UTC 
The lvm cache failure is https://bugzilla.redhat.com/show_bug.cgi?id=1952881, still not included in the current builds.

The iSCSI failure looks real, I'll look into it.
Comment 2 Tomáš Bžatek 2021-06-02 13:48:23 UTC 
FYI, there seems to be another (perhaps related) issue in the iscsi-initiator-utils code where login action sometimes take excessive amount of time (before reporting failure) that exceeeds the default D-Bus method call timeout. The error message is slightly different in this case:

======================================================================
FAIL: test_login_chap_auth (test_30_iscsi.UdisksISCSITest)
----------------------------------------------------------------------
dbus.exceptions.DBusException: org.freedesktop.DBus.Error.NoReply: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/tbzatek/devel/udisks/src/tests/dbus-tests/test_30_iscsi.py", line 140, in test_login_chap_auth
    manager.Login(iqn, tpg, host, port, iface, options,
AssertionError: "Login failed: initiator reported error" does not match "org.freedesktop.DBus.Error.NoReply: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken."

> Thread 82 (Thread 0x7f3c43734640 (LWP 231928) "pool-lt-udisksd"):
> #0  0x00007f3c530c65bf in __GI___poll (fds=fds@entry=0x7f3c4372e040, nfds=nfds@entry=1, timeout=timeout@entry=1000) at ../sysdeps/unix/sysv/linux/poll.c:29
> #1  0x00007f3c437d9f5f in poll (__timeout=1000, __nfds=1, __fds=0x7f3c4372e040) at /usr/include/bits/poll2.h:47
> #2  iscsid_response (fd=16, cmd=cmd@entry=MGMT_IPC_SESSION_LOGIN, rsp=rsp@entry=0x7f3c4372e090, timeout=1000, timeout@entry=-1) at ../usr/iscsid_req.c:155
> #3  0x00007f3c437da08e in iscsid_req_wait (cmd=cmd@entry=MGMT_IPC_SESSION_LOGIN, fd=<optimized out>) at ../usr/iscsid_req.c:202
> #4  0x00007f3c437da6de in iscsid_req_by_rec (cmd=MGMT_IPC_SESSION_LOGIN, rec=0x7f3c4372eb20) at ../usr/iscsid_req.c:223
> #5  login_helper (data=data@entry=0x7f3c4373303c, rec=rec@entry=0x7f3c4372eb20) at /usr/src/debug/iscsi-initiator-utils-6.2.1.4-0.git095f59c.fc35.x86_64/libiscsi/libiscsi.c:417
> #6  0x00007f3c437d7a9f in idbm_for_each_iface (found=found@entry=0x7f3c43732a54, data=0x7f3c4373303c, fn=fn@entry=0x7f3c437da660 <login_helper>, targetname=0x7f3c43732b30 "iqn.2003-01.udisks.test:iscsi-test-chap", tpgt=1, ip=0x7f3c43732c34 "127.0.0.1", port=3260, ruw_lock=false) at ../usr/idbm.c:1911
> #7  0x00007f3c437da91b in libiscsi_node_login (context=0xa448a0, node=<optimized out>) at /usr/src/debug/iscsi-initiator-utils-6.2.1.4-0.git095f59c.fc35.x86_64/libiscsi/libiscsi.c:430
> #8  0x00007f3c50036ea2 in iscsi_perform_login_action (module=0xa3a040, action=ACTION_LOGIN, node=0x7f3c43732b30, auth_info=0x7f3c43733140, errorstr=0x7f3c437335e0) at udisksiscsiutil.c:182
> #9  0x00007f3c5003750d in iscsi_login (module=0xa3a040, name=0x7f3c3000c540 "iqn.2003-01.udisks.test:iscsi-test-chap", tpgt=1, address=0x7f3c3000c050 "127.0.0.1", port=3260, iface=0x7f3c30008120 "default", params=0xb89a90, errorstr=0x7f3c437335e0) at udisksiscsiutil.c:311
> #10 0x00007f3c50036664 in handle_login (object=0x9ee4f0, invocation=0x7f3c4800aad0, arg_name=0x7f3c3000c540 "iqn.2003-01.udisks.test:iscsi-test-chap", arg_tpgt=1, arg_address=0x7f3c3000c050 "127.0.0.1", arg_port=3260, arg_iface=0x7f3c30008120 "default", arg_options=0xb89a90) at udiskslinuxmanageriscsiinitiator.c:605
Comment 3 Tomáš Bžatek 2021-06-03 14:17:36 UTC 
Upstream pull request about extending timeouts: https://github.com/storaged-project/udisks/pull/893
That however doesn't solve this issue.
Comment 4 Tomáš Bžatek 2021-06-03 15:00:03 UTC 
Found this in the journal when the timeout occurs:

Jun 03 10:56:49 localhost kernel: scsi host10: iSCSI Initiator over TCP/IP
Jun 03 10:56:49 localhost kernel: Security negotiation failed.
Jun 03 10:56:49 localhost kernel: iSCSI Login negotiation failed.
Jun 03 10:56:49 localhost kernel:  connection110:0: detected conn error (1020)
Jun 03 10:56:49 localhost iscsid[195660]: iscsid: Could not set session110 priority. READ/WRITE throughout and latency could be affected.
Jun 03 10:56:49 localhost iscsid[195660]: iscsid: Login failed to authenticate with target iqn.2003-01.udisks.test:iscsi-test-chap
Jun 03 10:56:49 localhost iscsid[195660]: iscsid: session 110 login rejected: Initiator failed authentication with target
Jun 03 10:56:49 localhost iscsid[195660]: iscsid: Received iferror -11: Resource temporarily unavailable.
Jun 03 10:56:49 localhost iscsid[195660]: iscsid: can not safely destroy connection 0
Jun 03 10:56:49 localhost iscsid[195660]: iscsid: Kernel reported iSCSI connection 110:0 error (1020 - ISCSI_ERR_TCP_CONN_CLOSE: TCP connection closed) state (2)
Jun 03 10:57:19 localhost systemd[1]: systemd-hostnamed.service: Deactivated successfully.
Jun 03 10:57:19 localhost audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-hostnamed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Jun 03 10:57:19 localhost audit: BPF prog-id=191 op=UNLOAD
Jun 03 10:57:19 localhost audit: BPF prog-id=190 op=UNLOAD
Jun 03 10:57:21 localhost iscsid[195660]: iscsid: Login I/O error, failed to send a PDU
Jun 03 10:57:21 localhost kernel: rx_data returned -104, expecting 48.
Jun 03 10:57:21 localhost kernel: iSCSI Login negotiation failed.
Jun 03 10:57:23 localhost iscsid[195660]: iscsid: Login I/O error, failed to send a PDU
Jun 03 10:57:23 localhost kernel: rx_data returned -104, expecting 48.
Jun 03 10:57:23 localhost kernel: iSCSI Login negotiation failed.
...
Comment 5 Tomáš Bžatek 2021-06-04 14:33:10 UTC 
Filed bug 1967959 for the kernel issue (connection error).
Comment 7 Tomáš Bžatek 2022-10-31 14:41:18 UTC 
The original test failures should be fixed by this upstream change: https://github.com/storaged-project/udisks/pull/1035

The change is just about a test environment modification, no actual udisks code changed.
Comment 12 guazhang@redhat.com 2022-11-03 02:23:22 UTC 
Udisks2 regression have pass, move to verified.
Comment 14 errata-xmlrpc 2023-05-09 07:28:54 UTC 
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (udisks2 bug fix and enhancement update), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2023:2173
Note You need to log in before you can comment on or make changes to this bug.