[syzbot] WARNING in ring_buffer_lock_reserve

[syzbot]

Hello,

syzbot found the following issue on:

HEAD commit: c00c5e1d157b Merge tag 'ext4_for_linus_stable' of git://gi..
git tree: upstream
console output: https://syzkaller.appspot.com/x/log.txt?x=16c71798f00000
kernel config: https://syzkaller.appspot.com/x/.config?x=d1843173f299d1e8
dashboard link: https://syzkaller.appspot.com/bug?extid=7cc6f78de62bf22bda9c
compiler: Debian clang version 13.0.1-++20220126092033+75e33f71c2da-1~exp1~20220126212112.63, GNU ld (GNU Binutils for Debian) 2.35.2

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

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

------------[ cut here ]------------
Delta way too big! 8384096949562536641 ts=8384098609305280746 before=1659742744105 after=1659742744105 write stamp=8384098609305280746
WARNING: CPU: 0 PID: 19417 at kernel/trace/ring_buffer.c:2744 rb_check_timestamp+0x129/0x130 kernel/trace/ring_buffer.c:2734
Modules linked in:
CPU: 0 PID: 19417 Comm: syz-executor.2 Tainted: G S 5.18.0-rc3-syzkaller-00190-gc00c5e1d157b #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
RIP: 0010:rb_check_timestamp+0x129/0x130 kernel/trace/ring_buffer.c:2734
Code: e8 91 8a 48 0f 44 e8 48 c7 c7 e0 ea 91 8a 48 8b 34 24 4c 89 fa 4c 89 e9 4d 89 f0 49 89 d9 31 c0 55 e8 5b 17 c6 ff 48 83 c4 08 <0f> 0b e9 f4 fe ff ff 55 41 57 41 56 41 55 41 54 53 48 83 ec 58 49
RSP: 0018:ffffc90002bef798 EFLAGS: 00010082
RAX: 45645b4ce4a40800 RBX: 745a4d43a97ce0ea RCX: 0000000000040000
RDX: ffffc9000bb08000 RSI: 000000000000adf6 RDI: 000000000000adf7
RBP: ffffffff8a91e8e0 R08: ffffffff816ac162 R09: ffffed1017344f24
R10: ffffed1017344f24 R11: 1ffff11017344f23 R12: ffff888011468930
R13: 0000018270606e29 R14: 0000018270606e29 R15: 745a4d43a97ce0ea
FS: 00007ff57856c700(0000) GS:ffff8880b9a00000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007ff57759d090 CR3: 0000000073001000 CR4: 00000000003526f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
<TASK>
rb_add_timestamp+0x324/0x520 kernel/trace/ring_buffer.c:2772
rb_update_event kernel/trace/ring_buffer.c:2809 [inline]
__rb_reserve_next kernel/trace/ring_buffer.c:3565 [inline]
rb_reserve_next_event kernel/trace/ring_buffer.c:3635 [inline]
ring_buffer_lock_reserve+0x10df/0x22a0 kernel/trace/ring_buffer.c:3694
__trace_buffer_lock_reserve kernel/trace/trace.c:949 [inline]
trace_event_buffer_lock_reserve+0xd8/0x6a0 kernel/trace/trace.c:2821
trace_event_buffer_reserve+0x2ae/0x3d0 kernel/trace/trace_events.c:496
trace_event_raw_event_bpf_trace_printk+0xfd/0x210 kernel/trace/./bpf_trace.h:11
trace_bpf_trace_printk+0x1c8/0x210 kernel/trace/./bpf_trace.h:11
____bpf_trace_printk kernel/trace/bpf_trace.c:388 [inline]
bpf_trace_printk+0x194/0x200 kernel/trace/bpf_trace.c:371
bpf_prog_0605f9f479290f07+0x2f/0x33
bpf_dispatcher_nop_func include/linux/bpf.h:804 [inline]
__bpf_prog_run include/linux/filter.h:628 [inline]
bpf_prog_run include/linux/filter.h:635 [inline]
__bpf_trace_run kernel/trace/bpf_trace.c:2022 [inline]
bpf_trace_run2+0x18a/0x320 kernel/trace/bpf_trace.c:2059
__bpf_trace_sys_exit+0x60/0x70 include/trace/events/syscalls.h:44
trace_sys_exit+0xb2/0xd0 include/trace/events/syscalls.h:44
syscall_exit_work+0x4a/0xe0 kernel/entry/common.c:245
syscall_exit_to_user_mode_prepare+0x62/0x80 kernel/entry/common.c:276
__syscall_exit_to_user_mode_work kernel/entry/common.c:281 [inline]
syscall_exit_to_user_mode+0xa/0x70 kernel/entry/common.c:294
entry_SYSCALL_64_after_hwframe+0x44/0xae
RIP: 0033:0x7ff5774890e9
Code: ff ff c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 40 00 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 73 01 c3 48 c7 c1 b8 ff ff ff f7 d8 64 89 01 48
RSP: 002b:00007ff57856c168 EFLAGS: 00000246 ORIG_RAX: 0000000000000141
RAX: 0000000000000004 RBX: 00007ff57759bf60 RCX: 00007ff5774890e9
RDX: 0000000000000010 RSI: 0000000020000180 RDI: 0000000000000011
RBP: 00007ff5774e308d R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000
R13: 00007ffe5033831f R14: 00007ff57856c300 R15: 0000000000022000
</TASK>


