Bug 192641 - [iwn] panic in AMPDU tx code "ni: no node"
Summary: [iwn] panic in AMPDU tx code "ni: no node"
Status: Closed FIXED
Alias: None
Product: Base System
Classification: Unclassified
Component: wireless (show other bugs)
Version: CURRENT
Hardware: Any Any
: --- Affects Only Me
Assignee: Andriy Voskoboinyk
URL:
Keywords: panic
Depends on:
Blocks:
 
Reported: 2014-08-13 16:51 UTC by Adrian Chadd
Modified: 2019-02-16 01:29 UTC (History)
4 users (show)

See Also:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Adrian Chadd freebsd_committer 2014-08-13 16:51:00 UTC
(kgdb) bt
#0  doadump (textdump=-1059352868) at pcpu.h:233
#1  0xc04f92cd in db_fncall (dummy1=-332454048, dummy2=0, dummy3=-951087536, dummy4=0xec2f274c "�&R��\216��") at /usr/home/adrian/work/freebsd/head/src/sys/ddb/db_command.c:578
#2  0xc04f8fab in db_command (cmd_table=<value optimized out>) at /usr/home/adrian/work/freebsd/head/src/sys/ddb/db_command.c:449
#3  0xc04f8cf0 in db_command_loop () at /usr/home/adrian/work/freebsd/head/src/sys/ddb/db_command.c:502
#4  0xc04fb640 in db_trap (type=<value optimized out>, code=<value optimized out>) at /usr/home/adrian/work/freebsd/head/src/sys/ddb/db_main.c:231
#5  0xc06c2bf4 in kdb_trap (type=<value optimized out>, code=<value optimized out>, tf=<value optimized out>) at /usr/home/adrian/work/freebsd/head/src/sys/kern/subr_kdb.c:654
#6  0xc093df67 in trap (frame=<value optimized out>) at /usr/home/adrian/work/freebsd/head/src/sys/i386/i386/trap.c:693
#7  0xc0926a7c in calltrap () at /usr/home/adrian/work/freebsd/head/src/sys/i386/i386/exception.s:169
#8  0xc06c247d in kdb_enter (why=0xc09ba864 "panic", msg=<value optimized out>) at cpufunc.h:71
#9  0xc0687f61 in vpanic (fmt=<value optimized out>, ap=<value optimized out>) at /usr/home/adrian/work/freebsd/head/src/sys/kern/kern_shutdown.c:739
#10 0xc0687e13 in kassert_panic (fmt=<value optimized out>) at /usr/home/adrian/work/freebsd/head/src/sys/kern/kern_shutdown.c:634
#11 0xc8f14751 in iwn_ampdu_tx_done (sc=0xc8f21000, qid=10, idx=<value optimized out>, nframes=1, stat=<value optimized out>) at /usr/home/adrian/work/freebsd/head/src/sys/modules/iwn/../../dev/iwn/if_iwn.c:3613
#12 0xc8f13eb5 in iwn5000_tx_done (sc=<value optimized out>, desc=<value optimized out>, data=<value optimized out>) at /usr/home/adrian/work/freebsd/head/src/sys/modules/iwn/../../dev/iwn/if_iwn.c:3411
#13 0xc8f0b9ff in iwn_notif_intr (sc=0xc8f21000) at /usr/home/adrian/work/freebsd/head/src/sys/modules/iwn/../../dev/iwn/if_iwn.c:3696
#14 0xc8f0b2e0 in iwn_intr (arg=0xc8f21000) at /usr/home/adrian/work/freebsd/head/src/sys/modules/iwn/../../dev/iwn/if_iwn.c:3995
#15 0xc0655913 in intr_event_execute_handlers (ie=<value optimized out>) at /usr/home/adrian/work/freebsd/head/src/sys/kern/kern_intr.c:1252
#16 0xc0656213 in ithread_loop (arg=0xc85e6ee0) at /usr/home/adrian/work/freebsd/head/src/sys/kern/kern_intr.c:1265
#17 0xc0652e2f in fork_exit (callout=0xc0656180 <ithread_loop>) at /usr/home/adrian/work/freebsd/head/src/sys/kern/kern_fork.c:977
#18 0xc0926b24 in fork_trampoline () at /usr/home/adrian/work/freebsd/head/src/sys/i386/i386/exception.s:278
Current language:  auto; currently minimal
(kgdb) frame 11
#11 0xc8f14751 in iwn_ampdu_tx_done (sc=0xc8f21000, qid=10, idx=<value optimized out>, nframes=1, stat=<value optimized out>) at /usr/home/adrian/work/freebsd/head/src/sys/modules/iwn/../../dev/iwn/if_iwn.c:3613
3613			KASSERT(ni != NULL, ("no node"));
(kgdb) print ni
$1 = <value optimized out>
(kgdb) 

