From 566a91544d55a27bb5215fb9464d52e4d2d70495 Mon Sep 17 00:00:00 2001 From: Matan Breizman Date: Thu, 29 May 2025 09:18:01 +0000 Subject: [PATCH] crimson/admin/admin_socket: add logs, move to ceph_assert Signed-off-by: Matan Breizman --- src/crimson/admin/admin_socket.cc | 148 ++++++++++++++++++++---------- 1 file changed, 98 insertions(+), 50 deletions(-) diff --git a/src/crimson/admin/admin_socket.cc b/src/crimson/admin/admin_socket.cc index 3b18708cb59af..4bebf5de4e727 100644 --- a/src/crimson/admin/admin_socket.cc +++ b/src/crimson/admin/admin_socket.cc @@ -30,12 +30,7 @@ using ceph::common::bad_cmd_get; using ceph::common::validate_cmd; using ceph::common::dump_cmd_and_help_to_json; -namespace { -seastar::logger& logger() -{ - return crimson::get_logger(ceph_subsys_osd); -} -} // namespace +SET_SUBSYS(asok); using std::string; using std::string_view; @@ -59,15 +54,18 @@ tell_result_t::tell_result_t(std::unique_ptr formatter) void AdminSocket::register_command(std::unique_ptr&& hook) { + LOG_PREFIX(AdminSocket::register_command); auto prefix = hook->prefix; auto [it, added] = hooks.emplace(prefix, std::move(hook)); - assert(added); - logger().info("register_command(): {})", it->first); + ceph_assert(added); + INFO("register_command(): {})", it->first); } auto AdminSocket::parse_cmd(const std::vector& cmd) -> std::variant { + LOG_PREFIX(AdminSocket::parse_cmd); + INFO(""); // preliminaries: // - create the formatter specified by the cmd parameters // - locate the "op-code" string (the 'prefix' segment) @@ -79,13 +77,13 @@ auto AdminSocket::parse_cmd(const std::vector& cmd) stringstream errss; // note that cmdmap_from_json() may throw on syntax issues if (!cmdmap_from_json(cmd, &cmdmap, errss)) { - logger().error("{}: incoming command error: {}", __func__, errss.str()); + ERROR("incoming command error: {}", errss.str()); out.append("error:"s); out.append(errss.str()); return tell_result_t{-EINVAL, "invalid json", std::move(out)}; } } catch (const std::runtime_error& e) { - logger().error("{}: incoming command syntax: {}", __func__, cmd); + ERROR("incoming command syntax: {}", cmd); out.append(string{e.what()}); return tell_result_t{-EINVAL, "invalid json", std::move(out)}; } @@ -100,30 +98,34 @@ auto AdminSocket::parse_cmd(const std::vector& cmd) cmd_getval(cmdmap, "cmd", prefix); } } catch (const bad_cmd_get& e) { - logger().error("{}: invalid syntax: {}", __func__, cmd); + ERROR("invalid syntax: {}", cmd); out.append(string{e.what()}); return tell_result_t{-EINVAL, "invalid json", std::move(out)}; } // match the incoming op-code to one of the registered APIs - if (auto found = hooks.find(prefix); found != hooks.end()) { - return parsed_command_t{ cmdmap, format, *found->second }; - } else { + auto found = hooks.find(prefix); + if (found == hooks.end()) { + ERROR("unknown command: {}", prefix); return tell_result_t{-EINVAL, fmt::format("unknown command '{}'", prefix), std::move(out)}; } + DEBUG("parsed successfully {} {}", prefix, cmd); + return parsed_command_t{ cmdmap, format, *found->second }; } seastar::future<> AdminSocket::finalize_response( seastar::output_stream& out, ceph::bufferlist&& msgs) { + LOG_PREFIX(AdminSocket::finalize_response); + INFO(""); string outbuf_cont = msgs.to_str(); if (outbuf_cont.empty()) { outbuf_cont = " {} "; } uint32_t response_length = htonl(outbuf_cont.length()); - logger().info("asok response length: {}", outbuf_cont.length()); + INFO("asok response length: {}", outbuf_cont.length()); return out.write(reinterpret_cast(&response_length), sizeof(response_length)) @@ -134,12 +136,15 @@ seastar::future<> AdminSocket::finalize_response( seastar::future<> AdminSocket::handle_command(crimson::net::ConnectionRef conn, boost::intrusive_ptr m) { + LOG_PREFIX(AdminSocket::handle_command); + INFO(""); return execute_command(m->cmd, std::move(m->get_data())).then( - [conn, tid=m->get_tid()](auto result) { + [FNAME, conn, tid=m->get_tid()](auto result) { auto [ret, err, out] = std::move(result); auto reply = crimson::make_message(ret, err); reply->set_tid(tid); reply->set_data(out); + DEBUG("replying with ret {} error {}", ret, err); return conn->send(std::move(reply)); }); } @@ -147,12 +152,16 @@ seastar::future<> AdminSocket::handle_command(crimson::net::ConnectionRef conn, seastar::future<> AdminSocket::execute_line(std::string cmdline, seastar::output_stream& out) { - return execute_command({std::move(cmdline)}, {}).then([&out, this](auto result) { + LOG_PREFIX(AdminSocket::execute_line); + INFO(""); + return execute_command({std::move(cmdline)}, {}).then([FNAME, &out, this](auto result) { auto [ret, stderr, stdout] = std::move(result); if (ret < 0) { + ERROR("{}", cpp_strerror(ret)); stdout.append(fmt::format("ERROR: {}\n", cpp_strerror(ret))); stdout.append(stderr); } + DEBUG("finalizing response"); return finalize_response(out, std::move(stdout)); }); } @@ -161,20 +170,24 @@ auto AdminSocket::execute_command(const std::vector& cmd, ceph::bufferlist&& buf) -> seastar::future { + LOG_PREFIX(AdminSocket::execute_command); + INFO(""); auto maybe_parsed = parse_cmd(cmd); if (auto* parsed = std::get_if(&maybe_parsed); parsed) { + DEBUG("parsed ok"); stringstream os; string desc{parsed->hook.desc}; if (!validate_cmd(desc, parsed->params, os)) { - logger().error("AdminSocket::execute_command: " - "failed to validate '{}': {}", cmd, os.str()); + ERROR("failed to validate '{}': {}", cmd, os.str()); ceph::bufferlist out; out.append(os); return seastar::make_ready_future( tell_result_t{-EINVAL, "invalid command json", std::move(out)}); } + DEBUG("validated {} {}", cmd, os.str()); return parsed->hook.call(parsed->params, parsed->format, std::move(buf)); } else { + DEBUG("failed to parse"); auto& result = std::get(maybe_parsed); return seastar::make_ready_future(std::move(result)); } @@ -188,17 +201,21 @@ struct line_consumer { typename seastar::input_stream::consumption_result_type; seastar::future operator()(tmp_buf&& buf) { + LOG_PREFIX(line_consumer::operator()); + INFO(""); size_t consumed = 0; for (auto c : buf) { consumed++; if (c == '\0') { buf.trim_front(consumed); + INFO("stop consuming"); return seastar::make_ready_future( consumption_result_type::stop_consuming_type(std::move(buf))); } else { line.push_back(c); } } + INFO("continue consuming"); return seastar::make_ready_future( seastar::continue_consuming{}); } @@ -208,77 +225,90 @@ struct line_consumer { seastar::future<> AdminSocket::handle_client(seastar::input_stream& in, seastar::output_stream& out) { + LOG_PREFIX(AdminSocket::handle_client); + INFO(""); auto consumer = seastar::make_shared(); - return in.consume(*consumer).then([consumer, &out, this] { - logger().debug("AdminSocket::handle_client: incoming asok string: {}", - consumer->line); + return in.consume(*consumer).then([FNAME, consumer, &out, this] { + DEBUG("incoming asok string: {}", consumer->line); return execute_line(consumer->line, out); - }).then([&out] { + }).then([FNAME, &out] { + DEBUG("flush"); return out.flush(); - }).finally([&out] { + }).finally([FNAME, &out] { + DEBUG("out close"); return out.close(); - }).then([&in] { + }).then([FNAME, &in] { + DEBUG("in close"); return in.close(); - }).handle_exception([](auto ep) { - logger().debug("exception on {}: {}", __func__, ep); + }).handle_exception([FNAME](auto ep) { + ERROR("exception on {}", ep); }); } seastar::future<> AdminSocket::start(const std::string& path) { + LOG_PREFIX(AdminSocket::start); + INFO(""); if (path.empty()) { - logger().error( - "{}: Admin Socket socket path missing from the configuration", __func__); + ERROR("socket path missing from the configuration"); return seastar::now(); } - logger().debug("{}: asok socket path={}", __func__, path); + DEBUG("asok socket path={}", path); auto sock_path = seastar::socket_address{ seastar::unix_domain_addr{ path } }; try { server_sock = seastar::engine().listen(sock_path); } catch (const std::system_error& e) { if (e.code() == std::errc::address_in_use) { - logger().debug("{}: Admin Socket socket path={} already exists, retrying", - __func__, path); - return seastar::remove_file(path).then([this, path] { + DEBUG("socket path={} already exists, retrying", path); + return seastar::remove_file(path).then([FNAME, this, path] { + DEBUG("socket path={} retrying", path); server_sock.reset(); return start(path); }); } - logger().error("{}: unable to listen({}): {}", __func__, path, e.what()); + ERROR("unable to listen({}): {}", path, e.what()); server_sock.reset(); return seastar::make_ready_future<>(); } // listen in background - task = seastar::keep_doing([this] { - return seastar::try_with_gate(stop_gate, [this] { - assert(!connected_sock.has_value()); - return server_sock->accept().then([this](seastar::accept_result acc) { + task = seastar::keep_doing([FNAME, this] { + return seastar::try_with_gate(stop_gate, [FNAME, this] { + ceph_assert(!connected_sock.has_value()); + return server_sock->accept().then([FNAME, this](seastar::accept_result acc) { connected_sock = std::move(acc.connection); return seastar::do_with(connected_sock->input(), connected_sock->output(), - [this](auto& input, auto& output) mutable { + [FNAME, this](auto& input, auto& output) mutable { + DEBUG("handling client"); return handle_client(input, output); - }).finally([this] { - assert(connected_sock.has_value()); + }).finally([FNAME, this] { + DEBUG("reset"); + ceph_assert(connected_sock.has_value()); connected_sock.reset(); }); - }).handle_exception([this](auto ep) { + }).handle_exception([FNAME, this](auto ep) { if (!stop_gate.is_closed()) { - logger().error("AdminSocket: terminated: {}", ep); + ERROR("terminated: {}", ep); } }); }); - }).handle_exception_type([](const seastar::gate_closed_exception&) { - }).finally([path] { + }).handle_exception_type([FNAME](const seastar::gate_closed_exception&) { + DEBUG("gate closed"); + }).finally([FNAME, path] { + DEBUG("closing: {}", path); return seastar::remove_file(path); }); + DEBUG("exisited, listening in background"); return seastar::make_ready_future<>(); } seastar::future<> AdminSocket::stop() { + LOG_PREFIX(AdminSocket::stop); + INFO(""); if (!server_sock) { + DEBUG("no server socket"); return seastar::now(); } server_sock->abort_accept(); @@ -286,10 +316,10 @@ seastar::future<> AdminSocket::stop() connected_sock->shutdown_input(); connected_sock->shutdown_output(); } - return stop_gate.close().then([this] { - assert(task.has_value()); - return task->then([] { - logger().info("AdminSocket: stopped"); + return stop_gate.close().then([FNAME, this] { + ceph_assert(task.has_value()); + return task->then([FNAME] { + INFO("stopped"); return seastar::now(); }); }); @@ -308,6 +338,8 @@ class VersionHook final : public AdminSocketHook { std::string_view format, ceph::bufferlist&&) const final { + LOG_PREFIX(AdminSocket::VersionHook); + INFO(""); unique_ptr f{Formatter::create(format, "json-pretty", "json-pretty")}; f->open_object_section("version"); f->dump_string("version", ceph_version_to_str()); @@ -331,6 +363,8 @@ class GitVersionHook final : public AdminSocketHook { std::string_view format, ceph::bufferlist&&) const final { + LOG_PREFIX(AdminSocket::AdminSocketHook); + INFO(""); unique_ptr f{Formatter::create(format, "json-pretty", "json-pretty")}; f->open_object_section("version"); f->dump_string("git_version", git_version_to_str()); @@ -352,6 +386,8 @@ class HelpHook final : public AdminSocketHook { std::string_view format, ceph::bufferlist&&) const final { + LOG_PREFIX(AdminSocket::HelpHook); + INFO(""); unique_ptr f{Formatter::create(format, "json-pretty", "json-pretty")}; f->open_object_section("help"); @@ -379,6 +415,8 @@ class GetdescsHook final : public AdminSocketHook { std::string_view format, ceph::bufferlist&&) const final { + LOG_PREFIX(AdminSocket::GetdescsHook); + INFO(""); unique_ptr f{Formatter::create(format, "json-pretty", "json-pretty")}; int cmdnum = 0; f->open_object_section("command_descriptions"); @@ -405,6 +443,8 @@ public: std::string_view format, ceph::bufferlist&&) const final { + LOG_PREFIX(AdminSocket::InjectArgsHook); + INFO(""); std::vector argv; if (!cmd_getval(cmdmap, "injected_args", argv)) { return seastar::make_ready_future(); @@ -433,6 +473,8 @@ public: std::string_view format, ceph::bufferlist&& input) const final { + LOG_PREFIX(AdminSocket::ConfigShowHook); + INFO(""); unique_ptr f{Formatter::create(format, "json-pretty", "json-pretty")}; f->open_object_section("config_show"); local_conf().show_config(f.get()); @@ -455,9 +497,11 @@ public: std::string_view format, ceph::bufferlist&& input) const final { + LOG_PREFIX(AdminSocket::ConfigGetHook); + INFO(""); std::string var; [[maybe_unused]] bool found = cmd_getval(cmdmap, "var", var); - assert(found); + ceph_assert(found); std::string conf_val; if (int r = local_conf().get_val(var, &conf_val); r < 0) { return seastar::make_ready_future( @@ -490,6 +534,8 @@ public: std::string_view format, ceph::bufferlist&&) const final { + LOG_PREFIX(AdminSocket::ConfigSetHook); + INFO(""); std::string var; std::vector new_val; cmd_getval(cmdmap, "var", var); @@ -523,6 +569,8 @@ public: std::string_view format, ceph::bufferlist&& input) const final { + LOG_PREFIX(AdminSocket::ConfigHelpHook); + INFO(""); unique_ptr f{Formatter::create(format, "json-pretty", "json-pretty")}; // Output all f->open_array_section("options"); -- 2.39.5