[Bug 297976] Panic in the kern_symlinkat()->ffs_truncate()->flush_newblk_dep(): flush_newblk_dep: Bad newblk

[email protected]
Newsgroups gmane.os.freebsd.bugs
Message-ID <[email protected]/bugzilla/>
https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=297976

            Bug ID: 297976
           Summary: Panic in the
                    kern_symlinkat()->ffs_truncate()->flush_newblk_dep():
                    flush_newblk_dep: Bad newblk
           Product: Base System
           Version: Unspecified
          Hardware: Any
                OS: Any
            Status: New
          Severity: Affects Many People
          Priority: ---
         Component: kern
          Assignee: [email protected]
          Reporter: [email protected]

I've only seen this once, but it's on AWS EC2 instance, so it should not be
some memory fluke. The code has no substantial changes between this and latest
CURRENT, so I think this should be investigated and possibly fixed even though
reported on the old version.

I've checked the sources in question, the assertion that it trips on is 7,
which is D_ALLOCINDIR, while expected value is D_ALLOCDIRECT so again this
looks like a logical error.

What's also suspicious is that the failure is in the symlinkat(), which is new
code path relatively speaking.

I still got the dump in question so if anything useful can be extracted out of
that let me know.

Unread portion of the kernel message buffer:
panic: flush_newblk_dep: Bad newblk 0xfffff8005c096000
cpuid = 6
time = 1787724147
KDB: stack backtrace:
#0 0xffffffff805e0b8d at kdb_backtrace+0x5d
#1 0xffffffff80596551 at vpanic+0x161
#2 0xffffffff805963e3 at panic+0x43
#3 0xffffffff807ef366 at softdep_sync_buf+0xfc6
#4 0xffffffff80802a09 at ffs_syncvnode+0x2c9
#5 0xffffffff807d30f8 at ffs_truncate+0x768
#6 0xffffffff80801ba5 at ffs_vput_pair+0x125
#7 0xffffffff80685c15 at kern_symlinkat+0x345
#8 0xffffffff808ca227 at amd64_syscall+0x117
#9 0xffffffff808a159b at fast_syscall_common+0xf8
Uptime: 35m56s
Dumping 2391 out of 16085 MB:..1%..11%..21%..31%..41%..51%..61%..71%..81%..91%

__curthread () at /usr/src/sys/amd64/include/pcpu_aux.h:57
57              __asm("movq %%gs:%P1,%0" : "=r" (td) : "n" (offsetof(struct
pcpu,
(kgdb) where
#0  __curthread () at /usr/src/sys/amd64/include/pcpu_aux.h:57
#1  doadump (textdump=<optimized out>) at /usr/src/sys/kern/kern_shutdown.c:405
#2  0xffffffff805960ab in kern_reboot (howto=260) at
/usr/src/sys/kern/kern_shutdown.c:523
#3  0xffffffff805965a9 in vpanic (fmt=0xffffffff8090127b "flush_newblk_dep: Bad
newblk %p", ap=ap@entry=0xfffffe013bb17880) at
/usr/src/sys/kern/kern_shutdown.c:967
#4  0xffffffff805963e3 in panic (fmt=<unavailable>) at
/usr/src/sys/kern/kern_shutdown.c:891
#5  0xffffffff807ef366 in flush_newblk_dep (vp=0xfffff8006b1a1700,
mp=0xfffffe01128d6600, lbn=0) at /usr/src/sys/ufs/ffs/ffs_softdep.c:13254
#6  flush_pagedep_deps (pvp=0xfffff801a4fdea80, mp=0xfffffe01128d6600,
diraddhdp=0xfffff801c8e5f560, locked_bp=0xfffffe001c447030) at
/usr/src/sys/ufs/ffs/ffs_softdep.c:13394
#7  softdep_sync_buf (vp=vp@entry=0xfffff801a4fdea80,
bp=bp@entry=0xfffffe001c447030, waitfor=waitfor@entry=1) at
/usr/src/sys/ufs/ffs/ffs_softdep.c:13081
#8  0xffffffff80802a09 in ffs_syncvnode (vp=vp@entry=0xfffff801a4fdea80,
waitfor=waitfor@entry=1, flags=flags@entry=0) at
/usr/src/sys/ufs/ffs/ffs_vnops.c:348
#9  0xffffffff807d30f8 in ffs_truncate (vp=0xfffff801a4fdea80, vp@entry=<error
reading variable: value is not available>, length=26112, length@entry=<error
reading variable: value is not available>,
    flags=2176, flags@entry=<error reading variable: value is not available>,
