Capture TLS handshake bytes in metrics

Add txn log fields for the same HS metrics

Requestor: Craig T.

Author: zwoop

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,12 @@ 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. Since the TLS handshake
+                             only occurs once per connection, the handshake bytes
+                             are only attributed to the first transaction to
+                             prevent double-counting.
 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 +474,12 @@ 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. Since the TLS handshake only
+                             occurs once per connection, the handshake bytes are
+                             only attributed to the first transaction to prevent
+                             double-counting.
 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 +637,9 @@ SSL / Encryption
 .. _cqssc:
 .. _cqssu:
 .. _cqssa:
+.. _cthbr:
+.. _cthbt:
+.. _cthb:
 .. _pqssl:
 .. _pscert:
 
@@ -659,6 +676,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/NetVConnection.h

@@ -322,6 +322,15 @@ class NetVConnection : public VConnection, public PluginUserArgs<TS_USER_ARGS_VC
     return 0;
   }
 
+  /** Capture handshake byte statistics.  */
+  virtual bool
+  capture_handshake_bytes(uint64_t &bytes_in, uint64_t &bytes_out)
+  {
+    bytes_in  = 0;
+    bytes_out = 0;
+    return false;
+  }
+
   /** Structure holding user options. */
   NetVCOptions options;
 

include/proxy/http/HttpUserAgent.h

@@ -55,6 +55,10 @@ 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};
 };
 
 class HttpUserAgent
@@ -97,6 +101,10 @@ 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;
+
 private:
   HttpVCTableEntry *m_entry{nullptr};
   IOBufferReader   *m_raw_buffer_reader{nullptr};
@@ -186,6 +194,7 @@ 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();
     }
+    netvc->capture_handshake_bytes(m_conn_info.tls_handshake_bytes_rx, m_conn_info.tls_handshake_bytes_tx);
   }
 
   if (auto as = netvc->get_service<ALPNSupport>()) {
@@ -301,6 +310,18 @@ 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 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/P_SSLNetVConnection.h

@@ -309,6 +309,8 @@ class SSLNetVConnection : public UnixNetVConnection,
   EThread        *getThreadForTLSEvents() override;
   Ptr<ProxyMutex> getMutexForTLSEvents() override;
 
+  bool capture_handshake_bytes(uint64_t &bytes_in, uint64_t &bytes_out) override;
+
 protected:
   // UnixNetVConnection
   bool _isReadyToTransferData() const override;
@@ -376,6 +378,10 @@ class SSLNetVConnection : public UnixNetVConnection,
    */
   char *_getCoalescedHandShakeBuffer(int64_t total_chain_size);
 
+  // TLS handshake byte tracking (bytes read/written during handshake only)
+  uint64_t _tls_handshake_bytes_in  = 0;
+  uint64_t _tls_handshake_bytes_out = 0;
+
   enum SSLHandshakeStatus sslHandshakeStatus          = SSLHandshakeStatus::SSL_HANDSHAKE_ONGOING;
   bool                    sslClientRenegotiationAbort = false;
   bool                    first_ssl_connect           = true;

src/iocore/net/SSLNetVConnection.cc

@@ -978,10 +978,11 @@ SSLNetVConnection::clear()
   sslLastWriteTime            = 0;
   sslTotalBytesSent           = 0;
   sslClientRenegotiationAbort = false;
+  _tls_handshake_bytes_in     = 0;
+  _tls_handshake_bytes_out    = 0;
+  hookOpRequested             = SslVConnOp::SSL_HOOK_OP_DEFAULT;
 
-  hookOpRequested = SslVConnOp::SSL_HOOK_OP_DEFAULT;
   free_handshake_buffers();
-
   super::clear();
 }
 void
@@ -2484,3 +2485,31 @@ SSLNetVConnection::_ssl_read_buffer(void *buf, int64_t nbytes, int64_t &nread)
 
   return ssl_error;
 }
+
+bool
+SSLNetVConnection::capture_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;
+  }
+
+  // If no SSL object, nothing to capture
+  if (this->ssl == nullptr) {
+    bytes_in  = 0;
+    bytes_out = 0;
+
+    return false;
+  }
+
+  // Capture bytes from BIO statistics
+  BIO *rbio = SSL_get_rbio(this->ssl);
+  BIO *wbio = SSL_get_wbio(this->ssl);
+
+  bytes_in = _tls_handshake_bytes_in = rbio ? BIO_number_read(rbio) : 0;
+  bytes_out = _tls_handshake_bytes_out = wbio ? BIO_number_written(wbio) : 0;
+
+  return true;
+}

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);
     }
+
+    // Capture TLS handshake byte statistics
+    if (netvc && netvc->get_context() == NET_VCONNECTION_IN) {
+      uint64_t bytes_in = 0, bytes_out = 0;
+
+      if (netvc->capture_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/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);