Merge branch 'LPardue-accesslog_port'

src/shrpx.cc

@@ -461,22 +461,7 @@ void graceful_shutdown_signal_cb(evutil_socket_t sig, short events, void *arg)
 namespace {
 std::unique_ptr<std::string> generate_time()
 {
-  char buf[32];
+  return util::make_unique<std::string>(util::format_common_log(std::chrono::system_clock::now()));
-
-  // 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<std::string>("");
-  }
-
-  if(strftime(buf, sizeof(buf), "%d/%b/%Y:%T %z", &tms) == 0) {
-    return util::make_unique<std::string>("");
-  }
-
-  return util::make_unique<std::string>(buf);
 }
 } // 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=<FORMAT>
                      Specify  format  string   for  access  log.   The
                      default format is combined format.  The following
-                     variables are available:  $remote_addr: client IP
+                     variables are available: 
-                     address.   $time_local:  local  time.   $request:
+                       $remote_addr: client IP address
-                     HTTP request line.  $status: HTTP response status
+                       $time_local: local time in Common Log format
-                     code.  $body_bytes_sent: the number of bytes sent
+                       $time_iso8601:  local time in ISO 8601 format
-                     to client  as response body.   $http_<VAR>: value
+                       $request: HTTP request line
-                     of HTTP request header <VAR>.
+                       $status: HTTP response status code.
+                       $body_bytes_sent: the number of bytes sent
+                                         to client  as response body
+                       $http_<VAR>: value of HTTP request header <VAR>
+                       $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=<PATH>

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);

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> upstream_;
   std::string ipaddr_;
+  std::string port_;
   DownstreamConnectionPool *dconn_pool_;
   bufferevent *bev_;
   // Shared HTTP2 session for each thread. NULL if backend is not

src/shrpx_config.cc

@@ -384,6 +384,8 @@ std::vector<LogFragment> 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<LogFragment> 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);

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_;

src/shrpx_downstream.h

@@ -32,6 +32,7 @@
 #include <vector>
 #include <string>
 #include <memory>
+#include <chrono>
 
 #include <event.h>
 #include <event2/bufferevent.h>
@@ -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.
@@ -287,6 +290,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_;
 

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);

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));
 

src/shrpx_log.cc

@@ -33,6 +33,7 @@
 #include <cstring>
 #include <ctime>
 #include <iostream>
+#include <iomanip>
 
 #include "shrpx_config.h"
 #include "shrpx_downstream.h"
@@ -192,8 +193,6 @@ void upstream_accesslog(const std::vector<LogFragment>& 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<LogFragment>& 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<LogFragment>& 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<std::chrono::milliseconds>
+          (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;

src/shrpx_log.h

@@ -30,6 +30,7 @@
 #include <sstream>
 #include <memory>
 #include <vector>
+#include <chrono>
 
 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<LogFragment>& lf, LogSpec *lgsp);

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);
     }

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,
+  rv = getnameinfo(addr, addrlen, host, sizeof(host),
-                   NI_NUMERICHOST);
+                   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,
+  return new ClientHandler(bev, rate_limit_group, fd, ssl, host, service,
-                           dconn_pool);
+                           worker_stat, dconn_pool);
 }
 
 namespace {

src/util.cc

@@ -715,26 +715,6 @@ std::vector<unsigned char> get_default_alpn()
   return res;
 }
 
-std::string format_iso8601(const std::chrono::system_clock::time_point& tp)
-{
-  auto t = std::chrono::duration_cast<std::chrono::milliseconds>
-    (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, ".%03dZ",
-           static_cast<int>(t.count() % 1000));
-
-  return buf;
-}
-
 } // namespace util
 
 } // namespace nghttp2

src/util.h

@@ -483,9 +483,62 @@ bool check_h2_is_selected(const unsigned char *alpn, size_t len);
 // HTTP/2 protocol identifier.
 std::vector<unsigned char> 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 <typename T>
+std::string format_common_log(const T& tp)
+{
+  auto t = std::chrono::duration_cast<std::chrono::milliseconds>
+    (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 <typename T>
+std::string format_iso8601(const T& tp)
+{
+  auto t = std::chrono::duration_cast<std::chrono::milliseconds>
+    (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",
+      static_cast<int>(t.count() % 1000));
+
+  return buf;
+}
+
+// Return the system precision of the template parameter |Clock| as
+// a nanosecond value of type |Rep|
+template <typename Clock, typename Rep>
+Rep
+clock_precision()
+{
+  std::chrono::duration<Rep, std::nano> duration = typename Clock::duration(1);
+
+  return duration.count();
+}
+
 
 } // namespace util