Re: WARNING: CPU: 1 PID: 23668 at drivers/net/wireless/intel/iwlwifi/mvm/sta.c:1539 iwl_mvm_rm_sta+0x3ce/0x450

Re: WARNING: CPU: 1 PID: 23668 at drivers/net/wireless/intel/iwlwifi/mvm/sta.c:1539 iwl_mvm_rm_sta+0x3ce/0x450

[Jens Axboe]

On 03/01/2017 08:33 PM, Luca Coelho wrote:
> Hi Jens,
> 
> On Mar 1, 2017 20:25, Jens Axboe <axboe@kernel.dk> wrote:
> 
>     Not that folks have been jumping all over this, but in case someone is
>     curious, it triggered twice here today. For those two times, the value
>     of mvm->pending_frames[sta_id] was 80 and 39, respectively.
> 
> Sorry for the delay, I'm on vacation now with limited internet access.
> But we'll take a look into this early next week at the latest.
> 
> Thanks a lot for the detailed report!

No worries, thanks for responding. I just wanted to ensure this wasn't
dropped on the floor.

BTW, a few more values of ->pending_frames[sta_id]:

$ dmesg | grep "ret="
[ 2334.308254] ret=39
[ 7915.311828] ret=80
[31602.317204] ret=41
[32139.510993] ret=54
[33292.917759] ret=96

it seems to often happen around resume.

-- 
Jens Axboe

Re: WARNING: CPU: 1 PID: 23668 at drivers/net/wireless/intel/iwlwifi/mvm/sta.c:1539 iwl_mvm_rm_sta+0x3ce/0x450

[Jens Axboe]

On 03/01/2017 09:10 PM, Jens Axboe wrote:
> On 03/01/2017 08:33 PM, Luca Coelho wrote:
>> Hi Jens,
>>
>> On Mar 1, 2017 20:25, Jens Axboe <axboe@kernel.dk> wrote:
>>
>>     Not that folks have been jumping all over this, but in case someone is
>>     curious, it triggered twice here today. For those two times, the value
>>     of mvm->pending_frames[sta_id] was 80 and 39, respectively.
>>
>> Sorry for the delay, I'm on vacation now with limited internet access.
>> But we'll take a look into this early next week at the latest.
>>
>> Thanks a lot for the detailed report!
> 
> No worries, thanks for responding. I just wanted to ensure this wasn't
> dropped on the floor.
> 
> BTW, a few more values of ->pending_frames[sta_id]:
> 
> $ dmesg | grep "ret="
> [ 2334.308254] ret=39
> [ 7915.311828] ret=80
> [31602.317204] ret=41
> [32139.510993] ret=54
> [33292.917759] ret=96
> 
> it seems to often happen around resume.

This is still happening all the time in current -git.

-- 
Jens Axboe

Re: WARNING: CPU: 1 PID: 23668 at drivers/net/wireless/intel/iwlwifi/mvm/sta.c:1539 iwl_mvm_rm_sta+0x3ce/0x450

[Luca Coelho]

Hi Jens,

On Thu, 2017-03-09 at 21:41 -0700, Jens Axboe wrote:
> On 03/01/2017 09:10 PM, Jens Axboe wrote:
> > On 03/01/2017 08:33 PM, Luca Coelho wrote:
> > > Hi Jens,
> > > 
> > > On Mar 1, 2017 20:25, Jens Axboe <axboe@kernel.dk> wrote:
> > > 
> > >     Not that folks have been jumping all over this, but in case someone is
> > >     curious, it triggered twice here today. For those two times, the value
> > >     of mvm->pending_frames[sta_id] was 80 and 39, respectively.
> > > 
> > > Sorry for the delay, I'm on vacation now with limited internet access.
> > > But we'll take a look into this early next week at the latest.
> > > 
> > > Thanks a lot for the detailed report!
> > 
> > No worries, thanks for responding. I just wanted to ensure this wasn't
> > dropped on the floor.
> > 
> > BTW, a few more values of ->pending_frames[sta_id]:
> > 
> > $ dmesg | grep "ret="
> > [ 2334.308254] ret=39
> > [ 7915.311828] ret=80
> > [31602.317204] ret=41
> > [32139.510993] ret=54
> > [33292.917759] ret=96
> > 
> > it seems to often happen around resume.
> 
> This is still happening all the time in current -git.

Could you collect traces with trace-cmd, as explained in our wiki[1]?
This will probably help point out the problem.  I know it's a bit
difficult because it appears to happen randomly for you, but it's worth
trying.

--
Cheers,
Luca.

Re: WARNING: CPU: 1 PID: 23668 at drivers/net/wireless/intel/iwlwifi/mvm/sta.c:1539 iwl_mvm_rm_sta+0x3ce/0x450

[Coelho, Luciano]

T24gRnJpLCAyMDE3LTAzLTEwIGF0IDE0OjAxICswMjAwLCBMdWNhIENvZWxobyB3cm90ZToNCj4g
SGkgSmVucywNCj4gDQo+IE9uIFRodSwgMjAxNy0wMy0wOSBhdCAyMTo0MSAtMDcwMCwgSmVucyBB
eGJvZSB3cm90ZToNCj4gPiBPbiAwMy8wMS8yMDE3IDA5OjEwIFBNLCBKZW5zIEF4Ym9lIHdyb3Rl
Og0KPiA+ID4gT24gMDMvMDEvMjAxNyAwODozMyBQTSwgTHVjYSBDb2VsaG8gd3JvdGU6DQo+ID4g
PiA+IEhpIEplbnMsDQo+ID4gPiA+IA0KPiA+ID4gPiBPbiBNYXIgMSwgMjAxNyAyMDoyNSwgSmVu
cyBBeGJvZSA8YXhib2VAa2VybmVsLmRrPiB3cm90ZToNCj4gPiA+ID4gDQo+ID4gPiA+ICAgICBO
b3QgdGhhdCBmb2xrcyBoYXZlIGJlZW4ganVtcGluZyBhbGwgb3ZlciB0aGlzLCBidXQgaW4gY2Fz
ZSBzb21lb25lIGlzDQo+ID4gPiA+ICAgICBjdXJpb3VzLCBpdCB0cmlnZ2VyZWQgdHdpY2UgaGVy
ZSB0b2RheS4gRm9yIHRob3NlIHR3byB0aW1lcywgdGhlIHZhbHVlDQo+ID4gPiA+ICAgICBvZiBt
dm0tPnBlbmRpbmdfZnJhbWVzW3N0YV9pZF0gd2FzIDgwIGFuZCAzOSwgcmVzcGVjdGl2ZWx5Lg0K
PiA+ID4gPiANCj4gPiA+ID4gU29ycnkgZm9yIHRoZSBkZWxheSwgSSdtIG9uIHZhY2F0aW9uIG5v
dyB3aXRoIGxpbWl0ZWQgaW50ZXJuZXQgYWNjZXNzLg0KPiA+ID4gPiBCdXQgd2UnbGwgdGFrZSBh
IGxvb2sgaW50byB0aGlzIGVhcmx5IG5leHQgd2VlayBhdCB0aGUgbGF0ZXN0Lg0KPiA+ID4gPiAN
Cj4gPiA+ID4gVGhhbmtzIGEgbG90IGZvciB0aGUgZGV0YWlsZWQgcmVwb3J0IQ0KPiA+ID4gDQo+
ID4gPiBObyB3b3JyaWVzLCB0aGFua3MgZm9yIHJlc3BvbmRpbmcuIEkganVzdCB3YW50ZWQgdG8g
ZW5zdXJlIHRoaXMgd2Fzbid0DQo+ID4gPiBkcm9wcGVkIG9uIHRoZSBmbG9vci4NCj4gPiA+IA0K
PiA+ID4gQlRXLCBhIGZldyBtb3JlIHZhbHVlcyBvZiAtPnBlbmRpbmdfZnJhbWVzW3N0YV9pZF06
DQo+ID4gPiANCj4gPiA+ICQgZG1lc2cgfCBncmVwICJyZXQ9Ig0KPiA+ID4gWyAyMzM0LjMwODI1
NF0gcmV0PTM5DQo+ID4gPiBbIDc5MTUuMzExODI4XSByZXQ9ODANCj4gPiA+IFszMTYwMi4zMTcy
MDRdIHJldD00MQ0KPiA+ID4gWzMyMTM5LjUxMDk5M10gcmV0PTU0DQo+ID4gPiBbMzMyOTIuOTE3
NzU5XSByZXQ9OTYNCj4gPiA+IA0KPiA+ID4gaXQgc2VlbXMgdG8gb2Z0ZW4gaGFwcGVuIGFyb3Vu
ZCByZXN1bWUuDQo+ID4gDQo+ID4gVGhpcyBpcyBzdGlsbCBoYXBwZW5pbmcgYWxsIHRoZSB0aW1l
IGluIGN1cnJlbnQgLWdpdC4NCj4gDQo+IENvdWxkIHlvdSBjb2xsZWN0IHRyYWNlcyB3aXRoIHRy
YWNlLWNtZCwgYXMgZXhwbGFpbmVkIGluIG91ciB3aWtpWzFdPw0KPiBUaGlzIHdpbGwgcHJvYmFi
bHkgaGVscCBwb2ludCBvdXQgdGhlIHByb2JsZW0uICBJIGtub3cgaXQncyBhIGJpdA0KPiBkaWZm
aWN1bHQgYmVjYXVzZSBpdCBhcHBlYXJzIHRvIGhhcHBlbiByYW5kb21seSBmb3IgeW91LCBidXQg
aXQncyB3b3J0aA0KPiB0cnlpbmcuDQoNCkFuZCBvZiBjb3Vyc2UsIHRoZSBsaW5rIEkgd2FudGVk
IHRvIGdpdmUgeW91IGlzIHRoaXM6DQoNClsxXSBodHRwczovL3dpcmVsZXNzLndpa2kua2VybmVs
Lm9yZy9lbi91c2Vycy9kcml2ZXJzL2l3bHdpZmkvZGVidWdnaW5nI3RyYWNpbmcNCg0KDQotLQ0K
THVjYS4=

Re: WARNING: CPU: 1 PID: 23668 at drivers/net/wireless/intel/iwlwifi/mvm/sta.c:1539 iwl_mvm_rm_sta+0x3ce/0x450

[Jens Axboe]

On 03/10/2017 05:01 AM, Luca Coelho wrote:
> Hi Jens,
> 
> On Thu, 2017-03-09 at 21:41 -0700, Jens Axboe wrote:
>> On 03/01/2017 09:10 PM, Jens Axboe wrote:
>>> On 03/01/2017 08:33 PM, Luca Coelho wrote:
>>>> Hi Jens,
>>>>
>>>> On Mar 1, 2017 20:25, Jens Axboe <axboe@kernel.dk> wrote:
>>>>
>>>>     Not that folks have been jumping all over this, but in case someone is
>>>>     curious, it triggered twice here today. For those two times, the value
>>>>     of mvm->pending_frames[sta_id] was 80 and 39, respectively.
>>>>
>>>> Sorry for the delay, I'm on vacation now with limited internet access.
>>>> But we'll take a look into this early next week at the latest.
>>>>
>>>> Thanks a lot for the detailed report!
>>>
>>> No worries, thanks for responding. I just wanted to ensure this wasn't
>>> dropped on the floor.
>>>
>>> BTW, a few more values of ->pending_frames[sta_id]:
>>>
>>> $ dmesg | grep "ret="
>>> [ 2334.308254] ret=39
>>> [ 7915.311828] ret=80
>>> [31602.317204] ret=41
>>> [32139.510993] ret=54
>>> [33292.917759] ret=96
>>>
>>> it seems to often happen around resume.
>>
>> This is still happening all the time in current -git.
> 
> Could you collect traces with trace-cmd, as explained in our wiki[1]?
> This will probably help point out the problem.  I know it's a bit
> difficult because it appears to happen randomly for you, but it's worth
> trying.

Sure I can, but honestly I'm a little puzzled that nobody else can
reproduce this, it happens every time I resume of switch access points.
Is anyone trying to reproduce this?

