Bug#849875: broadcom-sta-dkms: Wifi association took too long, failing activation

[Steven Monai]

Package: broadcom-sta-dkms
Version: 6.30.223.271-5
Severity: important

Dear Maintainer,

I am reporting essentially the same issue as in the recently-closed bug
#849034.

After upgrading to latest version of broadcom-sta-dkms, wifi connections
no longer work on my Dell Latitude E5520, running up-to-date debian sid.
The problem began once I upgraded broadcom-sta-dkms to the above-stated
version.

Here is the output of 'lspci -v' for the wireless card:

02:00.0 Network controller: Broadcom Limited BCM43228 802.11a/b/g/n
Subsystem: Dell Wireless 1530 Half-size Mini PCIe Card
Flags: bus master, fast devsel, latency 0, IRQ 17
Memory at e5300000 (64-bit, non-prefetchable) [size=16K]
Capabilities: [40] Power Management version 3
Capabilities: [58] Vendor Specific Information: Len=78 <?>
Capabilities: [48] MSI: Enable- Count=1/1 Maskable- 64bit+
Capabilities: [d0] Express Endpoint, MSI 00
Capabilities: [100] Advanced Error Reporting
Capabilities: [13c] Virtual Channel
Capabilities: [160] Device Serial Number 00-00-da-ff-ff-7c-c0-f8
Capabilities: [16c] Power Budgeting <?>
Kernel driver in use: wl
Kernel modules: bcma, wl

Here is what appears in the NetworkManager log when attempting to
connect (to SSID "TheFrogurtIsAlsoCursed", with correct passphrase):

Jan 01 11:52:55 sid NetworkManager[453]: <info> [1483300375.6204] device (wlp2s0): Activation: starting connection 'TheFrogurtIsAlsoCursed' (adf41f0e-3504-4367-9685-a7d204785857)
Jan 01 11:52:55 sid NetworkManager[453]: <info> [1483300375.6209] audit: op="connection-activate" uuid="adf41f0e-3504-4367-9685-a7d204785857" name="TheFrogurtIsAlsoCursed" pid=833 uid=1000 result="success"
Jan 01 11:52:55 sid NetworkManager[453]: <info> [1483300375.6212] device (wlp2s0): state change: disconnected -> prepare (reason 'none') [30 40 0]
Jan 01 11:52:55 sid NetworkManager[453]: <info> [1483300375.6216] manager: NetworkManager state is now CONNECTING
Jan 01 11:52:55 sid NetworkManager[453]: <info> [1483300375.6231] device (wlp2s0): state change: prepare -> config (reason 'none') [40 50 0]
Jan 01 11:52:55 sid NetworkManager[453]: <info> [1483300375.6236] device (wlp2s0): Activation: (wifi) access point 'TheFrogurtIsAlsoCursed' has security, but secrets are required.
Jan 01 11:52:55 sid NetworkManager[453]: <info> [1483300375.6237] device (wlp2s0): state change: config -> need-auth (reason 'none') [50 60 0]
Jan 01 11:52:55 sid NetworkManager[453]: <info> [1483300375.6407] device (wlp2s0): state change: need-auth -> prepare (reason 'none') [60 40 0]
Jan 01 11:52:55 sid NetworkManager[453]: <info> [1483300375.6413] device (wlp2s0): state change: prepare -> config (reason 'none') [40 50 0]
Jan 01 11:52:55 sid NetworkManager[453]: <info> [1483300375.6416] device (wlp2s0): Activation: (wifi) connection 'TheFrogurtIsAlsoCursed' has security, and secrets exist. No new secrets needed.
Jan 01 11:52:55 sid NetworkManager[453]: <info> [1483300375.6417] Config: added 'ssid' value 'TheFrogurtIsAlsoCursed'
Jan 01 11:52:55 sid NetworkManager[453]: <info> [1483300375.6417] Config: added 'scan_ssid' value '1'
Jan 01 11:52:55 sid NetworkManager[453]: <info> [1483300375.6418] Config: added 'key_mgmt' value 'WPA-PSK'
Jan 01 11:52:55 sid NetworkManager[453]: <info> [1483300375.6418] Config: added 'auth_alg' value 'OPEN'
Jan 01 11:52:55 sid NetworkManager[453]: <info> [1483300375.6418] Config: added 'psk' value '<omitted>'
Jan 01 11:52:55 sid NetworkManager[453]: <info> [1483300375.6446] sup-iface[0x55aa8feea970,wlp2s0]: config: set interface ap_scan to 1
Jan 01 11:53:20 sid NetworkManager[453]: <warn> [1483300400.5283] device (wlp2s0): Activation: (wifi) association took too long, failing activation
Jan 01 11:53:20 sid NetworkManager[453]: <info> [1483300400.5284] device (wlp2s0): state change: config -> failed (reason 'ssid-not-found') [50 120 53]
Jan 01 11:53:20 sid NetworkManager[453]: <info> [1483300400.5291] manager: NetworkManager state is now DISCONNECTED
Jan 01 11:53:20 sid NetworkManager[453]: <warn> [1483300400.5317] device (wlp2s0): Activation: failed for connection 'TheFrogurtIsAlsoCursed'
Jan 01 11:53:20 sid NetworkManager[453]: <info> [1483300400.5328] device (wlp2s0): supplicant interface state: inactive -> disconnected
Jan 01 11:53:20 sid NetworkManager[453]: <info> [1483300400.5352] device (wlp2s0): state change: failed -> disconnected (reason 'none') [120 30 0]
Jan 01 11:53:22 sid NetworkManager[453]: <info> [1483300402.6625] device (wlp2s0): supplicant interface state: disconnected -> inactive

