From 11180ae9871d46131123973cd4915fe305e28823 Mon Sep 17 00:00:00 2001 From: sacOO7 Date: Fri, 6 Dec 2024 18:53:12 +0530 Subject: [PATCH] [ECO-5166][CHA-RC2] Implement logging for the Room 1. Renamed property roomLogger to logger 2. Added basic trace, debug and error loggings for the Room 3. Updated 'ensureAttached` method to accept featureLogger, added missing loggings for the same --- .../src/main/java/com/ably/chat/Messages.kt | 4 +- .../src/main/java/com/ably/chat/Occupancy.kt | 4 +- .../src/main/java/com/ably/chat/Presence.kt | 12 ++--- .../src/main/java/com/ably/chat/Room.kt | 52 ++++++++++++++----- .../main/java/com/ably/chat/RoomOptions.kt | 3 +- .../main/java/com/ably/chat/RoomReactions.kt | 6 +-- .../src/main/java/com/ably/chat/Typing.kt | 10 ++-- .../src/test/java/com/ably/chat/TypingTest.kt | 2 +- .../ably/chat/room/RoomEnsureAttachedTest.kt | 10 ++-- 9 files changed, 66 insertions(+), 37 deletions(-) diff --git a/chat-android/src/main/java/com/ably/chat/Messages.kt b/chat-android/src/main/java/com/ably/chat/Messages.kt index bd5c21d5..defd1199 100644 --- a/chat-android/src/main/java/com/ably/chat/Messages.kt +++ b/chat-android/src/main/java/com/ably/chat/Messages.kt @@ -220,13 +220,13 @@ internal class DefaultMessagesSubscription( internal class DefaultMessages( val room: DefaultRoom, -) : Messages, ContributesToRoomLifecycleImpl(room.roomLogger) { +) : Messages, ContributesToRoomLifecycleImpl(room.logger) { override val featureName: String = "messages" private var channelStateListener: ChannelStateListener - private val logger = room.roomLogger.withContext(tag = "Messages") + private val logger = room.logger.withContext(tag = "Messages") private val roomId = room.roomId diff --git a/chat-android/src/main/java/com/ably/chat/Occupancy.kt b/chat-android/src/main/java/com/ably/chat/Occupancy.kt index 7979fb56..a61d5f76 100644 --- a/chat-android/src/main/java/com/ably/chat/Occupancy.kt +++ b/chat-android/src/main/java/com/ably/chat/Occupancy.kt @@ -73,7 +73,7 @@ data class OccupancyEvent( internal class DefaultOccupancy( private val room: DefaultRoom, -) : Occupancy, ContributesToRoomLifecycleImpl(room.roomLogger) { +) : Occupancy, ContributesToRoomLifecycleImpl(room.logger) { override val featureName: String = "occupancy" @@ -81,7 +81,7 @@ internal class DefaultOccupancy( override val detachmentErrorCode: ErrorCode = ErrorCode.OccupancyDetachmentFailed - private val logger = room.roomLogger.withContext(tag = "Occupancy") + private val logger = room.logger.withContext(tag = "Occupancy") override val channel: Channel = room.messages.channel diff --git a/chat-android/src/main/java/com/ably/chat/Presence.kt b/chat-android/src/main/java/com/ably/chat/Presence.kt index 8e1060c4..79fcfe44 100644 --- a/chat-android/src/main/java/com/ably/chat/Presence.kt +++ b/chat-android/src/main/java/com/ably/chat/Presence.kt @@ -136,7 +136,7 @@ data class PresenceEvent( internal class DefaultPresence( private val room: DefaultRoom, -) : Presence, ContributesToRoomLifecycleImpl(room.roomLogger) { +) : Presence, ContributesToRoomLifecycleImpl(room.logger) { override val featureName = "presence" @@ -146,12 +146,12 @@ internal class DefaultPresence( override val channel: Channel = room.messages.channel - private val logger = room.roomLogger.withContext(tag = "Presence") + private val logger = room.logger.withContext(tag = "Presence") private val presence = channel.presence override suspend fun get(waitForSync: Boolean, clientId: String?, connectionId: String?): List { - room.ensureAttached() // CHA-PR6d, CHA-PR6c, CHA-PR6h + room.ensureAttached(logger) // CHA-PR6d, CHA-PR6c, CHA-PR6h return presence.getCoroutine(waitForSync, clientId, connectionId).map { user -> PresenceMember( clientId = user.clientId, @@ -165,17 +165,17 @@ internal class DefaultPresence( override suspend fun isUserPresent(clientId: String): Boolean = presence.getCoroutine(clientId = clientId).isNotEmpty() override suspend fun enter(data: PresenceData?) { - room.ensureAttached() // CHA-PR3e, CHA-PR3d, CHA-PR3h + room.ensureAttached(logger) // CHA-PR3e, CHA-PR3d, CHA-PR3h presence.enterClientCoroutine(room.clientId, wrapInUserCustomData(data)) } override suspend fun update(data: PresenceData?) { - room.ensureAttached() // CHA-PR10e, CHA-PR10d, CHA-PR10h + room.ensureAttached(logger) // CHA-PR10e, CHA-PR10d, CHA-PR10h presence.updateClientCoroutine(room.clientId, wrapInUserCustomData(data)) } override suspend fun leave(data: PresenceData?) { - room.ensureAttached() // CHA-PR4d, CHA-PR4b, CHA-PR4c + room.ensureAttached(logger) // CHA-PR4d, CHA-PR4b, CHA-PR4c presence.leaveClientCoroutine(room.clientId, wrapInUserCustomData(data)) } diff --git a/chat-android/src/main/java/com/ably/chat/Room.kt b/chat-android/src/main/java/com/ably/chat/Room.kt index 8e0d852f..28ac2cd2 100644 --- a/chat-android/src/main/java/com/ably/chat/Room.kt +++ b/chat-android/src/main/java/com/ably/chat/Room.kt @@ -117,7 +117,7 @@ internal class DefaultRoom( internal val clientId: String, logger: Logger, ) : Room { - internal val roomLogger = logger.withContext("Room", mapOf("roomId" to roomId)) + internal val logger = logger.withContext("Room", mapOf("roomId" to roomId)) /** * RoomScope is a crucial part of the Room lifecycle. It manages sequential and atomic operations. @@ -133,7 +133,8 @@ internal class DefaultRoom( override val presence: Presence get() { if (_presence == null) { // CHA-RC2b - throw ablyException("Presence is not enabled for this room", ErrorCode.BadRequest) + logger.error("Presence access failed, not enabled in provided RoomOptions: $options") + throw clientError("Presence is not enabled for this room") } return _presence as Presence } @@ -142,7 +143,8 @@ internal class DefaultRoom( override val reactions: RoomReactions get() { if (_reactions == null) { // CHA-RC2b - throw ablyException("Reactions are not enabled for this room", ErrorCode.BadRequest) + logger.error("Reactions access failed, not enabled in provided RoomOptions: $options") + throw clientError("Reactions are not enabled for this room") } return _reactions as RoomReactions } @@ -151,7 +153,8 @@ internal class DefaultRoom( override val typing: Typing get() { if (_typing == null) { // CHA-RC2b - throw ablyException("Typing is not enabled for this room", ErrorCode.BadRequest) + logger.error("Typing access failed, not enabled in provided RoomOptions: $options") + throw clientError("Typing is not enabled for this room") } return _typing as Typing } @@ -160,12 +163,13 @@ internal class DefaultRoom( override val occupancy: Occupancy get() { if (_occupancy == null) { // CHA-RC2b - throw ablyException("Occupancy is not enabled for this room", ErrorCode.BadRequest) + logger.error("Occupancy access failed, not enabled in provided RoomOptions: $options") + throw clientError("Occupancy is not enabled for this room") } return _occupancy as Occupancy } - private val statusLifecycle = DefaultRoomLifecycle(roomLogger) + private val statusLifecycle = DefaultRoomLifecycle(this.logger) override val status: RoomStatus get() = statusLifecycle.status @@ -176,7 +180,9 @@ internal class DefaultRoom( private var lifecycleManager: RoomLifecycleManager init { - options.validateRoomOptions() // CHA-RC2a + this.logger.debug("Initializing based on provided RoomOptions: $options") + + options.validateRoomOptions(this.logger) // CHA-RC2a // CHA-RC2e - Add contributors/features as per the order of precedence val roomFeatures = mutableListOf(messages) @@ -205,7 +211,9 @@ internal class DefaultRoom( _occupancy = occupancyContributor } - lifecycleManager = RoomLifecycleManager(roomScope, statusLifecycle, roomFeatures, roomLogger) + lifecycleManager = RoomLifecycleManager(roomScope, statusLifecycle, roomFeatures, this.logger) + + this.logger.debug("Initialized with features: ${roomFeatures.joinToString { it.featureName }}") } override fun onStatusChange(listener: RoomLifecycle.Listener): Subscription = @@ -216,10 +224,12 @@ internal class DefaultRoom( } override suspend fun attach() { + logger.trace("attach();") lifecycleManager.attach() } override suspend fun detach() { + logger.trace("detach();") lifecycleManager.detach() } @@ -228,34 +238,49 @@ internal class DefaultRoom( * This is an internal method and only called from Rooms interface implementation. */ internal suspend fun release() { + logger.trace("release();") lifecycleManager.release() } /** * Ensures that the room is attached before performing any realtime room operation. + * Accepts featureLogger as a param, to log respective operation. * @throws roomInvalidStateException if room is not in ATTACHING/ATTACHED state. * Spec: CHA-RL9 */ - internal suspend fun ensureAttached() { + internal suspend fun ensureAttached(featureLogger: Logger) { + featureLogger.trace("ensureAttached();") // CHA-PR3e, CHA-PR10e, CHA-PR4d, CHA-PR6d, CHA-T2d, CHA-T4a1, CHA-T5e when (val currentRoomStatus = statusLifecycle.status) { - RoomStatus.Attached -> return + RoomStatus.Attached -> { + featureLogger.debug("ensureAttached(); Room is already attached") + return + } // CHA-PR3d, CHA-PR10d, CHA-PR4b, CHA-PR6c, CHA-T2c, CHA-T4a3, CHA-T5c RoomStatus.Attaching -> { // CHA-RL9 + featureLogger.debug("ensureAttached(); Room is in attaching state, waiting for attach to complete") val attachDeferred = CompletableDeferred() roomScope.launch { when (statusLifecycle.status) { - RoomStatus.Attached -> attachDeferred.complete(Unit) + RoomStatus.Attached -> { + featureLogger.debug("ensureAttached(); waiting complete, room is now ATTACHED") + attachDeferred.complete(Unit) + } RoomStatus.Attaching -> statusLifecycle.onChangeOnce { if (it.current == RoomStatus.Attached) { + featureLogger.debug("ensureAttached(); waiting complete, room is now ATTACHED") attachDeferred.complete(Unit) } else { + featureLogger.error("ensureAttached(); waiting complete, room ATTACHING failed with error: ${it.error}") val exception = roomInvalidStateException(roomId, statusLifecycle.status, HttpStatusCode.InternalServerError) attachDeferred.completeExceptionally(exception) } } else -> { + featureLogger.error( + "ensureAttached(); waiting complete, room ATTACHING failed with error: ${statusLifecycle.error}", + ) val exception = roomInvalidStateException(roomId, statusLifecycle.status, HttpStatusCode.InternalServerError) attachDeferred.completeExceptionally(exception) } @@ -265,7 +290,10 @@ internal class DefaultRoom( return } // CHA-PR3h, CHA-PR10h, CHA-PR4c, CHA-PR6h, CHA-T2g, CHA-T4a4, CHA-T5d - else -> throw roomInvalidStateException(roomId, currentRoomStatus, HttpStatusCode.BadRequest) + else -> { + featureLogger.error("ensureAttached(); Room is in invalid state: $currentRoomStatus, error: ${statusLifecycle.error}") + throw roomInvalidStateException(roomId, currentRoomStatus, HttpStatusCode.BadRequest) + } } } } diff --git a/chat-android/src/main/java/com/ably/chat/RoomOptions.kt b/chat-android/src/main/java/com/ably/chat/RoomOptions.kt index 03f20304..a9394d5a 100644 --- a/chat-android/src/main/java/com/ably/chat/RoomOptions.kt +++ b/chat-android/src/main/java/com/ably/chat/RoomOptions.kt @@ -104,9 +104,10 @@ class OccupancyOptions { * Throws AblyException for invalid room configuration. * Spec: CHA-RC2a */ -internal fun RoomOptions.validateRoomOptions() { +internal fun RoomOptions.validateRoomOptions(logger: Logger) { typing?.let { if (typing.timeoutMs <= 0) { + logger.error("Typing timeout must be greater than 0, found ${typing.timeoutMs}") throw ablyException("Typing timeout must be greater than 0", ErrorCode.InvalidRequestBody) } } diff --git a/chat-android/src/main/java/com/ably/chat/RoomReactions.kt b/chat-android/src/main/java/com/ably/chat/RoomReactions.kt index 2412200d..dacafccd 100644 --- a/chat-android/src/main/java/com/ably/chat/RoomReactions.kt +++ b/chat-android/src/main/java/com/ably/chat/RoomReactions.kt @@ -106,7 +106,7 @@ data class SendReactionParams( internal class DefaultRoomReactions( private val room: DefaultRoom, -) : RoomReactions, ContributesToRoomLifecycleImpl(room.roomLogger) { +) : RoomReactions, ContributesToRoomLifecycleImpl(room.logger) { override val featureName = "reactions" @@ -118,7 +118,7 @@ internal class DefaultRoomReactions( override val detachmentErrorCode: ErrorCode = ErrorCode.ReactionsDetachmentFailed - private val logger = room.roomLogger.withContext(tag = "Reactions") + private val logger = room.logger.withContext(tag = "Reactions") // (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. @@ -137,7 +137,7 @@ internal class DefaultRoomReactions( ) } } - room.ensureAttached() // TODO - This check might be removed in the future due to core spec change + room.ensureAttached(logger) // TODO - This check might be removed in the future due to core spec change channel.publishCoroutine(pubSubMessage) } diff --git a/chat-android/src/main/java/com/ably/chat/Typing.kt b/chat-android/src/main/java/com/ably/chat/Typing.kt index 4b85fd16..f7607d93 100644 --- a/chat-android/src/main/java/com/ably/chat/Typing.kt +++ b/chat-android/src/main/java/com/ably/chat/Typing.kt @@ -94,7 +94,7 @@ data class TypingEvent(val currentlyTyping: Set) internal class DefaultTyping( private val room: DefaultRoom, dispatcher: CoroutineDispatcher = Dispatchers.Default, -) : Typing, ContributesToRoomLifecycleImpl(room.roomLogger) { +) : Typing, ContributesToRoomLifecycleImpl(room.logger) { private val typingIndicatorsChannelName = "${room.roomId}::\$chat::\$typingIndicators" override val featureName = "typing" @@ -103,7 +103,7 @@ internal class DefaultTyping( override val detachmentErrorCode: ErrorCode = ErrorCode.TypingDetachmentFailed - private val logger = room.roomLogger.withContext(tag = "Typing") + private val logger = room.logger.withContext(tag = "Typing") private val typingScope = CoroutineScope(dispatcher.limitedParallelism(1) + SupervisorJob()) @@ -155,7 +155,7 @@ internal class DefaultTyping( override suspend fun get(): Set { logger.trace("DefaultTyping.get()") - room.ensureAttached() // CHA-T2d, CHA-T2c, CHA-T2g + room.ensureAttached(logger) // CHA-T2d, CHA-T2c, CHA-T2g return channel.presence.getCoroutine().map { it.clientId }.toSet() } @@ -170,7 +170,7 @@ internal class DefaultTyping( startTypingTimer() } else { startTypingTimer() - room.ensureAttached() // CHA-T4a1, CHA-T4a3, CHA-T4a4 + room.ensureAttached(logger) // CHA-T4a1, CHA-T4a3, CHA-T4a4 channel.presence.enterClientCoroutine(room.clientId) } }.join() @@ -180,7 +180,7 @@ internal class DefaultTyping( logger.trace("DefaultTyping.stop()") typingScope.launch { typingJob?.cancel() - room.ensureAttached() // CHA-T5e, CHA-T5c, CHA-T5d + room.ensureAttached(logger) // CHA-T5e, CHA-T5c, CHA-T5d channel.presence.leaveClientCoroutine(room.clientId) }.join() } diff --git a/chat-android/src/test/java/com/ably/chat/TypingTest.kt b/chat-android/src/test/java/com/ably/chat/TypingTest.kt index 0570903e..bdb2e9a3 100644 --- a/chat-android/src/test/java/com/ably/chat/TypingTest.kt +++ b/chat-android/src/test/java/com/ably/chat/TypingTest.kt @@ -42,7 +42,7 @@ class TypingTest { val mockChatApi = createMockChatApi(realtimeClient) room = spyk(createMockRoom("room1", realtimeClient = realtimeClient, chatApi = mockChatApi)) - coEvery { room.ensureAttached() } returns Unit + coEvery { room.ensureAttached(any()) } returns Unit } /** diff --git a/chat-android/src/test/java/com/ably/chat/room/RoomEnsureAttachedTest.kt b/chat-android/src/test/java/com/ably/chat/room/RoomEnsureAttachedTest.kt index 5578305c..d5df305e 100644 --- a/chat-android/src/test/java/com/ably/chat/room/RoomEnsureAttachedTest.kt +++ b/chat-android/src/test/java/com/ably/chat/room/RoomEnsureAttachedTest.kt @@ -44,7 +44,7 @@ class RoomEnsureAttachedTest { room.StatusLifecycle.setStatus(RoomStatus.Attached) Assert.assertEquals(RoomStatus.Attached, room.status) - val result = kotlin.runCatching { room.ensureAttached() } + val result = kotlin.runCatching { room.ensureAttached(logger) } Assert.assertTrue(result.isSuccess) } @@ -70,7 +70,7 @@ class RoomEnsureAttachedTest { Assert.assertEquals(invalidStatus, room.status) // Check for exception when ensuring room ATTACHED - val result = kotlin.runCatching { room.ensureAttached() } + val result = kotlin.runCatching { room.ensureAttached(logger) } Assert.assertTrue(result.isFailure) val exception = result.exceptionOrNull() as AblyException Assert.assertEquals(ErrorCode.RoomInInvalidState.code, exception.errorInfo.code) @@ -98,7 +98,7 @@ class RoomEnsureAttachedTest { room.StatusLifecycle.setStatus(RoomStatus.Attaching) Assert.assertEquals(RoomStatus.Attaching, room.status) - room.ensureAttached() + room.ensureAttached(logger) verify(exactly = 1) { roomLifecycleMock.onChangeOnce(any()) @@ -114,7 +114,7 @@ class RoomEnsureAttachedTest { room.StatusLifecycle.setStatus(RoomStatus.Attaching) Assert.assertEquals(RoomStatus.Attaching, room.status) - val ensureAttachJob = async { room.ensureAttached() } + val ensureAttachJob = async { room.ensureAttached(logger) } // Wait for listener to be registered assertWaiter { room.StatusLifecycle.InternalEmitter.Filters.size == 1 } @@ -150,7 +150,7 @@ class RoomEnsureAttachedTest { room.StatusLifecycle.setStatus(RoomStatus.Attaching) Assert.assertEquals(RoomStatus.Attaching, room.status) - val ensureAttachJob = async(SupervisorJob()) { room.ensureAttached() } + val ensureAttachJob = async(SupervisorJob()) { room.ensureAttached(logger) } // Wait for listener to be registered assertWaiter { room.StatusLifecycle.InternalEmitter.Filters.size == 1 }