Expensify / App

Welcome to New Expensify: a complete re-imagination of financial collaboration, centered around chat. Help us build the next generation of Expensify by sharing feedback and contributing to the code.
https://new.expensify.com
MIT License
3.48k stars 2.84k forks source link

[HOLD for payment 2024-05-08] HIGH: [API Reliability] [$500] Multiple calls to `GetNewerActions` on report open #39674

Closed m-natarajan closed 5 months ago

m-natarajan commented 6 months ago

If you haven’t already, check out our contributing guidelines for onboarding and email contributors@expensify.com to request to join our Slack channel!


Version Number: 1.4.60-7 Reproducible in staging?: y Reproducible in production?: y If this was caught during regression testing, add the test name, ID and link from TestRail: Email or phone of affected tester (no customers): Logs: https://stackoverflow.com/c/expensify/questions/4856 Expensify/Expensify Issue URL: Issue reported by: @quinthar Slack conversation: https://expensify.slack.com/archives/C049HHMV9SM/p1712180926567259

Action Performed:

  1. Sign in to NewDot
  2. Open any report and don't scroll anywhere

Expected Result:

Shouldn't call GetNewerActions multiple times

Actual Result:

GetNewerActions called 5times, despite not scrolling anywhere. Also, all 5 calls seem identical

Workaround:

unknown

Platforms:

Which of our officially supported platforms is this issue occurring on?

Screenshots/Videos

Add any screenshot/video evidence

image (10)

View all open jobs on GitHub

Upwork Automation - Do Not Edit
  • Upwork Job URL: https://www.upwork.com/jobs/~01d7ea3b088204e3df
  • Upwork Job ID: 1778413819479543808
  • Last Price Increase: 2024-04-26
Issue OwnerCurrent Issue Owner: @twisterdotcom
melvin-bot[bot] commented 6 months ago

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

twisterdotcom commented 6 months ago

Asking a clarifying Q: https://expensify.slack.com/archives/C049HHMV9SM/p1712318653409559?thread_ts=1712180926.567259&cid=C049HHMV9SM

MelvinBot commented 6 months ago

This has been labelled "Needs Reproduction". Follow the steps here: https://stackoverflowteams.com/c/expensify/questions/16989

twisterdotcom commented 6 months ago

https://github.com/Expensify/App/assets/9133401/ad6495ad-0e92-4da3-ab9e-734fec7a5519

twisterdotcom commented 6 months ago

I still can't reproduce this. Nobody else has reported it recently.

twisterdotcom commented 6 months ago

https://github.com/Expensify/App/assets/9133401/d319aa5d-38f9-4e9d-972f-dbdd55aedae0

So, an example of a single report loading GetNewerActions twice is https://staging.new.expensify.com/r/8036391930866711

When I load it, there are two GetNewerActions calls:

First:

jsonCode : 200
onyxData : [{onyxMethod: "merge", key: "reportActions_6028698164025499", value: {,…}}]
    0 : {onyxMethod: "merge", key: "reportActions_6028698164025499", value: {,…}}
        key : "reportActions_6028698164025499"
        onyxMethod : "merge"
    value : {,…}
        3459936395858833627 : {person: [{type: "TEXT", style: "strong", text: "CFO expensivepie.com"}], actorAccountID: 14459901,…}
            actionName : "REPORTPREVIEW"
            actorAccountID : 14459901
            actorEmail : "cfo@expensivepie.com"
            automatic : false
            avatar : "https://d1wpcgnaa73g0y.cloudfront.net/f427ffa485716562c8a975c8805a447b5684b740_128.jpeg"
            childCommenterCount : 1
            childLastActorAccountID : 8698376
            childLastReceiptTransactionIDs : "1204108464410787705"
            childLastVisibleActionCreated : "2024-03-14 21:38:55.951"
            childMoneyRequestCount : 1
            childOldestFourAccountIDs : "11665625"
            childRecentReceiptTransactionIDs : {1204108464410787705: "2024-03-14 21:37:29"}
                1204108464410787705 : "2024-03-14 21:37:29"
            childReportID : 1783551381563554
            childReportNotificationPreference : "hidden"
            childStateNum : 1
            childStatusNum : 1
            childType : "iou"
            childVisibleActionCount : 1
            created : "2024-03-14 21:37:29.911"
            lastModified : "2024-03-14 21:37:29.911"
            message : [,…]
                0 : {type: "COMMENT", html: "cfo@expensivepie.com owes A$0.00", text: "cfo@expensivepie.com owes A$0.00",…}
                    deleted : ""
                    html : "cfo@expensivepie.com owes A$0.00"
                    isDeletedParentAction : false
                    isEdited : false
                    reactions : []
                    text : "cfo@expensivepie.com owes A$0.00"
                    type : "COMMENT"
                    whisperedTo : []
                originalMessage : {lastModified: "2024-03-14 21:37:29.911", linkedReportID: "1783551381563554",…}
                    lastModified : "2024-03-14 21:37:29.911"
                    linkedReportID : "1783551381563554"
                    originalActionAccountID : 14459901
                person : [{type: "TEXT", style: "strong", text: "CFO expensivepie.com"}]
                    0 : {type: "TEXT", style: "strong", text: "CFO expensivepie.com"}
                        style : "strong"
                        text : "CFO expensivepie.com"
                        type : "TEXT"
                    previousReportActionID : "90093531819613915"
                    reportActionID : "3459936395858833627"
                    reportActionTimestamp : 1710452249911
                    shouldShow : true
                    timestamp : 1710452249
                    whisperedToAccountIDs : []
    requestID : "872b3661fb7e63ec-LHR"

Second:

jsonCode : 200
onyxData : [{onyxMethod: "merge", key: "reportActions_8036391930866711", value: {,…}}]
    0 : {onyxMethod: "merge", key: "reportActions_8036391930866711", value: {,…}}
        key : "reportActions_8036391930866711"
        onyxMethod : "merge"
            value : {,…}
                2397210080192955362 : {person: [{type: "TEXT", style: "strong", text: "Admin Pie User"}], actorAccountID: 8698376,…}
                    actionName : "REPORTPREVIEW"
                    actorAccountID : 8698376
                    actorEmail : "pecan@expensivepie.com"
                    automatic : false
                    avatar : "https://d1wpcgnaa73g0y.cloudfront.net/f7493165a790b796c92bd0337f8cf6b9bb74c669_128.jpeg"
                    childLastActorAccountID : 8698376
                    childMoneyRequestCount : 3
                    childReportID : 438513267536357
                    childReportNotificationPreference : "hidden"
                    childType : "expense"
                    created : "2024-03-16 13:30:42.420"
                    lastModified : "2024-03-16 13:30:42.420"
                    message : [{type: "COMMENT", html: "Xero owes $132.30", text: "Xero owes $132.30", isEdited: false,…}]
                        0 : {type: "COMMENT", html: "Xero owes $132.30", text: "Xero owes $132.30", isEdited: false,…}
                            deleted : ""
                            html : "Xero owes $132.30"
                            isDeletedParentAction : false
                            isEdited : false
                            reactions : []
                            text : "Xero owes $132.30"
                            type : "COMMENT"
                            whisperedTo : []
                        originalMessage : {lastModified: "2024-03-16 13:30:42.420", linkedReportID: "438513267536357"}
                            lastModified : "2024-03-16 13:30:42.420"
                            linkedReportID : "438513267536357"
                        person : [{type: "TEXT", style: "strong", text: "Admin Pie User"}]
                            0 : {type: "TEXT", style: "strong", text: "Admin Pie User"}
                                style : "strong"
                                text : "Admin Pie User"
                                type : "TEXT"
                        previousReportActionID : "5789708545474438065"
                        reportActionID : "2397210080192955362"
                        reportActionTimestamp : 1710595842420
                        shouldShow : true
                        timestamp : 1710595842
                        whisperedToAccountIDs : []
    requestID : "872b3661fb7d63ec-LHR"

Maybe this is normal, maybe not?

melvin-bot[bot] commented 6 months ago

Job added to Upwork: https://www.upwork.com/jobs/~01d7ea3b088204e3df

melvin-bot[bot] commented 6 months ago

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

shahinyan11 commented 6 months ago

Proposal

Please re-state the problem that we are trying to solve in this issue.

HIGH: [Needs Reproduction] [Reliability] Multiple calls to GetNewerActions on report open

What is the root cause of that problem?

There is two different bugs.

  1. When we navigate to any report screen the Report.getNewerActions is called multiple time with the sam params due to calling onStartReached multiple times which is upstream bug
  2. When we navigate from report A to report B the Report.getNewerActions is called for both reports due to calling onStartReached for both screens which is upstream bug

    What changes do you think we should make in order to solve the problem?

  3. Add new const isStartReachedInitCallExecuted as a ref in MVCPFlatList which will be set true after first call of onStartReached function and set to false on focus
const isStartReachedInitCallExecuted = useRef(false)
...

useFocusEffect(
    useCallback(() => {
        isStartReachedInitCallExecuted.current = false
    }, []),
);

Add below onStartReached prop to Flatlist which will prevent additional calls if it has already been called once

<FlatList
    ...
    onStartReached={(e)=>{
        if(e.distanceFromStart === 0 && isStartReachedInitCallExecuted.current){
            return
        }

        props.onStartReached?.(e)
        isStartReachedInitCallExecuted.current = true
    }}
/>

What alternative solutions did you explore? (Optional)

Add below props to Flatlist . maxToRenderPerBatch for bug 1 and onStartReached for bug 2

maxToRenderPerBatch={props.data.lengt}
onStartReached={(e)=>{
    if(!isFocused){
        return
    }
    props.onStartReached?.(e)
}}
s77rt commented 6 months ago

@shahinyan11 Thanks for the proposal. Your RCA is not complete. Can you explain why is the loadNewerChats function being called in the first place for the first report (report A)?

PS: I think that's a different bug than what's reported, I'm suspecting GetNewerActions is getting called for the same report multiple times, I didn't experience this much but got 3 total calls (one for the report A and two for report B)

Screenshot 2024-04-11 at 9 52 48 PM
shahinyan11 commented 6 months ago

Proposal

Updated. Added solution for two bugs.

s77rt commented 6 months ago

@shahinyan11 Thanks for the update. The root cause is still not correct. The call sequence is as follow: loadNewerChats -> handleReportActionPagination -> fetchNewerAction and in fetchNewerAction we have an early return checking for isLoadingNewerReportActions https://github.com/Expensify/App/blob/b59ae94dbbfac2d3b5da8df5c4dc6fbdb7785c6b/src/pages/home/report/ReportActionsView.tsx#L193-L197

Thus not checking for isLoadingNewerReportActions in loadNewerChats is not the culprit. On the other hand I'm seeing unguarded calls to getNewerActions in loadOlderChats which could be the culprit. Let's investigate more on that

shahinyan11 commented 6 months ago

@s77rt In our case the getNewerActions never called from loadOlderChats function. My root cause may not be entirely correct, but you can test my solution and see if it fixes the error.

s77rt commented 6 months ago

@shahinyan11 Let's focus on narrowing down the root cause first

shahinyan11 commented 6 months ago

@s77rt Ok I will work on it

shahinyan11 commented 6 months ago

@s77rt With the latest version, I can't reproduce the case where the same GetNewerActions request is sent multiple times. The only remaining case is when GetNewActions is called from a previous report.

s77rt commented 6 months ago

@shahinyan11 Was not able to reproduce that bug either. And for the case where GetNewActions is called from the previous report, this is not reproducible all the time. The root cause for this one is still not clear

https://github.com/Expensify/App/assets/16493223/20561048-ffe0-4a1c-83af-1b5c0d27f6ee

shahinyan11 commented 6 months ago

@s77rt in fact, the loadNewerChats function is always called for both the previous and the current report. But GetNewActions request will not be called for the previous report if there are more than 23 reportActions in it. Here we prevent action if the isLoadingOlderReportsFirstNeeded is true

s77rt commented 6 months ago

@shahinyan11 loadNewerChats shouldn't be called in the first place. Re-rendering ReportActionsList on its own is not the culprit

https://github.com/Expensify/App/assets/16493223/d402fbf9-ecf9-401e-8096-c654395db780

quinthar commented 6 months ago

So I'm a bit confused, where does this stand? What are the next steps, and who is doing them?

twisterdotcom commented 6 months ago

This is following the normal BugZero process, no changes to that. We're not yet understanding the root cause and @s77rt and @shahinyan11 are discussing it. It remains open to other External proposals.

shahinyan11 commented 6 months ago

@s77rt onStartReached is called for the previous report even if I manually prevent the MVCPFlatList component from re-rendering. I think this behavior is coming from the react-native-web package because I noticed onStartReached in the patch files and I also tested it on Native platforms and onStartReached is not called for the previous report after navigating to the new one

s77rt commented 6 months ago

@shahinyan11 Can you elaborate on this? Is the bug caused by the react-native-web patch?

shahinyan11 commented 6 months ago

@shahinyan11 Can you elaborate on this? Is the bug caused by the react-native-web patch?

Yes, this is the result of my research about calling loadNewerChats.

s77rt commented 6 months ago

@shahinyan11 Did you explore any possible solutions here?

