From 44824c8127a61328ef1865fc1285767be4bdea6a Mon Sep 17 00:00:00 2001 From: Morgan Pretty Date: Tue, 23 May 2023 14:02:12 +1000 Subject: [PATCH] Added a bunch of logs to the Jobs to better track the startup state --- Session/Notifications/SyncPushTokensJob.swift | 7 ++++++- .../Jobs/Types/AttachmentUploadJob.swift | 4 ++++ .../Jobs/Types/ConfigurationSyncJob.swift | 7 +++++-- .../Jobs/Types/DisappearingMessagesJob.swift | 12 +++++++++--- .../Jobs/Types/FailedAttachmentDownloadsJob.swift | 7 ++++--- .../Jobs/Types/FailedMessageSendsJob.swift | 10 ++++++---- SessionMessagingKit/Jobs/Types/GroupLeavingJob.swift | 4 +++- SessionMessagingKit/Jobs/Types/MessageSendJob.swift | 11 ++++++++--- .../Jobs/Types/NotifyPushServerJob.swift | 1 + .../Types/RetrieveDefaultOpenGroupRoomsJob.swift | 9 +++++++-- .../Jobs/Types/UpdateProfilePictureJob.swift | 6 +++++- SessionSnodeKit/Jobs/GetSnodePoolJob.swift | 10 ++++++++-- 12 files changed, 66 insertions(+), 22 deletions(-) diff --git a/Session/Notifications/SyncPushTokensJob.swift b/Session/Notifications/SyncPushTokensJob.swift index 4ac93c7a8..c11ec93d3 100644 --- a/Session/Notifications/SyncPushTokensJob.swift +++ b/Session/Notifications/SyncPushTokensJob.swift @@ -26,6 +26,7 @@ public enum SyncPushTokensJob: JobExecutor { (UserDefaults.sharedLokiProject?[.isMainAppActive]).defaulting(to: false), Identity.userCompletedRequiredOnboarding() else { + SNLog("[SyncPushTokensJob] Deferred due to incomplete registration") deferred(job) // Don't need to do anything if it's not the main app return } @@ -62,6 +63,7 @@ public enum SyncPushTokensJob: JobExecutor { !UIApplication.shared.isRegisteredForRemoteNotifications || Date().timeIntervalSince(lastPushNotificationSync) >= SyncPushTokensJob.maxFrequency else { + SNLog("[SyncPushTokensJob] Deferred due to Fast Mode disabled or recent-enough registration") deferred(job) // Don't need to do anything if push notifications are already registered return } @@ -86,9 +88,12 @@ public enum SyncPushTokensJob: JobExecutor { .handleEvents( receiveCompletion: { result in switch result { - case .failure: break + case .failure(let error): + SNLog("[SyncPushTokensJob] Failed to register due to error: \(error)") + case .finished: Logger.warn("Recording push tokens locally. pushToken: \(redact(pushToken)), voipToken: \(redact(voipToken))") + SNLog("[SyncPushTokensJob] Completed") Storage.shared.write { db in db[.lastRecordedPushToken] = pushToken diff --git a/SessionMessagingKit/Jobs/Types/AttachmentUploadJob.swift b/SessionMessagingKit/Jobs/Types/AttachmentUploadJob.swift index 47981542d..9d0f14ee4 100644 --- a/SessionMessagingKit/Jobs/Types/AttachmentUploadJob.swift +++ b/SessionMessagingKit/Jobs/Types/AttachmentUploadJob.swift @@ -31,6 +31,7 @@ public enum AttachmentUploadJob: JobExecutor { return (attachment, try OpenGroup.fetchOne(db, id: threadId)) }) else { + SNLog("[AttachmentUploadJob] Failed due to missing details") failure(job, JobRunnerError.missingRequiredDetails, true) return } @@ -38,12 +39,14 @@ public enum AttachmentUploadJob: JobExecutor { // If the original interaction no longer exists then don't bother uploading the attachment (ie. the // message was deleted before it even got sent) guard Storage.shared.read({ db in try Interaction.exists(db, id: interactionId) }) == true else { + SNLog("[AttachmentUploadJob] Failed due to missing interaction") failure(job, StorageError.objectNotFound, true) return } // If the attachment is still pending download the hold off on running this job guard attachment.state != .pendingDownload && attachment.state != .downloading else { + SNLog("[AttachmentUploadJob] Deferred as attachment is still being downloaded") deferred(job) return } @@ -98,6 +101,7 @@ public enum AttachmentUploadJob: JobExecutor { ) } + SNLog("[AttachmentUploadJob] Failed due to error: \(error)") failure(job, error, false) case .finished: success(job, false) diff --git a/SessionMessagingKit/Jobs/Types/ConfigurationSyncJob.swift b/SessionMessagingKit/Jobs/Types/ConfigurationSyncJob.swift index 7be4b4a3a..7dbde8b4a 100644 --- a/SessionMessagingKit/Jobs/Types/ConfigurationSyncJob.swift +++ b/SessionMessagingKit/Jobs/Types/ConfigurationSyncJob.swift @@ -49,6 +49,7 @@ public enum ConfigurationSyncJob: JobExecutor { // If there are no pending changes then the job can just complete (next time something // is updated we want to try and run immediately so don't scuedule another run in this case) guard !pendingConfigChanges.isEmpty else { + SNLog("[ConfigurationSyncJob] Completed with no pending changes") success(job, true) return } @@ -118,8 +119,10 @@ public enum ConfigurationSyncJob: JobExecutor { .sinkUntilComplete( receiveCompletion: { result in switch result { - case .finished: break - case .failure(let error): failure(job, error, false) + case .finished: SNLog("[ConfigurationSyncJob] Completed") + case .failure(let error): + SNLog("[ConfigurationSyncJob] Failed due to error: \(error)") + failure(job, error, false) } }, receiveValue: { (configDumps: [ConfigDump]) in diff --git a/SessionMessagingKit/Jobs/Types/DisappearingMessagesJob.swift b/SessionMessagingKit/Jobs/Types/DisappearingMessagesJob.swift index d294c27b3..777c7fad8 100644 --- a/SessionMessagingKit/Jobs/Types/DisappearingMessagesJob.swift +++ b/SessionMessagingKit/Jobs/Types/DisappearingMessagesJob.swift @@ -20,9 +20,10 @@ public enum DisappearingMessagesJob: JobExecutor { // The 'backgroundTask' gets captured and cleared within the 'completion' block let timestampNowMs: TimeInterval = TimeInterval(SnodeAPI.currentOffsetTimestampMs()) var backgroundTask: OWSBackgroundTask? = OWSBackgroundTask(label: #function) + var numDeleted: Int = -1 let updatedJob: Job? = Storage.shared.write { db in - _ = try Interaction + numDeleted = try Interaction .filter(Interaction.Columns.expiresStartedAtMs != nil) .filter((Interaction.Columns.expiresStartedAtMs + (Interaction.Columns.expiresInSeconds * 1000)) <= timestampNowMs) .deleteAll(db) @@ -35,6 +36,7 @@ public enum DisappearingMessagesJob: JobExecutor { .saved(db) } + SNLog("[DisappearingMessagesJob] Deleted \(numDeleted) expired messages") success(updatedJob ?? job, false) // The 'if' is only there to prevent the "variable never read" warning from showing @@ -58,12 +60,16 @@ public extension DisappearingMessagesJob { .asRequest(of: Double.self) .fetchOne(db) - guard let nextExpirationTimestampMs: Double = nextExpirationTimestampMs else { return nil } + guard let nextExpirationTimestampMs: Double = nextExpirationTimestampMs else { + SNLog("[DisappearingMessagesJob] No remaining expiring messages") + return nil + } /// The `expiresStartedAtMs` timestamp is now based on the `SnodeAPI.currentOffsetTimestampMs()` value /// so we need to make sure offset the `nextRunTimestamp` accordingly to ensure it runs at the correct local time let clockOffsetMs: Int64 = SnodeAPI.clockOffsetMs.wrappedValue + SNLog("[DisappearingMessagesJob] Scheduled future message expiration") return try? Job .filter(Job.Columns.variant == Job.Variant.disappearingMessages) .fetchOne(db)? @@ -103,7 +109,7 @@ public extension DisappearingMessagesJob { return updateNextRunIfNeeded(db, interactionIds: [interactionId], startedAtMs: startedAtMs) } catch { - SNLog("Failed to update the expiring messages timer on an interaction") + SNLog("[DisappearingMessagesJob] Failed to update the expiring messages timer on an interaction") return nil } } diff --git a/SessionMessagingKit/Jobs/Types/FailedAttachmentDownloadsJob.swift b/SessionMessagingKit/Jobs/Types/FailedAttachmentDownloadsJob.swift index a2d921eee..747664c9b 100644 --- a/SessionMessagingKit/Jobs/Types/FailedAttachmentDownloadsJob.swift +++ b/SessionMessagingKit/Jobs/Types/FailedAttachmentDownloadsJob.swift @@ -17,15 +17,16 @@ public enum FailedAttachmentDownloadsJob: JobExecutor { failure: @escaping (Job, Error?, Bool) -> (), deferred: @escaping (Job) -> () ) { + var changeCount: Int = -1 + // Update all 'sending' message states to 'failed' Storage.shared.write { db in - let changeCount: Int = try Attachment + changeCount = try Attachment .filter(Attachment.Columns.state == Attachment.State.downloading) .updateAll(db, Attachment.Columns.state.set(to: Attachment.State.failedDownload)) - - Logger.debug("Marked \(changeCount) attachments as failed") } + SNLog("[FailedAttachmentDownloadsJob] Marked \(changeCount) attachments as failed") success(job, false) } } diff --git a/SessionMessagingKit/Jobs/Types/FailedMessageSendsJob.swift b/SessionMessagingKit/Jobs/Types/FailedMessageSendsJob.swift index 48298d73c..31d382cc7 100644 --- a/SessionMessagingKit/Jobs/Types/FailedMessageSendsJob.swift +++ b/SessionMessagingKit/Jobs/Types/FailedMessageSendsJob.swift @@ -16,6 +16,9 @@ public enum FailedMessageSendsJob: JobExecutor { failure: @escaping (Job, Error?, Bool) -> (), deferred: @escaping (Job) -> () ) { + var changeCount: Int = -1 + var attachmentChangeCount: Int = -1 + // Update all 'sending' message states to 'failed' Storage.shared.write { db in let sendChangeCount: Int = try RecipientState @@ -24,14 +27,13 @@ public enum FailedMessageSendsJob: JobExecutor { let syncChangeCount: Int = try RecipientState .filter(RecipientState.Columns.state == RecipientState.State.syncing) .updateAll(db, RecipientState.Columns.state.set(to: RecipientState.State.failedToSync)) - let attachmentChangeCount: Int = try Attachment + attachmentChangeCount = try Attachment .filter(Attachment.Columns.state == Attachment.State.uploading) .updateAll(db, Attachment.Columns.state.set(to: Attachment.State.failedUpload)) - let changeCount: Int = (sendChangeCount + syncChangeCount) - - SNLog("Marked \(changeCount) message\(changeCount == 1 ? "" : "s") as failed (\(attachmentChangeCount) upload\(attachmentChangeCount == 1 ? "" : "s") cancelled)") + changeCount = (sendChangeCount + syncChangeCount) } + SNLog("[FailedMessageSendsJob] Marked \(changeCount) message\(changeCount == 1 ? "" : "s") as failed (\(attachmentChangeCount) upload\(attachmentChangeCount == 1 ? "" : "s") cancelled)") success(job, false) } } diff --git a/SessionMessagingKit/Jobs/Types/GroupLeavingJob.swift b/SessionMessagingKit/Jobs/Types/GroupLeavingJob.swift index af9918392..a66935fac 100644 --- a/SessionMessagingKit/Jobs/Types/GroupLeavingJob.swift +++ b/SessionMessagingKit/Jobs/Types/GroupLeavingJob.swift @@ -25,6 +25,7 @@ public enum GroupLeavingJob: JobExecutor { let threadId: String = job.threadId, let interactionId: Int64 = job.interactionId else { + SNLog("[GroupLeavingJob] Failed due to missing details") failure(job, JobRunnerError.missingRequiredDetails, true) return } @@ -34,10 +35,11 @@ public enum GroupLeavingJob: JobExecutor { Storage.shared .writePublisher { db in guard (try? SessionThread.exists(db, id: threadId)) == true else { - SNLog("Can't update nonexistent closed group.") + SNLog("[GroupLeavingJob] Failed due to non-existent group conversation") throw MessageSenderError.noThread } guard (try? ClosedGroup.exists(db, id: threadId)) == true else { + SNLog("[GroupLeavingJob] Failed due to non-existent group") throw MessageSenderError.invalidClosedGroupUpdate } diff --git a/SessionMessagingKit/Jobs/Types/MessageSendJob.swift b/SessionMessagingKit/Jobs/Types/MessageSendJob.swift index 50a462f9a..8e97addcd 100644 --- a/SessionMessagingKit/Jobs/Types/MessageSendJob.swift +++ b/SessionMessagingKit/Jobs/Types/MessageSendJob.swift @@ -23,6 +23,7 @@ public enum MessageSendJob: JobExecutor { let detailsData: Data = job.details, let details: Details = try? JSONDecoder().decode(Details.self, from: detailsData) else { + SNLog("[MessageSendJob] Failing due to missing details") failure(job, JobRunnerError.missingRequiredDetails, true) return } @@ -45,6 +46,7 @@ public enum MessageSendJob: JobExecutor { let jobId: Int64 = job.id, let interactionId: Int64 = job.interactionId else { + SNLog("[MessageSendJob] Failing due to missing details") failure(job, JobRunnerError.missingRequiredDetails, true) return } @@ -52,6 +54,7 @@ public enum MessageSendJob: JobExecutor { // If the original interaction no longer exists then don't bother sending the message (ie. the // message was deleted before it even got sent) guard Storage.shared.read({ db in try Interaction.exists(db, id: interactionId) }) == true else { + SNLog("[MessageSendJob] Failing due to missing interaction") failure(job, StorageError.objectNotFound, true) return } @@ -150,12 +153,14 @@ public enum MessageSendJob: JobExecutor { // Note: If we have gotten to this point then any dependant attachment upload // jobs will have permanently failed so this message send should also do so guard attachmentState?.shouldFail == false else { + SNLog("[MessageSendJob] Failing due to failed attachment upload") failure(job, AttachmentError.notUploaded, true) return } // Defer the job if we found incomplete uploads guard attachmentState?.shouldDefer == false else { + SNLog("[MessageSendJob] Deferring pending attachment uploads") deferred(job) return } @@ -190,7 +195,7 @@ public enum MessageSendJob: JobExecutor { switch result { case .finished: success(job, false) case .failure(let error): - SNLog("Couldn't send message due to error: \(error).") + SNLog("[MessageSendJob] Couldn't send message due to error: \(error).") switch error { case let senderError as MessageSenderError where !senderError.isRetryable: @@ -200,11 +205,11 @@ public enum MessageSendJob: JobExecutor { failure(job, error, true) case SnodeAPIError.clockOutOfSync: - SNLog("\(originalSentTimestamp != nil ? "Permanently Failing" : "Failing") to send \(type(of: details.message)) due to clock out of sync issue.") + SNLog("[MessageSendJob] \(originalSentTimestamp != nil ? "Permanently Failing" : "Failing") to send \(type(of: details.message)) due to clock out of sync issue.") failure(job, error, (originalSentTimestamp != nil)) default: - SNLog("Failed to send \(type(of: details.message)).") + SNLog("[MessageSendJob] Failed to send \(type(of: details.message)).") if details.message is VisibleMessage { guard diff --git a/SessionMessagingKit/Jobs/Types/NotifyPushServerJob.swift b/SessionMessagingKit/Jobs/Types/NotifyPushServerJob.swift index 121aa0d47..fa2e1fdb4 100644 --- a/SessionMessagingKit/Jobs/Types/NotifyPushServerJob.swift +++ b/SessionMessagingKit/Jobs/Types/NotifyPushServerJob.swift @@ -21,6 +21,7 @@ public enum NotifyPushServerJob: JobExecutor { let detailsData: Data = job.details, let details: Details = try? JSONDecoder().decode(Details.self, from: detailsData) else { + SNLog("[NotifyPushServerJob] Failing due to missing details") failure(job, JobRunnerError.missingRequiredDetails, true) return } diff --git a/SessionMessagingKit/Jobs/Types/RetrieveDefaultOpenGroupRoomsJob.swift b/SessionMessagingKit/Jobs/Types/RetrieveDefaultOpenGroupRoomsJob.swift index ba029b0cb..f1629925a 100644 --- a/SessionMessagingKit/Jobs/Types/RetrieveDefaultOpenGroupRoomsJob.swift +++ b/SessionMessagingKit/Jobs/Types/RetrieveDefaultOpenGroupRoomsJob.swift @@ -47,8 +47,13 @@ public enum RetrieveDefaultOpenGroupRoomsJob: JobExecutor { .sinkUntilComplete( receiveCompletion: { result in switch result { - case .finished: success(job, false) - case .failure(let error): failure(job, error, false) + case .finished: + SNLog("[RetrieveDefaultOpenGroupRoomsJob] Successfully retrieved default Community rooms") + success(job, false) + + case .failure(let error): + SNLog("[RetrieveDefaultOpenGroupRoomsJob] Failed to get default Community rooms") + failure(job, error, false) } } ) diff --git a/SessionMessagingKit/Jobs/Types/UpdateProfilePictureJob.swift b/SessionMessagingKit/Jobs/Types/UpdateProfilePictureJob.swift index 43bab45c1..be6dcb321 100644 --- a/SessionMessagingKit/Jobs/Types/UpdateProfilePictureJob.swift +++ b/SessionMessagingKit/Jobs/Types/UpdateProfilePictureJob.swift @@ -55,10 +55,14 @@ public enum UpdateProfilePictureJob: JobExecutor { // issue as it will write to the database and this closure is already called within // another database write queue.async { + SNLog("[UpdateProfilePictureJob] Profile successfully updated") success(job, false) } }, - failure: { error in failure(job, error, false) } + failure: { error in + SNLog("[UpdateProfilePictureJob] Failed to update profile") + failure(job, error, false) + } ) } } diff --git a/SessionSnodeKit/Jobs/GetSnodePoolJob.swift b/SessionSnodeKit/Jobs/GetSnodePoolJob.swift index 365ef1773..2d0c5e827 100644 --- a/SessionSnodeKit/Jobs/GetSnodePoolJob.swift +++ b/SessionSnodeKit/Jobs/GetSnodePoolJob.swift @@ -23,6 +23,7 @@ public enum GetSnodePoolJob: JobExecutor { // to block if we have no Snode pool and prevent other jobs from failing but avoids having to // wait if we already have a potentially valid snode pool guard !SnodeAPI.hasCachedSnodesInclusingExpired() else { + SNLog("[GetSnodePoolJob] Has valid cached pool, running async instead") SnodeAPI .getSnodePool() .subscribe(on: DispatchQueue.global(qos: .default)) @@ -40,8 +41,13 @@ public enum GetSnodePoolJob: JobExecutor { .sinkUntilComplete( receiveCompletion: { result in switch result { - case .finished: success(job, false) - case .failure(let error): failure(job, error, false) + case .finished: + SNLog("[GetSnodePoolJob] Completed") + success(job, false) + + case .failure(let error): + SNLog("[GetSnodePoolJob] Failed due to error: \(error)") + failure(job, error, false) } } )