[CHECKER] e2fsck writes out blocks out of order, causing root dir to be corrupted (ext3, linux 2.4.19, e2fsprogs 1.34)

[CHECKER] e2fsck writes out blocks out of order, causing root dir to be corrupted (ext3, linux 2.4.19, e2fsprogs 1.34)

[Junfeng Yang]

Hi,

We got a warning that the filesystem was in a inconsistent state when:
1. created a crashed disk image
2. ran fsck over the image and then crash fsck at certain point
3. re-ran fsck.

We got the crashed disk image by making 2 directories under / then runing
kjournald to commit.  once we saw the commit block was written to disk, we
crashed the experimental disk (a virtual ram disk), prior to actual disk
writes.

We then ran fsck over the crashed disk image.  We interrupted fsck after
 the journal super block was reset on disk (fsck will reset the journal
superblock once it is done replaying).  We ran fsck again on the half-done
disk image (half-done because some block writes were cached by fsck).
e2fsck complained that the two directories we created are unconnected and
linked them into lost+found.  It also fixed the datablock for the root /.

After we investigated the message, it seems that e2fsck does cache writes
(unix_io.c).  Actual raw block device writes can happen when 1. a dirty
block is kicked out of the cache 2. the cache is flushed.  Neither of
these pay attention to the journaling constraints of EXT3 and JBD.

In our case, after journal recovering, the journal super block hits the
disk before the root dir block hits the disk.  If fsck is interrupted
(e.g. power outage) after the journal super block and the first few
sectors of the root dir block are written, we could be in an irrecoverable
state with a corrupted root dir block.  (Worse things could happen if
blocks can be written out in arbitrary order)

We checked ext3 on linux 2.4.19, with e2fsprogs-1.34.  The crashed disk
image can be obtained from http://keeda.stanford.edu/~junfeng/exp_disk.tgz

As usual, clarifications/confirmations are appreciated.  Let me know if
anything is not clear.

Thanks,
-Junfeng

------------------------------------------------------------------------------
Below is the commented messages collected from runing e2fsck without
interruption.  We print out a debug message when unix_write_blk,
flush_cached_blocks, reuse_cache, raw_blk_write are called.  reuse_cache
does the cache eviction.  Comments are in brackets.

e2fsck 1.34 (25-Jul-2003)
FSCK: unix_write_blk block 268   [268 = journal super block]
FSCK: cache hit for block 268
/dev/shm/junfeng/exp_disk: recovering journal
FSCK: unix_write_blk block 4
FSCK: unix_write_blk block 2
FSCK: cache evict block 268
FSCK: raw_write_blk 268
FSCK: unix_write_blk block 1
FSCK: unix_write_blk block 6
FSCK: unix_write_blk block 3
FSCK: cache evict block 4
FSCK: raw_write_blk 4	         [4 = inode bitmap]
FSCK: unix_write_blk block 1298
FSCK: cache evict block 2
FSCK: raw_write_blk 2		 [2 = group descriptor]
FSCK: unix_write_blk block 5
FSCK: cache evict block 1
FSCK: raw_write_blk 1		 [1 = super block]
FSCK: unix_write_blk block 255 	 [255 = first block for root /]
FSCK: cache evict block 6
FSCK: raw_write_blk 6		 [write inodes for the two new dirs]
FSCK: unix_write_blk block 1299
FSCK: cache evict block 3
FSCK: raw_write_blk 3		 [3 = block bitmap]
FSCK: unix_write_blk block 268
FSCK: cache evict block 1298
FSCK: raw_write_blk 1298
FSCK: cache flush block 1299
FSCK: raw_write_blk 1299
FSCK: cache flush block 268
FSCK: raw_write_blk 268		  [log is reset by this write]
FSCK: cache flush block 255 	  [if crash here, bad!]
FSCK: raw_write_blk 255		  [write out root block after journal is reset]
FSCK: cache flush block 5
FSCK: raw_write_blk 5		  [write root inode]
FSCK: unix_write_blk block 2
FSCK: cache flush block 2
FSCK: raw_write_blk 2
FSCK: unix_write_blk block 268
FSCK: cache hit for block 268
Pass 1: Checking inodes, blocks, and sizes
FSCK: cache flush block 268
FSCK: raw_write_blk 268
Pass 2: Checking directory structure
Pass 3: Checking directory connectivity
Pass 4: Checking reference counts
Pass 5: Checking group summary information
/dev/shm/junfeng/exp_disk: 13/2000 files (0.0% non-contiguous), 1300/8000 blocks
FSCK: unix_write_blk block 2
FSCK: cache flush block 2
FSCK: raw_write_blk 2

------------------------------------------------------------------------------
Here are the details of how to get the crashed disk image:

1. Call sys_create to create a directory '1' under /. The filesystem looks like
[0:D]
  [1:D]

2. journal->j_commit_timer times out.

3. Call sys_create to create another directory '2'.
[0:D]
  [1:D]
  [2:D]

4. kjournald starts to run.  once we see the commit block is written to
disk, we crash the experimental disk

Re: [MC] [CHECKER] e2fsck writes out blocks out of order, causing root dir to be corrupted (ext3, linux 2.4.19, e2fsprogs 1.34)

[Junfeng Yang]

Although the kernel and e2fsck share the same copy of recovery.c, the same
problem doesn't seem to exist to the kernel, since fsync_no_super will do
the sync for the kernel.  While for e2fsck, fsync_no_super is defined as a
nop.

int journal_recover(journal_t *journal)
{
	int			err;
	journal_superblock_t *	sb;

	struct recovery_info	info;

	memset(&info, 0, sizeof(info));
	sb = journal->j_superblock;

	/*
	 * The journal superblock's s_start field (the current log head)
	 * is always zero if, and only if, the journal was cleanly
	 * unmounted.
	 */

	if (!sb->s_start) {
		jbd_debug(1, "No recovery required, last transaction
%d\n",
			  ntohl(sb->s_sequence));
		journal->j_transaction_sequence = ntohl(sb->s_sequence) +
1;
		return 0;
	}


	err = do_one_pass(journal, &info, PASS_SCAN);
	if (!err)
		err = do_one_pass(journal, &info, PASS_REVOKE);
	if (!err)
		err = do_one_pass(journal, &info, PASS_REPLAY);

	jbd_debug(0, "JBD: recovery, exit status %d, "
		  "recovered transactions %u to %u\n",
		  err, info.start_transaction, info.end_transaction);
	jbd_debug(0, "JBD: Replayed %d and revoked %d/%d blocks\n",
		  info.nr_replays, info.nr_revoke_hits, info.nr_revokes);

	/* Restart the log at the next transaction ID, thus invalidating
	 * any existing commit records in the log. */
	journal->j_transaction_sequence = ++info.end_transaction;

	journal_clear_revoke(journal);
	fsync_no_super(journal->j_fs_dev);
	return err;
}

Re: [CHECKER] e2fsck writes out blocks out of order, causing root dir to be corrupted (ext3, linux 2.4.19, e2fsprogs 1.34)

[Richard B. Johnson]

On Tue, 11 May 2004, Junfeng Yang wrote:

> Hi,
>
> We got a warning that the filesystem was in a inconsistent state when:
> 1. created a crashed disk image
> 2. ran fsck over the image and then crash fsck at certain point
> 3. re-ran fsck.

Question?  Is fsck specified to be able to be crashed? I'm not
sure you could ever make a repair-tool that could do that unless
there was some "guaranteed to save device" on an independent power
source during the repair. Fsck can't commit partial fixes of some
stuff because it would leave the file-system in an unrecoverable
state. It needs to complete.

Judging by the number of Stanford people being copied, I would
guess that this is a troll-probe?

Cheers,
Dick Johnson
Penguin : Linux version 2.4.26 on an i686 machine (5557.45 BogoMips).
            Note 96.31% of all statistics are fiction.

Re: [CHECKER] e2fsck writes out blocks out of order, causing root dir to be corrupted (ext3, linux 2.4.19, e2fsprogs 1.34)

[Valdis.Kletnieks]

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

On Tue, 11 May 2004 22:45:33 EDT, "Richard B. Johnson" said:

> Question?  Is fsck specified to be able to be crashed? I'm not
> sure you could ever make a repair-tool that could do that unless
> there was some "guaranteed to save device" on an independent power
> source during the repair. Fsck can't commit partial fixes of some
> stuff because it would leave the file-system in an unrecoverable
> state. It needs to complete.

On the flip side, if you poke through the code in fs/ext2/, you'll find that
a very large percentage of the code is not actually doing directly productive
work, but merely making sure that things always go to disk in the right
order, and double checking that things haven't been changed out from under
us, and the like.