I'll have to recompile with iwlwifi tracing enabled, then I'll send a trace
when it happens.

-- 
Jens Axboe

Re: WARNING: CPU: 1 PID: 23668 at drivers/net/wireless/intel/iwlwifi/mvm/sta.c:1539 iwl_mvm_rm_sta+0x3ce/0x450

[Luca Coelho]

On Fri, 2017-03-10 at 08:23 -0700, Jens Axboe wrote:
> On 03/10/2017 05:01 AM, Luca Coelho wrote:
> > Hi Jens,
> > 
> > On Thu, 2017-03-09 at 21:41 -0700, Jens Axboe wrote:
> > > On 03/01/2017 09:10 PM, Jens Axboe wrote:
> > > > On 03/01/2017 08:33 PM, Luca Coelho wrote:
> > > > > Hi Jens,
> > > > > 
> > > > > On Mar 1, 2017 20:25, Jens Axboe <axboe@kernel.dk> wrote:
> > > > > 
> > > > >     Not that folks have been jumping all over this, but in case someone is
> > > > >     curious, it triggered twice here today. For those two times, the value
> > > > >     of mvm->pending_frames[sta_id] was 80 and 39, respectively.
> > > > > 
> > > > > Sorry for the delay, I'm on vacation now with limited internet access.
> > > > > But we'll take a look into this early next week at the latest.
> > > > > 
> > > > > Thanks a lot for the detailed report!
> > > > 
> > > > No worries, thanks for responding. I just wanted to ensure this wasn't
> > > > dropped on the floor.
> > > > 
> > > > BTW, a few more values of ->pending_frames[sta_id]:
> > > > 
> > > > $ dmesg | grep "ret="
> > > > [ 2334.308254] ret=39
> > > > [ 7915.311828] ret=80
> > > > [31602.317204] ret=41
> > > > [32139.510993] ret=54
> > > > [33292.917759] ret=96
> > > > 
> > > > it seems to often happen around resume.
> > > 
> > > This is still happening all the time in current -git.
> > 
> > Could you collect traces with trace-cmd, as explained in our wiki[1]?
> > This will probably help point out the problem.  I know it's a bit
> > difficult because it appears to happen randomly for you, but it's worth
> > trying.
> 
> Sure I can, but honestly I'm a little puzzled that nobody else can
> reproduce this, it happens every time I resume of switch access points.
> Is anyone trying to reproduce this?
> 
> I'll have to recompile with iwlwifi tracing enabled, then I'll send a trace
> when it happens.

Are you using 4.11-rc1? Or linus' master? Or...?

--
Luca.

Re: WARNING: CPU: 1 PID: 23668 at drivers/net/wireless/intel/iwlwifi/mvm/sta.c:1539 iwl_mvm_rm_sta+0x3ce/0x450

[Jens Axboe]

On 03/10/2017 08:36 AM, Luca Coelho wrote:
> On Fri, 2017-03-10 at 08:23 -0700, Jens Axboe wrote:
>> On 03/10/2017 05:01 AM, Luca Coelho wrote:
>>> Hi Jens,
>>>
>>> On Thu, 2017-03-09 at 21:41 -0700, Jens Axboe wrote:
>>>> On 03/01/2017 09:10 PM, Jens Axboe wrote:
>>>>> On 03/01/2017 08:33 PM, Luca Coelho wrote:
>>>>>> Hi Jens,
>>>>>>
>>>>>> On Mar 1, 2017 20:25, Jens Axboe <axboe@kernel.dk> wrote:
>>>>>>
>>>>>>     Not that folks have been jumping all over this, but in case someone is
>>>>>>     curious, it triggered twice here today. For those two times, the value
>>>>>>     of mvm->pending_frames[sta_id] was 80 and 39, respectively.
>>>>>>
>>>>>> Sorry for the delay, I'm on vacation now with limited internet access.
>>>>>> But we'll take a look into this early next week at the latest.
>>>>>>
>>>>>> Thanks a lot for the detailed report!
>>>>>
>>>>> No worries, thanks for responding. I just wanted to ensure this wasn't
>>>>> dropped on the floor.
>>>>>
>>>>> BTW, a few more values of ->pending_frames[sta_id]:
>>>>>
>>>>> $ dmesg | grep "ret="
>>>>> [ 2334.308254] ret=39
>>>>> [ 7915.311828] ret=80
>>>>> [31602.317204] ret=41
>>>>> [32139.510993] ret=54
>>>>> [33292.917759] ret=96
>>>>>
>>>>> it seems to often happen around resume.
>>>>
>>>> This is still happening all the time in current -git.
>>>
>>> Could you collect traces with trace-cmd, as explained in our wiki[1]?
>>> This will probably help point out the problem.  I know it's a bit
>>> difficult because it appears to happen randomly for you, but it's worth
>>> trying.
>>
>> Sure I can, but honestly I'm a little puzzled that nobody else can
>> reproduce this, it happens every time I resume of switch access points.
>> Is anyone trying to reproduce this?
>>
>> I'll have to recompile with iwlwifi tracing enabled, then I'll send a trace
>> when it happens.
> 
> Are you using 4.11-rc1? Or linus' master? Or...?

The trace I just sent is tip of Linus' tree. It's happened continually
since the commit I mentioned in my initial report was merged:

commit 94c3e614df2117626fccfac8f821c66e30556384
Author: Sara Sharon <sara.sharon@intel.com>
Date:   Wed Dec 7 15:04:37 2016 +0200

    iwlwifi: mvm: fix pending frame counter calculation

-- 
Jens Axboe

Re: WARNING: CPU: 1 PID: 23668 at drivers/net/wireless/intel/iwlwifi/mvm/sta.c:1539 iwl_mvm_rm_sta+0x3ce/0x450

[Luca Coelho]

On Fri, 2017-03-10 at 08:37 -0700, Jens Axboe wrote:
> On 03/10/2017 08:23 AM, Jens Axboe wrote:
> > On 03/10/2017 05:01 AM, Luca Coelho wrote:
> > > Hi Jens,
> > > 
> > > On Thu, 2017-03-09 at 21:41 -0700, Jens Axboe wrote:
> > > > On 03/01/2017 09:10 PM, Jens Axboe wrote:
> > > > > On 03/01/2017 08:33 PM, Luca Coelho wrote:
> > > > > > Hi Jens,
> > > > > > 
> > > > > > On Mar 1, 2017 20:25, Jens Axboe <axboe@kernel.dk> wrote:
> > > > > > 
> > > > > >     Not that folks have been jumping all over this, but in case someone is
> > > > > >     curious, it triggered twice here today. For those two times, the value
> > > > > >     of mvm->pending_frames[sta_id] was 80 and 39, respectively.
> > > > > > 
> > > > > > Sorry for the delay, I'm on vacation now with limited internet access.
> > > > > > But we'll take a look into this early next week at the latest.
> > > > > > 
> > > > > > Thanks a lot for the detailed report!
> > > > > 
> > > > > No worries, thanks for responding. I just wanted to ensure this wasn't
> > > > > dropped on the floor.
> > > > > 
> > > > > BTW, a few more values of ->pending_frames[sta_id]:
> > > > > 
> > > > > $ dmesg | grep "ret="
> > > > > [ 2334.308254] ret=39
> > > > > [ 7915.311828] ret=80
> > > > > [31602.317204] ret=41
> > > > > [32139.510993] ret=54
> > > > > [33292.917759] ret=96
> > > > > 
> > > > > it seems to often happen around resume.
> > > > 
> > > > This is still happening all the time in current -git.
> > > 
> > > Could you collect traces with trace-cmd, as explained in our wiki[1]?
> > > This will probably help point out the problem.  I know it's a bit
> > > difficult because it appears to happen randomly for you, but it's worth
> > > trying.
> > 
> > Sure I can, but honestly I'm a little puzzled that nobody else can
> > reproduce this, it happens every time I resume of switch access points.
> > Is anyone trying to reproduce this?
> > 
> > I'll have to recompile with iwlwifi tracing enabled, then I'll send a trace
> > when it happens.
> 
> Booted up, logged in, and started tracing:
> 
> $ sudo trace-cmd record -e iwlwifi -e mac80211 -e cfg80211 -e iwlwifi_msg
> /sys/kernel/tracing/events/iwlwifi/filter
> /sys/kernel/tracing/events/*/iwlwifi/filter
> /sys/kernel/tracing/events/mac80211/filter
> /sys/kernel/tracing/events/*/mac80211/filter
> /sys/kernel/tracing/events/cfg80211/filter
> /sys/kernel/tracing/events/*/cfg80211/filter
> /sys/kernel/tracing/events/iwlwifi_msg/filter
> /sys/kernel/tracing/events/*/iwlwifi_msg/filter
> Hit Ctrl^C to stop recording
> 
> Then I switched to a different access point, and I immediately got the
> trace in dmesg:
> [   41.439499] wlp4s0: deauthenticating from b4:75:0e:99:1f:e0 by local choice (Reason: 3=DEAUTH_LEAVING)
> [   41.548817] ------------[ cut here ]------------
> [   41.548833] WARNING: CPU: 1 PID: 1001 at drivers/net/wireless/intel/iwlwifi/mvm/sta.c:1539 iwl_mvm_rm_sta+0x3f6/0x470 [iwlmvm]
> [   41.548834] Modules linked in: ctr ccm rfcomm fuse bnep arc4 binfmt_misc snd_hda_codec_hdmi nls_iso8859_1 nls_cp437 vfat snd_hda_codec_conexant snd_hda_codec_generic fat snd_hda_intel snd_hda_codec snd_hwdep snd_hda_core iwlmvm snd_pcm snd_seq_midi snd_seq_midi_event mac80211 snd_rawmidi snd_seq x86_pkg_temp_thermal intel_powerclamp kvm_intel kvm iwlwifi snd_seq_device snd_timer irqbypass uvcvideo videobuf2_vmalloc videobuf2_memops snd aesni_intel videobuf2_v4l2 aes_x86_64 crypto_simd btusb btintel videobuf2_core cryptd bluetooth glue_helper videodev cfg80211 soundcore hid_generic usbhid hid i915 psmouse e1000e ptp pps_core xhci_pci xhci_hcd intel_gtt
> [   41.548880] CPU: 1 PID: 1001 Comm: wpa_supplicant Tainted: G     U          4.11.0-rc1+ #24
> [   41.548881] Hardware name: LENOVO 20FBCTO1WW/20FBCTO1WW, BIOS N1FET45W (1.19 ) 11/08/2016
> [   41.548882] Call Trace:
> [   41.548888]  dump_stack+0x4d/0x63
> [   41.548891]  __warn+0xcb/0xf0
> [   41.548894]  warn_slowpath_null+0x1d/0x20
> [   41.548903]  iwl_mvm_rm_sta+0x3f6/0x470 [iwlmvm]
> [   41.548910]  iwl_mvm_mac_sta_state+0x516/0x600 [iwlmvm]
> [   41.548925]  drv_sta_state+0x83/0x4b0 [mac80211]
> [   41.548938]  __sta_info_destroy_part2+0x128/0x160 [mac80211]
> [   41.548951]  __sta_info_flush+0xdb/0x180 [mac80211]
> [   41.548969]  ieee80211_set_disassoc+0xba/0x3c0 [mac80211]
> [   41.548988]  ieee80211_mgd_deauth+0xfa/0x210 [mac80211]
> [   41.549005]  ieee80211_deauth+0x18/0x20 [mac80211]
> [   41.549025]  cfg80211_mlme_deauth+0xa0/0x1e0 [cfg80211]
> [   41.549041]  nl80211_deauthenticate+0x124/0x160 [cfg80211]
> [   41.549045]  genl_family_rcv_msg+0x1b5/0x360
> [   41.549048]  genl_rcv_msg+0x44/0x80
> [   41.549051]  ? genl_family_rcv_msg+0x360/0x360
> [   41.549053]  netlink_rcv_skb+0x97/0xb0
> [   41.549055]  genl_rcv+0x28/0x40
> [   41.549058]  netlink_unicast+0x181/0x210
> [   41.549060]  netlink_sendmsg+0x2d8/0x390
> [   41.549064]  sock_sendmsg+0x38/0x50
> [   41.549067]  ___sys_sendmsg+0x25f/0x270
> [   41.549069]  ? ___sys_recvmsg+0x141/0x1b0
> [   41.549073]  ? __set_current_blocked+0x55/0x60
> [   41.549076]  ? signal_setup_done+0x5c/0xa0
> [   41.549078]  ? do_signal+0x175/0x640
> [   41.549081]  ? __fpu__restore_sig+0x8c/0x4e0
> [   41.549085]  __sys_sendmsg+0x45/0x80
> [   41.549088]  SyS_sendmsg+0x12/0x20
> [   41.549091]  entry_SYSCALL_64_fastpath+0x13/0x94
> [   41.549093] RIP: 0033:0x7f94475358a0
> [   41.549094] RSP: 002b:00007ffd7dd1a1d8 EFLAGS: 00000246 ORIG_RAX: 000000000000002e
> [   41.549097] RAX: ffffffffffffffda RBX: 000055ff43bb1f90 RCX: 00007f94475358a0
> [   41.549098] RDX: 0000000000000000 RSI: 00007ffd7dd1a260 RDI: 0000000000000007
> [   41.549099] RBP: 000055ff43bb24d0 R08: 0000000000000000 R09: 0000000000000000
> [   41.549100] R10: 000055ff43bb3300 R11: 0000000000000246 R12: 0000000000000001
> [   41.549101] R13: 00007ffd7dd1a888 R14: 000055ff43bb26f0 R15: 000000000000000b
> [   41.549103] ---[ end trace 30bc14424e760dd4 ]---
> [   41.555170] iwlwifi 0000:04:00.0: Failed to find station
> [   41.555177] wlp4s0: failed to remove key (2, ff:ff:ff:ff:ff:ff) from hardware (-22)
> 
> Then I stopped tracing:
> 
> ^CKernel buffer statistics:
>   Note: "entries" are the entries left in the kernel ring buffer and are not
>         recorded in the trace data. They should all be zero.
> Kernel buffer statistics:
>   Note: "entries" are the entries left in the kernel ring buffer and are not
>         recorded in the trace data. They should all be zero.
> 
> CPU: 0
> entries: 0
> overrun: 0
> commit overrun: 0
> bytes: 2584
> oldest event ts:    44.361525
> now ts:    45.772870
> dropped events: 0
> read events: 3281
> 
> CPU: 1
> entries: 0
> overrun: 0
> commit overrun: 0
> bytes: 1636
> oldest event ts:    43.917128
> now ts:    45.772909
> dropped events: 0
> read events: 557
> 
> CPU: 2
> entries: 0
> overrun: 0
> commit overrun: 0
> bytes: 2472
> oldest event ts:    44.211886
> now ts:    45.772938
> dropped events: 0
> read events: 314
> 
> CPU: 3
> entries: 0
> overrun: 0
> commit overrun: 0
> bytes: 1864
> oldest event ts:    44.023886
> now ts:    45.772966
> dropped events: 0
> read events: 204
> 
> CPU0 data recorded at offset=0x3dd000
>     507904 bytes in size
> CPU1 data recorded at offset=0x459000
>     81920 bytes in size
> CPU2 data recorded at offset=0x46d000
>     61440 bytes in size
> CPU3 data recorded at offset=0x47c000
>     32768 bytes in size
> 
> And I have attached trace.dat for you.

