Bug #55331
closedpjd failure (caused by xattr's value not consistent between auth MDS and replicate MDSes)
Added by Venky Shankar about 2 years ago. Updated over 1 year ago.
0%
Description
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'
Updated by Venky Shankar about 2 years ago
- Status changed from New to Triaged
- Assignee set to Milind Changire
- Labels (FS) task(medium) added
Milind, please take a look.
Updated by Milind Changire about 2 years 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
Updated by Milind Changire about 2 years ago
- Assignee changed from Milind Changire to Xiubo Li
Assigning to Xiubo for further investigation about which commit fixed this issue.
Updated by Jeff Layton about 2 years 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.
Updated by Xiubo Li almost 2 years 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
Updated by Xiubo Li almost 2 years 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
Updated by Xiubo Li almost 2 years 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
Updated by Xiubo Li almost 2 years 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
Updated by Xiubo Li almost 2 years 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.
Updated by Xiubo Li almost 2 years 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.
Updated by Xiubo Li almost 2 years ago
- Copied to Bug #55778: client: choose auth MDS for getxattr with the Xs caps added
Updated by Xiubo Li almost 2 years 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.
Updated by Xiubo Li almost 2 years 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
Updated by Venky Shankar almost 2 years ago
- Status changed from Fix Under Review to Pending Backport
Updated by Backport Bot almost 2 years ago
- Copied to Backport #56448: quincy: pjd failure (caused by xattr's value not consistent between auth MDS and replicate MDSes) added
Updated by Backport Bot almost 2 years ago
- Copied to Backport #56449: pacific: pjd failure (caused by xattr's value not consistent between auth MDS and replicate MDSes) added
Updated by Xiubo Li over 1 year ago
- Status changed from Pending Backport to Resolved