About the weird tree block corruption

[Qu Wenruo <quwenruo.btrfs@gmx.com>]

[-- Attachment #1: Type: text/plain, Size: 1620 bytes --]

Hi Tavian,

Thanks for all the awesome help debugging the weird tree block corruption.
And sorry for the late reply.

Unfortunately I still failed to reproduce the bug, so I can only craft a
debug patchset for you to test.

The patchset contains 2 patches, the first one is adding the extra
trace_printk() into btrfs.
It requires CONFIG_FTRACE and CONFIG_DYNAMIC_FTRACE kernel configs to be
enabled.

You can use ftrace-cmd to help setting up your environment, but for my
case I normally go with the following bash snippet:

  tracefs="/sys/kernel/debug/tracing"
  begin_trace()
  {
	trace-cmd clear
	echo 1 > $tracefs/tracing_on
  }

  stop_trace()
  {
	cp $tracefs/trace /tmp
	chmod 666 /tmp/trace
	trace-cmd clear
  }

  # Setup the environment
  begin_trace
  workload
  stop_trace

The second patch is to making tree-checker to BUG_ON() when something
went wrong.
This patch should only be applied if you can reliably reproduce it
inside a VM.

When using the 2nd patch, it's strongly recommended to enable the
following sysctl:

  kernel.ftrace_dump_on_oops = 1
  kernel.panic = 5
  kernel.panic_on_oops = 1

And you need a way to reliably access the VM (either netconsole or a
serial console setup).
In that case, you would got all the ftrace buffer to be dumped into the
netconsole/serial console.

This has the extra benefit of reducing the noise. But really needs a
reliable VM setup and can be a little tricky to setup.

Feel free to ask for any extra help to setup the environment, as you're
our last hope to properly pin down the bug.

Thanks,
Qu

[-- Attachment #2: 0002-btrfs-trigger-BUG_ON-when-tree-checker-failed.patch --]
[-- Type: text/x-patch, Size: 1438 bytes --]

From 8632a21d616b358d4db30796b57e6f05b2964464 Mon Sep 17 00:00:00 2001
Message-ID: <8632a21d616b358d4db30796b57e6f05b2964464.1710309440.git.wqu@suse.com>
In-Reply-To: <cover.1710309440.git.wqu@suse.com>
References: <cover.1710309440.git.wqu@suse.com>
From: Qu Wenruo <wqu@suse.com>
Date: Wed, 13 Mar 2024 16:26:47 +1030
Subject: [PATCH 2/2] btrfs: trigger BUG_ON() when tree-checker failed

This allows kernel to crash and dump it ftrace buffer.

Signed-off-by: Qu Wenruo <wqu@suse.com>
---
 fs/btrfs/tree-checker.c | 8 ++++++--
 1 file changed, 6 insertions(+), 2 deletions(-)

diff --git a/fs/btrfs/tree-checker.c b/fs/btrfs/tree-checker.c
index c8fbcae4e88e..ebf019c96ada 100644
--- a/fs/btrfs/tree-checker.c
+++ b/fs/btrfs/tree-checker.c
@@ -1942,8 +1942,10 @@ int btrfs_check_leaf(struct extent_buffer *leaf)
 	enum btrfs_tree_block_status ret;
 
 	ret = __btrfs_check_leaf(leaf);
-	if (unlikely(ret != BTRFS_TREE_BLOCK_CLEAN))
+	if (unlikely(ret != BTRFS_TREE_BLOCK_CLEAN)) {
+		BUG_ON(1);
 		return -EUCLEAN;
+	}
 	return 0;
 }
 ALLOW_ERROR_INJECTION(btrfs_check_leaf, ERRNO);
@@ -2006,8 +2008,10 @@ int btrfs_check_node(struct extent_buffer *node)
 	enum btrfs_tree_block_status ret;
 
 	ret = __btrfs_check_node(node);
-	if (unlikely(ret != BTRFS_TREE_BLOCK_CLEAN))
+	if (unlikely(ret != BTRFS_TREE_BLOCK_CLEAN)) {
+		BUG_ON(1);
 		return -EUCLEAN;
+	}
 	return 0;
 }
 ALLOW_ERROR_INJECTION(btrfs_check_node, ERRNO);
-- 
2.44.0


