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
