Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Closed
marcaaron opened this issue Jul 18, 2022 · 4 comments
Closed

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

marcaaron opened this issue Jul 18, 2022 · 4 comments
Assignees
@marcaaron
Labels
Daily KSv2 Engineering Improvement Item broken or needs improvement. Internal Requires API changes or must be handled by Expensify staff

Comments

@marcaaron
Copy link
Contributor

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 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 | [email protected] | PID ~~ 1624330
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 150 | [email protected] | 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: '[email protected]' partnerName: 'expensify.com' browserGUID: '62d58e7124bbe'
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 150 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | [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 | [email protected] | ~~ 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 | [email protected] | StoreUtils - Clearing all the stores.
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 152 | [email protected] | TransactionStore cache fully cleared
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 152 | [email protected] | ReportStore cache cleared
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 152 | [email protected] | NVPStore - clear cache
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 152 | [email protected] | NVPStore - clear cache
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 152 | [email protected] | SharedInNVPStore - clear cache
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 152 | [email protected] | ReportDuplicatedTransactionsStore - Cache cleared
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 152 | [email protected] | TransactionIDs are not converted to string
72ccb1e2cfb2bc79-SJC | virt1.rno | 2022-07-18 16:46:41 152 | [email protected] | 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 | [email protected] | 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
@marcaaron marcaaron added AutoAssignerTriage Auto assign issues for triage to an available triage team member Daily KSv2 labels Jul 18, 2022
@melvin-bot
Copy link

melvin-bot bot commented Jul 18, 2022

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

@melvin-bot melvin-bot bot removed the AutoAssignerTriage Auto assign issues for triage to an available triage team member label Jul 18, 2022
@marcaaron marcaaron assigned marcaaron and unassigned sakluger Jul 18, 2022
@marcaaron marcaaron added the Internal Requires API changes or must be handled by Expensify staff label Jul 18, 2022
@marcaaron
Copy link
Contributor Author

@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
Copy link
Contributor Author

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 marcaaron mentioned this issue Jul 18, 2022
Merged
92 tasks
@marcaaron
Copy link
Contributor Author

Figured it out and more context in PR.

@marcaaron marcaaron added Reviewing Has a PR in review Engineering Improvement Item broken or needs improvement. and removed Reviewing Has a PR in review labels Jul 18, 2022
@marcaaron marcaaron mentioned this issue Jul 18, 2022
Merged
87 tasks
@melvin-bot melvin-bot bot closed this as completed Jul 18, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@marcaaron marcaaron

Labels
Daily KSv2 Engineering Improvement Item broken or needs improvement. Internal Requires API changes or must be handled by Expensify staff
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@sakluger @marcaaron