syzbot


INFO: task hung in gfs2_log_flush

Status: upstream: reported on 2022/12/25 14:49
Subsystems: gfs2
[Documentation on labels]
Reported-by: syzbot+e586a445dabf92619c6b@syzkaller.appspotmail.com
First crash: 675d, last: 675d

Sample crash report:
audit: type=1804 audit(1671979736.701:397): pid=27511 uid=0 auid=4294967295 ses=4294967295 subj==unconfined op=invalid_pcr cause=open_writers comm="syz-executor.0" name="/root/syzkaller-testdir3564173170/syzkaller.HoGew1/183/file0/bus" dev="loop0" ino=43 res=1
INFO: task kworker/u4:6:9400 blocked for more than 140 seconds.
      Not tainted 4.19.211-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kworker/u4:6    D25024  9400      2 0x80000000
Workqueue: writeback wb_workfn (flush-7:4)
Call Trace:
 context_switch kernel/sched/core.c:2828 [inline]
 __schedule+0x887/0x2040 kernel/sched/core.c:3517
 schedule+0x8d/0x1b0 kernel/sched/core.c:3561
 __rwsem_down_write_failed_common kernel/locking/rwsem-xadd.c:589 [inline]
 rwsem_down_write_failed+0x3aa/0x760 kernel/locking/rwsem-xadd.c:618
 call_rwsem_down_write_failed+0x13/0x20 arch/x86/lib/rwsem.S:117
 __down_write arch/x86/include/asm/rwsem.h:142 [inline]
 down_write+0x4f/0x90 kernel/locking/rwsem.c:72
 gfs2_log_flush+0xd5/0x1ef0 fs/gfs2/log.c:793
 gfs2_write_inode+0x3f2/0x550 fs/gfs2/super.c:760
 write_inode fs/fs-writeback.c:1244 [inline]
 __writeback_single_inode+0x733/0x11d0 fs/fs-writeback.c:1442
 writeback_sb_inodes+0x537/0xef0 fs/fs-writeback.c:1647
 __writeback_inodes_wb+0xc6/0x280 fs/fs-writeback.c:1716
 wb_writeback+0x841/0xcc0 fs/fs-writeback.c:1822
 wb_check_background_flush fs/fs-writeback.c:1890 [inline]
 wb_do_writeback fs/fs-writeback.c:1978 [inline]
 wb_workfn+0xacd/0x1250 fs/fs-writeback.c:2006
gfs2: fsid=loop1: Trying to join cluster "lock_nolock", "loop1"
 process_one_work+0x864/0x1570 kernel/workqueue.c:2153
gfs2: fsid=loop1: Now mounting FS...
gfs2: fsid=loop1.0: journal 0 mapped with 3 extents
 worker_thread+0x64c/0x1130 kernel/workqueue.c:2296
gfs2: fsid=loop1.0: jid=0, already locked for use
gfs2: fsid=loop1.0: jid=0: Looking at journal...
 kthread+0x33f/0x460 kernel/kthread.c:259
 ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:415
gfs2: fsid=loop1.0: jid=0: Done
INFO: task syz-executor.4:20769 blocked for more than 140 seconds.
gfs2: fsid=loop1.0: first mount done, others may mount
      Not tainted 4.19.211-syzkaller #0
XFS (loop0): Unmounting Filesystem
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor.4  D28648 20769   8155 0x00000004
Call Trace:
 context_switch kernel/sched/core.c:2828 [inline]
 __schedule+0x887/0x2040 kernel/sched/core.c:3517
 schedule+0x8d/0x1b0 kernel/sched/core.c:3561
 __rwsem_down_read_failed_common kernel/locking/rwsem-xadd.c:292 [inline]
 rwsem_down_read_failed+0x20a/0x390 kernel/locking/rwsem-xadd.c:309
 call_rwsem_down_read_failed+0x14/0x30 arch/x86/lib/rwsem.S:94
 __down_read arch/x86/include/asm/rwsem.h:83 [inline]
 down_read+0x44/0x80 kernel/locking/rwsem.c:26
 __do_page_fault+0x97f/0xd60 arch/x86/mm/fault.c:1348
 page_fault+0x1e/0x30 arch/x86/entry/entry_64.S:1205
