[LU-14864] osd_fid_lookup() ASSERTION( !updated ) failed Created: 19/Jul/21  Updated: 01/Apr/23

Status: Open
Project: Lustre
Component/s: None
Affects Version/s: Lustre 2.11.0, Lustre 2.12.0, Lustre 2.13.0, Lustre 2.14.0
Fix Version/s: None

Type: Bug Priority: Major
Reporter: Etienne Aujames Assignee: Etienne Aujames
Resolution: Unresolved Votes: 0
Labels: None
Environment:

Lustre 2.12.6 with ldiskfs (with MDT0000 formatted in Lustre 2.7)

Attachments: Text File getinfo_fid2path.txt     Text File gf_root_fid.txt     Text File osd_device.txt     File vmcore-dk.log     Text File vmcore-dmesg.txt    
Issue Links:
Related
is related to LU-3934 Directories gone missing after 2.4 up... Resolved
is related to LU-3335 LFSCK II: MDT-OST OST local consisten... Resolved
is related to LU-9019 Migrate lustre to standard 64 bit tim... Resolved
is related to LU-16655 Files not accessible after 2.12 -> 2.... Resolved
Severity: 3
Rank (Obsolete): 9223372036854775807

 Description   

This crash has occurred in production.

A admin executed script sending fid2path requests with malformed FID. This caused the following crash on the MDT0000.

[65226.320307] LustreError: 24497:0:(osd_handler.c:1368:osd_fid_lookup()) ASSERTION( !updated ) failed: 
[65226.321549] LustreError: 24497:0:(osd_handler.c:1368:osd_fid_lookup()) LBUG
[65226.322160] Pid: 24497, comm: mdt00_004 3.10.0-1127.8.2.el7_lustre.x86_64 #1 SMP Mon Jun 8 13:48:45 UTC 2020
[65226.322161] Call Trace:
[65226.322171]  [<ffffffffc09c57cc>] libcfs_call_trace+0x8c/0xc0 [libcfs]
[65226.322180]  [<ffffffffc09c587c>] lbug_with_loc+0x4c/0xa0 [libcfs]
[65226.322184]  [<ffffffffc113c4e1>] osd_fid_lookup+0x17e1/0x1d90 [osd_ldiskfs]
[65226.322192]  [<ffffffffc113caf1>] osd_object_init+0x61/0x110 [osd_ldiskfs]
[65226.322198]  [<ffffffffc0c0d82b>] lu_object_start.isra.35+0x8b/0x120 [obdclass]
[65226.322221]  [<ffffffffc0c11744>] lu_object_find_at+0x234/0xab0 [obdclass]
[65226.322235]  [<ffffffffc0c11fd6>] lu_object_find+0x16/0x20 [obdclass]
[65226.322248]  [<ffffffffc12e146b>] mdt_object_find+0x4b/0x170 [mdt]
[65226.322259]  [<ffffffffc12ed0a5>] mdt_rpc_fid2path+0x4a5/0x17c0 [mdt]
[65226.322267]  [<ffffffffc12ee770>] mdt_get_info+0x3b0/0x490 [mdt]
[65226.322275]  [<ffffffffc0f5489a>] tgt_request_handle+0xada/0x1570 [ptlrpc]
[65226.322319]  [<ffffffffc0ef973b>] ptlrpc_server_handle_request+0x24b/0xab0 [ptlrpc]
[65226.322343]  [<ffffffffc0efd0a4>] ptlrpc_main+0xb34/0x1470 [ptlrpc]
[65226.322366]  [<ffffffffa2ac6691>] kthread+0xd1/0xe0
[65226.322369]  [<ffffffffa3192d37>] ret_from_fork_nospec_end+0x0/0x39
[65226.322372]  [<ffffffffffffffff>] 0xffffffffffffffff

 

After some troubleshooting, I was able to reproduce the issue on a 2.12.7.

