2021-12-07 17:46:33

by James Prestwood

[permalink] [raw]
Subject: BUG: missing ROC/Cancel ROC events (iwlwifi)

Hi,

I have noticed a possible bug in iwlwifi related to
CMD_[CANCEL_]REMAIN_ON_CHANNEL. I have connected to an AP, then in a
loop:

- Call CMD_REMAIN_ON_CHANNEL
- Wait for NL80211 ACK
- Wait for the ROC event
- Send a frame
- Wait for CANCEL_ROC event
- Repeat

Note sometimes the driver will deny the ROC request an immediately send
Cancel ROC, which is fine.

Specifically with about a 200ms duration I notice that eventually no
ROC event comes in. NL80211 ACKs my request which has a cookie but no
events follow. Not sure what exactly is going on but it appears to be
related to iwlwifi specifically:


< Request: Remain on Channel (0x37) len 28 [ack]
1638898585.172028
Wireless Device: 1 (0x0000000000000001)
Wiphy Frequency: 2437 (0x00000985)
Duration: 200 (0x000000c8)
> Result: Remain on Channel (0x37) len 12
1638898585.179108
Cookie: 7075 (0x0000000000001ba3)
> Response: Remain on Channel (0x37) len 4 [0x100]
1638898585.179117
Status: Success (0)
> Event: Cancel Remain on Channel (0x38) len 56
1638898585.478102
Wiphy: 0 (0x00000000)
Interface Index: 3 (0x00000003)
Wireless Device: 1 (0x0000000000000001)
Wiphy Frequency: 2437 (0x00000985)
Wiphy Channel Type: 0 (0x00000000)
Cookie: 7075 (0x0000000000001ba3)
< Request: Remain on Channel (0x37) len 28 [ack]
1638898585.478214
Wireless Device: 1 (0x0000000000000001)
Wiphy Frequency: 2437 (0x00000985)
Duration: 200 (0x000000c8)
> Result: Remain on Channel (0x37) len 12
1638898585.489078
Cookie: 7076 (0x0000000000001ba4)
> Response: Remain on Channel (0x37) len 4 [0x100]
1638898585.489088
Status: Success (0)
> Event: Remain on Channel (0x37) len 64
1638898585.672127
Wiphy: 0 (0x00000000)
Interface Index: 3 (0x00000003)
Wireless Device: 1 (0x0000000000000001)
Wiphy Frequency: 2437 (0x00000985)
Wiphy Channel Type: 0 (0x00000000)
Cookie: 7076 (0x0000000000001ba4)
Duration: 200 (0x000000c8)
< Request: Frame (0x3b) len 96 [ack]
1638898585.672333
Wireless Device: 1 (0x0000000000000001)
Wiphy Frequency: 2437 (0x00000985)
Offchannel TX OK: true
Frame: len 68
Frame Type: 0x00d0
Type: Management (0)
Subtype: Action
Action Category: Public (4)
Public Action: Vendor-specific (9)
d0 00 00 00 ff ff ff ff ff ff 7c 7a 91 2b d8 0b
..........|z.+..
ff ff ff ff ff ff 00 00 04 09 50 6f 9a 1a 01 0d
..........Po....
02 10 20 00 6a 1d 82 fa c1 f2 5f 48 3e 13 1b 99 ..
.j....._H>...
a3 92 7c 93 20 90 0a 06 34 78 fe 54 04 57 42 01 ..|.
...4x.T.WB.
7d b2 7a 89 }.z.
> Result: Frame (0x3b) len 12
1638898585.672377
Cookie: 7077 (0x0000000000001ba5)
> Response: Frame (0x3b) len 4 [0x100]
1638898585.672380
Status: Success (0)
> Event: Frame TX Status (0x3c) len 116
1638898585.673263
Wiphy: 0 (0x00000000)
Interface Index: 3 (0x00000003)
Wireless Device: 1 (0x0000000000000001)
Frame: len 68
Frame Type: 0x00d0
Type: Management (0)
Subtype: Action
Action Category: Public (4)
Public Action: Vendor-specific (9)
d0 00 00 00 ff ff ff ff ff ff 7c 7a 91 2b d8 0b
..........|z.+..
ff ff ff ff ff ff 00 00 04 09 50 6f 9a 1a 01 0d
..........Po....
02 10 20 00 6a 1d 82 fa c1 f2 5f 48 3e 13 1b 99 ..
.j....._H>...
a3 92 7c 93 20 90 0a 06 34 78 fe 54 04 57 42 01 ..|.
...4x.T.WB.
7d b2 7a 89 }.z.
Cookie: 7077 (0x0000000000001ba5)
ACK: true
> Event: Cancel Remain on Channel (0x38) len 56
1638898585.867523
Wiphy: 0 (0x00000000)
Interface Index: 3 (0x00000003)
Wireless Device: 1 (0x0000000000000001)
Wiphy Frequency: 2437 (0x00000985)
Wiphy Channel Type: 0 (0x00000000)
Cookie: 7076 (0x0000000000001ba4)
> Event: Frame Wait Cancel (0x43) len 56
1638898585.867539
Wiphy: 0 (0x00000000)
Interface Index: 3 (0x00000003)
Wireless Device: 1 (0x0000000000000001)
Wiphy Frequency: 2437 (0x00000985)
Wiphy Channel Type: 0 (0x00000000)
Cookie: 7077 (0x0000000000001ba5)
< Request: Remain on Channel (0x37) len 28 [ack]
1638898585.867664
Wireless Device: 1 (0x0000000000000001)
Wiphy Frequency: 2437 (0x00000985)
Duration: 200 (0x000000c8)
> Result: Remain on Channel (0x37) len 12
1638898585.881073
Cookie: 7078 (0x0000000000001ba6)
> Response: Remain on Channel (0x37) len 4 [0x100]
1638898585.881085
Status: Success (0)
> Event: Cancel Remain on Channel (0x38) len 56
1638898585.975207
Wiphy: 0 (0x00000000)
Interface Index: 3 (0x00000003)
Wireless Device: 1 (0x0000000000000001)
Wiphy Frequency: 2437 (0x00000985)
Wiphy Channel Type: 0 (0x00000000)
Cookie: 7078 (0x0000000000001ba6)
< Request: Remain on Channel (0x37) len 28 [ack]
1638898585.975359
Wireless Device: 1 (0x0000000000000001)
Wiphy Frequency: 2437 (0x00000985)
Duration: 200 (0x000000c8)
> Result: Remain on Channel (0x37) len 12
1638898585.987983
Cookie: 7079 (0x0000000000001ba7)
> Response: Remain on Channel (0x37) len 4 [0x100]
1638898585.988007
Status: Success (0)


... And nothing after this point. My code is waiting for the ROC/Cancel
event but it never comes.

I have tested mt76x2u, several rtl* cards, and rt2800usb and not seen
this behavior. It only happens on my iwlwifi card and only while
connected.

Thanks,
James