[-- Attachment #3: 0001-btrfs-add-extra-debug-for-eb-read-path.patch --]
[-- Type: text/x-patch, Size: 3828 bytes --]

From fad1d5ff67e18ceaa8fa439f09be7f4320f327df Mon Sep 17 00:00:00 2001
Message-ID: <fad1d5ff67e18ceaa8fa439f09be7f4320f327df.1710309440.git.wqu@suse.com>
In-Reply-To: <cover.1710309440.git.wqu@suse.com>
References: <cover.1710309440.git.wqu@suse.com>
From: Qu Wenruo <wqu@suse.com>
Date: Wed, 13 Mar 2024 16:24:03 +1030
Subject: [PATCH 1/2] btrfs: add extra debug for eb read path

This is for the recently exposed but very hard to reproduce (for
everyone except awesome and helpful Tavian Barnes) bug, where we seem to
got trash contents for our extent buffer.

Signed-off-by: Qu Wenruo <wqu@suse.com>
---
 fs/btrfs/extent_io.c | 24 +++++++++++++++++++++++-
 1 file changed, 23 insertions(+), 1 deletion(-)

diff --git a/fs/btrfs/extent_io.c b/fs/btrfs/extent_io.c
index bb225798bb89..43331ba74c64 100644
--- a/fs/btrfs/extent_io.c
+++ b/fs/btrfs/extent_io.c
@@ -90,6 +90,18 @@ void btrfs_extent_buffer_leak_debug_check(struct btrfs_fs_info *fs_info)
 #define btrfs_leak_debug_del_eb(eb)			do {} while (0)
 #endif
 
+static inline void dump_extent_buffer(const char *prefix, struct extent_buffer *eb)
+{
+	u8 fsid[BTRFS_FSID_SIZE] = { 0 };
+
+	read_extent_buffer(eb, &fsid, offsetof(struct btrfs_header, fsid),
+			   BTRFS_FSID_SIZE);
+
+	trace_printk("%s, eb=%llu page_refs=%d eb level=%d fsid=%pUb\n",
+			prefix, eb->start, atomic_read(&eb->refs),
+			btrfs_header_level(eb), fsid);
+}
+
 /*
  * Structure to record info about the bio being assembled, and other info like
  * how many bytes are there before stripe/ordered extent boundary.
@@ -3481,6 +3493,7 @@ static void btrfs_release_extent_buffer_pages(struct extent_buffer *eb)
 {
 	ASSERT(!extent_buffer_under_io(eb));
 
+	dump_extent_buffer("before release", eb);
 	for (int i = 0; i < INLINE_EXTENT_BUFFER_PAGES; i++) {
 		struct folio *folio = eb->folios[i];
 
@@ -3499,6 +3512,7 @@ static void btrfs_release_extent_buffer_pages(struct extent_buffer *eb)
  */
 static inline void btrfs_release_extent_buffer(struct extent_buffer *eb)
 {
+	trace_printk("called from %s", __func__);
 	btrfs_release_extent_buffer_pages(eb);
 	btrfs_leak_debug_del_eb(eb);
 	__free_extent_buffer(eb);
@@ -3532,6 +3546,7 @@ struct extent_buffer *btrfs_clone_extent_buffer(const struct extent_buffer *src)
 	int num_folios = num_extent_folios(src);
 	int ret;
 
+	trace_printk("%s: alloc eb=%llu len=%u\n", __func__, src->start, src->len);
 	new = __alloc_extent_buffer(src->fs_info, src->start, src->len);
 	if (new == NULL)
 		return NULL;
@@ -3573,6 +3588,7 @@ struct extent_buffer *__alloc_dummy_extent_buffer(struct btrfs_fs_info *fs_info,
 	int num_folios = 0;
 	int ret;
 
+	trace_printk("%s: alloc eb=%llu len=%lu\n", __func__, start, len);
 	eb = __alloc_extent_buffer(fs_info, start, len);
 	if (!eb)
 		return NULL;
@@ -3893,6 +3909,7 @@ struct extent_buffer *alloc_extent_buffer(struct btrfs_fs_info *fs_info,
 	if (eb)
 		return eb;
 
+	trace_printk("%s: alloc eb=%llu len=%lu\n", __func__, start, len);
 	eb = __alloc_extent_buffer(fs_info, start, len);
 	if (!eb)
 		return ERR_PTR(-ENOMEM);
@@ -4114,6 +4131,8 @@ static int release_extent_buffer(struct extent_buffer *eb)
 		}
 
 		btrfs_leak_debug_del_eb(eb);
+
+		trace_printk("called from %s", __func__);
 		/* Should be safe to release our pages at this point */
 		btrfs_release_extent_buffer_pages(eb);
 #ifdef CONFIG_BTRFS_FS_RUN_SANITY_TESTS
@@ -4347,9 +4366,12 @@ static void end_bbio_meta_read(struct btrfs_bio *bbio)
 
 	eb->read_mirror = bbio->mirror_num;
 
+	dump_extent_buffer("read done", eb);
 	if (uptodate &&
-	    btrfs_validate_extent_buffer(eb, &bbio->parent_check) < 0)
+	    btrfs_validate_extent_buffer(eb, &bbio->parent_check) < 0) {
+		trace_printk("!!! Validation failed, eb=%llu !!!\n", eb->start);
 		uptodate = false;
+	}
 
 	if (uptodate) {
 		set_extent_buffer_uptodate(eb);
-- 
2.44.0