.. and leading up to it:

Unread portion of the kernel message buffer:
iwn0: iwn_tx_data: m=0xc9572900: seqno (53004) (12) != ring index (0) !
iwn0: iwn_tx_data: m=0xc896f200: seqno (53005) (13) != ring index (1) !
panic: no node
cpuid = 1
KDB: stack backtrace:
db_trace_self_wrapper(c09bf552,ec2f29b8,fc,10000000,0,...) at db_trace_self_wrapper+0x2d/frame 0xec2f29a0
kdb_backtrace(c09fc9a7,1,c8f18b78,ec2f2a8c,ec2f2a30,...) at kdb_backtrace+0x30/frame 0xec2f2a08
vpanic(c0af9f18,100,c8f18b78,ec2f2a8c,4000ace,...) at vpanic+0x11d/frame 0xec2f2a44
kassert_panic(c8f18b78,5,cdd25c00,cdd25c00,c8d6dc00,...) at kassert_panic+0x153/frame 0xec2f2a80
iwn_ampdu_tx_done(0,1,cae8f028,c0671aa1,c8f2100c,...) at iwn_ampdu_tx_done+0x251/frame 0xec2f2adc
iwn5000_tx_done(c8f21000,cae8f000,c8f3a934,bd2,c8f0dea0,...) at iwn5000_tx_done+0xe5/frame 0xec2f2b20
iwn_notif_intr(c8f2101c,0,c8f18029,f5a,c0b07b80,...) at iwn_notif_intr+0x4bf/frame 0xec2f2bd0
iwn_intr(c8f21000,c09b3975,4e0,c09b3b43,c09b3b68,...) at iwn_intr+0x7c0/frame 0xec2f2c3c
intr_event_execute_handlers(c7492bc0,c86c6480,c09b3975,55a,3c9,...) at intr_event_execute_handlers+0xe3/frame 0xec2f2c80
ithread_loop(c85e6ee0,ec2f2d08,c09b367a,3c9,0,...) at ithread_loop+0x93/frame 0xec2f2ccc
fork_exit(c0656180,c85e6ee0,ec2f2d08) at fork_exit+0x7f/frame 0xec2f2cf4
fork_trampoline() at fork_trampoline+0x8/frame 0xec2f2cf4
--- trap 0, eip = 0, esp = 0xec2f2d40, ebp = 0 ---
KDB: enter: panic

.. so something went a little pear shaped and we didn't handle it right.
Comment 1 Tim Marinin 2016-01-16 21:50:13 UTC
It seems like I'm having the same problem with N-2230 on CURRENT, it causes panics once in a while (I have 9 core dumps since New Year). Not sure how to debug it.
Comment 2 gl00my 2018-11-08 05:45:43 UTC
Hello! While working with iwfi drivers in Haiku (those drivers are ported from FreeBSD) i founded the bugs, that potentially is FreeBSD specific.

iprowifi4965 and iprowifi3945 are affected. May be others.

I will describe them on iprowifi4965 code.

iwn_tx_done has KASSERT(data->ni != NULL, ("no node")) at beginning that is triggers in some situations. 

The situation can be:

