Re: Panic in sys_fstatat()

From: Steve Kargl <sgk_at_troutmask.apl.washington.edu>
Date: Thu, 14 Feb 2019 18:49:49 -0800
On Thu, Feb 14, 2019 at 12:47:26PM -0800, John Baldwin wrote:
> On 2/14/19 12:38 PM, Steve Kargl wrote:
> > On Thu, Feb 14, 2019 at 12:26:01PM -0800, John Baldwin wrote:
> >> On 2/13/19 6:47 PM, Steve Kargl wrote:
> >>> #16 0x00ff58bb in trap (frame=0x2e7b6880) at /usr/src/sys/i386/i386/trap.c:519
> >>> #17 0xffc0315d in ?? ()
> >>> #18 0x2e7b6880 in ?? ()
> >>> #19 0x00d1de64 in lookup (ndp=0x2e7b6a50)
> >>>     at /usr/src/sys/kern/vfs_lookup.c:710
> >>> #20 0x00d1d763 in namei (ndp=0x2e7b6a50) at /usr/src/sys/kern/vfs_lookup.c:487
> >>> #21 0x00d372c5 in kern_statat (td=0x3c5dc700, flag=0, fd=-100, 
> >>>     path=0x2cced08e <error: Cannot access memory at address 0x2cced08e>, 
> >>>     pathseg=UIO_USERSPACE, sbp=0x2e7b6b18, hook=0x0)
> >>>     at /usr/src/sys/kern/vfs_syscalls.c:2307
> >>> #22 0x00d37c99 in sys_fstatat (td=0x3c5dc700, uap=0x3c5dc988)
> >>>     at /usr/src/sys/kern/vfs_syscalls.c:2284
> >>> #23 0x00ff69fa in syscallenter (td=<optimized out>)
> >>>     at /usr/src/sys/i386/i386/../../kern/subr_syscall.c:135
> >>> #24 syscall (frame=0x2e7b6ce8) at /usr/src/sys/i386/i386/trap.c:1144
> >>> #25 0xffc033a7 in ?? ()
> >>> #26 0x2e7b6ce8 in ?? ()
> >>> Backtrace stopped: Cannot access memory at address 0xfbafbbbc
> >>> (kgdb) 
> >>
> >> Frame 18 is probably the root problem, though it doesn't look like kgdb is
> >> able to unwind it correctly.  Looking at frame 19 might help though.  It
> >> seems like a NULL pointer dereference when invoking VOP_LOCK.
> >>
> > 
> > I can't look at this until tonight (about 6-7 hours).
> > Anything in frame 19 that you would be particularly
> > interested in?
> 
> Just what source line it is and what the value of the arguments passed to the
> function it is calling are.  Probably it's vn_lock() or VOP_LOCK() and it's
> most likely the 'vp' that is NULL, but it would be good to see all the args
> passed to the function if possible.
> 

I can make kernel.debug and vmcore.0 available on freefall
if that would help someone look this over.

