witness: reversal: inode fdlock

[syzbot]

Hello,

syzbot found the following crash on:

HEAD commit: 6f9e9be94f66 sort output suffixes
git tree: openbsd
console output: https://syzkaller.appspot.com/x/log.txt?x=116178b8c00000
kernel config: https://syzkaller.appspot.com/x/.config?x=3303344588104330
dashboard link: https://syzkaller.appspot.com/bug?extid=c278abadcbeb7150b6c2
compiler:

Unfortunately, I don't have any reproducer for this crash yet.

IMPORTANT: if you fix the bug, please add the following tag to the commit:
Reported-by: syzbot+c278ab...@syzkaller.appspotmail.com

lock order reversal:
1st 0xfffffd807cc6d818 inode (&ip->i_lock) @
/syzkaller/managers/multicore/kernel/sys/ufs/ufs/ufs_vnops.c:1547
2nd 0xfffffd806f6819e8 fdlock (&newfdp->fd_fd.fd_lock) @
/syzkaller/managers/multicore/kernel/sys/kern/vfs_syscalls.c:1113
lock order "&newfdp->fd_fd.fd_lock"(rwlock) -> "&ip->i_lock"(rrwlock) first
seen at:
#0 witness_checkorder+0x6d8
#1 _rw_enter+0xbf
#2 _rrw_enter+0x5c
#3 VOP_LOCK+0x55
#4 vn_closefile+0x11e
#5 fdrop+0xdf
#6 closef+0x128
#7 finishdup+0x2cc
#8 dodup3+0x5da
#9 syscall+0x5a0
#10 Xsyscall+0x128
lock order "&ip->i_lock"(rrwlock) -> "&newfdp->fd_fd.fd_lock"(rwlock) first
seen at:
#0 witness_checkorder+0x6d8
#1 _rw_enter_write+0x6b
#2 doopenat+0x679
#3 syscall+0x5a0
#4 Xsyscall+0x128
Stopped at db_enter+0x18: addq $0x8,%rsp
ddb{1}>
ddb{1}> set $lines = 0
ddb{1}> show panic
the kernel did not panic
ddb{1}> trace
db_enter() at db_enter+0x18 sys/arch/amd64/amd64/db_interface.c:399
witness_checkorder(e4aada9413748460,ffffffff81ee4b9d,459,0,fffffd806f6819e8)
at
witness_checkorder+0x12f9 witness_debugger sys/kern/subr_witness.c:2543
[inline]
witness_checkorder(e4aada9413748460,ffffffff81ee4b9d,459,0,fffffd806f6819e8)
at
witness_checkorder+0x12f9 sys/kern/subr_witness.c:1089
_rw_enter_write(0,1,1) at _rw_enter_write+0x6b sys/kern/kern_rwlock.c:118
doopenat(b023420ee3e82e2e,0,ffff800020b93788,8d291387ba8,0,50) at
doopenat+0x679 sys/kern/vfs_syscalls.c:1114
syscall(23cd535de81e3510) at syscall+0x5a0 mi_syscall
sys/sys/syscall_mi.h:99 [inline]
syscall(23cd535de81e3510) at syscall+0x5a0 sys/arch/amd64/amd64/trap.c:583
Xsyscall(6,0,ffffffffffffffb0,0,3,8cfd1467010) at Xsyscall+0x128
end of kernel
end trace frame: 0x8d291387c30, count: -6
ddb{1}> show registers
rdi 0x3
rsi 0x3ffff acpi_pdirpa+0x2be67
rbp 0xffff800020c4f810
rbx 0x3
rdx 0x40000 acpi_pdirpa+0x2be68
rcx 0xffff800002b48000
rax 0xffff800001b46780
r8 0xffffffff81e8d9bf witness_checkorder+0x12cf
r9 0x5
r10 0xde1321c7453cc625
r11 0x74d98c5a86427b25
r12 0xfffffd80025d8570
r13 0xffffffff81f25008 apollo_pio_rec+0x161
r14 0xffffffff822b7730 w_lodata+0x3eb10
r15 0xffffffff822cdb50 w_lodata+0x54f30
rip 0xffffffff8171e6c8 db_enter+0x18
cs 0x8
rflags 0x246
rsp 0xffff800020c4f800
ss 0x10
db_enter+0x18: addq $0x8,%rsp
ddb{1}> show proc
PROC (syz-executor1) pid=104171 stat=onproc
flags process=0 proc=4000000<THREAD>
pri=32, usrpri=77, nice=20
forw=0xffffffffffffffff, list=0xffff800020b924c8,0xffff800020b932e8
process=0xffff800020b953c0 user=0xffff800020c4a000,
vmspace=0xfffffd807f00d2d0
estcpu=36, cpticks=0, pctcpu=0.0
user=0, sys=0, intr=0
ddb{1}> ps
PID TID PPID UID S FLAGS WAIT COMMAND
47248 356329 94527 0 2 0 syz-executor0
47248 219795 94527 0 3 0x4000080 fsleep syz-executor0
61801 380133 92951 0 2 0 syz-executor1
*61801 104171 92951 0 7 0x4000000 syz-executor1
61801 244059 92951 0 2 0x4000000 syz-executor1
56631 65331 1 0 3 0x100083 ttyin getty
14094 223580 0 0 3 0x14200 bored sosplice
92951 109119 23181 0 3 0x82 nanosleep syz-executor1
94527 522225 23181 0 3 0x82 nanosleep syz-executor0
23181 132209 10064 0 3 0x82 thrsleep syz-fuzzer
23181 328350 10064 0 3 0x4000082 thrsleep syz-fuzzer
23181 168070 10064 0 3 0x4000082 thrsleep syz-fuzzer
23181 294580 10064 0 3 0x4000082 thrsleep syz-fuzzer
23181 288126 10064 0 3 0x4000082 thrsleep syz-fuzzer
23181 23642 10064 0 3 0x4000082 thrsleep syz-fuzzer
23181 401394 10064 0 3 0x4000082 thrsleep syz-fuzzer
23181 331587 10064 0 3 0x4000082 kqread syz-fuzzer
23181 300678 10064 0 3 0x4000082 thrsleep syz-fuzzer
23181 130788 10064 0 3 0x4000082 thrsleep syz-fuzzer
10064 196677 81948 0 3 0x10008a pause ksh
81948 75520 52882 0 3 0x92 select sshd
52882 286675 1 0 3 0x80 select sshd
5656 340084 9758 73 7 0x100090 syslogd
9758 137432 1 0 3 0x100082 netio syslogd
41774 434711 1 77 3 0x100090 poll dhclient
75680 134250 1 0 3 0x80 poll dhclient
7420 124534 0 0 2 0x14200 zerothread
17740 282418 0 0 3 0x14200 aiodoned aiodoned
41460 41175 0 0 3 0x14200 syncer update
53403 328068 0 0 3 0x14200 cleaner cleaner
90809 222454 0 0 3 0x14200 reaper reaper
91611 468821 0 0 3 0x14200 pgdaemon pagedaemon
16411 499648 0 0 3 0x14200 bored crynlk
74274 77256 0 0 3 0x14200 bored crypto
3254 321402 0 0 3 0x40014200 acpi0 acpi0
87677 51875 0 0 3 0x40014200 idle1
94367 98977 0 0 3 0x14200 bored softnet
7025 416047 0 0 3 0x14200 bored systqmp
11799 91942 0 0 3 0x14200 bored systq
21410 408983 0 0 3 0x40014200 bored softclock
63857 96449 0 0 3 0x40014200 idle0
1 208176 0 0 3 0x82 wait init
0 0 -1 0 3 0x10200 scheduler swapper


