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 - anaconda failed to login to the iscsi target if attachment takes longer than ~15 seconds
Summary: anaconda failed to login to the iscsi target if attachment takes longer than ...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: anaconda
Version: 32
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: Radek Vykydal
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard: RejectedBlocker AcceptedFreezeException
: 1772357 (view as bug list)
Depends On:
Blocks: F32FinalFreezeException
TreeView+ depends on / blocked
 
Reported: 2020-03-08 08:17 UTC by lnie
Modified: 2020-04-03 00:51 UTC (History)
14 users (show)

Fixed In Version: anaconda-32.24.4-1.fc32
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2020-04-03 00:51:19 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)
anaconda.log (9.46 KB, text/plain)
2020-03-08 08:17 UTC, lnie
no flags Details
storage.log (21.04 KB, text/plain)
2020-03-08 08:18 UTC, lnie
no flags Details
screenshot (109.34 KB, image/png)
2020-03-08 12:51 UTC, lnie
no flags Details
screenshot2 (97.23 KB, image/png)
2020-03-08 12:52 UTC, lnie
no flags Details
anaconda.log from server iso (14.49 KB, text/plain)
2020-03-09 10:03 UTC, lnie
no flags Details
syslog (418.53 KB, text/plain)
2020-03-09 10:04 UTC, lnie
no flags Details
storage.log from server iso (2.82 KB, text/plain)
2020-03-09 10:04 UTC, lnie
no flags Details

Description lnie 2020-03-08 08:17:27 UTC
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:

Comment 1 lnie 2020-03-08 08:18:16 UTC
Created attachment 1668391 [details]
storage.log

Comment 2 lnie 2020-03-08 08:20:39 UTC
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

Comment 3 lnie 2020-03-08 12:47:53 UTC
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

Comment 4 lnie 2020-03-08 12:51:38 UTC
Created attachment 1668425 [details]
screenshot

Comment 5 lnie 2020-03-08 12:52:07 UTC
Created attachment 1668426 [details]
screenshot2

Comment 6 lnie 2020-03-09 10:03:12 UTC
Created attachment 1668619 [details]
anaconda.log from server iso

Comment 7 lnie 2020-03-09 10:04:11 UTC
Created attachment 1668621 [details]
syslog

Comment 8 lnie 2020-03-09 10:04:56 UTC
Created attachment 1668622 [details]
storage.log from server iso

Comment 9 Fedora Blocker Bugs Application 2020-03-09 10:20:18 UTC
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.

Comment 10 Adam Williamson 2020-03-09 16:00:39 UTC
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.

Comment 11 Geoffrey Marr 2020-03-10 01:10:00 UTC
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

Comment 12 lnie 2020-03-10 07:33:46 UTC
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.

Comment 13 Radek Vykydal 2020-03-11 09:32:04 UTC
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

Comment 14 Radek Vykydal 2020-03-11 12:11:27 UTC
Vojto, any ideas about comment #13 please? (Timeout after ~15s).

Comment 15 Vojtech Trefny 2020-03-11 12:22:30 UTC
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?

Comment 16 Radek Vykydal 2020-03-11 12:26:47 UTC
Thank you Vojto for confirmation, from the logs it really seems kernel has not attached the disk by the 15 secs timeout.

Comment 17 Radek Vykydal 2020-03-11 12:28:42 UTC
(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...

Comment 18 lnie 2020-03-11 12:35:01 UTC
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

Comment 19 lnie 2020-03-11 12:37:14 UTC
Vojtech,

The /dev/disk/by-path/<target name>  path  didn't show up until about 20s later

Comment 20 Vojtech Trefny 2020-03-13 07:04:57 UTC
(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.

Comment 21 Radek Vykydal 2020-03-13 07:59:01 UTC
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.

Comment 22 Geoffrey Marr 2020-03-16 19:03:23 UTC
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

Comment 23 Radek Vykydal 2020-03-17 16:08:52 UTC
(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.

Comment 24 Radek Vykydal 2020-03-17 16:14:35 UTC
(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.

Comment 25 Radek Vykydal 2020-03-18 18:21:09 UTC
*** Bug 1772357 has been marked as a duplicate of this bug. ***

Comment 26 Fedora Update System 2020-03-31 19:09:11 UTC
FEDORA-2020-073681d379 has been submitted as an update to Fedora 32. https://bodhi.fedoraproject.org/updates/FEDORA-2020-073681d379

Comment 27 Fedora Update System 2020-04-01 02:15:25 UTC
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.

Comment 28 lnie 2020-04-01 11:08:21 UTC
It works as described in comment #23 and comment #24

Comment 29 Fedora Update System 2020-04-03 00:51:19 UTC
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.


Note You need to log in before you can comment on or make changes to this bug.