Message-ID: <baa3101d-e2f7-823e-040f-8739ab610419@colorfullife.com>
Date:   Tue, 28 Dec 2021 21:36:22 +0100
From:   Manfred Spraul <manfred@...orfullife.com>
To:     tytso@....edu, adilger.kernel@...ger.ca, linux-ext4@...r.kernel.org
Cc:     1vier1@....de
Subject: JBD2: journal transaction 6943 on loop0-8 is corrupt.

Hi,

with simulated power failures, I see a corrupted journal

[39056.200845] JBD2: journal transaction 6943 on loop0-8 is corrupt.
[39056.200851] EXT4-fs (loop0): error loading journal

I can't rule out that this is an artifact from bugs in my setup. Thus 
any hints are welcome.

Especially: I assume that data is written in 512 byte blocks. Thus a 
1024 byte write can be interrupted.

- Fedora 5.15.10-200.fc35.x86_64.

- Test load: Mostly dbench for 20 seconds, with a 512 MB ext4 image over 
nbd. Further details below.

- nbd-server modified so that it creates a trace file of all block write 
operations.

- trim is not used.

- in total, there are around 2.2 mio 512-byte writes in the trace. The 
uncompressed trace is ~1GB large.

- If I stop after 1908363 512-byte writes, then the mount will fail. 
After 1908362 or 1908364 blocks, the image mounts properly.

The compressed image files are ~20 MB, thus if there is a suitable 
storage area, I can copy it there.

I have attached the hexdumps starting from 0x8c77000. From outside, it 
appears as if the old content at 0x8c77e00 confuses ext4. The write 
1908364 sets the sector to 0x00, then everything works again.


Extract from replaying the trace:

> > H=740000008e000000 C=0x40000001 (NBD_CMD_WRITE+NONE) 
> O=0000000008c70400 L=00007800
> writing to offset 147260416 (0x8c70400), len 512 (0x200).
> writing to offset 147260928 (0x8c70600), len 512 (0x200).
> writing to offset 147261440 (0x8c70800), len 512 (0x200).
>
> [...]
>
> writing to offset 147288576 (0x8c77200), len 512 (0x200).
> writing to offset 147289088 (0x8c77400), len 512 (0x200).
> writing to offset 147289600 (0x8c77600), len 512 (0x200).
> writing to offset 147290112 (0x8c77800), len 512 (0x200).
> writing to offset 147290624 (0x8c77a00), len 512 (0x200).
>
<stop after 1908362 512-byte writes: ok>
>
> < H=740000008e000000 E=0x00000000
> > H=750000002b3c0000 C=0x00000003 (NBD_CMD_FLUSH+NONE) 
> O=0000000000000000 L=00000000
> < H=750000002b3c0000 E=0x00000000
> > H=7600000096000000 C=0x40010001 (NBD_CMD_WRITE+ FUA) 
> O=0000000008c77c00 L=00000400
> writing to offset 147291136 (0x8c77c00), len 512 (0x200).
>
<stop after 1908363 512-byte writes: bad>
>
> writing to offset 147291648 (0x8c77e00), len 512 (0x200).
>
<stop after 1908364 512-byte writes: : good>

stress test: modified maketr from nbd project. The tar file is a partial 
linux-2.2.26 source code.

