witness Re: Why does printf(9) hang network?

[dieterbsd at engineer.com]

I received a suggestion to try witness, so I build a kernel with
WITNESS, WITNESS_KDB, KDB, DDB, KDB_TRACE, and DDB_NUMSYM.
This is my first attempt to use witness, so if I got something wrong
let me know.  Didn't quite make it all the way up to a multiuser prompt:

Starting syslogd.
Starting rpcbind.
lock order reversal:
  1st 0xffffff8029549320 bufwait (bufwait) @ 
/usr/src/sys/kern/vfs_bio.c:2559
  2nd 0xffffff000498b000 dirhash (dirhash) @ 
/usr/src/sys/ufs/ufs/ufs_dirhash.c:2
85
KDB: stack backtrace:
db_trace_self_wrapper() at 0xffffffff801dab0a = 
db_trace_self_wrapper+0x2a
_witness_debugger() at 0xffffffff805a144c = _witness_debugger+0x2c
witness_checkorder() at 0xffffffff805a24af = witness_checkorder+0x66f
_sx_xlock() at 0xffffffff8056b6d4 = _sx_xlock+0x34
ufsdirhash_acquire() at 0xffffffff8076f833 = ufsdirhash_acquire+0x33
ufsdirhash_add() at 0xffffffff8076fd99 = ufsdirhash_add+0x19
ufs_direnter() at 0xffffffff80772498 = ufs_direnter+0x848
ufs_mkdir() at 0xffffffff807783d6 = ufs_mkdir+0x5e6
VOP_MKDIR_APV() at 0xffffffff808650d4 = VOP_MKDIR_APV+0x34
kern_mkdirat() at 0xffffffff805eb740 = kern_mkdirat+0x270
syscall() at 0xffffffff8081ec5e = syscall+0x19e
Xfast_syscall() at 0xffffffff80806ab1 = Xfast_syscall+0xe1
--- syscall (136, FreeBSD ELF64, mkdir), rip = 0x80072c53c, rsp = 
0x7fffffffec88
, rbp = 0x7fffffffef66 ---
KDB: enter: witness_checkorder
[thread pid 1255 tid 100076 ]
Stopped at      0xffffffff8059083d = kdb_enter+0x3d:    movq    
$0,0x6508a0(%rip
)
db>


Managed to reboot to single user mode, changed /boot/kernel
back to my production kernel, and got another lock order reversal
rebooting:

# sync
# reboot
Waiting (max 60 seconds) for system process `vnlru' to stop...done
Waiting (max 60 seconds) for system process `bufdaemon' to stop...done
Waiting (max 60 seconds) for system process `syncer' to stop...
Syncing disks, vnodes remaining...0 done
All buffers synced.
lock order reversal:
 1st 0xffffff0004831448 ufs (ufs) @ /usr/src/sys/kern/vfs_mount.c:1200
  2nd 0xffffff0004831d80 devfs (devfs) @ 
/usr/src/sys/kern/vfs_subr.c:2083
KDB: stack backtrace:
db_trace_self_wrapper() at 0xffffffff801dab0a = 
db_trace_self_wrapper+0x2a
_witness_debugger() at 0xffffffff805a144c = _witness_debugger+0x2c
witness_checkorder() at 0xffffffff805a24af = witness_checkorder+0x66f
__lockmgr_args() at 0xffffffff80552054 = __lockmgr_args+0xd04
vop_stdlock() at 0xffffffff805d9239 = vop_stdlock+0x39
VOP_LOCK1_APV() at 0xffffffff80864f56 = VOP_LOCK1_APV+0x46
_vn_lock() at 0xffffffff805f3cc7 = _vn_lock+0x47
vget() at 0xffffffff805e8856 = vget+0x56
devfs_allocv() at 0xffffffff804fa993 = devfs_allocv+0x103
devfs_root() at 0xffffffff804f9268 = devfs_root+0x48
dounmount() at 0xffffffff805e3369 = dounmount+0x419
vfs_unmountall() at 0xffffffff805e82a2 = vfs_unmountall+0x42
boot() at 0xffffffff80564bd3 = boot+0x683
reboot() at 0xffffffff80564ef8 = reboot+0x68
syscall() at 0xffffffff8081ec5e = syscall+0x19e
Xfast_syscall() at 0xffffffff80806ab1 = Xfast_syscall+0xe1
--- syscall (55, FreeBSD ELF64, reboot), rip = 0x80078f83c, rsp = 
0x7fffffffece8
, rbp = 0 ---
KDB: enter: witness_checkorder
[thread pid 35 tid 100073 ]
Stopped at      0xffffffff8059083d = kdb_enter+0x3d:    movq    
$0,0x6508a0(%rip
)
db> lock order reversal:
  1st 0xffffff0004831da8 vnode interlock (vnode interlock) @ 
/usr/src/sys/fs/devf
s/devfs_vnops.c:349
  2nd 0xffffff8000248858 firewire (firewire) @ 
/usr/src/sys/dev/firewire/fwohci.c
:2227
KDB: stack backtrace:
db_trace_self_wrapper() at 0xffffffff801dab0a = 
db_trace_self_wrapper+0x2a
_witness_debugger() at 0xffffffff805a144c = _witness_debugger+0x2c
witness_checkorder() at 0xffffffff805a24af = witness_checkorder+0x66f
_mtx_lock_flags() at 0xffffffff80557b52 = _mtx_lock_flags+0x32
fwohci_poll() at 0xffffffff8035feb1 = fwohci_poll+0x31
dcons_cngetc() at 0xffffffff80303d69 = dcons_cngetc+0x59
cncheckc() at 0xffffffff8052d425 = cncheckc+0x65
cngetc() at 0xffffffff8052d44c = cngetc+0x1c
db_readline() at 0xffffffff801d9ef7 = db_readline+0x77
db_read_line() at 0xffffffff801da975 = db_read_line+0x15
db_command_loop() at 0xffffffff801d8ad8 = db_command_loop+0x38
db_trap() at 0xffffffff801daa49 = db_trap+0x89
kdb_trap() at 0xffffffff80590665 = kdb_trap+0x95
trap() at 0xffffffff8081f200 = trap+0x170
calltrap() at 0xffffffff808067d3 = calltrap+0x8
--- trap 0x3, rip = 0xffffffff8059083d, rsp = 0xffffff80405d9710, rbp = 
0xffffff
80405d9730 ---
kdb_enter() at 0xffffffff8059083d = kdb_enter+0x3d
witness_checkorder() at 0xffffffff805a24af = witness_checkorder+0x66f
__lockmgr_args() at 0xffffffff80552054 = __lockmgr_args+0xd04
vop_stdlock() at 0xffffffff805d9239 = vop_stdlock+0x39
VOP_LOCK1_APV() at 0xffffffff80864f56 = VOP_LOCK1_APV+0x46
_vn_lock() at 0xffffffff805f3cc7 = _vn_lock+0x47
vget() at 0xffffffff805e8856 = vget+0x56
devfs_allocv() at 0xffffffff804fa993 = devfs_allocv+0x103
devfs_root() at 0xffffffff804f9268 = devfs_root+0x48
dounmount() at 0xffffffff805e3369 = dounmount+0x419
vfs_unmountall() at 0xffffffff805e82a2 = vfs_unmountall+0x42
boot() at 0xffffffff80564bd3 = boot+0x683
reboot() at 0xffffffff80564ef8 = reboot+0x68
syscall() at 0xffffffff8081ec5e = syscall+0x19e
Xfast_syscall() at 0xffffffff80806ab1 = Xfast_syscall+0xe1
--- syscall (55, FreeBSD ELF64, reboot), rip = 0x80078f83c, rsp = 
0x7fffffffece8
, rbp = 0 ---