syzbot


INFO: task hung in extent_write_cache_pages

Status: fixed on 2023/06/08 14:41
Subsystems: btrfs
[Documentation on labels]
Reported-by: syzbot+cc35f55c41e34c30dcb5@syzkaller.appspotmail.com
Fix commit: 519b7e13b5ae btrfs: lock the inode in shared mode before starting fiemap
First crash: 687d, last: 543d
Cause bisection: failed (error log, bisect log)
  
Discussions (1)
Title Replies (including bot) Last reply
[syzbot] [btrfs?] INFO: task hung in extent_write_cache_pages 0 (1) 2023/01/19 23:38

Sample crash report:
INFO: task kworker/u4:3:46 blocked for more than 143 seconds.
      Not tainted 6.3.0-syzkaller-13505-g17784de648be #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:kworker/u4:3    state:D stack:25320 pid:46    ppid:2      flags:0x00004000
Workqueue: writeback wb_workfn (flush-btrfs-251)
Call Trace:
 <TASK>
 context_switch kernel/sched/core.c:5343 [inline]
 __schedule+0xc9a/0x5880 kernel/sched/core.c:6669
 schedule+0xde/0x1a0 kernel/sched/core.c:6745
 io_schedule+0xbe/0x130 kernel/sched/core.c:8979
 folio_wait_bit_common+0x394/0x9b0 mm/filemap.c:1301
 folio_lock include/linux/pagemap.h:955 [inline]
 extent_write_cache_pages+0x657/0xd10 fs/btrfs/extent_io.c:2457
 extent_writepages+0x20c/0x4a0 fs/btrfs/extent_io.c:2599
 do_writepages+0x1a8/0x640 mm/page-writeback.c:2551
 __writeback_single_inode+0x121/0xdb0 fs/fs-writeback.c:1603
 writeback_sb_inodes+0x54d/0xe70 fs/fs-writeback.c:1894
 __writeback_inodes_wb+0xc6/0x280 fs/fs-writeback.c:1965
 wb_writeback+0x7e9/0xa50 fs/fs-writeback.c:2070
 wb_check_background_flush fs/fs-writeback.c:2136 [inline]
 wb_do_writeback fs/fs-writeback.c:2224 [inline]
 wb_workfn+0x8b0/0xfc0 fs/fs-writeback.c:2251
 process_one_work+0x99a/0x15e0 kernel/workqueue.c:2405
 worker_thread+0x67d/0x10c0 kernel/workqueue.c:2552
 kthread+0x344/0x440 kernel/kthread.c:379
 ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:308
 </TASK>
INFO: task syz-executor945:12203 blocked for more than 143 seconds.
      Not tainted 6.3.0-syzkaller-13505-g17784de648be #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:syz-executor945 state:D stack:25128 pid:12203 ppid:5046   flags:0x00000004
Call Trace:
 <TASK>
 context_switch kernel/sched/core.c:5343 [inline]
 __schedule+0xc9a/0x5880 kernel/sched/core.c:6669
 schedule+0xde/0x1a0 kernel/sched/core.c:6745
 wait_on_state fs/btrfs/extent-io-tree.c:707 [inline]
 wait_extent_bit+0x56e/0x670 fs/btrfs/extent-io-tree.c:751
 lock_extent+0x120/0x1c0 fs/btrfs/extent-io-tree.c:1742
 find_lock_delalloc_range+0x27e/0x700 fs/btrfs/extent_io.c:479
 writepage_delalloc+0x16a/0x3e0 fs/btrfs/extent_io.c:1323
 __extent_writepage+0xf8d/0x15e0 fs/btrfs/extent_io.c:1609
 extent_write_cache_pages+0x465/0xd10 fs/btrfs/extent_io.c:2477
 extent_writepages+0x20c/0x4a0 fs/btrfs/extent_io.c:2599
 do_writepages+0x1a8/0x640 mm/page-writeback.c:2551
 filemap_fdatawrite_wbc mm/filemap.c:390 [inline]
 filemap_fdatawrite_wbc+0x147/0x1b0 mm/filemap.c:380
 __filemap_fdatawrite_range+0xb8/0xf0 mm/filemap.c:423
 btrfs_fdatawrite_range+0x4a/0x110 fs/btrfs/file.c:3862
 btrfs_direct_write fs/btrfs/file.c:1603 [inline]
 btrfs_do_write_iter+0xf24/0x1470 fs/btrfs/file.c:1674
 call_write_iter include/linux/fs.h:1868 [inline]
 new_sync_write fs/read_write.c:491 [inline]
 vfs_write+0x945/0xd50 fs/read_write.c:584
 ksys_write+0x12b/0x250 fs/read_write.c:637
 do_syscall_x64 arch/x86/entry/common.c:50 [inline]
 do_syscall_64+0x39/0xb0 arch/x86/entry/common.c:80
 entry_SYSCALL_64_after_hwframe+0x63/0xcd
