syzbot


panic: mtx ADDR: locking against myself

Status: fixed on 2019/04/22 08:46
Reported-by: syzbot+135587e4f892b4c1214c@syzkaller.appspotmail.com
Fix commit: vmm(4): remove a debug printf that was causing lock issues (it was being called from an IPI routine).
First crash: 1317d, last: 1317d

Sample crash report:
login: panic: mtx 0xffffffff821ae640: locking against myself
Stopped at      db_enter+0x18:  addq    $0x8,%rsp
    TID    PID    UID     PRFLAGS     PFLAGS  CPU  COMMAND
 379694   1843      0         0x2          0    0K syz-executor1308
db_enter() at db_enter+0x18 sys/arch/amd64/amd64/db_interface.c:398
panic() at panic+0x174 sys/kern/subr_prf.c:208
__mtx_enter_try(ffffffff821ae640) at __mtx_enter_try+0x131 sys/kern/kern_lock.c:297
_mtx_enter(ffffffff821ae640,ffffffff81fb85c6,1ff) at _mtx_enter+0x54 __mtx_enter sys/kern/kern_lock.c:267 [inline]
_mtx_enter(ffffffff821ae640,ffffffff81fb85c6,1ff) at _mtx_enter+0x54 sys/kern/kern_lock.c:447
printf(ffffffff81fcd105) at printf+0x6b sys/kern/subr_prf.c:511
splassert_fail(d,e,ffffffff81fb0566) at splassert_fail+0x67 sys/kern/subr_prf.c:223
witness_lock(ffffffff823c2350,8,ffffffff81fa3cf4,1bc) at witness_lock+0x423 witness_lock_stack_get sys/kern/subr_witness.c:1880 [inline]
witness_lock(ffffffff823c2350,8,ffffffff81fa3cf4,1bc) at witness_lock+0x423 sys/kern/subr_witness.c:1199
wakeup_n(ffff800000970a88,ffffffff) at wakeup_n+0x43 sys/kern/kern_synch.c:444
tputchar(73,ffff800000970a00) at tputchar+0xf5 ttstart sys/kern/tty.c:1341 [inline]
tputchar(73,ffff800000970a00) at tputchar+0xf5 sys/kern/tty.c:2277
kputchar(73,5,0) at kputchar+0xe6 sys/kern/subr_prf.c:342
kprintf() at kprintf+0x1b2c sys/kern/subr_prf.c:1058
printf(ffffffff81f68c1b) at printf+0x80 sys/kern/subr_prf.c:512
start_vmm_on_cpu(ffff800020aa0ff0) at start_vmm_on_cpu+0x165 sys/arch/amd64/amd64/vmm.c:922
x86_ipi_handler() at x86_ipi_handler+0xc6 sys/arch/amd64/amd64/ipi.c:106
end trace frame: 0xffff800020add420, count: 0
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{1}> 
ddb{1}> set $lines = 0
ddb{1}> set $maxwidth = 0
ddb{1}> show panic
mtx 0xffffffff821ae640: locking against myself
ddb{1}> trace
db_enter() at db_enter+0x18 sys/arch/amd64/amd64/db_interface.c:398
panic() at panic+0x174 sys/kern/subr_prf.c:208
__mtx_enter_try(ffffffff821ae640) at __mtx_enter_try+0x131 sys/kern/kern_lock.c:297
_mtx_enter(ffffffff821ae640,ffffffff81fb85c6,1ff) at _mtx_enter+0x54 __mtx_enter sys/kern/kern_lock.c:267 [inline]
_mtx_enter(ffffffff821ae640,ffffffff81fb85c6,1ff) at _mtx_enter+0x54 sys/kern/kern_lock.c:447
printf(ffffffff81fcd105) at printf+0x6b sys/kern/subr_prf.c:511
splassert_fail(d,e,ffffffff81fb0566) at splassert_fail+0x67 sys/kern/subr_prf.c:223
witness_lock(ffffffff823c2350,8,ffffffff81fa3cf4,1bc) at witness_lock+0x423 witness_lock_stack_get sys/kern/subr_witness.c:1880 [inline]
witness_lock(ffffffff823c2350,8,ffffffff81fa3cf4,1bc) at witness_lock+0x423 sys/kern/subr_witness.c:1199
wakeup_n(ffff800000970a88,ffffffff) at wakeup_n+0x43 sys/kern/kern_synch.c:444
tputchar(73,ffff800000970a00) at tputchar+0xf5 ttstart sys/kern/tty.c:1341 [inline]
tputchar(73,ffff800000970a00) at tputchar+0xf5 sys/kern/tty.c:2277
kputchar(73,5,0) at kputchar+0xe6 sys/kern/subr_prf.c:342
kprintf() at kprintf+0x1b2c sys/kern/subr_prf.c:1058
printf(ffffffff81f68c1b) at printf+0x80 sys/kern/subr_prf.c:512
start_vmm_on_cpu(ffff800020aa0ff0) at start_vmm_on_cpu+0x165 sys/arch/amd64/amd64/vmm.c:922
x86_ipi_handler() at x86_ipi_handler+0xc6 sys/arch/amd64/amd64/ipi.c:106
Xresume_lapic_ipi(0,3,1388,0,0,ffff80000001db00) at Xresume_lapic_ipi+0x23
acpicpu_idle() at acpicpu_idle+0x301 sys/dev/acpi/acpicpu.c:1187
sched_idle(ffff800020aa0ff0) at sched_idle+0x422 sys/kern/kern_sched.c:181
end trace frame: 0x0, count: -17
ddb{1}> show registers
rdi                                0
rsi                              0x1
rbp               0xffff800020adcda0
rbx               0xffff800020adce50
rdx               0xffffffff81fb85c6    apollo_pio_rec+0x7a19
rcx                            0x201
rax                              0x1
r8                0xffffffff8100f603    kprintf+0x173
r9                               0x1
r10               0xca0962e79a982b18
r11               0xaa5d3a25fb8dff8c
r12                     0x3000000008
r13               0xffff800020adcdb0
r14                            0x100
r15                              0x1
rip               0xffffffff81cdc368    db_enter+0x18
cs                               0x8
rflags                         0x246
rsp               0xffff800020adcd90
ss                              0x10
db_enter+0x18:  addq    $0x8,%rsp
ddb{1}> show proc
PROC (idle1) pid=136800 stat=onproc
    flags process=14000<NOZOMBIE,SYSTEM> proc=40000200<SYSTEM,CPUPEG>
    pri=0, usrpri=50, nice=20
    forw=0x65486e589328cc26, list=0xffff800020ab0e10,0xffff800020ab0010
    process=0xffff800020ab33b0 user=0xffff800020ad8000, vmspace=0xffffffff8236e8e8
    estcpu=0, cpticks=3043, pctcpu=0.0
    user=0, sys=0, intr=0
