Bug 100621

Summary: iwlwifi: dvm: deauthenticated Reason: 15=4WAY_HANDSHAKE_TIMEOUT
Product: Drivers Reporter: Vincent Legoll (vincent.legoll)
Component: network-wirelessAssignee: drivers_network-wireless (drivers_network-wireless)
Status: CLOSED INVALID    
Severity: normal CC: ilw, vincent.legoll
Priority: P1    
Hardware: x86-64   
OS: Linux   
Kernel Version: 4.1.0 Subsystem:
Regression: No Bisected commit-id:
Attachments: dmesg from working fedora
dmesg from failing debian
dmesg from failing debian, new kernel, with iwlwifi debug options
trace-cmd

Description Vincent Legoll 2015-06-28 08:11:11 UTC
Some times ago (I'll say about a month or two) my wifi stopped working.
As I had no time back then, I used eth0 instead.

Now that I'm willing to investigate that issue, I'm trying things,
so far none worked, except when I booted a usb stick with a recent
fedora image, this was working fine.

Symptoms: AP association is OK, but authentication fails.

Tried a few older kernels (back to 3.14) that were used when it
was working.

Downgraded some packages that may be related to the issue:

firmware-iwlwifi 0.44 -> 0.42 (dunno if this was really taken into account)
libssl1.0.0 1.0.2c-1 -> 1.0.2-1
wpasupplicant 2.3-2 -> 2.2-1

More infos

$ lspci -vs 02:00.0
02:00.0 Network controller: Intel Corporation WiFi Link 5100
	Subsystem: Intel Corporation WiFi Link 5100 AGN
	Flags: bus master, fast devsel, latency 0, IRQ 33
	Memory at d9900000 (64-bit, non-prefetchable) [size=8K]
	Capabilities: <access denied>
	Kernel driver in use: iwlwifi

$ dmesg
[...]
[    3.852593] Intel(R) Wireless WiFi driver for Linux
[    3.852597] Copyright(c) 2003- 2015 Intel Corporation
[    3.852802] iwlwifi 0000:02:00.0: can't disable ASPM; OS doesn't have ASPM control
[    3.879158] iwlwifi 0000:02:00.0: loaded firmware version 8.83.5.1 build 33692 op_mode iwldvm
[...]
[    3.910148] iwlwifi 0000:02:00.0: CONFIG_IWLWIFI_DEBUG disabled
[    3.910154] iwlwifi 0000:02:00.0: CONFIG_IWLWIFI_DEBUGFS disabled
[    3.910157] iwlwifi 0000:02:00.0: CONFIG_IWLWIFI_DEVICE_TRACING disabled
[    3.910160] iwlwifi 0000:02:00.0: Detected Intel(R) WiFi Link 5100 AGN, REV=0x54
[    3.910272] iwlwifi 0000:02:00.0: L1 Enabled - LTR Disabled
[    3.967702] ieee80211 phy0: Selected rate control algorithm 'iwl-agn-rs'
[...]
[    5.330290] iwlwifi 0000:02:00.0: L1 Enabled - LTR Disabled
[    5.333944] iwlwifi 0000:02:00.0: Radio type=0x1-0x2-0x0
[    5.431692] iwlwifi 0000:02:00.0: L1 Enabled - LTR Disabled
[    5.434698] iwlwifi 0000:02:00.0: Radio type=0x1-0x2-0x0
[    5.777094] cfg80211: Calling CRDA to update world regulatory domain
[    5.862314] cfg80211: Calling CRDA to update world regulatory domain
[    6.988104] cfg80211: Calling CRDA to update world regulatory domain
[...]
[    8.628420] cfg80211: Calling CRDA to update world regulatory domain
[    8.677038] wlan0: authenticate with 52:f2:79:19:0b:78
[    8.680610] wlan0: send auth to 52:f2:79:19:0b:78 (try 1/3)
[    8.683367] wlan0: authenticated
[    8.684694] wlan0: associate with 52:f2:79:19:0b:78 (try 1/3)
[    8.687594] wlan0: RX AssocResp from 52:f2:79:19:0b:78 (capab=0x411 status=0 aid=3)
[    8.692691] wlan0: associated
[   10.144065] cfg80211: Calling CRDA to update world regulatory domain
[...]
[   13.292126] cfg80211: Calling CRDA to update world regulatory domain
[   14.898131] wlan0: deauthenticated from 52:f2:79:19:0b:78 (Reason: 15=4WAY_HANDSHAKE_TIMEOUT)
[   14.934452] cfg80211: Calling CRDA to update world regulatory domain
[   15.181292] cfg80211: Calling CRDA to update world regulatory domain
[   15.299529] cfg80211: Calling CRDA to update world regulatory domain
[   16.444070] cfg80211: Calling CRDA to update world regulatory domain
[   18.049103] cfg80211: Calling CRDA to update world regulatory domain
[   18.051124] wlan0: authenticate with 52:f2:79:19:0b:78
[   18.056643] wlan0: send auth to 52:f2:79:19:0b:78 (try 1/3)
[   18.059290] wlan0: authenticated
[   18.068037] wlan0: associate with 52:f2:79:19:0b:78 (try 1/3)
[   18.070963] wlan0: RX AssocResp from 52:f2:79:19:0b:78 (capab=0x411 status=0 aid=3)
[   18.075820] wlan0: associated
[   19.596099] cfg80211: Calling CRDA to update world regulatory domain
[   22.748036] cfg80211: Calling CRDA to update world regulatory domain
[   24.344580] wlan0: deauthenticated from 52:f2:79:19:0b:78 (Reason: 15=4WAY_HANDSHAKE_TIMEOUT)
[   24.361552] cfg80211: Calling CRDA to update world regulatory domain
[   24.835054] cfg80211: Calling CRDA to update world regulatory domain
[   24.844865] cfg80211: Calling CRDA to update world regulatory domain
[   25.900082] cfg80211: Calling CRDA to update world regulatory domain
[   27.572349] cfg80211: Calling CRDA to update world regulatory domain
[   27.574626] wlan0: authenticate with 52:f2:79:19:0b:78
[   27.581557] wlan0: send auth to 52:f2:79:19:0b:78 (try 1/3)
[   27.583869] wlan0: authenticated
[   27.588084] wlan0: associate with 52:f2:79:19:0b:78 (try 1/3)
[   27.591244] wlan0: RX AssocResp from 52:f2:79:19:0b:78 (capab=0x411 status=0 aid=3)
[   27.593284] wlan0: associated
[   29.052264] cfg80211: Calling CRDA to update world regulatory domain
[   29.359266] iwlwifi 0000:02:00.0: RF_KILL bit toggled to disable radio.
[   29.359432] wlan0: deauthenticating from 52:f2:79:19:0b:78 by local choice (Reason: 3=DEAUTH_LEAVING)
Comment 1 Vincent Legoll 2015-06-28 08:22:54 UTC
tried that too :

# cat /etc/modprobe.d/iwlwifi.conf 
options iwlwifi 11n_disable=1
Comment 2 Vincent Legoll 2015-06-28 08:24:02 UTC
and also:
options iwlwifi swcrypto=1
Comment 3 Emmanuel Grumbach 2015-06-28 08:40:57 UTC
Please share your syslog output.
What is the kernel / supplicant version you have on the USB stick?

Note: Nothing has really changed in the kernel in that driver for a long time.
Comment 4 Vincent Legoll 2015-06-28 08:52:58 UTC
You mean syslog from the working fedora ?
I'll reboot into it now...
Comment 5 Emmanuel Grumbach 2015-06-28 09:08:02 UTC
No, the syslog of the failing system
Comment 6 Vincent Legoll 2015-06-28 09:33:49 UTC
Working fedora liveUSB

$ cat /etc/fedora-release 
Fedora release 21 (Twenty One)

$ uname -a
Linux localhost 3.17.4-301.fc21.x86_64 #1 SMP Thu Nov 27 19:09:10 UTC 2014 x86_64 x86_64 x86_64 GNU/Linux

Name        : wpa_supplicant
Version     : 2.0
Release     : 12.fc21
Comment 7 Vincent Legoll 2015-06-28 09:34:57 UTC
Created attachment 181161 [details]
dmesg from working fedora
Comment 8 Vincent Legoll 2015-06-28 09:36:04 UTC
Firmware from fedora

Name        : iwl5000-firmware
Version     : 8.83.5.1_1
Release     : 41.fc21
Comment 9 Vincent Legoll 2015-06-28 09:41:12 UTC
Created attachment 181171 [details]
dmesg from failing debian
Comment 10 Emmanuel Grumbach 2015-06-28 10:41:29 UTC
I start now to understand that the Debian is working and not the Fedora... Not very clear from your first report.... Oh well...


I asked for the syslog and not for the dmesg.
Why supplicant version do you have on your Debian system?
Comment 11 Emmanuel Grumbach 2015-06-28 10:42:41 UTC
Ah ok - got on my mail
Comment 12 Emmanuel Grumbach 2015-06-28 10:48:18 UTC
Oh, please add -dd to your wpa_supplicant options.

can you record a tracing?

sudo trace-cmd record -e iwlwifi -e iwlwifi_data?
Comment 13 Vincent Legoll 2015-06-28 15:58:02 UTC
Debian sid is my installed system, which stopped working some times ago.
I tried booting a fedora 21 liveusb to test, and this one is working.

I sent the dmesgs before seeing that you wanted the full syslogs

I'll get you the other requested infos
Comment 14 Vincent Legoll 2015-06-28 16:52:06 UTC
On the failing debian system, I tried various versions of wpasupplicant
2.3-2
2.2-1
1.1-1
1.0-3.1
1.0-3
1.0-2
Comment 15 Vincent Legoll 2015-06-28 17:00:29 UTC
I also tried older libssl version because of this https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=788567
Comment 16 Vincent Legoll 2015-06-28 17:07:40 UTC
Created attachment 181191 [details]
dmesg from failing debian, new kernel, with iwlwifi debug options
Comment 17 Vincent Legoll 2015-06-28 17:19:20 UTC
Created attachment 181201 [details]
trace-cmd

gzipped output from

trace-cmd record -e iwlwifi -e iwlwifi_data

when trying to connect to AP (through NM-applet)
Comment 18 Vincent Legoll 2015-06-28 17:21:27 UTC
where do I put the -dd wpasupplicant option ?
Comment 19 Emmanuel Grumbach 2015-06-28 18:54:29 UTC
From the driver point of view, I don't see any failure besides the fact that I can only see the EAPOL 1/4 and 4/4 which is strange but very unlikely to be related to the kernel which is what this bugzilla is all about.

Note that as I said, very little has changed in the driver for many years now. So if it works in Fedora and not in Debian, I'd check the supplicant / libssl and whatnot.

You mentioned that wpa_supplicant 2.0 works for you on Fedora, but didn't test that one on Debian.

To add -dd to the supplicant, you can launch it manually:
/sbin/wpa_supplicant -s -d -P /run/wpa_supplicant.wlan0.pid -i wlan0 -D nl80211 -c /etc/wpa_supplicant/wpa_supplicant.conf

You'll need to create a wpa_supplicant.conf file.
Comment 20 Vincent Legoll 2015-06-28 20:53:35 UTC
Yeah, I'm fairly confident this is not a kernel problem, as I keep a lot of old kernels around (that I build myself from linus's repo) and going back to an older kernel that was used when the wifi was working did not fix the problem.

