possible deadlock in pie_timer

Status: upstream: reported C repro on 2019/10/06 16:17
Reported-by: syzbot+49121b310d1c242c9cb8@syzkaller.appspotmail.com
First crash: 2483d, last: 1621d
Fix bisection the fix commit could be any of (bisect log):
  db1892238c55 Linux 4.14.147
  56dfe6252c68 Linux 4.14.188
   
▶ ▼ Similar bugs (4)
Kernel Title Rank 🛈 Repro Cause bisect Fix bisect Count Last Reported Patched Status
upstream possible deadlock in pie_timer (2) net 4 2 1127d 1128d 23/29 fixed on 2023/09/28 17:51
upstream possible deadlock in pie_timer net 4 C done 2 2490d 2491d 13/29 fixed on 2019/10/15 23:40
linux-6.1 possible deadlock in pie_timer 4 1 1087d 1087d 0/3 auto-obsoleted due to no activity on 2023/11/10 02:26
linux-4.19 possible deadlock in pie_timer 4 C error 1 1632d 1632d 0/1 upstream: reported C repro on 2022/02/03 09:38
▶ ▼ Last patch testing requests (4)
Created Duration User Patch Repo Result
2023/02/12 07:32 9m retest repro linux-4.14.y report log
2023/02/12 06:32 9m retest repro linux-4.14.y report log
2022/09/22 10:29 10m retest repro linux-4.14.y report log
2022/09/22 09:29 17m retest repro linux-4.14.y report log
▶ ▼ Fix bisection attempts (8)
Created Duration User Patch Repo Result
2020/07/09 20:06 38m bisect fix linux-4.14.y OK (2) job log
2020/06/09 18:52 37m bisect fix linux-4.14.y OK (0) job log log
2020/05/10 18:14 38m bisect fix linux-4.14.y OK (0) job log log
2020/04/10 17:36 37m bisect fix linux-4.14.y OK (0) job log log
2020/03/11 16:57 38m bisect fix linux-4.14.y OK (0) job log log
2020/02/10 16:19 38m bisect fix linux-4.14.y OK (0) job log log
2020/01/11 10:49 37m bisect fix linux-4.14.y OK (0) job log log
2019/12/12 10:12 37m bisect fix linux-4.14.y OK (0) job log log

Sample crash report:
======================================================
WARNING: possible circular locking dependency detected
4.14.266-syzkaller #0 Not tainted
------------------------------------------------------
syz-executor191/8185 is trying to acquire lock:
 (&qdisc_rx_lock){+.-.}, at: [<ffffffff85de32bb>] spin_lock include/linux/spinlock.h:317 [inline]
 (&qdisc_rx_lock){+.-.}, at: [<ffffffff85de32bb>] pie_timer+0x6b/0x630 net/sched/sch_pie.c:431

but task is already holding lock:
 (((&q->adapt_timer))){+.-.}, at: [<ffffffff81485b98>] lockdep_copy_map include/linux/lockdep.h:174 [inline]
 (((&q->adapt_timer))){+.-.}, at: [<ffffffff81485b98>] call_timer_fn+0xb8/0x650 kernel/time/timer.c:1270

which lock already depends on the new lock.


the existing dependency chain (in reverse order) is:

-> #1 (((&q->adapt_timer))){+.-.}:
       del_timer_sync+0xaf/0x240 kernel/time/timer.c:1236
       qdisc_destroy+0x13c/0x310 net/sched/sch_generic.c:726
       sfb_change+0x27a/0xa20 net/sched/sch_sfb.c:525
       qdisc_change net/sched/sch_api.c:1145 [inline]
       tc_modify_qdisc+0xd4e/0x1250 net/sched/sch_api.c:1411
       rtnetlink_rcv_msg+0x3be/0xb10 net/core/rtnetlink.c:4322
       netlink_rcv_skb+0x125/0x390 net/netlink/af_netlink.c:2446
       netlink_unicast_kernel net/netlink/af_netlink.c:1294 [inline]
       netlink_unicast+0x437/0x610 net/netlink/af_netlink.c:1320
       netlink_sendmsg+0x648/0xbc0 net/netlink/af_netlink.c:1891
       sock_sendmsg_nosec net/socket.c:646 [inline]
       sock_sendmsg+0xb5/0x100 net/socket.c:656
       ___sys_sendmsg+0x6c8/0x800 net/socket.c:2062
       __sys_sendmsg+0xa3/0x120 net/socket.c:2096
       SYSC_sendmsg net/socket.c:2107 [inline]
       SyS_sendmsg+0x27/0x40 net/socket.c:2103
       do_syscall_64+0x1d5/0x640 arch/x86/entry/common.c:292
       entry_SYSCALL_64_after_hwframe+0x46/0xbb

