Chat - Second and subsequent messages not displayed in chat until chat reloaded

[lanitochka17]

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-2
Reproducible in staging?: Y
Reproducible in production?: N
If this was caught during regression testing, add the test name, ID and link from TestRail: N/A
Issue reported by: Applause - Internal Team

Issue found when executing PR #34902

Action Performed:

Precondition: user signed up with a new account A on the main testing device and account B on secondary device or app

1. Open https://staging.new.expensify.com/
2. From secondary account B create chat with account A on the main device
3. Send a first message from a secondary account B to account A
4. Open chat on main device with account B
5. Verify that message received and displayed in chat
6. Send second message from secondary device to account A
7. Verify if message received and displayed in chat on main device
8. Repeat steps 6-7 a few times
9. Navigate to other conversation
10. Navigate back to main conversation with account B

Expected Result:

All messages should be displayed in chat. Second and subsequent messages are missing

Actual Result:

Only first message displayed in chat. The second and subsequent messages missing until chat will be reloaded

Workaround:

Unknown

Platforms:

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

• Android: Native
• Android: mWeb Chrome
• iOS: Native
• iOS: mWeb Safari
• MacOS: Chrome / Safari
• MacOS: Desktop

Screenshots/Videos

Add any screenshot/video evidence

Bug6438253_1712260999641.Screen_Recording_2024-04-04_at_22.57.08.mp4

View all open jobs on GitHub

[melvin-bot]

Triggered auto assignment to @hayata-suenaga (DeployBlockerCash), see https://stackoverflowteams.com/c/expensify/questions/9980/ for more details.

[github-actions]

👋 Friendly reminder that deploy blockers are time-sensitive ⏱ issues! Check out the open `StagingDeployCash` deploy checklist to see the list of PRs included in this release, then work quickly to do one of the following:

1. Identify the pull request that introduced this issue and revert it.
2. Find someone who can quickly fix the issue.
3. Fix the issue yourself.

[lanitochka17]

@hayata-suenaga FYI I haven't added the External label as I wasn't 100% sure about this issue. Please take a look and add the label if you agree it's a bug and can be handled by external contributors

[jasperhuangg]

This definitely just seems like a case of Pusher being really slow to send the updates, I don't think this needs to be a blocker since if there is a problem it exists in the back-end anyways. Still probably a good thing to investigate,

[aldo-expensify]

In the video it looks like pusher events with the report updates are reaching the other client, but the report actions maybe not?

The steps are somewhat confusing to me when it mixes account A/B and main/secondary device. Is the "secondary/main device" only mentioned to say that both accounts are logged in simultaneously in different devices?

[aldo-expensify]

@lanitochka17 is this step wrong?

Open chat on main device with account B

The "account A" is supposed to be using the "main device", right?

[aldo-expensify]

Reproduced

[aldo-expensify]

I can see that the SendFetchableUpdates job pushed the update with the new reportAction to both accounts in these logs.

