Add origin server tcp_info logging

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 <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. 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:

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.

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

@@ -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;

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

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,41 @@ 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_RETRANS)
+  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()
 {

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;
 

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<int>(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.

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);