mds: log session open stats

This is to assist with tracking what clients are connecting and how long it
takes for them to open a session (a rough estimate of how long it takes to
mount).

Example line:

    2018-12-17 17:21:31.682 7f822703c700  2 mds.0.server New client session: addr="127.0.0.1:60552/2307908923",elapsed=0.013384,throttled=0.000071,status="ACCEPTED",root="/"

Fixes: http://tracker.ceph.com/issues/37678
Signed-off-by: Patrick Donnelly <pdonnell@redhat.com>
(cherry picked from commit c89cd8cac16789ed98dc1487ec17f45adf03dd26)

Conflicts:
	src/mds/Server.cc
	src/mds/SessionMap.cc
	src/mds/SessionMap.h
	src/mds/events/ESession.h

diff --git a/src/mds/Server.cc b/src/mds/Server.cc
index e3fe19aa321d9c95491b5cdb83bc2079251a78d4..9d9b5f98256a46daa1eb7c0a768f4e5967280fef 100644 (file)
--- a/src/mds/Server.cc
+++ b/src/mds/Server.cc
@@ -354,8 +354,7 @@ void Server::handle_client_session(MClientSession *m)
       m->put();
       return;
     }
-    assert(session->is_closed() ||
-          session->is_closing());
+    assert(session->is_closed() || session->is_closing());
 
     if (mds->is_stopping()) {
       dout(10) << "mds is stopping, dropping open req" << dendl;
@@ -368,50 +367,86 @@ void Server::handle_client_session(MClientSession *m)
           return osd_map.is_blacklisted(session->info.inst.addr);
         });
 
-    if (blacklisted) {
-      dout(10) << "rejecting blacklisted client " << session->info.inst.addr << dendl;
-      mds->send_message_client(new MClientSession(CEPH_SESSION_REJECT), session);
-      m->put();
-      return;
-    }
+    {
+      auto& addr = session->info.inst.addr;
+      session->set_client_metadata(m->client_meta);
+      auto& client_metadata = session->info.client_metadata;
+
+      auto log_session_status = [this, m, session](boost::string_view status, boost::string_view err) {
+        auto now = ceph_clock_now();
+        auto throttle_elapsed = m->get_recv_complete_stamp() - m->get_throttle_stamp();
+        auto elapsed = now - m->get_recv_stamp();
+        std::stringstream ss;
+        ss << "New client session:"
+             << " addr=\"" <<  session->info.inst.addr << "\""
+             << ",elapsed=" << elapsed
+             << ",throttled=" << throttle_elapsed
+             << ",status=\"" << status << "\"";
+        if (!err.empty()) {
+          ss << ",error=\"" << err << "\"";
+        }
+        const auto& metadata = session->info.client_metadata;
+        auto it = metadata.find("root");
+        if (it != metadata.end()) {
+          ss << ",root=\"" << it->second << "\"";
+        }
+        dout(2) << ss.str() << dendl;
+      };
 
-    session->set_client_metadata(m->client_meta);
-    dout(20) << __func__ << " CEPH_SESSION_REQUEST_OPEN "
-      << session->info.client_metadata.size() << " metadata entries:" << dendl;
-    for (map<string, string>::iterator i = session->info.client_metadata.begin();
-        i != session->info.client_metadata.end(); ++i) {
-      dout(20) << "  " << i->first << ": " << i->second << dendl;
-    }
-
-    // Special case for the 'root' metadata path; validate that the claimed
-    // root is actually within the caps of the session
-    if (session->info.client_metadata.count("root")) {
-      const auto claimed_root = session->info.client_metadata.at("root");
-      // claimed_root has a leading "/" which we strip before passing
-      // into caps check
-      if (claimed_root.empty() || claimed_root[0] != '/' ||
-          !session->auth_caps.path_capable(claimed_root.substr(1))) {
-        derr << __func__ << " forbidden path claimed as mount root: "
-             << claimed_root << " by " << m->get_source() << dendl;
-        // Tell the client we're rejecting their open
+      if (blacklisted) {
+        dout(10) << "rejecting blacklisted client " << addr << dendl;
+        log_session_status("REJECTED", "blacklisted");
         mds->send_message_client(new MClientSession(CEPH_SESSION_REJECT), session);
-        mds->clog->warn() << "client session with invalid root '" <<
-          claimed_root << "' denied (" << session->info.inst << ")";
-        session->clear();
-        // Drop out; don't record this session in SessionMap or journal it.
-        break;
+        m->put();
+        return;
       }
-    }
 
-    if (session->is_closed())
-      mds->sessionmap.add_session(session);
+      dout(20) << __func__ << " CEPH_SESSION_REQUEST_OPEN "
+        << session->info.client_metadata.size() << " metadata entries:" << dendl;
+      for (map<string, string>::iterator i = session->info.client_metadata.begin();
+          i != session->info.client_metadata.end(); ++i) {
+        dout(20) << "  " << i->first << ": " << i->second << dendl;
+      }
 
-    pv = mds->sessionmap.mark_projected(session);
-    sseq = mds->sessionmap.set_state(session, Session::STATE_OPENING);
-    mds->sessionmap.touch_session(session);
-    mdlog->start_submit_entry(new ESession(m->get_source_inst(), true, pv, m->client_meta),
-                             new C_MDS_session_finish(this, session, sseq, true, pv));
-    mdlog->flush();
+      // Special case for the 'root' metadata path; validate that the claimed
+      // root is actually within the caps of the session
+      if (session->info.client_metadata.count("root")) {
+        const auto claimed_root = session->info.client_metadata.at("root");
+        // claimed_root has a leading "/" which we strip before passing
+        // into caps check
+        if (claimed_root.empty() || claimed_root[0] != '/' ||
+            !session->auth_caps.path_capable(claimed_root.substr(1))) {
+          derr << __func__ << " forbidden path claimed as mount root: "
+               << claimed_root << " by " << m->get_source() << dendl;
+          // Tell the client we're rejecting their open
+          log_session_status("REJECTED", "invalid root");
+          mds->send_message_client(new MClientSession(CEPH_SESSION_REJECT), session);
+          mds->clog->warn() << "client session with invalid root '" <<
+            claimed_root << "' denied (" << session->info.inst << ")";
+          session->clear();
+          // Drop out; don't record this session in SessionMap or journal it.
+          break;
+        }
+      }
+
+      if (session->is_closed())
+        mds->sessionmap.add_session(session);
+
+      pv = mds->sessionmap.mark_projected(session);
+      sseq = mds->sessionmap.set_state(session, Session::STATE_OPENING);
+      mds->sessionmap.touch_session(session);
+      auto fin = new FunctionContext([log_session_status = std::move(log_session_status)](int r){
+        if (r == 0) {
+          log_session_status("ACCEPTED", "");
+        } else {
+          std::stringstream ss;
+          ss << "(internal) r = " << r;
+          log_session_status("REJECTED", ss.str());
+        }
+      });
+      mdlog->start_submit_entry(new ESession(m->get_source_inst(), true, pv, client_metadata),
+                               new C_MDS_session_finish(this, session, sseq, true, pv, fin));
+    }
     break;
 
   case CEPH_SESSION_REQUEST_RENEWCAPS:

diff --git a/src/mds/SessionMap.cc b/src/mds/SessionMap.cc
index 15776ea7144c68bff8399d792782733f7fdb06aa..68ba509c23dbe4a1c0e9646aa4c1fac0bff4f1ee 100644 (file)
--- a/src/mds/SessionMap.cc
+++ b/src/mds/SessionMap.cc
@@ -893,13 +893,6 @@ void Session::clear_recalled_at()
   recall_release_count = 0;
 }
 