1) hw interrupt is scheduled

2) iwn_hw_stop is called (and it disables/enables interrupss) node is destroyed here.

3) here we got scheduled (threaded) interrupt that is not actual anymore -> panic

In fact, i was thinking it is Haiku specific bug, because of threaded inr handlers. But i found this bug report and it seems the same for me.

To reproduce it on Haiku i run floodping to roater while reboot the system. But on FreeBSD i am not sure, what can couse iwn_hw_stop while sending packets...

Hope it helps.
Comment 3 commit-hook freebsd_committer 2019-01-16 12:33:15 UTC
A commit references this bug:

Author: avos
Date: Wed Jan 16 12:33:07 UTC 2019
New revision: 343094
URL: https://svnweb.freebsd.org/changeset/base/343094

Log:
  iwn(4): (partially) rewrite A-MPDU Tx path

  Generic Tx stats fixes:
  - do not try to parse "aggregation status" for single frames; send them
  to iwn_tx_done() instead;
  - try to attach mbuf / node reference pair to reported BA events;
  allows to fix reported status for ieee80211_tx_complete() and ifnet counters
  (previously all A-MPDU frames were counted as failed - see PR 210211);
  requires few more firmware bug workarounds;
  - preserve short / long retry counters for wlan_amrr(4)
  (disabled for now - causes significant performance degradation).
  - Add new IWN_DEBUG_AMPDU debug category.
  - Add one more check into iwn_tx_data() to prevent aggregation ring
  overflow.
  - Workaround 'seqno % 256' != 'current Tx slot' case (until D9195 is not
  in the tree).
  - Improve watchdog timer updates (previously watchdog check was omitted
  when at least one frame was transmitted).
  - Stop Tx when memory leak in currently used ring was detected (unlikely
  to happen).
  - Few other minor fixes.

  Was previously tested with:
   - Intel 6205, STA mode (Tx aggregation behaves much better now).
   - Intel 4965AGN, STA mode (still unstable).

  PR:		192641, 210211
  Reviewed by:	adrian, dhw
  MFC after:	1 month
  Differential Revision:	https://reviews.freebsd.org/D10728

Changes:
  head/sys/dev/iwn/if_iwn.c
  head/sys/dev/iwn/if_iwn_debug.h
  head/sys/dev/iwn/if_iwnreg.h
  head/sys/dev/iwn/if_iwnvar.h
Comment 4 Michael Zhilin 2019-02-05 08:22:47 UTC
Hi,

Thank you, Andriy!!!

This night laptop panicked with similar error on r343662:

__curthread () at ./machine/pcpu.h:230
230             __asm("movq %%gs:%P1,%0" : "=r" (td) : "n" (OFFSETOF_CURTHREAD));
(kgdb) #0  __curthread () at ./machine/pcpu.h:230
#1  doadump (textdump=<optimized out>)
    at /usr/src/sys/kern/kern_shutdown.c:371
#2  0xffffffff8049aa3b in db_dump (dummy=<optimized out>, 
    dummy2=<unavailable>, dummy3=<unavailable>, dummy4=<unavailable>)
    at /usr/src/sys/ddb/db_command.c:574
#3  0xffffffff8049a809 in db_command (last_cmdp=<optimized out>, 
    cmd_table=<optimized out>, dopager=1) at /usr/src/sys/ddb/db_command.c:481
#4  0xffffffff8049a584 in db_command_loop ()
    at /usr/src/sys/ddb/db_command.c:534
#5  0xffffffff8049d73f in db_trap (type=<optimized out>, code=<optimized out>)
    at /usr/src/sys/ddb/db_main.c:252
#6  0xffffffff80c257a4 in kdb_trap (type=3, code=0, tf=<optimized out>)
    at /usr/src/sys/kern/subr_kdb.c:692
#7  0xffffffff810adf9b in trap (frame=0xfffffe00005646c0)
    at /usr/src/sys/amd64/amd64/trap.c:619
