[PATCH 3/7] f2fs: fix to return -EIO from f2fs_write_checkpoint() once cp_error is set

[Chao Yu]

From: Chao Yu <chao@xxxxxxxxxx>

f2fs_write_checkpoint() skips a CP_SYNC/CP_FASTBOOT/CP_DISCARD request
w/ err = 0 if the superblock is not dirty, and this check is done before
the f2fs_cp_error() check.

However, do_checkpoint() clears SBI_IS_DIRTY unconditionally, even when
the checkpoint fails due to cp_error (e.g. shutdown), and only returns
-EIO at the end. So a checkpoint request which was queued before cp_error
was set, and waits on cp_global_sem or in the checkpoint merge queue, will
see a clean superblock once the previous checkpoint failed, and returns 0
w/o doing checkpoint.

For a file which relies on checkpoint to persist its fsynced data, e.g. a
compressed file (CP_COMPRESSED), f2fs_do_sync_file() -> f2fs_sync_fs()
then returns 0, and fsync() reports false success, whereas its data was
neither covered by a checkpoint nor by fsync node blocks: after recovery,
the fsynced data is rolled back to an old version.

Note that commit e41de21d78ec ("f2fs: fix to return -EIO from
f2fs_sync_fs() if cp_error is set") only covers the case cp_error is set
before f2fs_sync_fs() is called, not the case it is set while the request
is pending.

This was reproduced by the f2fs consistency test (verify_consistency.sh
--init zoned -S 64 --mode consistency, w/ compress_algorithm=lz4 and
default checkpoint_merge, under fault injection): fsync_verify.py randomly
overwrites 4K blocks w/ a generation number and fsyncs them, the test
injects "f2fs_io shutdown 2" in the middle, then verifies the fsynced
generation after fsck and remount:

  FAIL: file 2 block 510: rolled back: gen 17 < durable gen 18
  FAIL: file 2 block 561: rolled back: gen 22 < durable gen 23
  FAIL: file 2 block 955: rolled back: gen 12 < durable gen 13
  FAIL: file 2 block 3986: rolled back: gen 23 < durable gen 24

w/ debug logs (trace_printk) added in f2fs, the ftrace log of the
failing compressed file (ino 438) shows:

  python3-346519  2267.558508: FSV SYNC-BEGIN f=2 fdatasync n=4
  python3-346519  2267.558519: ino=438 FSYNC enter datasync=1 dirty=4 cpver=14c8edcb
  f2fs_ckpt       2267.559876: CP end reason=4 err=0 cpver=14c8edcb
  python3-346519  2267.570549: ino=438 DOWRITE OPU idx=510 old=a21bc1 new=ae4af3 hdr[f=2 b=510 g=18]
  python3-346519  2267.571478: ino=438 WCACHE exit ret=0 nwritten=4 dirty_left=0
  bash            2267.571810: iteration 4: injecting shutdown 2
  f2fs_ckpt       2267.573403: CP start reason=4 cpver=14c8edcb dirty=1
  python3-346519  2267.579576: ino=438 FSYNC wait_range ret=0 dirty_left=0 append=1
  f2fs_ckpt       2267.589393: CP end reason=4 err=-5 cpver=14c8edcc cp_error=1
  f2fs_ckpt       2267.589413: CP start reason=4 cpver=14c8edcc dirty=0
  f2fs_ckpt       2267.589414: CP SKIPPED (sb not dirty) reason=4
  f2fs_ckpt       2267.589415: CP end reason=4 err=0 cpver=14c8edcc cp_error=1
  python3-346516  2267.589431: SYNC_FS sync=1 err=-5
  python3-346519  2267.589503: SYNC_FS sync=1 err=0          <--- false success
  python3-346519  2267.589507: ino=438 FSYNC cp_reason=2 sync_fs ret=0
  python3-346519  2267.589510: ino=438 FSYNC exit ret=0
  python3-346519  2267.589567: FSV SYNC-OK f=2 D=510:18,561:23,955:13,3986:24
  [shutdown -> umount -> fsck -> remount, recovery from cpver 14c8edcb]
  kworker         2370.028185: ino=438 READ-END idx=510 hdr[f=2 b=510 g=17]

- the checkpoint which should cover the data written at 2267.570549
failed w/ -EIO due to shutdown, and cleared SBI_IS_DIRTY.
- the next merged checkpoint request was skipped as the superblock looked
clean, and returned 0, so fdatasync() of ino 438 returned 0.
- after recovery from the last valid checkpoint (14c8edcb), block 510
has gen 17 instead of the fsynced gen 18.

Let's check cp_error before the "superblock is not dirty" check in
f2fs_write_checkpoint(), so that a pending checkpoint request returns
-EIO once cp_error is set.

Cc: stable@xxxxxxxxxx
Fixes: c34f42e2cb2d ("f2fs: report error of do_checkpoint")
Signed-off-by: Chao Yu <chao@xxxxxxxxxx>
---
 fs/f2fs/checkpoint.c | 13 +++++++++----
 1 file changed, 9 insertions(+), 4 deletions(-)

diff --git a/fs/f2fs/checkpoint.c b/fs/f2fs/checkpoint.c
index 5c5b45d3c67b..819073671f3d 100644
--- a/fs/f2fs/checkpoint.c
+++ b/fs/f2fs/checkpoint.c
@@ -1945,14 +1945,19 @@ int f2fs_write_checkpoint(struct f2fs_sb_info *sbi, struct cp_control *cpc)
 
 	stat_cp_time(cpc, CP_TIME_LOCK);
 
-	if (!is_sbi_flag_set(sbi, SBI_IS_DIRTY) &&
-		((cpc->reason & CP_FASTBOOT) || (cpc->reason & CP_SYNC) ||
-		((cpc->reason & CP_DISCARD) && !sbi->discard_blks)))
-		goto out;
+	/*
+	 * Check cp_error first: a failed checkpoint has cleared SBI_IS_DIRTY
+	 * in do_checkpoint(), so a following request would be skipped below
+	 * and report false success.
+	 */
 	if (unlikely(f2fs_cp_error(sbi))) {
 		err = -EIO;
 		goto out;
 	}
+	if (!is_sbi_flag_set(sbi, SBI_IS_DIRTY) &&
+		((cpc->reason & CP_FASTBOOT) || (cpc->reason & CP_SYNC) ||
+		((cpc->reason & CP_DISCARD) && !sbi->discard_blks)))
+		goto out;
 
 	trace_f2fs_write_checkpoint(sbi->sb, cpc->reason, CP_PHASE_START_BLOCK_OPS);
 
-- 
2.49.0