diff --git a/packages/controller-utils/CHANGELOG.md b/packages/controller-utils/CHANGELOG.md index 4d211062157..983ccf81b0a 100644 --- a/packages/controller-utils/CHANGELOG.md +++ b/packages/controller-utils/CHANGELOG.md @@ -7,6 +7,12 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +### Changed + +- **BREAKING:** The `ServicePolicy` type's `onDegraded` event now emits `{ duration: number }` instead of `void` when the service succeeds but takes longer than the `degradedThreshold` ([#8455](https://github.com/MetaMask/core/pull/8455)) + - `void` has been removed from the event's type union. Listeners that checked for `undefined` data should now check for the `duration` property instead. + - The event still emits a `FailureReason` when retries are exhausted. + ## [11.20.0] ### Added diff --git a/packages/controller-utils/src/create-service-policy.test.ts b/packages/controller-utils/src/create-service-policy.test.ts index 7d487617197..5545f6eb4d3 100644 --- a/packages/controller-utils/src/create-service-policy.test.ts +++ b/packages/controller-utils/src/create-service-policy.test.ts @@ -1500,6 +1500,27 @@ describe('createServicePolicy', () => { expect(onDegradedListener).toHaveBeenCalledTimes(1); }); + it('calls onDegraded listeners with duration when the request succeeds but is slow', async () => { + jest.useFakeTimers(); + const policy = createServicePolicy({ + degradedThreshold: 2000, + }); + const onDegradedListener = jest.fn(); + + policy.onDegraded(onDegradedListener); + await policy.execute(async () => { + jest.advanceTimersByTime(2001); + return 'result'; + }); + + expect(onDegradedListener).toHaveBeenCalledTimes(1); + expect(onDegradedListener).toHaveBeenCalledWith({ + duration: expect.any(Number), + }); + const { duration } = onDegradedListener.mock.calls[0][0]; + expect(duration).toBeGreaterThan(2000); + }); + it('does not call onAvailable listeners', async () => { let invocationCounter = 0; const delay = DEFAULT_DEGRADED_THRESHOLD + 1; diff --git a/packages/controller-utils/src/create-service-policy.ts b/packages/controller-utils/src/create-service-policy.ts index dc394bca76c..0c27fdf6155 100644 --- a/packages/controller-utils/src/create-service-policy.ts +++ b/packages/controller-utils/src/create-service-policy.ts @@ -117,7 +117,7 @@ export type ServicePolicy = IPolicy & { * never succeeds before the retry policy gives up and before the maximum * number of consecutive failures has been reached. */ - onDegraded: CockatielEvent | void>; + onDegraded: CockatielEvent | { duration: number }>; /** * A function which is called when the service succeeds for the first time, * or when the service fails enough times to cause the circuit to break and @@ -321,8 +321,9 @@ export function createServicePolicy( }); const onBreak = circuitBreakerPolicy.onBreak.bind(circuitBreakerPolicy); - const onDegradedEventEmitter = - new CockatielEventEmitter | void>(); + const onDegradedEventEmitter = new CockatielEventEmitter< + FailureReason | { duration: number } + >(); const onDegraded = onDegradedEventEmitter.addListener; const onAvailableEventEmitter = new CockatielEventEmitter(); @@ -338,7 +339,7 @@ export function createServicePolicy( if (circuitBreakerPolicy.state === CircuitState.Closed) { if (duration > degradedThreshold) { availabilityStatus = AVAILABILITY_STATUSES.Degraded; - onDegradedEventEmitter.emit(); + onDegradedEventEmitter.emit({ duration }); } else if (availabilityStatus !== AVAILABILITY_STATUSES.Available) { availabilityStatus = AVAILABILITY_STATUSES.Available; onAvailableEventEmitter.emit(); diff --git a/packages/network-controller/CHANGELOG.md b/packages/network-controller/CHANGELOG.md index 52e404223a7..476bbae3922 100644 --- a/packages/network-controller/CHANGELOG.md +++ b/packages/network-controller/CHANGELOG.md @@ -24,6 +24,9 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 - `NetworkController:loadBackup` - Corresponding action types are available as well. - Add `getEthQuery` method to `NetworkController` ([#8350](https://github.com/MetaMask/core/pull/8350)) +- Add `duration` and `traceId` to `NetworkController:rpcEndpointDegraded` and `NetworkController:rpcEndpointChainDegraded` event payloads ([#8455](https://github.com/MetaMask/core/pull/8455)) + - `duration` contains the policy execution time in milliseconds when the request succeeded but was slow. It is `undefined` when retries were exhausted. + - `traceId` contains the value of the `x-trace-id` response header from the last request attempt, or `undefined` if the header was not present. ### Changed diff --git a/packages/network-controller/src/NetworkController.ts b/packages/network-controller/src/NetworkController.ts index 91a1f1f52cc..229d3b6de14 100644 --- a/packages/network-controller/src/NetworkController.ts +++ b/packages/network-controller/src/NetworkController.ts @@ -518,21 +518,28 @@ export type NetworkControllerRpcEndpointUnavailableEvent = { * * @param payload - The event payload. * @param payload.chainId - The target network's chain ID. + * @param payload.duration - The duration in milliseconds of the policy + * execution when the request succeeded but was slow. `undefined` when retries + * were exhausted. * @param payload.error - The last error produced by the endpoint (or * `undefined` if the request was slow). * @param payload.networkClientId - The target network's client ID. * @param payload.rpcMethodName - The JSON-RPC method that was being executed * when the chain became degraded. + * @param payload.traceId - The value of the `x-trace-id` response header from + * the last request attempt, or `undefined` if the header was not present. */ export type NetworkControllerRpcEndpointChainDegradedEvent = { type: 'NetworkController:rpcEndpointChainDegraded'; payload: [ { chainId: Hex; + duration?: number; error: unknown; networkClientId: NetworkClientId; retryReason?: RetryReason; rpcMethodName: string; + traceId?: string; type: DegradedEventType; }, ]; @@ -553,6 +560,9 @@ export type NetworkControllerRpcEndpointChainDegradedEvent = { * * @param payload - The event payload. * @param payload.chainId - The target network's chain ID. + * @param payload.duration - The duration in milliseconds of the policy + * execution when the request succeeded but was slow. `undefined` when retries + * were exhausted. * @param payload.endpointUrl - The URL of the endpoint for which requests * failed or were slow to complete. You can compare this to `primaryEndpointUrl` * to know whether it was a failover or a primary. @@ -562,18 +572,22 @@ export type NetworkControllerRpcEndpointChainDegradedEvent = { * @param payload.primaryEndpointUrl - The endpoint chain's primary URL. * @param payload.rpcMethodName - The JSON-RPC method that was being executed * when the endpoint became degraded. + * @param payload.traceId - The value of the `x-trace-id` response header from + * the last request attempt, or `undefined` if the header was not present. */ export type NetworkControllerRpcEndpointDegradedEvent = { type: 'NetworkController:rpcEndpointDegraded'; payload: [ { chainId: Hex; + duration?: number; endpointUrl: string; error: unknown; networkClientId: NetworkClientId; primaryEndpointUrl: string; retryReason?: RetryReason; rpcMethodName: string; + traceId?: string; type: DegradedEventType; }, ]; diff --git a/packages/network-controller/src/create-network-client-tests/rpc-endpoint-events.test.ts b/packages/network-controller/src/create-network-client-tests/rpc-endpoint-events.test.ts index 28069e17aa3..a0dd8885849 100644 --- a/packages/network-controller/src/create-network-client-tests/rpc-endpoint-events.test.ts +++ b/packages/network-controller/src/create-network-client-tests/rpc-endpoint-events.test.ts @@ -544,6 +544,8 @@ describe('createNetworkClient - RPC endpoint events', () => { networkClientId: 'AAAA-AAAA-AAAA-AAAA', retryReason: 'non_successful_http_status', rpcMethodName: 'eth_blockNumber', + duration: undefined, + traceId: undefined, }); }, ); @@ -667,6 +669,8 @@ describe('createNetworkClient - RPC endpoint events', () => { networkClientId: 'AAAA-AAAA-AAAA-AAAA', retryReason: 'non_successful_http_status', rpcMethodName: 'eth_blockNumber', + duration: undefined, + traceId: undefined, }); }, ); @@ -780,6 +784,8 @@ describe('createNetworkClient - RPC endpoint events', () => { primaryEndpointUrl: rpcUrl, retryReason: 'non_successful_http_status', rpcMethodName: 'eth_blockNumber', + duration: undefined, + traceId: undefined, }); expect( rpcEndpointDegradedEventHandler, @@ -792,6 +798,8 @@ describe('createNetworkClient - RPC endpoint events', () => { primaryEndpointUrl: rpcUrl, retryReason: 'non_successful_http_status', rpcMethodName: 'eth_blockNumber', + duration: undefined, + traceId: undefined, }); expect( rpcEndpointDegradedEventHandler, @@ -804,6 +812,8 @@ describe('createNetworkClient - RPC endpoint events', () => { primaryEndpointUrl: rpcUrl, retryReason: 'non_successful_http_status', rpcMethodName: 'eth_blockNumber', + duration: undefined, + traceId: undefined, }); }, ); @@ -929,6 +939,8 @@ describe('createNetworkClient - RPC endpoint events', () => { primaryEndpointUrl: rpcUrl, retryReason: 'non_successful_http_status', rpcMethodName: 'eth_blockNumber', + duration: undefined, + traceId: undefined, }); expect( rpcEndpointDegradedEventHandler, @@ -941,6 +953,8 @@ describe('createNetworkClient - RPC endpoint events', () => { primaryEndpointUrl: rpcUrl, retryReason: 'non_successful_http_status', rpcMethodName: 'eth_blockNumber', + duration: undefined, + traceId: undefined, }); expect( rpcEndpointDegradedEventHandler, @@ -952,6 +966,8 @@ describe('createNetworkClient - RPC endpoint events', () => { networkClientId: 'AAAA-AAAA-AAAA-AAAA', primaryEndpointUrl: rpcUrl, rpcMethodName: 'eth_blockNumber', + duration: expect.any(Number), + traceId: undefined, }); expect( rpcEndpointDegradedEventHandler, @@ -963,6 +979,8 @@ describe('createNetworkClient - RPC endpoint events', () => { networkClientId: 'AAAA-AAAA-AAAA-AAAA', primaryEndpointUrl: rpcUrl, rpcMethodName: 'eth_gasPrice', + duration: expect.any(Number), + traceId: undefined, }); }, ); @@ -1164,6 +1182,8 @@ describe('createNetworkClient - RPC endpoint events', () => { networkClientId: 'AAAA-AAAA-AAAA-AAAA', retryReason: 'non_successful_http_status', rpcMethodName: 'eth_blockNumber', + duration: undefined, + traceId: undefined, }); }, ); @@ -1242,6 +1262,8 @@ describe('createNetworkClient - RPC endpoint events', () => { error: undefined, networkClientId: 'AAAA-AAAA-AAAA-AAAA', rpcMethodName: 'eth_blockNumber', + duration: expect.any(Number), + traceId: undefined, }); }, ); @@ -1331,6 +1353,8 @@ describe('createNetworkClient - RPC endpoint events', () => { primaryEndpointUrl: rpcUrl, retryReason: 'non_successful_http_status', rpcMethodName: 'eth_blockNumber', + duration: undefined, + traceId: undefined, }); expect(rpcEndpointDegradedEventHandler).toHaveBeenCalledWith({ chainId, @@ -1341,6 +1365,8 @@ describe('createNetworkClient - RPC endpoint events', () => { primaryEndpointUrl: rpcUrl, retryReason: 'non_successful_http_status', rpcMethodName: 'eth_blockNumber', + duration: undefined, + traceId: undefined, }); }, ); @@ -1572,6 +1598,8 @@ describe('createNetworkClient - RPC endpoint events', () => { networkClientId: 'AAAA-AAAA-AAAA-AAAA', primaryEndpointUrl: rpcUrl, rpcMethodName: 'eth_blockNumber', + duration: expect.any(Number), + traceId: undefined, }); expect(rpcEndpointDegradedEventHandler).toHaveBeenCalledWith({ chainId, @@ -1581,6 +1609,8 @@ describe('createNetworkClient - RPC endpoint events', () => { networkClientId: 'AAAA-AAAA-AAAA-AAAA', primaryEndpointUrl: rpcUrl, rpcMethodName: 'eth_gasPrice', + duration: expect.any(Number), + traceId: undefined, }); }, ); diff --git a/packages/network-controller/src/create-network-client.ts b/packages/network-controller/src/create-network-client.ts index bac8cda2af9..5070d9eefcd 100644 --- a/packages/network-controller/src/create-network-client.ts +++ b/packages/network-controller/src/create-network-client.ts @@ -350,25 +350,32 @@ function createRpcServiceChain({ }, ); - rpcServiceChain.onDegraded(({ rpcMethodName, ...rest }) => { - const error = getError(rest); - const type: DegradedEventType = - error === undefined ? 'slow_success' : 'retries_exhausted'; - messenger.publish('NetworkController:rpcEndpointChainDegraded', { - chainId: configuration.chainId, - networkClientId: id, - error, - rpcMethodName, - type, - retryReason: error === undefined ? undefined : classifyRetryReason(error), - }); - }); + rpcServiceChain.onDegraded( + ({ rpcMethodName, duration, traceId, ...rest }) => { + const error = getError(rest); + const type: DegradedEventType = + error === undefined ? 'slow_success' : 'retries_exhausted'; + messenger.publish('NetworkController:rpcEndpointChainDegraded', { + chainId: configuration.chainId, + networkClientId: id, + error, + rpcMethodName, + duration, + traceId, + type, + retryReason: + error === undefined ? undefined : classifyRetryReason(error), + }); + }, + ); rpcServiceChain.onServiceDegraded( ({ endpointUrl, primaryEndpointUrl: primaryEndpointUrlFromEvent, rpcMethodName, + duration, + traceId, ...rest }) => { const error = getError(rest); @@ -382,6 +389,8 @@ function createRpcServiceChain({ endpointUrl, error, rpcMethodName, + duration, + traceId, type, retryReason: error === undefined ? undefined : classifyRetryReason(error), diff --git a/packages/network-controller/src/rpc-service/rpc-service-chain.test.ts b/packages/network-controller/src/rpc-service/rpc-service-chain.test.ts index bc62a3ee93f..5a8ffa37e87 100644 --- a/packages/network-controller/src/rpc-service/rpc-service-chain.test.ts +++ b/packages/network-controller/src/rpc-service/rpc-service-chain.test.ts @@ -1094,6 +1094,8 @@ describe('RpcServiceChain', () => { expect(onDegradedListener).toHaveBeenCalledWith({ error: expectedDegradedError, rpcMethodName: 'eth_chainId', + duration: undefined, + traceId: undefined, }); }); @@ -1141,6 +1143,8 @@ describe('RpcServiceChain', () => { expect(onDegradedListener).toHaveBeenCalledTimes(1); expect(onDegradedListener).toHaveBeenCalledWith({ rpcMethodName: 'eth_chainId', + duration: expect.any(Number), + traceId: undefined, }); }); @@ -1216,6 +1220,8 @@ describe('RpcServiceChain', () => { expect(onDegradedListener).toHaveBeenCalledWith({ error: expectedDegradedError, rpcMethodName: 'eth_chainId', + duration: undefined, + traceId: undefined, }); }); @@ -1284,6 +1290,8 @@ describe('RpcServiceChain', () => { expect(onDegradedListener).toHaveBeenCalledWith({ error: expectedDegradedError, rpcMethodName: 'eth_blockNumber', + duration: undefined, + traceId: undefined, }); }); @@ -1361,6 +1369,8 @@ describe('RpcServiceChain', () => { expect(onDegradedListener).toHaveBeenCalledWith({ error: expectedDegradedError, rpcMethodName: 'eth_chainId', + duration: undefined, + traceId: undefined, }); }); @@ -1434,9 +1444,13 @@ describe('RpcServiceChain', () => { expect(onDegradedListener).toHaveBeenNthCalledWith(1, { error: expectedDegradedError, rpcMethodName: 'eth_chainId', + duration: undefined, + traceId: undefined, }); expect(onDegradedListener).toHaveBeenNthCalledWith(2, { rpcMethodName: 'eth_chainId', + duration: expect.any(Number), + traceId: undefined, }); }); @@ -1535,9 +1549,13 @@ describe('RpcServiceChain', () => { expect(onDegradedListener).toHaveBeenNthCalledWith(1, { error: expectedDegradedError, rpcMethodName: 'eth_chainId', + duration: undefined, + traceId: undefined, }); expect(onDegradedListener).toHaveBeenNthCalledWith(2, { rpcMethodName: 'eth_chainId', + duration: expect.any(Number), + traceId: undefined, }); }); @@ -1594,12 +1612,16 @@ describe('RpcServiceChain', () => { endpointUrl: `${endpointUrl}/`, error: expectedDegradedError, rpcMethodName: 'eth_chainId', + duration: undefined, + traceId: undefined, }); expect(onServiceDegradedListener).toHaveBeenNthCalledWith(2, { primaryEndpointUrl: `${endpointUrl}/`, endpointUrl: `${endpointUrl}/`, error: expectedDegradedError, rpcMethodName: 'eth_chainId', + duration: undefined, + traceId: undefined, }); }); @@ -1649,11 +1671,15 @@ describe('RpcServiceChain', () => { primaryEndpointUrl: `${endpointUrl}/`, endpointUrl: `${endpointUrl}/`, rpcMethodName: 'eth_chainId', + duration: expect.any(Number), + traceId: undefined, }); expect(onServiceDegradedListener).toHaveBeenNthCalledWith(2, { primaryEndpointUrl: `${endpointUrl}/`, endpointUrl: `${endpointUrl}/`, rpcMethodName: 'eth_chainId', + duration: expect.any(Number), + traceId: undefined, }); }); @@ -1731,17 +1757,23 @@ describe('RpcServiceChain', () => { endpointUrl: `${endpointUrl}/`, error: expectedDegradedError, rpcMethodName: 'eth_chainId', + duration: undefined, + traceId: undefined, }); expect(onServiceDegradedListener).toHaveBeenNthCalledWith(2, { primaryEndpointUrl: `${endpointUrl}/`, endpointUrl: `${endpointUrl}/`, rpcMethodName: 'eth_chainId', + duration: expect.any(Number), + traceId: undefined, }); expect(onServiceDegradedListener).toHaveBeenNthCalledWith(3, { primaryEndpointUrl: `${endpointUrl}/`, endpointUrl: `${endpointUrl}/`, error: expectedDegradedError, rpcMethodName: 'eth_chainId', + duration: undefined, + traceId: undefined, }); }); @@ -1821,17 +1853,23 @@ describe('RpcServiceChain', () => { endpointUrl: `${primaryEndpointUrl}/`, error: expectedDegradedError, rpcMethodName: 'eth_chainId', + duration: undefined, + traceId: undefined, }); expect(onServiceDegradedListener).toHaveBeenNthCalledWith(2, { primaryEndpointUrl: `${primaryEndpointUrl}/`, endpointUrl: `${primaryEndpointUrl}/`, error: expectedDegradedError, rpcMethodName: 'eth_chainId', + duration: undefined, + traceId: undefined, }); expect(onServiceDegradedListener).toHaveBeenNthCalledWith(3, { primaryEndpointUrl: `${primaryEndpointUrl}/`, endpointUrl: `${secondaryEndpointUrl}/`, rpcMethodName: 'eth_chainId', + duration: expect.any(Number), + traceId: undefined, }); }); @@ -1907,17 +1945,23 @@ describe('RpcServiceChain', () => { endpointUrl: `${endpointUrl}/`, error: expectedDegradedError, rpcMethodName: 'eth_chainId', + duration: undefined, + traceId: undefined, }); expect(onServiceDegradedListener).toHaveBeenNthCalledWith(2, { primaryEndpointUrl: `${endpointUrl}/`, endpointUrl: `${endpointUrl}/`, error: expectedDegradedError, rpcMethodName: 'eth_chainId', + duration: undefined, + traceId: undefined, }); expect(onServiceDegradedListener).toHaveBeenNthCalledWith(3, { primaryEndpointUrl: `${endpointUrl}/`, endpointUrl: `${endpointUrl}/`, rpcMethodName: 'eth_chainId', + duration: expect.any(Number), + traceId: undefined, }); }); @@ -2018,29 +2062,135 @@ describe('RpcServiceChain', () => { endpointUrl: `${primaryEndpointUrl}/`, error: expectedDegradedError, rpcMethodName: 'eth_chainId', + duration: undefined, + traceId: undefined, }); expect(onServiceDegradedListener).toHaveBeenNthCalledWith(2, { primaryEndpointUrl: `${primaryEndpointUrl}/`, endpointUrl: `${primaryEndpointUrl}/`, error: expectedDegradedError, rpcMethodName: 'eth_chainId', + duration: undefined, + traceId: undefined, }); expect(onServiceDegradedListener).toHaveBeenNthCalledWith(3, { primaryEndpointUrl: `${primaryEndpointUrl}/`, endpointUrl: `${secondaryEndpointUrl}/`, error: expectedDegradedError, rpcMethodName: 'eth_chainId', + duration: undefined, + traceId: undefined, }); expect(onServiceDegradedListener).toHaveBeenNthCalledWith(4, { primaryEndpointUrl: `${primaryEndpointUrl}/`, endpointUrl: `${secondaryEndpointUrl}/`, error: expectedDegradedError, rpcMethodName: 'eth_chainId', + duration: undefined, + traceId: undefined, }); expect(onServiceDegradedListener).toHaveBeenNthCalledWith(5, { primaryEndpointUrl: `${primaryEndpointUrl}/`, endpointUrl: `${primaryEndpointUrl}/`, rpcMethodName: 'eth_chainId', + duration: expect.any(Number), + traceId: undefined, + }); + }); + + it('forwards duration and traceId from the underlying service via onDegraded', async () => { + const endpointUrl = 'https://some.endpoint'; + nock(endpointUrl) + .post('/', { + id: 1, + jsonrpc: '2.0', + method: 'eth_chainId', + params: [], + }) + .reply( + 200, + () => { + jest.advanceTimersByTime(DEFAULT_DEGRADED_THRESHOLD + 1); + return { + id: 1, + jsonrpc: '2.0', + result: '0x1', + }; + }, + { 'x-trace-id': 'some-trace' }, + ); + const rpcServiceChain = new RpcServiceChain([ + { + fetch, + btoa, + isOffline: (): boolean => false, + endpointUrl, + }, + ]); + const onDegradedListener = jest.fn(); + rpcServiceChain.onDegraded(onDegradedListener); + + await rpcServiceChain.request({ + id: 1, + jsonrpc: '2.0' as const, + method: 'eth_chainId', + params: [], + }); + + expect(onDegradedListener).toHaveBeenCalledTimes(1); + expect(onDegradedListener).toHaveBeenCalledWith({ + rpcMethodName: 'eth_chainId', + duration: expect.any(Number), + traceId: 'some-trace', + }); + }); + + it('forwards duration and traceId from the underlying service via onServiceDegraded', async () => { + const endpointUrl = 'https://some.endpoint'; + nock(endpointUrl) + .post('/', { + id: 1, + jsonrpc: '2.0', + method: 'eth_chainId', + params: [], + }) + .reply( + 200, + () => { + jest.advanceTimersByTime(DEFAULT_DEGRADED_THRESHOLD + 1); + return { + id: 1, + jsonrpc: '2.0', + result: '0x1', + }; + }, + { 'x-trace-id': 'some-trace' }, + ); + const rpcServiceChain = new RpcServiceChain([ + { + fetch, + btoa, + isOffline: (): boolean => false, + endpointUrl, + }, + ]); + const onServiceDegradedListener = jest.fn(); + rpcServiceChain.onServiceDegraded(onServiceDegradedListener); + + await rpcServiceChain.request({ + id: 1, + jsonrpc: '2.0' as const, + method: 'eth_chainId', + params: [], + }); + + expect(onServiceDegradedListener).toHaveBeenCalledTimes(1); + expect(onServiceDegradedListener).toHaveBeenCalledWith({ + primaryEndpointUrl: `${endpointUrl}/`, + endpointUrl: `${endpointUrl}/`, + rpcMethodName: 'eth_chainId', + duration: expect.any(Number), + traceId: 'some-trace', }); }); @@ -2213,6 +2363,8 @@ describe('RpcServiceChain', () => { expect(onDegradedListener).toHaveBeenCalledTimes(1); expect(onDegradedListener).toHaveBeenCalledWith({ rpcMethodName: 'eth_chainId', + duration: expect.any(Number), + traceId: undefined, }); // Verify recovery occurred after the second (fast) request diff --git a/packages/network-controller/src/rpc-service/rpc-service.test.ts b/packages/network-controller/src/rpc-service/rpc-service.test.ts index 5b65bd853a2..c548eb09906 100644 --- a/packages/network-controller/src/rpc-service/rpc-service.test.ts +++ b/packages/network-controller/src/rpc-service/rpc-service.test.ts @@ -1,4 +1,5 @@ import { + ConstantBackoff, DEFAULT_CIRCUIT_BREAK_DURATION, DEFAULT_DEGRADED_THRESHOLD, HttpError, @@ -1030,6 +1031,8 @@ describe('RpcService', () => { expect(onDegradedListener).toHaveBeenCalledWith({ endpointUrl: `${endpointUrl}/`, rpcMethodName: 'eth_chainId', + duration: expect.any(Number), + traceId: undefined, }); }); @@ -1094,10 +1097,14 @@ describe('RpcService', () => { expect(onDegradedListener).toHaveBeenCalledWith({ endpointUrl: `${endpointUrl}/`, rpcMethodName: 'eth_blockNumber', + duration: expect.any(Number), + traceId: undefined, }); expect(onDegradedListener).toHaveBeenCalledWith({ endpointUrl: `${endpointUrl}/`, rpcMethodName: 'eth_gasPrice', + duration: expect.any(Number), + traceId: undefined, }); }); @@ -1172,6 +1179,235 @@ describe('RpcService', () => { ); }); + it('forwards the x-trace-id response header as traceId in the slow-success case', async () => { + const endpointUrl = 'https://rpc.example.chain'; + nock(endpointUrl) + .post('/', { + id: 1, + jsonrpc: '2.0', + method: 'eth_chainId', + params: [], + }) + .reply( + 200, + () => { + jest.advanceTimersByTime(DEFAULT_DEGRADED_THRESHOLD + 1); + return { + id: 1, + jsonrpc: '2.0', + result: '0x1', + }; + }, + { 'x-trace-id': 'abc-123-trace' }, + ); + const onDegradedListener = jest.fn(); + const service = new RpcService({ + fetch, + btoa, + endpointUrl, + isOffline: (): boolean => false, + }); + service.onDegraded(onDegradedListener); + + await service.request({ + id: 1, + jsonrpc: '2.0', + method: 'eth_chainId', + params: [], + }); + + expect(onDegradedListener).toHaveBeenCalledTimes(1); + expect(onDegradedListener).toHaveBeenCalledWith( + expect.objectContaining({ + traceId: 'abc-123-trace', + duration: expect.any(Number), + }), + ); + }); + + it('forwards traceId as undefined when the x-trace-id response header is missing', async () => { + const endpointUrl = 'https://rpc.example.chain'; + nock(endpointUrl) + .post('/', { + id: 1, + jsonrpc: '2.0', + method: 'eth_chainId', + params: [], + }) + .reply(200, () => { + jest.advanceTimersByTime(DEFAULT_DEGRADED_THRESHOLD + 1); + return { + id: 1, + jsonrpc: '2.0', + result: '0x1', + }; + }); + const onDegradedListener = jest.fn(); + const service = new RpcService({ + fetch, + btoa, + endpointUrl, + isOffline: (): boolean => false, + }); + service.onDegraded(onDegradedListener); + + await service.request({ + id: 1, + jsonrpc: '2.0', + method: 'eth_chainId', + params: [], + }); + + expect(onDegradedListener).toHaveBeenCalledTimes(1); + expect(onDegradedListener).toHaveBeenCalledWith( + expect.objectContaining({ traceId: undefined }), + ); + }); + + it('forwards the traceId from the last retry attempt when retries are exhausted', async () => { + const endpointUrl = 'https://rpc.example.chain'; + for (let i = 0; i < DEFAULT_MAX_RETRIES; i++) { + nock(endpointUrl) + .post('/', { + id: 1, + jsonrpc: '2.0', + method: 'eth_chainId', + params: [], + }) + .reply(503, '', { 'x-trace-id': `trace-attempt-${i}` }); + } + // Last attempt + nock(endpointUrl) + .post('/', { + id: 1, + jsonrpc: '2.0', + method: 'eth_chainId', + params: [], + }) + .reply(503, '', { 'x-trace-id': 'trace-last-attempt' }); + const onDegradedListener = jest.fn(); + const service = new RpcService({ + fetch, + btoa, + endpointUrl, + policyOptions: { + backoff: new ConstantBackoff(0), + }, + isOffline: (): boolean => false, + }); + service.onRetry(() => { + jest.advanceTimersToNextTimer(); + }); + service.onDegraded(onDegradedListener); + + await ignoreRejection( + service.request({ + id: 1, + jsonrpc: '2.0', + method: 'eth_chainId', + params: [], + }), + ); + + expect(onDegradedListener).toHaveBeenCalledTimes(1); + expect(onDegradedListener).toHaveBeenCalledWith( + expect.objectContaining({ traceId: 'trace-last-attempt' }), + ); + }); + + it('does not leak a stale traceId when the last retry attempt throws before receiving a response', async () => { + const endpointUrl = 'https://rpc.example.chain'; + // First attempts return 503 with a trace ID header + for (let i = 0; i < DEFAULT_MAX_RETRIES; i++) { + nock(endpointUrl) + .post('/', { + id: 1, + jsonrpc: '2.0', + method: 'eth_chainId', + params: [], + }) + .reply(503, '', { 'x-trace-id': `trace-attempt-${i}` }); + } + // Last attempt throws a network error before a response is received + nock(endpointUrl) + .post('/', { + id: 1, + jsonrpc: '2.0', + method: 'eth_chainId', + params: [], + }) + .replyWithError('Connection refused'); + const onDegradedListener = jest.fn(); + const service = new RpcService({ + fetch, + btoa, + endpointUrl, + policyOptions: { + backoff: new ConstantBackoff(0), + }, + isOffline: (): boolean => false, + }); + service.onRetry(() => { + jest.advanceTimersToNextTimer(); + }); + service.onDegraded(onDegradedListener); + + await ignoreRejection( + service.request({ + id: 1, + jsonrpc: '2.0', + method: 'eth_chainId', + params: [], + }), + ); + + expect(onDegradedListener).toHaveBeenCalledTimes(1); + expect(onDegradedListener).toHaveBeenCalledWith( + expect.objectContaining({ traceId: undefined }), + ); + }); + + it('forwards duration as undefined in the retries-exhausted case', async () => { + const endpointUrl = 'https://rpc.example.chain'; + nock(endpointUrl) + .post('/', { + id: 1, + jsonrpc: '2.0', + method: 'eth_chainId', + params: [], + }) + .times(DEFAULT_MAX_RETRIES + 1) + .reply(503); + const onDegradedListener = jest.fn(); + const service = new RpcService({ + fetch, + btoa, + endpointUrl, + policyOptions: { + backoff: new ConstantBackoff(0), + }, + isOffline: (): boolean => false, + }); + service.onRetry(() => { + jest.advanceTimersToNextTimer(); + }); + service.onDegraded(onDegradedListener); + + await ignoreRejection( + service.request({ + id: 1, + jsonrpc: '2.0', + method: 'eth_chainId', + params: [], + }), + ); + + expect(onDegradedListener).toHaveBeenCalledTimes(1); + expect(onDegradedListener).toHaveBeenCalledWith( + expect.objectContaining({ duration: undefined }), + ); + }); + it('calls the onAvailable callback the first time a successful request occurs', async () => { const endpointUrl = 'https://rpc.example.chain'; nock(endpointUrl) @@ -1494,6 +1730,8 @@ function testsForRetriableFetchErrors({ endpointUrl: `${endpointUrl}/`, error: expectedError, rpcMethodName: 'eth_chainId', + duration: undefined, + traceId: undefined, }); }); diff --git a/packages/network-controller/src/rpc-service/rpc-service.ts b/packages/network-controller/src/rpc-service/rpc-service.ts index 17b6f85aa3e..90c405c6a20 100644 --- a/packages/network-controller/src/rpc-service/rpc-service.ts +++ b/packages/network-controller/src/rpc-service/rpc-service.ts @@ -302,6 +302,15 @@ export class RpcService { */ #currentRpcMethodName = ''; + /** + * The trace ID from the `x-trace-id` response header of the most recent + * request. Passed to `onDegraded` event listeners for debugging. + * + * `undefined` when no response has been received yet or when the response + * did not include the header. + */ + #currentTraceId: string | undefined; + /** * The function used to make an HTTP request. */ @@ -462,22 +471,21 @@ export class RpcService { onDegraded( listener: CockatielEventToEventListenerWithData< ServicePolicy['onDegraded'], - { endpointUrl: string; rpcMethodName: string } + { + duration?: number; + endpointUrl: string; + rpcMethodName: string; + traceId?: string; + } >, ): ReturnType { return this.#policy.onDegraded((data) => { - if (data === undefined) { - listener({ - endpointUrl: this.endpointUrl.toString(), - rpcMethodName: this.#currentRpcMethodName, - }); - } else { - listener({ - ...data, - endpointUrl: this.endpointUrl.toString(), - rpcMethodName: this.#currentRpcMethodName, - }); - } + listener({ + ...data, + endpointUrl: this.endpointUrl.toString(), + rpcMethodName: this.#currentRpcMethodName, + traceId: this.#currentTraceId, + }); }); } @@ -645,6 +653,10 @@ export class RpcService { ); const jsonDecodedResponse = await this.#policy.execute( async (context) => { + // Reset response so that if this attempt throws before + // assigning a new response, the finally block does not read + // a stale response from a previous attempt. + response = undefined; try { log( 'REQUEST INITIATED:', @@ -666,21 +678,24 @@ export class RpcService { ); return await response.json(); } finally { - // Track the RPC method for the request that has just taken place. - // We pass this property to `onDegraded` event listeners. + // Track the RPC method and trace ID for the request that has just + // taken place. We pass these properties to `onDegraded` event + // listeners. // - // We set this property after the request completes and not before - // the request starts to account for race conditions. That is, if - // there are two requests that are being performed concurrently, and - // the second request fails fast but the first request succeeds - // slowly, when `onDegraded` is called we want it to include the - // first request as the RPC method, not the second. + // We set these properties after the request completes and not + // before the request starts to account for race conditions. That + // is, if there are two requests that are being performed + // concurrently, and the second request fails fast but the first + // request succeeds slowly, when `onDegraded` is called we want it + // to include the first request as the RPC method, not the second. // - // Also, we set this property within a `finally` block inside of the - // function passed to `policy.execute` to ensure that it is set - // before `onDegraded` gets called, no matter the outcome of the - // request. + // Also, we set these properties within a `finally` block inside of + // the function passed to `policy.execute` to ensure that they are + // set before `onDegraded` gets called, no matter the outcome of + // the request. this.#currentRpcMethodName = rpcMethodName; + this.#currentTraceId = + response?.headers.get('x-trace-id') ?? undefined; } }, );