nghttpx: Add --accesslog-write-early option

--accesslog-write-early option is analogous to HAProxy's logasap.  If
used, nghttpx writes access log when response header fields are
received from backend rather than when request transaction finishes.

gennghttpxfun.py

@@ -157,6 +157,7 @@ OPTIONS = [
     "client-psk-secrets",
     "client-no-http2-cipher-black-list",
     "client-ciphers",
+    "accesslog-write-early",
 ]
 
 LOGVARS = [

src/shrpx.cc

@@ -2307,6 +2307,10 @@ Logging:
 
               Default: )"
       << DEFAULT_ACCESSLOG_FORMAT << R"(
+  --accesslog-write-early
+              Write  access  log  when   response  header  fields  are
+              received   from  backend   rather   than  when   request
+              transaction finishes.
   --errorlog-file=<PATH>
               Set path to write error  log.  To reopen file, send USR1
               signal  to nghttpx.   stderr will  be redirected  to the
@@ -3126,6 +3130,7 @@ int main(int argc, char **argv) {
         {SHRPX_OPT_CLIENT_NO_HTTP2_CIPHER_BLACK_LIST.c_str(), no_argument,
          &flag, 149},
         {SHRPX_OPT_CLIENT_CIPHERS.c_str(), required_argument, &flag, 150},
+        {SHRPX_OPT_ACCESSLOG_WRITE_EARLY.c_str(), no_argument, &flag, 151},
         {nullptr, 0, nullptr, 0}};
 
     int option_index = 0;
@@ -3833,6 +3838,11 @@ int main(int argc, char **argv) {
         // --client-ciphers
         cmdcfgs.emplace_back(SHRPX_OPT_CLIENT_CIPHERS, StringRef{optarg});
         break;
+      case 151:
+        // --accesslog-write-early
+        cmdcfgs.emplace_back(SHRPX_OPT_ACCESSLOG_WRITE_EARLY,
+                             StringRef::from_lit("yes"));
+        break;
       default:
         break;
       }

src/shrpx_config.cc

@@ -1786,6 +1786,11 @@ int option_lookup_token(const char *name, size_t namelen) {
         return SHRPX_OPTID_FRONTEND_READ_TIMEOUT;
       }
       break;
+    case 'y':
+      if (util::strieq_l("accesslog-write-earl", name, 20)) {
+        return SHRPX_OPTID_ACCESSLOG_WRITE_EARLY;
+      }
+      break;
     }
     break;
   case 22:
@@ -3290,6 +3295,10 @@ int parse_config(Config *config, int optid, const StringRef &opt,
   case SHRPX_OPTID_CLIENT_CIPHERS:
     config->tls.client.ciphers = make_string_ref(config->balloc, optarg);
 
+    return 0;
+  case SHRPX_OPTID_ACCESSLOG_WRITE_EARLY:
+    config->logging.access.write_early = util::strieq_l("yes", optarg);
+
     return 0;
   case SHRPX_OPTID_CONF:
     LOG(WARN) << "conf: ignored";

src/shrpx_config.h

@@ -325,6 +325,8 @@ constexpr auto SHRPX_OPT_CLIENT_PSK_SECRETS =
 constexpr auto SHRPX_OPT_CLIENT_NO_HTTP2_CIPHER_BLACK_LIST =
     StringRef::from_lit("client-no-http2-cipher-black-list");
 constexpr auto SHRPX_OPT_CLIENT_CIPHERS = StringRef::from_lit("client-ciphers");
+constexpr auto SHRPX_OPT_ACCESSLOG_WRITE_EARLY =
+    StringRef::from_lit("accesslog-write-early");
 
 constexpr size_t SHRPX_OBFUSCATED_NODE_LENGTH = 8;
 
@@ -686,6 +688,9 @@ struct LoggingConfig {
     StringRef file;
     // Send accesslog to syslog, ignoring accesslog_file.
     bool syslog;
+    // Write accesslog when response headers are received from
+    // backend, rather than response body is received and sent.
+    bool write_early;
   } access;
   struct {
     StringRef file;
@@ -888,6 +893,7 @@ enum {
   SHRPX_OPTID_ACCESSLOG_FILE,
   SHRPX_OPTID_ACCESSLOG_FORMAT,
   SHRPX_OPTID_ACCESSLOG_SYSLOG,
+  SHRPX_OPTID_ACCESSLOG_WRITE_EARLY,
   SHRPX_OPTID_ADD_FORWARDED,
   SHRPX_OPTID_ADD_REQUEST_HEADER,
   SHRPX_OPTID_ADD_RESPONSE_HEADER,

src/shrpx_downstream.cc

@@ -138,7 +138,8 @@ Downstream::Downstream(Upstream *upstream, MemchunkPool *mcpool,
       chunked_response_(false),
       expect_final_response_(false),
       request_pending_(false),
-      request_header_sent_(false) {
+      request_header_sent_(false),
+      accesslog_written_(false) {
 
   auto &timeoutconf = get_config()->http2.timeout;
 
@@ -906,7 +907,9 @@ void Downstream::disable_downstream_wtimer() {
   disable_timer(loop, &downstream_wtimer_);
 }
 
-bool Downstream::accesslog_ready() const { return resp_.http_status > 0; }
+bool Downstream::accesslog_ready() const {
+  return !accesslog_written_ && resp_.http_status > 0;
+}
 
 void Downstream::add_retry() { ++num_retry_; }
 
@@ -985,4 +988,6 @@ void Downstream::set_addr(const DownstreamAddr *addr) { addr_ = addr; }
 
 const DownstreamAddr *Downstream::get_addr() const { return addr_; }
 
+void Downstream::set_accesslog_written(bool f) { accesslog_written_ = f; }
+
 } // namespace shrpx

src/shrpx_downstream.h

@@ -406,6 +406,8 @@ public:
 
   const DownstreamAddr *get_addr() const;
 
+  void set_accesslog_written(bool f);
+
   enum {
     EVENT_ERROR = 0x1,
     EVENT_TIMEOUT = 0x2,
@@ -489,6 +491,8 @@ private:
   bool request_pending_;
   // true if downstream request header is considered to be sent.
   bool request_header_sent_;
+  // true if access.log has been written.
+  bool accesslog_written_;
 };
 
 } // namespace shrpx

src/shrpx_http2_session.cc

@@ -1090,11 +1090,15 @@ int on_response_headers(Http2Session *http2session, Downstream *downstream,
   int rv;
 
   auto upstream = downstream->get_upstream();
+  auto handler = upstream->get_client_handler();
   const auto &req = downstream->request();
   auto &resp = downstream->response();
 
   auto &nva = resp.fs.headers();
 
+  auto config = get_config();
+  auto &loggingconf = config->logging;
+
   downstream->set_expect_final_response(false);
 
   auto status = resp.fs.header(http2::HD__STATUS);
@@ -1147,7 +1151,7 @@ int on_response_headers(Http2Session *http2session, Downstream *downstream,
     // On upgrade sucess, both ends can send data
     if (upstream->resume_read(SHRPX_NO_BUFFER, downstream, 0) != 0) {
       // If resume_read fails, just drop connection. Not ideal.
-      delete upstream->get_client_handler();
+      delete handler;
       return -1;
     }
     downstream->set_request_state(Downstream::HEADER_COMPLETE);
@@ -1184,6 +1188,11 @@ int on_response_headers(Http2Session *http2session, Downstream *downstream,
     resp.headers_only = true;
   }
 
+  if (loggingconf.access.write_early && downstream->accesslog_ready()) {
+    handler->write_accesslog(downstream);
+    downstream->set_accesslog_written(true);
+  }
+
   rv = upstream->on_downstream_header_complete(downstream);
   if (rv != 0) {
     // Handling early return (in other words, response was hijacked by

src/shrpx_http_downstream_connection.cc

@@ -822,10 +822,14 @@ namespace {
 int htp_hdrs_completecb(http_parser *htp) {
   auto downstream = static_cast<Downstream *>(htp->data);
   auto upstream = downstream->get_upstream();
+  auto handler = upstream->get_client_handler();
   const auto &req = downstream->request();
   auto &resp = downstream->response();
   int rv;
 
+  auto config = get_config();
+  auto &loggingconf = config->logging;
+
   resp.http_status = htp->status_code;
   resp.http_major = htp->http_major;
   resp.http_minor = htp->http_minor;
@@ -911,6 +915,11 @@ int htp_hdrs_completecb(http_parser *htp) {
     downstream->set_chunked_response(false);
   }
 
+  if (loggingconf.access.write_early && downstream->accesslog_ready()) {
+    handler->write_accesslog(downstream);
+    downstream->set_accesslog_written(true);
+  }
+
   if (upstream->on_downstream_header_complete(downstream) != 0) {
     return -1;
   }