cred=0xfffff801c9b88d00, cred@entry=<error reading variable: value is not
available>) at /usr/src/sys/ufs/ffs/ffs_inode.c:435
#10 0xffffffff80801ba5 in ffs_vput_pair (ap=0xfffffe013bb17da0, ap@entry=<error
reading variable: value is not available>) at
/usr/src/sys/ufs/ffs/ffs_vnops.c:2044
#11 0xffffffff80685c15 in VOP_VPUT_PAIR (dvp=<unavailable>, vpp=<optimized
out>, unlock_vp=true) at ./vnode_if.h:2449
#12 kern_symlinkat (td=0xfffff80382f71000, path1=<optimized out>, fd=29,
path2=0x1efeff3ed2c1 <error: Cannot access memory at address 0x1efeff3ed2c1>,
segflg=UIO_USERSPACE)
    at /usr/src/sys/kern/vfs_syscalls.c:1807
#13 0xffffffff808ca227 in syscallenter (td=0xfffff80382f71000) at
/usr/src/sys/amd64/amd64/../../kern/subr_syscall.c:193
#14 amd64_syscall (td=0xfffff80382f71000, traced=0) at
/usr/src/sys/amd64/amd64/trap.c:1241
#15 <signal handler called>
#16 0x0000000000b8709a in ?? ()
Backtrace stopped: Cannot access memory at address 0x820dc5c18
#5  0xffffffff807ef366 in flush_newblk_dep (vp=0xfffff8006b1a1700,
mp=0xfffffe01128d6600, lbn=0) at /usr/src/sys/ufs/ffs/ffs_softdep.c:13254
13254                           panic("flush_newblk_dep: Bad newblk %p",
newblk);
(kgdb) print *newblk
value is not available
(kgdb) l flush_newblk_dep
13232           ufs2_daddr_t blkno;
13233           int error;
13234
13235           error = 0;
13236           bo = &vp->v_bufobj;
13237           ip = VTOI(vp);
13238           blkno = DIP(ip, i_db[lbn]);
13239           if (blkno == 0)
13240                   panic("flush_newblk_dep: Missing block");
13241           ump = VFSTOUFS(mp);
(kgdb) l
13242           ACQUIRE_LOCK(ump);
13243           /*
13244            * Loop until all dependencies related to this block are
satisfied.
13245            * We must be careful to restart after each sleep in case a
write
13246            * completes some part of this process for us.
13247            */
13248           for (;;) {
13249                   if (newblk_lookup(mp, blkno, 0, &newblk) == 0) {
13250                           FREE_LOCK(ump);
13251                           break;
(kgdb) l
13252                   }
13253                   if (newblk->nb_list.wk_type != D_ALLOCDIRECT)
13254                           panic("flush_newblk_dep: Bad newblk %p",
newblk);
13255                   /*
13256                    * Flush the journal.
13257                    */
13258                   if (newblk->nb_jnewblk != NULL) {
13259                           jwait(&newblk->nb_jnewblk->jn_list, MNT_WAIT);
13260                           continue;
13261                   }
(kgdb) l 13200
13195                           jwait(&newblk->nb_jnewblk->jn_list, MNT_WAIT);
13196                           return (1);
13197                   }
13198                   if (newblk->nb_state & DEPCOMPLETE)
13199                           continue;
13200                   bp = newblk->nb_bmsafemap->sm_buf;
13201                   bp = getdirtybuf(bp, LOCK_PTR(ump), waitfor);
13202                   if (bp == NULL) {
13203                           if (waitfor == MNT_NOWAIT)
13204                                   continue;
(kgdb) print *(struct newblk *)0xfffff8005c096000
$2 = {nb_list = {wk_list = {le_next = 0x0, le_prev = 0xfffffe001e190da0}, wk_mp
= 0xfffffe01128d6600, wk_type = 7, wk_state = 13, wk_all = {le_next =
0xfffff8030cba9900, le_prev = 0xfffff8005c089e20}},
  nb_hash = {le_next = 0x0, le_prev = 0xfffffe012eed9680}, nb_deps = {le_next =
0x0, le_prev = 0xfffff8005c096198}, nb_jnewblk = 0x0, nb_bmsafemap = 0x0,
nb_freefrag = 0x0, nb_indirdeps = {lh_first = 0x0},
  nb_newdirblk = {lh_first = 0x0}, nb_jwork = {lh_first = 0x0}, nb_newblkno =
1342672}
(kgdb) print ((struct newblk *)0xfffff8005c096000)->nb_list.wk_type
$3 = 7
(kgdb) print ((struct newblk *)0xfffff8005c096000)->nb_list
$4 = {wk_list = {le_next = 0x0, le_prev = 0xfffffe001e190da0}, wk_mp =
0xfffffe01128d6600, wk_type = 7, wk_state = 13, wk_all = {le_next =
0xfffff8030cba9900, le_prev = 0xfffff8005c089e20}}
(kgdb) info threads
  Id   Target Id                                             Frame
  1    Thread 100000 (PID=0: kernel/swapper)                 sched_switch
(td=td@entry=0xffffffff80e98c60 <thread0_st>, flags=flags@entry=259) at
/usr/src/sys/kern/sched_ule.c:2290
  2    Thread 100011 (PID=0: kernel/softirq_0)               sched_switch
(td=td@entry=0xfffff80002855740, flags=flags@entry=259) at
/usr/src/sys/kern/sched_ule.c:2290
[PIDs 3-35x also in sched_switch sched_ule.c:2290]
  357  Thread 100001 (PID=10: audit)                         sched_switch
(td=td@entry=0xfffff80002860740, flags=flags@entry=259) at
/usr/src/sys/kern/sched_ule.c:2290
  358  Thread 100003 (PID=11: idle/idle: cpu0)               cpustop_handler ()
at /usr/src/sys/x86/x86/mp_x86.c:1530
  359  Thread 100004 (PID=11: idle/idle: cpu1)               cpustop_handler ()
at /usr/src/sys/x86/x86/mp_x86.c:1530
  360  Thread 100005 (PID=11: idle/idle: cpu2)               cpustop_handler ()
at /usr/src/sys/x86/x86/mp_x86.c:1530
  361  Thread 100006 (PID=11: idle/idle: cpu3)               cpustop_handler ()
at /usr/src/sys/x86/x86/mp_x86.c:1530
  362  Thread 100007 (PID=11: idle/idle: cpu4)               cpustop_handler ()
at /usr/src/sys/x86/x86/mp_x86.c:1530
  363  Thread 100008 (PID=11: idle/idle: cpu5)               cpustop_handler ()
at /usr/src/sys/x86/x86/mp_x86.c:1530
  364  Thread 100009 (PID=11: idle/idle: cpu6)               sched_switch
(td=td@entry=0xfffff80002854740, flags=flags@entry=1546) at
/usr/src/sys/kern/sched_ule.c:2290
  365  Thread 100010 (PID=11: idle/idle: cpu7)               cpustop_handler ()
at /usr/src/sys/x86/x86/mp_x86.c:1530
  366  Thread 100022 (PID=12: intr/swi6: task queue)         sched_switch
(td=td@entry=0xfffff80002834000, flags=flags@entry=263) at
/usr/src/sys/kern/sched_ule.c:2290
  367  Thread 100023 (PID=12: intr/swi6: Giant taskq)        <signal handler
called>
  368  Thread 100025 (PID=12: intr/swi5: fast taskq)         <signal handler
called>
  369  Thread 100038 (PID=12: intr/swi1: netisr 0)           sched_switch
(td=td@entry=0xfffff800028ff000, flags=flags@entry=263) at
/usr/src/sys/kern/sched_ule.c:2290
  370  Thread 100063 (PID=12: intr/irq32: nvme0:admin)       sched_switch
(td=td@entry=0xfffff80002b0e000, flags=flags@entry=263) at
/usr/src/sys/kern/sched_ule.c:2290
[PIDs 371-39x also in sched_switch sched_ule.c:2290]
  395  Thread 100151 (PID=12: intr/irq55: nvme7:io1)         sched_switch
(td=td@entry=0xfffff80002a5f000, flags=flags@entry=263) at
/usr/src/sys/kern/sched_ule.c:2290
--Type <RET> for more, q to quit, c to continue without paging--
  396  Thread 100444 (PID=12: intr/irq9: acpi0 intsmb0)      <signal handler
called>
  397  Thread 100445 (PID=12: intr/irq56: ena0)              sched_switch
(td=td@entry=0xfffff80009aa8000, flags=flags@entry=263) at
/usr/src/sys/kern/sched_ule.c:2290
[PIDs 398-510 also in sched_switch sched_ule.c:2290]
  511  Thread 100506 (PID=88194: pkg-static)                 sched_switch
(td=td@entry=0xfffff800170db740, flags=flags@entry=259) at
/usr/src/sys/kern/sched_ule.c:2290
* 512  Thread 101004 (PID=88195: pkg-static)                 __curthread () at
/usr/src/sys/amd64/include/pcpu_aux.h:57
  513  Thread 100524 (PID=89502: sleep)                      sched_switch
(td=td@entry=0xfffff80017e70740, flags=flags@entry=259) at
/usr/src/sys/kern/sched_ule.c:2290

-- 
You are receiving this mail because:
You are the assignee for the bug.
lmpx.com only provides a reader for public news (NNTP) servers. It is not affiliated with the servers or forums shown here and is not responsible for the content of articles, which is written by their respective authors.