diff --git a/doc/admin-guide/logging/formatting.en.rst b/doc/admin-guide/logging/formatting.en.rst index ba74dcb8f33..d8ee434918a 100644 --- a/doc/admin-guide/logging/formatting.en.rst +++ b/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 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 @@ -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. @@ -629,6 +639,9 @@ SSL / Encryption .. _cqssc: .. _cqssu: .. _cqssa: +.. _cthbr: +.. _cthbt: +.. _cthb: .. _pqssl: .. _pscert: @@ -665,6 +678,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 015633607b1..7d9354fa558 100644 --- a/include/iocore/net/TLSBasicSupport.h +++ b/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) const; + /** * Returns a certificate that need to be verified. * @@ -101,6 +103,9 @@ class TLSBasicSupport 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 4761e4a30e4..95b1120545d 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 @@ 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()) { + m_conn_info.tls_early_data_len = eds->get_early_data_len(); } if (auto as = netvc->get_service()) { @@ -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 1a799ca3b0c..4f9aafa00c1 100644 --- a/include/proxy/logging/LogAccess.h +++ b/include/proxy/logging/LogAccess.h @@ -144,6 +144,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 @@ -162,6 +163,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 // @@ -170,6 +174,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 diff --git a/src/iocore/net/SSLNetVConnection.cc b/src/iocore/net/SSLNetVConnection.cc index c4aeb44a89d..7193c4a329e 100644 --- a/src/iocore/net/SSLNetVConnection.cc +++ b/src/iocore/net/SSLNetVConnection.cc @@ -976,10 +976,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 fdec94b1e46..bca43ee49ab 100644 --- a/src/iocore/net/SSLStats.cc +++ b/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_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 82b84445302..cd0ec4bd811 100644 --- a/src/iocore/net/SSLStats.h +++ b/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 diff --git a/src/iocore/net/SSLUtils.cc b/src/iocore/net/SSLUtils.cc index 6d262c1ca6b..d180a11f98b 100644 --- a/src/iocore/net/SSLUtils.cc +++ b/src/iocore/net/SSLUtils.cc @@ -1080,6 +1080,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)); + + 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 7510aeb4281..5d7187da4a9 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 29b0949698e..cc24d1b4cc1 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); @@ -589,6 +595,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 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"); @@ -638,6 +662,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 7d2bcb54da8..06849e8e760 100644 --- a/src/proxy/logging/LogAccess.cc +++ b/src/proxy/logging/LogAccess.cc @@ -2206,6 +2206,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(early_data_len)); + } + + val += handshake_rx; + } + marshal_int(buf, val); + } + return INK_MIN_ALIGN; +} + /*------------------------------------------------------------------------- -------------------------------------------------------------------------*/ @@ -2430,6 +2461,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(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(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(total)); + } + return INK_MIN_ALIGN; +} + /*------------------------------------------------------------------------- -------------------------------------------------------------------------*/ @@ -2470,6 +2539,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; +} + /*------------------------------------------------------------------------- -------------------------------------------------------------------------*/