I suspect this bug is merely a special case of "your filesystem can get scrogged
if something's doing caching behind your back" - the same sort of issues
that prompted recent "flush the IDE cache on shutdown" fixes, and the
well-known issues with using journalling file systems on a file-backed loopback
device.

Having said that, I admit being surprised that their demonstration test case
is *that* simple - that's a truly small number of I/Os to get it into a repeatably
corruptible state.  I'm sure many of us have a mental image of these class of
failures as being heisenbugs, dependent on the cache contents.

> Judging by the number of Stanford people being copied, I would
> guess that this is a troll-probe?

Hardly - the class of errors is one that does (or should) concern the kernel
community - and I don't consider identifying a "your filesystem *will* be toast
if you get into this repeatable scenario" a troll.  At the very least, we can
consider what additional hardening we can do to either the kernel or userspace
to make sure that we don't re-order the blocks - note the key phrase here:

"Neither of these pay attention to the journaling constraints of EXT3 and JBD."

There seems to have been a thread about write barriers for IDE drives back in
Feb 2003, to address exactly this issue.  Has the current 2.4/2.6 tree had any
significant real improvement regarding this since the admittedly old 2.4.19
kernel that the Stanford crew was testing?  I can't remember if that thread
resulted in any committed code actually used by the filesystems....



