journal recovery problems with metadata_csum, *non-64bit*

journal recovery problems with metadata_csum, *non-64bit*

[TR Reardon]

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

Kernel 3.16, e2fsprogs 1.43-WIP (1.42.11 compiled with metadata_csum
support), filesystems mounted with journal_async_commit.

This may be an fsck problem, hard to tell.  I consistently have
problems with journal recovery after hard reboot when filesystem has
metadata_csum.   Interestingly, no problems with 64-bit filesystems.

during journal replay, bogus block numbers are reported.  in this
case, a 128MB file was deleted on two filesystems where the only
difference is 64bit vs non-64bit.  This also happens with or without
bigalloc, though I only document bigalloc case here.

please see attached superblocks, dumped just prior to hard reboot.
disk8=sdm1, disk9=sdn1

dmesg:

[Fri Aug  8 15:16:28 2014] JBD2: Out of memory during recovery.
[Fri Aug  8 15:16:28 2014] JBD2: recovery failed
[Fri Aug  8 15:16:28 2014] EXT4-fs (sdm1): error loading journal
[Fri Aug  8 15:16:27 2014] EXT4-fs (sdn1): recovery complete
[Fri Aug  8 15:16:27 2014] EXT4-fs (sdn1): mounted filesystem with
ordered data mode. Opts: journal_async_commit


fsck:

#e2fsck -f -v /dev/sdm1
e2fsck 1.43-WIP (09-Jul-2014)
disk8: recovering journal
Error writing block 549755813991 (Invalid argument).  Ignore error<y>? yes
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 (11332304, counted=11365072).
Fix<y>? yes
Free inodes count wrong (177287, counted=177288).
Fix<y>? yes

disk8: ***** FILE SYSTEM WAS MODIFIED *****

        1656 inodes used (0.93%, out of 178944)
         260 non-contiguous files (15.7%)
           0 non-contiguous directories (0.0%)
             # of inodes with ind/dind/tind blocks: 0/0/0
             Extent depth histogram: 1280/363/5
   721201312 blocks used (98.45%, out of 732566384)
           0 bad blocks
         358 large files

        1267 regular files
         380 directories
           0 character device files
           0 block device files
           0 fifos
           0 links
           0 symbolic links (0 fast symbolic links)
           0 sockets
------------
        1647 files

