On Thu, Dec 01, 2022 at 01:34:47AM +0800, Zorro Lang wrote:
> On Tue, Nov 29, 2022 at 01:57:14PM -0800, Darrick J. Wong wrote:
> > From: Darrick J. Wong <djwong@xxxxxxxxxx>
> >
> > This is a regression test for a data corruption bug that existed in XFS'
> > copy on write code between 4.9 and 4.19. The root cause is a
> > concurrency bug wherein we would drop ILOCK_SHARED after querying the
> > CoW fork in xfs_map_cow and retake it before querying the data fork in
> > xfs_map_blocks. See the test description for a lot more details.
> >
> > Cc: Wengang Wang <wen.gang.wang@xxxxxxxxxx>
> > Signed-off-by: Darrick J. Wong <djwong@xxxxxxxxxx>
> > ---
> > common/rc | 15 ++++
> > common/tracing | 69 +++++++++++++++++
> > tests/xfs/924 | 215 +++++++++++++++++++++++++++++++++++++++++++++++++++++
> > tests/xfs/924.out | 2
> > 4 files changed, 301 insertions(+)
> > create mode 100644 common/tracing
> > create mode 100755 tests/xfs/924
> > create mode 100644 tests/xfs/924.out
> >
> > diff --git a/common/rc b/common/rc
> > index d71fc0603f..b1b7a3e553 100644
> > --- a/common/rc
> > +++ b/common/rc
> > @@ -3625,6 +3625,21 @@ _check_xflag()
> > fi
> > }
> >
> > +# Make sure the given file access mode is set to use the pagecache. If
> > +# userspace or kernel don't support statx or STATX_ATTR_DAX, we assume that
> > +# means pagecache. The sole parameter must be a directory.
> > +_require_pagecache_access() {
> > + local testfile="$1/testfile"
> > +
> > + touch "$testfile"
> > + if ! _check_s_dax "$testfile" 0 &>> $seqres.full; then
> > + rm -f "$testfile"
> > + _notrun 'test requires pagecache access'
> > + fi
> > +
> > + rm -f "$testfile"
> > +}
> > +
> > # Check if dax mount options are supported
> > #
> > # $1 can be either 'dax=always' or 'dax'
> > diff --git a/common/tracing b/common/tracing
> > new file mode 100644
> > index 0000000000..35e5ed41c2
> > --- /dev/null
> > +++ b/common/tracing
> > @@ -0,0 +1,69 @@
> > +##/bin/bash
> > +# SPDX-License-Identifier: GPL-2.0-or-later
> > +# Copyright (c) 2022 Oracle. All Rights Reserved.
> > +#
> > +# Routines for dealing with ftrace (or any other tracing).
> > +
> > +_require_ftrace() {
> > + local ftrace_dir="/sys/kernel/debug/tracing/instances/"
> > + test -d "$ftrace_dir" || _notrun "kernel does not support ftrace"
> > +
> > + # Give this fstest its own ftrace buffer so that we don't mess up
> > + # any other tracers that might be running.
> > + FTRACE_DIR="$ftrace_dir/fstests.$seq"
> > + test -d "$FTRACE_DIR" && rmdir "$FTRACE_DIR"
> > +}
> > +
> > +_ftrace_cleanup() {
> > + if [ -d "$FTRACE_DIR" ]; then
> > + _ftrace_ignore_events
> > + # Removing an ftrace buffer requires rmdir, even though the
> > + # virtual directory contains children.
> > + rmdir "$FTRACE_DIR"
> > + fi
> > +}
> > +
> > +# Intercept the given events. Arguments may be regular expressions.
> > +_ftrace_record_events() {
> > + local pwd="$PWD"
> > +
> > + test -n "$FTRACE_DIR" || _fail "_require_ftrace not run?"
> > + mkdir "$FTRACE_DIR"
> > + cd "$FTRACE_DIR/events/" || _fail "$FTRACE_DIR: ftrace not set up?"
> > +
> > + for arg in "$@"; do
> > + for tp in */${arg}; do
> > + # Replace slashes with semicolons per ftrace convention
> > + echo "${tp////:}" >> ../set_event
> > + done
> > + done
> > + cd "$pwd"
>
> Is the relative path necessary, can we use absolute path at here?
Hm. I suppose that inner loop could be replaced by:
find "$FTRACE_DIR/events/ -type d -name "$arg" -printf '%P\n' | \
tr '/' ':' >> "$FTRACE_DIR/set_event"
and then we don't need all this cd'ing insanity. I'll try that and
report back.
> > +}
> > +
> > +# Stop intercepting the given events. If no arguments, stops all events.
> > +_ftrace_ignore_events() {
> > + local pwd="$PWD"
> > +
> > + test -n "$FTRACE_DIR" || _fail "_require_ftrace not run?"
> > + cd "$FTRACE_DIR/events/" || _fail "$FTRACE_DIR: ftrace not set up?"
> > +
> > + if [ "$#" -eq 0 ]; then
> > + echo > ../set_event
> > + else
> > + for arg in "$@"; do
> > + for tp in */${arg}; do
> > + # Replace slashes with semicolons per ftrace convention
> > + echo "!${tp////:}" >> ../set_event
> > + done
> > + done
> > + fi
> > +
> > + cd "$pwd"
>
> Same at here
>
> > +}
> > +
> > +# Dump whatever was written to the ftrace buffer since the last time this
> > +# helper was called.
> > +_ftrace_dump() {
> > + test -n "$FTRACE_DIR" || _fail "_require_ftrace not run?"
> > + (cd "$FTRACE_DIR" && cat trace)
>
> Why not "cat $FTRACE_DIR/trace" ?
Fixed.
> > +}
> > diff --git a/tests/xfs/924 b/tests/xfs/924
> > new file mode 100755
> > index 0000000000..81f8ba2743
> > --- /dev/null
> > +++ b/tests/xfs/924
> > @@ -0,0 +1,215 @@
> > +#! /bin/bash
> > +# SPDX-License-Identifier: GPL-2.0
> > +# Copyright (c) 2022 Oracle. All Rights Reserved.
> > +#
> > +# FS QA Test 924
> > +#
> > +# This is a regression test for a data corruption bug that existed in XFS' copy
> > +# on write code between 4.9 and 4.19. The root cause is a concurrency bug
> > +# wherein we would drop ILOCK_SHARED after querying the CoW fork in xfs_map_cow
> > +# and retake it before querying the data fork in xfs_map_blocks. If a second
> > +# thread changes the CoW fork mappings between the two calls, it's possible for
> > +# xfs_map_blocks to return a zero-block mapping, which results in writeback
> > +# being elided for that block. Elided writeback of dirty data results in
> > +# silent loss of writes.
> > +#
> > +# Worse yet, kernels from that era still used buffer heads, which means that an
> > +# elided writeback leaves the page clean but the bufferheads dirty. Due to a
> > +# naïve optimization in mark_buffer_dirty, the SetPageDirty call is elided if
> > +# the bufferhead is dirty, which means that a subsequent rewrite of the data
> > +# block will never result in the page being marked dirty, and all subsequent
> > +# writes are lost.
> > +#
> > +# It turns out that Christoph Hellwig unwittingly fixed the race in commit
> > +# 5c665e5b5af6 ("xfs: remove xfs_map_cow"), and no testcase was ever written.
> > +# Four years later, we hit it on a production 4.14 kernel. This testcase
> > +# relies on a debugging knob that introduces artificial delays into writeback.
> > +#
> > +# Before the race, the file blocks 0-1 are not shared and blocks 2-5 are
> > +# shared. There are no extents in CoW fork.
> > +#
> > +# Two threads race like this:
> > +#
> > +# Thread 1 (writeback block 0) | Thread 2 (write to block 2)
> > +# ---------------------------------|--------------------------------
> > +# |
> > +# 1. Check if block 0 in CoW fork |
> > +# from xfs_map_cow. |
> > +# |
> > +# 2. Block 0 not found in CoW |
> > +# fork; the block is considered |
> > +# not shared. |
> > +# |
> > +# 3. xfs_map_blocks looks up data |
> > +# fork to get a map covering |
> > +# block 0. |
> > +# |
> > +# 4. It gets a data fork mapping |
> > +# for block 0 with length 2. |
> > +# |
> > +# | 1. A buffered write to block 2 sees
> > +# | that it is a shared block and no
> > +# | extent covers block 2 in CoW fork.
> > +# |
> > +# | It creates a new CoW fork mapping.
> > +# | Due to the cowextsize, the new
> > +# | extent starts at block 0 with
> > +# | length 128.
> > +# |
> > +# |
> > +# 5. It lookup CoW fork again to |
> > +# trim the map (0, 2) to a |
> > +# shared block boundary. |
> > +# |
> > +# 5a. It finds (0, 128) in CoW fork|
> > +# 5b. It trims the data fork map |
> > +# from (0, 1) to (0, 0) (!!!) |
> > +# |
> > +# 6. The xfs_imap_valid call after |
> > +# the xfs_map_blocks call checks|
> > +# if the mapping (0, 0) covers |
> > +# block 0. The result is "NO". |
> > +# |
> > +# 7. Since block 0 has no physical |
> > +# block mapped, it's not added |
> > +# to the ioend. This is the |
> > +# first problem. |
> > +# |
> > +# 8. xfs_add_to_ioend usually |
> > +# clears the bufferhead dirty |
> > +# flag Because this is skipped,|
> > +# we leave the page clean with |
> > +# the associated buffer head(s) |
> > +# dirty (the second problem). |
> > +# Now the dirty state is |
> > +# inconsistent.
> > +#
> > +# On newer kernels, this is also a functionality test for the ifork sequence
> > +# counter because the writeback completions will change the data fork and force
> > +# revalidations of the wb mapping.
> > +#
> > +. ./common/preamble
> > +_begin_fstest auto quick clone
> > +
> > +# Import common functions.
> > +. ./common/reflink
> > +. ./common/inject
> > +. ./common/tracing
> > +
> > +# real QA test starts here
> > +_cleanup()
> > +{
> > + _ftrace_cleanup
> > + cd /
> > + rm -r -f $tmp.* $sentryfile $tracefile
> > +}
> > +
> > +# Modify as appropriate.
> > +_supported_fs xfs
> > +_fixed_by_kernel_commit 5c665e5b5af6 "xfs: remove xfs_map_cow"
> > +_require_ftrace
> > +_require_error_injection
> > +_require_scratch_reflink
> > +_require_cp_reflink
> > +
> > +_scratch_mkfs >> $seqres.full
> > +_scratch_mount >> $seqres.full
> > +
> > +# This is a pagecache test, so try to disable fsdax mode.
> > +$XFS_IO_PROG -c 'chattr -x' $SCRATCH_MNT &> $seqres.full
> > +_require_pagecache_access $SCRATCH_MNT
> > +
> > +knob="$(_find_xfs_mountdev_errortag_knob $SCRATCH_DEV "wb_delay_ms")"
> > +test -w "$knob" || _notrun "Kernel does not have wb_delay_ms error injector"
>
> Can `_require_xfs_io_error_injection` help that?
>
> > +
> > +blksz=65536
> > +_require_congruent_file_oplen $SCRATCH_MNT $blksz
> > +
> > +# Make sure we have sufficient extent size to create speculative CoW
> > +# preallocations.
> > +$XFS_IO_PROG -c 'cowextsize 1m' $SCRATCH_MNT
> > +
> > +# Write out a file with the first two blocks unshared and the rest shared.
> > +_pwrite_byte 0x59 0 $((160 * blksz)) $SCRATCH_MNT/file >> $seqres.full
> > +_pwrite_byte 0x59 0 $((160 * blksz)) $SCRATCH_MNT/file.compare >> $seqres.full
> > +sync
> > +
> > +_cp_reflink $SCRATCH_MNT/file $SCRATCH_MNT/file.reflink
> > +
> > +_pwrite_byte 0x58 0 $((2 * blksz)) $SCRATCH_MNT/file >> $seqres.full
> > +_pwrite_byte 0x58 0 $((2 * blksz)) $SCRATCH_MNT/file.compare >> $seqres.full
> > +sync
> > +
> > +# Avoid creation of large folios on newer kernels by cycling the mount and
> > +# immediately writing to the page cache.
> > +_scratch_cycle_mount
> > +
> > +# Write the same data to file.compare as we're about to do to file. Do this
> > +# before slowing down writeback to avoid unnecessary delay.
> > +_pwrite_byte 0x57 0 $((2 * blksz)) $SCRATCH_MNT/file.compare >> $seqres.full
> > +_pwrite_byte 0x56 $((2 * blksz)) $((2 * blksz)) $SCRATCH_MNT/file.compare >> $seqres.full
> > +sync
> > +
> > +# Introduce a half-second wait to each writeback block mapping call. This
> > +# gives us a chance to race speculative cow prealloc with writeback.
> > +wb_delay=500
> > +echo $wb_delay > $knob
>
> Oh, you'd like to avoid depending on xfs_io ?
Oops, this was leftover from before I ported the xfs_errortag.h changes
to xfsprogs.
> > +curval="$(cat $knob)"
> > +test "$curval" -eq $wb_delay || echo "expected wb_delay_ms == $wb_delay"
> > +
> > +_ftrace_record_events 'xfs_wb*iomap_invalid'
> > +
> > +# Start thread 1 + writeback above
> > +$XFS_IO_PROG -c "pwrite -S 0x57 0 $((2 * blksz))" \
> > + -c 'bmap -celpv' -c 'bmap -elpv' \
>
> I didn't find the "bmap -c" option, is it a new option? Won't it break the
> golden image if a system doesn't support it?
-c is a deliberately undocumented option to the bmap command; it's been
there since the introduction of reflink.
> > + -c 'fsync' $SCRATCH_MNT/file >> $seqres.full &
> > +sleep 1
> > +
> > +# Start a sentry to look for evidence of the XFS_ERRORTAG_REPORT logging. If
> > +# we see that, we know we've forced writeback to revalidate a mapping. The
> > +# test has been successful, so turn off the delay.
> > +sentryfile=$TEST_DIR/$seq.sentry
> > +tracefile=$TEST_DIR/$seq.ftrace
> > +wait_for_errortag() {
> > + while [ -e "$sentryfile" ]; do
> > + _ftrace_dump | grep iomap_invalid >> "$tracefile"
> > + if grep -q iomap_invalid "$tracefile"; then
> > + echo 0 > "$knob"
> > + _ftrace_ignore_events
> > + break;
> > + fi
> > + sleep 0.5
> > + done
> > +}
> > +touch $sentryfile
> > +wait_for_errortag &
>
> Should we *wait* background processes in cleanup after removing $sentryfile.
Yes.
> > +
> > +# Start thread 2 to create the cowextsize reservation
> > +$XFS_IO_PROG -c "pwrite -S 0x56 $((2 * blksz)) $((2 * blksz))" \
> > + -c 'bmap -celpv' -c 'bmap -elpv' \
> > + -c 'fsync' $SCRATCH_MNT/file >> $seqres.full
> > +rm -f $sentryfile
> > +
> > +cat "$tracefile" >> $seqres.full
> > +grep -q iomap_invalid "$tracefile"
> > +saw_invalidation=$?
> > +
> > +# Flush everything to disk. If the bug manifests, then after the cycle,
> > +# file should have stale 0x58 in block 0 because we silently dropped a write.
> > +_scratch_cycle_mount
> > +
> > +if ! cmp -s $SCRATCH_MNT/file $SCRATCH_MNT/file.compare; then
> > + echo file and file.compare do not match
> > + $XFS_IO_PROG -c 'bmap -celpv' -c 'bmap -elpv' $SCRATCH_MNT/file >> $seqres.full
> > + echo file.compare
> > + od -tx1 -Ad -c $SCRATCH_MNT/file.compare
> > + echo file
> > + od -tx1 -Ad -c $SCRATCH_MNT/file
> > +elif [ $saw_invalidation -ne 0 ]; then
> > + # The files matched, but nothing got logged about the revalidation?
> > + echo "Expected to hear about writeback iomap invalidations?"
> > +fi
> > +
> > +echo Silence is golden
> > +status=0
> > +exit
> > diff --git a/tests/xfs/924.out b/tests/xfs/924.out
> > new file mode 100644
> > index 0000000000..c6655da35a
> > --- /dev/null
> > +++ b/tests/xfs/924.out
> > @@ -0,0 +1,2 @@
> > +QA output created by 924
> > +Silence is golden
> >
>
