[PATCH 0/2] xfs: a couple minor shutdown fixes

[PATCH 0/2] xfs: a couple minor shutdown fixes

[Brian Foster]

Hi all,

Here are a couple of shutdown fixups that fell out of Darrick's recent
report of a deadlock problem via generic/475. I've still not been able
to reproduce the generic/475 deadlock, but Darrick has tested patch 1
and last I heard reported that the deadlock had not reoccurred. Patch 2
fixes up a buffer leak and reorders the shutdown in the
xfs_iflush_cluster() abort codepath.

After making a higher level pass across the codebase, there are still
places where we technically invoke synchronous log forces (or filesystem
shutdowns, which can induce a sync log force) with various object locks
held. This isn't always a problem as some are contexts where a buffer
should never be pinned, etc. That said, if we want to institute a
general policy of never inducing sync log forces or shutdowns from
contexts with held locks then I'd suggest that's something we should
evolve opportunistically over time.

Thoughts, reviews, flames appreciated.

Brian

Brian Foster (2):
  xfs: wake commit waiters on CIL abort before log item abort
  xfs: shutdown after buf release in iflush cluster abort path

 fs/xfs/xfs_inode.c   |  4 +++-
 fs/xfs/xfs_log_cil.c | 21 +++++++++++++--------
 2 files changed, 16 insertions(+), 9 deletions(-)

-- 
2.17.2

[PATCH 1/2] xfs: wake commit waiters on CIL abort before log item abort

[Brian Foster]

XFS shutdown deadlocks have been reproduced by fstest generic/475.
The deadlock signature involves log I/O completion running error
handling to abort logged items and waiting for an inode cluster
buffer lock in the buffer item unpin handler. The buffer lock is
held by xfsaild attempting to flush an inode. The buffer happens to
be pinned and so xfs_iflush() triggers an async log force to begin
work required to get it unpinned. The log force is blocked waiting
on the commit completion, which never occurs and thus leaves the
filesystem deadlocked.

The root problem is that aborted log I/O completion pots commit
completion behind callback completion, which is unexpected for async
log forces. Under normal running conditions, an async log force
returns to the caller once the CIL ctx has been formatted/submitted
and the commit completion event triggered at the tail end of
xlog_cil_push(). If the filesystem has shutdown, however, we rely on
xlog_cil_committed() to trigger the completion event and it happens
to do so after running log item unpin callbacks. This makes it
unsafe to invoke an async log force from contexts that hold locks
that might also be required in log completion processing.

To address this problem, wake commit completion waiters before
aborting log items in the log I/O completion handler. This ensures
that an async log force will not deadlock on held locks if the
filesystem happens to shutdown. Note that it is still unsafe to
issue a sync log force while holding such locks because a sync log
force explicitly waits on the force completion, which occurs after
log I/O completion processing.

Signed-off-by: Brian Foster <bfoster@redhat.com>
---
 fs/xfs/xfs_log_cil.c | 21 +++++++++++++--------
 1 file changed, 13 insertions(+), 8 deletions(-)

