[No QA] Improve logging for Pusher `error` event. Avoid unnecessary reauthentication. Update Pusher. #8635

marcaaron · 2022-04-13T20:18:59Z

Details

Improve logging for Pusher
Stop triggering re-authentication when we handle a Pusher error event
Pusher error events are not related to authentication and trigger when there are issues with websockets

Fixed Issues

Tests

Sign into NewDot and grep JS logs for 'pusher'
Manually break your authToken somehow e.g.

diff --git a/src/libs/Network/NetworkStore.js b/src/libs/Network/NetworkStore.js
index c0973fa50..c1cb1ff96 100644
--- a/src/libs/Network/NetworkStore.js
+++ b/src/libs/Network/NetworkStore.js
@@ -11,6 +11,8 @@ let hasReadRequiredData = false;
 let isAuthenticating = false;
 let isOffline = false;

+window.borkToken = () => authToken = 'piza';
+
 /**
  * @param {Boolean} val
  */

Go offline by shutting wifi off and wait about 15-30 seconds
Turn wifi back on
Verify that the logs show and that we are successfully connected to Pusher and the channels

Verify that no errors appear in the JS console

PR Reviewer Checklist

QA Steps

No QA

Verify that no errors appear in the JS console

Screenshots

Web

Mobile Web

Desktop

iOS

Android

marcaaron · 2022-04-18T23:31:00Z

src/libs/Pusher/pusher.js

