Skip to content

Add logging to the new HTTPConnectionPool #428

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 1 commit into from
Sep 20, 2021
Merged

Add logging to the new HTTPConnectionPool #428

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
15 changes: 14 additions & 1 deletion Sources/AsyncHTTPClient/ConnectionPool.swift
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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":
Expand Down Expand Up @@ -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)"
}
}
}

Expand Down
14 changes: 5 additions & 9 deletions Sources/AsyncHTTPClient/ConnectionPool/HTTP1.1/HTTP1ClientChannelHandler.swift
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand Down Expand Up @@ -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)
Expand All @@ -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)
}
Comment on lines -147 to -149
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This could be removed, since it is already included in the request setter (l. 143). We have tests that ensure that idle read timeouts work as expected. Those continue to succeed.


self.logger.debug("Request was scheduled on connection")
req.willExecuteRequest(self)

let action = self.state.runNewRequest(head: req.requestHead, metadata: req.requestFramingMetadata)
Expand Down
2 changes: 1 addition & 1 deletion Sources/AsyncHTTPClient/ConnectionPool/HTTPConnectionPool+Factory.swift
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand Down
47 changes: 38 additions & 9 deletions Sources/AsyncHTTPClient/ConnectionPool/HTTPConnectionPool.swift
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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)",
])
}
Comment on lines -134 to -139
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Removed, since it produces way too many logs. We should solely focus on recording the events so that we can replay the finite state machine if needed.

}
private var _state: StateMachine

private static let fallbackConnectTimeout: TimeAmount = .seconds(30)

Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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 {
Expand Down Expand Up @@ -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(
Expand Down Expand Up @@ -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
Expand All @@ -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)
}
Expand All @@ -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 {
Expand Down Expand Up @@ -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))
}
Expand All @@ -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)
}
Expand All @@ -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)
}
Expand Down
2 changes: 2 additions & 0 deletions Sources/AsyncHTTPClient/RequestBag.swift
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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)
}
Expand Down