Re: [PATCH v10 4/5] btrfs: test verity orphans with dmlogwrites

Re: [PATCH v10 4/5] btrfs: test verity orphans with dmlogwrites

[Boris Burkov]

On Mon, Jul 18, 2022 at 02:22:44PM -0400, Sweet Tea Dorminy wrote:
> 
> > At each log entry, we want to assert a
> > somewhat complicated invariant:
> > 
> > If verity has not yet started: an orphan indicates that verity has
> > started.
> > If verity has started: mount should handle the orphan and blow away
> > verity data: expect 0 merkle items after mounting the snapshot dev. If
> > we can measure the file, verity has finished.
> > If verity has finished: the orphan should be gone, so mount should not
> > blow away merkle items. Expect the same number of merkle items before
> > and after mounting the snapshot dev.
> 
> I was a bit confused by the mix of invariants and state transition
> conditions, and think this would be somewhat clearer to split into 'state
> transition' and 'state invariant' sections, perhaps as follows:
> 
> There are three possible states for a given point in the log: initially
> verity has not yet started; then verity has started but not finished; and
> finally verity has finished. The log must proceed through these states in
> order: verity starts when an orphan item is added; and
> verity has finished when, post-mount, the verity tool can measure the file.
> 
> Each state has its own invariant for testing:
> - If verity has not yet started: no verity items exist.
> - If verity has started: mount should handle the orphan and blow away
>  verity data: expect 0 merkle items after mounting.
> - If verity has finished: the orphan should be gone and mount should not
>  blow away merkle items. Expect the same number of merkle items before
>  and after mounting.

Thank you so much for untangling the state transitions from the
invariant at each state, that makes it much much clearer.

> 
> > 
> > Note that this relies on grepping btrfs inspect-internal dump-tree.
> > Until btrfs-progs has the ability to print the new Merkle items, they
> > will show up as UNKNOWN.36/37.
> 
> I think that progs versions 5.17+ include print verity items [1] but I don't
> know how tests deal with version-dependent output...
> 
> [1] https://github.com/kdave/btrfs-progs/commit/c4947248580c20869e75e8e61fb9b5e020053b3c

Good point! I think we should just target the new one?

> 
> > +replay_log_prog=$here/src/log-writes/replay-log
> > +num_entries=$($replay_log_prog --log $LOGWRITES_DEV --num-entries)
> > +entry=$($replay_log_prog --log $LOGWRITES_DEV --replay $replay_dev
> > --find --end-mark mkfs | cut -d@ -f1)
> > +$replay_log_prog --log $LOGWRITES_DEV --replay $replay_dev --limit
> > $entry || \
> > + _fail "failed to replay to start entry $entry"
> > +let entry+=1
> > +
> > +# state = 0: verity hasn't started
> > +# state = 1: verity underway
> > +# state = 2: verity done
> > +state=0
> > +while [ $entry -lt $num_entries ];
> > +do
> > + $replay_log_prog --limit 1 --log $LOGWRITES_DEV --replay $replay_dev
> > --start $entry || \
> > + _fail "failed to take replay step at entry: $entry"
> > +
> > + $LVM_PROG lvcreate -s -L 4M -n $snapname $vgname/$lvname
> > >>$seqres.full 2>&1 || \
> > + _fail "Failed to create snapshot"
> > + $UDEV_SETTLE_PROG >>$seqres.full 2>&1
> > +
> > + orphan=$(count_item $snap_dev ORPHAN)
> > + if [ $state -eq 0 ]; then
> > + [ $orphan -gt 0 ] && state=1
> > + fi
> This being in an if is inconsistent with the state transitions a few lines
> down; it would be nice to be consistent, though I don't have a preference
> about which way.

Oh yeah, I am a bit inconsistent. I'll try to make it more uniform.

