From ec05cfd31f5e48150f36c94007d4ccaf626d8f1e Mon Sep 17 00:00:00 2001 From: brennobemoura <37243584+brennobemoura@users.noreply.github.com> Date: Fri, 2 Oct 2026 06:49:58 -0300 Subject: [PATCH 1/5] Add per-transaction HTTP metrics (request/response phases and connection info) Record when a request was queued, started, finished sending, and when the response head and end arrived, plus which connection it ran on (id, h1/h2, reuse, local/remote address). One HTTPClientTransactionMetrics is delivered per transaction, i.e. per redirect hop, through the new HTTPClientResponseDelegate.didCollectMetrics and through new HTTPClient.execute(_:timeout:logger:metrics:) overloads on the async API. Connection setup phases (DNS, connect, TLS) are not covered yet. Co-Authored-By: Claude Sonnet 5.5 --- .../AsyncAwait/HTTPClient+execute.swift | 87 +++- .../AsyncAwait/Transaction.swift | 59 ++- .../HTTP1/HTTP1Connection.swift | 16 + .../HTTP2/HTTP2Connection.swift | 16 + .../HTTPExecutableRequest.swift | 11 + .../AsyncHTTPClient/HTTPClientMetrics.swift | 246 +++++++++++ Sources/AsyncHTTPClient/HTTPHandler.swift | 15 + Sources/AsyncHTTPClient/RequestBag.swift | 62 ++- .../HTTPClientMetricsTests.swift | 404 ++++++++++++++++++ 9 files changed, 894 insertions(+), 22 deletions(-) create mode 100644 Sources/AsyncHTTPClient/HTTPClientMetrics.swift create mode 100644 Tests/AsyncHTTPClientTests/HTTPClientMetricsTests.swift 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..8cdf428de 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() { @@ -179,6 +197,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 +213,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 +227,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 +235,12 @@ 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. + if self.requestFramingMetadata.body == .fixedSize(0) { + let time = NIODeadline.now() + self.metrics.withLockedValue { $0.requestEnded(at: time) } + } } func resumeRequestBodyStream() { @@ -256,6 +286,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 +304,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) } @@ -311,11 +347,15 @@ extension Transaction: HTTPExecutableRequest { } func receiveResponseEnd(_ buffer: CircularBuffer?, trailers: HTTPHeaders?) { + let time = NIODeadline.now() + self.metrics.withLockedValue { $0.responseEnded(at: time) } + 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 +393,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 +426,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..ca36e07c0 100644 --- a/Sources/AsyncHTTPClient/ConnectionPool/HTTP1/HTTP1Connection.swift +++ b/Sources/AsyncHTTPClient/ConnectionPool/HTTP1/HTTP1Connection.swift @@ -37,6 +37,10 @@ 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 + let id: HTTPConnectionPool.Connection.ID init( @@ -113,6 +117,18 @@ 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, + acquiredAt: .now() + ) + ) + self.requestsStarted += 1 + self.channel.pipeline.syncOperations.write(NIOAny(request), promise: nil) } diff --git a/Sources/AsyncHTTPClient/ConnectionPool/HTTP2/HTTP2Connection.swift b/Sources/AsyncHTTPClient/ConnectionPool/HTTP2/HTTP2Connection.swift index 1c24554e2..6f7c45834 100644 --- a/Sources/AsyncHTTPClient/ConnectionPool/HTTP2/HTTP2Connection.swift +++ b/Sources/AsyncHTTPClient/ConnectionPool/HTTP2/HTTP2Connection.swift @@ -84,6 +84,10 @@ 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 let id: HTTPConnectionPool.Connection.ID let decompression: HTTPClient.Decompression let maximumConnectionUses: Int? @@ -254,6 +258,18 @@ final class HTTP2Connection { preconditionFailure("Invalid state: \(self.state). Sending requests is not allowed before we are started.") case .active: + request.connectionAcquired( + HTTPConnectionMetricsInfo( + id: self.id, + negotiatedProtocol: .http2, + isReused: self.requestsStarted > 0, + localAddress: self.channel.localAddress, + remoteAddress: self.channel.remoteAddress, + acquiredAt: .now() + ) + ) + self.requestsStarted += 1 + let createStreamChannelPromise = self.channel.eventLoop.makePromise(of: Channel.self) let loopBoundSelf = NIOLoopBound(self, eventLoop: self.channel.eventLoop) 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/HTTPClientMetrics.swift b/Sources/AsyncHTTPClient/HTTPClientMetrics.swift new file mode 100644 index 000000000..25d2c0fe5 --- /dev/null +++ b/Sources/AsyncHTTPClient/HTTPClientMetrics.swift @@ -0,0 +1,246 @@ +//===----------------------------------------------------------------------===// +// +// 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 + +#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? + + public init( + id: Int, + negotiatedProtocol: NegotiatedProtocol, + isReused: Bool, + localAddress: SocketAddress? = nil, + remoteAddress: SocketAddress? = nil + ) { + self.id = id + self.negotiatedProtocol = negotiatedProtocol + self.isReused = isReused + self.localAddress = localAddress + self.remoteAddress = remoteAddress + } + } + + /// 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`. + 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 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, + 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.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? + 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? + + 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 + } + + mutating func requestEnded(at time: NIODeadline) { + self.requestEndAt = self.requestEndAt ?? time + } + + mutating func responseHeadReceived(at time: NIODeadline) { + self.responseStartAt = self.responseStartAt ?? time + } + + mutating func responseEnded(at time: NIODeadline) { + self.responseEndAt = self.responseEndAt ?? time + } + + /// 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 + + 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), + connection: self.connection.map { + .init( + id: $0.id, + negotiatedProtocol: $0.negotiatedProtocol, + isReused: $0.isReused, + localAddress: $0.localAddress, + remoteAddress: $0.remoteAddress + ) + }, + error: error + ) + } + + 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..3feab2f54 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) @@ -159,6 +165,7 @@ final class RequestBag: Sendabl 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) } } @@ -239,6 +246,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 +256,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 +284,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 +324,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, @@ -327,6 +351,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 +369,8 @@ final class RequestBag: Sendabl } } - private func receiveResponseEnd0(_ buffer: CircularBuffer?) { + private func receiveResponseEnd0(_ buffer: CircularBuffer?, at time: NIODeadline) { + self.loopBoundState.value.metrics.responseEnded(at: time) let action = self.loopBoundState.value.state.receiveResponseEnd(buffer) switch action { @@ -358,6 +384,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 +393,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 +442,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 +504,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 +546,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 +607,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 +628,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/HTTPClientMetricsTests.swift b/Tests/AsyncHTTPClientTests/HTTPClientMetricsTests.swift new file mode 100644 index 000000000..cf8b45428 --- /dev/null +++ b/Tests/AsyncHTTPClientTests/HTTPClientMetricsTests.swift @@ -0,0 +1,404 @@ +//===----------------------------------------------------------------------===// +// +// 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 NIOHTTP1 +import NIOSSL +import XCTest + +#if canImport(FoundationEssentials) +import FoundationEssentials +#else +import Foundation +#endif + +@testable import AsyncHTTPClient + +// 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) + } + } + } +} From c81ad0e66cfab42319fe5310ffd9d25ae0a55d98 Mon Sep 17 00:00:00 2001 From: brennobemoura <37243584+brennobemoura@users.noreply.github.com> Date: Fri, 2 Oct 2026 07:42:08 -0300 Subject: [PATCH 2/5] Add connection setup metrics (DNS, connect, TLS, proxy) The first transaction on a new connection now reports how the connection was established: when the DNS lookup, connecting and the TLS handshake started and ended, and whether it goes through a proxy. Reused connections, and connections that existed before the request started, report none of it. - NIOPosix: DNS is timed by wrapping the resolver. SwiftNIO's default resolver can't be wrapped, so HTTPClient.Configuration.collectDNSMetrics replaces it with a copy that resolves the same way (errors still come from SwiftNIO). The randomized resolver is always timed. - Network.framework: the phases are derived from NWConnection's establishment report, which only has durations. The report is read without holding back the connection, because delaying the hand-over hangs HTTP/2 connections. - Proxies: connecting includes setting up the tunnel, TLS to the target follows. Co-Authored-By: Claude Sonnet 5.5 --- .../HTTP1/HTTP1Connection.swift | 18 +- .../HTTP2/HTTP2Connection.swift | 14 +- .../HTTPConnectionPool+Factory.swift | 143 ++++- .../HTTPConnectionSetupRecorder.swift | 154 +++++ .../ConnectionPool/MeasuredDNSResolver.swift | 177 ++++++ Sources/AsyncHTTPClient/HTTPClient.swift | 13 + .../AsyncHTTPClient/HTTPClientMetrics.swift | 84 ++- .../HTTPClientMetricsTests.swift | 535 +++++++++++++++++- 8 files changed, 1095 insertions(+), 43 deletions(-) create mode 100644 Sources/AsyncHTTPClient/ConnectionPool/HTTPConnectionSetupRecorder.swift create mode 100644 Sources/AsyncHTTPClient/ConnectionPool/MeasuredDNSResolver.swift diff --git a/Sources/AsyncHTTPClient/ConnectionPool/HTTP1/HTTP1Connection.swift b/Sources/AsyncHTTPClient/ConnectionPool/HTTP1/HTTP1Connection.swift index ca36e07c0..2cf5749bb 100644 --- a/Sources/AsyncHTTPClient/ConnectionPool/HTTP1/HTTP1Connection.swift +++ b/Sources/AsyncHTTPClient/ConnectionPool/HTTP1/HTTP1Connection.swift @@ -41,16 +41,21 @@ final class HTTP1Connection { /// are the first on a connection from those that reuse it. private var requestsStarted = 0 + /// How the connection was established. Handed to the first request that runs on the connection. + private let setup: HTTPConnectionSetupRecorder? + 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 { @@ -64,9 +69,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 } @@ -124,6 +135,7 @@ final class HTTP1Connection { isReused: self.requestsStarted > 0, localAddress: self.channel.localAddress, remoteAddress: self.channel.remoteAddress, + setup: self.requestsStarted == 0 ? self.setup : nil, acquiredAt: .now() ) ) diff --git a/Sources/AsyncHTTPClient/ConnectionPool/HTTP2/HTTP2Connection.swift b/Sources/AsyncHTTPClient/ConnectionPool/HTTP2/HTTP2Connection.swift index 6f7c45834..3dc74bf7b 100644 --- a/Sources/AsyncHTTPClient/ConnectionPool/HTTP2/HTTP2Connection.swift +++ b/Sources/AsyncHTTPClient/ConnectionPool/HTTP2/HTTP2Connection.swift @@ -88,6 +88,9 @@ final class HTTP2Connection { /// 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. Handed to the first request that runs on the connection. + private let setup: HTTPConnectionSetupRecorder? let id: HTTPConnectionPool.Connection.ID let decompression: HTTPClient.Decompression let maximumConnectionUses: Int? @@ -103,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 @@ -138,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, @@ -147,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 @@ -265,6 +272,7 @@ final class HTTP2Connection { isReused: self.requestsStarted > 0, localAddress: self.channel.localAddress, remoteAddress: self.channel.remoteAddress, + setup: self.requestsStarted == 0 ? self.setup : nil, acquiredAt: .now() ) ) diff --git a/Sources/AsyncHTTPClient/ConnectionPool/HTTPConnectionPool+Factory.swift b/Sources/AsyncHTTPClient/ConnectionPool/HTTPConnectionPool+Factory.swift index d940ceebd..937835eda 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,7 @@ extension HTTPConnectionPool.ConnectionFactory { return channel.eventLoop.makeFailedFuture(error) } }.flatMap { negotiated -> EventLoopFuture in + setup.markSecureConnectionEnd() do { let sync = channel.pipeline.syncOperations let context = try sync.context(handlerType: TLSEventsHandler.self) @@ -452,7 +495,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 +545,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 +568,7 @@ extension HTTPConnectionPool.ConnectionFactory { deadline: NIODeadline, eventLoop: EventLoop, logger: Logger, + setup: HTTPConnectionSetupRecorder, promise: EventLoopPromise ) { precondition(self.key.scheme.usesTLS, "Unexpected scheme") @@ -535,14 +577,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 +600,10 @@ 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() + return channel.pipeline.syncOperations.removeHandler(tlsEventHandler).map { + (channel, negotiated) + } }.nonisolated() } catch { assert( @@ -581,7 +633,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 +716,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 +750,51 @@ 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 makes HTTP/2 connections hang, 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 + } + 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..788e287a8 --- /dev/null +++ b/Sources/AsyncHTTPClient/ConnectionPool/HTTPConnectionSetupRecorder.swift @@ -0,0 +1,154 @@ +//===----------------------------------------------------------------------===// +// +// 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 + +#if canImport(Network) +import Network +#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 + } + + 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 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 + } +} 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 index 25d2c0fe5..baf6e8f81 100644 --- a/Sources/AsyncHTTPClient/HTTPClientMetrics.swift +++ b/Sources/AsyncHTTPClient/HTTPClientMetrics.swift @@ -54,18 +54,60 @@ public struct HTTPClientTransactionMetrics: Sendable { public var remoteAddress: SocketAddress? + /// Whether the connection goes through a proxy. + public var isProxyConnection: Bool + + // 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 + remoteAddress: SocketAddress? = nil, + isProxyConnection: Bool = false, + 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.domainLookupStartDate = domainLookupStartDate + self.domainLookupEndDate = domainLookupEndDate + self.connectStartDate = connectStartDate + self.connectEndDate = connectEndDate + self.secureConnectionStartDate = secureConnectionStartDate + self.secureConnectionEndDate = secureConnectionEndDate } } @@ -78,7 +120,8 @@ public struct HTTPClientTransactionMetrics: Sendable { /// 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`. + /// 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. @@ -133,6 +176,11 @@ struct HTTPConnectionMetricsInfo: Sendable { var isReused: Bool var localAddress: SocketAddress? var remoteAddress: SocketAddress? + /// How the connection was established. Only the first request on a connection gets this. + /// + /// 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? var acquiredAt: NIODeadline } @@ -194,19 +242,33 @@ struct HTTPRequestMetricsRecorder: Sendable { requestEndDate: self.requestEndAt.map(self.date), responseStartDate: self.responseStartAt.map(self.date), responseEndDate: self.responseEndAt.map(self.date), - connection: self.connection.map { - .init( - id: $0.id, - negotiatedProtocol: $0.negotiatedProtocol, - isReused: $0.isReused, - localAddress: $0.localAddress, - remoteAddress: $0.remoteAddress - ) - }, + connection: self.connection.map(self.makeConnection), error: error ) } + private func makeConnection(_ info: HTTPConnectionMetricsInfo) -> HTTPClientTransactionMetrics.Connection { + // 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 { $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: setup?.isProxyConnection ?? false, + 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) diff --git a/Tests/AsyncHTTPClientTests/HTTPClientMetricsTests.swift b/Tests/AsyncHTTPClientTests/HTTPClientMetricsTests.swift index cf8b45428..8df3d5792 100644 --- a/Tests/AsyncHTTPClientTests/HTTPClientMetricsTests.swift +++ b/Tests/AsyncHTTPClientTests/HTTPClientMetricsTests.swift @@ -16,17 +16,22 @@ import Logging import NIOConcurrencyHelpers import NIOCore import NIOHTTP1 +import NIOPosix import NIOSSL import XCTest +@testable import AsyncHTTPClient + +#if canImport(Network) +import NIOTransportServices +#endif + #if canImport(FoundationEssentials) import FoundationEssentials #else import Foundation #endif -@testable import AsyncHTTPClient - // MARK: - Recorder final class HTTPRequestMetricsRecorderTests: XCTestCase { @@ -402,3 +407,529 @@ final class HTTPClientMetricsTests: XCTestCase { } } } + +// 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 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 +} From 211f8e6267d32404b666dd1c5f10a445198c779f Mon Sep 17 00:00:00 2001 From: brennobemoura <37243584+brennobemoura@users.noreply.github.com> Date: Fri, 2 Oct 2026 08:21:57 -0300 Subject: [PATCH 3/5] Add byte counts, TLS version and cipher suite to the transaction metrics Every transaction now reports how many bytes it moved: the request head and body that were sent, the response head and body that were received, and the body as the caller gets it after decompression. For HTTP/1 they are counted on the connection, which carries one transaction at a time; header sizes are not known for HTTP/2, which compresses the headers and shares the connection. The negotiated TLS version is reported for every transaction on a connection, and so is the cipher suite where the platform tells it. NIOSSL does not, so that is Network.framework only. The Network.framework queries run without holding the connection back, and are skipped when NIOSSL does the TLS: asking NIOTS for TLS metadata of a connection without TLS crashes it. Co-Authored-By: Claude Sonnet 5.5 --- .../AsyncAwait/Transaction.swift | 23 +- .../HTTP1/HTTP1Connection.swift | 10 +- .../HTTP2/HTTP2Connection.swift | 10 +- .../ConnectionPool/HTTPByteCounters.swift | 92 ++++ .../HTTPConnectionPool+Factory.swift | 30 ++ .../HTTPConnectionSetupRecorder.swift | 32 ++ .../AsyncHTTPClient/HTTPClientMetrics.swift | 119 ++++- Sources/AsyncHTTPClient/RequestBag.swift | 6 + .../EmbeddedChannel+HTTPConvenience.swift | 5 +- .../HTTPClientMetricsTests.swift | 479 ++++++++++++++++++ 10 files changed, 792 insertions(+), 14 deletions(-) create mode 100644 Sources/AsyncHTTPClient/ConnectionPool/HTTPByteCounters.swift diff --git a/Sources/AsyncHTTPClient/AsyncAwait/Transaction.swift b/Sources/AsyncHTTPClient/AsyncAwait/Transaction.swift index 8cdf428de..f59ae3295 100644 --- a/Sources/AsyncHTTPClient/AsyncAwait/Transaction.swift +++ b/Sources/AsyncHTTPClient/AsyncAwait/Transaction.swift @@ -85,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: @@ -132,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 @@ -153,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()) @@ -237,9 +241,13 @@ extension Transaction: HTTPExecutableRequest { func requestHeadSent() { // A request without a body is complete as soon as its head was sent, `requestBodyStreamSent` // is not called for it. - if self.requestFramingMetadata.body == .fixedSize(0) { - let time = NIODeadline.now() - self.metrics.withLockedValue { $0.requestEnded(at: time) } + let isComplete = self.requestFramingMetadata.body == .fixedSize(0) + let time = NIODeadline.now() + self.metrics.withLockedValue { + $0.requestHeadSent() + if isComplete { + $0.requestEnded(at: time) + } } } @@ -330,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) } @@ -348,7 +359,11 @@ extension Transaction: HTTPExecutableRequest { func receiveResponseEnd(_ buffer: CircularBuffer?, trailers: HTTPHeaders?) { let time = NIODeadline.now() - self.metrics.withLockedValue { $0.responseEnded(at: time) } + 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) diff --git a/Sources/AsyncHTTPClient/ConnectionPool/HTTP1/HTTP1Connection.swift b/Sources/AsyncHTTPClient/ConnectionPool/HTTP1/HTTP1Connection.swift index 2cf5749bb..421aa5b3c 100644 --- a/Sources/AsyncHTTPClient/ConnectionPool/HTTP1/HTTP1Connection.swift +++ b/Sources/AsyncHTTPClient/ConnectionPool/HTTP1/HTTP1Connection.swift @@ -41,9 +41,12 @@ final class HTTP1Connection { /// are the first on a connection from those that reuse it. private var requestsStarted = 0 - /// How the connection was established. Handed to the first request that runs on the connection. + /// 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( @@ -135,7 +138,8 @@ final class HTTP1Connection { isReused: self.requestsStarted > 0, localAddress: self.channel.localAddress, remoteAddress: self.channel.remoteAddress, - setup: self.requestsStarted == 0 ? self.setup : nil, + setup: self.setup, + byteCounters: self.byteCounters, acquiredAt: .now() ) ) @@ -167,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 3dc74bf7b..0d358db04 100644 --- a/Sources/AsyncHTTPClient/ConnectionPool/HTTP2/HTTP2Connection.swift +++ b/Sources/AsyncHTTPClient/ConnectionPool/HTTP2/HTTP2Connection.swift @@ -89,7 +89,7 @@ final class HTTP2Connection { /// are the first on a connection from those that reuse it. private var requestsStarted = 0 - /// How the connection was established. Handed to the first request that runs on the connection. + /// How the connection was established. private let setup: HTTPConnectionSetupRecorder? let id: HTTPConnectionPool.Connection.ID let decompression: HTTPClient.Decompression @@ -265,6 +265,8 @@ 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, @@ -272,7 +274,8 @@ final class HTTP2Connection { isReused: self.requestsStarted > 0, localAddress: self.channel.localAddress, remoteAddress: self.channel.remoteAddress, - setup: self.requestsStarted == 0 ? self.setup : nil, + setup: self.setup, + byteCounters: byteCounters, acquiredAt: .now() ) ) @@ -298,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 937835eda..d52e2de4a 100644 --- a/Sources/AsyncHTTPClient/ConnectionPool/HTTPConnectionPool+Factory.swift +++ b/Sources/AsyncHTTPClient/ConnectionPool/HTTPConnectionPool+Factory.swift @@ -478,6 +478,7 @@ extension HTTPConnectionPool.ConnectionFactory { } }.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) @@ -601,6 +602,7 @@ extension HTTPConnectionPool.ConnectionFactory { // pipeline. It is created in TLSEventsHandler's handlerAdded method. return tlsEventHandler.tlsEstablishedFuture!.assumeIsolated().flatMap { negotiated in setup.markSecureConnectionEnd() + Self.recordTLSInfo(of: channel, setup: setup) return channel.pipeline.syncOperations.removeHandler(tlsEventHandler).map { (channel, negotiated) } @@ -795,6 +797,34 @@ extension HTTPConnectionPool.ConnectionFactory { #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 index 788e287a8..8cb676dae 100644 --- a/Sources/AsyncHTTPClient/ConnectionPool/HTTPConnectionSetupRecorder.swift +++ b/Sources/AsyncHTTPClient/ConnectionPool/HTTPConnectionSetupRecorder.swift @@ -14,9 +14,11 @@ import NIOConcurrencyHelpers import NIOCore +import NIOSSL #if canImport(Network) import Network +import Security #endif #if canImport(FoundationEssentials) @@ -40,6 +42,8 @@ final class HTTPConnectionSetupRecorder: Sendable { var secureConnectionStart: NIODeadline? var secureConnectionEnd: NIODeadline? var isProxyConnection = false + var tlsVersion: TLSVersion? + var tlsCipherSuite: UInt16? } private let state: NIOLockedValueBox @@ -78,6 +82,14 @@ final class HTTPConnectionSetupRecorder: Sendable { 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 } } @@ -152,3 +164,23 @@ final class HTTPConnectionSetupRecorder: Sendable { 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/HTTPClientMetrics.swift b/Sources/AsyncHTTPClient/HTTPClientMetrics.swift index baf6e8f81..575a245b1 100644 --- a/Sources/AsyncHTTPClient/HTTPClientMetrics.swift +++ b/Sources/AsyncHTTPClient/HTTPClientMetrics.swift @@ -14,6 +14,7 @@ import NIOConcurrencyHelpers import NIOCore +import NIOSSL #if canImport(FoundationEssentials) import FoundationEssentials @@ -57,6 +58,17 @@ public struct HTTPClientTransactionMetrics: Sendable { /// 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. // @@ -89,6 +101,8 @@ public struct HTTPClientTransactionMetrics: Sendable { localAddress: SocketAddress? = nil, remoteAddress: SocketAddress? = nil, isProxyConnection: Bool = false, + tlsVersion: TLSVersion? = nil, + tlsCipherSuite: UInt16? = nil, domainLookupStartDate: Date? = nil, domainLookupEndDate: Date? = nil, connectStartDate: Date? = nil, @@ -102,6 +116,8 @@ public struct HTTPClientTransactionMetrics: Sendable { self.localAddress = localAddress self.remoteAddress = remoteAddress self.isProxyConnection = isProxyConnection + self.tlsVersion = tlsVersion + self.tlsCipherSuite = tlsCipherSuite self.domainLookupStartDate = domainLookupStartDate self.domainLookupEndDate = domainLookupEndDate self.connectStartDate = connectStartDate @@ -140,6 +156,31 @@ public struct HTTPClientTransactionMetrics: Sendable { /// 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? @@ -154,6 +195,12 @@ public struct HTTPClientTransactionMetrics: Sendable { 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 ) { @@ -164,6 +211,12 @@ public struct HTTPClientTransactionMetrics: Sendable { 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 } @@ -176,11 +229,13 @@ struct HTTPConnectionMetricsInfo: Sendable { var isReused: Bool var localAddress: SocketAddress? var remoteAddress: SocketAddress? - /// How the connection was established. Only the first request on a connection gets this. + /// 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 } @@ -199,6 +254,16 @@ struct HTTPRequestMetricsRecorder: Sendable { 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()) { @@ -213,10 +278,24 @@ struct HTTPRequestMetricsRecorder: Sendable { 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) { @@ -225,6 +304,7 @@ struct HTTPRequestMetricsRecorder: Sendable { 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`. @@ -234,6 +314,26 @@ struct HTTPRequestMetricsRecorder: Sendable { } 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, @@ -242,16 +342,23 @@ struct HTTPRequestMetricsRecorder: Sendable { 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 { - // 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. + // 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 { $0.start >= self.fetchStart ? $0 : nil } + let setup = recorded.flatMap { !info.isReused && $0.start >= self.fetchStart ? $0 : nil } return .init( id: info.id, @@ -259,7 +366,9 @@ struct HTTPRequestMetricsRecorder: Sendable { isReused: info.isReused || (recorded != nil && setup == nil), localAddress: info.localAddress, remoteAddress: info.remoteAddress, - isProxyConnection: setup?.isProxyConnection ?? false, + 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), diff --git a/Sources/AsyncHTTPClient/RequestBag.swift b/Sources/AsyncHTTPClient/RequestBag.swift index 3feab2f54..7afa2dcac 100644 --- a/Sources/AsyncHTTPClient/RequestBag.swift +++ b/Sources/AsyncHTTPClient/RequestBag.swift @@ -160,6 +160,7 @@ 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) @@ -228,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) @@ -343,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 @@ -371,6 +374,9 @@ final class RequestBag: Sendabl 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 { 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 index 8df3d5792..4ba295493 100644 --- a/Tests/AsyncHTTPClientTests/HTTPClientMetricsTests.swift +++ b/Tests/AsyncHTTPClientTests/HTTPClientMetricsTests.swift @@ -15,7 +15,9 @@ import Logging import NIOConcurrencyHelpers import NIOCore +import NIOEmbedded import NIOHTTP1 +import NIOHTTPCompression import NIOPosix import NIOSSL import XCTest @@ -912,6 +914,28 @@ final class HTTPClientConnectionSetupMetricsTests: XCTestCase { } } + 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) @@ -933,3 +957,458 @@ final class HTTPClientConnectionSetupMetricsTests: XCTestCase { } #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 + + let received = NIOLockedValueBox(0) + private let response: String + private var seen = ByteBuffer() + + init(response: String) { + self.response = response + } + + 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 responder = RawResponder(response: head + "hello") + let server = try await ServerBootstrap(group: serverGroup) + .childChannelInitializer { channel in channel.pipeline.addHandler(responder) } + .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, responder.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 +} From 0bfbb2bb12d158309c96c1d5cea714e2bfbb2362 Mon Sep 17 00:00:00 2001 From: brennobemoura <37243584+brennobemoura@users.noreply.github.com> Date: Fri, 2 Oct 2026 08:36:56 -0300 Subject: [PATCH 4/5] Make the raw responder of the byte metrics test Sendable-clean The Linux builds of the CI treat warnings as errors and reject sharing the responder through a @Sendable closure. Create one per connection and share the counter through a lock instead. Co-Authored-By: Claude Sonnet 5.5 --- .../HTTPClientMetricsTests.swift | 21 ++++++++++++++----- 1 file changed, 16 insertions(+), 5 deletions(-) diff --git a/Tests/AsyncHTTPClientTests/HTTPClientMetricsTests.swift b/Tests/AsyncHTTPClientTests/HTTPClientMetricsTests.swift index 4ba295493..7b592e5e2 100644 --- a/Tests/AsyncHTTPClientTests/HTTPClientMetricsTests.swift +++ b/Tests/AsyncHTTPClientTests/HTTPClientMetricsTests.swift @@ -1148,12 +1148,13 @@ private final class RawResponder: ChannelInboundHandler { typealias InboundIn = ByteBuffer typealias OutboundOut = ByteBuffer - let received = NIOLockedValueBox(0) + private let received: NIOLockedValueBox private let response: String private var seen = ByteBuffer() - init(response: String) { + init(response: String, received: NIOLockedValueBox) { self.response = response + self.received = received } func channelRead(context: ChannelHandlerContext, data: NIOAny) { @@ -1226,9 +1227,19 @@ final class HTTPClientByteMetricsTests: XCTestCase { 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 responder = RawResponder(response: head + "hello") + let received = NIOLockedValueBox(0) + let response = head + "hello" let server = try await ServerBootstrap(group: serverGroup) - .childChannelInitializer { channel in channel.pipeline.addHandler(responder) } + .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()) } @@ -1242,7 +1253,7 @@ final class HTTPClientByteMetricsTests: XCTestCase { ) XCTAssertEqual(body, ByteBuffer(string: "hello")) - XCTAssertEqual(metrics.requestHeaderBytesSent, responder.received.withLockedValue { $0 }) + XCTAssertEqual(metrics.requestHeaderBytesSent, received.withLockedValue { $0 }) XCTAssertEqual(metrics.responseHeaderBytesReceived, head.utf8.count) XCTAssertEqual(metrics.responseBodyBytesReceived, 5) XCTAssertEqual(metrics.responseBodyBytesAfterDecoding, 5) From bf72233afb01a143baf85ed8de509d913f37e5c9 Mon Sep 17 00:00:00 2001 From: brennobemoura <37243584+brennobemoura@users.noreply.github.com> Date: Fri, 2 Oct 2026 09:18:44 -0300 Subject: [PATCH 5/5] Reword a comment that the unacceptable language check rejects Co-Authored-By: Claude Sonnet 5.5 --- .../ConnectionPool/HTTPConnectionPool+Factory.swift | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/Sources/AsyncHTTPClient/ConnectionPool/HTTPConnectionPool+Factory.swift b/Sources/AsyncHTTPClient/ConnectionPool/HTTPConnectionPool+Factory.swift index d52e2de4a..8c332cc77 100644 --- a/Sources/AsyncHTTPClient/ConnectionPool/HTTPConnectionPool+Factory.swift +++ b/Sources/AsyncHTTPClient/ConnectionPool/HTTPConnectionPool+Factory.swift @@ -779,7 +779,7 @@ extension HTTPConnectionPool.ConnectionFactory { /// connections. /// /// This must not hold the connection back. Putting an asynchronous step between a connection being established - /// and it being handed over makes HTTP/2 connections hang, see `HTTP2ClientTests`. Until the report arrives the + /// 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) {