KCSAN BUG report on p9_client_cb / p9_client_rpc

KCSAN BUG report on p9_client_cb / p9_client_rpc

[jim.cromie]

I got this on rc7 + my hacks ( not near p9 )
ISTM someone here will know what it means.
If theres anything else i can do to help,
(configs, drop my patches and retry)
 please let me know



[   14.904783] ==================================================================
[   14.905848] BUG: KCSAN: data-race in p9_client_cb / p9_client_rpc
[   14.906769]
[   14.907040] write to 0xffff888005eb0360 of 4 bytes by interrupt on cpu 0:
[   14.907989]  p9_client_cb+0x1a/0x100
[   14.908485]  req_done+0xd3/0x130
[   14.908931]  vring_interrupt+0xac/0x130
[   14.909460]  __handle_irq_event_percpu+0x64/0x260
[   14.910095]  handle_irq_event+0x93/0x120
[   14.910637]  handle_edge_irq+0x123/0x400
[   14.911156]  __common_interrupt+0x3e/0xa0
[   14.911723]  common_interrupt+0x7e/0xa0
[   14.912270]  asm_common_interrupt+0x1e/0x40
[   14.912816]  native_safe_halt+0xe/0x10
[   14.913350]  default_idle+0xa/0x10
[   14.913801]  default_idle_call+0x38/0xc0
[   14.914361]  do_idle+0x1e7/0x270
[   14.914840]  cpu_startup_entry+0x19/0x20
[   14.915436]  rest_init+0xd0/0xd2
[   14.915878]  arch_call_rest_init+0xa/0x11
[   14.916428]  start_kernel+0xacb/0xadd
[   14.916927]  secondary_startup_64_no_verify+0xc2/0xcb
[   14.917613]
[   14.917819] read to 0xffff888005eb0360 of 4 bytes by task 261 on cpu 1:
[   14.918764]  p9_client_rpc+0x1cf/0x860
[   14.919340]  p9_client_walk+0xcf/0x350
[   14.919857]  v9fs_file_open+0x16c/0x340
[   14.920411]  do_dentry_open+0x298/0x6a0
[   14.920980]  vfs_open+0x58/0x60
[   14.921475]  path_openat+0x1130/0x1860
[   14.922126]  do_filp_open+0x116/0x1f0
[   14.922731]  do_sys_openat2+0x91/0x190
[   14.923267]  __x64_sys_openat+0x9b/0xd0
[   14.923790]  do_syscall_64+0x42/0x80
[   14.924295]  entry_SYSCALL_64_after_hwframe+0x44/0xae
[   14.924955]
[   14.925159] Reported by Kernel Concurrency Sanitizer on:
[   14.925899] CPU: 1 PID: 261 Comm: ip Not tainted
5.13.0-rc7-dd7i-00036-gb82eaba47adf-dirty #121
[   14.927094] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996),
BIOS 1.14.0-3.fc34 04/01/2014
[   14.928292] ==================================================================
virtme-init: console is ttyS0

Re: [V9fs-developer] KCSAN BUG report on p9_client_cb / p9_client_rpc

[Dominique Martinet]

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

jim.cromie@gmail.com wrote on Tue, Jun 22, 2021 at 10:42:58AM -0600:
> I got this on rc7 + my hacks ( not near p9 )
> ISTM someone here will know what it means.
> If theres anything else i can do to help,
> (configs, drop my patches and retry)
>  please let me know

Thanks for the report!

> [   14.904783] ==================================================================
> [   14.905848] BUG: KCSAN: data-race in p9_client_cb / p9_client_rpc

hm, this code hasn't changed in ages (unless someone merged code behind
my back :D)

I had assumed the p9_req_put() in p9_client_cb would protect the tag,
but that doesn't appear to be true -- could you try this patch if this
is reproductible to you?

The tag is actually reclaimed in the woken up p9_client_rpc thread so
that would be a good match (reset in the other thread vs. read here),
caching the value is good enough but that is definitely not obvious...

-- 
Dominique

