Ceph » CephFS

Another instance, but this time another workunit: https://pulpito.ceph.com/vshankar-2023-05-12_08:25:27-fs-wip-vshankar-testing-20230509.090020-1-testing-default-smithi/7272434/

More detail call trace:

2023-05-12T09:01:09.193610+00:00 smithi112 kernel: libceph: loaded (mon/osd proto 15/24)
2023-05-12T09:01:09.238532+00:00 smithi112 kernel: ceph: loaded (mds proto 32)
2023-05-12T09:01:09.255186+00:00 smithi112 kernel: ceph: device name is missing path (no : separator in 1@0afa14a7-ddc9-42b4-9ff9-1cfaa5d42797.cephfs=/)
2023-05-12T09:01:09.273518+00:00 smithi112 kernel: libceph: mon2 (1)172.21.15.112:6790 session established
2023-05-12T09:01:09.273626+00:00 smithi112 kernel: libceph: client4661 fsid 0afa14a7-ddc9-42b4-9ff9-1cfaa5d42797
2023-05-12T09:01:09.296497+00:00 smithi112 kernel: ceph: mds0 session blocklisted
2023-05-12T09:02:29.608132+00:00 smithi112 kernel: WARNING: CPU: 3 PID: 132346 at fs/ceph/caps.c:690 ceph_add_cap+0x541/0x550 [ceph]
2023-05-12T09:02:29.608268+00:00 smithi112 kernel: Modules linked in: ceph libceph dns_resolver veth nft_chain_nat ipt_MASQUERADE nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 nft_compat nft_counter nf_tables nfnetlink bridge stp llc xfs libcrc32c intel_rapl_msr intel_rapl_common sb_edac x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm irqbypass crct10dif_pclmul crc32_pclmul iTCO_wdt iTCO_vendor_support ghash_clmulni_intel ipmi_ssif rapl joydev intel_cstate mei_me pcspkr intel_uncore wmi mei lpc_ich acpi_ipmi i2c_i801 ipmi_si ipmi_devintf ipmi_msghandler ioatdma sunrpc acpi_power_meter acpi_pad fuse dm_mod ext4 mbcache jbd2 sd_mod sg ast drm_vram_helper drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops drm_ttm_helper ahci ixgbe ttm libahci igb crc32c_intel drm nvme libata mdio i2c_algo_bit nvme_core dca t10_pi
2023-05-12T09:02:29.608317+00:00 smithi112 kernel: CPU: 3 PID: 132346 Comm: kworker/3:10 Kdump: loaded Not tainted 4.18.0-372.9.1.el8.x86_64 #1
2023-05-12T09:02:29.608352+00:00 smithi112 kernel: Hardware name: Supermicro SYS-5018R-WR/X10SRW-F, BIOS 2.0 12/17/2015
2023-05-12T09:02:29.608388+00:00 smithi112 kernel: Workqueue: ceph-msgr ceph_con_workfn [libceph]
2023-05-12T09:02:29.608423+00:00 smithi112 kernel: RIP: 0010:ceph_add_cap+0x541/0x550 [ceph]
2023-05-12T09:02:29.608448+00:00 smithi112 kernel: Code: c0 e8 7c ba f8 d0 0f 0b 44 89 7c 24 04 e9 82 fc ff ff 44 8b 7c 24 04 e9 68 fe ff ff 0f 0b e9 cd fc ff ff 0f 0b e9 0a fe ff ff <0f> 0b e9 12 fe ff ff 0f 0b 66 0f 1f 44 00 00 0f 1f 44 00 00 41 57
2023-05-12T09:02:29.608471+00:00 smithi112 kernel: RSP: 0018:ffffba17099e7a28 EFLAGS: 00010283
2023-05-12T09:02:29.608497+00:00 smithi112 kernel: RAX: 0000000000000075 RBX: 0000000000000000 RCX: dead000000000200
2023-05-12T09:02:29.608518+00:00 smithi112 kernel: RDX: ffff9a98539377d0 RSI: ffff9a98539377d0 RDI: ffff9a98539377c8
2023-05-12T09:02:29.608538+00:00 smithi112 kernel: RBP: ffff9a9a2eeb3970 R08: ffff9a98848a8be0 R09: 0000000000000001
2023-05-12T09:02:29.608562+00:00 smithi112 kernel: R10: ffff9a9a2eeb3970 R11: 00000000f06ee8fa R12: 0000000000002455
2023-05-12T09:02:29.608587+00:00 smithi112 kernel: R13: ffff9a98848a8780 R14: ffff9a98848a8788 R15: 0000000000000035
2023-05-12T09:02:29.608605+00:00 smithi112 kernel: FS:  0000000000000000(0000) GS:ffff9a9f9fcc0000(0000) knlGS:0000000000000000
2023-05-12T09:02:29.608624+00:00 smithi112 kernel: CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
2023-05-12T09:02:29.608646+00:00 smithi112 kernel: CR2: 000055b1c7d861a0 CR3: 0000000494410003 CR4: 00000000003706e0
2023-05-12T09:02:29.608667+00:00 smithi112 kernel: DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
2023-05-12T09:02:29.608686+00:00 smithi112 kernel: DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
2023-05-12T09:02:29.608704+00:00 smithi112 kernel: Call Trace:
2023-05-12T09:02:29.608722+00:00 smithi112 kernel: ceph_fill_inode+0xd0f/0xf50 [ceph]
2023-05-12T09:02:29.608741+00:00 smithi112 kernel: ceph_readdir_prepopulate+0x338/0xc50 [ceph]
2023-05-12T09:02:29.608759+00:00 smithi112 kernel: handle_reply+0x775/0x7b0 [ceph]
2023-05-12T09:02:29.608777+00:00 smithi112 kernel: mds_dispatch+0xa6/0x660 [ceph]
2023-05-12T09:02:29.608797+00:00 smithi112 kernel: ceph_con_process_message+0x79/0x140 [libceph]
2023-05-12T09:02:29.608815+00:00 smithi112 kernel: ? calc_signature+0xdb/0x100 [libceph]
2023-05-12T09:02:29.608833+00:00 smithi112 kernel: ceph_con_v1_try_read+0x5d7/0xf30 [libceph]
2023-05-12T09:02:29.608851+00:00 smithi112 kernel: ? __switch_to_asm+0x35/0x70
2023-05-12T09:02:29.608869+00:00 smithi112 kernel: ? __switch_to_asm+0x41/0x70
2023-05-12T09:02:29.608887+00:00 smithi112 kernel: ? __switch_to_asm+0x35/0x70
2023-05-12T09:02:29.608906+00:00 smithi112 kernel: ceph_con_workfn+0x329/0x680 [libceph]
2023-05-12T09:02:29.608924+00:00 smithi112 kernel: process_one_work+0x1a7/0x360
2023-05-12T09:02:29.608943+00:00 smithi112 kernel: worker_thread+0x30/0x390
2023-05-12T09:02:29.608962+00:00 smithi112 kernel: ? create_worker+0x1a0/0x1a0
2023-05-12T09:02:29.608981+00:00 smithi112 kernel: kthread+0x10a/0x120
2023-05-12T09:02:29.608999+00:00 smithi112 kernel: ? set_kthread_struct+0x40/0x40
2023-05-12T09:02:29.609018+00:00 smithi112 kernel: ret_from_fork+0x35/0x40
2023-05-12T09:02:29.609035+00:00 smithi112 kernel: ---[ end trace a0052b2a878e5e5f ]---
2023-05-12T12:02:03.904514+00:00 smithi112 kernel: ceph-brx: port 1(brx.0) entered disabled state
2023-05-12T12:02:03.932737+00:00 smithi112 kernel: device brx.0 left promiscuous mode

