Re: syscons problem in ddb, if_afdata initialization (was: Re: 5.3-BETA3 , panic, probably IPv6+SMP+mpsafenet related)

From: Jan Srzednicki <w_at_expro.pl>
Date: Sat, 4 Sep 2004 21:22:18 +0200
On Sat, Sep 04, 2004 at 01:51:06PM -0400, Robert Watson wrote:
> 
> The two sentence summary: this appears to involve three problems, one
> known.  There's a lock order reversal involving TCP and the "uid/gid" 
> layering violation in pf/ipfw, a new issue reported regarding if_afdata
> dereferencing from nd6_slowtimo, and an issue involving syscons calling
> into the tty code from it's low level DDB console API (should never
> happen). 

Well, if you need more data from me, I'm willing to send them. The panic
is easily reproduceable (it just happens after an hour of uptime).

> On Sat, 4 Sep 2004, Jan Srzednicki wrote:
> 
> > I'm running a fresh (cvsupped just after the BETA3 commit in newvers.sh) 
> > RELENG_5 system. It's a SMP with 2 processors, it's doing some
> > home-routing with pf. pf and some netgraph stuff is compiled into
> > kernel, otherwise it's mostly GENERIC. 
> > 
> > It seems to me that the panic is IPv6 and mpsafenet (and probably SMP) 
> > related. It happens about an hour after a boot (happened twice, so it's
> > repeatable). 
> 
> Saw your follow-up e-mail which suggests mpsafenet is not at cause.
> 
> > http://wrzask.pl/stuff/smieci/vmcore.2.dmesg
> 
[..]
> % --- trap 0x1, eip = 0, esp = 0xd51b0d7c, ebp = 0 ---
> % lock order reversal
> %  1st 0xc0808240 ifnet (ifnet) _at_ /usr/src/sys/netinet6/nd6.c:1777
> %  2nd 0xc07d36c4 user map (user map) _at_ /usr/src/sys/vm/vm_map.c:2997
> % KDB: stack backtrace:
> % witness_checkorder(c07d36c4,9,c0787eb3,bb5,0) at witness_checkorder+0x5bb
> % _sx_xlock(c07d36c4,c0787eb3,bb5,1000108,0) at _sx_xlock+0x5d
> % vm_map_lookup(d57e3b5c,0,1,d57e3b60,d57e3b50) at vm_map_lookup+0x3a
> % vm_fault(c07d3680,0,1,0,c12e8580) at vm_fault+0x7a
> % trap_pfault(8,d57e3c50,c05bd344,c07e2aa0,8) at trap_pfault+0x13e
> % trap(c0770018,10,c07e0010,3a00,c1405c00) at trap+0x363
> % calltrap() at calltrap+0x5
> % --- trap 0xc, eip = 0xc06677a6, esp = 0xd57e3c84, ebp = 0xd57e3ca0 ---
> 
> This is the real failure down here, the kernel page faulting; the lock
> order reversal is because the VM code tries to process the page fault
> running into lock order problems.
> 
> What follows though is a bit hard to read.
> 
> % nd6_slowtimo(0,8,c0774781,f7,57e49) at nd6_slowtimo+0x66
> % softclock(0,0,c0770f78,268,d57e3d10) at softclock+0x12f
> % ithread_loop(c12b9c80,d57e3d48,c0770d4d,32c,0) at ithread_loop+0x1fd
> % fork_exit(c057dab0,c12b9c80,d57e3d48) at fork_exit+0xa9
> % fork_trampoline() at fork_trampoline+0x8
> % --- trap 0x1, eip = 0, esp = 0xd57e3d7c, ebp = 0 ---
> 
> It looks like this is a cascading problem that started with dereferencing
> ND_IFINFO(ifp) in nd6_slowtimo().  if_afdata is initialized on demand by
> if_attachdomain1().  It would be interesting to know the contents of *ifp
> in the nd6_slowtimo() frame.  This might be a race/bug involving if_afdata
> initialization...

OK. I'm not sure if I'm doing that the right way, but here it is:

(kgdb) select-frame 22 (that's the one with nd6_slowtimo() in this dump)
(kgdb) print ifp
$1 = (struct ifnet *) 0xc1405c00
(kgdb) print *ifp
$2 = {if_softc = 0xc1405c00, if_link = {tqe_next = 0xc140d000, 
    tqe_prev = 0xc13fa004}, 
  if_xname = "pflog0\000\000\000\000\000\000\000\000\000", 
  if_dname = 0xc075e3a3 "pflog", if_dunit = 0, if_addrhead = {
    tqh_first = 0xc140e000, tqh_last = 0xc140e060}, if_klist = {
    kl_lock = 0xc07d6a20, kl_list = {slh_first = 0x0}}, if_pcount = 1, 
  if_carp = 0x0, if_bpf = 0xc14064c0, if_index = 5, if_timer = 0, 
  if_nvlans = 0, if_flags = 321, if_capabilities = 0, if_capenable = 0, 
  if_linkmib = 0x0, if_linkmiblen = 0, if_data = {ifi_type = 246 'ö', 
    ifi_physical = 0 '\0', ifi_addrlen = 0 '\0', ifi_hdrlen = 48 '0', 
    ifi_link_state = 0 '\0', ifi_recvquota = 0 '\0', ifi_xmitquota = 0 '\0', 
    ifi_mtu = 33208, ifi_metric = 0, ifi_baudrate = 0, ifi_ipackets = 0, 
    ifi_ierrors = 0, ifi_opackets = 0, ifi_oerrors = 0, ifi_collisions = 0, 
    ifi_ibytes = 0, ifi_obytes = 0, ifi_imcasts = 0, ifi_omcasts = 0, 
    ifi_iqdrops = 0, ifi_noproto = 0, ifi_hwassist = 0, ifi_unused = 0, 
    ifi_lastchange = {tv_sec = 1094301842, tv_usec = 136803}}, 
  if_multiaddrs = {tqh_first = 0x0, tqh_last = 0xc1405cac}, if_amcount = 0, 
  if_output = 0xc0484a80 <pflogoutput>, if_input = 0, 
  if_start = 0xc04849c0 <pflogstart>, if_ioctl = 0xc0484ac0 <pflogioctl>, 
  if_watchdog = 0, if_init = 0, if_resolvemulti = 0, if_snd = {ifq_head = 0x0, 
    ifq_tail = 0x0, ifq_len = 0, ifq_maxlen = 50, ifq_drops = 0, ifq_mtx = {
      mtx_object = {lo_class = 0xc07ad4e4, lo_name = 0xc1405c0c "pflog0", 
        lo_type = 0xc077c33e "if send queue", lo_flags = 196608, lo_list = {
          tqe_next = 0xc140e07c, tqe_prev = 0xc1405e04}, 
---Type <return> to continue, or q <return> to quit---
        lo_witness = 0xc07e3530}, mtx_lock = 4, mtx_recurse = 0}, 
    ifq_drv_head = 0x0, ifq_drv_tail = 0x0, ifq_drv_len = 0, 
    ifq_drv_maxlen = 0, altq_type = 0, altq_flags = 0, altq_disc = 0x0, 
    altq_ifp = 0xc1405c00, altq_enqueue = 0, altq_dequeue = 0, 
    altq_request = 0, altq_clfier = 0x0, altq_classify = 0, altq_tbr = 0x0, 
    altq_cdnr = 0x0}, if_broadcastaddr = 0x0, lltables = 0x0, if_label = 0x0, 
  if_prefixhead = {tqh_first = 0x0, tqh_last = 0xc1405d54}, if_afdata = {
    0x0 <repeats 37 times>}, if_afdata_initialized = 1, if_afdata_mtx = {
    mtx_object = {lo_class = 0xc07ad4e4, lo_name = 0xc077c32e "if_afdata", 
      lo_type = 0xc077c32e "if_afdata", lo_flags = 196608, lo_list = {
        tqe_next = 0xc1405ce8, tqe_prev = 0xc079cba0}, 
      lo_witness = 0xc07e3558}, mtx_lock = 4, mtx_recurse = 0}, 
  if_starttask = {ta_link = {stqe_next = 0x0}, ta_pending = 0, 
    ta_priority = 0, ta_func = 0xc060cc10 <if_start_deferred>, 
    ta_context = 0xc1405c00}}

Hope this helps.

It's also worth noting that on the previous kernel (that is: FreeBSD
5.3-BETA2 (SIN) #9: Sun Aug 29 14:24:19 CEST 2004) nothing like that
happened, so it appears to be somehow related to (or uncovered by) some
very recent commit.

> % Fatal trap 12: page fault while in kernel mode
> % cpuid = 0; apic id = 01
> % fault virtual address	= 0x8
> % fault code		= supervisor read, page not present
> % instruction pointer	= 0x8:0xc06677a6
> % stack pointer	        = 0x10:0xd57e3c84
> % frame pointer	        = 0x10:0xd57e3ca0
> % code segment		= base 0x0, limit 0xfffff, type 0x1b
> % 			= DPL 0, pres 1, def32 1, gran 1
> % processor eflags	= interrupt enabled, resume, IOPL = 0
> % current process		= 36 (swi5: clock sio)
> % panic: blockable sleep lock (sleep mutex) tty _at_ /usr/src/sys/kern/kern_event.c:1450
> % cpuid = 0
> % boot() called on cpu#0
> % Uptime: 1h0m18s
> % Dumping 127 MB
> %  16 32 48 64 80 96 112
> 
> 
> This one is pretty unfortunate, but hopefully easily fixable.  Here's my
> interpretation:
> 
> % #0  doadump () at pcpu.h:159
> % #1  0xc0595216 in boot (howto=260) at /usr/src/sys/kern/kern_shutdown.c:396
> % #2  0xc0594ceb in panic (fmt=0xc0776fd5 "blockable sleep lock (%s) %s _at_ %s:%d")
> %     at /usr/src/sys/kern/kern_shutdown.c:552
> % #3  0xc05bd589 in witness_checkorder (lock=0xc13fd910, flags=9, 
> %     file=0xc0770940 "/usr/src/sys/kern/kern_event.c", line=1450)
> %     at /usr/src/sys/kern/subr_witness.c:703
> % #4  0xc058b374 in _mtx_lock_flags (m=0xc13fd910, opts=0, 
> %     file=0xc0770940 "/usr/src/sys/kern/kern_event.c", line=1450)
> %     at /usr/src/sys/kern/kern_mutex.c:261
> % #5  0xc0575559 in knote (list=0xc13fd898, hint=0, islocked=0)
> %     at /usr/src/sys/kern/kern_event.c:1450
> % #6  0xc05cb793 in ttwwakeup (tp=0xc13fd800) at /usr/src/sys/kern/tty.c:2394
> % #7  0xc0715ef8 in scstart (tp=0xc13fd800)
> %     at /usr/src/sys/dev/syscons/syscons.c:1367
> % #8  0xc0716489 in scgetc (sc=0xc082ef60, flags=3)
> %     at /usr/src/sys/dev/syscons/syscons.c:3209
> % #9  0xc07167de in sccngetch (flags=3)
> %     at /usr/src/sys/dev/syscons/syscons.c:1553
> % #10 0xc05d0ad9 in cncheckc () at /usr/src/sys/kern/tty_cons.c:567
> % #11 0xc05d0b15 in cngetc () at /usr/src/sys/kern/tty_cons.c:548
> % #12 0xc04ab335 in db_readline (lstart=0xc07cea00 "", lsize=120)
> 
> The polled console support used by DDB has lead somehow to a call to
> ttwwakeup(), which should never happen (TM) using the polled interface.
> This is because we can't run all the TTY level code from the debugger,
> only low level polled console operation.  I'm not sure who to point at for 

The hint here would be that after I got the ddb prompt I tried to scroll
up some lines (scroll lock + page up) and then the (second) panic
occured.

-- 
Jan 'Winfried' Srzednicki
w_at_expro.pl
Received on Sat Sep 04 2004 - 17:22:21 UTC

This archive was generated by hypermail 2.4.0 : Wed May 19 2021 - 11:38:10 UTC