logging support

Motivation:

AsyncHTTPClient is not a simple piece of software and nowadays also
quite stateful. To debug issues, the user may want logging.

Modification:

Support passing a logger to the request methods.

Result:

Debugging simplified.

Author: weissi

Package.swift

@@ -25,15 +25,18 @@ let package = Package(
         .package(url: "https://github.com/apple/swift-nio-ssl.git", from: "2.7.0"),
         .package(url: "https://github.com/apple/swift-nio-extras.git", from: "1.3.0"),
         .package(url: "https://github.com/apple/swift-nio-transport-services.git", from: "1.5.1"),
+        .package(url: "https://github.com/apple/swift-log.git", from: "1.0.0"),
     ],
     targets: [
         .target(
             name: "AsyncHTTPClient",
-            dependencies: ["NIO", "NIOHTTP1", "NIOSSL", "NIOConcurrencyHelpers", "NIOHTTPCompression", "NIOFoundationCompat", "NIOTransportServices"]
+            dependencies: ["NIO", "NIOHTTP1", "NIOSSL", "NIOConcurrencyHelpers", "NIOHTTPCompression",
+                           "NIOFoundationCompat", "NIOTransportServices", "Logging"]
         ),
         .testTarget(
             name: "AsyncHTTPClientTests",
-            dependencies: ["NIO", "NIOConcurrencyHelpers", "NIOSSL", "AsyncHTTPClient", "NIOFoundationCompat", "NIOTestUtils"]
+            dependencies: ["NIO", "NIOConcurrencyHelpers", "NIOSSL", "AsyncHTTPClient", "NIOFoundationCompat",
+                           "NIOTestUtils", "Logging"]
         ),
     ]
 )

Sources/AsyncHTTPClient/ConnectionPool.swift

@@ -13,6 +13,7 @@
 //===----------------------------------------------------------------------===//
 
 import Foundation
+import Logging
 import NIO
 import NIOConcurrencyHelpers
 import NIOHTTP1
