syzbot


INFO: task hung in lock_extent_bits

Status: upstream: reported C repro on 2023/03/30 19:10
Bug presence: origin:upstream
Labels: missing-backport
[Documentation on labels]
Reported-by: syzbot+d359f673fb66296c98be@syzkaller.appspotmail.com
First crash: 403d, last: 17d
Fix commit to backport (bisect log) :
tree: upstream
commit a1912f712188291f9d7d434fba155461f1ebef66
Author: Josef Bacik <josef@toxicpanda.com>
Date: Wed Nov 22 17:17:55 2023 +0000

  btrfs: remove code for inode_cache and recovery mount options

  
Fix bisection: the issue occurs on the latest tested release (bisect log)
Crash: INFO: task hung in lock_extent_bits (log)
Repro: C syz .config
  
Bug presence (3)
Date Name Commit Repro Result
2024/01/16 linux-5.15.y (ToT) ddcaf4999061 C [report] INFO: task hung in lock_extent_bits
2023/06/04 upstream (ToT) e5282a7d8f6b C [report] INFO: task hung in lock_extent
2024/01/16 upstream (ToT) 052d534373b7 C Didn't crash
Fix bisection attempts (7)
Created Duration User Patch Repo Result
2024/03/26 07:49 8h20m fix candidate upstream job log (1)
2024/02/24 11:17 1h38m bisect fix linux-5.15.y job log (0) log
2023/12/25 05:58 1h28m bisect fix linux-5.15.y job log (0) log
2023/11/23 12:25 1h12m bisect fix linux-5.15.y job log (0) log
2023/10/22 11:21 1h15m bisect fix linux-5.15.y job log (0) log
2023/09/21 08:43 1h24m bisect fix linux-5.15.y job log (0) log
2023/07/08 03:33 1h43m bisect fix linux-5.15.y job log (0) log

Sample crash report:
INFO: task kworker/u4:5:1464 blocked for more than 143 seconds.
      Not tainted 5.15.114-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:kworker/u4:5    state:D stack:19520 pid: 1464 ppid:     2 flags:0x00004000
Workqueue: btrfs-endio-write btrfs_work_helper
Call Trace:
 <TASK>
 context_switch kernel/sched/core.c:5026 [inline]
 __schedule+0x12c4/0x4590 kernel/sched/core.c:6372
 schedule+0x11b/0x1f0 kernel/sched/core.c:6455
 wait_on_state fs/btrfs/extent_io.c:868 [inline]
 wait_extent_bit+0x3f9/0x530 fs/btrfs/extent_io.c:906
 lock_extent_bits+0x10d/0x1e0 fs/btrfs/extent_io.c:1469
 btrfs_finish_ordered_io+0x6e9/0x1c40 fs/btrfs/inode.c:3108
 btrfs_work_helper+0x368/0xba0 fs/btrfs/async-thread.c:325
 process_one_work+0x8a1/0x10c0 kernel/workqueue.c:2307
 worker_thread+0xaca/0x1280 kernel/workqueue.c:2454
 kthread+0x3f6/0x4f0 kernel/kthread.c:319
 ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:298
 </TASK>
INFO: task syz-executor259:3521 blocked for more than 143 seconds.
      Not tainted 5.15.114-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:syz-executor259 state:D stack:22416 pid: 3521 ppid:  3520 flags:0x00004004
Call Trace:
 <TASK>
 context_switch kernel/sched/core.c:5026 [inline]
 __schedule+0x12c4/0x4590 kernel/sched/core.c:6372
 schedule+0x11b/0x1f0 kernel/sched/core.c:6455
 wait_on_state fs/btrfs/extent_io.c:868 [inline]
 wait_extent_bit+0x3f9/0x530 fs/btrfs/extent_io.c:906
 lock_extent_bits+0x10d/0x1e0 fs/btrfs/extent_io.c:1469
 btrfs_page_mkwrite+0x5f2/0xd60 fs/btrfs/inode.c:8898
 do_page_mkwrite+0x1a9/0x440 mm/memory.c:2883
 wp_page_shared+0x179/0x690 mm/memory.c:3216
 handle_pte_fault mm/memory.c:4626 [inline]
 __handle_mm_fault mm/memory.c:4743 [inline]
 handle_mm_fault+0x2a3d/0x5950 mm/memory.c:4841
 do_user_addr_fault arch/x86/mm/fault.c:1397 [inline]
 handle_page_fault arch/x86/mm/fault.c:1485 [inline]
 exc_page_fault+0x271/0x740 arch/x86/mm/fault.c:1541
 asm_exc_page_fault+0x22/0x30 arch/x86/include/asm/idtentry.h:568