[-- Attachment #2: 0001-9p-net-cache-tag-in-p9_client_cb.patch --]
[-- Type: text/plain, Size: 1396 bytes --]

From 1135d60baa5d743e8a123812428a342b101e290e Mon Sep 17 00:00:00 2001
From: Dominique Martinet <asmadeus@codewreck.org>
Date: Wed, 23 Jun 2021 02:12:20 +0900
Subject: [PATCH] 9p net: cache tag in p9_client_cb

req->tc.tag is not safe to access after status has been set,
because tag is reclaimed by p9_client_rpc and not by the p9_req_put
below as one might think.

Reported-by: jim.cromie@gmail.com
Signed-off-by: Dominique Martinet <asmadeus@codewreck.org>
---
 net/9p/client.c | 6 ++++--
 1 file changed, 4 insertions(+), 2 deletions(-)

diff --git a/net/9p/client.c b/net/9p/client.c
index b7b958f61faf..3e95a56ead80 100644
--- a/net/9p/client.c
+++ b/net/9p/client.c
@@ -419,7 +419,8 @@ static void p9_tag_cleanup(struct p9_client *c)
  */
 void p9_client_cb(struct p9_client *c, struct p9_req_t *req, int status)
 {
-	p9_debug(P9_DEBUG_MUX, " tag %d\n", req->tc.tag);
+	u16 tag = req->tc.tag;
+	p9_debug(P9_DEBUG_MUX, " tag %d\n", tag);
 
 	/*
 	 * This barrier is needed to make sure any change made to req before
@@ -429,7 +430,8 @@ void p9_client_cb(struct p9_client *c, struct p9_req_t *req, int status)
 	req->status = status;
 
 	wake_up(&req->wq);
-	p9_debug(P9_DEBUG_MUX, "wakeup: %d\n", req->tc.tag);
+	/* req->tc.tag is not safe to access after status has been set */
+	p9_debug(P9_DEBUG_MUX, "wakeup: %d\n", tag);
 	p9_req_put(req);
 }
 EXPORT_SYMBOL(p9_client_cb);
-- 
2.31.1

Re: [V9fs-developer] KCSAN BUG report on p9_client_cb / p9_client_rpc

[jim.cromie]

On Tue, Jun 22, 2021 at 11:13 AM Dominique Martinet
<asmadeus@codewreck.org> wrote:
>
> jim.cromie@gmail.com wrote on Tue, Jun 22, 2021 at 10:42:58AM -0600:
> > I got this on rc7 + my hacks ( not near p9 )
> > ISTM someone here will know what it means.
> > If theres anything else i can do to help,
> > (configs, drop my patches and retry)
> >  please let me know
>
> Thanks for the report!
>
> > [   14.904783] ==================================================================
> > [   14.905848] BUG: KCSAN: data-race in p9_client_cb / p9_client_rpc
>
> hm, this code hasn't changed in ages (unless someone merged code behind
> my back :D)
>
> I had assumed the p9_req_put() in p9_client_cb would protect the tag,
> but that doesn't appear to be true -- could you try this patch if this
> is reproductible to you?
>

I applied your patch on top of my triggering case, it fixes the report  !
you have my tested-by

> The tag is actually reclaimed in the woken up p9_client_rpc thread so
> that would be a good match (reset in the other thread vs. read here),
> caching the value is good enough but that is definitely not obvious...
>
> --
> Dominique

Re: [V9fs-developer] KCSAN BUG report on p9_client_cb / p9_client_rpc

[jim.cromie]

 >
> > I had assumed the p9_req_put() in p9_client_cb would protect the tag,
> > but that doesn't appear to be true -- could you try this patch if this
> > is reproductible to you?
> >
>
> I applied your patch on top of my triggering case, it fixes the report  !
> you have my tested-by

I seem to have gotten ahead of my skis,
Im seeing another now, similar to 1st, differing in 2nd block

