Help to work around hostapd: WPA: group key handshake failed (RSN) after 4 tries, wlan1: AP-STA-DISCONNTED

Installing and Using OpenWrt
1

Can anyone offer hints to fix or work around a bunch of disconnections by hostapd's group rekey operations?

The problem occurs in 17.01.6, 18.06.2 and the following snapshot on an EA3500/E4500. Device specific?

SNAPSHOT r9614-b614954, hostapd-common - 2018-12-02-c2c6c01b-2, kmod-mwl8k - 4.14.105+4.19.23-1-4, mwl8k-firmware - 2018-12-16-211de167-1

Run an EA3500 as an AP, serving around 15 devices in a small open office. The signal level is good, SNR -ge 30. When using the default wpa_group_rekey value 600s, there were a lot of disconnections from failed handshakes (RSN). More than 50% of App requests ended up with a timeout on some clients, such as iPads. Trying different wpa_group_rekey values in wireless and leasetime in dhcp relieved the problem somewhat. The following log focuses on one device during a period of quiet time, with wpa_group_rekey being 3600s and leasetime 3600s as well. The problem/log is at least 15 times bigger/longer. The "WPA: group key handshake failed (RSN) after 4 tries" showed up every hour at 0*:03:30, and then the iPad was re-connected soon after at its request.

Fri Mar 29 05:02:36 2019 daemon.info dnsmasq-dhcp[2946]: DHCPREQUEST(br-lan) 192.168.1.52 11:22:33:44:55:66
Fri Mar 29 05:02:36 2019 daemon.info dnsmasq-dhcp[2946]: DHCPACK(br-lan) 192.168.1.52 11:22:33:44:55:66 iPad
Fri Mar 29 05:03:30 2019 daemon.info hostapd: wlan1: STA 11:22:33:44:55:66 WPA: group key handshake failed (RSN) after 4 tries
Fri Mar 29 05:03:30 2019 daemon.notice hostapd: wlan1: AP-STA-DISCONNECTED 11:22:33:44:55:66
Fri Mar 29 05:03:35 2019 daemon.info hostapd: wlan1: STA 11:22:33:44:55:66 IEEE 802.11: deauthenticated due to local deauth request
Fri Mar 29 05:08:14 2019 daemon.info hostapd: wlan1: STA 11:22:33:44:55:66 IEEE 802.11: authenticated
Fri Mar 29 05:08:14 2019 daemon.info hostapd: wlan1: STA 11:22:33:44:55:66 IEEE 802.11: associated (aid 7)
Fri Mar 29 05:08:14 2019 daemon.notice hostapd: wlan1: AP-STA-CONNECTED 11:22:33:44:55:66
Fri Mar 29 05:08:14 2019 daemon.info hostapd: wlan1: STA 11:22:33:44:55:66 WPA: pairwise key handshake completed (RSN)
Fri Mar 29 05:08:14 2019 daemon.info dnsmasq-dhcp[2946]: DHCPREQUEST(br-lan) 192.168.1.52 11:22:33:44:55:66
Fri Mar 29 05:08:14 2019 daemon.info dnsmasq-dhcp[2946]: DHCPACK(br-lan) 192.168.1.52 11:22:33:44:55:66 iPad
Fri Mar 29 05:38:14 2019 daemon.info dnsmasq-dhcp[2946]: DHCPREQUEST(br-lan) 192.168.1.52 11:22:33:44:55:66
Fri Mar 29 05:38:14 2019 daemon.info dnsmasq-dhcp[2946]: DHCPACK(br-lan) 192.168.1.52 11:22:33:44:55:66 iPad
Fri Mar 29 06:03:30 2019 daemon.info hostapd: wlan1: STA 11:22:33:44:55:66 WPA: group key handshake failed (RSN) after 4 tries
Fri Mar 29 06:03:30 2019 daemon.notice hostapd: wlan1: AP-STA-DISCONNECTED 11:22:33:44:55:66
Fri Mar 29 06:03:35 2019 daemon.info hostapd: wlan1: STA 11:22:33:44:55:66 IEEE 802.11: deauthenticated due to local deauth request
Fri Mar 29 06:04:21 2019 daemon.info hostapd: wlan1: STA 11:22:33:44:55:66 IEEE 802.11: authenticated
Fri Mar 29 06:04:21 2019 daemon.info hostapd: wlan1: STA 11:22:33:44:55:66 IEEE 802.11: associated (aid 2)
Fri Mar 29 06:04:21 2019 daemon.notice hostapd: wlan1: AP-STA-CONNECTED 11:22:33:44:55:66
Fri Mar 29 06:04:21 2019 daemon.info hostapd: wlan1: STA 11:22:33:44:55:66 WPA: pairwise key handshake completed (RSN)
Fri Mar 29 06:04:21 2019 daemon.info dnsmasq-dhcp[2946]: DHCPREQUEST(br-lan) 192.168.1.52 11:22:33:44:55:66
Fri Mar 29 06:04:21 2019 daemon.info dnsmasq-dhcp[2946]: DHCPACK(br-lan) 192.168.1.52 11:22:33:44:55:66 iPad
Fri Mar 29 06:34:21 2019 daemon.info dnsmasq-dhcp[2946]: DHCPREQUEST(br-lan) 192.168.1.52 11:22:33:44:55:66
Fri Mar 29 06:34:21 2019 daemon.info dnsmasq-dhcp[2946]: DHCPACK(br-lan) 192.168.1.52 11:22:33:44:55:66 iPad
Fri Mar 29 07:02:21 2019 daemon.info dnsmasq-dhcp[2946]: DHCPREQUEST(br-lan) 192.168.1.52 11:22:33:44:55:66
Fri Mar 29 07:02:21 2019 daemon.info dnsmasq-dhcp[2946]: DHCPACK(br-lan) 192.168.1.52 11:22:33:44:55:66 iPad
Fri Mar 29 07:03:30 2019 daemon.info hostapd: wlan1: STA 11:22:33:44:55:66 WPA: group key handshake failed (RSN) after 4 tries
Fri Mar 29 07:03:30 2019 daemon.notice hostapd: wlan1: AP-STA-DISCONNECTED 11:22:33:44:55:66
Fri Mar 29 07:03:35 2019 daemon.info hostapd: wlan1: STA 11:22:33:44:55:66 IEEE 802.11: deauthenticated due to local deauth request
Fri Mar 29 07:06:37 2019 daemon.info hostapd: wlan1: STA 11:22:33:44:55:66 IEEE 802.11: authenticated
Fri Mar 29 07:06:37 2019 daemon.info hostapd: wlan1: STA 11:22:33:44:55:66 IEEE 802.11: associated (aid 7)
Fri Mar 29 07:06:37 2019 daemon.notice hostapd: wlan1: AP-STA-CONNECTED 11:22:33:44:55:66
Fri Mar 29 07:06:37 2019 daemon.info hostapd: wlan1: STA 11:22:33:44:55:66 WPA: pairwise key handshake completed (RSN)
Fri Mar 29 07:06:37 2019 daemon.info dnsmasq-dhcp[2946]: DHCPREQUEST(br-lan) 192.168.1.52 11:22:33:44:55:66
Fri Mar 29 07:06:37 2019 daemon.info dnsmasq-dhcp[2946]: DHCPACK(br-lan) 192.168.1.52 11:22:33:44:55:66 iPad
Fri Mar 29 07:36:37 2019 daemon.info dnsmasq-dhcp[2946]: DHCPREQUEST(br-lan) 192.168.1.52 11:22:33:44:55:66
Fri Mar 29 07:36:37 2019 daemon.info dnsmasq-dhcp[2946]: DHCPACK(br-lan) 192.168.1.52 11:22:33:44:55:66 iPad
Fri Mar 29 08:03:30 2019 daemon.info hostapd: wlan1: STA 11:22:33:44:55:66 WPA: group key handshake failed (RSN) after 4 tries
Fri Mar 29 08:03:30 2019 daemon.notice hostapd: wlan1: AP-STA-DISCONNECTED 11:22:33:44:55:66
Fri Mar 29 08:03:35 2019 daemon.info hostapd: wlan1: STA 11:22:33:44:55:66 IEEE 802.11: deauthenticated due to local deauth request
Fri Mar 29 08:04:16 2019 daemon.info hostapd: wlan1: STA 11:22:33:44:55:66 IEEE 802.11: authenticated
Fri Mar 29 08:04:16 2019 daemon.info hostapd: wlan1: STA 11:22:33:44:55:66 IEEE 802.11: associated (aid 3)
Fri Mar 29 08:04:16 2019 daemon.notice hostapd: wlan1: AP-STA-CONNECTED 11:22:33:44:55:66
Fri Mar 29 08:04:16 2019 daemon.info hostapd: wlan1: STA 11:22:33:44:55:66 WPA: pairwise key handshake completed (RSN)
Fri Mar 29 08:04:16 2019 daemon.info dnsmasq-dhcp[2946]: DHCPREQUEST(br-lan) 192.168.1.52 11:22:33:44:55:66
Fri Mar 29 08:04:16 2019 daemon.info dnsmasq-dhcp[2946]: DHCPACK(br-lan) 192.168.1.52 11:22:33:44:55:66 iPad

