Bug 225927

Summary: [panic] NULL pointer dereference in nd6_llinfo_timer()
Product: Base System Reporter: Andrey V. Elsukov <ae>
Component: kernAssignee: Andrey V. Elsukov <ae>
Status: Closed FIXED    
Severity: Affects Only Me CC: hselasky, markj, net, rgrimes, vegeta
Priority: --- Keywords: crash
Version: CURRENTFlags: koobs: mfc-stable11+
Hardware: Any   
OS: Any   
See Also: https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=209682

Description Andrey V. Elsukov freebsd_committer freebsd_triage 2018-02-15 17:09:16 UTC
We got this panic several times already. I filled this PR in case someone else can put here "we have this panic too".

The panic happens when network configuration is being changed (i.e. some vlan interfaces destroyed, IPv6 prefixes removed, etc.)

The system usually has 5-20 thousands of NDP entries.

The backtrace is the following: 
Fatal trap 12: page fault while in kernel mode
cpuid = 45; apic id = 33
fault virtual address	= 0x330
fault code		= supervisor read data, page not present
instruction pointer	= 0x20:0xffffffff80cc3c65
stack pointer	        = 0x28:0xfffffe104a3da890
frame pointer	        = 0x28:0xfffffe104a3da900
code segment		= base rx0, limit 0xfffff, type 0x1b
			= DPL 0, pres 1, long 1, def32 0, gran 1
processor eflags	= interrupt enabled, resume, IOPL = 0
current process		= 12 (swi4: clock (0))
trap number		= 12
panic: page fault
cpuid = 45
time = 1518707404
KDB: stack backtrace:
db_trace_self_wrapper() at db_trace_self_wrapper+0x2b/frame 0xfffffe104a3da470
vpanic() at vpanic+0x19c/frame 0xfffffe104a3da4f0
panic() at panic+0x43/frame 0xfffffe104a3da550
trap_fatal() at trap_fatal+0x34d/frame 0xfffffe104a3da5a0
trap_pfault() at trap_pfault+0x49/frame 0xfffffe104a3da600
trap() at trap+0x2a9/frame 0xfffffe104a3da7c0
calltrap() at calltrap+0x8/frame 0xfffffe104a3da7c0
--- trap 0xc, rip = 0xffffffff80cc3c65, rsp = 0xfffffe104a3da890, rbp = 0xfffffe104a3da900 ---
nd6_llinfo_timer() at nd6_llinfo_timer+0x75/frame 0xfffffe104a3da900
softclock_call_cc() at softclock_call_cc+0x12f/frame 0xfffffe104a3da9b0
softclock() at softclock+0xb9/frame 0xfffffe104a3da9e0
intr_event_execute_handlers() at intr_event_execute_handlers+0xec/frame 0xfffffe104a3daa20
ithread_loop() at ithread_loop+0xd6/frame 0xfffffe104a3daa70
fork_exit() at fork_exit+0x85/frame 0xfffffe104a3daab0
fork_trampoline() at fork_trampoline+0xe/frame 0xfffffe104a3daab0
--- trap 0, rip = 0, rsp = 0, rbp = 0 ---
Uptime: 18d20h16m49s
Dumping 17367 out of 65386 MB:..1%..11%..21%..31%..41%..51%..61%..71%..81%..91%

__curthread () at ./machine/pcpu.h:232
232	./machine/pcpu.h: No such file or directory.

