[ECO-5165][CHA-RC1] Implement logging for Rooms

1. Added private property roomsLogger for DefaultRooms class
2. Added basic logging for Rooms#get method
3. Updated fields roomGetDeferred and roomReleaseDeferred to roomGetDeferredMap
and roomReleaseDeferredMap respectively
4. Refactored roomGetDeferred.invokeOnCompletion, to make sure operation is
executed under sequential scope, moved it as a part of release

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

@@ -62,8 +62,9 @@ internal class DefaultRooms(
     private val chatApi: ChatApi,
     override val clientOptions: ClientOptions,
     private val clientId: String,
-    private val logger: Logger,
+    logger: Logger,
 ) : Rooms {
+    private val logger = logger.withContext(tag = "Rooms")
 
     /**
      * All operations for DefaultRooms should be executed under sequentialScope to avoid concurrency issues.
@@ -72,49 +73,59 @@ internal class DefaultRooms(
     private val sequentialScope = CoroutineScope(Dispatchers.Default.limitedParallelism(1) + SupervisorJob())
 
     private val roomIdToRoom: MutableMap<String, DefaultRoom> = mutableMapOf()
-    private val roomGetDeferred: MutableMap<String, CompletableDeferred<Unit>> = mutableMapOf()
-    private val roomReleaseDeferred: MutableMap<String, CompletableDeferred<Unit>> = mutableMapOf()
+    private val roomGetDeferredMap: MutableMap<String, CompletableDeferred<Unit>> = mutableMapOf()
+    private val roomReleaseDeferredMap: MutableMap<String, CompletableDeferred<Unit>> = mutableMapOf()
 
     override suspend fun get(roomId: String, options: RoomOptions): Room {
+        logger.trace("get(); $roomId; $options")
         return sequentialScope.async {
             val existingRoom = getReleasedOrExistingRoom(roomId)
             existingRoom?.let {
                 if (options != existingRoom.options) { // CHA-RC1f1
                     throw ablyException("room already exists with different options", ErrorCode.BadRequest)
                 }
+                logger.debug("get(); returning existing room with roomId: $roomId")
                 return@async existingRoom // CHA-RC1f2
             }
             // CHA-RC1f3
             val newRoom = makeRoom(roomId, options)
             roomIdToRoom[roomId] = newRoom
+            logger.debug("get(); returning new room with roomId: $roomId")
             return@async newRoom
         }.await()
     }
 
     override suspend fun release(roomId: String) {
+        logger.trace("release(); $roomId")
         sequentialScope.launch {
             // CHA-RC1g4 - Previous Room Get in progress, cancel all of them
-            roomGetDeferred[roomId]?.let {
+            roomGetDeferredMap[roomId]?.let {
+                logger.debug("release(); cancelling existing rooms.get() for roomId: $roomId")
                 val exception = ablyException(
                     "room released before get operation could complete",
                     ErrorCode.RoomReleasedBeforeOperationCompleted,
                 )
                 it.completeExceptionally(exception)
+                it.join() // Doesn't throw exception, only waits till job is complete.
+                roomGetDeferredMap.remove(roomId)
+                logger.warn("release(); cancelled existing rooms.get() for roomId: $roomId")
             }
 
             // CHA-RC1g2, CHA-RC1g3
             val existingRoom = roomIdToRoom[roomId]
             existingRoom?.let {
-                if (roomReleaseDeferred.containsKey(roomId)) {
-                    roomReleaseDeferred[roomId]?.await()
+                logger.debug("release(); releasing roomId: $roomId")
+                if (roomReleaseDeferredMap.containsKey(roomId)) {
+                    roomReleaseDeferredMap[roomId]?.await()
                 } else {
                     val roomReleaseDeferred = CompletableDeferred<Unit>()
-                    this@DefaultRooms.roomReleaseDeferred[roomId] = roomReleaseDeferred
+                    roomReleaseDeferredMap[roomId] = roomReleaseDeferred
                     existingRoom.release() // CHA-RC1g5
                     roomReleaseDeferred.complete(Unit)
                 }
+                logger.debug("release(); released roomId: $roomId")
             }
-            roomReleaseDeferred.remove(roomId)
+            roomReleaseDeferredMap.remove(roomId)
             roomIdToRoom.remove(roomId)
         }.join()
     }
@@ -127,33 +138,33 @@ internal class DefaultRooms(
     private suspend fun getReleasedOrExistingRoom(roomId: String): Room? {
         // Previous Room Get in progress, because room release in progress
         // So await on same deferred and return null
-        roomGetDeferred[roomId]?.let {
+        roomGetDeferredMap[roomId]?.let {
+            logger.debug("getReleasedOrExistingRoom(); awaiting on previous rooms.get() for roomId: $roomId")
             it.await()
             return null
         }
 
         val existingRoom = roomIdToRoom[roomId]
         existingRoom?.let {
-            val roomReleaseInProgress = roomReleaseDeferred[roomId]
+            logger.debug("getReleasedOrExistingRoom(); existing room found, roomId: $roomId")
+            val roomReleaseInProgress = roomReleaseDeferredMap[roomId]
             roomReleaseInProgress?.let {
+                logger.debug("getReleasedOrExistingRoom(); waiting for roomId: $roomId to be released")
                 val roomGetDeferred = CompletableDeferred<Unit>()
-                this.roomGetDeferred[roomId] = roomGetDeferred
-                roomGetDeferred.invokeOnCompletion { throwable ->
-                    throwable?.let {
-                        this.roomGetDeferred.remove(roomId)
-                    }
-                }
+                roomGetDeferredMap[roomId] = roomGetDeferred
                 roomReleaseInProgress.await()
                 if (roomGetDeferred.isActive) {
                     roomGetDeferred.complete(Unit)
                 } else {
                     roomGetDeferred.await()
                 }
-                this.roomGetDeferred.remove(roomId)
+                roomGetDeferredMap.remove(roomId)
+                logger.debug("getReleasedOrExistingRoom(); waiting complete, roomId: $roomId is released")
                 return null
             }
             return existingRoom
         }
+        logger.debug("getReleasedOrExistingRoom(); no existing room found, roomId: $roomId")
         return null
     }
 

chat-android/src/test/java/com/ably/chat/room/RoomGetTest.kt

@@ -123,8 +123,8 @@ class RoomGetTest {
         val roomId = "1234"
 
         // No release op. in progress
-        Assert.assertEquals(0, rooms.RoomReleaseDeferred.size)
-        Assert.assertNull(rooms.RoomReleaseDeferred[roomId])
+        Assert.assertEquals(0, rooms.RoomReleaseDeferredMap.size)
+        Assert.assertNull(rooms.RoomReleaseDeferredMap[roomId])
 
         // Creates a new room and adds to the room map
         val room = rooms.get("1234", RoomOptions())
@@ -185,24 +185,24 @@ class RoomGetTest {
 
         // Room is in releasing state, hence RoomReleaseDeferred contain deferred for given roomId
         assertWaiter { originalRoom.status == RoomStatus.Releasing }
-        Assert.assertEquals(1, rooms.RoomReleaseDeferred.size)
-        Assert.assertNotNull(rooms.RoomReleaseDeferred[roomId])
+        Assert.assertEquals(1, rooms.RoomReleaseDeferredMap.size)
+        Assert.assertNotNull(rooms.RoomReleaseDeferredMap[roomId])
 
         // CHA-RC1f5 - Room Get is in waiting state, for room to get released
-        assertWaiter { rooms.RoomGetDeferred.size == 1 }
-        Assert.assertEquals(1, rooms.RoomGetDeferred.size)
-        Assert.assertNotNull(rooms.RoomGetDeferred[roomId])
+        assertWaiter { rooms.RoomGetDeferredMap.size == 1 }
+        Assert.assertEquals(1, rooms.RoomGetDeferredMap.size)
+        Assert.assertNotNull(rooms.RoomGetDeferredMap[roomId])
 
         // Release the room, room release deferred gets empty
         roomReleased.send(Unit)
         assertWaiter { originalRoom.status == RoomStatus.Released }
-        assertWaiter { rooms.RoomReleaseDeferred.isEmpty() }
-        Assert.assertNull(rooms.RoomReleaseDeferred[roomId])
+        assertWaiter { rooms.RoomReleaseDeferredMap.isEmpty() }
+        Assert.assertNull(rooms.RoomReleaseDeferredMap[roomId])
 
         // Room Get in waiting state gets cleared, so it's map for the same is cleared
-        assertWaiter { rooms.RoomGetDeferred.isEmpty() }
-        Assert.assertEquals(0, rooms.RoomGetDeferred.size)
-        Assert.assertNull(rooms.RoomGetDeferred[roomId])
+        assertWaiter { rooms.RoomGetDeferredMap.isEmpty() }
+        Assert.assertEquals(0, rooms.RoomGetDeferredMap.size)
+        Assert.assertNull(rooms.RoomGetDeferredMap[roomId])
 
         val newRoom = roomGetDeferred.await()
         roomReleaseDeferred.join()

chat-android/src/test/java/com/ably/chat/room/RoomReleaseTest.kt

@@ -114,15 +114,15 @@ class RoomReleaseTest {
 
         // No room exists
         Assert.assertEquals(0, rooms.RoomIdToRoom.size)
-        Assert.assertEquals(0, rooms.RoomReleaseDeferred.size)
-        Assert.assertEquals(0, rooms.RoomGetDeferred.size)
+        Assert.assertEquals(0, rooms.RoomReleaseDeferredMap.size)
+        Assert.assertEquals(0, rooms.RoomGetDeferredMap.size)
 
         // Release the room
         rooms.release(roomId)
 
         Assert.assertEquals(0, rooms.RoomIdToRoom.size)
-        Assert.assertEquals(0, rooms.RoomReleaseDeferred.size)
-        Assert.assertEquals(0, rooms.RoomGetDeferred.size)
+        Assert.assertEquals(0, rooms.RoomReleaseDeferredMap.size)
+        Assert.assertEquals(0, rooms.RoomGetDeferredMap.size)
     }
 
     @Test
@@ -164,15 +164,15 @@ class RoomReleaseTest {
 
         // Wait for room to get into releasing state
         assertWaiter { room.status == RoomStatus.Releasing }
-        Assert.assertEquals(1, rooms.RoomReleaseDeferred.size)
-        Assert.assertNotNull(rooms.RoomReleaseDeferred[roomId])
+        Assert.assertEquals(1, rooms.RoomReleaseDeferredMap.size)
+        Assert.assertNotNull(rooms.RoomReleaseDeferredMap[roomId])
 
         // Release the room, room release deferred gets empty
         roomReleased.send(Unit)
         releasedDeferredList.awaitAll()
         Assert.assertEquals(RoomStatus.Released, room.status)
 
-        Assert.assertTrue(rooms.RoomReleaseDeferred.isEmpty())
+        Assert.assertTrue(rooms.RoomReleaseDeferredMap.isEmpty())
         Assert.assertTrue(rooms.RoomIdToRoom.isEmpty())
 
         coVerify(exactly = 1) {
@@ -223,8 +223,8 @@ class RoomReleaseTest {
 
         // Room is in releasing state, hence RoomReleaseDeferred contain deferred for given roomId
         assertWaiter { originalRoom.status == RoomStatus.Releasing }
-        Assert.assertEquals(1, rooms.RoomReleaseDeferred.size)
-        Assert.assertNotNull(rooms.RoomReleaseDeferred[roomId])
+        Assert.assertEquals(1, rooms.RoomReleaseDeferredMap.size)
+        Assert.assertNotNull(rooms.RoomReleaseDeferredMap[roomId])
 
         // Call roomGet Dispatchers.IO scope, it should wait for release op
         val roomGetDeferredList = mutableListOf<Deferred<Room>>()
@@ -235,32 +235,32 @@ class RoomReleaseTest {
             roomGetDeferredList.add(roomGetDeferred)
         }
         // CHA-RC1f5 - Room Get is in waiting state, for room to get released
-        assertWaiter { rooms.RoomGetDeferred.size == 1 }
-        Assert.assertNotNull(rooms.RoomGetDeferred[roomId])
+        assertWaiter { rooms.RoomGetDeferredMap.size == 1 }
+        Assert.assertNotNull(rooms.RoomGetDeferredMap[roomId])
 
         // Call the release again, so that all pending roomGet gets cancelled
         val roomReleaseDeferred = launch { rooms.release(roomId) }
 
         // All RoomGetDeferred got cancelled due to room release.
-        assertWaiter { rooms.RoomGetDeferred.isEmpty() }
+        assertWaiter { rooms.RoomGetDeferredMap.isEmpty() }
 
         // Call RoomGet after release, so this should return a new room when room is released
         val roomGetDeferred = async { rooms.get(roomId) }
 
         // CHA-RC1f5 - Room Get is in waiting state, for room to get released
-        assertWaiter { rooms.RoomGetDeferred.size == 1 }
-        Assert.assertNotNull(rooms.RoomGetDeferred[roomId])
+        assertWaiter { rooms.RoomGetDeferredMap.size == 1 }
+        Assert.assertNotNull(rooms.RoomGetDeferredMap[roomId])
 
         // Release the room, room release deferred gets empty
         roomReleased.send(Unit)
         assertWaiter { originalRoom.status == RoomStatus.Released }
-        assertWaiter { rooms.RoomReleaseDeferred.isEmpty() }
-        Assert.assertNull(rooms.RoomReleaseDeferred[roomId])
+        assertWaiter { rooms.RoomReleaseDeferredMap.isEmpty() }
+        Assert.assertNull(rooms.RoomReleaseDeferredMap[roomId])
 
         // Room Get in waiting state gets cleared, so it's map for the same is cleared
-        assertWaiter { rooms.RoomGetDeferred.isEmpty() }
-        Assert.assertEquals(0, rooms.RoomGetDeferred.size)
-        Assert.assertNull(rooms.RoomGetDeferred[roomId])
+        assertWaiter { rooms.RoomGetDeferredMap.isEmpty() }
+        Assert.assertEquals(0, rooms.RoomGetDeferredMap.size)
+        Assert.assertNull(rooms.RoomGetDeferredMap[roomId])
 
         roomReleaseDeferred.join()
 

chat-android/src/test/java/com/ably/chat/room/RoomTestHelpers.kt

@@ -66,8 +66,8 @@ internal fun createMockRoom(
 
 // Rooms mocks
 val Rooms.RoomIdToRoom get() = getPrivateField<MutableMap<String, Room>>("roomIdToRoom")
-val Rooms.RoomGetDeferred get() = getPrivateField<MutableMap<String, CompletableDeferred<Unit>>>("roomGetDeferred")
-val Rooms.RoomReleaseDeferred get() = getPrivateField<MutableMap<String, CompletableDeferred<Unit>>>("roomReleaseDeferred")
+val Rooms.RoomGetDeferredMap get() = getPrivateField<MutableMap<String, CompletableDeferred<Unit>>>("roomGetDeferredMap")
+val Rooms.RoomReleaseDeferredMap get() = getPrivateField<MutableMap<String, CompletableDeferred<Unit>>>("roomReleaseDeferredMap")
 
 // Room mocks
 internal val Room.StatusLifecycle get() = getPrivateField<DefaultRoomLifecycle>("statusLifecycle")