diff --git a/src/shrpx_client_handler.cc b/src/shrpx_client_handler.cc index 3f75ada4..aceb3332 100644 --- a/src/shrpx_client_handler.cc +++ b/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(); } diff --git a/src/shrpx_client_handler.h b/src/shrpx_client_handler.h index 4185d649..eb8cb388 100644 --- a/src/shrpx_client_handler.h +++ b/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; diff --git a/src/shrpx_downstream.h b/src/shrpx_downstream.h index 8a432031..1c360f89 100644 --- a/src/shrpx_downstream.h +++ b/src/shrpx_downstream.h @@ -152,6 +152,8 @@ struct Request { } FieldStore fs; + // Timestamp when all request header fields are received. + std::shared_ptr 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; diff --git a/src/shrpx_http2_upstream.cc b/src/shrpx_http2_upstream.cc index e55e3451..ce6287a6 100644 --- a/src/shrpx_http2_upstream.cc +++ b/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{ {http2::make_nv_ls_nocopy(":status", response_status), diff --git a/src/shrpx_https_upstream.cc b/src/shrpx_https_upstream.cc index 0c2b28b3..b575dcf3 100644 --- a/src/shrpx_https_upstream.cc +++ b/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); diff --git a/src/shrpx_log.cc b/src/shrpx_log.cc index 25353861..a85bcc76 100644 --- a/src/shrpx_log.cc +++ b/src/shrpx_log.cc @@ -146,7 +146,7 @@ Log::~Log() { // Error log format: // (:) 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 &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 &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 &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); - if (hd) { - std::tie(p, avail) = copy((*hd).value, avail, p); - break; - } + 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; - } + if (!req.authority.empty()) { + std::tie(p, avail) = copy(req.authority, avail, p); + break; } std::tie(p, avail) = copy_l("-", avail, p); diff --git a/src/shrpx_log.h b/src/shrpx_log.h index d93d49c8..3d742a11 100644 --- a/src/shrpx_log.h +++ b/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; diff --git a/src/shrpx_log_config.cc b/src/shrpx_log_config.cc index 93735cce..3290f0f8 100644 --- a/src/shrpx_log_config.cc +++ b/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(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(&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(now); } } // namespace shrpx diff --git a/src/shrpx_log_config.h b/src/shrpx_log_config.h index 8fa44a9a..8be2d2bb 100644 --- a/src/shrpx_log_config.h +++ b/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 time_local_buf; std::array time_iso8601_buf; std::array 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 tstamp; + std::string thread_id; pid_t pid; int accesslog_fd; int errorlog_fd; diff --git a/src/shrpx_mruby_module_response.cc b/src/shrpx_mruby_module_response.cc index 7e263804..13b7192a 100644 --- a/src/shrpx_mruby_module_response.cc +++ b/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(); diff --git a/src/shrpx_spdy_upstream.cc b/src/shrpx_spdy_upstream.cc index 1bc9bfa7..ce952298 100644 --- a/src/shrpx_spdy_upstream.cc +++ b/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,