kernel fails to load iwlwifi firmware - disable CONFIG_FW_LOADER_USER_HELPER

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

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?

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.

OK. In that case, it goes to the Gnome people who care for NetworkManager

(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.

Likely related to https://bugzilla.novell.com/show_bug.cgi?id=817551

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

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.

(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.

Bernhard? Please choose the correct maintainer which could be NetworkManager and/or wicked

(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

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

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?

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)

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

Cool guys, so do you have the firmware in-place? Show me your:
* rpm -ql kernel-firmware
* lspci -nn

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)

Yes, and could you also attach lsinitrd /boot/initrd?

Created attachment 603345
rpm -ql kernel-firmware

Created attachment 603346
lspci -nn

Created attachment 603347
lsinitrd /boot/initrd

Created attachment 603348
Full dmesg log

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/p...

(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.

Pushed:
   8f730c579d8f..2873b40b1bc3 master -> master

*** Bug 898858 has been marked as a duplicate of this bug. ***

(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)

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.