AP drops STA data frames for ~130-170ms after 4-way handshake completes (ath9k_htc, mt76; not brcmfmac)

Hi,

When an AP runs on a mac80211 SoftMAC driver, data frames sent by a freshly associated station are acknowledged at the MAC layer but never reach the network stack for ~130-170ms after the WPA2 4-way handshake has completed. The same station against FullMAC APs shows no such gap.

Because the frames are hardware-ACKed, the station receives no backpressure and TCP cannot detect the loss; a dropped SYN therefore costs a full initial RTO (~1.3s) rather than a retransmit.

Test setup
----------

One station, five APs, measured one at a time, everything else held
constant: same SSID, same WPA2-PSK passphrase, channel 11, hw_mode=g, ieee80211n=1, 20MHz, hostapd v2.10, AP bridged to the wired LAN. The station associates, sends one short TCP request, disconnects and deep sleeps, repeating about once per second, so every cycle is a fresh association. 100-140 cycles per AP. No other stations associated.

  AP  radio                    driver              kernel
  --  -----------------------  ------------------  -----------------
  1   Espressif ESP32 softAP   vendor stack        (ESP-IDF v5.5.5)
  2   MediaTek MT7986          mt76      SoftMAC   6.12.51
  3   Broadcom CYW43455        brcmfmac  FullMAC   6.18.39
  4   Atheros AR9271 (USB)     ath9k_htc SoftMAC   6.18.39
  5   Atheros AR958x           ath9k     SoftMAC   excluded, see below

Station: ESP32-C5, ESP-IDF v5.5.5.

APs 3 and 4 are the *same machine, same kernel, same hostapd binary, same bridge, same channel*, differing only in radio and driver.

Results
-------

"attempts" is the number of TCP connect() attempts the station needed before one succeeded; it retries every 30ms. Time is the median from association to a completed TCP handshake.

  AP  driver              n    attempts   assoc->connected
  --  ------------------  ---  --------   ----------------
  1   vendor (FullMAC)    132     1.00           2.7 ms
  3   brcmfmac (FullMAC)  140     1.01           4.8 ms
  4   ath9k_htc (SoftMAC) 105     5.04         134   ms
  2   mt76 (SoftMAC)      118     6.19         168   ms

Association itself is 23-30ms on all four; the entire difference is in how long the AP takes to start passing the station's data frames.

Air trace
---------

Captured with a separate monitor-mode radio (AR9271 on an unrelated host), against AP2. Times relative to the station's Assoc Request:

    +0.0 ms   ASSOC-REQ    from STA
    +3.2 ms   ASSOC-RESP   to STA
    +7.8 ms   EAPOL        from STA      (4-way)
   +12.5 ms   EAPOL        from STA
   +15.1 ms   DATA (enc)   from STA      <- ACKed by AP
   +45.2 ms   DATA (enc)   from STA      <- ACKed

+76 / +105 / +135 / +165 ms <- ACKed (BlockAck)
+178.1 ms DATA (enc) to STA <- first downlink; SYN-ACK

Every one of those uplink data frames is acknowledged. None of them appears on the AP's netdev: tcpdump on the AP interface sees no TCP SYN until roughly the +165ms frame.

Corresponding hostapd -dd output for the same association:

  .697155  AP-STA-CONNECTED
  .697237  nl80211: Set STA flags ... flags_or=0x1
  .698663  IEEE 802.1X: authorizing port
  .698795  WPA: pairwise key handshake completed (RSN)
  .698816  EAPOL-4WAY-HS-COMPLETED

The port is authorized 0.2ms before the handshake-complete line, so hostapd is not the one holding the frames back. Association to EAPOL-4WAY-HS-COMPLETED is a median of 70.7ms (n=229).

There is no group-key handshake in these logs, and the behaviour is unchanged with RADIUS accounting absent from the configuration.

Why this looks like mac80211 rather than one driver
---------------------------------------------------

Two SoftMAC drivers from unrelated vendors (ath9k_htc, mt76) both show it; two FullMAC/firmware-offloaded stacks (brcmfmac, Espressif) both do not. The AP3/AP4 pair isolates this to the radio and driver with everything else identical.

That suggests the pairwise key becomes usable for RX some time after hostapd authorizes the controlled port, rather than atomically with it. I have not instrumented the kernel, so the split above is inference from black-box behaviour, not from code inspection - happy to run whatever tracing would settle it.

Anticipated objection
---------------------