RIP: 0033:0x7f1bd2b36d49
Code: Bad RIP value.
RSP: 002b:00007fff3ed6f670 EFLAGS: 00010246
RAX: 00000000200015c0 RBX: 0000000000000000 RCX: 0000000000000000
RDX: 0000000020000080 RSI: 0000000000000000 RDI: 0000555556ef42e8
RBP: 00007fff3ed6f768 R08: 0000000000000000 R09: 0000000000000000
R10: 00007f1bd271da08 R11: 0000000000000001 R12: 0000000000073621
R13: 00007fff3ed6f790 R14: 00007fff3ed6f7b0 R15: 0000000000000032
INFO: task syz-executor.4:20771 blocked for more than 140 seconds.
      Not tainted 4.19.211-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor.4  D25536 20771   8155 0x00000004
Call Trace:
 context_switch kernel/sched/core.c:2828 [inline]
 __schedule+0x887/0x2040 kernel/sched/core.c:3517
 schedule+0x8d/0x1b0 kernel/sched/core.c:3561
 __rwsem_down_read_failed_common kernel/locking/rwsem-xadd.c:292 [inline]
 rwsem_down_read_failed+0x20a/0x390 kernel/locking/rwsem-xadd.c:309
 call_rwsem_down_read_failed+0x14/0x30 arch/x86/lib/rwsem.S:94
 __down_read arch/x86/include/asm/rwsem.h:83 [inline]
 down_read+0x44/0x80 kernel/locking/rwsem.c:26
 __do_page_fault+0x97f/0xd60 arch/x86/mm/fault.c:1348
 page_fault+0x1e/0x30 arch/x86/entry/entry_64.S:1205
RIP: 0010:fault_in_pages_readable include/linux/pagemap.h:602 [inline]
RIP: 0010:iov_iter_fault_in_readable+0x18b/0x3f0 lib/iov_iter.c:421
XFS (loop0): DAX enabled. Warning: EXPERIMENTAL, use at your own risk
Code: 39 f3 76 18 eb 3c e8 a4 88 ee fd 48 81 c3 00 10 00 00 48 39 1c 24 0f 82 94 01 00 00 e8 8e 88 ee fd 0f 01 cb 0f ae e8 45 31 f6 <8a> 13 0f 01 ca 31 ff 44 89 f6 88 54 24 38 e8 e2 89 ee fd 45 85 f6
XFS (loop0): DAX unsupported by block device. Turning off DAX.
RSP: 0018:ffff888037e278e8 EFLAGS: 00050246
XFS (loop0): Mounting V4 Filesystem
RAX: 0000000000040000 RBX: 000000002021c000 RCX: ffffc90008327000
RDX: 0000000000040000 RSI: ffffffff8373fce2 RDI: 0000000000000005
XFS (loop0): Ending clean mount
RBP: 1ffff11006fc4f1e R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000005 R11: 0000000000000000 R12: 0000000000001000
XFS (loop0): Quotacheck needed: Please wait.
R13: 0000000000001000 R14: 0000000000000000 R15: ffff888037e27d20
XFS (loop0): Quotacheck: Done.
 iomap_write_actor+0xff/0x380 fs/iomap.c:837
 iomap_apply+0x18b/0x290 fs/iomap.c:87