I'm not so sure about the other components: firmware, wpa_supplicant, libssl...
BTW, are there *other* packages that make the wifi stack for this HW ?

I didn't test wpa_supplicant 2.0 since I couldn't find a binary package of this version, but going before 2.0 does not fix it anyways...

The strange thing, is that I'm currently on :

wpa_supplicant 1.0-2
firmware-iwlwifi 0.42
libssl 1.0.1k-3

Which is fairly far in the past, and nothing changed...

I'd need to double check with the working fedora, but I'm wondering if I'm not missing a piece of the puzzle...
Comment 21 Emmanuel Grumbach 2015-06-29 05:37:26 UTC
The components that are needed are:
kernel
firmware
supplicant

now the supplicant itself has a few dependencies:
$ ldd /sbin/wpa_supplicant 
	linux-vdso.so.1 =>  (0x00007fff5d72e000)
	librt.so.1 => /lib/x86_64-linux-gnu/librt.so.1 (0x00007fd00db26000)
	libnl-3.so.200 => /lib/x86_64-linux-gnu/libnl-3.so.200 (0x00007fd00d90a000)
	libnl-genl-3.so.200 => /lib/x86_64-linux-gnu/libnl-genl-3.so.200 (0x00007fd00d704000)
	libdl.so.2 => /lib/x86_64-linux-gnu/libdl.so.2 (0x00007fd00d500000)
	libpcsclite.so.1 => /lib/x86_64-linux-gnu/libpcsclite.so.1 (0x00007fd00d2f5000)
	libssl.so.1.0.0 => /lib/x86_64-linux-gnu/libssl.so.1.0.0 (0x00007fd00d094000)
	libcrypto.so.1.0.0 => /lib/x86_64-linux-gnu/libcrypto.so.1.0.0 (0x00007fd00ccb0000)
	libdbus-1.so.3 => /lib/x86_64-linux-gnu/libdbus-1.so.3 (0x00007fd00ca68000)
	libc.so.6 => /lib/x86_64-linux-gnu/libc.so.6 (0x00007fd00c69e000)
	libpthread.so.0 => /lib/x86_64-linux-gnu/libpthread.so.0 (0x00007fd00c480000)
	libm.so.6 => /lib/x86_64-linux-gnu/libm.so.6 (0x00007fd00c178000)
	/lib64/ld-linux-x86-64.so.2 (0x00007fd00dd2e000)

