This is an automated email from the ASF dual-hosted git repository.
bcall pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/trafficserver.git
The following commit(s) were added to refs/heads/master by this push:
new 33566ff856 Add: Server-side TLS handshake milestones and timing fixes
(#12860)
33566ff856 is described below
commit 33566ff8565e56b97963986715976705c7549692
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.
---
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 86aff5202f..e82eb7f0ae 100644
--- a/include/ts/apidefs.h.in
+++ b/include/ts/apidefs.h.in
@@ -985,6 +985,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 7b979ca217..b7c46574c8 100644
--- a/src/proxy/http/HttpSM.cc
+++ b/src/proxy/http/HttpSM.cc
@@ -1893,9 +1893,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
@@ -1903,11 +1917,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();
@@ -7803,12 +7825,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] = "";
@@ -7847,7 +7878,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 "
@@ -7859,6 +7890,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 "
@@ -7882,6 +7914,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 914363ced6..5852949079 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});