audit: type=1804 audit(1671979738.591:398): pid=27586 uid=0 auid=4294967295 ses=4294967295 subj==unconfined op=invalid_pcr cause=open_writers comm="syz-executor.0" name="/root/syzkaller-testdir3564173170/syzkaller.HoGew1/184/file0/bus" dev="loop0" ino=43 res=1
gfs2: fsid=loop1: Trying to join cluster "lock_nolock", "loop1"
audit: type=1804 audit(1671979738.741:399): pid=27617 uid=0 auid=4294967295 ses=4294967295 subj==unconfined op=invalid_pcr cause=open_writers comm="syz-executor.0" name="/root/syzkaller-testdir3564173170/syzkaller.HoGew1/184/file0/bus" dev="loop0" ino=43 res=1
 iomap_file_buffered_write+0x14e/0x1e0 fs/iomap.c:894
gfs2: fsid=loop1: Now mounting FS...
 gfs2_file_write_iter+0x3cb/0xb30 fs/gfs2/file.c:847
 call_write_iter include/linux/fs.h:1821 [inline]
 new_sync_write fs/read_write.c:474 [inline]
 __vfs_write+0x51b/0x770 fs/read_write.c:487
 vfs_write+0x1f3/0x540 fs/read_write.c:549
 ksys_write+0x12b/0x2a0 fs/read_write.c:599
gfs2: fsid=loop1.0: journal 0 mapped with 3 extents
gfs2: fsid=loop1.0: jid=0, already locked for use
gfs2: fsid=loop1.0: jid=0: Looking at journal...
 do_syscall_64+0xf9/0x620 arch/x86/entry/common.c:293
gfs2: fsid=loop1.0: jid=0: Done
 entry_SYSCALL_64_after_hwframe+0x49/0xbe
gfs2: fsid=loop1.0: first mount done, others may mount
RIP: 0033:0x7f1bd2b970a9
Code: Bad RIP value.
RSP: 002b:00007f1bd1109168 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
RAX: ffffffffffffffda RBX: 00007f1bd2cb6f80 RCX: 00007f1bd2b970a9
RDX: 000000000208e24b RSI: 0000000020000000 RDI: 0000000000000004
RBP: 00007f1bd2bf2ae9 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000
R13: 00007fff3ed6f62f R14: 00007f1bd1109300 R15: 0000000000022000
XFS (loop0): Unmounting Filesystem
INFO: task syz-executor.4:20854 blocked for more than 140 seconds.
      Not tainted 4.19.211-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor.4  D29168 20854   8155 0x00000004
Call Trace:
 context_switch kernel/sched/core.c:2828 [inline]
 __schedule+0x887/0x2040 kernel/sched/core.c:3517
 schedule+0x8d/0x1b0 kernel/sched/core.c:3561
 bit_wait+0x12/0x90 kernel/sched/wait_bit.c:197
 __wait_on_bit+0x7e/0x150 kernel/sched/wait_bit.c:48
 out_of_line_wait_on_bit+0xd2/0x100 kernel/sched/wait_bit.c:63
 wait_on_bit include/linux/wait_bit.h:76 [inline]
 gfs2_glock_wait+0xb7/0x1d0 fs/gfs2/glock.c:949
 gfs2_glock_nq+0xae2/0x1360 fs/gfs2/glock.c:1118
 gfs2_glock_nq_init fs/gfs2/glock.h:228 [inline]
 gfs2_mmap+0x235/0x320 fs/gfs2/file.c:528
 call_mmap include/linux/fs.h:1826 [inline]
 mmap_region+0xc94/0x16b0 mm/mmap.c:1757
 do_mmap+0x8e8/0x1080 mm/mmap.c:1530
 do_mmap_pgoff include/linux/mm.h:2329 [inline]
 vm_mmap_pgoff+0x197/0x200 mm/util.c:357
 ksys_mmap_pgoff+0x298/0x5a0 mm/mmap.c:1580
 do_syscall_64+0xf9/0x620 arch/x86/entry/common.c:293
 entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x7f1bd2b970a9
