From: Patrick Donnelly Date: Sat, 15 Dec 2018 02:16:09 +0000 (-0800) Subject: mds: log session open stats X-Git-Tag: v12.2.12~109^2~2 X-Git-Url: http://git-server-git.apps.pok.os.sepia.ceph.com/?a=commitdiff_plain;h=8b0ebcc4c425625ff6029783e35a888137eac989;p=ceph.git 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 (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 e3fe19aa321..9d9b5f98256 100644 --- 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::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::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 15776ea7144..68ba509c23d 100644 --- 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 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 eee382f4af7..b969d06d849 100644 --- 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 const &meta); + template + void set_client_metadata(T&& meta) + { + info.client_metadata = std::forward(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 29ce49256be..98e2212506f 100644 --- 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({{"root", "/rhubarb"}})); Session *b = new Session(); - b->set_client_metadata({{"root", "/custard"}}); + b->set_client_metadata(std::map({{"root", "/custard"}})); ASSERT_TRUE(filter.match(*a, [](client_t c) -> bool {return false;})); ASSERT_FALSE(filter.match(*b, [](client_t c) -> bool {return false;}));