panic during shutdown from vfs_umountall()

From: Robert Watson <rwatson_at_FreeBSD.org>
Date: Mon, 1 Dec 2003 12:29:28 -0500 (EST)
Running with a MAC kernel, about to try booting identical but non-MAC; I'm
not able to reproduceit , however.  bgfsck may have been running during
the shutdown.  Apparently the device vnode for /usr is vrele()'d one too
many times at some point during the run, resulting in a panic.  This is
with vfs_mount.c:1.116. 

Robert N M Watson             FreeBSD Core Team, TrustedBSD Projects
robert_at_fledge.watson.org      Senior Research Scientist, McAfee Research

Script started on Mon Dec  1 12:23:10 2003
GNU gdb 5.2.1 (FreeBSD)
Copyright 2002 Free Software Foundation, Inc.
GDB is free software, covered by the GNU General Public License, and you are
welcome to change it and/or distribute copies of it under certain conditions.
Type "show copying" to see the conditions.
There is absolutely no warranty for GDB.  Type "show warranty" for details.
This GDB was configured as "i386-undermydesk-freebsd"...
panic: vrele: negative ref cnt
panic messages:
---
panic: vrele: negative ref cnt
cpuid = 0; 
panic: from debugger
cpuid = 0; 
Uptime: 23h36m45s
Dumping 511 MB
 16 32 48 64 80 96 112 128 144 160 176 192 208 224 240 256 272 288 304 320 336 352 368 384 400 416 432 448 464 480 496
---
Reading symbols from /boot/kernel/snd_maestro3.ko...done.
Loaded symbols for /boot/kernel/snd_maestro3.ko
Reading symbols from /boot/kernel/snd_pcm.ko...done.
Loaded symbols for /boot/kernel/snd_pcm.ko
Reading symbols from /usr/obj/usr/src/sys/PAPRIKAMAC/modules/usr/src/sys/modules/mac_biba/mac_biba.ko.debug...done.
Loaded symbols for /usr/obj/usr/src/sys/PAPRIKAMAC/modules/usr/src/sys/modules/mac_biba/mac_biba.ko.debug
Reading symbols from /usr/obj/usr/src/sys/PAPRIKAMAC/modules/usr/src/sys/modules/mac_mls/mac_mls.ko.debug...done.
Loaded symbols for /usr/obj/usr/src/sys/PAPRIKAMAC/modules/usr/src/sys/modules/mac_mls/mac_mls.ko.debug
Reading symbols from /boot/kernel/r128.ko...done.
Loaded symbols for /boot/kernel/r128.ko
Reading symbols from /usr/obj/usr/src/sys/PAPRIKAMAC/modules/usr/src/sys/modules/linprocfs/linprocfs.ko.debug...done.
Loaded symbols for /usr/obj/usr/src/sys/PAPRIKAMAC/modules/usr/src/sys/modules/linprocfs/linprocfs.ko.debug
Reading symbols from /usr/obj/usr/src/sys/PAPRIKAMAC/modules/usr/src/sys/modules/linux/linux.ko.debug...done.
Loaded symbols for /usr/obj/usr/src/sys/PAPRIKAMAC/modules/usr/src/sys/modules/linux/linux.ko.debug
#0  doadump () at /usr/src/sys/kern/kern_shutdown.c:240
240		dumping++;
(kgdb) bt
#0  doadump () at /usr/src/sys/kern/kern_shutdown.c:240
#1  0xc06719f7 in boot (howto=260) at /usr/src/sys/kern/kern_shutdown.c:372
#2  0xc0671dfd in panic () at /usr/src/sys/kern/kern_shutdown.c:550
#3  0xc048cc82 in db_panic () at /usr/src/sys/ddb/db_command.c:450
#4  0xc048cbe2 in db_command (last_cmdp=0xc094efc0, cmd_table=0x0, 
    aux_cmd_tablep=0xc08d09cc, aux_cmd_tablep_end=0xc08d09e4)
    at /usr/src/sys/ddb/db_command.c:346
#5  0xc048cd25 in db_command_loop () at /usr/src/sys/ddb/db_command.c:472
#6  0xc048fd25 in db_trap (type=3, code=0) at /usr/src/sys/ddb/db_trap.c:73
#7  0xc082861c in kdb_trap (type=3, code=0, regs=0xd77c6b48)
    at /usr/src/sys/i386/i386/db_interface.c:171
