Skip to content

Add: Server-side TLS handshake milestones and timing fixes #12860

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
bryancall wants to merge 7 commits into
base: master
Choose a base branch
from
Open

Add: Server-side TLS handshake milestones and timing fixes #12860

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
7 commits
Select commit Hold shift + click to select a range
07e0f9c
Add server-side TLS handshake milestones and fix outbound TLS timing
bryancall Feb 5, 2026
9bac89e
Fix difference_msec() to check both start and end milestones for unset
bryancall Feb 5, 2026
d0ab0ac
Use SM_START as base for server_tls_handshake in slow log
bryancall Feb 5, 2026
9ef7b31
Add comments explaining the two server connection paths
bryancall Feb 5, 2026
16951f2
Make slow_log_report.pl backward compatible with old log format
bryancall Feb 5, 2026
2f0b819
Use pre-remap URL in slow log output
bryancall Feb 6, 2026
c50964b
Improve comments explaining server TLS milestone capture pattern
bryancall Mar 3, 2026
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 2 additions & 0 deletions doc/admin-guide/plugins/lua.en.rst
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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 <admin-plugins-ts-lua>`
Expand Down
12 changes: 10 additions & 2 deletions doc/developer-guide/api/functions/TSHttpTxnMilestoneGet.en.rst
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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

Expand Down
2 changes: 1 addition & 1 deletion include/proxy/Milestones.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -64,7 +64,7 @@ template <class T, size_t entries> 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<size_t>(ms_end)] == 0) {
if (this->_milestones[static_cast<size_t>(ms_start)] == 0 || this->_milestones[static_cast<size_t>(ms_end)] == 0) {
return missing;
}
return ink_hrtime_to_msec(this->_milestones[static_cast<size_t>(ms_end)] - this->_milestones[static_cast<size_t>(ms_start)]);
Expand Down
2 changes: 2 additions & 0 deletions include/ts/apidefs.h.in
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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,
};

Expand Down
54 changes: 29 additions & 25 deletions plugins/lua/ts_lua_http_milestone.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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),
Expand All @@ -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);

Expand Down
12 changes: 12 additions & 0 deletions src/iocore/net/SSLNetVConnection.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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();
}
Copy link
Contributor

@cmcfarlen cmcfarlen Mar 3, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why was this added? This function seems to deal with the client side, but the comment mentions outbound connections. And, if this were the outbound side, are we expecting the metrics this function updates to include both sides TLS?

Copy link
Contributor Author

@bryancall bryancall Mar 3, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The naming in this file is from the TLS role perspective, not the ATS role. sslClientHandShakeEvent() handles the outbound side where ATS acts as the TLS client connecting to the origin. sslServerHandShakeEvent() handles the inbound side where ATS acts as the TLS server accepting client connections.

The inbound side already records the end time (line 1383), but the outbound side was missing it — this is a bug fix. Without this, get_tls_handshake_end_time() returns zero when HttpSM tries to copy the timestamps into milestones.

I've updated the comment to clarify the naming convention and the two-stage pattern.


return EVENT_DONE;

case SSL_ERROR_WANT_WRITE:
Expand Down
51 changes: 42 additions & 9 deletions src/proxy/http/HttpSM.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -1881,21 +1881,43 @@ 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();
Copy link
Contributor

@cmcfarlen cmcfarlen Mar 3, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This sets both milestones after the end time is known. Should we set the start milestone when it starts vs here? As it is, if this code isn't reached, the start milestone won't be set.

Copy link
Contributor Author

@bryancall bryancall Mar 3, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The HttpSM doesn't have access to the netvc during the handshake in the multiplexed path — ConnectingEntry owns the connection and dispatches CONNECT_EVENT_TXN after the handshake completes. So this is the earliest point the SM can grab the timestamps.

The actual start/end times are captured in real-time at the netvc layer (sslClientHandShakeEvent() records the end time, and the begin time is set when the handshake starts). We're just copying them into milestones here. If this code isn't reached (e.g. connection failure), the milestones stay at zero, which is correct — difference_msec() checks for zero before computing the difference.

Updated the comments to make this clearer.

}
}
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
// Try again (probably need a bounding counter here)
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();
}
Copy link
Contributor

@cmcfarlen cmcfarlen Mar 3, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why are these set again?

Copy link
Contributor Author

@bryancall bryancall Mar 3, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

These aren't duplicates — they're two mutually exclusive connection paths. CONNECT_EVENT_TXN fires for multiplexed connections (H2/H3) where ConnectingEntry manages the connection. VC_EVENT_WRITE_COMPLETE fires for direct connections (H1) where the SM owns the netvc. A given connection goes through one path or the other, never both.

Updated both comments to cross-reference each other and explicitly state they're mutually exclusive.

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();
Expand Down Expand Up @@ -7755,12 +7777,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] = "";
Expand Down Expand Up @@ -7799,7 +7830,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 "
Expand All @@ -7811,6 +7842,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 "
Expand All @@ -7834,6 +7866,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),
Expand Down
54 changes: 30 additions & 24 deletions src/proxy/logging/LogField.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
13 changes: 8 additions & 5 deletions tools/slow_log_report.pl
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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'
)
{

Expand Down Expand Up @@ -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});
Expand Down