xfs: log recovery should replay deferred ops in order

PATCH In review Darrick J. Wong 3 participants 5 messages Nov 22, 2017 – Nov 30, 2017 XFS filesystem

lore

Share & tools

lore

Darrick J. Wong

author

2017-11-22 18:30 UTC #0 lore raw

PATCH 1/1 xfs: log recovery should replay deferred ops in order

From: Darrick J. Wong <[email protected]>

As part of testing log recovery with dm_log_writes, Amir Goldstein discovered an error in the deferred ops recovery that lead to corruption of the filesystem metadata if a reflink+rmap filesystem happened to shut down midway through a CoW remap:

"This is what happens [after failed log recovery]:

"Phase 1 - find and verify superblock...
"Phase 2 - using internal log

"        - zero log...
"        - scan filesystem freespace and inode maps...
"        - found root inode chunk
"Phase 3 - for each AG...
"        - scan (but don't clear) agi unlinked lists...
"        - process known inodes and perform inode discovery...
"        - agno = 0

"data fork in regular inode 134 claims CoW block 376 "correcting nextents for inode 134
"bad data fork in inode 134
"would have cleared inode 134"

Hou Tao dissected the log contents of exactly such a crash:

"According to the implementation of xfs_defer_finish(), these ops should be completed in the following sequence:

"Have been done:
"(1) CUI: Oper (160)
"(2) BUI: Oper (161)
"(3) CUD: Oper (194), for CUI Oper (160)
"(4) RUI A: Oper (197), free rmap [0x155, 2, -9]

"Should be done:
"(5) BUD: for BUI Oper (161)
"(6) RUI B: add rmap [0x155, 2, 137]
"(7) RUD: for RUI A
"(8) RUD: for RUI B

"Actually be done by xlog_recover_process_intents() "(5) BUD: for BUI Oper (161)
"(6) RUI B: add rmap [0x155, 2, 137]
"(7) RUD: for RUI B
"(8) RUD: for RUI A

"So the rmap entry [0x155, 2, -9] for COW should be freed firstly, then a new rmap entry [0x155, 2, 137] will be added. However, as we can see from the log record in post_mount.log (generated after umount) and the trace print, the new rmap entry [0x155, 2, 137] are added firstly, then the rmap entry [0x155, 2, -9] are freed."

When reconstructing the internal log state from the log items found on disk, it's required that deferred ops replay in exactly the same order that they would have had the filesystem not gone down. However, replaying unfinished deferred ops can create /more/ deferred ops. These new deferred ops are finished in the wrong order. This causes fs corruption and replay crashes, so let's create a single defer_ops to handle the subsequent ops created during replay, then use one single transaction at the end of log recovery to ensure that everything is replayed in the same order as they're supposed to be.

Reported-by Amir Goldstein <[email protected]>

Analyzed-by Hou Tao <[email protected]>

Signed-off-by Darrick J. Wong <[email protected]>

---
 fs/xfs/xfs_bmap_item.c     |   23 ++++----------
 fs/xfs/xfs_bmap_item.h     |    3 +-
 fs/xfs/xfs_log_recover.c   |   73 +++++++++++++++++++++++++++++++++++++++-----
 fs/xfs/xfs_refcount_item.c |   21 ++++---------
 fs/xfs/xfs_refcount_item.h |    3 +-
 5 files changed, 83 insertions(+), 40 deletions(-)

fs/xfs/xfs_bmap_item.c +7 ~~-16~~

