From 786461204f670aedadce44129c32e3689c36a717 Mon Sep 17 00:00:00 2001 From: Ali Maredia Date: Fri, 9 Oct 2020 23:18:39 -0400 Subject: [PATCH] rgw: add request time into beast log instead of current time Change time format on the line that prints a summary of the request in apache common log format to match the format suggested by apache and encapsulate apache time formatting in stream output operator. For more information visit: https://httpd.apache.org/docs/current/logs.html#common Signed-off-by: Ali Maredia Co-authored-by: Casey Bodley --- src/rgw/rgw_asio_frontend.cc | 35 +++++++++++++++++++++++++++----- src/rgw/rgw_civetweb_frontend.cc | 2 +- src/rgw/rgw_loadgen_process.cc | 2 +- src/rgw/rgw_process.cc | 6 ++++++ src/rgw/rgw_process.h | 1 + src/rgw/rgw_sal.h | 1 + 6 files changed, 40 insertions(+), 7 deletions(-) diff --git a/src/rgw/rgw_asio_frontend.cc b/src/rgw/rgw_asio_frontend.cc index 577f70f385d89..e5334844f6361 100644 --- a/src/rgw/rgw_asio_frontend.cc +++ b/src/rgw/rgw_asio_frontend.cc @@ -2,6 +2,7 @@ // vim: ts=8 sw=2 smarttab ft=cpp #include +#include #include #include @@ -138,6 +139,29 @@ std::ostream& operator<<(std::ostream& out, const log_header& h) { return out << h.quote << p->value() << h.quote; } +// log fractional seconds in milliseconds +struct log_ms_remainder { + ceph::coarse_real_time t; + log_ms_remainder(ceph::coarse_real_time t) : t(t) {} +}; +std::ostream& operator<<(std::ostream& out, const log_ms_remainder& m) { + using namespace std::chrono; + return out << std::setfill('0') << std::setw(3) + << duration_cast(m.t.time_since_epoch()).count() % 1000; +} + +// log time in apache format: day/month/year:hour:minute:second zone +struct log_apache_time { + ceph::coarse_real_time t; + log_apache_time(ceph::coarse_real_time t) : t(t) {} +}; +std::ostream& operator<<(std::ostream& out, const log_apache_time& a) { + const auto t = ceph::coarse_real_clock::to_time_t(a.t); + const auto local = std::localtime(&t); + return out << std::put_time(local, "%d/%b/%Y:%T.") << log_ms_remainder{a.t} + << std::put_time(local, " %z"); +}; + using SharedMutex = ceph::async::SharedMutex; template @@ -228,16 +252,17 @@ void handle_connection(boost::asio::io_context& context, RGWRestfulIO client(cct, &real_client_io); auto y = optional_yield{context, yield}; int http_ret = 0; + string user = "-"; + const auto started = ceph::coarse_real_clock::now(); + process_request(env.store, env.rest, &req, env.uri_prefix, *env.auth_registry, &client, env.olog, y, - scheduler, &http_ret); + scheduler, &user, &http_ret); if (cct->_conf->subsys.should_gather(dout_subsys, 1)) { // access log line elements begin per Apache Combined Log Format with additions following - const auto now = ceph::coarse_real_clock::now(); - using ceph::operator<<; // for coarse_real_time - ldout(cct, 1) << "beast: " << hex << &req << dec << ": " - << remote_endpoint.address() << " - - [" << now << "] \"" + ldout(cct, 1) << "beast: " << std::hex << &req << std::dec << ": " + << remote_endpoint.address() << " - " << user << " [" << log_apache_time{started} << "] \"" << message.method_string() << ' ' << message.target() << ' ' << http_version{message.version()} << "\" " << http_ret << ' ' << client.get_bytes_sent() + client.get_bytes_received() << ' ' diff --git a/src/rgw/rgw_civetweb_frontend.cc b/src/rgw/rgw_civetweb_frontend.cc index ba12e7bebc83b..98dd4010df9c6 100644 --- a/src/rgw/rgw_civetweb_frontend.cc +++ b/src/rgw/rgw_civetweb_frontend.cc @@ -69,7 +69,7 @@ int RGWCivetWebFrontend::process(struct mg_connection* const conn) //assert (scheduler != nullptr); int ret = process_request(env.store, env.rest, &req, env.uri_prefix, *env.auth_registry, &client_io, env.olog, - null_yield, scheduler.get() ,&http_ret); + null_yield, scheduler.get(), nullptr, &http_ret); if (ret < 0) { /* We don't really care about return code. */ dout(20) << "process_request() returned " << ret << dendl; diff --git a/src/rgw/rgw_loadgen_process.cc b/src/rgw/rgw_loadgen_process.cc index 34842bf39d676..fe0b198874705 100644 --- a/src/rgw/rgw_loadgen_process.cc +++ b/src/rgw/rgw_loadgen_process.cc @@ -134,7 +134,7 @@ void RGWLoadGenProcess::handle_request(RGWRequest* r) int ret = process_request(store, rest, req, uri_prefix, *auth_registry, &client_io, olog, - null_yield, nullptr); + null_yield, nullptr, nullptr); if (ret < 0) { /* we don't really care about return code */ dout(20) << "process_request() returned " << ret << dendl; diff --git a/src/rgw/rgw_process.cc b/src/rgw/rgw_process.cc index b95ed15082cc0..462e66c247ccc 100644 --- a/src/rgw/rgw_process.cc +++ b/src/rgw/rgw_process.cc @@ -181,6 +181,7 @@ int process_request(rgw::sal::RGWRadosStore* const store, OpsLogSocket* const olog, optional_yield yield, rgw::dmclock::Scheduler *scheduler, + string* user, int* http_ret) { int ret = client_io->init(g_ceph_context); @@ -337,6 +338,11 @@ done: *http_ret = s->err.http_ret; } int op_ret = 0; + + if (user && !rgw::sal::RGWUser::empty(s->user.get())) { + *user = s->user->get_id().to_str(); + } + if (op) { op_ret = op->get_ret(); ldpp_dout(op, 2) << "op status=" << op_ret << dendl; diff --git a/src/rgw/rgw_process.h b/src/rgw/rgw_process.h index 9d2e46db42f6e..b0365ece9d088 100644 --- a/src/rgw/rgw_process.h +++ b/src/rgw/rgw_process.h @@ -185,6 +185,7 @@ extern int process_request(rgw::sal::RGWRadosStore* store, OpsLogSocket* olog, optional_yield y, rgw::dmclock::Scheduler *scheduler, + std::string* user, int* http_ret = nullptr); extern int rgw_process_authenticated(RGWHandler_REST* handler, diff --git a/src/rgw/rgw_sal.h b/src/rgw/rgw_sal.h index c0ea9df9c9fc4..0ab0bf059583f 100644 --- a/src/rgw/rgw_sal.h +++ b/src/rgw/rgw_sal.h @@ -134,6 +134,7 @@ class RGWUser { uint32_t get_type() const { return info.type; } int32_t get_max_buckets() const { return info.max_buckets; } const RGWUserCaps& get_caps() const { return info.caps; } + static bool empty(RGWUser* u) { return (!u || u->info.user_id.id.empty()); } /* Placeholders */ virtual int load_by_id(optional_yield y) = 0; -- 2.47.3