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);
+    }
+}