It's the stock kernel, not the upstream krenel testing branch.

And crashed in line#690:

 679                 /*
 680                  * auth mds of the inode changed. we received the cap export
 681                  * message, but still haven't received the cap import message.
 682                  * handle_cap_export() updated the new auth MDS' cap.
 683                  *
 684                  * "ceph_seq_cmp(seq, cap->seq) <= 0" means we are processing
 685                  * a message that was send before the cap import message. So
 686                  * don't remove caps.
 687                  */
 688                 if (ceph_seq_cmp(seq, cap->seq) <= 0) {
 689                         WARN_ON(cap != ci->i_auth_cap);
 690                         WARN_ON(cap->cap_id != cap_id);                                                                                                                                                                           
 691                         seq = cap->seq;
 692                         mseq = cap->mseq;
 693                         issued |= cap->issued;
 694                         flags |= CEPH_CAP_FLAG_AUTH;
 695                 }
 696         }

Okay, this morning I saw you have merged the PR https://github.com/ceph/ceph/pull/47752.

This issue should be introduced by commit https://github.com/ceph/ceph/pull/47752/commits/9fbde6da076f2d7c8bfde50c3f9e581e967c0df0, we just missed one case:

        MDS                                          Client
                                    Close fileX and remove and send cap release reqA to MDS.
