kernel BUG at net/rxrpc/local_object.c:LINE!

kernel BUG at net/rxrpc/local_object.c:LINE!

[syzbot]

Hello,

syzbot found the following crash on:

HEAD commit:    249155c2 Merge branch 'parisc-5.2-4' of git://git.kernel.o..
git tree:       upstream
console output: https://syzkaller.appspot.com/x/log.txt?x=14fabe45a00000
kernel config:  https://syzkaller.appspot.com/x/.config?x=e7c31a94f66cc0aa
dashboard link: https://syzkaller.appspot.com/bug?extid=1e0edc4b8b7494c28450
compiler:       gcc (GCC) 9.0.0 20181231 (experimental)
syz repro:      https://syzkaller.appspot.com/x/repro.syz?x=13e2738da00000

The bug was bisected to:

commit 46894a13599a977ac35411b536fb3e0b2feefa95
Author: David Howells <dhowells@redhat.com>
Date:   Thu Oct 4 08:32:28 2018 +0000

     rxrpc: Use IPv4 addresses throught the IPv6

bisection log:  https://syzkaller.appspot.com/x/bisect.txt?x=152fabe3a00000
final crash:    https://syzkaller.appspot.com/x/report.txt?x=172fabe3a00000
console output: https://syzkaller.appspot.com/x/log.txt?x=132fabe3a00000

IMPORTANT: if you fix the bug, please add the following tag to the commit:
Reported-by: syzbot+1e0edc4b8b7494c28450@syzkaller.appspotmail.com
Fixes: 46894a13599a ("rxrpc: Use IPv4 addresses throught the IPv6")

