You are viewing a plain text version of this content. The canonical link for it is here.
Posted to github@trafficserver.apache.org by "bryancall (via GitHub)" <gi...@apache.org> on 2026/02/05 19:41:32 UTC
[PR] Add: Server-side TLS handshake milestones and timing fixes [trafficserver]
bryancall opened a new pull request, #12860:
URL: https://github.com/apache/trafficserver/pull/12860
## Description
Add `TS_MILESTONE_SERVER_TLS_HANDSHAKE_START` and `TS_MILESTONE_SERVER_TLS_HANDSHAKE_END` milestones to capture origin-side TLS handshake timing. Previously, only client-side TLS timing was available via `TS_MILESTONE_TLS_HANDSHAKE_START/END`, making it impossible to measure origin TLS handshake overhead in the slow log or via the milestone API.
## Changes
### New server-side TLS milestones (commit 1)
- Add `TS_MILESTONE_SERVER_TLS_HANDSHAKE_START/END` enum values in `apidefs.h.in` (ABI compatible — appended before `TS_MILESTONE_LAST_ENTRY`)
- Capture server TLS timing in `HttpSM::state_http_server_open()` for both the direct (`VC_EVENT_WRITE_COMPLETE`) and multiplexed (`CONNECT_EVENT_TXN`) connection paths
- **Fix**: `SSLNetVConnection::sslClientHandShakeEvent()` was recording TLS handshake start time for outbound connections but never calling `_record_tls_handshake_end_time()` — outbound TLS end time was always 0
- Rename slow log field `tls_handshake` → `ua_tls_handshake` for clarity, add new `server_tls_handshake` field in logical position after `server_connect_end`
- Update `LogField.cc` milestone-to-string mappings for custom log fields
- Add Lua plugin milestone constants (`TS_LUA_MILESTONE_SERVER_TLS_HANDSHAKE_START/END`)
- Update `TSHttpTxnMilestoneGet` API documentation
- Update `slow_log_report.pl` to parse new field names
### Fix `difference_msec()` milestone check (commit 2)
- `difference_msec()` only checked if `ms_end == 0` (unset) before returning the missing sentinel. If `ms_start` was unset but `ms_end` was set, the subtraction would produce a garbage value. Now checks both `ms_start` and `ms_end` for 0.
## Behavior Notes
- When no server TLS handshake occurs (non-TLS origin, connection reuse), the milestones remain 0 and the slow log reports `-0.001` (the "missing" sentinel), consistent with other unset milestones.
- The `tls_handshake` → `ua_tls_handshake` rename is a slow log text change only — it does not affect ABI.
- Existing `TS_MILESTONE_TLS_HANDSHAKE_START/END` enum values and behavior are unchanged.
## Testing
- [x] Build passes (including ASAN build)
- [x] Manual testing with client-side and server-side TLS verified both milestone pairs populate correctly
- [x] `slow_log_report.pl` correctly parses and reports both `ua_tls_handshake` and `server_tls_handshake`
- [x] Verified milestones remain 0 for non-TLS and connection-reuse scenarios
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: github-unsubscribe@trafficserver.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [PR] Add: Server-side TLS handshake milestones and timing fixes [trafficserver]
Posted by "cmcfarlen (via GitHub)" <gi...@apache.org>.
cmcfarlen commented on code in PR #12860:
URL: https://github.com/apache/trafficserver/pull/12860#discussion_r2879070924
##########
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();
+ }
Review Comment:
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?
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: github-unsubscribe@trafficserver.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [PR] Add: Server-side TLS handshake milestones and timing fixes [trafficserver]
Posted by "bryancall (via GitHub)" <gi...@apache.org>.
bryancall commented on code in PR #12860:
URL: https://github.com/apache/trafficserver/pull/12860#discussion_r2879835307
##########
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();
+ }
Review Comment:
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.
##########
src/proxy/http/HttpSM.cc:
##########
@@ -1881,21 +1881,39 @@ 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<PoolableSession *>(data))) {
+ PoolableSession *session = static_cast<PoolableSession *>(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<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();
Review Comment:
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.
##########
src/proxy/http/HttpSM.cc:
##########
@@ -1881,21 +1881,39 @@ 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<PoolableSession *>(data))) {
+ PoolableSession *session = static_cast<PoolableSession *>(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<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
// 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 (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<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();
+ }
Review Comment:
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 is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: github-unsubscribe@trafficserver.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [PR] Add: Server-side TLS handshake milestones and timing fixes [trafficserver]
Posted by "bryancall (via GitHub)" <gi...@apache.org>.
bryancall merged PR #12860:
URL: https://github.com/apache/trafficserver/pull/12860
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: github-unsubscribe@trafficserver.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [PR] Add: Server-side TLS handshake milestones and timing fixes [trafficserver]
Posted by "Copilot (via GitHub)" <gi...@apache.org>.
Copilot commented on code in PR #12860:
URL: https://github.com/apache/trafficserver/pull/12860#discussion_r2770930119
##########
src/proxy/http/HttpSM.cc:
##########
@@ -7834,6 +7853,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),
Review Comment:
The `server_tls_handshake` calculation is inconsistent with `ua_tls_handshake`. The `ua_tls_handshake` field measures the duration of the TLS handshake (END - START), but `server_tls_handshake` measures the time from SM_START to handshake END. For consistency, `server_tls_handshake` should measure the handshake duration like `ua_tls_handshake` does, using `difference_sec(TS_MILESTONE_SERVER_TLS_HANDSHAKE_START, TS_MILESTONE_SERVER_TLS_HANDSHAKE_END)` instead of `difference_sec(TS_MILESTONE_SM_START, TS_MILESTONE_SERVER_TLS_HANDSHAKE_END)`.
```suggestion
milestones.difference_sec(TS_MILESTONE_SERVER_TLS_HANDSHAKE_START, TS_MILESTONE_SERVER_TLS_HANDSHAKE_END),
```
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: github-unsubscribe@trafficserver.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [PR] Add: Server-side TLS handshake milestones and timing fixes [trafficserver]
Posted by "bryancall (via GitHub)" <gi...@apache.org>.
bryancall commented on code in PR #12860:
URL: https://github.com/apache/trafficserver/pull/12860#discussion_r2770937668
##########
src/proxy/http/HttpSM.cc:
##########
@@ -7834,6 +7853,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),
Review Comment:
yeah, I thought about that and the only reason the ua tls handshake is recorded that way is because it happens before the sm start
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: github-unsubscribe@trafficserver.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [PR] Add: Server-side TLS handshake milestones and timing fixes [trafficserver]
Posted by "cmcfarlen (via GitHub)" <gi...@apache.org>.
cmcfarlen commented on code in PR #12860:
URL: https://github.com/apache/trafficserver/pull/12860#discussion_r2879100876
##########
src/proxy/http/HttpSM.cc:
##########
@@ -1881,21 +1881,39 @@ 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<PoolableSession *>(data))) {
+ PoolableSession *session = static_cast<PoolableSession *>(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<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();
Review Comment:
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.
##########
src/proxy/http/HttpSM.cc:
##########
@@ -1881,21 +1881,39 @@ 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<PoolableSession *>(data))) {
+ PoolableSession *session = static_cast<PoolableSession *>(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<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
// 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 (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<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();
+ }
Review Comment:
Why are these set again?
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: github-unsubscribe@trafficserver.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [PR] Add: Server-side TLS handshake milestones and timing fixes [trafficserver]
Posted by "bryancall (via GitHub)" <gi...@apache.org>.
bryancall commented on PR #12860:
URL: https://github.com/apache/trafficserver/pull/12860#issuecomment-3999749252
[approve ci autest 1]
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: github-unsubscribe@trafficserver.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [PR] Add: Server-side TLS handshake milestones and timing fixes [trafficserver]
Posted by "bryancall (via GitHub)" <gi...@apache.org>.
bryancall commented on code in PR #12860:
URL: https://github.com/apache/trafficserver/pull/12860#discussion_r2770937668
##########
src/proxy/http/HttpSM.cc:
##########
@@ -7834,6 +7853,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),
Review Comment:
Yes, I thought about that and the only reason the ua tls handshake is recorded that way is because it happens before the sm start.
The other thought I had was to use the ua tls handshake start as the "start" if it is set instead of using sm start.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: github-unsubscribe@trafficserver.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org