Add origin server tcp_info logging

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)

doc/admin-guide/files/records.yaml.en.rst

@@ -3776,6 +3776,39 @@ HostDB
 Logging Configuration
 =====================
 
+.. ts:cv:: CONFIG proxy.config.http.log_server_tcp_info INT 0
+   :reloadable:
+   :overridable:
+
+   Enables sampling of ``TCP_INFO`` on the origin connection, so that the round
+   trip time to the origin can be logged.
+
+   This can be overridden per transaction using ``conf_remap`` or
+   ``header_rewrite`` before the origin response header is parsed. For example,
+   leave the global value at ``0`` and enable collection on a selected remap::
+
+      map http://cdn.example/ http://origin.example/ @plugin=conf_remap.so @pparam=proxy.config.http.log_server_tcp_info=1
+
+   When this is enabled, |TS| reads ``TCP_INFO`` from the origin socket once for
+   each successfully parsed origin response header and keeps the values for the
+   access log. This normally means one snapshot per transaction; retries,
+   redirects, or informational responses can cause additional snapshots. A direct
+   cache hit does not read ``TCP_INFO``. By log time, the connection may have been
+   closed or released for reuse by another transaction. The values feed the :ref:`srtt <srtt>`,
+   :ref:`srtv <srtv>`, :ref:`sret <sret>` and :ref:`scwn <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:
 

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.

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`

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

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 <cstdint>
 #include <string_view>
@@ -381,6 +382,21 @@ class NetVConnection : public VConnection, public PluginUserArgs<TS_USER_ARGS_VC
   /** Set the MPTCP state for this connection */
   virtual void set_mptcp_state() = 0;
 
+  /** Read @c TCP_INFO from the underlying socket.
+   *
+   * @param[out] info Filled in only when this returns @c true.
+   * @return @c true if the kernel supplied the information.
+   *
+   * The default reports no information, which covers every connection that is
+   * not carried over TCP.  Call this while the connection is still open; the
+   * caller keeps the copy it needs.
+   */
+  virtual bool
+  get_tcp_info(TcpInfoSnapshot & /* info */) const
+  {
+    return false;
+  }
+
   // for InkAPI
   bool
   get_is_internal_request() const

include/iocore/net/TcpInfoSnapshot.h

@@ -0,0 +1,43 @@
+/** @file
+
+  A snapshot of the TCP_INFO fields that ATS reports.
+
+  @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.
+ */
+
+#pragma once
+
+#include <cstdint>
+
+/** 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.
+};

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 //

include/proxy/http/HttpSM.h

@@ -50,6 +50,7 @@
 // inknet
 #include "proxy/http/PreWarmManager.h"
 #include "iocore/net/TLSTunnelSupport.h"
+#include "iocore/net/TcpInfoSnapshot.h"
 
 #include "tscore/History.h"
 #include "tscore/PendingAction.h"
@@ -531,8 +532,11 @@ class HttpSM : public Continuation, public PluginUserArgs<TS_USER_ARGS_TXN>
   //  do_api_callout_internal()
   bool                hooks_set = false;
   std::optional<bool> 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<TcpInfoSnapshot> server_tcp_info;
+  const char                    *server_protocol       = "-";
+  int                            server_transact_count = 0;
 
   TransactionMilestones milestones;
   ink_hrtime            api_timer = 0;

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

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;

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 <cstddef>
@@ -162,6 +163,9 @@ class TransactionLogData
   // ===== MPTCP =====
   std::optional<bool> get_mptcp_state() const;
 
+  // ===== Origin connection TCP_INFO =====
+  std::optional<TcpInfoSnapshot> get_server_tcp_info() const;
+
   // ===== Misc transaction state =====
   in_port_t get_incoming_port() const;
   int       get_orig_scheme() const;

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,
 };
 

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

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

src/iocore/net/P_UnixNetVConnection.h

@@ -31,6 +31,7 @@
 
 #pragma once
 
+#include <cinttypes>
 #include <memory>
 
 #include "tscore/ink_sock.h"
@@ -203,6 +204,7 @@ class UnixNetVConnection : public NetVConnection, public NetEvent
 
   void set_local_addr() override;
   void set_mptcp_state() override;
+  bool get_tcp_info(TcpInfoSnapshot &info) const override;
   void set_remote_addr() override;
   void set_remote_addr(const sockaddr *) override;
   int  set_tcp_congestion_control(tcp_congestion_control_side side) override;
@@ -245,6 +247,7 @@ class UnixNetVConnection : public NetVConnection, public NetEvent
 
   inline static DbgCtl _dbg_ctl_socket{"socket"};
   inline static DbgCtl _dbg_ctl_socket_mptcp{"socket_mptcp"};
+  inline static DbgCtl _dbg_ctl_socket_tcp_info{"socket_tcp_info"};
 
   /** The shared group across all connections for this IP to track incoming
    * connections for connection limiting. */
@@ -304,6 +307,48 @@ UnixNetVConnection::set_mptcp_state()
 #endif
 }
 
+// Copy the TCP_INFO fields ATS reports out of the kernel.
+inline bool
+UnixNetVConnection::get_tcp_info(TcpInfoSnapshot &info) const
+{
+#if defined(TCP_INFO) && defined(HAVE_STRUCT_TCP_INFO) && \
+  (HAVE_STRUCT_TCP_INFO_TCPI_TOTAL_RETRANS || HAVE_STRUCT_TCP_INFO_TCPI_SND_REXMITPACK)
+  if (con.sock_type != SOCK_STREAM) {
+    return false;
+  }
+
+  struct tcp_info tinfo     = {};
+  int             tinfo_len = sizeof(tinfo);
+  int const       fd        = con.sock.get_fd();
+
+  if (0 != safe_getsockopt(fd, IPPROTO_TCP, TCP_INFO, &tinfo, &tinfo_len)) {
+    Dbg(_dbg_ctl_socket_tcp_info, "failed getsockopt(%d, TCP_INFO): %s", fd, strerror(errno));
+    return false;
+  }
+  if (tinfo_len != static_cast<int>(sizeof(tinfo))) {
+    return false;
+  }
+
+  info.rtt      = tinfo.tcpi_rtt;
+  info.rttvar   = tinfo.tcpi_rttvar;
+  info.snd_cwnd = tinfo.tcpi_snd_cwnd;
+#if HAVE_STRUCT_TCP_INFO_TCPI_TOTAL_RETRANS
+  info.retrans = tinfo.tcpi_total_retrans;
+#elif HAVE_STRUCT_TCP_INFO_TCPI_SND_REXMITPACK
+  // FreeBSD spells the cumulative count differently; __tcpi_retrans is the
+  // currently outstanding count, which is not what this reports.
+  info.retrans = tinfo.tcpi_snd_rexmitpack;
+#endif
+
+  Dbg(_dbg_ctl_socket_tcp_info, "fd %d rtt=%" PRId64 " rttvar=%" PRId64 " retrans=%" PRId64 " cwnd=%" PRId64, fd, info.rtt,
+      info.rttvar, info.retrans, info.snd_cwnd);
+  return true;
+#else
+  (void)info;
+  return false;
+#endif
+}
+
 inline ink_hrtime
 UnixNetVConnection::get_active_timeout()
 {

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 <catch2/catch_test_macros.hpp>
+
+#include <cerrno>
+
+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);
+}