Note: This is a public test instance of Red Hat Bugzilla. The data contained within is a snapshot of the live data so any changes you make will not be reflected in the production Bugzilla. Email is disabled so feel free to test any aspect of the site that you want. File any problems you find or give feedback at bugzilla.redhat.com.
Bug 1811382
Summary: | anaconda failed to login to the iscsi target if attachment takes longer than ~15 seconds | ||||||||||||||||||
---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|
Product: | [Fedora] Fedora | Reporter: | lnie <lnie> | ||||||||||||||||
Component: | anaconda | Assignee: | Radek Vykydal <rvykydal> | ||||||||||||||||
Status: | CLOSED ERRATA | QA Contact: | Fedora Extras Quality Assurance <extras-qa> | ||||||||||||||||
Severity: | unspecified | Docs Contact: | |||||||||||||||||
Priority: | unspecified | ||||||||||||||||||
Version: | 32 | CC: | 837637215, anaconda-maint-list, awilliam, gmarr, jkonecny, jonathan, kellin, lnie, robatino, tbzatek, vanmeeuwen+fedora, vponcova, vtrefny, wwoods | ||||||||||||||||
Target Milestone: | --- | ||||||||||||||||||
Target Release: | --- | ||||||||||||||||||
Hardware: | Unspecified | ||||||||||||||||||
OS: | Unspecified | ||||||||||||||||||
Whiteboard: | RejectedBlocker AcceptedFreezeException | ||||||||||||||||||
Fixed In Version: | anaconda-32.24.4-1.fc32 | Doc Type: | If docs needed, set a value | ||||||||||||||||
Doc Text: | Story Points: | --- | |||||||||||||||||
Clone Of: | Environment: | ||||||||||||||||||
Last Closed: | 2020-04-03 00:51:19 UTC | Type: | Bug | ||||||||||||||||
Regression: | --- | Mount Type: | --- | ||||||||||||||||
Documentation: | --- | CRM: | |||||||||||||||||
Verified Versions: | Category: | --- | |||||||||||||||||
oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |||||||||||||||||
Cloudforms Team: | --- | Target Upstream Version: | |||||||||||||||||
Embargoed: | |||||||||||||||||||
Bug Depends On: | |||||||||||||||||||
Bug Blocks: | 1705306 | ||||||||||||||||||
Attachments: |
|
Created attachment 1668391 [details]
storage.log
The iscsi target works fine with iscsiadm [root@bogon Documents]# iscsiadm -m node -T iqn.2016-01.com.example:target -l Logging in to [iface: default, target: iqn.2016-01.com.example:target, portal: 10.16.218.98,3260] (multiple) Login to [iface: default, target: iqn.2016-01.com.example:target, portal: 10.16.218.98,3260] successful. FYI,I've also tried with the target created by tgtadm,also affected Actually,the target login successfully.But anaconda complaints authorization failure,and you can't continue the installation with server installer [root@localhost-live liveuser]# lsblk NAME MAJ:MIN RM SIZE RO TYPE MOUNTPOINT loop0 7:0 0 1.7G 1 loop loop1 7:1 0 7.5G 1 loop ├─live-rw 253:0 0 7.5G 0 dm / └─live-base 253:1 0 7.5G 1 dm /run/install/source loop2 7:2 0 32G 0 loop └─live-rw 253:0 0 7.5G 0 dm / sda 8:0 0 1G 0 disk sr0 11:0 1 1.9G 0 rom /run/initramfs/live zram0 251:0 0 2G 0 disk [SWAP] vda 252:0 0 15G 0 disk Created attachment 1668425 [details]
screenshot
Created attachment 1668426 [details]
screenshot2
Created attachment 1668619 [details]
anaconda.log from server iso
Created attachment 1668621 [details]
syslog
Created attachment 1668622 [details]
storage.log from server iso
Proposed as a Blocker for 32-final by Fedora user lnie using the blocker tracking app because: This affects: The installer must be able to detect (if possible) and install to supported network-attached storage devices. This is almost certainly a dupe of https://bugzilla.redhat.com/show_bug.cgi?id=1774746 . lili, can you please check if it works for you with Rawhide? If so, that's likely the bug. https://bodhi.fedoraproject.org/updates/FEDORA-2020-1ed3392208 should fix it on F32, you'd need to build an updates.iso or respin an installer image to test it though...I'll post one here later today. Discussed during the 2020-03-09 blocker review meeting: [0] The decision to delay the classification of this as a blocker bug was made as we believe this is very likely to be a duplicate of 1774746, so we will delay the decision while we confirm that. [0] https://meetbot.fedoraproject.org/fedora-blocker-review/2020-03-09/f32-blocker-review.2020-03-09-16.01.txt Adam,this seems like a different bug,https://bodhi.fedoraproject.org/updates/FEDORA-2020-1ed3392208 doesn't work for fedora32(worklive and server iso),and I downloaded Fedora-Workstation-Live-x86_64-Rawhide-20200307.n.1.iso today,it is also affected by this bug. Lili, I am not able to reproduce the issue locally. Maybe the problem is slower attaching of the target in your case (~16 seconds): 08:49:31,382 WARNING org.fedoraproject.Anaconda.Modules.Storage:INFO:anaconda.threading:Running Thread: AnaTaskThread-ISCSILoginTask-1 (140123606939392) 08:49:32,390 INFO kernel:scsi host2: iSCSI Initiator over TCP/IP 08:49:32,752 INFO iscsid:iscsid: Connection1:0 to [target: iqn.2016-01.com.example:target, portal: 10.16.218.23,3260] through [iface: default] is operational now 08:49:33,216 NOTICE kernel:scsi 2:0:0:0: Direct-Access LIO-ORG testfile 4.0 PQ: 0 ANSI: 5 08:49:34,856 INFO kernel:scsi 2:0:0:0: alua: supports implicit and explicit TPGS 08:49:34,857 INFO kernel:scsi 2:0:0:0: alua: device naa.6001405bff115cc1b134534ad17f1362 port group 0 rel port 1 08:49:34,860 NOTICE kernel:sd 2:0:0:0: Attached scsi generic sg1 type 0 08:49:35,201 INFO systemd:Created slice system-anaconda\x2dshell.slice. 08:49:35,210 INFO systemd:Started Shell on tty2. 08:49:35,213 NOTICE audit:SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:kernel_t:s0 msg='unit=anaconda-shell@tty2 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' 08:49:35,266 INFO kernel:sd 2:0:0:0: alua: transition timeout set to 60 seconds 08:49:35,266 INFO kernel:sd 2:0:0:0: alua: port group 00 state A non-preferred supports TOlUSNA 08:49:37,209 NOTICE kernel:sd 2:0:0:0: [sda] 2097152 512-byte logical blocks: (1.07 GB/1.00 GiB) 08:49:37,621 NOTICE kernel:sd 2:0:0:0: [sda] Write Protect is off 08:49:37,622 DEBUG kernel:sd 2:0:0:0: [sda] Mode Sense: 43 00 00 08 08:49:38,440 NOTICE kernel:sd 2:0:0:0: [sda] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA 08:49:39,155 INFO kernel:sd 2:0:0:0: [sda] Optimal transfer size 8388608 bytes 08:49:48,675 NOTICE kernel:sd 2:0:0:0: [sda] Attached SCSI disk 08:49:50,915 WARNING org.fedoraproject.Anaconda.Modules.Storage:WARNING:blivet:iSCSI: could not log into iqn.2016-01.com.example:target: Failed to call Login method on /org/freedesktop/UDisks2/Manager with ('iqn.2016-01.com.example:target', 1, '10.16.218.23', 3260, 'default', {'node.startup': <'automatic'>}) arguments: GDBus.Error:org.freedesktop.UDisks2.Error.Failed: Error waiting for iSCSI device to appear: Timed out waiting for object 08:49:50,917 WARNING org.fedoraproject.Anaconda.Modules.Storage:INFO:anaconda.threading:Thread Failed: AnaTaskThread-ISCSILoginTask-1 (140123606939392) 08:49:50,919 WARNING org.fedoraproject.Anaconda.Modules.Storage:ERROR:anaconda.modules.common.task.task:Thread AnaTaskThread-ISCSILoginTask-1 has failed: Traceback (most recent call last): 08:49:50,919 WARNING org.fedoraproject.Anaconda.Modules.Storage: File "/usr/lib64/python3.8/site-packages/pyanaconda/threading.py", line 280, in run 08:49:50,919 WARNING org.fedoraproject.Anaconda.Modules.Storage: threading.Thread.run(self) 08:49:50,919 WARNING org.fedoraproject.Anaconda.Modules.Storage: File "/usr/lib64/python3.8/threading.py", line 870, in run 08:49:50,919 WARNING org.fedoraproject.Anaconda.Modules.Storage: self._target(*self._args, **self._kwargs) 08:49:50,919 WARNING org.fedoraproject.Anaconda.Modules.Storage: File "/usr/lib64/python3.8/site-packages/pyanaconda/modules/common/task/task.py", line 95, in _task_run_callback 08:49:50,919 WARNING org.fedoraproject.Anaconda.Modules.Storage: self._set_result(self.run()) 08:49:50,919 WARNING org.fedoraproject.Anaconda.Modules.Storage: File "/usr/lib64/python3.8/site-packages/pyanaconda/modules/storage/iscsi/discover.py", line 140, in run 08:49:50,919 WARNING org.fedoraproject.Anaconda.Modules.Storage: self._log_into_node(node_info, self._credentials) 08:49:50,919 WARNING org.fedoraproject.Anaconda.Modules.Storage: File "/usr/lib64/python3.8/site-packages/pyanaconda/modules/storage/iscsi/discover.py", line 179, in _log_into_node 08:49:50,919 WARNING org.fedoraproject.Anaconda.Modules.Storage: raise StorageDiscoveryError(msg) 08:49:50,919 WARNING org.fedoraproject.Anaconda.Modules.Storage:pyanaconda.modules.common.errors.configuration.StorageDiscoveryError: Failed to call Login method on /org/freedesktop/UDisks2/Manager with ('iqn.2016-01.com.example:target', 1, '10.16.218.23', 3260, 'default', {'node.startup': <'automatic'>}) arguments: GDBus.Error:org.freedesktop.UDisks2.Error.Failed: Error waiting for iSCSI device to appear: Timed out waiting for object I have some additional questions: - How long does attaching with iscsiadm tool take? - Are there any other targets where the case / your test works? - Does your case work with Fedora 31? Could you provide logs if it does (/tmp/syslog, /tmp/storage.log)? - Could you please provide detailed setup of your target (complete targetcli ls or ideally script to create the target if you have such). Maybe there is some important detail I am missing in my target setup. Thank you Vojto, any ideas about comment #13 please? (Timeout after ~15s). The timeout happens in UDisks. After login (which was successful) we wait for the device to appear -- we check if symlink /dev/disk/by-path/<target name> exists -- this is the 15 seconds timeout, the symlink should be created by UDev and it shouldn't take that long, /dev/sda appeared after 2 seconds. Lili can you check if the symlink in /dev/disk/by-path was created? Thank you Vojto for confirmation, from the logs it really seems kernel has not attached the disk by the 15 secs timeout. (In reply to Radek Vykydal from comment #16) > Thank you Vojto for confirmation, from the logs it really seems kernel has > not attached the disk by the 15 secs timeout. Well, scratch this comment, I don't understand what is happening there in the kernel... Radek, You are right,I have set up a target on my local server,and the bug is gone. I have checked,Fedora 31 doesn't work either with the remote server. Fedora31 used to work well on my home laptops,my home network becomes a little slower this several days,seems that's really the problem Anyway, Here is the simple script I used: targetcli /backstores/fileio create testfile /tmp/fileio 1G write_back=false targetcli /iscsi create iqn.2016-01.com.example:target targetcli /iscsi/iqn.2016-01.com.example:target/tpg1/luns create /backstores/fileio/testfile targetcli /iscsi/iqn.2016-01.com.example:target/tpg1/acls create iqn.1994-05.com.redhat:71fc25b8ad3 targetcli exit firewall-cmd --permanent --add-port=3260/tcp firewall-cmd --reload here is the targetcli ls: [root@dell-pe-fm120-1b ~]# targetcli ls o- / ......................................................................................................................... [...] o- backstores .............................................................................................................. [...] | o- block .................................................................................................. [Storage Objects: 0] | o- fileio ................................................................................................. [Storage Objects: 1] | | o- testfile ...................................................................... [/tmp/fileio (1.0GiB) write-thru activated] | | o- alua ................................................................................................... [ALUA Groups: 1] | | o- default_tg_pt_gp ....................................................................... [ALUA state: Active/optimized] | o- pscsi .................................................................................................. [Storage Objects: 0] | o- ramdisk ................................................................................................ [Storage Objects: 0] o- iscsi ............................................................................................................ [Targets: 1] | o- iqn.2016-01.com.example:target .................................................................................... [TPGs: 1] | o- tpg1 ............................................................................................... [no-gen-acls, no-auth] | o- acls .......................................................................................................... [ACLs: 8] | | o- iqn.1994-05.com.redhat:1cca1b87d979 .................................................................. [Mapped LUNs: 1] | | | o- mapped_lun0 ............................................................................. [lun0 fileio/testfile (rw)] | | o- iqn.1994-05.com.redhat:71fc25b8ad3 ................................................................... [Mapped LUNs: 1] | | | o- mapped_lun0 ............................................................................. [lun0 fileio/testfile (rw)] | | o- iqn.1994-05.com.redhat:a1e06728cd57 .................................................................. [Mapped LUNs: 1] | | | o- mapped_lun0 ............................................................................. [lun0 fileio/testfile (rw)] | | o- iqn.1994-05.com.redhat:a781af1f6ad8 .................................................................. [Mapped LUNs: 1] | | | o- mapped_lun0 ............................................................................. [lun0 fileio/testfile (rw)] | | o- iqn.1994-05.com.redhat:b3fd68d1d2e9 .................................................................. [Mapped LUNs: 1] | | o- mapped_lun0 ............................................................................. [lun0 fileio/testfile (rw)] | o- luns .......................................................................................................... [LUNs: 1] | | o- lun0 ............................................................... [fileio/testfile (/tmp/fileio) (default_tg_pt_gp)] | o- portals .................................................................................................... [Portals: 1] | o- 0.0.0.0:3260 ..................................................................................................... [OK] o- loopback ......................................................................................................... [Targets: 0] o- vhost ............................................................................................................ [Targets: 0] [root@dell-pe-fm120-1b ~]# ip addr 1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN group default qlen 1000 link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00 inet 127.0.0.1/8 scope host lo valid_lft forever preferred_lft forever inet6 ::1/128 scope host valid_lft forever preferred_lft forever 2: eno1: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc mq state UP group default qlen 1000 link/ether 4c:76:25:d5:73:2f brd ff:ff:ff:ff:ff:ff inet 10.16.218.23/23 brd 10.16.219.255 scope global dynamic noprefixroute eno1 valid_lft 50827sec preferred_lft 50827sec inet6 2620:52:0:10da:4e76:25ff:fed5:732f/64 scope global dynamic noprefixroute valid_lft 2591999sec preferred_lft 604799sec inet6 fe80::4e76:25ff:fed5:732f/64 scope link noprefixroute valid_lft forever preferred_lft forever 3: eno2: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc mq state UP group default qlen 1000 link/ether 4c:76:25:d5:73:30 brd ff:ff:ff:ff:ff:ff inet 10.16.219.187/23 brd 10.16.219.255 scope global dynamic noprefixroute eno2 valid_lft 1665sec preferred_lft 1665sec inet6 2620:52:0:10da:1cd8:415:869:55bd/64 scope global dynamic noprefixroute valid_lft 2591999sec preferred_lft 604799sec inet6 fe80::668a:1940:2b29:bf14/64 scope link noprefixroute valid_lft forever preferred_lft forever iscsiadm login takes pretty shorter time than the installer [root@bogon avocado-vt-76.0]# time iscsiadm -m node -T iqn.2016-01.com.example:target -l Logging in to [iface: default, target: iqn.2016-01.com.example:target, portal: 10.16.218.23,3260] (multiple) Login to [iface: default, target: iqn.2016-01.com.example:target, portal: 10.16.218.23,3260] successful. real 0m3.289s user 0m0.005s sys 0m0.004s Vojtech, The /dev/disk/by-path/<target name> path didn't show up until about 20s later (In reply to lnie from comment #18) > > iscsiadm login takes pretty shorter time than the installer > [root@bogon avocado-vt-76.0]# time iscsiadm -m node -T > iqn.2016-01.com.example:target -l > Logging in to [iface: default, target: iqn.2016-01.com.example:target, > portal: 10.16.218.23,3260] (multiple) > Login to [iface: default, target: iqn.2016-01.com.example:target, portal: > 10.16.218.23,3260] successful. > > real 0m3.289s > user 0m0.005s > sys 0m0.004s The 15 seconds wait in UDisks starts after a successful login. The problem is not login, but attaching the disk as Radek mention in comment #16. We can raise the time limit in UDisks (we are actually raising it in UDisks 2.9.0 for unrelated reasons to 20 seconds for all API calls) but I don't think this is a good solution -- next time this could take 25 seconds instead of 15 and we have the same issue again. I think there are two things we could improve in Anaconda: 1) Wrap the error message text. 2) Replace the hint for checking authorization information in the message with something better / less misleading - for this case (Timeout) or in general. But I think the cause of the issue (bad network connection) would makes it no blocker. Discussed during the 2020-03-16 blocker review meeting: [0] The decision to classify this bug as a "RejectedBlocker" and an "AcceptedFreezeException" was made as it's only a conditional violation in an unusual condition (in the normal case, iSCSI works fine) and it's not new behaviour (F31 behaves the same). Accepted as an FE issue as it cannot be addressed with an update and a fix or mitigation (better error message for e.g.) would be welcome for the Final release. [0] https://meetbot.fedoraproject.org/fedora-blocker-review/2020-03-16/f32-blocker-review.2020-03-16-16.03.txt (In reply to Radek Vykydal from comment #21) > I think there are two things we could improve in Anaconda: > > 1) Wrap the error message text. PR: https://github.com/rhinstaller/anaconda/pull/2385 > 2) Replace the hint for checking authorization information in the message > with something better / less misleading - for this case (Timeout) or in > general. Given the failure in the BZ is quite a corner case I'd leave the message as is, including the hint "Please double check your authorization information and try again" which applies in vast majority of cases. (In reply to Radek Vykydal from comment #23) > (In reply to Radek Vykydal from comment #21) > > I think there are two things we could improve in Anaconda: > > > > 1) Wrap the error message text. > > PR: https://github.com/rhinstaller/anaconda/pull/2385 This should fix the dialog running out of the screen as can be seen in screenshots in comment #4 and comment #5. *** Bug 1772357 has been marked as a duplicate of this bug. *** FEDORA-2020-073681d379 has been submitted as an update to Fedora 32. https://bodhi.fedoraproject.org/updates/FEDORA-2020-073681d379 FEDORA-2020-073681d379 has been pushed to the Fedora 32 testing repository. In short time you'll be able to install the update with the following command: `sudo dnf upgrade --enablerepo=updates-testing --advisory=FEDORA-2020-073681d379` You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2020-073681d379 See also https://fedoraproject.org/wiki/QA:Updates_Testing for more information on how to test updates. It works as described in comment #23 and comment #24 FEDORA-2020-073681d379 has been pushed to the Fedora 32 stable repository. If problem still persists, please make note of it in this bug report. |
Created attachment 1668390 [details] anaconda.log Description of problem: boot the installer, click into "Add a disk",try to use an iscsi disk, anaconda able to find the target,but failed to login. /iscsi/iqn.20...get/tpg1/acls> ls o- acls .................................................................................................................. [ACLs: 1] o- iqn.1994-05.com.redhat:71fc25b8ad3 ........................................................................... [Mapped LUNs: 1] | o- mapped_lun0 ..................................................................................... [lun0 fileio/testfile (rw)] /iscsi/iqn.20...get/tpg1/acls> cd .. /iscsi/iqn.20...e:target/tpg1> get attribute authentication authentication=0 Version-Release number of selected component (if applicable): Fedora-Workstation-Live-x86_64-32-20200307.n.0.iso How reproducible: always Steps to Reproduce: 1. 2. 3. Actual results: Expected results: Additional info: