⬢ DragonFlyBSD Kernel Audit
DF-4099 / run.log
← back to finding ↓ download raw 
=============== DF-4097: XPT_RESET_DEV opcode clobber ===============
--- control: normal XPT_SCSI_IO TUR, CAM_DIR_NONE
[queue] err=0 id=0 bccb=0xfffff801167df620 flags=0x0 hccb(op=0x00 cmd_len=0 sense_len=0 din=0 dout=0 btstat=0x00 sdstat=0x00) ccb_status=0x0 timer=0 map=0 on_pending=0 comp=0 last_status=0x0 rec_kva=0x0 rec_flags=0x0 async_bdr=0 async_busrst=0 vregs=[00 00 00 00] outbox(ccb=0x00000000 act=0x00) active=0 free=0 pending=0
[snap] err=0 id=0 bccb=0xfffff801167df620 flags=0x1 hccb(op=0x00 cmd_len=6 sense_len=0 din=1 dout=1 btstat=0x00 sdstat=0x00) ccb_status=0x200 timer=1 map=1 on_pending=1 comp=0 last_status=0x0 rec_kva=0xfffff801167df690 rec_flags=0x0 async_bdr=0 async_busrst=0 vregs=[10 02 00 00] outbox(ccb=0x00000000 act=0x00) active=1 free=14 pending=1
--- XPT_RESET_DEV through the SAME production xpt_action path.
    btaction stores opcode 0x81 INITIATOR_BUS_DEV_RESET (bt.c:1062)
    but btexecuteccb's nseg==0 path overwrites it with 0x00
    INITIATOR_CCB (bt.c:1285), leaving cmd_len=0 sense_len=0
[queue] err=0 id=1 bccb=0xfffff801167df5b0 flags=0x0 hccb(op=0x00 cmd_len=0 sense_len=0 din=0 dout=0 btstat=0x00 sdstat=0x00) ccb_status=0x0 timer=0 map=0 on_pending=0 comp=0 last_status=0x0 rec_kva=0x0 rec_flags=0x0 async_bdr=0 async_busrst=0 vregs=[00 00 00 00] outbox(ccb=0x00000000 act=0x00) active=0 free=0 pending=0
[snap] err=0 id=1 bccb=0xfffff801167df5b0 flags=0x1 hccb(op=0x00 cmd_len=0 sense_len=0 din=1 dout=1 btstat=0x00 sdstat=0x00) ccb_status=0x200 timer=1 map=1 on_pending=1 comp=0 last_status=0x0 rec_kva=0xfffff801167df690 rec_flags=0x0 async_bdr=0 async_busrst=0 vregs=[10 02 00 00] outbox(ccb=0x00000000 act=0x00) active=2 free=13 pending=2
--- clean-complete both
[comp] err=0 id=0 bccb=0x167df620 flags=0x0 hccb(op=0x00 cmd_len=0 sense_len=0 din=0 dout=0 btstat=0x00 sdstat=0x00) ccb_status=0x0 timer=0 map=0 on_pending=0 comp=0 last_status=0x0 rec_kva=0x0 rec_flags=0x0 async_bdr=0 async_busrst=0 vregs=[00 00 00 00] outbox(ccb=0x00000000 act=0x00) active=0 free=0 pending=0
[comp] err=0 id=1 bccb=0x167df5b0 flags=0x0 hccb(op=0x00 cmd_len=0 sense_len=0 din=0 dout=0 btstat=0x00 sdstat=0x00) ccb_status=0x0 timer=0 map=0 on_pending=0 comp=0 last_status=0x0 rec_kva=0x0 rec_flags=0x0 async_bdr=0 async_busrst=0 vregs=[00 00 00 00] outbox(ccb=0x00000000 act=0x00) active=0 free=0 pending=0

=============== DF-4100: recovery BCCB never BCCB_ACTIVE ===============
--- queue one I/O, then fire the production bttimeout() on it
[queue] err=0 id=2 bccb=0xfffff801167df5b0 flags=0x0 hccb(op=0x00 cmd_len=0 sense_len=0 din=0 dout=0 btstat=0x00 sdstat=0x00) ccb_status=0x0 timer=0 map=0 on_pending=0 comp=0 last_status=0x0 rec_kva=0x0 rec_flags=0x0 async_bdr=0 async_busrst=0 vregs=[00 00 00 00] outbox(ccb=0x00000000 act=0x00) active=0 free=0 pending=0
[snap] err=0 id=2 bccb=0xfffff801167df5b0 flags=0x1 hccb(op=0x00 cmd_len=6 sense_len=0 din=1 dout=1 btstat=0x00 sdstat=0x00) ccb_status=0x200 timer=1 map=1 on_pending=1 comp=0 last_status=0x0 rec_kva=0xfffff801167df690 rec_flags=0x0 async_bdr=0 async_busrst=0 vregs=[10 02 00 00] outbox(ccb=0x00000000 act=0x00) active=1 free=14 pending=1
[timeout] err=0 id=2 bccb=0xfffff801167df5b0 flags=0x7 hccb(op=0x00 cmd_len=6 sense_len=0 din=1 dout=1 btstat=0x00 sdstat=0x00) ccb_status=0x200 timer=1 map=1 on_pending=1 comp=0 last_status=0x0 rec_kva=0xfffff801167df690 rec_flags=0x0 async_bdr=0 async_busrst=0 vregs=[10 02 00 00] outbox(ccb=0x00000000 act=0x00) active=1 free=14 pending=1
--- recovery_bccb flags at BDR-arm time: rec_flags=0 == BCCB_FREE;
    nothing ever sets BCCB_ACTIVE on it (only bt.c:1302 does, and the
    recovery BCCB never transits btexecuteccb)
--- firmware completes the BDR mailbox with BMBI_OK -> production
    btdone must hit the bt.c:1388 guard and return early
[comprec] err=0 id=0 bccb=0x167df690 flags=0x0 hccb(op=0x00 cmd_len=0 sense_len=0 din=0 dout=0 btstat=0x00 sdstat=0x00) ccb_status=0x0 timer=0 map=0 on_pending=0 comp=0 last_status=0x0 rec_kva=0x0 rec_flags=0x0 async_bdr=0 async_busrst=0 vregs=[00 00 00 00] outbox(ccb=0x00000000 act=0x00) active=0 free=0 pending=0
[snap] err=0 id=2 bccb=0xfffff801167df5b0 flags=0x7 hccb(op=0x00 cmd_len=6 sense_len=0 din=1 dout=1 btstat=0x00 sdstat=0x00) ccb_status=0x200 timer=1 map=1 on_pending=1 comp=0 last_status=0x0 rec_kva=0xfffff801167df690 rec_flags=0x0 async_bdr=0 async_busrst=0 vregs=[10 02 00 00] outbox(ccb=0x00000000 act=0x00) active=1 free=14 pending=1
--- AC_SENT_BDR must NOT fire (async_bdr stays 0); the pending CCB's
    timer must stay stopped -> recovery branch dead
--- 3s later the 2s re-arm (bt.c:2215) fires bttimeout again ->
    BCCB_DEVICE_RESET -> hard reset branch (bt.c:2199-2200)
[snap] err=0 id=2 bccb=0xfffff801167df5b0 flags=0x7 hccb(op=0x00 cmd_len=6 sense_len=0 din=1 dout=1 btstat=0x00 sdstat=0x00) ccb_status=0xb timer=0 map=1 on_pending=1 comp=0 last_status=0x0 rec_kva=0xfffff801167df690 rec_flags=0x0 async_bdr=0 async_busrst=0 vregs=[00 02 00 00] outbox(ccb=0x00000000 act=0x00) active=1 free=14 pending=1
vhba counters (hard_resets mbox_starts last_ctl): sysctl -n kern.dfbt_vhba_hard_resets kern.dfbt_vhba_mbox_starts kern.dfbt_vhba_last_ctl
1
1
128
(dfbt0:bt9:0:3:0): CCB 0xfffff801167df5b0 - timed out
unknown: btdone - Attempt to free non-active BCCB 0xfffff801167df690
(dfbt0:bt9:0:3:0): CCB 0xfffff801167df5b0 - timed out
unknown: No longer in timeout

=============== DF-4101: stale bttimeout on recycled CCB ===============
--- queue ccb-A (healthy, 60s timeout); hold bt->lock; fire the
    production bttimeout on a kthread which blocks acquiring the
    lock -- the in-progress handler callout_stop cannot cancel
