From bcaa235c25497678453d4f1c22f5327da482f151 Mon Sep 17 00:00:00 2001 From: Guilherme Souza Date: Wed, 29 May 2024 09:34:29 -0300 Subject: [PATCH] chore(logs): better logs --- Sources/Auth/Internal/SessionManager.swift | 139 ++++++++++-------- Sources/_Helpers/HTTP/LoggerInterceptor.swift | 38 ++--- Sources/_Helpers/SupabaseLogger.swift | 94 ++++++++++-- Sources/_Helpers/TaskLocalHelpers.swift | 26 ++++ 4 files changed, 202 insertions(+), 95 deletions(-) create mode 100644 Sources/_Helpers/TaskLocalHelpers.swift diff --git a/Sources/Auth/Internal/SessionManager.swift b/Sources/Auth/Internal/SessionManager.swift index 5991837ec..15ed6c501 100644 --- a/Sources/Auth/Internal/SessionManager.swift +++ b/Sources/Auth/Internal/SessionManager.swift @@ -32,57 +32,62 @@ private actor LiveSessionManager { private var scheduledNextRefreshTask: Task? func session() async throws -> Session { - guard let currentSession = try storage.getSession() else { - throw AuthError.sessionNotFound - } + try await trace(using: logger) { + guard let currentSession = try storage.getSession() else { + throw AuthError.sessionNotFound + } - if !currentSession.isExpired { - scheduleNextTokenRefresh(currentSession) + if !currentSession.isExpired { + await scheduleNextTokenRefresh(currentSession) - return currentSession - } + return currentSession + } - return try await refreshSession(currentSession.refreshToken) + return try await refreshSession(currentSession.refreshToken) + } } func refreshSession(_ refreshToken: String) async throws -> Session { - logger?.debug("begin") - defer { logger?.debug("end") } - - if let inFlightRefreshTask { - logger?.debug("refresh already in flight") - return try await inFlightRefreshTask.value - } - - inFlightRefreshTask = Task { - logger?.debug("refresh task started") - - defer { - inFlightRefreshTask = nil - logger?.debug("refresh task ended") + try await SupabaseLoggerTaskLocal.$additionalContext.withValue( + merging: ["refreshID": .string(UUID().uuidString)] + ) { + try await trace(using: logger) { + if let inFlightRefreshTask { + logger?.debug("refresh already in flight") + return try await inFlightRefreshTask.value + } + + inFlightRefreshTask = Task { + logger?.debug("refresh task started") + + defer { + inFlightRefreshTask = nil + logger?.debug("refresh task ended") + } + + let session = try await api.execute( + HTTPRequest( + url: configuration.url.appendingPathComponent("token"), + method: .post, + query: [ + URLQueryItem(name: "grant_type", value: "refresh_token"), + ], + body: configuration.encoder.encode(UserCredentials(refreshToken: refreshToken)) + ) + ) + .decoded(as: Session.self, decoder: configuration.decoder) + + update(session) + eventEmitter.emit(.tokenRefreshed, session: session) + + await scheduleNextTokenRefresh(session) + + return session + } + + return try await inFlightRefreshTask!.value } - - let session = try await api.execute( - HTTPRequest( - url: configuration.url.appendingPathComponent("token"), - method: .post, - query: [ - URLQueryItem(name: "grant_type", value: "refresh_token"), - ], - body: configuration.encoder.encode(UserCredentials(refreshToken: refreshToken)) - ) - ) - .decoded(as: Session.self, decoder: configuration.decoder) - - update(session) - eventEmitter.emit(.tokenRefreshed, session: session) - - scheduleNextTokenRefresh(session) - - return session } - - return try await inFlightRefreshTask!.value } func update(_ session: Session) { @@ -101,37 +106,41 @@ private actor LiveSessionManager { } } - private func scheduleNextTokenRefresh(_ refreshedSession: Session, source: StaticString = #function) { - logger?.debug("source: \(source)") + private func scheduleNextTokenRefresh(_ refreshedSession: Session, caller: StaticString = #function) async { + await SupabaseLoggerTaskLocal.$additionalContext.withValue( + merging: ["caller": .string("\(caller)")] + ) { + guard configuration.autoRefreshToken else { + logger?.debug("auto refresh token disabled") + return + } - guard configuration.autoRefreshToken else { - logger?.debug("auto refresh token disabled") - return - } + guard scheduledNextRefreshTask == nil else { + logger?.debug("refresh task already scheduled") + return + } - guard scheduledNextRefreshTask == nil else { - logger?.debug("source: \(source) refresh task already scheduled") - return - } + scheduledNextRefreshTask = Task { + await trace(using: logger) { + defer { scheduledNextRefreshTask = nil } - scheduledNextRefreshTask = Task { - defer { scheduledNextRefreshTask = nil } + let expiresAt = Date(timeIntervalSince1970: refreshedSession.expiresAt) + let expiresIn = expiresAt.timeIntervalSinceNow - let expiresAt = Date(timeIntervalSince1970: refreshedSession.expiresAt) - let expiresIn = expiresAt.timeIntervalSinceNow + // if expiresIn < 0, it will refresh right away. + let timeToRefresh = max(expiresIn * 0.9, 0) - // if expiresIn < 0, it will refresh right away. - let timeToRefresh = max(expiresIn * 0.9, 0) + logger?.debug("scheduled next token refresh in: \(timeToRefresh)s") - logger?.debug("source: \(source) scheduled next token refresh in: \(timeToRefresh)s") + try? await Task.sleep(nanoseconds: NSEC_PER_SEC * UInt64(timeToRefresh)) - try? await Task.sleep(nanoseconds: NSEC_PER_SEC * UInt64(timeToRefresh)) + if Task.isCancelled { + return + } - if Task.isCancelled { - return + _ = try? await refreshSession(refreshedSession.refreshToken) + } } - - _ = try? await refreshSession(refreshedSession.refreshToken) } } } diff --git a/Sources/_Helpers/HTTP/LoggerInterceptor.swift b/Sources/_Helpers/HTTP/LoggerInterceptor.swift index 65559002a..05e196f48 100644 --- a/Sources/_Helpers/HTTP/LoggerInterceptor.swift +++ b/Sources/_Helpers/HTTP/LoggerInterceptor.swift @@ -19,28 +19,30 @@ package struct LoggerInterceptor: HTTPClientInterceptor { next: @Sendable (HTTPRequest) async throws -> HTTPResponse ) async throws -> HTTPResponse { let id = UUID().uuidString - logger.verbose( - """ - Request [\(id)]: \(request.method.rawValue) \(request.url.absoluteString - .removingPercentEncoding ?? "") - Body: \(stringfy(request.body)) - """ - ) - - do { - let response = try await next(request) + return try await SupabaseLoggerTaskLocal.$additionalContext.withValue(merging: ["requestID": .string(id)]) { logger.verbose( """ - Response [\(id)]: Status code: \(response.statusCode) Content-Length: \( - response.underlyingResponse.expectedContentLength - ) - Body: \(stringfy(response.data)) + Request: \(request.method.rawValue) \(request.url.absoluteString + .removingPercentEncoding ?? "") + Body: \(stringfy(request.body)) """ ) - return response - } catch { - logger.error("Response [\(id)]: Failure \(error)") - throw error + + do { + let response = try await next(request) + logger.verbose( + """ + Response: Status code: \(response.statusCode) Content-Length: \( + response.underlyingResponse.expectedContentLength + ) + Body: \(stringfy(response.data)) + """ + ) + return response + } catch { + logger.error("Response: Failure \(error)") + throw error + } } } } diff --git a/Sources/_Helpers/SupabaseLogger.swift b/Sources/_Helpers/SupabaseLogger.swift index 07cf9cf45..8bf018c35 100644 --- a/Sources/_Helpers/SupabaseLogger.swift +++ b/Sources/_Helpers/SupabaseLogger.swift @@ -16,6 +16,13 @@ public enum SupabaseLogLevel: Int, Codable, CustomStringConvertible, Sendable { } } +@usableFromInline +package enum SupabaseLoggerTaskLocal { + @TaskLocal + @usableFromInline + package static var additionalContext: JSONObject = [:] +} + public struct SupabaseLogMessage: Codable, CustomStringConvertible, Sendable { public let system: String public let level: SupabaseLogLevel @@ -24,6 +31,7 @@ public struct SupabaseLogMessage: Codable, CustomStringConvertible, Sendable { public let function: String public let line: UInt public let timestamp: TimeInterval + public let additionalContext: JSONObject @usableFromInline init( @@ -33,7 +41,8 @@ public struct SupabaseLogMessage: Codable, CustomStringConvertible, Sendable { fileID: String, function: String, line: UInt, - timestamp: TimeInterval + timestamp: TimeInterval, + additionalContext: JSONObject ) { self.system = system self.level = level @@ -42,12 +51,17 @@ public struct SupabaseLogMessage: Codable, CustomStringConvertible, Sendable { self.function = function self.line = line self.timestamp = timestamp + self.additionalContext = additionalContext } public var description: String { let date = iso8601Formatter.string(from: Date(timeIntervalSince1970: timestamp)) let file = fileID.split(separator: ".", maxSplits: 1).first.map(String.init) ?? fileID - return "\(date) [\(level)] [\(system)] [\(file).\(function):\(line)] \(message)" + var description = "\(date) [\(level)] [\(system)] [\(file).\(function):\(line)] \(message)" + if !additionalContext.isEmpty { + description += "\ncontext: \(additionalContext.description)" + } + return description } } @@ -68,7 +82,8 @@ extension SupabaseLogger { message: @autoclosure () -> String, fileID: StaticString = #fileID, function: StaticString = #function, - line: UInt = #line + line: UInt = #line, + additionalContext: JSONObject = [:] ) { let system = "\(fileID)".split(separator: "/").first ?? "" @@ -80,7 +95,11 @@ extension SupabaseLogger { fileID: "\(fileID)", function: "\(function)", line: line, - timestamp: Date().timeIntervalSince1970 + timestamp: Date().timeIntervalSince1970, + additionalContext: additionalContext.merging( + SupabaseLoggerTaskLocal.additionalContext, + uniquingKeysWith: { _, new in new } + ) ) ) } @@ -90,9 +109,17 @@ extension SupabaseLogger { _ message: @autoclosure () -> String, fileID: StaticString = #fileID, function: StaticString = #function, - line: UInt = #line + line: UInt = #line, + additionalContext: JSONObject = [:] ) { - log(.verbose, message: message(), fileID: fileID, function: function, line: line) + log( + .verbose, + message: message(), + fileID: fileID, + function: function, + line: line, + additionalContext: additionalContext + ) } @inlinable @@ -100,9 +127,17 @@ extension SupabaseLogger { _ message: @autoclosure () -> String, fileID: StaticString = #fileID, function: StaticString = #function, - line: UInt = #line + line: UInt = #line, + additionalContext: JSONObject = [:] ) { - log(.debug, message: message(), fileID: fileID, function: function, line: line) + log( + .debug, + message: message(), + fileID: fileID, + function: function, + line: line, + additionalContext: additionalContext + ) } @inlinable @@ -110,9 +145,17 @@ extension SupabaseLogger { _ message: @autoclosure () -> String, fileID: StaticString = #fileID, function: StaticString = #function, - line: UInt = #line + line: UInt = #line, + additionalContext: JSONObject = [:] ) { - log(.warning, message: message(), fileID: fileID, function: function, line: line) + log( + .warning, + message: message(), + fileID: fileID, + function: function, + line: line, + additionalContext: additionalContext + ) } @inlinable @@ -120,8 +163,35 @@ extension SupabaseLogger { _ message: @autoclosure () -> String, fileID: StaticString = #fileID, function: StaticString = #function, - line: UInt = #line + line: UInt = #line, + additionalContext: JSONObject = [:] ) { - log(.error, message: message(), fileID: fileID, function: function, line: line) + log( + .error, + message: message(), + fileID: fileID, + function: function, + line: line, + additionalContext: additionalContext + ) + } +} + +@inlinable +package func trace( + using logger: (any SupabaseLogger)?, + @_inheritActorContext _ operation: @Sendable () async throws -> R, + fileID: StaticString = #fileID, + function: StaticString = #function, + line: UInt = #line +) async rethrows -> R { + logger?.debug("begin", fileID: fileID, function: function, line: line) + defer { logger?.debug("end", fileID: fileID, function: function, line: line) } + + do { + return try await operation() + } catch { + logger?.debug("error: \(error)", fileID: fileID, function: function, line: line) + throw error } } diff --git a/Sources/_Helpers/TaskLocalHelpers.swift b/Sources/_Helpers/TaskLocalHelpers.swift new file mode 100644 index 000000000..326669dfb --- /dev/null +++ b/Sources/_Helpers/TaskLocalHelpers.swift @@ -0,0 +1,26 @@ +// +// TaskLocalHelpers.swift +// +// +// Created by Guilherme Souza on 29/05/24. +// + +import Foundation + +extension TaskLocal where Value == JSONObject { + @discardableResult + @inlinable package func withValue( + merging valueDuringOperation: Value, + @_inheritActorContext operation: @Sendable () async throws -> R, + file: String = #fileID, + line: UInt = #line + ) async rethrows -> R { + let currentValue = wrappedValue + return try await withValue( + currentValue.merging(valueDuringOperation) { _, new in new }, + operation: operation, + file: file, + line: line + ) + } +}