This is an automated email from the ASF dual-hosted git repository. cmcfarlen pushed a commit to branch 10.2.x in repository https://gitbox.apache.org/repos/asf/trafficserver.git
commit 7f69d8a319281f9f5398997f13476431534891bb Author: Leif Hedstrom <[email protected]> AuthorDate: Thu Jun 4 17:21:00 2026 -0600 Adds metrics and log fields for tracking TLS handshake bytes (#12763) * Capture TLS handshake bytes in metrics Add txn log fields for the same HS metrics Requestor: Craig T. * Move things out of the NetVC, subtract early data * Fixed review comments * Address Copilot review comments - Use _tls_handshake_bytes_measured flag instead of > 0 sentinel, so the cache works correctly when both byte counts are zero - Use std::min() when subtracting early data from handshake_rx to handle the == case and prevent underflow - Add static_cast<int64_t> to marshal_int calls for rx/tx bytes (cherry picked from commit fb1f03d3aa9a2bfe1c61c07830d0df7ac66ac376) --- doc/admin-guide/logging/formatting.en.rst | 24 +++++++++ include/iocore/net/TLSBasicSupport.h | 9 +++- include/proxy/http/HttpUserAgent.h | 35 +++++++++++++ include/proxy/logging/LogAccess.h | 5 ++ src/iocore/net/SSLNetVConnection.cc | 3 +- src/iocore/net/SSLStats.cc | 2 + src/iocore/net/SSLStats.h | 2 + src/iocore/net/SSLUtils.cc | 10 ++++ src/iocore/net/TLSBasicSupport.cc | 38 +++++++++++++- src/proxy/logging/Log.cc | 30 +++++++++++ src/proxy/logging/LogAccess.cc | 86 +++++++++++++++++++++++++++++++ 11 files changed, 238 insertions(+), 6 deletions(-) diff --git a/doc/admin-guide/logging/formatting.en.rst b/doc/admin-guide/logging/formatting.en.rst index b121ad440b..420df43090 100644 --- a/doc/admin-guide/logging/formatting.en.rst +++ b/doc/admin-guide/logging/formatting.en.rst @@ -477,6 +477,7 @@ Lengths and Sizes .. _cqcl: .. _cqhl: .. _cqql: +.. _cqqtl: .. _csscl: .. _csshl: .. _cssql: @@ -487,6 +488,7 @@ Lengths and Sizes .. _pscl: .. _pshl: .. _psql: +.. _psqtl: .. _sscl: .. _sshl: .. _ssql: @@ -502,6 +504,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 metric + 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 @@ -517,6 +523,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. @@ -682,6 +692,9 @@ SSL / Encryption .. _cqssc: .. _cqssu: .. _cqssa: +.. _cthbr: +.. _cthbt: +.. _cthb: .. _pqssl: .. _pscert: @@ -718,6 +731,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; diff --git a/include/iocore/net/TLSBasicSupport.h b/include/iocore/net/TLSBasicSupport.h index 015633607b..7d9354fa55 100644 --- a/include/iocore/net/TLSBasicSupport.h +++ b/include/iocore/net/TLSBasicSupport.h @@ -51,6 +51,8 @@ public: 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) const; + /** * Returns a certificate that need to be verified. * @@ -101,6 +103,9 @@ private: X509_STORE_CTX *_cert_to_verify = nullptr; - ink_hrtime _tls_handshake_begin_time = 0; - ink_hrtime _tls_handshake_end_time = 0; + ink_hrtime _tls_handshake_begin_time = 0; + ink_hrtime _tls_handshake_end_time = 0; + mutable bool _tls_handshake_bytes_measured = false; + mutable uint64_t _tls_handshake_bytes_in = 0; + mutable uint64_t _tls_handshake_bytes_out = 0; }; diff --git a/include/proxy/http/HttpUserAgent.h b/include/proxy/http/HttpUserAgent.h index 4761e4a30e..95b1120545 100644 --- a/include/proxy/http/HttpUserAgent.h +++ b/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 @@ public: 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() { diff --git a/include/proxy/logging/LogAccess.h b/include/proxy/logging/LogAccess.h index e59b49a8f2..16237b0289 100644 --- a/include/proxy/logging/LogAccess.h +++ b/include/proxy/logging/LogAccess.h @@ -156,6 +156,7 @@ public: 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 @@ -174,6 +175,9 @@ public: 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 // @@ -182,6 +186,7 @@ public: 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 diff --git a/src/iocore/net/SSLNetVConnection.cc b/src/iocore/net/SSLNetVConnection.cc index b06fc630ea..35404629a6 100644 --- a/src/iocore/net/SSLNetVConnection.cc +++ b/src/iocore/net/SSLNetVConnection.cc @@ -1005,10 +1005,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 diff --git a/src/iocore/net/SSLStats.cc b/src/iocore/net/SSLStats.cc index 463e67599e..0b9b94343d 100644 --- a/src/iocore/net/SSLStats.cc +++ b/src/iocore/net/SSLStats.cc @@ -292,6 +292,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_out"); #if defined(OPENSSL_IS_BORINGSSL) size_t n = SSL_get_all_cipher_names(nullptr, 0); diff --git a/src/iocore/net/SSLStats.h b/src/iocore/net/SSLStats.h index 0ecb5db3e1..495092b7fb 100644 --- a/src/iocore/net/SSLStats.h +++ b/src/iocore/net/SSLStats.h @@ -111,6 +111,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 diff --git a/src/iocore/net/SSLUtils.cc b/src/iocore/net/SSLUtils.cc index c7b13f63e1..7c37a2367d 100644 --- a/src/iocore/net/SSLUtils.cc +++ b/src/iocore/net/SSLUtils.cc @@ -1172,6 +1172,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); + } + } } } diff --git a/src/iocore/net/TLSBasicSupport.cc b/src/iocore/net/TLSBasicSupport.cc index 7510aeb428..5d7187da4a 100644 --- a/src/iocore/net/TLSBasicSupport.cc +++ b/src/iocore/net/TLSBasicSupport.cc @@ -70,8 +70,42 @@ TLSBasicSupport::unbind(SSL *ssl) void TLSBasicSupport::clear() { - this->_tls_handshake_begin_time = 0; - this->_tls_handshake_end_time = 0; + this->_tls_handshake_begin_time = 0; + this->_tls_handshake_end_time = 0; + this->_tls_handshake_bytes_measured = false; + this->_tls_handshake_bytes_in = 0; + this->_tls_handshake_bytes_out = 0; +} + +// Returns true only on the first call that reads from the BIOs, so callers +// can distinguish fresh values (for metrics) from cached ones. +bool +TLSBasicSupport::get_tls_handshake_bytes(uint64_t &bytes_in, uint64_t &bytes_out) const +{ + if (_tls_handshake_bytes_measured) { + 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; + _tls_handshake_bytes_measured = true; + + return true; } TLSHandle diff --git a/src/proxy/logging/Log.cc b/src/proxy/logging/Log.cc index d845e58505..f5f685d68a 100644 --- a/src/proxy/logging/Log.cc +++ b/src/proxy/logging/Log.cc @@ -500,6 +500,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); @@ -593,6 +599,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"); @@ -642,6 +666,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); diff --git a/src/proxy/logging/LogAccess.cc b/src/proxy/logging/LogAccess.cc index 662a8b5daa..2f2c1d2b24 100644 --- a/src/proxy/logging/LogAccess.cc +++ b/src/proxy/logging/LogAccess.cc @@ -2190,6 +2190,37 @@ LogAccess::marshal_client_req_squid_len(char *buf) return INK_MIN_ALIGN; } +/*------------------------------------------------------------------------- + Client request squid length plus TLS handshake bytes received for TLS connections. + For TLS 1.3 early data (0-RTT), we subtract the early data length from the + handshake bytes to avoid double-counting since the early data bytes are + already included in client_request_body_bytes. + -------------------------------------------------------------------------*/ +int +LogAccess::marshal_client_req_squid_len_tls(char *buf) +{ + if (buf) { + int64_t val = 0; + + if (m_client_request) { + val = m_client_request->length_get() + m_http_sm->client_request_body_bytes; + } + + if (!m_http_sm->get_user_agent().get_client_tcp_reused()) { + uint64_t handshake_rx = m_http_sm->get_user_agent().get_client_tls_handshake_bytes_rx(); + size_t early_data_len = m_http_sm->get_user_agent().get_client_tls_early_data_len(); + + if (early_data_len > 0) { + handshake_rx -= std::min(handshake_rx, static_cast<uint64_t>(early_data_len)); + } + + val += handshake_rx; + } + marshal_int(buf, val); + } + return INK_MIN_ALIGN; +} + /*------------------------------------------------------------------------- -------------------------------------------------------------------------*/ @@ -2408,6 +2439,44 @@ LogAccess::marshal_client_security_alpn(char *buf) return round_len; } +/*------------------------------------------------------------------------- + TLS Handshake Bytes - Bytes received from client during TLS handshake + -------------------------------------------------------------------------*/ +int +LogAccess::marshal_client_tls_handshake_bytes_rx(char *buf) +{ + if (buf) { + marshal_int(buf, static_cast<int64_t>(m_http_sm->get_user_agent().get_client_tls_handshake_bytes_rx())); + } + return INK_MIN_ALIGN; +} + +/*------------------------------------------------------------------------- + TLS Handshake Bytes - Bytes sent to client during TLS handshake + -------------------------------------------------------------------------*/ +int +LogAccess::marshal_client_tls_handshake_bytes_tx(char *buf) +{ + if (buf) { + marshal_int(buf, static_cast<int64_t>(m_http_sm->get_user_agent().get_client_tls_handshake_bytes_tx())); + } + return INK_MIN_ALIGN; +} + +/*------------------------------------------------------------------------- + TLS Handshake Bytes - Total bytes (rx + tx) during TLS handshake + -------------------------------------------------------------------------*/ +int +LogAccess::marshal_client_tls_handshake_bytes(char *buf) +{ + if (buf) { + uint64_t total = m_http_sm->get_user_agent().get_client_tls_handshake_bytes_rx() + + m_http_sm->get_user_agent().get_client_tls_handshake_bytes_tx(); + marshal_int(buf, static_cast<int64_t>(total)); + } + return INK_MIN_ALIGN; +} + /*------------------------------------------------------------------------- -------------------------------------------------------------------------*/ @@ -2448,6 +2517,23 @@ LogAccess::marshal_proxy_resp_squid_len(char *buf) return INK_MIN_ALIGN; } +/*------------------------------------------------------------------------- + Squid length plus TLS handshake bytes sent for TLS connections. + -------------------------------------------------------------------------*/ +int +LogAccess::marshal_proxy_resp_squid_len_tls(char *buf) +{ + if (buf) { + int64_t val = m_http_sm->client_response_hdr_bytes + m_http_sm->client_response_body_bytes; + + if (!m_http_sm->get_user_agent().get_client_tcp_reused()) { + val += m_http_sm->get_user_agent().get_client_tls_handshake_bytes_tx(); + } + marshal_int(buf, val); + } + return INK_MIN_ALIGN; +} + /*------------------------------------------------------------------------- -------------------------------------------------------------------------*/
