Ath10k: the dreadful bug "deauthenticated due to inactivity (timer DEAUTH/REMOVE)"

Hi there

I think I am affected by this bug: https://bugs.openwrt.org/index.php?do=details&task_id=2537

It is happening with 5Ghz and 2 different APs (Archer C7 v2 and R7800) that use the same driver (ath10k).

Logs: https://pastebin.com/FAHhu33K

I am using OpenWRT 21.02.1 and this wireless config on both:

config wifi-device 'radio0'
	option type 'mac80211'
	option hwmode '11a'
	option path 'pci0000:00/0000:00:00.0'
	option country 'DE'
	option cell_density '0'
	option disabled '0'
	option txpower '13'
	option htmode 'VHT40'
	option channel '40'
	option log_level '2'
	option beacon_int '100'

config wifi-iface 'wifinet2'
	option device 'radio0'
	option mode 'ap'
	option ssid 'AtomNet'
	option key '*********'
	option network 'lan'
	option encryption 'sae-mixed'
	option dtim_period '3'
	option disassoc_low_ack '0'
	option max_inactivity '3600'

I have tried all possible combinations of 'disassoc_low_ack', 'max_inactivity', disabling inactivity polling, changing channel, setting noscan=1, allowing only WPA2.

I also compiled hostapd from sources and was looking into the code, but I do not really know how to debug this further. Any hints?

I have also read that this could be a "hidden node problem" of the specific Apple devices.

Have you tried if there is a difference ath10k / ath10k-ct?

it happens on both.

Haven't tried ath10k-ct but the open issues do not make me think it would be a great improvement: https://github.com/greearb/ath10k-ct

By the way, I also got this issue: https://github.com/greearb/ath10k-ct/issues/188 " invalid VHT TX rate code 0xff" with the ath10k one.

What it is not clear to me yet is whether it is the driver/firmware that trigger these early timeouts (my configured timeout is 1h and they happen within few seconds instead) or whether it is hostapd with its ap_handle_timer scheduled timer

My issue is exactly like this one: Random disassociation due to inactivity - #8 by wired

As I also see the "event 2 notification" (EVENT_MICHAEL_MIC_FAILURE) in hostapd debug logs, mixed with "event 1 notification" (EVENT_DISASSOC); it only happens when this Apple device goes to sleep.

17:31:16 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: event 1 notification
17:31:19 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: event 2 notification
17:31:20 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: event 1 notification
17:31:22 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: event 2 notification
17:31:24 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: event 1 notification
17:31:26 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: event 2 notification
17:33:29 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: event 1 notification
17:33:32 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: event 2 notification
17:34:04 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: event 1 notification
17:34:06 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: event 2 notification
17:34:07 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: event 1 notification
17:34:28 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: event 2 notification
17:38:13 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: event 1 notification
17:38:43 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: event 2 notification
17:38:45 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: event 1 notification
17:38:48 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: event 2 notification
17:39:04 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: event 1 notification
17:39:19 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: event 2 notification
17:39:20 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: event 1 notification
17:39:22 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: event 2 notification
17:39:23 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: event 1 notification
17:39:26 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: event 2 notification
17:39:27 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: event 1 notification
19:48:39 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: event 2 notification
19:49:58 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: event 1 notification
20:10:59 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: event 2 notification
20:22:23 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: event 1 notification
20:22:51 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: event 2 notification
20:25:01 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: event 1 notification
20:25:15 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: event 2 notification
20:26:06 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: event 1 notification
20:26:15 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: event 2 notification
20:30:15 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: event 1 notification

Cc @wired @Stefan1

This post (11 years ago!) is also interesting: https://community.ui.com/questions/SOLVED-Stations-bulk-disassociation-from-time-to-time-greaterGAP-in-timestamp-hostapd/b952c431-b8c2-454e-97ba-44dbf8c10007 but probably unrelated.

OWRT is using hostapd from it's master branch from 22-05-2021, there have been tons of bug fixes in 7 months so maybe this bug has been fixed.

I am still unable to confirm whether it is a bug in the firmware+driver or hostapd

Try the following...

Uncheck "Disable Inactivity Polling".

Increase the value in "Station inactivity limit".

I have a couple of static devices that were getting kicked when I didn't want them kicked, so that solved it.

It is mentioned in first post, I have already tried that (multiple times); disabling activity polling will directly deauthenticate the STAs without the polling, so it is actually detrimental.