__curthread () at ./machine/pcpu.h:226
226             __asm("movl %%fs:%1,%0" : "=r" (td)
(kgdb) frame 19
#19 0x00d1de64 in lookup (ndp=0x2e7b6a50) at /usr/src/sys/kern/vfs_lookup.c:710
710             vn_lock(dp,
(kgdb) list
705              * we adjust based on the requesting flags.
706              */
707             cnp->cn_lkflags = LK_SHARED;
708             dp = ndp->ni_startdir;
709             ndp->ni_startdir = NULLVP;
710             vn_lock(dp,
711                 compute_cn_lkflags(dp->v_mount, cnp->cn_lkflags | LK_RETRY,
712                 cnp->cn_flags));
713
714     dirloop:
(kgdb) p *cnp
$1 = {cn_nameiop = 0, cn_flags = 67109188, cn_thread = 0x3c5dc700, 
  cn_cred = 0x2fd5b300, cn_lkflags = 2097152, 
  cn_pnbuf = 0x181dac00 "/usr/home/kargl/.mozilla/seamonkey/565lcgtb.default/cert9.db-journal", 
  cn_nameptr = 0x181dac01 "usr/home/kargl/.mozilla/seamonkey/565lcgtb.default/cert9.db-journal", cn_namelen = 18180272}
(kgdb) p *cnp->cn_thread
$3 = {td_lock = 0x133e76c <sched_lock>, td_proc = 0x2f6f9a08, td_plist = {
    tqe_next = 0x3c5f2000, tqe_prev = 0x333ac708}, td_runq = {tqe_next = 0x0, 
    tqe_prev = 0x133ece0 <runq_pcpu+856>}, td_slpq = {tqe_next = 0x0, 
    tqe_prev = 0x8dd34c0}, td_lockq = {tqe_next = 0x0, tqe_prev = 0x2e5d99d0}, 
  td_hash = {le_next = 0x0, le_prev = 0x8b6f0d0}, td_cpuset = 0x8b74f80, 
  td_domain = {dr_policy = 0x132c1c0 <domainset0>, dr_iter = 0}, 
  td_sel = 0x31e94500, td_sleepqueue = 0x8dd34c0, td_turnstile = 0x8dd7900, 
  td_rlqe = 0x183adefc, td_umtxq = 0x2eac6000, td_tid = 100404, td_sigqueue = {
    sq_signals = {__bits = {0, 0, 0, 0}}, sq_kill = {__bits = {0, 0, 0, 0}}, 
    sq_ptrace = {__bits = {0, 0, 0, 0}}, sq_list = {tqh_first = 0x0, 
      tqh_last = 0x3c5dc784}, sq_proc = 0x2f6f9a08, sq_flags = 1}, 
  td_lend_user_pri = 255 '\377', td_epochnest = 0 '\000', td_flags = 16842756, 
  td_inhibitors = 0, td_pflags = 0, td_dupfd = 0, td_sqqueue = 0, 
  td_wchan = 0x0, td_wmesg = 0x0, td_owepreempt = 0 '\000', 
  td_tsqueue = 0 '\000', td_locks = 0, td_rw_rlocks = 0, td_sx_slocks = 0, 
  td_lk_slocks = 0, td_stopsched = 1, td_blocked = 0x0, td_lockname = 0x0, 
  td_contested = {lh_first = 0x0}, td_sleeplocks = 0x0, 
  td_intr_nesting_level = 0, td_pinned = 1, td_ucred = 0x2fd5b300, 
  td_limit = 0x2f4e0300, td_slptick = 0, td_blktick = 0, 
  td_swvoltick = -2027751151, td_swinvoltick = -2027751162, td_cow = 414, 
  td_ru = {ru_utime = {tv_sec = 0, tv_usec = 0}, ru_stime = {tv_sec = 0, 
      tv_usec = 0}, ru_maxrss = 766720, ru_ixrss = 2820160, ru_idrss = 80576, 
    ru_isrss = 12122624, ru_minflt = 6983, ru_majflt = 0, ru_nswap = 0, 
    ru_inblock = 0, ru_oublock = 0, ru_msgsnd = 4421, ru_msgrcv = 36987, 
    ru_nsignals = 0, ru_nvcsw = 18339, ru_nivcsw = 78866}, td_rux = {
    rux_runtime = 313960691210, rux_uticks = 17521, rux_sticks = 2521, 
    rux_iticks = 0, rux_uu = 0, rux_su = 0, rux_tu = 0}, 
  td_incruntime = 1647457400, td_runtime = 315608148610, td_pticks = 0, 
  td_sticks = 16, td_iticks = 0, td_uticks = 86, td_intrval = 0, 
  td_oldsigmask = {__bits = {0, 0, 0, 0}}, td_generation = 97205, td_sigstk = {
    ss_sp = 0x0, ss_size = 0, ss_flags = 0}, td_xsig = 0, td_profil_addr = 0, 
  td_profil_ticks = 0, td_name = "Socket Thread\000\000\000\000\000\000", 
  td_fpop = 0x0, td_dbgflags = 0, td_si = {si_signo = 0, si_errno = 0, 
    si_code = 0, si_pid = 0, si_uid = 0, si_status = 0, si_addr = 0x0, 
    si_value = {sival_int = 0, sival_ptr = 0x0, sigval_int = 0, 
      sigval_ptr = 0x0}, _reason = {_fault = {_trapno = 0}, _timer = {
        _timerid = 0, _overrun = 0}, _mesgq = {_mqd = 0}, _poll = {_band = 0}, 
      __spare__ = {__spare1__ = 0, __spare2__ = {0, 0, 0, 0, 0, 0, 0}}}}, 
  td_ng_outbound = 0, td_osd = {osd_nslots = 0, osd_slots = 0x0, osd_next = {
      le_next = 0x0, le_prev = 0x0}}, td_map_def_user = 0x0, 
  td_dbg_forked = 0, td_vp_reserv = 0, td_no_sleeping = 0, td_su = 0x0, 
  td_sleeptimo = 0, td_rtcgen = 0, td_vslock_sz = 0, td_kcov_info = 0x0, 
  td_sigmask = {__bits = {0, 0, 0, 0}}, td_rqindex = 41 ')', 
  td_base_pri = 165 '\245', td_priority = 165 '\245', td_pri_class = 3 '\003', 
  td_user_pri = 165 '\245', td_base_user_pri = 165 '\245', 
  td_pre_epoch_prio = 166 '\246', td_rb_list = 0, td_rbp_list = 0, 
  td_rb_inact = 0, td_sa = {code = 552, callp = 0x114b09c <sysent+17664>, 
    args = {-100, 751751310, -72369208, 0, 0, 0, 0, 0}, narg = 4}, 
  td_pcb = 0x2e7b6d40, td_state = TDS_RUNNING, td_uretoff = {tdu_retval = {0, 
      -72368928}, tdu_off = -310822179006578688}, td_cowgen = 0, 
  td_slpcallout = {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 = 0x0, c_lock = 0x0, c_flags = 0, 
    c_iflags = 16, c_cpu = 0}, td_frame = 0x2e7b6ce8, 
  td_kstack_obj = 0x33e38a5c, td_kstack = 779825152, td_kstack_pages = 4, 
  td_critnest = 1, td_md = {md_spinlock_count = 1, md_saved_flags = 2097734, 
    md_spurflt_addr = 0}, td_ar = 0x0, td_lprof = {{lh_first = 0x0}, {
      lh_first = 0x0}}, td_dtrace = 0x2ea40e00, td_errno = 0, td_vnet = 0x0, 
  td_vnet_lpush = 0x0, td_intr_frame = 0x0, td_rfppwait_p = 0x0, td_ma = 0x0, 
  td_ma_cnt = 0, td_emuldata = 0x0, td_lastcpu = 1, td_oncpu = 1, 
  td_lkpi_task = 0x0, td_et = 0x1810b270, td_pmcpend = 0}
(kgdb) p *dp
$4 = {v_tag = 0x103c325 "ufs", v_op = 0x1187054 <ffs_vnodeops2>, 
  v_data = 0x183689f8, v_mount = 0x18364000, v_nmntvnodes = {
    tqe_next = 0x1836a000, tqe_prev = 0x37c9d7f0}, {v_mountedhere = 0x0, 
    v_unpcb = 0x0, v_rdev = 0x0, v_fifoinfo = 0x0}, v_hashlist = {
    le_next = 0x0, le_prev = 0x3577849c}, v_cache_src = {
    lh_first = 0x373b8240}, v_cache_dst = {tqh_first = 0x0, 
    tqh_last = 0x1836a148}, v_cache_dd = 0x0, v_lock = {lock_object = {
      lo_name = 0x103c325 "ufs", lo_flags = 117112832, lo_data = 0, 
      lo_witness = 0x0}, lk_lock = 1, lk_exslpfail = 0, lk_timo = 51, 
    lk_pri = 96}, v_interlock = {lock_object = {
      lo_name = 0x10b8f99 "vnode interlock", lo_flags = 16973824, lo_data = 0, 
      lo_witness = 0x0}, mtx_lock = 0}, v_vnlock = 0x1836a154, 
  v_actfreelist = {tqe_next = 0x0, tqe_prev = 0x1836a06c}, v_bufobj = {
    bo_lock = {lock_object = {lo_name = 0x109e1b0 "bufobj interlock", 
        lo_flags = 86179840, lo_data = 0, lo_witness = 0x0}, rw_lock = 1}, 
    bo_ops = 0x115c6d8 <buf_ops_bio>, bo_object = 0x8de01d4, bo_synclist = {
      le_next = 0x0, le_prev = 0x8c2d6fc}, bo_private = 0x1836a120, 
    bo_clean = {bv_hd = {tqh_first = 0x8a2f950, tqh_last = 0x8a2f994}, 
      bv_root = {pt_root = 144898533}, bv_cnt = 1}, bo_dirty = {bv_hd = {
        tqh_first = 0x0, tqh_last = 0x1836a1cc}, bv_root = {pt_root = 0}, 
      bv_cnt = 0}, bo_numoutput = 0, bo_flag = 0, bo_domain = 0, 
    bo_bsize = 32768}, v_pollinfo = 0x0, v_label = 0x0, v_lockf = 0x0, v_rl = {
    rl_waiters = {tqh_first = 0x0, tqh_last = 0x1836a1f8}, rl_currdep = 0x0}, 
  v_cstart = 0, v_lasta = 0, v_lastw = 0, v_clen = 0, v_holdcnt = 97, 
  v_usecount = 94, v_iflag = 512, v_vflag = 1, v_mflag = 0, v_writecount = 0, 
  v_hash = 2, v_type = VDIR}
(kgdb) p *dp->v_mount
$5 = {mnt_mtx = {lock_object = {lo_name = 0x102f1e1 "struct mount mtx", 
      lo_flags = 16973824, lo_data = 0, lo_witness = 0x0}, mtx_lock = 0}, 
  mnt_gen = 1, mnt_list = {tqe_next = 0x181d3000, 
    tqe_prev = 0x1167ed4 <mountlist>}, mnt_op = 0x1186cac <ufs_vfsops>, 
  mnt_vfc = 0x1186d44 <ufs_vfsconf>, mnt_vnodecovered = 0x0, 
  mnt_syncer = 0x183e16c0, mnt_ref = 116920, mnt_nvnodelist = {
    tqh_first = 0x3559b5a0, tqh_last = 0x3230db50}, 
  mnt_nvnodelistsize = 116920, mnt_writeopcount = 0, 
  mnt_kern_flag = 1082155332, mnt_flag = 4294987776, mnt_opt = 0x887f760, 
  mnt_optnew = 0x0, mnt_maxsymlinklen = 120, mnt_stat = {
    f_version = 538182936, f_type = 53, f_flags = 4294987776, f_bsize = 4096, 
    f_iosize = 32768, f_blocks = 27420863, f_bfree = 19467160, 
    f_bavail = 17273491, f_files = 14205310, f_ffree = 13031599, 
    f_syncwrites = 125736, f_asyncwrites = 1574684, f_syncreads = 797814, 
    f_asyncreads = 50806, f_spare = {0, 0, 0, 0, 0, 0, 0, 0, 0, 0}, 
    f_namemax = 255, f_owner = 0, f_fsid = {val = {1526655831, -370706533}}, 
    f_charspare = '\000' <repeats 79 times>, 
    f_fstypename = "ufs", '\000' <repeats 12 times>, 
    f_mntfromname = "/dev/ada0s1a", '\000' <repeats 1011 times>, 
    f_mntonname = "/", '\000' <repeats 1022 times>}, mnt_cred = 0x9338a00, 
  mnt_data = 0x8de5400, mnt_time = 1549991399, mnt_iosize_max = 131072, 
  mnt_export = 0x0, mnt_label = 0x0, mnt_hashseed = 558371606, 
  mnt_lockref = 0, mnt_secondary_writes = 0, 
  mnt_secondary_accwrites = 16615928, mnt_susp_owner = 0x0, 
  mnt_gjprovider = 0x0, mnt_listmtx = {lock_object = {
      lo_name = 0x1068b01 "struct mount vlist mtx", lo_flags = 16973824, 
      lo_data = 0, lo_witness = 0x0}, mtx_lock = 0}, mnt_activevnodelist = {
    tqh_first = 0x3230db40, tqh_last = 0x1836a18c}, 
  mnt_activevnodelistsize = 81818, mnt_tmpfreevnodelist = {
    tqh_first = 0x37bda120, tqh_last = 0x3465a4ec}, 
  mnt_tmpfreevnodelistsize = 46, mnt_explock = {lock_object = {
      lo_name = 0x107dd9e "explock", lo_flags = 108199936, lo_data = 0, 
      lo_witness = 0x0}, lk_lock = 1, lk_exslpfail = 0, lk_timo = 0, 
    lk_pri = 96}, mnt_upper_link = {tqe_next = 0x0, tqe_prev = 0x0}, 
  mnt_uppers = {tqh_first = 0x0, tqh_last = 0x18364a08}}


-- 
Steve
Received on Fri Feb 15 2019 - 01:49:58 UTC

This archive was generated by hypermail 2.4.0 : Wed May 19 2021 - 11:41:20 UTC