[-- Attachment #2: disk8-dumpe2fs-postrm --]
[-- Type: application/octet-stream, Size: 2068 bytes --]

Filesystem volume name:   disk8
Last mounted on:          /mnt/disk8
Filesystem UUID:          0df882a5-1df6-4d51-b037-c132e308e341
Filesystem magic number:  0xEF53
Filesystem revision #:    1 (dynamic)
Filesystem features:      has_journal ext_attr resize_inode dir_index filetype needs_recovery extent flex_bg sparse_super large_file huge_file dir_nlink extra_isize bigalloc 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:              178944
Block count:              732566384
Reserved block count:     0
Free blocks:              11332304
Free inodes:              177287
First block:              0
Block size:               4096
Cluster size:             65536
Reserved GDT blocks:      53
Blocks per group:         524288
Clusters per group:       32768
Inodes per group:         128
Inode blocks per group:   8
Flex block group size:    16
Filesystem created:       Tue Jan 15 17:18:07 2013
Last mount time:          Fri Aug  8 14:46:01 2014
Last write time:          Fri Aug  8 14:46:01 2014
Mount count:              1
Maximum mount count:      -1
Last checked:             Fri Aug  8 14:43:58 2014
Check interval:           0 (<none>)
Lifetime writes:          6022 GB
Reserved blocks uid:      0 (user root)
Reserved blocks gid:      0 (group root)
First inode:              11
Inode size:	          256
Required extra isize:     28
Desired extra isize:      28
Journal inode:            8
Default directory hash:   half_md4
Directory Hash Seed:      e0f46c10-ece6-43a4-9469-c0d89d644b0f
Journal backup:           inode blocks
Checksum type:            crc32c
Checksum:                 0xfa490415
Journal features:         journal_incompat_revoke journal_async_commit journal_checksum_v2
Journal size:             128M
Journal length:           32768
Journal sequence:         0x0000007f
Journal start:            1
Journal checksum type:    crc32c
Journal checksum:         0xcfb7b45e


[-- Attachment #3: disk9-dumpe2fs-postrm --]
[-- Type: application/octet-stream, Size: 2077 bytes --]

Filesystem volume name:   disk9
Last mounted on:          /mnt/disk9
Filesystem UUID:          11399183-4f42-4b14-8b5d-37cbda38b029
Filesystem magic number:  0xEF53
Filesystem revision #:    1 (dynamic)
Filesystem features:      has_journal ext_attr dir_index filetype needs_recovery extent 64bit flex_bg sparse_super large_file huge_file dir_nlink extra_isize bigalloc 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:              178944
Block count:              732566384
Reserved block count:     0
Free blocks:              167886960
Free inodes:              177612
First block:              0
Block size:               4096
Cluster size:             65536
Group descriptor size:    64
Blocks per group:         524288
Clusters per group:       32768
Inodes per group:         128
Inode blocks per group:   8
Flex block group size:    16
Filesystem created:       Thu Dec 26 19:29:21 2013
Last mount time:          Fri Aug  8 14:42:56 2014
Last write time:          Fri Aug  8 14:42:56 2014
Mount count:              10
Maximum mount count:      -1
Last checked:             Thu Aug  7 01:35:20 2014
Check interval:           0 (<none>)
Lifetime writes:          2413 GB
Reserved blocks uid:      0 (user root)
Reserved blocks gid:      0 (group root)
First inode:              11
Inode size:	          256
Required extra isize:     28
Desired extra isize:      28
Journal inode:            8
Default directory hash:   half_md4
Directory Hash Seed:      77780d74-59c9-4910-88c1-ff50c3e955c1
Journal backup:           inode blocks
Checksum type:            crc32c
Checksum:                 0x20f09425
Journal features:         journal_incompat_revoke journal_64bit journal_async_commit journal_checksum_v2
Journal size:             128M
Journal length:           32768
Journal sequence:         0x0001e11b
Journal start:            1
Journal checksum type:    crc32c
Journal checksum:         0x98d70b93

Re: journal recovery problems with metadata_csum, *non-64bit*

[Theodore Ts'o]

On Fri, Aug 08, 2014 at 03:31:12PM -0400, TR Reardon wrote:
> Kernel 3.16, e2fsprogs 1.43-WIP (1.42.11 compiled with metadata_csum
> support), filesystems mounted with journal_async_commit.
> 
> This may be an fsck problem, hard to tell.  I consistently have
> problems with journal recovery after hard reboot when filesystem has
> metadata_csum.   Interestingly, no problems with 64-bit filesystems.

These are test file systems I hope.  metadata_csum is something where
we're still working out some of the bugs.  (Obviously)

So metadata_csum works fine with 64-bit file systems, but it is
failing with journal recovery if the 64-bit file system feature is not
enabled?  Is that a correct summary of what you are seeing?

Also, with e2fsprogs 1.43-WIP releases, it's important that you
specify the git commit id you are using, since the next branch in
particular is quite fast moving.

						- Ted

Re: journal recovery problems with metadata_csum, *non-64bit*

[TR Reardon]

On Fri, Aug 8, 2014 at 5:47 PM, Theodore Ts'o <tytso@mit.edu> wrote:
> So metadata_csum works fine with 64-bit file systems, but it is
> failing with journal recovery if the 64-bit file system feature is not
> enabled?  Is that a correct summary of what you are seeing?

Correct.

> Also, with e2fsprogs 1.43-WIP releases, it's important that you
> specify the git commit id you are using, since the next branch in
> particular is quite fast moving.
>

Using master @ de25d9c8c48c7474828e9452184e204b18b8e090, which was the
1.42.11 release.  The current master and next have same problem.

I'd rather use debian versions, but metadata_csum is disabled there.
debian does not sync with git master, so what exactly does it sync
with?  ie, how are the metadata_csum patches dropped, since they exist
in master?

Re: journal recovery problems with metadata_csum, *non-64bit*

[Theodore Ts'o]

On Fri, Aug 08, 2014 at 06:29:40PM -0400, TR Reardon wrote:
> 
> Using master @ de25d9c8c48c7474828e9452184e204b18b8e090, which was the
> 1.42.11 release.  The current master and next have same problem.

What's going on is that the "master" and "next" branches on the
e2fsprogs git tree are development branches which will eventually be
the 1.43.0 release.  The "maint" branch is where the 1.42.x releases
are cut.

The maint branch does not have metadata_csum and inline_data support
at all.  It's not a matter of it being disabled, that code is simply
not there.

So I'm not sure what you mean by "master @
de25d9c8c48c7474828e9452184e204b18b8e090".  Your local git tree may
have assigned master to that git commit id, but then it wouldn't have
any metadata_csum support at all.


> I'd rather use debian versions, but metadata_csum is disabled there.
> debian does not sync with git master, so what exactly does it sync
> with?  ie, how are the metadata_csum patches dropped, since they exist
> in master?

See above.  The reason why debian doesn't support metadata_csum is
because it's not ready yet.  If you'd like to help us debug it, we
will be very grateful, but please understand it's still a work in
progress.

There's a big difference between "it mostly works", and "it's ready
for it to be used in production".  When I have time I might drop a
1.43-WIP ("work in progress") into debian experimental, but Debian
Jessie is going to be targetting 3.16, and we will need to make sure
that all of the necessary kernel bits for metadata_csum and
inline_data are working flawlessly before I'll want to let a 1.43
release into Debian testing --- and that's assuming we can get the
1.43 userspace bits fully stablized as well before Jessie date of
November 5, 2014.

Cheers,

					- Ted

Re: journal recovery problems with metadata_csum, *non-64bit*

[Theodore Ts'o]

On Fri, Aug 08, 2014 at 11:29:11PM -0400, TR Reardon wrote:
> 
> I meant only: that commit is in master _and_ maint branches, so to get a
> version roughly = 1.42.11 + metadata_csum, I pulled up to that commit.

Right but you gave me the git commit id for 1.42.11, which is not
particularly useful; I know the commit id for v1.42.11 already.  :-)

What I needed to know was the git commit of "master" that you had
grabbed, since the "master" and "next" branches are fairly active
these days.  (The master branch langs the next branch, so depending on
how exciting a life you want to live, you can try the next branch
instead of the master branch.)

> Regardless, the problem exists in kernel too, judging by the JBD2 errors.

Yes, we'll need to look into that.  Definitely worth knowing; thanks
for that.

Cheers,

					- Ted

Re: journal recovery problems with metadata_csum, *non-64bit*

[Darrick J. Wong]

On Fri, Aug 08, 2014 at 03:31:12PM -0400, TR Reardon wrote:
> Kernel 3.16, e2fsprogs 1.43-WIP (1.42.11 compiled with metadata_csum
> support), filesystems mounted with journal_async_commit.
> 
> This may be an fsck problem, hard to tell.  I consistently have
> problems with journal recovery after hard reboot when filesystem has
> metadata_csum.   Interestingly, no problems with 64-bit filesystems.
> 
> during journal replay, bogus block numbers are reported.  in this
> case, a 128MB file was deleted on two filesystems where the only
> difference is 64bit vs non-64bit.  This also happens with or without
> bigalloc, though I only document bigalloc case here.

Could you post full logs, including the bogus block numbers, please?  I've a
suspicion that we might be mishandling the 32/64 bit switch in either the
descriptor block or the revocation block, but it's hard to tell from the five
lines of log.

--D
> 
> please see attached superblocks, dumped just prior to hard reboot.
> disk8=sdm1, disk9=sdn1
> 
> dmesg:
> 
> [Fri Aug  8 15:16:28 2014] JBD2: Out of memory during recovery.
> [Fri Aug  8 15:16:28 2014] JBD2: recovery failed
> [Fri Aug  8 15:16:28 2014] EXT4-fs (sdm1): error loading journal
> [Fri Aug  8 15:16:27 2014] EXT4-fs (sdn1): recovery complete
> [Fri Aug  8 15:16:27 2014] EXT4-fs (sdn1): mounted filesystem with
> ordered data mode. Opts: journal_async_commit
> 
> 
> fsck:
> 
> #e2fsck -f -v /dev/sdm1
> e2fsck 1.43-WIP (09-Jul-2014)
> disk8: recovering journal
> Error writing block 549755813991 (Invalid argument).  Ignore error<y>? yes
> 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 (11332304, counted=11365072).
> Fix<y>? yes
> Free inodes count wrong (177287, counted=177288).
> Fix<y>? yes
> 
> disk8: ***** FILE SYSTEM WAS MODIFIED *****
> 
>         1656 inodes used (0.93%, out of 178944)
>          260 non-contiguous files (15.7%)
>            0 non-contiguous directories (0.0%)
>              # of inodes with ind/dind/tind blocks: 0/0/0
>              Extent depth histogram: 1280/363/5
>    721201312 blocks used (98.45%, out of 732566384)
>            0 bad blocks
>          358 large files
> 
>         1267 regular files
>          380 directories
>            0 character device files
>            0 block device files
>            0 fifos
>            0 links
>            0 symbolic links (0 fast symbolic links)
>            0 sockets
> ------------
>         1647 files

Re: journal recovery problems with metadata_csum, *non-64bit*

[TR Reardon]

Ok, I found the problem in jbd2, and have a solution, though it's
debatable what the ideal solution is.  For now, the simplest patch is
below, though a similar patch in lib/ext2fs/kernel-jbd.h is required
to get e2fsck back in sync.

The original c3900875 commit adding metadata_csum (ie
journal_checksum_v2) to jbd2 added 2 extra bytes for the block
checksums, in addition to re-allocating 2 bytes from the 4 bytes of
flags.  However, a decision was made to only retain the lower 16-bits
of the crc32c, and thus those extra 2 bytes were unneeded.  But those
2 extra bytes were never "deallocated" from journal_tag_bytes().

Unfortunately, different code relies on JBD_TAG_SIZE32/64 constants
directly rather than the journal_tag_bytes() utility function, in
particular the recovery code which is common to e2fsck and jbd2.  This
led different tools to think they were looking at a 64bit journal when
actually it was 32bit.  Code that relied on journal_tag_bytes()
remained safe, so the block iterators were fine, but any direct use of
those constants [including the hideous greater-than comparison in
read_tag_bytes()] went awry, and journal replay will fail.

As far as I can tell, metadata_csum + journal checksum has never
worked for 32bit filesystems. By a little bit of padding luck, 64bit
worked fine.

Now, as to the solution: depends on whether one feels that existing
in-the-wild journals matter. The original commit was May 2012, are we
past early-adopters now?  If this patch is taken, you shrink the
journal block tags to the intended size but in-the-wild journals will
be broken.  But they already are, so...?  This opens up the
possibility of now using those extra 2 bytes and retaining full 32-bit
crc32c for the block tags.  If going that route, debugs/logdump needs
a fix in addition to changes to jbd2.

FWIW, the "JBD2: Out of memory during recovery." error in
fs/jbd2/recovery.c was opaque at best and should be changed to always
include the block# that caused the problem.

+Reardon

---
diff --git a/fs/jbd2/journal.c b/fs/jbd2/journal.c
index 67b8e30..dc27d09 100644
--- a/fs/jbd2/journal.c
+++ b/fs/jbd2/journal.c
@@ -2166,15 +2166,11 @@ int jbd2_journal_blocks_per_page(struct inode *inode)
 size_t journal_tag_bytes(journal_t *journal)
 {
        journal_block_tag_t tag;
-       size_t x = 0;

Re: journal recovery problems with metadata_csum, *non-64bit*

[Darrick J. Wong]

On Sun, Aug 10, 2014 at 06:35:33PM -0400, TR Reardon wrote:
> Ok, I found the problem in jbd2, and have a solution, though it's
> debatable what the ideal solution is.  For now, the simplest patch is
> below, though a similar patch in lib/ext2fs/kernel-jbd.h is required
> to get e2fsck back in sync.
> 
> The original c3900875 commit adding metadata_csum (ie
> journal_checksum_v2) to jbd2 added 2 extra bytes for the block
> checksums, in addition to re-allocating 2 bytes from the 4 bytes of
> flags.  However, a decision was made to only retain the lower 16-bits
> of the crc32c, and thus those extra 2 bytes were unneeded.  But those
> 2 extra bytes were never "deallocated" from journal_tag_bytes().

Hrmm... yes, I remember trying to push for full 32-bit checksums on journal
blocks, and our subsequent decision not to put in the two bytes.  Oops.

(This looks more like a coding error on my part.)

I suppose it would help to be able to use debugfs or something to create
journal transactions just to see if they'll replay correctly in the
kernel/e2fsck.  I've wondered for a while if the e2fsck jbd code ought to be
pushed into libext2fs (or libjbd2) to make this easier.  A long ago fuse2fs
patchbomb actually did this so that fuse2fs could at least replay the journal.

> Unfortunately, different code relies on JBD_TAG_SIZE32/64 constants
> directly rather than the journal_tag_bytes() utility function, in
> particular the recovery code which is common to e2fsck and jbd2.  This
> led different tools to think they were looking at a 64bit journal when
> actually it was 32bit.  Code that relied on journal_tag_bytes()
> remained safe, so the block iterators were fine, but any direct use of
> those constants [including the hideous greater-than comparison in
> read_tag_bytes()] went awry, and journal replay will fail.

Hmm... I thought recovery.c sets tag_bytes to journal_tag_bytes()?

(It's late, I'll have another look in the morning.)

> As far as I can tell, metadata_csum + journal checksum has never
> worked for 32bit filesystems. By a little bit of padding luck, 64bit
> worked fine.
`
D'oh. :(

FWIW, 64bit is recommended for metadata_csum since it enables full 32-bit
bitmap checksums.

> Now, as to the solution: depends on whether one feels that existing
> in-the-wild journals matter. The original commit was May 2012, are we
> past early-adopters now?  If this patch is taken, you shrink the

Definitely not past the early adopter stage.  The e2fsprogs code will be in
1.43, which means that most people can't use metadata_csum yet.

So, thank you very much for helping us to smoke test. :)

> journal block tags to the intended size but in-the-wild journals will
> be broken.  But they already are, so...?  This opens up the
> possibility of now using those extra 2 bytes and retaining full 32-bit
> crc32c for the block tags.  If going that route, debugs/logdump needs
> a fix in addition to changes to jbd2.

In theory the only wild journals should be on test FSes anyway, so breaking
them isn't the end of the world.

But as you point out, the space is already getting used because journal_csum_v2
is the gate for the extra 2 bytes to be turned on, so I guess we could just use
the extra 2 bytes and store the full checksum.

> FWIW, the "JBD2: Out of memory during recovery." error in
> fs/jbd2/recovery.c was opaque at best and should be changed to always
> include the block# that caused the problem.

recovery.c line 611, correct?

--D
> 
> +Reardon
> 
> ---
> diff --git a/fs/jbd2/journal.c b/fs/jbd2/journal.c
> index 67b8e30..dc27d09 100644
> --- a/fs/jbd2/journal.c
> +++ b/fs/jbd2/journal.c
> @@ -2166,15 +2166,11 @@ int jbd2_journal_blocks_per_page(struct inode *inode)
>  size_t journal_tag_bytes(journal_t *journal)
>  {
>         journal_block_tag_t tag;
> -       size_t x = 0;
> -
> -       if (JBD2_HAS_INCOMPAT_FEATURE(journal, JBD2_FEATURE_INCOMPAT_CSUM_V2))
> -               x += sizeof(tag.t_checksum);
> 
>         if (JBD2_HAS_INCOMPAT_FEATURE(journal, JBD2_FEATURE_INCOMPAT_64BIT))
> -               return x + JBD2_TAG_SIZE64;
> +               return JBD2_TAG_SIZE64;
>         else
> -               return x + JBD2_TAG_SIZE32;
> +               return JBD2_TAG_SIZE32;
>  }
> 
>  /*