diff --git a/src/shrpx-unittest.cc b/src/shrpx-unittest.cc index 42998acf..e6c9cb2d 100644 --- a/src/shrpx-unittest.cc +++ b/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", diff --git a/src/shrpx.cc b/src/shrpx.cc index 714f8715..5cb57ec7 100644 --- a/src/shrpx.cc +++ b/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= + 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 . + Default: )" + << DEFAULT_ACCESSLOG_FORMAT << R"( --errorlog-file= 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; } diff --git a/src/shrpx_client_handler.cc b/src/shrpx_client_handler.cc index ad953d4d..732d5f84 100644 --- a/src/shrpx_client_handler.cc +++ b/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 diff --git a/src/shrpx_client_handler.h b/src/shrpx_client_handler.h index 7f027abb..22fba159 100644 --- a/src/shrpx_client_handler.h +++ b/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_; std::string ipaddr_; diff --git a/src/shrpx_config.cc b/src/shrpx_config.cc index 547f968c..a3b7ba65 100644 --- a/src/shrpx_config.cc +++ b/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 strcopy(const char *val) { - auto len = strlen(val); + return strcopy(val, strlen(val)); +} + +std::unique_ptr strcopy(const char *val, size_t len) +{ auto res = util::make_unique(len + 1); - memcpy(res.get(), val, len + 1); + memcpy(res.get(), val, len); + res[len] = '\0'; return res; } std::unique_ptr strcopy(const std::string& val) { - auto len = val.size(); - auto res = util::make_unique(len + 1); - memcpy(res.get(), val.c_str(), len + 1); - return res; + return strcopy(val.c_str(), val.size()); } std::vector 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 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 parse_log_format(const char *optarg) +{ + auto literal_start = optarg; + auto p = optarg; + auto eop = p + strlen(optarg); + + auto res = std::vector(); + + 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); diff --git a/src/shrpx_config.h b/src/shrpx_config.h index 446c19d1..cbb70f37 100644 --- a/src/shrpx_config.h +++ b/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 altsvcs; std::vector> add_response_headers; std::vector alpn_prefs; + std::vector accesslog_format; std::shared_ptr 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& list); // allowed. This function returns pair of NAME and VALUE. std::pair parse_header(const char *optarg); +std::vector parse_log_format(const char *optarg); + // Returns a copy of NULL-terminated string |val|. std::unique_ptr strcopy(const char *val); +// Returns a copy of string |val| of length |n|. The returned string +// will be NULL-terminated. +std::unique_ptr strcopy(const char *val, size_t n); + // Returns a copy of val.c_str(). std::unique_ptr strcopy(const std::string& val); diff --git a/src/shrpx_config_test.cc b/src/shrpx_config_test.cc index cfe95c4e..c9023925 100644 --- a/src/shrpx_config_test.cc +++ b/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 diff --git a/src/shrpx_config_test.h b/src/shrpx_config_test.h index 6b915766..9df73736 100644 --- a/src/shrpx_config_test.h +++ b/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 diff --git a/src/shrpx_downstream.cc b/src/shrpx_downstream.cc index 973bb787..2cc6bc5c 100644 --- a/src/shrpx_downstream.cc +++ b/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; diff --git a/src/shrpx_downstream.h b/src/shrpx_downstream.h index 406b6b7f..f033046e 100644 --- a/src/shrpx_downstream.h +++ b/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 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 diff --git a/src/shrpx_http2_downstream_connection.cc b/src/shrpx_http2_downstream_connection.cc index 2c6df3c6..e9665812 100644 --- a/src/shrpx_http2_downstream_connection.cc +++ b/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()); diff --git a/src/shrpx_http2_upstream.cc b/src/shrpx_http2_upstream.cc index bbbbd64a..54f12b83 100644 --- a/src/shrpx_http2_upstream.cc +++ b/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; } diff --git a/src/shrpx_http_downstream_connection.cc b/src/shrpx_http_downstream_connection.cc index 9215dcef..e903b5b5 100644 --- a/src/shrpx_http_downstream_connection.cc +++ b/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(); diff --git a/src/shrpx_https_upstream.cc b/src/shrpx_https_upstream.cc index 621c72a4..e4a2d5a4 100644 --- a/src/shrpx_https_upstream.cc +++ b/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) 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(); diff --git a/src/shrpx_log.cc b/src/shrpx_log.cc index f6062a34..7b09be56 100644 --- a/src/shrpx_log.cc +++ b/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, - Downstream *downstream) +namespace { +template +std::pair +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& 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]; - int rv; + char buf[4096]; - const char *path; - const char *method; - unsigned int major, minor; - const char *user_agent; - int64_t response_bodylen; + auto downstream = lgsp->downstream; - if(!downstream) { - path = "-"; - 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 p = buf; + auto avail = sizeof(buf) - 2; auto cached_time = get_config()->cached_time; - rv = snprintf(buf, sizeof(buf), fmt, - client_ip.c_str(), - cached_time->c_str(), - method, - path, - major, - minor, - status_code, - (long long int)response_bodylen, - user_agent); + for(auto& lf : lfv) { + switch(lf.type) { + case SHRPX_LOGF_LITERAL: + std::tie(p, avail) = copy(lf.value.get(), avail, p); + break; + case SHRPX_LOGF_REMOTE_ADDR: + 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); + 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) { - return; + std::tie(p, avail) = copy("-", avail, p); + + break; + default: + break; + } } - auto nwrite = std::min(static_cast(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); } diff --git a/src/shrpx_log.h b/src/shrpx_log.h index 1166d3b0..79fab4e7 100644 --- a/src/shrpx_log.h +++ b/src/shrpx_log.h @@ -28,6 +28,8 @@ #include "shrpx.h" #include +#include +#include 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, - Downstream *downstream); +enum LogFragmentType { + 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 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& lf, LogSpec *lgsp); int reopen_log_files(); diff --git a/src/shrpx_spdy_upstream.cc b/src/shrpx_spdy_upstream.cc index 9fdefc08..bbad5a87 100644 --- a/src/shrpx_spdy_upstream.cc +++ b/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; } diff --git a/src/util.cc b/src/util.cc index 67a9dd39..124c3102 100644 --- a/src/util.cc +++ b/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(b), bn); +} + int strcompare(const char *a, const uint8_t *b, size_t bn) { assert(a && b); diff --git a/src/util.h b/src/util.h index e5629ffd..880b9a74 100644 --- a/src/util.h +++ 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 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 bool streq(const A *a, const B *b, size_t bn) {