nghttpx: Add configurable access logging format

This commit adds functionality to customize access logging format in
nghttpx.  The format variables are inspired by nginx.  The default
format is combined format.

src/shrpx-unittest.cc

@@ -112,6 +112,8 @@ int main(int argc, char* argv[])
                    shrpx::test_shrpx_config_parse_config_str_list) ||
       !CU_add_test(pSuite, "config_parse_header",
                    shrpx::test_shrpx_config_parse_header) ||
+      !CU_add_test(pSuite, "config_parse_log_format",
+                   shrpx::test_shrpx_config_parse_log_format) ||
       !CU_add_test(pSuite, "util_streq", shrpx::test_util_streq) ||
       !CU_add_test(pSuite, "util_strieq", shrpx::test_util_strieq) ||
       !CU_add_test(pSuite, "util_inp_strlower",

src/shrpx.cc

@@ -682,6 +682,13 @@ namespace {
 const char *DEFAULT_TLS_PROTO_LIST = "TLSv1.2,TLSv1.1";
 } // namespace
 
+namespace {
+const char *DEFAULT_ACCESSLOG_FORMAT =
+  "$remote_addr - - [$time_local] "
+  "\"$request\" $status $body_bytes_sent "
+  "\"$http_referer\" \"$http_user_agent\"";
+} // namespace
+
 namespace {
 void fill_default_config()
 {
@@ -745,6 +752,7 @@ void fill_default_config()
   mod_config()->no_via = false;
   mod_config()->accesslog_file = nullptr;
   mod_config()->accesslog_syslog = false;
+  mod_config()->accesslog_format = parse_log_format(DEFAULT_ACCESSLOG_FORMAT);
 #if defined(__ANDROID__) || defined(ANDROID)
   // Android does not have /dev/stderr.  Use /proc/self/fd/2 instead.
   mod_config()->errorlog_file = strcopy("/proc/self/fd/2");
@@ -1133,6 +1141,17 @@ Logging:
   --accesslog-syslog
                      Send  access log  to syslog.   If this  option is
                      used, --access-file option is ignored.
+  --accesslog-format=<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_<VAR>: value
+                     of HTTP request header <VAR>.
+                     Default: )"
+      << DEFAULT_ACCESSLOG_FORMAT << R"(
   --errorlog-file=<PATH>
                      Set  path to  write error  log.  To  reopen file,
                      send USR1 signal to nghttpx.
@@ -1305,6 +1324,7 @@ int main(int argc, char **argv)
       {"backend-connections-per-frontend", required_argument, &flag, 63},
       {"listener-disable-timeout", required_argument, &flag, 64},
       {"strip-incoming-x-forwarded-for", no_argument, &flag, 65},
+      {"accesslog-format", required_argument, &flag, 66},
       {nullptr, 0, nullptr, 0 }
     };
 
@@ -1606,6 +1626,10 @@ int main(int argc, char **argv)
         // --strip-incoming-x-forwarded-for
         cmdcfgs.emplace_back(SHRPX_OPT_STRIP_INCOMING_X_FORWARDED_FOR, "yes");
         break;
+      case 66:
+        // --accesslog-format
+        cmdcfgs.emplace_back(SHRPX_OPT_ACCESSLOG_FORMAT, optarg);
+        break;
       default:
         break;
       }

src/shrpx_client_handler.cc

@@ -37,6 +37,7 @@
 #include "shrpx_worker.h"
 #include "shrpx_worker_config.h"
 #include "shrpx_downstream_connection_pool.h"
+#include "shrpx_downstream.h"
 #ifdef HAVE_SPDYLAY
 #include "shrpx_spdy_upstream.h"
 #endif // HAVE_SPDYLAY
@@ -720,4 +721,41 @@ void ClientHandler::update_last_write_time()
   }
 }
 
+void ClientHandler::write_accesslog(Downstream *downstream)
+{
+  LogSpec lgsp = {
+    downstream,
+    ipaddr_.c_str(),
+    downstream->get_request_method().c_str(),
+
+    downstream->get_request_path().empty() ?
+    downstream->get_request_http2_authority().c_str() :
+    downstream->get_request_path().c_str(),
+
+    downstream->get_request_major(),
+    downstream->get_request_minor(),
+    downstream->get_response_http_status(),
+    downstream->get_response_sent_bodylen()
+  };
+
+  upstream_accesslog(get_config()->accesslog_format, &lgsp);
+}
+
+void ClientHandler::write_accesslog(int major, int minor,
+                                    unsigned int status,
+                                    int64_t body_bytes_sent)
+{
+  LogSpec lgsp = {
+    nullptr,
+    ipaddr_.c_str(),
+    "-", // method
+    "-", // path,
+    major, minor, // major, minor
+    status,
+    body_bytes_sent
+  };
+
+  upstream_accesslog(get_config()->accesslog_format, &lgsp);
+}
+
 } // namespace shrpx

src/shrpx_client_handler.h