And here is what appears in the wpa_supplicant log at the same time:

Jan 01 11:52:55 sid wpa_supplicant[552]: wlp2s0: CTRL-EVENT-SCAN-FAILED ret=-22 retry=1
Jan 01 11:52:56 sid wpa_supplicant[552]: wlp2s0: CTRL-EVENT-SCAN-FAILED ret=-22 retry=1
Jan 01 11:52:57 sid wpa_supplicant[552]: wlp2s0: CTRL-EVENT-SCAN-FAILED ret=-22 retry=1
Jan 01 11:52:58 sid wpa_supplicant[552]: wlp2s0: CTRL-EVENT-SCAN-FAILED ret=-22 retry=1
Jan 01 11:52:59 sid wpa_supplicant[552]: wlp2s0: CTRL-EVENT-SCAN-FAILED ret=-22 retry=1
Jan 01 11:53:00 sid wpa_supplicant[552]: wlp2s0: CTRL-EVENT-SCAN-FAILED ret=-22 retry=1
Jan 01 11:53:01 sid wpa_supplicant[552]: wlp2s0: CTRL-EVENT-SCAN-FAILED ret=-22 retry=1
Jan 01 11:53:02 sid wpa_supplicant[552]: wlp2s0: CTRL-EVENT-SCAN-FAILED ret=-22 retry=1
Jan 01 11:53:03 sid wpa_supplicant[552]: wlp2s0: CTRL-EVENT-SCAN-FAILED ret=-22 retry=1
Jan 01 11:53:04 sid wpa_supplicant[552]: wlp2s0: CTRL-EVENT-SCAN-FAILED ret=-22 retry=1
Jan 01 11:53:05 sid wpa_supplicant[552]: wlp2s0: CTRL-EVENT-SCAN-FAILED ret=-22 retry=1
Jan 01 11:53:06 sid wpa_supplicant[552]: wlp2s0: CTRL-EVENT-SCAN-FAILED ret=-22 retry=1
Jan 01 11:53:07 sid wpa_supplicant[552]: wlp2s0: CTRL-EVENT-SCAN-FAILED ret=-22 retry=1
Jan 01 11:53:08 sid wpa_supplicant[552]: wlp2s0: CTRL-EVENT-SCAN-FAILED ret=-22 retry=1
Jan 01 11:53:09 sid wpa_supplicant[552]: wlp2s0: CTRL-EVENT-SCAN-FAILED ret=-22 retry=1
Jan 01 11:53:10 sid wpa_supplicant[552]: wlp2s0: CTRL-EVENT-SCAN-FAILED ret=-22 retry=1
Jan 01 11:53:11 sid wpa_supplicant[552]: wlp2s0: CTRL-EVENT-SCAN-FAILED ret=-22 retry=1
Jan 01 11:53:12 sid wpa_supplicant[552]: wlp2s0: CTRL-EVENT-SCAN-FAILED ret=-22 retry=1
Jan 01 11:53:13 sid wpa_supplicant[552]: wlp2s0: CTRL-EVENT-SCAN-FAILED ret=-22 retry=1
Jan 01 11:53:14 sid wpa_supplicant[552]: wlp2s0: CTRL-EVENT-SCAN-FAILED ret=-22 retry=1
Jan 01 11:53:15 sid wpa_supplicant[552]: wlp2s0: CTRL-EVENT-SCAN-FAILED ret=-22 retry=1
Jan 01 11:53:16 sid wpa_supplicant[552]: wlp2s0: CTRL-EVENT-SCAN-FAILED ret=-22 retry=1
Jan 01 11:53:17 sid wpa_supplicant[552]: wlp2s0: CTRL-EVENT-SCAN-FAILED ret=-22 retry=1
Jan 01 11:53:18 sid wpa_supplicant[552]: wlp2s0: CTRL-EVENT-SCAN-FAILED ret=-22 retry=1
Jan 01 11:53:19 sid wpa_supplicant[552]: wlp2s0: CTRL-EVENT-SCAN-FAILED ret=-22 retry=1

