App icon indicating copy to clipboard operation
App copied to clipboard

[$1000] Skeleton UI is displayed when clicking on any chat reported by @thesahindia

Open kavimuru opened this issue 3 years ago • 22 comments

If you haven’t already, check out our contributing guidelines for onboarding and email [email protected] to request to join our Slack channel!


Action Performed:

  1. Open app
  2. Click on any chat

Expected Result:

Chat should be loading instantly

Actual Result:

Skeleton UI appears

Workaround:

Refresh the page or close and reopen the app (Native apps)

Platform:

Where is this issue occurring?

  • Web
  • iOS
  • Android
  • Desktop App
  • Mobile Web

Version Number: 1.2.26-0 Reproducible in staging?: y Reproducible in production?: y Email or phone of affected tester (no customers): Logs: https://stackoverflow.com/c/expensify/questions/4856 Notes/Photos/Videos: Screenshot 2022-11-09 at 11 13 41 PM

https://user-images.githubusercontent.com/43996225/201110883-348e3783-5f90-43a5-a73f-1b8ffe88819f.mp4

Expensify/Expensify Issue URL: Issue reported by: @thesahindia Slack conversation: https://expensify.slack.com/archives/C01GTK53T8Q/p1668015943860829

View all open jobs on GitHub

kavimuru avatar Nov 10 '22 13:11 kavimuru

Triggered auto assignment to @lschurr (Bug), see https://stackoverflow.com/c/expensify/questions/14418 for more details.

melvin-bot[bot] avatar Nov 10 '22 13:11 melvin-bot[bot]

Taking this one, because this is a pretty bad regression and I'd like to raise the price to $1000 immediately.

JmillsExpensify avatar Nov 10 '22 16:11 JmillsExpensify

Calling all contributors, we need your help resolving this performance regression! Upwork job is here: https://www.upwork.com/jobs/~01d434cec2c2807231. Compensation starts at $1,000.

JmillsExpensify avatar Nov 10 '22 16:11 JmillsExpensify

Current assignee @JmillsExpensify is eligible for the External assigner, not assigning anyone new.

melvin-bot[bot] avatar Nov 10 '22 16:11 melvin-bot[bot]

Triggered auto assignment to Contributor-plus team member for initial proposal review - @Santhosh-Sellavel (External)

melvin-bot[bot] avatar Nov 10 '22 16:11 melvin-bot[bot]

Triggered auto assignment to @dangrous (External), see https://stackoverflow.com/c/expensify/questions/7972 for more details.

melvin-bot[bot] avatar Nov 10 '22 16:11 melvin-bot[bot]

@dangrous Can you take at look at this issue and the related Slack thread. We need to figure out a couple of things, though I'm keeping the external label on this issue until we rule that out.

  • Any theories as to how this regression got introduced?
  • Do you think external is appropriate, or do we need to take internal?

And that's probably it for now. Thanks!

JmillsExpensify avatar Nov 10 '22 16:11 JmillsExpensify

Will investigate!

dangrous avatar Nov 10 '22 17:11 dangrous

Just putting the info I found so far here as well as in Slack:

This appears to be caused not by any slow responses from the API, but from a long delayed call to the API - AuthenticatePusher is sent about 3-4 seconds (on web) after the previous API call, and possibly never on iOS. Either OpenReport is not called until after that response is returned, or it's called at the same time (but therefore is still delayed). As soon as that response comes, the UI loads in.

Do you think external is appropriate, or do we need to take internal?

  • It's likely this is an issue with the app, not with the API, since there are no outstanding requests during the delay period, and so External is fine.

Any theories as to how this regression got introduced?

  • One potential cause might be this PR which actively (on purpose) delays calling subscribeToReportTypingEvents because AuthenticatePusher - part of that function - was being called too early when a new report is created. However, I'm not sure why that would cause this behavior, but the timeline and commands do match up, so it's worth looking into.

EDIT: On refresh, we still get a delay before calling OpenReport (which causes the long loading UI) but AuthenticatePusher isn't delayed. So maybe it's related but not the cause. You can see the delay here: Screen Shot 2022-11-10 at 13 15 08

dangrous avatar Nov 10 '22 18:11 dangrous

@mollfpr This could potentially be a regression from https://github.com/Expensify/App/pull/12365 so wanted to see if you had any thoughts!

dangrous avatar Nov 10 '22 19:11 dangrous

@dangrous I think this is due to OpenApp delay, so maybe it's indeed internal?

One thing i can add is this (not directly related to this issue):

diff --git a/src/pages/home/ReportScreen.js b/src/pages/home/ReportScreen.js
index 7d6828b01..3e3a300f2 100644
--- a/src/pages/home/ReportScreen.js
+++ b/src/pages/home/ReportScreen.js
@@ -159,7 +159,7 @@ class ReportScreen extends React.Component {
 
         // This is necessary so that when we are retrieving the next report data from Onyx the ReportActionsView will remount completely
         const isTransitioning = this.props.report && this.props.report.reportID !== reportIDFromPath;
-        return reportIDFromPath && this.props.report.reportID && !isTransitioning && !isLoadingInitialAppData;
+        return reportIDFromPath && this.props.report.reportID && !isTransitioning && isLoadingInitialAppData === false;
     }
 
     fetchReportIfNeeded() {

initially isLoadingInitialAppData will be undefined and !undefined is true which is not the desired results. Comparing with false is safer.

s77rt avatar Nov 10 '22 19:11 s77rt

Changing the chat will also trigger the skeleton but the chat gets loaded normally after calling OpenReport I'm unable to consistently reproduce the reported issue. I was only able to reproduce it with the case of delayed OpenApp response and just few times

s77rt avatar Nov 10 '22 20:11 s77rt

@dangrous

I think the skeleton view loader is not depending on the AuthenticatePusher response.

We use !this.isReportReadyForDisplay() to show the skeleton view. The isReportReadyForDisplay value depends on isLoadingInitialAppData which is from the OpenApp success response and isTransitioning where the report data load from the OpenReport success response. https://github.com/Expensify/App/blob/ae385f9f676ba1527cf44fa5ec658072ba070113/src/pages/home/ReportScreen.js#L148-L163

mollfpr avatar Nov 11 '22 03:11 mollfpr

My take here:

The issue is happening due to isLoadingInitialAppData being true and hence isReadyForDisplay is false.

Because I am not able to consistently reproduce this on Web, I haven't debugged the API response. But the OpenApp API is returning 407 (NOT_AUTHENTICATED), which should probably get into failureData of the API call.

I saw this part inSaveResponseInOnyx.

} else if (responseData.jsonCode !== 200 && request.failureData) {
                    Onyx.update(request.failureData);
                }

Logs I captured:

[info] Making API request - {"command":"OpenApp"}
DEBUG  [info] Finished API request - {"command":"OpenApp","jsonCode":407,"requestID":"76845a4cdff5f35f-BOM"}

LOG  Flag Info {"isReadyForDisplayFlag": false, "isLoadingInitialAppData": true, "isTransitioning": false, "reportID": "77921477", "reportIDFromPath": "77921477"}

What I need to check is if failureData is set when we get 407 Unauthenticated request error.

I'll try to dig further but meanwhile if it helps identify the issue further.

mananjadhav avatar Nov 11 '22 04:11 mananjadhav

Proposal

I can reproduce this with a high-traffic account [email protected]. The issue workarounds don't resolve the issue.

~~I think it's a regression from https://github.com/Expensify/App/pull/12169~~ where we update the Onyx response data first then the success data. https://github.com/Expensify/App/blob/ae385f9f676ba1527cf44fa5ec658072ba070113/src/libs/Middleware/SaveResponseInOnyx.js#L16-L30