diff --git a/fs/xfs/xfs_log_cil.c b/fs/xfs/xfs_log_cil.c
index d3884e08b43c..5e595948bc5a 100644
--- a/fs/xfs/xfs_log_cil.c
+++ b/fs/xfs/xfs_log_cil.c
@@ -582,6 +582,19 @@ xlog_cil_committed(
 	struct xfs_cil_ctx	*ctx = args;
 	struct xfs_mount	*mp = ctx->cil->xc_log->l_mp;
 
+	/*
+	 * If the I/O failed, we're aborting the commit and already shutdown.
+	 * Wake any commit waiters before aborting the log items so we don't
+	 * block async log pushers on callbacks. Async log pushers explicitly do
+	 * not wait on log force completion because they may be holding locks
+	 * required to unpin items.
+	 */
+	if (abort) {
+		spin_lock(&ctx->cil->xc_push_lock);
+		wake_up_all(&ctx->cil->xc_commit_wait);
+		spin_unlock(&ctx->cil->xc_push_lock);
+	}
+
 	xfs_trans_committed_bulk(ctx->cil->xc_log->l_ailp, ctx->lv_chain,
 					ctx->start_lsn, abort);
 
@@ -589,15 +602,7 @@ xlog_cil_committed(
 	xfs_extent_busy_clear(mp, &ctx->busy_extents,
 			     (mp->m_flags & XFS_MOUNT_DISCARD) && !abort);
 
-	/*
-	 * If we are aborting the commit, wake up anyone waiting on the
-	 * committing list.  If we don't, then a shutdown we can leave processes
-	 * waiting in xlog_cil_force_lsn() waiting on a sequence commit that
-	 * will never happen because we aborted it.
-	 */
 	spin_lock(&ctx->cil->xc_push_lock);
-	if (abort)
-		wake_up_all(&ctx->cil->xc_commit_wait);
 	list_del(&ctx->committing);
 	spin_unlock(&ctx->cil->xc_push_lock);
 
-- 
2.17.2

Re: [PATCH 1/2] xfs: wake commit waiters on CIL abort before log item abort

[Allison Henderson]

Alrighty, thanks for the detailed commit message, it helps.  Sometimes I 
wonder if adding links to the corresponding discussion threads would 
help tie the patches to the discussions that went into them?  In any 
case, you can add my review.

Reviewed-by: Allison Henderson <allison.henderson@oracle.com>

On 3/29/19 6:40 AM, Brian Foster wrote:
> XFS shutdown deadlocks have been reproduced by fstest generic/475.
> The deadlock signature involves log I/O completion running error
> handling to abort logged items and waiting for an inode cluster
> buffer lock in the buffer item unpin handler. The buffer lock is
> held by xfsaild attempting to flush an inode. The buffer happens to
> be pinned and so xfs_iflush() triggers an async log force to begin
> work required to get it unpinned. The log force is blocked waiting
> on the commit completion, which never occurs and thus leaves the
> filesystem deadlocked.
> 
> The root problem is that aborted log I/O completion pots commit
> completion behind callback completion, which is unexpected for async
> log forces. Under normal running conditions, an async log force
> returns to the caller once the CIL ctx has been formatted/submitted
> and the commit completion event triggered at the tail end of
> xlog_cil_push(). If the filesystem has shutdown, however, we rely on
> xlog_cil_committed() to trigger the completion event and it happens
> to do so after running log item unpin callbacks. This makes it
> unsafe to invoke an async log force from contexts that hold locks
> that might also be required in log completion processing.
> 
> To address this problem, wake commit completion waiters before
> aborting log items in the log I/O completion handler. This ensures
> that an async log force will not deadlock on held locks if the
> filesystem happens to shutdown. Note that it is still unsafe to
> issue a sync log force while holding such locks because a sync log
> force explicitly waits on the force completion, which occurs after
> log I/O completion processing.
> 
> Signed-off-by: Brian Foster <bfoster@redhat.com>
> ---
>   fs/xfs/xfs_log_cil.c | 21 +++++++++++++--------
>   1 file changed, 13 insertions(+), 8 deletions(-)
> 
> diff --git a/fs/xfs/xfs_log_cil.c b/fs/xfs/xfs_log_cil.c
> index d3884e08b43c..5e595948bc5a 100644
> --- a/fs/xfs/xfs_log_cil.c
> +++ b/fs/xfs/xfs_log_cil.c
> @@ -582,6 +582,19 @@ xlog_cil_committed(
>   	struct xfs_cil_ctx	*ctx = args;
>   	struct xfs_mount	*mp = ctx->cil->xc_log->l_mp;
>   
> +	/*
> +	 * If the I/O failed, we're aborting the commit and already shutdown.
> +	 * Wake any commit waiters before aborting the log items so we don't
> +	 * block async log pushers on callbacks. Async log pushers explicitly do
> +	 * not wait on log force completion because they may be holding locks
> +	 * required to unpin items.
> +	 */
> +	if (abort) {
> +		spin_lock(&ctx->cil->xc_push_lock);
> +		wake_up_all(&ctx->cil->xc_commit_wait);
> +		spin_unlock(&ctx->cil->xc_push_lock);
> +	}
> +
>   	xfs_trans_committed_bulk(ctx->cil->xc_log->l_ailp, ctx->lv_chain,
>   					ctx->start_lsn, abort);
>   
> @@ -589,15 +602,7 @@ xlog_cil_committed(
>   	xfs_extent_busy_clear(mp, &ctx->busy_extents,
>   			     (mp->m_flags & XFS_MOUNT_DISCARD) && !abort);
>   
> -	/*
> -	 * If we are aborting the commit, wake up anyone waiting on the
> -	 * committing list.  If we don't, then a shutdown we can leave processes
> -	 * waiting in xlog_cil_force_lsn() waiting on a sequence commit that
> -	 * will never happen because we aborted it.
> -	 */
>   	spin_lock(&ctx->cil->xc_push_lock);
> -	if (abort)
> -		wake_up_all(&ctx->cil->xc_commit_wait);
>   	list_del(&ctx->committing);
>   	spin_unlock(&ctx->cil->xc_push_lock);
>   
> 

Re: [PATCH 1/2] xfs: wake commit waiters on CIL abort before log item abort

[Brian Foster]

On Fri, Mar 29, 2019 at 01:15:44PM -0700, Allison Henderson wrote:
> Alrighty, thanks for the detailed commit message, it helps.  Sometimes I
> wonder if adding links to the corresponding discussion threads would help
> tie the patches to the discussions that went into them?  In any case, you
> can add my review.
> 

Er, yeah. I intended to cite the original thread in the cover letter but
apparently forgot. If you haven't found it already, the thread is here:

https://marc.info/?l=linux-xfs&m=155305825226667&w=2

> Reviewed-by: Allison Henderson <allison.henderson@oracle.com>
> 

Thanks for the reviews.

Brian

> On 3/29/19 6:40 AM, Brian Foster wrote:
> > XFS shutdown deadlocks have been reproduced by fstest generic/475.
> > The deadlock signature involves log I/O completion running error
> > handling to abort logged items and waiting for an inode cluster
> > buffer lock in the buffer item unpin handler. The buffer lock is
> > held by xfsaild attempting to flush an inode. The buffer happens to
> > be pinned and so xfs_iflush() triggers an async log force to begin
> > work required to get it unpinned. The log force is blocked waiting
> > on the commit completion, which never occurs and thus leaves the
> > filesystem deadlocked.
> > 
> > The root problem is that aborted log I/O completion pots commit
> > completion behind callback completion, which is unexpected for async
> > log forces. Under normal running conditions, an async log force
> > returns to the caller once the CIL ctx has been formatted/submitted
> > and the commit completion event triggered at the tail end of
> > xlog_cil_push(). If the filesystem has shutdown, however, we rely on
> > xlog_cil_committed() to trigger the completion event and it happens
> > to do so after running log item unpin callbacks. This makes it
> > unsafe to invoke an async log force from contexts that hold locks
> > that might also be required in log completion processing.
> > 
> > To address this problem, wake commit completion waiters before
> > aborting log items in the log I/O completion handler. This ensures
> > that an async log force will not deadlock on held locks if the
> > filesystem happens to shutdown. Note that it is still unsafe to
> > issue a sync log force while holding such locks because a sync log
> > force explicitly waits on the force completion, which occurs after
> > log I/O completion processing.
> > 
> > Signed-off-by: Brian Foster <bfoster@redhat.com>
> > ---
> >   fs/xfs/xfs_log_cil.c | 21 +++++++++++++--------
> >   1 file changed, 13 insertions(+), 8 deletions(-)
> > 
> > diff --git a/fs/xfs/xfs_log_cil.c b/fs/xfs/xfs_log_cil.c
> > index d3884e08b43c..5e595948bc5a 100644
> > --- a/fs/xfs/xfs_log_cil.c
> > +++ b/fs/xfs/xfs_log_cil.c
> > @@ -582,6 +582,19 @@ xlog_cil_committed(
> >   	struct xfs_cil_ctx	*ctx = args;
> >   	struct xfs_mount	*mp = ctx->cil->xc_log->l_mp;
> > +	/*
> > +	 * If the I/O failed, we're aborting the commit and already shutdown.
> > +	 * Wake any commit waiters before aborting the log items so we don't
> > +	 * block async log pushers on callbacks. Async log pushers explicitly do
> > +	 * not wait on log force completion because they may be holding locks
> > +	 * required to unpin items.
> > +	 */
> > +	if (abort) {
> > +		spin_lock(&ctx->cil->xc_push_lock);
> > +		wake_up_all(&ctx->cil->xc_commit_wait);
> > +		spin_unlock(&ctx->cil->xc_push_lock);
> > +	}
> > +
> >   	xfs_trans_committed_bulk(ctx->cil->xc_log->l_ailp, ctx->lv_chain,
> >   					ctx->start_lsn, abort);
> > @@ -589,15 +602,7 @@ xlog_cil_committed(
> >   	xfs_extent_busy_clear(mp, &ctx->busy_extents,
> >   			     (mp->m_flags & XFS_MOUNT_DISCARD) && !abort);
> > -	/*
> > -	 * If we are aborting the commit, wake up anyone waiting on the
> > -	 * committing list.  If we don't, then a shutdown we can leave processes
> > -	 * waiting in xlog_cil_force_lsn() waiting on a sequence commit that
> > -	 * will never happen because we aborted it.
> > -	 */
> >   	spin_lock(&ctx->cil->xc_push_lock);
> > -	if (abort)
> > -		wake_up_all(&ctx->cil->xc_commit_wait);
> >   	list_del(&ctx->committing);
> >   	spin_unlock(&ctx->cil->xc_push_lock);
> > 

[PATCH 2/2] xfs: shutdown after buf release in iflush cluster abort path

[Brian Foster]

If xfs_iflush_cluster() fails due to corruption, the error path
issues a shutdown and simulates an I/O completion to release the
buffer. This code has a couple small problems. First, the shutdown
sequence can issue a synchronous log force, which is unsafe to do
with buffer locks held. Second, the simulated I/O completion does not
guarantee the buffer is async and thus is unlocked and released.

For example, if the last operation on the buffer was a read off disk
prior to the corruption event, XBF_ASYNC is not set and the buffer
is left locked and held upon return. This results in a memory leak
as shown by the following message on module unload:

 BUG xfs_buf (...): Objects remaining in xfs_buf on __kmem_cache_shutdown()

Fix both of these problems by setting XBF_ASYNC on the buffer prior
to the simulated I/O error and performing the shutdown immediately
after ioend processing when the buffer has been released.

Signed-off-by: Brian Foster <bfoster@redhat.com>
---
 fs/xfs/xfs_inode.c | 4 +++-
 1 file changed, 3 insertions(+), 1 deletion(-)

diff --git a/fs/xfs/xfs_inode.c b/fs/xfs/xfs_inode.c
index f643a9295179..4591598ca04d 100644
--- a/fs/xfs/xfs_inode.c
+++ b/fs/xfs/xfs_inode.c
@@ -3614,7 +3614,6 @@ xfs_iflush_cluster(
 	 * inode buffer and shut down the filesystem.
 	 */
 	rcu_read_unlock();
-	xfs_force_shutdown(mp, SHUTDOWN_CORRUPT_INCORE);
 
 	/*
 	 * We'll always have an inode attached to the buffer for completion
@@ -3624,11 +3623,14 @@ xfs_iflush_cluster(
 	 * xfs_buf_submit().
 	 */
 	ASSERT(bp->b_iodone);
+	bp->b_flags |= XBF_ASYNC;
 	bp->b_flags &= ~XBF_DONE;
 	xfs_buf_stale(bp);
 	xfs_buf_ioerror(bp, -EIO);
 	xfs_buf_ioend(bp);
 
+	xfs_force_shutdown(mp, SHUTDOWN_CORRUPT_INCORE);
+
 	/* abort the corrupt inode, as it was not attached to the buffer */
 	xfs_iflush_abort(cip, false);
 	kmem_free(cilist);
-- 
2.17.2

Re: [PATCH 2/2] xfs: shutdown after buf release in iflush cluster abort path

[Allison Henderson]

Ok, thanks again for the explanation!  You can add my review:

Reviewed-by: Allison Henderson <allison.henderson@oracle.com>

On 3/29/19 6:40 AM, Brian Foster wrote:
> If xfs_iflush_cluster() fails due to corruption, the error path
> issues a shutdown and simulates an I/O completion to release the
> buffer. This code has a couple small problems. First, the shutdown
> sequence can issue a synchronous log force, which is unsafe to do
> with buffer locks held. Second, the simulated I/O completion does not
> guarantee the buffer is async and thus is unlocked and released.
> 
> For example, if the last operation on the buffer was a read off disk
> prior to the corruption event, XBF_ASYNC is not set and the buffer
> is left locked and held upon return. This results in a memory leak
> as shown by the following message on module unload:
> 
>   BUG xfs_buf (...): Objects remaining in xfs_buf on __kmem_cache_shutdown()
> 
> Fix both of these problems by setting XBF_ASYNC on the buffer prior
> to the simulated I/O error and performing the shutdown immediately
> after ioend processing when the buffer has been released.
> 
> Signed-off-by: Brian Foster <bfoster@redhat.com>
> ---
>   fs/xfs/xfs_inode.c | 4 +++-
>   1 file changed, 3 insertions(+), 1 deletion(-)
> 
> diff --git a/fs/xfs/xfs_inode.c b/fs/xfs/xfs_inode.c
> index f643a9295179..4591598ca04d 100644
> --- a/fs/xfs/xfs_inode.c
> +++ b/fs/xfs/xfs_inode.c
> @@ -3614,7 +3614,6 @@ xfs_iflush_cluster(
>   	 * inode buffer and shut down the filesystem.
>   	 */
>   	rcu_read_unlock();
> -	xfs_force_shutdown(mp, SHUTDOWN_CORRUPT_INCORE);
>   
>   	/*
>   	 * We'll always have an inode attached to the buffer for completion
> @@ -3624,11 +3623,14 @@ xfs_iflush_cluster(
>   	 * xfs_buf_submit().
>   	 */
>   	ASSERT(bp->b_iodone);
> +	bp->b_flags |= XBF_ASYNC;
>   	bp->b_flags &= ~XBF_DONE;
>   	xfs_buf_stale(bp);
>   	xfs_buf_ioerror(bp, -EIO);
>   	xfs_buf_ioend(bp);
>   
> +	xfs_force_shutdown(mp, SHUTDOWN_CORRUPT_INCORE);
> +
>   	/* abort the corrupt inode, as it was not attached to the buffer */
>   	xfs_iflush_abort(cip, false);
>   	kmem_free(cilist);
>