From 79b50898741f28f8ead0ca6e5255754198296e07 Mon Sep 17 00:00:00 2001 From: bneradt Date: Tue, 17 May 2022 16:34:14 -0500 Subject: [PATCH] Allow for long Http* error.log lines Many URLs and log paths are long enough that the previous 256 byte error.log limit for HttpSM and HttpTransact made it so that the logs got truncated. Some of those logs had meaningful strings at the end which made them hard to interpret unless you had the source code in front of you to figure out what was truncated. This utilizes bwprint and local std::string buffers for arbitrarily long log lines. --- proxy/http/HttpSM.cc | 36 ++++++++++++------------------- proxy/http/HttpTransact.cc | 43 ++++++++++++++++---------------------- 2 files changed, 31 insertions(+), 48 deletions(-) diff --git a/proxy/http/HttpSM.cc b/proxy/http/HttpSM.cc index bc7137fb47f..f18a79bea2e 100644 --- a/proxy/http/HttpSM.cc +++ b/proxy/http/HttpSM.cc @@ -101,6 +101,9 @@ namespace // Unique state machine identifier std::atomic next_sm_id(0); +/// Buffer for some error logs. +thread_local std::string error_bw_buffer; + /** Outbound PROXY Protocol @@ -4168,27 +4171,18 @@ HttpSM::check_sni_host() Warning("No SNI for TLS request with hostname %.*s action=%s", host_len, host_name, action_value); SMDebug("ssl_sni", "No SNI for TLS request with hostname %.*s action=%s", host_len, host_name, action_value); if (host_sni_policy == 2) { - Log::error("%s", lbw() - .clip(1) - .print("No SNI for TLS request: connecting to {} for host='{}', returning a 403", - t_state.client_info.dst_addr, std::string_view{host_name, static_cast(host_len)}) - .extend(1) - .write('\0') - .data()); + ts::bwprint(error_bw_buffer, "No SNI for TLS request: connecting to {} for host='{}', returning a 403", + t_state.client_info.dst_addr, std::string_view{host_name, static_cast(host_len)}); + Log::error("%s", error_bw_buffer.c_str()); this->t_state.client_connection_enabled = false; } } else if (strncasecmp(host_name, sni_value, host_len) != 0) { // Name mismatch Warning("SNI/hostname mismatch sni=%s host=%.*s action=%s", sni_value, host_len, host_name, action_value); SMDebug("ssl_sni", "SNI/hostname mismatch sni=%s host=%.*s action=%s", sni_value, host_len, host_name, action_value); if (host_sni_policy == 2) { - Log::error("%s", lbw() - .clip(1) - .print("SNI/hostname mismatch: connecting to {} for host='{}' sni='{}', returning a 403", - t_state.client_info.dst_addr, std::string_view{host_name, static_cast(host_len)}, - sni_value) - .extend(1) - .write('\0') - .data()); + ts::bwprint(error_bw_buffer, "SNI/hostname mismatch: connecting to {} for host='{}' sni='{}', returning a 403", + t_state.client_info.dst_addr, std::string_view{host_name, static_cast(host_len)}, sni_value); + Log::error("%s", error_bw_buffer.c_str()); this->t_state.client_connection_enabled = false; } } else { @@ -5556,14 +5550,10 @@ HttpSM::mark_host_failure(HostDBInfo *info, time_t time_down) int host_len; const char *host_name_ptr = t_state.unmapped_url.host_get(&host_len); std::string_view host_name{host_name_ptr, size_t(host_len)}; - Log::error("%s", lbw() - .clip(1) - .print("CONNECT: {::s} connecting to {} for host='{}' url='{}' marking down", - ts::bwf::Errno(t_state.current.server->connect_result), t_state.current.server->dst_addr, - host_name, ts::bwf::FirstOf(url_str, "")) - .extend(1) - .write('\0') - .data()); + ts::bwprint(error_bw_buffer, "CONNECT: {::s} connecting to {} for host='{}' url='{}' marking down", + ts::bwf::Errno(t_state.current.server->connect_result), t_state.current.server->dst_addr, host_name, + ts::bwf::FirstOf(url_str, "")); + Log::error("%s", error_bw_buffer.c_str()); if (url_str) { t_state.arena.str_free(url_str); diff --git a/proxy/http/HttpTransact.cc b/proxy/http/HttpTransact.cc index 8618cbdc6a0..d7544ed598a 100644 --- a/proxy/http/HttpTransact.cc +++ b/proxy/http/HttpTransact.cc @@ -51,7 +51,10 @@ namespace { char const Dns_error_body[] = "connect#dns_failed"; -} + +/// Buffer for some error logs. +thread_local std::string error_bw_buffer; +} // namespace // Support ip_resolve override. const MgmtConverter HttpTransact::HOST_RES_CONV{[](const void *data) -> std::string_view { @@ -95,9 +98,6 @@ static char range_type[] = "multipart/byteranges; boundary=RANGE_SEPARATOR"; extern HttpBodyFactory *body_factory; -// Handy typedef for short (single line) message generation. -using lbw = ts::LocalBufferWriter<256>; - // wrapper to choose between a remap next hop strategy or use parent.config // remap next hop strategy is preferred inline static bool @@ -908,13 +908,9 @@ HttpTransact::OriginDead(State *s) int host_len; const char *host_name_ptr = s->unmapped_url.host_get(&host_len); std::string_view host_name{host_name_ptr, size_t(host_len)}; - Log::error("%s", lbw() - .clip(1) - .print("CONNECT: dead server no request to {} for host='{}' url='{}'", s->current.server->dst_addr, host_name, - ts::bwf::FirstOf(url_str, "")) - .extend(1) - .write('\0') - .data()); + ts::bwprint(error_bw_buffer, "CONNECT: dead server no request to {} for host='{}' url='{}'", s->current.server->dst_addr, + host_name, ts::bwf::FirstOf(url_str, "")); + Log::error("%s", error_bw_buffer.c_str()); s->arena.str_free(url_str); TRANSACT_RETURN(SM_ACTION_SEND_ERROR_CACHE_NOOP, nullptr); @@ -1891,8 +1887,8 @@ HttpTransact::ReDNSRoundRobin(State *s) s->next_action = SM_ACTION_SEND_ERROR_CACHE_NOOP; // s->next_action = PROXY_INTERNAL_CACHE_NOOP; char *url_str = s->hdr_info.client_request.url_string_get(&s->arena, nullptr); - Log::error("%s", - lbw().clip(1).print("DNS Error: looking up {}", ts::bwf::FirstOf(url_str, "")).extend(1).write('\0').data()); + ts::bwprint(error_bw_buffer, "DNS Error: looking up {}", ts::bwf::FirstOf(url_str, "")); + Log::error("%s", error_bw_buffer.c_str()); } return; @@ -1963,8 +1959,8 @@ HttpTransact::OSDNSLookup(State *s) // Set to internal server error so later logging will pick up SQUID_LOG_ERR_DNS_FAIL build_error_response(s, HTTP_STATUS_INTERNAL_SERVER_ERROR, "Cannot find server.", "connect#dns_failed"); char *url_str = s->hdr_info.client_request.url_string_get(&s->arena, nullptr); - Log::error("%s", - lbw().clip(1).print("DNS Error: looking up {}", ts::bwf::FirstOf(url_str, "")).extend(1).write('\0').data()); + ts::bwprint(error_bw_buffer, "DNS Error: looking up {}", ts::bwf::FirstOf(url_str, "")); + Log::error("%s", error_bw_buffer.c_str()); // s->cache_info.action = CACHE_DO_NO_ACTION; TRANSACT_RETURN(SM_ACTION_SEND_ERROR_CACHE_NOOP, nullptr); } @@ -3906,16 +3902,13 @@ HttpTransact::error_log_connection_failure(State *s, ServerState_t conn_state) host_name_ptr = s->unmapped_url.host_get(&host_len); } std::string_view host_name{host_name_ptr, size_t(host_len)}; - Log::error("%s", lbw() - .clip(1) - .print("CONNECT: attempt fail [{}] to {} for host='{}' " - "connection_result={::s} error={::s} attempts={} url='{}'", - HttpDebugNames::get_server_state_name(conn_state), s->current.server->dst_addr, host_name, - ts::bwf::Errno(s->current.server->connect_result), ts::bwf::Errno(s->cause_of_death_errno), - s->current.attempts, ts::bwf::FirstOf(url_str, "")) - .extend(1) - .write('\0') - .data()); + ts::bwprint(error_bw_buffer, + "CONNECT: attempt fail [{}] to {} for host='{}' " + "connection_result={::s} error={::s} attempts={} url='{}'", + HttpDebugNames::get_server_state_name(conn_state), s->current.server->dst_addr, host_name, + ts::bwf::Errno(s->current.server->connect_result), ts::bwf::Errno(s->cause_of_death_errno), s->current.attempts, + ts::bwf::FirstOf(url_str, "")); + Log::error("%s", error_bw_buffer.c_str()); s->arena.str_free(url_str); }