From c89cd8cac16789ed98dc1487ec17f45adf03dd26 Mon Sep 17 00:00:00 2001 From: Patrick Donnelly Date: Fri, 14 Dec 2018 18:16:09 -0800 Subject: [PATCH] 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 --- src/mds/Server.cc | 63 ++++++++++++++++++++++++++++----------- src/mds/SessionMap.cc | 7 ----- src/mds/SessionMap.h | 8 ++++- src/mds/events/ESession.h | 4 +-- 4 files changed, 54 insertions(+), 28 deletions(-) diff --git a/src/mds/Server.cc b/src/mds/Server.cc index 0171b3b2eb3..d38809f2f0b 100644 --- a/src/mds/Server.cc +++ b/src/mds/Server.cc @@ -473,8 +473,7 @@ void Server::handle_client_session(const MClientSession::const_ref &m) dout(10) << "currently open|opening|stale|killing, dropping this req" << dendl; return; } - ceph_assert(session->is_closed() || - session->is_closing()); + ceph_assert(session->is_closed() || session->is_closing()); if (mds->is_stopping()) { dout(10) << "mds is stopping, dropping open req" << dendl; @@ -482,32 +481,56 @@ void Server::handle_client_session(const MClientSession::const_ref &m) } { - auto send_reject_message = [this, session](std::string_view err_str) { + auto& addr = session->info.inst.addr; + session->set_client_metadata(client_metadata_t(m->metadata, m->supported_features)); + auto& client_metadata = session->info.client_metadata; + + auto log_session_status = [this, m, session](std::string_view status, std::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(); + CachedStackStringStream css; + *css << "New client session:" + << " addr=\"" << session->info.inst.addr << "\"" + << ",elapsed=" << elapsed + << ",throttled=" << throttle_elapsed + << ",status=\"" << status << "\""; + if (!err.empty()) { + *css << ",error=\"" << err << "\""; + } + const auto& metadata = session->info.client_metadata; + if (auto it = metadata.find("root"); it != metadata.end()) { + *css << ",root=\"" << it->second << "\""; + } + dout(2) << css->strv() << dendl; + }; + + auto send_reject_message = [this, &session, &log_session_status](std::string_view err_str) { auto m = MClientSession::create(CEPH_SESSION_REJECT); if (session->info.has_feature(CEPHFS_FEATURE_MIMIC)) m->metadata["error_string"] = err_str; mds->send_message_client(m, session); + log_session_status("REJECTED", err_str); }; bool blacklisted = mds->objecter->with_osdmap( - [session](const OSDMap &osd_map) -> bool { - return osd_map.is_blacklisted(session->info.inst.addr); + [&addr](const OSDMap &osd_map) -> bool { + return osd_map.is_blacklisted(addr); }); if (blacklisted) { - dout(10) << "rejecting blacklisted client " << session->info.inst.addr << dendl; + dout(10) << "rejecting blacklisted client " << addr << dendl; send_reject_message("blacklisted"); session->clear(); break; } - client_metadata_t client_metadata(m->metadata, m->supported_features); if (client_metadata.features.empty()) infer_supported_features(session, client_metadata); dout(20) << __func__ << " CEPH_SESSION_REQUEST_OPEN metadata entries:" << dendl; dout(20) << " features: '" << client_metadata.features << dendl; - for (auto& p : client_metadata) { + for (const auto& p : client_metadata) { dout(20) << " " << p.first << ": " << p.second << dendl; } @@ -523,11 +546,9 @@ void Server::handle_client_session(const MClientSession::const_ref &m) break; } - client_metadata_t::iterator it; // Special case for the 'root' metadata path; validate that the claimed // root is actually within the caps of the session - it = client_metadata.find("root"); - if (it != client_metadata.end()) { + if (auto it = client_metadata.find("root"); it != client_metadata.end()) { auto claimed_root = it->second; stringstream ss; bool denied = false; @@ -551,8 +572,7 @@ void Server::handle_client_session(const MClientSession::const_ref &m) } } - it = client_metadata.find("uuid"); - if (it != client_metadata.end()) { + if (auto it = client_metadata.find("uuid"); it != client_metadata.end()) { if (find_session_by_uuid(it->second)) { send_reject_message("duplicated session uuid"); mds->clog->warn() << "client session with duplicated session uuid '" @@ -562,17 +582,24 @@ void Server::handle_client_session(const MClientSession::const_ref &m) } } - session->set_client_metadata(client_metadata); - 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); - mdlog->start_submit_entry(new ESession(m->get_source_inst(), true, pv, - std::move(client_metadata)), - new C_MDS_session_finish(this, session, sseq, true, pv)); + auto fin = new FunctionContext([log_session_status = std::move(log_session_status)](int r){ + if (r == 0) { + log_session_status("ACCEPTED", ""); + } else { + CachedStackStringStream _ss; + auto& ss = _ss.get_stream(); + ss << "(internal) r = " << r; + log_session_status("REJECTED", ss.strv()); + } + }); + 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)); mdlog->flush(); } break; diff --git a/src/mds/SessionMap.cc b/src/mds/SessionMap.cc index 8d54bd6d307..79ecb5644fa 100644 --- a/src/mds/SessionMap.cc +++ b/src/mds/SessionMap.cc @@ -889,13 +889,6 @@ void Session::clear_recalled_at() recall_release_count = 0; } -void Session::set_client_metadata(const client_metadata_t& 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 c5ae604f9a6..52e507f3573 100644 --- a/src/mds/SessionMap.h +++ b/src/mds/SessionMap.h @@ -144,7 +144,13 @@ public: } } void decode(bufferlist::const_iterator &p); - void set_client_metadata(const client_metadata_t& meta); + template + void set_client_metadata(T&& meta) + { + info.client_metadata = std::forward(meta); + _update_human_name(); + } + const std::string& get_human_name() const {return human_name;} // Ephemeral state for tracking progress of capability recalls diff --git a/src/mds/events/ESession.h b/src/mds/events/ESession.h index c3b7c70f67c..0b65765e147 100644 --- a/src/mds/events/ESession.h +++ b/src/mds/events/ESession.h @@ -35,10 +35,10 @@ class ESession : public LogEvent { public: ESession() : LogEvent(EVENT_SESSION), open(false) { } ESession(const entity_inst_t& inst, bool o, version_t v, - client_metadata_t &&cm) : + const client_metadata_t& cm) : LogEvent(EVENT_SESSION), client_inst(inst), open(o), cmapv(v), inotablev(0), - client_metadata(std::move(cm)) { } + client_metadata(cm) { } ESession(const entity_inst_t& inst, bool o, version_t v, const interval_set& i, version_t iv) : LogEvent(EVENT_SESSION), -- 2.39.5