WARNING in tracing_func_proto

WARNING in tracing_func_proto

[syzbot]

Hello,

syzbot found the following crash on:

HEAD commit:    428cd523 sfc/ethtool_common: Make some function to static
git tree:       net-next
console output: https://syzkaller.appspot.com/x/log.txt?x=10483421e00000
kernel config:  https://syzkaller.appspot.com/x/.config?x=66d8660c57ff3c98
dashboard link: https://syzkaller.appspot.com/bug?extid=0c147ca7bd4352547635
compiler:       gcc (GCC) 9.0.0 20181231 (experimental)

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

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

------------[ cut here ]------------
Could not allocate percpu trace_printk buffer
WARNING: CPU: 1 PID: 11733 at kernel/trace/trace.c:3112 alloc_percpu_trace_buffer kernel/trace/trace.c:3112 [inline]
WARNING: CPU: 1 PID: 11733 at kernel/trace/trace.c:3112 trace_printk_init_buffers+0x5b/0x60 kernel/trace/trace.c:3126
Kernel panic - not syncing: panic_on_warn set ...
CPU: 1 PID: 11733 Comm: syz-executor.2 Not tainted 5.5.0-rc5-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Call Trace:
 __dump_stack lib/dump_stack.c:77 [inline]
 dump_stack+0x197/0x210 lib/dump_stack.c:118
 panic+0x2e3/0x75c kernel/panic.c:221
 __warn.cold+0x2f/0x3e kernel/panic.c:582
 report_bug+0x289/0x300 lib/bug.c:195
 fixup_bug arch/x86/kernel/traps.c:174 [inline]
 fixup_bug arch/x86/kernel/traps.c:169 [inline]
 do_error_trap+0x11b/0x200 arch/x86/kernel/traps.c:267
 do_invalid_op+0x37/0x50 arch/x86/kernel/traps.c:286
 invalid_op+0x23/0x30 arch/x86/entry/entry_64.S:1027
RIP: 0010:alloc_percpu_trace_buffer kernel/trace/trace.c:3112 [inline]
RIP: 0010:trace_printk_init_buffers+0x5b/0x60 kernel/trace/trace.c:3126
Code: ff be 04 00 00 00 bf 04 10 00 00 e8 3f 84 24 00 48 85 c0 0f 85 e8 37 00 00 e8 d1 57 fb ff 48 c7 c7 e0 92 2f 88 e8 54 07 cc ff <0f> 0b eb c2 90 55 48 89 e5 41 57 49 c7 c7 e0 79 2f 88 41 56 49 89
RSP: 0018:ffffc900018e7528 EFLAGS: 00010282
RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000
RDX: 00000000000070cd RSI: ffffffff815e5e56 RDI: fffff5200031ce97
RBP: ffffc900018e7538 R08: ffff8880a204c3c0 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000000 R12: ffffffff88309580
R13: ffffffff88309240 R14: 0000000000000006 R15: ffff88805a52c000
 bpf_get_trace_printk_proto kernel/trace/bpf_trace.c:457 [inline]
 tracing_func_proto.isra.0+0x150/0x1a0 kernel/trace/bpf_trace.c:794
 pe_prog_func_proto+0x69/0x90 kernel/trace/bpf_trace.c:1023
 check_helper_call+0x123/0x48f0 kernel/bpf/verifier.c:4196
 do_check+0x613a/0x8a40 kernel/bpf/verifier.c:7978
 bpf_check+0x73d9/0xa9ef kernel/bpf/verifier.c:9777
 bpf_prog_load+0xe36/0x1960 kernel/bpf/syscall.c:1837
 __do_sys_bpf+0xa4b/0x3610 kernel/bpf/syscall.c:3073
 __se_sys_bpf kernel/bpf/syscall.c:3032 [inline]
 __x64_sys_bpf+0x73/0xb0 kernel/bpf/syscall.c:3032
 do_syscall_64+0xfa/0x790 arch/x86/entry/common.c:294
 entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x45af49
