[PATCH] tools: add a dm-logwrites replay tool

[PATCH] tools: add a dm-logwrites replay tool

[Dave Chinner]

From: Dave Chinner <dchinner@redhat.com>

Trying to decipher a dm-logwrites replay failure from generic/482 is
difficult. The test destroys all the dm state and devices when the
test fails, leaving nothing behind for post-mortem analysis. This
script is intended to allow replay of the dm-logwrites device one
FUA at a time similar to generic/482, and is used in conjunction
with a modifed g/482 test that does not tear down the dm volumes
or state when the test fails.

This allows the developer to replay the logwrites up to just prior
to failure to examine just the differences between the last good
state and the first failure state, greatly reducing the complexity
of analysing failures.

Instructions for use are in the tools/dm-logwrite-replay script
itself.

Signed-off-by: Dave Chinner <dchinner@redhat.com>
---
 common/dmlogwrites       |   8 +--
 tests/generic/482        |  18 +++++++
 tools/dm-logwrite-replay | 113 +++++++++++++++++++++++++++++++++++++++
 3 files changed, 135 insertions(+), 4 deletions(-)
 create mode 100755 tools/dm-logwrite-replay

diff --git a/common/dmlogwrites b/common/dmlogwrites
index 573f4b8a..66c57e2b 100644
--- a/common/dmlogwrites
+++ b/common/dmlogwrites
@@ -180,11 +180,11 @@ _log_writes_replay_log_range()
 	[ -z "$blkdev" ] && _fail \
 	"block dev must be specified for _log_writes_replay_log_range"
 
-	# To ensure we replay the last entry,
-	# we need to manually increase the end entry number to ensure
-	# it's played
+	# To ensure we replay the last entry, we need to manually increase the
+	# end entry number to ensure it's played. We also dump all the
+	# operations performed as this helps post-mortem analysis of failures.
 	echo "=== replay to $end ===" >> $seqres.full
-	$here/src/log-writes/replay-log --log $LOGWRITES_DEV \
+	$here/src/log-writes/replay-log -vv --log $LOGWRITES_DEV \
 		--replay $blkdev --limit $(($end + 1)) \
 		>> $seqres.full 2>&1
 	[ $? -ne 0 ] && _fail "replay failed"
diff --git a/tests/generic/482 b/tests/generic/482
index f26e6fc4..416b929a 100755
--- a/tests/generic/482
+++ b/tests/generic/482
@@ -12,6 +12,10 @@
 _begin_fstest auto metadata replay thin
 
 # Override the default cleanup function.
+#
+# If debugging logwrites failures using the tools/dm-logwrite-replay script,
+# switch the cleanup function to the version that is commented out below so that
+# failure leaves the corpse intact for post-mortem failure analysis.
 _cleanup()
 {
 	cd /
@@ -21,6 +25,20 @@ _cleanup()
 	rm -f $tmp.*
 }
 
+# tools/dm-logwrite-replay _cleanup version
+#_cleanup()
+#{
+#	cd /
+#	$KILLALL_PROG -KILL -q $FSSTRESS_PROG &> /dev/null
+#	if [ $status -eq 0 ]; then
+#		_log_writes_cleanup &> /dev/null
+#		_dmthin_cleanup
+#	else
+#		echo dm-thinvol-dev: $DMTHIN_VOL_DEV >> $seqres.full
+#	fi
+#	rm -f $tmp.*
+#}
+
 # Import common functions.
 . ./common/filter
 . ./common/dmthin
diff --git a/tools/dm-logwrite-replay b/tools/dm-logwrite-replay
new file mode 100755
index 00000000..56d0121c
--- /dev/null
+++ b/tools/dm-logwrite-replay
@@ -0,0 +1,113 @@
+#!/bin/bash
+# SPDX-License-Identifier: GPL-2.0 Copyright (c) 2021 Red Hat, Inc.  All Rights
+# Reserved.
+#
+# dm-logwrite-replay utility.
+#
+# This is used to replay failures that result from generic/482. Modify the
+# cleanup function in g/482 to the version that does not tear down the dm-thin
+# volume and grab the thin volume name from the the 482.full output file.  Then
+# you can replay the log writes manually with this tool so that the changes
+# between a good replay and a bad replay can be isolated. The 482.full output
+# file has all the FUA write locations recorded - these are what you pass the
+# tool as "PREV_FUA" and "END_FUA".
+#
+# The tool uses the fstests infrastructure and scripts, so it needs to be run
+# from the base fstests directory similar to the check script. RESULT_DIR is
+# pointed at the current directory, which means that debug output from the tool
+# placed in $seqres.full points ends up in ./dm-logwrite-replay.full.
+#
+# For example:
+#	- device name /dev/mapper/thin-vol
+# 	- last good replay @ write 124
+# 	- first bad replay @ write 125
+#
+# Replay from start to 124:
+#
+# cd src/fstests
+# tools/dm-logwrite-replay --dev /dev/mapper/thin-vol --end 124
+# <take image of filesystem /dev/mapper/thin-vol>
+#
+# Replay from 124 to 125:
+#
+# tools/dm-logwrite-replay --dev /dev/mapper/thin-vol --start 124 --end 125
+# <take image of filesystem from /dev/mapper/thin-vol>
+#
+# Now compare images of the filesystem to see the differences and analyse the
+# failure.
+#
+# Often with log recovery failures, you need to see the pre-recovery state of
+# the filesystem. To do this, use the --no-recovery option in conjunction with
+# the above commands.  This allows you to determine if recovery is doing the
+# wrong thing or not.
+#
+# Once finished, teardown the logwrites/thin vol with
+#
+# tools/dm-logwrite-replay --dev /dev/mapper/thin-vol --cleanup
+#
+
+DMTHIN_VOL_DEV=""
+PREV_FUA=""
+END_FUA=""
+CLEANUP=""
+DO_RECOVERY="y"
+
+while [ $# -gt 0 ]; do
+	case "$1" in
+	--dev) DMTHIN_VOL_DEV="$2" ; shift ;;
+	--start) PREV_FUA="$2" ; shift ;;
+	--end) END_FUA="$2" ; shift ;;
+	--cleanup) CLEANUP=y ;;
+	--no-recovery) DO_RECOVERY="" ;;
+	esac
+	shift
+done
+
+[ -z "$DMTHIN_VOL_DEV" ] && _fail "not dmthin vol defined"
+
+RESULT_DIR=`pwd`
+
+. ./common/preamble
+_begin_fstest replay
+
+MOUNT_OPTIONS="-o dax=never"
+
+# Import common functions.
+. ./common/filter
+. ./common/dmthin
+. ./common/dmlogwrites
+
+LOGWRITES_NAME=logwrites-test
+LOGWRITES_DMDEV=/dev/mapper/$LOGWRITES_NAME
+
+if [ -n "$CLEANUP" ]; then
+	_log_writes_cleanup &> /dev/null
+	_dmthin_cleanup
+	exit;
+fi
+
+if [ -z "$PREV_FUA" ]; then
+	prev=$(_log_writes_mark_to_entry_number mkfs)
+	[ -z "$prev" ] && _fail "failed to locate entry mark 'mkfs'"
+else
+	prev="$((PREV_FUA + 1))"
+fi
+cur=$(_log_writes_find_next_fua $prev)
+[ -z "$cur" ] && _fail "failed to locate next FUA write"
+
+while [ ! -z "$cur" ]; do
+	echo "Replay writes from $prev to $cur"
+	_log_writes_replay_log_range $cur $DMTHIN_VOL_DEV
+
+	if [ -n "$DO_RECOVERY" ]; then
+		_dmthin_mount
+		_dmthin_check_fs
+	fi
+
+	[ -n "$END_FUA" -a "$END_FUA" -eq "$cur" ] && break;
+
+	prev=$cur
+	cur=$(_log_writes_find_next_fua $(($cur + 1)))
+	[ -z "$cur" ] && break
+done
+
-- 
2.31.1

Re: [PATCH] tools: add a dm-logwrites replay tool

[Amir Goldstein]

On Wed, Jul 21, 2021 at 3:14 AM Dave Chinner <david@fromorbit.com> wrote:
>
> From: Dave Chinner <dchinner@redhat.com>
>
> Trying to decipher a dm-logwrites replay failure from generic/482 is
> difficult. The test destroys all the dm state and devices when the
> test fails, leaving nothing behind for post-mortem analysis. This
> script is intended to allow replay of the dm-logwrites device one
> FUA at a time similar to generic/482, and is used in conjunction
> with a modifed g/482 test that does not tear down the dm volumes
> or state when the test fails.
>
> This allows the developer to replay the logwrites up to just prior
> to failure to examine just the differences between the last good
> state and the first failure state, greatly reducing the complexity
> of analysing failures.
>
> Instructions for use are in the tools/dm-logwrite-replay script
> itself.
>

This looks very useful!
Thanks for sharing :)

