[LU-14511] oak-MDT0000: deleted inode referenced and aborted journal

• Status: Resolved
• Project: Lustre
• Affects Version/s: Lustre 2.12.6
• Type: Bug
• Priority: Critical
• Reporter: Stephane Thiell
• Assignee: Alex Zhuravlev
• Resolution: Fixed

Environment

CentOS 7.9

• Severity: 1

Description

Hello, I think an old problem fo ours came back to haunt us, that I originally described in LU-11578, that was because we tried lfs migrate -m on a directory with early 2.10.x (then we stopped and then lfs migrate -m was disabled). Since then, we have upgraded Oak to Lustre 2.12, and just yesterday, we tried to upgrade from 2.12.5 to 2.12.6 by failing over the MDT but we cannot mount it anymore.

It's also very likely that since the last umount, I had deleted some files in the bad directory in question /oak/stanford/groups/ruthm/sthiell/anaconda2.off to make some cleanup
MDT worked fine before un-mounting.

So at the moment, we can't mount oak-MDT0000 anymore as we hit the following problem:

[2021-03-10T15:31:29-08:00] [29905.173864] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc^M
[2021-03-10T15:31:29-08:00] [29905.322318] LustreError: 166-1: MGC10.0.2.51@o2ib5: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail^M
[2021-03-10T15:31:29-08:00] [29905.336575] Lustre: Evicted from MGS (at MGC10.0.2.51@o2ib5_0) after server handle changed from 0xd5a7458f859bc1ba to 0xd5a7458fad8ca5e1^M
[2021-03-10T15:31:38-08:00] [29914.525782] LDISKFS-fs (dm-4): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,acl,no_mbcache,nodelalloc^M
[2021-03-10T15:31:38-08:00] [29914.709510] LDISKFS-fs error (device dm-4): ldiskfs_lookup:1817: inode #11: comm mount.lustre: deleted inode referenced: 459882777^M
[2021-03-10T15:31:38-08:00] [29914.722944] Aborting journal on device dm-4-8.^M
[2021-03-10T15:31:38-08:00] [29914.728143] LDISKFS-fs (dm-4): Remounting filesystem read-only^M
[2021-03-10T15:31:38-08:00] [29914.734658] LustreError: 8949:0:(osd_scrub.c:1758:osd_ios_lookup_one_len()) Fail to find #459882777 in lost+found (11/0): rc = -5^M
[2021-03-10T15:31:38-08:00] [29914.752101] LDISKFS-fs error (device dm-4): ldiskfs_lookup:1817: inode #11: comm mount.lustre: deleted inode referenced: 627060535^M
[2021-03-10T15:31:38-08:00] [29914.766588] LDISKFS-fs error (device dm-4): ldiskfs_lookup:1817: inode #11: comm mount.lustre: deleted inode referenced: 627060536^M
[2021-03-10T15:31:38-08:00] [29914.779958] LDISKFS-fs error (device dm-4): ldiskfs_lookup:1817: inode #11: comm mount.lustre: deleted inode referenced: 627060537^M
[2021-03-10T15:31:39-08:00] [29914.793611] LDISKFS-fs error (device dm-4): ldiskfs_lookup:1817: inode #11: comm mount.lustre: deleted inode referenced: 627060539^M
[2021-03-10T15:31:39-08:00] [29914.806965] LDISKFS-fs error (device dm-4): ldiskfs_lookup:1817: inode #11: comm mount.lustre: deleted inode referenced: 627060540^M
[2021-03-10T15:31:39-08:00] [29914.820521] LDISKFS-fs error (device dm-4): ldiskfs_lookup:1817: inode #11: comm mount.lustre: deleted inode referenced: 627060542^M
[2021-03-10T15:31:39-08:00] [29914.834339] LDISKFS-fs error (device dm-4): ldiskfs_lookup:1817: inode #11: comm mount.lustre: deleted inode referenced: 627060544^M
[2021-03-10T15:31:39-08:00] [29914.978593] Lustre: 8962:0:(obd_config.c:1641:class_config_llog_handler()) Skip config outside markers, (inst: 0000000000000000, uuid: , flags: 0x0)^M
[2021-03-10T15:31:39-08:00] [29914.993510] LustreError: 8962:0:(genops.c:556:class_register_device()) oak-OST0133-osc-MDT0001: already exists, won't add^M
[2021-03-10T15:31:39-08:00] [29915.005744] LustreError: 8962:0:(obd_config.c:1835:class_config_llog_handler()) MGC10.0.2.51@o2ib5: cfg command failed: rc = -17^M
[2021-03-10T15:31:39-08:00] [29915.018654] Lustre:    cmd=cf001 0:oak-OST0133-osc-MDT0001  1:osp  2:oak-MDT0001-mdtlov_UUID  ^M
[2021-03-10T15:31:39-08:00] [29915.018654] ^M
[2021-03-10T15:31:39-08:00] [29915.029929] LustreError: 3800:0:(mgc_request.c:599:do_requeue()) failed processing log: -17^M
[2021-03-10T15:31:39-08:00] [29915.036492] LustreError: 8949:0:(llog.c:1398:llog_backup()) MGC10.0.2.51@o2ib5: failed to open backup logfile oak-MDT0000T: rc = -30^M
[2021-03-10T15:31:39-08:00] [29915.036495] LustreError: 8949:0:(mgc_request.c:1879:mgc_llog_local_copy()) MGC10.0.2.51@o2ib5: failed to copy remote log oak-MDT0000: rc = -30^M
[2021-03-10T15:31:39-08:00] [29915.046574] Lustre: oak-MDT0000: Not available for connect from 10.51.3.5@o2ib3 (not set up)^M
[2021-03-10T15:31:39-08:00] [29915.076247] LustreError: 8963:0:(tgt_lastrcvd.c:1133:tgt_client_del()) oak-MDT0000: failed to update server data, skip client 9925e6e6-5de6-4 zeroing, rc -30^M
[2021-03-10T15:31:39-08:00] [29915.127660] LustreError: 8963:0:(obd_config.c:559:class_setup()) setup oak-MDT0000 failed (-30)^M
[2021-03-10T15:31:39-08:00] [29915.137373] Lustre:    cmd=cf003 0:oak-MDT0000  1:oak-MDT0000_UUID  2:0  3:oak-MDT0000-mdtlov  4:f  ^M
[2021-03-10T15:31:39-08:00] [29915.137373] ^M
[2021-03-10T15:31:39-08:00] [29915.149242] LustreError: 15c-8: MGC10.0.2.51@o2ib5: The configuration from log 'oak-MDT0000' failed (-30). This may be the result of communication errors between this node and the MGS, a bad configuration, or other errors. See the syslog for more information.^M
[2021-03-10T15:31:39-08:00] [29915.174853] LustreError: 8949:0:(obd_mount_server.c:1397:server_start_targets()) failed to start server oak-MDT0000: -30^M
[2021-03-10T15:31:39-08:00] [29915.187010] LustreError: 8949:0:(obd_mount_server.c:1992:server_fill_super()) Unable to start targets: -30^M
[2021-03-10T15:31:39-08:00] [29915.197797] LustreError: 8949:0:(obd_config.c:610:class_cleanup()) Device 316 not setup^M
[2021-03-10T15:31:39-08:00] [29915.315800] Lustre: server umount oak-MDT0000 complete^M
[2021-03-10T15:31:39-08:00] [29915.321537] LustreError: 8949:0:(obd_mount.c:1608:lustre_fill_super()) Unable to mount  (-30)^M

We have been running e2fsck -m 16 -f /dev/mapper/md1-rbod1-ssd-mdt0 for ~7 hours and pass1 is still not finished at this point (it's still running though). This MDT has 857,751,831 used inodes.

[root@oak-md1-s2 ~]# e2fsck -m 16 -y  /dev/mapper/md1-rbod1-ssd-mdt0
e2fsck 1.45.6.wc5 (09-Feb-2021)
oak-MDT0000 contains a file system with errors, check forced.
Pass 1: Checking inodes, blocks, and sizes
[Thread 0] Scan group range [0, 3552)
[Thread 1] Scan group range [3552, 7104)
[Thread 2] Scan group range [7104, 10656)
[Thread 3] Scan group range [10656, 14208)
[Thread 4] Scan group range [14208, 17760)
[Thread 5] Scan group range [17760, 21312)
[Thread 6] Scan group range [21312, 24864)
[Thread 7] Scan group range [24864, 28416)
[Thread 8] Scan group range [28416, 31968)
[Thread 9] Scan group range [31968, 35520)
[Thread 10] Scan group range [35520, 39072)
[Thread 11] Scan group range [39072, 42624)
[Thread 12] Scan group range [42624, 46176)
[Thread 13] Scan group range [46176, 49728)
[Thread 14] Scan group range [49728, 53280)
[Thread 15] Scan group range [53280, 57056)
[Thread 15] Scanned group range [53280, 57056), inodes 9005176
[Thread 3] Inode 459888758, i_size is 13547843328140, should be 0.  [Thread 3] Fix? yes

[Thread 14] Scanned group range [49728, 53280), inodes 59487037
[Thread 12] Scanned group range [42624, 46176), inodes 53210338
[Thread 2] Scanned group range [7104, 10656), inodes 61985386
[Thread 1] Scanned group range [3552, 7104), inodes 61737338
[Thread 11] Scanned group range [39072, 42624), inodes 62681960

This is our ldiskfs specs for oak-MDT0000:

[root@oak-md1-s2 ~]# dumpe2fs -h /dev/mapper/md1-rbod1-ssd-mdt0 
dumpe2fs 1.45.6.wc5 (09-Feb-2021)
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 mmp flex_bg dirdata sparse_super large_file huge_file uninit_bg dir_nlink quota project
Filesystem flags:         signed_directory_hash 
Default mount options:    user_xattr acl
Filesystem state:         clean with errors
Errors behavior:          Continue
Filesystem OS type:       Linux
Inode count:              1869611008
Block count:              934803456
Reserved block count:     46740172
Free blocks:              354807380
Free inodes:              1011859177
First block:              0
Block size:               4096
Fragment size:            4096
Reserved GDT blocks:      787
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:          Wed Mar 10 15:33:05 2021
Last write time:          Wed Mar 10 17:13:04 2021
Mount count:              17
Maximum mount count:      -1
Last checked:             Tue Sep 10 06:37:13 2019
Check interval:           0 (<none>)
Lifetime writes:          249 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
FS Error count:           16
First error time:         Wed Mar 10 15:31:38 2021
First error function:     ldiskfs_lookup
First error line #:       1817
First error inode #:      11
First error block #:      0
Last error time:          Wed Mar 10 15:32:03 2021
Last error function:      ldiskfs_lookup
Last error line #:        1817
Last error inode #:       11
Last error block #:       0
MMP block number:         13560
MMP update interval:      5
User quota inode:         3
Group quota inode:        4
Project quota inode:      325
Journal features:         journal_incompat_revoke
Journal size:             4096M
Journal length:           1048576
Journal sequence:         0x4343e81b
Journal start:            0
MMP_block:
    mmp_magic: 0x4d4d50
    mmp_check_interval: 5
    mmp_sequence: 0xe24d4d50
    mmp_update_date: Thu Mar 11 02:02:50 2021
    mmp_update_time: 1615456970
    mmp_node_name: oak-md1-s2
    mmp_device_name: /dev/mapper/md1-rbod1-ssd-mdt0

Issue Links

• is related to: LU-11578 ldiskfs_map_blocks: comm mdt00_100: l...

Comments

[Peter Jones]

Alex

What do you advise here?

Peter

[Alex Zhuravlev]

can you please check few inodes from the list:

914.752101] LDISKFS-fs error (device dm-4): ldiskfs_lookup:1817: inode #11: comm mount.lustre: deleted inode referenced: 627060535^M
[2021-03-10T15:31:38-08:00] [29914.766588] LDISKFS-fs error (device dm-4): ldiskfs_lookup:1817: inode #11: comm mount.lustre: deleted inode referenced: 627060536^M
[2021-03-10T15:31:38-08:00] [29914.779958] LDISKFS-fs error (device dm-4): ldiskfs_lookup:1817: inode #11: comm mount.lustre: deleted inode referenced: 627060537^M
[2021-03-10T15:31:39-08:00] [29914.793611] LDISKFS-fs error (device dm-4): ldiskfs_lookup:1817: inode #11: comm mount.lustre: deleted inode referenced: 627060539^M
[2021-03-10T15:31:39-08:00] [29914.806965] LDISKFS-fs error (device dm-4): ldiskfs_lookup:1817: inode #11: comm mount.lustre: deleted inode referenced: 627060540^M
[2021-03-10T15:31:39-08:00] [29914.820521] LDISKFS-fs error (device dm-4): ldiskfs_lookup:1817: inode #11: comm mount.lustre: deleted inode referenced: 627060542^M
[2021-03-10T15:31:39-08:00] [29914.834339] LDISKFS-fs error (device dm-4): ldiskfs_lookup:1817: inode #11: comm mount.lustre: deleted inode referenced: 627060544^M

