WiFi constantly changes association

[Jouni Malinen]

On Wed, Aug 28, 2024 at 09:19:05AM +0200, Johannes Berg wrote:
> 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.

That depends on what exactly is failing.. I did not bother going through
all the details of the debug log since it seemed to be missing
something. I did notice one of the APs using comeback mechanism which is
a sign of the STA having an older entry on it and PMF being used. That
is actually not a failure but part of the expected behavior for
protecting against disconnection attacks. One would need to have a full
log from the first initial connection to the point of a failed
reassociation. Ideally, I'd like to see that from wpa_supplicant stdout
with -ddt on the command line instead of syslog.

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

Indeed. That log is not sufficient to debug this.

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

This is clearly missing entries. Maybe something in syslog is filtering
things out? Like I noted above, debug log directly from wpa_supplicant
stdout would be better way of getting a complete log in a form that
could be analyzed without having to guess what exactly happened in this
type of a case.

Something external(?) seemed to do some management of the PMKSA cache
here. It is not what that is. If it is NetworkManager through the
wpa_supplicant D-Bus interface, it is possible that wpa_supplicant does
not log all the details in its debug log. If that is indeed the case, I
would recommend testing this with NM disabled or with a closer look at
NM debug log to see what it is trying to do here. Adding PMKSA cache
entries should not result in roaming, but removing them could if
something is removing the currently used PMKSA entry. I'd expect
wpa_supplicant debug log to include more detaild about that, though.

-- 
Jouni Malinen                                            PGP id EFC895FA