Merge pull request #8635 from Expensify/marcaaron-fixCustomAuthorizer

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

package.json

@@ -71,7 +71,7 @@
     "moment-timezone": "^0.5.31",
     "onfido-sdk-ui": "^6.15.2",
     "prop-types": "^15.7.2",
-    "pusher-js": "^7.0.0",
+    "pusher-js": "^7.0.6",
     "react": "^17.0.2",
     "react-collapse": "^5.1.0",
     "react-dom": "^17.0.2",

src/CONST.js

@@ -323,6 +323,8 @@ const CONST = {
         REQUEST_CANCELLED: 'AbortError',
         FAILED_TO_FETCH: 'Failed to fetch',
         ENSURE_BUGBOT: 'ENSURE_BUGBOT',
+        PUSHER_ERROR: 'PusherError',
+        WEB_SOCKET_ERROR: 'WebSocketError',
         NETWORK_REQUEST_FAILED: 'Network request failed',
         SAFARI_DOCUMENT_LOAD_ABORTED: 'cancelled',
         FIREFOX_DOCUMENT_LOAD_ABORTED: 'NetworkError when attempting to fetch resource.',

src/libs/Pusher/pusher.js

@@ -214,15 +214,15 @@ function subscribe(
                 onResubscribe();
             });
 