[    8.730061] Run /bin/sh as init process
[    9.027218] ==================================================================
[    9.028237] BUG: KCSAN: data-race in p9_client_cb / p9_client_rpc
[    9.029073]
[    9.029282] write to 0xffff888005e45ea0 of 4 bytes by interrupt on cpu 0:
[    9.030214]  p9_client_cb+0x1a/0x100
[    9.030735]  req_done+0xd3/0x130
[    9.031171]  vring_interrupt+0xac/0x130
[    9.031752]  __handle_irq_event_percpu+0x64/0x260
[    9.032381]  handle_irq_event+0x93/0x120
[    9.032950]  handle_edge_irq+0x123/0x400
[    9.033502]  __common_interrupt+0x3e/0xa0
[    9.034051]  common_interrupt+0x7e/0xa0
[    9.034608]  asm_common_interrupt+0x1e/0x40
[    9.035173]  native_safe_halt+0xe/0x10
[    9.035826]  default_idle+0xa/0x10
[    9.036299]  default_idle_call+0x38/0xc0
[    9.036845]  do_idle+0x1e7/0x270
[    9.037294]  cpu_startup_entry+0x19/0x20
[    9.037905]  rest_init+0xd0/0xd2
[    9.038354]  arch_call_rest_init+0xa/0x11
[    9.038922]  start_kernel+0xacb/0xadd
[    9.039444]  secondary_startup_64_no_verify+0xc2/0xcb
[    9.040140]
[    9.040369] read to 0xffff888005e45ea0 of 4 bytes by task 1 on cpu 1:
[    9.041283]  p9_client_rpc+0x185/0x860
[    9.041837]  p9_client_getattr_dotl+0x71/0x160
[    9.042645]  v9fs_inode_from_fid_dotl+0x21/0x160
[    9.043418]  v9fs_vfs_lookup.part.0+0x139/0x180
[    9.044059]  v9fs_vfs_lookup+0x32/0x40
[    9.044584]  __lookup_slow+0xc3/0x190
[    9.045095]  walk_component+0x1b8/0x270
[    9.045626]  link_path_walk.part.0.constprop.0+0x336/0x550
[    9.046425]  path_lookupat+0x59/0x340
[    9.046935]  filename_lookup+0x134/0x2a0
[    9.047484]  user_path_at_empty+0x6d/0x90
[    9.048145]  vfs_statx+0x79/0x1a0
[    9.048610]  __do_sys_newfstatat+0x1e/0x40
[    9.049173]  __x64_sys_newfstatat+0x4e/0x60
[    9.049755]  do_syscall_64+0x42/0x80
[    9.050233]  entry_SYSCALL_64_after_hwframe+0x44/0xae
[    9.050940]
[    9.051148] Reported by Kernel Concurrency Sanitizer on:
[    9.051893] CPU: 1 PID: 1 Comm: virtme-init Not tainted
5.13.0-rc7-dd7i-00038-g4e27591489f1-dirty #126
[    9.053185] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996),
BIOS 1.14.0-3.fc34 04/01/2014
[    9.054358] ==================================================================




>
> > The tag is actually reclaimed in the woken up p9_client_rpc thread so
> > that would be a good match (reset in the other thread vs. read here),
> > caching the value is good enough but that is definitely not obvious...
> >
> > --
> > Dominique

Re: [V9fs-developer] KCSAN BUG report on p9_client_cb / p9_client_rpc

[Dominique Martinet]

Hi,

let's keep the lists in Cc :)

jim.cromie@gmail.com wrote on Tue, Jun 22, 2021 at 02:55:19PM -0600:
> heres a fuller report - Im seeing some new stuff here.

Thanks, the one two should be the same as p9_client_cb / p9_client_rpc
and p9_client_cb / p9_virtio_zc_request are very similar, and also the
same to the first you had, so the patch didn't really work.

I thought after sending it that it probably needs to be tag =
READ_ONCE(req->tc.tag) instead of just assigning it... Would you mind
trying that?

> Im running in a vm, using virtme, which uses 9p to share host filesystems
> since 1st report to you, Ive added --smp 2 to my testing, it seems to
> have increased reporting

I'm ashamed to say I've just never tried KCSAN... I can give it a try over
the next few weeks* if that patch + READ_ONCE doesn't cut it

(*sorry)

Thanks,
-- 
Dominique

Re: [V9fs-developer] KCSAN BUG report on p9_client_cb / p9_client_rpc

[jim.cromie]