Code: Bad RIP value.
RSP: 002b:00007f1bc9ce8168 EFLAGS: 00000246 ORIG_RAX: 0000000000000009
RAX: ffffffffffffffda RBX: 00007f1bd2cb7050 RCX: 00007f1bd2b970a9
RDX: 0000000000000002 RSI: 0000000000b36000 RDI: 0000000020000000
RBP: 00007f1bd2bf2ae9 R08: 0000000000000004 R09: 0000000000000000
gfs2: fsid=loop1: Trying to join cluster "lock_nolock", "loop1"
R10: 0000000000028011 R11: 0000000000000246 R12: 0000000000000000
gfs2: fsid=loop1: Now mounting FS...
R13: 00007fff3ed6f62f R14: 00007f1bc9ce8300 R15: 0000000000022000
gfs2: fsid=loop1.0: journal 0 mapped with 3 extents

Showing all locks held in the system:
2 locks held by ksoftirqd/1/18:
1 lock held by khungtaskd/1571:
 #0: 00000000f21657da (rcu_read_lock){....}, at: debug_show_all_locks+0x53/0x265 kernel/locking/lockdep.c:4441
gfs2: fsid=loop1.0: jid=0, already locked for use
1 lock held by in:imklog/7799:
 #0: 0000000017d94c34 (&f->f_pos_lock){+.+.}, at: __fdget_pos+0x26f/0x310 fs/file.c:767
gfs2: fsid=loop1.0: jid=0: Looking at journal...
2 locks held by kworker/u4:5/8853:
2 locks held by kworker/1:3/8994:
4 locks held by kworker/u4:6/9400:
gfs2: fsid=loop1.0: jid=0: Done
 #0: 000000003e287f8c ((wq_completion)"writeback"){+.+.}, at: process_one_work+0x767/0x1570 kernel/workqueue.c:2124
gfs2: fsid=loop1.0: first mount done, others may mount
 #1: 000000005e4183bb ((work_completion)(&(&wb->dwork)->work)){+.+.}, at: process_one_work+0x79c/0x1570 kernel/workqueue.c:2128
 #2: 00000000a0723536 (&type->s_umount_key#71){++++}, at: trylock_super+0x1d/0x100 fs/super.c:412
 #3: 00000000503411e1 (&sdp->sd_log_flush_lock){++++}, at: gfs2_log_flush+0xd5/0x1ef0 fs/gfs2/log.c:793
1 lock held by syz-executor.4/20769:
 #0: 000000006d9e917e (&mm->mmap_sem){++++}, at: __do_page_fault+0x97f/0xd60 arch/x86/mm/fault.c:1348
6 locks held by syz-executor.4/20771:
 #0: 00000000a5ba32b5 (&f->f_pos_lock){+.+.}, at: __fdget_pos+0x26f/0x310 fs/file.c:767
 #1: 000000005888db87 (sb_writers#24){.+.+}, at: file_start_write include/linux/fs.h:2779 [inline]
 #1: 000000005888db87 (sb_writers#24){.+.+}, at: vfs_write+0x463/0x540 fs/read_write.c:548
 #2: 00000000bc601fea (&sb->s_type->i_mutex_key#31){+.+.}, at: inode_lock include/linux/fs.h:748 [inline]
 #2: 00000000bc601fea (&sb->s_type->i_mutex_key#31){+.+.}, at: gfs2_file_write_iter+0x239/0xb30 fs/gfs2/file.c:800
 #3: 00000000274eef0e (sb_internal#4){.+.+}, at: sb_start_intwrite include/linux/fs.h:1626 [inline]
 #3: 00000000274eef0e (sb_internal#4){.+.+}, at: gfs2_trans_begin+0x32b/0x590 fs/gfs2/trans.c:62
 #4: 00000000503411e1 (&sdp->sd_log_flush_lock){++++}, at: gfs2_log_reserve+0x35f/0x8b0 fs/gfs2/log.c:400
 #5: 000000006d9e917e (&mm->mmap_sem){++++}, at: __do_page_fault+0x97f/0xd60 arch/x86/mm/fault.c:1348
