syzbot


possible deadlock in detach_timer

Status: upstream: reported on 2024/09/27 01:14
Reported-by: syzbot+1973e58f7f6771bc93c2@syzkaller.appspotmail.com
First crash: 25d, last: 25d

Sample crash report:
==================================================================
======================================================
WARNING: possible circular locking dependency detected
5.15.167-syzkaller #0 Not tainted
------------------------------------------------------
ksoftirqd/1/20 is trying to acquire lock:
ffffffff8c7fc4b8 ((console_sem).lock){-.-.}-{2:2}, at: down_trylock+0x1c/0xa0 kernel/locking/semaphore.c:138

but task is already holding lock:
ffffffff8c9f5778 (report_lock){..-.}-{2:2}, at: start_report mm/kasan/report.c:109 [inline]
ffffffff8c9f5778 (report_lock){..-.}-{2:2}, at: __kasan_report mm/kasan/report.c:426 [inline]
ffffffff8c9f5778 (report_lock){..-.}-{2:2}, at: kasan_report+0xba/0x1c0 mm/kasan/report.c:451

which lock already depends on the new lock.


the existing dependency chain (in reverse order) is:

-> #4 (report_lock){..-.}-{2:2}:
       lock_acquire+0x1db/0x4f0 kernel/locking/lockdep.c:5623
       __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
       _raw_spin_lock_irqsave+0xd1/0x120 kernel/locking/spinlock.c:162
       start_report mm/kasan/report.c:109 [inline]
       __kasan_report mm/kasan/report.c:426 [inline]
       kasan_report+0xba/0x1c0 mm/kasan/report.c:451
       __hlist_del include/linux/list.h:858 [inline]
       detach_timer+0x14b/0x2f0 kernel/time/timer.c:827
       expire_timers kernel/time/timer.c:1485 [inline]
       __run_timers+0x60c/0x890 kernel/time/timer.c:1767
       run_timer_softirq+0x63/0xf0 kernel/time/timer.c:1780
       handle_softirqs+0x3a7/0x930 kernel/softirq.c:558
       run_ksoftirqd+0xc6/0x120 kernel/softirq.c:925
       smpboot_thread_fn+0x51b/0x9d0 kernel/smpboot.c:164
       kthread+0x3f6/0x4f0 kernel/kthread.c:334
       ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:287

-> #3 (&base->lock){-.-.}-{2:2}:
       lock_acquire+0x1db/0x4f0 kernel/locking/lockdep.c:5623
       __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
       _raw_spin_lock_irqsave+0xd1/0x120 kernel/locking/spinlock.c:162
       lock_timer_base+0x120/0x260 kernel/time/timer.c:946
       __mod_timer+0x1d6/0xeb0 kernel/time/timer.c:1019
       queue_delayed_work_on+0x156/0x250 kernel/workqueue.c:1715
       psi_enqueue kernel/sched/stats.h:104 [inline]
       enqueue_task+0x2fe/0x3a0 kernel/sched/core.c:1970
       activate_task kernel/sched/core.c:2002 [inline]
       wake_up_new_task+0x515/0xb60 kernel/sched/core.c:4519
       kernel_clone+0x44e/0x960 kernel/fork.c:2628
       kernel_thread+0x168/0x1e0 kernel/fork.c:2656
       rest_init+0x21/0x330 init/main.c:706
       start_kernel+0x48c/0x540 init/main.c:1140
       secondary_startup_64_no_verify+0xb1/0xbb

