Hi,
a rather odd behavior was noticed with ath11k and EAP. All kind of devices can
successfully connect to the AP and use it perfectly fine for over an hour. But
after 65 minutes, the ath11k firmware suddenly sends an
WMI_PEER_STA_KICKOUT_EVENT - which will be handled by hostapd as
DISASSOC_LOW_ACK. Which means that the connected station will be disconnected.
This was observed with firmware WLAN.HK.2.4.0.1.r1-00026-QCAHKSWPL_SILICONZ-2
and WLAN.HK.2.5.0.1.r1-00004-QCAHKSWPL_SILICONZ-1 (no other firmware was
tested). And all kind of clients (Linux/Windows/Mac, ath9k/iwlwifi/...) were
tested - with the same results.
Interestingly, I can just remove the WMI_PEER_STA_KICKOUT_EVENTID handler and
then I can use the AP for hours. It should also be possible to achieve the
same by setting disassoc_low_ack=0 but I haven't verified this with my
setup yet.
But here the logs for when it actually happens (hostapd, verbose logs):
Fri Jan 15 07:40:15 2021 daemon.debug hostapd: ap2_1: STA a4:34:d9:c4:8a:a1 IEEE 802.1X: Sending EAP Packet (identifier 10)
Fri Jan 15 07:40:15 2021 daemon.debug hostapd: ap2_1: STA a4:34:d9:c4:8a:a1 IEEE 802.1X: received EAP packet (code=2 id=10 len=46) from STA: EAP Response-unknown (25)
Fri Jan 15 07:40:15 2021 daemon.debug hostapd: ap2_1: RADIUS Sending RADIUS message to authentication server
Fri Jan 15 07:40:15 2021 daemon.debug hostapd: ap2_1: RADIUS Next RADIUS client retransmit in 3 seconds
Fri Jan 15 07:40:15 2021 daemon.debug hostapd: ap2_1: RADIUS Received 167 bytes from RADIUS server
Fri Jan 15 07:40:15 2021 daemon.debug hostapd: ap2_1: RADIUS Received RADIUS message
Fri Jan 15 07:40:15 2021 daemon.debug hostapd: ap2_1: STA a4:34:d9:c4:8a:a1 RADIUS: Received RADIUS packet matched with a pending request, round trip time 0.00 sec
Fri Jan 15 07:40:15 2021 daemon.debug hostapd: ap2_1: STA a4:34:d9:c4:8a:a1 IEEE 802.11: binding station to interface 'ap2_1'
Fri Jan 15 07:40:15 2021 daemon.debug hostapd: ap2_1: STA a4:34:d9:c4:8a:a1 IEEE 802.1X: old identity 'steve' updated with User-Name from Access-Accept 'steve'
Fri Jan 15 07:40:15 2021 daemon.debug hostapd: ap2_1: STA a4:34:d9:c4:8a:a1 IEEE 802.1X: decapsulated EAP packet (code=3 id=10 len=4) from RADIUS server: EAP Success
Fri Jan 15 07:40:15 2021 daemon.notice hostapd: ap2_1: CTRL-EVENT-EAP-SUCCESS2 a4:34:d9:c4:8a:a1
Fri Jan 15 07:40:15 2021 daemon.debug hostapd: ap2_1: STA a4:34:d9:c4:8a:a1 IEEE 802.1X: Sending EAP Packet (identifier 10)
Fri Jan 15 07:40:15 2021 daemon.debug hostapd: ap2_1: STA a4:34:d9:c4:8a:a1 WPA: sending 1/4 msg of 4-Way Handshake
Fri Jan 15 07:40:15 2021 daemon.debug hostapd: ap2_1: STA a4:34:d9:c4:8a:a1 WPA: received EAPOL-Key frame (2/4 Pairwise)
Fri Jan 15 07:40:15 2021 daemon.debug hostapd: ap2_1: STA a4:34:d9:c4:8a:a1 WPA: sending 3/4 msg of 4-Way Handshake
Fri Jan 15 07:40:15 2021 daemon.debug hostapd: ap2_1: STA a4:34:d9:c4:8a:a1 WPA: received EAPOL-Key frame (4/4 Pairwise)
Fri Jan 15 07:40:15 2021 daemon.info hostapd: ap2_1: STA a4:34:d9:c4:8a:a1 WPA: pairwise key handshake completed (RSN)
Fri Jan 15 07:40:15 2021 daemon.notice hostapd: ap2_1: AP-STA-CONNECTED a4:34:d9:c4:8a:a1
Fri Jan 15 07:40:15 2021 daemon.debug hostapd: ap2_1: STA a4:34:d9:c4:8a:a1 IEEE 802.1X: authorizing port
Fri Jan 15 07:40:15 2021 daemon.info hostapd: ap2_1: STA a4:34:d9:c4:8a:a1 RADIUS: starting accounting session 4E2531BE1954F4B0
Fri Jan 15 07:40:15 2021 daemon.info hostapd: ap2_1: STA a4:34:d9:c4:8a:a1 IEEE 802.1X: authenticated - EAP type: 25 (unknown)
Fri Jan 15 08:45:16 2021 daemon.info hostapd: ap2_1: STA a4:34:d9:c4:8a:a1 IEEE 802.11: disconnected due to excessive missing ACKs
Fri Jan 15 08:45:16 2021 daemon.notice hostapd: ap2_1: AP-STA-DISCONNECTED a4:34:d9:c4:8a:a1
Fri Jan 15 08:45:16 2021 daemon.debug hostapd: ap2_1: STA a4:34:d9:c4:8a:a1 MLME: MLME-DISASSOCIATE.indication(a4:34:d9:c4:8a:a1, 34)
Fri Jan 15 08:45:16 2021 daemon.debug hostapd: ap2_1: STA a4:34:d9:c4:8a:a1 MLME: MLME-DELETEKEYS.request(a4:34:d9:c4:8a:a1)
Fri Jan 15 08:45:16 2021 kern.info kernel: [ 4096.030938] ath11k c000000.wifi1: Station a4:34:d9:c4:8a:a1 moved to disassociated state
This was tested with hostapd ca8c2bd28ad53f431d6ee60ef754e98cfdb4c17b
(2019-08-08) and 58b384f467224a1d43f3f947fd53e08b019cbcd3 (2020-06-26)
Btw. rekeying was disabled (but also setting it to 900s or 3600s doesn't
change the behavior at all. So here my hostapd config for completeness:
driver=nl80211
logger_syslog=127
logger_syslog_level=0
logger_stdout=127
logger_stdout_level=0
country_code=US
ieee80211d=1
hw_mode=g
beacon_int=100
channel=6
ieee80211n=1
ht_coex=0
ht_capab=[LDPC][SHORT-GI-20][SHORT-GI-40][TX-STBC][RX-STBC1][MAX-AMSDU-7935][DSSS_CCK-40]
interface=ap2_1
ctrl_interface=/var/run/hostapd
ap_isolate=1
bss_load_update_period=60
chan_util_avg_period=600
disassoc_low_ack=1
preamble=1
wmm_enabled=1
ignore_broadcast_ssid=0
uapsd_advertisement_enabled=1
utf8_ssid=1
multi_ap=0
auth_server_addr=192.168.72.101
auth_server_port=1812
auth_server_shared_secret=testing123
eapol_key_index_workaround=1
ieee8021x=1
auth_algs=1
wpa=2
wpa_pairwise=CCMP
ssid=eaptest
bridge=br-lan
wpa_disable_eapol_key_retries=0
wpa_key_mgmt=WPA-EAP
okc=0
disable_pmksa_caching=1
bssid=f8:d9:b8:2e:37:d0
eap_reauth_period=0
The server you see here is just standard freeradius from Debian Buster with
two changes to allow PEAP (without CA) password logins:
diff --git a/freeradius/3.0/clients.conf b/freeradius/3.0/clients.conf
index 9dbc3e9..ec3895e 100644
--- a/freeradius/3.0/clients.conf
+++ b/freeradius/3.0/clients.conf
@@ -238,10 +238,10 @@ client localhost_ipv6 {
# When a client request comes in, the BEST match is chosen.
# i.e. The entry from the smallest possible network.
#
-#client private-network-1 {
-# ipaddr = 192.0.2.0/24
-# secret = testing123-1
-#}
+client private-network-1 {
+ ipaddr = 192.168.0.0/16
+ secret = testing123
+}
#client private-network-2 {
# ipaddr = 198.51.100.0/24
diff --git a/freeradius/3.0/mods-config/files/authorize b/freeradius/3.0/mods-config/files/authorize
index 67e0cd4..bf27365 100644
--- a/freeradius/3.0/mods-config/files/authorize
+++ b/freeradius/3.0/mods-config/files/authorize
@@ -70,7 +70,7 @@
# entry so that no DEFAULT entry will be used, and the user will NOT
# get any attributes in addition to the ones listed here.
#
-#steve Cleartext-Password := "testing"
+steve Cleartext-Password := "testing"
# Service-Type = Framed-User,
# Framed-Protocol = PPP,
# Framed-IP-Address = 172.16.3.33,
Exactly the same software was tested on the same hardware with ath10k - by
replacing the "interface=" with the ath10k (fw QCA9887 10.2.4-1.0-00047).
This worked stable for more than these odd 65 minutes.
Kind regards,
Sven
On Friday, 15 January 2021 15:22:02 CET Sven Eckelmann wrote:
> a rather odd behavior was noticed with ath11k and EAP.
[...]
> Btw. rekeying was disabled (but also setting it to 900s or 3600s doesn't
> change the behavior at all. So here my hostapd config for completeness:
It seems like it also happens after 3900 seconds with PSK. So following
config will also create this problem:
driver=nl80211
logger_syslog=127
logger_syslog_level=0
logger_stdout=127
logger_stdout_level=0
country_code=US
ieee80211d=1
hw_mode=g
beacon_int=100
channel=6
ieee80211n=1
ht_coex=0
ht_capab=[LDPC][SHORT-GI-20][SHORT-GI-40][TX-STBC][RX-STBC1][MAX-AMSDU-7935][DSSS_CCK-40]
interface=ap2_1
ctrl_interface=/var/run/hostapd
ap_isolate=1
bss_load_update_period=60
chan_util_avg_period=600
disassoc_low_ack=1
preamble=1
wmm_enabled=1
ignore_broadcast_ssid=0
uapsd_advertisement_enabled=1
utf8_ssid=1
multi_ap=0
wpa_passphrase=testtest
auth_algs=1
wpa=2
wpa_pairwise=CCMP
ssid=psktest
bridge=br-lan
wpa_disable_eapol_key_retries=0
wpa_key_mgmt=WPA-PSK
okc=0
disable_pmksa_caching=1
bssid=f8:d9:b8:2e:37:d0
And this problem is trivial to see on the AP (with a single client) using the
following patch:
diff --git a/drivers/net/wireless/ath/ath11k/wmi.c b/drivers/net/wireless/ath/ath11k/wmi.c
index 9fa6ff9..d1b2c61 100644
--- a/drivers/net/wireless/ath/ath11k/wmi.c
+++ b/drivers/net/wireless/ath/ath11k/wmi.c
@@ -6504,6 +6504,7 @@ static void ath11k_peer_sta_kickout_event(struct ath11k_base *ab, struct sk_buff
ath11k_dbg(ab, ATH11K_DBG_WMI, "peer sta kickout event %pM",
arg.mac_addr);
+ WARN_ON(1);
ieee80211_report_low_ack(sta, 10);
exit:
Maybe someone knows whether there is already a non upstream (keepalive?) patch
from QCA in their wlan-open repository (in some of the branches) which I might
miss.
Kind regards,
Sven