From 685e926494921065e2a4f8d48549b9df87544e05 Mon Sep 17 00:00:00 2001 From: Tatsuhiro Tsujikawa Date: Wed, 11 Jan 2017 19:27:08 +0900 Subject: [PATCH] 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 | 1 + src/shrpx.cc | 10 ++++++++++ src/shrpx_config.cc | 9 +++++++++ src/shrpx_config.h | 6 ++++++ src/shrpx_downstream.cc | 9 +++++++-- src/shrpx_downstream.h | 4 ++++ src/shrpx_http2_session.cc | 11 ++++++++++- src/shrpx_http_downstream_connection.cc | 9 +++++++++ 8 files changed, 56 insertions(+), 3 deletions(-) diff --git a/gennghttpxfun.py b/gennghttpxfun.py index c394486f..5aaf7483 100755 --- a/gennghttpxfun.py +++ b/gennghttpxfun.py @@ -157,6 +157,7 @@ OPTIONS = [ "client-psk-secrets", "client-no-http2-cipher-black-list", "client-ciphers", + "accesslog-write-early", ] LOGVARS = [ diff --git a/src/shrpx.cc b/src/shrpx.cc index 56e2ba09..7fc57584 100644 --- a/src/shrpx.cc +++ b/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= 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; } diff --git a/src/shrpx_config.cc b/src/shrpx_config.cc index 0880f3b7..56d265ca 100644 --- a/src/shrpx_config.cc +++ b/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"; diff --git a/src/shrpx_config.h b/src/shrpx_config.h index efdc50a5..7f3135a4 100644 --- a/src/shrpx_config.h +++ b/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, diff --git a/src/shrpx_downstream.cc b/src/shrpx_downstream.cc index 78f795dd..a07ce1c2 100644 --- a/src/shrpx_downstream.cc +++ b/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 diff --git a/src/shrpx_downstream.h b/src/shrpx_downstream.h index 1c360f89..68ec8d1a 100644 --- a/src/shrpx_downstream.h +++ b/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 diff --git a/src/shrpx_http2_session.cc b/src/shrpx_http2_session.cc index 65f16aaa..440b4460 100644 --- a/src/shrpx_http2_session.cc +++ b/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 diff --git a/src/shrpx_http_downstream_connection.cc b/src/shrpx_http_downstream_connection.cc index 85a72b76..86aee9ea 100644 --- a/src/shrpx_http_downstream_connection.cc +++ b/src/shrpx_http_downstream_connection.cc @@ -822,10 +822,14 @@ namespace { int htp_hdrs_completecb(http_parser *htp) { auto downstream = static_cast(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; }