All of lore.kernel.org
 help / color / mirror / Atom feed
* AMPDU stalls with brcmfmac4366b-pcie.bin triggering WARNINGs
@ 2016-09-14  5:45 Rafał Miłecki
  2016-09-14  7:25 ` Rafał Miłecki
                   ` (2 more replies)
  0 siblings, 3 replies; 6+ messages in thread
From: Rafał Miłecki @ 2016-09-14  5:45 UTC (permalink / raw)
  To: Hante Meuleman, Arend van Spriel, brcm80211-dev-list
  Cc: linux-wireless, Rafał Miłecki

Hi,

Even with the most recent brcmfmac code ppl keep seeing WARNINGs from
brcmf_netdev_wait_pend8021x [0].

Hante suggested using CONSOLE for debugging some firmware crash so I
decided to see I it could also help understanding WARNINGs. I believe it
did.

First of all, I can't reproduce these problems reliably. One evening I
got WARNINGs one by one and I could work on my debugging patch easily.
Yesterday when I got my patch complete, it took me 10+ hours to get a
single WARNING.

Anyway, it seems to me that sometimes AMPDU stalls in the firmware. It
seems firmware has some AMPDU watchdog that notices the problem and
kicks in. It prints some debugging info and starts cleaning up process.

If brcmf_netdev_wait_pend8021x gets called shortly after that (I set
wpa_group_rekey=30 in hostapd to get brcmf_cfg80211_add_key called more
often) it results in a WARNING.

For better debugging I wrote brcmfmac patch that:
1) Keeps track of every 802.1x skb submitted to the device
2) During WARNING it prints skbs and marks them as timedout
3) It informs when timedout skb gets finally reported as sent

Enough talking, please take a look at my debugging log. Does it give you
enough hint? Could you review/debug firmware's code responsible for
AMPDU? FWIW Merlin users (so no brcmfmac invovled) also saw this [1].

[  913.569121] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c7369480 brcmf_ifname(ifp):wlan1
[  913.579521] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c70cd480 brcmf_ifname(ifp):wlan0
[  913.627346] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c71a1480 brcmf_ifname(ifp):wlan1-1
[  913.839833] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c6464c80 brcmf_ifname(ifp):wlan0-1
[  914.179775] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c64cac80 brcmf_ifname(ifp):wlan0-2
[  914.191129] brcmfmac: CONSOLE: 027644.261 wl0.3: wlc_send_bar: seq 0x3 tid 0
[  914.198474] brcmfmac: CONSOLE: 027644.266 wl0.3: wlc_send_bar: seq 0x3 tid 0
[  914.206020] brcmfmac: CONSOLE: 027644.273 wl0.3: wlc_send_bar: seq 0x3 tid 0
[  914.215243] brcmfmac: CONSOLE: 027644.284 wl0.3: wlc_send_bar: seq 0x3 tid 0
[  914.224521] brcmfmac: CONSOLE: 027644.294 wl0.3: wlc_send_bar: seq 0x3 tid 0
[  914.231878] brcmfmac: CONSOLE: 027644.298 wl0.3: wlc_send_bar: seq 0x3 tid 0
[  914.239425] brcmfmac: CONSOLE: 027644.307 wl0.3: wlc_send_bar: seq 0x3 tid 0
[  914.248444] brcmfmac: CONSOLE: 027644.318 wl0.3: wlc_send_bar: seq 0x3 tid 0
[  914.257163] brcmfmac: CONSOLE: 027644.326 wl0.3: wlc_send_bar: seq 0x3 tid 0
[  914.266616] brcmfmac: CONSOLE: 027644.336 wl0.3: wlc_send_bar: seq 0x3 tid 0
[  914.274072] brcmfmac: CONSOLE: 027644.341 wl0.3: wlc_send_bar: seq 0x3 tid 0
[  914.284716] brcmfmac: CONSOLE: 027644.354 wl0.3: wlc_send_bar: seq 0x3 tid 0
[  914.291962] brcmfmac: CONSOLE: 027644.359 wl0.3: wlc_send_bar: seq 0x3 tid 0
[  914.299172] brcmfmac: CONSOLE: 027644.364 wl0.3: wlc_send_bar: seq 0x3 tid 0
[  914.306646] brcmfmac: CONSOLE: 027644.371 wl0.3: wlc_send_bar: seq 0x3 tid 0
[  914.314058] brcmfmac: CONSOLE: 027644.380 wl0.3: wlc_send_bar: seq 0x3 tid 0
[  914.323193] brcmfmac: CONSOLE: 027644.393 wl0.3: wlc_send_bar: seq 0x3 tid 0
[  914.330640] brcmfmac: CONSOLE: 027644.400 wl0.3: wlc_send_bar: seq 0x3 tid 0
[  914.340886] brcmfmac: CONSOLE: 027644.410 wl0.3: wlc_send_bar: seq 0x3 tid 0
[  914.352975] brcmfmac: CONSOLE: 027644.422 wl0.3: wlc_send_bar: seq 0x3 tid 0
[  914.365365] brcmfmac: CONSOLE: 027644.434 wl0.3: wlc_send_bar: seq 0x3 tid 0
[  914.372790] brcmfmac: CONSOLE: 027644.440 wl0.3: wlc_send_bar: seq 0x3 tid 0
[  914.384982] brcmfmac: CONSOLE: 027644.454 wl0.3: wlc_send_bar: seq 0x3 tid 0
[  914.395488] brcmfmac: CONSOLE: 027644.465 wl0.3: wlc_send_bar: seq 0x3 tid 0
[  914.402977] brcmfmac: CONSOLE: 027644.471 wl0.3: wlc_send_bar: seq 0x3 tid 0
[  914.701404] brcmfmac: CONSOLE: 027644.771 wl0.3: wlc_send_bar: seq 0x4 tid 0
[  914.710513] brcmfmac: CONSOLE: 027644.780 wl0.3: wlc_send_bar: seq 0x4 tid 0
[  914.717731] brcmfmac: CONSOLE: 027644.787 wl0.3: wlc_send_bar: seq 0x4 tid 0
[  914.728099] brcmfmac: CONSOLE: 027644.798 wl0.3: wlc_send_bar: seq 0x4 tid 0
[  914.737616] brcmfmac: CONSOLE: 027644.807 wl0.3: wlc_send_bar: seq 0x4 tid 0
[  914.745320] brcmfmac: CONSOLE: 027644.815 wl0.3: wlc_send_bar: seq 0x4 tid 0
[  914.757985] brcmfmac: CONSOLE: 027644.827 wl0.3: wlc_send_bar: seq 0x4 tid 0
[  914.765457] brcmfmac: CONSOLE: 027644.833 wl0.3: wlc_send_bar: seq 0x4 tid 0
[  914.772729] brcmfmac: CONSOLE: 027644.841 wl0.3: wlc_send_bar: seq 0x4 tid 0
[  914.781407] brcmfmac: CONSOLE: 027644.851 wl0.3: wlc_send_bar: seq 0x4 tid 0
[  914.789268] brcmfmac: CONSOLE: 027644.859 wl0.3: wlc_send_bar: seq 0x4 tid 0
[  914.796754] brcmfmac: CONSOLE: 027644.866 wl0.3: wlc_send_bar: seq 0x4 tid 0
[  914.808174] brcmfmac: CONSOLE: 027644.878 wl0.3: wlc_send_bar: seq 0x4 tid 0
[  914.818975] brcmfmac: CONSOLE: 027644.888 wl0.3: wlc_send_bar: seq 0x4 tid 0
[  917.077991] brcmfmac: CONSOLE: 027647.149 ampdu_dbg: wl0.3 scb:00347c74 tid:0 
[  917.085368] brcmfmac: CONSOLE: 027647.149 ampdu_dbg: wl0.3 dead_cnt 2 tx_in_transit 1 psm_mux 0xfff0 aqmqmap 0x0x101 aqmfifo_status 0x0x4000 fifordy 0x0 cpbusy 0x0
[  917.100070] brcmfmac: CONSOLE: 027647.149 ampdu_dbg: ifsstat 0xaf nav_stat 0x0 txop 30788
[  917.108303] brcmfmac: CONSOLE: 027647.149 ampdu_dbg: pktpend: 0 2 0 0 0 ap 1
[  917.115434] brcmfmac: CONSOLE: 027647.149 ampdu_dbg: txall 5901 txbcn 0 txrts 0 rxcts 0 rsptmout 0 rxstrt 0
[  917.125265] brcmfmac: CONSOLE: 027647.149 ampdu_dbg: cwcur0-3 f f 7 3 bslots cur/0-3 9 0 9 0 0 ifs_boff 0
[  917.134907] brcmfmac: CONSOLE: 027647.149 ampdu_dbg: again1 ifsstat 0xaf nav_stat 0x0
[  917.142806] brcmfmac: CONSOLE: 027647.149 ampdu_dbg: again2 ifsstat 0xaf nav_stat 0x0
[  917.150739] brcmfmac: CONSOLE: 027647.149 wl0: wlc_ampdu_watchdog: cleaning up ini tid 0 due to no progress for 2 secs tx_in_transit 1
[  917.162912] brcmfmac: CONSOLE: 027647.149 wl0: wlc_ampdu_tx_send_delba: tid 0 initiator 1 reason 39
[  917.718723] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c6518c80 brcmf_ifname(ifp):wlan1-2
[  918.678558] ------------[ cut here ]------------
[  918.683329] WARNING: CPU: 1 PID: 1145 at compat-wireless-2016-06-20/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.c:1219 brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac]()
[  918.699599] Modules linked in: pppoe ppp_async iptable_nat brcmfmac pppox ppp_generic nf_nat_ipv4 nf_conntrack_ipv6 nf_conntrack_ipv4 ipt_REJECT ipt_MASQUERADE cfg80211 xt_time xt_tcpudp xt_state xt_nat xt_multiport xt_mark xt_mac xt_limit xt_id xt_conntrack xt_commed
[  918.771954] CPU: 1 PID: 1145 Comm: hostapd Not tainted 4.4.19 #0
[  918.777971] Hardware name: BCM5301X
[  918.781461] Backtrace: 
[  918.783938] [<c001708c>] (dump_backtrace) from [<c0017288>] (show_stack+0x18/0x1c)
[  918.791523]  r7:000004c3 r6:bf1d0e9c r5:60000013 r4:00000000
[  918.797240] [<c0017270>] (show_stack) from [<c017c210>] (dump_stack+0x84/0xa4)
[  918.804480] [<c017c18c>] (dump_stack) from [<c0021490>] (warn_slowpath_common+0x8c/0xb8)
[  918.812587]  r5:00000009 r4:00000000
[  918.816184] [<c0021404>] (warn_slowpath_common) from [<c0021560>] (warn_slowpath_null+0x24/0x2c)
[  918.824981]  r8:c72f10a4 r7:00000001 r6:c64f7b3c r5:00000000 r4:c6518c80
[  918.831764] [<c002153c>] (warn_slowpath_null) from [<bf1be578>] (brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac])
[  918.842243] [<bf1be4bc>] (brcmf_netdev_wait_pend8021x [brcmfmac]) from [<bf1ab200>] (brcmf_cfg80211_sched_scan_start+0x460/0x6c0 [brcmfmac])
[  918.854870]  r8:c72f10a4 r7:bf1c8613 r6:c6518c80 r5:c04903c8 r4:c72f1394
[  918.861641] [<bf1ab13c>] (brcmf_cfg80211_sched_scan_start [brcmfmac]) from [<bf1ad740>] (brcmf_cfg80211_add_key+0x2e0/0x3dc [brcmfmac])
[  918.873836]  r7:00000000 r6:c6518c80 r5:c72f10a4 r4:00000004
[  918.879578] [<bf1ad460>] (brcmf_cfg80211_add_key [brcmfmac]) from [<bf160b48>] (nl80211_new_key+0xfc/0x128 [cfg80211])
[  918.890296]  r10:00000014 r9:c7250800 r8:c64f7ca0 r7:c72de000 r6:c6518800 r5:00000000
[  918.898181]  r4:bf1ad460
[  918.900751] [<bf160a4c>] (nl80211_new_key [cfg80211]) from [<c0286f40>] (genl_rcv_msg+0x260/0x2e4)
[  918.909723]  r8:c5d50300 r7:c658b614 r6:bf170540 r5:bf1787d0 r4:00000000
[  918.916482] [<c0286ce0>] (genl_rcv_msg) from [<c0286260>] (netlink_rcv_skb+0x60/0xbc)
[  918.924328]  r10:c5d50300 r9:00000000 r8:c64f7d84 r7:c6b0e400 r6:c0286ce0 r5:c5d50300
[  918.932214]  r4:c658b600
[  918.934761] [<c0286200>] (netlink_rcv_skb) from [<c0286ccc>] (genl_rcv+0x28/0x3c)
[  918.942258]  r7:c6b0e400 r6:c5d50300 r5:c5d50300 r4:c04a42a0
[  918.947965] [<c0286ca4>] (genl_rcv) from [<c0285c48>] (netlink_unicast+0x138/0x1f4)
[  918.955637]  r5:00000048 r4:c7952000
[  918.959236] [<c0285b10>] (netlink_unicast) from [<c02860c8>] (netlink_sendmsg+0x300/0x320)
[  918.967517]  r9:00000008 r8:00000000 r7:00000048 r6:c64f7f4c r5:c6b0e400 r4:00000000
[  918.975324] [<c0285dc8>] (netlink_sendmsg) from [<c0248de4>] (sock_sendmsg+0x1c/0x2c)
[  918.983167]  r10:00000000 r9:00000000 r8:00000000 r7:c7544900 r6:c64f7e64 r5:00000000
[  918.991053]  r4:c64f7f4c
[  918.993598] [<c0248dc8>] (sock_sendmsg) from [<c0249398>] (___sys_sendmsg+0x198/0x228)
[  919.001529] [<c0249200>] (___sys_sendmsg) from [<c024a1ec>] (__sys_sendmsg+0x44/0x68)
[  919.009375]  r10:00000000 r9:c64f6000 r8:c00098c4 r7:00000128 r6:00000000 r5:bee617c0
[  919.017260]  r4:c7544900
[  919.019807] [<c024a1a8>] (__sys_sendmsg) from [<c024a220>] (SyS_sendmsg+0x10/0x14)
[  919.027393]  r6:00003000 r5:00000000 r4:00000000
[  919.032046] [<c024a210>] (SyS_sendmsg) from [<c0009700>] (ret_fast_syscall+0x0/0x3c)
[  919.039829] ---[ end trace ab86393507c49518 ]---
[  919.044467] brcmfmac: [brcmf_netdev_wait_pend8021x] ifp:c6518c80 brcmf_ifname(ifp):wlan1-2 brcmf_get_pend_8021x_cnt(ifp):2
[  919.055542] brcmfmac: [brcmf_netdev_wait_pend8021x] List of pending 802.1x skbs:
[  919.062956] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c7269780 skb->dev:c6518800 skb->dev->name:wlan1-2
[  919.072547] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c72693c0 skb->dev:c6518800 skb->dev->name:wlan1-2
[  919.082148] brcmfmac: [brcmf_msgbuf_process_txstatus -> __brcmf_txfinalize] Finally finalizing skb:c7269780 skb->dev:c6518800 skb->dev->name:wlan1-2
[  919.098449] brcmfmac: [brcmf_cfg80211_del_key -> __send_key_to_dongle] ifp:c6518c80 brcmf_ifname(ifp):wlan1-2
[  920.058595] ------------[ cut here ]------------
[  920.063473] WARNING: CPU: 1 PID: 1145 at compat-wireless-2016-06-20/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.c:1219 brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac]()
[  920.079937] Modules linked in: pppoe ppp_async iptable_nat brcmfmac pppox ppp_generic nf_nat_ipv4 nf_conntrack_ipv6 nf_conntrack_ipv4 ipt_REJECT ipt_MASQUERADE cfg80211 xt_time xt_tcpudp xt_state xt_nat xt_multiport xt_mark xt_mac xt_limit xt_id xt_conntrack xt_commed
[  920.152313] CPU: 1 PID: 1145 Comm: hostapd Tainted: G        W       4.4.19 #0
[  920.159547] Hardware name: BCM5301X
[  920.163038] Backtrace: 
[  920.165515] [<c001708c>] (dump_backtrace) from [<c0017288>] (show_stack+0x18/0x1c)
[  920.173101]  r7:000004c3 r6:bf1d0e9c r5:60000013 r4:00000000
[  920.178818] [<c0017270>] (show_stack) from [<c017c210>] (dump_stack+0x84/0xa4)
[  920.186056] [<c017c18c>] (dump_stack) from [<c0021490>] (warn_slowpath_common+0x8c/0xb8)
[  920.194164]  r5:00000009 r4:00000000
[  920.197761] [<c0021404>] (warn_slowpath_common) from [<c0021560>] (warn_slowpath_null+0x24/0x2c)
[  920.206558]  r8:c5d50300 r7:00000001 r6:c64f7b74 r5:00000000 r4:c6518c80
[  920.213343] [<c002153c>] (warn_slowpath_null) from [<bf1be578>] (brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac])
[  920.223820] [<bf1be4bc>] (brcmf_netdev_wait_pend8021x [brcmfmac]) from [<bf1ab200>] (brcmf_cfg80211_sched_scan_start+0x460/0x6c0 [brcmfmac])
[  920.236447]  r8:c5d50300 r7:bf1c85fc r6:c6518c80 r5:c04903c8 r4:c72f12f0
[  920.243218] [<bf1ab13c>] (brcmf_cfg80211_sched_scan_start [brcmfmac]) from [<bf1ad420>] (brcmf_cfg80211_del_key+0xb0/0xf0 [brcmfmac])
[  920.255240]  r7:c6518c80 r6:00000002 r5:c72f1254 r4:c72f1000
[  920.260981] [<bf1ad370>] (brcmf_cfg80211_del_key [brcmfmac]) from [<bf1608b8>] (nl80211_del_key+0xf4/0x148 [cfg80211])
[  920.271699]  r7:c72de000 r6:c6518800 r5:c70c5620 r4:bf1ad370
[  920.277429] [<bf1607c4>] (nl80211_del_key [cfg80211]) from [<c0286f40>] (genl_rcv_msg+0x260/0x2e4)
[  920.286400]  r7:c70c5614 r6:bf170554 r5:bf1787d0 r4:00000000
[  920.292106] [<c0286ce0>] (genl_rcv_msg) from [<c0286260>] (netlink_rcv_skb+0x60/0xbc)
[  920.299952]  r10:c5d50300 r9:00000000 r8:c64f7d84 r7:c6b0e400 r6:c0286ce0 r5:c5d50300
[  920.307837]  r4:c70c5600
[  920.310384] [<c0286200>] (netlink_rcv_skb) from [<c0286ccc>] (genl_rcv+0x28/0x3c)
[  920.317882]  r7:c6b0e400 r6:c5d50300 r5:c5d50300 r4:c04a42a0
[  920.323588] [<c0286ca4>] (genl_rcv) from [<c0285c48>] (netlink_unicast+0x138/0x1f4)
[  920.331261]  r5:00000030 r4:c7952000
[  920.334859] [<c0285b10>] (netlink_unicast) from [<c02860c8>] (netlink_sendmsg+0x300/0x320)
[  920.343141]  r9:00000008 r8:00000000 r7:00000030 r6:c64f7f4c r5:c6b0e400 r4:00000000
[  920.350947] [<c0285dc8>] (netlink_sendmsg) from [<c0248de4>] (sock_sendmsg+0x1c/0x2c)
[  920.358790]  r10:00000000 r9:00000000 r8:00000000 r7:c7544900 r6:c64f7e64 r5:00000000
[  920.366677]  r4:c64f7f4c
[  920.369222] [<c0248dc8>] (sock_sendmsg) from [<c0249398>] (___sys_sendmsg+0x198/0x228)
[  920.377162] [<c0249200>] (___sys_sendmsg) from [<c024a1ec>] (__sys_sendmsg+0x44/0x68)
[  920.385007]  r10:00000000 r9:c64f6000 r8:c00098c4 r7:00000128 r6:00000000 r5:bee61790
[  920.392893]  r4:c7544900
[  920.395439] [<c024a1a8>] (__sys_sendmsg) from [<c024a220>] (SyS_sendmsg+0x10/0x14)
[  920.403024]  r6:00003000 r5:00000000 r4:00000000
[  920.407678] [<c024a210>] (SyS_sendmsg) from [<c0009700>] (ret_fast_syscall+0x0/0x3c)
[  920.415462] ---[ end trace ab86393507c49519 ]---
[  920.420108] brcmfmac: [brcmf_netdev_wait_pend8021x] ifp:c6518c80 brcmf_ifname(ifp):wlan1-2 brcmf_get_pend_8021x_cnt(ifp):1
[  920.431188] brcmfmac: [brcmf_netdev_wait_pend8021x] List of pending 802.1x skbs:
[  920.438608] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c72693c0 skb->dev:c6518800 skb->dev->name:wlan1-2
[  921.488695] brcmfmac: CONSOLE: 027651.562 wl0: Proxy STA 78:d6:f0:9b:ba:bc link is already gone !!??
[  921.498112] brcmfmac: [brcmf_msgbuf_process_txstatus -> __brcmf_txfinalize] Finally finalizing skb:c72693c0 skb->dev:c6518800 skb->dev->name:wlan1-2
[  943.599077] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c7369480 brcmf_ifname(ifp):wlan1
[  943.609854] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c70cd480 brcmf_ifname(ifp):wlan0
[  943.642073] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c71a1480 brcmf_ifname(ifp):wlan1-1
[  943.859842] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c6464c80 brcmf_ifname(ifp):wlan0-1
[  944.189138] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c6518c80 brcmf_ifname(ifp):wlan1-2
[  944.209834] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c64cac80 brcmf_ifname(ifp):wlan0-2

[0] https://forum.openwrt.org/viewtopic.php?pid=335019#p335019
[1] http://www.snbforums.com/threads/alpha-builds-for-rt-ac88u-and-rt-ac3100.28024/#post-215754
---
 .../broadcom/brcm80211/brcmfmac/cfg80211.c         |  4 +-
 .../wireless/broadcom/brcm80211/brcmfmac/core.c    | 66 +++++++++++++++++++++-
 .../wireless/broadcom/brcm80211/brcmfmac/core.h    | 15 ++++-
 .../broadcom/brcm80211/brcmfmac/flowring.c         |  2 +
 .../broadcom/brcm80211/brcmfmac/fwsignal.c         | 12 +++-
 .../wireless/broadcom/brcm80211/brcmfmac/msgbuf.c  |  3 +
 .../net/wireless/broadcom/brcm80211/brcmfmac/usb.c |  3 +
 .../wireless/broadcom/brcm80211/brcmutil/utils.c   |  2 +-
 .../broadcom/brcm80211/include/brcmu_utils.h       |  2 +-
 9 files changed, 101 insertions(+), 8 deletions(-)

diff --git a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/cfg80211.c b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/cfg80211.c
index 201a980..c7ccea5 100644
--- a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/cfg80211.c
+++ b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/cfg80211.c
@@ -464,11 +464,12 @@ static void convert_key_from_CPU(struct brcmf_wsec_key *key,
 }
 
 static int
-send_key_to_dongle(struct brcmf_if *ifp, struct brcmf_wsec_key *key)
+__send_key_to_dongle(const char *c0, struct brcmf_if *ifp, struct brcmf_wsec_key *key)
 {
 	int err;
 	struct brcmf_wsec_key_le key_le;
 
+	pr_info("[%s -> %s] ifp:%p brcmf_ifname(ifp):%s\n", c0, __func__, ifp, brcmf_ifname(ifp));
 	convert_key_from_CPU(key, &key_le);
 
 	brcmf_netdev_wait_pend8021x(ifp);
@@ -480,6 +481,7 @@ send_key_to_dongle(struct brcmf_if *ifp, struct brcmf_wsec_key *key)
 		brcmf_err("wsec_key error (%d)\n", err);
 	return err;
 }
+#define send_key_to_dongle(ifp, key)	__send_key_to_dongle(__func__, ifp, key)
 
 static s32
 brcmf_configure_arp_nd_offload(struct brcmf_if *ifp, bool enable)
diff --git a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.c b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.c
index 8d16f02..cc02e3d 100644
--- a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.c
+++ b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.c
@@ -38,6 +38,30 @@
 #include "pcie.h"
 #include "common.h"
 
+/* Free the driver packet. Free the tag if present */
+void __brcmu_pkt_buf_free_skb(const char *c0, struct brcmf_if *ifp, struct sk_buff *skb)
+{
+	if (!skb)
+		return;
+
+	if (ifp) {
+		struct skb_list *e;
+
+		mutex_lock(&ifp->pend_8021x_mutex);
+		list_for_each_entry(e, &ifp->pend_8021x_skbs, list) {
+			if (e->skb == skb) {
+				pr_info("[%s -> %s] [ifp:%p] ***BUG*** skb:%p skb->dev:%p skb->dev->name:%s\n", c0, __func__, ifp, e->skb, e->skb->dev, e->skb->dev ? e->skb->dev->name : "---");
+			}
+		}
+		mutex_unlock(&ifp->pend_8021x_mutex);
+	} else if (strcmp(c0, "brcmf_msgbuf_query_dcmd")) {
+		pr_info("[%s -> %s] [ifp:%p] Freeing skb:%p skb->dev:%p skb->dev->name:%s\n", c0, __func__, ifp, skb, skb->dev, skb->dev ? skb->dev->name : "---");
+	}
+
+	WARN_ON(skb->next);
+	dev_kfree_skb_any(skb);
+}
+
 #define MAX_WAIT_FOR_8021X_TX			msecs_to_jiffies(950)
 
 #define BRCMF_BSSIDX_INVALID			-1
@@ -247,8 +271,17 @@ static netdev_tx_t brcmf_netdev_start_xmit(struct sk_buff *skb,
 		goto done;
 	}
 
-	if (eh->h_proto == htons(ETH_P_PAE))
+	if (eh->h_proto == htons(ETH_P_PAE)) {
+		struct skb_list *e;
+
+		e = kzalloc(sizeof(*e), GFP_KERNEL);
+		e->skb = skb;
+
 		atomic_inc(&ifp->pend_8021x_cnt);
+		mutex_lock(&ifp->pend_8021x_mutex);
+		list_add_tail(&e->list, &ifp->pend_8021x_skbs);
+		mutex_unlock(&ifp->pend_8021x_mutex);
+	}
 
 	ret = brcmf_fws_process_skb(ifp, skb);
 
@@ -333,7 +366,7 @@ static int brcmf_rx_hdrpull(struct brcmf_pub *drvr, struct sk_buff *skb,
 	if (ret || !(*ifp) || !(*ifp)->ndev) {
 		if (ret != -ENODATA && *ifp)
 			(*ifp)->stats.rx_errors++;
-		brcmu_pkt_buf_free_skb(skb);
+		__brcmu_pkt_buf_free_skb(__func__, *ifp, skb);
 		return -ENODATA;
 	}
 
@@ -378,7 +411,7 @@ void brcmf_rx_event(struct device *dev, struct sk_buff *skb)
 	brcmu_pkt_buf_free_skb(skb);
 }
 
-void brcmf_txfinalize(struct brcmf_if *ifp, struct sk_buff *txp, bool success)
+void __brcmf_txfinalize(const char *c0, struct brcmf_if *ifp, struct sk_buff *txp, bool success)
 {
 	struct ethhdr *eh;
 	u16 type;
@@ -387,7 +420,19 @@ void brcmf_txfinalize(struct brcmf_if *ifp, struct sk_buff *txp, bool success)
 	type = ntohs(eh->h_proto);
 
 	if (type == ETH_P_PAE) {
+		struct skb_list *e, *tmp;
+
 		atomic_dec(&ifp->pend_8021x_cnt);
+		mutex_lock(&ifp->pend_8021x_mutex);
+		list_for_each_entry_safe(e, tmp, &ifp->pend_8021x_skbs, list) {
+			if (e->skb == txp) {
+				if (e->timedout)
+					pr_info("[%s -> %s] Finally finalizing skb:%p skb->dev:%p skb->dev->name:%s\n", c0, __func__, e->skb, e->skb->dev, e->skb->dev ? e->skb->dev->name : "---");
+				list_del(&e->list);
+				kfree(e);
+			}
+		}
+		mutex_unlock(&ifp->pend_8021x_mutex);
 		if (waitqueue_active(&ifp->pend_8021x_wait))
 			wake_up(&ifp->pend_8021x_wait);
 	}
@@ -476,6 +521,8 @@ static int brcmf_netdev_open(struct net_device *ndev)
 	}
 
 	atomic_set(&ifp->pend_8021x_cnt, 0);
+	INIT_LIST_HEAD(&ifp->pend_8021x_skbs);
+	mutex_init(&ifp->pend_8021x_mutex);
 
 	/* Get current TOE mode from dongle */
 	if (brcmf_fil_iovar_int_get(ifp, "toe_ol", &toe_ol) >= 0
@@ -1170,6 +1217,19 @@ int brcmf_netdev_wait_pend8021x(struct brcmf_if *ifp)
 				 MAX_WAIT_FOR_8021X_TX);
 
 	WARN_ON(!err);
+	if (!err)
+		pr_info("[%s] ifp:%p brcmf_ifname(ifp):%s brcmf_get_pend_8021x_cnt(ifp):%d\n", __func__, ifp, brcmf_ifname(ifp), brcmf_get_pend_8021x_cnt(ifp));
+	if (!list_empty(&ifp->pend_8021x_skbs)) {
+		struct skb_list *e;
+
+		mutex_lock(&ifp->pend_8021x_mutex);
+		pr_info("[%s] List of pending 802.1x skbs:\n", __func__);
+		list_for_each_entry(e, &ifp->pend_8021x_skbs, list) {
+			e->timedout = true;
+			pr_info("[%s] skb:%p skb->dev:%p skb->dev->name:%s\n", __func__, e->skb, e->skb->dev, e->skb->dev ? e->skb->dev->name : "---");
+		}
+		mutex_unlock(&ifp->pend_8021x_mutex);
+	}
 
 	return !err;
 }
diff --git a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.h b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.h
index 8fa34ca..1509d4f 100644
--- a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.h
+++ b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.h
@@ -50,6 +50,9 @@
 
 #define NDOL_MAX_ENTRIES	8
 
