From ba00fbf3b13b8e72ecdeb6292e887aea0c839d82 Mon Sep 17 00:00:00 2001 From: Mo Chen Date: Thu, 10 Sep 2026 10:59:18 -0500 Subject: [PATCH 1/7] 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/7] 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): From d39eebe26416437e9f82394d9fa27b483e081973 Mon Sep 17 00:00:00 2001 From: Mo Chen Date: Fri, 11 Sep 2026 15:08:20 -0500 Subject: [PATCH 3/7] Clear origin TCP_INFO when following redirects A redirected request can hit cache without reaching any origin sampling reset, leaving the previous response's TCP_INFO in its access log. Clear the snapshot after logging the redirect response so cached targets report unavailable fields. --- include/iocore/net/NetVConnection.h | 2 +- src/proxy/http/HttpSM.cc | 1 + .../logging/log-origin-tcp-info.test.py | 2 +- .../origin-tcp-info-redirect.replay.yaml | 87 +++++++++++++++++++ .../logging/verify_origin_tcp_info.py | 15 ++-- 5 files changed, 100 insertions(+), 7 deletions(-) create mode 100644 tests/gold_tests/logging/replay/origin-tcp-info-redirect.replay.yaml diff --git a/include/iocore/net/NetVConnection.h b/include/iocore/net/NetVConnection.h index b81cde1b9f1..58931f21c5d 100644 --- a/include/iocore/net/NetVConnection.h +++ b/include/iocore/net/NetVConnection.h @@ -384,7 +384,7 @@ class NetVConnection : public VConnection, public PluginUserArgs % % % % %' + 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/verify_origin_tcp_info.py b/tests/gold_tests/logging/verify_origin_tcp_info.py index e9b8f0e8b1b..25b09c7aac1 100644 --- a/tests/gold_tests/logging/verify_origin_tcp_info.py +++ b/tests/gold_tests/logging/verify_origin_tcp_info.py @@ -25,6 +25,7 @@ def verify(log_path: Path, mode: str) -> None: 'disabled': {'miss'}, 'enabled': {'miss', 'hit', 'guard', 'oversized', 'malformed'}, 'retry': {'retry'}, + 'redirect': {'prime', 'redirect-response', 'redirect'}, }[mode] # Wait for the asynchronous log writer, rather than sleeping a fixed time. deadline = time.monotonic() + 15 @@ -47,6 +48,9 @@ def verify(log_path: Path, mode: str) -> None: 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]) @@ -54,14 +58,15 @@ def verify(log_path: Path, mode: str) -> None: if set(rows) != expected_keys: raise AssertionError(f'Unexpected transaction IDs: {rows}') - for key in expected_keys & {'miss', 'guard'}: + for key in expected_keys & {'miss', 'guard', 'prime'}: 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 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 mode == 'enabled' and key == 'miss': + if (mode == 'enabled' and key == 'miss') or (mode == 'redirect' and key in {'prime', 'redirect-response'}): 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}') @@ -75,6 +80,6 @@ def verify(log_path: Path, mode: str) -> None: if __name__ == '__main__': parser = argparse.ArgumentParser(description=__doc__) parser.add_argument('log_path', type=Path) - parser.add_argument('mode', choices=('disabled', 'enabled', 'retry')) + parser.add_argument('mode', choices=('disabled', 'enabled', 'retry', 'redirect')) args = parser.parse_args() verify(args.log_path, args.mode) From 4aeb84adba5dbff9b40fabae207802ff108a4ecc Mon Sep 17 00:00:00 2001 From: Mo Chen Date: Fri, 11 Sep 2026 15:56:19 -0500 Subject: [PATCH 4/7] Allow per-transaction origin TCP_INFO control Allow remap rules and plugins to enable origin TCP_INFO collection only for selected traffic, so operators can limit its overhead. Keep the global default disabled. --- doc/admin-guide/files/records.yaml.en.rst | 7 +++ .../functions/TSHttpOverridableConfig.en.rst | 1 + .../api/types/TSOverridableConfigKey.en.rst | 1 + include/proxy/http/HttpConfig.h | 3 +- include/proxy/http/OverridableConfigDefs.h | 3 +- include/ts/apidefs.h.in | 1 + src/proxy/http/HttpConfig.cc | 4 +- src/proxy/http/HttpSM.cc | 2 +- .../logging/log-origin-tcp-info.test.py | 2 +- .../logging/origin-tcp-info.rewrite.config | 8 +++ .../origin-tcp-info-disabled.replay.yaml | 50 +++++++++++++++++-- .../origin-tcp-info-enabled.replay.yaml | 42 ++++++++++++++++ .../logging/verify_origin_tcp_info.py | 14 ++++-- 13 files changed, 124 insertions(+), 14 deletions(-) diff --git a/doc/admin-guide/files/records.yaml.en.rst b/doc/admin-guide/files/records.yaml.en.rst index a127669ef63..c2b32a71afd 100644 --- a/doc/admin-guide/files/records.yaml.en.rst +++ b/doc/admin-guide/files/records.yaml.en.rst @@ -2435,10 +2435,17 @@ Security .. 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 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 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/proxy/http/HttpConfig.h b/include/proxy/http/HttpConfig.h index 52a75530a08..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 // @@ -877,8 +878,6 @@ 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/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/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/src/proxy/http/HttpConfig.cc b/src/proxy/http/HttpConfig.cc index b34fbdb6705..1d02f565d1e 100644 --- a/src/proxy/http/HttpConfig.cc +++ b/src/proxy/http/HttpConfig.cc @@ -1099,7 +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.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"); @@ -1448,7 +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.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 a065ffc6894..0faf63390ab 100644 --- a/src/proxy/http/HttpSM.cc +++ b/src/proxy/http/HttpSM.cc @@ -2141,7 +2141,7 @@ HttpSM::state_read_server_response_header(int event, void *data) // 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() && + 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) { diff --git a/tests/gold_tests/logging/log-origin-tcp-info.test.py b/tests/gold_tests/logging/log-origin-tcp-info.test.py index 6acde15ddca..554b2ab5971 100644 --- a/tests/gold_tests/logging/log-origin-tcp-info.test.py +++ b/tests/gold_tests/logging/log-origin-tcp-info.test.py @@ -22,7 +22,7 @@ Test.Summary = 'Verify origin TCP_INFO fields and sampling controls' Test.ContinueOnFail = True -Test.SkipUnless(Condition.IsPlatform('linux'), Condition.PluginExists('header_rewrite.so')) +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') diff --git a/tests/gold_tests/logging/origin-tcp-info.rewrite.config b/tests/gold_tests/logging/origin-tcp-info.rewrite.config index c528c085061..19523fe88b2 100644 --- a/tests/gold_tests/logging/origin-tcp-info.rewrite.config +++ b/tests/gold_tests/logging/origin-tcp-info.rewrite.config @@ -23,3 +23,11 @@ set-http-cntl LOGGING off 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 index cfe6d1ecab9..32479c3d64a 100644 --- a/tests/gold_tests/logging/replay/origin-tcp-info-disabled.replay.yaml +++ b/tests/gold_tests/logging/replay/origin-tcp-info-disabled.replay.yaml @@ -18,7 +18,7 @@ meta: version: "1.0" autest: - description: 'Verify all origin TCP_INFO fields are unavailable with the default configuration' + description: 'Verify default-disabled origin TCP_INFO can be enabled per transaction' server: name: server_disabled client: @@ -34,6 +34,16 @@ autest: 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: @@ -54,10 +64,44 @@ sessions: fields: - [Host, origin-tcp-info.test] - [uuid, miss] - server-response: + server-response: &origin_response status: 200 headers: fields: - [Content-Length, 16] - proxy-response: + 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 index 32d88a2fb6e..5eaa41ccdd2 100644 --- a/tests/gold_tests/logging/replay/origin-tcp-info-enabled.replay.yaml +++ b/tests/gold_tests/logging/replay/origin-tcp-info-enabled.replay.yaml @@ -35,6 +35,11 @@ autest: 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: @@ -118,6 +123,43 @@ sessions: 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 diff --git a/tests/gold_tests/logging/verify_origin_tcp_info.py b/tests/gold_tests/logging/verify_origin_tcp_info.py index 25b09c7aac1..e5e5d7633ad 100644 --- a/tests/gold_tests/logging/verify_origin_tcp_info.py +++ b/tests/gold_tests/logging/verify_origin_tcp_info.py @@ -22,11 +22,16 @@ def verify(log_path: Path, mode: str) -> None: expected_keys = { - 'disabled': {'miss'}, - 'enabled': {'miss', 'hit', 'guard', 'oversized', 'malformed'}, + '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: @@ -58,7 +63,8 @@ def verify(log_path: Path, mode: str) -> None: if set(rows) != expected_keys: raise AssertionError(f'Unexpected transaction IDs: {rows}') - for key in expected_keys & {'miss', 'guard', 'prime'}: + 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'}: @@ -66,7 +72,7 @@ def verify(log_path: Path, mode: str) -> None: raise AssertionError(f'Expected a cache hit: {rows[key]}') for key, (_, values) in rows.items(): - if (mode == 'enabled' and key == 'miss') or (mode == 'redirect' and key in {'prime', 'redirect-response'}): + 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}') From f9f213fd0720aca8c20f851cf28803da5f22dd37 Mon Sep 17 00:00:00 2001 From: Mo Chen Date: Fri, 11 Sep 2026 16:07:26 -0500 Subject: [PATCH 5/7] Clarify origin TCP_INFO sampling frequency Explain when snapshots are taken so operators can assess syscall frequency separately from access-log sampling. --- doc/admin-guide/files/records.yaml.en.rst | 13 ++++++++----- 1 file changed, 8 insertions(+), 5 deletions(-) diff --git a/doc/admin-guide/files/records.yaml.en.rst b/doc/admin-guide/files/records.yaml.en.rst index c2b32a71afd..7fa29294248 100644 --- a/doc/admin-guide/files/records.yaml.en.rst +++ b/doc/admin-guide/files/records.yaml.en.rst @@ -2446,10 +2446,12 @@ Security 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 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 `, + 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. @@ -2458,7 +2460,8 @@ Security 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. + 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. From 909ee6553939fb4c4dda2154f23bdac1e8cd2d57 Mon Sep 17 00:00:00 2001 From: Mo Chen Date: Fri, 11 Sep 2026 16:33:42 -0500 Subject: [PATCH 6/7] Tighten origin TCP_INFO platform guards Check for the FreeBSD counter actually consumed, and skip non-stream sockets before asking the kernel for TCP_INFO. Put the config record with the logging documentation so operators can find it. --- CMakeLists.txt | 1 + doc/admin-guide/files/records.yaml.en.rst | 66 +++++++++++------------ include/tscore/ink_config.h.cmake.in | 1 + src/iocore/net/CMakeLists.txt | 1 + src/iocore/net/P_UnixNetVConnection.h | 8 ++- src/iocore/net/unit_tests/test_TcpInfo.cc | 46 ++++++++++++++++ 6 files changed, 88 insertions(+), 35 deletions(-) create mode 100644 src/iocore/net/unit_tests/test_TcpInfo.cc 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 7fa29294248..47d73e1624c 100644 --- a/doc/admin-guide/files/records.yaml.en.rst +++ b/doc/admin-guide/files/records.yaml.en.rst @@ -2433,39 +2433,6 @@ 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: - :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.http.allow_multi_range INT 0 :reloadable: :overridable: @@ -3809,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/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 d9a0d70ba81..e219a9bc59a 100644 --- a/src/iocore/net/P_UnixNetVConnection.h +++ b/src/iocore/net/P_UnixNetVConnection.h @@ -312,7 +312,11 @@ 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_RETRANS) + (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(); @@ -327,7 +331,7 @@ UnixNetVConnection::get_tcp_info(TcpInfoSnapshot &info) const 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 +#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; 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); +} From 004c8b9c0fe906c5b3dd9c139c48f70689a821c3 Mon Sep 17 00:00:00 2001 From: Mo Chen Date: Fri, 11 Sep 2026 16:58:39 -0500 Subject: [PATCH 7/7] Reject incomplete TCP_INFO snapshots Reject incomplete TCP_INFO replies instead of exposing zero-filled fields as valid samples. Require the full build-time structure to keep validation simple across platforms. --- src/iocore/net/P_UnixNetVConnection.h | 3 +++ 1 file changed, 3 insertions(+) diff --git a/src/iocore/net/P_UnixNetVConnection.h b/src/iocore/net/P_UnixNetVConnection.h index e219a9bc59a..90c79535f2f 100644 --- a/src/iocore/net/P_UnixNetVConnection.h +++ b/src/iocore/net/P_UnixNetVConnection.h @@ -325,6 +325,9 @@ UnixNetVConnection::get_tcp_info(TcpInfoSnapshot &info) const 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;