---
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 syzk...@googlegroups.com.

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

[Steven Rostedt]

On Tue, 26 Apr 2022 09:51:32 -0700
syzbot <syzbot+7cc6f7...@syzkaller.appspotmail.com> wrote:

> Hello,
>
> syzbot found the following issue on:
>
> HEAD commit: c00c5e1d157b Merge tag 'ext4_for_linus_stable' of git://gi..
> git tree: upstream
> console output: https://syzkaller.appspot.com/x/log.txt?x=16c71798f00000
> kernel config: https://syzkaller.appspot.com/x/.config?x=d1843173f299d1e8
> dashboard link: https://syzkaller.appspot.com/bug?extid=7cc6f78de62bf22bda9c
> compiler: Debian clang version 13.0.1-++20220126092033+75e33f71c2da-1~exp1~20220126212112.63, GNU ld (GNU Binutils for Debian) 2.35.2
>
> Unfortunately, I don't have any reproducer for this issue yet.
>
> IMPORTANT: if you fix the issue, please add the following tag to the commit:
> Reported-by: syzbot+7cc6f7...@syzkaller.appspotmail.com
>
> ------------[ cut here ]------------
> Delta way too big! 8384096949562536641 ts=8384098609305280746 before=1659742744105 after=1659742744105 write stamp=8384098609305280746

Looks like something in the test messed with the timestamp. As it went
from 1659742744105 to 8384096949562536641, even for nanoseconds, that is a
delta of 265 years!


And looking at the console output, it looks like something happened because
even that shows:

[ 3577.088716][T18453] GRED: Unable to relocate VQ 0x0 after dequeue, screwing up backlog
[ 3577.088716][T18453] GRED: Unable to relocate VQ 0x0 after dequeue, screwing up backlog
[ 3577.088716][T17423] GRED: Unable to relocate VQ 0x0 after dequeue, screwing up backlog

[..]

[8384098609.310217][T18453] GRED: Unable to relocate VQ 0x0 after dequeue, screwing up backlog
[8384098609.310217][T19083] overlayfs: conflicting lowerdir path
[8384098609.310217][T18453] GRED: Unable to relocate VQ 0x0 after dequeue, screwing up backlog
[8384098609.310217][T18453] GRED: Unable to relocate VQ 0x0 after dequeue, screwing up backlog

And yes, if you change the time stamp between two events that use deltas
between them, it will cause this warning. That's a feature not a bug.

-- Steve

[Dmitry Vyukov]

syzkaller recently learned how to write into /dev/cpu/n/msr bypassing
all restrictions.
This looks like it may be caused by a timestamp MSR update.
syzbot will not use msr.allow_writes=off command line argument:
https://github.com/google/syzkaller/commit/0ede5bfc57b8910f6436a23955422fae109636c2
It should prevent such writes.

Thanks for looking into this.

#syz invalid

> --
> 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-bug...@googlegroups.com.
> To view this discussion on the web visit https://groups.google.com/d/msgid/syzkaller-bugs/20220426133314.09661e25%40gandalf.local.home.