-            channel.bind('pusher:subscription_error', (status) => {
-                if (status === 403) {
-                    Log.hmmm('[Pusher] Issue authenticating with Pusher during subscribe attempt.', {
-                        channelName,
-                        status,
-                    });
-                }
-
-                reject(status);
+            channel.bind('pusher:subscription_error', (data = {}) => {
+                const {type, error, status} = data;
+                Log.hmmm('[Pusher] Issue authenticating with Pusher during subscribe attempt.', {
+                    channelName,
+                    status,
+                    type,
+                    error,
+                });
+                reject(error);
             });
         } else {
             bindEventToChannel(channel, eventName, eventCallback, isChunked);

src/libs/PusherConnectionManager.js

@@ -1,6 +1,8 @@
+import lodashGet from 'lodash/get';
 import * as Pusher from './Pusher/pusher';
 import * as Session from './actions/Session';
 import Log from './Log';
+import CONST from '../CONST';
 
 function init() {
     /**
@@ -16,24 +18,37 @@ 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.
-     *
      * @params {string} eventName
      */
-    Pusher.registerSocketEventCallback((eventName, data) => {
+    Pusher.registerSocketEventCallback((eventName, error) => {
         switch (eventName) {
-            case 'error':
-                Log.info('[PusherConnectionManager] error event', false, {error: data});
-                Session.reauthenticatePusher();
+            case 'error': {
+                const errorType = lodashGet(error, 'type');
+                const code = lodashGet(error, 'data.code');
+                if (errorType === CONST.ERROR.PUSHER_ERROR && code === 1006) {
+                    // 1006 code happens when a websocket connection is closed. There may or may not be a reason attached indicating why the connection was closed.
+                    // https://datatracker.ietf.org/doc/html/rfc6455#section-7.1.5
+                    Log.hmmm('[PusherConnectionManager] Channels Error 1006', {error});
+                } else if (errorType === CONST.ERROR.PUSHER_ERROR && code === 4201) {
+                    // This means the connection was closed because Pusher did not recieve a reply from the client when it pinged them for a response
+                    // https://pusher.com/docs/channels/library_auth_reference/pusher-websockets-protocol/#4200-4299
+                    Log.hmmm('[PusherConnectionManager] Pong reply not received', {error});
+                } else if (errorType === CONST.ERROR.WEB_SOCKET_ERROR) {
+                    // It's not clear why some errors are wrapped in a WebSocketError type - this error could mean different things depending on the contents.
+                    Log.hmmm('[PusherConnectionManager] WebSocketError', {error});
+                } else {
+                    Log.alert(`${CONST.ERROR.ENSURE_BUGBOT} [PusherConnectionManager] Unknown error event`, {error});
+                }
                 break;
+            }
             case 'connected':
                 Log.info('[PusherConnectionManager] connected event');
                 break;
             case 'disconnected':
                 Log.info('[PusherConnectionManager] disconnected event');
                 break;
             default:
+                Log.info('[PusherConnectionManager] unhandled event', false, {eventName});
                 break;
         }
     });

src/libs/actions/Report.js

@@ -755,7 +755,7 @@ function subscribeToPrivateUserChannelEvent(eventName, onEvent, isChunked = fals
      * @param {*} error
      */
     function onSubscriptionFailed(error) {
-        Log.info('[Report] Failed to subscribe to Pusher channel', false, {error, pusherChannelName, eventName});
+        Log.hmmm('[Report] Failed to subscribe to Pusher channel', false, {error, pusherChannelName, eventName});
     }
 
     Pusher.subscribe(pusherChannelName, eventName, onEventPush, isChunked, onPusherResubscribeToPrivateUserChannel)
@@ -883,7 +883,7 @@ function subscribeToReportTypingEvents(reportID) {
         }, 1500);
     })
         .catch((error) => {
-            Log.info('[Report] Failed to initially subscribe to Pusher channel', false, {error, pusherChannelName});
+            Log.hmmm('[Report] Failed to initially subscribe to Pusher channel', false, {errorType: error.type, pusherChannelName});
         });
 }
 

src/libs/actions/Session/index.js

@@ -434,38 +434,40 @@ const reauthenticatePusher = _.throttle(() => {
  * @param {Function} callback
  */
 function authenticatePusher(socketID, channelName, callback) {
-    Log.info('[PusherConnectionManager] Attempting to authorize Pusher', false, {channelName});
+    Log.info('[PusherAuthorizer] Attempting to authorize Pusher', false, {channelName});
 
     API.Push_Authenticate({
         socket_id: socketID,
         channel_name: channelName,
         shouldRetry: false,
         forceNetworkRequest: true,
     })
-        .then((data) => {
-            if (data.jsonCode === CONST.JSON_CODE.NOT_AUTHENTICATED) {
-                callback(new Error('Expensify session expired'), {auth: ''});
+        .then((response) => {
+            if (response.jsonCode === CONST.JSON_CODE.NOT_AUTHENTICATED) {
+                Log.hmmm('[PusherAuthorizer] Unable to authenticate Pusher because authToken is expired');
+                callback(new Error('Pusher failed to authenticate because authToken is expired'), {auth: ''});
 
                 // Attempt to refresh the authToken then reconnect to Pusher
                 reauthenticatePusher();
                 return;
             }
 
-            if (data.jsonCode !== CONST.JSON_CODE.SUCCESS) {
-                Log.hmmm('[PusherConnectionManager] Unable to authenticate Pusher for some reason other than expired session');
+            if (response.jsonCode !== CONST.JSON_CODE.SUCCESS) {
+                Log.hmmm('[PusherAuthorizer] Unable to authenticate Pusher for reason other than expired session');
+                callback(new Error(`Pusher failed to authenticate because code: ${response.jsonCode} message: ${response.message}`), {auth: ''});
                 return;
             }
 
             Log.info(
-                '[PusherConnectionManager] Pusher authenticated successfully',
+                '[PusherAuthorizer] Pusher authenticated successfully',
                 false,
                 {channelName},
             );
-            callback(null, data);
+            callback(null, response);
         })
         .catch((error) => {
-            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: ''});
         });
 }
 

src/libs/actions/User.js

@@ -305,7 +305,7 @@ function subscribeToUserEvents() {
         NetworkConnection.triggerReconnectionCallbacks('pusher re-subscribed to private user channel');
     })
         .catch((error) => {
-            Log.info(
+            Log.hmmm(
                 '[User] Failed to subscribe to Pusher channel',
                 false,
                 {error, pusherChannelName, eventName: Pusher.TYPE.PREFERRED_LOCALE},
@@ -318,7 +318,14 @@ function subscribeToUserEvents() {
     }, false,
     () => {
         NetworkConnection.triggerReconnectionCallbacks('pusher re-subscribed to private user channel');
-    });
+    })
+        .catch((error) => {
+            Log.hmmm(
+                '[User] Failed to subscribe to Pusher channel',
+                false,
+                {error, pusherChannelName, eventName: Pusher.TYPE.SCREEN_SHARE_REQUEST},
+            );
+        });
 }
 
 /**