-> #2 (&rq->__lock){-.-.}-{2:2}:
       lock_acquire+0x1db/0x4f0 kernel/locking/lockdep.c:5623
       _raw_spin_lock_nested+0x2d/0x40 kernel/locking/spinlock.c:368
       raw_spin_rq_lock_nested+0x26/0x140 kernel/sched/core.c:475
       raw_spin_rq_lock kernel/sched/sched.h:1326 [inline]
       rq_lock kernel/sched/sched.h:1621 [inline]
       task_fork_fair+0x5d/0x350 kernel/sched/fair.c:11484
       sched_cgroup_fork+0x2d3/0x330 kernel/sched/core.c:4463
       copy_process+0x224a/0x3ef0 kernel/fork.c:2320
       kernel_clone+0x210/0x960 kernel/fork.c:2604
       kernel_thread+0x168/0x1e0 kernel/fork.c:2656
       rest_init+0x21/0x330 init/main.c:706
       start_kernel+0x48c/0x540 init/main.c:1140
       secondary_startup_64_no_verify+0xb1/0xbb

-> #1 (&p->pi_lock){-.-.}-{2:2}:
       lock_acquire+0x1db/0x4f0 kernel/locking/lockdep.c:5623
       __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
       _raw_spin_lock_irqsave+0xd1/0x120 kernel/locking/spinlock.c:162
       try_to_wake_up+0xae/0x1300 kernel/sched/core.c:4027
       up+0x6e/0x90 kernel/locking/semaphore.c:190
       __up_console_sem+0x11a/0x1e0 kernel/printk/printk.c:256
       console_unlock+0x1145/0x12b0 kernel/printk/printk.c:2760
       vprintk_emit+0xbf/0x150 kernel/printk/printk.c:2274
       _printk+0xd1/0x120 kernel/printk/printk.c:2299
       batadv_check_known_mac_addr+0x296/0x3d0 net/batman-adv/hard-interface.c:524
       batadv_hard_if_event+0x300/0x17a0 net/batman-adv/hard-interface.c:986
       notifier_call_chain kernel/notifier.c:83 [inline]
       raw_notifier_call_chain+0xd0/0x170 kernel/notifier.c:391
       call_netdevice_notifiers_info net/core/dev.c:2018 [inline]
       call_netdevice_notifiers_extack net/core/dev.c:2030 [inline]
       call_netdevice_notifiers net/core/dev.c:2044 [inline]
       dev_set_mac_address+0x325/0x470 net/core/dev.c:9074
       dev_set_mac_address_user+0x2d/0x50 net/core/dev.c:9088
       do_setlink+0x7f0/0x3d80 net/core/rtnetlink.c:2702
       __rtnl_newlink net/core/rtnetlink.c:3418 [inline]
       rtnl_newlink+0x17d6/0x2070 net/core/rtnetlink.c:3540
       rtnetlink_rcv_msg+0x993/0xee0 net/core/rtnetlink.c:5618
       netlink_rcv_skb+0x1cf/0x410 net/netlink/af_netlink.c:2503
       netlink_unicast_kernel net/netlink/af_netlink.c:1326 [inline]
       netlink_unicast+0x7b6/0x980 net/netlink/af_netlink.c:1352
       netlink_sendmsg+0xa30/0xd60 net/netlink/af_netlink.c:1920
       sock_sendmsg_nosec net/socket.c:704 [inline]
       __sock_sendmsg net/socket.c:716 [inline]
       __sys_sendto+0x564/0x720 net/socket.c:2058
       __do_sys_sendto net/socket.c:2070 [inline]
       __se_sys_sendto net/socket.c:2066 [inline]
       __x64_sys_sendto+0xda/0xf0 net/socket.c:2066
       do_syscall_x64 arch/x86/entry/common.c:50 [inline]
       do_syscall_64+0x3b/0xb0 arch/x86/entry/common.c:80
       entry_SYSCALL_64_after_hwframe+0x66/0xd0