> Signed-off-by: Dave Chinner <dchinner@redhat.com>
> ---
>  common/dmlogwrites       |   8 +--
>  tests/generic/482        |  18 +++++++
>  tools/dm-logwrite-replay | 113 +++++++++++++++++++++++++++++++++++++++
>  3 files changed, 135 insertions(+), 4 deletions(-)
>  create mode 100755 tools/dm-logwrite-replay
>
> diff --git a/common/dmlogwrites b/common/dmlogwrites
> index 573f4b8a..66c57e2b 100644
> --- a/common/dmlogwrites
> +++ b/common/dmlogwrites
> @@ -180,11 +180,11 @@ _log_writes_replay_log_range()
>         [ -z "$blkdev" ] && _fail \
>         "block dev must be specified for _log_writes_replay_log_range"
>
> -       # To ensure we replay the last entry,
> -       # we need to manually increase the end entry number to ensure
> -       # it's played
> +       # To ensure we replay the last entry, we need to manually increase the
> +       # end entry number to ensure it's played. We also dump all the
> +       # operations performed as this helps post-mortem analysis of failures.
>         echo "=== replay to $end ===" >> $seqres.full
> -       $here/src/log-writes/replay-log --log $LOGWRITES_DEV \
> +       $here/src/log-writes/replay-log -vv --log $LOGWRITES_DEV \
>                 --replay $blkdev --limit $(($end + 1)) \
>                 >> $seqres.full 2>&1
>         [ $? -ne 0 ] && _fail "replay failed"
> diff --git a/tests/generic/482 b/tests/generic/482
> index f26e6fc4..416b929a 100755
> --- a/tests/generic/482
> +++ b/tests/generic/482
> @@ -12,6 +12,10 @@
>  _begin_fstest auto metadata replay thin
>
>  # Override the default cleanup function.
> +#
> +# If debugging logwrites failures using the tools/dm-logwrite-replay script,
> +# switch the cleanup function to the version that is commented out below so that
> +# failure leaves the corpse intact for post-mortem failure analysis.

Please let's use KEEP_LOGWRITES=yes envvar for this.

>  _cleanup()
>  {
>         cd /
> @@ -21,6 +25,20 @@ _cleanup()
>         rm -f $tmp.*
>  }
>
> +# tools/dm-logwrite-replay _cleanup version
> +#_cleanup()
> +#{
> +#      cd /
> +#      $KILLALL_PROG -KILL -q $FSSTRESS_PROG &> /dev/null
> +#      if [ $status -eq 0 ]; then
> +#              _log_writes_cleanup &> /dev/null
> +#              _dmthin_cleanup
> +#      else
> +#              echo dm-thinvol-dev: $DMTHIN_VOL_DEV >> $seqres.full

In this case, let's print a message to stdout, with a hint to use
dm-logwrite-replay tool and reminder to run the cleanup.

But also, I wonder - we can call _log_writes_cleanup;_dmthin_cleanup
from _dmthin_init() as a service for debuggers who forgot to cleanup
after forensics just as ./check itself will umount scratch and test leftover
mounts.

We could do that conditional or regardless to KEEP_LOGWRITES envvar.

Does it cost us anything to do that? Any caveats?

Thanks,
Amir.

