use-after-free on log replay failure
Alex Lyakas
alex at zadarastorage.com
Tue Aug 12 07:39:02 CDT 2014
Hello Dave, Brian,
I will describe a generic reproduction that you ask for.
It was performed on pristine XFS code from 3.8.13, taken from here:
git://git.kernel.org/pub/scm/linux/kernel/git/stable/linux-stable.git
top commit being:
commit dbf932a9b316d5b29b3e220e5a30e7a165ad2992
Author: Greg Kroah-Hartman <gregkh at linuxfoundation.org>
Date: Sat May 11 13:57:46 2013 -0700
Linux 3.8.13
I made a single (I swear!) code change in XFS:
diff --git a/fs/xfs/xfs_log_recover.c b/fs/xfs/xfs_log_recover.c
index 96fcbb8..d756bf6 100644
--- a/fs/xfs/xfs_log_recover.c
+++ b/fs/xfs/xfs_log_recover.c
@@ -3736,6 +3736,9 @@ xlog_recover(
if ((error = xlog_find_tail(log, &head_blk, &tail_blk)))
return error;
+ xfs_notice(log->l_mp, "Sleep 10s before xlog_do_recover");
+ msleep(10000);
+
if (tail_blk != head_blk) {
/* There used to be a comment here:
*
Fresh XFS was formatted on a 20 GB block device within a VM, using:
mkfs.xfs -f -K /dev/vde -p /etc/zadara/xfs.protofile
and:
root at vc-00-00-1383-dev:~# cat /etc/zadara/xfs.protofile
dummy : bootfilename, not used, backward compatibility
0 0 : numbers of blocks and inodes, not used,
backward compatibility
d--777 0 0 : set 777 perms for the root dir
$
$
I mounted XFS with the following options:
rw,sync,noatime,wsync,attr2,inode64,noquota 0 0
I started a couple of processes writing files sequentially onto this mount
point, and after few seconds crashed the VM.
When the VM came up, I took the metadump file and placed it in:
https://drive.google.com/file/d/0ByBy89zr3kJNa0ZpdmZFS242RVU/edit?usp=sharing
Then I set up the following Device Mapper target onto /dev/vde:
dmsetup create VDE --table "0 41943040 linear-custom /dev/vde 0"
I am attaching the code (and Makefile) of dm-linear-custom target. It is
exact copy of dm-linear, except that it has a module parameter. With the
parameter set to 0, this is an identity mapping onto /dev/vde. If the
parameter is set to non-0, all WRITE bios are failed with ENOSPC. There is a
workqueue to fail them in a different context (not sure if really needed,
but that's what our "real" custom
block device does).
Now I did:
mount -o noatime,sync /dev/mapper/VDE /mnt/xfs
The log recovery flow went into the sleep that I added, and then I did:
echo 1 > /sys/module/dm_linear_custom/parameters/fail_writes
Problem reproduced:
Aug 12 14:23:04 vc-00-00-1383-dev kernel: [ 175.000657] XFS (dm-0):
Mounting Filesystem
Aug 12 14:23:04 vc-00-00-1383-dev kernel: [ 175.026991] XFS (dm-0): Sleep
10s before xlog_do_recover
Aug 12 14:23:14 vc-00-00-1383-dev kernel: [ 185.028113] XFS (dm-0):
Starting recovery (logdev: internal)
Aug 12 14:23:18 vc-00-00-1383-dev kernel: [ 188.556622] XFS (dm-0):
metadata I/O error: block 0x2 ("xlog_recover_iodone") error 28 numblks 1
Aug 12 14:23:18 vc-00-00-1383-dev kernel: [ 188.556675] XFS (dm-0):
metadata I/O error: block 0x40 ("xlog_recover_iodone") error 28 numblks 16
Aug 12 14:23:18 vc-00-00-1383-dev kernel: [ 188.556680] XFS (dm-0):
xfs_do_force_shutdown(0x1) called from line 377 of file
/mnt/work/alex/linux-stable/source/fs/xfs/xfs_log_recover.c. Return address
= 0xffffffffa0349f68
Aug 12 14:23:18 vc-00-00-1383-dev kernel: [ 188.556683] XFS (dm-0): I/O
Error Detected. Shutting down filesystem
Aug 12 14:23:18 vc-00-00-1383-dev kernel: [ 188.556684] XFS (dm-0): Please
umount the filesystem and rectify the problem(s)
Aug 12 14:23:18 vc-00-00-1383-dev kernel: [ 188.556766] XFS (dm-0):
metadata I/O error: block 0xa00002 ("xlog_recover_iodone") error 5 numblks 1
Aug 12 14:23:18 vc-00-00-1383-dev kernel: [ 188.556769] XFS (dm-0):
xfs_do_force_shutdown(0x1) called from line 377 of file
/mnt/work/alex/linux-stable/source/fs/xfs/xfs_log_recover.c. Return address
= 0xffffffffa0349f68
Aug 12 14:23:18 vc-00-00-1383-dev kernel: [ 188.556771] XFS (dm-0):
metadata I/O error: block 0xa00008 ("xlog_recover_iodone") error 5 numblks 8
Aug 12 14:23:18 vc-00-00-1383-dev kernel: [ 188.556774] XFS (dm-0):
xfs_do_force_shutdown(0x1) called from line 377 of file
/mnt/work/alex/linux-stable/source/fs/xfs/xfs_log_recover.c. Return address
= 0xffffffffa0349f68
Aug 12 14:23:18 vc-00-00-1383-dev kernel: [ 188.556776] XFS (dm-0):
metadata I/O error: block 0xa00010 ("xlog_recover_iodone") error 5 numblks 8
Aug 12 14:23:18 vc-00-00-1383-dev kernel: [ 188.556779] XFS (dm-0):
xfs_do_force_shutdown(0x1) called from line 377 of file
/mnt/work/alex/linux-stable/source/fs/xfs/xfs_log_recover.c. Return address
= 0xffffffffa0349f68
Aug 12 14:23:18 vc-00-00-1383-dev kernel: [ 188.556781] XFS (dm-0):
metadata I/O error: block 0xa00018 ("xlog_recover_iodone") error 5 numblks 8
Aug 12 14:23:18 vc-00-00-1383-dev kernel: [ 188.556783] XFS (dm-0):
xfs_do_force_shutdown(0x1) called from line 377 of file
/mnt/work/alex/linux-stable/source/fs/xfs/xfs_log_recover.c. Return address
= 0xffffffffa0349f68
Aug 12 14:23:18 vc-00-00-1383-dev kernel: [ 188.556785] XFS (dm-0):
metadata I/O error: block 0xa00040 ("xlog_recover_iodone") error 5 numblks
16
Aug 12 14:23:18 vc-00-00-1383-dev kernel: [ 188.556788] XFS (dm-0):
xfs_do_force_shutdown(0x1) called from line 377 of file
/mnt/work/alex/linux-stable/source/fs/xfs/xfs_log_recover.c. Return address
= 0xffffffffa0349f68
Aug 12 14:23:18 vc-00-00-1383-dev kernel: [ 188.556790] XFS (dm-0):
metadata I/O error: block 0xa00050 ("xlog_recover_iodone") error 5 numblks
16
Aug 12 14:23:18 vc-00-00-1383-dev kernel: [ 188.556793] XFS (dm-0):
xfs_do_force_shutdown(0x1) called from line 377 of file
/mnt/work/alex/linux-stable/source/fs/xfs/xfs_log_recover.c. Return address
= 0xffffffffa0349f68
Aug 12 14:23:18 vc-00-00-1383-dev kernel: [ 188.556880] XFS (dm-0):
metadata I/O error: block 0xa00001 ("xlog_recover_iodone") error 28 numblks
1
Aug 12 14:23:18 vc-00-00-1383-dev kernel: [ 188.556884] XFS (dm-0):
xfs_do_force_shutdown(0x1) called from line 377 of file
/mnt/work/alex/linux-stable/source/fs/xfs/xfs_log_recover.c. Return address
= 0xffffffffa0349f68
Aug 12 14:23:18 vc-00-00-1383-dev kernel: [ 188.556977] XFS (dm-0): log
mount/recovery failed: error 28
Aug 12 14:23:18 vc-00-00-1383-dev kernel: [ 188.557215] XFS (dm-0): log
mount failed
Aug 12 14:23:18 vc-00-00-1383-dev kernel: [ 188.573194] XFS ():
xfs_do_force_shutdown(0x1) called from line 377 of file
/mnt/work/alex/linux-stable/source/fs/xfs/xfs_log_recover.c. Return address
= 0xffffffffa0349f68
Aug 12 14:23:18 vc-00-00-1383-dev kernel: [ 188.573214] XFS (): metadata
I/O error: block 0x18 ("xlog_recover_iodone") error 28 numblks 8
Aug 12 14:23:18 vc-00-00-1383-dev kernel: [ 188.574685] XFS ():
xfs_do_force_shutdown(0x1) called from line 377 of file
/mnt/work/alex/linux-stable/source/fs/xfs/xfs_log_recover.c. Return address
= 0xffffffffa0349f68
As you see, after mount completes, IO callbacks are still arriving and
printing junk (empty string in this case). Immediately after that kernel
dies.
Is this description generic enough?
Thanks,
Alex.
-----Original Message-----
From: Brian Foster
Sent: 12 August, 2014 3:03 PM
To: Dave Chinner
Cc: Alex Lyakas ; xfs at oss.sgi.com
Subject: Re: use-after-free on log replay failure
On Tue, Aug 12, 2014 at 07:52:07AM +1000, Dave Chinner wrote:
> On Mon, Aug 11, 2014 at 09:20:57AM -0400, Brian Foster wrote:
> > On Sun, Aug 10, 2014 at 03:20:50PM +0300, Alex Lyakas wrote:
> > > On Wed, Aug 6, 2014 at 6:20 PM, Brian Foster <bfoster at redhat.com>
> > > wrote:
> > > > On Wed, Aug 06, 2014 at 03:52:03PM +0300, Alex Lyakas wrote:
> .....
> > > >> But I believe, my analysis shows that during the mount sequence XFS
> > > >> does not
> > > >> wait properly for all the bios to complete, before failing the
> > > >> mount
> > > >> sequence back to the caller.
> > > >>
> > > >
> > > > As an experiment, what about the following? Compile tested only and
> > > > not
> > > > safe for general use.
> ...
> > > > diff --git a/fs/xfs/xfs_buf.c b/fs/xfs/xfs_buf.c
> > > > index cd7b8ca..fbcf524 100644
> > > > --- a/fs/xfs/xfs_buf.c
> > > > +++ b/fs/xfs/xfs_buf.c
> > > > @@ -1409,19 +1409,27 @@ xfs_buf_iorequest(
> > > > * case nothing will ever complete. It returns the I/O error code,
> > > > if any, or
> > > > * 0 if there was no error.
> > > > */
> > > > -int
> > > > -xfs_buf_iowait(
> > > > - xfs_buf_t *bp)
> > > > +static int
> > > > +__xfs_buf_iowait(
> > > > + struct xfs_buf *bp,
> > > > + bool skip_error)
> > > > {
> > > > trace_xfs_buf_iowait(bp, _RET_IP_);
> > > >
> > > > - if (!bp->b_error)
> > > > + if (skip_error || !bp->b_error)
> > > > wait_for_completion(&bp->b_iowait);
> > > >
> > > > trace_xfs_buf_iowait_done(bp, _RET_IP_);
> > > > return bp->b_error;
> > > > }
> > > >
> > > > +int
> > > > +xfs_buf_iowait(
> > > > + struct xfs_buf *bp)
> > > > +{
> > > > + return __xfs_buf_iowait(bp, false);
> > > > +}
> > > > +
> > > > xfs_caddr_t
> > > > xfs_buf_offset(
> > > > xfs_buf_t *bp,
> > > > @@ -1866,7 +1874,7 @@ xfs_buf_delwri_submit(
> > > > bp = list_first_entry(&io_list, struct xfs_buf,
> > > > b_list);
> > > >
> > > > list_del_init(&bp->b_list);
> > > > - error2 = xfs_buf_iowait(bp);
> > > > + error2 = __xfs_buf_iowait(bp, true);
> > > > xfs_buf_relse(bp);
> > > > if (!error)
> > > > error = error2;
>
> Not waiting here on buffer error should not matter. Any buffer that
> is under IO and requires completion should be referenced, and that
> means it should be caught and waited on by xfs_wait_buftarg() in the
> mount failure path after log recovery fails.
>
I think that assumes the I/O is successful. Looking through
xlog_recover_buffer_pass2() as an example, we read the buffer which
should return with b_hold == 1. The delwri queue increments the hold and
we xfs_buf_relse() in the return path (i.e., buffer is now held by the
delwri queue awaiting submission).
Sometime later we delwri_submit()... xfs_buf_iorequest() does an
xfs_buf_hold() and xfs_buf_rele() within that single function. The
delwri_submit() releases its hold after xfs_buf_iowait(), which I guess
at that point bp should go onto the lru (b_hold back to 1 in
xfs_buf_rele(). Indeed, the caller has lost scope of the buffer at this
point.
So unless I miss something or got the lifecycle wrong here, which is
easily possible ;), this all hinges on xfs_buf_iowait(). That's where
the last hold forcing the buffer to stay around goes away.
xfs_buftarg_wait_rele() will dispose the buffer if b_hold == 1. If
xfs_buf_iowait() is racy in the event of I/O errors via the bio
callback, I think this path is susceptible just the same.
> > > > ---
> > > I think that this patch fixes the problem. I tried reproducing it like
> > > 30 times, and it doesn't happen with this patch. Dropping this patch
> > > reproduces the problem within 1 or 2 tries. Thanks!
> > > What are next steps? How to make it "safe for general use"?
> > >
> >
> > Ok, thanks for testing. I think that implicates the caller bypassing the
> > expected blocking with the right sequence of log recovery I/Os and
> > device failure. TBH, I'd still like to see the specifics, if possible.
> > Could you come up with a generic reproducer for this? I think a metadump
> > of the fs with the dirty log plus whatever device failure simulation
> > hack you're using would suffice.
>
> The real issue is we don't know exactly what code is being tested
> (it's 3.8 + random bug fix backports + custom code). Even if we have
> a reproducer there's no guarantee it will reproduce on a current
> kernel. IOWs, we are stumbling around in the dark bashing our heads
> against everything in the room, and that just wastes everyone's
> time.
>
> We need a reproducer that triggers on a current, unmodified
> kernel release. You can use dm-faulty to error out all writes just
> like you are doing with your custom code. See
> xfstests::tests/generic/321 and common/dmflakey for to do this.
> Ideally the reproducer is in a form that xfstests can use....
>
> If you can't reproduce it on an upstream kernel, then git bisect is
> your friend. It will find the commit that fixed the problem you are
> seeing....
>
Ugh, yeah. The fact that this was customized as such apparently went
over my head. I agree completely. This needs to be genericized to a
pristine, preferably current kernel. The experiment patch could be
papering over something completely different.
> > The ideal fix is not yet clear to me.
>
> We are not even that far along - the root cause of the bug is not at
> all clear to me. :/
>
Yeah.. the above was just the theory that motivated the experiment in
the previously posted patch. It of course remains a theory until we can
see the race in action. I was referring to the potential fix for the
raciness of xfs_buf_iowait() with regard to bio errors and the wq iodone
handling, while still asking for a reproducer to confirm the actual
problem. FWIW, I'm not too high on changes in the buf management code,
even a smallish behavior change, without a real trace of some sort that
documents the problem and justifies the change.
Brian
> Cheers,
>
> Dave.
> --
> Dave Chinner
> david at fromorbit.com
-------------- next part --------------
A non-text attachment was scrubbed...
Name: dm-linear-custom.c
Type: application/octet-stream
Size: 5540 bytes
Desc: not available
URL: <http://oss.sgi.com/pipermail/xfs/attachments/20140812/8b73dff5/attachment.obj>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: Makefile
Type: application/octet-stream
Size: 389 bytes
Desc: not available
URL: <http://oss.sgi.com/pipermail/xfs/attachments/20140812/8b73dff5/attachment-0001.obj>
More information about the xfs
mailing list