-
-                reject(status);
+            channel.bind('pusher:subscription_error', (data) => {
+                const {type, error, status} = data;


The signature of this error event has changed. Previously we were throwing an error that could be caught by any caller of Pusher.subscribe(). This can be an AuthError and then would get thrown with a reject(undefined). So, this change gives us a bit more information about what went wrong. I think for the most part this would be an AuthError (what would happen when the callback() in the custom authorizer returns an error).

marcaaron · 2022-04-18T23:33:28Z

src/libs/PusherConnectionManager.js

+                    Log.hmmm('[PusherConnectionManager] WebSocketError', {error});
+                } else {
+                    Log.alert(`${CONST.ERROR.ENSURE_BUGBOT} [PusherConnectionManager] Unknown error event`, {error});
+                }


I know this stuff is a little redundant, but I'm enumerating these and logging an alert so we can clearly document all the errors that can possibly happen.

Great addition

marcaaron · 2022-04-18T23:36:59Z

src/libs/actions/Session/index.js

-            Log.info('[PusherConnectionManager] Unhandled error: ', false, {channelName});
-            callback(error, {auth: ''});
+            Log.hmmm('[PusherAuthorizer] Unhandled error: ', {channelName, error});
+            callback(new Error('Push_Authenticate request failed'), {auth: ''});


I'm not re-throwing this error because the error that can show up in a catch doesn't really offer much information about why the request failed anyway. It could have:

run out of retries

server returned 403 Forbidden header (which we can't tell from the JS)

User doesn't have access to a report

Channel name isn't valid

etc...

marcaaron · 2022-04-18T23:37:50Z

src/libs/actions/User.js

@@ -318,7 +318,14 @@ function subscribeToUserEvents() {
    }, false,
    () => {
        NetworkConnection.triggerReconnectionCallbacks('pusher re-subscribed to private user channel');
-    });
+    })
+        .catch((error) => {


This needed a catch as it was causing an unhandled promise rejection.

marcaaron · 2022-04-19T00:03:14Z

src/libs/PusherConnectionManager.js

@@ -16,16 +17,20 @@ function init() {
    }));

    /**
-     * Events that happen on the pusher socket are used to determine if the app is online or offline.
-     * The offline setting is stored in Onyx so the rest of the app has access to it.
-     *


Removing this as it is not accurate. The events are not used to determine online/offline status.

techievivek · 2022-04-20T20:36:21Z

While testing this locally I can see that after disconnecting once I reconnect it doesn't throw any more error and the last command that it executes on server was Push_Authenticate. So I am thinking this is working as expected but I am not able to see the info logs on my console.

marcaaron · 2022-04-20T20:44:09Z

I am not able to see the info logs on my console.

Is Verbose level turned on in Chrome JS console?

techievivek

Ohh thanks, it works as expected now. For code, I think it will be better if someone else with experience writing code related to pusher can look into it because this is definitely a good upgrade over what we already had. As part of my review, it looked good to me.

marcaaron · 2022-04-20T21:34:57Z

For code, I think it will be better if someone else with experience writing code related to pusher can look into it because this is definitely a good upgrade over what we already had. As part of my review, it looked good to me.

Good call. I will ask for some help!

johnmlee101 · 2022-04-20T21:58:18Z

src/libs/PusherConnectionManager.js

        switch (eventName) {
            case 'error':
-                Log.info('[PusherConnectionManager] error event', false, {error: data});
-                Session.reauthenticatePusher();
+                if (error && error.type === 'PusherError' && error.data.code === 1006) {


NAB question, we are guaranteed to have the data field be present with code defined?

(given an error event name)

Ah good catch. I think it's probably unsafe to assume that.

johnmlee101 · 2022-04-20T21:59:13Z

src/libs/PusherConnectionManager.js

-                Session.reauthenticatePusher();
+                if (error && error.type === 'PusherError' && error.data.code === 1006) {
+                    Log.hmmm('[PusherConnectionManager] Channels Error 1006', {error});
+                } else if (error && error.type === 'PusherError' && error.data.code === 4201) {


Is there a place where these seemingly-arbituary integer error codes are referenced?

(aka could we add this as a comment to reference?)

Yeah, I think I can do that.

johnmlee101

Makes sense, just a few open questions

marcaaron · 2022-04-21T02:04:08Z

Updated 🙃

src/libs/PusherConnectionManager.js

marcaaron · 2022-04-22T16:22:40Z

Updated

Beamanator

Tested with your steps (borked the authToken, killed wifi ~ 20 seconds, reconnected) and saw successful pusher connection after 👍

OSBotify · 2022-04-23T00:29:57Z

✋ This PR was not deployed to staging yet because QA is ongoing. It will be automatically deployed to staging after the next production release.

OSBotify · 2022-04-25T23:42:16Z

🚀 Deployed to staging by @marcaaron in version: 1.1.57-0 🚀

platform	result
🤖 android 🤖	success ✅
🖥 desktop 🖥	success ✅
🍎 iOS 🍎	success ✅
🕸 web 🕸	success ✅

OSBotify · 2022-05-13T16:14:50Z

🚀 Deployed to production by @chiragsalian in version: 1.1.57-17 🚀

platform	result
🤖 android 🤖	success ✅
🖥 desktop 🖥	success ✅
🍎 iOS 🍎	success ✅
🕸 web 🕸	success ✅

Custom authorizer callback() is using wrong method signature

143beb9

marcaaron self-assigned this Apr 13, 2022

marcaaron added 3 commits April 18, 2022 11:13

Merge remote-tracking branch 'origin' into marcaaron-fixCustomAuthorizer

259668b

Stop re-authenticating when Pusher experiences an error event

8521d79

Update Pusher improve logging for error event

2e36cf8

marcaaron changed the title ~~[WIP] Fix Pusher Custom authorizer callback() using wrong method signature~~ [WIP] Improve logging for Pusher error event. Avoid unnecessary reauthentication. Apr 18, 2022

Update some callbacks to hmmm

c2d52ee

marcaaron changed the title ~~[WIP] Improve logging for Pusher error event. Avoid unnecessary reauthentication.~~ [No QA] Improve logging for Pusher error event. Avoid unnecessary reauthentication. Apr 18, 2022

marcaaron changed the title ~~[No QA] Improve logging for Pusher error event. Avoid unnecessary reauthentication.~~ [No QA] Improve logging for Pusher error event. Avoid unnecessary reauthentication. Update Pusher. Apr 18, 2022

marcaaron commented Apr 18, 2022

View reviewed changes

default to empty object here just in case...

5539e45

marcaaron commented Apr 18, 2022

View reviewed changes

marcaaron marked this pull request as ready for review April 18, 2022 23:38

marcaaron requested a review from a team as a code owner April 18, 2022 23:38

melvin-bot bot requested review from techievivek and removed request for a team April 18, 2022 23:38

marcaaron added 2 commits April 18, 2022 13:59

Remove comment that is inaccurate

7b541b5

Log events we maybe are not logging

f2ec123

marcaaron commented Apr 19, 2022

View reviewed changes

techievivek previously approved these changes Apr 20, 2022

View reviewed changes

johnmlee101 reviewed Apr 20, 2022

View reviewed changes

johnmlee101 previously approved these changes Apr 20, 2022

View reviewed changes

Add more comments

6196e5f

marcaaron dismissed johnmlee101’s stale review via 6196e5f April 20, 2022 22:29

marcaaron dismissed techievivek’s stale review via 6196e5f April 20, 2022 22:29

johnmlee101 previously approved these changes Apr 20, 2022

View reviewed changes

Fix conflicts

d781868

marcaaron dismissed johnmlee101’s stale review via d781868 April 20, 2022 23:11

Beamanator reviewed Apr 22, 2022

View reviewed changes

src/libs/PusherConnectionManager.js Outdated Show resolved Hide resolved

use curly braces

216cc74

Beamanator approved these changes Apr 22, 2022

View reviewed changes

marcaaron merged commit ad637d3 into main Apr 23, 2022

marcaaron deleted the marcaaron-fixCustomAuthorizer branch April 23, 2022 00:20

francoisl mentioned this pull request Apr 25, 2022

Deploy Checklist: New Expensify 2022-04-25 #8777

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[No QA] Improve logging for Pusher `error` event. Avoid unnecessary reauthentication. Update Pusher. #8635

[No QA] Improve logging for Pusher `error` event. Avoid unnecessary reauthentication. Update Pusher. #8635

marcaaron commented Apr 13, 2022 •

edited by techievivek

Loading

marcaaron Apr 18, 2022

marcaaron Apr 18, 2022

Julesssss Apr 21, 2022

marcaaron Apr 18, 2022

marcaaron Apr 18, 2022

marcaaron Apr 19, 2022

techievivek commented Apr 20, 2022

marcaaron commented Apr 20, 2022

techievivek left a comment

marcaaron commented Apr 20, 2022

johnmlee101 Apr 20, 2022

johnmlee101 Apr 20, 2022

marcaaron Apr 20, 2022

johnmlee101 Apr 20, 2022

johnmlee101 Apr 20, 2022

marcaaron Apr 20, 2022

johnmlee101 left a comment

marcaaron commented Apr 21, 2022

marcaaron commented Apr 22, 2022

Beamanator left a comment

OSBotify commented Apr 23, 2022

OSBotify commented Apr 25, 2022

OSBotify commented May 13, 2022

[No QA] Improve logging for Pusher error event. Avoid unnecessary reauthentication. Update Pusher. #8635

[No QA] Improve logging for Pusher error event. Avoid unnecessary reauthentication. Update Pusher. #8635

Conversation

marcaaron commented Apr 13, 2022 • edited by techievivek Loading

Details

Fixed Issues

Tests

PR Reviewer Checklist

QA Steps

Screenshots

Web

Mobile Web

Desktop

iOS

Android

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

techievivek commented Apr 20, 2022

marcaaron commented Apr 20, 2022

techievivek left a comment

Choose a reason for hiding this comment

marcaaron commented Apr 20, 2022

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

johnmlee101 left a comment

Choose a reason for hiding this comment

marcaaron commented Apr 21, 2022

marcaaron commented Apr 22, 2022

Beamanator left a comment

Choose a reason for hiding this comment

OSBotify commented Apr 23, 2022

OSBotify commented Apr 25, 2022

OSBotify commented May 13, 2022

[No QA] Improve logging for Pusher `error` event. Avoid unnecessary reauthentication. Update Pusher. #8635

[No QA] Improve logging for Pusher `error` event. Avoid unnecessary reauthentication. Update Pusher. #8635

marcaaron commented Apr 13, 2022 •

edited by techievivek

Loading