> > +
> > + pre_mount=$(count_item $snap_dev UNKNOWN.3[67])
> > + _mount $snap_dev $SCRATCH_MNT || _fail "mount failed at entry $entry"
> > + fsverity measure $SCRATCH_MNT/fsv >>$seqres.full 2>&1
> > + measured=$?
> > + umount $SCRATCH_MNT
> > + [ $state -eq 1 ] && [ $measured -eq 0 ] && state=2
> > + [ $state -eq 2 ] && ([ $measured -eq 0 ] || _fail "verity done, but
> > measurement failed at entry $entry")
> > + post_mount=$(count_item $snap_dev UNKNOWN.3[67])
> > +
> > + echo "entry: $entry, state: $state, orphan: $orphan, pre_mount:
> > $pre_mount, post_mount: $post_mount" >> $seqres.full
> > +
> > + if [ $state -eq 1 ]; then
> > + [ $post_mount -eq 0 ] || \
> > + _fail "mount failed to clear under-construction merkle items pre:
> > $pre_mount, post: $post_mount at entry $entry";
> > + fi
> > + if [ $state -eq 2 ]; then
> > + [ $pre_mount -gt 0 ] || \
> > + _fail "expected to have verity items before mount at entry $entry"
> > + [ $pre_mount -eq $post_mount ] || \
> > + _fail "mount cleared merkle items after verity was enabled
> > $pre_mount vs $post_mount at entry $entry";
> > + fi
> > +
> > + let entry+=1
> > + $LVM_PROG lvremove $vgname/$snapname -y >>$seqres.full
> > +done
> 
> I'm not understanding the snapshot part. It seems like most tests using
> log-writes do `_log_writes_replay_log_range $cur $SCRATCH_DEV >>
> $seqres.full` to start each iteration; and then it seems like this test can
> check the item counts before and after a _scratch_mount/_scratch_umount
> cycle  and get the same results. (And, if that worked, the test wouldn't
> need its own _cleanup() and its own lv management, I think?) But I'm
> probably missing something.

IIRC, the purpose of the snapshots is that the mount/unmount cycle is
destructive in the middle of the operation. If the orphan is present,
we'll blow up all the verity items, so if we did it on the device we
were replaying onto, it would leave it in a messed up state as we kept
replaying. So we snapshot at each entry and mount/unmount that to check
the invariants.

I think I might be able to switch to the helper functions for advancing
the log from FUA to FUA instead of by 1 entry each time, though. That
might make the test a bit faster :)

Re: [PATCH v10 4/5] btrfs: test verity orphans with dmlogwrites

[Sweet Tea Dorminy]

>> 
>> I'm not understanding the snapshot part. It seems like most tests 
>> using
>> log-writes do `_log_writes_replay_log_range $cur $SCRATCH_DEV >>
>> $seqres.full` to start each iteration; and then it seems like this 
>> test can
>> check the item counts before and after a 
>> _scratch_mount/_scratch_umount
>> cycle  and get the same results. (And, if that worked, the test 
>> wouldn't
>> need its own _cleanup() and its own lv management, I think?) But I'm
>> probably missing something.
> 
> IIRC, the purpose of the snapshots is that the mount/unmount cycle is
> destructive in the middle of the operation. If the orphan is present,
> we'll blow up all the verity items, so if we did it on the device we
> were replaying onto, it would leave it in a messed up state as we kept
> replaying. So we snapshot at each entry and mount/unmount that to check
> the invariants.

I think what you're saying is that we can't use the device itself 
instead of the snapshot, because mount/unmount change the underlying 
device, and this definitely makes sense.

Looking at other dmlogwrites users, though, generic/482 looks like it 
does something similar, and I don't understand what the difference 
between the replay+snapshot+mount cycles here and the replay+mount 
cycles there. I probably just don't understand what the difference 
between the two tests' scenarios is, though.

Re: [PATCH v10 4/5] btrfs: test verity orphans with dmlogwrites

[Boris Burkov]

On Mon, Jul 18, 2022 at 04:01:47PM -0400, Sweet Tea Dorminy wrote:
> 
> > > 
> > > I'm not understanding the snapshot part. It seems like most tests
> > > using
> > > log-writes do `_log_writes_replay_log_range $cur $SCRATCH_DEV >>
> > > $seqres.full` to start each iteration; and then it seems like this
> > > test can
> > > check the item counts before and after a
> > > _scratch_mount/_scratch_umount
> > > cycle  and get the same results. (And, if that worked, the test
> > > wouldn't
> > > need its own _cleanup() and its own lv management, I think?) But I'm
> > > probably missing something.
> > 
> > IIRC, the purpose of the snapshots is that the mount/unmount cycle is
> > destructive in the middle of the operation. If the orphan is present,
> > we'll blow up all the verity items, so if we did it on the device we
> > were replaying onto, it would leave it in a messed up state as we kept
> > replaying. So we snapshot at each entry and mount/unmount that to check
> > the invariants.
> 
> I think what you're saying is that we can't use the device itself instead of
> the snapshot, because mount/unmount change the underlying device, and this
> definitely makes sense.
> 
> Looking at other dmlogwrites users, though, generic/482 looks like it does
> something similar, and I don't understand what the difference between the
> replay+snapshot+mount cycles here and the replay+mount cycles there. I
> probably just don't understand what the difference between the two tests'
> scenarios is, though.

