From 07e0f9c04fd27a226957fee66893b967db41234a Mon Sep 17 00:00:00 2001 From: Bryan Call Date: Thu, 5 Feb 2026 11:38:39 -0800 Subject: [PATCH 1/6] Add server-side TLS handshake milestones and fix outbound TLS timing Add TS_MILESTONE_SERVER_TLS_HANDSHAKE_START/END to capture origin-side TLS handshake timing, complementing the existing client-side TS_MILESTONE_TLS_HANDSHAKE_START/END milestones. Changes: - Add new milestone enum values in apidefs.h.in (ABI compatible - appended before TS_MILESTONE_LAST_ENTRY) - Capture server TLS timing in HttpSM::state_http_server_open() for both the direct (VC_EVENT_WRITE_COMPLETE) and multiplexed (CONNECT_EVENT_TXN) connection paths - Fix missing _record_tls_handshake_end_time() call in SSLNetVConnection::sslClientHandShakeEvent() - outbound TLS handshakes were recording start time but never end time - Rename slow log field "tls_handshake" to "ua_tls_handshake" for clarity and add "server_tls_handshake" field - Update LogField.cc milestone mappings for custom log fields - Add Lua plugin milestone constants - Update API documentation and slow_log_report.pl --- doc/admin-guide/plugins/lua.en.rst | 2 + .../functions/TSHttpTxnMilestoneGet.en.rst | 12 ++++- include/ts/apidefs.h.in | 2 + plugins/lua/ts_lua_http_milestone.cc | 54 ++++++++++--------- src/iocore/net/SSLNetVConnection.cc | 6 +++ src/proxy/http/HttpSM.cc | 23 ++++++-- src/proxy/logging/LogField.cc | 54 ++++++++++--------- tools/slow_log_report.pl | 11 ++-- 8 files changed, 105 insertions(+), 59 deletions(-) diff --git a/doc/admin-guide/plugins/lua.en.rst b/doc/admin-guide/plugins/lua.en.rst index 08970e340ec..e029f92f3a5 100644 --- a/doc/admin-guide/plugins/lua.en.rst +++ b/doc/admin-guide/plugins/lua.en.rst @@ -4971,6 +4971,8 @@ Milestone constants TS_LUA_MILESTONE_PLUGIN_TOTAL TS_LUA_MILESTONE_TLS_HANDSHAKE_START TS_LUA_MILESTONE_TLS_HANDSHAKE_END + TS_LUA_MILESTONE_SERVER_TLS_HANDSHAKE_START + TS_LUA_MILESTONE_SERVER_TLS_HANDSHAKE_END :ref:`TOP ` diff --git a/doc/developer-guide/api/functions/TSHttpTxnMilestoneGet.en.rst b/doc/developer-guide/api/functions/TSHttpTxnMilestoneGet.en.rst index b1290db319e..dbabefca5a3 100644 --- a/doc/developer-guide/api/functions/TSHttpTxnMilestoneGet.en.rst +++ b/doc/developer-guide/api/functions/TSHttpTxnMilestoneGet.en.rst @@ -132,11 +132,19 @@ is successful. .. enumerator:: TS_MILESTONE_TLS_HANDSHAKE_START - Timestamp when the server starts the TLS handshake. 0 if no handshake is performed (connection reuse). + Timestamp when the client starts the TLS handshake with the proxy. 0 if no handshake is performed (connection reuse). .. enumerator:: TS_MILESTONE_TLS_HANDSHAKE_END - Timestamp when the server completes the TLS handshake. 0 if no handshake is performed (connection reuse). + Timestamp when the client completes the TLS handshake with the proxy. 0 if no handshake is performed (connection reuse). + + .. enumerator:: TS_MILESTONE_SERVER_TLS_HANDSHAKE_START + + Timestamp when the proxy starts the TLS handshake with the origin server. 0 if no handshake is performed (connection reuse or non-TLS origin). + + .. enumerator:: TS_MILESTONE_SERVER_TLS_HANDSHAKE_END + + Timestamp when the proxy completes the TLS handshake with the origin server. 0 if no handshake is performed (connection reuse or non-TLS origin). .. enumerator:: TS_MILESTONE_LAST_ENTRY diff --git a/include/ts/apidefs.h.in b/include/ts/apidefs.h.in index 078ce0eb69c..2b23735b354 100644 --- a/include/ts/apidefs.h.in +++ b/include/ts/apidefs.h.in @@ -978,6 +978,8 @@ enum TSMilestonesType { TS_MILESTONE_PLUGIN_TOTAL, TS_MILESTONE_TLS_HANDSHAKE_START, TS_MILESTONE_TLS_HANDSHAKE_END, + TS_MILESTONE_SERVER_TLS_HANDSHAKE_START, + TS_MILESTONE_SERVER_TLS_HANDSHAKE_END, TS_MILESTONE_LAST_ENTRY, }; diff --git a/plugins/lua/ts_lua_http_milestone.cc b/plugins/lua/ts_lua_http_milestone.cc index 81b9ae262f9..8bd88cf068c 100644 --- a/plugins/lua/ts_lua_http_milestone.cc +++ b/plugins/lua/ts_lua_http_milestone.cc @@ -19,30 +19,32 @@ #include "ts_lua_util.h" typedef enum { - TS_LUA_MILESTONE_UA_BEGIN = TS_MILESTONE_UA_BEGIN, - TS_LUA_MILESTONE_UA_FIRST_READ = TS_MILESTONE_UA_FIRST_READ, - TS_LUA_MILESTONE_UA_READ_HEADER_DONE = TS_MILESTONE_UA_READ_HEADER_DONE, - TS_LUA_MILESTONE_UA_BEGIN_WRITE = TS_MILESTONE_UA_BEGIN_WRITE, - TS_LUA_MILESTONE_UA_CLOSE = TS_MILESTONE_UA_CLOSE, - TS_LUA_MILESTONE_SERVER_FIRST_CONNECT = TS_MILESTONE_SERVER_FIRST_CONNECT, - TS_LUA_MILESTONE_SERVER_CONNECT = TS_MILESTONE_SERVER_CONNECT, - TS_LUA_MILESTONE_SERVER_CONNECT_END = TS_MILESTONE_SERVER_CONNECT_END, - TS_LUA_MILESTONE_SERVER_BEGIN_WRITE = TS_MILESTONE_SERVER_BEGIN_WRITE, - TS_LUA_MILESTONE_SERVER_FIRST_READ = TS_MILESTONE_SERVER_FIRST_READ, - TS_LUA_MILESTONE_SERVER_READ_HEADER_DONE = TS_MILESTONE_SERVER_READ_HEADER_DONE, - TS_LUA_MILESTONE_SERVER_CLOSE = TS_MILESTONE_SERVER_CLOSE, - TS_LUA_MILESTONE_CACHE_OPEN_READ_BEGIN = TS_MILESTONE_CACHE_OPEN_READ_BEGIN, - TS_LUA_MILESTONE_CACHE_OPEN_READ_END = TS_MILESTONE_CACHE_OPEN_READ_END, - TS_LUA_MILESTONE_CACHE_OPEN_WRITE_BEGIN = TS_MILESTONE_CACHE_OPEN_WRITE_BEGIN, - TS_LUA_MILESTONE_CACHE_OPEN_WRITE_END = TS_MILESTONE_CACHE_OPEN_WRITE_END, - TS_LUA_MILESTONE_DNS_LOOKUP_BEGIN = TS_MILESTONE_DNS_LOOKUP_BEGIN, - TS_LUA_MILESTONE_DNS_LOOKUP_END = TS_MILESTONE_DNS_LOOKUP_END, - TS_LUA_MILESTONE_SM_START = TS_MILESTONE_SM_START, - TS_LUA_MILESTONE_SM_FINISH = TS_MILESTONE_SM_FINISH, - TS_LUA_MILESTONE_PLUGIN_ACTIVE = TS_MILESTONE_PLUGIN_ACTIVE, - TS_LUA_MILESTONE_PLUGIN_TOTAL = TS_MILESTONE_PLUGIN_TOTAL, - TS_LUA_MILESTONE_TLS_HANDSHAKE_START = TS_MILESTONE_TLS_HANDSHAKE_START, - TS_LUA_MILESTONE_TLS_HANDSHAKE_END = TS_MILESTONE_TLS_HANDSHAKE_END + TS_LUA_MILESTONE_UA_BEGIN = TS_MILESTONE_UA_BEGIN, + TS_LUA_MILESTONE_UA_FIRST_READ = TS_MILESTONE_UA_FIRST_READ, + TS_LUA_MILESTONE_UA_READ_HEADER_DONE = TS_MILESTONE_UA_READ_HEADER_DONE, + TS_LUA_MILESTONE_UA_BEGIN_WRITE = TS_MILESTONE_UA_BEGIN_WRITE, + TS_LUA_MILESTONE_UA_CLOSE = TS_MILESTONE_UA_CLOSE, + TS_LUA_MILESTONE_SERVER_FIRST_CONNECT = TS_MILESTONE_SERVER_FIRST_CONNECT, + TS_LUA_MILESTONE_SERVER_CONNECT = TS_MILESTONE_SERVER_CONNECT, + TS_LUA_MILESTONE_SERVER_CONNECT_END = TS_MILESTONE_SERVER_CONNECT_END, + TS_LUA_MILESTONE_SERVER_BEGIN_WRITE = TS_MILESTONE_SERVER_BEGIN_WRITE, + TS_LUA_MILESTONE_SERVER_FIRST_READ = TS_MILESTONE_SERVER_FIRST_READ, + TS_LUA_MILESTONE_SERVER_READ_HEADER_DONE = TS_MILESTONE_SERVER_READ_HEADER_DONE, + TS_LUA_MILESTONE_SERVER_CLOSE = TS_MILESTONE_SERVER_CLOSE, + TS_LUA_MILESTONE_CACHE_OPEN_READ_BEGIN = TS_MILESTONE_CACHE_OPEN_READ_BEGIN, + TS_LUA_MILESTONE_CACHE_OPEN_READ_END = TS_MILESTONE_CACHE_OPEN_READ_END, + TS_LUA_MILESTONE_CACHE_OPEN_WRITE_BEGIN = TS_MILESTONE_CACHE_OPEN_WRITE_BEGIN, + TS_LUA_MILESTONE_CACHE_OPEN_WRITE_END = TS_MILESTONE_CACHE_OPEN_WRITE_END, + TS_LUA_MILESTONE_DNS_LOOKUP_BEGIN = TS_MILESTONE_DNS_LOOKUP_BEGIN, + TS_LUA_MILESTONE_DNS_LOOKUP_END = TS_MILESTONE_DNS_LOOKUP_END, + TS_LUA_MILESTONE_SM_START = TS_MILESTONE_SM_START, + TS_LUA_MILESTONE_SM_FINISH = TS_MILESTONE_SM_FINISH, + TS_LUA_MILESTONE_PLUGIN_ACTIVE = TS_MILESTONE_PLUGIN_ACTIVE, + TS_LUA_MILESTONE_PLUGIN_TOTAL = TS_MILESTONE_PLUGIN_TOTAL, + TS_LUA_MILESTONE_TLS_HANDSHAKE_START = TS_MILESTONE_TLS_HANDSHAKE_START, + TS_LUA_MILESTONE_TLS_HANDSHAKE_END = TS_MILESTONE_TLS_HANDSHAKE_END, + TS_LUA_MILESTONE_SERVER_TLS_HANDSHAKE_START = TS_MILESTONE_SERVER_TLS_HANDSHAKE_START, + TS_LUA_MILESTONE_SERVER_TLS_HANDSHAKE_END = TS_MILESTONE_SERVER_TLS_HANDSHAKE_END } TSLuaMilestoneType; ts_lua_var_item ts_lua_milestone_type_vars[] = {TS_LUA_MAKE_VAR_ITEM(TS_LUA_MILESTONE_UA_BEGIN), @@ -68,7 +70,9 @@ ts_lua_var_item ts_lua_milestone_type_vars[] = {TS_LUA_MAKE_VAR_ITEM(TS_LUA_MILE TS_LUA_MAKE_VAR_ITEM(TS_LUA_MILESTONE_PLUGIN_ACTIVE), TS_LUA_MAKE_VAR_ITEM(TS_LUA_MILESTONE_PLUGIN_TOTAL), TS_LUA_MAKE_VAR_ITEM(TS_LUA_MILESTONE_TLS_HANDSHAKE_START), - TS_LUA_MAKE_VAR_ITEM(TS_LUA_MILESTONE_TLS_HANDSHAKE_END)}; + TS_LUA_MAKE_VAR_ITEM(TS_LUA_MILESTONE_TLS_HANDSHAKE_END), + TS_LUA_MAKE_VAR_ITEM(TS_LUA_MILESTONE_SERVER_TLS_HANDSHAKE_START), + TS_LUA_MAKE_VAR_ITEM(TS_LUA_MILESTONE_SERVER_TLS_HANDSHAKE_END)}; static void ts_lua_inject_http_milestone_variables(lua_State *L); diff --git a/src/iocore/net/SSLNetVConnection.cc b/src/iocore/net/SSLNetVConnection.cc index c4aeb44a89d..41afb53e6cf 100644 --- a/src/iocore/net/SSLNetVConnection.cc +++ b/src/iocore/net/SSLNetVConnection.cc @@ -1579,6 +1579,12 @@ SSLNetVConnection::sslClientHandShakeEvent(int &err) Metrics::Counter::increment(ssl_rsb.total_success_handshake_count_out); sslHandshakeStatus = SSLHandshakeStatus::SSL_HANDSHAKE_DONE; + + // Record TLS handshake end time for outbound connections + if (this->get_tls_handshake_begin_time()) { + this->_record_tls_handshake_end_time(); + } + return EVENT_DONE; case SSL_ERROR_WANT_WRITE: diff --git a/src/proxy/http/HttpSM.cc b/src/proxy/http/HttpSM.cc index d9cfb662923..f53c70e0892 100644 --- a/src/proxy/http/HttpSM.cc +++ b/src/proxy/http/HttpSM.cc @@ -1881,9 +1881,18 @@ HttpSM::state_http_server_open(int event, void *data) case CONNECT_EVENT_RETRY: do_http_server_open(); break; - case CONNECT_EVENT_TXN: + case CONNECT_EVENT_TXN: { SMDbg(dbg_ctl_http, "Connection handshake complete via CONNECT_EVENT_TXN"); - if (this->create_server_txn(static_cast(data))) { + PoolableSession *session = static_cast(data); + ink_assert(session != nullptr); + // Capture server TLS handshake timing from the session's netvc + if (auto *netvc = session->get_netvc()) { + if (auto tbs = netvc->get_service()) { + milestones[TS_MILESTONE_SERVER_TLS_HANDSHAKE_START] = tbs->get_tls_handshake_begin_time(); + milestones[TS_MILESTONE_SERVER_TLS_HANDSHAKE_END] = tbs->get_tls_handshake_end_time(); + } + } + if (this->create_server_txn(session)) { t_state.current.server->clear_connect_fail(); handle_http_server_open(); } else { // Failed to create transaction. Maybe too many active transactions already @@ -1891,11 +1900,17 @@ HttpSM::state_http_server_open(int event, void *data) do_http_server_open(false); } return 0; + } case VC_EVENT_READ_COMPLETE: case VC_EVENT_WRITE_READY: case VC_EVENT_WRITE_COMPLETE: // Update the time out to the regular connection timeout. SMDbg(dbg_ctl_http_ss, "Connection handshake complete"); + // Capture server TLS handshake timing if this is a TLS connection + if (auto tbs = _netvc->get_service()) { + milestones[TS_MILESTONE_SERVER_TLS_HANDSHAKE_START] = tbs->get_tls_handshake_begin_time(); + milestones[TS_MILESTONE_SERVER_TLS_HANDSHAKE_END] = tbs->get_tls_handshake_end_time(); + } this->create_server_txn(this->create_server_session(*_netvc, _netvc_read_buffer, _netvc_reader)); t_state.current.server->clear_connect_fail(); handle_http_server_open(); @@ -7799,7 +7814,7 @@ HttpSM::update_stats() "fd: %d " "client state: %d " "server state: %d " - "tls_handshake: %.3f " + "ua_tls_handshake: %.3f " "ua_begin: %.3f " "ua_first_read: %.3f " "ua_read_header_done: %.3f " @@ -7811,6 +7826,7 @@ HttpSM::update_stats() "dns_lookup_end: %.3f " "server_connect: %.3f " "server_connect_end: %.3f " + "server_tls_handshake: %.3f " "server_first_read: %.3f " "server_read_header_done: %.3f " "server_close: %.3f " @@ -7834,6 +7850,7 @@ HttpSM::update_stats() milestones.difference_sec(TS_MILESTONE_SM_START, TS_MILESTONE_DNS_LOOKUP_END), milestones.difference_sec(TS_MILESTONE_SM_START, TS_MILESTONE_SERVER_CONNECT), milestones.difference_sec(TS_MILESTONE_SM_START, TS_MILESTONE_SERVER_CONNECT_END), + milestones.difference_sec(TS_MILESTONE_SERVER_TLS_HANDSHAKE_START, TS_MILESTONE_SERVER_TLS_HANDSHAKE_END), milestones.difference_sec(TS_MILESTONE_SM_START, TS_MILESTONE_SERVER_FIRST_READ), milestones.difference_sec(TS_MILESTONE_SM_START, TS_MILESTONE_SERVER_READ_HEADER_DONE), milestones.difference_sec(TS_MILESTONE_SM_START, TS_MILESTONE_SERVER_CLOSE), diff --git a/src/proxy/logging/LogField.cc b/src/proxy/logging/LogField.cc index f7dcbbd067a..a70aa9240c1 100644 --- a/src/proxy/logging/LogField.cc +++ b/src/proxy/logging/LogField.cc @@ -191,30 +191,36 @@ struct milestone { }; static const milestone milestones[] = { - {"TS_MILESTONE_UA_BEGIN", TS_MILESTONE_UA_BEGIN }, - {"TS_MILESTONE_UA_FIRST_READ", TS_MILESTONE_UA_FIRST_READ }, - {"TS_MILESTONE_UA_READ_HEADER_DONE", TS_MILESTONE_UA_READ_HEADER_DONE }, - {"TS_MILESTONE_UA_BEGIN_WRITE", TS_MILESTONE_UA_BEGIN_WRITE }, - {"TS_MILESTONE_UA_CLOSE", TS_MILESTONE_UA_CLOSE }, - {"TS_MILESTONE_SERVER_FIRST_CONNECT", TS_MILESTONE_SERVER_FIRST_CONNECT }, - {"TS_MILESTONE_SERVER_CONNECT", TS_MILESTONE_SERVER_CONNECT }, - {"TS_MILESTONE_SERVER_CONNECT_END", TS_MILESTONE_SERVER_CONNECT_END }, - {"TS_MILESTONE_SERVER_BEGIN_WRITE", TS_MILESTONE_SERVER_BEGIN_WRITE }, - {"TS_MILESTONE_SERVER_FIRST_READ", TS_MILESTONE_SERVER_FIRST_READ }, - {"TS_MILESTONE_SERVER_READ_HEADER_DONE", TS_MILESTONE_SERVER_READ_HEADER_DONE}, - {"TS_MILESTONE_SERVER_CLOSE", TS_MILESTONE_SERVER_CLOSE }, - {"TS_MILESTONE_CACHE_OPEN_READ_BEGIN", TS_MILESTONE_CACHE_OPEN_READ_BEGIN }, - {"TS_MILESTONE_CACHE_OPEN_READ_END", TS_MILESTONE_CACHE_OPEN_READ_END }, - {"TS_MILESTONE_CACHE_OPEN_WRITE_BEGIN", TS_MILESTONE_CACHE_OPEN_WRITE_BEGIN }, - {"TS_MILESTONE_CACHE_OPEN_WRITE_END", TS_MILESTONE_CACHE_OPEN_WRITE_END }, - {"TS_MILESTONE_DNS_LOOKUP_BEGIN", TS_MILESTONE_DNS_LOOKUP_BEGIN }, - {"TS_MILESTONE_DNS_LOOKUP_END", TS_MILESTONE_DNS_LOOKUP_END }, - {"TS_MILESTONE_SM_START", TS_MILESTONE_SM_START }, - {"TS_MILESTONE_SM_FINISH", TS_MILESTONE_SM_FINISH }, - {"TS_MILESTONE_PLUGIN_ACTIVE", TS_MILESTONE_PLUGIN_ACTIVE }, - {"TS_MILESTONE_PLUGIN_TOTAL", TS_MILESTONE_PLUGIN_TOTAL }, - {"TS_MILESTONE_TLS_HANDSHAKE_START", TS_MILESTONE_TLS_HANDSHAKE_START }, - {"TS_MILESTONE_TLS_HANDSHAKE_END", TS_MILESTONE_TLS_HANDSHAKE_END }, + {"TS_MILESTONE_UA_BEGIN", TS_MILESTONE_UA_BEGIN }, + {"TS_MILESTONE_UA_FIRST_READ", TS_MILESTONE_UA_FIRST_READ }, + {"TS_MILESTONE_UA_READ_HEADER_DONE", TS_MILESTONE_UA_READ_HEADER_DONE }, + {"TS_MILESTONE_UA_BEGIN_WRITE", TS_MILESTONE_UA_BEGIN_WRITE }, + {"TS_MILESTONE_UA_CLOSE", TS_MILESTONE_UA_CLOSE }, + {"TS_MILESTONE_SERVER_FIRST_CONNECT", TS_MILESTONE_SERVER_FIRST_CONNECT }, + {"TS_MILESTONE_SERVER_CONNECT", TS_MILESTONE_SERVER_CONNECT }, + {"TS_MILESTONE_SERVER_CONNECT_END", TS_MILESTONE_SERVER_CONNECT_END }, + {"TS_MILESTONE_SERVER_BEGIN_WRITE", TS_MILESTONE_SERVER_BEGIN_WRITE }, + {"TS_MILESTONE_SERVER_FIRST_READ", TS_MILESTONE_SERVER_FIRST_READ }, + {"TS_MILESTONE_SERVER_READ_HEADER_DONE", TS_MILESTONE_SERVER_READ_HEADER_DONE }, + {"TS_MILESTONE_SERVER_CLOSE", TS_MILESTONE_SERVER_CLOSE }, + {"TS_MILESTONE_CACHE_OPEN_READ_BEGIN", TS_MILESTONE_CACHE_OPEN_READ_BEGIN }, + {"TS_MILESTONE_CACHE_OPEN_READ_END", TS_MILESTONE_CACHE_OPEN_READ_END }, + {"TS_MILESTONE_CACHE_OPEN_WRITE_BEGIN", TS_MILESTONE_CACHE_OPEN_WRITE_BEGIN }, + {"TS_MILESTONE_CACHE_OPEN_WRITE_END", TS_MILESTONE_CACHE_OPEN_WRITE_END }, + {"TS_MILESTONE_DNS_LOOKUP_BEGIN", TS_MILESTONE_DNS_LOOKUP_BEGIN }, + {"TS_MILESTONE_DNS_LOOKUP_END", TS_MILESTONE_DNS_LOOKUP_END }, + {"TS_MILESTONE_SM_START", TS_MILESTONE_SM_START }, + {"TS_MILESTONE_SM_FINISH", TS_MILESTONE_SM_FINISH }, + {"TS_MILESTONE_PLUGIN_ACTIVE", TS_MILESTONE_PLUGIN_ACTIVE }, + {"TS_MILESTONE_PLUGIN_TOTAL", TS_MILESTONE_PLUGIN_TOTAL }, + {"TS_MILESTONE_TLS_HANDSHAKE_START", + TS_MILESTONE_TLS_HANDSHAKE_START }, // RENAME in ATS 11 - this is the client-side TLS handshake + {"TS_MILESTONE_TLS_HANDSHAKE_END", TS_MILESTONE_TLS_HANDSHAKE_END }, // RENAME in ATS 11 - this is the client-side TLS handshake + {"TS_MILESTONE_SERVER_TLS_HANDSHAKE_START", TS_MILESTONE_SERVER_TLS_HANDSHAKE_START}, + {"TS_MILESTONE_SERVER_TLS_HANDSHAKE_END", TS_MILESTONE_SERVER_TLS_HANDSHAKE_END }, + // TODO: Add these in ATS 11, remove TLS_HANDSHAKE_* above + // {"TS_MILESTONE_UA_TLS_HANDSHAKE_START", TS_MILESTONE_UA_TLS_HANDSHAKE_START }, + // {"TS_MILESTONE_UA_TLS_HANDSHAKE_END", TS_MILESTONE_UA_TLS_HANDSHAKE_END }, }; void diff --git a/tools/slow_log_report.pl b/tools/slow_log_report.pl index 317fa10a509..1627927ac01 100755 --- a/tools/slow_log_report.pl +++ b/tools/slow_log_report.pl @@ -41,10 +41,11 @@ ($) printf("%25s %10s %10s %10s %10s %10s %10s %10s %10s\n", 'key', 'total', 'count', 'mean', 'median', '95th', '99th', 'min', 'max'); foreach my $key ( - 'tls_handshake', 'ua_begin', 'ua_first_read', 'ua_read_header_done', 'cache_open_read_begin', - 'cache_open_read_end', 'cache_open_write_begin', 'cache_open_write_end', 'dns_lookup_begin', - 'dns_lookup_end', 'server_connect', 'server_connect_end', 'server_first_read', - 'server_read_header_done', 'server_close', 'ua_close', 'sm_finish', 'plugin_active', 'plugin_total' + 'ua_tls_handshake', 'ua_begin', 'ua_first_read', 'ua_read_header_done', + 'cache_open_read_begin', 'cache_open_read_end', 'cache_open_write_begin', 'cache_open_write_end', + 'dns_lookup_begin', 'dns_lookup_end', 'server_connect', 'server_connect_end', 'server_tls_handshake', + 'server_first_read', 'server_read_header_done', 'server_close', 'ua_close', 'sm_finish', + 'plugin_active', 'plugin_total' ) { @@ -78,7 +79,7 @@ ($) s/unique id/unique_id/; s/server state/server_state/; s/client state/client_state/; - if (m|Slow Request: .+ (tls_handshake: .+)|) { + if (m|Slow Request: .+ (ua_tls_handshake: .+)|) { my %data = split(/: | /, $1); foreach my $key (keys %data) { next if (!defined $data{$key}); From 9bac89e2bbd1bee7a4022ffbe830f3461d7a5cba Mon Sep 17 00:00:00 2001 From: Bryan Call Date: Thu, 5 Feb 2026 11:38:45 -0800 Subject: [PATCH 2/6] Fix difference_msec() to check both start and end milestones for unset Previously, difference_msec() only checked if ms_end was 0 (unset) before returning the "missing" sentinel value. If ms_start was unset (0) but ms_end was set, the subtraction would produce a garbage value equal to the raw nanosecond timestamp of ms_end. This affects any milestone difference calculation where the start milestone may not be set, such as server-side milestones on cache hits where no origin connection was made. The fix adds a check for ms_start == 0 alongside the existing ms_end check. This is safe because ink_hrtime values are nanoseconds from a reference point and are never legitimately 0. The difference_sec() function inherits this fix since it delegates to difference_msec(). --- include/proxy/Milestones.h | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/include/proxy/Milestones.h b/include/proxy/Milestones.h index 622b5738ae8..8f681357397 100644 --- a/include/proxy/Milestones.h +++ b/include/proxy/Milestones.h @@ -64,7 +64,7 @@ template class Milestones int64_t difference_msec(T ms_start, T ms_end, int64_t missing = -1) const // Return "missing" when Milestone is not set { - if (this->_milestones[static_cast(ms_end)] == 0) { + if (this->_milestones[static_cast(ms_start)] == 0 || this->_milestones[static_cast(ms_end)] == 0) { return missing; } return ink_hrtime_to_msec(this->_milestones[static_cast(ms_end)] - this->_milestones[static_cast(ms_start)]); From d0ab0ac3a4725f465a8c1810e271f46122fa446f Mon Sep 17 00:00:00 2001 From: Bryan Call Date: Thu, 5 Feb 2026 11:50:19 -0800 Subject: [PATCH 3/6] Use SM_START as base for server_tls_handshake in slow log Change server_tls_handshake from a duration (START to END) to an offset from SM_START (SM_START to END), consistent with all other server-side fields in the slow log (server_connect, server_connect_end, server_first_read, etc.). The TLS duration can be inferred from server_tls_handshake - server_connect_end. --- src/proxy/http/HttpSM.cc | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/proxy/http/HttpSM.cc b/src/proxy/http/HttpSM.cc index f53c70e0892..02101b90b3f 100644 --- a/src/proxy/http/HttpSM.cc +++ b/src/proxy/http/HttpSM.cc @@ -7850,7 +7850,7 @@ HttpSM::update_stats() milestones.difference_sec(TS_MILESTONE_SM_START, TS_MILESTONE_DNS_LOOKUP_END), milestones.difference_sec(TS_MILESTONE_SM_START, TS_MILESTONE_SERVER_CONNECT), milestones.difference_sec(TS_MILESTONE_SM_START, TS_MILESTONE_SERVER_CONNECT_END), - milestones.difference_sec(TS_MILESTONE_SERVER_TLS_HANDSHAKE_START, TS_MILESTONE_SERVER_TLS_HANDSHAKE_END), + milestones.difference_sec(TS_MILESTONE_SM_START, TS_MILESTONE_SERVER_TLS_HANDSHAKE_END), milestones.difference_sec(TS_MILESTONE_SM_START, TS_MILESTONE_SERVER_FIRST_READ), milestones.difference_sec(TS_MILESTONE_SM_START, TS_MILESTONE_SERVER_READ_HEADER_DONE), milestones.difference_sec(TS_MILESTONE_SM_START, TS_MILESTONE_SERVER_CLOSE), From 9ef7b316fe41662ec4313c6e44e3a7c5b30e1d9f Mon Sep 17 00:00:00 2001 From: Bryan Call Date: Thu, 5 Feb 2026 11:53:57 -0800 Subject: [PATCH 4/6] Add comments explaining the two server connection paths Clarify that CONNECT_EVENT_TXN is the multiplexed path (e.g. HTTP/2) where ConnectingEntry creates the session, and VC_EVENT_WRITE_COMPLETE is the direct path (e.g. HTTP/1) where HttpSM owns the netvc. Both paths need to capture server TLS handshake timing. --- src/proxy/http/HttpSM.cc | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/src/proxy/http/HttpSM.cc b/src/proxy/http/HttpSM.cc index 02101b90b3f..c0b3fd051fe 100644 --- a/src/proxy/http/HttpSM.cc +++ b/src/proxy/http/HttpSM.cc @@ -1882,6 +1882,8 @@ HttpSM::state_http_server_open(int event, void *data) do_http_server_open(); break; case CONNECT_EVENT_TXN: { + // Multiplexed connection path (e.g. HTTP/2): ConnectingEntry created the session + // and dispatched this event. Get the netvc from the PoolableSession. SMDbg(dbg_ctl_http, "Connection handshake complete via CONNECT_EVENT_TXN"); PoolableSession *session = static_cast(data); ink_assert(session != nullptr); @@ -1904,7 +1906,8 @@ HttpSM::state_http_server_open(int event, void *data) case VC_EVENT_READ_COMPLETE: case VC_EVENT_WRITE_READY: case VC_EVENT_WRITE_COMPLETE: - // Update the time out to the regular connection timeout. + // Direct connection path (e.g. HTTP/1): HttpSM owns the netvc directly + // and creates the session itself. SMDbg(dbg_ctl_http_ss, "Connection handshake complete"); // Capture server TLS handshake timing if this is a TLS connection if (auto tbs = _netvc->get_service()) { From 16951f216b6b9681df9e1db3640a676d3460c6cb Mon Sep 17 00:00:00 2001 From: Bryan Call Date: Thu, 5 Feb 2026 12:45:10 -0800 Subject: [PATCH 5/6] Make slow_log_report.pl backward compatible with old log format The tls_handshake field was renamed to ua_tls_handshake but the report script needs to handle both formats so it can parse logs from before and after the rename. --- tools/slow_log_report.pl | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/tools/slow_log_report.pl b/tools/slow_log_report.pl index 1627927ac01..1ce04047f0f 100755 --- a/tools/slow_log_report.pl +++ b/tools/slow_log_report.pl @@ -41,6 +41,7 @@ ($) printf("%25s %10s %10s %10s %10s %10s %10s %10s %10s\n", 'key', 'total', 'count', 'mean', 'median', '95th', '99th', 'min', 'max'); foreach my $key ( + 'tls_handshake', # TODO ATS 11: remove once old log format is no longer supported 'ua_tls_handshake', 'ua_begin', 'ua_first_read', 'ua_read_header_done', 'cache_open_read_begin', 'cache_open_read_end', 'cache_open_write_begin', 'cache_open_write_end', 'dns_lookup_begin', 'dns_lookup_end', 'server_connect', 'server_connect_end', 'server_tls_handshake', @@ -79,7 +80,8 @@ ($) s/unique id/unique_id/; s/server state/server_state/; s/client state/client_state/; - if (m|Slow Request: .+ (ua_tls_handshake: .+)|) { + # TODO ATS 11: remove 'tls_handshake' match once old log format is no longer supported + if (m|Slow Request: .+ ((?:ua_)?tls_handshake: .+)|) { my %data = split(/: | /, $1); foreach my $key (keys %data) { next if (!defined $data{$key}); From 2f0b81954eea3aa213924e8ca188806b36d1abfc Mon Sep 17 00:00:00 2001 From: Bryan Call Date: Thu, 5 Feb 2026 23:07:12 -0800 Subject: [PATCH 6/6] Use pre-remap URL in slow log output The slow log was printing the post-remap (origin-facing) URL which is less useful for debugging since it does not show what the client actually requested. Use t_state.unmapped_url (the pre-remap URL) instead, with a fallback to client_request URL if unmapped_url is not available. --- src/proxy/http/HttpSM.cc | 19 ++++++++++++++----- 1 file changed, 14 insertions(+), 5 deletions(-) diff --git a/src/proxy/http/HttpSM.cc b/src/proxy/http/HttpSM.cc index c0b3fd051fe..d41ace27b00 100644 --- a/src/proxy/http/HttpSM.cc +++ b/src/proxy/http/HttpSM.cc @@ -7773,12 +7773,21 @@ HttpSM::update_stats() // print slow requests if the threshold is set (> 0) and if we are over the time threshold if (t_state.txn_conf->slow_log_threshold != 0 && ink_hrtime_from_msec(t_state.txn_conf->slow_log_threshold) < total_time) { + // Use the unmapped (pre-remap) URL so the slow log shows the incoming client URL. + // unmapped_url may not be valid if the transaction ended before reaching the remap + // stage (e.g. client timeout during header read, malformed request). In that case + // fall back to client_request URL which hasn't been remapped yet either. char url_string[256] = ""; - int offset = 0; - int skip = 0; - - t_state.hdr_info.client_request.url_print(url_string, sizeof(url_string) - 1, &offset, &skip); - url_string[offset] = 0; // NULL terminate the string + int url_length = 0; + if (t_state.unmapped_url.valid()) { + t_state.unmapped_url.string_get_buf(url_string, sizeof(url_string) - 1, &url_length); + } else { + int offset = 0; + int skip = 0; + t_state.hdr_info.client_request.url_print(url_string, sizeof(url_string) - 1, &offset, &skip); + url_length = offset; + } + url_string[url_length] = 0; // NULL terminate the string // unique id char unique_id_string[128] = "";