Code: ad b6 fb ff c3 66 2e 0f 1f 84 00 00 00 00 00 66 90 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 0f 83 7b b6 fb ff c3 66 2e 0f 1f 84 00 00 00 00
RSP: 002b:00007f31faef6c78 EFLAGS: 00000246 ORIG_RAX: 0000000000000141
RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 000000000045af49
RDX: 0000000000000048 RSI: 0000000020000080 RDI: 0000000000000005
RBP: 000000000075bfc8 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00007f31faef76d4
R13: 00000000004c1697 R14: 00000000004d66a0 R15: 00000000ffffffff
Kernel Offset: disabled
Rebooting in 86400 seconds..


---
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.

Re: WARNING in tracing_func_proto

[Steven Rostedt]

On Fri, 17 Jan 2020 23:47:11 -0800
syzbot <syzbot+0c147ca7bd4352547635@syzkaller.appspotmail.com> wrote:

> Hello,
> 
> syzbot found the following crash on:
> 
> HEAD commit:    428cd523 sfc/ethtool_common: Make some function to static
> git tree:       net-next
> console output: https://syzkaller.appspot.com/x/log.txt?x=10483421e00000
> kernel config:  https://syzkaller.appspot.com/x/.config?x=66d8660c57ff3c98
> dashboard link: https://syzkaller.appspot.com/bug?extid=0c147ca7bd4352547635
> compiler:       gcc (GCC) 9.0.0 20181231 (experimental)
> 
> Unfortunately, I don't have any reproducer for this crash yet.
> 
> IMPORTANT: if you fix the bug, please add the following tag to the commit:
> Reported-by: syzbot+0c147ca7bd4352547635@syzkaller.appspotmail.com
> 
> ------------[ cut here ]------------
> Could not allocate percpu trace_printk buffer
> WARNING: CPU: 1 PID: 11733 at kernel/trace/trace.c:3112 alloc_percpu_trace_buffer kernel/trace/trace.c:3112 [inline]
> WARNING: CPU: 1 PID: 11733 at kernel/trace/trace.c:3112 trace_printk_init_buffers+0x5b/0x60 kernel/trace/trace.c:3126
> Kernel panic - not syncing: panic_on_warn set ...

So it failed to allocate memory for the buffer (must be running low on
memory, or allocated a really big buffer?), and that triggered a
warning. As you have "panic_on_warn" set, the warning triggered the
panic.

The only solution to this that I can see is to remove the WARN_ON and
replace it with a pr_warn() message. There's a lot of WARN_ON()s in the
kernel that need this conversion too, and I will postpone this change
to that effort.

-- Steve


