Adds metrics and log fields for tracking TLS handshake bytes

doc/admin-guide/logging/formatting.en.rst

@@ -426,6 +426,7 @@ Lengths and Sizes
 .. _cqcl:
 .. _cqhl:
 .. _cqql:
+.. _cqqtl:
 .. _csscl:
 .. _csshl:
 .. _cssql:
@@ -436,6 +437,7 @@ Lengths and Sizes
 .. _pscl:
 .. _pshl:
 .. _psql:
+.. _psqtl:
 .. _sscl:
 .. _sshl:
 .. _ssql:
@@ -451,6 +453,10 @@ cqcl  Client Request         Client request content length, in bytes.
 cqhl  Client Request         Client request header length, in bytes.
 cqql  Client Request         Client request header and content length combined,
                              in bytes.
+cqqtl Client Request         Same as cqql_, but for the first transaction on a
+                             TLS connection, also includes TLS handshake bytes
+                             received from the client. Note that this metrics
+                             may not always be 100% accurate.
 csscl Cached Origin Response Content body length from cached origin response.
 csshl Cached Origin Response Header length from cached origin response.
 cssql Cached Origin Response Content and header length from cached origin
@@ -466,6 +472,10 @@ pscl  Proxy Response         Content body length of the |TS| proxy response.
 pshl  Proxy Response         Header length of the |TS| response to client.
 psql  Proxy Response         Content body and header length combined of the
                              |TS| response to client.
+psqtl Proxy Response         Same as psql_, but for the first transaction on a
+                             TLS connection, also includes TLS handshake bytes
+                             sent to the client. Note that this metric may not
+                             always be 100% accurate.
 sscl  Origin Response        Content body length of the origin server response
                              to |TS|.
 sshl  Origin Response        Header length of the origin server response.
@@ -623,6 +633,9 @@ SSL / Encryption
 .. _cqssc:
 .. _cqssu:
 .. _cqssa:
+.. _cthbr:
+.. _cthbt:
+.. _cthb:
 .. _pqssl:
 .. _pscert:
 
@@ -659,6 +672,17 @@ cqssg  Client Request SSL Group used by |TS| to communicate with the client.
                       OpenSSL 3.2 or later or a version of BoringSSL that
                       supports querying group names.
 cqssa  Client Request ALPN Protocol ID negotiated with the client.
+cthbr  Client Request TLS handshake bytes received from the client. This is the
+                      number of bytes read from the client during the TLS
+                      handshake. Populated for all transactions on a TLS connection,
+                      including reused connections.
+cthbt  Client Request TLS handshake bytes sent to the client. This is the number
+                      of bytes written to the client during the TLS handshake.
+                      Populated for all transactions on a TLS connection,
+                      including reused connections.
+cthb   Client Request Total TLS handshake bytes (received + sent). This is the
+                      sum of cthbr_ and cthbt_. Populated for all transactions
+                      on a TLS connection, including reused connections.
 pqssl  Proxy Request  Indicates whether the connection from |TS| to the origin
                       was over SSL or not.
 pqssr  Proxy Request  SSL session ticket reused status from |TS| to the origin;

include/iocore/net/TLSBasicSupport.h

@@ -51,6 +51,8 @@ class TLSBasicSupport
   std::string_view get_tls_group() const;
   ink_hrtime       get_tls_handshake_begin_time() const;
   ink_hrtime       get_tls_handshake_end_time() const;
