Collect timings related with TLS handshake

core/src/main/java/com/linecorp/armeria/client/HttpChannelPool.java

@@ -72,6 +72,7 @@
 import io.netty.handler.proxy.Socks4ProxyHandler;
 import io.netty.handler.proxy.Socks5ProxyHandler;
 import io.netty.handler.ssl.SslContext;
+import io.netty.util.AttributeKey;
 import io.netty.util.concurrent.Future;
 import io.netty.util.concurrent.Promise;
 import reactor.core.scheduler.NonBlocking;
@@ -81,6 +82,9 @@ final class HttpChannelPool implements AsyncCloseable {
  private static final Logger logger = LoggerFactory.getLogger(HttpChannelPool.class);
  private static final Channel[] EMPTY_CHANNELS = new Channel[0];
 
+ static final AttributeKey<ClientConnectionTimingsBuilder> TIMINGS_BUILDER_KEY =
+ AttributeKey.valueOf(HttpChannelPool.class, "TIMINGS_BUILDER_KEY");
+
  private final HttpClientFactory clientFactory;
  private final EventLoop eventLoop;
  private final AsyncCloseableSupport closeable = AsyncCloseableSupport.of(this::closeAsync);
@@ -350,7 +354,7 @@ private void connect(SessionProtocol desiredProtocol, SerializationFormat serial
 
  // Create a new connection.
  final Promise<Channel> sessionPromise = eventLoop.newPromise();
- connect(remoteAddress, desiredProtocol, serializationFormat, key, sessionPromise);
+ connect(remoteAddress, desiredProtocol, serializationFormat, key, sessionPromise, timingsBuilder);
 
  if (sessionPromise.isDone()) {
  notifyConnect(desiredProtocol, key, sessionPromise, promise, timingsBuilder);
@@ -371,8 +375,8 @@ private void connect(SessionProtocol desiredProtocol, SerializationFormat serial
  */
  void connect(SocketAddress remoteAddress, SessionProtocol desiredProtocol,
  SerializationFormat serializationFormat,
- PoolKey poolKey, Promise<Channel> sessionPromise) {
-
+ PoolKey poolKey, Promise<Channel> sessionPromise,
+ ClientConnectionTimingsBuilder timingsBuilder) {
  final Bootstrap bootstrap;
  try {
  bootstrap = bootstraps.get(remoteAddress, desiredProtocol, serializationFormat);
@@ -391,6 +395,18 @@ void connect(SocketAddress remoteAddress, SessionProtocol desiredProtocol,
  final Channel channel = registerFuture.channel();
  configureProxy(channel, poolKey.proxyConfig, desiredProtocol);
 
+ if (desiredProtocol.isTls() && timingsBuilder != null) {
+ channel.attr(TIMINGS_BUILDER_KEY).set(timingsBuilder);
+
+ // If TCP fast open is enabled,
+ // Should start the TLS handshake timer after` before connecting the TCP connection.
+ final boolean fastOpen =
+ Boolean.TRUE.equals(channel.config().getOption(ChannelOption.TCP_FASTOPEN_CONNECT));
+ if (fastOpen) {
+ timingsBuilder.tlsHandshakeStart();
+ }
+ }
+
  // should be invoked right before channel.connect() is invoked as defined in javadocs
  clientFactory.channelPipelineCustomizer().accept(channel.pipeline());
 

core/src/main/java/com/linecorp/armeria/client/HttpClientPipelineConfigurator.java

@@ -17,6 +17,7 @@
 package com.linecorp.armeria.client;
 
 import static com.google.common.base.MoreObjects.firstNonNull;
+import static com.linecorp.armeria.client.HttpChannelPool.TIMINGS_BUILDER_KEY;
 import static com.linecorp.armeria.common.SessionProtocol.H1;
 import static com.linecorp.armeria.common.SessionProtocol.H1C;
 import static com.linecorp.armeria.common.SessionProtocol.H2;
@@ -49,6 +50,7 @@
 import com.linecorp.armeria.common.RequestTarget;
 import com.linecorp.armeria.common.SessionProtocol;
 import com.linecorp.armeria.common.annotation.Nullable;
+import com.linecorp.armeria.common.logging.ClientConnectionTimingsBuilder;
 import com.linecorp.armeria.common.util.Exceptions;
 import com.linecorp.armeria.common.util.SystemInfo;
 import com.linecorp.armeria.internal.client.DecodedHttpResponse;
@@ -227,6 +229,16 @@ private void configureAsHttps(Channel ch, SocketAddress remoteAddr) {
  sslHandler = sslCtx.newHandler(ch.alloc());
  }
 
+ p.addLast(new ChannelInboundHandlerAdapter() {
+ @Override
+ public void channelActive(ChannelHandlerContext ctx) throws Exception {
+ final ClientConnectionTimingsBuilder timingsBuilder =
+ ctx.channel().attr(TIMINGS_BUILDER_KEY).get();
+ timingsBuilder.tlsHandshakeStart();
+ super.channelActive(ctx);
+ p.remove(this);
+ }
+ });
  p.addLast(configureSslHandler(sslHandler));
  p.addLast(TrafficLoggingHandler.CLIENT);
  p.addLast(new ChannelInboundHandlerAdapter() {
@@ -240,6 +252,10 @@ public void userEventTriggered(ChannelHandlerContext ctx, Object evt) throws Exc
  return;
  }
 
+ final ClientConnectionTimingsBuilder timingsBuilder =
+ ctx.channel().attr(TIMINGS_BUILDER_KEY).get();
+ timingsBuilder.tlsHandshakeEnd();
+
  final SslHandshakeCompletionEvent handshakeEvent = (SslHandshakeCompletionEvent) evt;
  handshakeFailed = !handshakeEvent.isSuccess();
  if (handshakeFailed) {

core/src/main/java/com/linecorp/armeria/client/HttpSessionHandler.java

@@ -523,9 +523,10 @@ public void channelInactive(ChannelHandlerContext ctx) throws Exception {
  }
  if (proxyDestinationAddress != null) {
  channelPool.connect(proxyDestinationAddress, retryProtocol, serializationFormat,
- poolKey, sessionPromise);
+ poolKey, sessionPromise, null);
  } else {
- channelPool.connect(remoteAddress, retryProtocol, serializationFormat, poolKey, sessionPromise);
+ channelPool.connect(remoteAddress, retryProtocol, serializationFormat, poolKey, sessionPromise,
+ null);
  }
  } else {
  // Fail all pending responses.

core/src/main/java/com/linecorp/armeria/common/logging/ClientConnectionTimings.java

@@ -41,6 +41,8 @@ public final class ClientConnectionTimings {
  private final long dnsResolutionDurationNanos;
  private final long socketConnectStartTimeMicros;
  private final long socketConnectDurationNanos;
+ private final long tlsHandshakeStartTimeMicros;
+ private final long tlsHandshakeDurationNanos;
  private final long pendingAcquisitionStartTimeMicros;
  private final long pendingAcquisitionDurationNanos;
 
@@ -54,13 +56,16 @@ public static ClientConnectionTimingsBuilder builder() {
  ClientConnectionTimings(long connectionAcquisitionStartTimeMicros, long connectionAcquisitionDurationNanos,
  long dnsResolutionStartTimeMicros, long dnsResolutionDurationNanos,
  long socketConnectStartTimeMicros, long socketConnectDurationNanos,
+ long tlsHandshakeStartTimeMicros, long tlsHandshakeDurationNanos,
  long pendingAcquisitionStartTimeMicros, long pendingAcquisitionDurationNanos) {
  this.connectionAcquisitionStartTimeMicros = connectionAcquisitionStartTimeMicros;
  this.connectionAcquisitionDurationNanos = connectionAcquisitionDurationNanos;
  this.dnsResolutionStartTimeMicros = dnsResolutionStartTimeMicros;
  this.dnsResolutionDurationNanos = dnsResolutionDurationNanos;
  this.socketConnectStartTimeMicros = socketConnectStartTimeMicros;
  this.socketConnectDurationNanos = socketConnectDurationNanos;
+ this.tlsHandshakeStartTimeMicros = tlsHandshakeStartTimeMicros;
+ this.tlsHandshakeDurationNanos = tlsHandshakeDurationNanos;
  this.pendingAcquisitionStartTimeMicros = pendingAcquisitionStartTimeMicros;
  this.pendingAcquisitionDurationNanos = pendingAcquisitionDurationNanos;
  }
@@ -88,6 +93,36 @@ public long connectionAcquisitionDurationNanos() {
  return connectionAcquisitionDurationNanos;
  }
 
+ /**
+ * Returns the time when the client started to TLS handshake, in microseconds since the epoch.
+ *
+ * @return the start time, or {@code -1} if there was no action to TLS handshake.
+ */
+ public long tlsHandshakeStartTimeMicros() {
+ return tlsHandshakeStartTimeMicros;
+ }
+
+ /**
+ * Returns the time when the client started to TLS handshake, in milliseconds since the epoch.
+ *
+ * @return the start time, or {@code -1} if there was no action to TLS handshake.
+ */
+ public long tlsHandshakeStartTimeMillis() {
+ if (tlsHandshakeStartTimeMicros >= 0) {
+ return TimeUnit.MICROSECONDS.toMillis(tlsHandshakeStartTimeMicros);
+ }
+ return -1;
+ }
+
+ /**
+ * Returns the duration which was taken to TLS handshake, in nanoseconds.
+ *
+ * @return the duration, or {@code -1} if there was no action to TLS handshake.
+ */
+ public long tlsHandshakeDurationNanos() {
+ return tlsHandshakeDurationNanos;
+ }
+
  /**
  * Returns the time when the client started to resolve a domain name, in microseconds since the epoch.
  *
@@ -203,6 +238,14 @@ public String toString() {
  buf.append(", socketConnectDuration=");
  TextFormatter.appendElapsed(buf, socketConnectDurationNanos);
  }
+
+ if (tlsHandshakeDurationNanos >= 0) {
+ buf.append(", tlsHandshakeStartTime=");
+ TextFormatter.appendEpochMicros(buf, tlsHandshakeStartTimeMicros);
+ buf.append(", tlsHandshakeDuration=");
+ TextFormatter.appendElapsed(buf, tlsHandshakeDurationNanos);
+ }
+
  if (pendingAcquisitionDurationNanos >= 0) {
  buf.append(", pendingAcquisitionStartTime=");
  TextFormatter.appendEpochMicros(buf, pendingAcquisitionStartTimeMicros);

core/src/main/java/com/linecorp/armeria/common/logging/ClientConnectionTimingsBuilder.java

@@ -32,6 +32,10 @@ public final class ClientConnectionTimingsBuilder {
 
  private final long connectionAcquisitionStartTimeMicros;
  private final long connectionAcquisitionStartNanos;
+ private long tlsHandshakeStartTimeMicros;
+ private long tlsHandshakeStartNanos;
+ private long tlsHandshakeEndNanos;
+ private boolean tlsHandshakeEndSet;
  private long dnsResolutionEndNanos;
  private boolean dnsResolutionEndSet;
 
@@ -84,6 +88,31 @@ public ClientConnectionTimingsBuilder socketConnectEnd() {
  return this;
  }
 
+ /**
+ * Sets the time when the client started to TLS handshake to a remote peer.
+ */
+ public ClientConnectionTimingsBuilder tlsHandshakeStart() {
+ final boolean alreadySet = tlsHandshakeStartTimeMicros > 0;
+ if (!alreadySet) {
+ tlsHandshakeStartTimeMicros = SystemInfo.currentTimeMicros();
+ tlsHandshakeStartNanos = System.nanoTime();
+ }
+ return this;
+ }
+
+ /**
+ * Sets the time when the client ended to TLS handshake to a remote peer.
+ *
+ * @throws IllegalStateException if {@link #tlsHandshakeStart()} is not invoked before calling this.
+ */
+ public ClientConnectionTimingsBuilder tlsHandshakeEnd() {
+ checkState(tlsHandshakeStartTimeMicros > 0, "tlsHandshakeStart() is not called yet.");
+ checkState(!tlsHandshakeEndSet, "tlsHandshakeEnd() is already called.");
+ tlsHandshakeEndNanos = System.nanoTime();
+ tlsHandshakeEndSet = true;
+ return this;
+ }
+
  /**
  * Sets the time when the client started to wait for the completion of an existing connection attempt
  * in order to use one connection for HTTP/2.
@@ -127,6 +156,8 @@ public ClientConnectionTimings build() {
  dnsResolutionEndSet ? dnsResolutionEndNanos - connectionAcquisitionStartNanos : -1,
  socketConnectEndSet ? socketConnectStartTimeMicros : -1,
  socketConnectEndSet ? socketConnectEndNanos - socketConnectStartNanos : -1,
+ tlsHandshakeEndSet ? tlsHandshakeStartTimeMicros : -1,
+ tlsHandshakeEndSet ? tlsHandshakeEndNanos - tlsHandshakeStartNanos : -1,
  pendingAcquisitionEndSet ? pendingAcquisitionStartTimeMicros : -1,
  pendingAcquisitionEndSet ? pendingAcquisitionEndNanos - pendingAcquisitionStartNanos : -1);
  }

core/src/test/java/com/linecorp/armeria/client/TlsHandshakeTimingTest.java

@@ -0,0 +1,113 @@
+/*
+ * Copyright 2024 LINE Corporation
+ *
+ * LINE Corporation licenses this file to you under the Apache License,
+ * version 2.0 (the "License"); you may not use this file except in compliance
+ * with the License. You may obtain a copy of the License at:
+ *
+ * https://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
+ * WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
+ * License for the specific language governing permissions and limitations
+ * under the License.
+ */
+
+package com.linecorp.armeria.client;
+
+import static org.assertj.core.api.Assertions.assertThat;
+
+import java.util.concurrent.atomic.AtomicReference;
+
+import org.junit.jupiter.api.Test;
+import org.junit.jupiter.api.extension.RegisterExtension;
+
+import com.linecorp.armeria.common.AggregatedHttpResponse;
+import com.linecorp.armeria.common.HttpResponse;
+import com.linecorp.armeria.common.logging.ClientConnectionTimings;
+import com.linecorp.armeria.common.logging.RequestLogProperty;
+import com.linecorp.armeria.server.ServerBuilder;
+import com.linecorp.armeria.testing.junit5.server.ServerExtension;
+
+import io.netty.channel.ChannelOption;
+
+public class TlsHandshakeTimingTest {
+
+ @RegisterExtension
+ static ServerExtension server = new ServerExtension() {
+ @Override
+ protected void configure(ServerBuilder sb) {
+ sb.http(0);
+ sb.https(0);
+ sb.tlsSelfSigned();
+ sb.service("/", (ctx, req) -> HttpResponse.of(200));
+ }
+ };
+
+ @Test
+ void httpsServerConnectionWithTlsSelfSigned() {
+ final AtomicReference<ClientConnectionTimings> timingsHolder = new AtomicReference<>();
+ try (ClientFactory clientFactory = ClientFactory.builder().tlsNoVerify().build()) {
+ final AggregatedHttpResponse res =
+ WebClient.builder(server.httpsUri())
+ .factory(clientFactory)
+ .decorator((delegate, ctx, req) -> {
+ ctx.log().whenAvailable(RequestLogProperty.SESSION)
+ .thenAccept(log -> timingsHolder.set(log.connectionTimings()));
+ return delegate.execute(ctx, req);
+ })
+ .build()
+ .blocking()
+ .get("/");
+ assertThat(res.status().code()).isEqualTo(200);
+ assertThat(timingsHolder.get().tlsHandshakeStartTimeMicros()).isPositive();
+ assertThat(timingsHolder.get().tlsHandshakeStartTimeMillis()).isPositive();
+ assertThat(timingsHolder.get().tlsHandshakeDurationNanos()).isPositive();
+ }
+ }
+
+ @Test
+ void httpsServerConnectionWithTlsSelfSignedByTFOOption() {
+ final AtomicReference<ClientConnectionTimings> timingsHolder = new AtomicReference<>();
+ try (ClientFactory clientFactory = ClientFactory.builder()
+ .tlsNoVerify()
+ .channelOption(ChannelOption.TCP_FASTOPEN_CONNECT, true)
+ .build()) {
+ final AggregatedHttpResponse res =
+ WebClient.builder(server.httpsUri())
+ .factory(clientFactory)
+ .decorator((delegate, ctx, req) -> {
+ ctx.log().whenAvailable(RequestLogProperty.SESSION)
+ .thenAccept(log -> timingsHolder.set(log.connectionTimings()));
+ return delegate.execute(ctx, req);
+ })
+ .build()
+ .blocking()
+ .get("/");
+ assertThat(res.status().code()).isEqualTo(200);
+ assertThat(timingsHolder.get().tlsHandshakeStartTimeMicros()).isPositive();
+ assertThat(timingsHolder.get().tlsHandshakeStartTimeMillis()).isPositive();
+ assertThat(timingsHolder.get().tlsHandshakeDurationNanos()).isPositive();
+ }
+ }
+
+ @Test
+ void serverConnectionWithoutTls() {
+ final AtomicReference<ClientConnectionTimings> timingsHolder = new AtomicReference<>();
+ final AggregatedHttpResponse res =
+ WebClient.builder(server.httpUri())
+ .decorator((delegate, ctx, req) -> {
+ ctx.log().whenAvailable(RequestLogProperty.SESSION)
+ .thenAccept(log -> timingsHolder.set(log.connectionTimings()));
+ return delegate.execute(ctx, req);
+ })
+ .build()
+ .blocking()
+ .get("/");
+ assertThat(res.status().code()).isEqualTo(200);
+ assertThat(timingsHolder.get().tlsHandshakeStartTimeMicros()).isEqualTo(-1);
+ assertThat(timingsHolder.get().tlsHandshakeStartTimeMillis()).isEqualTo(-1);
+ assertThat(timingsHolder.get().tlsHandshakeDurationNanos()).isEqualTo(-1);
+ }
+}