diff --git a/packages/keyring-controller/CHANGELOG.md b/packages/keyring-controller/CHANGELOG.md index 81d110cb476..f94564dc3fa 100644 --- a/packages/keyring-controller/CHANGELOG.md +++ b/packages/keyring-controller/CHANGELOG.md @@ -9,6 +9,8 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ### Added +- Add debug timing logs for controller and vault mutex requests, acquisition, release, and completion, including wait, hold, and total durations; atomic keyring operations are timed separately from their controller-side commit windows ([#11267](https://github.com/MetaMask/core/pull/11267)) + - Include `keyring: { type, id, kind }`, identifying the underlying keyring and access kind (`v1`, `v2`, or `commit`), in keyring-scoped release/completion logs and atomic operation logs once the entry is selected. - Add support for Node.js 26 ([#10981](https://github.com/MetaMask/core/pull/10981)) - Add atomic keyring builder support: a `KeyringBuilder` can now declare `atomic: true` to receive a `KeyringBuilderContext`, whose `update` callback commits state mutations on the built keyring's behalf — the controller lock is held only for that short commit window, while long-running keyring operations run entirely outside it ([#TODO](https://github.com/MetaMask/core/pull/TODO)) - The declaration is enforced at the construction choke point: a builder declaring `atomic: true` whose result is not an `AtomicKeyring` (from `@metamask/keyring-sdk`) throws an explicit error. diff --git a/packages/keyring-controller/README.md b/packages/keyring-controller/README.md index d82d11f5c1a..928d03193a4 100644 --- a/packages/keyring-controller/README.md +++ b/packages/keyring-controller/README.md @@ -10,6 +10,39 @@ or `npm install @metamask/keyring-controller` +## Lock timing diagnostics + +Enable `DEBUG=metamask:keyring-controller*` to see lock timing +logs (using the same project/module logger setup as other controllers). + +Each controller or vault mutex acquisition logs `Lock requested`, `Lock acquired`, +`Lock released`, and `Locked operation finished`, correlated by `id` and labeled +with the lock and operation names. Durations use a monotonic clock, in milliseconds: + +- `waitMs`: time spent waiting to acquire the mutex. +- `holdMs`: time the mutex was actually held, including transaction setup, + persistence, and any rollback. +- `totalMs`: time from requesting the mutex until the operation finishes. +- `success`: whether the operation completed without throwing. + +For `withKeyring` and `withKeyringV2`, release/completion logs also include +`keyring: { type, id, kind }`, with kind `v1` or `v2`. The kind describes +the access path, while the type always identifies the underlying keyring, not +its V2 adapter. Metadata is added after selection inside the lock, so request +and acquisition logs do not include it. Wallet-wide operations omit these fields. + +Atomic keyrings run their operations outside the controller mutex. Separate +start/finish logs report their full `durationMs`, while `atomicUpdate` lock logs +measure only their controller-side commit windows. The keyring's own internal +lock wait/hold times are not observable by this controller. Atomic operation +logs include the selected keyring metadata; `atomicUpdate` release/completion +logs use `keyring.kind: 'commit'`, since commits can originate internally without +a V1/V2 access path. Rejected updates from detached keyrings omit metadata +because the registered entry no longer exists. Unsafe read-only +operations do not acquire a mutex and do not produce lock timing logs. + +Logs omit operation arguments, results, and errors to avoid exposing secrets. + ## Contributing This package is part of a monorepo. Instructions for contributing can be found in the [monorepo README](https://github.com/MetaMask/core#readme). diff --git a/packages/keyring-controller/src/KeyringController.test.ts b/packages/keyring-controller/src/KeyringController.test.ts index 9831877b61f..958eecc4f9f 100644 --- a/packages/keyring-controller/src/KeyringController.test.ts +++ b/packages/keyring-controller/src/KeyringController.test.ts @@ -66,6 +66,9 @@ import { isCustodyKeyring, keyringBuilderFactory, } from './KeyringController.js'; +import { lockLogger, projectLogger } from './logger.js'; + +vi.mock('./logger.js', () => ({ lockLogger: vi.fn(), projectLogger: vi.fn() })); type AllKeyringControllerActions = MessengerActions; @@ -4133,6 +4136,19 @@ describe('KeyringController', () => { 'Oops', ); + expect(lockLogger).toHaveBeenLastCalledWith( + 'Locked operation finished', + expect.objectContaining({ + operation: 'withKeyring', + keyring: { + type: KeyringTypes.hd, + kind: 'v1', + id: initialState.keyrings[0].metadata.id, + }, + success: false, + }), + ); + expect(controller.state.keyrings[0].accounts).toHaveLength(1); expect(await controller.getAccounts()).toStrictEqual( initialState.keyrings[0].accounts, @@ -5147,6 +5163,17 @@ describe('KeyringController', () => { metadata: expect.objectContaining({ id: expect.any(String) }), }), ); + expect(lockLogger).toHaveBeenCalledWith( + 'Locked operation finished', + expect.objectContaining({ + operation: 'withKeyringV2', + keyring: { + type: KeyringTypes.hd, + kind: 'v2', + id: controller.state.keyrings[0].metadata.id, + }, + }), + ); }); }); @@ -8107,6 +8134,8 @@ describe('KeyringController atomic keyring support', () => { { keyringBuilders: [buildFakeAtomicKeyringBuilder(remote)] }, async ({ controller }) => { await controller.addNewKeyring(ATOMIC_TEST_KEYRING_TYPE); + vi.mocked(lockLogger).mockClear(); + vi.mocked(projectLogger).mockClear(); const fake = controller.getKeyringsByType( ATOMIC_TEST_KEYRING_TYPE, )[0] as FakeAtomicKeyring; @@ -8136,10 +8165,70 @@ describe('KeyringController atomic keyring support', () => { expect(fake.state.status).toBe('uninitialized'); }); + expect(projectLogger).toHaveBeenCalledWith( + 'Atomic keyring operation started (outside controller lock)', + { + id: expect.any(Number), + operation: 'withKeyring', + keyring: { + type: ATOMIC_TEST_KEYRING_TYPE, + kind: 'v1', + id: controller.state.keyrings.find( + ({ type }) => type === ATOMIC_TEST_KEYRING_TYPE, + )?.metadata.id, + }, + }, + ); + expect(projectLogger).toHaveBeenCalledTimes(1); + expect(lockLogger).toHaveBeenCalledWith( + 'Locked operation finished', + expect.objectContaining({ + operation: 'withKeyring', + success: true, + keyring: { + type: ATOMIC_TEST_KEYRING_TYPE, + kind: 'v1', + id: expect.any(String), + }, + }), + ); + expect(lockLogger).not.toHaveBeenCalledWith( + 'Lock requested', + expect.objectContaining({ operation: 'atomicUpdate' }), + ); + ceremonyGate.resolve(); await operation; expect(fake.state.status).toBe('ready'); + expect(lockLogger).toHaveBeenCalledWith( + 'Locked operation finished', + expect.objectContaining({ + operation: 'atomicUpdate', + keyring: { + type: ATOMIC_TEST_KEYRING_TYPE, + kind: 'commit', + id: expect.any(String), + }, + }), + ); + expect(projectLogger).toHaveBeenLastCalledWith( + 'Atomic keyring operation finished (outside controller lock)', + expect.objectContaining({ + operation: 'withKeyring', + durationMs: expect.any(Number), + success: true, + }), + ); + expect( + vi + .mocked(lockLogger) + .mock.calls.filter(([message]) => message === 'Lock acquired') + .filter( + ([, details]) => + (details as { operation: string }).operation === 'atomicUpdate', + ), + ).toHaveLength(2); }, ); }); @@ -8170,6 +8259,14 @@ describe('KeyringController atomic keyring support', () => { ), ).rejects.toThrow('activation failed'); + expect(projectLogger).toHaveBeenLastCalledWith( + 'Atomic keyring operation finished (outside controller lock)', + expect.objectContaining({ + success: false, + durationMs: expect.any(Number), + }), + ); + // The staged update survived the operation error: there is no // rollback for atomic keyrings. expect(fake.state.status).toBe('staged'); diff --git a/packages/keyring-controller/src/KeyringController.ts b/packages/keyring-controller/src/KeyringController.ts index 133181481c2..2dd7f14f72c 100644 --- a/packages/keyring-controller/src/KeyringController.ts +++ b/packages/keyring-controller/src/KeyringController.ts @@ -38,7 +38,6 @@ import { remove0x, } from '@metamask/utils'; import { Mutex } from 'async-mutex'; -import type { MutexInterface } from 'async-mutex'; import * as ethereumjsWallet from 'ethereumjs-wallet'; import type { Patch } from 'immer'; // When generating a ULID within the same millisecond, monotonicFactory provides some guarantees regarding sort order. @@ -47,6 +46,7 @@ import { ulid } from 'ulid'; import { KeyringControllerErrorMessage } from './constants.js'; import { KeyringControllerError } from './errors.js'; import type { KeyringControllerMethodActions } from './KeyringController-method-action-types.js'; +import { projectLogger as log } from './logger.js'; import type { Eip7702AuthorizationParams, Credentials, @@ -60,6 +60,8 @@ import type { VaultSession, WalletTransactionScope, } from './VaultTransaction.js'; +import { withLock } from './withLock.js'; +import type { LogContext, MutuallyExclusiveCallback } from './withLock.js'; /** * `ethereumjs-wallet` is CommonJS, and Node cannot reliably detect its named @@ -619,18 +621,6 @@ export type KeyringV2Builder = { type: string; }; -/** - * A function executed within a mutually exclusive lock, with a mutex - * releaser in its option bag. - * - * @param releaseLock - A function to release the lock. - */ -type MutuallyExclusiveCallback = ({ - releaseLock, -}: { - releaseLock: MutexInterface.Releaser; -}) => Promise; - /** * Get builder function for `Keyring` * @@ -859,6 +849,8 @@ export class KeyringController< readonly #vaultOperationMutex = new Mutex(); + #nextAtomicOperationId = 0; + readonly #keyringBuilders: KeyringBuilder[]; readonly #keyringV2Builders: KeyringV2Builder[]; @@ -964,6 +956,7 @@ export class KeyringController< // TODO: Migrate this to `#withKeyringOrRollback` so that only the // operated keyring is snapshotted and diffed. return this.#withTransaction( + 'addNewAccount', () => this.#beginWalletTransaction(persistWhenSessionChanged), async () => { const primaryKeyring = this.getKeyringsByType('HD Key Tree')[0] as @@ -1018,6 +1011,7 @@ export class KeyringController< // TODO: Migrate this to `#withKeyringOrRollback` so that only the // operated keyring is snapshotted and diffed. return this.#withTransaction( + 'addNewAccountForKeyring', () => this.#beginWalletTransaction(persistWhenSessionChanged), async () => { const oldAccounts = await this.#getAccountsFromKeyrings(); @@ -1059,6 +1053,7 @@ export class KeyringController< seed: Uint8Array, ): Promise { return this.#withTransaction( + 'createNewVaultAndRestore', () => this.#beginWalletTransaction(persistWhenSessionChanged), async (transaction) => { assertIsValidPassword(password); @@ -1085,6 +1080,7 @@ export class KeyringController< */ async createNewVaultAndKeychain(password: string): Promise { return this.#withTransaction( + 'createNewVaultAndKeychain', () => this.#beginWalletTransaction(persistWhenSessionChanged), async (transaction) => { const accounts = await this.#getAccountsFromKeyrings(); @@ -1115,6 +1111,7 @@ export class KeyringController< // operated keyring is snapshotted and diffed. return this.#getKeyringMetadata( await this.#withTransaction( + 'addNewKeyring', () => this.#beginWalletTransaction(persistWhenSessionChanged), async () => this.#newKeyring(type, opts), ), @@ -1406,6 +1403,7 @@ export class KeyringController< */ async persistAllKeyrings(): Promise { return this.#withTransaction( + 'persistAllKeyrings', // The deprecated method's contract is an unconditional vault write. () => this.#beginWalletTransaction(() => true), async () => { @@ -1435,6 +1433,7 @@ export class KeyringController< // TODO: Migrate this to `#withKeyringOrRollback` so that only the // operated keyring is snapshotted and diffed. return this.#withTransaction( + 'importAccountWithStrategy', () => this.#beginWalletTransaction(persistWhenSessionChanged), async () => { let privateKey; @@ -1507,6 +1506,7 @@ export class KeyringController< // TODO: Migrate this to `#withKeyringOrRollback` so that only the // operated keyring is snapshotted and diffed. await this.#withTransaction( + 'removeAccount', () => this.#beginWalletTransaction(persistWhenSessionChanged), async (transaction) => { const keyringIndex = await this.#findKeyringIndexForAccount(address); @@ -1571,6 +1571,7 @@ export class KeyringController< this.#assertIsUnlocked(); return this.#withTransaction( + 'setLocked', // Locking clears the session without rewriting the vault, and the // encryption key is gone by commit time anyway. () => this.#beginWalletTransaction(() => false), @@ -1850,6 +1851,7 @@ export class KeyringController< this.#assertIsUnlocked(); return this.#withTransaction( + 'changePassword', () => this.#beginWalletTransaction(persistWhenSessionChanged), async () => { assertIsValidPassword(password); @@ -1874,6 +1876,7 @@ export class KeyringController< encryptionSalt?: string, ): Promise { const { hasChanged } = await this.#withTransaction( + 'submitEncryptionKey', // The unlock transaction is a rollback safety net: whether to // upgrade the vault is the next transaction's decision, on the // restoration's own change flag. @@ -1892,6 +1895,7 @@ export class KeyringController< // if new metadata has been generated during login, we // can attempt to upgrade the vault. await this.#withTransaction( + 'submitEncryptionKey:upgradeVault', // The criterion is the restoration's change flag from the unlock // above — not this transaction's own session diff. () => this.#beginWalletTransaction(() => hasChanged), @@ -1912,7 +1916,7 @@ export class KeyringController< async exportEncryptionKey(): Promise { this.#assertIsUnlocked(); - return await this.#withControllerLock(async () => { + return await this.#withControllerLock('exportEncryptionKey', async () => { assertIsEncryptionKeySet(this.#encryptionKey?.serialized); return this.#encryptionKey.serialized; }); @@ -1927,6 +1931,7 @@ export class KeyringController< */ async submitPassword(password: string): Promise { const { hasChanged } = await this.#withTransaction( + 'submitPassword', // The unlock transaction is a rollback safety net: whether to // upgrade the vault is the next transaction's decision. () => this.#beginWalletTransaction(() => false), @@ -1942,6 +1947,7 @@ export class KeyringController< // if the keyring state has changed during deserialization, we // can attempt to upgrade the vault. await this.#withTransaction( + 'submitPassword:upgradeVault', // The criterion combines the restoration's change flag from the // unlock above — not this transaction's own session diff — with // the available encryption params, and gates the re-derivation @@ -1978,7 +1984,7 @@ export class KeyringController< async verifySeedPhrase(keyringId?: string): Promise { this.#assertIsUnlocked(); - return this.#withControllerLock(async () => + return this.#withControllerLock('verifySeedPhrase', async () => this.#verifySeedPhrase(keyringId), ); } @@ -2344,6 +2350,7 @@ export class KeyringController< this.#assertIsUnlocked(); return this.#withTransaction( + 'withController', () => this.#beginWalletTransaction(persistWhenSessionChanged), async (transaction) => { // Track created and removed keyrings during the operation execution. @@ -2856,7 +2863,7 @@ export class KeyringController< keyrings: { keyring: EthKeyring; metadata: KeyringMetadata }[]; hasChanged: boolean; }> { - return this.#withVaultLock(async () => { + return this.#withVaultLock('unlockKeyrings', async () => { if (!this.state.vault) { throw new KeyringControllerError( KeyringControllerErrorMessage.VaultError, @@ -2915,7 +2922,7 @@ export class KeyringController< * @returns A promise resolving to `true` if the operation is successful. */ #updateVault(): Promise { - return this.#withVaultLock(async () => { + return this.#withVaultLock('updateVault', async () => { // Ensure no duplicate accounts are persisted. await this.#assertNoDuplicateAccounts(); @@ -3071,29 +3078,42 @@ export class KeyringController< keyring: AtomicKeyring, action: () => void | Promise, ): Promise { - await this.#withControllerLock(async () => { - // Load-bearing, not defensive: detached keyrings cannot write the - // vault. Proceeding would silently write a vault without them, and - // update actions queued behind the controller lock during a lock or - // a restore would commit past it, to a fresh instance they never - // belonged to. - const keyringRef: object = keyring; - if (!this.#keyrings.some((entry) => entry.keyring === keyringRef)) { - throw new KeyringControllerError( - KeyringControllerErrorMessage.AtomicUpdateKeyringDetached, + await this.#withControllerLock( + 'atomicUpdate', + async ({ setLogContext }) => { + // Load-bearing, not defensive: detached keyrings cannot write the + // vault. Proceeding would silently write a vault without them, and + // update actions queued behind the controller lock during a lock or + // a restore would commit past it, to a fresh instance they never + // belonged to. + const keyringRef: object = keyring; + const entry = this.#keyrings.find( + (candidate) => candidate.keyring === keyringRef, ); - } + if (!entry) { + throw new KeyringControllerError( + KeyringControllerErrorMessage.AtomicUpdateKeyringDetached, + ); + } + setLogContext({ + keyring: { + type: entry.keyring.type, + kind: 'commit', + id: entry.metadata.id, + }, + }); - // The commit window: a wallet-scope transaction whose persist - // policy writes the vault if and only if the session state - // changed. Only the commit runs — a failure of the action leaves - // the transaction abandoned, restoring nothing. - const { transaction } = await this.#beginWalletTransaction( - persistWhenSessionChanged, - ); - await action(); - await transaction.commit(); - }); + // The commit window: a wallet-scope transaction whose persist + // policy writes the vault if and only if the session state + // changed. Only the commit runs — a failure of the action leaves + // the transaction abandoned, restoring nothing. + const { transaction } = await this.#beginWalletTransaction( + persistWhenSessionChanged, + ); + await action(); + await transaction.commit(); + }, + ); } /** @@ -3345,11 +3365,17 @@ export class KeyringController< create: () => Promise, run: (entry: KeyringEntry) => Promise, ): Promise { + let logContext: LogContext | undefined; const outcome = await this.#withTransaction< TransactionOutcome, KeyringEntry >( - () => this.#beginKeyringTransaction({ v2 }, select, create), + v2 ? 'withKeyringV2' : 'withKeyring', + ({ setLogContext }) => + this.#beginKeyringTransaction({ v2 }, select, create, (context) => { + logContext = context; + setLogContext(context); + }), async (transaction, entry) => { if (transaction.scope.type === 'atomic') { // An atomic keyring serializes its own operations and persists @@ -3396,7 +3422,29 @@ export class KeyringController< // The selected (or transaction-created) keyring is atomic: the // operation runs unlocked, so the keyring's `update` commits can // take the controller lock. - return outcome.run(); + const startedAt = performance.now(); + const details = { + ...logContext, + id: this.#nextAtomicOperationId, + operation: v2 ? 'withKeyringV2' : 'withKeyring', + }; + this.#nextAtomicOperationId += 1; + let success = false; + log( + 'Atomic keyring operation started (outside controller lock)', + details, + ); + try { + const result = await outcome.run(); + success = true; + return result; + } finally { + log('Atomic keyring operation finished (outside controller lock)', { + ...details, + durationMs: performance.now() - startedAt, + success, + }); + } } return outcome.result; @@ -3424,12 +3472,14 @@ export class KeyringController< * @param select - Selects the keyring entry to operate on, if any. * @param create - Creates the keyring entry to operate on when selection * found nothing, if needed. + * @param setLogContext - Adds the selected identity to subsequent lock logs. * @returns The transaction, and the operated entry. */ async #beginKeyringTransaction( { v2 }: { v2: boolean }, select: () => Promise, create: () => Promise, + setLogContext: (context: LogContext) => void, ): Promise<{ transaction: VaultTransaction; setup: KeyringEntry; @@ -3443,6 +3493,14 @@ export class KeyringController< ); } + setLogContext({ + keyring: { + type: entry.keyring.type, + kind: v2 ? 'v2' : 'v1', + id: entry.metadata.id, + }, + }); + if (v2 && !entry.keyringV2) { throw new KeyringControllerError( KeyringControllerErrorMessage.KeyringV2NotSupported, @@ -3526,6 +3584,7 @@ export class KeyringController< * controller untouched — and committed after the function succeeds, or * rolled back if it throws. * + * @param operation - A non-sensitive operation label for lock diagnostics. * @param construct - Constructs and begins the transaction, plus * whatever the operation needs from the construction. * @param run - Runs the operation, with the transaction and what its @@ -3533,14 +3592,20 @@ export class KeyringController< * @returns The result of the operation. */ async #withTransaction( - construct: () => Promise<{ + operation: string, + construct: ( + options: Pick< + Parameters>[0], + 'setLogContext' + >, + ) => Promise<{ transaction: VaultTransaction; setup: Setup; }>, run: (transaction: VaultTransaction, setup: Setup) => Promise, ): Promise { - return this.#withControllerLock(async () => { - const { transaction, setup } = await construct(); + return this.#withControllerLock(operation, async (options) => { + const { transaction, setup } = await construct(options); try { const result = await run(transaction, setup); @@ -3640,13 +3705,19 @@ export class KeyringController< * controller and that changes its state is executed in a mutually exclusive way, * preventing unsafe concurrent access that could lead to unpredictable behavior. * + * @param operation - A non-sensitive operation label for lock diagnostics. * @param callback - The function to execute while the controller mutex is locked. * @returns The result of the function. */ async #withControllerLock( + operation: string, callback: MutuallyExclusiveCallback, ): Promise { - return withLock(this.#controllerOperationMutex, callback); + return withLock( + this.#controllerOperationMutex, + { lock: 'controller', operation }, + callback, + ); } /** @@ -3657,37 +3728,21 @@ export class KeyringController< * This ensures that each operation that interacts with the vault * is executed in a mutually exclusive way. * + * @param operation - A non-sensitive operation label for lock diagnostics. * @param callback - The function to execute while the vault mutex is locked. * @returns The result of the function. */ async #withVaultLock( + operation: string, callback: MutuallyExclusiveCallback, ): Promise { this.#assertControllerMutexIsLocked(); - return withLock(this.#vaultOperationMutex, callback); - } -} - -/** - * Lock the given mutex before executing the given function, - * and release it after the function is resolved or after an - * error is thrown. - * - * @param mutex - The mutex to lock. - * @param callback - The function to execute while the mutex is locked. - * @returns The result of the function. - */ -async function withLock( - mutex: Mutex, - callback: MutuallyExclusiveCallback, -): Promise { - const releaseLock = await mutex.acquire(); - - try { - return await callback({ releaseLock }); - } finally { - releaseLock(); + return withLock( + this.#vaultOperationMutex, + { lock: 'vault', operation }, + callback, + ); } } diff --git a/packages/keyring-controller/src/logger.ts b/packages/keyring-controller/src/logger.ts new file mode 100644 index 00000000000..d963b68c2a5 --- /dev/null +++ b/packages/keyring-controller/src/logger.ts @@ -0,0 +1,4 @@ +import { createProjectLogger, createModuleLogger } from '@metamask/utils'; + +export const projectLogger = createProjectLogger('keyring-controller'); +export const lockLogger = createModuleLogger(projectLogger, 'locks'); diff --git a/packages/keyring-controller/src/withLock.test.ts b/packages/keyring-controller/src/withLock.test.ts new file mode 100644 index 00000000000..a1fcf27cee6 --- /dev/null +++ b/packages/keyring-controller/src/withLock.test.ts @@ -0,0 +1,145 @@ +import { Mutex } from 'async-mutex'; +import { describe, expect, it, vi } from 'vitest'; + +import { lockLogger } from './logger.js'; +import { withLock } from './withLock.js'; + +vi.mock('./logger.js', () => ({ lockLogger: vi.fn() })); + +describe('withLock', () => { + it('adds selected keyring metadata only to subsequent logs', async () => { + const context = { + keyring: { + type: 'HD Key Tree', + kind: 'v2' as const, + id: 'keyring-id', + }, + }; + await withLock( + new Mutex(), + { lock: 'controller', operation: 'withKeyringV2' }, + async ({ setLogContext }) => { + setLogContext(context); + }, + ); + + expect(lockLogger).toHaveBeenCalledWith('Lock requested', { + lock: 'controller', + operation: 'withKeyringV2', + id: expect.any(Number), + }); + expect(lockLogger).toHaveBeenCalledWith('Lock acquired', { + lock: 'controller', + operation: 'withKeyringV2', + id: expect.any(Number), + waitMs: expect.any(Number), + }); + expect(lockLogger).toHaveBeenCalledWith( + 'Lock released', + expect.objectContaining(context), + ); + expect(lockLogger).toHaveBeenLastCalledWith( + 'Locked operation finished', + expect.objectContaining(context), + ); + }); + + it('logs requests, acquisition, release and completion with separate wait and hold times', async () => { + const mutex = new Mutex(); + const release = await mutex.acquire(); + let now = 10; + vi.spyOn(performance, 'now').mockImplementation(() => now); + const context = { lock: 'controller' as const, operation: 'withKeyring' }; + const result = withLock(mutex, context, async () => { + now = 50; + return 'result'; + }); + + expect(lockLogger).toHaveBeenLastCalledWith('Lock requested', { + ...context, + id: expect.any(Number), + }); + const { id } = vi.mocked(lockLogger).mock.calls[0][1] as { + id: number; + }; + now = 30; + release(); + + expect(await result).toBe('result'); + expect(lockLogger).toHaveBeenCalledWith('Lock acquired', { + ...context, + id, + waitMs: 20, + }); + expect(lockLogger).toHaveBeenCalledWith('Lock released', { + ...context, + id, + waitMs: 20, + holdMs: 20, + }); + expect(lockLogger).toHaveBeenLastCalledWith('Locked operation finished', { + ...context, + id, + waitMs: 20, + holdMs: 20, + totalMs: 40, + success: true, + }); + expect(mutex.isLocked()).toBe(false); + }); + + it('releases and logs failures without logging potentially sensitive errors', async () => { + const mutex = new Mutex(); + const error = new Error('secret'); + await expect( + withLock(mutex, { lock: 'vault', operation: 'updateVault' }, async () => { + throw error; + }), + ).rejects.toBe(error); + + expect(mutex.isLocked()).toBe(false); + expect(lockLogger).toHaveBeenLastCalledWith('Locked operation finished', { + lock: 'vault', + operation: 'updateVault', + id: expect.any(Number), + waitMs: expect.any(Number), + holdMs: expect.any(Number), + totalMs: expect.any(Number), + success: false, + }); + expect(JSON.stringify(vi.mocked(lockLogger).mock.calls)).not.toContain( + 'secret', + ); + }); + + it('measures early release independently of operation completion and releases only once', async () => { + let now = 0; + vi.spyOn(performance, 'now').mockImplementation(() => now); + const mutex = new Mutex(); + await withLock( + mutex, + { lock: 'controller', operation: 'test' }, + async ({ releaseLock }) => { + now = 10; + releaseLock(); + releaseLock(); + expect(mutex.isLocked()).toBe(false); + now = 40; + }, + ); + + expect( + vi + .mocked(lockLogger) + .mock.calls.filter(([message]) => message === 'Lock released'), + ).toHaveLength(1); + expect(lockLogger).toHaveBeenLastCalledWith( + 'Locked operation finished', + expect.objectContaining({ + holdMs: 10, + totalMs: 40, + success: true, + }), + ); + }); +}); diff --git a/packages/keyring-controller/src/withLock.ts b/packages/keyring-controller/src/withLock.ts new file mode 100644 index 00000000000..5a596f628c2 --- /dev/null +++ b/packages/keyring-controller/src/withLock.ts @@ -0,0 +1,82 @@ +import type { Mutex, MutexInterface } from 'async-mutex'; + +import { lockLogger as log } from './logger.js'; + +/** An operation which may explicitly release its mutex before completing. */ +export type MutuallyExclusiveCallback = (options: { + releaseLock: MutexInterface.Releaser; + setLogContext: (context: LogContext) => void; +}) => Promise; + +/** The keyring identity and access path, not its serialized state. */ +export type LogContext = { + keyring: { + type: string; + kind: 'v1' | 'v2' | 'commit'; + id: string; + }; +}; + +/** Diagnostic labels only; never include operation arguments or secrets. */ +export type LockContext = { + lock: 'controller' | 'vault'; + operation: string; +}; + +let nextLockId = 0; + +/** + * Run an operation under a mutex, measuring queue wait and actual lock hold + * time separately. Completion includes persistence and rollback by the caller. + * + * @param mutex - The mutex to acquire. + * @param context - Non-sensitive labels identifying the lock and operation. + * @param callback - The operation to run while holding the lock. + * @returns The operation's result. + */ +export async function withLock( + mutex: Mutex, + context: LockContext, + callback: MutuallyExclusiveCallback, +): Promise { + const details = { ...context, id: nextLockId }; + nextLockId += 1; + const requestedAt = performance.now(); + log('Lock requested', details); + const release = await mutex.acquire(); + const acquiredAt = performance.now(); + const waitMs = acquiredAt - requestedAt; + let holdMs: number | undefined; + let success = false; + let logContext: LogContext | undefined; + + const releaseLock = (): void => { + if (holdMs === undefined) { + holdMs = performance.now() - acquiredAt; + release(); + log('Lock released', { ...details, ...logContext, waitMs, holdMs }); + } + }; + + try { + log('Lock acquired', { ...details, waitMs }); + const result = await callback({ + releaseLock, + setLogContext: (additionalContext) => { + logContext = { keyring: { ...additionalContext.keyring } }; + }, + }); + success = true; + return result; + } finally { + releaseLock(); + log('Locked operation finished', { + ...details, + ...logContext, + waitMs, + holdMs, + totalMs: performance.now() - requestedAt, + success, + }); + } +}