[syzbot] [afs?] [net?] KCSAN: data-race in rxrpc_send_data / rxrpc_set_call_completion

[syzbot] [afs?] [net?] KCSAN: data-race in rxrpc_send_data / rxrpc_set_call_completion

[syzbot]

Hello,

syzbot found the following issue on:

HEAD commit:    148341f0a2f5 Merge tag 'vfs.misc.fixes.v6.3-rc6' of git://..
git tree:       upstream
console output: https://syzkaller.appspot.com/x/log.txt?x=14a62269c80000
kernel config:  https://syzkaller.appspot.com/x/.config?x=54d63ee086ae78d0
dashboard link: https://syzkaller.appspot.com/bug?extid=ebc945fdb4acd72cba78
compiler:       Debian clang version 15.0.7, GNU ld (GNU Binutils for Debian) 2.35.2

Unfortunately, I don't have any reproducer for this issue yet.

Downloadable assets:
disk image: https://storage.googleapis.com/syzbot-assets/1c557f92a6e1/disk-148341f0.raw.xz
vmlinux: https://storage.googleapis.com/syzbot-assets/f2c85210e1ce/vmlinux-148341f0.xz
kernel image: https://storage.googleapis.com/syzbot-assets/b019d0447709/bzImage-148341f0.xz

IMPORTANT: if you fix the issue, please add the following tag to the commit:
Reported-by: syzbot+ebc945fdb4acd72cba78@syzkaller.appspotmail.com

==================================================================
BUG: KCSAN: data-race in rxrpc_send_data / rxrpc_set_call_completion

write to 0xffff888159cf3c50 of 4 bytes by task 25673 on cpu 1:
 rxrpc_set_call_completion+0x71/0x1c0 net/rxrpc/call_state.c:22
 rxrpc_send_data_packet+0xba9/0x1650 net/rxrpc/output.c:479
 rxrpc_transmit_one+0x1e/0x130 net/rxrpc/output.c:714
 rxrpc_decant_prepared_tx net/rxrpc/call_event.c:326 [inline]
 rxrpc_transmit_some_data+0x496/0x600 net/rxrpc/call_event.c:350
 rxrpc_input_call_event+0x564/0x1220 net/rxrpc/call_event.c:464
 rxrpc_io_thread+0x307/0x1d80 net/rxrpc/io_thread.c:461
 kthread+0x1ac/0x1e0 kernel/kthread.c:376
 ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:308

read to 0xffff888159cf3c50 of 4 bytes by task 25672 on cpu 0:
 rxrpc_send_data+0x29e/0x1950 net/rxrpc/sendmsg.c:296
 rxrpc_do_sendmsg+0xb7a/0xc20 net/rxrpc/sendmsg.c:726
 rxrpc_sendmsg+0x413/0x520 net/rxrpc/af_rxrpc.c:565
 sock_sendmsg_nosec net/socket.c:724 [inline]
 sock_sendmsg net/socket.c:747 [inline]
 ____sys_sendmsg+0x375/0x4c0 net/socket.c:2501
 ___sys_sendmsg net/socket.c:2555 [inline]
 __sys_sendmmsg+0x263/0x500 net/socket.c:2641
 __do_sys_sendmmsg net/socket.c:2670 [inline]
 __se_sys_sendmmsg net/socket.c:2667 [inline]
 __x64_sys_sendmmsg+0x57/0x60 net/socket.c:2667
 do_syscall_x64 arch/x86/entry/common.c:50 [inline]
 do_syscall_64+0x41/0xc0 arch/x86/entry/common.c:80
 entry_SYSCALL_64_after_hwframe+0x63/0xcd

value changed: 0x00000000 -> 0xffffffea

Reported by Kernel Concurrency Sanitizer on:
CPU: 0 PID: 25672 Comm: syz-executor.5 Not tainted 6.3.0-rc5-syzkaller-00005-g148341f0a2f5 #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 03/02/2023
==================================================================


---
This report is generated by a bot. It may contain errors.
See https://goo.gl/tpsmEJ for more information about syzbot.
syzbot engineers can be reached at syzkaller@googlegroups.com.

syzbot will keep track of this issue. See:
https://goo.gl/tpsmEJ#status for how to communicate with syzbot.

Re: [syzbot] [afs?] [net?] KCSAN: data-race in rxrpc_send_data / rxrpc_set_call_completion

[Dmitry Vyukov]

On Mon, 24 Apr 2023 at 10:17, syzbot
<syzbot+ebc945fdb4acd72cba78@syzkaller.appspotmail.com> wrote:
>
> Hello,
>
> syzbot found the following issue on:
>
> HEAD commit:    148341f0a2f5 Merge tag 'vfs.misc.fixes.v6.3-rc6' of git://..
> git tree:       upstream
> console output: https://syzkaller.appspot.com/x/log.txt?x=14a62269c80000
> kernel config:  https://syzkaller.appspot.com/x/.config?x=54d63ee086ae78d0
> dashboard link: https://syzkaller.appspot.com/bug?extid=ebc945fdb4acd72cba78
> compiler:       Debian clang version 15.0.7, GNU ld (GNU Binutils for Debian) 2.35.2
>
> Unfortunately, I don't have any reproducer for this issue yet.
>
> Downloadable assets:
> disk image: https://storage.googleapis.com/syzbot-assets/1c557f92a6e1/disk-148341f0.raw.xz
> vmlinux: https://storage.googleapis.com/syzbot-assets/f2c85210e1ce/vmlinux-148341f0.xz
> kernel image: https://storage.googleapis.com/syzbot-assets/b019d0447709/bzImage-148341f0.xz
>
> IMPORTANT: if you fix the issue, please add the following tag to the commit:
> Reported-by: syzbot+ebc945fdb4acd72cba78@syzkaller.appspotmail.com

