WiFi constantly changes association

WiFi constantly changes association

[Alan Stern]

The WiFi interface on my laptop is constantly (i.e., every 5 - 10 
minutes or so) changing access point association.  Some of the time 
there is an actual error code in the log (although I don't understand 
it), but not always.  This occurs in a totally static situation: The 
laptop is sitting still on a desk and the access points aren't moving or 
changing.

Can someone help me to find out why this is happening and how I can stop 
it?  Each time a re-assocation occurs, the network connections stop for 
a few seconds.  This can be very annoying when it occurs in the middle 
of a video conference.

Here is a sample extract from the dmesg log:

[ 5924.412721] wlan0: disconnect from AP 48:b4:c3:81:b1:a0 for new auth to 48:b4:c3:81:b7:d3
[ 5924.464823] wlan0: authenticate with 48:b4:c3:81:b7:d3 (local address=3e:de:7e:33:e6:22)
[ 5924.465609] wlan0: send auth to 48:b4:c3:81:b7:d3 (try 1/3)
[ 5924.476258] wlan0: authenticated
[ 5924.476740] wlan0: associate with 48:b4:c3:81:b7:d3 (try 1/3)
[ 5924.485408] wlan0: RX ReassocResp from 48:b4:c3:81:b7:d3 (capab=0x11 status=0 aid=16)
[ 5924.489408] wlan0: associated
[ 5924.489745] wlan0: deauthenticating from 48:b4:c3:81:b7:d3 by local choice (Reason: 13=INVALID_IE)
[ 5926.459344] wlan0: authenticate with 48:b4:c3:81:b1:a0 (local address=3e:de:7e:33:e6:22)
[ 5926.460183] wlan0: send auth to 48:b4:c3:81:b1:a0 (try 1/3)
[ 5926.465654] wlan0: authenticated
[ 5926.466701] wlan0: associate with 48:b4:c3:81:b1:a0 (try 1/3)
[ 5926.474615] wlan0: RX AssocResp from 48:b4:c3:81:b1:a0 (capab=0x111 status=0 aid=16)
[ 5926.478361] wlan0: associated
[ 6007.455887] wlan0: deauthenticating from 48:b4:c3:81:b1:a0 by local choice (Reason: 2=PREV_AUTH_NOT_VALID)
[ 6008.413727] wlan0: authenticate with 48:b4:c3:81:b8:03 (local address=3e:de:7e:33:e6:22)
[ 6008.414588] wlan0: send auth to 48:b4:c3:81:b8:03 (try 1/3)
[ 6008.423586] wlan0: authenticated
[ 6008.425652] wlan0: associate with 48:b4:c3:81:b8:03 (try 1/3)
[ 6008.435906] wlan0: RX AssocResp from 48:b4:c3:81:b8:03 (capab=0x111 status=0 aid=18)
[ 6008.439903] wlan0: associated
[ 6042.021133] wlan0: disconnect from AP 48:b4:c3:81:b8:03 for new auth to 48:b4:c3:81:b1:a0
[ 6042.106585] wlan0: authenticate with 48:b4:c3:81:b1:a0 (local address=3e:de:7e:33:e6:22)
[ 6042.107509] wlan0: send auth to 48:b4:c3:81:b1:a0 (try 1/3)
[ 6042.115457] wlan0: authenticated
[ 6042.116068] wlan0: associate with 48:b4:c3:81:b1:a0 (try 1/3)
[ 6042.125980] wlan0: RX ReassocResp from 48:b4:c3:81:b1:a0 (capab=0x11 status=0 aid=16)
[ 6042.130435] wlan0: associated
[ 6042.131232] wlan0: deauthenticating from 48:b4:c3:81:b1:a0 by local choice (Reason: 13=INVALID_IE)
[ 6042.138005] iwlwifi 0000:72:00.0: Unhandled alg: 0x707
[ 6045.236581] wlan0: authenticate with 48:b4:c3:81:b8:03 (local address=3e:de:7e:33:e6:22)
[ 6045.237429] wlan0: send auth to 48:b4:c3:81:b8:03 (try 1/3)
[ 6045.239528] wlan0: authenticated
[ 6045.240097] wlan0: associate with 48:b4:c3:81:b8:03 (try 1/3)
[ 6045.244380] iwlwifi 0000:72:00.0: Unhandled alg: 0x707
[ 6045.245552] wlan0: RX AssocResp from 48:b4:c3:81:b8:03 (capab=0x1 status=30 aid=0)
[ 6045.245574] wlan0: 48:b4:c3:81:b8:03 rejected association temporarily; comeback duration 4882 TU (4999 ms)
[ 6050.242115] wlan0: aborting association with 48:b4:c3:81:b8:03 by local choice (Reason: 3=DEAUTH_LEAVING)
[ 6051.552052] wlan0: authenticate with 48:b4:c3:81:b7:b3 (local address=3e:de:7e:33:e6:22)
[ 6051.552888] wlan0: send auth to 48:b4:c3:81:b7:b3 (try 1/3)
[ 6051.558910] wlan0: authenticated
[ 6051.561162] wlan0: associate with 48:b4:c3:81:b7:b3 (try 1/3)
[ 6051.568711] wlan0: RX AssocResp from 48:b4:c3:81:b7:b3 (capab=0x1111 status=0 aid=3)
[ 6051.572783] wlan0: associated
[ 6051.645974] wlan0: Limiting TX power to 36 (36 - 0) dBm as advertised by 48:b4:c3:81:b7:b3
[ 6257.740072] wlan0: deauthenticating from 48:b4:c3:81:b7:b3 by local choice (Reason: 2=PREV_AUTH_NOT_VALID)
[ 6258.495979] wlan0: authenticate with 48:b4:c3:81:b1:a0 (local address=3e:de:7e:33:e6:22)
[ 6258.496970] wlan0: send auth to 48:b4:c3:81:b1:a0 (try 1/3)
[ 6258.506457] wlan0: authenticated
[ 6258.508568] wlan0: associate with 48:b4:c3:81:b1:a0 (try 1/3)
[ 6258.516662] wlan0: RX AssocResp from 48:b4:c3:81:b1:a0 (capab=0x111 status=0 aid=16)
[ 6258.520362] wlan0: associated

Is there any way to debug those INVALID_TE and PREV_AUTH_NOT_VALID errors?

Thanks,

Alan Stern

Re: WiFi constantly changes association

[Johannes Berg]

On Mon, 2024-08-26 at 15:06 -0400, Alan Stern wrote:
> 
> Is there any way to debug those INVALID_TE and PREV_AUTH_NOT_VALID errors?
> 