It seems that every WPA: group key handshake failed.

2

This could be a bug in the drivers for the wifi hardware. As a last resort, you can disable rekeying entirely.

3

Appreciate eduperez' input. It seems that the issue pertains to mac80211 drivers and mobile devices when they are in a power saving mode. I'm prolonging the rekey interval. Unfortunately, there is a security concern/requirement in an office environment.

I see @nbd checked in a couple commits 2 weeks ago:

60659b2d: mac80211: improve the txq scheduling API to deal with driver buffered packets
ca9ad880: mac80211: fix an issue with the TXQ scheduling API and powersave clients

Are they designed to address this issue, failed (RSN) after 4 tries? Running the snapshot from 2 days ago overnight, it appears ~10% of key handshakes completed. Better than failed almost every time.

4

This issue disappeared for me by changing the WiFi to another non-overlapping channel.

5

I have been trying different non-overlapping channels. The failed handshakes still happen. Perhaps my surrounding environments are too noise, each with 30~40 AP's in 2.4 GHz and ~10 in 5 GHz.:worried:

6

Wow that's a lot of APs...!

Are you also using full power on the OpenWrt?

7

I like to use the full power on OpenWrt. With the default option txpower, it sets to 18. Is that the max allowed?

I tried option txpower 19, but iw dev wlan1 info still says txpower 18.00 dBm.

8

What does the web GUI say?

(To install on snapshot: opkg update && opkg install luci)

9

On the Edit page of radio1, the status says Tx-Power: 18 dBm, too.

The Transmit Power menu offers choices up to 23 dBm (199 mW). But when I change to any value higher than 18, the status stays at 18.