---
This bug is generated by a bot. It may contain errors.
See https://goo.gl/tpsmEJ for more information about syzbot.
syzbot engineers can be reached at syzk...@googlegroups.com.

syzbot will keep track of this bug report. See:
https://goo.gl/tpsmEJ#bug-status-tracking for how to communicate with
syzbot.

[syzbot]

syzbot has found a reproducer for the following crash on:

HEAD commit: 6f9e9be94f66 sort output suffixes
git tree: openbsd

console output: https://syzkaller.appspot.com/x/log.txt?x=14c598b8c00000

kernel config: https://syzkaller.appspot.com/x/.config?x=3303344588104330
dashboard link: https://syzkaller.appspot.com/bug?extid=c278abadcbeb7150b6c2
compiler:

syz repro: https://syzkaller.appspot.com/x/repro.syz?x=15da73cf400000
C reproducer: https://syzkaller.appspot.com/x/repro.c?x=17cdfd5f400000

IMPORTANT: if you fix the bug, please add the following tag to the commit:
Reported-by: syzbot+c278ab...@syzkaller.appspotmail.com

login: lock order reversal:
1st 0xfffffd806d614f80 inode (&ip->i_lock) @
/syzkaller/managers/multicore/kernel/sys/ufs/ufs/ufs_vnops.c:1547
2nd 0xfffffd807f7c67f8 fdlock (&newfdp->fd_fd.fd_lock) @

/syzkaller/managers/multicore/kernel/sys/kern/vfs_syscalls.c:1113
lock order "&newfdp->fd_fd.fd_lock"(rwlock) -> "&ip->i_lock"(rrwlock) first
seen at:
#0 witness_checkorder+0x6d8
#1 _rw_enter+0xbf
#2 _rrw_enter+0x5c
#3 VOP_LOCK+0x55
#4 vn_closefile+0x11e
#5 fdrop+0xdf
#6 closef+0x128
#7 finishdup+0x2cc
#8 dodup3+0x5da
#9 syscall+0x5a0
#10 Xsyscall+0x128
lock order "&ip->i_lock"(rrwlock) -> "&newfdp->fd_fd.fd_lock"(rwlock) first
seen at:
#0 witness_checkorder+0x6d8
#1 _rw_enter_write+0x6b
#2 doopenat+0x679
#3 syscall+0x5a0
#4 Xsyscall+0x128
Stopped at db_enter+0x18: addq $0x8,%rsp

ddb{0}>
ddb{0}> set $lines = 0
ddb{0}> show panic

the kernel did not panic

ddb{0}> trace