On Tue, Jun 22, 2021 at 3:03 PM Dominique Martinet
<asmadeus@codewreck.org> wrote:
>
> Hi,
>
> let's keep the lists in Cc :)
>
> jim.cromie@gmail.com wrote on Tue, Jun 22, 2021 at 02:55:19PM -0600:
> > heres a fuller report - Im seeing some new stuff here.
>
> Thanks, the one two should be the same as p9_client_cb / p9_client_rpc
> and p9_client_cb / p9_virtio_zc_request are very similar, and also the
> same to the first you had, so the patch didn't really work.
>
> I thought after sending it that it probably needs to be tag =
> READ_ONCE(req->tc.tag) instead of just assigning it... Would you mind
> trying that?
>

I tried it, still getting the reports.
I havent replicated it on a nearby work-tree
and I tried bisecting on the problem work-tree,
got past all my patches and problem remained.
So everything is suspect ...
I'll try to narrow things down.

heres the latest report, for the list

qemu-system-x86_64: warning: 9p: degraded performance: a reasonable
high msize should be chosen on client/guest side (chosen msize is <=
8192). See https://wiki.qemu.org/Documentation/9psetup#msize for
details.
[    8.566576] VFS: Mounted root (9p filesystem) readonly on device 0:22.
qemu-system-x86_64: warning: 9p: Multiple devices detected in same
VirtFS export, which might lead to file ID collisions and severe
misbehaviours on guest! You should either use a separate export for
each device shared from host or use virtfs option 'multidevs=remap'!
[    8.573452] devtmpfs: mounted
[    8.585150] Freeing unused decrypted memory: 2036K
[    8.589527] Freeing unused kernel image (initmem) memory: 3092K
[    8.591756] Write protecting the kernel read-only data: 30720k
[    8.601183] Freeing unused kernel image (text/rodata gap) memory: 2032K
[    8.604040] Freeing unused kernel image (rodata/data gap) memory: 440K
[    8.787167] x86/mm: Checked W+X mappings: passed, no W+X pages found.
[    8.788573] rodata_test: all tests were successful
[    8.789531] x86/mm: Checking user space page tables
[    8.968680] x86/mm: Checked W+X mappings: passed, no W+X pages found.
[    8.969933] Run /bin/sh as init process
[    9.537655] ==================================================================
[    9.538731] BUG: KCSAN: data-race in p9_client_cb / p9_virtio_zc_request
[    9.539873]
[    9.540113] write to 0xffff888005e5d000 of 4 bytes by interrupt on cpu 0:
[    9.541192]  p9_client_cb+0x27/0x110
[    9.541858]  req_done+0xd3/0x130
[    9.542482]  vring_interrupt+0xac/0x130
[    9.543171]  __handle_irq_event_percpu+0x64/0x260
[    9.544042]  handle_irq_event+0x93/0x120
[    9.544717]  handle_edge_irq+0x123/0x400
[    9.545429]  __common_interrupt+0x3e/0xa0
[    9.546001]  common_interrupt+0x7e/0xa0
[    9.546518]  asm_common_interrupt+0x1e/0x40
[    9.547127]  native_safe_halt+0xe/0x10
[    9.547846]  default_idle+0xa/0x10
[    9.548348]  default_idle_call+0x38/0xc0
[    9.548991]  do_idle+0x1e7/0x270
[    9.549548]  cpu_startup_entry+0x19/0x20
[    9.550180]  rest_init+0xd0/0xd2
[    9.550740]  arch_call_rest_init+0xa/0x11
[    9.551493]  start_kernel+0xacb/0xadd
[    9.552035]  secondary_startup_64_no_verify+0xc2/0xcb
[    9.552739]
[    9.552954] read to 0xffff888005e5d000 of 4 bytes by task 185 on cpu 1:
[    9.553986]  p9_virtio_zc_request+0x449/0x7b0
[    9.554586]  p9_client_zc_rpc.constprop.0+0x175/0x770
[    9.555421]  p9_client_read_once+0x24d/0x330
[    9.556013]  p9_client_read+0x81/0xa0
[    9.556518]  v9fs_fid_readpage+0xca/0x310
[    9.557084]  v9fs_vfs_readpage+0x28/0x30
[    9.557785]  filemap_read_page+0x6e/0x1a0
[    9.558337]  filemap_fault+0xc2a/0x1010
[    9.558874]  __do_fault+0x76/0x210
[    9.559343]  __handle_mm_fault+0x16fe/0x2010
[    9.559934]  handle_mm_fault+0x129/0x410
[    9.560472]  do_user_addr_fault+0x1b7/0x670
[    9.561052]  exc_page_fault+0x78/0x160
[    9.561569]  asm_exc_page_fault+0x1e/0x30
[    9.562122]
[    9.562336] Reported by Kernel Concurrency Sanitizer on:
[    9.563054] CPU: 1 PID: 185 Comm: mount Not tainted
5.13.0-rc7-dd7i-00040-g07a2fabfd89c-dirty #131
[    9.564368] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996),
BIOS 1.14.0-3.fc34 04/01/2014
[    9.565543] ==================================================================
[    9.842861] virtme-init: basic initialization done
[    9.870984] virtme-init: running systemd-tmpfiles
[   10.371613] ==================================================================
[   10.372752] BUG: KCSAN: data-race in p9_client_cb / p9_client_rpc
[   10.373617]
[   10.373832] write to 0xffff888005e5d000 of 4 bytes by interrupt on cpu 0:
[   10.374753]  p9_client_cb+0x27/0x110
[   10.375252]  req_done+0xd3/0x130
[   10.375749]  vring_interrupt+0xac/0x130
[   10.376282]  __handle_irq_event_percpu+0x64/0x260
[   10.376927]  handle_irq_event+0x93/0x120
[   10.377465]  handle_edge_irq+0x123/0x400
[   10.378035]  __common_interrupt+0x3e/0xa0
[   10.378611]  common_interrupt+0x7e/0xa0
[   10.379126]  asm_common_interrupt+0x1e/0x40
[   10.379720]  native_safe_halt+0xe/0x10
[   10.380271]  default_idle+0xa/0x10
[   10.380770]  default_idle_call+0x38/0xc0
[   10.381328]  do_idle+0x1e7/0x270
[   10.381835]  cpu_startup_entry+0x19/0x20
[   10.382358]  rest_init+0xd0/0xd2
[   10.382832]  arch_call_rest_init+0xa/0x11
[   10.383414]  start_kernel+0xacb/0xadd
[   10.383944]  secondary_startup_64_no_verify+0xc2/0xcb
[   10.384660]
[   10.384869] read to 0xffff888005e5d000 of 4 bytes by task 194 on cpu 1:
[   10.385832]  p9_client_rpc+0x1cf/0x860
[   10.386398]  p9_client_readlink+0x3b/0x110
[   10.386972]  v9fs_vfs_get_link_dotl+0x37/0x80
[   10.387568]  step_into+0xa7c/0xb60
[   10.388042]  walk_component+0x8a/0x270
[   10.388558]  path_lookupat+0xca/0x340
[   10.389065]  filename_lookup+0x134/0x2a0
[   10.389628]  user_path_at_empty+0x6d/0x90
[   10.390187]  vfs_statx+0x79/0x1a0
[   10.390681]  __do_sys_newfstatat+0x1e/0x40
[   10.391237]  __x64_sys_newfstatat+0x4e/0x60
[   10.391845]  do_syscall_64+0x42/0x80
[   10.392373]  entry_SYSCALL_64_after_hwframe+0x44/0xae
[   10.393082]
[   10.393310] Reported by Kernel Concurrency Sanitizer on:
[   10.394106] CPU: 1 PID: 194 Comm: systemd-tmpfile Not tainted
5.13.0-rc7-dd7i-00040-g07a2fabfd89c-dirty #131
[   10.395779] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996),
BIOS 1.14.0-3.fc34 04/01/2014
[   10.397131] ==================================================================
Failed to create directory or subvolume "/var/spool/cups/tmp": Permission denied

