From ddd36b96a2e7a76bfa4261ef97e680c25836d8ca Mon Sep 17 00:00:00 2001 From: Morgan Pretty Date: Tue, 3 Sep 2024 09:45:33 +1000 Subject: [PATCH] Reworked deadlock handling, fixed a few other issues MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit • Fixed an issue where the background task to finish sending messages may not have sent the sync message or the main message after and upload • Fixed an issue where the SessionBackgroundTask was incorrectly reporting a failure to be created • Fixed an incorrect modal action colour • Fixed a crash when creating legacy groups • Updated the code so that we take charge of resolving the deadlock issue instead of relying on GRDB to do it • Updated the logic to timeout the SessionBackgroundTask with 5 seconds of background time remaining (to ensure we have enough time to suspend the network & database) --- LibSession-Util | 2 +- Session.xcodeproj/project.pbxproj | 8 +- .../Call Management/SessionCallManager.swift | 2 +- Session/Meta/AppDelegate.swift | 20 +- Session/Meta/MainAppContext.swift | 1 + Session/Meta/SessionApp.swift | 6 +- .../PushRegistrationManager.swift | 5 +- .../Settings/PrivacySettingsViewModel.swift | 3 +- .../NotificationServiceExtension.swift | 6 +- SessionShareExtension/ThreadPickerVC.swift | 6 +- .../Database/Models/Identity.swift | 4 +- SessionUtilitiesKit/Database/Storage.swift | 390 ++++++++++-------- .../Database/StorageError.swift | 1 + SessionUtilitiesKit/General/AppContext.swift | 2 + SessionUtilitiesKit/JobRunner/JobRunner.swift | 56 ++- .../Utilities/BackgroundTaskManager.swift | 51 ++- 16 files changed, 349 insertions(+), 214 deletions(-) diff --git a/LibSession-Util b/LibSession-Util index 2bf8c8144..de7d8a658 160000 --- a/LibSession-Util +++ b/LibSession-Util @@ -1 +1 @@ -Subproject commit 2bf8c81443494f227a9509ddd95889f196b668d6 +Subproject commit de7d8a6580d8317007460d8dcbf4ce821644f80a diff --git a/Session.xcodeproj/project.pbxproj b/Session.xcodeproj/project.pbxproj index 09b821a47..fcc09622f 100644 --- a/Session.xcodeproj/project.pbxproj +++ b/Session.xcodeproj/project.pbxproj @@ -7673,7 +7673,7 @@ CLANG_WARN__ARC_BRIDGE_CAST_NONARC = YES; CLANG_WARN__DUPLICATE_METHOD_MATCH = YES; CODE_SIGN_IDENTITY = "iPhone Developer"; - CURRENT_PROJECT_VERSION = 478; + CURRENT_PROJECT_VERSION = 483; ENABLE_BITCODE = NO; ENABLE_STRICT_OBJC_MSGSEND = YES; ENABLE_TESTABILITY = YES; @@ -7710,7 +7710,7 @@ GCC_WARN_UNUSED_VARIABLE = YES; HEADER_SEARCH_PATHS = ""; IPHONEOS_DEPLOYMENT_TARGET = 13.0; - MARKETING_VERSION = 2.7.2; + MARKETING_VERSION = 2.7.3; ONLY_ACTIVE_ARCH = YES; OTHER_CFLAGS = ( "-fobjc-arc-exceptions", @@ -7751,7 +7751,7 @@ CLANG_WARN__ARC_BRIDGE_CAST_NONARC = YES; CLANG_WARN__DUPLICATE_METHOD_MATCH = YES; CODE_SIGN_IDENTITY = "iPhone Distribution"; - CURRENT_PROJECT_VERSION = 478; + CURRENT_PROJECT_VERSION = 483; ENABLE_BITCODE = NO; ENABLE_STRICT_OBJC_MSGSEND = YES; GCC_NO_COMMON_BLOCKS = YES; @@ -7783,7 +7783,7 @@ GCC_WARN_UNUSED_VARIABLE = YES; HEADER_SEARCH_PATHS = ""; IPHONEOS_DEPLOYMENT_TARGET = 13.0; - MARKETING_VERSION = 2.7.2; + MARKETING_VERSION = 2.7.3; ONLY_ACTIVE_ARCH = NO; OTHER_CFLAGS = ( "-DNS_BLOCK_ASSERTIONS=1", diff --git a/Session/Calls/Call Management/SessionCallManager.swift b/Session/Calls/Call Management/SessionCallManager.swift index 981d36cbd..c2ccfac72 100644 --- a/Session/Calls/Call Management/SessionCallManager.swift +++ b/Session/Calls/Call Management/SessionCallManager.swift @@ -205,7 +205,7 @@ public final class SessionCallManager: NSObject, CallManagerProtocol { // Stop all jobs except for message sending and when completed suspend the database JobRunner.stopAndClearPendingJobs(exceptForVariant: .messageSend, using: dependencies) { _ in LibSession.suspendNetworkAccess() - Storage.suspendDatabaseAccess() + Storage.suspendDatabaseAccess(using: dependencies) Log.flush() } } diff --git a/Session/Meta/AppDelegate.swift b/Session/Meta/AppDelegate.swift index d3ebdb617..155ec6bcd 100644 --- a/Session/Meta/AppDelegate.swift +++ b/Session/Meta/AppDelegate.swift @@ -147,7 +147,7 @@ class AppDelegate: UIResponder, UIApplicationDelegate, UNUserNotificationCenterD /// Apple's documentation on the matter) UNUserNotificationCenter.current().delegate = self - Storage.resumeDatabaseAccess() + Storage.resumeDatabaseAccess(using: dependencies) LibSession.resumeNetworkAccess() // Reset the 'startTime' (since it would be invalid from the last launch) @@ -209,10 +209,10 @@ class AppDelegate: UIResponder, UIApplicationDelegate, UNUserNotificationCenterD stopPollers(shouldStopUserPoller: !self.hasCallOngoing()) // Stop all jobs except for message sending and when completed suspend the database - JobRunner.stopAndClearPendingJobs(exceptForVariant: .messageSend, using: dependencies) { neededBackgroundProcessing in + JobRunner.stopAndClearPendingJobs(exceptForVariant: .messageSend, using: dependencies) { [dependencies] neededBackgroundProcessing in if !self.hasCallOngoing() && (!neededBackgroundProcessing || Singleton.hasAppContext && Singleton.appContext.isInBackground) { LibSession.suspendNetworkAccess() - Storage.suspendDatabaseAccess() + Storage.suspendDatabaseAccess(using: dependencies) Log.info("[AppDelegate] completed network and database shutdowns.") Log.flush() } @@ -238,7 +238,7 @@ class AppDelegate: UIResponder, UIApplicationDelegate, UNUserNotificationCenterD UserDefaults.sharedLokiProject?[.isMainAppActive] = true // FIXME: Seems like there are some discrepancies between the expectations of how the iOS lifecycle methods work, we should look into them and ensure the code behaves as expected (in this case there were situations where these two wouldn't get called when returning from the background) - Storage.resumeDatabaseAccess() + Storage.resumeDatabaseAccess(using: dependencies) LibSession.resumeNetworkAccess() ensureRootViewController(calledFrom: .didBecomeActive) @@ -288,7 +288,7 @@ class AppDelegate: UIResponder, UIApplicationDelegate, UNUserNotificationCenterD func application(_ application: UIApplication, performFetchWithCompletionHandler completionHandler: @escaping (UIBackgroundFetchResult) -> Void) { Log.appResumedExecution() Log.info("Starting background fetch.") - Storage.resumeDatabaseAccess() + Storage.resumeDatabaseAccess(using: dependencies) LibSession.resumeNetworkAccess() let queue: DispatchQueue = .global(qos: .userInitiated) @@ -302,7 +302,7 @@ class AppDelegate: UIResponder, UIApplicationDelegate, UNUserNotificationCenterD let cancelTimer: Timer = Timer.scheduledTimerOnMainThread( withTimeInterval: (application.backgroundTimeRemaining - 5), repeats: false - ) { [poller] timer in + ) { [poller, dependencies] timer in timer.invalidate() guard cancellable != nil else { return } @@ -312,7 +312,7 @@ class AppDelegate: UIResponder, UIApplicationDelegate, UNUserNotificationCenterD if Singleton.hasAppContext && Singleton.appContext.isInBackground { LibSession.suspendNetworkAccess() - Storage.suspendDatabaseAccess() + Storage.suspendDatabaseAccess(using: dependencies) Log.flush() } @@ -338,7 +338,7 @@ class AppDelegate: UIResponder, UIApplicationDelegate, UNUserNotificationCenterD if Singleton.hasAppContext && Singleton.appContext.isInBackground { LibSession.suspendNetworkAccess() - Storage.suspendDatabaseAccess() + Storage.suspendDatabaseAccess(using: dependencies) Log.flush() } @@ -934,7 +934,7 @@ private enum StartupError: Error { var name: String { switch self { - case .databaseError(StorageError.startupFailed), .databaseError(DatabaseError.SQLITE_LOCKED): + case .databaseError(StorageError.startupFailed), .databaseError(DatabaseError.SQLITE_LOCKED), .databaseError(StorageError.databaseSuspended): return "Database startup failed" case .databaseError(StorageError.migrationNoLongerSupported): return "Unsupported version" @@ -946,7 +946,7 @@ private enum StartupError: Error { var message: String { switch self { - case .databaseError(StorageError.startupFailed), .databaseError(DatabaseError.SQLITE_LOCKED): + case .databaseError(StorageError.startupFailed), .databaseError(DatabaseError.SQLITE_LOCKED), .databaseError(StorageError.databaseSuspended): return "DATABASE_STARTUP_FAILED".localized() case .databaseError(StorageError.migrationNoLongerSupported): diff --git a/Session/Meta/MainAppContext.swift b/Session/Meta/MainAppContext.swift index adfedcf43..31edf0b38 100644 --- a/Session/Meta/MainAppContext.swift +++ b/Session/Meta/MainAppContext.swift @@ -23,6 +23,7 @@ final class MainAppContext: AppContext { return result } var frontmostViewController: UIViewController? { UIApplication.shared.frontmostViewControllerIgnoringAlerts } + var backgroundTimeRemaining: TimeInterval { UIApplication.shared.backgroundTimeRemaining } var mainWindow: UIWindow? var wasWokenUpByPushNotification: Bool = false diff --git a/Session/Meta/SessionApp.swift b/Session/Meta/SessionApp.swift index 043f63a5d..1dc53a1a3 100644 --- a/Session/Meta/SessionApp.swift +++ b/Session/Meta/SessionApp.swift @@ -126,7 +126,11 @@ public struct SessionApp { Log.info("Data Reset Complete.") Log.flush() - exit(0) + /// Wait until the next run loop to kill the app (hoping to avoid a crash due to the connection closes + /// triggering logs) + DispatchQueue.main.async { + exit(0) + } } public static func showHomeView(using dependencies: Dependencies) { diff --git a/Session/Notifications/PushRegistrationManager.swift b/Session/Notifications/PushRegistrationManager.swift index c4cc87cc8..3c1f82531 100644 --- a/Session/Notifications/PushRegistrationManager.swift +++ b/Session/Notifications/PushRegistrationManager.swift @@ -290,7 +290,10 @@ public enum PushRegistrationError: Error { return } - Storage.resumeDatabaseAccess() + // FIXME: Initialise the `PushRegistrationManager` with a dependencies instance + let dependencies: Dependencies = Dependencies() + + Storage.resumeDatabaseAccess(using: dependencies) LibSession.resumeNetworkAccess() let maybeCall: SessionCall? = Storage.shared.write { db in diff --git a/Session/Settings/PrivacySettingsViewModel.swift b/Session/Settings/PrivacySettingsViewModel.swift index 1526e0193..c67bc87be 100644 --- a/Session/Settings/PrivacySettingsViewModel.swift +++ b/Session/Settings/PrivacySettingsViewModel.swift @@ -307,7 +307,8 @@ class PrivacySettingsViewModel: SessionTableViewModel, NavigationItemSource, Nav showCondition: .disabled, confirmTitle: "continue_2".localized(), confirmAccessibility: Accessibility(identifier: "Enable"), - confirmStyle: .textPrimary, + confirmStyle: .danger, + cancelStyle: .alert_text, onConfirm: { _ in Permissions.requestMicrophonePermissionIfNeeded() } ), onTap: { diff --git a/SessionNotificationServiceExtension/NotificationServiceExtension.swift b/SessionNotificationServiceExtension/NotificationServiceExtension.swift index f0c589d48..4eb4b578e 100644 --- a/SessionNotificationServiceExtension/NotificationServiceExtension.swift +++ b/SessionNotificationServiceExtension/NotificationServiceExtension.swift @@ -51,7 +51,7 @@ public final class NotificationServiceExtension: UNNotificationServiceExtension } // Perform main setup - Storage.resumeDatabaseAccess() + Storage.resumeDatabaseAccess(using: dependencies) DispatchQueue.main.sync { self.setUpIfNecessary() { [weak self] in self?.handleNotification(notificationContent, isPerformingResetup: false) @@ -415,7 +415,7 @@ public final class NotificationServiceExtension: UNNotificationServiceExtension Log.info(handledNotification ? "Completed after handling notification." : "Completed silently.") if !isMainAppAndActive { - Storage.suspendDatabaseAccess() + Storage.suspendDatabaseAccess(using: dependencies) } Log.flush() @@ -495,7 +495,7 @@ public final class NotificationServiceExtension: UNNotificationServiceExtension private func handleFailure(for content: UNMutableNotificationContent, error: NotificationError) { Log.error("Show generic failure message due to error: \(error).") - Storage.suspendDatabaseAccess() + Storage.suspendDatabaseAccess(using: dependencies) Log.flush() content.title = "Session" diff --git a/SessionShareExtension/ThreadPickerVC.swift b/SessionShareExtension/ThreadPickerVC.swift index 93cec4622..259f9ef5d 100644 --- a/SessionShareExtension/ThreadPickerVC.swift +++ b/SessionShareExtension/ThreadPickerVC.swift @@ -111,7 +111,7 @@ final class ThreadPickerVC: UIViewController, UITableViewDataSource, UITableView // When the thread picker disappears it means the user has left the screen (this will be called // whether the user has sent the message or cancelled sending) LibSession.suspendNetworkAccess() - Storage.suspendDatabaseAccess() + Storage.suspendDatabaseAccess(using: viewModel.dependencies) Log.flush() } @@ -240,7 +240,7 @@ final class ThreadPickerVC: UIViewController, UITableViewDataSource, UITableView shareNavController?.dismiss(animated: true, completion: nil) ModalActivityIndicatorViewController.present(fromViewController: shareNavController!, canCancel: false, message: "vc_share_sending_message".localized()) { [dependencies = viewModel.dependencies] activityIndicator in - Storage.resumeDatabaseAccess() + Storage.resumeDatabaseAccess(using: dependencies) LibSession.resumeNetworkAccess() let swarmPublicKey: String = { @@ -336,7 +336,7 @@ final class ThreadPickerVC: UIViewController, UITableViewDataSource, UITableView .sinkUntilComplete( receiveCompletion: { [weak self] result in LibSession.suspendNetworkAccess() - Storage.suspendDatabaseAccess() + Storage.suspendDatabaseAccess(using: dependencies) Log.flush() activityIndicator.dismiss { } diff --git a/SessionUtilitiesKit/Database/Models/Identity.swift b/SessionUtilitiesKit/Database/Models/Identity.swift index f420bc6f8..ef2ea789e 100644 --- a/SessionUtilitiesKit/Database/Models/Identity.swift +++ b/SessionUtilitiesKit/Database/Models/Identity.swift @@ -142,7 +142,7 @@ public extension Identity { static func mnemonic() throws -> String { let dbIsValid: Bool = Storage.shared.isValid - let dbIsSuspendedUnsafe: Bool = Storage.shared.isSuspendedUnsafe + let dbIsSuspended: Bool = Storage.shared.isSuspended if let hexEncodedSeed: String = Identity.fetchHexEncodedSeed() { return Mnemonic.encode(hexEncodedString: hexEncodedSeed) @@ -153,7 +153,7 @@ public extension Identity { let hasStoredEdKeyPair: Bool = (Identity.fetchUserEd25519KeyPair() != nil) let dbStates: [String] = [ "dbIsValid: \(dbIsValid)", - "dbIsSuspendedUnsafe: \(dbIsSuspendedUnsafe)", + "dbIsSuspended: \(dbIsSuspended)", "storedSeed: false", "userPublicKey: \(hasStoredPublicKey)", "userPrivateKey: false", diff --git a/SessionUtilitiesKit/Database/Storage.swift b/SessionUtilitiesKit/Database/Storage.swift index 21af6afc9..68792df55 100644 --- a/SessionUtilitiesKit/Database/Storage.swift +++ b/SessionUtilitiesKit/Database/Storage.swift @@ -17,7 +17,12 @@ open class Storage { public static let queuePrefix: String = "SessionDatabase" private static let dbFileName: String = "Session.sqlite" private static let kSQLCipherKeySpecLength: Int = 48 - private static let writeWarningThreadshold: TimeInterval = 3 + + /// If a transaction takes longer than this duration a warning will be logged but the transaction will continue to run + private static let slowTransactionThreshold: TimeInterval = 3 + + /// When attempting to do a write the transaction will wait this long to acquite a lock before failing + private static let writeTransactionStartTimeout: TimeInterval = 5 private static var sharedDatabaseDirectoryPath: String { "\(FileManager.default.appSharedDataDirectoryPath)/database" } private static var databasePath: String { "\(Storage.sharedDatabaseDirectoryPath)/\(Storage.dbFileName)" } @@ -38,11 +43,7 @@ open class Storage { public static let shared: Storage = Storage() public private(set) var isValid: Bool = false - - /// This property gets set when triggering the suspend/resume notifications for the database but `GRDB` will attempt to - /// resume the suspention when it attempts to perform a write so it's possible for this to return a **false-positive** so - /// this should be taken into consideration when used - public private(set) var isSuspendedUnsafe: Bool = false + public private(set) var isSuspended: Bool = false /// This property gets set the first time we successfully read from the database public private(set) var hasSuccessfullyRead: Bool = false @@ -98,8 +99,15 @@ open class Storage { // Configure the database and create the DatabasePool for interacting with the database var config = Configuration() config.label = Storage.queuePrefix - config.maximumReaderCount = 10 // Increase the max read connection limit - Default is 5 - config.observesSuspensionNotifications = true // Minimise `0xDEAD10CC` exceptions + config.maximumReaderCount = 10 /// Increase the max read connection limit - Default is 5 + + /// It seems we should do this per https://github.com/groue/GRDB.swift/pull/1485 but with this change + /// we then need to define how long a write transaction should wait for before timing out (read transactions always run + /// in`DEFERRED` mode so won't be affected by these settings) + config.defaultTransactionKind = .immediate + config.busyMode = .timeout(Storage.writeTransactionStartTimeout) + + /// Load in the SQLCipher keys config.prepareDatabase { db in var keySpec: Data = try Storage.getOrGenerateDatabaseKeySpec() defer { keySpec.resetBytes(in: 0..(_ error: Error, isWrite: Bool) -> T? { + logIfNeeded(error, isWrite: isWrite) + return nil + } + + static func logIfNeeded(_ error: Error, isWrite: Bool) -> AnyPublisher { + logIfNeeded(error, isWrite: isWrite) + return Fail(error: error).eraseToAnyPublisher() + } } - 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? = { - guard info.actions.contains(.logIfSlow) else { return nil } - - 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: .background).async { - Log.warn("[Storage\(fileName)] Slow \(actionName) taking longer than \(Storage.writeWarningThreadshold, format: ".2", omitZeroDecimal: true)s - \(info.function)") - } - } - }() + guard info.storage?.isSuspended == false else { throw StorageError.databaseSuspended } - // If we timed out and are logging slow actions then log the actual duration to help us - // prioritise performance issues - defer { - if timeout != nil && timeout?.isValid == false { - let end: CFTimeInterval = CACurrentMediaTime() - - DispatchQueue.global(qos: .background).async { - Log.warn("[Storage\(fileName)] Slow \(actionName) completed after \(end - start, format: ".2", omitZeroDecimal: true)s") - } - } - - timeout?.invalidate() - } + let timer: TransactionTimer = TransactionTimer.start(duration: Storage.slowTransactionThreshold, info: info) + defer { timer.stop() } // 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 + switch info.isWrite { + case true: info.storage?.hasSuccessfullyWritten = true + case false: info.storage?.hasSuccessfullyRead = true } return result } } - private static func logIfNeeded(_ error: Error, isWrite: Bool) { - switch error { - case DatabaseError.SQLITE_ABORT: - let message: String = ((error as? DatabaseError)?.message ?? "Unknown") - SNLog("[Storage] Database \(isWrite ? "write" : "read") failed due to error: \(message)") - - default: break - } - } - - private static func logIfNeeded(_ error: Error, isWrite: Bool) -> T? { - logIfNeeded(error, isWrite: isWrite) - return nil - } - // MARK: - Functions @discardableResult public func write( @@ -547,28 +547,13 @@ open class Storage { using dependencies: Dependencies = Dependencies(), updates: @escaping (Database) throws -> T? ) -> T? { - guard isValid, let dbWriter: DatabaseWriter = dbWriter else { return nil } - - 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) } - } - - open func writeAsync( - fileName: String = #file, - functionName: String = #function, - lineNumber: Int = #line, - using dependencies: Dependencies = Dependencies(), - updates: @escaping (Database) throws -> T - ) { - writeAsync( - fileName: fileName, - functionName: functionName, - lineNumber: lineNumber, - using: dependencies, - updates: updates, - completion: { _, _ in } - ) + switch StorageState(self) { + case .invalid(let error): return StorageState.logIfNeeded(error, isWrite: true) + case .valid(let dbWriter): + let info: CallInfo = CallInfo(fileName, functionName, lineNumber, true, self) + do { return try dbWriter.write(Storage.perform(info: info, updates: updates)) } + catch { return StorageState.logIfNeeded(error, isWrite: true) } + } } open func writeAsync( @@ -577,23 +562,24 @@ open class Storage { lineNumber: Int = #line, using dependencies: Dependencies = Dependencies(), updates: @escaping (Database) throws -> T, - completion: @escaping (Database, Swift.Result) throws -> Void + completion: @escaping (Database, Swift.Result) throws -> Void = { _, _ in } ) { - guard isValid, let dbWriter: DatabaseWriter = dbWriter else { return } - - let info: CallInfo = { [weak self] in (self, [.write, .logIfSlow], fileName, functionName, lineNumber) }() - - dbWriter.asyncWrite( - Storage.perform(info: info, updates: updates), - completion: { db, result in - switch result { - case .failure(let error): Storage.logIfNeeded(error, isWrite: true) - default: break - } - - try? completion(db, result) - } - ) + switch StorageState(self) { + case .invalid(let error): return StorageState.logIfNeeded(error, isWrite: true) + case .valid(let dbWriter): + let info: CallInfo = CallInfo(fileName, functionName, lineNumber, true, self) + dbWriter.asyncWrite( + Storage.perform(info: info, updates: updates), + completion: { db, result in + switch result { + case .failure(let error): StorageState.logIfNeeded(error, isWrite: true) + default: break + } + + try? completion(db, result) + } + ) + } } open func writePublisher( @@ -603,75 +589,73 @@ open class Storage { using dependencies: Dependencies = Dependencies(), updates: @escaping (Database) throws -> T ) -> AnyPublisher { - guard isValid, let dbWriter: DatabaseWriter = dbWriter else { - return Fail(error: StorageError.databaseInvalid) - .eraseToAnyPublisher() + switch StorageState(self) { + case .invalid(let error): return StorageState.logIfNeeded(error, isWrite: true) + case .valid(let dbWriter): + /// **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 + /// behaviours (this behaviour is apparently expected but still causes a number of odd behaviours in our code + /// for more information see https://github.com/groue/GRDB.swift/issues/1334) + /// + /// Instead of this we are just using `Deferred { Future {} }` which is executed on the specified scheduled + /// which behaves in a much more expected way than the GRDB `writePublisher` does + let info: CallInfo = CallInfo(fileName, functionName, lineNumber, true, self) + return Deferred { + Future { resolver in + do { resolver(Result.success(try dbWriter.write(Storage.perform(info: info, updates: updates)))) } + catch { + StorageState.logIfNeeded(error, isWrite: true) + resolver(Result.failure(error)) + } + } + }.eraseToAnyPublisher() } - - 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 - /// behaviours (this behaviour is apparently expected but still causes a number of odd behaviours in our code - /// for more information see https://github.com/groue/GRDB.swift/issues/1334) - /// - /// Instead of this we are just using `Deferred { Future {} }` which is executed on the specified scheduled - /// 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.perform(info: info, updates: updates)))) } - catch { - Storage.logIfNeeded(error, isWrite: true) - resolver(Result.failure(error)) - } - } - }.eraseToAnyPublisher() } - open func readPublisher( + @discardableResult public func read( fileName: String = #file, functionName: String = #function, lineNumber: Int = #line, using dependencies: Dependencies = Dependencies(), - value: @escaping (Database) throws -> T - ) -> AnyPublisher { - guard isValid, let dbWriter: DatabaseWriter = dbWriter else { - return Fail(error: StorageError.databaseInvalid) - .eraseToAnyPublisher() + _ value: @escaping (Database) throws -> T? + ) -> T? { + switch StorageState(self) { + case .invalid(let error): return StorageState.logIfNeeded(error, isWrite: false) + case .valid(let dbWriter): + let info: CallInfo = CallInfo(fileName, functionName, lineNumber, false, self) + do { return try dbWriter.read(Storage.perform(info: info, updates: value)) } + catch { return StorageState.logIfNeeded(error, isWrite: false) } } - - 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 - /// for more information see https://github.com/groue/GRDB.swift/issues/1334) - /// - /// Instead of this we are just using `Deferred { Future {} }` which is executed on the specified scheduled - /// 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(Storage.perform(info: info, updates: value)))) } - catch { - Storage.logIfNeeded(error, isWrite: false) - resolver(Result.failure(error)) - } - } - }.eraseToAnyPublisher() } - @discardableResult public func read( + open func readPublisher( fileName: String = #file, functionName: String = #function, lineNumber: Int = #line, using dependencies: Dependencies = Dependencies(), - _ value: @escaping (Database) throws -> T? - ) -> T? { - guard isValid, let dbWriter: DatabaseWriter = dbWriter else { return nil } - - 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) } + value: @escaping (Database) throws -> T + ) -> AnyPublisher { + switch StorageState(self) { + case .invalid(let error): return StorageState.logIfNeeded(error, isWrite: false) + case .valid(let dbWriter): + /// **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 + /// for more information see https://github.com/groue/GRDB.swift/issues/1334) + /// + /// Instead of this we are just using `Deferred { Future {} }` which is executed on the specified scheduled + /// which behaves in a much more expected way than the GRDB `readPublisher` does + let info: CallInfo = CallInfo(fileName, functionName, lineNumber, false, self) + return Deferred { + Future { resolver in + do { resolver(Result.success(try dbWriter.read(Storage.perform(info: info, updates: value)))) } + catch { + StorageState.logIfNeeded(error, isWrite: false) + resolver(Result.failure(error)) + } + } + }.eraseToAnyPublisher() + } } /// Rever to the `ValueObservation.start` method for full documentation @@ -779,3 +763,79 @@ public extension Storage { } } #endif + +// MARK: - CallInfo + +private extension Storage { + class CallInfo { + let file: String + let function: String + let line: Int + let isWrite: Bool + weak var storage: Storage? + + var callInfo: String { + let fileInfo: String = (file.components(separatedBy: "/").last.map { "\($0):\(line) - " } ?? "") + + return "\(fileInfo)\(function)" + } + + init( + _ file: String, + _ function: String, + _ line: Int, + _ isWrite: Bool, + _ storage: Storage? + ) { + self.file = file + self.function = function + self.line = line + self.isWrite = isWrite + self.storage = storage + } + } +} + +// MARK: - TransactionTimer + +private extension Storage { + private static let timerQueue = DispatchQueue(label: "\(Storage.queuePrefix)-.transactionTimer", qos: .background) + + class TransactionTimer { + private let info: Storage.CallInfo + private let start: CFTimeInterval = CACurrentMediaTime() + private var timer: DispatchSourceTimer? = DispatchSource.makeTimerSource(queue: Storage.timerQueue) + private var wasSlowTransaction: Bool = false + + private init(info: Storage.CallInfo) { + self.info = info + } + + static func start(duration: TimeInterval, info: Storage.CallInfo) -> TransactionTimer { + let result: TransactionTimer = TransactionTimer(info: info) + result.timer?.schedule(deadline: .now() + .seconds(Int(duration)), repeating: .infinity) // Infinity to fire once + result.timer?.setEventHandler { [weak result] in + result?.timer?.cancel() + result?.timer = nil + + let action: String = (info.isWrite ? "write" : "read") + Log.warn("[Storage] Slow \(action) taking longer than \(Storage.slowTransactionThreshold, format: ".2", omitZeroDecimal: true)s - [ \(info.callInfo) ]") + result?.wasSlowTransaction = true + } + result.timer?.resume() + + return result + } + + func stop() { + timer?.cancel() + timer = nil + + guard wasSlowTransaction else { return } + + let end: CFTimeInterval = CACurrentMediaTime() + let action: String = (info.isWrite ? "write" : "read") + Log.warn("[Storage] Slow \(action) completed after \(end - start, format: ".2", omitZeroDecimal: true)s - [ \(info.callInfo) ]") + } + } +} diff --git a/SessionUtilitiesKit/Database/StorageError.swift b/SessionUtilitiesKit/Database/StorageError.swift index 5094ee875..6e3f63de9 100644 --- a/SessionUtilitiesKit/Database/StorageError.swift +++ b/SessionUtilitiesKit/Database/StorageError.swift @@ -5,6 +5,7 @@ import Foundation public enum StorageError: Error { case generic case databaseInvalid + case databaseSuspended case startupFailed case migrationFailed case migrationNoLongerSupported diff --git a/SessionUtilitiesKit/General/AppContext.swift b/SessionUtilitiesKit/General/AppContext.swift index 7ea5db7f5..47a1cbb88 100644 --- a/SessionUtilitiesKit/General/AppContext.swift +++ b/SessionUtilitiesKit/General/AppContext.swift @@ -24,6 +24,7 @@ public protocol AppContext: AnyObject { var mainWindow: UIWindow? { get } var isRTL: Bool { get } var frontmostViewController: UIViewController? { get } + var backgroundTimeRemaining: TimeInterval { get } func setMainWindow(_ mainWindow: UIWindow) func ensureSleepBlocking(_ shouldBeBlocking: Bool, blockingObjects: [Any]) @@ -43,6 +44,7 @@ public extension AppContext { var isShareExtension: Bool { false } var mainWindow: UIWindow? { nil } var frontmostViewController: UIViewController? { nil } + var backgroundTimeRemaining: TimeInterval { 0 } var isInBackground: Bool { reportedApplicationState == .background } var isAppForegroundAndActive: Bool { reportedApplicationState == .active } diff --git a/SessionUtilitiesKit/JobRunner/JobRunner.swift b/SessionUtilitiesKit/JobRunner/JobRunner.swift index 6dc4f03a9..dfff4201a 100644 --- a/SessionUtilitiesKit/JobRunner/JobRunner.swift +++ b/SessionUtilitiesKit/JobRunner/JobRunner.swift @@ -21,7 +21,7 @@ public protocol JobRunnerType { func appDidBecomeActive(using dependencies: Dependencies) func startNonBlockingQueues(using dependencies: Dependencies) - /// Stops and clears any pending jobs except for the specified variant, the `onComplete` closure will be called once complete providing a flag indicating whether any additionak + /// Stops and clears any pending jobs except for the specified variant, the `onComplete` closure will be called once complete providing a flag indicating whether any additional /// processing was needed before the closure was called (if not then the closure will be called synchronously) func stopAndClearPendingJobs(exceptForVariant: Job.Variant?, using dependencies: Dependencies, onComplete: ((Bool) -> ())?) @@ -555,6 +555,11 @@ public final class JobRunner: JobRunnerType { let jobQueues: [Job.Variant: JobQueue] = queues.wrappedValue let blockingQueueIsRunning: Bool = (blockingQueue.wrappedValue?.isRunning.wrappedValue == true) + // Reset the 'isRunningInBackgroundTask' flag just in case (since we aren't in the background anymore) + jobQueues.forEach { _, queue in + queue.isRunningInBackgroundTask.mutate { $0 = false } + } + guard !jobsToRun.isEmpty else { if !blockingQueueIsRunning { jobQueues.map { _, queue in queue }.asSet().forEach { $0.start(using: dependencies) } @@ -629,6 +634,7 @@ public final class JobRunner: JobRunnerType { } let oldQueueDrained: (() -> ())? = queue.onQueueDrained + queue.isRunningInBackgroundTask.mutate { $0 = true } // Create a backgroundTask to give the queue the chance to properly be drained shutdownBackgroundTask.mutate { @@ -636,12 +642,14 @@ public final class JobRunner: JobRunnerType { // If the background task didn't succeed then trigger the onComplete (and hope we have // enough time to complete it's logic) guard state != .cancelled else { + queue?.isRunningInBackgroundTask.mutate { $0 = false } queue?.onQueueDrained = oldQueueDrained return } guard state != .success else { return } onComplete?(true) + queue?.isRunningInBackgroundTask.mutate { $0 = false } queue?.onQueueDrained = oldQueueDrained queue?.stopAndClearPendingJobs() } @@ -650,6 +658,7 @@ public final class JobRunner: JobRunnerType { // Add a callback to be triggered once the queue is drained queue.onQueueDrained = { [weak self, weak queue] in oldQueueDrained?() + queue?.isRunningInBackgroundTask.mutate { $0 = false } queue?.onQueueDrained = oldQueueDrained onComplete?(true) @@ -677,11 +686,14 @@ public final class JobRunner: JobRunnerType { .insert(db) } + // Get the target queue + let jobQueue: JobQueue? = queues.wrappedValue[updatedJob.variant] + // Don't add to the queue if the JobRunner isn't ready (it's been saved to the db so it'll be loaded // once the queue actually get started later) - guard canAddToQueue(updatedJob) else { return updatedJob } + guard canAddToQueue(updatedJob) || jobQueue?.isRunningInBackgroundTask.wrappedValue == true else { return updatedJob } - let jobQueue: JobQueue? = queues.wrappedValue[updatedJob.variant] + // The queue is ready or running in a background task so we can add the job jobQueue?.add(db, job: updatedJob, canStartJob: canStartJob, using: dependencies) // Don't start the queue if the job can't be started @@ -986,6 +998,7 @@ public final class JobQueue: Hashable { fileprivate var hasStartedAtLeastOnce: Atomic = Atomic(false) fileprivate var isRunning: Atomic = Atomic(false) fileprivate var pendingJobsQueue: Atomic<[Job]> = Atomic([]) + fileprivate var isRunningInBackgroundTask: Atomic = Atomic(false) private var nextTrigger: Atomic = Atomic(nil) fileprivate var jobCallbacks: Atomic<[Int64: [(JobRunner.JobResult) -> ()]]> = Atomic([:]) @@ -1263,9 +1276,12 @@ public final class JobQueue: Hashable { forceWhenAlreadyRunning: Bool = false, using dependencies: Dependencies ) { - // Only start if the JobRunner is allowed to start the queue - guard canStart?(self) == true else { return } - guard forceWhenAlreadyRunning || !isRunning.wrappedValue else { return } + // Only start if the JobRunner is allowed to start the queue or if this queue is running in + // a background task + let isRunningInBackgroundTask: Bool = self.isRunningInBackgroundTask.wrappedValue + + guard canStart?(self) == true || isRunningInBackgroundTask else { return } + guard forceWhenAlreadyRunning || !isRunning.wrappedValue || isRunningInBackgroundTask else { return } // The JobRunner runs synchronously we need to ensure this doesn't start // on the main thread (if it is on the main thread then swap to a different thread) @@ -1290,18 +1306,24 @@ public final class JobQueue: Hashable { 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 - try Job - .filterPendingJobs( - variants: jobVariants, - excludeFutureJobs: true, - includeJobsWithDependencies: false - ) - .filter(!jobIdsAlreadyRunning.contains(Job.Columns.id)) // Exclude jobs already running - .filter(!jobsAlreadyInQueue.contains(Job.Columns.id)) // Exclude jobs already in the queue - .fetchAll(db) + let jobsToRun: [Job] + + switch isRunningInBackgroundTask { + case true: jobsToRun = [] // When running in a background task we don't want to schedule extra jobs + case false: + jobsToRun = dependencies.storage.read(using: dependencies) { db in + try Job + .filterPendingJobs( + variants: jobVariants, + excludeFutureJobs: true, + includeJobsWithDependencies: false + ) + .filter(!jobIdsAlreadyRunning.contains(Job.Columns.id)) // Exclude jobs already running + .filter(!jobsAlreadyInQueue.contains(Job.Columns.id)) // Exclude jobs already in the queue + .fetchAll(db) + } + .defaulting(to: []) } - .defaulting(to: []) // Determine the number of jobs to run var jobCount: Int = 0 diff --git a/SessionUtilitiesKit/Utilities/BackgroundTaskManager.swift b/SessionUtilitiesKit/Utilities/BackgroundTaskManager.swift index 2a15cf0d8..3733e8e0d 100644 --- a/SessionUtilitiesKit/Utilities/BackgroundTaskManager.swift +++ b/SessionUtilitiesKit/Utilities/BackgroundTaskManager.swift @@ -42,6 +42,11 @@ public class SessionBackgroundTaskManager { /// This property should only be accessed while synchronized on this instance. private var continuityTimer: Timer? + /// In order to ensure we have sufficient time to clean up before background tasks expire (without having to kick off additional tasks) + /// we track the remaining background execution time and end tasks 5 seconds early (same as the AppDelegate background fetch) + private var expirationTimeObserver: Timer? + private var hasGottenValidBackgroundTimeRemaining: Bool = false + fileprivate init() { self.isAppActive = ( Singleton.hasAppContext && @@ -118,6 +123,16 @@ public class SessionBackgroundTaskManager { self?.continuityTimer?.invalidate() self?.continuityTimer = nil + // Start observing the background time remaining + if self?.expirationTimeObserver?.isValid != true { + self?.hasGottenValidBackgroundTimeRemaining = false + self?.expirationTimeObserver = Timer.scheduledTimerOnMainThread( + withTimeInterval: 1, + repeats: true, + block: { _ in self?.expirationTimerDidFire() } + ) + } + return taskId } } @@ -137,7 +152,7 @@ public class SessionBackgroundTaskManager { self?.continuityTimer?.invalidate() self?.continuityTimer = Timer.scheduledTimerOnMainThread( withTimeInterval: 0.25, - block: { _ in self?.timerDidFire() } + block: { _ in self?.continuityTimerDidFire() } ) self?.ensureBackgroundTaskState() } @@ -175,6 +190,8 @@ public class SessionBackgroundTaskManager { // Need to end background task. let maybeBackgroundTaskId: UIBackgroundTaskIdentifier? = self?.backgroundTaskId self?.backgroundTaskId = .invalid + self?.expirationTimeObserver?.invalidate() + self?.expirationTimeObserver = nil if let backgroundTaskId: UIBackgroundTaskIdentifier = maybeBackgroundTaskId, backgroundTaskId != .invalid { Singleton.appContext.endBackgroundTask(backgroundTaskId) @@ -188,7 +205,6 @@ public class SessionBackgroundTaskManager { private func startBackgroundTask() -> Bool { guard Singleton.hasAppContext else { return false } - // TODO: Need to test that this does block itself (I guess the old @sync'ed allowed reentry? return SessionBackgroundTaskManager.synced(self) { [weak self] in self?.backgroundTaskId = Singleton.appContext.beginBackgroundTask { /// Supposedly `[UIApplication beginBackgroundTaskWithExpirationHandler]`'s handler @@ -211,6 +227,8 @@ public class SessionBackgroundTaskManager { SessionBackgroundTaskManager.synced(self) { [weak self] in backgroundTaskId = (self?.backgroundTaskId ?? .invalid) self?.backgroundTaskId = .invalid + self?.expirationTimeObserver?.invalidate() + self?.expirationTimeObserver = nil expirationMap = (self?.expirationMap ?? [:]) self?.expirationMap.removeAll() @@ -232,13 +250,35 @@ public class SessionBackgroundTaskManager { } } - private func timerDidFire() { + private func continuityTimerDidFire() { SessionBackgroundTaskManager.synced(self) { [weak self] in self?.continuityTimer?.invalidate() self?.continuityTimer = nil self?.ensureBackgroundTaskState() } } + + private func expirationTimerDidFire() { + guard Singleton.hasAppContext else { return } + + let backgroundTimeRemaining: TimeInterval = Singleton.appContext.backgroundTimeRemaining + + SessionBackgroundTaskManager.synced(self) { [weak self] in + // It takes the OS a little while to update the 'backgroundTimeRemaining' value so if it hasn't been updated + // yet then don't do anything + guard self?.hasGottenValidBackgroundTimeRemaining == true || backgroundTimeRemaining != .greatestFiniteMagnitude else { + return + } + + self?.hasGottenValidBackgroundTimeRemaining = true + + // If there is more than 5 seconds remaining then no need to do anything yet (plenty of time to continue running) + guard backgroundTimeRemaining <= 5 else { return } + + // There isn't a lot of time remaining so trigger the expiration + self?.backgroundTaskExpired() + } + } } // MARK: - SessionBackgroundTask @@ -292,8 +332,9 @@ public class SessionBackgroundTask { } } - // If a background task could not be begun, call the completion block - guard taskId != nil else { return } + // If we didn't get a taskId then the background task could not be started so + // we should call the completion block with a 'couldNotStart' error + guard taskId == nil else { return } SessionBackgroundTask.synced(self) { [weak self] in completion = self?.completion