Skip to content

Commit

Permalink
Metrics and Logging name changes (#541)
Browse files Browse the repository at this point in the history
  • Loading branch information
@adam-fowler
adam-fowler authored Sep 9, 2024
1 parent b482bb7 commit b286e64
Show file tree
Hide file tree
Showing 9 changed files with 74 additions and 56 deletions.
4 changes: 2 additions & 2 deletions Sources/Hummingbird/Application.swift
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand All @@ -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()
Expand Down
4 changes: 2 additions & 2 deletions Sources/Hummingbird/Files/FileIO.swift
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand All @@ -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)
}
Expand Down
16 changes: 8 additions & 8 deletions Sources/Hummingbird/Middleware/LogRequestMiddleware.swift
View file
Original file line number Diff line number Diff line change
Expand Up @@ -72,28 +72,28 @@ public struct LogRequestsMiddleware<Context: RequestContext>: 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):
context.logger.log(
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):
context.logger.log(
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)),
]
)
}
Expand Down
34 changes: 23 additions & 11 deletions Sources/Hummingbird/Middleware/MetricsMiddleware.swift
View file
Original file line number Diff line number Diff line change
Expand Up @@ -24,42 +24,54 @@ public struct MetricsMiddleware<Context: RequestContext>: 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
}
}
Expand Down
2 changes: 1 addition & 1 deletion Sources/Hummingbird/Server/RequestContext.swift
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand Down
2 changes: 1 addition & 1 deletion Sources/HummingbirdTesting/RouterTestFramework.swift
View file
Original file line number Diff line number Diff line change
Expand Up @@ -108,7 +108,7 @@ struct RouterTestFramework<Responder: HTTPResponder>: 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 {
Expand Down
4 changes: 4 additions & 0 deletions Sources/PerformanceTest/main.swift
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
34 changes: 18 additions & 16 deletions Tests/HummingbirdTests/MetricsTests.swift
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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")
}

Expand All @@ -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")
}

Expand All @@ -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 {
Expand All @@ -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 {
Expand All @@ -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)
}
}
30 changes: 15 additions & 15 deletions Tests/HummingbirdTests/MiddlewareTests.swift
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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"])
}
}
}
Expand Down Expand Up @@ -349,26 +349,26 @@ 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",
method: .get,
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",
method: .get,
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])
Expand Down Expand Up @@ -401,17 +401,17 @@ 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",
method: .get,
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])
Expand Down Expand Up @@ -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"]))
}
}
}
Expand Down

0 comments on commit b286e64

Please sign in to comment.