Re: WiFi constantly changes association

On Tue, 2024-08-27 at 15:09 -0400, Alan Stern wrote:
>=20
> Well, I'd prefer to avoid unnecessary roaming because of the short=20
> interruptions in service that it causes.

Right, but the interruptions for you are much longer because it _fails_.
Perhaps wpa_supplicant should remember that, and not attempt to use FT
when it keeps failing.

> Below is an extract from the system log for a period of about two=20
> minutes, running with wpa_supplicant's -dd option set for verbose=20
> debugging.  As of the start of the extract, the system had been=20
> associated with an AP for about five minutes.  The log shows a few=20
> spontaneous reassociations and some errors.  I hardly understand any of=
=20
> it, so thanks for your efforts to make sense of what it shows.

I'm not sure I understand it either ... I don't see anything that
_caused_ the roaming.

> [snip]

I'll skip that since I don't know if it's complete, or what came before.
There are some failed transitions there, but eventually it's connected
again:

> Aug 27 14:49:06 strephon kernel: wlan0: associated
> Aug 27 14:49:06 strephon wpa_supplicant[5906]: wlan0: Associated with 48:=
b4:c3:81:b1:a0
> Aug 27 14:49:06 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-EAP-STAR=
TED EAP authentication started
> Aug 27 14:49:06 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-SUBNET-S=
TATUS-UPDATE status=3D0
> Aug 27 14:49:06 strephon NetworkManager[978]: <info>  [1724784546.5694] d=
evice (wlan0): supplicant interface state: associating -> associated
> Aug 27 14:49:06 strephon NetworkManager[978]: <info>  [1724784546.5695] d=
evice (p2p-dev-wlan0): supplicant management interface state: associating -=
> associated
> Aug 27 14:49:06 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-EAP-PROP=
OSED-METHOD vendor=3D0 method=3D13
> ...
> Aug 27 14:49:06 strephon NetworkManager[978]: <info>  [1724784546.8164] d=
evice (wlan0): supplicant interface state: associated -> 4way_handshake
> Aug 27 14:49:06 strephon NetworkManager[978]: <info>  [1724784546.8165] d=
evice (p2p-dev-wlan0): supplicant management interface state: associated ->=
 4way_handshake
> Aug 27 14:49:06 strephon kernel: iwlwifi 0000:72:00.0: Unhandled alg: 0x7=
07
> Aug 27 14:49:06 strephon wpa_supplicant[5906]: wlan0: WPA: Key negotiatio=
n completed with 48:b4:c3:81:b1:a0 [PTK=3DCCMP GTK=3DCCMP]
> Aug 27 14:49:06 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-CONNECTE=
D - Connection to 48:b4:c3:81:b1:a0 completed [id=3D1 id_str=3D]
> Aug 27 14:49:06 strephon NetworkManager[978]: <info>  [1724784546.8649] d=
evice (wlan0): supplicant interface state: 4way_handshake -> completed

Now it's fully connected.

> Aug 27 14:49:06 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-SIGNAL-C=
HANGE above=3D0 signal=3D-68 noise=3D9999 txrate=3D29200
> Aug 27 14:49:06 strephon NetworkManager[978]: <info>  [1724784546.8660] d=
evice (wlan0): ip:dhcp4: restarting
> Aug 27 14:49:06 strephon NetworkManager[978]: <info>  [1724784546.8660] d=
hcp4 (wlan0): canceled DHCP transaction
> Aug 27 14:49:06 strephon NetworkManager[978]: <info>  [1724784546.8660] d=
hcp4 (wlan0): activation: beginning transaction (timeout in 45 seconds)
> Aug 27 14:49:06 strephon NetworkManager[978]: <info>  [1724784546.8660] d=
hcp4 (wlan0): state changed no lease
> Aug 27 14:49:06 strephon NetworkManager[978]: <info>  [1724784546.8661] d=
hcp4 (wlan0): activation: beginning transaction (timeout in 45 seconds)
> Aug 27 14:49:06 strephon NetworkManager[978]: <info>  [1724784546.8661] d=
evice (p2p-dev-wlan0): supplicant management interface state: 4way_handshak=
e -> completed
> Aug 27 14:49:06 strephon NetworkManager[978]: <info>  [1724784546.9397] d=
hcp4 (wlan0): state changed new lease, address=3D10.250.66.194, acd pending
> Aug 27 14:49:06 strephon NetworkManager[978]: <info>  [1724784546.9401] d=
hcp4 (wlan0): state changed new lease, address=3D10.250.66.194

and also with DHCP from NetworkManager now.

> Aug 27 14:49:06 strephon systemd[1]: Starting NetworkManager-dispatcher.s=
ervice - Network Manager Script Dispatcher Service...
> Aug 27 14:49:06 strephon systemd[1]: Started NetworkManager-dispatcher.se=
rvice - Network Manager Script Dispatcher Service.
> Aug 27 14:49:17 strephon systemd[1]: NetworkManager-dispatcher.service: D=
eactivated successfully.
> Aug 27 14:49:41 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-ADDED 4=
8:b4:c3:80:58:a1 1
> Aug 27 14:49:41 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-ADDED 4=
8:b4:c3:81:c8:e2 1
> Aug 27 14:49:41 strephon wpa_supplicant[5906]: wlan0: SME: Trying to auth=
enticate with 48:b4:c3:81:b8:03 (SSID=3D'Harvard Secure' freq=3D6215 MHz)
> Aug 27 14:49:41 strephon kernel: wlan0: disconnect from AP 48:b4:c3:81:b1=
:a0 for new auth to 48:b4:c3:81:b8:03
> Aug 27 14:49:41 strephon kernel: wlan0: authenticate with 48:b4:c3:81:b8:=
03 (local address=3D3e:de:7e:33:e6:22)
> Aug 27 14:49:41 strephon kernel: wlan0: send auth to 48:b4:c3:81:b8:03 (t=
ry 1/3)

But I don't know what causes this? Maybe a higher debug level would show
something here? But also I don't know too much about wpa_supplicant
behaviour, so perhaps someone on the list can chime in what might've
caused it to decide to roam here.

johannes