-> #0 ((console_sem).lock){-.-.}-{2:2}:
       check_prev_add kernel/locking/lockdep.c:3053 [inline]
       check_prevs_add kernel/locking/lockdep.c:3172 [inline]
       validate_chain+0x1649/0x5930 kernel/locking/lockdep.c:3788
       __lock_acquire+0x1295/0x1ff0 kernel/locking/lockdep.c:5012
       lock_acquire+0x1db/0x4f0 kernel/locking/lockdep.c:5623
       __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
       _raw_spin_lock_irqsave+0xd1/0x120 kernel/locking/spinlock.c:162
       down_trylock+0x1c/0xa0 kernel/locking/semaphore.c:138
       __down_trylock_console_sem+0x105/0x250 kernel/printk/printk.c:239
       console_trylock kernel/printk/printk.c:2575 [inline]
       console_trylock_spinning+0x8a/0x3f0 kernel/printk/printk.c:1867
       vprintk_emit+0xa6/0x150 kernel/printk/printk.c:2273
       _printk+0xd1/0x120 kernel/printk/printk.c:2299
       start_report mm/kasan/report.c:110 [inline]
       __kasan_report mm/kasan/report.c:426 [inline]
       kasan_report+0xcb/0x1c0 mm/kasan/report.c:451
       __hlist_del include/linux/list.h:858 [inline]
       detach_timer+0x14b/0x2f0 kernel/time/timer.c:827
       expire_timers kernel/time/timer.c:1485 [inline]
       __run_timers+0x60c/0x890 kernel/time/timer.c:1767
       run_timer_softirq+0x63/0xf0 kernel/time/timer.c:1780
       handle_softirqs+0x3a7/0x930 kernel/softirq.c:558
       run_ksoftirqd+0xc6/0x120 kernel/softirq.c:925
       smpboot_thread_fn+0x51b/0x9d0 kernel/smpboot.c:164
       kthread+0x3f6/0x4f0 kernel/kthread.c:334
       ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:287

other info that might help us debug this:

Chain exists of:
  (console_sem).lock --> &base->lock --> report_lock

 Possible unsafe locking scenario:

       CPU0                    CPU1
       ----                    ----
  lock(report_lock);
                               lock(&base->lock);
                               lock(report_lock);
  lock((console_sem).lock);

 *** DEADLOCK ***

2 locks held by ksoftirqd/1/20:
 #0: ffff8880b9128098 (&base->lock){-.-.}-{2:2}, at: expire_timers kernel/time/timer.c:1492 [inline]
 #0: ffff8880b9128098 (&base->lock){-.-.}-{2:2}, at: __run_timers+0x6b0/0x890 kernel/time/timer.c:1767
 #1: ffffffff8c9f5778 (report_lock){..-.}-{2:2}, at: start_report mm/kasan/report.c:109 [inline]
 #1: ffffffff8c9f5778 (report_lock){..-.}-{2:2}, at: __kasan_report mm/kasan/report.c:426 [inline]
 #1: ffffffff8c9f5778 (report_lock){..-.}-{2:2}, at: kasan_report+0xba/0x1c0 mm/kasan/report.c:451

stack backtrace:
CPU: 1 PID: 20 Comm: ksoftirqd/1 Not tainted 5.15.167-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 09/13/2024
Call Trace:
 <TASK>
 __dump_stack lib/dump_stack.c:88 [inline]
 dump_stack_lvl+0x1e3/0x2d0 lib/dump_stack.c:106
 check_noncircular+0x2f8/0x3b0 kernel/locking/lockdep.c:2133
 check_prev_add kernel/locking/lockdep.c:3053 [inline]
 check_prevs_add kernel/locking/lockdep.c:3172 [inline]
 validate_chain+0x1649/0x5930 kernel/locking/lockdep.c:3788
 __lock_acquire+0x1295/0x1ff0 kernel/locking/lockdep.c:5012
 lock_acquire+0x1db/0x4f0 kernel/locking/lockdep.c:5623
 __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
 _raw_spin_lock_irqsave+0xd1/0x120 kernel/locking/spinlock.c:162
 down_trylock+0x1c/0xa0 kernel/locking/semaphore.c:138
 __down_trylock_console_sem+0x105/0x250 kernel/printk/printk.c:239
 console_trylock kernel/printk/printk.c:2575 [inline]
 console_trylock_spinning+0x8a/0x3f0 kernel/printk/printk.c:1867
 vprintk_emit+0xa6/0x150 kernel/printk/printk.c:2273
 _printk+0xd1/0x120 kernel/printk/printk.c:2299
 start_report mm/kasan/report.c:110 [inline]
 __kasan_report mm/kasan/report.c:426 [inline]
 kasan_report+0xcb/0x1c0 mm/kasan/report.c:451
 __hlist_del include/linux/list.h:858 [inline]
 detach_timer+0x14b/0x2f0 kernel/time/timer.c:827
 expire_timers kernel/time/timer.c:1485 [inline]
 __run_timers+0x60c/0x890 kernel/time/timer.c:1767
 run_timer_softirq+0x63/0xf0 kernel/time/timer.c:1780
 handle_softirqs+0x3a7/0x930 kernel/softirq.c:558
 run_ksoftirqd+0xc6/0x120 kernel/softirq.c:925
 smpboot_thread_fn+0x51b/0x9d0 kernel/smpboot.c:164
 kthread+0x3f6/0x4f0 kernel/kthread.c:334
 ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:287
 </TASK>
