Ceph » CephFS

https://pulpito.ceph.com/vshankar-2023-06-15_04:58:28-fs-wip-vshankar-testing-20230614.124123-testing-default-smithi/7305053/

2023-06-15T06:33:23.297+0000 7fde93b16700 10 mds.2.cache.ino(0x3000000025b) add_waiter tag 2000000060000000 0x556a82096aa0 !ambig 1 !frozen 1 !freezing 1
2023-06-15T06:33:23.297+0000 7fde93b16700 15 mds.2.cache.ino(0x3000000025b) taking waiter here
2023-06-15T06:33:23.297+0000 7fde93b16700 10 mds.2.locker nudge_log (ifile lock->sync) on [inode 0x3000000025b [...2,head] /client.0/tmp/tmp.o8Xb5OZu0n/p8/db/d23/f28 auth v128 ap=2 snaprealm=0x556a8355cb40 DIRTYPARENT s=5984600 nl=2 n(v0 rc2023-06-15T06:33:20.586624+0000 b5984600 1=1+0) (ifile lock->sync) (iversion lock) cr={4941=0-12582912@1} caps={4941=pAsLsXsFcb/Fcr@18},l=4941 | ptrwaiter=0 request=1 lock=1 caps=1 remoteparent=1 dirtyparent=1 dirty=1 waiter=1 authpin=1 0x556a83664000]
2023-06-15T06:33:23.297+0000 7fde93b16700  7 mds.2.locker get_allowed_caps loner client.4941 allowed=pAsLsXsFc, xlocker allowed=pAsLsXsFc, others allowed=pAsLsXsFc on [inode 0x3000000025b [...2,head] /client.0/tmp/tmp.o8Xb5OZu0n/p8/db/d23/f28 auth v128 ap=2 snaprealm=0x556a8355cb40 DIRTYPARENT s=5984600 nl=2 n(v0 rc2023-06-15T06:33:20.586624+0000 b5984600 1=1+0) (ifile lock->sync) (iversion lock) cr={4941=0-12582912@1} caps={4941=pAsLsXsFcb/Fcr@18},l=4941 | ptrwaiter=0 request=1 lock=1 caps=1 remoteparent=1 dirtyparent=1 dirty=1 waiter=1 authpin=1 0x556a83664000]
2023-06-15T06:33:23.297+0000 7fde93b16700 20 mds.2.locker  client.4941 pending pAsLsXsFcb allowed pAsLsXsFc wanted Fcr
2023-06-15T06:33:23.297+0000 7fde93b16700  7 mds.2.locker    sending MClientCaps to client.4941 seq 19 new pending pAsLsXsFc was pAsLsXsFcb
2023-06-15T06:33:23.297+0000 7fde93b16700 20 mds.2.cache.ino(0x3000000025b) encode_cap_message pfile 0 pauth 0 plink 0 pxattr 0 mtime 2023-06-15T06:33:20.586624+0000 ctime 2023-06-15T06:33:20.586624+0000 change_attr 136
2023-06-15T06:33:23.297+0000 7fde93b16700 10 mds.2.12 send_message_client_counted client.4941 seq 6710 client_caps(revoke ino 0x3000000025b 1 seq 19 caps=pAsLsXsFc dirty=- wanted=Fcr follows 0 size 5984600/12582912 ts 1/18446744073709551615 mtime 2023-06-15T06:33:20.586624+0000 ctime 2023-06-15T06:33:20.586624+0000 change_attr 136 tws 1) v12
2023-06-15T06:33:23.297+0000 7fde93b16700  1 -- [v2:172.21.15.29:6832/1469037096,v1:172.21.15.29:6833/1469037096] --> 192.168.0.1:0/1731885576 -- client_caps(revoke ino 0x3000000025b 1 seq 19 caps=pAsLsXsFc dirty=- wanted=Fcr follows 0 size 5984600/12582912 ts 1/18446744073709551615 mtime 2023-06-15T06:33:20.586624+0000 ctime 2023-06-15T06:33:20.586624+0000 change_attr 136 tws 1) v12 -- 0x556a81dff180 con 0x556a81cc5c00
2023-06-15T06:33:23.297+0000 7fde93b16700 10 mds.2.locker eval done
2023-06-15T06:33:23.297+0000 7fde93b16700  1 -- [v2:172.21.15.29:6832/1469037096,v1:172.21.15.29:6833/1469037096] <== client.4941 192.168.0.1:0/1731885576 4980 ==== client_caps(update ino 0x3000000025b 1 seq 18 caps=pAsLsXsFc dirty=- wanted=- follows 0 size 5984600/12582912 ts 1/18446744073709551615 mtime 2023-06-15T06:33:20.586624+0000 ctime 2023-06-15T06:33:20.586624+0000 change_attr 136 tws 1) v12 ==== 260+0+0 (crc 0 0 0) 0x556a8282d180 con 0x556a81cc5c00
2023-06-15T06:33:23.297+0000 7fde93b16700  7 mds.2.locker handle_client_caps  on 0x3000000025b tid 0 follows 0 op update flags 0x0
2023-06-15T06:33:23.297+0000 7fde93b16700 20 mds.2.12 get_session have 0x556a81c89900 client.4941 192.168.0.1:0/1731885576 state open

The revoke request's seq is 19, while the cap update seq is 18. And this will miss updating the inode caps.