syzbot


witness: reversal: &pr->ps_mtx &sched_lock

Status: fixed on 2019/06/02 02:28
Reported-by: syzbot+8e4863b3dde88eb706dc@syzkaller.appspotmail.com
Fix commit: 17b25159f963 Revert to using the SCHED_LOCK() to protect time accounting.
First crash: 2003d, last: 2002d

Sample crash report:
login: witness: lock order reversal:
 1st 0xffff800020b3ab38 &pr->ps_mtx (&pr->ps_mtx)
 2nd 0xffffffff8236e2f8 &sched_lock (&sched_lock)
lock order "&sched_lock"(sched_lock) -> "&pr->ps_mtx"(mutex) first seen at:
#0  witness_checkorder+0x6a7 sys/kern/subr_witness.c:877
#1  mtx_enter+0x3a sys/kern/kern_lock.c:265
#2  tuagg+0x32 sys/kern/kern_resource.c:360
#3  mi_switch+0x1c7 x86_atomic_clearbits_u32 sys/arch/amd64/compile/SYZKALLER/obj/machine/atomic.h:298 [inline]
#3  mi_switch+0x1c7 sys/kern/sched_bsd.c:392
#4  sleep_finish+0x110 sys/kern/kern_synch.c:303
#5  msleep+0x1af sleep_finish_timeout sys/kern/kern_synch.c:327 [inline]
#5  msleep+0x1af sleep_finish_all sys/kern/kern_synch.c:157 [inline]
#5  msleep+0x1af sys/kern/kern_synch.c:220
#6  scsi_xs_sync+0x14f sys/scsi/scsi_base.c:1339
#7  scsi_start+0x86 sys/scsi/scsi_base.c:938
#8  sdopen+0x22b sys/scsi/sd.c:400
#9  spec_open+0x41c sys/kern/spec_vnops.c:158
#10 VOP_OPEN+0x6a sys/kern/vfs_vops.c:153
#11 sr_meta_native_bootprobe+0xd3 sys/dev/softraid.c:1038
#12 sr_boot_assembly+0x1aa sys/dev/softraid.c:1202
#13 sr_attach+0x183 sys/dev/softraid.c:1822
#14 config_attach+0x347 sys/kern/subr_autoconf.c:404
#15 main+0x6de sys/kern/init_main.c:483
#16 longmode_hi+0x95
lock order "&pr->ps_mtx"(mutex) -> "&sched_lock"(sched_lock) first seen at:
#0  witness_checkorder+0x6a7 sys/kern/subr_witness.c:877
#1  __mp_lock+0xa1
#2  schedclock+0x99 sys/kern/sched_bsd.c:547
#3  hardclock+0x1d8 sys/kern/kern_clock.c:174
#4  lapic_clockintr+0x44 sys/arch/amd64/amd64/lapic.c:425
#5  Xresume_lapic_ltimer+0x26
#6  calcru+0x7 sys/kern/kern_resource.c:417
#7  sys_exit+0x17 sys/kern/kern_exit.c:94
#8  syscall+0x552 mi_syscall sys/sys/syscall_mi.h:99 [inline]
#8  syscall+0x552 sys/arch/amd64/amd64/trap.c:574
#9  Xsyscall+0x128
Stopped at      db_enter+0x18:  addq    $0x8,%rsp
ddb{1}> 
ddb{1}> set $lines = 0
ddb{1}> set $maxwidth = 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:398
witness_checkorder(ffffffff8236e2f8,9,0) at witness_checkorder+0xffc witness_debugger sys/kern/subr_witness.c:2504 [inline]
witness_checkorder(ffffffff8236e2f8,9,0) at witness_checkorder+0xffc sys/kern/subr_witness.c:1084
__mp_lock(ffffffff8236e0f0) at __mp_lock+0xa1
schedclock(ffff800020b15070) at schedclock+0x99 sys/kern/sched_bsd.c:547
hardclock(ffff800020bb95f0) at hardclock+0x1d8 sys/kern/kern_clock.c:174
lapic_clockintr(0,0) at lapic_clockintr+0x44 sys/arch/amd64/amd64/lapic.c:425
Xresume_lapic_ltimer(9,1,ffff800020b3ab28,0,ffff800020b3aa78,2000) at Xresume_lapic_ltimer+0x26
calcru(ffff800020b15070,0,1,ffff800020b15070) at calcru+0x7 sys/kern/kern_resource.c:417
sys_exit(ffff800020b15070,ffff800020bb9770,ffff800020bb97e0) at sys_exit+0x17 sys/kern/kern_exit.c:94
syscall(ffff800020bb9850) at syscall+0x552 mi_syscall sys/sys/syscall_mi.h:99 [inline]
syscall(ffff800020bb9850) at syscall+0x552 sys/arch/amd64/amd64/trap.c:574
Xsyscall(6,1,85,1,532,0) at Xsyscall+0x128
end of kernel
end trace frame: 0x7f7ffffbd9e0, count: -11
ddb{1}> show registers
rdi                              0x3
rsi               0xffffffff82243e20    __sancov_gen_cov_switch_values.122
rbp               0xffff800020bb93f0
rbx                              0x3
rdx                             0x8b
rcx                              0x3
rax                              0x3
r8                0xffffffff81da2df5    witness_checkorder+0xfd5
r9                               0x5
r10               0xf946c18084dd6b15
r11               0xdef91fa3ad5c917e
r12               0xfffffd8002661340
r13                              0xc
r14               0xffffffff8233cdd0    w_lodata+0x4df20
r15               0xffffffff82345ee0    w_lodata+0x57030
rip               0xffffffff819ca3d8    db_enter+0x18
cs                               0x8
rflags                         0x246
rsp               0xffff800020bb93e0
ss                              0x10
db_enter+0x18:  addq    $0x8,%rsp
ddb{1}> show proc
PROC (syz-executor3352) pid=79263 stat=dead
    flags process=1008<EXITING,SINGLEEXIT> proc=2000<WEXIT>
    pri=50, usrpri=76, nice=20
    forw=0xffffffffffffffff, list=0xffffffffffffffff,0xffffffffffffffff
    process=0xffff800020b3aa78 user=0xffff800020bb4000, vmspace=0xfffffd806e8ebb48
    estcpu=36, cpticks=3, pctcpu=0.0
    user=0, sys=1, intr=0
