diff --git a/Sources/AsyncHTTPClient/AsyncAwait/HTTPClient+execute.swift b/Sources/AsyncHTTPClient/AsyncAwait/HTTPClient+execute.swift index 8fc0b3759..0d239cb96 100644 --- a/Sources/AsyncHTTPClient/AsyncAwait/HTTPClient+execute.swift +++ b/Sources/AsyncHTTPClient/AsyncAwait/HTTPClient+execute.swift @@ -13,6 +13,7 @@ //===----------------------------------------------------------------------===// import Logging +import NIOConcurrencyHelpers import NIOCore import NIOHTTP1 import Tracing @@ -46,7 +47,40 @@ extension HTTPClient { request, deadline: deadline, logger: logger ?? Self.loggingDisabled, - redirectMode: self.configuration.redirectConfiguration.mode + redirectMode: self.configuration.redirectConfiguration.mode, + metricsHandler: nil + ) + } + } + + /// Execute arbitrary HTTP requests and receive the timing and connection information of every transaction. + /// + /// - Parameters: + /// - request: HTTP request to execute. + /// - deadline: Point in time by which the request must complete. + /// - logger: The logger to use for this request. + /// - metrics: Called once per HTTP transaction, i.e. once per followed redirect plus once for the final response. + /// The calls are made in order and may happen on any thread. Each call happens when the transaction ended, + /// which for the last one can be after this method returned, because the response body is still being streamed. + /// A transaction that fails is reported as well, with ``HTTPClientTransactionMetrics/error`` set. + /// + /// - warning: This method may violates Structured Concurrency because it returns a `HTTPClientResponse` that needs to be + /// streamed by the user. This means the request, the connection and other resources are still alive when the request returns. + /// + /// - Returns: The response to the request. Note that the `body` of the response may not yet have been fully received. + public func execute( + _ request: HTTPClientRequest, + deadline: NIODeadline, + logger: Logger? = nil, + metrics: @escaping @Sendable (HTTPClientTransactionMetrics) -> Void + ) async throws -> HTTPClientResponse { + try await withRequestSpan(request) { + try await self.executeAndFollowRedirectsIfNeeded( + request, + deadline: deadline, + logger: logger ?? Self.loggingDisabled, + redirectMode: self.configuration.redirectConfiguration.mode, + metricsHandler: metrics ) } } @@ -78,6 +112,34 @@ extension HTTPClient { logger: logger ) } + + /// Execute arbitrary HTTP requests and receive the timing and connection information of every transaction. + /// + /// See ``execute(_:deadline:logger:metrics:)`` for when and how often `metrics` is called. + /// + /// - Parameters: + /// - request: HTTP request to execute. + /// - timeout: time the the request has to complete. + /// - logger: The logger to use for this request. + /// - metrics: Called once per HTTP transaction. + /// + /// - warning: This method may violates Structured Concurrency because it returns a `HTTPClientResponse` that needs to be + /// streamed by the user. This means the request, the connection and other resources are still alive when the request returns. + /// + /// - Returns: The response to the request. Note that the `body` of the response may not yet have been fully received. + public func execute( + _ request: HTTPClientRequest, + timeout: TimeAmount, + logger: Logger? = nil, + metrics: @escaping @Sendable (HTTPClientTransactionMetrics) -> Void + ) async throws -> HTTPClientResponse { + try await self.execute( + request, + deadline: .now() + timeout, + logger: logger, + metrics: metrics + ) + } } @available(macOS 10.15, iOS 13.0, watchOS 6.0, tvOS 13.0, *) @@ -88,7 +150,8 @@ extension HTTPClient { _ request: HTTPClientRequest, deadline: NIODeadline, logger: Logger, - redirectMode: HTTPClient.Configuration.RedirectConfiguration.Mode + redirectMode: HTTPClient.Configuration.RedirectConfiguration.Mode, + metricsHandler: (@Sendable (HTTPClientTransactionMetrics) -> Void)? ) async throws -> HTTPClientResponse { var currentRequest = request var currentRedirectState = RedirectState(redirectMode, initialURL: request.url) @@ -97,6 +160,8 @@ extension HTTPClient { // this loop is there to follow potential redirects while true { + let hopMetricsHandler = metricsHandler.map { HTTPHopMetricsHandler($0) } + let preparedRequest = try HTTPClientRequest.Prepared( currentRequest, @@ -105,7 +170,12 @@ extension HTTPClient { tracing: self.configuration.tracing ) let response = try await { - var response = try await self.executeCancellable(preparedRequest, deadline: deadline, logger: logger) + var response = try await self.executeCancellable( + preparedRequest, + deadline: deadline, + logger: logger, + metricsHandler: hopMetricsHandler?.transactionHandler + ) history.append( .init( @@ -217,6 +287,11 @@ extension HTTPClient { currentRequest = newRequest } } + + // Only the paths that follow a redirect get here. `response` must stay alive until the + // flag is set, otherwise its body could be dropped, and the hop cancelled, before. + hopMetricsHandler?.redirectWillBeFollowed() + withExtendedLifetime(response) {} } } @@ -225,7 +300,8 @@ extension HTTPClient { private func executeCancellable( _ request: HTTPClientRequest.Prepared, deadline: NIODeadline, - logger: Logger + logger: Logger, + metricsHandler: (@Sendable (HTTPClientTransactionMetrics) -> Void)? ) async throws -> HTTPClientResponse { let cancelHandler = TransactionCancelHandler() @@ -246,7 +322,8 @@ extension HTTPClient { logger: logger, connectionDeadline: .now() + (self.configuration.timeout.connectionCreationTimeout), preferredEventLoop: eventLoop, - responseContinuation: continuation + responseContinuation: continuation, + metricsHandler: metricsHandler ) cancelHandler.registerTransaction(transaction) diff --git a/Sources/AsyncHTTPClient/AsyncAwait/Transaction.swift b/Sources/AsyncHTTPClient/AsyncAwait/Transaction.swift index 0b62116cb..f59ae3295 100644 --- a/Sources/AsyncHTTPClient/AsyncAwait/Transaction.swift +++ b/Sources/AsyncHTTPClient/AsyncAwait/Transaction.swift @@ -36,13 +36,17 @@ final class Transaction: private let state: NIOLockedValueBox + private let metrics: NIOLockedValueBox + private let metricsHandler: (@Sendable (HTTPClientTransactionMetrics) -> Void)? + init( request: HTTPClientRequest.Prepared, requestOptions: RequestOptions, logger: Logger, connectionDeadline: NIODeadline, preferredEventLoop: EventLoop, - responseContinuation: CheckedContinuation + responseContinuation: CheckedContinuation, + metricsHandler: (@Sendable (HTTPClientTransactionMetrics) -> Void)? = nil ) { self.request = request self.requestOptions = requestOptions @@ -50,6 +54,20 @@ final class Transaction: self.connectionDeadline = connectionDeadline self.preferredEventLoop = preferredEventLoop self.state = NIOLockedValueBox(StateMachine(responseContinuation)) + self.metrics = NIOLockedValueBox(HTTPRequestMetricsRecorder(url: request.url)) + self.metricsHandler = metricsHandler + } + + /// Hands the recorded metrics to the handler. Only the first call has an effect, so every path + /// that ends the transaction can call this without coordinating with the others. + private func deliverMetrics(error: (any Error)?) { + guard let metricsHandler = self.metricsHandler else { + return + } + let metrics = self.metrics.withLockedValue { $0.finish(error: error) } + if let metrics { + metricsHandler(metrics) + } } func cancel() { @@ -67,6 +85,7 @@ final class Transaction: switch writeAction { case .writeAndWait(let executor), .writeAndContinue(let executor): + self.metrics.withLockedValue { $0.requestBodyBytesWritten(byteBuffer.readableBytes) } executor.writeRequestBodyPart(.byteBuffer(byteBuffer), request: self, promise: nil) case .fail: @@ -114,6 +133,7 @@ final class Transaction: switch action { case .writeAndContinue(let executor): + self.metrics.withLockedValue { $0.requestBodyBytesWritten(part.readableBytes) } executor.writeRequestBodyPart(.byteBuffer(part), request: self, promise: nil) case .writeAndWait: // Holding the lock here *should* be safe but because of a bug in the runtime @@ -135,9 +155,11 @@ final class Transaction: switch action { case .writeAndContinue(let executor): + self.metrics.withLockedValue { $0.requestBodyBytesWritten(part.readableBytes) } executor.writeRequestBodyPart(.byteBuffer(part), request: self, promise: nil) continuation.resume() case .writeAndWait(let executor): + self.metrics.withLockedValue { $0.requestBodyBytesWritten(part.readableBytes) } executor.writeRequestBodyPart(.byteBuffer(part), request: self, promise: nil) case .fail: continuation.resume(throwing: BreakTheWriteLoopError()) @@ -179,6 +201,8 @@ extension Transaction: HTTPSchedulableRequest { var requiredEventLoop: EventLoop? { nil } func requestWasQueued(_ scheduler: HTTPRequestScheduler) { + let time = NIODeadline.now() + self.metrics.withLockedValue { $0.requestWasQueued(at: time) } self.state.withLockedValue { state in state.requestWasQueued(scheduler) } @@ -193,6 +217,10 @@ extension Transaction: HTTPExecutableRequest { // MARK: Request + func connectionAcquired(_ info: HTTPConnectionMetricsInfo) { + self.metrics.withLockedValue { $0.connectionAcquired(info) } + } + func willExecuteRequest(_ executor: HTTPRequestExecutor) { let action = self.state.withLockedValue { state in state.willExecuteRequest(executor) @@ -203,6 +231,7 @@ extension Transaction: HTTPExecutableRequest { executor.cancelRequest(self) case .cancelAndFail(let executor, let continuation, with: let error): executor.cancelRequest(self) + self.deliverMetrics(error: error) continuation.resume(throwing: error) case .none: break @@ -210,7 +239,16 @@ extension Transaction: HTTPExecutableRequest { } func requestHeadSent() { - // protocol requirement. Intentionally not needed. + // A request without a body is complete as soon as its head was sent, `requestBodyStreamSent` + // is not called for it. + let isComplete = self.requestFramingMetadata.body == .fixedSize(0) + let time = NIODeadline.now() + self.metrics.withLockedValue { + $0.requestHeadSent() + if isComplete { + $0.requestEnded(at: time) + } + } } func resumeRequestBodyStream() { @@ -256,6 +294,9 @@ extension Transaction: HTTPExecutableRequest { } func requestBodyStreamSent() { + let time = NIODeadline.now() + self.metrics.withLockedValue { $0.requestEnded(at: time) } + let action = self.state.withLockedValue { state in state.requestBodyStreamSent() } @@ -271,6 +312,9 @@ extension Transaction: HTTPExecutableRequest { // MARK: Response func receiveResponseHead(_ head: HTTPResponseHead) { + let time = NIODeadline.now() + self.metrics.withLockedValue { $0.responseHeadReceived(at: time) } + let action = self.state.withLockedValue { state in state.receiveResponseHead(head, delegate: self) } @@ -294,6 +338,9 @@ extension Transaction: HTTPExecutableRequest { } func receiveResponseBodyParts(_ buffer: CircularBuffer) { + let bytes = buffer.reduce(0) { $0 + $1.readableBytes } + self.metrics.withLockedValue { $0.responseBodyBytesDelivered(bytes) } + let action = self.state.withLockedValue { state in state.receiveResponseBodyParts(buffer) } @@ -311,11 +358,19 @@ extension Transaction: HTTPExecutableRequest { } func receiveResponseEnd(_ buffer: CircularBuffer?, trailers: HTTPHeaders?) { + let time = NIODeadline.now() + let bytes = buffer?.reduce(0) { $0 + $1.readableBytes } ?? 0 + self.metrics.withLockedValue { + $0.responseEnded(at: time) + $0.responseBodyBytesDelivered(bytes) + } + let receiveResponseEndAction = self.state.withLockedValue { state in state.receiveResponseEnd(buffer, trailers: trailers) } switch receiveResponseEndAction { case .finishResponseStream(let source, let finalResponse): + self.deliverMetrics(error: nil) if let finalResponse = finalResponse { _ = source.yield(contentsOf: finalResponse) } @@ -353,22 +408,26 @@ extension Transaction: HTTPExecutableRequest { break case .failResponseHead(let continuation, let error, let scheduler, let executor, let bodyStreamContinuation): - continuation.resume(throwing: error) - bodyStreamContinuation?.resume(throwing: error) scheduler?.cancelRequest(self) // NOTE: scheduler and executor are exclusive here executor?.cancelRequest(self) + self.deliverMetrics(error: error) + continuation.resume(throwing: error) + bodyStreamContinuation?.resume(throwing: error) case .failResponseStream(let source, let error, let executor, let requestBodyStreamContinuation): + executor.cancelRequest(self) + self.deliverMetrics(error: error) source.finish(error) requestBodyStreamContinuation?.resume(throwing: error) - executor.cancelRequest(self) case .failRequestStreamContinuation(let bodyStreamContinuation, let error, let executor): - bodyStreamContinuation.resume(throwing: error) executor.cancelRequest(self) + self.deliverMetrics(error: error) + bodyStreamContinuation.resume(throwing: error) case .cancelExecutor(let executor): executor.cancelRequest(self) + self.deliverMetrics(error: HTTPClientError.cancelled) } } @@ -382,9 +441,10 @@ extension Transaction: HTTPExecutableRequest { private func performDeadlineExceededAction(_ action: StateMachine.DeadlineExceededAction) { switch action { case .cancel(let requestContinuation, let scheduler, let executor, let bodyStreamContinuation): - requestContinuation.resume(throwing: HTTPClientError.deadlineExceeded) scheduler?.cancelRequest(self) executor?.cancelRequest(self) + self.deliverMetrics(error: HTTPClientError.deadlineExceeded) + requestContinuation.resume(throwing: HTTPClientError.deadlineExceeded) bodyStreamContinuation?.resume(throwing: HTTPClientError.deadlineExceeded) case .cancelSchedulerOnly(let scheduler): scheduler.cancelRequest(self) diff --git a/Sources/AsyncHTTPClient/ConnectionPool/HTTP1/HTTP1Connection.swift b/Sources/AsyncHTTPClient/ConnectionPool/HTTP1/HTTP1Connection.swift index 6f64e0407..421aa5b3c 100644 --- a/Sources/AsyncHTTPClient/ConnectionPool/HTTP1/HTTP1Connection.swift +++ b/Sources/AsyncHTTPClient/ConnectionPool/HTTP1/HTTP1Connection.swift @@ -37,16 +37,28 @@ final class HTTP1Connection { private var state: State = .initialized + /// How many requests were handed to this connection so far. Used to tell requests apart that + /// are the first on a connection from those that reuse it. + private var requestsStarted = 0 + + /// How the connection was established. + private let setup: HTTPConnectionSetupRecorder? + + /// What went through the connection so far. Transactions measure what is theirs against it. + private let byteCounters = HTTPByteCounters() + let id: HTTPConnectionPool.Connection.ID init( channel: Channel, connectionID: HTTPConnectionPool.Connection.ID, - delegate: HTTP1ConnectionDelegate + delegate: HTTP1ConnectionDelegate, + setup: HTTPConnectionSetupRecorder? = nil ) { self.channel = channel self.id = connectionID self.delegate = delegate + self.setup = setup } deinit { @@ -60,9 +72,15 @@ final class HTTP1Connection { connectionID: HTTPConnectionPool.Connection.ID, delegate: HTTP1ConnectionDelegate, decompression: HTTPClient.Decompression, - logger: Logger + logger: Logger, + setup: HTTPConnectionSetupRecorder? = nil ) throws -> HTTP1Connection { - let connection = HTTP1Connection(channel: channel, connectionID: connectionID, delegate: delegate) + let connection = HTTP1Connection( + channel: channel, + connectionID: connectionID, + delegate: delegate, + setup: setup + ) try connection.start(decompression: decompression, logger: logger) return connection } @@ -113,6 +131,20 @@ final class HTTP1Connection { return request.fail(ChannelError.ioOnClosedChannel) } + request.connectionAcquired( + HTTPConnectionMetricsInfo( + id: self.id, + negotiatedProtocol: .http1_1, + isReused: self.requestsStarted > 0, + localAddress: self.channel.localAddress, + remoteAddress: self.channel.remoteAddress, + setup: self.setup, + byteCounters: self.byteCounters, + acquiredAt: .now() + ) + ) + self.requestsStarted += 1 + self.channel.pipeline.syncOperations.write(NIOAny(request), promise: nil) } @@ -139,8 +171,10 @@ final class HTTP1Connection { leftOverBytesStrategy: .dropBytes, informationalResponseStrategy: .forward ) + try sync.addHandler(HTTPRawByteCountingHandler(counters: self.byteCounters)) try sync.addHandler(requestEncoder) try sync.addHandler(ByteToMessageHandler(responseDecoder)) + try sync.addHandler(HTTPResponseBodyCountingHandler(counters: self.byteCounters)) if case .enabled(let limit) = decompression { let decompressHandler = NIOHTTPResponseDecompressor(limit: limit) diff --git a/Sources/AsyncHTTPClient/ConnectionPool/HTTP2/HTTP2Connection.swift b/Sources/AsyncHTTPClient/ConnectionPool/HTTP2/HTTP2Connection.swift index 1c24554e2..0d358db04 100644 --- a/Sources/AsyncHTTPClient/ConnectionPool/HTTP2/HTTP2Connection.swift +++ b/Sources/AsyncHTTPClient/ConnectionPool/HTTP2/HTTP2Connection.swift @@ -84,6 +84,13 @@ final class HTTP2Connection { /// we want to close the connection. The channels shall than cancel their currently running /// request. This property must only be accessed from the connections `EventLoop`. private var openStreams = Set() + + /// How many requests were handed to this connection so far. Used to tell requests apart that + /// are the first on a connection from those that reuse it. + private var requestsStarted = 0 + + /// How the connection was established. + private let setup: HTTPConnectionSetupRecorder? let id: HTTPConnectionPool.Connection.ID let decompression: HTTPClient.Decompression let maximumConnectionUses: Int? @@ -99,9 +106,11 @@ final class HTTP2Connection { maximumConnectionUses: Int?, delegate: HTTP2ConnectionDelegate, logger: Logger, - streamChannelDebugInitializer: (@Sendable (Channel) -> EventLoopFuture)? = nil + streamChannelDebugInitializer: (@Sendable (Channel) -> EventLoopFuture)? = nil, + setup: HTTPConnectionSetupRecorder? = nil ) { self.channel = channel + self.setup = setup self.id = connectionID self.decompression = decompression self.maximumConnectionUses = maximumConnectionUses @@ -134,7 +143,8 @@ final class HTTP2Connection { decompression: HTTPClient.Decompression, maximumConnectionUses: Int?, logger: Logger, - streamChannelDebugInitializer: (@Sendable (Channel) -> EventLoopFuture)? = nil + streamChannelDebugInitializer: (@Sendable (Channel) -> EventLoopFuture)? = nil, + setup: HTTPConnectionSetupRecorder? = nil ) -> EventLoopFuture<(HTTP2Connection, Int)>.Isolated { let connection = HTTP2Connection( channel: channel, @@ -143,7 +153,8 @@ final class HTTP2Connection { maximumConnectionUses: maximumConnectionUses, delegate: delegate, logger: logger, - streamChannelDebugInitializer: streamChannelDebugInitializer + streamChannelDebugInitializer: streamChannelDebugInitializer, + setup: setup ) return connection._start0().assumeIsolated().map { maxStreams in @@ -254,6 +265,22 @@ final class HTTP2Connection { preconditionFailure("Invalid state: \(self.state). Sending requests is not allowed before we are started.") case .active: + // Every request has a stream of its own, with counters of its own. + let byteCounters = HTTPByteCounters() + request.connectionAcquired( + HTTPConnectionMetricsInfo( + id: self.id, + negotiatedProtocol: .http2, + isReused: self.requestsStarted > 0, + localAddress: self.channel.localAddress, + remoteAddress: self.channel.remoteAddress, + setup: self.setup, + byteCounters: byteCounters, + acquiredAt: .now() + ) + ) + self.requestsStarted += 1 + let createStreamChannelPromise = self.channel.eventLoop.makePromise(of: Channel.self) let loopBoundSelf = NIOLoopBound(self, eventLoop: self.channel.eventLoop) @@ -274,6 +301,9 @@ final class HTTP2Connection { // Protocol Negotiation (ALPN). For this reason it is safe to fix this to `.https`. let translate = HTTP2FramePayloadToHTTP1ClientCodec(httpProtocol: .https) try channel.pipeline.syncOperations.addHandler(translate) + try channel.pipeline.syncOperations.addHandler( + HTTPResponseBodyCountingHandler(counters: byteCounters) + ) if case .enabled(let limit) = connection.decompression { let decompressHandler = NIOHTTPResponseDecompressor(limit: limit) diff --git a/Sources/AsyncHTTPClient/ConnectionPool/HTTPByteCounters.swift b/Sources/AsyncHTTPClient/ConnectionPool/HTTPByteCounters.swift new file mode 100644 index 000000000..48460982f --- /dev/null +++ b/Sources/AsyncHTTPClient/ConnectionPool/HTTPByteCounters.swift @@ -0,0 +1,92 @@ +//===----------------------------------------------------------------------===// +// +// This source file is part of the AsyncHTTPClient open source project +// +// Copyright (c) 2026 Apple Inc. and the AsyncHTTPClient project authors +// Licensed under Apache License v2.0 +// +// See LICENSE.txt for license information +// See CONTRIBUTORS.txt for the list of AsyncHTTPClient project authors +// +// SPDX-License-Identifier: Apache-2.0 +// +//===----------------------------------------------------------------------===// + +import NIOConcurrencyHelpers +import NIOCore +import NIOHTTP1 + +/// Counts the bytes that go through a connection, or for HTTP/2 through one stream of it. +/// +/// The counters only ever grow. A transaction learns how many bytes were its own by taking a snapshot when it starts and +/// another one when it ends. That is exact for HTTP/1, where a connection carries one transaction at a time. +final class HTTPByteCounters: Sendable { + struct Snapshot: Sendable, Equatable { + /// Bytes written to the connection, with everything the HTTP encoder adds to them. + var sent = 0 + /// Bytes read from the connection, before they are decoded. + var received = 0 + /// Bytes of response bodies as they were decoded off the wire, which is before they are decompressed. + var responseBodyReceived = 0 + } + + private let state = NIOLockedValueBox(Snapshot()) + + func snapshot() -> Snapshot { + self.state.withLockedValue { $0 } + } + + func addSent(_ bytes: Int) { + self.state.withLockedValue { $0.sent += bytes } + } + + func addReceived(_ bytes: Int) { + self.state.withLockedValue { $0.received += bytes } + } + + func addResponseBodyReceived(_ bytes: Int) { + self.state.withLockedValue { $0.responseBodyReceived += bytes } + } +} + +/// Counts the bytes that are written to and read from the connection. It sits right behind the part of the pipeline +/// that deals with the transport, so it sees the HTTP/1 bytes as they are on the wire, without TLS. +final class HTTPRawByteCountingHandler: ChannelDuplexHandler, RemovableChannelHandler { + typealias InboundIn = ByteBuffer + typealias OutboundIn = IOData + + private let counters: HTTPByteCounters + + init(counters: HTTPByteCounters) { + self.counters = counters + } + + func channelRead(context: ChannelHandlerContext, data: NIOAny) { + self.counters.addReceived(self.unwrapInboundIn(data).readableBytes) + context.fireChannelRead(data) + } + + func write(context: ChannelHandlerContext, data: NIOAny, promise: EventLoopPromise?) { + self.counters.addSent(self.unwrapOutboundIn(data).readableBytes) + context.write(data, promise: promise) + } +} + +/// Counts the response body bytes that the HTTP decoder produces. It has to sit before the decompression handler, to +/// count what the server sent and not what the caller gets. +final class HTTPResponseBodyCountingHandler: ChannelInboundHandler { + typealias InboundIn = HTTPClientResponsePart + + private let counters: HTTPByteCounters + + init(counters: HTTPByteCounters) { + self.counters = counters + } + + func channelRead(context: ChannelHandlerContext, data: NIOAny) { + if case .body(let body) = self.unwrapInboundIn(data) { + self.counters.addResponseBodyReceived(body.readableBytes) + } + context.fireChannelRead(data) + } +} diff --git a/Sources/AsyncHTTPClient/ConnectionPool/HTTPConnectionPool+Factory.swift b/Sources/AsyncHTTPClient/ConnectionPool/HTTPConnectionPool+Factory.swift index d940ceebd..8c332cc77 100644 --- a/Sources/AsyncHTTPClient/ConnectionPool/HTTPConnectionPool+Factory.swift +++ b/Sources/AsyncHTTPClient/ConnectionPool/HTTPConnectionPool+Factory.swift @@ -13,6 +13,7 @@ //===----------------------------------------------------------------------===// import Logging +import NIOConcurrencyHelpers import NIOCore import NIOHTTP1 import NIOHTTPCompression @@ -82,6 +83,8 @@ extension HTTPConnectionPool.ConnectionFactory { var logger = logger logger[metadataKey: "ahc-connection-id"] = "\(connectionID)" + let setup = HTTPConnectionSetupRecorder() + let promise = eventLoop.makePromise(of: NegotiatedProtocol.self) promise.futureResult.whenComplete { [logger] result in switch result { @@ -92,7 +95,8 @@ extension HTTPConnectionPool.ConnectionFactory { connectionID: connectionID, delegate: http1ConnectionDelegate, decompression: self.clientConfiguration.decompression, - logger: logger + logger: logger, + setup: setup ) if let connectionDebugInitializer = self.clientConfiguration.http1_1ConnectionDebugInitializer { @@ -121,7 +125,8 @@ extension HTTPConnectionPool.ConnectionFactory { maximumConnectionUses: self.clientConfiguration.maximumUsesPerConnection, logger: logger, streamChannelDebugInitializer: - self.clientConfiguration.http2StreamChannelDebugInitializer + self.clientConfiguration.http2StreamChannelDebugInitializer, + setup: setup ).whenComplete { result in switch result { case .success((let connection, let maximumStreams)): @@ -170,6 +175,7 @@ extension HTTPConnectionPool.ConnectionFactory { deadline: deadline, eventLoop: eventLoop, logger: logger, + setup: setup, promise: promise ) } @@ -185,6 +191,7 @@ extension HTTPConnectionPool.ConnectionFactory { deadline: NIODeadline, eventLoop: EventLoop, logger: Logger, + setup: HTTPConnectionSetupRecorder = HTTPConnectionSetupRecorder(), promise: EventLoopPromise ) { if self.key.scheme.isProxyable, let proxy = self.clientConfiguration.proxy { @@ -197,6 +204,7 @@ extension HTTPConnectionPool.ConnectionFactory { deadline: deadline, eventLoop: eventLoop, logger: logger, + setup: setup, promise: promise ) case .http: @@ -207,6 +215,7 @@ extension HTTPConnectionPool.ConnectionFactory { deadline: deadline, eventLoop: eventLoop, logger: logger, + setup: setup, promise: promise ) } @@ -217,6 +226,7 @@ extension HTTPConnectionPool.ConnectionFactory { deadline: deadline, eventLoop: eventLoop, logger: logger, + setup: setup, promise: promise ) } @@ -228,6 +238,7 @@ extension HTTPConnectionPool.ConnectionFactory { deadline: NIODeadline, eventLoop: EventLoop, logger: Logger, + setup: HTTPConnectionSetupRecorder, promise: EventLoopPromise ) { switch self.key.scheme { @@ -237,6 +248,7 @@ extension HTTPConnectionPool.ConnectionFactory { connectionID: connectionID, deadline: deadline, eventLoop: eventLoop, + setup: setup, promise: promise ) case .https, .httpsUnix: @@ -246,6 +258,7 @@ extension HTTPConnectionPool.ConnectionFactory { deadline: deadline, eventLoop: eventLoop, logger: logger, + setup: setup, promise: promise ) } @@ -256,6 +269,7 @@ extension HTTPConnectionPool.ConnectionFactory { connectionID: HTTPConnectionPool.Connection.ID, deadline: NIODeadline, eventLoop: EventLoop, + setup: HTTPConnectionSetupRecorder, promise: EventLoopPromise ) { precondition(!self.key.scheme.usesTLS, "Unexpected scheme") @@ -264,10 +278,14 @@ extension HTTPConnectionPool.ConnectionFactory { requester: requester, connectionID: connectionID, deadline: deadline, - eventLoop: eventLoop + eventLoop: eventLoop, + setup: setup ) - bootstrap.connect(target: self.key.connectionTarget).map { - .http1_1($0) + setup.markConnectStart() + bootstrap.connect(target: self.key.connectionTarget).map { channel -> NegotiatedProtocol in + setup.markConnectEnd() + Self.recordEstablishmentReport(of: channel, setup: setup) + return .http1_1(channel) }.cascade(to: promise) } catch { promise.fail(error) @@ -281,26 +299,31 @@ extension HTTPConnectionPool.ConnectionFactory { deadline: NIODeadline, eventLoop: EventLoop, logger: Logger, + setup: HTTPConnectionSetupRecorder, promise: EventLoopPromise ) { // A proxy connection starts with a plain text connection to the proxy server. After // the connection has been established with the proxy server, the connection might be // upgraded to TLS before we send our first request. + setup.markProxyConnection() let bootstrap: NIOClientTCPBootstrapProtocol do { bootstrap = try self.makePlainBootstrap( requester: requester, connectionID: connectionID, deadline: deadline, - eventLoop: eventLoop + eventLoop: eventLoop, + setup: setup ) } catch { promise.fail(error) return } + setup.markConnectStart() bootstrap.connect(host: proxy.host, port: proxy.port).whenComplete { result in switch result { case .success(let channel): + Self.recordEstablishmentReport(of: channel, setup: setup) let encoder = HTTPRequestEncoder() let decoder = ByteToMessageHandler(HTTPResponseDecoder(leftOverBytesStrategy: .dropBytes)) let proxyHandler = HTTP1ProxyConnectHandler( @@ -327,7 +350,13 @@ extension HTTPConnectionPool.ConnectionFactory { }.nonisolated() }.nonisolated() }.flatMap { - self.setupTLSInProxyConnectionIfNeeded(channel, deadline: deadline, logger: logger) + setup.markTunnelEstablished() + return self.setupTLSInProxyConnectionIfNeeded( + channel, + deadline: deadline, + logger: logger, + setup: setup + ) }.nonisolated().cascade(to: promise) case .failure(let error): promise.fail(error) @@ -342,26 +371,31 @@ extension HTTPConnectionPool.ConnectionFactory { deadline: NIODeadline, eventLoop: EventLoop, logger: Logger, + setup: HTTPConnectionSetupRecorder, promise: EventLoopPromise ) { // A proxy connection starts with a plain text connection to the proxy server. After // the connection has been established with the proxy server, the connection might be // upgraded to TLS before we send our first request. + setup.markProxyConnection() let bootstrap: NIOClientTCPBootstrapProtocol do { bootstrap = try self.makePlainBootstrap( requester: requester, connectionID: connectionID, deadline: deadline, - eventLoop: eventLoop + eventLoop: eventLoop, + setup: setup ) } catch { promise.fail(error) return } + setup.markConnectStart() bootstrap.connect(host: proxy.host, port: proxy.port).whenComplete { result in switch result { case .success(let channel): + Self.recordEstablishmentReport(of: channel, setup: setup) let socksConnectHandler = SOCKSClientHandler(targetAddress: SOCKSAddress(self.key.connectionTarget)) let socksEventHandler = SOCKSEventsHandler(deadline: deadline) @@ -379,7 +413,13 @@ extension HTTPConnectionPool.ConnectionFactory { channel.pipeline.syncOperations.removeHandler(socksConnectHandler) }.nonisolated() }.flatMap { - self.setupTLSInProxyConnectionIfNeeded(channel, deadline: deadline, logger: logger) + setup.markTunnelEstablished() + return self.setupTLSInProxyConnectionIfNeeded( + channel, + deadline: deadline, + logger: logger, + setup: setup + ) }.nonisolated().cascade(to: promise) case .failure(let error): promise.fail(error) @@ -391,7 +431,8 @@ extension HTTPConnectionPool.ConnectionFactory { private func setupTLSInProxyConnectionIfNeeded( _ channel: Channel, deadline: NIODeadline, - logger: Logger + logger: Logger, + setup: HTTPConnectionSetupRecorder ) -> EventLoopFuture { switch self.key.scheme { case .unix, .httpUnix, .httpsUnix: @@ -424,6 +465,7 @@ extension HTTPConnectionPool.ConnectionFactory { context: sslContext, serverHostname: sslServerHostname ) + setup.markSecureConnectionStart() try channel.pipeline.syncOperations.addHandler(sslHandler) let tlsEventHandler = TLSEventsHandler(deadline: deadline) try channel.pipeline.syncOperations.addHandler(tlsEventHandler) @@ -435,6 +477,8 @@ extension HTTPConnectionPool.ConnectionFactory { return channel.eventLoop.makeFailedFuture(error) } }.flatMap { negotiated -> EventLoopFuture in + setup.markSecureConnectionEnd() + Self.recordTLSInfo(of: channel, setup: setup) do { let sync = channel.pipeline.syncOperations let context = try sync.context(handlerType: TLSEventsHandler.self) @@ -452,7 +496,8 @@ extension HTTPConnectionPool.ConnectionFactory { requester: Requester, connectionID: HTTPConnectionPool.Connection.ID, deadline: NIODeadline, - eventLoop: EventLoop + eventLoop: EventLoop, + setup: HTTPConnectionSetupRecorder ) throws -> NIOClientTCPBootstrapProtocol { if let localAddress = self.key.localAddress, !localAddress.isIPAddress { throw HTTPClientError.invalidLocalAddress @@ -501,11 +546,8 @@ extension HTTPConnectionPool.ConnectionFactory { nioBootstrap .connectTimeout(deadline - NIODeadline.now()) .enableMPTCP(clientConfiguration.enableMultipath) - switch clientConfiguration.dnsResolver.backing { - case .system: - break - case .randomized: - bootstrap = bootstrap.resolver(NIORandomizedDNSResolver(loop: eventLoop)) + if let resolver = self.makeResolver(eventLoop: eventLoop, setup: setup) { + bootstrap = bootstrap.resolver(resolver) } if let localAddress = self.key.localAddress { do { @@ -527,6 +569,7 @@ extension HTTPConnectionPool.ConnectionFactory { deadline: NIODeadline, eventLoop: EventLoop, logger: Logger, + setup: HTTPConnectionSetupRecorder, promise: EventLoopPromise ) { precondition(self.key.scheme.usesTLS, "Unexpected scheme") @@ -535,14 +578,21 @@ extension HTTPConnectionPool.ConnectionFactory { connectionID: connectionID, deadline: deadline, eventLoop: eventLoop, - logger: logger + logger: logger, + setup: setup ) bootstrapFuture.whenComplete { result in switch result { case .success(let bootstrap): + setup.markConnectStart() bootstrap.connect(target: self.key.connectionTarget).flatMap { channel -> EventLoopFuture<(Channel, String?)> in + // With the NIOSSL handler the TLS handshake starts as soon as the connection is up. With the + // Network framework the handshake is already done, `recordEstablishmentReport` corrects that. + setup.markConnectEnd() + setup.markSecureConnectionStart() + Self.recordEstablishmentReport(of: channel, setup: setup) do { // if the channel is closed before flatMap is executed, all ChannelHandler are removed // and TLSEventsHandler is therefore not present either @@ -551,7 +601,11 @@ extension HTTPConnectionPool.ConnectionFactory { // The tlsEstablishedFuture is set as soon as the TLSEventsHandler is in a // pipeline. It is created in TLSEventsHandler's handlerAdded method. return tlsEventHandler.tlsEstablishedFuture!.assumeIsolated().flatMap { negotiated in - channel.pipeline.syncOperations.removeHandler(tlsEventHandler).map { (channel, negotiated) } + setup.markSecureConnectionEnd() + Self.recordTLSInfo(of: channel, setup: setup) + return channel.pipeline.syncOperations.removeHandler(tlsEventHandler).map { + (channel, negotiated) + } }.nonisolated() } catch { assert( @@ -581,7 +635,8 @@ extension HTTPConnectionPool.ConnectionFactory { connectionID: HTTPConnectionPool.Connection.ID, deadline: NIODeadline, eventLoop: EventLoop, - logger: Logger + logger: Logger, + setup: HTTPConnectionSetupRecorder ) -> EventLoopFuture { if let localAddress = self.key.localAddress, !localAddress.isIPAddress { return eventLoop.makeFailedFuture(HTTPClientError.invalidLocalAddress) @@ -663,11 +718,8 @@ extension HTTPConnectionPool.ConnectionFactory { var bootstrap = ClientBootstrap(group: eventLoop) .connectTimeout(deadline - NIODeadline.now()) .enableMPTCP(clientConfiguration.enableMultipath) - switch clientConfiguration.dnsResolver.backing { - case .system: - break - case .randomized: - bootstrap = bootstrap.resolver(NIORandomizedDNSResolver(loop: eventLoop)) + if let resolver = self.makeResolver(eventLoop: eventLoop, setup: setup) { + bootstrap = bootstrap.resolver(resolver) } if let localAddress = key.localAddress { do { @@ -700,6 +752,79 @@ extension HTTPConnectionPool.ConnectionFactory { } } + /// The resolver to connect with, or `nil` to leave it to SwiftNIO's default resolver. + /// + /// Everything that resolves host names reports the lookup to `setup`. SwiftNIO's default resolver is not + /// available to wrap, so `.system` only is measured when the configuration asks for it, which replaces + /// it with ``SystemDNSResolver``. + private func makeResolver( + eventLoop: EventLoop, + setup: HTTPConnectionSetupRecorder + ) -> (any (Resolver & Sendable))? { + switch self.clientConfiguration.dnsResolver.backing { + case .system: + #if canImport(Darwin) || canImport(Glibc) || canImport(Musl) || canImport(Android) + if self.clientConfiguration.collectDNSMetrics { + return MeasuredDNSResolver(SystemDNSResolver(loop: eventLoop), setup: setup) + } + #endif + return nil + case .randomized: + return MeasuredDNSResolver(NIORandomizedDNSResolver(loop: eventLoop), setup: setup) + } + } + + /// Asks the Network framework how it established the connection, so the DNS, connect and TLS phases can be + /// told apart, and records the answer once it arrives. Does nothing for channels that are not Network framework + /// connections. + /// + /// This must not hold the connection back. Putting an asynchronous step between a connection being established + /// and it being handed over stalls HTTP/2 connections for good, see `HTTP2ClientTests`. Until the report arrives the + /// connection is reported with the phases as they were observed from the outside. The report is normally there + /// long before the request has finished. + static func recordEstablishmentReport(of channel: Channel, setup: HTTPConnectionSetupRecorder) { + #if canImport(Network) + if #available(OSX 10.15, iOS 13.0, tvOS 13.0, watchOS 6.0, *), channel.eventLoop is QoSEventLoop { + let snapshot = setup.snapshot() + let connectStart = snapshot.connectStart ?? snapshot.start + + channel.getOption(NIOTSChannelOptions.establishmentReport).flatMap { $0 }.whenSuccess { report in + if let report { + setup.record(report, connectStart: connectStart) + } + } + } + #endif + } + + /// Records which TLS version the connection negotiated and, where the platform says, which cipher suite. Call this + /// on the connection's event loop once the TLS handshake is done. + /// + /// NIOSSL tells the version, and does not tell the cipher suite. The Network framework tells both, it hands them + /// out asynchronously, which is why this does not hold anything back. + /// + /// A connection made with the Network framework can have its TLS done by NIOSSL, when it goes through a proxy. + /// The Network framework knows nothing about that TLS, and must not be asked about it. + static func recordTLSInfo(of channel: Channel, setup: HTTPConnectionSetupRecorder) { + if let handler = try? channel.pipeline.syncOperations.handler(type: NIOSSLClientHandler.self) { + setup.setTLSVersion(handler.tlsVersion) + return + } + + #if canImport(Network) + if #available(OSX 10.15, iOS 13.0, tvOS 13.0, watchOS 6.0, *), channel.eventLoop is QoSEventLoop { + channel.getOption(NIOTSChannelOptions.metadata(NWProtocolTLS.definition)).whenSuccess { metadata in + guard let tls = metadata as? NWProtocolTLS.Metadata else { + return + } + let security = tls.securityProtocolMetadata + setup.setTLSVersion(TLSVersion(sec_protocol_metadata_get_negotiated_tls_protocol_version(security))) + setup.setTLSCipherSuite(sec_protocol_metadata_get_negotiated_tls_ciphersuite(security).rawValue) + } + } + #endif + } + private static func matchALPNToHTTPVersion(_ negotiated: String?, channel: Channel) throws -> NegotiatedProtocol { switch negotiated { case .none, .some("http/1.1"): diff --git a/Sources/AsyncHTTPClient/ConnectionPool/HTTPConnectionSetupRecorder.swift b/Sources/AsyncHTTPClient/ConnectionPool/HTTPConnectionSetupRecorder.swift new file mode 100644 index 000000000..8cb676dae --- /dev/null +++ b/Sources/AsyncHTTPClient/ConnectionPool/HTTPConnectionSetupRecorder.swift @@ -0,0 +1,186 @@ +//===----------------------------------------------------------------------===// +// +// This source file is part of the AsyncHTTPClient open source project +// +// Copyright (c) 2026 Apple Inc. and the AsyncHTTPClient project authors +// Licensed under Apache License v2.0 +// +// See LICENSE.txt for license information +// See CONTRIBUTORS.txt for the list of AsyncHTTPClient project authors +// +// SPDX-License-Identifier: Apache-2.0 +// +//===----------------------------------------------------------------------===// + +import NIOConcurrencyHelpers +import NIOCore +import NIOSSL + +#if canImport(Network) +import Network +import Security +#endif + +#if canImport(FoundationEssentials) +import FoundationEssentials +#else +import Foundation +#endif + +/// Collects when the phases of establishing one connection started and ended. +/// +/// One recorder belongs to one connection and is written to while the connection is being established, +/// from the event loop and, for DNS, from the thread that resolves. Every phase keeps only its first mark. +final class HTTPConnectionSetupRecorder: Sendable { + struct Snapshot: Sendable, Equatable { + /// When the client started to establish the connection. + var start: NIODeadline + var domainLookupStart: NIODeadline? + var domainLookupEnd: NIODeadline? + var connectStart: NIODeadline? + var connectEnd: NIODeadline? + var secureConnectionStart: NIODeadline? + var secureConnectionEnd: NIODeadline? + var isProxyConnection = false + var tlsVersion: TLSVersion? + var tlsCipherSuite: UInt16? + } + + private let state: NIOLockedValueBox + + init(now: NIODeadline = .now()) { + self.state = NIOLockedValueBox(Snapshot(start: now)) + } + + func markDomainLookupStart(at time: NIODeadline = .now()) { + self.state.withLockedValue { $0.domainLookupStart = $0.domainLookupStart ?? time } + } + + func markDomainLookupEnd(at time: NIODeadline = .now()) { + self.state.withLockedValue { $0.domainLookupEnd = $0.domainLookupEnd ?? time } + } + + func markConnectStart(at time: NIODeadline = .now()) { + self.state.withLockedValue { $0.connectStart = $0.connectStart ?? time } + } + + func markConnectEnd(at time: NIODeadline = .now()) { + self.state.withLockedValue { $0.connectEnd = $0.connectEnd ?? time } + } + + func markSecureConnectionStart(at time: NIODeadline = .now()) { + self.state.withLockedValue { $0.secureConnectionStart = $0.secureConnectionStart ?? time } + } + + func markSecureConnectionEnd(at time: NIODeadline = .now()) { + self.state.withLockedValue { $0.secureConnectionEnd = $0.secureConnectionEnd ?? time } + } + + /// The tunnel through a proxy was established, which ends the connect phase. Unlike the other marks this one + /// replaces an earlier mark, the TCP connection to the proxy ended before the tunnel was there. + func markTunnelEstablished(at time: NIODeadline = .now()) { + self.state.withLockedValue { $0.connectEnd = time } + } + + func setTLSVersion(_ version: TLSVersion?) { + self.state.withLockedValue { $0.tlsVersion = version ?? $0.tlsVersion } + } + + func setTLSCipherSuite(_ cipherSuite: UInt16?) { + self.state.withLockedValue { $0.tlsCipherSuite = cipherSuite ?? $0.tlsCipherSuite } + } + + func markProxyConnection() { + self.state.withLockedValue { $0.isProxyConnection = true } + } + + /// Fills in the phases from what the Network framework reports about an established connection. + /// + /// Network.framework resolves, connects and does the TLS handshake on its own, so only durations are known. + /// The phases are laid out one after another starting at `connectStart`. + func record( + resolutionDuration: TimeInterval?, + handshakeDuration: TimeInterval?, + totalDuration: TimeInterval, + connectStart: NIODeadline, + now: NIODeadline = .now() + ) { + func offset(_ interval: TimeInterval) -> NIODeadline { + connectStart + .nanoseconds(Int64((max(interval, 0) * 1_000_000_000).rounded())) + } + + // never claim to have finished later than we know the connection was ready + let end = Swift.min(offset(totalDuration), now) + + self.state.withLockedValue { state in + var cursor = connectStart + if let resolutionDuration { + let lookupEnd = Swift.min(offset(resolutionDuration), end) + state.domainLookupStart = connectStart + state.domainLookupEnd = lookupEnd + cursor = lookupEnd + } + + state.connectStart = cursor + if let handshakeDuration { + let secureStart = Swift.max(Swift.min(offset(totalDuration - handshakeDuration), end), cursor) + state.connectEnd = secureStart + state.secureConnectionStart = secureStart + state.secureConnectionEnd = end + } else { + state.connectEnd = end + } + } + } + + #if canImport(Network) + @available(OSX 10.15, iOS 13.0, tvOS 13.0, watchOS 6.0, *) + func record( + _ report: NWConnection.EstablishmentReport, + connectStart: NIODeadline, + now: NIODeadline = .now() + ) { + let resolutionDuration = report.resolutions.map(\.duration).max() + let handshakeDuration = report.handshakes.first { $0.definition == NWProtocolTLS.definition }? + .handshakeDuration + + self.record( + resolutionDuration: resolutionDuration, + handshakeDuration: handshakeDuration, + totalDuration: report.duration, + connectStart: connectStart, + now: now + ) + } + #endif + + func snapshot() -> Snapshot { + var snapshot = self.state.withLockedValue { $0 } + // With a measured DNS lookup, connecting can only start once there is an address to connect to. + if let lookupEnd = snapshot.domainLookupEnd, let connectStart = snapshot.connectStart, lookupEnd > connectStart + { + snapshot.connectStart = lookupEnd + } + return snapshot + } +} + +#if canImport(Network) +extension TLSVersion { + /// The version the Network framework negotiated, or `nil` for a version that has no equivalent, like DTLS. + init?(_ version: tls_protocol_version_t) { + switch version { + case .TLSv10: + self = .tlsv1 + case .TLSv11: + self = .tlsv11 + case .TLSv12: + self = .tlsv12 + case .TLSv13: + self = .tlsv13 + default: + return nil + } + } +} +#endif diff --git a/Sources/AsyncHTTPClient/ConnectionPool/HTTPExecutableRequest.swift b/Sources/AsyncHTTPClient/ConnectionPool/HTTPExecutableRequest.swift index 32308a6be..164d1aaab 100644 --- a/Sources/AsyncHTTPClient/ConnectionPool/HTTPExecutableRequest.swift +++ b/Sources/AsyncHTTPClient/ConnectionPool/HTTPExecutableRequest.swift @@ -233,6 +233,13 @@ protocol HTTPExecutableRequest: AnyObject, Sendable { /// request must call `executor.cancel()` to stop request execution. func willExecuteRequest(_: HTTPRequestExecutor) + /// Will be called by the connection right before it starts executing the request, to tell the request + /// which connection it was assigned to. + /// + /// This will be called on the Channel's EventLoop. Do **not block** during your execution! The default + /// implementation ignores the information. + func connectionAcquired(_: HTTPConnectionMetricsInfo) + /// Will be called by the ChannelHandler to indicate that the request head has been sent. /// /// This will be called on the Channel's EventLoop. Do **not block** during your execution! @@ -279,3 +286,7 @@ protocol HTTPExecutableRequest: AnyObject, Sendable { /// Fails the executing request, with an error. func fail(_ error: Error) } + +extension HTTPExecutableRequest { + func connectionAcquired(_: HTTPConnectionMetricsInfo) {} +} diff --git a/Sources/AsyncHTTPClient/ConnectionPool/MeasuredDNSResolver.swift b/Sources/AsyncHTTPClient/ConnectionPool/MeasuredDNSResolver.swift new file mode 100644 index 000000000..58e4bce9a --- /dev/null +++ b/Sources/AsyncHTTPClient/ConnectionPool/MeasuredDNSResolver.swift @@ -0,0 +1,177 @@ +//===----------------------------------------------------------------------===// +// +// This source file is part of the AsyncHTTPClient open source project +// +// Copyright (c) 2026 Apple Inc. and the AsyncHTTPClient project authors +// Licensed under Apache License v2.0 +// +// See LICENSE.txt for license information +// See CONTRIBUTORS.txt for the list of AsyncHTTPClient project authors +// +// SPDX-License-Identifier: Apache-2.0 +// +//===----------------------------------------------------------------------===// + +import NIOConcurrencyHelpers +import NIOCore +import NIOPosix + +#if canImport(Dispatch) +import Dispatch +#endif + +#if canImport(Darwin) +import Darwin +#elseif canImport(Glibc) +import Glibc +#elseif canImport(Musl) +import Musl +#elseif canImport(Android) +import Android +#endif + +/// Resolves host names through another resolver and records when the lookup started and ended. +/// +/// The lookup starts with the first query and ends when the first query completes. The system resolver +/// answers both queries from the same lookup, so they complete together. +final class MeasuredDNSResolver: Resolver, Sendable { + private let underlying: any (Resolver & Sendable) + private let setup: HTTPConnectionSetupRecorder + + init(_ underlying: any (Resolver & Sendable), setup: HTTPConnectionSetupRecorder) { + self.underlying = underlying + self.setup = setup + } + + func initiateAQuery(host: String, port: Int) -> EventLoopFuture<[SocketAddress]> { + self.setup.markDomainLookupStart() + return self.underlying.initiateAQuery(host: host, port: port).always { [setup] _ in + setup.markDomainLookupEnd() + } + } + + func initiateAAAAQuery(host: String, port: Int) -> EventLoopFuture<[SocketAddress]> { + self.setup.markDomainLookupStart() + return self.underlying.initiateAAAAQuery(host: host, port: port).always { [setup] _ in + setup.markDomainLookupEnd() + } + } + + func cancelQueries() { + self.underlying.cancelQueries() + } +} + +#if canImport(Darwin) || canImport(Glibc) || canImport(Musl) || canImport(Android) + +/// Does what SwiftNIO's default resolver does: one `getaddrinfo` call per connection attempt for TCP +/// addresses, run off the event loop, with the result split into IPv4 and IPv6 addresses. +/// +/// SwiftNIO does not make its default resolver available, which is why there is a copy of it here. Errors +/// are produced by SwiftNIO itself, see ``SystemDNSResolver/resolveBlocking(host:port:)``, so callers see the same +/// errors they would see with the default resolver. +final class SystemDNSResolver: Resolver, Sendable { + private struct Promises { + var v4: EventLoopPromise<[SocketAddress]> + var v6: EventLoopPromise<[SocketAddress]> + } + + private let loop: EventLoop + + /// Created with the first query. A resolver that is never asked, because the target is an IP address, must not + /// leave promises behind that are never completed. + private let promises = NIOLockedValueBox(nil) + + init(loop: EventLoop) { + self.loop = loop + } + + private func currentPromises() -> Promises { + self.promises.withLockedValue { promises in + if let promises { + return promises + } + let created = Promises(v4: self.loop.makePromise(), v6: self.loop.makePromise()) + promises = created + return created + } + } + + func initiateAQuery(host: String, port: Int) -> EventLoopFuture<[SocketAddress]> { + self.currentPromises().v4.futureResult + } + + /// Both queries are answered by the one lookup that is started here, like SwiftNIO's resolver does it. + func initiateAAAAQuery(host: String, port: Int) -> EventLoopFuture<[SocketAddress]> { + let promises = self.currentPromises() + DispatchQueue.global().async { + self.resolveBlocking(host: host, port: port, promises: promises) + } + return promises.v6.futureResult + } + + func cancelQueries() {} + + private func resolveBlocking(host: String, port: Int, promises: Promises) { + var info: UnsafeMutablePointer? + + var hint = addrinfo() + #if canImport(Glibc) + hint.ai_socktype = CInt(SOCK_STREAM.rawValue) + #else + hint.ai_socktype = CInt(SOCK_STREAM) + #endif + hint.ai_protocol = CInt(IPPROTO_TCP) + + guard getaddrinfo(host, String(port), &hint, &info) == 0, let info else { + // `UnknownHost` can only be created by SwiftNIO. Resolving the host again through it makes it report + // the failure the way it does for its own resolver. This is the failure path, so the second call is cheap. + do { + _ = try SocketAddress.makeAddressResolvingHost(host, port: port) + self.fail(SocketAddressError.unsupported, promises) + } catch { + self.fail(error, promises) + } + return + } + defer { freeaddrinfo(info) } + + var v4Results: [SocketAddress] = [] + var v6Results: [SocketAddress] = [] + + var current: UnsafeMutablePointer = info + while true { + let addressBytes = UnsafeRawPointer(current.pointee.ai_addr) + switch NIOBSDSocket.AddressFamily(rawValue: current.pointee.ai_family) { + case .inet: + // `getaddrinfo` fills in an address of the family it reports + v4Results.append(SocketAddress(addressBytes!.load(as: sockaddr_in.self), host: host)) + case .inet6: + v6Results.append(SocketAddress(addressBytes!.load(as: sockaddr_in6.self), host: host)) + default: + self.fail(SocketAddressError.unsupported, promises) + return + } + + guard let next = current.pointee.ai_next else { + break + } + current = next + } + + // Both promises are completed in the same tick, so neither is left behind. + self.loop.execute { [v4Results, v6Results] in + promises.v6.succeed(v6Results) + promises.v4.succeed(v4Results) + } + } + + private func fail(_ error: Error, _ promises: Promises) { + self.loop.execute { + promises.v6.fail(error) + promises.v4.fail(error) + } + } +} + +#endif diff --git a/Sources/AsyncHTTPClient/HTTPClient.swift b/Sources/AsyncHTTPClient/HTTPClient.swift index 43d76ed0a..39f61fd8d 100644 --- a/Sources/AsyncHTTPClient/HTTPClient.swift +++ b/Sources/AsyncHTTPClient/HTTPClient.swift @@ -888,6 +888,19 @@ public final class HTTPClient: Sendable { /// ``HTTPClient/EventLoopGroupProvider/shared(_:)``. public var dnsResolver: DNSResolver = .system + /// Whether to measure how long resolving host names takes, even where that is not possible with the default + /// resolver. Defaults to `false`. + /// + /// The transaction metrics report when the DNS lookup of a new connection started and ended + /// (``HTTPClientTransactionMetrics/Connection/domainLookupStartDate``). SwiftNIO's default resolver cannot be + /// observed, so the lookup is only reported if the connection is made with the randomized resolver, or if this + /// is `true`. Setting it makes the client resolve host names with its own implementation of what SwiftNIO's + /// default resolver does: `getaddrinfo` for TCP addresses, run off the event loop. + /// + /// - Note: This setting has no effect when connections run on an `NIOTSEventLoopGroup`. Network.framework + /// reports how long it took to resolve the host name by itself. + public var collectDNSMetrics: Bool = false + /// Enables following 3xx redirects automatically. /// /// Following redirects are supported: diff --git a/Sources/AsyncHTTPClient/HTTPClientMetrics.swift b/Sources/AsyncHTTPClient/HTTPClientMetrics.swift new file mode 100644 index 000000000..575a245b1 --- /dev/null +++ b/Sources/AsyncHTTPClient/HTTPClientMetrics.swift @@ -0,0 +1,417 @@ +//===----------------------------------------------------------------------===// +// +// This source file is part of the AsyncHTTPClient open source project +// +// Copyright (c) 2026 Apple Inc. and the AsyncHTTPClient project authors +// Licensed under Apache License v2.0 +// +// See LICENSE.txt for license information +// See CONTRIBUTORS.txt for the list of AsyncHTTPClient project authors +// +// SPDX-License-Identifier: Apache-2.0 +// +//===----------------------------------------------------------------------===// + +import NIOConcurrencyHelpers +import NIOCore +import NIOSSL + +#if canImport(FoundationEssentials) +import FoundationEssentials +#else +import Foundation +#endif + +/// Timing and connection information for a single HTTP transaction, i.e. one request/response +/// exchange on the wire. +/// +/// A request that follows redirects produces one `HTTPClientTransactionMetrics` value per hop, delivered +/// in order. Every date is `nil` when the corresponding phase was never reached, for example when the +/// request failed while waiting for a connection. +/// +/// Dates are derived from a monotonic clock anchored at ``fetchStartDate``, so differences between +/// two dates of the same value are accurate even if the wall clock is adjusted while the request runs. +public struct HTTPClientTransactionMetrics: Sendable { + /// Describes the connection a transaction ran on. + public struct Connection: Sendable { + /// The application protocol that was negotiated for the connection. + public enum NegotiatedProtocol: Sendable, Hashable { + case http1_1 + case http2 + } + + /// An identifier that is unique among the connections of one ``HTTPClient``. Two transactions with the same + /// identifier ran on the same connection. + public var id: Int + + public var negotiatedProtocol: NegotiatedProtocol + + /// Whether the connection had already carried at least one transaction before this one. + /// + /// This is `false` for the transaction that is the first one to run on a freshly established connection. + public var isReused: Bool + + public var localAddress: SocketAddress? + + public var remoteAddress: SocketAddress? + + /// Whether the connection goes through a proxy. + public var isProxyConnection: Bool + + /// The TLS version that was negotiated for the connection, or `nil` if it does not use TLS or the version is + /// not known. + public var tlsVersion: TLSVersion? + + /// The TLS cipher suite that was negotiated for the connection, as its number in the IANA registry of TLS cipher + /// suites, for example `0x1301` for `TLS_AES_128_GCM_SHA256`. + /// + /// This is only known for connections made with the Network framework. NIOSSL does not tell which cipher suite it + /// negotiated, so it is `nil` everywhere else. + public var tlsCipherSuite: UInt16? + + // The phases of establishing the connection. They are `nil` for a reused connection, and for the phases that + // did not take place, for example the secure connection phase of a connection without TLS. + // + // Connections made with the Network framework are resolved, connected and secured by it. It reports how long + // each phase took, in whole milliseconds, which is turned into dates by laying the phases out one after the + // other, so those dates are only as exact as the report is. + + /// When resolving the host name started. `nil` if there was nothing to resolve, or if the lookup cannot be + /// observed, see ``HTTPClient/Configuration/collectDNSMetrics``. + public var domainLookupStartDate: Date? + + /// When the host name was resolved. This is when the first addresses were available, which is when connecting + /// can start. + public var domainLookupEndDate: Date? + + /// When connecting started. With a proxy this includes setting up the tunnel to the target. + public var connectStartDate: Date? + + public var connectEndDate: Date? + + /// When the TLS handshake started. + public var secureConnectionStartDate: Date? + + public var secureConnectionEndDate: Date? + + public init( + id: Int, + negotiatedProtocol: NegotiatedProtocol, + isReused: Bool, + localAddress: SocketAddress? = nil, + remoteAddress: SocketAddress? = nil, + isProxyConnection: Bool = false, + tlsVersion: TLSVersion? = nil, + tlsCipherSuite: UInt16? = nil, + domainLookupStartDate: Date? = nil, + domainLookupEndDate: Date? = nil, + connectStartDate: Date? = nil, + connectEndDate: Date? = nil, + secureConnectionStartDate: Date? = nil, + secureConnectionEndDate: Date? = nil + ) { + self.id = id + self.negotiatedProtocol = negotiatedProtocol + self.isReused = isReused + self.localAddress = localAddress + self.remoteAddress = remoteAddress + self.isProxyConnection = isProxyConnection + self.tlsVersion = tlsVersion + self.tlsCipherSuite = tlsCipherSuite + self.domainLookupStartDate = domainLookupStartDate + self.domainLookupEndDate = domainLookupEndDate + self.connectStartDate = connectStartDate + self.connectEndDate = connectEndDate + self.secureConnectionStartDate = secureConnectionStartDate + self.secureConnectionEndDate = secureConnectionEndDate + } + } + + /// The URL this transaction was sent to. + public var url: URL + + /// When the client started working on the request. + public var fetchStartDate: Date + + /// When the request had to wait for a connection to become available. `nil` if a connection was + /// available immediately. + /// + /// The time spent waiting is `requestStartDate - queuedDate`. For the first request on a new connection that is + /// the time it took to establish the connection, see ``Connection/connectStartDate``. + public var queuedDate: Date? + + /// When a connection was assigned and the request head started to be written. + public var requestStartDate: Date? + + /// When the complete request, including its body, was handed to the connection. + public var requestEndDate: Date? + + /// When the response head was received. + public var responseStartDate: Date? + + /// When the complete response was received from the connection. + /// + /// This is the point at which the last byte arrived, not the point at which the caller consumed it. + /// It is `nil` if the transaction ended before the response was complete, for example because + /// a redirect was followed as soon as the response head arrived. + public var responseEndDate: Date? + + // The bytes the transaction moved. They are counted above TLS, which is what HTTP is made of, and not on the + // network, which is more than that. + + /// The bytes of the request head that were sent, with the request line and the headers. `nil` if that is not + /// known, which is the case for HTTP/2: it compresses the headers, and the connection is shared with other requests. + public var requestHeaderBytesSent: Int? + + /// The bytes of the request body that were sent, with what the transfer encoding adds to them. For HTTP/2 these are + /// the bytes of the body, because they are all it sends. + public var requestBodyBytesSent: Int + + /// The bytes of the request body as the caller gave them, before the transfer encoding added to them. + public var requestBodyBytesBeforeEncoding: Int + + /// The bytes of the response head that were received, with the status line and the headers. For a response with a + /// chunked body this includes the chunk framing, and the trailers. `nil` if that is not known, which is the case for + /// HTTP/2, and for a response that was not received completely. + public var responseHeaderBytesReceived: Int? + + /// The bytes of the response body that were received, which is before they are decompressed. + public var responseBodyBytesReceived: Int + + /// The bytes of the response body as the caller gets them, after they were decompressed. + public var responseBodyBytesAfterDecoding: Int + + /// The connection the transaction ran on, or `nil` if it never got one. + public var connection: Connection? + + /// The error that ended the transaction, or `nil` if it ended without one. + public var error: (any Error)? + + public init( + url: URL, + fetchStartDate: Date, + queuedDate: Date? = nil, + requestStartDate: Date? = nil, + requestEndDate: Date? = nil, + responseStartDate: Date? = nil, + responseEndDate: Date? = nil, + requestHeaderBytesSent: Int? = nil, + requestBodyBytesSent: Int = 0, + requestBodyBytesBeforeEncoding: Int = 0, + responseHeaderBytesReceived: Int? = nil, + responseBodyBytesReceived: Int = 0, + responseBodyBytesAfterDecoding: Int = 0, + connection: Connection? = nil, + error: (any Error)? = nil + ) { + self.url = url + self.fetchStartDate = fetchStartDate + self.queuedDate = queuedDate + self.requestStartDate = requestStartDate + self.requestEndDate = requestEndDate + self.responseStartDate = responseStartDate + self.responseEndDate = responseEndDate + self.requestHeaderBytesSent = requestHeaderBytesSent + self.requestBodyBytesSent = requestBodyBytesSent + self.requestBodyBytesBeforeEncoding = requestBodyBytesBeforeEncoding + self.responseHeaderBytesReceived = responseHeaderBytesReceived + self.responseBodyBytesReceived = responseBodyBytesReceived + self.responseBodyBytesAfterDecoding = responseBodyBytesAfterDecoding + self.connection = connection + self.error = error + } +} + +/// What a connection tells a request about itself at the moment it is assigned to it. +struct HTTPConnectionMetricsInfo: Sendable { + var id: Int + var negotiatedProtocol: HTTPClientTransactionMetrics.Connection.NegotiatedProtocol + var isReused: Bool + var localAddress: SocketAddress? + var remoteAddress: SocketAddress? + /// How the connection was established, and what is known about it since. + /// + /// This is the recorder and not what it recorded so far, because the connection is handed out before everything + /// is known about how it was established. It is read when the transaction ends. + var setup: HTTPConnectionSetupRecorder? + /// What went through the connection or, for HTTP/2, through the stream the request runs on. + var byteCounters: HTTPByteCounters? + var acquiredAt: NIODeadline +} + +/// Collects the events of one transaction and turns them into a ``HTTPClientTransactionMetrics``. +/// +/// The recorder is a plain value. Whoever owns it is responsible for serialising access, which for +/// `RequestBag` is the task's event loop and for `Transaction` its lock. +struct HTTPRequestMetricsRecorder: Sendable { + private let url: URL + private let fetchStart: NIODeadline + private let fetchStartDate: Date + + private var queuedAt: NIODeadline? + private var connection: HTTPConnectionMetricsInfo? + private var requestEndAt: NIODeadline? + private var responseStartAt: NIODeadline? + private var responseEndAt: NIODeadline? + + // The byte counters when the connection was acquired, when the request head and the request were sent, and when + // the response was received. + private var baseCounters = HTTPByteCounters.Snapshot() + private var headSentCounters: HTTPByteCounters.Snapshot? + private var requestEndCounters: HTTPByteCounters.Snapshot? + private var responseEndCounters: HTTPByteCounters.Snapshot? + + private var requestBodyBytesBeforeEncoding = 0 + private var responseBodyBytesAfterDecoding = 0 + + private var isFinished = false + + init(url: URL, now: NIODeadline = .now(), date: Date = Date()) { + self.url = url + self.fetchStart = now + self.fetchStartDate = date + } + + mutating func requestWasQueued(at time: NIODeadline) { + self.queuedAt = self.queuedAt ?? time + } + + mutating func connectionAcquired(_ info: HTTPConnectionMetricsInfo) { + self.connection = info + self.baseCounters = info.byteCounters?.snapshot() ?? HTTPByteCounters.Snapshot() + } + + mutating func requestHeadSent() { + self.headSentCounters = self.headSentCounters ?? self.connection?.byteCounters?.snapshot() + } + + mutating func requestBodyBytesWritten(_ bytes: Int) { + self.requestBodyBytesBeforeEncoding += bytes + } + + mutating func requestEnded(at time: NIODeadline) { + self.requestEndAt = self.requestEndAt ?? time + self.requestEndCounters = self.requestEndCounters ?? self.connection?.byteCounters?.snapshot() + } + + mutating func responseBodyBytesDelivered(_ bytes: Int) { + self.responseBodyBytesAfterDecoding += bytes + } + + mutating func responseHeadReceived(at time: NIODeadline) { + self.responseStartAt = self.responseStartAt ?? time + } + + mutating func responseEnded(at time: NIODeadline) { + self.responseEndAt = self.responseEndAt ?? time + self.responseEndCounters = self.responseEndCounters ?? self.connection?.byteCounters?.snapshot() + } + + /// Produces the final metrics, exactly once. Every later call returns `nil`. + mutating func finish(error: (any Error)?) -> HTTPClientTransactionMetrics? { + guard !self.isFinished else { + return nil + } + self.isFinished = true + + let isHTTP1 = self.connection?.negotiatedProtocol == .http1_1 + let base = self.baseCounters + let latest = self.responseEndCounters ?? self.connection?.byteCounters?.snapshot() ?? base + + var requestHeaderBytesSent: Int? + var requestBodyBytesSent = self.requestBodyBytesBeforeEncoding + if isHTTP1, let headSent = self.headSentCounters { + requestHeaderBytesSent = headSent.sent - base.sent + if let requestEnd = self.requestEndCounters { + requestBodyBytesSent = requestEnd.sent - headSent.sent + } + } + + var responseHeaderBytesReceived: Int? + if isHTTP1, let responseEnd = self.responseEndCounters { + let received = responseEnd.received - base.received + let body = responseEnd.responseBodyReceived - base.responseBodyReceived + responseHeaderBytesReceived = received - body + } + + return HTTPClientTransactionMetrics( + url: self.url, + fetchStartDate: self.fetchStartDate, + queuedDate: self.queuedAt.map(self.date), + requestStartDate: self.connection.map { self.date($0.acquiredAt) }, + requestEndDate: self.requestEndAt.map(self.date), + responseStartDate: self.responseStartAt.map(self.date), + responseEndDate: self.responseEndAt.map(self.date), + requestHeaderBytesSent: requestHeaderBytesSent, + requestBodyBytesSent: requestBodyBytesSent, + requestBodyBytesBeforeEncoding: self.requestBodyBytesBeforeEncoding, + responseHeaderBytesReceived: responseHeaderBytesReceived, + responseBodyBytesReceived: latest.responseBodyReceived - base.responseBodyReceived, + responseBodyBytesAfterDecoding: self.responseBodyBytesAfterDecoding, + connection: self.connection.map(self.makeConnection), + error: error + ) + } + + private func makeConnection(_ info: HTTPConnectionMetricsInfo) -> HTTPClientTransactionMetrics.Connection { + // Only the first transaction on a connection reports how it was established. A connection that was established + // before the request started, for example a pre-warmed one, was not established for this request, which makes it + // a reused connection and the setup none of its business. + let recorded = info.setup?.snapshot() + let setup = recorded.flatMap { !info.isReused && $0.start >= self.fetchStart ? $0 : nil } + + return .init( + id: info.id, + negotiatedProtocol: info.negotiatedProtocol, + isReused: info.isReused || (recorded != nil && setup == nil), + localAddress: info.localAddress, + remoteAddress: info.remoteAddress, + isProxyConnection: recorded?.isProxyConnection ?? false, + tlsVersion: recorded?.tlsVersion, + tlsCipherSuite: recorded?.tlsCipherSuite, + domainLookupStartDate: setup?.domainLookupStart.map(self.date), + domainLookupEndDate: setup?.domainLookupEnd.map(self.date), + connectStartDate: setup?.connectStart.map(self.date), + connectEndDate: setup?.connectEnd.map(self.date), + secureConnectionStartDate: setup?.secureConnectionStart.map(self.date), + secureConnectionEndDate: setup?.secureConnectionEnd.map(self.date) + ) + } + + private func date(_ time: NIODeadline) -> Date { + let elapsed = Double((time - self.fetchStart).nanoseconds) / 1_000_000_000 + return self.fetchStartDate.addingTimeInterval(elapsed) + } +} + +/// Hands the metrics of one hop of a redirect chain to the caller's handler. +/// +/// When a hop ends in a redirect, its response body is dropped without being read. If the response was not +/// complete yet, that cancels the transaction, which is not an error of the hop. Once the redirect is known to be +/// followed, such a cancellation is therefore reported without an error. +struct HTTPHopMetricsHandler: Sendable { + private let followedRedirect = NIOLockedValueBox(false) + private let handler: @Sendable (HTTPClientTransactionMetrics) -> Void + + init(_ handler: @escaping @Sendable (HTTPClientTransactionMetrics) -> Void) { + self.handler = handler + } + + /// Call this before the response of the hop is dropped. + func redirectWillBeFollowed() { + self.followedRedirect.withLockedValue { $0 = true } + } + + /// The handler to hand to the transaction of the hop. + var transactionHandler: @Sendable (HTTPClientTransactionMetrics) -> Void { + { metrics in self(metrics) } + } + + func callAsFunction(_ metrics: HTTPClientTransactionMetrics) { + var metrics = metrics + if (metrics.error as? HTTPClientError) == .cancelled, self.followedRedirect.withLockedValue({ $0 }) { + metrics.error = nil + } + self.handler(metrics) + } +} diff --git a/Sources/AsyncHTTPClient/HTTPHandler.swift b/Sources/AsyncHTTPClient/HTTPHandler.swift index 6bb265bf2..f74e7dc7f 100644 --- a/Sources/AsyncHTTPClient/HTTPHandler.swift +++ b/Sources/AsyncHTTPClient/HTTPHandler.swift @@ -806,6 +806,18 @@ public protocol HTTPClientResponseDelegate: AnyObject, Sendable { /// - error: Error that occured during response processing. func didReceiveError(task: HTTPClient.Task, _ error: Error) + /// Called once per HTTP transaction with the timing and connection information that was recorded for it. + /// + /// A request that follows redirects results in one call per hop, in order. The call happens before + /// ``HTTPClientResponseDelegate/didFinishRequest(task:)`` or ``HTTPClientResponseDelegate/didReceiveError(task:_:)-fhsg`` + /// for the transaction, or, when a redirect is followed, before the next hop starts. If the transaction + /// failed, ``HTTPClientTransactionMetrics/error`` is set and phases that were never reached are `nil`. + /// + /// - parameters: + /// - task: Current request context. + /// - metrics: What was recorded for the transaction. + func didCollectMetrics(task: HTTPClient.Task, _ metrics: HTTPClientTransactionMetrics) + /// Called when the complete HTTP request is finished. You must return an instance of your ``Response`` associated type. Will be called once, except if an error occurred. /// /// This function will not be called until all futures returned by ``HTTPClientResponseDelegate/didReceiveHead(task:_:)-9r4xd`` and ``HTTPClientResponseDelegate/didReceiveBodyPart(task:_:)-4fd4v`` @@ -819,6 +831,9 @@ public protocol HTTPClientResponseDelegate: AnyObject, Sendable { } extension HTTPClientResponseDelegate { + /// Default implementation of ``HTTPClientResponseDelegate/didCollectMetrics(task:_:)``. Does nothing. + public func didCollectMetrics(task: HTTPClient.Task, _ metrics: HTTPClientTransactionMetrics) {} + /// Default implementation of ``HTTPClientResponseDelegate/didSendRequest(task:)-9od5p``. /// /// By default, this does nothing. diff --git a/Sources/AsyncHTTPClient/RequestBag.swift b/Sources/AsyncHTTPClient/RequestBag.swift index 6d596d5a6..7afa2dcac 100644 --- a/Sources/AsyncHTTPClient/RequestBag.swift +++ b/Sources/AsyncHTTPClient/RequestBag.swift @@ -56,6 +56,9 @@ final class RequestBag: Sendabl var tracing: HTTPClient.TracingConfiguration // The current span, representing the entire request/response made by an execute call. var activeSpan: (any Span)? = nil + + // - Metrics + var metrics: HTTPRequestMetricsRecorder } private let loopBoundState: NIOLoopBoundBox @@ -112,7 +115,8 @@ final class RequestBag: Sendabl request: request, state: StateMachine(redirectHandler: redirectHandler, requestFramingMetadata: metadata), consumeBodyPartStackDepth: 0, - tracing: task.tracing + tracing: task.tracing, + metrics: HTTPRequestMetricsRecorder(url: request.url) ) self.loopBoundState = NIOLoopBoundBox.makeBoxSendingValue(loopBoundState, eventLoop: task.eventLoop) self.connectionDeadline = connectionDeadline @@ -127,8 +131,9 @@ final class RequestBag: Sendabl } } - private func requestWasQueued0(_ scheduler: HTTPRequestScheduler) { + private func requestWasQueued0(_ scheduler: HTTPRequestScheduler, at time: NIODeadline) { self.logger.debug("Request was queued (waiting for a connection to become available)") + self.loopBoundState.value.metrics.requestWasQueued(at: time) self.loopBoundState.value.state.requestWasQueued(scheduler) } @@ -144,6 +149,7 @@ final class RequestBag: Sendabl executor.cancelRequest(self) self.loopBoundState.value.failRequestSpanAsCancelled() case .failTaskAndCancelExecutor(let error, let executor): + self.deliverMetrics(error: error) self.delegate.didReceiveError(task: self.task, error) self.task.failInternal(with: error) executor.cancelRequest(self) @@ -154,11 +160,13 @@ final class RequestBag: Sendabl } private func requestHeadSent0() { + self.loopBoundState.value.metrics.requestHeadSent() self.loopBoundState.value.state.requestHeadSent() self.delegate.didSendRequestHead(task: self.task, self.requestHead) if self.requestFramingMetadata.body == .fixedSize(0) { + self.loopBoundState.value.metrics.requestEnded(at: .now()) self.delegate.didSendRequest(task: self.task) } } @@ -221,6 +229,7 @@ final class RequestBag: Sendabl return self.task.eventLoop.makeFailedFuture(error) case .write(let part, let writer, let future): + self.loopBoundState.value.metrics.requestBodyBytesWritten(part.readableBytes) let promise = self.task.eventLoop.makePromise(of: Void.self) promise.futureResult.whenSuccess { self.delegate.didSendRequestPart(task: self.task, part) @@ -239,6 +248,7 @@ final class RequestBag: Sendabl case .forwardStreamFinished(let writer, let writerPromise): let promise = writerPromise ?? self.task.eventLoop.makePromise(of: Void.self) promise.futureResult.whenSuccess { + self.loopBoundState.value.metrics.requestEnded(at: .now()) self.delegate.didSendRequest(task: self.task) } writer.finishRequestBodyStream(trailers: nil, request: self, promise: promise) @@ -248,7 +258,9 @@ final class RequestBag: Sendabl promise.futureResult.whenComplete { result in switch result { case .success: + self.loopBoundState.value.metrics.requestEnded(at: .now()) self.delegate.didSendRequest(task: self.task) + self.deliverMetrics(error: nil) do { let response = try self.delegate.didFinishRequest(task: self.task) self.task.promise.succeed(response) @@ -274,13 +286,26 @@ final class RequestBag: Sendabl func failTask0(_ error: Error) { self.task.eventLoop.assertInEventLoop() + self.deliverMetrics(error: error) self.delegate.didReceiveError(task: self.task, error) self.task.promise.fail(error) } + /// Hands the recorded metrics to the delegate. Only the first call of a bag has an effect, so every + /// path that ends the transaction can call this without coordinating with the others. + private func deliverMetrics(error: (any Error)?) { + self.task.eventLoop.assertInEventLoop() + + guard let metrics = self.loopBoundState.value.metrics.finish(error: error) else { + return + } + self.delegate.didCollectMetrics(task: self.task, metrics) + } + // MARK: - Response - - private func receiveResponseHead0(_ head: HTTPResponseHead) { + private func receiveResponseHead0(_ head: HTTPResponseHead, at time: NIODeadline) { + self.loopBoundState.value.metrics.responseHeadReceived(at: time) self.delegate.didVisitURL(task: self.task, self.loopBoundState.value.request, head) self.loopBoundState.value.endRequestSpan(response: head) @@ -301,6 +326,7 @@ final class RequestBag: Sendabl executor.demandResponseBodyStream(self) case .redirect(let executor, let handler, let head, let newURL): + self.deliverMetrics(error: nil) self.loopBoundState.value.redirectTask = handler.redirect( head: head, to: newURL, @@ -319,6 +345,7 @@ final class RequestBag: Sendabl } private func receiveResponseBodyParts0(_ buffer: CircularBuffer) { + self.loopBoundState.value.metrics.responseBodyBytesDelivered(buffer.reduce(0) { $0 + $1.readableBytes }) switch self.loopBoundState.value.state.receiveResponseBodyParts(buffer) { case .none: break @@ -327,6 +354,7 @@ final class RequestBag: Sendabl executor.demandResponseBodyStream(self) case .redirect(let executor, let handler, let head, let newURL): + self.deliverMetrics(error: nil) self.loopBoundState.value.redirectTask = handler.redirect( head: head, to: newURL, @@ -344,7 +372,11 @@ final class RequestBag: Sendabl } } - private func receiveResponseEnd0(_ buffer: CircularBuffer?) { + private func receiveResponseEnd0(_ buffer: CircularBuffer?, at time: NIODeadline) { + self.loopBoundState.value.metrics.responseEnded(at: time) + if let buffer { + self.loopBoundState.value.metrics.responseBodyBytesDelivered(buffer.reduce(0) { $0 + $1.readableBytes }) + } let action = self.loopBoundState.value.state.receiveResponseEnd(buffer) switch action { @@ -358,6 +390,7 @@ final class RequestBag: Sendabl } case .succeedRequest: + self.deliverMetrics(error: nil) do { let response = try self.delegate.didFinishRequest(task: self.task) self.task.promise.succeed(response) @@ -366,6 +399,7 @@ final class RequestBag: Sendabl } case .redirect(let handler, let head, let newURL): + self.deliverMetrics(error: nil) self.loopBoundState.value.redirectTask = handler.redirect( head: head, to: newURL, @@ -414,6 +448,7 @@ final class RequestBag: Sendabl case .doNothing: break case .finishStream: + self.deliverMetrics(error: nil) do { let response = try self.delegate.didFinishRequest(task: self.task) self.task.promise.assumeIsolated().succeed(response) @@ -475,11 +510,12 @@ final class RequestBag: Sendabl extension RequestBag: HTTPSchedulableRequest, HTTPClientTaskDelegate { func requestWasQueued(_ scheduler: HTTPRequestScheduler) { + let time = NIODeadline.now() if self.task.eventLoop.inEventLoop { - self.requestWasQueued0(scheduler) + self.requestWasQueued0(scheduler, at: time) } else { self.task.eventLoop.execute { - self.requestWasQueued0(scheduler) + self.requestWasQueued0(scheduler, at: time) } } } @@ -516,6 +552,16 @@ extension RequestBag: HTTPExecutableRequest { } } + func connectionAcquired(_ info: HTTPConnectionMetricsInfo) { + if self.task.eventLoop.inEventLoop { + self.loopBoundState.value.metrics.connectionAcquired(info) + } else { + self.task.eventLoop.execute { + self.loopBoundState.value.metrics.connectionAcquired(info) + } + } + } + func willExecuteRequest(_ executor: HTTPRequestExecutor) { if self.task.eventLoop.inEventLoop { self.willExecuteRequest0(executor) @@ -567,11 +613,12 @@ extension RequestBag: HTTPExecutableRequest { } func receiveResponseHead(_ head: HTTPResponseHead) { + let time = NIODeadline.now() if self.task.eventLoop.inEventLoop { - self.receiveResponseHead0(head) + self.receiveResponseHead0(head, at: time) } else { self.task.eventLoop.execute { - self.receiveResponseHead0(head) + self.receiveResponseHead0(head, at: time) } } } @@ -587,11 +634,12 @@ extension RequestBag: HTTPExecutableRequest { } func receiveResponseEnd(_ buffer: CircularBuffer?, trailers: HTTPHeaders?) { + let time = NIODeadline.now() if self.task.eventLoop.inEventLoop { - self.receiveResponseEnd0(buffer) + self.receiveResponseEnd0(buffer, at: time) } else { self.task.eventLoop.execute { - self.receiveResponseEnd0(buffer) + self.receiveResponseEnd0(buffer, at: time) } } } diff --git a/Tests/AsyncHTTPClientTests/EmbeddedChannel+HTTPConvenience.swift b/Tests/AsyncHTTPClientTests/EmbeddedChannel+HTTPConvenience.swift index 5cc35bce8..4fb7be007 100644 --- a/Tests/AsyncHTTPClientTests/EmbeddedChannel+HTTPConvenience.swift +++ b/Tests/AsyncHTTPClientTests/EmbeddedChannel+HTTPConvenience.swift @@ -82,18 +82,21 @@ extension EmbeddedChannel { logger: logger ) - // remove HTTP client encoder and decoder + // remove HTTP client encoder and decoder, and the counter of the bytes they work on let decoder = try self.pipeline.syncOperations.handler(type: ByteToMessageHandler.self) let encoder = try self.pipeline.syncOperations.handler(type: HTTPRequestEncoder.self) + let byteCounter = try self.pipeline.syncOperations.handler(type: HTTPRawByteCountingHandler.self) let removeDecoderFuture = self.pipeline.syncOperations.removeHandler(decoder) let removeEncoderFuture = self.pipeline.syncOperations.removeHandler(encoder) + let removeByteCounterFuture = self.pipeline.syncOperations.removeHandler(byteCounter) self.embeddedEventLoop.run() try removeDecoderFuture.wait() try removeEncoderFuture.wait() + try removeByteCounterFuture.wait() return .init( connection: connection.sendableView, diff --git a/Tests/AsyncHTTPClientTests/HTTPClientMetricsTests.swift b/Tests/AsyncHTTPClientTests/HTTPClientMetricsTests.swift new file mode 100644 index 000000000..7b592e5e2 --- /dev/null +++ b/Tests/AsyncHTTPClientTests/HTTPClientMetricsTests.swift @@ -0,0 +1,1425 @@ +//===----------------------------------------------------------------------===// +// +// This source file is part of the AsyncHTTPClient open source project +// +// Copyright (c) 2026 Apple Inc. and the AsyncHTTPClient project authors +// Licensed under Apache License v2.0 +// +// See LICENSE.txt for license information +// See CONTRIBUTORS.txt for the list of AsyncHTTPClient project authors +// +// SPDX-License-Identifier: Apache-2.0 +// +//===----------------------------------------------------------------------===// + +import Logging +import NIOConcurrencyHelpers +import NIOCore +import NIOEmbedded +import NIOHTTP1 +import NIOHTTPCompression +import NIOPosix +import NIOSSL +import XCTest + +@testable import AsyncHTTPClient + +#if canImport(Network) +import NIOTransportServices +#endif + +#if canImport(FoundationEssentials) +import FoundationEssentials +#else +import Foundation +#endif + +// MARK: - Recorder + +final class HTTPRequestMetricsRecorderTests: XCTestCase { + private let url = URL(string: "https://example.com/path")! + + private func connection( + at time: NIODeadline, + id: Int = 7, + isReused: Bool = false + ) -> HTTPConnectionMetricsInfo { + HTTPConnectionMetricsInfo( + id: id, + negotiatedProtocol: .http1_1, + isReused: isReused, + localAddress: nil, + remoteAddress: nil, + acquiredAt: time + ) + } + + func testDatesAreOffsetFromTheFetchStartAnchor() throws { + let start = NIODeadline.uptimeNanoseconds(1_000_000_000) + let anchor = Date(timeIntervalSince1970: 1_000) + var recorder = HTTPRequestMetricsRecorder(url: self.url, now: start, date: anchor) + + recorder.requestWasQueued(at: start + .milliseconds(10)) + recorder.connectionAcquired(self.connection(at: start + .milliseconds(30))) + recorder.requestEnded(at: start + .milliseconds(31)) + recorder.responseHeadReceived(at: start + .milliseconds(50)) + recorder.responseEnded(at: start + .milliseconds(70)) + + let metrics = try XCTUnwrap(recorder.finish(error: nil)) + + XCTAssertEqual(metrics.url, self.url) + XCTAssertEqual(metrics.fetchStartDate, anchor) + XCTAssertEqual(try XCTUnwrap(metrics.queuedDate).timeIntervalSince(anchor), 0.010, accuracy: 0.0001) + XCTAssertEqual(try XCTUnwrap(metrics.requestStartDate).timeIntervalSince(anchor), 0.030, accuracy: 0.0001) + XCTAssertEqual(try XCTUnwrap(metrics.requestEndDate).timeIntervalSince(anchor), 0.031, accuracy: 0.0001) + XCTAssertEqual(try XCTUnwrap(metrics.responseStartDate).timeIntervalSince(anchor), 0.050, accuracy: 0.0001) + XCTAssertEqual(try XCTUnwrap(metrics.responseEndDate).timeIntervalSince(anchor), 0.070, accuracy: 0.0001) + XCTAssertEqual(metrics.connection?.id, 7) + XCTAssertNil(metrics.error) + } + + func testPhasesThatWereNeverReachedStayNil() throws { + var recorder = HTTPRequestMetricsRecorder(url: self.url) + + let metrics = try XCTUnwrap(recorder.finish(error: HTTPClientError.cancelled)) + + XCTAssertNil(metrics.queuedDate) + XCTAssertNil(metrics.requestStartDate) + XCTAssertNil(metrics.requestEndDate) + XCTAssertNil(metrics.responseStartDate) + XCTAssertNil(metrics.responseEndDate) + XCTAssertNil(metrics.connection) + XCTAssertEqual(metrics.error as? HTTPClientError, .cancelled) + } + + func testOnlyTheFirstOccurrenceOfAnEventIsKept() throws { + let start = NIODeadline.uptimeNanoseconds(1_000_000_000) + var recorder = HTTPRequestMetricsRecorder(url: self.url, now: start, date: Date(timeIntervalSince1970: 0)) + + recorder.requestWasQueued(at: start + .milliseconds(1)) + recorder.requestWasQueued(at: start + .milliseconds(2)) + recorder.responseHeadReceived(at: start + .milliseconds(3)) + recorder.responseHeadReceived(at: start + .milliseconds(4)) + + let metrics = try XCTUnwrap(recorder.finish(error: nil)) + + XCTAssertEqual(try XCTUnwrap(metrics.queuedDate).timeIntervalSince1970, 0.001, accuracy: 0.0001) + XCTAssertEqual(try XCTUnwrap(metrics.responseStartDate).timeIntervalSince1970, 0.003, accuracy: 0.0001) + } + + func testFinishProducesMetricsExactlyOnce() { + var recorder = HTTPRequestMetricsRecorder(url: self.url) + + XCTAssertNotNil(recorder.finish(error: nil)) + XCTAssertNil(recorder.finish(error: HTTPClientError.cancelled)) + } +} + +// MARK: - Redirect hops + +final class HTTPHopMetricsHandlerTests: XCTestCase { + private func metrics(error: (any Error)?) -> HTTPClientTransactionMetrics { + HTTPClientTransactionMetrics( + url: URL(string: "https://example.com")!, + fetchStartDate: Date(timeIntervalSince1970: 0), + error: error + ) + } + + func testCancellationOfAHopThatFollowedARedirectIsNotAnError() { + let received = NIOLockedValueBox<[HTTPClientTransactionMetrics]>([]) + let handler = HTTPHopMetricsHandler { metrics in received.withLockedValue { $0.append(metrics) } } + + handler.redirectWillBeFollowed() + handler(self.metrics(error: HTTPClientError.cancelled)) + + XCTAssertEqual(received.withLockedValue { $0 }.count, 1) + XCTAssertNil(received.withLockedValue { $0 }.first?.error) + } + + func testCancellationOfAHopThatDidNotFollowARedirectIsKept() { + let received = NIOLockedValueBox<[HTTPClientTransactionMetrics]>([]) + let handler = HTTPHopMetricsHandler { metrics in received.withLockedValue { $0.append(metrics) } } + + handler(self.metrics(error: HTTPClientError.cancelled)) + + XCTAssertEqual(received.withLockedValue { $0 }.first?.error as? HTTPClientError, .cancelled) + } + + func testOtherErrorsAreKeptEvenIfARedirectWasFollowed() { + let received = NIOLockedValueBox<[HTTPClientTransactionMetrics]>([]) + let handler = HTTPHopMetricsHandler { metrics in received.withLockedValue { $0.append(metrics) } } + + handler.redirectWillBeFollowed() + handler(self.metrics(error: HTTPClientError.remoteConnectionClosed)) + + XCTAssertEqual(received.withLockedValue { $0 }.first?.error as? HTTPClientError, .remoteConnectionClosed) + } +} + +// MARK: - Through the client + +private final class MetricsCollector: Sendable { + private let storage = NIOLockedValueBox<[HTTPClientTransactionMetrics]>([]) + + var metrics: [HTTPClientTransactionMetrics] { + self.storage.withLockedValue { $0 } + } + + @Sendable func record(_ metrics: HTTPClientTransactionMetrics) { + self.storage.withLockedValue { $0.append(metrics) } + } +} + +private final class MetricsRecordingDelegate: HTTPClientResponseDelegate { + typealias Response = [HTTPClientTransactionMetrics] + + private let collector = MetricsCollector() + + func didCollectMetrics(task: HTTPClient.Task, _ metrics: HTTPClientTransactionMetrics) { + self.collector.record(metrics) + } + + func didFinishRequest(task: HTTPClient.Task) throws -> Response { + self.collector.metrics + } +} + +@available(macOS 10.15, iOS 13.0, watchOS 6.0, tvOS 13.0, *) +final class HTTPClientMetricsTests: XCTestCase { + private static func makeClient(configure: (inout HTTPClient.Configuration) -> Void = { _ in }) -> HTTPClient { + var config = HTTPClient.Configuration() + config.tlsConfiguration = .clientDefault + config.tlsConfiguration?.certificateVerification = .none + config.httpVersion = .automatic + configure(&config) + return HTTPClient(eventLoopGroupProvider: .singleton, configuration: config) + } + + private static func assertPhasesAreOrdered( + _ metrics: HTTPClientTransactionMetrics, + file: StaticString = #filePath, + line: UInt = #line + ) throws { + let requestStart = try XCTUnwrap(metrics.requestStartDate, file: file, line: line) + let requestEnd = try XCTUnwrap(metrics.requestEndDate, file: file, line: line) + let responseStart = try XCTUnwrap(metrics.responseStartDate, file: file, line: line) + let responseEnd = try XCTUnwrap(metrics.responseEndDate, file: file, line: line) + + XCTAssertLessThanOrEqual(metrics.fetchStartDate, requestStart, file: file, line: line) + XCTAssertLessThanOrEqual(requestStart, requestEnd, file: file, line: line) + XCTAssertLessThanOrEqual(requestStart, responseStart, file: file, line: line) + XCTAssertLessThanOrEqual(responseStart, responseEnd, file: file, line: line) + } + + func testHTTP1TransactionIsReportedAndSecondRequestReusesTheConnection() { + XCTAsyncTest { + let bin = HTTPBin(.http1_1(compress: false)) + defer { XCTAssertNoThrow(try bin.shutdown()) } + let client = Self.makeClient() + defer { XCTAssertNoThrow(try client.syncShutdown()) } + + let url = "http://localhost:\(bin.port)/ok" + let first = MetricsCollector() + let firstResponse = try await client.execute( + HTTPClientRequest(url: url), + timeout: .seconds(10), + metrics: first.record + ) + _ = try await firstResponse.body.collect(upTo: 1024) + + let second = MetricsCollector() + let secondResponse = try await client.execute( + HTTPClientRequest(url: url), + timeout: .seconds(10), + metrics: second.record + ) + _ = try await secondResponse.body.collect(upTo: 1024) + + let firstMetrics = try XCTUnwrap(first.metrics.first) + XCTAssertEqual(first.metrics.count, 1) + XCTAssertEqual(firstMetrics.url.absoluteString, url) + XCTAssertNil(firstMetrics.error) + // nothing to reuse yet: the request waited for its connection to be established + XCTAssertNotNil(firstMetrics.queuedDate) + try Self.assertPhasesAreOrdered(firstMetrics) + + let firstConnection = try XCTUnwrap(firstMetrics.connection) + XCTAssertEqual(firstConnection.negotiatedProtocol, .http1_1) + XCTAssertFalse(firstConnection.isReused) + XCTAssertEqual(firstConnection.remoteAddress?.port, bin.port) + XCTAssertNotNil(firstConnection.localAddress) + + let secondMetrics = try XCTUnwrap(second.metrics.first) + XCTAssertEqual(second.metrics.count, 1) + let secondConnection = try XCTUnwrap(secondMetrics.connection) + XCTAssertNil(secondMetrics.queuedDate) + XCTAssertTrue(secondConnection.isReused) + XCTAssertEqual(secondConnection.id, firstConnection.id) + try Self.assertPhasesAreOrdered(secondMetrics) + } + } + + func testHTTP2TransactionReportsTheNegotiatedProtocolAndReuse() { + XCTAsyncTest { + let bin = HTTPBin(.http2(compress: false)) + defer { XCTAssertNoThrow(try bin.shutdown()) } + let client = Self.makeClient() + defer { XCTAssertNoThrow(try client.syncShutdown()) } + + let url = "https://localhost:\(bin.port)/get" + var collected: [HTTPClientTransactionMetrics] = [] + for _ in 0..<2 { + let collector = MetricsCollector() + let response = try await client.execute( + HTTPClientRequest(url: url), + timeout: .seconds(10), + metrics: collector.record + ) + _ = try await response.body.collect(upTo: 1024 * 1024) + collected.append(contentsOf: collector.metrics) + } + + XCTAssertEqual(collected.count, 2) + let first = try XCTUnwrap(collected.first) + let second = try XCTUnwrap(collected.last) + XCTAssertEqual(first.connection?.negotiatedProtocol, .http2) + XCTAssertEqual(first.connection?.isReused, false) + XCTAssertEqual(second.connection?.negotiatedProtocol, .http2) + XCTAssertEqual(second.connection?.isReused, true) + XCTAssertEqual(second.connection?.id, first.connection?.id) + try Self.assertPhasesAreOrdered(first) + try Self.assertPhasesAreOrdered(second) + } + } + + func testEachRedirectHopIsReportedInOrder() { + XCTAsyncTest { + let bin = HTTPBin(.http1_1(compress: false)) + defer { XCTAssertNoThrow(try bin.shutdown()) } + var config = HTTPClient.Configuration() + config.redirectConfiguration = .follow(max: 5, allowCycles: false) + let client = HTTPClient(eventLoopGroupProvider: .singleton, configuration: config) + defer { XCTAssertNoThrow(try client.syncShutdown()) } + + let collector = MetricsCollector() + let response = try await client.execute( + HTTPClientRequest(url: "http://localhost:\(bin.port)/redirect/302"), + timeout: .seconds(10), + metrics: collector.record + ) + _ = try await response.body.collect(upTo: 1024) + + XCTAssertEqual( + collector.metrics.map(\.url.path), + ["/redirect/302", "/ok"] + ) + XCTAssertEqual(collector.metrics.map { $0.error == nil }, [true, true]) + } + } + + func testTransactionThatFailsAfterGettingAConnectionIsReportedWithTheError() { + XCTAsyncTest { + let bin = HTTPBin(.http1_1(compress: false)) + defer { XCTAssertNoThrow(try bin.shutdown()) } + let client = Self.makeClient() + defer { XCTAssertNoThrow(try client.syncShutdown()) } + + // the server closes the connection without answering + let collector = MetricsCollector() + do { + _ = try await client.execute( + HTTPClientRequest(url: "http://localhost:\(bin.port)/close"), + timeout: .seconds(10), + metrics: collector.record + ) + XCTFail("Expected the request to fail") + } catch { + XCTAssertEqual(collector.metrics.count, 1) + let metrics = try XCTUnwrap(collector.metrics.first) + XCTAssertNotNil(metrics.error) + XCTAssertNotNil(metrics.connection) + XCTAssertNotNil(metrics.requestStartDate) + XCTAssertNil(metrics.responseStartDate) + XCTAssertNil(metrics.responseEndDate) + } + } + } + + func testRequestThatWaitsForAConnectionReportsWhenItWasQueued() { + XCTAsyncTest { + let bin = HTTPBin(.http1_1(compress: false)) + defer { XCTAssertNoThrow(try bin.shutdown()) } + let client = Self.makeClient { + $0.connectionPool.concurrentHTTP1ConnectionsPerHostSoftLimit = 1 + } + defer { XCTAssertNoThrow(try client.syncShutdown()) } + + let url = "http://localhost:\(bin.port)/wait" + + // occupies the only connection, `/wait` never answers + let blocker = Task { + try? await client.execute(HTTPClientRequest(url: url), timeout: .seconds(3)) + } + try await Task.sleep(nanoseconds: 300_000_000) + + let collector = MetricsCollector() + do { + _ = try await client.execute( + HTTPClientRequest(url: url), + timeout: .milliseconds(500), + metrics: collector.record + ) + XCTFail("Expected the request to run into its deadline") + } catch { + XCTAssertEqual(error as? HTTPClientError, .deadlineExceeded) + } + blocker.cancel() + + XCTAssertEqual(collector.metrics.count, 1) + let metrics = try XCTUnwrap(collector.metrics.first) + XCTAssertNotNil(metrics.queuedDate) + XCTAssertNil(metrics.connection) + XCTAssertNil(metrics.requestStartDate) + XCTAssertEqual(metrics.error as? HTTPClientError, .deadlineExceeded) + } + } + + func testDelegateReceivesMetricsBeforeTheRequestFinishes() { + XCTAsyncTest { + let bin = HTTPBin(.http1_1(compress: false)) + defer { XCTAssertNoThrow(try bin.shutdown()) } + var config = HTTPClient.Configuration() + config.redirectConfiguration = .follow(max: 5, allowCycles: false) + let client = HTTPClient(eventLoopGroupProvider: .singleton, configuration: config) + defer { XCTAssertNoThrow(try client.syncShutdown()) } + + let request = try HTTPClient.Request(url: "http://localhost:\(bin.port)/redirect/302") + let delegate = MetricsRecordingDelegate() + let collected = try await client.execute(request: request, delegate: delegate).get() + + // `didFinishRequest` ran after the metrics of the last hop were delivered. The redirect hop + // went to a second task with the same delegate, so both hops were seen. + XCTAssertEqual(collected.map(\.url.path), ["/redirect/302", "/ok"]) + XCTAssertEqual(collected.map { $0.error == nil }, [true, true]) + for metrics in collected { + try Self.assertPhasesAreOrdered(metrics) + XCTAssertEqual(metrics.connection?.negotiatedProtocol, .http1_1) + } + } + } +} + +// MARK: - Connection setup: recorder + +final class HTTPConnectionSetupRecorderTests: XCTestCase { + private let start = NIODeadline.uptimeNanoseconds(10_000_000_000) + + func testOnlyTheFirstMarkOfAPhaseIsKept() { + let recorder = HTTPConnectionSetupRecorder(now: self.start) + + recorder.markConnectStart(at: self.start + .milliseconds(1)) + recorder.markConnectStart(at: self.start + .milliseconds(2)) + recorder.markDomainLookupEnd(at: self.start + .milliseconds(3)) + recorder.markDomainLookupEnd(at: self.start + .milliseconds(4)) + + let snapshot = recorder.snapshot() + XCTAssertEqual(snapshot.connectStart, self.start + .milliseconds(3), "pushed back to the end of the lookup") + XCTAssertEqual(snapshot.domainLookupEnd, self.start + .milliseconds(3)) + XCTAssertEqual(snapshot.start, self.start) + } + + func testConnectingStartsWhenTheLookupEnds() { + let recorder = HTTPConnectionSetupRecorder(now: self.start) + + recorder.markConnectStart(at: self.start + .milliseconds(1)) + recorder.markDomainLookupStart(at: self.start + .milliseconds(1)) + recorder.markDomainLookupEnd(at: self.start + .milliseconds(20)) + recorder.markConnectEnd(at: self.start + .milliseconds(30)) + + XCTAssertEqual(recorder.snapshot().connectStart, self.start + .milliseconds(20)) + } + + func testConnectStartIsLeftAloneWithoutALookup() { + let recorder = HTTPConnectionSetupRecorder(now: self.start) + + recorder.markConnectStart(at: self.start + .milliseconds(1)) + + XCTAssertEqual(recorder.snapshot().connectStart, self.start + .milliseconds(1)) + XCTAssertNil(recorder.snapshot().domainLookupStart) + } + + func testTunnelReplacesTheEndOfTheConnectPhase() { + let recorder = HTTPConnectionSetupRecorder(now: self.start) + + recorder.markConnectStart(at: self.start) + recorder.markConnectEnd(at: self.start + .milliseconds(5)) + recorder.markTunnelEstablished(at: self.start + .milliseconds(12)) + + XCTAssertEqual(recorder.snapshot().connectEnd, self.start + .milliseconds(12)) + } + + func testReportWithResolutionAndHandshakeIsLaidOutPhaseByPhase() { + let recorder = HTTPConnectionSetupRecorder(now: self.start) + + recorder.record( + resolutionDuration: 0.010, + handshakeDuration: 0.030, + totalDuration: 0.100, + connectStart: self.start, + now: self.start + .seconds(1) + ) + + let snapshot = recorder.snapshot() + XCTAssertEqual(snapshot.domainLookupStart, self.start) + XCTAssertEqual(snapshot.domainLookupEnd, self.start + .milliseconds(10)) + XCTAssertEqual(snapshot.connectStart, self.start + .milliseconds(10)) + XCTAssertEqual(snapshot.connectEnd, self.start + .milliseconds(70)) + XCTAssertEqual(snapshot.secureConnectionStart, self.start + .milliseconds(70)) + XCTAssertEqual(snapshot.secureConnectionEnd, self.start + .milliseconds(100)) + } + + func testReportWithoutHandshakeHasNoSecureConnectionPhase() { + let recorder = HTTPConnectionSetupRecorder(now: self.start) + + recorder.record( + resolutionDuration: nil, + handshakeDuration: nil, + totalDuration: 0.050, + connectStart: self.start, + now: self.start + .seconds(1) + ) + + let snapshot = recorder.snapshot() + XCTAssertNil(snapshot.domainLookupStart) + XCTAssertNil(snapshot.domainLookupEnd) + XCTAssertEqual(snapshot.connectStart, self.start) + XCTAssertEqual(snapshot.connectEnd, self.start + .milliseconds(50)) + XCTAssertNil(snapshot.secureConnectionStart) + XCTAssertNil(snapshot.secureConnectionEnd) + } + + func testReportNeverClaimsToHaveEndedAfterNow() { + let recorder = HTTPConnectionSetupRecorder(now: self.start) + + recorder.record( + resolutionDuration: 0.010, + handshakeDuration: 0.040, + totalDuration: 5, + connectStart: self.start, + now: self.start + .milliseconds(80) + ) + + let snapshot = recorder.snapshot() + XCTAssertEqual(snapshot.secureConnectionEnd, self.start + .milliseconds(80)) + XCTAssertLessThanOrEqual(snapshot.secureConnectionStart!, snapshot.secureConnectionEnd!) + XCTAssertLessThanOrEqual(snapshot.domainLookupEnd!, snapshot.connectEnd!) + } + + func testHandshakeLongerThanTheConnectionDoesNotStartBeforeTheLookupEnded() { + let recorder = HTTPConnectionSetupRecorder(now: self.start) + + recorder.record( + resolutionDuration: 0.020, + handshakeDuration: 0.500, + totalDuration: 0.100, + connectStart: self.start, + now: self.start + .seconds(1) + ) + + let snapshot = recorder.snapshot() + XCTAssertEqual(snapshot.secureConnectionStart, snapshot.domainLookupEnd) + XCTAssertEqual(snapshot.secureConnectionEnd, self.start + .milliseconds(100)) + } +} + +final class HTTPRequestMetricsSetupMappingTests: XCTestCase { + private let url = URL(string: "https://example.com")! + private let start = NIODeadline.uptimeNanoseconds(10_000_000_000) + + private func info(setup: HTTPConnectionSetupRecorder?, isReused: Bool = false) -> HTTPConnectionMetricsInfo { + HTTPConnectionMetricsInfo( + id: 1, + negotiatedProtocol: .http1_1, + isReused: isReused, + localAddress: nil, + remoteAddress: nil, + setup: setup, + acquiredAt: self.start + .milliseconds(50) + ) + } + + func testSetupThatBeganAfterTheRequestStartedIsReported() throws { + var recorder = HTTPRequestMetricsRecorder(url: self.url, now: self.start, date: Date(timeIntervalSince1970: 0)) + let setup = HTTPConnectionSetupRecorder(now: self.start + .milliseconds(5)) + setup.markDomainLookupStart(at: self.start + .milliseconds(6)) + setup.markDomainLookupEnd(at: self.start + .milliseconds(10)) + setup.markConnectStart(at: self.start + .milliseconds(10)) + setup.markConnectEnd(at: self.start + .milliseconds(30)) + setup.markSecureConnectionStart(at: self.start + .milliseconds(30)) + setup.markSecureConnectionEnd(at: self.start + .milliseconds(45)) + setup.markProxyConnection() + recorder.connectionAcquired(self.info(setup: setup)) + + let connection = try XCTUnwrap(recorder.finish(error: nil)?.connection) + + XCTAssertFalse(connection.isReused) + XCTAssertTrue(connection.isProxyConnection) + XCTAssertEqual(try XCTUnwrap(connection.domainLookupStartDate).timeIntervalSince1970, 0.006, accuracy: 0.0001) + XCTAssertEqual(try XCTUnwrap(connection.domainLookupEndDate).timeIntervalSince1970, 0.010, accuracy: 0.0001) + XCTAssertEqual(try XCTUnwrap(connection.connectStartDate).timeIntervalSince1970, 0.010, accuracy: 0.0001) + XCTAssertEqual(try XCTUnwrap(connection.connectEndDate).timeIntervalSince1970, 0.030, accuracy: 0.0001) + XCTAssertEqual( + try XCTUnwrap(connection.secureConnectionStartDate).timeIntervalSince1970, + 0.030, + accuracy: 0.0001 + ) + XCTAssertEqual( + try XCTUnwrap(connection.secureConnectionEndDate).timeIntervalSince1970, + 0.045, + accuracy: 0.0001 + ) + } + + func testSetupThatIsRecordedAfterTheConnectionWasAcquiredIsStillReported() throws { + var recorder = HTTPRequestMetricsRecorder(url: self.url, now: self.start, date: Date(timeIntervalSince1970: 0)) + let setup = HTTPConnectionSetupRecorder(now: self.start + .milliseconds(5)) + recorder.connectionAcquired(self.info(setup: setup)) + + // for example what the Network framework reports about a connection after it was established + setup.markConnectStart(at: self.start + .milliseconds(5)) + setup.markConnectEnd(at: self.start + .milliseconds(20)) + + let connection = try XCTUnwrap(recorder.finish(error: nil)?.connection) + XCTAssertEqual(try XCTUnwrap(connection.connectEndDate).timeIntervalSince1970, 0.020, accuracy: 0.0001) + } + + func testConnectionThatExistedBeforeTheRequestIsReusedAndHasNoSetup() throws { + var recorder = HTTPRequestMetricsRecorder(url: self.url, now: self.start, date: Date(timeIntervalSince1970: 0)) + let setup = HTTPConnectionSetupRecorder(now: self.start - .seconds(2)) + setup.markConnectStart(at: self.start - .seconds(2)) + setup.markConnectEnd(at: self.start - .seconds(1)) + // the first request on a pre-warmed connection is handed its setup, but it was not made for the request + recorder.connectionAcquired(self.info(setup: setup, isReused: false)) + + let connection = try XCTUnwrap(recorder.finish(error: nil)?.connection) + + XCTAssertTrue(connection.isReused) + XCTAssertNil(connection.connectStartDate) + XCTAssertNil(connection.connectEndDate) + XCTAssertFalse(connection.isProxyConnection) + } + + func testConnectionWithoutSetupHasNoSetupPhases() throws { + var recorder = HTTPRequestMetricsRecorder(url: self.url, now: self.start, date: Date(timeIntervalSince1970: 0)) + recorder.connectionAcquired(self.info(setup: nil, isReused: true)) + + let connection = try XCTUnwrap(recorder.finish(error: nil)?.connection) + + XCTAssertTrue(connection.isReused) + XCTAssertNil(connection.domainLookupStartDate) + XCTAssertNil(connection.secureConnectionEndDate) + } +} + +// MARK: - Connection setup: resolvers + +final class DNSResolverMetricsTests: XCTestCase { + private var group: MultiThreadedEventLoopGroup! + + override func setUp() { + self.group = MultiThreadedEventLoopGroup(numberOfThreads: 1) + } + + override func tearDown() { + XCTAssertNoThrow(try self.group.syncShutdownGracefully()) + } + + #if canImport(Darwin) || canImport(Glibc) || canImport(Musl) || canImport(Android) + func testSystemResolverResolvesLocalhost() throws { + let resolver = SystemDNSResolver(loop: self.group.next()) + + let v6 = try resolver.initiateAAAAQuery(host: "localhost", port: 8080).wait() + let v4 = try resolver.initiateAQuery(host: "localhost", port: 8080).wait() + + XCTAssertFalse((v4 + v6).isEmpty) + XCTAssertTrue(v4.allSatisfy { $0.protocol == .inet && $0.port == 8080 }) + XCTAssertTrue(v6.allSatisfy { $0.protocol == .inet6 && $0.port == 8080 }) + } + + func testSystemResolverFailsLikeSwiftNIOForUnknownHosts() { + let resolver = SystemDNSResolver(loop: self.group.next()) + + let v6 = resolver.initiateAAAAQuery(host: "does-not-exist.invalid", port: 80) + let v4 = resolver.initiateAQuery(host: "does-not-exist.invalid", port: 80) + + XCTAssertThrowsError(try v6.wait()) { error in + XCTAssertTrue(error is SocketAddressError.UnknownHost, "unexpected error \(error)") + } + XCTAssertThrowsError(try v4.wait()) { error in + XCTAssertTrue(error is SocketAddressError.UnknownHost, "unexpected error \(error)") + } + } + + func testMeasuredResolverRecordsTheLookupAroundTheSystemResolver() throws { + let setup = HTTPConnectionSetupRecorder() + let resolver = MeasuredDNSResolver(SystemDNSResolver(loop: self.group.next()), setup: setup) + + XCTAssertNil(setup.snapshot().domainLookupStart) + _ = try resolver.initiateAAAAQuery(host: "localhost", port: 80).wait() + _ = try resolver.initiateAQuery(host: "localhost", port: 80).wait() + + let snapshot = setup.snapshot() + let lookupStart = try XCTUnwrap(snapshot.domainLookupStart) + let lookupEnd = try XCTUnwrap(snapshot.domainLookupEnd) + XCTAssertLessThanOrEqual(snapshot.start, lookupStart) + XCTAssertLessThanOrEqual(lookupStart, lookupEnd) + } + + func testMeasuredResolverRecordsFailedLookups() throws { + let setup = HTTPConnectionSetupRecorder() + let resolver = MeasuredDNSResolver(SystemDNSResolver(loop: self.group.next()), setup: setup) + + XCTAssertThrowsError(try resolver.initiateAAAAQuery(host: "does-not-exist.invalid", port: 80).wait()) + _ = try? resolver.initiateAQuery(host: "does-not-exist.invalid", port: 80).wait() + + XCTAssertNotNil(setup.snapshot().domainLookupStart) + XCTAssertNotNil(setup.snapshot().domainLookupEnd) + } + #endif +} + +// MARK: - Connection setup: through the client + +@available(macOS 10.15, iOS 13.0, watchOS 6.0, tvOS 13.0, *) +final class HTTPClientConnectionSetupMetricsTests: XCTestCase { + private static func fetch( + _ client: HTTPClient, + _ url: String + ) async throws -> HTTPClientTransactionMetrics { + let collector = MetricsCollector() + let response = try await client.execute( + HTTPClientRequest(url: url), + timeout: .seconds(10), + metrics: collector.record + ) + _ = try await response.body.collect(upTo: 1024 * 1024) + return try XCTUnwrap(collector.metrics.first) + } + + private static func makeClient( + group: EventLoopGroup, + configure: (inout HTTPClient.Configuration) -> Void = { _ in } + ) -> HTTPClient { + var config = HTTPClient.Configuration() + config.tlsConfiguration = .clientDefault + config.tlsConfiguration?.certificateVerification = .none + configure(&config) + return HTTPClient(eventLoopGroupProvider: .shared(group), configuration: config) + } + + private static func assertPhasesAreOrdered( + _ connection: HTTPClientTransactionMetrics.Connection, + secure: Bool, + file: StaticString = #filePath, + line: UInt = #line + ) throws { + let connectStart = try XCTUnwrap(connection.connectStartDate, file: file, line: line) + let connectEnd = try XCTUnwrap(connection.connectEndDate, file: file, line: line) + XCTAssertLessThanOrEqual(connectStart, connectEnd, file: file, line: line) + + if let lookupStart = connection.domainLookupStartDate, let lookupEnd = connection.domainLookupEndDate { + XCTAssertLessThanOrEqual(lookupStart, lookupEnd, file: file, line: line) + XCTAssertLessThanOrEqual(lookupEnd, connectStart, file: file, line: line) + } + + if secure { + let secureStart = try XCTUnwrap(connection.secureConnectionStartDate, file: file, line: line) + let secureEnd = try XCTUnwrap(connection.secureConnectionEndDate, file: file, line: line) + XCTAssertLessThanOrEqual(connectEnd, secureStart, file: file, line: line) + XCTAssertLessThanOrEqual(secureStart, secureEnd, file: file, line: line) + } else { + XCTAssertNil(connection.secureConnectionStartDate, file: file, line: line) + XCTAssertNil(connection.secureConnectionEndDate, file: file, line: line) + } + } + + func testPlainConnectionReportsConnectAndMeasuredDNSAndReuseHasNoSetup() { + XCTAsyncTest { + let group = MultiThreadedEventLoopGroup(numberOfThreads: 1) + defer { XCTAssertNoThrow(try group.syncShutdownGracefully()) } + let bin = HTTPBin(.http1_1(compress: false)) + defer { XCTAssertNoThrow(try bin.shutdown()) } + let client = Self.makeClient(group: group) { $0.collectDNSMetrics = true } + defer { XCTAssertNoThrow(try client.syncShutdown()) } + + let url = "http://localhost:\(bin.port)/ok" + let first = try await Self.fetch(client, url) + let second = try await Self.fetch(client, url) + + let connection = try XCTUnwrap(first.connection) + XCTAssertFalse(connection.isReused) + XCTAssertFalse(connection.isProxyConnection) + XCTAssertNotNil(connection.domainLookupStartDate) + XCTAssertNotNil(connection.domainLookupEndDate) + try Self.assertPhasesAreOrdered(connection, secure: false) + + let reused = try XCTUnwrap(second.connection) + XCTAssertTrue(reused.isReused) + XCTAssertEqual(reused.id, connection.id) + XCTAssertNil(reused.domainLookupStartDate) + XCTAssertNil(reused.connectStartDate) + XCTAssertNil(reused.connectEndDate) + XCTAssertNil(reused.secureConnectionStartDate) + } + } + + func testDNSIsNotReportedWhenTheDefaultResolverIsUsed() { + XCTAsyncTest { + let group = MultiThreadedEventLoopGroup(numberOfThreads: 1) + defer { XCTAssertNoThrow(try group.syncShutdownGracefully()) } + let bin = HTTPBin(.http1_1(compress: false)) + defer { XCTAssertNoThrow(try bin.shutdown()) } + let client = Self.makeClient(group: group) + defer { XCTAssertNoThrow(try client.syncShutdown()) } + + let metrics = try await Self.fetch(client, "http://localhost:\(bin.port)/ok") + + let connection = try XCTUnwrap(metrics.connection) + XCTAssertNil(connection.domainLookupStartDate) + XCTAssertNil(connection.domainLookupEndDate) + try Self.assertPhasesAreOrdered(connection, secure: false) + } + } + + func testRandomizedResolverIsMeasuredWithoutAskingFor() { + XCTAsyncTest { + let group = MultiThreadedEventLoopGroup(numberOfThreads: 1) + defer { XCTAssertNoThrow(try group.syncShutdownGracefully()) } + let bin = HTTPBin(.http1_1(compress: false)) + defer { XCTAssertNoThrow(try bin.shutdown()) } + let client = Self.makeClient(group: group) { $0.dnsResolver = .randomized } + defer { XCTAssertNoThrow(try client.syncShutdown()) } + + let metrics = try await Self.fetch(client, "http://localhost:\(bin.port)/ok") + + let connection = try XCTUnwrap(metrics.connection) + XCTAssertNotNil(connection.domainLookupStartDate) + XCTAssertNotNil(connection.domainLookupEndDate) + try Self.assertPhasesAreOrdered(connection, secure: false) + } + } + + func testIPAddressHasNothingToResolve() { + XCTAsyncTest { + let group = MultiThreadedEventLoopGroup(numberOfThreads: 1) + defer { XCTAssertNoThrow(try group.syncShutdownGracefully()) } + let bin = HTTPBin(.http1_1(compress: false)) + defer { XCTAssertNoThrow(try bin.shutdown()) } + let client = Self.makeClient(group: group) { $0.collectDNSMetrics = true } + defer { XCTAssertNoThrow(try client.syncShutdown()) } + + let metrics = try await Self.fetch(client, "http://127.0.0.1:\(bin.port)/ok") + + let connection = try XCTUnwrap(metrics.connection) + XCTAssertNil(connection.domainLookupStartDate) + XCTAssertNil(connection.domainLookupEndDate) + try Self.assertPhasesAreOrdered(connection, secure: false) + } + } + + func testTLSConnectionReportsTheSecureConnectionPhase() { + XCTAsyncTest { + let group = MultiThreadedEventLoopGroup(numberOfThreads: 1) + defer { XCTAssertNoThrow(try group.syncShutdownGracefully()) } + let bin = HTTPBin(.http2(compress: false)) + defer { XCTAssertNoThrow(try bin.shutdown()) } + let client = Self.makeClient(group: group) { $0.collectDNSMetrics = true } + defer { XCTAssertNoThrow(try client.syncShutdown()) } + + let metrics = try await Self.fetch(client, "https://localhost:\(bin.port)/get") + + let connection = try XCTUnwrap(metrics.connection) + XCTAssertEqual(connection.negotiatedProtocol, .http2) + XCTAssertNotNil(connection.domainLookupStartDate) + try Self.assertPhasesAreOrdered(connection, secure: true) + } + } + + func testConnectionThroughAProxyIsReported() { + XCTAsyncTest { + let group = MultiThreadedEventLoopGroup(numberOfThreads: 1) + defer { XCTAssertNoThrow(try group.syncShutdownGracefully()) } + let bin = HTTPBin(.http1_1(ssl: true), proxy: .simulate(authorization: nil)) + defer { XCTAssertNoThrow(try bin.shutdown()) } + let client = Self.makeClient(group: group) { + $0.proxy = .server(host: "localhost", port: bin.port) + } + defer { XCTAssertNoThrow(try client.syncShutdown()) } + + let metrics = try await Self.fetch(client, "https://test/ok") + + let connection = try XCTUnwrap(metrics.connection) + XCTAssertTrue(connection.isProxyConnection) + // connecting includes the tunnel, the TLS handshake with the target comes after it + try Self.assertPhasesAreOrdered(connection, secure: true) + } + } + + func testTransactionThatFailsAfterConnectingStillReportsTheConnectionSetup() { + XCTAsyncTest { + let group = MultiThreadedEventLoopGroup(numberOfThreads: 1) + defer { XCTAssertNoThrow(try group.syncShutdownGracefully()) } + let bin = HTTPBin(.http1_1(compress: false)) + defer { XCTAssertNoThrow(try bin.shutdown()) } + let client = Self.makeClient(group: group) + defer { XCTAssertNoThrow(try client.syncShutdown()) } + + let collector = MetricsCollector() + do { + _ = try await client.execute( + HTTPClientRequest(url: "http://localhost:\(bin.port)/close"), + timeout: .seconds(10), + metrics: collector.record + ) + XCTFail("Expected the request to fail") + } catch { + // the connection was established, only the response never came + let connection = try XCTUnwrap(collector.metrics.first?.connection) + try Self.assertPhasesAreOrdered(connection, secure: false) + } + } + } + + #if canImport(Network) + func testNetworkFrameworkConnectionReportsConnectAndSecureConnection() { + XCTAsyncTest { + let group = NIOTSEventLoopGroup(loopCount: 1, defaultQoS: .default) + defer { XCTAssertNoThrow(try group.syncShutdownGracefully()) } + let plainBin = HTTPBin(.http1_1(compress: false)) + defer { XCTAssertNoThrow(try plainBin.shutdown()) } + let tlsBin = HTTPBin(.http1_1(ssl: true)) + defer { XCTAssertNoThrow(try tlsBin.shutdown()) } + let client = Self.makeClient(group: group) + defer { XCTAssertNoThrow(try client.syncShutdown()) } + + let plain = try await Self.fetch(client, "http://localhost:\(plainBin.port)/ok") + let tls = try await Self.fetch(client, "https://localhost:\(tlsBin.port)/ok") + + let plainConnection = try XCTUnwrap(plain.connection) + try Self.assertPhasesAreOrdered(plainConnection, secure: false) + + let tlsConnection = try XCTUnwrap(tls.connection) + try Self.assertPhasesAreOrdered(tlsConnection, secure: true) + } + } + + func testProxyConnectionOverTheNetworkFrameworkReportsTheTLSOfNIOSSL() { + XCTAsyncTest { + let group = NIOTSEventLoopGroup(loopCount: 1, defaultQoS: .default) + defer { XCTAssertNoThrow(try group.syncShutdownGracefully()) } + let bin = HTTPBin(.http1_1(ssl: true), proxy: .simulate(authorization: nil)) + defer { XCTAssertNoThrow(try bin.shutdown()) } + let client = Self.makeClient(group: group) { + $0.proxy = .server(host: "localhost", port: bin.port) + } + defer { XCTAssertNoThrow(try client.syncShutdown()) } + + let metrics = try await Self.fetch(client, "https://test/ok") + + // The tunnel is a Network framework connection without TLS, the TLS to the target is done by NIOSSL. + let connection = try XCTUnwrap(metrics.connection) + XCTAssertTrue(connection.isProxyConnection) + XCTAssertNotNil(connection.tlsVersion) + XCTAssertNil(connection.tlsCipherSuite) + try Self.assertPhasesAreOrdered(connection, secure: true) + } + } + + func testHTTP2ConnectionsOverTheNetworkFrameworkWorkWithTheEstablishmentReport() { + XCTAsyncTest { + let group = NIOTSEventLoopGroup(loopCount: 1, defaultQoS: .default) + defer { XCTAssertNoThrow(try group.syncShutdownGracefully()) } + let bin = HTTPBin(.http2(compress: false)) + defer { XCTAssertNoThrow(try bin.shutdown()) } + + // Every round has a new client, so every round establishes a connection and asks the Network framework + // how it did that. + for _ in 0..<20 { + let client = Self.makeClient(group: group) + defer { XCTAssertNoThrow(try client.syncShutdown()) } + + let metrics = try await Self.fetch(client, "https://localhost:\(bin.port)/get") + XCTAssertEqual(metrics.connection?.negotiatedProtocol, .http2) + XCTAssertEqual(metrics.connection?.isReused, false) + } + } + } + #endif +} + +// MARK: - Bytes: counters + +final class HTTPByteCountersTests: XCTestCase { + func testRawHandlerCountsWhatIsWrittenAndRead() throws { + let counters = HTTPByteCounters() + let channel = EmbeddedChannel(handler: HTTPRawByteCountingHandler(counters: counters)) + defer { XCTAssertNoThrow(try channel.finish(acceptAlreadyClosed: true)) } + + try channel.writeInbound(ByteBuffer(string: "12345")) + try channel.writeInbound(ByteBuffer(string: "678")) + try channel.writeOutbound(IOData.byteBuffer(ByteBuffer(string: "abcd"))) + + XCTAssertEqual(counters.snapshot(), HTTPByteCounters.Snapshot(sent: 4, received: 8, responseBodyReceived: 0)) + // what was counted is passed on untouched + XCTAssertEqual(try channel.readInbound(as: ByteBuffer.self)?.readableBytes, 5) + XCTAssertEqual(try channel.readInbound(as: ByteBuffer.self)?.readableBytes, 3) + XCTAssertEqual(try channel.readOutbound(as: IOData.self)?.readableBytes, 4) + } + + func testBodyHandlerCountsOnlyBodyParts() throws { + let counters = HTTPByteCounters() + let channel = EmbeddedChannel(handler: HTTPResponseBodyCountingHandler(counters: counters)) + defer { XCTAssertNoThrow(try channel.finish(acceptAlreadyClosed: true)) } + + try channel.writeInbound(HTTPClientResponsePart.head(.init(version: .http1_1, status: .ok))) + try channel.writeInbound(HTTPClientResponsePart.body(ByteBuffer(string: "hello"))) + try channel.writeInbound(HTTPClientResponsePart.body(ByteBuffer(string: "world!"))) + try channel.writeInbound(HTTPClientResponsePart.end(nil)) + + XCTAssertEqual(counters.snapshot().responseBodyReceived, 11) + XCTAssertEqual(counters.snapshot().received, 0) + // and passes all four parts on + for _ in 0..<4 { + XCTAssertNotNil(try channel.readInbound(as: HTTPClientResponsePart.self)) + } + XCTAssertNil(try channel.readInbound(as: HTTPClientResponsePart.self)) + } +} + +// MARK: - Bytes and TLS: recorder + +final class HTTPRequestMetricsBytesTests: XCTestCase { + private let url = URL(string: "https://example.com")! + private let start = NIODeadline.uptimeNanoseconds(10_000_000_000) + + private func info( + _ negotiatedProtocol: HTTPClientTransactionMetrics.Connection.NegotiatedProtocol, + counters: HTTPByteCounters?, + setup: HTTPConnectionSetupRecorder? = nil, + isReused: Bool = false + ) -> HTTPConnectionMetricsInfo { + HTTPConnectionMetricsInfo( + id: 1, + negotiatedProtocol: negotiatedProtocol, + isReused: isReused, + localAddress: nil, + remoteAddress: nil, + setup: setup, + byteCounters: counters, + acquiredAt: self.start + ) + } + + func testHTTP1TransactionIsMeasuredAgainstTheCountersOfTheConnection() throws { + let counters = HTTPByteCounters() + // an earlier transaction on the same connection + counters.addSent(1000) + counters.addReceived(5000) + counters.addResponseBodyReceived(4000) + + var recorder = HTTPRequestMetricsRecorder(url: self.url, now: self.start) + recorder.connectionAcquired(self.info(.http1_1, counters: counters, isReused: true)) + + counters.addSent(120) // the head + recorder.requestHeadSent() + counters.addSent(40 + 13) // a chunked body of 40 bytes and what the encoding adds + recorder.requestBodyBytesWritten(25) + recorder.requestBodyBytesWritten(15) + recorder.requestEnded(at: self.start) + + counters.addReceived(200 + 30 + 77) // a head, the chunk framing and the body + counters.addResponseBodyReceived(77) + recorder.responseBodyBytesDelivered(300) // it was compressed + recorder.responseEnded(at: self.start) + + // what comes later is another transaction's + counters.addSent(999) + counters.addReceived(999) + counters.addResponseBodyReceived(999) + + let metrics = try XCTUnwrap(recorder.finish(error: nil)) + + XCTAssertEqual(metrics.requestHeaderBytesSent, 120) + XCTAssertEqual(metrics.requestBodyBytesSent, 53) + XCTAssertEqual(metrics.requestBodyBytesBeforeEncoding, 40) + XCTAssertEqual(metrics.responseHeaderBytesReceived, 230) + XCTAssertEqual(metrics.responseBodyBytesReceived, 77) + XCTAssertEqual(metrics.responseBodyBytesAfterDecoding, 300) + } + + func testHTTP2TransactionHasNoHeaderBytesAndTheBodyIsWhatWasWritten() throws { + let counters = HTTPByteCounters() + var recorder = HTTPRequestMetricsRecorder(url: self.url, now: self.start) + recorder.connectionAcquired(self.info(.http2, counters: counters)) + + recorder.requestHeadSent() + recorder.requestBodyBytesWritten(64) + recorder.requestEnded(at: self.start) + counters.addResponseBodyReceived(10) + recorder.responseBodyBytesDelivered(10) + recorder.responseEnded(at: self.start) + + let metrics = try XCTUnwrap(recorder.finish(error: nil)) + + XCTAssertNil(metrics.requestHeaderBytesSent) + XCTAssertEqual(metrics.requestBodyBytesSent, 64) + XCTAssertEqual(metrics.requestBodyBytesBeforeEncoding, 64) + XCTAssertNil(metrics.responseHeaderBytesReceived) + XCTAssertEqual(metrics.responseBodyBytesReceived, 10) + XCTAssertEqual(metrics.responseBodyBytesAfterDecoding, 10) + } + + func testTransactionThatEndedBeforeTheResponseWasCompleteKeepsWhatWasCounted() throws { + let counters = HTTPByteCounters() + var recorder = HTTPRequestMetricsRecorder(url: self.url, now: self.start) + recorder.connectionAcquired(self.info(.http1_1, counters: counters)) + counters.addSent(90) + recorder.requestHeadSent() + recorder.requestEnded(at: self.start) + counters.addReceived(150) + counters.addResponseBodyReceived(20) + recorder.responseBodyBytesDelivered(20) + + let metrics = try XCTUnwrap(recorder.finish(error: HTTPClientError.cancelled)) + + XCTAssertEqual(metrics.requestHeaderBytesSent, 90) + XCTAssertEqual(metrics.responseBodyBytesReceived, 20) + XCTAssertEqual(metrics.responseBodyBytesAfterDecoding, 20) + XCTAssertNil(metrics.responseHeaderBytesReceived, "the response was not complete, the head size is not known") + } + + func testTransactionWithoutConnectionHasNoBytes() throws { + var recorder = HTTPRequestMetricsRecorder(url: self.url, now: self.start) + + let metrics = try XCTUnwrap(recorder.finish(error: HTTPClientError.cancelled)) + + XCTAssertNil(metrics.requestHeaderBytesSent) + XCTAssertNil(metrics.responseHeaderBytesReceived) + XCTAssertEqual(metrics.requestBodyBytesSent, 0) + XCTAssertEqual(metrics.responseBodyBytesReceived, 0) + XCTAssertEqual(metrics.responseBodyBytesAfterDecoding, 0) + } + + func testTLSAndProxyAreReportedForReusedConnectionsToo() throws { + let setup = HTTPConnectionSetupRecorder(now: self.start - .seconds(5)) + setup.markConnectStart(at: self.start - .seconds(5)) + setup.markConnectEnd(at: self.start - .seconds(4)) + setup.markProxyConnection() + setup.setTLSVersion(.tlsv13) + setup.setTLSCipherSuite(0x1301) + var recorder = HTTPRequestMetricsRecorder(url: self.url, now: self.start) + recorder.connectionAcquired(self.info(.http1_1, counters: nil, setup: setup, isReused: true)) + + let connection = try XCTUnwrap(recorder.finish(error: nil)?.connection) + + XCTAssertTrue(connection.isReused) + XCTAssertTrue(connection.isProxyConnection) + XCTAssertEqual(connection.tlsVersion, .tlsv13) + XCTAssertEqual(connection.tlsCipherSuite, 0x1301) + XCTAssertNil(connection.connectStartDate, "how it was established is only reported once") + } + + func testVersionOrCipherSuiteThatIsKnownLaterIsNotLostToAnUnknownOne() { + let setup = HTTPConnectionSetupRecorder() + + setup.setTLSVersion(.tlsv12) + setup.setTLSVersion(nil) + setup.setTLSCipherSuite(0xC02F) + setup.setTLSCipherSuite(nil) + + XCTAssertEqual(setup.snapshot().tlsVersion, .tlsv12) + XCTAssertEqual(setup.snapshot().tlsCipherSuite, 0xC02F) + } +} + +/// A server that answers every request with the same bytes, and that knows how many bytes made up the request head. +private final class RawResponder: ChannelInboundHandler { + typealias InboundIn = ByteBuffer + typealias OutboundOut = ByteBuffer + + private let received: NIOLockedValueBox + private let response: String + private var seen = ByteBuffer() + + init(response: String, received: NIOLockedValueBox) { + self.response = response + self.received = received + } + + func channelRead(context: ChannelHandlerContext, data: NIOAny) { + var buffer = self.unwrapInboundIn(data) + self.seen.writeBuffer(&buffer) + if self.seen.getString(at: 0, length: self.seen.readableBytes)?.contains("\r\n\r\n") == true { + let bytes = self.seen.readableBytes + self.received.withLockedValue { $0 = bytes } + context.writeAndFlush(self.wrapOutboundOut(ByteBuffer(string: self.response)), promise: nil) + } + } +} + +// MARK: - Bytes and TLS: through the client + +@available(macOS 10.15, iOS 13.0, watchOS 6.0, tvOS 13.0, *) +final class HTTPClientByteMetricsTests: XCTestCase { + private static func fetch( + _ client: HTTPClient, + _ request: HTTPClientRequest + ) async throws -> (HTTPClientTransactionMetrics, ByteBuffer) { + let collector = MetricsCollector() + let response = try await client.execute(request, timeout: .seconds(10), metrics: collector.record) + let body = try await response.body.collect(upTo: 10 * 1024 * 1024) + return (try XCTUnwrap(collector.metrics.first), body) + } + + private static func makeClient( + group: EventLoopGroup, + configure: (inout HTTPClient.Configuration) -> Void = { _ in } + ) -> HTTPClient { + var config = HTTPClient.Configuration() + config.tlsConfiguration = .clientDefault + config.tlsConfiguration?.certificateVerification = .none + configure(&config) + return HTTPClient(eventLoopGroupProvider: .shared(group), configuration: config) + } + + func testHTTP1TransactionsAreMeasuredOneByOneOnASharedConnection() { + XCTAsyncTest { + let group = MultiThreadedEventLoopGroup(numberOfThreads: 1) + defer { XCTAssertNoThrow(try group.syncShutdownGracefully()) } + let bin = HTTPBin(.http1_1(compress: false)) + defer { XCTAssertNoThrow(try bin.shutdown()) } + let client = Self.makeClient(group: group) + defer { XCTAssertNoThrow(try client.syncShutdown()) } + + let request = HTTPClientRequest(url: "http://localhost:\(bin.port)/get") + let (first, firstBody) = try await Self.fetch(client, request) + let (second, _) = try await Self.fetch(client, request) + + XCTAssertEqual(second.connection?.id, first.connection?.id) + XCTAssertTrue(try XCTUnwrap(first.requestHeaderBytesSent) > 0) + XCTAssertTrue(try XCTUnwrap(first.responseHeaderBytesReceived) > 0) + XCTAssertEqual(first.requestBodyBytesSent, 0) + XCTAssertEqual(first.requestBodyBytesBeforeEncoding, 0) + XCTAssertEqual(first.responseBodyBytesReceived, firstBody.readableBytes) + XCTAssertEqual(first.responseBodyBytesAfterDecoding, firstBody.readableBytes) + // The same request over the same connection costs the same, and does not add up what came before. + XCTAssertEqual(second.requestHeaderBytesSent, first.requestHeaderBytesSent) + XCTAssertEqual(second.responseHeaderBytesReceived, first.responseHeaderBytesReceived) + } + } + + func testHeaderBytesMatchWhatTheServerSawAndWhatItSent() { + XCTAsyncTest { + let serverGroup = MultiThreadedEventLoopGroup(numberOfThreads: 1) + defer { XCTAssertNoThrow(try serverGroup.syncShutdownGracefully()) } + let clientGroup = MultiThreadedEventLoopGroup(numberOfThreads: 1) + defer { XCTAssertNoThrow(try clientGroup.syncShutdownGracefully()) } + + let head = "HTTP/1.1 200 OK\r\nContent-Length: 5\r\nX-Padding: 0123456789\r\n\r\n" + let received = NIOLockedValueBox(0) + let response = head + "hello" + let server = try await ServerBootstrap(group: serverGroup) + .childChannelInitializer { channel in + do { + try channel.pipeline.syncOperations.addHandler( + RawResponder(response: response, received: received) + ) + return channel.eventLoop.makeSucceededVoidFuture() + } catch { + return channel.eventLoop.makeFailedFuture(error) + } + } + .bind(host: "127.0.0.1", port: 0).get() + defer { XCTAssertNoThrow(try server.close().wait()) } + + let client = Self.makeClient(group: clientGroup) + defer { XCTAssertNoThrow(try client.syncShutdown()) } + + let port = try XCTUnwrap(server.localAddress?.port) + let (metrics, body) = try await Self.fetch( + client, + HTTPClientRequest(url: "http://127.0.0.1:\(port)/some/path") + ) + + XCTAssertEqual(body, ByteBuffer(string: "hello")) + XCTAssertEqual(metrics.requestHeaderBytesSent, received.withLockedValue { $0 }) + XCTAssertEqual(metrics.responseHeaderBytesReceived, head.utf8.count) + XCTAssertEqual(metrics.responseBodyBytesReceived, 5) + XCTAssertEqual(metrics.responseBodyBytesAfterDecoding, 5) + } + } + + func testRequestBodyWithKnownLengthIsSentAsIs() { + XCTAsyncTest { + let group = MultiThreadedEventLoopGroup(numberOfThreads: 1) + defer { XCTAssertNoThrow(try group.syncShutdownGracefully()) } + let bin = HTTPBin(.http1_1(compress: false)) + defer { XCTAssertNoThrow(try bin.shutdown()) } + let client = Self.makeClient(group: group) + defer { XCTAssertNoThrow(try client.syncShutdown()) } + + var request = HTTPClientRequest(url: "http://localhost:\(bin.port)/post") + request.method = .POST + request.body = .bytes(ByteBuffer(repeating: UInt8(ascii: "x"), count: 5000)) + let (metrics, _) = try await Self.fetch(client, request) + + XCTAssertEqual(metrics.requestBodyBytesBeforeEncoding, 5000) + XCTAssertEqual(metrics.requestBodyBytesSent, 5000) + XCTAssertTrue(try XCTUnwrap(metrics.requestHeaderBytesSent) > 0) + } + } + + func testChunkedRequestBodyIsLargerOnTheWireThanTheCallerGaveIt() { + XCTAsyncTest { + let group = MultiThreadedEventLoopGroup(numberOfThreads: 1) + defer { XCTAssertNoThrow(try group.syncShutdownGracefully()) } + let bin = HTTPBin(.http1_1(compress: false)) + defer { XCTAssertNoThrow(try bin.shutdown()) } + let client = Self.makeClient(group: group) + defer { XCTAssertNoThrow(try client.syncShutdown()) } + + let parts = AsyncStream { continuation in + continuation.yield(ByteBuffer(repeating: UInt8(ascii: "x"), count: 1000)) + continuation.yield(ByteBuffer(repeating: UInt8(ascii: "y"), count: 2000)) + continuation.finish() + } + var request = HTTPClientRequest(url: "http://localhost:\(bin.port)/post") + request.method = .POST + request.body = .stream(parts, length: .unknown) + let (metrics, _) = try await Self.fetch(client, request) + + XCTAssertEqual(metrics.requestBodyBytesBeforeEncoding, 3000) + XCTAssertGreaterThan(metrics.requestBodyBytesSent, 3000, "every chunk comes with its size and delimiters") + } + } + + func testCompressedResponseCountsTheBytesBeforeAndAfterDecompression() { + XCTAsyncTest { + let group = MultiThreadedEventLoopGroup(numberOfThreads: 1) + defer { XCTAssertNoThrow(try group.syncShutdownGracefully()) } + let bin = HTTPBin(.http1_1(compress: true)) + defer { XCTAssertNoThrow(try bin.shutdown()) } + let client = Self.makeClient(group: group) { $0.decompression = .enabled(limit: .none) } + defer { XCTAssertNoThrow(try client.syncShutdown()) } + + // the server answers a POST with a description of it that contains the whole body + var request = HTTPClientRequest(url: "http://localhost:\(bin.port)/post") + request.method = .POST + request.headers.add(name: "Accept-Encoding", value: "gzip") + request.body = .bytes(ByteBuffer(string: String(repeating: "Lorem ipsum dolor sit amet. ", count: 4000))) + let (metrics, body) = try await Self.fetch(client, request) + + XCTAssertEqual(metrics.responseBodyBytesAfterDecoding, body.readableBytes) + XCTAssertGreaterThan(metrics.responseBodyBytesReceived, 0) + XCTAssertLessThan( + metrics.responseBodyBytesReceived, + metrics.responseBodyBytesAfterDecoding, + "the response was compressed on the wire" + ) + } + } + + func testHTTP2TransactionCountsBodiesAndNotHeaders() { + XCTAsyncTest { + let group = MultiThreadedEventLoopGroup(numberOfThreads: 1) + defer { XCTAssertNoThrow(try group.syncShutdownGracefully()) } + let bin = HTTPBin(.http2(compress: false)) + defer { XCTAssertNoThrow(try bin.shutdown()) } + let client = Self.makeClient(group: group) + defer { XCTAssertNoThrow(try client.syncShutdown()) } + + var request = HTTPClientRequest(url: "https://localhost:\(bin.port)/post-respond-with-byte-count") + request.method = .POST + request.body = .bytes(ByteBuffer(repeating: UInt8(ascii: "x"), count: 3000)) + let (metrics, body) = try await Self.fetch(client, request) + + XCTAssertEqual(metrics.connection?.negotiatedProtocol, .http2) + XCTAssertNil(metrics.requestHeaderBytesSent) + XCTAssertNil(metrics.responseHeaderBytesReceived) + XCTAssertEqual(metrics.requestBodyBytesBeforeEncoding, 3000) + XCTAssertEqual(metrics.requestBodyBytesSent, 3000) + XCTAssertGreaterThan(body.readableBytes, 0) + XCTAssertEqual(metrics.responseBodyBytesReceived, body.readableBytes) + XCTAssertEqual(metrics.responseBodyBytesAfterDecoding, body.readableBytes) + } + } + + func testTLSVersionIsReportedForEveryTransactionAndTheCipherSuiteOnlyWhereKnown() { + XCTAsyncTest { + let group = MultiThreadedEventLoopGroup(numberOfThreads: 1) + defer { XCTAssertNoThrow(try group.syncShutdownGracefully()) } + let bin = HTTPBin(.http1_1(ssl: true)) + defer { XCTAssertNoThrow(try bin.shutdown()) } + let client = Self.makeClient(group: group) + defer { XCTAssertNoThrow(try client.syncShutdown()) } + + let request = HTTPClientRequest(url: "https://localhost:\(bin.port)/get") + let (first, _) = try await Self.fetch(client, request) + let (second, _) = try await Self.fetch(client, request) + + let firstConnection = try XCTUnwrap(first.connection) + XCTAssertFalse(firstConnection.isReused) + XCTAssertNotNil(firstConnection.tlsVersion) + XCTAssertNotNil(firstConnection.secureConnectionStartDate) + XCTAssertNil(firstConnection.tlsCipherSuite, "NIOSSL does not tell") + + let secondConnection = try XCTUnwrap(second.connection) + XCTAssertTrue(secondConnection.isReused) + XCTAssertEqual(secondConnection.tlsVersion, firstConnection.tlsVersion) + XCTAssertNil(secondConnection.secureConnectionStartDate) + } + } + + func testPlainConnectionHasNoTLSInformation() { + XCTAsyncTest { + let group = MultiThreadedEventLoopGroup(numberOfThreads: 1) + defer { XCTAssertNoThrow(try group.syncShutdownGracefully()) } + let bin = HTTPBin(.http1_1(compress: false)) + defer { XCTAssertNoThrow(try bin.shutdown()) } + let client = Self.makeClient(group: group) + defer { XCTAssertNoThrow(try client.syncShutdown()) } + + let (metrics, _) = try await Self.fetch(client, HTTPClientRequest(url: "http://localhost:\(bin.port)/get")) + + XCTAssertNil(metrics.connection?.tlsVersion) + XCTAssertNil(metrics.connection?.tlsCipherSuite) + } + } + + #if canImport(Network) + func testNetworkFrameworkReportsTheTLSVersionAndTheCipherSuite() { + XCTAsyncTest { + let group = NIOTSEventLoopGroup(loopCount: 1, defaultQoS: .default) + defer { XCTAssertNoThrow(try group.syncShutdownGracefully()) } + let bin = HTTPBin(.http1_1(ssl: true)) + defer { XCTAssertNoThrow(try bin.shutdown()) } + let client = Self.makeClient(group: group) + defer { XCTAssertNoThrow(try client.syncShutdown()) } + + let request = HTTPClientRequest(url: "https://localhost:\(bin.port)/get") + let (first, _) = try await Self.fetch(client, request) + let (second, _) = try await Self.fetch(client, request) + + for metrics in [first, second] { + let connection = try XCTUnwrap(metrics.connection) + XCTAssertNotNil(connection.tlsVersion) + XCTAssertNotNil(connection.tlsCipherSuite) + } + // Over the Network framework the bytes are counted above TLS as well. + XCTAssertTrue(try XCTUnwrap(first.requestHeaderBytesSent) > 0) + XCTAssertTrue(try XCTUnwrap(first.responseHeaderBytesReceived) > 0) + } + } + #endif +}