ddb{1}> ps
   PID     TID   PPID    UID  S       FLAGS  WAIT          COMMAND
  1843  379694  67005      0  7         0x2                syz-executor1308
 67005  140859  46819      0  3    0x10008a  pause         ksh
 46819  163666  99561      0  3        0x92  select        sshd
 27917  137465      1      0  3    0x100083  ttyin         getty
 99561  250835      1      0  3        0x80  select        sshd
 35446  468839  99376     74  3    0x100092  bpf           pflogd
 99376   98313      1      0  3        0x80  netio         pflogd
 61015   84409  44635     73  3    0x100090  kqread        syslogd
 44635  340294      1      0  3    0x100082  netio         syslogd
 83561  242693      1     77  3    0x100090  poll          dhclient
 69512  412288      1      0  3        0x80  poll          dhclient
 29589  104735      0      0  3     0x14200  pgzero        zerothread
 75168  460541      0      0  3     0x14200  aiodoned      aiodoned
 71879   31311      0      0  3     0x14200  syncer        update
 47530   12707      0      0  3     0x14200  cleaner       cleaner
 50205  350331      0      0  3     0x14200  reaper        reaper
 85643  226705      0      0  3     0x14200  pgdaemon      pagedaemon
 34387   19927      0      0  3     0x14200  bored         crynlk
 27256   61234      0      0  3     0x14200  bored         crypto
 50166  375141      0      0  3  0x40014200  acpi0         acpi0
*26904  136800      0      0  7  0x40014200                idle1
  6891  302887      0      0  3     0x14200  bored         softnet
 33217   19750      0      0  3     0x14200  bored         systqmp
 38364  399393      0      0  3     0x14200  bored         systq
 90129   36432      0      0  3  0x40014200  bored         softclock
 88405  346170      0      0  3  0x40014200                idle0
 39799  224024      0      0  3     0x14200  bored         smr
     1  229434      0      0  3        0x82  wait          init
     0       0     -1      0  3     0x10200  scheduler     swapper
ddb{1}> show all locks
CPU 1:
exclusive sched_lock &sched_lock r = 0 (0xffffffff823c2350) locked @ /syzkaller/managers/multicore/kernel/sys/kern/kern_synch.c:444
Process 1843 (syz-executor1308) thread 0xffff800020b75078 (379694)
exclusive kernel_lock &kernel_lock r = 0 (0xffffffff8236d9f8) locked @ /syzkaller/managers/multicore/kernel/sys/sys/syscall_mi.h:90
#0  witness_lock+0x5a4 sys/kern/subr_witness.c:1201
#1  syscall+0x45e mi_syscall sys/sys/syscall_mi.h:91 [inline]
#1  syscall+0x45e sys/arch/amd64/amd64/trap.c:574
#2  Xsyscall+0x128
ddb{1}> show malloc
           Type InUse  MemUse  HighUse   Limit  Requests Type Lim Kern Lim
         devbuf  9451   6382K    6383K  78643K     10538        0        0
            pcb    25      9K       9K  78643K        57        0        0
         rtable    61      2K       2K  78643K       125        0        0
         ifaddr    25      7K       7K  78643K        26        0        0
       counters    39     33K      33K  78643K        39        0        0
       ioctlops     1      2K       4K  78643K      1468        0        0
          mount     1      1K       1K  78643K         1        0        0
         vnodes  1169     73K      73K  78643K      1174        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     2      2K       3K  78643K         4        0        0
           proc    52     50K      58K  78643K       279        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    24    106K     106K  78643K        24        0        0
           exec     0      0K       1K  78643K       179        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    53      3K       3K  78643K       764        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     4      0K       0K  78643K         4        0        0
           temp    39   2692K    2756K  78643K      1995        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       29    0       23     1     0     1     1     0     8    0
