INFO: rcu detected stall in corrupted (2)

INFO: rcu detected stall in corrupted (2)
Status: upstream: reported C repro on 2020/01/04 08:54
Reported-by: syzbot+58e46c9db31b4c06a7b0@syzkaller.appspotmail.com
First crash: 866d, last: 704d

Fix bisection: failed (bisect log)

similar bugs (8):
Kernel	Title	Repro	Cause bisect	Fix bisect	Count	Last	Reported	Patched	Status
android-414	INFO: rcu detected stall in corrupted	C			3	1061d	1134d	0/1	public: reported C repro on 2019/04/10 16:04
android-49	INFO: rcu detected stall in corrupted	C			27	946d	1131d	0/3	public: reported C repro on 2019/04/14 00:00
upstream	INFO: rcu detected stall in corrupted (3)	C	done		1	1150d	1146d	0/22	closed as invalid on 2019/03/30 00:13
upstream	INFO: rcu detected stall in corrupted (4)	C	done	inconclusive	115	79d	621d	0/22	upstream: reported C repro on 2020/09/04 18:49
upstream	INFO: rcu detected stall in corrupted	syz			1	1459d	1458d	9/22	fixed on 2018/07/09 18:05
linux-4.14	INFO: rcu detected stall in corrupted	C		done	3	979d	1001d	1/1	fixed on 2019/12/05 23:59
linux-4.19	INFO: rcu detected stall in corrupted	C		error	2	118d	826d	0/1	upstream: reported C repro on 2020/02/13 05:06
upstream	INFO: rcu detected stall in corrupted (2)	syz			1	1390d	1390d	0/22	closed as invalid on 2018/07/29 11:55

Sample crash report:

audit: type=1400 audit(1592062617.653:8): avc:  denied  { execmem } for  pid=6352 comm="syz-executor934" scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:system_r:kernel_t:s0 tclass=process permissive=1
hrtimer: interrupt took 42564 ns
hrtimer: interrupt took 40505 ns
INFO: rcu_sched detected stalls on CPUs/tasks:
INFO: rcu_preempt detected stalls on CPUs/tasks:
	
	(detected by 0, t=10502 jiffies, g=329, c=328, q=0)
(detected by 1, t=10502 jiffies, g=1103, c=1102, q=2)
All QSes seen, last rcu_sched kthread activity 10502 (4294978725-4294968223), jiffies_till_next_fqs=1, root ->qsmask 0x0
All QSes seen, last rcu_preempt kthread activity 10502 (4294978725-4294968223), jiffies_till_next_fqs=1, root ->qsmask 0x0
syz-executor934 R
syz-executor934 R
  running task    
  running task    
26848  6364   6353 0x00000000
26528  6362   6357 0x00000000
Call Trace:
Call Trace:
 <IRQ>
 <IRQ>
 sched_show_task kernel/sched/core.c:5168 [inline]
 sched_show_task.cold+0x335/0x399 kernel/sched/core.c:5143
 sched_show_task kernel/sched/core.c:5168 [inline]
 sched_show_task.cold+0x335/0x399 kernel/sched/core.c:5143
 print_other_cpu_stall kernel/rcu/tree.c:1501 [inline]
 check_cpu_stall kernel/rcu/tree.c:1616 [inline]
 __rcu_pending kernel/rcu/tree.c:3390 [inline]
 rcu_pending kernel/rcu/tree.c:3452 [inline]
 rcu_check_callbacks.cold+0xd3f/0xdaa kernel/rcu/tree.c:2792
 print_other_cpu_stall kernel/rcu/tree.c:1501 [inline]
 check_cpu_stall kernel/rcu/tree.c:1616 [inline]
 __rcu_pending kernel/rcu/tree.c:3390 [inline]
 rcu_pending kernel/rcu/tree.c:3452 [inline]
 rcu_check_callbacks.cold+0xd3f/0xdaa kernel/rcu/tree.c:2792
 update_process_times+0x29/0x60 kernel/time/timer.c:1590
 update_process_times+0x29/0x60 kernel/time/timer.c:1590
 tick_sched_handle.isra.0+0x73/0x150 kernel/time/tick-sched.c:165
 tick_sched_handle.isra.0+0x73/0x150 kernel/time/tick-sched.c:165
 tick_sched_timer+0x41/0x120 kernel/time/tick-sched.c:1223
 tick_sched_timer+0x41/0x120 kernel/time/tick-sched.c:1223
 __run_hrtimer kernel/time/hrtimer.c:1223 [inline]
 __hrtimer_run_queues+0x24b/0xb90 kernel/time/hrtimer.c:1287
 __run_hrtimer kernel/time/hrtimer.c:1223 [inline]
 __hrtimer_run_queues+0x24b/0xb90 kernel/time/hrtimer.c:1287
 hrtimer_interrupt+0x1e6/0x5e0 kernel/time/hrtimer.c:1321
 hrtimer_interrupt+0x1e6/0x5e0 kernel/time/hrtimer.c:1321
 local_apic_timer_interrupt arch/x86/kernel/apic/apic.c:1075 [inline]
 smp_apic_timer_interrupt+0x117/0x5f0 arch/x86/kernel/apic/apic.c:1100
 local_apic_timer_interrupt arch/x86/kernel/apic/apic.c:1075 [inline]
 smp_apic_timer_interrupt+0x117/0x5f0 arch/x86/kernel/apic/apic.c:1100
 apic_timer_interrupt+0x93/0xa0 arch/x86/entry/entry_64.S:793
 apic_timer_interrupt+0x93/0xa0 arch/x86/entry/entry_64.S:793
 </IRQ>
 </IRQ>
