DF-5739 / run.log
DF-5739 baseline race run โ serial console transcript (raw capture; the
panic printer interleaves with hci_acl_recv's kprintfs on the serial line)
$ kldload /root/hcih/hci_link_harness.ko
$ sysctl hw.hlh_setup=1
[harness] === setup: attach unit + ACL link #5 (OPEN) ===
[harness] unit 0xfffff801168abf20 ACL link 0xfffff8008fa922f0 handle #5 refcnt=0 links=1
$ sysctl hw.hlh_race_arm=5 # sanity: unraced arms
[harness] === DF-5739 arm x5: hci_acl_newconn() + 1-tick hci_acl_timeout callout (production re-arm pattern) ===
[harness] arm done: 5 links armed (0 skipped), links now=5
[harness] state: unit links=1 # all 5 freed cleanly by their timers when not raced
[harness] link 0xfffff801185a7b30 type=1 state=5 handle=5 refcnt=0 txqlen=0 rxp=0
$ (sysctl hw.hlh_race_discon=100000 &); (sysctl hw.hlh_race_frag=50000 &); sleep 1
$ sysctl hw.hlh_race_arm=100000
[harness] === DF-5739 discon x100000: Disconnect_Complete(handle 0) flood via hci_input_event() ===
[harness] === DF-5739 arm x100000: hci_acl_newconn() + 1-tick hci_acl_timeout callout (production re-arm pattern) ===
hcih0: dropped incomplete ACL packet <- production hci_acl_recv():473 prints,
hcih0: unexpected packet fragment <- rx path concurrently active on the
hcih0: dropped incomplete ACL packet same handle-0 link population
... (hundreds of these, concurrent with the panic printer below) ...
--- ~90 s into the race: guest dies ---
pahncic:i h0m:em unoerxype cctehudn k p0axckfetf ffragmfef8nt0
1h1ci7hc802: adc0 rios aplrpeedad iyn fcreo!m
(de-interleaved: "panic: memchunk 0xfffff8011780adc0 is already freed!"
mixed with "hcih0: unexpected packet fragment")
kTertaec h cbihe0:gin ndrionpgp eadt i fnrcaomem p0lxetffefff801A1C8L2 9pba6c0k8e
t (de-interleaved: "Trace beginning at frame 0xfffff8011829b08"
mixed with "hcih0: dropped incomplete ACL packet")
chunk_mark_free() at chunk_mark_free+0xfd
xacei h00x: fdfrffofpfpfefd80655d be i
ncomcphluentke_ mACaLr kp_acfkreeet() (mixed)
ath cchuinkh_0mar:k _fdrroeep+p0exda ei n0xffcfofmfpfleftfe8 A0C655Ld bpae c
ket
h_kcmiallh0o:c( )dr ato p_pkmaeldlo icn+c0x97ome p0xlfeftffef fAfCfL80 65p7a7c3kee t
(de-interleaved: "kfree() at kmalloc+0x97" โ kfree frame)
hchcii_hl0i:n dkr_oppaeld lioncc(o)m aplt ehtcei _ACLl ipankc_aklelto
c+0hx2c6 0xfffifhffff820602ca6
(de-interleaved: "hci_link_free() at hci_link_free+0x2c6" โ the
kfree(link, M_BLUETOOTH) call site, sys/netbt/hci_link.c:1024)
drhocpip_eadc l_innewcconno(m)pl eatte AChLci_ acpalc_nkete wco nhn+0x2h60 0x:ff drfofpfpffefd8 2603336i n
(frame at 0xffffffff80633336)
complhelth_er aACcLe p_aacrkemt( hacti hh0lh:_ radcreo_apprm+0exed7 0i n0xffcfofmfpffflfetf8e2 AC60L033 7p
(de-interleaved includes "hlh_race_arm+0x7..")
Deetb
ugghecirh(0": drpoapnipecd" )i nc ("Debugger(\"panic\")")
omCPpUl5 etset opACpL piang cCketPU s:h 0xc0i00h0000:1f d stopped
Stopped at Debugger+0x7c: movb $0,0xbdaf09(%rip)
db>
RESULT: reproduced โ allocator-level duplicate-free detection
("memchunk ... is already freed!") reached from production
hci_link_free()'s kfree() while the softclock/netisr/rx contexts raced
on the same refcnt-0 link.
Repeat runs (same rig, later passes): 3 additional passes survived โ
the race is probabilistic; first hit occurred on the first full pass.