Ceph » CephFS

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

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.

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

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

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  

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.

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.

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.