Here are the following steps:

  1. Format filesystem (ldiskfs and mount FS
  2. umount MDT0000
  3. Mount MDT0000 as ldiskfs and modify OI_scrub file (binary) by clearing the SIF_NO_HANDLE_OLD_FID in sf_internal_flags
  4. Remount MDT0000 as lustre
  5. Get the inode number of  a Lustre system file:
    debugfs -c -R 'stat lfsck_layout' /dev/mapper/mds1_flakey
    Inode: 132 ....
  6. Execute fid2path with inode as FID (IGIF FID):
    lfs fid2path /media/lustrefs/client 0x84
  7. Crash

Dk log extracted from the crash:

00000004:00000040:0.0:1626701081.815693:0:24497:0:(mdt_handler.c:5736:mdt_object_init()) object init, fid = [0x84:0x0:0x0]
00000004:00000010:0.0:1626701081.815695:0:24497:0:(mdd_object.c:277:mdd_object_alloc()) slab-alloced 'mdd_obj': 96 at ffff9c86d6d6a120.
00000004:00000001:0.0:1626701081.815697:0:24497:0:(mdt_handler.c:5745:mdt_object_init()) Process leaving (rc=0 : 0 : 0)
00000004:00000001:0.0:1626701081.815698:0:24497:0:(mdd_object.c:299:mdd_object_init()) Process entered
00000004:00000001:0.0:1626701081.815699:0:24497:0:(lod_dev.c:212:lod_object_alloc()) Process entered
00000004:00000010:0.0:1626701081.815700:0:24497:0:(lod_dev.c:214:lod_object_alloc()) slab-alloced 'lod_obj': 152 at ffff9c8699f347b8.
00000004:00000001:0.0:1626701081.815701:0:24497:0:(lod_dev.c:224:lod_object_alloc()) Process leaving (rc=18446634700655249336 : -109373054302280 : ffff9c8699f347b8)
00000004:00000001:0.0:1626701081.815701:0:24497:0:(mdd_object.c:309:mdd_object_init()) Process leaving (rc=0 : 0 : 0)
00000004:00000001:0.0:1626701081.815703:0:24497:0:(lod_object.c:6967:lod_object_init()) Process entered
00000004:00000001:0.0:1626701081.815703:0:24497:0:(lod_dev.c:128:lod_fld_lookup()) Process entered
80000000:00000001:0.0:1626701081.815704:0:24497:0:(fld_handler.c:248:fld_server_lookup()) Process entered
80000000:00000001:0.0:1626701081.815704:0:24497:0:(fld_handler.c:212:fld_local_lookup()) Process entered
80000000:00000001:0.0:1626701081.815705:0:24497:0:(fld_cache.c:517:fld_cache_lookup()) Process entered
80000000:00000001:0.0:1626701081.815705:0:24497:0:(fld_cache.c:536:fld_cache_lookup()) Process leaving (rc=0 : 0 : 0)
80000000:00000001:0.0:1626701081.815706:0:24497:0:(fld_handler.c:229:fld_local_lookup()) Process leaving (rc=0 : 0 : 0)
80000000:00000001:0.0:1626701081.815706:0:24497:0:(fld_handler.c:252:fld_server_lookup()) Process leaving (rc=0 : 0 : 0)
00000004:00000040:0.0:1626701081.815707:0:24497:0:(lod_dev.c:169:lod_fld_lookup()) lustrefs-MDT0000-mdtlov: got tgt 0 for sequence: 0x84
00000004:00000001:0.0:1626701081.815708:0:24497:0:(lod_dev.c:171:lod_fld_lookup()) Process leaving (rc=0 : 0 : 0)
00080000:00000010:0.0:1626701081.815709:0:24497:0:(osd_handler.c:420:osd_object_alloc()) kmalloced '(mo)': 200 at ffff9c86d56fc400.
00000004:00000001:0.0:1626701081.815710:0:24497:0:(lod_object.c:7010:lod_object_init()) Process leaving (rc=0 : 0 : 0)
00080000:00000001:0.0:1626701081.815711:0:24497:0:(osd_handler.c:1142:osd_fid_lookup()) Process entered
00080000:00000001:0.0:1626701081.815712:0:24497:0:(osd_oi.c:576:fid_is_on_ost()) Process entered
00080000:00000001:0.0:1626701081.815712:0:24497:0:(osd_oi.c:584:fid_is_on_ost()) Process leaving (rc=0 : 0 : 0)
00080000:00000001:0.0:1626701081.815713:0:24497:0:(osd_handler.c:628:osd_iget_check()) Process entered
00080000:00000001:0.0:1626701081.815715:0:24497:0:(osd_handler.c:770:osd_iget_check()) Process leaving via put (rc=0 : 0 : 0x0)
00080000:00000001:0.0:1626701081.815715:0:24497:0:(osd_handler.c:854:osd_check_lma()) Process entered
00080000:00000001:0.0:1626701081.815722:0:24497:0:(osd_handler.c:929:osd_check_lma()) Process leaving (rc=18446744073709551538 : -78 : ffffffffffffffb2)
00080000:00000001:0.0:1626701081.815723:0:24497:0:(osd_oi.c:576:fid_is_on_ost()) Process entered
00080000:00000001:0.0:1626701081.815723:0:24497:0:(osd_oi.c:584:fid_is_on_ost()) Process leaving (rc=0 : 0 : 0)
00080000:00000001:0.0:1626701081.815723:0:24497:0:(osd_oi.c:576:fid_is_on_ost()) Process entered
00080000:00000001:0.0:1626701081.815723:0:24497:0:(osd_oi.c:584:fid_is_on_ost()) Process leaving (rc=0 : 0 : 0)
00080000:00000001:0.0:1626701081.815724:0:24497:0:(osd_handler.c:628:osd_iget_check()) Process entered
00080000:00000001:0.0:1626701081.815724:0:24497:0:(osd_handler.c:770:osd_iget_check()) Process leaving via put (rc=0 : 0 : 0x0)
00080000:00000001:0.0:1626701081.815725:0:24497:0:(osd_handler.c:854:osd_check_lma()) Process entered
00080000:00000001:0.0:1626701081.815725:0:24497:0:(osd_handler.c:929:osd_check_lma()) Process leaving (rc=18446744073709551538 : -78 : ffffffffffffffb2)
00080000:00040000:0.0:1626701081.815726:0:24497:0:(osd_handler.c:1368:osd_fid_lookup()) ASSERTION( !updated ) failed: 
00080000:00040000:0.0:1626701081.816969:0:24497:0:(osd_handler.c:1368:osd_fid_lookup()) LBUG

It appears that the flag SIF_NO_HANDLE_OLD_FID was not set in older versions of Lustre. In our case the FS was formatted in Lustre 2.7. But I checked some other filesystems with a Lustre's clusterstore version and they seem to be affected too.

This cause od_igif_inoi flag to not be set in osd_device.
And then the following code get the inode directly from the FID's sequence (as in Lustre 1.8 for IGIF FID):

int osd_oi_lookup(....
....
         if (!osd->od_igif_inoi && fid_is_igif(fid)) {              
                 osd_id_gen(id, lu_igif_ino(fid), lu_igif_gen(fid));
                 return 0;                                          
         }

Then osd_check_lma returns an error because FID in LMA and the current FID (IGIF: [0x84:0x0:0x0]) does not match: 

static int osd_check_lma(const struct lu_env *env, struct osd_object *obj)
......
         if (fid != NULL && unlikely(!lu_fid_eq(rfid, fid))) {                    
                 if (fid_is_idif(rfid) && fid_is_idif(fid)) {                     
                         ...................                                    
                 }                                                                
                                                                                  
                 rc = -EREMCHG;                                                   
         }                                                                        
 

 

 Comments   
Comment by Etienne Aujames [ 19/Jul/21 ]

This issue can be prevented by running oi_scrub 1 time on the MDT0000:

lctl lfsck_start -M lustrefs-MDT0000 -t scrub

This is the reason why:

osd_scrub_setup( ....
.....
         if (sf->sf_flags & SF_UPGRADE ||                           
             !(sf->sf_internal_flags & SIF_NO_HANDLE_OLD_FID ||     
    ------->   sf->sf_success_count > 0)) {                         
                 dev->od_igif_inoi = 0;                             
                 dev->od_check_ff = dev->od_is_ost;                 
         } else {                                                   
                 dev->od_igif_inoi = 1;                             
                 dev->od_check_ff = 0;                              
         }

 

Comment by Andreas Dilger [ 19/Jul/21 ]

It looks like this code has been in place since commit v2_4_92_0-66-g3ce87d9ab4 (2.5.0 release). Are you sure the filesystem wasn't formatted before 2.7.0? There definitely have not been IGIF FIDs in use since pre-2.0 releases, though I guess it is possible for IGIFs to be created for inodes that lose their trusted.lma xattr. In any case, running OI Scrub at least once is needed in this case to process all of the MDT inodes .

Comment by Etienne Aujames [ 20/Jul/21 ]

Hello Andreas,

All the filesystems affected (3) by the issue was formatted in Lustre 2.7.

I tested to format a filesystem in Lustre 2.7 and the SIF_NO_HANDLE_OLD_FID is set.

So I suspected that the flag was cleared during an upgrade.

Here what I have found (upgrade between 2.7 and 2.12.7):

scrub_file_load()) lustre-MDT0000: fail to load scrub file, expected = 408: rc = 400

scrub_file_load returns -EFAULT because the "struct scrub_file" change between 2.7 and 2.12.7.

Then the flag SIF_NO_HANDLE_OLD_FID is cleared by this code (OI_scrub is overwritten) : 

osd_scrub_setup( ....
.....
        rc = scrub_file_load(env, scrub);                                 
        if (rc == -ENOENT || rc == -EFAULT) {                             
                scrub_file_init(scrub, es->s_uuid);                       
                /* If the "/O" dir does not exist when mount (indicated by
                 * osd_device::od_maybe_new), neither for the "/OI_scrub",
                 * then it is quite probably that the device is a new one,
                 * under such case, mark it as SIF_NO_HANDLE_OLD_FID.     
                 *                                                        
                 * For the rare case that "/O" and "OI_scrub" both lost on
                 * an old device, it can be found and cleared later.      
                 *                                                        
                 * For the system with "SIF_NO_HANDLE_OLD_FID", we do not 
                 * need to check "filter_fid_18_23" and to convert it to  
                 * "filter_fid" for each object, and all the IGIF should  
                 * have their FID mapping in OI files already. */         
                if (dev->od_maybe_new && rc == -ENOENT)                   
                        sf->sf_internal_flags = SIF_NO_HANDLE_OLD_FID;    
                dirty = true;
         } else if (rc < 0) {                                             
.................
         if (dirty) {                              
                 rc = scrub_file_store(env, scrub);
                 if (rc)                           
                         GOTO(cleanup_obj, rc);    
         }

The patch that has changed the structure is https://review.whamcloud.com/29857 ("LU-9019 osd-ldiskfs: migrate to 64 bit time"):

-       __u32   sf_run_time;
+       /* How long the OI scrub has run in seconds. Do NOT change
+        * to time64_t since this breaks backwards compatibility.
+        * It shouldn't take more than 136 years to complete :-)
+        */
+       time_t  sf_run_time;

time_t is not 32bit size but 64bit (on x86_64):

crash> struct scrub_file -o              
struct scrub_file {                      
    [0] __u8 sf_uuid[16];                
   [16] __u64 sf_flags;                  
   [24] __u32 sf_magic;                  
   [28] __u16 sf_status;                 
   [30] __u16 sf_param;                  
   [32] time64_t sf_time_last_complete;  
   [40] time64_t sf_time_latest_start;   
   [48] time64_t sf_time_last_checkpoint;
   [56] __u64 sf_pos_latest_start;       
   [64] __u64 sf_pos_last_checkpoint;    
   [72] __u64 sf_pos_first_inconsistent; 
   [80] __u64 sf_items_checked;          
   [88] __u64 sf_items_updated;          
   [96] __u64 sf_items_failed;           
  [104] __u64 sf_items_updated_prior;    
  [112] __u64 sf_items_noscrub;          
  [120] __u64 sf_items_igif;             
  [128] time_t sf_run_time;              
  [136] __u32 sf_success_count;          
  [140] __u16 sf_oi_count;               
  [142] __u16 sf_internal_flags;         
  [144] __u32 sf_reserved_1;             
  [152] __u64 sf_reserved_2[16];         
  [280] __u8 sf_oi_bitmap[128];          
}                                        
SIZE: 408

This patch has landed on Lustre 2.11.0.

 

Generated at Sat Feb 10 03:13:26 UTC 2024 using Jira 9.4.14#940014-sha1:734e6822bbf0d45eff9af51f82432957f73aa32c.