Logout bug hunt (#294)

* Stop storing the log on disk

* Add more info to the session logging

* Only clear session tokens from storage when they've expired

* Retry session resumption a few times if it's a network issue

* Improvements to the 'connecting' screen

src/lib/async/retry.ts

@@ -0,0 +1,29 @@
+import {isNetworkError} from 'lib/strings/errors'
+
+export async function retry<P>(
+  retries: number,
+  cond: (err: any) => boolean,
+  fn: () => Promise<P>,
+): Promise<P> {
+  let lastErr
+  while (retries > 0) {
+    try {
+      return await fn()
+    } catch (e: any) {
+      lastErr = e
+      if (cond(e)) {
+        retries--
+        continue
+      }
+      throw e
+    }
+  }
+  throw lastErr
+}
+
+export async function networkRetry<P>(
+  retries: number,
+  fn: () => Promise<P>,
+): Promise<P> {
+  return retry(retries, isNetworkError, fn)
+}

src/state/models/log.ts

@@ -1,6 +1,7 @@
 import {makeAutoObservable} from 'mobx'
 import {XRPCError, XRPCInvalidResponseError} from '@atproto/xrpc'
-import {isObj, hasProp} from 'lib/type-guards'
+
+const MAX_ENTRIES = 300
 
 interface LogEntry {
   id: string
@@ -28,27 +29,14 @@ export class LogModel {
   entries: LogEntry[] = []
 
   constructor() {
-    makeAutoObservable(this, {serialize: false, hydrate: false})
-  }
-
-  serialize(): unknown {
-    return {
-      entries: this.entries.slice(-100),
-    }
-  }
-
-  hydrate(v: unknown) {
-    if (isObj(v)) {
-      if (hasProp(v, 'entries') && Array.isArray(v.entries)) {
-        this.entries = v.entries.filter(
-          e => isObj(e) && hasProp(e, 'id') && typeof e.id === 'string',
-        )
-      }
-    }
+    makeAutoObservable(this)
   }
 
   private add(entry: LogEntry) {
     this.entries.push(entry)
+    while (this.entries.length > MAX_ENTRIES) {
+      this.entries = this.entries.slice(50)
+    }
   }
 
   debug(summary: string, details?: any) {

src/state/models/root-store.ts

@@ -78,7 +78,6 @@ export class RootStoreModel {
   serialize(): unknown {
     return {
       appInfo: this.appInfo,
-      log: this.log.serialize(),
       session: this.session.serialize(),
       me: this.me.serialize(),
       shell: this.shell.serialize(),
@@ -93,9 +92,6 @@ export class RootStoreModel {
           this.setAppInfo(appInfoParsed.data)
         }
       }
-      if (hasProp(v, 'log')) {
-        this.log.hydrate(v.log)
-      }
       if (hasProp(v, 'me')) {
         this.me.hydrate(v.me)
       }

src/state/models/session.ts

@@ -7,6 +7,7 @@ import {
 } from '@atproto/api'
 import normalizeUrl from 'normalize-url'
 import {isObj, hasProp} from 'lib/type-guards'
+import {networkRetry} from 'lib/async/retry'
 import {z} from 'zod'
 import {RootStoreModel} from './root-store'
 
@@ -35,6 +36,25 @@ interface AdditionalAccountData {
 }
 
 export class SessionModel {
+  // DEBUG
+  // emergency log facility to help us track down this logout issue
+  // remove when resolved
+  // -prf
+  private _log(message: string, details?: Record<string, any>) {
+    details = details || {}
+    details.state = {
+      data: this.data,
+      accounts: this.accounts.map(
+        a =>
+          `${!!a.accessJwt && !!a.refreshJwt ? '✅' : '❌'} ${a.handle} (${
+            a.service
+          })`,
+      ),
+      isResumingSession: this.isResumingSession,
+    }
+    this.rootStore.log.debug(message, details)
+  }
+
   /**
    * Currently-active session
    */
@@ -115,9 +135,7 @@ export class SessionModel {
   async attemptSessionResumption() {
     const sess = this.currentSession
     if (sess) {
-      this.rootStore.log.debug(
-        'SessionModel:attemptSessionResumption found stored session',
-      )
+      this._log('SessionModel:attemptSessionResumption found stored session')
       this.isResumingSession = true
       try {
         return await this.resumeSession(sess)
@@ -127,7 +145,7 @@ export class SessionModel {
         })
       }
     } else {
-      this.rootStore.log.debug(
+      this._log(
         'SessionModel:attemptSessionResumption has no session to resume',
       )
     }
@@ -137,7 +155,7 @@ export class SessionModel {
    * Sets the active session
    */
   setActiveSession(agent: AtpAgent, did: string) {
-    this.rootStore.log.debug('SessionModel:setActiveSession')
+    this._log('SessionModel:setActiveSession')
     this.data = {
       service: agent.service.toString(),
       did,
@@ -155,22 +173,32 @@ export class SessionModel {
     session?: AtpSessionData,
     addedInfo?: AdditionalAccountData,
   ) {
-    this.rootStore.log.debug('SessionModel:persistSession', {
+    this._log('SessionModel:persistSession', {
       service,
       did,
       event,
       hasSession: !!session,
     })
 
-    // upsert the account in our listing
     const existingAccount = this.accounts.find(
       account => account.service === service && account.did === did,
     )
+
+    // fall back to any pre-existing access tokens
+    let refreshJwt = session?.refreshJwt || existingAccount?.refreshJwt
+    let accessJwt = session?.accessJwt || existingAccount?.accessJwt
+    if (event === 'expired') {
+      // only clear the tokens when they're known to have expired
+      refreshJwt = undefined
+      accessJwt = undefined
+    }
+
     const newAccount = {
       service,
       did,
-      refreshJwt: session?.refreshJwt,
-      accessJwt: session?.accessJwt,
+      refreshJwt,
+      accessJwt,
+
       handle: session?.handle || existingAccount?.handle || '',
       displayName: addedInfo
         ? addedInfo.displayName
@@ -198,7 +226,7 @@ export class SessionModel {
    * Clears any session tokens from the accounts; used on logout.
    */
   private clearSessionTokens() {
-    this.rootStore.log.debug('SessionModel:clearSessionTokens')
+    this._log('SessionModel:clearSessionTokens')
     this.accounts = this.accounts.map(acct => ({
       service: acct.service,
       handle: acct.handle,
@@ -236,9 +264,9 @@ export class SessionModel {
    * Attempt to resume a session that we still have access tokens for.
    */
   async resumeSession(account: AccountData): Promise<boolean> {
-    this.rootStore.log.debug('SessionModel:resumeSession')
+    this._log('SessionModel:resumeSession')
     if (!(account.accessJwt && account.refreshJwt && account.service)) {
-      this.rootStore.log.debug(
+      this._log(
         'SessionModel:resumeSession aborted due to lack of access tokens',
       )
       return false
@@ -252,12 +280,14 @@ export class SessionModel {
     })
 
     try {
-      await agent.resumeSession({
-        accessJwt: account.accessJwt,
-        refreshJwt: account.refreshJwt,
-        did: account.did,
-        handle: account.handle,
-      })
+      await networkRetry(3, () =>
+        agent.resumeSession({
+          accessJwt: account.accessJwt || '',
+          refreshJwt: account.refreshJwt || '',
+          did: account.did,
+          handle: account.handle,
+        }),
+      )
       const addedInfo = await this.loadAccountInfo(agent, account.did)
       this.persistSession(
         account.service,
@@ -266,9 +296,9 @@ export class SessionModel {
         agent.session,
         addedInfo,
       )
-      this.rootStore.log.debug('SessionModel:resumeSession succeeded')
+      this._log('SessionModel:resumeSession succeeded')
     } catch (e: any) {
-      this.rootStore.log.debug('SessionModel:resumeSession failed', {
+      this._log('SessionModel:resumeSession failed', {
         error: e.toString(),
       })
       return false
@@ -290,7 +320,7 @@ export class SessionModel {
     identifier: string
     password: string
   }) {
-    this.rootStore.log.debug('SessionModel:login')
+    this._log('SessionModel:login')
     const agent = new AtpAgent({service})
     await agent.login({identifier, password})
     if (!agent.session) {
@@ -308,7 +338,7 @@ export class SessionModel {
     )
 
     this.setActiveSession(agent, did)
-    this.rootStore.log.debug('SessionModel:login succeeded')
+    this._log('SessionModel:login succeeded')
   }
 
   async createAccount({
@@ -324,7 +354,7 @@ export class SessionModel {
     handle: string
     inviteCode?: string
   }) {
-    this.rootStore.log.debug('SessionModel:createAccount')
+    this._log('SessionModel:createAccount')
     const agent = new AtpAgent({service})
     await agent.createAccount({
       handle,
@@ -348,14 +378,14 @@ export class SessionModel {
 
     this.setActiveSession(agent, did)
     this.rootStore.shell.setOnboarding(true)
-    this.rootStore.log.debug('SessionModel:createAccount succeeded')
+    this._log('SessionModel:createAccount succeeded')
   }
 
   /**
    * Close all sessions across all accounts.
    */
   async logout() {
-    this.rootStore.log.debug('SessionModel:logout')
+    this._log('SessionModel:logout')
     // TODO
     // need to evaluate why deleting the session has caused errors at times
     // -prf

src/view/com/auth/withAuthRequired.tsx

@@ -22,11 +22,20 @@ export const withAuthRequired = <P extends object>(
 
 function Loading() {
   const pal = usePalette('default')
+
+  const [isTakingTooLong, setIsTakingTooLong] = React.useState(false)
+  React.useEffect(() => {
+    const t = setTimeout(() => setIsTakingTooLong(true), 15e3)
+    return () => clearTimeout(t)
+  }, [setIsTakingTooLong])
+
   return (
     <View style={[styles.loading, pal.view]}>
       <ActivityIndicator size="large" />
       <Text type="2xl" style={[styles.loadingText, pal.textLight]}>
-        Firing up the grill...
+        {isTakingTooLong
+          ? "This is taking too long. There may be a problem with your internet or with the service, but we're going to try a couple more times..."
+          : 'Connecting...'}
       </Text>
     </View>
   )