The station does transmit its first data frame ~3ms after sending EAPOL 4/4, i.e. before the AP has finished installing the key. That is legal, and more importantly the AP acknowledges those frames, so the station has no way to learn they were discarded. FullMAC APs carry the very same frames from the very same station without loss.

AP5 excluded
------------

The AR958x card came up in regulatory domain 00 advertising 30 dBm; "iw reg set DE" corrected it to 20 dBm. Even then, association and the 4-way handshake succeed while no data frame ever reaches the netdev, so that card looks miscalibrated and is not reported as a data point.

Reproducing
-----------

Any station that sends immediately on association will show it. The metric that makes it obvious is "TCP connect attempts before success" with a short (20-40ms) per-attempt timeout; with a normal blocking connect it is masked as a single ~1.3s stall, which is how it went unnoticed here for a long time.

Happy to provide pcaps, full hostapd -dd logs, or to test patches.

I am not subscribed to the list; please keep me on Cc for replies.

Thanks,
Thomas Hilber

I think that's right, and I don't think SoftMAC is where it splits. I ran your test on two more access points.

The first had no radio at all, just software. Median 2.8 ms over 91 associations, not one above 100. That is your FullMAC column, produced by a SoftMAC access point.

The second was real silicon: a newer MediaTek part on its own driver, but the same family you already reported, so corroboration rather than a fresh witness.

35 of 40 associations 5 to 16 ms
5 of 40 116, 128, 138, 162, 181 ms

Your range, just not every time. About one in eight, where you were seeing nearly all of them.

What separates the fast case from the slow ones isn't SoftMAC, it's where decryption happens. In software the key works the instant it is set. Everywhere else it has to be shipped out to a chip first.

The port opens on schedule. It's the key that is still in transit.

Your Atheros access point will skip hardware encryption if you ask it to, with the nohwcrypt parameter.

If the gap goes with it, that is your answer for the price of a reload. The MediaTek one has no such switch.

The reorder buffer is out as well. Anything dropped later, at decryption or at the port check, has already been through it and moved the window along, so no hole opens and the timer never starts.

Mine differs from yours in three ways: a MediaTek client instead of your ESP32, 5 GHz wide instead of 2.4 narrow, and my clock starts at the client's end of the handshake rather than the access point's.

Thanks for the pair that were the same box, same kernel, same hostapd, differing only in radio and driver. That is what made this worth chasing.

Devin

It goes with it, and it takes the whole effect with it.

AP4 from my table (AR9271, ath9k_htc, kernel 6.18.39). Same station, same hostapd, same channel, same bridge, no other station associated; the two arms were alternated and differ only in the module parameter:

  ath9k_htc         n     connect attempts   >1 attempt   TCP connect
  --------------   ---    ----------------   ----------   -----------
  nohwcrypt=0      216          5.20            97%         134.9 ms
  nohwcrypt=1      302          1.06             3%           4.1 ms

For reference, the AP4 row of my original mail was 105 cycles at 5.04 attempts and 134 ms, taken 11 days earlier. The hardware-crypto arm above reproduces it to within noise, which is the best evidence I have that nothing else about the bench moved in between.

Attempt distribution, since the shape matters more than the mean:

  nohwcrypt=0    1:6   2:27  3:24  4:17  5:71  6:29  7:13  8:7  ... 16:1
  nohwcrypt=1    1:292 2:6   3:1   4:2   5:1

Under software crypto 292 of 302 associations placed their first frame successfully. Under hardware crypto 6 of 216 did.

Two caveats, both of which cut against the result rather than for it. Cycles where the station never got a reply at all are excluded above: 33 of 249 hardware-crypto cycles and 22 of 324 software-crypto cycles. Dropping the hardware side's worst cycles understates the gap. And a late arm in the session degraded for unrelated local reasons and was discarded whole rather than pooled.

One corroboration measured at the AP, which does not depend on the station's TCP target at all - completed four-way handshakes in fixed 120s windows, with the station associating and deep-sleeping in a loop throughout:

nohwcrypt=0 64, 65 associations per 120s
nohwcrypt=1 87, 86 associations per 120s

About a third more cycles in the same wall time, which is what you would expect if every cycle stops losing ~130ms to the dead window.

So the split in my table is not SoftMAC vs FullMAC. It is where the key lives, exactly as you said - the same driver, on the same silicon, in the same box, lands in either column depending on one module parameter. Espressif and brcmfmac looked clean because the key is already in the device by the time the port opens; ath9k_htc and mt76 look bad because the port opens first and the key is still on its way to the chip.