+void __brcmu_pkt_buf_free_skb(const char *c0, struct brcmf_if *ifp, struct sk_buff *skb);
+#define brcmu_pkt_buf_free_skb(skb)	__brcmu_pkt_buf_free_skb(__func__, ifp, skb)
+
 /**
  * struct brcmf_ampdu_rx_reorder - AMPDU receive reorder info
  *
@@ -169,6 +172,12 @@ enum brcmf_netif_stop_reason {
 	BRCMF_NETIF_STOP_REASON_DISCONNECTED = BIT(2)
 };
 
+struct skb_list {
+	struct sk_buff *skb;
+	bool timedout;
+	struct list_head list;
+};
+
 /**
  * struct brcmf_if - interface control information.
  *
@@ -203,6 +212,9 @@ struct brcmf_if {
 	u8 netif_stop;
 	spinlock_t netif_stop_lock;
 	atomic_t pend_8021x_cnt;
+	struct list_head pend_8021x_skbs;
+	struct mutex pend_8021x_mutex;
+	bool pend_8021x_ready;
 	wait_queue_head_t pend_8021x_wait;
 	struct in6_addr ipv6_addr_tbl[NDOL_MAX_ENTRIES];
 	u8 ipv6addr_idx;
@@ -219,7 +231,8 @@ struct brcmf_if *brcmf_add_if(struct brcmf_pub *drvr, s32 bsscfgidx, s32 ifidx,
 void brcmf_remove_interface(struct brcmf_if *ifp, bool rtnl_locked);
 void brcmf_txflowblock_if(struct brcmf_if *ifp,
 			  enum brcmf_netif_stop_reason reason, bool state);
-void brcmf_txfinalize(struct brcmf_if *ifp, struct sk_buff *txp, bool success);
+void __brcmf_txfinalize(const char *c0, struct brcmf_if *ifp, struct sk_buff *txp, bool success);
+#define brcmf_txfinalize(ifp, txp, success)	__brcmf_txfinalize(__func__, ifp, txp, success)
 void brcmf_netif_rx(struct brcmf_if *ifp, struct sk_buff *skb);
 void brcmf_net_setcarrier(struct brcmf_if *ifp, bool on);
 void brcmf_c_set_joinpref_default(struct brcmf_if *ifp);
diff --git a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/flowring.c b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/flowring.c
index 7e269f9..87c8de0 100644
--- a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/flowring.c
+++ b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/flowring.c
@@ -249,6 +249,8 @@ void brcmf_flowring_delete(struct brcmf_flowring *flow, u16 flowid)
 
 	skb = skb_dequeue(&ring->skblist);
 	while (skb) {
+		struct brcmf_if *ifp = NULL;
+
 		brcmu_pkt_buf_free_skb(skb);
 		skb = skb_dequeue(&ring->skblist);
 	}
diff --git a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/fwsignal.c b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/fwsignal.c
index 9f9024a..41dd3fb 100644
--- a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/fwsignal.c
+++ b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/fwsignal.c
@@ -590,6 +590,8 @@ static void brcmf_fws_psq_flush(struct brcmf_fws_info *fws, struct pktq *q,
 	for (prec = 0; prec < q->num_prec; prec++) {
 		skb = brcmu_pktq_pdeq_match(q, prec, matchfn, &ifidx);
 		while (skb) {
+			struct brcmf_if *ifp = NULL;
+
 			brcmu_pkt_buf_free_skb(skb);
 			skb = brcmu_pktq_pdeq_match(q, prec, matchfn, &ifidx);
 		}
@@ -697,6 +699,8 @@ static void brcmf_fws_hanger_cleanup(struct brcmf_fws_info *fws,
 		    s == BRCMF_FWS_HANGER_ITEM_STATE_INUSE_SUPPRESSED) {
 			skb = h->items[i].pkt;
 			if (fn == NULL || fn(skb, &ifidx)) {
+				struct brcmf_if *ifp = NULL;
+
 				/* suppress packets freed from psq */
 				if (s == BRCMF_FWS_HANGER_ITEM_STATE_INUSE)
 					brcmu_pkt_buf_free_skb(skb);
