[LU-11578] ldiskfs_map_blocks: comm mdt00_100: lblock 0 mapped to illegal pblock

• Type: Bug
• Resolution: Fixed
• Priority: Major
• Affects Version/s: Lustre 2.10.4
• Environment: CentOS 7.4
• Severity: 3
• Assignee: Yang Sheng
• Reporter: Stephane Thiell

Description

We hit the following issue today on Oak's MDT0. We just added another MDT a few days ago so it was empty but I started today to lfs migrate a test directory (from MDT0 to MDT1) when this happened on MDT0. lfs migrate did actually work for a while (about ~40k inodes have been migrated) until MDT0 did this:

Oct 26 17:26:13 oak-md1-s2 kernel: LDISKFS-fs error (device dm-0): ldiskfs_map_blocks:594: inode #659619751: block 774843950: comm mdt00_100: lblock 0 mapped to illegal pblock (length 1)
Oct 26 17:26:13 oak-md1-s2 kernel: Aborting journal on device dm-0-8.
Oct 26 17:26:13 oak-md1-s2 kernel: LustreError: 3844:0:(osd_handler.c:1586:osd_trans_commit_cb()) transaction @0xffff881b024c6a80 commit error: 2
Oct 26 17:26:13 oak-md1-s2 kernel: LDISKFS-fs (dm-0): Remounting filesystem read-only

I performed a fsck with the new e2fsprogs-1.44.3.wc1-0.el7.x86_64
Not sure this fixed our issue as I don't see any reference to inode 659619751 in it. I'm attaching the full fsck logs.

Hopefully, MDT0 then restarted without problem but I haven't touched the partially migrated directory at this time to avoid further issues on a Friday night on this production system. My feeling is that lfs migrate hit some migrated inode that somehow got corrupted on MDT0? The system has been working fine for weeks now (we only have the issue reported in LU-11205 regarding changelog_clear errors), so I assume this is due to my running lfs migrate. I can perform troubleshooting next week. Any recommendation to avoid this in the future is welcome, thanks much!

Stephane

Issue Links

• duplicates: LU-12485 (osd_handler.c:2146:osd_object_release()) ASSERTION( !(o->oo_destroyed == 0 && o->oo_inode && o->oo_inode->i_nlink == 0) ) faile
• is related to: LU-13157 migrate symlink with target name length > 59 cause crash
• is related to: LU-14511 oak-MDT0000: deleted inode referenced and aborted journal
• is related to: LU-10581 osd_handler.c:1978:osd_object_release()) LBUG

Comments

[Stephane Thiell]

Attached results of fsck on MDT0000 as oak-MDT0000-fsck-2018-11-06.log

[Stephane Thiell]

Ok this is not good. I tried to launch lfs migrate again:

lfs migrate --mdt-index 1 ./sthiell

Immediately the MDT0 crashed with:

[5516611.089815] LustreError: 15595:0:(osd_handler.c:1982:osd_object_release()) LBUG
[5516611.114441] Pid: 15595, comm: mdt00_105
[5516611.127614] 
Call Trace:
[5516611.141658]  [<ffffffffc08587ae>] libcfs_call_trace+0x4e/0x60 [libcfs]
[5516611.163987]  [<ffffffffc085883c>] lbug_with_loc+0x4c/0xb0 [libcfs]
[5516611.185171]  [<ffffffffc1019610>] osd_get_ldiskfs_dirent_param+0x0/0x130 [osd_ldiskfs]
[5516611.212390]  [<ffffffffc099ec4d>] lu_object_put+0x17d/0x3d0 [obdclass]
[5516611.235012]  [<ffffffffc116d233>] mdt_reint_migrate_internal.isra.38+0x793/0x16e0 [mdt]
[5516611.261959]  [<ffffffffc0b44851>] ? ldlm_cli_enqueue_local+0x271/0x860 [ptlrpc]
[5516611.287397]  [<ffffffffc116e3e5>] mdt_reint_rename_or_migrate.isra.39+0x265/0x860 [mdt]
[5516611.315164]  [<ffffffffc0b47ee0>] ? ldlm_blocking_ast+0x0/0x170 [ptlrpc]
[5516611.337804]  [<ffffffffc0b42340>] ? ldlm_completion_ast+0x0/0x920 [ptlrpc]
[5516611.361002]  [<ffffffffc116e9f0>] mdt_reint_migrate+0x10/0x20 [mdt]
[5516611.382451]  [<ffffffffc1172a40>] mdt_reint_rec+0x80/0x210 [mdt]
[5516611.402775]  [<ffffffffc115431b>] mdt_reint_internal+0x5fb/0x9c0 [mdt]
[5516611.425379]  [<ffffffffc115fe47>] mdt_reint+0x67/0x140 [mdt]
[5516611.444583]  [<ffffffffc0bdad95>] tgt_request_handle+0x925/0x1370 [ptlrpc]
[5516611.467794]  [<ffffffffc0b83bf6>] ptlrpc_server_handle_request+0x236/0xa90 [ptlrpc]
[5516611.494998]  [<ffffffffc0b80228>] ? ptlrpc_wait_event+0x98/0x340 [ptlrpc]
[5516611.517896]  [<ffffffff810c4822>] ? default_wake_function+0x12/0x20
[5516611.539085]  [<ffffffff810ba588>] ? __wake_up_common+0x58/0x90
[5516611.558854]  [<ffffffffc0b87332>] ptlrpc_main+0xa92/0x1e40 [ptlrpc]
[5516611.580053]  [<ffffffffc0b868a0>] ? ptlrpc_main+0x0/0x1e40 [ptlrpc]
[5516611.602365]  [<ffffffff810b098f>] kthread+0xcf/0xe0
[5516611.618967]  [<ffffffff810b08c0>] ? kthread+0x0/0xe0
[5516611.635856]  [<ffffffff816b4f58>] ret_from_fork+0x58/0x90
[5516611.654178]  [<ffffffff810b08c0>] ? kthread+0x0/0xe0
[5516611.671066] 
[5516611.676514] Kernel panic - not syncing: LBUG
[5516611.691113] CPU: 2 PID: 15595 Comm: mdt00_105 Tainted: G           OE  ------------   3.10.0-693.2.2.el7_lustre.pl1.x86_64 #1
[5516611.728879] Hardware name: Dell Inc. PowerEdge R630/0CNCJW, BIOS 2.6.0 10/26/2017
[5516611.754060]  ffff880e12696e00 00000000e8661d26 ffff8816667b3a08 ffffffff816a3db1
[5516611.778993]  ffff8816667b3a88 ffffffff8169dc74 ffffffff00000008 ffff8816667b3a98
[5516611.803930]  ffff8816667b3a38 00000000e8661d26 00000000e8661d26 ffff88103ce4f8b8
[5516611.828860] Call Trace:
[5516611.837456]  [<ffffffff816a3db1>] dump_stack+0x19/0x1b
[5516611.854920]  [<ffffffff8169dc74>] panic+0xe8/0x20d
[5516611.871240]  [<ffffffffc0858854>] lbug_with_loc+0x64/0xb0 [libcfs]
[5516611.892136]  [<ffffffffc1019610>] osd_object_release+0x60/0x60 [osd_ldiskfs]
[5516611.915909]  [<ffffffffc099ec4d>] lu_object_put+0x17d/0x3d0 [obdclass]
[5516611.942513]  [<ffffffffc116d233>] mdt_reint_migrate_internal.isra.38+0x793/0x16e0 [mdt]
[5516611.972007]  [<ffffffffc0b44851>] ? ldlm_cli_enqueue_local+0x271/0x860 [ptlrpc]
[5516611.996623]  [<ffffffffc116e3e5>] mdt_reint_rename_or_migrate.isra.39+0x265/0x860 [mdt]
[5516612.024113]  [<ffffffffc0b47ee0>] ? ldlm_blocking_ast_nocheck+0x310/0x310 [ptlrpc]
[5516612.049600]  [<ffffffffc0b42340>] ? ldlm_expired_completion_wait+0x240/0x240 [ptlrpc]
[5516612.075932]  [<ffffffffc116e9f0>] mdt_reint_migrate+0x10/0x20 [mdt]
[5516612.097115]  [<ffffffffc1172a40>] mdt_reint_rec+0x80/0x210 [mdt]
[5516612.118587]  [<ffffffffc115431b>] mdt_reint_internal+0x5fb/0x9c0 [mdt]
[5516612.140628]  [<ffffffffc115fe47>] mdt_reint+0x67/0x140 [mdt]
[5516612.160410]  [<ffffffffc0bdad95>] tgt_request_handle+0x925/0x1370 [ptlrpc]
[5516612.183611]  [<ffffffffc0b83bf6>] ptlrpc_server_handle_request+0x236/0xa90 [ptlrpc]
[5516612.209387]  [<ffffffffc0b80228>] ? ptlrpc_wait_event+0x98/0x340 [ptlrpc]
[5516612.232549]  [<ffffffff810c4822>] ? default_wake_function+0x12/0x20
[5516612.253726]  [<ffffffff810ba588>] ? __wake_up_common+0x58/0x90
[5516612.273494]  [<ffffffffc0b87332>] ptlrpc_main+0xa92/0x1e40 [ptlrpc]
[5516612.294971]  [<ffffffffc0b868a0>] ? ptlrpc_register_service+0xe30/0xe30 [ptlrpc]
[5516612.322155]  [<ffffffff810b098f>] kthread+0xcf/0xe0
[5516612.338755]  [<ffffffff810b08c0>] ? insert_kthread_work+0x40/0x40
[5516612.360224]  [<ffffffff816b4f58>] ret_from_fork+0x58/0x90
[5516612.378539]  [<ffffffff810b08c0>] ? insert_kthread_work+0x40/0x40