@@ -105,6 +105,15 @@ public:
   void update_warmup_writelen(size_t n);
   // Updates the time when last write was done.
   void update_last_write_time();
+
+  // Writes upstream accesslog using |downstream|.  The |downstream|
+  // 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);
 private:
   std::unique_ptr<Upstream> upstream_;
   std::string ipaddr_;

src/shrpx_config.cc

@@ -79,6 +79,7 @@ const char SHRPX_OPT_STREAM_READ_TIMEOUT[] = "stream-read-timeout";
 const char SHRPX_OPT_STREAM_WRITE_TIMEOUT[] = "stream-write-timeout";
 const char SHRPX_OPT_ACCESSLOG_FILE[] = "accesslog-file";
 const char SHRPX_OPT_ACCESSLOG_SYSLOG[] = "accesslog-syslog";
+const char SHRPX_OPT_ACCESSLOG_FORMAT[] = "accesslog-format";
 const char SHRPX_OPT_ERRORLOG_FILE[] = "errorlog-file";
 const char SHRPX_OPT_ERRORLOG_SYSLOG[] = "errorlog-syslog";
 const char
@@ -236,18 +237,20 @@ std::string read_passwd_from_file(const char *filename)
 
 std::unique_ptr<char[]> strcopy(const char *val)
 {
-  auto len = strlen(val);
+  return strcopy(val, strlen(val));
+}
+
+std::unique_ptr<char[]> strcopy(const char *val, size_t len)
+{
   auto res = util::make_unique<char[]>(len + 1);
-  memcpy(res.get(), val, len + 1);
+  memcpy(res.get(), val, len);
+  res[len] = '\0';
   return res;
 }
 
 std::unique_ptr<char[]> strcopy(const std::string& val)
 {
-  auto len = val.size();
+  return strcopy(val.c_str(), val.size());
-  auto res = util::make_unique<char[]>(len + 1);
-  memcpy(res.get(), val.c_str(), len + 1);
-  return res;
 }
 
 std::vector<char*> parse_config_str_list(const char *s)
@@ -336,6 +339,97 @@ int parse_int(T *dest, const char *opt, const char *optarg)
   return 0;
 }
 
+namespace {
+LogFragment make_log_fragment(LogFragmentType type,
+                              std::unique_ptr<char[]> value = nullptr)
+{
+  return LogFragment{type, std::move(value)};
+}
+} // namespace
+
+namespace {
+bool var_token(char c)
+{
+  return util::isAlpha(c) || util::isDigit(c) || c == '_';
+}
+} // namespace
+
+std::vector<LogFragment> parse_log_format(const char *optarg)
+{
+  auto literal_start = optarg;
+  auto p = optarg;
+  auto eop = p + strlen(optarg);
+
+  auto res = std::vector<LogFragment>();
+
+  for(; p != eop;) {
+    if(*p != '$') {
+      ++p;
+      continue;
+    }
+
+    auto var_start = p;
+
+    ++p;
+
+    for(; p != eop && var_token(*p); ++p);
+
+    auto varlen = p - var_start;
+
+    auto type = SHRPX_LOGF_NONE;
+    const char *value = nullptr;
+    size_t valuelen = 0;
+
+    if(util::strieq("$remote_addr", var_start, varlen)) {
+      type = SHRPX_LOGF_REMOTE_ADDR;
+    } else if(util::strieq("$time_local", var_start, varlen)) {
+      type = SHRPX_LOGF_TIME_LOCAL;
+    } else if(util::strieq("$request", var_start, varlen)) {
+      type = SHRPX_LOGF_REQUEST;
+    } else if(util::strieq("$status", var_start, varlen)) {
+      type = SHRPX_LOGF_STATUS;
+    } else if(util::strieq("$body_bytes_sent", var_start, varlen)) {
+      type = SHRPX_LOGF_BODY_BYTES_SENT;
+    } else if(util::istartsWith(var_start, varlen, "$http_")) {
+      type = SHRPX_LOGF_HTTP;
+      value = var_start + sizeof("$http_") - 1;
+      valuelen = varlen - (sizeof("$http_") - 1);
+    } else {
+      LOG(WARN) << "Unrecognized log format variable: "
+                << std::string(var_start, varlen);
+      continue;
+    }
+
+    if(literal_start < var_start) {
+      res.push_back(make_log_fragment
+                    (SHRPX_LOGF_LITERAL,
+                     strcopy(literal_start, var_start - literal_start)));
+    }
+
+    if(value == nullptr) {
+      res.push_back(make_log_fragment(type));
+    } else {
+      res.push_back(make_log_fragment(type, strcopy(value, valuelen)));
+      auto& v = res.back().value;
+      for(size_t i = 0; v[i]; ++i) {
+        if(v[i] == '_') {
+          v[i] = '-';
+        }
+      }
+    }
+
+    literal_start = var_start + varlen;
+  }
+
+  if(literal_start != eop) {
+    res.push_back(make_log_fragment
+                  (SHRPX_LOGF_LITERAL,
+                   strcopy(literal_start, eop - literal_start)));
+  }
+
+  return res;
+}
+
 namespace {
 int parse_timeval(timeval *dest, const char *opt, const char *optarg)
 {
@@ -479,6 +573,12 @@ int parse_config(const char *opt, const char *optarg)
     return 0;
   }
 
+  if(util::strieq(opt, SHRPX_OPT_ACCESSLOG_FORMAT)) {
+    mod_config()->accesslog_format = parse_log_format(optarg);
+
+    return 0;
+  }
+
   if(util::strieq(opt, SHRPX_OPT_ERRORLOG_FILE)) {
     mod_config()->errorlog_file = strcopy(optarg);
 

src/shrpx_config.h

@@ -44,6 +44,8 @@
 
 namespace shrpx {
 
+struct LogFragment;
+
 namespace ssl {
 
 struct CertLookupTree;
@@ -76,6 +78,7 @@ extern const char SHRPX_OPT_STREAM_READ_TIMEOUT[];
 extern const char SHRPX_OPT_STREAM_WRITE_TIMEOUT[];
 extern const char SHRPX_OPT_ACCESSLOG_FILE[];
 extern const char SHRPX_OPT_ACCESSLOG_SYSLOG[];
+extern const char SHRPX_OPT_ACCESSLOG_FORMAT[];
 extern const char SHRPX_OPT_ERRORLOG_FILE[];
 extern const char SHRPX_OPT_ERRORLOG_SYSLOG[];
 extern const char SHRPX_OPT_BACKEND_KEEP_ALIVE_TIMEOUT[];
@@ -163,6 +166,7 @@ struct Config {
   std::vector<AltSvc> altsvcs;
   std::vector<std::pair<std::string, std::string>> add_response_headers;
   std::vector<unsigned char> alpn_prefs;
+  std::vector<LogFragment> accesslog_format;
   std::shared_ptr<std::string> cached_time;
   sockaddr_union downstream_addr;
   // binary form of http proxy host and port
@@ -318,9 +322,15 @@ void clear_config_str_list(std::vector<char*>& list);
 // allowed.  This function returns pair of NAME and VALUE.
 std::pair<std::string, std::string> parse_header(const char *optarg);
 
+std::vector<LogFragment> parse_log_format(const char *optarg);
+
 // Returns a copy of NULL-terminated string |val|.
 std::unique_ptr<char[]> strcopy(const char *val);
 
+// Returns a copy of string |val| of length |n|.  The returned string
+// will be NULL-terminated.
+std::unique_ptr<char[]> strcopy(const char *val, size_t n);
+
 // Returns a copy of val.c_str().
 std::unique_ptr<char[]> strcopy(const std::string& val);
 

src/shrpx_config_test.cc

@@ -90,4 +90,49 @@ void test_shrpx_config_parse_header(void)
   CU_ASSERT("bravo charlie" == p.second);
 }
 
+void test_shrpx_config_parse_log_format(void)
+{
+  auto res = parse_log_format("$remote_addr - $remote_user [$time_local] "
+                              "\"$request\" $status $body_bytes_sent "
+                              "\"$http_referer\" \"$http_user_agent\"");
+  CU_ASSERT(14 == res.size());
+
+  CU_ASSERT(SHRPX_LOGF_REMOTE_ADDR == res[0].type);
+
+  CU_ASSERT(SHRPX_LOGF_LITERAL == res[1].type);
+  CU_ASSERT(0 == strcmp(" - $remote_user [", res[1].value.get()));
+
+  CU_ASSERT(SHRPX_LOGF_TIME_LOCAL == res[2].type);
+
+  CU_ASSERT(SHRPX_LOGF_LITERAL == res[3].type);
+  CU_ASSERT(0 == strcmp("] \"", res[3].value.get()));
+
+  CU_ASSERT(SHRPX_LOGF_REQUEST == res[4].type);
+
+  CU_ASSERT(SHRPX_LOGF_LITERAL == res[5].type);
+  CU_ASSERT(0 == strcmp("\" ", res[5].value.get()));
+
+  CU_ASSERT(SHRPX_LOGF_STATUS == res[6].type);
+
+  CU_ASSERT(SHRPX_LOGF_LITERAL == res[7].type);
+  CU_ASSERT(0 == strcmp(" ", res[7].value.get()));
+
+  CU_ASSERT(SHRPX_LOGF_BODY_BYTES_SENT == res[8].type);
+
+  CU_ASSERT(SHRPX_LOGF_LITERAL == res[9].type);
+  CU_ASSERT(0 == strcmp(" \"", res[9].value.get()));
+
+  CU_ASSERT(SHRPX_LOGF_HTTP == res[10].type);
+  CU_ASSERT(0 == strcmp("referer", res[10].value.get()));
+
+  CU_ASSERT(SHRPX_LOGF_LITERAL == res[11].type);
+  CU_ASSERT(0 == strcmp("\" \"", res[11].value.get()));
+
+  CU_ASSERT(SHRPX_LOGF_HTTP == res[12].type);
+  CU_ASSERT(0 == strcmp("user-agent", res[12].value.get()));
+
+  CU_ASSERT(SHRPX_LOGF_LITERAL == res[13].type);
+  CU_ASSERT(0 == strcmp("\"", res[13].value.get()));
+}
+
 } // namespace shrpx

src/shrpx_config_test.h

@@ -29,6 +29,7 @@ namespace shrpx {
 
 void test_shrpx_config_parse_config_str_list(void);
 void test_shrpx_config_parse_header(void);
+void test_shrpx_config_parse_log_format(void);
 
 } // namespace shrpx
 

src/shrpx_downstream.cc

@@ -41,6 +41,7 @@ namespace shrpx {
 Downstream::Downstream(Upstream *upstream, int32_t stream_id, int32_t priority)
   : request_bodylen_(0),
     response_bodylen_(0),
+    response_sent_bodylen_(0),
     upstream_(upstream),
     response_body_buf_(nullptr),
     upstream_rtimerev_(nullptr),
@@ -73,7 +74,8 @@ Downstream::Downstream(Upstream *upstream, int32_t stream_id, int32_t priority)
     chunked_response_(false),
     response_connection_close_(false),
     response_header_key_prev_(false),
-    expect_final_response_(false)
+    expect_final_response_(false),
+    request_headers_normalized_(false)
 {}
 
 Downstream::~Downstream()
@@ -191,6 +193,19 @@ Headers::iterator get_norm_header(Headers& headers, const std::string& name)
 }
 } // namespace
 
+namespace {
+Headers::const_iterator get_header_linear(const Headers& headers,
+                                          const std::string& name)
+{
+  auto i = std::find_if(std::begin(headers), std::end(headers),
+                        [&name](const Header& header)
+                        {
+                          return header.name == name;
+                        });
+  return i;
+}
+} // namespace
+
 const Headers& Downstream::get_request_headers() const
 {
   return request_headers_;
@@ -257,6 +272,9 @@ void Downstream::crumble_request_cookie()
   request_headers_.insert(std::end(request_headers_),
                           std::make_move_iterator(std::begin(cookie_hdrs)),
                           std::make_move_iterator(std::end(cookie_hdrs)));
+  if(request_headers_normalized_) {
+    normalize_request_headers();
+  }
 }
 
 const std::string& Downstream::get_assembled_request_cookie() const
@@ -267,6 +285,7 @@ const std::string& Downstream::get_assembled_request_cookie() const
 void Downstream::normalize_request_headers()
 {
   http2::normalize_headers(request_headers_);
+  request_headers_normalized_ = true;
 }
 
 Headers::const_iterator Downstream::get_norm_request_header
@@ -275,6 +294,21 @@ Headers::const_iterator Downstream::get_norm_request_header
   return get_norm_header(request_headers_, name);
 }
 
+Headers::const_iterator Downstream::get_request_header
+(const std::string& name) const
+{
+  if(request_headers_normalized_) {
+    return get_norm_request_header(name);
+  }
+
+  return get_header_linear(request_headers_, name);
+}
+
+bool Downstream::get_request_headers_normalized() const
+{
+  return request_headers_normalized_;
+}
+
 void Downstream::add_request_header(std::string name, std::string value)
 {
   request_header_key_prev_ = true;
@@ -449,16 +483,6 @@ void Downstream::set_request_connection_close(bool f)
   request_connection_close_ = f;
 }
 
-void Downstream::set_request_user_agent(std::string user_agent)
-{
-  request_user_agent_ = std::move(user_agent);
-}
-
-const std::string& Downstream::get_request_user_agent() const
-{
-  return request_user_agent_;
-}
-
 bool Downstream::get_request_http2_expect_body() const
 {
   return request_http2_expect_body_;
@@ -732,6 +756,16 @@ int64_t Downstream::get_response_bodylen() const
   return response_bodylen_;
 }
 
+void Downstream::add_response_sent_bodylen(size_t amount)
+{
+  response_sent_bodylen_ += amount;
+}
+
+int64_t Downstream::get_response_sent_bodylen() const
+{
+  return response_sent_bodylen_;
+}
+
 void Downstream::set_priority(int32_t pri)
 {
   priority_ = pri;

src/shrpx_downstream.h

@@ -107,6 +107,13 @@ public:
   // called after calling normalize_request_headers().
   Headers::const_iterator get_norm_request_header
   (const std::string& name) const;
+  // Returns iterator pointing to the request header with the name
+  // |name|.  This function acts like get_norm_request_header(), but
+  // if request_headers_ was not normalized, use linear search to find
+  // the header.  Otherwise, get_norm_request_header() is used.
+  Headers::const_iterator get_request_header
+  (const std::string& name) const;
+  bool get_request_headers_normalized() const;
   void add_request_header(std::string name, std::string value);
   void set_last_request_header_value(std::string value);
 
@@ -144,8 +151,6 @@ public:
   void set_chunked_request(bool f);
   bool get_request_connection_close() const;
   void set_request_connection_close(bool f);
-  void set_request_user_agent(std::string user_agent);
-  const std::string& get_request_user_agent() const;
   bool get_request_http2_expect_body() const;
   void set_request_http2_expect_body(bool f);
   int push_upload_data_chunk(const uint8_t *data, size_t datalen);
@@ -215,6 +220,8 @@ public:
   evbuffer* get_response_body_buf();
   void add_response_bodylen(size_t amount);
   int64_t get_response_bodylen() const;
+  void add_response_sent_bodylen(size_t amount);
+  int64_t get_response_sent_bodylen() const;
   uint32_t get_response_rst_stream_error_code() const;
   void set_response_rst_stream_error_code(uint32_t error_code);
   // Inspects HTTP/1 response.  This checks tranfer-encoding etc.
@@ -275,7 +282,6 @@ private:
 
   std::string request_method_;
   std::string request_path_;
-  std::string request_user_agent_;
   std::string request_http2_scheme_;
   std::string request_http2_authority_;
   std::string assembled_request_cookie_;
@@ -285,6 +291,8 @@ private:
   int64_t request_bodylen_;
   // the length of response body
   int64_t response_bodylen_;
+  // the length of response body sent to upstream client
+  int64_t response_sent_bodylen_;
 
   Upstream *upstream_;
   std::unique_ptr<DownstreamConnection> dconn_;
@@ -340,6 +348,9 @@ private:
   bool response_connection_close_;
   bool response_header_key_prev_;
   bool expect_final_response_;
+
+  // true if request_headers_ is normalized
+  bool request_headers_normalized_;
 };
 
 } // namespace shrpx

src/shrpx_http2_downstream_connection.cc

@@ -274,7 +274,8 @@ int Http2DownstreamConnection::push_request_headers()
   if(!get_config()->http2_no_cookie_crumbling) {
     downstream_->crumble_request_cookie();
   }
-  downstream_->normalize_request_headers();
+
+  assert(downstream_->get_request_headers_normalized());
 
   auto end_headers = std::end(downstream_->get_request_headers());
 

src/shrpx_http2_upstream.cc

@@ -323,7 +323,6 @@ int on_request_headers(Http2Upstream *upstream,
   auto path = http2::get_unique_header(nva, ":path");
   auto method = http2::get_unique_header(nva, ":method");
   auto scheme = http2::get_unique_header(nva, ":scheme");
-  auto user_agent = http2::get_header(nva, "user-agent");
 
   bool is_connect = method  && "CONNECT" == method->value;
   bool having_host = http2::non_empty_value(host);
@@ -356,7 +355,6 @@ 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_user_agent(http2::value_to_str(user_agent));
 
   if(!(frame->hd.flags & NGHTTP2_FLAG_END_STREAM)) {
     downstream->set_request_http2_expect_body(true);
@@ -1110,10 +1108,6 @@ ssize_t downstream_data_read_callback(nghttp2_session *session,
 
     if(!downstream->get_upgraded()) {
 
-      upstream_accesslog(upstream->get_client_handler()->get_ipaddr(),
-                         downstream->get_response_http_status(),
-                         downstream);
-
       if(nghttp2_session_get_stream_remote_close(session, stream_id) == 0) {
         upstream->rst_stream(downstream, NGHTTP2_NO_ERROR);
       }
@@ -1141,6 +1135,10 @@ ssize_t downstream_data_read_callback(nghttp2_session *session,
     return NGHTTP2_ERR_DEFERRED;
   }
 
+  if(nread > 0) {
+    downstream->add_response_sent_bodylen(nread);
+  }
+
   return nread;
 }
 } // namespace
@@ -1207,6 +1205,10 @@ void Http2Upstream::add_pending_downstream
 
 void Http2Upstream::remove_downstream(Downstream *downstream)
 {
+  if(downstream->get_response_state() == Downstream::MSG_COMPLETE) {
+    handler_->write_accesslog(downstream);
+  }
+
   downstream_queue_.remove(downstream->get_stream_id());
 
   maintain_downstream_concurrency();
@@ -1329,14 +1331,6 @@ int Http2Upstream::on_downstream_header_complete(Downstream *downstream)
     return -1;
   }
 
-  if(downstream->get_upgraded()) {
-    upstream_accesslog(get_client_handler()->get_ipaddr(),
-                       downstream->get_response_http_status(), downstream);
-  }
-
-  downstream->clear_response_headers();
-  downstream->clear_request_headers();
-
   return 0;
 }
 

src/shrpx_http_downstream_connection.cc

@@ -142,8 +142,10 @@ int HttpDownstreamConnection::attach_downstream(Downstream *downstream)
 
 int HttpDownstreamConnection::push_request_headers()
 {
+  assert(downstream_->get_request_headers_normalized());
+
   downstream_->assemble_request_cookie();
-  downstream_->normalize_request_headers();
+
   auto end_headers = std::end(downstream_->get_request_headers());
   // Assume that method and request path do not contain \r\n.
   std::string hdrs = downstream_->get_request_method();

src/shrpx_https_upstream.cc

@@ -57,7 +57,12 @@ HttpsUpstream::HttpsUpstream(ClientHandler *handler)
 }
 
 HttpsUpstream::~HttpsUpstream()
-{}
+{
+  if(downstream_ &&
+     downstream_->get_response_state() == Downstream::MSG_COMPLETE) {
+    handler_->write_accesslog(downstream_.get());
+  }
+}
 
 void HttpsUpstream::reset_current_header_length()
 {
@@ -161,11 +166,6 @@ int htp_hdrs_completecb(http_parser *htp)
   }
 
   downstream->normalize_request_headers();
-  auto& nva = downstream->get_request_headers();
-
-  auto user_agent = http2::get_header(nva, "user-agent");
-
-  downstream->set_request_user_agent(http2::value_to_str(user_agent));
 
   downstream->inspect_http1_request();
 
@@ -712,7 +712,10 @@ int HttpsUpstream::error_reply(unsigned int status_code)
   }
 
   if(downstream) {
+    downstream->add_response_sent_bodylen(html.size());
     downstream->set_response_state(Downstream::MSG_COMPLETE);
+  } else {
+    handler_->write_accesslog(1, 1, status_code, html.size());
   }
 
   return 0;
@@ -741,6 +744,11 @@ void HttpsUpstream::attach_downstream(std::unique_ptr<Downstream> downstream)
 
 void HttpsUpstream::delete_downstream()
 {
+  if(downstream_ &&
+     downstream_->get_response_state() == Downstream::MSG_COMPLETE) {
+    handler_->write_accesslog(downstream_.get());
+  }
+
   downstream_.reset();
 }
 
@@ -884,14 +892,6 @@ int HttpsUpstream::on_downstream_header_complete(Downstream *downstream)
     return -1;
   }
 
-  if(downstream->get_upgraded()) {
-    upstream_accesslog(this->get_client_handler()->get_ipaddr(),
-                       downstream->get_response_http_status(), downstream);
-  }
-
-  downstream->clear_response_headers();
-  downstream->clear_request_headers();
-
   return 0;
 }
 
@@ -920,6 +920,8 @@ int HttpsUpstream::on_downstream_body(Downstream *downstream,
     return -1;
   }
 
+  downstream->add_response_sent_bodylen(len);
+
   if(downstream->get_chunked_response()) {
     if(evbuffer_add(output, "\r\n", 2) != 0) {
       ULOG(FATAL, this) << "evbuffer_add() failed";
@@ -942,12 +944,6 @@ int HttpsUpstream::on_downstream_body_complete(Downstream *downstream)
     DLOG(INFO, downstream) << "HTTP response completed";
   }
 
-  if(!downstream->get_upgraded()) {
-    upstream_accesslog(get_client_handler()->get_ipaddr(),
-                       downstream->get_response_http_status(),
-                       downstream);
-  }
-
   if(downstream->get_request_connection_close() ||
      downstream->get_response_connection_close()) {
     auto handler = get_client_handler();

src/shrpx_log.cc

@@ -105,6 +105,10 @@ Log::~Log()
 {
   int rv;
 
+  if(!get_config()) {
+    return;
+  }
+
   auto wconf = worker_config;
 
   if(!log_enabled(severity_) ||
@@ -162,8 +166,18 @@ Log::~Log()
   while(write(wconf->errorlog_fd, buf, nwrite) == -1 && errno == EINTR);
 }
 
-void upstream_accesslog(const std::string& client_ip, unsigned int status_code,
+namespace {
-                        Downstream *downstream)
+template<typename OutputIterator>
+std::pair<OutputIterator, size_t>
+copy(const char *src, size_t avail, OutputIterator oitr)
+{
+  auto nwrite = std::min(strlen(src), avail);
+  auto noitr = std::copy_n(src, nwrite, oitr);
+  return std::make_pair(noitr, avail - nwrite);
+}
+} // namespace
+
+void upstream_accesslog(const std::vector<LogFragment>& lfv, LogSpec *lgsp)
 {
   auto wconf = worker_config;
 
@@ -171,60 +185,60 @@ void upstream_accesslog(const std::string& client_ip, unsigned int status_code,
     return;
   }
 
-  char buf[1024];
+  char buf[4096];
-  int rv;
 
-  const char *path;
+  auto downstream = lgsp->downstream;
-  const char *method;
-  unsigned int major, minor;
-  const char *user_agent;
-  int64_t response_bodylen;
 
-  if(!downstream) {
+  auto p = buf;
-    path = "-";
+  auto avail = sizeof(buf) - 2;
-    method = "-";
-    major = 1;
-    minor = 0;
-    user_agent = "-";
-    response_bodylen = 0;
-  } else {
-    if(downstream->get_request_path().empty()) {
-      path = downstream->get_request_http2_authority().c_str();
-    } else {
-      path = downstream->get_request_path().c_str();
-    }
-
-    method = downstream->get_request_method().c_str();
-    major = downstream->get_request_major();
-    minor = downstream->get_request_minor();
-    user_agent = downstream->get_request_user_agent().c_str();
-    if(!user_agent[0]) {
-      user_agent = "-";
-    }
-    response_bodylen = downstream->get_response_bodylen();
-  }
-
-  static const char fmt[] =
-    "%s - - [%s] \"%s %s HTTP/%u.%u\" %u %lld \"-\" \"%s\"\n";
 
   auto cached_time = get_config()->cached_time;
 
-  rv = snprintf(buf, sizeof(buf), fmt,
+  for(auto& lf : lfv) {
-                client_ip.c_str(),
+    switch(lf.type) {
-                cached_time->c_str(),
+    case SHRPX_LOGF_LITERAL:
-                method,
+      std::tie(p, avail) = copy(lf.value.get(), avail, p);
-                path,
+      break;
-                major,
+    case SHRPX_LOGF_REMOTE_ADDR:
-                minor,
+      std::tie(p, avail) = copy(lgsp->remote_addr, avail, p);
-                status_code,
+      break;
-                (long long int)response_bodylen,
+    case SHRPX_LOGF_TIME_LOCAL:
-                user_agent);
+      std::tie(p, avail) = copy(cached_time->c_str(), avail, p);
+      break;
+    case SHRPX_LOGF_REQUEST:
+      std::tie(p, avail) = copy(lgsp->method, avail, p);
+      std::tie(p, avail) = copy(" ", avail, p);
+      std::tie(p, avail) = copy(lgsp->path, avail, p);
+      std::tie(p, avail) = copy(" HTTP/", avail, p);
+      std::tie(p, avail) = copy(util::utos(lgsp->major).c_str(), avail, p);
+      std::tie(p, avail) = copy(".", avail, p);
+      std::tie(p, avail) = copy(util::utos(lgsp->minor).c_str(), avail, p);
+      break;
+    case SHRPX_LOGF_STATUS:
+      std::tie(p, avail) = copy(util::utos(lgsp->status).c_str(), avail, p);
+      break;
+    case SHRPX_LOGF_BODY_BYTES_SENT:
+      std::tie(p, avail) = copy(util::utos(lgsp->body_bytes_sent).c_str(),
+                                avail, p);
+      break;
+    case SHRPX_LOGF_HTTP:
+      if(downstream) {
+        auto hd = downstream->get_request_header(lf.value.get());
+        if(hd != std::end(downstream->get_request_headers())) {
+          std::tie(p, avail) = copy((*hd).value.c_str(), avail, p);
+          break;
+        }
+      }
 
-  if(rv < 0) {
+      std::tie(p, avail) = copy("-", avail, p);
-    return;
+
+      break;
+    default:
+      break;
+    }
   }
 
-  auto nwrite = std::min(static_cast<size_t>(rv), sizeof(buf) - 1);
+  *p = '\0';
 
   if(get_config()->accesslog_syslog) {
     syslog(LOG_INFO, "%s", buf);
@@ -232,6 +246,9 @@ void upstream_accesslog(const std::string& client_ip, unsigned int status_code,
     return;
   }
 
+  *p++ = '\n';
+
+  auto nwrite = p - buf;
   while(write(wconf->accesslog_fd, buf, nwrite) == -1 && errno == EINTR);
 }
 

src/shrpx_log.h

@@ -28,6 +28,8 @@
 #include "shrpx.h"
 
 #include <sstream>
+#include <memory>
+#include <vector>
 
 namespace shrpx {
 
@@ -100,8 +102,33 @@ private:
 #define TTY_HTTP_HD (worker_config->errorlog_tty ? "\033[1;34m" : "")
 #define TTY_RST (worker_config->errorlog_tty ? "\033[0m" : "")
 
-void upstream_accesslog(const std::string& client_ip, unsigned int status_code,
+enum LogFragmentType {
-                        Downstream *downstream);
+  SHRPX_LOGF_NONE,
+  SHRPX_LOGF_LITERAL,
+  SHRPX_LOGF_REMOTE_ADDR,
+  SHRPX_LOGF_TIME_LOCAL,
+  SHRPX_LOGF_REQUEST,
+  SHRPX_LOGF_STATUS,
+  SHRPX_LOGF_BODY_BYTES_SENT,
+  SHRPX_LOGF_HTTP,
+};
+
+struct LogFragment {
+  LogFragmentType type;
+  std::unique_ptr<char[]> value;
+};
+
+struct LogSpec {
+  Downstream *downstream;
+  const char *remote_addr;
+  const char *method;
+  const char *path;
+  int major, minor;
+  unsigned int status;
+  int64_t body_bytes_sent;
+};
+
+void upstream_accesslog(const std::vector<LogFragment>& lf, LogSpec *lgsp);
 
 int reopen_log_files();
 

src/shrpx_spdy_upstream.cc

@@ -171,7 +171,6 @@ void on_ctrl_recv_callback
     const char *host = nullptr;
     const char *method = nullptr;
     const char *content_length = nullptr;
-    const char *user_agent = nullptr;
 
     for(size_t i = 0; nv[i]; i += 2) {
       if(strcmp(nv[i], ":path") == 0) {
@@ -185,12 +184,13 @@ void on_ctrl_recv_callback
       } else if(nv[i][0] != ':') {
         if(strcmp(nv[i], "content-length") == 0) {
           content_length = nv[i+1];
-        } else if(strcmp(nv[i], "user-agent") == 0) {
-          user_agent = nv[i+1];
         }
         downstream->add_request_header(nv[i], nv[i+1]);
       }
     }
+
+    downstream->normalize_request_headers();
+
     bool is_connect = method && strcmp("CONNECT", method) == 0;
     if(!path || !host || !method ||
        http2::lws(host) || http2::lws(path) || http2::lws(method) ||
@@ -214,10 +214,6 @@ void on_ctrl_recv_callback
       downstream->set_request_path(path);
     }
 
-    if(user_agent) {
-      downstream->set_request_user_agent(user_agent);
-    }
-
     if(!(frame->syn_stream.hd.flags & SPDYLAY_CTRL_FLAG_FIN)) {
       downstream->set_request_http2_expect_body(true);
     }
@@ -821,9 +817,6 @@ ssize_t spdy_data_read_callback(spdylay_session *session,
      downstream->get_response_state() == Downstream::MSG_COMPLETE) {
     if(!downstream->get_upgraded()) {
       *eof = 1;
-
-      upstream_accesslog(upstream->get_client_handler()->get_ipaddr(),
-                         downstream->get_response_http_status(), downstream);
     } else {
       // For tunneling, issue RST_STREAM to finish the stream.
       if(LOG_ENABLED(INFO)) {
@@ -849,6 +842,10 @@ ssize_t spdy_data_read_callback(spdylay_session *session,
     return SPDYLAY_ERR_DEFERRED;
   }
 
+  if(nread > 0) {
+    downstream->add_response_sent_bodylen(nread);
+  }
+
   return nread;
 }
 } // namespace
@@ -921,6 +918,10 @@ Downstream* SpdyUpstream::add_pending_downstream
 
 void SpdyUpstream::remove_downstream(Downstream *downstream)
 {
+  if(downstream->get_response_state() == Downstream::MSG_COMPLETE) {
+    handler_->write_accesslog(downstream);
+  }
+
   downstream_queue_.remove(downstream->get_stream_id());
 
   maintain_downstream_concurrency();
@@ -1032,14 +1033,6 @@ int SpdyUpstream::on_downstream_header_complete(Downstream *downstream)
     return -1;
   }
 
-  if(downstream->get_upgraded()) {
-    upstream_accesslog(get_client_handler()->get_ipaddr(),
-                       downstream->get_response_http_status(), downstream);
-  }
-
-  downstream->clear_response_headers();
-  downstream->clear_request_headers();
-
   return 0;
 }
 

src/util.cc

@@ -260,6 +260,11 @@ bool istartsWith(const char *a, const char* b)
   return !*b;
 }
 
+bool istartsWith(const char *a, size_t n, const char *b)
+{
+  return istartsWith(a, a + n, b, b + strlen(b));
+}
+
 bool endsWith(const std::string& a, const std::string& b)
 {
   return endsWith(a.begin(), a.end(), b.begin(), b.end());
@@ -297,6 +302,11 @@ bool strieq(const char *a, const uint8_t *b, size_t bn)
   return !*a && b == blast;
 }
 
+bool strieq(const char *a, const char *b, size_t bn)
+{
+  return strieq(a, reinterpret_cast<const uint8_t*>(b), bn);
+}
+
 int strcompare(const char *a, const uint8_t *b, size_t bn)
 {
   assert(a && b);

src/util.h

@@ -257,6 +257,7 @@ bool istartsWith
 
 bool istartsWith(const std::string& a, const std::string& b);
 bool istartsWith(const char *a, const char* b);
+bool istartsWith(const char *a, size_t n, const char *b);
 
 template<typename InputIterator1, typename InputIterator2>
 bool endsWith
@@ -294,6 +295,8 @@ bool strieq(const char *a, const char *b);
 
 bool strieq(const char *a, const uint8_t *b, size_t n);
 
+bool strieq(const char *a, const char *b, size_t n);
+
 template<typename A, typename B>
 bool streq(const A *a, const B *b, size_t bn)
 {