-> #0 (&qdisc_rx_lock){+.-.}:
       lock_acquire+0x170/0x3f0 kernel/locking/lockdep.c:3998
       __raw_spin_lock include/linux/spinlock_api_smp.h:142 [inline]
       _raw_spin_lock+0x2a/0x40 kernel/locking/spinlock.c:152
       spin_lock include/linux/spinlock.h:317 [inline]
       pie_timer+0x6b/0x630 net/sched/sch_pie.c:431
       call_timer_fn+0x14a/0x650 kernel/time/timer.c:1280
       expire_timers+0x232/0x4d0 kernel/time/timer.c:1319
       __run_timers kernel/time/timer.c:1637 [inline]
       run_timer_softirq+0x1d5/0x5a0 kernel/time/timer.c:1650
       __do_softirq+0x24d/0x9ff kernel/softirq.c:288
       invoke_softirq kernel/softirq.c:368 [inline]
       irq_exit+0x193/0x240 kernel/softirq.c:409
       exiting_irq arch/x86/include/asm/apic.h:638 [inline]
       smp_apic_timer_interrupt+0x141/0x5e0 arch/x86/kernel/apic/apic.c:1106
       apic_timer_interrupt+0x93/0xa0 arch/x86/entry/entry_64.S:793
       arch_local_irq_restore arch/x86/include/asm/paravirt.h:779 [inline]
       lock_acquire+0x1ec/0x3f0 kernel/locking/lockdep.c:4001
       fs_reclaim_acquire mm/page_alloc.c:3558 [inline]
       fs_reclaim_acquire+0xf4/0x120 mm/page_alloc.c:3555
       slab_pre_alloc_hook mm/slab.h:416 [inline]
       slab_alloc mm/slab.c:3376 [inline]
       kmem_cache_alloc_trace+0x29/0x3d0 mm/slab.c:3616
       kmalloc include/linux/slab.h:488 [inline]
       kzalloc include/linux/slab.h:661 [inline]
       aa_alloc_file_ctx security/apparmor/include/file.h:60 [inline]
       apparmor_file_alloc_security+0x129/0x800 security/apparmor/lsm.c:431
       security_file_alloc+0x66/0xa0 security/security.c:874
       get_empty_filp+0x16b/0x3f0 fs/file_table.c:129
       path_openat+0x84/0x2970 fs/namei.c:3545
       do_filp_open+0x179/0x3c0 fs/namei.c:3603
       do_sys_open+0x296/0x410 fs/open.c:1081
       do_syscall_64+0x1d5/0x640 arch/x86/entry/common.c:292
       entry_SYSCALL_64_after_hwframe+0x46/0xbb

other info that might help us debug this:

 Possible unsafe locking scenario:

       CPU0                    CPU1
       ----                    ----
  lock(((&q->adapt_timer)));
                               lock(&qdisc_rx_lock);
                               lock(((&q->adapt_timer)));
  lock(&qdisc_rx_lock);

 *** DEADLOCK ***

2 locks held by syz-executor191/8185:
 #0:  (fs_reclaim){+.+.}, at: [<ffffffff8169f2a4>] __need_fs_reclaim mm/page_alloc.c:3549 [inline]
 #0:  (fs_reclaim){+.+.}, at: [<ffffffff8169f2a4>] fs_reclaim_acquire+0xd4/0x120 mm/page_alloc.c:3557
 #1:  (((&q->adapt_timer))){+.-.}, at: [<ffffffff81485b98>] lockdep_copy_map include/linux/lockdep.h:174 [inline]
 #1:  (((&q->adapt_timer))){+.-.}, at: [<ffffffff81485b98>] call_timer_fn+0xb8/0x650 kernel/time/timer.c:1270