RIP: 0033:0x7f2ec96df9d9
RSP: 002b:00007f2ec968b2f8 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
RAX: ffffffffffffffda RBX: 00007f2ec97697a0 RCX: 00007f2ec96df9d9
RDX: 0000000000000090 RSI: 0000000020000000 RDI: 0000000000000006
RBP: 00007f2ec97361d0 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 61635f65646f6e69
R13: 65646f7475616f6e R14: 7261637369646f6e R15: 00007f2ec97697a8
 </TASK>
INFO: task syz-executor945:12230 blocked for more than 144 seconds.
      Not tainted 6.3.0-syzkaller-13505-g17784de648be #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:syz-executor945 state:D stack:26544 pid:12230 ppid:5046   flags:0x00000004
Call Trace:
 <TASK>
 context_switch kernel/sched/core.c:5343 [inline]
 __schedule+0xc9a/0x5880 kernel/sched/core.c:6669
 schedule+0xde/0x1a0 kernel/sched/core.c:6745
 io_schedule+0xbe/0x130 kernel/sched/core.c:8979
 folio_wait_bit_common+0x394/0x9b0 mm/filemap.c:1301
 lock_page include/linux/pagemap.h:976 [inline]
 btrfs_page_mkwrite+0x77f/0x11a0 fs/btrfs/inode.c:8117
 do_page_mkwrite+0x1a1/0x690 mm/memory.c:2931
 wp_page_shared mm/memory.c:3280 [inline]
 do_wp_page+0x356/0x33c0 mm/memory.c:3362
 handle_pte_fault mm/memory.c:4964 [inline]
 __handle_mm_fault+0x1635/0x41c0 mm/memory.c:5089
 handle_mm_fault+0x2af/0x9f0 mm/memory.c:5243
 do_user_addr_fault+0x51a/0x1210 arch/x86/mm/fault.c:1440
 handle_page_fault arch/x86/mm/fault.c:1534 [inline]
 exc_page_fault+0x98/0x170 arch/x86/mm/fault.c:1590
 asm_exc_page_fault+0x26/0x30 arch/x86/include/asm/idtentry.h:570
RIP: 0010:rep_movs_alternative+0x33/0xb0 arch/x86/lib/copy_user_64.S:56
Code: 46 83 f9 08 73 21 85 c9 74 0f 8a 06 88 07 48 ff c7 48 ff c6 48 ff c9 75 f1 c3 66 66 2e 0f 1f 84 00 00 00 00 00 66 90 48 8b 06 <48> 89 07 48 83 c6 08 48 83 c7 08 83 e9 08 74 df 83 f9 08 73 e8 eb
RSP: 0018:ffffc9000ab87728 EFLAGS: 00050206
RAX: 0000000000000000 RBX: 0000000000000038 RCX: 0000000000000038
RDX: fffff52001570efb RSI: ffffc9000ab877a0 RDI: 0000000020000120
RBP: 0000000020000120 R08: 0000000000000000 R09: ffffc9000ab877d7
R10: fffff52001570efa R11: 0000000000094001 R12: ffffc9000ab877a0
R13: 0000000020000158 R14: 0000000000000000 R15: ffffc9000ab877a0
 copy_user_generic arch/x86/include/asm/uaccess_64.h:112 [inline]
 raw_copy_to_user arch/x86/include/asm/uaccess_64.h:133 [inline]
 _copy_to_user lib/usercopy.c:41 [inline]
 _copy_to_user+0xab/0xc0 lib/usercopy.c:34
 copy_to_user include/linux/uaccess.h:191 [inline]
 fiemap_fill_next_extent+0x217/0x370 fs/ioctl.c:144
 emit_fiemap_extent+0x18e/0x380 fs/btrfs/extent_io.c:2846
 fiemap_process_hole+0x516/0x610 fs/btrfs/extent_io.c:3104
 extent_fiemap+0x123b/0x1950 fs/btrfs/extent_io.c:3319
 btrfs_fiemap+0xe9/0x170 fs/btrfs/inode.c:7799
 ioctl_fiemap fs/ioctl.c:219 [inline]
 do_vfs_ioctl+0x466/0x1670 fs/ioctl.c:810
 __do_sys_ioctl fs/ioctl.c:868 [inline]
 __se_sys_ioctl fs/ioctl.c:856 [inline]
 __x64_sys_ioctl+0x10c/0x210 fs/ioctl.c:856
 do_syscall_x64 arch/x86/entry/common.c:50 [inline]
 do_syscall_64+0x39/0xb0 arch/x86/entry/common.c:80
 entry_SYSCALL_64_after_hwframe+0x63/0xcd