> CPU: 1 PID: 11733 Comm: syz-executor.2 Not tainted 5.5.0-rc5-syzkaller #0
> Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
> Call Trace:
>  __dump_stack lib/dump_stack.c:77 [inline]
>  dump_stack+0x197/0x210 lib/dump_stack.c:118
>  panic+0x2e3/0x75c kernel/panic.c:221
>  __warn.cold+0x2f/0x3e kernel/panic.c:582
>  report_bug+0x289/0x300 lib/bug.c:195
>  fixup_bug arch/x86/kernel/traps.c:174 [inline]
>  fixup_bug arch/x86/kernel/traps.c:169 [inline]
>  do_error_trap+0x11b/0x200 arch/x86/kernel/traps.c:267
>  do_invalid_op+0x37/0x50 arch/x86/kernel/traps.c:286
>  invalid_op+0x23/0x30 arch/x86/entry/entry_64.S:1027
> RIP: 0010:alloc_percpu_trace_buffer kernel/trace/trace.c:3112 [inline]
> RIP: 0010:trace_printk_init_buffers+0x5b/0x60 kernel/trace/trace.c:3126
> Code: ff be 04 00 00 00 bf 04 10 00 00 e8 3f 84 24 00 48 85 c0 0f 85 e8 37 00 00 e8 d1 57 fb ff 48 c7 c7 e0 92 2f 88 e8 54 07 cc ff <0f> 0b eb c2 90 55 48 89 e5 41 57 49 c7 c7 e0 79 2f 88 41 56 49 89
> RSP: 0018:ffffc900018e7528 EFLAGS: 00010282
> RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000
> RDX: 00000000000070cd RSI: ffffffff815e5e56 RDI: fffff5200031ce97
> RBP: ffffc900018e7538 R08: ffff8880a204c3c0 R09: 0000000000000000
> R10: 0000000000000000 R11: 0000000000000000 R12: ffffffff88309580
> R13: ffffffff88309240 R14: 0000000000000006 R15: ffff88805a52c000
>  bpf_get_trace_printk_proto kernel/trace/bpf_trace.c:457 [inline]
>  tracing_func_proto.isra.0+0x150/0x1a0 kernel/trace/bpf_trace.c:794
>  pe_prog_func_proto+0x69/0x90 kernel/trace/bpf_trace.c:1023
>  check_helper_call+0x123/0x48f0 kernel/bpf/verifier.c:4196
>  do_check+0x613a/0x8a40 kernel/bpf/verifier.c:7978
>  bpf_check+0x73d9/0xa9ef kernel/bpf/verifier.c:9777
>  bpf_prog_load+0xe36/0x1960 kernel/bpf/syscall.c:1837
>  __do_sys_bpf+0xa4b/0x3610 kernel/bpf/syscall.c:3073
>  __se_sys_bpf kernel/bpf/syscall.c:3032 [inline]
>  __x64_sys_bpf+0x73/0xb0 kernel/bpf/syscall.c:3032
>  do_syscall_64+0xfa/0x790 arch/x86/entry/common.c:294
>  entry_SYSCALL_64_after_hwframe+0x49/0xbe
> RIP: 0033:0x45af49
> Code: ad b6 fb ff c3 66 2e 0f 1f 84 00 00 00 00 00 66 90 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 0f 83 7b b6 fb ff c3 66 2e 0f 1f 84 00 00 00 00
> RSP: 002b:00007f31faef6c78 EFLAGS: 00000246 ORIG_RAX: 0000000000000141
> RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 000000000045af49
> RDX: 0000000000000048 RSI: 0000000020000080 RDI: 0000000000000005
> RBP: 000000000075bfc8 R08: 0000000000000000 R09: 0000000000000000
> R10: 0000000000000000 R11: 0000000000000246 R12: 00007f31faef76d4
> R13: 00000000004c1697 R14: 00000000004d66a0 R15: 00000000ffffffff
> Kernel Offset: disabled
> Rebooting in 86400 seconds..
> 

Re: WARNING in tracing_func_proto

[Dan Carpenter]

On Tue, Jan 21, 2020 at 06:02:55PM -0500, Steven Rostedt wrote:
> On Fri, 17 Jan 2020 23:47:11 -0800
> syzbot <syzbot+0c147ca7bd4352547635@syzkaller.appspotmail.com> wrote:
> 
> > Hello,
> > 
> > syzbot found the following crash on:
> > 
> > HEAD commit:    428cd523 sfc/ethtool_common: Make some function to static
> > git tree:       net-next
> > console output: https://syzkaller.appspot.com/x/log.txt?x=10483421e00000
> > kernel config:  https://syzkaller.appspot.com/x/.config?x=66d8660c57ff3c98
> > dashboard link: https://syzkaller.appspot.com/bug?extid=0c147ca7bd4352547635
> > compiler:       gcc (GCC) 9.0.0 20181231 (experimental)
> > 
> > Unfortunately, I don't have any reproducer for this crash yet.
> > 
> > IMPORTANT: if you fix the bug, please add the following tag to the commit:
> > Reported-by: syzbot+0c147ca7bd4352547635@syzkaller.appspotmail.com
> > 
> > ------------[ cut here ]------------
> > Could not allocate percpu trace_printk buffer
> > WARNING: CPU: 1 PID: 11733 at kernel/trace/trace.c:3112 alloc_percpu_trace_buffer kernel/trace/trace.c:3112 [inline]
> > WARNING: CPU: 1 PID: 11733 at kernel/trace/trace.c:3112 trace_printk_init_buffers+0x5b/0x60 kernel/trace/trace.c:3126
> > Kernel panic - not syncing: panic_on_warn set ...
> 
> So it failed to allocate memory for the buffer (must be running low on
> memory, or allocated a really big buffer?), and that triggered a
> warning. As you have "panic_on_warn" set, the warning triggered the
> panic.
> 
> The only solution to this that I can see is to remove the WARN_ON and
> replace it with a pr_warn() message. There's a lot of WARN_ON()s in the
> kernel that need this conversion too, and I will postpone this change
> to that effort.
> 