#8  <signal handler called>
#9  kdb_enter (why=0xffffffff8133e78d "panic", msg=<optimized out>)
    at /usr/src/sys/kern/subr_kdb.c:479
#10 0xffffffff80bdd351 in vpanic (fmt=<optimized out>, ap=0xfffffe0000564830)
    at /usr/src/sys/kern/kern_shutdown.c:866
#11 0xffffffff80bdd0e3 in panic (
    fmt=0xffffffff81e96658 <cnputs_mtx> "R80\201\377\377\377\377")
    at /usr/src/sys/kern/kern_shutdown.c:804
#12 0xffffffff806ac92f in iwn_tx_done (sc=0xfffffe0005df9000, 
    desc=<optimized out>, rtsfailcnt=5654144, ackfailcnt=128, status=0 '\000')
    at /usr/src/sys/dev/iwn/if_iwn.c:3659
#13 0xffffffff806b29d4 in iwn_notif_intr (sc=<optimized out>)
    at /usr/src/sys/dev/iwn/if_iwn.c:4033
#14 0xffffffff806a9992 in iwn_intr (arg=0xfffffe0005df9000)
    at /usr/src/sys/dev/iwn/if_iwn.c:4327
#15 0xffffffff80ba02c7 in intr_event_execute_handlers (ie=<optimized out>, 
    p=<optimized out>) at /usr/src/sys/kern/kern_intr.c:1119
#16 ithread_execute_handlers (ie=<optimized out>, p=<optimized out>)
    at /usr/src/sys/kern/kern_intr.c:1132
#17 ithread_loop (arg=<optimized out>) at /usr/src/sys/kern/kern_intr.c:1212
#18 0xffffffff80b9cf44 in fork_exit (
    callout=0xffffffff80ba0140 <ithread_loop>, arg=0xfffff80004a59000, 
    frame=0xfffffe0000564ac0) at /usr/src/sys/kern/kern_fork.c:1055
#19 <signal handler called>
(kgdb) 

Conditions: I have unstable connection to WiFi AP because of long distance between laptop and router. Sometimes connectivity is lost. 

I can upload dump / textdump if it's required. 

Best regards
Comment 5 Andriy Voskoboinyk freebsd_committer 2019-02-05 10:14:50 UTC
Hi,
is it 4965agn? (I cannot determine chipset from the backtrace)
Comment 6 Andriy Voskoboinyk freebsd_committer 2019-02-05 12:11:50 UTC
I remember there were some similar issues with wpi(4) (fixed few years ago); does this happen when power save is turned off?
(ifconfig wlan0 -powersave - before NIC is connected, since it will be ignored until next reassociation)

P.S. ackfailcnt / rtsfailcnt is bogus; I hope they were corrupted in backtrace only...
Comment 7 Andriy Voskoboinyk freebsd_committer 2019-02-05 12:22:17 UTC
Firmware panic and/or device restart may result in this issue too - there is a (possible) race between beacon miss and initialization path; I will try to add a workaround here a bit later.
Comment 8 Michael Zhilin 2019-02-05 12:41:49 UTC
avos@,