(kgdb) bt
#0  __curthread () at ./machine/pcpu.h:232
#1  doadump (textdump=1) at /usr/src/sys/kern/kern_shutdown.c:318
#2  0xffffffff80a8bdd6 in kern_reboot (howto=260) at /usr/src/sys/kern/kern_shutdown.c:386
#3  0xffffffff80a8c2c6 in vpanic (fmt=<optimized out>, ap=0xfffffe104a3da530) at /usr/src/sys/kern/kern_shutdown.c:779
#4  0xffffffff80a8c0e3 in panic (fmt=<unavailable>) at /usr/src/sys/kern/kern_shutdown.c:710
#5  0xffffffff80f1376d in trap_fatal (frame=0xfffffe104a3da7d0, eva=816) at /usr/src/sys/amd64/amd64/trap.c:799
#6  0xffffffff80f137c9 in trap_pfault (frame=0xfffffe104a3da7d0, usermode=0) at /usr/src/sys/amd64/amd64/trap.c:653
#7  0xffffffff80f13019 in trap (frame=0xfffffe104a3da7d0) at /usr/src/sys/amd64/amd64/trap.c:420
#8  <signal handler called>
#9  nd6_llinfo_timer (arg=0xfffff808285af000) at /usr/src/sys/netinet6/nd6.c:781
#10 0xffffffff80aa44af in softclock_call_cc (c=<optimized out>, cc=0xffffffff81dbff80 <cc_cpu>, direct=<optimized out>) at /usr/src/sys/kern/kern_timeout.c:729
#11 0xffffffff80aa49d9 in softclock (arg=0xffffffff81dbff80 <cc_cpu>) at /usr/src/sys/kern/kern_timeout.c:867
#12 0xffffffff80a50d4c in intr_event_execute_handlers (p=<optimized out>, ie=0xfffff8000b60d000) at /usr/src/sys/kern/kern_intr.c:1336
#13 0xffffffff80a51416 in ithread_execute_handlers (ie=<optimized out>, p=<optimized out>) at /usr/src/sys/kern/kern_intr.c:1349
#14 ithread_loop (arg=0xfffff8000b54b980) at /usr/src/sys/kern/kern_intr.c:1430
#15 0xffffffff80a4e095 in fork_exit (callout=0xffffffff80a51340 <ithread_loop>, arg=0xfffff8000b54b980, frame=0xfffffe104a3daac0)
    at /usr/src/sys/kern/kern_fork.c:1038
#16 <signal handler called>
(kgdb) f 9
#9  nd6_llinfo_timer (arg=0xfffff808285af000) at /usr/src/sys/netinet6/nd6.c:781
781	/usr/src/sys/netinet6/nd6.c: No such file or directory.
(kgdb) i lo
ln = 0xfffff808285af000
ifp = 0x0
ndi = <optimized out>
send_ns = <optimized out>
pdst = <optimized out>
delay = <optimized out>
do_switch = <optimized out>
src = <optimized out>
psrc = <optimized out>
(kgdb) p *ln
$1 = {lle_next = {le_next = 0xfffff8054ff07200, le_prev = 0xfffff80408aa8e70}, r_l3addr = {addr4 = {s_addr = 3087401514}, addr6 = {__u6_addr = {
        __u6_addr8 = "*\002\006\270\000\000\032\001\230\370\036\370\203\253\036X", __u6_addr16 = {554, 47110, 0, 282, 63640, 63518, 43907, 22558}, __u6_addr32 = {
          3087401514, 18481152, 4162779288, 1478404995}}}}, r_linkdata = "\000%\220\353\223|$\212\a\021P\204\206\335\000\000\000\000\000\000\000\000\000", 
  r_hdrlen = 14 '\016', spare0 = "\000\000", r_flags = 1, r_skip_req = 1, lle_tbl = 0xfffff80cfead8e00, lle_head = 0xfffff80408aa8e70, 
  lle_free = 0xffffffff80ca8af0 <in6_lltable_destroy_lle>, la_hold = 0x0, la_numheld = 0, la_expire = 1628209, la_flags = 8, la_asked = 0, la_preempt = 0, 
  ln_state = 2, ln_router = 0, ln_ntick = 0, lle_remtime = 85985000, lle_hittime = 0, lle_refcnt = 1, ll_addr = 0xfffff808285af020 "", lle_chain = {
    le_next = 0xfffff80408951a00, le_prev = 0xfffff80e9100d6a8}, lle_timer = {c_links = {le = {le_next = 0x0, le_prev = 0xffffffff81dc0058 <cc_cpu+216>}, sle = {
        sle_next = 0x0}, tqe = {tqe_next = 0x0, tqe_prev = 0xffffffff81dc0058 <cc_cpu+216>}}, c_time = 6993108294966657, c_precision = 1342177187, 
    c_arg = 0xfffff808285af000, c_func = 0xffffffff80cc3bf0 <nd6_llinfo_timer>, c_lock = 0x0, c_flags = 2, c_iflags = 144, c_cpu = 0}, lle_lock = {lock_object = {
      lo_name = 0xffffffff81493c80 "lle", lo_flags = 90374144, lo_data = 0, lo_witness = 0x0}, rw_lock = 18446735277807501312}, req_mtx = {lock_object = {
      lo_name = 0xffffffff81493c84 "lle req", lo_flags = 16973824, lo_data = 0, lo_witness = 0x0}, mtx_lock = 4}}