using the following command as an example:

debugfs -c -R "stat <627060536>" /dev/dm-4{code{

[Stephane Thiell]

Thanks so much Alex. Attached deleted_inodes_debugfs.txt with the requested output.

User 20088 doesn't exist, but the group 3199 shown by debugfs matches my group (oak_ruthm) and this is the same group we used for the files originally migrated in 2.10. These are test files that could be deleted.

[Stephane Thiell]

There is also the very first one #459882777:

[root@oak-md1-s2 ~]# debugfs -c -R "stat <459882777>" /dev//mapper/md1-rbod1-ssd-mdt0
debugfs 1.45.6.wc5 (09-Feb-2021)
/dev//mapper/md1-rbod1-ssd-mdt0: catastrophic mode - not reading inode or group bitmaps
Inode: 459882777   Type: regular    Mode:  0660   Flags: 0x20000000
Generation: 529158975    Version: 0x000000d3:43f093fd
User: 20088   Group:  3199   Project:  3199   Size: 0
File ACL: 0
Links: 0   Blockcount: 0
Fragment:  Address: 0    Number: 0    Size: 0
 ctime: 0x59790e80:55a6db90 -- Wed Jul 26 14:49:52 2017
 atime: 0x5de59c63:00000000 -- Mon Dec  2 15:21:07 2019
 mtime: 0x59790e80:55a6db90 -- Wed Jul 26 14:49:52 2017
crtime: 0x59790e80:55a6db90 -- Wed Jul 26 14:49:52 2017
 dtime: 0x600765ed:(55a6db90) -- Tue Jan 19 15:06:21 2021
Size of extra inode fields: 32
Extended attributes:
  system.posix_acl_access (28) = 01 00 00 00 01 00 06 00 04 00 07 00 08 00 07 00 7f 0c 00 00 10 00 06 00 20 00 00 00 
  trusted.lma (24) = 00 00 00 00 00 00 00 00 64 2b 00 00 02 00 00 00 dd 32 01 00 00 00 00 00 
  lma: fid=[0x200002b64:0x132dd:0x0] compat=0 incompat=0
  trusted.lov (56)
  trusted.link (55)
  trusted.som (24) = 04 00 00 00 00 00 00 00 6a 00 00 00 00 00 00 00 08 00 00 00 00 00 00 00 
BLOCKS:

[Stephane Thiell]

Alex, does the following mean that OI Scrub was automatically triggered at mount time and tried to access inode #459882777 in lost+found? Do you know why?

[2021-03-10T15:31:38-08:00] [29914.734658] LustreError: 8949:0:(osd_scrub.c:1758:osd_ios_lookup_one_len()) Fail to find #459882777 in lost+found (11/0): rc = -5^M

Perhaps noscrub could help us mount the MDT? Of course, it would be better for e2fsck to complete, but it has been running for 16+ hours now and it's still at pass1 (9 out of 16 threads have completed as of now).

[Stephane Thiell]

This is what I have in lost+found from a previous fsck run (I think the one we did for LU-11578):

[root@oak-md1-s2 ~]# debugfs -c -R "ls -l /lost+found" /dev//mapper/md1-rbod1-ssd-mdt0
debugfs 1.45.6.wc5 (09-Feb-2021)
/dev//mapper/md1-rbod1-ssd-mdt0: catastrophic mode - not reading inode or group bitmaps
     11   40700 (2)      0      0   16384 13-Feb-2017 12:36 .
      2   40755 (2)      0      0    4096 28-Oct-2020 06:16 ..
 459800597  100640 (1)  282232   3199       0 13-Mar-2017 07:50 #459800597
 459802857  100674 (1)  282232   3199       5 27-Mar-2017 07:21 #459802857
 459846375  100660 (1)  275666   3325       0  1-Mar-2020 15:00 #459846375
 459855607  100600 (1)  282232   3199       0 18-Jun-2017 17:30 #459855607
 459855609  100660 (1)  282232   3199       0 18-Jun-2017 17:54 #459855609
 459882717  100660 (1)  277781   3360       0 20-Jan-2021 11:04 #459882717
 459882777  100660 (1)  20088   3199       0 26-Jul-2017 14:49 #459882777
 459901591  100644 (1)  282232   3199       0 10-Aug-2017 15:57 #459901591
 459903111  100660 (1)  282232   3199       0 24-Sep-2017 10:34 #459903111
 459919063  100640 (1)  282232   3199       0 28-Sep-2018 17:39 #459919063
 459941351  100640 (1)  282232   3199       0  8-Sep-2017 11:20 #459941351
 627060535  100644 (1)  20088   3199     654 26-Jul-2017 14:53 #627060535
 460450823  100750 (1)  282232   3199       0 26-Jul-2017 14:49 #460450823
 627060536  100644 (1)  20088   3199     677 26-Jul-2017 14:53 #627060536
 627060537  100644 (1)  20088   3199     715 26-Jul-2017 14:53 #627060537
 627060538  100644 (1)  282232   3199     521 26-Jul-2017 14:53 #627060538
 627060539  100644 (1)  20088   3199     522 26-Jul-2017 14:53 #627060539
 627060540  100644 (1)  20088   3199     982 26-Jul-2017 14:53 #627060540
 627060541  100644 (1)  282232   3199     999 26-Jul-2017 14:53 #627060541
 627060542  100644 (1)  20088   3199    1691 26-Jul-2017 14:53 #627060542
 627060543  100644 (1)  282232   3199    1450 26-Jul-2017 14:53 #627060543
 627060544  100664 (1)  20088   3199     107 26-Jul-2017 14:53 #627060544
 659619748  120777 (7)  282232   3199      59 26-Jul-2017 14:49 #659619748
 659619749  120777 (7)  282232   3199      63 26-Jul-2017 14:49 #659619749
 460451069  100750 (1)  282232   3199       0 26-Jul-2017 14:49 #460451069
 659619750  120777 (7)  282232   3199      62 26-Jul-2017 14:49 #659619750
 460451094  100750 (1)  282232   3199       0 26-Jul-2017 14:50 #460451094
 460451099  100750 (1)  282232   3199       0 26-Jul-2017 14:50 #460451099
 460451113  100750 (1)  282232   3199       0 26-Jul-2017 14:50 #460451113
 659619751  120777 (7)  282232   3199      59 26-Jul-2017 14:49 #659619751
 460451152  100640 (1)  282232   3199       0 26-Jul-2017 14:50 #460451152
 659619755  120777 (7)  282232   3199      54 26-Jul-2017 14:49 #659619755
 460451183  100640 (1)  282232   3199       0 26-Jul-2017 14:50 #460451183
 659619759  120777 (7)  282232   3199      58 26-Jul-2017 14:49 #659619759
 460451217  100640 (1)  282232   3199       0 26-Jul-2017 14:50 #460451217
 460451261  100640 (1)  282232   3199       0 26-Jul-2017 14:50 #460451261
 460451269  100640 (1)  282232   3199       0 26-Jul-2017 14:50 #460451269
 460451283  100640 (1)  282232   3199       0 26-Jul-2017 14:50 #460451283
 460451296  100640 (1)  282232   3199       0 26-Jul-2017 14:50 #460451296
 659619761  120777 (7)  282232   3199      52 26-Jul-2017 14:49 #659619761
 460451322  100640 (1)  282232   3199       0 26-Jul-2017 14:50 #460451322
 460451342  100640 (1)  282232   3199       0 26-Jul-2017 14:50 #460451342
 659619764  100640 (1)  282232   3199       0 26-Jul-2017 14:49 #659619764
 659627176  100640 (1)  282232   3199       0 26-Jul-2017 14:49 #659627176
 659627177  100640 (1)  282232   3199       0 26-Jul-2017 14:49 #659627177
 749413474  100660 (1)  343406   3623       0 24-Feb-2019 16:04 #749413474
      0       0 (0)      0      0       0                   
      0       0 (0)      0      0       0                   
      0       0 (0)      0      0       0                   

Most of them are owned by our group (3199) and are not important (so could be deleted). I'm a bit worried that the fsck on this MDT won't finish anytime soon, and I'm looking at our options, because this outage is affecting our researchers. Perhaps I would try to rename or delete #459882777 from lost+found? ldiskfs got -5 (EOI) when trying to access it though, that I don't know about.

[Stephane Thiell]

Current e2fsck status is as follow:

 

[root@oak-md1-s2 ~]# e2fsck -m 16 -y  /dev/mapper/md1-rbod1-ssd-mdt0
e2fsck 1.45.6.wc5 (09-Feb-2021)
oak-MDT0000 contains a file system with errors, check forced.
Pass 1: Checking inodes, blocks, and sizes
[Thread 0] Scan group range [0, 3552)
[Thread 1] Scan group range [3552, 7104)
[Thread 2] Scan group range [7104, 10656)
[Thread 3] Scan group range [10656, 14208)
[Thread 4] Scan group range [14208, 17760)
[Thread 5] Scan group range [17760, 21312)
[Thread 6] Scan group range [21312, 24864)
[Thread 7] Scan group range [24864, 28416)
[Thread 8] Scan group range [28416, 31968)
[Thread 9] Scan group range [31968, 35520)
[Thread 10] Scan group range [35520, 39072)
[Thread 11] Scan group range [39072, 42624)
[Thread 12] Scan group range [42624, 46176)
[Thread 13] Scan group range [46176, 49728)
[Thread 14] Scan group range [49728, 53280)
[Thread 15] Scan group range [53280, 57056)
[Thread 15] Scanned group range [53280, 57056), inodes 9005176
[Thread 3] Inode 459888758, i_size is 13547843328140, should be 0.  [Thread 3] Fix? yes


[Thread 14] Scanned group range [49728, 53280), inodes 59487037
[Thread 12] Scanned group range [42624, 46176), inodes 53210338
[Thread 2] Scanned group range [7104, 10656), inodes 61985386
[Thread 1] Scanned group range [3552, 7104), inodes 61737338
[Thread 11] Scanned group range [39072, 42624), inodes 62681960
[Thread 13] Scanned group range [46176, 49728), inodes 58501633
[Thread 10] Scanned group range [35520, 39072), inodes 66242954
[Thread 9] Scanned group range [31968, 35520), inodes 77570424 

There is no progress anymore.
I can see that a thread is blocked in a lock:

Thread 7 (Thread 0x7f90c6ffd700 (LWP 4352)):
#0  0x00007f90d37ef39e in pthread_rwlock_wrlock () from /lib64/libpthread.so.0
#1  0x000000000042d23b in e2fsck_write_inode ()
#2  0x000000000041915f in check_blocks ()
#3  0x000000000041c565 in e2fsck_pass1_run ()
#4  0x000000000041fa0f in e2fsck_pass1_thread ()
#5  0x00007f90d37ebea5 in start_thread () from /lib64/libpthread.so.0
#6  0x00007f90d351496d in clone () from /lib64/libc.so.6

the other threads seem to be doing something but it's unclear how long it will take:

Thread 6 (Thread 0x7f90c67fc700 (LWP 4353)):
#0  0x00007f90d356aa18 in __memmove_ssse3 () from /lib64/libc.so.6
#1  0x00000000004328d0 in insert_refcount_el ()
#2  0x0000000000432cf9 in ea_refcount_store ()
#3  0x0000000000419f92 in check_blocks ()
#4  0x000000000041a80b in process_inodes.part.45 ()
#5  0x000000000041c290 in e2fsck_pass1_run ()
#6  0x000000000041fa0f in e2fsck_pass1_thread ()
#7  0x00007f90d37ebea5 in start_thread () from /lib64/libpthread.so.0
#8  0x00007f90d351496d in clone () from /lib64/libc.so.6

I would like to try my idea of getting mounting the filesystem as ldiskfs and getting rid of old inodes from lost+found. The filesystem state is clean with errors, so I guess I can do it. Then, I would start it as lustre again. It would be nice to have your advise on this plan. Thanks!

[Alex Zhuravlev]

what exact version of Lustre you're using now?

[Stephane Thiell]

Lustre 2.12.6 + only 1 patch (LU-13609 mgs: fix config_log buffer handling)

[Alex Zhuravlev]

one (relatively fast, but a bit risky) option is to modify those inodes to "undelete" them.
if dtime is set to 0 and nlink is set to 0, then ldiskfs shouldn't complain about deleted inodes, AFAICS.
debugfs has a command to do that interactively:

# debugfs -w <your device>
debugfs:  mi <11>
                          Mode    [040700] 
                       User ID    [0] 
                      Group ID    [0] 
                          Size    [12288] 
                 Creation time    [1615493043] 
             Modification time    [1615493043] 
                   Access time    [1615493043] 
                 Deletion time    [0] 0
                    Link count    [2] 2
              Block count high    [0] 
                   Block count    [24] 
                    File flags    [0x80000] 
                    Generation    [0x0] 
                      File acl    [0] 
           High 32bits of size    [0] 
              Fragment address    [0] 
               Direct Block #0    [127754] 
               Direct Block #1    [4] 
               Direct Block #2    [0] 
               Direct Block #3    [0] 
               Direct Block #4    [12] 
               Direct Block #5    [4388] 
               Direct Block #6    [0] 
               Direct Block #7    [0] 
               Direct Block #8    [0] 
               Direct Block #9    [0] 
              Direct Block #10    [0] 
              Direct Block #11    [0] 
                Indirect Block    [0] 
         Double Indirect Block    [0] 
         Triple Indirect Block    [0] 
debugfs:  

notice lines with "Link count" and "Deletion time"

[Stephane Thiell]

If there is an EIO on #459882777, I've been thinking trying this:

mount as ldiskfs
mv lost+found lost+found.old
mkdir lost+found
umount

mount as lustre

what do you think?

[Alex Zhuravlev]

this way the inodes mentioned by ldiskfs_lookup:1817 should become "normal" orphans and hopefully ldiskfs stop to remounting read-only.

[Alex Zhuravlev]

what do you think?

sounds like a good idea. unfortunately I don't remember all the details of OI scrub and can't guarantee it doesn't touch that but should be fine to try, IMO.

[Stephane Thiell]

Thanks Alex!

I was able to mount MDT0000 after renaming lost+found.

Mar 11 12:23:07 oak-md1-s2 kernel: Lustre: Lustre: Build Version: 2.12.6_1_g68bbfcf
Mar 11 12:23:08 oak-md1-s2 kernel: LDISKFS-fs (dm-2): warning: mounting fs with errors, running e2fsck is recommended
Mar 11 12:23:08 oak-md1-s2 kernel: LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,acl,no_mbcache,nodelalloc
Mar 11 12:23:08 oak-md1-s2 kernel: LustreError: 137-5: oak-MDT0001_UUID: not available for connect from 10.12.4.77@o2ib (no target). If you are running an HA pair check that the target is mounted on the other server.
...
Mar 11 12:24:12 oak-md1-s2 kernel: LustreError: Skipped 1411 previous similar messages
Mar 11 12:24:38 oak-md1-s2 kernel: Lustre: oak-MDT0000: Imperative Recovery not enabled, recovery window 300-900
Mar 11 12:24:38 oak-md1-s2 kernel: Lustre: oak-MDD0000: changelog on
Mar 11 12:24:38 oak-md1-s2 kernel: Lustre: oak-MDT0000: in recovery but waiting for the first client to connect
Mar 11 12:24:38 oak-md1-s2 kernel: Lustre: oak-MDT0000: Will be in recovery for at least 5:00, or until 1930 clients reconnect
Mar 11 12:24:38 oak-md1-s2 kernel: Lustre: oak-MDT0000: nosquash_nids set to 10.49.0.[11-12]@o2ib1 10.50.0.1@o2ib2 10.50.0.[11-12]@o2ib2 10.51.0.[1-2]@o2ib3 10.51.0.[11-18]@o2ib3 10.0.2.[1-3]@o2ib5 10.0.2.[51-58]@o2ib5 10.0.2.[66-77]@o2ib
Mar 11 12:24:38 oak-md1-s2 kernel: Lustre: oak-MDT0000: root_squash is set to 99:99

OI scrub is currently running, I'm waiting for it to complete to really confirm that we're good to go.

[root@oak-md1-s2 ~]# lctl get_param -n osd-ldiskfs.oak-MDT0000.oi_scrub
name: OI_scrub
magic: 0x4c5fd252
oi_files: 64
status: scanning
flags: recreated,inconsistent,auto,upgrade
param:
time_since_last_completed: N/A
time_since_latest_start: 1233 seconds
time_since_last_checkpoint: 33 seconds
latest_start_position: 12
last_checkpoint_position: 37267791
first_failure_position: N/A
checked: 25501392
updated: 4
failed: 0
prior_updated: 0
noscrub: 0
igif: 2
success_count: 0
run_time: 1233 seconds
average_speed: 20682 objects/sec
real-time_speed: 54703 objects/sec
current_position: 39489872
scrub_in_prior: no
scrub_full_speed: yes
partial_scan: no
lf_scanned: 0
lf_repaired: 0
lf_failed: 0

[Stephane Thiell]

OI Scrub has completed without error. Thanks for your help, Alex!

[root@oak-md1-s2 ~]# lctl get_param -n osd-ldiskfs.oak-MDT0000.oi_scrub
name: OI_scrub
magic: 0x4c5fd252
oi_files: 64
status: completed
flags:
param:
time_since_last_completed: 772 seconds
time_since_latest_start: 36738 seconds
time_since_last_checkpoint: 772 seconds
latest_start_position: 12
last_checkpoint_position: 1869611009
first_failure_position: N/A
checked: 857721498
updated: 4
failed: 0
prior_updated: 0
noscrub: 23216
igif: 3
success_count: 1
run_time: 35966 seconds
average_speed: 23848 objects/sec
real-time_speed: N/A
current_position: N/A
lf_scanned: 0
lf_repaired: 0
lf_failed: 0 

[Peter Jones]

Good news - thanks!