ddb{1}> ps
   PID     TID   PPID    UID  S       FLAGS  WAIT          COMMAND
 23377  365022  68321      0  7           0                syz-executor3352
 23377  155205  68321      0  2   0x4000000                syz-executor3352
 68321  383172   8656      0  3        0x80  nanosleep     syz-executor3352
 96743  274366   8656      0  3        0x80  nanosleep     syz-executor3352
  8656   56782   6498      0  3        0x82  nanosleep     syz-executor3352
  6498  109639  71189      0  3    0x10008a  pause         ksh
 71189  442522  19668      0  3        0x92  select        sshd
 49226   24056      1      0  3    0x100083  ttyin         getty
 19668   83452      1      0  3        0x80  select        sshd
 76852   55857  86698     73  2    0x100090                syslogd
 86698  436812      1      0  3    0x100082  netio         syslogd
 81323  270611      1     77  3    0x100090  poll          dhclient
 22654  156256      1      0  3        0x80  poll          dhclient
 26540  181559      0      0  2     0x14200                zerothread
  5074  156114      0      0  3     0x14200  aiodoned      aiodoned
 28706  489458      0      0  3     0x14200  syncer        update
 45921   41391      0      0  3     0x14200  cleaner       cleaner
 37902  305699      0      0  3     0x14200  reaper        reaper
 14482  320646      0      0  3     0x14200  pgdaemon      pagedaemon
  8622  400588      0      0  3     0x14200  bored         crynlk
 84285  476876      0      0  3     0x14200  bored         crypto
 47632  507749      0      0  3  0x40014200  acpi0         acpi0
 45749   50659      0      0  3  0x40014200                idle1
 19016   17193      0      0  3     0x14200  bored         softnet
 96464  485971      0      0  3     0x14200  bored         systqmp
 44675  229173      0      0  3     0x14200  bored         systq
 65033  260115      0      0  3  0x40014200  bored         softclock
 17192  314582      0      0  3  0x40014200                idle0
 71801  444351      0      0  3     0x14200  bored         smr
     1  468104      0      0  3        0x82  wait          init
     0       0     -1      0  3     0x10200  scheduler     swapper
