From https://ci.freebsd.org/job/FreeBSD-head-amd64-test/9853/console : 03:41:28 sys/netpfil/pf/fragmentation:too_many_fragments -> passed [11.324s] 03:41:40 sys/netpfil/pf/fragmentation:v6 -> passed [0.215s] 03:41:40 sys/netpfil/pf/names:names -> passed [0.165s] 03:41:40 sys/netpfil/pf/nat:exhaust -> lock order reversal: 03:41:43 1st 0xfffff8013181a490 filedesc structure (filedesc structure) @ /usr/src/sys/kern/sys_generic.c:1515 03:41:43 2nd 0xfffff80131b3e608 ufs (ufs) @ /usr/src/sys/kern/vfs_vnops.c:1513 03:41:43 stack backtrace: 03:41:43 #0 0xffffffff80c44c13 at witness_debugger+0x73 03:41:43 #1 0xffffffff80c44963 at witness_checkorder+0xac3 03:41:43 #2 0xffffffff80bb186d at lockmgr_xlock_hard+0x6d 03:41:43 #3 0xffffffff80bb2303 at __lockmgr_args+0x5f3 03:41:43 #4 0xffffffff80eeeaf5 at ffs_lock+0xa5 03:41:43 #5 0xffffffff81234703 at VOP_LOCK1_APV+0x63 03:41:43 #6 0xffffffff80cbfe25 at _vn_lock+0x65 03:41:43 #7 0xffffffff80cbec3a at vn_poll+0x3a 03:41:43 #8 0xffffffff80c4b06a at kern_poll+0x3ca 03:41:43 #9 0xffffffff80c4ac90 at sys_poll+0x50 03:41:43 #10 0xffffffff810abe96 at amd64_syscall+0x276 03:41:43 #11 0xffffffff81085f7d at fast_syscall_common+0x101 03:41:44 passed [3.421s] 03:41:44 sys/netpfil/pf/pass_block:noalias -> Jan 21 03:41:45 kernel: nd6_dad_timer: called with non-tentative address fe80:3::5a:1bff:fe50:80b(epair3b) 03:41:46 Jan 21 03:41:46 kernel: nd6_dad_timer: called with non-tentative address fe80:5::5a:1bff:fe50:80a(epair3a) 03:41:48 panic: Memory modified after free 0xfffffe003ee0c080(8) val=deadc0df @ 0xfffffe003ee0c080 03:41:48 03:41:48 cpuid = 1 03:41:48 time = 1548042108 03:41:48 KDB: stack backtrace: 03:41:48 db_trace_self_wrapper() at db_trace_self_wrapper+0x2b/frame 0xfffffe003f2f4030 03:41:48 vpanic() at vpanic+0x1b4/frame 0xfffffe003f2f4090 03:41:48 panic() at panic+0x43/frame 0xfffffe003f2f40f0 03:41:48 trash_ctor() at trash_ctor+0x4c/frame 0xfffffe003f2f4100 03:41:48 uma_zalloc_arg() at uma_zalloc_arg+0x9ff/frame 0xfffffe003f2f4190 03:41:48 uma_zalloc_pcpu_arg() at uma_zalloc_pcpu_arg+0x23/frame 0xfffffe003f2f41c0 03:41:48 pfioctl() at pfioctl+0x419e/frame 0xfffffe003f2f46b0 03:41:48 devfs_ioctl() at devfs_ioctl+0xca/frame 0xfffffe003f2f4700 03:41:48 VOP_IOCTL_APV() at VOP_IOCTL_APV+0x63/frame 0xfffffe003f2f4720 03:41:48 vn_ioctl() at vn_ioctl+0x124/frame 0xfffffe003f2f4830 03:41:48 devfs_ioctl_f() at devfs_ioctl_f+0x1f/frame 0xfffffe003f2f4850 03:41:48 kern_ioctl() at kern_ioctl+0x29b/frame 0xfffffe003f2f48c0 03:41:48 sys_ioctl() at sys_ioctl+0x15d/frame 0xfffffe003f2f4990 03:41:48 amd64_syscall() at amd64_syscall+0x276/frame 0xfffffe003f2f4ab0 03:41:48 fast_syscall_common() at fast_syscall_common+0x101/frame 0xfffffe003f2f4ab0 03:41:48 --- syscall (54, FreeBSD ELF64, sys_ioctl), rip = 0x8004b02fa, rsp = 0x7fffffffcc38, rbp = 0x7fffffffd860 --- 03:41:48 KDB: enter: panic 03:41:48 [ thread pid 81820 tid 100186 ] 03:41:48 Stopped at kdb_enter+0x3b: movq $0,kdb_why 03:41:48 db:0:kdb.enter.panic> show pcpu 03:41:48 cpuid = 1 03:41:48 dynamic pcpu = 0xfffffe00801938c0 03:41:48 curthread = 0xfffff801317f55a0: pid 81820 tid 100186 "pfctl" 03:41:48 curpcb = 0xfffffe003f2f4b80 03:41:48 fpcurthread = 0xfffff801317f55a0: pid 81820 "pfctl" 03:41:48 idlethread = 0xfffff8000327b5a0: tid 100004 "idle: cpu1" 03:41:48 curpmap = 0xfffff80028f45130 03:41:48 tssp = 0xffffffff821cb208 03:41:48 commontssp = 0xffffffff821cb208 03:41:48 rsp0 = 0xfffffe003f2f4b80 03:41:48 gs32p = 0xffffffff821d1e40 03:41:48 ldt = 0xffffffff821d1e80 03:41:48 tss = 0xffffffff821d1e70 03:41:48 tlb gen = 466083 03:41:48 curvnet = 0xfffff800032e7a80 03:41:48 spin locks held: 03:41:48 db:0:kdb.enter.panic> alltrace 03:41:48 03:41:48 Tracing command pfctl pid 81820 tid 100186 td 0xfffff801317f55a0 (CPU 1) 03:41:48 kdb_enter() at kdb_enter+0x3b/frame 0xfffffe003f2f4030 03:41:48 vpanic() at vpanic+0x1d1/frame 0xfffffe003f2f4090 03:41:48 panic() at panic+0x43/frame 0xfffffe003f2f40f0 03:41:48 trash_ctor() at trash_ctor+0x4c/frame 0xfffffe003f2f4100 03:41:48 uma_zalloc_arg() at uma_zalloc_arg+0x9ff/frame 0xfffffe003f2f4190 03:41:48 uma_zalloc_pcpu_arg() at uma_zalloc_pcpu_arg+0x23/frame 0xfffffe003f2f41c0 03:41:48 pfioctl() at pfioctl+0x419e/frame 0xfffffe003f2f46b0 03:41:48 devfs_ioctl() at devfs_ioctl+0xca/frame 0xfffffe003f2f4700 03:41:48 VOP_IOCTL_APV() at VOP_IOCTL_APV+0x63/frame 0xfffffe003f2f4720 03:41:49 vn_ioctl() at vn_ioctl+0x124/frame 0xfffffe003f2f4830 03:41:49 devfs_ioctl_f() at devfs_ioctl_f+0x1f/frame 0xfffffe003f2f4850 03:41:49 kern_ioctl() at kern_ioctl+0x29b/frame 0xfffffe003f2f48c0 03:41:49 sys_ioctl() at sys_ioctl+0x15d/frame 0xfffffe003f2f4990 03:41:49 amd64_syscall() at amd64_syscall+0x276/frame 0xfffffe003f2f4ab0 03:41:49 fast_syscall_common() at fast_syscall_common+0x101/frame 0xfffffe003f2f4ab0 03:41:49 --- syscall (54, FreeBSD ELF64, sys_ioctl), rip = 0x8004b02fa, rsp = 0x7fffffffcc38, rbp = 0x7fffffffd860 ---
I'm also checking this one, it seems started from r341998 or r341999, although I cannot have a reliable way to reproduce it.
It seems to be pretty non-deterministic. I've just now produced this panic: panic: Memory modified after free 0xfffffe00a4442ac0(8) val=deadc0df @ 0xfffffe00a4442ac0 cpuid = 4 time = 1548105766 KDB: stack backtrace: db_trace_self_wrapper() at db_trace_self_wrapper+0x2b/frame 0xfffffe009ddff2d0 vpanic() at vpanic+0x1b4/frame 0xfffffe009ddff330 panic() at panic+0x43/frame 0xfffffe009ddff390 trash_ctor() at trash_ctor+0x4c/frame 0xfffffe009ddff3a0 uma_zalloc_arg() at uma_zalloc_arg+0x9ff/frame 0xfffffe009ddff430 uma_zalloc_pcpu_arg() at uma_zalloc_pcpu_arg+0x23/frame 0xfffffe009ddff460 bpfopen() at bpfopen+0x8f/frame 0xfffffe009ddff4a0 devfs_open() at devfs_open+0x134/frame 0xfffffe009ddff510 VOP_OPEN_APV() at VOP_OPEN_APV+0x60/frame 0xfffffe009ddff530 vn_open_vnode() at vn_open_vnode+0x1b1/frame 0xfffffe009ddff5d0 vn_open_cred() at vn_open_cred+0x34c/frame 0xfffffe009ddff720 kern_openat() at kern_openat+0x1fd/frame 0xfffffe009ddff890 amd64_syscall() at amd64_syscall+0x276/frame 0xfffffe009ddff9b0 fast_syscall_common() at fast_syscall_common+0x101/frame 0xfffffe009ddff9b0 --- syscall (499, FreeBSD ELF64, sys_openat), rip = 0x80061e3ca, rsp = 0x7fffffffa918, rbp = 0x7fffffffa990 --- KDB: enter: panic [ thread pid 5254 tid 100499 ] Stopped at kdb_enter+0x3b: movq $0,kdb_why MY current thinking is that it's more fallout of the epochification work done recently. Something's still being used after being released and depending on the timing of that we get different panics.
(In reply to Kristof Provost from comment #2) Do the tests kldunload pf at any point? There aren't many situations where we'd destroy a counter(9).
No. The module is loaded at startup and never unloaded. The tests do instantiate and destroy vnet jails and epairs, so the exercise quite a lot of network related setup and teardown code.
(In reply to Li-Wen Hsu from comment #1) Why do you think these two revision numbers have introduced the problem? Because if they did the search pattern is very small. Just trying to understand. (In reply to Kristof Provost from comment #4) Depending on the answer above it could be anything (a x++, refcount, ..). It doesn't have to be a counter(9) increment. It could also be anywhere in the code, not necessarily the network stack where this happens. It's just that the test cases run a lot of network stack code, which means it's most likely to be the next allocation that then finds the modified memory.
I'm running into a different panic trying to reproduce this one: Fatal trap 9: general protection fault while in kernel mode cpuid = 4; apic id = 04 instruction pointer = 0x20:0xffffffff80d07e9a stack pointer = 0x28:0xfffffe0074beb6a0 frame pointer = 0x28:0xfffffe0074beb770 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 = 0 (config_0) trap number = 9 panic: general protection fault cpuid = 4 time = 1548285422 KDB: stack backtrace: db_trace_self_wrapper() at db_trace_self_wrapper+0x2b/frame 0xfffffe0074beb3b0 vpanic() at vpanic+0x1b4/frame 0xfffffe0074beb410 panic() at panic+0x43/frame 0xfffffe0074beb470 trap_fatal() at trap_fatal+0x369/frame 0xfffffe0074beb4c0 trap() at trap+0x6c/frame 0xfffffe0074beb5d0 calltrap() at calltrap+0x8/frame 0xfffffe0074beb5d0 --- trap 0x9, rip = 0xffffffff80d07e9a, rsp = 0xfffffe0074beb6a0, rbp = 0xfffffe0074beb770 --- rtsock_msg_mbuf() at rtsock_msg_mbuf+0xda/frame 0xfffffe0074beb770 rt_newmaddrmsg() at rt_newmaddrmsg+0x108/frame 0xfffffe0074beb820 if_delmulti_locked() at if_delmulti_locked+0x74/frame 0xfffffe0074beb860 if_delmulti_ifma_flags() at if_delmulti_ifma_flags+0x5f/frame 0xfffffe0074beb890 in6m_release_task() at in6m_release_task+0x30e/frame 0xfffffe0074beb8f0 gtaskqueue_run_locked() at gtaskqueue_run_locked+0xf9/frame 0xfffffe0074beb940 gtaskqueue_thread_loop() at gtaskqueue_thread_loop+0x88/frame 0xfffffe0074beb970 fork_exit() at fork_exit+0x84/frame 0xfffffe0074beb9b0 fork_trampoline() at fork_trampoline+0xe/frame 0xfffffe0074beb9b0 --- trap 0, rip = 0, rsp = 0, rbp = 0 --- KDB: enter: panic I thought that might have been fixed by mark's r 343363 fix for 234296, but that doesn't appear to be the case.
(In reply to Kristof Provost from comment #6) Could it be related to https://reviews.freebsd.org/D18887 ?
(In reply to Mark Johnston from comment #7) Your problem from comment #6 probably yes; can the mld bug be related to the use-after-free? Unlikely.
(In reply to Mark Johnston from comment #7) I've just done a run with that patch included and I see the same panic. It does need 'net.fibs=3' to trigger. That might be because the triggering test is sys/netinet/fibs_test:slaac_on_nondefault_fib6 which requires that to run.
The panic in comment #6 seems to happen because ifp->if_addr has been freed. (kgdb) fr #16 0xffffffff80d087e8 in rt_newmaddrmsg (cmd=520194696, ifma=0xfffff8000753ee00) at /usr/src/sys/net/rtsock.c:1436 1436 m = rtsock_msg_mbuf(cmd, &info); (kgdb) p info $8 = {rti_addrs = 18, rti_flags = 0, rti_info = {0x0, 0xfffff8006c4cc300, 0x0, 0x0, 0xdeadc0dedeadc0de, 0xfffff800060102a0, 0x0, 0x0}, rti_ifa = 0x0, rti_ifp = 0x0, rti_filter = 0x0, rti_filterdata = 0x0, rti_mflags = 0, rti_spare = 0, rti_rmx = 0x0} (kgdb) p *ifp->if_addr $9 = {ifa_addr = 0xdeadc0dedeadc0de, ifa_dstaddr = 0xdeadc0dedeadc0de, ifa_netmask = 0xdeadc0dedeadc0de, ifa_ifp = 0xdeadc0dedeadc0de, ifa_carp = 0xdeadc0dedeadc0de, ifa_link = {cstqe_next = 0xdeadc0dedeadc0de}, ifa_rtrequest = 0xdeadc0dedeadc0de, ifa_flags = 49374, ifa_refcnt = 3735929054, ifa_ipackets = 0xdeadc0dedeadc0de, ifa_opackets = 0xdeadc0dedeadc0de, ifa_ibytes = 0xdeadc0dedeadc0de, ifa_obytes = 0xdeadc0dedeadc0de, ifa_epoch_ctx = {data = {0xdeadc0dedeadc0de, 0xdeadc0dedeadc0de}}}
I think I understand the use-after-free bug, and it's a pf problem. Patching the counter increment code to check for 0xdeadc0dedeadc0de (and panicing) produces this backtrace: panic: Incrementing freed counter! cpuid = 0 time = 1548368229 KDB: stack backtrace: db_trace_self_wrapper() at db_trace_self_wrapper+0x2b/frame 0xfffffe00a94da210 vpanic() at vpanic+0x1b4/frame 0xfffffe00a94da270 panic() at panic+0x43/frame 0xfffffe00a94da2d0 pf_purge_expired_src_nodes() at pf_purge_expired_src_nodes+0x1f4/frame 0xfffffe00a94da320 pf_unload_vnet_purge() at pf_unload_vnet_purge+0x2b/frame 0xfffffe00a94da330 vnet_pf_uninit() at vnet_pf_uninit+0x74a/frame 0xfffffe00a94da7d0 vnet_destroy() at vnet_destroy+0x124/frame 0xfffffe00a94da800 prison_deref() at prison_deref+0x29d/frame 0xfffffe00a94da840 sys_jail_remove() at sys_jail_remove+0x28e/frame 0xfffffe00a94da890 amd64_syscall() at amd64_syscall+0x29b/frame 0xfffffe00a94da9b0 fast_syscall_common() at fast_syscall_common+0x101/frame 0xfffffe00a94da9b0 Essentially, pf frees its counters before it's all the way done cleaning up, and it can end up incrementing a counter.
The following appears to fix the panic in comment #6: diff --git a/sys/net/if.c b/sys/net/if.c index a6552f80f37..7e3e662d342 100644 --- a/sys/net/if.c +++ b/sys/net/if.c @@ -1194,6 +1195,11 @@ if_detach_internal(struct ifnet *ifp, int vmove, struct if_clone **ifcp) if (!CK_STAILQ_EMPTY(&ifp->if_addrhead)) { ifa = CK_STAILQ_FIRST(&ifp->if_addrhead); CK_STAILQ_REMOVE(&ifp->if_addrhead, ifa, ifaddr, ifa_link); + //KASSERT(ifa != ifp->if_addr, ("")); + if (ifa == ifp->if_addr) { + ifp->if_addr = NULL; + printf("KP: set ifp->if_addr to NULL\n"); + } IF_ADDR_WUNLOCK(ifp); ifa_free(ifa); } else We free the ifaddr, but we can still have a pointer to it in ifp->if_addr. This check triggers, and in several test runs with this patch I've not managed to reproduce the panic any more. I'm doing more runs, because this problem comes and goes, but I hope this will be a useful pointer to someone who knows that code better than me.
A commit references this bug: Author: kp Date: Fri Jan 25 01:06:06 UTC 2019 New revision: 343418 URL: https://svnweb.freebsd.org/changeset/base/343418 Log: pf: Fix use-after-free of counters When cleaning up a vnet we free the counters in V_pf_default_rule and V_pf_status from shutdown_pf(), but we can still use them later, for example through pf_purge_expired_src_nodes(). Free them as the very last operation, as they rely on nothing else themselves. PR: 235097 MFC after: 1 week Changes: head/sys/netpfil/pf/pf_ioctl.c
(In reply to Kristof Provost from comment #12) > The following appears to fix the panic in comment #6: > > diff --git a/sys/net/if.c b/sys/net/if.c > index a6552f80f37..7e3e662d342 100644 > --- a/sys/net/if.c > +++ b/sys/net/if.c > @@ -1194,6 +1195,11 @@ if_detach_internal(struct ifnet *ifp, int vmove, > struct if_clone **ifcp) > if (!CK_STAILQ_EMPTY(&ifp->if_addrhead)) { > ifa = CK_STAILQ_FIRST(&ifp->if_addrhead); > CK_STAILQ_REMOVE(&ifp->if_addrhead, ifa, ifaddr, > ifa_link); > + //KASSERT(ifa != ifp->if_addr, ("")); > + if (ifa == ifp->if_addr) { > + ifp->if_addr = NULL; > + printf("KP: set ifp->if_addr to NULL\n"); > + } > IF_ADDR_WUNLOCK(ifp); > ifa_free(ifa); > } else > > We free the ifaddr, but we can still have a pointer to it in ifp->if_addr. > This check triggers, and in several test runs with this patch I've not > managed to reproduce the panic any more. I'm doing more runs, because this > problem comes and goes, but I hope this will be a useful pointer to someone > who knows that code better than me. ifa_free() does not free the memory immediately, so it is safe to make access to ifp->if_addr while you are in NET_EPOCH() section.
(In reply to Andrey V. Elsukov from comment #14) > > We free the ifaddr, but we can still have a pointer to it in ifp->if_addr. > > This check triggers, and in several test runs with this patch I've not > > managed to reproduce the panic any more. I'm doing more runs, because this > > problem comes and goes, but I hope this will be a useful pointer to someone > > who knows that code better than me. > > ifa_free() does not free the memory immediately, so it is safe to make > access to ifp->if_addr while you are in NET_EPOCH() section. or while you keep the reference to if_addr, look at the history of recent changes to this code.
(In reply to Andrey V. Elsukov from comment #14) > ifa_free() does not free the memory immediately, so it is safe to make access to ifp->if_addr while you are in NET_EPOCH() section. Right, but if ifa_free() queues the release to happen after everyone who might be using it has left the NET_EPOCH() section we can still have the pointer to a freed structure around if we don't NULL out the if_addr pointer. The problem is that there are two pointers to the struct ifaddr. We remove one (from the if_addrhead list), but keep the other one around.
(In reply to Andrey V. Elsukov from comment #15) > or while you keep the reference to if_addr, look at the history of recent changes to this code. Ah, I think I see what you mean. There's a reference count as well. However, do we increment the reference count for the if_addr pointer? I seem to be overlooking that one in if_attach_internal().
A commit references this bug: Author: kp Date: Fri Feb 1 10:04:53 UTC 2019 New revision: 343652 URL: https://svnweb.freebsd.org/changeset/base/343652 Log: MFC r343418: pf: Fix use-after-free of counters When cleaning up a vnet we free the counters in V_pf_default_rule and V_pf_status from shutdown_pf(), but we can still use them later, for example through pf_purge_expired_src_nodes(). Free them as the very last operation, as they rely on nothing else themselves. PR: 235097 Changes: _U stable/12/ stable/12/sys/netpfil/pf/pf_ioctl.c
A commit references this bug: Author: kp Date: Fri Feb 1 10:04:55 UTC 2019 New revision: 343653 URL: https://svnweb.freebsd.org/changeset/base/343653 Log: MFC r343418: pf: Fix use-after-free of counters When cleaning up a vnet we free the counters in V_pf_default_rule and V_pf_status from shutdown_pf(), but we can still use them later, for example through pf_purge_expired_src_nodes(). Free them as the very last operation, as they rely on nothing else themselves. PR: 235097 Changes: _U stable/11/ stable/11/sys/netpfil/pf/pf_ioctl.c