[pkg-wpa-devel] Bug#849875: Attributing the problem to NM after all

Sun Jul 30 18:22:07 UTC 2017

clone 849875 -1
reassign -1 network-manager
retitle -1 WPA usage error: Invalid passphrase character
thanks

On Sat, Jul 01, 2017 at 11:32:28PM +0200, Francesco Poli wrote:
> 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 ?

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.

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.
-------------- next part --------------

Jul 30 19:25:32 idefix NetworkManager[7274]: <info>  [1501435532.6262] manager: startup complete
Jul 30 19:25:32 idefix NetworkManager[7274]: <info>  [1501435532.7215] device (wlan0): disconnecting for new activation request.
Jul 30 19:25:32 idefix NetworkManager[7274]: <info>  [1501435532.7216] device (wlan0): state change: activated -> deactivating (reason 'new-activation', internal state 'managed')
Jul 30 19:25:32 idefix NetworkManager[7274]: <info>  [1501435532.7230] manager: NetworkManager state is now DISCONNECTING
Jul 30 19:25:32 idefix NetworkManager[7274]: <info>  [1501435532.7588] audit: op="connection-activate" uuid="6f48a4fc-94ec-49c0-be4b-6c6e4f9224b7" name="FOO_nomap" pid=1219 uid=1000 result="
Jul 30 19:25:32 idefix nm-dispatcher[7254]: req:6 'connectivity-change': new request (1 scripts)
Jul 30 19:25:32 idefix nm-dispatcher[7254]: req:6 'connectivity-change': start running ordered scripts...
Jul 30 19:25:32 idefix NetworkManager[7274]: <info>  [1501435532.7716] device (wlan0): state change: deactivating -> disconnected (reason 'new-activation', internal state 'managed')
Jul 30 19:25:32 idefix avahi-daemon[697]: Withdrawing address record for fe80::4a5a:b6ff:fedb:b295 on wlan0.
Jul 30 19:25:32 idefix avahi-daemon[697]: Leaving mDNS multicast group on interface wlan0.IPv6 with address fe80::4a5a:b6ff:fedb:b295.
Jul 30 19:25:32 idefix avahi-daemon[697]: Interface wlan0.IPv6 no longer relevant for mDNS.
Jul 30 19:25:32 idefix NetworkManager[7274]: <info>  [1501435532.7942] dhcp4 (wlan0): canceled DHCP transaction, DHCP client pid 7285
Jul 30 19:25:32 idefix NetworkManager[7274]: <info>  [1501435532.7943] dhcp4 (wlan0): state changed bound -> done
Jul 30 19:25:32 idefix wpa_supplicant[6958]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:24:fe:04:fc:bb reason=3 locally_generated=1
Jul 30 19:25:32 idefix wpa_supplicant[6958]: nl80211: Was expecting local disconnect but got another disconnect event first
Jul 30 19:25:32 idefix avahi-daemon[697]: Withdrawing address record for 192.168.0.122 on wlan0.
Jul 30 19:25:32 idefix avahi-daemon[697]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.0.122.
Jul 30 19:25:32 idefix avahi-daemon[697]: Interface wlan0.IPv4 no longer relevant for mDNS.
Jul 30 19:25:32 idefix NetworkManager[7274]: <info>  [1501435532.8124] device (wlan0): set-hw-addr: set MAC address to 56:D8:F2:95:EE:68 (scanning)
Jul 30 19:25:32 idefix wpa_supplicant[6958]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD
Jul 30 19:25:32 idefix NetworkManager[7274]: <info>  [1501435532.8508] manager: NetworkManager state is now DISCONNECTED
Jul 30 19:25:32 idefix NetworkManager[7274]: <info>  [1501435532.8543] device (wlan0): Activation: starting connection 'FOO_nomap' (6f48a4fc-94ec-49c0-be4b-6c6e4f9224b7)
Jul 30 19:25:32 idefix NetworkManager[7274]: <warn>  [1501435532.8597] sup-iface[0x3988ed7a90,wlan0]: connection disconnected (reason -3)
Jul 30 19:25:32 idefix nm-dispatcher[7254]: req:7 'down' [wlan0]: new request (1 scripts)
Jul 30 19:25:32 idefix NetworkManager[7274]: <info>  [1501435532.8600] device (wlan0): supplicant interface state: completed -> disconnected
Jul 30 19:25:32 idefix nm-dispatcher[7254]: req:7 'down' [wlan0]: start running ordered scripts...
Jul 30 19:25:32 idefix NetworkManager[7274]: <info>  [1501435532.8761] device (wlan0): state change: disconnected -> prepare (reason 'none', internal state 'managed')
Jul 30 19:25:32 idefix NetworkManager[7274]: <info>  [1501435532.8783] manager: NetworkManager state is now CONNECTING
Jul 30 19:25:32 idefix ntpdate[7345]: sendto(109.239.58.247): Network is unreachable
Jul 30 19:25:32 idefix NetworkManager[7274]: <info>  [1501435532.8850] device (wlan0): set-hw-addr: reset MAC address to 48:5A:B6:DB:B2:95 (preserve)
Jul 30 19:25:32 idefix NetworkManager[7274]: <info>  [1501435532.8967] device (wlan0): state change: prepare -> config (reason 'none', internal state 'managed')
Jul 30 19:25:32 idefix NetworkManager[7274]: <info>  [1501435532.8990] device (wlan0): Activation: (wifi) access point 'FOO_nomap' has security, but secrets are required.
Jul 30 19:25:32 idefix NetworkManager[7274]: <info>  [1501435532.9002] device (wlan0): state change: config -> need-auth (reason 'none', internal state 'managed')
Jul 30 19:25:32 idefix NetworkManager[7274]: <info>  [1501435532.9428] device (wlan0): state change: need-auth -> prepare (reason 'none', internal state 'managed')
Jul 30 19:25:32 idefix NetworkManager[7274]: <info>  [1501435532.9475] device (wlan0): state change: prepare -> config (reason 'none', internal state 'managed')
Jul 30 19:25:32 idefix NetworkManager[7274]: <info>  [1501435532.9486] device (wlan0): Activation: (wifi) connection 'FOO_nomap' has security, and secrets exist.  No new secrets needed.
Jul 30 19:25:32 idefix NetworkManager[7274]: <info>  [1501435532.9486] Config: added 'ssid' value 'FOO_nomap'
Jul 30 19:25:32 idefix NetworkManager[7274]: <info>  [1501435532.9487] Config: added 'scan_ssid' value '1'
Jul 30 19:25:32 idefix NetworkManager[7274]: <info>  [1501435532.9487] Config: added 'key_mgmt' value 'WPA-PSK'
Jul 30 19:25:32 idefix NetworkManager[7274]: <info>  [1501435532.9488] Config: added 'auth_alg' value 'OPEN'
Jul 30 19:25:32 idefix NetworkManager[7274]: <info>  [1501435532.9488] Config: added 'psk' value '<hidden>'
Jul 30 19:25:32 idefix wpa_supplicant[6958]: Line 0: Invalid passphrase character
Jul 30 19:25:32 idefix NetworkManager[7274]: <warn>  [1501435532.9637] sup-iface[0x3988ed7a90,wlan0]: assoc[0x7fc59400b440]: failure to add network: invalid message format
Jul 30 19:25:32 idefix NetworkManager[7274]: <info>  [1501435532.9639] device (wlan0): state change: config -> failed (reason 'supplicant-failed', internal state 'managed')
Jul 30 19:25:32 idefix NetworkManager[7274]: <info>  [1501435532.9645] manager: NetworkManager state is now DISCONNECTED
Jul 30 19:25:32 idefix NetworkManager[7274]: <warn>  [1501435532.9689] device (wlan0): Activation: failed for connection 'FOO_nomap'