syzbot
witness: userret: returning with the following locks held:
Status:
fixed on 2019/08/27 06:31
Reported-by: syzbot+374d0e7e2400004957f7@syzkaller.appspotmail.com
Fix commit:
b808994cf339
When a thread tries to exclusively lock a vnode, the same thread must ensure that any other thread currently trying to acquire the underlying vnode lock has observed that the same vnode is about to be exclusively locked. Such threads must then sleep until the exclusive lock has been released and then try to acquire the lock again. Otherwise, exclusive access to the vnode cannot be guaranteed.
First crash: 2781d, last: 2571d
▶
▼
Last patch testing requests (6)
Sample crash report:
login: witness: userret: returning with the following locks held:
exclusive rrwlock inode r = 0 (0xfffffd8076c5d5f0) locked @ /syzkaller/managers/multicore/kernel/sys/ufs/ufs/ufs_vnops.c:1547
panic: witness_warn
Stopped at db_enter+0x18: addq $0x8,%rsp
TID PID UID PRFLAGS PFLAGS CPU COMMAND
270698 73942 0 0 0x480 1 syz-executor6228
*453653 73942 0 0 0x4000000 0 syz-executor6228
db_enter() at db_enter+0x18 sys/arch/amd64/amd64/db_interface.c:399
panic() at panic+0x16c sys/kern/subr_prf.c:208
witness_warn(507bcae4261ef179,0,ffff800020be4970) at witness_warn+0x700 witness_debugger sys/kern/subr_witness.c:2549 [inline]
witness_warn(507bcae4261ef179,0,ffff800020be4970) at witness_warn+0x700 sys/kern/subr_witness.c:1465
userret(d178c027f79620c5) at userret+0x361 sys/kern/kern_sig.c:1899
syscall(c556373217555fb7) at syscall+0x680 mi_syscall_return sys/sys/syscall_mi.h:122 [inline]
syscall(c556373217555fb7) at syscall+0x680 sys/arch/amd64/amd64/trap.c:605
Xsyscall(6,5,ed5f89010b8,0,ed5f8901098,ed5f8901090) at Xsyscall+0x128
end of kernel
end trace frame: 0xed8e6972ad0, count: 9
https://www.openbsd.org/ddb.html describes the minimum info required in bug
reports. Insufficient info makes it difficult to find and fix bugs.
ddb{0}>
ddb{0}> set $lines = 0
ddb{0}> show panic
witness_warn
ddb{0}> trace
db_enter() at db_enter+0x18 sys/arch/amd64/amd64/db_interface.c:399
panic() at panic+0x16c sys/kern/subr_prf.c:208
witness_warn(507bcae4261ef179,0,ffff800020be4970) at witness_warn+0x700 witness_debugger sys/kern/subr_witness.c:2549 [inline]
witness_warn(507bcae4261ef179,0,ffff800020be4970) at witness_warn+0x700 sys/kern/subr_witness.c:1465
userret(d178c027f79620c5) at userret+0x361 sys/kern/kern_sig.c:1899
syscall(c556373217555fb7) at syscall+0x680 mi_syscall_return sys/sys/syscall_mi.h:122 [inline]
syscall(c556373217555fb7) at syscall+0x680 sys/arch/amd64/amd64/trap.c:605
Xsyscall(6,5,ed5f89010b8,0,ed5f8901098,ed5f8901090) at Xsyscall+0x128
end of kernel
end trace frame: 0xed8e6972ad0, count: -6
ddb{0}> show registers
rdi 0
rsi 0x1
rbp 0xffff800020c0af40
rbx 0xffff800020c0afe0
rdx 0xffffffff81f33250 cy_pio_rec+0x41b4
rcx 0x201
rax 0x1
r8 0xffffffff81df7814 kprintf+0x174
r9 0x1
r10 0x7cf76f81e813f7f6
r11 0x795e7570cf214d5b
r12 0x3000000008
r13 0xffff800020c0af50
r14 0x100
r15 0x1
rip 0xffffffff8100c2e8 db_enter+0x18
cs 0x8
rflags 0x246
rsp 0xffff800020c0af30
ss 0x10
db_enter+0x18: addq $0x8,%rsp
ddb{0}> show proc
PROC (syz-executor6228) pid=453653 stat=onproc
flags process=0 proc=4000000<THREAD>
pri=32, usrpri=86, nice=20
forw=0xffffffffffffffff, list=0xffff800020be4010,0xffff800020be44d0
process=0xffff800020bca360 user=0xffff800020c06000, vmspace=0xfffffd806e925710
estcpu=36, cpticks=2, pctcpu=0.0
user=0, sys=2, intr=0
ddb{0}> ps
PID TID PPID UID S FLAGS WAIT COMMAND
73942 270698 59418 0 7 0x480 syz-executor6228
*73942 453653 59418 0 7 0x4000000 syz-executor6228
73942 230439 59418 0 3 0x4000080 fsleep syz-executor6228
73942 179925 59418 0 3 0x4000080 fsleep syz-executor6228
73942 478723 59418 0 3 0x4000080 fsleep syz-executor6228
59418 268678 44260 0 2 0x482 syz-executor6228
44260 436522 24337 0 3 0x10008a pause ksh
24337 114902 93407 0 3 0x92 select sshd
96871 135617 1 0 3 0x100083 ttyin getty
93407 256335 1 0 3 0x80 select sshd
73530 194253 21231 73 2 0x100010 syslogd
21231 372363 1 0 3 0x100082 netio syslogd
88110 507126 1 77 3 0x100090 poll dhclient
57580 250122 1 0 3 0x80 poll dhclient
86817 507807 0 0 3 0x14200 pgzero zerothread
93105 400105 0 0 3 0x14200 aiodoned aiodoned
35533 261527 0 0 3 0x14200 syncer update
48959 6084 0 0 3 0x14200 cleaner cleaner
68307 205827 0 0 3 0x14200 reaper reaper
19355 374577 0 0 3 0x14200 pgdaemon pagedaemon
5889 28487 0 0 3 0x14200 bored crynlk
97009 36008 0 0 3 0x14200 bored crypto
8639 319581 0 0 3 0x40014200 acpi0 acpi0
46574 116492 0 0 3 0x40014200 idle1
52318 511356 0 0 3 0x14200 bored softnet
86374 441737 0 0 3 0x14200 bored systqmp
28510 186753 0 0 3 0x14200 bored systq
47051 510633 0 0 3 0x40014200 bored softclock
83513 233275 0 0 3 0x40014200 idle0
1 523314 0 0 3 0x82 wait init
0 0 -1 0 3 0x10200 scheduler swapper
ddb{0}> show all locks
CPU 1:
exclusive sched_lock &sched_lock r = 0 (0xffffffff822f2bb0) locked @ /syzkaller/managers/multicore/kernel/sys/kern/kern_sched.c:162
Process 73942 (syz-executor6228) thread 0xffff800020be4970 (453653)
exclusive rrwlock inode r = 0 (0xfffffd8076c5d5f0) locked @ /syzkaller/managers/multicore/kernel/sys/ufs/ufs/ufs_vnops.c:1547
Process 73530 (syslogd) thread 0xffff800020be5c30 (194253)
exclusive rrwlock inode r = 0 (0xfffffd806ebab6f8) locked @ /syzkaller/managers/multicore/kernel/sys/ufs/ufs/ufs_vnops.c:1547
ddb{0}> show malloc
Type InUse MemUse HighUse Limit Requests Type Lim Kern Lim
devbuf 9445 6315K 6316K 78643K 10532 0 0
pcb 23 9K 9K 78643K 55 0 0
rtable 61 2K 2K 78643K 115 0 0
ifaddr 21 7K 7K 78643K 21 0 0
counters 39 33K 33K 78643K 39 0 0
ioctlops 0 0K 2K 78643K 13 0 0
mount 1 1K 1K 78643K 1 0 0
vnodes 1166 73K 73K 78643K 1261 0 0
UFS quota 1 32K 32K 78643K 1 0 0
UFS mount 5 36K 36K 78643K 5 0 0
shm 2 1K 1K 78643K 2 0 0
VM map 2 1K 1K 78643K 2 0 0
sem 2 0K 0K 78643K 2 0 0
dirhash 12 2K 2K 78643K 12 0 0
ACPI 1792 194K 288K 78643K 12592 0 0
file desc 2 2K 3K 78643K 91 0 0
proc 40 38K 46K 78643K 201 0 0
NFS srvsock 1 0K 0K 78643K 1 0 0
NFS daemon 1 16K 16K 78643K 1 0 0
in_multi 11 0K 0K 78643K 11 0 0
ether_multi 1 0K 0K 78643K 1 0 0
ISOFS mount 1 32K 32K 78643K 1 0 0
MSDOSFS mount 1 16K 16K 78643K 1 0 0
ttys 36 159K 159K 78643K 36 0 0
exec 0 0K 1K 78643K 149 0 0
pagedep 1 8K 8K 78643K 1 0 0
inodedep 1 32K 32K 78643K 1 0 0
newblk 1 0K 0K 78643K 1 0 0
VM swap 7 26K 26K 78643K 7 0 0
UVM amap 52 2K 3K 78643K 792 0 0
UVM aobj 2 2K 2K 78643K 2 0 0
memdesc 1 4K 4K 78643K 1 0 0
crypto data 1 1K 1K 78643K 1 0 0
NDP 3 0K 0K 78643K 3 0 0
temp 30 2343K 2407K 78643K 1747 0 0
SYN cache 2 16K 16K 78643K 2 0 0
ddb{0}> show all pools
Name Size Requests Fail Releases Pgreq Pgrel Npage Hiwat Minpg Maxpg Idle
arp 64 2 0 0 1 0 1 1 0 8 0
inpcbpl 280 22 0 16 1 0 1 1 0 8 0
plimitpl 152 13 0 8 1 0 1 1 0 8 0
plcache 128 20 0 0 1 0 1 1 0 8 0
rtentry 112 23 0 1 1 0 1 1 0 8 0
syncache 264 5 0 5 1 0 1 1 0 8 1
tcpcb 544 8 0 5 1 0 1 1 0 8 0
art_heap8 4096 1 0 0 1 0 1 1 0 8 0
art_heap4 256 97 0 0 7 0 7 7 0 8 0
art_table 32 98 0 0 1 0 1 1 0 8 0
art_node 16 22 0 2 1 0 1 1 0 8 0
dirhash 1024 17 0 0 3 0 3 3 0 8 0
dino1pl 128 1502 0 135 45 0 45 45 0 8 0
ffsino 272 1502 0 135 92 0 92 92 0 8 0
nchpl 144 1704 0 179 57 0 57 57 0 8 0
uvmvnodes 72 1511 0 0 28 0 28 28 0 8 0
vnodes 200 1511 0 0 80 0 80 80 0 8 0
namei 1024 4096 0 4096 2 1 1 1 0 8 1
percpumem 16 30 0 0 1 0 1 1 0 8 0
scxspl 192 2662 0 2662 8 2 6 6 0 8 6
sigapl 432 203 0 192 2 0 2 2 0 8 0
futexpl 56 188 0 185 1 0 1 1 0 8 0
knotepl 112 5 0 0 1 0 1 1 0 8 0
kqueuepl 104 1 0 0 1 0 1 1 0 8 0
pipepl 112 114 0 107 2 1 1 1 0 8 0
fdescpl 488 204 0 192 2 0 2 2 0 8 0
filepl 152 1376 0 1325 3 0 3 3 0 8 1
lockfpl 96 6 0 6 1 1 0 1 0 8 0
lockfspl 24 3 0 3 1 1 0 1 0 8 0
sessionpl 112 17 0 9 1 0 1 1 0 8 0
pgrppl 48 17 0 9 1 0 1 1 0 8 0
ucredpl 96 587 0 580 1 0 1 1 0 8 0
zombiepl 144 192 0 192 2 1 1 1 0 8 1
processpl 840 218 0 192 4 0 4 4 0 8 0
procpl 600 328 0 298 3 0 3 3 0 8 0
sockpl 384 64 0 48 2 0 2 2 0 8 0
mcl4k 4096 2 0 0 1 0 1 1 0 8 0
mcl2k 2048 67 0 0 9 0 9 9 0 8 0
mtagpl 80 1 0 0 1 0 1 1 0 8 0
mbufpl 256 85 0 0 6 0 6 6 0 8 0
bufpl 256 2046 0 261 112 0 112 112 0 8 0
anonpl 16 18529 0 17364 6 1 5 6 0 125 0
amapchunkpl 152 743 0 699 2 0 2 2 0 158 0
amappl16 192 134 0 125 1 0 1 1 0 8 0
amappl15 184 1 0 1 1 1 0 1 0 8 0
amappl14 176 1 0 1 1 1 0 1 0 8 0
amappl13 168 16 0 13 1 0 1 1 0 8 0
amappl12 160 4 0 4 1 1 0 1 0 8 0
amappl11 152 177 0 168 1 0 1 1 0 8 0
amappl10 144 43 0 43 2 1 1 1 0 8 1
amappl9 136 203 0 202 1 0 1 1 0 8 0
amappl8 128 106 0 99 1 0 1 1 0 8 0
amappl7 120 30 0 26 1 0 1 1 0 8 0
amappl6 112 42 0 38 1 0 1 1 0 8 0
amappl5 104 176 0 164 1 0 1 1 0 8 0
amappl4 96 257 0 238 1 0 1 1 0 8 0
amappl3 88 112 0 106 1 0 1 1 0 8 0
amappl2 80 814 0 768 1 0 1 1 0 8 0
amappl1 72 12427 0 12012 15 5 10 15 0 8 0
amappl 72 507 0 483 1 0 1 1 0 75 0
dma4096 4096 1 0 1 1 1 0 1 0 8 0
dma256 256 6 0 6 1 1 0 1 0 8 0
dma64 64 259 0 259 1 1 0 1 0 8 0
dma32 32 7 0 7 1 1 0 1 0 8 0
dma16 16 17 0 17 1 1 0 1 0 8 0
aobjpl 64 1 0 0 1 0 1 1 0 8 0
uaddrrnd 24 204 0 192 1 0 1 1 0 8 0
uaddrbest 32 2 0 0 1 0 1 1 0 8 0
uaddr 24 204 0 192 1 0 1 1 0 8 0
vmmpekpl 168 5377 0 5357 1 0 1 1 0 8 0
vmmpepl 168 25699 0 24920 49 15 34 43 0 357 0
vmsppl 360 203 0 192 2 0 2 2 0 8 0
pdppl 4096 415 0 384 5 0 5 5 0 8 0
pvpl 32 73927 0 71052 30 4 26 26 0 265 2
pmappl 224 203 0 192 1 0 1 1 0 8 0
extentpl 40 39 0 25 1 0 1 1 0 8 0
phpool 112 241 0 3 7 0 7 7 0 8 0
ddb{0}>
Struck through repros no longer work on HEAD.