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