fs/btrfs/volumes.c:6114 suspicious rcu_dereference_check() usage!

fs/btrfs/volumes.c:6114 suspicious rcu_dereference_check() usage!

[David Howells]

I'm seeing the attached message generated from this line:

	btrfs_debug_in_rcu(fs_info,
	"btrfs_map_bio: rw %d 0x%x, sector=%llu, dev=%lu (%s id %llu), size=%u",
		bio_op(bio), bio->bi_opf, (u64)bio->bi_iter.bi_sector,
		(u_long)dev->bdev->bd_dev, rcu_str_deref(dev->name), dev->devid,
		bio->bi_iter.bi_size);

in submit_stripe_bio().  I'm not sure exactly why, but I suspect
rcu_str_deref() is the point from where it is generated.

Note that the mount succeeds.

This code was introduced by:

	commit 672d599041c862dd61a1576c32e946ef0d77aa34
	Author: Misono Tomohiro <misono.tomohiro@jp.fujitsu.com>
	Date:   Thu Aug 2 16:19:07 2018 +0900

David
---
=============================
WARNING: suspicious RCU usage
4.18.0-fscache+ #540 Not tainted
-----------------------------
fs/btrfs/volumes.c:6114 suspicious rcu_dereference_check() usage!

other info that might help us debug this:


rcu_scheduler_active = 2, debug_locks = 1
1 lock held by mount/3194:
 #0: 0000000072604777 (&fc->fs_type->s_umount_key#54/1){+.+.}, at: alloc_super+0xa4/0x313

stack backtrace:
CPU: 2 PID: 3194 Comm: mount Not tainted 4.18.0-fscache+ #540
Hardware name: ASUS All Series/H97-PLUS, BIOS 2306 10/09/2014
Call Trace:
 dump_stack+0x67/0x8e
 btrfs_map_bio+0x282/0x321
 btree_submit_bio_hook+0x71/0xa6
 submit_one_bio+0x55/0x66
 read_extent_buffer_pages+0x1ec/0x2ab
 btree_read_extent_buffer_pages+0x6e/0x237
 ? alloc_extent_buffer+0x28f/0x2f2
 read_tree_block+0x43/0x5e
 open_ctree+0x139b/0x1ee4
 btrfs_get_tree+0x357/0xa33
 ? selinux_fs_context_dup+0x2d/0x104
 vfs_get_tree+0x7a/0x162
 btrfs_mount_root+0x52/0x8b
 btrfs_get_tree+0x4ab/0xa33
 ? vfs_parse_fs_string+0x5b/0x9e
 vfs_get_tree+0x7a/0x162
 do_mount+0x7f0/0x8b2
 ? memdup_user+0x3e/0x5a
 ksys_mount+0x72/0x97
 __x64_sys_mount+0x21/0x24
 do_syscall_64+0x7d/0x1a0
 entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x7f11b8365ada
Code: 48 8b 0d c9 a3 2b 00 f7 d8 64 89 01 48 83 c8 ff c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 49 89 ca b8 a5 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 96 a3 2b 00 f7 d8 64 89 01 48
RSP: 002b:00007ffe0d9a5b98 EFLAGS: 00000246 ORIG_RAX: 00000000000000a5
RAX: ffffffffffffffda RBX: 00005562bf7702a0 RCX: 00007f11b8365ada
RDX: 00005562bf77a620 RSI: 00005562bf7704a0 RDI: 00005562bf770480
RBP: 0000000000000000 R08: 0000000000000000 R09: 00007f11b8620c40
R10: 00000000c0ed0000 R11: 0000000000000246 R12: 00005562bf770480
R13: 00005562bf77a620 R14: 0000000000000000 R15: 00007f11b90f9184

Re: fs/btrfs/volumes.c:6114 suspicious rcu_dereference_check() usage!

[David Sterba]

On Thu, Aug 23, 2018 at 04:49:11PM +0100, David Howells wrote:
> I'm seeing the attached message generated from this line:
> 
> 	btrfs_debug_in_rcu(fs_info,
> 	"btrfs_map_bio: rw %d 0x%x, sector=%llu, dev=%lu (%s id %llu), size=%u",
> 		bio_op(bio), bio->bi_opf, (u64)bio->bi_iter.bi_sector,
> 		(u_long)dev->bdev->bd_dev, rcu_str_deref(dev->name), dev->devid,
> 		bio->bi_iter.bi_size);
> 
> in submit_stripe_bio().  I'm not sure exactly why, but I suspect
> rcu_str_deref() is the point from where it is generated.