[   10.720448] virtme-init: starting udevd
[   10.784768] ==================================================================
[   10.785855] BUG: KCSAN: data-race in p9_client_cb / p9_client_rpc
[   10.786937]
[   10.787152] write to 0xffff888005e5d000 of 4 bytes by interrupt on cpu 0:
[   10.788185]  p9_client_cb+0x27/0x110
[   10.788687]  req_done+0xd3/0x130
[   10.789133]  vring_interrupt+0xac/0x130
[   10.789669]  __handle_irq_event_percpu+0x64/0x260
[   10.790306]  handle_irq_event+0x93/0x120
[   10.790845]  handle_edge_irq+0x123/0x400
[   10.791384]  __common_interrupt+0x3e/0xa0
[   10.791933]  common_interrupt+0x7e/0xa0
[   10.792460]  asm_common_interrupt+0x1e/0x40
[   10.793052]  native_safe_halt+0xe/0x10
[   10.793674]  default_idle+0xa/0x10
[   10.794293]  default_idle_call+0x38/0xc0
[   10.794914]  do_idle+0x1e7/0x270
[   10.795366]  cpu_startup_entry+0x19/0x20
[   10.795909]  rest_init+0xd0/0xd2
[   10.796353]  arch_call_rest_init+0xa/0x11
[   10.796911]  start_kernel+0xacb/0xadd
[   10.797459]  secondary_startup_64_no_verify+0xc2/0xcb
[   10.798153]
[   10.798367] read to 0xffff888005e5d000 of 4 bytes by task 196 on cpu 1:
[   10.799256]  p9_client_rpc+0x185/0x860
[   10.799776]  p9_client_clunk+0x99/0x150
[   10.800300]  v9fs_dentry_release+0x38/0x60
[   10.800863]  __dentry_kill+0x203/0x2b0
[   10.801374]  dput+0x217/0x480
[   10.801788]  path_openat+0x803/0x1860
[   10.802573]  do_filp_open+0x116/0x1f0
[   10.803322]  do_sys_openat2+0x91/0x190
[   10.804215]  __x64_sys_openat+0x9b/0xd0
[   10.805003]  do_syscall_64+0x42/0x80
[   10.805838]  entry_SYSCALL_64_after_hwframe+0x44/0xae
[   10.806854]
[   10.807226] Reported by Kernel Concurrency Sanitizer on:
[   10.808460] CPU: 1 PID: 196 Comm: systemd-udevd Not tainted
5.13.0-rc7-dd7i-00040-g07a2fabfd89c-dirty #131
[   10.810544] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996),
BIOS 1.14.0-3.fc34 04/01/2014
[   10.812337] ==================================================================
...
[   12.579025] ==================================================================
[   12.580064] BUG: KCSAN: data-race in p9_client_cb / p9_virtio_zc_request
[   12.580978]
[   12.581193] write to 0xffff888005e5d900 of 4 bytes by interrupt on cpu 0:
[   12.582107]  p9_client_cb+0x27/0x110
[   12.582647]  req_done+0xd3/0x130
[   12.583080]  vring_interrupt+0xac/0x130
[   12.583632]  __handle_irq_event_percpu+0x64/0x260
[   12.584335]  handle_irq_event+0x93/0x120
[   12.584899]  handle_edge_irq+0x123/0x400
[   12.585456]  __common_interrupt+0x3e/0xa0
[   12.586028]  common_interrupt+0x43/0xa0
[   12.586537]  asm_common_interrupt+0x1e/0x40
[   12.587179]
[   12.587387] read to 0xffff888005e5d900 of 4 bytes by task 238 on cpu 1:
[   12.588322]  p9_virtio_zc_request+0x449/0x7b0
[   12.588942]  p9_client_zc_rpc.constprop.0+0x175/0x770
[   12.589645]  p9_client_read_once+0x24d/0x330
[   12.590417]  p9_client_read+0x81/0xa0
[   12.590946]  v9fs_fid_readpage+0xca/0x310
[   12.591712]  v9fs_vfs_readpage+0x28/0x30
[   12.592470]  filemap_read_page+0x6e/0x1a0
[   12.593218]  filemap_fault+0xc2a/0x1010
[   12.593922]  __do_fault+0x76/0x210
[   12.594590]  __handle_mm_fault+0x16fe/0x2010
[   12.595219]  handle_mm_fault+0x129/0x410
[   12.596017]  do_user_addr_fault+0x1b7/0x670
[   12.596902]  exc_page_fault+0x78/0x160
[   12.597449]  asm_exc_page_fault+0x1e/0x30
[   12.597999]
[   12.598212] Reported by Kernel Concurrency Sanitizer on:
[   12.598927] CPU: 1 PID: 238 Comm: modprobe Not tainted
5.13.0-rc7-dd7i-00040-g07a2fabfd89c-dirty #131
[   12.600153] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996),
BIOS 1.14.0-3.fc34 04/01/2014
[   12.601318] ==================================================================
...
[   12.861485] ==================================================================
[   12.862516] BUG: KCSAN: data-race in virtqueue_get_buf_ctx_split+0x62/0x250
[   12.863531]
[   12.863796] race at unknown origin, with read to 0xffff888005dcb942
of 2 bytes by interrupt on cpu 0:
[   12.865289]  virtqueue_get_buf_ctx_split+0x62/0x250
[   12.866190]  virtqueue_get_buf+0x33/0x40
[   12.866890]  req_done+0x6c/0x130
[   12.867376]  vring_interrupt+0xac/0x130
[   12.867913]  __handle_irq_event_percpu+0x64/0x260
[   12.868559]  handle_irq_event+0x93/0x120
[   12.869109]  handle_edge_irq+0x123/0x400
[   12.869663]  __common_interrupt+0x3e/0xa0
[   12.870213]  common_interrupt+0x7e/0xa0
[   12.870840]  asm_common_interrupt+0x1e/0x40
[   12.871444]  native_safe_halt+0xe/0x10
[   12.872046]  default_idle+0xa/0x10
[   12.872628]  default_idle_call+0x38/0xc0
[   12.873214]  do_idle+0x1e7/0x270
[   12.873756]  cpu_startup_entry+0x19/0x20
[   12.874301]  rest_init+0xd0/0xd2
[   12.874855]  arch_call_rest_init+0xa/0x11
[   12.875418]  start_kernel+0xacb/0xadd
[   12.875950]  secondary_startup_64_no_verify+0xc2/0xcb
[   12.876683]
[   12.876893] Reported by Kernel Concurrency Sanitizer on:
[   12.877630] CPU: 0 PID: 0 Comm: swapper/0 Not tainted
5.13.0-rc7-dd7i-00040-g07a2fabfd89c-dirty #131
[   12.878962] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996),
BIOS 1.14.0-3.fc34 04/01/2014

