Skip to content

Commit 33566ff

Browse files
authored
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.
1 parent 51a277d commit 33566ff

8 files changed

Lines changed: 135 additions & 65 deletions

File tree

doc/admin-guide/plugins/lua.en.rst

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -5039,6 +5039,8 @@ Milestone constants
50395039
TS_LUA_MILESTONE_PLUGIN_TOTAL
50405040
TS_LUA_MILESTONE_TLS_HANDSHAKE_START
50415041
TS_LUA_MILESTONE_TLS_HANDSHAKE_END
5042+
TS_LUA_MILESTONE_SERVER_TLS_HANDSHAKE_START
5043+
TS_LUA_MILESTONE_SERVER_TLS_HANDSHAKE_END
50425044

50435045

50445046
:ref:`TOP <admin-plugins-ts-lua>`

doc/developer-guide/api/functions/TSHttpTxnMilestoneGet.en.rst

Lines changed: 10 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -132,11 +132,19 @@ is successful.
132132

133133
.. enumerator:: TS_MILESTONE_TLS_HANDSHAKE_START
134134

135-
Timestamp when the server starts the TLS handshake. 0 if no handshake is performed (connection reuse).
135+
Timestamp when the client starts the TLS handshake with the proxy. 0 if no handshake is performed (connection reuse).
136136

137137
.. enumerator:: TS_MILESTONE_TLS_HANDSHAKE_END
138138

139-
Timestamp when the server completes the TLS handshake. 0 if no handshake is performed (connection reuse).
139+
Timestamp when the client completes the TLS handshake with the proxy. 0 if no handshake is performed (connection reuse).
140+
141+
.. enumerator:: TS_MILESTONE_SERVER_TLS_HANDSHAKE_START
142+
143+
Timestamp when the proxy starts the TLS handshake with the origin server. 0 if no handshake is performed (connection reuse or non-TLS origin).
144+
145+
.. enumerator:: TS_MILESTONE_SERVER_TLS_HANDSHAKE_END
146+
147+
Timestamp when the proxy completes the TLS handshake with the origin server. 0 if no handshake is performed (connection reuse or non-TLS origin).
140148

141149
.. enumerator:: TS_MILESTONE_LAST_ENTRY
142150

include/ts/apidefs.h.in

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -985,6 +985,8 @@ enum TSMilestonesType {
985985
TS_MILESTONE_PLUGIN_TOTAL,
986986
TS_MILESTONE_TLS_HANDSHAKE_START,
987987
TS_MILESTONE_TLS_HANDSHAKE_END,
988+
TS_MILESTONE_SERVER_TLS_HANDSHAKE_START,
989+
TS_MILESTONE_SERVER_TLS_HANDSHAKE_END,
988990
TS_MILESTONE_LAST_ENTRY,
989991
};
990992

plugins/lua/ts_lua_http_milestone.cc

Lines changed: 29 additions & 25 deletions
Original file line numberDiff line numberDiff line change
@@ -19,30 +19,32 @@
1919
#include "ts_lua_util.h"
2020

