diff --git a/Session.xcodeproj/project.pbxproj b/Session.xcodeproj/project.pbxproj index 45cbabab4..ec1eaeea5 100644 --- a/Session.xcodeproj/project.pbxproj +++ b/Session.xcodeproj/project.pbxproj @@ -6649,7 +6649,7 @@ "CODE_SIGN_IDENTITY[sdk=iphoneos*]" = "iPhone Developer"; CODE_SIGN_STYLE = Automatic; COPY_PHASE_STRIP = NO; - CURRENT_PROJECT_VERSION = 415; + CURRENT_PROJECT_VERSION = 416; DEBUG_INFORMATION_FORMAT = "dwarf-with-dsym"; DEVELOPMENT_TEAM = SUQ8J2PCT7; FRAMEWORK_SEARCH_PATHS = "$(inherited)"; @@ -6721,7 +6721,7 @@ "CODE_SIGN_IDENTITY[sdk=iphoneos*]" = "iPhone Developer"; CODE_SIGN_STYLE = Automatic; COPY_PHASE_STRIP = NO; - CURRENT_PROJECT_VERSION = 415; + CURRENT_PROJECT_VERSION = 416; DEBUG_INFORMATION_FORMAT = "dwarf-with-dsym"; DEVELOPMENT_TEAM = SUQ8J2PCT7; ENABLE_NS_ASSERTIONS = NO; @@ -6786,7 +6786,7 @@ "CODE_SIGN_IDENTITY[sdk=iphoneos*]" = "iPhone Developer"; CODE_SIGN_STYLE = Automatic; COPY_PHASE_STRIP = NO; - CURRENT_PROJECT_VERSION = 415; + CURRENT_PROJECT_VERSION = 416; DEBUG_INFORMATION_FORMAT = "dwarf-with-dsym"; DEVELOPMENT_TEAM = SUQ8J2PCT7; FRAMEWORK_SEARCH_PATHS = "$(inherited)"; @@ -6860,7 +6860,7 @@ "CODE_SIGN_IDENTITY[sdk=iphoneos*]" = "iPhone Developer"; CODE_SIGN_STYLE = Automatic; COPY_PHASE_STRIP = NO; - CURRENT_PROJECT_VERSION = 415; + CURRENT_PROJECT_VERSION = 416; DEBUG_INFORMATION_FORMAT = "dwarf-with-dsym"; DEVELOPMENT_TEAM = SUQ8J2PCT7; ENABLE_NS_ASSERTIONS = NO; @@ -7768,7 +7768,7 @@ CODE_SIGN_ENTITLEMENTS = Session/Meta/Signal.entitlements; CODE_SIGN_IDENTITY = "iPhone Developer"; "CODE_SIGN_IDENTITY[sdk=iphoneos*]" = "iPhone Developer"; - CURRENT_PROJECT_VERSION = 415; + CURRENT_PROJECT_VERSION = 416; DEVELOPMENT_TEAM = SUQ8J2PCT7; FRAMEWORK_SEARCH_PATHS = ( "$(inherited)", @@ -7839,7 +7839,7 @@ CODE_SIGN_ENTITLEMENTS = Session/Meta/Signal.entitlements; CODE_SIGN_IDENTITY = "iPhone Developer"; "CODE_SIGN_IDENTITY[sdk=iphoneos*]" = "iPhone Developer"; - CURRENT_PROJECT_VERSION = 415; + CURRENT_PROJECT_VERSION = 416; DEVELOPMENT_TEAM = SUQ8J2PCT7; FRAMEWORK_SEARCH_PATHS = ( "$(inherited)", diff --git a/Session/Conversations/ConversationViewModel.swift b/Session/Conversations/ConversationViewModel.swift index 81f84fe6c..4aa7db7fb 100644 --- a/Session/Conversations/ConversationViewModel.swift +++ b/Session/Conversations/ConversationViewModel.swift @@ -1,6 +1,7 @@ // Copyright © 2022 Rangeproof Pty Ltd. All rights reserved. import Foundation +import Combine import GRDB import DifferenceKit import SessionMessagingKit @@ -44,6 +45,8 @@ public class ConversationViewModel: OWSAudioPlayerDelegate { public let focusedInteractionInfo: Interaction.TimestampInfo? // Note: This is used for global search public let focusBehaviour: FocusBehaviour private let initialUnreadInteractionId: Int64? + private let markAsReadTrigger: PassthroughSubject<(SessionThreadViewModel.ReadTarget, Int64?), Never> = PassthroughSubject() + private var markAsReadPublisher: AnyPublisher? public lazy var blockedBannerMessage: String = { switch self.threadData.threadVariant { @@ -640,29 +643,45 @@ public class ConversationViewModel: OWSAudioPlayerDelegate { timestampMs: Int64? ) { /// Since this method now gets triggered when scrolling we want to try to optimise it and avoid busying the database - /// write queue when it isn't needed, in order to do this we don't bother marking anything as read if this was called with - /// the same `interactionId` that we previously marked as read (ie. when scrolling and the last message hasn't changed) + /// write queue when it isn't needed, in order to do this we: + /// - Throttle the updates to 100ms (quick enough that users shouldn't notice, but will help the DB when the user flings the list) + /// - Don't bother marking anything as read if this was called with the same `interactionId` that we previously marked as + /// read (ie. when scrolling and the last message hasn't changed) /// /// The `ThreadViewModel.markAsRead` method also tries to avoid marking as read if a conversation is already fully read - switch target { - case .thread: self.threadData.markAsRead(target: target) - case .threadAndInteractions: - guard - timestampMs == nil || - self.lastInteractionTimestampMsMarkedAsRead < (timestampMs ?? 0) - else { - self.threadData.markAsRead(target: .thread) - return - } - - // If we were given a timestamp then update the 'lastInteractionTimestampMsMarkedAsRead' - // to avoid needless updates - if let timestampMs: Int64 = timestampMs { - self.lastInteractionTimestampMsMarkedAsRead = timestampMs - } - - self.threadData.markAsRead(target: target) + if markAsReadPublisher == nil { + markAsReadPublisher = markAsReadTrigger + .throttle(for: .milliseconds(100), scheduler: DispatchQueue.global(qos: .userInitiated), latest: true) + .handleEvents( + receiveOutput: { [weak self] target, timestampMs in + switch target { + case .thread: self?.threadData.markAsRead(target: target) + case .threadAndInteractions: + guard + timestampMs == nil || + (self?.lastInteractionTimestampMsMarkedAsRead ?? 0) < (timestampMs ?? 0) + else { + self?.threadData.markAsRead(target: .thread) + return + } + + // If we were given a timestamp then update the 'lastInteractionTimestampMsMarkedAsRead' + // to avoid needless updates + if let timestampMs: Int64 = timestampMs { + self?.lastInteractionTimestampMsMarkedAsRead = timestampMs + } + + self?.threadData.markAsRead(target: target) + } + } + ) + .map { _ in () } + .eraseToAnyPublisher() + + markAsReadPublisher?.sinkUntilComplete() } + + markAsReadTrigger.send((target, timestampMs)) } public func swapToThread(updatedThreadId: String) { diff --git a/Session/Meta/AppDelegate.swift b/Session/Meta/AppDelegate.swift index 5495583c3..1f193601c 100644 --- a/Session/Meta/AppDelegate.swift +++ b/Session/Meta/AppDelegate.swift @@ -352,6 +352,10 @@ class AppDelegate: UIResponder, UIApplicationDelegate, UNUserNotificationCenterD /// App won't be ready for extensions and no need to enqueue a config sync unless we successfully completed startup Storage.shared.writeAsync { db in + // Increment the launch count (guaranteed to change which results in the write actually + // doing something and outputting and error if the DB is suspended) + db[.activeCounter] = ((db[.activeCounter] ?? 0) + 1) + // Disable the SAE until the main app has successfully completed launch process // at least once in the post-SAE world. db[.isReadyForAppExtensions] = true diff --git a/SessionMessagingKit/Sending & Receiving/Pollers/Poller.swift b/SessionMessagingKit/Sending & Receiving/Pollers/Poller.swift index 277196448..480f40a07 100644 --- a/SessionMessagingKit/Sending & Receiving/Pollers/Poller.swift +++ b/SessionMessagingKit/Sending & Receiving/Pollers/Poller.swift @@ -262,6 +262,7 @@ public class Poller { var hadValidHashUpdate: Bool = false var configMessageJobsToRun: [Job] = [] var standardMessageJobsToRun: [Job] = [] + var pollerLogOutput: String = "\(pollerName) failed to process any messages" Storage.shared.write { db in let allProcessedMessages: [ProcessedMessage] = allMessages @@ -369,11 +370,12 @@ public class Poller { } } + // Set the output for logging + pollerLogOutput = "Received \(messageCount) new message\(messageCount == 1 ? "" : "s") in \(pollerName) (duplicates: \(allMessages.count - messageCount))" + // Clean up message hashes and add some logs about the poll results if allMessages.isEmpty && !hadValidHashUpdate { - if !calledFromBackgroundPoller { - SNLog("Received \(allMessages.count) new message\(allMessages.count == 1 ? "" : "s"), all duplicates - marking the hash we polled with as invalid") - } + pollerLogOutput = "Received \(allMessages.count) new message\(allMessages.count == 1 ? "" : "s") in \(pollerName), all duplicates - marking the hash we polled with as invalid" // Update the cached validity of the messages try SnodeReceivedMessageInfo.handlePotentialDeletedOrInvalidHash( @@ -382,9 +384,11 @@ public class Poller { otherKnownValidHashes: otherKnownHashes ) } - else if !calledFromBackgroundPoller { - SNLog("Received \(messageCount) new message\(messageCount == 1 ? "" : "s") in \(pollerName) (duplicates: \(allMessages.count - messageCount))") - } + } + + // Only output logs if it isn't the background poller + if !calledFromBackgroundPoller { + SNLog(pollerLogOutput) } // If we aren't runing in a background poller then just finish immediately diff --git a/SessionMessagingKit/Utilities/Preferences.swift b/SessionMessagingKit/Utilities/Preferences.swift index 0b3c91209..34a00860e 100644 --- a/SessionMessagingKit/Utilities/Preferences.swift +++ b/SessionMessagingKit/Utilities/Preferences.swift @@ -89,6 +89,12 @@ public extension Setting.DoubleKey { static let screenLockTimeoutSeconds: Setting.DoubleKey = "screenLockTimeoutSeconds" } +public extension Setting.IntKey { + /// This is the number of times the app has successfully become active, it's not actually used for anything but allows us to make + /// a database change on launch so the database will output an error if it fails to write + static let activeCounter: Setting.IntKey = "activeCounter" +} + public enum Preferences { public enum NotificationPreviewType: Int, CaseIterable, EnumIntSetting, Differentiable { public static var defaultPreviewType: NotificationPreviewType = .nameAndPreview diff --git a/SessionSnodeKit/Networking/SnodeAPI.swift b/SessionSnodeKit/Networking/SnodeAPI.swift index 690fa4c89..9ed038796 100644 --- a/SessionSnodeKit/Networking/SnodeAPI.swift +++ b/SessionSnodeKit/Networking/SnodeAPI.swift @@ -1301,7 +1301,6 @@ public final class SnodeAPI { // MARK: - Error Handling - /// - Note: Should only be invoked from `Threading.workQueue` to avoid race conditions. @discardableResult internal static func handleError( withStatusCode statusCode: UInt, diff --git a/SessionUtilitiesKit/Database/Storage.swift b/SessionUtilitiesKit/Database/Storage.swift index 426694ee7..3ad3d81ab 100644 --- a/SessionUtilitiesKit/Database/Storage.swift +++ b/SessionUtilitiesKit/Database/Storage.swift @@ -7,10 +7,12 @@ import GRDB import SignalCoreKit open class Storage { + public static let queuePrefix: String = "SessionDatabase" private static let dbFileName: String = "Session.sqlite" private static let keychainService: String = "TSKeyChainService" private static let dbCipherKeySpecKey: String = "GRDBDatabaseCipherKeySpec" private static let kSQLCipherKeySpecLength: Int = 48 + private static let writeWarningThreadshold: TimeInterval = 3 private static var sharedDatabaseDirectoryPath: String { "\(OWSFileSystem.appSharedDataDirectoryPath())/database" } private static var databasePath: String { "\(Storage.sharedDatabaseDirectoryPath)/\(Storage.dbFileName)" } @@ -78,6 +80,7 @@ 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.prepareDatabase { db in @@ -365,7 +368,29 @@ open class Storage { try SSKDefaultKeychainStorage.shared.remove(service: keychainService, key: dbCipherKeySpecKey) } - // MARK: - Functions + // MARK: - Logging Functions + + typealias CallInfo = (file: String, function: String, line: Int) + + private static func logSlowWrites( + info: CallInfo, + updates: @escaping (Database) throws -> T + ) -> (Database) throws -> T { + return { db in + let timeout: Timer = Timer.scheduledTimerOnMainThread(withTimeInterval: writeWarningThreadshold) { + $0.invalidate() + + // Don't want to log on the main thread as to avoid confusion when debugging issues + DispatchQueue.global(qos: .default).async { + let fileName: String = (info.file.components(separatedBy: "/").last.map { " \($0):\(info.line)" } ?? "") + SNLog("[Storage\(fileName)] Slow write taking longer than \(writeWarningThreadshold)s - \(info.function)") + } + } + defer { timeout.invalidate() } + + return try updates(db) + } + } private static func logIfNeeded(_ error: Error, isWrite: Bool) { switch error { @@ -382,22 +407,50 @@ open class Storage { return nil } - @discardableResult public final func write(updates: (Database) throws -> T?) -> T? { + // MARK: - Functions + + @discardableResult public final func write( + fileName: String = #file, + functionName: String = #function, + lineNumber: Int = #line, + updates: @escaping (Database) throws -> T? + ) -> T? { guard isValid, let dbWriter: DatabaseWriter = dbWriter else { return nil } - do { return try dbWriter.write(updates) } + let info: CallInfo = (fileName, functionName, lineNumber) + + do { return try dbWriter.write(Storage.logSlowWrites(info: info, updates: updates)) } catch { return Storage.logIfNeeded(error, isWrite: true) } } - open func writeAsync(updates: @escaping (Database) throws -> T) { - writeAsync(updates: updates, completion: { _, _ in }) + open func writeAsync( + fileName: String = #file, + functionName: String = #function, + lineNumber: Int = #line, + updates: @escaping (Database) throws -> T + ) { + writeAsync( + fileName: fileName, + functionName: functionName, + lineNumber: lineNumber, + updates: updates, + completion: { _, _ in } + ) } - open func writeAsync(updates: @escaping (Database) throws -> T, completion: @escaping (Database, Swift.Result) throws -> Void) { + open func writeAsync( + fileName: String = #file, + functionName: String = #function, + lineNumber: Int = #line, + updates: @escaping (Database) throws -> T, + completion: @escaping (Database, Swift.Result) throws -> Void + ) { guard isValid, let dbWriter: DatabaseWriter = dbWriter else { return } + let info: CallInfo = (fileName, functionName, lineNumber) + dbWriter.asyncWrite( - updates, + Storage.logSlowWrites(info: info, updates: updates), completion: { db, result in switch result { case .failure(let error): Storage.logIfNeeded(error, isWrite: true) @@ -410,6 +463,9 @@ open class Storage { } open func writePublisher( + fileName: String = #file, + functionName: String = #function, + lineNumber: Int = #line, updates: @escaping (Database) throws -> T ) -> AnyPublisher { guard isValid, let dbWriter: DatabaseWriter = dbWriter else { @@ -417,6 +473,8 @@ open class Storage { .eraseToAnyPublisher() } + let info: CallInfo = (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 @@ -426,7 +484,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(updates))) } + do { resolver(Result.success(try dbWriter.write(Storage.logSlowWrites(info: info, updates: updates)))) } catch { Storage.logIfNeeded(error, isWrite: true) resolver(Result.failure(error)) diff --git a/SessionUtilitiesKit/General/Logging.swift b/SessionUtilitiesKit/General/Logging.swift index b3f64899e..e759e83fd 100644 --- a/SessionUtilitiesKit/General/Logging.swift +++ b/SessionUtilitiesKit/General/Logging.swift @@ -3,13 +3,36 @@ import Foundation import SignalCoreKit +private extension DispatchQueue { + static var isDBWriteQueue: Bool { + /// The `dispatch_queue_get_label` function is used to get the label for a given DispatchQueue, in Swift this + /// was replaced with the `label` property on a queue instance but you used to be able to just pass `nil` in order + /// to get the name of the current queue - it seems that there might be a hole in the current design where there isn't + /// a built-in way to get the label of the current queue natively in Swift + /// + /// On a positive note it seems that we can safely call `__dispatch_queue_get_label(nil)` in order to do this, + /// it won't appear in auto-completed code but works properly + /// + /// For more information see + /// https://developer.apple.com/forums/thread/701313?answerId=705773022#705773022 + /// https://forums.swift.org/t/gcd-getting-current-dispatch-queue-name-with-swift-3/3039/2 + return (String(cString: __dispatch_queue_get_label(nil)) == "\(Storage.queuePrefix).writer") + } +} + public func SNLog(_ message: String) { - let threadString: String = (Thread.isMainThread ? " Main" : "") + let logPrefixes: String = [ + "Session", + (Thread.isMainThread ? "Main" : nil), + (DispatchQueue.isDBWriteQueue ? "DBWrite" : nil) + ] + .compactMap { $0 } + .joined(separator: ", ") #if DEBUG - print("[Session\(threadString)] \(message)") + print("[\(logPrefixes)] \(message)") #endif - OWSLogger.info("[Session\(threadString)] \(message)") + OWSLogger.info("[\(logPrefixes)] \(message)") } public func SNLogNotTests(_ message: String) { diff --git a/SessionUtilitiesKit/General/Timer+MainThread.swift b/SessionUtilitiesKit/General/Timer+MainThread.swift index b8a5ce314..7cea385a2 100644 --- a/SessionUtilitiesKit/General/Timer+MainThread.swift +++ b/SessionUtilitiesKit/General/Timer+MainThread.swift @@ -5,7 +5,11 @@ import Foundation extension Timer { @discardableResult - public static func scheduledTimerOnMainThread(withTimeInterval timeInterval: TimeInterval, repeats: Bool, block: @escaping (Timer) -> Void) -> Timer { + public static func scheduledTimerOnMainThread( + withTimeInterval timeInterval: TimeInterval, + repeats: Bool = false, + block: @escaping (Timer) -> Void + ) -> Timer { let timer = Timer(timeInterval: timeInterval, repeats: repeats, block: block) RunLoop.main.add(timer, forMode: .common) return timer diff --git a/SessionUtilitiesKit/JobRunner/JobRunner.swift b/SessionUtilitiesKit/JobRunner/JobRunner.swift index 4a70aa368..e6ba82f32 100644 --- a/SessionUtilitiesKit/JobRunner/JobRunner.swift +++ b/SessionUtilitiesKit/JobRunner/JobRunner.swift @@ -1211,21 +1211,16 @@ public final class JobQueue { // Get the max failure count for the job (a value of '-1' means it will retry indefinitely) let maxFailureCount: Int = (JobRunner.executorMap.wrappedValue[job.variant]?.maxFailureCount ?? 0) let nextRunTimestamp: TimeInterval = (Date().timeIntervalSince1970 + JobRunner.getRetryInterval(for: job)) + var dependantJobIds: [Int64] = [] + var failureText: String = "failed" Storage.shared.write { db in - /// Remove any dependant jobs from the queue (shouldn't be in there but filter the queue just in case so we don't try - /// to run a deleted job or get stuck in a loop of trying to run dependencies indefinitely) - let dependantJobIds: [Int64] = try job.dependantJobs + /// Retrieve a list of dependant jobs so we can clear them from the queue + dependantJobIds = try job.dependantJobs .select(.id) .asRequest(of: Int64.self) .fetchAll(db) - - if !dependantJobIds.isEmpty { - queue.mutate { queue in - queue = queue.filter { !dependantJobIds.contains($0.id ?? -1) } - } - } - + /// Delete/update the failed jobs and any dependencies let updatedFailureCount: UInt = (job.failureCount + 1) @@ -1235,7 +1230,10 @@ public final class JobQueue { updatedFailureCount <= maxFailureCount ) else { - SNLog("[JobRunner] \(queueContext) \(job.variant) failed permanently\(maxFailureCount >= 0 && updatedFailureCount > maxFailureCount ? "; too many retries" : "")") + failureText = (maxFailureCount >= 0 && updatedFailureCount > maxFailureCount ? + "failed permanently; too many retries" : + "failed permanently" + ) // If the job permanently failed or we have performed all of our retry attempts // then delete the job and all of it's dependant jobs (it'll probably never succeed) @@ -1243,12 +1241,10 @@ public final class JobQueue { .deleteAll(db) _ = try job.delete(db) - - performCleanUp(for: job, result: .failed) return } - SNLog("[JobRunner] \(queueContext) \(job.variant) job failed; scheduling retry (failure count is \(job.failureCount + 1))") + failureText = "failed; scheduling retry (failure count is \(updatedFailureCount))" _ = try job .with( @@ -1268,6 +1264,15 @@ public final class JobQueue { ) } + /// Remove any dependant jobs from the queue (shouldn't be in there but filter the queue just in case so we don't try + /// to run a deleted job or get stuck in a loop of trying to run dependencies indefinitely) + if !dependantJobIds.isEmpty { + queue.mutate { queue in + queue = queue.filter { !dependantJobIds.contains($0.id ?? -1) } + } + } + + SNLog("[JobRunner] \(queueContext) \(job.variant) job \(failureText)") performCleanUp(for: job, result: .failed) internalQueue.async { [weak self] in self?.runNextJob()