Yes, the macro is rcu_dereference in disguise.

The code previously had explicit rcu_lock/unlock, now it uses the
btrfs_debug_in_rcu helper which is supposed to provide that. It's
possible that the helper is missing it due to some #ifdef mess, but I
don't see it.

Re: fs/btrfs/volumes.c:6114 suspicious rcu_dereference_check() usage!

[David Howells]

David Sterba <dsterba@suse.cz> wrote:

> The code previously had explicit rcu_lock/unlock, now it uses the
> btrfs_debug_in_rcu helper which is supposed to provide that. It's
> possible that the helper is missing it due to some #ifdef mess, but I
> don't see it.

I preprocessed the function and extracted submit_stripe_bio() (see attached).

The problem is that btrfs_no_printk() is being called, but not within an RCU
section.

#define btrfs_debug_in_rcu(fs_info, fmt, args...) \
	btrfs_printk_in_rcu(fs_info, KERN_DEBUG fmt, ##args)

David
---
static void submit_stripe_bio(struct btrfs_bio *bbio, struct bio *bio,
         u64 physical, int dev_nr, int async)
{
 struct btrfs_device *dev = bbio->stripes[dev_nr].dev;
 struct btrfs_fs_info *fs_info = bbio->fs_info;

 bio->bi_private = bbio;
 btrfs_io_bio(bio)->stripe_index = dev_nr;
 bio->bi_end_io = btrfs_end_bio;
 bio->bi_iter.bi_sector = physical >> 9;
 btrfs_no_printk(fs_info, "\001" "7" "btrfs_map_bio: rw %d 0x%x, sector=%llu, dev=%lu (%s id %llu), size=%u", ((bio)->bi_opf & ((1 << 8) - 1)), bio->bi_opf, (u64)bio->bi_iter.bi_sector, (u_long)dev->bdev->bd_dev, ({ struct rcu_string *__str = ({ typeof(*(dev->name)) *________p1 = (typeof(*(dev->name)) *)({ union { typeof((dev->name)) __val; char __c[1]; } __u; if (1) __read_once_size(&((dev->name)), __u.__c, sizeof((dev->name))); else __read_once_size_nocheck(&((dev->name)), __u.__c, sizeof((dev->name))); do { } while (0); __u.__val; }); do { static bool __attribute__ ((__section__(".data.unlikely"))) __warned; if (debug_lockdep_rcu_enabled() && !__warned && (!((0) || rcu_read_lock_held()))) { __warned = true; lockdep_rcu_suspicious(



                      "fs/btrfs/volumes.c"
# 6110 "../fs/btrfs/volumes.c"
 ,



                      6114
# 6110 "../fs/btrfs/volumes.c"
 , "suspicious rcu_dereference_check() usage"); } } while (0); ; ((typeof(*(dev->name)) *)(________p1)); }); __str->str; }), dev->devid, bio->bi_iter.bi_size)



                       ;
 do { if ((bio)->bi_disk != (dev->bdev)->bd_disk) bio_clear_flag(bio, 9); (bio)->bi_disk = (dev->bdev)->bd_disk; (bio)->bi_partno = (dev->bdev)->bd_partno; } while (0);

 btrfs_bio_counter_inc_noblocked(fs_info);

 if (async)
  btrfs_schedule_bio(dev, bio);
 else
  btrfsic_submit_bio(bio);
}

Re: fs/btrfs/volumes.c:6114 suspicious rcu_dereference_check() usage!

[Misono Tomohiro]

On 2018/08/24 0:49, David Howells wrote:
> I'm seeing the attached message generated from this line:
> 
> 	btrfs_debug_in_rcu(fs_info,
> 	"btrfs_map_bio: rw %d 0x%x, sector=%llu, dev=%lu (%s id %llu), size=%u",
> 		bio_op(bio), bio->bi_opf, (u64)bio->bi_iter.bi_sector,
> 		(u_long)dev->bdev->bd_dev, rcu_str_deref(dev->name), dev->devid,
> 		bio->bi_iter.bi_size);
> 
> in submit_stripe_bio().  I'm not sure exactly why, but I suspect
> rcu_str_deref() is the point from where it is generated.
> 
> Note that the mount succeeds.
> 
> This code was introduced by:
> 
> 	commit 672d599041c862dd61a1576c32e946ef0d77aa34
> 	Author: Misono Tomohiro <misono.tomohiro@jp.fujitsu.com>
> 	Date:   Thu Aug 2 16:19:07 2018 +0900
> 


Thanks for the reporting.
I didn't turn on CONFIG_PROVE_RCU and missed the warning.

I will send a fix.

Thanks,
Misono

> David
> ---
> =============================
> WARNING: suspicious RCU usage
> 4.18.0-fscache+ #540 Not tainted
> -----------------------------
> fs/btrfs/volumes.c:6114 suspicious rcu_dereference_check() usage!
> 
> other info that might help us debug this:
> 
> 
> rcu_scheduler_active = 2, debug_locks = 1
> 1 lock held by mount/3194:
>  #0: 0000000072604777 (&fc->fs_type->s_umount_key#54/1){+.+.}, at: alloc_super+0xa4/0x313
> 
> stack backtrace:
> CPU: 2 PID: 3194 Comm: mount Not tainted 4.18.0-fscache+ #540
> Hardware name: ASUS All Series/H97-PLUS, BIOS 2306 10/09/2014
> Call Trace:
>  dump_stack+0x67/0x8e
>  btrfs_map_bio+0x282/0x321
>  btree_submit_bio_hook+0x71/0xa6
>  submit_one_bio+0x55/0x66
>  read_extent_buffer_pages+0x1ec/0x2ab
>  btree_read_extent_buffer_pages+0x6e/0x237
>  ? alloc_extent_buffer+0x28f/0x2f2
>  read_tree_block+0x43/0x5e
>  open_ctree+0x139b/0x1ee4
>  btrfs_get_tree+0x357/0xa33
>  ? selinux_fs_context_dup+0x2d/0x104
>  vfs_get_tree+0x7a/0x162
>  btrfs_mount_root+0x52/0x8b
>  btrfs_get_tree+0x4ab/0xa33
>  ? vfs_parse_fs_string+0x5b/0x9e
>  vfs_get_tree+0x7a/0x162
>  do_mount+0x7f0/0x8b2
>  ? memdup_user+0x3e/0x5a
>  ksys_mount+0x72/0x97
>  __x64_sys_mount+0x21/0x24
>  do_syscall_64+0x7d/0x1a0
>  entry_SYSCALL_64_after_hwframe+0x49/0xbe
> RIP: 0033:0x7f11b8365ada
> Code: 48 8b 0d c9 a3 2b 00 f7 d8 64 89 01 48 83 c8 ff c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 49 89 ca b8 a5 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 96 a3 2b 00 f7 d8 64 89 01 48
> RSP: 002b:00007ffe0d9a5b98 EFLAGS: 00000246 ORIG_RAX: 00000000000000a5
> RAX: ffffffffffffffda RBX: 00005562bf7702a0 RCX: 00007f11b8365ada
> RDX: 00005562bf77a620 RSI: 00005562bf7704a0 RDI: 00005562bf770480
> RBP: 0000000000000000 R08: 0000000000000000 R09: 00007f11b8620c40
> R10: 00000000c0ed0000 R11: 0000000000000246 R12: 00005562bf770480
> R13: 00005562bf77a620 R14: 0000000000000000 R15: 00007f11b90f9184
> 
> 

[PATCH] btrfs: ctree.h: Fix suspicious rcu usage warning in btrfs_debug_in_rcu()

[Misono Tomohiro]

commit 672d599041c8 ("btrfs: Use wrapper macro for rcu string to remove
duplicate code") replaces some open coded rcu string handling with macro.

It turns out that btrfs_debug_in_rcu() is used for the first time and
the macro lacks lock/unlock of rcu string for non debug case
(i.e. when message is not printed), leading suspicious RCU usage warning
when CONFIG_PROVE_RCU is on.

Fix this by adding a wrapper to call lock/unlock for non debug case too.

Fixes: 672d599041c8 ("btrfs: Use wrapper macro for rcu string to remove
duplicate code")
Reported-by: David Howells <dhowells@redhat.com>
Signed-off-by: Misono Tomohiro <misono.tomohiro@jp.fujitsu.com>
---
 fs/btrfs/ctree.h | 11 +++++++++--
 1 file changed, 9 insertions(+), 2 deletions(-)

diff --git a/fs/btrfs/ctree.h b/fs/btrfs/ctree.h
index 53af9f5253f4..cc8b4ff8dcea 100644
--- a/fs/btrfs/ctree.h
+++ b/fs/btrfs/ctree.h
@@ -3390,9 +3390,9 @@ do {									\
 #define btrfs_debug(fs_info, fmt, args...) \
 	btrfs_no_printk(fs_info, KERN_DEBUG fmt, ##args)
 #define btrfs_debug_in_rcu(fs_info, fmt, args...) \
-	btrfs_no_printk(fs_info, KERN_DEBUG fmt, ##args)
+	btrfs_no_printk_in_rcu(fs_info, KERN_DEBUG fmt, ##args)
 #define btrfs_debug_rl_in_rcu(fs_info, fmt, args...) \
-	btrfs_no_printk(fs_info, KERN_DEBUG fmt, ##args)
+	btrfs_no_printk_in_rcu(fs_info, KERN_DEBUG fmt, ##args)
 #define btrfs_debug_rl(fs_info, fmt, args...) \
 	btrfs_no_printk(fs_info, KERN_DEBUG fmt, ##args)
 #endif
@@ -3404,6 +3404,13 @@ do {							\
 	rcu_read_unlock();				\
 } while (0)
 
+#define btrfs_no_printk_in_rcu(fs_info, fmt, args...)	\
+do {							\
+	rcu_read_lock();				\
+	btrfs_no_printk(fs_info, fmt, ##args);		\
+	rcu_read_unlock();				\
+} while (0)
+
 #define btrfs_printk_ratelimited(fs_info, fmt, args...)		\
 do {								\
 	static DEFINE_RATELIMIT_STATE(_rs,			\
-- 
2.14.4

Re: [PATCH] btrfs: ctree.h: Fix suspicious rcu usage warning in btrfs_debug_in_rcu()

[David Sterba]

On Fri, Aug 24, 2018 at 11:35:28AM +0900, Misono Tomohiro wrote:
> commit 672d599041c8 ("btrfs: Use wrapper macro for rcu string to remove
> duplicate code") replaces some open coded rcu string handling with macro.
> 
> It turns out that btrfs_debug_in_rcu() is used for the first time and
> the macro lacks lock/unlock of rcu string for non debug case
> (i.e. when message is not printed), leading suspicious RCU usage warning
> when CONFIG_PROVE_RCU is on.
> 
> Fix this by adding a wrapper to call lock/unlock for non debug case too.
> 
> Fixes: 672d599041c8 ("btrfs: Use wrapper macro for rcu string to remove
> duplicate code")
> Reported-by: David Howells <dhowells@redhat.com>
> Signed-off-by: Misono Tomohiro <misono.tomohiro@jp.fujitsu.com>

Reviewed-by: David Sterba <dsterba@suse.com>

Thanks, I'll add it to the 4.19 queue, expected to appear in rc2.

Re: [PATCH] btrfs: ctree.h: Fix suspicious rcu usage warning in btrfs_debug_in_rcu()

[David Howells]

Misono Tomohiro <misono.tomohiro@jp.fujitsu.com> wrote:

> commit 672d599041c8 ("btrfs: Use wrapper macro for rcu string to remove
> duplicate code") replaces some open coded rcu string handling with macro.
> 
> It turns out that btrfs_debug_in_rcu() is used for the first time and
> the macro lacks lock/unlock of rcu string for non debug case
> (i.e. when message is not printed), leading suspicious RCU usage warning
> when CONFIG_PROVE_RCU is on.
> 
> Fix this by adding a wrapper to call lock/unlock for non debug case too.
> 
> Fixes: 672d599041c8 ("btrfs: Use wrapper macro for rcu string to remove
> duplicate code")
> Reported-by: David Howells <dhowells@redhat.com>
> Signed-off-by: Misono Tomohiro <misono.tomohiro@jp.fujitsu.com>

Tested-by: David Howells <dhowells@redhat.com>