Re: And probably the final crash for today's current :) (panic: filesystem goof: vop_panic[vop_print])

On Mon, Aug 20, 2007 at 11:40:29PM +0300, Nikolay Pavlov wrote:
> I am testing latest coda client code. 
> After simple ls -l /coda i am getting this panic:
> 
> Unread portion of the kernel message buffer:
> KDB: stack backtrace:
> db_trace_self_wrapper(c0a9e0a9,e69729b0,c07c7933,0,e69729b0,...) at 
> db_trace_self_wrapper+0x26
> kdb_backtrace(0,e69729b0,c0a15cf5,e69729c0,c821ac3c,...) at 
> kdb_backtrace+0x29
> vfs_badlock(c4448c80,e69729c0,c0b7efc0,c821ac3c,0) at vfs_badlock+0x23
> assert_vop_locked(c821ac3c,c0acdaac,810,0,c65aca00,...) at 
> assert_vop_locked+0x50
> VOP_OPEN_APV(c4448c80,e6972a18,1,c483a500,c4867ab0,...) at 
> VOP_OPEN_APV+0x8a
> coda_open(e6972a8c,c0acdaac,c4864c00,0,e6972b80,...) at coda_open+0x11e
> VOP_OPEN_APV(c83ee6e0,e6972a8c,e6972a78,246,c8242984,...) at 
> VOP_OPEN_APV+0xc5
> vn_open_cred(e6972b80,e6972c78,0,c483a500,c48358b8,...) at 
> vn_open_cred+0x43b
> vn_open(e6972b80,e6972c78,0,c48358b8,0,...) at vn_open+0x33
> kern_open(c4864c00,281b280c,0,1,0,...) at kern_open+0xe7
> open(c4864c00,e6972cfc,c,c0aa0d7e,c0b48838,...) at open+0x30
> syscall(e6972d38) at syscall+0x2d3
> Xint0x80_syscall() at Xint0x80_syscall+0x20
> --- syscall (5, FreeBSD ELF32, open), eip = 0x2819af0b, esp = 0xbfbfe64c, 
> ebp = 0xbfbfe688 ---
> VOP_OPEN: 0xc821ac3c is not locked but should be
> KDB: enter: lock violation
> exclusive sleep mutex Giant r = 0 (0xc0bb0a30) locked 
> _at_ /usr/src/sys/kern/vfs_lookup.c:658
> Locked vnodes
> 
> 0xc8242984: tag coda, type VDIR
>     usecount 7, writecount 0, refcount 7 mountedhere 0
>     flags (VV_ROOT)
>      lock type coda: EXCL (count 1) by thread 0xc4864c00 (pid 1247)#0 
> 0xc073efc0 at _lockmgr+0x560
> #1 0xc07bcb30 at vop_stdlock+0x40
> #2 0xc0a18ea5 at VOP_LOCK1_APV+0xa5
> #3 0xc07d6a68 at _vn_lock+0xf8
> #4 0xc07bfbe0 at lookup+0xf0
> #5 0xc07c0bce at namei+0x35e
> #6 0xc07d6529 at vn_open_cred+0x2b9
> #7 0xc07d67c3 at vn_open+0x33
> #8 0xc07d5417 at kern_open+0xe7
> #9 0xc07d5900 at open+0x30
> #10 0xc0a01ea3 at syscall+0x2d3
> #11 0xc09e8190 at Xint0x80_syscall+0x20
> 
> panic: filesystem goof: vop_panic[vop_print]
> cpuid = 0
> Uptime: 15m52s
> Physical memory: 1003 MB
> Dumping 205 MB: 190 174 158 142 126 110 94 78 62 46 30 14
> 
> #0  doadump () at pcpu.h:195
> 195     pcpu.h: No such file or directory.
>         in pcpu.h
> (kgdb) bt
> #0  doadump () at pcpu.h:195
> #1  0xc074ec7e in boot (howto=260) at /usr/src/sys/kern/kern_shutdown.c:409
> #2  0xc074ef3b in panic (fmt=Variable "fmt" is not available.
> ) at /usr/src/sys/kern/kern_shutdown.c:563
> #3  0xc07bca9d in vop_panic (ap=Could not find the frame base 
> for "vop_panic".
> ) at /usr/src/sys/kern/vfs_default.c:152
> #4  0xc0a15f25 in VOP_PRINT_APV (vop=0xc83ee6e0, a=0xe6972634) at 
> vnode_if.c:1873
> #5  0xc07c84af in vn_printf (vp=0xc8242984, fmt=0xc0a64c81 "%s\n") at 
> vnode_if.h:978
> #6  0xc07cabf1 in lockedvnodes (addr=-1065918974, have_addr=0, count=-1, 
> modif=0xe697279c "") at /usr/src/sys/kern/vfs_subr.c:2662
> #7  0xc048d255 in db_command_loop () at /usr/src/sys/ddb/db_command.c:401
> #8  0xc048e9c5 in db_trap (type=3, code=0) 
> at /usr/src/sys/ddb/db_main.c:222
> #9  0xc0775c86 in kdb_trap (type=3, code=0, tf=0xe6972944) 
> at /usr/src/sys/kern/subr_kdb.c:502
> #10 0xc0a026eb in trap (frame=0xe6972944) 
> at /usr/src/sys/i386/i386/trap.c:621
> #11 0xc09e812b in calltrap () at /usr/src/sys/i386/i386/exception.s:139
> #12 0xc0775e02 in kdb_enter (msg=0xc0aa6bc4 "lock violation") at 
> cpufunc.h:60
> #13 0xc07c7969 in vfs_badlock (msg=0xc0aa6c19 "is not locked but should 
> be", str=0xc0acdaac "VOP_OPEN", vp=0xc821ac3c) 
> at /usr/src/sys/kern/vfs_subr.c:3432
> #14 0xc07ca360 in assert_vop_locked (vp=0xc821ac3c, 
> str=0xc0acdaac "VOP_OPEN") at /usr/src/sys/kern/vfs_subr.c:3456
> #15 0xc0a1841a in VOP_OPEN_APV (vop=0xc4448c80, a=0xe6972a18) at 
> vnode_if.c:369
> #16 0xc83ea78e in ?? ()
> #17 0xc4448c80 in ?? ()
> #18 0xe6972a18 in ?? ()
> #19 0x00000001 in ?? ()
> #20 0xc483a500 in ?? ()
> #21 0xc4867ab0 in ?? ()
> #22 0xe6972a30 in ?? ()
> #23 0x00000001 in ?? ()
> #24 0xc483a500 in ?? ()
> #25 0xc4864c00 in ?? ()
> #26 0xc0b7f080 in vop_mknod_desc ()
> #27 0xc821ac3c in ?? ()
> #28 0x00000001 in ?? ()
> #29 0xc483a500 in ?? ()
> #30 0xc4864c00 in ?? ()
> #31 0x00000000 in ?? ()
> #32 0xc821ac3c in ?? ()
> #33 0xc83ee6e0 in ?? ()
> #34 0xe6972a8c in ?? ()
> #35 0x00000001 in ?? ()
> #36 0xe6972a5c in ?? ()
> #37 0xc0a18455 in VOP_OPEN_APV (vop=0x0, a=0xc65aca00) at vnode_if.c:371
> Previous frame identical to this frame (corrupt stack?)
> 
> P.S. I forgot the original CODA maintainer email, could some forward this 
> to him?

Quite often, the "impossible" panics with vnode locking are happens
because some other thread already paniced the kernel. Then, lockmgr
passes all lock requests without actually locking. I would suggest
looking around to make sure this is not the case there.