@@ -845,6 +849,8 @@ static void brcmf_fws_bus_txq_cleanup(struct brcmf_fws_info *fws,
 	for (prec = 0; prec < txq->num_prec; prec++) {
 		skb = brcmu_pktq_pdeq_match(txq, prec, fn, &ifidx);
 		while (skb) {
+			struct brcmf_if *ifp = NULL;
+
 			hslot = brcmf_skb_htod_tag_get_field(skb, HSLOT);
 			hi = &fws->hanger.items[hslot];
 			WARN_ON(skb != hi->pkt);
@@ -971,8 +977,11 @@ static bool brcmf_fws_tim_update(struct brcmf_fws_info *fws,
 		brcmf_fws_unlock(fws);
 		err = brcmf_proto_txdata(fws->drvr, ifidx, data_offset, skb);
 		brcmf_fws_lock(fws);
-		if (err)
+		if (err) {
+			struct brcmf_if *ifp = NULL;
+
 			brcmu_pkt_buf_free_skb(skb);
+		}
 		return true;
 	}
 	return false;
@@ -2454,6 +2463,7 @@ bool brcmf_fws_fc_active(struct brcmf_fws_info *fws)
 
 void brcmf_fws_bustxfail(struct brcmf_fws_info *fws, struct sk_buff *skb)
 {
+	struct brcmf_if *ifp = NULL;
 	u32 hslot;
 
 	if (brcmf_skbcb(skb)->state == BRCMF_FWS_SKBSTATE_TIM) {
diff --git a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/msgbuf.c b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/msgbuf.c
index 2b9a2bc..e47f5a3 100644
--- a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/msgbuf.c
+++ b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/msgbuf.c
@@ -392,6 +392,8 @@ brcmf_msgbuf_release_array(struct device *dev,
 	count = 0;
 	do {
 		if (array[count].allocated.counter) {
+			struct brcmf_if *ifp = NULL;
+
 			pktid = &array[count];
 			dma_unmap_single(dev, pktid->physaddr,
 					 pktid->skb->len - pktid->data_offset,
@@ -483,6 +485,7 @@ static int brcmf_msgbuf_query_dcmd(struct brcmf_pub *drvr, int ifidx,
 {
 	struct brcmf_msgbuf *msgbuf = (struct brcmf_msgbuf *)drvr->proto->pd;
 	struct sk_buff *skb = NULL;
+	struct brcmf_if *ifp = NULL;
 	int timeout;
 	int err;
 
diff --git a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/usb.c b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/usb.c
index 2f978a3..edbe353 100644
--- a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/usb.c
+++ b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/usb.c
@@ -498,6 +498,7 @@ static void brcmf_usb_rx_complete(struct urb *urb)
 {
 	struct brcmf_usbreq  *req = (struct brcmf_usbreq *)urb->context;
 	struct brcmf_usbdev_info *devinfo = req->devinfo;
+	struct brcmf_if *ifp = NULL;
 	struct sk_buff *skb;
 
 	brcmf_dbg(USB, "Enter, urb->status=%d\n", urb->status);
@@ -548,6 +549,8 @@ static void brcmf_usb_rx_refill(struct brcmf_usbdev_info *devinfo,
 
 	ret = usb_submit_urb(req->urb, GFP_ATOMIC);
 	if (ret) {
+		struct brcmf_if *ifp = NULL;
+
 		brcmf_usb_del_fromq(devinfo, req);
 		brcmu_pkt_buf_free_skb(req->skb);
 		req->skb = NULL;
diff --git a/drivers/net/wireless/broadcom/brcm80211/brcmutil/utils.c b/drivers/net/wireless/broadcom/brcm80211/brcmutil/utils.c
index 0543607..bf525b7 100644
--- a/drivers/net/wireless/broadcom/brcm80211/brcmutil/utils.c
+++ b/drivers/net/wireless/broadcom/brcm80211/brcmutil/utils.c
@@ -49,7 +49,7 @@ void brcmu_pkt_buf_free_skb(struct sk_buff *skb)
 	WARN_ON(skb->next);
 	dev_kfree_skb_any(skb);
 }
-EXPORT_SYMBOL(brcmu_pkt_buf_free_skb);
+//EXPORT_SYMBOL(brcmu_pkt_buf_free_skb);
 
 /*
  * osl multiple-precedence packet queue
diff --git a/drivers/net/wireless/broadcom/brcm80211/include/brcmu_utils.h b/drivers/net/wireless/broadcom/brcm80211/include/brcmu_utils.h
index 4196952..7bd705d 100644
--- a/drivers/net/wireless/broadcom/brcm80211/include/brcmu_utils.h
+++ b/drivers/net/wireless/broadcom/brcm80211/include/brcmu_utils.h
@@ -126,7 +126,7 @@ struct sk_buff *brcmu_pktq_pdeq_match(struct pktq *pq, int prec,
 
 /* packet primitives */
 struct sk_buff *brcmu_pkt_buf_get_skb(uint len);
-void brcmu_pkt_buf_free_skb(struct sk_buff *skb);
+//void brcmu_pkt_buf_free_skb(struct sk_buff *skb);
 
 /* Empty the queue at particular precedence level */
 /* callback function fn(pkt, arg) returns true if pkt belongs to if */
-- 
2.9.3

^ permalink raw reply related	[flat|nested] 6+ messages in thread

* Re: AMPDU stalls with brcmfmac4366b-pcie.bin triggering WARNINGs
  2016-09-14  5:45 AMPDU stalls with brcmfmac4366b-pcie.bin triggering WARNINGs Rafał Miłecki
@ 2016-09-14  7:25 ` Rafał Miłecki
  2016-09-14  8:43 ` Rafał Miłecki
  2016-09-14 18:28 ` Arend Van Spriel
  2 siblings, 0 replies; 6+ messages in thread
From: Rafał Miłecki @ 2016-09-14  7:25 UTC (permalink / raw)
  To: Hante Meuleman, Arend van Spriel, brcm80211-dev-list; +Cc: linux-wireless

On 09/14/2016 07:45 AM, Rafał Miłecki wrote:
> Even with the most recent brcmfmac code ppl keep seeing WARNINGs from
> brcmf_netdev_wait_pend8021x [0].
>
> Hante suggested using CONSOLE for debugging some firmware crash so I
> decided to see I it could also help understanding WARNINGs. I believe it
> did.
>
> First of all, I can't reproduce these problems reliably. One evening I
> got WARNINGs one by one and I could work on my debugging patch easily.
> Yesterday when I got my patch complete, it took me 10+ hours to get a
> single WARNING.
>
> Anyway, it seems to me that sometimes AMPDU stalls in the firmware. It
> seems firmware has some AMPDU watchdog that notices the problem and
> kicks in. It prints some debugging info and starts cleaning up process.
>
> If brcmf_netdev_wait_pend8021x gets called shortly after that (I set
> wpa_group_rekey=30 in hostapd to get brcmf_cfg80211_add_key called more
> often) it results in a WARNING.

Above log was from D-Link DIR-885L.

I can also see WARNINGs on SmartRG SR-400ac with 2 x 43602a1. Unfortunately
brcmfmac43602-pcie.ap.bin doesn't seem to have so many debugging messages so
despite having CONSOLE enabled, I didn't get anything interesting :(

Below you can find 4 logs that look pretty identical to me. At the end of
e-mail there is a confirmation of CONSOLE working.


[30256.622554] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c7b2ec80 brcmf_ifname(ifp):wlan0
[30258.179143] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c652ec80 brcmf_ifname(ifp):wlan0-1
[30258.402521] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c64e1c80 brcmf_ifname(ifp):wlan1-1
[30258.525317] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c64e2c80 brcmf_ifname(ifp):wlan1-2
[30258.539100] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c647c480 brcmf_ifname(ifp):wlan0-2
[30260.112015] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c7b2d480 brcmf_ifname(ifp):wlan1
[30261.071798] ------------[ cut here ]------------
[30261.076459] WARNING: CPU: 1 PID: 1505 at compat-wireless-2016-06-20/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.c:1219 brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac]()
[30261.092493] Modules linked in: pppoe ppp_async iptable_nat brcmfmac pppox ppp_generic nf_nat_ipv4 nf_conntrack_ipv6 nf_conntrack_ipv4 ipt_REJECT ipt_MASQUERADE cfg80211 xt_time xt_tcpudp xt_state xt_nat xt_multiport xt_mark xt_mac xt_limit xt_id xt_conntrack xt_commed
[30261.164362] CPU: 1 PID: 1505 Comm: hostapd Not tainted 4.4.19 #0
[30261.170342] Hardware name: BCM5301X
[30261.173816] Backtrace:
[30261.176284] [<c001708c>] (dump_backtrace) from [<c0017288>] (show_stack+0x18/0x1c)
[30261.183813]  r7:000004c3 r6:bf1d0e9c r5:60000013 r4:00000000
[30261.189496] [<c0017270>] (show_stack) from [<c017c210>] (dump_stack+0x84/0xa4)
[30261.196687] [<c017c18c>] (dump_stack) from [<c0021490>] (warn_slowpath_common+0x8c/0xb8)
[30261.204738]  r5:00000009 r4:00000000
[30261.208312] [<c0021404>] (warn_slowpath_common) from [<c0021560>] (warn_slowpath_null+0x24/0x2c)
[30261.217050]  r8:c71b3148 r7:00000001 r6:c6505b3c r5:00000000 r4:c7b2d480
[30261.223791] [<c002153c>] (warn_slowpath_null) from [<bf1be578>] (brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac])
[30261.234206] [<bf1be4bc>] (brcmf_netdev_wait_pend8021x [brcmfmac]) from [<bf1ab200>] (brcmf_cfg80211_sched_scan_start+0x460/0x6c0 [brcmfmac])
[30261.246746]  r8:c71b3148 r7:bf1c8613 r6:c7b2d480 r5:c04903c8 r4:c71b3438
[30261.253477] [<bf1ab13c>] (brcmf_cfg80211_sched_scan_start [brcmfmac]) from [<bf1ad740>] (brcmf_cfg80211_add_key+0x2e0/0x3dc [brcmfmac])
[30261.265589]  r7:00000000 r6:c7b2d480 r5:c71b3148 r4:00000004
[30261.271315] [<bf1ad460>] (brcmf_cfg80211_add_key [brcmfmac]) from [<bf160b48>] (nl80211_new_key+0xfc/0x128 [cfg80211])
[30261.281955]  r10:00000014 r9:c7a61c00 r8:c6505ca0 r7:c6a58000 r6:c7b2d000 r5:00000000
[30261.289781]  r4:bf1ad460
[30261.292349] [<bf160a4c>] (nl80211_new_key [cfg80211]) from [<c0286f40>] (genl_rcv_msg+0x260/0x2e4)
[30261.301264]  r8:c68ef900 r7:c656fc14 r6:bf170540 r5:bf1787d0 r4:00000000
[30261.307978] [<c0286ce0>] (genl_rcv_msg) from [<c0286260>] (netlink_rcv_skb+0x60/0xbc)
[30261.315770]  r10:c68ef900 r9:00000000 r8:c6505d84 r7:c646dc00 r6:c0286ce0 r5:c68ef900
[30261.323599]  r4:c656fc00
[30261.326131] [<c0286200>] (netlink_rcv_skb) from [<c0286ccc>] (genl_rcv+0x28/0x3c)
[30261.333577]  r7:c646dc00 r6:c68ef900 r5:c68ef900 r4:c04a42a0
[30261.339247] [<c0286ca4>] (genl_rcv) from [<c0285c48>] (netlink_unicast+0x138/0x1f4)
[30261.346865]  r5:00000048 r4:c7931c00
[30261.350443] [<c0285b10>] (netlink_unicast) from [<c02860c8>] (netlink_sendmsg+0x300/0x320)
[30261.358667]  r9:00000008 r8:00000000 r7:00000048 r6:c6505f4c r5:c646dc00 r4:00000000
[30261.366421] [<c0285dc8>] (netlink_sendmsg) from [<c0248de4>] (sock_sendmsg+0x1c/0x2c)
[30261.374211]  r10:00000000 r9:00000000 r8:00000000 r7:c756e900 r6:c6505e64 r5:00000000
[30261.382039]  r4:c6505f4c
[30261.384568] [<c0248dc8>] (sock_sendmsg) from [<c0249398>] (___sys_sendmsg+0x198/0x228)
[30261.392450] [<c0249200>] (___sys_sendmsg) from [<c024a1ec>] (__sys_sendmsg+0x44/0x68)
[30261.400235]  r10:00000000 r9:c6504000 r8:c00098c4 r7:00000128 r6:00000000 r5:be8ca7a0
[30261.408062]  r4:c756e900
[30261.410593] [<c024a1a8>] (__sys_sendmsg) from [<c024a220>] (SyS_sendmsg+0x10/0x14)
[30261.418119]  r6:b6f371c8 r5:00000000 r4:00000000
[30261.422743] [<c024a210>] (SyS_sendmsg) from [<c0009700>] (ret_fast_syscall+0x0/0x3c)
[30261.430519] ---[ end trace 7622542e763ab584 ]---
[30261.435138] brcmfmac: [brcmf_netdev_wait_pend8021x] ifp:c7b2d480 brcmf_ifname(ifp):wlan1 brcmf_get_pend_8021x_cnt(ifp):3
[30261.445963] brcmfmac: [brcmf_netdev_wait_pend8021x] List of pending 802.1x skbs:
[30261.453335] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c68ef540 skb->dev:c7b2d000 skb->dev->name:wlan1
[30261.462690] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c68ef240 skb->dev:c7b2d000 skb->dev->name:wlan1
[30261.472048] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c68ef600 skb->dev:c7b2d000 skb->dev->name:wlan1
[30261.481438] brcmfmac: [brcmf_msgbuf_process_txstatus -> __brcmf_txfinalize] Finally finalizing skb:c68ef540 skb->dev:c7b2d000 skb->dev->name:wlan1
[30261.495608] brcmfmac: [brcmf_cfg80211_del_key -> __send_key_to_dongle] ifp:c7b2d480 brcmf_ifname(ifp):wlan1
[30262.451804] ------------[ cut here ]------------
[30262.456462] WARNING: CPU: 1 PID: 1505 at compat-wireless-2016-06-20/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.c:1219 brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac]()
[30262.472486] Modules linked in: pppoe ppp_async iptable_nat brcmfmac pppox ppp_generic nf_nat_ipv4 nf_conntrack_ipv6 nf_conntrack_ipv4 ipt_REJECT ipt_MASQUERADE cfg80211 xt_time xt_tcpudp xt_state xt_nat xt_multiport xt_mark xt_mac xt_limit xt_id xt_conntrack xt_commed
[30262.544371] CPU: 1 PID: 1505 Comm: hostapd Tainted: G        W       4.4.19 #0
[30262.551559] Hardware name: BCM5301X
[30262.555032] Backtrace:
[30262.557500] [<c001708c>] (dump_backtrace) from [<c0017288>] (show_stack+0x18/0x1c)
[30262.565030]  r7:000004c3 r6:bf1d0e9c r5:60000013 r4:00000000
[30262.570722] [<c0017270>] (show_stack) from [<c017c210>] (dump_stack+0x84/0xa4)
[30262.577920] [<c017c18c>] (dump_stack) from [<c0021490>] (warn_slowpath_common+0x8c/0xb8)
[30262.585971]  r5:00000009 r4:00000000
[30262.589546] [<c0021404>] (warn_slowpath_common) from [<c0021560>] (warn_slowpath_null+0x24/0x2c)
[30262.598284]  r8:c68ef540 r7:00000001 r6:c6505b74 r5:00000000 r4:c7b2d480
[30262.605024] [<c002153c>] (warn_slowpath_null) from [<bf1be578>] (brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac])
[30262.615440] [<bf1be4bc>] (brcmf_netdev_wait_pend8021x [brcmfmac]) from [<bf1ab200>] (brcmf_cfg80211_sched_scan_start+0x460/0x6c0 [brcmfmac])
[30262.627979]  r8:c68ef540 r7:bf1c85fc r6:c7b2d480 r5:c04903c8 r4:c71b32f0
[30262.634711] [<bf1ab13c>] (brcmf_cfg80211_sched_scan_start [brcmfmac]) from [<bf1ad420>] (brcmf_cfg80211_del_key+0xb0/0xf0 [brcmfmac])
[30262.646649]  r7:c7b2d480 r6:00000002 r5:c71b3254 r4:c71b3000
[30262.652374] [<bf1ad370>] (brcmf_cfg80211_del_key [brcmfmac]) from [<bf1608b8>] (nl80211_del_key+0xf4/0x148 [cfg80211])
[30262.663014]  r7:c6a58000 r6:c7b2d000 r5:c644b720 r4:bf1ad370
[30262.668718] [<bf1607c4>] (nl80211_del_key [cfg80211]) from [<c0286f40>] (genl_rcv_msg+0x260/0x2e4)
[30262.677634]  r7:c644b714 r6:bf170554 r5:bf1787d0 r4:00000000
[30262.683301] [<c0286ce0>] (genl_rcv_msg) from [<c0286260>] (netlink_rcv_skb+0x60/0xbc)
[30262.691095]  r10:c68ef540 r9:00000000 r8:c6505d84 r7:c646dc00 r6:c0286ce0 r5:c68ef540
[30262.698922]  r4:c644b700
[30262.701453] [<c0286200>] (netlink_rcv_skb) from [<c0286ccc>] (genl_rcv+0x28/0x3c)
[30262.708892]  r7:c646dc00 r6:c68ef540 r5:c68ef540 r4:c04a42a0
[30262.714561] [<c0286ca4>] (genl_rcv) from [<c0285c48>] (netlink_unicast+0x138/0x1f4)
[30262.722180]  r5:00000030 r4:c7931c00
[30262.725758] [<c0285b10>] (netlink_unicast) from [<c02860c8>] (netlink_sendmsg+0x300/0x320)
[30262.733974]  r9:00000008 r8:00000000 r7:00000030 r6:c6505f4c r5:c646dc00 r4:00000000
[30262.741728] [<c0285dc8>] (netlink_sendmsg) from [<c0248de4>] (sock_sendmsg+0x1c/0x2c)
[30262.749518]  r10:00000000 r9:00000000 r8:00000000 r7:c756e900 r6:c6505e64 r5:00000000
[30262.757345]  r4:c6505f4c
[30262.759875] [<c0248dc8>] (sock_sendmsg) from [<c0249398>] (___sys_sendmsg+0x198/0x228)
[30262.767756] [<c0249200>] (___sys_sendmsg) from [<c024a1ec>] (__sys_sendmsg+0x44/0x68)
[30262.775542]  r10:00000000 r9:c6504000 r8:c00098c4 r7:00000128 r6:00000000 r5:be8ca770
[30262.783369]  r4:c756e900
[30262.785901] [<c024a1a8>] (__sys_sendmsg) from [<c024a220>] (SyS_sendmsg+0x10/0x14)
[30262.793427]  r6:b6f371c8 r5:00000000 r4:00000000
[30262.798050] [<c024a210>] (SyS_sendmsg) from [<c0009700>] (ret_fast_syscall+0x0/0x3c)
[30262.805792] ---[ end trace 7622542e763ab585 ]---
[30262.810397] brcmfmac: [brcmf_netdev_wait_pend8021x] ifp:c7b2d480 brcmf_ifname(ifp):wlan1 brcmf_get_pend_8021x_cnt(ifp):2
[30262.821229] brcmfmac: [brcmf_netdev_wait_pend8021x] List of pending 802.1x skbs:
[30262.828606] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c68ef240 skb->dev:c7b2d000 skb->dev->name:wlan1
[30262.837962] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c68ef600 skb->dev:c7b2d000 skb->dev->name:wlan1
[30264.339034] brcmfmac: [brcmf_msgbuf_process_txstatus -> __brcmf_txfinalize] Finally finalizing skb:c68ef240 skb->dev:c7b2d000 skb->dev->name:wlan1
[30264.352306] brcmfmac: [brcmf_msgbuf_process_txstatus -> __brcmf_txfinalize] Finally finalizing skb:c68ef600 skb->dev:c7b2d000 skb->dev->name:wlan1



[ 2688.254245] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c719d480 brcmf_ifname(ifp):wlan1
[ 2688.597156] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c719a480 brcmf_ifname(ifp):wlan0
[ 2689.411719] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c7ab4480 brcmf_ifname(ifp):wlan0-1
[ 2689.961683] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c7b1ec80 brcmf_ifname(ifp):wlan0-2
[ 2689.974174] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c6532c80 brcmf_ifname(ifp):wlan1-2
[ 2692.133701] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c649bc80 brcmf_ifname(ifp):wlan1-1
[ 2693.093493] ------------[ cut here ]------------
[ 2693.098153] WARNING: CPU: 1 PID: 1202 at compat-wireless-2016-06-20/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.c:1219 brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac]()
[ 2693.114191] Modules linked in: pppoe ppp_async iptable_nat brcmfmac pppox ppp_generic nf_nat_ipv4 nf_conntrack_ipv6 nf_conntrack_ipv4 ipt_REJECT ipt_MASQUERADE cfg80211 xt_time xt_tcpudp xt_state xt_nat xt_multiport xt_mark xt_mac xt_limit xt_id xt_conntrack xt_commed
[ 2693.186072] CPU: 1 PID: 1202 Comm: hostapd Not tainted 4.4.19 #0
[ 2693.192051] Hardware name: BCM5301X
[ 2693.195524] Backtrace:
[ 2693.197993] [<c001708c>] (dump_backtrace) from [<c0017288>] (show_stack+0x18/0x1c)
[ 2693.205520]  r7:000004c3 r6:bf1d0e9c r5:60000013 r4:00000000
[ 2693.211206] [<c0017270>] (show_stack) from [<c017c210>] (dump_stack+0x84/0xa4)
[ 2693.218401] [<c017c18c>] (dump_stack) from [<c0021490>] (warn_slowpath_common+0x8c/0xb8)
[ 2693.226446]  r5:00000009 r4:00000000
[ 2693.230020] [<c0021404>] (warn_slowpath_common) from [<c0021560>] (warn_slowpath_null+0x24/0x2c)
[ 2693.238758]  r8:c72f4148 r7:00000001 r6:c6475b3c r5:00000000 r4:c649bc80
[ 2693.245498] [<c002153c>] (warn_slowpath_null) from [<bf1be578>] (brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac])
[ 2693.255915] [<bf1be4bc>] (brcmf_netdev_wait_pend8021x [brcmfmac]) from [<bf1ab200>] (brcmf_cfg80211_sched_scan_start+0x460/0x6c0 [brcmfmac])
[ 2693.268453]  r8:c72f4148 r7:bf1c8613 r6:c649bc80 r5:c04903c8 r4:c72f4438
[ 2693.275185] [<bf1ab13c>] (brcmf_cfg80211_sched_scan_start [brcmfmac]) from [<bf1ad740>] (brcmf_cfg80211_add_key+0x2e0/0x3dc [brcmfmac])
[ 2693.287298]  r7:00000000 r6:c649bc80 r5:c72f4148 r4:00000004
[ 2693.293021] [<bf1ad460>] (brcmf_cfg80211_add_key [brcmfmac]) from [<bf160b48>] (nl80211_new_key+0xfc/0x128 [cfg80211])
[ 2693.303661]  r10:00000014 r9:c7966800 r8:c6475ca0 r7:c715e000 r6:c649b800 r5:00000000
[ 2693.311489]  r4:bf1ad460
[ 2693.314057] [<bf160a4c>] (nl80211_new_key [cfg80211]) from [<c0286f40>] (genl_rcv_msg+0x260/0x2e4)
[ 2693.322972]  r8:c6bd2b40 r7:c785f014 r6:bf170540 r5:bf1787d0 r4:00000000
[ 2693.329686] [<c0286ce0>] (genl_rcv_msg) from [<c0286260>] (netlink_rcv_skb+0x60/0xbc)
[ 2693.337478]  r10:c6bd2b40 r9:00000000 r8:c6475d84 r7:c68bb000 r6:c0286ce0 r5:c6bd2b40
[ 2693.345306]  r4:c785f000
[ 2693.347838] [<c0286200>] (netlink_rcv_skb) from [<c0286ccc>] (genl_rcv+0x28/0x3c)
[ 2693.355277]  r7:c68bb000 r6:c6bd2b40 r5:c6bd2b40 r4:c04a42a0
[ 2693.360945] [<c0286ca4>] (genl_rcv) from [<c0285c48>] (netlink_unicast+0x138/0x1f4)
[ 2693.368565]  r5:00000048 r4:c7931c00
[ 2693.372143] [<c0285b10>] (netlink_unicast) from [<c02860c8>] (netlink_sendmsg+0x300/0x320)
[ 2693.380367]  r9:00000008 r8:00000000 r7:00000048 r6:c6475f4c r5:c68bb000 r4:00000000
[ 2693.388120] [<c0285dc8>] (netlink_sendmsg) from [<c0248de4>] (sock_sendmsg+0x1c/0x2c)
[ 2693.395910]  r10:00000000 r9:00000000 r8:00000000 r7:c7503500 r6:c6475e64 r5:00000000
[ 2693.403738]  r4:c6475f4c
[ 2693.406267] [<c0248dc8>] (sock_sendmsg) from [<c0249398>] (___sys_sendmsg+0x198/0x228)
[ 2693.414148] [<c0249200>] (___sys_sendmsg) from [<c024a1ec>] (__sys_sendmsg+0x44/0x68)
[ 2693.421935]  r10:00000000 r9:c6474000 r8:c00098c4 r7:00000128 r6:00000000 r5:beaf37a0
[ 2693.429762]  r4:c7503500
[ 2693.432292] [<c024a1a8>] (__sys_sendmsg) from [<c024a220>] (SyS_sendmsg+0x10/0x14)
[ 2693.439820]  r6:b6f201c8 r5:00000000 r4:00000000
[ 2693.444442] [<c024a210>] (SyS_sendmsg) from [<c0009700>] (ret_fast_syscall+0x0/0x3c)
[ 2693.452191] ---[ end trace b29225cb54365624 ]---
[ 2693.456815] brcmfmac: [brcmf_netdev_wait_pend8021x] ifp:c649bc80 brcmf_ifname(ifp):wlan1-1 brcmf_get_pend_8021x_cnt(ifp):1
[ 2693.467821] brcmfmac: [brcmf_netdev_wait_pend8021x] List of pending 802.1x skbs:
[ 2693.475197] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c6bd2e40 skb->dev:c649b800 skb->dev->name:wlan1-1
[ 2693.486107] brcmfmac: [brcmf_cfg80211_del_key -> __send_key_to_dongle] ifp:c649bc80 brcmf_ifname(ifp):wlan1-1
[ 2694.443471] ------------[ cut here ]------------
[ 2694.448127] WARNING: CPU: 1 PID: 1202 at compat-wireless-2016-06-20/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.c:1219 brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac]()
[ 2694.464159] Modules linked in: pppoe ppp_async iptable_nat brcmfmac pppox ppp_generic nf_nat_ipv4 nf_conntrack_ipv6 nf_conntrack_ipv4 ipt_REJECT ipt_MASQUERADE cfg80211 xt_time xt_tcpudp xt_state xt_nat xt_multiport xt_mark xt_mac xt_limit xt_id xt_conntrack xt_commed
[ 2694.536044] CPU: 1 PID: 1202 Comm: hostapd Tainted: G        W       4.4.19 #0
[ 2694.543235] Hardware name: BCM5301X
[ 2694.546708] Backtrace:
[ 2694.549175] [<c001708c>] (dump_backtrace) from [<c0017288>] (show_stack+0x18/0x1c)
[ 2694.556704]  r7:000004c3 r6:bf1d0e9c r5:60000013 r4:00000000
[ 2694.562388] [<c0017270>] (show_stack) from [<c017c210>] (dump_stack+0x84/0xa4)
[ 2694.569577] [<c017c18c>] (dump_stack) from [<c0021490>] (warn_slowpath_common+0x8c/0xb8)
[ 2694.577621]  r5:00000009 r4:00000000
[ 2694.581195] [<c0021404>] (warn_slowpath_common) from [<c0021560>] (warn_slowpath_null+0x24/0x2c)
[ 2694.589932]  r8:c6bd2b40 r7:00000001 r6:c6475b74 r5:00000000 r4:c649bc80
[ 2694.596677] [<c002153c>] (warn_slowpath_null) from [<bf1be578>] (brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac])
[ 2694.607089] [<bf1be4bc>] (brcmf_netdev_wait_pend8021x [brcmfmac]) from [<bf1ab200>] (brcmf_cfg80211_sched_scan_start+0x460/0x6c0 [brcmfmac])
[ 2694.619629]  r8:c6bd2b40 r7:bf1c85fc r6:c649bc80 r5:c04903c8 r4:c72f42f0
[ 2694.626359] [<bf1ab13c>] (brcmf_cfg80211_sched_scan_start [brcmfmac]) from [<bf1ad420>] (brcmf_cfg80211_del_key+0xb0/0xf0 [brcmfmac])
[ 2694.638291]  r7:c649bc80 r6:00000002 r5:c72f4254 r4:c72f4000
[ 2694.644015] [<bf1ad370>] (brcmf_cfg80211_del_key [brcmfmac]) from [<bf1608b8>] (nl80211_del_key+0xf4/0x148 [cfg80211])
[ 2694.654655]  r7:c715e000 r6:c649b800 r5:c68eb520 r4:bf1ad370
[ 2694.660360] [<bf1607c4>] (nl80211_del_key [cfg80211]) from [<c0286f40>] (genl_rcv_msg+0x260/0x2e4)
[ 2694.669273]  r7:c68eb514 r6:bf170554 r5:bf1787d0 r4:00000000
[ 2694.674942] [<c0286ce0>] (genl_rcv_msg) from [<c0286260>] (netlink_rcv_skb+0x60/0xbc)
[ 2694.682735]  r10:c6bd2b40 r9:00000000 r8:c6475d84 r7:c68bb000 r6:c0286ce0 r5:c6bd2b40
[ 2694.690563]  r4:c68eb500
[ 2694.693094] [<c0286200>] (netlink_rcv_skb) from [<c0286ccc>] (genl_rcv+0x28/0x3c)
[ 2694.700533]  r7:c68bb000 r6:c6bd2b40 r5:c6bd2b40 r4:c04a42a0
[ 2694.706202] [<c0286ca4>] (genl_rcv) from [<c0285c48>] (netlink_unicast+0x138/0x1f4)
[ 2694.713821]  r5:00000030 r4:c7931c00
[ 2694.717399] [<c0285b10>] (netlink_unicast) from [<c02860c8>] (netlink_sendmsg+0x300/0x320)
[ 2694.725615]  r9:00000008 r8:00000000 r7:00000030 r6:c6475f4c r5:c68bb000 r4:00000000
[ 2694.733369] [<c0285dc8>] (netlink_sendmsg) from [<c0248de4>] (sock_sendmsg+0x1c/0x2c)
[ 2694.741158]  r10:00000000 r9:00000000 r8:00000000 r7:c7503500 r6:c6475e64 r5:00000000
[ 2694.748986]  r4:c6475f4c
[ 2694.751516] [<c0248dc8>] (sock_sendmsg) from [<c0249398>] (___sys_sendmsg+0x198/0x228)
[ 2694.759397] [<c0249200>] (___sys_sendmsg) from [<c024a1ec>] (__sys_sendmsg+0x44/0x68)
[ 2694.767182]  r10:00000000 r9:c6474000 r8:c00098c4 r7:00000128 r6:00000000 r5:beaf3770
[ 2694.775010]  r4:c7503500
[ 2694.777541] [<c024a1a8>] (__sys_sendmsg) from [<c024a220>] (SyS_sendmsg+0x10/0x14)
[ 2694.785068]  r6:b6f201c8 r5:00000000 r4:00000000
[ 2694.789691] [<c024a210>] (SyS_sendmsg) from [<c0009700>] (ret_fast_syscall+0x0/0x3c)
[ 2694.797445] ---[ end trace b29225cb54365625 ]---
[ 2694.802054] brcmfmac: [brcmf_netdev_wait_pend8021x] ifp:c649bc80 brcmf_ifname(ifp):wlan1-1 brcmf_get_pend_8021x_cnt(ifp):1
[ 2694.813060] brcmfmac: [brcmf_netdev_wait_pend8021x] List of pending 802.1x skbs:
[ 2694.820436] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c6bd2e40 skb->dev:c649b800 skb->dev->name:wlan1-1
[ 2696.497370] brcmfmac: [brcmf_msgbuf_process_txstatus -> __brcmf_txfinalize] Finally finalizing skb:c6bd2e40 skb->dev:c649b800 skb->dev->name:wlan1-1
[ 2715.160649] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c649bc80 brcmf_ifname(ifp):wlan1-1
[ 2718.274307] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c719d480 brcmf_ifname(ifp):wlan1
[ 2718.607701] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c719a480 brcmf_ifname(ifp):wlan0
[ 2718.881713] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c649bc80 brcmf_ifname(ifp):wlan1-1
[ 2719.431788] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c7ab4480 brcmf_ifname(ifp):wlan0-1
[ 2719.981819] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c7b1ec80 brcmf_ifname(ifp):wlan0-2
[ 2719.994262] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c6532c80 brcmf_ifname(ifp):wlan1-2



[ 2928.414290] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c719d480 brcmf_ifname(ifp):wlan1
[ 2928.679474] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c719a480 brcmf_ifname(ifp):wlan0
[ 2929.564278] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c7ab4480 brcmf_ifname(ifp):wlan0-1
[ 2930.151747] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c6532c80 brcmf_ifname(ifp):wlan1-2
[ 2930.162258] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c7b1ec80 brcmf_ifname(ifp):wlan0-2
[ 2932.211271] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c649bc80 brcmf_ifname(ifp):wlan1-1
[ 2933.171045] ------------[ cut here ]------------
[ 2933.175701] WARNING: CPU: 0 PID: 1202 at compat-wireless-2016-06-20/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.c:1219 brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac]()
[ 2933.191731] Modules linked in: pppoe ppp_async iptable_nat brcmfmac pppox ppp_generic nf_nat_ipv4 nf_conntrack_ipv6 nf_conntrack_ipv4 ipt_REJECT ipt_MASQUERADE cfg80211 xt_time xt_tcpudp xt_state xt_nat xt_multiport xt_mark xt_mac xt_limit xt_id xt_conntrack xt_commed
[ 2933.263627] CPU: 0 PID: 1202 Comm: hostapd Tainted: G        W       4.4.19 #0
[ 2933.270814] Hardware name: BCM5301X
[ 2933.274288] Backtrace:
[ 2933.276756] [<c001708c>] (dump_backtrace) from [<c0017288>] (show_stack+0x18/0x1c)
[ 2933.284285]  r7:000004c3 r6:bf1d0e9c r5:60000013 r4:00000000
[ 2933.289969] [<c0017270>] (show_stack) from [<c017c210>] (dump_stack+0x84/0xa4)
[ 2933.297158] [<c017c18c>] (dump_stack) from [<c0021490>] (warn_slowpath_common+0x8c/0xb8)
[ 2933.305210]  r5:00000009 r4:00000000
[ 2933.308784] [<c0021404>] (warn_slowpath_common) from [<c0021560>] (warn_slowpath_null+0x24/0x2c)
[ 2933.317521]  r8:c72f4148 r7:00000001 r6:c6475b3c r5:00000000 r4:c649bc80
[ 2933.324263] [<c002153c>] (warn_slowpath_null) from [<bf1be578>] (brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac])
[ 2933.334677] [<bf1be4bc>] (brcmf_netdev_wait_pend8021x [brcmfmac]) from [<bf1ab200>] (brcmf_cfg80211_sched_scan_start+0x460/0x6c0 [brcmfmac])
[ 2933.347218]  r8:c72f4148 r7:bf1c8613 r6:c649bc80 r5:c04903c8 r4:c72f4438
[ 2933.353949] [<bf1ab13c>] (brcmf_cfg80211_sched_scan_start [brcmfmac]) from [<bf1ad740>] (brcmf_cfg80211_add_key+0x2e0/0x3dc [brcmfmac])
[ 2933.366061]  r7:00000000 r6:c649bc80 r5:c72f4148 r4:00000004
[ 2933.371785] [<bf1ad460>] (brcmf_cfg80211_add_key [brcmfmac]) from [<bf160b48>] (nl80211_new_key+0xfc/0x128 [cfg80211])
[ 2933.382426]  r10:00000014 r9:c7966800 r8:c6475ca0 r7:c715e000 r6:c649b800 r5:00000000
[ 2933.390253]  r4:bf1ad460
[ 2933.392821] [<bf160a4c>] (nl80211_new_key [cfg80211]) from [<c0286f40>] (genl_rcv_msg+0x260/0x2e4)
[ 2933.401737]  r8:c6abd540 r7:c653f214 r6:bf170540 r5:bf1787d0 r4:00000000
[ 2933.408451] [<c0286ce0>] (genl_rcv_msg) from [<c0286260>] (netlink_rcv_skb+0x60/0xbc)
[ 2933.416243]  r10:c6abd540 r9:00000000 r8:c6475d84 r7:c68bb000 r6:c0286ce0 r5:c6abd540
[ 2933.424070]  r4:c653f200
[ 2933.426602] [<c0286200>] (netlink_rcv_skb) from [<c0286ccc>] (genl_rcv+0x28/0x3c)
[ 2933.434041]  r7:c68bb000 r6:c6abd540 r5:c6abd540 r4:c04a42a0
[ 2933.439708] [<c0286ca4>] (genl_rcv) from [<c0285c48>] (netlink_unicast+0x138/0x1f4)
[ 2933.447321]  r5:00000048 r4:c7931c00
[ 2933.450898] [<c0285b10>] (netlink_unicast) from [<c02860c8>] (netlink_sendmsg+0x300/0x320)
[ 2933.459123]  r9:00000008 r8:00000000 r7:00000048 r6:c6475f4c r5:c68bb000 r4:00000000
[ 2933.466877] [<c0285dc8>] (netlink_sendmsg) from [<c0248de4>] (sock_sendmsg+0x1c/0x2c)
[ 2933.474666]  r10:00000000 r9:00000000 r8:00000000 r7:c7503500 r6:c6475e64 r5:00000000
[ 2933.482494]  r4:c6475f4c
[ 2933.485022] [<c0248dc8>] (sock_sendmsg) from [<c0249398>] (___sys_sendmsg+0x198/0x228)
[ 2933.492905] [<c0249200>] (___sys_sendmsg) from [<c024a1ec>] (__sys_sendmsg+0x44/0x68)
[ 2933.500690]  r10:00000000 r9:c6474000 r8:c00098c4 r7:00000128 r6:00000000 r5:beaf37a0
[ 2933.508518]  r4:c7503500
[ 2933.511048] [<c024a1a8>] (__sys_sendmsg) from [<c024a220>] (SyS_sendmsg+0x10/0x14)
[ 2933.518574]  r6:b6f201c8 r5:00000000 r4:00000000
[ 2933.523199] [<c024a210>] (SyS_sendmsg) from [<c0009700>] (ret_fast_syscall+0x0/0x3c)
[ 2933.530975] ---[ end trace b29225cb54365626 ]---
[ 2933.535595] brcmfmac: [brcmf_netdev_wait_pend8021x] ifp:c649bc80 brcmf_ifname(ifp):wlan1-1 brcmf_get_pend_8021x_cnt(ifp):2
[ 2933.546602] brcmfmac: [brcmf_netdev_wait_pend8021x] List of pending 802.1x skbs:
[ 2933.553984] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c7bcb300 skb->dev:c649b800 skb->dev->name:wlan1-1
[ 2933.563523] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c7bcb240 skb->dev:c649b800 skb->dev->name:wlan1-1
[ 2933.574411] brcmfmac: [brcmf_cfg80211_del_key -> __send_key_to_dongle] ifp:c649bc80 brcmf_ifname(ifp):wlan1-1
[ 2934.531066] ------------[ cut here ]------------
[ 2934.535734] WARNING: CPU: 0 PID: 1202 at compat-wireless-2016-06-20/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.c:1219 brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac]()
[ 2934.551769] Modules linked in: pppoe ppp_async iptable_nat brcmfmac pppox ppp_generic nf_nat_ipv4 nf_conntrack_ipv6 nf_conntrack_ipv4 ipt_REJECT ipt_MASQUERADE cfg80211 xt_time xt_tcpudp xt_state xt_nat xt_multiport xt_mark xt_mac xt_limit xt_id xt_conntrack xt_commed
[ 2934.623666] CPU: 0 PID: 1202 Comm: hostapd Tainted: G        W       4.4.19 #0
[ 2934.630855] Hardware name: BCM5301X
[ 2934.634328] Backtrace:
[ 2934.636794] [<c001708c>] (dump_backtrace) from [<c0017288>] (show_stack+0x18/0x1c)
[ 2934.644324]  r7:000004c3 r6:bf1d0e9c r5:60000013 r4:00000000
[ 2934.650008] [<c0017270>] (show_stack) from [<c017c210>] (dump_stack+0x84/0xa4)
[ 2934.657197] [<c017c18c>] (dump_stack) from [<c0021490>] (warn_slowpath_common+0x8c/0xb8)
[ 2934.665241]  r5:00000009 r4:00000000
[ 2934.668814] [<c0021404>] (warn_slowpath_common) from [<c0021560>] (warn_slowpath_null+0x24/0x2c)
[ 2934.677552]  r8:c709be40 r7:00000001 r6:c6475b74 r5:00000000 r4:c649bc80
[ 2934.684294] [<c002153c>] (warn_slowpath_null) from [<bf1be578>] (brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac])
[ 2934.694708] [<bf1be4bc>] (brcmf_netdev_wait_pend8021x [brcmfmac]) from [<bf1ab200>] (brcmf_cfg80211_sched_scan_start+0x460/0x6c0 [brcmfmac])
[ 2934.707248]  r8:c709be40 r7:bf1c85fc r6:c649bc80 r5:c04903c8 r4:c72f42f0
[ 2934.713981] [<bf1ab13c>] (brcmf_cfg80211_sched_scan_start [brcmfmac]) from [<bf1ad420>] (brcmf_cfg80211_del_key+0xb0/0xf0 [brcmfmac])
[ 2934.725919]  r7:c649bc80 r6:00000002 r5:c72f4254 r4:c72f4000
[ 2934.731644] [<bf1ad370>] (brcmf_cfg80211_del_key [brcmfmac]) from [<bf1608b8>] (nl80211_del_key+0xf4/0x148 [cfg80211])
[ 2934.742284]  r7:c715e000 r6:c649b800 r5:c6906720 r4:bf1ad370
[ 2934.747987] [<bf1607c4>] (nl80211_del_key [cfg80211]) from [<c0286f40>] (genl_rcv_msg+0x260/0x2e4)
[ 2934.756903]  r7:c6906714 r6:bf170554 r5:bf1787d0 r4:00000000
[ 2934.762572] [<c0286ce0>] (genl_rcv_msg) from [<c0286260>] (netlink_rcv_skb+0x60/0xbc)
[ 2934.770364]  r10:c709be40 r9:00000000 r8:c6475d84 r7:c68bb000 r6:c0286ce0 r5:c709be40
[ 2934.778192]  r4:c6906700
[ 2934.780723] [<c0286200>] (netlink_rcv_skb) from [<c0286ccc>] (genl_rcv+0x28/0x3c)
[ 2934.788171]  r7:c68bb000 r6:c709be40 r5:c709be40 r4:c04a42a0
[ 2934.793838] [<c0286ca4>] (genl_rcv) from [<c0285c48>] (netlink_unicast+0x138/0x1f4)
[ 2934.801450]  r5:00000030 r4:c7931c00
[ 2934.805028] [<c0285b10>] (netlink_unicast) from [<c02860c8>] (netlink_sendmsg+0x300/0x320)
[ 2934.813253]  r9:00000008 r8:00000000 r7:00000030 r6:c6475f4c r5:c68bb000 r4:00000000
[ 2934.821006] [<c0285dc8>] (netlink_sendmsg) from [<c0248de4>] (sock_sendmsg+0x1c/0x2c)
[ 2934.828795]  r10:00000000 r9:00000000 r8:00000000 r7:c7503500 r6:c6475e64 r5:00000000
[ 2934.836624]  r4:c6475f4c
[ 2934.839153] [<c0248dc8>] (sock_sendmsg) from [<c0249398>] (___sys_sendmsg+0x198/0x228)
[ 2934.847034] [<c0249200>] (___sys_sendmsg) from [<c024a1ec>] (__sys_sendmsg+0x44/0x68)
[ 2934.854820]  r10:00000000 r9:c6474000 r8:c00098c4 r7:00000128 r6:00000000 r5:beaf3770
[ 2934.862648]  r4:c7503500
[ 2934.865179] [<c024a1a8>] (__sys_sendmsg) from [<c024a220>] (SyS_sendmsg+0x10/0x14)
[ 2934.872704]  r6:b6f201c8 r5:00000000 r4:00000000
[ 2934.877328] [<c024a210>] (SyS_sendmsg) from [<c0009700>] (ret_fast_syscall+0x0/0x3c)
[ 2934.885107] ---[ end trace b29225cb54365627 ]---
[ 2934.889718] brcmfmac: [brcmf_netdev_wait_pend8021x] ifp:c649bc80 brcmf_ifname(ifp):wlan1-1 brcmf_get_pend_8021x_cnt(ifp):2
[ 2934.900737] brcmfmac: [brcmf_netdev_wait_pend8021x] List of pending 802.1x skbs:
[ 2934.908123] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c7bcb300 skb->dev:c649b800 skb->dev->name:wlan1-1
[ 2934.917659] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c7bcb240 skb->dev:c649b800 skb->dev->name:wlan1-1
[ 2934.927268] brcmfmac: [brcmf_msgbuf_process_txstatus -> __brcmf_txfinalize] Finally finalizing skb:c7bcb300 skb->dev:c649b800 skb->dev->name:wlan1-1
[ 2934.940547] brcmfmac: [brcmf_msgbuf_process_txstatus -> __brcmf_txfinalize] Finally finalizing skb:c7bcb240 skb->dev:c649b800 skb->dev->name:wlan1-1
[ 2958.431826] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c719d480 brcmf_ifname(ifp):wlan1
[ 2958.689224] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c719a480 brcmf_ifname(ifp):wlan0
[ 2958.983312] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c649bc80 brcmf_ifname(ifp):wlan1-1
[ 2959.584290] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c7ab4480 brcmf_ifname(ifp):wlan0-1
[ 2960.174354] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c7b1ec80 brcmf_ifname(ifp):wlan0-2
[ 2960.185643] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c6532c80 brcmf_ifname(ifp):wlan1-2



[ 3198.584369] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c719d480 brcmf_ifname(ifp):wlan1
[ 3198.759755] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c719a480 brcmf_ifname(ifp):wlan0
[ 3199.734358] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c7ab4480 brcmf_ifname(ifp):wlan0-1
[ 3200.374309] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c7b1ec80 brcmf_ifname(ifp):wlan0-2
[ 3200.384905] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c6532c80 brcmf_ifname(ifp):wlan1-2
[ 3202.291309] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c649bc80 brcmf_ifname(ifp):wlan1-1
[ 3203.251121] ------------[ cut here ]------------
[ 3203.255787] WARNING: CPU: 0 PID: 1202 at compat-wireless-2016-06-20/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.c:1219 brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac]()
[ 3203.271827] Modules linked in: pppoe ppp_async iptable_nat brcmfmac pppox ppp_generic nf_nat_ipv4 nf_conntrack_ipv6 nf_conntrack_ipv4 ipt_REJECT ipt_MASQUERADE cfg80211 xt_time xt_tcpudp xt_state xt_nat xt_multiport xt_mark xt_mac xt_limit xt_id xt_conntrack xt_commed
[ 3203.343719] CPU: 0 PID: 1202 Comm: hostapd Tainted: G        W       4.4.19 #0
[ 3203.350908] Hardware name: BCM5301X
[ 3203.354381] Backtrace:
[ 3203.356849] [<c001708c>] (dump_backtrace) from [<c0017288>] (show_stack+0x18/0x1c)
[ 3203.364378]  r7:000004c3 r6:bf1d0e9c r5:60000013 r4:00000000
[ 3203.370062] [<c0017270>] (show_stack) from [<c017c210>] (dump_stack+0x84/0xa4)
[ 3203.377259] [<c017c18c>] (dump_stack) from [<c0021490>] (warn_slowpath_common+0x8c/0xb8)
[ 3203.385304]  r5:00000009 r4:00000000
[ 3203.388877] [<c0021404>] (warn_slowpath_common) from [<c0021560>] (warn_slowpath_null+0x24/0x2c)
[ 3203.397614]  r8:c72f40a4 r7:00000001 r6:c6475b3c r5:00000000 r4:c649bc80
[ 3203.404355] [<c002153c>] (warn_slowpath_null) from [<bf1be578>] (brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac])
[ 3203.414771] [<bf1be4bc>] (brcmf_netdev_wait_pend8021x [brcmfmac]) from [<bf1ab200>] (brcmf_cfg80211_sched_scan_start+0x460/0x6c0 [brcmfmac])
[ 3203.427311]  r8:c72f40a4 r7:bf1c8613 r6:c649bc80 r5:c04903c8 r4:c72f4394
[ 3203.434043] [<bf1ab13c>] (brcmf_cfg80211_sched_scan_start [brcmfmac]) from [<bf1ad740>] (brcmf_cfg80211_add_key+0x2e0/0x3dc [brcmfmac])
[ 3203.446154]  r7:00000000 r6:c649bc80 r5:c72f40a4 r4:00000004
[ 3203.451877] [<bf1ad460>] (brcmf_cfg80211_add_key [brcmfmac]) from [<bf160b48>] (nl80211_new_key+0xfc/0x128 [cfg80211])
[ 3203.462519]  r10:00000014 r9:c7966800 r8:c6475ca0 r7:c715e000 r6:c649b800 r5:00000000
[ 3203.470346]  r4:bf1ad460
[ 3203.472915] [<bf160a4c>] (nl80211_new_key [cfg80211]) from [<c0286f40>] (genl_rcv_msg+0x260/0x2e4)
[ 3203.481829]  r8:c6901300 r7:c653f614 r6:bf170540 r5:bf1787d0 r4:00000000
[ 3203.488544] [<c0286ce0>] (genl_rcv_msg) from [<c0286260>] (netlink_rcv_skb+0x60/0xbc)
[ 3203.496336]  r10:c6901300 r9:00000000 r8:c6475d84 r7:c68bb000 r6:c0286ce0 r5:c6901300
[ 3203.504163]  r4:c653f600
[ 3203.506695] [<c0286200>] (netlink_rcv_skb) from [<c0286ccc>] (genl_rcv+0x28/0x3c)
[ 3203.514142]  r7:c68bb000 r6:c6901300 r5:c6901300 r4:c04a42a0
[ 3203.519810] [<c0286ca4>] (genl_rcv) from [<c0285c48>] (netlink_unicast+0x138/0x1f4)
[ 3203.527423]  r5:00000048 r4:c7931c00
[ 3203.531000] [<c0285b10>] (netlink_unicast) from [<c02860c8>] (netlink_sendmsg+0x300/0x320)
[ 3203.539224]  r9:00000008 r8:00000000 r7:00000048 r6:c6475f4c r5:c68bb000 r4:00000000
[ 3203.546978] [<c0285dc8>] (netlink_sendmsg) from [<c0248de4>] (sock_sendmsg+0x1c/0x2c)
[ 3203.554768]  r10:00000000 r9:00000000 r8:00000000 r7:c7503500 r6:c6475e64 r5:00000000
[ 3203.562596]  r4:c6475f4c
[ 3203.565125] [<c0248dc8>] (sock_sendmsg) from [<c0249398>] (___sys_sendmsg+0x198/0x228)
[ 3203.573006] [<c0249200>] (___sys_sendmsg) from [<c024a1ec>] (__sys_sendmsg+0x44/0x68)
[ 3203.580791]  r10:00000000 r9:c6474000 r8:c00098c4 r7:00000128 r6:00000000 r5:beaf37a0
[ 3203.588619]  r4:c7503500
[ 3203.591150] [<c024a1a8>] (__sys_sendmsg) from [<c024a220>] (SyS_sendmsg+0x10/0x14)
[ 3203.598676]  r6:b6f201c8 r5:00000000 r4:00000000
[ 3203.603300] [<c024a210>] (SyS_sendmsg) from [<c0009700>] (ret_fast_syscall+0x0/0x3c)
[ 3203.611046] ---[ end trace b29225cb54365628 ]---
[ 3203.615668] brcmfmac: [brcmf_netdev_wait_pend8021x] ifp:c649bc80 brcmf_ifname(ifp):wlan1-1 brcmf_get_pend_8021x_cnt(ifp):3
[ 3203.626670] brcmfmac: [brcmf_netdev_wait_pend8021x] List of pending 802.1x skbs:
[ 3203.634050] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c6901180 skb->dev:c649b800 skb->dev->name:wlan1-1
[ 3203.643591] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c6901f00 skb->dev:c649b800 skb->dev->name:wlan1-1
[ 3203.653126] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c6901b40 skb->dev:c649b800 skb->dev->name:wlan1-1
[ 3203.666634] brcmfmac: [brcmf_cfg80211_del_key -> __send_key_to_dongle] ifp:c649bc80 brcmf_ifname(ifp):wlan1-1
[ 3204.621117] ------------[ cut here ]------------
[ 3204.625777] WARNING: CPU: 0 PID: 1202 at compat-wireless-2016-06-20/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.c:1219 brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac]()
[ 3204.641806] Modules linked in: pppoe ppp_async iptable_nat brcmfmac pppox ppp_generic nf_nat_ipv4 nf_conntrack_ipv6 nf_conntrack_ipv4 ipt_REJECT ipt_MASQUERADE cfg80211 xt_time xt_tcpudp xt_state xt_nat xt_multiport xt_mark xt_mac xt_limit xt_id xt_conntrack xt_commed
[ 3204.713721] CPU: 0 PID: 1202 Comm: hostapd Tainted: G        W       4.4.19 #0
[ 3204.720908] Hardware name: BCM5301X
[ 3204.724374] Backtrace:
[ 3204.726840] [<c001708c>] (dump_backtrace) from [<c0017288>] (show_stack+0x18/0x1c)
[ 3204.734370]  r7:000004c3 r6:bf1d0e9c r5:60000013 r4:00000000
[ 3204.740054] [<c0017270>] (show_stack) from [<c017c210>] (dump_stack+0x84/0xa4)
[ 3204.747243] [<c017c18c>] (dump_stack) from [<c0021490>] (warn_slowpath_common+0x8c/0xb8)
[ 3204.755287]  r5:00000009 r4:00000000
[ 3204.758861] [<c0021404>] (warn_slowpath_common) from [<c0021560>] (warn_slowpath_null+0x24/0x2c)
[ 3204.767600]  r8:c6709b40 r7:00000001 r6:c6475b74 r5:00000000 r4:c649bc80
[ 3204.774337] [<c002153c>] (warn_slowpath_null) from [<bf1be578>] (brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac])
[ 3204.784755] [<bf1be4bc>] (brcmf_netdev_wait_pend8021x [brcmfmac]) from [<bf1ab200>] (brcmf_cfg80211_sched_scan_start+0x460/0x6c0 [brcmfmac])
[ 3204.797295]  r8:c6709b40 r7:bf1c85fc r6:c649bc80 r5:c04903c8 r4:c72f42f0
[ 3204.804026] [<bf1ab13c>] (brcmf_cfg80211_sched_scan_start [brcmfmac]) from [<bf1ad420>] (brcmf_cfg80211_del_key+0xb0/0xf0 [brcmfmac])
[ 3204.815966]  r7:c649bc80 r6:00000002 r5:c72f4254 r4:c72f4000
[ 3204.821689] [<bf1ad370>] (brcmf_cfg80211_del_key [brcmfmac]) from [<bf1608b8>] (nl80211_del_key+0xf4/0x148 [cfg80211])
[ 3204.832330]  r7:c715e000 r6:c649b800 r5:c6906e20 r4:bf1ad370
[ 3204.838033] [<bf1607c4>] (nl80211_del_key [cfg80211]) from [<c0286f40>] (genl_rcv_msg+0x260/0x2e4)
[ 3204.846949]  r7:c6906e14 r6:bf170554 r5:bf1787d0 r4:00000000
[ 3204.852618] [<c0286ce0>] (genl_rcv_msg) from [<c0286260>] (netlink_rcv_skb+0x60/0xbc)
[ 3204.860410]  r10:c6709b40 r9:00000000 r8:c6475d84 r7:c68bb000 r6:c0286ce0 r5:c6709b40
[ 3204.868238]  r4:c6906e00
[ 3204.870770] [<c0286200>] (netlink_rcv_skb) from [<c0286ccc>] (genl_rcv+0x28/0x3c)
[ 3204.878217]  r7:c68bb000 r6:c6709b40 r5:c6709b40 r4:c04a42a0
[ 3204.883886] [<c0286ca4>] (genl_rcv) from [<c0285c48>] (netlink_unicast+0x138/0x1f4)
[ 3204.891505]  r5:00000030 r4:c7931c00
[ 3204.895083] [<c0285b10>] (netlink_unicast) from [<c02860c8>] (netlink_sendmsg+0x300/0x320)
[ 3204.903307]  r9:00000008 r8:00000000 r7:00000030 r6:c6475f4c r5:c68bb000 r4:00000000
[ 3204.911061] [<c0285dc8>] (netlink_sendmsg) from [<c0248de4>] (sock_sendmsg+0x1c/0x2c)
[ 3204.918851]  r10:00000000 r9:00000000 r8:00000000 r7:c7503500 r6:c6475e64 r5:00000000
[ 3204.926678]  r4:c6475f4c
[ 3204.929208] [<c0248dc8>] (sock_sendmsg) from [<c0249398>] (___sys_sendmsg+0x198/0x228)
[ 3204.937088] [<c0249200>] (___sys_sendmsg) from [<c024a1ec>] (__sys_sendmsg+0x44/0x68)
[ 3204.944874]  r10:00000000 r9:c6474000 r8:c00098c4 r7:00000128 r6:00000000 r5:beaf3770
[ 3204.952702]  r4:c7503500
[ 3204.955233] [<c024a1a8>] (__sys_sendmsg) from [<c024a220>] (SyS_sendmsg+0x10/0x14)
[ 3204.962760]  r6:b6f201c8 r5:00000000 r4:00000000
[ 3204.967382] [<c024a210>] (SyS_sendmsg) from [<c0009700>] (ret_fast_syscall+0x0/0x3c)
[ 3204.975127] ---[ end trace b29225cb54365629 ]---
[ 3204.979728] brcmfmac: [brcmf_netdev_wait_pend8021x] ifp:c649bc80 brcmf_ifname(ifp):wlan1-1 brcmf_get_pend_8021x_cnt(ifp):3
[ 3204.990733] brcmfmac: [brcmf_netdev_wait_pend8021x] List of pending 802.1x skbs:
[ 3204.998108] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c6901180 skb->dev:c649b800 skb->dev->name:wlan1-1
[ 3205.007650] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c6901f00 skb->dev:c649b800 skb->dev->name:wlan1-1
[ 3205.017190] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c6901b40 skb->dev:c649b800 skb->dev->name:wlan1-1
[ 3205.026823] brcmfmac: [brcmf_msgbuf_process_txstatus -> __brcmf_txfinalize] Finally finalizing skb:c6901180 skb->dev:c649b800 skb->dev->name:wlan1-1
[ 3205.040104] brcmfmac: [brcmf_msgbuf_process_txstatus -> __brcmf_txfinalize] Finally finalizing skb:c6901f00 skb->dev:c649b800 skb->dev->name:wlan1-1
[ 3205.053367] brcmfmac: [brcmf_msgbuf_process_txstatus -> __brcmf_txfinalize] Finally finalizing skb:c6901b40 skb->dev:c649b800 skb->dev->name:wlan1-1
[ 3228.604387] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c719d480 brcmf_ifname(ifp):wlan1
[ 3228.769758] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c719a480 brcmf_ifname(ifp):wlan0
[ 3229.737659] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c649bc80 brcmf_ifname(ifp):wlan1-1
[ 3229.751855] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c7ab4480 brcmf_ifname(ifp):wlan0-1
[ 3230.401808] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c7b1ec80 brcmf_ifname(ifp):wlan0-2
[ 3230.412403] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c6532c80 brcmf_ifname(ifp):wlan1-2



I'm pretty sure I have CONSOLE working as restarting wifi gives me some
messages:

[ 3604.964790] brcmfmac: CONSOLE: 003590.895 wl0: wlc_enable_probe_req: state down, deferring setting of host flags
[ 3607.429608] brcmfmac: CONSOLE: 003595.110 wl0: wlc_enable_probe_req: state down, deferring setting of host flags
[ 3609.430295] brcmfmac: CONSOLE: 003595.359 wl0: bc/mc deauth_reason on STA BSS?
[ 3609.623067] brcmfmac: CONSOLE: 003595.551 wl0: wlc_enable_probe_req: state down, deferring setting of host flags
[ 3609.739680] brcmfmac: CONSOLE: 003595.587 wl0: wlc_enable_probe_req: state down, deferring setting of host flags

^ permalink raw reply	[flat|nested] 6+ messages in thread

* Re: AMPDU stalls with brcmfmac4366b-pcie.bin triggering WARNINGs
  2016-09-14  5:45 AMPDU stalls with brcmfmac4366b-pcie.bin triggering WARNINGs Rafał Miłecki
  2016-09-14  7:25 ` Rafał Miłecki
@ 2016-09-14  8:43 ` Rafał Miłecki
  2016-09-14 18:28 ` Arend Van Spriel
  2 siblings, 0 replies; 6+ messages in thread
From: Rafał Miłecki @ 2016-09-14  8:43 UTC (permalink / raw)
  To: Hante Meuleman, Arend van Spriel, brcm80211-dev-list; +Cc: linux-wireless

On 09/14/2016 07:45 AM, Rafał Miłecki wrote:
> First of all, I can't reproduce these problems reliably. One evening I
> got WARNINGs one by one and I could work on my debugging patch easily.
> Yesterday when I got my patch complete, it took me 10+ hours to get a
> single WARNING.

I think I found a way to reproduce this more reliably! It seems doing a static
transfer from few devices (I use iperf) doesn't matter much. So this is what I
do to get WARNINGs on my DIR-885L:
1) Notebook sending data with iperf to DIR-885L
2) iPad playing YouTube using SR400ac on the same channel
3) I take my 2 smartphones to the next room and keep switching between 2 out of
    3 SSIDs of DIR-885L. Once connected I run iperf for a bit randomly.

It seems I can get a WARNINGs every few minutes this way.


> Enough talking, please take a look at my debugging log. Does it give you
> enough hint? Could you review/debug firmware's code responsible for
> AMPDU? FWIW Merlin users (so no brcmfmac invovled) also saw this [1].

I grabbed more logs I can share now. I believe they show the same: stall and
warning soon after ampdu_dbg/wlc_ampdu_watchdog. I'm attaching them anyway.

Please note that calls to __send_key_to_dongle happen all the time, I'm
including them in logs for a context. You can treat them as an indicator that
things are going well.
It's ampdu_dbg + wlc_ampdu_watchdog that lead up to the WARNINGs.


[ 1213.809245] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c695bc80 brcmf_ifname(ifp):wlan1
[ 1213.819946] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c780ec80 brcmf_ifname(ifp):wlan0
[ 1214.029819] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c64c1c80 brcmf_ifname(ifp):wlan0-1
[ 1214.359083] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c65a0480 brcmf_ifname(ifp):wlan1-2
[ 1214.389756] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c64c5c80 brcmf_ifname(ifp):wlan0-2
[ 1215.581850] brcmfmac: CONSOLE: 027945.032 ampdu_dbg: wl0.2 scb:00343a08 tid:0
[ 1215.589269] brcmfmac: CONSOLE: 027945.032 ampdu_dbg: wl0.2 dead_cnt 2 tx_in_transit 1 psm_mux 0xfff0 aqmqmap 0x0x101 aqmfifo_status 0x0x1a fifordy 0x2 cpbusy 0x0
[ 1215.603896] brcmfmac: CONSOLE: 027945.032 ampdu_dbg: ifsstat 0x18a0 nav_stat 0x0 txop 24973
[ 1215.612317] brcmfmac: CONSOLE: 027945.032 ampdu_dbg: pktpend: 0 32 0 0 0 ap 1
[ 1215.619540] brcmfmac: CONSOLE: 027945.032 ampdu_dbg: txall 4821 txbcn 0 txrts 0 rxcts 0 rsptmout 0 rxstrt 0
[ 1215.629381] brcmfmac: CONSOLE: 027945.032 ampdu_dbg: cwcur0-3 f f 7 3 bslots cur/0-3 4 0 4 0 0 ifs_boff 5
[ 1215.639015] brcmfmac: CONSOLE: 027945.032 ampdu_dbg: again1 ifsstat 0xa0 nav_stat 0x0
[ 1215.646906] brcmfmac: CONSOLE: 027945.032 ampdu_dbg: again2 ifsstat 0x18a0 nav_stat 0x0
[ 1215.655024] brcmfmac: CONSOLE: 027945.032 wl0: wlc_ampdu_watchdog: cleaning up ini tid 0 due to no progress for 2 secs tx_in_transit 1
[ 1215.667206] brcmfmac: CONSOLE: 027945.032 wl0: wlc_ampdu_tx_send_delba: tid 0 initiator 1 reason 39
[ 1217.368721] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c64d3480 brcmf_ifname(ifp):wlan1-1
[ 1218.328557] ------------[ cut here ]------------
[ 1218.333232] WARNING: CPU: 1 PID: 1130 at compat-wireless-2016-06-20/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.c:1219 brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac]()
[ 1218.349366] Modules linked in: pppoe ppp_async iptable_nat brcmfmac pppox ppp_generic nf_nat_ipv4 nf_conntrack_ipv6 nf_conntrack_ipv4 ipt_REJECT ipt_MASQUERADE cfg80211 xt_time xt_tcpudp xt_state xt_nat xt_multiport xt_mark xt_mac xt_limit xt_id xt_conntrack xt_commed
[ 1218.421716] CPU: 1 PID: 1130 Comm: hostapd Not tainted 4.4.19 #0
[ 1218.427735] Hardware name: BCM5301X
[ 1218.431225] Backtrace:
[ 1218.433699] [<c001708c>] (dump_backtrace) from [<c0017288>] (show_stack+0x18/0x1c)
[ 1218.441287]  r7:000004c3 r6:bf1d0e9c r5:60000013 r4:00000000
[ 1218.447003] [<c0017270>] (show_stack) from [<c017c210>] (dump_stack+0x84/0xa4)
[ 1218.454243] [<c017c18c>] (dump_stack) from [<c0021490>] (warn_slowpath_common+0x8c/0xb8)
[ 1218.462349]  r5:00000009 r4:00000000
[ 1218.465948] [<c0021404>] (warn_slowpath_common) from [<c0021560>] (warn_slowpath_null+0x24/0x2c)
[ 1218.474754]  r8:c72ce0a4 r7:00000001 r6:c6b8fb3c r5:00000000 r4:c64d3480
[ 1218.481533] [<c002153c>] (warn_slowpath_null) from [<bf1be578>] (brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac])
[ 1218.492006] [<bf1be4bc>] (brcmf_netdev_wait_pend8021x [brcmfmac]) from [<bf1ab200>] (brcmf_cfg80211_sched_scan_start+0x460/0x6c0 [brcmfmac])
[ 1218.504633]  r8:c72ce0a4 r7:bf1c8613 r6:c64d3480 r5:c04903c8 r4:c72ce394
[ 1218.511404] [<bf1ab13c>] (brcmf_cfg80211_sched_scan_start [brcmfmac]) from [<bf1ad740>] (brcmf_cfg80211_add_key+0x2e0/0x3dc [brcmfmac])
[ 1218.523599]  r7:00000000 r6:c64d3480 r5:c72ce0a4 r4:00000004
[ 1218.529341] [<bf1ad460>] (brcmf_cfg80211_add_key [brcmfmac]) from [<bf160b48>] (nl80211_new_key+0xfc/0x128 [cfg80211])
[ 1218.540059]  r10:00000014 r9:c735ec00 r8:c6b8fca0 r7:c696c000 r6:c64d3000 r5:00000000
[ 1218.547944]  r4:bf1ad460
[ 1218.550514] [<bf160a4c>] (nl80211_new_key [cfg80211]) from [<c0286f40>] (genl_rcv_msg+0x260/0x2e4)
[ 1218.559487]  r8:c66663c0 r7:c6b42e14 r6:bf170540 r5:bf1787d0 r4:00000000
[ 1218.566246] [<c0286ce0>] (genl_rcv_msg) from [<c0286260>] (netlink_rcv_skb+0x60/0xbc)
[ 1218.574091]  r10:c66663c0 r9:00000000 r8:c6b8fd84 r7:c6516400 r6:c0286ce0 r5:c66663c0
[ 1218.581977]  r4:c6b42e00
[ 1218.584524] [<c0286200>] (netlink_rcv_skb) from [<c0286ccc>] (genl_rcv+0x28/0x3c)
[ 1218.592022]  r7:c6516400 r6:c66663c0 r5:c66663c0 r4:c04a42a0
[ 1218.597728] [<c0286ca4>] (genl_rcv) from [<c0285c48>] (netlink_unicast+0x138/0x1f4)
[ 1218.605400]  r5:00000048 r4:c799a000
[ 1218.609000] [<c0285b10>] (netlink_unicast) from [<c02860c8>] (netlink_sendmsg+0x300/0x320)
[ 1218.617281]  r9:00000008 r8:00000000 r7:00000048 r6:c6b8ff4c r5:c6516400 r4:00000000
[ 1218.625087] [<c0285dc8>] (netlink_sendmsg) from [<c0248de4>] (sock_sendmsg+0x1c/0x2c)
[ 1218.632930]  r10:00000000 r9:00000000 r8:00000000 r7:c7536a80 r6:c6b8fe64 r5:00000000
[ 1218.640816]  r4:c6b8ff4c
[ 1218.643361] [<c0248dc8>] (sock_sendmsg) from [<c0249398>] (___sys_sendmsg+0x198/0x228)
[ 1218.651292] [<c0249200>] (___sys_sendmsg) from [<c024a1ec>] (__sys_sendmsg+0x44/0x68)
[ 1218.659139]  r10:00000000 r9:c6b8e000 r8:c00098c4 r7:00000128 r6:00000000 r5:bee037c0
[ 1218.667024]  r4:c7536a80
[ 1218.669571] [<c024a1a8>] (__sys_sendmsg) from [<c024a220>] (SyS_sendmsg+0x10/0x14)
[ 1218.677156]  r6:b6f0a1c8 r5:00000000 r4:00000000
[ 1218.681810] [<c024a210>] (SyS_sendmsg) from [<c0009700>] (ret_fast_syscall+0x0/0x3c)
[ 1218.689603] ---[ end trace e3199c520974d43f ]---
[ 1218.694230] brcmfmac: [brcmf_netdev_wait_pend8021x] ifp:c64d3480 brcmf_ifname(ifp):wlan1-1 brcmf_get_pend_8021x_cnt(ifp):3
[ 1218.705307] brcmfmac: [brcmf_netdev_wait_pend8021x] List of pending 802.1x skbs:
[ 1218.712730] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c647ee40 skb->dev:c64d3000 skb->dev->name:wlan1-1
[ 1218.722321] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c72369c0 skb->dev:c64d3000 skb->dev->name:wlan1-1
[ 1218.731912] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c6b99180 skb->dev:c64d3000 skb->dev->name:wlan1-1
[ 1218.744839] brcmfmac: [brcmf_cfg80211_del_key -> __send_key_to_dongle] ifp:c64d3480 brcmf_ifname(ifp):wlan1-1
[ 1219.708556] ------------[ cut here ]------------
[ 1219.713235] WARNING: CPU: 1 PID: 1130 at compat-wireless-2016-06-20/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.c:1219 brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac]()
[ 1219.729367] Modules linked in: pppoe ppp_async iptable_nat brcmfmac pppox ppp_generic nf_nat_ipv4 nf_conntrack_ipv6 nf_conntrack_ipv4 ipt_REJECT ipt_MASQUERADE cfg80211 xt_time xt_tcpudp xt_state xt_nat xt_multiport xt_mark xt_mac xt_limit xt_id xt_conntrack xt_commed
[ 1219.801736] CPU: 1 PID: 1130 Comm: hostapd Tainted: G        W       4.4.19 #0
[ 1219.808973] Hardware name: BCM5301X
[ 1219.812462] Backtrace:
[ 1219.814937] [<c001708c>] (dump_backtrace) from [<c0017288>] (show_stack+0x18/0x1c)
[ 1219.822524]  r7:000004c3 r6:bf1d0e9c r5:60000013 r4:00000000
[ 1219.828241] [<c0017270>] (show_stack) from [<c017c210>] (dump_stack+0x84/0xa4)
[ 1219.835480] [<c017c18c>] (dump_stack) from [<c0021490>] (warn_slowpath_common+0x8c/0xb8)
[ 1219.843587]  r5:00000009 r4:00000000
[ 1219.847185] [<c0021404>] (warn_slowpath_common) from [<c0021560>] (warn_slowpath_null+0x24/0x2c)
[ 1219.855982]  r8:c739dd80 r7:00000001 r6:c6b8fb74 r5:00000000 r4:c64d3480
[ 1219.862760] [<c002153c>] (warn_slowpath_null) from [<bf1be578>] (brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac])
[ 1219.873234] [<bf1be4bc>] (brcmf_netdev_wait_pend8021x [brcmfmac]) from [<bf1ab200>] (brcmf_cfg80211_sched_scan_start+0x460/0x6c0 [brcmfmac])
[ 1219.885862]  r8:c739dd80 r7:bf1c85fc r6:c64d3480 r5:c04903c8 r4:c72ce2f0
[ 1219.892633] [<bf1ab13c>] (brcmf_cfg80211_sched_scan_start [brcmfmac]) from [<bf1ad420>] (brcmf_cfg80211_del_key+0xb0/0xf0 [brcmfmac])
[ 1219.904654]  r7:c64d3480 r6:00000002 r5:c72ce254 r4:c72ce000
[ 1219.910396] [<bf1ad370>] (brcmf_cfg80211_del_key [brcmfmac]) from [<bf1608b8>] (nl80211_del_key+0xf4/0x148 [cfg80211])
[ 1219.921114]  r7:c696c000 r6:c64d3000 r5:c650f220 r4:bf1ad370
[ 1219.926844] [<bf1607c4>] (nl80211_del_key [cfg80211]) from [<c0286f40>] (genl_rcv_msg+0x260/0x2e4)
[ 1219.935824]  r7:c650f214 r6:bf170554 r5:bf1787d0 r4:00000000
[ 1219.941530] [<c0286ce0>] (genl_rcv_msg) from [<c0286260>] (netlink_rcv_skb+0x60/0xbc)
[ 1219.949376]  r10:c739dd80 r9:00000000 r8:c6b8fd84 r7:c6516400 r6:c0286ce0 r5:c739dd80
[ 1219.957261]  r4:c650f200
[ 1219.959809] [<c0286200>] (netlink_rcv_skb) from [<c0286ccc>] (genl_rcv+0x28/0x3c)
[ 1219.967306]  r7:c6516400 r6:c739dd80 r5:c739dd80 r4:c04a42a0
[ 1219.973012] [<c0286ca4>] (genl_rcv) from [<c0285c48>] (netlink_unicast+0x138/0x1f4)
[ 1219.980685]  r5:00000030 r4:c799a000
[ 1219.984284] [<c0285b10>] (netlink_unicast) from [<c02860c8>] (netlink_sendmsg+0x300/0x320)
[ 1219.992565]  r9:00000008 r8:00000000 r7:00000030 r6:c6b8ff4c r5:c6516400 r4:00000000
[ 1220.000371] [<c0285dc8>] (netlink_sendmsg) from [<c0248de4>] (sock_sendmsg+0x1c/0x2c)
[ 1220.008214]  r10:00000000 r9:00000000 r8:00000000 r7:c7536a80 r6:c6b8fe64 r5:00000000
[ 1220.016100]  r4:c6b8ff4c
[ 1220.018646] [<c0248dc8>] (sock_sendmsg) from [<c0249398>] (___sys_sendmsg+0x198/0x228)
[ 1220.026576] [<c0249200>] (___sys_sendmsg) from [<c024a1ec>] (__sys_sendmsg+0x44/0x68)
[ 1220.034422]  r10:00000000 r9:c6b8e000 r8:c00098c4 r7:00000128 r6:00000000 r5:bee03790
[ 1220.042309]  r4:c7536a80
[ 1220.044854] [<c024a1a8>] (__sys_sendmsg) from [<c024a220>] (SyS_sendmsg+0x10/0x14)
[ 1220.052440]  r6:b6f0a1c8 r5:00000000 r4:00000000
[ 1220.057094] [<c024a210>] (SyS_sendmsg) from [<c0009700>] (ret_fast_syscall+0x0/0x3c)
[ 1220.064881] ---[ end trace e3199c520974d440 ]---
[ 1220.069529] brcmfmac: [brcmf_netdev_wait_pend8021x] ifp:c64d3480 brcmf_ifname(ifp):wlan1-1 brcmf_get_pend_8021x_cnt(ifp):3
[ 1220.080605] brcmfmac: [brcmf_netdev_wait_pend8021x] List of pending 802.1x skbs:
[ 1220.088016] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c647ee40 skb->dev:c64d3000 skb->dev->name:wlan1-1
[ 1220.097606] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c72369c0 skb->dev:c64d3000 skb->dev->name:wlan1-1
[ 1220.107197] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c6b99180 skb->dev:c64d3000 skb->dev->name:wlan1-1
[ 1222.597085] brcmfmac: CONSOLE: 027952.044 wl0: Proxy STA 78:d6:f0:9b:ba:bc link is already gone !!??
[ 1222.606543] brcmfmac: [brcmf_msgbuf_process_txstatus -> __brcmf_txfinalize] Finally finalizing skb:c647ee40 skb->dev:c64d3000 skb->dev->name:wlan1-1
[ 1222.619911] brcmfmac: [brcmf_msgbuf_process_txstatus -> __brcmf_txfinalize] Finally finalizing skb:c72369c0 skb->dev:c64d3000 skb->dev->name:wlan1-1
[ 1222.633274] brcmfmac: [brcmf_msgbuf_process_txstatus -> __brcmf_txfinalize] Finally finalizing skb:c6b99180 skb->dev:c64d3000 skb->dev->name:wlan1-1
[ 1243.839113] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c695bc80 brcmf_ifname(ifp):wlan1
[ 1243.850070] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c780ec80 brcmf_ifname(ifp):wlan0
[ 1244.049797] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c64c1c80 brcmf_ifname(ifp):wlan0-1
[ 1244.379059] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c65a0480 brcmf_ifname(ifp):wlan1-2
[ 1244.409084] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c64c5c80 brcmf_ifname(ifp):wlan0-2
[ 1244.532211] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c64d3480 brcmf_ifname(ifp):wlan1-1
[ 1244.672407] brcmfmac: CONSOLE: 027974.121 wl0.2: wlc_send_bar: seq 0xd96 tid 0


[ 1419.521703] brcmfmac: CONSOLE: 028148.962 wl0: wlc_ampdu_rx_recv_delba: AMPDU OFF: tid 0 initiator 1 reason 39
[ 1420.346975] brcmfmac: CONSOLE: 028149.786 wl0.3: wlc_send_bar: seq 0x1 tid 6
[ 1423.166160] brcmfmac: CONSOLE: 028152.603 ampdu_dbg: wl0.3 scb:00344c30 tid:0
[ 1423.173521] brcmfmac: CONSOLE: 028152.603 ampdu_dbg: wl0.3 dead_cnt 2 tx_in_transit 1 psm_mux 0x200 aqmqmap 0x0x101 aqmfifo_status 0x0x1 fifordy 0x2 cpbusy 0x0
[ 1423.187872] brcmfmac: CONSOLE: 028152.603 ampdu_dbg: ifsstat 0x1da0 nav_stat 0x0 txop 27528
[ 1423.196289] brcmfmac: CONSOLE: 028152.603 ampdu_dbg: pktpend: 0 1 0 0 0 ap 1
[ 1423.203434] brcmfmac: CONSOLE: 028152.603 ampdu_dbg: txall 5454 txbcn 0 txrts 0 rxcts 0 rsptmout 0 rxstrt 0
[ 1423.213266] brcmfmac: CONSOLE: 028152.603 ampdu_dbg: cwcur0-3 f f 7 3 bslots cur/0-3 8 0 8 0 0 ifs_boff 0
[ 1423.222905] brcmfmac: CONSOLE: 028152.603 ampdu_dbg: again1 ifsstat 0x1d80 nav_stat 0x0
[ 1423.230972] brcmfmac: CONSOLE: 028152.603 ampdu_dbg: again2 ifsstat 0x1d80 nav_stat 0x0
[ 1423.239081] brcmfmac: CONSOLE: 028152.603 wl0: wlc_ampdu_watchdog: cleaning up ini tid 0 due to no progress for 2 secs tx_in_transit 1
[ 1423.251255] brcmfmac: CONSOLE: 028152.603 wl0: wlc_ampdu_tx_send_delba: tid 0 initiator 1 reason 39
[ 1423.989156] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c695bc80 brcmf_ifname(ifp):wlan1
[ 1424.000369] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c780ec80 brcmf_ifname(ifp):wlan0
[ 1424.018123] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c64d3480 brcmf_ifname(ifp):wlan1-1
[ 1424.170006] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c64c1c80 brcmf_ifname(ifp):wlan0-1
[ 1424.529823] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c64c5c80 brcmf_ifname(ifp):wlan0-2
[ 1427.958783] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c65a0480 brcmf_ifname(ifp):wlan1-2
[ 1428.918558] ------------[ cut here ]------------
[ 1428.923235] WARNING: CPU: 1 PID: 1130 at compat-wireless-2016-06-20/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.c:1219 brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac]()
[ 1428.939369] Modules linked in: pppoe ppp_async iptable_nat brcmfmac pppox ppp_generic nf_nat_ipv4 nf_conntrack_ipv6 nf_conntrack_ipv4 ipt_REJECT ipt_MASQUERADE cfg80211 xt_time xt_tcpudp xt_state xt_nat xt_multiport xt_mark xt_mac xt_limit xt_id xt_conntrack xt_commed
[ 1429.011756] CPU: 1 PID: 1130 Comm: hostapd Tainted: G        W       4.4.19 #0
[ 1429.018992] Hardware name: BCM5301X
[ 1429.022481] Backtrace:
[ 1429.024957] [<c001708c>] (dump_backtrace) from [<c0017288>] (show_stack+0x18/0x1c)
[ 1429.032544]  r7:000004c3 r6:bf1d0e9c r5:60000013 r4:00000000
[ 1429.038261] [<c0017270>] (show_stack) from [<c017c210>] (dump_stack+0x84/0xa4)
[ 1429.045499] [<c017c18c>] (dump_stack) from [<c0021490>] (warn_slowpath_common+0x8c/0xb8)
[ 1429.053606]  r5:00000009 r4:00000000
[ 1429.057205] [<c0021404>] (warn_slowpath_common) from [<c0021560>] (warn_slowpath_null+0x24/0x2c)
[ 1429.066010]  r8:c71c8148 r7:00000001 r6:c6b8fb3c r5:00000000 r4:c65a0480
[ 1429.072791] [<c002153c>] (warn_slowpath_null) from [<bf1be578>] (brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac])
[ 1429.083263] [<bf1be4bc>] (brcmf_netdev_wait_pend8021x [brcmfmac]) from [<bf1ab200>] (brcmf_cfg80211_sched_scan_start+0x460/0x6c0 [brcmfmac])
[ 1429.095891]  r8:c71c8148 r7:bf1c8613 r6:c65a0480 r5:c04903c8 r4:c71c8438
[ 1429.102661] [<bf1ab13c>] (brcmf_cfg80211_sched_scan_start [brcmfmac]) from [<bf1ad740>] (brcmf_cfg80211_add_key+0x2e0/0x3dc [brcmfmac])
[ 1429.114857]  r7:00000000 r6:c65a0480 r5:c71c8148 r4:00000004
[ 1429.120598] [<bf1ad460>] (brcmf_cfg80211_add_key [brcmfmac]) from [<bf160b48>] (nl80211_new_key+0xfc/0x128 [cfg80211])
[ 1429.131317]  r10:00000014 r9:c735ec00 r8:c6b8fca0 r7:c696c000 r6:c65a0000 r5:00000000
[ 1429.139201]  r4:bf1ad460
[ 1429.141771] [<bf160a4c>] (nl80211_new_key [cfg80211]) from [<c0286f40>] (genl_rcv_msg+0x260/0x2e4)
[ 1429.150743]  r8:c731ee40 r7:c6a5e614 r6:bf170540 r5:bf1787d0 r4:00000000
[ 1429.157503] [<c0286ce0>] (genl_rcv_msg) from [<c0286260>] (netlink_rcv_skb+0x60/0xbc)
[ 1429.165348]  r10:c731ee40 r9:00000000 r8:c6b8fd84 r7:c6516400 r6:c0286ce0 r5:c731ee40
[ 1429.173235]  r4:c6a5e600
[ 1429.175781] [<c0286200>] (netlink_rcv_skb) from [<c0286ccc>] (genl_rcv+0x28/0x3c)
[ 1429.183279]  r7:c6516400 r6:c731ee40 r5:c731ee40 r4:c04a42a0
[ 1429.188985] [<c0286ca4>] (genl_rcv) from [<c0285c48>] (netlink_unicast+0x138/0x1f4)
[ 1429.196657]  r5:00000048 r4:c799a000
[ 1429.200256] [<c0285b10>] (netlink_unicast) from [<c02860c8>] (netlink_sendmsg+0x300/0x320)
[ 1429.208537]  r9:00000008 r8:00000000 r7:00000048 r6:c6b8ff4c r5:c6516400 r4:00000000
[ 1429.216344] [<c0285dc8>] (netlink_sendmsg) from [<c0248de4>] (sock_sendmsg+0x1c/0x2c)
[ 1429.224187]  r10:00000000 r9:00000000 r8:00000000 r7:c7536a80 r6:c6b8fe64 r5:00000000
[ 1429.232073]  r4:c6b8ff4c
[ 1429.234618] [<c0248dc8>] (sock_sendmsg) from [<c0249398>] (___sys_sendmsg+0x198/0x228)
[ 1429.242558] [<c0249200>] (___sys_sendmsg) from [<c024a1ec>] (__sys_sendmsg+0x44/0x68)
[ 1429.250404]  r10:00000000 r9:c6b8e000 r8:c00098c4 r7:00000128 r6:00000000 r5:bee037c0
[ 1429.258290]  r4:c7536a80
[ 1429.260836] [<c024a1a8>] (__sys_sendmsg) from [<c024a220>] (SyS_sendmsg+0x10/0x14)
[ 1429.268422]  r6:00000006 r5:00000000 r4:00000000
[ 1429.273075] [<c024a210>] (SyS_sendmsg) from [<c0009700>] (ret_fast_syscall+0x0/0x3c)
[ 1429.280917] ---[ end trace e3199c520974d441 ]---
[ 1429.285548] brcmfmac: [brcmf_netdev_wait_pend8021x] ifp:c65a0480 brcmf_ifname(ifp):wlan1-2 brcmf_get_pend_8021x_cnt(ifp):1
[ 1429.296627] brcmfmac: [brcmf_netdev_wait_pend8021x] List of pending 802.1x skbs:
[ 1429.304048] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c64e5d80 skb->dev:c65a0000 skb->dev->name:wlan1-2
[ 1429.316441] brcmfmac: [brcmf_cfg80211_del_key -> __send_key_to_dongle] ifp:c65a0480 brcmf_ifname(ifp):wlan1-2
[ 1430.278565] ------------[ cut here ]------------
[ 1430.283245] WARNING: CPU: 1 PID: 1130 at compat-wireless-2016-06-20/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.c:1219 brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac]()
[ 1430.299380] Modules linked in: pppoe ppp_async iptable_nat brcmfmac pppox ppp_generic nf_nat_ipv4 nf_conntrack_ipv6 nf_conntrack_ipv4 ipt_REJECT ipt_MASQUERADE cfg80211 xt_time xt_tcpudp xt_state xt_nat xt_multiport xt_mark xt_mac xt_limit xt_id xt_conntrack xt_commed
[ 1430.371763] CPU: 1 PID: 1130 Comm: hostapd Tainted: G        W       4.4.19 #0
[ 1430.379000] Hardware name: BCM5301X
[ 1430.382491] Backtrace:
[ 1430.384965] [<c001708c>] (dump_backtrace) from [<c0017288>] (show_stack+0x18/0x1c)
[ 1430.392552]  r7:000004c3 r6:bf1d0e9c r5:60000013 r4:00000000
[ 1430.398269] [<c0017270>] (show_stack) from [<c017c210>] (dump_stack+0x84/0xa4)
[ 1430.405508] [<c017c18c>] (dump_stack) from [<c0021490>] (warn_slowpath_common+0x8c/0xb8)
[ 1430.413615]  r5:00000009 r4:00000000
[ 1430.417213] [<c0021404>] (warn_slowpath_common) from [<c0021560>] (warn_slowpath_null+0x24/0x2c)
[ 1430.426010]  r8:c64b90c0 r7:00000001 r6:c6b8fb74 r5:00000000 r4:c65a0480
[ 1430.432789] [<c002153c>] (warn_slowpath_null) from [<bf1be578>] (brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac])
[ 1430.443262] [<bf1be4bc>] (brcmf_netdev_wait_pend8021x [brcmfmac]) from [<bf1ab200>] (brcmf_cfg80211_sched_scan_start+0x460/0x6c0 [brcmfmac])
[ 1430.455891]  r8:c64b90c0 r7:bf1c85fc r6:c65a0480 r5:c04903c8 r4:c71c82f0
[ 1430.462661] [<bf1ab13c>] (brcmf_cfg80211_sched_scan_start [brcmfmac]) from [<bf1ad420>] (brcmf_cfg80211_del_key+0xb0/0xf0 [brcmfmac])
[ 1430.474682]  r7:c65a0480 r6:00000002 r5:c71c8254 r4:c71c8000
[ 1430.480423] [<bf1ad370>] (brcmf_cfg80211_del_key [brcmfmac]) from [<bf1608b8>] (nl80211_del_key+0xf4/0x148 [cfg80211])
[ 1430.491142]  r7:c696c000 r6:c65a0000 r5:c7389d20 r4:bf1ad370
[ 1430.496870] [<bf1607c4>] (nl80211_del_key [cfg80211]) from [<c0286f40>] (genl_rcv_msg+0x260/0x2e4)
[ 1430.505842]  r7:c7389d14 r6:bf170554 r5:bf1787d0 r4:00000000
[ 1430.511550] [<c0286ce0>] (genl_rcv_msg) from [<c0286260>] (netlink_rcv_skb+0x60/0xbc)
[ 1430.519394]  r10:c64b90c0 r9:00000000 r8:c6b8fd84 r7:c6516400 r6:c0286ce0 r5:c64b90c0
[ 1430.527281]  r4:c7389d00
[ 1430.529827] [<c0286200>] (netlink_rcv_skb) from [<c0286ccc>] (genl_rcv+0x28/0x3c)
[ 1430.537324]  r7:c6516400 r6:c64b90c0 r5:c64b90c0 r4:c04a42a0
[ 1430.543031] [<c0286ca4>] (genl_rcv) from [<c0285c48>] (netlink_unicast+0x138/0x1f4)
[ 1430.550702]  r5:00000030 r4:c799a000
[ 1430.554304] [<c0285b10>] (netlink_unicast) from [<c02860c8>] (netlink_sendmsg+0x300/0x320)
[ 1430.562583]  r9:00000008 r8:00000000 r7:00000030 r6:c6b8ff4c r5:c6516400 r4:00000000
[ 1430.570391] [<c0285dc8>] (netlink_sendmsg) from [<c0248de4>] (sock_sendmsg+0x1c/0x2c)
[ 1430.578234]  r10:00000000 r9:00000000 r8:00000000 r7:c7536a80 r6:c6b8fe64 r5:00000000
[ 1430.586120]  r4:c6b8ff4c
[ 1430.588665] [<c0248dc8>] (sock_sendmsg) from [<c0249398>] (___sys_sendmsg+0x198/0x228)
[ 1430.596604] [<c0249200>] (___sys_sendmsg) from [<c024a1ec>] (__sys_sendmsg+0x44/0x68)
[ 1430.604450]  r10:00000000 r9:c6b8e000 r8:c00098c4 r7:00000128 r6:00000000 r5:bee03790
[ 1430.612336]  r4:c7536a80
[ 1430.614882] [<c024a1a8>] (__sys_sendmsg) from [<c024a220>] (SyS_sendmsg+0x10/0x14)
[ 1430.622467]  r6:00000006 r5:00000000 r4:00000000
[ 1430.627121] [<c024a210>] (SyS_sendmsg) from [<c0009700>] (ret_fast_syscall+0x0/0x3c)
[ 1430.634935] ---[ end trace e3199c520974d442 ]---
[ 1430.639574] brcmfmac: [brcmf_netdev_wait_pend8021x] ifp:c65a0480 brcmf_ifname(ifp):wlan1-2 brcmf_get_pend_8021x_cnt(ifp):1
[ 1430.650650] brcmfmac: [brcmf_netdev_wait_pend8021x] List of pending 802.1x skbs:
[ 1430.658061] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c64e5d80 skb->dev:c65a0000 skb->dev->name:wlan1-2
[ 1433.091596] brcmfmac: CONSOLE: 028162.527 wl0: Proxy STA 78:d6:f0:9b:ba:bc link is already gone !!??
[ 1433.151731] brcmfmac: [brcmf_msgbuf_process_txstatus -> __brcmf_txfinalize] Finally finalizing skb:c64e5d80 skb->dev:c65a0000 skb->dev->name:wlan1-2
[ 1445.329593] brcmfmac: CONSOLE: 028174.764 wl0.3: wlc_send_bar: seq 0xc6e tid 0
[ 1446.332452] brcmfmac: CONSOLE: 028175.767 wl0.3: wlc_send_bar: seq 0xc6f tid 0
[ 1454.009194] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c695bc80 brcmf_ifname(ifp):wlan1
[ 1454.020432] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c780ec80 brcmf_ifname(ifp):wlan0
[ 1454.121584] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c64d3480 brcmf_ifname(ifp):wlan1-1
[ 1454.189851] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c64c1c80 brcmf_ifname(ifp):wlan0-1
[ 1454.549783] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c64c5c80 brcmf_ifname(ifp):wlan0-2
[ 1454.561299] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c65a0480 brcmf_ifname(ifp):wlan1-2


[ 1604.139419] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c780ec80 brcmf_ifname(ifp):wlan0
[ 1604.150635] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c695bc80 brcmf_ifname(ifp):wlan1
[ 1604.238314] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c64d3480 brcmf_ifname(ifp):wlan1-1
[ 1604.289129] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c64c1c80 brcmf_ifname(ifp):wlan0-1
[ 1604.659083] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c64c5c80 brcmf_ifname(ifp):wlan0-2
[ 1605.551886] brcmfmac: CONSOLE: 028334.964 ampdu_dbg: wl0.3 scb:00344060 tid:0
[ 1605.559253] brcmfmac: CONSOLE: 028334.964 ampdu_dbg: wl0.3 dead_cnt 2 tx_in_transit 1 psm_mux 0xfff0 aqmqmap 0x0x101 aqmfifo_status 0x0x1 fifordy 0x2 cpbusy 0x0
[ 1605.573688] brcmfmac: CONSOLE: 028334.964 ampdu_dbg: ifsstat 0x1d80 nav_stat 0x0 txop 31752
[ 1605.582096] brcmfmac: CONSOLE: 028334.964 ampdu_dbg: pktpend: 0 1 0 0 0 ap 1
[ 1605.589224] brcmfmac: CONSOLE: 028334.964 ampdu_dbg: txall 5893 txbcn 0 txrts 0 rxcts 0 rsptmout 0 rxstrt 0
[ 1605.599049] brcmfmac: CONSOLE: 028334.964 ampdu_dbg: cwcur0-3 f f 7 3 bslots cur/0-3 13 0 13 0 0 ifs_boff 0
[ 1605.608861] brcmfmac: CONSOLE: 028334.964 ampdu_dbg: again1 ifsstat 0x1ea0 nav_stat 0x0
[ 1605.616923] brcmfmac: CONSOLE: 028334.964 ampdu_dbg: again2 ifsstat 0xa0 nav_stat 0x0
[ 1605.624853] brcmfmac: CONSOLE: 028334.964 wl0: wlc_ampdu_watchdog: cleaning up ini tid 0 due to no progress for 2 secs tx_in_transit 1
[ 1605.637027] brcmfmac: CONSOLE: 028334.964 wl0: wlc_ampdu_tx_send_delba: tid 0 initiator 1 reason 39
[ 1607.988759] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c65a0480 brcmf_ifname(ifp):wlan1-2
[ 1608.948558] ------------[ cut here ]------------
[ 1608.953229] WARNING: CPU: 1 PID: 1130 at compat-wireless-2016-06-20/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.c:1219 brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac]()
[ 1608.969361] Modules linked in: pppoe ppp_async iptable_nat brcmfmac pppox ppp_generic nf_nat_ipv4 nf_conntrack_ipv6 nf_conntrack_ipv4 ipt_REJECT ipt_MASQUERADE cfg80211 xt_time xt_tcpudp xt_state xt_nat xt_multiport xt_mark xt_mac xt_limit xt_id xt_conntrack xt_commed
[ 1609.041801] CPU: 1 PID: 1130 Comm: hostapd Tainted: G        W       4.4.19 #0
[ 1609.049036] Hardware name: BCM5301X
[ 1609.052528] Backtrace:
[ 1609.055001] [<c001708c>] (dump_backtrace) from [<c0017288>] (show_stack+0x18/0x1c)
[ 1609.062581]  r7:000004c3 r6:bf1d0e9c r5:60000013 r4:00000000
[ 1609.068297] [<c0017270>] (show_stack) from [<c017c210>] (dump_stack+0x84/0xa4)
[ 1609.075537] [<c017c18c>] (dump_stack) from [<c0021490>] (warn_slowpath_common+0x8c/0xb8)
[ 1609.083643]  r5:00000009 r4:00000000
[ 1609.087241] [<c0021404>] (warn_slowpath_common) from [<c0021560>] (warn_slowpath_null+0x24/0x2c)
[ 1609.096038]  r8:c71c8148 r7:00000001 r6:c6b8fb3c r5:00000000 r4:c65a0480
[ 1609.102820] [<c002153c>] (warn_slowpath_null) from [<bf1be578>] (brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac])
[ 1609.113292] [<bf1be4bc>] (brcmf_netdev_wait_pend8021x [brcmfmac]) from [<bf1ab200>] (brcmf_cfg80211_sched_scan_start+0x460/0x6c0 [brcmfmac])
[ 1609.125920]  r8:c71c8148 r7:bf1c8613 r6:c65a0480 r5:c04903c8 r4:c71c8438
[ 1609.132689] [<bf1ab13c>] (brcmf_cfg80211_sched_scan_start [brcmfmac]) from [<bf1ad740>] (brcmf_cfg80211_add_key+0x2e0/0x3dc [brcmfmac])
[ 1609.144885]  r7:00000000 r6:c65a0480 r5:c71c8148 r4:00000004
[ 1609.150626] [<bf1ad460>] (brcmf_cfg80211_add_key [brcmfmac]) from [<bf160b48>] (nl80211_new_key+0xfc/0x128 [cfg80211])
[ 1609.161345]  r10:00000014 r9:c735ec00 r8:c6b8fca0 r7:c696c000 r6:c65a0000 r5:00000000
[ 1609.169230]  r4:bf1ad460
[ 1609.171800] [<bf160a4c>] (nl80211_new_key [cfg80211]) from [<c0286f40>] (genl_rcv_msg+0x260/0x2e4)
[ 1609.180771]  r8:c731e9c0 r7:c69b7414 r6:bf170540 r5:bf1787d0 r4:00000000
[ 1609.187533] [<c0286ce0>] (genl_rcv_msg) from [<c0286260>] (netlink_rcv_skb+0x60/0xbc)
[ 1609.195378]  r10:c731e9c0 r9:00000000 r8:c6b8fd84 r7:c6516400 r6:c0286ce0 r5:c731e9c0
[ 1609.203263]  r4:c69b7400
[ 1609.205810] [<c0286200>] (netlink_rcv_skb) from [<c0286ccc>] (genl_rcv+0x28/0x3c)
[ 1609.213307]  r7:c6516400 r6:c731e9c0 r5:c731e9c0 r4:c04a42a0
[ 1609.219014] [<c0286ca4>] (genl_rcv) from [<c0285c48>] (netlink_unicast+0x138/0x1f4)
[ 1609.226685]  r5:00000048 r4:c799a000
[ 1609.230286] [<c0285b10>] (netlink_unicast) from [<c02860c8>] (netlink_sendmsg+0x300/0x320)
[ 1609.238567]  r9:00000008 r8:00000000 r7:00000048 r6:c6b8ff4c r5:c6516400 r4:00000000
[ 1609.246372] [<c0285dc8>] (netlink_sendmsg) from [<c0248de4>] (sock_sendmsg+0x1c/0x2c)
[ 1609.254216]  r10:00000000 r9:00000000 r8:00000000 r7:c7536a80 r6:c6b8fe64 r5:00000000
[ 1609.262102]  r4:c6b8ff4c
[ 1609.264647] [<c0248dc8>] (sock_sendmsg) from [<c0249398>] (___sys_sendmsg+0x198/0x228)
[ 1609.272577] [<c0249200>] (___sys_sendmsg) from [<c024a1ec>] (__sys_sendmsg+0x44/0x68)
[ 1609.280423]  r10:00000000 r9:c6b8e000 r8:c00098c4 r7:00000128 r6:00000000 r5:bee037c0
[ 1609.288310]  r4:c7536a80
[ 1609.290855] [<c024a1a8>] (__sys_sendmsg) from [<c024a220>] (SyS_sendmsg+0x10/0x14)
[ 1609.298441]  r6:00000006 r5:00000000 r4:00000000
[ 1609.303095] [<c024a210>] (SyS_sendmsg) from [<c0009700>] (ret_fast_syscall+0x0/0x3c)
[ 1609.310876] ---[ end trace e3199c520974d443 ]---
[ 1609.315507] brcmfmac: [brcmf_netdev_wait_pend8021x] ifp:c65a0480 brcmf_ifname(ifp):wlan1-2 brcmf_get_pend_8021x_cnt(ifp):3
[ 1609.326581] brcmfmac: [brcmf_netdev_wait_pend8021x] List of pending 802.1x skbs:
[ 1609.333997] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c681f3c0 skb->dev:c65a0000 skb->dev->name:wlan1-2
[ 1609.343589] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c7116900 skb->dev:c65a0000 skb->dev->name:wlan1-2
[ 1609.353185] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c7361a80 skb->dev:c65a0000 skb->dev->name:wlan1-2
[ 1609.365870] brcmfmac: [brcmf_cfg80211_del_key -> __send_key_to_dongle] ifp:c65a0480 brcmf_ifname(ifp):wlan1-2
[ 1610.328562] ------------[ cut here ]------------
[ 1610.333240] WARNING: CPU: 1 PID: 1130 at compat-wireless-2016-06-20/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.c:1219 brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac]()
[ 1610.349374] Modules linked in: pppoe ppp_async iptable_nat brcmfmac pppox ppp_generic nf_nat_ipv4 nf_conntrack_ipv6 nf_conntrack_ipv4 ipt_REJECT ipt_MASQUERADE cfg80211 xt_time xt_tcpudp xt_state xt_nat xt_multiport xt_mark xt_mac xt_limit xt_id xt_conntrack xt_commed
[ 1610.421742] CPU: 1 PID: 1130 Comm: hostapd Tainted: G        W       4.4.19 #0
[ 1610.428977] Hardware name: BCM5301X
[ 1610.432469] Backtrace:
[ 1610.434943] [<c001708c>] (dump_backtrace) from [<c0017288>] (show_stack+0x18/0x1c)
[ 1610.442529]  r7:000004c3 r6:bf1d0e9c r5:60000013 r4:00000000
[ 1610.448246] [<c0017270>] (show_stack) from [<c017c210>] (dump_stack+0x84/0xa4)
[ 1610.455486] [<c017c18c>] (dump_stack) from [<c0021490>] (warn_slowpath_common+0x8c/0xb8)
[ 1610.463593]  r5:00000009 r4:00000000
[ 1610.467191] [<c0021404>] (warn_slowpath_common) from [<c0021560>] (warn_slowpath_null+0x24/0x2c)
[ 1610.475987]  r8:c65b0840 r7:00000001 r6:c6b8fb74 r5:00000000 r4:c65a0480
[ 1610.482769] [<c002153c>] (warn_slowpath_null) from [<bf1be578>] (brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac])
[ 1610.493241] [<bf1be4bc>] (brcmf_netdev_wait_pend8021x [brcmfmac]) from [<bf1ab200>] (brcmf_cfg80211_sched_scan_start+0x460/0x6c0 [brcmfmac])
[ 1610.505869]  r8:c65b0840 r7:bf1c85fc r6:c65a0480 r5:c04903c8 r4:c71c82f0
[ 1610.512639] [<bf1ab13c>] (brcmf_cfg80211_sched_scan_start [brcmfmac]) from [<bf1ad420>] (brcmf_cfg80211_del_key+0xb0/0xf0 [brcmfmac])
[ 1610.524660]  r7:c65a0480 r6:00000002 r5:c71c8254 r4:c71c8000
[ 1610.530402] [<bf1ad370>] (brcmf_cfg80211_del_key [brcmfmac]) from [<bf1608b8>] (nl80211_del_key+0xf4/0x148 [cfg80211])
[ 1610.541120]  r7:c696c000 r6:c65a0000 r5:c650fd20 r4:bf1ad370
[ 1610.546848] [<bf1607c4>] (nl80211_del_key [cfg80211]) from [<c0286f40>] (genl_rcv_msg+0x260/0x2e4)
[ 1610.555821]  r7:c650fd14 r6:bf170554 r5:bf1787d0 r4:00000000
[ 1610.561527] [<c0286ce0>] (genl_rcv_msg) from [<c0286260>] (netlink_rcv_skb+0x60/0xbc)
[ 1610.569373]  r10:c65b0840 r9:00000000 r8:c6b8fd84 r7:c6516400 r6:c0286ce0 r5:c65b0840
[ 1610.577258]  r4:c650fd00
[ 1610.579806] [<c0286200>] (netlink_rcv_skb) from [<c0286ccc>] (genl_rcv+0x28/0x3c)
[ 1610.587303]  r7:c6516400 r6:c65b0840 r5:c65b0840 r4:c04a42a0
[ 1610.593010] [<c0286ca4>] (genl_rcv) from [<c0285c48>] (netlink_unicast+0x138/0x1f4)
[ 1610.600682]  r5:00000030 r4:c799a000
[ 1610.604282] [<c0285b10>] (netlink_unicast) from [<c02860c8>] (netlink_sendmsg+0x300/0x320)
[ 1610.612561]  r9:00000008 r8:00000000 r7:00000030 r6:c6b8ff4c r5:c6516400 r4:00000000
[ 1610.620368] [<c0285dc8>] (netlink_sendmsg) from [<c0248de4>] (sock_sendmsg+0x1c/0x2c)
[ 1610.628212]  r10:00000000 r9:00000000 r8:00000000 r7:c7536a80 r6:c6b8fe64 r5:00000000
[ 1610.636098]  r4:c6b8ff4c
[ 1610.638643] [<c0248dc8>] (sock_sendmsg) from [<c0249398>] (___sys_sendmsg+0x198/0x228)
[ 1610.646582] [<c0249200>] (___sys_sendmsg) from [<c024a1ec>] (__sys_sendmsg+0x44/0x68)
[ 1610.654428]  r10:00000000 r9:c6b8e000 r8:c00098c4 r7:00000128 r6:00000000 r5:bee03790
[ 1610.662315]  r4:c7536a80
[ 1610.664861] [<c024a1a8>] (__sys_sendmsg) from [<c024a220>] (SyS_sendmsg+0x10/0x14)
[ 1610.672446]  r6:00000006 r5:00000000 r4:00000000
[ 1610.677100] [<c024a210>] (SyS_sendmsg) from [<c0009700>] (ret_fast_syscall+0x0/0x3c)
[ 1610.684897] ---[ end trace e3199c520974d444 ]---
[ 1610.689536] brcmfmac: [brcmf_netdev_wait_pend8021x] ifp:c65a0480 brcmf_ifname(ifp):wlan1-2 brcmf_get_pend_8021x_cnt(ifp):3
[ 1610.700612] brcmfmac: [brcmf_netdev_wait_pend8021x] List of pending 802.1x skbs:
[ 1610.708021] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c681f3c0 skb->dev:c65a0000 skb->dev->name:wlan1-2
[ 1610.717611] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c7116900 skb->dev:c65a0000 skb->dev->name:wlan1-2
[ 1610.727202] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c7361a80 skb->dev:c65a0000 skb->dev->name:wlan1-2
[ 1612.571349] brcmfmac: CONSOLE: 028341.979 wl0: Proxy STA 78:d6:f0:9b:ba:bc link is already gone !!??
[ 1612.580961] brcmfmac: [brcmf_msgbuf_process_txstatus -> __brcmf_txfinalize] Finally finalizing skb:c681f3c0 skb->dev:c65a0000 skb->dev->name:wlan1-2
[ 1612.594343] brcmfmac: [brcmf_msgbuf_process_txstatus -> __brcmf_txfinalize] Finally finalizing skb:c7116900 skb->dev:c65a0000 skb->dev->name:wlan1-2
[ 1612.607715] brcmfmac: [brcmf_msgbuf_process_txstatus -> __brcmf_txfinalize] Finally finalizing skb:c7361a80 skb->dev:c65a0000 skb->dev->name:wlan1-2
[ 1634.169780] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c780ec80 brcmf_ifname(ifp):wlan0
[ 1634.180374] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c695bc80 brcmf_ifname(ifp):wlan1
[ 1634.309650] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c64c1c80 brcmf_ifname(ifp):wlan0-1
[ 1634.346305] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c64d3480 brcmf_ifname(ifp):wlan1-1
[ 1634.679761] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c64c5c80 brcmf_ifname(ifp):wlan0-2
[ 1635.294903] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c65a0480 brcmf_ifname(ifp):wlan1-2