(kgdb) p ln->lle_timer
$2 = {c_links = {le = {le_next = 0x0, le_prev = 0xffffffff81dc0058 <cc_cpu+216>}, sle = {sle_next = 0x0}, tqe = {tqe_next = 0x0, 
      tqe_prev = 0xffffffff81dc0058 <cc_cpu+216>}}, c_time = 6993108294966657, c_precision = 1342177187, c_arg = 0xfffff808285af000, 
  c_func = 0xffffffff80cc3bf0 <nd6_llinfo_timer>, c_lock = 0x0, c_flags = 2, c_iflags = 144, c_cpu = 0}

(kgdb) p &((((struct ifnet *)0)->if_afdata[28])->nd_ifinfo)
Cannot access memory at address 0x330


The system doesn't have VIMAGE in the kernel, with this option I think it will crash in the CURVNET_SET()

 752         KASSERT(arg != NULL, ("%s: arg NULL", __func__));
 753         ln = (struct llentry *)arg;
 754         ifp = lltable_get_ifp(ln->lle_tbl);
 755         CURVNET_SET(ifp->if_vnet);
 756 
 757         ND6_RLOCK();
 758         LLE_WLOCK(ln);
 759         if (callout_pending(&ln->lle_timer)) { 
 760                 /*
 761                  * Here we are a bit odd here in the treatment of 
....
 779                 return;                                                       
 780         }
 781         ndi = ND_IFINFO(ifp);

I think this happens when lltable_free() calls callout_stop() for already active callout, and then llentry_free() releases LLE_WLOCK() via LLE_FREE_LOCKED().
Comment 1 Andrey V. Elsukov freebsd_committer freebsd_triage 2018-02-15 17:33:47 UTC
Add lle_tbl

(kgdb) p *ln->lle_tbl
$4 = {llt_link = {sle_next = 0x2}, llt_af = 33770267, llt_hsize = 0, lle_head = 0x0, llt_ifp = 0x0, llt_lookup = 0x0, llt_alloc_entry = 0x0, 
  llt_delete_entry = 0x8013070200010001, llt_prefix_free = 0x0, llt_dump_entry = 0x0, llt_hash = 0x0, llt_match_prefix = 0xc4f59, llt_free_entry = 0x1, 
  llt_foreach_entry = 0x48c0a4d8d9, llt_link_entry = 0x290e5e84a44f, llt_unlink_entry = 0xdf61b3ed0ad2e, llt_fill_sa_entry = 0x388ec15688a8057, llt_free_tbl = 0x0}
Comment 2 Hans Petter Selasky freebsd_committer freebsd_triage 2018-02-15 17:34:55 UTC
Is this related to:

https://reviews.freebsd.org/D4605

--HPS
Comment 3 Hans Petter Selasky freebsd_committer freebsd_triage 2018-02-15 17:36:04 UTC
Can you try the patch in D4605 ?
Comment 4 Andrey V. Elsukov freebsd_committer freebsd_triage 2018-02-16 10:33:34 UTC
(In reply to Hans Petter Selasky from comment #3)
> Can you try the patch in D4605 ?

This problem is not easy to trigger and I'm not sure that the patch solves it.
I think how it happens:
on ifnet departure in6_domifdetach() is called, then lltable_free() unlinks lltable and acquires LLE_WLOCK for each llentry. While we are acquiring all these locks it is possible, that callout for some entry has been started and blocked on the LLE_WLOCK() since lock is held by lltable_free(). Then llentry_free() releases LLE_WLOCK(), and nd6_llinfo_timer() acquires it. Now we have invalid ifp pointer, it is strange enough that it is NULL...

About your patch, it seems the code:
 
  if (callout_stop(&lle->lle_timer) > 0)
      LLE_REMREF(lle);

can be placed in the llentry_free() only once, and also removed from lltable_free(). But it doesn't protect from described scenario. I think we need somehow handle the case when nd6_llinfo_timer() is already active, but it hasn't obtained lock yet.
Comment 5 Hans Petter Selasky freebsd_committer freebsd_triage 2018-02-16 11:15:32 UTC
There is a generic problem in the LLE code (IPv4 and IPv6) that it cannot sleep to drain the timers. In case an active timer is detected after callout_stop(), then the LL entry should be put on a taskqueue and callout_drain() _must_ be used for sane operation.
Comment 6 Hans Petter Selasky freebsd_committer freebsd_triage 2018-02-16 11:16:03 UTC
I agree about your suggestion to move callout stop to a central place.
Comment 7 Andrey V. Elsukov freebsd_committer freebsd_triage 2018-02-16 11:25:13 UTC
For now I'll try this patch with your D4605.

@@ -780,8 +778,13 @@ nd6_llinfo_timer(void *arg)
                CURVNET_RESTORE();
                return;
        }
-       ndi = ND_IFINFO(ifp);
        send_ns = 0;
+       /*
+        * Check that entry is still linked to LLE table.
+        */
+       if ((ln->la_flags & LLE_LINKED) == 0)
+               goto done;
+       ndi = ND_IFINFO(ifp);
        dst = &ln->r_l3addr.addr6;
        pdst = dst;
Comment 8 Kajetan Staszkiewicz 2018-07-16 15:54:46 UTC
Is there any progress on this issue? Does the proposed patch really help? I had a similar stacktrace (no debug information though, sorry) when destroying a VLAN interface running some badly misconfigured (See bug 229384) carp IP addresses.
Comment 9 Andrey V. Elsukov freebsd_committer freebsd_triage 2018-07-17 10:32:10 UTC
(In reply to Kajetan Staszkiewicz from comment #8)
> Is there any progress on this issue? Does the proposed patch really help? I
> had a similar stacktrace (no debug information though, sorry) when
> destroying a VLAN interface running some badly misconfigured (See bug
> 229384) carp IP addresses.

We have not seen such panic since then. But there were many changes regarding to locking in the network stack in CURRENT, and probably this patch now needs some changes. I'll take a look at this problem.
Comment 10 commit-hook freebsd_committer freebsd_triage 2018-07-17 11:34:08 UTC
A commit references this bug:

Author: ae
Date: Tue Jul 17 11:33:24 UTC 2018
New revision: 336405
URL: https://svnweb.freebsd.org/changeset/base/336405

Log:
  Move invoking of callout_stop(&lle->lle_timer) into llentry_free().

  This deduplicates the code a bit, and also implicitly adds missing
  callout_stop() to in[6]_lltable_delete_entry() functions.

  PR:		209682, 225927
  Submitted by:	hselasky (previous version)
  MFC after:	2 weeks
  Differential Revision:	https://reviews.freebsd.org/D4605

Changes:
  head/sys/net/if_llatbl.c
  head/sys/netinet/in.c
  head/sys/netinet6/in6.c
Comment 11 Kubilay Kocak freebsd_committer freebsd_triage 2018-07-18 09:54:12 UTC
Assign to committer resolving
Comment 12 commit-hook freebsd_committer freebsd_triage 2018-08-08 16:10:16 UTC
A commit references this bug:

Author: ae
Date: Wed Aug  8 16:09:29 UTC 2018
New revision: 337460
URL: https://svnweb.freebsd.org/changeset/base/337460

Log:
  MFC r336405:
    Move invoking of callout_stop(&lle->lle_timer) into llentry_free().

    This deduplicates the code a bit, and also implicitly adds missing
    callout_stop() to in[6]_lltable_delete_entry() functions.

    PR:		209682, 225927

Changes:
_U  stable/11/
  stable/11/sys/net/if_llatbl.c
  stable/11/sys/netinet/in.c
  stable/11/sys/netinet6/in6.c