INFO: rcu detected stall in security_file

INFO: rcu detected stall in security_file_free (2)
Status: upstream: reported C repro on 2020/09/08 13:49
Reported-by: syzbot+f590c1bada839a48b7b1@syzkaller.appspotmail.com
First crash: 407d, last: 96d

Cause bisection: failed (bisect log)

Fix bisection: failed (bisect log)
similar bugs (1):
Kernel	Title	Repro	Cause bisect	Fix bisect	Count	Last	Reported	Patched	Status
upstream	INFO: rcu detected stall in security_file_free				2	648d	683d	0/22	closed as dup on 2019/12/03 08:34
Sample crash report:
rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
rcu: 	0-...!: (3 ticks this GP) idle=382/1/0x4000000000000002 softirq=9307/9307 fqs=0 
	(detected by 1, t=10502 jiffies, g=11173, q=564)
Sending NMI from CPU 1 to CPUs 0:
NMI backtrace for cpu 0
CPU: 0 PID: 8139 Comm: syz-executor202 Not tainted 5.9.0-rc1-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
RIP: 0010:unwind_next_frame+0x7d/0x1f90 arch/x86/kernel/unwind_orc.c:426
Code: 48 89 fa 65 48 8b 34 25 28 00 00 00 48 89 b4 24 98 00 00 00 31 f6 48 c1 ea 03 0f b6 04 02 84 c0 74 08 3c 03 0f 8e 54 0b 00 00 <41> 8b 2f 31 c0 85 ed 75 3b 48 ba 00 00 00 00 00 fc ff df 48 c7 04
RSP: 0018:ffffc90000007048 EFLAGS: 00000046
RAX: 0000000000000000 RBX: 1ffff92000000e11 RCX: 1ffff11011ba10a0
RDX: 1ffff92000000e30 RSI: 0000000000000000 RDI: ffffc90000007180
RBP: ffffc90000007248 R08: ffffffff8b9bff4c R09: ffffffff8b9bff50
R10: 0000000000000000 R11: 0000000000000001 R12: ffffffff81b40fac
R13: dffffc0000000000 R14: 0000000000000000 R15: ffffc90000007180
FS:  000000000227e880(0000) GS:ffff8880ae600000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 0000000000000000 CR3: 00000000a468a000 CR4: 00000000001506f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
 <IRQ>
 perf_callchain_kernel+0x444/0x6a0 arch/x86/events/core.c:2449
 get_perf_callchain+0x16e/0x620 kernel/events/callchain.c:200
 perf_callchain+0x165/0x1c0 kernel/events/core.c:6985
 perf_prepare_sample+0x8fd/0x1d40 kernel/events/core.c:7012
 __perf_event_output kernel/events/core.c:7170 [inline]
 perf_event_output_forward+0xf3/0x270 kernel/events/core.c:7190
 __perf_event_overflow+0x13c/0x370 kernel/events/core.c:8845
 perf_swevent_overflow kernel/events/core.c:8921 [inline]
 perf_swevent_event+0x347/0x550 kernel/events/core.c:8949
 perf_tp_event+0x2e4/0xb50 kernel/events/core.c:9377
 perf_trace_run_bpf_submit+0x11c/0x200 kernel/events/core.c:9351
 perf_trace_preemptirq_template+0x289/0x440 include/trace/events/preemptirq.h:14
 trace_irq_enable_rcuidle include/trace/events/preemptirq.h:40 [inline]
 trace_irq_enable_rcuidle include/trace/events/preemptirq.h:40 [inline]
 trace_hardirqs_on+0x18a/0x220 kernel/trace/trace_preemptirq.c:44
 asm_sysvec_irq_work+0x12/0x20 arch/x86/include/asm/idtentry.h:611