The kernel and the firmware haven't changed for years for that device and you have the latest firmware.
Comment 22 Vincent Legoll 2015-06-29 18:09:43 UTC
I finally found something after stumbling upon that other bug report:
https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=790326

by creating a very minimal wpa.conf file:

network={
  ssid="NETWORK_NAME"
  scan_ssid=1
  key_mgmt=WPA-PSK
  psk="NETWORK_PASSWORD"
}

and then running:
wpa_supplicant -i wlan0 -ddd -Dwext -cwpa.conf

So I think that some update made wpa_supplicant configuration change from wext driver to another not working one...

That may be a NetworkManager change, or some other random change somewhere...

:-/

BTW thanks for all the help and time spent on this...

I hope, other people that fall into this trap, can find some help reading this bug report...
Comment 23 Vincent Legoll 2015-06-29 18:19:57 UTC
And for completeness sake, I also had to:

rfkill unblock wlan
Comment 24 Emmanuel Grumbach 2015-06-29 18:40:48 UTC
Ok - so I guess we can close this issue and smash the wpa_s / NM packager at Debian :)
Comment 25 Vincent Legoll 2015-06-29 18:52:20 UTC
No, I wouldn't want to smash anyone, at least not until I fully
understand where the problem came from...

:-)

On Mon, Jun 29, 2015 at 8:40 PM,  <bugzilla-daemon@bugzilla.kernel.org> wrote:
> https://bugzilla.kernel.org/show_bug.cgi?id=100621
>
> --- Comment #24 from Emmanuel Grumbach <emmanuel.grumbach@intel.com> ---
> Ok - so I guess we can close this issue and smash the wpa_s / NM packager at
> Debian :)
>
> --
> You are receiving this mail because:
> You are on the CC list for the bug.
> You reported the bug.
Comment 26 Vincent Legoll 2015-06-29 18:55:19 UTC
But yes, I'm OK to close this bug report...

On Mon, Jun 29, 2015 at 8:52 PM, Vincent Legoll
<vincent.legoll@gmail.com> wrote:
> No, I wouldn't want to smash anyone, at least not until I fully
> understand where the problem came from...
>
> :-)
>
> On Mon, Jun 29, 2015 at 8:40 PM,  <bugzilla-daemon@bugzilla.kernel.org>
> wrote:
>> https://bugzilla.kernel.org/show_bug.cgi?id=100621
>>
>> --- Comment #24 from Emmanuel Grumbach <emmanuel.grumbach@intel.com> ---
>> Ok - so I guess we can close this issue and smash the wpa_s / NM packager at
>> Debian :)
>>
>> --
>> You are receiving this mail because:
>> You are on the CC list for the bug.
>> You reported the bug.
>
>
>
> --
> Vincent Legoll