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/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)]); 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..d41ace27b00 100644 --- a/src/proxy/http/HttpSM.cc +++ b/src/proxy/http/HttpSM.cc @@ -1881,9 +1881,20 @@ 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 (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"); - 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 +1902,18 @@ 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 (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()) { + 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(); @@ -7755,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] = ""; @@ -7799,7 +7826,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 +7838,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 +7862,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 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..1ce04047f0f 100755 --- a/tools/slow_log_report.pl +++ b/tools/slow_log_report.pl @@ -41,10 +41,12 @@ ($) 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 @@ ($) 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});