ceph: improve caps debugging output

This improves uniformity and exposes important sequence numbers.

Now looks like:

    <7>[   73.749563] ceph:           caps.c:4465 : [c9653bca-110b-4f70-9f84-5a195b205e9a 15290]  caps mds2 op export ino 20000000000.fffffffffffffffe inode 0000000008d2e5ea seq 0 iseq 0 mseq 0
    ...
    <7>[   73.749574] ceph:           caps.c:4102 : [c9653bca-110b-4f70-9f84-5a195b205e9a 15290]  cap 20000000000.fffffffffffffffe export to peer 1 piseq 1 pmseq 1
    ...
    <7>[   73.749645] ceph:           caps.c:4465 : [c9653bca-110b-4f70-9f84-5a195b205e9a 15290]  caps mds1 op import ino 20000000000.fffffffffffffffe inode 0000000008d2e5ea seq 1 iseq 1 mseq 1
    ...
    <7>[   73.749681] ceph:           caps.c:4244 : [c9653bca-110b-4f70-9f84-5a195b205e9a 15290]  cap 20000000000.fffffffffffffffe import from peer 2 piseq 686 pmseq 0
    ...
    <7>[  248.645596] ceph:           caps.c:4465 : [c9653bca-110b-4f70-9f84-5a195b205e9a 15290]  caps mds1 op revoke ino 20000000000.fffffffffffffffe inode 0000000008d2e5ea seq 2538 iseq 1 mseq 1

See also: "mds: add issue_seq to all cap messages" in ceph.git

See-also: https://tracker.ceph.com/issues/66704
Signed-off-by: Patrick Donnelly <pdonnell@redhat.com>

diff --git a/fs/ceph/caps.c b/fs/ceph/caps.c
index 88a674cf27a877bb7cd757013e6c3ee2947ef597..74ba310dfcc7ec652aabeb190e571d8bc6513c99 100644 (file)
--- a/fs/ceph/caps.c
+++ b/fs/ceph/caps.c
@@ -4085,8 +4085,7 @@ static void handle_cap_export(struct inode *inode, struct ceph_mds_caps *ex,
        struct ceph_cap *cap, *tcap, *new_cap = NULL;
        struct ceph_inode_info *ci = ceph_inode(inode);
        u64 t_cap_id;
-       unsigned mseq = le32_to_cpu(ex->migrate_seq);
-       unsigned t_issue_seq, t_mseq;
+       u32 t_issue_seq, t_mseq;
        int target, issued;
        int mds = session->s_mds;
 
@@ -4100,8 +4099,8 @@ static void handle_cap_export(struct inode *inode, struct ceph_mds_caps *ex,
                target = -1;
        }
 
-       doutc(cl, "%p %llx.%llx ci %p mds%d mseq %d target %d\n",
-             inode, ceph_vinop(inode), ci, mds, mseq, target);
+       doutc(cl, " cap %llx.%llx export to peer %d piseq %u pmseq %u\n",
+             ceph_vinop(inode), target, t_issue_seq, t_mseq);
 retry:
        down_read(&mdsc->snap_rwsem);
        spin_lock(&ci->i_ceph_lock);
@@ -4228,18 +4227,22 @@ static void handle_cap_import(struct ceph_mds_client *mdsc,
        u64 realmino = le64_to_cpu(im->realm);
        u64 cap_id = le64_to_cpu(im->cap_id);
        u64 p_cap_id;
+       u32 piseq = 0;
+       u32 pmseq = 0;
        int peer;
 
        if (ph) {
                p_cap_id = le64_to_cpu(ph->cap_id);
                peer = le32_to_cpu(ph->mds);
+               piseq = le32_to_cpu(ph->issue_seq);
+               pmseq = le32_to_cpu(ph->mseq);
        } else {
                p_cap_id = 0;
                peer = -1;
        }
 
-       doutc(cl, "%p %llx.%llx ci %p mds%d mseq %d peer %d\n",
-             inode, ceph_vinop(inode), ci, mds, mseq, peer);
+       doutc(cl, " cap %llx.%llx import from peer %d piseq %u pmseq %u\n",
+             ceph_vinop(inode), peer, piseq, pmseq);
 retry:
        cap = __get_cap_for_mds(ci, mds);
        if (!cap) {
@@ -4268,15 +4271,13 @@ retry:
                doutc(cl, " remove export cap %p mds%d flags %d\n",
                      ocap, peer, ph->flags);
                if ((ph->flags & CEPH_CAP_FLAG_AUTH) &&
-                   (ocap->seq != le32_to_cpu(ph->issue_seq) ||
-                    ocap->mseq != le32_to_cpu(ph->mseq))) {
+                   (ocap->seq != piseq ||
+                    ocap->mseq != pmseq)) {
                        pr_err_ratelimited_client(cl, "mismatched seq/mseq: "
                                        "%p %llx.%llx mds%d seq %d mseq %d"
                                        " importer mds%d has peer seq %d mseq %d\n",
                                        inode, ceph_vinop(inode), peer,
-                                       ocap->seq, ocap->mseq, mds,
-                                       le32_to_cpu(ph->issue_seq),
-                                       le32_to_cpu(ph->mseq));
+                                       ocap->seq, ocap->mseq, mds, piseq, pmseq);
                }
                ceph_remove_cap(mdsc, ocap, (ph->flags & CEPH_CAP_FLAG_RELEASE));
        }
@@ -4360,8 +4361,6 @@ void ceph_handle_caps(struct ceph_mds_session *session,
        bool close_sessions = false;
        bool do_cap_release = false;
 
-       doutc(cl, "from mds%d\n", session->s_mds);
-
        if (!ceph_inc_mds_stopping_blocker(mdsc, session))
                return;
 
@@ -4463,12 +4462,11 @@ void ceph_handle_caps(struct ceph_mds_session *session,
 
        /* lookup ino */
        inode = ceph_find_inode(mdsc->fsc->sb, vino);
-       doutc(cl, " op %s ino %llx.%llx inode %p\n", ceph_cap_op_name(op),
-             vino.ino, vino.snap, inode);
+       doutc(cl, " caps mds%d op %s ino %llx.%llx inode %p seq %u iseq %u mseq %u\n",
+          session->s_mds, ceph_cap_op_name(op), vino.ino, vino.snap, inode,
+          seq, issue_seq, mseq);
 
        mutex_lock(&session->s_mutex);
-       doutc(cl, " mds%d seq %lld cap seq %u\n", session->s_mds,
-             session->s_seq, (unsigned)seq);
 
        if (!inode) {
                doutc(cl, " i don't have ino %llx\n", vino.ino);