The inactivity limit is precisely always ignored if you checked the timestamps I posted in both dumps. The problem is that event 2 which means there is a mismatch somewhere at TKIP level.

This problem has nothing to do with the inactivity polling, it is just that the ap_handle_timer function is the same for all cases (whether a STA disconnects for inactivity or other reasons). This log message is re-used in hostapd and completely misleading.

Here's the third dump (check timestamps) with even more verbose debugging:

21:16:45 2021 daemon.notice hostapd: wlan0: AP-STA-CONNECTED <Apple_MAC>
21:16:45 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> IEEE 802.1X: authorizing port
21:16:45 2021 daemon.info hostapd: wlan0: STA <Apple_MAC> WPA: pairwise key handshake completed (RSN)
21:16:46 2021 daemon.info dnsmasq-dhcp[2159]: DHCPREQUEST(br-lan) 192.168.1.109 <Apple_MAC>
21:16:46 2021 daemon.info dnsmasq-dhcp[2159]: DHCPACK(br-lan) 192.168.1.109 <Apple_MAC> My iPhone
21:17:14 2021 daemon.notice hostapd: wlan0: AP-STA-DISCONNECTED <Apple_MAC>
21:17:14 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: event 2 notification
21:17:14 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> IEEE 802.1X: unauthorizing port
21:17:14 2021 daemon.info hostapd: wlan0: STA <Apple_MAC> IEEE 802.11: disassociated
21:17:14 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> MLME: MLME-DISASSOCIATE.indication(<Apple_MAC>, 8)
21:17:14 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> MLME: MLME-DELETEKEYS.request(<Apple_MAC>)
21:17:15 2021 daemon.info hostapd: wlan0: STA <Apple_MAC> IEEE 802.11: deauthenticated due to inactivity (timer DEAUTH/REMOVE)
21:17:15 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> MLME: MLME-DEAUTHENTICATE.indication(<Apple_MAC>, 2)
21:17:15 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> MLME: MLME-DELETEKEYS.request(<Apple_MAC>)
21:19:58 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> IEEE 802.11: start SAE authentication (RX commit, status=0 (SUCCESS))
21:19:59 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> IEEE 802.11: SAE authentication (RX confirm, status=0 (SUCCESS))
21:19:59 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> MLME: MLME-AUTHENTICATE.indication(<Apple_MAC>, unknown)
21:19:59 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> MLME: MLME-DELETEKEYS.request(<Apple_MAC>)
21:19:59 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: PMKID found from PMKSA cache eap_type=0 vlan=0
21:19:59 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> IEEE 802.11: association OK (aid 2)
21:19:59 2021 daemon.info hostapd: wlan0: STA <Apple_MAC> IEEE 802.11: associated (aid 2)
21:19:59 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> MLME: MLME-ASSOCIATE.indication(<Apple_MAC>)
21:19:59 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> MLME: MLME-DELETEKEYS.request(<Apple_MAC>)
21:19:59 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> IEEE 802.11: binding station to interface 'wlan0'
21:19:59 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: event 1 notification
21:19:59 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: start authentication
21:19:59 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> IEEE 802.1X: unauthorizing port
21:19:59 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: sending 1/4 msg of 4-Way Handshake
21:19:59 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: received EAPOL-Key frame (2/4 Pairwise)
21:19:59 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: sending 3/4 msg of 4-Way Handshake
21:19:59 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: received EAPOL-Key frame (4/4 Pairwise)
21:19:59 2021 daemon.notice hostapd: wlan0: AP-STA-CONNECTED <Apple_MAC>
21:19:59 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> IEEE 802.1X: authorizing port
21:19:59 2021 daemon.info hostapd: wlan0: STA <Apple_MAC> WPA: pairwise key handshake completed (RSN)
21:19:59 2021 daemon.info dnsmasq-dhcp[2159]: DHCPREQUEST(br-lan) 192.168.1.109 <Apple_MAC>
21:19:59 2021 daemon.info dnsmasq-dhcp[2159]: DHCPACK(br-lan) 192.168.1.109 <Apple_MAC> My iPhone
21:20:31 2021 daemon.notice hostapd: wlan0: AP-STA-DISCONNECTED <Apple_MAC>
21:20:31 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: event 2 notification
21:20:31 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> IEEE 802.1X: unauthorizing port
21:20:31 2021 daemon.info hostapd: wlan0: STA <Apple_MAC> IEEE 802.11: disassociated
21:20:31 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> MLME: MLME-DISASSOCIATE.indication(<Apple_MAC>, 8)
21:20:31 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> MLME: MLME-DELETEKEYS.request(<Apple_MAC>)
21:20:32 2021 daemon.info hostapd: wlan0: STA <Apple_MAC> IEEE 802.11: deauthenticated due to inactivity (timer DEAUTH/REMOVE)
21:20:32 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> MLME: MLME-DEAUTHENTICATE.indication(<Apple_MAC>, 2)
21:20:32 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> MLME: MLME-DELETEKEYS.request(<Apple_MAC>)
21:24:41 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> IEEE 802.11: start SAE authentication (RX commit, status=0 (SUCCESS))
21:24:41 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> IEEE 802.11: SAE authentication (RX confirm, status=0 (SUCCESS))
21:24:41 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> MLME: MLME-AUTHENTICATE.indication(<Apple_MAC>, unknown)
21:24:41 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> MLME: MLME-DELETEKEYS.request(<Apple_MAC>)
21:24:41 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: PMKID found from PMKSA cache eap_type=0 vlan=0
21:24:41 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> IEEE 802.11: association OK (aid 2)
21:24:41 2021 daemon.info hostapd: wlan0: STA <Apple_MAC> IEEE 802.11: associated (aid 2)
21:24:41 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> MLME: MLME-ASSOCIATE.indication(<Apple_MAC>)
21:24:41 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> MLME: MLME-DELETEKEYS.request(<Apple_MAC>)
21:24:41 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> IEEE 802.11: binding station to interface 'wlan0'
21:24:41 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: event 1 notification
21:24:41 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: start authentication
21:24:41 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> IEEE 802.1X: unauthorizing port
21:24:41 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: sending 1/4 msg of 4-Way Handshake
21:24:41 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: received EAPOL-Key frame (2/4 Pairwise)
21:24:41 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: sending 3/4 msg of 4-Way Handshake
21:24:41 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: received EAPOL-Key frame (4/4 Pairwise)
21:24:41 2021 daemon.notice hostapd: wlan0: AP-STA-CONNECTED <Apple_MAC>
21:24:41 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> IEEE 802.1X: authorizing port
21:24:41 2021 daemon.info hostapd: wlan0: STA <Apple_MAC> WPA: pairwise key handshake completed (RSN)
21:24:41 2021 daemon.info dnsmasq-dhcp[2159]: DHCPREQUEST(br-lan) 192.168.1.109 <Apple_MAC>hostapd_timer
21:24:41 2021 daemon.info dnsmasq-dhcp[2159]: DHCPACK(br-lan) 192.168.1.109 <Apple_MAC> My iPhone
21:32:19 2021 daemon.notice hostapd: wlan0: AP-STA-DISCONNECTED <Apple_MAC>
21:32:19 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> WPA: event 2 notification
21:32:19 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> IEEE 802.1X: unauthorizing port
21:32:19 2021 daemon.info hostapd: wlan0: STA <Apple_MAC> IEEE 802.11: disassociated
21:32:19 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> MLME: MLME-DISASSOCIATE.indication(<Apple_MAC>, 8)
21:32:19 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> MLME: MLME-DELETEKEYS.request(<Apple_MAC>)
21:32:20 2021 daemon.info hostapd: wlan0: STA <Apple_MAC> IEEE 802.11: deauthenticated due to inactivity (timer DEAUTH/REMOVE)
21:32:20 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> MLME: MLME-DEAUTHENTICATE.indication(<Apple_MAC>, 2)
21:32:20 2021 daemon.debug hostapd: wlan0: STA <Apple_MAC> MLME: MLME-DELETEKEYS.request(<Apple_MAC>)
1 Like

