App icon indicating copy to clipboard operation
App copied to clipboard

Published 20 hours ago • verified publisher icon Expensify

Got logged out of the app in web staging. 3 replies

Open m-natarajan opened this issue 1 year ago • 10 comments

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: @iwiznia Slack conversation: https://expensify.slack.com/archives/C049HHMV9SM/p1730209919216239

Action Performed:

  1. Go to staging.new.expensify.com and signin
  2. Do some browsing

Expected Result:

User able to use the app without any issue

Actual Result:

User got log out of the app

Workaround:

Unknown

Platforms:

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

  • [ ] Android: Standalone
  • [ ] Android: HybridApp
  • [ ] Android: mWeb Chrome
  • [ ] iOS: Standalone
  • [ ] iOS: HybridApp
  • [ ] iOS: mWeb Safari
  • [x] MacOS: Chrome / Safari
  • [ ] MacOS: Desktop

Screenshots/Videos

Add any screenshot/video evidence

View all open jobs on GitHub

m-natarajan avatar Oct 30 '24 00:10 m-natarajan

Triggered auto assignment to @mallenexpensify (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.

melvin-bot[bot] avatar Oct 30 '24 00:10 melvin-bot[bot]

Triggered auto assignment to @MarioExpensify (AutoAssignerNewDotQuality)

melvin-bot[bot] avatar Oct 30 '24 00:10 melvin-bot[bot]

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

MelvinBot avatar Oct 30 '24 00:10 MelvinBot

Got it again today.

iwiznia avatar Oct 30 '24 15:10 iwiznia

Alright, got it again. Seems I get it every day at the start of my day. Here's some data:

  • Page was stuck
  • I reloaded
  • Ended up on login screen

This is the logs and network requests after reloading: image

Suspicious thing is accountID=unknwon. Here are the logs:

10:44:19.051 index.ts:148 [OnyxUpdateManager] Listening for updates from the server
10:44:19.114 Log.ts:76 [info] [Onyx] set called for key: logs properties:  hasChanged: true - "" 
10:44:19.124 hook.js:591 Animated: `useNativeDriver` is not supported because the native animated module is missing. Falling back to JS-based animation. To resolve this, add `RCTAnimation` module to this app, or remove `useNativeDriver`. Make sure to run `bundle exec pod install` first. Read more about autolinking: https://github.com/react-native-community/cli/blob/master/docs/autolinking.md
overrideMethod @ hook.js:591
T @ NativeAnimatedHelper.js:412
Z @ AnimatedEvent.js:92
event @ AnimatedImplementation.js:395
(anonymous) @ animated.js:66
useMemo @ react-dom.production.min.js:177
t.useMemo @ react.production.min.js:26
T @ animated.js:66
fo @ react-dom.production.min.js:160
vA @ react-dom.production.min.js:289
Il @ react-dom.production.min.js:279
pl @ react-dom.production.min.js:279
fl @ react-dom.production.min.js:279
al @ react-dom.production.min.js:267
b @ scheduler.production.min.js:13
k @ scheduler.production.min.js:14
e.exports @ _invoke.js:5
p.<computed> @ _task.js:35
I @ _task.js:21
y @ _task.js:25
Show 20 more frames
Show lessUnderstand this warning
10:44:19.128 Log.ts:76 [info] [Onyx] set called for key: activeClients properties: 0,1,2,3 hasChanged: true - "" 
10:44:19.129 Log.ts:76 [info] [NetworkConnection] NetInfo state change - {"isInternetReachable":null,"isConnected":true,"type":"other","details":{"isConnectionExpensive":false}} 
10:44:19.129 Log.ts:76 [info] [Network] Client is back online because: NetInfo received a state change event - "" 
10:44:19.129 Log.ts:76 [info] [NetworkStatus] NetInfo.addEventListener event coming, setting "offlineStatus" to false with network state: {"isInternetReachable":null,"isConnected":true,"type":"other","details":{"isConnectionExpensive":false}} - "" 
10:44:19.129 Log.ts:76 [info] [NetworkConnection] NetInfo state change - {"isInternetReachable":null,"isConnected":true,"type":"other","details":{"isConnectionExpensive":false}} 
10:44:19.129 Log.ts:76 [info] [Network] Client is back online because: NetInfo received a state change event - "" 
10:44:19.129 Log.ts:76 [info] [NetworkStatus] NetInfo.addEventListener event coming, setting "offlineStatus" to false with network state: {"isInternetReachable":null,"isConnected":true,"type":"other","details":{"isConnectionExpensive":false}} - "" 
10:44:19.129 Log.ts:76 [info] [Onyx] merge called for key: network properties: isOffline,networkStatus hasChanged: true - "" 
10:44:19.129 Log.ts:76 [info] [NetworkConnection] NetInfo state change - {"isInternetReachable":null,"isConnected":true,"type":"other","details":{"isConnectionExpensive":false}} 
10:44:19.129 Log.ts:76 [info] [Network] Client is back online because: NetInfo received a state change event - "" 
10:44:19.129 Log.ts:76 [info] [NetworkStatus] NetInfo.addEventListener event coming, setting "offlineStatus" to false with network state: {"isInternetReachable":null,"isConnected":true,"type":"other","details":{"isConnectionExpensive":false}} - "" 
10:44:19.130 Log.ts:76 [info] [Onyx] merge called for key: network properties: isOffline,networkStatus hasChanged: false - "" 
10:44:19.134 Log.ts:76 [info] App launched - {"Platform":{"OS":"web","isTesting":false},"CONFIG":{"default":{"APP_NAME":"NewExpensify","AUTH_TOKEN_EXPIRATION_TIME":5400000,"ENVIRONMENT":"staging","EXPENSIFY":{"EXPENSIFY_URL":"https://www.expensify.com/","SECURE_EXPENSIFY_URL":"https://secure.expensify.com/","NEW_EXPENSIFY_URL":"https://staging.new.expensify.com/","DEFAULT_API_ROOT":"https://www.expensify.com/","DEFAULT_SECURE_API_ROOT":"https://secure.expensify.com/","STAGING_API_ROOT":"https://staging.expensify.com/","STAGING_SECURE_API_ROOT":"https://staging-secure.expensify.com/","PARTNER_NAME":"chat-expensify-com","PARTNER_PASSWORD":"e21965746fd75f82bb66","EXPENSIFY_CASH_REFERER":"ecash","CONCIERGE_URL_PATHNAME":"concierge/","DEVPORTAL_URL_PATHNAME":"_devportal/","CONCIERGE_URL":"https://www.expensify.com/concierge/","SAML_URL":"https://www.expensify.com/authentication/saml/login"},"IS_IN_PRODUCTION":true,"IS_IN_STAGING":true,"IS_USING_LOCAL_WEB":false,"PUSHER":{"APP_KEY":"268df511a204fbb60884","SUFFIX":"","CLUSTER":"mt1"},"SITE_TITLE":"New Expensify","FAVICON":{"DEFAULT":"/favicon.png","UNREAD":"/favicon-unread.png"},"CAPTURE_METRICS":false,"ONYX_METRICS":false,"DEV_PORT":8082,"E2E_TESTING":false,"SEND_CRASH_REPORTS":true,"IS_USING_WEB_PROXY":false,"APPLE_SIGN_IN":{"SERVICE_ID":"com.chat.expensify.chat.AppleSignIn","REDIRECT_URI":"https://staging.new.expensify.com/appleauth"},"GOOGLE_SIGN_IN":{"WEB_CLIENT_ID":"921154746561-gpsoaqgqfuqrfsjdf8l7vohfkfj7b9up.apps.googleusercontent.com","IOS_CLIENT_ID":"921154746561-s3uqn2oe4m85tufi6mqflbfbuajrm2i3.apps.googleusercontent.com"},"GCP_GEOLOCATION_API_KEY":"","FIREBASE_WEB_CONFIG":{"apiKey":"AIzaSyDxzigVLZl4G8MP7jACQ0qpmADMzmrrON0","appId":"1:921154746561:web:7b8213357d07d6e4027c40","projectId":"expensify-chat"},"USE_REACT_STRICT_MODE_IN_DEV":false}}} 
10:44:19.134 Log.ts:76 [info] [Migrate Onyx] start - "" 
10:44:19.135 Log.ts:76 [info] [API] Called API.paginate - {"command":"OpenReport","reportID":"64819207","reportActionID":"","emailList":"","accountIDList":"","parentReportActionID":"0","shouldRetry":false,"clientLastReadTime":""} 
10:44:19.135 Log.ts:76 [info] [API] Preparing request - {"command":"OpenReport","type":"makeRequestWithSideEffects"} 
10:44:19.135 Log.ts:76 [info] [API] Applying optimistic data - {"command":"OpenReport","type":"makeRequestWithSideEffects"} 
10:44:19.136 Log.ts:76 [info] [Network] Making API request - {"command":"OpenReport"} {request: {…}, response: undefined}
10:44:19.136 Log.ts:76 [info] [Migrate Onyx] Skipped migration RenameCardIsVirtual because there are no cards linked to the account - "" 
10:44:19.137 Log.ts:76 [info] [Migrate Onyx] Skipped migration RenameReceiptFilename because there are no transactions - "" 
10:44:19.137 Log.ts:76 [info] [Migrate Onyx] Skipped migration KeyReportActionsDraftByReportActionID because there were no reportActionsDrafts - "" 
10:44:19.137 Log.ts:76 [info] [Migrate Onyx] Skipped TransactionBackupsToCollection migration because there are no transactions - "" 
10:44:19.137 Log.ts:76 [info] [Migrate Onyx] Skipped migration RemoveEmptyReportActionsDrafts because there were no reportActionsDrafts - "" 
10:44:19.138 Log.ts:76 [info] [Migrate Onyx] finished in 6ms - "" 
10:44:19.165 rocket-loader.min.js:1 [Violation] Added non-passive event listener to a scroll-blocking 'touchstart' event. Consider marking event handler as 'passive' to make the page more responsive. See https://www.chromestatus.com/feature/5745543795965952
t.addEventListener @ rocket-loader.min.js:1
registerListeners @ TouchEventManager.ts:136
attachEventManager @ GestureHandler.ts:78
(anonymous) @ GestureHandlerWebDelegate.ts:51
init @ GestureHandlerWebDelegate.ts:50
init @ GestureHandler.ts:62
init @ FlingGestureHandler.ts:30
attachGestureHandler @ RNGestureHandlerModule.web.ts:71
Na @ attachHandlers.ts:82
(anonymous) @ index.tsx:154
rA @ react-dom.production.min.js:243
yA @ react-dom.production.min.js:260
IA @ react-dom.production.min.js:259
mA @ react-dom.production.min.js:258
(anonymous) @ react-dom.production.min.js:282
El @ react-dom.production.min.js:280
al @ react-dom.production.min.js:269
b @ scheduler.production.min.js:13
k @ scheduler.production.min.js:14
e.exports @ _invoke.js:5
p.<computed> @ _task.js:35
I @ _task.js:21
y @ _task.js:25
Show 13 more frames
Show less
10:44:19.165 rocket-loader.min.js:1 [Violation] Added non-passive event listener to a scroll-blocking 'touchmove' event. Consider marking event handler as 'passive' to make the page more responsive. See https://www.chromestatus.com/feature/5745543795965952
t.addEventListener @ rocket-loader.min.js:1
registerListeners @ TouchEventManager.ts:137
attachEventManager @ GestureHandler.ts:78
(anonymous) @ GestureHandlerWebDelegate.ts:51
init @ GestureHandlerWebDelegate.ts:50
init @ GestureHandler.ts:62
init @ FlingGestureHandler.ts:30
attachGestureHandler @ RNGestureHandlerModule.web.ts:71
Na @ attachHandlers.ts:82
(anonymous) @ index.tsx:154
rA @ react-dom.production.min.js:243
yA @ react-dom.production.min.js:260
IA @ react-dom.production.min.js:259
mA @ react-dom.production.min.js:258
(anonymous) @ react-dom.production.min.js:282
El @ react-dom.production.min.js:280
al @ react-dom.production.min.js:269
b @ scheduler.production.min.js:13
k @ scheduler.production.min.js:14
e.exports @ _invoke.js:5
p.<computed> @ _task.js:35
I @ _task.js:21
y @ _task.js:25
Show 13 more frames
Show less
10:44:19.167 Log.ts:76 [info] [BootSplash] hiding splash screen - "" 
10:44:19.168 Log.ts:76 [info] [Onyx] merge called for key: modal properties: willAlertModalBecomeVisible,isPopover hasChanged: true - "" 
10:44:19.170 Log.ts:76 [info] [Onyx] merge called for key: modal properties: willAlertModalBecomeVisible,isPopover hasChanged: false - "" 
10:44:19.180 Log.ts:76 [info] Found existing deviceID - "78a46e99-5eea-28e8-1810-965c31336f03" 
10:44:19.181 Log.ts:76 [info] [SequentialQueue] Unable to flush. No requests to process. - "" 
10:44:19.181 Log.ts:76 [info] [Onyx] merge called for key: report_64819207 properties: reportName hasChanged: true - "" 
10:44:19.183 Log.ts:76 [info] [Onyx] merge called for key: reportMetadata_64819207 properties: isLoadingInitialReportActions,isLoadingOlderReportActions,hasLoadingOlderReportActionsError,isLoadingNewerReportActions,hasLoadingNewerReportActionsError,lastVisitTime hasChanged: true - "" 
10:44:19.259 Timing.ts:54 Timing:staging.new.expensify.trie_initialization 18.799999997019768
10:44:19.259 Log.ts:76 [info] [API] Called API.read - {"command":"SendPerformanceTiming","name":"staging.new.expensify.trie_initialization","value":18.799999997019768,"platform":"web"} 
10:44:19.259 Log.ts:76 [info] [API] Preparing request - {"command":"SendPerformanceTiming","type":"read"} 
10:44:19.259 Log.ts:76 [info] [Network] Making API request - {"command":"SendPerformanceTiming"} {request: {…}, response: undefined}
10:44:19.701 Log.ts:76 [info] [NetworkConnection] NetInfo state change - {"isInternetReachable":true,"isConnected":true,"type":"other","details":{"isConnectionExpensive":false}} 
10:44:19.701 Log.ts:76 [info] [Network] Client is back online because: NetInfo received a state change event - "" 
10:44:19.701 Log.ts:76 [info] [NetworkStatus] NetInfo.addEventListener event coming, setting "offlineStatus" to true with network state: {"isInternetReachable":true,"isConnected":true,"type":"other","details":{"isConnectionExpensive":false}} - "" 
10:44:19.701 Log.ts:76 [info] [Onyx] merge called for key: network properties: isOffline,networkStatus hasChanged: true - "" 
10:44:19.712 Log.ts:76 [info] [Onyx] merge called for key: network properties: timeSkew hasChanged: false - "" 
10:44:19.723 Log.ts:76 [info] [Network] Finished API request in 588ms - {"command":"OpenReport","jsonCode":404,"requestID":"8db414413d7c9c0e-EZE"} {request: {…}, response: {…}}
10:44:19.723 Log.ts:76 [hmmm] [Pagination] Did not receive any items in the response to OpenReport - "" 
10:44:19.723 OnyxUpdates.ts:29 [OnyxUpdateManager] Applying https update
10:44:19.723 Log.ts:76 [info] [OnyxUpdateManager] Applying update type: https with lastUpdateID: 0 - {"command":"OpenReport"} 
10:44:19.724 Log.ts:76 [info] [Onyx] set called for key: isCheckingPublicRoom hasChanged: true - "" 
10:44:19.724 Log.ts:76 [info] [Onyx] merge called for key: reportMetadata_64819207 properties: isLoadingInitialReportActions hasChanged: true - "" 
10:44:19.726 OnyxUpdates.ts:64 [OnyxUpdateManager] Done applying HTTPS update
10:44:19.726 Log.ts:76 [info] [Onyx] set called for key: isCheckingPublicRoom hasChanged: false - "" 
10:44:19.983 Log.ts:76 [info] [Network] Finished API request in 724ms - {"command":"SendPerformanceTiming","jsonCode":200,"requestID":"8db414413d909c0e-EZE"} {request: {…}, response: {…}}
10:44:19.984 OnyxUpdates.ts:29 [OnyxUpdateManager] Applying https update
10:44:19.984 Log.ts:76 [info] [OnyxUpdateManager] Applying update type: https with lastUpdateID: 0 - {"command":"SendPerformanceTiming"} 
10:44:19.984 OnyxUpdates.ts:64 [OnyxUpdateManager] Done applying HTTPS update
10:44:20.242 Log.ts:76 [info] [Onyx] merge called for key: account properties: success,errors,message,isLoading hasChanged: false - "" 
10:44:20.267 Log.ts:76 [info] Navigating to route - {"path":"/"} 
10:44:20.270 Log.ts:76 [info] [Onyx] merge called for key: lastVisitedPath hasChanged: true - "" 
7610:44:20.501 Chrome is moving towards a new experience that lets people make an informed choice with respect to third-party cookies.Understand this warning
10:44:20.642 client:168 [GSI_LOGGER]: Failed to render button because there is no parent or options set.
overrideMethod @ hook.js:591
_.Q @ client:168
tr @ client:283
g @ index.tsx:48
c @ rocket-loader.min.js:1
load
t.addEventListener @ rocket-loader.min.js:1
M @ index.tsx:61
rA @ react-dom.production.min.js:243
bl @ react-dom.production.min.js:285
Al @ react-dom.production.min.js:272
Ua @ react-dom.production.min.js:127
(anonymous) @ react-dom.production.min.js:282
El @ react-dom.production.min.js:280
al @ react-dom.production.min.js:269
b @ scheduler.production.min.js:13
k @ scheduler.production.min.js:14
e.exports @ _invoke.js:5
p.<computed> @ _task.js:35
I @ _task.js:21
y @ _task.js:25
Show 14 more frames
Show lessUnderstand this warning
10:44:21.478 Log.ts:76 [info] Previous log requestID - {"requestID":"8db4144d4e4d9c0e-EZE"} 
10:44:21.478 OnyxUpdates.ts:29 [OnyxUpdateManager] Applying https update
10:44:21.478 Log.ts:76 [info] [OnyxUpdateManager] Applying update type: https with lastUpdateID: 0 - {"command":"Log"} 
10:44:21.478 OnyxUpdates.ts:64 [OnyxUpdateManager] Done applying HTTPS update
10:44:24.606 firebaseWebConfig.ts:8 
        
        
       POST https://firebaselogging-pa.googleapis.com/v1/firelog/legacy/log?key=AIzaSyCx80ru6-RXeTi3GvqkFsMVyMf-vpgIoVw net::ERR_BLOCKED_BY_CLIENT
(anonymous) @ index.esm2017.js:782
(anonymous) @ index.esm2017.js:752
(anonymous) @ index.esm2017.js:742
(anonymous) @ index.esm2017.js:718
setTimeout
Fe @ index.esm2017.js:709
(anonymous) @ index.esm2017.js:704
Promise.then
_init @ index.esm2017.js:1411
(anonymous) @ index.esm2017.js:1509
getOrInitializeService @ index.esm2017.js:290
initialize @ index.esm2017.js:234
Je @ index.esm2017.js:1480
98164 @ firebaseWebConfig.ts:8
f @ bootstrap:19
30168 @ main-eec7ac5a15dd017f60c0.bundle.js:1
f @ bootstrap:19
35646 @ main-eec7ac5a15dd017f60c0.bundle.js:1
f @ bootstrap:19
53947 @ main-eec7ac5a15dd017f60c0.bundle.js:1
f @ bootstrap:19
17328 @ main-eec7ac5a15dd017f60c0.bundle.js:1
f @ bootstrap:19
99018 @ main-eec7ac5a15dd017f60c0.bundle.js:1
f @ bootstrap:19
55922 @ main-eec7ac5a15dd017f60c0.bundle.js:1
f @ bootstrap:19
91149 @ main-eec7ac5a15dd017f60c0.bundle.js:1
f @ bootstrap:19
42851 @ main-eec7ac5a15dd017f60c0.bundle.js:1
f @ bootstrap:19
5577 @ main-eec7ac5a15dd017f60c0.bundle.js:1
f @ bootstrap:19
49636 @ main-eec7ac5a15dd017f60c0.bundle.js:1
f @ bootstrap:19
94067 @ main-eec7ac5a15dd017f60c0.bundle.js:1
f @ bootstrap:19
67707 @ main-eec7ac5a15dd017f60c0.bundle.js:1
f @ bootstrap:19
77394 @ main-eec7ac5a15dd017f60c0.bundle.js:1
f @ bootstrap:19
t @ main-eec7ac5a15dd017f60c0.bundle.js:1
(anonymous) @ main-eec7ac5a15dd017f60c0.bundle.js:1
f.O @ chunk loaded:23
(anonymous) @ main-eec7ac5a15dd017f60c0.bundle.js:1
t @ jsonp chunk loading:71
(anonymous) @ main-eec7ac5a15dd017f60c0.bundle.js:1
Show 11 more frames
Show lessUnderstand this error
10:44:24.606 index.esm2017.js:78 [2024-10-31T13:44:24.606Z]  Performance: Tries left: 2.
10:44:24.985 Log.ts:76 [info] [Onyx] set called for key: currentDate hasChanged: true - "" 
10:44:31.379 m=credential_button_library:216 
        
        
       POST https://play.google.com/log?format=json&hasfast=true&authuser=0 net::ERR_BLOCKED_BY_CLIENT
(anonymous) @ m=credential_button_library:216
Uh @ m=credential_button_library:190
Wh.next @ m=credential_button_library:191
(anonymous) @ m=credential_button_library:191
Xh @ m=credential_button_library:191
Ui.send @ m=credential_button_library:216
Ji.flush @ m=credential_button_library:209
(anonymous) @ m=credential_button_library:204
qi @ m=credential_button_library:203
(anonymous) @ m=credential_button_library:202
setTimeout
ni.start @ m=credential_button_library:202
Ji.log @ m=credential_button_library:206
dj.log @ m=credential_button_library:220
Gl @ m=credential_button_library:303
(anonymous) @ m=credential_button_library:303
Promise.then
Ll.h @ m=credential_button_library:303
(anonymous) @ m=credential_button_library:307
(anonymous) @ button?theme=outline&size=large&type=icon&shape=circle&client_id=921154746561-gpsoaqgqfuqrfsjdf8l7vohfkfj7b9up.apps.googleusercontent.com&iframe_id=gsi_260640_173583&as=sAaQ9cPqaLqi085Fv63PYA:313Understand this error
10:44:34.609 firebaseWebConfig.ts:8 
        
        
       POST https://firebaselogging-pa.googleapis.com/v1/firelog/legacy/log?key=AIzaSyCx80ru6-RXeTi3GvqkFsMVyMf-vpgIoVw net::ERR_BLOCKED_BY_CLIENT
(anonymous) @ index.esm2017.js:782
(anonymous) @ index.esm2017.js:752
(anonymous) @ index.esm2017.js:742
(anonymous) @ index.esm2017.js:718
setTimeout
Fe @ index.esm2017.js:709
(anonymous) @ index.esm2017.js:748
Promise.catch
(anonymous) @ index.esm2017.js:742
(anonymous) @ index.esm2017.js:718
setTimeout
Fe @ index.esm2017.js:709
(anonymous) @ index.esm2017.js:704
Promise.then
_init @ index.esm2017.js:1411
(anonymous) @ index.esm2017.js:1509
getOrInitializeService @ index.esm2017.js:290
initialize @ index.esm2017.js:234
Je @ index.esm2017.js:1480
98164 @ firebaseWebConfig.ts:8
f @ bootstrap:19
30168 @ main-eec7ac5a15dd017f60c0.bundle.js:1
f @ bootstrap:19
35646 @ main-eec7ac5a15dd017f60c0.bundle.js:1
f @ bootstrap:19
53947 @ main-eec7ac5a15dd017f60c0.bundle.js:1
f @ bootstrap:19
17328 @ main-eec7ac5a15dd017f60c0.bundle.js:1
f @ bootstrap:19
99018 @ main-eec7ac5a15dd017f60c0.bundle.js:1
f @ bootstrap:19
55922 @ main-eec7ac5a15dd017f60c0.bundle.js:1
f @ bootstrap:19
91149 @ main-eec7ac5a15dd017f60c0.bundle.js:1
f @ bootstrap:19
42851 @ main-eec7ac5a15dd017f60c0.bundle.js:1
f @ bootstrap:19
5577 @ main-eec7ac5a15dd017f60c0.bundle.js:1
f @ bootstrap:19
49636 @ main-eec7ac5a15dd017f60c0.bundle.js:1
f @ bootstrap:19
94067 @ main-eec7ac5a15dd017f60c0.bundle.js:1
f @ bootstrap:19
67707 @ main-eec7ac5a15dd017f60c0.bundle.js:1
f @ bootstrap:19
77394 @ main-eec7ac5a15dd017f60c0.bundle.js:1
f @ bootstrap:19
t @ main-eec7ac5a15dd017f60c0.bundle.js:1
(anonymous) @ main-eec7ac5a15dd017f60c0.bundle.js:1
f.O @ chunk loaded:23
(anonymous) @ main-eec7ac5a15dd017f60c0.bundle.js:1
t @ jsonp chunk loading:71
(anonymous) @ main-eec7ac5a15dd017f60c0.bundle.js:1
Show 15 more frames
Show lessUnderstand this error
10:44:34.609 index.esm2017.js:78 [2024-10-31T13:44:34.609Z]  Performance: Tries left: 1.
10:44:45.015 firebaseWebConfig.ts:8 
        
        
       POST https://firebaselogging-pa.googleapis.com/v1/firelog/legacy/log?key=AIzaSyCx80ru6-RXeTi3GvqkFsMVyMf-vpgIoVw net::ERR_BLOCKED_BY_CLIENT
(anonymous) @ index.esm2017.js:782
(anonymous) @ index.esm2017.js:752
(anonymous) @ index.esm2017.js:742
(anonymous) @ index.esm2017.js:718
setTimeout
Fe @ index.esm2017.js:709
(anonymous) @ index.esm2017.js:748
Promise.catch
(anonymous) @ index.esm2017.js:742
(anonymous) @ index.esm2017.js:718
setTimeout
Fe @ index.esm2017.js:709
(anonymous) @ index.esm2017.js:748
Promise.catch
(anonymous) @ index.esm2017.js:742
(anonymous) @ index.esm2017.js:718
setTimeout
Fe @ index.esm2017.js:709
(anonymous) @ index.esm2017.js:704
Promise.then
_init @ index.esm2017.js:1411
(anonymous) @ index.esm2017.js:1509
getOrInitializeService @ index.esm2017.js:290
initialize @ index.esm2017.js:234
Je @ index.esm2017.js:1480
98164 @ firebaseWebConfig.ts:8
f @ bootstrap:19
30168 @ main-eec7ac5a15dd017f60c0.bundle.js:1
f @ bootstrap:19
35646 @ main-eec7ac5a15dd017f60c0.bundle.js:1
f @ bootstrap:19
53947 @ main-eec7ac5a15dd017f60c0.bundle.js:1
f @ bootstrap:19
17328 @ main-eec7ac5a15dd017f60c0.bundle.js:1
f @ bootstrap:19
99018 @ main-eec7ac5a15dd017f60c0.bundle.js:1
f @ bootstrap:19
55922 @ main-eec7ac5a15dd017f60c0.bundle.js:1
f @ bootstrap:19
91149 @ main-eec7ac5a15dd017f60c0.bundle.js:1
f @ bootstrap:19
42851 @ main-eec7ac5a15dd017f60c0.bundle.js:1
f @ bootstrap:19
5577 @ main-eec7ac5a15dd017f60c0.bundle.js:1
f @ bootstrap:19
49636 @ main-eec7ac5a15dd017f60c0.bundle.js:1
f @ bootstrap:19
94067 @ main-eec7ac5a15dd017f60c0.bundle.js:1
f @ bootstrap:19
67707 @ main-eec7ac5a15dd017f60c0.bundle.js:1
f @ bootstrap:19
77394 @ main-eec7ac5a15dd017f60c0.bundle.js:1
f @ bootstrap:19
t @ main-eec7ac5a15dd017f60c0.bundle.js:1
(anonymous) @ main-eec7ac5a15dd017f60c0.bundle.js:1
f.O @ chunk loaded:23
(anonymous) @ main-eec7ac5a15dd017f60c0.bundle.js:1
t @ jsonp chunk loading:71
(anonymous) @ main-eec7ac5a15dd017f60c0.bundle.js:1
Show 19 more frames
Show lessUnderstand this error
10:44:45.015 index.esm2017.js:78 [2024-10-31T13:44:45.015Z]  Performance: Tries left: 0.
10:44:50.013 Log.ts:76 [info] [BootSplash] splash screen status - {"appState":"background","splashScreenState":"visible"} 
10:44:50.013 Log.ts:76 [alrt] [BootSplash] splash screen is still visible - {"propsToLog":{"isSidebarLoaded":false,"isAuthenticated":false}} 
10:44:50.241 Log.ts:76 [info] Previous log requestID - {"requestID":"8db41501793c9c0e-EZE"} 
10:44:50.242 OnyxUpdates.ts:29 [OnyxUpdateManager] Applying https update
10:44:50.242 Log.ts:76 [info] [OnyxUpdateManager] Applying update type: https with lastUpdateID: 0 - {"command":"Log"} 
10:44:50.242 OnyxUpdates.ts:64 [OnyxUpdateManager] Done applying HTTPS update
10:45:06.843 Log.ts:76 [info] [Onyx] set called for key: activeClients properties: 0,1,2,3 hasChanged: false - "" 
10:45:10.682 Log.ts:76 [info] Flushing logs as app is going inactive - {} 
10:45:12.232 Log.ts:76 [info] Previous log requestID - {"requestID":"8db4158ae9c59c0e-EZE"} 
10:45:12.232 OnyxUpdates.ts:29 [OnyxUpdateManager] Applying https update
10:45:12.232 Log.ts:76 [info] [OnyxUpdateManager] Applying update type: https with lastUpdateID: 0 - {"command":"Log"} 
10:45:12.232 OnyxUpdates.ts:64 [OnyxUpdateManager] Done applying HTTPS update
10:45:40.349 Log.ts:76 [info] [Onyx] set called for key: activeClients properties: 0,1,2,3 hasChanged: false - "" 
10:46:31.538 Log.ts:76 [info] Flushing logs as app is going inactive - {} 
10:46:33.248 Log.ts:76 [info] Previous log requestID - {"requestID":"8db417853ac69c0e-EZE"} 
10:46:33.249 OnyxUpdates.ts:29 [OnyxUpdateManager] Applying https update
10:46:33.249 Log.ts:76 [info] [OnyxUpdateManager] Applying update type: https with lastUpdateID: 0 - {"command":"Log"} 
10:46:33.249 OnyxUpdates.ts:64 [OnyxUpdateManager] Done applying HTTPS update
10:46:47.030 Log.ts:76 [info] [Onyx] set called for key: activeClients properties: 0,1,2,3 hasChanged: false - ""

iwiznia avatar Oct 31 '24 13:10 iwiznia

Another weird thing:

10:44:19.723 Log.ts:76 [info] [Network] Finished API request in 588ms - {"command":"OpenReport","jsonCode":404,"requestID":"8db414413d7c9c0e-EZE"} {request: {…}, response: {…}} That response is: image

so why 404 but with onyx data? Logs for that request are here

iwiznia avatar Oct 31 '24 13:10 iwiznia

Odd about that request:

Throwing exception with message: '404 Public room not found' from auth/command/OpenReport.cpp:120

Why would it think it's a public room?

iwiznia avatar Oct 31 '24 13:10 iwiznia

Ohhh probably because of:

8db414413d7c9c0e-EZE	2024-10-31 13:44:19 513		/api.php	staging-www1.rno	undefined	[104.28.152.17->/api.php] Malformed REQUEST: 'authToken', ignoring (should match '([vV]\d:[\w\d+\/]+={0,2}:)?[0-9A-F]{1,1024}') ~~ value: '<REDACTED> (strlen: 4)'
8db414413d7c9c0e-EZE	2024-10-31 13:44:19 513		/api.php	staging-www1.rno	undefined	[104.28.152.17->/api.php] Malformed REQUEST: 'email', ignoring (should match '((?:DELETED_\d@)*[\w\.'#%+-]+@[a-zA-Z\d\.-]+\.[a-zA-Z]{2,}|^\+?[1-9]\d{1,14}$)') ~~ value: 'null'

Why I have no authToken or email?!?

iwiznia avatar Oct 31 '24 13:10 iwiznia

The session onyx key has this: image

iwiznia avatar Oct 31 '24 13:10 iwiznia

@MarioExpensify @iwiznia any chance this can be worked on Externally? Guessing not

mallenexpensify avatar Nov 02 '24 00:11 mallenexpensify

Hey @mallenexpensify @iwiznia, I still haven't got a chance to take a look at this one in detail. I'll try to reproduce it locally (possibly later today) and report back.

MarioExpensify avatar Nov 04 '24 15:11 MarioExpensify

I get this every day or really every time I close my computer and come back a few hours later.

iwiznia avatar Nov 04 '24 18:11 iwiznia

I know I was on staging.new.expensify.com yesterday in Chrome cuz I was testing. Just hopped on there again and didn't got logged off. Site's wonky right now though, so likely not the best time to test :/

mallenexpensify avatar Nov 05 '24 22:11 mallenexpensify

Triggered auto assignment to @slafortune (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.

melvin-bot[bot] avatar Nov 06 '24 19:11 melvin-bot[bot]

@slafortune I'm off the next week, can you please keep an eye on this issue til I'm back? Thx

mallenexpensify avatar Nov 06 '24 19:11 mallenexpensify

I'm taking this over as discussed here

neil-marcellini avatar Nov 07 '24 16:11 neil-marcellini

When re-authentication fails in App we set an error message at the key shown in the session data screenshot, 'passwordForm.error.fallback'. So I want to find the request that failed authentication initially, and then why it failed to re-authenticate.

Here are all the requests that returned 407 for Ionatan on that day. https://www.expensify.com/_devportal/tools/logSearch/#sort=asc&size=10000&query=blob%3A%22jsonCode%3A%20'407%22%20AND%20email%3A%22ionatan%40expensify.com%22%20AND%20timestamp%3A%5B2024-10-31T00%3A00%20TO%202024-10-31T23%3A59%5D.

We know that when the OpenReport request was made at 2024-10-31 13:44:19 508, the app no longer had an AuthToken.

So if we look at the requests on staging before that time which returned 407, specifically the first one, then it shows that AuthenticatePusher encountered an expired authToken.

8db0f9509bea9c0e-EZE 2024-10-31 04:41:38 776 [email protected] [email protected] db2.sjc Checking authToken validity for accountID=2536717 / partnerID=83 / partnerUserID=expensify.cash-78a46e99-5eea-28e8-1810-965c31336f03 / isValidated=true / expiresAt=1730337365754797 / isPasswordless=true
8db0f9509bea9c0e-EZE 2024-10-31 04:41:38 776 [email protected] [email protected] db2.sjc Throwing exception with message: '407 Unauthorized - Invalid token' from auth/lib/AuthToken.cpp:1230
8db0f9509bea9c0e-EZE 2024-10-31 04:41:38 777 [email protected] [email protected] db2.sjc Error processing command 'Get' (407 Unauthorized - Invalid token), ignoring.
8db0f9509bea9c0e-EZE 2024-10-31 04:41:38 777 [email protected] [email protected] db2.sjc command 'Get_account' timing info (ms): prePeek:0 (count: 0), peek:0 (count:1), process:0 (count:0), postProcess:0 (count:0), total:0, unaccounted:0, blockingCommitThreadTime:0, exclusiveTransactionLockTime:0. Commit: worker:0, sync:0. Queue: worker:0, sync:0, blocking:0, pageLock:0, escalation:0. Blocking: prePeek:0, peek:0, process:0, postProcess:0, commit:0. Upstream: peek:0, process:0, total:0, unaccounted:0.
8db0f9509bea9c0e-EZE 2024-10-31 04:41:38 777 [email protected] [email protected] staging-www1.sjc Bedrock\Client - Request finished ~~ host: 'db2.sjc' command: 'Get' jsonCode: '407 Unauthorized - Invalid token' duration: '1' net: '0.735' wait: '0.265' proc: '0' commitCount: ''
8db0f9509bea9c0e-EZE 2024-10-31 04:41:38 777 [email protected] [email protected] staging-www1.sjc Got an authorization error Expensify\Error\Auth\AuthTokenExpired - 9b953676-e64d-4262-bf74-1bf0ff888e4d ~~ command: 'AuthenticatePusher' exceptionJsonCode: '407' exceptionUserMessage: 'Your session has expired. Please sign in again.' exceptionMessage: '' exceptionFile: '/git/releases/expensify.com/75ecd63/lib/Auth.php' exceptionLine: '263' exceptionCode: '666'

Now the Reauthentication middleware should make a call to Authenticate. How can I find that request? I need to be able to identify it to the user. I should be able to use the autoGeneratedLogin. That's created on login as the partnerUserID, and there's a log line for that. So probably the first occurrence of that log line before the authentication expired. Here are the logs.

8dac3f583a2fba68-EZE 2024-10-30 14:55:39 009 [email protected] [email protected] db1.sjc Creating login expensify.cash-78a46e99-5eea-28e8-1810-965c31336f03 with partnerID 83. Primary email [email protected] is validated.

So the autoGeneratedLogin should be expensify.cash-78a46e99-5eea-28e8-1810-965c31336f03. Oh right, that also matches the partnerUserID in the AuthenticatePusher call that failed. Great!

After AuthenticatePusher fails, here are logs to find the next call to Authenticate with that partnerUserID.

Here's the next call.

8db0f9521e1d9c0e-EZE 2024-10-31 04:41:39 008 [email protected] staging-www1.sjc Processing 'Authenticate' for 'expensify.com' from '104.28.152.17' ~~ command: 'Authenticate' useExpensifyLogin: 'false' partnerName: 'chat-expensify-com' partnerPassword: '<REDACTED>' partnerUserID: 'expensify.cash-78a46e99-5eea-28e8-1810-965c31336f03' partnerUserSecret: '<REDACTED>' email: '[email protected]' appversion: '9.0.55-9' referer: 'ecash' platform: 'web' api_setCookie: 'false' isFromDevEnv: 'false' clientUpdateID: '2681857372' browserGUID: '67230a8302213' HTTP_CF_BOT_SCORE: '99' HTTP_CF_JA3_HASH: '550518ce2834286070c227fa8bc8c9d9'

That request seems to have completed successfully, so the mystery continues...

neil-marcellini avatar Nov 07 '24 20:11 neil-marcellini

I would like to find frontend logs for after re-authentication succeeds. It should set the authToken into Onyx and things should work properly.

Searching for any app logs after that time, I don't see any until much later at 2024-10-31 13:58:49 430, which is odd. https://www.expensify.com/_devportal/tools/logSearch/#sort=asc&size=10000&query=blob%3A%22%5BApp%5D%22%20AND%20email%3A%22ionatan%40expensify.com%22%20AND%20timestamp%3A%5B2024-10-31T04%3A41%20TO%202024-10-31T23%3A59%5D.

I guess probably because the email isn't set when un-authenticated. We need a better way to track users App logs. Luckily I spotted a deviceID that I can use, and I found some relevant logs.

8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 736   staging-www1.sjc [App] 2024-10-31T04:57:42.795Z - [hmmm] [Network] API request error: Failed to fetch ~~ message: 'Failed to fetch' request: '[command: 'Authenticate' data: '[useExpensifyLogin: '' partnerName: 'chat-expensify-com' partnerPassword: '<REDACTED>' partnerUserID: 'expensify.cash-78a46e99-5eea-28e8-1810-965c31336f03' partnerUserSecret: '<REDACTED>' shouldRetry: '' forceNetworkRequest: '1' canCancel: '1' appversion: '9.0.55-9']' type: 'post' shouldUseSecure: '']' 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'
These are the key logs
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 731   staging-www1.sjc [App] PID ~~ 1102864
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 734   staging-www1.sjc [App] [104.28.152.17->/api.php] Malformed REQUEST: 'email', ignoring (should match '((?:DELETED_\d@)*[\w.'#%+-]+@[a-zA-Z\d.-]+.[a-zA-Z]{2,}|^+?[1-9]\d{1,14}$)') ~~ value: 'null'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 735   staging-www1.sjc [App] Processing 'Log' for 'expensify.com' from '104.28.152.17' ~~ command: 'Log' api_setCookie: 'false' expensifyCashAppVersion: 'expensifyCash[web]9.0.55-9' appversion: '9.0.55-9' referer: 'ecash' platform: 'web' isFromDevEnv: 'false' clientUpdateID: '-1' partnerName: 'expensify.com' browserGUID: '67230e48b3736' HTTP_CF_BOT_SCORE: '99' HTTP_CF_JA3_HASH: '550518ce2834286070c227fa8bc8c9d9'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 735   staging-www1.sjc [App] 2024-10-30T23:20:46.407Z - [info] [RequestThrottle] in clear() ~~ 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 735   staging-www1.sjc [App] 2024-10-30T23:20:46.407Z - [info] [SequentialQueue] Unable to process. No requests to process. ~~ 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 735   staging-www1.sjc [App] 2024-10-30T23:20:46.408Z - [info] [SequentialQueue] Finished processing queue. ~~ 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 735   staging-www1.sjc [App] 2024-10-30T23:20:46.408Z - [info] [Network] Making API request ~~ command: 'SendPerformanceTiming' 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 735   staging-www1.sjc [App] 2024-10-30T23:20:46.409Z - [info] [Onyx] merge called for key: isLoadingReportData 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 735   staging-www1.sjc [App] 2024-10-30T23:20:46.410Z - [info] [SequentialQueue] 'ReconnectApp' removed from the queue. Queue length is 0 ~~ 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 735   staging-www1.sjc [App] 2024-10-30T23:29:18.176Z - [info] Previous log requestID ~~ requestID: '8daf2fc7a8e69c0e-EZE' 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 735   staging-www1.sjc [App] 2024-10-30T23:29:18.176Z - [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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 735   staging-www1.sjc [App] 2024-10-30T23:29:18.603Z - [info] [Network] Finished API request in 512195ms ~~ command: 'SendPerformanceTiming' jsonCode: '200' requestID: '8daf2fc7a8ea9c0e-EZE' 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 735   staging-www1.sjc [App] 2024-10-30T23:29:18.603Z - [info] [OnyxUpdateManager] Applying update type: https with lastUpdateID: 0 ~~ command: 'SendPerformanceTiming' 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 735   staging-www1.sjc [App] 2024-10-31T04:41:36.285Z - [hmmm] [PusherConnectionManager] Channels Error 1006 ~~ error: '[type: 'PusherError' data: '[code: '1006']']' 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 735   staging-www1.sjc [App] 2024-10-31T04:41:37.589Z - [hmmm] [PusherConnectionManager] state change ~~ states: '[previous: 'connected' current: 'connecting']' 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 735   staging-www1.sjc [App] 2024-10-31T04:41:38.444Z - [hmmm] [PusherConnectionManager] state change ~~ states: '[previous: 'connecting' current: 'connected']' 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 735   staging-www1.sjc [App] 2024-10-31T04:41:38.444Z - [info] [PusherAuthorizer] Attempting to authorize Pusher ~~ channelName: 'private-encrypted-user-accountID-2536717' 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 736   staging-www1.sjc [App] 2024-10-31T04:41:38.444Z - [info] [API] Called API makeRequestWithSideEffects ~~ command: 'AuthenticatePusher' socket_id: '788476.13603634' channel_name: 'private-encrypted-user-accountID-2536717' shouldRetry: '' forceNetworkRequest: '1' 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 736   staging-www1.sjc [App] 2024-10-31T04:41:38.444Z - [info] [API] Preparing request ~~ command: 'AuthenticatePusher' type: 'makeRequestWithSideEffects' 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 736   staging-www1.sjc [App] 2024-10-31T04:41:38.444Z - [info] [Network] Making API request ~~ command: 'AuthenticatePusher' 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 736   staging-www1.sjc [App] 2024-10-31T04:41:38.444Z - [info] [PusherAuthorizer] Attempting to authorize Pusher ~~ channelName: 'private-report-reportID-8681063504293996' 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 736   staging-www1.sjc [App] 2024-10-31T04:41:38.444Z - [info] [API] Called API makeRequestWithSideEffects ~~ command: 'AuthenticatePusher' socket_id: '788476.13603634' channel_name: 'private-report-reportID-8681063504293996' shouldRetry: '' forceNetworkRequest: '1' 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 736   staging-www1.sjc [App] 2024-10-31T04:41:38.444Z - [info] [API] Preparing request ~~ command: 'AuthenticatePusher' type: 'makeRequestWithSideEffects' 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 736   staging-www1.sjc [App] 2024-10-31T04:41:38.445Z - [info] [Network] Making API request ~~ command: 'AuthenticatePusher' 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 736   staging-www1.sjc [App] 2024-10-31T04:41:38.445Z - [info] [PusherAuthorizer] Attempting to authorize Pusher ~~ channelName: 'private-report-reportID-74050725' 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 736   staging-www1.sjc [App] 2024-10-31T04:41:38.445Z - [info] [API] Called API makeRequestWithSideEffects ~~ command: 'AuthenticatePusher' socket_id: '788476.13603634' channel_name: 'private-report-reportID-74050725' shouldRetry: '' forceNetworkRequest: '1' 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 736   staging-www1.sjc [App] 2024-10-31T04:41:38.445Z - [info] [API] Preparing request ~~ command: 'AuthenticatePusher' type: 'makeRequestWithSideEffects' 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 736   staging-www1.sjc [App] 2024-10-31T04:41:38.445Z - [info] [Network] Making API request ~~ command: 'AuthenticatePusher' 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 736   staging-www1.sjc [App] 2024-10-31T04:41:38.445Z - [info] [PusherAuthorizer] Attempting to authorize Pusher ~~ channelName: 'private-report-reportID-64819207' 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 736   staging-www1.sjc [App] 2024-10-31T04:41:38.445Z - [info] [API] Called API makeRequestWithSideEffects ~~ command: 'AuthenticatePusher' socket_id: '788476.13603634' channel_name: 'private-report-reportID-64819207' shouldRetry: '' forceNetworkRequest: '1' 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 736   staging-www1.sjc [App] 2024-10-31T04:41:38.445Z - [info] [API] Preparing request ~~ command: 'AuthenticatePusher' type: 'makeRequestWithSideEffects' 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 736   staging-www1.sjc [App] 2024-10-31T04:41:38.445Z - [info] [Network] Making API request ~~ command: 'AuthenticatePusher' 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 736   staging-www1.sjc [App] 2024-10-31T04:41:38.445Z - [hmmm] [PusherConnectionManager] connected event ~~ 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 736   staging-www1.sjc [App] 2024-10-31T04:41:38.796Z - [info] [Network] Finished API request in 351ms ~~ command: 'AuthenticatePusher' jsonCode: '407' requestID: '8db0f9509bea9c0e-EZE' 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 736   staging-www1.sjc [App] 2024-10-31T04:41:38.797Z - [info] [Network] Making API request ~~ command: 'Authenticate' shouldUseSecure: '' 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 736   staging-www1.sjc [App] 2024-10-31T04:41:38.836Z - [info] [Network] Finished API request in 391ms ~~ command: 'AuthenticatePusher' jsonCode: '407' requestID: '8db0f9509beb9c0e-EZE' 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 736   staging-www1.sjc [App] 2024-10-31T04:41:38.839Z - [info] [Network] Finished API request in 394ms ~~ command: 'AuthenticatePusher' jsonCode: '407' requestID: '8db0f9509be69c0e-EZE' 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 736   staging-www1.sjc [App] 2024-10-31T04:41:39.238Z - [info] [Network] Finished API request in 793ms ~~ command: 'AuthenticatePusher' jsonCode: '407' requestID: '8db0f9509be89c0e-EZE' 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 736   staging-www1.sjc [App] 2024-10-31T04:57:42.795Z - [hmmm] [Network] API request error: Failed to fetch ~~ message: 'Failed to fetch' request: '[command: 'Authenticate' data: '[useExpensifyLogin: '' partnerName: 'chat-expensify-com' partnerPassword: '<REDACTED>' partnerUserID: 'expensify.cash-78a46e99-5eea-28e8-1810-965c31336f03' partnerUserSecret: '<REDACTED>' shouldRetry: '' forceNetworkRequest: '1' canCancel: '1' appversion: '9.0.55-9']' type: 'post' shouldUseSecure: '']' 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 736   staging-www1.sjc [App] 2024-10-31T04:57:42.795Z - [info] [NetworkConnection] recheck NetInfo ~~ 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 736   staging-www1.sjc [App] 2024-10-31T04:57:42.796Z - [info] [NetworkConnection] NetInfo state change ~~ isInternetReachable: '1' isConnected: '1' type: 'other' details: '[isConnectionExpensive: '']' 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 736   staging-www1.sjc [App] 2024-10-31T04:57:42.796Z - [info] [Network] Client is back online because: NetInfo received a state change event ~~ 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 736   staging-www1.sjc [App] 2024-10-31T04:57:42.796Z - [info] [NetworkStatus] NetInfo.addEventListener event coming, setting "offlineStatus" to true with network state: {"isInternetReachable":true,"isConnected":true,"type":"other","details":{"isConnectionExpensive":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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 736   staging-www1.sjc [App] 2024-10-31T04:57:42.796Z - [info] [Onyx] merge called for key: network properties: isOffline,networkStatus 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 736   staging-www1.sjc [App] 2024-10-31T04:57:42.796Z - [hmmm] Redirecting to Sign In because we failed to reauthenticate ~~ error: '[]' 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 736   staging-www1.sjc [App] 2024-10-31T04:57:42.796Z - [info] [OnyxUpdateManager] Applying update type: https with lastUpdateID: 0 ~~ command: 'Authenticate' 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 736   staging-www1.sjc [App] 2024-10-31T04:57:42.868Z - [info] [Network] Making API request ~~ command: 'AuthenticatePusher' 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 736   staging-www1.sjc [App] 2024-10-31T04:57:42.868Z - [info] [Network] Making API request ~~ command: 'AuthenticatePusher' 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 736   staging-www1.sjc [App] 2024-10-31T04:57:42.868Z - [info] [Network] Making API request ~~ command: 'AuthenticatePusher' 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 736   staging-www1.sjc [App] 2024-10-31T04:57:42.868Z - [info] [Network] Making API request ~~ command: 'AuthenticatePusher' 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 736   staging-www1.sjc [App] 2024-10-31T04:57:43.012Z - [info] [Onyx] merge called for key: session properties: errors 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 737   staging-www1.sjc [App] 2024-10-31T04:57:43.832Z - [info] [Onyx] set called for key: activeClients properties: 0,1,2 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 737   staging-www1.sjc [App] 2024-10-31T04:57:43.832Z - [info] [NetworkConnection] NetInfo state change ~~ isInternetReachable: '' isConnected: '1' type: 'other' details: '[isConnectionExpensive: '']' 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 737   staging-www1.sjc [App] 2024-10-31T04:57:43.832Z - [info] [Network] Client is entering offline mode because: NetInfo received a state change event ~~ 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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 737   staging-www1.sjc [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'
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 737   staging-www1.sjc [App] StoreUtils - Clearing all the stores.
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 737   staging-www1.sjc [App] TransactionStore cache fully cleared
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 737   staging-www1.sjc [App] ReportStore cache cleared
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 737   staging-www1.sjc [App] NVPStore - clear cache
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 737   staging-www1.sjc [App] NVPStore - clear cache
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 737   staging-www1.sjc [App] SharedInNVPStore - clear cache
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 737   staging-www1.sjc [App] ReportDuplicatedTransactionsStore - Cache cleared
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 738   staging-www1.sjc [bench] [App] Bench totals for command Log ~~ {"total":0}
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 738   staging-www1.sjc [App] Profile ~~ {"total":7,"cmd":"Log","jsonCode":200,"output":{"size":71,"gzip":1,"ratio":139},"gzip":71,"PHP":{"total":7,"%":100,"boot":4,"proc":3,"pack":0,"mem":2}}
8db110e5ba2b9c0e-EZE 2024-10-31 04:57:44 738   staging-www1.sjc [App] Timing: cmd= Log totalTime= 7 authTotalTime= authRunTime= 0

Source for the above

So what happened is that the call to Authenticate from the Reauthenticate middleware failed to fetch, for some reason, and then we do not retry it and hit this block which will sign the user out.

So I think if the error is failed to fetch while re-authenticating, and the credentials are set, then the request should be retried, maybe with an exponential backoff like we do for write requests.

neil-marcellini avatar Nov 07 '24 22:11 neil-marcellini

Oh wow, so we have a unit test that should ensure this is working, but the test makes no sense to me. I tweaked it and now it's failing, which is expected and in line with what happens in the issue.

neil-marcellini avatar Nov 07 '24 23:11 neil-marcellini

Is the test that makes no sense the one we just added here https://github.com/Expensify/App/pull/51805?

iwiznia avatar Nov 08 '24 16:11 iwiznia

Oh shoot I better pull main since that was updated recently.

neil-marcellini avatar Nov 08 '24 17:11 neil-marcellini

I left a comment asking about what we're doing with those tests and what the purpose is, because it looks like they're only adding tests but no actual fixes. Hopefully I'm just missing where the fixes are happening.

Anyways, I also figured out a way to reproduce this error, specifically the fact that a user will be signed out if their auth token expires and then the re-authenticate request fails to fetch. Here are some draft PRs I've created just to demonstrate the error.

Make AddComment invalidated auth tokens for testing purposes only Demonstrate reauth failing to fetch once

Steps to reproduce with those PRs:

  1. Send a message
  2. Send another message

You will be logged out, when instead the re-auth should be retried, succeed, and you will not get logged out.

neil-marcellini avatar Nov 08 '24 21:11 neil-marcellini

Heads up, I'm OOO next week. I hope to pick this up when I get back.

neil-marcellini avatar Nov 08 '24 21:11 neil-marcellini

I ran the test with this PR Fix re-authentication when it fails to fetch, and the single commit from Demonstrate reauth failing to fetch once cherry picked into that branch, and I confirmed that the user does not get signed out.

I need to polish some things up there, merge main, and figure out why the unit test isn't passing after the fix even though it works with a manual test. If anyone wants to work on the PR while I'm gone please go ahead 🙂

neil-marcellini avatar Nov 08 '24 21:11 neil-marcellini

@slafortune, @mallenexpensify, @neil-marcellini Whoops! This issue is 2 days overdue. Let's get this updated quick!

melvin-bot[bot] avatar Nov 12 '24 09:11 melvin-bot[bot]

@zirgulis will look into this as we're working on the linked issue, definitely related! Updated here in Slack.

adhorodyski avatar Nov 12 '24 22:11 adhorodyski

@slafortune @mallenexpensify @neil-marcellini 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!

melvin-bot[bot] avatar Nov 13 '24 09:11 melvin-bot[bot]

@slafortune, @mallenexpensify, @neil-marcellini Huh... This is 4 days overdue. Who can take care of this?

melvin-bot[bot] avatar Nov 14 '24 09:11 melvin-bot[bot]

@neil-marcellini @adhorodyski I checked this PR locally and want to share some findings.

Tests in the APITest.ts file are failing because of a RequestThrottle.ts was changed here to a class and getLastRequestWaitTime() in APTest.ts aways returns 0. Reverting it back to be function based fixes the tests and they pass.

More interesting stuff happens in NetworkTest.ts. When I run npm run test tests/unit/NetworkTest.ts every time it produces different results, it seems there's some test pollution occurring somewhere when executing one test after the other. If I comment out the rest of the code and run each test isolated the test passes. Even after adding this test in combination with Neil's fix it passes and the user doesn't get logged out.

I've been working on resolving the test pollution issue, but I haven't had any success yet.

zirgulis avatar Nov 14 '24 17:11 zirgulis

Thanks for the update!

muttmuure avatar Nov 14 '24 17:11 muttmuure