Add logging to the new ConnectionPool (#428)

fabianfett · web-flow · commit 7c9662d31cfd · 2021-09-20T16:23:09.000+02:00
diff --git a/Sources/AsyncHTTPClient/ConnectionPool.swift b/Sources/AsyncHTTPClient/ConnectionPool.swift
@@ -124,7 +124,7 @@ final class ConnectionPool {
     /// A key is initialized from a `URL`, it uses the components to derive a hashed value
     /// used by the `providers` dictionary to allow retrieving and creating
     /// connection providers associated to a certain request in constant time.
-    struct Key: Hashable {
+    struct Key: Hashable, CustomStringConvertible {
         init(_ request: HTTPClient.Request) {
             switch request.scheme {
             case "http":
@@ -179,6 +179,19 @@ final class ConnectionPool {
             }
             return config
         }
+
+        var description: String {
+            var hasher = Hasher()
+            self.tlsConfiguration?.hash(into: &hasher)
+            let hash = hasher.finalize()
+            var path = ""
+            if self.unixPath != "" {
+                path = self.unixPath
+            } else {
+                path = "\(self.host):\(self.port)"
+            }
+            return "\(self.scheme)://\(path) TLS-hash: \(hash)"
+        }
     }
 }
 
diff --git a/Sources/AsyncHTTPClient/ConnectionPool/HTTP1.1/HTTP1ClientChannelHandler.swift b/Sources/AsyncHTTPClient/ConnectionPool/HTTP1.1/HTTP1ClientChannelHandler.swift
@@ -36,6 +36,7 @@ final class HTTP1ClientChannelHandler: ChannelDuplexHandler {
             if let newRequest = self.request {
                 var requestLogger = newRequest.logger
                 requestLogger[metadataKey: "ahc-connection-id"] = "\(self.connection.id)"
+                requestLogger[metadataKey: "ahc-el"] = "\(self.connection.channel.eventLoop)"
                 self.logger = requestLogger
 
                 if let idleReadTimeout = newRequest.idleReadTimeout {
@@ -120,15 +121,15 @@ final class HTTP1ClientChannelHandler: ChannelDuplexHandler {
     }
 
     func channelReadComplete(context: ChannelHandlerContext) {
-        self.logger.trace("Read complete caught")
+        self.logger.trace("Channel read complete caught")
 
         let action = self.state.channelReadComplete()
         self.run(action, context: context)
     }
 
     func errorCaught(context: ChannelHandlerContext, error: Error) {
-        self.logger.trace("Error caught", metadata: [
-            "error": "\(error)",
+        self.logger.trace("Channel error caught", metadata: [
+            "ahc-error": "\(error)",
         ])
 
         let action = self.state.errorHappened(error)
@@ -142,12 +143,7 @@ final class HTTP1ClientChannelHandler: ChannelDuplexHandler {
         let req = self.unwrapOutboundIn(data)
         self.request = req
 
-        self.logger.trace("New request to execute")
-
-        if let idleReadTimeout = self.request?.idleReadTimeout {
-            self.idleReadTimeoutStateMachine = .init(timeAmount: idleReadTimeout)
-        }
-
+        self.logger.debug("Request was scheduled on connection")
         req.willExecuteRequest(self)
 
         let action = self.state.runNewRequest(head: req.requestHead, metadata: req.requestFramingMetadata)
diff --git a/Sources/AsyncHTTPClient/ConnectionPool/HTTPConnectionPool+Factory.swift b/Sources/AsyncHTTPClient/ConnectionPool/HTTPConnectionPool+Factory.swift
@@ -65,7 +65,7 @@ extension HTTPConnectionPool.ConnectionFactory {
         logger: Logger
     ) {
         var logger = logger
-        logger[metadataKey: "ahc-connection"] = "\(connectionID)"
+        logger[metadataKey: "ahc-connection-id"] = "\(connectionID)"
 
         self.makeChannel(connectionID: connectionID, deadline: deadline, eventLoop: eventLoop, logger: logger).whenComplete { result in
             switch result {
diff --git a/Sources/AsyncHTTPClient/ConnectionPool/HTTPConnectionPool.swift b/Sources/AsyncHTTPClient/ConnectionPool/HTTPConnectionPool.swift
@@ -130,14 +130,7 @@ final class HTTPConnectionPool {
     }
 
     private let stateLock = Lock()
-    private var _state: StateMachine {
-        didSet {
-            self.logger.trace("Connection Pool State changed", metadata: [
-                "key": "\(self.key)",
-                "state": "\(self._state)",
-            ])
-        }
-    }
+    private var _state: StateMachine
 
     private static let fallbackConnectTimeout: TimeAmount = .seconds(30)
 
@@ -175,6 +168,8 @@ final class HTTPConnectionPool {
         self.clientConfiguration = clientConfiguration
         self.key = key
         self.delegate = delegate
+        var logger = logger
+        logger[metadataKey: "ahc-pool-key"] = "\(key)"
         self.logger = logger
 
         self.idleConnectionTimeout = clientConfiguration.connectionPool.idleTimeout
@@ -222,7 +217,11 @@ final class HTTPConnectionPool {
             self.cancelIdleTimerForConnection(connectionID)
 
         case .closeConnection(let connection, isShutdown: let isShutdown):
-            // we are not interested in the close future...
+            self.logger.trace("close connection", metadata: [
+                "ahc-connection-id": "\(connection.id)",
+            ])
+
+            // we are not interested in the close promise...
             connection.close(promise: nil)
 
             if case .yes(let unclean) = isShutdown {
@@ -289,6 +288,9 @@ final class HTTPConnectionPool {
     }
 
     private func createConnection(_ connectionID: Connection.ID, on eventLoop: EventLoop) {
+        self.logger.trace("Opening fresh connection", metadata: [
+            "ahc-connection-id": "\(connectionID)",
+        ])
         // Even though this function is called make it actually creates/establishes a connection.
         // TBD: Should we rename it? To what?
         self.connectionFactory.makeConnection(
@@ -353,6 +355,9 @@ final class HTTPConnectionPool {
     }
 
     private func scheduleIdleTimerForConnection(_ connectionID: Connection.ID, on eventLoop: EventLoop) {
+        self.logger.trace("Schedule idle connection timeout timer", metadata: [
+            "ahc-connection-id": "\(connectionID)",
+        ])
         let scheduled = eventLoop.scheduleTask(in: self.idleConnectionTimeout) {
             // there might be a race between a cancelTimer call and the triggering
             // of this scheduled task. both want to acquire the lock
@@ -375,6 +380,10 @@ final class HTTPConnectionPool {
     }
 
     private func cancelIdleTimerForConnection(_ connectionID: Connection.ID) {
+        self.logger.trace("Cancel idle connection timeout timer", metadata: [
+            "ahc-connection-id": "\(connectionID)",
+        ])
+
         let cancelTimer = self.timerLock.withLock {
             self._idleTimer.removeValue(forKey: connectionID)
         }
@@ -387,6 +396,10 @@ final class HTTPConnectionPool {
         _ timeAmount: TimeAmount,
         on eventLoop: EventLoop
     ) {
+        self.logger.trace("Schedule connection creation backoff timer", metadata: [
+            "ahc-connection-id": "\(connectionID)",
+        ])
+
         let scheduled = eventLoop.scheduleTask(in: timeAmount) {
             // there might be a race between a backoffTimer and the pool shutting down.
             let timerExisted = self.timerLock.withLock {
@@ -420,6 +433,10 @@ final class HTTPConnectionPool {
 
 extension HTTPConnectionPool: HTTPConnectionRequester {
     func http1ConnectionCreated(_ connection: HTTP1Connection) {
+        self.logger.trace("successfully created connection", metadata: [
+            "ahc-connection-id": "\(connection.id)",
+            "ahc-http-version": "http/1.1",
+        ])
         let action = self.stateLock.withLock {
             self._state.newHTTP1ConnectionCreated(.http1_1(connection))
         }
@@ -442,6 +459,10 @@ extension HTTPConnectionPool: HTTPConnectionRequester {
     }
 
     func failedToCreateHTTPConnection(_ connectionID: HTTPConnectionPool.Connection.ID, error: Error) {
+        self.logger.debug("connection attempt failed", metadata: [
+            "ahc-error": "\(error)",
+            "ahc-connection-id": "\(connectionID)",
+        ])
         let action = self.stateLock.withLock {
             self._state.failedToCreateNewConnection(error, connectionID: connectionID)
         }
@@ -451,13 +472,21 @@ extension HTTPConnectionPool: HTTPConnectionRequester {
 
 extension HTTPConnectionPool: HTTP1ConnectionDelegate {
     func http1ConnectionClosed(_ connection: HTTP1Connection) {
+        self.logger.debug("connection closed", metadata: [
+            "ahc-connection-id": "\(connection.id)",
+            "ahc-http-version": "http/1.1",
+        ])
         let action = self.stateLock.withLock {
             self._state.connectionClosed(connection.id)
         }
         self.run(action: action)
     }
 
     func http1ConnectionReleased(_ connection: HTTP1Connection) {
+        self.logger.trace("releasing connection", metadata: [
+            "ahc-connection-id": "\(connection.id)",
+            "ahc-http-version": "http/1.1",
+        ])
         let action = self.stateLock.withLock {
             self._state.http1ConnectionReleased(connection.id)
         }
diff --git a/Sources/AsyncHTTPClient/RequestBag.swift b/Sources/AsyncHTTPClient/RequestBag.swift
@@ -73,6 +73,8 @@ final class RequestBag<Delegate: HTTPClientResponseDelegate> {
     }
 
     private func requestWasQueued0(_ scheduler: HTTPRequestScheduler) {
+        self.logger.debug("Request was queued (waiting for a connection to become available)")
+
         self.task.eventLoop.assertInEventLoop()
         self.state.requestWasQueued(scheduler)
     }

Original file line number	Diff line number	Diff line change
`@@ -73,6 +73,8 @@ final class RequestBag<Delegate: HTTPClientResponseDelegate> {`
`73`	`73`	`}`
`74`	`74`
`75`	`75`	`private func requestWasQueued0(_ scheduler: HTTPRequestScheduler) {`
	`76`	`+ self.logger.debug("Request was queued (waiting for a connection to become available)")`
	`77`	`+`
`76`	`78`	`self.task.eventLoop.assertInEventLoop()`
`77`	`79`	`self.state.requestWasQueued(scheduler)`
`78`	`80`	`}`