Use server logs instead of console.debug most places #5827

roryabraham · 2021-10-13T21:45:19Z

Details

Send NewDot logs to servers where it is possible + makes sense.

Fixed Issues

$ #5624

Tests / QA Steps.

Run the app
Check for logs in console, they should appear like existing server logs.
Look at the network tab, make sure logs are being sent, but not one request for every log line. Logs should be sent in batches of 50 log lines.

Tested On

Screenshots

Confirmed that logs are still showing up in console and sending in batches (of 50):

roryabraham · 2021-10-13T21:59:43Z

A few things I thought about doing but didn't:

I notice that Log.info has parameters as the third argument instead of the second one. This is inconsistent with the other Log functions such as warn or hmmm and almost always false. IMO it would make more sense to have parameters be the second argument so that you don't always have to pass false as the second arg before passing parameters. Didn't make that change because the logger lives in expensify-common.
Also, there are a few locations, such as API or Network where using the server-logger doesn't make sense because it causes a circular dependency. So I left those as console.debug statements.
Lastly, I thought about trying to ban console.debug statements via an ESLint rule to discourage their use in the future, but the no-console rule doesn't seem to enable that and it's not worth making a custom rule at this time.

marcochavezf · 2021-10-14T19:05:49Z

Hi @roryabraham! :)

I found there are still few places where console.debug is called, but not sure if those also could have circular dependency issues with Log

marcochavezf · 2021-10-14T19:07:24Z

Also, there are a few locations, such as API or Network where using the server-logger doesn't make sense because it causes a circular dependency. So I left those as console.debug statements.

I'm a bit concerned about not logging to the server the messages in those locations because for example this issue seems to be caused in API.js and that can still be a blind spot if a similar issue happens in the future.

I was thinking if it's better to decouple the logic that uses console.debug from API. For example, moving this function (and the code that calls it) to another file (where Log and API can be imported without issues):

App/src/libs/API.js

Lines 51 to 76 in 9ea80ba

    
           function addDefaultValuesToParameters(command, parameters) { 
        
               const finalParameters = {...parameters}; 
        
               if (isAuthTokenRequired(command) && !parameters.authToken) { 
        
                   // If we end up here with no authToken it means we are trying to make an API request before we are signed in. 
        
                   // In this case, we should cancel the current request by pausing the queue and clearing the remaining requests. 
        
                   if (!authToken) { 
        
                       redirectToSignIn(); 
        
                       console.debug('A request was made without an authToken', {command, parameters}); 
        
                       Network.pauseRequestQueue(); 
        
                       Network.clearRequestQueue(); 
        
                       return; 
        
                   } 
        
                   finalParameters.authToken = authToken; 
        
               } 
        
               finalParameters.referer = CONFIG.EXPENSIFY.EXPENSIFY_CASH_REFERER; 
        
               // This application does not save its authToken in cookies like the classic Expensify app. 
        
               // Setting api_setCookie to false will ensure that the Expensify API doesn't set any cookies 
        
               // and prevents interfering with the cookie authToken that Expensify classic uses. 
        
               finalParameters.api_setCookie = false; 
        
               return finalParameters; 
        
           }

And call the new file may be in componentDidMount of Expensify.js (or a similar place when the app starts up)? cc @tgolen @marcaaron

src/components/AddPlaidBankAccount.js

src/components/ImageWithSizeCalculation.js

src/libs/Navigation/Navigation.js

src/libs/Notification/PushNotification/index.native.js

src/libs/Pusher/pusher.js

marcaaron · 2021-10-14T19:27:06Z

src/libs/actions/PersonalDetails.js

@@ -129,7 +130,7 @@ function fetchPersonalDetails() {
            // Set my personal details so they can be easily accessed and subscribed to on their own key
            Onyx.merge(ONYXKEYS.MY_PERSONAL_DETAILS, myPersonalDetails);
        })
-        .catch(error => console.debug('Error fetching personal details', error));
+        .catch(error => Log.hmmm('Error fetching personal details', error));