BhxPoR	staging-www1.sjc	2024-04-04 23:29:44 469	we@dont.know	[push] Push_Service - Sending chunked event ~~ name: 'multipleEvents' channels: '[0: 'private-encrypted-user-accountID-16596361']' shouldChunk: '1' data: '[updates: '[0: '[data: '[0: '[key: 'report_6583009741597437' onyxMethod: 'merge' value: '[lastActorAccountID: '16596362' lastMentionTime: '2024-04-04 23:29:37.409' lastMessageText: '<REDACTED>' lastVisibleActionCreated: '2024-04-04 23:29:37.409' maxSequenceNumber: '2' reportID: '6583009741597437']']' 1: '[key: 'reportActions_6583009741597437' onyxMethod: 'merge' shouldNotify: '1' value: '[4501046319237944138: '[actionName: 'ADDCOMMENT' actorAccountID: '16596362' automatic: '' avatar: 'https://d2k5nsl2zxldvw.cloudfront.net/images/avatars/default-avatar_3.png' created: '2024-04-04 23:29:37.409' isAttachment: '' lastModified: '2024-04-04 23:29:37.409' message: '[0: '[deleted: '' html: '<REDACTED>' isDeletedParentAction: '' isEdited: '' reactions: '[]' text: '<REDACTED>' type: 'COMMENT' whisperedTo: '[]']']' originalMessage: '[html: '<REDACTED>' lastModified: '2024-04-04 23:29:37.409']' person: '[0: '[style: 'strong' text: '<REDACTED>' type: 'TEXT']']' previousReportActionID: '1864704912092156641' reportActionID: '4501046319237944138' reportActionTimestamp: '1712273377409' sequenceNumber: '2' shouldShow: '1' timestamp: '1712273377' whisperedToAccountIDs: '[]']']']']' eventType: 'onyxApiUpdate']']' lastUpdateID: '239122686' previousUpdateID: '239122475']' socket_id: '692979.212478'
BhxPoR	staging-www1.sjc	2024-04-04 23:29:44 470	we@dont.know	[push] Push_Service - Sending chunked event ~~ name: 'multipleEvents' channels: '[0: 'private-encrypted-user-accountID-16596362']' shouldChunk: '1' data: '[updates: '[0: '[data: '[0: '[key: 'report_6583009741597437' onyxMethod: 'merge' value: '[lastActorAccountID: '16596362' lastMentionTime: '2024-04-04 23:29:37.409' lastMessageText: '<REDACTED>' lastVisibleActionCreated: '2024-04-04 23:29:37.409' maxSequenceNumber: '2' reportID: '6583009741597437']']' 1: '[key: 'reportActions_6583009741597437' onyxMethod: 'merge' shouldNotify: '1' value: '[4501046319237944138: '[actionName: 'ADDCOMMENT' actorAccountID: '16596362' automatic: '' avatar: 'https://d2k5nsl2zxldvw.cloudfront.net/images/avatars/default-avatar_3.png' created: '2024-04-04 23:29:37.409' isAttachment: '' lastModified: '2024-04-04 23:29:37.409' message: '[0: '[deleted: '' html: '<REDACTED>' isDeletedParentAction: '' isEdited: '' reactions: '[]' text: '<REDACTED>' type: 'COMMENT' whisperedTo: '[]']']' originalMessage: '[html: '<REDACTED>' lastModified: '2024-04-04 23:29:37.409']' person: '[0: '[style: 'strong' text: '<REDACTED>' type: 'TEXT']']' previousReportActionID: '1864704912092156641' reportActionID: '4501046319237944138' reportActionTimestamp: '1712273377409' sequenceNumber: '2' shouldShow: '1' timestamp: '1712273377' whisperedToAccountIDs: '[]']']']']' eventType: 'onyxApiUpdate']']' lastUpdateID: '239122686' previousUpdateID: '239122475']' socket_id: '692979.212478'

The receiver account is 16596361 (aldo+test39650-account-a@expensifail.com)
The sender account is 16596362 (aldo+test39650-account-b@expensifail.com)

When looking in dev tools > Application > keyvaluepair > reportActions_6583009741597437, the comment was never added there.

I can see in the console that the event with the comment did reach the front end:

[info] [Report] Handled multipleEvents event sent by Pusher - {"updates":[{"data":[{"key":"report_6583009741597437","onyxMethod":"merge","value":{"lastActorAccountID":16596362,"lastMentionTime":"2024-04-04 23:29:37.409","lastMessageText":"second message","lastVisibleActionCreated":"2024-04-04 23:29:37.409","maxSequenceNumber":2,"reportID":"6583009741597437"}},{"key":"reportActions_6583009741597437","onyxMethod":"merge","shouldNotify":true,"value":{"4501046319237944138":{"actionName":"ADDCOMMENT","actorAccountID":16596362,"automatic":false,"avatar":"https://d2k5nsl2zxldvw.cloudfront.net/images/avatars/default-avatar_3.png","created":"2024-04-04 23:29:37.409","isAttachment":false,"lastModified":"2024-04-04 23:29:37.409","message":[{"deleted":"","html":"second message","isDeletedParentAction":false,"isEdited":false,"reactions":[],"text":"second message","type":"COMMENT","whisperedTo":[]}],"originalMessage":{"html":"second message","lastModified":"2024-04-04 23:29:37.409"},"person":[{"style":"strong","text":"aldo+test39650-account-b@expensifail.com","type":"TEXT"}],"previousReportActionID":"1864704912092156641","reportActionID":"4501046319237944138","reportActionTimestamp":1712273377409,"sequenceNumber":2,"shouldShow":true,"timestamp":1712273377,"whisperedToAccountIDs":[]}}}],"eventType":"onyxApiUpdate"}],"lastUpdateID":239122686,"previousUpdateID":239122475}

but somehow it wasn't applied in Onyx? 🤷 X 1000

[aldo-expensify]

Tested in production, and it works fine there. Here is a comparison of the pusher events received in the front end in staging vs production. Both look the same to me, so I think the update shape or the backend is not the problem. The staging frontend seems to be ignoring the update for some reason.

Comparison onyx updates prod/staging

Staging

Production

{ "updates": [ { "data": [ { "key": "report_1869229811124868", "onyxMethod": "merge", "value": { "lastActorAccountID": 16596388, "lastMentionTime": "2024-04-04 23:42:24.502", "lastMessageText": "1", "lastVisibleActionCreated": "2024-04-04 23:42:24.502", "maxSequenceNumber": 4, "reportID": "1869229811124868" } }, { "key": "reportActions_1869229811124868", "onyxMethod": "merge", "shouldNotify": true, "value": { "4585206169631678243": { "actionName": "ADDCOMMENT", "actorAccountID": 16596388, "automatic": false, "avatar": "https://d2k5nsl2zxldvw.cloudfront.net/images/avatars/default-avatar_5.png", "created": "2024-04-04 23:42:24.502", "isAttachment": false, "lastModified": "2024-04-04 23:42:24.502", "message": [ { "deleted": "", "html": "1", "isDeletedParentAction": false, "isEdited": false, "reactions": [], "text": "1", "type": "COMMENT", "whisperedTo": [] } ], "originalMessage": { "html": "1", "lastModified": "2024-04-04 23:42:24.502" }, "person": [ { "style": "strong", "text": "aldo+test39650-account-b-prod@expensifail.com", "type": "TEXT" } ], "previousReportActionID": "7546131154617022882", "reportActionID": "4585206169631678243", "reportActionTimestamp": 1712274144502, "sequenceNumber": 4, "shouldShow": true, "timestamp": 1712274144, "whisperedToAccountIDs": [] } } } ], "eventType": "onyxApiUpdate" } ], "lastUpdateID": 239140017, "previousUpdateID": 239139159 }

{ "updates": [ { "data": [ { "key": "report_6583009741597437", "onyxMethod": "merge", "value": { "lastActorAccountID": 16596362, "lastMentionTime": "2024-04-04 23:42:53.899", "lastMessageText": "1", "lastVisibleActionCreated": "2024-04-04 23:42:53.899", "maxSequenceNumber": 5, "reportID": "6583009741597437" } }, { "key": "reportActions_6583009741597437", "onyxMethod": "merge", "shouldNotify": true, "value": { "5843399410900401428": { "actionName": "ADDCOMMENT", "actorAccountID": 16596362, "automatic": false, "avatar": "https://d2k5nsl2zxldvw.cloudfront.net/images/avatars/default-avatar_3.png", "created": "2024-04-04 23:42:53.899", "isAttachment": false, "lastModified": "2024-04-04 23:42:53.899", "message": [ { "deleted": "", "html": "1", "isDeletedParentAction": false, "isEdited": false, "reactions": [], "text": "1", "type": "COMMENT", "whisperedTo": [] } ], "originalMessage": { "html": "1", "lastModified": "2024-04-04 23:42:53.899" }, "person": [ { "style": "strong", "text": "aldo+test39650-account-b@expensifail.com", "type": "TEXT" } ], "previousReportActionID": "643022834268743072", "reportActionID": "5843399410900401428", "reportActionTimestamp": 1712274173899, "sequenceNumber": 5, "shouldShow": true, "timestamp": 1712274173, "whisperedToAccountIDs": [] } } } ], "eventType": "onyxApiUpdate" } ], "lastUpdateID": 239140637, "previousUpdateID": 239136944 }

[aldo-expensify]

Tried to reproduce in dev using main and tag 1.4.60-7 (current staging) and couldn't reproduce

[aldo-expensify]

Asked in slack: https://expensify.slack.com/archives/C01GTK53T8Q/p1712274581354349

The cause seems to be this PR #38997. Testing the ad-hoc build with the revert #39668 makes the problem disappear.

I also noticed that in staging, when the bug happens, the following log lines never appear:

[OnyxUpdateManager] Applying pusher update
[OnyxUpdateManager] Done applying Pusher update

[aldo-expensify]

This is fixed now: #39668 (comment)

[hayata-suenaga]

thank you Aldo for triaging this issue. Removing myself from assignment as I didn't fix the issue