⬢ DragonFlyBSD Kernel Audit
DF-3982 / run.log
← back to finding ↓ download raw
=================================================================
DF-3982 mechanism verification - DragonFly 6.5-DEVELOPMENT guest
callout_stop() from the sbp_recv1 state (crit section / interrupt
path) BLOCKS in 'costp' while the target callout is INPROG, and the
wedged softclock thread cascades to unrelated tsleep timeouts.
=================================================================

RUN 1 (15s busy-wait callback, stop arrived after INPROG had cleared -
       negative-control datapoint: stop of a non-INPROG callout returns
       in 9 ms):
sbpprep[B]: armed 1-tick mgm_ocb_timeout replica
sbpprep[B]: mgm_timeout replica callback STARTED (INPROG set, cpu=2)
sbpprep[B]: mgm_timeout replica callback DONE (INPROG cleared after 15160238 usec)
sbpprep[B]: callout_stop() ENTERED inside crit section (sbp.c:1600 state) at 1789636881.479961
sbpprep[B]: callout_stop() RETURNED after 9 ms (callback body is 5000 ms) at 1789636881.489438
[the busy-wait body froze userland scheduling on the callback CPU, so the
 stopper landed late - replaced by the no-timeout-sleep design of RUN 2]

RUN 2 (callback blocks in 'bcb' until released - the sbp_mgm_timeout shape
       whose body completes only when the bus answers):
# arm, then background a fully-detached stopb (survives the ssh session):
$ sysctl kern.sbpprep_armb=1
kern.sbpprep_armb: 0 -> 0
$ (sysctl -n kern.sbpprep_stopb=1 >/dev/null 2>&1 </dev/null &); echo DETACHED
DETACHED
# 3 s later, LIVE CAPTURE:
$ ps -o pid,stat,wchan,comm -ax | grep sysctl | grep -v grep
  1237 D5     costp    sysctl          <-- callout_stop() caller asleep INSIDE crit (D-state)
$ ps -axH -o pid,tdpri,stat,wchan,comm | grep softclock
    -1    12 B1     -        softclock 1
    -1    12 B2     bcb      softclock 2   <-- mgm-timeout replica callback INPROG, blocked in body
    -1    12 B3     -        softclock 3
    -1    12 B4     -        softclock 4
    -1    12 B5     -        softclock 5
    -1    12 B0     -        softclock 0

# release attempt from a third thread (wakeb) with a 3 s tsleep before the
# wakeup - CASCADE: that tsleep's own timeout callout lands on the wedged
# cpu2 wheel and never fires:
$ sysctl -n kern.sbpprep_wakeb=1
sbpprep[B]: callout_stop() ENTERED inside crit section (sbp.c:1600 state) at 1789637158.530768
sbpprep[B]: wakeb: releasing callback in 3s (stopper has been in 'costp' all this time)
$ ps -o pid,stat,wchan,comm -ax | grep sysctl | grep -v grep
  1237 D5     costp    sysctl          <-- stopper, still blocked (crit held)
  1256 D2     wkdelay  sysctl          <-- third thread: tsleep timeout starved by wedged softclock

INTERPRETATION (mechanism PROVEN on the shipped kernel):
 1. kern_timeout.c callout_stop() (= _callout_cancel_or_stop(sync=1),
    kern_timeout.c:1091) sleeps in 'costp' (kern_timeout.c:923 ssleep) for
    the ENTIRE duration of an INPROG callback - even when the caller holds
    a critical section. sbp.c:1600/2590/2705 run in exactly that state
    (fwohci hard-IRQ: fwohcivar.h:37 FWOHCI_TASKQUEUE=0 -> fwohci_intr
    -> fwohci_intr_body -> fwohci_arcv crit_enter fwohci.c:2688 -> fw_rcv
    -> fw_xfer_done firewire.c:991 -> sbp_recv crit_enter sbp.c:1823).
    In the real driver the blocked context is the fwohci interrupt thread:
    the FireWire IRQ stalls for as long as sbp_mgm_timeout takes (its body
    does kprintf + sbp_reset_start -> fw_asyreq, allocation-dependent).
 2. Cascade: the softclock thread wedged INPROG in the callback starves
    every tsleep-with-timeout whose callout shares that CPU (observed live:
    wkdelay) - i.e. an unbounded set of unrelated kernel sleeps.
 Guest was wedged by design at the end of RUN 2 -> vm.sh reset with-src.