Re: fork_findpid() - Fatal trap 12: page fault while in kernel mode

Konstantin Belousov <kostikbel_at_gmail.com> wrote:

> On Tue, Dec 15, 2015 at 05:42:38PM +0100, Fabian Keil wrote:
> > I've seen the following panic a couple of times in the last three
> > months, usually while poudriere was running and with sh being the
> > current process.
> > 
> > This one is from a system based on r290926 running with
> > kern.randompid=9001 and forking frequently (>1000 forks/second)
> > due to poudriere and afl-fuzz:
> > 
> > Fatal trap 12: page fault while in kernel mode
> > cpuid = 1; apic id = 04
> > fault virtual address   = 0x618b00a8
> > fault code              = supervisor read data, page not present
> > instruction pointer     = 0x20:0xffffffff80909158
> > stack pointer           = 0x28:0xfffffe011e03b940
> > frame pointer           = 0x28:0xfffffe011e03b960
> > code segment            = base 0x0, limit 0xfffff, type 0x1b
> >                         = DPL 0, pres 1, long 1, def32 0, gran 1
> > processor eflags        = interrupt enabled, resume, IOPL = 0
> > current process         = 71325 (sh)
> > trap number             = 12
> > panic: page fault
> > cpuid = 1
> > KDB: stack backtrace:
> > [...]
> > Uptime: 13d20h43m20s
> > [...]
> > (kgdb) where
> > #0  doadump (textdump=1) at pcpu.h:221
> > #1  0xffffffff8094a923 in kern_reboot (howto=260) at /usr/src/sys/kern/kern_shutdown.c:364
> > #2  0xffffffff8094ae8b in vpanic (fmt=<value optimized out>, ap=<value optimized out>) at /usr/src/sys/kern/kern_shutdown.c:757
> > #3  0xffffffff8094acc3 in panic (fmt=0x0) at /usr/src/sys/kern/kern_shutdown.c:688
> > #4  0xffffffff80c2fbb1 in trap_fatal (frame=<value optimized out>, eva=<value optimized out>) at /usr/src/sys/amd64/amd64/trap.c:834
> > #5  0xffffffff80c2fda4 in trap_pfault (frame=0xfffffe011e03b890, usermode=<value optimized out>) at /usr/src/sys/amd64/amd64/trap.c:684
> > #6  0xffffffff80c2f55e in trap (frame=0xfffffe011e03b890) at /usr/src/sys/amd64/amd64/trap.c:435
> > #7  0xffffffff80c120a7 in calltrap () at /usr/src/sys/amd64/amd64/exception.S:234
> > #8  0xffffffff80909158 in fork_findpid (flags=<value optimized out>) at /usr/src/sys/kern/kern_fork.c:281  
> It is the values of *p and *(p->p_pgrp) that are needed, from the frame 8.

Unfortunately it's not available and apparently I removed the attempts
to get it from the previous output.

#8  0xffffffff80909158 in fork_findpid (flags=<value optimized out>) at /usr/src/sys/kern/kern_fork.c:281
warning: Source file is more recent than executable.