XFS (loop0): DAX enabled. Warning: EXPERIMENTAL, use at your own risk
XFS (loop0): DAX unsupported by block device. Turning off DAX.
1 lock held by syz-executor.4/20854:
 #0: 000000006d9e917e (&mm->mmap_sem){++++}, at: vm_mmap_pgoff+0x152/0x200 mm/util.c:355
XFS (loop0): Mounting V4 Filesystem
1 lock held by gfs2_logd/20848:
 #0: 00000000503411e1 (&sdp->sd_log_flush_lock){++++}, at: gfs2_log_flush+0xd5/0x1ef0 fs/gfs2/log.c:793
XFS (loop0): Ending clean mount
3 locks held by gfs2_quotad/20849:
XFS (loop0): Quotacheck needed: Please wait.
 #0: 000000005888db87 (sb_writers#24){.+.+}, at: sb_start_write include/linux/fs.h:1579 [inline]
 #0: 000000005888db87 (sb_writers#24){.+.+}, at: gfs2_statfs_sync+0x107/0x670 fs/gfs2/super.c:593
XFS (loop0): Quotacheck: Done.
 #1: 00000000274eef0e (sb_internal#4){.+.+}, at: sb_start_intwrite include/linux/fs.h:1626 [inline]
 #1: 00000000274eef0e (sb_internal#4){.+.+}, at: gfs2_trans_begin+0x32b/0x590 fs/gfs2/trans.c:62
audit: type=1804 audit(1671979740.871:400): pid=27677 uid=0 auid=4294967295 ses=4294967295 subj==unconfined op=invalid_pcr cause=open_writers comm="syz-executor.0" name="/root/syzkaller-testdir3564173170/syzkaller.HoGew1/185/file0/bus" dev="loop0" ino=43 res=1
 #2: 00000000503411e1 (&sdp->sd_log_flush_lock){++++}, at: gfs2_log_reserve+0x35f/0x8b0 fs/gfs2/log.c:400
2 locks held by systemd-udevd/27740:
 #0: 00000000b7a1f438 (&rq->lock){-.-.}, at: idle_balance kernel/sched/fair.c:9702 [inline]
 #0: 00000000b7a1f438 (&rq->lock){-.-.}, at: pick_next_task_fair+0x556/0x1570 kernel/sched/fair.c:6841
 #1: 00000000b7a1f438 (&rq->lock){-.-.}, at: rq_lock kernel/sched/sched.h:1826 [inline]
 #1: 00000000b7a1f438 (&rq->lock){-.-.}, at: attach_tasks kernel/sched/fair.c:7432 [inline]
 #1: 00000000b7a1f438 (&rq->lock){-.-.}, at: load_balance+0xa88/0x2080 kernel/sched/fair.c:8749

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

NMI backtrace for cpu 1
CPU: 1 PID: 1571 Comm: khungtaskd Not tainted 4.19.211-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 10/26/2022
Call Trace:
 __dump_stack lib/dump_stack.c:77 [inline]
 dump_stack+0x1fc/0x2ef lib/dump_stack.c:118
 nmi_cpu_backtrace.cold+0x63/0xa2 lib/nmi_backtrace.c:101
 nmi_trigger_cpumask_backtrace+0x1a6/0x1f0 lib/nmi_backtrace.c:62
 trigger_all_cpu_backtrace include/linux/nmi.h:146 [inline]
 check_hung_uninterruptible_tasks kernel/hung_task.c:203 [inline]
 watchdog+0x991/0xe60 kernel/hung_task.c:287
 kthread+0x33f/0x460 kernel/kthread.c:259
 ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:415