I just noticed a comment in generic/482 that I think explains it:

# We don't care to preserve any data on the replay dev, as we can replay
# back to the point we need, and in fact sometimes creating/deleting
# snapshots repeatedly can be slower than replaying the log.

So it looks to me like those tests re-replay the full log, including
whatever the mkfs preamble stuff is onto replaydev for each FUA. That
would work for me, I just assumed snapshots would be more efficient,
though this comment challenges that assumption.

Also, it looks like that tests tracks the prev entry redundantly.
Looking into its history, it looks like it was always that way, but
evolved into that state from originally being more like my test.
https://patchwork.kernel.org/project/linux-btrfs/patch/20180314090230.25055-3-wqu@suse.com/#21608233

[PATCH v10 4/5] btrfs: test verity orphans with dmlogwrites

[Boris Burkov]

The behavior of orphans is most interesting across mounts, interrupted
at arbitrary points during fsverity enable. To cover as many such cases
as possible, use dmlogwrites and dmsnapshot as in
log-writes/replay-individual.sh. At each log entry, we want to assert a
somewhat complicated invariant:

If verity has not yet started: an orphan indicates that verity has
started.
If verity has started: mount should handle the orphan and blow away
verity data: expect 0 merkle items after mounting the snapshot dev. If
we can measure the file, verity has finished.
If verity has finished: the orphan should be gone, so mount should not
blow away merkle items. Expect the same number of merkle items before
and after mounting the snapshot dev.

Note that this relies on grepping btrfs inspect-internal dump-tree.
Until btrfs-progs has the ability to print the new Merkle items, they
will show up as UNKNOWN.36/37.

Signed-off-by: Boris Burkov <boris@bur.io>
---
 tests/btrfs/291     | 162 ++++++++++++++++++++++++++++++++++++++++++++
 tests/btrfs/291.out |   2 +
 2 files changed, 164 insertions(+)
 create mode 100755 tests/btrfs/291
 create mode 100644 tests/btrfs/291.out

