Firebase Realtime Database onDisconnect - Very unexpected results.

[Brian McBride]

Looking for some help if anyone knows here:

I was following a "last connected" pattern from the Firebase docs. Here are the key lines:

lastOnlineRef = firebase.database().ref('users/'+user.uid+'/lastOnline');

lastOnlineRef.onDisconnect().set(firebase.database.ServerValue.TIMESTAMP);

Trying to keep it really crazy simple there.

Ok, here is the deal. Say my UID is J4Cv32nls3g9JEmL7jr5EcLER0G2 and this reflects correctly in logging. If I call lastOnlineRef.set(true) I get exactly what I expect: a true value set for the path: users/J4Cv32nls3g9JEmL7jr5EcLER0G2/lastOnline

Here is the crazy part. With that exact UID up there, the path that onDisconnect().set() saved was: users/6w69C1iNEHM6wzRuSAZOzWjTXYD2/lastOnline

So, the path that onDisconnect returned is a TOTALLY different user path?! When I set the reference above, it is a string.

users/J4Cv32nls3g9JEmL7jr5EcLER0G2/lastOnline < Real user id/path

users/6w69C1iNEHM6wzRuSAZOzWjTXYD2/lastOnline < Path where the onDisconnect().set() saved data to

Last, if I change the start code to look like:

lastOnlineRef = firebase.database().ref('users/TEST/lastOnline');

lastOnlineRef.onDisconnect().set(firebase.database.ServerValue.TIMESTAMP);

That actually works just as expected!

What in the world?!

It seems like the lastOnlineRef.onDisconnect() reference somehow freaks out when I'm using a valid UID. That UID number gets changed in the path....

[Tyler Rockwood]

Hey Brian,

I suggest turning on debug logging and see what values are actually getting sent to the server. If the server is being sent the correct value, then please reach out to support.

-tyler

[Brian McBride]

Tyler, 

I should have thought to get that generated. Here are my findings...

The running code, the user variable is pulled from within the onAuthStateChanged callback.

