Skip to content
This commit does not belong to any branch on this repository, and may belong to a fork outside of the repository.

Commit 26baf4f

Browse files
committedMay 29, 2020
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.
1 parent 070c1e5 commit 26baf4f

12 files changed

+1118
-415
lines changed
 

‎Package.swift

Lines changed: 5 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -25,15 +25,18 @@ let package = Package(
2525
.package(url: "https://github.com/apple/swift-nio-ssl.git", from: "2.7.0"),
2626
.package(url: "https://github.com/apple/swift-nio-extras.git", from: "1.3.0"),
2727
.package(url: "https://github.com/apple/swift-nio-transport-services.git", from: "1.5.1"),
28+
.package(url: "https://github.com/apple/swift-log.git", from: "1.0.0"),
2829
],
2930
targets: [
3031
.target(
3132
name: "AsyncHTTPClient",
32-
dependencies: ["NIO", "NIOHTTP1", "NIOSSL", "NIOConcurrencyHelpers", "NIOHTTPCompression", "NIOFoundationCompat", "NIOTransportServices"]
33+
dependencies: ["NIO", "NIOHTTP1", "NIOSSL", "NIOConcurrencyHelpers", "NIOHTTPCompression",
34+
"NIOFoundationCompat", "NIOTransportServices", "Logging"]
3335
),
3436
.testTarget(
3537
name: "AsyncHTTPClientTests",
36-
dependencies: ["NIO", "NIOConcurrencyHelpers", "NIOSSL", "AsyncHTTPClient", "NIOFoundationCompat", "NIOTestUtils"]
38+
dependencies: ["NIO", "NIOConcurrencyHelpers", "NIOSSL", "AsyncHTTPClient", "NIOFoundationCompat",
39+
"NIOTestUtils", "Logging"]
3740
),
3841
]
3942
)

‎Sources/AsyncHTTPClient/ConnectionPool.swift

Lines changed: 97 additions & 35 deletions
Large diffs are not rendered by default.

‎Sources/AsyncHTTPClient/HTTPClient.swift

Lines changed: 227 additions & 26 deletions
Large diffs are not rendered by default.

‎Sources/AsyncHTTPClient/HTTPHandler.swift

Lines changed: 25 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -13,6 +13,7 @@
1313
//===----------------------------------------------------------------------===//
1414