In one of the responses to bug #849034, it was suggested to try adding these
lines ...

[device]
wifi.scan-rand-mac-address=no

... to /etc/NetworkManager/NetworkManager.conf, and then reboot.

Unfortunately, this did not solve the problem for me.

I wanted to try downgrading to the previous version of the package,
but it appears that the sid version recently migrated to stretch,
and so I can only find the jessie and jessie-backports versions.

Anyway, thank you for your time.
Steven M.


-- System Information:
Debian Release: stretch/sid
APT prefers unstable
APT policy: (500, 'unstable')
Architecture: amd64 (x86_64)

Kernel: Linux 4.8.0-2-amd64 (SMP w/4 CPU cores)
Locale: LANG=en_CA.UTF-8, LC_CTYPE=en_CA.UTF-8 (charmap=UTF-8)
Shell: /bin/sh linked to /bin/dash
Init: systemd (via /run/systemd/system)

Versions of packages broadcom-sta-dkms depends on:
ii dkms 2.3-2

Versions of packages broadcom-sta-dkms recommends:
ii wireless-tools 30~pre9-12

broadcom-sta-dkms suggests no packages.

-- no debconf information

[Eduard Bloch]

Hallo,
* Steven Monai [Sun, Jan 01 2017, 12:59:22PM]:

> I wanted to try downgrading to the previous version of the package,
> but it appears that the sid version recently migrated to stretch,
> and so I can only find the jessie and jessie-backports versions.

You can find them on http://snapshot.debian.org/package/broadcom-sta/ .

However, I doubt this alone will solve your problem. I sometimes get
this kind of hickups, and they don't go away, even with a reboot. What
helps is a real power cycle (i.e. pull the battery, wait some seconds,
reinstall).

Best regards,
Eduard.

--
<charolastra> argumentum ad populum?
<Ganneff> argentum ad wirhabengenugdavonum

[Steven Monai]

On 17-01-02 04:04 AM, Eduard Bloch wrote:
> * Steven Monai [Sun, Jan 01 2017, 12:59:22PM]:
>> I wanted to try downgrading to the previous version of the package,
>> but it appears that the sid version recently migrated to stretch,
>> and so I can only find the jessie and jessie-backports versions.
>
> You can find them on http://snapshot.debian.org/package/broadcom-sta/

Thanks! How was I not aware of this fantastic resource?

> However, I doubt this alone will solve your problem. I sometimes get
> this kind of hickups, and they don't go away, even with a reboot. What
> helps is a real power cycle (i.e. pull the battery, wait some seconds,
> reinstall).