> +#      fi
> +#      rm -f $tmp.*
> +#}
> +
>  # Import common functions.
>  . ./common/filter
>  . ./common/dmthin
> diff --git a/tools/dm-logwrite-replay b/tools/dm-logwrite-replay
> new file mode 100755
> index 00000000..56d0121c
> --- /dev/null
> +++ b/tools/dm-logwrite-replay
> @@ -0,0 +1,113 @@
> +#!/bin/bash
> +# SPDX-License-Identifier: GPL-2.0 Copyright (c) 2021 Red Hat, Inc.  All Rights
> +# Reserved.
> +#
> +# dm-logwrite-replay utility.
> +#
> +# This is used to replay failures that result from generic/482. Modify the
> +# cleanup function in g/482 to the version that does not tear down the dm-thin
> +# volume and grab the thin volume name from the the 482.full output file.  Then
> +# you can replay the log writes manually with this tool so that the changes
> +# between a good replay and a bad replay can be isolated. The 482.full output
> +# file has all the FUA write locations recorded - these are what you pass the
> +# tool as "PREV_FUA" and "END_FUA".
> +#
> +# The tool uses the fstests infrastructure and scripts, so it needs to be run
> +# from the base fstests directory similar to the check script. RESULT_DIR is
> +# pointed at the current directory, which means that debug output from the tool
> +# placed in $seqres.full points ends up in ./dm-logwrite-replay.full.
> +#
> +# For example:
> +#      - device name /dev/mapper/thin-vol
> +#      - last good replay @ write 124
> +#      - first bad replay @ write 125
> +#
> +# Replay from start to 124:
> +#
> +# cd src/fstests
> +# tools/dm-logwrite-replay --dev /dev/mapper/thin-vol --end 124
> +# <take image of filesystem /dev/mapper/thin-vol>
> +#
> +# Replay from 124 to 125:
> +#
> +# tools/dm-logwrite-replay --dev /dev/mapper/thin-vol --start 124 --end 125
> +# <take image of filesystem from /dev/mapper/thin-vol>
> +#
> +# Now compare images of the filesystem to see the differences and analyse the
> +# failure.
> +#
> +# Often with log recovery failures, you need to see the pre-recovery state of
> +# the filesystem. To do this, use the --no-recovery option in conjunction with
> +# the above commands.  This allows you to determine if recovery is doing the
> +# wrong thing or not.
> +#
> +# Once finished, teardown the logwrites/thin vol with
> +#
> +# tools/dm-logwrite-replay --dev /dev/mapper/thin-vol --cleanup
> +#
> +
> +DMTHIN_VOL_DEV=""
> +PREV_FUA=""
> +END_FUA=""
> +CLEANUP=""
> +DO_RECOVERY="y"
> +
> +while [ $# -gt 0 ]; do
> +       case "$1" in
> +       --dev) DMTHIN_VOL_DEV="$2" ; shift ;;
> +       --start) PREV_FUA="$2" ; shift ;;
> +       --end) END_FUA="$2" ; shift ;;
> +       --cleanup) CLEANUP=y ;;
> +       --no-recovery) DO_RECOVERY="" ;;
> +       esac
> +       shift
> +done
> +
> +[ -z "$DMTHIN_VOL_DEV" ] && _fail "not dmthin vol defined"
> +
> +RESULT_DIR=`pwd`
> +
> +. ./common/preamble
> +_begin_fstest replay
> +
> +MOUNT_OPTIONS="-o dax=never"
> +
> +# Import common functions.
> +. ./common/filter
> +. ./common/dmthin
> +. ./common/dmlogwrites
> +
> +LOGWRITES_NAME=logwrites-test
> +LOGWRITES_DMDEV=/dev/mapper/$LOGWRITES_NAME
> +
> +if [ -n "$CLEANUP" ]; then
> +       _log_writes_cleanup &> /dev/null
> +       _dmthin_cleanup
> +       exit;
> +fi
> +
> +if [ -z "$PREV_FUA" ]; then
> +       prev=$(_log_writes_mark_to_entry_number mkfs)
> +       [ -z "$prev" ] && _fail "failed to locate entry mark 'mkfs'"
> +else
> +       prev="$((PREV_FUA + 1))"
> +fi
> +cur=$(_log_writes_find_next_fua $prev)
> +[ -z "$cur" ] && _fail "failed to locate next FUA write"
> +
> +while [ ! -z "$cur" ]; do
> +       echo "Replay writes from $prev to $cur"
> +       _log_writes_replay_log_range $cur $DMTHIN_VOL_DEV
> +
> +       if [ -n "$DO_RECOVERY" ]; then
> +               _dmthin_mount
> +               _dmthin_check_fs
> +       fi
> +
> +       [ -n "$END_FUA" -a "$END_FUA" -eq "$cur" ] && break;
> +
> +       prev=$cur
> +       cur=$(_log_writes_find_next_fua $(($cur + 1)))
> +       [ -z "$cur" ] && break
> +done
> +
> --
> 2.31.1
>

Re: [PATCH] tools: add a dm-logwrites replay tool

[Dave Chinner]