RIP: 0010:arch_local_irq_restore arch/x86/include/asm/paravirt.h:779 [inline]
RIP: 0010:lock_release+0x41e/0x7f0 kernel/locking/lockdep.c:4020
RIP: 0010:find_get_entry+0x2eb/0x660 mm/filemap.c:1386
RSP: 0018:ffff8880a9eb7870 EFLAGS: 00000282
RSP: 0018:ffff88809b16f4c8 EFLAGS: 00000246
 ORIG_RAX: ffffffffffffff10
 ORIG_RAX: ffffffffffffff10
RAX: 1ffffffff0f62cd1 RBX: 1ffff110153d6f12 RCX: 1ffff11010c2252f
RAX: 1ffff11012beaeeb RBX: ffffea0001fdcf80 RCX: 0000000000000000
RDX: dffffc0000000000 RSI: 0000000000000002 RDI: 0000000000000282
RDX: 0000000000000000 RSI: 00000000ffffffff RDI: 0000000000000282
RBP: ffffea0001fdcf80 R08: 0000000000000000 R09: 0000000000020012
RBP: ffff888086112100 R08: 0000000000000001 R09: 0000000000000001
R10: ffff888097e26958 R11: ffff888097e26080 R12: ffff888095f57758
R10: ffff8880861129b0 R11: ffff888086112100 R12: ffffffff816d515b
R13: dffffc0000000000 R14: ffffea0001fdcfa0 R15: ffffea0001fdcf80
R13: 0000000000000003 R14: ffff888086112100 R15: 0000000000000002
 pagecache_get_page+0x44/0xa10 mm/filemap.c:1465
 grab_cache_page_write_begin+0x63/0x90 mm/filemap.c:2997
 ext4_da_write_begin+0x244/0xe50 fs/ext4/inode.c:3074
 rcu_lock_release include/linux/rcupdate.h:247 [inline]
 rcu_read_unlock include/linux/rcupdate.h:685 [inline]
 find_get_entry+0x342/0x660 mm/filemap.c:1392
 pagecache_get_page+0x44/0xa10 mm/filemap.c:1465
 generic_perform_write+0x1c9/0x420 mm/filemap.c:3047
 find_get_page include/linux/pagemap.h:276 [inline]
 generic_file_buffered_read mm/filemap.c:1999 [inline]
 generic_file_read_iter+0x564/0x21d0 mm/filemap.c:2273
 ext4_file_read_iter+0x14b/0x330 fs/ext4/file.c:76
 call_read_iter include/linux/fs.h:1772 [inline]
 generic_file_splice_read+0x374/0x5d0 fs/splice.c:307
 __generic_file_write_iter+0x227/0x590 mm/filemap.c:3172
 ext4_file_write_iter+0x279/0xd90 fs/ext4/file.c:270
 call_write_iter include/linux/fs.h:1778 [inline]
 do_iter_readv_writev+0x3df/0x600 fs/read_write.c:675
 do_splice_to+0xfb/0x150 fs/splice.c:880
 do_iter_write fs/read_write.c:954 [inline]
 do_iter_write+0x152/0x550 fs/read_write.c:935
 vfs_iter_write+0x70/0xa0 fs/read_write.c:967
 splice_direct_to_actor+0x20a/0x730 fs/splice.c:952
 iter_file_splice_write+0x52e/0xa10 fs/splice.c:749
 do_splice_direct+0x164/0x210 fs/splice.c:1061
 do_sendfile+0x469/0xaf0 fs/read_write.c:1441
 do_splice_from fs/splice.c:851 [inline]
 direct_splice_actor+0x115/0x160 fs/splice.c:1018
 splice_direct_to_actor+0x27e/0x730 fs/splice.c:973
 SYSC_sendfile64 fs/read_write.c:1496 [inline]
 SyS_sendfile64+0x9b/0x110 fs/read_write.c:1488
 do_splice_direct+0x164/0x210 fs/splice.c:1061
 do_syscall_64+0x1d5/0x640 arch/x86/entry/common.c:292
 entry_SYSCALL_64_after_hwframe+0x46/0xbb
