From owner-freebsd-current@freebsd.org Sun Aug 30 10:28:36 2015 Return-Path: Delivered-To: freebsd-current@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:1900:2254:206a::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id 0DA3B9C00DA for ; Sun, 30 Aug 2015 10:28:36 +0000 (UTC) (envelope-from avg@FreeBSD.org) Received: from citadel.icyb.net.ua (citadel.icyb.net.ua [212.40.38.140]) by mx1.freebsd.org (Postfix) with ESMTP id E57AE9E; Sun, 30 Aug 2015 10:28:34 +0000 (UTC) (envelope-from avg@FreeBSD.org) Received: from porto.starpoint.kiev.ua (porto-e.starpoint.kiev.ua [212.40.38.100]) by citadel.icyb.net.ua (8.8.8p3/ICyb-2.3exp) with ESMTP id NAA06847; Sun, 30 Aug 2015 13:28:26 +0300 (EEST) (envelope-from avg@FreeBSD.org) Received: from localhost ([127.0.0.1]) by porto.starpoint.kiev.ua with esmtp (Exim 4.34 (FreeBSD)) id 1ZVzqc-0002Am-Dg; Sun, 30 Aug 2015 13:28:26 +0300 To: FreeBSD Current From: Andriy Gapon Subject: panic: Stray timeout X-Enigmail-Draft-Status: N1110 Message-ID: <55E2DA91.6080206@FreeBSD.org> Date: Sun, 30 Aug 2015 13:27:29 +0300 User-Agent: Mozilla/5.0 (X11; FreeBSD amd64; rv:38.0) Gecko/20100101 Thunderbird/38.2.0 MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 7bit X-BeenThere: freebsd-current@freebsd.org X-Mailman-Version: 2.1.20 Precedence: list List-Id: Discussions about the use of FreeBSD-current List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Sun, 30 Aug 2015 10:28:36 -0000 I've got the following kernel panic seemingly at random. I have been using the kernel for about a week without any issues and I wasn't doing anything special when the panic occurred. Does this panic ring any bells? Could the problem be already fixed by more recent changes? r286985 panic: Stray timeout (kgdb) bt #0 doadump (textdump=1) at /usr/src/sys/kern/kern_shutdown.c:260 #1 0xffffffff8063236f in kern_reboot (howto=260) at /usr/src/sys/kern/kern_shutdown.c:328 #2 0xffffffff806329d4 in vpanic (fmt=, ap=) at /usr/src/sys/kern/kern_shutdown.c:508 #3 0xffffffff806326d3 in panic (fmt=0x0) at /usr/src/sys/kern/kern_shutdown.c:441 #4 0xffffffff80677dea in taskqueue_timeout_func (arg=) at /usr/src/sys/kern/subr_taskqueue.c:269 #5 0xffffffff8064858d in softclock_call_cc (c=0xfffffe000241cb50, cc=0xffffffff81066000, direct=0) at /usr/src/sys/kern/kern_timeout.c:722 #6 0xffffffff80648917 in softclock (arg=) at /usr/src/sys/kern/kern_timeout.c:851 #7 0xffffffff805fe47f in intr_event_execute_handlers (p=0xfffff800059b0548, ie=0xfffff8000599d900) at /usr/src/sys/kern/kern_intr.c:1262 #8 0xffffffff805fefac in ithread_execute_handlers (p=0xfffff800059b0548, ie=0xfffff8000599d900) at /usr/src/sys/kern/kern_intr.c:1275 #9 0xffffffff805fee1b in ithread_loop (arg=) at /usr/src/sys/kern/kern_intr.c:1356 #10 0xffffffff805fba9b in fork_exit (callout=0xffffffff805fedc0 , arg=0xfffff800059adb60, frame=0xfffffe01dc55bc00) at /usr/src/sys/kern/kern_fork.c:1006 #11 0xffffffff808073de in fork_trampoline () at /usr/src/sys/libkern/explicit_bzero.c:28 #12 0x0000000000000000 in ?? () (kgdb) fr 5 #5 0xffffffff8064858d in softclock_call_cc (c=0xfffffe000241cb50, cc=0xffffffff81066000, direct=0) at /usr/src/sys/kern/kern_timeout.c:722 722 c_func(c_arg); (kgdb) p *c $1 = {c_links = {le = {le_next = 0x0, le_prev = 0xffffffff81066108}, sle = {sle_next = 0x0}, tqe = {tqe_next = 0x0, tqe_prev = 0xffffffff81066108}}, c_time = 171699241227799, c_precision = 2684354, c_arg = 0xfffffe000241cb28, c_func = 0xffffffff80677db0 , c_lock = 0xfffff80013d66d30, c_flags = 2, c_iflags = 144, c_cpu = 0} c_flags = CALLOUT_ACTIVE c_iflags = CALLOUT_RETURNUNLOCKED | CALLOUT_PROCESSED (kgdb) p *cc $2 = {cc_lock = {lock_object = {lo_name = 0xffffffff809a0177 "callout", lo_flags = 720896, lo_data = 0, lo_witness = 0xfffffe0001fd1400}, mtx_lock = 4}, cc_exec_entity = 0xffffffff81066080, cc_next = 0x0, cc_callout = 0xfffffe0002116000, cc_callwheel = 0xfffffe0002238000, cc_expireq = {tqh_first = 0x0, tqh_last = 0xffffffff81066108}, cc_callfree = {slh_first = 0xfffffe00022372c0}, cc_firstevent = 171699349138844, cc_lastscan = 171699243988142, cc_cookie = 0xfffff800059a9b00, cc_bucket = 10456, cc_inited = 1, cc_ktr_event_name = 0xffffffff81066140 "callwheel cpu 0"} (kgdb) p c_arg $3 = (void *) 0xfffffe000241cb28 (kgdb) down #4 0xffffffff80677dea in taskqueue_timeout_func (arg=) at /usr/src/sys/kern/subr_taskqueue.c:269 269 KASSERT((timeout_task->f & DT_CALLOUT_ARMED) != 0, ("Stray timeout")); (kgdb) p *(struct timeout_task *)0xfffffe000241cb28 $4 = {q = 0xfffff80013d66d00, t = {ta_link = {stqe_next = 0x0}, ta_pending = 0, ta_priority = 0, ta_func = 0xffffffff82197220 , ta_context = 0xfffffe000241c5c0}, c = {c_links = {le = {le_next = 0x0, le_prev = 0xffffffff81066108}, sle = {sle_next = 0x0}, tqe = {tqe_next = 0x0, tqe_prev = 0xffffffff81066108}}, c_time = 171699241227799, c_precision = 2684354, c_arg = 0xfffffe000241cb28, c_func = 0xffffffff80677db0 , c_lock = 0xfffff80013d66d30, c_flags = 2, c_iflags = 144, c_cpu = 0}, f = 0} (kgdb) p *$4.q $5 = {tq_queue = {stqh_first = 0x0, stqh_last = 0xfffff80013d66d00}, tq_enqueue = 0xffffffff80678c30 , tq_context = 0xffffffff811130d8, tq_active = {tqh_first = 0x0, tqh_last = 0xfffff80013d66d20}, tq_mutex = {lock_object = {lo_name = 0xffffffff809a52a1 "taskqueue", lo_flags = 16973824, lo_data = 0, lo_witness = 0xfffffe0001fd7200}, mtx_lock = 18446735277710583024}, tq_threads = 0xfffff80013dd1bd0, tq_tcount = 1, tq_spin = 0, tq_flags = 5, tq_callouts = 1, tq_callbacks = 0xfffff80013d66d68, tq_cb_contexts = 0xfffff80013d66d78} BTW, I see the following potential problem. taskqueue_cancel_timeout() unconditionally resets DT_CALLOUT_ARMED, so that happens even if callout_stop() signals that the callout is going to be called. In that case, when taskqueue_timeout_func() gets called it's going to run into the assertion. -- Andriy Gapon