Great, thanks! I'll take a look and also try to repro locally.

--
Cheers,
Luca.

Re: WARNING: CPU: 1 PID: 23668 at drivers/net/wireless/intel/iwlwifi/mvm/sta.c:1539 iwl_mvm_rm_sta+0x3ce/0x450

[Luca Coelho]

On Fri, 2017-03-10 at 08:41 -0700, Jens Axboe wrote:
> On 03/10/2017 08:36 AM, Luca Coelho wrote:
> > On Fri, 2017-03-10 at 08:23 -0700, Jens Axboe wrote:
> > > On 03/10/2017 05:01 AM, Luca Coelho wrote:
> > > > Hi Jens,
> > > > 
> > > > On Thu, 2017-03-09 at 21:41 -0700, Jens Axboe wrote:
> > > > > On 03/01/2017 09:10 PM, Jens Axboe wrote:
> > > > > > On 03/01/2017 08:33 PM, Luca Coelho wrote:
> > > > > > > Hi Jens,
> > > > > > > 
> > > > > > > On Mar 1, 2017 20:25, Jens Axboe <axboe@kernel.dk> wrote:
> > > > > > > 
> > > > > > >     Not that folks have been jumping all over this, but in case someone is
> > > > > > >     curious, it triggered twice here today. For those two times, the value
> > > > > > >     of mvm->pending_frames[sta_id] was 80 and 39, respectively.
> > > > > > > 
> > > > > > > Sorry for the delay, I'm on vacation now with limited internet access.
> > > > > > > But we'll take a look into this early next week at the latest.
> > > > > > > 
> > > > > > > Thanks a lot for the detailed report!
> > > > > > 
> > > > > > No worries, thanks for responding. I just wanted to ensure this wasn't
> > > > > > dropped on the floor.
> > > > > > 
> > > > > > BTW, a few more values of ->pending_frames[sta_id]:
> > > > > > 
> > > > > > $ dmesg | grep "ret="
> > > > > > [ 2334.308254] ret=39
> > > > > > [ 7915.311828] ret=80
> > > > > > [31602.317204] ret=41
> > > > > > [32139.510993] ret=54
> > > > > > [33292.917759] ret=96
> > > > > > 
> > > > > > it seems to often happen around resume.
> > > > > 
> > > > > This is still happening all the time in current -git.
> > > > 
> > > > Could you collect traces with trace-cmd, as explained in our wiki[1]?
> > > > This will probably help point out the problem.  I know it's a bit
> > > > difficult because it appears to happen randomly for you, but it's worth
> > > > trying.
> > > 
> > > Sure I can, but honestly I'm a little puzzled that nobody else can
> > > reproduce this, it happens every time I resume of switch access points.
> > > Is anyone trying to reproduce this?
> > > 
> > > I'll have to recompile with iwlwifi tracing enabled, then I'll send a trace
> > > when it happens.
> > 
> > Are you using 4.11-rc1? Or linus' master? Or...?
> 
> The trace I just sent is tip of Linus' tree. It's happened continually
> since the commit I mentioned in my initial report was merged:
> 
> commit 94c3e614df2117626fccfac8f821c66e30556384
> Author: Sara Sharon <sara.sharon@intel.com>
> Date:   Wed Dec 7 15:04:37 2016 +0200
> 
>     iwlwifi: mvm: fix pending frame counter calculation

I found the patch that fixes this issue in our internal tree.  I'll send
it out for you to try now.

The reason is that in DQA (Dynamic Queue Allocation) mode that we
introduced recently, we should not be counting the frames in the same
way as before.  The warning was introduced exactly to catch this kind of
problems.

Please let me know if it works for you!

--
Cheers,
Luca.

[PATCH] iwlwifi: mvm: cleanup pending frames in DQA mode

[Luca Coelho]

From: Sara Sharon <sara.sharon@intel.com>

When a station is asleep, the fw will set it as "asleep".
All queues that are used only by one station will be stopped by
the fw.

In pre-DQA mode this was relevant for aggregation queues. However,
in DQA mode a queue is owned by one station only, so all queues
will be stopped.
As a result, we don't expect to get filtered frames back to
mac80211 and don't have to maintain the entire pending_frames
state logic, the same way as we do in aggregations.

The correct behavior is to align DQA behavior with the aggregation
queue behaviour pre-DQA:
- Don't count pending frames.
- Let mac80211 know we have frames in these queues so that it can
properly handle trigger frames.

When a trigger frame is received, mac80211 tells the driver to send
frames from the queues using release_buffered_frames.
The driver will tell the fw to let frames out even if the station
is asleep. This is done by iwl_mvm_sta_modify_sleep_tx_count.

Signed-off-by: Sara Sharon <sara.sharon@intel.com>
Signed-off-by: Luca Coelho <luciano.coelho@intel.com>
---
 drivers/net/wireless/intel/iwlwifi/mvm/mac80211.c |  5 +--
 drivers/net/wireless/intel/iwlwifi/mvm/sta.c      | 11 +++---
 drivers/net/wireless/intel/iwlwifi/mvm/sta.h      |  2 +-
 drivers/net/wireless/intel/iwlwifi/mvm/tx.c       | 41 ++++++++++-------------
 4 files changed, 28 insertions(+), 31 deletions(-)