[queue] err=0 id=3 bccb=0xfffff801167df620 flags=0x0 hccb(op=0x00 cmd_len=0 sense_len=0 din=0 dout=0 btstat=0x00 sdstat=0x00) ccb_status=0x0 timer=0 map=0 on_pending=0 comp=0 last_status=0x0 rec_kva=0x0 rec_flags=0x0 async_bdr=0 async_busrst=0 vregs=[00 00 00 00] outbox(ccb=0x00000000 act=0x00) active=0 free=0 pending=0
[snap] err=0 id=3 bccb=0xfffff801167df620 flags=0x1 hccb(op=0x00 cmd_len=6 sense_len=0 din=1 dout=1 btstat=0x00 sdstat=0x00) ccb_status=0x200 timer=1 map=1 on_pending=1 comp=0 last_status=0x0 rec_kva=0xfffff801167df690 rec_flags=0x0 async_bdr=0 async_busrst=0 vregs=[00 02 00 00] outbox(ccb=0x00000000 act=0x00) active=2 free=13 pending=2
[racefire] stale bttimeout thread entered
--- with the stale handler blocked: complete ccb-A (BMBI_OK) and
    queue ccb-B; production btgetccb recycles the SAME bccb
[comp] err=0 id=3 bccb=0x167df620 flags=0x0 hccb(op=0x00 cmd_len=0 sense_len=0 din=0 dout=0 btstat=0x00 sdstat=0x00) ccb_status=0x0 timer=0 map=0 on_pending=0 comp=0 last_status=0x0 rec_kva=0x0 rec_flags=0x0 async_bdr=0 async_busrst=0 vregs=[00 00 00 00] outbox(ccb=0x00000000 act=0x00) active=0 free=0 pending=0
[queue] err=0 id=4 bccb=0xfffff801167df620 flags=0x0 hccb(op=0x00 cmd_len=0 sense_len=0 din=0 dout=0 btstat=0x00 sdstat=0x00) ccb_status=0x0 timer=0 map=0 on_pending=0 comp=0 last_status=0x0 rec_kva=0x0 rec_flags=0x0 async_bdr=0 async_busrst=0 vregs=[00 00 00 00] outbox(ccb=0x00000000 act=0x00) active=0 free=0 pending=0
--- ccb-B dispatched on the recycled bccb (bccb_kva must equal A's):
[snap] err=0 id=4 bccb=0xfffff801167df620 flags=0x1 hccb(op=0x00 cmd_len=6 sense_len=0 din=1 dout=1 btstat=0x00 sdstat=0x00) ccb_status=0x200 timer=1 map=1 on_pending=1 comp=0 last_status=0x0 rec_kva=0xfffff801167df690 rec_flags=0x0 async_bdr=0 async_busrst=0 vregs=[00 02 00 00] outbox(ccb=0x00000000 act=0x00) active=2 free=13 pending=2
--- release the lock: the stale bttimeout proceeds on ccb-B
--- ccb-B (healthy, 60s) misreported as timed out: DEVICE_RESET flag,
    SIM frozen, BDR mailbox armed; ccb-A completed CAM_REQ_CMP:
[snap] err=0 id=3 bccb=0xfffff801167df620 flags=0x7 hccb(op=0x00 cmd_len=6 sense_len=0 din=1 dout=1 btstat=0x00 sdstat=0x00) ccb_status=0x1 timer=1 map=1 on_pending=1 comp=1 last_status=0x1 rec_kva=0xfffff801167df690 rec_flags=0x0 async_bdr=0 async_busrst=0 vregs=[00 02 00 00] outbox(ccb=0x00000000 act=0x00) active=2 free=13 pending=2
[snap] err=0 id=4 bccb=0xfffff801167df620 flags=0x7 hccb(op=0x00 cmd_len=6 sense_len=0 din=1 dout=1 btstat=0x00 sdstat=0x00) ccb_status=0x200 timer=1 map=1 on_pending=1 comp=0 last_status=0x0 rec_kva=0xfffff801167df690 rec_flags=0x0 async_bdr=0 async_busrst=0 vregs=[00 02 00 00] outbox(ccb=0x00000000 act=0x00) active=2 free=13 pending=2
--- 2s later: hard bus reset on the healthy bus; ccb-B completes
    CAM_CMD_TIMEOUT (0x0b):
[snap] err=0 id=4 bccb=0xfffff801167df620 flags=0x7 hccb(op=0x00 cmd_len=6 sense_len=0 din=1 dout=1 btstat=0x00 sdstat=0x00) ccb_status=0xb timer=0 map=1 on_pending=1 comp=0 last_status=0x0 rec_kva=0xfffff801167df690 rec_flags=0x0 async_bdr=0 async_busrst=0 vregs=[00 02 00 00] outbox(ccb=0x00000000 act=0x00) active=2 free=13 pending=2
2
1
128
(dfbt0:bt9:0:3:0): CCB 0xfffff801167df5b0 - timed out
(dfbt0:bt9:0:3:0): CCB 0xfffff801167df5b0 - timed out
unknown: No longer in timeout
[rig] stale handler thread: calling production bttimeout(0xfffff801167df620), will block on bt->lock
(dfbt0:bt9:0:3:0): CCB 0xfffff801167df620 - timed out
unknown: No longer in timeout

=============== DF-4099: unknown comp_code leaks the BCCB/CCB ===============
--- queue a CAM_DIR_IN command (512B, real dmamap)
[queuein] err=0 id=5 bccb=0xfffff801167df540 flags=0x0 hccb(op=0x00 cmd_len=0 sense_len=0 din=0 dout=0 btstat=0x00 sdstat=0x00) ccb_status=0x0 timer=0 map=0 on_pending=0 comp=0 last_status=0x0 rec_kva=0x0 rec_flags=0x0 async_bdr=0 async_busrst=0 vregs=[00 00 00 00] outbox(ccb=0x00000000 act=0x00) active=0 free=0 pending=0
--- firmware replies comp_code=0x42 (unknown; no default at
    bt.c:1451); callout_stop already ran at bt.c:1449
[compx] err=0 id=5 bccb=0x167df540 flags=0x0 hccb(op=0x00 cmd_len=0 sense_len=0 din=0 dout=0 btstat=0x00 sdstat=0x00) ccb_status=0x0 timer=0 map=0 on_pending=0 comp=0 last_status=0x0 rec_kva=0x0 rec_flags=0x0 async_bdr=0 async_busrst=0 vregs=[00 00 00 00] outbox(ccb=0x00000000 act=0x00) active=0 free=0 pending=0
--- 3s later: comp=0, flags=1 (ACTIVE), on_pending=1, timer=0:
    the BCCB and the CAM command are leaked forever
[snap] err=0 id=5 bccb=0xfffff801167df540 flags=0x1 hccb(op=0x03 cmd_len=6 sense_len=0 din=1 dout=0 btstat=0x00 sdstat=0x00) ccb_status=0x200 timer=0 map=1 on_pending=1 comp=0 last_status=0x0 rec_kva=0xfffff801167df690 rec_flags=0x0 async_bdr=0 async_busrst=0 vregs=[00 02 00 00] outbox(ccb=0x00000000 act=0x00) active=3 free=12 pending=3
--- exhaust every remaining BCCB the same way
RIGIOC_COMP: Invalid argument
RIGIOC_COMP: Invalid argument
RIGIOC_COMP: Invalid argument
RIGIOC_COMP: Invalid argument
--- all BCCBs leaked; the next I/O is CAM_REQUEUE_REQ'd (btgetccb
    NULL, resource_shortage, simq frozen) -> all I/O on the bus wedges
RIGIOC_COMP: Invalid argument
[queue] err=0 id=20 bccb=0x0 flags=0x0 hccb(op=0x00 cmd_len=0 sense_len=0 din=0 dout=0 btstat=0x00 sdstat=0x00) ccb_status=0x0 timer=0 map=0 on_pending=0 comp=0 last_status=0x0 rec_kva=0x0 rec_flags=0x0 async_bdr=0 async_busrst=0 vregs=[00 00 00 00] outbox(ccb=0x00000000 act=0x00) active=0 free=0 pending=0
[snap] err=0 id=0 bccb=0x0 flags=0x0 hccb(op=0x00 cmd_len=0 sense_len=0 din=0 dout=0 btstat=0x00 sdstat=0x00) ccb_status=0x0 timer=0 map=0 on_pending=0 comp=0 last_status=0x0 rec_kva=0xfffff801167df690 rec_flags=0x0 async_bdr=0 async_busrst=0 vregs=[00 02 00 00] outbox(ccb=0x00101150 act=0x01) active=11 free=4 pending=11
[snap] err=0 id=5 bccb=0xfffff801167df540 flags=0x1 hccb(op=0x03 cmd_len=6 sense_len=0 din=1 dout=0 btstat=0x00 sdstat=0x00) ccb_status=0x200 timer=0 map=1 on_pending=1 comp=0 last_status=0x0 rec_kva=0xfffff801167df690 rec_flags=0x0 async_bdr=0 async_busrst=0 vregs=[00 02 00 00] outbox(ccb=0x00101150 act=0x01) active=11 free=4 pending=11
=============== run1 complete ===============