RIP: 0010:copy_user_generic_unrolled+0x89/0xc0 arch/x86/lib/copy_user_64.S:92
Code: 38 4c 89 47 20 4c 89 4f 28 4c 89 57 30 4c 89 5f 38 48 8d 76 40 48 8d 7f 40 ff c9 75 b6 89 d1 83 e2 07 c1 e9 03 74 12 4c 8b 06 <4c> 89 07 48 8d 76 08 48 8d 7f 08 ff c9 75 ee 21 d2 74 10 89 d1 8a
RSP: 0018:ffffc90002b9f668 EFLAGS: 00050202
RAX: ffffffff84063501 RBX: 0000000020000118 RCX: 0000000000000007
RDX: 0000000000000000 RSI: ffffc90002b9f720 RDI: 00000000200000e0
RBP: ffffc90002b9f7d0 R08: 0000000000000000 R09: fffff52000573eeb
R10: 0000000000000000 R11: dffffc0000000001 R12: 0000000000000038
R13: 00007ffffffff000 R14: ffffc90002b9f720 R15: 00000000200000e0
 copy_user_generic arch/x86/include/asm/uaccess_64.h:37 [inline]
 raw_copy_to_user arch/x86/include/asm/uaccess_64.h:58 [inline]
 _copy_to_user+0xef/0x130 lib/usercopy.c:40
 copy_to_user include/linux/uaccess.h:200 [inline]
 fiemap_fill_next_extent+0x231/0x410 fs/ioctl.c:144
 emit_fiemap_extent fs/btrfs/extent_io.c:5460 [inline]
 extent_fiemap+0x1218/0x1650 fs/btrfs/extent_io.c:5686
 btrfs_fiemap+0x121/0x160 fs/btrfs/inode.c:8521
 ioctl_fiemap fs/ioctl.c:219 [inline]
 do_vfs_ioctl+0x1934/0x2b70 fs/ioctl.c:814
 __do_sys_ioctl fs/ioctl.c:872 [inline]
 __se_sys_ioctl+0x81/0x160 fs/ioctl.c:860
 do_syscall_x64 arch/x86/entry/common.c:50 [inline]
 do_syscall_64+0x3d/0xb0 arch/x86/entry/common.c:80
 entry_SYSCALL_64_after_hwframe+0x61/0xcb
RIP: 0033:0x7fdeb3193309
RSP: 002b:00007ffe1bf08708 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
RAX: ffffffffffffffda RBX: 0000000020000080 RCX: 00007fdeb3193309
RDX: 00000000200000c0 RSI: 00000000c020660b RDI: 0000000000000004
RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00007ffe1bf08740
R13: 0000000000000000 R14: 431bde82d7b634db R15: 0000000000000000
 </TASK>

Showing all locks held in the system:
1 lock held by khungtaskd/27:
 #0: ffffffff8c91c5e0 (rcu_read_lock){....}-{1:2}, at: rcu_lock_acquire+0x0/0x30
2 locks held by kworker/u4:5/1464:
 #0: ffff8880242eb138 ((wq_completion)btrfs-endio-write){+.+.}-{0:0}, at: process_one_work+0x78a/0x10c0 kernel/workqueue.c:2280
 #1: ffffc90006897d20 ((work_completion)(&work->normal_work)){+.+.}-{0:0}, at: process_one_work+0x7d0/0x10c0 kernel/workqueue.c:2282
2 locks held by getty/3255:
 #0: ffff888024832098 (&tty->ldisc_sem){++++}-{0:0}, at: tty_ldisc_ref_wait+0x21/0x70 drivers/tty/tty_ldisc.c:252
 #1: ffffc90002bb62e8 (&ldata->atomic_read_lock){+.+.}-{3:3}, at: n_tty_read+0x6af/0x1da0 drivers/tty/n_tty.c:2147
