Behaviour logging improvements and add logs to more controllers

src/controllers/addressBook/addressBook.ts

@@ -122,12 +122,16 @@ export class AddressBookController extends EventEmitter implements IAddressBookC
       return
     }
 
-    this.#manuallyAddedContacts.push({
+    const newContact = {
       name: trimmedName,
       address: checksummedAddress,
       createdAt: Date.now(),
       updatedAt: Date.now()
-    })
+    }
+
+    this.debugLog('Adding a new contact', newContact)
+
+    this.#manuallyAddedContacts.push(newContact)
 
     this.#handleManuallyAddedContactsChange()
   }
@@ -150,6 +154,12 @@ export class AddressBookController extends EventEmitter implements IAddressBookC
 
     this.#manuallyAddedContacts = this.#manuallyAddedContacts.map((contact) => {
       if (contact.address.toLowerCase() === address.toLowerCase()) {
+        this.debugLog('Renaming manually added contact', () => ({
+          oldName: contact.name,
+          newName: trimmedNewName,
+          address: contact.address
+        }))
+
         return { ...contact, name: trimmedNewName, updatedAt: Date.now() }
       }
 
@@ -174,6 +184,8 @@ export class AddressBookController extends EventEmitter implements IAddressBookC
       return
     }
 
+    this.debugLog('Removing manually added contact', checksummedAddress)
+
     this.#manuallyAddedContacts = this.#manuallyAddedContacts.filter(
       (contact) => contact.address.toLowerCase() !== address.toLowerCase()
     )

src/controllers/autoLogin/autoLogin.ts

@@ -127,6 +127,7 @@ export class AutoLoginController extends EventEmitter implements IAutoLoginContr
   }
 
   static convertSiweToViemFormat(parsedSiweMessage: SiweMessage): SiweMessageType {
+    // eslint-disable-next-line @typescript-eslint/no-unused-vars
     const { expirationTime, notBefore, issuedAt, address, ...viemFormatParsedMessage } =
       parsedSiweMessage
 
@@ -162,6 +163,7 @@ export class AutoLoginController extends EventEmitter implements IAutoLoginContr
       // Quick check to see if it looks like a SIWE message at all
       if (messageString.match(prefixRegex) === null) return null
     } catch (e) {
+      console.error('Error parsing message:', e, 'Original message:', message)
       return null
     }
 
@@ -336,6 +338,11 @@ export class AutoLoginController extends EventEmitter implements IAutoLoginContr
 
       if (accountPolicies.length === 0) return
 
+      this.debugLog(
+        `Revoking auto-login policy for ${accountAddress} on ${policyDomain}`,
+        policyUriPrefix
+      )
+
       this.#policiesByAccount[accountAddress] = accountPolicies.filter(
         (p) => !(p.domain === policyDomain && p.uriPrefix === policyUriPrefix)
       )