db_enter() at db_enter+0x18 sys/arch/amd64/amd64/db_interface.c:399

witness_checkorder(79db3275ff2465d5,ffffffff81ee4b9d,459,0,fffffd807f7c67f8)

at
witness_checkorder+0x12f9 witness_debugger sys/kern/subr_witness.c:2543
[inline]

witness_checkorder(79db3275ff2465d5,ffffffff81ee4b9d,459,0,fffffd807f7c67f8)

at
witness_checkorder+0x12f9 sys/kern/subr_witness.c:1089
_rw_enter_write(0,1,1) at _rw_enter_write+0x6b sys/kern/kern_rwlock.c:118

doopenat(ae693c3f463dc669,0,ffff800020b744b8,1190e5cb7c8,0,50) at
doopenat+0x679 sys/kern/vfs_syscalls.c:1114
syscall(caf084539f826dba) at syscall+0x5a0 mi_syscall
sys/sys/syscall_mi.h:99 [inline]
syscall(caf084539f826dba) at syscall+0x5a0 sys/arch/amd64/amd64/trap.c:583
Xsyscall(6,0,1165bf9e0c8,0,1165bf9e0a8,1165bf9e0a0) at Xsyscall+0x128
end of kernel
end trace frame: 0x1190e5cb800, count: -6
ddb{0}> show registers
rdi 0x3
rsi 0xffffffff821dad78
__sancov_gen_cov_switch_values.125+0x28rbp 0xffff800020c17b00
rbx 0x3
rdx 0x8b
rcx 0x3
rax 0

r8 0xffffffff81e8d9bf witness_checkorder+0x12cf
r9 0x5

r10 0x51d18c2bd52e6884
r11 0x5ccd9507b4682770

r12 0xfffffd80025d8570
r13 0xffffffff81f25008 apollo_pio_rec+0x161

r14 0xffffffff822ca450 w_lodata+0x51830
r15 0xffffffff822cdec0 w_lodata+0x552a0

rip 0xffffffff8171e6c8 db_enter+0x18
cs 0x8
rflags 0x246

rsp 0xffff800020c17af0
ss 0
db_enter+0x18: addq $0x8,%rsp
ddb{0}> show proc
PROC (syz-executor1946) pid=190813 stat=onproc
flags process=0 proc=4000000<THREAD>
pri=32, usrpri=50, nice=20
forw=0xffffffffffffffff, list=0xffff800020b74260,0xffff800020b752d8
process=0xffff800020bcb710 user=0xffff800020c12000,
vmspace=0xfffffd806e921b48

estcpu=36, cpticks=0, pctcpu=0.0
user=0, sys=0, intr=0

ddb{0}> ps

PID TID PPID UID S FLAGS WAIT COMMAND

47543 9107 98686 0 2 0 syz-executor1946
47543 358443 98686 0 7 0x4000000 syz-executor1946
91694 252564 6151 0 2 0 syz-executor1946
*91694 190813 6151 0 7 0x4000000 syz-executor1946
91694 409568 6151 0 2 0x4000000 syz-executor1946
98686 88220 24258 0 3 0x80 nanosleep syz-executor1946
6151 277969 24258 0 3 0x80 nanosleep syz-executor1946
24258 94023 48006 0 3 0x82 nanosleep syz-executor1946
48006 180577 11174 0 3 0x10008a pause ksh
11174 132453 50816 0 3 0x92 select sshd
55781 272133 1 0 3 0x100083 ttyin getty
50816 169381 1 0 3 0x80 select sshd
44756 465893 69120 73 2 0x100090 syslogd
69120 508776 1 0 3 0x100082 netio syslogd
86756 63979 1 77 3 0x100090 poll dhclient
36293 324585 1 0 3 0x80 poll dhclient
59764 425633 0 0 2 0x14200 zerothread
28593 348272 0 0 3 0x14200 aiodoned aiodoned
52471 305557 0 0 3 0x14200 syncer update
60144 412117 0 0 3 0x14200 cleaner cleaner
4133 92384 0 0 3 0x14200 reaper reaper
82005 17799 0 0 3 0x14200 pgdaemon pagedaemon
61041 458604 0 0 3 0x14200 bored crynlk
98719 277870 0 0 3 0x14200 bored crypto
46537 56770 0 0 3 0x40014200 acpi0 acpi0
98249 504127 0 0 3 0x40014200 idle1
96670 508805 0 0 3 0x14200 bored softnet
96927 55003 0 0 3 0x14200 bored systqmp
45333 356745 0 0 3 0x14200 bored systq
21283 43065 0 0 3 0x40014200 bored softclock
83456 368178 0 0 3 0x40014200 idle0
1 38763 0 0 3 0x82 wait init

0 0 -1 0 3 0x10200 scheduler swapper

ddb{0}>

[Anton Lindqvist]

No action in 64 days. The reproducer(s) are not triggering the panic
according to my testing. Could have been fixed by the following
commit[1]. Closing for now, lets see if it ever occurs again.

#syz invalid

[1] https://github.com/openbsd/src/commit/b808994cf33919dd4ce1daa99a93f531dfd16afe