BUG: KASAN: use-after-free in __hlist_del include/linux/list.h:858 [inline]
BUG: KASAN: use-after-free in detach_timer+0x14b/0x2f0 kernel/time/timer.c:827
Write of size 8 at addr ffff88807a78ca40 by task ksoftirqd/1/20

CPU: 1 PID: 20 Comm: ksoftirqd/1 Not tainted 5.15.167-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 09/13/2024
Call Trace:
 <TASK>
 __dump_stack lib/dump_stack.c:88 [inline]
 dump_stack_lvl+0x1e3/0x2d0 lib/dump_stack.c:106
 print_address_description+0x63/0x3b0 mm/kasan/report.c:248
 __kasan_report mm/kasan/report.c:434 [inline]
 kasan_report+0x16b/0x1c0 mm/kasan/report.c:451
 __hlist_del include/linux/list.h:858 [inline]
 detach_timer+0x14b/0x2f0 kernel/time/timer.c:827
 expire_timers kernel/time/timer.c:1485 [inline]
 __run_timers+0x60c/0x890 kernel/time/timer.c:1767
 run_timer_softirq+0x63/0xf0 kernel/time/timer.c:1780
 handle_softirqs+0x3a7/0x930 kernel/softirq.c:558
 run_ksoftirqd+0xc6/0x120 kernel/softirq.c:925
 smpboot_thread_fn+0x51b/0x9d0 kernel/smpboot.c:164
 kthread+0x3f6/0x4f0 kernel/kthread.c:334
 ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:287
 </TASK>

Allocated by task 10078:
 kasan_save_stack mm/kasan/common.c:38 [inline]
 kasan_set_track mm/kasan/common.c:46 [inline]
 set_alloc_info mm/kasan/common.c:434 [inline]
 ____kasan_kmalloc+0xba/0xf0 mm/kasan/common.c:513
 kasan_kmalloc include/linux/kasan.h:264 [inline]
 kmem_cache_alloc_trace+0x143/0x290 mm/slub.c:3247
 kmalloc include/linux/slab.h:591 [inline]
 kzalloc include/linux/slab.h:721 [inline]
 hfsplus_fill_super+0x134/0x1c90 fs/hfsplus/super.c:387
 mount_bdev+0x2c9/0x3f0 fs/super.c:1398
 legacy_get_tree+0xeb/0x180 fs/fs_context.c:611
 vfs_get_tree+0x88/0x270 fs/super.c:1528
 do_new_mount+0x2ba/0xb40 fs/namespace.c:3005
 do_mount fs/namespace.c:3348 [inline]
 __do_sys_mount fs/namespace.c:3556 [inline]
 __se_sys_mount+0x2d5/0x3c0 fs/namespace.c:3533
 do_syscall_x64 arch/x86/entry/common.c:50 [inline]
 do_syscall_64+0x3b/0xb0 arch/x86/entry/common.c:80
 entry_SYSCALL_64_after_hwframe+0x66/0xd0

