Messages sent on staging web are only appearing after navigate away from the report and run OpenReport again #51132

m-natarajan · 2024-10-19T19:01:39Z

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

Version Number:
Reproducible in staging?: Needs Reproduction
Reproducible in production?: Needs Reproduction
If this was caught on HybridApp, is this reproducible on New Expensify Standalone?:
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: @muttmuure
Slack conversation: https://expensify.slack.com/archives/C05LX9D6E07/p1729266448987419

Action Performed:

Log in to web and native app with same account as user A
Send messages to User A from user B

Expected Result:

Messages delivered to both the devices at the same time

Actual Result:

Not receiving messages in web on real time but getting push notifications for the same in app. Messages sent on staging web are only appearing after navigate away from the report and run OpenReport again

Workaround:

Unknown

Platforms:

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

Screenshots/Videos

Add any screenshot/video evidence

{
    "chatType": "group",
    "currency": "USD",
    "description": "",
    "errorFields": {},
    "hasOutstandingChildRequest": false,
    "hasOutstandingChildTask": false,
    "isCancelledIOU": false,
    "isOwnPolicyExpenseChat": false,
    "isPinned": true,
    "isWaitingOnBankAccount": false,
    "lastActionType": "ADDCOMMENT",
    "lastActorAccountID": 6851710,
    "lastMentionedTime": "2024-10-16 15:23:27.935",
    "lastMessageHtml": "that's so weird",
    "lastMessageText": "could you ping me on Slack if you've replied already? I'll copy the onyx data f…",
    "lastReadSequenceNumber": 0,
    "lastReadTime": "2024-10-18 15:24:29.471",
    "lastVisibleActionCreated": "2024-10-18 15:24:29.471",
    "lastVisibleActionLastModified": "2024-10-18 15:23:06.471",
    "nonReimbursableTotal": 0,
    "notificationPreference": "always",
    "oldPolicyName": "",
    "ownerAccountID": 0,
    "participants": {
        "778531": {
            "hidden": false,
            "notificationPreference": "always",
            "role": "member"
        },
        "2697693": {
            "hidden": false,
            "notificationPreference": "always",
            "role": "member"
        },
        "6851710": {
            "hidden": false,
            "notificationPreference": "always",
            "role": "member"
        },
        "10160771": {
            "hidden": false,
            "notificationPreference": "always",
            "role": "admin"
        }
    },
    "permissions": [
        "read",
        "write",
        "share"
    ],
    "policyID": "_FAKE_",
    "private_isArchived": "",
    "reportID": "4160486413986541",
    "reportName": "NewDot Quality Curation",
    "stateNum": 0,
    "statusNum": 0,
    "total": 0,
    "type": "chat",
    "unheldTotal": 0,
    "welcomeMessage": "",
    "writeCapability": "all",
    "lastMessageTranslationKey": "",
    "state": "OPEN",
    "unheldNonReimbursableTotal": 0
}

logs-2024-10-18 15_34_39.778.txt

View all open jobs on GitHub

The text was updated successfully, but these errors were encountered:

melvin-bot · 2024-10-19T19:01:51Z

Triggered auto assignment to @justinpersaud (AutoAssignerNewDotQuality)

melvin-bot · 2024-10-19T19:01:52Z

Triggered auto assignment to @zanyrenney (Bug), see https://stackoverflow.com/c/expensify/questions/14418 for more details. Please add this bug to a GH project, as outlined in the SO.

MelvinBot · 2024-10-19T19:02:22Z

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

justinpersaud · 2024-10-21T18:56:25Z

Is this still happening? I am not able to reproduce

justinpersaud · 2024-10-21T22:17:25Z

Ok seems like I sort of was able to reproduce this.

I left staging web open in the background for a few hours. I then went back to the tab and saw no new messages were posted in #social.

However, I didn't do anything else and eventually it just updated everything at once.

muttmuure · 2024-10-22T00:35:11Z

Yes it was happening to me this morning. I wasn't receiving updates until I navigated back to the report

muttmuure · 2024-10-22T00:36:08Z

It's going to be tough to establish reproduction steps if you can't do it straight away, I thought it was an obvious regression but perhaps not

zanyrenney · 2024-10-23T10:53:18Z

Matt - do you mind taking this one if you're experiencing it? I can't access staging at all so it's not possible for me to test this? https://expensify.slack.com/archives/C049HHMV9SM/p1729158805892819

cc @muttmuure

muttmuure · 2024-10-23T11:53:31Z

I think for this one, we need to trace the logs at the time, and understand if pusher was disconnected

zanyrenney · 2024-10-25T13:52:07Z

