Re: [syzbot] possible deadlock in jbd2_journal_lock_updates

[Thilo Fromm <t-lo@linux.microsoft.com>]

Hello Honza, hello Ye,

Just want to make sure this does not get lost - as mentioned earlier, 
reverting 51ae846cff5 leads to a kernel build that does not have this issue.

>>>>>>>>> So this seems like a real issue. Essentially, the problem is that
>>>>>>>>> ext4_bmap() acquires inode->i_rwsem while its caller
>>>>>>>>> jbd2_journal_flush() is holding journal->j_checkpoint_mutex. This
>>>>>>>>> looks like a real deadlock possibility.
>>>>>>>>
>>> [...]
>>>>>>>> The issue can be triggered on Flatcar release 3227.2.2 / kernel version
>>>>>>>> 5.15.63 (we ship LTS kernels) but not on release 3227.2.1 / kernel 5.15.58.
>>>>>>>> 51ae846cff5 was introduced to 5.15 in 5.15.61.
>>>>>>>
>>>>>>> Well, so far your stacktraces do not really show anything pointing to that
>>>>>>> particular commit. So we need to understand that hang some more.
>>>>>>
>>> [...]
>>>>> So our stacktraces were mangled because historically our kernel build used
>>>>> INSTALL_MOD_STRIP=--strip-unneeded, we've now switched it back to --strip-debug
>>>>> which is the default. We're still using CONFIG_UNWINDER_ORC=y.
>>>>>
>>>>> Here's the hung task output after the change to stripping:
>>>>
>>>> Yeah, the stacktraces now look as what I'd expect. Thanks for fixing that!
>>>> Sadly they don't point to the culprit of the problem. They show jbd2/sda9-8
>>>> is waiting for someone to drop its transaction handle. Other processes are
>>>> waiting for jbd2/sda9-8 to commit a transaction. And then a few processes
>>>> are waiting for locks held by these waiting processes. But I don't see
>>>> anywhere the process holding the transaction handle. Can you please
>>>> reproduce the problem once more and when the system hangs run:
>>>>
>>>> echo w >/proc/sysrq-trigger
>>>>
>>>> Unlike softlockup detector, this will dump all blocked task so hopefully
>>>> we'll see the offending task there. Thanks!
>>
>>> [ 3451.530765] sysrq: Show Blocked State
>>> [ 3451.534632] task:jbd2/sda9-8     state:D stack:    0 pid:  704 ppid:    2
>>> flags:0x00004000
>>> [ 3451.543107] Call Trace:
>>> [ 3451.545671]  <TASK>
>>> [ 3451.547888]  __schedule+0x2eb/0x8d0
>>> [ 3451.551491]  schedule+0x5b/0xd0
>>> [ 3451.554749]  jbd2_journal_commit_transaction+0x301/0x18e0 [jbd2]
>>> [ 3451.560881]  ? wait_woken+0x70/0x70
>>> [ 3451.564485]  ? lock_timer_base+0x61/0x80
>>> [ 3451.568524]  kjournald2+0xab/0x270 [jbd2]
>>> [ 3451.572657]  ? wait_woken+0x70/0x70
>>> [ 3451.576258]  ? load_superblock.part.0+0xb0/0xb0 [jbd2]
>>> [ 3451.581526]  kthread+0x124/0x150
>>> [ 3451.584874]  ? set_kthread_struct+0x50/0x50
>>> [ 3451.589177]  ret_from_fork+0x1f/0x30
>>> [ 3451.592887]  </TASK>
>>
>> So again jdb2 waiting for the transaction handle to be dropped. The task
>> having the handle open is:
>>
>>> [ 3473.580964] task:containerd      state:D stack:    0 pid:92591 ppid:
>>> 70946 flags:0x00004000
>>> [ 3473.589432] Call Trace:
>>> [ 3473.591997]  <TASK>
>>> [ 3473.594209]  ? ext4_mark_iloc_dirty+0x56a/0xaf0 [ext4]
>>> [ 3473.599518]  ? __schedule+0x2eb/0x8d0
>>> [ 3473.603301]  ? _raw_spin_lock_irqsave+0x36/0x50
>>> [ 3473.607947]  ? __ext4_journal_start_sb+0xf8/0x110 [ext4]
>>> [ 3473.613393]  ? __wait_on_bit_lock+0x40/0xb0
>>> [ 3473.617689]  ? out_of_line_wait_on_bit_lock+0x92/0xb0
>>> [ 3473.622854]  ? var_wake_function+0x30/0x30
>>> [ 3473.627062]  ? ext4_xattr_block_set+0x865/0xf00 [ext4]
>>> [ 3473.632346]  ? ext4_xattr_set_handle+0x48e/0x630 [ext4]
>>> [ 3473.637718]  ? ext4_initxattrs+0x43/0x60 [ext4]
>>> [ 3473.642389]  ? security_inode_init_security+0xab/0x140
>>> [ 3473.647640]  ? ext4_init_acl+0x170/0x170 [ext4]
>>> [ 3473.652315]  ? __ext4_new_inode+0x11f7/0x1710 [ext4]
>>> [ 3473.657430]  ? ext4_create+0x115/0x1d0 [ext4]
>>> [ 3473.661935]  ? path_openat+0xf48/0x1280
>>> [ 3473.665888]  ? do_filp_open+0xa9/0x150
>>> [ 3473.669751]  ? vfs_statx+0x74/0x130
>>> [ 3473.673359]  ? __check_object_size+0x146/0x160
>>> [ 3473.677917]  ? do_sys_openat2+0x9b/0x160
>>> [ 3473.681953]  ? __x64_sys_openat+0x54/0xa0
>>> [ 3473.686076]  ? do_syscall_64+0x38/0x90
>>> [ 3473.689942]  ? entry_SYSCALL_64_after_hwframe+0x61/0xcb
>>> [ 3473.695281]  </TASK>
>>
>> Which seems to be waiting on something in ext4_xattr_block_set(). This
>> "something" is not quite clear because the stacktrace looks a bit
>> unreliable at the top - either it is a buffer lock or we are waiting for
>> xattr block reference usecount to decrease (which would kind of make sense
>> because there were changes to ext4 xattr block handling in the time window
>> where the lockup started happening).
>>
>> Can you try to feed the stacktrace through addr2line utility (it will need
>> objects & debug symbols for the kernel)? Maybe it will show something
>> useful...
> 
> Sure, I think this worked fine. It's the buffer lock but right before it we're
> opening a journal transaction. Symbolized it looks like this:
> 
>    ext4_mark_iloc_dirty (include/linux/buffer_head.h:308 fs/ext4/inode.c:5712) ext4
>    __schedule (kernel/sched/core.c:4994 kernel/sched/core.c:6341)
>    _raw_spin_lock_irqsave (arch/x86/include/asm/paravirt.h:585 arch/x86/include/asm/qspinlock.h:51 include/asm-generic/qspinlock.h:85 include/linux/spinlock.h:199 include/linux/spinlock_api_smp.h:119 kernel/locking/spinlock.c:162)
>    __ext4_journal_start_sb (fs/ext4/ext4_jbd2.c:105) ext4
>    __wait_on_bit_lock (arch/x86/include/asm/bitops.h:214 include/asm-generic/bitops/instrumented-non-atomic.h:135 kernel/sched/wait_bit.c:89)
>    out_of_line_wait_on_bit_lock (kernel/sched/wait_bit.c:118)
>    var_wake_function (kernel/sched/wait_bit.c:22)
>    ext4_xattr_block_set (include/linux/buffer_head.h:391 fs/ext4/xattr.c:2019) ext4
>    ext4_xattr_set_handle (fs/ext4/xattr.c:2395) ext4
>    ext4_initxattrs (fs/ext4/xattr_security.c:48) ext4
>    security_inode_init_security (security/security.c:1114)
>    ext4_init_acl (fs/ext4/xattr_security.c:38) ext4
>    __ext4_new_inode (fs/ext4/ialloc.c:1325) ext4
>    ext4_create (fs/ext4/namei.c:2796) ext4
>    path_openat (fs/namei.c:3334 fs/namei.c:3404 fs/namei.c:3612)
>    do_filp_open (fs/namei.c:3642)
>    vfs_statx (include/linux/namei.h:57 fs/stat.c:221)
>    __check_object_size (mm/usercopy.c:240 mm/usercopy.c:286 mm/usercopy.c:256)
>    do_sys_openat2 (fs/open.c:1214)
>    __x64_sys_openat (fs/open.c:1241)
>    do_syscall_64 (arch/x86/entry/common.c:50 arch/x86/entry/common.c:80)
>    entry_SYSCALL_64_after_hwframe (arch/x86/entry/entry_64.S:118)

Is the symbolised stack trace Jeremi sent helpful to get to the bottom 
of this issue? Can we do anything else to help?

Best regards,
Thilo