RIP: 0033:0x7f2ec96df9d9
RSP: 002b:00007f2ec226a2f8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
RAX: ffffffffffffffda RBX: 00007f2ec97697b0 RCX: 00007f2ec96df9d9
RDX: 0000000020000100 RSI: 00000000c020660b RDI: 0000000000000005
RBP: 00007f2ec97361d0 R08: 00007f2ec226a700 R09: 0000000000000000
R10: 00007f2ec226a700 R11: 0000000000000246 R12: 61635f65646f6e69
R13: 65646f7475616f6e R14: 7261637369646f6e R15: 00007f2ec97697b8
 </TASK>

Showing all locks held in the system:
1 lock held by rcu_tasks_kthre/13:
 #0: ffffffff8c798430 (rcu_tasks.tasks_gp_mutex){+.+.}-{3:3}, at: rcu_tasks_one_gp+0x31/0xd80 kernel/rcu/tasks.h:518
1 lock held by rcu_tasks_trace/14:
 #0: ffffffff8c798130 (rcu_tasks_trace.tasks_gp_mutex){+.+.}-{3:3}, at: rcu_tasks_one_gp+0x31/0xd80 kernel/rcu/tasks.h:518
1 lock held by khungtaskd/28:
 #0: ffffffff8c799040 (rcu_read_lock){....}-{1:2}, at: debug_show_all_locks+0x55/0x340 kernel/locking/lockdep.c:6545
3 locks held by kworker/u4:3/46:
 #0: ffff888141a5d138 ((wq_completion)writeback){+.+.}-{0:0}, at: arch_atomic64_set arch/x86/include/asm/atomic64_64.h:34 [inline]
 #0: ffff888141a5d138 ((wq_completion)writeback){+.+.}-{0:0}, at: arch_atomic_long_set include/linux/atomic/atomic-long.h:41 [inline]
 #0: ffff888141a5d138 ((wq_completion)writeback){+.+.}-{0:0}, at: atomic_long_set include/linux/atomic/atomic-instrumented.h:1324 [inline]
 #0: ffff888141a5d138 ((wq_completion)writeback){+.+.}-{0:0}, at: set_work_data kernel/workqueue.c:643 [inline]
 #0: ffff888141a5d138 ((wq_completion)writeback){+.+.}-{0:0}, at: set_work_pool_and_clear_pending kernel/workqueue.c:670 [inline]
 #0: ffff888141a5d138 ((wq_completion)writeback){+.+.}-{0:0}, at: process_one_work+0x883/0x15e0 kernel/workqueue.c:2376
 #1: ffffc90000b77db0 ((work_completion)(&(&wb->dwork)->work)){+.+.}-{0:0}, at: process_one_work+0x8b7/0x15e0 kernel/workqueue.c:2380
 #2: ffff8880279c80e0 (&type->s_umount_key#42){++++}-{3:3}, at: trylock_super+0x21/0x110 fs/super.c:414
2 locks held by getty/4756:
 #0: ffff888028aff098 (&tty->ldisc_sem){++++}-{0:0}, at: tty_ldisc_ref_wait+0x26/0x80 drivers/tty/tty_ldisc.c:243
 #1: ffffc900015a02f0 (&ldata->atomic_read_lock){+.+.}-{3:3}, at: n_tty_read+0xef4/0x13e0 drivers/tty/n_tty.c:2176
2 locks held by syz-executor945/12203:
 #0: ffff88802a0a1268 (&f->f_pos_lock){+.+.}-{3:3}, at: __fdget_pos+0xe7/0x100 fs/file.c:1047
 #1: ffff8880279c8460 (sb_writers#9){.+.+}-{0:0}, at: ksys_write+0x12b/0x250 fs/read_write.c:637