> #!/bin/sh
> #
> # Example script to make a transaction log file
> # Must be run as root. Remember to chown the file afterwards
>
> # Insert the name of a tarfile here
> tarfile=/home/manfred/git/manfred/nbd-datalog/data.tar.gz
> tmpnam=$(mktemp)
> tmpmnt=$(echo -n /tmp/mnt-; basename $tmpnam)
> conffile=${tmpnam}.conf
> pidfile=${tmpnam}.pid
> output=`pwd`/output.tr
>
> ulimit -c unlimited
>
> cat >${conffile} <<EOF
> [generic]
> [export1]
>        exportname = $tmpnam
>        transactionlog = $output
>        datalog = true
>        flush = true
>        fua = true
>        rotational = true
> EOF
> nbd-server -C ${conffile} -p ${pidfile}&
> PID=$!
> sleep 1
> dd if=/dev/zero of=${tmpnam} bs=1M count=500
> nbd-client -N export1 127.0.0.1 /dev/nbd0
> mkfs.ext4 /dev/nbd0
> mkdir $tmpmnt
> mount -t ext4 /dev/nbd0 $tmpmnt
> (cd $tmpmnt ; mkdir abc; cd abc; tar xvzf ${tarfile} ; setfacl -R -m 
> u:432:rwx linux-2.2.26/Documentation;cd .. ; (setfacl -R -m u:123:rx 
> abc&); (rm abc -Rf
> &); tar xvfz ${tarfile};wait;sync) 2>&1 >/dev/null
> dbench -x -D $tmpmnt -t 30 8&
> (cd $tmpmnt ; mkdir abd; cd abd; tar xvzf ${tarfile} ; setfacl -R -m 
> u:432:rwx linux-2.2.26/Documentation;cd .. ; (setfacl -R -m u:123:rx 
> abd&); (rm abd -Rf
> &);wait;sync) 2>&1 >/dev/null
> sleep 20
> killall dbench
> sleep 2
> killall -KILL dbench
> sync
> wait
> sleep 3
> umount $tmpmnt
> nbd-client -d /dev/nbd0
> if [ -f ${pidfile} ]
> then
>        kill `cat ${pidfile}`
>        rm -f ${pidfile}
> else
>        kill $PID
> fi
> rm -f ${conffile}
> ls -la ${output}
> ls -la ${tmpnam}
>

tune2fs:

> une2fs 1.46.3 (27-Jul-2021)
> Filesystem volume name:   <none>
> Last mounted on:          /tmp/mnt-tmp.BYToCaXtWn
> Filesystem UUID:          393d4a8f-4c60-4e35-a723-554bc6ab7c6f
> Filesystem magic number:  0xEF53
> Filesystem revision #:    1 (dynamic)
> Filesystem features:      has_journal ext_attr resize_inode dir_index 
> filetype needs_recovery extent 64bit flex_bg sparse_super large_file 
> huge_file dir_nli
> nk extra_isize metadata_csum
> Filesystem flags:         signed_directory_hash
> Default mount options:    user_xattr acl
> Filesystem state:         clean
> Errors behavior:          Continue
> Filesystem OS type:       Linux
> Inode count:              128016
> Block count:              512000
> Reserved block count:     25600
> Overhead clusters:        26670
> Free blocks:              485316
> Free inodes:              128005
> First block:              1
> Block size:               1024
> Fragment size:            1024
> Group descriptor size:    64
> Reserved GDT blocks:      256
> Blocks per group:         8192
> Fragments per group:      8192
> Inodes per group:         2032
> Inode blocks per group:   254
> Flex block group size:    16
> Filesystem created:       Tue Dec 28 17:52:31 2021
> Last mount time:          Tue Dec 28 17:52:31 2021
> Last write time:          Tue Dec 28 17:52:31 2021
> Mount count:              1
> Maximum mount count:      -1
> Last checked:             Tue Dec 28 17:52:31 2021
> Check interval:           0 (<none>)
> Lifetime writes:          284 kB
> Reserved blocks uid:      0 (user root)
> Reserved blocks gid:      0 (group root)
> First inode:              11
> Inode size:               128
> Journal inode:            8
> Default directory hash:   half_md4
> Directory Hash Seed:      4799ae9b-680a-41a7-aa0f-3ae76e28ef13
> Journal backup:           inode blocks
> Checksum type:            crc32c
> Checksum:                 0xc6a92ff8
>

View attachment "extract-data-1908364.img.txt" of type "text/plain" (20233 bytes)

View attachment "extract-data-1908363.img.txt" of type "text/plain" (20233 bytes)

View attachment "extract-data-1908362.img.txt" of type "text/plain" (20233 bytes)

Powered by blists - more mailing lists