connect callback not called when listeners are added.

[narsi-mindoula]

The connect works fine without the listeners. But once I uncomment the below code for listeners, the connect callback is never called. I tried to debug SDK code little bit, once the debugger reaches userSubscription.await() it doens't go to next step. The same works fine if there are no listeners and goes to next line and proceeds with rest of code.

        ckManager.connect(
//            listeners = ChatListeners(
//                onAddedToRoom = {room -> onCurrentUserAddedToRoom(room)}
//            ),
            callback = { result ->
                when (result) {
                    is Result.Success -> {
                        ckCurrentUser = result.value
                        ckCurrentUser.enablePushNotifications { result ->
                            when (result) {
                                is Result.Success -> {
                                    Log.d("Push Notifications", "Registered successfully")
                                }
                                is Error -> Log.e("Error", "Error starting Push Notifications")
                            }
                        }
                    }
                    is Result.Failure -> {
                        Log.d("Connection", "Can't connect to chatkit" + result.error)
                    }
                }
            }
        )

[mdpye]

Hi @narsi-mindoula. I've added a test for what you describe, but I'm not able to replicate, my callback is fired. (https://github.com/pusher/chatkit-android/commit/3bc9173c96c1713b61e5f528b86450b0a50e1761)

Can you share anything about what your listener does? Perhaps it is somehow interacting with the Chatkit SDK again in a way which is causing the lockup.

Also, the SDK emits quite detailed logs at debug and verbose levels, if you provide a logger. They would be very helpful in debugging.

[narsi-mindoula]

@mdpye This is what the listener method supposed to (subscribe to that new room):

    private fun subscribeToRoom(room: Room) {
        ckCurrentUser.subscribeToRoom(
                room = room,
                consumer = { roomEvent: RoomEvent ->
                    when (roomEvent) {
                        is RoomEvent.Message -> {
                            onMessage(room.id, roomEvent.message)
                        }
                        is RoomEvent.UserStartedTyping -> {
                            onUserTyping(room.id, roomEvent.user, true)
                        }
                        is RoomEvent.UserStoppedTyping -> {
                            onUserTyping(room.id, roomEvent.user, false)
                        }
                        is RoomEvent.NewReadCursor -> {
                            onNewReadCursor(room.id, roomEvent.cursor)
                        }
                        is RoomEvent.InitialReadCursors -> {
                            onInitialReadCursor(roomEvent.cursor)
                        }
                        is RoomEvent.PresenceChange -> {
                            onPresenceChanged(room.id, roomEvent.user, roomEvent.currentState)
                        }
                    }
                },
                callback = { subscription ->
                    subscriptionStore.add(subscription)
                },
                messageLimit = 20
        )
    }

But whatever happens inside method will be executed only when the new room gets added, so I am not sure it would have any implications for connecting.

[mdpye]

That is true, though I have a ticket I'm coming to soon which will ensure that no listeners are invoked until the connect callback is hit. Until I do that I have some concerns about the listener being invoked during connection (say, when the initial set of rooms arrives).

Given that I can't replicate it, the debug+verbose log output from your app would be really useful, or a minimal reproduction case.

[narsi-mindoula]

@mdpye Ok, that makes sense.

here is the some log output (without listeners enabled):

D/pusherPlatform: [Subscription User ESWubp7Q9DymvNkP6rLn] Opened
D/pusherPlatform: [Subscription Cursor /cursors/0/users/ESWubp7Q9DymvNkP6rLn] Opened
D/pusherPlatform: [Subscription User ESWubp7Q9DymvNkP6rLn] Received event: InitialState(rooms=[Room(id=19695496, createdById=zDE5xfjnu1C2dGVNCmcB, name=mpce_704, isPrivate=true, customData={care_extenders=[zDE5xfjnu1C2dGVNCmcB], member=ESWubp7Q9DymvNkP6rLn}, createdAt=2019-01-27T04:39:06Z, updatedAt=2019-01-27T04:39:06Z, deletedAt=null), Room(id=19695754, createdById=JfwA_xsM5HtwLZ2maKW4, name=mpce_7026, isPrivate=true, customData={care_extenders=[JfwA_xsM5HtwLZ2maKW4], member=ESWubp7Q9DymvNkP6rLn}, createdAt=2019-01-27T05:48:09Z, updatedAt=2019-01-27T05:48:09Z, deletedAt=null), Room(id=19704716, createdById=VTRgzZJyT2XTjSPxi2xC, name=mpce_701, isPrivate=true, customData={care_extenders=[VTRgzZJyT2XTjSPxi2xC], member=ESWubp7Q9DymvNkP6rLn}, createdAt=2019-01-29T08:52:47Z, updatedAt=2019-01-29T08:52:47Z, deletedAt=null)], currentUser=User(id=ESWubp7Q9DymvNkP6rLn, createdAt=2019-01-02T16:54:23Z, updatedAt=2019-01-02T16:54:23Z, name=alva, avatarURL=null, customData=null, online=false))
D/pusherPlatform: [Subscription Cursor /cursors/0/users/ESWubp7Q9DymvNkP6rLn] Received event: InitialState(cursors=[Cursor(userId=ESWubp7Q9DymvNkP6rLn, roomId=19695496, position=4472031, updatedAt=2019-01-29T11:16:26Z, type=0), Cursor(userId=ESWubp7Q9DymvNkP6rLn, roomId=19695754, position=4466499, updatedAt=2019-01-29T11:32:18Z, type=0), Cursor(userId=ESWubp7Q9DymvNkP6rLn, roomId=19704716, position=4474164, updatedAt=2019-01-29T11:16:44Z, type=0)])
D/pusherPlatform: [Subscription Room 19695496] Opened
D/pusherPlatform: [Subscription Room 19704716] Opened
D/pusherPlatform: [Subscription Cursor /cursors/0/rooms/19704716] Opened
D/pusherPlatform: [Subscription Cursor /cursors/0/rooms/19695496] Opened
D/pusherPlatform: [Subscription Memberships room 19704716] Opened
D/pusherPlatform: [Subscription Memberships room 19695496] Opened
D/pusherPlatform: [Subscription Room 19695754] Opened
D/pusherPlatform: [Subscription Cursor /cursors/0/rooms/19695754] Opened
D/pusherPlatform: [Subscription Memberships room 19695754] Opened
D/pusherPlatform: [Subscription Memberships room 19704716] Received event: InitialState(userIds=[ESWubp7Q9DymvNkP6rLn, VTRgzZJyT2XTjSPxi2xC])
D/pusherPlatform: [Subscription Memberships room 19695496] Received event: InitialState(userIds=[ESWubp7Q9DymvNkP6rLn, zDE5xfjnu1C2dGVNCmcB])
D/pusherPlatform: [Subscription Memberships room 19695754] Received event: InitialState(userIds=[ESWubp7Q9DymvNkP6rLn, JfwA_xsM5HtwLZ2maKW4])
I/PushNotificationsInstance: PushNotifications device id: fcm-30a310a7-ce87-4d84-bc12-3346a369e2b5
I/firebase-iid-ex: type=1400 audit(0.0:1421): avc: denied { lock } for path="/data/data/com.mindoula.royals.staging/no_backup/com.google.InstanceId.properties" dev="sdb3" ino=89635 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:system_data_file:s0:c512,c768 tclass=file permissive=1
D/Push Notifications: Registered successfully
D/pusherPlatform: [Subscription Presence ESWubp7Q9DymvNkP6rLn] Opened
D/pusherPlatform: [Subscription Presence ESWubp7Q9DymvNkP6rLn] Received event: PresenceUpdate(presence=UserPresence(presence=com.pusher.chatkit.presence.Presence$Online@26e8dbb, userId=ESWubp7Q9DymvNkP6rLn))
D/pusherPlatform: [Subscription Presence VTRgzZJyT2XTjSPxi2xC] Opened
D/pusherPlatform: [Subscription Presence VTRgzZJyT2XTjSPxi2xC] Received event: PresenceUpdate(presence=UserPresence(presence=com.pusher.chatkit.presence.Presence$Offline@380c8a2, userId=VTRgzZJyT2XTjSPxi2xC))
D/pusherPlatform: [Subscription Presence JfwA_xsM5HtwLZ2maKW4] Opened
D/pusherPlatform: [Subscription Presence zDE5xfjnu1C2dGVNCmcB] Opened
D/pusherPlatform: [Subscription Presence JfwA_xsM5HtwLZ2maKW4] Received event: PresenceUpdate(presence=UserPresence(presence=com.pusher.chatkit.presence.Presence$Offline@380c8a2, userId=JfwA_xsM5HtwLZ2maKW4))
D/pusherPlatform: [Subscription Presence zDE5xfjnu1C2dGVNCmcB] Received event: PresenceUpdate(presence=UserPresence(presence=com.pusher.chatkit.presence.Presence$Offline@380c8a2, userId=zDE5xfjnu1C2dGVNCmcB))

Here is the log (when the listeners are enabled):

W/OpenGLRenderer: Failed to set EGL_SWAP_BEHAVIOR on surface 0xd4cee4c0, error=EGL_BAD_MATCH
D/pusherPlatform: [Subscription PresenceRegistration ESWubp7Q9DymvNkP6rLn] Opened
D/pusherPlatform: [Subscription User ESWubp7Q9DymvNkP6rLn] Opened
D/pusherPlatform: [Subscription Cursor /cursors/0/users/ESWubp7Q9DymvNkP6rLn] Opened
D/pusherPlatform: [Subscription Cursor /cursors/0/users/ESWubp7Q9DymvNkP6rLn] Received event: InitialState(cursors=[Cursor(userId=ESWubp7Q9DymvNkP6rLn, roomId=19695496, position=4472031, updatedAt=2019-01-29T11:16:26Z, type=0), Cursor(userId=ESWubp7Q9DymvNkP6rLn, roomId=19695754, position=4466499, updatedAt=2019-01-29T11:32:18Z, type=0), Cursor(userId=ESWubp7Q9DymvNkP6rLn, roomId=19704716, position=4474164, updatedAt=2019-01-29T11:16:44Z, type=0)])
D/pusherPlatform: [Subscription User ESWubp7Q9DymvNkP6rLn] Received event: InitialState(rooms=[Room(id=19695496, createdById=zDE5xfjnu1C2dGVNCmcB, name=mpce_704, isPrivate=true, customData={care_extenders=[zDE5xfjnu1C2dGVNCmcB], member=ESWubp7Q9DymvNkP6rLn}, createdAt=2019-01-27T04:39:06Z, updatedAt=2019-01-27T04:39:06Z, deletedAt=null), Room(id=19695754, createdById=JfwA_xsM5HtwLZ2maKW4, name=mpce_7026, isPrivate=true, customData={care_extenders=[JfwA_xsM5HtwLZ2maKW4], member=ESWubp7Q9DymvNkP6rLn}, createdAt=2019-01-27T05:48:09Z, updatedAt=2019-01-27T05:48:09Z, deletedAt=null), Room(id=19704716, createdById=VTRgzZJyT2XTjSPxi2xC, name=mpce_701, isPrivate=true, customData={care_extenders=[VTRgzZJyT2XTjSPxi2xC], member=ESWubp7Q9DymvNkP6rLn}, createdAt=2019-01-29T08:52:47Z, updatedAt=2019-01-29T08:52:47Z, deletedAt=null)], currentUser=User(id=ESWubp7Q9DymvNkP6rLn, createdAt=2019-01-02T16:54:23Z, updatedAt=2019-01-02T16:54:23Z, name=alva, avatarURL=null, customData=null, online=false))
I/fifo-pool-threa: type=1400 audit(0.0:1595): avc: denied { append } for name="journal" dev="sdb3" ino=89692 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:system_data_file:s0:c512,c768 tclass=file permissive=1
I/zygote: Do partial code cache collection, code=248KB, data=162KB
I/zygote: After code cache collection, code=248KB, data=162KB
    Increasing code cache capacity to 1024KB

[mdpye]

OK. If you alter your listener to read something like...

           listeners = ChatListeners(
               onAddedToRoom = { room ->
                   logger.info("Added to room")
                   onCurrentUserAddedToRoom(room)
               }
           ),

...I presume you will see the listener being invoked before connection is complete? That would give me enough to work with. Like I said, I believe this bug is basically next on my list already, but a test case in the wild is useful, it makes it much less of a theoretical problem.

[narsi-mindoula]

Ok, here is output with changes you suggested to listener:

D/pusherPlatform: [Subscription User ESWubp7Q9DymvNkP6rLn] Opened
D/pusherPlatform: [Subscription Cursor /cursors/0/users/ESWubp7Q9DymvNkP6rLn] Opened
D/pusherPlatform: [Subscription PresenceRegistration ESWubp7Q9DymvNkP6rLn] Opened
D/pusherPlatform: [Subscription Cursor /cursors/0/users/ESWubp7Q9DymvNkP6rLn] Received event: InitialState(cursors=[Cursor(userId=ESWubp7Q9DymvNkP6rLn, roomId=19695496, position=4472031, updatedAt=2019-01-29T11:16:26Z, type=0), Cursor(userId=ESWubp7Q9DymvNkP6rLn, roomId=19695754, position=4466499, updatedAt=2019-01-29T11:32:18Z, type=0), Cursor(userId=ESWubp7Q9DymvNkP6rLn, roomId=19704716, position=4474164, updatedAt=2019-01-29T11:16:44Z, type=0)])
D/pusherPlatform: [Subscription User ESWubp7Q9DymvNkP6rLn] Received event: InitialState(rooms=[Room(id=19695496, createdById=zDE5xfjnu1C2dGVNCmcB, name=mpce_704, isPrivate=true, customData={care_extenders=[zDE5xfjnu1C2dGVNCmcB], member=ESWubp7Q9DymvNkP6rLn}, createdAt=2019-01-27T04:39:06Z, updatedAt=2019-01-27T04:39:06Z, deletedAt=null), Room(id=19695754, createdById=JfwA_xsM5HtwLZ2maKW4, name=mpce_7026, isPrivate=true, customData={care_extenders=[JfwA_xsM5HtwLZ2maKW4], member=ESWubp7Q9DymvNkP6rLn}, createdAt=2019-01-27T05:48:09Z, updatedAt=2019-01-27T05:48:09Z, deletedAt=null), Room(id=19704716, createdById=VTRgzZJyT2XTjSPxi2xC, name=mpce_701, isPrivate=true, customData={care_extenders=[VTRgzZJyT2XTjSPxi2xC], member=ESWubp7Q9DymvNkP6rLn}, createdAt=2019-01-29T08:52:47Z, updatedAt=2019-01-29T08:52:47Z, deletedAt=null)], currentUser=User(id=ESWubp7Q9DymvNkP6rLn, createdAt=2019-01-02T16:54:23Z, updatedAt=2019-01-02T16:54:23Z, name=alva, avatarURL=null, customData=null, online=false))
I/Chatkit Listener: Added to room
I/fifo-pool-threa: type=1400 audit(0.0:1753): avc: denied { append } for name="journal" dev="sdb3" ino=89692 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:system_data_file:s0:c512,c768 tclass=file permissive=1
I/zygote: Do partial code cache collection, code=248KB, data=164KB
I/zygote: After code cache collection, code=248KB, data=164KB
    Increasing code cache capacity to 1024KB

[narsi-mindoula]

@mdpye I debugged bit more and can confirm that listeners gets called before the connection.

Even if it gets called after the connection is established, is that intended behavior? Because we subscribe to all the rooms the user belongs when the user is returned. My understanding is that the listener gets called only when the new room gets added to the current user during the session.

[mdpye]

My understanding is that the listener gets called only when the new room gets added to the current user during the session.

You're correct, that is the intended behaviour. I'd already identified it as a bug, which is why it's next on my list. It's not a straightforward fix though, there are some architectural problems in the SDK which I'm working through.

But I am working towards it.

[narsi-mindoula]

@mdpye I understand it might not be straight forward, thanks for working on this. Any estimates on timelines for this fix?

I tried to see if I changed the code to process the listener only if the chatkit user is available, but even then the execution just halts once the listener is activated. Is there any workaround? Depending on when the fix will be out, I might have to plan for an alternative fix if one is available as we are planning to release this app soon.

[mdpye]

I'm working on it now, though I'm not deep enough to suggest when it might be done.

The first thing that occurs to me as I try to write a test to validate any fixes is that your code has probably entered an invalid state here!

You're trying to subscribe to a room using the CurrentUser object, before the connect callback is invoked. But that object is only provided to you in the callback of connect. Presumably then the variable you're invoking the method on is still null.

In which case, the reason for the lock-up, and the lack of visibility into the problem is that exceptions raised in your code aren't guarded against properly when I invoke your code from the SDK as callbacks.

I'll add catches so that the SDK internals can't be mangled by exceptions raised in callbacks I invoke, but the best I will be able to do with those exceptions is log them and carry on.

[mdpye]

To be clear - the SDK should not be firing the listener callbacks before connect resolves, that's our bug.

Having given the interface some thought, it's clear that each listener should receive a reference to the currentUser in addition to the other arguments describing the event, so that you can interact with the SDK in response to event without having to capture state from outside (which in this case, isn't even available at the time of defining the listeners).

I'm going to have a serious think about whether this is acheivable without making a breaking change to the interface. If not, it may still be worth it for the improved ergonomics.

This (and the bug leaking events before connection is complete) are my focus now. I'll keep you updated.

[mdpye]

In the spirit of an open source SDK, you can follow progress on #92.

I won't always push my work immediately, but it's there.

[narsi-mindoula]

@mdpye at least for now, I found the workaround. There was an exception in our code (because of the assumption that chatkit user is available at this time), but as you mentioned before they weren't guarded properly. Obviously your fix is still needed to make sure that those listeners are not invoked before the connection is established, but I am unblocked now. Thanks for your help so far. I will upgrade the SDK as soon as your fix is available.

[mdpye]

Hi. 1.1.1 release has been cut, which should help with these issues. There will always be a race between the callback and the first event, because your storing of the callback value happens on a different thread from your later access of it. The fix for that is the interface improvement I was suggesting to pass the current user object to all callbacks/listeners. But that will come later.

For now, we buffer events so that we won't emit them at least until all of the internal state that you might query from the SDK should be consistent, and we no longer fire hooks for the transition from the pre-connected to initial state (that was a bug which was causing your listener to be called early).