From ba00fbf3b13b8e72ecdeb6292e887aea0c839d82 Mon Sep 17 00:00:00 2001 From: Mo Chen Date: Thu, 10 Sep 2026 10:59:18 -0500 Subject: [PATCH 1/2] Log TCP_INFO for origin connections Expose origin TCP measurements so access logs can help distinguish network delay from origin processing time. Preserve a snapshot while the socket is available, discard it on retries, and require opt-in sampling with logging enabled to avoid unnecessary syscalls. --- doc/admin-guide/files/records.yaml.en.rst | 23 +++ doc/admin-guide/logging/formatting.en.rst | 16 ++ include/iocore/net/NetVConnection.h | 16 ++ include/iocore/net/TcpInfoSnapshot.h | 43 ++++++ include/proxy/http/HttpConfig.h | 2 + include/proxy/http/HttpSM.h | 7 +- include/proxy/logging/LogAccess.h | 7 + include/proxy/logging/TransactionLogData.h | 4 + src/iocore/net/P_UnixNetVConnection.h | 36 +++++ src/proxy/http/HttpConfig.cc | 2 + src/proxy/http/HttpSM.cc | 20 +++ src/proxy/logging/Log.cc | 20 +++ src/proxy/logging/LogAccess.cc | 49 +++++++ src/proxy/logging/TransactionLogData.cc | 11 ++ src/records/RecordsConfig.cc | 2 + .../logging/log-origin-tcp-info.test.py | 46 ++++++ .../logging/origin-tcp-info.rewrite.config | 25 ++++ .../origin-tcp-info-disabled.replay.yaml | 63 ++++++++ .../origin-tcp-info-enabled.replay.yaml | 137 ++++++++++++++++++ ...rigin-tcp-info-global-disabled.replay.yaml | 60 ++++++++ .../replay/origin-tcp-info-retry.replay.yaml | 76 ++++++++++ .../logging/verify_origin_tcp_info.py | 78 ++++++++++ 22 files changed, 741 insertions(+), 2 deletions(-) create mode 100644 include/iocore/net/TcpInfoSnapshot.h create mode 100644 tests/gold_tests/logging/log-origin-tcp-info.test.py create mode 100644 tests/gold_tests/logging/origin-tcp-info.rewrite.config create mode 100644 tests/gold_tests/logging/replay/origin-tcp-info-disabled.replay.yaml create mode 100644 tests/gold_tests/logging/replay/origin-tcp-info-enabled.replay.yaml create mode 100644 tests/gold_tests/logging/replay/origin-tcp-info-global-disabled.replay.yaml create mode 100644 tests/gold_tests/logging/replay/origin-tcp-info-retry.replay.yaml create mode 100644 tests/gold_tests/logging/verify_origin_tcp_info.py diff --git a/doc/admin-guide/files/records.yaml.en.rst b/doc/admin-guide/files/records.yaml.en.rst index 5d75b68bafc..a127669ef63 100644 --- a/doc/admin-guide/files/records.yaml.en.rst +++ b/doc/admin-guide/files/records.yaml.en.rst @@ -2433,6 +2433,29 @@ Security post body larger than this limit the response will be terminated with 413 - Request Entity Too Large and logged accordingly. +.. ts:cv:: CONFIG proxy.config.http.log_server_tcp_info INT 0 + :reloadable: + + Enables sampling of ``TCP_INFO`` on the origin connection, so that the round + trip time to the origin can be logged. + + When this is enabled, |TS| reads ``TCP_INFO`` from the origin socket at the + point it successfully parses the origin response header, and keeps the values for + the access log. 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. Later 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.http.allow_multi_range INT 0 :reloadable: :overridable: 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/include/iocore/net/NetVConnection.h b/include/iocore/net/NetVConnection.h index fe090bf77bf..b81cde1b9f1 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..52a75530a08 100644 --- a/include/proxy/http/HttpConfig.h +++ b/include/proxy/http/HttpConfig.h @@ -877,6 +877,8 @@ struct HttpConfigParams : public ConfigInfo { MgmtByte enable_http_stats = 1; // Can be "slow" + MgmtByte log_server_tcp_info = 0; // Sample origin TCP_INFO for access logging. + MgmtByte push_method_enabled = 0; MgmtByte referer_filter_enabled = 0; diff --git a/include/proxy/http/HttpSM.h b/include/proxy/http/HttpSM.h index c2128eeca20..2152e47532c 100644 --- a/include/proxy/http/HttpSM.h +++ b/include/proxy/http/HttpSM.h @@ -531,8 +531,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/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/src/iocore/net/P_UnixNetVConnection.h b/src/iocore/net/P_UnixNetVConnection.h index 71d27374541..6c0a83664c1 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,39 @@ 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) + 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; + } + 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_RETRANS + // 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/proxy/http/HttpConfig.cc b/src/proxy/http/HttpConfig.cc index 08a3ed23633..b34fbdb6705 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.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->log_server_tcp_info = INT_TO_BOOL(m_master.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..4aa04ccb21c 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.http_config_param->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. 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..354c8be873f --- /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')) + +for mode in ('disabled', 'enabled', 'retry'): + 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..c528c085061 --- /dev/null +++ b/tests/gold_tests/logging/origin-tcp-info.rewrite.config @@ -0,0 +1,25 @@ +# 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 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..cfe6d1ecab9 --- /dev/null +++ b/tests/gold_tests/logging/replay/origin-tcp-info-disabled.replay.yaml @@ -0,0 +1,63 @@ +# 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 all origin TCP_INFO fields are unavailable with the default configuration' + 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}/' + 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: + status: 200 + headers: + fields: + - [Content-Length, 16] + proxy-response: + status: 200 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..32d88a2fb6e --- /dev/null +++ b/tests/gold_tests/logging/replay/origin-tcp-info-enabled.replay.yaml @@ -0,0 +1,137 @@ +# 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}/' + 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: /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-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..36dd2d21cca --- /dev/null +++ b/tests/gold_tests/logging/verify_origin_tcp_info.py @@ -0,0 +1,78 @@ +# 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'}, + 'enabled': {'miss', 'hit', 'guard', 'oversized', 'malformed'}, + 'retry': {'retry'}, + }[mode] + # Wait for the asynchronous log writer, rather than sleeping a fixed time. + deadline = time.monotonic() + 15 + while True: + lines = log_path.read_text().splitlines() if log_path.exists() else [] + if len(lines) >= len(expected_keys): + break + if time.monotonic() >= deadline: + raise AssertionError(f'Timed out waiting for access-log records for {expected_keys}: {lines}') + 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 + 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'}: + if rows[key][0] != 'TCP_MISS': + raise AssertionError(f'{key} must reach the origin: {rows[key]}') + if 'hit' in rows and rows['hit'][0] not in ('TCP_HIT', 'TCP_MEM_HIT'): + raise AssertionError(f'Expected a cache hit: {rows["hit"]}') + + for key, (_, values) in rows.items(): + if mode == 'enabled' and key == 'miss': + 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')) + args = parser.parse_args() + verify(args.log_path, args.mode) From 3e3c87618d9e056997a1fe9b15eb4e70e6abd51f Mon Sep 17 00:00:00 2001 From: Mo Chen Date: Thu, 10 Sep 2026 11:57:31 -0500 Subject: [PATCH 2/2] Harden origin TCP_INFO logging Avoid uninitialized TCP_INFO data and reporting unsupported retransmit counters as zero. Wait for complete log records so asynchronous writes cannot produce spurious test failures. --- include/proxy/http/HttpSM.h | 1 + src/iocore/net/P_UnixNetVConnection.h | 6 ++++-- tests/gold_tests/logging/verify_origin_tcp_info.py | 6 ++++-- 3 files changed, 9 insertions(+), 4 deletions(-) diff --git a/include/proxy/http/HttpSM.h b/include/proxy/http/HttpSM.h index 2152e47532c..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" diff --git a/src/iocore/net/P_UnixNetVConnection.h b/src/iocore/net/P_UnixNetVConnection.h index 6c0a83664c1..d9a0d70ba81 100644 --- a/src/iocore/net/P_UnixNetVConnection.h +++ b/src/iocore/net/P_UnixNetVConnection.h @@ -311,8 +311,9 @@ UnixNetVConnection::set_mptcp_state() inline bool UnixNetVConnection::get_tcp_info(TcpInfoSnapshot &info) const { -#if defined(TCP_INFO) && defined(HAVE_STRUCT_TCP_INFO) - struct tcp_info tinfo; +#if defined(TCP_INFO) && defined(HAVE_STRUCT_TCP_INFO) && \ + (HAVE_STRUCT_TCP_INFO_TCPI_TOTAL_RETRANS || HAVE_STRUCT_TCP_INFO___TCPI_RETRANS) + struct tcp_info tinfo = {}; int tinfo_len = sizeof(tinfo); int const fd = con.sock.get_fd(); @@ -320,6 +321,7 @@ UnixNetVConnection::get_tcp_info(TcpInfoSnapshot &info) const Dbg(_dbg_ctl_socket_tcp_info, "failed getsockopt(%d, TCP_INFO): %s", fd, strerror(errno)); return false; } + info.rtt = tinfo.tcpi_rtt; info.rttvar = tinfo.tcpi_rttvar; info.snd_cwnd = tinfo.tcpi_snd_cwnd; diff --git a/tests/gold_tests/logging/verify_origin_tcp_info.py b/tests/gold_tests/logging/verify_origin_tcp_info.py index 36dd2d21cca..e9b8f0e8b1b 100644 --- a/tests/gold_tests/logging/verify_origin_tcp_info.py +++ b/tests/gold_tests/logging/verify_origin_tcp_info.py @@ -29,11 +29,13 @@ def verify(log_path: Path, mode: str) -> None: # Wait for the asynchronous log writer, rather than sleeping a fixed time. deadline = time.monotonic() + 15 while True: - lines = log_path.read_text().splitlines() if log_path.exists() else [] + 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}: {lines}') + 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):