Re: ext3/ext4 filesystem corruption under post 5.1.0 kernels

Re: ext3/ext4 filesystem corruption under post 5.1.0 kernels

[Richard Weinberger]

[CC'in linux-ext4]

On Sat, May 11, 2019 at 1:47 PM Arthur Marsh
<arthur.marsh@internode.on.net> wrote:
>
> I have yet to bisect, but have had trouble with recent, post 5.1.0 kernels built from Linus' git head on both i386 (Pentium 4 pc) and amd64 (Athlon II X4 640).
>
> The easiest way to trigger the problem is:
>
> git gc
>
> on the kernel source tree, although the problem can occur without doing a git gc.
>
> The filesystem with the kernel source tree is the root file system, ext3, mounted as:
>
> /dev/sdb7 on / type ext3 (rw,relatime,errors=remount-ro)
>
> After the "Compressing objects" stage, the following appears in dmesg:
>
> [  848.968550] EXT4-fs error (device sdb7): ext4_get_branch:171: inode #8: block 30343695: comm jbd2/sdb7-8: invalid block
> [  849.077426] Aborting journal on device sdb7-8.
> [  849.100963] EXT4-fs (sdb7): Remounting filesystem read-only
> [  849.100976] jbd2_journal_bmap: journal block not found at offset 989 on sdb7-8
>
> fsck -yv
>
> then reports:
>
> # fsck -yv
> fsck from util-linux 2.33.1
> e2fsck 1.45.0 (6-Mar-2019)
> /dev/sdb7: recovering journal
> /dev/sdb7 contains a file system with errors, check forced.
> Pass 1: Checking inodes, blocks, and sizes
> Pass 2: Checking directory structure
> Pass 3: Checking directory connectivity
> Pass 4: Checking reference counts
> Pass 5: Checking group summary information
> Free blocks count wrong (4619656, counted=4619444).
> Fix? yes
>
> Free inodes count wrong (15884075, counted=15884058).
> Fix? yes
>
>
> /dev/sdb7: ***** FILE SYSTEM WAS MODIFIED *****
>
> Other times, I have gotten:
>
> "Inodes that were part of a corrupted orphan linked list found."
> "Block bitmap differences:"
> "Free blocks sound wrong for group"
>
> No problems have been observed with the 5.1.0 release kernel.
>
> Any suggestions for narrowing down the issue welcome.

Can you git-bisect it?

-- 
Thanks,
//richard

Re: ext3/ext4 filesystem corruption under post 5.1.0 kernels

[Theodore Ts'o]

On Sat, May 11, 2019 at 02:43:16PM +0200, Richard Weinberger wrote:
> [CC'in linux-ext4]
> 
> On Sat, May 11, 2019 at 1:47 PM Arthur Marsh
> <arthur.marsh@internode.on.net> wrote:
> >
> >
> > The filesystem with the kernel source tree is the root file system, ext3, mounted as:
> >
> > /dev/sdb7 on / type ext3 (rw,relatime,errors=remount-ro)
> >
> > After the "Compressing objects" stage, the following appears in dmesg:
> >
> > [  848.968550] EXT4-fs error (device sdb7): ext4_get_branch:171: inode #8: block 30343695: comm jbd2/sdb7-8: invalid block
> > [  849.077426] Aborting journal on device sdb7-8.
> > [  849.100963] EXT4-fs (sdb7): Remounting filesystem read-only
> > [  849.100976] jbd2_journal_bmap: journal block not found at offset 989 on sdb7-8

This indicates that the extent tree blocks for the journal was found
to be corrupt; so the journal couldn't be found.

> > # fsck -yv
> > fsck from util-linux 2.33.1
> > e2fsck 1.45.0 (6-Mar-2019)
> > /dev/sdb7: recovering journal
> > /dev/sdb7 contains a file system with errors, check forced.

But e2fsck had no problem finding the journal.

> > Pass 1: Checking inodes, blocks, and sizes
> > Pass 2: Checking directory structure
> > Pass 3: Checking directory connectivity
> > Pass 4: Checking reference counts
> > Pass 5: Checking group summary information
> > Free blocks count wrong (4619656, counted=4619444).
> > Fix? yes
> >
> > Free inodes count wrong (15884075, counted=15884058).
> > Fix? yes

And no other significant problems were found.  (Ext4 never updates or
relies on the summary number of free blocks and free inodes, since
updating it is a scalability bottleneck and these values can be
calculated from the per block group free block/inodes count.  So the
fact that e2fsck needed to update them is not an issue.)

So that implies that we got one set of values when we read the journal
inode when attempting to mount the file system, and a *different* set
of values when e2fsck was run.  Which makes means that we need
consider the possibility that the problem is below the file system
layer (e.g., the block layer, device drivers, etc.).


> > /dev/sdb7: ***** FILE SYSTEM WAS MODIFIED *****
> >
> > Other times, I have gotten:
> >
> > "Inodes that were part of a corrupted orphan linked list found."
> > "Block bitmap differences:"
> > "Free blocks sound wrong for group"
> >

This variety of issues also implies that the issue may be in the data
read by the file system, as opposed to an issue in the file system.

Arthur, can you give us the full details of your hardware
configuration and your kernel config file?  Also, what kernel git
commit ID were you testing?

					- Ted

Re: ext3/ext4 filesystem corruption under post 5.1.0 kernels

[Arthur Marsh]

After a git bisect reset and updating to the current Linus git head, the problem no longer occurs.

Thanks for the feedback on the problem that I experienced.

Arthur. 
-- 
Sent from my Android device with K-9 Mail. Please excuse my brevity.

Re: ext3/ext4 filesystem corruption under post 5.1.0 kernels

[Arthur Marsh]

Apologies, I had forgotten to

got bisect - - hard origin/master

I am still seeing the corruption leading to the invalid block error on 5.1.0+ kernels on both my machines.

Arthur. 
-- 
Sent from my Android device with K-9 Mail. Please excuse my brevity.

Re: ext3/ext4 filesystem corruption under post 5.1.0 kernels

[Ondrej Zary]

On Tuesday 14 May 2019, Arthur Marsh wrote:
> Apologies, I had forgotten to
> 
> got bisect - - hard origin/master
> 
> I am still seeing the corruption leading to the invalid block error on 5.1.0+ kernels on both my machines.
> 
> Arthur. 

I've been probably hit by the same bug. ext3 filesystem on my test machine was corrupted twice with 5.1.0+. Only the corruption was heavier. Some files that were open (e.g. logs) became cros-linked with files that were not used for ages.

-- 
Ondrej Zary

Re: ext3/ext4 filesystem corruption under post 5.1.0 kernels

[Arthur Marsh]

On 14 May 2019 11:29:37 am ACST, Arthur Marsh <arthur.marsh@internode.on.net> wrote:
>Apologies, I had forgotten to
>
>git bisect - - hard origin/master
>
>I am still seeing the corruption leading to the invalid block error on
>5.1.0+ kernels on both my machines.
>
>Arthur. 

After the mm commits, the 32 bit kernel on Pentium-D still exhibits the "invalid block" issue when running git gc on the kernel source. 

The 64 bit kernel on Athlon II X4 640 has since the mm commits had less problems running git gc on the kernel source but had an "invalid block" error after a second run of git gc. 

Arthur. 

Arthur. 
-- 
Sent from my Android device with K-9 Mail. Please excuse my brevity.

Re: ext3/ext4 filesystem corruption under post 5.1.0 kernels

[Theodore Ts'o]

Ah, I think I see the problem.  Sorry, this one was my fault.  Does
this fix things for you?

						- Ted

From 0c72924ef346d54e8627440e6d71257aa5b56105 Mon Sep 17 00:00:00 2001
From: Theodore Ts'o <tytso@mit.edu>
Date: Wed, 15 May 2019 00:51:19 -0400
Subject: [PATCH] ext4: fix block validity checks for journal inodes using indirect blocks

Commit 345c0dbf3a30 ("ext4: protect journal inode's blocks using
block_validity") failed to add an exception for the journal inode in
ext4_check_blockref(), which is the function used by ext4_get_branch()
for indirect blocks.  This caused attempts to read from the ext3-style
journals to fail with:

[  848.968550] EXT4-fs error (device sdb7): ext4_get_branch:171: inode #8: block 30343695: comm jbd2/sdb7-8: invalid block

Fix this by adding the missing exception check.

Fixes: 345c0dbf3a30 ("ext4: protect journal inode's blocks using block_validity")
Reported-by: Arthur Marsh <arthur.marsh@internode.on.net>
Signed-off-by: Theodore Ts'o <tytso@mit.edu>
---
 fs/ext4/block_validity.c | 5 +++++
 1 file changed, 5 insertions(+)

diff --git a/fs/ext4/block_validity.c b/fs/ext4/block_validity.c
index 8d03550aaae3..8e83741b02e0 100644
--- a/fs/ext4/block_validity.c
+++ b/fs/ext4/block_validity.c
@@ -277,6 +277,11 @@ int ext4_check_blockref(const char *function, unsigned int line,
 	__le32 *bref = p;
 	unsigned int blk;
 
+	if (ext4_has_feature_journal(inode->i_sb) &&
+	    (inode->i_ino ==
+	     le32_to_cpu(EXT4_SB(inode->i_sb)->s_es->s_journal_inum)))
+		return 0;
+
 	while (bref < p+max) {
 		blk = le32_to_cpu(*bref++);
 		if (blk &&
-- 
2.19.1

Re: ext3/ext4 filesystem corruption under post 5.1.0 kernels

[Arthur Marsh]

[-- Attachment #1: Type: text/plain, Size: 2297 bytes --]



On 15 May 2019 2:27:17 pm ACST, Theodore Ts'o <tytso@mit.edu> wrote:
>Ah, I think I see the problem.  Sorry, this one was my fault.  Does
>this fix things for you?
>
>						- Ted
>
>From 0c72924ef346d54e8627440e6d71257aa5b56105 Mon Sep 17 00:00:00 2001
>From: Theodore Ts'o <tytso@mit.edu>
>Date: Wed, 15 May 2019 00:51:19 -0400
>Subject: [PATCH] ext4: fix block validity checks for journal inodes
>using indirect blocks
>
>Commit 345c0dbf3a30 ("ext4: protect journal inode's blocks using
>block_validity") failed to add an exception for the journal inode in
>ext4_check_blockref(), which is the function used by ext4_get_branch()
>for indirect blocks.  This caused attempts to read from the ext3-style
>journals to fail with:
>
>[  848.968550] EXT4-fs error (device sdb7): ext4_get_branch:171: inode
>#8: block 30343695: comm jbd2/sdb7-8: invalid block
>
>Fix this by adding the missing exception check.
>
>Fixes: 345c0dbf3a30 ("ext4: protect journal inode's blocks using
>block_validity")
>Reported-by: Arthur Marsh <arthur.marsh@internode.on.net>
>Signed-off-by: Theodore Ts'o <tytso@mit.edu>
>---
> fs/ext4/block_validity.c | 5 +++++
> 1 file changed, 5 insertions(+)
>
>diff --git a/fs/ext4/block_validity.c b/fs/ext4/block_validity.c
>index 8d03550aaae3..8e83741b02e0 100644
>--- a/fs/ext4/block_validity.c
>+++ b/fs/ext4/block_validity.c
>@@ -277,6 +277,11 @@ int ext4_check_blockref(const char *function,
>unsigned int line,
> 	__le32 *bref = p;
> 	unsigned int blk;
> 
>+	if (ext4_has_feature_journal(inode->i_sb) &&
>+	    (inode->i_ino ==
>+	     le32_to_cpu(EXT4_SB(inode->i_sb)->s_es->s_journal_inum)))
>+		return 0;
>+
> 	while (bref < p+max) {
> 		blk = le32_to_cpu(*bref++);
> 		if (blk &&

I have built kernels with the attached patch applied and run git gc on the patched kernels (both the 32 bit kernel on the Pentium-D and the 64 bit kernel on the Athlon II X4 640). 

There were a couple of warnings from other processes being blocked while the git gc was taking place but no filesystem corruption detected. (I ran forced fsck checks on the root filesystems after the git gc runs to check for corruption). 

Thanks for the patch! 

Arthur. 

-- 
Sent from my Android device with K-9 Mail. Please excuse my brevity.

[-- Attachment #2: ext4.tmp --]
[-- Type: application/octet-stream, Size: 506 bytes --]

diff --git a/fs/ext4/block_validity.c b/fs/ext4/block_validity.c
index 968f163b5feb..66146a711871 100644
--- a/fs/ext4/block_validity.c
+++ b/fs/ext4/block_validity.c
@@ -276,6 +276,11 @@ int ext4_check_blockref(const char *function, unsigned int line,
 	__le32 *bref = p;
 	unsigned int blk;
 
+	if (ext4_has_feature_journal(inode->i_sb) &&
+	(inode->i_ino ==
+		le32_to_cpu(EXT4_SB(inode->i_sb)->s_es->s_journal_inum)))
+	return 0;
+
 	while (bref < p+max) {
 		blk = le32_to_cpu(*bref++);
 		if (blk &&

[-- Attachment #3: 20190515iucode_tool.log --]
[-- Type: application/octet-stream, Size: 4281 bytes --]

[ 1088.155025] INFO: task iucode_tool:9456 blocked for more than 120 seconds.
[ 1088.155032]       Not tainted 5.1.0+ #3417
[ 1088.155033] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1088.155035] iucode_tool     D    0  9456   9453 0x00004000
[ 1088.155039] Call Trace:
[ 1088.155052]  ? __schedule+0x297/0x690
[ 1088.155055]  ? _raw_spin_lock_irqsave+0x22/0x50
[ 1088.155057]  schedule+0x33/0xc0
[ 1088.155070]  jbd2_log_wait_commit+0x9b/0x100 [jbd2]
[ 1088.155075]  ? finish_wait+0xb0/0xb0
[ 1088.155110]  ext4_sync_file+0x3eb/0x440 [ext4]
[ 1088.155115]  do_fsync+0x43/0x80
[ 1088.155117]  __x64_sys_fdatasync+0x13/0x20
[ 1088.155120]  do_syscall_64+0x64/0x3d0
[ 1088.155123]  ? __do_page_fault+0x288/0x590
[ 1088.155126]  ? fpregs_assert_state_consistent+0x1e/0x50
[ 1088.155129]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 1088.155132] RIP: 0033:0x7f519f7a32c4
[ 1088.155139] Code: Bad RIP value.
[ 1088.155140] RSP: 002b:00007ffeb09a8848 EFLAGS: 00000246 ORIG_RAX: 000000000000004b
[ 1088.155142] RAX: ffffffffffffffda RBX: 000000000024d000 RCX: 00007f519f7a32c4
[ 1088.155144] RDX: 0000000000000000 RSI: 0000000000000001 RDI: 0000000000000003
[ 1088.155145] RBP: 0000000000000003 R08: 000000000000014f R09: 000055a9e2d3b190
[ 1088.155146] R10: 0000000000000000 R11: 0000000000000246 R12: 000055a9e2d37870
[ 1088.155147] R13: 0000000000000150 R14: 000000000000006c R15: 0000000000000000
[ 1208.926585] INFO: task iucode_tool:9456 blocked for more than 241 seconds.
[ 1208.926589]       Not tainted 5.1.0+ #3417
[ 1208.926590] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1208.926592] iucode_tool     D    0  9456   9453 0x00004000
[ 1208.926595] Call Trace:
[ 1208.926604]  ? __schedule+0x297/0x690
[ 1208.926607]  ? _raw_spin_lock_irqsave+0x22/0x50
[ 1208.926609]  schedule+0x33/0xc0
[ 1208.926618]  jbd2_log_wait_commit+0x9b/0x100 [jbd2]
[ 1208.926621]  ? finish_wait+0xb0/0xb0
[ 1208.926643]  ext4_sync_file+0x3eb/0x440 [ext4]
[ 1208.926647]  do_fsync+0x43/0x80
[ 1208.926649]  __x64_sys_fdatasync+0x13/0x20
[ 1208.926651]  do_syscall_64+0x64/0x3d0
[ 1208.926654]  ? __do_page_fault+0x288/0x590
[ 1208.926656]  ? fpregs_assert_state_consistent+0x1e/0x50
[ 1208.926658]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 1208.926661] RIP: 0033:0x7f519f7a32c4
[ 1208.926666] Code: Bad RIP value.
[ 1208.926667] RSP: 002b:00007ffeb09a8848 EFLAGS: 00000246 ORIG_RAX: 000000000000004b
[ 1208.926669] RAX: ffffffffffffffda RBX: 000000000024d000 RCX: 00007f519f7a32c4
[ 1208.926670] RDX: 0000000000000000 RSI: 0000000000000001 RDI: 0000000000000003
[ 1208.926671] RBP: 0000000000000003 R08: 000000000000014f R09: 000055a9e2d3b190
[ 1208.926672] R10: 0000000000000000 R11: 0000000000000246 R12: 000055a9e2d37870
[ 1208.926673] R13: 0000000000000150 R14: 000000000000006c R15: 0000000000000000

[ 1933.556182] INFO: task Thread (pooled):20910 blocked for more than 120 seconds.
[ 1933.556189]       Not tainted 5.1.0+ #3417
[ 1933.556190] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1933.556192] Thread (pooled) D    0 20910      1 0x00004000
[ 1933.556195] Call Trace:
[ 1933.556207]  ? __schedule+0x297/0x690
[ 1933.556210]  ? _raw_spin_lock_irqsave+0x22/0x50
[ 1933.556212]  schedule+0x33/0xc0
[ 1933.556224]  jbd2_log_wait_commit+0x9b/0x100 [jbd2]
[ 1933.556228]  ? finish_wait+0xb0/0xb0
[ 1933.556261]  ext4_sync_file+0x3eb/0x440 [ext4]
[ 1933.556266]  do_fsync+0x43/0x80
[ 1933.556268]  __x64_sys_fdatasync+0x13/0x20
[ 1933.556271]  do_syscall_64+0x64/0x3d0
[ 1933.556274]  ? __do_page_fault+0x288/0x590
[ 1933.556277]  ? fpregs_assert_state_consistent+0x1e/0x50
[ 1933.556279]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 1933.556282] RIP: 0033:0x7f90e22d62e7
[ 1933.556288] Code: Bad RIP value.
[ 1933.556290] RSP: 002b:00007f909d4e7a00 EFLAGS: 00000293 ORIG_RAX: 000000000000004b
[ 1933.556292] RAX: ffffffffffffffda RBX: 000000000000001a RCX: 00007f90e22d62e7
[ 1933.556293] RDX: 0000000000000000 RSI: 00007f909d4e79f0 RDI: 000000000000001a
[ 1933.556294] RBP: 00007f908c004bf0 R08: 000000000000401f R09: 00007f908c009940
[ 1933.556295] R10: 00007f908c009910 R11: 0000000000000293 R12: 0000000000000001
[ 1933.556296] R13: 0000000000000001 R14: 00007f909d4e7b50 R15: 0000000000000001

Re: ext3/ext4 filesystem corruption under post 5.1.0 kernels

[Theodore Ts'o]

On Wed, May 15, 2019 at 09:42:11PM +0930, Arthur Marsh wrote:
> I have built kernels with the attached patch applied and run git gc
> on the patched kernels (both the 32 bit kernel on the Pentium-D and
> the 64 bit kernel on the Athlon II X4 640).
> 
> There were a couple of warnings from other processes being blocked
> while the git gc was taking place but no filesystem corruption
> detected. (I ran forced fsck checks on the root filesystems after
> the git gc runs to check for corruption).
> 
> Thanks for the patch!

Thanks for the bug report!  My apologies for the inconvenience; I'm
going to take a look at improving my regression test configurations so
I would have noticed this earlier.

Cheers,

						- Ted

Re: ext3/ext4 filesystem corruption under post 5.1.0 kernels

[Geert Uytterhoeven]

Hi Ted,

On Wed, May 15, 2019 at 6:57 AM Theodore Ts'o <tytso@mit.edu> wrote:
> Ah, I think I see the problem.  Sorry, this one was my fault.  Does
> this fix things for you?

Thanks!
Sorry for missing this patch in the thread before.

> From 0c72924ef346d54e8627440e6d71257aa5b56105 Mon Sep 17 00:00:00 2001
> From: Theodore Ts'o <tytso@mit.edu>
> Date: Wed, 15 May 2019 00:51:19 -0400
> Subject: [PATCH] ext4: fix block validity checks for journal inodes using indirect blocks
>
> Commit 345c0dbf3a30 ("ext4: protect journal inode's blocks using
> block_validity") failed to add an exception for the journal inode in
> ext4_check_blockref(), which is the function used by ext4_get_branch()
> for indirect blocks.  This caused attempts to read from the ext3-style
> journals to fail with:
>
> [  848.968550] EXT4-fs error (device sdb7): ext4_get_branch:171: inode #8: block 30343695: comm jbd2/sdb7-8: invalid block
>
> Fix this by adding the missing exception check.
>
> Fixes: 345c0dbf3a30 ("ext4: protect journal inode's blocks using block_validity")
> Reported-by: Arthur Marsh <arthur.marsh@internode.on.net>
> Signed-off-by: Theodore Ts'o <tytso@mit.edu>

Intermittent issue no more seen in 10 test boots, so
Tested-by: Geert Uytterhoeven <geert@linux-m68k.org>

Gr{oetje,eeting}s,

                        Geert

-- 
Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org

In personal conversations with technical people, I call myself a hacker. But
when I'm talking to journalists I just say "programmer" or something like that.
                                -- Linus Torvalds

Re: ext3/ext4 filesystem corruption under post 5.1.0 kernels

[Geert Uytterhoeven]

Hi Ted,

On Fri, May 17, 2019 at 6:44 PM Geert Uytterhoeven <geert@linux-m68k.org> wrote:
> On Wed, May 15, 2019 at 6:57 AM Theodore Ts'o <tytso@mit.edu> wrote:
> > Ah, I think I see the problem.  Sorry, this one was my fault.  Does
> > this fix things for you?
>
> Thanks!
> Sorry for missing this patch in the thread before.
>
> > From 0c72924ef346d54e8627440e6d71257aa5b56105 Mon Sep 17 00:00:00 2001
> > From: Theodore Ts'o <tytso@mit.edu>
> > Date: Wed, 15 May 2019 00:51:19 -0400
> > Subject: [PATCH] ext4: fix block validity checks for journal inodes using indirect blocks
> >
> > Commit 345c0dbf3a30 ("ext4: protect journal inode's blocks using
> > block_validity") failed to add an exception for the journal inode in
> > ext4_check_blockref(), which is the function used by ext4_get_branch()
> > for indirect blocks.  This caused attempts to read from the ext3-style
> > journals to fail with:
> >
> > [  848.968550] EXT4-fs error (device sdb7): ext4_get_branch:171: inode #8: block 30343695: comm jbd2/sdb7-8: invalid block
> >
> > Fix this by adding the missing exception check.
> >
> > Fixes: 345c0dbf3a30 ("ext4: protect journal inode's blocks using block_validity")
> > Reported-by: Arthur Marsh <arthur.marsh@internode.on.net>
> > Signed-off-by: Theodore Ts'o <tytso@mit.edu>
>
> Intermittent issue no more seen in 10 test boots, so
> Tested-by: Geert Uytterhoeven <geert@linux-m68k.org>

Despite this fix having been applied upstream,  the kernel prints from
time to time:

    EXT4-fs (sda1): error count since last fsck: 5
    EXT4-fs (sda1): initial error at time 1557931133:
ext4_get_branch:171: inode 1980: block 27550
    EXT4-fs (sda1): last error at time 1558114349:
ext4_get_branch:171: inode 1980: block 27550

This happens even after a manual run of "e2fsck -f" (while it's mounted
RO), which reports a clean file system.

The inode and block numbers match the numbers printed due to the
previous bug.

Do you have an idea what's wrong?
Note that I run a very old version of e2fsck (from a decade ago).

Thanks!

Gr{oetje,eeting}s,

                        Geert

-- 
Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org

In personal conversations with technical people, I call myself a hacker. But
when I'm talking to journalists I just say "programmer" or something like that.
                                -- Linus Torvalds

Re: ext3/ext4 filesystem corruption under post 5.1.0 kernels

[Theodore Ts'o]

On Mon, Jul 01, 2019 at 02:43:14PM +0200, Geert Uytterhoeven wrote:
> Hi Ted,
> 
> Despite this fix having been applied upstream,  the kernel prints from
> time to time:
> 
>     EXT4-fs (sda1): error count since last fsck: 5
>     EXT4-fs (sda1): initial error at time 1557931133:
> ext4_get_branch:171: inode 1980: block 27550
>     EXT4-fs (sda1): last error at time 1558114349:
> ext4_get_branch:171: inode 1980: block 27550
> 
> This happens even after a manual run of "e2fsck -f" (while it's mounted
> RO), which reports a clean file system.

What's happening is this.  When the kernel detects a corruption, newer
kernels will set these superblock fields:

	__le32	s_error_count;		/* number of fs errors */
	__le32	s_first_error_time;	/* first time an error happened */
	__le32	s_first_error_ino;	/* inode involved in first error */
	__le64	s_first_error_block;	/* block involved of first error */
	__u8	s_first_error_func[32] __nonstring;	/* function where the error happened */
	__le32	s_first_error_line;	/* line number where error happened */
	__le32	s_last_error_time;	/* most recent time of an error */
	__le32	s_last_error_ino;	/* inode involved in last error */
	__le32	s_last_error_line;	/* line number where error happened */
	__le64	s_last_error_block;	/* block involved of last error */
	__u8	s_last_error_func[32] __nonstring;	/* function where the error happened */

When newer versions of e2fsck *fix* the corruption, it will clear
these fields.  It's basically a safety check because *way* too many
ext4 users run with errors=continue (aka, "don't worry, be happy"
mode), and so this is a poke in the system logs that the file system
is corrupted, and they, really, *REALLY* should fix it before they
lose (more) data.

> The inode and block numbers match the numbers printed due to the
> previous bug.

You can also see when the last file system error was detected via:

% date -d @1558114349
Fri 17 May 2019 01:32:29 PM EDT

> Do you have an idea what's wrong?
> Note that I run a very old version of e2fsck (from a decade ago).

... and that's the problem.  If you're going to be using newer
versions of the kernel, you really should be using newer versions of
e2fsprogs.

There have been a lot of bug fixes in the last 10 years, and some of
them can be data corruption bugs....

					- Ted

Re: ext3/ext4 filesystem corruption under post 5.1.0 kernels

[Geert Uytterhoeven]

Hi Ted,

On Mon, Jul 1, 2019 at 3:56 PM Theodore Ts'o <tytso@mit.edu> wrote:
> On Mon, Jul 01, 2019 at 02:43:14PM +0200, Geert Uytterhoeven wrote:
> > Despite this fix having been applied upstream,  the kernel prints from
> > time to time:
> >
> >     EXT4-fs (sda1): error count since last fsck: 5
> >     EXT4-fs (sda1): initial error at time 1557931133:
> > ext4_get_branch:171: inode 1980: block 27550
> >     EXT4-fs (sda1): last error at time 1558114349:
> > ext4_get_branch:171: inode 1980: block 27550
> >
> > This happens even after a manual run of "e2fsck -f" (while it's mounted
> > RO), which reports a clean file system.
>
> What's happening is this.  When the kernel detects a corruption, newer
> kernels will set these superblock fields:
>
>         __le32  s_error_count;          /* number of fs errors */
>         __le32  s_first_error_time;     /* first time an error happened */
>         __le32  s_first_error_ino;      /* inode involved in first error */
>         __le64  s_first_error_block;    /* block involved of first error */
>         __u8    s_first_error_func[32] __nonstring;     /* function where the error happened */
>         __le32  s_first_error_line;     /* line number where error happened */
>         __le32  s_last_error_time;      /* most recent time of an error */
>         __le32  s_last_error_ino;       /* inode involved in last error */
>         __le32  s_last_error_line;      /* line number where error happened */
>         __le64  s_last_error_block;     /* block involved of last error */
>         __u8    s_last_error_func[32] __nonstring;      /* function where the error happened */
>
> When newer versions of e2fsck *fix* the corruption, it will clear
> these fields.  It's basically a safety check because *way* too many
> ext4 users run with errors=continue (aka, "don't worry, be happy"
> mode), and so this is a poke in the system logs that the file system
> is corrupted, and they, really, *REALLY* should fix it before they
> lose (more) data.

Thanks for the explanation, much appreciated!

> > The inode and block numbers match the numbers printed due to the
> > previous bug.
>
> You can also see when the last file system error was detected via:
>
> % date -d @1558114349
> Fri 17 May 2019 01:32:29 PM EDT

Good. So no new errors detected after the fix.

> > Do you have an idea what's wrong?
> > Note that I run a very old version of e2fsck (from a decade ago).
>
> ... and that's the problem.  If you're going to be using newer
> versions of the kernel, you really should be using newer versions of
> e2fsprogs.
>
> There have been a lot of bug fixes in the last 10 years, and some of
> them can be data corruption bugs....

Yeah, one day I'll have to change the winning horse...

Gr{oetje,eeting}s,

                        Geert

-- 
Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org

In personal conversations with technical people, I call myself a hacker. But
when I'm talking to journalists I just say "programmer" or something like that.
                                -- Linus Torvalds

Re: ext3/ext4 filesystem corruption under post 5.1.0 kernels

[Geert Uytterhoeven]

Hi Ted,

On Sun, May 12, 2019 at 12:07 AM Theodore Ts'o <tytso@mit.edu> wrote:
> On Sat, May 11, 2019 at 02:43:16PM +0200, Richard Weinberger wrote:
> > [CC'in linux-ext4]
> >
> > On Sat, May 11, 2019 at 1:47 PM Arthur Marsh
> > <arthur.marsh@internode.on.net> wrote:
> > >
> > >
> > > The filesystem with the kernel source tree is the root file system, ext3, mounted as:
> > >
> > > /dev/sdb7 on / type ext3 (rw,relatime,errors=remount-ro)
> > >
> > > After the "Compressing objects" stage, the following appears in dmesg:
> > >
> > > [  848.968550] EXT4-fs error (device sdb7): ext4_get_branch:171: inode #8: block 30343695: comm jbd2/sdb7-8: invalid block
> > > [  849.077426] Aborting journal on device sdb7-8.
> > > [  849.100963] EXT4-fs (sdb7): Remounting filesystem read-only
> > > [  849.100976] jbd2_journal_bmap: journal block not found at offset 989 on sdb7-8
>
> This indicates that the extent tree blocks for the journal was found
> to be corrupt; so the journal couldn't be found.
>
> > > # fsck -yv
> > > fsck from util-linux 2.33.1
> > > e2fsck 1.45.0 (6-Mar-2019)
> > > /dev/sdb7: recovering journal
> > > /dev/sdb7 contains a file system with errors, check forced.
>
> But e2fsck had no problem finding the journal.
>
> > > Pass 1: Checking inodes, blocks, and sizes
> > > Pass 2: Checking directory structure
> > > Pass 3: Checking directory connectivity
> > > Pass 4: Checking reference counts
> > > Pass 5: Checking group summary information
> > > Free blocks count wrong (4619656, counted=4619444).
> > > Fix? yes
> > >
> > > Free inodes count wrong (15884075, counted=15884058).
> > > Fix? yes
>
> And no other significant problems were found.  (Ext4 never updates or
> relies on the summary number of free blocks and free inodes, since
> updating it is a scalability bottleneck and these values can be
> calculated from the per block group free block/inodes count.  So the
> fact that e2fsck needed to update them is not an issue.)
>
> So that implies that we got one set of values when we read the journal
> inode when attempting to mount the file system, and a *different* set
> of values when e2fsck was run.  Which makes means that we need
> consider the possibility that the problem is below the file system
> layer (e.g., the block layer, device drivers, etc.).
>
>
> > > /dev/sdb7: ***** FILE SYSTEM WAS MODIFIED *****
> > >
> > > Other times, I have gotten:
> > >
> > > "Inodes that were part of a corrupted orphan linked list found."
> > > "Block bitmap differences:"
> > > "Free blocks sound wrong for group"
> > >
>
> This variety of issues also implies that the issue may be in the data
> read by the file system, as opposed to an issue in the file system.
>
> Arthur, can you give us the full details of your hardware
> configuration and your kernel config file?  Also, what kernel git
> commit ID were you testing?

I'm seeing similar things running post v5.1 on ARAnyM (Atari emulator):

    EXT4-fs (sda1): mounting ext3 file system using the ext4 subsystem
    ...
    EXT4-fs error (device sda1): ext4_get_branch:171: inode #1980:
block 27550: comm jbd2/sda1-1980: invalid block

and userspace hung somewhere during initial system startup, so I had to
kill the instance.

-----

    EXT4-fs (sda1): mounting ext3 file system using the ext4 subsystem
    EXT4-fs (sda1): INFO: recovery required on readonly filesystem
    EXT4-fs (sda1): write access will be enabled during recovery
    EXT4-fs warning (device sda1): ext4_clear_journal_err:5078:
Filesystem error recorded from previous mount: IO failure
    EXT4-fs warning (device sda1): ext4_clear_journal_err:5079:
Marking fs in need of filesystem check.
    EXT4-fs (sda1): recovery complete
    EXT4-fs (sda1): mounted filesystem with ordered data mode. Opts: (null)
    VFS: Mounted root (ext3 filesystem) readonly on device 8:1.
    ...
    Run /sbin/init as init process
    random: fast init done
    EXT4-fs (sda1): re-mounted. Opts:
    random: crng init done
    EXT4-fs (sda1): re-mounted. Opts: errors=remount-ro
    EXT4-fs (sda1): error count since last fsck: 1
    EXT4-fs (sda1): initial error at time 1557931133:
ext4_get_branch:171: inode 1980: block 27550
    EXT4-fs (sda1): last error at time 1557931133:
ext4_get_branch:171: inode 1980: block 27550

-----

    EXT4-fs (sda1): mounting ext3 file system using the ext4 subsystem
    EXT4-fs (sda1): mounted filesystem with ordered data mode. Opts: (null)
    VFS: Mounted root (ext3 filesystem) readonly on device 8:1.
    ...
    Run /sbin/init as init process
    random: fast init done
    EXT4-fs (sda1): re-mounted. Opts:
    EXT4-fs (sda1): re-mounted. Opts: errors=remount-ro
    random: crng init done
    EXT4-fs error (device sda1): ext4_get_branch:171: inode #1980:
block 27550: comm jbd2/sda1-1980: invalid block
    Aborting journal on device sda1-1980.
    EXT4-fs (sda1): Remounting filesystem read-only
    jbd2_journal_bmap: journal block not found at offset 426 on sda1-1980
    EXT4-fs error (device sda1): ext4_journal_check_start:61: Detected
aborted journal
    EXT4-fs (sda1): error count since last fsck: 3
    EXT4-fs (sda1): initial error at time 1557931133:
ext4_get_branch:171: inode 1980: block 27550
    EXT4-fs (sda1): last error at time 1558083596:
ext4_journal_check_start:61: inode 1980: block 27550
    EXT4-fs error (device sda1): ext4_remount:5328: Abort forced by user

---

    EXT4-fs (sda1): mounting ext3 file system using the ext4 subsystem
    EXT4-fs (sda1): INFO: recovery required on readonly filesystem
    EXT4-fs (sda1): write access will be enabled during recovery
    random: fast init done
    EXT4-fs warning (device sda1): ext4_clear_journal_err:5078:
Filesystem error recorded from previous mount: IO failure
    EXT4-fs warning (device sda1): ext4_clear_journal_err:5079:
Marking fs in need of filesystem check.
    EXT4-fs (sda1): recovery complete
    EXT4-fs (sda1): mounted filesystem with ordered data mode. Opts: (null)
    ...
    Run /sbin/init as init process
    random: crng init done
    EXT4-fs (sda1): re-mounted. Opts:
    EXT4-fs (sda1): re-mounted. Opts: errors=remount-ro
    EXT4-fs (sda1): error count since last fsck: 4
    EXT4-fs (sda1): initial error at time 1557931133:
ext4_get_branch:171: inode 1980: block 27550
    EXT4-fs (sda1): last error at time 1558083665: ext4_remount:5328:
inode 1980: block 27550

Notes:
  - It's always the same block,
  - Block device is an image file, accessed using
    arch/m68k/emu/nfblock.c, which did not receive any recent (bvec)
    updates.
  - There are no reported errors for the device containing the image
    file on the host,
  - Given Arthur sees the issue on a different class of machines, it's
    unlikely the issue is related to a problem with the block device
    (driver). It may still be an issue with the block layer, though,
  - Both Arthur and I are mounting an ext3 file system using the ext4
    subsystem.

Thanks!

Gr{oetje,eeting}s,

                        Geert

-- 
Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org

In personal conversations with technical people, I call myself a hacker. But
when I'm talking to journalists I just say "programmer" or something like that.
                                -- Linus Torvalds