[Bug 217408] Crash on boot due to race between vt_upgrade() and vt_resume_flush_timer()
bugzilla-noreply at freebsd.org
bugzilla-noreply at freebsd.org
Tue Feb 28 00:09:24 UTC 2017
https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=217408
Bug ID: 217408
Summary: Crash on boot due to race between vt_upgrade() and
vt_resume_flush_timer()
Product: Base System
Version: CURRENT
Hardware: amd64
OS: Any
Status: New
Severity: Affects Some People
Priority: ---
Component: kern
Assignee: freebsd-bugs at FreeBSD.org
Reporter: jtl at freebsd.org
Created attachment 180352
--> https://bugs.freebsd.org/bugzilla/attachment.cgi?id=180352&action=edit
This patch makes it more likely we will hit the race condition on bootup. It
can be used for seeing the bug and testing fixes.
It appears this is more fallout in the vt driver from EARLY_AP_STARTUP allowing
SMP prior to vt_upgrade() running.
Crash at boot:
Fatal trap 12: page fault while in kernel mode
cpuid = 0; apic id = 00
fault virtual address = 0x0
fault code = supervisor read instruction, page not present
instruction pointer = 0x20:0x0
stack pointer = 0x28:0xfffffe3ec2392908
frame pointer = 0x28:0xfffffe3ec23929b0
code segment = base 0x0, limit 0xfffff, type 0x1b
= DPL 0, pres 1, long 1, def32 0, gran 1
processor eflags = interrupt enabled, resume, IOPL = 0
current process = 12 (swi4: clock (0))
[ thread pid 12 tid 100028 ]
Stopped at 0
db> bt
Tracing pid 12 tid 100028 td 0xfffff8018e3a5a00
??() at 0
softclock_call_cc() at softclock_call_cc+0x14a/frame 0xfffffe3ec23929b0
softclock() at softclock+0x94/frame 0xfffffe3ec23929e0
intr_event_execute_handlers() at intr_event_execute_handlers+0x20f/frame
0xfffffe3ec2392a20
ithread_loop() at ithread_loop+0xc6/frame 0xfffffe3ec2392a70
fork_exit() at fork_exit+0x85/frame 0xfffffe3ec2392ab0
fork_trampoline() at fork_trampoline+0xe/frame 0xfffffe3ec2392ab0
--- trap 0, rip = 0, rsp = 0, rbp = 0 ---
db> show registers
cs 0x20
ds 0x3b
es 0x3b
fs 0x13
gs 0x28
ss 0x28
rax 0x4
rcx 0x1
rdx 0
rbx 0xfffff8018e3a5a00
rsp 0xfffffe3ec2392908
rbp 0xfffffe3ec23929b0
rsi 0xfffff8018e3a5a00
rdi 0
r8 0xffffffff8029baa0 cam_iosched_ticker
r9 0x40002
r10 0xffffffff80d637f8 vt_consdev+0xd8
r11 0x1e
r12 0xffffffff8102d7b8 cc_cpu+0x78
r13 0x84
rbp 0xfffffe3ec23929b0
rsi 0xfffff8018e3a5a00
rdi 0
r8 0xffffffff8029baa0 cam_iosched_ticker
r9 0x40002
r10 0xffffffff80d637f8 vt_consdev+0xd8
r11 0x1e
r12 0xffffffff8102d7b8 cc_cpu+0x78
r13 0x84
r14 0
r15 0xffffffff8102d740 cc_cpu
rip 0
rflags 0x10246 _binary_t4fw_cfg_uwire_fw_size+0xae81
It is crashing on the line in softclock_call_cc that calls the function. It is
0 in this case.
The current callout struct is stored at -0x40(%rbp). Examining that location,
we see that this is stored in the vt console driver. (Thanks, DDB!)
db> x/gx 0xfffffe3ec2392970
0xfffffe3ec2392970: ffffffff80d63828
db> x/gx 0xffffffff80d63828,8
vt_consdev+0x108: 0 ffffffff8102d818
vt_consdev+0x118: 1f62b6ace8 a3d709
vt_consdev+0x128: 0 0
vt_consdev+0x138: ffffffff80d637f8 800002
db>
I suspect we are seeing a race between callout_schedule and callout_reset_on.
CPU1: Running vt_upgrade()
CPU2: Trying to print to the VT device
CPU1 (running vt_upgrade()) is running this code:
2613 if (!(vd->vd_flags & VDF_ASYNC)) {
2614 /* Attach keyboard. */
2615 vt_allocate_keyboard(vd);
2616
2617 /* Init 25 Hz timer. */
2618 callout_init_mtx(&vd->vd_timer, &vd->vd_lock, 0);
2619
2620 /* Start timer when everything ready. */
2621 vd->vd_flags |= VDF_ASYNC;
2622 callout_reset(&vd->vd_timer, hz / VT_TIMERFREQ,
vt_timer, vd);
2623 vd->vd_timer_armed = 1;
2624 register_handlers = 1;
2625 }
In particular, I suspect it is running line 2622 when CPU2 tries to print a
'\n'. CPU2 follows this callchain:
{trimmed} -> termcn_cnputc -> teken_input -> teken_input_byte ->
teken_input_char -> teken_subr_newline -> teken_funcs_cursor ->
vt_resume_flush_timer
vt_resume_flush_timer is pretty simple (but you also need to see
vt_schedule_flush() to fully understand the code:
276static void
277vt_schedule_flush(struct vt_device *vd, int ms)
278{
279
280 if (ms <= 0)
281 /* Default to initial value. */
282 ms = 1000 / VT_TIMERFREQ;
283
284 callout_schedule(&vd->vd_timer, hz / (1000 / ms));
285}
286
287void
288vt_resume_flush_timer(struct vt_device *vd, int ms)
289{
290
291 if (!(vd->vd_flags & VDF_ASYNC) ||
292 !atomic_cmpset_int(&vd->vd_timer_armed, 0, 1))
293 return;
294
295 vt_schedule_flush(vd, ms);
296}
Note that this thread does not hold the vd lock at this point. (And, it
probably can't hold the vd lock, since the vd lock is a normal mutex and
termcn_cnputc() may hold a spin lock.) However, also note that the code told
the callout subsystem that this callout structure was protected by the vd lock.
Yet, this code path touches the callout structure without holding the vd lock.
That means the callout subsystem will make erroneous assumptions about how to
handle callout events. (This is a larger problem. And, it is difficult to fix
because of the spin lock issue.)
One more relevant piece of code:
1170int
1171callout_schedule(struct callout *c, int to_ticks)
1172{
1173 return callout_reset_on(c, to_ticks, c->c_func, c->c_arg,
c->c_cpu);
1174}
So, I suspect that what is happening is:
CPU1: Sets (vd->vd_flags |= VDF_ASYNC) and calls callout_reset().
CPU2: Checks (vd->vd_flags & VDF_ASYNC) and finds it is set (line 291).
CPU2: Does atomic_cmpset_int(&vd->vd_timer_armed, 0, 1) and finds it succeeds
(line 292).
CPU2: Runs callout_schedule. callout_schedule pulls out the current c->c_func
and c->c_arg.
CPU2: Calls callout_reset_on with the c->c_func and c->c_arg it just acquired.
(Because CPU1 has not initialized these yet, they are NULL.)
CPU1: callout_reset sets c->c_func and c->c_arg to the correct values and
completes.
CPU2: callout_reset_on overwrites c->c_func and c->c_arg with the NULL values
it acquired.
Eventually, the callout fires and things blow up.
The easy fix for this problem is to reorder the way the variables are assigned
in vt_upgrade().
However, this will not fix the larger error in using the callout system APIs
with respect to locking.
I have a reliable replication of this where I lengthen the window to hit the
race condition. (I'll attach the reproduction patch to this bug.) It seems to
reliably produce a crash without a fix. With a patch to vt_upgrade(), the crash
goes away. I've opened review D9828 with the fix.
--
You are receiving this mail because:
You are the assignee for the bug.
More information about the freebsd-bugs
mailing list