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  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 
>> 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 

to the patch.

-- 
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: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  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 
> 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.

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  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.54]  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]  

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  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  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 
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

[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  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

[Coelho, Luciano]

On Fri, 2017-03-10 at 14:01 +0200, 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  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.

And of course, the link I wanted to give you is this:

[1] https://wireless.wiki.kernel.org/en/users/drivers/iwlwifi/debugging#tracing


--
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]

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  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

[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  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

[Jens Axboe]

On 03/01/2017 08:33 PM, Luca Coelho wrote:
> Hi Jens,
> 
> On Mar 1, 2017 20:25, Jens Axboe  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 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(>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 
>> 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

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(>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 
Date:   Wed Dec 7 15:04:37 2016 +0200

iwlwifi: mvm: fix pending frame counter calculation

but the pestering is new.

-- 
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]

]  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:7fff813000f8 EFLAGS: 0246 ORIG_RAX: 
002e
[15632.621604] RAX: ffda RBX: 0013 RCX: 7f78c96308a0
[15632.621606] RDX:  RSI: 7fff81300180 RDI: 0007
[15632.621606] RBP: 556ff484221c R08:  R09: 00df
[15632.621607] R10: 556ff4811de0 R11: 0246 R12: 556ff484221c
[15632.621608] R13: 556ff4857490 R14:  R15: 
[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 :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