Chipset is centrino wireless-N 2200 (vendor=8086 chip=0891)
Last logs from wpa_supplicant:
Feb  5 02:17:46 gidrarium wpa_supplicant[325]: wlan0: Event SCAN_RESULTS (3) received
Feb  5 02:17:46 gidrarium kernel: iwn0: scan timeout
Feb  5 02:17:46 gidrarium wpa_supplicant[325]: Received 0 bytes of scan results (0 BSSes)
Feb  5 02:17:46 gidrarium kernel: iwn0: iwn_read_firmware: ucode rev=0x12a80601
Feb  5 02:17:46 gidrarium wpa_supplicant[325]: wlan0: BSS: Start scan result update 127
Feb  5 02:17:46 gidrarium wpa_supplicant[325]: wlan0: BSS: Remove id 187 BSSID c4:71:54:3e:88:ac SSID 'kvartira50' due to no match in scan
Feb  5 02:17:46 gidrarium wpa_supplicant[325]: wlan0: BSS: Remove id 179 BSSID b0:4e:26:b4:2b:be SSID 'TP-L-492' due to no match in scan
Feb  5 02:17:46 gidrarium wpa_supplicant[325]: BSS: last_scan_res_used=0/32
Feb  5 02:17:46 gidrarium wpa_supplicant[325]: wlan0: New scan results available (own=0 ext=0)
Feb  5 02:17:46 gidrarium wpa_supplicant[325]: WPS: Unknown Vendor Extension (Vendor ID 9442)
Feb  5 02:17:46 gidrarium syslogd: last message repeated 5 times
Feb  5 02:17:46 gidrarium wpa_supplicant[325]: wlan0: Radio work 'scan'@0x800e1a380 done in 4.997372 seconds
Feb  5 02:17:46 gidrarium wpa_supplicant[325]: wlan0: radio_work_free('scan'@0x800e1a380): num_active_works --> 0
Feb  5 02:17:46 gidrarium wpa_supplicant[325]: wlan0: No suitable network found
Feb  5 02:17:46 gidrarium wpa_supplicant[325]: wlan0: Setting scan request: 5.000000 sec

I wonder is it possible to test timestamp of panic from dump.
Comment 9 Andriy Voskoboinyk freebsd_committer 2019-02-05 12:51:17 UTC
That is - 'scan timeout' causes device restart.
Comment 10 commit-hook freebsd_committer 2019-02-06 01:34:49 UTC
A commit references this bug:

Author: avos
Date: Wed Feb  6 01:34:14 UTC 2019
New revision: 343815
URL: https://svnweb.freebsd.org/changeset/base/343815

Log:
  iwn(4): plug initialization path vs interrupt handler races

  There are few places in interrupt handler where the driver
  lock is dropped; ensure that device is still running before
  processing remaining ring entries.

  PR:		192641
  MFC after:	5 days

Changes:
  head/sys/dev/iwn/if_iwn.c
Comment 11 Michael Zhilin 2019-02-06 07:06:35 UTC
Thank you, Andriy!
Comment 12 commit-hook freebsd_committer 2019-02-11 00:32:39 UTC
A commit references this bug:

Author: avos
Date: Mon Feb 11 00:31:59 UTC 2019
New revision: 343992
URL: https://svnweb.freebsd.org/changeset/base/343992

Log:
  MFC r343815:
  iwn(4): plug initialization path vs interrupt handler races

  There are few places in interrupt handler where the driver
  lock is dropped; ensure that device is still running before
  processing remaining ring entries.

  PR:		192641

Changes:
_U  stable/11/
  stable/11/sys/dev/iwn/if_iwn.c
_U  stable/12/
  stable/12/sys/dev/iwn/if_iwn.c
Comment 13 commit-hook freebsd_committer 2019-02-16 01:19:47 UTC
A commit references this bug:

Author: avos
Date: Sat Feb 16 01:19:15 UTC 2019
New revision: 344197
URL: https://svnweb.freebsd.org/changeset/base/344197

Log:
  MFC r343094:
  iwn(4): (partially) rewrite A-MPDU Tx path

  The change fixes ifnet counters and improves Tx stability when A-MPDU
  is used.

  MFC r343292:
  iwn(4): drop i_seq field initialization for A-MPDU frames

  It is done by net80211 since r319460.

  PR:		192641, 210211
  Reviewed by:	adrian, dhw
  Differential Revision:	https://reviews.freebsd.org/D10728

Changes:
_U  stable/12/
  stable/12/sys/dev/iwn/if_iwn.c
  stable/12/sys/dev/iwn/if_iwn_debug.h
  stable/12/sys/dev/iwn/if_iwnreg.h
  stable/12/sys/dev/iwn/if_iwnvar.h
Comment 14 Andriy Voskoboinyk freebsd_committer 2019-02-16 01:29:49 UTC
Looks like the issue can be closed now.