rxrpc: Assertion failed
------------[ cut here ]------------
kernel BUG at net/rxrpc/local_object.c:468!
invalid opcode: 0000 [#1] PREEMPT SMP KASAN
CPU: 1 PID: 16 Comm: ksoftirqd/1 Not tainted 5.2.0-rc6+ #60
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS  
Google 01/01/2011
RIP: 0010:rxrpc_local_rcu net/rxrpc/local_object.c:468 [inline]
RIP: 0010:rxrpc_local_rcu.cold+0x11/0x13 net/rxrpc/local_object.c:462
Code: 83 eb 20 e9 74 ff ff ff e8 58 aa 2d fb eb cc 4c 89 ef e8 6e aa 2d fb  
eb e2 e8 d7 fd f4 fa 48 c7 c7 20 8c 15 88 e8 6f 03 df fa <0f> 0b e8 c4 fd  
f4 fa 48 c7 c7 20 8c 15 88 e8 5c 03 df fa 0f 0b e8
RSP: 0018:ffff8880a9917c98 EFLAGS: 00010286
RAX: 0000000000000017 RBX: 0000000000000001 RCX: 0000000000000000
RDX: 0000000000000000 RSI: ffffffff815ad926 RDI: ffffed1015322f85
RBP: ffff8880a9917ca8 R08: 0000000000000017 R09: ffffed1015d260a1
R10: ffffed1015d260a0 R11: ffff8880ae930507 R12: ffff888099033b40
R13: ffff888099033b40 R14: ffffffff867b8f10 R15: ffff8880a9917d28
FS:  0000000000000000(0000) GS:ffff8880ae900000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007f380ebda000 CR3: 000000007ad50000 CR4: 00000000001406e0
Call Trace:
  __rcu_reclaim kernel/rcu/rcu.h:222 [inline]
  rcu_do_batch kernel/rcu/tree.c:2092 [inline]
  invoke_rcu_callbacks kernel/rcu/tree.c:2310 [inline]
  rcu_core+0xba5/0x1500 kernel/rcu/tree.c:2291
  __do_softirq+0x25c/0x94c kernel/softirq.c:292
  run_ksoftirqd kernel/softirq.c:603 [inline]
  run_ksoftirqd+0x8e/0x110 kernel/softirq.c:595
  smpboot_thread_fn+0x6a3/0xa30 kernel/smpboot.c:165
  kthread+0x354/0x420 kernel/kthread.c:255
  ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:352
Modules linked in:
---[ end trace 0e784d6285151217 ]---
RIP: 0010:rxrpc_local_rcu net/rxrpc/local_object.c:468 [inline]
RIP: 0010:rxrpc_local_rcu.cold+0x11/0x13 net/rxrpc/local_object.c:462
Code: 83 eb 20 e9 74 ff ff ff e8 58 aa 2d fb eb cc 4c 89 ef e8 6e aa 2d fb  
eb e2 e8 d7 fd f4 fa 48 c7 c7 20 8c 15 88 e8 6f 03 df fa <0f> 0b e8 c4 fd  
f4 fa 48 c7 c7 20 8c 15 88 e8 5c 03 df fa 0f 0b e8
RSP: 0018:ffff8880a9917c98 EFLAGS: 00010286
RAX: 0000000000000017 RBX: 0000000000000001 RCX: 0000000000000000
RDX: 0000000000000000 RSI: ffffffff815ad926 RDI: ffffed1015322f85
RBP: ffff8880a9917ca8 R08: 0000000000000017 R09: ffffed1015d260a1
R10: ffffed1015d260a0 R11: ffff8880ae930507 R12: ffff888099033b40
R13: ffff888099033b40 R14: ffffffff867b8f10 R15: ffff8880a9917d28
FS:  0000000000000000(0000) GS:ffff8880ae900000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007f380ebda000 CR3: 000000007ad50000 CR4: 00000000001406e0


---
This bug 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 bug report. See:
https://goo.gl/tpsmEJ#status for how to communicate with syzbot.
For information about bisection process see: https://goo.gl/tpsmEJ#bisection
syzbot can test patches for this bug, for details see:
https://goo.gl/tpsmEJ#testing-patches

Re: kernel BUG at net/rxrpc/local_object.c:LINE!

[David Howells]

syzbot <syzbot+1e0edc4b8b7494c28450@syzkaller.appspotmail.com> wrote:

I *think* the reproducer boils down to the attached, but I can't get syzkaller
to work and the attached sample does not cause the oops to occur.  Can you try
it in your environment?

> The bug was bisected to:
> 
> commit 46894a13599a977ac35411b536fb3e0b2feefa95
> Author: David Howells <dhowells@redhat.com>
> Date:   Thu Oct 4 08:32:28 2018 +0000
> 
>     rxrpc: Use IPv4 addresses throught the IPv6

This might not be the correct bisection point.  If you look at the attached
sample, you're mixing AF_INET and AF_INET6.  If you try AF_INET throughout,
that might get a different point.  On the other hand, since you've bound the
socket, the AF_INET6 passed to socket() should be ignored.

David
---
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <unistd.h>
#include <sys/socket.h>
#include <arpa/inet.h>
#include <linux/rxrpc.h>

static const unsigned char inet4_addr[4] = {
	0xe0, 0x00, 0x00, 0x01
};

int main(void)
{
	struct sockaddr_rxrpc srx;
	int fd;

	memset(&srx, 0, sizeof(srx));
	srx.srx_family			= AF_RXRPC;
	srx.srx_service			= 0;
	srx.transport_type		= AF_INET;
	srx.transport_len		= sizeof(srx.transport.sin);
	srx.transport.sin.sin_family	= AF_INET;
	srx.transport.sin.sin_port	= htons(0x4e21);
	memcpy(&srx.transport.sin.sin_addr, inet4_addr, 4);

	fd = socket(AF_RXRPC, SOCK_DGRAM, AF_INET6);
	if (fd == -1) {
		perror("socket");
		exit(1);
	}

	if (bind(fd, (struct sockaddr *)&srx, sizeof(srx)) == -1) {
		perror("bind");
		exit(1);
	}

	sleep(20);

	// Whilst sleeping, hit with:
	// echo -e '\0\0\0\0\0\0\0\0' | ncat -4u --send-only 224.0.0.1 20001
	
	return 0;
}

Re: kernel BUG at net/rxrpc/local_object.c:LINE!

[Dmitry Vyukov]

,On Tue, Jul 2, 2019 at 3:37 PM David Howells <dhowells@redhat.com> wrote:
>
> syzbot <syzbot+1e0edc4b8b7494c28450@syzkaller.appspotmail.com> wrote:
>
> I *think* the reproducer boils down to the attached, but I can't get syzkaller
> to work and the attached sample does not cause the oops to occur.  Can you try
> it in your environment?
>
> > The bug was bisected to:
> >
> > commit 46894a13599a977ac35411b536fb3e0b2feefa95
> > Author: David Howells <dhowells@redhat.com>
> > Date:   Thu Oct 4 08:32:28 2018 +0000
> >
> >     rxrpc: Use IPv4 addresses throught the IPv6
>
> This might not be the correct bisection point.  If you look at the attached
> sample, you're mixing AF_INET and AF_INET6.  If you try AF_INET throughout,
> that might get a different point.  On the other hand, since you've bound the
> socket, the AF_INET6 passed to socket() should be ignored.
>
> David
> ---
> #include <stdio.h>
> #include <stdlib.h>
> #include <string.h>
> #include <unistd.h>
> #include <sys/socket.h>
> #include <arpa/inet.h>
> #include <linux/rxrpc.h>
>
> static const unsigned char inet4_addr[4] = {
>         0xe0, 0x00, 0x00, 0x01
> };
>
> int main(void)
> {
>         struct sockaddr_rxrpc srx;
>         int fd;
>
>         memset(&srx, 0, sizeof(srx));
>         srx.srx_family                  = AF_RXRPC;
>         srx.srx_service                 = 0;
>         srx.transport_type              = AF_INET;
>         srx.transport_len               = sizeof(srx.transport.sin);
>         srx.transport.sin.sin_family    = AF_INET;
>         srx.transport.sin.sin_port      = htons(0x4e21);
>         memcpy(&srx.transport.sin.sin_addr, inet4_addr, 4);
>
>         fd = socket(AF_RXRPC, SOCK_DGRAM, AF_INET6);
>         if (fd == -1) {
>                 perror("socket");
>                 exit(1);
>         }
>
>         if (bind(fd, (struct sockaddr *)&srx, sizeof(srx)) == -1) {
>                 perror("bind");
>                 exit(1);
>         }
>
>         sleep(20);
>
>         // Whilst sleeping, hit with:
>         // echo -e '\0\0\0\0\0\0\0\0' | ncat -4u --send-only 224.0.0.1 20001
>
>         return 0;
> }

Hi David,

I can't re-reproduce it locally in qemu either. Though, syzbot managed
to re-reproduce it reliably during bisection (maybe there is some
difference in hardware and as the result the injected ethernet packet
would need some different values). Let's try to ask it again to make
sure:
#syz test: git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git
master

Re bisection, I don't know if there are some more subtle things as
play (you are in the better position to judge that), but bisection log
looks good, it tracked the target crash throughout and wasn't
distracted by any unrelated bugs, etc. So I don't see any obvious
reasons to not trust it.

Re: kernel BUG at net/rxrpc/local_object.c:LINE!

[Dmitry Vyukov]

On Fri, Jul 5, 2019 at 2:12 PM Dmitry Vyukov <dvyukov@google.com> wrote:
> > syzbot <syzbot+1e0edc4b8b7494c28450@syzkaller.appspotmail.com> wrote:
> >
> > I *think* the reproducer boils down to the attached, but I can't get syzkaller
> > to work and the attached sample does not cause the oops to occur.  Can you try
> > it in your environment?
> >
> > > The bug was bisected to:
> > >
> > > commit 46894a13599a977ac35411b536fb3e0b2feefa95
> > > Author: David Howells <dhowells@redhat.com>
> > > Date:   Thu Oct 4 08:32:28 2018 +0000
> > >
> > >     rxrpc: Use IPv4 addresses throught the IPv6
> >
> > This might not be the correct bisection point.  If you look at the attached
> > sample, you're mixing AF_INET and AF_INET6.  If you try AF_INET throughout,
> > that might get a different point.  On the other hand, since you've bound the
> > socket, the AF_INET6 passed to socket() should be ignored.
> >
> > David
> > ---
> > #include <stdio.h>
> > #include <stdlib.h>
> > #include <string.h>
> > #include <unistd.h>
> > #include <sys/socket.h>
> > #include <arpa/inet.h>
> > #include <linux/rxrpc.h>
> >
> > static const unsigned char inet4_addr[4] = {
> >         0xe0, 0x00, 0x00, 0x01
> > };
> >
> > int main(void)
> > {
> >         struct sockaddr_rxrpc srx;
> >         int fd;
> >
> >         memset(&srx, 0, sizeof(srx));
> >         srx.srx_family                  = AF_RXRPC;
> >         srx.srx_service                 = 0;
> >         srx.transport_type              = AF_INET;
> >         srx.transport_len               = sizeof(srx.transport.sin);
> >         srx.transport.sin.sin_family    = AF_INET;
> >         srx.transport.sin.sin_port      = htons(0x4e21);
> >         memcpy(&srx.transport.sin.sin_addr, inet4_addr, 4);
> >
> >         fd = socket(AF_RXRPC, SOCK_DGRAM, AF_INET6);
> >         if (fd == -1) {
> >                 perror("socket");
> >                 exit(1);
> >         }
> >
> >         if (bind(fd, (struct sockaddr *)&srx, sizeof(srx)) == -1) {
> >                 perror("bind");
> >                 exit(1);
> >         }
> >
> >         sleep(20);
> >
> >         // Whilst sleeping, hit with:
> >         // echo -e '\0\0\0\0\0\0\0\0' | ncat -4u --send-only 224.0.0.1 20001
> >
> >         return 0;
> > }
>
> Hi David,
>
> I can't re-reproduce it locally in qemu either. Though, syzbot managed
> to re-reproduce it reliably during bisection (maybe there is some
> difference in hardware and as the result the injected ethernet packet
> would need some different values). Let's try to ask it again to make
> sure:
> #syz test: git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git
> master
>
> Re bisection, I don't know if there are some more subtle things as
> play (you are in the better position to judge that), but bisection log
> looks good, it tracked the target crash throughout and wasn't
> distracted by any unrelated bugs, etc. So I don't see any obvious
> reasons to not trust it.

FWIW here is a more complete translation of the syzkaller repro to C using:

$ syz-prog2c -prog /tmp/prog -threaded -collide -repeat=0 -procs=6
-sandbox=namespace -enable=tun,net_dev,net_reset,cgroups,close_fds
-tmpdir -segv

https://gist.githubusercontent.com/dvyukov/f712ca7c3a0d355ce63823d7882c2934/raw/7a72635b99e5a85599a6bcf9b7901fa9d8c494d4/repro.c

However, both syzbot and me won't able to repro with this C program,
so it is expected that it does not reproduce the crash for some
reason.

Re: kernel BUG at net/rxrpc/local_object.c:LINE!

[syzbot]

Hello,

syzbot has tested the proposed patch but the reproducer still triggered  
crash:
kernel BUG at net/rxrpc/local_object.c:LINE!

rxrpc: Assertion failed
------------[ cut here ]------------
kernel BUG at net/rxrpc/local_object.c:468!
invalid opcode: 0000 [#1] PREEMPT SMP KASAN
CPU: 1 PID: 10548 Comm: udevd Not tainted 5.2.0-rc7+ #1
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS  
Google 01/01/2011
RIP: 0010:rxrpc_local_rcu net/rxrpc/local_object.c:468 [inline]
RIP: 0010:rxrpc_local_rcu.cold+0x11/0x13 net/rxrpc/local_object.c:462
Code: 83 eb 20 e9 74 ff ff ff e8 68 a9 2d fb eb cc 4c 89 ef e8 7e a9 2d fb  
eb e2 e8 97 f2 f4 fa 48 c7 c7 e0 8c 15 88 e8 2f f8 de fa <0f> 0b e8 84 f2  
f4 fa 48 c7 c7 e0 8c 15 88 e8 1c f8 de fa 0f 0b e8
RSP: 0018:ffff8880ae909de8 EFLAGS: 00010282
RAX: 0000000000000017 RBX: 0000000000000001 RCX: 0000000000000000
RDX: 0000000000000000 RSI: ffffffff815ad9e6 RDI: ffffed1015d213af
RBP: ffff8880ae909df8 R08: 0000000000000017 R09: ffffed1015d260a1
R10: ffffed1015d260a0 R11: ffff8880ae930507 R12: ffff888095d10940
R13: ffff888095d10940 R14: ffffffff867b9b10 R15: ffff8880ae909e78
FS:  0000000000000000(0000) GS:ffff8880ae900000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 0000000000625208 CR3: 00000000a11ba000 CR4: 00000000001406e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
  <IRQ>
  __rcu_reclaim kernel/rcu/rcu.h:222 [inline]
  rcu_do_batch kernel/rcu/tree.c:2092 [inline]
  invoke_rcu_callbacks kernel/rcu/tree.c:2310 [inline]
  rcu_core+0xba5/0x1500 kernel/rcu/tree.c:2291
  __do_softirq+0x25c/0x94c kernel/softirq.c:292
  invoke_softirq kernel/softirq.c:373 [inline]
  irq_exit+0x180/0x1d0 kernel/softirq.c:413
  exiting_irq arch/x86/include/asm/apic.h:536 [inline]
  smp_apic_timer_interrupt+0x13b/0x550 arch/x86/kernel/apic/apic.c:1068
  apic_timer_interrupt+0xf/0x20 arch/x86/entry/entry_64.S:806
  </IRQ>
RIP: 0010:arch_local_irq_restore arch/x86/include/asm/paravirt.h:767  
[inline]
RIP: 0010:__raw_spin_unlock_irqrestore include/linux/spinlock_api_smp.h:160  
[inline]
RIP: 0010:_raw_spin_unlock_irqrestore+0x95/0xe0  
kernel/locking/spinlock.c:191
Code: 48 c7 c0 30 76 b2 88 48 ba 00 00 00 00 00 fc ff df 48 c1 e8 03 80 3c  
10 00 75 39 48 83 3d 82 18 95 01 00 74 24 48 89 df 57 9d <0f> 1f 44 00 00  
bf 01 00 00 00 e8 dc 2e 30 fa 65 8b 05 bd 9f e4 78
RSP: 0018:ffff8880a78bf728 EFLAGS: 00000286 ORIG_RAX: ffffffffffffff13
RAX: 1ffffffff1164ec6 RBX: 0000000000000286 RCX: 1ffff11011248d84
RDX: dffffc0000000000 RSI: ffff888089246c00 RDI: 0000000000000286
RBP: ffff8880a78bf738 R08: ffff888089246380 R09: ffff888089246c20
R10: 0000000000000000 R11: 0000000000000000 R12: ffffffff8a758108
R13: 0000000000000286 R14: ffffffff8a758108 R15: 0000000000000000
  __debug_check_no_obj_freed lib/debugobjects.c:798 [inline]
  debug_check_no_obj_freed+0x200/0x464 lib/debugobjects.c:817
  free_pages_prepare mm/page_alloc.c:1140 [inline]
  free_pcp_prepare mm/page_alloc.c:1156 [inline]
  free_unref_page_prepare mm/page_alloc.c:2947 [inline]
  free_unref_page_list+0x1f9/0xc30 mm/page_alloc.c:3016
  release_pages+0x5df/0x1930 mm/swap.c:795
  free_pages_and_swap_cache+0x2a0/0x3d0 mm/swap_state.c:295
  tlb_batch_pages_flush mm/mmu_gather.c:49 [inline]
  tlb_flush_mmu_free mm/mmu_gather.c:184 [inline]
  tlb_flush_mmu+0x89/0x630 mm/mmu_gather.c:191
  tlb_finish_mmu+0x98/0x3b0 mm/mmu_gather.c:272
  exit_mmap+0x2cd/0x510 mm/mmap.c:3147
  __mmput kernel/fork.c:1063 [inline]
  mmput+0x15f/0x4c0 kernel/fork.c:1084
  exec_mmap fs/exec.c:1047 [inline]
  flush_old_exec+0x8c8/0x1c00 fs/exec.c:1280
  load_elf_binary+0xa53/0x56c0 fs/binfmt_elf.c:867
  search_binary_handler fs/exec.c:1658 [inline]
  search_binary_handler+0x16d/0x570 fs/exec.c:1635
  exec_binprm fs/exec.c:1701 [inline]
  __do_execve_file.isra.0+0x1310/0x22f0 fs/exec.c:1821
  do_execveat_common fs/exec.c:1868 [inline]
  do_execve fs/exec.c:1885 [inline]
  __do_sys_execve fs/exec.c:1961 [inline]
  __se_sys_execve fs/exec.c:1956 [inline]
  __x64_sys_execve+0x8f/0xc0 fs/exec.c:1956
  do_syscall_64+0xfd/0x680 arch/x86/entry/common.c:301
  entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x7f67dfd66207
Code: Bad RIP value.
RSP: 002b:00007fff900c3538 EFLAGS: 00000202 ORIG_RAX: 000000000000003b
RAX: ffffffffffffffda RBX: 00000000ffffffff RCX: 00007f67dfd66207
RDX: 0000000000695c20 RSI: 00007fff900c3630 RDI: 00007fff900c4640
RBP: 0000000000625500 R08: 00000000000020d5 R09: 00000000000020d5
R10: 0000000000000000 R11: 0000000000000202 R12: 0000000000695c20
R13: 0000000000000007 R14: 0000000000691250 R15: 0000000000000005
Modules linked in:
---[ end trace 5b4a4001a18479d0 ]---
RIP: 0010:rxrpc_local_rcu net/rxrpc/local_object.c:468 [inline]
RIP: 0010:rxrpc_local_rcu.cold+0x11/0x13 net/rxrpc/local_object.c:462
Code: 83 eb 20 e9 74 ff ff ff e8 68 a9 2d fb eb cc 4c 89 ef e8 7e a9 2d fb  
eb e2 e8 97 f2 f4 fa 48 c7 c7 e0 8c 15 88 e8 2f f8 de fa <0f> 0b e8 84 f2  
f4 fa 48 c7 c7 e0 8c 15 88 e8 1c f8 de fa 0f 0b e8
RSP: 0018:ffff8880ae909de8 EFLAGS: 00010282
RAX: 0000000000000017 RBX: 0000000000000001 RCX: 0000000000000000
RDX: 0000000000000000 RSI: ffffffff815ad9e6 RDI: ffffed1015d213af
RBP: ffff8880ae909df8 R08: 0000000000000017 R09: ffffed1015d260a1
R10: ffffed1015d260a0 R11: ffff8880ae930507 R12: ffff888095d10940
R13: ffff888095d10940 R14: ffffffff867b9b10 R15: ffff8880ae909e78
FS:  0000000000000000(0000) GS:ffff8880ae900000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007f67dfd661dd CR3: 00000000a11ba000 CR4: 00000000001406e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400


Tested on:

commit:         69bf4b6b Revert "mm: page cache: store only head pages in ..
git tree:       upstream
console output: https://syzkaller.appspot.com/x/log.txt?x=146e5673a00000
kernel config:  https://syzkaller.appspot.com/x/.config?x=f6451f0da3d42d53
compiler:       gcc (GCC) 9.0.0 20181231 (experimental)

Re: kernel BUG at net/rxrpc/local_object.c:LINE!

[David Howells]

Dmitry Vyukov <dvyukov@google.com> wrote:

> Re bisection, I don't know if there are some more subtle things as
> play (you are in the better position to judge that), but bisection log
> looks good, it tracked the target crash throughout and wasn't
> distracted by any unrelated bugs, etc. So I don't see any obvious
> reasons to not trust it.

Can you turn on:

	echo 1 > /sys/kernel/debug/tracing/events/rxrpc/rxrpc_local/enable

and capture the trace log at the point it crashes?

David

Re: kernel BUG at net/rxrpc/local_object.c:LINE!

[Dmitry Vyukov]

On Wed, Jul 31, 2019 at 4:30 PM David Howells <dhowells@redhat.com> wrote:
>
> Dmitry Vyukov <dvyukov@google.com> wrote:
>
> > Re bisection, I don't know if there are some more subtle things as
> > play (you are in the better position to judge that), but bisection log
> > looks good, it tracked the target crash throughout and wasn't
> > distracted by any unrelated bugs, etc. So I don't see any obvious
> > reasons to not trust it.
>
> Can you turn on:
>
>         echo 1 > /sys/kernel/debug/tracing/events/rxrpc/rxrpc_local/enable
>
> and capture the trace log at the point it crashes?

Please send a patch for testing that enables this tracing
unconditionally. This should have the same effect. There is no way to
hook into a middle of the automated process and arbitrary tune things.

Re: kernel BUG at net/rxrpc/local_object.c:LINE!

[David Howells]

Dmitry Vyukov <dvyukov@google.com> wrote:

> Please send a patch for testing that enables this tracing
> unconditionally. This should have the same effect. There is no way to
> hook into a middle of the automated process and arbitrary tune things.

I don't know how to do that off hand.  Do you have an example?

Anyway, I think rxrpc_local_processor() is broken with respect to refcounting
as it gets scheduled when usage==0, but that doesn't stop it being rescheduled
again by a network packet before it manages to close the UDP socket.

David

Re: kernel BUG at net/rxrpc/local_object.c:LINE!

[Dmitry Vyukov]

On Wed, Jul 31, 2019 at 5:19 PM David Howells <dhowells@redhat.com> wrote:
>
> Dmitry Vyukov <dvyukov@google.com> wrote:
>
> > Please send a patch for testing that enables this tracing
> > unconditionally. This should have the same effect. There is no way to
> > hook into a middle of the automated process and arbitrary tune things.
>
> I don't know how to do that off hand.  Do you have an example?

Few messages above I asked it to test:
https://groups.google.com/d/msg/syzkaller-bugs/gEnZkmEWf1s/r2_X_KVQAQAJ

Basically, git repo + branch + patch. Here are the docs:
https://github.com/google/syzkaller/blob/master/docs/syzbot.md#testing-patches


> Anyway, I think rxrpc_local_processor() is broken with respect to refcounting
> as it gets scheduled when usage==0, but that doesn't stop it being rescheduled
> again by a network packet before it manages to close the UDP socket.
>
> David

Re: kernel BUG at net/rxrpc/local_object.c:LINE!

[David Howells]

Dmitry Vyukov <dvyukov@google.com> wrote:

> > > Please send a patch for testing that enables this tracing
> > > unconditionally. This should have the same effect. There is no way to
> > > hook into a middle of the automated process and arbitrary tune things.
> >
> > I don't know how to do that off hand.  Do you have an example?
> 
> Few messages above I asked it to test:
> https://groups.google.com/d/msg/syzkaller-bugs/gEnZkmEWf1s/r2_X_KVQAQAJ
> 
> Basically, git repo + branch + patch. Here are the docs:
> https://github.com/google/syzkaller/blob/master/docs/syzbot.md#testing-patches

I meant that I don't know how to turn a tracepoint on from inside the kernel.

David

Re: kernel BUG at net/rxrpc/local_object.c:LINE!

[Dmitry Vyukov]

On Tue, Aug 13, 2019 at 4:23 PM David Howells <dhowells@redhat.com> wrote:
>
> Dmitry Vyukov <dvyukov@google.com> wrote:
>
> > > > Please send a patch for testing that enables this tracing
> > > > unconditionally. This should have the same effect. There is no way to
> > > > hook into a middle of the automated process and arbitrary tune things.
> > >
> > > I don't know how to do that off hand.  Do you have an example?
> >
> > Few messages above I asked it to test:
> > https://groups.google.com/d/msg/syzkaller-bugs/gEnZkmEWf1s/r2_X_KVQAQAJ
> >
> > Basically, git repo + branch + patch. Here are the docs:
> > https://github.com/google/syzkaller/blob/master/docs/syzbot.md#testing-patches
>
> I meant that I don't know how to turn a tracepoint on from inside the kernel.

This /sys/kernel/debug/tracing/events/rxrpc/rxrpc_local/enable in:
        echo 1 > /sys/kernel/debug/tracing/events/rxrpc/rxrpc_local/enable
should map to some global variable, right? If so, it should be
possible to initialize that var to 1 statically. Or that won't work
for some reason?

Re: kernel BUG at net/rxrpc/local_object.c:LINE!

[David Howells]

Dmitry Vyukov <dvyukov@google.com> wrote:

> > I meant that I don't know how to turn a tracepoint on from inside the kernel.
> 
> This /sys/kernel/debug/tracing/events/rxrpc/rxrpc_local/enable in:
>         echo 1 > /sys/kernel/debug/tracing/events/rxrpc/rxrpc_local/enable
> should map to some global variable, right? If so, it should be
> possible to initialize that var to 1 statically. Or that won't work
> for some reason?

As I understand it, it's all hidden inside of tracing macros and ftrace
infrastructure and involves runtime patching the code to enable tracepoints
(they're effectively NOP'ed out when not in use).

So, no, it's not that simple.

I asked Steven and he says:

	trace_set_clr_event("sched", "sched_switch", 1);

is the same as

	echo 1 > events/sched/sched_switch/enable

So it can be done.  Will syzbot actually collect the trace log?

David

Re: kernel BUG at net/rxrpc/local_object.c:LINE!

[Dmitry Vyukov]

On Tue, Aug 13, 2019 at 5:06 PM David Howells <dhowells@redhat.com> wrote:
>
> Dmitry Vyukov <dvyukov@google.com> wrote:
>
> > > I meant that I don't know how to turn a tracepoint on from inside the kernel.
> >
> > This /sys/kernel/debug/tracing/events/rxrpc/rxrpc_local/enable in:
> >         echo 1 > /sys/kernel/debug/tracing/events/rxrpc/rxrpc_local/enable
> > should map to some global variable, right? If so, it should be
> > possible to initialize that var to 1 statically. Or that won't work
> > for some reason?
>
> As I understand it, it's all hidden inside of tracing macros and ftrace
> infrastructure and involves runtime patching the code to enable tracepoints
> (they're effectively NOP'ed out when not in use).
>
> So, no, it's not that simple.
>
> I asked Steven and he says:
>
>         trace_set_clr_event("sched", "sched_switch", 1);
>
> is the same as
>
>         echo 1 > events/sched/sched_switch/enable
>
> So it can be done.  Will syzbot actually collect the trace log?

It only collects console output. I don't know what is trace log. If
the trace log is not console output, then it won't.

Re: kernel BUG at net/rxrpc/local_object.c:LINE!

[David Howells]

Dmitry Vyukov <dvyukov@google.com> wrote:

> It only collects console output. I don't know what is trace log. If
> the trace log is not console output, then it won't.

Assuming the system is still alive:

	cat /sys/kernel/debug/tracing/trace

David

Re: kernel BUG at net/rxrpc/local_object.c:LINE!

[syzbot]

syzbot has found a reproducer for the following crash on:

HEAD commit:    0c3d3d64 Add linux-next specific files for 20190816
git tree:       linux-next
console output: https://syzkaller.appspot.com/x/log.txt?x=108b58f2600000
kernel config:  https://syzkaller.appspot.com/x/.config?x=dffdf1e146f941f4
dashboard link: https://syzkaller.appspot.com/bug?extid=1e0edc4b8b7494c28450
compiler:       gcc (GCC) 9.0.0 20181231 (experimental)
syz repro:      https://syzkaller.appspot.com/x/repro.syz?x=13feb73c600000
C reproducer:   https://syzkaller.appspot.com/x/repro.c?x=127088f2600000

The bug was bisected to:

commit 46894a13599a977ac35411b536fb3e0b2feefa95
Author: David Howells <dhowells@redhat.com>
Date:   Thu Oct 4 08:32:28 2018 +0000

     rxrpc: Use IPv4 addresses throught the IPv6

bisection log:  https://syzkaller.appspot.com/x/bisect.txt?x=152fabe3a00000
final crash:    https://syzkaller.appspot.com/x/report.txt?x=172fabe3a00000
console output: https://syzkaller.appspot.com/x/log.txt?x=132fabe3a00000

IMPORTANT: if you fix the bug, please add the following tag to the commit:
Reported-by: syzbot+1e0edc4b8b7494c28450@syzkaller.appspotmail.com
Fixes: 46894a13599a ("rxrpc: Use IPv4 addresses throught the IPv6")

rxrpc: Assertion failed
------------[ cut here ]------------
kernel BUG at net/rxrpc/local_object.c:433!
invalid opcode: 0000 [#1] PREEMPT SMP KASAN
CPU: 0 PID: 12 Comm: kworker/0:1 Not tainted 5.3.0-rc4-next-20190816 #67
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS  
Google 01/01/2011
Workqueue: krxrpcd rxrpc_local_processor
RIP: 0010:rxrpc_local_destroyer net/rxrpc/local_object.c:433 [inline]
RIP: 0010:rxrpc_local_processor.cold+0x24/0x29 net/rxrpc/local_object.c:466
Code: df a1 bc fa 0f 0b e8 c4 2b d3 fa 48 c7 c7 e0 24 5b 88 e8 cc a1 bc fa  
0f 0b e8 b1 2b d3 fa 48 c7 c7 e0 24 5b 88 e8 b9 a1 bc fa <0f> 0b 90 90 90  
55 48 89 e5 41 57 49 89 ff 41 56 41 55 41 54 53 48
RSP: 0018:ffff8880a98d7ce8 EFLAGS: 00010282
RAX: 0000000000000017 RBX: ffff88808c90a978 RCX: 0000000000000000
RDX: 0000000000000000 RSI: ffffffff815bb906 RDI: ffffed101531af8f
RBP: ffff8880a98d7d30 R08: 0000000000000017 R09: ffffed1015d060d9
R10: ffffed1015d060d8 R11: ffff8880ae8306c7 R12: ffff88808c90a208
R13: ffff88808dc48648 R14: ffff88808c90a940 R15: ffff8880929faa00
FS:  0000000000000000(0000) GS:ffff8880ae800000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 000000000049f2b0 CR3: 0000000008e6d000 CR4: 00000000001406f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
  process_one_work+0x9af/0x1740 kernel/workqueue.c:2269
  worker_thread+0x98/0xe40 kernel/workqueue.c:2415
  kthread+0x361/0x430 kernel/kthread.c:255
  ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:352
Modules linked in:
---[ end trace c65e44ef4b16c854 ]---
RIP: 0010:rxrpc_local_destroyer net/rxrpc/local_object.c:433 [inline]
RIP: 0010:rxrpc_local_processor.cold+0x24/0x29 net/rxrpc/local_object.c:466
Code: df a1 bc fa 0f 0b e8 c4 2b d3 fa 48 c7 c7 e0 24 5b 88 e8 cc a1 bc fa  
0f 0b e8 b1 2b d3 fa 48 c7 c7 e0 24 5b 88 e8 b9 a1 bc fa <0f> 0b 90 90 90  
55 48 89 e5 41 57 49 89 ff 41 56 41 55 41 54 53 48
RSP: 0018:ffff8880a98d7ce8 EFLAGS: 00010282
RAX: 0000000000000017 RBX: ffff88808c90a978 RCX: 0000000000000000
RDX: 0000000000000000 RSI: ffffffff815bb906 RDI: ffffed101531af8f
RBP: ffff8880a98d7d30 R08: 0000000000000017 R09: ffffed1015d060d9
R10: ffffed1015d060d8 R11: ffff8880ae8306c7 R12: ffff88808c90a208
R13: ffff88808dc48648 R14: ffff88808c90a940 R15: ffff8880929faa00
FS:  0000000000000000(0000) GS:ffff8880ae800000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: ffffffffff600400 CR3: 000000009b982000 CR4: 00000000001406f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400

Re: kernel BUG at net/rxrpc/local_object.c:LINE!

[David Howells]

Hi Hillf,

There are some commits in net/master that ought to fix this and conflict with
your longer patch:

	730c5fd42c1e3652a065448fd235cb9fafb2bd10
	rxrpc: Fix local endpoint refcounting

	68553f1a6f746bf860bce3eb42d78c26a717d9c0
	rxrpc: Fix local refcounting

	b00df840fb4004b7087940ac5f68801562d0d2de
	rxrpc: Fix local endpoint replacement

	06d9532fa6b34f12a6d75711162d47c17c1add72
	rxrpc: Fix read-after-free in rxrpc_queue_local()

After the first one, you should never see local->usage == 0 in
rxrpc_input_packet() as the UDP socket gets closed before the refcount is
reduced to 0 (there's now a second "usage" count that counts how many times
the local endpoint is in use and local->usage is the refcount for the struct
itself).

Thanks,
David