ddb{1}> show all locks
CPU 1:
exclusive mutex &pr->ps_mtx r = 0 (0xffff800020b3ab38)
#0  witness_lock+0x52e sys/kern/subr_witness.c:1161
#1  mtx_enter_try+0x102
#2  mtx_enter+0x4b sys/kern/kern_lock.c:266
#3  exit1+0x722 sys/kern/kern_exit.c:300
#4  sys_exit+0x17 sys/kern/kern_exit.c:94
#5  syscall+0x552 mi_syscall sys/sys/syscall_mi.h:99 [inline]
#5  syscall+0x552 sys/arch/amd64/amd64/trap.c:574
#6  Xsyscall+0x128
ddb{1}> show malloc
           Type InUse  MemUse  HighUse   Limit  Requests Type Lim Kern Lim
         devbuf  9442   6316K    6317K  78643K     10529        0        0
            pcb    23      9K       9K  78643K     72393        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  1174     74K      74K  78643K      1179        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  1808    196K     290K  78643K     12628        0        0
      file desc     1      0K       0K  78643K         1        0        0
           proc    40     38K      46K  78643K       207        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    18     79K      79K  78643K        18        0        0
           exec     0      0K       1K  78643K       152        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    58      3K       3K  78643K    109348        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   2715K    2779K  78643K      1720        0        0
      SYN cache     2     16K      16K  78643K         2        0        0