Freed by task 10078:
 kasan_save_stack mm/kasan/common.c:38 [inline]
 kasan_set_track+0x4b/0x80 mm/kasan/common.c:46
 kasan_set_free_info+0x1f/0x40 mm/kasan/generic.c:360
 ____kasan_slab_free+0xd8/0x120 mm/kasan/common.c:366
 kasan_slab_free include/linux/kasan.h:230 [inline]
 slab_free_hook mm/slub.c:1705 [inline]
 slab_free_freelist_hook+0xdd/0x160 mm/slub.c:1731
 slab_free mm/slub.c:3499 [inline]
 kfree+0xf1/0x270 mm/slub.c:4559
 hfsplus_fill_super+0xf21/0x1c90 fs/hfsplus/super.c:612
 mount_bdev+0x2c9/0x3f0 fs/super.c:1398
 legacy_get_tree+0xeb/0x180 fs/fs_context.c:611
 vfs_get_tree+0x88/0x270 fs/super.c:1528
 do_new_mount+0x2ba/0xb40 fs/namespace.c:3005
 do_mount fs/namespace.c:3348 [inline]
 __do_sys_mount fs/namespace.c:3556 [inline]
 __se_sys_mount+0x2d5/0x3c0 fs/namespace.c:3533
 do_syscall_x64 arch/x86/entry/common.c:50 [inline]
 do_syscall_64+0x3b/0xb0 arch/x86/entry/common.c:80
 entry_SYSCALL_64_after_hwframe+0x66/0xd0

Last potentially related work creation:
 kasan_save_stack+0x36/0x60 mm/kasan/common.c:38
 kasan_record_aux_stack+0xba/0x100 mm/kasan/generic.c:348
 insert_work+0x54/0x3e0 kernel/workqueue.c:1366
 __queue_work+0x963/0xd00 kernel/workqueue.c:1532
 call_timer_fn+0x16d/0x560 kernel/time/timer.c:1451
 expire_timers kernel/time/timer.c:1491 [inline]
 __run_timers+0x6a8/0x890 kernel/time/timer.c:1767
 run_timer_softirq+0x63/0xf0 kernel/time/timer.c:1780
 handle_softirqs+0x3a7/0x930 kernel/softirq.c:558
 run_ksoftirqd+0xc6/0x120 kernel/softirq.c:925
 smpboot_thread_fn+0x51b/0x9d0 kernel/smpboot.c:164
 kthread+0x3f6/0x4f0 kernel/kthread.c:334
 ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:287

The buggy address belongs to the object at ffff88807a78c800
 which belongs to the cache kmalloc-1k of size 1024
The buggy address is located 576 bytes inside of
 1024-byte region [ffff88807a78c800, ffff88807a78cc00)