4 locks held by syz-executor945/12230:
 #0: ffff888077695058 (&sb->s_type->i_mutex_key#15){++++}-{3:3}, at: inode_lock_shared include/linux/fs.h:785 [inline]
 #0: ffff888077695058 (&sb->s_type->i_mutex_key#15){++++}-{3:3}, at: btrfs_inode_lock+0xd8/0xf0 fs/btrfs/inode.c:170
 #1: ffff888076635268 (&mm->mmap_lock){++++}-{3:3}, at: mmap_read_trylock include/linux/mmap_lock.h:161 [inline]
 #1: ffff888076635268 (&mm->mmap_lock){++++}-{3:3}, at: do_user_addr_fault+0x448/0x1210 arch/x86/mm/fault.c:1381
 #2: ffff8880279c8558 (sb_pagefaults){.+.+}-{0:0}, at: do_page_mkwrite+0x1a1/0x690 mm/memory.c:2931
 #3: ffff888077694ee0 (&ei->i_mmap_lock){++++}-{3:3}, at: btrfs_page_mkwrite+0x6eb/0x11a0 fs/btrfs/inode.c:8116
3 locks held by syz-executor945/15692:

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

NMI backtrace for cpu 0
CPU: 0 PID: 28 Comm: khungtaskd Not tainted 6.3.0-syzkaller-13505-g17784de648be #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 04/14/2023
Call Trace:
 <TASK>
 __dump_stack lib/dump_stack.c:88 [inline]
 dump_stack_lvl+0xd9/0x150 lib/dump_stack.c:106
 nmi_cpu_backtrace+0x29c/0x350 lib/nmi_backtrace.c:113
 nmi_trigger_cpumask_backtrace+0x2a4/0x300 lib/nmi_backtrace.c:62
 trigger_all_cpu_backtrace include/linux/nmi.h:148 [inline]
 check_hung_uninterruptible_tasks kernel/hung_task.c:222 [inline]
 watchdog+0xe16/0x1090 kernel/hung_task.c:379
 kthread+0x344/0x440 kernel/kthread.c:379
 ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:308
 </TASK>
Sending NMI from CPU 0 to CPUs 1:
NMI backtrace for cpu 1
CPU: 1 PID: 15689 Comm: syz-executor945 Not tainted 6.3.0-syzkaller-13505-g17784de648be #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 04/14/2023
RIP: 0010:native_apic_mem_write+0xc/0x10 arch/x86/include/asm/apic.h:108
Code: 31 d2 bf 30 08 00 00 e8 12 f6 0a 03 4c 89 e0 41 5c c3 66 2e 0f 1f 84 00 00 00 00 00 66 90 f3 0f 1e fa 89 ff 89 b7 00 c0 5f ff <c3> 0f 1f 00 f3 0f 1e fa 48 b8 00 00 00 00 00 fc ff df 53 89 fb 48
RSP: 0018:ffffc900001e0fd0 EFLAGS: 00000046
RAX: dffffc0000000000 RBX: ffffffff8c131e60 RCX: 1ffff11017325102
RDX: 1ffffffff18263cc RSI: 0000000000000000 RDI: 00000000000000b0
RBP: 0000000000000000 R08: 0000014dff6d7ab8 R09: ffffffff8e7a7017
R10: fffffbfff1cf4e02 R11: ffffc900001e0ff8 R12: 0000000000000000
R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
FS:  00007f2ec968b700(0000) GS:ffff8880b9900000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007f2ec226a000 CR3: 0000000022a51000 CR4: 0000000000350ee0
Call Trace:
 <IRQ>
 apic_eoi arch/x86/include/asm/apic.h:398 [inline]
 ack_APIC_irq arch/x86/include/asm/apic.h:444 [inline]
 __sysvec_apic_timer_interrupt+0x7d/0x430 arch/x86/kernel/apic/apic.c:1110
 sysvec_apic_timer_interrupt+0x92/0xc0 arch/x86/kernel/apic/apic.c:1106
 </IRQ>
 <TASK>
 asm_sysvec_apic_timer_interrupt+0x1a/0x20 arch/x86/include/asm/idtentry.h:645
