diff --git a/Sources/AsyncHTTPClient/ConnectionPool.swift b/Sources/AsyncHTTPClient/ConnectionPool.swift index b80c6d485..db1b22e8b 100644 --- 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 index f5e50fb33..910be3d1d 100644 --- 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 index e321e6172..5cc49c994 100644 --- 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 index c4759a6c0..924ed17eb 100644 --- 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,6 +472,10 @@ 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) } @@ -458,6 +483,10 @@ extension HTTPConnectionPool: HTTP1ConnectionDelegate { } 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 index 8da4ca480..1be6ba9d2 100644 --- a/Sources/AsyncHTTPClient/RequestBag.swift +++ b/Sources/AsyncHTTPClient/RequestBag.swift @@ -73,6 +73,8 @@ final class RequestBag { } 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) }