2121
typedef enum {
22-
TS_LUA_MILESTONE_UA_BEGIN = TS_MILESTONE_UA_BEGIN,
23-
TS_LUA_MILESTONE_UA_FIRST_READ = TS_MILESTONE_UA_FIRST_READ,
24-
TS_LUA_MILESTONE_UA_READ_HEADER_DONE = TS_MILESTONE_UA_READ_HEADER_DONE,
25-
TS_LUA_MILESTONE_UA_BEGIN_WRITE = TS_MILESTONE_UA_BEGIN_WRITE,
26-
TS_LUA_MILESTONE_UA_CLOSE = TS_MILESTONE_UA_CLOSE,
27-
TS_LUA_MILESTONE_SERVER_FIRST_CONNECT = TS_MILESTONE_SERVER_FIRST_CONNECT,
28-
TS_LUA_MILESTONE_SERVER_CONNECT = TS_MILESTONE_SERVER_CONNECT,
29-
TS_LUA_MILESTONE_SERVER_CONNECT_END = TS_MILESTONE_SERVER_CONNECT_END,
30-
TS_LUA_MILESTONE_SERVER_BEGIN_WRITE = TS_MILESTONE_SERVER_BEGIN_WRITE,
31-
TS_LUA_MILESTONE_SERVER_FIRST_READ = TS_MILESTONE_SERVER_FIRST_READ,
32-
TS_LUA_MILESTONE_SERVER_READ_HEADER_DONE = TS_MILESTONE_SERVER_READ_HEADER_DONE,
33-
TS_LUA_MILESTONE_SERVER_CLOSE = TS_MILESTONE_SERVER_CLOSE,
34-
TS_LUA_MILESTONE_CACHE_OPEN_READ_BEGIN = TS_MILESTONE_CACHE_OPEN_READ_BEGIN,
35-
TS_LUA_MILESTONE_CACHE_OPEN_READ_END = TS_MILESTONE_CACHE_OPEN_READ_END,
36-
TS_LUA_MILESTONE_CACHE_OPEN_WRITE_BEGIN = TS_MILESTONE_CACHE_OPEN_WRITE_BEGIN,
37-
TS_LUA_MILESTONE_CACHE_OPEN_WRITE_END = TS_MILESTONE_CACHE_OPEN_WRITE_END,
38-
TS_LUA_MILESTONE_DNS_LOOKUP_BEGIN = TS_MILESTONE_DNS_LOOKUP_BEGIN,
39-
TS_LUA_MILESTONE_DNS_LOOKUP_END = TS_MILESTONE_DNS_LOOKUP_END,
40-
TS_LUA_MILESTONE_SM_START = TS_MILESTONE_SM_START,
41-
TS_LUA_MILESTONE_SM_FINISH = TS_MILESTONE_SM_FINISH,
42-
TS_LUA_MILESTONE_PLUGIN_ACTIVE = TS_MILESTONE_PLUGIN_ACTIVE,
43-
TS_LUA_MILESTONE_PLUGIN_TOTAL = TS_MILESTONE_PLUGIN_TOTAL,
44-
TS_LUA_MILESTONE_TLS_HANDSHAKE_START = TS_MILESTONE_TLS_HANDSHAKE_START,
45-
TS_LUA_MILESTONE_TLS_HANDSHAKE_END = TS_MILESTONE_TLS_HANDSHAKE_END
22+
TS_LUA_MILESTONE_UA_BEGIN = TS_MILESTONE_UA_BEGIN,
23+
TS_LUA_MILESTONE_UA_FIRST_READ = TS_MILESTONE_UA_FIRST_READ,
24+
TS_LUA_MILESTONE_UA_READ_HEADER_DONE = TS_MILESTONE_UA_READ_HEADER_DONE,
25+
TS_LUA_MILESTONE_UA_BEGIN_WRITE = TS_MILESTONE_UA_BEGIN_WRITE,
26+
TS_LUA_MILESTONE_UA_CLOSE = TS_MILESTONE_UA_CLOSE,
27+
TS_LUA_MILESTONE_SERVER_FIRST_CONNECT = TS_MILESTONE_SERVER_FIRST_CONNECT,
28+
TS_LUA_MILESTONE_SERVER_CONNECT = TS_MILESTONE_SERVER_CONNECT,
29+
TS_LUA_MILESTONE_SERVER_CONNECT_END = TS_MILESTONE_SERVER_CONNECT_END,
30+
TS_LUA_MILESTONE_SERVER_BEGIN_WRITE = TS_MILESTONE_SERVER_BEGIN_WRITE,
31+
TS_LUA_MILESTONE_SERVER_FIRST_READ = TS_MILESTONE_SERVER_FIRST_READ,
32+
TS_LUA_MILESTONE_SERVER_READ_HEADER_DONE = TS_MILESTONE_SERVER_READ_HEADER_DONE,
33+
TS_LUA_MILESTONE_SERVER_CLOSE = TS_MILESTONE_SERVER_CLOSE,
34+
TS_LUA_MILESTONE_CACHE_OPEN_READ_BEGIN = TS_MILESTONE_CACHE_OPEN_READ_BEGIN,
35+
TS_LUA_MILESTONE_CACHE_OPEN_READ_END = TS_MILESTONE_CACHE_OPEN_READ_END,
36+
TS_LUA_MILESTONE_CACHE_OPEN_WRITE_BEGIN = TS_MILESTONE_CACHE_OPEN_WRITE_BEGIN,
37+
TS_LUA_MILESTONE_CACHE_OPEN_WRITE_END = TS_MILESTONE_CACHE_OPEN_WRITE_END,
38+
TS_LUA_MILESTONE_DNS_LOOKUP_BEGIN = TS_MILESTONE_DNS_LOOKUP_BEGIN,
39+
TS_LUA_MILESTONE_DNS_LOOKUP_END = TS_MILESTONE_DNS_LOOKUP_END,
40+
TS_LUA_MILESTONE_SM_START = TS_MILESTONE_SM_START,
41+
TS_LUA_MILESTONE_SM_FINISH = TS_MILESTONE_SM_FINISH,
42+
TS_LUA_MILESTONE_PLUGIN_ACTIVE = TS_MILESTONE_PLUGIN_ACTIVE,
43+
TS_LUA_MILESTONE_PLUGIN_TOTAL = TS_MILESTONE_PLUGIN_TOTAL,
44+
TS_LUA_MILESTONE_TLS_HANDSHAKE_START = TS_MILESTONE_TLS_HANDSHAKE_START,
45+
TS_LUA_MILESTONE_TLS_HANDSHAKE_END = TS_MILESTONE_TLS_HANDSHAKE_END,
46+
TS_LUA_MILESTONE_SERVER_TLS_HANDSHAKE_START = TS_MILESTONE_SERVER_TLS_HANDSHAKE_START,
47+
TS_LUA_MILESTONE_SERVER_TLS_HANDSHAKE_END = TS_MILESTONE_SERVER_TLS_HANDSHAKE_END
4648
} TSLuaMilestoneType;
4749

