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

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

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

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

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

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

[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

[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

[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

[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