> > Im running in a vm, using virtme, which uses 9p to share host filesystems
> > since 1st report to you, Ive added --smp 2 to my testing, it seems to
> > have increased reporting
>
> I'm ashamed to say I've just never tried KCSAN... I can give it a try over
> the next few weeks* if that patch + READ_ONCE doesn't cut it
>
> (*sorry)
>
> Thanks,
> --
> Dominique

Re: [V9fs-developer] KCSAN BUG report on p9_client_cb / p9_client_rpc

[Marco Elver]

On Tue, 22 Jun 2021 at 23:03, Dominique Martinet <asmadeus@codewreck.org> wrote:

> jim.cromie@gmail.com wrote on Tue, Jun 22, 2021 at 02:55:19PM -0600:
> > heres a fuller report - Im seeing some new stuff here.

There are lots of known data races. A non-exhaustive list can be seen
here: https://syzkaller.appspot.com/upstream?manager=ci2-upstream-kcsan-gce

> Thanks, the one two should be the same as p9_client_cb / p9_client_rpc
> and p9_client_cb / p9_virtio_zc_request are very similar, and also the
> same to the first you had, so the patch didn't really work.
>
> I thought after sending it that it probably needs to be tag =
> READ_ONCE(req->tc.tag) instead of just assigning it... Would you mind
> trying that?
>
> > Im running in a vm, using virtme, which uses 9p to share host filesystems
> > since 1st report to you, Ive added --smp 2 to my testing, it seems to
> > have increased reporting
>
> I'm ashamed to say I've just never tried KCSAN... I can give it a try over
> the next few weeks* if that patch + READ_ONCE doesn't cut it

In case it helps, we have this LWN article series:
https://lwn.net/Articles/816850/

Paul McKenney also kindly wrote a summary of some parts of it:
https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tree/tools/memory-model/Documentation/access-marking.txt

There are some upcoming changes to KCSAN that can help filter some
data races that aren't too interesting today -- see linux-next and set
CONFIG_KCSAN_PERMISSIVE=y (the opposite of that is
CONFIG_KCSAN_STRICT=y, but not recommended at this time unless you're
writing complex concurrent code).

Thanks,
-- Marco