diff --git a/CMakeLists.txt b/CMakeLists.txt index 897cf30df74..679561bf3ad 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -769,6 +769,7 @@ check_struct_has_member("struct tcp_info" tcpi_total_retrans "linux/tcp.h" HAVE_ check_struct_has_member("struct tcp_info" tcpi_data_segs_out "linux/tcp.h" HAVE_STRUCT_TCP_INFO_TCPI_DATA_SEGS_OUT) # Since FreeBSD 6 check_struct_has_member("struct tcp_info" __tcpi_retrans "netinet/tcp.h" HAVE_STRUCT_TCP_INFO___TCPI_RETRANS) +check_struct_has_member("struct tcp_info" tcpi_snd_rexmitpack "netinet/tcp.h" HAVE_STRUCT_TCP_INFO_TCPI_SND_REXMITPACK) check_struct_has_member("struct sockaddr" sa_len "netinet/in.h" HAVE_STRUCT_SOCKADDR_SA_LEN) check_struct_has_member("struct sockaddr_in" sin_len "netinet/in.h" HAVE_STRUCT_SOCKADDR_IN_SIN_LEN) check_struct_has_member("struct sockaddr_in6" sin6_len "netinet/in.h" HAVE_STRUCT_SOCKADDR_IN6_SIN6_LEN) diff --git a/doc/admin-guide/files/records.yaml.en.rst b/doc/admin-guide/files/records.yaml.en.rst index 5d75b68bafc..47d73e1624c 100644 --- a/doc/admin-guide/files/records.yaml.en.rst +++ b/doc/admin-guide/files/records.yaml.en.rst @@ -3776,6 +3776,39 @@ HostDB Logging Configuration ===================== +.. ts:cv:: CONFIG proxy.config.http.log_server_tcp_info INT 0 + :reloadable: + :overridable: + + Enables sampling of ``TCP_INFO`` on the origin connection, so that the round + trip time to the origin can be logged. + + This can be overridden per transaction using ``conf_remap`` or + ``header_rewrite`` before the origin response header is parsed. For example, + leave the global value at ``0`` and enable collection on a selected remap:: + + map http://cdn.example/ http://origin.example/ @plugin=conf_remap.so @pparam=proxy.config.http.log_server_tcp_info=1 + + When this is enabled, |TS| reads ``TCP_INFO`` from the origin socket once for + each successfully parsed origin response header and keeps the values for the + access log. This normally means one snapshot per transaction; retries, + redirects, or informational responses can cause additional snapshots. A direct + cache hit does not read ``TCP_INFO``. By log time, the connection may have been + closed or released for reuse by another transaction. The values feed the :ref:`srtt `, + :ref:`srtv `, :ref:`sret ` and :ref:`scwn ` log fields, + which report -1 when no sample was taken. Starting another origin attempt or + reading another response header clears the previous sample. + + Sampling is skipped if access logging is disabled globally or transaction + logging is disabled through ``TS_HTTP_CNTL_LOGGING_MODE`` at that point. + Enabling logging later does not collect a sample retroactively; the fields + remain -1 unless another response header is successfully parsed with logging + enabled. The later :ts:cv:`proxy.config.log.sampling_frequency` decision and + log filtering can still discard a transaction that was sampled. + + This costs one ``getsockopt`` per sampled origin response, so it is disabled + by default. Only sockets carrying TCP supply the information. + .. ts:cv:: CONFIG proxy.config.log.logging_enabled INT 3 :reloadable: diff --git a/doc/admin-guide/logging/formatting.en.rst b/doc/admin-guide/logging/formatting.en.rst index 420df43090b..16aba01a613 100644 --- a/doc/admin-guide/logging/formatting.en.rst +++ b/doc/admin-guide/logging/formatting.en.rst @@ -202,6 +202,10 @@ Connections and Transactions .. _surc: .. _ssrc: .. _sstc: +.. _srtt: +.. _srtv: +.. _sret: +.. _scwn: .. _ccid: .. _ctid: .. _ctpw: @@ -220,6 +224,18 @@ ssrc Proxy Parent simple server retry count within the current transac sstc Proxy Number of transactions between the |TS| proxy and the origin server from a single session. Any value greater than zero indicates connection reuse. +srtt Proxy Smoothed round trip time to the origin server, in microseconds, + read when the origin response header was successfully parsed. + Requires :ts:cv:`proxy.config.http.log_server_tcp_info`. Reports + -1 when no origin socket was sampled. +srtv Proxy Round trip time variance for the origin connection, in + microseconds. Same source and conditions as ``srtt``. +sret Proxy Segments retransmitted since the origin connection opened, as of + the response-header sample. Includes retransmits from earlier + transactions on a reused connection. Same conditions as ``srtt``. +scwn Proxy Send congestion window for the origin connection: segments on + Linux, bytes on FreeBSD. + Same source and conditions as ``srtt``. ccid Client Request Client Connection ID, a non-negative number for a connection, which is different for all currently-active connections to clients. diff --git a/doc/developer-guide/api/functions/TSHttpOverridableConfig.en.rst b/doc/developer-guide/api/functions/TSHttpOverridableConfig.en.rst index f8c0a814b52..87419568162 100644 --- a/doc/developer-guide/api/functions/TSHttpOverridableConfig.en.rst +++ b/doc/developer-guide/api/functions/TSHttpOverridableConfig.en.rst @@ -140,6 +140,7 @@ TSOverridableConfigKey Value Confi :enumerator:`TS_CONFIG_HTTP_KEEP_ALIVE_NO_ACTIVITY_TIMEOUT_IN` :ts:cv:`proxy.config.http.keep_alive_no_activity_timeout_in` :enumerator:`TS_CONFIG_HTTP_KEEP_ALIVE_NO_ACTIVITY_TIMEOUT_OUT` :ts:cv:`proxy.config.http.keep_alive_no_activity_timeout_out` :enumerator:`TS_CONFIG_HTTP_KEEP_ALIVE_POST_OUT` :ts:cv:`proxy.config.http.keep_alive_post_out` +:enumerator:`TS_CONFIG_HTTP_LOG_SERVER_TCP_INFO` :ts:cv:`proxy.config.http.log_server_tcp_info` :enumerator:`TS_CONFIG_HTTP_NEGATIVE_CACHING_ENABLED` :ts:cv:`proxy.config.http.negative_caching_enabled` :enumerator:`TS_CONFIG_HTTP_NEGATIVE_CACHING_LIFETIME` :ts:cv:`proxy.config.http.negative_caching_lifetime` :enumerator:`TS_CONFIG_HTTP_NEGATIVE_CACHING_LIST` :ts:cv:`proxy.config.http.negative_caching_list` diff --git a/doc/developer-guide/api/types/TSOverridableConfigKey.en.rst b/doc/developer-guide/api/types/TSOverridableConfigKey.en.rst index 74897622a5e..ff5c7ede79d 100644 --- a/doc/developer-guide/api/types/TSOverridableConfigKey.en.rst +++ b/doc/developer-guide/api/types/TSOverridableConfigKey.en.rst @@ -169,6 +169,7 @@ Enumeration Members .. enumerator:: TS_CONFIG_HTTP_CACHE_POST_METHOD .. enumerator:: TS_CONFIG_HTTP_CACHE_TARGETED_CACHE_CONTROL_HEADERS .. enumerator:: TS_CONFIG_HTTP_CACHE_MAX_STALE_AGE_PERCENT +.. enumerator:: TS_CONFIG_HTTP_LOG_SERVER_TCP_INFO Description diff --git a/include/iocore/net/NetVConnection.h b/include/iocore/net/NetVConnection.h index fe090bf77bf..58931f21c5d 100644 --- a/include/iocore/net/NetVConnection.h +++ b/include/iocore/net/NetVConnection.h @@ -25,6 +25,7 @@ #include "iocore/net/NetVCOptions.h" #include "iocore/net/ProxyProtocol.h" +#include "iocore/net/TcpInfoSnapshot.h" #include #include @@ -381,6 +382,21 @@ class NetVConnection : public VConnection, public PluginUserArgs + +/** The subset of @c TCP_INFO that ATS reports. + * + * Sampling a connection copies these out of the kernel, so the values stay + * available after the connection itself is gone. The kernel smooths both times + * over the life of the connection, so they describe the path rather than any + * single segment. + * + * This lives in its own header so that consumers which only report the values, + * such as logging, do not have to include the network stack. + */ +struct TcpInfoSnapshot { + int64_t rtt = 0; ///< Smoothed round trip time, microseconds. + int64_t rttvar = 0; ///< Round trip time variance, microseconds. + int64_t retrans = 0; ///< Segments retransmitted since connection open, up to sampling time. + int64_t snd_cwnd = 0; ///< Send congestion window: segments on Linux, bytes on FreeBSD. +}; diff --git a/include/proxy/http/HttpConfig.h b/include/proxy/http/HttpConfig.h index 887ac1cb642..0f885ae852f 100644 --- a/include/proxy/http/HttpConfig.h +++ b/include/proxy/http/HttpConfig.h @@ -561,6 +561,7 @@ struct OverridableHttpConfigParams { MgmtByte forward_connect_method = 0; MgmtByte insert_age_in_response = 1; + MgmtByte log_server_tcp_info = 0; // Sample origin TCP_INFO for access logging. /////////////////////////////////////////////////////////////////// // Privacy: fields which are removed from the user agent request // diff --git a/include/proxy/http/HttpSM.h b/include/proxy/http/HttpSM.h index c2128eeca20..a48c3d4870c 100644 --- a/include/proxy/http/HttpSM.h +++ b/include/proxy/http/HttpSM.h @@ -50,6 +50,7 @@ // inknet #include "proxy/http/PreWarmManager.h" #include "iocore/net/TLSTunnelSupport.h" +#include "iocore/net/TcpInfoSnapshot.h" #include "tscore/History.h" #include "tscore/PendingAction.h" @@ -531,8 +532,11 @@ class HttpSM : public Continuation, public PluginUserArgs // do_api_callout_internal() bool hooks_set = false; std::optional mptcp_state; // Don't initialize, that marks it as "not defined". - const char *server_protocol = "-"; - int server_transact_count = 0; + /// TCP_INFO for the current origin response, sampled after successful header parsing. + /// Cleared when starting another origin attempt or reading another response header. + std::optional server_tcp_info; + const char *server_protocol = "-"; + int server_transact_count = 0; TransactionMilestones milestones; ink_hrtime api_timer = 0; diff --git a/include/proxy/http/OverridableConfigDefs.h b/include/proxy/http/OverridableConfigDefs.h index 8b18797494f..db3be7170be 100644 --- a/include/proxy/http/OverridableConfigDefs.h +++ b/include/proxy/http/OverridableConfigDefs.h @@ -255,6 +255,7 @@ X(SSL_CLIENT_CA_CERT_PATH, ssl_client_ca_cert_path, "proxy.config.ssl.client.CA.cert.path", STRING, NONE) \ X(HTTP_CACHE_MAX_STALE_AGE_PERCENT, cache_max_stale_age_percent, "proxy.config.http.cache.max_stale_age_percent", INT, GENERIC) \ X(HTTP_PER_SERVER_CONNECTION_METRIC_ENABLED, connection_tracker_config.metric_enabled, ConnectionTracker::CONFIG_SERVER_VAR_METRIC_ENABLED, INT, ConnectionTracker_METRIC_ENABLED_CONV) \ - X(HTTP_PER_SERVER_CONNECTION_METRIC_AGGREGATE, connection_tracker_config.metric_aggregate, ConnectionTracker::CONFIG_SERVER_VAR_METRIC_AGGREGATE, INT, ConnectionTracker_METRIC_AGGREGATE_CONV) + X(HTTP_PER_SERVER_CONNECTION_METRIC_AGGREGATE, connection_tracker_config.metric_aggregate, ConnectionTracker::CONFIG_SERVER_VAR_METRIC_AGGREGATE, INT, ConnectionTracker_METRIC_AGGREGATE_CONV) \ + X(HTTP_LOG_SERVER_TCP_INFO, log_server_tcp_info, "proxy.config.http.log_server_tcp_info", INT, GENERIC) // clang-format on diff --git a/include/proxy/logging/LogAccess.h b/include/proxy/logging/LogAccess.h index ea7a2aa3fac..847e6152573 100644 --- a/include/proxy/logging/LogAccess.h +++ b/include/proxy/logging/LogAccess.h @@ -30,6 +30,7 @@ #include "proxy/logging/LogField.h" class TransactionLogData; +struct TcpInfoSnapshot; class IpClass; union IpEndpoint; @@ -231,6 +232,10 @@ class LogAccess int marshal_server_simple_retry_count(char *); // INT int marshal_server_unavailable_retry_count(char *); // INT int marshal_server_connect_attempts(char *); // INT + int marshal_server_tcp_rtt(char *); // INT + int marshal_server_tcp_rttvar(char *); // INT + int marshal_server_tcp_retrans(char *); // INT + int marshal_server_tcp_snd_cwnd(char *); // INT int marshal_server_resp_all_header_fields(char *); // STR // @@ -390,6 +395,8 @@ class LogAccess LogAccess &operator=(LogAccess &rhs) = delete; // or assignment private: + int marshal_server_tcp_info(char *buf, int64_t TcpInfoSnapshot::*member); + TransactionLogData *m_data = nullptr; Arena m_arena; diff --git a/include/proxy/logging/TransactionLogData.h b/include/proxy/logging/TransactionLogData.h index 09b1c6fefb0..dc74ec98520 100644 --- a/include/proxy/logging/TransactionLogData.h +++ b/include/proxy/logging/TransactionLogData.h @@ -25,6 +25,7 @@ #include "proxy/Milestones.h" #include "proxy/hdrs/HTTP.h" +#include "iocore/net/TcpInfoSnapshot.h" #include "tscore/ink_inet.h" #include @@ -162,6 +163,9 @@ class TransactionLogData // ===== MPTCP ===== std::optional get_mptcp_state() const; + // ===== Origin connection TCP_INFO ===== + std::optional get_server_tcp_info() const; + // ===== Misc transaction state ===== in_port_t get_incoming_port() const; int get_orig_scheme() const; diff --git a/include/ts/apidefs.h.in b/include/ts/apidefs.h.in index 86bb8e2af13..630f227d963 100644 --- a/include/ts/apidefs.h.in +++ b/include/ts/apidefs.h.in @@ -922,6 +922,7 @@ enum TSOverridableConfigKey { TS_CONFIG_HTTP_CACHE_MAX_STALE_AGE_PERCENT, TS_CONFIG_HTTP_PER_SERVER_CONNECTION_METRIC_ENABLED, TS_CONFIG_HTTP_PER_SERVER_CONNECTION_METRIC_AGGREGATE, + TS_CONFIG_HTTP_LOG_SERVER_TCP_INFO, TS_CONFIG_LAST_ENTRY, }; diff --git a/include/tscore/ink_config.h.cmake.in b/include/tscore/ink_config.h.cmake.in index 40b52686c7c..bb9cbef6f82 100644 --- a/include/tscore/ink_config.h.cmake.in +++ b/include/tscore/ink_config.h.cmake.in @@ -98,6 +98,7 @@ #cmakedefine HAVE_STRUCT_TCP_INFO_TCPI_TOTAL_RETRANS 1 #cmakedefine HAVE_STRUCT_TCP_INFO_TCPI_DATA_SEGS_OUT 1 #cmakedefine HAVE_STRUCT_TCP_INFO___TCPI_RETRANS 1 +#cmakedefine HAVE_STRUCT_TCP_INFO_TCPI_SND_REXMITPACK 1 #cmakedefine HAVE_STRUCT_SOCKADDR_SA_LEN 1 #cmakedefine HAVE_STRUCT_SOCKADDR_IN_SIN_LEN 1 #cmakedefine HAVE_STRUCT_SOCKADDR_IN6_SIN6_LEN 1 diff --git a/src/iocore/net/CMakeLists.txt b/src/iocore/net/CMakeLists.txt index fbffe744194..d4256ad37d0 100644 --- a/src/iocore/net/CMakeLists.txt +++ b/src/iocore/net/CMakeLists.txt @@ -145,6 +145,7 @@ if(BUILD_TESTING) libinknet_stub.cc NetVCTest.cc unit_tests/test_NetHandler.cc + unit_tests/test_TcpInfo.cc unit_tests/test_ProxyProtocol.cc unit_tests/test_SSLCertLookup.cc unit_tests/test_SSLNetVConnectionAsyncEp.cc diff --git a/src/iocore/net/P_UnixNetVConnection.h b/src/iocore/net/P_UnixNetVConnection.h index 71d27374541..90c79535f2f 100644 --- a/src/iocore/net/P_UnixNetVConnection.h +++ b/src/iocore/net/P_UnixNetVConnection.h @@ -31,6 +31,7 @@ #pragma once +#include #include #include "tscore/ink_sock.h" @@ -203,6 +204,7 @@ class UnixNetVConnection : public NetVConnection, public NetEvent void set_local_addr() override; void set_mptcp_state() override; + bool get_tcp_info(TcpInfoSnapshot &info) const override; void set_remote_addr() override; void set_remote_addr(const sockaddr *) override; int set_tcp_congestion_control(tcp_congestion_control_side side) override; @@ -245,6 +247,7 @@ class UnixNetVConnection : public NetVConnection, public NetEvent inline static DbgCtl _dbg_ctl_socket{"socket"}; inline static DbgCtl _dbg_ctl_socket_mptcp{"socket_mptcp"}; + inline static DbgCtl _dbg_ctl_socket_tcp_info{"socket_tcp_info"}; /** The shared group across all connections for this IP to track incoming * connections for connection limiting. */ @@ -304,6 +307,48 @@ UnixNetVConnection::set_mptcp_state() #endif } +// Copy the TCP_INFO fields ATS reports out of the kernel. +inline bool +UnixNetVConnection::get_tcp_info(TcpInfoSnapshot &info) const +{ +#if defined(TCP_INFO) && defined(HAVE_STRUCT_TCP_INFO) && \ + (HAVE_STRUCT_TCP_INFO_TCPI_TOTAL_RETRANS || HAVE_STRUCT_TCP_INFO_TCPI_SND_REXMITPACK) + if (con.sock_type != SOCK_STREAM) { + return false; + } + + struct tcp_info tinfo = {}; + int tinfo_len = sizeof(tinfo); + int const fd = con.sock.get_fd(); + + if (0 != safe_getsockopt(fd, IPPROTO_TCP, TCP_INFO, &tinfo, &tinfo_len)) { + Dbg(_dbg_ctl_socket_tcp_info, "failed getsockopt(%d, TCP_INFO): %s", fd, strerror(errno)); + return false; + } + if (tinfo_len != static_cast(sizeof(tinfo))) { + return false; + } + + info.rtt = tinfo.tcpi_rtt; + info.rttvar = tinfo.tcpi_rttvar; + info.snd_cwnd = tinfo.tcpi_snd_cwnd; +#if HAVE_STRUCT_TCP_INFO_TCPI_TOTAL_RETRANS + info.retrans = tinfo.tcpi_total_retrans; +#elif HAVE_STRUCT_TCP_INFO_TCPI_SND_REXMITPACK + // FreeBSD spells the cumulative count differently; __tcpi_retrans is the + // currently outstanding count, which is not what this reports. + info.retrans = tinfo.tcpi_snd_rexmitpack; +#endif + + Dbg(_dbg_ctl_socket_tcp_info, "fd %d rtt=%" PRId64 " rttvar=%" PRId64 " retrans=%" PRId64 " cwnd=%" PRId64, fd, info.rtt, + info.rttvar, info.retrans, info.snd_cwnd); + return true; +#else + (void)info; + return false; +#endif +} + inline ink_hrtime UnixNetVConnection::get_active_timeout() { diff --git a/src/iocore/net/unit_tests/test_TcpInfo.cc b/src/iocore/net/unit_tests/test_TcpInfo.cc new file mode 100644 index 00000000000..2e817bd0e9a --- /dev/null +++ b/src/iocore/net/unit_tests/test_TcpInfo.cc @@ -0,0 +1,46 @@ +/** @file + + Tests for collecting TCP_INFO from network connections. + + @section license License + + Licensed to the Apache Software Foundation (ASF) under one + or more contributor license agreements. See the NOTICE file + distributed with this work for additional information + regarding copyright ownership. The ASF licenses this file + to you under the Apache License, Version 2.0 (the + "License"); you may not use this file except in compliance + with the License. You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + + Unless required by applicable law or agreed to in writing, software + distributed under the License is distributed on an "AS IS" BASIS, + WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + See the License for the specific language governing permissions and + limitations under the License. + */ + +#include "../P_UnixNetVConnection.h" + +#include + +#include + +TEST_CASE("TCP_INFO skips UDP sockets without a syscall", "[net][tcpinfo]") +{ + UnixNetVConnection vc; + NetVCOptions options; + TcpInfoSnapshot info; + + options.ip_proto = NetVCOptions::USE_UDP; + REQUIRE(vc.con.open(options) == 0); + + // TCP_INFO on a UDP socket would fail and set errno. + errno = 0; + bool const has_info = vc.get_tcp_info(info); + int const socket_errno = errno; + + CHECK_FALSE(has_info); + CHECK(socket_errno == 0); +} diff --git a/src/proxy/http/HttpConfig.cc b/src/proxy/http/HttpConfig.cc index 08a3ed23633..1d02f565d1e 100644 --- a/src/proxy/http/HttpConfig.cc +++ b/src/proxy/http/HttpConfig.cc @@ -1099,6 +1099,7 @@ HttpConfig::startup() HttpEstablishStaticConfigByte(c.oride.insert_age_in_response, "proxy.config.http.insert_age_in_response"); HttpEstablishStaticConfigByte(c.enable_http_stats, "proxy.config.http.enable_http_stats"); + HttpEstablishStaticConfigByte(c.oride.log_server_tcp_info, "proxy.config.http.log_server_tcp_info"); HttpEstablishStaticConfigByte(c.oride.normalize_ae, "proxy.config.http.normalize_ae"); HttpEstablishStaticConfigLongLong(c.oride.cache_heuristic_min_lifetime, "proxy.config.http.cache.heuristic_min_lifetime"); @@ -1447,6 +1448,7 @@ HttpConfig::reconfigure() params->oride.insert_forwarded = m_master.oride.insert_forwarded; params->oride.insert_age_in_response = INT_TO_BOOL(m_master.oride.insert_age_in_response); params->enable_http_stats = INT_TO_BOOL(m_master.enable_http_stats); + params->oride.log_server_tcp_info = INT_TO_BOOL(m_master.oride.log_server_tcp_info); params->oride.normalize_ae = m_master.oride.normalize_ae; params->oride.proxy_protocol_out = m_master.oride.proxy_protocol_out; diff --git a/src/proxy/http/HttpSM.cc b/src/proxy/http/HttpSM.cc index b7a123c6f62..0faf63390ab 100644 --- a/src/proxy/http/HttpSM.cc +++ b/src/proxy/http/HttpSM.cc @@ -2139,6 +2139,19 @@ HttpSM::state_read_server_response_header(int event, void *data) ATS_PROBE1(milestone_server_read_header_done, sm_id); milestones[TS_MILESTONE_SERVER_READ_HEADER_DONE] = ink_get_hrtime(); + // Sample while this transaction still owns the origin connection. By log time, + // the connection may have been closed or released for reuse. + if (state == ParseResult::DONE && t_state.txn_conf->log_server_tcp_info && Log::transaction_logging_enabled() && + t_state.api_info.logging_enabled) { + NetVConnection *server_vc = server_txn->get_netvc(); + if (server_vc != nullptr) { + TcpInfoSnapshot info; + if (server_vc->get_tcp_info(info)) { + server_tcp_info = info; + } + } + } + // Any other events to the end if (server_entry->vc_type == HttpVC_t::SERVER_VC) { server_entry->vc_read_handler = &HttpSM::tunnel_handler; @@ -5650,6 +5663,9 @@ HttpSM::open_prewarmed_connection() void HttpSM::do_http_server_open(bool raw, bool only_direct) { + // A failed new attempt must not report a previous origin's TCP_INFO. + server_tcp_info.reset(); + int ip_family = t_state.current.server->dst_addr.sa.sa_family; auto fam_name = ats_ip_family_name(ip_family); SMDbg(dbg_ctl_http_track, "[%.*s]", static_cast(fam_name.size()), fam_name.data()); @@ -7098,6 +7114,7 @@ HttpSM::setup_server_read_response_header() http_parser_clear(&http_parser); server_response_hdr_bytes = 0; milestones[TS_MILESTONE_SERVER_READ_HEADER_DONE] = 0; + server_tcp_info.reset(); // The tunnel from OS to UA is now setup. Ready to read the response server_entry->read_vio = server_txn->do_io_read(this, INT64_MAX, server_txn->get_remote_reader()->mbuf); @@ -8304,6 +8321,9 @@ HttpSM::set_next_state() } case HttpTransact::StateMachineAction_t::DNS_LOOKUP: { + // A retry can fail during resolution, before opening its connection. + server_tcp_info.reset(); + if (sockaddr const *addr; t_state.http_config_param->use_client_target_addr == 2 && // no CTA verification !t_state.url_remap_success && // wasn't remapped t_state.parent_result.result != ParentResultType::SPECIFIED && // no parent. @@ -8757,6 +8777,7 @@ HttpSM::redirect_request(const char *arg_redirect_url, const int arg_redirect_le } t_state.redirect_info.redirect_in_process = true; + server_tcp_info.reset(); // set the passed in location url and parse it URL redirectUrl; diff --git a/src/proxy/logging/Log.cc b/src/proxy/logging/Log.cc index e87b3453213..b6d249840a8 100644 --- a/src/proxy/logging/Log.cc +++ b/src/proxy/logging/Log.cc @@ -950,6 +950,26 @@ Log::init_fields() global_field_list.add(field, false); field_symbol_hash.emplace("sca", field); + field = new LogField("server_tcp_rtt", "srtt", LogField::Type::sINT, &LogAccess::marshal_server_tcp_rtt, + &LogAccess::unmarshal_int_to_str); + global_field_list.add(field, false); + field_symbol_hash.emplace("srtt", field); + + field = new LogField("server_tcp_rttvar", "srtv", LogField::Type::sINT, &LogAccess::marshal_server_tcp_rttvar, + &LogAccess::unmarshal_int_to_str); + global_field_list.add(field, false); + field_symbol_hash.emplace("srtv", field); + + field = new LogField("server_tcp_retrans", "sret", LogField::Type::sINT, &LogAccess::marshal_server_tcp_retrans, + &LogAccess::unmarshal_int_to_str); + global_field_list.add(field, false); + field_symbol_hash.emplace("sret", field); + + field = new LogField("server_tcp_snd_cwnd", "scwn", LogField::Type::sINT, &LogAccess::marshal_server_tcp_snd_cwnd, + &LogAccess::unmarshal_int_to_str); + global_field_list.add(field, false); + field_symbol_hash.emplace("scwn", field); + field = new LogField("origin_response_all_header_fields", "ssah", LogField::Type::STRING, &LogAccess::marshal_server_resp_all_header_fields, &LogUtils::unmarshalMimeHdr); global_field_list.add(field, false); diff --git a/src/proxy/logging/LogAccess.cc b/src/proxy/logging/LogAccess.cc index 92f878622e8..c5e75c0fd93 100644 --- a/src/proxy/logging/LogAccess.cc +++ b/src/proxy/logging/LogAccess.cc @@ -2995,6 +2995,55 @@ LogAccess::marshal_server_connect_attempts(char *buf) return INK_MIN_ALIGN; } +/*------------------------------------------------------------------------- + The origin connection TCP_INFO fields. Each reports -1 when there is no + sample for the current origin response, including cache hits and disabled + sampling. + -------------------------------------------------------------------------*/ + +int +LogAccess::marshal_server_tcp_info(char *buf, int64_t TcpInfoSnapshot::*member) +{ + if (buf) { + std::optional info = m_data->get_server_tcp_info(); + marshal_int(buf, info.has_value() ? (*info).*member : -1); + } + return INK_MIN_ALIGN; +} + +int +LogAccess::marshal_server_tcp_rtt(char *buf) +{ + return marshal_server_tcp_info(buf, &TcpInfoSnapshot::rtt); +} + +/*------------------------------------------------------------------------- + -------------------------------------------------------------------------*/ + +int +LogAccess::marshal_server_tcp_rttvar(char *buf) +{ + return marshal_server_tcp_info(buf, &TcpInfoSnapshot::rttvar); +} + +/*------------------------------------------------------------------------- + -------------------------------------------------------------------------*/ + +int +LogAccess::marshal_server_tcp_retrans(char *buf) +{ + return marshal_server_tcp_info(buf, &TcpInfoSnapshot::retrans); +} + +/*------------------------------------------------------------------------- + -------------------------------------------------------------------------*/ + +int +LogAccess::marshal_server_tcp_snd_cwnd(char *buf) +{ + return marshal_server_tcp_info(buf, &TcpInfoSnapshot::snd_cwnd); +} + /*------------------------------------------------------------------------- -------------------------------------------------------------------------*/ diff --git a/src/proxy/logging/TransactionLogData.cc b/src/proxy/logging/TransactionLogData.cc index b226fc8349f..a16e906c19f 100644 --- a/src/proxy/logging/TransactionLogData.cc +++ b/src/proxy/logging/TransactionLogData.cc @@ -916,6 +916,17 @@ TransactionLogData::get_mptcp_state() const return std::nullopt; } +// ===== Origin connection TCP_INFO ===== + +std::optional +TransactionLogData::get_server_tcp_info() const +{ + if (likely(m_http_sm != nullptr)) { + return m_http_sm->server_tcp_info; + } + return std::nullopt; +} + // ===== Misc transaction state ===== in_port_t diff --git a/src/records/RecordsConfig.cc b/src/records/RecordsConfig.cc index e429ac4680b..79325c5b112 100644 --- a/src/records/RecordsConfig.cc +++ b/src/records/RecordsConfig.cc @@ -565,6 +565,8 @@ static constexpr RecordElement RecordsConfig[] = , {RECT_CONFIG, "proxy.config.http.enable_http_stats", RECD_INT, "1", RECU_DYNAMIC, RR_NULL, RECC_INT, "[0-1]", RECA_NULL} , + {RECT_CONFIG, "proxy.config.http.log_server_tcp_info", RECD_INT, "0", RECU_DYNAMIC, RR_NULL, RECC_INT, "[0-1]", RECA_NULL} + , {RECT_CONFIG, "proxy.config.http.allow_multi_range", RECD_INT, "0", RECU_DYNAMIC, RR_NULL, RECC_INT, "[0-2]", RECA_NULL} , // This defaults to a special invalid value so the HTTP transaction handling code can tell that it was not explicitly set. diff --git a/tests/gold_tests/logging/log-origin-tcp-info.test.py b/tests/gold_tests/logging/log-origin-tcp-info.test.py new file mode 100644 index 00000000000..554b2ab5971 --- /dev/null +++ b/tests/gold_tests/logging/log-origin-tcp-info.test.py @@ -0,0 +1,46 @@ +# Licensed to the Apache Software Foundation (ASF) under one +# or more contributor license agreements. See the NOTICE file +# distributed with this work for additional information +# regarding copyright ownership. The ASF licenses this file +# to you under the Apache License, Version 2.0 (the +# "License"); you may not use this file except in compliance +# with the License. You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +import os +import shlex +import sys + +from ports import get_port + +Test.Summary = 'Verify origin TCP_INFO fields and sampling controls' +Test.ContinueOnFail = True +Test.SkipUnless(Condition.IsPlatform('linux'), Condition.PluginExists('header_rewrite.so'), Condition.PluginExists('conf_remap.so')) + +for mode in ('disabled', 'enabled', 'retry', 'redirect'): + tr = Test.ATSReplayTest(replay_file=f'replay/origin-tcp-info-{mode}.replay.yaml') + ts = getattr(tr.Processes, f'ts_{mode}') + if mode == 'retry': + server = tr.Processes.server_retry + get_port(ts, 'closed_port') + ts.Disk.parent_config.AddLine( + f'dest_domain=. parent="127.0.0.1:{server.Variables.http_port};127.0.0.1:{ts.Variables.closed_port}" ' + 'round_robin=false go_direct=false parent_is_proxy=true parent_retry=simple_retry ' + 'simple_server_retry_responses="503" max_simple_retries=1') + ts.Disk.traffic_out.Content += Testers.ContainsExpression( + f'open connection to .*127\\.0\\.0\\.1:{ts.Variables.closed_port}', 'The retry must attempt the second parent') + log_path = os.path.join(ts.Variables.LOGDIR, 'origin_tcp_info.log') + checker = os.path.join(Test.TestDirectory, 'verify_origin_tcp_info.py') + tr.Processes.Default.Command += (f' && {shlex.quote(sys.executable)} {shlex.quote(checker)} {shlex.quote(log_path)} {mode}') + tr.Processes.Default.TimeOut = 30 + tr.Processes.Default.Streams.stdout += Testers.ContainsExpression( + f'PASS: origin TCP_INFO sampling {mode}', f'Validate all four origin TCP_INFO fields with sampling {mode}') + +Test.ATSReplayTest(replay_file='replay/origin-tcp-info-global-disabled.replay.yaml') diff --git a/tests/gold_tests/logging/origin-tcp-info.rewrite.config b/tests/gold_tests/logging/origin-tcp-info.rewrite.config new file mode 100644 index 00000000000..19523fe88b2 --- /dev/null +++ b/tests/gold_tests/logging/origin-tcp-info.rewrite.config @@ -0,0 +1,33 @@ +# Licensed to the Apache Software Foundation (ASF) under one +# or more contributor license agreements. See the NOTICE file +# distributed with this work for additional information +# regarding copyright ownership. The ASF licenses this file +# to you under the Apache License, Version 2.0 (the +# "License"); you may not use this file except in compliance +# with the License. You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +cond %{READ_REQUEST_HDR_HOOK} [AND] +cond %{CLIENT-HEADER:uuid} =guard +set-http-cntl LOGGING off + +# Re-enable logging after core sampling, so the access log exposes whether +# TCP_INFO was incorrectly sampled while transaction logging was disabled. +cond %{SEND_RESPONSE_HDR_HOOK} [AND] +cond %{CLIENT-HEADER:uuid} =guard +set-http-cntl LOGGING on + +cond %{READ_REQUEST_HDR_HOOK} [AND] +cond %{CLIENT-HEADER:uuid} =rewrite-enabled +set-config proxy.config.http.log_server_tcp_info 1 + +cond %{READ_REQUEST_HDR_HOOK} [AND] +cond %{CLIENT-HEADER:uuid} =rewrite-disabled +set-config proxy.config.http.log_server_tcp_info 0 diff --git a/tests/gold_tests/logging/replay/origin-tcp-info-disabled.replay.yaml b/tests/gold_tests/logging/replay/origin-tcp-info-disabled.replay.yaml new file mode 100644 index 00000000000..32479c3d64a --- /dev/null +++ b/tests/gold_tests/logging/replay/origin-tcp-info-disabled.replay.yaml @@ -0,0 +1,107 @@ +# Licensed to the Apache Software Foundation (ASF) under one +# or more contributor license agreements. See the NOTICE file +# distributed with this work for additional information +# regarding copyright ownership. The ASF licenses this file +# to you under the Apache License, Version 2.0 (the +# "License"); you may not use this file except in compliance +# with the License. You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +meta: + version: "1.0" + +autest: + description: 'Verify default-disabled origin TCP_INFO can be enabled per transaction' + server: + name: server_disabled + client: + name: client_disabled + ats: + name: ts_disabled + process_config: + enable_cache: false + # Leave log_server_tcp_info unset to check that sampling defaults to off. + records_config: + proxy.config.log.max_secs_per_buffer: 1 + proxy.config.log.periodic_tasks_interval: 1 + remap_config: + - from: 'http://origin-tcp-info.test/' + to: 'http://127.0.0.1:{SERVER_HTTP_PORT}/' + - from: 'http://enabled-origin-tcp-info.test/' + to: 'http://127.0.0.1:{SERVER_HTTP_PORT}/' + plugins: + - name: conf_remap.so + args: ['proxy.config.http.log_server_tcp_info=1'] + copy_to_config_dir: + - origin-tcp-info.rewrite.config + plugin_config: + - name: header_rewrite.so + args: [origin-tcp-info.rewrite.config] + logging_yaml: + logging: + formats: + - name: origin_tcp_info + format: '%<{uuid}cqh> % % % % %' + logs: + - filename: origin_tcp_info + format: origin_tcp_info + mode: ascii + +sessions: +- transactions: + - client-request: + method: GET + url: /disabled + version: '1.1' + headers: + fields: + - [Host, origin-tcp-info.test] + - [uuid, miss] + server-response: &origin_response + status: 200 + headers: + fields: + - [Content-Length, 16] + proxy-response: &proxy_response + status: 200 + + - client-request: + method: GET + url: /remap-enabled + version: '1.1' + headers: + fields: + - [Host, enabled-origin-tcp-info.test] + - [uuid, remap-enabled] + server-response: *origin_response + proxy-response: *proxy_response + + - client-request: + method: GET + url: /rewrite-enabled + version: '1.1' + headers: + fields: + - [Host, origin-tcp-info.test] + - [uuid, rewrite-enabled] + server-response: *origin_response + proxy-response: *proxy_response + + # A later request on the same client connection must retain the global default. + - client-request: + method: GET + url: /default-after-override + version: '1.1' + headers: + fields: + - [Host, origin-tcp-info.test] + - [uuid, miss-after-override] + server-response: *origin_response + proxy-response: *proxy_response diff --git a/tests/gold_tests/logging/replay/origin-tcp-info-enabled.replay.yaml b/tests/gold_tests/logging/replay/origin-tcp-info-enabled.replay.yaml new file mode 100644 index 00000000000..5eaa41ccdd2 --- /dev/null +++ b/tests/gold_tests/logging/replay/origin-tcp-info-enabled.replay.yaml @@ -0,0 +1,179 @@ +# Licensed to the Apache Software Foundation (ASF) under one +# or more contributor license agreements. See the NOTICE file +# distributed with this work for additional information +# regarding copyright ownership. The ASF licenses this file +# to you under the Apache License, Version 2.0 (the +# "License"); you may not use this file except in compliance +# with the License. You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +meta: + version: "1.0" + +autest: + description: 'Verify origin TCP_INFO on a miss, a hit, and a transaction disabled at sampling time' + server: + name: server_enabled + client: + name: client_enabled + ats: + name: ts_enabled + process_config: + enable_cache: true + records_config: + proxy.config.http.log_server_tcp_info: 1 + proxy.config.http.response_header_max_size: 256 + proxy.config.log.max_secs_per_buffer: 1 + proxy.config.log.periodic_tasks_interval: 1 + remap_config: + - from: 'http://origin-tcp-info.test/' + to: 'http://127.0.0.1:{SERVER_HTTP_PORT}/' + - from: 'http://disabled-origin-tcp-info.test/' + to: 'http://127.0.0.1:{SERVER_HTTP_PORT}/' + plugins: + - name: conf_remap.so + args: ['proxy.config.http.log_server_tcp_info=0'] + copy_to_config_dir: + - origin-tcp-info.rewrite.config + plugin_config: + - name: header_rewrite.so + args: [origin-tcp-info.rewrite.config] + logging_yaml: + logging: + formats: + - name: origin_tcp_info + format: '%<{uuid}cqh> % % % % %' + logs: + - filename: origin_tcp_info + format: origin_tcp_info + mode: ascii + +sessions: +- transactions: + - client-request: + method: GET + url: /cacheable + version: '1.1' + headers: + fields: + - [Host, origin-tcp-info.test] + - [uuid, miss] + server-response: &origin_response + status: 200 + headers: + fields: + - [Content-Length, 16] + - [Cache-Control, 'public, max-age=300'] + proxy-response: + status: 200 + + - client-request: + delay: 100ms + method: GET + url: /cacheable + version: '1.1' + headers: + fields: + - [Host, origin-tcp-info.test] + - [uuid, hit] + # An unexpected origin request must fail the response check. + server-response: + status: 404 + proxy-response: + status: 200 + + - client-request: + method: GET + url: /guard + version: '1.1' + headers: + fields: + - [Host, origin-tcp-info.test] + - [uuid, guard] + server-response: *origin_response + proxy-response: + status: 200 + + - client-request: + method: GET + url: /oversized + version: '1.1' + headers: + fields: + - [Host, origin-tcp-info.test] + - [uuid, oversized] + server-response: + status: 200 + headers: + fields: + - [Content-Length, 0] + - - X-Large + - >- + aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa + aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa + aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa + + proxy-response: + status: 502 + + - client-request: + method: GET + url: /remap-disabled + version: '1.1' + headers: + fields: + - [Host, disabled-origin-tcp-info.test] + - [uuid, remap-disabled] + server-response: *origin_response + proxy-response: + status: 200 + + - client-request: + method: GET + url: /rewrite-disabled + version: '1.1' + headers: + fields: + - [Host, origin-tcp-info.test] + - [uuid, rewrite-disabled] + server-response: *origin_response + proxy-response: + status: 200 + + # A later request on the same client connection must retain the global default. + - client-request: + method: GET + url: /default-after-override + version: '1.1' + headers: + fields: + - [Host, origin-tcp-info.test] + - [uuid, miss-after-override] + server-response: *origin_response + proxy-response: + status: 200 + + - client-request: + method: GET + url: /malformed + version: '1.1' + headers: + fields: + - [Host, origin-tcp-info.test] + - [uuid, malformed] + server-response: + status: 200 + headers: + fields: + - [Content-Length, 0] + # A NUL in a header is rejected by the MIME parser. + - [X-Bad, "before\0after"] + proxy-response: + status: 502 diff --git a/tests/gold_tests/logging/replay/origin-tcp-info-global-disabled.replay.yaml b/tests/gold_tests/logging/replay/origin-tcp-info-global-disabled.replay.yaml new file mode 100644 index 00000000000..097bed76063 --- /dev/null +++ b/tests/gold_tests/logging/replay/origin-tcp-info-global-disabled.replay.yaml @@ -0,0 +1,60 @@ +# Licensed to the Apache Software Foundation (ASF) under one +# or more contributor license agreements. See the NOTICE file +# distributed with this work for additional information +# regarding copyright ownership. The ASF licenses this file +# to you under the Apache License, Version 2.0 (the +# "License"); you may not use this file except in compliance +# with the License. You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +meta: + version: "1.0" + +autest: + description: 'Skip TCP_INFO when access logging is globally disabled' + server: + name: server_global_disabled + client: + name: client_global_disabled + ats: + name: ts_global_disabled + process_config: + enable_cache: false + records_config: + proxy.config.http.log_server_tcp_info: 1 + proxy.config.log.logging_enabled: 0 + proxy.config.diags.debug.enabled: 1 + proxy.config.diags.debug.tags: 'socket_tcp_info' + remap_config: + - from: 'http://origin-tcp-info.test/' + to: 'http://127.0.0.1:{SERVER_HTTP_PORT}/' + log_validation: + traffic_out: + excludes: + - expression: '\(socket_tcp_info\)' + description: 'The TCP_INFO accessor must not run with access logging disabled' + +sessions: +- transactions: + - client-request: + method: GET + url: /global-disabled + version: '1.1' + headers: + fields: + - [Host, origin-tcp-info.test] + - [uuid, global-disabled] + server-response: + status: 200 + headers: + fields: + - [Content-Length, 16] + proxy-response: + status: 200 diff --git a/tests/gold_tests/logging/replay/origin-tcp-info-redirect.replay.yaml b/tests/gold_tests/logging/replay/origin-tcp-info-redirect.replay.yaml new file mode 100644 index 00000000000..ec80fdc7968 --- /dev/null +++ b/tests/gold_tests/logging/replay/origin-tcp-info-redirect.replay.yaml @@ -0,0 +1,87 @@ +# Licensed to the Apache Software Foundation (ASF) under one +# or more contributor license agreements. See the NOTICE file +# distributed with this work for additional information +# regarding copyright ownership. The ASF licenses this file +# to you under the Apache License, Version 2.0 (the +# "License"); you may not use this file except in compliance +# with the License. You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +meta: + version: "1.0" + +autest: + description: 'Clear origin TCP_INFO when following a redirect to a cached response' + server: + name: server_redirect + client: + name: client_redirect + ats: + name: ts_redirect + process_config: + enable_cache: true + records_config: + proxy.config.http.log_server_tcp_info: 1 + proxy.config.http.number_of_redirections: 1 + proxy.config.http.redirect_use_orig_cache_key: 0 + proxy.config.http.redirect.actions: 'self:follow' + proxy.config.log.max_secs_per_buffer: 1 + proxy.config.log.periodic_tasks_interval: 1 + remap_config: + - from: 'http://origin-tcp-info.test/' + to: 'http://127.0.0.1:{SERVER_HTTP_PORT}/' + logging_yaml: + logging: + formats: + - name: origin_tcp_info + format: '%<{uuid}cqh> % % % % %' + logs: + - filename: origin_tcp_info + format: origin_tcp_info + mode: ascii + +sessions: +- transactions: + - client-request: + method: GET + url: /target + version: '1.1' + headers: + fields: + - [Host, origin-tcp-info.test] + - [uuid, prime] + server-response: + status: 200 + headers: + fields: + - [Content-Length, 16] + - [Cache-Control, 'public, max-age=300'] + proxy-response: + status: 200 + + - client-request: + # Allow the target's cache write to finish before following the redirect. + delay: 100ms + method: GET + url: /redirect + version: '1.1' + headers: + fields: + - [Host, origin-tcp-info.test] + - [uuid, redirect] + server-response: + status: 302 + headers: + fields: + - [Content-Length, 0] + - [Location, /target] + - [Cache-Control, no-store] + proxy-response: + status: 200 diff --git a/tests/gold_tests/logging/replay/origin-tcp-info-retry.replay.yaml b/tests/gold_tests/logging/replay/origin-tcp-info-retry.replay.yaml new file mode 100644 index 00000000000..57700b554fb --- /dev/null +++ b/tests/gold_tests/logging/replay/origin-tcp-info-retry.replay.yaml @@ -0,0 +1,76 @@ +# Licensed to the Apache Software Foundation (ASF) under one +# or more contributor license agreements. See the NOTICE file +# distributed with this work for additional information +# regarding copyright ownership. The ASF licenses this file +# to you under the Apache License, Version 2.0 (the +# "License"); you may not use this file except in compliance +# with the License. You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +meta: + version: "1.0" + +autest: + description: 'Discard TCP_INFO from a 503 when the next parent connection fails' + server: + name: server_retry + client: + name: client_retry + ats: + name: ts_retry + process_config: + enable_cache: false + records_config: + proxy.config.http.log_server_tcp_info: 1 + proxy.config.http.no_dns_just_forward_to_parent: 1 + proxy.config.http.uncacheable_requests_bypass_parent: 0 + proxy.config.http.parent_proxy.total_connect_attempts: 1 + proxy.config.http.parent_proxy.per_parent_connect_attempts: 1 + proxy.config.http.parent_proxy.self_detect: 0 + proxy.config.log.max_secs_per_buffer: 1 + proxy.config.log.periodic_tasks_interval: 1 + proxy.config.diags.debug.enabled: 1 + proxy.config.diags.debug.tags: 'http|socket_tcp_info' + # The test adds two parents: this server, followed by an unused TCP port. + remap_config: + - from: 'http://origin-tcp-info.test/' + to: 'http://origin-tcp-info.test/' + logging_yaml: + logging: + formats: + - name: origin_tcp_info + format: '%<{uuid}cqh> % % % % %' + logs: + - filename: origin_tcp_info + format: origin_tcp_info + mode: ascii + log_validation: + traffic_out: + contains: + - expression: '\(socket_tcp_info\).*rtt=[1-9][0-9]*' + description: 'The first parent must supply a sample before the retry' + +sessions: +- transactions: + - client-request: + method: GET + url: /retry + version: '1.1' + headers: + fields: + - [Host, origin-tcp-info.test] + - [uuid, retry] + server-response: + status: 503 + headers: + fields: + - [Content-Length, 0] + proxy-response: + status: 502 diff --git a/tests/gold_tests/logging/verify_origin_tcp_info.py b/tests/gold_tests/logging/verify_origin_tcp_info.py new file mode 100644 index 00000000000..e5e5d7633ad --- /dev/null +++ b/tests/gold_tests/logging/verify_origin_tcp_info.py @@ -0,0 +1,91 @@ +# Licensed to the Apache Software Foundation (ASF) under one +# or more contributor license agreements. See the NOTICE file +# distributed with this work for additional information +# regarding copyright ownership. The ASF licenses this file +# to you under the Apache License, Version 2.0 (the +# "License"); you may not use this file except in compliance +# with the License. You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. +"""Validate origin TCP_INFO access-log fields after replay traffic completes.""" + +import argparse +from pathlib import Path +import time + + +def verify(log_path: Path, mode: str) -> None: + expected_keys = { + 'disabled': {'miss', 'remap-enabled', 'rewrite-enabled', 'miss-after-override'}, + 'enabled': {'miss', 'hit', 'guard', 'oversized', 'malformed', 'remap-disabled', 'rewrite-disabled', 'miss-after-override'}, + 'retry': {'retry'}, + 'redirect': {'prime', 'redirect-response', 'redirect'}, + }[mode] + expected_samples = { + 'disabled': {'remap-enabled', 'rewrite-enabled'}, + 'enabled': {'miss', 'miss-after-override'}, + 'redirect': {'prime', 'redirect-response'}, + }.get(mode, set()) + # Wait for the asynchronous log writer, rather than sleeping a fixed time. + deadline = time.monotonic() + 15 + while True: + contents = log_path.read_text() if log_path.exists() else '' + # A final record without its newline may still be partially written. + lines = contents.split('\n')[:-1] + if len(lines) >= len(expected_keys): + break + if time.monotonic() >= deadline: + raise AssertionError(f'Timed out waiting for access-log records for {expected_keys}: {contents!r}') + time.sleep(0.1) + + if len(lines) != len(expected_keys): + raise AssertionError(f'Expected {len(expected_keys)} access-log records: {lines}') + + rows = {} + for line in lines: + fields = line.split() + if len(fields) != 6: + raise AssertionError(f'Expected a transaction ID, cache result, and four TCP_INFO fields: {line}') + key, cache_result, *values = fields + # Following a redirect emits a row before the final response row. + if mode == 'redirect' and cache_result == 'TCP_MISS_REDIRECT': + key = f'{key}-response' + if key in rows: + raise AssertionError(f'Duplicate transaction ID: {key}') + rows[key] = (cache_result, [int(value) for value in values]) + + if set(rows) != expected_keys: + raise AssertionError(f'Unexpected transaction IDs: {rows}') + + for key in expected_keys & {'miss', 'guard', 'prime', 'remap-enabled', 'remap-disabled', 'rewrite-enabled', 'rewrite-disabled', + 'miss-after-override'}: + if rows[key][0] != 'TCP_MISS': + raise AssertionError(f'{key} must reach the origin: {rows[key]}') + for key in expected_keys & {'hit', 'redirect'}: + if rows[key][0] not in ('TCP_HIT', 'TCP_MEM_HIT'): + raise AssertionError(f'Expected a cache hit: {rows[key]}') + + for key, (_, values) in rows.items(): + if key in expected_samples: + rtt, rttvar, retrans, cwnd = values + if not (rtt > 0 and rttvar >= 0 and retrans >= 0 and cwnd > 0): + raise AssertionError(f'Expected a valid origin TCP_INFO sample: {values}') + elif values != [-1, -1, -1, -1]: + raise AssertionError(f'{key} must have no TCP_INFO sample with sampling {mode}: {values}') + + print(f'PASS: origin TCP_INFO sampling {mode}') + print('\n'.join(lines)) + + +if __name__ == '__main__': + parser = argparse.ArgumentParser(description=__doc__) + parser.add_argument('log_path', type=Path) + parser.add_argument('mode', choices=('disabled', 'enabled', 'retry', 'redirect')) + args = parser.parse_args() + verify(args.log_path, args.mode)