[syzbot] INFO: rcu detected stall in net_tx_action

[syzbot]

Hello,

syzbot found the following issue on:

HEAD commit: d6765985 Revert "be2net: disable bh with spin_lock in be_p..
git tree: net
console output: https://syzkaller.appspot.com/x/log.txt?x=1085a0d8300000
kernel config: https://syzkaller.appspot.com/x/.config?x=7ca96a2d153c74b0
dashboard link: https://syzkaller.appspot.com/bug?extid=3ba0493d523d007b3819
syz repro: https://syzkaller.appspot.com/x/repro.syz?x=14c9edc8300000
C reproducer: https://syzkaller.appspot.com/x/repro.c?x=172463c8300000

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

rcu: INFO: rcu_preempt self-detected stall on CPU
rcu: 1-...!: (11 ticks this GP) idle=eae/0/0x3 softirq=11934/11934 fqs=0
(t=13378 jiffies g=11625 q=43)
rcu: rcu_preempt kthread starved for 13378 jiffies! g11625 f0x0 RCU_GP_WAIT_FQS(5) ->state=0x0 ->cpu=1
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:R running task stack:28800 pid: 14 ppid: 2 flags:0x00004000
Call Trace:
context_switch kernel/sched/core.c:4339 [inline]
__schedule+0x916/0x23e0 kernel/sched/core.c:5147
schedule+0xcf/0x270 kernel/sched/core.c:5226
schedule_timeout+0x14a/0x250 kernel/time/timer.c:1892
rcu_gp_fqs_loop kernel/rcu/tree.c:2004 [inline]
rcu_gp_kthread+0xd07/0x2300 kernel/rcu/tree.c:2177
kthread+0x3b1/0x4a0 kernel/kthread.c:313
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:294
rcu: Stack dump where RCU GP kthread last ran:
NMI backtrace for cpu 1
CPU: 1 PID: 0 Comm: swapper/1 Not tainted 5.13.0-rc6-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Call Trace:
<IRQ>
__dump_stack lib/dump_stack.c:79 [inline]
dump_stack+0x141/0x1d7 lib/dump_stack.c:120
nmi_cpu_backtrace.cold+0x44/0xd7 lib/nmi_backtrace.c:105
nmi_trigger_cpumask_backtrace+0x1b3/0x230 lib/nmi_backtrace.c:62
trigger_single_cpu_backtrace include/linux/nmi.h:164 [inline]
rcu_check_gp_kthread_starvation.cold+0x1cc/0x1d1 kernel/rcu/tree_stall.h:478
print_cpu_stall kernel/rcu/tree_stall.h:622 [inline]
check_cpu_stall kernel/rcu/tree_stall.h:699 [inline]
rcu_pending kernel/rcu/tree.c:3911 [inline]
rcu_sched_clock_irq.cold+0x3ec/0x74b kernel/rcu/tree.c:2649
update_process_times+0x16d/0x200 kernel/time/timer.c:1796
tick_sched_handle+0x9b/0x180 kernel/time/tick-sched.c:226
tick_sched_timer+0x1b0/0x2d0 kernel/time/tick-sched.c:1374
__run_hrtimer kernel/time/hrtimer.c:1537 [inline]
__hrtimer_run_queues+0x1c0/0xe40 kernel/time/hrtimer.c:1601
hrtimer_interrupt+0x330/0xa00 kernel/time/hrtimer.c:1663
local_apic_timer_interrupt arch/x86/kernel/apic/apic.c:1089 [inline]
__sysvec_apic_timer_interrupt+0x146/0x540 arch/x86/kernel/apic/apic.c:1106
sysvec_apic_timer_interrupt+0x40/0xc0 arch/x86/kernel/apic/apic.c:1100
asm_sysvec_apic_timer_interrupt+0x12/0x20 arch/x86/include/asm/idtentry.h:647
RIP: 0010:arch_safe_halt arch/x86/include/asm/irqflags.h:90 [inline]
RIP: 0010:kvm_wait arch/x86/kernel/kvm.c:888 [inline]
RIP: 0010:kvm_wait+0xb2/0x100 arch/x86/kernel/kvm.c:871
Code: 89 74 24 0c 48 89 3c 24 e8 2b 2e 48 00 8b 74 24 0c 48 8b 3c 24 eb 82 e8 4c 33 48 00 e9 07 00 00 00 0f 00 2d 90 10 36 08 fb f4 <eb> 98 e9 07 00 00 00 0f 00 2d 80 10 36 08 f4 eb bf 89 74 24 0c 48
RSP: 0018:ffffc90000dc0d98 EFLAGS: 00000202
RAX: 0000000000097204 RBX: 0000000000000000 RCX: 1ffffffff204f312
RDX: 0000000000000000 RSI: 0000000000000102 RDI: 0000000000000000
RBP: ffff8880312710f0 R08: 0000000000000001 R09: ffffffff90228977
R10: 0000000000000001 R11: 0000000000000000 R12: 0000000000000000
R13: ffffed100624e21e R14: 0000000000000001 R15: ffff8880b9d36400
pv_wait arch/x86/include/asm/paravirt.h:597 [inline]
pv_wait_head_or_lock kernel/locking/qspinlock_paravirt.h:470 [inline]
__pv_queued_spin_lock_slowpath+0x8b8/0xb40 kernel/locking/qspinlock.c:508
pv_queued_spin_lock_slowpath arch/x86/include/asm/paravirt.h:585 [inline]
queued_spin_lock_slowpath arch/x86/include/asm/qspinlock.h:51 [inline]
queued_spin_lock include/asm-generic/qspinlock.h:85 [inline]
do_raw_spin_lock+0x200/0x2b0 kernel/locking/spinlock_debug.c:113
spin_lock include/linux/spinlock.h:354 [inline]
net_tx_action+0x437/0xe10 net/core/dev.c:5044
__do_softirq+0x29b/0x9f6 kernel/softirq.c:559
invoke_softirq kernel/softirq.c:433 [inline]
__irq_exit_rcu+0x136/0x200 kernel/softirq.c:637
irq_exit_rcu+0x5/0x20 kernel/softirq.c:649
sysvec_apic_timer_interrupt+0x93/0xc0 arch/x86/kernel/apic/apic.c:1100
</IRQ>
asm_sysvec_apic_timer_interrupt+0x12/0x20 arch/x86/include/asm/idtentry.h:647
RIP: 0010:native_save_fl arch/x86/include/asm/irqflags.h:29 [inline]
RIP: 0010:arch_local_save_flags arch/x86/include/asm/irqflags.h:70 [inline]
RIP: 0010:arch_irqs_disabled arch/x86/include/asm/irqflags.h:132 [inline]
RIP: 0010:acpi_safe_halt drivers/acpi/processor_idle.c:109 [inline]
RIP: 0010:acpi_idle_do_entry+0x1c9/0x250 drivers/acpi/processor_idle.c:513
Code: 9d 1f 5b f8 84 db 75 ac e8 e4 18 5b f8 e8 ff 25 61 f8 e9 0c 00 00 00 e8 d5 18 5b f8 0f 00 2d 3e b7 b4 00 e8 c9 18 5b f8 fb f4 <9c> 5b 81 e3 00 02 00 00 fa 31 ff 48 89 de e8 d4 20 5b f8 48 85 db
RSP: 0018:ffffc90000d57d18 EFLAGS: 00000293
RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000
RDX: ffff8880123d54c0 RSI: ffffffff8919c327 RDI: 0000000000000000
RBP: ffff8880190bb064 R08: 0000000000000001 R09: 0000000000000001
R10: ffffffff817ae948 R11: 0000000000000000 R12: 0000000000000001
R13: ffff8880190bb000 R14: ffff8880190bb064 R15: ffff88801c57c804
acpi_idle_enter+0x361/0x500 drivers/acpi/processor_idle.c:648
cpuidle_enter_state+0x1b1/0xc80 drivers/cpuidle/cpuidle.c:237
cpuidle_enter+0x4a/0xa0 drivers/cpuidle/cpuidle.c:351
call_cpuidle kernel/sched/idle.c:158 [inline]
cpuidle_idle_call kernel/sched/idle.c:239 [inline]
do_idle+0x3e8/0x590 kernel/sched/idle.c:306
cpu_startup_entry+0x14/0x20 kernel/sched/idle.c:403
start_secondary+0x274/0x350 arch/x86/kernel/smpboot.c:272
secondary_startup_64_no_verify+0xb0/0xbb
NMI backtrace for cpu 1
CPU: 1 PID: 0 Comm: swapper/1 Not tainted 5.13.0-rc6-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Call Trace:
<IRQ>
__dump_stack lib/dump_stack.c:79 [inline]
dump_stack+0x141/0x1d7 lib/dump_stack.c:120
nmi_cpu_backtrace.cold+0x44/0xd7 lib/nmi_backtrace.c:105
nmi_trigger_cpumask_backtrace+0x1b3/0x230 lib/nmi_backtrace.c:62
trigger_single_cpu_backtrace include/linux/nmi.h:164 [inline]
rcu_dump_cpu_stacks+0x25e/0x3f0 kernel/rcu/tree_stall.h:341
print_cpu_stall kernel/rcu/tree_stall.h:624 [inline]
check_cpu_stall kernel/rcu/tree_stall.h:699 [inline]
rcu_pending kernel/rcu/tree.c:3911 [inline]
rcu_sched_clock_irq.cold+0x3f1/0x74b kernel/rcu/tree.c:2649
update_process_times+0x16d/0x200 kernel/time/timer.c:1796
tick_sched_handle+0x9b/0x180 kernel/time/tick-sched.c:226
tick_sched_timer+0x1b0/0x2d0 kernel/time/tick-sched.c:1374
__run_hrtimer kernel/time/hrtimer.c:1537 [inline]
__hrtimer_run_queues+0x1c0/0xe40 kernel/time/hrtimer.c:1601
hrtimer_interrupt+0x330/0xa00 kernel/time/hrtimer.c:1663
local_apic_timer_interrupt arch/x86/kernel/apic/apic.c:1089 [inline]
__sysvec_apic_timer_interrupt+0x146/0x540 arch/x86/kernel/apic/apic.c:1106
sysvec_apic_timer_interrupt+0x40/0xc0 arch/x86/kernel/apic/apic.c:1100
asm_sysvec_apic_timer_interrupt+0x12/0x20 arch/x86/include/asm/idtentry.h:647
RIP: 0010:arch_safe_halt arch/x86/include/asm/irqflags.h:90 [inline]
RIP: 0010:kvm_wait arch/x86/kernel/kvm.c:888 [inline]
RIP: 0010:kvm_wait+0xb2/0x100 arch/x86/kernel/kvm.c:871
Code: 89 74 24 0c 48 89 3c 24 e8 2b 2e 48 00 8b 74 24 0c 48 8b 3c 24 eb 82 e8 4c 33 48 00 e9 07 00 00 00 0f 00 2d 90 10 36 08 fb f4 <eb> 98 e9 07 00 00 00 0f 00 2d 80 10 36 08 f4 eb bf 89 74 24 0c 48
RSP: 0018:ffffc90000dc0d98 EFLAGS: 00000202
RAX: 0000000000097204 RBX: 0000000000000000 RCX: 1ffffffff204f312
RDX: 0000000000000000 RSI: 0000000000000102 RDI: 0000000000000000
RBP: ffff8880312710f0 R08: 0000000000000001 R09: ffffffff90228977
R10: 0000000000000001 R11: 0000000000000000 R12: 0000000000000000
R13: ffffed100624e21e R14: 0000000000000001 R15: ffff8880b9d36400
pv_wait arch/x86/include/asm/paravirt.h:597 [inline]
pv_wait_head_or_lock kernel/locking/qspinlock_paravirt.h:470 [inline]
__pv_queued_spin_lock_slowpath+0x8b8/0xb40 kernel/locking/qspinlock.c:508
pv_queued_spin_lock_slowpath arch/x86/include/asm/paravirt.h:585 [inline]
queued_spin_lock_slowpath arch/x86/include/asm/qspinlock.h:51 [inline]
queued_spin_lock include/asm-generic/qspinlock.h:85 [inline]
do_raw_spin_lock+0x200/0x2b0 kernel/locking/spinlock_debug.c:113
spin_lock include/linux/spinlock.h:354 [inline]
net_tx_action+0x437/0xe10 net/core/dev.c:5044
__do_softirq+0x29b/0x9f6 kernel/softirq.c:559
invoke_softirq kernel/softirq.c:433 [inline]
__irq_exit_rcu+0x136/0x200 kernel/softirq.c:637
irq_exit_rcu+0x5/0x20 kernel/softirq.c:649
sysvec_apic_timer_interrupt+0x93/0xc0 arch/x86/kernel/apic/apic.c:1100
</IRQ>
asm_sysvec_apic_timer_interrupt+0x12/0x20 arch/x86/include/asm/idtentry.h:647
RIP: 0010:native_save_fl arch/x86/include/asm/irqflags.h:29 [inline]
RIP: 0010:arch_local_save_flags arch/x86/include/asm/irqflags.h:70 [inline]
RIP: 0010:arch_irqs_disabled arch/x86/include/asm/irqflags.h:132 [inline]
RIP: 0010:acpi_safe_halt drivers/acpi/processor_idle.c:109 [inline]
RIP: 0010:acpi_idle_do_entry+0x1c9/0x250 drivers/acpi/processor_idle.c:513
Code: 9d 1f 5b f8 84 db 75 ac e8 e4 18 5b f8 e8 ff 25 61 f8 e9 0c 00 00 00 e8 d5 18 5b f8 0f 00 2d 3e b7 b4 00 e8 c9 18 5b f8 fb f4 <9c> 5b 81 e3 00 02 00 00 fa 31 ff 48 89 de e8 d4 20 5b f8 48 85 db
RSP: 0018:ffffc90000d57d18 EFLAGS: 00000293
RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000
RDX: ffff8880123d54c0 RSI: ffffffff8919c327 RDI: 0000000000000000
RBP: ffff8880190bb064 R08: 0000000000000001 R09: 0000000000000001
R10: ffffffff817ae948 R11: 0000000000000000 R12: 0000000000000001
R13: ffff8880190bb000 R14: ffff8880190bb064 R15: ffff88801c57c804
acpi_idle_enter+0x361/0x500 drivers/acpi/processor_idle.c:648
cpuidle_enter_state+0x1b1/0xc80 drivers/cpuidle/cpuidle.c:237
cpuidle_enter+0x4a/0xa0 drivers/cpuidle/cpuidle.c:351
call_cpuidle kernel/sched/idle.c:158 [inline]
cpuidle_idle_call kernel/sched/idle.c:239 [inline]
do_idle+0x3e8/0x590 kernel/sched/idle.c:306
cpu_startup_entry+0x14/0x20 kernel/sched/idle.c:403
start_secondary+0x274/0x350 arch/x86/kernel/smpboot.c:272
secondary_startup_64_no_verify+0xb0/0xbb


---
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.
syzbot can test patches for this issue, for details see:
https://goo.gl/tpsmEJ#testing-patches

[syzbot]

syzbot suspects this issue was fixed by commit:

commit 0a9a25ca78437b39e691bcc3dc8240455b803d8d
Author: Ming Lei <ming...@redhat.com>
Date: Fri Mar 18 13:01:43 2022 +0000

block: let blkcg_gq grab request queue's refcnt

bisection log: https://syzkaller.appspot.com/x/bisect.txt?x=1004f05a080000
start commit: d6765985a42a Revert "be2net: disable bh with spin_lock in ..
git tree: net

kernel config: https://syzkaller.appspot.com/x/.config?x=7ca96a2d153c74b0
dashboard link: https://syzkaller.appspot.com/bug?extid=3ba0493d523d007b3819
syz repro: https://syzkaller.appspot.com/x/repro.syz?x=14c9edc8300000
C reproducer: https://syzkaller.appspot.com/x/repro.c?x=172463c8300000

If the result looks correct, please mark the issue as fixed by replying with:

#syz fix: block: let blkcg_gq grab request queue's refcnt

For information about bisection process see: https://goo.gl/tpsmEJ#bisection

[Hillf Danton]

On Thu, 01 Jul 2021 08:50:25 -0700

> syzbot found the following issue on:
>
> HEAD commit: d6765985 Revert "be2net: disable bh with spin_lock in be_p..
> git tree: net
> console output: https://syzkaller.appspot.com/x/log.txt?x=1085a0d8300000
> kernel config: https://syzkaller.appspot.com/x/.config?x=7ca96a2d153c74b0
> dashboard link: https://syzkaller.appspot.com/bug?extid=3ba0493d523d007b3819
> syz repro: https://syzkaller.appspot.com/x/repro.syz?x=14c9edc8300000
> C reproducer: https://syzkaller.appspot.com/x/repro.c?x=172463c8300000

And debug info to catch the softirq hog.

#syz test https://git.kernel.org/pub/scm/linux/kernel/git/netdev/net.git d6765985

