From a4f810d67d35275aea55c784d4119a5d89b26f46 Mon Sep 17 00:00:00 2001 From: Nicholas Gambino Date: Wed, 3 Jun 2026 15:03:20 -0700 Subject: [PATCH] refactor: dedupe sentry trace --- packages/perps-controller/CHANGELOG.md | 12 ++ .../src/constants/perpsConfig.ts | 3 + .../src/services/TradingService.ts | 65 +++++- packages/perps-controller/src/types/index.ts | 1 - .../TradingService.placeOrder.timeout.test.ts | 192 ++++++++++++++++++ 5 files changed, 268 insertions(+), 5 deletions(-) create mode 100644 packages/perps-controller/tests/src/services/TradingService.placeOrder.timeout.test.ts diff --git a/packages/perps-controller/CHANGELOG.md b/packages/perps-controller/CHANGELOG.md index 8af2f9c01a..e5fa4fe0b8 100644 --- a/packages/perps-controller/CHANGELOG.md +++ b/packages/perps-controller/CHANGELOG.md @@ -7,6 +7,18 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +### Added + +- Add observational hard timeout for order submission: tag the `Perps Order Submission` trace and emit a breadcrumb when a provider round-trip exceeds `PlaceOrderTimeoutMs` (60s), without cancelling the in-flight order ([#NNNN](https://github.com/MetaMask/core/pull/NNNN)) + +### Changed + +- Surface late order completions via trace `reason: 'late_success' | 'late_error'` ([#NNNN](https://github.com/MetaMask/core/pull/NNNN)) + +### Removed + +- Remove unused `Perps Order Submission Toast` trace name from the `PerpsTraceName` union ([#NNNN](https://github.com/MetaMask/core/pull/NNNN)) + ## [7.0.0] ### Added diff --git a/packages/perps-controller/src/constants/perpsConfig.ts b/packages/perps-controller/src/constants/perpsConfig.ts index bf6471b78a..73e85b3be9 100644 --- a/packages/perps-controller/src/constants/perpsConfig.ts +++ b/packages/perps-controller/src/constants/perpsConfig.ts @@ -41,6 +41,9 @@ export const PERPS_CONSTANTS = { BalanceUpdateThrottleMs: 15000, // Update at most every 15 seconds to reduce state updates in PerpsConnectionManager InitialDataDelayMs: 100, // Delay to allow initial data to load after connection establishment + // Order submission timing + PlaceOrderTimeoutMs: 60_000, // Hard timeout for provider round-trip in TradingService.placeOrder + // Deposit toast timing DepositTakingLongerToastDelayMs: 30_000, // Delay before showing "Deposit taking longer than usual" toast diff --git a/packages/perps-controller/src/services/TradingService.ts b/packages/perps-controller/src/services/TradingService.ts index 200d6a4d47..f54651a238 100644 --- a/packages/perps-controller/src/services/TradingService.ts +++ b/packages/perps-controller/src/services/TradingService.ts @@ -377,8 +377,17 @@ export class TradingService { const traceId = uuidv4(); const startTime = this.#deps.performance.now(); let traceData: - | { success: boolean; error?: string; orderId?: string } + | { + success: boolean; + error?: string; + orderId?: string; + reason?: 'error' | 'late_success' | 'late_error'; + } + | undefined; + let orderSubmissionThresholdTimeoutId: + | ReturnType | undefined; + let didExceedOrderSubmissionThreshold = false; const paymentToken = params.trackingData?.tradeWithToken === true @@ -438,17 +447,51 @@ export class TradingService { }, ); - // Execute order with fee discount management + // Observational threshold: when the provider round-trip exceeds + // PlaceOrderTimeoutMs we tag the trace and emit a breadcrumb, but we + // intentionally do NOT cancel the in-flight order. Cancelling client-side + // (e.g. Promise.race rejection) does not stop the provider request, so a + // race-based timeout would let the UI mark an order as failed while + // HyperLiquid could still accept it. Instead, we always await + // provider.placeOrder(params) to terminal completion and surface + // late completions via trace `reason: 'late_success' | 'late_error'`. + orderSubmissionThresholdTimeoutId = setTimeout(() => { + didExceedOrderSubmissionThreshold = true; + this.#deps.tracer.addBreadcrumb({ + category: 'perps', + message: 'Order submission exceeded threshold (still pending)', + level: 'warning', + data: { + thresholdMs: PERPS_CONSTANTS.PlaceOrderTimeoutMs, + payment_token: paymentToken, + market: params.symbol, + orderType: params.orderType, + }, + }); + this.#deps.debugLogger.log( + 'TradingService: Order submission exceeded threshold (still pending)', + { + thresholdMs: PERPS_CONSTANTS.PlaceOrderTimeoutMs, + symbol: params.symbol, + orderType: params.orderType, + }, + ); + }, PERPS_CONSTANTS.PlaceOrderTimeoutMs); const result = await this.#withFeeDiscount({ provider, feeDiscountBips, operation: () => provider.placeOrder(params), }); + if (orderSubmissionThresholdTimeoutId !== undefined) { + clearTimeout(orderSubmissionThresholdTimeoutId); + orderSubmissionThresholdTimeoutId = undefined; + } this.#deps.debugLogger.log('TradingService: Provider response received', { success: result.success, orderId: result.orderId, error: result.error, + didExceedOrderSubmissionThreshold, }); // Update state and handle success/failure @@ -461,13 +504,23 @@ export class TradingService { context, reportOrderToDataLake, }); - traceData = { success: true, orderId: result.orderId ?? '' }; + traceData = { + success: true, + orderId: result.orderId ?? '', + ...(didExceedOrderSubmissionThreshold + ? { reason: 'late_success' as const } + : {}), + }; // Invalidate standalone caches so external hooks (e.g., usePerpsPositionForAsset) refresh this.#deps.cacheInvalidator.invalidate({ cacheType: 'positions' }); this.#deps.cacheInvalidator.invalidate({ cacheType: 'accountState' }); } else { - traceData = { success: false, error: result.error ?? 'Unknown error' }; + traceData = { + success: false, + reason: didExceedOrderSubmissionThreshold ? 'late_error' : 'error', + error: result.error ?? 'Unknown error', + }; } // Track analytics (success or failure) @@ -511,10 +564,14 @@ export class TradingService { traceData = { success: false, + reason: didExceedOrderSubmissionThreshold ? 'late_error' : 'error', error: error instanceof Error ? error.message : 'Unknown error', }; throw error; } finally { + if (orderSubmissionThresholdTimeoutId !== undefined) { + clearTimeout(orderSubmissionThresholdTimeoutId); + } // Always end trace on exit (success or failure) this.#deps.tracer.endTrace({ name: PerpsTraceNames.PlaceOrder, diff --git a/packages/perps-controller/src/types/index.ts b/packages/perps-controller/src/types/index.ts index f9402d5bce..cce83fa1bf 100644 --- a/packages/perps-controller/src/types/index.ts +++ b/packages/perps-controller/src/types/index.ts @@ -1341,7 +1341,6 @@ export type PerpsTraceName = | 'Perps Update TP/SL' | 'Perps Update Margin' | 'Perps Flip Position' - | 'Perps Order Submission Toast' | 'Perps Market Data Update' | 'Perps Order View' | 'Perps Tab View' diff --git a/packages/perps-controller/tests/src/services/TradingService.placeOrder.timeout.test.ts b/packages/perps-controller/tests/src/services/TradingService.placeOrder.timeout.test.ts new file mode 100644 index 0000000000..b25efeede4 --- /dev/null +++ b/packages/perps-controller/tests/src/services/TradingService.placeOrder.timeout.test.ts @@ -0,0 +1,192 @@ +/* eslint-disable */ +import { PERPS_CONSTANTS } from '../../../src/constants/perpsConfig'; +import { TradingService } from '../../../src/services/TradingService'; +import type { + OrderParams, + OrderResult, + PerpsProvider, + PerpsPlatformDependencies, +} from '../../../src/types'; +import { createMockHyperLiquidProvider } from '../../helpers/providerMocks'; +import { + createMockInfrastructure, + createMockServiceContext, + createMockPerpsControllerState, +} from '../../helpers/serviceMocks'; + +jest.mock('uuid', () => ({ v4: () => 'mock-trace-id' })); + +describe('TradingService.placeOrder — order submission timeout', () => { + let tradingService: TradingService; + let mockDeps: jest.Mocked; + let mockProvider: jest.Mocked; + let mockRewardsService: { calculateUserFeeDiscount: jest.Mock }; + let mockContext: ReturnType; + let mockReportOrderToDataLake: jest.Mock; + + const baseOrderParams: OrderParams = { + symbol: 'BTC', + isBuy: true, + size: '0.1', + orderType: 'market', + }; + + beforeEach(() => { + jest.useFakeTimers(); + mockDeps = createMockInfrastructure(); + tradingService = new TradingService(mockDeps); + mockRewardsService = { + calculateUserFeeDiscount: jest.fn().mockResolvedValue(undefined), + }; + tradingService.setControllerDependencies({ + rewardsIntegrationService: mockRewardsService as never, + }); + mockProvider = + createMockHyperLiquidProvider() as unknown as jest.Mocked; + mockContext = createMockServiceContext({ + errorContext: { controller: 'TradingService', method: 'test' }, + stateManager: { + update: jest.fn(), + getState: jest.fn(() => createMockPerpsControllerState()), + }, + }); + mockReportOrderToDataLake = jest.fn().mockResolvedValue({ success: true }); + }); + + afterEach(() => { + jest.useRealTimers(); + jest.clearAllMocks(); + }); + + it('emits no threshold breadcrumb and leaves reason undefined when provider resolves before threshold', async () => { + const mockResult: OrderResult = { + success: true, + orderId: 'order-123', + filledSize: '0.1', + averagePrice: '50000', + }; + mockProvider.placeOrder.mockResolvedValue(mockResult); + + await tradingService.placeOrder({ + provider: mockProvider, + params: baseOrderParams, + context: mockContext, + reportOrderToDataLake: mockReportOrderToDataLake, + }); + + expect(mockDeps.tracer.addBreadcrumb).not.toHaveBeenCalledWith( + expect.objectContaining({ + message: 'Order submission exceeded threshold (still pending)', + }), + ); + + const endTraceArgs = (mockDeps.tracer.endTrace as jest.Mock).mock + .calls[0][0]; + expect(endTraceArgs.data?.reason).toBeUndefined(); + expect(jest.getTimerCount()).toBe(0); + }); + + it('emits breadcrumb exactly once and sets reason: late_success when provider resolves after threshold', async () => { + let resolveOrder!: (result: OrderResult) => void; + const slowOrder = new Promise((resolve) => { + resolveOrder = resolve; + }); + mockProvider.placeOrder.mockReturnValue(slowOrder); + + const placeOrderPromise = tradingService.placeOrder({ + provider: mockProvider, + params: baseOrderParams, + context: mockContext, + reportOrderToDataLake: mockReportOrderToDataLake, + }); + + // Advance past the threshold, allowing microtasks (fee discount await) to run first + await jest.advanceTimersByTimeAsync( + PERPS_CONSTANTS.PlaceOrderTimeoutMs + 1, + ); + + expect(mockDeps.tracer.addBreadcrumb).toHaveBeenCalledWith( + expect.objectContaining({ + message: 'Order submission exceeded threshold (still pending)', + level: 'warning', + category: 'perps', + data: expect.objectContaining({ + thresholdMs: PERPS_CONSTANTS.PlaceOrderTimeoutMs, + }), + }), + ); + // Exactly one threshold breadcrumb (plus the 'Order execution started' breadcrumb = 2 total) + const thresholdCalls = ( + mockDeps.tracer.addBreadcrumb as jest.Mock + ).mock.calls.filter( + ([args]: [{ message: string }]) => + args.message === 'Order submission exceeded threshold (still pending)', + ); + expect(thresholdCalls).toHaveLength(1); + + // Resolve the provider after the threshold fired + resolveOrder({ + success: true, + orderId: 'order-456', + filledSize: '0.1', + averagePrice: '50000', + }); + await placeOrderPromise; + + const endTraceArgs = (mockDeps.tracer.endTrace as jest.Mock).mock + .calls[0][0]; + expect(endTraceArgs.data?.reason).toBe('late_success'); + expect(jest.getTimerCount()).toBe(0); + }); + + it('sets reason: late_error and rethrows the original error when provider rejects after threshold', async () => { + let rejectOrder!: (error: Error) => void; + const slowOrder = new Promise((_, reject) => { + rejectOrder = reject; + }); + mockProvider.placeOrder.mockReturnValue(slowOrder); + + const placeOrderPromise = tradingService.placeOrder({ + provider: mockProvider, + params: baseOrderParams, + context: mockContext, + reportOrderToDataLake: mockReportOrderToDataLake, + }); + + await jest.advanceTimersByTimeAsync( + PERPS_CONSTANTS.PlaceOrderTimeoutMs + 1, + ); + + const originalError = new Error('Provider connection timed out'); + rejectOrder(originalError); + + await expect(placeOrderPromise).rejects.toThrow( + 'Provider connection timed out', + ); + + const endTraceArgs = (mockDeps.tracer.endTrace as jest.Mock).mock + .calls[0][0]; + expect(endTraceArgs.data?.reason).toBe('late_error'); + expect(endTraceArgs.data?.success).toBe(false); + expect(jest.getTimerCount()).toBe(0); + }); + + it('leaves no pending timers when the provider rejects before the threshold', async () => { + mockProvider.placeOrder.mockRejectedValue(new Error('immediate failure')); + + await expect( + tradingService.placeOrder({ + provider: mockProvider, + params: baseOrderParams, + context: mockContext, + reportOrderToDataLake: mockReportOrderToDataLake, + }), + ).rejects.toThrow('immediate failure'); + + expect(jest.getTimerCount()).toBe(0); + + const endTraceArgs = (mockDeps.tracer.endTrace as jest.Mock).mock + .calls[0][0]; + expect(endTraceArgs.data?.reason).toBe('error'); + }); +});