-void Session::set_client_metadata(map<string, string> const &meta)
-{
-  info.client_metadata = meta;
-
-  _update_human_name();
-}
-
 /**
  * Use client metadata to generate a somewhat-friendlier
  * name for the client than its session ID.

diff --git a/src/mds/SessionMap.h b/src/mds/SessionMap.h
index eee382f4af7849033909b0610f5182c00fa91ef8..b969d06d84951a5720fb8716c4f836275819bc2a 100644 (file)
--- a/src/mds/SessionMap.h
+++ b/src/mds/SessionMap.h
@@ -143,7 +143,12 @@ public:
     }
   }
   void decode(bufferlist::iterator &p);
-  void set_client_metadata(std::map<std::string, std::string> const &meta);
+  template<typename T>
+  void set_client_metadata(T&& meta)
+  {
+    info.client_metadata = std::forward<T>(meta);
+    _update_human_name();
+  }
   std::string get_human_name() const {return human_name;}
 
   // Ephemeral state for tracking progress of capability recalls

diff --git a/src/test/mds/TestSessionFilter.cc b/src/test/mds/TestSessionFilter.cc
index 29ce49256be849c663cb534586ebde982a6ab975..98e2212506fd7ace0130dc104aa733ee92bf936a 100644 (file)
--- a/src/test/mds/TestSessionFilter.cc
+++ b/src/test/mds/TestSessionFilter.cc
@@ -124,9 +124,9 @@ TEST(MDSSessionFilter, MetadataEquality)
   int r = filter.parse({"client_metadata.root=/rhubarb"}, &ss);
   ASSERT_EQ(r, 0);
   Session *a = new Session();
-  a->set_client_metadata({{"root", "/rhubarb"}});
+  a->set_client_metadata(std::map<std::string,std::string>({{"root", "/rhubarb"}}));
   Session *b = new Session();
-  b->set_client_metadata({{"root", "/custard"}});
+  b->set_client_metadata(std::map<std::string,std::string>({{"root", "/custard"}}));
 
   ASSERT_TRUE(filter.match(*a, [](client_t c) -> bool {return false;}));
   ASSERT_FALSE(filter.match(*b, [](client_t c) -> bool {return false;}));