diff -pur m/kernel/softirq.c n/kernel/softirq.c
--- m/kernel/softirq.c 2022-07-27 19:33:46.550253900 +0800
+++ n/kernel/softirq.c 2022-07-27 19:43:33.835184000 +0800
@@ -516,6 +516,7 @@ static inline void lockdep_softirq_end(b
asmlinkage __visible void __softirq_entry __do_softirq(void)
{
unsigned long end = jiffies + MAX_SOFTIRQ_TIME;
+ unsigned long ts_sum = jiffies + 2;
unsigned long old_flags = current->flags;
int max_restart = MAX_SOFTIRQ_RESTART;
struct softirq_action *h;
@@ -545,6 +546,7 @@ restart:
h = softirq_vec;

while ((softirq_bit = ffs(pending))) {
+ unsigned long ts_single = jiffies + 2;
unsigned int vec_nr;
int prev_count;

@@ -558,6 +560,11 @@ restart:
trace_softirq_entry(vec_nr);
h->action(h);
trace_softirq_exit(vec_nr);
+
+ WARN_ONCE(time_after(jiffies, ts_single),
+ "softirq hog %s\n", softirq_to_name[vec_nr]);
+ WARN_ON_ONCE(time_after(jiffies, ts_sum));
+
if (unlikely(prev_count != preempt_count())) {
pr_err("huh, entered softirq %u %s %p with preempt_count %08x, exited with %08x?\n",
vec_nr, softirq_to_name[vec_nr], h->action,
diff -pur m/net/core/dev.c n/net/core/dev.c
--- m/net/core/dev.c 2022-07-27 19:36:47.136101600 +0800
+++ n/net/core/dev.c 2022-07-27 19:45:49.911201000 +0800
@@ -5019,6 +5019,7 @@ static __latent_entropy void net_tx_acti

if (sd->output_queue) {
struct Qdisc *head;
+ unsigned long ts;

local_irq_disable();
head = sd->output_queue;
@@ -5028,12 +5029,15 @@ static __latent_entropy void net_tx_acti

rcu_read_lock();

+ ts = jiffies + 2;
+
while (head) {
struct Qdisc *q = head;
spinlock_t *root_lock = NULL;

head = head->next_sched;

+ WARN_ON_ONCE(time_after(jiffies, ts));
/* We need to make sure head->next_sched is read
* before clearing __QDISC_STATE_SCHED
*/
--

[syzbot]

Hello,

syzbot has tested the proposed patch but the reproducer is still triggering an issue:
WARNING in __do_softirq

hrtimer: interrupt took 5497694 ns
------------[ cut here ]------------
softirq hog NET_TX
WARNING: CPU: 0 PID: 5925 at kernel/softirq.c:564 __do_softirq+0x3c2/0xb44 kernel/softirq.c:564
Modules linked in:
CPU: 0 PID: 5925 Comm: syz-executor.0 Not tainted 5.13.0-rc6-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 06/29/2022
RIP: 0010:__do_softirq+0x3c2/0xb44 kernel/softirq.c:564
Code: 00 00 fc ff df 48 89 f8 48 c1 e8 03 80 3c 08 00 0f 85 25 07 00 00 4a 8b 34 ed e0 5b 6a 89 48 c7 c7 80 56 6a 89 e8 e9 7b 95 ff <0f> 0b e9 12 fe ff ff 65 8b 15 98 91 c1 76 83 fa 07 0f 87 94 04 00
RSP: 0018:ffffc90000007f78 EFLAGS: 00010282
RAX: 0000000000000000 RBX: ffffffff8b40a0d0 RCX: 0000000000000000
RDX: ffff888018ea9c40 RSI: ffffffff815ce2a5 RDI: fffff52000000fe1
RBP: 0000000000000002 R08: 0000000000000000 R09: 0000000000000000
R10: ffffffff815c810e R11: 0000000000000000 R12: 0000000000000101
R13: 0000000000000002 R14: 0000000000000001 R15: 0000000000000081
FS: 00007fe124111700(0000) GS:ffff8880b9c00000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 000000000051e370 CR3: 0000000011c93000 CR4: 00000000003506f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
<IRQ>
do_softirq.part.0+0xd9/0x130 kernel/softirq.c:460
</IRQ>
do_softirq kernel/softirq.c:452 [inline]
__local_bh_enable_ip+0x102/0x120 kernel/softirq.c:384
spin_unlock_bh include/linux/spinlock.h:399 [inline]
taprio_change+0x272d/0x4030 net/sched/sch_taprio.c:1641
taprio_init+0x52e/0x670 net/sched/sch_taprio.c:1759
qdisc_create+0x475/0x1310 net/sched/sch_api.c:1247
tc_modify_qdisc+0x4c8/0x1a50 net/sched/sch_api.c:1663
rtnetlink_rcv_msg+0x44e/0xad0 net/core/rtnetlink.c:5566
netlink_rcv_skb+0x153/0x420 net/netlink/af_netlink.c:2504
netlink_unicast_kernel net/netlink/af_netlink.c:1314 [inline]
netlink_unicast+0x533/0x7d0 net/netlink/af_netlink.c:1340
netlink_sendmsg+0x856/0xd90 net/netlink/af_netlink.c:1929
sock_sendmsg_nosec net/socket.c:654 [inline]
sock_sendmsg+0xcf/0x120 net/socket.c:674
____sys_sendmsg+0x6e8/0x810 net/socket.c:2337
___sys_sendmsg+0xf3/0x170 net/socket.c:2391
__sys_sendmsg+0xe5/0x1b0 net/socket.c:2420
do_syscall_64+0x3a/0xb0 arch/x86/entry/common.c:47
entry_SYSCALL_64_after_hwframe+0x44/0xae
RIP: 0033:0x4665d9
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 bc ff ff ff f7 d8 64 89 01 48
RSP: 002b:00007fe124111188 EFLAGS: 00000246 ORIG_RAX: 000000000000002e
RAX: ffffffffffffffda RBX: 000000000056bf80 RCX: 00000000004665d9
RDX: 0000000000000000 RSI: 00000000200007c0 RDI: 0000000000000004
RBP: 00000000004bfcb9 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 000000000056bf80
R13: 00007fff8efb607f R14: 00007fe124111300 R15: 0000000000022000


Tested on:

commit: d6765985 Revert "be2net: disable bh with spin_lock in ..
git tree: https://git.kernel.org/pub/scm/linux/kernel/git/netdev/net.git
console output: https://syzkaller.appspot.com/x/log.txt?x=11b32102080000
kernel config: https://syzkaller.appspot.com/x/.config?x=1d43f3e8616689bf
dashboard link: https://syzkaller.appspot.com/bug?extid=3ba0493d523d007b3819
compiler: gcc (Debian 10.2.1-6) 10.2.1 20210110, GNU ld (GNU Binutils for Debian) 2.35.2
patch: https://syzkaller.appspot.com/x/patch.diff?x=15c6b35a080000

[Hillf Danton]

On Thu, 01 Jul 2021 08:50:25 -0700

> syzbot found the following issue on:
>
> HEAD commit: d6765985 Revert "be2net: disable bh with spin_lock in be_p..
> git tree: net
> console output: https://syzkaller.appspot.com/x/log.txt?x=1085a0d8300000
> kernel config: https://syzkaller.appspot.com/x/.config?x=7ca96a2d153c74b0
> dashboard link: https://syzkaller.appspot.com/bug?extid=3ba0493d523d007b3819
> syz repro: https://syzkaller.appspot.com/x/repro.syz?x=14c9edc8300000
> C reproducer: https://syzkaller.appspot.com/x/repro.c?x=172463c8300000

Quit after transmitting two ticks to avoid softirq hog.

#syz test https://git.kernel.org/pub/scm/linux/kernel/git/netdev/net.git d6765985

--- m/net/core/dev.c
+++ n/net/core/dev.c
@@ -4990,6 +4990,7 @@ EXPORT_SYMBOL(netif_rx_any_context);
static __latent_entropy void net_tx_action(struct softirq_action *h)
{
struct softnet_data *sd = this_cpu_ptr(&softnet_data);
+ unsigned long ts = jiffies + 2;

if (sd->completion_queue) {
struct sk_buff *clist;
@@ -5034,6 +5035,11 @@ static __latent_entropy void net_tx_acti

head = head->next_sched;

+ if (time_after(jiffies, ts)) {
+ __netif_reschedule(q);
+ continue;
+ }
+

[syzbot]

Hello,

syzbot has tested the proposed patch but the reproducer is still triggering an issue:

INFO: rcu detected stall in net_tx_action

rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
(detected by 0, t=12253 jiffies, g=10185, q=161)
rcu: All QSes seen, last rcu_preempt kthread activity 12253 (4294958683-4294946430), jiffies_till_next_fqs=1, root ->qsmask 0x0
rcu: rcu_preempt kthread starved for 12253 jiffies! g10185 f0x2 RCU_GP_WAIT_FQS(5) ->state=0x0 ->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:R running task stack:28800 pid: 14 ppid: 2 flags:0x00004000
Call Trace:
context_switch kernel/sched/core.c:4339 [inline]
__schedule+0x916/0x23e0 kernel/sched/core.c:5147
schedule+0xcf/0x270 kernel/sched/core.c:5226
schedule_timeout+0x14a/0x250 kernel/time/timer.c:1892
rcu_gp_fqs_loop kernel/rcu/tree.c:2004 [inline]
rcu_gp_kthread+0xd07/0x2300 kernel/rcu/tree.c:2177
kthread+0x3b1/0x4a0 kernel/kthread.c:313
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:294
rcu: Stack dump where RCU GP kthread last ran:

NMI backtrace for cpu 0
CPU: 0 PID: 5 Comm: kworker/0:0 Not tainted 5.13.0-rc6-syzkaller #0

Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 06/29/2022

Workqueue: events_power_efficient toggle_allocation_gate

Call Trace:
<IRQ>
__dump_stack lib/dump_stack.c:79 [inline]
dump_stack+0x141/0x1d7 lib/dump_stack.c:120
nmi_cpu_backtrace.cold+0x44/0xd7 lib/nmi_backtrace.c:105
nmi_trigger_cpumask_backtrace+0x1b3/0x230 lib/nmi_backtrace.c:62
trigger_single_cpu_backtrace include/linux/nmi.h:164 [inline]
rcu_check_gp_kthread_starvation.cold+0x1cc/0x1d1 kernel/rcu/tree_stall.h:478

print_other_cpu_stall kernel/rcu/tree_stall.h:583 [inline]
check_cpu_stall kernel/rcu/tree_stall.h:708 [inline]
rcu_pending kernel/rcu/tree.c:3911 [inline]
rcu_sched_clock_irq+0x1d46/0x2080 kernel/rcu/tree.c:2649

update_process_times+0x16d/0x200 kernel/time/timer.c:1796
tick_sched_handle+0x9b/0x180 kernel/time/tick-sched.c:226
tick_sched_timer+0x1b0/0x2d0 kernel/time/tick-sched.c:1374
__run_hrtimer kernel/time/hrtimer.c:1537 [inline]
__hrtimer_run_queues+0x1c0/0xe40 kernel/time/hrtimer.c:1601
hrtimer_interrupt+0x330/0xa00 kernel/time/hrtimer.c:1663
local_apic_timer_interrupt arch/x86/kernel/apic/apic.c:1089 [inline]
__sysvec_apic_timer_interrupt+0x146/0x540 arch/x86/kernel/apic/apic.c:1106
sysvec_apic_timer_interrupt+0x40/0xc0 arch/x86/kernel/apic/apic.c:1100
asm_sysvec_apic_timer_interrupt+0x12/0x20 arch/x86/include/asm/idtentry.h:647
RIP: 0010:arch_safe_halt arch/x86/include/asm/irqflags.h:90 [inline]
RIP: 0010:kvm_wait arch/x86/kernel/kvm.c:888 [inline]
RIP: 0010:kvm_wait+0xb2/0x100 arch/x86/kernel/kvm.c:871

Code: 89 74 24 0c 48 89 3c 24 e8 3b 2c 48 00 8b 74 24 0c 48 8b 3c 24 eb 82 e8 5c 31 48 00 e9 07 00 00 00 0f 00 2d 90 10 36 08 fb f4 <eb> 98 e9 07 00 00 00 0f 00 2d 80 10 36 08 f4 eb bf 89 74 24 0c 48
RSP: 0018:ffffc90000007d88 EFLAGS: 00000206
RAX: 000000000003c406 RBX: 0000000000000000 RCX: 1ffffffff1f4ddb2

RDX: 0000000000000000 RSI: 0000000000000102 RDI: 0000000000000000

RBP: ffff8880301d08f0 R08: 0000000000000001 R09: ffffffff8fa2895f

R10: 0000000000000001 R11: 0000000000000000 R12: 0000000000000000

R13: ffffed100603a11e R14: 0000000000000001 R15: ffff8880b9c36400

pv_wait arch/x86/include/asm/paravirt.h:597 [inline]
pv_wait_head_or_lock kernel/locking/qspinlock_paravirt.h:470 [inline]
__pv_queued_spin_lock_slowpath+0x8b8/0xb40 kernel/locking/qspinlock.c:508
pv_queued_spin_lock_slowpath arch/x86/include/asm/paravirt.h:585 [inline]
queued_spin_lock_slowpath arch/x86/include/asm/qspinlock.h:51 [inline]
queued_spin_lock include/asm-generic/qspinlock.h:85 [inline]
do_raw_spin_lock+0x200/0x2b0 kernel/locking/spinlock_debug.c:113
spin_lock include/linux/spinlock.h:354 [inline]

net_tx_action+0x4c5/0xec0 net/core/dev.c:5050

__do_softirq+0x29b/0x9f6 kernel/softirq.c:559
invoke_softirq kernel/softirq.c:433 [inline]
__irq_exit_rcu+0x136/0x200 kernel/softirq.c:637
irq_exit_rcu+0x5/0x20 kernel/softirq.c:649
sysvec_apic_timer_interrupt+0x93/0xc0 arch/x86/kernel/apic/apic.c:1100
</IRQ>
asm_sysvec_apic_timer_interrupt+0x12/0x20 arch/x86/include/asm/idtentry.h:647

RIP: 0010:__sanitizer_cov_trace_const_cmp4+0x6b/0x70 kernel/kcov.c:286
Code: 00 00 00 48 39 fe 72 22 44 89 c6 48 83 c2 01 48 89 4c 38 f0 48 c7 44 38 e0 05 00 00 00 48 89 74 38 e8 4e 89 54 c8 20 48 89 10 <c3> 0f 1f 40 00 49 89 f8 bf 03 00 00 00 4c 8b 14 24 48 89 f1 65 48
RSP: 0018:ffffc90000ca79f0 EFLAGS: 00000246
RAX: 0000000000000000 RBX: ffff8880b9d3aaa0 RCX: 0000000000000001
RDX: 0000000000000000 RSI: ffff888011b50000 RDI: 0000000000000003
RBP: 0000000000000003 R08: 0000000000000000 R09: 0000000000000001
R10: ffffffff8169a046 R11: 0000000000000000 R12: ffffed10173a7555
R13: 0000000000000001 R14: ffff8880b9d3aaa8 R15: 0000000000000001
csd_lock_wait kernel/smp.c:440 [inline]
smp_call_function_many_cond+0x476/0xc20 kernel/smp.c:967
on_each_cpu_cond_mask+0x56/0xa0 kernel/smp.c:1133
on_each_cpu include/linux/smp.h:71 [inline]
text_poke_sync arch/x86/kernel/alternative.c:929 [inline]
text_poke_bp_batch+0x1b3/0x560 arch/x86/kernel/alternative.c:1114
text_poke_flush arch/x86/kernel/alternative.c:1268 [inline]
text_poke_flush arch/x86/kernel/alternative.c:1265 [inline]
text_poke_finish+0x16/0x30 arch/x86/kernel/alternative.c:1275
arch_jump_label_transform_apply+0x13/0x20 arch/x86/kernel/jump_label.c:122
jump_label_update+0x1da/0x400 kernel/jump_label.c:825
static_key_enable_cpuslocked+0x1b1/0x260 kernel/jump_label.c:177
static_key_enable+0x16/0x20 kernel/jump_label.c:190
toggle_allocation_gate mm/kfence/core.c:623 [inline]
toggle_allocation_gate+0x100/0x390 mm/kfence/core.c:615
process_one_work+0x98d/0x1600 kernel/workqueue.c:2276
worker_thread+0x64c/0x1120 kernel/workqueue.c:2422

kthread+0x3b1/0x4a0 kernel/kthread.c:313
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:294

Tested on:

commit: d6765985 Revert "be2net: disable bh with spin_lock in ..
git tree: https://git.kernel.org/pub/scm/linux/kernel/git/netdev/net.git

console output: https://syzkaller.appspot.com/x/log.txt?x=14c25202080000

kernel config: https://syzkaller.appspot.com/x/.config?x=1d43f3e8616689bf
dashboard link: https://syzkaller.appspot.com/bug?extid=3ba0493d523d007b3819
compiler: gcc (Debian 10.2.1-6) 10.2.1 20210110, GNU ld (GNU Binutils for Debian) 2.35.2

patch: https://syzkaller.appspot.com/x/patch.diff?x=1408beee080000

[Hillf Danton]

On Thu, 01 Jul 2021 08:50:25 -0700

> syzbot found the following issue on:
>
> HEAD commit: d6765985 Revert "be2net: disable bh with spin_lock in be_p..
> git tree: net
> console output: https://syzkaller.appspot.com/x/log.txt?x=1085a0d8300000
> kernel config: https://syzkaller.appspot.com/x/.config?x=7ca96a2d153c74b0
> dashboard link: https://syzkaller.appspot.com/bug?extid=3ba0493d523d007b3819
> syz repro: https://syzkaller.appspot.com/x/repro.syz?x=14c9edc8300000
> C reproducer: https://syzkaller.appspot.com/x/repro.c?x=172463c8300000

Trylock to avoid softirq hog.

#syz test https://git.kernel.org/pub/scm/linux/kernel/git/netdev/net.git d6765985

--- m/net/core/dev.c
+++ n/net/core/dev.c

@@ -5041,7 +5041,10 @@ static __latent_entropy void net_tx_acti

if (!(q->flags & TCQ_F_NOLOCK)) {
root_lock = qdisc_lock(q);
- spin_lock(root_lock);
+ if (!spin_trylock(root_lock)) {

+ __netif_reschedule(q);
+ continue;
+ }

} else if (unlikely(test_bit(__QDISC_STATE_DEACTIVATED,
&q->state))) {
/* There is a synchronize_net() between
--

[syzbot]

Hello,

syzbot has tested the proposed patch but the reproducer is still triggering an issue:

INFO: rcu detected stall in ieee80211_iface_work

hrtimer: interrupt took 7516710 ns

rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:

rcu: 0-...!: (1 GPs behind) idle=172/1/0x4000000000000000 softirq=7931/7939 fqs=0
(detected by 1, t=10571 jiffies, g=9957, q=578)

============================================
WARNING: possible recursive locking detected
5.13.0-rc6-syzkaller #0 Not tainted
--------------------------------------------
kworker/u4:5/216 is trying to acquire lock:
ffffffff8b782218 (rcu_node_0){-.-.}-{2:2}, at: rcu_dump_cpu_stacks+0xd0/0x3f0 kernel/rcu/tree_stall.h:336

but task is already holding lock:
ffffffff8b782218 (rcu_node_0){-.-.}-{2:2}, at: print_other_cpu_stall kernel/rcu/tree_stall.h:542 [inline]
ffffffff8b782218 (rcu_node_0){-.-.}-{2:2}, at: check_cpu_stall kernel/rcu/tree_stall.h:708 [inline]
ffffffff8b782218 (rcu_node_0){-.-.}-{2:2}, at: rcu_pending kernel/rcu/tree.c:3911 [inline]
ffffffff8b782218 (rcu_node_0){-.-.}-{2:2}, at: rcu_sched_clock_irq+0xc63/0x2080 kernel/rcu/tree.c:2649

other info that might help us debug this:
Possible unsafe locking scenario:

CPU0
----
lock(rcu_node_0);
lock(rcu_node_0);

*** DEADLOCK ***

May be due to missing lock nesting notation

5 locks held by kworker/u4:5/216:
#0: ffff88802de11138 ((wq_completion)phy6){+.+.}-{0:0}, at: arch_atomic64_set arch/x86/include/asm/atomic64_64.h:34 [inline]
#0: ffff88802de11138 ((wq_completion)phy6){+.+.}-{0:0}, at: atomic64_set include/asm-generic/atomic-instrumented.h:856 [inline]
#0: ffff88802de11138 ((wq_completion)phy6){+.+.}-{0:0}, at: atomic_long_set include/asm-generic/atomic-long.h:41 [inline]
#0: ffff88802de11138 ((wq_completion)phy6){+.+.}-{0:0}, at: set_work_data kernel/workqueue.c:617 [inline]
#0: ffff88802de11138 ((wq_completion)phy6){+.+.}-{0:0}, at: set_work_pool_and_clear_pending kernel/workqueue.c:644 [inline]
#0: ffff88802de11138 ((wq_completion)phy6){+.+.}-{0:0}, at: process_one_work+0x871/0x1600 kernel/workqueue.c:2247
#1: ffffc900018cfda8 ((work_completion)(&sdata->work)){+.+.}-{0:0}, at: process_one_work+0x8a5/0x1600 kernel/workqueue.c:2251
#2: ffff88801607cd00 (&wdev->mtx){+.+.}-{3:3}, at: sdata_lock net/mac80211/ieee80211_i.h:1003 [inline]
#2: ffff88801607cd00 (&wdev->mtx){+.+.}-{3:3}, at: ieee80211_ibss_rx_queued_mgmt+0xe9/0x1870 net/mac80211/ibss.c:1631
#3: ffff88802deb8170 (&rdev->bss_lock){+...}-{2:2}, at: spin_lock_bh include/linux/spinlock.h:359 [inline]
#3: ffff88802deb8170 (&rdev->bss_lock){+...}-{2:2}, at: cfg80211_bss_update+0x88/0x1e00 net/wireless/scan.c:1688
#4: ffffffff8b782218 (rcu_node_0){-.-.}-{2:2}, at: print_other_cpu_stall kernel/rcu/tree_stall.h:542 [inline]
#4: ffffffff8b782218 (rcu_node_0){-.-.}-{2:2}, at: check_cpu_stall kernel/rcu/tree_stall.h:708 [inline]
#4: ffffffff8b782218 (rcu_node_0){-.-.}-{2:2}, at: rcu_pending kernel/rcu/tree.c:3911 [inline]
#4: ffffffff8b782218 (rcu_node_0){-.-.}-{2:2}, at: rcu_sched_clock_irq+0xc63/0x2080 kernel/rcu/tree.c:2649

stack backtrace:
CPU: 1 PID: 216 Comm: kworker/u4:5 Not tainted 5.13.0-rc6-syzkaller #0

Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 06/29/2022

Workqueue: phy6 ieee80211_iface_work

Call Trace:
<IRQ>
__dump_stack lib/dump_stack.c:79 [inline]
dump_stack+0x141/0x1d7 lib/dump_stack.c:120

print_deadlock_bug kernel/locking/lockdep.c:2831 [inline]
check_deadlock kernel/locking/lockdep.c:2874 [inline]
validate_chain kernel/locking/lockdep.c:3663 [inline]
__lock_acquire.cold+0x22f/0x3b4 kernel/locking/lockdep.c:4902
lock_acquire kernel/locking/lockdep.c:5512 [inline]
lock_acquire+0x1ab/0x740 kernel/locking/lockdep.c:5477
__raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
_raw_spin_lock_irqsave+0x39/0x50 kernel/locking/spinlock.c:159
rcu_dump_cpu_stacks+0xd0/0x3f0 kernel/rcu/tree_stall.h:336
print_other_cpu_stall kernel/rcu/tree_stall.h:560 [inline]

check_cpu_stall kernel/rcu/tree_stall.h:708 [inline]
rcu_pending kernel/rcu/tree.c:3911 [inline]

rcu_sched_clock_irq+0x1a79/0x2080 kernel/rcu/tree.c:2649

update_process_times+0x16d/0x200 kernel/time/timer.c:1796
tick_sched_handle+0x9b/0x180 kernel/time/tick-sched.c:226
tick_sched_timer+0x1b0/0x2d0 kernel/time/tick-sched.c:1374
__run_hrtimer kernel/time/hrtimer.c:1537 [inline]
__hrtimer_run_queues+0x1c0/0xe40 kernel/time/hrtimer.c:1601
hrtimer_interrupt+0x330/0xa00 kernel/time/hrtimer.c:1663
local_apic_timer_interrupt arch/x86/kernel/apic/apic.c:1089 [inline]
__sysvec_apic_timer_interrupt+0x146/0x540 arch/x86/kernel/apic/apic.c:1106

sysvec_apic_timer_interrupt+0x8e/0xc0 arch/x86/kernel/apic/apic.c:1100
</IRQ>
asm_sysvec_apic_timer_interrupt+0x12/0x20 arch/x86/include/asm/idtentry.h:647
RIP: 0010:rol32 include/linux/bitops.h:108 [inline]
RIP: 0010:jhash2 include/linux/jhash.h:129 [inline]
RIP: 0010:hash_stack lib/stackdepot.c:181 [inline]
RIP: 0010:stack_depot_save+0xcf/0x4e0 lib/stackdepot.c:273
Code: 41 89 c0 89 f8 01 df c1 c0 06 44 31 c0 29 c3 41 89 d8 89 c3 01 f8 c1 c3 08 44 31 c3 41 89 d8 29 df 01 c3 41 c1 c0 10 44 31 c7 <41> 89 f8 29 f8 01 df 41 c1 c8 0d 44 31 c0 41 89 c0 29 c3 01 f8 41
RSP: 0018:ffffc900018ce878 EFLAGS: 00000286
RAX: 00000000ba727ad1 RBX: 00000000b859d5f5 RCX: 0000000000000011
RDX: ffffc900018ce93c RSI: 0000000000012b20 RDI: 00000000ba6c0718
RBP: ffffc900018ce8e8 R08: 000000005b24fde7 R09: ffffffff8dbd5dc4
R10: fffff52000319d03 R11: 0000000000084087 R12: 0000000000000013
R13: 0000000000000013 R14: 0000000000012b20 R15: 0000000000012b20
kasan_save_stack+0x32/0x40 mm/kasan/common.c:40
kasan_set_track mm/kasan/common.c:46 [inline]
set_alloc_info mm/kasan/common.c:428 [inline]
__kasan_slab_alloc+0x84/0xa0 mm/kasan/common.c:461
kasan_slab_alloc include/linux/kasan.h:236 [inline]
slab_post_alloc_hook mm/slab.h:524 [inline]
slab_alloc_node mm/slub.c:2914 [inline]
slab_alloc mm/slub.c:2922 [inline]
kmem_cache_alloc+0x219/0x3a0 mm/slub.c:2927
kmem_cache_zalloc include/linux/slab.h:676 [inline]
fill_pool+0x264/0x5c0 lib/debugobjects.c:171
__debug_object_init+0x7a/0xd10 lib/debugobjects.c:560
debug_object_init lib/debugobjects.c:615 [inline]
debug_object_activate+0x32c/0x3e0 lib/debugobjects.c:701
debug_rcu_head_queue kernel/rcu/rcu.h:176 [inline]
kvfree_call_rcu+0x32/0x8c0 kernel/rcu/tree.c:3588
cfg80211_update_known_bss+0x833/0xa60 net/wireless/scan.c:1651
cfg80211_bss_update+0xef/0x1e00 net/wireless/scan.c:1698
cfg80211_inform_single_bss_frame_data+0x6e8/0xee0 net/wireless/scan.c:2404
cfg80211_inform_bss_frame_data+0xa7/0xb10 net/wireless/scan.c:2437
ieee80211_bss_info_update+0x3ce/0xb20 net/mac80211/scan.c:190
ieee80211_rx_bss_info net/mac80211/ibss.c:1126 [inline]
ieee80211_rx_mgmt_probe_beacon+0xccd/0x16b0 net/mac80211/ibss.c:1615
ieee80211_ibss_rx_queued_mgmt+0xe43/0x1870 net/mac80211/ibss.c:1642
ieee80211_iface_work+0x761/0x9e0 net/mac80211/iface.c:1439

process_one_work+0x98d/0x1600 kernel/workqueue.c:2276
worker_thread+0x64c/0x1120 kernel/workqueue.c:2422
kthread+0x3b1/0x4a0 kernel/kthread.c:313
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:294


Tested on:

commit: d6765985 Revert "be2net: disable bh with spin_lock in ..
git tree: https://git.kernel.org/pub/scm/linux/kernel/git/netdev/net.git

console output: https://syzkaller.appspot.com/x/log.txt?x=11e98d64080000

kernel config: https://syzkaller.appspot.com/x/.config?x=1d43f3e8616689bf
dashboard link: https://syzkaller.appspot.com/bug?extid=3ba0493d523d007b3819
compiler: gcc (Debian 10.2.1-6) 10.2.1 20210110, GNU ld (GNU Binutils for Debian) 2.35.2

patch: https://syzkaller.appspot.com/x/patch.diff?x=13d694d2080000

[Ming Lei]

On Tue, Jul 26, 2022 at 08:50:09AM -0700, syzbot wrote:
> syzbot suspects this issue was fixed by commit:
>
> commit 0a9a25ca78437b39e691bcc3dc8240455b803d8d
> Author: Ming Lei <ming...@redhat.com>
> Date: Fri Mar 18 13:01:43 2022 +0000
>
> block: let blkcg_gq grab request queue's refcnt
>
> bisection log: https://syzkaller.appspot.com/x/bisect.txt?x=1004f05a080000
> start commit: d6765985a42a Revert "be2net: disable bh with spin_lock in ..
> git tree: net
> kernel config: https://syzkaller.appspot.com/x/.config?x=7ca96a2d153c74b0
> dashboard link: https://syzkaller.appspot.com/bug?extid=3ba0493d523d007b3819
> syz repro: https://syzkaller.appspot.com/x/repro.syz?x=14c9edc8300000
> C reproducer: https://syzkaller.appspot.com/x/repro.c?x=172463c8300000
>

The bad commit has been fixed by the following patch:

d578c770c852 block: avoid calling blkg_free() in atomic context



Thanks,
Ming

[Hillf Danton]

On Thu, 01 Jul 2021 08:50:25 -0700

> syzbot found the following issue on:
>
> HEAD commit: d6765985 Revert "be2net: disable bh with spin_lock in be_p..
> git tree: net
> console output: https://syzkaller.appspot.com/x/log.txt?x=1085a0d8300000
> kernel config: https://syzkaller.appspot.com/x/.config?x=7ca96a2d153c74b0
> dashboard link: https://syzkaller.appspot.com/bug?extid=3ba0493d523d007b3819
> syz repro: https://syzkaller.appspot.com/x/repro.syz?x=14c9edc8300000
> C reproducer: https://syzkaller.appspot.com/x/repro.c?x=172463c8300000

v1, Trylock to avoid softirq hog.
v2, release rnp->lock to avoid recursive deadlock.

#syz test https://git.kernel.org/pub/scm/linux/kernel/git/netdev/net.git d6765985

--- m/net/core/dev.c
+++ n/net/core/dev.c
@@ -5041,7 +5041,10 @@ static __latent_entropy void net_tx_acti

if (!(q->flags & TCQ_F_NOLOCK)) {
root_lock = qdisc_lock(q);
- spin_lock(root_lock);
+ if (!spin_trylock(root_lock)) {
+ __netif_reschedule(q);
+ continue;
+ }
} else if (unlikely(test_bit(__QDISC_STATE_DEACTIVATED,
&q->state))) {
/* There is a synchronize_net() between

--- m/kernel/rcu/tree_stall.h
+++ n/kernel/rcu/tree_stall.h
@@ -267,8 +267,10 @@ static int rcu_print_task_stall(struct r
struct task_struct *ts[8];

lockdep_assert_irqs_disabled();
- if (!rcu_preempt_blocked_readers_cgp(rnp))
+ if (!rcu_preempt_blocked_readers_cgp(rnp)) {
+ raw_spin_unlock_irqrestore_rcu_node(rnp, flags);
return 0;
+ }
pr_err("\tTasks blocked on level-%d rcu_node (CPUs %d-%d):",
rnp->level, rnp->grplo, rnp->grphi);
t = list_entry(rnp->gp_tasks->prev,
--

[syzbot]

Hello,

syzbot has tested the proposed patch but the reproducer is still triggering an issue:

INFO: rcu detected stall in tc_modify_qdisc

rcu: INFO: rcu_preempt self-detected stall on CPU

rcu: 1-...!: (11 ticks this GP) idle=1ba/1/0x4000000000000000 softirq=8504/8504 fqs=0
(t=13199 jiffies g=9753 q=157)
rcu: rcu_preempt kthread timer wakeup didn't happen for 13198 jiffies! g9753 f0x0 RCU_GP_WAIT_FQS(5) ->state=0x402
rcu: Possible timer handling issue on cpu=1 timer-softirq=2661
rcu: rcu_preempt kthread starved for 13199 jiffies! g9753 f0x0 RCU_GP_WAIT_FQS(5) ->state=0x402 ->cpu=1

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:29480 pid: 14 ppid: 2 flags:0x00004000

Call Trace:
context_switch kernel/sched/core.c:4339 [inline]
__schedule+0x916/0x23e0 kernel/sched/core.c:5147
schedule+0xcf/0x270 kernel/sched/core.c:5226
schedule_timeout+0x14a/0x250 kernel/time/timer.c:1892
rcu_gp_fqs_loop kernel/rcu/tree.c:2004 [inline]
rcu_gp_kthread+0xd07/0x2300 kernel/rcu/tree.c:2177

kthread+0x3b1/0x4a0 kernel/kthread.c:313
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:294

rcu: Stack dump where RCU GP kthread last ran:

NMI backtrace for cpu 1
CPU: 1 PID: 5948 Comm: syz-executor.0 Not tainted 5.13.0-rc6-syzkaller #0

Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 06/29/2022

Call Trace:
<IRQ>
__dump_stack lib/dump_stack.c:79 [inline]
dump_stack+0x141/0x1d7 lib/dump_stack.c:120

nmi_cpu_backtrace.cold+0x44/0xd7 lib/nmi_backtrace.c:105
nmi_trigger_cpumask_backtrace+0x1b3/0x230 lib/nmi_backtrace.c:62
trigger_single_cpu_backtrace include/linux/nmi.h:164 [inline]

rcu_check_gp_kthread_starvation.cold+0x1cc/0x1d1 kernel/rcu/tree_stall.h:480
print_cpu_stall kernel/rcu/tree_stall.h:624 [inline]
check_cpu_stall kernel/rcu/tree_stall.h:701 [inline]
rcu_pending kernel/rcu/tree.c:3911 [inline]
rcu_sched_clock_irq.cold+0x9a/0x747 kernel/rcu/tree.c:2649

update_process_times+0x16d/0x200 kernel/time/timer.c:1796
tick_sched_handle+0x9b/0x180 kernel/time/tick-sched.c:226
tick_sched_timer+0x1b0/0x2d0 kernel/time/tick-sched.c:1374
__run_hrtimer kernel/time/hrtimer.c:1537 [inline]
__hrtimer_run_queues+0x1c0/0xe40 kernel/time/hrtimer.c:1601
hrtimer_interrupt+0x330/0xa00 kernel/time/hrtimer.c:1663
local_apic_timer_interrupt arch/x86/kernel/apic/apic.c:1089 [inline]
__sysvec_apic_timer_interrupt+0x146/0x540 arch/x86/kernel/apic/apic.c:1106
sysvec_apic_timer_interrupt+0x8e/0xc0 arch/x86/kernel/apic/apic.c:1100
</IRQ>
asm_sysvec_apic_timer_interrupt+0x12/0x20 arch/x86/include/asm/idtentry.h:647

RIP: 0010:check_kcov_mode kernel/kcov.c:163 [inline]
RIP: 0010:__sanitizer_cov_trace_pc+0x7/0x60 kernel/kcov.c:197
Code: ff ff b9 ff ff ff ff ba 08 00 00 00 4d 8b 03 48 0f bd ca 49 8b 45 00 48 63 c9 e9 64 ff ff ff 0f 1f 40 00 65 8b 05 59 15 8d 7e <89> c1 48 8b 34 24 81 e1 00 01 00 00 65 48 8b 14 25 00 f0 01 00 a9
RSP: 0018:ffffc900018af270 EFLAGS: 00000202
RAX: 0000000000000201 RBX: ffff8880157ca340 RCX: 0000000000000000
RDX: 0000000000000202 RSI: 0000000000000202 RDI: 0000000000000001
RBP: ffff8880b9c26580 R08: 0000000000000001 R09: ffffffff8fa2895f
R10: 0000000000000001 R11: 0000000000000000 R12: 00000000ffffffff
R13: 0000000000000246 R14: ffff8880b9c26580 R15: dffffc0000000000
hrtimer_try_to_cancel+0x36/0x1e0 kernel/time/hrtimer.c:1180
hrtimer_cancel+0x13/0x40 kernel/time/hrtimer.c:1295
taprio_reset+0x72/0x280 net/sched/sch_taprio.c:1656
qdisc_reset+0xdb/0x730 net/sched/sch_generic.c:951
dev_reset_queue+0x92/0x120 net/sched/sch_generic.c:1202
netdev_for_each_tx_queue include/linux/netdevice.h:2337 [inline]
dev_deactivate_many+0x551/0xc30 net/sched/sch_generic.c:1267
dev_deactivate+0xe9/0x1b0 net/sched/sch_generic.c:1290
qdisc_graft+0xdc1/0x1260 net/sched/sch_api.c:1055
tc_modify_qdisc+0xb5a/0x1a50 net/sched/sch_api.c:1674

rtnetlink_rcv_msg+0x44e/0xad0 net/core/rtnetlink.c:5566
netlink_rcv_skb+0x153/0x420 net/netlink/af_netlink.c:2504
netlink_unicast_kernel net/netlink/af_netlink.c:1314 [inline]
netlink_unicast+0x533/0x7d0 net/netlink/af_netlink.c:1340
netlink_sendmsg+0x856/0xd90 net/netlink/af_netlink.c:1929
sock_sendmsg_nosec net/socket.c:654 [inline]
sock_sendmsg+0xcf/0x120 net/socket.c:674
____sys_sendmsg+0x6e8/0x810 net/socket.c:2337
___sys_sendmsg+0xf3/0x170 net/socket.c:2391
__sys_sendmsg+0xe5/0x1b0 net/socket.c:2420
do_syscall_64+0x3a/0xb0 arch/x86/entry/common.c:47
entry_SYSCALL_64_after_hwframe+0x44/0xae
RIP: 0033:0x4665d9
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 bc ff ff ff f7 d8 64 89 01 48

RSP: 002b:00007f74e9479188 EFLAGS: 00000246 ORIG_RAX: 000000000000002e

RAX: ffffffffffffffda RBX: 000000000056bf80 RCX: 00000000004665d9
RDX: 0000000000000000 RSI: 00000000200007c0 RDI: 0000000000000004
RBP: 00000000004bfcb9 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 000000000056bf80

R13: 00007ffe32f717ef R14: 00007f74e9479300 R15: 0000000000022000

NMI backtrace for cpu 1

CPU: 1 PID: 5948 Comm: syz-executor.0 Not tainted 5.13.0-rc6-syzkaller #0

Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 06/29/2022

Call Trace:
<IRQ>
__dump_stack lib/dump_stack.c:79 [inline]
dump_stack+0x141/0x1d7 lib/dump_stack.c:120

nmi_cpu_backtrace.cold+0x44/0xd7 lib/nmi_backtrace.c:105
nmi_trigger_cpumask_backtrace+0x1b3/0x230 lib/nmi_backtrace.c:62
trigger_single_cpu_backtrace include/linux/nmi.h:164 [inline]

rcu_dump_cpu_stacks+0x25e/0x3f0 kernel/rcu/tree_stall.h:343
print_cpu_stall kernel/rcu/tree_stall.h:626 [inline]
check_cpu_stall kernel/rcu/tree_stall.h:701 [inline]
rcu_pending kernel/rcu/tree.c:3911 [inline]
rcu_sched_clock_irq.cold+0x9f/0x747 kernel/rcu/tree.c:2649

update_process_times+0x16d/0x200 kernel/time/timer.c:1796
tick_sched_handle+0x9b/0x180 kernel/time/tick-sched.c:226
tick_sched_timer+0x1b0/0x2d0 kernel/time/tick-sched.c:1374
__run_hrtimer kernel/time/hrtimer.c:1537 [inline]
__hrtimer_run_queues+0x1c0/0xe40 kernel/time/hrtimer.c:1601
hrtimer_interrupt+0x330/0xa00 kernel/time/hrtimer.c:1663
local_apic_timer_interrupt arch/x86/kernel/apic/apic.c:1089 [inline]
__sysvec_apic_timer_interrupt+0x146/0x540 arch/x86/kernel/apic/apic.c:1106
sysvec_apic_timer_interrupt+0x8e/0xc0 arch/x86/kernel/apic/apic.c:1100
</IRQ>
asm_sysvec_apic_timer_interrupt+0x12/0x20 arch/x86/include/asm/idtentry.h:647

RIP: 0010:check_kcov_mode kernel/kcov.c:163 [inline]
RIP: 0010:__sanitizer_cov_trace_pc+0x7/0x60 kernel/kcov.c:197
Code: ff ff b9 ff ff ff ff ba 08 00 00 00 4d 8b 03 48 0f bd ca 49 8b 45 00 48 63 c9 e9 64 ff ff ff 0f 1f 40 00 65 8b 05 59 15 8d 7e <89> c1 48 8b 34 24 81 e1 00 01 00 00 65 48 8b 14 25 00 f0 01 00 a9
RSP: 0018:ffffc900018af270 EFLAGS: 00000202
RAX: 0000000000000201 RBX: ffff8880157ca340 RCX: 0000000000000000
RDX: 0000000000000202 RSI: 0000000000000202 RDI: 0000000000000001
RBP: ffff8880b9c26580 R08: 0000000000000001 R09: ffffffff8fa2895f
R10: 0000000000000001 R11: 0000000000000000 R12: 00000000ffffffff
R13: 0000000000000246 R14: ffff8880b9c26580 R15: dffffc0000000000
hrtimer_try_to_cancel+0x36/0x1e0 kernel/time/hrtimer.c:1180
hrtimer_cancel+0x13/0x40 kernel/time/hrtimer.c:1295
taprio_reset+0x72/0x280 net/sched/sch_taprio.c:1656
qdisc_reset+0xdb/0x730 net/sched/sch_generic.c:951
dev_reset_queue+0x92/0x120 net/sched/sch_generic.c:1202
netdev_for_each_tx_queue include/linux/netdevice.h:2337 [inline]
dev_deactivate_many+0x551/0xc30 net/sched/sch_generic.c:1267
dev_deactivate+0xe9/0x1b0 net/sched/sch_generic.c:1290
qdisc_graft+0xdc1/0x1260 net/sched/sch_api.c:1055
tc_modify_qdisc+0xb5a/0x1a50 net/sched/sch_api.c:1674

rtnetlink_rcv_msg+0x44e/0xad0 net/core/rtnetlink.c:5566
netlink_rcv_skb+0x153/0x420 net/netlink/af_netlink.c:2504
netlink_unicast_kernel net/netlink/af_netlink.c:1314 [inline]
netlink_unicast+0x533/0x7d0 net/netlink/af_netlink.c:1340
netlink_sendmsg+0x856/0xd90 net/netlink/af_netlink.c:1929
sock_sendmsg_nosec net/socket.c:654 [inline]
sock_sendmsg+0xcf/0x120 net/socket.c:674
____sys_sendmsg+0x6e8/0x810 net/socket.c:2337
___sys_sendmsg+0xf3/0x170 net/socket.c:2391
__sys_sendmsg+0xe5/0x1b0 net/socket.c:2420
do_syscall_64+0x3a/0xb0 arch/x86/entry/common.c:47
entry_SYSCALL_64_after_hwframe+0x44/0xae
RIP: 0033:0x4665d9
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 bc ff ff ff f7 d8 64 89 01 48

RSP: 002b:00007f74e9479188 EFLAGS: 00000246 ORIG_RAX: 000000000000002e

RAX: ffffffffffffffda RBX: 000000000056bf80 RCX: 00000000004665d9
RDX: 0000000000000000 RSI: 00000000200007c0 RDI: 0000000000000004
RBP: 00000000004bfcb9 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 000000000056bf80

R13: 00007ffe32f717ef R14: 00007f74e9479300 R15: 0000000000022000

Tested on:

commit: d6765985 Revert "be2net: disable bh with spin_lock in ..
git tree: https://git.kernel.org/pub/scm/linux/kernel/git/netdev/net.git

console output: https://syzkaller.appspot.com/x/log.txt?x=174b2102080000

kernel config: https://syzkaller.appspot.com/x/.config?x=1d43f3e8616689bf
dashboard link: https://syzkaller.appspot.com/bug?extid=3ba0493d523d007b3819
compiler: gcc (Debian 10.2.1-6) 10.2.1 20210110, GNU ld (GNU Binutils for Debian) 2.35.2

patch: https://syzkaller.appspot.com/x/patch.diff?x=1648beee080000

[Hillf Danton]

On Thu, 01 Jul 2021 08:50:25 -0700

> syzbot found the following issue on:
>
> HEAD commit: d6765985 Revert "be2net: disable bh with spin_lock in be_p..
> git tree: net
> console output: https://syzkaller.appspot.com/x/log.txt?x=1085a0d8300000
> kernel config: https://syzkaller.appspot.com/x/.config?x=7ca96a2d153c74b0
> dashboard link: https://syzkaller.appspot.com/bug?extid=3ba0493d523d007b3819
> syz repro: https://syzkaller.appspot.com/x/repro.syz?x=14c9edc8300000
> C reproducer: https://syzkaller.appspot.com/x/repro.c?x=172463c8300000

v1, Trylock to avoid softirq hog.
v2, release rnp->lock to avoid recursive deadlock.

v3, add change to hrtimer.

--- m/kernel/time/hrtimer.c
+++ n/kernel/time/hrtimer.c
@@ -1030,12 +1030,13 @@ static void __remove_hrtimer(struct hrti
* remove hrtimer, called with base lock held
*/
static inline int
-remove_hrtimer(struct hrtimer *timer, struct hrtimer_clock_base *base, bool restart)
+remove_hrtimer(struct hrtimer *timer, struct hrtimer_clock_base *base,
+ bool restart, bool keep_local)
{
u8 state = timer->state;

if (state & HRTIMER_STATE_ENQUEUED) {
- int reprogram;
+ bool reprogram;

/*
* Remove the timer and force reprogramming when high
@@ -1048,8 +1049,16 @@ remove_hrtimer(struct hrtimer *timer, st
debug_deactivate(timer);
reprogram = base->cpu_base == this_cpu_ptr(&hrtimer_bases);

+ /*
+ * If the timer is not restarted then reprogramming is
+ * required if the timer is local. If it is local and about
+ * to be restarted, avoid programming it twice (on removal
+ * and a moment later when it's requeued).
+ */
if (!restart)
state = HRTIMER_STATE_INACTIVE;
+ else
+ reprogram &= !keep_local;

__remove_hrtimer(timer, base, state, reprogram);
return 1;
@@ -1103,9 +1112,31 @@ static int __hrtimer_start_range_ns(stru
struct hrtimer_clock_base *base)
{
struct hrtimer_clock_base *new_base;
+ bool force_local, first;

- /* Remove an active timer from the queue: */
- remove_hrtimer(timer, base, true);
+ /*
+ * If the timer is on the local cpu base and is the first expiring
+ * timer then this might end up reprogramming the hardware twice
+ * (on removal and on enqueue). To avoid that by prevent the
+ * reprogram on removal, keep the timer local to the current CPU
+ * and enforce reprogramming after it is queued no matter whether
+ * it is the new first expiring timer again or not.
+ */
+ force_local = base->cpu_base == this_cpu_ptr(&hrtimer_bases);
+ force_local &= base->cpu_base->next_timer == timer;
+
+ /*
+ * Remove an active timer from the queue. In case it is not queued
+ * on the current CPU, make sure that remove_hrtimer() updates the
+ * remote data correctly.
+ *
+ * If it's on the current CPU and the first expiring timer, then
+ * skip reprogramming, keep the timer local and enforce
+ * reprogramming later if it was the first expiring timer. This
+ * avoids programming the underlying clock event twice (once at
+ * removal and once after enqueue).
+ */
+ remove_hrtimer(timer, base, true, force_local);

if (mode & HRTIMER_MODE_REL)
tim = ktime_add_safe(tim, base->get_time());
@@ -1115,9 +1146,24 @@ static int __hrtimer_start_range_ns(stru
hrtimer_set_expires_range_ns(timer, tim, delta_ns);

/* Switch the timer base, if necessary: */
- new_base = switch_hrtimer_base(timer, base, mode & HRTIMER_MODE_PINNED);
+ if (!force_local) {
+ new_base = switch_hrtimer_base(timer, base,
+ mode & HRTIMER_MODE_PINNED);
+ } else {
+ new_base = base;
+ }

- return enqueue_hrtimer(timer, new_base, mode);
+ first = enqueue_hrtimer(timer, new_base, mode);
+ if (!force_local)
+ return first;
+
+ /*
+ * Timer was forced to stay on the current CPU to avoid
+ * reprogramming on removal and enqueue. Force reprogram the
+ * hardware by evaluating the new first expiring timer.
+ */
+ hrtimer_force_reprogram(new_base->cpu_base, 1);
+ return 0;
}

/**
@@ -1183,7 +1229,7 @@ int hrtimer_try_to_cancel(struct hrtimer
base = lock_hrtimer_base(timer, &flags);

if (!hrtimer_callback_running(timer))
- ret = remove_hrtimer(timer, base, false);
+ ret = remove_hrtimer(timer, base, false, false);

unlock_hrtimer_base(timer, &flags);

--

[syzbot]

Hello,

syzbot has tested the proposed patch but the reproducer is still triggering an issue:

INFO: rcu detected stall in smp_call_function

hrtimer: interrupt took 6731213 ns

rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:

(detected by 1, t=16762 jiffies, g=9593, q=459)
rcu: All QSes seen, last rcu_preempt kthread activity 15495 (4294962574-4294947079), jiffies_till_next_fqs=1, root ->qsmask 0x0
rcu: rcu_preempt kthread starved for 15495 jiffies! g9593 f0x2 RCU_GP_WAIT_FQS(5) ->state=0x0 ->cpu=1

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:R running task stack:28800 pid: 14 ppid: 2 flags:0x00004000

Call Trace:
context_switch kernel/sched/core.c:4339 [inline]
__schedule+0x916/0x23e0 kernel/sched/core.c:5147
schedule+0xcf/0x270 kernel/sched/core.c:5226
schedule_timeout+0x14a/0x250 kernel/time/timer.c:1892
rcu_gp_fqs_loop kernel/rcu/tree.c:2004 [inline]
rcu_gp_kthread+0xd07/0x2300 kernel/rcu/tree.c:2177
kthread+0x3b1/0x4a0 kernel/kthread.c:313
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:294
rcu: Stack dump where RCU GP kthread last ran:
NMI backtrace for cpu 1

CPU: 1 PID: 25 Comm: kworker/u4:1 Not tainted 5.13.0-rc6-syzkaller #0

Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 06/29/2022

Workqueue: writeback wb_workfn (flush-8:0)

Call Trace:
<IRQ>
__dump_stack lib/dump_stack.c:79 [inline]
dump_stack+0x141/0x1d7 lib/dump_stack.c:120
nmi_cpu_backtrace.cold+0x44/0xd7 lib/nmi_backtrace.c:105
nmi_trigger_cpumask_backtrace+0x1b3/0x230 lib/nmi_backtrace.c:62
trigger_single_cpu_backtrace include/linux/nmi.h:164 [inline]
rcu_check_gp_kthread_starvation.cold+0x1cc/0x1d1 kernel/rcu/tree_stall.h:480

print_other_cpu_stall kernel/rcu/tree_stall.h:585 [inline]
check_cpu_stall kernel/rcu/tree_stall.h:710 [inline]
rcu_pending kernel/rcu/tree.c:3911 [inline]
rcu_sched_clock_irq+0x2079/0x20e0 kernel/rcu/tree.c:2649

update_process_times+0x16d/0x200 kernel/time/timer.c:1796
tick_sched_handle+0x9b/0x180 kernel/time/tick-sched.c:226
tick_sched_timer+0x1b0/0x2d0 kernel/time/tick-sched.c:1374

__run_hrtimer kernel/time/hrtimer.c:1583 [inline]
__hrtimer_run_queues+0x1c0/0xe40 kernel/time/hrtimer.c:1647
hrtimer_interrupt+0x330/0xa00 kernel/time/hrtimer.c:1709

local_apic_timer_interrupt arch/x86/kernel/apic/apic.c:1089 [inline]
__sysvec_apic_timer_interrupt+0x146/0x540 arch/x86/kernel/apic/apic.c:1106
sysvec_apic_timer_interrupt+0x8e/0xc0 arch/x86/kernel/apic/apic.c:1100
</IRQ>
asm_sysvec_apic_timer_interrupt+0x12/0x20 arch/x86/include/asm/idtentry.h:647

RIP: 0010:csd_lock_wait kernel/smp.c:440 [inline]
RIP: 0010:smp_call_function_many_cond+0x452/0xc20 kernel/smp.c:967
Code: 0b 00 85 ed 74 4d 48 b8 00 00 00 00 00 fc ff df 4d 89 f4 4c 89 f5 49 c1 ec 03 83 e5 07 49 01 c4 83 c5 03 e8 e0 39 0b 00 f3 90 <41> 0f b6 04 24 40 38 c5 7c 08 84 c0 0f 85 33 06 00 00 8b 43 08 31
RSP: 0018:ffffc90000dfef48 EFLAGS: 00000293
RAX: 0000000000000000 RBX: ffff8880b9c3bee0 RCX: 0000000000000000
RDX: ffff8880157c1c40 RSI: ffffffff8169a180 RDI: 0000000000000003
RBP: 0000000000000003 R08: 0000000000000000 R09: 0000000000000000
R10: ffffffff8169a1a6 R11: 0000000000000000 R12: ffffed10173877dd
R13: 0000000000000000 R14: ffff8880b9c3bee8 R15: 0000000000000001
on_each_cpu_cond_mask+0x56/0xa0 kernel/smp.c:1133
__flush_tlb_multi arch/x86/include/asm/paravirt.h:87 [inline]
flush_tlb_multi arch/x86/mm/tlb.c:862 [inline]
flush_tlb_mm_range+0x1d8/0x230 arch/x86/mm/tlb.c:948
flush_tlb_page arch/x86/include/asm/tlbflush.h:239 [inline]
ptep_clear_flush+0x12b/0x160 mm/pgtable-generic.c:97
page_mkclean_one+0x4d1/0xa80 mm/rmap.c:934
rmap_walk_file+0x397/0x860 mm/rmap.c:1951
rmap_walk+0x105/0x190 mm/rmap.c:1969
page_mkclean+0x21c/0x2b0 mm/rmap.c:1002
clear_page_dirty_for_io+0x31c/0xa10 mm/page-writeback.c:2698
mpage_submit_page+0x80/0x2a0 fs/ext4/inode.c:2080
mpage_map_and_submit_buffers fs/ext4/inode.c:2348 [inline]
mpage_map_and_submit_extent fs/ext4/inode.c:2487 [inline]
ext4_writepages+0x24c1/0x3b70 fs/ext4/inode.c:2800
do_writepages+0xec/0x290 mm/page-writeback.c:2352
__writeback_single_inode+0x126/0xfd0 fs/fs-writeback.c:1467
writeback_sb_inodes+0x53d/0xef0 fs/fs-writeback.c:1732
__writeback_inodes_wb+0xc6/0x280 fs/fs-writeback.c:1801
wb_writeback+0x814/0xc40 fs/fs-writeback.c:1907
wb_check_old_data_flush fs/fs-writeback.c:2009 [inline]
wb_do_writeback fs/fs-writeback.c:2062 [inline]
wb_workfn+0x891/0x12d0 fs/fs-writeback.c:2091

process_one_work+0x98d/0x1600 kernel/workqueue.c:2276
worker_thread+0x64c/0x1120 kernel/workqueue.c:2422

kthread+0x3b1/0x4a0 kernel/kthread.c:313
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:294

Tested on:

commit: d6765985 Revert "be2net: disable bh with spin_lock in ..
git tree: https://git.kernel.org/pub/scm/linux/kernel/git/netdev/net.git

console output: https://syzkaller.appspot.com/x/log.txt?x=143f08d2080000

kernel config: https://syzkaller.appspot.com/x/.config?x=1d43f3e8616689bf
dashboard link: https://syzkaller.appspot.com/bug?extid=3ba0493d523d007b3819
compiler: gcc (Debian 10.2.1-6) 10.2.1 20210110, GNU ld (GNU Binutils for Debian) 2.35.2

patch: https://syzkaller.appspot.com/x/patch.diff?x=14f00172080000

[Hillf Danton]

On Thu, 01 Jul 2021 08:50:25 -0700

> syzbot found the following issue on:
>
> HEAD commit: d6765985 Revert "be2net: disable bh with spin_lock in be_p..
> git tree: net
> console output: https://syzkaller.appspot.com/x/log.txt?x=1085a0d8300000
> kernel config: https://syzkaller.appspot.com/x/.config?x=7ca96a2d153c74b0
> dashboard link: https://syzkaller.appspot.com/bug?extid=3ba0493d523d007b3819
> syz repro: https://syzkaller.appspot.com/x/repro.syz?x=14c9edc8300000
> C reproducer: https://syzkaller.appspot.com/x/repro.c?x=172463c8300000

@@ -652,21 +652,10 @@ static inline int hrtimer_hres_active(vo
return __hrtimer_hres_active(this_cpu_ptr(&hrtimer_bases));
}

-/*
- * Reprogram the event source with checking both queues for the
- * next event
- * Called with interrupts disabled and base->lock held
- */
-static void
-hrtimer_force_reprogram(struct hrtimer_cpu_base *cpu_base, int skip_equal)
+static void __hrtimer_reprogram(struct hrtimer_cpu_base *cpu_base,
+ struct hrtimer *next_timer,
+ ktime_t expires_next)
{
- ktime_t expires_next;
-
- expires_next = hrtimer_update_next_event(cpu_base);
-
- if (skip_equal && expires_next == cpu_base->expires_next)
- return;
-
cpu_base->expires_next = expires_next;

/*
@@ -689,7 +678,25 @@ hrtimer_force_reprogram(struct hrtimer_c
if (!__hrtimer_hres_active(cpu_base) || cpu_base->hang_detected)
return;

- tick_program_event(cpu_base->expires_next, 1);
+ tick_program_event(expires_next, 1);
+}
+
+/*
+ * Reprogram the event source with checking both queues for the
+ * next event
+ * Called with interrupts disabled and base->lock held
+ */
+static void
+hrtimer_force_reprogram(struct hrtimer_cpu_base *cpu_base, int skip_equal)
+{
+ ktime_t expires_next;
+
+ expires_next = hrtimer_update_next_event(cpu_base);
+
+ if (skip_equal && expires_next == cpu_base->expires_next)
+ return;
+
+ __hrtimer_reprogram(cpu_base, cpu_base->next_timer, expires_next);
}

/* High resolution timer related functions */
@@ -720,23 +727,7 @@ static inline int hrtimer_is_hres_enable
return hrtimer_hres_enabled;
}

-/*
- * Retrigger next event is called after clock was set
- *
- * Called with interrupts disabled via on_each_cpu()
- */
-static void retrigger_next_event(void *arg)
-{
- struct hrtimer_cpu_base *base = this_cpu_ptr(&hrtimer_bases);
-
- if (!__hrtimer_hres_active(base))
- return;
-
- raw_spin_lock(&base->lock);
- hrtimer_update_base(base);
- hrtimer_force_reprogram(base, 0);
- raw_spin_unlock(&base->lock);
-}
+static void retrigger_next_event(void *arg);

/*
* Switch to high resolution mode
@@ -758,29 +749,54 @@ static void hrtimer_switch_to_hres(void)
retrigger_next_event(NULL);
}

-static void clock_was_set_work(struct work_struct *work)
-{
- clock_was_set();
-}
+#else

-static DECLARE_WORK(hrtimer_work, clock_was_set_work);
+static inline int hrtimer_is_hres_enabled(void) { return 0; }
+static inline void hrtimer_switch_to_hres(void) { }

+#endif /* CONFIG_HIGH_RES_TIMERS */
/*
- * Called from timekeeping and resume code to reprogram the hrtimer
- * interrupt device on all cpus.
+ * Retrigger next event is called after clock was set with interrupts
+ * disabled through an SMP function call or directly from low level
+ * resume code.
+ *
+ * This is only invoked when:
+ * - CONFIG_HIGH_RES_TIMERS is enabled.
+ * - CONFIG_NOHZ_COMMON is enabled
+ *
+ * For the other cases this function is empty and because the call sites
+ * are optimized out it vanishes as well, i.e. no need for lots of
+ * #ifdeffery.
*/
-void clock_was_set_delayed(void)
+static void retrigger_next_event(void *arg)
{
- schedule_work(&hrtimer_work);
-}
-
-#else
+ struct hrtimer_cpu_base *base = this_cpu_ptr(&hrtimer_bases);

-static inline int hrtimer_is_hres_enabled(void) { return 0; }
-static inline void hrtimer_switch_to_hres(void) { }
-static inline void retrigger_next_event(void *arg) { }
+ /*
+ * When high resolution mode or nohz is active, then the offsets of
+ * CLOCK_REALTIME/TAI/BOOTTIME have to be updated. Otherwise the
+ * next tick will take care of that.
+ *
+ * If high resolution mode is active then the next expiring timer
+ * must be reevaluated and the clock event device reprogrammed if
+ * necessary.
+ *
+ * In the NOHZ case the update of the offset and the reevaluation
+ * of the next expiring timer is enough. The return from the SMP
+ * function call will take care of the reprogramming in case the
+ * CPU was in a NOHZ idle sleep.
+ */
+ if (!__hrtimer_hres_active(base) && !tick_nohz_active)
+ return;

-#endif /* CONFIG_HIGH_RES_TIMERS */
+ raw_spin_lock(&base->lock);
+ hrtimer_update_base(base);
+ if (__hrtimer_hres_active(base))
+ hrtimer_force_reprogram(base, 0);
+ else
+ hrtimer_update_next_event(base);
+ raw_spin_unlock(&base->lock);
+}

/*
* When a timer is enqueued and expires earlier than the already enqueued
@@ -835,75 +851,161 @@ static void hrtimer_reprogram(struct hrt
if (base->cpu_base != cpu_base)
return;

+ if (expires >= cpu_base->expires_next)
+ return;
+
/*
- * If the hrtimer interrupt is running, then it will
- * reevaluate the clock bases and reprogram the clock event
- * device. The callbacks are always executed in hard interrupt
- * context so we don't need an extra check for a running
- * callback.
+ * If the hrtimer interrupt is running, then it will reevaluate the
+ * clock bases and reprogram the clock event device.
*/
if (cpu_base->in_hrtirq)
return;

- if (expires >= cpu_base->expires_next)
- return;
-
- /* Update the pointer to the next expiring timer */
cpu_base->next_timer = timer;
- cpu_base->expires_next = expires;
+
+ __hrtimer_reprogram(cpu_base, timer, expires);
+}
+
+static bool update_needs_ipi(struct hrtimer_cpu_base *cpu_base,
+ unsigned int active)
+{
+ struct hrtimer_clock_base *base;
+ unsigned int seq;
+ ktime_t expires;

/*
- * If hres is not active, hardware does not have to be
- * programmed yet.
+ * Update the base offsets unconditionally so the following
+ * checks whether the SMP function call is required works.
*
- * If a hang was detected in the last timer interrupt then we
- * do not schedule a timer which is earlier than the expiry
- * which we enforced in the hang detection. We want the system
- * to make progress.
+ * The update is safe even when the remote CPU is in the hrtimer
+ * interrupt or the hrtimer soft interrupt and expiring affected
+ * bases. Either it will see the update before handling a base or
+ * it will see it when it finishes the processing and reevaluates
+ * the next expiring timer.
*/
- if (!__hrtimer_hres_active(cpu_base) || cpu_base->hang_detected)
- return;
+ seq = cpu_base->clock_was_set_seq;
+ hrtimer_update_base(cpu_base);

/*
- * Program the timer hardware. We enforce the expiry for
- * events which are already in the past.
+ * If the sequence did not change over the update then the
+ * remote CPU already handled it.
*/
- tick_program_event(expires, 1);
+ if (seq == cpu_base->clock_was_set_seq)
+ return false;
+
+ /*
+ * If the remote CPU is currently handling an hrtimer interrupt, it
+ * will reevaluate the first expiring timer of all clock bases
+ * before reprogramming. Nothing to do here.
+ */
+ if (cpu_base->in_hrtirq)
+ return false;
+
+ /*
+ * Walk the affected clock bases and check whether the first expiring
+ * timer in a clock base is moving ahead of the first expiring timer of
+ * @cpu_base. If so, the IPI must be invoked because per CPU clock
+ * event devices cannot be remotely reprogrammed.
+ */
+ active &= cpu_base->active_bases;
+
+ for_each_active_base(base, cpu_base, active) {
+ struct timerqueue_node *next;
+
+ next = timerqueue_getnext(&base->active);
+ expires = ktime_sub(next->expires, base->offset);
+ if (expires < cpu_base->expires_next)
+ return true;
+
+ /* Extra check for softirq clock bases */
+ if (base->clockid < HRTIMER_BASE_MONOTONIC_SOFT)
+ continue;
+ if (cpu_base->softirq_activated)
+ continue;
+ if (expires < cpu_base->softirq_expires_next)
+ return true;
+ }
+ return false;
}

/*
- * Clock realtime was set
+ * Clock was set. This might affect CLOCK_REALTIME, CLOCK_TAI and
+ * CLOCK_BOOTTIME (for late sleep time injection).
*
- * Change the offset of the realtime clock vs. the monotonic
- * clock.
- *
- * We might have to reprogram the high resolution timer interrupt. On
- * SMP we call the architecture specific code to retrigger _all_ high
- * resolution timer interrupts. On UP we just disable interrupts and
- * call the high resolution interrupt code.
+ * This requires to update the offsets for these clocks
+ * vs. CLOCK_MONOTONIC. When high resolution timers are enabled, then this
+ * also requires to eventually reprogram the per CPU clock event devices
+ * when the change moves an affected timer ahead of the first expiring
+ * timer on that CPU. Obviously remote per CPU clock event devices cannot
+ * be reprogrammed. The other reason why an IPI has to be sent is when the
+ * system is in !HIGH_RES and NOHZ mode. The NOHZ mode updates the offsets
+ * in the tick, which obviously might be stopped, so this has to bring out
+ * the remote CPU which might sleep in idle to get this sorted.
*/
-void clock_was_set(void)
+void clock_was_set(unsigned int bases)
{
-#ifdef CONFIG_HIGH_RES_TIMERS
- /* Retrigger the CPU local events everywhere */
- on_each_cpu(retrigger_next_event, NULL, 1);
-#endif
+ struct hrtimer_cpu_base *cpu_base = raw_cpu_ptr(&hrtimer_bases);
+ cpumask_var_t mask;
+ int cpu;
+
+ if (!__hrtimer_hres_active(cpu_base) && !tick_nohz_active)
+ goto out_timerfd;
+
+ if (!zalloc_cpumask_var(&mask, GFP_KERNEL)) {
+ on_each_cpu(retrigger_next_event, NULL, 1);
+ goto out_timerfd;
+ }
+
+ /* Avoid interrupting CPUs if possible */
+ cpus_read_lock();
+ for_each_online_cpu(cpu) {
+ unsigned long flags;
+
+ cpu_base = &per_cpu(hrtimer_bases, cpu);
+ raw_spin_lock_irqsave(&cpu_base->lock, flags);
+
+ if (update_needs_ipi(cpu_base, bases))
+ cpumask_set_cpu(cpu, mask);
+
+ raw_spin_unlock_irqrestore(&cpu_base->lock, flags);
+ }
+
+ preempt_disable();
+ smp_call_function_many(mask, retrigger_next_event, NULL, 1);
+ preempt_enable();
+ cpus_read_unlock();
+ free_cpumask_var(mask);
+
+out_timerfd:
timerfd_clock_was_set();
}

+static void clock_was_set_work(struct work_struct *work)
+{
+ clock_was_set(CLOCK_SET_WALL);
+}
+
+static DECLARE_WORK(hrtimer_work, clock_was_set_work);
+
/*
- * During resume we might have to reprogram the high resolution timer
- * interrupt on all online CPUs. However, all other CPUs will be
- * stopped with IRQs interrupts disabled so the clock_was_set() call
- * must be deferred.
+ * Called from timekeeping code to reprogram the hrtimer interrupt device
+ * on all cpus and to notify timerfd.
*/
-void hrtimers_resume(void)
+void clock_was_set_delayed(void)
+{
+ schedule_work(&hrtimer_work);
+}
+
+/*
+ * Called during resume either directly from via timekeeping_resume()
+ * or in the case of s2idle from tick_unfreeze() to ensure that the
+ * hrtimers are up to date.
+ */
+void hrtimers_resume_local(void)
{
lockdep_assert_irqs_disabled();
/* Retrigger on the local CPU */
retrigger_next_event(NULL);
- /* And schedule a retrigger for all others */
- clock_was_set_delayed();
}

/*
@@ -1030,12 +1132,13 @@ static void __remove_hrtimer(struct hrti

* remove hrtimer, called with base lock held
*/
static inline int
-remove_hrtimer(struct hrtimer *timer, struct hrtimer_clock_base *base, bool restart)
+remove_hrtimer(struct hrtimer *timer, struct hrtimer_clock_base *base,
+ bool restart, bool keep_local)
{
u8 state = timer->state;

if (state & HRTIMER_STATE_ENQUEUED) {
- int reprogram;
+ bool reprogram;

/*
* Remove the timer and force reprogramming when high

@@ -1048,8 +1151,16 @@ remove_hrtimer(struct hrtimer *timer, st

debug_deactivate(timer);
reprogram = base->cpu_base == this_cpu_ptr(&hrtimer_bases);

+ /*
+ * If the timer is not restarted then reprogramming is
+ * required if the timer is local. If it is local and about
+ * to be restarted, avoid programming it twice (on removal
+ * and a moment later when it's requeued).
+ */
if (!restart)
state = HRTIMER_STATE_INACTIVE;
+ else
+ reprogram &= !keep_local;

__remove_hrtimer(timer, base, state, reprogram);
return 1;

@@ -1103,9 +1214,31 @@ static int __hrtimer_start_range_ns(stru

struct hrtimer_clock_base *base)
{
struct hrtimer_clock_base *new_base;
+ bool force_local, first;

+
+ /*
+ * If the timer is on the local cpu base and is the first expiring
+ * timer then this might end up reprogramming the hardware twice
+ * (on removal and on enqueue). To avoid that by prevent the
+ * reprogram on removal, keep the timer local to the current CPU
+ * and enforce reprogramming after it is queued no matter whether
+ * it is the new first expiring timer again or not.
+ */
+ force_local = base->cpu_base == this_cpu_ptr(&hrtimer_bases);
+ force_local &= base->cpu_base->next_timer == timer;

- /* Remove an active timer from the queue: */
- remove_hrtimer(timer, base, true);
+ /*

+ * Remove an active timer from the queue. In case it is not queued
+ * on the current CPU, make sure that remove_hrtimer() updates the
+ * remote data correctly.
+ *
+ * If it's on the current CPU and the first expiring timer, then
+ * skip reprogramming, keep the timer local and enforce
+ * reprogramming later if it was the first expiring timer. This
+ * avoids programming the underlying clock event twice (once at
+ * removal and once after enqueue).
+ */
+ remove_hrtimer(timer, base, true, force_local);

if (mode & HRTIMER_MODE_REL)
tim = ktime_add_safe(tim, base->get_time());

@@ -1115,9 +1248,24 @@ static int __hrtimer_start_range_ns(stru

hrtimer_set_expires_range_ns(timer, tim, delta_ns);

/* Switch the timer base, if necessary: */
- new_base = switch_hrtimer_base(timer, base, mode & HRTIMER_MODE_PINNED);
+ if (!force_local) {
+ new_base = switch_hrtimer_base(timer, base,
+ mode & HRTIMER_MODE_PINNED);
+ } else {
+ new_base = base;
+ }

- return enqueue_hrtimer(timer, new_base, mode);
+ first = enqueue_hrtimer(timer, new_base, mode);
+ if (!force_local)
+ return first;
+
+ /*
+ * Timer was forced to stay on the current CPU to avoid
+ * reprogramming on removal and enqueue. Force reprogram the
+ * hardware by evaluating the new first expiring timer.
+ */
+ hrtimer_force_reprogram(new_base->cpu_base, 1);
+ return 0;
}

/**

@@ -1183,7 +1331,7 @@ int hrtimer_try_to_cancel(struct hrtimer

[syzbot]

Hello,

syzbot tried to test the proposed patch but the build/boot failed:

kernel/time/hrtimer.c:945:6: error: conflicting types for 'clock_was_set'
kernel/time/hrtimer.c:985:16: error: 'CLOCK_SET_WALL' undeclared (first use in this function)

Tested on:

commit: d6765985 Revert "be2net: disable bh with spin_lock in ..
git tree: https://git.kernel.org/pub/scm/linux/kernel/git/netdev/net.git

dashboard link: https://syzkaller.appspot.com/bug?extid=3ba0493d523d007b3819
compiler: gcc (Debian 10.2.1-6) 10.2.1 20210110, GNU ld (GNU Binutils for Debian) 2.35.2

patch: https://syzkaller.appspot.com/x/patch.diff?x=161b38de080000

[Hillf Danton]

On Thu, 01 Jul 2021 08:50:25 -0700

> syzbot found the following issue on:
>
> HEAD commit: d6765985 Revert "be2net: disable bh with spin_lock in be_p..
> git tree: net
> console output: https://syzkaller.appspot.com/x/log.txt?x=1085a0d8300000
> kernel config: https://syzkaller.appspot.com/x/.config?x=7ca96a2d153c74b0
> dashboard link: https://syzkaller.appspot.com/bug?extid=3ba0493d523d007b3819
> syz repro: https://syzkaller.appspot.com/x/repro.syz?x=14c9edc8300000
> C reproducer: https://syzkaller.appspot.com/x/repro.c?x=172463c8300000

#syz test https://git.kernel.org/pub/scm/linux/kernel/git/netdev/net.git f80e21489590

[syzbot]

Hello,

syzbot has tested the proposed patch but the reproducer is still triggering an issue:

INFO: rcu detected stall in tc_modify_qdisc

rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:

rcu: 0-...!: (10 ticks this GP) idle=3ae/1/0x4000000000000000 softirq=8207/8207 fqs=0
(detected by 1, t=10563 jiffies, g=10445, q=543)

============================================
WARNING: possible recursive locking detected

5.14.0-rc5-syzkaller #0 Not tainted
--------------------------------------------
syz-executor.0/5969 is trying to acquire lock:
ffffffff8b985018 (rcu_node_0){-.-.}-{2:2}, at: rcu_dump_cpu_stacks+0xd0/0x3f0 kernel/rcu/tree_stall.h:337

but task is already holding lock:

ffffffff8b985018 (rcu_node_0){-.-.}-{2:2}, at: print_other_cpu_stall kernel/rcu/tree_stall.h:543 [inline]
ffffffff8b985018 (rcu_node_0){-.-.}-{2:2}, at: check_cpu_stall kernel/rcu/tree_stall.h:709 [inline]
ffffffff8b985018 (rcu_node_0){-.-.}-{2:2}, at: rcu_pending kernel/rcu/tree.c:3922 [inline]
ffffffff8b985018 (rcu_node_0){-.-.}-{2:2}, at: rcu_sched_clock_irq+0xc9a/0x20c0 kernel/rcu/tree.c:2641

other info that might help us debug this:
Possible unsafe locking scenario:

CPU0
----
lock(rcu_node_0);
lock(rcu_node_0);

*** DEADLOCK ***

May be due to missing lock nesting notation

3 locks held by syz-executor.0/5969:
#0: ffffffff8d0cd4e8 (rtnl_mutex){+.+.}-{3:3}, at: rtnl_lock net/core/rtnetlink.c:72 [inline]
#0: ffffffff8d0cd4e8 (rtnl_mutex){+.+.}-{3:3}, at: rtnetlink_rcv_msg+0x3be/0xb80 net/core/rtnetlink.c:5571
#1: ffff88802d07a908 (&sch->q.lock){+.-.}-{2:2}, at: spin_lock_bh include/linux/spinlock.h:359 [inline]
#1: ffff88802d07a908 (&sch->q.lock){+.-.}-{2:2}, at: dev_reset_queue+0x8a/0x130 net/sched/sch_generic.c:1226
#2: ffffffff8b985018 (rcu_node_0){-.-.}-{2:2}, at: print_other_cpu_stall kernel/rcu/tree_stall.h:543 [inline]
#2: ffffffff8b985018 (rcu_node_0){-.-.}-{2:2}, at: check_cpu_stall kernel/rcu/tree_stall.h:709 [inline]
#2: ffffffff8b985018 (rcu_node_0){-.-.}-{2:2}, at: rcu_pending kernel/rcu/tree.c:3922 [inline]
#2: ffffffff8b985018 (rcu_node_0){-.-.}-{2:2}, at: rcu_sched_clock_irq+0xc9a/0x20c0 kernel/rcu/tree.c:2641

stack backtrace:
CPU: 1 PID: 5969 Comm: syz-executor.0 Not tainted 5.14.0-rc5-syzkaller #0

Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 06/29/2022

Call Trace:
<IRQ>
__dump_stack lib/dump_stack.c:88 [inline]
dump_stack_lvl+0xcd/0x134 lib/dump_stack.c:105
print_deadlock_bug kernel/locking/lockdep.c:2944 [inline]
check_deadlock kernel/locking/lockdep.c:2987 [inline]
validate_chain kernel/locking/lockdep.c:3776 [inline]
__lock_acquire.cold+0x149/0x3ab kernel/locking/lockdep.c:5015
lock_acquire kernel/locking/lockdep.c:5625 [inline]
lock_acquire+0x1ab/0x510 kernel/locking/lockdep.c:5590

__raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
_raw_spin_lock_irqsave+0x39/0x50 kernel/locking/spinlock.c:159

rcu_dump_cpu_stacks+0xd0/0x3f0 kernel/rcu/tree_stall.h:337
print_other_cpu_stall kernel/rcu/tree_stall.h:561 [inline]
check_cpu_stall kernel/rcu/tree_stall.h:709 [inline]
rcu_pending kernel/rcu/tree.c:3922 [inline]
rcu_sched_clock_irq+0x1cc6/0x20c0 kernel/rcu/tree.c:2641
update_process_times+0x16d/0x200 kernel/time/timer.c:1785
tick_sched_handle+0x9b/0x180 kernel/time/tick-sched.c:226
tick_sched_timer+0x1b0/0x2d0 kernel/time/tick-sched.c:1421
__run_hrtimer kernel/time/hrtimer.c:1685 [inline]
__hrtimer_run_queues+0x1c0/0xe50 kernel/time/hrtimer.c:1749
hrtimer_interrupt+0x31c/0x790 kernel/time/hrtimer.c:1811
local_apic_timer_interrupt arch/x86/kernel/apic/apic.c:1089 [inline]
__sysvec_apic_timer_interrupt+0x146/0x530 arch/x86/kernel/apic/apic.c:1106
sysvec_apic_timer_interrupt+0x8e/0xc0 arch/x86/kernel/apic/apic.c:1100
</IRQ>
asm_sysvec_apic_timer_interrupt+0x12/0x20 arch/x86/include/asm/idtentry.h:638
RIP: 0010:get_current arch/x86/include/asm/current.h:15 [inline]
RIP: 0010:__sanitizer_cov_trace_pc+0x13/0x60 kernel/kcov.c:196
Code: 00 4d 8b 03 48 0f bd ca 49 8b 45 00 48 63 c9 e9 64 ff ff ff 0f 1f 00 65 8b 05 39 37 8c 7e 89 c1 48 8b 34 24 81 e1 00 01 00 00 <65> 48 8b 14 25 00 f0 01 00 a9 00 01 ff 00 74 0e 85 c9 74 35 8b 82
RSP: 0018:ffffc90001a9f210 EFLAGS: 00000246
RAX: 0000000000000201 RBX: 00000000028311d6 RCX: 0000000000000000
RDX: ffff88801a873880 RSI: ffffffff816539ca RDI: ffff8880b9c26608
RBP: ffff8880b9c265c0 R08: 0000000000000000 R09: 0000000000000000
R10: ffffffff81653947 R11: 0000000000000000 R12: 0000000000000001
R13: ffff88802d07ab40 R14: dffffc0000000000 R15: 0000000000000010
hrtimer_active+0x17a/0x1f0 kernel/time/hrtimer.c:1615
hrtimer_try_to_cancel+0x21/0x1e0 kernel/time/hrtimer.c:1328
hrtimer_cancel+0x13/0x40 kernel/time/hrtimer.c:1443
taprio_reset+0x72/0x280 net/sched/sch_taprio.c:1622
qdisc_reset+0xdb/0x730 net/sched/sch_generic.c:977
dev_reset_queue+0x92/0x130 net/sched/sch_generic.c:1228
netdev_for_each_tx_queue include/linux/netdevice.h:2337 [inline]
dev_deactivate_many+0x51c/0xc40 net/sched/sch_generic.c:1294
dev_deactivate+0xe9/0x1b0 net/sched/sch_generic.c:1317
qdisc_graft+0xdac/0x1260 net/sched/sch_api.c:1055
tc_modify_qdisc+0xba4/0x1a60 net/sched/sch_api.c:1674
rtnetlink_rcv_msg+0x413/0xb80 net/core/rtnetlink.c:5574

netlink_rcv_skb+0x153/0x420 net/netlink/af_netlink.c:2504
netlink_unicast_kernel net/netlink/af_netlink.c:1314 [inline]
netlink_unicast+0x533/0x7d0 net/netlink/af_netlink.c:1340

netlink_sendmsg+0x86d/0xdb0 net/netlink/af_netlink.c:1929
sock_sendmsg_nosec net/socket.c:703 [inline]
sock_sendmsg+0xcf/0x120 net/socket.c:723
____sys_sendmsg+0x6e8/0x810 net/socket.c:2392
___sys_sendmsg+0xf3/0x170 net/socket.c:2446
__sys_sendmsg+0xe5/0x1b0 net/socket.c:2475
do_syscall_x64 arch/x86/entry/common.c:50 [inline]
do_syscall_64+0x35/0xb0 arch/x86/entry/common.c:80

entry_SYSCALL_64_after_hwframe+0x44/0xae
RIP: 0033:0x4665d9
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 bc ff ff ff f7 d8 64 89 01 48

RSP: 002b:00007f141db04188 EFLAGS: 00000246 ORIG_RAX: 000000000000002e

RAX: ffffffffffffffda RBX: 000000000056bf80 RCX: 00000000004665d9
RDX: 0000000000000000 RSI: 00000000200007c0 RDI: 0000000000000004
RBP: 00000000004bfcb9 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 000000000056bf80

R13: 00007ffd8eafafcf R14: 00007f141db04300 R15: 0000000000022000


Tested on:

commit: f80e2148 hrtimer: Unbreak hrtimer_force_reprogram()
git tree: https://git.kernel.org/pub/scm/linux/kernel/git/netdev/net.git
console output: https://syzkaller.appspot.com/x/log.txt?x=1589b47a080000
kernel config: https://syzkaller.appspot.com/x/.config?x=31eef52c6517a0c2

dashboard link: https://syzkaller.appspot.com/bug?extid=3ba0493d523d007b3819
compiler: gcc (Debian 10.2.1-6) 10.2.1 20210110, GNU ld (GNU Binutils for Debian) 2.35.2

Note: no patches were applied.

[Hillf Danton]

On Thu, 01 Jul 2021 08:50:25 -0700

> syzbot found the following issue on:
>
> HEAD commit: d6765985 Revert "be2net: disable bh with spin_lock in be_p..
> git tree: net
> console output: https://syzkaller.appspot.com/x/log.txt?x=1085a0d8300000
> kernel config: https://syzkaller.appspot.com/x/.config?x=7ca96a2d153c74b0
> dashboard link: https://syzkaller.appspot.com/bug?extid=3ba0493d523d007b3819
> syz repro: https://syzkaller.appspot.com/x/repro.syz?x=14c9edc8300000
> C reproducer: https://syzkaller.appspot.com/x/repro.c?x=172463c8300000

Fix recursive deadlock.

#syz test https://git.kernel.org/pub/scm/linux/kernel/git/netdev/net.git f80e21489590

[syzbot]

Hello,

syzbot has tested the proposed patch but the reproducer is still triggering an issue:

INFO: rcu detected stall in net_tx_action

rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:

rcu: 0-...!: (1 GPs behind) idle=a16/1/0x4000000000000000 softirq=8550/8551 fqs=1
rcu: Tasks blocked on level-0 rcu_node (CPUs 0-1):
(detected by 1, t=10843 jiffies, g=10157, q=515)
Sending NMI from CPU 1 to CPUs 0:

NMI backtrace for cpu 0

CPU: 0 PID: 13 Comm: ksoftirqd/0 Not tainted 5.14.0-rc5-syzkaller #0

Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 06/29/2022

RIP: 0010:__lock_acquire+0xc1e/0x54a0 kernel/locking/lockdep.c:5003
Code: 80 3c 02 00 0f 85 75 45 00 00 48 83 7b 40 00 0f 84 c6 0c 00 00 0f b7 44 24 10 8b 4c 24 40 8b 5c 24 50 c1 e0 0d 66 0b 44 24 08 <98> 2b 44 24 60 33 44 24 58 89 c2 29 c1 01 d8 c1 c2 06 31 ca 41 89
RSP: 0018:ffffc90000007ba0 EFLAGS: 00000006
RAX: 0000000000004028 RBX: 00000000fffffffe RCX: 00000000ffffffff
RDX: 1ffffffff1f97760 RSI: 0000000000000008 RDI: ffffffff8fcbbb00
RBP: 0000000000000002 R08: 0000000000000000 R09: ffffffff8fcb98a7
R10: fffffbfff1f97314 R11: 0000000000000000 R12: ffff888010a60a40
R13: ffff888010a60000 R14: 0000000000000001 R15: 96c8533605eb7aa2
FS: 0000000000000000(0000) GS:ffff8880b9c00000(0000) knlGS:0000000000000000

CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033

CR2: 000000000051e370 CR3: 000000000b68e000 CR4: 00000000003506f0

DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
<IRQ>

lock_acquire kernel/locking/lockdep.c:5625 [inline]
lock_acquire+0x1ab/0x510 kernel/locking/lockdep.c:5590

rcu_lock_acquire include/linux/rcupdate.h:267 [inline]
rcu_read_lock include/linux/rcupdate.h:687 [inline]
advance_sched+0x4a5/0x9a0 net/sched/sch_taprio.c:763
__run_hrtimer kernel/time/hrtimer.c:1685 [inline]
__hrtimer_run_queues+0x609/0xe50 kernel/time/hrtimer.c:1749

hrtimer_interrupt+0x31c/0x790 kernel/time/hrtimer.c:1811
local_apic_timer_interrupt arch/x86/kernel/apic/apic.c:1089 [inline]
__sysvec_apic_timer_interrupt+0x146/0x530 arch/x86/kernel/apic/apic.c:1106
sysvec_apic_timer_interrupt+0x8e/0xc0 arch/x86/kernel/apic/apic.c:1100
</IRQ>
asm_sysvec_apic_timer_interrupt+0x12/0x20 arch/x86/include/asm/idtentry.h:638

RIP: 0010:arch_safe_halt arch/x86/include/asm/irqflags.h:90 [inline]
RIP: 0010:kvm_wait arch/x86/kernel/kvm.c:888 [inline]

RIP: 0010:kvm_wait+0xaf/0xf0 arch/x86/kernel/kvm.c:871
Code: 10 c3 c3 89 74 24 0c 48 89 3c 24 e8 9b b6 48 00 8b 74 24 0c 48 8b 3c 24 eb 82 e8 ac bb 48 00 eb 07 0f 00 2d d3 c5 55 08 fb f4 <eb> 9b eb 07 0f 00 2d c6 c5 55 08 f4 eb c5 89 74 24 0c 48 89 3c 24
RSP: 0018:ffffc90000d27c80 EFLAGS: 00000206
RAX: 0000000000052272 RBX: 0000000000000000 RCX: 1ffffffff1f9ff22
RDX: 0000000000000000 RSI: 0000000000000101 RDI: 0000000000000000
RBP: ffff88802150a8f0 R08: 0000000000000001 R09: ffffffff8fcb995f
R10: 0000000000000001 R11: 0000000000000000 R12: 0000000000000000
R13: ffffed10042a151e R14: 0000000000000001 R15: ffff8880b9c36880

pv_wait arch/x86/include/asm/paravirt.h:597 [inline]
pv_wait_head_or_lock kernel/locking/qspinlock_paravirt.h:470 [inline]
__pv_queued_spin_lock_slowpath+0x8b8/0xb40 kernel/locking/qspinlock.c:508
pv_queued_spin_lock_slowpath arch/x86/include/asm/paravirt.h:585 [inline]
queued_spin_lock_slowpath arch/x86/include/asm/qspinlock.h:51 [inline]
queued_spin_lock include/asm-generic/qspinlock.h:85 [inline]
do_raw_spin_lock+0x200/0x2b0 kernel/locking/spinlock_debug.c:113
spin_lock include/linux/spinlock.h:354 [inline]

net_tx_action+0x3d8/0xdc0 net/core/dev.c:5083
__do_softirq+0x29b/0x9c2 kernel/softirq.c:558
run_ksoftirqd kernel/softirq.c:920 [inline]
run_ksoftirqd+0x2d/0x60 kernel/softirq.c:912
smpboot_thread_fn+0x645/0x9c0 kernel/smpboot.c:164
kthread+0x3e5/0x4d0 kernel/kthread.c:319
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:295
task:udevd state:R running task stack:26800 pid: 4876 ppid: 1 flags:0x00000000
Call Trace:
context_switch kernel/sched/core.c:4681 [inline]
__schedule+0x93a/0x26f0 kernel/sched/core.c:5938
preempt_schedule_common+0x45/0xc0 kernel/sched/core.c:6098
preempt_schedule_thunk+0x16/0x18 arch/x86/entry/thunk_64.S:35
__raw_spin_unlock_irqrestore include/linux/spinlock_api_smp.h:161 [inline]
_raw_spin_unlock_irqrestore+0x57/0x70 kernel/locking/spinlock.c:191
spin_unlock_irqrestore include/linux/spinlock.h:409 [inline]
__wake_up_common_lock+0xde/0x130 kernel/sched/wait.c:140
sock_def_readable+0xec/0x4e0 net/core/sock.c:3015
__netlink_sendskb net/netlink/af_netlink.c:1261 [inline]
netlink_sendskb net/netlink/af_netlink.c:1267 [inline]
netlink_unicast+0x6d1/0x7d0 net/netlink/af_netlink.c:1355

netlink_sendmsg+0x86d/0xdb0 net/netlink/af_netlink.c:1929
sock_sendmsg_nosec net/socket.c:703 [inline]
sock_sendmsg+0xcf/0x120 net/socket.c:723
____sys_sendmsg+0x6e8/0x810 net/socket.c:2392
___sys_sendmsg+0xf3/0x170 net/socket.c:2446
__sys_sendmsg+0xe5/0x1b0 net/socket.c:2475
do_syscall_x64 arch/x86/entry/common.c:50 [inline]
do_syscall_64+0x35/0xb0 arch/x86/entry/common.c:80
entry_SYSCALL_64_after_hwframe+0x44/0xae

RIP: 0033:0x7f2ca7a61163
RSP: 002b:00007ffe2cbdf988 EFLAGS: 00000246 ORIG_RAX: 000000000000002e
RAX: ffffffffffffffda RBX: 000055833d861d50 RCX: 00007f2ca7a61163
RDX: 0000000000000000 RSI: 00007ffe2cbdf998 RDI: 0000000000000004
RBP: 000055833d88a300 R08: 0000000000000001 R09: 0000000000000000
R10: 0000000000000020 R11: 0000000000000246 R12: 0000000000000000
R13: 00000000000000a6 R14: 0000000000000000 R15: 0000000000000000
rcu: rcu_preempt kthread timer wakeup didn't happen for 10820 jiffies! g10157 f0x0 RCU_GP_WAIT_FQS(5) ->state=0x402
rcu: Possible timer handling issue on cpu=1 timer-softirq=3021
rcu: rcu_preempt kthread starved for 10821 jiffies! g10157 f0x0 RCU_GP_WAIT_FQS(5) ->state=0x402 ->cpu=1

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:29544 pid: 14 ppid: 2 flags:0x00004000
Call Trace:
context_switch kernel/sched/core.c:4681 [inline]
__schedule+0x93a/0x26f0 kernel/sched/core.c:5938
schedule+0xd3/0x270 kernel/sched/core.c:6017
schedule_timeout+0x14a/0x2a0 kernel/time/timer.c:1881
rcu_gp_fqs_loop kernel/rcu/tree.c:1996 [inline]
rcu_gp_kthread+0xd34/0x1980 kernel/rcu/tree.c:2169
kthread+0x3e5/0x4d0 kernel/kthread.c:319
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:295

rcu: Stack dump where RCU GP kthread last ran:
NMI backtrace for cpu 1

CPU: 1 PID: 6025 Comm: syz-executor.0 Not tainted 5.14.0-rc5-syzkaller #0

Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 06/29/2022
Call Trace:
<IRQ>
__dump_stack lib/dump_stack.c:88 [inline]
dump_stack_lvl+0xcd/0x134 lib/dump_stack.c:105

nmi_cpu_backtrace.cold+0x44/0xd7 lib/nmi_backtrace.c:105
nmi_trigger_cpumask_backtrace+0x1b3/0x230 lib/nmi_backtrace.c:62
trigger_single_cpu_backtrace include/linux/nmi.h:164 [inline]

rcu_check_gp_kthread_starvation.cold+0x1d1/0x1d6 kernel/rcu/tree_stall.h:481
print_other_cpu_stall kernel/rcu/tree_stall.h:586 [inline]
check_cpu_stall kernel/rcu/tree_stall.h:711 [inline]
rcu_pending kernel/rcu/tree.c:3922 [inline]
rcu_sched_clock_irq+0x1ee0/0x2190 kernel/rcu/tree.c:2641

update_process_times+0x16d/0x200 kernel/time/timer.c:1785
tick_sched_handle+0x9b/0x180 kernel/time/tick-sched.c:226
tick_sched_timer+0x1b0/0x2d0 kernel/time/tick-sched.c:1421
__run_hrtimer kernel/time/hrtimer.c:1685 [inline]
__hrtimer_run_queues+0x1c0/0xe50 kernel/time/hrtimer.c:1749
hrtimer_interrupt+0x31c/0x790 kernel/time/hrtimer.c:1811
local_apic_timer_interrupt arch/x86/kernel/apic/apic.c:1089 [inline]
__sysvec_apic_timer_interrupt+0x146/0x530 arch/x86/kernel/apic/apic.c:1106
sysvec_apic_timer_interrupt+0x8e/0xc0 arch/x86/kernel/apic/apic.c:1100
</IRQ>
asm_sysvec_apic_timer_interrupt+0x12/0x20 arch/x86/include/asm/idtentry.h:638

RIP: 0010:__raw_spin_unlock_irqrestore include/linux/spinlock_api_smp.h:161 [inline]
RIP: 0010:_raw_spin_unlock_irqrestore+0x38/0x70 kernel/locking/spinlock.c:191
Code: 74 24 10 e8 0a 0d 2e f8 48 89 ef e8 b2 82 2e f8 81 e3 00 02 00 00 75 25 9c 58 f6 c4 02 75 2d 48 85 db 74 01 fb bf 01 00 00 00 <e8> 73 60 22 f8 65 8b 05 7c d8 d4 76 85 c0 74 0a 5b 5d c3 e8 40 ca
RSP: 0018:ffffc90001f6f260 EFLAGS: 00000206
RAX: 0000000000000002 RBX: 0000000000000200 RCX: 1ffffffff1f9ff22
RDX: 0000000000000000 RSI: 0000000000000202 RDI: 0000000000000001
RBP: ffff8880b9c263c0 R08: 0000000000000001 R09: ffffffff8fcb995f

R10: 0000000000000001 R11: 0000000000000000 R12: 00000000ffffffff

R13: 0000000000000246 R14: ffff8880b9c265c0 R15: dffffc0000000000
unlock_hrtimer_base kernel/time/hrtimer.c:1017 [inline]
hrtimer_try_to_cancel kernel/time/hrtimer.c:1336 [inline]
hrtimer_try_to_cancel+0x14e/0x1e0 kernel/time/hrtimer.c:1316

hrtimer_cancel+0x13/0x40 kernel/time/hrtimer.c:1443
taprio_reset+0x72/0x280 net/sched/sch_taprio.c:1622
qdisc_reset+0xdb/0x730 net/sched/sch_generic.c:977
dev_reset_queue+0x92/0x130 net/sched/sch_generic.c:1228
netdev_for_each_tx_queue include/linux/netdevice.h:2337 [inline]
dev_deactivate_many+0x51c/0xc40 net/sched/sch_generic.c:1294
dev_deactivate+0xe9/0x1b0 net/sched/sch_generic.c:1317
qdisc_graft+0xdac/0x1260 net/sched/sch_api.c:1055
tc_modify_qdisc+0xba4/0x1a60 net/sched/sch_api.c:1674
rtnetlink_rcv_msg+0x413/0xb80 net/core/rtnetlink.c:5574
netlink_rcv_skb+0x153/0x420 net/netlink/af_netlink.c:2504
netlink_unicast_kernel net/netlink/af_netlink.c:1314 [inline]
netlink_unicast+0x533/0x7d0 net/netlink/af_netlink.c:1340
netlink_sendmsg+0x86d/0xdb0 net/netlink/af_netlink.c:1929
sock_sendmsg_nosec net/socket.c:703 [inline]
sock_sendmsg+0xcf/0x120 net/socket.c:723
____sys_sendmsg+0x6e8/0x810 net/socket.c:2392
___sys_sendmsg+0xf3/0x170 net/socket.c:2446
__sys_sendmsg+0xe5/0x1b0 net/socket.c:2475
do_syscall_x64 arch/x86/entry/common.c:50 [inline]
do_syscall_64+0x35/0xb0 arch/x86/entry/common.c:80
entry_SYSCALL_64_after_hwframe+0x44/0xae
RIP: 0033:0x4665d9
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 bc ff ff ff f7 d8 64 89 01 48

RSP: 002b:00007f2cc6289188 EFLAGS: 00000246 ORIG_RAX: 000000000000002e

RAX: ffffffffffffffda RBX: 000000000056bf80 RCX: 00000000004665d9
RDX: 0000000000000000 RSI: 00000000200007c0 RDI: 0000000000000004
RBP: 00000000004bfcb9 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 000000000056bf80

R13: 00007ffede22787f R14: 00007f2cc6289300 R15: 0000000000022000

Tested on:

commit: f80e2148 hrtimer: Unbreak hrtimer_force_reprogram()
git tree: https://git.kernel.org/pub/scm/linux/kernel/git/netdev/net.git

console output: https://syzkaller.appspot.com/x/log.txt?x=10e6b35a080000

kernel config: https://syzkaller.appspot.com/x/.config?x=31eef52c6517a0c2
dashboard link: https://syzkaller.appspot.com/bug?extid=3ba0493d523d007b3819
compiler: gcc (Debian 10.2.1-6) 10.2.1 20210110, GNU ld (GNU Binutils for Debian) 2.35.2

patch: https://syzkaller.appspot.com/x/patch.diff?x=136e177e080000

[Hillf Danton]

On Thu, 28 Jul 2022 00:46:17 -0700

> syzbot has tested the proposed patch but the reproducer is still triggering an issue:
> INFO: rcu detected stall in net_tx_action
>
> rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
> rcu: 0-...!: (1 GPs behind) idle=a16/1/0x4000000000000000 softirq=8550/8551 fqs=1
> rcu: Tasks blocked on level-0 rcu_node (CPUs 0-1):
> (detected by 1, t=10843 jiffies, g=10157, q=515)
> Sending NMI from CPU 1 to CPUs 0:
> NMI backtrace for cpu 0
> CPU: 0 PID: 13 Comm: ksoftirqd/0 Not tainted 5.14.0-rc5-syzkaller #0

See if it can be reproduced on top of the mainline tree.

#syz test git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git master

[syzbot]

Hello,

syzbot has tested the proposed patch and the reproducer did not trigger any issue:

Reported-and-tested-by: syzbot+3ba049...@syzkaller.appspotmail.com

Tested on:

commit: 6e7765cb Merge tag 'asm-generic-fixes-5.19-2' of git:/..
git tree: upstream
console output: https://syzkaller.appspot.com/x/log.txt?x=12d263ee080000
kernel config: https://syzkaller.appspot.com/x/.config?x=1eedaa77654417d0

dashboard link: https://syzkaller.appspot.com/bug?extid=3ba0493d523d007b3819
compiler: gcc (Debian 10.2.1-6) 10.2.1 20210110, GNU ld (GNU Binutils for Debian) 2.35.2

Note: no patches were applied.

Note: testing is done by a robot and is best-effort only.

[Hillf Danton]

On Thu, 28 Jul 2022 00:46:17 -0700
> syzbot has tested the proposed patch but the reproducer is still triggering an issue:
> INFO: rcu detected stall in net_tx_action
>
> rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
> rcu: 0-...!: (1 GPs behind) idle=a16/1/0x4000000000000000 softirq=8550/8551 fqs=1
> rcu: Tasks blocked on level-0 rcu_node (CPUs 0-1):
> (detected by 1, t=10843 jiffies, g=10157, q=515)
> Sending NMI from CPU 1 to CPUs 0:
> NMI backtrace for cpu 0
> CPU: 0 PID: 13 Comm: ksoftirqd/0 Not tainted 5.14.0-rc5-syzkaller #0

Correct hrtimer expire time.

#syz test https://git.kernel.org/pub/scm/linux/kernel/git/netdev/net.git f80e2148

--- m/net/sched/sch_taprio.c
+++ n/net/sched/sch_taprio.c
@@ -758,7 +758,16 @@ first_run:
rcu_assign_pointer(q->current_entry, next);
spin_unlock(&q->current_entry_lock);

- hrtimer_set_expires(&q->advance_timer, close_time);
+ do {
+ struct hrtimer *timer = &q->advance_timer;
+ ktime_t now = timer->base->get_time();
+
+ now = ktime_add_ns(now, 2000);
+ if (ktime_compare(now, close_time) > 0)
+ hrtimer_set_expires(&q->advance_timer, now);
+ else
+ hrtimer_set_expires(&q->advance_timer, close_time);
+ } while (0);

rcu_read_lock();
__netif_schedule(sch);
--

[syzbot]

Hello,

syzbot has tested the proposed patch and the reproducer did not trigger any issue:

Reported-and-tested-by: syzbot+3ba049...@syzkaller.appspotmail.com

Tested on:

commit: f80e2148 hrtimer: Unbreak hrtimer_force_reprogram()
git tree: https://git.kernel.org/pub/scm/linux/kernel/git/netdev/net.git

console output: https://syzkaller.appspot.com/x/log.txt?x=161c00ca080000
kernel config: https://syzkaller.appspot.com/x/.config?x=31eef52c6517a0c2

dashboard link: https://syzkaller.appspot.com/bug?extid=3ba0493d523d007b3819
compiler: gcc (Debian 10.2.1-6) 10.2.1 20210110, GNU ld (GNU Binutils for Debian) 2.35.2

patch: https://syzkaller.appspot.com/x/patch.diff?x=111abd26080000

[Hillf Danton]

Hey Thomas

On Thu, 28 Jul 2022 00:46:17 -0700
> syzbot has tested the proposed patch but the reproducer is still triggering an issue:
> INFO: rcu detected stall in net_tx_action
>
> rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
> rcu: 0-...!: (1 GPs behind) idle=a16/1/0x4000000000000000 softirq=8550/8551 fqs=1
> rcu: Tasks blocked on level-0 rcu_node (CPUs 0-1):
> (detected by 1, t=10843 jiffies, g=10157, q=515)
> Sending NMI from CPU 1 to CPUs 0:
> NMI backtrace for cpu 0
> CPU: 0 PID: 13 Comm: ksoftirqd/0 Not tainted 5.14.0-rc5-syzkaller #0

Despite the diff below that was prepared based on rcu stall [1] survived
syzbot test [2], I am not sure it is the correct fix given it failed to
reproduce on the mainline tree [3]. Could you please take a look at the
stall and tippoint us to the plumber dude fix?

Thanks
Hillf

[1] https://lore.kernel.org/lkml/00000000000090...@google.com/
[2] https://lore.kernel.org/lkml/00000000000078...@google.com/
[3] https://lore.kernel.org/lkml/000000000000b6...@google.com/

[syzbot]

> Hey Thomas
>
> On Thu, 28 Jul 2022 00:46:17 -0700
>> syzbot has tested the proposed patch but the reproducer is still triggering an issue:
>> INFO: rcu detected stall in net_tx_action
>>
>> rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
>> rcu: 0-...!: (1 GPs behind) idle=a16/1/0x4000000000000000 softirq=8550/8551 fqs=1
>> rcu: Tasks blocked on level-0 rcu_node (CPUs 0-1):
>> (detected by 1, t=10843 jiffies, g=10157, q=515)
>> Sending NMI from CPU 1 to CPUs 0:
>> NMI backtrace for cpu 0
>> CPU: 0 PID: 13 Comm: ksoftirqd/0 Not tainted 5.14.0-rc5-syzkaller #0
>
> Despite the diff below that was prepared based on rcu stall [1] survived
> syzbot test [2], I am not sure it is the correct fix given it failed to
> reproduce on the mainline tree [3]. Could you please take a look at the
> stall and tippoint us to the plumber dude fix?
>
> Thanks
> Hillf
>
> [1] https://lore.kernel.org/lkml/00000000000090...@google.com/
> [2] https://lore.kernel.org/lkml/00000000000078...@google.com/
> [3] https://lore.kernel.org/lkml/000000000000b6...@google.com/
>
> Correct hrtimer expire time.
>
> #syz test https://git.kernel.org/pub/scm/linux/kernel/git/netdev/net.git f80e2148

I see the command but can't find the corresponding bug.
Please resend the email to syzbo...@syzkaller.appspotmail.com address
that is the sender of the bug report (also present in the Reported-by tag).

>
> --- m/net/sched/sch_taprio.c
> +++ n/net/sched/sch_taprio.c
> @@ -758,7 +758,16 @@ first_run:
> rcu_assign_pointer(q->current_entry, next);
> spin_unlock(&q->current_entry_lock);
>
> - hrtimer_set_expires(&q->advance_timer, close_time);
> + do {
> + struct hrtimer *timer = &q->advance_timer;
> + ktime_t now = timer->base->get_time();
> +
> + now = ktime_add_ns(now, 2000);
> + if (ktime_compare(now, close_time) > 0)
> + hrtimer_set_expires(&q->advance_timer, now);
> + else
> + hrtimer_set_expires(&q->advance_timer, close_time);
> + } while (0);
>
> rcu_read_lock();
> __netif_schedule(sch);
> --
>

> --
> 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/20220728124803.958-1-hdanton%40sina.com.

[Hillf Danton]

On Thu, 28 Jul 2022 00:46:17 -0700

> syzbot has tested the proposed patch but the reproducer is still triggering an issue:
> INFO: rcu detected stall in net_tx_action
>
> rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
> rcu: 0-...!: (1 GPs behind) idle=a16/1/0x4000000000000000 softirq=8550/8551 fqs=1
> rcu: Tasks blocked on level-0 rcu_node (CPUs 0-1):
> (detected by 1, t=10843 jiffies, g=10157, q=515)
> Sending NMI from CPU 1 to CPUs 0:
> NMI backtrace for cpu 0
> CPU: 0 PID: 13 Comm: ksoftirqd/0 Not tainted 5.14.0-rc5-syzkaller #0

Print the hrtimer hog.

#syz test https://git.kernel.org/pub/scm/linux/kernel/git/netdev/net.git f80e2148

--- y/kernel/time/hrtimer.c
+++ h/kernel/time/hrtimer.c
@@ -1647,6 +1647,8 @@ static void __run_hrtimer(struct hrtimer
enum hrtimer_restart (*fn)(struct hrtimer *);
bool expires_in_hardirq;
int restart;
+ unsigned long ts;
+ ktime_t ts_thr, ts_ns;

lockdep_assert_held(&cpu_base->lock);

@@ -1681,13 +1683,19 @@ static void __run_hrtimer(struct hrtimer
raw_spin_unlock_irqrestore(&cpu_base->lock, flags);
trace_hrtimer_expire_entry(timer, now);
expires_in_hardirq = lockdep_hrtimer_enter(timer);
+ ts = jiffies + 1;

restart = fn(timer);

+ WARN_ONCE(time_after(jiffies, ts), "hrtimer hog %ps ran longer than 1 tick\n", fn);
+
lockdep_hrtimer_exit(expires_in_hardirq);
trace_hrtimer_expire_exit(timer);
raw_spin_lock_irq(&cpu_base->lock);

+ ts_ns = hrtimer_update_base(cpu_base);
+ ts_thr = ktime_add_ms(*now, 1);
+ WARN_ONCE(ktime_after(ts_ns, ts_thr), "hrtimer hog %ps ran longer than 1ms\n", fn);
/*
* Note: We clear the running state after enqueue_hrtimer and
* we do not reprogram the event hardware. Happens either in
--

[syzbot]

Hello,

syzbot tried to test the proposed patch but the build/boot failed:

3347][ T1] gre: GRE over IPv4 demultiplexor driver
[ 13.619124][ T1] ip_gre: GRE over IPv4 tunneling driver
[ 13.631725][ T1] IPv4 over IPsec tunneling driver
[ 13.640899][ T1] ipt_CLUSTERIP: ClusterIP Version 0.8 loaded successfully
[ 13.648512][ T1] Initializing XFRM netlink socket
[ 13.654216][ T1] IPsec XFRM device driver
[ 13.661054][ T1] NET: Registered PF_INET6 protocol family
[ 13.679714][ T1] Segment Routing with IPv6
[ 13.684244][ T1] RPL Segment Routing with IPv6
[ 13.690226][ T1] mip6: Mobile IPv6
[ 13.698639][ T1] sit: IPv6, IPv4 and MPLS over IPv4 tunneling driver
[ 13.712191][ T1] ip6_gre: GRE over IPv6 tunneling driver
[ 13.721733][ T1] NET: Registered PF_PACKET protocol family
[ 13.728154][ T1] NET: Registered PF_KEY protocol family
[ 13.734540][ T1] Bridge firewalling registered
[ 13.740978][ T1] NET: Registered PF_X25 protocol family
[ 13.746924][ T1] X25: Linux Version 0.2
[ 13.795301][ T1] NET: Registered PF_NETROM protocol family
[ 13.848772][ T1] NET: Registered PF_ROSE protocol family
[ 13.854996][ T1] NET: Registered PF_AX25 protocol family
[ 13.860824][ T1] can: controller area network core
[ 13.866436][ T1] NET: Registered PF_CAN protocol family
[ 13.872096][ T1] can: raw protocol
[ 13.876009][ T1] can: broadcast manager protocol
[ 13.881188][ T1] can: netlink gateway - max_hops=1
[ 13.886852][ T1] can: SAE J1939
[ 13.890404][ T1] can: isotp protocol
[ 13.894929][ T1] Bluetooth: RFCOMM TTY layer initialized
[ 13.900900][ T1] Bluetooth: RFCOMM socket layer initialized
[ 13.907196][ T1] Bluetooth: RFCOMM ver 1.11
[ 13.911864][ T1] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
[ 13.918198][ T1] Bluetooth: BNEP filters: protocol multicast
[ 13.924303][ T1] Bluetooth: BNEP socket layer initialized
[ 13.930379][ T1] Bluetooth: CMTP (CAPI Emulation) ver 1.0
[ 13.936749][ T1] Bluetooth: CMTP socket layer initialized
[ 13.936766][ T1] Bluetooth: HIDP (Human Interface Emulation) ver 1.2
[ 13.936797][ T1] Bluetooth: HIDP socket layer initialized
[ 13.941357][ T1] NET: Registered PF_RXRPC protocol family
[ 13.961443][ T1] Key type rxrpc registered
[ 13.966003][ T1] Key type rxrpc_s registered
[ 13.972441][ T1] NET: Registered PF_KCM protocol family
[ 13.978717][ T1] lec:lane_module_init: lec.c: initialized
[ 13.984564][ T1] mpoa:atm_mpoa_init: mpc.c: initialized
[ 13.990961][ T1] l2tp_core: L2TP core driver, V2.0
[ 13.996263][ T1] l2tp_ppp: PPPoL2TP kernel driver, V2.0
[ 14.001954][ T1] l2tp_ip: L2TP IP encapsulation support (L2TPv3)
[ 14.008954][ T1] l2tp_netlink: L2TP netlink interface
[ 14.014687][ T1] l2tp_eth: L2TP ethernet pseudowire support (L2TPv3)
[ 14.021503][ T1] l2tp_ip6: L2TP IP encapsulation support for IPv6 (L2TPv3)
[ 14.029452][ T1] NET: Registered PF_PHONET protocol family
[ 14.036072][ T1] 8021q: 802.1Q VLAN Support v1.8
[ 14.053536][ T1] DCCP: Activated CCID 2 (TCP-like)
[ 14.059597][ T1] DCCP: Activated CCID 3 (TCP-Friendly Rate Control)
[ 14.069073][ T1] sctp: Hash tables configured (bind 32/56)
[ 14.077557][ T1] NET: Registered PF_RDS protocol family
[ 14.084307][ T1] Registered RDS/infiniband transport
[ 14.091043][ T1] Registered RDS/tcp transport
[ 14.096039][ T1] tipc: Activated (version 2.0.0)
[ 14.101965][ T1] NET: Registered PF_TIPC protocol family
[ 14.108528][ T1] tipc: Started in single node mode
[ 14.114783][ T1] NET: Registered PF_SMC protocol family
[ 14.121190][ T1] 9pnet: Installing 9P2000 support
[ 14.127289][ T1] NET: Registered PF_CAIF protocol family
[ 14.138968][ T1] NET: Registered PF_IEEE802154 protocol family
[ 14.146086][ T1] Key type dns_resolver registered
[ 14.151586][ T1] Key type ceph registered
[ 14.157602][ T1] libceph: loaded (mon/osd proto 15/24)
[ 14.166085][ T1] batman_adv: B.A.T.M.A.N. advanced 2021.2 (compatibility version 15) loaded
[ 14.175270][ T1] openvswitch: Open vSwitch switching datapath
[ 14.185311][ T1] NET: Registered PF_VSOCK protocol family
[ 14.191809][ T1] mpls_gso: MPLS GSO support
[ 14.207214][ T1] IPI shorthand broadcast: enabled
[ 14.212607][ T1] AVX2 version of gcm_enc/dec engaged.
[ 14.218734][ T1] AES CTR mode by8 optimization enabled
[ 14.232847][ T1] sched_clock: Marking stable (14200464125, 32247819)->(14235442173, -2730229)
[ 14.243629][ T1] registered taskstats version 1
[ 14.258146][ T1] Loading compiled-in X.509 certificates
[ 14.266298][ T1] Loaded X.509 cert 'Build time autogenerated kernel key: f850c787ad998c396ae089c083b940ff0a9abb77'
[ 14.277236][ C0] ------------[ cut here ]------------
[ 14.277267][ C0] hrtimer hog tick_sched_timer ran longer than 1 tick
[ 14.277332][ C0] WARNING: CPU: 0 PID: 1 at kernel/time/hrtimer.c:1690 __hrtimer_run_queues+0xbf5/0x1230
[ 14.277391][ C0] Modules linked in:
[ 14.277399][ C0] CPU: 0 PID: 1 Comm: swapper/0 Not tainted 5.14.0-rc5-syzkaller #0
[ 14.277414][ C0] Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 07/22/2022
[ 14.277422][ C0] RIP: 0010:__hrtimer_run_queues+0xbf5/0x1230
[ 14.277441][ C0] Code: 10 00 0f 0b e9 70 f6 ff ff bd 01 00 00 00 e8 b2 44 10 00 48 8b 34 24 48 c7 c7 a0 cd 8d 89 c6 05 0b 9e f2 0b 01 e8 75 c9 82 07 <0f> 0b e8 94 44 10 00 31 ff 89 ee e8 cb 4a 10 00 40 84 ed 0f 84 00
[ 14.277454][ C0] RSP: 0000:ffffc90000007e20 EFLAGS: 00010086
[ 14.277466][ C0] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000
[ 14.277474][ C0] RDX: ffff888140160000 RSI: ffffffff815d8865 RDI: fffff52000000fb6
[ 14.277483][ C0] RBP: 0000000000000001 R08: 0000000000000000 R09: 0000000000000001
[ 14.277491][ C0] R10: ffffffff815d269e R11: 0000000000000000 R12: ffff8880b9c26d60
[ 14.277500][ C0] R13: ffff8880b9c26488 R14: ffff8880b9c26440 R15: ffff8880b9c263c0
[ 14.277510][ C0] FS: 0000000000000000(0000) GS:ffff8880b9c00000(0000) knlGS:0000000000000000
[ 14.277523][ C0] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 14.277532][ C0] CR2: ffff88823ffff000 CR3: 000000000b68e000 CR4: 00000000003506f0
[ 14.277541][ C0] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 14.277549][ C0] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 14.277557][ C0] Call Trace:
[ 14.277562][ C0] <IRQ>
[ 14.277566][ C0] ? get_cpu_iowait_time_us+0x3f0/0x3f0
[ 14.277589][ C0] ? hrtimer_sleeper_start_expires+0x80/0x80
[ 14.277605][ C0] ? ktime_get_update_offsets_now+0x3eb/0x5c0
[ 14.277624][ C0] hrtimer_interrupt+0x31c/0x790
[ 14.277647][ C0] __sysvec_apic_timer_interrupt+0x146/0x530
[ 14.277664][ C0] sysvec_apic_timer_interrupt+0x8e/0xc0
[ 14.277688][ C0] </IRQ>
[ 14.277693][ C0] asm_sysvec_apic_timer_interrupt+0x12/0x20
[ 14.277709][ C0] RIP: 0010:__sanitizer_cov_trace_pc+0x0/0x60
[ 14.277724][ C0] Code: 01 f0 4d 89 03 e9 63 fd ff ff b9 ff ff ff ff ba 08 00 00 00 4d 8b 03 48 0f bd ca 49 8b 45 00 48 63 c9 e9 64 ff ff ff 0f 1f 00 <65> 8b 05 59 33 8c 7e 89 c1 48 8b 34 24 81 e1 00 01 00 00 65 48 8b
[ 14.277736][ C0] RSP: 0000:ffffc90000c67b18 EFLAGS: 00000293
[ 14.277747][ C0] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000
[ 14.277757][ C0] RDX: ffff888140160000 RSI: ffffffff815d55f3 RDI: 0000000000000003
[ 14.277769][ C0] RBP: 0000000000000000 R08: 0000000000000000 R09: ffffffff8fcb98a7
[ 14.277778][ C0] R10: ffffffff815d55e9 R11: 0000000000000000 R12: ffffffff8432d7f0
[ 14.277786][ C0] R13: 0000000000000200 R14: dffffc0000000000 R15: ffffc90000c67b78
[ 14.277796][ C0] ? univ8250_console_exit+0x70/0x70
[ 14.277813][ C0] ? console_unlock+0x7b9/0xc40
[ 14.277828][ C0] ? console_unlock+0x7c3/0xc40
[ 14.277842][ C0] ? __sanitizer_cov_trace_const_cmp8+0x1d/0x70
[ 14.277856][ C0] console_unlock+0x7c9/0xc40
[ 14.277872][ C0] ? devkmsg_read+0x7d0/0x7d0
[ 14.277886][ C0] ? lock_release+0x720/0x720
[ 14.277904][ C0] ? vprintk+0x8d/0x260
[ 14.277918][ C0] ? vprintk+0x8d/0x260
[ 14.277933][ C0] vprintk_emit+0x1ca/0x560
[ 14.277948][ C0] vprintk+0x8d/0x260
[ 14.277961][ C0] printk+0xba/0xed
[ 14.277978][ C0] ? record_print_text.cold+0x16/0x16
[ 14.277997][ C0] ? copy_regset_to_user+0x160/0x160
[ 14.278016][ C0] load_certificate_list.cold+0x8f/0xa1
[ 14.278031][ C0] ? context_tracking_init+0x86/0x86
[ 14.278046][ C0] do_one_initcall+0x103/0x650
[ 14.278062][ C0] ? perf_trace_initcall_level+0x400/0x400
[ 14.278076][ C0] ? parameq+0xf0/0x170
[ 14.278089][ C0] ? asm_common_interrupt+0x1e/0x40
[ 14.278110][ C0] kernel_init_freeable+0x6b8/0x741
[ 14.278128][ C0] ? rest_init+0x3e0/0x3e0
[ 14.278141][ C0] kernel_init+0x1a/0x1d0
[ 14.278152][ C0] ? rest_init+0x3e0/0x3e0
[ 14.278163][ C0] ret_from_fork+0x1f/0x30
[ 14.278186][ C0] Kernel panic - not syncing: panic_on_warn set ...
[ 14.278193][ C0] CPU: 0 PID: 1 Comm: swapper/0 Not tainted 5.14.0-rc5-syzkaller #0
[ 14.278206][ C0] Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 07/22/2022
[ 14.278213][ C0] Call Trace:
[ 14.278217][ C0] <IRQ>
[ 14.278221][ C0] dump_stack_lvl+0xcd/0x134
[ 14.278240][ C0] panic+0x306/0x73d
[ 14.278252][ C0] ? __warn_printk+0xf3/0xf3
[ 14.278269][ C0] ? __warn.cold+0x1a/0x44
[ 14.278282][ C0] ? __hrtimer_run_queues+0xbf5/0x1230
[ 14.278299][ C0] __warn.cold+0x35/0x44
[ 14.278312][ C0] ? __hrtimer_run_queues+0xbf5/0x1230
[ 14.278328][ C0] report_bug+0x1bd/0x210
[ 14.278344][ C0] handle_bug+0x3c/0x60
[ 14.278364][ C0] exc_invalid_op+0x14/0x40
[ 14.278378][ C0] asm_exc_invalid_op+0x12/0x20
[ 14.278390][ C0] RIP: 0010:__hrtimer_run_queues+0xbf5/0x1230
[ 14.278407][ C0] Code: 10 00 0f 0b e9 70 f6 ff ff bd 01 00 00 00 e8 b2 44 10 00 48 8b 34 24 48 c7 c7 a0 cd 8d 89 c6 05 0b 9e f2 0b 01 e8 75 c9 82 07 <0f> 0b e8 94 44 10 00 31 ff 89 ee e8 cb 4a 10 00 40 84 ed 0f 84 00
[ 14.278419][ C0] RSP: 0000:ffffc90000007e20 EFLAGS: 00010086
[ 14.278430][ C0] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000
[ 14.278438][ C0] RDX: ffff888140160000 RSI: ffffffff815d8865 RDI: fffff52000000fb6
[ 14.278447][ C0] RBP: 0000000000000001 R08: 0000000000000000 R09: 0000000000000001
[ 14.278455][ C0] R10: ffffffff815d269e R11: 0000000000000000 R12: ffff8880b9c26d60
[ 14.278464][ C0] R13: ffff8880b9c26488 R14: ffff8880b9c26440 R15: ffff8880b9c263c0
[ 14.278476][ C0] ? wake_up_klogd.part.0+0x8e/0xd0
[ 14.278490][ C0] ? vprintk+0x95/0x260
[ 14.278504][ C0] ? get_cpu_iowait_time_us+0x3f0/0x3f0
[ 14.278524][ C0] ? hrtimer_sleeper_start_expires+0x80/0x80
[ 14.278540][ C0] ? ktime_get_update_offsets_now+0x3eb/0x5c0
[ 14.278559][ C0] hrtimer_interrupt+0x31c/0x790
[ 14.278581][ C0] __sysvec_apic_timer_interrupt+0x146/0x530
[ 14.278597][ C0] sysvec_apic_timer_interrupt+0x8e/0xc0
[ 14.278614][ C0] </IRQ>
[ 14.278619][ C0] asm_sysvec_apic_timer_interrupt+0x12/0x20
[ 14.278633][ C0] RIP: 0010:__sanitizer_cov_trace_pc+0x0/0x60
[ 14.278647][ C0] Code: 01 f0 4d 89 03 e9 63 fd ff ff b9 ff ff ff ff ba 08 00 00 00 4d 8b 03 48 0f bd ca 49 8b 45 00 48 63 c9 e9 64 ff ff ff 0f 1f 00 <65> 8b 05 59 33 8c 7e 89 c1 48 8b 34 24 81 e1 00 01 00 00 65 48 8b
[ 14.278659][ C0] RSP: 0000:ffffc90000c67b18 EFLAGS: 00000293
[ 14.278669][ C0] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000
[ 14.278677][ C0] RDX: ffff888140160000 RSI: ffffffff815d55f3 RDI: 0000000000000003
[ 14.278686][ C0] RBP: 0000000000000000 R08: 0000000000000000 R09: ffffffff8fcb98a7
[ 14.278694][ C0] R10: ffffffff815d55e9 R11: 0000000000000000 R12: ffffffff8432d7f0
[ 14.278703][ C0] R13: 0000000000000200 R14: dffffc0000000000 R15: ffffc90000c67b78
[ 14.278713][ C0] ? univ8250_console_exit+0x70/0x70
[ 14.278727][ C0] ? console_unlock+0x7b9/0xc40
[ 14.278741][ C0] ? console_unlock+0x7c3/0xc40
[ 14.278755][ C0] ? __sanitizer_cov_trace_const_cmp8+0x1d/0x70
[ 14.278769][ C0] console_unlock+0x7c9/0xc40
[ 14.278785][ C0] ? devkmsg_read+0x7d0/0x7d0
[ 14.278798][ C0] ? lock_release+0x720/0x720
[ 14.278815][ C0] ? vprintk+0x8d/0x260
[ 14.278828][ C0] ? vprintk+0x8d/0x260
[ 14.278843][ C0] vprintk_emit+0x1ca/0x560
[ 14.278858][ C0] vprintk+0x8d/0x260
[ 14.278871][ C0] printk+0xba/0xed
[ 14.278885][ C0] ? record_print_text.cold+0x16/0x16
[ 14.278905][ C0] ? copy_regset_to_user+0x160/0x160
[ 14.278922][ C0] load_certificate_list.cold+0x8f/0xa1
[ 14.278936][ C0] ? context_tracking_init+0x86/0x86
[ 14.278949][ C0] do_one_initcall+0x103/0x650
[ 14.278964][ C0] ? perf_trace_initcall_level+0x400/0x400
[ 14.278982][ C0] ? parameq+0xf0/0x170
[ 14.278995][ C0] ? asm_common_interrupt+0x1e/0x40
[ 14.279015][ C0] kernel_init_freeable+0x6b8/0x741
[ 14.279032][ C0] ? rest_init+0x3e0/0x3e0
[ 14.279044][ C0] kernel_init+0x1a/0x1d0
[ 14.279055][ C0] ? rest_init+0x3e0/0x3e0
[ 14.279066][ C0] ret_from_fork+0x1f/0x30
[ 14.279390][ C0] Kernel Offset: disabled
[ 15.085281][ C0] Rebooting in 86400 seconds..


syzkaller build log:
go env (err=<nil>)
GO111MODULE="auto"
GOARCH="amd64"
GOBIN=""
GOCACHE="/syzkaller/.cache/go-build"
GOENV="/syzkaller/.config/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/syzkaller/jobs/linux/gopath/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/syzkaller/jobs/linux/gopath"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/linux_amd64"
GOVCS=""
GOVERSION="go1.17"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/syzkaller/jobs/linux/gopath/src/github.com/google/syzkaller/go.mod"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build3435624800=/tmp/go-build -gno-record-gcc-switches"

git status (err=<nil>)
HEAD detached at 9d2ab5dfe
nothing to commit, working tree clean


go list -f '{{.Stale}}' ./sys/syz-sysgen | grep -q false || go install ./sys/syz-sysgen
make .descriptions
bin/syz-sysgen
touch .descriptions
GOOS=linux GOARCH=amd64 go build "-ldflags=-s -w -X github.com/google/syzkaller/prog.GitRevision=9d2ab5dfe7727dfea4b9b279f4edf731acb386ef -X 'github.com/google/syzkaller/prog.gitRevisionDate=20210626-071149'" "-tags=syz_target syz_os_linux syz_arch_amd64 " -o ./bin/linux_amd64/syz-fuzzer github.com/google/syzkaller/syz-fuzzer
GOOS=linux GOARCH=amd64 go build "-ldflags=-s -w -X github.com/google/syzkaller/prog.GitRevision=9d2ab5dfe7727dfea4b9b279f4edf731acb386ef -X 'github.com/google/syzkaller/prog.gitRevisionDate=20210626-071149'" "-tags=syz_target syz_os_linux syz_arch_amd64 " -o ./bin/linux_amd64/syz-execprog github.com/google/syzkaller/tools/syz-execprog
GOOS=linux GOARCH=amd64 go build "-ldflags=-s -w -X github.com/google/syzkaller/prog.GitRevision=9d2ab5dfe7727dfea4b9b279f4edf731acb386ef -X 'github.com/google/syzkaller/prog.gitRevisionDate=20210626-071149'" "-tags=syz_target syz_os_linux syz_arch_amd64 " -o ./bin/linux_amd64/syz-stress github.com/google/syzkaller/tools/syz-stress
mkdir -p ./bin/linux_amd64
gcc -o ./bin/linux_amd64/syz-executor executor/executor.cc \
-m64 -O2 -pthread -Wall -Werror -Wparentheses -Wunused-const-variable -Wframe-larger-than=16384 -static -fpermissive -w -DGOOS_linux=1 -DGOARCH_amd64=1 \
-DHOSTGOOS_linux=1 -DGIT_REVISION=\"9d2ab5dfe7727dfea4b9b279f4edf731acb386ef\"


Error text is too large and was truncated, full error text is at:
https://syzkaller.appspot.com/x/error.txt?x=14ce83da080000

Tested on:

commit: f80e2148 hrtimer: Unbreak hrtimer_force_reprogram()
git tree: https://git.kernel.org/pub/scm/linux/kernel/git/netdev/net.git

kernel config: https://syzkaller.appspot.com/x/.config?x=31eef52c6517a0c2
dashboard link: https://syzkaller.appspot.com/bug?extid=3ba0493d523d007b3819
compiler: gcc (Debian 10.2.1-6) 10.2.1 20210110, GNU ld (GNU Binutils for Debian) 2.35.2

patch: https://syzkaller.appspot.com/x/patch.diff?x=16b49b22080000

[Hillf Danton]

On Thu, 28 Jul 2022 00:46:17 -0700

> syzbot has tested the proposed patch but the reproducer is still triggering an issue:
> INFO: rcu detected stall in net_tx_action
>
> rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
> rcu: 0-...!: (1 GPs behind) idle=a16/1/0x4000000000000000 softirq=8550/8551 fqs=1
> rcu: Tasks blocked on level-0 rcu_node (CPUs 0-1):
> (detected by 1, t=10843 jiffies, g=10157, q=515)
> Sending NMI from CPU 1 to CPUs 0:
> NMI backtrace for cpu 0
> CPU: 0 PID: 13 Comm: ksoftirqd/0 Not tainted 5.14.0-rc5-syzkaller #0

Print the hrtimer hog.

#syz test https://git.kernel.org/pub/scm/linux/kernel/git/netdev/net.git f80e2148

--- y/kernel/time/hrtimer.c
+++ h/kernel/time/hrtimer.c
@@ -1647,6 +1647,8 @@ static void __run_hrtimer(struct hrtimer
enum hrtimer_restart (*fn)(struct hrtimer *);
bool expires_in_hardirq;
int restart;
+ unsigned long ts;
+ ktime_t ts_thr, ts_ns;

lockdep_assert_held(&cpu_base->lock);

@@ -1681,13 +1683,19 @@ static void __run_hrtimer(struct hrtimer
raw_spin_unlock_irqrestore(&cpu_base->lock, flags);
trace_hrtimer_expire_entry(timer, now);
expires_in_hardirq = lockdep_hrtimer_enter(timer);

+ ts = jiffies + 2;

restart = fn(timer);

+ WARN_ONCE(time_after(jiffies, ts), "hrtimer hog %ps ran longer than 2 ticks\n", fn);

+
lockdep_hrtimer_exit(expires_in_hardirq);
trace_hrtimer_expire_exit(timer);
raw_spin_lock_irq(&cpu_base->lock);

+ ts_ns = hrtimer_update_base(cpu_base);

+ ts_thr = ktime_add_ms(*now, 2);
+ WARN_ONCE(ktime_after(ts_ns, ts_thr), "hrtimer hog %ps ran longer than 2ms\n", fn);

[syzbot]

Hello,

syzbot has tested the proposed patch but the reproducer is still triggering an issue:

WARNING in __hrtimer_run_queues

------------[ cut here ]------------
hrtimer hog tick_sched_timer ran longer than 2 ticks
WARNING: CPU: 0 PID: 5792 at kernel/time/hrtimer.c:1690 __run_hrtimer kernel/time/hrtimer.c:1690 [inline]
WARNING: CPU: 0 PID: 5792 at kernel/time/hrtimer.c:1690 __hrtimer_run_queues+0xbf5/0x1230 kernel/time/hrtimer.c:1757
Modules linked in:
CPU: 0 PID: 5792 Comm: udevd Not tainted 5.14.0-rc5-syzkaller #0

Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 07/22/2022

RIP: 0010:__run_hrtimer kernel/time/hrtimer.c:1690 [inline]
RIP: 0010:__hrtimer_run_queues+0xbf5/0x1230 kernel/time/hrtimer.c:1757

Code: 10 00 0f 0b e9 70 f6 ff ff bd 01 00 00 00 e8 b2 44 10 00 48 8b 34 24 48 c7 c7 a0 cd 8d 89 c6 05 0b 9e f2 0b 01 e8 75 c9 82 07 <0f> 0b e8 94 44 10 00 31 ff 89 ee e8 cb 4a 10 00 40 84 ed 0f 84 00

RSP: 0018:ffffc90000007e20 EFLAGS: 00010086

RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000

RDX: ffff888017c79c40 RSI: ffffffff815d8865 RDI: fffff52000000fb6
RBP: 0000000000000001 R08: 0000000000000000 R09: 0000000000000000

R10: ffffffff815d269e R11: 0000000000000000 R12: ffff8880b9c26d60

R13: ffff8880b9c26488 R14: ffff8880b9c26440 R15: ffff8880b9c263c0

FS: 00007f5a1a630840(0000) GS:ffff8880b9c00000(0000) knlGS:0000000000000000

CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033

CR2: 000000000051e370 CR3: 00000000182e0000 CR4: 00000000003506f0

DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000

DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400

Call Trace:
<IRQ>
hrtimer_interrupt+0x31c/0x790 kernel/time/hrtimer.c:1819

local_apic_timer_interrupt arch/x86/kernel/apic/apic.c:1089 [inline]
__sysvec_apic_timer_interrupt+0x146/0x530 arch/x86/kernel/apic/apic.c:1106
sysvec_apic_timer_interrupt+0x8e/0xc0 arch/x86/kernel/apic/apic.c:1100
</IRQ>
asm_sysvec_apic_timer_interrupt+0x12/0x20 arch/x86/include/asm/idtentry.h:638

RIP: 0010:check_kcov_mode kernel/kcov.c:163 [inline]
RIP: 0010:__sanitizer_cov_trace_pc+0x7/0x60 kernel/kcov.c:197

Code: fd ff ff b9 ff ff ff ff ba 08 00 00 00 4d 8b 03 48 0f bd ca 49 8b 45 00 48 63 c9 e9 64 ff ff ff 0f 1f 00 65 8b 05 59 33 8c 7e <89> c1 48 8b 34 24 81 e1 00 01 00 00 65 48 8b 14 25 00 f0 01 00 a9
RSP: 0018:ffffc900016cf858 EFLAGS: 00000246
RAX: 0000000080000000 RBX: 0000000000000007 RCX: 0000000000000000
RDX: 0000000000000000 RSI: ffff888017c79c40 RDI: 0000000000000003
RBP: ffff8880190b8e00 R08: 0000000000000000 R09: 0000000000000007
R10: ffffffff839f55d7 R11: 0000000000000010 R12: 0000000000000002
R13: 000000000000024d R14: dffffc0000000000 R15: 0000000000000000
tomoyo_domain_quota_is_ok+0x31a/0x550 security/tomoyo/util.c:1092
tomoyo_supervisor+0x2f2/0xf00 security/tomoyo/common.c:2089
tomoyo_audit_path_log security/tomoyo/file.c:168 [inline]
tomoyo_path_permission security/tomoyo/file.c:587 [inline]
tomoyo_path_permission+0x270/0x3a0 security/tomoyo/file.c:573
tomoyo_path_perm+0x2f0/0x400 security/tomoyo/file.c:838
security_inode_getattr+0xcf/0x140 security/security.c:1332
vfs_getattr fs/stat.c:139 [inline]
vfs_statx+0x164/0x390 fs/stat.c:207
vfs_fstatat fs/stat.c:225 [inline]
__do_sys_newfstatat+0x96/0x120 fs/stat.c:394

do_syscall_x64 arch/x86/entry/common.c:50 [inline]
do_syscall_64+0x35/0xb0 arch/x86/entry/common.c:80
entry_SYSCALL_64_after_hwframe+0x44/0xae

RIP: 0033:0x7f5a1a7871da
Code: 48 89 f2 b9 00 01 00 00 48 89 fe bf 9c ff ff ff e9 0b 00 00 00 66 2e 0f 1f 84 00 00 00 00 00 90 41 89 ca b8 06 01 00 00 0f 05 <3d> 00 f0 ff ff 77 07 31 c0 c3 0f 1f 40 00 48 8b 15 69 fc 0c 00 f7
RSP: 002b:00007ffc16494b38 EFLAGS: 00000202 ORIG_RAX: 0000000000000106
RAX: ffffffffffffffda RBX: 0000000000006180 RCX: 00007f5a1a7871da
RDX: 00007ffc16494b68 RSI: 000055fa80fa7ba0 RDI: 00000000ffffff9c
RBP: 000055fa80fc4060 R08: 0000000000000000 R09: 000055fa80fb2640
R10: 0000000000000100 R11: 0000000000000202 R12: 000055fa80fa7ba0
R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000006180
----------------
Code disassembly (best guess), 3 bytes skipped:
0: b9 ff ff ff ff mov $0xffffffff,%ecx
5: ba 08 00 00 00 mov $0x8,%edx
a: 4d 8b 03 mov (%r11),%r8
d: 48 0f bd ca bsr %rdx,%rcx
11: 49 8b 45 00 mov 0x0(%r13),%rax
15: 48 63 c9 movslq %ecx,%rcx
18: e9 64 ff ff ff jmpq 0xffffff81
1d: 0f 1f 00 nopl (%rax)
20: 65 8b 05 59 33 8c 7e mov %gs:0x7e8c3359(%rip),%eax # 0x7e8c3380
* 27: 89 c1 mov %eax,%ecx <-- trapping instruction
29: 48 8b 34 24 mov (%rsp),%rsi
2d: 81 e1 00 01 00 00 and $0x100,%ecx
33: 65 48 8b 14 25 00 f0 mov %gs:0x1f000,%rdx
3a: 01 00
3c: a9 .byte 0xa9

Tested on:

commit: f80e2148 hrtimer: Unbreak hrtimer_force_reprogram()
git tree: https://git.kernel.org/pub/scm/linux/kernel/git/netdev/net.git

console output: https://syzkaller.appspot.com/x/log.txt?x=14d81282080000

kernel config: https://syzkaller.appspot.com/x/.config?x=31eef52c6517a0c2
dashboard link: https://syzkaller.appspot.com/bug?extid=3ba0493d523d007b3819
compiler: gcc (Debian 10.2.1-6) 10.2.1 20210110, GNU ld (GNU Binutils for Debian) 2.35.2

patch: https://syzkaller.appspot.com/x/patch.diff?x=1756f322080000

[Hillf Danton]

On Thu, 28 Jul 2022 00:46:17 -0700

> syzbot has tested the proposed patch but the reproducer is still triggering an issue:
> INFO: rcu detected stall in net_tx_action
>
> rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
> rcu: 0-...!: (1 GPs behind) idle=a16/1/0x4000000000000000 softirq=8550/8551 fqs=1
> rcu: Tasks blocked on level-0 rcu_node (CPUs 0-1):
> (detected by 1, t=10843 jiffies, g=10157, q=515)
> Sending NMI from CPU 1 to CPUs 0:
> NMI backtrace for cpu 0
> CPU: 0 PID: 13 Comm: ksoftirqd/0 Not tainted 5.14.0-rc5-syzkaller #0

Print the hrtimer hog.

#syz test https://git.kernel.org/pub/scm/linux/kernel/git/netdev/net.git f80e2148

--- y/kernel/time/hrtimer.c
+++ h/kernel/time/hrtimer.c

@@ -1647,6 +1647,7 @@ static void __run_hrtimer(struct hrtimer

enum hrtimer_restart (*fn)(struct hrtimer *);
bool expires_in_hardirq;
int restart;
+ unsigned long ts;

lockdep_assert_held(&cpu_base->lock);

@@ -1682,8 +1683,12 @@ static void __run_hrtimer(struct hrtimer

trace_hrtimer_expire_entry(timer, now);
expires_in_hardirq = lockdep_hrtimer_enter(timer);

+ ts = jiffies + 4;
+
restart = fn(timer);

+ WARN_ONCE(time_after(jiffies, ts), "hrtimer hog %ps ran longer than 4 ticks\n", fn);

+
lockdep_hrtimer_exit(expires_in_hardirq);
trace_hrtimer_expire_exit(timer);
raw_spin_lock_irq(&cpu_base->lock);

--

[syzbot]

Hello,

syzbot has tested the proposed patch but the reproducer is still triggering an issue:

WARNING in __hrtimer_run_queues

------------[ cut here ]------------

hrtimer hog advance_sched ran longer than 4 ticks
WARNING: CPU: 0 PID: 5822 at kernel/time/hrtimer.c:1690 __run_hrtimer kernel/time/hrtimer.c:1690 [inline]
WARNING: CPU: 0 PID: 5822 at kernel/time/hrtimer.c:1690 __hrtimer_run_queues+0xa93/0xff0 kernel/time/hrtimer.c:1754
Modules linked in:
CPU: 0 PID: 5822 Comm: syz-executor.0 Not tainted 5.14.0-rc5-syzkaller #0

Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 07/22/2022
RIP: 0010:__run_hrtimer kernel/time/hrtimer.c:1690 [inline]

RIP: 0010:__hrtimer_run_queues+0xa93/0xff0 kernel/time/hrtimer.c:1754
Code: 00 0f 0b e9 cd f7 ff ff bd 01 00 00 00 e8 d5 43 10 00 48 8b 74 24 08 48 c7 c7 a0 cd 8d 89 c6 05 2c 9f f2 0b 01 e8 d7 ba 82 07 <0f> 0b e8 b6 43 10 00 31 ff 89 ee e8 ed 49 10 00 40 84 ed 0f 84 5e
RSP: 0018:ffffc90000007e30 EFLAGS: 00010082
RAX: 0000000000000000 RBX: 0000000000000001 RCX: 0000000000000000
RDX: ffff888026cad4c0 RSI: ffffffff815d8865 RDI: fffff52000000fb8
RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
R10: ffffffff815d269e R11: 0000000000000000 R12: ffff88802c47a340
R13: 0000000000000003 R14: ffff8880b9c265c0 R15: ffff8880b9c263c0
FS: 0000000001684400(0000) GS:ffff8880b9c00000(0000) knlGS:0000000000000000

CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033

CR2: 00007ffc94018bf8 CR3: 000000002a6ff000 CR4: 00000000003506f0

DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
<IRQ>

hrtimer_interrupt+0x31c/0x790 kernel/time/hrtimer.c:1816

local_apic_timer_interrupt arch/x86/kernel/apic/apic.c:1089 [inline]
__sysvec_apic_timer_interrupt+0x146/0x530 arch/x86/kernel/apic/apic.c:1106
sysvec_apic_timer_interrupt+0x8e/0xc0 arch/x86/kernel/apic/apic.c:1100
</IRQ>
asm_sysvec_apic_timer_interrupt+0x12/0x20 arch/x86/include/asm/idtentry.h:638

RIP: 0010:__sanitizer_cov_trace_const_cmp4+0x8/0x70 kernel/kcov.c:285
Code: 44 30 e0 03 00 00 00 48 89 7c 30 e8 48 89 4c 30 f0 4c 89 54 d8 20 48 89 10 5b c3 0f 1f 80 00 00 00 00 41 89 f8 bf 03 00 00 00 <4c> 8b 14 24 89 f1 65 48 8b 34 25 00 f0 01 00 e8 54 f0 ff ff 84 c0
RSP: 0018:ffffc9000186f600 EFLAGS: 00000282
RAX: 1ffff11004f4e000 RBX: 00000000f23f97db RCX: 0000000000000000
RDX: ffff888026cad4c0 RSI: 0000000000000002 RDI: 0000000000000003
RBP: ffff888027a70008 R08: 0000000000000000 R09: 0000000075a57e01
R10: ffffffff8141eec8 R11: 0000000000000000 R12: 0000000000000002
R13: ffff888027a70000 R14: 0000000000000000 R15: dffffc0000000000
crc32c_intel_le_hw arch/x86/crypto/crc32c-intel_glue.c:65 [inline]
crc32c_pcl_intel_update+0xe0/0x320 arch/x86/crypto/crc32c-intel_glue.c:165
crypto_shash_update+0xc4/0x120 crypto/shash.c:131
ext4_chksum fs/ext4/ext4.h:2388 [inline]
ext4_group_desc_csum+0x30d/0x9c0 fs/ext4/super.c:2804
ext4_group_desc_csum_set+0xc7/0x2a0 fs/ext4/super.c:2850
ext4_free_blocks+0xb44/0x1ef0 fs/ext4/mballoc.c:5995
ext4_remove_blocks fs/ext4/extents.c:2502 [inline]
ext4_ext_rm_leaf fs/ext4/extents.c:2668 [inline]
ext4_ext_remove_space+0x2247/0x4590 fs/ext4/extents.c:2916
ext4_ext_truncate+0x205/0x260 fs/ext4/extents.c:4377
ext4_truncate+0xecc/0x1440 fs/ext4/inode.c:4262
ext4_evict_inode+0xa71/0x1950 fs/ext4/inode.c:288
evict+0x2ed/0x6b0 fs/inode.c:584
iput_final fs/inode.c:1660 [inline]
iput.part.0+0x539/0x850 fs/inode.c:1686
iput+0x58/0x70 fs/inode.c:1676
dentry_unlink_inode+0x2b1/0x3d0 fs/dcache.c:376
d_delete fs/dcache.c:2505 [inline]
d_delete+0x16b/0x1c0 fs/dcache.c:2494
vfs_rmdir.part.0+0x37b/0x430 fs/namei.c:3919
vfs_rmdir fs/namei.c:3891 [inline]
do_rmdir+0x3d6/0x480 fs/namei.c:3968

do_syscall_x64 arch/x86/entry/common.c:50 [inline]
do_syscall_64+0x35/0xb0 arch/x86/entry/common.c:80
entry_SYSCALL_64_after_hwframe+0x44/0xae

RIP: 0033:0x465f47
Code: 73 01 c3 48 c7 c1 bc ff ff ff f7 d8 64 89 01 48 83 c8 ff c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 b8 54 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 c7 c1 bc ff ff ff f7 d8 64 89 01 48
RSP: 002b:00007ffc94019338 EFLAGS: 00000207 ORIG_RAX: 0000000000000054
RAX: ffffffffffffffda RBX: 0000000000000065 RCX: 0000000000465f47
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 00007ffc9401a4d0
RBP: 00007ffc94019400 R08: 0000000000000000 R09: 00007ffc940191d0
R10: 00000000016858c3 R11: 0000000000000207 R12: 00000000004bee70
R13: 00007ffc9401a4d0 R14: 0000000001685810 R15: 00007ffc9401a510
----------------
Code disassembly (best guess):
0: 44 30 e0 xor %r12b,%al
3: 03 00 add (%rax),%eax
5: 00 00 add %al,(%rax)
7: 48 89 7c 30 e8 mov %rdi,-0x18(%rax,%rsi,1)
c: 48 89 4c 30 f0 mov %rcx,-0x10(%rax,%rsi,1)
11: 4c 89 54 d8 20 mov %r10,0x20(%rax,%rbx,8)
16: 48 89 10 mov %rdx,(%rax)
19: 5b pop %rbx
1a: c3 retq
1b: 0f 1f 80 00 00 00 00 nopl 0x0(%rax)
22: 41 89 f8 mov %edi,%r8d
25: bf 03 00 00 00 mov $0x3,%edi
* 2a: 4c 8b 14 24 mov (%rsp),%r10 <-- trapping instruction
2e: 89 f1 mov %esi,%ecx
30: 65 48 8b 34 25 00 f0 mov %gs:0x1f000,%rsi
37: 01 00
39: e8 54 f0 ff ff callq 0xfffff092
3e: 84 c0 test %al,%al

Tested on:

commit: f80e2148 hrtimer: Unbreak hrtimer_force_reprogram()
git tree: https://git.kernel.org/pub/scm/linux/kernel/git/netdev/net.git

console output: https://syzkaller.appspot.com/x/log.txt?x=175bd5e2080000

kernel config: https://syzkaller.appspot.com/x/.config?x=31eef52c6517a0c2
dashboard link: https://syzkaller.appspot.com/bug?extid=3ba0493d523d007b3819
compiler: gcc (Debian 10.2.1-6) 10.2.1 20210110, GNU ld (GNU Binutils for Debian) 2.35.2

patch: https://syzkaller.appspot.com/x/patch.diff?x=16d54ed2080000

[Hillf Danton]

On Thu, 28 Jul 2022 00:46:17 -0700

> syzbot has tested the proposed patch but the reproducer is still triggering an issue:
> INFO: rcu detected stall in net_tx_action
>
> rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
> rcu: 0-...!: (1 GPs behind) idle=a16/1/0x4000000000000000 softirq=8550/8551 fqs=1
> rcu: Tasks blocked on level-0 rcu_node (CPUs 0-1):
> (detected by 1, t=10843 jiffies, g=10157, q=515)
> Sending NMI from CPU 1 to CPUs 0:
> NMI backtrace for cpu 0
> CPU: 0 PID: 13 Comm: ksoftirqd/0 Not tainted 5.14.0-rc5-syzkaller #0

Add lockdep to hrtimer.

#syz test https://git.kernel.org/pub/scm/linux/kernel/git/netdev/net.git f80e2148

diff -pur x/include/linux/hrtimer.h y/include/linux/hrtimer.h
--- x/include/linux/hrtimer.h 2022-07-31 08:22:55.170197300 +0800
+++ y/include/linux/hrtimer.h 2022-07-31 09:35:26.448655000 +0800
@@ -124,6 +124,9 @@ struct hrtimer {
u8 is_rel;
u8 is_soft;
u8 is_hard;
+#ifdef CONFIG_LOCKDEP
+ struct lockdep_map lockdep_map;
+#endif
};

/**
@@ -369,10 +372,34 @@ static inline void hrtimer_cancel_wait_r
/* Exported timer functions: */

/* Initialize timers: */
-extern void hrtimer_init(struct hrtimer *timer, clockid_t which_clock,
+extern void hrtimer_init_core(struct hrtimer *timer, clockid_t which_clock,
enum hrtimer_mode mode);
-extern void hrtimer_init_sleeper(struct hrtimer_sleeper *sl, clockid_t clock_id,
+
+extern void hrtimer_init_sleeper_core(struct hrtimer_sleeper *sl, clockid_t clock_id,
enum hrtimer_mode mode);
+#ifdef CONFIG_LOCKDEP
+#define hrtimer_init(timer, clock, mode) \
+ do { \
+ static struct lock_class_key __key; \
+ lockdep_init_map(&(timer)->lockdep_map, #timer, &__key, 0); \
+ hrtimer_init_core(timer, clock, mode); \
+ } while (0)
+#define hrtimer_init_sleeper(sl, clock, mode) \
+ do { \
+ static struct lock_class_key __key; \
+ lockdep_init_map(&(sl)->timer.lockdep_map, #sl, &__key, 0); \
+ hrtimer_init_sleeper_core(sl, clock, mode); \
+ } while (0)
+#else
+#define hrtimer_init(timer, clock, mode) \
+ do { \
+ hrtimer_init_core(timer, clock, mode); \
+ } while (0)
+#define hrtimer_init_sleeper(sl, clock, mode) \
+ do { \
+ hrtimer_init_sleeper_core(sl, clock, mode); \
+ } while (0)
+#endif

#ifdef CONFIG_DEBUG_OBJECTS_TIMERS
extern void hrtimer_init_on_stack(struct hrtimer *timer, clockid_t which_clock,
diff -pur x/kernel/time/hrtimer.c y/kernel/time/hrtimer.c
--- x/kernel/time/hrtimer.c 2022-07-31 08:26:20.764371900 +0800
+++ y/kernel/time/hrtimer.c 2022-07-31 09:59:33.927031500 +0800
@@ -1439,6 +1439,8 @@ int hrtimer_cancel(struct hrtimer *timer
{
int ret;

+ lock_map_acquire(&timer->lockdep_map);
+ lock_map_release(&timer->lockdep_map);
do {
ret = hrtimer_try_to_cancel(timer);

@@ -1575,7 +1577,7 @@ static void __hrtimer_init(struct hrtime
}

/**
- * hrtimer_init - initialize a timer to the given clock
+ * hrtimer_init_core - initialize a timer to the given clock
* @timer: the timer to be initialized
* @clock_id: the clock to be used
* @mode: The modes which are relevant for initialization:
@@ -1586,13 +1588,13 @@ static void __hrtimer_init(struct hrtime
* but the PINNED bit is ignored as pinning happens
* when the hrtimer is started
*/
-void hrtimer_init(struct hrtimer *timer, clockid_t clock_id,
+void hrtimer_init_core(struct hrtimer *timer, clockid_t clock_id,
enum hrtimer_mode mode)
{
debug_init(timer, clock_id, mode);
__hrtimer_init(timer, clock_id, mode);
}
-EXPORT_SYMBOL_GPL(hrtimer_init);
+EXPORT_SYMBOL_GPL(hrtimer_init_core);

/*
* A timer is active, when it is enqueued into the rbtree or the
@@ -1682,7 +1684,9 @@ static void __run_hrtimer(struct hrtimer

trace_hrtimer_expire_entry(timer, now);
expires_in_hardirq = lockdep_hrtimer_enter(timer);

+ lock_map_acquire(&timer->lockdep_map);
restart = fn(timer);
+ lock_map_release(&timer->lockdep_map);

lockdep_hrtimer_exit(expires_in_hardirq);
trace_hrtimer_expire_exit(timer);
@@ -1999,19 +2003,19 @@ static void __hrtimer_init_sleeper(struc
}

/**
- * hrtimer_init_sleeper - initialize sleeper to the given clock
+ * hrtimer_init_sleeper_core - initialize sleeper to the given clock
* @sl: sleeper to be initialized
* @clock_id: the clock to be used
* @mode: timer mode abs/rel
*/
-void hrtimer_init_sleeper(struct hrtimer_sleeper *sl, clockid_t clock_id,
+void hrtimer_init_sleeper_core(struct hrtimer_sleeper *sl, clockid_t clock_id,
enum hrtimer_mode mode)
{
debug_init(&sl->timer, clock_id, mode);
__hrtimer_init_sleeper(sl, clock_id, mode);

}
-EXPORT_SYMBOL_GPL(hrtimer_init_sleeper);
+EXPORT_SYMBOL_GPL(hrtimer_init_sleeper_core);

int nanosleep_copyout(struct restart_block *restart, struct timespec64 *ts)
{
--

[syzbot]

Hello,

syzbot has tested the proposed patch and the reproducer did not trigger any issue:

Reported-and-tested-by: syzbot+3ba049...@syzkaller.appspotmail.com

Tested on:

commit: f80e2148 hrtimer: Unbreak hrtimer_force_reprogram()
git tree: https://git.kernel.org/pub/scm/linux/kernel/git/netdev/net.git

console output: https://syzkaller.appspot.com/x/log.txt?x=15be83da080000

kernel config: https://syzkaller.appspot.com/x/.config?x=31eef52c6517a0c2
dashboard link: https://syzkaller.appspot.com/bug?extid=3ba0493d523d007b3819
compiler: gcc (Debian 10.2.1-6) 10.2.1 20210110, GNU ld (GNU Binutils for Debian) 2.35.2

patch: https://syzkaller.appspot.com/x/patch.diff?x=155655de080000