[LU-6528] permission denied over NFS (intermittent

• Type: Bug
• Resolution: Fixed
• Priority: Major
• Fix Version/s: Lustre 2.8.0
• Affects Version/s: Lustre 2.5.3
• Severity: 3
• Assignee: Lai Siyao
• Reporter: Frederik Ferner (Inactive)

Description

(This might be related to LU-5730 but as the symptoms are different, I'm opening a new ticket.)

Our users are

Issue Links

• is related to: LU-7630 permission denied over NFS
• is related to: LU-5730 intermittent I/O errors for some directories
• is related to: LU-13791 Capabilities are not effective

Comments

[Lai Siyao]

yes, it's fsuid that's used in permission check, and it looks like it's mistakenly set somewhere. I'm still checking related code, will update you later.

[Frederik Ferner (Inactive)]

Yes, 37058 is the owner of top_hT52pM and is the user id that I'm running the tests as:

[bnh65367@ws104 frederik-test]$ ls -lnd top_hT52pM
drwx--S---+ 8597 37058 111733 266240 May 11 12:01 top_hT52pM
[bnh65367@ws104 frederik-test]$ id
uid=37058(bnh65367) gid=37058(bnh65367) groups=37058(bnh65367),500(dcs),37900(dls_staff),37907(dls_sysadmin),37910(dls-softinst),37911(dls-i15),109216(nt11000_2) context=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023
[bnh65367@ws104 frederik-test]$ 

uid "1200328" is a random user where I don't recognise the name. Re-running the tests again shows the same mismatch but a different fsuid.

NFS root_squash is enabled, root user (uid=0) is mapped to nfsnobody (uid=65534).

Could you confirm which way round it is, is fsuid the user (apparently) trying to access the file system or is it the apparent owner of the file?

[Lai Siyao]

LustreError: 2723:0:(mdd_permission.c:310:__mdd_permission_internal()) permission denied, mode 45c0, fsuid 1200328, uid 37058

shows uid doesn't match, which is the cause permission is denied.

Could you help verify '37058' is owner of "top_hT52pM"? and which should be current test user too. Besides, could you find the user with uid "1200328"?

BTW, what's the status of NFS root_squash? and if it's enabled, what's the uid for root_squash?

[Frederik Ferner (Inactive)]

Latest dumps, collected with these debug flags on both MDS and client/NFS server:

trace super ioctl neterror warning dlmtrace error emerg ha rpctrace vfstrace config console lfsck

[Frederik Ferner (Inactive)]

After applying the patch we initially failed to reproduce it until today (possibly related to restarting the MDS?)

I have just reproduced it again, though /var/log/messages on the MDS server doesn't quite contain what I was expecting:

May 11 11:23:59 cs04r-sc-mds02-03 kernel: format at ldlm_pool.c:628:ldlm_pool_recalc doesn't end in newline
May 11 11:43:42 cs04r-sc-mds02-03 kernel: format at ldlm_pool.c:628:ldlm_pool_recalc doesn't end in newline
May 11 11:45:49 cs04r-sc-mds02-03 kernel: format at ldlm_pool.c:628:ldlm_pool_recalc doesn't end in newline
May 11 11:51:10 cs04r-sc-mds02-03 kernel: Lustre: MGS: non-config logname received: params
May 11 11:51:23 cs04r-sc-mds02-03 kernel: Lustre: MGS: non-config logname received: params
May 11 11:54:11 cs04r-sc-mds02-03 kernel: Lustre: MGS: non-config logname received: params
May 11 11:56:43 cs04r-sc-mds02-03 kernel: Lustre: MGS: non-config logname received: params
May 11 12:01:35 cs04r-sc-mds02-03 kernel: format at mdd_permission.c:310:__mdd_permission_internal doesn't end in newline

Ah, dmesg contained this:

LustreError: 2723:0:(mdd_permission.c:310:__mdd_permission_internal()) permission denied, mode 45c0, fsuid 1200328, uid 37058

I'll upload the dumps as well, but in case it matters, here is the output:

Traceback (most recent call last):
  File "/home/bnh65367/bin/LU-6528-reproducer1.sh", line 16, in <module>
    fd, pth = tempfile.mkstemp(prefix='script', dir=sub_dir)
  File "/usr/lib64/python2.6/tempfile.py", line 293, in mkstemp
    return _mkstemp_inner(dir, prefix, suffix, flags)
  File "/usr/lib64/python2.6/tempfile.py", line 228, in _mkstemp_inner
    fd = _os.open(file, flags, 0600)
OSError: [Errno 13] Permission denied: '/dls/p45/data/2015/cm12185-2/tmp/frederik-test/top_hT52pM/sub_GYZ7QL/script1IzmRI'

And this is what seems to be the relevant bit of syslog entries on the NFS server:

May 11 12:01:34 p45-storage kernel: nfsd: MKDIR(3)    40: 97010001 000038a5 0000bb99 00000002 00000674 00000000 sub_GYZ7QL
May 11 12:01:34 p45-storage kernel: nfsd: fh_verify(40: 97010001 000038a5 0000bb99 00000002 00000674 00000000)
May 11 12:01:34 p45-storage kernel: nfsd: fh_compose(exp 32c:b8e6/4555387 top_hT52pM/sub_GYZ7QL, ino=0)
May 11 12:01:34 p45-storage kernel: nfsd_dispatch: vers 3 proc 2
May 11 12:01:34 p45-storage kernel: nfsd: fh_verify(40: 97010001 000038a5 0000bb99 00000002 00004999 00000000)
May 11 12:01:35 p45-storage kernel: nfsd_dispatch: vers 3 proc 4
May 11 12:01:35 p45-storage kernel: nfsd: ACCESS(3)   40: 97010001 000038a5 0000bb99 00000002 00004999 00000000 0x1f
May 11 12:01:35 p45-storage kernel: nfsd: fh_verify(40: 97010001 000038a5 0000bb99 00000002 00004999 00000000)

As always, if you need more information, please ask.

[Lai Siyao]

The debug log lacks information, and I just uploaded a debug patch LU-6528_debug.diff, could you reproduce it again?

[Lai Siyao]

This is a debug patch which will print mode and id information upon permission deny, could you apply it on MDS and reproduce? BTW it looks like only "trace" is enabled in debug log, could you `lctl set_param debug="super ioctl neterror warning dlmtrace error emerg ha rpctrace vfstrace config console lfsck trace" during reproduce?

[Frederik Ferner (Inactive)]

could you verify that the test user has EXEC access right to all directories in "/dls/p45/data/2015/cm12185-2/tmp/frederik-test/top_D19Rnh"?

Yes, I've have checked and this is the case.

Thanks,
Frederik

[Lai Siyao]

The log shows lustre client .lookup_nd failed with -13, and it looks quite possible to be inside kernel function reconnect_path() when it finds a disconnected dentry:
1. ->get_parent() found parent.
2. ->get_name() found child dentry name.
3. ->lookup_one_len() on parent for this name failed with -EACCES, MDS log shows it doesn't have EXEC right to parent.

I'm not clear of the cause yet, but first could you verify that the test user has EXEC access right to all directories in "/dls/p45/data/2015/cm12185-2/tmp/frederik-test/top_D19Rnh"?

[Frederik Ferner (Inactive)]

Also, we are receiving an increasing number of reports from users who are trying to access files and directories written days ago and are receiving intermittent permission denied (for example when running ls). This is obviously much harder to debug as we are not (yet) able to reproduce at will...

[Frederik Ferner (Inactive)]

This is on our test file system, I believe it should be fairly quite at most times, so I don't think there are other clients creating files but I'm not absolutely sure.

I've noticed (now) that on the lustre client it seems the lnet/debug_mb was quite small (only 8) during the previous test, not sure if this meant that some of the interesting information has been overwritten, so I've increased this now (to 32) and repeated the test. I've verified that the string "setattr" now exists in the client dump file as well.

I'll upload the new dump files and /var/log/message from the lustre client/nfs server after reproducing it again: The error was

Traceback (most recent call last):
  File "/home/bnh65367/bin/LU-6528-reproducer1.sh", line 15, in <module>
    sub_dir = tempfile.mkdtemp(prefix='sub_', dir=top_dir)
  File "/usr/lib64/python2.6/tempfile.py", line 318, in mkdtemp
    _os.mkdir(file, 0700)
OSError: [Errno 13] Permission denied: '/dls/p45/data/2015/cm12185-2/tmp/frederik-test/top_D19Rnh/sub_4GFmt6'