If true, this really sucks. I don't want to believe that I need to
resort to voodoo techniques to get hardware working. :(

[Some time passes...]

So I tried downgrading the broadcom-sta-dkms package to the previous
version (6.30.223.271-4), and there was no change, unfortunately. :(

Next, I decided to try a scientific approach, systematically downgrading
the other packages that directly affect wifi, namely the network-manager
and wpasupplicant packages. So I restored the broadcom-sta-dkms package
back to the current version, and proceeded to use dpkg to directly
install the .deb files for network-manager and wpasupplicant downloaded
from snapshot.debian.org.

Summary of my findings:

Downgrading network-manager made no difference. I tried the previous two
package versions (1.4.2-3 and 1.4.2-2).

Downgrading wpasupplicant, however, resulted in a successful wifi
connection! Specifically, the version of wpasupplicant currently in
stretch (2.5-2+v2.4-3+b1) works for me, with the other two packages
(broadcom-sta-dkms and network-manager) at their latest versions in sid.

So, for now, I have put a hold on the wpasupplicant package, to keep
version 2.5-2+v2.4-3+b1 installed.

Eduard: Should this information be shared with the wpasupplicant package
maintainer(s)? It seems like there could be some kind of incompatibility
between the the latest versions of broadcom-sta-dkms and wpasupplicant.

Steven M.

[Eduard Bloch]

Control: reassign 849875 wpasupplicant
Control: severity 849875 serious

Hallo,
* Steven Monai [Mon, Jan 02 2017, 08:11:03AM]:

> On 17-01-02 04:04 AM, Eduard Bloch wrote:
> > * Steven Monai [Sun, Jan 01 2017, 12:59:22PM]:
> >> I wanted to try downgrading to the previous version of the package,
> >> but it appears that the sid version recently migrated to stretch,
> >> and so I can only find the jessie and jessie-backports versions.
> >
> > You can find them on http://snapshot.debian.org/package/broadcom-sta/
>
> Thanks! How was I not aware of this fantastic resource?
>
> > However, I doubt this alone will solve your problem. I sometimes get
> > this kind of hickups, and they don't go away, even with a reboot. What
> > helps is a real power cycle (i.e. pull the battery, wait some seconds,
> > reinstall).
>
> If true, this really sucks. I don't want to believe that I need to
> resort to voodoo techniques to get hardware working. :(

Please don't beat the messenger and I don't know for sure. This might be
a stupid coincidence or a problem with some of my APs. But I am still
not impressed by the quality of that driver.

> [Some time passes...]
>
> So I tried downgrading the broadcom-sta-dkms package to the previous
> version (6.30.223.271-4), and there was no change, unfortunately. :(
>
> Next, I decided to try a scientific approach, systematically downgrading
> the other packages that directly affect wifi, namely the network-manager
> and wpasupplicant packages. So I restored the broadcom-sta-dkms package
> back to the current version, and proceeded to use dpkg to directly
> install the .deb files for network-manager and wpasupplicant downloaded
> from snapshot.debian.org.
>
> Summary of my findings:
>
> Downgrading network-manager made no difference. I tried the previous two
> package versions (1.4.2-3 and 1.4.2-2).
>
> Downgrading wpasupplicant, however, resulted in a successful wifi
> connection! Specifically, the version of wpasupplicant currently in
> stretch (2.5-2+v2.4-3+b1) works for me, with the other two packages
> (broadcom-sta-dkms and network-manager) at their latest versions in sid.
>
> So, for now, I have put a hold on the wpasupplicant package, to keep
> version 2.5-2+v2.4-3+b1 installed.

Oh, that's bad. Let's reassign to the wpasupplicant with appropriate
severity.

@Andrew and wpasupplicant folks: feel free to downgrade since the
driver is non-free and I cannot reproduce it with my hardware but if
true this will hit some users.

> Eduard: Should this information be shared with the wpasupplicant package
> maintainer(s)? It seems like there could be some kind of incompatibility
> between the the latest versions of broadcom-sta-dkms and wpasupplicant.

Thanks for the report and additional investigation!

Best Regards,
Eduard.

--
<Salz> jjFux: Ted hieß ja früher auch Walther
<Salz> winkiller: hm... es sind 8... die 7 kandidaten und NOTA
<Madkiss> Ist der jetzt eigentlich eine gespaltene Persönlichkeit, bei der aber
beide Teile bekloppt sind?

[Eduard Bloch]

Hallo,
* Michael Biebl [Sun, Aug 27 2017, 01:04:53PM]:
> > Ok, now the problem from the original report has hit me too.
> >
> > I could not figure out what is going on. I selected an AP which has been
> > working fine for months, and suddenly NM switched me to another AP
> > (which works partly since it is far away and reception quality is bad).
> >
> > I tried removing wpasupplicant and network-manager. Purging config.
> > Nothing helps. Checking the log, and WOW... (see attachment).
> > So wpa_supplicant says "Line 0: Invalid passphrase character".
> > Line 0 of what? This is most likely the input from NM which means: NM
> > feeds wpa_supplicant with CRAP. But which crap? When NM asked me for
> > passphrase, I am absolutely sure that I entered the correct one.
>
> Does the password have any special characters?

No. Actually, I have two APs here with different SSIDs but the same
password. One of them works fine, the other has the metioned problem.

> Can you change the WPA passphrase to something else (say only letters)
> and try again?

I did that and it worked. I reverted the change and then it works.

So the idea is then that something has corrupted the credentials store?
If so, why does it not drop the password from the store in case of
errors like this?

> Please also provide a full debug log from NetworkManager (and
> wpasupplicant) when the problem happens.
> https://wiki.gnome.org/Projects/NetworkManager/Debugging

Cannot do that right now. Luckily, I have a system backup and spare
hardware where it could be installed on... so I could try to reproduce
it if you want.

If you don't want, I think there should be some upstream fix which
deletes the credentials. The same way it does when the PSK has changed.

> which versions of wpasupplicant and network-manager do you have installed?

All Sid.

Best regards,
Eduard.

[Eduard Bloch]

On Sun, Sep 03, 2017 at 05:37:04PM +0200, Eduard Bloch wrote:
> Hallo,

> > Can you change the WPA passphrase to something else (say only letters)
> > and try again?
>
> I did that and it worked. I reverted the change and then it works.
>
> So the idea is then that something has corrupted the credentials store?
> If so, why does it not drop the password from the store in case of
> errors like this?

Actually, it did NOT last long. After a couple of sessions, the problem
started coming back again. I am in front of another laptop now with
Intel hardware instead of Broadcom but the home filesystem is cloned,
and running latest 4.13.x kernel from Sid. NM did work with this "new"
setup a couple of times and then it suddenly has fallen back to other
broken state: One APs does work, the other one (with better signal)
doesn't work (failure to associate, see dmesg stuff below).

If I stop NM and wpa_supplicant and go the old-school way
(wpa_supplicant run manually with custom config, then dhclient and
wavemon for status checking) then it works perfectly.

[73516.563547] IPv6: ADDRCONF(NETDEV_UP): wlp3s0: link is not ready
[73516.626325] wlp3s0: authenticate with 00:24:fe:04:fc:bb
[73516.633049] wlp3s0: send auth to 00:24:fe:04:fc:bb (try 1/3)
[73516.637369] wlp3s0: authenticated
[73516.640424] wlp3s0: associate with 00:24:fe:04:fc:bb (try 1/3)
[73516.644237] wlp3s0: RX AssocResp from 00:24:fe:04:fc:bb (capab=0x431 status=0 aid=1)
[73516.646138] wlp3s0: associated
[73516.646183] IPv6: ADDRCONF(NETDEV_CHANGE): wlp3s0: link becomes ready
[73525.076702] wlp3s0: deauthenticating from 00:24:fe:04:fc:bb by local choice (Reason: 3=DEAUTH_LEAVING)
[73525.085871] wlp3s0: failed to remove key (2, ff:ff:ff:ff:ff:ff) from hardware (-22)
[73525.093110] IPv6: ADDRCONF(NETDEV_UP): wlp3s0: link is not ready
[73525.114446] IPv6: ADDRCONF(NETDEV_UP): wlp3s0: link is not ready
[73526.018848] wlp3s0: authenticate with 00:1f:3f:15:f4:2d
[73526.023846] wlp3s0: send auth to 00:1f:3f:15:f4:2d (try 1/3)
[73526.028484] wlp3s0: authenticated
[73526.637884] iwlwifi 0000:03:00.0: No association and the time event is over already...
[73526.637906] wlp3s0: Connection to AP 00:1f:3f:15:f4:2d lost
[73531.025649] wlp3s0: aborting authentication with 00:1f:3f:15:f4:2d by local choice (Reason: 3=DEAUTH_LEAVING)
[73532.067555] wlp3s0: authenticate with 00:1f:3f:15:f4:2d
[73532.071953] wlp3s0: send auth to 00:1f:3f:15:f4:2d (try 1/3)
[73532.076262] wlp3s0: authenticated
[73532.685942] iwlwifi 0000:03:00.0: No association and the time event is over already...
[73532.685978] wlp3s0: Connection to AP 00:1f:3f:15:f4:2d lost
[73537.075125] wlp3s0: aborting authentication with 00:1f:3f:15:f4:2d by local choice (Reason: 3=DEAUTH_LEAVING)
[73538.527078] wlp3s0: authenticate with 00:1f:3f:15:f4:2d
[73538.531875] wlp3s0: send auth to 00:1f:3f:15:f4:2d (try 1/3)
[73538.535537] wlp3s0: authenticated
[73539.145858] iwlwifi 0000:03:00.0: No association and the time event is over already...
[73539.145912] wlp3s0: Connection to AP 00:1f:3f:15:f4:2d lost
[73543.535149] wlp3s0: aborting authentication with 00:1f:3f:15:f4:2d by local choice (Reason: 3=DEAUTH_LEAVING)
[73545.477916] wlp3s0: authenticate with 00:1f:3f:15:f4:2d
[73545.482598] wlp3s0: send auth to 00:1f:3f:15:f4:2d (try 1/3)
[73545.486713] wlp3s0: authenticated
[73546.096685] iwlwifi 0000:03:00.0: No association and the time event is over already...
[73546.096739] wlp3s0: Connection to AP 00:1f:3f:15:f4:2d lost
[73550.483871] wlp3s0: aborting authentication with 00:1f:3f:15:f4:2d by local choice (Reason: 3=DEAUTH_LEAVING)

Regards,
Eduard.