After than, when trying to remount MDT0, I got:

Nov 06 09:56:39 oak-md1-s2 kernel: Lustre: Lustre: Build Version: 2.10.4
Nov 06 09:56:39 oak-md1-s2 kernel: LNet: Using FMR for registration
Nov 06 09:56:39 oak-md1-s2 kernel: LNet: Added LNI 10.0.2.52@o2ib5 [8/256/0/180]
Nov 06 09:56:41 oak-md1-s2 kernel: LDISKFS-fs warning (device dm-1): ldiskfs_multi_mount_protect:322: MMP interval 42 higher than expected, please wait.
Nov 06 09:57:33 oak-md1-s2 kernel: LDISKFS-fs (dm-1): recovery complete
Nov 06 09:57:33 oak-md1-s2 kernel: LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,acl,no_mbcache,nodelalloc
Nov 06 09:57:36 oak-md1-s2 kernel: LDISKFS-fs error (device dm-1): ldiskfs_lookup:1809: inode #11: comm mount.lustre: deleted inode referenced: 460450747
Nov 06 09:57:36 oak-md1-s2 kernel: Aborting journal on device dm-1-8.
Nov 06 09:57:36 oak-md1-s2 kernel: LDISKFS-fs (dm-1): Remounting filesystem read-only
Nov 06 09:57:36 oak-md1-s2 kernel: LustreError: 3564:0:(osd_scrub.c:1962:osd_ios_lookup_one_len()) Fail to find #460450747 in lost+found (11/0): rc = -5
Nov 06 09:57:36 oak-md1-s2 kernel: LDISKFS-fs error (device dm-1): ldiskfs_lookup:1809: inode #11: comm mount.lustre: deleted inode referenced: 460450866
Nov 06 09:57:36 oak-md1-s2 kernel: LDISKFS-fs error (device dm-1): ldiskfs_lookup:1809: inode #11: comm mount.lustre: deleted inode referenced: 460450930
Nov 06 09:57:37 oak-md1-s2 kernel: LDISKFS-fs error (device dm-1): ldiskfs_lookup:1809: inode #11: comm mount.lustre: deleted inode referenced: 460450942
Nov 06 09:57:37 oak-md1-s2 kernel: LDISKFS-fs error (device dm-1): ldiskfs_lookup:1809: inode #11: comm mount.lustre: deleted inode referenced: 460450954
Nov 06 09:57:37 oak-md1-s2 kernel: LDISKFS-fs error (device dm-1): ldiskfs_lookup:1809: inode #11: comm mount.lustre: deleted inode referenced: 460450963
Nov 06 09:57:37 oak-md1-s2 kernel: LDISKFS-fs error (device dm-1): ldiskfs_lookup:1809: inode #11: comm mount.lustre: deleted inode referenced: 460450965
Nov 06 09:57:37 oak-md1-s2 kernel: LDISKFS-fs error (device dm-1): ldiskfs_lookup:1809: inode #11: comm mount.lustre: deleted inode referenced: 460450970
Nov 06 09:57:37 oak-md1-s2 kernel: LDISKFS-fs error (device dm-1): ldiskfs_lookup:1809: inode #11: comm mount.lustre: deleted inode referenced: 460451000
Nov 06 09:57:37 oak-md1-s2 kernel: LDISKFS-fs error (device dm-1): ldiskfs_lookup:1809: inode #11: comm mount.lustre: deleted inode referenced: 460451002
Nov 06 09:57:37 oak-md1-s2 kernel: LustreError: 137-5: oak-MDT0000_UUID: not available for connect from 10.9.107.16@o2ib4 (no target). If you are running an HA pair check that the target is mounted on the other server.
Nov 06 09:57:37 oak-md1-s2 kernel: LustreError: Skipped 1 previous similar message
Nov 06 09:57:37 oak-md1-s2 kernel: LustreError: 3564:0:(obd_mount_server.c:304:server_mgc_set_fs()) can't set_fs -30
Nov 06 09:57:37 oak-md1-s2 kernel: LustreError: 3564:0:(obd_mount_server.c:1879:server_fill_super()) Unable to start targets: -30
Nov 06 09:57:37 oak-md1-s2 kernel: LustreError: 3564:0:(obd_mount_server.c:1589:server_put_super()) no obd oak-MDT0000
Nov 06 09:57:37 oak-md1-s2 kernel: LustreError: 3564:0:(obd_mount_server.c:135:server_deregister_mount()) oak-MDT0000 not registered
Nov 06 09:57:37 oak-md1-s2 kernel: Lustre: server umount oak-MDT0000 complete
Nov 06 09:57:37 oak-md1-s2 kernel: LustreError: 3564:0:(obd_mount.c:1582:lustre_fill_super()) Unable to mount  (-30)

