kern/57307: panic: ffs_blkfree: bad size

[manu%netbsd.org@localhost]

>Number:         57307
>Category:       kern
>Synopsis:       panic: ffs_blkfree: bad size
>Confidential:   no
>Severity:       serious
>Priority:       medium
>Responsible:    kern-bug-people
>State:          open
>Class:          sw-bug
>Submitter-Id:   net
>Arrival-Date:   Wed Mar 29 07:55:00 +0000 2023
>Originator:     Emmanuel Dreyfus
>Release:        NetBSD 9.3
>Organization:
NetBSD
>Environment:
	NetBSD 9.3 / i386, FFSv2 mounted with -o log
Architecture: i386
Machine: i386
>Description:
Taking snapshot on a FFSv2 filesystem with -o log causes a reproductible panic. After reboot, the machine will panic again when mounting the filesystem, until the problem is cleared using fsck. 

Backtrace and fsck output are below.

Snapshot is created with 
fss_flags = FSS_UNCONFIG_ON_CLOSE|unlink_on_create
Backing store is truncate()'ed to  vfs.f_blocks * vfs.f_frsize which means the size of the partition, 14 To.

The panic is 
panic: ffs_blkfree: bad size: dev = 0xa804, bno = 1 bsize = 32768, size = 32768, fs = /raid0

It happens in src/sys/ufs/ffs/ffs_alloc.c on 
if ((u_int)size > fs->fs_bsize || ffs_fragoff(fs, size) != 0 ||
            ffs_fragnum(fs, bno) + ffs_numfrags(fs, size) > fs->fs_frag) 

Here we have three conditions:
1) size == fs->fs_bsize
2) ffs_fragoff is ((loc) & (fs)->fs_qfmask) but fs_qfmask seems only defined for FFSv1 so I expect it to be 0 
3) ffs_fragnum is ((fsb) & ((fs)->fs_frag - 1))
   ffs_numfrags is ((loc) >> (fs)->fs_fshift)
dumpfs says:
bsize   32768   shift   15      mask    0xffff8000
fsize   4096    shift   12      mask    0xfffff000
frag    8       shift   3       fsbtodb 3
Reading src/usr.sbin/dumpfs/dumpfs.c
fs->fs_frag = 8 hence ffs_fragnum(fs, bno) = 1 & 7 = 1
fd->fs_fshift = 12 hence ffs_numfrags(fs, size) = 32768 >> 12 = 8

The third condition turns into 1 + 8 > 8 and we panic. But I have no idea of what it means.


