Messages not appearing on desktop. New message appeared as iOS notification even though desktop app is open.

[marcaaron]

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

---

Action Performed:

1. Open app after away for the weekend
2. Receive a new message from another user

Expected Result:

When we start the New Expensify desktop app we should be subscribed to Pusher and notifications about new messages should appear on desktop.

Actual Result:

Pusher failed to subscribe to the private user channel (necessary to receive chat messages) and new messages were sent as device push notifications (iOS) instead despite being online and having the Desktop app open.

Workaround:

Refreshing the app command + r or closing and reopening seems to resolve this and fix the broken Pusher connection.

Platform:

• Desktop App

Version Number: 1.1.84.12
Reproducible in staging?: Yes
Reproducible in production?: Unknown
Email or phone of affected tester (no customers):
Logs:

72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 150 | marc@expensify.com | PID ~~ 1624330
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 150 | marc@expensify.com | Processing 'Log' for 'expensify.com' from '66.91.255.172' ~~ command: 'Log' api_setCookie: 'false' expensifyCashAppVersion: 'expensifyCash[desktop]1.1.84-11' appversion: '1.1.84-11' referer: 'ecash' platform: 'desktop' email: 'marc@expensify.com' partnerName: 'expensify.com' browserGUID: '62d58e7124bbe'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 150 | marc@expensify.com | [info] Persisted request failed ~~ retryCount: '1' command: 'OpenReport' error: 'Cannot complete sequential request because we are already authenticating' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 150 | marc@expensify.com | [info] Making API request ~~ command: 'SendPerformanceTiming' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 150 | marc@expensify.com | [info] Finished API request ~~ command: 'Get' shouldUseSecure: '' returnValueList: 'chatList' jsonCode: '407' requestID: '72ccb1cf7a84bc79-SJC' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 150 | marc@expensify.com | [info] Finished API request ~~ command: 'Get' shouldUseSecure: '' returnValueList: 'account, loginList, nameValuePairs' nvpNames: 'expensify_payPalMeAddress,expensify_preferredEmojiSkinTone,expensify_frequentlyUsedEmojis,private_blockedFromConcierge' jsonCode: '407' requestID: '72ccb1cf7a7fbc79-HNL' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [info] Finished API request ~~ command: 'OpenApp' jsonCode: '407' requestID: '72ccb1cf7a85bc79-HNL' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [info] Finished API request ~~ command: 'Get' shouldUseSecure: '' returnValueList: 'personalDetailsList' jsonCode: '407' requestID: '72ccb1cf7a83bc79-SJC' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [info] [PusherConnectionManager] unhandled event ~~ eventName: 'state_change' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [info] [PusherAuthorizer] Attempting to authorize Pusher ~~ channelName: 'private-report-reportID-74050763' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [info] Making API request ~~ command: 'AuthenticatePusher' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [info] [PusherConnectionManager] connected event ~~ parameters: '' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [info] [Pusher] Attempting to subscribe to channel ~~ channelName: 'private-encrypted-user-accountID-6533726' eventName: 'reportCommentEdit' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [info] [PusherAuthorizer] Attempting to authorize Pusher ~~ channelName: 'private-encrypted-user-accountID-6533726' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [info] Making API request ~~ command: 'AuthenticatePusher' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [info] [Pusher] Attempting to subscribe to channel ~~ channelName: 'private-encrypted-user-accountID-6533726' eventName: 'onyxApiUpdate' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [info] [Pusher] Attempting to subscribe to channel ~~ channelName: 'private-encrypted-user-accountID-6533726' eventName: 'preferredLocale' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [info] [Pusher] Attempting to subscribe to channel ~~ channelName: 'private-encrypted-user-accountID-6533726' eventName: 'screenshareRequest' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [info] [Pusher] Attempting to subscribe to channel ~~ channelName: 'public-policyEditor-010931807F672475' eventName: 'policyEmployeeRemoved' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [info] [Pusher] Attempting to subscribe to channel ~~ channelName: 'public-policyEditor-08D0600B8AAE868D' eventName: 'policyEmployeeRemoved' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [info] [Pusher] Attempting to subscribe to channel ~~ channelName: 'public-policyEditor-137DA25D273F2423' eventName: 'policyEmployeeRemoved' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [info] [Pusher] Attempting to subscribe to channel ~~ channelName: 'public-policyEditor-43BC6076D3D1418B' eventName: 'policyEmployeeRemoved' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [info] [Pusher] Attempting to subscribe to channel ~~ channelName: 'public-policyEditor-456619EAC8A1A4BF' eventName: 'policyEmployeeRemoved' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [info] [Pusher] Attempting to subscribe to channel ~~ channelName: 'public-policyEditor-6B40F9444C3F2EFF' eventName: 'policyEmployeeRemoved' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [info] [Pusher] Attempting to subscribe to channel ~~ channelName: 'public-policyEditor-7A35FD885AE104E1' eventName: 'policyEmployeeRemoved' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [info] [Pusher] Attempting to subscribe to channel ~~ channelName: 'public-policyEditor-A55A7962A1F001A4' eventName: 'policyEmployeeRemoved' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [info] [Pusher] Attempting to subscribe to channel ~~ channelName: 'public-policyEditor-C25E8D06D27010EB' eventName: 'policyEmployeeRemoved' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [info] [Onyx] set() called for key: reportWithDraft_74050763 ~~ parameters: '' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [info] Finished API request ~~ command: 'SendPerformanceTiming' jsonCode: '200' requestID: '72ccb1d3dd9abc79-SJC' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [info] [Onyx] set() called for key: networkRequestQueue properties: 0,1 ~~ parameters: '' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [info] Making API request ~~ command: 'OpenReport' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [info] Finished API request ~~ command: 'AuthenticatePusher' jsonCode: '407' requestID: '72ccb1d41ddabc79-HNL' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [hmmm] [PusherAuthorizer] Unhandled error: ~~ channelName: 'private-report-reportID-74050763' error: '[]' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [hmmm] [Pusher] Issue authenticating with Pusher during subscribe attempt. ~~ channelName: 'private-report-reportID-74050763' type: 'AuthError' error: 'AuthenticatePusher request failed' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [hmmm] [Report] Failed to initially subscribe to Pusher channel ~~ parameters: '' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [info] Previous log requestID ~~ requestID: '72ccb1d3dd9bbc79-SJC' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [info] Finished API request ~~ command: 'AuthenticatePusher' jsonCode: '407' requestID: '72ccb1d42ddebc79-SJC' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [hmmm] [PusherAuthorizer] Unhandled error: ~~ channelName: 'private-encrypted-user-accountID-6533726' error: '[]' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [hmmm] [Pusher] Issue authenticating with Pusher during subscribe attempt. ~~ channelName: 'private-encrypted-user-accountID-6533726' type: 'AuthError' error: 'AuthenticatePusher request failed' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [hmmm] [Pusher] Issue authenticating with Pusher during subscribe attempt. ~~ channelName: 'private-encrypted-user-accountID-6533726' type: 'AuthError' error: 'AuthenticatePusher request failed' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [hmmm] [Pusher] Issue authenticating with Pusher during subscribe attempt. ~~ channelName: 'private-encrypted-user-accountID-6533726' type: 'AuthError' error: 'AuthenticatePusher request failed' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [hmmm] [Pusher] Issue authenticating with Pusher during subscribe attempt. ~~ channelName: 'private-encrypted-user-accountID-6533726' type: 'AuthError' error: 'AuthenticatePusher request failed' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [hmmm] Failed to subscribe to Pusher channel ~~ parameters: '' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [hmmm] Failed to subscribe to Pusher channel ~~ parameters: '' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [hmmm] [User] Failed to subscribe to Pusher channel ~~ parameters: '' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [hmmm] [User] Failed to subscribe to Pusher channel ~~ parameters: '' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [info] Finished API request ~~ command: 'Authenticate' shouldUseSecure: '' jsonCode: '200' requestID: '72ccb1d3dd99bc79-SJC' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [info] [Onyx] set() called for key: session properties: loading,shouldShowComposeInput,authToken,accountID,email,encryptedAuthToken ~~ parameters: '' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [info] Finished API request ~~ command: 'OpenReport' jsonCode: '407' requestID: '72ccb1d87891bc79-SJC' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [info] Making API request ~~ command: 'Authenticate' shouldUseSecure: '' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [info] [Onyx] set() called for key: reportDraftComment_74050763 ~~ parameters: '' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [info] Finished API request ~~ command: 'Authenticate' shouldUseSecure: '' jsonCode: '200' requestID: '72ccb1db3a55bc79-SJC' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | [info] [Onyx] set() called for key: session properties: loading,shouldShowComposeInput,authToken,accountID,email,encryptedAuthToken ~~ parameters: '' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | ~~ userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 151 | marc@expensify.com | StoreUtils - Clearing all the stores.
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 152 | marc@expensify.com | TransactionStore cache fully cleared
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 152 | marc@expensify.com | ReportStore cache cleared
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 152 | marc@expensify.com | NVPStore - clear cache
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 152 | marc@expensify.com | NVPStore - clear cache
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 152 | marc@expensify.com | SharedInNVPStore - clear cache
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 152 | marc@expensify.com | ReportDuplicatedTransactionsStore - Cache cleared
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 152 | marc@expensify.com | TransactionIDs are not converted to string
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 152 | marc@expensify.com | Profile ~~ {"total":3,"cmd":"Log","jsonCode":200,"output":{"size":71,"gzip":1,"ratio":139},"gzip":71,"PHP":{"total":3,"%":100,"boot":1,"proc":2,"pack":0,"mem":2}}
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 152 | marc@expensify.com | Timing: cmd= Log totalTime= 3 authTotalTime= authRunTime= 0

Notes/Photos/Videos:

I'm unsure how to reproduce this reliably, but it seems related to the authToken expiring and something about the reauthentication and sequential queue is maybe not working quite right. I tried to create a repro by invalidating the token manually and closing then reopening the app, but Pusher connected fine in this case.

Expensify/Expensify Issue URL:
Issue reported by:
Slack conversation:

View all open jobs on GitHub

[melvin-bot]

Triggered auto assignment to @sakluger (AutoAssignerTriage), see https://stackoverflow.com/c/expensify/questions/4749 for more details.

[marcaaron]

@yuwenmemon think this could be related to the change here:

App/src/libs/actions/Session/index.js

Line 464 in da22ec6

API.makeRequestWithSideEffects('AuthenticatePusher', {

?

I'm wondering why we did not end up in this block if the issue was an expired authToken

App/src/libs/actions/Session/index.js

Lines 471 to 475 in da22ec6

	Log.hmmm('[PusherAuthorizer] Unable to authenticate Pusher because authToken is expired');
	callback(new Error('Pusher failed to authenticate because authToken is expired'), {auth: ''});
	// Attempt to refresh the authToken then reconnect to Pusher
	reauthenticatePusher();

We also didn't make it here:

App/src/libs/actions/Session/index.js

Lines 479 to 483 in da22ec6

	if (response.jsonCode !== CONST.JSON_CODE.SUCCESS) {
	Log.hmmm('[PusherAuthorizer] Unable to authenticate Pusher for reason other than expired session');
	callback(new Error(`Pusher failed to authenticate because code: ${response.jsonCode} message: ${response.message}`), {auth: ''});
	return;
	}

Which means we threw in makeRequestWithSideEffects() instead of returning the "not authenticated" code that would land us in the first block even though we had a normal jsonCode: 407 response.

[info] Finished API request ~~ command: 'AuthenticatePusher' jsonCode: '407' requestID: '72ccb1d42ddebc79-SJC' userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) NewExpensify/1.1.84-11 Chrome/98.0.4758.141 Electron/17.4.10 Safari/537.36'

Looked a bit deeper and I think that will only happen if we are processing the request in the SequentialQueue from looking at this code...

App/src/libs/Middleware/Reauthentication.js

Lines 36 to 46 in c45e58f

	const shouldRetry = lodashGet(request, 'data.shouldRetry');
	if (!shouldRetry) {
	if (isFromSequentialQueue) {
	return data;
	}
	if (request.resolve) {
	request.resolve(data);
	}
	return;
	}

we don't pass a promise that can be resolved when calling makeRequestWithSideEffects() and returning undefined from the Reauthentication middleware. But still not sure what is making this request... throw an error? What is the error and why isn't it logged...?

First solution that comes to mind is to allow makeRequestWithSideEffects() to run in the SequentialQueue by passing the second parameter here as true:

App/src/libs/API.js

Line 87 in c45e58f

return Request.processWithMiddleware(request);

If we do this then Pusher would be able to handle it's reauthentication.

[marcaaron]

Actually, we probably don't want to do that because it would persist those requests and we don't really need to do that. 🤔

[marcaaron]

Figured it out and more context in PR.