Received reqA but deferred          Then immediately send reqB to MDS to open fileX
Received reqB and sends reply
                                    Add cap back
Handle reqA and removes cap

So for any new client request from client the MDS may will add a new cap with the different cap_id.

Xiubo Li wrote:

Okay, this morning I saw you have merged the PR https://github.com/ceph/ceph/pull/47752.

I was suspecting https://github.com/ceph/ceph/pull/49691 and dropped that from my test branch (but, not entirely for that reason).

Xiubo Li wrote:

Okay, this morning I saw you have merged the PR https://github.com/ceph/ceph/pull/47752.

This issue should be introduced by commit https://github.com/ceph/ceph/pull/47752/commits/9fbde6da076f2d7c8bfde50c3f9e581e967c0df0, we just missed one case:

[...]

So for any new client request from client the MDS may will add a new cap with the different cap_id.

Could you explain the reason for reqA to be deferred but the MDS processing reqB although its for the same dentry#? Are we seeing this in the failed MDS logs for the test where the kclient runs into this particular WARN_ON?

Venky Shankar wrote:

Xiubo Li wrote:

Okay, this morning I saw you have merged the PR https://github.com/ceph/ceph/pull/47752.

This issue should be introduced by commit https://github.com/ceph/ceph/pull/47752/commits/9fbde6da076f2d7c8bfde50c3f9e581e967c0df0, we just missed one case:

[...]

So for any new client request from client the MDS may will add a new cap with the different cap_id.

Could you explain the reason for reqA to be deferred but the MDS processing reqB although its for the same dentry#? Are we seeing this in the failed MDS logs for the test where the kclient runs into this particular WARN_ON?

Readed the logs again, just deferred by waiting the mds_lock, more exactly it's just a racy:

The kclient logs:

2023-05-12T09:47:33.603644+00:00 smithi063 kernel: ceph: handle_cap_import: mismatched seq/mseq: ino (1000000cc54.fffffffffffffffe) mds2 seq 2 mseq 1 importer mds0 has peer seq 1 mseq 1

And the MDS received a open request first:

2023-05-12T09:42:19.281+0000 7f31c8bb3700  1 -- [v2:172.21.15.63:6838/1664571178,v1:172.21.15.63:6839/1664571178] <== client.25175 v1:172.21.15.63:0/1856403233 26024 ==== client_request(client.25175:76943 open #0x1000000c673/rbtree_augmented.h 2023-05-12T09:42:19.272697+0000 caller_uid=1000, caller_gid=1265{6,36,1000,1265,}) v6 ==== 198+0+0 (unknown 752160367 0 0) 0x5589774f5b00 con 0x558970ab6400
...
2023-05-12T09:42:19.281+0000 7f31c8bb3700 20 mds.2.cache.den(0x1000000c673.100101* rbtree_augmented.h) add_client_lease client.25175 on (dn sync r=1)
2023-05-12T09:42:19.281+0000 7f31c8bb3700 20 mds.2.locker issue_client_lease seq 470 dur 30000ms  on [dentry #0x1/volumes/_nogroup/sv_1/da000437-0ef5-4084-a308-4f5607c7a833/client.0/tmp/t/linux-5.4/include/linux/rbtree_augmented.h [5,head] auth (dn sync l r=1) (dversion lock) v=2305 ap=1 ino=0x1000000cc54 state=1610612736 | lock=1 inodepin=1 replicated=0 dirty=1 authpin=1 clientlease=1 0x5589761d4280]
2023-05-12T09:42:19.281+0000 7f31c8bb3700 20 mds.2.cache.ino(0x1000000cc54)  pfile 1 pauth 1 plink 1 pxattr 1 plocal 0 mtime 2019-11-25T00:32:01.000000+0000 ctime 2023-05-12T09:41:14.930334+0000 change_attr 3 valid=1
2023-05-12T09:42:19.281+0000 7f31c8bb3700 10 mds.2.cache.ino(0x1000000cc54) encode_inodestat issuing pAsLsXsFscr seq 2
2023-05-12T09:42:19.281+0000 7f31c8bb3700 10 mds.2.cache.ino(0x1000000cc54) encode_inodestat caps pAsLsXsFscr seq 2 mseq 1 xattrv 1
2023-05-12T09:42:19.281+0000 7f31c8bb3700 10 mds.2.cache.ino(0x1000000cc54) including xattrs version 1
2023-05-12T09:42:19.281+0000 7f31c8bb3700 20 mds.2.server set_trace_dist added snap head in [inode 0x1000000cc54 [5,head] /volumes/_nogroup/sv_1/da000437-0ef5-4084-a308-4f5607c7a833/client.0/tmp/t/linux-5.4/include/linux/rbtree_augmented.h auth v2305 ap=1 DIRTYPARENT s=9835 n(v0 rc2019-11-25T00:32:01.000000+0000 b9835 1=1+0) (iauth sync r=1) (ixattr sync r=1) (iversion lock) caps={25175=pAsLsXsFscr/pFscr@2},l=25175 | ptrwaiter=0 request=1 lock=3 importingcaps=0 caps=1 dirtyparent=1 replicated=0 dirty=1 authpin=1 0x558978639600]
2023-05-12T09:42:19.281+0000 7f31c8bb3700 10 mds.2.20 send_message_client client.25175 v1:172.21.15.63:0/1856403233 client_reply(???:76943 = 0 (0) Success) v1
2023-05-12T09:42:19.281+0000 7f31c8bb3700  1 -- [v2:172.21.15.63:6838/1664571178,v1:172.21.15.63:6839/1664571178] --> v1:172.21.15.63:0/1856403233 -- client_reply(???:76943 = 0 (0) Success) v1 -- 0x558979a5ae00 con 0x558970ab6400
2023-05-12T09:42:19.281+0000 7f31c8bb3700  7 mds.2.cache request_finish request(client.25175:76943 nref=2 cr=0x5589774f5b00)

The open succeeded by increasing the seq to 2. And then the MDS received a cap release request:

2023-05-12T09:42:19.334+0000 7f31c8bb3700  1 -- [v2:172.21.15.63:6838/1664571178,v1:172.21.15.63:6839/1664571178] <== client.25175 v1:172.21.15.63:0/1856403233 26032 ==== client_cap_release(76) v2 ==== 1832+0+0 (unknown 2358920823 0 0) 0x558976400c60 con 0x558970ab6400
2023-05-12T09:42:19.334+0000 7f31c2ba7700 10 MDSContext::complete: 18C_MDS_openc_finish
...
2023-05-12T09:42:19.334+0000 7f31c8bb3700  1 -- [v2:172.21.15.63:6838/1664571178,v1:172.21.15.63:6839/1664571178] <== client.25175 v1:172.21.15.63:0/1856403233 26032 ==== client_cap_release(76) v2 ==== 1832+0+0 (unknown 2358920823 0 0) 0x558976400c60 con 0x558970ab6400
...
2023-05-12T09:42:19.334+0000 7f31c8bb3700  7 mds.2.locker _do_cap_release for client.25175 on [inode 0x1000000cc54 [5,head] /volumes/_nogroup/sv_1/da000437-0ef5-4084-a308-4f5607c7a833/client.0/tmp/t/linux-5.4/include/linux/rbtree_augmented.h auth v2305 DIRTYPARENT s=9835 n(v0 rc2019-11-25T00:32:01.000000+0000 b9835 1=1+0) (iversion lock) caps={25175=pAsLsXsFscr/pFscr@2},l=25175 | ptrwaiter=0 request=0 lock=0 importingcaps=0 caps=1 dirtyparent=1 replicated=0 dirty=1 authpin=0 0x558978639600]
2023-05-12T09:42:19.334+0000 7f31c8bb3700 10 mds.2.openfiles remove_inode [inode 0x1000000cc54 [5,head] /volumes/_nogroup/sv_1/da000437-0ef5-4084-a308-4f5607c7a833/client.0/tmp/t/linux-5.4/include/linux/rbtree_augmented.h auth v2305 DIRTYPARENT s=9835 n(v0 rc2019-11-25T00:32:01.000000+0000 b9835 1=1+0) (iversion lock) caps={25175=pAsLsXsFscr/pFscr@2},l=-1(25175) | ptrwaiter=0 request=0 lock=0 importingcaps=0 caps=1 dirtyparent=1 replicated=0 dirty=1 authpin=0 0x558978639600]
2023-05-12T09:42:19.334+0000 7f31c8bb3700 10 mds.2.cache.ino(0x1000000cc54) remove_client_cap last cap, leaving realm snaprealm(0x100000001fa seq 1 lc 0 cr 1 cps 2 snaps={} last_modified 0.000000 change_attr 0 0x558970942fc0)
2023-05-12T09:42:19.334+0000 7f31c8bb3700 10 mds.2.locker eval 3648 [inode 0x1000000cc54 [5,head] /volumes/_nogroup/sv_1/da000437-0ef5-4084-a308-4f5607c7a833/client.0/tmp/t/linux-5.4/include/linux/rbtree_augmented.h auth v2305 DIRTYPARENT s=9835 n(v0 rc2019-11-25T00:32:01.000000+0000 b9835 1=1+0) (iversion lock) | ptrwaiter=0 request=0 lock=0 importingcaps=0 caps=0 dirtyparent=1 replicated=0 dirty=1 authpin=0 0x558978639600]
2023-05-12T09:42:19.334+0000 7f31c8bb3700  7 mds.2.locker file_eval wanted= loner_wanted= other_wanted=  filelock=(ifile sync) on [inode 0x1000000cc54 [5,head] /volumes/_nogroup/sv_1/da000437-0ef5-4084-a308-4f5607c7a833/client.0/tmp/t/linux-5.4/include/linux/rbtree_augmented.h auth v2305 DIRTYPARENT s=9835 n(v0 rc2019-11-25T00:32:01.000000+0000 b9835 1=1+0) (iversion lock) | ptrwaiter=0 request=0 lock=0 importingcaps=0 caps=0 dirtyparent=1 replicated=0 dirty=1 authpin=0 0x558978639600]
2023-05-12T09:42:19.334+0000 7f31c8bb3700 10 mds.2.locker simple_eval (iauth sync) on [inode 0x1000000cc54 [5,head] /volumes/_nogroup/sv_1/da000437-0ef5-4084-a308-4f5607c7a833/client.0/tmp/t/linux-5.4/include/linux/rbtree_augmented.h auth v2305 DIRTYPARENT s=9835 n(v0 rc2019-11-25T00:32:01.000000+0000 b9835 1=1+0) (iversion lock) | ptrwaiter=0 request=0 lock=0 importingcaps=0 caps=0 dirtyparent=1 replicated=0 dirty=1 authpin=0 0x558978639600]
2023-05-12T09:42:19.334+0000 7f31c8bb3700 10 mds.2.locker simple_eval (ilink sync) on [inode 0x1000000cc54 [5,head] /volumes/_nogroup/sv_1/da000437-0ef5-4084-a308-4f5607c7a833/client.0/tmp/t/linux-5.4/include/linux/rbtree_augmented.h auth v2305 DIRTYPARENT s=9835 n(v0 rc2019-11-25T00:32:01.000000+0000 b9835 1=1+0) (iversion lock) | ptrwaiter=0 request=0 lock=0 importingcaps=0 caps=0 dirtyparent=1 replicated=0 dirty=1 authpin=0 0x558978639600]
2023-05-12T09:42:19.334+0000 7f31c8bb3700 10 mds.2.locker simple_eval (ixattr sync) on [inode 0x1000000cc54 [5,head] /volumes/_nogroup/sv_1/da000437-0ef5-4084-a308-4f5607c7a833/client.0/tmp/t/linux-5.4/include/linux/rbtree_augmented.h auth v2305 DIRTYPARENT s=9835 n(v0 rc2019-11-25T00:32:01.000000+0000 b9835 1=1+0) (iversion lock) | ptrwaiter=0 request=0 lock=0 importingcaps=0 caps=0 dirtyparent=1 replicated=0 dirty=1 authpin=0 0x558978639600]
2023-05-12T09:42:19.334+0000 7f31c8bb3700 10 mds.2.locker eval done

And the MDS just removed the cap.

I think the time seq should be:

        MDS                                          Client
                                    Close fileX and removes and queues cap release.
                                    Then immediately send reqB to MDS to open fileX
                                    Sends cap release reqA to MDS
Received reqB and succeeded
Received reqA and removes cap       Add cap back

Xiubo Li wrote:

Venky Shankar wrote:

Xiubo Li wrote:

Okay, this morning I saw you have merged the PR https://github.com/ceph/ceph/pull/47752.

This issue should be introduced by commit https://github.com/ceph/ceph/pull/47752/commits/9fbde6da076f2d7c8bfde50c3f9e581e967c0df0, we just missed one case:

[...]

So for any new client request from client the MDS may will add a new cap with the different cap_id.

Could you explain the reason for reqA to be deferred but the MDS processing reqB although its for the same dentry#? Are we seeing this in the failed MDS logs for the test where the kclient runs into this particular WARN_ON?

Readed the logs again, just deferred by waiting the mds_lock, more exactly it's just a racy:

OK - so the client did a close() and open() concurrently and the MDS received the open() request first.

The kclient logs:

[...]

And the MDS received a open request first:

[...]

The open succeeded by increasing the seq to 2. And then the MDS received a cap release request:

[...]

And the MDS just removed the cap.

I think the time seq should be:

[...]

So, the Capability data structure is not ref-counted and that out-of-order request caused the MDS to remove the cap. What is `Capability` is ref-counted? Would that fix the premature removal of caps?

Venky Shankar wrote:

Xiubo Li wrote:

Venky Shankar wrote:

Xiubo Li wrote:

Okay, this morning I saw you have merged the PR https://github.com/ceph/ceph/pull/47752.

This issue should be introduced by commit https://github.com/ceph/ceph/pull/47752/commits/9fbde6da076f2d7c8bfde50c3f9e581e967c0df0, we just missed one case:

[...]

So for any new client request from client the MDS may will add a new cap with the different cap_id.

Could you explain the reason for reqA to be deferred but the MDS processing reqB although its for the same dentry#? Are we seeing this in the failed MDS logs for the test where the kclient runs into this particular WARN_ON?

Readed the logs again, just deferred by waiting the mds_lock, more exactly it's just a racy:

OK - so the client did a close() and open() concurrently and the MDS received the open() request first.

No, the MDS received the close() first, but the client just queued and deferred releasing the caps back to MDS. Just the cap releasing came after the open() request.

The kclient logs:

[...]

And the MDS received a open request first:

[...]

The open succeeded by increasing the seq to 2. And then the MDS received a cap release request:

[...]

And the MDS just removed the cap.

I think the time seq should be:

[...]

So, the Capability data structure is not ref-counted and that out-of-order request caused the MDS to remove the cap. What is `Capability` is ref-counted? Would that fix the premature removal of caps?

This is none business with the ref IMO. Just before the fix https://github.com/ceph/ceph/pull/47752/commits/9fbde6da076f2d7c8bfde50c3f9e581e967c0df0 the client will drop the cap metadatas if it finds the corresponding cap entity has been released. And since the racy the MDS will keep waiting for a new release request with the matched seq, but the MDS will never get it since the client drop that to floor.

The fix https://github.com/ceph/ceph/pull/47752/commits/9fbde6da076f2d7c8bfde50c3f9e581e967c0df0 just missed the case in https://tracker.ceph.com/issues/61148#note-7.

More detail please https://github.com/ceph/ceph/pull/51500#issuecomment-1551141348.

Thanks.

Xiubo Li wrote:

Venky Shankar wrote:

Xiubo Li wrote:

Venky Shankar wrote:

Xiubo Li wrote:

Okay, this morning I saw you have merged the PR https://github.com/ceph/ceph/pull/47752.

This issue should be introduced by commit https://github.com/ceph/ceph/pull/47752/commits/9fbde6da076f2d7c8bfde50c3f9e581e967c0df0, we just missed one case:

[...]

So for any new client request from client the MDS may will add a new cap with the different cap_id.

Could you explain the reason for reqA to be deferred but the MDS processing reqB although its for the same dentry#? Are we seeing this in the failed MDS logs for the test where the kclient runs into this particular WARN_ON?

Readed the logs again, just deferred by waiting the mds_lock, more exactly it's just a racy:

OK - so the client did a close() and open() concurrently and the MDS received the open() request first.

No, the MDS received the close() first, but the client just queued and deferred releasing the caps back to MDS. Just the cap releasing came after the open() request.

The kclient logs:

[...]

And the MDS received a open request first:

[...]

The open succeeded by increasing the seq to 2. And then the MDS received a cap release request:

[...]

And the MDS just removed the cap.

I think the time seq should be:

[...]

So, the Capability data structure is not ref-counted and that out-of-order request caused the MDS to remove the cap. What is `Capability` is ref-counted? Would that fix the premature removal of caps?

This is none business with the ref IMO. Just before the fix https://github.com/ceph/ceph/pull/47752/commits/9fbde6da076f2d7c8bfde50c3f9e581e967c0df0 the client will drop the cap metadatas if it finds the corresponding cap entity has been released. And since the racy the MDS will keep waiting for a new release request with the matched seq, but the MDS will never get it since the client drop that to floor.

The fix https://github.com/ceph/ceph/pull/47752/commits/9fbde6da076f2d7c8bfde50c3f9e581e967c0df0 just missed the case in https://tracker.ceph.com/issues/61148#note-7.

More detail please https://github.com/ceph/ceph/pull/51500#issuecomment-1551141348.

I interpreted this as a premature release of a metadata structure that just needed to be held on till the last consumer had reference to it. Clearly, this is more of a race between release and revocation of caps.

Hit this again in Patrick's `fsstressh` relevant tests:

https://pulpito.ceph.com/pdonnell-2023-05-19_20:26:49-fs-wip-pdonnell-testing-20230519.164114-distro-default-smithi/7279578/
https://pulpito.ceph.com/pdonnell-2023-05-19_20:26:49-fs-wip-pdonnell-testing-20230519.164114-distro-default-smithi/7279686/

2023-05-20T07:52:27.820468+00:00 smithi064 kernel: [ 1042.020637] CPU: 6 PID: 53660 Comm: kworker/6:59 Tainted: G        W          6.4.0-rc2-g986861e56cea #1
2023-05-20T07:52:27.820469+00:00 smithi064 kernel: [ 1042.020645] Hardware name: Supermicro SYS-5018R-WR/X10SRW-F, BIOS 2.0 12/17/2015
2023-05-20T07:52:27.820470+00:00 smithi064 kernel: [ 1042.020652] Workqueue: ceph-msgr ceph_con_workfn [libceph]
2023-05-20T07:52:27.820470+00:00 smithi064 kernel: [ 1042.020708] RIP: 0010:ceph_add_cap+0x5ec/0x600 [ceph]
2023-05-20T07:52:27.820471+00:00 smithi064 kernel: [ 1042.020753] Code: c1 e8 98 6d f2 eb 0f 0b 44 89 7c 24 04 e9 fa fb ff ff 44 8b 7c 24 04 e9 fa fd ff ff 0f 0b e9 42 fc ff ff 0f 0b e9 a9 fd ff ff <0f> 0b e9 b1 fd ff ff 48 89 f1 31 c0 e9 12 fb ff ff 0f 0b 90 0f 1f
2023-05-20T07:52:27.820472+00:00 smithi064 kernel: [ 1042.020761] RSP: 0018:ffff98dc459ff9d8 EFLAGS: 00010283
2023-05-20T07:52:27.820473+00:00 smithi064 kernel: [ 1042.020772] RAX: 0000000000001a8a RBX: ffff89e145f56b98 RCX: ffff89df053b6c38
2023-05-20T07:52:27.820473+00:00 smithi064 kernel: [ 1042.020779] RDX: 0000000000000006 RSI: ffff89df4a104908 RDI: ffff89df4a1048f0
2023-05-20T07:52:27.820474+00:00 smithi064 kernel: [ 1042.020786] RBP: ffff89df4a104000 R08: ffff89df4a104938 R09: ffff89df4a104938
2023-05-20T07:52:27.820475+00:00 smithi064 kernel: [ 1042.020793] R10: 0000000000000000 R11: 0000000000000001 R12: 0000000000000d55
2023-05-20T07:52:27.820475+00:00 smithi064 kernel: [ 1042.020799] R13: ffff89df053b6c30 R14: 0000000000000002 R15: 0000000000000007
2023-05-20T07:52:27.820476+00:00 smithi064 kernel: [ 1042.020806] FS:  0000000000000000(0000) GS:ffff89e65fd80000(0000) knlGS:0000000000000000
2023-05-20T07:52:27.820477+00:00 smithi064 kernel: [ 1042.020814] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
2023-05-20T07:52:27.820477+00:00 smithi064 kernel: [ 1042.020821] CR2: 000055fc3c4ad000 CR3: 000000011b242001 CR4: 00000000001706e0
2023-05-20T07:52:27.820478+00:00 smithi064 kernel: [ 1042.020828] Call Trace:
2023-05-20T07:52:27.820479+00:00 smithi064 kernel: [ 1042.020836]  <TASK>
2023-05-20T07:52:27.820480+00:00 smithi064 kernel: [ 1042.020860]  ceph_fill_inode+0x100e/0x14a0 [ceph]
2023-05-20T07:52:27.820480+00:00 smithi064 kernel: [ 1042.020931]  ceph_fill_trace+0x175/0xd60 [ceph]
2023-05-20T07:52:27.820481+00:00 smithi064 kernel: [ 1042.020969]  ? __mutex_lock+0xaac/0xd00
2023-05-20T07:52:27.820482+00:00 smithi064 kernel: [ 1042.020985]  ? mds_dispatch+0xc70/0x1c00 [ceph]
2023-05-20T07:52:27.820482+00:00 smithi064 kernel: [ 1042.021032]  ? mds_dispatch+0xc85/0x1c00 [ceph]
2023-05-20T07:52:27.820483+00:00 smithi064 kernel: [ 1042.021092]  mds_dispatch+0xca8/0x1c00 [ceph]
2023-05-20T07:52:27.820484+00:00 smithi064 kernel: [ 1042.021150]  ? __mutex_unlock_slowpath+0x45/0x280
2023-05-20T07:52:27.820484+00:00 smithi064 kernel: [ 1042.021170]  ceph_con_process_message+0x78/0x160 [libceph]
2023-05-20T07:52:27.820485+00:00 smithi064 kernel: [ 1042.021223]  process_message+0xe/0x110 [libceph]
2023-05-20T07:52:27.820485+00:00 smithi064 kernel: [ 1042.021273]  ceph_con_v2_try_read+0xc57/0x1b60 [libceph]
2023-05-20T07:52:27.820486+00:00 smithi064 kernel: [ 1042.021327]  ? __mutex_lock+0x97/0xd00
2023-05-20T07:52:27.820487+00:00 smithi064 kernel: [ 1042.021336]  ? __mutex_lock+0xaac/0xd00
2023-05-20T07:52:27.820487+00:00 smithi064 kernel: [ 1042.021353]  ? ceph_con_workfn+0x2e/0x730 [libceph]
2023-05-20T07:52:27.820488+00:00 smithi064 kernel: [ 1042.021395]  ? lock_acquire+0xcc/0x2a0
2023-05-20T07:52:27.820489+00:00 smithi064 kernel: [ 1042.021405]  ? process_one_work+0x1be/0x500
2023-05-20T07:52:27.820489+00:00 smithi064 kernel: [ 1042.021425]  ceph_con_workfn+0x329/0x730 [libceph]
2023-05-20T07:52:27.820490+00:00 smithi064 kernel: [ 1042.021473]  process_one_work+0x238/0x500
2023-05-20T07:52:27.820491+00:00 smithi064 kernel: [ 1042.021495]  ? process_one_work+0x500/0x500
2023-05-20T07:52:27.820491+00:00 smithi064 kernel: [ 1042.021504]  worker_thread+0x56/0x3b0
2023-05-20T07:52:27.820492+00:00 smithi064 kernel: [ 1042.021518]  ? process_one_work+0x500/0x500
2023-05-20T07:52:27.820515+00:00 smithi064 kernel: [ 1042.021528]  kthread+0xf1/0x120
2023-05-20T07:52:27.820516+00:00 smithi064 kernel: [ 1042.021536]  ? kthread_complete_and_exit+0x20/0x20
2023-05-20T07:52:27.820517+00:00 smithi064 kernel: [ 1042.021549]  ret_from_fork+0x1f/0x30
2023-05-20T07:52:27.820518+00:00 smithi064 kernel: [ 1042.021583]  </TASK>
2023-05-20T07:52:27.820518+00:00 smithi064 kernel: [ 1042.021589] irq event stamp: 242995
2023-05-20T07:52:27.820519+00:00 smithi064 kernel: [ 1042.021594] hardirqs last  enabled at (243001): [<ffffffffad13151e>] __up_console_sem+0x5e/0x70
2023-05-20T07:52:27.820520+00:00 smithi064 kernel: [ 1042.021604] hardirqs last disabled at (243006): [<ffffffffad131503>] __up_console_sem+0x43/0x70