@@ -348,6 +355,8 @@ export class AutoLoginController extends EventEmitter implements IAutoLoginContr
     await this.initialLoadPromise
 
     await this.withStatus('revokeAllPoliciesForDomain', async () => {
+      this.debugLog(`Revoking all auto-login policies for ${policyDomain}`, policyUriPrefix)
+
       Object.keys(this.#policiesByAccount).forEach((accountAddress) => {
         const accountPolicies = this.#policiesByAccount[accountAddress] || []
 
@@ -380,6 +389,10 @@ export class AutoLoginController extends EventEmitter implements IAutoLoginContr
     }
 
     const policy = this.#createOrUpdatePolicyFromSiwe(parsedSiwe, { autoLoginDuration })
+    this.debugLog(
+      `Auto-login policy created/updated for ${parsedSiwe.address} on ${parsedSiwe.domain}`,
+      policy
+    )
     await this.#storage.set('autoLoginPolicies', this.#policiesByAccount)
     this.emitUpdate()
 
@@ -395,6 +408,10 @@ export class AutoLoginController extends EventEmitter implements IAutoLoginContr
 
     const policyStatus = this.#getPolicyStatus(parsedSiwe, accountKeys, accountData)
 
+    this.debugLog(
+      `Auto-login status for ${parsedSiwe.address} on ${parsedSiwe.domain}: ${policyStatus}`
+    )
+
     switch (policyStatus) {
       case 'valid-policy':
         return 'active'
@@ -442,6 +459,10 @@ export class AutoLoginController extends EventEmitter implements IAutoLoginContr
 
     await this.#signMessage.sign()
 
+    this.debugLog(
+      `Auto-login signed message for ${messageToSign.accountAddr} on chain ${messageToSign.chainId}`
+    )
+
     return this.#signMessage.signedMessage
   }
 

src/controllers/eventEmitter/eventEmitter.ts

@@ -143,12 +143,11 @@ export default class EventEmitter<DebugFlow extends string = string> {
   /** Per-controller gated debug log. No-op unless this controller's namespace is
    *  toggled on via DebugController. */
   protected debugLog(
-    flow: DebugFlow,
     message: string,
     payload?: unknown | (() => unknown),
-    options?: DebugLogOptions
+    options?: DebugLogOptions & { flow?: DebugFlow }
   ): void {
-    moduleDebugLog(this.name, flow, message, payload, options)
+    moduleDebugLog(this.name, message, payload, options)
   }
 
   protected emitError(error: ErrorRef) {

src/controllers/portfolio/portfolio.ts

@@ -707,11 +707,11 @@ export class PortfolioController
   async overrideSimulationResults(accountOp: AccountOp) {
     const { accountAddr, chainId } = accountOp
     this.debugLog(
-      'simulation',
       `${chainId.toString()}: Overriding simulation results for ${accountAddr}`,
       () => ({
         accountOpId: accountOp.id
-      })
+      }),
+      { flow: 'simulation' }
     )
 
     const updatePromise = async () => {
@@ -842,20 +842,24 @@ export class PortfolioController
       networkAlreadyScheduledForAccount.scheduledAt = Date.now()
 
       this.debugLog(
-        'simulation',
         `${chainId.toString()} Debounced scheduled update for ${accountId}`,
         () => ({
           bypassServerSideCache: networkAlreadyScheduledForAccount.bypassServerSideCache,
           scheduledAt: networkAlreadyScheduledForAccount.scheduledAt
-        })
+        }),
+        { flow: 'simulation' }
       )
       return
     }
 
-    this.debugLog('simulation', `${chainId.toString()} Scheduled update for ${accountId}`, () => ({
-      bypassServerSideCache,
-      scheduledAt: Date.now()
-    }))
+    this.debugLog(
+      `${chainId.toString()} Scheduled update for ${accountId}`,
+      () => ({
+        bypassServerSideCache,
+        scheduledAt: Date.now()
+      }),
+      { flow: 'simulation' }
+    )
 
     this.#scheduledUpdates[accountId] = [
       ...(this.#scheduledUpdates[accountId] || []),
@@ -910,10 +914,14 @@ export class PortfolioController
     })
 
     if (!accountAddrToUpdate || networksToUpdate.length === 0) return
-    this.debugLog('simulation', `Discarding simulation for ${accountAddrToUpdate}`, () => ({
-      discardedOpIds: accountOps.map((op) => op.id),
-      chainIds: networksToUpdate.map((n) => n.chainId.toString())
-    }))
+    this.debugLog(
+      `Discarding simulation for ${accountAddrToUpdate}`,
+      () => ({
+        discardedOpIds: accountOps.map((op) => op.id),
+        chainIds: networksToUpdate.map((n) => n.chainId.toString())
+      }),
+      { flow: 'simulation' }
+    )
     await this.updateSelectedAccount(accountAddrToUpdate, networksToUpdate, {
       accountOps: accountOpsAfterUpdate
     })
@@ -1321,15 +1329,15 @@ export class PortfolioController
     // Request can be skipped altogether
     if (canSkipExternalApiHintsUpdate && canSkipDefiUpdate) {
       this.debugLog(
-        'discovery',
         `${chainId.toString()}: Skipping portfolio discovery for ${account.addr}`,
         () => ({
           lastUpdate: externalApiHintsResponse?.lastUpdate,
           hasHints: externalApiHintsResponse?.hasHints,
           isManualUpdate,
           bypassServerSideCache,
           hasNonceChangedSinceLastUpdate
-        })
+        }),
+        { flow: 'discovery' }
       )
 
       return null
@@ -1459,14 +1467,14 @@ export class PortfolioController
 
     if (canSkipUpdate) {
       this.debugLog(
-        'update',
         `${network.chainId.toString()} update skipped for ${account.addr}`,
         () => ({
           lastSuccessfulUpdate: accountState[network.chainId.toString()]?.lastSuccessfulUpdate,
           maxDataAgeMs,
           isManualUpdate,
           isLoading: accountState[network.chainId.toString()]?.isLoading
-        })
+        }),
+        { flow: 'update' }
       )
       return [true, null]
     }
@@ -1651,11 +1659,15 @@ export class PortfolioController
       PortfolioController.#getCanSkipUpdate(accountState['defiApps'], defiMaxDataAgeMs)
 
     if (canSkipUpdate) {
-      this.debugLog('defi', 'Skipping DeFi apps update for account', () => ({
-        account: account.addr,
-        lastSuccessfulUpdate: accountState['defiApps']?.lastSuccessfulUpdate,
-        defiMaxDataAgeMs
-      }))
+      this.debugLog(
+        'Skipping DeFi apps update for account',
+        () => ({
+          account: account.addr,
+          lastSuccessfulUpdate: accountState['defiApps']?.lastSuccessfulUpdate,
+          defiMaxDataAgeMs
+        }),
+        { flow: 'defi' }
+      )
       return
     }
 