The kernel doesn't use those codes for its own deauth, if that were to
happen, so you'll want to look at the wpa_supplicant log, perhaps
increasing the logging verbosity for it (I think how to do that probably
depends on the distro, and I don't know off the top of my head.)

joahnnes

Re: WiFi constantly changes association

[Johannes Berg]

On Mon, 2024-08-26 at 21:14 +0200, Johannes Berg wrote:
> On Mon, 2024-08-26 at 15:06 -0400, Alan Stern wrote:
> > 
> > Is there any way to debug those INVALID_TE and PREV_AUTH_NOT_VALID errors?
> > 
> 
> The kernel doesn't use those codes for its own deauth, if that were to
> happen, so you'll want to look at the wpa_supplicant log, perhaps
> increasing the logging verbosity for it (I think how to do that probably
> depends on the distro, and I don't know off the top of my head.)
> 

Then again, while what I said is still true, reading the log more
carefully shows that wpa_s decided to roam and then got into those bad
situations that caused it to deauth. So you'd want to figure out why it
decides to roam there.

Or perhaps roaming would be OK, if it weren't for the failures during
it.

johannes

Re: WiFi constantly changes association

[Alan Stern]

On Mon, Aug 26, 2024 at 09:19:46PM +0200, Johannes Berg wrote:
> On Mon, 2024-08-26 at 21:14 +0200, Johannes Berg wrote:
> > On Mon, 2024-08-26 at 15:06 -0400, Alan Stern wrote:
> > > 
> > > Is there any way to debug those INVALID_TE and PREV_AUTH_NOT_VALID errors?
> > > 
> > 
> > The kernel doesn't use those codes for its own deauth, if that were to
> > happen, so you'll want to look at the wpa_supplicant log, perhaps
> > increasing the logging verbosity for it (I think how to do that probably
> > depends on the distro, and I don't know off the top of my head.)
> > 
> 
> Then again, while what I said is still true, reading the log more
> carefully shows that wpa_s decided to roam and then got into those bad
> situations that caused it to deauth. So you'd want to figure out why it
> decides to roam there.
> 
> Or perhaps roaming would be OK, if it weren't for the failures during
> it.

Well, I'd prefer to avoid unnecessary roaming because of the short 
interruptions in service that it causes.

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.

Alan


Aug 27 14:48:56 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-ADDED 48:b4:c3:81:97:41 1
Aug 27 14:48:56 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-ADDED 48:b4:c3:81:ac:33 1
Aug 27 14:48:56 strephon wpa_supplicant[5906]: wlan0: SME: Trying to authenticate with 48:b4:c3:81:b7:d3 (SSID='Harvard Secure' freq=6535 MHz)
Aug 27 14:48:56 strephon kernel: wlan0: disconnect from AP 48:b4:c3:81:b8:03 for new auth to 48:b4:c3:81:b7:d3
Aug 27 14:48:56 strephon kernel: wlan0: authenticate with 48:b4:c3:81:b7:d3 (local address=3e:de:7e:33:e6:22)
Aug 27 14:48:56 strephon kernel: wlan0: send auth to 48:b4:c3:81:b7:d3 (try 1/3)
Aug 27 14:48:56 strephon NetworkManager[978]: <info>  [1724784536.8123] device (wlan0): supplicant interface state: completed -> authenticating
Aug 27 14:48:56 strephon NetworkManager[978]: <info>  [1724784536.8124] device (p2p-dev-wlan0): supplicant management interface state: completed -> authenticating
Aug 27 14:48:56 strephon kernel: wlan0: authenticated
Aug 27 14:48:56 strephon kernel: wlan0: associate with 48:b4:c3:81:b7:d3 (try 1/3)
Aug 27 14:48:56 strephon wpa_supplicant[5906]: nl80211: kernel reports: key not allowed
Aug 27 14:48:56 strephon wpa_supplicant[5906]: FT: Failed to set PTK to the driver
Aug 27 14:48:56 strephon wpa_supplicant[5906]: wlan0: Trying to associate with 48:b4:c3:81:b7:d3 (SSID='Harvard Secure' freq=6535 MHz)
Aug 27 14:48:56 strephon kernel: wlan0: RX ReassocResp from 48:b4:c3:81:b7:d3 (capab=0x11 status=0 aid=16)
Aug 27 14:48:56 strephon NetworkManager[978]: <info>  [1724784536.8326] device (wlan0): supplicant interface state: authenticating -> associating
Aug 27 14:48:56 strephon NetworkManager[978]: <info>  [1724784536.8326] device (p2p-dev-wlan0): supplicant management interface state: authenticating -> associating
Aug 27 14:48:56 strephon kernel: wlan0: associated
Aug 27 14:48:56 strephon kernel: wlan0: deauthenticating from 48:b4:c3:81:b7:d3 by local choice (Reason: 13=INVALID_IE)
Aug 27 14:48:56 strephon wpa_supplicant[5906]: wlan0: FT: RSNE mismatch between Beacon/ProbeResp and FT protocol Reassociation Response frame
Aug 27 14:48:56 strephon wpa_supplicant[5906]: RSNE in Beacon/ProbeResp - hexdump(len=32): 30 1e 01 00 00 0f ac 04 01 00 00 0f ac 04 02 00 00 0f ac 05 00 0f ac 03 e8 00 00 00 00 0f ac 06
Aug 27 14:48:56 strephon wpa_supplicant[5906]: RSNE in FT protocol Reassociation Response frame - hexdump(len=44): 30 2a 01 00 00 0f ac 04 01 00 00 0f ac 04 02 00 00 0f ac 01 00 0f ac 03 e8 00 01 00 ff 84 62 84 5a a3 06 82 4f b4 2d 43 36 76 87 4b
Aug 27 14:48:56 strephon kernel: iwlwifi 0000:72:00.0: Unhandled alg: 0x707
Aug 27 14:48:56 strephon kernel: iwlwifi 0000:72:00.0: Unhandled alg: 0x707
Aug 27 14:48:56 strephon wpa_supplicant[5906]: nl80211: send_event_marker failed: Source based routing not supported
Aug 27 14:48:56 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-DISCONNECTED bssid=48:b4:c3:81:b7:d3 reason=13 locally_generated=1
Aug 27 14:48:56 strephon wpa_supplicant[5906]: wlan0: BSSID 48:b4:c3:81:b7:d3 ignore list count incremented to 3, ignoring for 60 seconds
Aug 27 14:48:56 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-DSCP-POLICY clear_all
Aug 27 14:48:56 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
Aug 27 14:48:56 strephon NetworkManager[978]: <info>  [1724784536.8677] device (wlan0): supplicant interface state: associating -> disconnected
Aug 27 14:48:56 strephon NetworkManager[978]: <info>  [1724784536.8678] device (p2p-dev-wlan0): supplicant management interface state: associating -> disconnected
Aug 27 14:48:56 strephon NetworkManager[978]: <info>  [1724784536.9676] device (wlan0): supplicant interface state: disconnected -> scanning
Aug 27 14:48:56 strephon NetworkManager[978]: <info>  [1724784536.9677] device (p2p-dev-wlan0): supplicant management interface state: disconnected -> scanning
Aug 27 14:49:00 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-ADDED 48:b4:c3:81:b7:e3 1
Aug 27 14:49:00 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:00 strephon kernel: wlan0: authenticate with 48:b4:c3:81:b8:03 (local address=3e:de:7e:33:e6:22)
Aug 27 14:49:00 strephon kernel: wlan0: send auth to 48:b4:c3:81:b8:03 (try 1/3)
Aug 27 14:49:00 strephon NetworkManager[978]: <info>  [1724784540.4148] device (wlan0): supplicant interface state: scanning -> authenticating
Aug 27 14:49:00 strephon NetworkManager[978]: <info>  [1724784540.4148] device (p2p-dev-wlan0): supplicant management interface state: scanning -> authenticating
Aug 27 14:49:00 strephon kernel: wlan0: authenticated
Aug 27 14:49:00 strephon wpa_supplicant[5906]: wlan0: Trying to associate with 48:b4:c3:81:b8:03 (SSID='Harvard Secure' freq=6215 MHz)
Aug 27 14:49:00 strephon NetworkManager[978]: <info>  [1724784540.4170] device (wlan0): supplicant interface state: authenticating -> associating
Aug 27 14:49:00 strephon NetworkManager[978]: <info>  [1724784540.4170] device (p2p-dev-wlan0): supplicant management interface state: authenticating -> associating
Aug 27 14:49:00 strephon kernel: wlan0: associate with 48:b4:c3:81:b8:03 (try 1/3)
Aug 27 14:49:00 strephon kernel: iwlwifi 0000:72:00.0: Unhandled alg: 0x707
Aug 27 14:49:00 strephon kernel: wlan0: RX AssocResp from 48:b4:c3:81:b8:03 (capab=0x1 status=30 aid=0)
Aug 27 14:49:00 strephon kernel: wlan0: 48:b4:c3:81:b8:03 rejected association temporarily; comeback duration 4882 TU (4999 ms)
Aug 27 14:49:05 strephon kernel: wlan0: aborting association with 48:b4:c3:81:b8:03 by local choice (Reason: 3=DEAUTH_LEAVING)
Aug 27 14:49:05 strephon wpa_supplicant[5906]: nl80211: send_event_marker failed: Source based routing not supported
Aug 27 14:49:05 strephon wpa_supplicant[5906]: wlan0: Added BSSID 48:b4:c3:81:b8:03 into ignore list, ignoring for 10 seconds
Aug 27 14:49:05 strephon wpa_supplicant[5906]: wlan0: BSSID 48:b4:c3:81:b8:03 ignore list count incremented to 2, ignoring for 10 seconds
Aug 27 14:49:05 strephon NetworkManager[978]: <info>  [1724784545.4458] device (wlan0): supplicant interface state: associating -> disconnected
Aug 27 14:49:05 strephon NetworkManager[978]: <info>  [1724784545.4459] device (p2p-dev-wlan0): supplicant management interface state: associating -> disconnected
Aug 27 14:49:05 strephon NetworkManager[978]: <info>  [1724784545.9462] device (wlan0): supplicant interface state: disconnected -> scanning
Aug 27 14:49:05 strephon NetworkManager[978]: <info>  [1724784545.9463] device (p2p-dev-wlan0): supplicant management interface state: disconnected -> scanning
Aug 27 14:49:06 strephon wpa_supplicant[5906]: wlan0: SME: Trying to authenticate with 48:b4:c3:81:b1:a0 (SSID='Harvard Secure' freq=5975 MHz)
Aug 27 14:49:06 strephon kernel: wlan0: authenticate with 48:b4:c3:81:b1:a0 (local address=3e:de:7e:33:e6:22)
Aug 27 14:49:06 strephon kernel: wlan0: send auth to 48:b4:c3:81:b1:a0 (try 1/3)
Aug 27 14:49:06 strephon NetworkManager[978]: <info>  [1724784546.5417] device (wlan0): supplicant interface state: scanning -> authenticating
Aug 27 14:49:06 strephon NetworkManager[978]: <info>  [1724784546.5417] device (p2p-dev-wlan0): supplicant management interface state: scanning -> authenticating
Aug 27 14:49:06 strephon kernel: wlan0: authenticated
Aug 27 14:49:06 strephon wpa_supplicant[5906]: wlan0: Trying to associate with 48:b4:c3:81:b1:a0 (SSID='Harvard Secure' freq=5975 MHz)
Aug 27 14:49:06 strephon NetworkManager[978]: <info>  [1724784546.5504] device (wlan0): supplicant interface state: authenticating -> associating
Aug 27 14:49:06 strephon NetworkManager[978]: <info>  [1724784546.5505] device (p2p-dev-wlan0): supplicant management interface state: authenticating -> associating
Aug 27 14:49:06 strephon kernel: wlan0: associate with 48:b4:c3:81:b1:a0 (try 1/3)
Aug 27 14:49:06 strephon kernel: wlan0: RX AssocResp from 48:b4:c3:81:b1:a0 (capab=0x111 status=0 aid=17)
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 wpa_supplicant[5906]: wlan0: CTRL-EVENT-EAP-METHOD EAP vendor 0 method 13 (TLS) selected
Aug 27 14:49:06 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-EAP-PEER-CERT depth=2 subject='/C=US/ST=New Jersey/L=Jersey City/O=The USERTRUST Network/CN=USERTrust RSA Certification Authority' hash=e793c9b02fd8aa13e21c31228accb08119643b749c898964b1746d46c3d4cbd2
Aug 27 14:49:06 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-EAP-PEER-CERT depth=1 subject='/C=US/O=Internet2/CN=InCommon RSA Server CA 2' hash=87e01cc4dd0c9d92a3dbd49092ff13f9cd387445cdc57e5b984e1b7721b5b029
Aug 27 14:49:06 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-EAP-PEER-CERT depth=0 subject='/C=US/ST=Massachusetts/O=President and Fellows of Harvard College/CN=getonline.noc.harvard.edu' hash=3f49c12863e8b1acf739e8ab4c55e165d9466d1ba18287d0ef1ffa1e743a3d88
Aug 27 14:49:06 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-EAP-PEER-ALT depth=0 DNS:getonline.noc.harvard.edu
Aug 27 14:49:06 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-EAP-PEER-ALT depth=0 DNS:autoreg.fas.harvard.edu
Aug 27 14:49:06 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-EAP-PEER-ALT depth=0 DNS:autoreg1-10wa.noc.harvard.edu
Aug 27 14:49:06 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-EAP-PEER-ALT depth=0 DNS:autoreg1-60ox.noc.harvard.edu
Aug 27 14:49:06 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-EAP-PEER-ALT depth=0 DNS:getonline.harvard.edu
Aug 27 14:49:06 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-EAP-PEER-ALT depth=0 DNS:registration.noc.harvard.edu
Aug 27 14:49:06 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-EAP-PEER-ALT depth=0 DNS:sc-cppm-pub1.net.harvard.edu
Aug 27 14:49:06 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-EAP-PEER-ALT depth=0 DNS:sc-cppm-sub1.net.harvard.edu
Aug 27 14:49:06 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-EAP-PEER-ALT depth=0 DNS:sc-cppm-sub10.net.harvard.edu
Aug 27 14:49:06 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-EAP-PEER-ALT depth=0 DNS:sc-cppm-sub11.net.harvard.edu
Aug 27 14:49:06 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-EAP-SUCCESS EAP authentication completed successfully
Aug 27 14:49:06 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-REMOVED 48:b4:c3:81:b1:a0 1
Aug 27 14:49:06 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-ADDED 48:b4:c3:81:b1:a0 1
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
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
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)
Aug 27 14:49:41 strephon NetworkManager[978]: <info>  [1724784581.2208] device (wlan0): supplicant interface state: completed -> authenticating
Aug 27 14:49:41 strephon NetworkManager[978]: <info>  [1724784581.2209] device (p2p-dev-wlan0): supplicant management interface state: completed -> authenticating
Aug 27 14:49:41 strephon kernel: wlan0: authenticated
Aug 27 14:49:41 strephon wpa_supplicant[5906]: nl80211: kernel reports: key not allowed
Aug 27 14:49:41 strephon wpa_supplicant[5906]: FT: Failed to set PTK to the driver
Aug 27 14:49:41 strephon wpa_supplicant[5906]: wlan0: Trying to associate with 48:b4:c3:81:b8:03 (SSID='Harvard Secure' freq=6215 MHz)
Aug 27 14:49:41 strephon kernel: wlan0: associate with 48:b4:c3:81:b8:03 (try 1/3)
Aug 27 14:49:41 strephon NetworkManager[978]: <info>  [1724784581.2321] device (wlan0): supplicant interface state: authenticating -> associating
Aug 27 14:49:41 strephon NetworkManager[978]: <info>  [1724784581.2322] device (p2p-dev-wlan0): supplicant management interface state: authenticating -> associating
Aug 27 14:49:41 strephon kernel: wlan0: RX ReassocResp from 48:b4:c3:81:b8:03 (capab=0x11 status=0 aid=17)
Aug 27 14:49:41 strephon kernel: wlan0: associated
Aug 27 14:49:41 strephon kernel: wlan0: deauthenticating from 48:b4:c3:81:b8:03 by local choice (Reason: 13=INVALID_IE)
Aug 27 14:49:41 strephon wpa_supplicant[5906]: wlan0: FT: RSNE mismatch between Beacon/ProbeResp and FT protocol Reassociation Response frame
Aug 27 14:49:41 strephon wpa_supplicant[5906]: RSNE in Beacon/ProbeResp - hexdump(len=32): 30 1e 01 00 00 0f ac 04 01 00 00 0f ac 04 02 00 00 0f ac 05 00 0f ac 03 e8 00 00 00 00 0f ac 06
Aug 27 14:49:41 strephon wpa_supplicant[5906]: RSNE in FT protocol Reassociation Response frame - hexdump(len=44): 30 2a 01 00 00 0f ac 04 01 00 00 0f ac 04 02 00 00 0f ac 01 00 0f ac 03 e8 00 01 00 8c 34 e8 c2 21 bb 8a 04 04 fa 5b bb 29 23 ed eb
Aug 27 14:49:41 strephon kernel: iwlwifi 0000:72:00.0: Unhandled alg: 0x707
Aug 27 14:49:41 strephon wpa_supplicant[5906]: nl80211: send_event_marker failed: Source based routing not supported
Aug 27 14:49:41 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-DISCONNECTED bssid=48:b4:c3:81:b8:03 reason=13 locally_generated=1
Aug 27 14:49:41 strephon wpa_supplicant[5906]: wlan0: BSSID 48:b4:c3:81:b8:03 ignore list count incremented to 3, ignoring for 60 seconds
Aug 27 14:49:41 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-DSCP-POLICY clear_all
Aug 27 14:49:41 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
Aug 27 14:49:41 strephon NetworkManager[978]: <info>  [1724784581.2793] device (wlan0): supplicant interface state: associating -> disconnected
Aug 27 14:49:41 strephon NetworkManager[978]: <info>  [1724784581.2794] device (p2p-dev-wlan0): supplicant management interface state: associating -> disconnected
Aug 27 14:49:41 strephon NetworkManager[978]: <info>  [1724784581.3794] device (wlan0): supplicant interface state: disconnected -> scanning
Aug 27 14:49:41 strephon NetworkManager[978]: <info>  [1724784581.3795] device (p2p-dev-wlan0): supplicant management interface state: disconnected -> scanning
Aug 27 14:49:44 strephon wpa_supplicant[5906]: wlan0: SME: Trying to authenticate with 48:b4:c3:81:b1:a0 (SSID='Harvard Secure' freq=5975 MHz)
Aug 27 14:49:44 strephon kernel: wlan0: authenticate with 48:b4:c3:81:b1:a0 (local address=3e:de:7e:33:e6:22)
Aug 27 14:49:44 strephon kernel: wlan0: send auth to 48:b4:c3:81:b1:a0 (try 1/3)
Aug 27 14:49:44 strephon NetworkManager[978]: <info>  [1724784584.7189] device (wlan0): supplicant interface state: scanning -> authenticating
Aug 27 14:49:44 strephon NetworkManager[978]: <info>  [1724784584.7189] device (p2p-dev-wlan0): supplicant management interface state: scanning -> authenticating
Aug 27 14:49:44 strephon kernel: wlan0: authenticated
Aug 27 14:49:44 strephon wpa_supplicant[5906]: wlan0: Trying to associate with 48:b4:c3:81:b1:a0 (SSID='Harvard Secure' freq=5975 MHz)
Aug 27 14:49:44 strephon NetworkManager[978]: <info>  [1724784584.7253] device (wlan0): supplicant interface state: authenticating -> associating
Aug 27 14:49:44 strephon NetworkManager[978]: <info>  [1724784584.7254] device (p2p-dev-wlan0): supplicant management interface state: authenticating -> associating
Aug 27 14:49:44 strephon kernel: wlan0: associate with 48:b4:c3:81:b1:a0 (try 1/3)
Aug 27 14:49:44 strephon kernel: wlan0: RX AssocResp from 48:b4:c3:81:b1:a0 (capab=0x111 status=0 aid=17)
Aug 27 14:49:44 strephon kernel: wlan0: associated
Aug 27 14:49:44 strephon wpa_supplicant[5906]: wlan0: Associated with 48:b4:c3:81:b1:a0
Aug 27 14:49:44 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-EAP-STARTED EAP authentication started
Aug 27 14:49:44 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
Aug 27 14:49:44 strephon NetworkManager[978]: <info>  [1724784584.7446] device (wlan0): supplicant interface state: associating -> associated
Aug 27 14:49:44 strephon NetworkManager[978]: <info>  [1724784584.7447] device (p2p-dev-wlan0): supplicant management interface state: associating -> associated
Aug 27 14:49:44 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=13
Aug 27 14:49:44 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-EAP-METHOD EAP vendor 0 method 13 (TLS) selected
Aug 27 14:49:44 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-EAP-SUCCESS EAP authentication completed successfully
Aug 27 14:49:44 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-REMOVED 48:b4:c3:81:b1:a0 1
Aug 27 14:49:44 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-ADDED 48:b4:c3:81:b1:a0 1
Aug 27 14:49:44 strephon NetworkManager[978]: <info>  [1724784584.8524] device (wlan0): supplicant interface state: associated -> 4way_handshake
Aug 27 14:49:44 strephon NetworkManager[978]: <info>  [1724784584.8525] device (p2p-dev-wlan0): supplicant management interface state: associated -> 4way_handshake
Aug 27 14:49:44 strephon wpa_supplicant[5906]: wlan0: WPA: Key negotiation completed with 48:b4:c3:81:b1:a0 [PTK=CCMP GTK=CCMP]
Aug 27 14:49:44 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:44 strephon NetworkManager[978]: <info>  [1724784584.9010] device (wlan0): supplicant interface state: 4way_handshake -> completed
Aug 27 14:49:44 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-SIGNAL-CHANGE above=0 signal=-66 noise=9999 txrate=29200
Aug 27 14:49:44 strephon NetworkManager[978]: <info>  [1724784584.9021] device (wlan0): ip:dhcp4: restarting
Aug 27 14:49:44 strephon NetworkManager[978]: <info>  [1724784584.9022] dhcp4 (wlan0): canceled DHCP transaction
Aug 27 14:49:44 strephon NetworkManager[978]: <info>  [1724784584.9022] dhcp4 (wlan0): activation: beginning transaction (timeout in 45 seconds)
Aug 27 14:49:44 strephon NetworkManager[978]: <info>  [1724784584.9022] dhcp4 (wlan0): state changed no lease
Aug 27 14:49:44 strephon NetworkManager[978]: <info>  [1724784584.9023] dhcp4 (wlan0): activation: beginning transaction (timeout in 45 seconds)
Aug 27 14:49:44 strephon NetworkManager[978]: <info>  [1724784584.9024] device (p2p-dev-wlan0): supplicant management interface state: 4way_handshake -> completed
Aug 27 14:49:46 strephon NetworkManager[978]: <info>  [1724784586.9194] dhcp4 (wlan0): state changed new lease, address=10.250.66.194, acd pending
Aug 27 14:49:46 strephon NetworkManager[978]: <info>  [1724784586.9197] dhcp4 (wlan0): state changed new lease, address=10.250.66.194
Aug 27 14:49:46 strephon systemd[1]: Starting NetworkManager-dispatcher.service - Network Manager Script Dispatcher Service...
Aug 27 14:49:46 strephon systemd[1]: Started NetworkManager-dispatcher.service - Network Manager Script Dispatcher Service.
Aug 27 14:49:53 strephon kernel: wlan0: deauthenticating from 48:b4:c3:81:b1:a0 by local choice (Reason: 2=PREV_AUTH_NOT_VALID)
Aug 27 14:49:54 strephon wpa_supplicant[5906]: nl80211: send_event_marker failed: Source based routing not supported
Aug 27 14:49:54 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-DISCONNECTED bssid=48:b4:c3:81:b1:a0 reason=2 locally_generated=1
Aug 27 14:49:54 strephon wpa_supplicant[5906]: wlan0: Added BSSID 48:b4:c3:81:b1:a0 into ignore list, ignoring for 10 seconds
Aug 27 14:49:54 strephon wpa_supplicant[5906]: wlan0: BSSID 48:b4:c3:81:b1:a0 ignore list count incremented to 2, ignoring for 10 seconds
Aug 27 14:49:54 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-DSCP-POLICY clear_all
Aug 27 14:49:54 strephon NetworkManager[978]: <info>  [1724784594.0228] device (wlan0): supplicant interface state: completed -> disconnected
Aug 27 14:49:54 strephon NetworkManager[978]: <info>  [1724784594.0229] device (p2p-dev-wlan0): supplicant management interface state: completed -> disconnected
Aug 27 14:49:54 strephon NetworkManager[978]: <info>  [1724784594.1210] device (wlan0): supplicant interface state: disconnected -> scanning
Aug 27 14:49:54 strephon NetworkManager[978]: <info>  [1724784594.1210] device (p2p-dev-wlan0): supplicant management interface state: disconnected -> scanning
Aug 27 14:49:54 strephon wpa_supplicant[5906]: wlan0: SME: Trying to authenticate with 48:b4:c3:81:b7:b3 (SSID='Harvard Secure' freq=5220 MHz)
Aug 27 14:49:54 strephon kernel: wlan0: authenticate with 48:b4:c3:81:b7:b3 (local address=3e:de:7e:33:e6:22)
Aug 27 14:49:54 strephon kernel: wlan0: send auth to 48:b4:c3:81:b7:b3 (try 1/3)
Aug 27 14:49:54 strephon wpa_supplicant[5906]: wlan0: Trying to associate with 48:b4:c3:81:b7:b3 (SSID='Harvard Secure' freq=5220 MHz)
Aug 27 14:49:54 strephon kernel: wlan0: authenticated
Aug 27 14:49:54 strephon kernel: wlan0: associate with 48:b4:c3:81:b7:b3 (try 1/3)
Aug 27 14:49:54 strephon NetworkManager[978]: <info>  [1724784594.9699] device (wlan0): supplicant interface state: scanning -> associating
Aug 27 14:49:54 strephon NetworkManager[978]: <info>  [1724784594.9699] device (p2p-dev-wlan0): supplicant management interface state: scanning -> associating
Aug 27 14:49:54 strephon kernel: wlan0: RX AssocResp from 48:b4:c3:81:b7:b3 (capab=0x1111 status=0 aid=3)
Aug 27 14:49:54 strephon kernel: wlan0: associated
Aug 27 14:49:54 strephon wpa_supplicant[5906]: wlan0: Associated with 48:b4:c3:81:b7:b3
Aug 27 14:49:54 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-EAP-STARTED EAP authentication started
Aug 27 14:49:54 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
Aug 27 14:49:54 strephon NetworkManager[978]: <info>  [1724784594.9854] device (wlan0): supplicant interface state: associating -> associated
Aug 27 14:49:54 strephon NetworkManager[978]: <info>  [1724784594.9855] device (p2p-dev-wlan0): supplicant management interface state: associating -> associated
Aug 27 14:49:55 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=13
Aug 27 14:49:55 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-EAP-METHOD EAP vendor 0 method 13 (TLS) selected
Aug 27 14:49:55 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-EAP-SUCCESS EAP authentication completed successfully
Aug 27 14:49:55 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-REMOVED 48:b4:c3:81:b7:d3 1
Aug 27 14:49:55 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-REMOVED 48:b4:c3:81:b7:c3 1
Aug 27 14:49:55 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-REMOVED e8:10:98:7c:2d:42 1
Aug 27 14:49:55 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-REMOVED 54:d7:e3:d9:91:22 1
Aug 27 14:49:55 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-REMOVED 48:b4:c3:81:b1:80 1
Aug 27 14:49:55 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-REMOVED e8:10:98:7c:2d:52 1
Aug 27 14:49:55 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-REMOVED 48:b4:c3:81:b7:f3 1
Aug 27 14:49:55 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-REMOVED 48:b4:c3:81:b1:90 1
Aug 27 14:49:55 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-REMOVED 48:b4:c3:81:af:c3 1
Aug 27 14:49:55 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-REMOVED dc:b7:ac:e3:18:b1 1
Aug 27 14:49:55 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-REMOVED dc:b7:ac:e3:18:a1 1
Aug 27 14:49:55 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-REMOVED 48:b4:c3:81:c7:93 1
Aug 27 14:49:55 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-REMOVED 48:b4:c3:81:cc:33 1
Aug 27 14:49:55 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-REMOVED 54:d7:e3:d9:91:32 1
Aug 27 14:49:55 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-REMOVED 54:d7:e3:d9:91:12 1
Aug 27 14:49:55 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-REMOVED 48:4a:e9:c1:6c:31 1
Aug 27 14:49:55 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-REMOVED 48:b4:c3:81:af:a3 1
Aug 27 14:49:55 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-REMOVED 48:b4:c3:81:97:51 1
Aug 27 14:49:55 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-REMOVED 48:b4:c3:81:c8:c2 1
Aug 27 14:49:55 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-REMOVED 48:b4:c3:81:c8:d2 1
Aug 27 14:49:55 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-REMOVED 48:b4:c3:81:ac:23 1
Aug 27 14:49:55 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-REMOVED 48:b4:c3:81:c1:b2 1
Aug 27 14:49:55 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-REMOVED 48:b4:c3:81:c7:83 1
Aug 27 14:49:55 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-REMOVED 48:b4:c3:81:af:b3 1
Aug 27 14:49:55 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-REMOVED 48:b4:c3:81:97:41 1
Aug 27 14:49:55 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-REMOVED 48:b4:c3:81:ac:33 1
Aug 27 14:49:55 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-REMOVED 48:b4:c3:81:b7:e3 1
Aug 27 14:49:55 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-REMOVED 48:b4:c3:80:58:a1 1
Aug 27 14:49:55 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-REMOVED 48:b4:c3:81:c8:e2 1
Aug 27 14:49:55 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-REMOVED 48:b4:c3:81:b7:b3 1
Aug 27 14:49:55 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-ADDED 48:b4:c3:81:b7:b3 1
Aug 27 14:49:55 strephon NetworkManager[978]: <info>  [1724784595.0976] device (wlan0): supplicant interface state: associated -> 4way_handshake
Aug 27 14:49:55 strephon NetworkManager[978]: <info>  [1724784595.0976] device (p2p-dev-wlan0): supplicant management interface state: associated -> 4way_handshake
Aug 27 14:49:55 strephon wpa_supplicant[5906]: wlan0: WPA: Key negotiation completed with 48:b4:c3:81:b7:b3 [PTK=CCMP GTK=CCMP]
Aug 27 14:49:55 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-CONNECTED - Connection to 48:b4:c3:81:b7:b3 completed [id=1 id_str=]
Aug 27 14:49:55 strephon NetworkManager[978]: <info>  [1724784595.1426] device (wlan0): supplicant interface state: 4way_handshake -> completed
Aug 27 14:49:55 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-SIGNAL-CHANGE above=1 signal=-40 noise=9999 txrate=58500
Aug 27 14:49:55 strephon NetworkManager[978]: <info>  [1724784595.1431] device (wlan0): ip:dhcp4: restarting
Aug 27 14:49:55 strephon NetworkManager[978]: <info>  [1724784595.1498] dhcp4 (wlan0): canceled DHCP transaction
Aug 27 14:49:55 strephon NetworkManager[978]: <info>  [1724784595.1498] dhcp4 (wlan0): activation: beginning transaction (timeout in 45 seconds)
Aug 27 14:49:55 strephon NetworkManager[978]: <info>  [1724784595.1498] dhcp4 (wlan0): state changed no lease
Aug 27 14:49:55 strephon NetworkManager[978]: <info>  [1724784595.1499] dhcp4 (wlan0): activation: beginning transaction (timeout in 45 seconds)
Aug 27 14:49:55 strephon NetworkManager[978]: <info>  [1724784595.1501] device (p2p-dev-wlan0): supplicant management interface state: 4way_handshake -> completed
Aug 27 14:49:55 strephon NetworkManager[978]: <info>  [1724784595.1609] dhcp4 (wlan0): state changed new lease, address=10.250.66.194, acd pending
Aug 27 14:49:55 strephon NetworkManager[978]: <info>  [1724784595.1610] dhcp4 (wlan0): state changed new lease, address=10.250.66.194
Aug 27 14:50:02 strephon kernel: wlan0: deauthenticating from 48:b4:c3:81:b7:b3 by local choice (Reason: 2=PREV_AUTH_NOT_VALID)
Aug 27 14:50:02 strephon wpa_supplicant[5906]: nl80211: send_event_marker failed: Source based routing not supported
Aug 27 14:50:02 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-DISCONNECTED bssid=48:b4:c3:81:b7:b3 reason=2 locally_generated=1
Aug 27 14:50:02 strephon wpa_supplicant[5906]: wlan0: Added BSSID 48:b4:c3:81:b7:b3 into ignore list, ignoring for 10 seconds
Aug 27 14:50:02 strephon wpa_supplicant[5906]: wlan0: BSSID 48:b4:c3:81:b7:b3 ignore list count incremented to 2, ignoring for 10 seconds
Aug 27 14:50:02 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-DSCP-POLICY clear_all
Aug 27 14:50:02 strephon NetworkManager[978]: <info>  [1724784602.2273] device (wlan0): supplicant interface state: completed -> disconnected
Aug 27 14:50:02 strephon NetworkManager[978]: <info>  [1724784602.2275] device (p2p-dev-wlan0): supplicant management interface state: completed -> disconnected
Aug 27 14:50:02 strephon NetworkManager[978]: <info>  [1724784602.3249] device (wlan0): supplicant interface state: disconnected -> scanning
Aug 27 14:50:02 strephon NetworkManager[978]: <info>  [1724784602.3249] device (p2p-dev-wlan0): supplicant management interface state: disconnected -> scanning
Aug 27 14:50:02 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-ADDED 48:b4:c3:81:b7:d3 1
Aug 27 14:50:02 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-ADDED 48:b4:c3:81:b7:c3 1
Aug 27 14:50:02 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-ADDED 48:b4:c3:81:b7:e3 1
Aug 27 14:50:02 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-ADDED 48:b4:c3:81:b7:f3 1
Aug 27 14:50:02 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-ADDED 54:d7:e3:d9:91:22 1
Aug 27 14:50:02 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-ADDED e8:10:98:7c:2d:52 1
Aug 27 14:50:02 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-ADDED 48:b4:c3:81:b1:80 1
Aug 27 14:50:02 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-ADDED e8:10:98:7c:2d:42 1
Aug 27 14:50:02 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-ADDED 48:b4:c3:81:b1:90 1
Aug 27 14:50:02 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-ADDED dc:b7:ac:e3:18:b1 1
Aug 27 14:50:02 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-ADDED dc:b7:ac:e3:18:a1 1
Aug 27 14:50:02 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-ADDED 48:b4:c3:81:c7:93 1
Aug 27 14:50:02 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-ADDED 48:b4:c3:81:af:c3 1
Aug 27 14:50:02 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-ADDED 48:b4:c3:80:58:a1 1
Aug 27 14:50:02 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-ADDED 54:d7:e3:d9:91:32 1
Aug 27 14:50:02 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-ADDED 54:d7:e3:d9:91:12 1
Aug 27 14:50:02 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-ADDED 48:b4:c3:81:af:b3 1
Aug 27 14:50:02 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-ADDED 48:4a:e9:c1:6c:31 1
Aug 27 14:50:02 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-ADDED 48:b4:c3:81:ac:23 1
Aug 27 14:50:02 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-ADDED 48:b4:c3:81:cc:33 1
Aug 27 14:50:02 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-ADDED 48:b4:c3:81:c8:d2 1
Aug 27 14:50:02 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-ADDED 48:b4:c3:81:ac:33 1
Aug 27 14:50:02 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-ADDED 48:b4:c3:81:c8:e2 1
Aug 27 14:50:02 strephon wpa_supplicant[5906]: wlan0: SME: Trying to authenticate with 48:b4:c3:81:b7:d3 (SSID='Harvard Secure' freq=6535 MHz)
Aug 27 14:50:02 strephon kernel: wlan0: authenticate with 48:b4:c3:81:b7:d3 (local address=3e:de:7e:33:e6:22)
Aug 27 14:50:02 strephon kernel: wlan0: send auth to 48:b4:c3:81:b7:d3 (try 1/3)
Aug 27 14:50:02 strephon wpa_supplicant[5906]: wlan0: Trying to associate with 48:b4:c3:81:b7:d3 (SSID='Harvard Secure' freq=6535 MHz)
Aug 27 14:50:02 strephon kernel: wlan0: authenticated
Aug 27 14:50:02 strephon kernel: wlan0: associate with 48:b4:c3:81:b7:d3 (try 1/3)
Aug 27 14:50:02 strephon NetworkManager[978]: <info>  [1724784602.9674] device (wlan0): supplicant interface state: scanning -> authenticating
Aug 27 14:50:02 strephon NetworkManager[978]: <info>  [1724784602.9674] device (p2p-dev-wlan0): supplicant management interface state: scanning -> authenticating
Aug 27 14:50:02 strephon NetworkManager[978]: <info>  [1724784602.9675] device (wlan0): supplicant interface state: authenticating -> associating
Aug 27 14:50:02 strephon NetworkManager[978]: <info>  [1724784602.9675] device (p2p-dev-wlan0): supplicant management interface state: authenticating -> associating
Aug 27 14:50:02 strephon kernel: wlan0: RX AssocResp from 48:b4:c3:81:b7:d3 (capab=0x111 status=0 aid=16)
Aug 27 14:50:02 strephon kernel: wlan0: associated
Aug 27 14:50:02 strephon wpa_supplicant[5906]: wlan0: Associated with 48:b4:c3:81:b7:d3
Aug 27 14:50:02 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-EAP-STARTED EAP authentication started
Aug 27 14:50:02 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
Aug 27 14:50:02 strephon NetworkManager[978]: <info>  [1724784602.9837] device (wlan0): supplicant interface state: associating -> associated
Aug 27 14:50:02 strephon NetworkManager[978]: <info>  [1724784602.9838] device (p2p-dev-wlan0): supplicant management interface state: associating -> associated
Aug 27 14:50:03 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=13
Aug 27 14:50:03 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-EAP-METHOD EAP vendor 0 method 13 (TLS) selected
Aug 27 14:50:03 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-EAP-SUCCESS EAP authentication completed successfully
Aug 27 14:50:03 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-REMOVED 48:b4:c3:81:b7:d3 1
Aug 27 14:50:03 strephon wpa_supplicant[5906]: wlan0: PMKSA-CACHE-ADDED 48:b4:c3:81:b7:d3 1
Aug 27 14:50:03 strephon NetworkManager[978]: <info>  [1724784603.1089] device (wlan0): supplicant interface state: associated -> 4way_handshake
Aug 27 14:50:03 strephon NetworkManager[978]: <info>  [1724784603.1090] device (p2p-dev-wlan0): supplicant management interface state: associated -> 4way_handshake
Aug 27 14:50:03 strephon wpa_supplicant[5906]: wlan0: WPA: Key negotiation completed with 48:b4:c3:81:b7:d3 [PTK=CCMP GTK=CCMP]
Aug 27 14:50:03 strephon wpa_supplicant[5906]: wlan0: Removed BSSID 48:b4:c3:81:b7:d3 from ignore list
Aug 27 14:50:03 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-CONNECTED - Connection to 48:b4:c3:81:b7:d3 completed [id=1 id_str=]
Aug 27 14:50:03 strephon NetworkManager[978]: <info>  [1724784603.1655] device (wlan0): supplicant interface state: 4way_handshake -> completed
Aug 27 14:50:03 strephon wpa_supplicant[5906]: wlan0: CTRL-EVENT-SIGNAL-CHANGE above=1 signal=-43 noise=9999 txrate=245000
Aug 27 14:50:03 strephon NetworkManager[978]: <info>  [1724784603.1665] device (wlan0): ip:dhcp4: restarting
Aug 27 14:50:03 strephon NetworkManager[978]: <info>  [1724784603.1778] dhcp4 (wlan0): canceled DHCP transaction
Aug 27 14:50:03 strephon NetworkManager[978]: <info>  [1724784603.1778] dhcp4 (wlan0): activation: beginning transaction (timeout in 45 seconds)
Aug 27 14:50:03 strephon NetworkManager[978]: <info>  [1724784603.1778] dhcp4 (wlan0): state changed no lease
Aug 27 14:50:03 strephon NetworkManager[978]: <info>  [1724784603.1779] dhcp4 (wlan0): activation: beginning transaction (timeout in 45 seconds)
Aug 27 14:50:03 strephon NetworkManager[978]: <info>  [1724784603.1780] device (p2p-dev-wlan0): supplicant management interface state: 4way_handshake -> completed
Aug 27 14:50:03 strephon NetworkManager[978]: <info>  [1724784603.1851] dhcp4 (wlan0): state changed new lease, address=10.250.66.194, acd pending
Aug 27 14:50:03 strephon NetworkManager[978]: <info>  [1724784603.1853] dhcp4 (wlan0): state changed new lease, address=10.250.66.194
Aug 27 14:50:13 strephon systemd[1]: NetworkManager-dispatcher.service: Deactivated successfully.

Re: WiFi constantly changes association

[Johannes Berg]

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

Re: 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

Re: WiFi constantly changes association

[Johannes Berg]

On Wed, 2024-08-28 at 10:49 +0300, Jouni Malinen wrote:
> 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..

Agree.

>  I did not bother going through
> all the details of the debug log since it seemed to be missing
> something.

Also seems that way, yes, though not sure why.

But for example:

> wpa_supplicant[5906]: wlan0: FT: RSNE mismatch between Beacon/ProbeResp and FT protocol Reassociation Response frame

is something that perhaps could result in an FT-blocklist or something
for the BSSID in question, or perhaps even the whole network since it's
likely to be a single controller/unified installation or so.

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

True.

> Ideally, I'd like to see that from wpa_supplicant stdout
> with -ddt on the command line instead of syslog.

Right ... That needs more arguments to integrate with NetworkManager (or
configuration to have at least dbus), but I'm not sure how exactly
that'd work and how you'd stop the system one.

Actually if it's with systemd then that/journal will log everything from
the stdout/stderr, just not necessarily in the syslog - so perhaps
adding -t in addition to -dd and then using

	journalctl -u wpa_supplicant

would work.

johannes

Re: WiFi constantly changes association

[Jouni Malinen]

On Wed, Aug 28, 2024 at 09:55:09AM +0200, Johannes Berg wrote:
> But for example:
> 
> > wpa_supplicant[5906]: wlan0: FT: RSNE mismatch between Beacon/ProbeResp and FT protocol Reassociation Response frame
> 
> is something that perhaps could result in an FT-blocklist or something
> for the BSSID in question, or perhaps even the whole network since it's
> likely to be a single controller/unified installation or so.

Somehow I managed to miss then entry.. This is something that I'd be
quite interested in getting more details for since this seems to show a
clear interoperability issue with the FT reassociation implementation
between the AP and the STA.. I'd like to see the full wpa_supplicant
debug sequence that started from selecting the AP and how it resulted in
this mismatch.

Is there any idea which AP devices are used in the network? It is
clearly misbehaving if the wpa_supplicant debug log entries are accurate
on what RSNE values it uses:

RSNE in Beacon/ProbeResp - hexdump(len=32): 30 1e 01 00 00 0f ac 04 01 00 00 0f ac 04 02 00 00 0f ac 05 00 0f ac 03 e8 00 00 00 00 0f ac 06
RSNE in FT protocol Reassociation Response frame - hexdump(len=44): 30 2a 01 00 00 0f ac 04 01 00 00 0f ac 04 02 00 00 0f ac 01 00 0f ac 03 e8 00 01 00 ff 84 62 84 5a a3 06 82 4f b4 2d 43 36 76 87 4b

It is expected to add the PMKID entry for FT, but the AP changed its
list of AKM suites (!?) and removed the group management cipher suite.
Such changes are not allowed and the STA has to stop since those would
be a clear indication of an active downgrade attack. While
wpa_supplicant could in theory prevent FT attempts with this AP for some
time from the view point of interoperability workarounds, I'm not
exactly happy about such a change since it could make it easier to
perform various attacks.

As far as the AKM suite lists are concerned, the RSNE from scan results
indicated 00-0F-AC:5 (802.1X with SHA-256) and 00-0F-AC:3 (FT with
802.1X) while the RSNE from Reassocation Response frame indicated
00-0F-AC:1 (802.1X with SHA-1) and 00-0F-AC:3 (FT with 802.1X). This
feels really strange. Either the AP has a really broken FT
implementation or something has messed up with scan results.. Since this
attempt is on the 6 GHz band, I'm assuming the AP has other BSSs on the
2.4 and 5 GHz bands and it might be possible that there are differences
in which AKMs are enabled on different bands. That would be a bit
strange configuration of the AP, but still, possible. It would be nice
to get full scan results that show the RSNE values from all bands.

-- 
Jouni Malinen                                            PGP id EFC895FA

Re: WiFi constantly changes association

[Alan Stern]

[-- Attachment #1: Type: text/plain, Size: 1190 bytes --]

On Wed, Aug 28, 2024 at 09:55:09AM +0200, Johannes Berg wrote:
> On Wed, 2024-08-28 at 10:49 +0300, Jouni Malinen wrote:
> > Ideally, I'd like to see that from wpa_supplicant stdout
> > with -ddt on the command line instead of syslog.
> 
> Right ... That needs more arguments to integrate with NetworkManager (or
> configuration to have at least dbus), but I'm not sure how exactly
> that'd work and how you'd stop the system one.
> 
> Actually if it's with systemd then that/journal will log everything from
> the stdout/stderr, just not necessarily in the syslog - so perhaps
> adding -t in addition to -dd and then using
> 
> 	journalctl -u wpa_supplicant
> 
> would work.

Attached is a compressed file containing a 10-minute section of the 
journalctl output.  wpa_supplicant was running with -ddt and without -s, 
so this should contain all of its output.

Initially both wpa_supplicant and NetworkManager were turned off.  The 
log starts at the time when I turned on wpa_supplicant, and a few 
seconds later, turned on NetworkManager.  An INVALID_IE event occurred 
at timestamp 12:03:59.  The output is so voluminous it's hard to see 
what's really happening, however.

Alan Stern

[-- Attachment #2: wpa-log2.txt.gz --]
[-- Type: application/gzip, Size: 97985 bytes --]

Re: WiFi constantly changes association

[Jouni Malinen]

On Wed, Aug 28, 2024 at 02:02:32PM -0400, Alan Stern wrote:
> Attached is a compressed file containing a 10-minute section of the 
> journalctl output.  wpa_supplicant was running with -ddt and without -s, 
> so this should contain all of its output.
> 
> Initially both wpa_supplicant and NetworkManager were turned off.  The 
> log starts at the time when I turned on wpa_supplicant, and a few 
> seconds later, turned on NetworkManager.  An INVALID_IE event occurred 
> at timestamp 12:03:59.  The output is so voluminous it's hard to see 
> what's really happening, however.

Thanks. This seems to make it clear that the AP has an issue in its FT
implementation at least in the BSS that operates on the 6 GHz band.
Based on the OUI, that AP is from HPE (Aruba?), so I guess I'll check
with them whether this is a known issue.

The log did not include any other attempt to use the FT protocol, so I
could not check whether it could have worked on other bands. However, I
do note that the RSNE from the 5 GHz band is indeed different and
matches the value that the AP included on the 6 GHz band in the
Reassociation Response frame, so this seems to point towards some
implementation or configuration issues on the AP side and that could
result in an issue that is specific to the 6 GHz band.

PS.

The reason for this particular sequence is in the STA first connecting
on the 5 GHz band and wpa_supplicant being configured to use bgscan
to find a better candidate. Background scan from that ends up finding a
6 GHz AP and that has better estimated throughput and wpa_supplicant
decides to roam based on that. Since FT is enabled here, that roam tries
to use FT from the 5 GHz AP to the 6 GHz one and that fails. This
results in the 6 GHz AP getting temporarily disabled and a 5 GHz AP
being selected as the next option. That succeeds with initial FT
mobility domain association (i.e., not using FT protocol). However, now
we get back to that same state where bgscan will find a better AP on 6
GHz and that will result in the same failure..

As far as I can tell, the main issue here is in AP misbehavior. This
could be worked around by disabling FT or bgscan. A potential
wpa_supplicant change could be considered to disable FT protocol for
that specific AP when this type of behavior is detected. I'll talk to
Aruba first to see if I can get a better understanding on what is behind
this AP behavior.

-- 
Jouni Malinen                                            PGP id EFC895FA

Re: WiFi constantly changes association

[Alan Stern]

On Wed, Aug 28, 2024 at 10:00:22PM +0300, Jouni Malinen wrote:
> On Wed, Aug 28, 2024 at 02:02:32PM -0400, Alan Stern wrote:
> > Attached is a compressed file containing a 10-minute section of the 
> > journalctl output.  wpa_supplicant was running with -ddt and without -s, 
> > so this should contain all of its output.
> > 
> > Initially both wpa_supplicant and NetworkManager were turned off.  The 
> > log starts at the time when I turned on wpa_supplicant, and a few 
> > seconds later, turned on NetworkManager.  An INVALID_IE event occurred 
> > at timestamp 12:03:59.  The output is so voluminous it's hard to see 
> > what's really happening, however.
> 
> Thanks. This seems to make it clear that the AP has an issue in its FT
> implementation at least in the BSS that operates on the 6 GHz band.
> Based on the OUI, that AP is from HPE (Aruba?), so I guess I'll check
> with them whether this is a known issue.

Yes, I believe Harvard uses Aruba hardware for their access points.

> The log did not include any other attempt to use the FT protocol, so I
> could not check whether it could have worked on other bands. However, I
> do note that the RSNE from the 5 GHz band is indeed different and
> matches the value that the AP included on the 6 GHz band in the
> Reassociation Response frame, so this seems to point towards some
> implementation or configuration issues on the AP side and that could
> result in an issue that is specific to the 6 GHz band.
> 
> PS.
> 
> The reason for this particular sequence is in the STA first connecting
> on the 5 GHz band and wpa_supplicant being configured to use bgscan
> to find a better candidate. Background scan from that ends up finding a
> 6 GHz AP and that has better estimated throughput and wpa_supplicant
> decides to roam based on that. Since FT is enabled here, that roam tries
> to use FT from the 5 GHz AP to the 6 GHz one and that fails. This
> results in the 6 GHz AP getting temporarily disabled and a 5 GHz AP
> being selected as the next option. That succeeds with initial FT
> mobility domain association (i.e., not using FT protocol). However, now
> we get back to that same state where bgscan will find a better AP on 6
> GHz and that will result in the same failure..

Is there a way to tell wpa_supplicant to ignore APs on the 6-GHz band?

> As far as I can tell, the main issue here is in AP misbehavior. This
> could be worked around by disabling FT or bgscan. A potential
> wpa_supplicant change could be considered to disable FT protocol for
> that specific AP when this type of behavior is detected. I'll talk to
> Aruba first to see if I can get a better understanding on what is behind
> this AP behavior.

Thanks.  If you need more information, let me know.

Alan Stern

Re: WiFi constantly changes association

[Jouni Malinen]

On Wed, Aug 28, 2024 at 03:07:14PM -0400, Alan Stern wrote:
> Is there a way to tell wpa_supplicant to ignore APs on the 6-GHz band?

You can configure a list of allowed frequencies with the freq_list
parameter (space separated list of channel frequencies), so that could
be used to list all the 2.4 and 5 GHz channels. With some drivers, there
might be some other options like the control interface command "SET
setband 2G,5G".

-- 
Jouni Malinen                                            PGP id EFC895FA