1515
import Foundation
16+
import Logging
1617
import NIO
1718
import NIOConcurrencyHelpers
1819
import NIOFoundationCompat
@@ -494,17 +495,19 @@ extension HTTPClient {
494495
var connection: Connection?
495496
var cancelled: Bool
496497
let lock: Lock
498+
let logger: Logger // We are okay to store the logger here because a Task is for only ond request.
497499

498-
init(eventLoop: EventLoop) {
500+
init(eventLoop: EventLoop, logger: Logger) {
499501
self.eventLoop = eventLoop
500502
self.promise = eventLoop.makePromise()
501503
self.completion = self.promise.futureResult.map { _ in }
502504
self.cancelled = false
503505
self.lock = Lock()
506+
self.logger = logger
504507
}
505508

506-
static func failedTask(eventLoop: EventLoop, error: Error) -> Task<Response> {
507-
let task = self.init(eventLoop: eventLoop)
509+
static func failedTask(eventLoop: EventLoop, error: Error, logger: Logger) -> Task<Response> {
510+
let task = self.init(eventLoop: eventLoop, logger: logger)
508511
task.promise.fail(error)
509512
return task
510513
}
@@ -546,13 +549,18 @@ extension HTTPClient {
546549
}
547550
}
548551

549-
func succeed<Delegate: HTTPClientResponseDelegate>(promise: EventLoopPromise<Response>?, with value: Response, delegateType: Delegate.Type, closing: Bool) {
550-
self.releaseAssociatedConnection(delegateType: delegateType, closing: closing).whenSuccess {
552+
func succeed<Delegate: HTTPClientResponseDelegate>(promise: EventLoopPromise<Response>?,
553+
with value: Response,
554+
delegateType: Delegate.Type,
555+
closing: Bool) {
556+
self.releaseAssociatedConnection(delegateType: delegateType,
557+
closing: closing).whenSuccess {
551558
promise?.succeed(value)
552559
}
553560
}
554561

555-
func fail<Delegate: HTTPClientResponseDelegate>(with error: Error, delegateType: Delegate.Type) {
562+
func fail<Delegate: HTTPClientResponseDelegate>(with error: Error,
563+
delegateType: Delegate.Type) {
556564
if let connection = self.connection {
557565
self.releaseAssociatedConnection(delegateType: delegateType, closing: true)
558566
.whenSuccess {
@@ -562,13 +570,14 @@ extension HTTPClient {
562570
}
563571
}
564572

565-
func releaseAssociatedConnection<Delegate: HTTPClientResponseDelegate>(delegateType: Delegate.Type, closing: Bool) -> EventLoopFuture<Void> {
573+
func releaseAssociatedConnection<Delegate: HTTPClientResponseDelegate>(delegateType: Delegate.Type,
574+
closing: Bool) -> EventLoopFuture<Void> {
566575
if let connection = self.connection {
567576
// remove read timeout handler
568577
return connection.removeHandler(IdleStateHandler.self).flatMap {
569578
connection.removeHandler(TaskHandler<Delegate>.self)
570579
}.map {
571-
connection.release(closing: closing)
580+
connection.release(closing: closing, logger: self.logger)
572581
}.flatMapError { error in
573582
fatalError("Couldn't remove taskHandler: \(error)")
574583
}
@@ -600,6 +609,7 @@ internal class TaskHandler<Delegate: HTTPClientResponseDelegate>: RemovableChann
600609
let delegate: Delegate
601610
let redirectHandler: RedirectHandler<Delegate.Response>?
602611
let ignoreUncleanSSLShutdown: Bool
612+
let logger: Logger // We are okay to store the logger here because a TaskHandler is just for one request.
603613

604614
var state: State = .idle
605615
var pendingRead = false
@@ -617,12 +627,14 @@ internal class TaskHandler<Delegate: HTTPClientResponseDelegate>: RemovableChann
617627
kind: HTTPClient.Request.Kind,
618628
delegate: Delegate,
619629
redirectHandler: RedirectHandler<Delegate.Response>?,
620-
ignoreUncleanSSLShutdown: Bool) {
630+
ignoreUncleanSSLShutdown: Bool,
631+
logger: Logger) {
621632
self.task = task
622633
self.delegate = delegate
623634
self.redirectHandler = redirectHandler
624635
self.ignoreUncleanSSLShutdown = ignoreUncleanSSLShutdown
625636
self.kind = kind
637+
self.logger = logger
626638
}
627639
}
628640

@@ -678,7 +690,10 @@ extension TaskHandler {
678690
do {
679691
let result = try body(self.task)
680692

681-
self.task.succeed(promise: promise, with: result, delegateType: Delegate.self, closing: self.closing)
693+
self.task.succeed(promise: promise,
694+
with: result,
695+
delegateType: Delegate.self,
696+
closing: self.closing)
682697
} catch {
683698
self.task.fail(with: error, delegateType: Delegate.self)
684699
}
Lines changed: 40 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,40 @@
1+
//===----------------------------------------------------------------------===//
2+
//
3+
// This source file is part of the AsyncHTTPClient open source project
4+
//
5+
// Copyright (c) 2020 Apple Inc. and the AsyncHTTPClient project authors
6+
// Licensed under Apache License v2.0
7+
//
8+
// See LICENSE.txt for license information
9+
// See CONTRIBUTORS.txt for the list of AsyncHTTPClient project authors
10+
//
11+
// SPDX-License-Identifier: Apache-2.0
12+
//
13+
//===----------------------------------------------------------------------===//
14+
15+
import Logging
16+
17+
internal struct NoOpLogHandler: LogHandler {
18+
func log(level: Logger.Level, message: Logger.Message, metadata: Logger.Metadata?, file: String, function: String, line: UInt) {}
19+
20+
subscript(metadataKey _: String) -> Logger.Metadata.Value? {
21+
get {
22+
return nil
23+
}
24+
set {}
25+
}
26+
27+
var metadata: Logger.Metadata {
28+
get {
29+
return [:]
30+
}
31+
set {}
32+
}
33+
34+
var logLevel: Logger.Level {
35+
get {
36+
return .critical
37+
}
38+
set {}
39+
}
40+
}
Lines changed: 31 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,31 @@
1+
//===----------------------------------------------------------------------===//
2+
//
3+
// This source file is part of the AsyncHTTPClient open source project
4+
//
5+
// Copyright (c) 2020 Apple Inc. and the AsyncHTTPClient project authors
6+
// Licensed under Apache License v2.0
7+
//
8+
// See LICENSE.txt for license information
9+
// See CONTRIBUTORS.txt for the list of AsyncHTTPClient project authors
10+
//
11+
// SPDX-License-Identifier: Apache-2.0
12+
//
13+
//===----------------------------------------------------------------------===//
14+
15+
extension Connection: CustomStringConvertible {
16+
var description: String {
17+
return "\(self.channel)"
18+
}
19+
}
20+
21+
extension HTTP1ConnectionProvider.Waiter: CustomStringConvertible {
22+
var description: String {
23+
return "HTTP1ConnectionProvider.Waiter(\(self.preference))"
24+
}
25+
}
26+
27+
extension HTTPClient.EventLoopPreference: CustomStringConvertible {
28+
public var description: String {
29+
return "\(self.preference)"
30+
}
31+
}

‎Tests/AsyncHTTPClientTests/ConnectionPoolTests.swift

Lines changed: 343 additions & 316 deletions
Large diffs are not rendered by default.

‎Tests/AsyncHTTPClientTests/HTTPClientInternalTests.swift

Lines changed: 29 additions & 22 deletions
Original file line numberDiff line numberDiff line change
@@ -39,14 +39,15 @@ class HTTPClientInternalTests: XCTestCase {
3939
func testHTTPPartsHandler() throws {
4040
let channel = EmbeddedChannel()
4141
let recorder = RecordingHandler<HTTPClientResponsePart, HTTPClientRequestPart>()
42-
let task = Task<Void>(eventLoop: channel.eventLoop)
42+
let task = Task<Void>(eventLoop: channel.eventLoop, logger: HTTPClient.loggingDisabled)
4343

4444
try channel.pipeline.addHandler(recorder).wait()
4545
try channel.pipeline.addHandler(TaskHandler(task: task,
4646
kind: .host,
4747
delegate: TestHTTPDelegate(),
4848
redirectHandler: nil,
49-
ignoreUncleanSSLShutdown: false)).wait()
49+
ignoreUncleanSSLShutdown: false,
50+
logger: HTTPClient.loggingDisabled)).wait()
5051

5152
var request = try Request(url: "http://localhost/get")
5253
request.headers.add(name: "X-Test-Header", value: "X-Test-Value")
@@ -69,14 +70,15 @@ class HTTPClientInternalTests: XCTestCase {
6970
func testBadHTTPRequest() throws {
7071
let channel = EmbeddedChannel()
7172
let recorder = RecordingHandler<HTTPClientResponsePart, HTTPClientRequestPart>()
72-
let task = Task<Void>(eventLoop: channel.eventLoop)
73+
let task = Task<Void>(eventLoop: channel.eventLoop, logger: HTTPClient.loggingDisabled)
7374

7475
XCTAssertNoThrow(try channel.pipeline.addHandler(recorder).wait())
7576
XCTAssertNoThrow(try channel.pipeline.addHandler(TaskHandler(task: task,
7677
kind: .host,
7778
delegate: TestHTTPDelegate(),
7879
redirectHandler: nil,
79-
ignoreUncleanSSLShutdown: false)).wait())
80+
ignoreUncleanSSLShutdown: false,
81+
logger: HTTPClient.loggingDisabled)).wait())
8082

8183
var request = try Request(url: "http://localhost/get")
8284
request.headers.add(name: "X-Test-Header", value: "X-Test-Value")
@@ -91,12 +93,13 @@ class HTTPClientInternalTests: XCTestCase {
9193
func testHTTPPartsHandlerMultiBody() throws {
9294
let channel = EmbeddedChannel()
9395
let delegate = TestHTTPDelegate()
94-
let task = Task<Void>(eventLoop: channel.eventLoop)
96+
let task = Task<Void>(eventLoop: channel.eventLoop, logger: HTTPClient.loggingDisabled)
9597
let handler = TaskHandler(task: task,
9698
kind: .host,
9799
delegate: delegate,
98100
redirectHandler: nil,
99-
ignoreUncleanSSLShutdown: false)
101+
ignoreUncleanSSLShutdown: false,
102+
logger: HTTPClient.loggingDisabled)
100103

101104
try channel.pipeline.addHandler(handler).wait()
102105

@@ -573,19 +576,20 @@ class HTTPClientInternalTests: XCTestCase {
573576
// This is pretty evil but we literally just get hold of a connection to get to the channel to be able to
574577
// observe when the server closing the connection is known to the client.
575578
let el = group.next()
576-
XCTAssertNoThrow(maybeConnection = try client.pool.getConnection(for: .init(url: url),
579+
XCTAssertNoThrow(maybeConnection = try client.pool.getConnection(Request(url: url),
577580
preference: .indifferent,
578-
on: el,
581+
taskEventLoop: el,
579582
deadline: nil,
580-
setupComplete: el.makeSucceededFuture(())).wait())
583+
setupComplete: el.makeSucceededFuture(()),
584+
logger: HTTPClient.loggingDisabled).wait())
581585
guard let connection = maybeConnection else {
582586
XCTFail("couldn't get connection")
583587
return
584588
}
585589

586590
// And let's also give the connection back :).
587591
try connection.channel.eventLoop.submit {
588-
connection.release(closing: false)
592+
connection.release(closing: false, logger: HTTPClient.loggingDisabled)
589593
}.wait()
590594

591595
XCTAssertEqual(0, sharedStateServerHandler.requestNumber.load())
@@ -622,19 +626,20 @@ class HTTPClientInternalTests: XCTestCase {
622626
body: nil)
623627
var maybeConnection: Connection?
624628
let el = client.eventLoopGroup.next()
625-
XCTAssertNoThrow(try maybeConnection = client.pool.getConnection(for: req,
629+
XCTAssertNoThrow(try maybeConnection = client.pool.getConnection(req,
626630
preference: .indifferent,
627-
on: el,
631+
taskEventLoop: el,
628632
deadline: nil,
629-
setupComplete: el.makeSucceededFuture(())).wait())
633+
setupComplete: el.makeSucceededFuture(()),
634+
logger: HTTPClient.loggingDisabled).wait())
630635
guard let connection = maybeConnection else {
631636
XCTFail("couldn't make connection")
632637
throw NoChannelError()
633638
}
634639

635640
let channel = connection.channel
636641
try! channel.eventLoop.submit {
637-
connection.release(closing: true)
642+
connection.release(closing: true, logger: HTTPClient.loggingDisabled)
638643
}.wait()
639644
return (web, channel)
640645
})
@@ -707,11 +712,12 @@ class HTTPClientInternalTests: XCTestCase {
707712
// Let's start by getting a connection so we can mess with the Channel :).
708713
var maybeConnection: Connection?
709714
let el = client.eventLoopGroup.next()
710-
XCTAssertNoThrow(try maybeConnection = client.pool.getConnection(for: req,
715+
XCTAssertNoThrow(try maybeConnection = client.pool.getConnection(req,
711716
preference: .indifferent,
712-
on: el,
717+
taskEventLoop: el,
713718
deadline: nil,
714-
setupComplete: el.makeSucceededFuture(())).wait())
719+
setupComplete: el.makeSucceededFuture(()),
720+
logger: HTTPClient.loggingDisabled).wait())
715721
guard let connection = maybeConnection else {
716722
XCTFail("couldn't make connection")
717723
return
@@ -725,7 +731,7 @@ class HTTPClientInternalTests: XCTestCase {
725731
sawTheClosePromise: sawTheClosePromise),
726732
position: .first).wait())
727733
try! connection.channel.eventLoop.submit {
728-
connection.release(closing: false)
734+
connection.release(closing: false, logger: HTTPClient.loggingDisabled)
729735
}.wait()
730736

731737
XCTAssertNoThrow(try client.execute(request: req).wait())
@@ -742,11 +748,12 @@ class HTTPClientInternalTests: XCTestCase {
742748
// When asking for a connection again, we should _not_ get the same one back because we did most of the close,
743749
// similar to what the SSLHandler would do.
744750
let el2 = client.eventLoopGroup.next()
745-
let connection2Future = client.pool.getConnection(for: req,
751+
let connection2Future = client.pool.getConnection(req,
746752
preference: .indifferent,
747-
on: el2,
753+
taskEventLoop: el2,
748754
deadline: nil,
749-
setupComplete: el2.makeSucceededFuture(()))
755+
setupComplete: el2.makeSucceededFuture(()),
756+
logger: HTTPClient.loggingDisabled)
750757
doActualCloseNowPromise.succeed(())
751758

752759
XCTAssertNoThrow(try maybeConnection = connection2Future.wait())
@@ -757,7 +764,7 @@ class HTTPClientInternalTests: XCTestCase {
757764

758765
XCTAssert(connection !== connection2)
759766
try! connection2.channel.eventLoop.submit {
760-
connection2.release(closing: true)
767+
connection2.release(closing: true, logger: HTTPClient.loggingDisabled)
761768
}.wait()
762769
XCTAssertTrue(connection2.channel.isActive)
763770
}

‎Tests/AsyncHTTPClientTests/HTTPClientTestUtils.swift

Lines changed: 55 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -14,6 +14,7 @@
1414

1515
import AsyncHTTPClient
1616
import Foundation
17+
import Logging
1718
import NIO
1819
import NIOConcurrencyHelpers
1920
import NIOHTTP1
@@ -753,6 +754,60 @@ extension EventLoopFuture {
753754
}
754755
}
755756

757+
struct CollectEverythingLogHandler: LogHandler {
758+
var metadata: Logger.Metadata = [:]
759+
var logLevel: Logger.Level = .info
760+
let logStore: LogStore
761+
762+
class LogStore {
763+
struct Entry {
764+
var level: Logger.Level
765+
var message: String
766+
var metadata: [String: String]
767+
}
768+
769+
var lock = Lock()
770+
var logs: [Entry] = []
771+
772+
var allEntries: [Entry] {
773+
get {
774+
return self.lock.withLock { self.logs }
775+
}
776+
set {
777+
self.lock.withLock { self.logs = newValue }
778+
}
779+
}
780+
781+
func append(level: Logger.Level, message: Logger.Message, metadata: Logger.Metadata?) {
782+
self.lock.withLock {
783+
self.logs.append(Entry(level: level,
784+
message: message.description,
785+
metadata: metadata?.mapValues { $0.description } ?? [:]))
786+
}
787+
}
788+
}
789+
790+
init(logStore: LogStore) {
791+
self.logStore = logStore
792+
}
793+
794+
func log(level: Logger.Level,
795+
message: Logger.Message,
796+
metadata: Logger.Metadata?,
797+
file: String, function: String, line: UInt) {
798+
self.logStore.append(level: level, message: message, metadata: self.metadata.merging(metadata ?? [:]) { $1 })
799+
}
800+
801+
subscript(metadataKey key: String) -> Logger.Metadata.Value? {
802+
get {
803+
return self.metadata[key]
804+
}
805+
set {
806+
self.metadata[key] = newValue
807+
}
808+
}
809+
}
810+
756811
private let cert = """
757812
-----BEGIN CERTIFICATE-----
758813
MIICmDCCAYACCQCPC8JDqMh1zzANBgkqhkiG9w0BAQsFADANMQswCQYDVQQGEwJ1

‎Tests/AsyncHTTPClientTests/HTTPClientTests+XCTest.swift

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -103,6 +103,9 @@ extension HTTPClientTests {
103103
("testWeHandleUsReceivingACloseHeaderCorrectly", testWeHandleUsReceivingACloseHeaderCorrectly),
104104
("testWeHandleUsSendingACloseHeaderAmongstOtherConnectionHeadersCorrectly", testWeHandleUsSendingACloseHeaderAmongstOtherConnectionHeadersCorrectly),
105105
("testWeHandleUsReceivingACloseHeaderAmongstOtherConnectionHeadersCorrectly", testWeHandleUsReceivingACloseHeaderAmongstOtherConnectionHeadersCorrectly),
106+
("testLoggingCorrectlyAttachesRequestInformation", testLoggingCorrectlyAttachesRequestInformation),
107+
("testNothingIsLoggedAtInfoOrHigher", testNothingIsLoggedAtInfoOrHigher),
108+
("testAllMethodsLog", testAllMethodsLog),
106109
]
107110
}
108111
}

‎Tests/AsyncHTTPClientTests/HTTPClientTests.swift

Lines changed: 212 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -16,6 +16,7 @@
1616
#if canImport(Network)
1717
import Network
1818
#endif
19+
import Logging
1920
import NIO
2021
import NIOConcurrencyHelpers
2122
import NIOFoundationCompat
@@ -33,6 +34,7 @@ class HTTPClientTests: XCTestCase {
3334
var serverGroup: EventLoopGroup!
3435
var defaultHTTPBin: HTTPBin!
3536
var defaultClient: HTTPClient!
37+
var backgroundLogStore: CollectEverythingLogHandler.LogStore!
3638

3739
var defaultHTTPBinURLPrefix: String {
3840
return "http://localhost:\(self.defaultHTTPBin.port)/"
@@ -43,16 +45,26 @@ class HTTPClientTests: XCTestCase {
4345
XCTAssertNil(self.serverGroup)
4446
XCTAssertNil(self.defaultHTTPBin)
4547
XCTAssertNil(self.defaultClient)
48+
XCTAssertNil(self.backgroundLogStore)
49+
4650
self.clientGroup = getDefaultEventLoopGroup(numberOfThreads: 1)
4751
self.serverGroup = MultiThreadedEventLoopGroup(numberOfThreads: 1)
4852
self.defaultHTTPBin = HTTPBin()
49-
self.defaultClient = HTTPClient(eventLoopGroupProvider: .shared(self.clientGroup))
53+
self.backgroundLogStore = CollectEverythingLogHandler.LogStore()
54+
var backgroundLogger = Logger(label: "\(#function)", factory: { _ in
55+
CollectEverythingLogHandler(logStore: self.backgroundLogStore!)
56+
})
57+
backgroundLogger.logLevel = .trace
58+
self.defaultClient = HTTPClient(eventLoopGroupProvider: .shared(self.clientGroup),
59+
backgroundActivityLogger: backgroundLogger)
60+
5061
}
5162

5263
override func tearDown() {
53-
XCTAssertNotNil(self.defaultClient)
54-
XCTAssertNoThrow(try self.defaultClient.syncShutdown())
55-
self.defaultClient = nil
64+
if let defaultClient = self.defaultClient {
65+
XCTAssertNoThrow(try defaultClient.syncShutdown())
66+
self.defaultClient = nil
67+
}
5668

5769
XCTAssertNotNil(self.defaultHTTPBin)
5870
XCTAssertNoThrow(try self.defaultHTTPBin.shutdown())
@@ -65,6 +77,9 @@ class HTTPClientTests: XCTestCase {
6577
XCTAssertNotNil(self.serverGroup)
6678
XCTAssertNoThrow(try self.serverGroup.syncShutdownGracefully())
6779
self.serverGroup = nil
80+
81+
XCTAssertNotNil(self.backgroundLogStore)
82+
self.backgroundLogStore = nil
6883
}
6984

7085
func testRequestURI() throws {
@@ -1756,4 +1771,197 @@ class HTTPClientTests: XCTestCase {
17561771
XCTAssertEqual(stats2.connectionNumber, stats3.connectionNumber)
17571772
}
17581773
}
1774+
1775+
func testLoggingCorrectlyAttachesRequestInformation() {
1776+
let logStore = CollectEverythingLogHandler.LogStore()
1777+
1778+
var loggerYolo001: Logger = Logger(label: "\(#function)", factory: { _ in
1779+
CollectEverythingLogHandler(logStore: logStore)
1780+
})
1781+
loggerYolo001.logLevel = .trace
1782+
loggerYolo001[metadataKey: "yolo-request-id"] = "yolo-001"
1783+
var loggerACME002: Logger = Logger(label: "\(#function)", factory: { _ in
1784+
CollectEverythingLogHandler(logStore: logStore)
1785+
})
1786+
loggerACME002.logLevel = .trace
1787+
loggerACME002[metadataKey: "acme-request-id"] = "acme-002"
1788+
1789+
guard let request1 = try? HTTPClient.Request(url: self.defaultHTTPBinURLPrefix + "get"),
1790+
let request2 = try? HTTPClient.Request(url: self.defaultHTTPBinURLPrefix + "stats"),
1791+
let request3 = try? HTTPClient.Request(url: self.defaultHTTPBinURLPrefix + "ok") else {
1792+
XCTFail("bad stuff, can't even make request structures")
1793+
return
1794+
}
1795+
1796+
// === Request 1 (Yolo001)
1797+
XCTAssertNoThrow(try self.defaultClient.execute(request: request1,
1798+
eventLoop: .indifferent,
1799+
deadline: nil,
1800+
logger: loggerYolo001).wait())
1801+
let logsAfterReq1 = logStore.allEntries
1802+
logStore.allEntries = []
1803+
1804+
// === Request 2 (Yolo001)
1805+
XCTAssertNoThrow(try self.defaultClient.execute(request: request2,
1806+
eventLoop: .indifferent,
1807+
deadline: nil,
1808+
logger: loggerYolo001).wait())
1809+
let logsAfterReq2 = logStore.allEntries
1810+
logStore.allEntries = []
1811+
1812+
// === Request 3 (ACME002)
1813+
XCTAssertNoThrow(try self.defaultClient.execute(request: request3,
1814+
eventLoop: .indifferent,
1815+
deadline: nil,
1816+
logger: loggerACME002).wait())
1817+
let logsAfterReq3 = logStore.allEntries
1818+
logStore.allEntries = []
1819+
1820+
// === Assertions
1821+
XCTAssertGreaterThan(logsAfterReq1.count, 0)
1822+
XCTAssertGreaterThan(logsAfterReq2.count, 0)
1823+
XCTAssertGreaterThan(logsAfterReq3.count, 0)
1824+
1825+
XCTAssert(logsAfterReq1.allSatisfy { entry in
1826+
if let httpRequestMetadata = entry.metadata["ahc-request-id"],
1827+
let yoloRequestID = entry.metadata["yolo-request-id"] {
1828+
XCTAssertNil(entry.metadata["acme-request-id"])
1829+
XCTAssertEqual("yolo-001", yoloRequestID)
1830+
XCTAssertNotNil(Int(httpRequestMetadata))
1831+
return true
1832+
} else {
1833+
XCTFail("log message doesn't contain the right IDs: \(entry)")
1834+
return false
1835+
}
1836+
})
1837+
XCTAssert(logsAfterReq1.contains { entry in
1838+
entry.message == "opening fresh connection (no connections to reuse available)"
1839+
})
1840+
1841+
XCTAssert(logsAfterReq2.allSatisfy { entry in
1842+
if let httpRequestMetadata = entry.metadata["ahc-request-id"],
1843+
let yoloRequestID = entry.metadata["yolo-request-id"] {
1844+
XCTAssertNil(entry.metadata["acme-request-id"])
1845+
XCTAssertEqual("yolo-001", yoloRequestID)
1846+
XCTAssertNotNil(Int(httpRequestMetadata))
1847+
return true
1848+
} else {
1849+
XCTFail("log message doesn't contain the right IDs: \(entry)")
1850+
return false
1851+
}
1852+
})
1853+
XCTAssert(logsAfterReq2.contains { entry in
1854+
entry.message.starts(with: "leasing existing connection")
1855+
})
1856+
1857+
XCTAssert(logsAfterReq3.allSatisfy { entry in
1858+
if let httpRequestMetadata = entry.metadata["ahc-request-id"],
1859+
let acmeRequestID = entry.metadata["acme-request-id"] {
1860+
XCTAssertNil(entry.metadata["yolo-request-id"])
1861+
XCTAssertEqual("acme-002", acmeRequestID)
1862+
XCTAssertNotNil(Int(httpRequestMetadata))
1863+
return true
1864+
} else {
1865+
XCTFail("log message doesn't contain the right IDs: \(entry)")
1866+
return false
1867+
}
1868+
})
1869+
XCTAssert(logsAfterReq3.contains { entry in
1870+
entry.message.starts(with: "leasing existing connection")
1871+
})
1872+
}
1873+
1874+
func testNothingIsLoggedAtInfoOrHigher() {
1875+
let logStore = CollectEverythingLogHandler.LogStore()
1876+
1877+
var logger: Logger = Logger(label: "\(#function)", factory: { _ in
1878+
CollectEverythingLogHandler(logStore: logStore)
1879+
})
1880+
logger.logLevel = .info
1881+
1882+
guard let request1 = try? HTTPClient.Request(url: self.defaultHTTPBinURLPrefix + "get"),
1883+
let request2 = try? HTTPClient.Request(url: self.defaultHTTPBinURLPrefix + "stats") else {
1884+
XCTFail("bad stuff, can't even make request structures")
1885+
return
1886+
}
1887+
1888+
// === Request 1
1889+
XCTAssertNoThrow(try self.defaultClient.execute(request: request1,
1890+
eventLoop: .indifferent,
1891+
deadline: nil,
1892+
logger: logger).wait())
1893+
XCTAssertEqual(0, logStore.allEntries.count)
1894+
1895+
// === Request 2
1896+
XCTAssertNoThrow(try self.defaultClient.execute(request: request2,
1897+
eventLoop: .indifferent,
1898+
deadline: nil,
1899+
logger: logger).wait())
1900+
XCTAssertEqual(0, logStore.allEntries.count)
1901+
1902+
XCTAssertEqual(0, self.backgroundLogStore.allEntries.count)
1903+
}
1904+
1905+
func testAllMethodsLog() {
1906+
func checkExpectationsWithLogger<T>(type: String, _ body: (Logger, String) throws -> T) throws -> T {
1907+
let logStore = CollectEverythingLogHandler.LogStore()
1908+
1909+
var logger: Logger = Logger(label: "\(#function)", factory: { _ in
1910+
CollectEverythingLogHandler(logStore: logStore)
1911+
})
1912+
logger.logLevel = .trace
1913+
logger[metadataKey: "req"] = "yo-\(type)"
1914+
1915+
let url = self.defaultHTTPBinURLPrefix + "not-found/request/\(type))"
1916+
let result = try body(logger, url)
1917+
1918+
XCTAssertGreaterThan(logStore.allEntries.count, 0)
1919+
logStore.allEntries.forEach { entry in
1920+
XCTAssertEqual("yo-\(type)", entry.metadata["req"] ?? "n/a")
1921+
XCTAssertNotNil(Int(entry.metadata["ahc-request-id"] ?? "n/a"))
1922+
}
1923+
return result
1924+
}
1925+
1926+
XCTAssertNoThrow(XCTAssertEqual(.notFound, try checkExpectationsWithLogger(type: "GET") { logger, url in
1927+
try self.defaultClient.get(url: url, logger: logger).wait()
1928+
}.status))
1929+
1930+
XCTAssertNoThrow(XCTAssertEqual(.notFound, try checkExpectationsWithLogger(type: "PUT") { logger, url in
1931+
try self.defaultClient.put(url: url, logger: logger).wait()
1932+
}.status))
1933+
1934+
XCTAssertNoThrow(XCTAssertEqual(.notFound, try checkExpectationsWithLogger(type: "POST") { logger, url in
1935+
try self.defaultClient.post(url: url, logger: logger).wait()
1936+
}.status))
1937+
1938+
XCTAssertNoThrow(XCTAssertEqual(.notFound, try checkExpectationsWithLogger(type: "DELETE") { logger, url in
1939+
try self.defaultClient.delete(url: url, logger: logger).wait()
1940+
}.status))
1941+
1942+
XCTAssertNoThrow(XCTAssertEqual(.notFound, try checkExpectationsWithLogger(type: "PATCH") { logger, url in
1943+
try self.defaultClient.patch(url: url, logger: logger).wait()
1944+
}.status))
1945+
1946+
// No background activity expected here.
1947+
XCTAssertEqual(0, self.backgroundLogStore.allEntries.count)
1948+
}
1949+
1950+
func testClosingIdleConnectionsInPoolLogsInTheBackground() {
1951+
XCTAssertNoThrow(try self.defaultClient.get(url: self.defaultHTTPBinURLPrefix + "/get").wait())
1952+
1953+
XCTAssertNoThrow(try self.defaultClient.syncShutdown())
1954+
1955+
XCTAssertGreaterThanOrEqual(self.backgroundLogStore.allEntries.count, 0)
1956+
XCTAssert(self.backgroundLogStore.allEntries.contains { entry in
1957+
return entry.message == "closing provider"
1958+
})
1959+
XCTAssert(self.backgroundLogStore.allEntries.allSatisfy { entry in
1960+
entry.metadata["ahc-request-id"] == nil &&
1961+
entry.metadata["ahc-request"] == nil &&
1962+
entry.metadata["ahc-provider"] != nil
1963+
})
1964+
1965+
self.defaultClient = nil // so it doesn't get shut down again.
1966+
}
17591967
}

‎docs/logging-design.md

Lines changed: 51 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,51 @@
1+
# Design of the way AsyncHTTPClient logs
2+
3+
<details>
4+
<summary>Unless you explicitly pass AsyncHTTPClient a `Logger` instance, nothing is ever logged.</summary>
5+
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.
6+
</details>
7+
<details>
8+
<summary>Nothing is logged at level `info` or higher, unless something is really wrong that cannot be communicated through the API.</summary>
9+
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.
10+
</details>
11+
<details>
12+
<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>
13+
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.
14+
</details>
15+
<details>
16+
<summary>Your `Logger` metadata is preserved.</summary>
17+
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.
18+
19+
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.
20+
</details>
21+
<details>
22+
<summary>Instead of accepting one `Logger` instance per `HTTPClient` instance, each request method can accept a `Logger`.</summary>
23+
This allows AsyncHTTPClient to preserve your metadata and add its own metadata such as `ahc-request-id`.
24+
</details>
25+
<details>
26+
<summary>All logs use the structured logging pattern, i.e. only static log messages and accompanying key/value metadata are used.</summary>
27+
None of the log messages issued by AsyncHTTPClient will use String interpolation which means they will always be the exact same message.
28+
29+
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:
30+
31+
- message: `got connection for request`
32+
- metadata (the values are example):
33+
- `ahc-request-id`: `0`
34+
- `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) }`
35+
36+
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`.
37+
38+
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.
39+
</details>
40+
<details>
41+
<summary>`debug` should be enough to diagnose most problems but information that can be correlated is usually skipped.</summary>
42+
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`.
43+
44+
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.
45+
46+
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`.
47+
</details>
48+
<details>
49+
<summary>In `trace`, AsyncHTTPClient may log _a lot_.</summary>
50+
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.
51+
</details>

0 commit comments

Comments
 (0)
Please sign in to comment.