@@ -1833,14 +1845,14 @@ export class PortfolioController
     learnedTokensHints.push(...defiHints)
 
     this.debugLog(
-      'hints',
       `${chainId.toString()}: hints for ${accountId} (${!isManualUpdate ? 'not ' : ''}enhanced with those of other accounts)`,
       () => ({
         specialErc20Hints,
         specialErc721Hints,
         learnedTokensHints,
         learnedNftsHints
-      })
+      }),
+      { flow: 'hints' }
     )
 
     return {
@@ -1950,11 +1962,15 @@ export class PortfolioController
     const accountState = this.#state[accountId]
 
     const networksToUpdate = networks || this.#networks.networks
-    this.debugLog('update', `Update queued for ${accountId}`, () => ({
-      chainIds: networksToUpdate.map((n) => n.chainId.toString()),
-      hasSimulation: !!simulation,
-      opts
-    }))
+    this.debugLog(
+      `Update queued for ${accountId}`,
+      () => ({
+        chainIds: networksToUpdate.map((n) => n.chainId.toString()),
+        hasSimulation: !!simulation,
+        opts
+      }),
+      { flow: 'update' }
+    )
     await Promise.all([
       this.#getAdditionalPortfolio(accountId, paramsMaxDataAgeMs),
       ...networksToUpdate.map(async (network) => {
@@ -2022,20 +2038,20 @@ export class PortfolioController
 
           if (accountOpsToSimulate?.length)
             this.debugLog(
-              'simulation',
               `${network.chainId.toString()}: Simulated ${accountOpsToSimulate.length} account op(s)`,
               () => ({
                 accountOpIds: accountOpsToSimulate.map((op) => op.id),
                 isSuccessful
-              })
+              }),
+              { flow: 'simulation' }
             )
 
           this.debugLog(
-            'update',
             `${network.chainId.toString()}: Portfolio updated on ${network.name}`,
             () => ({
               isSuccessful
-            })
+            }),
+            { flow: 'update' }
           )
 
           // Learn tokens and nfts from the portfolio lib
@@ -2250,11 +2266,9 @@ export class PortfolioController
 
     networkToBeLearnedTokens = [...tokensToLearn, ...networkToBeLearnedTokens]
 
-    this.debugLog(
-      'learning',
-      `${chainId.toString()}: Added ERC-20 tokens to be learned`,
-      tokensToLearn
-    )
+    this.debugLog(`${chainId.toString()}: Added ERC-20 tokens to be learned`, tokensToLearn, {
+      flow: 'learning'
+    })
 
     this.#toBeLearnedAssets.erc20s[chainIdString] = networkToBeLearnedTokens
     return true
@@ -2343,11 +2357,15 @@ export class PortfolioController
 
           if (tokenId) toBeLearnedAssets[collectionAddress].push(tokenId)
 
-          this.debugLog('learning', `${chainId.toString()}: Added ERC-721 to be learned`, () => ({
-            collectionAddress,
-            tokenId: tokenId.toString(),
-            accountAddr
-          }))
+          this.debugLog(
+            `${chainId.toString()}: Added ERC-721 to be learned`,
+            () => ({
+              collectionAddress,
+              tokenId: tokenId.toString(),
+              accountAddr
+            }),
+            { flow: 'learning' }
+          )
         })
       })
 
@@ -2438,10 +2456,14 @@ export class PortfolioController
       .sort(([, timestampA], [, timestampB]) => timestampB - timestampA)
       .map(([address]) => address)
 
-    this.debugLog('learning', `${chainId.toString()}: Tokens learned for ${key}`, () => ({
-      learned: tokensWithBalance.filter((addr) => addr !== ZeroAddress),
-      currentlyTracked: Object.keys(learnedTokens).length
-    }))
+    this.debugLog(
+      `${chainId.toString()}: Tokens learned for ${key}`,
+      () => ({
+        learned: tokensWithBalance.filter((addr) => addr !== ZeroAddress),
+        currentlyTracked: Object.keys(learnedTokens).length
+      }),
+      { flow: 'learning' }
+    )
 
     // Remove the oldest no longer owned tokens
     if (noLongerOwnedTokens.length > LEARNED_UNOWNED_LIMITS.erc20s) {
@@ -2450,13 +2472,13 @@ export class PortfolioController
         delete learnedTokens[address]
       })
       this.debugLog(
-        'learning',
         `${chainId.toString()}: Discarded learned tokens for ${key}`,
         () => ({
           discarded,
           limit: LEARNED_UNOWNED_LIMITS.erc20s,
           noLongerOwned: noLongerOwnedTokens.length
-        })
+        }),
+        { flow: 'learning' }
       )
     }