+  bool             get_tls_handshake_bytes(uint64_t &bytes_in, uint64_t &bytes_out);
+
   /**
    * Returns a certificate that need to be verified.
    *
@@ -103,4 +105,6 @@ class TLSBasicSupport
 
   ink_hrtime _tls_handshake_begin_time = 0;
   ink_hrtime _tls_handshake_end_time   = 0;
+  uint64_t   _tls_handshake_bytes_in   = 0;
+  uint64_t   _tls_handshake_bytes_out  = 0;
 };

include/proxy/http/HttpUserAgent.h

@@ -31,6 +31,7 @@
 #include "proxy/ProxyTransaction.h"
 #include "records/RecHttp.h"
 #include "iocore/net/TLSBasicSupport.h"
+#include "iocore/net/TLSEarlyDataSupport.h"
 #include "iocore/net/TLSSessionResumptionSupport.h"
 #include "tscore/ink_assert.h"
 
@@ -55,6 +56,11 @@ struct ClientConnectionInfo {
   std::string security_group{"-"};
 
   int alpn_id{SessionProtocolNameRegistry::INVALID};
+
+  // TLS handshake bytes (rx = received from client, tx = sent to client)
+  uint64_t tls_handshake_bytes_rx{0};
+  uint64_t tls_handshake_bytes_tx{0};
+  size_t   tls_early_data_len{0};
 };
 
 class HttpUserAgent
@@ -97,6 +103,12 @@ class HttpUserAgent
 
   int get_client_alpn_id() const;
 
+  uint64_t get_client_tls_handshake_bytes_rx() const;
+
+  uint64_t get_client_tls_handshake_bytes_tx() const;
+
+  size_t get_client_tls_early_data_len() const;
+
 private:
   HttpVCTableEntry *m_entry{nullptr};
   IOBufferReader   *m_raw_buffer_reader{nullptr};
@@ -186,6 +198,11 @@ HttpUserAgent::set_txn(ProxyTransaction *txn, TransactionMilestones &milestones)
       milestones[TS_MILESTONE_TLS_HANDSHAKE_START] = tbs->get_tls_handshake_begin_time();
       milestones[TS_MILESTONE_TLS_HANDSHAKE_END]   = tbs->get_tls_handshake_end_time();
     }
+    tbs->get_tls_handshake_bytes(m_conn_info.tls_handshake_bytes_rx, m_conn_info.tls_handshake_bytes_tx);
+  }
+
+  if (auto eds = netvc->get_service<TLSEarlyDataSupport>()) {
+    m_conn_info.tls_early_data_len = eds->get_early_data_len();
   }
 
   if (auto as = netvc->get_service<ALPNSupport>()) {
@@ -301,6 +318,24 @@ HttpUserAgent::get_client_alpn_id() const
   return m_conn_info.alpn_id;
 }
 
+inline uint64_t
+HttpUserAgent::get_client_tls_handshake_bytes_rx() const
+{
+  return m_conn_info.tls_handshake_bytes_rx;
+}
+
+inline uint64_t
+HttpUserAgent::get_client_tls_handshake_bytes_tx() const
+{
+  return m_conn_info.tls_handshake_bytes_tx;
+}
+
+inline size_t
+HttpUserAgent::get_client_tls_early_data_len() const
+{
+  return m_conn_info.tls_early_data_len;
+}
+
 inline void
 HttpUserAgent::save_transaction_info()
 {

include/proxy/logging/LogAccess.h

@@ -142,6 +142,7 @@ class LogAccess
   int marshal_client_req_protocol_version(char *);   // STR
   int marshal_server_req_protocol_version(char *);   // STR
   int marshal_client_req_squid_len(char *);          // INT
+  int marshal_client_req_squid_len_tls(char *);      // INT
   int marshal_client_req_header_len(char *);         // INT
   int marshal_client_req_content_len(char *);        // INT
   int marshal_client_req_tcp_reused(char *);         // INT
@@ -160,6 +161,9 @@ class LogAccess
   int marshal_client_req_uuid(char *);               // STR
   int marshal_client_rx_error_code(char *);          // STR
   int marshal_client_tx_error_code(char *);          // STR
+  int marshal_client_tls_handshake_bytes_rx(char *); // INT
+  int marshal_client_tls_handshake_bytes_tx(char *); // INT
+  int marshal_client_tls_handshake_bytes(char *);    // INT
   int marshal_client_req_all_header_fields(char *);  // STR
 
   //
@@ -168,6 +172,7 @@ class LogAccess
   int marshal_proxy_resp_content_type(char *);      // STR
   int marshal_proxy_resp_reason_phrase(char *);     // STR
   int marshal_proxy_resp_squid_len(char *);         // INT
+  int marshal_proxy_resp_squid_len_tls(char *);     // INT
   int marshal_proxy_resp_content_len(char *);       // INT
   int marshal_proxy_resp_status_code(char *);       // INT
   int marshal_status_plugin_entry(char *);          // STR

src/iocore/net/SSLNetVConnection.cc

@@ -978,10 +978,9 @@ SSLNetVConnection::clear()
   sslLastWriteTime            = 0;
   sslTotalBytesSent           = 0;
   sslClientRenegotiationAbort = false;
+  hookOpRequested             = SslVConnOp::SSL_HOOK_OP_DEFAULT;
 
-  hookOpRequested = SslVConnOp::SSL_HOOK_OP_DEFAULT;
   free_handshake_buffers();
-
   super::clear();
 }
 void

src/iocore/net/SSLStats.cc

@@ -280,6 +280,8 @@ SSLInitializeStatistics()
   ssl_rsb.user_agent_version_too_high       = Metrics::Counter::createPtr("proxy.process.ssl.user_agent_version_too_high");
   ssl_rsb.user_agent_version_too_low        = Metrics::Counter::createPtr("proxy.process.ssl.user_agent_version_too_low");
   ssl_rsb.user_agent_wrong_version          = Metrics::Counter::createPtr("proxy.process.ssl.user_agent_wrong_version");
+  ssl_rsb.tls_handshake_bytes_in_total      = Metrics::Counter::createPtr("proxy.process.ssl.total_handshake_bytes_read_in");
+  ssl_rsb.tls_handshake_bytes_out_total     = Metrics::Counter::createPtr("proxy.process.ssl.total_handshake_bytes_write_in");
 
 #if defined(OPENSSL_IS_BORINGSSL)
   size_t                    n = SSL_get_all_cipher_names(nullptr, 0);

src/iocore/net/SSLStats.h

@@ -99,6 +99,8 @@ struct SSLStatsBlock {
   Metrics::Counter::AtomicType *user_agent_version_too_high                    = nullptr;
   Metrics::Counter::AtomicType *user_agent_version_too_low                     = nullptr;
   Metrics::Counter::AtomicType *user_agent_wrong_version                       = nullptr;
+  Metrics::Counter::AtomicType *tls_handshake_bytes_in_total                   = nullptr;
+  Metrics::Counter::AtomicType *tls_handshake_bytes_out_total                  = nullptr;
 
   // Note: The following user_agent_session_* metrics are implemented as Gauge types
   // even though they semantically represent cumulative counters. This is because

src/iocore/net/SSLUtils.cc

@@ -1078,6 +1078,16 @@ ssl_callback_info(const SSL *ssl, int where, int ret)
       }
       Metrics::Counter::increment(it->second);
     }
+
+    if (netvc && netvc->get_context() == NET_VCONNECTION_IN) {
+      uint64_t bytes_in = 0, bytes_out = 0;
+      auto     tbs = TLSBasicSupport::getInstance(const_cast<SSL *>(ssl));
+
+      if (tbs && tbs->get_tls_handshake_bytes(bytes_in, bytes_out)) {
+        Metrics::Counter::increment(ssl_rsb.tls_handshake_bytes_in_total, bytes_in);
+        Metrics::Counter::increment(ssl_rsb.tls_handshake_bytes_out_total, bytes_out);
+      }
+    }
   }
 }
 

src/iocore/net/TLSBasicSupport.cc

@@ -72,6 +72,36 @@ TLSBasicSupport::clear()
 {
   this->_tls_handshake_begin_time = 0;
   this->_tls_handshake_end_time   = 0;
+  this->_tls_handshake_bytes_in   = 0;
+  this->_tls_handshake_bytes_out  = 0;
+}
+
+bool
+TLSBasicSupport::get_tls_handshake_bytes(uint64_t &bytes_in, uint64_t &bytes_out)
+{
+  if (_tls_handshake_bytes_in > 0 || _tls_handshake_bytes_out > 0) {
+    bytes_in  = _tls_handshake_bytes_in;
+    bytes_out = _tls_handshake_bytes_out;
+    return false;
+  }
+
+  SSL *ssl = this->_get_ssl_object();
+  if (ssl == nullptr) {
+    bytes_in  = 0;
+    bytes_out = 0;
+    return false;
+  }
+
+  BIO *rbio = SSL_get_rbio(ssl);
+  BIO *wbio = SSL_get_wbio(ssl);
+
+  uint64_t bio_in  = rbio ? BIO_number_read(rbio) : 0;
+  uint64_t bio_out = wbio ? BIO_number_written(wbio) : 0;
+
+  bytes_in = _tls_handshake_bytes_in = bio_in;
+  bytes_out = _tls_handshake_bytes_out = bio_out;
+
+  return true;
 }
 
 TLSHandle

src/proxy/logging/Log.cc

@@ -485,6 +485,12 @@ Log::init_fields()
   global_field_list.add(field, false);
   field_symbol_hash.emplace("cqql", field);
 
+  // Client request squid length plus TLS handshake bytes received for TLS connections
+  field = new LogField("client_req_squid_len_tls", "cqqtl", LogField::sINT, &LogAccess::marshal_client_req_squid_len_tls,
+                       &LogAccess::unmarshal_int_to_str);
+  global_field_list.add(field, false);
+  field_symbol_hash.emplace("cqqtl", field);
+
   field = new LogField("cache_lookup_url_canonical", "cluc", LogField::STRING, &LogAccess::marshal_cache_lookup_url_canon,
                        &LogAccess::unmarshal_str);
   global_field_list.add(field, false);
@@ -574,6 +580,24 @@ Log::init_fields()
   global_field_list.add(field, false);
   field_symbol_hash.emplace("cqssa", field);
 
+  // TLS handshake bytes - bytes received from client during TLS handshake
+  field = new LogField("client_tls_handshake_bytes_rx", "cthbr", LogField::sINT, &LogAccess::marshal_client_tls_handshake_bytes_rx,
+                       &LogAccess::unmarshal_int_to_str);
+  global_field_list.add(field, false);
+  field_symbol_hash.emplace("cthbr", field);
+
+  // TLS handshake bytes - bytes sent to client during TLS handshake
+  field = new LogField("client_tls_handshake_bytes_tx", "cthbt", LogField::sINT, &LogAccess::marshal_client_tls_handshake_bytes_tx,
+                       &LogAccess::unmarshal_int_to_str);
+  global_field_list.add(field, false);
+  field_symbol_hash.emplace("cthbt", field);
+
+  // TLS handshake bytes - total (rx + tx) during TLS handshake
+  field = new LogField("client_tls_handshake_bytes", "cthb", LogField::sINT, &LogAccess::marshal_client_tls_handshake_bytes,
+                       &LogAccess::unmarshal_int_to_str);
+  global_field_list.add(field, false);
+  field_symbol_hash.emplace("cthb", field);
+
   Ptr<LogFieldAliasTable> finish_status_map = make_ptr(new LogFieldAliasTable);
   finish_status_map->init(N_LOG_FINISH_CODE_TYPES, LOG_FINISH_FIN, "FIN", LOG_FINISH_INTR, "INTR", LOG_FINISH_TIMEOUT, "TIMEOUT");
 
@@ -623,6 +647,12 @@ Log::init_fields()
   global_field_list.add(field, false);
   field_symbol_hash.emplace("psql", field);
 
+  // Squid length plus TLS handshake bytes sent for TLS connections
+  field = new LogField("proxy_resp_squid_len_tls", "psqtl", LogField::sINT, &LogAccess::marshal_proxy_resp_squid_len_tls,
+                       &LogAccess::unmarshal_int_to_str);
+  global_field_list.add(field, false);
+  field_symbol_hash.emplace("psqtl", field);
+
   field = new LogField("proxy_resp_content_len", "pscl", LogField::sINT, &LogAccess::marshal_proxy_resp_content_len,
                        &LogAccess::unmarshal_int_to_str);
   global_field_list.add(field, false);