From a96057009e96c9898398f275e2f4d2e28263ebc7 Mon Sep 17 00:00:00 2001 From: Stefan Ceriu Date: Fri, 22 Dec 2023 14:35:09 +0200 Subject: [PATCH] Introduce more logging around message sending to help debug missing sent messages (#2285) --- .../Services/Timeline/TimelineProxy.swift | 131 ++++++++++++++++-- 1 file changed, 119 insertions(+), 12 deletions(-) diff --git a/ElementX/Sources/Services/Timeline/TimelineProxy.swift b/ElementX/Sources/Services/Timeline/TimelineProxy.swift index ad5a3469e..8d42760cc 100644 --- a/ElementX/Sources/Services/Timeline/TimelineProxy.swift +++ b/ElementX/Sources/Services/Timeline/TimelineProxy.swift @@ -82,6 +82,8 @@ final class TimelineProxy: TimelineProxyProtocol { } func cancelSend(transactionID: String) async { + MXLog.info("Cancelling sending for transaction ID: \(transactionID)") + sendMessageBackgroundTask = await backgroundTaskService.startBackgroundTask(withName: backgroundTaskName, isReusable: true) defer { sendMessageBackgroundTask?.stop() @@ -89,6 +91,7 @@ final class TimelineProxy: TimelineProxyProtocol { return await Task.dispatch(on: messageSendingDispatchQueue) { self.timeline.cancelSend(txnId: transactionID) + MXLog.info("Finished cancelling sending for transaction ID: \(transactionID)") } } @@ -96,6 +99,8 @@ final class TimelineProxy: TimelineProxyProtocol { html: String, original eventID: String, intentionalMentions: IntentionalMentions) async -> Result { + MXLog.info("Editing message with original event ID: \(eventID)") + sendMessageBackgroundTask = await backgroundTaskService.startBackgroundTask(withName: backgroundTaskName, isReusable: true) defer { sendMessageBackgroundTask?.stop() @@ -110,8 +115,11 @@ final class TimelineProxy: TimelineProxyProtocol { let originalEvent = try self.timeline.getEventTimelineItemByEventId(eventId: eventID) try self.timeline.edit(newContent: messageContent, editItem: originalEvent) + MXLog.info("Finished editing message with original event ID: \(eventID)") + return .success(()) } catch { + MXLog.error("Failed editing message with original event ID: \(eventID) with error: \(error)") return .failure(.failedEditingMessage) } } @@ -123,48 +131,73 @@ final class TimelineProxy: TimelineProxyProtocol { do { MXLog.info("Fetching event details for \(eventID)") try self.timeline.fetchDetailsForEvent(eventId: eventID) + MXLog.info("Finished fetching event details for eventID: \(eventID)") } catch { - MXLog.error("Failed fetching event details for \(eventID) with error: \(error)") + MXLog.error("Failed fetching event details for eventID: \(eventID) with error: \(error)") } } } } func messageEventContent(for eventID: String) -> RoomMessageEventContentWithoutRelation? { - try? timeline.getTimelineEventContentByEventId(eventId: eventID) + MXLog.info("Fetching event content for \(eventID)") + + do { + let result = try timeline.getTimelineEventContentByEventId(eventId: eventID) + MXLog.info("Finished fetching event content for eventID: \(eventID)") + return result + } catch { + MXLog.error("Failed fetching event content for eventID: \(eventID) with error: \(error)") + return nil + } } func paginateBackwards(requestSize: UInt) async -> Result { + MXLog.info("Paginating backwards with requestSize: \(requestSize)") + do { try await Task.dispatch(on: .global()) { try self.timeline.paginateBackwards(opts: .simpleRequest(eventLimit: UInt16(requestSize), waitForToken: true)) } + MXLog.info("Finished paginating backwards with requestSize: \(requestSize)") + return .success(()) } catch { + MXLog.error("Failed paginating backwards with requestSize: \(requestSize) with error: \(error)") return .failure(.failedPaginatingBackwards) } } func paginateBackwards(requestSize: UInt, untilNumberOfItems: UInt) async -> Result { + MXLog.info("Paginating backwards with requestSize: \(requestSize), untilNumberOfItems: \(untilNumberOfItems)") + do { try await Task.dispatch(on: .global()) { try self.timeline.paginateBackwards(opts: .untilNumItems(eventLimit: UInt16(requestSize), items: UInt16(untilNumberOfItems), waitForToken: true)) } + MXLog.info("Finished paginating backwards with requestSize: \(requestSize), untilNumberOfItems: \(untilNumberOfItems)") + return .success(()) } catch { + MXLog.error("Finished paginating backwards with requestSize: \(requestSize), untilNumberOfItems: \(untilNumberOfItems) with error: \(error)") return .failure(.failedPaginatingBackwards) } } func retryDecryption(for sessionID: String) async { + MXLog.info("Retrying decryption for sessionID: \(sessionID)") + await Task.dispatch(on: .global()) { [weak self] in self?.timeline.retryDecryption(sessionIds: [sessionID]) + MXLog.info("Finished retrying decryption for sessionID: \(sessionID)") } } func retrySend(transactionID: String) async { + MXLog.info("Retrying sending for transactionID: \(transactionID)") + sendMessageBackgroundTask = await backgroundTaskService.startBackgroundTask(withName: backgroundTaskName, isReusable: true) defer { sendMessageBackgroundTask?.stop() @@ -172,6 +205,7 @@ final class TimelineProxy: TimelineProxyProtocol { return await Task.dispatch(on: messageSendingDispatchQueue) { self.timeline.retrySend(txnId: transactionID) + MXLog.info("Finished retrying sending for transactionID: \(transactionID)") } } @@ -179,6 +213,8 @@ final class TimelineProxy: TimelineProxyProtocol { audioInfo: AudioInfo, progressSubject: CurrentValueSubject?, requestHandle: @MainActor (SendAttachmentJoinHandleProtocol) -> Void) async -> Result { + MXLog.info("Sending audio") + sendMessageBackgroundTask = await backgroundTaskService.startBackgroundTask(withName: backgroundTaskName, isReusable: true) defer { sendMessageBackgroundTask?.stop() @@ -192,7 +228,9 @@ final class TimelineProxy: TimelineProxyProtocol { do { try await handle.join() + MXLog.info("Finished sending audio") } catch { + MXLog.error("Failed sending audio with error: \(error)") return .failure(.failedSendingMedia) } @@ -205,6 +243,8 @@ final class TimelineProxy: TimelineProxyProtocol { fileInfo: FileInfo, progressSubject: CurrentValueSubject?, requestHandle: @MainActor (SendAttachmentJoinHandleProtocol) -> Void) async -> Result { + MXLog.info("Sending file") + sendMessageBackgroundTask = await backgroundTaskService.startBackgroundTask(withName: backgroundTaskName, isReusable: true) defer { sendMessageBackgroundTask?.stop() @@ -218,7 +258,9 @@ final class TimelineProxy: TimelineProxyProtocol { do { try await handle.join() + MXLog.info("Finished sending file") } catch { + MXLog.error("Failed sending file with error: \(error)") return .failure(.failedSendingMedia) } @@ -232,6 +274,8 @@ final class TimelineProxy: TimelineProxyProtocol { imageInfo: ImageInfo, progressSubject: CurrentValueSubject?, requestHandle: @MainActor (SendAttachmentJoinHandleProtocol) -> Void) async -> Result { + MXLog.info("Sending image") + sendMessageBackgroundTask = await backgroundTaskService.startBackgroundTask(withName: backgroundTaskName, isReusable: true) defer { sendMessageBackgroundTask?.stop() @@ -245,7 +289,9 @@ final class TimelineProxy: TimelineProxyProtocol { do { try await handle.join() + MXLog.info("Finished sending image") } catch { + MXLog.error("Failed sending image with error: \(error)") return .failure(.failedSendingMedia) } @@ -259,6 +305,8 @@ final class TimelineProxy: TimelineProxyProtocol { description: String?, zoomLevel: UInt8?, assetType: AssetType?) async -> Result { + MXLog.info("Sending location") + sendMessageBackgroundTask = await backgroundTaskService.startBackgroundTask(withName: backgroundTaskName, isReusable: true) defer { sendMessageBackgroundTask?.stop() @@ -273,6 +321,8 @@ final class TimelineProxy: TimelineProxyProtocol { self.actionsSubject.send(.sentMessage) + MXLog.info("Finished sending location") + return .success(()) } } @@ -282,6 +332,8 @@ final class TimelineProxy: TimelineProxyProtocol { videoInfo: VideoInfo, progressSubject: CurrentValueSubject?, requestHandle: @MainActor (SendAttachmentJoinHandleProtocol) -> Void) async -> Result { + MXLog.info("Sending video") + sendMessageBackgroundTask = await backgroundTaskService.startBackgroundTask(withName: backgroundTaskName, isReusable: true) defer { sendMessageBackgroundTask?.stop() @@ -295,7 +347,9 @@ final class TimelineProxy: TimelineProxyProtocol { do { try await handle.join() + MXLog.info("Finished sending video") } catch { + MXLog.error("Failed sending video with error: \(error)") return .failure(.failedSendingMedia) } @@ -309,6 +363,8 @@ final class TimelineProxy: TimelineProxyProtocol { waveform: [UInt16], progressSubject: CurrentValueSubject?, requestHandle: @MainActor (SendAttachmentJoinHandleProtocol) -> Void) async -> Result { + MXLog.info("Sending voice message") + sendMessageBackgroundTask = await backgroundTaskService.startBackgroundTask(withName: backgroundTaskName, isReusable: true) defer { sendMessageBackgroundTask?.stop() @@ -322,7 +378,9 @@ final class TimelineProxy: TimelineProxyProtocol { do { try await handle.join() + MXLog.info("Finished sending voice message") } catch { + MXLog.error("Failed sending vocie message with error: \(error)") return .failure(.failedSendingMedia) } @@ -335,6 +393,12 @@ final class TimelineProxy: TimelineProxyProtocol { html: String, inReplyTo eventID: String? = nil, intentionalMentions: IntentionalMentions) async -> Result { + if let eventID { + MXLog.info("Sending reply to eventID: \(eventID)") + } else { + MXLog.info("Sending message") + } + sendMessageBackgroundTask = await backgroundTaskService.startBackgroundTask(withName: backgroundTaskName, isReusable: true) defer { sendMessageBackgroundTask?.stop() @@ -349,10 +413,18 @@ final class TimelineProxy: TimelineProxyProtocol { if let eventID { let replyItem = try self.timeline.getEventTimelineItemByEventId(eventId: eventID) try self.timeline.sendReply(msg: messageContent, replyItem: replyItem) + MXLog.info("Finished sending reply to eventID: \(eventID)") } else { self.timeline.send(msg: messageContent) + MXLog.info("Finished sending message") } } catch { + if let eventID { + MXLog.error("Failed sending reply to eventID: \(eventID)") + } else { + MXLog.error("Failed sending message") + } + return .failure(.failedSendingMessage) } @@ -363,6 +435,8 @@ final class TimelineProxy: TimelineProxyProtocol { } func sendMessageEventContent(_ messageContent: RoomMessageEventContentWithoutRelation) async -> Result { + MXLog.info("Sending message content") + sendMessageBackgroundTask = await backgroundTaskService.startBackgroundTask(withName: backgroundTaskName, isReusable: true) defer { sendMessageBackgroundTask?.stop() @@ -373,11 +447,15 @@ final class TimelineProxy: TimelineProxyProtocol { self.actionsSubject.send(.sentMessage) + MXLog.info("Finished sending message content") + return .success(()) } } func sendReadReceipt(for eventID: String) async -> Result { + MXLog.info("Sending read receipt for eventID: \(eventID)") + sendMessageBackgroundTask = await backgroundTaskService.startBackgroundTask(withName: backgroundTaskName, isReusable: true) defer { sendMessageBackgroundTask?.stop() @@ -386,14 +464,18 @@ final class TimelineProxy: TimelineProxyProtocol { return await Task.dispatch(on: lowPriorityDispatchQueue) { do { try self.timeline.sendReadReceipt(receiptType: .read, eventId: eventID) + MXLog.info("Finished sending read receipt for eventID: \(eventID)") return .success(()) } catch { + MXLog.error("Failed sending read receipt for eventID: \(eventID) with error: \(error)") return .failure(.failedSendingReadReceipt) } } } func toggleReaction(_ reaction: String, to eventID: String) async -> Result { + MXLog.info("Toggling reaction for eventID: \(eventID)") + sendMessageBackgroundTask = await backgroundTaskService.startBackgroundTask(withName: backgroundTaskName, isReusable: true) defer { sendMessageBackgroundTask?.stop() @@ -402,8 +484,10 @@ final class TimelineProxy: TimelineProxyProtocol { return await Task.dispatch(on: userInitiatedDispatchQueue) { do { try self.timeline.toggleReaction(eventId: eventID, key: reaction) + MXLog.info("Finished toggling reaction for eventID: \(eventID)") return .success(()) } catch { + MXLog.error("Failed toggling reaction for eventID: \(eventID)") return .failure(.failedSendingReaction) } } @@ -412,15 +496,19 @@ final class TimelineProxy: TimelineProxyProtocol { // MARK: - Polls func createPoll(question: String, answers: [String], pollKind: Poll.Kind) async -> Result { - await Task.dispatch(on: .global()) { + MXLog.info("Creating poll") + + return await Task.dispatch(on: .global()) { do { try self.timeline.createPoll(question: question, answers: answers, maxSelections: 1, pollKind: .init(pollKind: pollKind)) self.actionsSubject.send(.sentMessage) + MXLog.info("Finished creating poll") + return .success(()) } catch { - MXLog.error("Failed creating a poll: \(error)") + MXLog.error("Failed creating poll with error: \(error)") return .failure(.failedCreatingPoll) } } @@ -430,34 +518,53 @@ final class TimelineProxy: TimelineProxyProtocol { question: String, answers: [String], pollKind: Poll.Kind) async -> Result { + MXLog.info("Editing poll with eventID: \(eventID)") + do { let originalEvent = try await Task.dispatch(on: .global()) { try self.timeline.getEventTimelineItemByEventId(eventId: eventID) } - return try await .success(timeline.editPoll(question: question, answers: answers, maxSelections: 1, pollKind: .init(pollKind: pollKind), editItem: originalEvent)) + + try await timeline.editPoll(question: question, answers: answers, maxSelections: 1, pollKind: .init(pollKind: pollKind), editItem: originalEvent) + + MXLog.info("Finished editing poll with eventID: \(eventID)") + + return .success(()) } catch { - MXLog.error("Failed editing the poll: \(error), eventID: \(eventID)") + MXLog.error("Failed editing poll with eventID: \(eventID) with error: \(error)") return .failure(.failedEditingPoll) } } func endPoll(pollStartID: String, text: String) async -> Result { - await Task.dispatch(on: .global()) { + MXLog.info("Ending poll with eventID: \(pollStartID)") + + return await Task.dispatch(on: .global()) { do { - return try .success(self.timeline.endPoll(pollStartId: pollStartID, text: text)) + try self.timeline.endPoll(pollStartId: pollStartID, text: text) + + MXLog.info("Finished ending poll with eventID: \(pollStartID)") + + return .success(()) } catch { - MXLog.error("Failed ending a poll: \(error), pollStartID: \(pollStartID)") + MXLog.error("Failed ending poll with eventID: \(pollStartID) with error: \(error)") return .failure(.failedEndingPoll) } } } func sendPollResponse(pollStartID: String, answers: [String]) async -> Result { - await Task.dispatch(on: .global()) { + MXLog.info("Sending response for poll with eventID: \(pollStartID)") + + return await Task.dispatch(on: .global()) { do { - return try .success(self.timeline.sendPollResponse(pollStartId: pollStartID, answers: answers)) + try self.timeline.sendPollResponse(pollStartId: pollStartID, answers: answers) + + MXLog.info("Finished sending response for poll with eventID: \(pollStartID)") + + return .success(()) } catch { - MXLog.error("Failed sending a poll vote: \(error), pollStartID: \(pollStartID)") + MXLog.error("Failed sending response for poll with eventID: \(pollStartID) with error: \(error)") return .failure(.failedSendingPollResponse) } }