https://user-images.githubusercontent.com/25520267/201281626-be0a45b0-4de1-4a5a-8100-e6ffe11f231c.mov

In my case, the personalDetails response data has a value of around 5817 data (even my laptop can't expand the object). I guess this also makes the API OpenApp take a long time to return the response.

If I'm excluding the personalDetails key when updating the Onyx response data, the success data from OpenApp is set immediately.

So my suggestion is, we should separate the personalDetails data from the OpenApp API response. We should create another API for fetching the personalDetails after the OpenApp response is resolved. In this way, we will prioritize other data responses from the OpenApp API.

mollfpr avatar Nov 11 '22 07:11 mollfpr

@Santhosh-Sellavel thoughts on this latest proposal?

JmillsExpensify avatar Nov 11 '22 20:11 JmillsExpensify

I think this still needs more investigation. I can (randomly) reproduce the issue even with a barely new account.

s77rt avatar Nov 12 '22 12:11 s77rt

@mollfpr You might be onto something, but as @s77rt I can also reproduce this on low traffic account. I am unable to reproduce every time. Of 3-4 times I reproduced, I've waited for like upto 3-4 mins to see if it loads something but it doesn't and always fails with 407 auth code. It only works if I reload/refresh the app.

mananjadhav avatar Nov 12 '22 20:11 mananjadhav

I faced this issue with both low/high traffic accounts, but this has the most impact on high-traffic accounts which is for most of us (for our personal accounts as well)!

So my suggestion is, we should separate the personalDetails data from the OpenApp API response. We should create another API for fetching the personalDetails after the OpenApp response is resolved. In this way, we will prioritize other data responses from the OpenApp API.

Thanks, @mollfpr, I like the idea. If you have a full proposal please submit let's test this one and move this forward quickly!

Santhosh-Sellavel avatar Nov 13 '22 07:11 Santhosh-Sellavel

I'm able to reproduce it with App that has a session expired. To repro this in the DEV I'm customizing the authToken parameters, so the response from OpenApp will have jsonCode=407.

https://github.com/Expensify/App/blob/0d653cad15c32150c302ac12dc0acdbca1ece18b/src/libs/Network/enhanceParameters.js#L33-L38

if (isAuthTokenRequired(command) && !parameters.authToken) {
        finalParameters.authToken = NetworkStore.getAuthToken() + 'test';
    }

The thing that I found is OpenApp Onyx failure data is never updated to Onyx because turns out the response data is undefined on SaveResponseInOnyx where we not updating the Onyx. https://github.com/Expensify/App/blob/0d653cad15c32150c302ac12dc0acdbca1ece18b/src/libs/Middleware/SaveResponseInOnyx.js#L11-L14

So what I understand is, when the jsonCode from the API response is 407, it will catch in Reauthentication middleware. When OpenApp session is expired, it's indeed called the Reauthenticate API and will set the new authToken to the Onyx session. But in OpenApp we use the API request type as read, where after Reauthenticate is resolved, there's a condition to check if the request type is read run another function and resolve the promise but without sending back the API response data. https://github.com/Expensify/App/blob/0d653cad15c32150c302ac12dc0acdbca1ece18b/src/libs/Middleware/Reauthentication.js#L87-L90

Because of the promise resolve from Reauthenicate not passing the response data, the OpenApp doesn't have a chance to update the failure data.

We should update the return promise with the response data.

diff --git a/src/libs/Middleware/Reauthentication.js b/src/libs/Middleware/Reauthentication.js
index bf1bbad1a..dab836f56 100644
--- a/src/libs/Middleware/Reauthentication.js
+++ b/src/libs/Middleware/Reauthentication.js
@@ -86,7 +86,7 @@ function Reauthentication(response, request, isFromSequentialQueue) {

                         if (apiRequestType === CONST.API_REQUEST_TYPE.READ) {
                             NetworkConnection.triggerReconnectionCallbacks('read request made with expired authToken');
-                            return Promise.resolve();
+                            return Promise.resolve(data);
                         }

                         MainQueue.replay(request);

Before

https://user-images.githubusercontent.com/25520267/201511749-7b6808e0-fda4-4dfc-81e3-e1d850d4c927.mov

After

https://user-images.githubusercontent.com/25520267/201511754-aa5ce30c-49b6-423c-af1a-dfff749bcc44.mov

mollfpr avatar Nov 13 '22 07:11 mollfpr

That also explains why the App works again after refreshing the page or closing the App. Because the OpenApp will be called again with the new authToken and the success data is updated to Onyx.

mollfpr avatar Nov 13 '22 08:11 mollfpr

~~Proposal~~

Edit : my proposal will only fix this issue #12574 so I posted it in other thread , i agree with @mollfpr proposal https://github.com/Expensify/App/issues/12635#issuecomment-1312663705 , there is an update that will not be triggered for OpenApp command when session is expired

https://github.com/Expensify/App/commit/164f30955c7d26d5a7e004d5a3b7784a621091b2#diff-b900fb367aed6ac57460755de185e8cb616f156a58fbc167b948a700e10889ff this introduced the change and caused the miss update

Screenshot 2022-11-13 at 10 16 56 PM

fedirjh avatar Nov 13 '22 11:11 fedirjh

Thanks, @fedirjh, that makes sense!

Santhosh-Sellavel avatar Nov 14 '22 16:11 Santhosh-Sellavel

cc: @dangrous @mollfpr's proposal looks good!

Santhosh-Sellavel avatar Nov 14 '22 16:11 Santhosh-Sellavel

Cool! @mollfpr's proposal makes sense to me too.

@JmillsExpensify just wanted to run by you as well since I want to make sure I'm not missing any context or side effect trickiness from not knowing the codebase as well. Let us know and then we can get this approved, PRd, and merged!

dangrous avatar Nov 14 '22 16:11 dangrous

The proposal by @mollfpr definitely seems like a much bigger bug.

Mind if we slow down a bit?

For this issue specifically, my read is that there is likely a relationship to slow API calls since, yes, the report page will wait for OpenApp. But the expectation is that the "cached" report comments are shown immediately. That's the behavior that was reported to have "regressed". And I think we maybe introduced it by waiting for the report actions to load from the server in my PR here.

I added that code so that the "new markers" would work correctly - so we can revert it, but cause a regression to the new markers.

I think any proposal here should include that consideration.

marcaaron avatar Nov 14 '22 17:11 marcaaron

For this issue specifically, my read is that there is likely a relationship to slow API calls since, yes, the report page will wait for OpenApp. But the expectation is that the "cached" report comments are shown immediately. That's the behavior that was reported to have "regressed".

I like slowing down. I also agree that the regression seems to have occurred around not showing anything cached immediately, which is a big problem given that our design is Offline First.

JmillsExpensify avatar Nov 14 '22 17:11 JmillsExpensify

Pretty sure this is a dupe of this issue -> https://github.com/Expensify/App/issues/12574

I'm reverting my PR here to fix the new marker since I think that's where the trouble started. It does look like there's maybe some other issue related to authentication happening being discussed here. But we should explore it separately since those changes could have far reaching implications.

marcaaron avatar Nov 14 '22 19:11 marcaaron

Oh thanks for making the connection! Ok, so let's align in this issue what to do for the authentication issue for the time being then, sound good? I can update the title and what not, though we should also really decide if we're going to do anything about this at the moment. These bugs are tricky, as you rightly note. If we aren't going to move forward on the authentication side, then probably better to close out this issue.

JmillsExpensify avatar Nov 14 '22 20:11 JmillsExpensify

If we aren't going to move forward on the authentication side

It does sound like the cases where chats are not loading at all are due to an expired authToken. I can add those changes into my PR and test it out to get this done quickly. @mollfpr we'll of course compensate you for spotting this.

marcaaron avatar Nov 15 '22 00:11 marcaaron