kern/176034: UNEXPECTED SU+J INCONSISTENCY

Mon Feb 11 19:40:00 UTC 2013

>Number:         176034
>Category:       kern
>Synopsis:       UNEXPECTED SU+J INCONSISTENCY
>Confidential:   no
>Severity:       non-critical
>Priority:       low
>Responsible:    freebsd-bugs
>State:          open
>Quarter:        
>Keywords:       
>Date-Required:
>Class:          sw-bug
>Submitter-Id:   current-users
>Arrival-Date:   Mon Feb 11 19:40:00 UTC 2013
>Closed-Date:
>Last-Modified:
>Originator:     Marcin Wisnicki
>Release:        FreeBSD 9.1-STABLE #2 r246611
>Organization:
>Environment:
FreeBSD ghost.pnet.one.pl 9.1-STABLE FreeBSD 9.1-STABLE #2 r246611+8e48f63: Mon Feb 11 14:24:23 CET 2013     root at ghost.pnet.one.pl:/usr/obj/home/system/ghost/usr/src/sys/GENERIC_DEBUG  amd64

>Description:
I'll start with questions:

ad1. What could cause this ?
ad2.1. Outputs seem to be interspersed and hardly readable. If fscks run in parallel then maybe each line should be prefixed with device name, not just errors.
ad2.2. Why journaled fsck does not fall back to full fsck like it does when started manually ?
ad4. / was initially marked clean even though there was some serious damage.

Here goes actual report:

1. After update from 9.1-PRE-r242516 to 9.1-S-r246611 and second restart (from new kernel):

> sync;sync;sync
> shutdown -r now

--- 8< ---
Syncing disks, vnodes remaining...9 9 3 4 2 2 2 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 timed out
Syncing disks, buffers remaining... 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1
Giving up on 1 buffers
1 1 1 1 1 Uptime: 1d16h43m55s
--- 8< ---

2. I'm using UFS SU+J for all filesystems, one of them (mounted at /home) failed to recover after restart:

--- 8< ---
Starting file system checks:
** SU+J Recovering /dev/gpt/ghost-root
** Reading 33554432 byte journal from inode 4.
** Building recovery table.
** Resolving unreferenced inode list.
** Processing journal entries.
** 176 journal records in 12288 bytes for 45.83% utilization
** Freed 0 inodes (0 dirs) 2 blocks, and 0 frags.

***** FILE SYSTEM MARKED CLEAN *****
/dev/gpt/ghost-root-backup: FILE SYSTEM CLEAN; SKIPPING CHECKS
/dev/gpt/ghost-root-backup: clean, 3546046 free (14 frags, 443254 blocks, 0.0% fragmentation)
** SU+J Recovering /dev/gpt/ghost_tank2_enc.eli
** Reading 33554432 byte journal from inode 14.
** SU+J Recovering /dev/ufs/tank3
** Reading 33554432 byte journal from inode 4.
** SU+J Recovering /dev/gpt/ghost-squid
** Reading 33554432 byte journal from inode 4.
** SU+J Recovering /dev/gpt/ghost-home
** Reading 33554432 byte journal from inode 4.
** Building recovery table.
** Resolving unreferenced inode list.
** Processing journal entries.

***** FILE SYSTEM MARKED CLEAN *****
** Building recovery table.
** Resolving unreferenced inode list.
** Processing journal entries.
** 10 journal records in 12288 bytes for 2.60% utilization
** Freed 0 inodes (0 dirs) 0 blocks, and 0 frags.

***** FILE SYSTEM MARKED CLEAN *****
** Building recovery table.
** Building recovery table.
** Resolving unreferenced inode list.
** Processing journal entries.
** Resolving unreferenced inode list.
** Processing journal entries.
/dev/gpt/ghost-home: ino 23836056 nlink manipulation error, new link 65535, old link 2
/dev/gpt/ghost-home: UNEXPECTED SU+J INCONSISTENCY
/dev/gpt/ghost-home: INTERNAL ERROR: GOT TO reply()
/dev/gpt/ghost-home: UNEXPECTED SOFT UPDATE INCONSISTENCY; RUN fsck MANUALLY.
** 1222 journal records in 48640 bytes for 80.39% utilization
** Freed 0 inodes (0 dirs) 17 blocks, and 0 frags.

***** FILE SYSTEM MARKED CLEAN *****
THE FOLLOWING FILE SYSTEM HAD AN UNEXPECTED INCONSISTENCY:
        ufs: /dev/gpt/ghost-home (/home)
Automatic file system check failed; help!
ERROR: ABORTING BOOT (sending SIGTERM to parent)!
--- 8< ---

3. Not good :(

--- 8< ---
# fsck -y /dev/gpt/ghost-home
** /dev/gpt/ghost-home

USE JOURNAL? yes

** SU+J Recovering /dev/gpt/ghost-home
** Reading 33554432 byte journal from inode 4.

RECOVER? yes

** Building recovery table.
** Resolving unreferenced inode list.
** Processing journal entries.
ino 23836056 nlink manipulation error, new link 65535, old link 2
UNEXPECTED SU+J INCONSISTENCY

FALLBACK TO FULL FSCK? yes

** Skipping journal, falling through to full fsck

** Last Mounted on /home
** Phase 1 - Check Blocks and Sizes
** Phase 2 - Check Pathnames
** Phase 3 - Check Connectivity
UNREF DIR  I=23836406  OWNER=gdm MODE=40755
SIZE=512 MTIME=Feb 11 17:55 2013
RECONNECT? yes

DIR I=23836406 CONNECTED. PARENT WAS I=23836056
--- 8< ---

+ lots of other UNREF DIR and UNREF FILE

4. OK, now reboot, 1st try:

--- 8< ---
Starting jails:panic: ufs_dirrem: Bad link count 2 on parent
cpuid = 1
KDB: stack backtrace:
db_trace_self_wrapper() at db_trace_self_wrapper+0x2a/frame 0xffffff812399c640
kdb_backtrace() at kdb_backtrace+0x37/frame 0xffffff812399c700
panic() at panic+0x1ce/frame 0xffffff812399c800
ufs_rmdir() at ufs_rmdir+0x1dc/frame 0xffffff812399c840
VOP_RMDIR_APV() at VOP_RMDIR_APV+0x34/frame 0xffffff812399c860
null_bypass() at null_bypass+0xd3/frame 0xffffff812399c9b0
VOP_RMDIR_APV() at VOP_RMDIR_APV+0x59/frame 0xffffff812399c9d0
kern_rmdirat() at kern_rmdirat+0x21a/frame 0xffffff812399cb10
ia32_syscall() at ia32_syscall+0x550/frame 0xffffff812399cc30
Xint0x80_syscall() at Xint0x80_syscall+0x91/frame 0xffffff812399cc30
--- syscall (137, FreeBSD ELF32, sys_rmdir), rip = 0x280d8683, rsp = 0xffffcd3c, rbp = 0xffffcd68 ---
Uptime: 52s
--- 8< ---

5. Crap :/
(kgdb) p cnp->cn_pnbuf
$3 = 0xfffffe0006dd3c00 "/tmp/./.font-unix"

Also lots of errors slightly due to missing named.conf.
Turns out /etc/namedb symlink is unreadable.

Another restart into single mode. This time running fsck -fy.
No /lost+found, recreated /etc/namedb manually.

Another restart and things seem to be back to normal.
>How-To-Repeat:

>Fix:

>Release-Note:
>Audit-Trail:
>Unformatted: