Bug 201823

Summary: inconsistent behaviour of xfs_db, xfs_repair and xfs_scrub
Product: File System Reporter: Matthias (matthias)
Component: XFSAssignee: Eric Sandeen (sandeen)
Status: RESOLVED CODE_FIX    
Severity: normal CC: sandeen
Priority: P1    
Hardware: All   
OS: Linux   
Kernel Version: 4.19.5 Subsystem:
Regression: No Bisected commit-id:

Description Matthias 2018-12-01 08:16:13 UTC 
Hi,

I am using xfs on Manjaro with kernel 4.19 and latest xfsprogs 4.19.0-1.

I checked my root filesystem with xfs_db for fragmentation and got metadata corruption messages:

5# xfs_db -c frag -r /dev/sde1
Metadata corruption detected at 0x558ed74133f3, xfs_inode block 0x7faac0/0x8000
Metadata corruption detected at 0x558ed74133f3, xfs_inode block 0x20cb300/0x8000
Metadata corruption detected at 0x558ed74133f3, xfs_inode block 0x2341340/0x8000
aktuell 976616, ideal 970547, Unterteilungsfaktor 0,62%
Note, this number is largely meaningless.
Files on this filesystem average 1,01 extents per file

But xfs_repiar is not mentioning anything and hence not repairing anything. Also, xfs_scrub is not complaining:

8# xfs_scrub -v /    
EXPERIMENTAL xfs_scrub program in use! Use at your own risk!
Phase 1: Find filesystem geometry.
/: using 8 threads to scrub.
Phase 2: Check internal metadata.
Phase 3: Scan all inodes.
Phase 5: Check directory tree.
Phase 7: Check summary counters.
41,6GiB data used;  1,3M inodes used.
41,5GiB data found; 1,3M inodes found.
1,3M inodes counted; 1,3M inodes checked.


How do I have to interpret these results? 
What can I do to get repair it?

I created an xfs dump just in case somebody wants to debug this.

Thank you for your help
Matthias
Comment 1 Matthias 2018-12-01 19:13:48 UTC 
I see that inode 0x234134 has a bad v3.crc:

xfs_db> inode 0x2341340
Metadata corruption detected at 0x56047ae6a3f3, xfs_inode block 0x1bab340/0x4000
Metadata CRC error detected for ino 36967232
xfs_db> p
core.magic = 0x3132
core.mode = 033062
core.version = 32
core.format = 56
core.nlinkv2 = 775108409
core.onlink = 14649
core.projid_lo = 12597
core.projid_hi = 8268
core.uid = 775371058
core.gid = 925645104
core.flushiter = 13361
core.atime.sec = Wed May 24 22:18:58 2000
core.atime.nsec = 775173426
core.mtime.sec = Thu Aug 17 12:56:03 1995
core.mtime.nsec = 540555575
core.ctime.sec = Fri Jul 29 00:54:45 1994
core.ctime.nsec = 875313459
core.size = 3328777196389539896
core.nblocks = 4123096260573147948
core.extsize = 959655481
core.nextents = 942880825
core.naextents = 8248
core.forkoff = 57
core.aformat = 57
core.dmevmask = 0x2e343530
core.dmstate = 13612
core.newrtbm = 0
core.prealloc = 1
core.realtime = 1
core.immutable = 0
core.append = 1
core.sync = 1
core.noatime = 0
core.nodump = 0
core.rtinherit = 1
core.projinherit = 0
core.nosymlinks = 0
core.extsz = 1
core.extszinherit = 1
core.nodefrag = 1
core.filestream = 0
core.gen = 775371064
next_unlinked = 959717452
v3.crc = 0x20393031 (bad)
v3.change_count = 3330188947660289070
v3.lsn = 0x3130373037204320
v3.flags2 = 0x3930322e33333631
v3.cowextsize = 741946158
v3.crtime.sec = Wed Mar 26 15:01:29 1997
v3.crtime.nsec = 858665010
v3.inumber = 4123108269418885678
v3.uuid = 34333636-2c39-322e-3238-333338203930
v3.reflink = 0
v3.cowextsz = 0
u3 = (leer)
a = (leer)

I would like to know which file belongs to that inode before I try recalculate it. But "blockget -n" is always running out of memory. 

Anyways, why isnt xfs_repair fixing this? Why isnt xfs_scrub showing this?
Comment 2 Dave Chinner 2018-12-01 22:44:24 UTC 
On Sat, Dec 01, 2018 at 08:16:13AM +0000, bugzilla-daemon@bugzilla.kernel.org wrote:
> https://bugzilla.kernel.org/show_bug.cgi?id=201823
> 
>             Bug ID: 201823
>            Summary: inconsistent behaviour of xfs_db, xfs_repair and
>                     xfs_scrub
>            Product: File System
>            Version: 2.5
>     Kernel Version: 4.19.5
>           Hardware: All
>                 OS: Linux
>               Tree: Mainline
>             Status: NEW
>           Severity: normal
>           Priority: P1
>          Component: XFS
>           Assignee: filesystem_xfs@kernel-bugs.kernel.org
>           Reporter: matthias@bodenbinder.de
>         Regression: No
> 
> Hi,
> 
> I am using xfs on Manjaro with kernel 4.19 and latest xfsprogs 4.19.0-1.
> 
> I checked my root filesystem with xfs_db for fragmentation and got metadata
> corruption messages:
> 
> 5# xfs_db -c frag -r /dev/sde1
> Metadata corruption detected at 0x558ed74133f3, xfs_inode block
> 0x7faac0/0x8000
> Metadata corruption detected at 0x558ed74133f3, xfs_inode block
> 0x20cb300/0x8000
> Metadata corruption detected at 0x558ed74133f3, xfs_inode block
> 0x2341340/0x8000
> aktuell 976616, ideal 970547, Unterteilungsfaktor 0,62%
> Note, this number is largely meaningless.
> Files on this filesystem average 1,01 extents per file

That is expected if you are running xfs_db on a mounted filesystem.
What is on disk at any given instant is not consistent. The combined
in-memory state, the journal and what is on-disk is consistent, but
you cannot see all that extra in-memory state from xfs_db. If the
system crashes, journal replay is what brings it back to being
consistent on disk. IOWs, this is expected behaviour.

> But xfs_repiar is not mentioning anything and hence not repairing anything.

xfs_repair won't run on a mounted filesystem.

> Also, xfs_scrub is not complaining:
> 
> 8# xfs_scrub -v /    
> EXPERIMENTAL xfs_scrub program in use! Use at your own risk!
> Phase 1: Find filesystem geometry.
> /: using 8 threads to scrub.
> Phase 2: Check internal metadata.
> Phase 3: Scan all inodes.
> Phase 5: Check directory tree.
> Phase 7: Check summary counters.
> 41,6GiB data used;  1,3M inodes used.
> 41,5GiB data found; 1,3M inodes found.
> 1,3M inodes counted; 1,3M inodes checked.

Scrub runs online, so sees the in-memory state of the filesystem
along with what is on disk, and hence it doesn't find any
corruptions because there are none.

IOWs, there are no problems and everything is behaving as expected.

-Dave.
Comment 3 Eric Sandeen 2018-12-02 01:14:09 UTC 
> # xfs_db -c frag -r /dev/sde1

I think Dave's analysis is correct, but to be sure, can you confirm that this command was run while mounted?
Comment 4 Matthias 2018-12-02 08:27:48 UTC 
The error occurs also with unmounted drive. Sorry for posting the output of the "xfs_db -r" command this is misleading.

The first thing I did is checking it with a KNOPPIX 8.2 live CD. xfs_db is showing the erros but xfs_repair does not repair anything.

Here the relevant outputs. /dev/sde1 is not mounted:

######

knoppix@Microknoppix:~$ uname -a
Linux Microknoppix 4.16.5-64 #1 SMP PREEMPT Sun Apr 29 17:09:15 CEST 2018 x86_64 GNU/Linux

######

knoppix@Microknoppix:~$ xfs_db /dev/sde1
xfs_db> frag
Metadata corruption detected at xfs_inode block 0x7faac0/0x8000
Metadata corruption detected at xfs_inode block 0x7faac0/0x8000
Metadata corruption detected at xfs_inode block 0x7faac0/0x8000
Metadata corruption detected at xfs_inode block 0x7faac0/0x8000
Metadata corruption detected at xfs_inode block 0x7faac0/0x8000
Metadata corruption detected at xfs_inode block 0x7faac0/0x8000
Metadata corruption detected at xfs_inode block 0x7faac0/0x8000
Metadata corruption detected at xfs_inode block 0x7faac0/0x8000
Metadata corruption detected at xfs_inode block 0x7faac0/0x8000
Metadata corruption detected at xfs_inode block 0x7faac0/0x8000
Metadata corruption detected at xfs_inode block 0x7faac0/0x8000
Metadata corruption detected at xfs_inode block 0x7faac0/0x8000
Metadata corruption detected at xfs_inode block 0x7faac0/0x8000
Metadata corruption detected at xfs_inode block 0x7faac0/0x8000
Metadata corruption detected at xfs_inode block 0x7faac0/0x8000
Metadata corruption detected at xfs_inode block 0x7faac0/0x8000
Metadata corruption detected at xfs_inode block 0x7faac0/0x8000
Metadata corruption detected at xfs_inode block 0x7faac0/0x8000
Metadata corruption detected at xfs_inode block 0x7faac0/0x8000
Metadata corruption detected at xfs_inode block 0x7faac0/0x8000
Metadata corruption detected at xfs_inode block 0x7faac0/0x8000
Metadata corruption detected at xfs_inode block 0x7faac0/0x8000
Metadata corruption detected at xfs_inode block 0x7faac0/0x8000
Metadata corruption detected at xfs_inode block 0x7faac0/0x8000
Metadata corruption detected at xfs_inode block 0x7faac0/0x8000
Metadata corruption detected at xfs_inode block 0x7faac0/0x8000
Metadata corruption detected at xfs_inode block 0x7faac0/0x8000
Metadata corruption detected at xfs_inode block 0x7faac0/0x8000
Metadata corruption detected at xfs_inode block 0x7faac0/0x8000
Metadata corruption detected at xfs_inode block 0x7faac0/0x8000
Metadata corruption detected at xfs_inode block 0x7faac0/0x8000
Metadata corruption detected at xfs_inode block 0x7faac0/0x8000
Metadata corruption detected at xfs_inode block 0x20cb300/0x8000
Metadata corruption detected at xfs_inode block 0x20cb300/0x8000
Metadata corruption detected at xfs_inode block 0x20cb300/0x8000
Metadata corruption detected at xfs_inode block 0x20cb300/0x8000
Metadata corruption detected at xfs_inode block 0x20cb300/0x8000
Metadata corruption detected at xfs_inode block 0x20cb300/0x8000
Metadata corruption detected at xfs_inode block 0x20cb300/0x8000
Metadata corruption detected at xfs_inode block 0x20cb300/0x8000
Metadata corruption detected at xfs_inode block 0x20cb300/0x8000
Metadata corruption detected at xfs_inode block 0x20cb300/0x8000
Metadata corruption detected at xfs_inode block 0x20cb300/0x8000
Metadata corruption detected at xfs_inode block 0x20cb300/0x8000
Metadata corruption detected at xfs_inode block 0x20cb300/0x8000
Metadata corruption detected at xfs_inode block 0x20cb300/0x8000
Metadata corruption detected at xfs_inode block 0x20cb300/0x8000
Metadata corruption detected at xfs_inode block 0x20cb300/0x8000
Metadata corruption detected at xfs_inode block 0x20cb300/0x8000
Metadata corruption detected at xfs_inode block 0x20cb300/0x8000
Metadata corruption detected at xfs_inode block 0x20cb300/0x8000
Metadata corruption detected at xfs_inode block 0x20cb300/0x8000
Metadata corruption detected at xfs_inode block 0x20cb300/0x8000
Metadata corruption detected at xfs_inode block 0x20cb300/0x8000
Metadata corruption detected at xfs_inode block 0x20cb300/0x8000
Metadata corruption detected at xfs_inode block 0x20cb300/0x8000
Metadata corruption detected at xfs_inode block 0x20cb300/0x8000
Metadata corruption detected at xfs_inode block 0x20cb300/0x8000
Metadata corruption detected at xfs_inode block 0x20cb300/0x8000
Metadata corruption detected at xfs_inode block 0x20cb300/0x8000
Metadata corruption detected at xfs_inode block 0x20cb300/0x8000
Metadata corruption detected at xfs_inode block 0x20cb300/0x8000
Metadata corruption detected at xfs_inode block 0x20cb300/0x8000
Metadata corruption detected at xfs_inode block 0x20cb300/0x8000
Metadata corruption detected at xfs_inode block 0x2341340/0x8000
Metadata corruption detected at xfs_inode block 0x2341340/0x8000
Metadata corruption detected at xfs_inode block 0x2341340/0x8000
Metadata corruption detected at xfs_inode block 0x2341340/0x8000
Metadata corruption detected at xfs_inode block 0x2341340/0x8000
Metadata corruption detected at xfs_inode block 0x2341340/0x8000
Metadata corruption detected at xfs_inode block 0x2341340/0x8000
Metadata corruption detected at xfs_inode block 0x2341340/0x8000
Metadata corruption detected at xfs_inode block 0x2341340/0x8000
Metadata corruption detected at xfs_inode block 0x2341340/0x8000
Metadata corruption detected at xfs_inode block 0x2341340/0x8000
Metadata corruption detected at xfs_inode block 0x2341340/0x8000
Metadata corruption detected at xfs_inode block 0x2341340/0x8000
Metadata corruption detected at xfs_inode block 0x2341340/0x8000
Metadata corruption detected at xfs_inode block 0x2341340/0x8000
Metadata corruption detected at xfs_inode block 0x2341340/0x8000
Metadata corruption detected at xfs_inode block 0x2341340/0x8000
Metadata corruption detected at xfs_inode block 0x2341340/0x8000
Metadata corruption detected at xfs_inode block 0x2341340/0x8000
Metadata corruption detected at xfs_inode block 0x2341340/0x8000
Metadata corruption detected at xfs_inode block 0x2341340/0x8000
Metadata corruption detected at xfs_inode block 0x2341340/0x8000
Metadata corruption detected at xfs_inode block 0x2341340/0x8000
Metadata corruption detected at xfs_inode block 0x2341340/0x8000
Metadata corruption detected at xfs_inode block 0x2341340/0x8000
Metadata corruption detected at xfs_inode block 0x2341340/0x8000
Metadata corruption detected at xfs_inode block 0x2341340/0x8000
Metadata corruption detected at xfs_inode block 0x2341340/0x8000
Metadata corruption detected at xfs_inode block 0x2341340/0x8000
Metadata corruption detected at xfs_inode block 0x2341340/0x8000
Metadata corruption detected at xfs_inode block 0x2341340/0x8000
Metadata corruption detected at xfs_inode block 0x2341340/0x8000
aktuell 977134, ideal 970700, Unterteilungsfaktor 0,66%
Note, this number is largely meaningless.
Files on this filesystem average 1,01 extents per file
xfs_db> inode 0x2341340
Metadata corruption detected at xfs_inode block 0x1bab340/0x2000
Metadata corruption detected at xfs_inode block 0x1bab340/0x2000
Metadata corruption detected at xfs_inode block 0x1bab340/0x2000
Metadata corruption detected at xfs_inode block 0x1bab340/0x2000
Metadata corruption detected at xfs_inode block 0x1bab340/0x2000
Metadata corruption detected at xfs_inode block 0x1bab340/0x2000
Metadata corruption detected at xfs_inode block 0x1bab340/0x2000
Metadata corruption detected at xfs_inode block 0x1bab340/0x2000
Metadata corruption detected at xfs_inode block 0x1bab340/0x2000
Metadata corruption detected at xfs_inode block 0x1bab340/0x2000
Metadata corruption detected at xfs_inode block 0x1bab340/0x2000
Metadata corruption detected at xfs_inode block 0x1bab340/0x2000
Metadata corruption detected at xfs_inode block 0x1bab340/0x2000
Metadata corruption detected at xfs_inode block 0x1bab340/0x2000
Metadata corruption detected at xfs_inode block 0x1bab340/0x2000
Metadata corruption detected at xfs_inode block 0x1bab340/0x2000
Metadata CRC error detected for ino 36967232
xfs_db> p
core.magic = 0x3132
core.mode = 033062
core.version = 32
core.format = 56
core.nlinkv2 = 775108409
core.onlink = 14649
core.projid_lo = 12597
core.projid_hi = 8268
core.uid = 775371058
core.gid = 925645104
core.flushiter = 13361
core.atime.sec = Wed May 24 22:18:58 2000
core.atime.nsec = 775173426
core.mtime.sec = Thu Aug 17 12:56:03 1995
core.mtime.nsec = 540555575
core.ctime.sec = Fri Jul 29 00:54:45 1994
core.ctime.nsec = 875313459
core.size = 3328777196389539896
core.nblocks = 4123096260573147948
core.extsize = 959655481
core.nextents = 942880825
core.naextents = 8248
core.forkoff = 57
core.aformat = 57
core.dmevmask = 0x2e343530
core.dmstate = 13612
core.newrtbm = 0
core.prealloc = 1
core.realtime = 1
core.immutable = 0
core.append = 1
core.sync = 1
core.noatime = 0
core.nodump = 0
core.rtinherit = 1
core.projinherit = 0
core.nosymlinks = 0
core.extsz = 1
core.extszinherit = 1
core.nodefrag = 1
core.filestream = 0
core.gen = 775371064
next_unlinked = 959717452
v3.crc = 0x20393031 (bad)
v3.change_count = 3330188947660289070
v3.lsn = 0x3130373037204320
v3.flags2 = 0x3930322e33333631
v3.cowextsize = 741946158
v3.crtime.sec = Wed Mar 26 15:01:29 1997
v3.crtime.nsec = 858665010
v3.inumber = 4123108269418885678
v3.uuid = 34333636-2c39-322e-3238-333338203930
v3.reflink = 0
v3.cowextsz = 0
u3 = (leer)
a = (leer)
xfs_db> q

######

knoppix@Microknoppix:~$ xfs_repair -V
xfs_repair Version 4.9.0

######

knoppix@Microknoppix:~$ xfs_repair /dev/sde1
Phase 1 - Superblock finden und überprüfen...
Phase 2 - ein internes Protokoll benutzen
        - Null-Protokoll...
        - freier Speicher und Inode-Karten des Dateisystems werden
gescannt...
        - Wurzel-Inode-Stück gefunden
Phase 3 - für jedes AG...
        - agi unverknüpfte Listen werden gescannt und bereinigt...
        - bekannte Inodes werden behandelt und Inode-Entdeckung wird
durchgeführt...
        - agno = 0
        - agno = 1
        - agno = 2
        - agno = 3
        - neu entdeckte Inodes werden behandelt...
Phase 4 - auf doppelte Blöcke überprüfen...
        - Liste mit doppeltem Ausmaß wird eingerichtet...
        - es wird geprüft ob Inodes Blocks doppelt beanspruchen...
        - agno = 3
        - agno = 2
        - agno = 1
        - agno = 0
Phase 5 - AG-Köpfe und Bäume werden erneut gebildet...
        - Superblock wird zurückgesetzt...
Phase 6 - Inode-Verbindbarkeit wird geprüft...
        - Inhalte der Echtzeit-Bitmaps und Zusammenfassungs-Inodes werden zurückgesetzt
        - Dateisystem wird durchquert ...
        - durchqueren beendet ...
        - nicht verbundene Inodes werden nach lost+found verschoben ...
Phase 7 - Verweisanzahl wird geprüft und berichtigt...
erledigt

######
Comment 5 Eric Sandeen 2018-12-02 17:02:47 UTC 
If you'd like to send me a compressed metadump image (offline for maximum privacy) I'll take a look.

However, some of your messages above are a result user error: you are providing a block number as an inode number to xfs_db, so it is trying to parse a non-inode as an inode.
Comment 6 Matthias 2018-12-02 17:40:05 UTC 
Am 02.12.18 um 18:02 schrieb bugzilla-daemon@bugzilla.kernel.org:
> https://bugzilla.kernel.org/show_bug.cgi?id=201823
> 
> --- Comment #5 from Eric Sandeen (sandeen@sandeen.net) ---
> If you'd like to send me a compressed metadump image (offline for maximum
> privacy) I'll take a look.
> 
> However, some of your messages above are a result user error: you are
> providing
> a block number as an inode number to xfs_db, so it is trying to parse a
> non-inode as an inode.
> 

I will send you a dropbox link to the metadump
Comment 7 Eric Sandeen 2018-12-03 21:21:59 UTC 
So, the frag command emits these warnings under a debug build:

# xfs_db -c frag -r /dev/sde1
bad inode magic/vsn daddr 8366784 #0 (magic=5844)
Metadata corruption detected at 0x4289c3, xfs_inode block 0x7faac0/0x8000
bad inode magic/vsn daddr 34386688 #0 (magic=0)
Metadata corruption detected at 0x4289c3, xfs_inode block 0x20cb300/0x8000
bad inode magic/vsn daddr 36967232 #0 (magic=0)
Metadata corruption detected at 0x4289c3, xfs_inode block 0x2341340/0x8000

