diff --git a/packages/multichain-account-service/CHANGELOG.md b/packages/multichain-account-service/CHANGELOG.md index 650da81ae7b..92b7fd49623 100644 --- a/packages/multichain-account-service/CHANGELOG.md +++ b/packages/multichain-account-service/CHANGELOG.md @@ -15,6 +15,10 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 - This behavior was enabled by default and can now be turned off by the clients. - Add new `snapPlatformWatcher.timeoutMs` configuration ([#8196](https://github.com/MetaMask/core/pull/8196)) - Allows configuring how long to wait for the Snap keyring to appear in `KeyringController` before timing out (Default is 5000 ms). +- Add more tracing (alignment, create account v1/v2) ([#8244](https://github.com/MetaMask/core/pull/8244)) +- Add local perf tracing ([#8244](https://github.com/MetaMask/core/pull/8244)) + - Each traces are now automatically wrapped and will log performance timings using the internal logger. + - Only enabled if `metamask:multichain-account-service` is part of `DEBUG` (env var) filters. ### Changed diff --git a/packages/multichain-account-service/package.json b/packages/multichain-account-service/package.json index beab7a520f0..47e5c58a4a9 100644 --- a/packages/multichain-account-service/package.json +++ b/packages/multichain-account-service/package.json @@ -70,6 +70,7 @@ "devDependencies": { "@metamask/account-api": "^1.0.0", "@metamask/auto-changelog": "^3.4.4", + "@metamask/controller-utils": "^11.19.0", "@metamask/eth-hd-keyring": "^13.0.0", "@metamask/providers": "^22.1.0", "@ts-bridge/cli": "^0.6.4", diff --git a/packages/multichain-account-service/src/MultichainAccountService.test.ts b/packages/multichain-account-service/src/MultichainAccountService.test.ts index d22e3a999ee..c9d04a3c548 100644 --- a/packages/multichain-account-service/src/MultichainAccountService.test.ts +++ b/packages/multichain-account-service/src/MultichainAccountService.test.ts @@ -12,6 +12,8 @@ import { import type { KeyringObject } from '@metamask/keyring-controller'; import type { EthKeyring } from '@metamask/keyring-internal-api'; +import { traceFallback } from './analytics'; +import { isPerfEnabled, withLocalPerfTrace } from './analytics/perf'; import type { MultichainAccountServiceOptions } from './MultichainAccountService'; import { MultichainAccountService } from './MultichainAccountService'; import type { Bip44AccountProvider } from './providers'; @@ -48,6 +50,12 @@ import { } from './tests'; import type { MultichainAccountServiceMessenger } from './types'; +// Mock perf helpers so tests can control isPerfEnabled() without setting DEBUG env var. +jest.mock('./analytics/perf', () => ({ + isPerfEnabled: jest.fn().mockReturnValue(false), + withLocalPerfTrace: jest.fn((trace) => trace), +})); + // Mock providers. jest.mock('./providers/EvmAccountProvider', () => { return { @@ -136,11 +144,13 @@ async function setup({ keyrings = [MOCK_HD_KEYRING_1, MOCK_HD_KEYRING_2], accounts, providerConfigs, + config, }: { rootMessenger?: RootMessenger; keyrings?: KeyringObject[]; accounts?: KeyringAccount[]; providerConfigs?: MultichainAccountServiceOptions['providerConfigs']; + config?: MultichainAccountServiceOptions['config']; } = {}): Promise<{ service: MultichainAccountService; rootMessenger: RootMessenger; @@ -264,6 +274,7 @@ async function setup({ const service = new MultichainAccountService({ messenger, providerConfigs, + config, }); await service.init(); @@ -321,6 +332,90 @@ describe('MultichainAccountService', () => { ); }); + it('passes traceFallback to providers when no config.trace is provided and perf is disabled', async () => { + jest.mocked(isPerfEnabled).mockReturnValue(false); + + const { mocks, messenger } = await setup({ + accounts: [MOCK_HD_ACCOUNT_1, MOCK_SOL_ACCOUNT_1], + }); + + expect(withLocalPerfTrace).not.toHaveBeenCalled(); + expect(mocks.EvmAccountProvider.constructor).toHaveBeenCalledWith( + messenger, + undefined, + traceFallback, + ); + expect(mocks.SolAccountProvider.constructor).toHaveBeenCalledWith( + messenger, + undefined, + traceFallback, + ); + }); + + it('passes config.trace to providers when provided and perf is disabled', async () => { + jest.mocked(isPerfEnabled).mockReturnValue(false); + const customTrace = jest.fn(); + + const { mocks, messenger } = await setup({ + accounts: [MOCK_HD_ACCOUNT_1, MOCK_SOL_ACCOUNT_1], + config: { trace: customTrace }, + }); + + expect(withLocalPerfTrace).not.toHaveBeenCalled(); + expect(mocks.EvmAccountProvider.constructor).toHaveBeenCalledWith( + messenger, + undefined, + customTrace, + ); + expect(mocks.SolAccountProvider.constructor).toHaveBeenCalledWith( + messenger, + undefined, + customTrace, + ); + }); + + it('wraps trace with local perf trace and passes it to providers when perf is enabled', async () => { + jest.mocked(isPerfEnabled).mockReturnValue(true); + const wrappedTrace = jest.fn(); + jest.mocked(withLocalPerfTrace).mockReturnValue(wrappedTrace); + + const { mocks, messenger } = await setup({ + accounts: [MOCK_HD_ACCOUNT_1, MOCK_SOL_ACCOUNT_1], + }); + + expect(withLocalPerfTrace).toHaveBeenCalledTimes(1); + expect(withLocalPerfTrace).toHaveBeenCalledWith(traceFallback); + expect(mocks.EvmAccountProvider.constructor).toHaveBeenCalledWith( + messenger, + undefined, + wrappedTrace, + ); + expect(mocks.SolAccountProvider.constructor).toHaveBeenCalledWith( + messenger, + undefined, + wrappedTrace, + ); + }); + + it('wraps config.trace with local perf trace when perf is enabled', async () => { + jest.mocked(isPerfEnabled).mockReturnValue(true); + const customTrace = jest.fn(); + const wrappedTrace = jest.fn(); + jest.mocked(withLocalPerfTrace).mockReturnValue(wrappedTrace); + + const { mocks } = await setup({ + accounts: [MOCK_HD_ACCOUNT_1, MOCK_SOL_ACCOUNT_1], + config: { trace: customTrace }, + }); + + expect(withLocalPerfTrace).toHaveBeenCalledWith(customTrace); + expect(mocks.EvmAccountProvider.constructor).toHaveBeenCalledWith( + expect.anything(), + undefined, + wrappedTrace, + ); + }); + it('allows optional configs for some providers', async () => { const providerConfigs: MultichainAccountServiceOptions['providerConfigs'] = { diff --git a/packages/multichain-account-service/src/MultichainAccountService.ts b/packages/multichain-account-service/src/MultichainAccountService.ts index d1b41a4acc8..c8788f34704 100644 --- a/packages/multichain-account-service/src/MultichainAccountService.ts +++ b/packages/multichain-account-service/src/MultichainAccountService.ts @@ -6,6 +6,7 @@ import type { MultichainAccountWalletId, Bip44Account, } from '@metamask/account-api'; +import type { TraceCallback } from '@metamask/controller-utils'; import type { HdKeyring } from '@metamask/eth-hd-keyring'; import type { EntropySourceId, KeyringAccount } from '@metamask/keyring-api'; import { KeyringTypes } from '@metamask/keyring-controller'; @@ -13,6 +14,7 @@ import type { InternalAccount } from '@metamask/keyring-internal-api'; import { areUint8ArraysEqual, assert } from '@metamask/utils'; import { traceFallback } from './analytics'; +import { isPerfEnabled, withLocalPerfTrace } from './analytics/perf'; import { reportError } from './errors'; import { projectLogger as log } from './logger'; import type { MultichainAccountGroup } from './MultichainAccountGroup'; @@ -121,6 +123,8 @@ export class MultichainAccountService { readonly #providers: Bip44AccountProvider[]; + readonly #trace: TraceCallback; + readonly #wallets: Map< MultichainAccountWalletId, MultichainAccountWallet> @@ -153,23 +157,31 @@ export class MultichainAccountService { this.#messenger = messenger; this.#wallets = new Map(); - // Pass trace callback directly to preserve original 'this' context - // This avoids binding the callback to the MultichainAccountService instance - const traceCallback = config?.trace ?? traceFallback; + // Pass trace callback directly to preserve original 'this' context. + // This avoids binding the callback to the MultichainAccountService instance. + let trace: TraceCallback = config?.trace ?? traceFallback; + + // Wrap the trace callback with local performance tracing if performance logging is enabled. + if (isPerfEnabled()) { + trace = withLocalPerfTrace(trace); + } + + // This trace is passed down to wallets and providers to be used for tracing operations within them. + this.#trace = trace; // TODO: Rely on keyring capabilities once the keyring API is used by all keyrings. this.#providers = [ new EvmAccountProvider( this.#messenger, providerConfigs?.[EVM_ACCOUNT_PROVIDER_NAME], - traceCallback, + trace, ), new AccountProviderWrapper( this.#messenger, new SolAccountProvider( this.#messenger, providerConfigs?.[SOL_ACCOUNT_PROVIDER_NAME], - traceCallback, + trace, ), ), // Custom account providers that can be provided by the MetaMask client. @@ -264,6 +276,7 @@ export class MultichainAccountService { entropySource, providers: this.#providers, messenger: this.#messenger, + trace: this.#trace, }); wallet.init(serviceState[entropySource]); this.#wallets.set(wallet.id, wallet); @@ -410,6 +423,7 @@ export class MultichainAccountService { providers: this.#providers, entropySource: result.id, messenger: this.#messenger, + trace: this.#trace, }); } @@ -434,6 +448,7 @@ export class MultichainAccountService { providers: this.#providers, entropySource: entropySourceId, messenger: this.#messenger, + trace: this.#trace, }); } @@ -461,6 +476,7 @@ export class MultichainAccountService { providers: this.#providers, entropySource: entropySourceId, messenger: this.#messenger, + trace: this.#trace, }); } diff --git a/packages/multichain-account-service/src/MultichainAccountWallet.test.ts b/packages/multichain-account-service/src/MultichainAccountWallet.test.ts index a2ca44a9b77..705ff8a9cd3 100644 --- a/packages/multichain-account-service/src/MultichainAccountWallet.test.ts +++ b/packages/multichain-account-service/src/MultichainAccountWallet.test.ts @@ -14,6 +14,7 @@ import { AccountCreationType, } from '@metamask/keyring-api'; import type { InternalAccount } from '@metamask/keyring-internal-api'; +import { createDeferredPromise } from '@metamask/utils'; import type { WalletState } from './MultichainAccountWallet'; import { MultichainAccountWallet } from './MultichainAccountWallet'; @@ -542,11 +543,21 @@ describe('MultichainAccountWallet', () => { ]; evmProvider.createAccounts.mockResolvedValueOnce(evmAccounts); - jest.spyOn(wallet, 'alignAccounts').mockResolvedValue(undefined); + // We use a non-resolving mock for SOL provider because we want to verify + // that it's not called during group creation, but rather during the deferred alignment. + const { + promise: mockSolCreateAccountsPromise, + resolve: mockSolCreateAccountsResolve, + } = createDeferredPromise(); + jest + .spyOn(solProvider, 'createAccounts') + .mockImplementationOnce(() => mockSolCreateAccountsPromise); // With wait=false (default), only EVM accounts are created immediately. const groups = await wallet.createMultichainAccountGroups({ to: 2 }); + // At this point, only EVM provider should have been called to create accounts for groups 1 and 2, but + // the SOL provider is has been scheduled, so it shouldn't block. expect(groups).toHaveLength(3); expect(groups[0].groupIndex).toBe(0); // Existing group. expect(groups[1].groupIndex).toBe(1); // New group. @@ -554,7 +565,9 @@ describe('MultichainAccountWallet', () => { expect(wallet.getAccountGroups()).toHaveLength(3); // SOL provider is not called during group creation; it's deferred to alignment. - expect(solProvider.createAccounts).not.toHaveBeenCalled(); + mockSolCreateAccountsResolve(); + await mockSolCreateAccountsPromise; + expect(solProvider.createAccounts).toHaveBeenCalled(); }); it('returns all existing groups when maxGroupIndex is less than nextGroupIndex', async () => { @@ -575,8 +588,6 @@ describe('MultichainAccountWallet', () => { accounts: [[mockEvmAccount0, mockEvmAccount1, mockEvmAccount2]], }); - jest.spyOn(wallet, 'alignAccounts').mockResolvedValue(undefined); - // Request groups 0-1 when groups 0-2 exist. const groups = await wallet.createMultichainAccountGroups({ to: 1 }); diff --git a/packages/multichain-account-service/src/MultichainAccountWallet.ts b/packages/multichain-account-service/src/MultichainAccountWallet.ts index eb71ee60b23..af213db8f9e 100644 --- a/packages/multichain-account-service/src/MultichainAccountWallet.ts +++ b/packages/multichain-account-service/src/MultichainAccountWallet.ts @@ -12,11 +12,13 @@ import { toDefaultAccountGroupId, toMultichainAccountWalletId, } from '@metamask/account-api'; +import type { TraceCallback, TraceRequest } from '@metamask/controller-utils'; import { AccountCreationType } from '@metamask/keyring-api'; import type { EntropySourceId, KeyringAccount } from '@metamask/keyring-api'; import { assert } from '@metamask/utils'; import { Mutex } from 'async-mutex'; +import { toProviderDataTraces, traceFallback, TraceName } from './analytics'; import { reportError } from './errors'; import type { Logger } from './logger'; import { @@ -75,6 +77,8 @@ export class MultichainAccountWallet< readonly #messenger: MultichainAccountServiceMessenger; + readonly #trace: TraceCallback; + readonly #log: Logger; #initialized = false; @@ -85,16 +89,19 @@ export class MultichainAccountWallet< providers, entropySource, messenger, + trace, }: { providers: Bip44AccountProvider[]; entropySource: EntropySourceId; messenger: MultichainAccountServiceMessenger; + trace?: TraceCallback; }) { this.#id = toMultichainAccountWalletId(entropySource); this.#providers = providers; this.#entropySource = entropySource; this.#messenger = messenger; this.#accountGroups = new Map(); + this.#trace = trace ?? traceFallback; this.#log = createModuleLogger(log, `[${this.#id}]`); @@ -434,29 +441,46 @@ export class MultichainAccountWallet< * @param range.from - Starting group index (inclusive). * @param range.to - Ending group index (inclusive). * @param providers - The providers to align accounts for. + * @param options - Options. + * @param options.trace - Trace options. + * @param options.trace.data - Optional trace data. */ async #alignAccountsForRange( { from, to }: Required, providers: Bip44AccountProvider[], + options: { trace?: { data?: TraceRequest['data'] } } = {}, ): Promise { - const { groupStateByGroupIndex, failures } = - await this.#buildGroupStateForRange(from, to, providers); + await this.#trace( + { + name: TraceName.WalletAlignment, + data: { + from, + to, + ...toProviderDataTraces(providers), + ...options.trace?.data, + }, + }, + async () => { + const { groupStateByGroupIndex, failures } = + await this.#buildGroupStateForRange(from, to, providers); - if (failures.length) { - const error = failures.reduce( - (message, failure) => `${message}\n- ${failure}`, - 'Unable to align some accounts. Providers threw the following errors:', - ); - console.warn(error); - this.#log(`${WARNING_PREFIX} ${error}`); - } + if (failures.length) { + const error = failures.reduce( + (message, failure) => `${message}\n- ${failure}`, + 'Unable to align some accounts. Providers threw the following errors:', + ); + console.warn(error); + this.#log(`${WARNING_PREFIX} ${error}`); + } - for (let groupIndex = from; groupIndex <= to; groupIndex++) { - const groupState = groupStateByGroupIndex.get(groupIndex); - if (groupState) { - this.#createOrUpdateMultichainAccountGroup(groupIndex, groupState); - } - } + for (let groupIndex = from; groupIndex <= to; groupIndex++) { + const groupState = groupStateByGroupIndex.get(groupIndex); + if (groupState) { + this.#createOrUpdateMultichainAccountGroup(groupIndex, groupState); + } + } + }, + ); } /** @@ -548,27 +572,44 @@ export class MultichainAccountWallet< groupIndex: number, options: { waitForAllProvidersToFinishCreatingAccounts?: boolean; - } = { waitForAllProvidersToFinishCreatingAccounts: false }, + } = {}, ): Promise> { - // If the group already exists, return it. - const existingGroup = this.getMultichainAccountGroup(groupIndex); - if (existingGroup) { - this.#log( - `Trying to re-create existing group: [${existingGroup.id}] (idempotent)`, - ); - return existingGroup; - } + // Use this to avoid having it as `boolean | undefined`. + const waitForAllProvidersToFinishCreatingAccounts = + options.waitForAllProvidersToFinishCreatingAccounts ?? false; + + return await this.#trace( + { + name: TraceName.WalletCreateMultichainAccountGroup, + data: { + groupIndex, + waitForAllProvidersToFinishCreatingAccounts, + }, + }, + async () => { + assertGroupIndexIsValid(groupIndex, this.getNextGroupIndex()); + + // If the group already exists, return it. + const existingGroup = this.getMultichainAccountGroup(groupIndex); + if (existingGroup) { + this.#log( + `Trying to re-create existing group: [${existingGroup.id}] (idempotent)`, + ); + return existingGroup; + } - // Create a single group with a range of 1 (so we can reuse the batch creation logic) for the - // given group index. - const groups = await this.createMultichainAccountGroups( - { from: groupIndex, to: groupIndex }, - options, - ); + // Create a single group with a range of 1 (so we can reuse the batch creation logic) for the + // given group index. + const groups = await this.#createMultichainAccountGroups( + { from: groupIndex, to: groupIndex }, + options, + ); - const group = groups[0]; - assert(group, `Expected group at index ${groupIndex} to exist`); - return group; + const group = groups[0]; + assert(group, `Expected group at index ${groupIndex} to exist`); + return group; + }, + ); } /** @@ -591,13 +632,56 @@ export class MultichainAccountWallet< { from = 0, to }: GroupIndexRange, options: { waitForAllProvidersToFinishCreatingAccounts?: boolean; - } = { waitForAllProvidersToFinishCreatingAccounts: false }, + } = {}, + ): Promise[]> { + // Use this to avoid having it as `boolean | undefined`. + const waitForAllProvidersToFinishCreatingAccounts = + options.waitForAllProvidersToFinishCreatingAccounts ?? false; + + return await this.#trace( + { + name: TraceName.WalletCreateMultichainAccountGroups, + data: { + from, + to, + waitForAllProvidersToFinishCreatingAccounts, + }, + }, + async () => + await this.#createMultichainAccountGroups({ from, to }, options), + ); + } + + /** + * Creates multiple multichain account groups up to maxGroupIndex. + * + * NOTE: This operation WILL lock the wallet's mutex. + * + * @param range - The range of group indices to create. + * @param range.from - Starting group index to create (inclusive). + * @param range.to - Maximum group index to create (inclusive). + * @param options - Options to configure the account creation. + * @param options.waitForAllProvidersToFinishCreatingAccounts - Whether to wait for all + * account providers to finish creating their accounts before returning. If `false`, only + * the EVM provider is used and non-EVM account creation is deferred via + * {@link MultichainAccountWallet.alignAccounts}. Defaults to false. + * @throws If range is invalid (e.g. from is greater than to, from or to is negative, etc.). + * @returns Array of created multichain account groups. + */ + async #createMultichainAccountGroups( + { from, to }: Required, + options: { + waitForAllProvidersToFinishCreatingAccounts?: boolean; + }, ): Promise[]> { assertGroupIndexRangeIsValid({ from, to }); assertGroupIndexIsValid(from, this.getNextGroupIndex()); + const waitForAllProvidersToFinishCreatingAccounts = + options.waitForAllProvidersToFinishCreatingAccounts ?? false; + const [evmProvider, ...otherProviders] = this.#getProviders(); - const providers = options.waitForAllProvidersToFinishCreatingAccounts + const providers = waitForAllProvidersToFinishCreatingAccounts ? this.#providers : [evmProvider]; @@ -608,12 +692,18 @@ export class MultichainAccountWallet< // We need to run a post-alignment since non-EVM accounts have not // been created yet. - if (!options.waitForAllProvidersToFinishCreatingAccounts) { + if (!waitForAllProvidersToFinishCreatingAccounts) { const alignOtherAccounts = async (): Promise => { this.#log(`Aligning accounts... (post)`); await this.#withLock('in-progress:alignment', async () => { - await this.#alignAccountsForRange({ from, to }, otherProviders); + await this.#alignAccountsForRange({ from, to }, otherProviders, { + trace: { + data: { + post: true, // Tag to identify post-alignment traces in analytics. + }, + }, + }); }); this.#log('Aligned accounts! (post)'); @@ -657,12 +747,14 @@ export class MultichainAccountWallet< if (nextGroupIndex > 0) { this.#log('Aligning accounts...'); - await this.#withLock('in-progress:alignment', async () => { - await this.#alignAccountsForRange( - { from: 0, to: nextGroupIndex - 1 }, - this.#providers, - ); - }); + const from = 0; + const to = nextGroupIndex - 1; + + await this.#withLock( + 'in-progress:alignment', + async () => + await this.#alignAccountsForRange({ from, to }, this.#providers), + ); this.#log('Aligned!'); } @@ -681,12 +773,15 @@ export class MultichainAccountWallet< if (group) { this.#log(`Aligning accounts for group "${group.id}"...`); - await this.#withLock('in-progress:alignment', async () => { - await this.#alignAccountsForRange( - { from: groupIndex, to: groupIndex }, - this.#providers, - ); - }); + await this.#withLock( + 'in-progress:alignment', + async () => + await this.#alignAccountsForRange( + { from: groupIndex, to: groupIndex }, + this.#providers, + { trace: { data: { groupIndex } } }, + ), + ); this.#log(`Aligned accounts for group "${group.id}"!`); } @@ -814,6 +909,13 @@ export class MultichainAccountWallet< await this.#alignAccountsForRange( { from: 0, to: nextGroupIndex - 1 }, this.#providers, + { + trace: { + data: { + discovery: true, // Tag to identify discovery-alignment traces in analytics. + }, + }, + }, ); } diff --git a/packages/multichain-account-service/src/analytics/perf.test.ts b/packages/multichain-account-service/src/analytics/perf.test.ts new file mode 100644 index 00000000000..b391f271ddc --- /dev/null +++ b/packages/multichain-account-service/src/analytics/perf.test.ts @@ -0,0 +1,173 @@ +import type { TraceCallback, TraceRequest } from '@metamask/controller-utils'; + +import { + isPerfEnabled, + log as perfLog, + tick, + withLocalPerfTrace, +} from './perf'; +import { now } from './timer'; +import { projectLogger } from '../logger'; + +jest.mock('./timer', () => ({ + now: jest.fn(), +})); + +jest.mock('../logger', () => ({ + projectLogger: { enabled: false }, + createModuleLogger: jest + .fn() + .mockReturnValue(Object.assign(jest.fn(), { enabled: false })), +})); + +const mockProjectLogger = projectLogger as { enabled: boolean }; +const mockPerfLog = perfLog as unknown as { enabled: boolean }; + +describe('perf', () => { + describe('isPerfEnabled', () => { + it('returns false when projectLogger is disabled', () => { + mockProjectLogger.enabled = false; + mockPerfLog.enabled = false; + expect(isPerfEnabled()).toBe(false); + }); + + it('returns true when projectLogger is enabled', () => { + mockProjectLogger.enabled = true; + expect(isPerfEnabled()).toBe(true); + mockProjectLogger.enabled = false; + }); + + it('returns true when (perf) log is enabled', () => { + mockPerfLog.enabled = true; + expect(isPerfEnabled()).toBe(true); + mockPerfLog.enabled = false; + }); + }); + + describe('tick', () => { + const request: TraceRequest = { name: 'test-operation' }; + + beforeEach(() => { + jest.mocked(now).mockReset(); + }); + + afterEach(() => { + mockProjectLogger.enabled = false; + mockPerfLog.enabled = false; + }); + + it('returns a no-op when perf is disabled', () => { + mockProjectLogger.enabled = false; + const tock = tick(request); + + expect(now).not.toHaveBeenCalled(); + expect(tock()).toBeUndefined(); + }); + + it('captures start time when perf is enabled', () => { + mockProjectLogger.enabled = true; + jest.mocked(now).mockReturnValueOnce(100); + + tick(request); + + expect(now).toHaveBeenCalledTimes(1); + }); + + it('logs elapsed time when tock is called', () => { + mockProjectLogger.enabled = true; + jest.mocked(now).mockReturnValueOnce(100).mockReturnValueOnce(250); + + const tock = tick(request); + tock(); + + expect(now).toHaveBeenCalledTimes(2); + }); + + it('includes JSON-encoded data in the log when request has data', () => { + mockProjectLogger.enabled = true; + const requestWithData: TraceRequest = { + name: 'test-operation', + data: { foo: 'bar' }, + }; + jest.mocked(now).mockReturnValueOnce(0).mockReturnValueOnce(42); + + // Should not throw regardless of data shape + const tock = tick(requestWithData); + expect(() => tock()).not.toThrow(); + }); + + it('omits context when request has no data', () => { + mockProjectLogger.enabled = true; + jest.mocked(now).mockReturnValueOnce(0).mockReturnValueOnce(10); + + const tock = tick({ name: 'no-data' }); + expect(() => tock()).not.toThrow(); + }); + }); + + describe('withLocalPerfTrace', () => { + const request: TraceRequest = { name: 'wrapped-op' }; + let mockTrace: jest.MockedFunction; + + beforeEach(() => { + mockTrace = jest.fn(); + jest.mocked(now).mockReset(); + }); + + afterEach(() => { + mockProjectLogger.enabled = false; + }); + + it('calls trace directly when perf is disabled', async () => { + mockProjectLogger.enabled = false; + mockTrace.mockResolvedValue('result'); + + const wrapped = withLocalPerfTrace(mockTrace); + const fn = jest.fn().mockReturnValue('result'); + const result = await wrapped(request, fn); + + expect(mockTrace).toHaveBeenCalledTimes(1); + expect(mockTrace).toHaveBeenCalledWith(request, fn); + expect(result).toBe('result'); + expect(now).not.toHaveBeenCalled(); + }); + + it('calls trace and measures timing when perf is enabled', async () => { + mockProjectLogger.enabled = true; + jest.mocked(now).mockReturnValueOnce(0).mockReturnValueOnce(100); + mockTrace.mockResolvedValue('result'); + + const wrapped = withLocalPerfTrace(mockTrace); + const fn = jest.fn().mockReturnValue('result'); + const result = await wrapped(request, fn); + + expect(mockTrace).toHaveBeenCalledTimes(1); + expect(mockTrace).toHaveBeenCalledWith(request, fn); + expect(result).toBe('result'); + expect(now).toHaveBeenCalledTimes(2); + }); + + it('still calls tock when trace throws', async () => { + mockProjectLogger.enabled = true; + jest.mocked(now).mockReturnValueOnce(0).mockReturnValueOnce(50); + const error = new Error('trace failed'); + mockTrace.mockRejectedValue(error); + + const wrapped = withLocalPerfTrace(mockTrace); + + await expect(wrapped(request, jest.fn())).rejects.toThrow(error); + // now called once for tick (start) and once for tock (end) + expect(now).toHaveBeenCalledTimes(2); + }); + + it('works without a fn argument', async () => { + mockProjectLogger.enabled = false; + mockTrace.mockResolvedValue(undefined); + + const wrapped = withLocalPerfTrace(mockTrace); + await wrapped(request); + + expect(mockTrace).toHaveBeenCalledWith(request, undefined); + }); + }); +}); diff --git a/packages/multichain-account-service/src/analytics/perf.ts b/packages/multichain-account-service/src/analytics/perf.ts new file mode 100644 index 00000000000..726387d0d9f --- /dev/null +++ b/packages/multichain-account-service/src/analytics/perf.ts @@ -0,0 +1,74 @@ +import type { + TraceCallback, + TraceContext, + TraceRequest, +} from '@metamask/controller-utils'; + +import { now } from './timer'; +import { createModuleLogger, projectLogger } from '../logger'; + +export const log = createModuleLogger(projectLogger, 'perf'); + +/** + * Returns true when DEBUG=metamask:multichain-account-service, DEBUG=metamask:multichain-account-service:perf + * or a matching glob is set. + * Re-uses the same enable/disable logic as the rest of the package loggers. + * + * @returns True if performance logging is enabled, false otherwise. + */ +export function isPerfEnabled(): boolean { + return projectLogger.enabled || log.enabled; +} + +/** + * Starts a local performance timer. Returns a `tock` function that, when called, + * logs the elapsed time for `label`. + * + * @example + * ```ts + * const tock = tick(request); + * await createAccounts(...); + * tock(); // logs: "${request.name}: 123.45ms" + * ``` + * + * @param request - A trace request object containing the name and optional data. + * @returns A function that, when called, logs the elapsed time since `tick` was called. + */ +export function tick(request: TraceRequest): () => void { + if (!isPerfEnabled()) { + return () => undefined; + } + + const start = now(); + return function tock(): void { + const duration = now() - start; + + const context = request.data ? ` (${JSON.stringify(request.data)})` : ''; + + log(`${request.name}${context}: ${duration.toFixed(2)}ms`); + }; +} + +/** + * Wraps a trace callback with local performance logging. + * + * @param trace - The original trace callback to wrap. + * @returns A new trace callback that logs the duration of the traced operation. + */ +export function withLocalPerfTrace(trace: TraceCallback): TraceCallback { + return async ( + request: TraceRequest, + fn?: (context?: TraceContext) => ReturnType, + ): Promise => { + if (!isPerfEnabled()) { + return await trace(request, fn); + } + + const tock = tick(request); + try { + return await trace(request, fn); + } finally { + tock(); + } + }; +} diff --git a/packages/multichain-account-service/src/analytics/timer.ts b/packages/multichain-account-service/src/analytics/timer.ts new file mode 100644 index 00000000000..c4b2093cf8b --- /dev/null +++ b/packages/multichain-account-service/src/analytics/timer.ts @@ -0,0 +1,10 @@ +/* istanbul ignore file */ // We use this file mainly to ease testing of performance logging, so we don't need to cover it with tests. + +/** + * Returns the current high-resolution timestamp in milliseconds. This is a thin wrapper around `performance.now()`. + * + * @returns The current high-resolution timestamp in milliseconds. + */ +export function now(): number { + return performance.now(); +} diff --git a/packages/multichain-account-service/src/analytics/traces.test.ts b/packages/multichain-account-service/src/analytics/traces.test.ts index 9f97d94bb0d..2ad41c271de 100644 --- a/packages/multichain-account-service/src/analytics/traces.test.ts +++ b/packages/multichain-account-service/src/analytics/traces.test.ts @@ -1,18 +1,16 @@ import type { TraceRequest } from '@metamask/controller-utils'; +import { AccountCreationType } from '@metamask/keyring-api'; +import type { CreateAccountOptions } from '@metamask/keyring-api'; -import { traceFallback } from './traces'; -import { TraceName } from '../constants/traces'; +import { + toCreateAccountsV2DataTraces, + toProviderDataTraces, + traceFallback, + TraceName, +} from './traces'; +import type { Bip44AccountProvider } from '../providers'; describe('MultichainAccountService - Traces', () => { - describe('TraceName', () => { - it('contains expected trace names', () => { - expect(TraceName).toStrictEqual({ - SnapDiscoverAccounts: 'Snap Discover Accounts', - EvmDiscoverAccounts: 'EVM Discover Accounts', - }); - }); - }); - describe('traceFallback', () => { let mockTraceRequest: TraceRequest; @@ -73,4 +71,60 @@ describe('MultichainAccountService - Traces', () => { expect(mockFn).toHaveBeenCalledTimes(1); }); }); + + describe('toProviderDataTraces', () => { + const mockProvider = (name: string): Bip44AccountProvider => + ({ getName: () => name }) as unknown as Bip44AccountProvider; + + it('returns an empty object for an empty providers list', () => { + expect(toProviderDataTraces([])).toStrictEqual({}); + }); + + it('returns a single entry for a single provider', () => { + expect(toProviderDataTraces([mockProvider('evm')])).toStrictEqual({ + evm: true, + }); + }); + + it('returns one entry per provider', () => { + expect( + toProviderDataTraces([mockProvider('evm'), mockProvider('btc')]), + ).toStrictEqual({ evm: true, btc: true }); + }); + }); + + describe('toCreateAccountsV2DataTraces', () => { + it('returns groupIndex for bip44:derive-index options', () => { + const options: CreateAccountOptions = { + type: AccountCreationType.Bip44DeriveIndex, + entropySource: 'entropy-source-id', + groupIndex: 3, + }; + + expect(toCreateAccountsV2DataTraces(options)).toStrictEqual({ + groupIndex: 3, + }); + }); + + it('returns range bounds for bip44:derive-index-range options', () => { + const options: CreateAccountOptions = { + type: AccountCreationType.Bip44DeriveIndexRange, + entropySource: 'entropy-source-id', + range: { from: 0, to: 5 }, + }; + + expect(toCreateAccountsV2DataTraces(options)).toStrictEqual({ + from: 0, + to: 5, + }); + }); + + it('returns empty options otherwise', () => { + const options: CreateAccountOptions = { + type: AccountCreationType.Custom, + }; + + expect(toCreateAccountsV2DataTraces(options)).toStrictEqual({}); + }); + }); }); diff --git a/packages/multichain-account-service/src/analytics/traces.ts b/packages/multichain-account-service/src/analytics/traces.ts index 57eee11c914..003d0005f78 100644 --- a/packages/multichain-account-service/src/analytics/traces.ts +++ b/packages/multichain-account-service/src/analytics/traces.ts @@ -3,6 +3,10 @@ import type { TraceContext, TraceRequest, } from '@metamask/controller-utils'; +import { CreateAccountOptions } from '@metamask/keyring-api'; + +// Explicit import to avoid circular dependency between `analytics` and `providers`. +import type { Bip44AccountProvider } from '../providers/BaseBip44AccountProvider'; /** * Fallback function for tracing. @@ -23,3 +27,57 @@ export const traceFallback: TraceCallback = async ( } return await Promise.resolve(fn()); }; + +/** + * Compute trace data for a list of providers. + * + * @param providers Providers to be included in the trace data. + * @returns An object mapping provider names to true, indicating their presence in the trace. + */ +export function toProviderDataTraces( + providers: Bip44AccountProvider[], +): Record { + // We cannot use complex objects within traces, so we just map provider names with true. + return providers.reduce( + (data, provider) => ({ + ...data, + [provider.getName()]: true, + }), + {}, + ); +} + +/** + * Compute trace data for `createAccounts` options. + * + * @param options The `createAccounts` options. + * @returns An object containing options data depending on its type. + */ +export function toCreateAccountsV2DataTraces( + options: CreateAccountOptions, +): Record { + if (options.type === 'bip44:derive-index') { + return { + groupIndex: options.groupIndex, + }; + } else if (options.type === 'bip44:derive-index-range') { + return { + from: options.range.from, + to: options.range.to, + }; + } + return {}; +} + +/** + * Trace names. + */ +export enum TraceName { + SnapDiscoverAccounts = 'Snap Discover Accounts', + EvmDiscoverAccounts = 'EVM Discover Accounts', + ProviderCreateAccountV1 = 'Provider Create Account (v1)', + ProviderCreateAccounts = 'Provider Create Accounts (v2 - batched)', + WalletAlignment = 'Wallet Alignment', + WalletCreateMultichainAccountGroup = 'Wallet Create Multichain Account Group', + WalletCreateMultichainAccountGroups = 'Wallet Create Multichain Account Groups', +} diff --git a/packages/multichain-account-service/src/constants/traces.ts b/packages/multichain-account-service/src/constants/traces.ts deleted file mode 100644 index 59d74c0a9da..00000000000 --- a/packages/multichain-account-service/src/constants/traces.ts +++ /dev/null @@ -1,4 +0,0 @@ -export enum TraceName { - 'SnapDiscoverAccounts' = 'Snap Discover Accounts', - 'EvmDiscoverAccounts' = 'EVM Discover Accounts', -} diff --git a/packages/multichain-account-service/src/providers/BtcAccountProvider.test.ts b/packages/multichain-account-service/src/providers/BtcAccountProvider.test.ts index 3c723637b36..8edb7197846 100644 --- a/packages/multichain-account-service/src/providers/BtcAccountProvider.test.ts +++ b/packages/multichain-account-service/src/providers/BtcAccountProvider.test.ts @@ -16,7 +16,7 @@ import { BtcAccountProvider, } from './BtcAccountProvider'; import type { SnapAccountProviderConfig } from './SnapAccountProvider'; -import { TraceName } from '../constants/traces'; +import { TraceName } from '../analytics/traces'; import { getMultichainAccountServiceMessenger, getRootMessenger, @@ -173,6 +173,7 @@ function setup({ createAccount: jest.Mock; createAccounts: jest.Mock; }; + trace: jest.Mock; }; } { const keyring = new MockBtcKeyring(accounts); @@ -221,8 +222,16 @@ function setup({ }), ); + const mockTrace = jest.fn().mockImplementation(async (_request, fn) => { + return await fn(); + }); + const multichainMessenger = getMultichainAccountServiceMessenger(messenger); - const btcProvider = new MockBtcAccountProvider(multichainMessenger, config); + const btcProvider = new MockBtcAccountProvider( + multichainMessenger, + config, + mockTrace, + ); const accountIds = accounts.map((account) => account.id); btcProvider.init(accountIds); const provider = new AccountProviderWrapper(multichainMessenger, btcProvider); @@ -237,6 +246,7 @@ function setup({ createAccount: keyring.createAccount as jest.Mock, createAccounts: keyring.createAccounts as jest.Mock, }, + trace: mockTrace, }, }; } @@ -653,118 +663,74 @@ describe('BtcAccountProvider', () => { describe('trace functionality', () => { it('calls trace callback during account discovery', async () => { - const mockTrace = jest.fn().mockImplementation(async (request, fn) => { - expect(request.name).toBe(TraceName.SnapDiscoverAccounts); - expect(request.data).toStrictEqual({ - provider: BTC_ACCOUNT_PROVIDER_NAME, - }); - return await fn(); - }); - - const { messenger, mocks } = setup({ + const { provider, mocks } = setup({ accounts: [], }); // Simulate one discovered account at the requested index. mocks.handleRequest.mockReturnValue([MOCK_BTC_P2TR_DISCOVERED_ACCOUNT_1]); - const multichainMessenger = - getMultichainAccountServiceMessenger(messenger); - const btcProvider = new MockBtcAccountProvider( - multichainMessenger, - undefined, - mockTrace, - ); - const provider = new AccountProviderWrapper( - multichainMessenger, - btcProvider, - ); - const discovered = await provider.discoverAccounts({ entropySource: MOCK_HD_KEYRING_1.metadata.id, groupIndex: 0, }); expect(discovered).toHaveLength(1); - expect(mockTrace).toHaveBeenCalledTimes(1); + expect(mocks.trace).toHaveBeenCalledWith( + expect.objectContaining({ + name: TraceName.SnapDiscoverAccounts, + data: { provider: BTC_ACCOUNT_PROVIDER_NAME }, + }), + expect.any(Function), + ); }); it('uses fallback trace when no trace callback is provided', async () => { - const { provider, mocks } = setup({ - accounts: [], - }); + const { messenger, mocks } = setup({ accounts: [] }); mocks.handleRequest.mockReturnValue([MOCK_BTC_P2TR_DISCOVERED_ACCOUNT_1]); + const multichainMessenger = + getMultichainAccountServiceMessenger(messenger); + // No trace callback (defaults to `traceFallback`). + const btcProvider = new MockBtcAccountProvider(multichainMessenger); + const provider = new AccountProviderWrapper( + multichainMessenger, + btcProvider, + ); + const discovered = await provider.discoverAccounts({ entropySource: MOCK_HD_KEYRING_1.metadata.id, groupIndex: 0, }); expect(discovered).toHaveLength(1); - // No trace errors, fallback trace should be used silently }); it('trace callback is called even when discovery returns empty results', async () => { - const mockTrace = jest.fn().mockImplementation(async (request, fn) => { - expect(request.name).toBe(TraceName.SnapDiscoverAccounts); - expect(request.data).toStrictEqual({ - provider: BTC_ACCOUNT_PROVIDER_NAME, - }); - return await fn(); - }); - - const { messenger, mocks } = setup({ + const { provider, mocks } = setup({ accounts: [], }); mocks.handleRequest.mockReturnValue([]); - const multichainMessenger = - getMultichainAccountServiceMessenger(messenger); - const btcProvider = new MockBtcAccountProvider( - multichainMessenger, - undefined, - mockTrace, - ); - const provider = new AccountProviderWrapper( - multichainMessenger, - btcProvider, - ); - const discovered = await provider.discoverAccounts({ entropySource: MOCK_HD_KEYRING_1.metadata.id, groupIndex: 0, }); expect(discovered).toStrictEqual([]); - expect(mockTrace).toHaveBeenCalledTimes(1); + expect(mocks.trace).toHaveBeenCalledTimes(1); }); it('trace callback receives error when discovery fails', async () => { const mockError = new Error('Discovery failed'); - const mockTrace = jest.fn().mockImplementation(async (_request, fn) => { - return await fn(); - }); - - const { messenger, mocks } = setup({ + const { provider, mocks } = setup({ accounts: [], }); mocks.handleRequest.mockRejectedValue(mockError); - const multichainMessenger = - getMultichainAccountServiceMessenger(messenger); - const btcProvider = new MockBtcAccountProvider( - multichainMessenger, - undefined, - mockTrace, - ); - const provider = new AccountProviderWrapper( - multichainMessenger, - btcProvider, - ); - await expect( provider.discoverAccounts({ entropySource: MOCK_HD_KEYRING_1.metadata.id, @@ -772,7 +738,7 @@ describe('BtcAccountProvider', () => { }), ).rejects.toThrow(mockError); - expect(mockTrace).toHaveBeenCalledTimes(1); + expect(mocks.trace).toHaveBeenCalledTimes(1); }); }); diff --git a/packages/multichain-account-service/src/providers/BtcAccountProvider.ts b/packages/multichain-account-service/src/providers/BtcAccountProvider.ts index 0c6f1bdb59b..b8d1b95506e 100644 --- a/packages/multichain-account-service/src/providers/BtcAccountProvider.ts +++ b/packages/multichain-account-service/src/providers/BtcAccountProvider.ts @@ -20,7 +20,7 @@ import type { } from './SnapAccountProvider'; import { withRetry, withTimeout } from './utils'; import { traceFallback } from '../analytics'; -import { TraceName } from '../constants/traces'; +import { TraceName } from '../analytics/traces'; import type { MultichainAccountServiceMessenger } from '../types'; export type BtcAccountProviderConfig = SnapAccountProviderConfig; @@ -114,11 +114,12 @@ export class BtcAccountProvider extends SnapAccountProvider { const discoveredAccounts = await withRetry( () => withTimeout( - client.discoverAccounts( - [BtcScope.Mainnet], - entropySource, - groupIndex, - ), + () => + client.discoverAccounts( + [BtcScope.Mainnet], + entropySource, + groupIndex, + ), this.config.discovery.timeoutMs, ), { diff --git a/packages/multichain-account-service/src/providers/EvmAccountProvider.test.ts b/packages/multichain-account-service/src/providers/EvmAccountProvider.test.ts index bd347c5ffe6..5ebaec2599d 100644 --- a/packages/multichain-account-service/src/providers/EvmAccountProvider.test.ts +++ b/packages/multichain-account-service/src/providers/EvmAccountProvider.test.ts @@ -21,7 +21,7 @@ import { EvmAccountProviderConfig, } from './EvmAccountProvider'; import { TimeoutError } from './utils'; -import { TraceName } from '../constants/traces'; +import { TraceName } from '../analytics/traces'; import { getMultichainAccountServiceMessenger, getRootMessenger, diff --git a/packages/multichain-account-service/src/providers/EvmAccountProvider.ts b/packages/multichain-account-service/src/providers/EvmAccountProvider.ts index c247ae812d9..b0a68945fb5 100644 --- a/packages/multichain-account-service/src/providers/EvmAccountProvider.ts +++ b/packages/multichain-account-service/src/providers/EvmAccountProvider.ts @@ -32,7 +32,7 @@ import { } from './BaseBip44AccountProvider'; import { withRetry, withTimeout } from './utils'; import { traceFallback } from '../analytics'; -import { TraceName } from '../constants/traces'; +import { TraceName } from '../analytics/traces'; import { projectLogger as log, WARNING_PREFIX } from '../logger'; import type { MultichainAccountServiceMessenger } from '../types'; @@ -302,10 +302,11 @@ export class EvmAccountProvider extends BaseBip44AccountProvider { const response = await withRetry( () => withTimeout( - provider.request({ - method, - params: [address, 'latest'], - }), + () => + provider.request({ + method, + params: [address, 'latest'], + }), this.#config.discovery.timeoutMs, ), { diff --git a/packages/multichain-account-service/src/providers/SnapAccountProvider.ts b/packages/multichain-account-service/src/providers/SnapAccountProvider.ts index 87b0fc80fc7..55dfeecff10 100644 --- a/packages/multichain-account-service/src/providers/SnapAccountProvider.ts +++ b/packages/multichain-account-service/src/providers/SnapAccountProvider.ts @@ -23,7 +23,11 @@ import { Semaphore } from 'async-mutex'; import { BaseBip44AccountProvider } from './BaseBip44AccountProvider'; import { withTimeout } from './utils'; -import { traceFallback } from '../analytics'; +import { + toCreateAccountsV2DataTraces, + traceFallback, + TraceName, +} from '../analytics'; import { reportError } from '../errors'; import { projectLogger as log, WARNING_PREFIX } from '../logger'; import type { MultichainAccountServiceMessenger } from '../types'; @@ -342,13 +346,48 @@ export abstract class SnapAccountProvider extends BaseBip44AccountProvider { const batched = this.config.createAccounts.batched ?? false; const { entropySource } = options; + const createAccountV1 = async ( + groupIndex: number, + ): Promise => + await withTimeout( + () => + this.trace( + { + name: TraceName.ProviderCreateAccountV1, + data: { + provider: this.getName(), + groupIndex, + }, + }, + () => + this.createAccountV1(keyring, { entropySource, groupIndex }), + ), + this.config.createAccounts.timeoutMs, + ); + const createAccountsV2 = async ( + optionsV2: + | CreateAccountBip44DeriveIndexOptions + | CreateAccountBip44DeriveIndexRangeOptions, + ): Promise => + await withTimeout( + () => + this.trace( + { + name: TraceName.ProviderCreateAccounts, + data: { + provider: this.getName(), + ...toCreateAccountsV2DataTraces(optionsV2), + }, + }, + () => keyring.createAccounts(optionsV2), + ), + this.config.createAccounts.timeoutMs, + ); + if (options.type === `${AccountCreationType.Bip44DeriveIndexRange}`) { if (batched) { // Batch account creations. - snapAccounts = await withTimeout( - keyring.createAccounts(options), - this.config.createAccounts.timeoutMs, - ); + snapAccounts = await createAccountsV2(options); } else { const { range } = options; @@ -358,10 +397,7 @@ export abstract class SnapAccountProvider extends BaseBip44AccountProvider { groupIndex <= range.to; groupIndex++ ) { - const snapAccount = await withTimeout( - this.createAccountV1(keyring, { entropySource, groupIndex }), - this.config.createAccounts.timeoutMs, - ); + const snapAccount = await createAccountV1(groupIndex); snapAccounts.push(snapAccount); } @@ -372,18 +408,12 @@ export abstract class SnapAccountProvider extends BaseBip44AccountProvider { } else { if (batched) { // Create account using new v2-like flow (no async flow + no Snap keyring events). - snapAccounts = await withTimeout( - keyring.createAccounts(options), - this.config.createAccounts.timeoutMs, - ); + snapAccounts = await createAccountsV2(options); } else { const { groupIndex } = options; // Create account using the existing v1 flow. - const snapAccount = await withTimeout( - this.createAccountV1(keyring, { entropySource, groupIndex }), - this.config.createAccounts.timeoutMs, - ); + const snapAccount = await createAccountV1(groupIndex); snapAccounts = [snapAccount]; } diff --git a/packages/multichain-account-service/src/providers/SolAccountProvider.test.ts b/packages/multichain-account-service/src/providers/SolAccountProvider.test.ts index 0fc981b77b5..7445ccda062 100644 --- a/packages/multichain-account-service/src/providers/SolAccountProvider.test.ts +++ b/packages/multichain-account-service/src/providers/SolAccountProvider.test.ts @@ -16,7 +16,7 @@ import { SOL_ACCOUNT_PROVIDER_NAME, SolAccountProvider, } from './SolAccountProvider'; -import { TraceName } from '../constants/traces'; +import { TraceName } from '../analytics/traces'; import { getMultichainAccountServiceMessenger, getRootMessenger, @@ -191,11 +191,7 @@ function setup({ keyring.accounts.find((account) => account.address === address), ); - const mockTrace = jest.fn().mockImplementation(async (request, fn) => { - expect(request.name).toBe(TraceName.SnapDiscoverAccounts); - expect(request.data).toStrictEqual({ - provider: SOL_ACCOUNT_PROVIDER_NAME, - }); + const mockTrace = jest.fn().mockImplementation(async (_request, fn) => { return await fn(); }); @@ -673,16 +669,29 @@ describe('SolAccountProvider', () => { }); expect(discovered).toHaveLength(1); - expect(mocks.trace).toHaveBeenCalledTimes(1); + expect(mocks.trace).toHaveBeenCalledWith( + expect.objectContaining({ + name: TraceName.SnapDiscoverAccounts, + data: { provider: SOL_ACCOUNT_PROVIDER_NAME }, + }), + expect.any(Function), + ); }); it('uses fallback trace when no trace callback is provided', async () => { - const { provider, mocks } = setup({ - accounts: [], - }); + const { messenger, mocks } = setup({ accounts: [] }); mocks.handleRequest.mockReturnValue([MOCK_SOL_DISCOVERED_ACCOUNT_1]); + const multichainMessenger = + getMultichainAccountServiceMessenger(messenger); + // No trace callback (defaults to `traceFallback`). + const solProvider = new MockSolAccountProvider(multichainMessenger); + const provider = new AccountProviderWrapper( + multichainMessenger, + solProvider, + ); + const discovered = await provider.discoverAccounts({ entropySource: MOCK_HD_KEYRING_1.metadata.id, groupIndex: 0, diff --git a/packages/multichain-account-service/src/providers/SolAccountProvider.ts b/packages/multichain-account-service/src/providers/SolAccountProvider.ts index 5c9cc2f9502..b9bad3cc5cc 100644 --- a/packages/multichain-account-service/src/providers/SolAccountProvider.ts +++ b/packages/multichain-account-service/src/providers/SolAccountProvider.ts @@ -23,7 +23,7 @@ import type { } from './SnapAccountProvider'; import { withRetry, withTimeout } from './utils'; import { traceFallback } from '../analytics'; -import { TraceName } from '../constants/traces'; +import { TraceName } from '../analytics/traces'; import type { MultichainAccountServiceMessenger } from '../types'; export type SolAccountProviderConfig = SnapAccountProviderConfig; @@ -83,7 +83,7 @@ export class SolAccountProvider extends SnapAccountProvider { return `m/44'/501'/${groupIndex}'/0'`; } - protected override createAccountV1( + protected override async createAccountV1( keyring: RestrictedSnapKeyring, { entropySource, @@ -139,11 +139,12 @@ export class SolAccountProvider extends SnapAccountProvider { const discoveredAccounts = await withRetry( () => withTimeout( - client.discoverAccounts( - [SolScope.Mainnet], - entropySource, - groupIndex, - ), + () => + client.discoverAccounts( + [SolScope.Mainnet], + entropySource, + groupIndex, + ), this.config.discovery.timeoutMs, ), { diff --git a/packages/multichain-account-service/src/providers/TrxAccountProvider.test.ts b/packages/multichain-account-service/src/providers/TrxAccountProvider.test.ts index f76cb4b7bc4..832b843ceb0 100644 --- a/packages/multichain-account-service/src/providers/TrxAccountProvider.test.ts +++ b/packages/multichain-account-service/src/providers/TrxAccountProvider.test.ts @@ -16,7 +16,7 @@ import { TRX_ACCOUNT_PROVIDER_NAME, TrxAccountProvider, } from './TrxAccountProvider'; -import { TraceName } from '../constants/traces'; +import { TraceName } from '../analytics/traces'; import { getMultichainAccountServiceMessenger, getRootMessenger, @@ -147,6 +147,7 @@ function setup({ createAccounts: jest.Mock; discoverAccounts: jest.Mock; }; + trace: jest.Mock; }; } { const keyring = new MockTronKeyring(accounts); @@ -201,8 +202,16 @@ function setup({ }), ); + const mockTrace = jest.fn().mockImplementation(async (_request, fn) => { + return await fn(); + }); + const multichainMessenger = getMultichainAccountServiceMessenger(messenger); - const trxProvider = new MockTrxAccountProvider(multichainMessenger, config); + const trxProvider = new MockTrxAccountProvider( + multichainMessenger, + config, + mockTrace, + ); const accountIds = accounts.map((account) => account.id); trxProvider.init(accountIds); const provider = new AccountProviderWrapper(multichainMessenger, trxProvider); @@ -218,6 +227,7 @@ function setup({ createAccounts: keyring.createAccounts as jest.Mock, discoverAccounts: keyring.discoverAccounts, }, + trace: mockTrace, }, }; } @@ -638,15 +648,7 @@ describe('TrxAccountProvider', () => { describe('trace functionality', () => { it('calls trace callback during account discovery', async () => { - const mockTrace = jest.fn().mockImplementation(async (request, fn) => { - expect(request.name).toBe(TraceName.SnapDiscoverAccounts); - expect(request.data).toStrictEqual({ - provider: TRX_ACCOUNT_PROVIDER_NAME, - }); - return await fn(); - }); - - const { messenger, mocks } = setup({ + const { provider, mocks } = setup({ accounts: [], }); @@ -655,105 +657,69 @@ describe('TrxAccountProvider', () => { MOCK_TRX_DISCOVERED_ACCOUNT_1, ]); - const multichainMessenger = - getMultichainAccountServiceMessenger(messenger); - const trxProvider = new MockTrxAccountProvider( - multichainMessenger, - undefined, - mockTrace, - ); - const provider = new AccountProviderWrapper( - multichainMessenger, - trxProvider, - ); - const discovered = await provider.discoverAccounts({ entropySource: MOCK_HD_KEYRING_1.metadata.id, groupIndex: 0, }); expect(discovered).toHaveLength(1); - expect(mockTrace).toHaveBeenCalledTimes(1); + expect(mocks.trace).toHaveBeenCalledWith( + expect.objectContaining({ + name: TraceName.SnapDiscoverAccounts, + data: { provider: TRX_ACCOUNT_PROVIDER_NAME }, + }), + expect.any(Function), + ); }); it('uses fallback trace when no trace callback is provided', async () => { - const { provider, mocks } = setup({ - accounts: [], - }); + const { messenger, mocks } = setup({ accounts: [] }); mocks.keyring.discoverAccounts.mockResolvedValue([ MOCK_TRX_DISCOVERED_ACCOUNT_1, ]); + const multichainMessenger = + getMultichainAccountServiceMessenger(messenger); + // No trace callback (defaults to `traceFallback`). + const trxProvider = new MockTrxAccountProvider(multichainMessenger); + const provider = new AccountProviderWrapper( + multichainMessenger, + trxProvider, + ); + const discovered = await provider.discoverAccounts({ entropySource: MOCK_HD_KEYRING_1.metadata.id, groupIndex: 0, }); expect(discovered).toHaveLength(1); - // No trace errors, fallback trace should be used silently }); it('trace callback is called even when discovery returns empty results', async () => { - const mockTrace = jest.fn().mockImplementation(async (request, fn) => { - expect(request.name).toBe(TraceName.SnapDiscoverAccounts); - expect(request.data).toStrictEqual({ - provider: TRX_ACCOUNT_PROVIDER_NAME, - }); - return await fn(); - }); - - const { messenger, mocks } = setup({ + const { provider, mocks } = setup({ accounts: [], }); mocks.keyring.discoverAccounts.mockResolvedValue([]); - const multichainMessenger = - getMultichainAccountServiceMessenger(messenger); - const trxProvider = new MockTrxAccountProvider( - multichainMessenger, - undefined, - mockTrace, - ); - const provider = new AccountProviderWrapper( - multichainMessenger, - trxProvider, - ); - const discovered = await provider.discoverAccounts({ entropySource: MOCK_HD_KEYRING_1.metadata.id, groupIndex: 0, }); expect(discovered).toStrictEqual([]); - expect(mockTrace).toHaveBeenCalledTimes(1); + expect(mocks.trace).toHaveBeenCalledTimes(1); }); it('trace callback receives error when discovery fails', async () => { const mockError = new Error('Discovery failed'); - const mockTrace = jest.fn().mockImplementation(async (_request, fn) => { - return await fn(); - }); - - const { messenger, mocks } = setup({ + const { provider, mocks } = setup({ accounts: [], }); mocks.keyring.discoverAccounts.mockRejectedValue(mockError); - const multichainMessenger = - getMultichainAccountServiceMessenger(messenger); - const trxProvider = new MockTrxAccountProvider( - multichainMessenger, - undefined, - mockTrace, - ); - const provider = new AccountProviderWrapper( - multichainMessenger, - trxProvider, - ); - await expect( provider.discoverAccounts({ entropySource: MOCK_HD_KEYRING_1.metadata.id, @@ -761,7 +727,7 @@ describe('TrxAccountProvider', () => { }), ).rejects.toThrow(mockError); - expect(mockTrace).toHaveBeenCalledTimes(1); + expect(mocks.trace).toHaveBeenCalledTimes(1); }); }); diff --git a/packages/multichain-account-service/src/providers/TrxAccountProvider.ts b/packages/multichain-account-service/src/providers/TrxAccountProvider.ts index 09bb364ccf9..d95776266a0 100644 --- a/packages/multichain-account-service/src/providers/TrxAccountProvider.ts +++ b/packages/multichain-account-service/src/providers/TrxAccountProvider.ts @@ -21,7 +21,7 @@ import type { } from './SnapAccountProvider'; import { withRetry, withTimeout } from './utils'; import { traceFallback } from '../analytics'; -import { TraceName } from '../constants/traces'; +import { TraceName } from '../analytics/traces'; import type { MultichainAccountServiceMessenger } from '../types'; export type TrxAccountProviderConfig = SnapAccountProviderConfig; @@ -115,11 +115,12 @@ export class TrxAccountProvider extends SnapAccountProvider { const discoveredAccounts = await withRetry( () => withTimeout( - client.discoverAccounts( - [TrxScope.Mainnet], - entropySource, - groupIndex, - ), + () => + client.discoverAccounts( + [TrxScope.Mainnet], + entropySource, + groupIndex, + ), this.config.discovery.timeoutMs, ), { diff --git a/packages/multichain-account-service/src/providers/utils.test.ts b/packages/multichain-account-service/src/providers/utils.test.ts index cea24ca7854..4c285cb6fc6 100644 --- a/packages/multichain-account-service/src/providers/utils.test.ts +++ b/packages/multichain-account-service/src/providers/utils.test.ts @@ -25,11 +25,12 @@ describe('utils', () => { it('throws if the RPC request times out', async () => { await expect( withTimeout( - new Promise((resolve) => { - setTimeout(() => { - resolve(null); - }, 600); - }), + () => + new Promise((resolve) => { + setTimeout(() => { + resolve(null); + }, 600); + }), ), ).rejects.toThrow(TimeoutError); }); @@ -37,11 +38,12 @@ describe('utils', () => { it('includes the timeout duration in the error message', async () => { await expect( withTimeout( - new Promise((resolve) => { - setTimeout(() => { - resolve(null); - }, 600); - }), + () => + new Promise((resolve) => { + setTimeout(() => { + resolve(null); + }, 600); + }), 500, ), ).rejects.toThrow('Timed out after: 500ms'); diff --git a/packages/multichain-account-service/src/providers/utils.ts b/packages/multichain-account-service/src/providers/utils.ts index 6ead4026886..c1da4dbff7b 100644 --- a/packages/multichain-account-service/src/providers/utils.ts +++ b/packages/multichain-account-service/src/providers/utils.ts @@ -54,18 +54,18 @@ export async function withRetry( /** * Execute a promise with a timeout. * - * @param promise - The promise to execute. + * @param fn - A callback that returns the promise to execute. * @param timeoutMs - The timeout in milliseconds. * @returns The result of the promise. */ export async function withTimeout( - promise: Promise, + fn: () => Promise, timeoutMs: number = 500, ): Promise { let timer; try { return await Promise.race([ - promise, + fn(), new Promise((_resolve, reject) => { timer = setTimeout( () => reject(new TimeoutError(`Timed out after: ${timeoutMs}ms`)), diff --git a/yarn.lock b/yarn.lock index 529185d3373..146e01873c3 100644 --- a/yarn.lock +++ b/yarn.lock @@ -4359,6 +4359,7 @@ __metadata: "@metamask/accounts-controller": "npm:^37.0.0" "@metamask/auto-changelog": "npm:^3.4.4" "@metamask/base-controller": "npm:^9.0.0" + "@metamask/controller-utils": "npm:^11.19.0" "@metamask/eth-hd-keyring": "npm:^13.0.0" "@metamask/eth-snap-keyring": "npm:^19.0.0" "@metamask/key-tree": "npm:^10.1.1"