Re: xfs: system fails to boot up due to Internal error xfs_trans_cancel

["Linux regression tracking (Thorsten Leemhuis)" <regressions@leemhuis.info>]

Hi, Thorsten here, the Linux kernel's regression tracker. Top-posting
for once, to make this easily accessible to everyone.

Has any progress been made to fix below regression? It doesn't look like
it from here, hence I wondered if it fall through the cracks. Or is
there some good reason why this is safe to ignore?

Ciao, Thorsten (wearing his 'the Linux kernel's regression tracker' hat)
--
Everything you wanna know about Linux kernel regression tracking:
https://linux-regtracking.leemhuis.info/about/#tldr
If I did something stupid, please tell me, as explained on that page.

#regzbot poke

On 20.03.23 06:20, Ritesh Harjani (IBM) wrote:
> "Darrick J. Wong" <djwong@kernel.org> writes:
> 
>> On Sat, Mar 18, 2023 at 10:20:28PM +0530, Ritesh Harjani wrote:
>>> "Darrick J. Wong" <djwong@kernel.org> writes:
>>>
>>>> On Wed, Mar 15, 2023 at 10:20:37PM -0700, Darrick J. Wong wrote:
>>>>> On Thu, Mar 16, 2023 at 10:16:02AM +0530, Ritesh Harjani wrote:
>>>>>> "Darrick J. Wong" <djwong@kernel.org> writes:
>>>>>>
>>>>>> Hi Darrick,
>>>>>>
>>>>>> Thanks for your analysis and quick help on this.
>>>>>>
>>>>>>>>
>>>>>>>> Hi Darrick,
>>>>>>>>
>>>>>>>> Please find the information collected from the system. We added some
>>>>>>>> debug logs and looks like it is exactly what is happening which you
>>>>>>>> pointed out.
>>>>>>>>
>>>>>>>> We added a debug kernel patch to get more info from the system which
>>>>>>>> you had requested [1]
>>>>>>>>
>>>>>>>> 1. We first breaked into emergency shell where root fs is first getting
>>>>>>>> mounted on /sysroot as "ro" filesystem. Here are the logs.
>>>>>>>>
>>>>>>>> [  OK  ] Started File System Check on /dev/mapper/rhel_ltcden3--lp1-root.
>>>>>>>>          Mounting /sysroot...
>>>>>>>> [    7.203990] SGI XFS with ACLs, security attributes, quota, no debug enabled
>>>>>>>> [    7.205835] XFS (dm-0): Mounting V5 Filesystem 7b801289-75a7-4d39-8cd3-24526e9e9da7
>>>>>>>> [   ***] A start job is running for /sysroot (15s / 1min 35s)[   17.439377] XFS (dm-0): Starting recovery (logdev: internal)
>>>>>>>> [  *** ] A start job is running for /sysroot (16s / 1min 35s)[   17.771158] xfs_log_mount_finish: Recovery needed is set
>>>>>>>> [   17.771172] xlog_recover_iunlink_ag: ran xlog_recover_iunlink_bucket for agi:0, bucket:0
>>>>>>>> [   17.771179] xlog_recover_iunlink_ag: ran xlog_recover_iunlink_bucket for agi:0, bucket:1
>>>>>>>> [   17.771184] xlog_recover_iunlink_ag: ran xlog_recover_iunlink_bucket for agi:0, bucket:2
>>>>>>>> [   17.771190] xlog_recover_iunlink_ag: ran xlog_recover_iunlink_bucket for agi:0, bucket:3
>>>>>>>> [   17.771196] xlog_recover_iunlink_ag: ran xlog_recover_iunlink_bucket for agi:0, bucket:4
>>>>>>>> [   17.771201] xlog_recover_iunlink_ag: ran xlog_recover_iunlink_bucket for agi:0, bucket:5
>>>>>>>> [   17.801033] xlog_recover_iunlink_ag: ran xlog_recover_iunlink_bucket for agi:0, bucket:6
>>>>>>>> [   17.801041] xlog_recover_iunlink_ag: ran xlog_recover_iunlink_bucket for agi:0, bucket:7
>>>>>>>> [   17.801046] xlog_recover_iunlink_ag: ran xlog_recover_iunlink_bucket for agi:0, bucket:8
>>>>>>>> [   17.801052] xlog_recover_iunlink_ag: ran xlog_recover_iunlink_bucket for agi:0, bucket:9
>>>>>>>> [   17.801057] xlog_recover_iunlink_ag: ran xlog_recover_iunlink_bucket for agi:0, bucket:10
>>>>>>>> [   17.801063] xlog_recover_iunlink_ag: ran xlog_recover_iunlink_bucket for agi:0, bucket:11
>>>>>>>> [   17.801068] xlog_recover_iunlink_ag: ran xlog_recover_iunlink_bucket for agi:0, bucket:12
>>>>>>>> [   17.801272] xlog_recover_iunlink_bucket: bucket: 13, agino: 3064909, ino: 3064909, iget ret: 0, previno:18446744073709551615, prev_agino:4294967295
>>>>>>>>
>>>>>>>> <previno, prev_agino> is just <-1 %ull and -1 %u> in above. That's why
>>>>>>>> the huge value.
>>>>>>>
>>>>>>> Ok, so log recovery finds 3064909 and clears it...
>>>>>>>
>>>>>>>> [   17.801281] xlog_recover_iunlink_ag: ran xlog_recover_iunlink_bucket for agi:0, bucket:13
>>>>>>>> [   17.801287] xlog_recover_iunlink_ag: ran xlog_recover_iunlink_bucket for agi:0, bucket:14
>>>>>>>
>>>>>>> <snip the rest of these...>
>>>>>>>
>>>>>>>> [   17.844910] xlog_recover_iunlink_ag: ran xlog_recover_iunlink_bucket for agi:3, bucket:62
>>>>>>>> [   17.844916] xlog_recover_iunlink_ag: ran xlog_recover_iunlink_bucket for agi:3, bucket:63
>>>>>>>> [   17.886079] XFS (dm-0): Ending recovery (logdev: internal)
>>>>>>>> [  OK  ] Mounted /sysroot.
>>>>>>>> [  OK  ] Reached target Initrd Root File System.
>>>>>>>>
>>>>>>>>
>>>>>>>> 2. Then these are the logs from xfs_repair -n /dev/dm-0
>>>>>>>> Here you will notice the same agi 3064909 in bucket 13 (from phase-2) which got also
>>>>>>>> printed in above xlog_recover_iunlink_ag() function.
>>>>>>>>
>>>>>>>> switch_root:/# xfs_repair -n /dev/dm-0
>>>>>>>> Phase 1 - find and verify superblock...
>>>>>>>> Phase 2 - using internal log
>>>>>>>>         - zero log...
>>>>>>>>         - scan filesystem freespace and inode maps...
>>>>>>>> agi unlinked bucket 13 is 3064909 in ag 0 (inode=3064909)
>>>>>>>
>>>>>>> ...yet here we find that 3064909 is still on the unlinked list?
>>>>>>>
>>>>>>> Just to confirm -- you ran xfs_repair -n after the successful recovery
>>>>>>> above, right?
>>>>>>>
>>>>>> Yes, that's right.
>>>>>>
>>>>>>>>         - found root inode chunk
>>>>>>>> Phase 3 - for each AG...
>>>>>>>>         - scan (but don't clear) agi unlinked lists...
>>>>>>>>         - process known inodes and perform inode discovery...
>>>>>>>>         - agno = 0
>>>>>>>>         - agno = 1
>>>>>>>>         - agno = 2
>>>>>>>>         - agno = 3
>>>>>>>>         - process newly discovered inodes...
>>>>>>>> Phase 4 - check for duplicate blocks...
>>>>>>>>         - setting up duplicate extent list...
>>>>>>>>         - check for inodes claiming duplicate blocks...
>>>>>>>>         - agno = 0
>>>>>>>>         - agno = 2
>>>>>>>>         - agno = 1
>>>>>>>>         - agno = 3
>>>>>>>> No modify flag set, skipping phase 5
>>>>>>>> Phase 6 - check inode connectivity...
>>>>>>>>         - traversing filesystem ...
>>>>>>>>         - traversal finished ...
>>>>>>>>         - moving disconnected inodes to lost+found ...
>>>>>>>> Phase 7 - verify link counts...
>>>>>>>> would have reset inode 3064909 nlinks from 4294967291 to 2
>>>>>>>
>>>>>>> Oh now that's interesting.  Inode on unlinked list with grossly nonzero
>>>>>>> (but probably underflowed) link count.  That might explain why iunlink
>>>>>>> recovery ignores the inode.  Is inode 3064909 reachable via the
>>>>>>> directory tree?
>>>>>>>
>>>>>>> Would you mind sending me a metadump to play with?  metadump -ago would
>>>>>>> be best, if filenames/xattrnames aren't sensitive customer data.
>>>>>>
>>>>>> Sorry about the delay.
>>>>>> I am checking for any permissions part internally.
>>>>>> Meanwhile - I can help out if you would like me to try anything.
>>>>>
>>>>> Ok.  I'll try creating a filesystem with a weirdly high refcount
>>>>> unlinked inode and I guess you can try it to see if you get the same
>>>>> symptoms.  I've finished with my parent pointers work for the time
>>>>> being, so I might have some time tomorrow (after I kick the tires on
>>>>> SETFSUUID) to simulate this and see if I can adapt the AGI repair code
>>>>> to deal with this.
>>>>
>>>> If you uncompress and mdrestore the attached file to a blockdev, mount
>>>> it, and run some creat() exerciser, do you get the same symptoms?  I've
>>>> figured out how to make online fsck deal with it. :)
>>>>
>>>> A possible solution for runtime would be to make it so that
>>>> xfs_iunlink_lookup could iget the inode if it's not in cache at all.
>>>>
>>>
>>> Hello Darrick,
>>>
>>> I did xfs_mdrestore the metadump you provided on a loop mounted
>>> blockdev. I ran fsstress on the root dir of the mounted filesystem,
>>> but I was unable to hit the issue.
>>>
>>> I tried the same with the original FS metadump as well and I am unable
>>> to hit the issue while running fsstress on the filesystem.
>>>
>>> I am thinking of identifying which file unlink operation was in progress
>>> when we see the issue during mounting. Maybe that will help in
>>> recreating the issue.
>>
>> Yeah, creating a bunch of O_TMPFILE files will exercise the unlinked
>> lists, possibly enough to trip over the affected agi bucket.  See
>> t_open_tmpfiles.c in the fstests repo.
> 
> 
> Hello Darrick,
> 
> Yes, I am tripping over the issue very easily when I run t_open_tmpfiles
> testcase for the metadump you shared. (Not hitting with the original dump
> though. Will try to fetch more information on whay is that).
> 
> Here is the call stack with your metadump when we try to run
> t_open_tmpfiles test case.
> Its the same warning message which we were hitting too in the original
> case too.
> 
> xfs_iunlink_lookup()
> <...>
>     /*
> 	 * Inode not in memory or in RCU freeing limbo should not happen.
> 	 * Warn about this and let the caller handle the failure.
> 	 */
> 	if (WARN_ON_ONCE(!ip || !ip->i_ino)) {
> 		rcu_read_unlock();
> 		return NULL;
> 	}
> <...>
> 
> [43873.070585] xfs filesystem being mounted at /mnt1/scratch supports timestamps until 2038 (0x7fffffff)
> root@ubuntu:~# [43905.483065] ------------[ cut here ]------------
> [43905.485250] WARNING: CPU: 0 PID: 2379 at fs/xfs/xfs_inode.c:1839 xfs_iunlink_lookup+0x14c/0x1e0
> [43905.488325] Modules linked in:
> [43905.489594] CPU: 0 PID: 2379 Comm: t_open_tmpfiles Not tainted 6.3.0-rc2-xfstests-00051-gc1940a43e595 #57
> [43905.492828] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.15.0-0-g2dd4b9b3f840-prebuilt.qemu.org 04/01/2014
> [43905.496604] RIP: 0010:xfs_iunlink_lookup+0x14c/0x1e0
> [43905.498341] Code: 0f 85 6e ff ff ff 48 c7 c2 a8 95 be 82 be 22 03 00 00 48 c7 c7 30 23 b7 82 c6 05 c8 71 84 01 01 e8 e9 d3 91 ff e9 6
> [43905.504324] RSP: 0018:ffffc9000405fb98 EFLAGS: 00010246
> [43905.506224] RAX: 0000000000000000 RBX: 0000000000001b43 RCX: 0000000000000000
> [43905.508624] RDX: ffff8891f1edf488 RSI: ffff8891f1edf4c8 RDI: 0000000000001b43
> [43905.511087] RBP: 0000000000001b43 R08: 0000000000000000 R09: ffff88931446ba80
> [43905.514465] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
> [43905.517947] R13: ffff889313f67840 R14: ffff8892c0155b00 R15: ffff8889dc9b2900
> [43905.521519] FS:  00007ffff7fb2740(0000) GS:ffff889dc7600000(0000) knlGS:0000000000000000
> [43905.525570] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [43905.528402] CR2: 0000555555556060 CR3: 00000011b4790006 CR4: 0000000000170ef0
> [43905.532008] Call Trace:
> [43905.533399]  <TASK>
> [43905.534473]  xfs_iunlink_insert_inode+0x7a/0x100
> [43905.536663]  xfs_iunlink+0xa4/0x190
> [43905.537962]  xfs_create_tmpfile+0x277/0x2e0
> [43905.539654]  xfs_generic_create+0x100/0x350
> [43905.541303]  xfs_vn_tmpfile+0x1f/0x40
> [43905.542920]  vfs_tmpfile+0x10e/0x1b0
> [43905.544307]  path_openat+0x157/0x200
> [43905.545813]  do_filp_open+0xad/0x150
> [43905.547213]  ? alloc_fd+0x12d/0x220
> [43905.548646]  ? alloc_fd+0x12d/0x220
> [43905.550014]  ? lock_release+0x7f/0x130
> [43905.551435]  ? do_raw_spin_unlock+0x4f/0xa0
> [43905.553045]  ? _raw_spin_unlock+0x2d/0x50
> [43905.554554]  ? alloc_fd+0x12d/0x220
> [43905.556264]  do_sys_openat2+0x9b/0x160
> [43905.557680]  __x64_sys_openat+0x58/0xa0
> [43905.559065]  do_syscall_64+0x3f/0x90
> [43905.560589]  entry_SYSCALL_64_after_hwframe+0x72/0xdc
> [43905.562377] RIP: 0033:0x7ffff7d0ca45
> [43905.563970] Code: 75 53 89 f0 25 00 00 41 00 3d 00 00 41 00 74 45 80 3d a6 1b 0f 00 00 74 69 89 da 48 89 ee bf 9c ff ff ff b8 01 01 5
> [43905.570038] RSP: 002b:00007fffffffe2c0 EFLAGS: 00000202 ORIG_RAX: 0000000000000101
> [43905.572747] RAX: ffffffffffffffda RBX: 0000000000410002 RCX: 00007ffff7d0ca45
> [43905.575246] RDX: 0000000000410002 RSI: 0000555555556057 RDI: 00000000ffffff9c
> [43905.577782] RBP: 0000555555556057 R08: 000000000000ab7f R09: 00007ffff7fc1080
> [43905.580315] R10: 00000000000001a4 R11: 0000000000000202 R12: 0000000000000000
> [43905.582850] R13: 00007fffffffe4a0 R14: 0000555555557d68 R15: 00007ffff7ffd020
> [43905.585438]  </TASK>
> [43905.586528] irq event stamp: 14045
> [43905.587828] hardirqs last  enabled at (14055): [<ffffffff8121bc02>] __up_console_sem+0x52/0x60
> [43905.590861] hardirqs last disabled at (14066): [<ffffffff8121bbe7>] __up_console_sem+0x37/0x60
> [43905.593856] softirqs last  enabled at (13920): [<ffffffff82231b5a>] __do_softirq+0x2ea/0x3e1
> [43905.596813] softirqs last disabled at (13909): [<ffffffff8119573f>] irq_exit_rcu+0xdf/0x140
> [43905.599766] ---[ end trace 0000000000000000 ]---
> [43905.601450] XFS (loop7): Internal error xfs_trans_cancel at line 1097 of file fs/xfs/xfs_trans.c.  Caller xfs_create_tmpfile+0x1c6/00
> [43905.606100] CPU: 0 PID: 2379 Comm: t_open_tmpfiles Tainted: G        W          6.3.0-rc2-xfstests-00051-gc1940a43e595 #57
> [43905.609797] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.15.0-0-g2dd4b9b3f840-prebuilt.qemu.org 04/01/2014
> [43905.614562] Call Trace:
> [43905.616112]  <TASK>
> [43905.617245]  dump_stack_lvl+0x66/0x80
> [43905.619054]  xfs_trans_cancel+0x138/0x1f0
> [43905.620898]  xfs_create_tmpfile+0x1c6/0x2e0
> [43905.623140]  xfs_generic_create+0x100/0x350
> [43905.625483]  xfs_vn_tmpfile+0x1f/0x40
> [43905.627372]  vfs_tmpfile+0x10e/0x1b0
> [43905.629413]  path_openat+0x157/0x200
> [43905.631204]  do_filp_open+0xad/0x150
> [43905.633050]  ? alloc_fd+0x12d/0x220
> [43905.634844]  ? alloc_fd+0x12d/0x220
> [43905.636602]  ? lock_release+0x7f/0x130
> [43905.638479]  ? do_raw_spin_unlock+0x4f/0xa0
> [43905.640726]  ? _raw_spin_unlock+0x2d/0x50
> [43905.642916]  ? alloc_fd+0x12d/0x220
> [43905.644375]  do_sys_openat2+0x9b/0x160
> [43905.645763]  __x64_sys_openat+0x58/0xa0
> [43905.647145]  do_syscall_64+0x3f/0x90
> [43905.648685]  entry_SYSCALL_64_after_hwframe+0x72/0xdc
> [43905.650430] RIP: 0033:0x7ffff7d0ca45
> [43905.651731] Code: 75 53 89 f0 25 00 00 41 00 3d 00 00 41 00 74 45 80 3d a6 1b 0f 00 00 74 69 89 da 48 89 ee bf 9c ff ff ff b8 01 01 5
> [43905.657637] RSP: 002b:00007fffffffe2c0 EFLAGS: 00000202 ORIG_RAX: 0000000000000101
> [43905.660141] RAX: ffffffffffffffda RBX: 0000000000410002 RCX: 00007ffff7d0ca45
> [43905.662525] RDX: 0000000000410002 RSI: 0000555555556057 RDI: 00000000ffffff9c
> [43905.665086] RBP: 0000555555556057 R08: 000000000000ab7f R09: 00007ffff7fc1080
> [43905.667455] R10: 00000000000001a4 R11: 0000000000000202 R12: 0000000000000000
> [43905.669830] R13: 00007fffffffe4a0 R14: 0000555555557d68 R15: 00007ffff7ffd020
> [43905.672193]  </TASK>
> [43905.689666] XFS (loop7): Corruption of in-memory data (0x8) detected at xfs_trans_cancel+0x151/0x1f0 (fs/xfs/xfs_trans.c:1098).  Shu.
> [43905.694215] XFS (loop7): Please unmount the filesystem and rectify the problem(s)
> 
> 
> -ritesh
> 
> 
>>
>> --D
>>
>>> Although the xfs_repair -n does show a similar log of unlinked inode
>>> with the metadump you provided.
>>>
>>> root@ubuntu:~# xfs_repair -n -o force_geometry /dev/loop7
>>> Phase 1 - find and verify superblock...
>>> Phase 2 - using internal log
>>>         - zero log...
>>>         - scan filesystem freespace and inode maps...
>>> agi unlinked bucket 3 is 6979 in ag 0 (inode=6979)
>>> agi unlinked bucket 4 is 6980 in ag 0 (inode=6980)
>>>         - found root inode chunk
>>> Phase 3 - for each AG...
>>>         - scan (but don't clear) agi unlinked lists...
>>>         - process known inodes and perform inode discovery...
>>>         - agno = 0
>>>         - process newly discovered inodes...
>>> Phase 4 - check for duplicate blocks...
>>>         - setting up duplicate extent list...
>>>         - check for inodes claiming duplicate blocks...
>>>         - agno = 0
>>> No modify flag set, skipping phase 5
>>> Phase 6 - check inode connectivity...
>>>         - traversing filesystem ...
>>>         - traversal finished ...
>>>         - moving disconnected inodes to lost+found ...
>>> disconnected inode 6979, would move to lost+found
>>> disconnected inode 6980, would move to lost+found
>>> Phase 7 - verify link counts...
>>> would have reset inode 6979 nlinks from 5555 to 1
>>> would have reset inode 6980 nlinks from 0 to 1
>>> No modify flag set, skipping filesystem flush and exiting.
>>>
>>> Thanks again for the help. Once I have more info I will update the
>>> thread!
>>>
>>> -ritesh