To be clear, unchecking "Disable Inactivity Polling" enables inactivity polling.

I don't know what value you set for inactivity limit, but mine is set to well over 8 hours, and I haven't had an issue since.

You can also try increasing the value for "Time interval for rekeying GTK".

No:

			if (hapd->conf->skip_inactivity_poll)
				sta->timeout_next = STA_DISASSOC;

When skip_inactivity_poll is 1 (checkbox ticked in LuCI) the code block below the above will be skipped and it will run hostapd_drv_sta_disassoc() a few lines further. It will not do any polling and directly disassociate.

It is in the first post, check my option max_inactivity, it is way higher than what is happening in the logs and I already explained why this is unrelated to inactivity polling.

Already tried that, no changes in behavior.

1 Like

What exactly is your problem, besides the info log entries that tell you, that your devices suspended wifi to save power? The bug report mentions, that after some time no device can connect to the radio anymore, do you experience the same problem?

I have seen this on older R7800 builds, but on current builds I had 30+ days wifi uptime without a single interruption and I have devices that transfer 24 hours and are monitored.

1 Like

Same here.

The log entries do not tell that, I told you that in my comment e.g. that the Apple devices go to sleep. The logs tell about deauth and reauth, happening all the time every 30 seconds or few minutes. This drains battery on affected devices.

