syzbot


panic: acquiring blockable sleep lock with spinlock or critical section held (rwlock) solock

Status: fixed on 2021/04/27 09:44
Reported-by: syzbot+eb593ee96235d71ade89@syzkaller.appspotmail.com
Fix commit: Revert per-socket `so_lock' rwlock(9) and use it to protect routing (PF_ROUTE) sockets. There is a locking issue with timeouts that needs to be fixed. Requested by deraadt@
First crash: 1305d, last: 1304d

Sample crash report:
panic: acquiring blockable sleep lock with spinlock or critical section held (rwlock) solock
Stopped at      db_enter+0x18:  addq    $0x8,%rsp
    TID    PID    UID     PRFLAGS     PFLAGS  CPU  COMMAND
db_enter() at db_enter+0x18 sys/arch/amd64/amd64/db_interface.c:398
panic(ffffffff823e5094) at panic+0x15e sys/kern/subr_prf.c:218
witness_checkorder(fffffd806e7ae990,9,0) at witness_checkorder+0x1188 sys/kern/subr_witness.c:833
rw_enter_write(fffffd806e7ae980) at rw_enter_write+0x5b sys/kern/kern_rwlock.c:128
solock(fffffd806e7ae978) at solock+0x97 sys/kern/uipc_socket2.c:299
rtm_senddesync_timer(fffffd806e7ae978) at rtm_senddesync_timer+0x1a sys/net/rtsock.c:454
timeout_run(fffffd806f5eacc0) at timeout_run+0xcc sys/kern/kern_timeout.c:674
softclock_process_tick_timeout(fffffd806f5eacc0,0) at softclock_process_tick_timeout+0x196 sys/kern/kern_timeout.c:721
softclock(0) at softclock+0x11a sys/kern/kern_timeout.c:752
softintr_dispatch(0) at softintr_dispatch+0xfb sys/arch/amd64/amd64/softintr.c:90
Xsoftclock() at Xsoftclock+0x1f
acpicpu_idle() at acpicpu_idle+0x2eb sys/dev/acpi/acpicpu.c:1206
sched_idle(ffffffff826ceff0) at sched_idle+0x417 sys/kern/kern_sched.c:178
end trace frame: 0x0, count: 2
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}> set $maxwidth = 0
ddb{0}> show panic
acquiring blockable sleep lock with spinlock or critical section held (rwlock) solock
ddb{0}> trace
db_enter() at db_enter+0x18 sys/arch/amd64/amd64/db_interface.c:398
panic(ffffffff823e5094) at panic+0x15e sys/kern/subr_prf.c:218
witness_checkorder(fffffd806e7ae990,9,0) at witness_checkorder+0x1188 sys/kern/subr_witness.c:833
rw_enter_write(fffffd806e7ae980) at rw_enter_write+0x5b sys/kern/kern_rwlock.c:128
solock(fffffd806e7ae978) at solock+0x97 sys/kern/uipc_socket2.c:299
rtm_senddesync_timer(fffffd806e7ae978) at rtm_senddesync_timer+0x1a sys/net/rtsock.c:454
timeout_run(fffffd806f5eacc0) at timeout_run+0xcc sys/kern/kern_timeout.c:674
softclock_process_tick_timeout(fffffd806f5eacc0,0) at softclock_process_tick_timeout+0x196 sys/kern/kern_timeout.c:721
softclock(0) at softclock+0x11a sys/kern/kern_timeout.c:752
softintr_dispatch(0) at softintr_dispatch+0xfb sys/arch/amd64/amd64/softintr.c:90
Xsoftclock() at Xsoftclock+0x1f
acpicpu_idle() at acpicpu_idle+0x2eb sys/dev/acpi/acpicpu.c:1206
sched_idle(ffffffff826ceff0) at sched_idle+0x417 sys/kern/kern_sched.c:178
end trace frame: 0x0, count: -13
ddb{0}> show registers
rdi                                0
rsi                              0x1
rbp               0xffff80002116f2b0
rbx               0xffff80002116f2c0
rdx                             0x8b
rcx                              0x2
rax                              0x1
r8                0xffffffff81c643c5    kprintf+0x145
r9                               0x1
r10               0x5cc7123f99afadc3
r11               0xe311def80f1586d1
r12                     0x3000000008
r13               0xffff80002116f360
r14                            0x100
r15                              0x1
rip               0xffffffff81bca908    db_enter+0x18
cs                               0x8
rflags                         0x246
rsp               0xffff80002116f2a0
ss                              0x10
db_enter+0x18:  addq    $0x8,%rsp
ddb{0}> show proc
PROC (idle0) pid=168646 stat=onproc
    flags process=14000<NOZOMBIE,SYSTEM> proc=40000200<SYSTEM,CPUPEG>
    pri=0, usrpri=50, nice=20
    forw=0xf481e9a34b046c3c, list=0xffff800021168540,0xffff8000211682b0
    process=0xffff8000fffff2a0 user=0xffff80002116a000, vmspace=0xffffffff82914f58
    estcpu=0, cpticks=3328, pctcpu=0.0
    user=0, sys=0, intr=0
ddb{0}> ps
   PID     TID   PPID    UID  S       FLAGS  WAIT          COMMAND
 97063  346355  83246      0  3        0x82  msgwait       syz-executor3018
 83246  188003  56641      0  3    0x10008a  sigsusp       ksh
 56641  309159  44396      0  3        0x92  select        sshd
 65423  281098      1      0  3    0x100083  ttyin         getty
 44396  100409      1      0  3        0x80  select        sshd
 97543   23055  14389     73  3    0x100090  kqread        syslogd
 14389    4984      1      0  3    0x100082  netio         syslogd
 94015   37359      1     77  3    0x100090  poll          dhclient
 52022  128125      1      0  3        0x80  poll          dhclient
 79434  310923      0      0  3     0x14200  bored         smr
 78056  149471      0      0  3     0x14200  pgzero        zerothread
 47499   69030      0      0  3     0x14200  aiodoned      aiodoned
 34147    9873      0      0  3     0x14200  syncer        update
 44082   72676      0      0  3     0x14200  cleaner       cleaner
 66860  234816      0      0  3     0x14200  reaper        reaper
 58815   72721      0      0  3     0x14200  pgdaemon      pagedaemon
 17078  193614      0      0  3     0x14200  bored         crynlk
  5467  348031      0      0  3     0x14200  bored         crypto
 81361  356728      0      0  3     0x14200  bored         viomb
 63496  214254      0      0  3  0x40014200  acpi0         acpi0
 38275   60738      0      0  7  0x40014200                idle1
 72094  351429      0      0  3     0x14200  bored         softnet
 42911    1261      0      0  3     0x14200  bored         systqmp
 18340  210093      0      0  3     0x14200  bored         systq
 87168  133344      0      0  3  0x40014200  bored         softclock
*60102  168646      0      0  7  0x40014200                idle0
     1  289109      0      0  3        0x82  wait          init
     0       0     -1      0  3     0x10200  scheduler     swapper
ddb{0}> show all locks
CPU 0:
shared mutex timeout r = 0 (0xffffffff82721dc8)
#0  witness_lock+0x4b0 stacktrace_save sys/sys/stacktrace.h:36 [inline]
#0  witness_lock+0x4b0 sys/kern/subr_witness.c:1182
#1  timeout_run+0xb7 sys/kern/kern_timeout.c:670
#2  softclock_process_tick_timeout+0x196 sys/kern/kern_timeout.c:721
#3  softclock+0x11a sys/kern/kern_timeout.c:752
#4  softintr_dispatch+0xfb sys/arch/amd64/amd64/softintr.c:90
#5  Xsoftclock+0x1f
#6  acpicpu_idle+0x2eb sys/dev/acpi/acpicpu.c:1206
#7  sched_idle+0x417 sys/kern/kern_sched.c:178
#8  proc_trampoline+0x1c
Process 60102 (idle0) thread 0xffff800021168000 (168646)
exclusive kernel_lock &kernel_lock r = 0 (0xffffffff8290dfb0)
#0  witness_lock+0x4b0 stacktrace_save sys/sys/stacktrace.h:36 [inline]
#0  witness_lock+0x4b0 sys/kern/subr_witness.c:1182
#1  softintr_dispatch+0x4e sys/arch/amd64/amd64/softintr.c:90
#2  Xsoftclock+0x1f
#3  acpicpu_idle+0x2eb sys/dev/acpi/acpicpu.c:1206
#4  sched_idle+0x417 sys/kern/kern_sched.c:178
#5  proc_trampoline+0x1c
shared mutex timeout r = 0 (0xffffffff82721dc8)
#0  witness_lock+0x4b0 stacktrace_save sys/sys/stacktrace.h:36 [inline]
#0  witness_lock+0x4b0 sys/kern/subr_witness.c:1182
#1  timeout_run+0xb7 sys/kern/kern_timeout.c:670
#2  softclock_process_tick_timeout+0x196 sys/kern/kern_timeout.c:721
#3  softclock+0x11a sys/kern/kern_timeout.c:752
#4  softintr_dispatch+0xfb sys/arch/amd64/amd64/softintr.c:90
#5  Xsoftclock+0x1f
#6  acpicpu_idle+0x2eb sys/dev/acpi/acpicpu.c:1206
#7  sched_idle+0x417 sys/kern/kern_sched.c:178
#8  proc_trampoline+0x1c
ddb{0}> show malloc
           Type InUse  MemUse  HighUse   Limit  Requests Type Lim
         devbuf  9469   6344K    6345K  78643K     10559        0
            pcb    13      8K       8K  78643K        13        0
         rtable    61      2K       2K  78643K       113        0
         ifaddr    24      7K       7K  78643K        24        0
       counters    40     33K      33K  78643K        40        0
       ioctlops     0      0K       2K  78643K        13        0
          mount     1      1K       1K  78643K         1        0
            log     0      0K       0K  78643K         1        0
         vnodes  1182     74K      74K  78643K      1187        0
      UFS quota     1     32K      32K  78643K         1        0
      UFS mount     5     36K      36K  78643K         5        0
            shm     2      1K       1K  78643K         2        0
         VM map     2      1K       1K  78643K         2        0
            sem     2      0K       0K  78643K         2        0
        dirhash    12      2K       2K  78643K        12        0
           ACPI  1697    195K     286K  78643K     12598        0
      file desc     1      0K       0K  78643K         1        0
           proc    47     50K      58K  78643K       274        0
    NFS srvsock     1      0K       0K  78643K         1        0
     NFS daemon     1     16K      16K  78643K         1        0
       in_multi    11      0K       0K  78643K        11        0
    ether_multi     1      0K       0K  78643K         1        0
    ISOFS mount     1     32K      32K  78643K         1        0
  MSDOSFS mount     1     16K      16K  78643K         1        0
           ttys    19     95K      95K  78643K        19        0
           exec     0      0K       2K  78643K       259        0
        pagedep     1      8K       8K  78643K         1        0
       inodedep     1     32K      32K  78643K         1        0
         newblk     1      0K       0K  78643K         1        0
        VM swap     7     26K      26K  78643K         7        0
       UVM amap    56      2K       4K  78643K      1167        0
       UVM aobj     3      2K       2K  78643K         3        0
        memdesc     1      4K       4K  78643K         1        0
    crypto data     1      1K       1K  78643K         1        0
            NDP     3      0K       0K  78643K         3        0
           temp    19   3965K    4029K  78643K      1436        0
         kqueue     2      2K       2K  78643K         2        0
      SYN cache     2     16K      16K  78643K         2        0
ddb{0}> show all pools
Name      Size Requests Fail Releases Pgreq Pgrel Npage Hiwat Minpg Maxpg Idle
plcache    128       20    0        0     1     0     1     1     0     8    0
rtpcb      120       16    0       13     1     0     1     1     0     8    0
rtentry    112       23    0        1     1     0     1     1     0     8    0
unpcb      120       27    0       19     1     0     1     1     0     8    0
syncache   296        5    0        5     2     1     1     1     0     8    1
tcpcb      736        8    0        5     1     0     1     1     0     8    0
arp         64        2    0        0     1     0     1     1     0     8    0
inpcb      304       21    0       16     1     0     1     1     0     8    0
art_heap8  4096       1    0        0     1     0     1     1     0     8    0
art_heap4  256       95    0        0     6     0     6     6     0     8    0
art_table   32       96    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
dino2pl    256     1391    0       15    86     0    86    86     0     8    0
ffsino     272     1391    0       15    92     0    92    92     0     8    0
nchpl      144     1567    0       31    57     0    57    57     0     8    0
uvmvnodes   72     1400    0        0    26     0    26    26     0     8    0
vnodes     224     1400    0        0    83     0    83    83     0     8    0
namei      1024    3486    0     3486     2     1     1     1     0     8    1
percpumem   16       31    0        0     1     0     1     1     0     8    0
scxspl     216     3346    0     3346     2     1     1     2     0     8    1
plimitpl   152       13    0        8     1     0     1     1     0     8    0
sigapl     424      192    0      165     4     0     4     4     0     8    0
knotepl    112        5    0        0     1     0     1     1     0     8    0
kqueuepl   168        1    0        0     1     0     1     1     0     8    0
pipepl     336       57    0       53     2     1     1     1     0     8    0
fdescpl    496      176    0      165     2     0     2     2     0     8    0
filepl     152      822    0      779     2     0     2     2     0     8    0
lockfpl    104        5    0        4     1     0     1     1     0     8    0
lockfspl    48        3    0        2     1     0     1     1     0     8    0
sessionpl  144       17    0        9     1     0     1     1     0     8    0
pgrppl      48       17    0        9     1     0     1     1     0     8    0
ucredpl     96       57    0       50     1     0     1     1     0     8    0
zombiepl   144      165    0      165     2     1     1     1     0     8    1
processpl  1080     192    0      165     3     1     2     3     0     8    0
procpl     672      192    0      165     3     0     3     3     0     8    0
sockpl     480       64    0       48     4     1     3     3     0     8    0
mcl4k      4096       3    0        0     1     0     1     1     0     8    0
mcl2k      2048      80    0        0    10     0    10    10     0     8    0
mtagpl      96        1    0        0     1     0     1     1     0     8    0
mbufpl     256      106    0        0     7     0     7     7     0     8    0
bufpl      280     1922    0       80   132     0   132   132     0     8    0
anonpl      24    25328    0    23667    13     2    11    12     0   186    0
amapchunkpl 152    2244    0     2146     5     0     5     5     0   158    0
amappl16   200       25    0       24     2     1     1     1     0     8    0
amappl15   192       44    0       38     1     0     1     1     0     8    0
amappl13   176       12    0       11     2     1     1     1     0     8    0
amappl12   168       22    0       19     1     0     1     1     0     8    0
amappl11   160       42    0       35     1     0     1     1     0     8    0
amappl10   152        8    0        5     1     0     1     1     0     8    0
amappl9    144      232    0      232     2     1     1     1     0     8    1
amappl8    136      203    0      201     1     0     1     1     0     8    0
amappl7    128       30    0       27     1     0     1     1     0     8    0
amappl6    120       74    0       65     1     0     1     1     0     8    0
amappl5    112      130    0      123     1     0     1     1     0     8    0
amappl4    104      406    0      386     1     0     1     1     0     8    0
amappl3     96       37    0       32     1     0     1     1     0     8    0
amappl2     88      306    0      269     1     0     1     1     0     8    0
amappl1     80     5895    0     5576     9     1     8     8     0     8    0
amappl      88      995    0      952     2     0     2     2     0    92    0
dma4096    4096       1    0        1     1     1     0     1     0     8    0
dma1024    1024       1    0        0     1     0     1     1     0     8    0
dma256     256        6    0        6     1     1     0     1     0     8    0
dma128     128      253    0      253     1     1     0     1     0     8    0
dma64       64        6    0        6     1     1     0     1     0     8    0
dma32       32        7    0        7     1     1     0     1     0     8    0
dma16       16       18    0       17     1     0     1     1     0     8    0
aobjpl      64        2    0        0     1     0     1     1     0     8    0
uaddrrnd    24      176    0      165     1     0     1     1     0     8    0
uaddrbest   32        2    0        0     1     0     1     1     0     8    0
uaddr       24      176    0      165     1     0     1     1     0     8    0
vmmpekpl   168     5148    0     5134     1     0     1     1     0     8    0
vmmpepl    168    17427    0    16741    41     7    34    35     0   357    3
vmsppl     368      175    0      165     2     0     2     2     0     8    0
rwobjpl     56     5428    0     4993     8     1     7     7     0     8    0
pdppl      4096     359    0      330    45    16    29    35     0     8    0
pvpl        32    85266    0    82022    35     5    30    30     0   265    2
pmappl     232      175    0      165     1     0     1     1     0     8    0
extentpl    40       58    0       40     1     0     1     1     0     8    0
phpool     112      261    0       20     8     0     8     8     0     8    0
ddb{0}> machine ddbcpu 0
Invalid cpu 0
ddb{0}> trace
db_enter() at db_enter+0x18 sys/arch/amd64/amd64/db_interface.c:398
panic(ffffffff823e5094) at panic+0x15e sys/kern/subr_prf.c:218
witness_checkorder(fffffd806e7ae990,9,0) at witness_checkorder+0x1188 sys/kern/subr_witness.c:833
rw_enter_write(fffffd806e7ae980) at rw_enter_write+0x5b sys/kern/kern_rwlock.c:128
solock(fffffd806e7ae978) at solock+0x97 sys/kern/uipc_socket2.c:299
rtm_senddesync_timer(fffffd806e7ae978) at rtm_senddesync_timer+0x1a sys/net/rtsock.c:454
timeout_run(fffffd806f5eacc0) at timeout_run+0xcc sys/kern/kern_timeout.c:674
softclock_process_tick_timeout(fffffd806f5eacc0,0) at softclock_process_tick_timeout+0x196 sys/kern/kern_timeout.c:721
softclock(0) at softclock+0x11a sys/kern/kern_timeout.c:752
softintr_dispatch(0) at softintr_dispatch+0xfb sys/arch/amd64/amd64/softintr.c:90
Xsoftclock() at Xsoftclock+0x1f
acpicpu_idle() at acpicpu_idle+0x2eb sys/dev/acpi/acpicpu.c:1206
sched_idle(ffffffff826ceff0) at sched_idle+0x417 sys/kern/kern_sched.c:178
end trace frame: 0x0, count: -13
ddb{0}> machine ddbcpu 1
Stopped at      x86_ipi_db+0x1a:        addq    $0x8,%rsp
x86_ipi_db(ffff800020d58ff0) at x86_ipi_db+0x1a sys/arch/amd64/amd64/db_interface.c:352
x86_ipi_handler() at x86_ipi_handler+0xb7 sys/arch/amd64/amd64/ipi.c:106
Xresume_lapic_ipi() at Xresume_lapic_ipi+0x23
acpicpu_idle() at acpicpu_idle+0x2eb sys/dev/acpi/acpicpu.c:1206
sched_idle(ffff800020d58ff0) at sched_idle+0x417 sys/kern/kern_sched.c:178
end trace frame: 0x0, count: 10
ddb{1}> trace
x86_ipi_db(ffff800020d58ff0) at x86_ipi_db+0x1a sys/arch/amd64/amd64/db_interface.c:352
x86_ipi_handler() at x86_ipi_handler+0xb7 sys/arch/amd64/amd64/ipi.c:106
Xresume_lapic_ipi() at Xresume_lapic_ipi+0x23
acpicpu_idle() at acpicpu_idle+0x2eb sys/dev/acpi/acpicpu.c:1206
sched_idle(ffff800020d58ff0) at sched_idle+0x417 sys/kern/kern_sched.c:178
end trace frame: 0x0, count: -5
ddb{1}> 

Crashes (4):
Time Kernel Commit Syzkaller Config Log Report Syz repro C repro VM info Assets (help?) Manager Title
2021/04/27 03:18 openbsd 634e70801b8a 8ee2dea6 .config console log report syz C ci-openbsd-setuid panic: acquiring blockable sleep lock with spinlock or critical section held (rwlock) solock
2021/04/26 06:57 openbsd b0cb8ce4b1d4 2a82f1b3 .config console log report syz ci-openbsd-setuid panic: acquiring blockable sleep lock with spinlock or critical section held (rwlock) solock
2021/04/27 02:58 openbsd 634e70801b8a 8ee2dea6 .config console log report ci-openbsd-setuid panic: acquiring blockable sleep lock with spinlock or critical section held (rwlock) solock
2021/04/26 06:41 openbsd b0cb8ce4b1d4 2a82f1b3 .config console log report ci-openbsd-setuid panic: acquiring blockable sleep lock with spinlock or critical section held (rwlock) solock
* Struck through repros no longer work on HEAD.