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?
> +}
> +
> +# 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" ?
> +}
> 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 ?
> +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 '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.
> +
> +# 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
>