diff --git a/tests/btrfs/291 b/tests/btrfs/291
new file mode 100755
index 00000000..b66f0f30
--- /dev/null
+++ b/tests/btrfs/291
@@ -0,0 +1,162 @@
+#! /bin/bash
+# SPDX-License-Identifier: GPL-2.0
+# Copyright (C) 2021 Facebook, Inc. All Rights Reserved.
+#
+# FS QA Test 291
+#
+# Test btrfs consistency after each FUA while enabling verity on a file
+# This test works by following the pattern in log-writes/replay-individual.sh:
+# 1. run a workload (verity + sync) while logging to the log device
+# 2. replay an entry to the replay device
+# 3. snapshot the replay device to the snapshot device
+# 4. run destructive tests on the snapshot device (e.g. mount with orphans)
+# 5. goto 2
+#
+. ./common/preamble
+_begin_fstest auto verity
+
+# Override the default cleanup function.
+_cleanup()
+{
+	cd /
+	_log_writes_cleanup &> /dev/null
+	rm -f $img
+	$LVM_PROG vgremove -f -y $vgname >>$seqres.full 2>&1
+	losetup -d $loop_dev >>$seqres.full 2>&1
+}
+
+# Import common functions.
+. ./common/filter
+. ./common/attr
+. ./common/dmlogwrites
+. ./common/verity
+
+# real QA test starts here
+_supported_fs btrfs
+
+_require_scratch
+_require_test
+_require_loop
+_require_log_writes
+_require_dm_target snapshot
+_require_command $LVM_PROG lvm
+_require_scratch_verity
+_require_btrfs_command inspect-internal dump-tree
+_require_test_program "log-writes/replay-log"
+
+sync_loop() {
+	i=$1
+	[ -z "$i" ] && _fail "sync loop needs a number of iterations"
+	while [ $i -gt 0 ]
+	do
+		$XFS_IO_PROG -c sync $SCRATCH_MNT
+		let i-=1
+	done
+}
+
+dump_tree() {
+	local dev=$1
+	$BTRFS_UTIL_PROG inspect-internal dump-tree $dev
+}
+
+count_item() {
+	local dev=$1
+	local item=$2
+	dump_tree $dev | grep -c $item
+}
+
+_log_writes_init $SCRATCH_DEV
+_log_writes_mkfs
+_log_writes_mount
+
+f=$SCRATCH_MNT/fsv
+MB=$((1024 * 1024))
+img=$TEST_DIR/$$.img
+$XFS_IO_PROG -fc "pwrite -q 0 $((10 * $MB))" $f
+$XFS_IO_PROG -c sync $SCRATCH_MNT
+sync_loop 10 &
+sync_proc=$!
+_fsv_enable $f
+$XFS_IO_PROG -c sync $SCRATCH_MNT
+wait $sync_proc
+
+_log_writes_unmount
+_log_writes_remove
+
+# the snapshot and the replay will each be the size of the log writes dev
+# so we create a loop device of size 2 * logwrites and then split it into
+# replay and snapshot with lvm.
+log_writes_blocks=$(blockdev --getsz $LOGWRITES_DEV)
+replay_bytes=$((512 * $log_writes_blocks))
+img_bytes=$((2 * $replay_bytes))
+
+$XFS_IO_PROG -fc "pwrite -q -S 0 $img_bytes $MB" $img >>$seqres.full 2>&1 || \
+	_fail "failed to create image for loop device"
+loop_dev=$(losetup -f --show $img)
+vgname=vg_replay
+lvname=lv_replay
+replay_dev=/dev/mapper/vg_replay-lv_replay
+snapname=lv_snap
+snap_dev=/dev/mapper/vg_replay-$snapname
+
+$LVM_PROG vgcreate -f $vgname $loop_dev >>$seqres.full 2>&1 || _fail "failed to vgcreate $vgname"
+$LVM_PROG lvcreate -L "$replay_bytes"B -n $lvname $vgname -y >>$seqres.full 2>&1 || \
+	_fail "failed to lvcreate $lvname"
+$UDEV_SETTLE_PROG >>$seqres.full 2>&1
+
+replay_log_prog=$here/src/log-writes/replay-log
+num_entries=$($replay_log_prog --log $LOGWRITES_DEV --num-entries)
+entry=$($replay_log_prog --log $LOGWRITES_DEV --replay $replay_dev --find --end-mark mkfs | cut -d@ -f1)
+$replay_log_prog --log $LOGWRITES_DEV --replay $replay_dev --limit $entry || \
+	_fail "failed to replay to start entry $entry"
+let entry+=1
+
+# state = 0: verity hasn't started
+# state = 1: verity underway
+# state = 2: verity done
+state=0
+while [ $entry -lt $num_entries ];
+do
+	$replay_log_prog --limit 1 --log $LOGWRITES_DEV --replay $replay_dev --start $entry || \
+		_fail "failed to take replay step at entry: $entry"
+
+	$LVM_PROG lvcreate -s -L 4M -n $snapname $vgname/$lvname >>$seqres.full 2>&1 || \
+		_fail "Failed to create snapshot"
+	$UDEV_SETTLE_PROG >>$seqres.full 2>&1
+
+	orphan=$(count_item $snap_dev ORPHAN)
+	if [ $state -eq 0 ]; then
+		[ $orphan -gt 0 ] && state=1
+	fi
+
+	pre_mount=$(count_item $snap_dev UNKNOWN.3[67])
+	_mount $snap_dev $SCRATCH_MNT || _fail "mount failed at entry $entry"
+	fsverity measure $SCRATCH_MNT/fsv >>$seqres.full 2>&1
+	measured=$?
+	umount $SCRATCH_MNT
+	[ $state -eq 1 ] && [ $measured -eq 0 ] && state=2
+	[ $state -eq 2 ] && ([ $measured -eq 0 ] || _fail "verity done, but measurement failed at entry $entry")
+	post_mount=$(count_item $snap_dev UNKNOWN.3[67])
+
+	echo "entry: $entry, state: $state, orphan: $orphan, pre_mount: $pre_mount, post_mount: $post_mount" >> $seqres.full
+
+	if [ $state -eq 1 ]; then
+		[ $post_mount -eq 0 ] || \
+			_fail "mount failed to clear under-construction merkle items pre: $pre_mount, post: $post_mount at entry $entry";
+	fi
+	if [ $state -eq 2 ]; then
+		[ $pre_mount -gt 0 ] || \
+			_fail "expected to have verity items before mount at entry $entry"
+		[ $pre_mount -eq $post_mount ] || \
+			_fail "mount cleared merkle items after verity was enabled $pre_mount vs $post_mount at entry $entry";
+	fi
+
+	let entry+=1
+	$LVM_PROG lvremove $vgname/$snapname -y >>$seqres.full
+done
+
+echo "Silence is golden"
+
+# success, all done
+status=0
+exit
diff --git a/tests/btrfs/291.out b/tests/btrfs/291.out
new file mode 100644
index 00000000..04605c70
--- /dev/null
+++ b/tests/btrfs/291.out
@@ -0,0 +1,2 @@
+QA output created by 291
+Silence is golden
-- 
2.35.1