wpasupplicant 2.9 on eoan breaks wifi connections on arm64, reversion to 2.6-21ubuntu3.2 fixes.

[satmandu]

Summary: Connecting from a RPI4 running on arm64 eoan-server-preinstalled image with current "upstream" raspberry pi foundation kernel 4.19.71 to a WPA2 protected access point (Unifi nanoHD). The wifi connection drops out after ~ ten minutes. Reverting wpasupplicant to disco version keeps that from happening.

Running on arm64 eoan build with kernel from raspberry pi folks ( 4.19.71-v8-g6de367fd7 ) on a rpi4.
lsb_release -rd
Description: Ubuntu Eoan Ermine (development branch)
Release: 19.10

With wpasupplicant 2.9, wifi comes up on boot, but then drops out shortly thereafter.

Reverting wpasupplicant to 2.6-21ubuntu3.2 keeps the wifi connection from dropping out.

wireless driver:
[41385.982747] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6
[41386.000633] brcmfmac: brcmf_c_preinit_dcmds: Firmware: BCM4345/6 wl0: Mar 1 2015 07:29:38 version 7.45.18 (r538002) FWID 01-6a2c8ad4

Logs using journalctl -xe NM_CONNECTION=f7f9f91f-001a-46b5-9acc-038db489a0c8 + NM_DEVICE=wlan0

This is what I get with wpasupplicant 2.9:

Sep 12 12:09:49 rpi4 NetworkManager[25218]: <info> [1568304589.2749] manager: (wlan0): new 802.11 Wi-Fi device (/org/freedesktop/NetworkManager/Devices/7)
Sep 12 12:09:49 rpi4 NetworkManager[25218]: <info> [1568304589.3032] device (wlan0): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'ex
Sep 12 12:09:49 rpi4 NetworkManager[25218]: <info> [1568304589.3937] sup-iface[0x55b0b8faf0,wlan0]: supports 5 scan SSIDs
Sep 12 12:09:49 rpi4 NetworkManager[25218]: <info> [1568304589.3957] device (wlan0): supplicant interface state: starting -> ready
Sep 12 12:09:49 rpi4 NetworkManager[25218]: <info> [1568304589.3974] device (wlan0): state change: unavailable -> disconnected (reason 'supplicant-available', sys-
Sep 12 12:09:55 rpi4 NetworkManager[25218]: <info> [1568304595.9790] device (wlan0): supplicant interface state: ready -> scanning
Sep 12 12:09:58 rpi4 NetworkManager[25218]: <info> [1568304598.7770] device (wlan0): supplicant interface state: scanning -> inactive
Sep 12 12:10:01 rpi4 NetworkManager[25218]: <info> [1568304601.9310] device (wlan0): supplicant interface state: inactive -> scanning
Sep 12 12:10:04 rpi4 NetworkManager[25218]: <info> [1568304604.7332] device (wlan0): supplicant interface state: scanning -> inactive
Sep 12 12:10:15 rpi4 NetworkManager[25218]: <info> [1568304615.5964] device (wlan0): Activation: starting connection 'Manhattan' (f7f9f91f-001a-46b5-9acc-038db489a
Sep 12 12:10:15 rpi4 NetworkManager[25218]: <info> [1568304615.5975] device (wlan0): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'manage
Sep 12 12:10:15 rpi4 NetworkManager[25218]: <info> [1568304615.6018] device (wlan0): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Sep 12 12:10:15 rpi4 NetworkManager[25218]: <info> [1568304615.6027] device (wlan0): Activation: (wifi) access point 'Manhattan' has security, but secrets are requ
Sep 12 12:10:15 rpi4 NetworkManager[25218]: <info> [1568304615.6028] device (wlan0): state change: config -> need-auth (reason 'none', sys-iface-state: 'managed')
Sep 12 12:10:15 rpi4 NetworkManager[25218]: <info> [1568304615.6115] device (wlan0): state change: need-auth -> prepare (reason 'none', sys-iface-state: 'managed')
Sep 12 12:10:15 rpi4 NetworkManager[25218]: <info> [1568304615.6126] device (wlan0): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Sep 12 12:10:15 rpi4 NetworkManager[25218]: <info> [1568304615.6139] device (wlan0): Activation: (wifi) connection 'Manhattan' has security, and secrets exist. No
Sep 12 12:10:15 rpi4 NetworkManager[25218]: <info> [1568304615.6690] device (wlan0): supplicant interface state: inactive -> scanning
Sep 12 12:10:18 rpi4 NetworkManager[25218]: <info> [1568304618.4907] device (wlan0): supplicant interface state: scanning -> disconnected
Sep 12 12:10:18 rpi4 NetworkManager[25218]: <info> [1568304618.6313] device (wlan0): supplicant interface state: disconnected -> scanning
Sep 12 12:10:21 rpi4 NetworkManager[25218]: <info> [1568304621.4490] device (wlan0): supplicant interface state: scanning -> disconnected
Sep 12 12:10:21 rpi4 NetworkManager[25218]: <info> [1568304621.9910] device (wlan0): supplicant interface state: disconnected -> scanning
Sep 12 12:10:24 rpi4 NetworkManager[25218]: <info> [1568304624.8102] device (wlan0): supplicant interface state: scanning -> disconnected
Sep 12 12:10:25 rpi4 NetworkManager[25218]: <info> [1568304625.8531] device (wlan0): supplicant interface state: disconnected -> scanning
Sep 12 12:10:28 rpi4 NetworkManager[25218]: <info> [1568304628.6735] device (wlan0): supplicant interface state: scanning -> disconnected
Sep 12 12:10:28 rpi4 NetworkManager[25218]: <info> [1568304628.9667] device (wlan0): supplicant interface state: disconnected -> scanning
Sep 12 12:10:40 rpi4 NetworkManager[25218]: <warn> [1568304640.9264] device (wlan0): Activation: (wifi) association took too long, failing activation
Sep 12 12:10:40 rpi4 NetworkManager[25218]: <info> [1568304640.9266] device (wlan0): state change: config -> failed (reason 'ssid-not-found', sys-iface-state: 'man
Sep 12 12:10:40 rpi4 NetworkManager[25218]: <warn> [1568304640.9331] device (wlan0): Activation: failed for connection 'Manhattan'
Sep 12 12:10:40 rpi4 NetworkManager[25218]: <info> [1568304640.9354] device (wlan0): state change: failed -> disconnected (reason 'none', sys-iface-state: 'managed
Sep 12 12:10:40 rpi4 NetworkManager[25218]: <info> [1568304640.9431] device (wlan0): supplicant interface state: scanning -> disconnected
Sep 12 12:11:49 rpi4 NetworkManager[25218]: <info> [1568304709.9712] device (wlan0): supplicant interface state: disconnected -> scanning
Sep 12 12:11:52 rpi4 NetworkManager[25218]: <info> [1568304712.7757] device (wlan0): supplicant interface state: scanning -> disconnected

Working output from reverting the driver to 2.6:

Sep 12 12:28:19 rpi4 NetworkManager[6417]: <info> [1568305699.3450] device (wlan0): supplicant interface state: disconnected ->
Sep 12 12:28:19 rpi4 NetworkManager[6417]: <info> [1568305699.3469] device (wlan0): state change: disconnected -> unavailable (
Sep 12 12:28:19 rpi4 NetworkManager[6417]: <info> [1568305699.3538] device (wlan0): supplicant interface state: starting -> dow
Sep 12 12:28:29 rpi4 NetworkManager[6417]: <warn> [1568305709.9282] device (wlan0): re-acquiring supplicant interface (#1).
Sep 12 12:28:29 rpi4 NetworkManager[6417]: <info> [1568305709.9438] sup-iface[0x5578a3aaf0,wlan0]: supports 5 scan SSIDs
Sep 12 12:28:29 rpi4 NetworkManager[6417]: <info> [1568305709.9521] device (wlan0): supplicant interface state: starting -> rea
Sep 12 12:28:29 rpi4 NetworkManager[6417]: <info> [1568305709.9589] device (wlan0): state change: unavailable -> disconnected (
Sep 12 12:28:55 rpi4 NetworkManager[6417]: <info> [1568305735.9986] device (wlan0): Activation: starting connection 'Manhattan'
Sep 12 12:28:56 rpi4 NetworkManager[6417]: <info> [1568305736.0007] device (wlan0): state change: disconnected -> prepare (reas
Sep 12 12:28:56 rpi4 NetworkManager[6417]: <info> [1568305736.0113] device (wlan0): state change: prepare -> config (reason 'no
Sep 12 12:28:56 rpi4 NetworkManager[6417]: <info> [1568305736.0147] device (wlan0): Activation: (wifi) access point 'Manhattan'
Sep 12 12:28:56 rpi4 NetworkManager[6417]: <info> [1568305736.0148] device (wlan0): state change: config -> need-auth (reason '
Sep 12 12:28:56 rpi4 NetworkManager[6417]: <info> [1568305736.0292] device (wlan0): state change: need-auth -> prepare (reason
Sep 12 12:28:56 rpi4 NetworkManager[6417]: <info> [1568305736.0305] device (wlan0): state change: prepare -> config (reason 'no
Sep 12 12:28:56 rpi4 NetworkManager[6417]: <info> [1568305736.0333] device (wlan0): Activation: (wifi) connection 'Manhattan' h
Sep 12 12:28:58 rpi4 NetworkManager[6417]: <info> [1568305738.9713] device (wlan0): supplicant interface state: ready -> scanni
Sep 12 12:29:01 rpi4 NetworkManager[6417]: <info> [1568305741.7865] device (wlan0): supplicant interface state: scanning -> ass
Sep 12 12:29:04 rpi4 NetworkManager[6417]: <info> [1568305744.5812] device (wlan0): supplicant interface state: associating ->
Sep 12 12:29:04 rpi4 NetworkManager[6417]: <info> [1568305744.6819] device (wlan0): supplicant interface state: disconnected ->
Sep 12 12:29:07 rpi4 NetworkManager[6417]: <info> [1568305747.4923] device (wlan0): supplicant interface state: scanning -> ass
Sep 12 12:29:10 rpi4 NetworkManager[6417]: <info> [1568305750.4298] device (wlan0): supplicant interface state: associating ->
Sep 12 12:29:10 rpi4 NetworkManager[6417]: <info> [1568305750.4418] device (wlan0): supplicant interface state: 4-way handshake
Sep 12 12:29:10 rpi4 NetworkManager[6417]: <info> [1568305750.4419] device (wlan0): Activation: (wifi) Stage 2 of 5 (Device Con
Sep 12 12:29:10 rpi4 NetworkManager[6417]: <info> [1568305750.4423] device (wlan0): state change: config -> ip-config (reason '
Sep 12 12:29:10 rpi4 NetworkManager[6417]: <info> [1568305750.4482] dhcp4 (wlan0): activation: beginning transaction (timeout i
Sep 12 12:29:11 rpi4 NetworkManager[6417]: <info> [1568305751.5707] dhcp4 (wlan0): state changed unknown -> bound
Sep 12 12:29:11 rpi4 NetworkManager[6417]: <info> [1568305751.5823] device (wlan0): state change: ip-config -> ip-check (reason
Sep 12 12:29:11 rpi4 NetworkManager[6417]: <info> [1568305751.6165] device (wlan0): state change: ip-check -> secondaries (reas
Sep 12 12:29:11 rpi4 NetworkManager[6417]: <info> [1568305751.6177] device (wlan0): state change: secondaries -> activated (rea
Sep 12 12:29:11 rpi4 NetworkManager[6417]: <info> [1568305751.6327] device (wlan0): Activation: successful, device activated.
Sep 12 12:29:13 rpi4 NetworkManager[6417]: <info> [1568305753.1840] dhcp6 (wlan0): activation: beginning transaction (timeout i
Sep 12 12:29:13 rpi4 NetworkManager[6417]: <info> [1568305753.2105] dhcp6 (wlan0): state changed unknown -> bound

[Julian Andres Klode (juliank)]

I'm not sure the NM log is very useful, a wpa supplicant log would probably be helpful, but no idea on gathering that.

[Julian Andres Klode (juliank)]

If we can find something in wpa's log (however one gets them) and an upstream fix for that, that would be great. If you can, I suggest you try to git bisect the upstream repository from 2.6 to 2.9 and see what commit breaks it.

Please note that custom kernels are not supported, and we can't be sure it's a kernel or a wpa issue, so we'll probably have to wait for official rpi4 support if we can't figure out the cause and fix this way.

[satmandu (satadru-umich)]

Here is the wpa supplicant log, gathered as per: https://gist.github.com/wch/8305204#gistcomment-2477237

https://paste.ubuntu.com/p/Nm7G6STc22/

Note there are 3 sections.
The first section starts with "wpa_supplicant v2.6"
When I upgrade to 2.9 you can see this start with "wpa_supplicant v2.9"
When I revert back to 2.6 you can see "wpa_supplicant v2.6" again.

The wifi disconnects immediately after upgrading to 2.9, and I am able to reconnect to wifi immediately after downgrading to 2.6 using "sudo nmcli con up Manhattan". (That's the name of my network manager connection.)

As to bisecting the changes between 2.6 and 2.9.... That might take a while!

[Launchpad Janitor (janitor)]

[Expired for wpa (Ubuntu) because there has been no activity for 60 days.]