@muttmuure mind nailing down some of the specifics to help with the logsearch? I am seeing 93 instances of pusher in them.

https://www.expensify.com/_devportal/tools/logSearch/#sort=asc&size=2000&query=email%3A%22mmoore%40expensify.com%22%20AND%20timestamp%3A%5B2024-09-20T00%3A00%20TO%202024-10-26T23%3A59%5D

zanyrenney · 2024-10-28T16:54:17Z

bump @muttmuure

muttmuure · 2024-10-28T18:28:39Z

So to narrow this down, I think we should look for:

The time stamps around when I was reporting this.
The instances where pusher failed

muttmuure · 2024-10-28T18:48:24Z

This is the one I was looking for: https://www.expensify.com/_devportal/tools/logSearch/#query=request_id:(%228d4993c3095093f3-LHR%22)+AND+timestamp:[2024-10-18T14:31:45.887Z+TO+2024-10-18T16:31:45.887Z]&index=logs_expensify-030777

zanyrenney · 2024-10-30T12:03:33Z

Cool, Matt - cheers!

@justinpersaud do those Logs help you to push this forward? I don't think there is more the BZ can do here now Matt has got that log search.

Thanks in advance!

justinpersaud · 2024-10-30T12:52:19Z

In the logs Matt provided I see this

[App] 2024-10-18T15:31:44.995Z - [alXt] Unhandled Promise Rejection: Failed to write blobs (InvalidBlob)#012Stack: undefined ~~ userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/129.0.0.0 Safari/537.36'

Searching for that error, it seems this is not the first time we've seen similar issues

#45356

I bumped the old thread https://expensify.slack.com/archives/C05LX9D6E07/p1730292728785699?thread_ts=1721217121.843389&cid=C05LX9D6E07

justinpersaud · 2024-10-31T20:13:49Z

@chrispader I see you in the blame here for this https://github.com/Expensify/react-native-onyx/blob/main/lib/Onyx.ts#L274-L298

I think that is where the error above is coming from. Do you happen to have any ideas here?

justinpersaud · 2024-11-01T14:43:40Z

I'm going to be OOO next week but @chrispader said he would look into this later today.

melvin-bot · 2024-11-02T17:59:59Z

@justinpersaud @zanyrenney this issue was created 2 weeks ago. Are we close to a solution? Let's make sure we're treating this as a top priority. Don't hesitate to create a thread in #expensify-open-source to align faster in real time. Thanks!

zanyrenney · 2024-11-04T18:05:37Z

hey @chrispader any update on this one, please?

zanyrenney · 2024-11-04T18:06:00Z

Unfortunately i'm not able to assign you.

zanyrenney · 2024-11-04T18:07:49Z

also bumped here - https://expensify.slack.com/archives/C05LX9D6E07/p1730743660837999

melvin-bot · 2024-11-04T18:25:38Z

@justinpersaud, @zanyrenney Uh oh! This issue is overdue by 2 days. Don't forget to update your issues!

chrispader · 2024-11-05T17:11:31Z

Sorry for the delay. I'm looking into it later today!

chrispader · 2024-11-06T17:01:52Z

@chrispader I see you in the blame here for this Expensify/react-native-onyx@main/lib/Onyx.ts#L274-L298

The highlighted code in react-native-onyx is at a very low-level in the Onyx.merge function. This code basically just handles null values passed as the merge delta, logs info about the merge and handles different merge approaches for web (IndexedDB) vs native (SQLite).

I think that is where the error above is coming from. Do you happen to have any ideas here?

Therefore, i don't think this issue is directly caused by this code. We implemented this already a while back and so far, we didn't have any regressions because of this. (@justinpersaud, i know you're OOO so no hurry in answering, but how did you get to exactly this piece of code?)

The main thing we had to migrate from since this change was that null values passed to Onyx.merge/Onyx.setact as a "deleting" instruction to Onyx. We might want to check if any of the E/App report (action) related code handles null values incorrectly.

chrispader · 2024-11-06T17:05:16Z

I couldn't reproduce this issue myself. I tried the repro steps but always received messages on both native device and (staging) web.

Also i think the repro steps should be improved. E.g. in what state should each of the devices/sessions be? E.g. on the phone, should the app and chat be opened or not? Afaik, the user doesn't receive notifications when the app is in foreground.

On web, should the affected report be focussed or not?

chrispader · 2024-11-06T17:06:36Z

@zanyrenney i can ofc continue investigating this issue if you want, but i'm not sure if someone else is supposed to fix this. I'd probably need some more repro steps in order to actually see this issue :)

