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

[Luca Coelho <luca@coelho.fi>]

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.