Bug 891645 - Need to wait 2 minutes before wireless connects
Need to wait 2 minutes before wireless connects
Status: RESOLVED FIXED
: 898858 (view as bug list)
Classification: openSUSE
Product: openSUSE Tumbleweed
Classification: openSUSE
Component: Kernel
201407*
x86 openSUSE 13.2
: P3 - Medium : Major (vote)
: ---
Assigned To: Jiri Slaby
E-mail List
:
Depends on:
Blocks: 901767
  Show dependency treegraph
 
Reported: 2014-08-12 22:52 UTC by Michal ng
Modified: 2018-07-03 20:50 UTC (History)
8 users (show)

See Also:
Found By: ---
Services Priority:
Business Priority:
Blocker: ---
Marketing QA Status: ---
IT Deployment: ---


Attachments
rpm -ql kernel-firmware (26.90 KB, text/plain)
2014-08-22 16:43 UTC, Dominique Leuenberger
Details
lspci -nn (4.52 KB, text/plain)
2014-08-22 16:44 UTC, Dominique Leuenberger
Details
lsinitrd /boot/initrd (58.22 KB, text/plain)
2014-08-22 16:44 UTC, Dominique Leuenberger
Details
Full dmesg log (67.84 KB, text/plain)
2014-08-22 16:44 UTC, Dominique Leuenberger
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Michal ng 2014-08-12 22:52:04 UTC
User-Agent:       Mozilla/5.0 (X11; Linux i686; rv:31.0) Gecko/20100101 Firefox/31.0


Installed openSUSE Factory using the openSUSE-Factory-NET-i586-Current.iso.
During installation, wireless is detected but unable to connect so the installation was performed with Ethernet (RJ45) cable instead of wireless.


After installation,
noticed that when using Ethernet (RJ45) cable, do not need to wait much for the internet connection to be established during boot up.
However, if I were to remove the Ethernet cable and try to connect using wireless during boot up, will need to wait approximately 2 minutes before openSUSE activates the wireless connection.


Did try switching to Wicked and Disbling Network Service.
It allows the configuring of the Wireless and Ethernet connection but the 2 minutes wait is still there, even after configuring wireless and reboot.


Installed Fluxbox and nm-applet and booted into them.
Confirmed that the 2 minutes wait is still there.

Reproducible: Always

Steps to Reproduce:
1. Boot into openSUSE Factory
2. Wait for wireless connection.
3.
Actual Results:  
Need to wait approximately 2 minutes before wireless connects

Expected Results:  
Wireless connection within a very short period
Comment 1 Bernhard Wiedemann 2014-08-18 06:10:44 UTC
As it happens both with wicked and NetworkManager, 
it seems to not be related to any of them.

My best guess on how to get closer to the problem
would be to get timings out of systemd via
http://freedesktop.org/wiki/Software/systemd/Debugging/

Do you have NFS/Samba shares that could block things?
Comment 2 Michal ng 2014-08-18 12:48:39 UTC
Correction, the problem happens with NetworkManager.
I switched to Wicked (to disable NetworkManager) for a short moment so that I can configure the wireless interface (which will be locked if managed by NetworkManager).


If you still want me to play with http://freedesktop.org/wiki/Software/systemd/Debugging/ , will need you help to be more specific. Just a normal user here :D