RIP: 0010:arch_local_irq_restore arch/x86/include/asm/paravirt.h:770 [inline]
RIP: 0010:rcu_read_unlock_special kernel/rcu/tree_plugin.h:630 [inline]
RIP: 0010:__rcu_read_unlock+0x488/0x560 kernel/rcu/tree_plugin.h:395
Code: 48 c7 c0 c8 3b b6 89 48 ba 00 00 00 00 00 fc ff df 48 c1 e8 03 80 3c 10 00 75 53 48 83 3d 47 75 54 08 00 74 13 4c 89 e7 57 9d <0f> 1f 44 00 00 e9 ed fb ff ff 0f 0b 0f 0b 0f 0b 0f 0b 4c 89 ef e8
RSP: 0018:ffffc90000007b40 EFLAGS: 00000286
RAX: 1ffffffff136c779 RBX: ffffffff89bd9901 RCX: 0000000000000002
RDX: dffffc0000000000 RSI: 0000000000000000 RDI: 0000000000000286
RBP: 0000000000000001 R08: 0000000000000001 R09: ffffffff8c5f3a97
R10: fffffbfff18be752 R11: 0000000000000001 R12: 0000000000000286
R13: 0000000000000200 R14: ffff8880ae636c00 R15: 0000000000000000
 rcu_read_unlock include/linux/rcupdate.h:687 [inline]
 mld_sendpack+0x742/0xdb0 net/ipv6/mcast.c:1690
 mld_send_initial_cr.part.0+0x106/0x150 net/ipv6/mcast.c:2096
 mld_send_initial_cr net/ipv6/mcast.c:1191 [inline]
 mld_dad_timer_expire+0x1c7/0x6a0 net/ipv6/mcast.c:2115
 call_timer_fn+0x1ac/0x760 kernel/time/timer.c:1413
 expire_timers kernel/time/timer.c:1458 [inline]
 __run_timers.part.0+0x67c/0xaa0 kernel/time/timer.c:1755
 __run_timers kernel/time/timer.c:1736 [inline]
 run_timer_softirq+0xae/0x1a0 kernel/time/timer.c:1768
 __do_softirq+0x2de/0xa24 kernel/softirq.c:298
 asm_call_on_stack+0xf/0x20 arch/x86/entry/entry_64.S:706
 </IRQ>
 __run_on_irqstack arch/x86/include/asm/irq_stack.h:22 [inline]
 run_on_irqstack_cond arch/x86/include/asm/irq_stack.h:48 [inline]
 do_softirq_own_stack+0x9d/0xd0 arch/x86/kernel/irq_64.c:77
 invoke_softirq kernel/softirq.c:393 [inline]
 __irq_exit_rcu kernel/softirq.c:423 [inline]
 irq_exit_rcu+0x1f3/0x230 kernel/softirq.c:435
 sysvec_apic_timer_interrupt+0x51/0xf0 arch/x86/kernel/apic/apic.c:1091
 asm_sysvec_apic_timer_interrupt+0x12/0x20 arch/x86/include/asm/idtentry.h:581
RIP: 0010:__raw_spin_unlock_irq include/linux/spinlock_api_smp.h:169 [inline]
RIP: 0010:_raw_spin_unlock_irq+0x4b/0x80 kernel/locking/spinlock.c:199
Code: c0 d8 3b b6 89 48 ba 00 00 00 00 00 fc ff df 48 c1 e8 03 80 3c 10 00 75 31 48 83 3d 46 f6 bf 01 00 74 25 fb 66 0f 1f 44 00 00 <bf> 01 00 00 00 e8 db 6d 59 f9 65 8b 05 d4 b8 0b 78 85 c0 74 02 5d
RSP: 0018:ffffc90009cf7c00 EFLAGS: 00000286
RAX: 1ffffffff136c77b RBX: ffff8880a95ea1c0 RCX: 1ffffffff1563fd1
RDX: dffffc0000000000 RSI: 0000000000000000 RDI: ffffffff87f6456f
RBP: ffff8880ae635e00 R08: 0000000000000001 R09: 0000000000000001
R10: 0000000000000000 R11: 0000000000000001 R12: ffff8880ae635e00
R13: ffff88808850a440 R14: 0000000000000000 R15: 0000000000000001
 finish_lock_switch kernel/sched/core.c:3517 [inline]
 finish_task_switch+0x147/0x750 kernel/sched/core.c:3617
 context_switch kernel/sched/core.c:3781 [inline]
 __schedule+0x8ed/0x21e0 kernel/sched/core.c:4527
 preempt_schedule_irq+0xb0/0x150 kernel/sched/core.c:4785
 irqentry_exit_cond_resched kernel/entry/common.c:333 [inline]
 irqentry_exit_cond_resched kernel/entry/common.c:325 [inline]
 irqentry_exit+0x65/0x90 kernel/entry/common.c:363
 asm_sysvec_reschedule_ipi+0x12/0x20 arch/x86/include/asm/idtentry.h:586