^ permalink raw reply	[flat|nested] 6+ messages in thread

* Re: AMPDU stalls with brcmfmac4366b-pcie.bin triggering WARNINGs
  2016-09-14  5:45 AMPDU stalls with brcmfmac4366b-pcie.bin triggering WARNINGs Rafał Miłecki
  2016-09-14  7:25 ` Rafał Miłecki
  2016-09-14  8:43 ` Rafał Miłecki
@ 2016-09-14 18:28 ` Arend Van Spriel
  2016-09-15 11:48   ` Rafał Miłecki
  2 siblings, 1 reply; 6+ messages in thread
From: Arend Van Spriel @ 2016-09-14 18:28 UTC (permalink / raw)
  To: Rafał Miłecki, Hante Meuleman, Arend van Spriel,
	brcm80211-dev-list
  Cc: linux-wireless

On 14-9-2016 7:45, Rafał Miłecki wrote:
> Hi,
> 
> Even with the most recent brcmfmac code ppl keep seeing WARNINGs from
> brcmf_netdev_wait_pend8021x [0].
> 
> Hante suggested using CONSOLE for debugging some firmware crash so I
> decided to see I it could also help understanding WARNINGs. I believe it
> did.
> 
> First of all, I can't reproduce these problems reliably. One evening I
> got WARNINGs one by one and I could work on my debugging patch easily.
> Yesterday when I got my patch complete, it took me 10+ hours to get a
> single WARNING.
> 
> Anyway, it seems to me that sometimes AMPDU stalls in the firmware. It
> seems firmware has some AMPDU watchdog that notices the problem and
> kicks in. It prints some debugging info and starts cleaning up process.
> 
> If brcmf_netdev_wait_pend8021x gets called shortly after that (I set
> wpa_group_rekey=30 in hostapd to get brcmf_cfg80211_add_key called more
> often) it results in a WARNING.
> 
> For better debugging I wrote brcmfmac patch that:
> 1) Keeps track of every 802.1x skb submitted to the device
> 2) During WARNING it prints skbs and marks them as timedout
> 3) It informs when timedout skb gets finally reported as sent
> 
> Enough talking, please take a look at my debugging log. Does it give you
> enough hint? Could you review/debug firmware's code responsible for
> AMPDU? FWIW Merlin users (so no brcmfmac invovled) also saw this [1].
> 
> [  913.569121] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c7369480 brcmf_ifname(ifp):wlan1
> [  913.579521] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c70cd480 brcmf_ifname(ifp):wlan0
> [  913.627346] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c71a1480 brcmf_ifname(ifp):wlan1-1
> [  913.839833] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c6464c80 brcmf_ifname(ifp):wlan0-1
> [  914.179775] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c64cac80 brcmf_ifname(ifp):wlan0-2
> [  914.191129] brcmfmac: CONSOLE: 027644.261 wl0.3: wlc_send_bar: seq 0x3 tid 0
> [  914.198474] brcmfmac: CONSOLE: 027644.266 wl0.3: wlc_send_bar: seq 0x3 tid 0
> [  914.206020] brcmfmac: CONSOLE: 027644.273 wl0.3: wlc_send_bar: seq 0x3 tid 0
> [  914.215243] brcmfmac: CONSOLE: 027644.284 wl0.3: wlc_send_bar: seq 0x3 tid 0
> [  914.224521] brcmfmac: CONSOLE: 027644.294 wl0.3: wlc_send_bar: seq 0x3 tid 0
> [  914.231878] brcmfmac: CONSOLE: 027644.298 wl0.3: wlc_send_bar: seq 0x3 tid 0
> [  914.239425] brcmfmac: CONSOLE: 027644.307 wl0.3: wlc_send_bar: seq 0x3 tid 0
> [  914.248444] brcmfmac: CONSOLE: 027644.318 wl0.3: wlc_send_bar: seq 0x3 tid 0
> [  914.257163] brcmfmac: CONSOLE: 027644.326 wl0.3: wlc_send_bar: seq 0x3 tid 0
> [  914.266616] brcmfmac: CONSOLE: 027644.336 wl0.3: wlc_send_bar: seq 0x3 tid 0
> [  914.274072] brcmfmac: CONSOLE: 027644.341 wl0.3: wlc_send_bar: seq 0x3 tid 0
> [  914.284716] brcmfmac: CONSOLE: 027644.354 wl0.3: wlc_send_bar: seq 0x3 tid 0
> [  914.291962] brcmfmac: CONSOLE: 027644.359 wl0.3: wlc_send_bar: seq 0x3 tid 0
> [  914.299172] brcmfmac: CONSOLE: 027644.364 wl0.3: wlc_send_bar: seq 0x3 tid 0
> [  914.306646] brcmfmac: CONSOLE: 027644.371 wl0.3: wlc_send_bar: seq 0x3 tid 0
> [  914.314058] brcmfmac: CONSOLE: 027644.380 wl0.3: wlc_send_bar: seq 0x3 tid 0
> [  914.323193] brcmfmac: CONSOLE: 027644.393 wl0.3: wlc_send_bar: seq 0x3 tid 0
> [  914.330640] brcmfmac: CONSOLE: 027644.400 wl0.3: wlc_send_bar: seq 0x3 tid 0
> [  914.340886] brcmfmac: CONSOLE: 027644.410 wl0.3: wlc_send_bar: seq 0x3 tid 0
> [  914.352975] brcmfmac: CONSOLE: 027644.422 wl0.3: wlc_send_bar: seq 0x3 tid 0
> [  914.365365] brcmfmac: CONSOLE: 027644.434 wl0.3: wlc_send_bar: seq 0x3 tid 0
> [  914.372790] brcmfmac: CONSOLE: 027644.440 wl0.3: wlc_send_bar: seq 0x3 tid 0
> [  914.384982] brcmfmac: CONSOLE: 027644.454 wl0.3: wlc_send_bar: seq 0x3 tid 0
> [  914.395488] brcmfmac: CONSOLE: 027644.465 wl0.3: wlc_send_bar: seq 0x3 tid 0
> [  914.402977] brcmfmac: CONSOLE: 027644.471 wl0.3: wlc_send_bar: seq 0x3 tid 0
> [  914.701404] brcmfmac: CONSOLE: 027644.771 wl0.3: wlc_send_bar: seq 0x4 tid 0
> [  914.710513] brcmfmac: CONSOLE: 027644.780 wl0.3: wlc_send_bar: seq 0x4 tid 0
> [  914.717731] brcmfmac: CONSOLE: 027644.787 wl0.3: wlc_send_bar: seq 0x4 tid 0
> [  914.728099] brcmfmac: CONSOLE: 027644.798 wl0.3: wlc_send_bar: seq 0x4 tid 0
> [  914.737616] brcmfmac: CONSOLE: 027644.807 wl0.3: wlc_send_bar: seq 0x4 tid 0
> [  914.745320] brcmfmac: CONSOLE: 027644.815 wl0.3: wlc_send_bar: seq 0x4 tid 0
> [  914.757985] brcmfmac: CONSOLE: 027644.827 wl0.3: wlc_send_bar: seq 0x4 tid 0
> [  914.765457] brcmfmac: CONSOLE: 027644.833 wl0.3: wlc_send_bar: seq 0x4 tid 0
> [  914.772729] brcmfmac: CONSOLE: 027644.841 wl0.3: wlc_send_bar: seq 0x4 tid 0
> [  914.781407] brcmfmac: CONSOLE: 027644.851 wl0.3: wlc_send_bar: seq 0x4 tid 0
> [  914.789268] brcmfmac: CONSOLE: 027644.859 wl0.3: wlc_send_bar: seq 0x4 tid 0
> [  914.796754] brcmfmac: CONSOLE: 027644.866 wl0.3: wlc_send_bar: seq 0x4 tid 0
> [  914.808174] brcmfmac: CONSOLE: 027644.878 wl0.3: wlc_send_bar: seq 0x4 tid 0
> [  914.818975] brcmfmac: CONSOLE: 027644.888 wl0.3: wlc_send_bar: seq 0x4 tid 0
> [  917.077991] brcmfmac: CONSOLE: 027647.149 ampdu_dbg: wl0.3 scb:00347c74 tid:0 
> [  917.085368] brcmfmac: CONSOLE: 027647.149 ampdu_dbg: wl0.3 dead_cnt 2 tx_in_transit 1 psm_mux 0xfff0 aqmqmap 0x0x101 aqmfifo_status 0x0x4000 fifordy 0x0 cpbusy 0x0
> [  917.100070] brcmfmac: CONSOLE: 027647.149 ampdu_dbg: ifsstat 0xaf nav_stat 0x0 txop 30788
> [  917.108303] brcmfmac: CONSOLE: 027647.149 ampdu_dbg: pktpend: 0 2 0 0 0 ap 1
> [  917.115434] brcmfmac: CONSOLE: 027647.149 ampdu_dbg: txall 5901 txbcn 0 txrts 0 rxcts 0 rsptmout 0 rxstrt 0
> [  917.125265] brcmfmac: CONSOLE: 027647.149 ampdu_dbg: cwcur0-3 f f 7 3 bslots cur/0-3 9 0 9 0 0 ifs_boff 0
> [  917.134907] brcmfmac: CONSOLE: 027647.149 ampdu_dbg: again1 ifsstat 0xaf nav_stat 0x0
> [  917.142806] brcmfmac: CONSOLE: 027647.149 ampdu_dbg: again2 ifsstat 0xaf nav_stat 0x0
> [  917.150739] brcmfmac: CONSOLE: 027647.149 wl0: wlc_ampdu_watchdog: cleaning up ini tid 0 due to no progress for 2 secs tx_in_transit 1
> [  917.162912] brcmfmac: CONSOLE: 027647.149 wl0: wlc_ampdu_tx_send_delba: tid 0 initiator 1 reason 39
> [  917.718723] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c6518c80 brcmf_ifname(ifp):wlan1-2
> [  918.678558] ------------[ cut here ]------------
> [  918.683329] WARNING: CPU: 1 PID: 1145 at compat-wireless-2016-06-20/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.c:1219 brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac]()
> [  918.699599] Modules linked in: pppoe ppp_async iptable_nat brcmfmac pppox ppp_generic nf_nat_ipv4 nf_conntrack_ipv6 nf_conntrack_ipv4 ipt_REJECT ipt_MASQUERADE cfg80211 xt_time xt_tcpudp xt_state xt_nat xt_multiport xt_mark xt_mac xt_limit xt_id xt_conntrack xt_commed
> [  918.771954] CPU: 1 PID: 1145 Comm: hostapd Not tainted 4.4.19 #0
> [  918.777971] Hardware name: BCM5301X
> [  918.781461] Backtrace: 
> [  918.783938] [<c001708c>] (dump_backtrace) from [<c0017288>] (show_stack+0x18/0x1c)
> [  918.791523]  r7:000004c3 r6:bf1d0e9c r5:60000013 r4:00000000
> [  918.797240] [<c0017270>] (show_stack) from [<c017c210>] (dump_stack+0x84/0xa4)
> [  918.804480] [<c017c18c>] (dump_stack) from [<c0021490>] (warn_slowpath_common+0x8c/0xb8)
> [  918.812587]  r5:00000009 r4:00000000
> [  918.816184] [<c0021404>] (warn_slowpath_common) from [<c0021560>] (warn_slowpath_null+0x24/0x2c)
> [  918.824981]  r8:c72f10a4 r7:00000001 r6:c64f7b3c r5:00000000 r4:c6518c80
> [  918.831764] [<c002153c>] (warn_slowpath_null) from [<bf1be578>] (brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac])
> [  918.842243] [<bf1be4bc>] (brcmf_netdev_wait_pend8021x [brcmfmac]) from [<bf1ab200>] (brcmf_cfg80211_sched_scan_start+0x460/0x6c0 [brcmfmac])
> [  918.854870]  r8:c72f10a4 r7:bf1c8613 r6:c6518c80 r5:c04903c8 r4:c72f1394
> [  918.861641] [<bf1ab13c>] (brcmf_cfg80211_sched_scan_start [brcmfmac]) from [<bf1ad740>] (brcmf_cfg80211_add_key+0x2e0/0x3dc [brcmfmac])
> [  918.873836]  r7:00000000 r6:c6518c80 r5:c72f10a4 r4:00000004
> [  918.879578] [<bf1ad460>] (brcmf_cfg80211_add_key [brcmfmac]) from [<bf160b48>] (nl80211_new_key+0xfc/0x128 [cfg80211])
> [  918.890296]  r10:00000014 r9:c7250800 r8:c64f7ca0 r7:c72de000 r6:c6518800 r5:00000000
> [  918.898181]  r4:bf1ad460
> [  918.900751] [<bf160a4c>] (nl80211_new_key [cfg80211]) from [<c0286f40>] (genl_rcv_msg+0x260/0x2e4)
> [  918.909723]  r8:c5d50300 r7:c658b614 r6:bf170540 r5:bf1787d0 r4:00000000
> [  918.916482] [<c0286ce0>] (genl_rcv_msg) from [<c0286260>] (netlink_rcv_skb+0x60/0xbc)
> [  918.924328]  r10:c5d50300 r9:00000000 r8:c64f7d84 r7:c6b0e400 r6:c0286ce0 r5:c5d50300
> [  918.932214]  r4:c658b600
> [  918.934761] [<c0286200>] (netlink_rcv_skb) from [<c0286ccc>] (genl_rcv+0x28/0x3c)
> [  918.942258]  r7:c6b0e400 r6:c5d50300 r5:c5d50300 r4:c04a42a0
> [  918.947965] [<c0286ca4>] (genl_rcv) from [<c0285c48>] (netlink_unicast+0x138/0x1f4)
> [  918.955637]  r5:00000048 r4:c7952000
> [  918.959236] [<c0285b10>] (netlink_unicast) from [<c02860c8>] (netlink_sendmsg+0x300/0x320)
> [  918.967517]  r9:00000008 r8:00000000 r7:00000048 r6:c64f7f4c r5:c6b0e400 r4:00000000
> [  918.975324] [<c0285dc8>] (netlink_sendmsg) from [<c0248de4>] (sock_sendmsg+0x1c/0x2c)
> [  918.983167]  r10:00000000 r9:00000000 r8:00000000 r7:c7544900 r6:c64f7e64 r5:00000000
> [  918.991053]  r4:c64f7f4c
> [  918.993598] [<c0248dc8>] (sock_sendmsg) from [<c0249398>] (___sys_sendmsg+0x198/0x228)
> [  919.001529] [<c0249200>] (___sys_sendmsg) from [<c024a1ec>] (__sys_sendmsg+0x44/0x68)
> [  919.009375]  r10:00000000 r9:c64f6000 r8:c00098c4 r7:00000128 r6:00000000 r5:bee617c0
> [  919.017260]  r4:c7544900
> [  919.019807] [<c024a1a8>] (__sys_sendmsg) from [<c024a220>] (SyS_sendmsg+0x10/0x14)
> [  919.027393]  r6:00003000 r5:00000000 r4:00000000
> [  919.032046] [<c024a210>] (SyS_sendmsg) from [<c0009700>] (ret_fast_syscall+0x0/0x3c)
> [  919.039829] ---[ end trace ab86393507c49518 ]---
> [  919.044467] brcmfmac: [brcmf_netdev_wait_pend8021x] ifp:c6518c80 brcmf_ifname(ifp):wlan1-2 brcmf_get_pend_8021x_cnt(ifp):2
> [  919.055542] brcmfmac: [brcmf_netdev_wait_pend8021x] List of pending 802.1x skbs:
> [  919.062956] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c7269780 skb->dev:c6518800 skb->dev->name:wlan1-2
> [  919.072547] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c72693c0 skb->dev:c6518800 skb->dev->name:wlan1-2

