From b286e648cc8075a51e3b26ca907f1798034681cc Mon Sep 17 00:00:00 2001 From: Adam Fowler Date: Mon, 9 Sep 2024 08:13:06 +0100 Subject: [PATCH] Metrics and Logging name changes (#541) --- Sources/Hummingbird/Application.swift | 4 +-- Sources/Hummingbird/Files/FileIO.swift | 4 +-- .../Middleware/LogRequestMiddleware.swift | 16 ++++----- .../Middleware/MetricsMiddleware.swift | 34 +++++++++++++------ .../Hummingbird/Server/RequestContext.swift | 2 +- .../RouterTestFramework.swift | 2 +- Sources/PerformanceTest/main.swift | 4 +++ Tests/HummingbirdTests/MetricsTests.swift | 34 ++++++++++--------- Tests/HummingbirdTests/MiddlewareTests.swift | 30 ++++++++-------- 9 files changed, 74 insertions(+), 56 deletions(-) diff --git a/Sources/Hummingbird/Application.swift b/Sources/Hummingbird/Application.swift index c554193db..2cb893d6a 100644 --- a/Sources/Hummingbird/Application.swift +++ b/Sources/Hummingbird/Application.swift @@ -102,7 +102,7 @@ extension ApplicationProtocol { eventLoopGroup: self.eventLoopGroup, logger: self.logger ) { (request, responseWriter: consuming ResponseWriter, channel) in - let logger = self.logger.with(metadataKey: "hb_id", value: .stringConvertible(RequestID())) + let logger = self.logger.with(metadataKey: "hb.request.id", value: .stringConvertible(RequestID())) let context = Self.Responder.Context( source: .init( channel: channel, @@ -114,7 +114,7 @@ extension ApplicationProtocol { do { response = try await responder.respond(to: request, context: context) } catch { - logger.debug("Unrecognised Error", metadata: ["error": "\(error)"]) + logger.debug("Unrecognised Error", metadata: ["error.type": "\(error)"]) response = Response( status: .internalServerError, body: .init() diff --git a/Sources/Hummingbird/Files/FileIO.swift b/Sources/Hummingbird/Files/FileIO.swift index eafdb3684..e41598a17 100644 --- a/Sources/Hummingbird/Files/FileIO.swift +++ b/Sources/Hummingbird/Files/FileIO.swift @@ -79,7 +79,7 @@ public struct FileIO: Sendable { path: String, context: some RequestContext ) async throws where AS.Element == ByteBuffer { - context.logger.debug("[FileIO] PUT", metadata: ["file": .string(path)]) + context.logger.debug("[FileIO] PUT", metadata: ["hb.file.path": .string(path)]) try await self.fileIO.withFileHandle(path: path, mode: .write, flags: .allowFileCreation()) { handle in for try await buffer in contents { try await self.fileIO.write(fileHandle: handle, buffer: buffer) @@ -98,7 +98,7 @@ public struct FileIO: Sendable { path: String, context: some RequestContext ) async throws { - context.logger.debug("[FileIO] PUT", metadata: ["file": .string(path)]) + context.logger.debug("[FileIO] PUT", metadata: ["hb.file.path": .string(path)]) try await self.fileIO.withFileHandle(path: path, mode: .write, flags: .allowFileCreation()) { handle in try await self.fileIO.write(fileHandle: handle, buffer: buffer) } diff --git a/Sources/Hummingbird/Middleware/LogRequestMiddleware.swift b/Sources/Hummingbird/Middleware/LogRequestMiddleware.swift index bac40b7f3..5e479037b 100644 --- a/Sources/Hummingbird/Middleware/LogRequestMiddleware.swift +++ b/Sources/Hummingbird/Middleware/LogRequestMiddleware.swift @@ -72,8 +72,8 @@ public struct LogRequestsMiddleware: RouterMiddleware { level: self.logLevel, "Request", metadata: [ - "hb_uri": .stringConvertible(request.uri), - "hb_method": .string(request.method.rawValue), + "hb.request.path": .stringConvertible(request.uri), + "hb.request.method": .string(request.method.rawValue), ] ) case .all(let except): @@ -81,9 +81,9 @@ public struct LogRequestsMiddleware: RouterMiddleware { level: self.logLevel, "Request", metadata: [ - "hb_uri": .stringConvertible(request.uri), - "hb_method": .string(request.method.rawValue), - "hb_headers": .stringConvertible(self.allHeaders(headers: request.headers, except: except)), + "hb.request.path": .stringConvertible(request.uri), + "hb.request.method": .string(request.method.rawValue), + "hb.request.headers": .stringConvertible(self.allHeaders(headers: request.headers, except: except)), ] ) case .some(let filter): @@ -91,9 +91,9 @@ public struct LogRequestsMiddleware: RouterMiddleware { level: self.logLevel, "Request", metadata: [ - "hb_uri": .stringConvertible(request.uri), - "hb_method": .string(request.method.rawValue), - "hb_headers": .stringConvertible(self.filterHeaders(headers: request.headers, filter: filter)), + "hb.request.path": .stringConvertible(request.uri), + "hb.request.method": .string(request.method.rawValue), + "hb.request.headers": .stringConvertible(self.filterHeaders(headers: request.headers, filter: filter)), ] ) } diff --git a/Sources/Hummingbird/Middleware/MetricsMiddleware.swift b/Sources/Hummingbird/Middleware/MetricsMiddleware.swift index 85338f065..28e18eab0 100644 --- a/Sources/Hummingbird/Middleware/MetricsMiddleware.swift +++ b/Sources/Hummingbird/Middleware/MetricsMiddleware.swift @@ -24,42 +24,54 @@ public struct MetricsMiddleware: RouterMiddleware { public func handle(_ request: Request, context: Context, next: (Request, Context) async throws -> Response) async throws -> Response { let startTime = DispatchTime.now().uptimeNanoseconds - + let activeRequestMeter = Meter(label: "cod", dimensions: [("http.request.method", request.method.description)]) + activeRequestMeter.increment() do { var response = try await next(request, context) + let responseStatus = response.status response.body = response.body.withPostWriteClosure { // need to create dimensions once request has been responded to ensure // we have the correct endpoint path let dimensions: [(String, String)] = [ - ("hb_uri", context.endpointPath ?? request.uri.path), - ("hb_method", request.method.rawValue), + ("http.route", context.endpointPath ?? request.uri.path), + ("http.request.method", request.method.rawValue), + ("http.response.status_code", responseStatus.code.description), ] - Counter(label: "hb_requests", dimensions: dimensions).increment() + Counter(label: "hb.requests", dimensions: dimensions).increment() Metrics.Timer( - label: "hb_request_duration", + label: "http.server.request.duration", dimensions: dimensions, preferredDisplayUnit: .seconds ).recordNanoseconds(DispatchTime.now().uptimeNanoseconds - startTime) + activeRequestMeter.decrement() } return response } catch { + let errorType: String + if let httpError = error as? HTTPResponseError { + errorType = httpError.status.code.description + } else { + errorType = "500" + } // need to create dimensions once request has been responded to ensure // we have the correct endpoint path let dimensions: [(String, String)] // Don't record uri in 404 errors, to avoid spamming of metrics if let endpointPath = context.endpointPath { dimensions = [ - ("hb_uri", endpointPath), - ("hb_method", request.method.rawValue), + ("http.route", endpointPath), + ("http.request.method", request.method.rawValue), + ("error.type", errorType), ] - Counter(label: "hb_requests", dimensions: dimensions).increment() + Counter(label: "hb.requests", dimensions: dimensions).increment() } else { dimensions = [ - ("hb_uri", "NotFound"), - ("hb_method", request.method.rawValue), + ("http.request.method", request.method.rawValue), + ("error.type", errorType), ] } - Counter(label: "hb_errors", dimensions: dimensions).increment() + Counter(label: "hb.request.errors", dimensions: dimensions).increment() + activeRequestMeter.decrement() throw error } } diff --git a/Sources/Hummingbird/Server/RequestContext.swift b/Sources/Hummingbird/Server/RequestContext.swift index 8c9815b20..dcbcb5ebb 100644 --- a/Sources/Hummingbird/Server/RequestContext.swift +++ b/Sources/Hummingbird/Server/RequestContext.swift @@ -92,7 +92,7 @@ extension RequestContext { public var parameters: Parameters { coreContext.parameters } /// Request ID, extracted from Logger @inlinable - public var id: String { self.logger[metadataKey: "hb_id"]!.description } + public var id: String { self.logger[metadataKey: "hb.request.id"]!.description } } extension RequestContext where Decoder == JSONDecoder { diff --git a/Sources/HummingbirdTesting/RouterTestFramework.swift b/Sources/HummingbirdTesting/RouterTestFramework.swift index 75f96cf3f..01fdbf112 100644 --- a/Sources/HummingbirdTesting/RouterTestFramework.swift +++ b/Sources/HummingbirdTesting/RouterTestFramework.swift @@ -108,7 +108,7 @@ struct RouterTestFramework: ApplicationTestFramework w head: .init(method: method, scheme: "http", authority: "localhost", path: uri, headerFields: headers), body: stream ) - let logger = self.logger.with(metadataKey: "hb_id", value: .stringConvertible(RequestID())) + let logger = self.logger.with(metadataKey: "hb.request.id", value: .stringConvertible(RequestID())) let context = self.makeContext(logger) group.addTask { diff --git a/Sources/PerformanceTest/main.swift b/Sources/PerformanceTest/main.swift index 477b33180..a057451a7 100644 --- a/Sources/PerformanceTest/main.swift +++ b/Sources/PerformanceTest/main.swift @@ -25,6 +25,10 @@ let port = env.get("SERVER_PORT", as: Int.self) ?? 8080 // create app let elg = MultiThreadedEventLoopGroup(numberOfThreads: 4) var router = Router() +router.addMiddleware { + LogRequestsMiddleware(.info) +} + // number of raw requests // ./wrk -c 128 -d 15s -t 8 http://localhost:8080 router.get { _, _ in diff --git a/Tests/HummingbirdTests/MetricsTests.swift b/Tests/HummingbirdTests/MetricsTests.swift index 17302c8e3..1ba938f8c 100644 --- a/Tests/HummingbirdTests/MetricsTests.swift +++ b/Tests/HummingbirdTests/MetricsTests.swift @@ -200,11 +200,11 @@ final class MetricsTests: XCTestCase { try await client.execute(uri: "/hello", method: .get) { _ in } } - let counter = try XCTUnwrap(Self.testMetrics.counters.withLockedValue { $0 }["hb_requests"] as? TestCounter) + let counter = try XCTUnwrap(Self.testMetrics.counters.withLockedValue { $0 }["hb.requests"] as? TestCounter) XCTAssertEqual(counter.values.withLockedValue { $0 }[0].1, 1) - XCTAssertEqual(counter.dimensions[0].0, "hb_uri") + XCTAssertEqual(counter.dimensions[0].0, "http.route") XCTAssertEqual(counter.dimensions[0].1, "/hello") - XCTAssertEqual(counter.dimensions[1].0, "hb_method") + XCTAssertEqual(counter.dimensions[1].0, "http.request.method") XCTAssertEqual(counter.dimensions[1].1, "GET") } @@ -219,12 +219,12 @@ final class MetricsTests: XCTestCase { try await client.execute(uri: "/hello", method: .get) { _ in } } - let counter = try XCTUnwrap(Self.testMetrics.counters.withLockedValue { $0 }["hb_errors"] as? TestCounter) + let counter = try XCTUnwrap(Self.testMetrics.counters.withLockedValue { $0 }["hb.request.errors"] as? TestCounter) XCTAssertEqual(counter.values.withLockedValue { $0 }.count, 1) XCTAssertEqual(counter.values.withLockedValue { $0 }[0].1, 1) - XCTAssertEqual(counter.dimensions[0].0, "hb_uri") + XCTAssertEqual(counter.dimensions[0].0, "http.route") XCTAssertEqual(counter.dimensions[0].1, "/hello") - XCTAssertEqual(counter.dimensions[1].0, "hb_method") + XCTAssertEqual(counter.dimensions[1].0, "http.request.method") XCTAssertEqual(counter.dimensions[1].1, "GET") } @@ -239,14 +239,14 @@ final class MetricsTests: XCTestCase { try await client.execute(uri: "/hello2", method: .get) { _ in } } - let counter = try XCTUnwrap(Self.testMetrics.counters.withLockedValue { $0 }["hb_errors"] as? TestCounter) + let counter = try XCTUnwrap(Self.testMetrics.counters.withLockedValue { $0 }["hb.request.errors"] as? TestCounter) XCTAssertEqual(counter.values.withLockedValue { $0 }.count, 1) XCTAssertEqual(counter.values.withLockedValue { $0 }[0].1, 1) XCTAssertEqual(counter.dimensions.count, 2) - XCTAssertEqual(counter.dimensions[0].0, "hb_uri") - XCTAssertEqual(counter.dimensions[0].1, "NotFound") - XCTAssertEqual(counter.dimensions[1].0, "hb_method") - XCTAssertEqual(counter.dimensions[1].1, "GET") + XCTAssertEqual(counter.dimensions[0].0, "http.request.method") + XCTAssertEqual(counter.dimensions[0].1, "GET") + XCTAssertEqual(counter.dimensions[1].0, "error.type") + XCTAssertEqual(counter.dimensions[1].1, "404") } func testParameterEndpoint() async throws { @@ -260,14 +260,16 @@ final class MetricsTests: XCTestCase { try await client.execute(uri: "/user/765", method: .get) { _ in } } - let counter = try XCTUnwrap(Self.testMetrics.counters.withLockedValue { $0 }["hb_errors"] as? TestCounter) + let counter = try XCTUnwrap(Self.testMetrics.counters.withLockedValue { $0 }["hb.request.errors"] as? TestCounter) XCTAssertEqual(counter.values.withLockedValue { $0 }.count, 1) XCTAssertEqual(counter.values.withLockedValue { $0 }[0].1, 1) - XCTAssertEqual(counter.dimensions.count, 2) - XCTAssertEqual(counter.dimensions[0].0, "hb_uri") + XCTAssertEqual(counter.dimensions.count, 3) + XCTAssertEqual(counter.dimensions[0].0, "http.route") XCTAssertEqual(counter.dimensions[0].1, "/user/{id}") - XCTAssertEqual(counter.dimensions[1].0, "hb_method") + XCTAssertEqual(counter.dimensions[1].0, "http.request.method") XCTAssertEqual(counter.dimensions[1].1, "GET") + XCTAssertEqual(counter.dimensions[2].0, "error.type") + XCTAssertEqual(counter.dimensions[2].1, "400") } func testRecordingBodyWriteTime() async throws { @@ -283,7 +285,7 @@ final class MetricsTests: XCTestCase { try await client.execute(uri: "/hello", method: .get) { _ in } } - let timer = try XCTUnwrap(Self.testMetrics.timers.withLockedValue { $0 }["hb_request_duration"] as? TestTimer) + let timer = try XCTUnwrap(Self.testMetrics.timers.withLockedValue { $0 }["http.server.request.duration"] as? TestTimer) XCTAssertGreaterThan(timer.values.withLockedValue { $0 }[0].1, 5_000_000) } } diff --git a/Tests/HummingbirdTests/MiddlewareTests.swift b/Tests/HummingbirdTests/MiddlewareTests.swift index d5c0f175c..7642715dd 100644 --- a/Tests/HummingbirdTests/MiddlewareTests.swift +++ b/Tests/HummingbirdTests/MiddlewareTests.swift @@ -316,10 +316,10 @@ final class MiddlewareTests: XCTestCase { headers: [.contentType: "application/json"], body: .init(string: "{}") ) { _ in - let logs = logAccumalator.filter { $0.metadata?["hb_uri"]?.description == "/test" } + let logs = logAccumalator.filter { $0.metadata?["hb.request.path"]?.description == "/test" } let firstLog = try XCTUnwrap(logs.first) - XCTAssertEqual(firstLog.metadata?["hb_method"]?.description, "GET") - XCTAssertNotNil(firstLog.metadata?["hb_id"]) + XCTAssertEqual(firstLog.metadata?["hb.request.method"]?.description, "GET") + XCTAssertNotNil(firstLog.metadata?["hb.request.id"]) } } } @@ -349,8 +349,8 @@ final class MiddlewareTests: XCTestCase { headers: [.contentType: "application/json"], body: .init(string: "{}") ) { _ in - let logEntries = logAccumalator.filter { $0.metadata?["hb_uri"]?.description == "/some" } - XCTAssertEqual(logEntries.first?.metadata?["hb_headers"], .stringConvertible(["content-type": "application/json"])) + let logEntries = logAccumalator.filter { $0.metadata?["hb.request.path"]?.description == "/some" } + XCTAssertEqual(logEntries.first?.metadata?["hb.request.headers"], .stringConvertible(["content-type": "application/json"])) } try await client.execute( uri: "/none", @@ -358,8 +358,8 @@ final class MiddlewareTests: XCTestCase { headers: [.contentType: "application/json"], body: .init(string: "{}") ) { _ in - let logEntries = logAccumalator.filter { $0.metadata?["hb_uri"]?.description == "/none" } - XCTAssertNil(logEntries.first?.metadata?["hb_headers"]) + let logEntries = logAccumalator.filter { $0.metadata?["hb.request.path"]?.description == "/none" } + XCTAssertNil(logEntries.first?.metadata?["hb.request.headers"]) } try await client.execute( uri: "/all", @@ -367,8 +367,8 @@ final class MiddlewareTests: XCTestCase { headers: [.contentType: "application/json"], body: .init(string: "{}") ) { _ in - let logEntries = logAccumalator.filter { $0.metadata?["hb_uri"]?.description == "/all" } - guard case .stringConvertible(let headers) = logEntries.first?.metadata?["hb_headers"] else { + let logEntries = logAccumalator.filter { $0.metadata?["hb.request.path"]?.description == "/all" } + guard case .stringConvertible(let headers) = logEntries.first?.metadata?["hb.request.headers"] else { fatalError("Should never get here") } let reportedHeaders = try XCTUnwrap(headers as? [String: String]) @@ -401,8 +401,8 @@ final class MiddlewareTests: XCTestCase { headers: [.authorization: "basic okhasdf87654"], body: .init(string: "{}") ) { _ in - let logEntries = logAccumalator.filter { $0.metadata?["hb_uri"]?.description == "/some" } - XCTAssertEqual(logEntries.first?.metadata?["hb_headers"], .stringConvertible(["authorization": "***"])) + let logEntries = logAccumalator.filter { $0.metadata?["hb.request.path"]?.description == "/some" } + XCTAssertEqual(logEntries.first?.metadata?["hb.request.headers"], .stringConvertible(["authorization": "***"])) } try await client.execute( uri: "/all", @@ -410,8 +410,8 @@ final class MiddlewareTests: XCTestCase { headers: [.authorization: "basic kjhdfi7udsfkhj"], body: .init(string: "{}") ) { _ in - let logEntries = logAccumalator.filter { $0.metadata?["hb_uri"]?.description == "/all" } - guard case .stringConvertible(let headers) = logEntries.first?.metadata?["hb_headers"] else { + let logEntries = logAccumalator.filter { $0.metadata?["hb.request.path"]?.description == "/all" } + guard case .stringConvertible(let headers) = logEntries.first?.metadata?["hb.request.headers"] else { fatalError("Should never get here") } let reportedHeaders = try XCTUnwrap(headers as? [String: String]) @@ -444,9 +444,9 @@ final class MiddlewareTests: XCTestCase { headers: headers, body: .init(string: "{}") ) { _ in - let logs = logAccumalator.filter { $0.metadata?["hb_uri"]?.description == "/test" } + let logs = logAccumalator.filter { $0.metadata?["hb.request.path"]?.description == "/test" } let firstLog = try XCTUnwrap(logs.first) - XCTAssertEqual(firstLog.metadata?["hb_headers"], .stringConvertible(["hbtest": "One, Two"])) + XCTAssertEqual(firstLog.metadata?["hb.request.headers"], .stringConvertible(["hbtest": "One, Two"])) } } }