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 <amaredia@redhat.com>
Co-authored-by: Casey Bodley <cbodley@redhat.com>

diff --git a/src/rgw/rgw_asio_frontend.cc b/src/rgw/rgw_asio_frontend.cc
index 577f70f385d8942b135f44ce4981a33a6e7b9719..e5334844f6361024cb2e91e7dd6f2c1beb1ffd03 100644 (file)
--- 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 <atomic>
+#include <ctime>
 #include <thread>
 #include <vector>
 
@@ -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<milliseconds>(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<boost::asio::io_context::executor_type>;
 
 template <typename Stream>
@@ -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 ba12e7bebc83b6bd854c2bab2114445170c86c57..98dd4010df9c66d9ed4d084ee6cd70095d71bca9 100644 (file)
--- 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 34842bf39d6767e5d489d1c604d7462f7d8ed7bf..fe0b198874705b6ea3c9dd4bec04075d2e35a6d0 100644 (file)
--- 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 b95ed15082cc059d8b13ba8bc2ef8b83cce870aa..462e66c247ccc066573420b260f438cc94878462 100644 (file)
--- 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 9d2e46db42f6ec0cd641804ad1c0647cc0ad25ef..b0365ece9d088a7d6e91e56dd74cb26bcae47e9d 100644 (file)
--- 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 c0ea9df9c9fc49e93063c8b3057acaa922540de8..0ab0bf059583f9916c16c9bf3fccb1f1d40aafa4 100644 (file)
--- 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;