Re: WARNING: ODEBUG bug in f2fs_fill_super

From: Dmitry Vyukov
Date: Thu Feb 21 2019 - 04:27:43 EST

Next message: Peter Chen: "RE: [PATCH v3] usb: chipidea: Grab the (legacy) USB PHY by phandle first"
Previous message: Peter Chen: "Re: [PATCH v4 5/6] usb:cdns3 Add Cadence USB3 DRD Driver"
In reply to: Sheng Yong: "Re: WARNING: ODEBUG bug in f2fs_fill_super"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

On Thu, Feb 21, 2019 at 3:46 AM Sheng Yong <shengyong1@xxxxxxxxxx> wrote:
>
> Hi, Dmitry,
>
> On 2019/2/20 23:12, Dmitry Vyukov wrote:
> > On Mon, Aug 27, 2018 at 11:04 PM syzbot
> > <syzbot+77ea19d309d4cdc55cc1@xxxxxxxxxxxxxxxxxxxxxxxxx> wrote:
> >>
> >> Hello,
> >>
> >> syzbot found the following crash on:
> >>
> >> HEAD commit: e27bc174c9c6 Add linux-next specific files for 20180824
> >> git tree: linux-next
> >> console output: https://syzkaller.appspot.com/x/log.txt?x=11c0034a400000
> >> kernel config: https://syzkaller.appspot.com/x/.config?x=28446088176757ea
> >> dashboard link: https://syzkaller.appspot.com/bug?extid=77ea19d309d4cdc55cc1
> >> compiler: gcc (GCC) 8.0.1 20180413 (experimental)
> >>
> >> Unfortunately, I don't have any reproducer for this crash yet.
> >>
> >> IMPORTANT: if you fix the bug, please add the following tag to the commit:
> >> Reported-by: syzbot+77ea19d309d4cdc55cc1@xxxxxxxxxxxxxxxxxxxxxxxxx
> >>
> >> ------------[ cut here ]------------
> >> ODEBUG: free active (active state 0) object type: percpu_counter
> >> hint: (null)
> >> WARNING: CPU: 1 PID: 18832 at lib/debugobjects.c:329
> >> debug_print_object+0x16a/0x210 lib/debugobjects.c:326
> >> Kernel panic - not syncing: panic_on_warn set ...
> >
> >
> > Was this fixed by something?
> > It happened a number of times, but then stopped after Oct 23 2018. Was it:
> >
> > commit 26b5a079197c8cb6725565968b7fd3299bd1877b
> > Author: Sheng Yong <shengyong1@xxxxxxxxxx>
> > Date: Fri Oct 12 18:49:26 2018 +0800
> > f2fs: cleanup dirty pages if recover failed
> >
> > which fixed some bugs in f2fs_fill_super?
> >
> During mount, f2fs tries to recover fsync-ed data of last unclean umount.
> But if recover fails, f2fs_fill_super did not cleanup dirty pages which
> have already recovered. This will trigger f2fs_bug_on later.
>
> This patch fixes this by cleaning up these dirty pages and avoiding to
> writing back these pages. After that, f2fs will retry mount without
> recover.
>
> But I don't see the reason of the debugobject warning, and not sure if the
> patch fixed the warning :(

Thanks for the info.
So maybe it's still fixed by something (though, after briefly skimming
thorough the log, I don't see any other commits that could do it), or
maybe syzkaller unlearned how to trigger it, or maybe this bug is now
always preceded by some other bug so it's not possible to trigger it,
but it's still there.

Anyway, this bug report is a candidate for closure as obsoleted.

> >> CPU: 1 PID: 18832 Comm: syz-executor4 Not tainted 4.18.0-next-20180824+ #47
> >> Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS
> >> Google 01/01/2011
> >> Call Trace:
> >> __dump_stack lib/dump_stack.c:77 [inline]
> >> dump_stack+0x1c9/0x2b4 lib/dump_stack.c:113
> >> panic+0x238/0x4e7 kernel/panic.c:184
> >> __warn.cold.8+0x163/0x1ba kernel/panic.c:536
> >> report_bug+0x252/0x2d0 lib/bug.c:186
> >> fixup_bug arch/x86/kernel/traps.c:178 [inline]
> >> do_error_trap+0x1fc/0x4d0 arch/x86/kernel/traps.c:296
> >> do_invalid_op+0x1b/0x20 arch/x86/kernel/traps.c:316
> >> invalid_op+0x14/0x20 arch/x86/entry/entry_64.S:996
> >> RIP: 0010:debug_print_object+0x16a/0x210 lib/debugobjects.c:326
> >> Code: 3a 87 48 89 fa 48 c1 ea 03 80 3c 02 00 0f 85 92 00 00 00 48 8b 14 dd
> >> 20 e5 3a 87 4c 89 f6 48 c7 c7 c0 da 3a 87 e8 26 ec e3 fd <0f> 0b 83 05 a9
> >> 49 28 05 01 48 83 c4 18 5b 41 5c 41 5d 41 5e 41 5f
> >> RSP: 0018:ffff8801a9a97360 EFLAGS: 00010082
> >> RAX: 0000000000000000 RBX: 0000000000000003 RCX: ffffc90012037000
> >> RDX: 000000000002cd2b RSI: ffffffff8163b051 RDI: 0000000000000001
> >> RBP: ffff8801a9a973a0 R08: ffff8801c1f76100 R09: ffffed003b623eca
> >> R10: ffffed003b623eca R11: ffff8801db11f657 R12: 0000000000000001
> >> R13: ffffffff882b7ae0 R14: ffffffff873adf60 R15: 0000000000000000
> >> __debug_check_no_obj_freed lib/debugobjects.c:786 [inline]
> >> debug_check_no_obj_freed+0x3b2/0x595 lib/debugobjects.c:818
> >> kfree+0xc7/0x210 mm/slab.c:3812
> >> f2fs_fill_super+0xe1a/0x8150 fs/f2fs/super.c:3147
> >> mount_bdev+0x314/0x3e0 fs/super.c:1347
> >> f2fs_mount+0x3c/0x50 fs/f2fs/super.c:3161
> >> legacy_get_tree+0x131/0x460 fs/fs_context.c:732
> >> vfs_get_tree+0x1cb/0x5c0 fs/super.c:1746
> >> do_new_mount fs/namespace.c:2627 [inline]
> >> do_mount+0x6f9/0x1e30 fs/namespace.c:2951
> >> ksys_mount+0x12d/0x140 fs/namespace.c:3167
> >> __do_sys_mount fs/namespace.c:3181 [inline]
> >> __se_sys_mount fs/namespace.c:3178 [inline]
> >> __x64_sys_mount+0xbe/0x150 fs/namespace.c:3178
> >> do_syscall_64+0x1b9/0x820 arch/x86/entry/common.c:290
> >> entry_SYSCALL_64_after_hwframe+0x49/0xbe
> >> RIP: 0033:0x459aba
> >> Code: b8 a6 00 00 00 0f 05 48 3d 01 f0 ff ff 0f 83 bd 8a fb ff c3 66 2e 0f
> >> 1f 84 00 00 00 00 00 66 90 49 89 ca b8 a5 00 00 00 0f 05 <48> 3d 01 f0 ff
> >> ff 0f 83 9a 8a fb ff c3 66 0f 1f 84 00 00 00 00 00
> >> RSP: 002b:00007f16f9937a88 EFLAGS: 00000206 ORIG_RAX: 00000000000000a5
> >> RAX: ffffffffffffffda RBX: 00007f16f9937b30 RCX: 0000000000459aba
> >> RDX: 00007f16f9937ad0 RSI: 0000000020000100 RDI: 00007f16f9937af0
> >> RBP: 0000000020000100 R08: 00007f16f9937b30 R09: 00007f16f9937ad0
> >> R10: 0000000000000000 R11: 0000000000000206 R12: 0000000000000003
> >> R13: 0000000000000000 R14: 00000000004c9c12 R15: 0000000000000000
> >>
> >> ======================================================
> >> WARNING: possible circular locking dependency detected
> >> 4.18.0-next-20180824+ #47 Not tainted
> >> ------------------------------------------------------
> >> syz-executor4/18832 is trying to acquire lock:
> >> 00000000cd8e7eb7 ((console_sem).lock){-.-.}, at: down_trylock+0x13/0x70
> >> kernel/locking/semaphore.c:136
> >>
> >> but task is already holding lock:
> >> 0000000046ad1dd4 (&obj_hash[i].lock){-.-.}, at: __debug_check_no_obj_freed
> >> lib/debugobjects.c:777 [inline]
> >> 0000000046ad1dd4 (&obj_hash[i].lock){-.-.}, at:
> >> debug_check_no_obj_freed+0x16c/0x595 lib/debugobjects.c:818
> >>
> >> which lock already depends on the new lock.
> >>
> >>
> >> the existing dependency chain (in reverse order) is:
> >>
> >> -> #3 (&obj_hash[i].lock){-.-.}:
> >> __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
> >> _raw_spin_lock_irqsave+0x96/0xc0 kernel/locking/spinlock.c:152
> >> __debug_object_init+0x127/0x12e0 lib/debugobjects.c:384
> >> debug_object_init+0x16/0x20 lib/debugobjects.c:432
> >> debug_hrtimer_init kernel/time/hrtimer.c:410 [inline]
> >> debug_init kernel/time/hrtimer.c:458 [inline]
> >> hrtimer_init+0x97/0x410 kernel/time/hrtimer.c:1308
> >> init_dl_task_timer+0x1b/0x50 kernel/sched/deadline.c:1057
> >> __sched_fork+0x2ae/0x590 kernel/sched/core.c:2160
> >> init_idle+0x75/0x740 kernel/sched/core.c:5377
> >> sched_init+0xbee/0xcbd kernel/sched/core.c:6060
> >> start_kernel+0x47d/0x94e init/main.c:602
> >> x86_64_start_reservations+0x29/0x2b arch/x86/kernel/head64.c:452
> >> x86_64_start_kernel+0x76/0x79 arch/x86/kernel/head64.c:433
> >> secondary_startup_64+0xa4/0xb0 arch/x86/kernel/head_64.S:242
> >>
> >> -> #2 (&rq->lock){-.-.}:
> >> __raw_spin_lock include/linux/spinlock_api_smp.h:142 [inline]
> >> _raw_spin_lock+0x2a/0x40 kernel/locking/spinlock.c:144
> >> rq_lock kernel/sched/sched.h:1821 [inline]
> >> task_fork_fair+0x93/0x680 kernel/sched/fair.c:9574
> >> sched_fork+0x44b/0xbd0 kernel/sched/core.c:2353
> >> copy_process+0x235e/0x7af0 kernel/fork.c:1840
> >> _do_fork+0x1ca/0x1170 kernel/fork.c:2169
> >> kernel_thread+0x34/0x40 kernel/fork.c:2228
> >> rest_init+0x22/0xe4 init/main.c:408
> >> start_kernel+0x913/0x94e init/main.c:739
> >> x86_64_start_reservations+0x29/0x2b arch/x86/kernel/head64.c:452
> >> x86_64_start_kernel+0x76/0x79 arch/x86/kernel/head64.c:433
> >> secondary_startup_64+0xa4/0xb0 arch/x86/kernel/head_64.S:242
> >>
> >> -> #1 (&p->pi_lock){-.-.}:
> >> __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
> >> _raw_spin_lock_irqsave+0x96/0xc0 kernel/locking/spinlock.c:152
> >> try_to_wake_up+0xd2/0x1250 kernel/sched/core.c:1960
> >> wake_up_process+0x10/0x20 kernel/sched/core.c:2123
> >> __up.isra.1+0x1c0/0x2a0 kernel/locking/semaphore.c:262
> >> up+0x13c/0x1c0 kernel/locking/semaphore.c:187
> >> __up_console_sem+0xbe/0x1b0 kernel/printk/printk.c:245
> >> console_unlock+0x506/0x10d0 kernel/printk/printk.c:2430
> >> con_install+0x34e/0x420 drivers/tty/vt/vt.c:3241
> >> tty_driver_install_tty drivers/tty/tty_io.c:1224 [inline]
> >> tty_init_dev+0xfd/0x460 drivers/tty/tty_io.c:1324
> >> tty_open_by_driver drivers/tty/tty_io.c:1959 [inline]
> >> tty_open+0x692/0xb30 drivers/tty/tty_io.c:2007
> >> chrdev_open+0x25a/0x770 fs/char_dev.c:417
> >> do_dentry_open+0x49c/0x1140 fs/open.c:771
> >> vfs_open+0xa0/0xd0 fs/open.c:880
> >> do_last fs/namei.c:3418 [inline]
> >> path_openat+0x12fb/0x5300 fs/namei.c:3534
> >> do_filp_open+0x255/0x380 fs/namei.c:3564
> >> do_sys_open+0x584/0x720 fs/open.c:1063
> >> __do_sys_open fs/open.c:1081 [inline]
> >> __se_sys_open fs/open.c:1076 [inline]
> >> __x64_sys_open+0x7e/0xc0 fs/open.c:1076
> >> do_syscall_64+0x1b9/0x820 arch/x86/entry/common.c:290
> >> entry_SYSCALL_64_after_hwframe+0x49/0xbe
> >>
> >> -> #0 ((console_sem).lock){-.-.}:
> >> lock_acquire+0x1e4/0x4f0 kernel/locking/lockdep.c:3901
> >> __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
> >> _raw_spin_lock_irqsave+0x96/0xc0 kernel/locking/spinlock.c:152
> >> down_trylock+0x13/0x70 kernel/locking/semaphore.c:136
> >> __down_trylock_console_sem+0xae/0x200 kernel/printk/printk.c:228
> >> console_trylock+0x15/0xa0 kernel/printk/printk.c:2249
> >> console_trylock_spinning kernel/printk/printk.c:1651 [inline]
> >> vprintk_emit+0x31f/0x910 kernel/printk/printk.c:1926
> >> vprintk_default+0x28/0x30 kernel/printk/printk.c:1968
> >> vprintk_func+0x7a/0x117 kernel/printk/printk_safe.c:398
> >> printk+0xa7/0xcf kernel/printk/printk.c:2001
> >> __warn_printk+0x8c/0xe0 kernel/panic.c:590
> >> debug_print_object+0x16a/0x210 lib/debugobjects.c:326
> >> __debug_check_no_obj_freed lib/debugobjects.c:786 [inline]
> >> debug_check_no_obj_freed+0x3b2/0x595 lib/debugobjects.c:818
> >> kfree+0xc7/0x210 mm/slab.c:3812
> >> f2fs_fill_super+0xe1a/0x8150 fs/f2fs/super.c:3147
> >> mount_bdev+0x314/0x3e0 fs/super.c:1347
> >> f2fs_mount+0x3c/0x50 fs/f2fs/super.c:3161
> >> legacy_get_tree+0x131/0x460 fs/fs_context.c:732
> >> vfs_get_tree+0x1cb/0x5c0 fs/super.c:1746
> >> do_new_mount fs/namespace.c:2627 [inline]
> >> do_mount+0x6f9/0x1e30 fs/namespace.c:2951
> >> ksys_mount+0x12d/0x140 fs/namespace.c:3167
> >> __do_sys_mount fs/namespace.c:3181 [inline]
> >> __se_sys_mount fs/namespace.c:3178 [inline]
> >> __x64_sys_mount+0xbe/0x150 fs/namespace.c:3178
> >> do_syscall_64+0x1b9/0x820 arch/x86/entry/common.c:290
> >> entry_SYSCALL_64_after_hwframe+0x49/0xbe
> >>
> >> other info that might help us debug this:
> >>
> >> Chain exists of:
> >> (console_sem).lock --> &rq->lock --> &obj_hash[i].lock
> >>
> >> Possible unsafe locking scenario:
> >>
> >> CPU0 CPU1
> >> ---- ----
> >> lock(&obj_hash[i].lock);
> >> lock(&rq->lock);
> >> lock(&obj_hash[i].lock);
> >> lock((console_sem).lock);
> >>
> >> *** DEADLOCK ***
> >>
> >> 2 locks held by syz-executor4/18832:
> >> #0: 000000002b55bbcc (&fc->fs_type->s_umount_key#49/1){+.+.}, at:
> >> alloc_super+0x25e/0xb20 fs/super.c:225
> >> #1: 0000000046ad1dd4 (&obj_hash[i].lock){-.-.}, at:
> >> __debug_check_no_obj_freed lib/debugobjects.c:777 [inline]
> >> #1: 0000000046ad1dd4 (&obj_hash[i].lock){-.-.}, at:
> >> debug_check_no_obj_freed+0x16c/0x595 lib/debugobjects.c:818
> >>
> >> stack backtrace:
> >> CPU: 1 PID: 18832 Comm: syz-executor4 Not tainted 4.18.0-next-20180824+ #47
> >> Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS
> >> Google 01/01/2011
> >> Call Trace:
> >> __dump_stack lib/dump_stack.c:77 [inline]
> >> dump_stack+0x1c9/0x2b4 lib/dump_stack.c:113
> >> print_circular_bug.isra.34.cold.55+0x1bd/0x27d
> >> kernel/locking/lockdep.c:1222
> >> check_prev_add kernel/locking/lockdep.c:1862 [inline]
> >> check_prevs_add kernel/locking/lockdep.c:1975 [inline]
> >> validate_chain kernel/locking/lockdep.c:2416 [inline]
> >> __lock_acquire+0x3449/0x5020 kernel/locking/lockdep.c:3412
> >> lock_acquire+0x1e4/0x4f0 kernel/locking/lockdep.c:3901
> >> __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
> >> _raw_spin_lock_irqsave+0x96/0xc0 kernel/locking/spinlock.c:152
> >> down_trylock+0x13/0x70 kernel/locking/semaphore.c:136
> >> __down_trylock_console_sem+0xae/0x200 kernel/printk/printk.c:228
> >> console_trylock+0x15/0xa0 kernel/printk/printk.c:2249
> >> console_trylock_spinning kernel/printk/printk.c:1651 [inline]
> >> vprintk_emit+0x31f/0x910 kernel/printk/printk.c:1926
> >> vprintk_default+0x28/0x30 kernel/printk/printk.c:1968
> >> vprintk_func+0x7a/0x117 kernel/printk/printk_safe.c:398
> >> printk+0xa7/0xcf kernel/printk/printk.c:2001
> >> __warn_printk+0x8c/0xe0 kernel/panic.c:590
> >> debug_print_object+0x16a/0x210 lib/debugobjects.c:326
> >> __debug_check_no_obj_freed lib/debugobjects.c:786 [inline]
> >> debug_check_no_obj_freed+0x3b2/0x595 lib/debugobjects.c:818
> >> kfree+0xc7/0x210 mm/slab.c:3812
> >> f2fs_fill_super+0xe1a/0x8150 fs/f2fs/super.c:3147
> >> mount_bdev+0x314/0x3e0 fs/super.c:1347
> >> f2fs_mount+0x3c/0x50 fs/f2fs/super.c:3161
> >> legacy_get_tree+0x131/0x460 fs/fs_context.c:732
> >> vfs_get_tree+0x1cb/0x5c0 fs/super.c:1746
> >> do_new_mount fs/namespace.c:2627 [inline]
> >> do_mount+0x6f9/0x1e30 fs/namespace.c:2951
> >> ksys_mount+0x12d/0x140 fs/namespace.c:3167
> >> __do_sys_mount fs/namespace.c:3181 [inline]
> >> __se_sys_mount fs/namespace.c:3178 [inline]
> >> __x64_sys_mount+0xbe/0x150 fs/namespace.c:3178
> >> do_syscall_64+0x1b9/0x820 arch/x86/entry/common.c:290
> >> entry_SYSCALL_64_after_hwframe+0x49/0xbe
> >> RIP: 0033:0x459aba
> >> Code: b8 a6 00 00 00 0f 05 48 3d 01 f0 ff ff 0f 83 bd 8a fb ff c3 66 2e 0f
> >> 1f 84 00 00 00 00 00 66 90 49 89 ca b8 a5 00 00 00 0f 05 <48> 3d 01 f0 ff
> >> ff 0f 83 9a 8a fb ff c3 66 0f 1f 84 00 00 00 00 00
> >> RSP: 002b:00007f16f9937a88 EFLAGS: 00000206 ORIG_RAX: 00000000000000a5
> >> RAX: ffffffffffffffda RBX: 00007f16f9937b30 RCX: 0000000000459aba
> >> RDX: 00007f16f9937ad0 RSI: 0000000020000100 RDI: 00007f16f9937af0
> >> RBP: 0000000020000100 R08: 00007f16f9937b30 R09: 00007f16f9937ad0
> >> R10: 0000000000000000 R11: 0000000000000206 R12: 0000000000000003
> >> R13: 0000000000000000 R14: 00000000004c9c12 R15: 0000000000000000
> >> Dumping ftrace buffer:
> >> ---------------------------------
> >> syz-exec-23595 1...2 1079757271us : 0: }D
> >> syz-exec-23595 1..s3 1079757464us : 0: }D
> >> ---------------------------------
> >> Kernel Offset: disabled
> >> Rebooting in 86400 seconds..
> >>
> >>
> >> ---
> >> This bug is generated by a bot. It may contain errors.
> >> See https://goo.gl/tpsmEJ for more information about syzbot.
> >> syzbot engineers can be reached at syzkaller@xxxxxxxxxxxxxxxxx
> >>
> >> syzbot will keep track of this bug report. See:
> >> https://goo.gl/tpsmEJ#bug-status-tracking for how to communicate with
> >> syzbot.
> >>
> >> --
> >> You received this message because you are subscribed to the Google Groups "syzkaller-bugs" group.
> >> To unsubscribe from this group and stop receiving emails from it, send an email to syzkaller-bugs+unsubscribe@xxxxxxxxxxxxxxxxx
> >> To view this discussion on the web visit https://groups.google.com/d/msgid/syzkaller-bugs/0000000000009e76240574711017%40google.com.
> >> For more options, visit https://groups.google.com/d/optout.
> >
> > .
> >
>

Next message: Peter Chen: "RE: [PATCH v3] usb: chipidea: Grab the (legacy) USB PHY by phandle first"
Previous message: Peter Chen: "Re: [PATCH v4 5/6] usb:cdns3 Add Cadence USB3 DRD Driver"
In reply to: Sheng Yong: "Re: WARNING: ODEBUG bug in f2fs_fill_super"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]