diff --git a/drivers/net/wireless/intel/iwlwifi/mvm/mac80211.c b/drivers/net/wireless/intel/iwlwifi/mvm/mac80211.c
index d37b1695c64e..6927caecd48e 100644
--- a/drivers/net/wireless/intel/iwlwifi/mvm/mac80211.c
+++ b/drivers/net/wireless/intel/iwlwifi/mvm/mac80211.c
@@ -2319,7 +2319,7 @@ iwl_mvm_mac_release_buffered_frames(struct ieee80211_hw *hw,
 {
 	struct iwl_mvm *mvm = IWL_MAC80211_GET_MVM(hw);
 
-	/* Called when we need to transmit (a) frame(s) from agg queue */
+	/* Called when we need to transmit (a) frame(s) from agg or dqa queue */
 
 	iwl_mvm_sta_modify_sleep_tx_count(mvm, sta, reason, num_frames,
 					  tids, more_data, true);
@@ -2338,7 +2338,8 @@ static void __iwl_mvm_mac_sta_notify(struct ieee80211_hw *hw,
 	for (tid = 0; tid < IWL_MAX_TID_COUNT; tid++) {
 		struct iwl_mvm_tid_data *tid_data = &mvmsta->tid_data[tid];
 
-		if (tid_data->state != IWL_AGG_ON &&
+		if (!iwl_mvm_is_dqa_supported(mvm) &&
+		    tid_data->state != IWL_AGG_ON &&
 		    tid_data->state != IWL_EMPTYING_HW_QUEUE_DELBA)
 			continue;
 
diff --git a/drivers/net/wireless/intel/iwlwifi/mvm/sta.c b/drivers/net/wireless/intel/iwlwifi/mvm/sta.c
index bd1dcc863d8f..b51a2853cc80 100644
--- a/drivers/net/wireless/intel/iwlwifi/mvm/sta.c
+++ b/drivers/net/wireless/intel/iwlwifi/mvm/sta.c
@@ -3135,7 +3135,7 @@ void iwl_mvm_sta_modify_sleep_tx_count(struct iwl_mvm *mvm,
 				       struct ieee80211_sta *sta,
 				       enum ieee80211_frame_release_type reason,
 				       u16 cnt, u16 tids, bool more_data,
-				       bool agg)
+				       bool single_sta_queue)
 {
 	struct iwl_mvm_sta *mvmsta = iwl_mvm_sta_from_mac80211(sta);
 	struct iwl_mvm_add_sta_cmd cmd = {
@@ -3155,14 +3155,14 @@ void iwl_mvm_sta_modify_sleep_tx_count(struct iwl_mvm *mvm,
 	for_each_set_bit(tid, &_tids, IWL_MAX_TID_COUNT)
 		cmd.awake_acs |= BIT(tid_to_ucode_ac[tid]);
 
-	/* If we're releasing frames from aggregation queues then check if the
-	 * all queues combined that we're releasing frames from have
+	/* If we're releasing frames from aggregation or dqa queues then check
+	 * if all the queues that we're releasing frames from, combined, have:
 	 *  - more frames than the service period, in which case more_data
 	 *    needs to be set
 	 *  - fewer than 'cnt' frames, in which case we need to adjust the
 	 *    firmware command (but do that unconditionally)
 	 */
-	if (agg) {
+	if (single_sta_queue) {
 		int remaining = cnt;
 		int sleep_tx_count;
 
@@ -3172,7 +3172,8 @@ void iwl_mvm_sta_modify_sleep_tx_count(struct iwl_mvm *mvm,
 			u16 n_queued;
 
 			tid_data = &mvmsta->tid_data[tid];
-			if (WARN(tid_data->state != IWL_AGG_ON &&
+			if (WARN(!iwl_mvm_is_dqa_supported(mvm) &&
+				 tid_data->state != IWL_AGG_ON &&
 				 tid_data->state != IWL_EMPTYING_HW_QUEUE_DELBA,
 				 "TID %d state is %d\n",
 				 tid, tid_data->state)) {
diff --git a/drivers/net/wireless/intel/iwlwifi/mvm/sta.h b/drivers/net/wireless/intel/iwlwifi/mvm/sta.h
index 4be34f902278..1927ce607798 100644
--- a/drivers/net/wireless/intel/iwlwifi/mvm/sta.h
+++ b/drivers/net/wireless/intel/iwlwifi/mvm/sta.h
@@ -547,7 +547,7 @@ void iwl_mvm_sta_modify_sleep_tx_count(struct iwl_mvm *mvm,
 				       struct ieee80211_sta *sta,
 				       enum ieee80211_frame_release_type reason,
 				       u16 cnt, u16 tids, bool more_data,
-				       bool agg);
+				       bool single_sta_queue);
 int iwl_mvm_drain_sta(struct iwl_mvm *mvm, struct iwl_mvm_sta *mvmsta,
 		      bool drain);
 void iwl_mvm_sta_modify_disable_tx(struct iwl_mvm *mvm,
diff --git a/drivers/net/wireless/intel/iwlwifi/mvm/tx.c b/drivers/net/wireless/intel/iwlwifi/mvm/tx.c
index dd2b4a300819..3f37075f4cde 100644
--- a/drivers/net/wireless/intel/iwlwifi/mvm/tx.c
+++ b/drivers/net/wireless/intel/iwlwifi/mvm/tx.c
@@ -7,7 +7,7 @@
  *
  * Copyright(c) 2012 - 2014 Intel Corporation. All rights reserved.
  * Copyright(c) 2013 - 2015 Intel Mobile Communications GmbH
- * Copyright(c) 2016        Intel Deutschland GmbH
+ * Copyright(c) 2016 - 2017 Intel Deutschland GmbH
  *
  * This program is free software; you can redistribute it and/or modify
  * it under the terms of version 2 of the GNU General Public License as
@@ -34,6 +34,7 @@
  *
  * Copyright(c) 2012 - 2014 Intel Corporation. All rights reserved.
  * Copyright(c) 2013 - 2015 Intel Mobile Communications GmbH
+ * Copyright(c) 2016 - 2017 Intel Deutschland GmbH
  * All rights reserved.
  *
  * Redistribution and use in source and binary forms, with or without
@@ -628,8 +629,10 @@ int iwl_mvm_tx_skb_non_sta(struct iwl_mvm *mvm, struct sk_buff *skb)
 	 * values.
 	 * Note that we don't need to make sure it isn't agg'd, since we're
 	 * TXing non-sta
+	 * For DQA mode - we shouldn't increase it though
 	 */
-	atomic_inc(&mvm->pending_frames[sta_id]);
+	if (!iwl_mvm_is_dqa_supported(mvm))
+		atomic_inc(&mvm->pending_frames[sta_id]);
 
 	return 0;
 }
@@ -1005,11 +1008,8 @@ static int iwl_mvm_tx_mpdu(struct iwl_mvm *mvm, struct sk_buff *skb,
 
 	spin_unlock(&mvmsta->lock);
 
-	/* Increase pending frames count if this isn't AMPDU */
-	if ((iwl_mvm_is_dqa_supported(mvm) &&
-	     mvmsta->tid_data[tx_cmd->tid_tspec].state != IWL_AGG_ON &&
-	     mvmsta->tid_data[tx_cmd->tid_tspec].state != IWL_AGG_STARTING) ||
-	    (!iwl_mvm_is_dqa_supported(mvm) && !is_ampdu))
+	/* Increase pending frames count if this isn't AMPDU or DQA queue */
+	if (!iwl_mvm_is_dqa_supported(mvm) && !is_ampdu)
 		atomic_inc(&mvm->pending_frames[mvmsta->sta_id]);
 
 	return 0;
@@ -1079,12 +1079,13 @@ static void iwl_mvm_check_ratid_empty(struct iwl_mvm *mvm,
 	lockdep_assert_held(&mvmsta->lock);
 
 	if ((tid_data->state == IWL_AGG_ON ||
-	     tid_data->state == IWL_EMPTYING_HW_QUEUE_DELBA) &&
+	     tid_data->state == IWL_EMPTYING_HW_QUEUE_DELBA ||
+	     iwl_mvm_is_dqa_supported(mvm)) &&
 	    iwl_mvm_tid_queued(tid_data) == 0) {
 		/*
-		 * Now that this aggregation queue is empty tell mac80211 so it
-		 * knows we no longer have frames buffered for the station on
-		 * this TID (for the TIM bitmap calculation.)
+		 * Now that this aggregation or DQA queue is empty tell
+		 * mac80211 so it knows we no longer have frames buffered for
+		 * the station on this TID (for the TIM bitmap calculation.)
 		 */
 		ieee80211_sta_set_buffered(sta, tid, false);
 	}
@@ -1257,7 +1258,6 @@ static void iwl_mvm_rx_tx_cmd_single(struct iwl_mvm *mvm,
 	u8 skb_freed = 0;
 	u16 next_reclaimed, seq_ctl;
 	bool is_ndp = false;
-	bool txq_agg = false; /* Is this TXQ aggregated */
 
 	__skb_queue_head_init(&skbs);
 
@@ -1283,6 +1283,10 @@ static void iwl_mvm_rx_tx_cmd_single(struct iwl_mvm *mvm,
 			info->flags |= IEEE80211_TX_STAT_ACK;
 			break;
 		case TX_STATUS_FAIL_DEST_PS:
+			/* In DQA, the FW should have stopped the queue and not
+			 * return this status
+			 */
+			WARN_ON(iwl_mvm_is_dqa_supported(mvm));
 			info->flags |= IEEE80211_TX_STAT_TX_FILTERED;
 			break;
 		default:
@@ -1387,15 +1391,6 @@ static void iwl_mvm_rx_tx_cmd_single(struct iwl_mvm *mvm,
 			bool send_eosp_ndp = false;
 
 			spin_lock_bh(&mvmsta->lock);
-			if (iwl_mvm_is_dqa_supported(mvm)) {
-				enum iwl_mvm_agg_state state;
-
-				state = mvmsta->tid_data[tid].state;
-				txq_agg = (state == IWL_AGG_ON ||
-					state == IWL_EMPTYING_HW_QUEUE_DELBA);
-			} else {
-				txq_agg = txq_id >= mvm->first_agg_queue;
-			}
 
 			if (!is_ndp) {
 				tid_data->next_reclaimed = next_reclaimed;
@@ -1452,11 +1447,11 @@ static void iwl_mvm_rx_tx_cmd_single(struct iwl_mvm *mvm,
 	 * If the txq is not an AMPDU queue, there is no chance we freed
 	 * several skbs. Check that out...
 	 */
-	if (txq_agg)
+	if (iwl_mvm_is_dqa_supported(mvm) || txq_id >= mvm->first_agg_queue)
 		goto out;
 
 	/* We can't free more than one frame at once on a shared queue */
-	WARN_ON(!iwl_mvm_is_dqa_supported(mvm) && (skb_freed > 1));
+	WARN_ON(skb_freed > 1);
 
 	/* If we have still frames for this STA nothing to do here */
 	if (!atomic_sub_and_test(skb_freed, &mvm->pending_frames[sta_id]))
-- 
2.11.0

Re: WARNING: CPU: 1 PID: 23668 at drivers/net/wireless/intel/iwlwifi/mvm/sta.c:1539 iwl_mvm_rm_sta+0x3ce/0x450

[Jens Axboe]

On 03/13/2017 07:00 AM, Luca Coelho wrote:
> On Fri, 2017-03-10 at 08:41 -0700, Jens Axboe wrote:
>> On 03/10/2017 08:36 AM, Luca Coelho wrote:
>>> On Fri, 2017-03-10 at 08:23 -0700, Jens Axboe wrote:
>>>> On 03/10/2017 05:01 AM, Luca Coelho wrote:
>>>>> Hi Jens,
>>>>>
>>>>> On Thu, 2017-03-09 at 21:41 -0700, Jens Axboe wrote:
>>>>>> On 03/01/2017 09:10 PM, Jens Axboe wrote:
>>>>>>> On 03/01/2017 08:33 PM, Luca Coelho wrote:
>>>>>>>> Hi Jens,
>>>>>>>>
>>>>>>>> On Mar 1, 2017 20:25, Jens Axboe <axboe@kernel.dk> wrote:
>>>>>>>>
>>>>>>>>     Not that folks have been jumping all over this, but in case someone is
>>>>>>>>     curious, it triggered twice here today. For those two times, the value
>>>>>>>>     of mvm->pending_frames[sta_id] was 80 and 39, respectively.
>>>>>>>>
>>>>>>>> Sorry for the delay, I'm on vacation now with limited internet access.
>>>>>>>> But we'll take a look into this early next week at the latest.
>>>>>>>>
>>>>>>>> Thanks a lot for the detailed report!
>>>>>>>
>>>>>>> No worries, thanks for responding. I just wanted to ensure this wasn't
>>>>>>> dropped on the floor.
>>>>>>>
>>>>>>> BTW, a few more values of ->pending_frames[sta_id]:
>>>>>>>
>>>>>>> $ dmesg | grep "ret="
>>>>>>> [ 2334.308254] ret=39
>>>>>>> [ 7915.311828] ret=80
>>>>>>> [31602.317204] ret=41
>>>>>>> [32139.510993] ret=54
>>>>>>> [33292.917759] ret=96
>>>>>>>
>>>>>>> it seems to often happen around resume.
>>>>>>
>>>>>> This is still happening all the time in current -git.
>>>>>
>>>>> Could you collect traces with trace-cmd, as explained in our wiki[1]?
>>>>> This will probably help point out the problem.  I know it's a bit
>>>>> difficult because it appears to happen randomly for you, but it's worth
>>>>> trying.
>>>>
>>>> Sure I can, but honestly I'm a little puzzled that nobody else can
>>>> reproduce this, it happens every time I resume of switch access points.
>>>> Is anyone trying to reproduce this?
>>>>
>>>> I'll have to recompile with iwlwifi tracing enabled, then I'll send a trace
>>>> when it happens.
>>>
>>> Are you using 4.11-rc1? Or linus' master? Or...?
>>
>> The trace I just sent is tip of Linus' tree. It's happened continually
>> since the commit I mentioned in my initial report was merged:
>>
>> commit 94c3e614df2117626fccfac8f821c66e30556384
>> Author: Sara Sharon <sara.sharon@intel.com>
>> Date:   Wed Dec 7 15:04:37 2016 +0200
>>
>>     iwlwifi: mvm: fix pending frame counter calculation
> 
> I found the patch that fixes this issue in our internal tree.  I'll send
> it out for you to try now.
> 
> The reason is that in DQA (Dynamic Queue Allocation) mode that we
> introduced recently, we should not be counting the frames in the same
> way as before.  The warning was introduced exactly to catch this kind of
> problems.
> 
> Please let me know if it works for you!

Seems to work for me, thanks! You can add my

Tested-by: Jens Axboe <axboe@fb.com>

to the patch.

-- 
Jens Axboe

Re: [PATCH] iwlwifi: mvm: cleanup pending frames in DQA mode

[Jens Axboe]

On 03/13/2017 07:14 AM, Luca Coelho wrote:
> From: Sara Sharon <sara.sharon@intel.com>
> 
> When a station is asleep, the fw will set it as "asleep".
> All queues that are used only by one station will be stopped by
> the fw.
> 
> In pre-DQA mode this was relevant for aggregation queues. However,
> in DQA mode a queue is owned by one station only, so all queues
> will be stopped.
> As a result, we don't expect to get filtered frames back to
> mac80211 and don't have to maintain the entire pending_frames
> state logic, the same way as we do in aggregations.
> 
> The correct behavior is to align DQA behavior with the aggregation
> queue behaviour pre-DQA:
> - Don't count pending frames.
> - Let mac80211 know we have frames in these queues so that it can
> properly handle trigger frames.
> 
> When a trigger frame is received, mac80211 tells the driver to send
> frames from the queues using release_buffered_frames.
> The driver will tell the fw to let frames out even if the station
> is asleep. This is done by iwl_mvm_sta_modify_sleep_tx_count.

It fixes the warning for me.

Tested-by: Jens Axboe <axboe@fb.com>

-- 
Jens Axboe

Re: [PATCH] iwlwifi: mvm: cleanup pending frames in DQA mode

[Luca Coelho]

On Mon, 2017-03-13 at 08:24 -0600, Jens Axboe wrote:
> On 03/13/2017 07:14 AM, Luca Coelho wrote:
> > From: Sara Sharon <sara.sharon@intel.com>
> > 
> > When a station is asleep, the fw will set it as "asleep".
> > All queues that are used only by one station will be stopped by
> > the fw.
> > 
> > In pre-DQA mode this was relevant for aggregation queues. However,
> > in DQA mode a queue is owned by one station only, so all queues
> > will be stopped.
> > As a result, we don't expect to get filtered frames back to
> > mac80211 and don't have to maintain the entire pending_frames
> > state logic, the same way as we do in aggregations.
> > 
> > The correct behavior is to align DQA behavior with the aggregation
> > queue behaviour pre-DQA:
> > - Don't count pending frames.
> > - Let mac80211 know we have frames in these queues so that it can
> > properly handle trigger frames.
> > 
> > When a trigger frame is received, mac80211 tells the driver to send
> > frames from the queues using release_buffered_frames.
> > The driver will tell the fw to let frames out even if the station
> > is asleep. This is done by iwl_mvm_sta_modify_sleep_tx_count.
> 
> It fixes the warning for me.
> 
> Tested-by: Jens Axboe <axboe@fb.com>

Great! Thanks for testing.

I'll queue this for the 4.11-rc series via the normal path (i.e.
wireless-driver->netdev).

--
Cheers,
Luca.

[RESEND PATCH 4.11] iwlwifi: mvm: cleanup pending frames in DQA mode

[Luca Coelho]

From: Sara Sharon <sara.sharon@intel.com>

When a station is asleep, the fw will set it as "asleep".
All queues that are used only by one station will be stopped by
the fw.

In pre-DQA mode this was relevant for aggregation queues. However,
in DQA mode a queue is owned by one station only, so all queues
will be stopped.
As a result, we don't expect to get filtered frames back to
mac80211 and don't have to maintain the entire pending_frames
state logic, the same way as we do in aggregations.

The correct behavior is to align DQA behavior with the aggregation
queue behaviour pre-DQA:
- Don't count pending frames.
- Let mac80211 know we have frames in these queues so that it can
properly handle trigger frames.

When a trigger frame is received, mac80211 tells the driver to send
frames from the queues using release_buffered_frames.
The driver will tell the fw to let frames out even if the station
is asleep. This is done by iwl_mvm_sta_modify_sleep_tx_count.

Reported-and-tested-by: Jens Axboe <axboe@kernel.dk>
Reported-by: Linus Torvalds <torvalds@linux-foundation.org>
Signed-off-by: Sara Sharon <sara.sharon@intel.com>
Signed-off-by: Luca Coelho <luciano.coelho@intel.com>
---

Just resending with reported and tested by tags.


drivers/net/wireless/intel/iwlwifi/mvm/mac80211.c |  5 +--
 drivers/net/wireless/intel/iwlwifi/mvm/sta.c      | 11 +++---
 drivers/net/wireless/intel/iwlwifi/mvm/sta.h      |  2 +-
 drivers/net/wireless/intel/iwlwifi/mvm/tx.c       | 41 ++++++++++-------------
 4 files changed, 28 insertions(+), 31 deletions(-)

diff --git a/drivers/net/wireless/intel/iwlwifi/mvm/mac80211.c b/drivers/net/wireless/intel/iwlwifi/mvm/mac80211.c
index d37b1695c64e..6927caecd48e 100644
--- a/drivers/net/wireless/intel/iwlwifi/mvm/mac80211.c
+++ b/drivers/net/wireless/intel/iwlwifi/mvm/mac80211.c
@@ -2319,7 +2319,7 @@ iwl_mvm_mac_release_buffered_frames(struct ieee80211_hw *hw,
 {
 	struct iwl_mvm *mvm = IWL_MAC80211_GET_MVM(hw);
 
-	/* Called when we need to transmit (a) frame(s) from agg queue */
+	/* Called when we need to transmit (a) frame(s) from agg or dqa queue */
 
 	iwl_mvm_sta_modify_sleep_tx_count(mvm, sta, reason, num_frames,
 					  tids, more_data, true);
@@ -2338,7 +2338,8 @@ static void __iwl_mvm_mac_sta_notify(struct ieee80211_hw *hw,
 	for (tid = 0; tid < IWL_MAX_TID_COUNT; tid++) {
 		struct iwl_mvm_tid_data *tid_data = &mvmsta->tid_data[tid];
 
-		if (tid_data->state != IWL_AGG_ON &&
+		if (!iwl_mvm_is_dqa_supported(mvm) &&
+		    tid_data->state != IWL_AGG_ON &&
 		    tid_data->state != IWL_EMPTYING_HW_QUEUE_DELBA)
 			continue;
 
diff --git a/drivers/net/wireless/intel/iwlwifi/mvm/sta.c b/drivers/net/wireless/intel/iwlwifi/mvm/sta.c
index bd1dcc863d8f..b51a2853cc80 100644
--- a/drivers/net/wireless/intel/iwlwifi/mvm/sta.c
+++ b/drivers/net/wireless/intel/iwlwifi/mvm/sta.c
@@ -3135,7 +3135,7 @@ void iwl_mvm_sta_modify_sleep_tx_count(struct iwl_mvm *mvm,
 				       struct ieee80211_sta *sta,
 				       enum ieee80211_frame_release_type reason,
 				       u16 cnt, u16 tids, bool more_data,
-				       bool agg)
+				       bool single_sta_queue)
 {
 	struct iwl_mvm_sta *mvmsta = iwl_mvm_sta_from_mac80211(sta);
 	struct iwl_mvm_add_sta_cmd cmd = {
@@ -3155,14 +3155,14 @@ void iwl_mvm_sta_modify_sleep_tx_count(struct iwl_mvm *mvm,
 	for_each_set_bit(tid, &_tids, IWL_MAX_TID_COUNT)
 		cmd.awake_acs |= BIT(tid_to_ucode_ac[tid]);
 
-	/* If we're releasing frames from aggregation queues then check if the
-	 * all queues combined that we're releasing frames from have
+	/* If we're releasing frames from aggregation or dqa queues then check
+	 * if all the queues that we're releasing frames from, combined, have:
 	 *  - more frames than the service period, in which case more_data
 	 *    needs to be set
 	 *  - fewer than 'cnt' frames, in which case we need to adjust the
 	 *    firmware command (but do that unconditionally)
 	 */
-	if (agg) {
+	if (single_sta_queue) {
 		int remaining = cnt;
 		int sleep_tx_count;
 
@@ -3172,7 +3172,8 @@ void iwl_mvm_sta_modify_sleep_tx_count(struct iwl_mvm *mvm,
 			u16 n_queued;
 
 			tid_data = &mvmsta->tid_data[tid];
-			if (WARN(tid_data->state != IWL_AGG_ON &&
+			if (WARN(!iwl_mvm_is_dqa_supported(mvm) &&
+				 tid_data->state != IWL_AGG_ON &&
 				 tid_data->state != IWL_EMPTYING_HW_QUEUE_DELBA,
 				 "TID %d state is %d\n",
 				 tid, tid_data->state)) {
diff --git a/drivers/net/wireless/intel/iwlwifi/mvm/sta.h b/drivers/net/wireless/intel/iwlwifi/mvm/sta.h
index 4be34f902278..1927ce607798 100644
--- a/drivers/net/wireless/intel/iwlwifi/mvm/sta.h
+++ b/drivers/net/wireless/intel/iwlwifi/mvm/sta.h
@@ -547,7 +547,7 @@ void iwl_mvm_sta_modify_sleep_tx_count(struct iwl_mvm *mvm,
 				       struct ieee80211_sta *sta,
 				       enum ieee80211_frame_release_type reason,
 				       u16 cnt, u16 tids, bool more_data,
-				       bool agg);
+				       bool single_sta_queue);
 int iwl_mvm_drain_sta(struct iwl_mvm *mvm, struct iwl_mvm_sta *mvmsta,
 		      bool drain);
 void iwl_mvm_sta_modify_disable_tx(struct iwl_mvm *mvm,
diff --git a/drivers/net/wireless/intel/iwlwifi/mvm/tx.c b/drivers/net/wireless/intel/iwlwifi/mvm/tx.c
index dd2b4a300819..3f37075f4cde 100644
--- a/drivers/net/wireless/intel/iwlwifi/mvm/tx.c
+++ b/drivers/net/wireless/intel/iwlwifi/mvm/tx.c
@@ -7,7 +7,7 @@
  *
  * Copyright(c) 2012 - 2014 Intel Corporation. All rights reserved.
  * Copyright(c) 2013 - 2015 Intel Mobile Communications GmbH
- * Copyright(c) 2016        Intel Deutschland GmbH
+ * Copyright(c) 2016 - 2017 Intel Deutschland GmbH
  *
  * This program is free software; you can redistribute it and/or modify
  * it under the terms of version 2 of the GNU General Public License as
@@ -34,6 +34,7 @@
  *
  * Copyright(c) 2012 - 2014 Intel Corporation. All rights reserved.
  * Copyright(c) 2013 - 2015 Intel Mobile Communications GmbH
+ * Copyright(c) 2016 - 2017 Intel Deutschland GmbH
  * All rights reserved.
  *
  * Redistribution and use in source and binary forms, with or without
@@ -628,8 +629,10 @@ int iwl_mvm_tx_skb_non_sta(struct iwl_mvm *mvm, struct sk_buff *skb)
 	 * values.
 	 * Note that we don't need to make sure it isn't agg'd, since we're
 	 * TXing non-sta
+	 * For DQA mode - we shouldn't increase it though
 	 */
-	atomic_inc(&mvm->pending_frames[sta_id]);
+	if (!iwl_mvm_is_dqa_supported(mvm))
+		atomic_inc(&mvm->pending_frames[sta_id]);
 
 	return 0;
 }
@@ -1005,11 +1008,8 @@ static int iwl_mvm_tx_mpdu(struct iwl_mvm *mvm, struct sk_buff *skb,
 
 	spin_unlock(&mvmsta->lock);
 
-	/* Increase pending frames count if this isn't AMPDU */
-	if ((iwl_mvm_is_dqa_supported(mvm) &&
-	     mvmsta->tid_data[tx_cmd->tid_tspec].state != IWL_AGG_ON &&
-	     mvmsta->tid_data[tx_cmd->tid_tspec].state != IWL_AGG_STARTING) ||
-	    (!iwl_mvm_is_dqa_supported(mvm) && !is_ampdu))
+	/* Increase pending frames count if this isn't AMPDU or DQA queue */
+	if (!iwl_mvm_is_dqa_supported(mvm) && !is_ampdu)
 		atomic_inc(&mvm->pending_frames[mvmsta->sta_id]);
 
 	return 0;
@@ -1079,12 +1079,13 @@ static void iwl_mvm_check_ratid_empty(struct iwl_mvm *mvm,
 	lockdep_assert_held(&mvmsta->lock);
 
 	if ((tid_data->state == IWL_AGG_ON ||
-	     tid_data->state == IWL_EMPTYING_HW_QUEUE_DELBA) &&
+	     tid_data->state == IWL_EMPTYING_HW_QUEUE_DELBA ||
+	     iwl_mvm_is_dqa_supported(mvm)) &&
 	    iwl_mvm_tid_queued(tid_data) == 0) {
 		/*
-		 * Now that this aggregation queue is empty tell mac80211 so it
-		 * knows we no longer have frames buffered for the station on
-		 * this TID (for the TIM bitmap calculation.)
+		 * Now that this aggregation or DQA queue is empty tell
+		 * mac80211 so it knows we no longer have frames buffered for
+		 * the station on this TID (for the TIM bitmap calculation.)
 		 */
 		ieee80211_sta_set_buffered(sta, tid, false);
 	}
@@ -1257,7 +1258,6 @@ static void iwl_mvm_rx_tx_cmd_single(struct iwl_mvm *mvm,
 	u8 skb_freed = 0;
 	u16 next_reclaimed, seq_ctl;
 	bool is_ndp = false;
-	bool txq_agg = false; /* Is this TXQ aggregated */
 
 	__skb_queue_head_init(&skbs);
 
@@ -1283,6 +1283,10 @@ static void iwl_mvm_rx_tx_cmd_single(struct iwl_mvm *mvm,
 			info->flags |= IEEE80211_TX_STAT_ACK;
 			break;
 		case TX_STATUS_FAIL_DEST_PS:
+			/* In DQA, the FW should have stopped the queue and not
+			 * return this status
+			 */
+			WARN_ON(iwl_mvm_is_dqa_supported(mvm));
 			info->flags |= IEEE80211_TX_STAT_TX_FILTERED;
 			break;
 		default:
@@ -1387,15 +1391,6 @@ static void iwl_mvm_rx_tx_cmd_single(struct iwl_mvm *mvm,
 			bool send_eosp_ndp = false;
 
 			spin_lock_bh(&mvmsta->lock);
-			if (iwl_mvm_is_dqa_supported(mvm)) {
-				enum iwl_mvm_agg_state state;
-
-				state = mvmsta->tid_data[tid].state;
-				txq_agg = (state == IWL_AGG_ON ||
-					state == IWL_EMPTYING_HW_QUEUE_DELBA);
-			} else {
-				txq_agg = txq_id >= mvm->first_agg_queue;
-			}
 
 			if (!is_ndp) {
 				tid_data->next_reclaimed = next_reclaimed;
@@ -1452,11 +1447,11 @@ static void iwl_mvm_rx_tx_cmd_single(struct iwl_mvm *mvm,
 	 * If the txq is not an AMPDU queue, there is no chance we freed
 	 * several skbs. Check that out...
 	 */
-	if (txq_agg)
+	if (iwl_mvm_is_dqa_supported(mvm) || txq_id >= mvm->first_agg_queue)
 		goto out;
 
 	/* We can't free more than one frame at once on a shared queue */
-	WARN_ON(!iwl_mvm_is_dqa_supported(mvm) && (skb_freed > 1));
+	WARN_ON(skb_freed > 1);
 
 	/* If we have still frames for this STA nothing to do here */
 	if (!atomic_sub_and_test(skb_freed, &mvm->pending_frames[sta_id]))
-- 
2.11.0

Re: [RESEND PATCH 4.11] iwlwifi: mvm: cleanup pending frames in DQA mode

[Kalle Valo]

Luca Coelho <luca@coelho.fi> writes:

> From: Sara Sharon <sara.sharon@intel.com>
>
> When a station is asleep, the fw will set it as "asleep".
> All queues that are used only by one station will be stopped by
> the fw.
>
> In pre-DQA mode this was relevant for aggregation queues. However,
> in DQA mode a queue is owned by one station only, so all queues
> will be stopped.
> As a result, we don't expect to get filtered frames back to
> mac80211 and don't have to maintain the entire pending_frames
> state logic, the same way as we do in aggregations.
>
> The correct behavior is to align DQA behavior with the aggregation
> queue behaviour pre-DQA:
> - Don't count pending frames.
> - Let mac80211 know we have frames in these queues so that it can
> properly handle trigger frames.
>
> When a trigger frame is received, mac80211 tells the driver to send
> frames from the queues using release_buffered_frames.
> The driver will tell the fw to let frames out even if the station
> is asleep. This is done by iwl_mvm_sta_modify_sleep_tx_count.
>
> Reported-and-tested-by: Jens Axboe <axboe@kernel.dk>
> Reported-by: Linus Torvalds <torvalds@linux-foundation.org>
> Signed-off-by: Sara Sharon <sara.sharon@intel.com>
> Signed-off-by: Luca Coelho <luciano.coelho@intel.com>
> ---
>
> Just resending with reported and tested by tags.

Sorry, my usual rant follows :) But never ever use "RESEND", it's so
much simpler to have v2, v3 and so on to figure out what's the (latest)
version I should take.

-- 
Kalle Valo

Re: [RESEND PATCH 4.11] iwlwifi: mvm: cleanup pending frames in DQA mode

[Coelho, Luciano]

T24gV2VkLCAyMDE3LTAzLTE1IGF0IDExOjUyICswMjAwLCBLYWxsZSBWYWxvIHdyb3RlOg0KPiBM
dWNhIENvZWxobyA8bHVjYUBjb2VsaG8uZmk+IHdyaXRlczoNCj4gDQo+ID4gRnJvbTogU2FyYSBT
aGFyb24gPHNhcmEuc2hhcm9uQGludGVsLmNvbT4NCj4gPiANCj4gPiBXaGVuIGEgc3RhdGlvbiBp
cyBhc2xlZXAsIHRoZSBmdyB3aWxsIHNldCBpdCBhcyAiYXNsZWVwIi4NCj4gPiBBbGwgcXVldWVz
IHRoYXQgYXJlIHVzZWQgb25seSBieSBvbmUgc3RhdGlvbiB3aWxsIGJlIHN0b3BwZWQgYnkNCj4g
PiB0aGUgZncuDQo+ID4gDQo+ID4gSW4gcHJlLURRQSBtb2RlIHRoaXMgd2FzIHJlbGV2YW50IGZv
ciBhZ2dyZWdhdGlvbiBxdWV1ZXMuIEhvd2V2ZXIsDQo+ID4gaW4gRFFBIG1vZGUgYSBxdWV1ZSBp
cyBvd25lZCBieSBvbmUgc3RhdGlvbiBvbmx5LCBzbyBhbGwgcXVldWVzDQo+ID4gd2lsbCBiZSBz
dG9wcGVkLg0KPiA+IEFzIGEgcmVzdWx0LCB3ZSBkb24ndCBleHBlY3QgdG8gZ2V0IGZpbHRlcmVk
IGZyYW1lcyBiYWNrIHRvDQo+ID4gbWFjODAyMTEgYW5kIGRvbid0IGhhdmUgdG8gbWFpbnRhaW4g
dGhlIGVudGlyZSBwZW5kaW5nX2ZyYW1lcw0KPiA+IHN0YXRlIGxvZ2ljLCB0aGUgc2FtZSB3YXkg
YXMgd2UgZG8gaW4gYWdncmVnYXRpb25zLg0KPiA+IA0KPiA+IFRoZSBjb3JyZWN0IGJlaGF2aW9y
IGlzIHRvIGFsaWduIERRQSBiZWhhdmlvciB3aXRoIHRoZSBhZ2dyZWdhdGlvbg0KPiA+IHF1ZXVl
IGJlaGF2aW91ciBwcmUtRFFBOg0KPiA+IC0gRG9uJ3QgY291bnQgcGVuZGluZyBmcmFtZXMuDQo+
ID4gLSBMZXQgbWFjODAyMTEga25vdyB3ZSBoYXZlIGZyYW1lcyBpbiB0aGVzZSBxdWV1ZXMgc28g
dGhhdCBpdCBjYW4NCj4gPiBwcm9wZXJseSBoYW5kbGUgdHJpZ2dlciBmcmFtZXMuDQo+ID4gDQo+
ID4gV2hlbiBhIHRyaWdnZXIgZnJhbWUgaXMgcmVjZWl2ZWQsIG1hYzgwMjExIHRlbGxzIHRoZSBk
cml2ZXIgdG8gc2VuZA0KPiA+IGZyYW1lcyBmcm9tIHRoZSBxdWV1ZXMgdXNpbmcgcmVsZWFzZV9i
dWZmZXJlZF9mcmFtZXMuDQo+ID4gVGhlIGRyaXZlciB3aWxsIHRlbGwgdGhlIGZ3IHRvIGxldCBm
cmFtZXMgb3V0IGV2ZW4gaWYgdGhlIHN0YXRpb24NCj4gPiBpcyBhc2xlZXAuIFRoaXMgaXMgZG9u
ZSBieSBpd2xfbXZtX3N0YV9tb2RpZnlfc2xlZXBfdHhfY291bnQuDQo+ID4gDQo+ID4gUmVwb3J0
ZWQtYW5kLXRlc3RlZC1ieTogSmVucyBBeGJvZSA8YXhib2VAa2VybmVsLmRrPg0KPiA+IFJlcG9y
dGVkLWJ5OiBMaW51cyBUb3J2YWxkcyA8dG9ydmFsZHNAbGludXgtZm91bmRhdGlvbi5vcmc+DQo+
ID4gU2lnbmVkLW9mZi1ieTogU2FyYSBTaGFyb24gPHNhcmEuc2hhcm9uQGludGVsLmNvbT4NCj4g
PiBTaWduZWQtb2ZmLWJ5OiBMdWNhIENvZWxobyA8bHVjaWFuby5jb2VsaG9AaW50ZWwuY29tPg0K
PiA+IC0tLQ0KPiA+IA0KPiA+IEp1c3QgcmVzZW5kaW5nIHdpdGggcmVwb3J0ZWQgYW5kIHRlc3Rl
ZCBieSB0YWdzLg0KPiANCj4gU29ycnksIG15IHVzdWFsIHJhbnQgZm9sbG93cyA6KSBCdXQgbmV2
ZXIgZXZlciB1c2UgIlJFU0VORCIsIGl0J3Mgc28NCj4gbXVjaCBzaW1wbGVyIHRvIGhhdmUgdjIs
IHYzIGFuZCBzbyBvbiB0byBmaWd1cmUgb3V0IHdoYXQncyB0aGUgKGxhdGVzdCkNCj4gdmVyc2lv
biBJIHNob3VsZCB0YWtlLg0KDQpPa2F5LCBzb3JyeS4gIEkganVzdCB1c2VkIFJFU0VORCwgYmVj
YXVzZSBJIGRpZG4ndCBjaGFuZ2UgdGhlIHBhdGNoDQppdHNlbGYsIGJ1dCBvbmx5IGFkZGVkIHRo
ZSByZXBvcnRlZC1ieSB0YWdzLi4uDQoNCi0tDQpMdWNhLg==

Re: [RESEND,4.11] iwlwifi: mvm: cleanup pending frames in DQA mode

[Kalle Valo]

Luciano Coelho <luca@coelho.fi> wrote:
> From: Sara Sharon <sara.sharon@intel.com>
> 
> When a station is asleep, the fw will set it as "asleep".
> All queues that are used only by one station will be stopped by
> the fw.
> 
> In pre-DQA mode this was relevant for aggregation queues. However,
> in DQA mode a queue is owned by one station only, so all queues
> will be stopped.
> As a result, we don't expect to get filtered frames back to
> mac80211 and don't have to maintain the entire pending_frames
> state logic, the same way as we do in aggregations.
> 
> The correct behavior is to align DQA behavior with the aggregation
> queue behaviour pre-DQA:
> - Don't count pending frames.
> - Let mac80211 know we have frames in these queues so that it can
> properly handle trigger frames.
> 
> When a trigger frame is received, mac80211 tells the driver to send
> frames from the queues using release_buffered_frames.
> The driver will tell the fw to let frames out even if the station
> is asleep. This is done by iwl_mvm_sta_modify_sleep_tx_count.
> 
> Reported-and-tested-by: Jens Axboe <axboe@kernel.dk>
> Reported-by: Linus Torvalds <torvalds@linux-foundation.org>
> Signed-off-by: Sara Sharon <sara.sharon@intel.com>
> Signed-off-by: Luca Coelho <luciano.coelho@intel.com>

Patch applied to wireless-drivers.git, thanks.

9a3fcf912ef7 iwlwifi: mvm: cleanup pending frames in DQA mode

-- 
https://patchwork.kernel.org/patch/9622617/

Documentation about submitting wireless patches and checking status
from patchwork:

https://wireless.wiki.kernel.org/en/developers/documentation/submittingpatches

Re: WARNING: CPU: 1 PID: 23668 at drivers/net/wireless/intel/iwlwifi/mvm/sta.c:1539 iwl_mvm_rm_sta+0x3ce/0x450

[Jens Axboe]

On 02/28/2017 01:41 PM, Jens Axboe wrote:
> On 02/28/2017 11:02 AM, Jens Axboe wrote:
>> Hi,
>>
>> I'm hitting this one a lot with current -git, which is this one:
>>
>> if (iwl_mvm_is_dqa_supported(mvm)) {                            
>>         iwl_mvm_disable_sta_queues(mvm, vif, mvm_sta);          
>>         /*                                                      
>>          * If pending_frames is set at this point - it must be  
>>          * driver internal logic error, since queues are empty  
>>          * and removed successuly.                              
>>          * warn on it but set it to 0 anyway to avoid station   
>>          * not being removed later in the function              
>>          */                                                     
>>         WARN_ON(atomic_xchg(&mvm->pending_frames[sta_id], 0));  
>> }
>>
>> It's hit 4 times over the last day. The bug is probably older than the
>> commit that added this warning:
>>
>> commit 94c3e614df2117626fccfac8f821c66e30556384
>> Author: Sara Sharon <sara.sharon@intel.com>
>> Date:   Wed Dec 7 15:04:37 2016 +0200
>>
>>     iwlwifi: mvm: fix pending frame counter calculation
>>
>> but the pestering is new.
> 
> Forgot to include the traces, find them below.

Not that folks have been jumping all over this, but in case someone is
curious, it triggered twice here today. For those two times, the value
of mvm->pending_frames[sta_id] was 80 and 39, respectively.

-- 
Jens Axboe

Re: WARNING: CPU: 1 PID: 23668 at drivers/net/wireless/intel/iwlwifi/mvm/sta.c:1539 iwl_mvm_rm_sta+0x3ce/0x450

[Jens Axboe]

On 02/28/2017 11:02 AM, Jens Axboe wrote:
> Hi,
> 
> I'm hitting this one a lot with current -git, which is this one:
> 
> if (iwl_mvm_is_dqa_supported(mvm)) {                            
>         iwl_mvm_disable_sta_queues(mvm, vif, mvm_sta);          
>         /*                                                      
>          * If pending_frames is set at this point - it must be  
>          * driver internal logic error, since queues are empty  
>          * and removed successuly.                              
>          * warn on it but set it to 0 anyway to avoid station   
>          * not being removed later in the function              
>          */                                                     
>         WARN_ON(atomic_xchg(&mvm->pending_frames[sta_id], 0));  
> }
> 
> It's hit 4 times over the last day. The bug is probably older than the
> commit that added this warning:
> 
> commit 94c3e614df2117626fccfac8f821c66e30556384
> Author: Sara Sharon <sara.sharon@intel.com>
> Date:   Wed Dec 7 15:04:37 2016 +0200
> 
>     iwlwifi: mvm: fix pending frame counter calculation
> 
> but the pestering is new.

Forgot to include the traces, find them below.


[ 3829.774681] ------------[ cut here ]------------
[ 3829.774708] WARNING: CPU: 2 PID: 9155 at drivers/net/wireless/intel/iwlwifi/mvm/sta.c:1539 iwl_mvm_rm_sta+0x3ce/0x450 [iwlmvm]
[ 3829.774710] Modules linked in: rfcomm fuse ctr ccm arc4 bnep snd_hda_codec_hdmi snd_hda_codec_conexant snd_hda_codec_generic snd_hda_intel snd_hda_codec snd_hwdep snd_hda_core snd_pcm snd_seq_midi snd_seq_midi_event snd_rawmidi snd_seq snd_seq_device iwlmvm mac80211 binfmt_misc snd_timer iwlwifi uvcvideo x86_pkg_temp_thermal intel_powerclamp kvm_intel videobuf2_vmalloc kvm snd videobuf2_memops nls_iso8859_1 nls_cp437 irqbypass aesni_intel videobuf2_v4l2 aes_x86_64 videobuf2_core crypto_simd btusb vfat cryptd fat glue_helper videodev soundcore btintel cfg80211 bluetooth hid_generic usbhid hid psmouse i915 e1000e ptp pps_core xhci_pci xhci_hcd intel_gtt
[ 3829.774785] CPU: 2 PID: 9155 Comm: kworker/u8:0 Tainted: G     U          4.10.0+ #17
[ 3829.774787] Hardware name: LENOVO 20FBCTO1WW/20FBCTO1WW, BIOS N1FET45W (1.19 ) 11/08/2016
[ 3829.774824] Workqueue: phy0 ieee80211_iface_work [mac80211]
[ 3829.774826] Call Trace:
[ 3829.774837]  dump_stack+0x4d/0x63
[ 3829.774843]  __warn+0xcb/0xf0
[ 3829.774849]  warn_slowpath_null+0x1d/0x20
[ 3829.774864]  iwl_mvm_rm_sta+0x3ce/0x450 [iwlmvm]
[ 3829.774875]  iwl_mvm_mac_sta_state+0x3fb/0x590 [iwlmvm]
[ 3829.774898]  drv_sta_state+0x83/0x4b0 [mac80211]
[ 3829.774922]  __sta_info_destroy_part2+0x128/0x160 [mac80211]
[ 3829.774945]  __sta_info_flush+0xdb/0x180 [mac80211]
[ 3829.774979]  ieee80211_set_disassoc+0xba/0x3c0 [mac80211]
[ 3829.775017]  ieee80211_sta_connection_lost.constprop.23+0x2a/0x50 [mac80211]
[ 3829.775056]  ieee80211_sta_work+0x1f3/0x1440 [mac80211]
[ 3829.775063]  ? update_curr+0x76/0x190
[ 3829.775069]  ? dequeue_task_fair+0x612/0x1830
[ 3829.775100]  ieee80211_iface_work+0x332/0x430 [mac80211]
[ 3829.775104]  ? finish_task_switch+0x78/0x200
[ 3829.775111]  process_one_work+0x1f3/0x4a0
[ 3829.775116]  worker_thread+0x48/0x4e0
[ 3829.775121]  kthread+0x101/0x140
[ 3829.775125]  ? process_one_work+0x4a0/0x4a0
[ 3829.775129]  ? kthread_create_on_node+0x40/0x40
[ 3829.775135]  ret_from_fork+0x29/0x40
[ 3829.775140] ---[ end trace 4da4612127066e04 ]---
[ 3829.780886] iwlwifi 0000:04:00.0: Failed to find station
[ 3829.780899] wlp4s0: failed to remove key (1, ff:ff:ff:ff:ff:ff) from hardware (-22)
[ 3829.780934] iwlwifi 0000:04:00.0: Failed to find station
[ 3829.780938] wlp4s0: failed to remove key (2, ff:ff:ff:ff:ff:ff) from hardware (-22)
[ 3829.903700] wlp4s0: authenticate with b4:75:0e:99:1f:e0
[ 3829.911954] wlp4s0: send auth to b4:75:0e:99:1f:e0 (try 1/3)
[ 3829.924048] wlp4s0: authenticated
[ 3829.927968] wlp4s0: associate with b4:75:0e:99:1f:e0 (try 1/3)
[ 3829.932783] wlp4s0: RX AssocResp from b4:75:0e:99:1f:e0 (capab=0x11 status=0 aid=1)
[ 3829.933844] wlp4s0: associated
[...]
[15590.492927] wlp4s0: deauthenticating from e2:cc:f8:1a:52:be by local choice (Reason: 3=DEAUTH_LEAVING)
[15590.503419] ------------[ cut here ]------------
[15590.503429] WARNING: CPU: 1 PID: 1012 at drivers/net/wireless/intel/iwlwifi/mvm/sta.c:1539 iwl_mvm_rm_sta+0x3ce/0x450 [iwlmvm]
[15590.503430] Modules linked in: iwlmvm iwlwifi rfcomm fuse ctr ccm arc4 bnep snd_hda_codec_hdmi snd_hda_codec_conexant snd_hda_codec_generic snd_hda_intel snd_hda_codec snd_hwdep snd_hda_core snd_pcm snd_seq_midi snd_seq_midi_event snd_rawmidi snd_seq snd_seq_device mac80211 binfmt_misc snd_timer uvcvideo x86_pkg_temp_thermal intel_powerclamp kvm_intel videobuf2_vmalloc kvm snd videobuf2_memops nls_iso8859_1 nls_cp437 irqbypass aesni_intel videobuf2_v4l2 aes_x86_64 videobuf2_core crypto_simd btusb vfat cryptd fat glue_helper videodev soundcore btintel cfg80211 bluetooth hid_generic usbhid hid psmouse i915 e1000e ptp pps_core xhci_pci xhci_hcd intel_gtt [last unloaded: iwlwifi]
[15590.503458] CPU: 1 PID: 1012 Comm: wpa_supplicant Tainted: G     U  W       4.10.0+ #17
[15590.503459] Hardware name: LENOVO 20FBCTO1WW/20FBCTO1WW, BIOS N1FET45W (1.19 ) 11/08/2016
[15590.503460] Call Trace:
[15590.503464]  dump_stack+0x4d/0x63
[15590.503466]  __warn+0xcb/0xf0
[15590.503468]  warn_slowpath_null+0x1d/0x20
[15590.503472]  iwl_mvm_rm_sta+0x3ce/0x450 [iwlmvm]
[15590.503475]  iwl_mvm_mac_sta_state+0x3fb/0x590 [iwlmvm]
[15590.503490]  drv_sta_state+0x83/0x4b0 [mac80211]
[15590.503496]  __sta_info_destroy_part2+0x128/0x160 [mac80211]
[15590.503502]  __sta_info_flush+0xdb/0x180 [mac80211]
[15590.503512]  ieee80211_set_disassoc+0xba/0x3c0 [mac80211]
[15590.503521]  ieee80211_mgd_deauth+0xfa/0x210 [mac80211]
[15590.503530]  ieee80211_deauth+0x18/0x20 [mac80211]
[15590.503546]  cfg80211_mlme_deauth+0xa0/0x1e0 [cfg80211]
[15590.503554]  nl80211_deauthenticate+0x124/0x160 [cfg80211]
[15590.503556]  genl_family_rcv_msg+0x1b5/0x360
[15590.503558]  genl_rcv_msg+0x59/0xa0
[15590.503560]  ? genl_register_family+0x630/0x630
[15590.503561]  netlink_rcv_skb+0x97/0xb0
[15590.503563]  genl_rcv+0x28/0x40
[15590.503564]  netlink_unicast+0x181/0x210
[15590.503566]  netlink_sendmsg+0x2d8/0x390
[15590.503567]  sock_sendmsg+0x38/0x50
[15590.503568]  ___sys_sendmsg+0x25f/0x270
[15590.503569]  ? ___sys_recvmsg+0x141/0x1b0
[15590.503572]  ? __set_current_blocked+0x55/0x60
[15590.503574]  ? signal_setup_done+0x5c/0xa0
[15590.503575]  ? do_signal+0x175/0x640
[15590.503577]  ? __fpu__restore_sig+0x8c/0x4e0
[15590.503578]  __sys_sendmsg+0x45/0x80
[15590.503580]  SyS_sendmsg+0x12/0x20
[15590.503582]  entry_SYSCALL_64_fastpath+0x13/0x94
[15590.503583] RIP: 0033:0x7f78c96308a0
[15590.503583] RSP: 002b:00007fff812ffe28 EFLAGS: 00000246 ORIG_RAX: 000000000000002e
[15590.503585] RAX: ffffffffffffffda RBX: 0000556ff4800f90 RCX: 00007f78c96308a0
[15590.503585] RDX: 0000000000000000 RSI: 00007fff812ffeb0 RDI: 0000000000000007
[15590.503586] RBP: 0000556ff48014a0 R08: 0000000000000000 R09: 0000000000000000
[15590.503586] R10: 0000556ff483ee80 R11: 0000000000000246 R12: 0000000000000001
[15590.503587] R13: 00007fff813004d8 R14: 0000556ff48016f0 R15: 000000000000000b
[15590.503588] ---[ end trace 4da4612127066e06 ]---
[15590.508925] iwlwifi 0000:04:00.0: Failed to find station
[15590.508929] wlp4s0: failed to remove key (1, ff:ff:ff:ff:ff:ff) from hardware (-22)
[15590.508941] iwlwifi 0000:04:00.0: Failed to find station
[15590.508943] wlp4s0: failed to remove key (2, ff:ff:ff:ff:ff:ff) from hardware (-22)
[...]
[15605.883212] wlp4s0: authenticate with b4:75:0e:99:1f:e0
[15605.891574] wlp4s0: send auth to b4:75:0e:99:1f:e0 (try 1/3)
[15605.897327] wlp4s0: authenticated
[15605.903406] wlp4s0: associate with b4:75:0e:99:1f:e0 (try 1/3)
[15605.904771] wlp4s0: RX AssocResp from b4:75:0e:99:1f:e0 (capab=0x11 status=0 aid=2)
[15605.905850] wlp4s0: associated
[15605.905895] IPv6: ADDRCONF(NETDEV_CHANGE): wlp4s0: link becomes ready
[15632.617250] wlp4s0: disconnect from AP b4:75:0e:99:1f:e0 for new auth to b4:75:0e:99:1f:df
[15632.621364] ------------[ cut here ]------------
[15632.621377] WARNING: CPU: 0 PID: 1012 at drivers/net/wireless/intel/iwlwifi/mvm/sta.c:1539 iwl_mvm_rm_sta+0x3ce/0x450 [iwlmvm]
[15632.621378] Modules linked in: iwlmvm iwlwifi rfcomm fuse ctr ccm arc4 bnep snd_hda_codec_hdmi snd_hda_codec_conexant snd_hda_codec_generic snd_hda_intel snd_hda_codec snd_hwdep snd_hda_core snd_pcm snd_seq_midi snd_seq_midi_event snd_rawmidi snd_seq snd_seq_device mac80211 binfmt_misc snd_timer uvcvideo x86_pkg_temp_thermal intel_powerclamp kvm_intel videobuf2_vmalloc kvm snd videobuf2_memops nls_iso8859_1 nls_cp437 irqbypass aesni_intel videobuf2_v4l2 aes_x86_64 videobuf2_core crypto_simd btusb vfat cryptd fat glue_helper videodev soundcore btintel cfg80211 bluetooth hid_generic usbhid hid psmouse i915 e1000e ptp pps_core xhci_pci xhci_hcd intel_gtt [last unloaded: iwlwifi]
[15632.621417] CPU: 0 PID: 1012 Comm: wpa_supplicant Tainted: G     U  W       4.10.0+ #17
[15632.621418] Hardware name: LENOVO 20FBCTO1WW/20FBCTO1WW, BIOS N1FET45W (1.19 ) 11/08/2016
[15632.621419] Call Trace:
[15632.621424]  dump_stack+0x4d/0x63
[15632.621427]  __warn+0xcb/0xf0
[15632.621430]  warn_slowpath_null+0x1d/0x20
[15632.621436]  iwl_mvm_rm_sta+0x3ce/0x450 [iwlmvm]
[15632.621442]  iwl_mvm_mac_sta_state+0x3fb/0x590 [iwlmvm]
[15632.621455]  drv_sta_state+0x83/0x4b0 [mac80211]
[15632.621468]  __sta_info_destroy_part2+0x128/0x160 [mac80211]
[15632.621480]  __sta_info_flush+0xdb/0x180 [mac80211]
[15632.621497]  ieee80211_set_disassoc+0xba/0x3c0 [mac80211]
[15632.621512]  ieee80211_mgd_auth+0x2f5/0x330 [mac80211]
[15632.621528]  ieee80211_auth+0x18/0x20 [mac80211]
[15632.621544]  cfg80211_mlme_auth+0xf3/0x210 [cfg80211]
[15632.621558]  nl80211_authenticate+0x2e0/0x340 [cfg80211]
[15632.621562]  genl_family_rcv_msg+0x1b5/0x360
[15632.621565]  genl_rcv_msg+0x59/0xa0
[15632.621567]  ? genl_register_family+0x630/0x630
[15632.621569]  netlink_rcv_skb+0x97/0xb0
[15632.621572]  genl_rcv+0x28/0x40
[15632.621574]  netlink_unicast+0x181/0x210
[15632.621576]  netlink_sendmsg+0x2d8/0x390
[15632.621579]  sock_sendmsg+0x38/0x50
[15632.621581]  ___sys_sendmsg+0x25f/0x270
[15632.621582]  ? ___sys_recvmsg+0x141/0x1b0
[15632.621585]  ? iput+0x1c5/0x240
[15632.621587]  ? dentry_free+0x4e/0x80
[15632.621589]  ? mntput_no_expire+0x2c/0x1b0
[15632.621590]  ? mntput+0x24/0x40
[15632.621592]  ? __fput+0x174/0x1e0
[15632.621594]  __sys_sendmsg+0x45/0x80
[15632.621597]  SyS_sendmsg+0x12/0x20
[15632.621600]  entry_SYSCALL_64_fastpath+0x13/0x94
[15632.621601] RIP: 0033:0x7f78c96308a0
[15632.621602] RSP: 002b:00007fff813000f8 EFLAGS: 00000246 ORIG_RAX: 000000000000002e
[15632.621604] RAX: ffffffffffffffda RBX: 0000000000000013 RCX: 00007f78c96308a0
[15632.621606] RDX: 0000000000000000 RSI: 00007fff81300180 RDI: 0000000000000007
[15632.621606] RBP: 0000556ff484221c R08: 0000000000000000 R09: 00000000000000df
[15632.621607] R10: 0000556ff4811de0 R11: 0000000000000246 R12: 0000556ff484221c
[15632.621608] R13: 0000556ff4857490 R14: 0000000000000000 R15: 0000000000000000
[15632.621610] ---[ end trace 4da4612127066e07 ]---
[15632.627578] wlp4s0: authenticate with b4:75:0e:99:1f:df
[15632.636345] wlp4s0: send auth to b4:75:0e:99:1f:df (try 1/3)
[15632.650504] wlp4s0: authenticated
[15632.655376] wlp4s0: associate with b4:75:0e:99:1f:df (try 1/3)
[15632.660036] wlp4s0: RX AssocResp from b4:75:0e:99:1f:df (capab=0x1411 status=0 aid=1)
[15632.675702] wlp4s0: associated
[15759.464681] ------------[ cut here ]------------
[15759.464718] WARNING: CPU: 1 PID: 23668 at drivers/net/wireless/intel/iwlwifi/mvm/sta.c:1539 iwl_mvm_rm_sta+0x3ce/0x450 [iwlmvm]
[15759.464720] Modules linked in: iwlmvm iwlwifi rfcomm fuse ctr ccm arc4 bnep snd_hda_codec_hdmi snd_hda_codec_conexant snd_hda_codec_generic snd_hda_intel snd_hda_codec snd_hwdep snd_hda_core snd_pcm snd_seq_midi snd_seq_midi_event snd_rawmidi snd_seq snd_seq_device mac80211 binfmt_misc snd_timer uvcvideo x86_pkg_temp_thermal intel_powerclamp kvm_intel videobuf2_vmalloc kvm snd videobuf2_memops nls_iso8859_1 nls_cp437 irqbypass aesni_intel videobuf2_v4l2 aes_x86_64 videobuf2_core crypto_simd btusb vfat cryptd fat glue_helper videodev soundcore btintel cfg80211 bluetooth hid_generic usbhid hid psmouse i915 e1000e ptp pps_core xhci_pci xhci_hcd intel_gtt [last unloaded: iwlwifi]
[15759.464819] CPU: 1 PID: 23668 Comm: kworker/u8:4 Tainted: G     U  W       4.10.0+ #17
[15759.464822] Hardware name: LENOVO 20FBCTO1WW/20FBCTO1WW, BIOS N1FET45W (1.19 ) 11/08/2016
[15759.464871] Workqueue: phy1 ieee80211_iface_work [mac80211]
[15759.464875] Call Trace:
[15759.464889]  dump_stack+0x4d/0x63
[15759.464897]  __warn+0xcb/0xf0
[15759.464904]  warn_slowpath_null+0x1d/0x20
[15759.464925]  iwl_mvm_rm_sta+0x3ce/0x450 [iwlmvm]
[15759.464939]  iwl_mvm_mac_sta_state+0x3fb/0x590 [iwlmvm]
[15759.464971]  drv_sta_state+0x83/0x4b0 [mac80211]
[15759.465002]  __sta_info_destroy_part2+0x128/0x160 [mac80211]
[15759.465033]  __sta_info_flush+0xdb/0x180 [mac80211]
[15759.465079]  ieee80211_set_disassoc+0xba/0x3c0 [mac80211]
[15759.465121]  ieee80211_sta_connection_lost.constprop.23+0x2a/0x50 [mac80211]
[15759.465161]  ieee80211_sta_work+0x1f3/0x1440 [mac80211]
[15759.465168]  ? update_curr+0x76/0x190
[15759.465173]  ? dequeue_task_fair+0x612/0x1830
[15759.465212]  ieee80211_iface_work+0x332/0x430 [mac80211]
[15759.465218]  ? finish_task_switch+0x78/0x200
[15759.465227]  process_one_work+0x1f3/0x4a0
[15759.465234]  worker_thread+0x48/0x4e0
[15759.465240]  kthread+0x101/0x140
[15759.465247]  ? process_one_work+0x4a0/0x4a0
[15759.465252]  ? kthread_create_on_node+0x40/0x40
[15759.465260]  ret_from_fork+0x29/0x40
[15759.465267] ---[ end trace 4da4612127066e08 ]---
[15759.473252] iwlwifi 0000:04:00.0: Failed to find station
[15759.473267] wlp4s0: failed to remove key (2, ff:ff:ff:ff:ff:ff) from hardware (-22)
[15759.596780] wlp4s0: authenticate with b4:75:0e:99:1f:e0
[15759.605604] wlp4s0: send auth to b4:75:0e:99:1f:e0 (try 1/3)
[15759.607833] wlp4s0: authenticated
[15759.617745] wlp4s0: associate with b4:75:0e:99:1f:e0 (try 1/3)
[15759.619111] wlp4s0: RX AssocResp from b4:75:0e:99:1f:e0 (capab=0x11 status=0 aid=2)
[15759.620061] wlp4s0: associated

-- 
Jens Axboe

WARNING: CPU: 1 PID: 23668 at drivers/net/wireless/intel/iwlwifi/mvm/sta.c:1539 iwl_mvm_rm_sta+0x3ce/0x450

[Jens Axboe]

Hi,

I'm hitting this one a lot with current -git, which is this one:

if (iwl_mvm_is_dqa_supported(mvm)) {                            
        iwl_mvm_disable_sta_queues(mvm, vif, mvm_sta);          
        /*                                                      
         * If pending_frames is set at this point - it must be  
         * driver internal logic error, since queues are empty  
         * and removed successuly.                              
         * warn on it but set it to 0 anyway to avoid station   
         * not being removed later in the function              
         */                                                     
        WARN_ON(atomic_xchg(&mvm->pending_frames[sta_id], 0));  
}

It's hit 4 times over the last day. The bug is probably older than the
commit that added this warning:

commit 94c3e614df2117626fccfac8f821c66e30556384
Author: Sara Sharon <sara.sharon@intel.com>
Date:   Wed Dec 7 15:04:37 2016 +0200

    iwlwifi: mvm: fix pending frame counter calculation

but the pestering is new.

-- 
Jens Axboe