From 8f6c83e2c29fa1a200afc03e9adce2d22ac5dd47 Mon Sep 17 00:00:00 2001 From: Dan J Miller Date: Mon, 29 Jul 2024 13:04:58 -0230 Subject: [PATCH] fix: setupControllerConnection outstream end event listener (#26141) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ## **Description** This PR addresses a problem which had the following surface level symptoms: when the UI is closed, the extension continues to send network requests to the provider. Upon some investigation, we discovered that these requests were the result of polling initiated from the account tracker. And then upon further investigation, we discovered that the callback in the `outstream` `'end'` listener in `setupControllerConnection` of `metamask-controller.js` was not being called when the UI was closed. This problem was introduced with https://github.com/MetaMask/metamask-extension/pull/24533. That PR updates the `object-multiplex` dependency to v2.0.0. The major change in that update is the update of the `readable-stream` dependency from a v2 version to a v3 version. With that update, we see new `premature-close` errors in the background. It seems that these errors are still present in v2, but they are handled differently, resulting in an `'error'` event instead of an `'end'` event. We still have not established a definitive understanding of why this is happening, and follow up investigation will be needed. However, this PR still puts forward a fix that safely resolves the issue. The solution added here is to make use of the `readableStream.finished` function. The callback passed to this function will be called when the stream is ended. This function has the same behaviour as the `outstream.on('end'` listener had prior to the aforementioned PR. Instead of fully replacing the existing listener, we have added the `readableStream.finished` call in addition to the existing listener. The reason for this is explained in a code comment: > The presence of both of the below handlers may be redundant. After upgrading metamask/object-multiples to v2.0.0, which included an upgrade of readable-streams from v2 to v3, we saw that the `outStream.on('end'` handler was almost never being called. This seems to related to how v3 handles errors vs how v2 handles errors; there are "premature close" errors in both cases, although in the case of v2 they don't prevent `outStream.on('end'` from being called. At the time that this comment was committed, it was known that we need to investigate and resolve the underlying error, however, for expediency, we are not addressing them at this time. Instead, we can observe that `readableStream.finished` preserves the same functionality as we had when we relied on readable-stream v2. Meanwhile, the `outStream.on('end'` handler was observed to have been called at least once. As we do not yet fully understand the conditions under which both of these are being called, we include both handlers at the risk of redundancy. Logic has been added to the handler to ensure that calling it more than once does not have any affect. To achieve "Logic has been added to the handler to ensure that calling it more than once does not have any affect.", the PR adds a unique id to each stream passed to `setupControllerConnection`, and uses a `Set` to ensure the handler code only runs once per stream. This PR then adds automated tests. The added unit tests are focused on validating both pre-existing and new behaviour of `setupControllerChanged`. The added e2e tests focus on the inititially mentioned surface level symptoms: it confirms that `eth_call` and `eth_getBalance` calls, the calls coming from the account-tracker initiated polling, are not continued after the UI is closed. This e2e test fails on current develop but passes on this branch. MetaMask team members can see more details in this thread: https://consensys.slack.com/archives/CTQAGKY5V/p1721653870583869 [![Open in GitHub Codespaces](https://github.com/codespaces/badge.svg)](https://codespaces.new/MetaMask/metamask-extension/pull/26141?quickstart=1) ## **Related issues** Fixes: https://github.com/MetaMask/metamask-extension/issues/26002 ## **Manual testing steps** To observe the bug on develop: 1. Install and onboard 2. Open the service worker dev console and go to the network tab 3. Observe `eth_call` and `eth_getBalance` requests to infura 4. Close the UI, observe that the requests from step 3 continue On this branch, in step 4, after closing the UI, those requests will not continue. ## **Screenshots/Recordings** ### **Before** ### **After** ## **Pre-merge author checklist** - [x] I've followed [MetaMask Contributor Docs](https://github.com/MetaMask/contributor-docs) and [MetaMask Extension Coding Standards](https://github.com/MetaMask/metamask-extension/blob/develop/.github/guidelines/CODING_GUIDELINES.md). - [x] I've completed the PR template to the best of my ability - [x] I’ve included tests if applicable - [ ] I’ve documented my code using [JSDoc](https://jsdoc.app/) format if applicable - [ ] I’ve applied the right labels on the PR (see [labeling guidelines](https://github.com/MetaMask/metamask-extension/blob/develop/.github/guidelines/LABELING_GUIDELINES.md)). Not required for external contributors. ## **Pre-merge reviewer checklist** - [ ] I've manually tested the PR (e.g. pull and build branch, run the app, test code being changed). - [ ] I confirm that this PR addresses all acceptance criteria described in the ticket it closes and includes the necessary testing evidence such as recordings and or screenshots. --------- Co-authored-by: legobt <6wbvkn0j@anonaddy.me> Co-authored-by: legobeat <109787230+legobeat@users.noreply.github.com> Co-authored-by: Danica Shen --- app/scripts/metamask-controller.js | 43 ++- app/scripts/metamask-controller.test.js | 280 ++++++++++++++++++ .../account-tracker-api-usage.spec.ts | 209 +++++++++++++ 3 files changed, 523 insertions(+), 9 deletions(-) create mode 100644 test/e2e/tests/api-usage/account-tracker-api-usage.spec.ts diff --git a/app/scripts/metamask-controller.js b/app/scripts/metamask-controller.js index fff0096e856b..20b581f26bcb 100644 --- a/app/scripts/metamask-controller.js +++ b/app/scripts/metamask-controller.js @@ -1,5 +1,5 @@ import EventEmitter from 'events'; -import { pipeline } from 'readable-stream'; +import { finished, pipeline } from 'readable-stream'; import { AssetsContractController, CurrencyRateController, @@ -5090,14 +5090,39 @@ export default class MetamaskController extends EventEmitter { this.once('startUISync', startUISync); } - outStream.on('end', () => { - this.activeControllerConnections -= 1; - this.emit( - 'controllerConnectionChanged', - this.activeControllerConnections, - ); - this.removeListener('update', handleUpdate); - }); + const outstreamEndHandler = () => { + if (!outStream.mmFinished) { + this.activeControllerConnections -= 1; + this.emit( + 'controllerConnectionChanged', + this.activeControllerConnections, + ); + outStream.mmFinished = true; + this.removeListener('update', handleUpdate); + } + }; + + // The presence of both of the below handlers may be redundant. + // After upgrading metamask/object-multiples to v2.0.0, which included + // an upgrade of readable-streams from v2 to v3, we saw that the + // `outStream.on('end'` handler was almost never being called. This seems to + // related to how v3 handles errors vs how v2 handles errors; there + // are "premature close" errors in both cases, although in the case + // of v2 they don't prevent `outStream.on('end'` from being called. + // At the time that this comment was committed, it was known that we + // need to investigate and resolve the underlying error, however, + // for expediency, we are not addressing them at this time. Instead, we + // can observe that `readableStream.finished` preserves the same + // functionality as we had when we relied on readable-stream v2. Meanwhile, + // the `outStream.on('end')` handler was observed to have been called at least once. + // In an abundance of caution to prevent against unexpected future behavioral changes in + // streams implementations, we redundantly use multiple paths to attach the same event handler. + // The outstreamEndHandler therefore needs to be idempotent, which introduces the `mmFinished` property. + + outStream.mmFinished = false; + finished(outStream, outstreamEndHandler); + outStream.once('close', outstreamEndHandler); + outStream.once('end', outstreamEndHandler); } /** diff --git a/app/scripts/metamask-controller.test.js b/app/scripts/metamask-controller.test.js index 8f5e37123a9e..3b9c731c97ca 100644 --- a/app/scripts/metamask-controller.test.js +++ b/app/scripts/metamask-controller.test.js @@ -27,6 +27,7 @@ import { RatesController, TokenListController, } from '@metamask/assets-controllers'; +import ObjectMultiplex from '@metamask/object-multiplex'; import { TrezorKeyring } from '@metamask/eth-trezor-keyring'; import { LedgerKeyring } from '@metamask/eth-ledger-bridge-keyring'; import { NETWORK_TYPES } from '../../shared/constants/network'; @@ -1406,9 +1407,288 @@ describe('MetaMaskController', () => { }); metamaskController.setupTrustedCommunication(streamTest, messageSender); + await promise; streamTest.end(); }); + + it('uses a new multiplex to set up a connection', () => { + jest.spyOn(metamaskController, 'setupControllerConnection'); + + const streamTest = createThroughStream((chunk, _, cb) => { + cb(chunk); + }); + + metamaskController.setupTrustedCommunication(streamTest, {}); + + expect(metamaskController.setupControllerConnection).toHaveBeenCalled(); + expect( + metamaskController.setupControllerConnection, + ).toHaveBeenCalledWith( + expect.objectContaining({ + _name: 'controller', + _parent: expect.any(ObjectMultiplex), + }), + ); + }); + + const createTestStream = () => { + const { + promise: onFinishedCallbackPromise, + resolve: onFinishedCallbackResolve, + } = deferredPromise(); + const { promise: onStreamEndPromise, resolve: onStreamEndResolve } = + deferredPromise(); + const testStream = createThroughStream((chunk, _, cb) => { + expect(chunk.name).toStrictEqual('controller'); + onStreamEndResolve(); + cb(); + }); + + return { + onFinishedCallbackPromise, + onStreamEndPromise, + onFinishedCallbackResolve, + testStream, + }; + }; + + it('sets up a controller connection which emits a controllerConnectionChanged event when the controller connection is created and ended, and activeControllerConnections are updated accordingly', async () => { + const mockControllerConnectionChangedHandler = jest.fn(); + + const { + onStreamEndPromise, + onFinishedCallbackPromise, + onFinishedCallbackResolve, + testStream, + } = createTestStream(); + + metamaskController.on( + 'controllerConnectionChanged', + (activeControllerConnections) => { + mockControllerConnectionChangedHandler(activeControllerConnections); + if ( + mockControllerConnectionChangedHandler.mock.calls.length === 2 + ) { + onFinishedCallbackResolve(); + } + }, + ); + + expect(metamaskController.activeControllerConnections).toBe(0); + + metamaskController.setupTrustedCommunication(testStream, {}); + + expect(mockControllerConnectionChangedHandler).toHaveBeenCalledTimes(1); + expect(mockControllerConnectionChangedHandler).toHaveBeenLastCalledWith( + 1, + ); + + expect(metamaskController.activeControllerConnections).toBe(1); + + await onStreamEndPromise; + testStream.end(); + + await onFinishedCallbackPromise; + + expect(metamaskController.activeControllerConnections).toBe(0); + expect(mockControllerConnectionChangedHandler).toHaveBeenCalledTimes(2); + expect(mockControllerConnectionChangedHandler).toHaveBeenLastCalledWith( + 0, + ); + }); + + it('can be called multiple times to set up multiple controller connections, which can be ended independently', async () => { + const mockControllerConnectionChangedHandler = jest.fn(); + + const testStreams = [ + createTestStream(), + createTestStream(), + createTestStream(), + createTestStream(), + createTestStream(), + ]; + metamaskController.on( + 'controllerConnectionChanged', + (activeControllerConnections) => { + const initialChangeHandlerCallCount = + mockControllerConnectionChangedHandler.mock.calls.length; + mockControllerConnectionChangedHandler(activeControllerConnections); + + if ( + initialChangeHandlerCallCount === 5 && + activeControllerConnections === 4 + ) { + testStreams[1].onFinishedCallbackResolve(); + } + if ( + initialChangeHandlerCallCount === 7 && + activeControllerConnections === 2 + ) { + testStreams[3].onFinishedCallbackResolve(); + testStreams[4].onFinishedCallbackResolve(); + } + if ( + initialChangeHandlerCallCount === 9 && + activeControllerConnections === 0 + ) { + testStreams[2].onFinishedCallbackResolve(); + testStreams[0].onFinishedCallbackResolve(); + } + }, + ); + + metamaskController.setupTrustedCommunication( + testStreams[0].testStream, + {}, + ); + metamaskController.setupTrustedCommunication( + testStreams[1].testStream, + {}, + ); + metamaskController.setupTrustedCommunication( + testStreams[2].testStream, + {}, + ); + metamaskController.setupTrustedCommunication( + testStreams[3].testStream, + {}, + ); + metamaskController.setupTrustedCommunication( + testStreams[4].testStream, + {}, + ); + + expect(metamaskController.activeControllerConnections).toBe(5); + + await testStreams[1].promise; + testStreams[1].testStream.end(); + + await testStreams[1].onFinishedCallbackPromise; + + expect(metamaskController.activeControllerConnections).toBe(4); + + await testStreams[3].promise; + testStreams[3].testStream.end(); + + await testStreams[4].promise; + testStreams[4].testStream.end(); + + await testStreams[3].onFinishedCallbackPromise; + await testStreams[4].onFinishedCallbackPromise; + + expect(metamaskController.activeControllerConnections).toBe(2); + + await testStreams[2].promise; + testStreams[2].testStream.end(); + + await testStreams[0].promise; + testStreams[0].testStream.end(); + + await testStreams[2].onFinishedCallbackPromise; + await testStreams[0].onFinishedCallbackPromise; + + expect(metamaskController.activeControllerConnections).toBe(0); + }); + + // this test could be improved by testing for actual behavior of handlers, + // without touching rawListeners from test + it('attaches listeners for trusted communication streams and removes them as streams close', async () => { + jest + .spyOn(metamaskController, 'triggerNetworkrequests') + .mockImplementation(); + jest + .spyOn(metamaskController.onboardingController.store, 'getState') + .mockReturnValue({ completedOnboarding: true }); + const mockControllerConnectionChangedHandler = jest.fn(); + + const testStreams = [ + createTestStream(), + createTestStream(2), + createTestStream(3), + createTestStream(4), + createTestStream(5), + ]; + const baseUpdateListenerCount = + metamaskController.rawListeners('update').length; + + metamaskController.on( + 'controllerConnectionChanged', + (activeControllerConnections) => { + const initialChangeHandlerCallCount = + mockControllerConnectionChangedHandler.mock.calls.length; + mockControllerConnectionChangedHandler(activeControllerConnections); + if ( + initialChangeHandlerCallCount === 8 && + activeControllerConnections === 1 + ) { + testStreams[1].onFinishedCallbackResolve(); + testStreams[3].onFinishedCallbackResolve(); + testStreams[4].onFinishedCallbackResolve(); + testStreams[2].onFinishedCallbackResolve(); + } + if ( + initialChangeHandlerCallCount === 9 && + activeControllerConnections === 0 + ) { + testStreams[0].onFinishedCallbackResolve(); + } + }, + ); + + metamaskController.setupTrustedCommunication( + testStreams[0].testStream, + {}, + ); + metamaskController.setupTrustedCommunication( + testStreams[1].testStream, + {}, + ); + metamaskController.setupTrustedCommunication( + testStreams[2].testStream, + {}, + ); + metamaskController.setupTrustedCommunication( + testStreams[3].testStream, + {}, + ); + metamaskController.setupTrustedCommunication( + testStreams[4].testStream, + {}, + ); + + await testStreams[1].promise; + + expect(metamaskController.rawListeners('update')).toHaveLength( + baseUpdateListenerCount + 5, + ); + + testStreams[1].testStream.end(); + await testStreams[3].promise; + testStreams[3].testStream.end(); + testStreams[3].testStream.end(); + + await testStreams[4].promise; + testStreams[4].testStream.end(); + await testStreams[2].promise; + testStreams[2].testStream.end(); + await testStreams[1].onFinishedCallbackPromise; + await testStreams[3].onFinishedCallbackPromise; + await testStreams[4].onFinishedCallbackPromise; + await testStreams[2].onFinishedCallbackPromise; + expect(metamaskController.rawListeners('update')).toHaveLength( + baseUpdateListenerCount + 1, + ); + + await testStreams[0].promise; + testStreams[0].testStream.end(); + + await testStreams[0].onFinishedCallbackPromise; + + expect(metamaskController.rawListeners('update')).toHaveLength( + baseUpdateListenerCount, + ); + }); }); describe('#markPasswordForgotten', () => { diff --git a/test/e2e/tests/api-usage/account-tracker-api-usage.spec.ts b/test/e2e/tests/api-usage/account-tracker-api-usage.spec.ts new file mode 100644 index 000000000000..5ab35138ce7b --- /dev/null +++ b/test/e2e/tests/api-usage/account-tracker-api-usage.spec.ts @@ -0,0 +1,209 @@ +import { strict as assert } from 'assert'; +import { MockedEndpoint } from 'mockttp'; +import { JsonRpcRequest } from '@metamask/utils'; +import { + withFixtures, + defaultGanacheOptions, + unlockWallet, + veryLargeDelayMs, +} from '../../helpers'; +import FixtureBuilder from '../../fixture-builder'; +import { Driver } from '../../webdriver/driver'; +import { Mockttp } from '../../mock-e2e'; + +async function mockInfura(mockServer: Mockttp): Promise { + const blockNumber = { value: 0 }; + + return [ + await mockServer + .forPost(/infura/u) + .withJsonBodyIncluding({ method: 'eth_blockNumber' }) + .times(50) + .thenCallback(() => { + // We need to ensure the mocked block number keeps increasing, + // as this results in block tracker listeners firing, which is + // needed for the potential account tracker network requests being + // tested against here. + blockNumber.value += 1; + + return { + statusCode: 200, + json: { + jsonrpc: '2.0', + id: '1111111111111111', + result: blockNumber.value.toString(16), + }, + }; + }), + await mockServer.forPost(/infura/u).thenCallback(() => { + return { + statusCode: 200, + json: { + jsonrpc: '2.0', + id: '1111111111111111', + result: '0x1', + }, + }; + }), + await mockServer.forGet(/infura/u).thenCallback(() => { + return { + statusCode: 200, + json: { + jsonrpc: '2.0', + id: '1111111111111111', + result: '0x0', + }, + }; + }), + ]; +} + +async function getAllInfuraJsonRpcRequests( + mockedEndpoint: MockedEndpoint[], +): Promise { + const allInfuraJsonRpcRequests: JsonRpcRequest[] = []; + let seenRequests; + let seenProviderRequests; + + for (const m of mockedEndpoint) { + seenRequests = await m.getSeenRequests(); + seenProviderRequests = seenRequests.filter((request) => + request.url.match('infura'), + ); + + for (const r of seenProviderRequests) { + const json = await r.body.getJson(); + if (json !== undefined) { + allInfuraJsonRpcRequests.push(json); + } + } + } + + return allInfuraJsonRpcRequests; +} + +function getSpecifiedJsonRpcRequests( + jsonRpcRequestArray: JsonRpcRequest[], + methodsToGet: string[], +) { + return jsonRpcRequestArray.filter(({ method }) => + methodsToGet.includes(method), + ); +} + +describe('Account Tracker API Usage', function () { + it('should not make eth_call or eth_getBalance requests before the UI is opened and should make those requests after the UI is opened', async function () { + // Note: we are not testing that eth_getBlockByNumber is not called before the UI + // is opened because there is a known bug that results in it being called if the + // user is already onboarded: https://github.com/MetaMask/MetaMask-planning/issues/2151 + // Once that issue is resolved, we can add eth_getBlockByNumber to the below array. + const RPC_METHODS_TO_TEST = ['eth_call', 'eth_getBalance']; + + await withFixtures( + { + fixtures: new FixtureBuilder().withNetworkControllerOnMainnet().build(), + ganacheOptions: defaultGanacheOptions, + title: this.test?.fullTitle(), + testSpecificMock: mockInfura, + }, + async ({ + driver, + mockedEndpoint, + }: { + driver: Driver; + mockedEndpoint: MockedEndpoint[]; + }) => { + await driver.delay(veryLargeDelayMs); + let allInfuraJsonRpcRequests = await getAllInfuraJsonRpcRequests( + mockedEndpoint, + ); + let rpcMethodsToTestRequests = getSpecifiedJsonRpcRequests( + allInfuraJsonRpcRequests, + RPC_METHODS_TO_TEST, + ); + + assert.ok( + rpcMethodsToTestRequests.length === 0, + `An ${RPC_METHODS_TO_TEST.join( + ' or ', + )} request has been made to infura before opening the UI`, + ); + + await unlockWallet(driver); + await driver.delay(veryLargeDelayMs); + + allInfuraJsonRpcRequests = await getAllInfuraJsonRpcRequests( + mockedEndpoint, + ); + rpcMethodsToTestRequests = getSpecifiedJsonRpcRequests( + allInfuraJsonRpcRequests, + RPC_METHODS_TO_TEST, + ); + + assert.ok( + rpcMethodsToTestRequests.length > 0, + `No ${RPC_METHODS_TO_TEST.join( + ' or ', + )} request has been made to infura since opening the UI`, + ); + }, + ); + }); + + it('should not make eth_call or eth_getBalance or eth_getBlockByNumber requests after the UI is closed', async function () { + const RPC_METHODS_TO_TEST = [ + 'eth_getBlockByNumber', + 'eth_call', + 'eth_getBalance', + ]; + + await withFixtures( + { + fixtures: new FixtureBuilder().withNetworkControllerOnMainnet().build(), + ganacheOptions: defaultGanacheOptions, + title: this.test?.fullTitle(), + testSpecificMock: mockInfura, + }, + async ({ + driver, + mockedEndpoint, + }: { + driver: Driver; + mockedEndpoint: MockedEndpoint[]; + }) => { + await unlockWallet(driver); + await driver.delay(veryLargeDelayMs); + const initialInfuraJsonRpcRequests = await getAllInfuraJsonRpcRequests( + mockedEndpoint, + ); + + await driver.openNewURL('about:blank'); + // The delay is intentionally 20000, to ensure we cover at least 1 polling + // loop of time for the block tracker. + await driver.delay(20000); + + const currentInfuraJsonRpcRequests = await getAllInfuraJsonRpcRequests( + mockedEndpoint, + ); + + const initialRpcMethodsToTestRequests = getSpecifiedJsonRpcRequests( + initialInfuraJsonRpcRequests, + RPC_METHODS_TO_TEST, + ); + + const currentRpcMethodsToTestRequests = getSpecifiedJsonRpcRequests( + currentInfuraJsonRpcRequests, + RPC_METHODS_TO_TEST, + ); + + assert.ok( + initialRpcMethodsToTestRequests.length === + currentRpcMethodsToTestRequests.length, + `An ${RPC_METHODS_TO_TEST.join( + ' or ', + )} request has been made to infura after closing the UI`, + ); + }, + ); + }); +});