stack backtrace:
CPU: 0 PID: 8185 Comm: syz-executor191 Not tainted 4.14.266-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:17 [inline]
 dump_stack+0x1b2/0x281 lib/dump_stack.c:58
 print_circular_bug.constprop.0.cold+0x2d7/0x41e kernel/locking/lockdep.c:1258
 check_prev_add kernel/locking/lockdep.c:1905 [inline]
 check_prevs_add kernel/locking/lockdep.c:2022 [inline]
 validate_chain kernel/locking/lockdep.c:2464 [inline]
 __lock_acquire+0x2e0e/0x3f20 kernel/locking/lockdep.c:3491
 lock_acquire+0x170/0x3f0 kernel/locking/lockdep.c:3998
 __raw_spin_lock include/linux/spinlock_api_smp.h:142 [inline]
 _raw_spin_lock+0x2a/0x40 kernel/locking/spinlock.c:152
 spin_lock include/linux/spinlock.h:317 [inline]
 pie_timer+0x6b/0x630 net/sched/sch_pie.c:431
 call_timer_fn+0x14a/0x650 kernel/time/timer.c:1280
 expire_timers+0x232/0x4d0 kernel/time/timer.c:1319
 __run_timers kernel/time/timer.c:1637 [inline]
 run_timer_softirq+0x1d5/0x5a0 kernel/time/timer.c:1650
 __do_softirq+0x24d/0x9ff kernel/softirq.c:288
 invoke_softirq kernel/softirq.c:368 [inline]
 irq_exit+0x193/0x240 kernel/softirq.c:409
 exiting_irq arch/x86/include/asm/apic.h:638 [inline]
 smp_apic_timer_interrupt+0x141/0x5e0 arch/x86/kernel/apic/apic.c:1106
 apic_timer_interrupt+0x93/0xa0 arch/x86/entry/entry_64.S:793
 </IRQ>
RIP: 0010:arch_local_irq_restore arch/x86/include/asm/paravirt.h:779 [inline]
RIP: 0010:lock_acquire+0x1ec/0x3f0 kernel/locking/lockdep.c:4001
RSP: 0018:ffff88808f96fa68 EFLAGS: 00000286 ORIG_RAX: ffffffffffffff10
RAX: 1ffffffff11e1279 RBX: ffff8880b29b6340 RCX: 0000000000000ec1
RDX: dffffc0000000000 RSI: 0000000000000001 RDI: 0000000000000286
RBP: ffffffff88fd7ae0 R08: ffffffff8b9a90c8 R09: 000000000004008f
R10: ffff8880b29b6bc8 R11: ffff8880b29b6340 R12: 0000000000000000
R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000001
 fs_reclaim_acquire mm/page_alloc.c:3558 [inline]
 fs_reclaim_acquire+0xf4/0x120 mm/page_alloc.c:3555
 slab_pre_alloc_hook mm/slab.h:416 [inline]
 slab_alloc mm/slab.c:3376 [inline]
 kmem_cache_alloc_trace+0x29/0x3d0 mm/slab.c:3616
 kmalloc include/linux/slab.h:488 [inline]
 kzalloc include/linux/slab.h:661 [inline]
 aa_alloc_file_ctx security/apparmor/include/file.h:60 [inline]
 apparmor_file_alloc_security+0x129/0x800 security/apparmor/lsm.c:431
 security_file_alloc+0x66/0xa0 security/security.c:874
 get_empty_filp+0x16b/0x3f0 fs/file_table.c:129
 path_openat+0x84/0x2970 fs/namei.c:3545
 do_filp_open+0x179/0x3c0 fs/namei.c:3603
 do_sys_open+0x296/0x410 fs/open.c:1081
 do_syscall_64+0x1d5/0x640 arch/x86/entry/common.c:292
 entry_SYSCALL_64_after_hwframe+0x46/0xbb
RIP: 0033:0x7fa564afad47
RSP: 002b:00007fff71b3d780 EFLAGS: 00000246 ORIG_RAX: 0000000000000101
RAX: ffffffffffffffda RBX: 0000000000000004 RCX: 00007fa564afad47
RDX: 0000000000080001 RSI: 00007fa564b7c04a RDI: 00000000ffffff9c
RBP: 00007fa564b7c04a R08: 0000000000000000 R09: 00007fff71b3d770
R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000080001
R13: 0000000000000000 R14: 00007fff71b3dd10 R15: 00007fff71b3dd04

Crashes (3):
Time Kernel Commit Syzkaller Config Log Report Syz repro C repro VM info Assets (help?) Manager Title
2022/02/13 21:14 linux-4.14.y 8034e99d1a01 8b9ca619 .config console log report syz C ci2-linux-4-14 possible deadlock in pie_timer
2019/10/06 15:16 linux-4.14.y db1892238c55 f3f7d9c8 .config console log report syz C ci2-linux-4-14
2019/10/13 05:45 linux-4.14.y e132c8d7b58d 426631dd .config console log report ci2-linux-4-14
* Struck through repros no longer work on HEAD.