Re: WiFi constantly changes association

[Johannes Berg <johannes@sipsolutions.net>]

On Tue, 2024-08-27 at 15:09 -0400, Alan Stern wrote:
> 
> Well, I'd prefer to avoid unnecessary roaming because of the short 
> 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 
> minutes, running with wpa_supplicant's -dd option set for verbose 
> debugging.  As of the start of the extract, the system had been 
> associated with an AP for about five minutes.  The log shows a few 
> spontaneous reassociations and some errors.  I hardly understand any of 
> 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-STARTED EAP authentication started
> Aug 27 14:49:06 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
> Aug 27 14:49:06 strephon NetworkManager[978]: <info>  [1724784546.5694] device (wlan0): supplicant interface state: associating -> associated
> Aug 27 14:49:06 strephon NetworkManager[978]: <info>  [1724784546.5695] device (p2p-dev-wlan0): supplicant management interface state: associating -> associated
> Aug 27 14:49:06 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=13
> ...
> Aug 27 14:49:06 strephon NetworkManager[978]: <info>  [1724784546.8164] device (wlan0): supplicant interface state: associated -> 4way_handshake
> Aug 27 14:49:06 strephon NetworkManager[978]: <info>  [1724784546.8165] device (p2p-dev-wlan0): supplicant management interface state: associated -> 4way_handshake
> Aug 27 14:49:06 strephon kernel: iwlwifi 0000:72:00.0: Unhandled alg: 0x707
> Aug 27 14:49:06 strephon wpa_supplicant[5906]: wlan0: WPA: Key negotiation completed with 48:b4:c3:81:b1:a0 [PTK=CCMP GTK=CCMP]
> Aug 27 14:49:06 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-CONNECTED - Connection to 48:b4:c3:81:b1:a0 completed [id=1 id_str=]
> Aug 27 14:49:06 strephon NetworkManager[978]: <info>  [1724784546.8649] device (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-CHANGE above=0 signal=-68 noise=9999 txrate=29200
> Aug 27 14:49:06 strephon NetworkManager[978]: <info>  [1724784546.8660] device (wlan0): ip:dhcp4: restarting
> Aug 27 14:49:06 strephon NetworkManager[978]: <info>  [1724784546.8660] dhcp4 (wlan0): canceled DHCP transaction
> Aug 27 14:49:06 strephon NetworkManager[978]: <info>  [1724784546.8660] dhcp4 (wlan0): activation: beginning transaction (timeout in 45 seconds)
> Aug 27 14:49:06 strephon NetworkManager[978]: <info>  [1724784546.8660] dhcp4 (wlan0): state changed no lease
> Aug 27 14:49:06 strephon NetworkManager[978]: <info>  [1724784546.8661] dhcp4 (wlan0): activation: beginning transaction (timeout in 45 seconds)
> Aug 27 14:49:06 strephon NetworkManager[978]: <info>  [1724784546.8661] device (p2p-dev-wlan0): supplicant management interface state: 4way_handshake -> completed
> Aug 27 14:49:06 strephon NetworkManager[978]: <info>  [1724784546.9397] dhcp4 (wlan0): state changed new lease, address=10.250.66.194, acd pending
> Aug 27 14:49:06 strephon NetworkManager[978]: <info>  [1724784546.9401] dhcp4 (wlan0): state changed new lease, address=10.250.66.194

and also with DHCP from NetworkManager now.

> Aug 27 14:49:06 strephon systemd[1]: Starting NetworkManager-dispatcher.service - Network Manager Script Dispatcher Service...
> Aug 27 14:49:06 strephon systemd[1]: Started NetworkManager-dispatcher.service - Network Manager Script Dispatcher Service.
> Aug 27 14:49:17 strephon systemd[1]: NetworkManager-dispatcher.service: Deactivated successfully.
> Aug 27 14:49:41 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-ADDED 48:b4:c3:80:58:a1 1
> Aug 27 14:49:41 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-ADDED 48:b4:c3:81:c8:e2 1
> Aug 27 14:49:41 strephon wpa_supplicant[5906]: wlan0: SME: Trying to authenticate with 48:b4:c3:81:b8:03 (SSID='Harvard Secure' freq=6215 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=3e:de:7e:33:e6:22)
> Aug 27 14:49:41 strephon kernel: wlan0: send auth to 48:b4:c3:81:b8:03 (try 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