That also fits your reorder-buffer point: with hardware crypto the frames are ACKed, so they have been through the reorder window before they are discarded, and no hole ever opens.

I have not instrumented the key-install path itself, so I still cannot say whether the right fix is to defer authorization until the key is confirmed installed, or to buffer rather than drop in that window. Happy to test patches, or to run whatever tracing would distinguish those.

Thanks - that was a good call, and a cheap one.

Thomas

Thanks for running that. Six of 216 against 292 of 302 does not need arguing.

I have it on an MT7922 built to your AP2 spec: 27 of 95 associations hold 134 to 189 ms after the handshake, which is your 130 to 170.

They are held, not dropped. On a slow cycle my station's attempts go out every 5 ms for 150 ms and none of them reaches the access point's interface, until fourteen arrive within sixteen microseconds of each other and every one is answered. Across the capture the station retransmitted three of 110, so they were arriving all along.

A monitor radio says why. Over twenty-five associations, every request to open a block acknowledgement session declared a starting sequence number of zero, and zero never arrived under any of them: the first frame after the request was one, two, three or seven. In fourteen of them the station had already sent zero before it asked for the session.

So the reorder window opens on a sequence the station will not send. The first slot can never be filled, everything queues behind it, and the release timer is what eventually lets go.

Worth a look in your own captures: the starting sequence number in the request against the sequence number of the first frame after it.

Devin

Done, and it does not hold here. The window is filled correctly and my stall happens anyway.

First, in case it is useful to anyone: I have only the one radio, and it is the access point under test. It turns out ath9k_htc will give you a monitor interface on the same phy while hostapd is running on it:

iw dev wlan1 interface add mon0 type monitor

No second radio needed. (Use "iw dev <dev>", not "iw phy phyN" - rmmod plus modprobe renumbers the phy, which cost me a run.)

Air capture and the AP's netdev, captured together, so the sequence numbers and the stall are measured on the same associations:

station side TID 0 SSN seq==SSN
sessions declared arrived

  nohwcrypt=0    5.36 attempts, 134.9 ms       259     0 in all   256/259
  nohwcrypt=1    1.01 attempts,   3.8 ms       348     0 in all   345/348

n=249 and n=342 cycles respectively. Of the 256 arrivals under hardware crypto, 237 were fresh transmissions rather than retries.

So on this hardware the reorder window opens on zero, zero arrives, and the 134.9 ms is still there. Whatever holds my frames, it is not a slot that can never be filled.

One thing that did reproduce your signature, and then disqualified itself. My station opens three sessions per association, TIDs 0, 5 and 7. TID 0 carries the traffic. TID 7 declares SSN=2, the first frame to arrive under it is seq 0, and the declared SSN never arrives in about 97% of sessions - exactly what you describe. But it is 251/259 under hardware crypto and 340/348 under software crypto: the same mismatch, at the same rate, in the arm that has no stall at all. So the pattern is real here and simply does not track the symptom.

I would not lean on my TID 7 numbers anyway. It carries 538 frames against 3116 on TID 0, and if my station keeps one sequence counter across TIDs rather than one per TID, a per-TID comparison there is meaningless. TID 0 is the measurement I trust.

I also timed the first frame of each cycle from the air to the AP's
netdev: 22.2 ms median with hardware crypto against 2.4 ms with software. The right direction, but an order of magnitude short of the 135 ms, so the frames are not simply being held for the whole window either.

Which leaves the two of us with different mechanisms producing timings that look alike. Mine responds to one module parameter and does not involve a reorder hole; yours involves a reorder hole on a part that has no such parameter to test. It may be that a missing first frame is sufficient but not necessary, and that hardware key install can also stall delivery some other way.

If your MT7922 will hand you a monitor interface on its own phy the way ath9k_htc does, the cheap check on your side is whether your slow cycles survive a session where the declared SSN *does* arrive. If they do, we are looking at one mechanism with two symptoms; if they never do, we have two.

Captures available if anyone wants them.

Thomas

Welp, that kills it, and TID 0 on its own is enough. I read too much into one capture.

Your question first, and the answer is half unhelpful. I can't check whether my slow cycles survive a session where the SSN does arrive, because I can't reproduce the slow cycles any more. Cleaning up the harness took the effect with it. My traffic had been going over loopback, and my timing metric merged the stall into the reassociation gap. Thirty five associations on the MT7922 across both bands since, nothing in your range at all. So treat my 27-in-95 from the 30th as unreliable until I can produce it again.

