From 9cf1a0c77c992ae0548a7f12045a2c969d5d6fda Mon Sep 17 00:00:00 2001 From: Lucas Pardue Date: Wed, 19 Nov 2014 16:53:30 +0000 Subject: [PATCH] Add features to logging, client and server port, time_iso8601 and request_time. --- src/shrpx.cc | 38 +++++++++++--------------- src/shrpx_client_handler.cc | 15 +++++++++-- src/shrpx_client_handler.h | 4 ++- src/shrpx_config.cc | 8 ++++++ src/shrpx_downstream.cc | 10 +++++++ src/shrpx_downstream.h | 4 +++ src/shrpx_http2_upstream.cc | 1 + src/shrpx_https_upstream.cc | 1 + src/shrpx_log.cc | 33 ++++++++++++++++++++--- src/shrpx_log.h | 9 +++++++ src/shrpx_spdy_upstream.cc | 2 ++ src/shrpx_ssl.cc | 9 ++++--- src/util.cc | 19 ------------- src/util.h | 54 ++++++++++++++++++++++++++++++++++++- 14 files changed, 154 insertions(+), 53 deletions(-) diff --git a/src/shrpx.cc b/src/shrpx.cc index 5cb57ec7..20185b37 100644 --- a/src/shrpx.cc +++ b/src/shrpx.cc @@ -461,22 +461,7 @@ void graceful_shutdown_signal_cb(evutil_socket_t sig, short events, void *arg) namespace { std::unique_ptr generate_time() { - char buf[32]; - - // Format data like this: - // 03/Jul/2014:00:19:38 +0900 - struct tm tms; - auto now = time(nullptr); - - if(localtime_r(&now, &tms) == nullptr) { - return util::make_unique(""); - } - - if(strftime(buf, sizeof(buf), "%d/%b/%Y:%T %z", &tms) == 0) { - return util::make_unique(""); - } - - return util::make_unique(buf); + return util::make_unique(util::format_common_log(std::chrono::system_clock::now())); } } // namespace @@ -487,7 +472,6 @@ void refresh_cb(evutil_socket_t sig, short events, void *arg) auto worker_stat = listener_handler->get_worker_stat(); mod_config()->cached_time = generate_time(); - // In multi threaded mode (get_config()->num_worker > 1), we have to // wait for event notification to workers to finish. if(get_config()->num_worker == 1 && @@ -1144,12 +1128,20 @@ Logging: --accesslog-format= Specify format string for access log. The default format is combined format. The following - variables are available: $remote_addr: client IP - address. $time_local: local time. $request: - HTTP request line. $status: HTTP response status - code. $body_bytes_sent: the number of bytes sent - to client as response body. $http_: value - of HTTP request header . + variables are available: + $remote_addr: client IP address + $time_local: local time in Common Log format + $time_iso8601: local time in ISO 8601 format + $request: HTTP request line + $status: HTTP response status code. + $body_bytes_sent: the number of bytes sent + to client as response body + $http_: value of HTTP request header + $remote_port: client port + $server_port: server port + $request_time: request processing time in + seconds with milliseconds + resolution. Default: )" << DEFAULT_ACCESSLOG_FORMAT << R"( --errorlog-file= diff --git a/src/shrpx_client_handler.cc b/src/shrpx_client_handler.cc index c66033d8..a7f5a422 100644 --- a/src/shrpx_client_handler.cc +++ b/src/shrpx_client_handler.cc @@ -168,9 +168,11 @@ ClientHandler::ClientHandler(bufferevent *bev, bufferevent_rate_limit_group *rate_limit_group, int fd, SSL *ssl, const char *ipaddr, + const char *port, WorkerStat *worker_stat, DownstreamConnectionPool *dconn_pool) : ipaddr_(ipaddr), + port_(port), dconn_pool_(dconn_pool), bev_(bev), http2session_(nullptr), @@ -736,10 +738,15 @@ void ClientHandler::write_accesslog(Downstream *downstream) downstream->get_request_http2_authority().c_str() : downstream->get_request_path().c_str(), + downstream->get_request_start_time(), + std::chrono::high_resolution_clock::now(), + downstream->get_request_major(), downstream->get_request_minor(), downstream->get_response_http_status(), - downstream->get_response_sent_bodylen() + downstream->get_response_sent_bodylen(), + port_.c_str(), + get_config()->port }; upstream_accesslog(get_config()->accesslog_format, &lgsp); @@ -754,9 +761,13 @@ void ClientHandler::write_accesslog(int major, int minor, ipaddr_.c_str(), "-", // method "-", // path, + std::chrono::high_resolution_clock::now(), //request_start_time TODO is there a better value? + std::chrono::high_resolution_clock::now(), //time_now major, minor, // major, minor status, - body_bytes_sent + body_bytes_sent, + port_.c_str(), + get_config()->port }; upstream_accesslog(get_config()->accesslog_format, &lgsp); diff --git a/src/shrpx_client_handler.h b/src/shrpx_client_handler.h index 22fba159..dc6091cd 100644 --- a/src/shrpx_client_handler.h +++ b/src/shrpx_client_handler.h @@ -48,7 +48,7 @@ class ClientHandler { public: ClientHandler(bufferevent *bev, bufferevent_rate_limit_group *rate_limit_group, - int fd, SSL *ssl, const char *ipaddr, + int fd, SSL *ssl, const char *ipaddr, const char *port, WorkerStat *worker_stat, DownstreamConnectionPool *dconn_pool); ~ClientHandler(); @@ -62,6 +62,7 @@ public: const timeval *write_timeout); int validate_next_proto(); const std::string& get_ipaddr() const; + const std::string& get_port() const; bool get_should_close_after_write() const; void set_should_close_after_write(bool f); Upstream* get_upstream(); @@ -117,6 +118,7 @@ public: private: std::unique_ptr upstream_; std::string ipaddr_; + std::string port_; DownstreamConnectionPool *dconn_pool_; bufferevent *bev_; // Shared HTTP2 session for each thread. NULL if backend is not diff --git a/src/shrpx_config.cc b/src/shrpx_config.cc index a3b7ba65..2465011e 100644 --- a/src/shrpx_config.cc +++ b/src/shrpx_config.cc @@ -384,6 +384,8 @@ std::vector parse_log_format(const char *optarg) type = SHRPX_LOGF_REMOTE_ADDR; } else if(util::strieq("$time_local", var_start, varlen)) { type = SHRPX_LOGF_TIME_LOCAL; + } else if(util::strieq("$time_iso8601", var_start, varlen)) { + type = SHRPX_LOGF_TIME_ISO8601; } else if(util::strieq("$request", var_start, varlen)) { type = SHRPX_LOGF_REQUEST; } else if(util::strieq("$status", var_start, varlen)) { @@ -394,6 +396,12 @@ std::vector parse_log_format(const char *optarg) type = SHRPX_LOGF_HTTP; value = var_start + sizeof("$http_") - 1; valuelen = varlen - (sizeof("$http_") - 1); + } else if(util::strieq("$remote_port", var_start, varlen)) { + type = SHRPX_LOGF_REMOTE_PORT; + } else if(util::strieq("$server_port", var_start, varlen)) { + type = SHRPX_LOGF_SERVER_PORT; + } else if(util::strieq("$request_time", var_start, varlen)) { + type = SHRPX_LOGF_REQUEST_TIME; } else { LOG(WARN) << "Unrecognized log format variable: " << std::string(var_start, varlen); diff --git a/src/shrpx_downstream.cc b/src/shrpx_downstream.cc index 2cc6bc5c..27091ca1 100644 --- a/src/shrpx_downstream.cc +++ b/src/shrpx_downstream.cc @@ -390,6 +390,16 @@ const std::string& Downstream::get_request_path() const return request_path_; } +void Downstream::set_request_start_time(std::chrono::high_resolution_clock::time_point time) +{ + request_start_time_ = std::move(time); +} + +const std::chrono::high_resolution_clock::time_point& Downstream::get_request_start_time() const +{ + return request_start_time_; +} + const std::string& Downstream::get_request_http2_scheme() const { return request_http2_scheme_; diff --git a/src/shrpx_downstream.h b/src/shrpx_downstream.h index f033046e..514b8dc5 100644 --- a/src/shrpx_downstream.h +++ b/src/shrpx_downstream.h @@ -32,6 +32,7 @@ #include #include #include +#include #include #include @@ -132,6 +133,8 @@ public: void set_request_method(std::string method); const std::string& get_request_method() const; void set_request_path(std::string path); + void set_request_start_time(std::chrono::high_resolution_clock::time_point time); + const std::chrono::high_resolution_clock::time_point& get_request_start_time() const; void append_request_path(const char *data, size_t len); // Returns request path. For HTTP/1.1, this is request-target. For // HTTP/2, this is :path header field value. @@ -284,6 +287,7 @@ private: std::string request_path_; std::string request_http2_scheme_; std::string request_http2_authority_; + std::chrono::high_resolution_clock::time_point request_start_time_; std::string assembled_request_cookie_; std::string http2_settings_; diff --git a/src/shrpx_http2_upstream.cc b/src/shrpx_http2_upstream.cc index d6a2884f..586fcb90 100644 --- a/src/shrpx_http2_upstream.cc +++ b/src/shrpx_http2_upstream.cc @@ -355,6 +355,7 @@ int on_request_headers(Http2Upstream *upstream, downstream->set_request_http2_scheme(http2::value_to_str(scheme)); downstream->set_request_http2_authority(http2::value_to_str(authority)); downstream->set_request_path(http2::value_to_str(path)); + downstream->set_request_start_time(std::chrono::high_resolution_clock::now()); if(!(frame->hd.flags & NGHTTP2_FLAG_END_STREAM)) { downstream->set_request_http2_expect_body(true); diff --git a/src/shrpx_https_upstream.cc b/src/shrpx_https_upstream.cc index a4ad2209..61befc7d 100644 --- a/src/shrpx_https_upstream.cc +++ b/src/shrpx_https_upstream.cc @@ -143,6 +143,7 @@ int htp_hdrs_completecb(http_parser *htp) downstream->set_request_method(http_method_str((enum http_method)htp->method)); downstream->set_request_major(htp->http_major); downstream->set_request_minor(htp->http_minor); + downstream->set_request_start_time(std::chrono::high_resolution_clock::now()); downstream->set_request_connection_close(!http_should_keep_alive(htp)); diff --git a/src/shrpx_log.cc b/src/shrpx_log.cc index 7b09be56..3456fbc2 100644 --- a/src/shrpx_log.cc +++ b/src/shrpx_log.cc @@ -33,6 +33,7 @@ #include #include #include +#include #include "shrpx_config.h" #include "shrpx_downstream.h" @@ -192,8 +193,6 @@ void upstream_accesslog(const std::vector& lfv, LogSpec *lgsp) auto p = buf; auto avail = sizeof(buf) - 2; - auto cached_time = get_config()->cached_time; - for(auto& lf : lfv) { switch(lf.type) { case SHRPX_LOGF_LITERAL: @@ -203,7 +202,10 @@ void upstream_accesslog(const std::vector& lfv, LogSpec *lgsp) std::tie(p, avail) = copy(lgsp->remote_addr, avail, p); break; case SHRPX_LOGF_TIME_LOCAL: - std::tie(p, avail) = copy(cached_time->c_str(), avail, p); + std::tie(p, avail) = copy(util::format_common_log(lgsp->time_now).c_str(), avail, p); + break; + case SHRPX_LOGF_TIME_ISO8601: + std::tie(p, avail) = copy(util::format_iso8601(lgsp->time_now).c_str(), avail, p); break; case SHRPX_LOGF_REQUEST: std::tie(p, avail) = copy(lgsp->method, avail, p); @@ -232,6 +234,31 @@ void upstream_accesslog(const std::vector& lfv, LogSpec *lgsp) std::tie(p, avail) = copy("-", avail, p); + break; + case SHRPX_LOGF_REMOTE_PORT: + std::tie(p, avail) = copy(lgsp->remote_port, avail, p); + break; + case SHRPX_LOGF_SERVER_PORT: + std::tie(p, avail) = copy(util::utos(lgsp->server_port).c_str(), + avail, p); + break; + case SHRPX_LOGF_REQUEST_TIME: + { + auto t = std::chrono::duration_cast + (lgsp->time_now - lgsp->request_start_time).count(); + + auto frac = util::utos(t % 1000); + auto sec = util::utos(t / 1000); + if (frac.size() < 3) { + frac = std::string(3 - frac.size(), '0') + frac; + } + sec += "."; + sec += frac; + + std::tie(p, avail) = copy( sec.c_str(), avail, p); + } + break; + case SHRPX_LOGF_NONE: break; default: break; diff --git a/src/shrpx_log.h b/src/shrpx_log.h index 79fab4e7..342450d3 100644 --- a/src/shrpx_log.h +++ b/src/shrpx_log.h @@ -30,6 +30,7 @@ #include #include #include +#include namespace shrpx { @@ -107,10 +108,14 @@ enum LogFragmentType { SHRPX_LOGF_LITERAL, SHRPX_LOGF_REMOTE_ADDR, SHRPX_LOGF_TIME_LOCAL, + SHRPX_LOGF_TIME_ISO8601, SHRPX_LOGF_REQUEST, SHRPX_LOGF_STATUS, SHRPX_LOGF_BODY_BYTES_SENT, SHRPX_LOGF_HTTP, + SHRPX_LOGF_REMOTE_PORT, + SHRPX_LOGF_SERVER_PORT, + SHRPX_LOGF_REQUEST_TIME, }; struct LogFragment { @@ -123,9 +128,13 @@ struct LogSpec { const char *remote_addr; const char *method; const char *path; + std::chrono::high_resolution_clock::time_point request_start_time; + std::chrono::high_resolution_clock::time_point time_now; int major, minor; unsigned int status; int64_t body_bytes_sent; + const char *remote_port; + uint16_t server_port; }; void upstream_accesslog(const std::vector& lf, LogSpec *lgsp); diff --git a/src/shrpx_spdy_upstream.cc b/src/shrpx_spdy_upstream.cc index dd52a5eb..a7135614 100644 --- a/src/shrpx_spdy_upstream.cc +++ b/src/shrpx_spdy_upstream.cc @@ -214,6 +214,8 @@ void on_ctrl_recv_callback downstream->set_request_path(path); } + downstream->set_request_start_time(std::chrono::high_resolution_clock::now()); + if(!(frame->syn_stream.hd.flags & SPDYLAY_CTRL_FLAG_FIN)) { downstream->set_request_http2_expect_body(true); } diff --git a/src/shrpx_ssl.cc b/src/shrpx_ssl.cc index 03e1c1bd..b9e195bc 100644 --- a/src/shrpx_ssl.cc +++ b/src/shrpx_ssl.cc @@ -476,9 +476,10 @@ ClientHandler* accept_connection DownstreamConnectionPool *dconn_pool) { char host[NI_MAXHOST]; + char service[NI_MAXSERV]; int rv; - rv = getnameinfo(addr, addrlen, host, sizeof(host), nullptr, 0, - NI_NUMERICHOST); + rv = getnameinfo(addr, addrlen, host, sizeof(host), + service, sizeof(service), NI_NUMERICHOST); if(rv != 0) { LOG(ERROR) << "getnameinfo() failed: " << gai_strerror(rv); @@ -522,8 +523,8 @@ ClientHandler* accept_connection return nullptr; } - return new ClientHandler(bev, rate_limit_group, fd, ssl, host, worker_stat, - dconn_pool); + return new ClientHandler(bev, rate_limit_group, fd, ssl, host, service, + worker_stat, dconn_pool); } namespace { diff --git a/src/util.cc b/src/util.cc index 124c3102..b40fd40c 100644 --- a/src/util.cc +++ b/src/util.cc @@ -715,25 +715,6 @@ std::vector get_default_alpn() return res; } -std::string format_iso8601(const std::chrono::system_clock::time_point& tp) -{ - auto t = std::chrono::duration_cast - (tp.time_since_epoch()); - time_t sec = t.count() / 1000; - - tm tms; - if(gmtime_r(&sec, &tms) == nullptr) { - return ""; - } - - char buf[128]; - - auto nwrite = strftime(buf, sizeof(buf), "%Y-%m-%dT%H:%M:%S", &tms); - snprintf(&buf[nwrite], sizeof(buf) - nwrite, ".%03ldZ", t.count() % 1000); - - return buf; -} - } // namespace util } // namespace nghttp2 diff --git a/src/util.h b/src/util.h index 880b9a74..916fe84c 100644 --- a/src/util.h +++ b/src/util.h @@ -483,9 +483,61 @@ bool check_h2_is_selected(const unsigned char *alpn, size_t len); // HTTP/2 protocol identifier. std::vector get_default_alpn(); +// Returns given time |tp| in Common Log format (e.g., +// 03/Jul/2014:00:19:38 +0900) +// Expected type of |tp| is std::chrono::timepoint +template +std::string format_common_log(const T& tp) +{ + auto t = std::chrono::duration_cast + (tp.time_since_epoch()); + time_t sec = t.count() / 1000; + + tm tms; + if(localtime_r(&sec, &tms) == nullptr) { + return ""; + } + + char buf[32]; + + strftime(buf, sizeof(buf), "%d/%b/%Y:%T %z", &tms); + + return buf; +} // Returns given time |tp| in ISO 8601 format (e.g., // 2014-11-15T12:58:24.741Z) -std::string format_iso8601(const std::chrono::system_clock::time_point& tp); +// Expected type of |tp| is std::chrono::timepoint +template +std::string format_iso8601(const T& tp) +{ + auto t = std::chrono::duration_cast + (tp.time_since_epoch()); + time_t sec = t.count() / 1000; + + tm tms; + if(gmtime_r(&sec, &tms) == nullptr) { + return ""; + } + + char buf[128]; + + auto nwrite = strftime(buf, sizeof(buf), "%Y-%m-%dT%H:%M:%S", &tms); + snprintf(&buf[nwrite], sizeof(buf) - nwrite, ".%03ldZ", t.count() % 1000); + + return buf; +} + +// Return the system precision of the template parameter |Clock| as +// a nanosecond value of type |Rep| +template +Rep +clock_precision() +{ + std::chrono::duration duration = typename Clock::duration(1); + + return duration.count(); +} + } // namespace util