3 locks held by syz-executor259/3521:
 #0: ffff88807aa86328 (&mm->mmap_lock#2){++++}-{3:3}, at: mmap_read_trylock include/linux/mmap_lock.h:136 [inline]
 #0: ffff88807aa86328 (&mm->mmap_lock#2){++++}-{3:3}, at: do_user_addr_fault arch/x86/mm/fault.c:1338 [inline]
 #0: ffff88807aa86328 (&mm->mmap_lock#2){++++}-{3:3}, at: handle_page_fault arch/x86/mm/fault.c:1485 [inline]
 #0: ffff88807aa86328 (&mm->mmap_lock#2){++++}-{3:3}, at: exc_page_fault+0x181/0x740 arch/x86/mm/fault.c:1541
 #1: ffff888078478558 (sb_pagefaults){.+.+}-{0:0}, at: do_page_mkwrite+0x1a9/0x440 mm/memory.c:2883
 #2: ffff888070850e68 (&ei->i_mmap_lock){.+.+}-{3:3}, at: btrfs_page_mkwrite+0x4a2/0xd60 fs/btrfs/inode.c:8887

=============================================

NMI backtrace for cpu 1
CPU: 1 PID: 27 Comm: khungtaskd Not tainted 5.15.114-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 05/25/2023
Call Trace:
 <TASK>
 __dump_stack lib/dump_stack.c:88 [inline]
 dump_stack_lvl+0x1e3/0x2cb lib/dump_stack.c:106
 nmi_cpu_backtrace+0x46a/0x4a0 lib/nmi_backtrace.c:111
 nmi_trigger_cpumask_backtrace+0x181/0x2a0 lib/nmi_backtrace.c:62
 trigger_all_cpu_backtrace include/linux/nmi.h:148 [inline]
 check_hung_uninterruptible_tasks kernel/hung_task.c:210 [inline]
 watchdog+0xe72/0xeb0 kernel/hung_task.c:295
 kthread+0x3f6/0x4f0 kernel/kthread.c:319
 ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:298
 </TASK>
Sending NMI from CPU 1 to CPUs 0:
NMI backtrace for cpu 0
CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.15.114-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 05/25/2023
RIP: 0010:kvm_set_cpu_l1tf_flush_l1d+0x0/0x20 arch/x86/include/asm/hardirq.h:67
Code: db fe ff ff 44 89 e1 80 e1 07 80 c1 03 38 c1 0f 8c df fe ff ff 4c 89 e7 89 d3 e8 ab 24 94 00 89 da e9 ce fe ff ff cc cc cc cc <48> c7 c7 e0 99 87 8a e8 94 9d e5 08 65 c6 05 ae 5c ce 7e 01 c3 66
RSP: 0018:ffffffff8c607ab8 EFLAGS: 00000093
RAX: ffffffff81866d01 RBX: ffffffff8c607ad8 RCX: ffffffff8c6bb5c0
RDX: 0000000000000000 RSI: ffffffff8ad85f60 RDI: ffffffff8ad85f20
RBP: 0000000081866d01 R08: ffffffff81866d05 R09: fffffbfff1bc7736
R10: 0000000000000000 R11: dffffc0000000001 R12: 0000000000000000
R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
FS:  0000000000000000(0000) GS:ffff8880b9a00000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007ffef421c158 CR3: 0000000022a45000 CR4: 00000000003506f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
 <NMI>
 </NMI>
 <TASK>
 sysvec_call_function_single+0x11/0xb0 arch/x86/kernel/smp.c:243
 asm_sysvec_call_function_single+0x16/0x20 arch/x86/include/asm/idtentry.h:646
