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

.swiftformat

@@ -9,5 +9,6 @@
 --patternlet inline
 --stripunusedargs unnamed-only
 --ranges nospace
+--disable typeSugar # https://github.com/nicklockwood/SwiftFormat/issues/636
 
 # rules

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 NIOFoundationCompat
@@ -533,17 +534,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
         }
@@ -585,13 +588,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 {
@@ -601,13 +609,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)")
                 }
@@ -639,6 +648,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
@@ -656,12 +666,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
     }
 }
 
@@ -717,7 +729,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/HTTPClient.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 NoOpLogHandler: 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/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/NoOpLogHandler.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)
     }

Sources/AsyncHTTPClient/StringConvertibleInstances.swift

@@ -14,6 +14,7 @@
 
 import AsyncHTTPClient
 import Foundation
+import Logging
 import NIO
 import NIOConcurrencyHelpers
 import NIOHTTP1
@@ -752,6 +753,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/ConnectionPoolTests.swift

@@ -105,6 +105,10 @@ extension HTTPClientTests {
             ("testWeHandleUsReceivingACloseHeaderCorrectly", testWeHandleUsReceivingACloseHeaderCorrectly),
             ("testWeHandleUsSendingACloseHeaderAmongstOtherConnectionHeadersCorrectly", testWeHandleUsSendingACloseHeaderAmongstOtherConnectionHeadersCorrectly),
             ("testWeHandleUsReceivingACloseHeaderAmongstOtherConnectionHeadersCorrectly", testWeHandleUsReceivingACloseHeaderAmongstOtherConnectionHeadersCorrectly),
+            ("testLoggingCorrectlyAttachesRequestInformation", testLoggingCorrectlyAttachesRequestInformation),
+            ("testNothingIsLoggedAtInfoOrHigher", testNothingIsLoggedAtInfoOrHigher),
+            ("testAllMethodsLog", testAllMethodsLog),
+            ("testClosingIdleConnectionsInPoolLogsInTheBackground", testClosingIdleConnectionsInPoolLogsInTheBackground),
         ]
     }
 }

Tests/AsyncHTTPClientTests/HTTPClientInternalTests.swift

@@ -16,6 +16,7 @@
 #if canImport(Network)
     import Network
 #endif
+import Logging
 import NIO
 import NIOConcurrencyHelpers
 import NIOFoundationCompat