Oak is down. I'm running fsck on it at the moment.
Thanks,
Stephane

[Stephane Thiell]

Hi YangSheng,

Thanks for the explanation, this is helpful and that makes sense. And this would also explain why fsck didn't find anything interesting. I'll try to check what exactly have been migrated and possibly launch lfs migrate again today and see how it goes. I'll report back any useful info.

Best,
Stephane

[Yang Sheng]

Hi, Stephane,

I don't think this inode can be moved to other place, Since the failure ldiskfs_map_blocks was issued by read syscall. And then MDT0 was remounted as read-only immediately after this failure. From failure location we can see the block No(774843950) comes from extent status tree. This is a cache was managed by ldiskfs internal. It means this block No should valid before(it can be cached) and become invalid when read again. So i think this issue should relate to memory corruption rather than migration.

Thanks,
YangSheng

[Stephane Thiell]

Hi YangSheng,

Thanks! Looks like the inode can't be found anymore on MDT 0:

[root@oak-md1-s2 ~]# debugfs /dev/mapper/md1-rbod1-mdt0
debugfs 1.44.3.wc1 (23-July-2018)
debugfs:  ncheck 659619751
Inode	Pathname
debugfs:  

The command took at least two hours to perform so I guess it worked. Perhaps the file was migrated to MDT 1 after all. But how to know... the inode # is probably different on MDT 1 after migration. Anyway, what do you think?

Thanks again,
Stephane

[Yang Sheng]

Hi, Stephane,

First, Looks like the block No 774843950 is really wrong. You only have 436659200 blocks in your MDS. You still have free inodes 571125380. So the inode No 659619751 also suspected. You can check it use command debugfs as below:

#
# debugfs {MDS device}
debugfs: ncheck  659619751 

It should report a pathname to be consistent with this inode. If so, you can check blocks occupied by this pathname.

debug: blocks {pathname}

Please paste output in here.

Thanks,
YangSheng

[Stephane Thiell]

YangSheng,
Any idea of what could have gone wrong here?
I'm very reluctant to use lfs migrate again until we figure this out. Thanks.

[Stephane Thiell]

Hi Yang,

Absolutely! Thanks for taking a look at this.
 
Original MDT0 (formatted at the time of Lustre 2.9):