ddb{1}> 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    36191    0    36185     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     2     2     0     1     0     8    0
tcpcb      544    36177    0    36173     1     0     1     1     0     8    0
art_heap8  4096       1    0        0     1     0     1     1     0     8    0
art_heap4  256       96    0        0     6     0     6     6     0     8    0
art_table   32       97    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     1385    0       16    45     0    45    45     0     8    0
ffsino     272     1385    0       16    92     0    92    92     0     8    0
nchpl      144     1558    0       30    57     0    57    57     0     8    0
uvmvnodes   72     1394    0        0    26     0    26    26     0     8    0
vnodes     200     1394    0        0    74     0    74    74     0     8    0
namei      1024    3280    0     3280     3     3     0     1     0     8    0
percpumem   16       30    0        0     1     0     1     1     0     8    0
scxspl     192     2521    0     2521    53    52     1     6     0     8    1
sigapl     432    36348    0    36334     2     0     2     2     0     8    0
futexpl     56    53469    0    53469     1     0     1     1     0     8    1
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    72456    0    72449     3     2     1     1     0     8    0
fdescpl    488    36349    0    36335     2     0     2     2     0     8    0
filepl     152   181661    0   181619    20    17     3     3     0     8    1
lockfpl    104        6    0        6     1     1     0     1     0     8    0
lockfspl    48        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       47    0       40     1     0     1     1     0     8    0
zombiepl   144    36335    0    36334     3     2     1     1     0     8    0
processpl  888    36364    0    36334     4     0     4     4     0     8    0
procpl     600    72668    0    72637     3     0     3     3     0     8    0
sockpl     384   108571    0   108555    18    15     3     3     0     8    1
mcl4k      4096       2    0        0     1     0     1     1     0     8    0
mcl2k      2048      89    0        0    10     0    10    10     0     8    0
mtagpl      80        1    0        0     1     0     1     1     0     8    0
mbufpl     256      132    0        0     7     0     7     7     0     8    0
bufpl      256     2068    0      258   114     0   114   114     0     8    0
anonpl      16  1762918    0  1761702     8     2     6     6     0   125    0
amapchunkpl 152  109269    0   109228     2     0     2     2     0   158    0
amappl16   192    36250    0    36245     1     0     1     1     0     8    0
amappl14   176       14    0       13     3     2     1     1     0     8    0
amappl12   160       12    0       12     2     2     0     1     0     8    0
amappl11   152       48    0       34     1     0     1     1     0     8    0
amappl10   144       51    0       51     3     3     0     1     0     8    0
amappl9    136      392    0      391     1     0     1     1     0     8    0
amappl8    128    36257    0    36248     1     0     1     1     0     8    0
amappl7    120       17    0       16     1     0     1     1     0     8    0
amappl6    112       42    0       38     1     0     1     1     0     8    0
amappl5    104      110    0      101     1     0     1     1     0     8    0
amappl4     96      319    0      298     1     0     1     1     0     8    0
amappl3     88      155    0      144     1     0     1     1     0     8    0
amappl2     80   326213    0   326148     4     2     2     2     0     8    0
amappl1     72   844821    0   844399    14     4    10    14     0     8    0
amappl      80    72844    0    72820     1     0     1     1     0    84    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    36349    0    36334     1     0     1     1     0     8    0
uaddrbest   32        2    0        0     1     0     1     1     0     8    0
uaddr       24    36349    0    36334     1     0     1     1     0     8    0
vmmpekpl   168   330853    0   330833     2     0     2     2     0     8    0
vmmpepl    168  2537195    0  2536312    79    39    40    44     0   357    1
vmsppl     360    36348    0    36334     2     0     2     2     0     8    0
pdppl      4096   72706    0    72668     5     0     5     5     0     8    0
pvpl        32  3445091    0  3442138    49    24    25    27     0   265    1
pmappl     232    36348    0    36334     1     0     1     1     0     8    0
extentpl    40       41    0       26     1     0     1     1     0     8    0
phpool     112      245    0        5     7     0     7     7     0     8    0