@@ -64,21 +65,29 @@ final class ConnectionPool {
     /// When the pool is asked for a new connection, it creates a `Key` from the url associated to the `request`. This key
     /// is used to determine if there already exists an associated `HTTP1ConnectionProvider` in `providers`.
     /// If there is, the connection provider then takes care of leasing a new connection. If a connection provider doesn't exist, it is created.
-    func getConnection(for request: HTTPClient.Request, preference: HTTPClient.EventLoopPreference, on eventLoop: EventLoop, deadline: NIODeadline?, setupComplete: EventLoopFuture<Void>) -> EventLoopFuture<Connection> {
+    func getConnection(_ request: HTTPClient.Request,
+                       preference: HTTPClient.EventLoopPreference,
+                       taskEventLoop: EventLoop,
+                       deadline: NIODeadline?,
+                       setupComplete: EventLoopFuture<Void>,
+                       logger: Logger) -> EventLoopFuture<Connection> {
         let key = Key(request)
 
         let provider: HTTP1ConnectionProvider = self.lock.withLock {
             if let existing = self.providers[key], existing.enqueue() {
                 return existing
             } else {
                 // Connection provider will be created with `pending = 1`
-                let provider = HTTP1ConnectionProvider(key: key, eventLoop: eventLoop, configuration: self.configuration, pool: self)
+                let provider = HTTP1ConnectionProvider(key: key,
+                                                       eventLoop: taskEventLoop,
+                                                       configuration: self.configuration,
+                                                       pool: self)
                 self.providers[key] = provider
                 return provider
             }
         }
 
-        return provider.getConnection(preference: preference, setupComplete: setupComplete)
+        return provider.getConnection(preference: preference, setupComplete: setupComplete, logger: logger)
     }
 
     func delete(_ provider: HTTP1ConnectionProvider) {
@@ -167,21 +176,21 @@ class Connection {
     /// Release this `Connection` to its associated `HTTP1ConnectionProvider`.
     ///
     /// - Warning: This only releases the connection and doesn't take care of cleaning handlers in the `Channel` pipeline.
-    func release(closing: Bool) {
+    func release(closing: Bool, logger: Logger) {
         assert(self.channel.eventLoop.inEventLoop)
-        self.provider.release(connection: self, closing: closing)
+        self.provider.release(connection: self, closing: closing, logger: logger)
     }
 
     /// Called when channel exceeds idle time in pool.
-    func timeout() {
+    func timeout(logger: Logger) {
         assert(self.channel.eventLoop.inEventLoop)
-        self.provider.timeout(connection: self)
+        self.provider.timeout(connection: self, logger: logger)
     }
 
     /// Called when channel goes inactive while in the pool.
-    func remoteClosed() {
+    func remoteClosed(logger: Logger) {
         assert(self.channel.eventLoop.inEventLoop)
-        self.provider.remoteClosed(connection: self)
+        self.provider.remoteClosed(connection: self, logger: logger)
     }
 
     func cancel() -> EventLoopFuture<Void> {
@@ -194,9 +203,10 @@ class Connection {
     }
 
     /// Sets idle timeout handler and channel inactivity listener.
-    func setIdleTimeout(timeout: TimeAmount?) {
+    func setIdleTimeout(timeout: TimeAmount?, logger: Logger) {
         _ = self.channel.pipeline.addHandler(IdleStateHandler(writeTimeout: timeout), position: .first).flatMap { _ in
-            self.channel.pipeline.addHandler(IdlePoolConnectionHandler(connection: self))
+            self.channel.pipeline.addHandler(IdlePoolConnectionHandler(connection: self,
+                                                                       logger: logger))
         }
     }
 
@@ -280,50 +290,76 @@ class HTTP1ConnectionProvider {
         self.state.assertInvariants()
     }
 
-    private func execute(_ action: Action) {
+    private func execute(_ action: Action, logger: Logger) {
         switch action {
         case .lease(let connection, let waiter):
             // if connection is became inactive, we create a new one.
             connection.cancelIdleTimeout().whenComplete { _ in
                 if connection.isActiveEstimation {
+                    logger.trace("leasing existing connection",
+                                 metadata: ["ahc-connection": connection])
                     waiter.promise.succeed(connection)
                 } else {
+                    logger.trace("opening fresh connection (found matching but inactive connection)",
+                                 metadata: ["ahc-dead-connection": "\(connection)"])
                     self.makeChannel(preference: waiter.preference).whenComplete { result in
-                        self.connect(result, waiter: waiter, replacing: connection)
+                        self.connect(result, waiter: waiter, replacing: connection, logger: logger)
                     }
                 }
             }
         case .create(let waiter):
+            logger.trace("opening fresh connection (no connections to reuse available)")
             self.makeChannel(preference: waiter.preference).whenComplete { result in
-                self.connect(result, waiter: waiter)
+                self.connect(result, waiter: waiter, logger: logger)
             }
         case .replace(let connection, let waiter):
             connection.cancelIdleTimeout().flatMap {
                 connection.close()
             }.whenComplete { _ in
+                logger.trace("opening fresh connection (replacing exising connection)",
+                             metadata: ["ahc-old-connection": "\(connection)",
+                                        "ahc-waiter": "\(waiter)"])
                 self.makeChannel(preference: waiter.preference).whenComplete { result in
-                    self.connect(result, waiter: waiter, replacing: connection)
+                    self.connect(result, waiter: waiter, replacing: connection, logger: logger)
                 }
             }
         case .park(let connection):
-            connection.setIdleTimeout(timeout: self.configuration.maximumAllowedIdleTimeInConnectionPool)
+            logger.trace("parking connection",
+                         metadata: ["ahc-connection": "\(connection)"])
+            connection.setIdleTimeout(timeout: self.configuration.maximumAllowedIdleTimeInConnectionPool,
+                                      logger: logger.detachingRequestInformation())
         case .closeProvider:
+            logger.debug("closing provider",
+                         metadata: ["ahc-provider": "\(self)"])
             self.closeAndDelete()
         case .none:
             break
         case .parkAnd(let connection, let action):
-            connection.setIdleTimeout(timeout: self.configuration.maximumAllowedIdleTimeInConnectionPool)
-            self.execute(action)
+            logger.trace("parking connection & doing further action",
+                         metadata: ["ahc-connection": "\(connection)",
+                                    "ahc-action": "\(action)"])
+            connection.setIdleTimeout(timeout: self.configuration.maximumAllowedIdleTimeInConnectionPool,
+                                      logger: logger.detachingRequestInformation())
+            self.execute(action, logger: logger)
         case .closeAnd(let connection, let action):
+            logger.trace("closing connection & doing further action",
+                         metadata: ["ahc-connection": "\(connection)",
+                                    "ahc-action": "\(action)"])
             connection.channel.close(promise: nil)
-            self.execute(action)
+            self.execute(action, logger: logger)
         case .cancel(let connection, let close):
+            logger.trace("cancelling connection",
+                         metadata: ["ahc-connection": "\(connection)",
+                                    "ahc-close": "\(close)"])
             connection.cancel().whenComplete { _ in
                 if close {
                     self.closeAndDelete()
                 }
             }
         case .fail(let waiter, let error):
+            logger.debug("failing connection for waiter",
+                         metadata: ["ahc-waiter": "\(waiter)",
+                                    "ahc-error": "\(error)"])
             waiter.promise.fail(error)
         }
     }
@@ -335,19 +371,24 @@ class HTTP1ConnectionProvider {
         }
     }
 
-    func getConnection(preference: HTTPClient.EventLoopPreference, setupComplete: EventLoopFuture<Void>) -> EventLoopFuture<Connection> {
+    func getConnection(preference: HTTPClient.EventLoopPreference,
+                       setupComplete: EventLoopFuture<Void>,
+                       logger: Logger) -> EventLoopFuture<Connection> {
         let waiter = Waiter(promise: self.eventLoop.makePromise(), setupComplete: setupComplete, preference: preference)
 
         let action: Action = self.lock.withLock {
             self.state.acquire(waiter: waiter)
         }
 
-        self.execute(action)
+        self.execute(action, logger: logger)
 
         return waiter.promise.futureResult
     }
 
-    func connect(_ result: Result<Channel, Error>, waiter: Waiter, replacing closedConnection: Connection? = nil) {
+    func connect(_ result: Result<Channel, Error>,
+                 waiter: Waiter,
+                 replacing closedConnection: Connection? = nil,
+                 logger: Logger) {
         let action: Action
         switch result {
         case .success(let channel):
@@ -366,11 +407,13 @@ class HTTP1ConnectionProvider {
             waiter.promise.fail(error)
         }
         waiter.setupComplete.whenComplete { _ in
-            self.execute(action)
+            self.execute(action, logger: logger)
         }
     }
 
-    func release(connection: Connection, closing: Bool) {
+    func release(connection: Connection, closing: Bool, logger: Logger) {
+        logger.debug("releasing connection, request complete",
+                     metadata: ["ahc-closing": "\(closing)"])
         let action: Action = self.lock.withLock {
             self.state.release(connection: connection, closing: closing)
         }
@@ -381,31 +424,31 @@ class HTTP1ConnectionProvider {
         case .park, .closeProvider:
             // Since both `.park` and `.deleteProvider` are terminal in terms of execution,
             // we can execute them immediately
-            self.execute(action)
+            self.execute(action, logger: logger)
         case .cancel, .closeAnd, .create, .fail, .lease, .parkAnd, .replace:
             // This is needed to start a new stack, otherwise, since this is called on a previous
             // future completion handler chain, it will be growing indefinitely until the connection is closed.
             // We might revisit this when https://github.com/apple/swift-nio/issues/970 is resolved.
             connection.channel.eventLoop.execute {
-                self.execute(action)
+                self.execute(action, logger: logger)
             }
         }
     }
 
-    func remoteClosed(connection: Connection) {
+    func remoteClosed(connection: Connection, logger: Logger) {
         let action: Action = self.lock.withLock {
             self.state.remoteClosed(connection: connection)
         }
 
-        self.execute(action)
+        self.execute(action, logger: logger)
     }
 
-    func timeout(connection: Connection) {
+    func timeout(connection: Connection, logger: Logger) {
         let action: Action = self.lock.withLock {
             self.state.timeout(connection: connection)
         }
 
-        self.execute(action)
+        self.execute(action, logger: logger)
     }
 
     private func closeAndDelete() {
@@ -510,25 +553,27 @@ class IdlePoolConnectionHandler: ChannelInboundHandler, RemovableChannelHandler
 
     let connection: Connection
     var eventSent: Bool
+    let logger: Logger
 
-    init(connection: Connection) {
+    init(connection: Connection, logger: Logger) {
         self.connection = connection
         self.eventSent = false
+        self.logger = logger
     }
 
     // this is needed to detect when remote end closes connection while connection is in the pool idling
     func channelInactive(context: ChannelHandlerContext) {
         if !self.eventSent {
             self.eventSent = true
-            self.connection.remoteClosed()
+            self.connection.remoteClosed(logger: self.logger)
         }
     }
 
     func userInboundEventTriggered(context: ChannelHandlerContext, event: Any) {
         if let idleEvent = event as? IdleStateHandler.IdleStateEvent, idleEvent == .write {
             if !self.eventSent {
                 self.eventSent = true
-                self.connection.timeout()
+                self.connection.timeout(logger: self.logger)
             }
         } else {
             context.fireUserInboundEventTriggered(event)

Sources/AsyncHTTPClient/DoNotLogger.swift

@@ -0,0 +1,40 @@
+//===----------------------------------------------------------------------===//
+//
+// This source file is part of the AsyncHTTPClient open source project
+//
+// Copyright (c) 2020 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
+
+internal struct DoNotLogger: LogHandler {
+    func log(level: Logger.Level, message: Logger.Message, metadata: Logger.Metadata?, file: String, function: String, line: UInt) {}
+
+    subscript(metadataKey _: String) -> Logger.Metadata.Value? {
+        get {
+            return nil
+        }
+        set {}
+    }
+
+    var metadata: Logger.Metadata {
+        get {
+            return [:]
+        }
+        set {}
+    }
+
+    var logLevel: Logger.Level {
+        get {
+            return .critical
+        }
+        set {}
+    }
+}

Sources/AsyncHTTPClient/HTTPClient.swift

@@ -13,6 +13,7 @@
 //===----------------------------------------------------------------------===//
 
 import Foundation
+import Logging
 import NIO
 import NIOConcurrencyHelpers
 import NIOFoundationCompat
@@ -494,17 +495,19 @@ extension HTTPClient {
         var connection: Connection?
         var cancelled: Bool
         let lock: Lock
+        let logger: Logger // We are okay to store the logger here because a Task is for only ond request.
 
-        init(eventLoop: EventLoop) {
+        init(eventLoop: EventLoop, logger: Logger) {
             self.eventLoop = eventLoop
             self.promise = eventLoop.makePromise()
             self.completion = self.promise.futureResult.map { _ in }
             self.cancelled = false
             self.lock = Lock()
+            self.logger = logger
         }
 
-        static func failedTask(eventLoop: EventLoop, error: Error) -> Task<Response> {
-            let task = self.init(eventLoop: eventLoop)
+        static func failedTask(eventLoop: EventLoop, error: Error, logger: Logger) -> Task<Response> {
+            let task = self.init(eventLoop: eventLoop, logger: logger)
             task.promise.fail(error)
             return task
         }
@@ -546,13 +549,18 @@ extension HTTPClient {
             }
         }
 
-        func succeed<Delegate: HTTPClientResponseDelegate>(promise: EventLoopPromise<Response>?, with value: Response, delegateType: Delegate.Type, closing: Bool) {
-            self.releaseAssociatedConnection(delegateType: delegateType, closing: closing).whenSuccess {
+        func succeed<Delegate: HTTPClientResponseDelegate>(promise: EventLoopPromise<Response>?,
+                                                           with value: Response,
+                                                           delegateType: Delegate.Type,
+                                                           closing: Bool) {
+            self.releaseAssociatedConnection(delegateType: delegateType,
+                                             closing: closing).whenSuccess {
                 promise?.succeed(value)
             }
         }
 
-        func fail<Delegate: HTTPClientResponseDelegate>(with error: Error, delegateType: Delegate.Type) {
+        func fail<Delegate: HTTPClientResponseDelegate>(with error: Error,
+                                                        delegateType: Delegate.Type) {
             if let connection = self.connection {
                 self.releaseAssociatedConnection(delegateType: delegateType, closing: true)
                     .whenSuccess {
@@ -562,13 +570,14 @@ extension HTTPClient {
             }
         }
 
-        func releaseAssociatedConnection<Delegate: HTTPClientResponseDelegate>(delegateType: Delegate.Type, closing: Bool) -> EventLoopFuture<Void> {
+        func releaseAssociatedConnection<Delegate: HTTPClientResponseDelegate>(delegateType: Delegate.Type,
+                                                                               closing: Bool) -> EventLoopFuture<Void> {
             if let connection = self.connection {
                 // remove read timeout handler
                 return connection.removeHandler(IdleStateHandler.self).flatMap {
                     connection.removeHandler(TaskHandler<Delegate>.self)
                 }.map {
-                    connection.release(closing: closing)
+                    connection.release(closing: closing, logger: self.logger)
                 }.flatMapError { error in
                     fatalError("Couldn't remove taskHandler: \(error)")
                 }
@@ -600,6 +609,7 @@ internal class TaskHandler<Delegate: HTTPClientResponseDelegate>: RemovableChann
     let delegate: Delegate
     let redirectHandler: RedirectHandler<Delegate.Response>?
     let ignoreUncleanSSLShutdown: Bool
+    let logger: Logger // We are okay to store the logger here because a TaskHandler is just for one request.
 
     var state: State = .idle
     var pendingRead = false
@@ -617,12 +627,14 @@ internal class TaskHandler<Delegate: HTTPClientResponseDelegate>: RemovableChann
          kind: HTTPClient.Request.Kind,
          delegate: Delegate,
          redirectHandler: RedirectHandler<Delegate.Response>?,
-         ignoreUncleanSSLShutdown: Bool) {
+         ignoreUncleanSSLShutdown: Bool,
+         logger: Logger) {
         self.task = task
         self.delegate = delegate
         self.redirectHandler = redirectHandler
         self.ignoreUncleanSSLShutdown = ignoreUncleanSSLShutdown
         self.kind = kind
+        self.logger = logger
     }
 }
 
@@ -678,7 +690,10 @@ extension TaskHandler {
             do {
                 let result = try body(self.task)
 
-                self.task.succeed(promise: promise, with: result, delegateType: Delegate.self, closing: self.closing)
+                self.task.succeed(promise: promise,
+                                  with: result,
+                                  delegateType: Delegate.self,
+                                  closing: self.closing)
             } catch {
                 self.task.fail(with: error, delegateType: Delegate.self)
             }

Sources/AsyncHTTPClient/HTTPHandler.swift

@@ -0,0 +1,31 @@
+//===----------------------------------------------------------------------===//
+//
+// This source file is part of the AsyncHTTPClient open source project
+//
+// Copyright (c) 2020 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
+//
+//===----------------------------------------------------------------------===//
+
+extension Connection: CustomStringConvertible {
+    var description: String {
+        return "\(self.channel)"
+    }
+}
+
+extension HTTP1ConnectionProvider.Waiter: CustomStringConvertible {
+    var description: String {
+        return "HTTP1ConnectionProvider.Waiter(\(self.preference))"
+    }
+}
+
+extension HTTPClient.EventLoopPreference: CustomStringConvertible {
+    public var description: String {
+        return "\(self.preference)"
+    }
+}

Sources/AsyncHTTPClient/StringConvertibleInstances.swift

@@ -1229,7 +1229,7 @@ class ConnectionPoolTests: XCTestCase {
         XCTAssertEqual(1, snapshot.pending)
         XCTAssertEqual(1, snapshot.openedConnectionsCount)
 
-        connection.release(closing: false)
+        connection.release(closing: false, logger: HTTPClient.loggingDisabled)
 
         // XCTAssertFalse(connection.isInUse)
         snapshot = provider.state.testsOnly_getInternalState()
@@ -1263,7 +1263,7 @@ class ConnectionPoolTests: XCTestCase {
         XCTAssertEqual(1, snapshot.pending)
         XCTAssertEqual(1, snapshot.openedConnectionsCount)
 
-        connection.release(closing: true)
+        connection.release(closing: true, logger: HTTPClient.loggingDisabled)
 
         snapshot = provider.state.testsOnly_getInternalState()
         XCTAssertEqual(0, snapshot.availableConnections.count)
@@ -1296,7 +1296,7 @@ class ConnectionPoolTests: XCTestCase {
         XCTAssertEqual(1, snapshot.pending)
         XCTAssertEqual(1, snapshot.openedConnectionsCount)
 
-        connection.remoteClosed()
+        connection.remoteClosed(logger: HTTPClient.loggingDisabled)
 
         snapshot = provider.state.testsOnly_getInternalState()
         XCTAssertEqual(0, snapshot.availableConnections.count)
@@ -1329,7 +1329,7 @@ class ConnectionPoolTests: XCTestCase {
         XCTAssertEqual(1, snapshot.pending)
         XCTAssertEqual(1, snapshot.openedConnectionsCount)
 
-        connection.timeout()
+        connection.timeout(logger: HTTPClient.loggingDisabled)
 
         snapshot = provider.state.testsOnly_getInternalState()
         XCTAssertEqual(0, snapshot.availableConnections.count)
@@ -1367,7 +1367,7 @@ class ConnectionPoolTests: XCTestCase {
         switch action {
         case .lease(let connection, let waiter):
             // Since this connection is already in use, this should be a no-op and state should not have changed from normal lease
-            connection.timeout()
+            connection.timeout(logger: HTTPClient.loggingDisabled)
 
             snapshot = provider.state.testsOnly_getInternalState()
             XCTAssertTrue(connection.isActiveEstimation)
@@ -1380,7 +1380,7 @@ class ConnectionPoolTests: XCTestCase {
 
             // This is unrecoverable, but in this case we create a new connection, so state again should not change, even though release will be called
             // This is important to prevent provider deletion since connection is released and there could be 0 waiters
-            connection.remoteClosed()
+            connection.remoteClosed(logger: HTTPClient.loggingDisabled)
 
             snapshot = provider.state.testsOnly_getInternalState()
             XCTAssertTrue(snapshot.leasedConnections.contains(ConnectionKey(connection)))

Tests/AsyncHTTPClientTests/ConnectionPoolTests.swift

@@ -39,14 +39,15 @@ class HTTPClientInternalTests: XCTestCase {
     func testHTTPPartsHandler() throws {
         let channel = EmbeddedChannel()
         let recorder = RecordingHandler<HTTPClientResponsePart, HTTPClientRequestPart>()
-        let task = Task<Void>(eventLoop: channel.eventLoop)
+        let task = Task<Void>(eventLoop: channel.eventLoop, logger: HTTPClient.loggingDisabled)
 
         try channel.pipeline.addHandler(recorder).wait()
         try channel.pipeline.addHandler(TaskHandler(task: task,
                                                     kind: .host,
                                                     delegate: TestHTTPDelegate(),
                                                     redirectHandler: nil,
-                                                    ignoreUncleanSSLShutdown: false)).wait()
+                                                    ignoreUncleanSSLShutdown: false,
+                                                    logger: HTTPClient.loggingDisabled)).wait()
 
         var request = try Request(url: "http://localhost/get")
         request.headers.add(name: "X-Test-Header", value: "X-Test-Value")
@@ -69,14 +70,15 @@ class HTTPClientInternalTests: XCTestCase {
     func testBadHTTPRequest() throws {
         let channel = EmbeddedChannel()
         let recorder = RecordingHandler<HTTPClientResponsePart, HTTPClientRequestPart>()
-        let task = Task<Void>(eventLoop: channel.eventLoop)
+        let task = Task<Void>(eventLoop: channel.eventLoop, logger: HTTPClient.loggingDisabled)
 
         XCTAssertNoThrow(try channel.pipeline.addHandler(recorder).wait())
         XCTAssertNoThrow(try channel.pipeline.addHandler(TaskHandler(task: task,
                                                                      kind: .host,
                                                                      delegate: TestHTTPDelegate(),
                                                                      redirectHandler: nil,
-                                                                     ignoreUncleanSSLShutdown: false)).wait())
+                                                                     ignoreUncleanSSLShutdown: false,
+                                                                     logger: HTTPClient.loggingDisabled)).wait())
 
         var request = try Request(url: "http://localhost/get")
         request.headers.add(name: "X-Test-Header", value: "X-Test-Value")
@@ -91,12 +93,13 @@ class HTTPClientInternalTests: XCTestCase {
     func testHTTPPartsHandlerMultiBody() throws {
         let channel = EmbeddedChannel()
         let delegate = TestHTTPDelegate()
-        let task = Task<Void>(eventLoop: channel.eventLoop)
+        let task = Task<Void>(eventLoop: channel.eventLoop, logger: HTTPClient.loggingDisabled)
         let handler = TaskHandler(task: task,
                                   kind: .host,
                                   delegate: delegate,
                                   redirectHandler: nil,
-                                  ignoreUncleanSSLShutdown: false)
+                                  ignoreUncleanSSLShutdown: false,
+                                  logger: HTTPClient.loggingDisabled)
 
         try channel.pipeline.addHandler(handler).wait()
 
@@ -573,19 +576,20 @@ class HTTPClientInternalTests: XCTestCase {
         // This is pretty evil but we literally just get hold of a connection to get to the channel to be able to
         // observe when the server closing the connection is known to the client.
         let el = group.next()
-        XCTAssertNoThrow(maybeConnection = try client.pool.getConnection(for: .init(url: url),
+        XCTAssertNoThrow(maybeConnection = try client.pool.getConnection(Request(url: url),
                                                                          preference: .indifferent,
-                                                                         on: el,
+                                                                         taskEventLoop: el,
                                                                          deadline: nil,
-                                                                         setupComplete: el.makeSucceededFuture(())).wait())
+                                                                         setupComplete: el.makeSucceededFuture(()),
+                                                                         logger: HTTPClient.loggingDisabled).wait())
         guard let connection = maybeConnection else {
             XCTFail("couldn't get connection")
             return
         }
 
         // And let's also give the connection back :).
         try connection.channel.eventLoop.submit {
-            connection.release(closing: false)
+            connection.release(closing: false, logger: HTTPClient.loggingDisabled)
         }.wait()
 
         XCTAssertEqual(0, sharedStateServerHandler.requestNumber.load())
@@ -622,19 +626,20 @@ class HTTPClientInternalTests: XCTestCase {
                                               body: nil)
             var maybeConnection: Connection?
             let el = client.eventLoopGroup.next()
-            XCTAssertNoThrow(try maybeConnection = client.pool.getConnection(for: req,
+            XCTAssertNoThrow(try maybeConnection = client.pool.getConnection(req,
                                                                              preference: .indifferent,
-                                                                             on: el,
+                                                                             taskEventLoop: el,
                                                                              deadline: nil,
-                                                                             setupComplete: el.makeSucceededFuture(())).wait())
+                                                                             setupComplete: el.makeSucceededFuture(()),
+                                                                             logger: HTTPClient.loggingDisabled).wait())
             guard let connection = maybeConnection else {
                 XCTFail("couldn't make connection")
                 throw NoChannelError()
             }
 
             let channel = connection.channel
             try! channel.eventLoop.submit {
-                connection.release(closing: true)
+                connection.release(closing: true, logger: HTTPClient.loggingDisabled)
             }.wait()
             return (web, channel)
         })
@@ -707,11 +712,12 @@ class HTTPClientInternalTests: XCTestCase {
         // Let's start by getting a connection so we can mess with the Channel :).
         var maybeConnection: Connection?
         let el = client.eventLoopGroup.next()
-        XCTAssertNoThrow(try maybeConnection = client.pool.getConnection(for: req,
+        XCTAssertNoThrow(try maybeConnection = client.pool.getConnection(req,
                                                                          preference: .indifferent,
-                                                                         on: el,
+                                                                         taskEventLoop: el,
                                                                          deadline: nil,
-                                                                         setupComplete: el.makeSucceededFuture(())).wait())
+                                                                         setupComplete: el.makeSucceededFuture(()),
+                                                                         logger: HTTPClient.loggingDisabled).wait())
         guard let connection = maybeConnection else {
             XCTFail("couldn't make connection")
             return
@@ -725,7 +731,7 @@ class HTTPClientInternalTests: XCTestCase {
                                                                                            sawTheClosePromise: sawTheClosePromise),
                                                          position: .first).wait())
         try! connection.channel.eventLoop.submit {
-            connection.release(closing: false)
+            connection.release(closing: false, logger: HTTPClient.loggingDisabled)
         }.wait()
 
         XCTAssertNoThrow(try client.execute(request: req).wait())
@@ -742,11 +748,12 @@ class HTTPClientInternalTests: XCTestCase {
         // When asking for a connection again, we should _not_ get the same one back because we did most of the close,
         // similar to what the SSLHandler would do.
         let el2 = client.eventLoopGroup.next()
-        let connection2Future = client.pool.getConnection(for: req,
+        let connection2Future = client.pool.getConnection(req,
                                                           preference: .indifferent,
-                                                          on: el2,
+                                                          taskEventLoop: el2,
                                                           deadline: nil,
-                                                          setupComplete: el2.makeSucceededFuture(()))
+                                                          setupComplete: el2.makeSucceededFuture(()),
+                                                          logger: HTTPClient.loggingDisabled)
         doActualCloseNowPromise.succeed(())
 
         XCTAssertNoThrow(try maybeConnection = connection2Future.wait())
@@ -757,7 +764,7 @@ class HTTPClientInternalTests: XCTestCase {
 
         XCTAssert(connection !== connection2)
         try! connection2.channel.eventLoop.submit {
-            connection2.release(closing: true)
+            connection2.release(closing: true, logger: HTTPClient.loggingDisabled)
         }.wait()
         XCTAssertTrue(connection2.channel.isActive)
     }

Tests/AsyncHTTPClientTests/HTTPClientInternalTests.swift

@@ -14,6 +14,7 @@
 
 import AsyncHTTPClient
 import Foundation
+import Logging
 import NIO
 import NIOConcurrencyHelpers
 import NIOHTTP1
@@ -753,6 +754,60 @@ extension EventLoopFuture {
     }
 }
 
+struct CollectEverythingLogHandler: LogHandler {
+    var metadata: Logger.Metadata = [:]
+    var logLevel: Logger.Level = .info
+    let logStore: LogStore
+
+    class LogStore {
+        struct Entry {
+            var level: Logger.Level
+            var message: String
+            var metadata: [String: String]
+        }
+
+        var lock = Lock()
+        var logs: [Entry] = []
+
+        var allEntries: [Entry] {
+            get {
+                return self.lock.withLock { self.logs }
+            }
+            set {
+                self.lock.withLock { self.logs = newValue }
+            }
+        }
+
+        func append(level: Logger.Level, message: Logger.Message, metadata: Logger.Metadata?) {
+            self.lock.withLock {
+                self.logs.append(Entry(level: level,
+                                       message: message.description,
+                                       metadata: metadata?.mapValues { $0.description } ?? [:]))
+            }
+        }
+    }
+
+    init(logStore: LogStore) {
+        self.logStore = logStore
+    }
+
+    func log(level: Logger.Level,
+             message: Logger.Message,
+             metadata: Logger.Metadata?,
+             file: String, function: String, line: UInt) {
+        self.logStore.append(level: level, message: message, metadata: self.metadata.merging(metadata ?? [:]) { $1 })
+    }
+
+    subscript(metadataKey key: String) -> Logger.Metadata.Value? {
+        get {
+            return self.metadata[key]
+        }
+        set {
+            self.metadata[key] = newValue
+        }
+    }
+}
+
 private let cert = """
 -----BEGIN CERTIFICATE-----
 MIICmDCCAYACCQCPC8JDqMh1zzANBgkqhkiG9w0BAQsFADANMQswCQYDVQQGEwJ1

Tests/AsyncHTTPClientTests/HTTPClientTestUtils.swift

@@ -103,6 +103,9 @@ extension HTTPClientTests {
             ("testWeHandleUsReceivingACloseHeaderCorrectly", testWeHandleUsReceivingACloseHeaderCorrectly),
             ("testWeHandleUsSendingACloseHeaderAmongstOtherConnectionHeadersCorrectly", testWeHandleUsSendingACloseHeaderAmongstOtherConnectionHeadersCorrectly),
             ("testWeHandleUsReceivingACloseHeaderAmongstOtherConnectionHeadersCorrectly", testWeHandleUsReceivingACloseHeaderAmongstOtherConnectionHeadersCorrectly),
+            ("testLoggingCorrectlyAttachesRequestInformation", testLoggingCorrectlyAttachesRequestInformation),
+            ("testNothingIsLoggedAtInfoOrHigher", testNothingIsLoggedAtInfoOrHigher),
+            ("testAllMethodsLog", testAllMethodsLog),
         ]
     }
 }

Tests/AsyncHTTPClientTests/HTTPClientTests+XCTest.swift

@@ -16,6 +16,7 @@
 #if canImport(Network)
     import Network
 #endif
+import Logging
 import NIO
 import NIOConcurrencyHelpers
 import NIOFoundationCompat
@@ -1756,4 +1757,174 @@ class HTTPClientTests: XCTestCase {
             XCTAssertEqual(stats2.connectionNumber, stats3.connectionNumber)
         }
     }
+
+    func testLoggingCorrectlyAttachesRequestInformation() {
+        let logStore = CollectEverythingLogHandler.LogStore()
+
+        var loggerYolo001: Logger = Logger(label: "\(#function)", factory: { _ in
+            CollectEverythingLogHandler(logStore: logStore)
+        })
+        loggerYolo001.logLevel = .trace
+        loggerYolo001[metadataKey: "yolo-request-id"] = "yolo-001"
+        var loggerACME002: Logger = Logger(label: "\(#function)", factory: { _ in
+            CollectEverythingLogHandler(logStore: logStore)
+        })
+        loggerACME002.logLevel = .trace
+        loggerACME002[metadataKey: "acme-request-id"] = "acme-002"
+
+        guard let request1 = try? HTTPClient.Request(url: self.defaultHTTPBinURLPrefix + "get"),
+            let request2 = try? HTTPClient.Request(url: self.defaultHTTPBinURLPrefix + "stats"),
+            let request3 = try? HTTPClient.Request(url: self.defaultHTTPBinURLPrefix + "ok") else {
+            XCTFail("bad stuff, can't even make request structures")
+            return
+        }
+
+        // === Request 1 (Yolo001)
+        XCTAssertNoThrow(try self.defaultClient.execute(request: request1,
+                                                        eventLoop: .indifferent,
+                                                        deadline: nil,
+                                                        logger: loggerYolo001).wait())
+        let logsAfterReq1 = logStore.allEntries
+        logStore.allEntries = []
+
+        // === Request 2 (Yolo001)
+        XCTAssertNoThrow(try self.defaultClient.execute(request: request2,
+                                                        eventLoop: .indifferent,
+                                                        deadline: nil,
+                                                        logger: loggerYolo001).wait())
+        let logsAfterReq2 = logStore.allEntries
+        logStore.allEntries = []
+
+        // === Request 3 (ACME002)
+        XCTAssertNoThrow(try self.defaultClient.execute(request: request3,
+                                                        eventLoop: .indifferent,
+                                                        deadline: nil,
+                                                        logger: loggerACME002).wait())
+        let logsAfterReq3 = logStore.allEntries
+        logStore.allEntries = []
+
+        // === Assertions
+        XCTAssertGreaterThan(logsAfterReq1.count, 0)
+        XCTAssertGreaterThan(logsAfterReq2.count, 0)
+        XCTAssertGreaterThan(logsAfterReq3.count, 0)
+
+        XCTAssert(logsAfterReq1.allSatisfy { entry in
+            if let httpRequestMetadata = entry.metadata["ahc-request"],
+                let yoloRequestID = entry.metadata["yolo-request-id"] {
+                XCTAssertNil(entry.metadata["acme-request-id"])
+                XCTAssertEqual("yolo-001", yoloRequestID)
+                XCTAssertEqual("GET \(self.defaultHTTPBinURLPrefix)get", httpRequestMetadata)
+                return true
+            } else {
+                XCTFail("log message doesn't contain the right IDs: \(entry)")
+                return false
+            }
+        })
+        XCTAssert(logsAfterReq1.contains { entry in
+            entry.message == "opening fresh connection (no connections to reuse available)"
+        })
+
+        XCTAssert(logsAfterReq2.allSatisfy { entry in
+            if let httpRequestMetadata = entry.metadata["ahc-request"],
+                let yoloRequestID = entry.metadata["yolo-request-id"] {
+                XCTAssertNil(entry.metadata["acme-request-id"])
+                XCTAssertEqual("yolo-001", yoloRequestID)
+                XCTAssertEqual("GET \(self.defaultHTTPBinURLPrefix)stats", httpRequestMetadata)
+                return true
+            } else {
+                XCTFail("log message doesn't contain the right IDs: \(entry)")
+                return false
+            }
+        })
+        XCTAssert(logsAfterReq2.contains { entry in
+            entry.message.starts(with: "reusing active connection ")
+        })
+
+        XCTAssert(logsAfterReq3.allSatisfy { entry in
+            if let httpRequestMetadata = entry.metadata["ahc-request"],
+                let acmeRequestID = entry.metadata["acme-request-id"] {
+                XCTAssertNil(entry.metadata["yolo-request-id"])
+                XCTAssertEqual("acme-002", acmeRequestID)
+                XCTAssertEqual("GET \(self.defaultHTTPBinURLPrefix)ok", httpRequestMetadata)
+                return true
+            } else {
+                XCTFail("log message doesn't contain the right IDs: \(entry)")
+                return false
+            }
+        })
+        XCTAssert(logsAfterReq3.contains { entry in
+            entry.message.starts(with: "reusing active connection ")
+        })
+    }
+
+    func testNothingIsLoggedAtInfoOrHigher() {
+        let logStore = CollectEverythingLogHandler.LogStore()
+
+        var logger: Logger = Logger(label: "\(#function)", factory: { _ in
+            CollectEverythingLogHandler(logStore: logStore)
+        })
+        logger.logLevel = .info
+
+        guard let request1 = try? HTTPClient.Request(url: self.defaultHTTPBinURLPrefix + "get"),
+            let request2 = try? HTTPClient.Request(url: self.defaultHTTPBinURLPrefix + "stats") else {
+            XCTFail("bad stuff, can't even make request structures")
+            return
+        }
+
+        // === Request 1
+        XCTAssertNoThrow(try self.defaultClient.execute(request: request1,
+                                                        eventLoop: .indifferent,
+                                                        deadline: nil,
+                                                        logger: logger).wait())
+        XCTAssertEqual(0, logStore.allEntries.count)
+
+        // === Request 2
+        XCTAssertNoThrow(try self.defaultClient.execute(request: request2,
+                                                        eventLoop: .indifferent,
+                                                        deadline: nil,
+                                                        logger: logger).wait())
+        XCTAssertEqual(0, logStore.allEntries.count)
+    }
+
+    func testAllMethodsLog() {
+        func checkExpectationsWithLogger<T>(type: String, _ body: (Logger, String) throws -> T) throws -> T {
+            let logStore = CollectEverythingLogHandler.LogStore()
+
+            var logger: Logger = Logger(label: "\(#function)", factory: { _ in
+                CollectEverythingLogHandler(logStore: logStore)
+            })
+            logger.logLevel = .trace
+            logger[metadataKey: "req"] = "yo-\(type)"
+
+            let url = self.defaultHTTPBinURLPrefix + "not-found/request/\(type))"
+            let result = try body(logger, url)
+
+            XCTAssertGreaterThan(logStore.allEntries.count, 0)
+            logStore.allEntries.forEach { entry in
+                XCTAssertEqual("yo-\(type)", entry.metadata["req"] ?? "n/a")
+                XCTAssertEqual("\(type) \(url)", entry.metadata["ahc-request"] ?? "n/a")
+            }
+            return result
+        }
+
+        XCTAssertNoThrow(XCTAssertEqual(.notFound, try checkExpectationsWithLogger(type: "GET") { logger, url in
+            try self.defaultClient.get(url: url, logger: logger).wait()
+        }.status))
+
+        XCTAssertNoThrow(XCTAssertEqual(.notFound, try checkExpectationsWithLogger(type: "PUT") { logger, url in
+            try self.defaultClient.put(url: url, logger: logger).wait()
+        }.status))
+
+        XCTAssertNoThrow(XCTAssertEqual(.notFound, try checkExpectationsWithLogger(type: "POST") { logger, url in
+            try self.defaultClient.post(url: url, logger: logger).wait()
+        }.status))
+
+        XCTAssertNoThrow(XCTAssertEqual(.notFound, try checkExpectationsWithLogger(type: "DELETE") { logger, url in
+            try self.defaultClient.delete(url: url, logger: logger).wait()
+        }.status))
+
+        XCTAssertNoThrow(XCTAssertEqual(.notFound, try checkExpectationsWithLogger(type: "PATCH") { logger, url in
+            try self.defaultClient.patch(url: url, logger: logger).wait()
+        }.status))
+    }
 }

Tests/AsyncHTTPClientTests/HTTPClientTests.swift

@@ -0,0 +1,51 @@
+# Design of the way AsyncHTTPClient logs
+
+<details>
+  <summary>Unless you explicitly pass AsyncHTTPClient a `Logger` instance, nothing is ever logged.</summary>
+  AsyncHTTPClient is useful in many places where you wouldn't want to log, for example a command line HTTP client. Also, we do not want to change its default behaviour in a minor release.
+</details>
+<details>
+  <summary>Nothing is logged at level `info` or higher, unless something is really wrong that cannot be communicated through the API.</summary>
+  Fundamentally, AsyncHTTPClient performs a simple task, it makes a HTTP request and communicates the outcome back via its API. In normal usage, we would not expect people to want AsyncHTTPClient to log. In certain scenarios, for example when debugging why a request takes longer than expected it may however be useful to get information about AsyncHTTPClient's connection pool. That is when enabling logging may become useful.
+</details>
+<details>
+  <summary>Each request will get a globally unique request ID (`ahc-request-id`) that will be attached (as metadata) to each log message relevant to a request.</summary>
+  When many concurrent requests are active, it can be challenging to figure out which log message is associated with which request. To facilitate this task, AsyncHTTPClient will add a metadata field `ahc-request-id` to each log message so you can first find the request ID that is causing issues and then filter only messages with that ID.
+</details>
+<details>
+  <summary>Your `Logger` metadata is preserved.</summary>
+  AsyncHTTPClient accepts a `Logger` on every request method. This means that all the metadata you have attached, will be present on log messages issued by AsyncHTTPClient.
+
+ For example, if you attach `["my-system-req-uuid": "84B453E0-0DFD-4B4B-BF22-3434812C9015"]` and then do two requests using AsyncHTTPClient, both of those requests will carry `"my-system-req-uuid` as well as AsyncHTTPClient's `ahc-request-id`. This allows you to filter all HTTP request made from one of your system's requests whilst still disambiguating the HTTP requests (they will have different `ahc-request-id`s.
+</details>
+<details>
+  <summary>Instead of accepting one `Logger` instance per `HTTPClient` instance, each request method can accept a `Logger`.</summary>
+  This allows AsyncHTTPClient to preserve your metadata and add its own metadata such as `ahc-request-id`.
+</details>
+<details>
+  <summary>All logs use the structured logging pattern, i.e. only static log messages and accompanying key/value metadata are used.</summary>
+  None of the log messages issued by AsyncHTTPClient will use String interpolation which means they will always be the exact same message.
+
+  For example when AsyncHTTPClient wants to tell you it got an actual network connection to perform a request on, it will give the logger the following pieces of information:
+
+  - message: `got connection for request`
+  - metadata (the values are example):
+    - `ahc-request-id`: `0`
+    - `ahc-connection`: `SocketChannel { BaseSocket { fd=15 }, active = true, localAddress = Optional([IPv4]127.0.0.1/127.0.0.1:54459), remoteAddress = Optional([IPv4]127.0.0.1/127.0.0.1:54457) }`
+
+  As you can see above, the log message doesn't actually contain the request or the network connection. Both of those pieces of information are in the `metadata`.
+
+  The rationale is that many people use log aggregation systems where it is very useful to aggregate, search and group by log message, or specific metadata values. This is greatly simplified by using a constant string (relatively stable) string and explicitly marked metadata values which make it easy to filter by.
+</details>
+<details>
+  <summary>`debug` should be enough to diagnose most problems but information that can be correlated is usually skipped.</summary>
+  When crafting log messages, it's often hard to strike a balance between logging everything and logging just enough. A rule of thumb is that you have to assume someone may be running with `logLevel = .debug` in production. So it can't be too much. Yet `.trace` can log everything you would need to know when debugging a tricky implementation issue. We assume nobody is running in production with `logLevel = .trace`.
+
+  The problem with logging everything is that logging itself becomes very slow. We want logging in `debug` level to still be reasonably performant and therefore avoid logging information that can be correlated from other log messages.
+
+  For example, AsyncHTTPClient may tell you in two log messages that it `got a connection` (from the connection pool) and a little later that it's `parking connection` (in the connection pool). Just like all messages, both of them will have an associated `ahc-request-id` which makes it possible to correlate the two log messages. The message that logs that we actually got a network connection will also include information about this network connection. The message that we're now parking the connection however _will not_. The information which connection is being parked can be found by filtering all other log messages with the same `ahc-request-id`.
+</details>
+<details>
+  <summary>In `trace`, AsyncHTTPClient may log _a lot_.</summary>
+  In the `.trace` log level, AsyncHTTPClient basically logs all the information that it has handily available. The frugality considerations we take in `.debug` do not apply here. We just want to log as much information as possible. This is useful almost exclusively for local debugging and should almost certainly not be sent into a log aggregation system where the information might be persisted for a long time. This also means, handing AsyncHTTPClient a logger in `logLevel = .trace` may have a fairly serious performance impact.
+</details>