This stuff is sooo difficult to troubleshoot. I'm moving my phone from one tin box with an AP to the other trying to get stuff to happen, logging syslog and multiple tcpdumps, and then the phone just switches to cellular !@#$%^&*.
I applied some stuff recommended by 802.11r Fast Transition how to understand that FT works? - #134 by 72105 (mostly disabling dhcp and firewall services).
Also a difference from yesterday is that then the APs were in different rooms and I would observe AP#1 -> AP#2 (FT) resulting in no connectivity, then device going back to AP#1 and resuming operation.
Now with the tin cans I have:
- AP#1 -> AP#2 (FT) resulting in no connectivity
- STA disconnects and reconnects to AP#2 using 4-way-HS, no connectivity
- STA repeats disconnect/reconnect, same outcome
- STA eventually finds AP#1 and resumes normal operation
The syslog on AP#2 is as follows. I put blank lines between the phases above.
Sat Sep 10 10:48:14 2022 daemon.err hostapd: nl80211: kernel reports: key addition failed
Sat Sep 10 10:48:14 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb IEEE 802.11: binding station to interface 'wlan1'
Sat Sep 10 10:48:14 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb IEEE 802.11: authentication OK (FT)
Sat Sep 10 10:48:14 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb MLME: MLME-AUTHENTICATE.indication(58:cb:52:38:a3:bb, FT)
Sat Sep 10 10:48:14 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb IEEE 802.11: association OK (aid 1)
Sat Sep 10 10:48:14 2022 daemon.info hostapd: wlan1: STA 58:cb:52:38:a3:bb IEEE 802.11: associated (aid 1)
Sat Sep 10 10:48:14 2022 daemon.notice hostapd: wlan1: AP-STA-CONNECTED 58:cb:52:38:a3:bb
Sat Sep 10 10:48:14 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb MLME: MLME-REASSOCIATE.indication(58:cb:52:38:a3:bb)
Sat Sep 10 10:48:14 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb IEEE 802.11: binding station to interface 'wlan1'
Sat Sep 10 10:48:14 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb WPA: event 6 notification
Sat Sep 10 10:48:15 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb WPA: FT authentication already completed - do not start 4-way handshake
Sat Sep 10 10:48:18 2022 daemon.notice hostapd: wlan1: AP-STA-DISCONNECTED 58:cb:52:38:a3:bb
Sat Sep 10 10:48:18 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb WPA: event 3 notification
Sat Sep 10 10:48:19 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb IEEE 802.1X: unauthorizing port
Sat Sep 10 10:48:19 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb IEEE 802.11: deauthenticated
Sat Sep 10 10:48:19 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb MLME: MLME-DEAUTHENTICATE.indication(58:cb:52:38:a3:bb, 3)
Sat Sep 10 10:48:19 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb MLME: MLME-DELETEKEYS.request(58:cb:52:38:a3:bb)
Sat Sep 10 10:48:21 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb IEEE 802.11: authentication OK (open system)
Sat Sep 10 10:48:21 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb MLME: MLME-AUTHENTICATE.indication(58:cb:52:38:a3:bb, OPEN_SYSTEM)
Sat Sep 10 10:48:21 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb MLME: MLME-DELETEKEYS.request(58:cb:52:38:a3:bb)
Sat Sep 10 10:48:21 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb IEEE 802.11: association OK (aid 1)
Sat Sep 10 10:48:21 2022 daemon.info hostapd: wlan1: STA 58:cb:52:38:a3:bb IEEE 802.11: authenticated
Sat Sep 10 10:48:21 2022 daemon.info hostapd: wlan1: STA 58:cb:52:38:a3:bb IEEE 802.11: associated (aid 1)
Sat Sep 10 10:48:21 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb MLME: MLME-ASSOCIATE.indication(58:cb:52:38:a3:bb)
Sat Sep 10 10:48:21 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb MLME: MLME-DELETEKEYS.request(58:cb:52:38:a3:bb)
Sat Sep 10 10:48:21 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb IEEE 802.11: binding station to interface 'wlan1'
Sat Sep 10 10:48:21 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb WPA: event 1 notification
Sat Sep 10 10:48:21 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb WPA: start authentication
Sat Sep 10 10:48:21 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb IEEE 802.1X: unauthorizing port
Sat Sep 10 10:48:21 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb WPA: sending 1/4 msg of 4-Way Handshake
Sat Sep 10 10:48:21 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb WPA: received EAPOL-Key frame (2/4 Pairwise)
Sat Sep 10 10:48:21 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb WPA: sending 3/4 msg of 4-Way Handshake
Sat Sep 10 10:48:21 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb WPA: received EAPOL-Key frame (4/4 Pairwise)
Sat Sep 10 10:48:21 2022 daemon.notice hostapd: wlan1: AP-STA-CONNECTED 58:cb:52:38:a3:bb
Sat Sep 10 10:48:22 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb IEEE 802.1X: authorizing port
Sat Sep 10 10:48:22 2022 daemon.info hostapd: wlan1: STA 58:cb:52:38:a3:bb RADIUS: starting accounting session 0F21276C4A92770B
Sat Sep 10 10:48:22 2022 daemon.info hostapd: wlan1: STA 58:cb:52:38:a3:bb WPA: pairwise key handshake completed (RSN)
Sat Sep 10 10:48:22 2022 daemon.notice hostapd: wlan1: EAPOL-4WAY-HS-COMPLETED 58:cb:52:38:a3:bb
Sat Sep 10 10:48:39 2022 daemon.notice hostapd: wlan1: AP-STA-DISCONNECTED 58:cb:52:38:a3:bb
Sat Sep 10 10:48:39 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb WPA: event 3 notification
Sat Sep 10 10:48:40 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb IEEE 802.1X: unauthorizing port
Sat Sep 10 10:48:40 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb IEEE 802.11: deauthenticated
Sat Sep 10 10:48:40 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb MLME: MLME-DEAUTHENTICATE.indication(58:cb:52:38:a3:bb, 3)
Sat Sep 10 10:48:40 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb MLME: MLME-DELETEKEYS.request(58:cb:52:38:a3:bb)
Sat Sep 10 10:48:42 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb IEEE 802.11: authentication OK (open system)
Sat Sep 10 10:48:42 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb MLME: MLME-AUTHENTICATE.indication(58:cb:52:38:a3:bb, OPEN_SYSTEM)
Sat Sep 10 10:48:42 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb MLME: MLME-DELETEKEYS.request(58:cb:52:38:a3:bb)
Sat Sep 10 10:48:42 2022 daemon.info hostapd: wlan1: STA 58:cb:52:38:a3:bb IEEE 802.11: authenticated
Sat Sep 10 10:48:42 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb IEEE 802.11: association OK (aid 1)
Sat Sep 10 10:48:42 2022 daemon.info hostapd: wlan1: STA 58:cb:52:38:a3:bb IEEE 802.11: associated (aid 1)
Sat Sep 10 10:48:42 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb MLME: MLME-ASSOCIATE.indication(58:cb:52:38:a3:bb)
Sat Sep 10 10:48:42 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb MLME: MLME-DELETEKEYS.request(58:cb:52:38:a3:bb)
Sat Sep 10 10:48:42 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb IEEE 802.11: binding station to interface 'wlan1'
Sat Sep 10 10:48:42 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb WPA: event 1 notification
Sat Sep 10 10:48:42 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb WPA: start authentication
Sat Sep 10 10:48:42 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb IEEE 802.1X: unauthorizing port
Sat Sep 10 10:48:42 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb WPA: sending 1/4 msg of 4-Way Handshake
Sat Sep 10 10:48:43 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb WPA: received EAPOL-Key frame (2/4 Pairwise)
Sat Sep 10 10:48:43 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb WPA: sending 3/4 msg of 4-Way Handshake
Sat Sep 10 10:48:43 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb WPA: received EAPOL-Key frame (4/4 Pairwise)
Sat Sep 10 10:48:43 2022 daemon.notice hostapd: wlan1: AP-STA-CONNECTED 58:cb:52:38:a3:bb
Sat Sep 10 10:48:43 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb IEEE 802.1X: authorizing port
Sat Sep 10 10:48:43 2022 daemon.info hostapd: wlan1: STA 58:cb:52:38:a3:bb RADIUS: starting accounting session E11037D83998A4F0
Sat Sep 10 10:48:43 2022 daemon.info hostapd: wlan1: STA 58:cb:52:38:a3:bb WPA: pairwise key handshake completed (RSN)
Sat Sep 10 10:48:43 2022 daemon.notice hostapd: wlan1: EAPOL-4WAY-HS-COMPLETED 58:cb:52:38:a3:bb
Sat Sep 10 10:49:01 2022 daemon.notice hostapd: wlan1: AP-STA-DISCONNECTED 58:cb:52:38:a3:bb
Sat Sep 10 10:49:01 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb WPA: event 3 notification
Sat Sep 10 10:49:01 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb IEEE 802.1X: unauthorizing port
Sat Sep 10 10:49:01 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb IEEE 802.11: deauthenticated
Sat Sep 10 10:49:01 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb MLME: MLME-DEAUTHENTICATE.indication(58:cb:52:38:a3:bb, 3)
Sat Sep 10 10:49:01 2022 daemon.debug hostapd: wlan1: STA 58:cb:52:38:a3:bb MLME: MLME-DELETEKEYS.request(58:cb:52:38:a3:bb)
Something that has changed from previous tests is that I see nothing from the STA on the AP's ethernet (or switch port). Dunno whether this has to do with disabling DHCP & firewall or what. Now I also need to tcpdump the wireless interface... It just takes a crazy amount of time to get a clean test run.