Skip to content

Commit

Permalink
fix: setupControllerConnection outstream end event listener (#26141)
Browse files Browse the repository at this point in the history
## **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
#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: #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**

<!-- If applicable, add screenshots and/or recordings to visualize the
before and after of your change. -->

### **Before**

<!-- [screenshots/recordings] -->

### **After**

<!-- [screenshots/recordings] -->

## **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 <[email protected]>
Co-authored-by: legobeat <[email protected]>
Co-authored-by: Danica Shen <[email protected]>
  • Loading branch information
4 people authored Jul 29, 2024
1 parent 0d8b35f commit 8f6c83e
Show file tree
Hide file tree
Showing 3 changed files with 523 additions and 9 deletions.
43 changes: 34 additions & 9 deletions app/scripts/metamask-controller.js
Original file line number Diff line number Diff line change
@@ -1,5 +1,5 @@
import EventEmitter from 'events';
import { pipeline } from 'readable-stream';
import { finished, pipeline } from 'readable-stream';
import {
AssetsContractController,
CurrencyRateController,
Expand Down Expand Up @@ -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);
}

/**
Expand Down
280 changes: 280 additions & 0 deletions app/scripts/metamask-controller.test.js
Original file line number Diff line number Diff line change
Expand Up @@ -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';
Expand Down Expand Up @@ -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', () => {
Expand Down
Loading

0 comments on commit 8f6c83e

Please sign in to comment.