Message-ID: <7843b8e41120f9c6af8e7c51ca172999dc248df3.camel@gmail.com>
Subject: BUG: missing ROC/Cancel ROC events (iwlwifi)
From:   James Prestwood <prestwoj@gmail.com>
To:     "linux-wireless@vger.kernel.org" <linux-wireless@vger.kernel.org>
Date:   Tue, 07 Dec 2021 09:46:30 -0800
Content-Type: text/plain; charset="UTF-8"
User-Agent: Evolution 3.40.4 (3.40.4-2.fc34) 
MIME-Version: 1.0
Content-Transfer-Encoding: 7bit
Precedence: bulk

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