#870171 WPA usage error: Invalid passphrase character

Package:
network-manager
Source:
network-manager
Description:
network management framework (daemon and userspace tools)
Submitter:
Steven Monai
Date:
2017-09-23 22:27:04 UTC
Severity:
normal
#870171#5
Date:
2017-01-01 20:59:22 UTC
From:
To:
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.

#870171#10
Date:
2017-01-02 12:04:03 UTC
From:
To:
Hallo,
* Steven Monai [Sun, Jan 01 2017, 12:59:22PM]:

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.

#870171#15
Date:
2017-01-02 16:11:03 UTC
From:
To:
Thanks! How was I not aware of this fantastic resource?
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.

#870171#20
Date:
2017-01-03 18:33:11 UTC
From:
To:
Hallo,
* Steven Monai [Mon, Jan 02 2017, 08:11:03AM]:

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.

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.

Thanks for the report and additional investigation!

Best Regards,
Eduard.

#870171#29
Date:
2017-01-26 17:36:08 UTC
From:
To:
Hi everyone,

I have cherry-picked a few patches from the upstream Git repository.

While I don't have much hope they fix all of your issues, there's still
some chance they do improve the state of things.

Please test this version, ensuring you have the latest NM/wicd/whatever
installed, making sure you don't have misconfigurations with MSCHAPv2 as
in [1], and you have MAC randomisation disabled as in [2].

If by any chance you're not observing your symptoms any longer, please
report here, and if you have enough time, try reverting [2] and seeing
whether that breaks it again or not — and report here again.

Thanks.

[1]:
https://wiki.archlinux.org/index.php/WPA_supplicant#Problems_with_eduroam_and_other_MSCHAPv2_connections

[2]: https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=849077#50

#870171#34
Date:
2017-01-30 05:28:18 UTC
From:
To:
2.5-2+v2.4-3+b1 (I was holding at that version, until now).

I am also using the latest network-manager (1.6.0-1), with the
"wifi.scan-rand-mac-address=no" setting documented in [2].

The result is an improvement over what I was experiencing with the
previous version of wpasupplicant (2.6-2). Specifically, I can now get a
reliable wifi connection with WPA/WPA2 security.

However, when creating a new connection profile in NM (using nmtui), I
do need to "activate" the profile twice before it connects successfully.
What happens is: the first attempt to activate the new connection always
fails after ~25 seconds, but then a second "activate" usually succeeds
immediately. Weird. On subsequent reboots, the connection seems to come
up successfully automatically. So, for me, this version of wpasupplicant
is working adequately.

However, I feel like wpasupplicant 2.5-2+v2.4-3+b1 is still more stable
with my wifi hardware and driver (BCM43228 and broadcom-sta-dkms,
respectively), since it never seems to have any hiccups or problems
activating new connection profiles.

I tried removing "wifi.scan-rand-mac-address=no" from my NM config. It
seems to make wifi reconnections after a reboot to fail quite often (but
not always). So, for now, I am going keep that configuration.

Steven M.

#870171#37
Date:
2017-01-30 15:08:27 UTC
From:
To:
On jueves, 26 de enero de 2017 18:36:08 ART Andrew Shadura wrote:
[snip]

I don't know about [1], but for [2] I still need to turn it off.

#870171#40
Date:
2017-02-26 20:27:44 UTC
From:
To:
#870171#47
Date:
2017-07-01 21:32:28 UTC
From:
To:
Dear Debian wpasupplicant Maintainers,
I noticed that these 3 RC bugs (#849122, #849077, #849875) are marked
as found in wpa/2.6-2, which is now superseded by versions with epoch 2.
What seems to have happened (please correct me, if I am wrong) is that
the upstream version 2.4 was reintroduced into unstable (with epoch 2)
and then migrated to stretch (before the stretch release as stable).

Hence, I would say that those three bugs only affect experimental and
are not in stretch, buster or sid.

Could you please confirm that these 3 bugs should be marked as fixed in
wpa/2:2.4-1 and found in wpa/2:2.6-4 ?

Thanks for your time!
Bye.

#870171#52
Date:
2017-07-30 18:22:07 UTC
From:
To:
clone 849875 -1
reassign -1 network-manager
retitle -1 WPA usage error: Invalid passphrase character
thanks

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.

So I made some experiments. First I saw really weird stuff until I
googled and realized that one MUST NOT run NM when doing anything
manually with wpa_supplicant. Ok, stopped network-manager service.
Stopped wpa_supplicant. Used wpa_passphrase tool to setup
/etc/wpa_supplicant.conf manually. And run wpa_supplicant with that
config manually.

And guess what?  Apart from some warnings, the connection the connection
was established just fine. Works like a charm, perfectly stable
link, no issues whatsoever.

For me, that means: I will purge network-manager now and go old-school
until the problem is fixed.

Successfully initialized wpa_supplicant
ioctl[SIOCSIWENCODEEXT]: Invalid argument
ioctl[SIOCSIWENCODEEXT]: Invalid argument
wlan0: Trying to associate with 00:1f:3f:15:f4:2d (SSID='FOO_nomap' freq=2472 MHz)
wlan0: CTRL-EVENT-DISCONNECTED bssid=00:1f:3f:15:f4:2d reason=0
ioctl[SIOCSIWSCAN]: Device or resource busy
wlan0: CTRL-EVENT-SCAN-FAILED ret=-1 retry=1
wlan0: Associated with 00:00:00:00:00:00
wlan0: WPA: No SSID info found (msg 1 of 4)
wlan0: WPA: No SSID info found (msg 1 of 4)
wlan0: WPA: No SSID info found (msg 1 of 4)
wlan0: WPA: No SSID info found (msg 1 of 4)
wlan0: CTRL-EVENT-DISCONNECTED bssid=00:00:00:00:00:00 reason=0
wlan0: Trying to associate with 00:1f:3f:15:f4:2d (SSID='FOO_nomap' freq=2472 MHz)
wlan0: Associated with 00:1f:3f:15:f4:2d
wlan0: WPA: Key negotiation completed with 00:1f:3f:15:f4:2d [PTK=CCMP GTK=TKIP]
wlan0: CTRL-EVENT-CONNECTED - Connection to 00:1f:3f:15:f4:2d completed [id=0 id_str=]
wlan0: WPA: Group rekeying completed with 00:1f:3f:15:f4:2d [GTK=TKIP]

Regards,
Eduard.

#870171#65
Date:
2017-08-27 11:04:53 UTC
From:
To:
On Sun, 30 Jul 2017 20:22:07 +0200 "Eduard Bloch" <bloch@unix-ag.uni-kl.de> wrote:

Does the password have any special characters?
Can you change the WPA passphrase to something else (say only letters)
and try again?
Please also provide a full debug log from NetworkManager (and
wpasupplicant) when the problem happens.
https://wiki.gnome.org/Projects/NetworkManager/Debugging

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

#870171#72
Date:
2017-09-03 15:37:04 UTC
From:
To:
Hallo,
* Michael Biebl [Sun, Aug 27 2017, 01:04:53PM]:

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.

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?

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.

All Sid.

Best regards,
Eduard.

#870171#79
Date:
2017-09-23 22:18:23 UTC
From:
To:
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.