@@ -33,6 +34,7 @@ class HTTPClientTests: XCTestCase {
     var serverGroup: EventLoopGroup!
     var defaultHTTPBin: HTTPBin!
     var defaultClient: HTTPClient!
+    var backgroundLogStore: CollectEverythingLogHandler.LogStore!
 
     var defaultHTTPBinURLPrefix: String {
         return "http://localhost:\(self.defaultHTTPBin.port)/"
@@ -43,16 +45,25 @@ class HTTPClientTests: XCTestCase {
         XCTAssertNil(self.serverGroup)
         XCTAssertNil(self.defaultHTTPBin)
         XCTAssertNil(self.defaultClient)
+        XCTAssertNil(self.backgroundLogStore)
+
         self.clientGroup = getDefaultEventLoopGroup(numberOfThreads: 1)
         self.serverGroup = MultiThreadedEventLoopGroup(numberOfThreads: 1)
         self.defaultHTTPBin = HTTPBin()
-        self.defaultClient = HTTPClient(eventLoopGroupProvider: .shared(self.clientGroup))
+        self.backgroundLogStore = CollectEverythingLogHandler.LogStore()
+        var backgroundLogger = Logger(label: "\(#function)", factory: { _ in
+            CollectEverythingLogHandler(logStore: self.backgroundLogStore!)
+        })
+        backgroundLogger.logLevel = .trace
+        self.defaultClient = HTTPClient(eventLoopGroupProvider: .shared(self.clientGroup),
+                                        backgroundActivityLogger: backgroundLogger)
     }
 
     override func tearDown() {
-        XCTAssertNotNil(self.defaultClient)
-        XCTAssertNoThrow(try self.defaultClient.syncShutdown())
-        self.defaultClient = nil
+        if let defaultClient = self.defaultClient {
+            XCTAssertNoThrow(try defaultClient.syncShutdown())
+            self.defaultClient = nil
+        }
 
         XCTAssertNotNil(self.defaultHTTPBin)
         XCTAssertNoThrow(try self.defaultHTTPBin.shutdown())
@@ -65,6 +76,9 @@ class HTTPClientTests: XCTestCase {
         XCTAssertNotNil(self.serverGroup)
         XCTAssertNoThrow(try self.serverGroup.syncShutdownGracefully())
         self.serverGroup = nil
+
+        XCTAssertNotNil(self.backgroundLogStore)
+        self.backgroundLogStore = nil
     }
 
     func testRequestURI() throws {
@@ -1793,4 +1807,197 @@ 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-id"],
+                let yoloRequestID = entry.metadata["yolo-request-id"] {
+                XCTAssertNil(entry.metadata["acme-request-id"])
+                XCTAssertEqual("yolo-001", yoloRequestID)
+                XCTAssertNotNil(Int(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-id"],
+                let yoloRequestID = entry.metadata["yolo-request-id"] {
+                XCTAssertNil(entry.metadata["acme-request-id"])
+                XCTAssertEqual("yolo-001", yoloRequestID)
+                XCTAssertNotNil(Int(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: "leasing existing connection")
+        })
+
+        XCTAssert(logsAfterReq3.allSatisfy { entry in
+            if let httpRequestMetadata = entry.metadata["ahc-request-id"],
+                let acmeRequestID = entry.metadata["acme-request-id"] {
+                XCTAssertNil(entry.metadata["yolo-request-id"])
+                XCTAssertEqual("acme-002", acmeRequestID)
+                XCTAssertNotNil(Int(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: "leasing existing 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)
+
+        XCTAssertEqual(0, self.backgroundLogStore.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")
+                XCTAssertNotNil(Int(entry.metadata["ahc-request-id"] ?? "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))
+
+        // No background activity expected here.
+        XCTAssertEqual(0, self.backgroundLogStore.allEntries.count)
+    }
+
+    func testClosingIdleConnectionsInPoolLogsInTheBackground() {
+        XCTAssertNoThrow(try self.defaultClient.get(url: self.defaultHTTPBinURLPrefix + "/get").wait())
+
+        XCTAssertNoThrow(try self.defaultClient.syncShutdown())
+
+        XCTAssertGreaterThanOrEqual(self.backgroundLogStore.allEntries.count, 0)
+        XCTAssert(self.backgroundLogStore.allEntries.contains { entry in
+            entry.message == "closing provider"
+        })
+        XCTAssert(self.backgroundLogStore.allEntries.allSatisfy { entry in
+            entry.metadata["ahc-request-id"] == nil &&
+                entry.metadata["ahc-request"] == nil &&
+                entry.metadata["ahc-provider"] != nil
+        })
+
+        self.defaultClient = nil // so it doesn't get shut down again.
+    }
 }

Tests/AsyncHTTPClientTests/HTTPClientTestUtils.swift

@@ -0,0 +1,70 @@
+# Design of the way AsyncHTTPClient logs
+
+<details>
+  <summary>The logging is strictly separated between request activity & background activity.</summary>
+  AsyncHTTPClient is very much a request-driven library. Almost all work happens when you invoke a request, say `httpClient.get(someURL)`. To preserve the metadata you may have attached to your current `Logger`, we accept a `logger: Logger` parameter on each request. For example to so a `GET` request with logging use the following code.
+
+```swift
+httpClient.get(someURL, logger: myLogger)
+```
+
+  Apart from the request-driven work, AsyncHTTPClient does do some very limited amount of background work, for example expiring connections that stayed unused in the connection pool for too long. Logs associated with the activity from background tasks can be seen only if you attach a `Logger` in `HTTPClient`'s initialiser like below.
+
+```swift
+HTTPClient(eventLoopGroupProvider: .shared(group),
+           backgroundActivityLogger: self.myBackgroundLogger)
+```
+
+The rationale for the strict separation is the correct propagation of the `Logger`'s `metadata`. You are likely to attach request specific information to a `Logger` before passing it to one of AsyncHTTPClient's request methods. This metadata will then be correctly attached to all log messages that occur from AsyncHTTPClient processing this request.
+
+If AsyncHTTPClient does some work in the background (like closing a connection that was long idle) however you likely do _not_ want the request-specific information from some previous request to be attached to those messages. Therefore, those messages get logged with the `backgroundActivityLogger` passed to HTTPClient's initialiser.
+</details>
+<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](https://www.sumologic.com/glossary/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>