On Wed, Jul 21, 2021 at 09:04:29AM +0300, Amir Goldstein wrote:
> On Wed, Jul 21, 2021 at 3:14 AM Dave Chinner <david@fromorbit.com> wrote:
> >
> > From: Dave Chinner <dchinner@redhat.com>
> >
> > Trying to decipher a dm-logwrites replay failure from generic/482 is
> > difficult. The test destroys all the dm state and devices when the
> > test fails, leaving nothing behind for post-mortem analysis. This
> > script is intended to allow replay of the dm-logwrites device one
> > FUA at a time similar to generic/482, and is used in conjunction
> > with a modifed g/482 test that does not tear down the dm volumes
> > or state when the test fails.
> >
> > This allows the developer to replay the logwrites up to just prior
> > to failure to examine just the differences between the last good
> > state and the first failure state, greatly reducing the complexity
> > of analysing failures.
> >
> > Instructions for use are in the tools/dm-logwrite-replay script
> > itself.
> >
> 
> This looks very useful!
> Thanks for sharing :)
> 
> > Signed-off-by: Dave Chinner <dchinner@redhat.com>
> > ---
> >  common/dmlogwrites       |   8 +--
> >  tests/generic/482        |  18 +++++++
> >  tools/dm-logwrite-replay | 113 +++++++++++++++++++++++++++++++++++++++
> >  3 files changed, 135 insertions(+), 4 deletions(-)
> >  create mode 100755 tools/dm-logwrite-replay
> >
> > diff --git a/common/dmlogwrites b/common/dmlogwrites
> > index 573f4b8a..66c57e2b 100644
> > --- a/common/dmlogwrites
> > +++ b/common/dmlogwrites
> > @@ -180,11 +180,11 @@ _log_writes_replay_log_range()
> >         [ -z "$blkdev" ] && _fail \
> >         "block dev must be specified for _log_writes_replay_log_range"
> >
> > -       # To ensure we replay the last entry,
> > -       # we need to manually increase the end entry number to ensure
> > -       # it's played
> > +       # To ensure we replay the last entry, we need to manually increase the
> > +       # end entry number to ensure it's played. We also dump all the
> > +       # operations performed as this helps post-mortem analysis of failures.
> >         echo "=== replay to $end ===" >> $seqres.full
> > -       $here/src/log-writes/replay-log --log $LOGWRITES_DEV \
> > +       $here/src/log-writes/replay-log -vv --log $LOGWRITES_DEV \
> >                 --replay $blkdev --limit $(($end + 1)) \
> >                 >> $seqres.full 2>&1
> >         [ $? -ne 0 ] && _fail "replay failed"
> > diff --git a/tests/generic/482 b/tests/generic/482
> > index f26e6fc4..416b929a 100755
> > --- a/tests/generic/482
> > +++ b/tests/generic/482
> > @@ -12,6 +12,10 @@
> >  _begin_fstest auto metadata replay thin
> >
> >  # Override the default cleanup function.
> > +#
> > +# If debugging logwrites failures using the tools/dm-logwrite-replay script,
> > +# switch the cleanup function to the version that is commented out below so that
> > +# failure leaves the corpse intact for post-mortem failure analysis.
> 
> Please let's use KEEP_LOGWRITES=yes envvar for this.

Where would that be set? And how would one use it?

FWIW, I won't remember about this or use it - my work-flow is based
on patches that modify test behaviour in an unchanging test
environment, rather changing the test environment to modify test
behaviour. Hence it's much easier for me to select the
debug-482-switch-cleanup patch from my local library of debug hacks,
push it onto my fstests stack and then run the test and have it
behave as I want...

> >  _cleanup()
> >  {
> >         cd /
> > @@ -21,6 +25,20 @@ _cleanup()
> >         rm -f $tmp.*
> >  }
> >
> > +# tools/dm-logwrite-replay _cleanup version
> > +#_cleanup()
> > +#{
> > +#      cd /
> > +#      $KILLALL_PROG -KILL -q $FSSTRESS_PROG &> /dev/null
> > +#      if [ $status -eq 0 ]; then
> > +#              _log_writes_cleanup &> /dev/null
> > +#              _dmthin_cleanup
> > +#      else
> > +#              echo dm-thinvol-dev: $DMTHIN_VOL_DEV >> $seqres.full
> 
> In this case, let's print a message to stdout, with a hint to use
> dm-logwrite-replay tool and reminder to run the cleanup.

Sure, but I think the person running it this way is going to know
that this happens on failure already :/

> But also, I wonder - we can call _log_writes_cleanup;_dmthin_cleanup
> from _dmthin_init() as a service for debuggers who forgot to cleanup
> after forensics just as ./check itself will umount scratch and test leftover
> mounts.

No, we can't, because we don't even get that far trying to run
fstests when the devices have not been torn down. i.e. check
failures to access the scratch device because it's still busy and
immmediately aborts before it gets to running any tests.

Further, I'm actually using that "scratch device busy" check failure
to terminate the repeated iteration loop when a failure occurs. This
ensures that the output files from the test failure are not
overwritten by the next attempt to run the test.

Hence, even if it were possible, having the test auto-cleanup is not
a useful thing to do from a failure reproducer/debugging point of
view....

> We could do that conditional or regardless to KEEP_LOGWRITES envvar.
> 
> Does it cost us anything to do that? Any caveats?

I'm not sure what adding KEEP_LOGWRITES actually gains us other than
having just another undocumented, largely unused environment
variable that people will not remember about but we still have to
maintain.

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com