RIP: 0010:arch_local_irq_restore arch/x86/include/asm/paravirt.h:770 [inline]
RIP: 0010:kmem_cache_free.part.0+0x8c/0x1f0 mm/slab.c:3694
Code: e8 89 25 00 00 84 c0 74 76 41 f7 c4 00 02 00 00 74 4e e8 a7 f6 c5 ff 48 83 3d 27 2c 02 08 00 0f 84 2f 01 00 00 4c 89 e7 57 9d <0f> 1f 44 00 00 4c 8b 64 24 20 0f 1f 44 00 00 65 8b 05 9e 83 4d 7e
RSP: 0018:ffffc90009cf7e20 EFLAGS: 00000286
RAX: 000000000000168d RBX: ffff88809f747380 RCX: 1ffffffff1563fd1
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000286
RBP: ffff8880aa241e00 R08: 0000000000000001 R09: 0000000000000001
R10: 0000000000000000 R11: 0000000000000001 R12: 0000000000000286
R13: ffffffff8358c3f4 R14: ffff88808828d600 R15: ffff8880896a26a0
 security_file_free+0xa4/0xd0 security/security.c:1474
 file_free fs/file_table.c:55 [inline]
 __fput+0x3d7/0x920 fs/file_table.c:299
 task_work_run+0xdd/0x190 kernel/task_work.c:141
 tracehook_notify_resume include/linux/tracehook.h:188 [inline]
 exit_to_user_mode_loop kernel/entry/common.c:140 [inline]
 exit_to_user_mode_prepare+0x195/0x1c0 kernel/entry/common.c:167
 syscall_exit_to_user_mode+0x59/0x2b0 kernel/entry/common.c:242
 entry_SYSCALL_64_after_hwframe+0x44/0xa9
RIP: 0033:0x403fc0
Code: 01 f0 ff ff 0f 83 40 0d 00 00 c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 83 3d cd 9f 2d 00 00 75 14 b8 03 00 00 00 0f 05 <48> 3d 01 f0 ff ff 0f 83 14 0d 00 00 c3 48 83 ec 08 e8 7a 02 00 00
RSP: 002b:00007ffe459c68a8 EFLAGS: 00000246 ORIG_RAX: 0000000000000003
RAX: 0000000000000000 RBX: 0000000000000004 RCX: 0000000000403fc0
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000003
RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000400326777
R10: 00000000ffffffff R11: 0000000000000246 R12: 0000000000000004
R13: 00000000004051f0 R14: 0000000000000000 R15: 0000000000000000
INFO: NMI handler (nmi_cpu_backtrace_handler) took too long to run: 0.000 msecs
rcu: rcu_preempt kthread starved for 10502 jiffies! g11173 f0x0 RCU_GP_WAIT_FQS(5) ->state=0x402 ->cpu=0
rcu: 	Unless rcu_preempt kthread gets sufficient CPU time, OOM is now expected behavior.
rcu: RCU grace-period kthread stack dump:
task:rcu_preempt     state:I stack:29664 pid:   10 ppid:     2 flags:0x00004000
Call Trace:
 context_switch kernel/sched/core.c:3778 [inline]
 __schedule+0x8e5/0x21e0 kernel/sched/core.c:4527
 schedule+0xd0/0x2a0 kernel/sched/core.c:4602
 schedule_timeout+0x148/0x250 kernel/time/timer.c:1879
 rcu_gp_fqs_loop kernel/rcu/tree.c:1888 [inline]
 rcu_gp_kthread+0xae5/0x1b50 kernel/rcu/tree.c:2058
 kthread+0x3b5/0x4a0 kernel/kthread.c:292
 ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:294
Crashes (2):
Manager	Time	Kernel	Commit	Syzkaller	Config	Log	Report	Syz repro	C repro	VM info	Title
ci-upstream-bpf-kasan-gce	2020/09/04 13:38	bpf	e6135df45e21	abf9ba4f	.config	log	report	syz	C
ci-upstream-bpf-kasan-gce	2021/07/12 21:55	bpf	f35e0cc25280	f415556d	.config	log	report			info	INFO: rcu detected stall in security_file_free