From c02abe8f032ff127732943ca0d156ac7eba920de Mon Sep 17 00:00:00 2001 From: Umair Date: Fri, 15 Nov 2024 02:04:27 +0000 Subject: [PATCH] Add and improve logging for Messages and Reactions --- Sources/AblyChat/DefaultMessages.swift | 24 ++++++++++++++++--- Sources/AblyChat/DefaultRoomReactions.swift | 5 +++- Sources/AblyChat/Room.swift | 3 ++- .../AblyChatTests/DefaultMessagesTests.swift | 8 +++---- 4 files changed, 31 insertions(+), 9 deletions(-) diff --git a/Sources/AblyChat/DefaultMessages.swift b/Sources/AblyChat/DefaultMessages.swift index 23074557..d8546526 100644 --- a/Sources/AblyChat/DefaultMessages.swift +++ b/Sources/AblyChat/DefaultMessages.swift @@ -16,16 +16,18 @@ internal final class DefaultMessages: Messages, EmitsDiscontinuities { public nonisolated let featureChannel: FeatureChannel private let chatAPI: ChatAPI private let clientID: String + private let logger: InternalLogger // TODO: https://github.com/ably-labs/ably-chat-swift/issues/36 - Handle unsubscribing in line with CHA-M4b // UUID acts as a unique identifier for each listener/subscription. MessageSubscriptionWrapper houses the subscription and the timeserial of when it was attached or resumed. private var subscriptionPoints: [UUID: MessageSubscriptionWrapper] = [:] - internal nonisolated init(featureChannel: FeatureChannel, chatAPI: ChatAPI, roomID: String, clientID: String) async { + internal nonisolated init(featureChannel: FeatureChannel, chatAPI: ChatAPI, roomID: String, clientID: String, logger: InternalLogger) async { self.featureChannel = featureChannel self.chatAPI = chatAPI self.roomID = roomID self.clientID = clientID + self.logger = logger // Implicitly handles channel events and therefore listners within this class. Alternative is to explicitly call something like `DefaultMessages.start()` which makes the SDK more cumbersome to interact with. This class is useless without kicking off this flow so I think leaving it here is suitable. // "Calls to instance method 'handleChannelEvents(roomId:)' from outside of its actor context are implicitly asynchronous" hence the `await` here. @@ -38,6 +40,7 @@ internal final class DefaultMessages: Messages, EmitsDiscontinuities { // (CHA-M4) Messages can be received via a subscription in realtime. internal func subscribe(bufferingPolicy: BufferingPolicy) async throws -> MessageSubscription { + logger.log(message: "Subscribing to messages", level: .debug) let uuid = UUID() let timeserial = try await resolveSubscriptionStart() let messageSubscription = MessageSubscription( @@ -162,8 +165,10 @@ internal final class DefaultMessages: Messages, EmitsDiscontinuities { } private func handleAttach(fromResume: Bool) async throws { + logger.log(message: "Handling attach", level: .debug) // Do nothing if we have resumed as there is no discontinuity in the message stream if fromResume { + logger.log(message: "Channel has resumed, no need to handle attach", level: .debug) return } @@ -171,20 +176,26 @@ internal final class DefaultMessages: Messages, EmitsDiscontinuities { let timeserialOnChannelAttach = try await timeserialOnChannelAttach() for uuid in subscriptionPoints.keys { + logger.log(message: "Resetting subscription point for listener: \(uuid)", level: .debug) subscriptionPoints[uuid]?.timeserial = timeserialOnChannelAttach } } catch { + logger.log(message: "Error handling attach: \(error)", level: .error) throw ARTErrorInfo.create(from: error) } } private func resolveSubscriptionStart() async throws -> TimeserialString { + logger.log(message: "Resolving subscription start", level: .debug) // (CHA-M5a) If a subscription is added when the underlying realtime channel is ATTACHED, then the subscription point is the current channelSerial of the realtime channel. if channel.state == .attached { if let channelSerial = channel.properties.channelSerial { + logger.log(message: "Channel is attached, returning channelSerial: \(channelSerial)", level: .debug) return channelSerial } else { - throw ARTErrorInfo.create(withCode: 40000, status: 400, message: "channel is attached, but channelSerial is not defined") + let error = ARTErrorInfo.create(withCode: 40000, status: 400, message: "channel is attached, but channelSerial is not defined") + logger.log(message: "Error resolving subscription start: \(error)", level: .error) + throw error } } @@ -194,12 +205,16 @@ internal final class DefaultMessages: Messages, EmitsDiscontinuities { // Always returns the attachSerial and not the channelSerial to also serve (CHA-M5c) - If a channel leaves the ATTACHED state and then re-enters ATTACHED with resumed=false, then it must be assumed that messages have been missed. The subscription point of any subscribers must be reset to the attachSerial. private func timeserialOnChannelAttach() async throws -> TimeserialString { + logger.log(message: "Resolving timeserial on channel attach", level: .debug) // If the state is already 'attached', return the attachSerial immediately if channel.state == .attached { if let attachSerial = channel.properties.attachSerial { + logger.log(message: "Channel is attached, returning attachSerial: \(attachSerial)", level: .debug) return attachSerial } else { - throw ARTErrorInfo.create(withCode: 40000, status: 400, message: "Channel is attached, but attachSerial is not defined") + let error = ARTErrorInfo.create(withCode: 40000, status: 400, message: "Channel is attached, but attachSerial is not defined") + logger.log(message: "Error resolving timeserial on channel attach: \(error)", level: .error) + throw error } } @@ -217,13 +232,16 @@ internal final class DefaultMessages: Messages, EmitsDiscontinuities { case .attached: // Handle successful attachment if let attachSerial = channel.properties.attachSerial { + logger.log(message: "Channel is attached, returning attachSerial: \(attachSerial)", level: .debug) nillableContinuation?.resume(returning: attachSerial) } else { + logger.log(message: "Channel is attached, but attachSerial is not defined", level: .error) nillableContinuation?.resume(throwing: ARTErrorInfo.create(withCode: 40000, status: 400, message: "Channel is attached, but attachSerial is not defined")) } nillableContinuation = nil case .failed, .suspended: // TODO: Revisit as part of https://github.com/ably-labs/ably-chat-swift/issues/32 + logger.log(message: "Channel failed to attach", level: .error) nillableContinuation?.resume( throwing: ARTErrorInfo.create( withCode: ErrorCode.messagesAttachmentFailed.rawValue, diff --git a/Sources/AblyChat/DefaultRoomReactions.swift b/Sources/AblyChat/DefaultRoomReactions.swift index 9924e27d..6f6cfcfe 100644 --- a/Sources/AblyChat/DefaultRoomReactions.swift +++ b/Sources/AblyChat/DefaultRoomReactions.swift @@ -22,6 +22,7 @@ internal final class DefaultRoomReactions: RoomReactions, EmitsDiscontinuities { // (CHA-ER3) Ephemeral room reactions are sent to Ably via the Realtime connection via a send method. // (CHA-ER3a) Reactions are sent on the channel using a message in a particular format - see spec for format. internal func send(params: SendReactionParams) async throws { + logger.log(message: "Sending reaction with params: \(params)", level: .debug) let extras = ["headers": params.headers ?? [:]] as ARTJsonCompatible channel.publish(RoomReactionEvents.reaction.rawValue, data: params.asQueryItems(), extras: extras) } @@ -29,10 +30,12 @@ internal final class DefaultRoomReactions: RoomReactions, EmitsDiscontinuities { // (CHA-ER4) A user may subscribe to reaction events in Realtime. // (CHA-ER4a) A user may provide a listener to subscribe to reaction events. This operation must have no side-effects in relation to room or underlying status. When a realtime message with name roomReaction is received, this message is converted into a reaction object and emitted to subscribers. internal func subscribe(bufferingPolicy: BufferingPolicy) async -> Subscription { + logger.log(message: "Subscribing to reaction events", level: .debug) let subscription = Subscription(bufferingPolicy: bufferingPolicy) // (CHA-ER4c) Realtime events with an unknown name shall be silently discarded. channel.subscribe(RoomReactionEvents.reaction.rawValue) { [clientID, logger] message in + logger.log(message: "Received roomReaction message: \(message)", level: .debug) Task { do { guard let data = message.data as? [String: Any], @@ -65,7 +68,7 @@ internal final class DefaultRoomReactions: RoomReactions, EmitsDiscontinuities { clientID: messageClientID, isSelf: messageClientID == clientID ) - + logger.log(message: "Emitting reaction: \(reaction)", level: .debug) subscription.emit(reaction) } catch { logger.log(message: "Error processing incoming reaction message: \(error)", level: .error) diff --git a/Sources/AblyChat/Room.swift b/Sources/AblyChat/Room.swift index b0c6b6f5..f4bf01c6 100644 --- a/Sources/AblyChat/Room.swift +++ b/Sources/AblyChat/Room.swift @@ -99,7 +99,8 @@ internal actor DefaultRoom featureChannel: featureChannels[.messages]!, chatAPI: chatAPI, roomID: roomID, - clientID: clientId + clientID: clientId, + logger: logger ) _reactions = options.reactions != nil ? await DefaultRoomReactions( diff --git a/Tests/AblyChatTests/DefaultMessagesTests.swift b/Tests/AblyChatTests/DefaultMessagesTests.swift index 4ab88a51..77f7d26b 100644 --- a/Tests/AblyChatTests/DefaultMessagesTests.swift +++ b/Tests/AblyChatTests/DefaultMessagesTests.swift @@ -12,7 +12,7 @@ struct DefaultMessagesTests { let chatAPI = ChatAPI(realtime: realtime) let channel = MockRealtimeChannel() let featureChannel = MockFeatureChannel(channel: channel) - let defaultMessages = await DefaultMessages(featureChannel: featureChannel, chatAPI: chatAPI, roomID: "basketball", clientID: "clientId") + let defaultMessages = await DefaultMessages(featureChannel: featureChannel, chatAPI: chatAPI, roomID: "basketball", clientID: "clientId", logger: TestLogger()) // Then await #expect(throws: ARTErrorInfo.create(withCode: 40000, status: 400, message: "channel is attached, but channelSerial is not defined"), performing: { @@ -30,7 +30,7 @@ struct DefaultMessagesTests { let chatAPI = ChatAPI(realtime: realtime) let channel = MockRealtimeChannel() let featureChannel = MockFeatureChannel(channel: channel) - let defaultMessages = await DefaultMessages(featureChannel: featureChannel, chatAPI: chatAPI, roomID: "basketball", clientID: "clientId") + let defaultMessages = await DefaultMessages(featureChannel: featureChannel, chatAPI: chatAPI, roomID: "basketball", clientID: "clientId", logger: TestLogger()) // Then await #expect(throws: Never.self, performing: { @@ -55,7 +55,7 @@ struct DefaultMessagesTests { ) ) let featureChannel = MockFeatureChannel(channel: channel) - let defaultMessages = await DefaultMessages(featureChannel: featureChannel, chatAPI: chatAPI, roomID: "basketball", clientID: "clientId") + let defaultMessages = await DefaultMessages(featureChannel: featureChannel, chatAPI: chatAPI, roomID: "basketball", clientID: "clientId", logger: TestLogger()) let subscription = try await defaultMessages.subscribe(bufferingPolicy: .unbounded) let expectedPaginatedResult = PaginatedResultWrapper( paginatedResponse: MockHTTPPaginatedResponse.successGetMessagesWithNoItems, @@ -77,7 +77,7 @@ struct DefaultMessagesTests { let chatAPI = ChatAPI(realtime: realtime) let channel = MockRealtimeChannel() let featureChannel = MockFeatureChannel(channel: channel) - let messages = await DefaultMessages(featureChannel: featureChannel, chatAPI: chatAPI, roomID: "basketball", clientID: "clientId") + let messages = await DefaultMessages(featureChannel: featureChannel, chatAPI: chatAPI, roomID: "basketball", clientID: "clientId", logger: TestLogger()) // When: The feature channel emits a discontinuity through `subscribeToDiscontinuities` let featureChannelDiscontinuity = ARTErrorInfo.createUnknownError() // arbitrary