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