RIP: 0010:native_save_fl arch/x86/include/asm/irqflags.h:22 [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:110 [inline]
RIP: 0010:acpi_idle_do_entry+0x10f/0x340 drivers/acpi/processor_idle.c:570
Code: ed 5b f7 48 83 e3 08 0f 85 0a 01 00 00 4c 8d 74 24 20 e8 94 5a 62 f7 0f 1f 44 00 00 e8 aa e9 5b f7 0f 00 2d 93 49 be 00 fb f4 <4c> 89 f3 48 c1 eb 03 42 80 3c 3b 00 74 08 4c 89 f7 e8 bb 44 a5 f7
RSP: 0018:ffffffff8c607b80 EFLAGS: 000002d3
RAX: ffffffff8a240fa6 RBX: 0000000000000000 RCX: ffffffff8c6bb5c0
RDX: 0000000000000000 RSI: ffffffff8a8afc60 RDI: ffffffff8ad85f80
RBP: ffffffff8c607c10 R08: ffffffff81866a60 R09: fffffbfff18d76b9
R10: 0000000000000000 R11: dffffc0000000001 R12: 1ffffffff18c0f70
R13: ffff888141fa3004 R14: ffffffff8c607ba0 R15: dffffc0000000000
 acpi_idle_enter+0x352/0x4f0 drivers/acpi/processor_idle.c:705
 cpuidle_enter_state+0x521/0xef0 drivers/cpuidle/cpuidle.c:237
 cpuidle_enter+0x59/0x90 drivers/cpuidle/cpuidle.c:351
 call_cpuidle kernel/sched/idle.c:158 [inline]
 cpuidle_idle_call kernel/sched/idle.c:239 [inline]
 do_idle+0x3e4/0x670 kernel/sched/idle.c:306
 cpu_startup_entry+0x14/0x20 kernel/sched/idle.c:403
 start_kernel+0x491/0x53a init/main.c:1144
 secondary_startup_64_no_verify+0xb1/0xbb
 </TASK>
INFO: NMI handler (nmi_cpu_backtrace_handler) took too long to run: 1.025 msecs

Crashes (18):
Time Kernel Commit Syzkaller Config Log Report Syz repro C repro VM info Assets (help?) Manager Title
2023/06/04 05:15 linux-5.15.y 0ab06468cbd1 a4ae4f42 .config console log report syz C [disk image] [vmlinux] [kernel image] [mounted in repro] ci2-linux-5-15-kasan INFO: task hung in lock_extent_bits
2024/04/19 18:34 linux-5.15.y c52b9710c83d af24b050 .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan INFO: task hung in lock_extent_bits
2024/04/19 18:34 linux-5.15.y c52b9710c83d af24b050 .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan INFO: task hung in lock_extent_bits
2024/04/14 00:58 linux-5.15.y fa3df276cd36 c8349e48 .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan INFO: task hung in lock_extent_bits
2024/04/12 22:45 linux-5.15.y cdfd0a7f0139 c8349e48 .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan INFO: task hung in lock_extent_bits
2024/04/12 22:45 linux-5.15.y cdfd0a7f0139 c8349e48 .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan INFO: task hung in lock_extent_bits
2024/04/11 19:45 linux-5.15.y cdfd0a7f0139 95ed9ece .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan INFO: task hung in lock_extent_bits
2024/04/05 05:33 linux-5.15.y 9465fef4ae35 0ee3535e .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan INFO: task hung in lock_extent_bits
2024/04/05 05:33 linux-5.15.y 9465fef4ae35 0ee3535e .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan INFO: task hung in lock_extent_bits
2024/03/27 20:42 linux-5.15.y 9465fef4ae35 120789fd .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan INFO: task hung in lock_extent_bits
2024/03/12 14:57 linux-5.15.y 574362648507 c35c26ec .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan INFO: task hung in lock_extent_bits
2024/03/12 13:53 linux-5.15.y 574362648507 c35c26ec .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan INFO: task hung in lock_extent_bits
2024/03/12 13:23 linux-5.15.y 574362648507 c35c26ec .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan INFO: task hung in lock_extent_bits
2024/03/09 21:45 linux-5.15.y 574362648507 6ee49f2e .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan INFO: task hung in lock_extent_bits
2024/03/09 04:13 linux-5.15.y 574362648507 8e75c913 .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan INFO: task hung in lock_extent_bits
2024/03/12 13:36 linux-5.15.y 574362648507 c35c26ec .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan-arm64 INFO: task hung in lock_extent_bits
2023/03/30 19:09 linux-5.15.y c957cbb87315 f325deb0 .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan INFO: task hung in lock_extent_bits
2023/06/03 16:20 linux-5.15.y 0ab06468cbd1 a4ae4f42 .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan-arm64 INFO: task hung in lock_extent_bits
* Struck through repros no longer work on HEAD.