Project

General

Profile

Bug #55331

pjd failure (caused by xattr's value not consistent between auth MDS and replicate MDSes)

Added by Venky Shankar 8 months ago. Updated 3 months ago.

Status:
Resolved
Priority:
Normal
Assignee:
Category:
Correctness/Safety
Target version:
% Done:

0%

Source:
Community (dev)
Tags:
backport_processed
Backport:
quincy, pacific
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
fs
Component(FS):
MDS
Labels (FS):
task(medium)
Pull request ID:
Crash signature (v1):
Crash signature (v2):

Description

This run: https://pulpito.ceph.com/vshankar-2022-04-11_12:24:06-fs-wip-vshankar-testing1-20220411-144044-testing-default-smithi/6786559/

None of the PRs in the branch seem to be causing this and its not easily reproducible.

pjd fails in:

2022-04-13T04:59:41.926 INFO:tasks.workunit.client.0.smithi167.stderr:+ ntest=80
2022-04-13T04:59:41.926 INFO:tasks.workunit.client.0.smithi167.stderr:+ expect u::r--,u:root:r-x,u:65531:rwx,g::r--,g:root:rw-,g:65532:rwx,m::rwx,o::r-- getfacl fstest_73fed23d6d34bccdc1d73b05e3d22103/fstest_da3b235a078085ef61f2cae3419311a2 access
2022-04-13T04:59:41.926 INFO:tasks.workunit.client.0.smithi167.stderr:+ e=u::r--,u:root:r-x,u:65531:rwx,g::r--,g:root:rw-,g:65532:rwx,m::rwx,o::r--
2022-04-13T04:59:41.926 INFO:tasks.workunit.client.0.smithi167.stderr:+ shift
2022-04-13T04:59:41.927 INFO:tasks.workunit.client.0.smithi167.stderr:++ /home/ubuntu/cephtest/mnt.0/client.0/tmp/tmp/../pjd-fstest-20090130-RC/tests/xacl/../../fstest getfacl fstest_73fed23d6d34bccdc1d73b05e3d22103/fstest_da3b235a078085ef61f2cae3419311a2 access
2022-04-13T04:59:41.927 INFO:tasks.workunit.client.0.smithi167.stderr:++ tail -1
2022-04-13T04:59:41.928 INFO:tasks.workunit.client.0.smithi167.stderr:+ r=u::r--,u:root:r-x,g::r--,g:root:rw-,m::r-x,o::r--
2022-04-13T04:59:41.928 INFO:tasks.workunit.client.0.smithi167.stderr:+ echo u::r--,u:root:r-x,g::r--,g:root:rw-,m::r-x,o::r--
2022-04-13T04:59:41.929 INFO:tasks.workunit.client.0.smithi167.stderr:+ egrep '^u::r--,u:root:r-x,u:65531:rwx,g::r--,g:root:rw-,g:65532:rwx,m::rwx,o::r--$'
2022-04-13T04:59:41.929 INFO:tasks.workunit.client.0.smithi167.stderr:+ '[' 1 -eq 0 ']'
2022-04-13T04:59:41.929 INFO:tasks.workunit.client.0.smithi167.stderr:+ echo 'not ok 80'


Related issues

Copied to CephFS - Bug #55778: client: choose auth MDS for getxattr with the Xs caps Resolved
Copied to CephFS - Backport #56448: quincy: pjd failure (caused by xattr's value not consistent between auth MDS and replicate MDSes) Resolved
Copied to CephFS - Backport #56449: pacific: pjd failure (caused by xattr's value not consistent between auth MDS and replicate MDSes) Resolved

History

#1 Updated by Venky Shankar 7 months ago

  • Status changed from New to Triaged
  • Assignee set to Milind Changire
  • Labels (FS) task(medium) added

Milind, please take a look.

#2 Updated by Milind Changire 7 months ago

Since the teuthology run used a kclient, I tried running 100 iterations of pjd.sh on the latest testing kernel 5.18.0-rc4+
(HEAD at commit 5efacacc980658c97571abb0ce2f1ffc0c242411 - ceph: try to queue a writeback if revoking fails)

No error encountered in any of the 100 iterations with the following script:

for ((test_num=1; test_num <= 100; test_num++)); do
    ${CEPH_SRC}/qa/workunits/suites/pjd.sh >& ~/pjd/pjd-test-kernel-5.18-rc4-$(printf "%03d" $test_num).log;
    if [ $? != 0 ]; then break; fi;
    sleep 1;
done

#3 Updated by Milind Changire 7 months ago

  • Assignee changed from Milind Changire to Xiubo Li

Assigning to Xiubo for further investigation about which commit fixed this issue.

#4 Updated by Jeff Layton 7 months ago

I don't think you have enough information to solve this:

It's not clear which test actually failed. pjdfstests contains hundreds of individual tests, and I'm not sure which one failed here. Looking at my pjdfstests tree, I don't even see any invocations of getfacl -- is this running a fork of the upstream tests?

In any case, the set -x output is not particularly helpful. We need a description of what this test is trying to do, and what went wrong. Without that, we'll just be guessing as to the cause.

#5 Updated by Xiubo Li 6 months ago

  • Status changed from Triaged to In Progress

It was failed in xacl test 80, from teuthology.log:

2022-04-13T04:59:41.925 INFO:tasks.workunit.client.0.smithi167.stderr:++ expr 79 + 1
2022-04-13T04:59:41.926 INFO:tasks.workunit.client.0.smithi167.stderr:+ ntest=80
2022-04-13T04:59:41.926 INFO:tasks.workunit.client.0.smithi167.stderr:+ expect u::r--,u:root:r-x,u:65531:rwx,g::r--,g:root:rw-,g:65532:rwx,m::rwx,o::r-- getfacl fstest_73fed23d6d34bccdc1d73b05e3d22103/fstest_da3b235a078085ef61f2cae3419311a2 access
2022-04-13T04:59:41.926 INFO:tasks.workunit.client.0.smithi167.stderr:+ e=u::r--,u:root:r-x,u:65531:rwx,g::r--,g:root:rw-,g:65532:rwx,m::rwx,o::r--
2022-04-13T04:59:41.926 INFO:tasks.workunit.client.0.smithi167.stderr:+ shift
2022-04-13T04:59:41.927 INFO:tasks.workunit.client.0.smithi167.stderr:++ /home/ubuntu/cephtest/mnt.0/client.0/tmp/tmp/../pjd-fstest-20090130-RC/tests/xacl/../../fstest getfacl fstest_73fed23d6d34bccdc1d73b05e3d22103/fstest_da3b235a078085ef61f2cae3419311a2 access
2022-04-13T04:59:41.927 INFO:tasks.workunit.client.0.smithi167.stderr:++ tail -1
2022-04-13T04:59:41.928 INFO:tasks.workunit.client.0.smithi167.stderr:+ r=u::r--,u:root:r-x,g::r--,g:root:rw-,m::r-x,o::r--
2022-04-13T04:59:41.928 INFO:tasks.workunit.client.0.smithi167.stderr:+ echo u::r--,u:root:r-x,g::r--,g:root:rw-,m::r-x,o::r--
2022-04-13T04:59:41.929 INFO:tasks.workunit.client.0.smithi167.stderr:+ egrep '^u::r--,u:root:r-x,u:65531:rwx,g::r--,g:root:rw-,g:65532:rwx,m::rwx,o::r--$'
2022-04-13T04:59:41.929 INFO:tasks.workunit.client.0.smithi167.stderr:+ '[' 1 -eq 0 ']'
2022-04-13T04:59:41.929 INFO:tasks.workunit.client.0.smithi167.stderr:+ echo 'not ok 80'
2022-04-13T04:59:41.929 INFO:tasks.workunit.client.0.smithi167.stderr:++ expr 80 + 1
2022-04-13T04:59:41.930 INFO:tasks.workunit.client.0.smithi167.stderr:+ ntest=81

From pjd test code, pjd-fstest-20090130-RC/tests/xacl/02.t:

133 expect 0 setfacl ${d0}/${n1} m 'u::r--,u:root:r-x,u:65531:rwx,g::r--,g:root:rw-,g:65532:rwx,m::rwx,o::r--'
134 expect EPERM -u 65531 -g 65532 chown ${d0}/${n1} 65531 65532
135 expect 0474 stat ${d0}/${n1} mode
136 expect 65533,65533 stat ${d0}/${n1} uid,gid
137 expect 'u::r--,u:root:r-x,u:65531:rwx,g::r--,g:root:rw-,g:65532:rwx,m::rwx,o::r--' getfacl ${d0}/${n1} access  

#6 Updated by Xiubo Li 6 months ago

Xiubo Li wrote:

It was failed in xacl test 80, from teuthology.log:

[...]

From pjd test code, pjd-fstest-20090130-RC/tests/xacl/02.t:

[...]

133 expect 0 setfacl ${d0}/${n1} m 'u::r--,u:root:r-x,u:65531:rwx,g::r--,g:root:rw-,g:65532:rwx,m::rwx,o::r--'

The mds.0 has received the setxattr request and succeeded:

2022-04-13T04:59:36.930+0000 7f6d1a92e700  1 -- [v2:172.21.15.173:6832/626268664,v1:172.21.15.173:6833/626268664] <== client.4755 v1:192.168.0.1:0/3849904474 244 ==== client_request(client.4755:2451 setxattr #0x1000000057d system.posix_acl_access 2022-04-13T04:59:36.930376+0000 caller_uid=0, caller_gid=0{0,}) v4 ==== 211+0+68 (unknown 73286752 0 1424359596) 0x56264b851080 con 0x56264b738800
2022-04-13T04:59:36.930+0000 7f6d1a92e700  4 mds.1.server handle_client_request client_request(client.4755:2451 setxattr #0x1000000057d system.posix_acl_access 2022-04-13T04:59:36.930376+0000 caller_uid=0, caller_gid=0{0,}) v4

...

2022-04-13T04:59:36.932+0000 7f6d1a92e700 10 mds.1.server journal_and_reply tracei 0x56264b95b080 tracedn 0
2022-04-13T04:59:36.932+0000 7f6d1a92e700 10 mds.1.locker set_xlocks_done on (ixattr xlock x=1 by 0x56264b730c00) [inode 0x1000000057d [2,head] /client.0/tmp/tmp/fstest_73fed23d6d34bccdc1d73b05e3d22103/fstest_da3b235a078085ef61f2cae3419311a2 auth{0=1} v20 pv25 ap=4 DIRTYPARENT s=0 n(v0 rc2022-04-13T04:59:31.928468+0000 1=1+0)->n(v0 rc2022-04-13T04:59:36.930376+0000 1=1+0) (iauth xlockdone x=1) (ixattr xlock x=1 by 0x56264b730c00) (iversion lock w=2 last_client=4755) caps={4755=pLsFscr/p@10} | ptrwaiter=0 request=2 lock=4 importingcaps=0 caps=1 dirtyparent=1 replicated=1 dirty=1 waiter=0 authpin=1 0x56264b95b080]
2022-04-13T04:59:36.932+0000 7f6d1a92e700 10 mds.1.server early_reply 0 ((0) Success) client_request(client.4755:2451 setxattr #0x1000000057d system.posix_acl_access 2022-04-13T04:59:36.930376+0000 caller_uid=0, caller_gid=0{0,}) v4
2022-04-13T04:59:36.932+0000 7f6d1a92e700 20 mds.1.server set_trace_dist snapid head

#7 Updated by Xiubo Li 6 months ago

Locally with the latest testing branch in ceph-client repo I can reproduce it:

Test Summary Report
-------------------
../pjd-fstest-20090130-RC/tests/xacl/02.t    (Wstat: 0 Tests: 80 Failed: 3)
  Failed tests:  9, 44, 80
Files=191, Tests=2286, 433 wallclock secs ( 3.29 usr  6.44 sys + 13.42 cusr 259.31 csys = 282.46 CPU)
Result: FAIL

#8 Updated by Xiubo Li 6 months ago

Another failure in xacl/04.t:

10412 Test Summary Report
10413 -------------------
10414 ../pjd-fstest-20090130-RC/tests/xacl/04.t (Wstat: 0 Tests: 53 Failed: 2)
10415   Failed tests:  8, 10
10416 Files=7, Tests=329, 38 wallclock secs ( 0.32 usr  0.77 sys +  1.48 cusr 32.66 csys = 35.23 CPU)
10417 Result: FAIL  

#9 Updated by Xiubo Li 6 months ago

Locally I have reproduce it again and found that for the setxattr when early reply the xattr version was dropped because there had no caps Xs was issued to the client:

1958 2022-05-26T14:19:53.210+0800 148d259f6700 10 mds.1.server journal_and_reply tracei 0x5603a0665080 tracedn 0
1959 2022-05-26T14:19:53.210+0800 148d259f6700 10 mds.1.locker set_xlocks_done on (ixattr xlock x=1 by 0x5603a02a9180) [inode 0x100000006cb [2,head] /a     /tmp/fstest_df999d6f866bf9ef6b403b636b062ad1/fstest_8b9853973b36418e9c7ebfbdd8603b05 auth{0=1} v29 pv33 ap=4 DIRTYPARENT s=0 n(v0 rc2022-05-26T14:     19:48.182217+0800 1=1+0) (iauth xlockdone x=1) (ixattr xlock x=1 by 0x5603a02a9180) (iversion lock w=2 last_client=4242) caps={4242=pLsFscr/p@5} |      request=2 lock=4 importingcaps=0 caps=1 dirtyparent=1 replicated=1 dirty=1 waiter=0 authpin=1 0x5603a0665080]
1960 2022-05-26T14:19:53.210+0800 148d259f6700 10 mds.1.server early_reply 0 ((0) Success) client_request(client.4242:3586 setxattr #0x100000006cb syst     em.posix_acl_access 2022-05-26T14:19:53.206408+0800 caller_uid=0, caller_gid=0{0,}) v4                                                            
1961 2022-05-26T14:19:53.210+0800 148d259f6700 20 mds.1.server set_trace_dist snapid head
1962 2022-05-26T14:19:53.210+0800 148d259f6700 10 mds.1.server set_trace_dist snaprealm snaprealm(0x1 seq 1 lc 0 cr 0 cps 1 snaps={} past_parent_snaps=      0x5603a0003a00) len=48
1963 2022-05-26T14:19:53.210+0800 148d259f6700 20 mds.1.cache.ino(0x100000006cb)  pfile 0 pauth 1 plink 0 pxattr 1 plocal 1 ctime 2022-05-26T14:19:53.2     06408+0800 valid=1
1964 2022-05-26T14:19:53.210+0800 148d259f6700 10 mds.1.cache.ino(0x100000006cb) encode_inodestat issuing pLsFscr seq 6
1965 2022-05-26T14:19:53.210+0800 148d259f6700 10 mds.1.cache.ino(0x100000006cb) encode_inodestat caps pLsFscr seq 6 mseq 1 xattrv 4
1966 2022-05-26T14:19:53.210+0800 148d259f6700 10 mds.1.cache.ino(0x100000006cb) dropping xattrs version 4
1967 2022-05-26T14:19:53.210+0800 148d259f6700 20 mds.1.server set_trace_dist added in   [inode 0x100000006cb [2,head] /a/tmp/fstest_df999d6f866bf9ef6b     403b636b062ad1/fstest_8b9853973b36418e9c7ebfbdd8603b05 auth{0=1} v29 pv33 ap=4 DIRTYPARENT s=0 n(v0 rc2022-05-26T14:19:48.182217+0800 1=1+0) (iaut     h xlockdone x=1) (ixattr xlockdone x=1) (iversion lock w=2 last_client=4242) caps={4242=pLsFscr/p@6} | request=2 lock=4 importingcaps=0 caps=1 dir     typarent=1 replicated=1 dirty=1 waiter=0 authpin=1 0x5603a0665080]
1968 2022-05-26T14:19:53.210+0800 148d259f6700 10 mds.1.11 send_message_client client.4242 v1:10.72.47.117:0/3910359581 client_reply(???:3586 = 0 (0) S     uccess unsafe) v1
1969 2022-05-26T14:19:53.210+0800 148d259f6700  1 -- v1:10.72.47.117:6816/3246669422 --> v1:10.72.47.117:0/3910359581 -- client_reply(???:3586 = 0 (0)      Success unsafe) v1 -- 0x5603a06f1180 con 0x5603a0182000
1970 2022-05-26T14:19:53.210+0800 148d259f6700 20 mds.1.server lat 0.004183

The corresponding kernel logs, we can see that the xattr.ver was 3 before and after the setxattr and sent the request to mds.1:

 54238 <7>[165144.502096] ceph:  setxattr value=^B
 54239 <7>[165144.502194] ceph:  xattr.ver (before): 3
 54240 <7>[165144.502199] ceph:  do_request on 00000000657e3060
 54241 <7>[165144.502204] ceph:  submit_request on 00000000657e3060 for inode 0000000000000000
 54242 <7>[165144.502208] ceph:  reserve caps ctx=0000000041b33692 need=1
 54243 <7>[165144.502212] ceph:  reserve caps ctx=0000000041b33692 575 = 22 used + 1 resv + 552 avail
 54244 <7>[165144.502218] ceph:  __register_request 00000000657e3060 tid 3586
 54245 <7>[165144.502223] ceph:  __choose_mds 0000000089e5d4be is_hash=0 (0x0) mode 2
 54246 <7>[165144.502228] ceph:  __choose_mds 0000000089e5d4be 100000006cb.fffffffffffffffe mds1 (auth cap 0000000091c0a0bc)
 54247 <7>[165144.502237] ceph:  do_request mds1 session 00000000f3ef838c state open
 54248 <7>[165144.502242] ceph:  __prepare_send_request 00000000657e3060 tid 3586 setxattr (attempt 1)
 54249 <7>[165144.502248] ceph:   inode 0000000089e5d4be 100000006cb.fffffffffffffffe
 54250 <7>[165144.502253] ceph:   path system.posix_acl_access
 54251 <7>[165144.502360] ceph:  encode_inode_release 0000000089e5d4be mds1 used|dirty p drop Xs unless -
 54252 <7>[165144.502366] ceph:  encode_inode_release 0000000089e5d4be cap 0000000091c0a0bc pLsXsFscr -> pLsFscr, wanted p -> p
 54253 <7>[165144.502373] ceph:   r_parent = 0000000000000000
 54254 <7>[165144.502393] ceph:  do_request waiting
...
 54276 <7>[165144.504885] ceph:   mds1 cap 0000000091c0a0bc used p issued pLsFscr implemented pLsFscr revoking -
 54277 <7>[165144.507302] ceph:  handle_reply 00000000657e3060
 54278 <7>[165144.507308] ceph:  handle_reply tid 3586 result 0
 54279 <7>[165144.507317] ceph:  get_inode on 1099511629515=100000006cb.fffffffffffffffe got 0000000089e5d4be new 0
 54280 <7>[165144.507323] ceph:  ceph_update_snap_trace deletion=0
 54281 <7>[165144.507328] ceph:  __lookup_snap_realm 1 0000000030ac3707
 54282 <7>[165144.507333] ceph:  ceph_update_snap_trace 1 0000000030ac3707 seq 1 unchanged
 54283 <7>[165144.507337] ceph:  done with 1 0000000030ac3707, rebuild_snapcs=0, 00000000f41a93cf 00000000f41a93cf
 54284 <7>[165144.507344] ceph:  fill_trace 00000000657e3060 is_dentry 0 is_target 1
 54285 <7>[165144.507349] ceph:  ceph_fill_inode 0000000089e5d4be ino 100000006cb.fffffffffffffffe v 59 had 59
 54286 <7>[165144.507356] ceph:  get_cap ctx=0000000041b33692 (1) 575 = 22 used + 1 resv + 552 avail
 54287 <7>[165144.507363] ceph:  __ceph_caps_issued 0000000089e5d4be cap 00000000759edf18 issued pLsFscr
 54288 <7>[165144.507368] ceph:  __ceph_caps_issued 0000000089e5d4be cap 0000000091c0a0bc issued pLsFscr
 54289 <7>[165144.507373] ceph:  0000000089e5d4be mode 0100474 uid.gid 65533.65533
 54290 <7>[165144.507380] ceph:  add_cap 0000000089e5d4be mds1 cap 109 pLsFscr seq 6
 54291 <7>[165144.507386] ceph:  __ceph_caps_issued 0000000089e5d4be cap 00000000759edf18 issued pLsFscr
 54292 <7>[165144.507390] ceph:  __ceph_caps_issued 0000000089e5d4be cap 0000000091c0a0bc issued pLsFscr                                               
 54293 <7>[165144.507401] ceph:  add_cap inode 0000000089e5d4be (100000006cb.fffffffffffffffe) cap 0000000091c0a0bc pLsFscr now pLsFscr seq 6 mds1
 54294 <7>[165144.507408] ceph:  put_cap 00000000d77de720 575 = 23 used + 0 resv + 552 avail
 54295 <7>[165144.507413] ceph:  fill_trace done err=0
 54296 <7>[165144.507442] ceph:  do_request waited, got 0
 54297 <7>[165144.507451] ceph:  do_request 00000000657e3060 done, result 0
 54298 <7>[165144.507459] ceph:  xattr.ver (after): 3

The related code:

3973   // include those xattrs?
3974   if (xattr_version && cap) {
3975     if ((cap->pending() | getattr_caps) & CEPH_CAP_XATTR_SHARED) {
3976       dout(10) << "including xattrs version " << xattr_version << dendl;
3977       cap->client_xattr_version = xattr_version;
3978     } else {
3979       dout(10) << "dropping xattrs version " << xattr_version << dendl;
3980       xattr_version = 0;
3981     }
3982   }

And then later when the kclient fired a getxattr for _ it send the request to _mds.0 instead:

 54592 <7>[165144.587564] ceph:  getxattr 0000000089e5d4be name 'security.capability' ver=3 index_ver=3
 54593 <7>[165144.587573] ceph:  do_getattr inode 0000000089e5d4be mask Xs mode 0100474
 54594 <7>[165144.587580] ceph:  __ceph_caps_issued 0000000089e5d4be cap 00000000759edf18 issued pLsFscr
 54595 <7>[165144.587587] ceph:  __ceph_caps_issued 0000000089e5d4be cap 0000000091c0a0bc issued pLsFscr
 54596 <7>[165144.587645] ceph:  do_request on 00000000930a2150
 54597 <7>[165144.587652] ceph:  submit_request on 00000000930a2150 for inode 0000000000000000
 54598 <7>[165144.587658] ceph:  reserve caps ctx=0000000075e9e4a3 need=1
 54599 <7>[165144.587665] ceph:  reserve caps ctx=0000000075e9e4a3 575 = 22 used + 1 resv + 552 avail
 54600 <7>[165144.587672] ceph:  __register_request 00000000930a2150 tid 3587
 54601 <7>[165144.587679] ceph:  __choose_mds 0000000089e5d4be is_hash=0 (0x0) mode 0
 54602 <7>[165144.587688] ceph:  __choose_mds 0000000089e5d4be 100000006cb.fffffffffffffffe mds0 (cap 00000000759edf18)
 54603 <7>[165144.587700] ceph:  do_request mds0 session 000000004dd806f2 state open
 54604 <7>[165144.587708] ceph:  __prepare_send_request 00000000930a2150 tid 3587 getattr (attempt 1)
 54605 <7>[165144.587717] ceph:   inode 0000000089e5d4be 100000006cb.fffffffffffffffe
 54606 <7>[165144.587903] ceph:   r_parent = 0000000000000000
 54607 <7>[165144.587942] ceph:  do_request waiting
...
 54617 <7>[165149.240848] ceph:  __unregister_request 00000000930a2150 tid 3587
 54618 <7>[165149.240855] ceph:  handle_reply tid 3587 result 0
...
 54619 <7>[165149.240865] ceph:  get_inode on 1099511629515=100000006cb.fffffffffffffffe got 0000000089e5d4be new 0
 54620 <7>[165149.240874] ceph:  ceph_update_snap_trace deletion=0
 54621 <7>[165149.240881] ceph:  __lookup_snap_realm 1 0000000030ac3707
 54622 <7>[165149.240887] ceph:  ceph_update_snap_trace 1 0000000030ac3707 seq 1 unchanged
 54623 <7>[165149.240894] ceph:  done with 1 0000000030ac3707, rebuild_snapcs=0, 00000000c0acc9cf 00000000c0acc9cf
 54624 <7>[165149.240902] ceph:  fill_trace 00000000930a2150 is_dentry 0 is_target 1
 54625 <7>[165149.240908] ceph:  ceph_fill_inode 0000000089e5d4be ino 100000006cb.fffffffffffffffe v 66 had 59
 54626 <7>[165149.240917] ceph:  get_cap ctx=0000000075e9e4a3 (1) 575 = 22 used + 1 resv + 552 avail
 54627 <7>[165149.241037] ceph:  __ceph_caps_issued 0000000089e5d4be cap 00000000759edf18 issued pLsFscr
 54628 <7>[165149.241045] ceph:  __ceph_caps_issued 0000000089e5d4be cap 0000000091c0a0bc issued pLsFscr
 54629 <7>[165149.241052] ceph:  0000000089e5d4be mode 0100474 uid.gid 65533.65533
 54630 <7>[165149.241059] ceph:  add_cap 0000000089e5d4be mds0 cap f pAsLsXsFscr seq 10
 54631 <7>[165149.241067] ceph:  __ceph_caps_issued 0000000089e5d4be cap 00000000759edf18 issued pLsFscr
 54632 <7>[165149.241073] ceph:  __ceph_caps_issued 0000000089e5d4be cap 0000000091c0a0bc issued pLsFscr
 54633 <7>[165149.241080] ceph:  add_cap inode 0000000089e5d4be (100000006cb.fffffffffffffffe) cap 00000000759edf18 pAsLsXsFscr now pAsLsXsFscr seq 10        mds0
 54634 <7>[165149.241090] ceph:  put_cap 00000000d77de720 575 = 23 used + 0 resv + 552 avail
 54635 <7>[165149.241144] ceph:  fill_trace done err=0
 54636 <7>[165149.241270] ceph:  do_request waited, got 0
 54637 <7>[165149.241276] ceph:  do_request 00000000930a2150 done, result 0
 54638 <7>[165149.241444] ceph:  put_cap_refs 0000000089e5d4be had p
 54639 <7>[165149.241486] ceph:  do_getattr result=0
 54640 <7>[165149.241491] ceph:  __build_xattrs() len=87
 54641 <7>[165149.241497] ceph:  __get_xattr security.capability: not found

And from mds.0 it get the Xs caps, but still get the xattr.ver of 3. Then later when the test case fired a getfacl, which was translated to getxattr in kernel, since the Xs caps is already issued, so it will just use the old value for system.posix_acl_access:

 55524 <7>[165149.465441] ceph:  do_getattr inode 00000000927b91aa mask As mode 040777
 55525 <7>[165149.465448] ceph:  __ceph_caps_issued_mask ino 0x100000006ca cap 00000000598c8826 issued pAsLsXs (mask As)
 55526 <7>[165149.465457] ceph:  __touch_cap 00000000927b91aa cap 00000000598c8826 mds0
 55527 <7>[165149.465468] ceph:  d_revalidate 00000000f0e7713b 'fstest_8b9853973b36418e9c7ebfbdd8603b05' inode 0000000089e5d4be offset 0x0
 55528 <7>[165149.465478] ceph:  dentry_lease_is_valid - dentry 00000000f0e7713b = 1
 55529 <7>[165149.465484] ceph:  d_revalidate 00000000f0e7713b valid
 55530 <7>[165149.465538] ceph:  getxattr 0000000089e5d4be name 'system.posix_acl_access' ver=3 index_ver=3
 55531 <7>[165149.465549] ceph:  __ceph_caps_issued_mask ino 0x100000006cb cap 00000000759edf18 issued pAsLsXsFscr (mask Xs)
 55532 <7>[165149.465558] ceph:  __touch_cap 0000000089e5d4be cap 00000000759edf18 mds0
 55533 <7>[165149.465566] ceph:  __build_xattrs() len=87
 55534 <7>[165149.465573] ceph:  __get_xattr system.posix_acl_access: found ^B
 55535 <7>[165149.465630] ceph:  getxattr 0000000089e5d4be name 'system.posix_acl_access' ver=3 index_ver=3
 55536 <7>[165149.465639] ceph:  __ceph_caps_issued_mask ino 0x100000006cb cap 00000000759edf18 issued pAsLsXsFscr (mask Xs)
 55537 <7>[165149.465648] ceph:  __touch_cap 0000000089e5d4be cap 00000000759edf18 mds0                                                                
 55538 <7>[165149.465656] ceph:  __build_xattrs() len=87
 55539 <7>[165149.465662] ceph:  __get_xattr system.posix_acl_access: found ^B

The mds.1 journaled the new value for system.posix_acl_access but didn't notify mds.0, so when the mds.0 was issuing the Xs caps to kclient the mds.0 was still using the old value.

#10 Updated by Xiubo Li 6 months ago

We need to fix this in both client and ceph side:

1, in client side, we will always try to choose the auth MDS when getting the xattr to at least make it work for old ceph.

The kernel client fixing is here: https://patchwork.kernel.org/project/ceph-devel/list/?series=645451
And will fix it in libcephfs later.

2, in MDS side we need to notify the replica MDSes when values change for the setxattr.

#11 Updated by Xiubo Li 6 months ago

  • Copied to Bug #55778: client: choose auth MDS for getxattr with the Xs caps added

#12 Updated by Xiubo Li 6 months ago

Xiubo Li wrote:

We need to fix this in both client and ceph side:

1, in client side, we will always try to choose the auth MDS when getting the xattr to at least make it work for old ceph.

The kernel client fixing is here: https://patchwork.kernel.org/project/ceph-devel/list/?series=645451
And will fix it in libcephfs later.

Fixed the libcephfs and raised one dedicated tracker in https://tracker.ceph.com/issues/55778.

2, in MDS side we need to notify the replica MDSes when values change for the setxattr.

#13 Updated by Xiubo Li 6 months ago

  • Subject changed from pjd failure to pjd failure (caused by xattr's value not consistent between auth MDS and replicate MDSes)
  • Status changed from In Progress to Fix Under Review
  • Pull request ID set to 46472
  • ceph-qa-suite fs added
  • Component(FS) MDS added

#14 Updated by Venky Shankar 5 months ago

  • Status changed from Fix Under Review to Pending Backport

#15 Updated by Backport Bot 5 months ago

  • Copied to Backport #56448: quincy: pjd failure (caused by xattr's value not consistent between auth MDS and replicate MDSes) added

#16 Updated by Backport Bot 5 months ago

  • Copied to Backport #56449: pacific: pjd failure (caused by xattr's value not consistent between auth MDS and replicate MDSes) added

#17 Updated by Backport Bot 4 months ago

  • Tags set to backport_processed

#18 Updated by Xiubo Li 3 months ago

  • Status changed from Pending Backport to Resolved

Also available in: Atom PDF