I bet the syzbot folk have changed to lot of WARN_ON()s.  Maybe they
just comment them out on their local tree?

regards,
dan carpenter

Re: WARNING in tracing_func_proto

[Dmitry Vyukov]

On Wed, Jan 22, 2020 at 6:54 AM Dan Carpenter <dan.carpenter@oracle.com> wrote:
>
> On Tue, Jan 21, 2020 at 06:02:55PM -0500, Steven Rostedt wrote:
> > On Fri, 17 Jan 2020 23:47:11 -0800
> > syzbot <syzbot+0c147ca7bd4352547635@syzkaller.appspotmail.com> wrote:
> >
> > > Hello,
> > >
> > > syzbot found the following crash on:
> > >
> > > HEAD commit:    428cd523 sfc/ethtool_common: Make some function to static
> > > git tree:       net-next
> > > console output: https://syzkaller.appspot.com/x/log.txt?x=10483421e00000
> > > kernel config:  https://syzkaller.appspot.com/x/.config?x=66d8660c57ff3c98
> > > dashboard link: https://syzkaller.appspot.com/bug?extid=0c147ca7bd4352547635
> > > compiler:       gcc (GCC) 9.0.0 20181231 (experimental)
> > >
> > > Unfortunately, I don't have any reproducer for this crash yet.
> > >
> > > IMPORTANT: if you fix the bug, please add the following tag to the commit:
> > > Reported-by: syzbot+0c147ca7bd4352547635@syzkaller.appspotmail.com
> > >
> > > ------------[ cut here ]------------
> > > Could not allocate percpu trace_printk buffer
> > > WARNING: CPU: 1 PID: 11733 at kernel/trace/trace.c:3112 alloc_percpu_trace_buffer kernel/trace/trace.c:3112 [inline]
> > > WARNING: CPU: 1 PID: 11733 at kernel/trace/trace.c:3112 trace_printk_init_buffers+0x5b/0x60 kernel/trace/trace.c:3126
> > > Kernel panic - not syncing: panic_on_warn set ...
> >
> > So it failed to allocate memory for the buffer (must be running low on
> > memory, or allocated a really big buffer?), and that triggered a
> > warning. As you have "panic_on_warn" set, the warning triggered the
> > panic.
> >
> > The only solution to this that I can see is to remove the WARN_ON and
> > replace it with a pr_warn() message. There's a lot of WARN_ON()s in the
> > kernel that need this conversion too, and I will postpone this change
> > to that effort.
> >
>
> I bet the syzbot folk have changed to lot of WARN_ON()s.  Maybe they
> just comment them out on their local tree?

FWIW this is invalid use of WARN macros:
https://elixir.bootlin.com/linux/v5.5-rc7/source/include/asm-generic/bug.h#L72
This should be replaced with pr_err (if really necessary, kernel does
not generally spew stacks on every ENOMEM/EINVAL).

There are no _lots_ such wrong uses of WARN in the kernel. There were
some, all get fixed over time, we are still discovering long tail, but
it's like one per months at most. Note: syzbot reports each and every
WARNING. If there were lots, you would notice :)

