From 1515d4fbc110fdcd28fd707ac81edf35147659d7 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Adrien=20Coye=20de=20Brune=CC=81lis?= Date: Tue, 18 Jun 2024 15:50:33 +0200 Subject: [PATCH 1/3] feat: New Sentry events to track in detail Token update issues --- MailCore/API/SyncedAuthenticator.swift | 104 ++++++++++++++++++------- MailCore/Utils/Logging.swift | 42 ++++++++++ MailCore/Utils/SentryDebug.swift | 68 +++++++++++++++- 3 files changed, 184 insertions(+), 30 deletions(-) diff --git a/MailCore/API/SyncedAuthenticator.swift b/MailCore/API/SyncedAuthenticator.swift index 65bd005f0..4e266dfc7 100644 --- a/MailCore/API/SyncedAuthenticator.swift +++ b/MailCore/API/SyncedAuthenticator.swift @@ -23,34 +23,63 @@ import InfomaniakDI import InfomaniakLogin import Sentry +public extension ApiToken { + var isInfinite: Bool { + expirationDate == nil + } + + var metadata: [String: Any] { + [ + "User id": userId, + "Expiration date": expirationDate?.timeIntervalSince1970 ?? "infinite", + "Access Token": truncatedAccessToken, + "Refresh Token": truncatedRefreshToken + ] + } +} + final class SyncedAuthenticator: OAuthAuthenticator { @LazyInjectService var keychainHelper: KeychainHelper @LazyInjectService var tokenStore: TokenStore @LazyInjectService var networkLoginService: InfomaniakNetworkLoginable - func handleFailedRefreshingToken(oldToken: ApiToken, error: Error?) -> Result { + func handleFailedRefreshingToken(oldToken: ApiToken, + newToken: ApiToken?, + error: Error?) -> Result { guard let error else { // Couldn't refresh the token, keep the old token and fetch it later. Maybe because of bad network ? - SentrySDK - .addBreadcrumb(oldToken.generateBreadcrumb(level: .error, - message: "Refreshing token failed - Other \(error.debugDescription)")) + Log.tokenAuthentication( + "Refreshing token failed - Other \(error.debugDescription)", + oldToken: oldToken, + newToken: newToken, + level: .error + ) + return .failure(MailError.unknownError) } if case .noRefreshToken = (error as? InfomaniakLoginError) { // Couldn't refresh the token because we don't have a refresh token - SentrySDK - .addBreadcrumb(oldToken.generateBreadcrumb(level: .error, - message: "Refreshing token failed - Cannot refresh infinite token")) + Log.tokenAuthentication( + "Refreshing token failed - Cannot refresh infinite token", + oldToken: oldToken, + newToken: newToken, + level: .error + ) + refreshTokenDelegate?.didFailRefreshToken(oldToken) return .failure(error) } if (error as NSError).domain == "invalid_grant" { // Couldn't refresh the token, API says it's invalid - SentrySDK - .addBreadcrumb(oldToken.generateBreadcrumb(level: .error, - message: "Refreshing token failed - Invalid grant")) + Log.tokenAuthentication( + "Refreshing token failed - Invalid grant", + oldToken: oldToken, + newToken: newToken, + level: .error + ) + refreshTokenDelegate?.didFailRefreshToken(oldToken) return .failure(error) } @@ -64,23 +93,37 @@ final class SyncedAuthenticator: OAuthAuthenticator { for session: Session, completion: @escaping (Result) -> Void ) { - SentrySDK.addBreadcrumb((credential as ApiToken).generateBreadcrumb(level: .info, message: "Refreshing token - Starting")) + let storedToken = tokenStore.tokenFor(userId: credential.userId, fetchLocation: .keychain) + + Log.tokenAuthentication( + "Refreshing token - Starting", + oldToken: storedToken, + newToken: credential, + level: .info + ) guard keychainHelper.isKeychainAccessible else { - SentrySDK - .addBreadcrumb((credential as ApiToken) - .generateBreadcrumb(level: .error, message: "Refreshing token failed - Keychain unaccessible")) + Log.tokenAuthentication( + "Refreshing token failed - Keychain unaccessible", + oldToken: storedToken, + newToken: credential, + level: .error + ) + completion(.failure(MailError.keychainUnavailable)) return } - if let storedToken = tokenStore.tokenFor(userId: credential.userId, fetchLocation: .keychain) { + if let storedToken { // Someone else refreshed our token and we already have an infinite token if storedToken.expirationDate == nil && credential.expirationDate != nil { - SentrySDK.addBreadcrumb(storedToken.generateBreadcrumb( - level: .info, - message: "Refreshing token - Success with local (infinite)" - )) + Log.tokenAuthentication( + "Refreshing token - Success with local (infinite)", + oldToken: storedToken, + newToken: credential, + level: .info + ) + completion(.success(storedToken)) return } @@ -88,10 +131,13 @@ final class SyncedAuthenticator: OAuthAuthenticator { if let storedTokenExpirationDate = storedToken.expirationDate, let tokenExpirationDate = credential.expirationDate, tokenExpirationDate > storedTokenExpirationDate { - SentrySDK.addBreadcrumb(storedToken.generateBreadcrumb( - level: .info, - message: "Refreshing token - Success with local" - )) + Log.tokenAuthentication( + "Refreshing token - Success with local", + oldToken: storedToken, + newToken: credential, + level: .info + ) + completion(.success(storedToken)) return } @@ -103,13 +149,17 @@ final class SyncedAuthenticator: OAuthAuthenticator { networkLoginService.refreshToken(token: credential) { token, error in // New token has been fetched correctly if let token { - SentrySDK - .addBreadcrumb(token - .generateBreadcrumb(level: .info, message: "Refreshing token - Success with remote")) + Log.tokenAuthentication( + "Refreshing token - Success with remote", + oldToken: credential, + newToken: token, + level: .info + ) + self.refreshTokenDelegate?.didUpdateToken(newToken: token, oldToken: credential) completion(.success(token)) } else { - completion(self.handleFailedRefreshingToken(oldToken: credential, error: error)) + completion(self.handleFailedRefreshingToken(oldToken: credential, newToken: token, error: error)) } expiringActivity.endAll() } diff --git a/MailCore/Utils/Logging.swift b/MailCore/Utils/Logging.swift index 9934dc824..17892062a 100644 --- a/MailCore/Utils/Logging.swift +++ b/MailCore/Utils/Logging.swift @@ -22,6 +22,7 @@ import CocoaLumberjackSwift import Foundation import InfomaniakCore import InfomaniakDI +import InfomaniakLogin import RealmSwift import Sentry @@ -125,3 +126,44 @@ public enum Logging { #endif } } + +/// Something to centralize log methods per feature +public enum Log { + public static func tokenAuthentication(_ message: @autoclosure () -> String, + oldToken: ApiToken?, + newToken: ApiToken?, + level: SentryLevel = .debug, + file: StaticString = #file, + function: StaticString = #function, + line: UInt = #line, + tag: Any? = nil) { + let message = message() + let oldTokenMetadata: Any = oldToken?.metadata ?? "NULL" + let newTokenMetadata: Any = newToken?.metadata ?? "NULL" + var metadata = [String: Any]() + metadata["oldToken"] = oldTokenMetadata + metadata["newToken"] = newTokenMetadata + + SentryDebug.capture( + message: message, + context: metadata, + level: level, + extras: ["file": "\(file)", "function": "\(function)", "line": "\(line)"] + ) + + SentryDebug.addBreadcrumb( + message: message, + category: SentryDebug.Category.threadAlgorithm, + level: level, + metadata: metadata + ) + + if level == .error { + DDLogError(message) + DDLogError("old token: \(oldTokenMetadata)") + DDLogError("new token: \(newTokenMetadata)") + } else { + DDLogInfo(message) + } + } +} diff --git a/MailCore/Utils/SentryDebug.swift b/MailCore/Utils/SentryDebug.swift index fd963dba6..81cfcee44 100644 --- a/MailCore/Utils/SentryDebug.swift +++ b/MailCore/Utils/SentryDebug.swift @@ -174,8 +174,9 @@ public enum SentryDebug { // MARK: - Breadcrumb - enum Category { - static let ThreadAlgorithm = "Thread algo" + public enum Category: String { + case threadAlgorithm = "Thread algo" + case syncedAuthenticator = "SyncedAuthenticator" } private static func createBreadcrumb(level: SentryLevel, @@ -201,7 +202,7 @@ public enum SentryDebug { static func nilDateParsingBreadcrumb(uid: String) { let breadcrumb = createBreadcrumb(level: .warning, - category: Category.ThreadAlgorithm, + category: Category.threadAlgorithm.rawValue, message: "Nil message date decoded", data: ["uid": uid]) SentrySDK.addBreadcrumb(breadcrumb) @@ -343,3 +344,64 @@ public enum SentryDebug { return true } } + +// MARK: - SHARED - + +public extension SentryDebug { + static func addBreadcrumb( + message: String, + category: SentryDebug.Category, + level: SentryLevel, + metadata: [String: Any]? = nil + ) { + Task { + let breadcrumb = Breadcrumb(level: level, category: category.rawValue) + breadcrumb.message = message + breadcrumb.data = metadata + SentrySDK.addBreadcrumb(breadcrumb) + } + } + + static func capture( + error: Error, + context: [String: Any]? = nil, + contextKey: String? = nil, + extras: [String: Any]? = nil + ) { + Task { + SentrySDK.capture(error: error) { scope in + if let context, let contextKey { + scope.setContext(value: context, key: contextKey) + } + + if let extras { + scope.setExtras(extras) + } + } + } + } + + static func capture( + message: String, + context: [String: Any]? = nil, + contextKey: String? = nil, + level: SentryLevel? = nil, + extras: [String: Any]? = nil + ) { + Task { + SentrySDK.capture(message: message) { scope in + if let context, let contextKey { + scope.setContext(value: context, key: contextKey) + } + + if let level { + scope.setLevel(level) + } + + if let extras { + scope.setExtras(extras) + } + } + } + } +} From 2920662b354a407f8440e5cd4a11d06578105690 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Adrien=20Coye=20de=20Brune=CC=81lis?= Date: Tue, 18 Jun 2024 16:28:54 +0200 Subject: [PATCH 2/3] chore: SonarCloud feedback --- MailCore/Utils/Logging.swift | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/MailCore/Utils/Logging.swift b/MailCore/Utils/Logging.swift index 17892062a..d185c13e2 100644 --- a/MailCore/Utils/Logging.swift +++ b/MailCore/Utils/Logging.swift @@ -135,8 +135,7 @@ public enum Log { level: SentryLevel = .debug, file: StaticString = #file, function: StaticString = #function, - line: UInt = #line, - tag: Any? = nil) { + line: UInt = #line) { let message = message() let oldTokenMetadata: Any = oldToken?.metadata ?? "NULL" let newTokenMetadata: Any = newToken?.metadata ?? "NULL" From 502917364997c7cd73911987cb0482c5e38d241a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Adrien=20Coye=20de=20Brune=CC=81lis?= Date: Wed, 19 Jun 2024 12:37:13 +0200 Subject: [PATCH 3/3] chore: PR Feedback --- MailCore/Utils/Logging.swift | 12 +++++------- MailCore/Utils/SentryDebug.swift | 28 ++++++++-------------------- 2 files changed, 13 insertions(+), 27 deletions(-) diff --git a/MailCore/Utils/Logging.swift b/MailCore/Utils/Logging.swift index d185c13e2..2b1ffe076 100644 --- a/MailCore/Utils/Logging.swift +++ b/MailCore/Utils/Logging.swift @@ -143,19 +143,17 @@ public enum Log { metadata["oldToken"] = oldTokenMetadata metadata["newToken"] = newTokenMetadata - SentryDebug.capture( + SentryDebug.asyncCapture( message: message, context: metadata, level: level, extras: ["file": "\(file)", "function": "\(function)", "line": "\(line)"] ) - SentryDebug.addBreadcrumb( - message: message, - category: SentryDebug.Category.threadAlgorithm, - level: level, - metadata: metadata - ) + SentryDebug.addAsyncBreadcrumb(level: level, + category: SentryDebug.Category.threadAlgorithm.rawValue, + message: message, + data: metadata) if level == .error { DDLogError(message) diff --git a/MailCore/Utils/SentryDebug.swift b/MailCore/Utils/SentryDebug.swift index 81cfcee44..805a33b52 100644 --- a/MailCore/Utils/SentryDebug.swift +++ b/MailCore/Utils/SentryDebug.swift @@ -190,16 +190,6 @@ public enum SentryDebug { return crumb } - private static func addAsyncBreadcrumb(level: SentryLevel, - category: String, - message: String, - data: [String: Any]? = nil) { - Task { - let breadcrumb = createBreadcrumb(level: level, category: category, message: message, data: data) - SentrySDK.addBreadcrumb(breadcrumb) - } - } - static func nilDateParsingBreadcrumb(uid: String) { let breadcrumb = createBreadcrumb(level: .warning, category: Category.threadAlgorithm.rawValue, @@ -348,21 +338,19 @@ public enum SentryDebug { // MARK: - SHARED - public extension SentryDebug { - static func addBreadcrumb( - message: String, - category: SentryDebug.Category, - level: SentryLevel, - metadata: [String: Any]? = nil - ) { + static func addAsyncBreadcrumb(level: SentryLevel, + category: String, + message: String, + data: [String: Any]? = nil) { Task { - let breadcrumb = Breadcrumb(level: level, category: category.rawValue) + let breadcrumb = Breadcrumb(level: level, category: category) breadcrumb.message = message - breadcrumb.data = metadata + breadcrumb.data = data SentrySDK.addBreadcrumb(breadcrumb) } } - static func capture( + static func asyncCapture( error: Error, context: [String: Any]? = nil, contextKey: String? = nil, @@ -381,7 +369,7 @@ public extension SentryDebug { } } - static func capture( + static func asyncCapture( message: String, context: [String: Any]? = nil, contextKey: String? = nil,