4850
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
6870
TS_LUA_MAKE_VAR_ITEM(TS_LUA_MILESTONE_PLUGIN_ACTIVE),
6971
TS_LUA_MAKE_VAR_ITEM(TS_LUA_MILESTONE_PLUGIN_TOTAL),
7072
TS_LUA_MAKE_VAR_ITEM(TS_LUA_MILESTONE_TLS_HANDSHAKE_START),
71-
TS_LUA_MAKE_VAR_ITEM(TS_LUA_MILESTONE_TLS_HANDSHAKE_END)};
73+
TS_LUA_MAKE_VAR_ITEM(TS_LUA_MILESTONE_TLS_HANDSHAKE_END),
74+
TS_LUA_MAKE_VAR_ITEM(TS_LUA_MILESTONE_SERVER_TLS_HANDSHAKE_START),
75+
TS_LUA_MAKE_VAR_ITEM(TS_LUA_MILESTONE_SERVER_TLS_HANDSHAKE_END)};
7276

7377
static void ts_lua_inject_http_milestone_variables(lua_State *L);
7478

src/iocore/net/SSLNetVConnection.cc

Lines changed: 12 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1579,6 +1579,18 @@ SSLNetVConnection::sslClientHandShakeEvent(int &err)
15791579
Metrics::Counter::increment(ssl_rsb.total_success_handshake_count_out);
15801580

15811581
sslHandshakeStatus = SSLHandshakeStatus::SSL_HANDSHAKE_DONE;
1582+
1583+
// Record TLS handshake end time for outbound (origin) connections.
1584+
// Despite the name, sslClientHandShakeEvent() handles the *outbound* side
1585+
// where ATS acts as the TLS client connecting to the origin server.
1586+
// (The inbound/client-facing side is handled by sslServerHandShakeEvent(),
1587+
// where ATS acts as the TLS server.)
1588+
// The begin time is set when the handshake starts; we record the end time
1589+
// here so HttpSM can later copy both into milestones for logging.
1590+
if (this->get_tls_handshake_begin_time()) {
1591+
this->_record_tls_handshake_end_time();
1592+
}
1593+
15821594
return EVENT_DONE;
15831595