#8  0xc083e688 in trap (frame=
      {tf_fs = 24, tf_es = -1064697840, tf_ds = 16, tf_edi = -1064617494, tf_esi = 1, tf_ebp = -679711852, tf_isp = -679711884, tf_ebx = 0, tf_edx = 0, tf_ecx = 32, tf_eax = 18, tf_trapno = 3, tf_err = 0, tf_eip = -1065187035, tf_cs = 8, tf_eflags = 642, 
tf_esp = -1064532435, tf_ss = -1064643348})
    at /usr/src/sys/i386/i386/trap.c:580
#9  0xc082a068 in calltrap () at {standard input}:94
#10 0xc0671d96 in panic (fmt=0xc08b39ea "vrele: negative ref cnt")
    at /usr/src/sys/kern/kern_shutdown.c:534
#11 0xc06cb44e in vrele () at /usr/src/sys/kern/vfs_subr.c:2221
#12 0xc07d4b18 in ffs_unmount (mp=0xc481c800, mntflags=524288, td=0xc1d29500)
    at /usr/src/sys/ufs/ffs/ffs_vfsops.c:999
#13 0xc06c68f4 in dounmount (mp=0xc481c800, flags=524288, td=0xc1d29500)
    at /usr/src/sys/kern/vfs_mount.c:1126
#14 0xc06cce3e in vfs_unmountall () at /usr/src/sys/kern/vfs_subr.c:3176
#15 0xc06718c3 in boot (howto=16392) at /usr/src/sys/kern/kern_shutdown.c:357
#16 0xc06711d4 in reboot (td=0xc1d29500, uap=0xd77c6d14)
    at /usr/src/sys/kern/kern_shutdown.c:178
#17 0xc083f050 in syscall (frame=
      {tf_fs = 47, tf_es = 47, tf_ds = 47, tf_edi = -1077940488, tf_esi = -1077940488, tf_ebp = -1077940744, tf_isp = -679711372, tf_ebx = -1077940584, tf_edx = -1, tf_ecx = 4, tf_eax = 55, tf_trapno = 12, tf_err = 2, tf_eip = 134547627, tf_cs = 31, tf_ef
lags = 515, tf_esp = -1077940948, tf_ss = 47})
    at /usr/src/sys/i386/i386/trap.c:1010
#18 0xc082a0bd in Xint0x80_syscall () at {standard input}:136
---Can't read userspace from dump, or kernel process---

(kgdb) up
#1  0xc06719f7 in boot (howto=260) at /usr/src/sys/kern/kern_shutdown.c:372
372			doadump();
(kgdb) up
#2  0xc0671dfd in panic () at /usr/src/sys/kern/kern_shutdown.c:550
550		boot(bootopt);
(kgdb) up
#3  0xc048cc82 in db_panic () at /usr/src/sys/ddb/db_command.c:450
450		panic("from debugger");
(kgdb) up
#4  0xc048cbe2 in db_command (last_cmdp=0xc094efc0, cmd_table=0x0, 
    aux_cmd_tablep=0xc08d09cc, aux_cmd_tablep_end=0xc08d09e4)
    at /usr/src/sys/ddb/db_command.c:346
346		    (*cmd->fcn)(addr, have_addr, count, modif);
(kgdb) up
#5  0xc048cd25 in db_command_loop () at /usr/src/sys/ddb/db_command.c:472
472		    db_command(&db_last_command, db_command_table,
(kgdb) up
#6  0xc048fd25 in db_trap (type=3, code=0) at /usr/src/sys/ddb/db_trap.c:73
73		    db_command_loop();
(kgdb) up
#7  0xc082861c in kdb_trap (type=3, code=0, regs=0xd77c6b48)
    at /usr/src/sys/i386/i386/db_interface.c:171
171		    db_trap(type, code);
(kgdb) up
#8  0xc083e688 in trap (frame=
      {tf_fs = 24, tf_es = -1064697840, tf_ds = 16, tf_edi = -1064617494, tf_esi = 1, tf_ebp = -679711852, tf_isp = -679711884, tf_ebx = 0, tf_edx = 0, tf_ecx = 32, tf_eax = 18, tf_trapno = 3, tf_err = 0, tf_eip = -1065187035, tf_cs = 8, tf_eflags = 642, 
tf_esp = -1064532435, tf_ss = -1064643348})
    at /usr/src/sys/i386/i386/trap.c:580
580				if (kdb_trap (type, 0, &frame))
(kgdb) up
#9  0xc082a068 in calltrap () at {standard input}:94
94	{standard input}: No such file or directory.
	in {standard input}