If we look at each of those blocks (daddr) after a blockget -n, 

xfs_db> daddr 8366784
xfs_db> blockuse
block 1045848 (0/1045848) type dir inode 8366719
xfs_db> daddr 34386688
xfs_db> blockuse
block 5292640 (1/1098336) type free2
xfs_db> daddr 36967232
xfs_db> blockuse
block 5615208 (1/1420904) type data inode 44934228

The "inode" corruption it's finding isn't actually in inode blocks...
Comment 8 Eric Sandeen 2018-12-03 22:16:45 UTC 
I think this is probably just a bug in the frag command, and not indicative of actual filesystem corruption.  Another reason to kill off the worthless frag() command.  ;)

I think the bug is probably in sparse inode chunk handling.
Comment 9 Eric Sandeen 2018-12-03 22:35:03 UTC 
Yep, that's the case.  We're missing the equivalent of

ea8a48f xfs_check: process sparse inode chunks correctly

for the frag function's version of scanfun_ino.  I'll send a patch to the list, but in the meantime I think you can relax: this is a bug in the xfs_db frag command, not filesystem corruption.
Comment 10 Eric Sandeen 2018-12-03 23:06:21 UTC 
I've sent a patch,

[PATCH] xfs_db: teach the frag command about sparse inode chunks
Comment 11 Eric Sandeen 2021-01-25 02:11:22 UTC 
commit 2a5eb70cbffdec6bfaba2916479a1743ec407751
Author: Eric Sandeen <sandeen@redhat.com>
Date:   Wed Dec 12 11:42:40 2018 -0600

    xfs_db: teach the frag command about sparse inode chunks
    
    This is the equivalent of:
    
    ea8a48f xfs_check: process sparse inode chunks correctly
    
    for the frag_f() command in xfs_db.
    
    Without this, the xfs_db frag command shows corruption as it
    wanders into blocks that are not inodes.
    
    Bugzilla: https://bugzilla.kernel.org/show_bug.cgi?id=201823
    Signed-off-by: Eric Sandeen <sandeen@redhat.com>
    Reviewed-by: Brian Foster <bfoster@redhat.com>
    Signed-off-by: Eric Sandeen <sandeen@sandeen.net>