Merge pull request #4191 from Expensify/ionatan_improve_logs

Update expensify common with new logging methods and improve logging

package.json

@@ -60,7 +60,7 @@
     "electron-log": "^4.3.5",
     "electron-serve": "^1.0.0",
     "electron-updater": "^4.3.4",
-    "expensify-common": "git://github.com/Expensify/expensify-common.git#8f286b5826a041ecb739cff1ad6940ffb9324bee",
+    "expensify-common": "git://github.com/Expensify/expensify-common.git#5fb22bd4a3619eb9fe9e2a9c0dc25e291863a2a2",
     "expo-haptics": "^10.0.0",
     "file-loader": "^6.0.0",
     "html-entities": "^1.3.1",

src/components/ErrorBoundary/index.js

@@ -3,7 +3,6 @@ import Log from '../../libs/Log';
 
 BaseErrorBoundary.defaultProps.logError = (errorMessage, error, errorInfo) => {
     // Log the error to the server
-    Log.alert(errorMessage, 0, {error: error.message, errorInfo}, false);
+    Log.alert(errorMessage, {error: error.message, errorInfo}, false);
 };
-
 export default BaseErrorBoundary;

src/components/ErrorBoundary/index.native.js

@@ -5,7 +5,7 @@ import Log from '../../libs/Log';
 
 BaseErrorBoundary.defaultProps.logError = (errorMessage, error, errorInfo) => {
     // Log the error to the server
-    Log.alert(errorMessage, 0, {error: error.message, errorInfo}, false);
+    Log.alert(errorMessage, {error: error.message, errorInfo}, false);
 
     /* On native we also log the error to crashlytics
     * Since the error was handled we need to manually tell crashlytics about it */

src/libs/API.js

@@ -484,15 +484,13 @@ function GetRequestCountryCode() {
 
 /**
  * @param {Object} parameters
- * @param {String} parameters.message
- * @param {Object} parameters.parameters
  * @param {String} parameters.expensifyCashAppVersion
- * @param {String} [parameters.email]
+ * @param {Object[]} parameters.logPacket
  * @returns {Promise}
  */
 function Log(parameters) {
     const commandName = 'Log';
-    requireParameters(['message', 'parameters', 'expensifyCashAppVersion'],
+    requireParameters(['logPacket', 'expensifyCashAppVersion'],
         parameters, commandName);
 
     // Note: We are forcing Log to run since it requires no authToken and should only be queued when we are offline.

src/libs/HttpUtils.js

@@ -2,6 +2,9 @@ import _ from 'underscore';
 import CONFIG from '../CONFIG';
 import CONST from '../CONST';
 
+// To avoid a circular dependency, we can't include Log here, so instead, we define an empty logging method and expose the setLogger method to set the logger from outside this file
+let info = () => {};
+
 /**
  * Send an HTTP request, and attempt to resolve the json response.
  * If there is a network error, we'll set the application offline.
@@ -28,10 +31,30 @@ function processHTTPRequest(url, method = 'get', body = null) {
  * @returns {Promise}
  */
 function xhr(command, data, type = CONST.NETWORK.METHOD.POST, shouldUseSecure = false) {
+    if (command !== 'Log') {
+        info('Making API request', false, {
+            command,
+            type,
+            shouldUseSecure,
+            rvl: data.returnValueList,
+        });
+    }
     const formData = new FormData();
     _.each(data, (val, key) => formData.append(key, val));
     const apiRoot = shouldUseSecure ? CONFIG.EXPENSIFY.URL_EXPENSIFY_SECURE : CONFIG.EXPENSIFY.URL_API_ROOT;
-    return processHTTPRequest(`${apiRoot}api?command=${command}`, type, formData);
+    return processHTTPRequest(`${apiRoot}api?command=${command}`, type, formData)
+        .then((response) => {
+            if (command !== 'Log') {
+                info('Finished API request', false, {
+                    command,
+                    type,
+                    shouldUseSecure,
+                    jsonCode: response.jsonCode,
+                    requestID: response.requestID,
+                });
+            }
+            return response;
+        });
 }
 
 /**
@@ -51,7 +74,12 @@ function download(relativePath) {
     return processHTTPRequest(`${siteRoot}${strippedRelativePath}`);
 }
 
+function setLogger(logger) {
+    info = logger.info;
+}
+
 export default {
+    setLogger,
     download,
     xhr,
 };

src/libs/Log.js

@@ -4,22 +4,28 @@ import CONFIG from '../CONFIG';
 import getPlatform from './getPlatform';
 import {version} from '../../package.json';
 import NetworkConnection from './NetworkConnection';
+import HttpUtils from './HttpUtils';
+
+let timeout = null;
 
 /**
  * Network interface for logger.
  *
+ * @param {Logger} logger
  * @param {Object} params
  * @param {Object} params.parameters
  * @param {String} params.message
+ * @return {Promise}
  */
-function serverLoggingCallback(params) {
-    const requestParams = {
-        message: params.message,
-        parameters: JSON.stringify(params.parameters || {}),
-        expensifyCashAppVersion: `expensifyCash[${getPlatform()}]${version}`,
-    };
-
-    API.Log(requestParams);
+function serverLoggingCallback(logger, params) {
+    const requestParams = params;
+    requestParams.expensifyCashAppVersion = `expensifyCash[${getPlatform()}]${version}`;
+    if (requestParams.parameters) {
+        requestParams.parameters = JSON.stringify(params.parameters);
+    }
+    clearTimeout(timeout);
+    timeout = setTimeout(() => logger.info('Flushing logs older than 10 minutes', true, {}, true), 10 * 60 * 1000);
+    return API.Log(requestParams);
 }
 
 // Note: We are importing Logger from expensify-common because it is
@@ -33,6 +39,9 @@ const Log = new Logger({
     },
     isDebug: !CONFIG.IS_IN_PRODUCTION,
 });
+timeout = setTimeout(() => Log.info('Flushing logs older than 10 minutes', true, {}, true), 10 * 60 * 1000);
 
 NetworkConnection.registerLogInfoCallback(Log.info);
+HttpUtils.setLogger(Log);
+
 export default Log;

src/libs/Navigation/NavigationRoot.js

@@ -6,6 +6,7 @@ import linkingConfig from './linkingConfig';
 import AppNavigator from './AppNavigator';
 import {setCurrentURL} from '../actions/App';
 import FullScreenLoadingIndicator from '../../components/FullscreenLoadingIndicator';
+import Log from '../Log';
 
 const propTypes = {
     /** Whether the current user is logged in with an authToken */
@@ -29,6 +30,7 @@ class NavigationRoot extends Component {
         }
 
         const path = getPathFromState(state, linkingConfig.config);
+        Log.info('Navigating to route', false, {path});
         setCurrentURL(path);
     }
 

src/libs/NetworkConnection.js

@@ -19,7 +19,7 @@ const reconnectionCallbacks = [];
  * Loop over all reconnection callbacks and fire each one
  */
 const triggerReconnectionCallbacks = _.throttle((reason) => {
-    logInfo(`[NetworkConnection] Firing reconnection callbacks because ${reason}`, true);
+    logInfo(`[NetworkConnection] Firing reconnection callbacks because ${reason}`);
     Onyx.set(ONYXKEYS.IS_LOADING_AFTER_RECONNECT, true);
     promiseAllSettled(_.map(reconnectionCallbacks, callback => callback()))
         .then(() => Onyx.set(ONYXKEYS.IS_LOADING_AFTER_RECONNECT, false));
@@ -49,7 +49,7 @@ function setOfflineStatus(isCurrentlyOffline) {
  * `disconnected` event which takes about 10-15 seconds to emit.
  */
 function listenForReconnect() {
-    logInfo('[NetworkConnection] listenForReconnect called', true);
+    logInfo('[NetworkConnection] listenForReconnect called');
 
     unsubscribeFromAppState = AppStateMonitor.addBecameActiveListener(() => {
         triggerReconnectionCallbacks('app became active');
@@ -67,7 +67,7 @@ function listenForReconnect() {
  * Tear down the event listeners when we are finished with them.
  */
 function stopListeningForReconnect() {
-    logInfo('[NetworkConnection] stopListeningForReconnect called', true);
+    logInfo('[NetworkConnection] stopListeningForReconnect called');
     if (unsubscribeFromNetInfo) {
         unsubscribeFromNetInfo();
         unsubscribeFromNetInfo = undefined;

src/libs/PusherConnectionManager.js

@@ -7,7 +7,7 @@ import Log from './Log';
 // reconnect each time when we only need to reconnect once. This way, if an authToken is expired and we try to
 // subscribe to a bunch of channels at once we will only reauthenticate and force reconnect Pusher once.
 const reauthenticate = _.throttle(() => {
-    Log.info('[Pusher] Re-authenticating and then reconnecting', true);
+    Log.info('[Pusher] Re-authenticating and then reconnecting');
     API.reauthenticate('Push_Authenticate')
         .then(() => Pusher.reconnect())
         .catch(() => {
@@ -27,7 +27,7 @@ function init() {
      */
     Pusher.registerCustomAuthorizer(channel => ({
         authorize: (socketID, callback) => {
-            Log.info('[PusherConnectionManager] Attempting to authorize Pusher', true);
+            Log.info('[PusherConnectionManager] Attempting to authorize Pusher', false, {channelName: channel.name});
 
             API.Push_Authenticate({
                 socket_id: socketID,
@@ -44,11 +44,15 @@ function init() {
                         return;
                     }
 
-                    Log.info('[PusherConnectionManager] Pusher authenticated successfully', true);
+                    Log.info(
+                        '[PusherConnectionManager] Pusher authenticated successfully',
+                        false,
+                        {channelName: channel.name},
+                    );
                     callback(null, data);
                 })
                 .catch((error) => {
-                    Log.info('[PusherConnectionManager] Unhandled error: ', error);
+                    Log.info('[PusherConnectionManager] Unhandled error: ', false, {channelName: channel.name});
                     callback(error, {auth: ''});
                 });
         },
@@ -63,14 +67,14 @@ function init() {
     Pusher.registerSocketEventCallback((eventName, data) => {
         switch (eventName) {
             case 'error':
-                Log.info('[PusherConnectionManager] error event', true, {error: data});
+                Log.info('[PusherConnectionManager] error event', false, {error: data});
                 reauthenticate();
                 break;
             case 'connected':
-                Log.info('[PusherConnectionManager] connected event', true);
+                Log.info('[PusherConnectionManager] connected event');
                 break;
             case 'disconnected':
-                Log.info('[PusherConnectionManager] disconnected event', true);
+                Log.info('[PusherConnectionManager] disconnected event');
                 break;
             default:
                 break;

src/libs/actions/App.js

@@ -1,9 +1,10 @@
+import {AppState, Linking} from 'react-native';
 import Onyx from 'react-native-onyx';
-import {Linking} from 'react-native';
 import lodashGet from 'lodash/get';
 import ONYXKEYS from '../../ONYXKEYS';
 import * as API from '../API';
 import CONST from '../../CONST';
+import Log from '../Log';
 import CONFIG from '../../CONFIG';
 import Firebase from '../Firebase';
 import ROUTES from '../../ROUTES';
@@ -71,6 +72,14 @@ function setSidebarLoaded() {
     printPerformanceMetrics();
 }
 
+let appState;
+AppState.addEventListener('change', (nextAppState) => {
+    if (nextAppState.match(/inactive|background/) && appState === 'active') {
+        Log.info('Flushing logs as app is going inactive', true, {}, true);
+    }
+    appState = nextAppState;
+});
+
 export {
     setCurrentURL,
     setLocale,

src/libs/actions/Report.js

@@ -309,7 +309,7 @@ function fetchChatReportsByIDs(chatList, shouldRedirectIfInacessible = false) {
     const simplifiedReports = {};
     return API.GetReportSummaryList({reportIDList: chatList.join(',')})
         .then(({reportSummaryList, jsonCode}) => {
-            Log.info('[Report] successfully fetched report data', true);
+            Log.info('[Report] successfully fetched report data', false, {chatList});
             fetchedReports = reportSummaryList;
 
             // If we receive a 404 response while fetching a single report, treat that report as inacessible.
@@ -329,7 +329,7 @@ function fetchChatReportsByIDs(chatList, shouldRedirectIfInacessible = false) {
                     return;
                 }
                 if (participants.length === 0) {
-                    Log.alert('[Report] Report with IOU action but does not have any participant.', true, {
+                    Log.alert('[Report] Report with IOU action but does not have any participant.', {
                         reportID: chatReport.reportID,
                         participants,
                     });
@@ -682,7 +682,7 @@ function subscribeToUserEvents() {
     // Live-update a report's actions when a 'report comment' event is received.
     Pusher.subscribe(pusherChannelName, Pusher.TYPE.REPORT_COMMENT, (pushJSON) => {
         Log.info(
-            `[Report] Handled ${Pusher.TYPE.REPORT_COMMENT} event sent by Pusher`, true, {reportID: pushJSON.reportID},
+            `[Report] Handled ${Pusher.TYPE.REPORT_COMMENT} event sent by Pusher`, false, {reportID: pushJSON.reportID},
         );
         updateReportWithNewAction(pushJSON.reportID, pushJSON.reportAction, pushJSON.notificationPreference);
     }, false,
@@ -692,15 +692,15 @@ function subscribeToUserEvents() {
         .catch((error) => {
             Log.info(
                 '[Report] Failed to subscribe to Pusher channel',
-                true,
+                false,
                 {error, pusherChannelName, eventName: Pusher.TYPE.REPORT_COMMENT},
             );
         });
 
     // Live-update a report's actions when an 'edit comment' event is received.
     Pusher.subscribe(pusherChannelName, Pusher.TYPE.REPORT_COMMENT_EDIT, (pushJSON) => {
         Log.info(
-            `[Report] Handled ${Pusher.TYPE.REPORT_COMMENT_EDIT} event sent by Pusher`, true, {
+            `[Report] Handled ${Pusher.TYPE.REPORT_COMMENT_EDIT} event sent by Pusher`, false, {
                 reportActionID: pushJSON.reportActionID,
             },
         );
@@ -712,7 +712,7 @@ function subscribeToUserEvents() {
         .catch((error) => {
             Log.info(
                 '[Report] Failed to subscribe to Pusher channel',
-                true,
+                false,
                 {error, pusherChannelName, eventName: Pusher.TYPE.REPORT_COMMENT_EDIT},
             );
         });
@@ -721,7 +721,7 @@ function subscribeToUserEvents() {
     Pusher.subscribe(pusherChannelName, Pusher.TYPE.REPORT_TOGGLE_PINNED, (pushJSON) => {
         Log.info(
             `[Report] Handled ${Pusher.TYPE.REPORT_TOGGLE_PINNED} event sent by Pusher`,
-            true,
+            false,
             {reportID: pushJSON.reportID},
         );
         updateReportPinnedState(pushJSON.reportID, pushJSON.isPinned);
@@ -732,13 +732,13 @@ function subscribeToUserEvents() {
         .catch((error) => {
             Log.info(
                 '[Report] Failed to subscribe to Pusher channel',
-                true,
+                false,
                 {error, pusherChannelName, eventName: Pusher.TYPE.REPORT_TOGGLE_PINNED},
             );
         });
 
     PushNotification.onReceived(PushNotification.TYPE.REPORT_COMMENT, ({reportID, reportAction}) => {
-        Log.info('[Report] Handled event sent by Airship', true, {reportID});
+        Log.info('[Report] Handled event sent by Airship', false, {reportID});
         updateReportWithNewAction(reportID, reportAction);
     });
 
@@ -810,7 +810,7 @@ function subscribeToReportTypingEvents(reportID) {
         }, 1500);
     })
         .catch((error) => {
-            Log.info('[Report] Failed to initially subscribe to Pusher channel', true, {error, pusherChannelName});
+            Log.info('[Report] Failed to initially subscribe to Pusher channel', false, {error, pusherChannelName});
         });
 }
 
@@ -877,7 +877,7 @@ function fetchActions(reportID, offset) {
     const reportActionsOffset = !_.isUndefined(offset) ? offset : -1;
 
     if (!_.isNumber(reportActionsOffset)) {
-        Log.alert('[Report] Offset provided is not a number', true, {
+        Log.alert('[Report] Offset provided is not a number', {
             offset,
             reportActionsOffset,
         });

src/libs/actions/Session.js

@@ -5,6 +5,7 @@ import ONYXKEYS from '../../ONYXKEYS';
 import redirectToSignIn from './SignInRedirect';
 import * as API from '../API';
 import CONFIG from '../../CONFIG';
+import Log from '../Log';
 import PushNotification from '../Notification/PushNotification';
 import Timing from './Timing';
 import CONST from '../../CONST';
@@ -63,6 +64,7 @@ function createAccount(login) {
  * Clears the Onyx store and redirects user to the sign in page
  */
 function signOut() {
+    Log.info('Flushing logs before signing out', true, {}, true);
     if (credentials && credentials.autoGeneratedLogin) {
         // Clean up the login that we created
         API.DeleteLogin({