[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

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
 

chat-android/src/main/java/com/ably/chat/Occupancy.kt

@@ -73,15 +73,15 @@ data class OccupancyEvent(
 
 internal class DefaultOccupancy(
     private val room: DefaultRoom,
-) : Occupancy, ContributesToRoomLifecycleImpl(room.roomLogger) {
+) : Occupancy, ContributesToRoomLifecycleImpl(room.logger) {
 
     override val featureName: String = "occupancy"
 
     override val attachmentErrorCode: ErrorCode = ErrorCode.OccupancyAttachmentFailed
 
     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
 

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<PresenceMember> {
-        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))
     }
 

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<ContributesToRoomLifecycle>(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<Unit>()
                 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)
+            }
         }
     }
 }

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)
         }
     }

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)
     }
 

chat-android/src/main/java/com/ably/chat/Typing.kt

@@ -94,7 +94,7 @@ data class TypingEvent(val currentlyTyping: Set<String>)
 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<String> {
         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()
     }

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<Logger>()) } returns Unit
     }
 
     /**

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<RoomLifecycle.Listener>())
@@ -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 }