Current language:  auto; currently asm
(kgdb) up
#10 0xc0671d96 in panic (fmt=0xc08b39ea "vrele: negative ref cnt")
    at /usr/src/sys/kern/kern_shutdown.c:534
534			Debugger ("panic");
Current language:  auto; currently c
(kgdb) up
#11 0xc06cb44e in vrele () at /usr/src/sys/kern/vfs_subr.c:2221
2221			panic("vrele: negative ref cnt");
(kgdb) list
2216		} else {
2217	#ifdef DIAGNOSTIC
2218			vprint("vrele: negative ref count", vp);
2219	#endif
2220			VI_UNLOCK(vp);
2221			panic("vrele: negative ref cnt");
2222		}
2223	}
2224	
2225	/*
(kgdb) inspect *vp
$1 = {v_interlock = {mtx_object = {lo_class = 0xc0907a9c, 
      lo_name = 0xc08b37b0 "vnode interlock", 
      lo_type = 0xc08b37b0 "vnode interlock", lo_flags = 196608, lo_list = {
        tqe_next = 0x0, tqe_prev = 0x0}, lo_witness = 0x0}, mtx_lock = 4, 
    mtx_recurse = 0}, v_iflag = 256, v_usecount = 0, v_numoutput = 0, 
  v_vxproc = 0x0, v_holdcnt = 0, v_cleanblkhd = {tqh_first = 0x0, 
    tqh_last = 0xc49c4b64}, v_cleanblkroot = 0x0, v_cleanbufcnt = 0, 
  v_dirtyblkhd = {tqh_first = 0x0, tqh_last = 0xc49c4b74}, 
  v_dirtyblkroot = 0x0, v_dirtybufcnt = 0, v_vflag = 8, v_writecount = 0, 
  v_object = 0xc10366b4, v_lastw = 0, v_cstart = 0, v_lasta = 0, v_clen = 0, 
  v_un = {vu_mountedhere = 0xc486a300, vu_socket = 0xc486a300, vu_spec = {
      vu_cdev = 0xc486a300, vu_specnext = {sle_next = 0x0}}, 
    vu_fifoinfo = 0xc486a300}, v_freelist = {tqe_next = 0x0, 
    tqe_prev = 0xc4974088}, v_nmntvnodes = {tqe_next = 0xc49c4a28, 
    tqe_prev = 0xc4946090}, v_synclist = {le_next = 0x0, 
    le_prev = 0xc47e6830}, v_type = VCHR, v_tag = 0xc08a7281 "devfs", 
  v_data = 0xc4968580, v_lock = {lk_interlock = 0xc096ccf8, 
    lk_flags = 16777216, lk_sharecount = 0, lk_waitcount = 0, 
    lk_exclusivecount = 0, lk_prio = 80, lk_wmesg = 0xc08a7281 "devfs", 
    lk_timo = 6, lk_lockholder = 0xffffffff, lk_newlock = 0x0}, 
  v_vnlock = 0xc49c4bd8, v_op = 0xc480cc00, v_mount = 0xc481e000, 
  v_cache_src = {lh_first = 0x0}, v_cache_dst = {tqh_first = 0x0, 
    tqh_last = 0xc49c4c0c}, v_id = 179, v_dd = 0xc49c4b2c, v_ddid = 0, 
  v_pollinfo = 0x0, v_label = 0xc4967618, v_cachedfs = 4294967295, 
  v_cachedid = 97}
(kgdb) up
#12 0xc07d4b18 in ffs_unmount (mp=0xc481c800, mntflags=524288, td=0xc1d29500)
    at /usr/src/sys/ufs/ffs/ffs_vfsops.c:999
999		vrele(ump->um_devvp);
(kgdb) inspect *ump
$2 = {um_mountp = 0xc481c800, um_dev = 0xc486a300, um_devvp = 0xc49c4b2c, 
  um_fstype = 2, um_fs = 0xc4911000, um_quotas = {0x0, 0x0}, um_cred = {0x0, 
    0x0}, um_extattr = {uepm_lock = {lk_interlock = 0x0, lk_flags = 0, 
      lk_sharecount = 0, lk_waitcount = 0, lk_exclusivecount = 0, lk_prio = 0, 
      lk_wmesg = 0x0, lk_timo = 0, lk_lockholder = 0x0, lk_newlock = 0x0}, 
    uepm_list = {lh_first = 0x0}, uepm_ucred = 0x0, uepm_flags = 0}, 
  um_nindir = 2048, um_bptrtodb = 2, um_seqinc = 8, um_numindirdeps = 0, 
  um_btime = {0, 0}, um_itime = {0, 0}, um_qflags = "\0", 
  um_savedmaxfilesize = 0, um_balloc = 0xc07beee0 <ffs_balloc_ufs2>, 
  um_blkatoff = 0xc07d25a0 <ffs_blkatoff>, 
  um_truncate = 0xc07c0fa0 <ffs_truncate>, 
  um_update = 0xc07c0c50 <ffs_update>, um_valloc = 0xc07ba700 <ffs_valloc>, 
  um_vfree = 0xc07bcd60 <ffs_vfree>, um_ifree = 0xc07d5c90 <ffs_ifree>}
(kgdb) inspect *mp
$3 = {mnt_list = {tqe_next = 0x0, tqe_prev = 0xc481e000}, mnt_op = 0xc0940220, 
  mnt_vfc = 0xc0940260, mnt_vnodecovered = 0xc4946924, mnt_syncer = 0x0, 
  mnt_nvnodelist = {tqh_first = 0x0, tqh_last = 0xc481c818}, 
  mnt_reservedvnlist = {tqh_first = 0x0, tqh_last = 0xc481c820}, mnt_lock = {
    lk_interlock = 0xc096ce3c, lk_flags = 16794624, lk_sharecount = 0, 
    lk_waitcount = 0, lk_exclusivecount = 1, lk_prio = 80, 
    lk_wmesg = 0xc08b312b "vfslock", lk_timo = 0, lk_lockholder = 0xc1d29500, 
    lk_newlock = 0x0}, mnt_mtx = {mtx_object = {lo_class = 0xc0907a9c, 
      lo_name = 0xc08b311a "struct mount mtx", 
      lo_type = 0xc08b311a "struct mount mtx", lo_flags = 196608, lo_list = {
        tqe_next = 0x0, tqe_prev = 0x0}, lo_witness = 0x0}, mtx_lock = 4, 
    mtx_recurse = 0}, mnt_writeopcount = 1, mnt_flag = 2101248, mnt_opt = 0x0, 
  mnt_optnew = 0x0, mnt_kern_flag = 16777217, mnt_maxsymlinklen = 120, 
  mnt_stat = {f_version = 537068824, f_type = 4, f_flags = 2101248, 
    f_bsize = 2048, f_iosize = 16384, f_blocks = 8707399, f_bfree = 1046155, 
    f_bavail = 349564, f_files = 2260990, f_ffree = 1262107, 
    f_syncwrites = 152, f_asyncwrites = 56103, f_syncreads = 234360, 
    f_asyncreads = 1263, f_spare = {0, 0, 0, 0, 0, 0, 0, 0, 0, 0}, 
    f_namemax = 255, f_owner = 0, f_fsid = {val = {1048561141, 1317826222}}, 
    f_charspare = '\0' <repeats 79 times>, 
    f_fstypename = "ufs", '\0' <repeats 12 times>, 
    f_mntfromname = "/dev/ad0s1e", '\0' <repeats 76 times>, 
    f_mntonname = "/usr", '\0' <repeats 83 times>}, mnt_cred = 0xc496e780, 
  mnt_data = 0xc499b300, mnt_time = 0, mnt_iosize_max = 131072, 
  mnt_export = 0x0, mnt_mntlabel = 0xc496767c, mnt_fslabel = 0xc49677bc, 
  mnt_nvnodelistsize = 0}
(kgdb) list
994			NOCRED, td);
995	#else
996		error = VOP_CLOSE(ump->um_devvp, FREAD|FWRITE, NOCRED, td);
997	#endif
998	
999		vrele(ump->um_devvp);
1000	
1001		free(fs->fs_csp, M_UFSMNT);
1002		free(fs, M_UFSMNT);
1003		free(ump, M_UFSMNT);
(kgdb) up
#13 0xc06c68f4 in dounmount (mp=0xc481c800, flags=524288, td=0xc1d29500)
    at /usr/src/sys/kern/vfs_mount.c:1126
1126			error = VFS_UNMOUNT(mp, flags, td);
(kgdb) inspect flags
$4 = 524288
(kgdb) up
#14 0xc06cce3e in vfs_unmountall () at /usr/src/sys/kern/vfs_subr.c:3176
3176			error = dounmount(mp, MNT_FORCE, td);
(kgdb) quit

Script done on Mon Dec  1 12:23:54 2003
Received on Mon Dec 01 2003 - 08:33:20 UTC

This archive was generated by hypermail 2.4.0 : Wed May 19 2021 - 11:37:32 UTC