marcaaron commented 2 years ago

Problem

Walked away from my computer for a bit and just returned to see that I had been logged out of desktop
Looked at the JS console and found:

[info] Flushing logs as app is going inactive - {}
Log.js:53 [info] Flushing logs older than 10 minutes - {}
Log.js:53 [info] Making API request - {"command":"Get","type":"post","shouldUseSecure":false,"rvl":"personalDetailsList"}
Log.js:53 [info] Making API request - {"command":"Get","type":"post","shouldUseSecure":false,"rvl":"account, loginList, nameValuePairs"}
Log.js:53 [info] Making API request - {"command":"User_GetBetas","type":"post","shouldUseSecure":false}
Log.js:53 [info] Finished API request - {"command":"Get","type":"post","shouldUseSecure":false,"jsonCode":407,"requestID":"6e4d9e408962f4d8-SJC"}
Log.js:53 [info] Making API request - {"command":"Authenticate","type":"post","shouldUseSecure":false}
Log.js:53 [info] Finished API request - {"command":"User_GetBetas","type":"post","shouldUseSecure":false,"jsonCode":407,"requestID":"6e4d9e408960f4d8-SJC"}
Network.js:176 Skipping request and re-queueing:  Objectcommand: "User_GetBetas"isQueuePaused: trueshouldRetry: true[[Prototype]]: Object
Log.js:53 [info] Finished API request - {"command":"Get","type":"post","shouldUseSecure":false,"jsonCode":407,"requestID":"6e4d9e40895af4d8-SJC"}
Network.js:176 Skipping request and re-queueing:  Objectcommand: "User_GetBetas"isQueuePaused: trueshouldRetry: true[[Prototype]]: Object
Network.js:176 Skipping request and re-queueing:  Objectcommand: "Get"isQueuePaused: truereturnValueList: "personalDetailsList"shouldRetry: true[[Prototype]]: Object
Log.js:53 [info] Finished API request - {"command":"Authenticate","type":"post","shouldUseSecure":false,"jsonCode":404,"requestID":"6e4d9e412b36f4d8-SJC"}
Log.js:53 [hmmm] Redirecting to Sign In because we failed to reauthenticate - {"command":"Get","error":"404 No user with that partner/userID"}

So, my authToken looks like it had expired, but when we tried to authenticate Auth threw these logs:

6e4d9e412b36f4d8-SJC | db1.sjc | 2022-03-01 00:01:27 302 | marc@expensify.com | Attempting authenticate for partnerUserID=expensify.cash-5538b172-a933-158d-1da4-842bce1473a0, partnerName=chat-expensify-com
6e4d9e412b36f4d8-SJC | db1.sjc | 2022-03-01 00:01:27 304 | marc@expensify.com | Throwing exception with message: '404 No user with that partner/userID' from auth/command/Authenticate.cpp:109

https://www.expensify.com/_devportal/tools/logSearch/#query=request_id:(%226e4d9e412b36f4d8-SJC%22)+AND+timestamp:[2022-02-28T23:01:27.301Z+TO+2022-03-01T01:01:27.301Z]&index=logs_expensify-015621

I can't think of any reason why the auto generated login would just stop working like that so I looked to compare the last successful call to Authenticate with the most recent failures...

Here's the last successful one:

https://www.expensify.com/_devportal/tools/logSearch/#query=request_id:(%226e4d7ccd0d50f4d0-SJC%22)+AND+timestamp:[2022-02-28T22:38:37.243Z+TO+2022-03-01T00:38:37.243Z]&index=logs_expensify-015621

And the first that failed:

https://www.expensify.com/_devportal/tools/logSearch/#query=request_id:(%226e4d9e408962f4d8-SJC%22)+AND+timestamp:[2022-02-28T23:01:27.178Z+TO+2022-03-01T01:01:27.178Z]&index=logs_expensify-015621

I tried to look for when this login was deleted and found this log:

https://www.expensify.com/_devportal/tools/logSearch/#query=request_id:(%226e4d2f9718c4253c-SJC%22)+AND+timestamp:[2022-02-28T21:45:54.428Z+TO+2022-02-28T23:45:54.428Z]&index=logs_expensify-015620

Which looks like it happened before the last successful one (even more confused). But enough for me to assume that we should be using the new login that was created:

expensify.cash-110b5f78-8255-6e29-5b92-607539848531

And not the deleted one:

expensify.cash-5538b172-a933-158d-1da4-842bce1473a0

So what is happening here exactly? I'm not sure, but I'm thinking that we called CreateLogin at some point and should have set the new updated credentials, but didn't do that for some reason and then kept trying to use the old ones instead...

Why is this important?

We should not be logged out randomly and should stay logged in.

Solution

There's only one place we call API.CreateLogin() in NewDot and it's right here:

https://github.com/Expensify/App/blob/00805b2b495fac25f53a42231dd3e5ae78138a2a/src/libs/actions/Session/index.js#L179-L211

We also set the autoGenerated credentials in that step.. so why did API not use them?

I wasn't able to find out the answer, but it's concerning since the most likely possibility is that we:

Called Onyx.merge() to set the credentials
Subscribers did not update with the new data (e.g. API.js here)

Note: Marking this as Internal since there are many logs referenced that won't be accessible to contributors (but hoping someone spots something that I've missed).