firebase.auth().onAuthStateChanged((user: firebase.User) => {

  if (user) {

    const lastOnlinePath = `users/${user.uid}/lastOnline`;

    lastOnlineRef = firebase.database().ref(lastOnlinePath);

    const connectedRef = firebase.database().ref('.info/connected');

    connectedRef.on('value', (snap) => {

        if (snap && snap.val() === true) {

          lastOnlineRef.onDisconnect().set(firebase.database.ServerValue.TIMESTAMP)

        }

      }

  }

}

The actual log:

[2018-09-24T22:49:13.860Z]  @firebase/database: p:0: reportStats {"c":{"sdk.node.5-5-0":1}} 

[2018-09-24T22:49:13.861Z]  @firebase/database: p:0: {"r":1,"a":"s","b":{"c":{"sdk.node.5-5-0":1}}}

[2018-09-24T22:49:13.862Z]  @firebase/database: event: /.info/connected:value:true

[2018-09-24T22:49:13.863Z]  @firebase/database: p:0: onDisconnect o {"p":"/users/Rodpwg0ZliSMin4ussiLOz7oRUs1/lastOnline","d":{".sv":"timestamp"}}

[2018-09-24T22:49:13.864Z]  @firebase/database: p:0: {"r":2,"a":"o","b":{"p":"/users/Rodpwg0ZliSMin4ussiLOz7oRUs1/lastOnline","d":{".sv":"timestamp"}}}

[2018-09-24T22:49:13.923Z]  @firebase/database: p:0: from server: {"r":1,"b":{"s":"ok","d":""}}

[2018-09-24T22:49:13.928Z]  @firebase/database: c:0:0: Primary connection is healthy.

[2018-09-24T22:49:13.928Z]  @firebase/database: p:0: from server: {"r":2,"b":{"s":"ok","d":""}}

[2018-09-24T22:49:14.736Z]  @firebase/database: p:0: onDisconnect o {"p":"/users/Rodpwg0ZliSMin4ussiLOz7oRUs1/lastOnline","d":{".sv":"timestamp"}} 

[2018-09-24T22:49:14.736Z]  @firebase/database: p:0: {"r":4,"a":"o","b":{"p":"/users/Rodpwg0ZliSMin4ussiLOz7oRUs1/lastOnline","d":{".sv":"timestamp"}}}

Pretty simple code. My last unit test had this:

user.uid == Rodpwg0ZliSMin4ussiLOz7oRUs1

So far, all this looks good. However, when I run the code above as part of my unit tests, which consists of create a user, sign out, try to sign in with bad password (expect fail) and sign in with same previous user. I trimmed down the logs to the relevant ones. 

In my realtime database, this is the path and value set:

/users/YVZ2q2pd8uZh7NqGZpsJeNiRZfn1/lastOnline

Also, if I were to replace the above code:
 lastOnlineRef.onDisconnect().set(firebase.database.ServerValue.TIMESTAMP) 

with: 

lastOnlineRef.set(firebase.database.ServerValue.TIMESTAMP) 

that writes exactly to the expected path.

So, yeah... I'm baffled and I wouldn't be surprised if I'm missing some nuance though. Remember, if I use a path OTHER than the current user.uid then it writes exactly where expected on that onDisconnect :/

[Brian McBride]

Ruh roh... 

Right. My unit tests are built around testing 

1. User Creation
   
2. User Logout
   
3. Bad Password.
   
4. User Login
   

The onDisconnect() is writing to the PREVIOUS user I had logged into. This is even a bit more confusing, because I'm using JEST as my testing framework and this is the Node Client SDK. 

To be clear: 
1. I create a new user. Let's say UID = 5. I have created 4 previous users in previous tests.

2. I sign out.

3. onDisconnect LOGS that it is writing to /users/5/lastOnline

4. onDisconnect ACTUALLY writes to /users/4/lastOnline

5. I log into the account again.

6. I sign out again. 

7. onDisconnect LOGS that it is writing to /users/5/lastOnline

8. onDisconnect ACTUALLY writes to /users/4/lastOnline

I'm going to guess that somewhere, the on disconnect is saving something in some cache layer that my JEST environment is keeping around. This is part of a ReactJS app, so it's using jsdom. Maybe something in localstorage is being pulled? 

My console.log() shows correct UID. A correct path in reference and the logs all match. So how the onDisconnect is pulling from the previous path, I'm not sure. But I'd call this an error in the NodeJS Client SDK. 

Sorry for all the load of information. I'll search around for any other people having issues with onDisconnect and jest + jsdom. Hopefully someone smarter than me will know what is going on. 

[Brian McBride]

Here are the unexpected results that I ran across. 

I think the short answer might be to force a firebase.database().goOffline() in unit tests. Maybe with a goOnline() with a brief delay in there.

Here is a repo with a unit test that can be run over and over. Note, I build this in Node 10.

https://github.com/Brian-McBride/firebase-onDisconnect-issue

Instrucitons:

Clone repo

Enter your firebase credentials in index.test.js

run:  npm install

run:  npm run test

Check your realtime database. You should have an entry /examine/~UID~/hasLoggedIn == true

However, there is no lastOnline entry.

again, run:  npm run test

Now, the first user will finally have an onDisconnect() entry, and there will be a new user without one. 

again, run:  npm run test

The pattern repeats. The previous test entry onDisconnect() event fires.

The problem I have with this is that it indicates that onDisconnect isn't something that is queued up on the server side. But rather is stashed in the client. That means that if a user drops networking connection, onDisconnect() doesn't actually change the database until the user comes back online some time later. I was assuming that the onDisconnect was taking the parameters from the call and stashing them into a serverside event listener on the websocket drop. 

Maybe I'm doing it wrong. 

Is there a way - server side - to reliably monitor if a user is suddenly dropped from the network and take action on?