plimitpl   152       14    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
pfosfp      40      846    0      423     5     0     5     5     0     8    0
pfosfpen   112     1428    0      714    21     0    21    21     0     8    0
pfstitem    24        8    0        0     1     0     1     1     0     8    0
pfstkey    112        8    0        0     1     0     1     1     0     8    0
pfstate    328        8    0        0     1     0     1     1     0     8    0
pfrule     1360      21    0       16     2     1     1     2     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     1393    0       18    45     0    45    45     0     8    0
ffsino     272     1393    0       18    92     0    92    92     0     8    0
nchpl      144     1566    0       33    57     0    57    57     0     8    0
uvmvnodes   72     1403    0        0    26     0    26    26     0     8    0
vnodes     200     1403    0        0    74     0    74    74     0     8    0
namei      1024    3556    0     3556     1     0     1     1     0     8    1
percpumem   16       30    0        0     1     0     1     1     0     8    0
scxspl     192     2311    0     2311     2     1     1     2     0     8    1
sigapl     432      205    0      193     2     0     2     2     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      134    0      127     2     1     1     1     0     8    0
fdescpl    488      206    0      193     3     0     3     3     0     8    0
filepl     152      964    0      914     2     0     2     2     0     8    0
lockfpl    104        6    0        6     1     1     0     1     0     8    0
lockfspl    32        3    0        3     1     1     0     1     0     8    0
sessionpl  112       18    0        9     1     0     1     1     0     8    0
pgrppl      48       18    0        9     1     0     1     1     0     8    0
ucredpl     96       55    0       46     1     0     1     1     0     8    0
zombiepl   144      193    0      193     2     1     1     1     0     8    1
processpl  840      221    0      193     4     0     4     4     0     8    0
procpl     600      221    0      193     3     0     3     3     0     8    0
sockpl     384       73    0       55     2     0     2     2     0     8    0
mcl4k      4096       3    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       84    0        0     6     0     6     6     0     8    0
bufpl      256     2133    0      271   117     0   117   117     0     8    0
anonpl      16    19041    0    17839     8     2     6     7     0   125    1
amapchunkpl 152     554    0      517     2     0     2     2     0   158    0
amappl16   192       89    0       83     1     0     1     1     0     8    0
amappl14   176       16    0       15     2     1     1     1     0     8    0
amappl12   160        3    0        3     1     0     1     1     0     8    1
amappl11   152       46    0       28     1     0     1     1     0     8    0
amappl10   144       55    0       53     1     0     1     1     0     8    0
amappl9    136      422    0      421     1     0     1     1     0     8    0
amappl8    128       97    0       93     1     0     1     1     0     8    0
amappl7    120       21    0       20     1     0     1     1     0     8    0
amappl6    112       47    0       42     1     0     1     1     0     8    0
amappl5    104      116    0      102     1     0     1     1     0     8    0
amappl4     96      446    0      420     1     0     1     1     0     8    0
amappl3     88      105    0      100     1     0     1     1     0     8    0
amappl2     80      598    0      558     1     0     1     1     0     8    0
amappl1     72    13551    0    13135    15     5    10    15     0     8    0
amappl      72      427    0      406     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      206    0      193     1     0     1     1     0     8    0
uaddrbest   32        2    0        0     1     0     1     1     0     8    0
uaddr       24      206    0      193     1     0     1     1     0     8    0
vmmpekpl   168     5609    0     5588     2     0     2     2     0     8    0
vmmpepl    168    27138    0    26382    46     9    37    46     0   357    2
vmsppl     360      205    0      193     2     0     2     2     0     8    0
pdppl      4096     420    0      386     6     0     6     6     0     8    0
pvpl        32    80161    0    77225    31     3    28    28     0   265    3
pmappl     232      205    0      193     1     0     1     1     0     8    0
extentpl    40       39    0       25     1     0     1     1     0     8    0
phpool     112      247    0        3     7     0     7     7     0     8    0
ddb{1}> 

Crashes (3):
Manager Time Kernel Commit Syzkaller Config Log Report Syz repro C repro VM info Title
ci-openbsd-multicore 2019/04/21 00:36 openbsd e2502dba36e3 b0e8efcb .config log report syz C
ci-openbsd-multicore 2019/04/21 00:15 openbsd e2502dba36e3 b0e8efcb .config log report
ci-openbsd-multicore 2019/04/20 07:23 openbsd 59d550fca72e b0e8efcb .config log report
* Struck through repros no longer work on HEAD.