No, sometimes the Apple devices do not have internet even if they say they are connected, but it does not happen all the time. The current issue is the one mentioned before (reconnections).

check that

It is unrelated; it happens also with WPA2 only allowed.

i don't see that in your setting

I see, I didn't read the whole thread where you posted another link to the forum "#8 by wired".

OK, so on your side you have issues with apple devices, I have 3 myself and don't experience that.
But I just use defaults on my radios except encryption WPA2/WPA3.

Have you tried with dfferent SSIDs and with normal tx power, if you lower TX power, than it is possible that messages reach the AP, but won't reach the phones, as you only reduce tx power on one side.

1 Like

I use an r7500v2 with ath10k-ct and the htt firmware on master (well master with an experimental DSA patch but i don't think that's relevant). I have 5+ apple devices that use this access point and all usually don't have this issue (the android, linux, and windows devices do not currently have this symptom).

I just check my logs and saw an iphone 11 with the same symptoms you describe.

Checking this iphone, it's battery was low. As soon as i plugged in this device to charge, the frequent log deauth due to inactivity messages stopped. I suspect this case indicates the apple device turning off wifi to save power.

Even if your case is not related to a device related power save "feature", it does seem to be client related and you will have to look there. Perhaps ask "how does one determine if an apple device is initiating a wifi disconnect? (I'd answer but i don't know.)

FWIW I've seen these messages and complaints about them in the past (mostly android and iphone devices), ath10k users start by pointing the finger at the driver/firmware (ct or not), and then there is a quite update to hostapd (or I update my devices) and the symptoms disappear. It will be difficult to identify the reason for these messages with so many wifi factors to look at (router wifi driver, mac80211, hostapd, device wifi, device and router placement, wifi interfearance, etc).

You mention the "hidden node problem" I think meaning the apple devices can not see each other but can see the AP. Have you tried moving the affected apple devices near each other and within line of site of the AP?

HTH

2 Likes

I disabled WPA3 as part of my tests; for example now I run 1 AP with WPA3 possible and one only with WPA2 possible, same symptoms.

I haven't tried with different SSIDs yet; as for power: the device is 3 or 4 metres from the AP the whole day, there's just air in the line of sight between them.

Just to be clear: the malfunction is that an iPhone disconnects "AP-STA-DISCONNECTED", "WPA: event 2 notification" gets logged as well and also "MLME-DISASSOCIATE.indication", then after ~3 seconds it connects again, goes as far as getting an IP via DHCP, and then disconnects, and this is repeated for quite a while. If device is not "awaken" from its sleep, it keeps doing it.

I have previously written that this "WPA: event 2 notification" corresponds to "EVENT_MICHAEL_MIC_FAILURE" but I just manually disconnected the device and noticed that it logs as well the same log lines, so this is from the perspective of the AP a voluntary disconnection that the device initiates.

Thanks for checking; in my case one of them is an iPhone 7S+.

I am convinced that it happens while the device is in power save mode because for example it happens all night long when nobody is using it, or during the day when it is not being used for a while (I didn't miss the irony of such device disconnecting/reconnecting every ~3 seconds while supposedly being saving battery) and at least from hostapd logs it seems to be initiated by device (once again I am disappointed that in hostapd EVENT_MICHAEL_MIC_FAILURE can be used for voluntary device disconnection, in these regards some clarity on that "WPA: event 2 notification" would be great)

I have no problem to "blame the device", but I wonder if I could verify what happens with stock Netgear or TP-link firmwares, perhaps they use some trick to prevent this.

Can imagine; I did find quite a bit of such posts, for example also this one in a different forum. I was trying to diagnose the problem as best as I can here so that perhaps a patch can be attempted but I am no fool, after seeing so many threads I came to the conclusion that there is either multiple problems with same symptoms or a regression that keeps happening as you described.

Unfortunately it happens also when the devices is a few meters from AP with nothing in-between, so I don't think this could be a root cause.