No, I do not have NFS/Samba shares. Just a Ext4 partition with / and /home altogether. Do have an encrypted Ext4 mounted at boot at /mnt/extra.
Comment 3 Bernhard Wiedemann 2014-08-18 13:11:20 UTC
OK. In that case, it goes to the Gnome people who care for NetworkManager
Comment 4 Dominique Leuenberger 2014-08-18 13:26:45 UTC
(In reply to comment #3)
> OK. In that case, it goes to the Gnome people who care for NetworkManager

I have my fair share of doubt on that one... I actually see it on my machine too (yes, with NM.. but)


- my driver used is iwlwifi
During boot, the driver fails to load the firmware (error -2), retries after 60s, fails, retries after 60s success, trying to pass on to 'user space'

It does not matter if I start a session or not in the meantime.

The issue with 'user space': this is meant to be udev - but udev no longer does that.

http://lists.freedesktop.org/archives/systemd-devel/2013-August/012536.html

I'm CCing udev/systemtd maintainers for their valuable input on the topic as well.
Comment 5 Dominique Leuenberger 2014-08-18 13:43:53 UTC
Likely related to https://bugzilla.novell.com/show_bug.cgi?id=817551
Comment 6 Dominique Leuenberger 2014-08-18 13:57:40 UTC
from systemd.spec:

%if 0%{?suse_version} <= 1310
  --with-firmware-path="%{_prefix}/lib/firmware:/lib/firmware" \
%endif

Introduced with https://build.opensuse.org/request/show/238853
Comment 7 Dr. Werner Fink 2014-08-18 15:37:12 UTC
Are you aware that this is a WONTFIX!

From systemd-210/README:

        Userspace firmware loading is deprecated, will go away, and
        sometimes causes problems:
          CONFIG_FW_LOADER_USER_HELPER=n

and as long as this is deprecated the firmware part will not go into.
Comment 8 Dominique Leuenberger 2014-08-18 15:46:51 UTC
(In reply to comment #7)
> Are you aware that this is a WONTFIX!
> 
> From systemd-210/README:
> 
>         Userspace firmware loading is deprecated, will go away, and
>         sometimes causes problems:
>           CONFIG_FW_LOADER_USER_HELPER=n
> 
> and as long as this is deprecated the firmware part will not go into.

Hold it right there - before there are misunderstandings:

I never said it was a bug that needed fixing in systemd. I merely pointed out that which change caused it to happen to surface.

The bug though is that the systemd maintainer introduced this without talking to the kernel maintainer...

As a current openSUSE Kernel still has:
> zgrep FW_LOADER /proc/config.gz 
CONFIG_FW_LOADER=y
CONFIG_FW_LOADER_USER_HELPER=y

Pleae, look beyond your garden - if you are already aware that a change in your package requires a fix in something else - why not coordinate those two changes?

As such: should you really decide to 'wontfix' that, there is likely not much I can do, but it will not make the issue go away.
Comment 9 Dr. Werner Fink 2014-08-18 16:13:18 UTC
Bernhard? Please choose the correct maintainer which could be NetworkManager and/or wicked
Comment 10 Dominique Leuenberger 2014-08-18 16:21:16 UTC
(In reply to comment #9)
> Bernhard? Please choose the correct maintainer which could be NetworkManager
> and/or wicked

???

you claim
>         Userspace firmware loading is deprecated, will go away, and
>         sometimes causes problems:
>           CONFIG_FW_LOADER_USER_HELPER=n

Our kernel has this different (=y).

Yet, it shall be a wicked/NM bug?

/me is confused
Comment 11 Dr. Werner Fink 2014-08-18 16:43:49 UTC
Suppose there will be an update of systemd and there is no firmware anymore ... now what will happen then?  Upstream of systemd has decided not to go this way.

config FW_LOADER_USER_HELPER
        bool "Fallback user-helper invocation for firmware loading"
        depends on FW_LOADER
        default y
        help
          This option enables / disables the invocation of user-helper
          (e.g. udev) for loading firmware files as a fallback after the
          direct file loading in kernel fails.  The user-mode helper is
          no longer required unless you have a special firmware file that
          resides in a non-standard path.

Maybe Robert has aa idea why this is depricated.  AFAIK such helpers are not required anymore
Comment 15 Jiri Slaby 2014-08-21 13:24:01 UTC
Hmm, that is interesting. The config option is there for backward compatibility. To make the kernel work with older userspace (those predating 13.1 in this case).

The bug seems to be that the kernel fails to load the firmware and falls back to udev loading.

Can you provide the dmesg output from a machine booted with the delay?
Comment 16 Dominique Leuenberger 2014-08-21 18:17:33 UTC
Jiri,

on my system i see:

dle1gis@linux:~> dmesg | grep iwl
[    7.050451] iwlwifi 0000:03:00.0: can't disable ASPM; OS doesn't have ASPM control
[    7.050520] iwlwifi 0000:03:00.0: irq 47 for MSI/MSI-X
[    7.055182] iwlwifi 0000:03:00.0: Direct firmware load failed with error -2
[    7.055187] iwlwifi 0000:03:00.0: Falling back to user helper
[   67.119868] iwlwifi 0000:03:00.0: Direct firmware load failed with error -2
[   67.119876] iwlwifi 0000:03:00.0: Falling back to user helper
[  127.257650] iwlwifi 0000:03:00.0: loaded firmware version 9.221.4.1 build 25532 op_mode iwldvm
[  127.278256] iwlwifi 0000:03:00.0: CONFIG_IWLWIFI_DEBUG enabled
[  127.278261] iwlwifi 0000:03:00.0: CONFIG_IWLWIFI_DEBUGFS enabled
[  127.278265] iwlwifi 0000:03:00.0: CONFIG_IWLWIFI_DEVICE_TRACING disabled
[  127.278269] iwlwifi 0000:03:00.0: Detected Intel(R) Centrino(R) Advanced-N 6200 AGN, REV=0x74
[  127.278343] iwlwifi 0000:03:00.0: L1 Enabled; Disabling L0S
[  127.298454] ieee80211 phy0: Selected rate control algorithm 'iwl-agn-rs'
[  127.305733] iwlwifi 0000:03:00.0: L1 Enabled; Disabling L0S
[  127.312159] iwlwifi 0000:03:00.0: Radio type=0x1-0x3-0x1
[  127.523766] iwlwifi 0000:03:00.0: L1 Enabled; Disabling L0S
[  127.530183] iwlwifi 0000:03:00.0: Radio type=0x1-0x3-0x1


(not changing NEEDINFO - but I guess Michal has something alike)
Comment 17 Michal ng 2014-08-21 22:21:09 UTC
output from my system

dmesg | grep iwl
[   15.686273] iwlwifi 0000:03:00.0: can't disable ASPM; OS doesn't have ASPM control
[   15.686335] iwlwifi 0000:03:00.0: irq 45 for MSI/MSI-X
[   15.727254] iwlwifi 0000:03:00.0: Direct firmware load failed with error -2
[   15.727262] iwlwifi 0000:03:00.0: Falling back to user helper
[   75.896537] iwlwifi 0000:03:00.0: Direct firmware load failed with error -2
[   75.896545] iwlwifi 0000:03:00.0: Falling back to user helper
[  136.094305] iwlwifi 0000:03:00.0: loaded firmware version 9.221.4.1 build 25532 op_mode iwldvm
[  136.158913] iwlwifi 0000:03:00.0: CONFIG_IWLWIFI_DEBUG enabled
[  136.158920] iwlwifi 0000:03:00.0: CONFIG_IWLWIFI_DEBUGFS enabled
[  136.158924] iwlwifi 0000:03:00.0: CONFIG_IWLWIFI_DEVICE_TRACING disabled
[  136.158929] iwlwifi 0000:03:00.0: Detected Intel(R) Centrino(R) Ultimate-N 6300 AGN, REV=0x74
[  136.158987] iwlwifi 0000:03:00.0: L1 Enabled; Disabling L0S
[  136.180935] ieee80211 phy0: Selected rate control algorithm 'iwl-agn-rs'
[  136.204473] iwlwifi 0000:03:00.0: L1 Enabled; Disabling L0S
[  136.204685] iwlwifi 0000:03:00.0: Radio type=0x0-0x3-0x1
[  136.419495] iwlwifi 0000:03:00.0: L1 Enabled; Disabling L0S
[  136.419728] iwlwifi 0000:03:00.0: Radio type=0x0-0x3-0x1
Comment 18 Jiri Slaby 2014-08-22 11:30:15 UTC
Cool guys, so do you have the firmware in-place? Show me your:
* rpm -ql  kernel-firmware
* lspci -nn
Comment 19 Dominique Leuenberger 2014-08-22 11:37:41 UTC
Considering it magically finds firmware after two minutes, I would cast a guess and say yes:

[  127.257650] iwlwifi 0000:03:00.0: loaded firmware version 9.221.4.1 build
25532 op_mode iwldvm

(but I will confirm in the evening on my machine - Michal might be faster to that)
Comment 20 Jiri Slaby 2014-08-22 11:55:09 UTC
Yes, and could you also attach lsinitrd /boot/initrd?
Comment 21 Dominique Leuenberger 2014-08-22 16:43:37 UTC
Created attachment 603345 [details]
rpm -ql kernel-firmware
Comment 22 Dominique Leuenberger 2014-08-22 16:44:08 UTC
Created attachment 603346 [details]
lspci -nn
Comment 23 Dominique Leuenberger 2014-08-22 16:44:30 UTC
Created attachment 603347 [details]
lsinitrd /boot/initrd
Comment 24 Dominique Leuenberger 2014-08-22 16:44:55 UTC
Created attachment 603348 [details]
Full dmesg log
Comment 25 Dominique Leuenberger 2014-08-22 17:20:45 UTC
NOTE: unloading and reloading iwlwifi brings back the 2 minute window - so it is definitively NOT related to a race on bootup: even if the system was up for 30 minutes already, simply do:

rmmod iwlwifi
modprobe iwlwifi
=> it will take again 2 minutes to load the firmware

some udevadm monitoring:

after 'modprobe iwlwifi'

KERNEL[3055.484684] add      /module/iwlwifi (module)
UDEV  [3055.485613] add      /module/iwlwifi (module)
KERNEL[3055.485656] add      /bus/pci/drivers/iwlwifi (drivers)
KERNEL[3055.485810] add      /devices/pci0000:00/0000:00:1c.1/0000:03:00.0/firmware/iwlwifi-6000-6.ucode (firmware)
UDEV  [3055.486038] add      /bus/pci/drivers/iwlwifi (drivers)
UDEV  [3055.486638] add      /devices/pci0000:00/0000:00:1c.1/0000:03:00.0/firmware/iwlwifi-6000-6.ucode (firmware)
KERNEL[3055.487174] add      /module/iwldvm (module)
UDEV  [3055.487377] add      /module/iwldvm (module)

one minute later (note: remove *-6.ucode, add *-5.ucode)

1KERNEL[3115.612278] remove   /devices/pci0000:00/0000:00:1c.1/0000:03:00.0/firmware/iwlwifi-6000-6.ucode (firmware)
KERNEL[3115.612320] add      /devices/pci0000:00/0000:00:1c.1/0000:03:00.0/firmware/iwlwifi-6000-5.ucode (firmware)
UDEV  [3115.613263] remove   /devices/pci0000:00/0000:00:1c.1/0000:03:00.0/firmware/iwlwifi-6000-6.ucode (firmware)
UDEV  [3115.613708] add      /devices/pci0000:00/0000:00:1c.1/0000:03:00.0/firmware/iwlwifi-6000-5.ucode (firmware)

one minute later (note: remove *-5.ucode; I assume it would add *-4*.ucode, BUT this is loaded in kernel, as this is the file that exists!)

KERNEL[3175.644300] remove   /devices/pci0000:00/0000:00:1c.1/0000:03:00.0/firmware/iwlwifi-6000-5.ucode (firmware)
UDEV  [3175.645274] remove   /devices/pci0000:00/0000:00:1c.1/0000:03:00.0/firmware/iwlwifi-6000-5.ucode (firmware)
KERNEL[3175.660107] add      /devices/pci0000:00/0000:00:1c.1/0000:03:00.0/leds/phy3-led (leds)
KERNEL[3175.660145] add      /devices/pci0000:00/0000:00:1c.1/0000:03:00.0/ieee80211/phy3 (ieee80211)
KERNEL[3175.660220] add      /devices/pci0000:00/0000:00:1c.1/0000:03:00.0/ieee80211/phy3/rfkill6 (rfkill)
KERNEL[3175.660480] change   /devices/pci0000:00/0000:00:1c.1/0000:03:00.0/leds/phy3-led (leds)
KERNEL[3175.660507] add      /devices/pci0000:00/0000:00:1c.1/0000:03:00.0/net/wlan0 (net)
UDEV  [3175.660525] add      /devices/pci0000:00/0000:00:1c.1/0000:03:00.0/leds/phy3-led (leds)
KERNEL[3175.660541] add      /devices/pci0000:00/0000:00:1c.1/0000:03:00.0/net/wlan0/queues/rx-0 (queues)
KERNEL[3175.660557] add      /devices/pci0000:00/0000:00:1c.1/0000:03:00.0/net/wlan0/queues/tx-0 (queues)
KERNEL[3175.660572] add      /devices/pci0000:00/0000:00:1c.1/0000:03:00.0/net/wlan0/queues/tx-1 (queues)
KERNEL[3175.660587] add      /devices/pci0000:00/0000:00:1c.1/0000:03:00.0/net/wlan0/queues/tx-2 (queues)
KERNEL[3175.660602] add      /devices/pci0000:00/0000:00:1c.1/0000:03:00.0/net/wlan0/queues/tx-3 (queues)
UDEV  [3175.661026] change   /devices/pci0000:00/0000:00:1c.1/0000:03:00.0/leds/phy3-led (leds)
UDEV  [3175.661060] add      /devices/pci0000:00/0000:00:1c.1/0000:03:00.0/ieee80211/phy3 (ieee80211)
UDEV  [3175.661768] add      /devices/pci0000:00/0000:00:1c.1/0000:03:00.0/ieee80211/phy3/rfkill6 (rfkill)
UDEV  [3175.666579] add      /devices/pci0000:00/0000:00:1c.1/0000:03:00.0/net/wlan0 (net)
UDEV  [3175.667090] add      /devices/pci0000:00/0000:00:1c.1/0000:03:00.0/net/wlan0/queues/rx-0 (queues)
UDEV  [3175.667520] add      /devices/pci0000:00/0000:00:1c.1/0000:03:00.0/net/wlan0/queues/tx-2 (queues)
UDEV  [3175.667705] add      /devices/pci0000:00/0000:00:1c.1/0000:03:00.0/net/wlan0/queues/tx-1 (queues)
UDEV  [3175.668393] add      /devices/pci0000:00/0000:00:1c.1/0000:03:00.0/net/wlan0/queues/tx-3 (queues)
UDEV  [3175.669080] add      /devices/pci0000:00/0000:00:1c.1/0000:03:00.0/net/wlan0/queues/tx-0 (queues)



So the main issue is indeed that we pass off to udev for loading - and there is a 60s timeout (per try)
Comment 26 Jiri Slaby 2014-08-27 14:52:09 UTC
(In reply to comment #25)
> So the main issue is indeed that we pass off to udev for loading - and there is
> a 60s timeout (per try)

Yes, indeed. That's the root cause. Your symptoms result from the fact, that the driver tries two firmwares, which were never released by intel.

I will disable to helper as we used to have the firmwares in the preset locations, so it should not cause problems to anybody even if the kernel is installed on older distros.
Comment 27 Jiri Slaby 2014-08-27 15:40:05 UTC
Pushed:
   8f730c579d8f..2873b40b1bc3  master -> master
Comment 28 Bernhard Wiedemann 2014-09-30 10:51:30 UTC
*** Bug 898858 has been marked as a duplicate of this bug. ***
Comment 29 Dominique Leuenberger 2014-09-30 11:02:13 UTC
(In reply to Jiri Slaby from comment #27)
> Pushed:
>    8f730c579d8f..2873b40b1bc3  master -> master

Can you make an assessment in which kernel in Factory this fix will appear? I now have kernel 3.16.2 (latest changelog entry Sep 7 2014), but this fix is not yet included (so also the kernel in upcoming openSUSE 13.2 seems to be missing this fix)
Comment 30 Jiri Slaby 2014-10-01 15:19:48 UTC
We cannot disable userspace fw loader in the stable branch which is pulled into factory. Dell RBU driver depends on that. So the fix gets to factory as soon as 3.17 is released and merged to the stable branch.