From owner-freebsd-stable@FreeBSD.ORG Wed May 7 18:34:42 2014 Return-Path: Delivered-To: freebsd-stable@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:1900:2254:206a::19:1]) (using TLSv1 with cipher ADH-AES256-SHA (256/256 bits)) (No client certificate requested) by hub.freebsd.org (Postfix) with ESMTPS id AA2B6EB9; Wed, 7 May 2014 18:34:42 +0000 (UTC) Received: from bigwig.baldwin.cx (bigwig.baldwin.cx [IPv6:2001:470:1f11:75::1]) (using TLSv1 with cipher DHE-RSA-CAMELLIA256-SHA (256/256 bits)) (Client did not present a certificate) by mx1.freebsd.org (Postfix) with ESMTPS id 65863C9F; Wed, 7 May 2014 18:34:42 +0000 (UTC) Received: from jhbbsd.localnet (unknown [209.249.190.124]) by bigwig.baldwin.cx (Postfix) with ESMTPSA id 54075B949; Wed, 7 May 2014 14:34:41 -0400 (EDT) From: John Baldwin To: hiren panchasara Subject: Re: stable/10 panic Date: Wed, 7 May 2014 14:31:38 -0400 User-Agent: KMail/1.13.5 (FreeBSD/8.4-CBSD-20140415; KDE/4.5.5; amd64; ; ) References: <1398097892.1101.6.camel@powernoodle.corp.yahoo.com> <201405061634.34868.jhb@freebsd.org> In-Reply-To: MIME-Version: 1.0 Content-Type: Text/Plain; charset="utf-8" Content-Transfer-Encoding: 7bit Message-Id: <201405071431.38812.jhb@freebsd.org> X-Greylist: Sender succeeded SMTP AUTH, not delayed by milter-greylist-4.2.7 (bigwig.baldwin.cx); Wed, 07 May 2014 14:34:41 -0400 (EDT) Cc: freebsd-stable@freebsd.org X-BeenThere: freebsd-stable@freebsd.org X-Mailman-Version: 2.1.18 Precedence: list List-Id: Production branch of FreeBSD source code List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Wed, 07 May 2014 18:34:42 -0000 On Tuesday, May 06, 2014 7:47:05 pm hiren panchasara wrote: > On Tue, May 6, 2014 at 1:34 PM, John Baldwin wrote: > > On Monday, May 05, 2014 2:46:12 pm Sean Bruno wrote: > >> On Mon, 2014-05-05 at 13:48 -0400, John Baldwin wrote: > >> > On Monday, April 21, 2014 12:31:32 pm Sean Bruno wrote: > >> > > We're seeing this *a lot* on our qmail based hosts during our stable/10 > >> > > rollout. We're running stable/10 from around svn rev 261579 (mid > >> > > february) with one or two patches strewn in. > >> > > > >> > > sean > >> > > > >> > > > >> > > GNU gdb 6.1.1 [FreeBSD] > >> > > Copyright 2004 Free Software Foundation, Inc. > >> > > GDB is free software, covered by the GNU General Public License, and you > > are > >> > > welcome to change it and/or distribute copies of it under certain > > conditions. > >> > > Type "show copying" to see the conditions. > >> > > There is absolutely no warranty for GDB. Type "show warranty" for > > details. > >> > > This GDB was configured as "amd64-marcel-freebsd"... > >> > > > >> > > Unread portion of the kernel message buffer: > >> > > panic: page fault > >> > > cpuid = 5 > >> > > KDB: stack backtrace: > >> > > db_trace_self_wrapper() at db_trace_self_wrapper+0x2b/frame > > 0xfffffe048b9b12a0 > >> > > kdb_backtrace() at kdb_backtrace+0x39/frame 0xfffffe048b9b1350 > >> > > vpanic() at vpanic+0x126/frame 0xfffffe048b9b1390 > >> > > panic() at panic+0x43/frame 0xfffffe048b9b13f0 > >> > > trap_fatal() at trap_fatal+0x3a2/frame 0xfffffe048b9b1450 > >> > > trap_pfault() at trap_pfault+0x22f/frame 0xfffffe048b9b14f0 > >> > > trap() at trap+0x670/frame 0xfffffe048b9b1710 > >> > > calltrap() at calltrap+0x8/frame 0xfffffe048b9b1710 > >> > > --- trap 0xc, rip = 0xffffffff805e759b, rsp = 0xfffffe048b9b17d0, rbp = > > 0xfffffe048b9b17e0 --- > >> > > __mtx_assert() at __mtx_assert+0x3b/frame 0xfffffe048b9b17e0 > >> > > knote() at knote+0x39/frame 0xfffffe048b9b1830 > >> > > pipeclose() at pipeclose+0xbe/frame 0xfffffe048b9b1860 > >> > > >> > Can you show which line this is via kgdb? Can you also 'p *cpipe' > >> > and 'p *ppipe'? > >> > > >> > >> > >> Looks like its in here: > >> (kgdb) whe > >> #0 doadump (textdump=1) at pcpu.h:219 > >> #1 0xffffffff805fb2a7 in kern_reboot (howto=260) > >> at ../../../kern/kern_shutdown.c:452 > >> #2 0xffffffff805fb7b5 in vpanic (fmt=, ap= >> optimized out>) at ../../../kern/kern_shutdown.c:759 > >> #3 0xffffffff805fb803 in panic (fmt=) > >> at ../../../kern/kern_shutdown.c:688 > >> #4 0xffffffff80977852 in trap_fatal (frame=, > >> eva=) at ../../../amd64/amd64/trap.c:882 > >> #5 0xffffffff80977a8f in trap_pfault (frame=0x0, usermode= >> optimized out>) at ../../../amd64/amd64/trap.c:699 > >> #6 0xffffffff809772a0 in trap (frame=0xfffffe048c3df6e0) > >> at ../../../amd64/amd64/trap.c:463 > >> #7 0xffffffff8095c7e2 in calltrap () > >> at ../../../amd64/amd64/exception.S:232 > >> #8 0xffffffff805e759b in __mtx_assert (c=0x18, what=4, > >> file=0xffffffff80ca0bcb "../../../kern/kern_event.c", line=1960) > >> at ../../../kern/kern_mutex.c:791 > >> #9 0xffffffff805c2099 in knote (list=0xfffff8003498aae0, hint=0, > >> lockflags=1) at ../../../kern/kern_event.c:1822 > >> #10 0xffffffff806510fe in pipeclose (cpipe=0xfffff8003498aa18) > >> at ../../../kern/sys_pipe.c:1655 > >> #11 0xffffffff80651019 in pipe_dtor (dpipe=) > >> at ../../../kern/sys_pipe.c:395 > >> #12 0xffffffff80559924 in fifo_close (ap=) > >> at ../../../fs/fifofs/fifo_vnops.c:115 > >> #13 0xffffffff80a6ba6a in VOP_CLOSE_APV (vop=, > >> a=) at vnode_if.c:535 > >> #14 0xffffffff806acc09 in vn_close (vp=0xfffff8032000cce8, flags=6, > >> file_cred=0xfffff8040400d200, td=0xfffff804044f9490) at vnode_if.h:225 > >> #15 0xffffffff806abad8 in vn_closefile (fp=0xfffff803b2f3c410, > >> td=0xfffff804044f9490) at ../../../kern/vfs_vnops.c:1481 > >> #16 0xffffffff805b8789 in _fdrop (fp=0xfffff803b2f3c410, td=0x4) at > >> file.h:342 > >> #17 0xffffffff805bb0e1 in closef (fp=0xfffff803b2f3c410, > >> td=0xfffff804044f9490) at ../../../kern/kern_descrip.c:2415 > >> #18 0xffffffff805b8bf0 in closefp (fdp=0xfffff800263f5000, fd= >> optimized out>, fp=0xfffff803b2f3c410, td=0xfffff804044f9490, > >> holdleaders=) at ../../../kern/kern_descrip.c:1257 > >> #19 0xffffffff80a332b5 in ia32_syscall (frame=0xfffffe048c3dfbc0) at > >> subr_syscall.c:135 > >> #20 0xffffffff8095cdc5 in Xint0x80_syscall () at ia32_exception.S:73 > >> #21 0x00000000210f7804 in ?? () > >> Previous frame inner to this frame (corrupt stack?) > >> Current language: auto; currently minimal > >> > >> > >> > >> ---------------- > >> > >> (kgdb) f 10 > >> #10 0xffffffff806510fe in pipeclose (cpipe=0xfffff8003498aa18) > >> at ../../../kern/sys_pipe.c:1655 > >> 1655 ../../../kern/sys_pipe.c: No such file or directory. > >> in ../../../kern/sys_pipe.c > >> (kgdb) p *cpipe > >> $1 = {pipe_buffer = {cnt = 0, in = 0, out = 0, size = 0, buffer = 0x0}, > >> pipe_map = {cnt = 0, pos = 0, npages = 0, ms = {0x0 >> times>}}, pipe_sel = {si_tdlist = {tqh_first = 0x0, tqh_last = 0x0}, > >> si_note = {kl_list = { > >> slh_first = 0x0}, kl_lock = 0, kl_unlock = 0, kl_assert_locked = > >> 0xffffffff805c25c0 , kl_assert_unlocked = > >> 0xffffffff805c25e0 , kl_lockarg = 0x0}, > >> si_mtx = 0x0}, > >> pipe_atime = {tv_sec = 1399120887, tv_nsec = 0}, pipe_mtime = {tv_sec > >> = 1399120887, tv_nsec = 0}, pipe_ctime = {tv_sec = 1399120887, tv_nsec = > >> 0}, pipe_sigio = 0x0, pipe_peer = 0xfffff8003498a8b8, pipe_pair = > >> 0xfffff8003498a8b8, > >> pipe_state = 2432, pipe_busy = 0, pipe_present = 3, pipe_wgen = 0, > >> pipe_ino = 4294967295} > >> > >> (kgdb) p *ppipe > >> $2 = {pipe_buffer = {cnt = 0, in = 0, out = 0, size = 0, buffer = 0x0}, > >> pipe_map = {cnt = 0, pos = 0, npages = 0, ms = {0x0 >> times>}}, pipe_sel = {si_tdlist = {tqh_first = 0x0, tqh_last = 0x0}, > >> si_note = {kl_list = { > >> slh_first = 0x0}, kl_lock = 0, kl_unlock = 0, kl_assert_locked = > >> 0xffffffff805c25c0 , kl_assert_unlocked = > >> 0xffffffff805c25e0 , kl_lockarg = 0x0}, > >> si_mtx = 0x0}, > >> pipe_atime = {tv_sec = 1399120887, tv_nsec = 0}, pipe_mtime = {tv_sec > >> = 1399120887, tv_nsec = 0}, pipe_ctime = {tv_sec = 1399120887, tv_nsec = > >> 0}, pipe_sigio = 0x0, pipe_peer = 0xfffff8003498a8b8, pipe_pair = > >> 0xfffff8003498a8b8, > >> pipe_state = 2432, pipe_busy = 0, pipe_present = 3, pipe_wgen = 0, > >> pipe_ino = 4294967295} > > > > So the knlist for both of these has already been destroyed (knlist_destroy > > clears kl_lock, but not the assert function pointers). Note that pipe_present > > is set to PIPE_FINALIZED for both pipes here. Can you do an 'l' at frame > > 10 to see exactly which line is being called? > > #10 0xffffffff806510fe in pipeclose (cpipe=0xfffff8028a6c6730) at > ../../../kern/sys_pipe.c:1655 > > (kgdb) frame 10 > #10 0xffffffff806510fe in pipeclose (cpipe=0xfffff8028a6c6730) at > ../../../kern/sys_pipe.c:1655 > 1655 ../../../kern/sys_pipe.c: No such file or directory. > in ../../../kern/sys_pipe.c > (kgdb) l > 1650 in ../../../kern/sys_pipe.c > (kgdb) > > > 1639. /* > 1640. * shutdown the pipe > 1641. */ > 1642. static void > 1643. pipeclose(cpipe) > 1644. struct pipe *cpipe; > 1645. { > 1646. struct pipepair *pp; > 1647. struct pipe *ppipe; > 1648. > 1649. KASSERT(cpipe != NULL, ("pipeclose: cpipe == NULL")); > 1650. > 1651. PIPE_LOCK(cpipe); > 1652. pipelock(cpipe, 0); > 1653. pp = cpipe->pipe_pair; > 1654. > 1655. pipeselwakeup(cpipe); > > pipeclose() gets called from pipe_dtor() Eh, so it seems like pipeclose() has been called twice on the same pipe which should never happen. > 384. void > 385. pipe_dtor(struct pipe *dpipe) > 386. { > 387. ino_t ino; > 388. > 389. ino = dpipe->pipe_ino; > 390. funsetown(&dpipe->pipe_sigio); > 391. pipeclose(dpipe); <--------------- > 392. if (dpipe->pipe_state & PIPE_NAMED) { > 393. dpipe = dpipe->pipe_peer; > 394. funsetown(&dpipe->pipe_sigio); > 395. pipeclose(dpipe); > 396. } > 397. if (ino != 0 && ino != (ino_t)-1) > 398. free_unr(pipeino_unr, ino); > 399. } > > (kgdb) f 11 > #11 0xffffffff80651019 in pipe_dtor (dpipe=) at > ../../../kern/sys_pipe.c:395 > 395 ../../../kern/sys_pipe.c: No such file or directory. > in ../../../kern/sys_pipe.c > (kgdb) p *dpipe > $8 = {pipe_buffer = {cnt = 2160683902, in = 4294967295, out = > 2165433456, size = 4294967295, buffer = 0xfffff803c220be70 ""}, > pipe_map = { > cnt = 18446735278181777408, pos = 18446735295352500696, npages = > -1841788584, ms = {0x0, 0x0, 0xfffff80125a6a798, 0x0, > 0xfffff803c2b7b2a0, > 0xfffff803c2b7b2c0, 0x0, 0xffffffff80c96b7e, 0x6fb0008, 0x0, > 0xfffff80060c08490, 0x1500000000, 0x60, 0xffffffff80cb7fa9, 0x1030000, > 0x0, 0x4}}, > pipe_sel = {si_tdlist = {tqh_first = 0xfffff801cb464068, tqh_last = > 0xfffff8020bfa9b10}, si_note = {kl_list = {slh_first = > 0xfffff8022bb72648}, > kl_lock = 0xffffffff80cb7fb9 , kl_unlock = > 0x5230000, kl_assert_locked = 0, kl_assert_unlocked = 0x1, > kl_lockarg = 0xffffffff81105f80}, si_mtx = 0x0}, pipe_atime = > {tv_sec = 0, tv_nsec = 0}, pipe_mtime = {tv_sec = -8788387676160, > tv_nsec = -8788387676160}, pipe_ctime = {tv_sec = 0, tv_nsec = > -8788387675872}, pipe_sigio = 0x0, pipe_peer = 0x0, pipe_pair = 0x0, > pipe_state = 3410379072, pipe_busy = -2047, pipe_present = 0, > pipe_wgen = 0, pipe_ino = 0} > (kgdb) This looks like complete garbage, but it should be matching 'cpipe' from earlier. Can you 'p dpipe' at this frame? > which gets called from fifo_cleanup() > > 106. static void > 107. fifo_cleanup(struct vnode *vp) > 108. { > 109. struct fifoinfo *fip; > 110. > 111. ASSERT_VOP_ELOCKED(vp, "fifo_cleanup"); > 112. fip = vp->v_fifoinfo; > 113. if (fip->fi_readers == 0 && fip->fi_writers == 0) { > 114. vp->v_fifoinfo = NULL; > 115. pipe_dtor(fip->fi_pipe); <----------------------------- > 116. free(fip, M_VNODE); > 117. } > 118. } > > (kgdb) p *fip->fi_pipe > $7 = {pipe_buffer = {cnt = 7562869, in = 1701147238, out = 761557858, > size = 1970170230, > buffer = 0x736265657266006d
bounds>}, pipe_map = {cnt = 7596447167107706212, pos = > 7022344801864938862, > npages = 1852402688, ms = {0x78756e696c006d76, 0x696c00646961722d, > 0x706177732d78756e, 0x697361622d736d00, 0x6d00617461642d63, > 0x61642d6d646c2d73, > 0x646c2d736d006174, 0x61646174656d2d6d, 0x65722d736d006174, > 0x6e00646576726573, 0x63632d6473627465, 0x64736274656e0064, > 0x74656e006467632d, > 0x7366662d647362, 0x6c2d64736274656e, 0x736274656e007366, > 0x6e00646961722d64}}, pipe_sel = {si_tdlist = {tqh_first = > 0x77732d6473627465, > tqh_last = 0x7261776d76007061}, si_note = {kl_list = {slh_first > = 0x760073666d762d65}, kl_lock = 0x6d762d657261776d, kl_unlock = > 0x6d7600676169646b, > kl_assert_locked = 0x7365722d65726177, kl_assert_unlocked = > 0x6d76006465767265, kl_lockarg = 0x6173762d65726177}, si_mtx = > 0x4f4547007264686e}, > pipe_atime = {tv_sec = 2322261270122749773, tv_nsec = > 2675249699185255283}, pipe_mtime = {tv_sec = 8245071809811652723, > tv_nsec = 7450486642355495269}, > pipe_ctime = {tv_sec = 2406159642925495145, tv_nsec = > 3399705548884410378}, pipe_sigio = 0x2f6d6f65672f2e2e, pipe_peer = > 0x705f672f74726170, > pipe_pair = 0x5f6700632e747261, pipe_state = 1953653104, pipe_busy = > 1886547807, pipe_present = 7233896, pipe_wgen = 623407909, pipe_ino = > 620767603} > (kgdb) This should also be the same pipe, but it has an even different set of garbage. Can you 'p *fip'? -- John Baldwin