[-- Attachment #2: Type: application/pgp-signature, Size: 226 bytes --]

Re: [CHECKER] e2fsck writes out blocks out of order, causing root dir to be corrupted (ext3, linux 2.4.19, e2fsprogs 1.34)

[Theodore Ts'o]

On Tue, May 11, 2004 at 10:45:33PM -0400, Richard B. Johnson wrote:
> On Tue, 11 May 2004, Junfeng Yang wrote:
> 
> > We got a warning that the filesystem was in a inconsistent state when:
> > 1. created a crashed disk image
> > 2. ran fsck over the image and then crash fsck at certain point
> > 3. re-ran fsck.
> 
> Question?  Is fsck specified to be able to be crashed? I'm not
> sure you could ever make a repair-tool that could do that unless
> there was some "guaranteed to save device" on an independent power
> source during the repair. Fsck can't commit partial fixes of some
> stuff because it would leave the file-system in an unrecoverable
> state. It needs to complete.

There will always be some repairs that e2fsck will need to do that
can't be crash safe, but that doesn't mean that we shouldn't strive to
make it as crash-proof as possible.  Especially when the fix is
relatively simple.....

						- Ted

Re: [CHECKER] e2fsck writes out blocks out of order, causing root dir to be corrupted (ext3, linux 2.4.19, e2fsprogs 1.34)

[Theodore Ts'o]

On Tue, May 11, 2004 at 05:55:30PM -0700, Junfeng Yang wrote:
> 
> We got a warning that the filesystem was in a inconsistent state when:
> 1. created a crashed disk image
> 2. ran fsck over the image and then crash fsck at certain point
> 3. re-ran fsck.
> 
> We got the crashed disk image by making 2 directories under / then runing
> kjournald to commit.  once we saw the commit block was written to disk, we
> crashed the experimental disk (a virtual ram disk), prior to actual disk
> writes.

I'm not sure how this is really a [CHECKER] issue per se, since it
isn't a kernel issue and you didn't really find this via using the a
hacked-up gcc compiler, did you?  

In any case, though, thanks for pointing this out.

> We then ran fsck over the crashed disk image.  We interrupted fsck after
>  the journal super block was reset on disk (fsck will reset the journal
> superblock once it is done replaying).  

I assume you did this by setting a breakpoint somewhere inside e2fsck?
Where, specifically?  I want to make sure I can replicate this test
case exactly as you did, at least under gdb control.  Later I'll think
about some way of automating this for the e2fsck regression test
suite....

> We checked ext3 on linux 2.4.19, with e2fsprogs-1.34.  The crashed disk
> image can be obtained from http://keeda.stanford.edu/~junfeng/exp_disk.tgz

Assuming I can automate this for a regression test suite, may I have
permission to include a compressed version of this crashed disk image
in e2fsprogs?

> Below is the commented messages collected from runing e2fsck without
> interruption.  We print out a debug message when unix_write_blk,
> flush_cached_blocks, reuse_cache, raw_blk_write are called.  reuse_cache
> does the cache eviction.  Comments are in brackets.

BTW, it looks like you didn't realize that there was a simpler way of
instrumenting e2fsck's I/O.  You could have simple built e2fsck with
configure --enable-testio-debug, and then set the environment variable
TEST_IO_FLAGS=0x0F to log all reads, writes, set_blksize, and flush
operations.  See lib/ext2fs/test_io.c for more information.  There are
also environment variables that can be used to direct the log
information to a file, as well as ask the test_io layer to dump out
the contents of a specific block whenver it is read or written.
E2fsprogs has a very civilized debugging environment.  :-)


In any case, I believe the following patch (versus the latest
e2fsprogs tree in Bitkeeper; it looks like probably won't apply
cleanly to e2fpsrogs 1.34, but it shouldn't be that hard to fix up for
1.34) should address this issue, but I'd like to repeat your test case
exactly as you performed it before pronouncing it fixed.  The fix
doesn't cause any problems for the existing regression test suite, so
at the very least I'm confident the fix is safe.

						- Ted


===== e2fsck/jfs_user.h 1.8 vs edited =====
--- 1.8/e2fsck/jfs_user.h	Sun Dec  7 01:00:01 2003
+++ edited/e2fsck/jfs_user.h	Tue May 11 23:15:30 2004
@@ -41,8 +41,6 @@
 
 typedef struct kdev_s *kdev_t;
 
-#define fsync_no_super(dev) do {} while(0)
-#define sync_blockdev(dev) do {} while(0)
 #define lock_buffer(bh) do {} while(0)
 #define unlock_buffer(bh) do {} while(0)
 #define buffer_req(bh) 1
@@ -107,6 +105,7 @@
  */
 int journal_bmap(journal_t *journal, blk_t block, unsigned long *phys);
 struct buffer_head *getblk(kdev_t ctx, blk_t blocknr, int blocksize);
+void sync_blockdev(kdev_t kdev);
 void ll_rw_block(int rw, int dummy, struct buffer_head *bh[]);
 void mark_buffer_dirty(struct buffer_head *bh);
 void mark_buffer_uptodate(struct buffer_head *bh, int val);
===== e2fsck/journal.c 1.53 vs edited =====
--- 1.53/e2fsck/journal.c	Sun Dec 28 09:21:08 2003
+++ edited/e2fsck/journal.c	Tue May 11 23:15:07 2004
@@ -87,6 +87,18 @@
 	return bh;
 }
 
+void sync_blockdev(kdev_t kdev)
+{
+	io_channel	io;
+
+	if (kdev->k_dev == K_DEV_FS)
+		io = kdev->k_ctx->fs->io;
+	else 
+		io = kdev->k_ctx->journal_io;
+
+	io_channel_flush(io);
+}
+
 void ll_rw_block(int rw, int nr, struct buffer_head *bhp[])
 {
 	int retval;

Re: [Ext2-devel] Re: [CHECKER] e2fsck writes out blocks out of order, causing root dir to be corrupted (ext3, linux 2.4.19, e2fsprogs 1.34)

[Theodore Ts'o]

On Tue, May 11, 2004 at 11:09:45PM -0400, Valdis.Kletnieks@vt.edu wrote:
> 
> I suspect this bug is merely a special case of "your filesystem can
> get scrogged if something's doing caching behind your back" - the
> same sort of issues that prompted recent "flush the IDE cache on
> shutdown" fixes, and the well-known issues with using journalling
> file systems on a file-backed loopback device.

No, not really.  This is the case of "we moved code that was original
kernel-space to user space", and we failed to simulate certain
functions, such as sync_blockdev().

> Having said that, I admit being surprised that their demonstration
> test case is *that* simple - that's a truly small number of I/Os to
> get it into a repeatably corruptible state.  I'm sure many of us
> have a mental image of these class of failures as being heisenbugs,
> dependent on the cache contents.

Well, the demonstration test case *wasn't* that simple.  It required
the system crashing twice at very specific points.  Once to create the
filesystem requiring a journal replay, and then a second crash at
exactly the right time in the middle of e2fsck's journal replaying
code.  This failure would be fairly hard to replicate in real-life
conditions, since it would require to crashes in quick succession, at
very carefully chosen points, although if you had really flaky AC
mains, I suppose it might be considered a more likely failure case.

> Hardly - the class of errors is one that does (or should) concern
> the kernel community - and I don't consider identifying a "your
> filesystem *will* be toast if you get into this repeatable scenario"
> a troll.  At the very least, we can consider what additional
> hardening we can do to either the kernel or userspace to make sure
> that we don't re-order the blocks - note the key phrase here:
> 
> "Neither of these pay attention to the journaling constraints of
> EXT3 and JBD."

Well, actually it was the e2fsprogs user space code that wasn't paying
attention t the journalling constraints, mainly because we had been we
weren't faithfully implementing sync_blockdev()/fsync_no_super().  The
patch to fix this in e2fsprogs was fairly simple.

						- Ted

Re: [CHECKER] e2fsck writes out blocks out of order, causing root dir to be corrupted (ext3, linux 2.4.19, e2fsprogs 1.34)

[Junfeng Yang]

> I'm not sure how this is really a [CHECKER] issue per se, since it
> isn't a kernel issue and you didn't really find this via using the a
> hacked-up gcc compiler, did you?

Yeah this is a bug in e2fsprogs not in kernel.  The kernel journal_recover
flushes out the blocks using sync_dev_no_super, so it's fine.

We caught this warning by a new FS checking tool.  It is based on a C
Model Checker developed by Madan and a few Stanford people (Descritions of
CMC can be found at
http://chicory.stanford.edu/thesis/madan-thesis-abs.html).  You can think
of the tool as a whole machine simulator.  Althought the disk is virtual
in memory, both the kernel and e2fsck will believe they are talking to a
real block device.  The strength of the tool is that it can systematically
enumerate all the possible failures and check for errors.  We aim at
catching deep consistency errors in both the kernel fs code and the fs
utilities code.

> I assume you did this by setting a breakpoint somewhere inside e2fsck?
> Where, specifically?  I want to make sure I can replicate this test
> case exactly as you did, at least under gdb control.  Later I'll think

We got the warning using our tool, which can stop fsck after each block
write and run it again.  To repeat it with gdb, try to stop fsck when the
journal is closed (after replaying is done) and the journal super block is
flushed out by flush_cached_blocks.  If you use the image I provide, the
journal super block should be block 268.

> Assuming I can automate this for a regression test suite, may I have
> permission to include a compressed version of this crashed disk image
> in e2fsprogs?

sure, my pleasure :)

> BTW, it looks like you didn't realize that there was a simpler way of
> instrumenting e2fsck's I/O.  You could have simple built e2fsck with
> configure --enable-testio-debug, and then set the environment variable
> TEST_IO_FLAGS=0x0F to log all reads, writes, set_blksize, and flush
> operations.  See lib/ext2fs/test_io.c for more information.  There are
> also environment variables that can be used to direct the log
> information to a file, as well as ask the test_io layer to dump out
> the contents of a specific block whenver it is read or written.
> E2fsprogs has a very civilized debugging environment.  :-)

Thanks for the information :)  I used debuge2fs utility last night when
diagnosing this warning.  It is really nice.  Without it I wouldn't be
able to pin down the warning.  Thanks!

>
>
> In any case, I believe the following patch (versus the latest
> e2fsprogs tree in Bitkeeper; it looks like probably won't apply
> cleanly to e2fpsrogs 1.34, but it shouldn't be that hard to fix up for
> 1.34) should address this issue, but I'd like to repeat your test case
> exactly as you performed it before pronouncing it fixed.  The fix
> doesn't cause any problems for the existing regression test suite, so
> at the very least I'm confident the fix is safe.

I'll apply the patch and re-run our tool. I'll let know you if this will
fix it or not.

Thanks for the quick reply and the patch!

-Junfeng

Re: [MC] Re: [CHECKER] e2fsck writes out blocks out of order,

[Dawson Engler]

> 
> On Tue, 11 May 2004, Junfeng Yang wrote:
> 
> > Hi,
> >
> > We got a warning that the filesystem was in a inconsistent state when:
> > 1. created a crashed disk image
> > 2. ran fsck over the image and then crash fsck at certain point
> > 3. re-ran fsck.
> 
> Question?  Is fsck specified to be able to be crashed? I'm not
> sure you could ever make a repair-tool that could do that unless
> there was some "guaranteed to save device" on an independent power
> source during the repair. Fsck can't commit partial fixes of some
> stuff because it would leave the file-system in an unrecoverable
> state. It needs to complete.

To the extent that it is simply replaying records in a journal, it should
be able to crash at arbitrary points before commit and then restart
without fuss.  That's one of the motivations for using logging in a file
system ;-)