RIP: 0033:0x4418a9
RSP: 002b:00007ffe99a10118 EFLAGS: 00000246 ORIG_RAX: 0000000000000028
 do_sendfile+0x469/0xaf0 fs/read_write.c:1441
RAX: ffffffffffffffda RBX: 00007ffe99a102c0 RCX: 00000000004418a9
RDX: 00000000200001c0 RSI: 0000000000000003 RDI: 0000000000000003
 SYSC_sendfile64 fs/read_write.c:1496 [inline]
 SyS_sendfile64+0x9b/0x110 fs/read_write.c:1488
RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
R10: 00008080fffffffe R11: 0000000000000246 R12: 0000000000000000
R13: 0000000000402580 R14: 0000000000000000 R15: 0000000000000000
rcu_sched kthread starved for 10502 jiffies! g329 c328 f0x2 RCU_GP_WAIT_FQS(3) ->state=0x0 ->cpu=1
rcu_sched       R
 do_syscall_64+0x1d5/0x640 arch/x86/entry/common.c:292
  running task    
 entry_SYSCALL_64_after_hwframe+0x46/0xbb
29904     9      2 0x80000000
RIP: 0033:0x4418a9
Call Trace:
RSP: 002b:00007ffe99a10118 EFLAGS: 00000246
 context_switch kernel/sched/core.c:2808 [inline]
 __schedule+0x8a6/0x1d70 kernel/sched/core.c:3384
 ORIG_RAX: 0000000000000028
RAX: ffffffffffffffda RBX: 00007ffe99a102c0 RCX: 00000000004418a9
RDX: 00000000200001c0 RSI: 0000000000000003 RDI: 0000000000000003
RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
 schedule+0x8d/0x1b0 kernel/sched/core.c:3428
R10: 00008080fffffffe R11: 0000000000000246 R12: 0000000000000000
 schedule_timeout+0x4df/0xe50 kernel/time/timer.c:1746
R13: 0000000000402580 R14: 0000000000000000 R15: 0000000000000000
rcu_preempt kthread starved for 10502 jiffies! g1103 c1102 f0x2 RCU_GP_WAIT_FQS(3) ->state=0x0 ->cpu=1
rcu_preempt     R
  running task    29904     8      2 0x80000000
Call Trace:
 context_switch kernel/sched/core.c:2808 [inline]
 __schedule+0x8a6/0x1d70 kernel/sched/core.c:3384
 rcu_gp_kthread+0xb3d/0x1ce0 kernel/rcu/tree.c:2255
 kthread+0x30d/0x420 kernel/kthread.c:232
 schedule+0x8d/0x1b0 kernel/sched/core.c:3428
 schedule_timeout+0x4df/0xe50 kernel/time/timer.c:1746
 ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:404
 rcu_gp_kthread+0xb3d/0x1ce0 kernel/rcu/tree.c:2255
 kthread+0x30d/0x420 kernel/kthread.c:232
 ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:404

Crashes (4):
Manager	Time	Kernel	Commit	Syzkaller	Config	Log	Report	Syz repro	C repro
ci2-linux-4-14	2020/06/13 15:40	linux-4.14.y	b850307b279c	dbce178a	.config	log	report	syz	C
ci2-linux-4-14	2020/04/03 15:51	linux-4.14.y	4520f06b03ae	5ed396e6	.config	log	report	syz	C
ci2-linux-4-14	2020/01/04 08:53	linux-4.14.y	4c5bf01e16a7	68256974	.config	log	report	syz	C
ci2-linux-4-14	2020/03/07 16:03	linux-4.14.y	78d697fc93f9	2e9971bb	.config	log	report	syz