281                                 (p->p_pgrp != NULL &&
Current language:  auto; currently minimal
(kgdb) p p
No symbol "p" in current context.
(kgdb)  p trypid
$1 = <value optimized out>
(kgdb)  p pidchecked
$2 = 99999
(kgdb) p lastpid
$3 = 51281

allproc is available and the first one matches lastpid and has an invalid
p_pgrp, but due to trypid being optimized out as well, it's not obvious
(to me) that it's the right process.

(kgdb)  p *allproc->lh_first
$4 = {p_list = {le_next = 0xfffff800a99e4548, le_prev = 0xffffffff813f3cc8}, p_threads = {tqh_first = 0xfffff801162819a0, tqh_last = 0xfffff801162819b0}, p_slock = {lock_object = {
      lo_name = 0xffffffff80e22449 "process slock", lo_flags = 537067520, lo_data = 0, lo_witness = 0x0}, mtx_lock = 4}, p_ucred = 0xfffff8009d070000, p_fd = 0x0, p_fdtol = 0x0, p_stats = 0xfffff800299e5800, 
  p_limit = 0x0, p_limco = {c_links = {le = {le_next = 0x0, le_prev = 0x0}, sle = {sle_next = 0x0}, tqe = {tqe_next = 0x0, tqe_prev = 0x0}}, c_time = 0, c_precision = 0, c_arg = 0x0, c_func = 0, 
    c_lock = 0xfffff800304df120, c_flags = 0, c_iflags = 0, c_cpu = 0}, p_sigacts = 0x0, p_flag = 268443648, p_flag2 = 0, p_state = PRS_NEW, p_pid = 51281, p_hash = {le_next = 0x0, 
    le_prev = 0xfffffe0000c8a288}, p_pglist = {le_next = 0x0, le_prev = 0xfffff800aa94d618}, p_pptr = 0xfffff800aa94d548, p_sibling = {le_next = 0x0, le_prev = 0xfffff800aa94d640}, p_children = {
    lh_first = 0x0}, p_reaper = 0xfffff800029a5548, p_reaplist = {lh_first = 0x0}, p_reapsibling = {le_next = 0xfffff8007e713548, le_prev = 0xfffff80023df1110}, p_mtx = {lock_object = {
      lo_name = 0xffffffff80e2243c "process lock", lo_flags = 558039040, lo_data = 0, lo_witness = 0x0}, mtx_lock = 18446735280470265856}, p_statmtx = {lock_object = {lo_name = 0xffffffff80e22457 "pstatl", 
      lo_flags = 537067520, lo_data = 0, lo_witness = 0x0}, mtx_lock = 4}, p_itimmtx = {lock_object = {lo_name = 0xffffffff80e2245e "pitiml", lo_flags = 537067520, lo_data = 0, lo_witness = 0x0}, 
    mtx_lock = 4}, p_profmtx = {lock_object = {lo_name = 0xffffffff80e22465 "pprofl", lo_flags = 537067520, lo_data = 0, lo_witness = 0x0}, mtx_lock = 4}, p_ksi = 0xfffff80126950380, p_sigqueue = {
    sq_signals = {__bits = 0xfffff800304df1a8}, sq_kill = {__bits = 0xfffff800304df1b8}, sq_list = {tqh_first = 0x0, tqh_last = 0xfffff800304df1c8}, sq_proc = 0xfffff800304df000, sq_flags = 1}, p_oppid = 0, 
  p_vmspace = 0x0, p_swtick = 3344683412, p_cowgen = 0, p_realtimer = {it_interval = {tv_sec = 0, tv_usec = 0}, it_value = {tv_sec = 0, tv_usec = 0}}, p_ru = {ru_utime = {tv_sec = 0, tv_usec = 0}, ru_stime = {
      tv_sec = 0, tv_usec = 0}, ru_maxrss = 0, ru_ixrss = 0, ru_idrss = 0, ru_isrss = 0, ru_minflt = 63, ru_majflt = 0, ru_nswap = 0, ru_inblock = 1, ru_oublock = 1, ru_msgsnd = 0, ru_msgrcv = 0, 
    ru_nsignals = 0, ru_nvcsw = 2, ru_nivcsw = 3}, p_rux = {rux_runtime = 1704892, rux_uticks = 0, rux_sticks = 0, rux_iticks = 0, rux_uu = 0, rux_su = 0, rux_tu = 0}, p_crux = {rux_runtime = 0, 
    rux_uticks = 0, rux_sticks = 0, rux_iticks = 0, rux_uu = 0, rux_su = 0, rux_tu = 0}, p_profthreads = 0, p_exitthreads = 0, p_traceflag = 0, p_tracevp = 0x0, p_tracecred = 0x0, p_textvp = 0x0, p_lock = 0, 
  p_sigiolst = {slh_first = 0x0}, p_sigparent = 20, p_sig = 0, p_code = 0, p_stops = 0, p_stype = 0, p_step = 0 '\0', p_pfsflags = 0 '\0', p_nlminfo = 0x0, p_aioinfo = 0x0, p_singlethread = 0x0, 
  p_suspcount = 0, p_xthread = 0xfffff801162819a0, p_boundary_count = 0, p_pendingcnt = 0, p_itimers = 0x0, p_procdesc = 0x0, p_treeflag = 0, p_magic = 3203398350, p_osrel = 1100090, 
  p_comm = 0xfffff800304df3c4 "privoxy", p_pgrp = 0x618b0080, p_sysent = 0xffffffff8118f9f8, p_args = 0x0, p_cpulimit = 9223372036854775807, p_nice = 0 '\0', p_fibnum = 0, p_reapsubtree = 28, p_xexit = 0, 
  p_xsig = 0, p_klist = {kl_list = {slh_first = 0x0}, kl_lock = 0xffffffff808fc960 <knlist_mtx_lock>, kl_unlock = 0xffffffff808fc9c0 <knlist_mtx_unlock>, 
    kl_assert_locked = 0xffffffff808fca30 <knlist_mtx_assert_locked>, kl_assert_unlocked = 0xffffffff808fca40 <knlist_mtx_assert_unlocked>, kl_lockarg = 0xfffff800304df120}, p_numthreads = 1, p_md = {
    md_ldt = 0x0, md_ldt_sd = {sd_lolimit = 0, sd_lobase = 0, sd_type = 0, sd_dpl = 0, sd_p = 0, sd_hilimit = 0, sd_xx0 = 0, sd_gran = 0, sd_hibase = 0, sd_xx1 = 0, sd_mbz = 0, sd_xx2 = 0}}, p_itcallout = {
    c_links = {le = {le_next = 0x0, le_prev = 0x0}, sle = {sle_next = 0x0}, tqe = {tqe_next = 0x0, tqe_prev = 0x0}}, c_time = 0, c_precision = 0, c_arg = 0x0, c_func = 0, c_lock = 0xfffff800304df120, 
    c_flags = 0, c_iflags = 0, c_cpu = 0}, p_acflag = 1, p_peers = 0x0, p_leader = 0xfffff800304df000, p_emuldata = 0x0, p_label = 0x0, p_sched = 0xfffff800304df548, p_ktr = {stqh_first = 0x0, 
    stqh_last = 0xfffff800304df4d0}, p_mqnotifier = {lh_first = 0x0}, p_dtrace = 0xfffff80087571840, p_pwait = {cv_description = 0xffffffff80e22d2a "ppwait", cv_waiters = 0}, p_dbgwait = {
    cv_description = 0xffffffff80e22d31 "dbgwait", cv_waiters = 0}, p_prev_runtime = 0, p_racct = 0x0, p_throttled = 0 '\0', p_vm_dom_policy = {seq = 2, p = {policy = VM_POLICY_NONE, domain = -1}}, 
  p_orphan = {le_next = 0x0, le_prev = 0x0}, p_orphans = {lh_first = 0x0}}
(kgdb) p *allproc->lh_first->p_pgrp
Cannot access memory at address 0x618b0080

I've changed p's declaration to static so hopefully its value will
be available the next time the panic occurs, but it may take a while
until that happens.

Fabian