nghttpx: Fix access.log timestamp

access.log timestamp is now when request header fields are received,
rather than when access log is written.

src/shrpx_client_handler.cc

@@ -1230,12 +1230,18 @@ StringRef construct_absolute_request_uri(BlockAllocator &balloc,
 
 void ClientHandler::write_accesslog(Downstream *downstream) {
   nghttp2::ssl::TLSSessionInfo tls_info;
-  const auto &req = downstream->request();
+  auto &req = downstream->request();
   const auto &resp = downstream->response();
 
   auto &balloc = downstream->get_block_allocator();
   auto config = get_config();
 
+  if (!req.tstamp) {
+    auto lgconf = log_config();
+    lgconf->update_tstamp(std::chrono::system_clock::now());
+    req.tstamp = lgconf->tstamp;
+  }
+
   upstream_accesslog(
       config->logging.access.format,
       LogSpec{
@@ -1253,8 +1259,6 @@ void ClientHandler::write_accesslog(Downstream *downstream) {
                           : StringRef(req.path),
 
           alpn_, nghttp2::ssl::get_tls_session_info(&tls_info, conn_.tls.ssl),
-
-          std::chrono::system_clock::now(),          // time_now
           downstream->get_request_start_time(),      // request_start_time
           std::chrono::high_resolution_clock::now(), // request_end_time
 
@@ -1264,29 +1268,6 @@ void ClientHandler::write_accesslog(Downstream *downstream) {
       });
 }
 
-void ClientHandler::write_accesslog(int major, int minor, unsigned int status,
-                                    int64_t body_bytes_sent) {
-  auto time_now = std::chrono::system_clock::now();
-  auto highres_now = std::chrono::high_resolution_clock::now();
-  nghttp2::ssl::TLSSessionInfo tls_info;
-  auto config = get_config();
-
-  upstream_accesslog(
-      config->logging.access.format,
-      LogSpec{
-          nullptr, nullptr, ipaddr_,
-          StringRef::from_lit("-"), // method
-          StringRef::from_lit("-"), // path,
-          alpn_, nghttp2::ssl::get_tls_session_info(&tls_info, conn_.tls.ssl),
-          time_now,
-          highres_now,  // request_start_time TODO is
-                        // there a better value?
-          highres_now,  // request_end_time
-          major, minor, // major, minor
-          status, body_bytes_sent, port_, faddr_->port, config->pid,
-      });
-}
-
 ClientHandler::ReadBuf *ClientHandler::get_rb() { return &rb_; }
 
 void ClientHandler::signal_write() { conn_.wlimit.startw(); }

src/shrpx_client_handler.h

@@ -118,10 +118,6 @@ public:
   // must not be nullptr.
   void write_accesslog(Downstream *downstream);
 
-  // Writes upstream accesslog.  This function is used if
-  // corresponding Downstream object is not available.
-  void write_accesslog(int major, int minor, unsigned int status,
-                       int64_t body_bytes_sent);
   Worker *get_worker() const;
 
   using ReadBuf = DefaultMemchunkBuffer;

src/shrpx_downstream.h

@@ -152,6 +152,8 @@ struct Request {
   }
 
   FieldStore fs;
+  // Timestamp when all request header fields are received.
+  std::shared_ptr<Timestamp> tstamp;
   // Request scheme.  For HTTP/2, this is :scheme header field value.
   // For HTTP/1.1, this is deduced from URI or connection.
   StringRef scheme;

src/shrpx_http2_upstream.cc

@@ -296,11 +296,15 @@ int on_begin_headers_callback(nghttp2_session *session,
 
 int Http2Upstream::on_request_headers(Downstream *downstream,
                                       const nghttp2_frame *frame) {
+  auto lgconf = log_config();
+  lgconf->update_tstamp(std::chrono::system_clock::now());
+  auto &req = downstream->request();
+  req.tstamp = lgconf->tstamp;
+
   if (downstream->get_response_state() == Downstream::MSG_COMPLETE) {
     return 0;
   }
 
-  auto &req = downstream->request();
   auto &nva = req.fs.headers();
 
   if (LOG_ENABLED(INFO)) {
@@ -1489,7 +1493,7 @@ int Http2Upstream::error_reply(Downstream *downstream,
 
   auto response_status = http2::stringify_status(balloc, status_code);
   auto content_length = util::make_string_ref_uint(balloc, html.size());
-  auto date = make_string_ref(balloc, lgconf->time_http);
+  auto date = make_string_ref(balloc, lgconf->tstamp->time_http);
 
   auto nva = std::array<nghttp2_nv, 5>{
       {http2::make_nv_ls_nocopy(":status", response_status),

src/shrpx_https_upstream.cc

@@ -292,6 +292,10 @@ int htp_hdrs_completecb(http_parser *htp) {
   auto downstream = upstream->get_downstream();
   auto &req = downstream->request();
 
+  auto lgconf = log_config();
+  lgconf->update_tstamp(std::chrono::system_clock::now());
+  req.tstamp = lgconf->tstamp;
+
   req.http_major = htp->http_major;
   req.http_minor = htp->http_minor;
 
@@ -950,7 +954,7 @@ void HttpsUpstream::error_reply(unsigned int status_code) {
   output->append("\r\nDate: ");
   auto lgconf = log_config();
   lgconf->update_tstamp(std::chrono::system_clock::now());
-  output->append(lgconf->time_http);
+  output->append(lgconf->tstamp->time_http);
   output->append("\r\nContent-Type: text/html; "
                  "charset=UTF-8\r\nConnection: close\r\n\r\n");
   output->append(html);

src/shrpx_log.cc

@@ -146,7 +146,7 @@ Log::~Log() {
   // Error log format: <datetime> <master-pid> <current-pid>
   // <thread-id> <level> (<filename>:<line>) <msg>
   rv = snprintf(buf, sizeof(buf), "%s %d %d %s %s%s%s (%s:%d) %s\n",
-                lgconf->time_iso8601.c_str(), config->pid, lgconf->pid,
+                lgconf->tstamp->time_iso8601.c_str(), config->pid, lgconf->pid,
                 lgconf->thread_id.c_str(), tty ? SEVERITY_COLOR[severity_] : "",
                 SEVERITY_STR[severity_].c_str(), tty ? "\033[0m" : "",
                 filename_, linenum_, stream_.str().c_str());
@@ -242,18 +242,12 @@ void upstream_accesslog(const std::vector<LogFragment> &lfv,
 
   auto downstream = lgsp.downstream;
 
-  const Request *req = nullptr;
-  if (downstream) {
-    req = &downstream->request();
-  }
+  const auto &req = downstream->request();
+  const auto &tstamp = req.tstamp;
 
   auto p = buf;
   auto avail = sizeof(buf) - 2;
 
-  lgconf->update_tstamp(lgsp.time_now);
-  auto &time_local = lgconf->time_local;
-  auto &time_iso8601 = lgconf->time_iso8601;
-
   for (auto &lf : lfv) {
     switch (lf.type) {
     case SHRPX_LOGF_LITERAL:
@@ -263,10 +257,10 @@ void upstream_accesslog(const std::vector<LogFragment> &lfv,
       std::tie(p, avail) = copy(lgsp.remote_addr, avail, p);
       break;
     case SHRPX_LOGF_TIME_LOCAL:
-      std::tie(p, avail) = copy(time_local, avail, p);
+      std::tie(p, avail) = copy(tstamp->time_local, avail, p);
       break;
     case SHRPX_LOGF_TIME_ISO8601:
-      std::tie(p, avail) = copy(time_iso8601, avail, p);
+      std::tie(p, avail) = copy(tstamp->time_iso8601, avail, p);
       break;
     case SHRPX_LOGF_REQUEST:
       std::tie(p, avail) = copy(lgsp.method, avail, p);
@@ -285,24 +279,21 @@ void upstream_accesslog(const std::vector<LogFragment> &lfv,
     case SHRPX_LOGF_BODY_BYTES_SENT:
       std::tie(p, avail) = copy(util::utos(lgsp.body_bytes_sent), avail, p);
       break;
-    case SHRPX_LOGF_HTTP:
-      if (req) {
-        auto hd = req->fs.header(lf.value);
+    case SHRPX_LOGF_HTTP: {
+      auto hd = req.fs.header(lf.value);
       if (hd) {
         std::tie(p, avail) = copy((*hd).value, avail, p);
         break;
       }
-      }
 
       std::tie(p, avail) = copy_l("-", avail, p);
 
-      break;
-    case SHRPX_LOGF_AUTHORITY:
-      if (req) {
-        if (!req->authority.empty()) {
-          std::tie(p, avail) = copy(req->authority, avail, p);
       break;
     }
+    case SHRPX_LOGF_AUTHORITY:
+      if (!req.authority.empty()) {
+        std::tie(p, avail) = copy(req.authority, avail, p);
+        break;
       }
 
       std::tie(p, avail) = copy_l("-", avail, p);

src/shrpx_log.h

@@ -151,7 +151,6 @@ struct LogSpec {
   StringRef path;
   StringRef alpn;
   const nghttp2::ssl::TLSSessionInfo *tls_info;
-  std::chrono::system_clock::time_point time_now;
   std::chrono::high_resolution_clock::time_point request_start_time;
   std::chrono::high_resolution_clock::time_point request_end_time;
   int major, minor;

src/shrpx_log_config.cc

@@ -35,8 +35,19 @@ using namespace nghttp2;
 
 namespace shrpx {
 
+Timestamp::Timestamp(const std::chrono::system_clock::time_point &tp) {
+  time_local = util::format_common_log(time_local_buf.data(), tp);
+  time_iso8601 = util::format_iso8601(time_iso8601_buf.data(), tp);
+  time_http = util::format_http_date(time_http_buf.data(), tp);
+}
+
 LogConfig::LogConfig()
-    : pid(getpid()), accesslog_fd(-1), errorlog_fd(-1), errorlog_tty(false) {
+    : time_str_updated(std::chrono::system_clock::now()),
+      tstamp(std::make_shared<Timestamp>(time_str_updated)),
+      pid(getpid()),
+      accesslog_fd(-1),
+      errorlog_fd(-1),
+      errorlog_tty(false) {
   auto tid = std::this_thread::get_id();
   auto tid_hash =
       util::hash32(StringRef{reinterpret_cast<uint8_t *>(&tid),
@@ -87,17 +98,15 @@ void delete_log_config() {}
 
 void LogConfig::update_tstamp(
     const std::chrono::system_clock::time_point &now) {
-  auto t0 = std::chrono::system_clock::to_time_t(time_str_updated_);
+  auto t0 = std::chrono::system_clock::to_time_t(time_str_updated);
   auto t1 = std::chrono::system_clock::to_time_t(now);
   if (t0 == t1) {
     return;
   }
 
-  time_str_updated_ = now;
+  time_str_updated = now;
 
-  time_local = util::format_common_log(time_local_buf.data(), now);
-  time_iso8601 = util::format_iso8601(time_iso8601_buf.data(), now);
-  time_http = util::format_http_date(time_http_buf.data(), now);
+  tstamp = std::make_shared<Timestamp>(now);
 }
 
 } // namespace shrpx

src/shrpx_log_config.h

@@ -37,15 +37,21 @@ using namespace nghttp2;
 
 namespace shrpx {
 
-struct LogConfig {
-  std::chrono::system_clock::time_point time_str_updated_;
+struct Timestamp {
+  Timestamp(const std::chrono::system_clock::time_point &tp);
+
   std::array<char, sizeof("03/Jul/2014:00:19:38 +0900")> time_local_buf;
   std::array<char, sizeof("2014-11-15T12:58:24.741+09:00")> time_iso8601_buf;
   std::array<char, sizeof("Mon, 10 Oct 2016 10:25:58 GMT")> time_http_buf;
-  std::string thread_id;
   StringRef time_local;
   StringRef time_iso8601;
   StringRef time_http;
+};
+
+struct LogConfig {
+  std::chrono::system_clock::time_point time_str_updated;
+  std::shared_ptr<Timestamp> tstamp;
+  std::string thread_id;
   pid_t pid;
   int accesslog_fd;
   int errorlog_fd;

src/shrpx_mruby_module_response.cc

@@ -255,8 +255,8 @@ mrb_value response_return(mrb_state *mrb, mrb_value self) {
     auto lgconf = log_config();
     lgconf->update_tstamp(std::chrono::system_clock::now());
     resp.fs.add_header_token(StringRef::from_lit("date"),
-                             make_string_ref(balloc, lgconf->time_http), false,
-                             http2::HD_DATE);
+                             make_string_ref(balloc, lgconf->tstamp->time_http),
+                             false, http2::HD_DATE);
   }
 
   auto upstream = downstream->get_upstream();

src/shrpx_spdy_upstream.cc

@@ -181,6 +181,10 @@ void on_ctrl_recv_callback(spdylay_session *session, spdylay_frame_type type,
 
     auto &balloc = downstream->get_block_allocator();
 
+    auto lgconf = log_config();
+    lgconf->update_tstamp(std::chrono::system_clock::now());
+    req.tstamp = lgconf->tstamp;
+
     downstream->reset_upstream_rtimer();
 
     auto nv = frame->syn_stream.nv;
@@ -1006,7 +1010,7 @@ int SpdyUpstream::error_reply(Downstream *downstream,
                       "content-type",   "text/html; charset=UTF-8",
                       "server",         get_config()->http.server_name.c_str(),
                       "content-length", content_length.c_str(),
-                      "date",           lgconf->time_http.c_str(),
+                      "date",           lgconf->tstamp->time_http.c_str(),
                       nullptr};
 
   rv = spdylay_submit_response(session_, downstream->get_stream_id(), nv,