panic: ffs_blkfree: bad size: dev = 0xa804, bno = 1 bsize = 32768, size = 32768, fs = /raid0
cpu1: Begin traceback...
vpanic(c0573c9b,dd846c10,dd846c48,c0392968,c0573c9b,c0515df4,a804,0,1,0) at netbsd:vpanic+0x16a
snprintf(c0573c9b,c0515df4,a804,0,1,0,8000,8000,c56210d4,8000)at netbsd:snprintf
ffs_check_bad_allocation(1,0,8000,a804,0,28210501,0,c53e8df8,c5621000,c561c344)at netbsd:ffs_check_bad_allocation+0x97
ffs_blkfree(c5621000,c561c344,1,0,8000,28210501,0,100,fffe8008,c55bc940) at netbsd:ffs_blkfree+0x85
ffs_truncate(c03a309d,c6b819ac,0,0,0,ffffffff,23,c6db398c,c6b819ac,dd846e58) at netbsd:ffs_truncate+0xf8e
ufs_truncate_retry(c6b819ac,0,0,ffffffff,c55d7000,dd846e54,c6b819ac,c6b819ac,0,c74a5800) at netbsd:ufs_truncate_retry+0x42
ufs_inactive(dd846e58,20012,1020012,c55d7000,c0524714,c6b819ac,dd846e7f,c6b819ac,dd846e88,c042ae31) at netbsd:ufs_inactive+0x6e
VOP_INACTIVE(c6b819ac,dd846e7f,c879e780,5a16e0,c6b819ac,0,dd846eac,c03a5dc0,c6b819ac,c55d7000) at netbsd:VOP_INACTIVE+0x38
vrelel(c6b819ac,c55d7000,c6db398c,c6294968,c74a5800,c6b819ac,cb225000,dd846ed8,c043194b,dd846ec4) at netbsd:vrelel+0xf6
ufs_remove(dd846ec4,0,1000000,c55d7000,c052486c,c74a5800,c6b819ac,dd846f20,14,dd846f44) at netbsd:ufs_remove+0xae
VOP_REMOVE(c74a5800,c6b819ac,dd846f20,0,1,c8eb4480,0,c8eb4480,c9608000,c53674b8) at netbsd:VOP_REMOVE+0x3e
do_sys_unlinkat.isra.4(0,dd846f68,dd846f60,0,a,0,0,bfbfe248,25ac,bfbfef65) at netbsd:do_sys_unlinkat.isra.4+0xdc
ffs_check_bad_allocation(1,0,8000,a804,0,28210501,0,c53e8df8,c5621000,c561c344) at netbsd:ffs_check_bad_allocation+0x97
ffs_blkfree(c5621000,c561c344,1,0,8000,28210501,0,100,fffe8008,c55bc940) at netbsd:ffs_blkfree+0x85
ffs_truncate(c03a309d,c6b819ac,0,0,0,ffffffff,23,c6db398c,c6b819ac,dd846e58) at netbsd:ffs_truncate+0xf8e
ufs_truncate_retry(c6b819ac,0,0,ffffffff,c55d7000,dd846e54,c6b819ac,c6b819ac,0,c74a5800) at netbsd:ufs_truncate_retry+0x42
ufs_inactive(dd846e58,20012,1020012,c55d7000,c0524714,c6b819ac,dd846e7f,c6b819ac,dd846e88,c042ae31) at netbsd:ufs_inactive+0x6e
VOP_INACTIVE(c6b819ac,dd846e7f,c879e780,5a16e0,c6b819ac,0,dd846eac,c03a5dc0,c6b819ac,c55d7000) at netbsd:VOP_INACTIVE+0x38
vrelel(c6b819ac,c55d7000,c6db398c,c6294968,c74a5800,c6b819ac,cb225000,dd846ed8,c043194b,dd846ec4) at netbsd:vrelel+0xf6
ufs_remove(dd846ec4,0,1000000,c55d7000,c052486c,c74a5800,c6b819ac,dd846f20,14,dd846f44) at netbsd:ufs_remove+0xae
VOP_REMOVE(c74a5800,c6b819ac,dd846f20,0,1,c8eb4480,0,c8eb4480,c9608000,c53674b8) at netbsd:VOP_REMOVE+0x3e
do_sys_unlinkat.isra.4(0,dd846f68,dd846f60,0,a,0,0,bfbfe248,25ac,bfbfef65) at netbsd:do_sys_unlinkat.isra.4+0xdc


fsck -fy /dev/dk4
** /dev/rdk4
** File system is journaled; replaying journal
** Last Mounted on /raid0
** Phase 1 - Check Blocks and Sizes
1 DUP I=673252609
2 DUP I=673252609
3 DUP I=673252609
4 DUP I=673252609
5 DUP I=673252609
6 DUP I=673252609
7 DUP I=673252609
8 DUP I=673252609
** Phase 1b - Rescan For More DUPS
1 DUP I=673252609
2 DUP I=673252609
3 DUP I=673252609
4 DUP I=673252609
5 DUP I=673252609
6 DUP I=673252609
7 DUP I=673252609
8 DUP I=673252609
** Phase 2 - Check Pathnames
** Phase 3 - Check Connectivity
** Phase 4 - Check Reference Counts
BAD/DUP FILE I=673252609 OWNER=0 MODE=100600
SIZE=12000138526728 MTIME=Mar 21 02:26 2023
CLEAR? yes

** Phase 5 - Check Cyl groups
FREE BLK COUNT(S) WRONG IN SUPERBLK
SALVAGE? yes

SUMMARY INFORMATION BAD
SALVAGE? yes

BLK(S) MISSING IN BIT MAPS
SALVAGE? yes

618106 files, 760176660 used, 2124159866 free (28234 frags, 265516454
blocks, 0.0% fragmentation)

MARK FILE SYSTEM CLEAN? yes


***** FILE SYSTEM MARKED CLEAN *****

***** FILE SYSTEM WAS MODIFIED *****
>How-To-Repeat:
	
>Fix: