I'm running a NetGear WAX220 AP with OpenWrt 23.05.0, and things are generally working, but I have an annoying issue with my phone: every time I reboot the phone, the first association request is rejected by the AP.
The second connection request always works.
I ran a wireshark trace, and the AP sends "Status code: Association request rejected temporarily; try again later (0x001e)" in the first Association Response to my phone.
My setup is a bit peculiar, I'm running OpenWrt in AP mode, PSK2, with a Radius server providing the VLAN to use for each station. I'm using hostapd. If more details for the configuration is required, I'll provide that.
I have checked both association requests (the failed and the successful one) from the phone, and they are identical (apart from TSF, SNR and sequence number).
Also the Radius responses are identical.
In the log I don't fund much information:
First attempt:
Mon Apr 29 12:31:06 2024 daemon.info hostapd: phy1-ap0: STA aa:59:f2:xx:xx:xx RADIUS: VLAN ID 10
Mon Apr 29 12:31:06 2024 daemon.info hostapd: phy1-ap0: STA aa:59:f2:xx:xx:xx IEEE 802.11: authenticated
Second Attempt:
Mon Apr 29 12:32:23 2024 daemon.info hostapd: phy1-ap0: STA aa:59:f2:xx:xx:xx RADIUS: VLAN ID 10
Mon Apr 29 12:32:23 2024 daemon.info hostapd: phy1-ap0: STA aa:59:f2:xx:xx:xx IEEE 802.11: authenticated
Mon Apr 29 12:32:23 2024 daemon.notice hostapd: phy1-ap0: STA-OPMODE-N_SS-CHANGED aa:59:f2:xx:xx:xx 2
Mon Apr 29 12:32:23 2024 daemon.info hostapd: phy1-ap0: STA aa:59:f2:xx:xx:xx IEEE 802.11: associated (aid 6)
Mon Apr 29 12:32:23 2024 daemon.info hostapd: phy1-ap0: STA aa:59:f2:xx:xx:xx RADIUS: starting accounting session 46378A99F30A2FEE
Mon Apr 29 12:32:23 2024 daemon.info hostapd: phy1-ap0: STA aa:59:f2:xx:xx:xx WPA: pairwise key handshake completed (RSN)
Mon Apr 29 12:32:23 2024 daemon.notice hostapd: phy1-ap0: EAPOL-4WAY-HS-COMPLETED aa:59:f2:xx:xx:xx
Does anyone know how i could debug this? Can I increase the hostapd logging?
Thanks,
Thomas
Setting the hostapd log level to 1 (or 0) does not reveal much more information:
First attempt:
Tue Apr 30 18:37:56 2024 daemon.debug hostapd: phy1-ap0: STA aa:59:f2:xx:xx:xx RADIUS: Received RADIUS packet matched with a pending request, round trip time 0.00 sec
Tue Apr 30 18:37:56 2024 daemon.info hostapd: phy1-ap0: STA aa:59:f2:xx:xx:xx RADIUS: VLAN ID 10
Tue Apr 30 18:37:56 2024 daemon.debug hostapd: phy1-ap0: STA aa:59:f2:xx:xx:xx IEEE 802.11: authentication OK (open system)
Tue Apr 30 18:37:56 2024 daemon.debug hostapd: phy1-ap0: STA aa:59:f2:xx:xx:xx WPA: event 0 notification
Tue Apr 30 18:37:56 2024 daemon.debug hostapd: phy1-ap0: STA aa:59:f2:xx:xx:xx MLME: MLME-AUTHENTICATE.indication(aa:59:f2:xx:xx:xx, OPEN_SYSTEM)
Tue Apr 30 18:37:56 2024 daemon.info hostapd: phy1-ap0: STA aa:59:f2:xx:xx:xx IEEE 802.11: authenticated
Tue Apr 30 18:37:56 2024 daemon.debug hostapd: phy1-ap0: STA aa:59:f2:xx:xx:xx IEEE 802.11: association SA Query attempt 1
Tue Apr 30 18:37:57 2024 daemon.debug hostapd: phy1-ap0: STA aa:59:f2:xx:xx:xx IEEE 802.11: association SA Query attempt 2
Tue Apr 30 18:37:57 2024 daemon.debug hostapd: phy1-ap0: STA aa:59:f2:xx:xx:xx IEEE 802.11: association SA Query attempt 3
Tue Apr 30 18:37:57 2024 daemon.debug hostapd: phy1-ap0: STA aa:59:f2:xx:xx:xx IEEE 802.11: association SA Query attempt 4
Tue Apr 30 18:37:57 2024 daemon.debug hostapd: phy1-ap0: STA aa:59:f2:xx:xx:xx IEEE 802.11: association SA Query attempt 5
Tue Apr 30 18:37:57 2024 daemon.debug hostapd: phy1-ap0: STA aa:59:f2:xx:xx:xx IEEE 802.11: association SA Query timed out
Second (successful) one:
Tue Apr 30 18:38:11 2024 daemon.info hostapd: phy1-ap0: STA aa:59:f2:xx:xx:xx RADIUS: VLAN ID 10
Tue Apr 30 18:38:11 2024 daemon.debug hostapd: phy1-ap0: STA aa:59:f2:xx:xx:xx IEEE 802.11: authentication OK (open system)
Tue Apr 30 18:38:11 2024 daemon.debug hostapd: phy1-ap0: STA aa:59:f2:xx:xx:xx WPA: event 0 notification
Tue Apr 30 18:38:11 2024 daemon.debug hostapd: phy1-ap0: STA aa:59:f2:xx:xx:xx MLME: MLME-AUTHENTICATE.indication(aa:59:f2:xx:xx:xx, OPEN_SYSTEM)
Tue Apr 30 18:38:11 2024 daemon.info hostapd: phy1-ap0: STA aa:59:f2:xx:xx:xx IEEE 802.11: authenticated
Tue Apr 30 18:38:11 2024 daemon.debug hostapd: phy1-ap0: STA aa:59:f2:xx:xx:xx IEEE 802.11: association OK (aid 5)
Tue Apr 30 18:38:11 2024 daemon.debug hostapd: phy1-ap0: STA aa:59:f2:xx:xx:xx WPA: event 8 notification
Tue Apr 30 18:38:11 2024 daemon.notice hostapd: phy1-ap0: STA-OPMODE-N_SS-CHANGED aa:59:f2:xx:xx:xx 2
Tue Apr 30 18:38:11 2024 daemon.info hostapd: phy1-ap0: STA aa:59:f2:xx:xx:xx IEEE 802.11: associated (aid 5)
Tue Apr 30 18:38:11 2024 daemon.debug hostapd: phy1-ap0: STA aa:59:f2:xx:xx:xx MLME: MLME-ASSOCIATE.indication(aa:59:f2:xx:xx:xx)
Tue Apr 30 18:38:11 2024 daemon.debug hostapd: phy1-ap0: STA aa:59:f2:xx:xx:xx MLME: MLME-DELETEKEYS.request(aa:59:f2:xx:xx:xx)
Tue Apr 30 18:38:11 2024 daemon.debug hostapd: phy1-ap0: STA aa:59:f2:xx:xx:xx IEEE 802.11: binding station to interface 'phy1-ap0.10'
Tue Apr 30 18:38:11 2024 daemon.debug hostapd: phy1-ap0: STA aa:59:f2:xx:xx:xx WPA: event 1 notification
Tue Apr 30 18:38:11 2024 daemon.debug hostapd: phy1-ap0: STA aa:59:f2:xx:xx:xx WPA: event 4 notification
Tue Apr 30 18:38:11 2024 daemon.debug hostapd: phy1-ap0: STA aa:59:f2:xx:xx:xx WPA: sending 1/4 msg of 4-Way Handshake
Tue Apr 30 18:38:11 2024 daemon.debug hostapd: phy1-ap0: STA aa:59:f2:xx:xx:xx WPA: received EAPOL-Key frame (2/4 Pairwise)
Tue Apr 30 18:38:11 2024 daemon.debug hostapd: phy1-ap0: STA aa:59:f2:xx:xx:xx WPA: sending 3/4 msg of 4-Way Handshake
Tue Apr 30 18:38:11 2024 daemon.debug hostapd: phy1-ap0: STA aa:59:f2:xx:xx:xx WPA: received EAPOL-Key frame (4/4 Pairwise)
Tue Apr 30 18:38:11 2024 daemon.debug hostapd: phy1-ap0: STA aa:59:f2:xx:xx:xx IEEE 802.1X: authorizing port
Tue Apr 30 18:38:11 2024 daemon.info hostapd: phy1-ap0: STA aa:59:f2:xx:xx:xx RADIUS: starting accounting session A06C50C5A7EA8354
Tue Apr 30 18:38:11 2024 daemon.info hostapd: phy1-ap0: STA aa:59:f2:xx:xx:xx WPA: pairwise key handshake completed (RSN)
Tue Apr 30 18:38:11 2024 daemon.notice hostapd: phy1-ap0: EAPOL-4WAY-HS-COMPLETED aa:59:f2:xx:xx:xx
So I was digging around in the hostapd source code and the WLAN_STATUS_ASSOC_REJECTED_TEMPORARILY reason can be sent in a few places. One cause -- in check_sa_query() -- is when MFP is used and the station appears to authenticate twice.
So I disabled the ieee80211w option in /etc/config/wireless restarted the wifi, and as per magic, my Android phone connects at the first attempt after a reboot.
Perhaps MPF is not implemented correctly on my phone or it does not dissociate from the network on reboot.
Whether it is wise to keep 802.11w disabled is a different issue, but at least my initial problem appears to have a plausible explanation.