If we are going to catch and log API promise rejections then perhaps we should do it in a global way so we don't have to apply these inconsistently? Same comment about local currency, reportStuff, etc calls below.

Okay, added a global server log for API errors here

Nice, that takes care of the logs, but will we have unhandled rejections now for these cases?

To be totally honest, I'm not sure in which cases this should reject or why a catch() was added - but if it was throwing before it was handled and with your change they are not. Does it matter?

src/libs/listenToStorageEvents/index.js

marcaaron · 2021-10-14T19:39:43Z

I'm a bit concerned about not logging to the server the messages in those locations

@marcochavezf I agree that those logs would be really valuable to have and it would be nice if we can come up with a solution for the circular dependency. But sorry not sure if I understand the exact proposal.

Maybe it would be acceptable in these few cases to just call API.Log() directly.

marcochavezf · 2021-10-14T22:11:41Z

I'm a bit concerned about not logging to the server the messages in those locations

@marcochavezf I agree that those logs would be really valuable to have and it would be nice if we can come up with a solution for the circular dependency. But sorry not sure if I understand the exact proposal.

Maybe it would be acceptable in these few cases to just call API.Log() directly.

@marcaaron Ah yeah, in other words, I think to remove the circular dependency issues we can move all this code to a new file (let's say the new file can be AuthenticationManager.js or NetworkManager.js):

App/src/libs/API.js

Lines 10 to 21 in 029a3dd

    
           let isAuthenticating; 
        
           let credentials; 
        
           Onyx.connect({ 
        
               key: ONYXKEYS.CREDENTIALS, 
        
               callback: val => credentials = val, 
        
           }); 
        
           let authToken; 
        
           Onyx.connect({ 
        
               key: ONYXKEYS.SESSION, 
        
               callback: val => authToken = val ? val.authToken : null, 
        
           });

App/src/libs/API.js

Lines 44 to 80 in 029a3dd

    
           /** 
        
            * Adds default values to our request data 
        
            * 
        
            * @param {String} command 
        
            * @param {Object} parameters 
        
            * @returns {Object} 
        
            */ 
        
           function addDefaultValuesToParameters(command, parameters) { 
        
               const finalParameters = {...parameters}; 
        
               if (isAuthTokenRequired(command) && !parameters.authToken) { 
        
                   // If we end up here with no authToken it means we are trying to make an API request before we are signed in. 
        
                   // In this case, we should cancel the current request by pausing the queue and clearing the remaining requests. 
        
                   if (!authToken) { 
        
                       redirectToSignIn(); 
        
                       console.debug('A request was made without an authToken', {command, parameters}); 
        
                       Network.pauseRequestQueue(); 
        
                       Network.clearRequestQueue(); 
        
                       Network.unpauseRequestQueue(); 
        
                       return; 
        
                   } 
        
                   finalParameters.authToken = authToken; 
        
               } 
        
               finalParameters.referer = CONFIG.EXPENSIFY.EXPENSIFY_CASH_REFERER; 
        
               // This application does not save its authToken in cookies like the classic Expensify app. 
        
               // Setting api_setCookie to false will ensure that the Expensify API doesn't set any cookies 
        
               // and prevents interfering with the cookie authToken that Expensify classic uses. 
        
               finalParameters.api_setCookie = false; 
        
               return finalParameters; 
        
           } 
        
           // Tie into the network layer to add auth token to the parameters of all requests 
        
           Network.registerParameterEnhancer(addDefaultValuesToParameters);

App/src/libs/API.js

Lines 144 to 182 in 029a3dd

    
           Network.registerResponseHandler((queuedRequest, response) => { 
        
               if (response.jsonCode === 407) { 
        
                   // Credentials haven't been initialized. We will not be able to re-authenticates with the API 
        
                   const unableToReauthenticate = (!credentials || !credentials.autoGeneratedLogin 
        
                       || !credentials.autoGeneratedPassword); 
        
                   // There are some API requests that should not be retried when there is an auth failure like 
        
                   // creating and deleting logins. In those cases, they should handle the original response instead 
        
                   // of the new response created by handleExpiredAuthToken. 
        
                   if (queuedRequest.data.doNotRetry || unableToReauthenticate) { 
        
                       queuedRequest.resolve(response); 
        
                       return; 
        
                   } 
        
                   handleExpiredAuthToken(queuedRequest.command, queuedRequest.data, queuedRequest.type) 
        
                       .then(queuedRequest.resolve) 
        
                       .catch(queuedRequest.reject); 
        
                   return; 
        
               } 
        
               if (response.jsonCode === 405 || response.jsonCode === 404) { 
        
                   // IOU Split & Request money transactions failed due to invalid amount(405) or unable to split(404) 
        
                   // It's a failure, so reject the queued request 
        
                   queuedRequest.reject(response); 
        
                   return; 
        
               } 
        
               queuedRequest.resolve(response); 
        
           }); 
        
           Network.registerErrorHandler((queuedRequest, error) => { 
        
               console.debug('[API] Handled error when making request', error); 
        
               // Set an error state and signify we are done loading 
        
               Onyx.merge(ONYXKEYS.SESSION, {loading: false, error: 'Cannot connect to server'}); 
        
               // Reject the queued request with an API offline error so that the original caller can handle it. 
        
               queuedRequest.reject(new Error(CONST.ERROR.API_OFFLINE)); 
        
           });

And the new file now could import Log to replace the console.debug calls.

But I think calling API.Log() directly could solve the issue too :D

marcochavezf · 2021-10-14T22:30:05Z

IMO I think API.js should only contain the functions that decorate/calls Network.post (single responsibility) and the new file should contain the responsibility of managing the authToken, credentials, and the Network functions (Network.registerResponseHandler, Network.registerErrorHandler, etc).

roryabraham · 2021-10-14T23:19:21Z

Okay, I've made some updates and this is ready for another review. Take a look at the remaining uses of console.debug – I'm not sure it's necessary or valuable to send any of those logs to the server.

marcochavezf · 2021-10-14T23:35:35Z

Hi @roryabraham! :)

I found there are still few places where console.debug is called, but not sure if those also could have circular dependency issues with Log

Just to be sure, these console.debug calls are not required to be changed by Log.hmmm right?

App/src/libs/Performance.js

Line 99 in 7b50d3d

console.debug(error.message);

App/src/libs/PusherConnectionManager.js

Line 14 in 7b50d3d

console.debug(

App/src/libs/actions/Timing.js

Line 43 in 7b50d3d

console.debug(`Timing:${grafanaEventName}`, eventTime);

marcaaron · 2021-10-15T01:10:34Z

Performance.js logs are not needed as they only relevant on dev.
Grafana event timing log might be useful. I don't use Grafana too much and would probably look at a regular log before I did.
Pusher log there could be useful but is also sort of covered by the log added here now:

App/src/libs/API.js

Line 179 in 7b50d3d

LogUtil.hmmm('[API] Handled error when making request', error);

so maybe it could be deleted (but not sure if it should be left without a catch())

marcochavezf

👍🏽

OSBotify · 2021-10-18T21:42:56Z

✋ 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 · 2021-10-23T01:33:21Z

🚀 Deployed to staging by @marcaaron in version: 1.1.8-10 🚀

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

roryabraham · 2021-10-25T22:39:25Z

This will be internal QA btw

roryabraham · 2021-10-26T17:40:29Z

Did some testing on staging, marking this as a QA-pass.

OSBotify · 2021-10-28T20:58:13Z

🚀 Deployed to production by @roryabraham in version: 1.1.10-2 🚀

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

Use server logs where possible

fbce15e

roryabraham self-assigned this Oct 13, 2021

roryabraham added 2 commits October 13, 2021 14:50

Switch a few more Log.info to Log.hmmm

538a931

Nix duplicate import

d343119

roryabraham marked this pull request as ready for review October 13, 2021 22:06

roryabraham requested a review from a team as a code owner October 13, 2021 22:06

MelvinBot requested review from marcochavezf and removed request for a team October 13, 2021 22:06

marcaaron requested changes Oct 14, 2021

View reviewed changes

Make simple logging changes

c06b82b

roryabraham added 2 commits October 14, 2021 15:56

Use server logs in API error handler

f4c8023

Remove redundant logs and demote warn to hmmm

a51f1d4

roryabraham requested a review from marcaaron October 14, 2021 23:08

roryabraham added 2 commits October 14, 2021 16:11

Add a couple more server logs in reauthenticate

c5a388d

Don't attempt to Log when log command fails

7b50d3d

marcochavezf approved these changes Oct 15, 2021

View reviewed changes

marcaaron approved these changes Oct 18, 2021

View reviewed changes

marcaaron merged commit e69f603 into main Oct 18, 2021

marcaaron deleted the Rory-ServerLogs branch October 18, 2021 21:42

aldo-expensify mentioned this pull request Oct 19, 2021

Use sublocality when locality is missing - AddressSearch #5950

Merged

5 tasks

OSBotify mentioned this pull request Oct 23, 2021

Deploy Checklist: New Expensify 2021-10-23 #6017

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Use server logs instead of console.debug most places #5827

Use server logs instead of console.debug most places #5827

roryabraham commented Oct 13, 2021 •

edited

Loading

roryabraham commented Oct 13, 2021

marcochavezf commented Oct 14, 2021

marcochavezf commented Oct 14, 2021 •

edited

Loading

marcaaron Oct 14, 2021

roryabraham Oct 14, 2021 •

edited

Loading

marcaaron Oct 15, 2021

marcaaron commented Oct 14, 2021

marcochavezf commented Oct 14, 2021 •

edited

Loading

marcochavezf commented Oct 14, 2021 •

edited

Loading

roryabraham commented Oct 14, 2021

marcochavezf commented Oct 14, 2021 •

edited

Loading

marcaaron commented Oct 15, 2021 •

edited

Loading

marcochavezf left a comment

OSBotify commented Oct 18, 2021

OSBotify commented Oct 23, 2021

roryabraham commented Oct 25, 2021

roryabraham commented Oct 26, 2021

OSBotify commented Oct 28, 2021

Use server logs instead of console.debug most places #5827

Use server logs instead of console.debug most places #5827

Conversation

roryabraham commented Oct 13, 2021 • edited Loading

Details

Fixed Issues

Tests / QA Steps.

Tested On

Screenshots

roryabraham commented Oct 13, 2021

marcochavezf commented Oct 14, 2021

marcochavezf commented Oct 14, 2021 • edited Loading

marcaaron Oct 14, 2021

Choose a reason for hiding this comment

roryabraham Oct 14, 2021 • edited Loading

Choose a reason for hiding this comment

marcaaron Oct 15, 2021

Choose a reason for hiding this comment

marcaaron commented Oct 14, 2021

marcochavezf commented Oct 14, 2021 • edited Loading

marcochavezf commented Oct 14, 2021 • edited Loading

roryabraham commented Oct 14, 2021

marcochavezf commented Oct 14, 2021 • edited Loading

marcaaron commented Oct 15, 2021 • edited Loading

marcochavezf left a comment

Choose a reason for hiding this comment

OSBotify commented Oct 18, 2021

OSBotify commented Oct 23, 2021

roryabraham commented Oct 25, 2021

roryabraham commented Oct 26, 2021

OSBotify commented Oct 28, 2021

roryabraham commented Oct 13, 2021 •

edited

Loading

marcochavezf commented Oct 14, 2021 •

edited

Loading

roryabraham Oct 14, 2021 •

edited

Loading

marcochavezf commented Oct 14, 2021 •

edited

Loading

marcochavezf commented Oct 14, 2021 •

edited

Loading

marcochavezf commented Oct 14, 2021 •

edited

Loading

marcaaron commented Oct 15, 2021 •

edited

Loading