[LU-8015] Replication of operation failed(-22): 2885 HLINK (3)

• Status: Resolved
• Project: Lustre
• Affects Version/s: Lustre 2.9.0
• Fix Version/s: Lustre 2.9.0
• Type: Bug
• Priority: Minor
• Reporter: Jian Yu
• Assignee: Jian Yu
• Resolution: Fixed

Environment

Lustre Build: https://build.hpdd.intel.com/job/lustre-master/3343/

• Severity: 3

Description

I had a directory that contained two files (one is a hardlink of another):

# ls -il /hardlink/
total 120
163865 -rwxr-xr-x 2 root root 53400 Nov 11  2010 ed
163865 -rwxr-xr-x 2 root root 53400 Nov 11  2010 red

After copying the directory to a Lustre filesystem:

cp -a /hardlink /mnt/lustre/

Running lustre_rsync hit the following errors:

# lustre_rsync --source=/mnt/lustre/ --target=/mnt/backup/ --mdt=lustre-MDT0000 --user=cl1 --statuslog lustre_rsync.log --verbose
Lustre filesystem: lustre
MDT device: lustre-MDT0000
Source: /mnt/lustre/
Target: /mnt/backup/
Statuslog: lustre_rsync.log
Changelog registration: cl1
Starting changelog record: 0
Replication of operation failed(-22): 5 HLINK (3) [0x200000401:0x6e2:0x0] [0x200000401:0x6e1:0x0] ed
Replication of operation failed(-21): 6 SATTR (14) [0x200000401:0x6e1:0x0] [0x200000401:0x6e1:0x0] 
Errors: 2
lustre_rsync took 0 seconds
Changelog records consumed: 7

The type of the target filesystem /mnt/backup/ is ext4.

Comments

[Jian Yu]

The output (with "--debug 2" option) of lustre_rsync command, and the Lustre debug logs (with "debug=-1" level) for Client and MDS are attached.

[Jian Yu]

The detailed output of lustre_rsync command:

***** Start 5 HLINK (3) [0x200000401:0x6e2:0x0] [0x200000401:0x6e1:0x0] ed *****
	fid2path hardlink/red, ed, 0 rc=0
	fid2path hardlink/ed, ed, 1 rc=0
##### End 5 HLINK (3) [0x200000401:0x6e2:0x0] [0x200000401:0x6e1:0x0] ed rc=-22 #####

***** Start 6 SATTR (14) [0x200000401:0x6e1:0x0] [0x200000401:0x6e1:0x0]  *****
setattr: /mnt/lustre//.lustre/fid/[0x200000401:0x6e1:0x0] /mnt/backup//hardlink [0x200000401:0x6e1:0x0]
##### End 6 SATTR (14) [0x200000401:0x6e1:0x0] [0x200000401:0x6e1:0x0]  rc=-21 #####

Debug log on MDS:

00000004:20000000:0.0:1460512029.531552:0:31484:0:(mdt_hsm.c:345:mdt_hsm_state_set()) Incompatible flag change on [0x200000401:0x6e2:0x0]flags=0x2
00000004:00000001:0.0:1460512029.531554:0:31484:0:(mdt_hsm.c:346:mdt_hsm_state_set()) Process leaving via out_unlock (rc=18446744073709551594 : -22 : 0xffffffffffffffea)

Debug log on Client:

00000002:00000001:0.0:1460512029.686738:0:17272:0:(mdc_request.c:1703:mdc_ioc_hsm_state_set()) Process leaving via out (rc=18446744073709551594 : -22 : 0xffffffffffffffea)
<~snip~>
00000002:00000001:0.0:1460512029.686761:0:17272:0:(mdc_request.c:2075:mdc_iocontrol()) Process leaving via out (rc=18446744073709551594 : -22 : 0xffffffffffffffea)
00800000:00000001:0.0:1460512029.686763:0:17272:0:(obd_class.h:1143:obd_iocontrol()) Process leaving (rc=18446744073709551594 : -22 : ffffffffffffffea)
00800000:00000001:0.0:1460512029.686765:0:17272:0:(lmv_obd.c:1175:lmv_iocontrol()) Process leaving (rc=18446744073709551594 : -22 : ffffffffffffffea)
00000080:00000001:0.0:1460512029.686767:0:17272:0:(obd_class.h:1143:obd_iocontrol()) Process leaving (rc=18446744073709551594 : -22 : ffffffffffffffea)
00000080:00000010:0.0:1460512029.686768:0:17272:0:(llite_lib.c:2514:ll_finish_md_op_data()) kfreed 'op_data': 312 at ffff88004e3c0000.
00000080:00000001:0.0:1460512029.686770:0:17272:0:(file.c:2102:ll_hsm_state_set()) Process leaving (rc=18446744073709551594 : -22 : ffffffffffffffea)
00000080:00000040:0.0:1460512029.686772:0:17272:0:(llite_lib.c:1712:ll_setattr_raw()) [0x200000401:0x6e2:0x0]HSM set dirty failed: rc2 = -22
00000080:00000001:0.0:1460512029.686774:0:17272:0:(llite_lib.c:1715:ll_setattr_raw()) Process leaving

[Joseph Gmitter (Inactive)]

Hi Jian,

Is this something you can have a look at?

Thanks.
Joe

[Andreas Dilger]

Can you track down what the "Incompatible flag change" is? Is lustre_rsync trying to copy some HSM xattr from the source to the target?

[Jian Yu]

On Client side, the code path is ll_setattr()->ll_setattr_raw():

ll_setattr_raw()

        if (ll_file_test_and_clear_flag(lli, LLIF_DATA_MODIFIED)) {
                struct hsm_state_set hss = {
                        .hss_valid = HSS_SETMASK,
                        .hss_setmask = HS_DIRTY,
                };
                int rc2;

                rc2 = ll_hsm_state_set(inode, &hss); ------------------------------------- > ll_hsm_state_set() finally called mdc_ioc_hsm_state_set() and got -EINVAL from MDS side
                /* truncate and write can happen at the same time, so that
                 * the file can be set modified even though the file is not
                 * restored from released state, and ll_hsm_state_set() is
                 * not applicable for the file, and rc2 < 0 is normal in this
                 * case. */
                if (rc2 < 0)
                        CDEBUG(D_INFO, DFID "HSM set dirty failed: rc2 = %d\n",
                               PFID(ll_inode2fid(inode)), rc2);
        }

On MDS side, mdt_hsm_state_set() was called to handle the MDS_HSM_STATE_SET rpc from Client:

mdt_hsm_state_set()

        /* Check for inconsistant HSM flagset.
         * DIRTY without EXISTS: no dirty if no archive was created.
         * DIRTY and RELEASED: a dirty file could not be released.
         * RELEASED without ARCHIVED: do not release a non-archived file.
         * LOST without ARCHIVED: cannot lost a non-archived file.
         */
        flags = ma->ma_hsm.mh_flags;
        if ((flags & HS_DIRTY    && !(flags & HS_EXISTS)) ||
            (flags & HS_RELEASED && flags & HS_DIRTY) ||
            (flags & HS_RELEASED && !(flags & HS_ARCHIVED)) ||
            (flags & HS_LOST     && !(flags & HS_ARCHIVED))) {
                CDEBUG(D_HSM, "Incompatible flag change on "DFID
                              "flags="LPX64"\n",
                       PFID(&info->mti_body->mbo_fid1), flags);
                GOTO(out_unlock, rc = -EINVAL); -------------------------------------------> -EINVAL was returned to mdc_ioc_hsm_state_set() on Client side
        }

[Jian Yu]

There are two places where LLIF_DATA_MODIFIED is likely to be set. One is in vvp_io_write_start(), and the other is in vvp_io_setattr_fini().
From the Client debug log, we can see:

00000080:00000001:0.0:1460512029.678658:0:17272:0:(vvp_io.c:1060:vvp_io_write_start()) Process entered
00000080:00200000:0.0:1460512029.678660:0:17272:0:(vvp_io.c:1080:vvp_io_write_start()) write: [0, 53400)
<~snip~>
00000080:00200000:0.0:1460512029.681032:0:17272:0:(vvp_io.c:1131:vvp_io_write_start()) write: nob 53400, result: 53400
00000080:00000001:0.0:1460512029.681033:0:17272:0:(vvp_io.c:1144:vvp_io_write_start()) Process leaving (rc=0 : 0 : 0)

And also:

00000080:00200000:0.0:1460512029.681212:0:17272:0:(vvp_io.c:312:vvp_io_fini()) [0x200000401:0x6e2:0x0] ignore/verify layout 0/0, layout version 0 restore needed 0

The value after all of the "restore needed" messages is 0 in the debug log. So, LLIF_DATA_MODIFIED was only set in vvp_io_write_start(), not in vvp_io_setattr_fini(), and the file is not a restored file.

[Jian Yu]

According to the analysis in the above comments, we can see just checking LLIF_DATA_MODIFIED flag is not enough to make sure a file is a restored file. So, the following codes in ll_setattr_raw() need to be fixed:

ll_setattr_raw()

        /* If the file was restored, it needs to set dirty flag.
         *
         * We've already sent MDS_DATA_MODIFIED flag in
         * ll_md_setattr() for truncate. However, the MDT refuses to
         * set the HS_DIRTY flag on released files, so we have to set
         * it again if the file has been restored. Please check how
         * LLIF_DATA_MODIFIED is set in vvp_io_setattr_fini().
         *
         * Please notice that if the file is not released, the previous
         * MDS_DATA_MODIFIED has taken effect and usually
         * LLIF_DATA_MODIFIED is not set(see vvp_io_setattr_fini()).
         * This way we can save an RPC for common open + trunc
         * operation. */
        if (ll_file_test_and_clear_flag(lli, LLIF_DATA_MODIFIED)) {

[Jian Yu]

Hi Jinshan,

Could you please take a look at the above analysis to see whether it's in a correct direction? Thank you.

[Jinshan Xiong (Inactive)]

the race in ll_setattr_raw() should be normal and that error shouldn't be seen by user space applications.

[Jian Yu]

Jinshan is right. In the implementation of ll_setattr_raw(), the value of rc2 returned by ll_hsm_state_set() doesn't return to ll_setattr_raw(). However, in the experiment of ignoring the return value of ll_hsm_state_set(), the HLINK operation passed. Need investigate more.

[Jian Yu]

It turns out the "-EINVAL" error is another one returned from the following codes in lustre/utils/lustre_rsync.c:

lr_link()

                if (info->src[0] == 0 || info->dest[0] == 0)
                        /* Could not find the source or destination.
                         This can happen when some links don't exist
                         anymore. */
                        return -EINVAL;

And the defect is in the following codes:

lr_link()

                        len = strlen(info->path) - strlen(info->name);
                        if (len >= 0 && strcmp(info->path + len,
                                              info->name) == 0)
                                ......
                        else if (info->src[0] == 0)
                                ......

The above condition used to find out info->src and info->dest has defect in the following situations:
1) the source name ends with the destination name
2) the file has two links with the same name but in different directories

With the guidance from John and Jinshan, I'm creating a patch to fix the above issue.

[Gerrit Updater]

Jian Yu ([e-mail]) uploaded a new patch: http://review.whamcloud.com/19599
Subject: LU-8015 utils: fix lr_link() to get correct src and dest
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: 878a003b75d49606f124e16ef61ae4d620cd49c3

[Gerrit Updater]

Oleg Drokin ([e-mail]) merged in patch http://review.whamcloud.com/19599/
Subject: LU-8015 utils: fix lr_link() to get correct src and dest
Project: fs/lustre-release
Branch: master
Current Patch Set:
Commit: a72e6ee375248636cac1ea212d517254c8850b88

[Joseph Gmitter (Inactive)]

Landed to master for 2.9.0