Sorting this out is critical for just any kernel testing. Otherwise no
testing system will be able to say if a test triggers something bad in
kernel or not.

FWIW there are no local trees for syzbot. It only tests public trees
as is. Doing otherwise would not work/scale as a process.

Re: WARNING in tracing_func_proto

[Steven Rostedt]

On Fri, 24 Jan 2020 11:44:13 +0100
Dmitry Vyukov <dvyukov@google.com> wrote:

> FWIW this is invalid use of WARN macros:
> https://elixir.bootlin.com/linux/v5.5-rc7/source/include/asm-generic/bug.h#L72
> This should be replaced with pr_err (if really necessary, kernel does
> not generally spew stacks on every ENOMEM/EINVAL).

That message was added in 2018. The WARN macro in question here, was
added in 2011. Thus, this would be more of a clean up fix.

> 
> There are no _lots_ such wrong uses of WARN in the kernel. There were
> some, all get fixed over time, we are still discovering long tail, but
> it's like one per months at most. Note: syzbot reports each and every
> WARNING. If there were lots, you would notice :)

Hmm, I haven't looked, but are all these correct usage?

 $ git grep WARN_ON HEAD | wc -l
15384

I also checked the number of WARN_ON when that WARN_ON was added:

 $ git grep WARN_ON 07d777fe8c3985bc83428c2866713c2d1b3d4129 | wc -l
4730

A lot more were added since then!

> 
> Sorting this out is critical for just any kernel testing. Otherwise no
> testing system will be able to say if a test triggers something bad in
> kernel or not.
> 
> FWIW there are no local trees for syzbot. It only tests public trees
> as is. Doing otherwise would not work/scale as a process.

Anyway, I'll happily take a patch converting that WARN_ON macro to a
pr_err() print.

-- Steve

Re: WARNING in tracing_func_proto

[Dmitry Vyukov]

On Fri, Jan 24, 2020 at 4:28 PM Steven Rostedt <rostedt@goodmis.org> wrote:
>
> On Fri, 24 Jan 2020 11:44:13 +0100
> Dmitry Vyukov <dvyukov@google.com> wrote:
>
> > FWIW this is invalid use of WARN macros:
> > https://elixir.bootlin.com/linux/v5.5-rc7/source/include/asm-generic/bug.h#L72
> > This should be replaced with pr_err (if really necessary, kernel does
> > not generally spew stacks on every ENOMEM/EINVAL).
>
> That message was added in 2018. The WARN macro in question here, was
> added in 2011. Thus, this would be more of a clean up fix.
>
> >
> > There are no _lots_ such wrong uses of WARN in the kernel. There were
> > some, all get fixed over time, we are still discovering long tail, but
> > it's like one per months at most. Note: syzbot reports each and every
> > WARNING. If there were lots, you would notice :)
>
> Hmm, I haven't looked, but are all these correct usage?
>
>  $ git grep WARN_ON HEAD | wc -l
> 15384

Hard to say, nobody knows. But there is no need to check/fix all of
them proactively, at least not due to syzbot. It stomps on wrong uses
with very low rate now (<1/month), and then for these there is a
reason to fix (but then we also know precisely which one is that).


> I also checked the number of WARN_ON when that WARN_ON was added:
>
>  $ git grep WARN_ON 07d777fe8c3985bc83428c2866713c2d1b3d4129 | wc -l
> 4730
>
> A lot more were added since then!

Adding WARNs is not necessarily wrong/bad. There are totally
legitimate uses for them. Especially in the context of general desire
to have fewer BUGs and replace more of them with WARNs.



> > Sorting this out is critical for just any kernel testing. Otherwise no
> > testing system will be able to say if a test triggers something bad in
> > kernel or not.
> >
> > FWIW there are no local trees for syzbot. It only tests public trees
> > as is. Doing otherwise would not work/scale as a process.
>
> Anyway, I'll happily take a patch converting that WARN_ON macro to a
> pr_err() print.
>
> -- Steve