What I can do is make your window happen deliberately.

I built stock mt76 with a module parameter that sleeps inside set_key, so a key install takes as long as I like. Same binary both arms, the only difference is a number I echo into sysfs. The station is on a different driver, so the delay only hits the AP.

keydelay_ms=0 key install 1.1 ms
keydelay_ms=150 key install 155.3 ms

With the delay, all nine associations took 103 to 184 ms before traffic passed again. Without it, seven of nine were back inside 78 ms.

The reason it works is that mac80211 calls the driver before the key is reachable. In ieee80211_key_replace, enable_hw_accel runs first and the rcu_assign_pointer that publishes the key to the RX path runs after it. So while set_key is blocked, the AP has no key in hardware and none in software either. It is deaf, not slow.

And yes, the MT7922 does give me a monitor interface on its own phy with hostapd running, same as yours. So I captured air and the AP's netdev together through an induced window. Across four windows the station put 21, 26, 25 and 25 data frames on air and the netdev saw 7, 24, 13 and 24. In a quiet 200 ms a second later, nothing is lost at all.

Which says your 22.2 ms isn't evidence against a deaf window. Frames in the window are dropped, not delayed, so anything timed at the netdev can only be timing the survivors. Yours would look fast for the same reason mine does.

So the measurement worth making is your key install.

echo 1 > /sys/kernel/tracing/events/mac80211/drv_set_key/enable echo 1 > /sys/kernel/tracing/events/mac80211/drv_return_int/enable

Pair each set_key with the next return on the same pid. Near 134 ms and it's ath9k_htc's key path. A few ms like mine and it isn't, and your two-mechanisms reading is probably right.

Assuming CCMP, two things you can skip. The key writes take the else branch in ath_hw_set_keycache_entry and batch into one WMI multi-write, not six round trips. And the buffer enable and flush around them are a paired inc/dec, so nothing sits unflushed. TKIP takes a different branch.

Thanks for the monitor-on-the-same-phy trick. That'll save people a run.

Devin

Measured. It is not the key path.

Both tracepoints, paired by pid, taken during the same 150s window in which the stall was being measured on the station side, so these are the same associations and not a separate run:

station side ath9k_htc set_key
(drv_set_key -> return)
nohwcrypt=0 5.01 attempts, 134.4 ms median 0.418 ms, max 0.663 ms

                n=183 cycles, 98% >1 attempt      n=394, none over 50 ms

nohwcrypt=1 1.01 attempts, 3.8 ms median 0.001 ms
(driver barely involved)

394 key installs, not one above 0.7 ms, while every association in the same window was losing 134 ms. That is about 320x short of accounting for it, so by your test the two-mechanisms reading holds.

One caveat I cannot close from here. ath9k_htc is a USB part and set_key ends in a WMI write, so "drv_set_key returned" is only the driver call returning. If that write were queued rather than acknowledged, the number above would be measuring the queueing and not the install. Against that:
0.418 ms is about what a USB control round trip costs, and it is far too slow to be a memory write, which is what it would look like if nothing went out to the chip. So I think the key really is in the part when set_key returns - but I have not read the WMI path to confirm it is synchronous, and if someone who knows ath9k_htc says otherwise, this measurement is worth nothing.

You are right about my 22.2 ms and I should not have offered it. Timing first-frame delivery at the netdev can only ever time the frames that survived, so it cannot distinguish deaf from slow. It was not evidence, and I have dropped it.

Your induced window is a much better instrument than anything either of us had before, and it is worth saying what it does and does not settle. It shows that a slow key install produces this signature. It does not show that a slow key install is what produces it on hardware where the install is fast - and on ath9k_htc it now looks like it isn't. Both can be true.

Thanks also for the retraction on the reorder window; that saved me from building on it. For what it is worth, my TID 7 sessions still show your exact mismatch, declared SSN never arriving in about 97% of them - but at the same rate in the arm with no stall, so it is a real pattern here that simply does not track the symptom either.

Where that leaves ath9k_htc: association completes, the 4-way handshake completes, hostapd authorizes the port, the key reaches the chip in under a millisecond, the block-ack window opens on a sequence the station does send
- and the station's first several frames still do not come back. I am out of hypotheses that I can test from outside the driver. If anyone on the ath9k side wants a specific tracepoint or a debug patch exercised, I have a bench that reproduces this on demand, roughly 250 associations per two minutes, and I will run whatever you like.

Thomas