If I am reading this correctly, rxrpc_send_data() can read wrong
call->completion and state and incorrectly exit with an error if
rxrpc_wait_to_be_connected() exists early right after observing error
set here:
https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tree/net/rxrpc/sendmsg.c?id=148341f0a2f53b5e8808d093333d85170586a15d#n58
The code seems to assume that at that point all writes done by
rxrpc_set_call_completion() are already finished, but it's not
necessarily the case.






> ==================================================================
> BUG: KCSAN: data-race in rxrpc_send_data / rxrpc_set_call_completion
>
> write to 0xffff888159cf3c50 of 4 bytes by task 25673 on cpu 1:
>  rxrpc_set_call_completion+0x71/0x1c0 net/rxrpc/call_state.c:22
>  rxrpc_send_data_packet+0xba9/0x1650 net/rxrpc/output.c:479
>  rxrpc_transmit_one+0x1e/0x130 net/rxrpc/output.c:714
>  rxrpc_decant_prepared_tx net/rxrpc/call_event.c:326 [inline]
>  rxrpc_transmit_some_data+0x496/0x600 net/rxrpc/call_event.c:350
>  rxrpc_input_call_event+0x564/0x1220 net/rxrpc/call_event.c:464
>  rxrpc_io_thread+0x307/0x1d80 net/rxrpc/io_thread.c:461
>  kthread+0x1ac/0x1e0 kernel/kthread.c:376
>  ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:308
>
> read to 0xffff888159cf3c50 of 4 bytes by task 25672 on cpu 0:
>  rxrpc_send_data+0x29e/0x1950 net/rxrpc/sendmsg.c:296
>  rxrpc_do_sendmsg+0xb7a/0xc20 net/rxrpc/sendmsg.c:726
>  rxrpc_sendmsg+0x413/0x520 net/rxrpc/af_rxrpc.c:565
>  sock_sendmsg_nosec net/socket.c:724 [inline]
>  sock_sendmsg net/socket.c:747 [inline]
>  ____sys_sendmsg+0x375/0x4c0 net/socket.c:2501
>  ___sys_sendmsg net/socket.c:2555 [inline]
>  __sys_sendmmsg+0x263/0x500 net/socket.c:2641
>  __do_sys_sendmmsg net/socket.c:2670 [inline]
>  __se_sys_sendmmsg net/socket.c:2667 [inline]
>  __x64_sys_sendmmsg+0x57/0x60 net/socket.c:2667
>  do_syscall_x64 arch/x86/entry/common.c:50 [inline]
>  do_syscall_64+0x41/0xc0 arch/x86/entry/common.c:80
>  entry_SYSCALL_64_after_hwframe+0x63/0xcd
>
> value changed: 0x00000000 -> 0xffffffea
>
> Reported by Kernel Concurrency Sanitizer on:
> CPU: 0 PID: 25672 Comm: syz-executor.5 Not tainted 6.3.0-rc5-syzkaller-00005-g148341f0a2f5 #0
> Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 03/02/2023
> ==================================================================
>
>
> ---
> This report is generated by a bot. It may contain errors.
> See https://goo.gl/tpsmEJ for more information about syzbot.
> syzbot engineers can be reached at syzkaller@googlegroups.com.
>
> syzbot will keep track of this issue. See:
> https://goo.gl/tpsmEJ#status for how to communicate with syzbot.
>
> --
> You received this message because you are subscribed to the Google Groups "syzkaller-bugs" group.
> To unsubscribe from this group and stop receiving emails from it, send an email to syzkaller-bugs+unsubscribe@googlegroups.com.
> To view this discussion on the web visit https://groups.google.com/d/msgid/syzkaller-bugs/000000000000e7c6d205fa10a3cd%40google.com.

Re: [syzbot] [afs?] [net?] KCSAN: data-race in rxrpc_send_data / rxrpc_set_call_completion

[David Howells]

Dmitry Vyukov <dvyukov@google.com> wrote:

> If I am reading this correctly, rxrpc_send_data() can read wrong
> call->completion and state and incorrectly exit with an error if
> rxrpc_wait_to_be_connected() exists early right after observing error
> set here:
> https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tree/net/rxrpc/sendmsg.c?id=148341f0a2f53b5e8808d093333d85170586a15d#n58
> The code seems to assume that at that point all writes done by
> rxrpc_set_call_completion() are already finished, but it's not
> necessarily the case.

I'm not sure it matters.  call->error can only be set by the I/O thread and
only if a call fails - in which case the call state will be set shortly
thereafter - plus a couple of places where we fail to set the call up, in
which case we're under the call's user_mutex or didn't even manage to fully
allocate it.

That said, I probably should check the call state first.  I might also want to
ignore any signal if the call did manage to get connected, lest I leave it
dangling - a problem might come if userspace issues a single sendmsg() to set
up the call and supply data to be transmitted.  I need to have a ponder on
that one.

David