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 30041024cabb2ae161a52d728eb52a1909ac9f01 Author: Bryan Call <[email protected]> AuthorDate: Wed Mar 11 13:43:00 2026 -0700 Add: Server-side TLS handshake milestones and timing fixes (#12860) Add TS_MILESTONE_SERVER_TLS_HANDSHAKE_START/END to capture origin-side TLS handshake timing, complementing the existing client-side milestones. Capture server TLS timing in HttpSM::state_http_server_open() for both H2 multiplexed and H1 direct connection paths. Fix the missing _record_tls_handshake_end_time() call for outbound connections and fix difference_msec() to check both start and end for 0. Rename slow log field tls_handshake to ua_tls_handshake for clarity and add server_tls_handshake. Use pre-remap URL in slow log output. (cherry picked from commit 33566ff8565e56b97963986715976705c7549692) --- doc/admin-guide/plugins/lua.en.rst | 2 + .../api/functions/TSHttpTxnMilestoneGet.en.rst | 12 ++++- include/ts/apidefs.h.in | 2 + plugins/lua/ts_lua_http_milestone.cc | 54 ++++++++++++---------- src/iocore/net/SSLNetVConnection.cc | 12 +++++ src/proxy/http/HttpSM.cc | 51 ++++++++++++++++---- src/proxy/logging/LogField.cc | 54 ++++++++++++---------- tools/slow_log_report.pl | 13 ++++-- 8 files changed, 135 insertions(+), 65 deletions(-) diff --git a/doc/admin-guide/plugins/lua.en.rst b/doc/admin-guide/plugins/lua.en.rst index 122547ca58..d62a2f4e43 100644 --- a/doc/admin-guide/plugins/lua.en.rst +++ b/doc/admin-guide/plugins/lua.en.rst @@ -5039,6 +5039,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 <admin-plugins-ts-lua>` diff --git a/doc/developer-guide/api/functions/TSHttpTxnMilestoneGet.en.rst b/doc/developer-guide/api/functions/TSHttpTxnMilestoneGet.en.rst index b1290db319..dbabefca5a 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 5515aa7665..3cd81cb9ce 100644 --- a/include/ts/apidefs.h.in +++ b/include/ts/apidefs.h.in @@ -979,6 +979,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 81b9ae262f..8bd88cf068 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 c4aeb44a89..8b599e5e4a 100644 --- a/src/iocore/net/SSLNetVConnection.cc +++ b/src/iocore/net/SSLNetVConnection.cc @@ -1579,6 +1579,18 @@ 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 (origin) connections. + // Despite the name, sslClientHandShakeEvent() handles the *outbound* side + // where ATS acts as the TLS client connecting to the origin server. + // (The inbound/client-facing side is handled by sslServerHandShakeEvent(), + // where ATS acts as the TLS server.) + // The begin time is set when the handshake starts; we record the end time + // here so HttpSM can later copy both into milestones for logging. + 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 f454ddf24e..6f3bcf6bf9 100644 --- a/src/proxy/http/HttpSM.cc +++ b/src/proxy/http/HttpSM.cc @@ -1891,9 +1891,23 @@ 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: { + // Multiplexed connection path (H2/H3): ConnectingEntry owns the connection and + // dispatches this event with the PoolableSession once the handshake completes. + // The HttpSM has no access to the netvc during the handshake, so we copy the + // timestamps that were recorded in real-time by sslClientHandShakeEvent(). + // See also VC_EVENT_WRITE_COMPLETE below for the direct (H1) path -- these + // two paths are mutually exclusive. SMDbg(dbg_ctl_http, "Connection handshake complete via CONNECT_EVENT_TXN"); - if (this->create_server_txn(static_cast<PoolableSession *>(data))) { + PoolableSession *session = static_cast<PoolableSession *>(data); + ink_assert(session != nullptr); + if (auto *netvc = session->get_netvc()) { + if (auto tbs = netvc->get_service<TLSBasicSupport>()) { + 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 @@ -1901,11 +1915,19 @@ 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. + // Direct connection path (H1): HttpSM owns the netvc directly. + // Same milestone copy as CONNECT_EVENT_TXN above -- these two paths are + // mutually exclusive. Timestamps were recorded in real-time by + // sslClientHandShakeEvent(); we copy them into milestones here. SMDbg(dbg_ctl_http_ss, "Connection handshake complete"); + if (auto tbs = _netvc->get_service<TLSBasicSupport>()) { + 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(); @@ -7796,12 +7818,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] = ""; @@ -7840,7 +7871,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 " @@ -7852,6 +7883,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 " @@ -7875,6 +7907,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_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), diff --git a/src/proxy/logging/LogField.cc b/src/proxy/logging/LogField.cc index f7dcbbd067..a70aa9240c 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 317fa10a50..1ce04047f0 100755 --- a/tools/slow_log_report.pl +++ b/tools/slow_log_report.pl @@ -41,10 +41,12 @@ sub displayStat($) 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' + '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', + 'server_first_read', 'server_read_header_done', 'server_close', 'ua_close', 'sm_finish', + 'plugin_active', 'plugin_total' ) { @@ -78,7 +80,8 @@ sub displayStat($) s/unique id/unique_id/; s/server state/server_state/; s/client state/client_state/; - if (m|Slow Request: .+ (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});