[root@oak-md1-s2 ~]# tune2fs -l /dev/mapper/md1-rbod1-mdt0 
tune2fs 1.44.3.wc1 (23-July-2018)
device /dev/dm-0 mounted by lustre
Filesystem volume name:   oak-MDT0000
Last mounted on:          /
Filesystem UUID:          0ed1cfdd-8e25-4b6b-9cb9-7be1e89d70ad
Filesystem magic number:  0xEF53
Filesystem revision #:    1 (dynamic)
Filesystem features:      has_journal ext_attr resize_inode dir_index filetype needs_recovery mmp flex_bg dirdata sparse_super large_file huge_file uninit_bg dir_nlink quota
Filesystem flags:         signed_directory_hash 
Default mount options:    user_xattr acl
Filesystem state:         clean
Errors behavior:          Continue
Filesystem OS type:       Linux
Inode count:              873332736
Block count:              436659200
Reserved block count:     21832960
Free blocks:              243851408
Free inodes:              571125380
First block:              0
Block size:               4096
Fragment size:            4096
Reserved GDT blocks:      1024
Blocks per group:         16384
Fragments per group:      16384
Inodes per group:         32768
Inode blocks per group:   4096
Flex block group size:    16
Filesystem created:       Mon Feb 13 12:36:07 2017
Last mount time:          Fri Oct 26 18:39:01 2018
Last write time:          Fri Oct 26 18:39:01 2018
Mount count:              1
Maximum mount count:      -1
Last checked:             Fri Oct 26 17:41:18 2018
Check interval:           0 (<none>)
Lifetime writes:          52 TB
Reserved blocks uid:      0 (user root)
Reserved blocks gid:      0 (group root)
First inode:              11
Inode size:	          512
Required extra isize:     28
Desired extra isize:      28
Journal inode:            8
Default directory hash:   half_md4
Directory Hash Seed:      be3bd996-8da4-4d22-80e4-e7a4c8ce22a0
Journal backup:           inode blocks
MMP block number:         13560
MMP update interval:      5
User quota inode:         3
Group quota inode:        4

Just in case, same command with the new MDT0001, formatted with 2.10:

[root@oak-md1-s1 ~]# tune2fs -l /dev/mapper/md1-rbod1-mdt1 
tune2fs 1.42.13.wc6 (05-Feb-2017)
device /dev/dm-2 mounted by lustre
Filesystem volume name:   oak-MDT0001
Last mounted on:          /
Filesystem UUID:          169de89e-6b5d-4480-b118-8f726d7af07b
Filesystem magic number:  0xEF53
Filesystem revision #:    1 (dynamic)
Filesystem features:      has_journal ext_attr resize_inode dir_index filetype needs_recovery mmp flex_bg dirdata sparse_super large_file huge_file uninit_bg dir_nlink quota
Filesystem flags:         signed_directory_hash 
Default mount options:    user_xattr acl
Filesystem state:         clean
Errors behavior:          Continue
Filesystem OS type:       Linux
Inode count:              698600160
Block count:              436659200
Reserved block count:     21832704
Free blocks:              260890660
Free inodes:              698600147
First block:              0
Block size:               4096
Fragment size:            4096
Reserved GDT blocks:      1024
Blocks per group:         20472
Fragments per group:      20472
Inodes per group:         32752
Inode blocks per group:   8188
Flex block group size:    16
Filesystem created:       Thu Oct 18 11:43:21 2018
Last mount time:          Thu Oct 18 11:45:28 2018
Last write time:          Thu Oct 18 11:45:30 2018
Mount count:              3
Maximum mount count:      -1
Last checked:             Thu Oct 18 11:43:21 2018
Check interval:           0 (<none>)
Lifetime writes:          4145 MB
Reserved blocks uid:      0 (user root)
Reserved blocks gid:      0 (group root)
First inode:              11
Inode size:	          1024
Required extra isize:     32
Desired extra isize:      32
Journal inode:            8
Default directory hash:   half_md4
Directory Hash Seed:      c48690f3-5625-496d-adb1-9c3288cc8b00
Journal backup:           inode blocks
MMP block number:         17606
MMP update interval:      5
User quota inode:         3
Group quota inode:        4

Let me know if you need anything else.
Best,
Stephane

[Yang Sheng]

Hi, Stephane,

Could please collect superblock info of MDS as below:

# tune2fs -l {mds device}

Thanks,
YangSheng

[Peter Jones]

Yang Sheng

Can you please advise?

Thanks

Peter