Sending NMI from CPU 1 to CPUs 0:
NMI backtrace for cpu 0
CPU: 0 PID: 4694 Comm: systemd-journal Not tainted 4.19.211-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 10/26/2022
RIP: 0010:__read_once_size include/linux/compiler.h:263 [inline]
RIP: 0010:check_kcov_mode kernel/kcov.c:69 [inline]
RIP: 0010:write_comp_data+0x1d/0x70 kernel/kcov.c:122
Code: d1 48 89 11 c3 0f 1f 84 00 00 00 00 00 49 89 f1 49 89 fa 65 48 8b 34 25 c0 df 01 00 65 8b 05 7a 59 9f 7e a9 00 01 1f 00 75 4f <8b> 86 60 13 00 00 83 f8 03 75 44 48 8b 86 68 13 00 00 8b b6 64 13
RSP: 0018:ffff8880a0f7f970 EFLAGS: 00000046
RAX: 0000000080000000 RBX: 0000000000000001 RCX: ffffffff8167ad7d
RDX: 0000000000000001 RSI: ffff8880a0f72600 RDI: 0000000000000005
RBP: ffffffff8d405a08 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000005 R11: 0000000000000009 R12: 0000000000000086
R13: ffff88809f2c6000 R14: ffffea00027cb180 R15: dffffc0000000000
FS:  00007fec56ad48c0(0000) GS:ffff8880ba000000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007fec5413a000 CR3: 00000000a0d81000 CR4: 00000000003406f0
DR0: 0000000000000008 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
 trace_hardirqs_off+0x1d/0x200 kernel/trace/trace_preemptirq.c:36
 __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:108 [inline]
 _raw_spin_lock_irqsave+0x66/0xc0 kernel/locking/spinlock.c:152
 __debug_check_no_obj_freed lib/debugobjects.c:776 [inline]
 debug_check_no_obj_freed+0xb5/0x490 lib/debugobjects.c:817
 free_pages_prepare mm/page_alloc.c:1056 [inline]
 __free_pages_ok+0x22d/0xd30 mm/page_alloc.c:1279
 slab_destroy mm/slab.c:1713 [inline]
 slabs_destroy+0x90/0xd0 mm/slab.c:1729
 cache_flusharray mm/slab.c:3490 [inline]
 ___cache_free+0x295/0x3a0 mm/slab.c:3532
 qlink_free mm/kasan/quarantine.c:147 [inline]
 qlist_free_all+0x79/0x140 mm/kasan/quarantine.c:166
 quarantine_reduce+0x1a9/0x230 mm/kasan/quarantine.c:259
 kasan_kmalloc+0xa2/0x160 mm/kasan/kasan.c:538
 slab_post_alloc_hook mm/slab.h:445 [inline]
 slab_alloc mm/slab.c:3397 [inline]
 kmem_cache_alloc+0x110/0x370 mm/slab.c:3557
 prepare_creds+0x39/0x510 kernel/cred.c:255
 do_faccessat+0x94/0x7a0 fs/open.c:359
 do_syscall_64+0xf9/0x620 arch/x86/entry/common.c:293
 entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x7fec55d8f9c7
Code: 83 c4 08 48 3d 01 f0 ff ff 73 01 c3 48 8b 0d c8 d4 2b 00 f7 d8 64 89 01 48 83 c8 ff c3 66 0f 1f 44 00 00 b8 15 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d a1 d4 2b 00 f7 d8 64 89 01 48
RSP: 002b:00007ffeb6d7b668 EFLAGS: 00000246 ORIG_RAX: 0000000000000015
RAX: ffffffffffffffda RBX: 00007ffeb6d7e690 RCX: 00007fec55d8f9c7
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 000055df2f1ab9a3
RBP: 00007ffeb6d7b7b0 R08: 000055df2f1a13e5 R09: 0000000000000018
R10: 0000000000000069 R11: 0000000000000246 R12: 0000000000000000
R13: 0000000000000000 R14: 000055df306618a0 R15: 00007ffeb6d7bca0

Crashes (1):
Time Kernel Commit Syzkaller Config Log Report Syz repro C repro VM info Assets (help?) Manager Title
2022/12/25 14:49 linux-4.19.y 3f8a27f9e27b 9da18ae8 .config console log report info [disk image] [vmlinux] ci2-linux-4-19 INFO: task hung in gfs2_log_flush
* Struck through repros no longer work on HEAD.