15841596
case SSL_ERROR_WANT_WRITE:

src/proxy/http/HttpSM.cc

Lines changed: 42 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -1893,21 +1893,43 @@ HttpSM::state_http_server_open(int event, void *data)
18931893
case CONNECT_EVENT_RETRY:
18941894
do_http_server_open();
18951895
break;
1896-
case CONNECT_EVENT_TXN:
1896+
case CONNECT_EVENT_TXN: {
1897+
// Multiplexed connection path (H2/H3): ConnectingEntry owns the connection and
1898+
// dispatches this event with the PoolableSession once the handshake completes.
1899+
// The HttpSM has no access to the netvc during the handshake, so we copy the
1900+
// timestamps that were recorded in real-time by sslClientHandShakeEvent().
1901+
// See also VC_EVENT_WRITE_COMPLETE below for the direct (H1) path -- these
1902+
// two paths are mutually exclusive.
18971903
SMDbg(dbg_ctl_http, "Connection handshake complete via CONNECT_EVENT_TXN");
1898-
if (this->create_server_txn(static_cast<PoolableSession *>(data))) {
1904+
PoolableSession *session = static_cast<PoolableSession *>(data);
1905+
ink_assert(session != nullptr);
1906+
if (auto *netvc = session->get_netvc()) {
1907+
if (auto tbs = netvc->get_service<TLSBasicSupport>()) {
1908+
milestones[TS_MILESTONE_SERVER_TLS_HANDSHAKE_START] = tbs->get_tls_handshake_begin_time();
1909+
milestones[TS_MILESTONE_SERVER_TLS_HANDSHAKE_END] = tbs->get_tls_handshake_end_time();
1910+
}
1911+
}
1912+
if (this->create_server_txn(session)) {
18991913
t_state.current.server->clear_connect_fail();
19001914
handle_http_server_open();
19011915
} else { // Failed to create transaction. Maybe too many active transactions already
19021916
// Try again (probably need a bounding counter here)
19031917
do_http_server_open(false);
19041918
}
19051919
return 0;
1920+
}
19061921
case VC_EVENT_READ_COMPLETE:
19071922
case VC_EVENT_WRITE_READY:
19081923
case VC_EVENT_WRITE_COMPLETE:
1909-
// Update the time out to the regular connection timeout.
1924+
// Direct connection path (H1): HttpSM owns the netvc directly.
1925+
// Same milestone copy as CONNECT_EVENT_TXN above -- these two paths are
1926+
// mutually exclusive. Timestamps were recorded in real-time by
1927+
// sslClientHandShakeEvent(); we copy them into milestones here.
19101928
SMDbg(dbg_ctl_http_ss, "Connection handshake complete");
1929+
if (auto tbs = _netvc->get_service<TLSBasicSupport>()) {
1930+
milestones[TS_MILESTONE_SERVER_TLS_HANDSHAKE_START] = tbs->get_tls_handshake_begin_time();
1931+
milestones[TS_MILESTONE_SERVER_TLS_HANDSHAKE_END] = tbs->get_tls_handshake_end_time();
1932+
}
19111933
this->create_server_txn(this->create_server_session(*_netvc, _netvc_read_buffer, _netvc_reader));
19121934
t_state.current.server->clear_connect_fail();
19131935
handle_http_server_open();
@@ -7803,12 +7825,21 @@ HttpSM::update_stats()
78037825

78047826
// print slow requests if the threshold is set (> 0) and if we are over the time threshold
78057827
if (t_state.txn_conf->slow_log_threshold != 0 && ink_hrtime_from_msec(t_state.txn_conf->slow_log_threshold) < total_time) {
7828+
// Use the unmapped (pre-remap) URL so the slow log shows the incoming client URL.
7829+
// unmapped_url may not be valid if the transaction ended before reaching the remap
7830+
// stage (e.g. client timeout during header read, malformed request). In that case
7831+
// fall back to client_request URL which hasn't been remapped yet either.
78067832
char url_string[256] = "";
7807-
int offset = 0;
7808-
int skip = 0;
7809-
7810-
t_state.hdr_info.client_request.url_print(url_string, sizeof(url_string) - 1, &offset, &skip);
7811-
url_string[offset] = 0; // NULL terminate the string
7833+
int url_length = 0;
7834+
if (t_state.unmapped_url.valid()) {
7835+
t_state.unmapped_url.string_get_buf(url_string, sizeof(url_string) - 1, &url_length);
7836+
} else {
7837+
int offset = 0;
7838+
int skip = 0;
7839+
t_state.hdr_info.client_request.url_print(url_string, sizeof(url_string) - 1, &offset, &skip);
7840+
url_length = offset;
7841+
}
7842+
url_string[url_length] = 0; // NULL terminate the string
78127843

78137844
// unique id
78147845
char unique_id_string[128] = "";
@@ -7847,7 +7878,7 @@ HttpSM::update_stats()
78477878
"fd: %d "
78487879
"client state: %d "
78497880
"server state: %d "
7850-
"tls_handshake: %.3f "
7881+
"ua_tls_handshake: %.3f "
78517882
"ua_begin: %.3f "
78527883
"ua_first_read: %.3f "
78537884
"ua_read_header_done: %.3f "
@@ -7859,6 +7890,7 @@ HttpSM::update_stats()
78597890
"dns_lookup_end: %.3f "
78607891
"server_connect: %.3f "
78617892
"server_connect_end: %.3f "
7893+
"server_tls_handshake: %.3f "
78627894
"server_first_read: %.3f "
78637895
"server_read_header_done: %.3f "
78647896
"server_close: %.3f "
@@ -7882,6 +7914,7 @@ HttpSM::update_stats()
78827914
milestones.difference_sec(TS_MILESTONE_SM_START, TS_MILESTONE_DNS_LOOKUP_END),
78837915
milestones.difference_sec(TS_MILESTONE_SM_START, TS_MILESTONE_SERVER_CONNECT),
78847916
milestones.difference_sec(TS_MILESTONE_SM_START, TS_MILESTONE_SERVER_CONNECT_END),
7917+
milestones.difference_sec(TS_MILESTONE_SM_START, TS_MILESTONE_SERVER_TLS_HANDSHAKE_END),
78857918
milestones.difference_sec(TS_MILESTONE_SM_START, TS_MILESTONE_SERVER_FIRST_READ),
78867919
milestones.difference_sec(TS_MILESTONE_SM_START, TS_MILESTONE_SERVER_READ_HEADER_DONE),
78877920
milestones.difference_sec(TS_MILESTONE_SM_START, TS_MILESTONE_SERVER_CLOSE),

src/proxy/logging/LogField.cc

Lines changed: 30 additions & 24 deletions
Original file line numberDiff line numberDiff line change
@@ -191,30 +191,36 @@ struct milestone {
191191
};
192192

193193
static const milestone milestones[] = {
194-
{"TS_MILESTONE_UA_BEGIN", TS_MILESTONE_UA_BEGIN },
195-
{"TS_MILESTONE_UA_FIRST_READ", TS_MILESTONE_UA_FIRST_READ },
196-
{"TS_MILESTONE_UA_READ_HEADER_DONE", TS_MILESTONE_UA_READ_HEADER_DONE },
197-
{"TS_MILESTONE_UA_BEGIN_WRITE", TS_MILESTONE_UA_BEGIN_WRITE },
198-
{"TS_MILESTONE_UA_CLOSE", TS_MILESTONE_UA_CLOSE },
199-
{"TS_MILESTONE_SERVER_FIRST_CONNECT", TS_MILESTONE_SERVER_FIRST_CONNECT },
200-
{"TS_MILESTONE_SERVER_CONNECT", TS_MILESTONE_SERVER_CONNECT },
201-
{"TS_MILESTONE_SERVER_CONNECT_END", TS_MILESTONE_SERVER_CONNECT_END },
202-
{"TS_MILESTONE_SERVER_BEGIN_WRITE", TS_MILESTONE_SERVER_BEGIN_WRITE },
203-
{"TS_MILESTONE_SERVER_FIRST_READ", TS_MILESTONE_SERVER_FIRST_READ },
204-
{"TS_MILESTONE_SERVER_READ_HEADER_DONE", TS_MILESTONE_SERVER_READ_HEADER_DONE},
205-
{"TS_MILESTONE_SERVER_CLOSE", TS_MILESTONE_SERVER_CLOSE },
206-
{"TS_MILESTONE_CACHE_OPEN_READ_BEGIN", TS_MILESTONE_CACHE_OPEN_READ_BEGIN },
207-
{"TS_MILESTONE_CACHE_OPEN_READ_END", TS_MILESTONE_CACHE_OPEN_READ_END },
208-
{"TS_MILESTONE_CACHE_OPEN_WRITE_BEGIN", TS_MILESTONE_CACHE_OPEN_WRITE_BEGIN },
209-
{"TS_MILESTONE_CACHE_OPEN_WRITE_END", TS_MILESTONE_CACHE_OPEN_WRITE_END },
210-
{"TS_MILESTONE_DNS_LOOKUP_BEGIN", TS_MILESTONE_DNS_LOOKUP_BEGIN },
211-
{"TS_MILESTONE_DNS_LOOKUP_END", TS_MILESTONE_DNS_LOOKUP_END },
212-
{"TS_MILESTONE_SM_START", TS_MILESTONE_SM_START },
213-
{"TS_MILESTONE_SM_FINISH", TS_MILESTONE_SM_FINISH },
214-
{"TS_MILESTONE_PLUGIN_ACTIVE", TS_MILESTONE_PLUGIN_ACTIVE },
215-
{"TS_MILESTONE_PLUGIN_TOTAL", TS_MILESTONE_PLUGIN_TOTAL },
216-
{"TS_MILESTONE_TLS_HANDSHAKE_START", TS_MILESTONE_TLS_HANDSHAKE_START },
217-
{"TS_MILESTONE_TLS_HANDSHAKE_END", TS_MILESTONE_TLS_HANDSHAKE_END },
194+
{"TS_MILESTONE_UA_BEGIN", TS_MILESTONE_UA_BEGIN },
195+
{"TS_MILESTONE_UA_FIRST_READ", TS_MILESTONE_UA_FIRST_READ },
196+
{"TS_MILESTONE_UA_READ_HEADER_DONE", TS_MILESTONE_UA_READ_HEADER_DONE },
197+
{"TS_MILESTONE_UA_BEGIN_WRITE", TS_MILESTONE_UA_BEGIN_WRITE },
198+
{"TS_MILESTONE_UA_CLOSE", TS_MILESTONE_UA_CLOSE },
199+
{"TS_MILESTONE_SERVER_FIRST_CONNECT", TS_MILESTONE_SERVER_FIRST_CONNECT },
200+
{"TS_MILESTONE_SERVER_CONNECT", TS_MILESTONE_SERVER_CONNECT },
201+
{"TS_MILESTONE_SERVER_CONNECT_END", TS_MILESTONE_SERVER_CONNECT_END },
202+
{"TS_MILESTONE_SERVER_BEGIN_WRITE", TS_MILESTONE_SERVER_BEGIN_WRITE },
203+
{"TS_MILESTONE_SERVER_FIRST_READ", TS_MILESTONE_SERVER_FIRST_READ },
204+
{"TS_MILESTONE_SERVER_READ_HEADER_DONE", TS_MILESTONE_SERVER_READ_HEADER_DONE },
205+
{"TS_MILESTONE_SERVER_CLOSE", TS_MILESTONE_SERVER_CLOSE },
206+
{"TS_MILESTONE_CACHE_OPEN_READ_BEGIN", TS_MILESTONE_CACHE_OPEN_READ_BEGIN },
207+
{"TS_MILESTONE_CACHE_OPEN_READ_END", TS_MILESTONE_CACHE_OPEN_READ_END },
208+
{"TS_MILESTONE_CACHE_OPEN_WRITE_BEGIN", TS_MILESTONE_CACHE_OPEN_WRITE_BEGIN },
209+
{"TS_MILESTONE_CACHE_OPEN_WRITE_END", TS_MILESTONE_CACHE_OPEN_WRITE_END },
210+
{"TS_MILESTONE_DNS_LOOKUP_BEGIN", TS_MILESTONE_DNS_LOOKUP_BEGIN },
211+
{"TS_MILESTONE_DNS_LOOKUP_END", TS_MILESTONE_DNS_LOOKUP_END },
212+
{"TS_MILESTONE_SM_START", TS_MILESTONE_SM_START },
213+
{"TS_MILESTONE_SM_FINISH", TS_MILESTONE_SM_FINISH },
214+
{"TS_MILESTONE_PLUGIN_ACTIVE", TS_MILESTONE_PLUGIN_ACTIVE },
215+
{"TS_MILESTONE_PLUGIN_TOTAL", TS_MILESTONE_PLUGIN_TOTAL },
216+
{"TS_MILESTONE_TLS_HANDSHAKE_START",
217+
TS_MILESTONE_TLS_HANDSHAKE_START }, // RENAME in ATS 11 - this is the client-side TLS handshake
218+
{"TS_MILESTONE_TLS_HANDSHAKE_END", TS_MILESTONE_TLS_HANDSHAKE_END }, // RENAME in ATS 11 - this is the client-side TLS handshake
219+
{"TS_MILESTONE_SERVER_TLS_HANDSHAKE_START", TS_MILESTONE_SERVER_TLS_HANDSHAKE_START},
220+
{"TS_MILESTONE_SERVER_TLS_HANDSHAKE_END", TS_MILESTONE_SERVER_TLS_HANDSHAKE_END },
221+
// TODO: Add these in ATS 11, remove TLS_HANDSHAKE_* above
222+
// {"TS_MILESTONE_UA_TLS_HANDSHAKE_START", TS_MILESTONE_UA_TLS_HANDSHAKE_START },
223+
// {"TS_MILESTONE_UA_TLS_HANDSHAKE_END", TS_MILESTONE_UA_TLS_HANDSHAKE_END },
218224
};
219225

220226
void

tools/slow_log_report.pl

Lines changed: 8 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -41,10 +41,12 @@ ($)
4141
printf("%25s %10s %10s %10s %10s %10s %10s %10s %10s\n",
4242
'key', 'total', 'count', 'mean', 'median', '95th', '99th', 'min', 'max');
4343
foreach my $key (
44-
'tls_handshake', 'ua_begin', 'ua_first_read', 'ua_read_header_done', 'cache_open_read_begin',
45-
'cache_open_read_end', 'cache_open_write_begin', 'cache_open_write_end', 'dns_lookup_begin',
46-
'dns_lookup_end', 'server_connect', 'server_connect_end', 'server_first_read',
47-
'server_read_header_done', 'server_close', 'ua_close', 'sm_finish', 'plugin_active', 'plugin_total'
44+
'tls_handshake', # TODO ATS 11: remove once old log format is no longer supported
45+
'ua_tls_handshake', 'ua_begin', 'ua_first_read', 'ua_read_header_done',
46+
'cache_open_read_begin', 'cache_open_read_end', 'cache_open_write_begin', 'cache_open_write_end',
47+
'dns_lookup_begin', 'dns_lookup_end', 'server_connect', 'server_connect_end', 'server_tls_handshake',
48+
'server_first_read', 'server_read_header_done', 'server_close', 'ua_close', 'sm_finish',
49+
'plugin_active', 'plugin_total'
4850
)
4951
{
5052

@@ -78,7 +80,8 @@ ($)
7880
s/unique id/unique_id/;
7981
s/server state/server_state/;
8082
s/client state/client_state/;
81-
if (m|Slow Request: .+ (tls_handshake: .+)|) {
83+
# TODO ATS 11: remove 'tls_handshake' match once old log format is no longer supported
84+
if (m|Slow Request: .+ ((?:ua_)?tls_handshake: .+)|) {
8285
my %data = split(/: | /, $1);
8386
foreach my $key (keys %data) {
8487
next if (!defined $data{$key});

0 commit comments

Comments
 (0)