Hi Rafal,

Surprised to see those ampdu_dbg messages in official firmware release.
It would be great to have a timestamp for these skb when they arrive in
brcmfmac or transferred to firmware (or both).

The obvious solution would be to increase the pend8021x timeout in
brcmfmac. Probably another solution would be to exclude EAPOL frames
from A-MPDU in firmware. That still does not solve the A-MPDU stall.

Regards,
Arend

> [  919.082148] brcmfmac: [brcmf_msgbuf_process_txstatus -> __brcmf_txfinalize] Finally finalizing skb:c7269780 skb->dev:c6518800 skb->dev->name:wlan1-2
> [  919.098449] brcmfmac: [brcmf_cfg80211_del_key -> __send_key_to_dongle] ifp:c6518c80 brcmf_ifname(ifp):wlan1-2
> [  920.058595] ------------[ cut here ]------------
> [  920.063473] WARNING: CPU: 1 PID: 1145 at compat-wireless-2016-06-20/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.c:1219 brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac]()
> [  920.079937] Modules linked in: pppoe ppp_async iptable_nat brcmfmac pppox ppp_generic nf_nat_ipv4 nf_conntrack_ipv6 nf_conntrack_ipv4 ipt_REJECT ipt_MASQUERADE cfg80211 xt_time xt_tcpudp xt_state xt_nat xt_multiport xt_mark xt_mac xt_limit xt_id xt_conntrack xt_commed
> [  920.152313] CPU: 1 PID: 1145 Comm: hostapd Tainted: G        W       4.4.19 #0
> [  920.159547] Hardware name: BCM5301X
> [  920.163038] Backtrace: 
> [  920.165515] [<c001708c>] (dump_backtrace) from [<c0017288>] (show_stack+0x18/0x1c)
> [  920.173101]  r7:000004c3 r6:bf1d0e9c r5:60000013 r4:00000000
> [  920.178818] [<c0017270>] (show_stack) from [<c017c210>] (dump_stack+0x84/0xa4)
> [  920.186056] [<c017c18c>] (dump_stack) from [<c0021490>] (warn_slowpath_common+0x8c/0xb8)
> [  920.194164]  r5:00000009 r4:00000000
> [  920.197761] [<c0021404>] (warn_slowpath_common) from [<c0021560>] (warn_slowpath_null+0x24/0x2c)
> [  920.206558]  r8:c5d50300 r7:00000001 r6:c64f7b74 r5:00000000 r4:c6518c80
> [  920.213343] [<c002153c>] (warn_slowpath_null) from [<bf1be578>] (brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac])
> [  920.223820] [<bf1be4bc>] (brcmf_netdev_wait_pend8021x [brcmfmac]) from [<bf1ab200>] (brcmf_cfg80211_sched_scan_start+0x460/0x6c0 [brcmfmac])
> [  920.236447]  r8:c5d50300 r7:bf1c85fc r6:c6518c80 r5:c04903c8 r4:c72f12f0
> [  920.243218] [<bf1ab13c>] (brcmf_cfg80211_sched_scan_start [brcmfmac]) from [<bf1ad420>] (brcmf_cfg80211_del_key+0xb0/0xf0 [brcmfmac])
> [  920.255240]  r7:c6518c80 r6:00000002 r5:c72f1254 r4:c72f1000
> [  920.260981] [<bf1ad370>] (brcmf_cfg80211_del_key [brcmfmac]) from [<bf1608b8>] (nl80211_del_key+0xf4/0x148 [cfg80211])
> [  920.271699]  r7:c72de000 r6:c6518800 r5:c70c5620 r4:bf1ad370
> [  920.277429] [<bf1607c4>] (nl80211_del_key [cfg80211]) from [<c0286f40>] (genl_rcv_msg+0x260/0x2e4)
> [  920.286400]  r7:c70c5614 r6:bf170554 r5:bf1787d0 r4:00000000
> [  920.292106] [<c0286ce0>] (genl_rcv_msg) from [<c0286260>] (netlink_rcv_skb+0x60/0xbc)
> [  920.299952]  r10:c5d50300 r9:00000000 r8:c64f7d84 r7:c6b0e400 r6:c0286ce0 r5:c5d50300
> [  920.307837]  r4:c70c5600
> [  920.310384] [<c0286200>] (netlink_rcv_skb) from [<c0286ccc>] (genl_rcv+0x28/0x3c)
> [  920.317882]  r7:c6b0e400 r6:c5d50300 r5:c5d50300 r4:c04a42a0
> [  920.323588] [<c0286ca4>] (genl_rcv) from [<c0285c48>] (netlink_unicast+0x138/0x1f4)
> [  920.331261]  r5:00000030 r4:c7952000
> [  920.334859] [<c0285b10>] (netlink_unicast) from [<c02860c8>] (netlink_sendmsg+0x300/0x320)
> [  920.343141]  r9:00000008 r8:00000000 r7:00000030 r6:c64f7f4c r5:c6b0e400 r4:00000000
> [  920.350947] [<c0285dc8>] (netlink_sendmsg) from [<c0248de4>] (sock_sendmsg+0x1c/0x2c)
> [  920.358790]  r10:00000000 r9:00000000 r8:00000000 r7:c7544900 r6:c64f7e64 r5:00000000
> [  920.366677]  r4:c64f7f4c
> [  920.369222] [<c0248dc8>] (sock_sendmsg) from [<c0249398>] (___sys_sendmsg+0x198/0x228)
> [  920.377162] [<c0249200>] (___sys_sendmsg) from [<c024a1ec>] (__sys_sendmsg+0x44/0x68)
> [  920.385007]  r10:00000000 r9:c64f6000 r8:c00098c4 r7:00000128 r6:00000000 r5:bee61790
> [  920.392893]  r4:c7544900
> [  920.395439] [<c024a1a8>] (__sys_sendmsg) from [<c024a220>] (SyS_sendmsg+0x10/0x14)
> [  920.403024]  r6:00003000 r5:00000000 r4:00000000
> [  920.407678] [<c024a210>] (SyS_sendmsg) from [<c0009700>] (ret_fast_syscall+0x0/0x3c)
> [  920.415462] ---[ end trace ab86393507c49519 ]---
> [  920.420108] brcmfmac: [brcmf_netdev_wait_pend8021x] ifp:c6518c80 brcmf_ifname(ifp):wlan1-2 brcmf_get_pend_8021x_cnt(ifp):1
> [  920.431188] brcmfmac: [brcmf_netdev_wait_pend8021x] List of pending 802.1x skbs:
> [  920.438608] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c72693c0 skb->dev:c6518800 skb->dev->name:wlan1-2
> [  921.488695] brcmfmac: CONSOLE: 027651.562 wl0: Proxy STA 78:d6:f0:9b:ba:bc link is already gone !!??
> [  921.498112] brcmfmac: [brcmf_msgbuf_process_txstatus -> __brcmf_txfinalize] Finally finalizing skb:c72693c0 skb->dev:c6518800 skb->dev->name:wlan1-2
> [  943.599077] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c7369480 brcmf_ifname(ifp):wlan1
> [  943.609854] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c70cd480 brcmf_ifname(ifp):wlan0
> [  943.642073] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c71a1480 brcmf_ifname(ifp):wlan1-1
> [  943.859842] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c6464c80 brcmf_ifname(ifp):wlan0-1
> [  944.189138] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c6518c80 brcmf_ifname(ifp):wlan1-2
> [  944.209834] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c64cac80 brcmf_ifname(ifp):wlan0-2
> 
> [0] https://forum.openwrt.org/viewtopic.php?pid=335019#p335019
> [1] http://www.snbforums.com/threads/alpha-builds-for-rt-ac88u-and-rt-ac3100.28024/#post-215754
> ---
>  .../broadcom/brcm80211/brcmfmac/cfg80211.c         |  4 +-
>  .../wireless/broadcom/brcm80211/brcmfmac/core.c    | 66 +++++++++++++++++++++-
>  .../wireless/broadcom/brcm80211/brcmfmac/core.h    | 15 ++++-
>  .../broadcom/brcm80211/brcmfmac/flowring.c         |  2 +
>  .../broadcom/brcm80211/brcmfmac/fwsignal.c         | 12 +++-
>  .../wireless/broadcom/brcm80211/brcmfmac/msgbuf.c  |  3 +
>  .../net/wireless/broadcom/brcm80211/brcmfmac/usb.c |  3 +
>  .../wireless/broadcom/brcm80211/brcmutil/utils.c   |  2 +-
>  .../broadcom/brcm80211/include/brcmu_utils.h       |  2 +-
>  9 files changed, 101 insertions(+), 8 deletions(-)
> 
> diff --git a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/cfg80211.c b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/cfg80211.c
> index 201a980..c7ccea5 100644
> --- a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/cfg80211.c
> +++ b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/cfg80211.c
> @@ -464,11 +464,12 @@ static void convert_key_from_CPU(struct brcmf_wsec_key *key,
>  }
>  
>  static int
> -send_key_to_dongle(struct brcmf_if *ifp, struct brcmf_wsec_key *key)
> +__send_key_to_dongle(const char *c0, struct brcmf_if *ifp, struct brcmf_wsec_key *key)
>  {
>  	int err;
>  	struct brcmf_wsec_key_le key_le;
>  
> +	pr_info("[%s -> %s] ifp:%p brcmf_ifname(ifp):%s\n", c0, __func__, ifp, brcmf_ifname(ifp));
>  	convert_key_from_CPU(key, &key_le);
>  
>  	brcmf_netdev_wait_pend8021x(ifp);
> @@ -480,6 +481,7 @@ send_key_to_dongle(struct brcmf_if *ifp, struct brcmf_wsec_key *key)
>  		brcmf_err("wsec_key error (%d)\n", err);
>  	return err;
>  }
> +#define send_key_to_dongle(ifp, key)	__send_key_to_dongle(__func__, ifp, key)
>  
>  static s32
>  brcmf_configure_arp_nd_offload(struct brcmf_if *ifp, bool enable)
> diff --git a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.c b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.c
> index 8d16f02..cc02e3d 100644
> --- a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.c
> +++ b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.c
> @@ -38,6 +38,30 @@
>  #include "pcie.h"
>  #include "common.h"
>  
> +/* Free the driver packet. Free the tag if present */
> +void __brcmu_pkt_buf_free_skb(const char *c0, struct brcmf_if *ifp, struct sk_buff *skb)
> +{
> +	if (!skb)
> +		return;
> +
> +	if (ifp) {
> +		struct skb_list *e;
> +
> +		mutex_lock(&ifp->pend_8021x_mutex);
> +		list_for_each_entry(e, &ifp->pend_8021x_skbs, list) {
> +			if (e->skb == skb) {
> +				pr_info("[%s -> %s] [ifp:%p] ***BUG*** skb:%p skb->dev:%p skb->dev->name:%s\n", c0, __func__, ifp, e->skb, e->skb->dev, e->skb->dev ? e->skb->dev->name : "---");
> +			}
> +		}
> +		mutex_unlock(&ifp->pend_8021x_mutex);
> +	} else if (strcmp(c0, "brcmf_msgbuf_query_dcmd")) {
> +		pr_info("[%s -> %s] [ifp:%p] Freeing skb:%p skb->dev:%p skb->dev->name:%s\n", c0, __func__, ifp, skb, skb->dev, skb->dev ? skb->dev->name : "---");
> +	}
> +
> +	WARN_ON(skb->next);
> +	dev_kfree_skb_any(skb);
> +}
> +
>  #define MAX_WAIT_FOR_8021X_TX			msecs_to_jiffies(950)
>  
>  #define BRCMF_BSSIDX_INVALID			-1
> @@ -247,8 +271,17 @@ static netdev_tx_t brcmf_netdev_start_xmit(struct sk_buff *skb,
>  		goto done;
>  	}
>  
> -	if (eh->h_proto == htons(ETH_P_PAE))
> +	if (eh->h_proto == htons(ETH_P_PAE)) {
> +		struct skb_list *e;
> +
> +		e = kzalloc(sizeof(*e), GFP_KERNEL);
> +		e->skb = skb;
> +
>  		atomic_inc(&ifp->pend_8021x_cnt);
> +		mutex_lock(&ifp->pend_8021x_mutex);
> +		list_add_tail(&e->list, &ifp->pend_8021x_skbs);
> +		mutex_unlock(&ifp->pend_8021x_mutex);
> +	}
>  
>  	ret = brcmf_fws_process_skb(ifp, skb);
>  
> @@ -333,7 +366,7 @@ static int brcmf_rx_hdrpull(struct brcmf_pub *drvr, struct sk_buff *skb,
>  	if (ret || !(*ifp) || !(*ifp)->ndev) {
>  		if (ret != -ENODATA && *ifp)
>  			(*ifp)->stats.rx_errors++;
> -		brcmu_pkt_buf_free_skb(skb);
> +		__brcmu_pkt_buf_free_skb(__func__, *ifp, skb);
>  		return -ENODATA;
>  	}
>  
> @@ -378,7 +411,7 @@ void brcmf_rx_event(struct device *dev, struct sk_buff *skb)
>  	brcmu_pkt_buf_free_skb(skb);
>  }
>  
> -void brcmf_txfinalize(struct brcmf_if *ifp, struct sk_buff *txp, bool success)
> +void __brcmf_txfinalize(const char *c0, struct brcmf_if *ifp, struct sk_buff *txp, bool success)
>  {
>  	struct ethhdr *eh;
>  	u16 type;
> @@ -387,7 +420,19 @@ void brcmf_txfinalize(struct brcmf_if *ifp, struct sk_buff *txp, bool success)
>  	type = ntohs(eh->h_proto);
>  
>  	if (type == ETH_P_PAE) {
> +		struct skb_list *e, *tmp;
> +
>  		atomic_dec(&ifp->pend_8021x_cnt);
> +		mutex_lock(&ifp->pend_8021x_mutex);
> +		list_for_each_entry_safe(e, tmp, &ifp->pend_8021x_skbs, list) {
> +			if (e->skb == txp) {
> +				if (e->timedout)
> +					pr_info("[%s -> %s] Finally finalizing skb:%p skb->dev:%p skb->dev->name:%s\n", c0, __func__, e->skb, e->skb->dev, e->skb->dev ? e->skb->dev->name : "---");
> +				list_del(&e->list);
> +				kfree(e);
> +			}
> +		}
> +		mutex_unlock(&ifp->pend_8021x_mutex);
>  		if (waitqueue_active(&ifp->pend_8021x_wait))
>  			wake_up(&ifp->pend_8021x_wait);
>  	}
> @@ -476,6 +521,8 @@ static int brcmf_netdev_open(struct net_device *ndev)
>  	}
>  
>  	atomic_set(&ifp->pend_8021x_cnt, 0);
> +	INIT_LIST_HEAD(&ifp->pend_8021x_skbs);
> +	mutex_init(&ifp->pend_8021x_mutex);
>  
>  	/* Get current TOE mode from dongle */
>  	if (brcmf_fil_iovar_int_get(ifp, "toe_ol", &toe_ol) >= 0
> @@ -1170,6 +1217,19 @@ int brcmf_netdev_wait_pend8021x(struct brcmf_if *ifp)
>  				 MAX_WAIT_FOR_8021X_TX);
>  
>  	WARN_ON(!err);
> +	if (!err)
> +		pr_info("[%s] ifp:%p brcmf_ifname(ifp):%s brcmf_get_pend_8021x_cnt(ifp):%d\n", __func__, ifp, brcmf_ifname(ifp), brcmf_get_pend_8021x_cnt(ifp));
> +	if (!list_empty(&ifp->pend_8021x_skbs)) {
> +		struct skb_list *e;
> +
> +		mutex_lock(&ifp->pend_8021x_mutex);
> +		pr_info("[%s] List of pending 802.1x skbs:\n", __func__);
> +		list_for_each_entry(e, &ifp->pend_8021x_skbs, list) {
> +			e->timedout = true;
> +			pr_info("[%s] skb:%p skb->dev:%p skb->dev->name:%s\n", __func__, e->skb, e->skb->dev, e->skb->dev ? e->skb->dev->name : "---");
> +		}
> +		mutex_unlock(&ifp->pend_8021x_mutex);
> +	}
>  
>  	return !err;
>  }
> diff --git a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.h b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.h
> index 8fa34ca..1509d4f 100644
> --- a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.h
> +++ b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.h
> @@ -50,6 +50,9 @@
>  
>  #define NDOL_MAX_ENTRIES	8
>  
> +void __brcmu_pkt_buf_free_skb(const char *c0, struct brcmf_if *ifp, struct sk_buff *skb);
> +#define brcmu_pkt_buf_free_skb(skb)	__brcmu_pkt_buf_free_skb(__func__, ifp, skb)
> +
>  /**
>   * struct brcmf_ampdu_rx_reorder - AMPDU receive reorder info
>   *
> @@ -169,6 +172,12 @@ enum brcmf_netif_stop_reason {
>  	BRCMF_NETIF_STOP_REASON_DISCONNECTED = BIT(2)
>  };
>  
> +struct skb_list {
> +	struct sk_buff *skb;
> +	bool timedout;
> +	struct list_head list;
> +};
> +
>  /**
>   * struct brcmf_if - interface control information.
>   *
> @@ -203,6 +212,9 @@ struct brcmf_if {
>  	u8 netif_stop;
>  	spinlock_t netif_stop_lock;
>  	atomic_t pend_8021x_cnt;
> +	struct list_head pend_8021x_skbs;
> +	struct mutex pend_8021x_mutex;
> +	bool pend_8021x_ready;
>  	wait_queue_head_t pend_8021x_wait;
>  	struct in6_addr ipv6_addr_tbl[NDOL_MAX_ENTRIES];
>  	u8 ipv6addr_idx;
> @@ -219,7 +231,8 @@ struct brcmf_if *brcmf_add_if(struct brcmf_pub *drvr, s32 bsscfgidx, s32 ifidx,
>  void brcmf_remove_interface(struct brcmf_if *ifp, bool rtnl_locked);
>  void brcmf_txflowblock_if(struct brcmf_if *ifp,
>  			  enum brcmf_netif_stop_reason reason, bool state);
> -void brcmf_txfinalize(struct brcmf_if *ifp, struct sk_buff *txp, bool success);
> +void __brcmf_txfinalize(const char *c0, struct brcmf_if *ifp, struct sk_buff *txp, bool success);
> +#define brcmf_txfinalize(ifp, txp, success)	__brcmf_txfinalize(__func__, ifp, txp, success)
>  void brcmf_netif_rx(struct brcmf_if *ifp, struct sk_buff *skb);
>  void brcmf_net_setcarrier(struct brcmf_if *ifp, bool on);
>  void brcmf_c_set_joinpref_default(struct brcmf_if *ifp);
> diff --git a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/flowring.c b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/flowring.c
> index 7e269f9..87c8de0 100644
> --- a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/flowring.c
> +++ b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/flowring.c
> @@ -249,6 +249,8 @@ void brcmf_flowring_delete(struct brcmf_flowring *flow, u16 flowid)
>  
>  	skb = skb_dequeue(&ring->skblist);
>  	while (skb) {
> +		struct brcmf_if *ifp = NULL;
> +
>  		brcmu_pkt_buf_free_skb(skb);
>  		skb = skb_dequeue(&ring->skblist);
>  	}
> diff --git a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/fwsignal.c b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/fwsignal.c
> index 9f9024a..41dd3fb 100644
> --- a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/fwsignal.c
> +++ b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/fwsignal.c
> @@ -590,6 +590,8 @@ static void brcmf_fws_psq_flush(struct brcmf_fws_info *fws, struct pktq *q,
>  	for (prec = 0; prec < q->num_prec; prec++) {
>  		skb = brcmu_pktq_pdeq_match(q, prec, matchfn, &ifidx);
>  		while (skb) {
> +			struct brcmf_if *ifp = NULL;
> +
>  			brcmu_pkt_buf_free_skb(skb);
>  			skb = brcmu_pktq_pdeq_match(q, prec, matchfn, &ifidx);
>  		}
> @@ -697,6 +699,8 @@ static void brcmf_fws_hanger_cleanup(struct brcmf_fws_info *fws,
>  		    s == BRCMF_FWS_HANGER_ITEM_STATE_INUSE_SUPPRESSED) {
>  			skb = h->items[i].pkt;
>  			if (fn == NULL || fn(skb, &ifidx)) {
> +				struct brcmf_if *ifp = NULL;
> +
>  				/* suppress packets freed from psq */
>  				if (s == BRCMF_FWS_HANGER_ITEM_STATE_INUSE)
>  					brcmu_pkt_buf_free_skb(skb);
> @@ -845,6 +849,8 @@ static void brcmf_fws_bus_txq_cleanup(struct brcmf_fws_info *fws,
>  	for (prec = 0; prec < txq->num_prec; prec++) {
>  		skb = brcmu_pktq_pdeq_match(txq, prec, fn, &ifidx);
>  		while (skb) {
> +			struct brcmf_if *ifp = NULL;
> +
>  			hslot = brcmf_skb_htod_tag_get_field(skb, HSLOT);
>  			hi = &fws->hanger.items[hslot];
>  			WARN_ON(skb != hi->pkt);
> @@ -971,8 +977,11 @@ static bool brcmf_fws_tim_update(struct brcmf_fws_info *fws,
>  		brcmf_fws_unlock(fws);
>  		err = brcmf_proto_txdata(fws->drvr, ifidx, data_offset, skb);
>  		brcmf_fws_lock(fws);
> -		if (err)
> +		if (err) {
> +			struct brcmf_if *ifp = NULL;
> +
>  			brcmu_pkt_buf_free_skb(skb);
> +		}
>  		return true;
>  	}
>  	return false;
> @@ -2454,6 +2463,7 @@ bool brcmf_fws_fc_active(struct brcmf_fws_info *fws)
>  
>  void brcmf_fws_bustxfail(struct brcmf_fws_info *fws, struct sk_buff *skb)
>  {
> +	struct brcmf_if *ifp = NULL;
>  	u32 hslot;
>  
>  	if (brcmf_skbcb(skb)->state == BRCMF_FWS_SKBSTATE_TIM) {
> diff --git a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/msgbuf.c b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/msgbuf.c
> index 2b9a2bc..e47f5a3 100644
> --- a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/msgbuf.c
> +++ b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/msgbuf.c
> @@ -392,6 +392,8 @@ brcmf_msgbuf_release_array(struct device *dev,
>  	count = 0;
>  	do {
>  		if (array[count].allocated.counter) {
> +			struct brcmf_if *ifp = NULL;
> +
>  			pktid = &array[count];
>  			dma_unmap_single(dev, pktid->physaddr,
>  					 pktid->skb->len - pktid->data_offset,
> @@ -483,6 +485,7 @@ static int brcmf_msgbuf_query_dcmd(struct brcmf_pub *drvr, int ifidx,
>  {
>  	struct brcmf_msgbuf *msgbuf = (struct brcmf_msgbuf *)drvr->proto->pd;
>  	struct sk_buff *skb = NULL;
> +	struct brcmf_if *ifp = NULL;
>  	int timeout;
>  	int err;
>  
> diff --git a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/usb.c b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/usb.c
> index 2f978a3..edbe353 100644
> --- a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/usb.c
> +++ b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/usb.c
> @@ -498,6 +498,7 @@ static void brcmf_usb_rx_complete(struct urb *urb)
>  {
>  	struct brcmf_usbreq  *req = (struct brcmf_usbreq *)urb->context;
>  	struct brcmf_usbdev_info *devinfo = req->devinfo;
> +	struct brcmf_if *ifp = NULL;
>  	struct sk_buff *skb;
>  
>  	brcmf_dbg(USB, "Enter, urb->status=%d\n", urb->status);
> @@ -548,6 +549,8 @@ static void brcmf_usb_rx_refill(struct brcmf_usbdev_info *devinfo,
>  
>  	ret = usb_submit_urb(req->urb, GFP_ATOMIC);
>  	if (ret) {
> +		struct brcmf_if *ifp = NULL;
> +
>  		brcmf_usb_del_fromq(devinfo, req);
>  		brcmu_pkt_buf_free_skb(req->skb);
>  		req->skb = NULL;
> diff --git a/drivers/net/wireless/broadcom/brcm80211/brcmutil/utils.c b/drivers/net/wireless/broadcom/brcm80211/brcmutil/utils.c
> index 0543607..bf525b7 100644
> --- a/drivers/net/wireless/broadcom/brcm80211/brcmutil/utils.c
> +++ b/drivers/net/wireless/broadcom/brcm80211/brcmutil/utils.c
> @@ -49,7 +49,7 @@ void brcmu_pkt_buf_free_skb(struct sk_buff *skb)
>  	WARN_ON(skb->next);
>  	dev_kfree_skb_any(skb);
>  }
> -EXPORT_SYMBOL(brcmu_pkt_buf_free_skb);
> +//EXPORT_SYMBOL(brcmu_pkt_buf_free_skb);
>  
>  /*
>   * osl multiple-precedence packet queue
> diff --git a/drivers/net/wireless/broadcom/brcm80211/include/brcmu_utils.h b/drivers/net/wireless/broadcom/brcm80211/include/brcmu_utils.h
> index 4196952..7bd705d 100644
> --- a/drivers/net/wireless/broadcom/brcm80211/include/brcmu_utils.h
> +++ b/drivers/net/wireless/broadcom/brcm80211/include/brcmu_utils.h
> @@ -126,7 +126,7 @@ struct sk_buff *brcmu_pktq_pdeq_match(struct pktq *pq, int prec,
>  
>  /* packet primitives */
>  struct sk_buff *brcmu_pkt_buf_get_skb(uint len);
> -void brcmu_pkt_buf_free_skb(struct sk_buff *skb);
> +//void brcmu_pkt_buf_free_skb(struct sk_buff *skb);
>  
>  /* Empty the queue at particular precedence level */
>  /* callback function fn(pkt, arg) returns true if pkt belongs to if */
> 

^ permalink raw reply	[flat|nested] 6+ messages in thread

* Re: AMPDU stalls with brcmfmac4366b-pcie.bin triggering WARNINGs
  2016-09-14 18:28 ` Arend Van Spriel
@ 2016-09-15 11:48   ` Rafał Miłecki
  2016-09-15 14:27     ` Rafał Miłecki
  0 siblings, 1 reply; 6+ messages in thread
From: Rafał Miłecki @ 2016-09-15 11:48 UTC (permalink / raw)
  To: Hante Meuleman, Arend van Spriel, brcm80211-dev-list
  Cc: linux-wireless, Rafał Miłecki

On 09/14/2016 08:28 PM, Arend Van Spriel wrote:
> On 14-9-2016 7:45, Rafał Miłecki wrote:
>> Even with the most recent brcmfmac code ppl keep seeing WARNINGs from
>> brcmf_netdev_wait_pend8021x [0].
>>
>> Hante suggested using CONSOLE for debugging some firmware crash so I
>> decided to see I it could also help understanding WARNINGs. I believe it
>> did.
>>
>> First of all, I can't reproduce these problems reliably. One evening I
>> got WARNINGs one by one and I could work on my debugging patch easily.
>> Yesterday when I got my patch complete, it took me 10+ hours to get a
>> single WARNING.
>>
>> Anyway, it seems to me that sometimes AMPDU stalls in the firmware. It
>> seems firmware has some AMPDU watchdog that notices the problem and
>> kicks in. It prints some debugging info and starts cleaning up process.
>>
>> If brcmf_netdev_wait_pend8021x gets called shortly after that (I set
>> wpa_group_rekey=30 in hostapd to get brcmf_cfg80211_add_key called more
>> often) it results in a WARNING.
>>
>> For better debugging I wrote brcmfmac patch that:
>> 1) Keeps track of every 802.1x skb submitted to the device
>> 2) During WARNING it prints skbs and marks them as timedout
>> 3) It informs when timedout skb gets finally reported as sent
>>
>> Enough talking, please take a look at my debugging log. Does it give you
>> enough hint? Could you review/debug firmware's code responsible for
>> AMPDU? FWIW Merlin users (so no brcmfmac invovled) also saw this [1].
>>
>> [  913.569121] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c7369480 brcmf_ifname(ifp):wlan1
>> [  913.579521] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c70cd480 brcmf_ifname(ifp):wlan0
>> [  913.627346] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c71a1480 brcmf_ifname(ifp):wlan1-1
>> [  913.839833] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c6464c80 brcmf_ifname(ifp):wlan0-1
>> [  914.179775] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c64cac80 brcmf_ifname(ifp):wlan0-2
>> [  914.191129] brcmfmac: CONSOLE: 027644.261 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.198474] brcmfmac: CONSOLE: 027644.266 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.206020] brcmfmac: CONSOLE: 027644.273 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.215243] brcmfmac: CONSOLE: 027644.284 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.224521] brcmfmac: CONSOLE: 027644.294 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.231878] brcmfmac: CONSOLE: 027644.298 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.239425] brcmfmac: CONSOLE: 027644.307 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.248444] brcmfmac: CONSOLE: 027644.318 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.257163] brcmfmac: CONSOLE: 027644.326 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.266616] brcmfmac: CONSOLE: 027644.336 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.274072] brcmfmac: CONSOLE: 027644.341 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.284716] brcmfmac: CONSOLE: 027644.354 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.291962] brcmfmac: CONSOLE: 027644.359 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.299172] brcmfmac: CONSOLE: 027644.364 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.306646] brcmfmac: CONSOLE: 027644.371 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.314058] brcmfmac: CONSOLE: 027644.380 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.323193] brcmfmac: CONSOLE: 027644.393 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.330640] brcmfmac: CONSOLE: 027644.400 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.340886] brcmfmac: CONSOLE: 027644.410 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.352975] brcmfmac: CONSOLE: 027644.422 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.365365] brcmfmac: CONSOLE: 027644.434 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.372790] brcmfmac: CONSOLE: 027644.440 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.384982] brcmfmac: CONSOLE: 027644.454 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.395488] brcmfmac: CONSOLE: 027644.465 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.402977] brcmfmac: CONSOLE: 027644.471 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.701404] brcmfmac: CONSOLE: 027644.771 wl0.3: wlc_send_bar: seq 0x4 tid 0
>> [  914.710513] brcmfmac: CONSOLE: 027644.780 wl0.3: wlc_send_bar: seq 0x4 tid 0
>> [  914.717731] brcmfmac: CONSOLE: 027644.787 wl0.3: wlc_send_bar: seq 0x4 tid 0
>> [  914.728099] brcmfmac: CONSOLE: 027644.798 wl0.3: wlc_send_bar: seq 0x4 tid 0
>> [  914.737616] brcmfmac: CONSOLE: 027644.807 wl0.3: wlc_send_bar: seq 0x4 tid 0
>> [  914.745320] brcmfmac: CONSOLE: 027644.815 wl0.3: wlc_send_bar: seq 0x4 tid 0
>> [  914.757985] brcmfmac: CONSOLE: 027644.827 wl0.3: wlc_send_bar: seq 0x4 tid 0
>> [  914.765457] brcmfmac: CONSOLE: 027644.833 wl0.3: wlc_send_bar: seq 0x4 tid 0
>> [  914.772729] brcmfmac: CONSOLE: 027644.841 wl0.3: wlc_send_bar: seq 0x4 tid 0
>> [  914.781407] brcmfmac: CONSOLE: 027644.851 wl0.3: wlc_send_bar: seq 0x4 tid 0
>> [  914.789268] brcmfmac: CONSOLE: 027644.859 wl0.3: wlc_send_bar: seq 0x4 tid 0
>> [  914.796754] brcmfmac: CONSOLE: 027644.866 wl0.3: wlc_send_bar: seq 0x4 tid 0
>> [  914.808174] brcmfmac: CONSOLE: 027644.878 wl0.3: wlc_send_bar: seq 0x4 tid 0
>> [  914.818975] brcmfmac: CONSOLE: 027644.888 wl0.3: wlc_send_bar: seq 0x4 tid 0
>> [  917.077991] brcmfmac: CONSOLE: 027647.149 ampdu_dbg: wl0.3 scb:00347c74 tid:0 
>> [  917.085368] brcmfmac: CONSOLE: 027647.149 ampdu_dbg: wl0.3 dead_cnt 2 tx_in_transit 1 psm_mux 0xfff0 aqmqmap 0x0x101 aqmfifo_status 0x0x4000 fifordy 0x0 cpbusy 0x0
>> [  917.100070] brcmfmac: CONSOLE: 027647.149 ampdu_dbg: ifsstat 0xaf nav_stat 0x0 txop 30788
>> [  917.108303] brcmfmac: CONSOLE: 027647.149 ampdu_dbg: pktpend: 0 2 0 0 0 ap 1
>> [  917.115434] brcmfmac: CONSOLE: 027647.149 ampdu_dbg: txall 5901 txbcn 0 txrts 0 rxcts 0 rsptmout 0 rxstrt 0
>> [  917.125265] brcmfmac: CONSOLE: 027647.149 ampdu_dbg: cwcur0-3 f f 7 3 bslots cur/0-3 9 0 9 0 0 ifs_boff 0
>> [  917.134907] brcmfmac: CONSOLE: 027647.149 ampdu_dbg: again1 ifsstat 0xaf nav_stat 0x0
>> [  917.142806] brcmfmac: CONSOLE: 027647.149 ampdu_dbg: again2 ifsstat 0xaf nav_stat 0x0
>> [  917.150739] brcmfmac: CONSOLE: 027647.149 wl0: wlc_ampdu_watchdog: cleaning up ini tid 0 due to no progress for 2 secs tx_in_transit 1
>> [  917.162912] brcmfmac: CONSOLE: 027647.149 wl0: wlc_ampdu_tx_send_delba: tid 0 initiator 1 reason 39
>> [  917.718723] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c6518c80 brcmf_ifname(ifp):wlan1-2
>> [  918.678558] ------------[ cut here ]------------
>> [  918.683329] WARNING: CPU: 1 PID: 1145 at compat-wireless-2016-06-20/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.c:1219 brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac]()
>> [  918.699599] Modules linked in: pppoe ppp_async iptable_nat brcmfmac pppox ppp_generic nf_nat_ipv4 nf_conntrack_ipv6 nf_conntrack_ipv4 ipt_REJECT ipt_MASQUERADE cfg80211 xt_time xt_tcpudp xt_state xt_nat xt_multiport xt_mark xt_mac xt_limit xt_id xt_conntrack xt_commed
>> [  918.771954] CPU: 1 PID: 1145 Comm: hostapd Not tainted 4.4.19 #0
>> [  918.777971] Hardware name: BCM5301X
>> [  918.781461] Backtrace: 
>> [  918.783938] [<c001708c>] (dump_backtrace) from [<c0017288>] (show_stack+0x18/0x1c)
>> [  918.791523]  r7:000004c3 r6:bf1d0e9c r5:60000013 r4:00000000
>> [  918.797240] [<c0017270>] (show_stack) from [<c017c210>] (dump_stack+0x84/0xa4)
>> [  918.804480] [<c017c18c>] (dump_stack) from [<c0021490>] (warn_slowpath_common+0x8c/0xb8)
>> [  918.812587]  r5:00000009 r4:00000000
>> [  918.816184] [<c0021404>] (warn_slowpath_common) from [<c0021560>] (warn_slowpath_null+0x24/0x2c)
>> [  918.824981]  r8:c72f10a4 r7:00000001 r6:c64f7b3c r5:00000000 r4:c6518c80
>> [  918.831764] [<c002153c>] (warn_slowpath_null) from [<bf1be578>] (brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac])
>> [  918.842243] [<bf1be4bc>] (brcmf_netdev_wait_pend8021x [brcmfmac]) from [<bf1ab200>] (brcmf_cfg80211_sched_scan_start+0x460/0x6c0 [brcmfmac])
>> [  918.854870]  r8:c72f10a4 r7:bf1c8613 r6:c6518c80 r5:c04903c8 r4:c72f1394
>> [  918.861641] [<bf1ab13c>] (brcmf_cfg80211_sched_scan_start [brcmfmac]) from [<bf1ad740>] (brcmf_cfg80211_add_key+0x2e0/0x3dc [brcmfmac])
>> [  918.873836]  r7:00000000 r6:c6518c80 r5:c72f10a4 r4:00000004
>> [  918.879578] [<bf1ad460>] (brcmf_cfg80211_add_key [brcmfmac]) from [<bf160b48>] (nl80211_new_key+0xfc/0x128 [cfg80211])
>> [  918.890296]  r10:00000014 r9:c7250800 r8:c64f7ca0 r7:c72de000 r6:c6518800 r5:00000000
>> [  918.898181]  r4:bf1ad460
>> [  918.900751] [<bf160a4c>] (nl80211_new_key [cfg80211]) from [<c0286f40>] (genl_rcv_msg+0x260/0x2e4)
>> [  918.909723]  r8:c5d50300 r7:c658b614 r6:bf170540 r5:bf1787d0 r4:00000000
>> [  918.916482] [<c0286ce0>] (genl_rcv_msg) from [<c0286260>] (netlink_rcv_skb+0x60/0xbc)
>> [  918.924328]  r10:c5d50300 r9:00000000 r8:c64f7d84 r7:c6b0e400 r6:c0286ce0 r5:c5d50300
>> [  918.932214]  r4:c658b600
>> [  918.934761] [<c0286200>] (netlink_rcv_skb) from [<c0286ccc>] (genl_rcv+0x28/0x3c)
>> [  918.942258]  r7:c6b0e400 r6:c5d50300 r5:c5d50300 r4:c04a42a0
>> [  918.947965] [<c0286ca4>] (genl_rcv) from [<c0285c48>] (netlink_unicast+0x138/0x1f4)
>> [  918.955637]  r5:00000048 r4:c7952000
>> [  918.959236] [<c0285b10>] (netlink_unicast) from [<c02860c8>] (netlink_sendmsg+0x300/0x320)
>> [  918.967517]  r9:00000008 r8:00000000 r7:00000048 r6:c64f7f4c r5:c6b0e400 r4:00000000
>> [  918.975324] [<c0285dc8>] (netlink_sendmsg) from [<c0248de4>] (sock_sendmsg+0x1c/0x2c)
>> [  918.983167]  r10:00000000 r9:00000000 r8:00000000 r7:c7544900 r6:c64f7e64 r5:00000000
>> [  918.991053]  r4:c64f7f4c
>> [  918.993598] [<c0248dc8>] (sock_sendmsg) from [<c0249398>] (___sys_sendmsg+0x198/0x228)
>> [  919.001529] [<c0249200>] (___sys_sendmsg) from [<c024a1ec>] (__sys_sendmsg+0x44/0x68)
>> [  919.009375]  r10:00000000 r9:c64f6000 r8:c00098c4 r7:00000128 r6:00000000 r5:bee617c0
>> [  919.017260]  r4:c7544900
>> [  919.019807] [<c024a1a8>] (__sys_sendmsg) from [<c024a220>] (SyS_sendmsg+0x10/0x14)
>> [  919.027393]  r6:00003000 r5:00000000 r4:00000000
>> [  919.032046] [<c024a210>] (SyS_sendmsg) from [<c0009700>] (ret_fast_syscall+0x0/0x3c)
>> [  919.039829] ---[ end trace ab86393507c49518 ]---
>> [  919.044467] brcmfmac: [brcmf_netdev_wait_pend8021x] ifp:c6518c80 brcmf_ifname(ifp):wlan1-2 brcmf_get_pend_8021x_cnt(ifp):2
>> [  919.055542] brcmfmac: [brcmf_netdev_wait_pend8021x] List of pending 802.1x skbs:
>> [  919.062956] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c7269780 skb->dev:c6518800 skb->dev->name:wlan1-2
>> [  919.072547] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c72693c0 skb->dev:c6518800 skb->dev->name:wlan1-2
> 
> Hi Rafal,
> 
> Surprised to see those ampdu_dbg messages in official firmware release.

Well, I'm somehow glad they make it into the official firmware. It at least
allowed understanding what causes these delays (A-MPDU issue). They indeed don't
seem to be present in 43602a1 firmware so I can only guess it suffers from the
same problem.


> It would be great to have a timestamp for these skb when they arrive in
> brcmfmac or transferred to firmware (or both).

You ask and you have it :) I saved kernel's local time and printed it the same
way print_time function does it. Let me paste the most important lines:
[ 1876.496770] brcmfmac: CONSOLE: 028605.731 wl0: wlc_ampdu_watchdog: cleaning up ini tid 0 due to no progress for 2 secs tx_in_transit 1
[ 1877.958898] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c71c5480 brcmf_ifname(ifp):wlan1-1
[ 1878.923359] WARNING: CPU: 1 PID: 1140 at compat-wireless-2016-06-20/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.c:1256 brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac]()
[ 1880.659840] brcmfmac: [brcmf_netdev_wait_pend8021x] ifp:c71c5480 brcmf_ifname(ifp):wlan1-1 brcmf_get_pend_8021x_cnt(ifp):3
[ 1880.670922] brcmfmac: [brcmf_netdev_wait_pend8021x] List of pending 802.1x skbs:
[ 1880.678333] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c6b18d80 skb->dev:c71c5000 skb->dev->name:wlan1-1
[ 1880.687935] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c6b18900 skb->dev:c71c5000 skb->dev->name:wlan1-1
[ 1880.697530] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c721fc00 skb->dev:c71c5000 skb->dev->name:wlan1-1
[ 1881.439614] brcmfmac: [brcmf_msgbuf_process_txstatus -> __brcmf_txfinalize] Finally finalizing skb:c6b18d80 skb->dev:c71c5000 skb->dev->name:wlan1-1 (start_time:[ 1874.928858]; commit_time:[ 1874.928994])
[ 1881.457852] brcmfmac: [brcmf_msgbuf_process_txstatus -> __brcmf_txfinalize] Finally finalizing skb:c6b18900 skb->dev:c71c5000 skb->dev->name:wlan1-1 (start_time:[ 1875.938806]; commit_time:[ 1875.938858])
[ 1881.476074] brcmfmac: [brcmf_msgbuf_process_txstatus -> __brcmf_txfinalize] Finally finalizing skb:c721fc00 skb->dev:c71c5000 skb->dev->name:wlan1-1 (start_time:[ 1876.948805]; commit_time:[ 1876.948855])

For the first skb brcmf_netdev_start_xmit was called at 1874.928858.
It was commited to firmware with brcmf_msgbuf_txflow at 1874.928994.
Then there was A-MPDU hang in firmware.
Finally brcmf_msgbuf_process_txstatus was called and it called
brcmf_txfinalize and this one logged everything at 1881.439614.

You'll find full log at the end.


> The obvious solution would be to increase the pend8021x timeout in
> brcmfmac. Probably another solution would be to exclude EAPOL frames
> from A-MPDU in firmware. That still does not solve the A-MPDU stall.

For me the most obvious solution would be to fix A-MPDU problem in the firmware.
Of course that would require releasing updated firmware and ppl switching to it.
It still sounds like a desired long term solution.

I don't think we want few second stalls in communication with AP. Moreover Hante
seemed to be worried clients can get totally disconnected which would make
things even worse:
> This waiting uses a timeout (950ms) and in this case the timeout expired. It
> will most likely result in a situation where client and AP wont have the same
> keys anymore and eventually the client will disconnect en reconnect.

If xmit of skb was started at 1874.928858 and we got TX status at 1881.439614
that's 6-7 seconds of delay. Quite a lot so I really would prefer a *fix*
instead of workaround hiding the problem.


[ 1874.409157] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c6970c80 brcmf_ifname(ifp):wlan1
[ 1874.499840] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c79d5480 brcmf_ifname(ifp):wlan0
[ 1874.579199] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c64b0480 brcmf_ifname(ifp):wlan1-2
[ 1874.599201] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c79d0c80 brcmf_ifname(ifp):wlan0-1
[ 1874.719154] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c6aac480 brcmf_ifname(ifp):wlan0-2
[ 1876.423494] brcmfmac: CONSOLE: 028605.731 ampdu_dbg: wl0.2 scb:00345ba8 tid:0 
[ 1876.430873] brcmfmac: CONSOLE: 028605.731 ampdu_dbg: wl0.2 dead_cnt 2 tx_in_transit 1 psm_mux 0xfff0 aqmqmap 0x0x101 aqmfifo_status 0x0x4000 fifordy 0x0 cpbusy 0x0
[ 1876.445571] brcmfmac: CONSOLE: 028605.731 ampdu_dbg: ifsstat 0x1d80 nav_stat 0x0 txop 31893
[ 1876.453990] brcmfmac: CONSOLE: 028605.731 ampdu_dbg: pktpend: 0 0 0 0 0 ap 1
[ 1876.461122] brcmfmac: CONSOLE: 028605.731 ampdu_dbg: txall 5836 txbcn 0 txrts 0 rxcts 0 rsptmout 0 rxstrt 0
[ 1876.470948] brcmfmac: CONSOLE: 028605.731 ampdu_dbg: cwcur0-3 f f 7 3 bslots cur/0-3 6 0 0 0 0 ifs_boff 0
[ 1876.480586] brcmfmac: CONSOLE: 028605.731 ampdu_dbg: again1 ifsstat 0x1ea0 nav_stat 0x0
[ 1876.488657] brcmfmac: CONSOLE: 028605.731 ampdu_dbg: again2 ifsstat 0x1ea0 nav_stat 0x0
[ 1876.496770] brcmfmac: CONSOLE: 028605.731 wl0: wlc_ampdu_watchdog: cleaning up ini tid 0 due to no progress for 2 secs tx_in_transit 1
[ 1876.508943] brcmfmac: CONSOLE: 028605.731 wl0: wlc_ampdu_tx_send_delba: tid 0 initiator 1 reason 39
[ 1877.958898] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c71c5480 brcmf_ifname(ifp):wlan1-1
[ 1878.918681] ------------[ cut here ]------------
[ 1878.923359] WARNING: CPU: 1 PID: 1140 at compat-wireless-2016-06-20/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.c:1256 brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac]()
[ 1878.939505] Modules linked in: pppoe ppp_async iptable_nat brcmfmac pppox ppp_generic nf_nat_ipv4 nf_conntrack_ipv6 nf_conntrack_ipv4 ipt_REJECT ipt_MASQUERADE cfg80211 xt_time xt_tcpudp xt_state xt_nat xt_multiport xt_mark xt_mac xt_limit xt_id xt_conntrack xt_commed
[ 1879.011922] CPU: 1 PID: 1140 Comm: hostapd Tainted: G        W       4.4.19 #0
[ 1879.019157] Hardware name: BCM5301X
[ 1879.022647] Backtrace: 
[ 1879.025124] [<c001708c>] (dump_backtrace) from [<c0017288>] (show_stack+0x18/0x1c)
[ 1879.032710]  r7:000004e8 r6:bf1d12cf r5:60000013 r4:00000000
[ 1879.038428] [<c0017270>] (show_stack) from [<c017c210>] (dump_stack+0x84/0xa4)
[ 1879.045667] [<c017c18c>] (dump_stack) from [<c0021490>] (warn_slowpath_common+0x8c/0xb8)
[ 1879.053773]  r5:00000009 r4:00000000
[ 1879.057371] [<c0021404>] (warn_slowpath_common) from [<c0021560>] (warn_slowpath_null+0x24/0x2c)
[ 1879.066176]  r8:c79050a4 r7:00000001 r6:c6471b3c r5:00000000 r4:c71c5480
[ 1879.072960] [<c002153c>] (warn_slowpath_null) from [<bf1be784>] (brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac])
[ 1879.083444] [<bf1be6c8>] (brcmf_netdev_wait_pend8021x [brcmfmac]) from [<bf1ab200>] (brcmf_cfg80211_sched_scan_start+0x460/0x6c0 [brcmfmac])
[ 1879.096075]  r8:c79050a4 r7:bf1c8927 r6:c71c5480 r5:c04903c8 r4:c7905394
[ 1879.102848] [<bf1ab13c>] (brcmf_cfg80211_sched_scan_start [brcmfmac]) from [<bf1ad740>] (brcmf_cfg80211_add_key+0x2e0/0x3dc [brcmfmac])
[ 1879.115050]  r7:00000000 r6:c71c5480 r5:c79050a4 r4:00000004
[ 1879.120793] [<bf1ad460>] (brcmf_cfg80211_add_key [brcmfmac]) from [<bf160b48>] (nl80211_new_key+0xfc/0x128 [cfg80211])
[ 1879.131509]  r10:00000014 r9:c79da800 r8:c6471ca0 r7:c7306000 r6:c71c5000 r5:00000000
[ 1879.139394]  r4:bf1ad460
[ 1879.141976] [<bf160a4c>] (nl80211_new_key [cfg80211]) from [<c0286f40>] (genl_rcv_msg+0x260/0x2e4)
[ 1879.150953]  r8:c721f780 r7:c695e414 r6:bf170540 r5:bf1787d0 r4:00000000
[ 1879.157716] [<c0286ce0>] (genl_rcv_msg) from [<c0286260>] (netlink_rcv_skb+0x60/0xbc)
[ 1879.165558]  r10:c721f780 r9:00000000 r8:c6471d84 r7:c72e0800 r6:c0286ce0 r5:c721f780
[ 1879.173444]  r4:c695e400
[ 1879.175991] [<c0286200>] (netlink_rcv_skb) from [<c0286ccc>] (genl_rcv+0x28/0x3c)
[ 1879.183489]  r7:c72e0800 r6:c721f780 r5:c721f780 r4:c04a42a0
[ 1879.189194] [<c0286ca4>] (genl_rcv) from [<c0285c48>] (netlink_unicast+0x138/0x1f4)
[ 1879.196866]  r5:00000048 r4:c7952000
[ 1879.200467] [<c0285b10>] (netlink_unicast) from [<c02860c8>] (netlink_sendmsg+0x300/0x320)
[ 1879.208747]  r9:00000008 r8:00000000 r7:00000048 r6:c6471f4c r5:c72e0800 r4:00000000
[ 1879.216554] [<c0285dc8>] (netlink_sendmsg) from [<c0248de4>] (sock_sendmsg+0x1c/0x2c)
[ 1879.224396]  r10:00000000 r9:00000000 r8:00000000 r7:c7507c80 r6:c6471e64 r5:00000000
[ 1879.232283]  r4:c6471f4c
[ 1879.234829] [<c0248dc8>] (sock_sendmsg) from [<c0249398>] (___sys_sendmsg+0x198/0x228)
[ 1879.242767] [<c0249200>] (___sys_sendmsg) from [<c024a1ec>] (__sys_sendmsg+0x44/0x68)
[ 1879.250613]  r10:00000000 r9:c6470000 r8:c00098c4 r7:00000128 r6:00000000 r5:beb207c0
[ 1879.258499]  r4:c7507c80
[ 1879.261046] [<c024a1a8>] (__sys_sendmsg) from [<c024a220>] (SyS_sendmsg+0x10/0x14)
[ 1879.268630]  r6:b6f6b1c8 r5:00000000 r4:00000000
[ 1879.273285] [<c024a210>] (SyS_sendmsg) from [<c0009700>] (ret_fast_syscall+0x0/0x3c)
[ 1879.281100] ---[ end trace 86e59c15931392ff ]---
[ 1879.285743] brcmfmac: [brcmf_netdev_wait_pend8021x] ifp:c71c5480 brcmf_ifname(ifp):wlan1-1 brcmf_get_pend_8021x_cnt(ifp):3
[ 1879.296836] brcmfmac: [brcmf_netdev_wait_pend8021x] List of pending 802.1x skbs:
[ 1879.304264] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c6b18d80 skb->dev:c71c5000 skb->dev->name:wlan1-1
[ 1879.313856] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c6b18900 skb->dev:c71c5000 skb->dev->name:wlan1-1
[ 1879.323447] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c721fc00 skb->dev:c71c5000 skb->dev->name:wlan1-1
[ 1879.336774] brcmfmac: [brcmf_cfg80211_del_key -> __send_key_to_dongle] ifp:c71c5480 brcmf_ifname(ifp):wlan1-1
[ 1880.298704] ------------[ cut here ]------------
[ 1880.303383] WARNING: CPU: 1 PID: 1140 at compat-wireless-2016-06-20/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.c:1256 brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac]()
[ 1880.319629] Modules linked in: pppoe ppp_async iptable_nat brcmfmac pppox ppp_generic nf_nat_ipv4 nf_conntrack_ipv6 nf_conntrack_ipv4 ipt_REJECT ipt_MASQUERADE cfg80211 xt_time xt_tcpudp xt_state xt_nat xt_multiport xt_mark xt_mac xt_limit xt_id xt_conntrack xt_commed
[ 1880.391985] CPU: 1 PID: 1140 Comm: hostapd Tainted: G        W       4.4.19 #0
[ 1880.399220] Hardware name: BCM5301X
[ 1880.402711] Backtrace: 
[ 1880.405186] [<c001708c>] (dump_backtrace) from [<c0017288>] (show_stack+0x18/0x1c)
[ 1880.412774]  r7:000004e8 r6:bf1d12cf r5:60000013 r4:00000000
[ 1880.418490] [<c0017270>] (show_stack) from [<c017c210>] (dump_stack+0x84/0xa4)
[ 1880.425729] [<c017c18c>] (dump_stack) from [<c0021490>] (warn_slowpath_common+0x8c/0xb8)
[ 1880.433835]  r5:00000009 r4:00000000
[ 1880.437434] [<c0021404>] (warn_slowpath_common) from [<c0021560>] (warn_slowpath_null+0x24/0x2c)
[ 1880.446238]  r8:c646be40 r7:00000001 r6:c6471b74 r5:00000000 r4:c71c5480
[ 1880.453029] [<c002153c>] (warn_slowpath_null) from [<bf1be784>] (brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac])
[ 1880.463514] [<bf1be6c8>] (brcmf_netdev_wait_pend8021x [brcmfmac]) from [<bf1ab200>] (brcmf_cfg80211_sched_scan_start+0x460/0x6c0 [brcmfmac])
[ 1880.476145]  r8:c646be40 r7:bf1c8910 r6:c71c5480 r5:c04903c8 r4:c79052f0
[ 1880.482918] [<bf1ab13c>] (brcmf_cfg80211_sched_scan_start [brcmfmac]) from [<bf1ad420>] (brcmf_cfg80211_del_key+0xb0/0xf0 [brcmfmac])
[ 1880.494938]  r7:c71c5480 r6:00000002 r5:c7905254 r4:c7905000
[ 1880.500682] [<bf1ad370>] (brcmf_cfg80211_del_key [brcmfmac]) from [<bf1608b8>] (nl80211_del_key+0xf4/0x148 [cfg80211])
[ 1880.511396]  r7:c7306000 r6:c71c5000 r5:c659b420 r4:bf1ad370
[ 1880.517138] [<bf1607c4>] (nl80211_del_key [cfg80211]) from [<c0286f40>] (genl_rcv_msg+0x260/0x2e4)
[ 1880.526115]  r7:c659b414 r6:bf170554 r5:bf1787d0 r4:00000000
[ 1880.531824] [<c0286ce0>] (genl_rcv_msg) from [<c0286260>] (netlink_rcv_skb+0x60/0xbc)
[ 1880.539667]  r10:c646be40 r9:00000000 r8:c6471d84 r7:c72e0800 r6:c0286ce0 r5:c646be40
[ 1880.547553]  r4:c659b400
[ 1880.550100] [<c0286200>] (netlink_rcv_skb) from [<c0286ccc>] (genl_rcv+0x28/0x3c)
[ 1880.557597]  r7:c72e0800 r6:c646be40 r5:c646be40 r4:c04a42a0
[ 1880.563304] [<c0286ca4>] (genl_rcv) from [<c0285c48>] (netlink_unicast+0x138/0x1f4)
[ 1880.570975]  r5:00000030 r4:c7952000
[ 1880.574575] [<c0285b10>] (netlink_unicast) from [<c02860c8>] (netlink_sendmsg+0x300/0x320)
[ 1880.582856]  r9:00000008 r8:00000000 r7:00000030 r6:c6471f4c r5:c72e0800 r4:00000000
[ 1880.590663] [<c0285dc8>] (netlink_sendmsg) from [<c0248de4>] (sock_sendmsg+0x1c/0x2c)
[ 1880.598506]  r10:00000000 r9:00000000 r8:00000000 r7:c7507c80 r6:c6471e64 r5:00000000
[ 1880.606392]  r4:c6471f4c
[ 1880.608938] [<c0248dc8>] (sock_sendmsg) from [<c0249398>] (___sys_sendmsg+0x198/0x228)
[ 1880.616876] [<c0249200>] (___sys_sendmsg) from [<c024a1ec>] (__sys_sendmsg+0x44/0x68)
[ 1880.624722]  r10:00000000 r9:c6470000 r8:c00098c4 r7:00000128 r6:00000000 r5:beb20790
[ 1880.632608]  r4:c7507c80
[ 1880.635155] [<c024a1a8>] (__sys_sendmsg) from [<c024a220>] (SyS_sendmsg+0x10/0x14)
[ 1880.642741]  r6:b6f6b1c8 r5:00000000 r4:00000000
[ 1880.647394] [<c024a210>] (SyS_sendmsg) from [<c0009700>] (ret_fast_syscall+0x0/0x3c)
[ 1880.655195] ---[ end trace 86e59c1593139300 ]---
[ 1880.659840] brcmfmac: [brcmf_netdev_wait_pend8021x] ifp:c71c5480 brcmf_ifname(ifp):wlan1-1 brcmf_get_pend_8021x_cnt(ifp):3
[ 1880.670922] brcmfmac: [brcmf_netdev_wait_pend8021x] List of pending 802.1x skbs:
[ 1880.678333] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c6b18d80 skb->dev:c71c5000 skb->dev->name:wlan1-1
[ 1880.687935] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c6b18900 skb->dev:c71c5000 skb->dev->name:wlan1-1
[ 1880.697530] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c721fc00 skb->dev:c71c5000 skb->dev->name:wlan1-1
[ 1881.439614] brcmfmac: [brcmf_msgbuf_process_txstatus -> __brcmf_txfinalize] Finally finalizing skb:c6b18d80 skb->dev:c71c5000 skb->dev->name:wlan1-1 (start_time:[ 1874.928858]; commit_time:[ 1874.928994])
[ 1881.457852] brcmfmac: [brcmf_msgbuf_process_txstatus -> __brcmf_txfinalize] Finally finalizing skb:c6b18900 skb->dev:c71c5000 skb->dev->name:wlan1-1 (start_time:[ 1875.938806]; commit_time:[ 1875.938858])
[ 1881.476074] brcmfmac: [brcmf_msgbuf_process_txstatus -> __brcmf_txfinalize] Finally finalizing skb:c721fc00 skb->dev:c71c5000 skb->dev->name:wlan1-1 (start_time:[ 1876.948805]; commit_time:[ 1876.948855])
[ 1881.494440] brcmfmac: CONSOLE: 028610.749 wl0: Proxy STA 78:d6:f0:9b:ba:bc link is already gone !!??
[ 1888.235520] brcmfmac: CONSOLE: 028617.545 wl0.2: wlc_send_bar: seq 0x1 tid 0
[ 1888.331718] brcmfmac: CONSOLE: 028617.642 wl0.2: wlc_send_bar: seq 0x2 tid 0
[ 1888.339244] brcmfmac: CONSOLE: 028617.649 wl0.2: wlc_send_bar: seq 0x2 tid 0
[ 1888.346526] brcmfmac: CONSOLE: 028617.653 wl0.2: wlc_send_bar: seq 0x2 tid 0
[ 1889.340149] brcmfmac: CONSOLE: 028618.650 wl0.2: wlc_send_bar: seq 0x3 tid 0
[ 1889.347986] brcmfmac: CONSOLE: 028618.658 wl0.2: wlc_send_bar: seq 0x3 tid 0
[ 1889.356389] brcmfmac: CONSOLE: 028618.666 wl0.2: wlc_send_bar: seq 0x3 tid 0
[ 1889.365376] brcmfmac: CONSOLE: 028618.675 wl0.2: wlc_send_bar: seq 0x3 tid 0
[ 1889.820256] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c71c5480 brcmf_ifname(ifp):wlan1-1
[ 1891.234796] brcmfmac: CONSOLE: 028620.545 wl0.2: wlc_send_bar: seq 0x5 tid 0
[ 1891.450654] brcmfmac: CONSOLE: 028620.761 wl0.2: wlc_send_bar: seq 0x1 tid 6
[ 1896.459074] brcmfmac: CONSOLE: 028625.769 wl0.2: wlc_send_bar: seq 0xb tid 0
[ 1896.466714] brcmfmac: CONSOLE: 028625.777 wl0.2: wlc_send_bar: seq 0xb tid 0
[ 1899.466112] brcmfmac: CONSOLE: 028628.776 wl0.2: wlc_send_bar: seq 0x11 tid 0
[ 1899.477359] brcmfmac: CONSOLE: 028628.787 wl0.2: wlc_send_bar: seq 0x11 tid 0
[ 1899.485109] brcmfmac: CONSOLE: 028628.795 wl0.2: wlc_send_bar: seq 0x11 tid 0
[ 1899.493678] brcmfmac: CONSOLE: 028628.804 wl0.2: wlc_send_bar: seq 0x11 tid 0
[ 1899.502530] brcmfmac: CONSOLE: 028628.812 wl0.2: wlc_send_bar: seq 0x11 tid 0
[ 1899.512932] brcmfmac: CONSOLE: 028628.823 wl0.2: wlc_send_bar: seq 0x11 tid 0
[ 1899.521532] brcmfmac: CONSOLE: 028628.832 wl0.2: wlc_send_bar: seq 0x11 tid 0
[ 1899.533614] brcmfmac: CONSOLE: 028628.843 wl0.2: wlc_send_bar: seq 0x11 tid 0
[ 1899.542998] brcmfmac: CONSOLE: 028628.853 wl0.2: wlc_send_bar: seq 0x11 tid 0
[ 1899.550675] brcmfmac: CONSOLE: 028628.857 wl0.2: wlc_send_bar: seq 0x11 tid 0
[ 1899.558172] brcmfmac: CONSOLE: 028628.865 wl0.2: wlc_send_bar: seq 0x11 tid 0
[ 1899.567218] brcmfmac: CONSOLE: 028628.877 wl0.2: wlc_send_bar: seq 0x11 tid 0
[ 1900.541469] brcmfmac: CONSOLE: 028629.852 wl0.2: wlc_send_bar: seq 0x12 tid 0
[ 1900.562295] brcmfmac: CONSOLE: 028629.872 wl0.2: wlc_send_bar: seq 0x13 tid 0
[ 1901.357401] brcmfmac: CONSOLE: 028630.667 wl0: Proxy STA 78:d6:f0:9b:ba:bc link is already gone !!??
[ 1901.367534] brcmfmac: [brcmf_cfg80211_del_key -> __send_key_to_dongle] ifp:c71c5480 brcmf_ifname(ifp):wlan1-1
[ 1902.823503] brcmfmac: CONSOLE: 028632.131 wl0.3: wlc_send_bar: seq 0x3 tid 0
[ 1904.429210] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c6970c80 brcmf_ifname(ifp):wlan1
[ 1904.519856] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c79d5480 brcmf_ifname(ifp):wlan0
[ 1904.599225] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c64b0480 brcmf_ifname(ifp):wlan1-2
[ 1904.619978] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c79d0c80 brcmf_ifname(ifp):wlan0-1
[ 1904.654979] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c71c5480 brcmf_ifname(ifp):wlan1-1
[ 1904.739199] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c6aac480 brcmf_ifname(ifp):wlan0-2
---
 .../broadcom/brcm80211/brcmfmac/cfg80211.c         |  4 +-
 .../wireless/broadcom/brcm80211/brcmfmac/core.c    | 94 +++++++++++++++++++++-
 .../wireless/broadcom/brcm80211/brcmfmac/core.h    | 17 +++-
 .../broadcom/brcm80211/brcmfmac/flowring.c         |  2 +
 .../broadcom/brcm80211/brcmfmac/fwsignal.c         | 30 ++++++-
 .../wireless/broadcom/brcm80211/brcmfmac/msgbuf.c  | 21 +++++
 .../net/wireless/broadcom/brcm80211/brcmfmac/usb.c |  3 +
 .../wireless/broadcom/brcm80211/brcmutil/utils.c   |  2 +-
 .../broadcom/brcm80211/include/brcmu_utils.h       |  2 +-
 9 files changed, 167 insertions(+), 8 deletions(-)

diff --git a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/cfg80211.c b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/cfg80211.c
index 201a980..c7ccea5 100644
--- a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/cfg80211.c
+++ b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/cfg80211.c
@@ -464,11 +464,12 @@ static void convert_key_from_CPU(struct brcmf_wsec_key *key,
 }
 
 static int
-send_key_to_dongle(struct brcmf_if *ifp, struct brcmf_wsec_key *key)
+__send_key_to_dongle(const char *c0, struct brcmf_if *ifp, struct brcmf_wsec_key *key)
 {
 	int err;
 	struct brcmf_wsec_key_le key_le;
 
+	pr_info("[%s -> %s] ifp:%p brcmf_ifname(ifp):%s\n", c0, __func__, ifp, brcmf_ifname(ifp));
 	convert_key_from_CPU(key, &key_le);
 
 	brcmf_netdev_wait_pend8021x(ifp);
@@ -480,6 +481,7 @@ send_key_to_dongle(struct brcmf_if *ifp, struct brcmf_wsec_key *key)
 		brcmf_err("wsec_key error (%d)\n", err);
 	return err;
 }
+#define send_key_to_dongle(ifp, key)	__send_key_to_dongle(__func__, ifp, key)
 
 static s32
 brcmf_configure_arp_nd_offload(struct brcmf_if *ifp, bool enable)
diff --git a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.c b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.c
index 8d16f02..67f2623 100644
--- a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.c
+++ b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.c
@@ -38,6 +38,46 @@
 #include "pcie.h"
 #include "common.h"
 
+#include <linux/sched.h>
+
+static size_t print_time(u64 ts, char *buf)
+{
+	unsigned long rem_nsec;
+
+	rem_nsec = do_div(ts, 1000000000);
+
+	if (!buf)
+		return snprintf(NULL, 0, "[%5lu.000000]", (unsigned long)ts);
+
+	return sprintf(buf, "[%5lu.%06lu]",
+		       (unsigned long)ts, rem_nsec / 1000);
+}
+
+/* Free the driver packet. Free the tag if present */
+void __brcmu_pkt_buf_free_skb(const char *c0, struct brcmf_if *ifp, struct sk_buff *skb)
+{
+	if (!skb)
+		return;
+
+	if (ifp) {
+		struct pend_skb *e;
+
+		mutex_lock(&ifp->pend_8021x_mutex);
+		list_for_each_entry(e, &ifp->pend_8021x_skbs, list) {
+			if (e->skb == skb) {
+				pr_info("[%s -> %s] [ifp:%p] ***BUG*** skb:%p skb->dev:%p skb->dev->name:%s\n", c0, __func__, ifp, e->skb, e->skb->dev, e->skb->dev ? e->skb->dev->name : "---");
+				break;
+			}
+		}
+		mutex_unlock(&ifp->pend_8021x_mutex);
+	} else if (strcmp(c0, "brcmf_msgbuf_query_dcmd")) {
+		pr_info("[%s -> %s] [ifp:%p] Freeing skb:%p skb->dev:%p skb->dev->name:%s\n", c0, __func__, ifp, skb, skb->dev, skb->dev ? skb->dev->name : "---");
+	}
+
+	WARN_ON(skb->next);
+	dev_kfree_skb_any(skb);
+}
+
 #define MAX_WAIT_FOR_8021X_TX			msecs_to_jiffies(950)
 
 #define BRCMF_BSSIDX_INVALID			-1
@@ -247,8 +287,18 @@ static netdev_tx_t brcmf_netdev_start_xmit(struct sk_buff *skb,
 		goto done;
 	}
 
-	if (eh->h_proto == htons(ETH_P_PAE))
+	if (eh->h_proto == htons(ETH_P_PAE)) {
+		struct pend_skb *e;
+
+		e = kzalloc(sizeof(*e), GFP_KERNEL);
+		e->skb = skb;
+		e->start_time = local_clock();
+
 		atomic_inc(&ifp->pend_8021x_cnt);
+		mutex_lock(&ifp->pend_8021x_mutex);
+		list_add_tail(&e->list, &ifp->pend_8021x_skbs);
+		mutex_unlock(&ifp->pend_8021x_mutex);
+	}
 
 	ret = brcmf_fws_process_skb(ifp, skb);
 
@@ -333,7 +383,7 @@ static int brcmf_rx_hdrpull(struct brcmf_pub *drvr, struct sk_buff *skb,
 	if (ret || !(*ifp) || !(*ifp)->ndev) {
 		if (ret != -ENODATA && *ifp)
 			(*ifp)->stats.rx_errors++;
-		brcmu_pkt_buf_free_skb(skb);
+		__brcmu_pkt_buf_free_skb(__func__, *ifp, skb);
 		return -ENODATA;
 	}
 
@@ -378,7 +428,7 @@ void brcmf_rx_event(struct device *dev, struct sk_buff *skb)
 	brcmu_pkt_buf_free_skb(skb);
 }
 
-void brcmf_txfinalize(struct brcmf_if *ifp, struct sk_buff *txp, bool success)
+void __brcmf_txfinalize(const char *c0, struct brcmf_if *ifp, struct sk_buff *txp, bool success)
 {
 	struct ethhdr *eh;
 	u16 type;
@@ -387,7 +437,30 @@ void brcmf_txfinalize(struct brcmf_if *ifp, struct sk_buff *txp, bool success)
 	type = ntohs(eh->h_proto);
 
 	if (type == ETH_P_PAE) {
+		struct pend_skb *e, *tmp;
+
 		atomic_dec(&ifp->pend_8021x_cnt);
+		mutex_lock(&ifp->pend_8021x_mutex);
+		list_for_each_entry_safe(e, tmp, &ifp->pend_8021x_skbs, list) {
+			if (e->skb == txp) {
+				if (e->timedout) {
+					char start[32], commit[32];
+
+					print_time(e->start_time, start);
+					print_time(e->commit_time, commit);
+
+					pr_info("[%s -> %s] Finally finalizing skb:%p skb->dev:%p skb->dev->name:%s (start_time:%s; commit_time:%s)\n",
+						c0, __func__,
+						e->skb, e->skb->dev, e->skb->dev ? e->skb->dev->name : "---",
+						start, commit);
+				}
+
+				list_del(&e->list);
+				kfree(e);
+				break;
+			}
+		}
+		mutex_unlock(&ifp->pend_8021x_mutex);
 		if (waitqueue_active(&ifp->pend_8021x_wait))
 			wake_up(&ifp->pend_8021x_wait);
 	}
@@ -476,6 +549,8 @@ static int brcmf_netdev_open(struct net_device *ndev)
 	}
 
 	atomic_set(&ifp->pend_8021x_cnt, 0);
+	INIT_LIST_HEAD(&ifp->pend_8021x_skbs);
+	mutex_init(&ifp->pend_8021x_mutex);
 
 	/* Get current TOE mode from dongle */
 	if (brcmf_fil_iovar_int_get(ifp, "toe_ol", &toe_ol) >= 0
@@ -1170,6 +1245,19 @@ int brcmf_netdev_wait_pend8021x(struct brcmf_if *ifp)
 				 MAX_WAIT_FOR_8021X_TX);
 
 	WARN_ON(!err);
+	if (!err)
+		pr_info("[%s] ifp:%p brcmf_ifname(ifp):%s brcmf_get_pend_8021x_cnt(ifp):%d\n", __func__, ifp, brcmf_ifname(ifp), brcmf_get_pend_8021x_cnt(ifp));
+	if (!list_empty(&ifp->pend_8021x_skbs)) {
+		struct pend_skb *e;
+
+		mutex_lock(&ifp->pend_8021x_mutex);
+		pr_info("[%s] List of pending 802.1x skbs:\n", __func__);
+		list_for_each_entry(e, &ifp->pend_8021x_skbs, list) {
+			e->timedout = true;
+			pr_info("[%s] skb:%p skb->dev:%p skb->dev->name:%s\n", __func__, e->skb, e->skb->dev, e->skb->dev ? e->skb->dev->name : "---");
+		}
+		mutex_unlock(&ifp->pend_8021x_mutex);
+	}
 
 	return !err;
 }
diff --git a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.h b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.h
index 8fa34ca..0f66e8f 100644
--- a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.h
+++ b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.h
@@ -50,6 +50,9 @@
 
 #define NDOL_MAX_ENTRIES	8
 
+void __brcmu_pkt_buf_free_skb(const char *c0, struct brcmf_if *ifp, struct sk_buff *skb);
+#define brcmu_pkt_buf_free_skb(skb)	__brcmu_pkt_buf_free_skb(__func__, ifp, skb)
+
 /**
  * struct brcmf_ampdu_rx_reorder - AMPDU receive reorder info
  *
@@ -169,6 +172,14 @@ enum brcmf_netif_stop_reason {
 	BRCMF_NETIF_STOP_REASON_DISCONNECTED = BIT(2)
 };
 
+struct pend_skb {
+	struct sk_buff *skb;
+	u64 start_time;
+	u64 commit_time;
+	bool timedout;
+	struct list_head list;
+};
+
 /**
  * struct brcmf_if - interface control information.
  *
@@ -203,6 +214,9 @@ struct brcmf_if {
 	u8 netif_stop;
 	spinlock_t netif_stop_lock;
 	atomic_t pend_8021x_cnt;
+	struct list_head pend_8021x_skbs;
+	struct mutex pend_8021x_mutex;
+	bool pend_8021x_ready;
 	wait_queue_head_t pend_8021x_wait;
 	struct in6_addr ipv6_addr_tbl[NDOL_MAX_ENTRIES];
 	u8 ipv6addr_idx;
@@ -219,7 +233,8 @@ struct brcmf_if *brcmf_add_if(struct brcmf_pub *drvr, s32 bsscfgidx, s32 ifidx,
 void brcmf_remove_interface(struct brcmf_if *ifp, bool rtnl_locked);
 void brcmf_txflowblock_if(struct brcmf_if *ifp,
 			  enum brcmf_netif_stop_reason reason, bool state);
-void brcmf_txfinalize(struct brcmf_if *ifp, struct sk_buff *txp, bool success);
+void __brcmf_txfinalize(const char *c0, struct brcmf_if *ifp, struct sk_buff *txp, bool success);
+#define brcmf_txfinalize(ifp, txp, success)	__brcmf_txfinalize(__func__, ifp, txp, success)
 void brcmf_netif_rx(struct brcmf_if *ifp, struct sk_buff *skb);
 void brcmf_net_setcarrier(struct brcmf_if *ifp, bool on);
 void brcmf_c_set_joinpref_default(struct brcmf_if *ifp);
diff --git a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/flowring.c b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/flowring.c
index 7e269f9..87c8de0 100644
--- a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/flowring.c
+++ b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/flowring.c
@@ -249,6 +249,8 @@ void brcmf_flowring_delete(struct brcmf_flowring *flow, u16 flowid)
 
 	skb = skb_dequeue(&ring->skblist);
 	while (skb) {
+		struct brcmf_if *ifp = NULL;
+
 		brcmu_pkt_buf_free_skb(skb);
 		skb = skb_dequeue(&ring->skblist);
 	}
diff --git a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/fwsignal.c b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/fwsignal.c
index 9f9024a..7a17afd 100644
--- a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/fwsignal.c
+++ b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/fwsignal.c
@@ -38,6 +38,8 @@
 #include "proto.h"
 #include "common.h"
 
+#include <linux/sched.h>
+
 /**
  * DOC: Firmware Signalling
  *
@@ -590,6 +592,8 @@ static void brcmf_fws_psq_flush(struct brcmf_fws_info *fws, struct pktq *q,
 	for (prec = 0; prec < q->num_prec; prec++) {
 		skb = brcmu_pktq_pdeq_match(q, prec, matchfn, &ifidx);
 		while (skb) {
+			struct brcmf_if *ifp = NULL;
+
 			brcmu_pkt_buf_free_skb(skb);
 			skb = brcmu_pktq_pdeq_match(q, prec, matchfn, &ifidx);
 		}
@@ -697,6 +701,8 @@ static void brcmf_fws_hanger_cleanup(struct brcmf_fws_info *fws,
 		    s == BRCMF_FWS_HANGER_ITEM_STATE_INUSE_SUPPRESSED) {
 			skb = h->items[i].pkt;
 			if (fn == NULL || fn(skb, &ifidx)) {
+				struct brcmf_if *ifp = NULL;
+
 				/* suppress packets freed from psq */
 				if (s == BRCMF_FWS_HANGER_ITEM_STATE_INUSE)
 					brcmu_pkt_buf_free_skb(skb);
@@ -845,6 +851,8 @@ static void brcmf_fws_bus_txq_cleanup(struct brcmf_fws_info *fws,
 	for (prec = 0; prec < txq->num_prec; prec++) {
 		skb = brcmu_pktq_pdeq_match(txq, prec, fn, &ifidx);
 		while (skb) {
+			struct brcmf_if *ifp = NULL;
+
 			hslot = brcmf_skb_htod_tag_get_field(skb, HSLOT);
 			hi = &fws->hanger.items[hslot];
 			WARN_ON(skb != hi->pkt);
@@ -971,8 +979,11 @@ static bool brcmf_fws_tim_update(struct brcmf_fws_info *fws,
 		brcmf_fws_unlock(fws);
 		err = brcmf_proto_txdata(fws->drvr, ifidx, data_offset, skb);
 		brcmf_fws_lock(fws);
-		if (err)
+		if (err) {
+			struct brcmf_if *ifp = NULL;
+
 			brcmu_pkt_buf_free_skb(skb);
+		}
 		return true;
 	}
 	return false;
@@ -2056,6 +2067,22 @@ static int brcmf_fws_commit_skb(struct brcmf_fws_info *fws, int fifo,
 		(void)brcmf_proto_hdrpull(fws->drvr, false, skb, NULL);
 		goto rollback;
 	}
+	{
+		struct brcmf_if *ifp = brcmf_get_ifp(fws->drvr, brcmf_skb_if_flags_get_field(skb, INDEX));
+
+		if (ifp) {
+			struct pend_skb *e;
+
+			mutex_lock(&ifp->pend_8021x_mutex);
+			list_for_each_entry(e, &ifp->pend_8021x_skbs, list) {
+				if (e->skb == skb) {
+					e->commit_time = local_clock();
+					break;
+				}
+			}
+			mutex_unlock(&ifp->pend_8021x_mutex);
+		}
+	}
 
 	fws->stats.pkt2bus++;
 	fws->stats.send_pkts[fifo]++;
@@ -2454,6 +2481,7 @@ bool brcmf_fws_fc_active(struct brcmf_fws_info *fws)
 
 void brcmf_fws_bustxfail(struct brcmf_fws_info *fws, struct sk_buff *skb)
 {
+	struct brcmf_if *ifp = NULL;
 	u32 hslot;
 
 	if (brcmf_skbcb(skb)->state == BRCMF_FWS_SKBSTATE_TIM) {
diff --git a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/msgbuf.c b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/msgbuf.c
index 2b9a2bc..6ff91c2 100644
--- a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/msgbuf.c
+++ b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/msgbuf.c
@@ -34,6 +34,8 @@
 #include "bus.h"
 #include "tracepoint.h"
 
+#include <linux/sched.h>
+
 
 #define MSGBUF_IOCTL_RESP_TIMEOUT		msecs_to_jiffies(2000)
 
@@ -392,6 +394,8 @@ brcmf_msgbuf_release_array(struct device *dev,
 	count = 0;
 	do {
 		if (array[count].allocated.counter) {
+			struct brcmf_if *ifp = NULL;
+
 			pktid = &array[count];
 			dma_unmap_single(dev, pktid->physaddr,
 					 pktid->skb->len - pktid->data_offset,
@@ -483,6 +487,7 @@ static int brcmf_msgbuf_query_dcmd(struct brcmf_pub *drvr, int ifidx,
 {
 	struct brcmf_msgbuf *msgbuf = (struct brcmf_msgbuf *)drvr->proto->pd;
 	struct sk_buff *skb = NULL;
+	struct brcmf_if *ifp = NULL;
 	int timeout;
 	int err;
 
@@ -747,6 +752,22 @@ static void brcmf_msgbuf_txflow(struct brcmf_msgbuf *msgbuf, u16 flowid)
 			brcmf_commonring_write_complete(commonring);
 			count = 0;
 		}
+		{
+			struct brcmf_if *ifp = brcmf_get_ifp(msgbuf->drvr, tx_msghdr->msg.ifidx);
+
+			if (ifp) {
+				struct pend_skb *e;
+
+				mutex_lock(&ifp->pend_8021x_mutex);
+				list_for_each_entry(e, &ifp->pend_8021x_skbs, list) {
+					if (e->skb == skb) {
+						e->commit_time = local_clock();
+						break;
+					}
+				}
+				mutex_unlock(&ifp->pend_8021x_mutex);
+			}
+		}
 	}
 	if (count)
 		brcmf_commonring_write_complete(commonring);
diff --git a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/usb.c b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/usb.c
index 2f978a3..edbe353 100644
--- a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/usb.c
+++ b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/usb.c
@@ -498,6 +498,7 @@ static void brcmf_usb_rx_complete(struct urb *urb)
 {
 	struct brcmf_usbreq  *req = (struct brcmf_usbreq *)urb->context;
 	struct brcmf_usbdev_info *devinfo = req->devinfo;
+	struct brcmf_if *ifp = NULL;
 	struct sk_buff *skb;
 
 	brcmf_dbg(USB, "Enter, urb->status=%d\n", urb->status);
@@ -548,6 +549,8 @@ static void brcmf_usb_rx_refill(struct brcmf_usbdev_info *devinfo,
 
 	ret = usb_submit_urb(req->urb, GFP_ATOMIC);
 	if (ret) {
+		struct brcmf_if *ifp = NULL;
+
 		brcmf_usb_del_fromq(devinfo, req);
 		brcmu_pkt_buf_free_skb(req->skb);
 		req->skb = NULL;
diff --git a/drivers/net/wireless/broadcom/brcm80211/brcmutil/utils.c b/drivers/net/wireless/broadcom/brcm80211/brcmutil/utils.c
index 0543607..bf525b7 100644
--- a/drivers/net/wireless/broadcom/brcm80211/brcmutil/utils.c
+++ b/drivers/net/wireless/broadcom/brcm80211/brcmutil/utils.c
@@ -49,7 +49,7 @@ void brcmu_pkt_buf_free_skb(struct sk_buff *skb)
 	WARN_ON(skb->next);
 	dev_kfree_skb_any(skb);
 }
-EXPORT_SYMBOL(brcmu_pkt_buf_free_skb);
+//EXPORT_SYMBOL(brcmu_pkt_buf_free_skb);
 
 /*
  * osl multiple-precedence packet queue
diff --git a/drivers/net/wireless/broadcom/brcm80211/include/brcmu_utils.h b/drivers/net/wireless/broadcom/brcm80211/include/brcmu_utils.h
index 4196952..7bd705d 100644
--- a/drivers/net/wireless/broadcom/brcm80211/include/brcmu_utils.h
+++ b/drivers/net/wireless/broadcom/brcm80211/include/brcmu_utils.h
@@ -126,7 +126,7 @@ struct sk_buff *brcmu_pktq_pdeq_match(struct pktq *pq, int prec,
 
 /* packet primitives */
 struct sk_buff *brcmu_pkt_buf_get_skb(uint len);
-void brcmu_pkt_buf_free_skb(struct sk_buff *skb);
+//void brcmu_pkt_buf_free_skb(struct sk_buff *skb);
 
 /* Empty the queue at particular precedence level */
 /* callback function fn(pkt, arg) returns true if pkt belongs to if */
-- 
2.9.3

^ permalink raw reply related	[flat|nested] 6+ messages in thread

* Re: AMPDU stalls with brcmfmac4366b-pcie.bin triggering WARNINGs
  2016-09-15 11:48   ` Rafał Miłecki
@ 2016-09-15 14:27     ` Rafał Miłecki
  0 siblings, 0 replies; 6+ messages in thread
From: Rafał Miłecki @ 2016-09-15 14:27 UTC (permalink / raw)
  To: Hante Meuleman, Arend van Spriel, brcm80211-dev-list; +Cc: linux-wireless

On 09/15/2016 01:48 PM, Rafał Miłecki wrote:
> On 09/14/2016 08:28 PM, Arend Van Spriel wrote:
>> It would be great to have a timestamp for these skb when they arrive in
>> brcmfmac or transferred to firmware (or both).
>
> You ask and you have it :) I saved kernel's local time and printed it the same
> way print_time function does it. Let me paste the most important lines:
> [ 1876.496770] brcmfmac: CONSOLE: 028605.731 wl0: wlc_ampdu_watchdog: cleaning up ini tid 0 due to no progress for 2 secs tx_in_transit 1
> [ 1877.958898] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c71c5480 brcmf_ifname(ifp):wlan1-1
> [ 1878.923359] WARNING: CPU: 1 PID: 1140 at compat-wireless-2016-06-20/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.c:1256 brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac]()
> [ 1880.659840] brcmfmac: [brcmf_netdev_wait_pend8021x] ifp:c71c5480 brcmf_ifname(ifp):wlan1-1 brcmf_get_pend_8021x_cnt(ifp):3
> [ 1880.670922] brcmfmac: [brcmf_netdev_wait_pend8021x] List of pending 802.1x skbs:
> [ 1880.678333] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c6b18d80 skb->dev:c71c5000 skb->dev->name:wlan1-1
> [ 1880.687935] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c6b18900 skb->dev:c71c5000 skb->dev->name:wlan1-1
> [ 1880.697530] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c721fc00 skb->dev:c71c5000 skb->dev->name:wlan1-1
> [ 1881.439614] brcmfmac: [brcmf_msgbuf_process_txstatus -> __brcmf_txfinalize] Finally finalizing skb:c6b18d80 skb->dev:c71c5000 skb->dev->name:wlan1-1 (start_time:[ 1874.928858]; commit_time:[ 1874.928994])
> [ 1881.457852] brcmfmac: [brcmf_msgbuf_process_txstatus -> __brcmf_txfinalize] Finally finalizing skb:c6b18900 skb->dev:c71c5000 skb->dev->name:wlan1-1 (start_time:[ 1875.938806]; commit_time:[ 1875.938858])
> [ 1881.476074] brcmfmac: [brcmf_msgbuf_process_txstatus -> __brcmf_txfinalize] Finally finalizing skb:c721fc00 skb->dev:c71c5000 skb->dev->name:wlan1-1 (start_time:[ 1876.948805]; commit_time:[ 1876.948855])
>
> For the first skb brcmf_netdev_start_xmit was called at 1874.928858.
> It was commited to firmware with brcmf_msgbuf_txflow at 1874.928994.
> Then there was A-MPDU hang in firmware.
> Finally brcmf_msgbuf_process_txstatus was called and it called
> brcmf_txfinalize and this one logged everything at 1881.439614.
>
> You'll find full log at the end.

I kept thinking about this. Some more timing info:
1) wlc_ampdu_watchdog probably started with ampdu_dbg, so we can assume the
    beginning was about 1876.423494.
2) brcmf_netdev_wait_pend8021x waits for 950 ms, so it probably started about
    1877.973359

So the closest timeline I can guess/restore is:
1874.423494: A-MPDU stalls
1874.928994: Passing 802.1x packet #1 to the firmware
1875.938858: Passing 802.1x packet #2 to the firmware
1876.423494: A-MPDU stall detected
1876.508943: Firmware sends DELBA
1876.948855: Passing 802.1x packet #3 to the firmware
1877.973359: brcmf_netdev_wait_pend8021x starts waiting
1881.439614: TX status of 802.1x packet #1
1881.457852: TX status of 802.1x packet #2
1881.476074: TX status of 802.1x packet #3

Now I'm more thinking about this, maybe this A-MPDU stall wasn't any firmware
bug at all? Could it be firmware wasn't getting BA reply e.g. because STA simply
lost the signal?
5 seconds of firmware delay between noticing A-MPDU stall and finally sending
802.1x packets still sound like a big one, but maybe it's not *that* critical?

What's the real problem then is brcmfmac waiting for too long in
brcmf_netdev_wait_pend8021x. It prevents keys from updating and current timeout
of 950 ms sounds like quite a lot. Increasing it to few seconds would stop
WARNINGs from appearing, but would make keys update take even more time.

I guess ideally we should:
1) Have firmware quickly recover from A-MPDU stall (currently: 2 + 5 seconds)
2) Don't have to wait for so long to update keys

^ permalink raw reply	[flat|nested] 6+ messages in thread

end of thread, other threads:[~2016-09-15 14:27 UTC | newest]

Thread overview: 6+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2016-09-14  5:45 AMPDU stalls with brcmfmac4366b-pcie.bin triggering WARNINGs Rafał Miłecki
2016-09-14  7:25 ` Rafał Miłecki
2016-09-14  8:43 ` Rafał Miłecki
2016-09-14 18:28 ` Arend Van Spriel
2016-09-15 11:48   ` Rafał Miłecki
2016-09-15 14:27     ` Rafał Miłecki

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.