RIP: 0010:__raw_spin_unlock_irq include/linux/spinlock_api_smp.h:160 [inline]
RIP: 0010:_raw_spin_unlock_irq+0x29/0x50 kernel/locking/spinlock.c:202
Code: 90 f3 0f 1e fa 55 48 8b 74 24 08 48 89 fd 48 83 c7 18 e8 ea 34 53 f7 48 89 ef e8 12 a3 53 f7 e8 2d 2f 78 f7 fb bf 01 00 00 00 <e8> 72 77 45 f7 65 8b 05 93 09 f1 75 85 c0 74 02 5d c3 e8 60 d7 ed
RSP: 0018:ffffc9000d08f8d0 EFLAGS: 00000206
RAX: 0000000000012c39 RBX: 0000000000000001 RCX: 1ffffffff22a5c16
RDX: 0000000000000000 RSI: 0000000000000002 RDI: 0000000000000001
RBP: ffff88806c751640 R08: 0000000000000001 R09: ffffffff91527d0f
R10: 0000000000000001 R11: 0000000000000000 R12: ffff88806c751638
R13: ffff88806c751638 R14: ffff88806c751640 R15: 000000000000000a
 spin_unlock_irq include/linux/spinlock.h:400 [inline]
 filemap_remove_folio+0x164/0x3f0 mm/filemap.c:258
 truncate_inode_folio+0x4c/0x70 mm/truncate.c:196
 shmem_undo_range+0x333/0x1130 mm/shmem.c:950
 shmem_truncate_range mm/shmem.c:1049 [inline]
 shmem_evict_inode+0x32f/0xb60 mm/shmem.c:1164
 evict+0x2ed/0x6b0 fs/inode.c:665
 iput_final fs/inode.c:1747 [inline]
 iput.part.0+0x50a/0x740 fs/inode.c:1773
 iput+0x5c/0x80 fs/inode.c:1763
 dentry_unlink_inode+0x2b1/0x460 fs/dcache.c:401
 __dentry_kill+0x3c0/0x640 fs/dcache.c:607
 dentry_kill fs/dcache.c:733 [inline]
 dput+0x865/0xe10 fs/dcache.c:913
 __fput+0x3cc/0xa90 fs/file_table.c:329
 task_work_run+0x16f/0x270 kernel/task_work.c:179
 resume_user_mode_work include/linux/resume_user_mode.h:49 [inline]
 exit_to_user_mode_loop kernel/entry/common.c:171 [inline]
 exit_to_user_mode_prepare+0x210/0x240 kernel/entry/common.c:204
 __syscall_exit_to_user_mode_work kernel/entry/common.c:286 [inline]
 syscall_exit_to_user_mode+0x1d/0x50 kernel/entry/common.c:297
 do_syscall_64+0x46/0xb0 arch/x86/entry/common.c:86
 entry_SYSCALL_64_after_hwframe+0x63/0xcd
RIP: 0033:0x7f2ec96df897
Code: 3c 1c 48 f7 d8 49 39 c4 72 b8 e8 b4 5d 02 00 85 c0 78 bd 48 83 c4 08 4c 89 e0 5b 41 5c c3 0f 1f 44 00 00 b8 10 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 c7 c1 b8 ff ff ff f7 d8 64 89 01 48
RSP: 002b:00007f2ec968b168 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
RAX: 0000000000000000 RBX: 0000000000000011 RCX: 00007f2ec96df897
RDX: 0000000000000000 RSI: 0000000000004c01 RDI: 0000000000000004
RBP: 0000000000000004 R08: 00007f2ec968b1c0 R09: 00000000000050e9
R10: 0000000000000000 R11: 0000000000000246 R12: 00007f2ec968b6b8
R13: 00007f2ec968b180 R14: 00007f2ec968b1c0 R15: 0000000000000000
 </TASK>

Crashes (5):
Time Kernel Commit Syzkaller Config Log Report Syz repro C repro VM info Assets (help?) Manager Title
2023/05/08 05:41 upstream 17784de648be 90c93c40 .config console log report syz C [mounted in repro] ci-upstream-kasan-gce-root INFO: task hung in extent_write_cache_pages
2023/01/15 23:18 upstream 7c6984405241 a63719e7 .config console log report syz C [disk image] [vmlinux] [kernel image] [mounted in repro] ci2-upstream-fs INFO: task hung in extent_write_cache_pages
2023/02/03 17:03 upstream 66a87fff1a87 1b2f701a .config console log report info ci-upstream-kasan-gce-root INFO: task hung in extent_write_cache_pages
2022/12/15 05:16 upstream e2ca6ba6ba01 b18f0a64 .config console log report info [disk image] [vmlinux] [kernel image] ci2-upstream-fs INFO: task hung in extent_write_cache_pages
2023/01/29 19:01 linux-next e2f86c02fdc9 9dfcf09c .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-linux-next-kasan-gce-root INFO: task hung in extent_write_cache_pages
* Struck through repros no longer work on HEAD.