From f9dc85b7ab8030b4503afe1682d02786a9a4bd3b Mon Sep 17 00:00:00 2001 From: Morgan Pretty Date: Mon, 2 Oct 2023 12:59:52 +1100 Subject: [PATCH] Fixed a couple of onboarding bugs and tweaks some logs Fixed an issue where starting and then restarting onboarding would get the app into an invalid state Fixed an issue where newline characters could cause issues with parsing the recovery phrase Added additional logs to better be able to understand the database state --- .../Views & Modals/IncomingCallBanner.swift | 2 +- Session/Meta/AppDelegate.swift | 2 +- Session/Onboarding/LinkDeviceVC.swift | 4 - Session/Onboarding/Onboarding.swift | 15 +++- Session/Onboarding/SeedVC.swift | 4 + .../Config Handling/SessionUtil+Shared.swift | 4 +- .../SessionUtil/SessionUtil.swift | 16 ++-- SessionUtilitiesKit/Crypto/Mnemonic.swift | 2 +- SessionUtilitiesKit/Database/Storage.swift | 85 +++++++++++++------ .../Types/PagedDatabaseObserver.swift | 4 + SessionUtilitiesKit/JobRunner/JobRunner.swift | 2 + SignalUtilitiesKit/Utilities/AppSetup.swift | 10 --- 12 files changed, 98 insertions(+), 52 deletions(-) diff --git a/Session/Calls/Views & Modals/IncomingCallBanner.swift b/Session/Calls/Views & Modals/IncomingCallBanner.swift index 221531644..e37c4cce4 100644 --- a/Session/Calls/Views & Modals/IncomingCallBanner.swift +++ b/Session/Calls/Views & Modals/IncomingCallBanner.swift @@ -114,7 +114,7 @@ final class IncomingCallBanner: UIView, UIGestureRecognizerDelegate { publicKey: call.sessionId, threadVariant: .contact, customImageData: nil, - profile: Storage.shared.read { db in Profile.fetchOrCreate(db, id: call.sessionId) }, + profile: Storage.shared.read { [sessionId = call.sessionId] db in Profile.fetchOrCreate(db, id: sessionId) }, additionalProfile: nil ) displayNameLabel.text = call.contactName diff --git a/Session/Meta/AppDelegate.swift b/Session/Meta/AppDelegate.swift index 03103b7fe..c8afbab42 100644 --- a/Session/Meta/AppDelegate.swift +++ b/Session/Meta/AppDelegate.swift @@ -324,7 +324,7 @@ class AppDelegate: UIResponder, UIApplicationDelegate, UNUserNotificationCenterD // the user is in an invalid state (and should have already been shown a modal) guard success else { return } - SNLog("RootViewController ready, readying remaining processes") + SNLog("RootViewController ready for state: \(Onboarding.State.current), readying remaining processes") self?.initialLaunchFailed = false /// Trigger any launch-specific jobs and start the JobRunner with `JobRunner.appDidFinishLaunching()` some diff --git a/Session/Onboarding/LinkDeviceVC.swift b/Session/Onboarding/LinkDeviceVC.swift index 15d7b4a3a..261a25d75 100644 --- a/Session/Onboarding/LinkDeviceVC.swift +++ b/Session/Onboarding/LinkDeviceVC.swift @@ -130,10 +130,6 @@ final class LinkDeviceVC: BaseVC, UIPageViewControllerDataSource, UIPageViewCont // MARK: - Interaction - @objc private func close() { - dismiss(animated: true, completion: nil) - } - func controller(_ controller: QRCodeScanningViewController, didDetectQRCodeWith string: String, onError: (() -> ())?) { let seed = Data(hex: string) continueWithSeed(seed, onError: onError) diff --git a/Session/Onboarding/Onboarding.swift b/Session/Onboarding/Onboarding.swift index 7aab0b08d..22aa5d0b4 100644 --- a/Session/Onboarding/Onboarding.swift +++ b/Session/Onboarding/Onboarding.swift @@ -121,7 +121,7 @@ enum Onboarding { .eraseToAnyPublisher() } - enum State { + enum State: CustomStringConvertible { case newUser case missingName case completed @@ -138,6 +138,14 @@ enum Onboarding { // Otherwise we have enough for a full user and can start the app return .completed } + + var description: String { + switch self { + case .newUser: return "New User" // stringlint:disable + case .missingName: return "Missing Name" // stringlint:disable + case .completed: return "Completed" // stringlint:disable + } + } } enum Flow { @@ -145,7 +153,7 @@ enum Onboarding { /// If the user returns to an earlier screen during Onboarding we might need to clear out a partially created /// account (eg. returning from the PN setting screen to the seed entry screen when linking a device) - func unregister() { + func unregister(using dependencies: Dependencies = Dependencies()) { // Clear the in-memory state from SessionUtil SessionUtil.clearMemoryState() @@ -165,6 +173,9 @@ enum Onboarding { profileNameRetrievalIdentifier.mutate { $0 = nil } profileNameRetrievalPublisher.mutate { $0 = nil } + // Clear the cached 'encodedPublicKey' if needed + dependencies.caches.mutate(cache: .general) { $0.encodedPublicKey = nil } + UserDefaults.standard[.hasSyncedInitialConfiguration] = false } diff --git a/Session/Onboarding/SeedVC.swift b/Session/Onboarding/SeedVC.swift index f6ef5bdc8..a9952ade2 100644 --- a/Session/Onboarding/SeedVC.swift +++ b/Session/Onboarding/SeedVC.swift @@ -8,6 +8,8 @@ import SignalUtilitiesKit final class SeedVC: BaseVC { public static func mnemonic() throws -> String { let dbIsValid: Bool = Storage.shared.isValid + let dbHasRead: Bool = Storage.shared.hasSuccessfullyRead + let dbHasWritten: Bool = Storage.shared.hasSuccessfullyWritten let dbIsSuspendedUnsafe: Bool = Storage.shared.isSuspendedUnsafe if let hexEncodedSeed: String = Identity.fetchHexEncodedSeed() { @@ -19,6 +21,8 @@ final class SeedVC: BaseVC { let hasStoredEdKeyPair: Bool = (Identity.fetchUserEd25519KeyPair() != nil) let dbStates: [String] = [ "dbIsValid: \(dbIsValid)", // stringlint:disable + "dbHasRead: \(dbHasRead)", // stringlint:disable + "dbHasWritten: \(dbHasWritten)", // stringlint:disable "dbIsSuspendedUnsafe: \(dbIsSuspendedUnsafe)", // stringlint:disable "storedSeed: false", // stringlint:disable "userPublicKey: \(hasStoredPublicKey)", // stringlint:disable diff --git a/SessionMessagingKit/SessionUtil/Config Handling/SessionUtil+Shared.swift b/SessionMessagingKit/SessionUtil/Config Handling/SessionUtil+Shared.swift index 4a9c8d286..b3ee15dc5 100644 --- a/SessionMessagingKit/SessionUtil/Config Handling/SessionUtil+Shared.swift +++ b/SessionMessagingKit/SessionUtil/Config Handling/SessionUtil+Shared.swift @@ -77,7 +77,7 @@ internal extension SessionUtil { } } catch { - SNLog("[libSession] Failed to update/dump updated \(variant) config data due to error: \(error)") + SNLog("[SessionUtil] Failed to update/dump updated \(variant) config data due to error: \(error)") throw error } @@ -368,7 +368,7 @@ internal extension SessionUtil { loopCounter += 1 guard loopCounter < maxLoopCount else { - SNLog("[libSession] Got stuck in infinite loop processing '\(variant.configMessageKind.description)' data") + SNLog("[SessionUtil] Got stuck in infinite loop processing '\(variant.configMessageKind.description)' data") throw SessionUtilError.processingLoopLimitReached } } diff --git a/SessionMessagingKit/SessionUtil/SessionUtil.swift b/SessionMessagingKit/SessionUtil/SessionUtil.swift index 363951df4..e25a76c98 100644 --- a/SessionMessagingKit/SessionUtil/SessionUtil.swift +++ b/SessionMessagingKit/SessionUtil/SessionUtil.swift @@ -45,7 +45,7 @@ public enum SessionUtil { // MARK: - Variables internal static func syncDedupeId(_ publicKey: String) -> String { - return "EnqueueConfigurationSyncJob-\(publicKey)" + return "EnqueueConfigurationSyncJob-\(publicKey)" // stringlint:disable } /// Returns `true` if there is a config which needs to be pushed, but returns `false` if the configs are all up to date or haven't been @@ -63,7 +63,7 @@ public enum SessionUtil { public static var libSessionVersion: String { String(cString: LIBSESSION_UTIL_VERSION_STR) } internal static func lastError(_ conf: UnsafeMutablePointer?) -> String { - return (conf?.pointee.last_error.map { String(cString: $0) } ?? "Unknown") + return (conf?.pointee.last_error.map { String(cString: $0) } ?? "Unknown") // stringlint:disable } // MARK: - Loading @@ -84,7 +84,7 @@ public enum SessionUtil { guard let secretKey: [UInt8] = ed25519SecretKey, SessionUtil.configStore.wrappedValue.isEmpty - else { return } + else { return SNLog("[SessionUtil] Ignoring loadState for '\(userPublicKey)' due to existing state") } // If we weren't given a database instance then get one guard let db: Database = db else { @@ -125,6 +125,8 @@ public enum SessionUtil { ) } } + + SNLog("[SessionUtil] Completed loadState for '\(userPublicKey)'") } private static func loadState( @@ -169,7 +171,7 @@ public enum SessionUtil { }() guard result == 0 else { - let errorString: String = (error.map { String(cString: $0) } ?? "unknown error") + let errorString: String = (error.map { String(cString: $0) } ?? "unknown error") // stringlint:disable SNLog("[SessionUtil Error] Unable to create \(variant.rawValue) config object: \(errorString)") throw SessionUtilError.unableToCreateConfigObject } @@ -241,7 +243,7 @@ public enum SessionUtil { var cPushData: UnsafeMutablePointer! let configCountInfo: String = { - var result: String = "Invalid" + var result: String = "Invalid" // stringlint:disable try? CExceptionHelper.performSafely { switch variant { @@ -261,7 +263,7 @@ public enum SessionUtil { } } catch { - SNLog("[libSession] Failed to generate push data for \(variant) config data, size: \(configCountInfo), error: \(error)") + SNLog("[SessionUtil] Failed to generate push data for \(variant) config data, size: \(configCountInfo), error: \(error)") throw error } @@ -418,7 +420,7 @@ public enum SessionUtil { } } catch { - SNLog("[libSession] Failed to process merge of \(next.key) config data") + SNLog("[SessionUtil] Failed to process merge of \(next.key) config data") throw error } diff --git a/SessionUtilitiesKit/Crypto/Mnemonic.swift b/SessionUtilitiesKit/Crypto/Mnemonic.swift index c92cb8a50..a9dbcfd0c 100644 --- a/SessionUtilitiesKit/Crypto/Mnemonic.swift +++ b/SessionUtilitiesKit/Crypto/Mnemonic.swift @@ -118,7 +118,7 @@ public enum Mnemonic { } public static func decode(mnemonic: String, language: Language = .english) throws -> String { - var words: [String] = mnemonic.split(separator: " ").map { String($0) } + var words: [String] = mnemonic.components(separatedBy: .whitespacesAndNewlines) let truncatedWordSet: [String] = language.loadTruncatedWordSet() let prefixLength: Int = language.prefixLength var result = "" diff --git a/SessionUtilitiesKit/Database/Storage.swift b/SessionUtilitiesKit/Database/Storage.swift index 875cb85f5..7628f8b3d 100644 --- a/SessionUtilitiesKit/Database/Storage.swift +++ b/SessionUtilitiesKit/Database/Storage.swift @@ -41,6 +41,12 @@ open class Storage { /// this should be taken into consideration when used public private(set) var isSuspendedUnsafe: Bool = false + /// This property gets set the first time we successfully read from the database + public private(set) var hasSuccessfullyRead: Bool = false + + /// This property gets set the first time we successfully write to the database + public private(set) var hasSuccessfullyWritten: Bool = false + public var hasCompletedMigrations: Bool { migrationsCompleted.wrappedValue } public var currentlyRunningMigration: (identifier: TargetMigrations.Identifier, migration: Migration.Type)? { internalCurrentlyRunningMigration.wrappedValue @@ -456,37 +462,60 @@ open class Storage { // MARK: - Logging Functions - typealias CallInfo = (file: String, function: String, line: Int) - - private static func logSlowWrites( + private enum Action { + case read + case write + case logIfSlow + } + + private typealias CallInfo = (storage: Storage?, actions: [Action], file: String, function: String, line: Int) + + private static func perform( info: CallInfo, updates: @escaping (Database) throws -> T ) -> (Database) throws -> T { return { db in let start: CFTimeInterval = CACurrentMediaTime() + let actionName: String = (info.actions.contains(.write) ? "write" : "read") let fileName: String = (info.file.components(separatedBy: "/").last.map { " \($0):\(info.line)" } ?? "") - let timeout: Timer = Timer.scheduledTimerOnMainThread(withTimeInterval: writeWarningThreadshold) { - $0.invalidate() + let timeout: Timer? = { + guard info.actions.contains(.logIfSlow) else { return nil } - // Don't want to log on the main thread as to avoid confusion when debugging issues - DispatchQueue.global(qos: .default).async { - SNLog("[Storage\(fileName)] Slow write taking longer than \(writeWarningThreadshold, format: ".2", omitZeroDecimal: true)s - \(info.function)") + return Timer.scheduledTimerOnMainThread(withTimeInterval: Storage.writeWarningThreadshold) { + $0.invalidate() + + // Don't want to log on the main thread as to avoid confusion when debugging issues + DispatchQueue.global(qos: .default).async { + SNLog("[Storage\(fileName)] Slow \(actionName) taking longer than \(Storage.writeWarningThreadshold, format: ".2", omitZeroDecimal: true)s - \(info.function)") + } } - } + }() + + // If we timed out and are logging slow actions then log the actual duration to help us + // prioritise performance issues defer { - // If we timed out then log the actual duration to help us prioritise performance issues - if !timeout.isValid { + if timeout != nil && timeout?.isValid == false { let end: CFTimeInterval = CACurrentMediaTime() DispatchQueue.global(qos: .default).async { - SNLog("[Storage\(fileName)] Slow write completed after \(end - start, format: ".2", omitZeroDecimal: true)s") + SNLog("[Storage\(fileName)] Slow \(actionName) completed after \(end - start, format: ".2", omitZeroDecimal: true)s") } } - timeout.invalidate() + timeout?.invalidate() } - return try updates(db) + // Get the result + let result: T = try updates(db) + + // Update the state flags + switch info.actions { + case [.write], [.write, .logIfSlow]: info.storage?.hasSuccessfullyWritten = true + case [.read], [.read, .logIfSlow]: info.storage?.hasSuccessfullyRead = true + default: break + } + + return result } } @@ -516,9 +545,8 @@ open class Storage { ) -> T? { guard isValid, let dbWriter: DatabaseWriter = dbWriter else { return nil } - let info: CallInfo = (fileName, functionName, lineNumber) - - do { return try dbWriter.write(Storage.logSlowWrites(info: info, updates: updates)) } + let info: CallInfo = { [weak self] in (self, [.write, .logIfSlow], fileName, functionName, lineNumber) }() + do { return try dbWriter.write(Storage.perform(info: info, updates: updates)) } catch { return Storage.logIfNeeded(error, isWrite: true) } } @@ -549,10 +577,10 @@ open class Storage { ) { guard isValid, let dbWriter: DatabaseWriter = dbWriter else { return } - let info: CallInfo = (fileName, functionName, lineNumber) + let info: CallInfo = { [weak self] in (self, [.write, .logIfSlow], fileName, functionName, lineNumber) }() dbWriter.asyncWrite( - Storage.logSlowWrites(info: info, updates: updates), + Storage.perform(info: info, updates: updates), completion: { db, result in switch result { case .failure(let error): Storage.logIfNeeded(error, isWrite: true) @@ -576,7 +604,7 @@ open class Storage { .eraseToAnyPublisher() } - let info: CallInfo = (fileName, functionName, lineNumber) + let info: CallInfo = { [weak self] in (self, [.write, .logIfSlow], fileName, functionName, lineNumber) }() /// **Note:** GRDB does have a `writePublisher` method but it appears to asynchronously trigger /// both the `output` and `complete` closures at the same time which causes a lot of unexpected @@ -587,7 +615,7 @@ open class Storage { /// which behaves in a much more expected way than the GRDB `writePublisher` does return Deferred { Future { resolver in - do { resolver(Result.success(try dbWriter.write(Storage.logSlowWrites(info: info, updates: updates)))) } + do { resolver(Result.success(try dbWriter.write(Storage.perform(info: info, updates: updates)))) } catch { Storage.logIfNeeded(error, isWrite: true) resolver(Result.failure(error)) @@ -597,6 +625,9 @@ open class Storage { } open func readPublisher( + fileName: String = #file, + functionName: String = #function, + lineNumber: Int = #line, using dependencies: Dependencies = Dependencies(), value: @escaping (Database) throws -> T ) -> AnyPublisher { @@ -605,6 +636,8 @@ open class Storage { .eraseToAnyPublisher() } + let info: CallInfo = { [weak self] in (self, [.read], fileName, functionName, lineNumber) }() + /// **Note:** GRDB does have a `readPublisher` method but it appears to asynchronously trigger /// both the `output` and `complete` closures at the same time which causes a lot of unexpected /// behaviours (this behaviour is apparently expected but still causes a number of odd behaviours in our code @@ -614,7 +647,7 @@ open class Storage { /// which behaves in a much more expected way than the GRDB `readPublisher` does return Deferred { Future { resolver in - do { resolver(Result.success(try dbWriter.read(value))) } + do { resolver(Result.success(try dbWriter.read(Storage.perform(info: info, updates: value)))) } catch { Storage.logIfNeeded(error, isWrite: false) resolver(Result.failure(error)) @@ -624,12 +657,16 @@ open class Storage { } @discardableResult public func read( + fileName: String = #file, + functionName: String = #function, + lineNumber: Int = #line, using dependencies: Dependencies = Dependencies(), - _ value: (Database) throws -> T? + _ value: @escaping (Database) throws -> T? ) -> T? { guard isValid, let dbWriter: DatabaseWriter = dbWriter else { return nil } - do { return try dbWriter.read(value) } + let info: CallInfo = { [weak self] in (self, [.read], fileName, functionName, lineNumber) }() + do { return try dbWriter.read(Storage.perform(info: info, updates: value)) } catch { return Storage.logIfNeeded(error, isWrite: false) } } diff --git a/SessionUtilitiesKit/Database/Types/PagedDatabaseObserver.swift b/SessionUtilitiesKit/Database/Types/PagedDatabaseObserver.swift index 2c41643c2..6848bce11 100644 --- a/SessionUtilitiesKit/Database/Types/PagedDatabaseObserver.swift +++ b/SessionUtilitiesKit/Database/Types/PagedDatabaseObserver.swift @@ -131,6 +131,7 @@ public class PagedDatabaseObserver: TransactionObserver where // Retrieve the pagedRowId for the related value that is // getting deleted + let pagedTableName: String = self.pagedTableName let pagedRowIds: [Int64] = Storage.shared .read { db in PagedData.pagedRowIdsForRelatedRowIds( @@ -183,10 +184,13 @@ public class PagedDatabaseObserver: TransactionObserver where // Store the instance variables locally to avoid unwrapping let dataCache: DataCache = self.dataCache.wrappedValue let pageInfo: PagedData.PageInfo = self.pageInfo.wrappedValue + let pagedTableName: String = self.pagedTableName let joinSQL: SQL? = self.joinSQL let orderSQL: SQL = self.orderSQL let filterSQL: SQL = self.filterSQL + let dataQuery: ([Int64]) -> any FetchRequest = self.dataQuery let associatedRecords: [ErasedAssociatedRecord] = self.associatedRecords + let observedTableChangeTypes: [String: PagedData.ObservedChanges] = self.observedTableChangeTypes let getAssociatedDataInfo: (Database, PagedData.PageInfo) -> AssociatedDataInfo = { db, updatedPageInfo in associatedRecords.map { associatedRecord in let hasChanges: Bool = associatedRecord.tryUpdateForDatabaseCommit( diff --git a/SessionUtilitiesKit/JobRunner/JobRunner.swift b/SessionUtilitiesKit/JobRunner/JobRunner.swift index 5e80a9ee4..cc0ad5fdb 100644 --- a/SessionUtilitiesKit/JobRunner/JobRunner.swift +++ b/SessionUtilitiesKit/JobRunner/JobRunner.swift @@ -1096,6 +1096,7 @@ public final class JobQueue: Hashable { hasStartedAtLeastOnce.mutate { $0 = true } // Get any pending jobs + let jobVariants: [Job.Variant] = self.jobVariants let jobIdsAlreadyRunning: Set = currentlyRunningJobIds.wrappedValue let jobsAlreadyInQueue: Set = pendingJobsQueue.wrappedValue.compactMap { $0.id }.asSet() let jobsToRun: [Job] = dependencies.storage.read(using: dependencies) { db in @@ -1320,6 +1321,7 @@ public final class JobQueue: Hashable { } private func scheduleNextSoonestJob(using dependencies: Dependencies) { + let jobVariants: [Job.Variant] = self.jobVariants let jobIdsAlreadyRunning: Set = currentlyRunningJobIds.wrappedValue let nextJobTimestamp: TimeInterval? = dependencies.storage.read(using: dependencies) { db in try Job diff --git a/SignalUtilitiesKit/Utilities/AppSetup.swift b/SignalUtilitiesKit/Utilities/AppSetup.swift index 63d27a6f2..dfeb56848 100644 --- a/SignalUtilitiesKit/Utilities/AppSetup.swift +++ b/SignalUtilitiesKit/Utilities/AppSetup.swift @@ -112,16 +112,6 @@ public enum AppSetup { } }, onComplete: { result, needsConfigSync in - // After the migrations have run but before the migration completion we load the - // SessionUtil state and update the 'needsConfigSync' flag based on whether the - // configs also need to be sync'ed - if Identity.userExists() { - SessionUtil.loadState( - userPublicKey: getUserHexEncodedPublicKey(), - ed25519SecretKey: Identity.fetchUserEd25519KeyPair()?.secretKey - ) - } - // The 'needsConfigSync' flag should be based on whether either a migration or the // configs need to be sync'ed migrationsCompletion(result, (needsConfigSync || SessionUtil.needsSync))