index dd136f7..e5fb008 100644
@@ -389,7 +389,8 @@ xfs_bud_init(
 int
 xfs_bui_recover(
 	struct xfs_mount		*mp,
-	struct xfs_bui_log_item		*buip)
+	struct xfs_bui_log_item		*buip,
+	struct xfs_defer_ops		*dfops)
 {
 	int				error = 0;
 	unsigned int			bui_type;

@@ -404,9 +405,7 @@ xfs_bui_recover(
 	xfs_exntst_t			state;
 	struct xfs_trans		*tp;
 	struct xfs_inode		*ip = NULL;
-	struct xfs_defer_ops		dfops;
 	struct xfs_bmbt_irec		irec;
-	xfs_fsblock_t			firstfsb;
 
 	ASSERT(!test_bit(XFS_BUI_RECOVERED, &buip->bui_flags));

@@ -464,7 +463,6 @@ xfs_bui_recover(
 
 	if (VFS_I(ip)->i_nlink == 0)
 		xfs_iflags_set(ip, XFS_IRECOVERY);
-	xfs_defer_init(&dfops, &firstfsb);
 
 	/* Process deferred bmap item. */
 	state = (bmap->me_flags & XFS_BMAP_EXTENT_UNWRITTEN) ?

@@ -479,16 +477,16 @@ xfs_bui_recover(
 		break;
 	default:
 		error = -EFSCORRUPTED;
-		goto err_dfops;
+		goto err_inode;
 	}
 	xfs_trans_ijoin(tp, ip, 0);
 
 	count = bmap->me_len;
-	error = xfs_trans_log_finish_bmap_update(tp, budp, &dfops, type,
+	error = xfs_trans_log_finish_bmap_update(tp, budp, dfops, type,
 			ip, whichfork, bmap->me_startoff,
 			bmap->me_startblock, &count, state);
 	if (error)
-		goto err_dfops;
+		goto err_inode;
 
 	if (count > 0) {
 		ASSERT(type == XFS_BMAP_UNMAP);

@@ -496,16 +494,11 @@ xfs_bui_recover(
 		irec.br_blockcount = count;
 		irec.br_startoff = bmap->me_startoff;
 		irec.br_state = state;
-		error = xfs_bmap_unmap_extent(tp->t_mountp, &dfops, ip, &irec);
+		error = xfs_bmap_unmap_extent(tp->t_mountp, dfops, ip, &irec);
 		if (error)
-			goto err_dfops;
+			goto err_inode;
 	}
 
-	/* Finish transaction, free inodes. */
-	error = xfs_defer_finish(&tp, &dfops);
-	if (error)
-		goto err_dfops;
-
 	set_bit(XFS_BUI_RECOVERED, &buip->bui_flags);
 	error = xfs_trans_commit(tp);
 	xfs_iunlock(ip, XFS_ILOCK_EXCL);

@@ -513,8 +506,6 @@ xfs_bui_recover(
 
 	return error;
 
-err_dfops:
-	xfs_defer_cancel(&dfops);
 err_inode:
 	xfs_trans_cancel(tp);
 	if (ip) {

fs/xfs/xfs_bmap_item.h +2 -1

index c867daa..24b354a 100644
@@ -93,6 +93,7 @@ struct xfs_bud_log_item *xfs_bud_init(struct xfs_mount *,
 		struct xfs_bui_log_item *);
 void xfs_bui_item_free(struct xfs_bui_log_item *);
 void xfs_bui_release(struct xfs_bui_log_item *);
-int xfs_bui_recover(struct xfs_mount *mp, struct xfs_bui_log_item *buip);
+int xfs_bui_recover(struct xfs_mount *mp, struct xfs_bui_log_item *buip,
+		struct xfs_defer_ops *dfops);
 
 #endif	/* __XFS_BMAP_ITEM_H__ */

fs/xfs/xfs_log_recover.c +65 -8

143 lines not on this page · raw message

fs/xfs/xfs_refcount_item.c +7 ~~-14~~

index 8f2e2fa..3a55d6f 100644
@@ -393,7 +393,8 @@ xfs_cud_init(
 int
 xfs_cui_recover(
 	struct xfs_mount		*mp,
-	struct xfs_cui_log_item		*cuip)
+	struct xfs_cui_log_item		*cuip,
+	struct xfs_defer_ops		*dfops)
 {
 	int				i;
 	int				error = 0;

@@ -405,11 +406,9 @@ xfs_cui_recover(
 	struct xfs_trans		*tp;
 	struct xfs_btree_cur		*rcur = NULL;
 	enum xfs_refcount_intent_type	type;
-	xfs_fsblock_t			firstfsb;
 	xfs_fsblock_t			new_fsb;
 	xfs_extlen_t			new_len;
 	struct xfs_bmbt_irec		irec;
-	struct xfs_defer_ops		dfops;
 	bool				requeue_only = false;
 
 	ASSERT(!test_bit(XFS_CUI_RECOVERED, &cuip->cui_flags));

@@ -465,7 +464,6 @@ xfs_cui_recover(
 		return error;
 	cudp = xfs_trans_get_cud(tp, cuip);
 
-	xfs_defer_init(&dfops, &firstfsb);
 	for (i = 0; i < cuip->cui_format.cui_nextents; i++) {
 		refc = &cuip->cui_format.cui_extents[i];
 		refc_type = refc->pe_flags & XFS_REFCOUNT_EXTENT_TYPE_MASK;

@@ -485,7 +483,7 @@ xfs_cui_recover(
 			new_len = refc->pe_len;
 		} else
 			error = xfs_trans_log_finish_refcount_update(tp, cudp,
-				&dfops, type, refc->pe_startblock, refc->pe_len,
+				dfops, type, refc->pe_startblock, refc->pe_len,
 				&new_fsb, &new_len, &rcur);
 		if (error)
 			goto abort_error;

@@ -497,21 +495,21 @@ xfs_cui_recover(
 			switch (type) {
 			case XFS_REFCOUNT_INCREASE:
 				error = xfs_refcount_increase_extent(
-						tp->t_mountp, &dfops, &irec);
+						tp->t_mountp, dfops, &irec);
 				break;
 			case XFS_REFCOUNT_DECREASE:
 				error = xfs_refcount_decrease_extent(
-						tp->t_mountp, &dfops, &irec);
+						tp->t_mountp, dfops, &irec);
 				break;
 			case XFS_REFCOUNT_ALLOC_COW:
 				error = xfs_refcount_alloc_cow_extent(
-						tp->t_mountp, &dfops,
+						tp->t_mountp, dfops,
 						irec.br_startblock,
 						irec.br_blockcount);
 				break;
 			case XFS_REFCOUNT_FREE_COW:
 				error = xfs_refcount_free_cow_extent(
-						tp->t_mountp, &dfops,
+						tp->t_mountp, dfops,
 						irec.br_startblock,
 						irec.br_blockcount);
 				break;

@@ -525,17 +523,12 @@ xfs_cui_recover(
 	}
 
 	xfs_refcount_finish_one_cleanup(tp, rcur, error);
-	error = xfs_defer_finish(&tp, &dfops);
-	if (error)
-		goto abort_defer;
 	set_bit(XFS_CUI_RECOVERED, &cuip->cui_flags);
 	error = xfs_trans_commit(tp);
 	return error;
 
 abort_error:
 	xfs_refcount_finish_one_cleanup(tp, rcur, error);
-abort_defer:
-	xfs_defer_cancel(&dfops);
 	xfs_trans_cancel(tp);
 	return error;
 }

fs/xfs/xfs_refcount_item.h +2 -1

index 5b74ddd..0e53273 100644
@@ -96,6 +96,7 @@ struct xfs_cud_log_item *xfs_cud_init(struct xfs_mount *,
 		struct xfs_cui_log_item *);
 void xfs_cui_item_free(struct xfs_cui_log_item *);
 void xfs_cui_release(struct xfs_cui_log_item *);
-int xfs_cui_recover(struct xfs_mount *mp, struct xfs_cui_log_item *cuip);
+int xfs_cui_recover(struct xfs_mount *mp, struct xfs_cui_log_item *cuip,
+		struct xfs_defer_ops *dfops);
 
 #endif	/* __XFS_REFCOUNT_ITEM_H__ */

Amir Goldstein

Tested-by on v1 1/1

2017-11-23 10:46 UTC #1 lore raw

Quoted 62 lines · Darrick J. Wong

From: Darrick J. Wong <[email protected]>
As part of testing log recovery with dm_log_writes, Amir Goldstein discovered an error in the deferred ops recovery that lead to corruption of the filesystem metadata if a reflink+rmap filesystem happened to shut down midway through a CoW remap:
"This is what happens [after failed log recovery]:
"Phase 1 - find and verify superblock...
"Phase 2 - using internal log
"        - zero log...
"        - scan filesystem freespace and inode maps...
"        - found root inode chunk
"Phase 3 - for each AG...
"        - scan (but don't clear) agi unlinked lists...
"        - process known inodes and perform inode discovery...
"        - agno = 0
"data fork in regular inode 134 claims CoW block 376 "correcting nextents for inode 134
"bad data fork in inode 134
"would have cleared inode 134"
Hou Tao dissected the log contents of exactly such a crash:
"According to the implementation of xfs_defer_finish(), these ops should be completed in the following sequence:
"Have been done:
"(1) CUI: Oper (160)
"(2) BUI: Oper (161)
"(3) CUD: Oper (194), for CUI Oper (160)
"(4) RUI A: Oper (197), free rmap [0x155, 2, -9]
"Should be done:
"(5) BUD: for BUI Oper (161)
"(6) RUI B: add rmap [0x155, 2, 137]
"(7) RUD: for RUI A
"(8) RUD: for RUI B
"Actually be done by xlog_recover_process_intents() "(5) BUD: for BUI Oper (161)
"(6) RUI B: add rmap [0x155, 2, 137]
"(7) RUD: for RUI B
"(8) RUD: for RUI A
"So the rmap entry [0x155, 2, -9] for COW should be freed firstly, then a new rmap entry [0x155, 2, 137] will be added. However, as we can see from the log record in post_mount.log (generated after umount) and the trace print, the new rmap entry [0x155, 2, 137] are added firstly, then the rmap entry [0x155, 2, -9] are freed."
When reconstructing the internal log state from the log items found on disk, it's required that deferred ops replay in exactly the same order that they would have had the filesystem not gone down. However, replaying unfinished deferred ops can create /more/ deferred ops. These new deferred ops are finished in the wrong order. This causes fs corruption and replay crashes, so let's create a single defer_ops to handle the subsequent ops created during replay, then use one single transaction at the end of log recovery to ensure that everything is replayed in the same order as they're supposed to be.

Quoted 4 lines

Reported-by Amir Goldstein <[email protected]>
Analyzed-by Hou Tao <[email protected]>
Signed-off-by Darrick J. Wong <[email protected]>
---

You may add:

Tested-by Amir Goldstein <[email protected]>

Christoph Hellwig

Reviewed-by on v1 1/1

2017-11-23 13:36 UTC #2 lore raw

In reply to Darrick J. Wong

Hi Darrick,

this looks generally good to me:

Reviewed-by Christoph Hellwig <[email protected]>

But I have a few nitpicks below:

fs/xfs/xfs_log_recover.c static inline bool xlog_item_is_intent(struct xfs_log_item *lip) · line 4829

Quoted 8 lines

fs/xfs/xfs_log_recover.c +8 -0

+	/*
+	 * We're finishing the defer_ops that accumulated as a result of
+	 * recovering unfinished intent items during log recovery.  We
+	 * reserve an itruncate transaction because it is the largest
+	 * permanent transaction type.  Since we're the only user of the
+	 * fs right now, take 93% of the available free blocks.  Use
+	 * weird math to avoid a 64-bit division.
+	 */

Those magic 93% are 15/16th, maybe better to write it that way :) That being said / 16 still is a 64-bit division, and I'm pretty sure we'll run into an old gcc on some weird architecture that will not turn it into a shift, so better write it as a shift to start with.

fs/xfs/xfs_log_recover.c static inline bool xlog_item_is_intent(struct xfs_log_item *lip) · line 4831

Quoted 2 lines

fs/xfs/xfs_log_recover.c +2 -0

+	freeblks = percpu_counter_sum(&mp->m_fdblocks);
+	resblks = min_t(s64, UINT_MAX, freeblks);

Didn't I just got called out for using u* types? The same applies to s*, so use int64_t here to be consistent.

fs/xfs/xfs_log_recover.c xlog_recover_process_intents( · line 4911

Quoted 6 lines

fs/xfs/xfs_log_recover.c +6 -0

+		/*
+		 * NOTE: If your intent processing routine can create
+		 * more deferred ops, you /must/ attach them to the
+		 * dfops in this routine or else those subsequent
+		 * intents will get replayed in the wrong order!
+		 */

Please use up all available 80 characters for your comments.

Darrick J. Wong

author

2017-11-27 17:51 UTC #3 lore raw

Quoted 8 lines · Christoph Hellwig

Hi Darrick,
this looks generally good to me:
Reviewed-by Christoph Hellwig <[email protected]>
But I have a few nitpicks below:

Quoted 10 lines

fs/xfs/xfs_log_recover.c static inline bool xlog_item_is_intent(struct xfs_log_item *lip) · line 4829
Quoted 8 lines
fs/xfs/xfs_log_recover.c +8 -0
+	/*
+	 * We're finishing the defer_ops that accumulated as a result of
+	 * recovering unfinished intent items during log recovery.  We
+	 * reserve an itruncate transaction because it is the largest
+	 * permanent transaction type.  Since we're the only user of the
+	 * fs right now, take 93% of the available free blocks.  Use
+	 * weird math to avoid a 64-bit division.
+	 */
Those magic 93% are 15/16th, maybe better to write it that way :)

Ok, will update comment.

Quoted 3 lines

That being said / 16 still is a 64-bit division, and I'm pretty sure we'll run into an old gcc on some weird architecture that will not turn it into a shift, so better write it as a shift to start with.

It shouldn't be, since resblks is unsigned int, which afaik is 32-bit. But meh, I'll just change it to ">> 4" to make it obvious.

Quoted 5 lines

fs/xfs/xfs_log_recover.c static inline bool xlog_item_is_intent(struct xfs_log_item *lip) · line 4831
Quoted 2 lines
fs/xfs/xfs_log_recover.c +2 -0
+	freeblks = percpu_counter_sum(&mp->m_fdblocks);
+	resblks = min_t(s64, UINT_MAX, freeblks);
Didn't I just got called out for using u* types? The same applies to s*, so use int64_t here to be consistent.

Yeah... I pulled the return type directly from percpu_counter_sum, sigh. Will change to int64_t.

Quoted 8 lines

fs/xfs/xfs_log_recover.c xlog_recover_process_intents( · line 4911
Quoted 6 lines
fs/xfs/xfs_log_recover.c +6 -0
+		/*
+		 * NOTE: If your intent processing routine can create
+		 * more deferred ops, you /must/ attach them to the
+		 * dfops in this routine or else those subsequent
+		 * intents will get replayed in the wrong order!
+		 */
Please use up all available 80 characters for your comments.

Ok, will fix the comment.

--D