zanyrenney · 2024-11-07T18:14:29Z

We’re waiting until @justinpersaud returns because he identified Chris in the blame, but Chris isn’t clear on why or how. If we want Chris to investigate, we can, but it would be helpful to get the missing context from Justin!

zanyrenney · 2024-11-11T14:04:22Z

Hey @justinpersaud - I think you're back from OOO now. Mind reviewing this and clarifying for us, please? Thanks!

justinpersaud · 2024-11-11T17:19:49Z

@chrispader I got there from the logs @muttmuure provided above. Here they are since you can't see them

[App] PID ~~ 2184342
[App] Processing 'Log' for 'expensify.com' from '104.28.160.249' ~~ command: 'Log' api_setCookie: 'false' expensifyCashAppVersion: 'expensifyCash[web]9.0.50-8' appversion: '9.0.50-8' referer: 'ecash' platform: 'web' email: '[email protected]' isFromDevEnv: 'false' clientUpdateID: '2472469029' partnerName: 'expensify.com' browserGUID: '67127f61d7e2b' HTTP_CF_BOT_SCORE: '99' HTTP_CF_JA3_HASH: '550518ce2834286070c227fa8bc8c9d9'
[App] 2024-10-18T15:26:30.647Z - [info] Previous log requestID ~~ requestID: '8d498c107bfd93f3-LHR' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/129.0.0.0 Safari/537.36'
[App] 2024-10-18T15:26:30.647Z - [info] [OnyxUpdateManager] Applying update type: https with lastUpdateID: 0 ~~ command: 'Log' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/129.0.0.0 Safari/537.36'
[App] 2024-10-18T15:27:17.815Z - [info] [Onyx] set called for key: activeClients properties: 0,1,2,3,4,5 hasChanged: false ~~ parameters: '' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/129.0.0.0 Safari/537.36'
[App] 2024-10-18T15:31:39.557Z - [info] [Onyx] merge called for key: reportUserIsTyping_4160486413986541 properties: 778531 hasChanged: true ~~ parameters: '' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/129.0.0.0 Safari/537.36'
[App] 2024-10-18T15:31:40.783Z - [info] [Onyx] merge called for key: reportUserIsTyping_4160486413986541 properties: 778531 hasChanged: false ~~ parameters: '' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/129.0.0.0 Safari/537.36'
[App] 2024-10-18T15:31:42.286Z - [info] [Onyx] merge called for key: reportUserIsTyping_4160486413986541 properties: 778531 hasChanged: true ~~ parameters: '' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/129.0.0.0 Safari/537.36'
[App] 2024-10-18T15:31:44.993Z - [info] [Report] Handled multipleEvents event sent by Pusher ~~ updates: '[0: '[data: '[0: '[key: 'report_4160486413986541' onyxMethod: 'merge' value: '[participants: '[778531: '[hidden: '' notificationPreference: 'always' role: 'member']' 2697693: '[hidden: '' notificationPreference: 'always' role: 'member']' 6851710: '[hidden: '' notificationPreference: 'always' role: 'member']' 10160771: '[hidden: '' notificationPreference: 'always' role: 'admin']']']']' 1: '[key: 'report_4160486413986541' onyxMethod: 'merge' value: '[chatType: 'group' description: '' lastActorAccountID: '778531' lastMessageText: '<REDACTED>' lastVisibleActionCreated: '2024-10-18 15:31:40.375' managerID: '' ownerAccountID: '0' parentReportActionID: '' parentReportID: '' policyID: '_FAKE_' reportID: '4160486413986541' reportName: 'NewDot Quality Curation' state: 'OPEN' stateNum: '0' statusNum: '0' type: 'chat' visibility: '']']' 2: '[key: 'reportActions_4160486413986541' onyxMethod: 'merge' shouldShowPushNotification: '1' value: '[3075963487890658293: '[actionName: 'ADDCOMMENT' actorAccountID: '778531' avatar: 'https://d1wpcgnaa73g0y.cloudfront.net/36e397299365c36a787b6084a641bd2fe1b28a58_128.jpeg' created: '2024-10-18 15:31:40.375' lastModified: '2024-10-18 15:31:40.375' message: '[0: '[html: '<REDACTED>' text: '<REDACTED>' type: 'COMMENT' whisperedTo: '[]']']' originalMessage: '[html: '<REDACTED>' isNewDot: '1' lastModified: '2024-10-18 15:31:40.375']' person: '[0: '[style: 'strong' text: '<REDACTED>' type: 'TEXT']']' reportActionID: '3075963487890658293' shouldShow: '1']']']' 3: '[key: 'personalDetailsList' onyxMethod: 'merge' value: '[778531: '[accountID: '778531' avatar: 'https://d1wpcgnaa73g0y.cloudfront.net/36e397299365c36a787b6084a641bd2fe1b28a58_128.jpeg' displayName: 'Puneet Lath' firstName: 'Puneet' lastName: 'Lath' login: '[email protected]' phoneNumber: '' pronouns: '__predefined_heHimHis' status: '' timezone: '[automatic: '1' selected: 'America/New_York']' validated: '1']']']']' eventType: 'onyxApiUpdate']']' lastUpdateID: '2472469029' previousUpdateID: '2472339842' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/129.0.0.0 Safari/537.36'
[App] 2024-10-18T15:31:44.993Z - [info] [OnyxUpdateManager] Applying update type: pusher with lastUpdateID: 2472469029 ~~ userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/129.0.0.0 Safari/537.36'
[App] 2024-10-18T15:31:44.994Z - [info] [Onyx] merge called for key: OnyxUpdatesLastUpdateIDAppliedToClient hasChanged: true ~~ parameters: '' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/129.0.0.0 Safari/537.36'
[App] 2024-10-18T15:31:44.995Z - [alXt] Unhandled Promise Rejection: Failed to write blobs (InvalidBlob)#012Stack: undefined ~~ userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/129.0.0.0 Safari/537.36'
[App] ~~ userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/129.0.0.0 Safari/537.36'
[App] StoreUtils - Clearing all the stores.
[App] TransactionStore cache fully cleared
[App] ReportStore cache cleared
[App] NVPStore - clear cache
[App] NVPStore - clear cache
[App] SharedInNVPStore - clear cache
[App] ReportDuplicatedTransactionsStore - Cache cleared
bench] [[App] Bench totals for command Log ~~ {"total":0}
[App] Profile ~~ {"total":9,"cmd":"Log","jsonCode":200,"output":{"size":71,"gzip":1,"ratio":139},"gzip":71,"PHP":{"total":9,"%":100,"boot":5,"proc":4,"pack":0,"mem":2}}
[App] Timing: cmd= Log totalTime= 9 authTotalTime= authRunTime= 0

I see that it was doing an onyx merge right before, so that is where I found that code.

chrispader · 2024-11-12T15:16:39Z

@chrispader I got there from the logs @muttmuure provided above. Here they are since you can't see them

Hmm, so based on the logs i don't think this is an issue with the logic in Onyx.merge itself.

I happen to have also worked on the OnyxUpdateManager logic, which is in charge of handling missing Onyx updates. Based on the onyx key OnyxUpdatesLastUpdateIDAppliedToClient we keep track of missing updates, that haven't been received from the backend and that are therefore fetched manually with the GetMissingOnyxUpdates query.

[App] 2024-10-18T15:31:44.994Z - [info] [Onyx] merge called for key: OnyxUpdatesLastUpdateIDAppliedToClient hasChanged: true ~~ parameters: '' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/129.0.0.0 Safari/537.36'

The merge executed on this key effectively just changes a number value. Therefore i don't think the following error ("Failed to write blobx") stems from this merge:

[App] 2024-10-18T15:31:44.995Z - [alXt] Unhandled Promise Rejection: Failed to write blobs (InvalidBlob)#012Stack: undefined

The last Onyx.merge log must not necessarily be causing this issue. Most likely it is actually caused by some Onyx operation, but i think the problem is more about the actual content/value that we're trying to set

Since this issue is occurring on web, this is most likely caused by either IndexedDB or some other library. I did some research and found e.g. this thread: https://issues.chromium.org/issues/40728654

(This might be related to storage being almost full.)

chrispader · 2024-11-12T15:18:42Z

As said before, i can start investigating this issue if you guys want, but i couldn't reproduce it the last time i tested, so any further repro steps and maybe more (detailed) logs would be very much appreciated! 🙌

justinpersaud · 2024-11-12T17:33:04Z

I have been trying to reproduce but no luck here.

justinpersaud · 2024-11-13T15:26:13Z

We're going to close this off due to lack of reliable reproduction steps. Can revisit it again in the future if we see it https://expensify.slack.com/archives/C05LX9D6E07/p1731510575229519

m-natarajan added Daily KSv2 Needs Reproduction Reproducible steps needed Bug Something is broken. Auto assigns a BugZero manager. AutoAssignerNewDotQuality Used to assign quality issues to engineers labels Oct 19, 2024

m-natarajan added this to [#whatsnext] #quality Oct 19, 2024

melvin-bot bot assigned justinpersaud Oct 19, 2024

melvin-bot bot added the Weekly KSv2 label Oct 19, 2024

melvin-bot bot assigned zanyrenney Oct 19, 2024

melvin-bot bot removed the Weekly KSv2 label Oct 19, 2024

muttmuure moved this to MEDIUM in [#whatsnext] #quality Oct 23, 2024

melvin-bot bot added the Overdue label Nov 4, 2024

melvin-bot bot removed the Overdue label Nov 4, 2024

melvin-bot bot added the Overdue label Nov 11, 2024

melvin-bot bot removed the Overdue label Nov 11, 2024

justinpersaud closed this as completed Nov 13, 2024

github-project-automation bot moved this from MEDIUM to Done in [#whatsnext] #quality Nov 13, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Messages sent on staging web are only appearing after navigate away from the report and run OpenReport again #51132

Messages sent on staging web are only appearing after navigate away from the report and run OpenReport again #51132

m-natarajan commented Oct 19, 2024 •

edited by muttmuure

Loading

melvin-bot bot commented Oct 19, 2024

melvin-bot bot commented Oct 19, 2024

MelvinBot commented Oct 19, 2024

justinpersaud commented Oct 21, 2024

justinpersaud commented Oct 21, 2024

muttmuure commented Oct 22, 2024

muttmuure commented Oct 22, 2024

zanyrenney commented Oct 23, 2024

muttmuure commented Oct 23, 2024

zanyrenney commented Oct 25, 2024

zanyrenney commented Oct 28, 2024

muttmuure commented Oct 28, 2024

muttmuure commented Oct 28, 2024

zanyrenney commented Oct 30, 2024

justinpersaud commented Oct 30, 2024

justinpersaud commented Oct 31, 2024

justinpersaud commented Nov 1, 2024

melvin-bot bot commented Nov 2, 2024

zanyrenney commented Nov 4, 2024

zanyrenney commented Nov 4, 2024

zanyrenney commented Nov 4, 2024

melvin-bot bot commented Nov 4, 2024

chrispader commented Nov 5, 2024

chrispader commented Nov 6, 2024 •

edited

Loading

chrispader commented Nov 6, 2024

chrispader commented Nov 6, 2024

zanyrenney commented Nov 7, 2024

zanyrenney commented Nov 11, 2024

justinpersaud commented Nov 11, 2024

chrispader commented Nov 12, 2024 •

edited

Loading

chrispader commented Nov 12, 2024

justinpersaud commented Nov 12, 2024

justinpersaud commented Nov 13, 2024

Messages sent on staging web are only appearing after navigate away from the report and run OpenReport again #51132

Messages sent on staging web are only appearing after navigate away from the report and run OpenReport again #51132

Comments

m-natarajan commented Oct 19, 2024 • edited by muttmuure Loading

Action Performed:

Expected Result:

Actual Result:

Workaround:

Platforms:

Screenshots/Videos

melvin-bot bot commented Oct 19, 2024

melvin-bot bot commented Oct 19, 2024

MelvinBot commented Oct 19, 2024

justinpersaud commented Oct 21, 2024

justinpersaud commented Oct 21, 2024

muttmuure commented Oct 22, 2024

muttmuure commented Oct 22, 2024

zanyrenney commented Oct 23, 2024

muttmuure commented Oct 23, 2024

zanyrenney commented Oct 25, 2024

zanyrenney commented Oct 28, 2024

muttmuure commented Oct 28, 2024

muttmuure commented Oct 28, 2024

zanyrenney commented Oct 30, 2024

justinpersaud commented Oct 30, 2024

justinpersaud commented Oct 31, 2024

justinpersaud commented Nov 1, 2024

melvin-bot bot commented Nov 2, 2024

zanyrenney commented Nov 4, 2024

zanyrenney commented Nov 4, 2024

zanyrenney commented Nov 4, 2024

melvin-bot bot commented Nov 4, 2024

chrispader commented Nov 5, 2024

chrispader commented Nov 6, 2024 • edited Loading

chrispader commented Nov 6, 2024

chrispader commented Nov 6, 2024

zanyrenney commented Nov 7, 2024

zanyrenney commented Nov 11, 2024

justinpersaud commented Nov 11, 2024

chrispader commented Nov 12, 2024 • edited Loading

chrispader commented Nov 12, 2024

justinpersaud commented Nov 12, 2024

justinpersaud commented Nov 13, 2024

m-natarajan commented Oct 19, 2024 •

edited by muttmuure

Loading

chrispader commented Nov 6, 2024 •

edited

Loading

chrispader commented Nov 12, 2024 •

edited

Loading