The buggy address belongs to the page:
page:ffffea0001e9e200 refcount:1 mapcount:0 mapping:0000000000000000 index:0x0 pfn:0x7a788
head:ffffea0001e9e200 order:3 compound_mapcount:0 compound_pincount:0
flags: 0xfff00000010200(slab|head|node=0|zone=1|lastcpupid=0x7ff)
raw: 00fff00000010200 dead000000000100 dead000000000122 ffff888017041dc0
raw: 0000000000000000 0000000000100010 00000001ffffffff 0000000000000000
page dumped because: kasan: bad access detected
page_owner tracks the page as allocated
page last allocated via order 3, migratetype Unmovable, gfp_mask 0x1d2a20(GFP_ATOMIC|__GFP_NOWARN|__GFP_NORETRY|__GFP_COMP|__GFP_NOMEMALLOC|__GFP_HARDWALL), pid 6697, ts 410434637963, free_ts 410369890426
 prep_new_page mm/page_alloc.c:2426 [inline]
 get_page_from_freelist+0x322a/0x33c0 mm/page_alloc.c:4159
 __alloc_pages+0x272/0x700 mm/page_alloc.c:5423
 alloc_slab_page mm/slub.c:1775 [inline]
 allocate_slab mm/slub.c:1912 [inline]
 new_slab+0xbb/0x4b0 mm/slub.c:1975
 ___slab_alloc+0x6f6/0xe10 mm/slub.c:3008
 __slab_alloc mm/slub.c:3095 [inline]
 slab_alloc_node mm/slub.c:3186 [inline]
 __kmalloc_node_track_caller+0x1f6/0x390 mm/slub.c:4958
 kmalloc_reserve net/core/skbuff.c:356 [inline]
 __alloc_skb+0x12c/0x590 net/core/skbuff.c:427
 alloc_skb include/linux/skbuff.h:1167 [inline]
 wg_socket_send_buffer_to_peer+0x34/0x170 drivers/net/wireguard/socket.c:192
 wg_packet_send_handshake_initiation drivers/net/wireguard/send.c:40 [inline]
 wg_packet_handshake_send_worker+0x1d9/0x310 drivers/net/wireguard/send.c:51
 process_one_work+0x8a1/0x10c0 kernel/workqueue.c:2310
 worker_thread+0xaca/0x1280 kernel/workqueue.c:2457
 kthread+0x3f6/0x4f0 kernel/kthread.c:334
 ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:287
page last free stack trace:
 reset_page_owner include/linux/page_owner.h:24 [inline]
 free_pages_prepare mm/page_alloc.c:1340 [inline]
 free_pcp_prepare mm/page_alloc.c:1391 [inline]
 free_unref_page_prepare+0xc34/0xcf0 mm/page_alloc.c:3317
 free_unref_page+0x95/0x2d0 mm/page_alloc.c:3396
 do_slab_free mm/slub.c:3487 [inline]
 ___cache_free+0xe3/0x100 mm/slub.c:3506
 qlist_free_all+0x36/0x90 mm/kasan/quarantine.c:176
 kasan_quarantine_reduce+0x162/0x180 mm/kasan/quarantine.c:283
 __kasan_slab_alloc+0x2f/0xc0 mm/kasan/common.c:444
 kasan_slab_alloc include/linux/kasan.h:254 [inline]
 slab_post_alloc_hook+0x53/0x380 mm/slab.h:519
 slab_alloc_node mm/slub.c:3220 [inline]
 kmem_cache_alloc_node+0x121/0x2c0 mm/slub.c:3256
 __alloc_skb+0xdd/0x590 net/core/skbuff.c:415
 alloc_skb include/linux/skbuff.h:1167 [inline]
 alloc_skb_with_frags+0xa3/0x780 net/core/skbuff.c:6170
 sock_alloc_send_pskb+0x915/0xa50 net/core/sock.c:2530
 unix_dgram_sendmsg+0x6fd/0x2090 net/unix/af_unix.c:1798
 sock_sendmsg_nosec net/socket.c:704 [inline]
 __sock_sendmsg net/socket.c:716 [inline]
 __sys_sendto+0x564/0x720 net/socket.c:2058
 __do_sys_sendto net/socket.c:2070 [inline]
 __se_sys_sendto net/socket.c:2066 [inline]
 __x64_sys_sendto+0xda/0xf0 net/socket.c:2066
 do_syscall_x64 arch/x86/entry/common.c:50 [inline]
 do_syscall_64+0x3b/0xb0 arch/x86/entry/common.c:80
 entry_SYSCALL_64_after_hwframe+0x66/0xd0

Memory state around the buggy address:
 ffff88807a78c900: fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb
 ffff88807a78c980: fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb
>ffff88807a78ca00: fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb
                                           ^
 ffff88807a78ca80: fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb
 ffff88807a78cb00: fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb
==================================================================

Crashes (1):
Time Kernel Commit Syzkaller Config Log Report Syz repro C repro VM info Assets (help?) Manager Title
2024/09/27 01:13 linux-5.15.y 3a5928702e71 9314348a .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan possible deadlock in detach_timer
* Struck through repros no longer work on HEAD.