(also try revert the patch to be sure it's the culprit)

twisterdotcom commented 6 months ago

For opening a single report, why do I need to do all of these actions. Two OpenReport, two GetNewerActions, two SendPerformanceTiming. I guess most of it could be resolved by removing the second GetNewerActions call here, but I was surprised to see us call OpenReport again as well, and I've got to imagine they're linked.

image
shahinyan11 commented 6 months ago

(also try revert the patch to be sure it's the culprit)

I won't say it's because of the patch. Аrom the patch file I just realized that the package handles onStartReached. Tried deleting the patch file, but the behavior did not change.

s77rt commented 6 months ago

@shahinyan11 Please update your proposal and tag me once you get a clear understanding on the root cause.

PS: Keep in mind that we probably still have 2 bugs here, the GetNewerActions calls on same report (seems hard to reproduce) and the GetNewerActions call on the previous report

melvin-bot[bot] commented 6 months ago

📣 It's been a week! Do we have any satisfactory proposals yet? Do we need to adjust the bounty for this issue? 💸

melvin-bot[bot] commented 6 months ago

@twisterdotcom @s77rt this issue was created 2 weeks ago. Are we close to approving a proposal? If not, what's blocking us from getting this issue assigned? Don't hesitate to create a thread in #expensify-open-source to align faster in real time. Thanks!

shahinyan11 commented 6 months ago

@twisterdotcom @s77rt Would you mind increase the compensation here as this is not an easy subject and takes a lot of time to learn RCA.

twisterdotcom commented 6 months ago

Sure, we can make this $500, it's reliability. As long as we get to the root cause.

melvin-bot[bot] commented 6 months ago

Upwork job price has been updated to $500

quinthar commented 6 months ago

Hi all, anybody able to take this on? It's an important one!

s77rt commented 6 months ago

Posted on slack to get more attention

twisterdotcom commented 6 months ago

Also discussed internally here: https://expensify.slack.com/archives/C01SKUP7QR0/p1713818410907859

Still would love to get some external proposals. @shahinyan11 any more thoughts here?

shahinyan11 commented 6 months ago

@twisterdotcom If the onStartReached function of FlatList should not be called while the screen is blurring, then I think it is a react-native-web bug, I am going to investigate it when I have time but currently don't know how to fix this in the package. But if it is expected behavior then I already proposed solution

twisterdotcom commented 6 months ago

@s77rt what do you think? It's kind of over my head I'm afraid.

s77rt commented 6 months ago

Reminder: We have two bugs:

  1. On opening a report we make multiple calls to GetNewerActions (onStartReached)
  2. On unmounting a report we make an extra call to GetNewerActions (onStartReached)

I tried to isolate the problem by creating a snack https://snack.expo.dev/IDlFHIFq6DZP2MIDaqs-T and I can tell that the first problem is in react-native and the second is from our side.

Results:

Regarding the first bug, upon further testing I concluded that onStartReached will be called upto n times where n = Math.ceil(data.length / initialNumToRender). The more report actions in a chat the more the buggy behaviour is experienced.

https://github.com/Expensify/App/assets/16493223/2387505c-13cb-4ddd-a2d8-92b515b11489

s77rt commented 6 months ago

From ^ We have to fix the first bug at react-native level and second bug at /App level.

shahinyan11 commented 6 months ago

@s77rt Thanks for providing useful information. But we make an extra call to GetNewerActions (onStartReached) not when unmounting, but when the screen is blurred. And this behavior only happens on Web I also created a snack (https://snack.expo.dev/@shahinyan11/flatlist-simple?platform=web with navigation. And you can see that the second problem also is not from our side.

https://github.com/Expensify/App/assets/46921547/708b59b8-e877-4f9b-af6f-4aa85f66eb29

s77rt commented 6 months ago

@shahinyan11 You are right thanks for checking that! Both bugs are upstream

s77rt commented 6 months ago

Bugs summary:

twisterdotcom commented 6 months ago

Wow, amazing work here both. Okay, so which repos do we need fixes in? Just react-native-web? We typically pay higher bounties for upstream fixes and I'm willing to commit to that here.

shahinyan11 commented 6 months ago

I think we can consider handling those behaviors in src/components/FlatList component as well.

s77rt commented 6 months ago

@twisterdotcom react-native and react-native-web both need to be fixed.

s77rt commented 6 months ago

@shahinyan11 Upstream bugs require upstream PRs. Handling any /App would have to be a workaround

twisterdotcom commented 6 months ago

I'm open to a workaround for now if @s77rt agrees it's not going to be too detrimental, as upstream PRs often take ages to merge and this is something we think might be causing a fair few issues. Asking internally if we know of anybody with more clout with their maintainers who might take on the upstreams.

s77rt commented 6 months ago

Finding the root cause on RNW may be easier. We can start by checking the number of calls to _maybeCallOnEdgeReached and find in which case it's called more often i.e. on blur which function calls this one.

s77rt commented 6 months ago

@twisterdotcom For the RNW bug (the one extra call) the workaround is pretty straightforward which is to ignore onStartReached callbacks if the screen is not focused. For the RN bug (the many extra calls) no clear workaround yet