Crashes (141):
Time Kernel Commit Syzkaller Config Log Report Syz repro C repro VM info Assets (help?) Manager Title
2019/06/01 05:43 openbsd 337db0858115 53c81ea5 .config console log report syz C ci-openbsd-setuid
2019/06/01 03:56 openbsd 337db0858115 53c81ea5 .config console log report syz C ci-openbsd-multicore
2019/06/02 01:47 openbsd 5d3046682a6c 53c81ea5 .config console log report ci-openbsd-setuid
2019/06/02 00:55 openbsd 5d3046682a6c 53c81ea5 .config console log report ci-openbsd-setuid
2019/06/01 23:41 openbsd 5d3046682a6c 53c81ea5 .config console log report ci-openbsd-setuid
2019/06/01 22:15 openbsd 5d3046682a6c 53c81ea5 .config console log report ci-openbsd-setuid
2019/06/01 21:09 openbsd 5d3046682a6c 53c81ea5 .config console log report ci-openbsd-setuid
2019/06/01 19:49 openbsd 5d3046682a6c 53c81ea5 .config console log report ci-openbsd-setuid
2019/06/01 19:41 openbsd 5d3046682a6c 53c81ea5 .config console log report ci-openbsd-setuid
2019/06/01 18:34 openbsd 5d3046682a6c 53c81ea5 .config console log report ci-openbsd-setuid
2019/06/01 17:08 openbsd 5d3046682a6c 53c81ea5 .config console log report ci-openbsd-multicore
2019/06/01 16:07 openbsd 5d3046682a6c 53c81ea5 .config console log report ci-openbsd-setuid
2019/06/01 15:39 openbsd 5d3046682a6c 53c81ea5 .config console log report ci-openbsd-setuid
2019/06/01 14:25 openbsd 5d3046682a6c 53c81ea5 .config console log report ci-openbsd-setuid
2019/06/01 13:13 openbsd 5d3046682a6c 53c81ea5 .config console log report ci-openbsd-setuid
2019/06/01 12:38 openbsd 337db0858115 53c81ea5 .config console log report ci-openbsd-setuid
2019/06/01 11:30 openbsd 337db0858115 53c81ea5 .config console log report ci-openbsd-setuid
2019/06/01 10:30 openbsd 337db0858115 53c81ea5 .config console log report ci-openbsd-setuid
2019/06/01 09:25 openbsd 337db0858115 53c81ea5 .config console log report ci-openbsd-setuid
2019/06/01 09:11 openbsd 337db0858115 53c81ea5 .config console log report ci-openbsd-setuid
2019/06/01 08:51 openbsd 337db0858115 53c81ea5 .config console log report ci-openbsd-setuid
2019/06/01 08:45 openbsd 337db0858115 53c81ea5 .config console log report ci-openbsd-setuid
2019/06/01 08:39 openbsd 337db0858115 53c81ea5 .config console log report ci-openbsd-setuid
2019/06/01 08:37 openbsd 337db0858115 53c81ea5 .config console log report ci-openbsd-multicore
2019/06/01 08:30 openbsd 337db0858115 53c81ea5 .config console log report ci-openbsd-multicore
2019/06/01 08:13 openbsd 337db0858115 53c81ea5 .config console log report ci-openbsd-setuid
2019/06/01 08:05 openbsd 337db0858115 53c81ea5 .config console log report ci-openbsd-multicore
2019/06/01 07:50 openbsd 337db0858115 53c81ea5 .config console log report ci-openbsd-setuid
2019/06/01 07:45 openbsd 337db0858115 53c81ea5 .config console log report ci-openbsd-multicore
2019/06/01 07:42 openbsd 337db0858115 53c81ea5 .config console log report ci-openbsd-setuid
2019/06/01 07:42 openbsd 337db0858115 53c81ea5 .config console log report ci-openbsd-setuid
2019/06/01 07:37 openbsd 337db0858115 53c81ea5 .config console log report ci-openbsd-multicore
2019/06/01 07:32 openbsd 337db0858115 53c81ea5 .config console log report ci-openbsd-setuid
2019/06/01 06:50 openbsd 337db0858115 53c81ea5 .config console log report ci-openbsd-multicore
2019/06/01 06:42 openbsd 337db0858115 53c81ea5 .config console log report ci-openbsd-setuid
2019/06/01 06:36 openbsd 337db0858115 53c81ea5 .config console log report ci-openbsd-multicore
2019/06/01 06:13 openbsd 337db0858115 53c81ea5 .config console log report ci-openbsd-multicore
2019/06/01 06:10 openbsd 337db0858115 53c81ea5 .config console log report ci-openbsd-multicore
2019/06/01 06:08 openbsd 337db0858115 53c81ea5 .config console log report ci-openbsd-setuid
2019/06/01 05:33 openbsd 337db0858115 53c81ea5 .config console log report ci-openbsd-multicore
2019/06/01 05:26 openbsd 337db0858115 53c81ea5 .config console log report ci-openbsd-multicore
2019/06/01 05:21 openbsd 337db0858115 53c81ea5 .config console log report ci-openbsd-multicore
2019/06/01 05:04 openbsd 337db0858115 53c81ea5 .config console log report ci-openbsd-setuid
2019/06/01 04:55 openbsd 337db0858115 53c81ea5 .config console log report ci-openbsd-setuid
2019/06/01 00:10 openbsd 337db0858115 53c81ea5 .config console log report ci-openbsd-setuid
* Struck through repros no longer work on HEAD.