On Wed, Nov 30, 2022 at 11:04:18AM -0800, Darrick J. Wong wrote:
> 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.
But when I tried that on rhel8 with a varietal ersion of xfsprogs 5.0.0
(xfsprogs-5.0.0-10.el8), I got below error output:
# xfs_io -c "bmap -celpv" testfile >/dev/null
xfs_io: xfsctl(XFS_IOC_GETBMAPX) iflags=0x28 ["testfile"]: Invalid argument
# xfs_io -c "bmap -c" testfile >/dev/null
xfs_io: xfsctl(XFS_IOC_GETBMAPX) iflags=0x28 ["testfile"]: Invalid argument
# xfs_io -c "bmap -elpv" testfile >/dev/null
(no error output)
So, maybe, if you don't need this output to be golden image, how about filter
out the error output to $seqres.full too? Or any better idea?
Thanks,
Zorro
>
> > > + -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
> > >
> >
>
