diff --git a/src/libs/Network/SequentialQueue.ts b/src/libs/Network/SequentialQueue.ts index 43e16066489b..2a90a05e12ca 100644 --- a/src/libs/Network/SequentialQueue.ts +++ b/src/libs/Network/SequentialQueue.ts @@ -47,6 +47,7 @@ type RequestError = Error & { message?: string; status?: string; }; +type RequestWithLegacyID = AnyRequest & {requestID?: number}; let resolveIsReadyPromise: (() => void) | undefined; let isReadyPromise: Promise = Promise.resolve(); @@ -74,8 +75,39 @@ function setIsReadyPromisePending() { let isSequentialQueueRunning = false; let currentRequestPromise: Promise | null = null; let isQueuePaused = false; +let clearActiveLoadingQueueWedgedTimer: (() => void) | undefined; const sequentialQueueRequestThrottle = new RequestThrottle('SequentialQueue'); +function clearLoadingQueueWedgedTimer() { + clearActiveLoadingQueueWedgedTimer?.(); +} + +function startLoadingQueueWedgedTimer(requestToProcess: RequestWithLegacyID) { + clearLoadingQueueWedgedTimer(); + const startedAt = Date.now(); + const timer = setTimeout(() => { + if (clearActiveLoadingQueueWedgedTimer === clearTimer) { + clearActiveLoadingQueueWedgedTimer = undefined; + } + Log.info('loading_queue_wedged', true, { + command: requestToProcess.command, + requestIndex: requestToProcess.requestIndex ?? requestToProcess.requestID, + elapsedTime: Date.now() - startedAt, + queueLength: getAllPersistedRequests().length + 1, + isOffline: isOfflineNetwork(), + isPaused: isQueuePaused, + }); + }, CONST.TELEMETRY.CONFIG.SKELETON_MIN_DURATION); + function clearTimer() { + clearTimeout(timer); + if (clearActiveLoadingQueueWedgedTimer === clearTimer) { + clearActiveLoadingQueueWedgedTimer = undefined; + } + } + clearActiveLoadingQueueWedgedTimer = clearTimer; + return clearTimer; +} + /** * Puts the queue into a paused state so that no requests will be processed */ @@ -181,7 +213,16 @@ function process(): Promise { }); // Set the current request to a promise awaiting its processing so that getCurrentRequest can be used to take some action after the current request has processed. - currentRequestPromise = processWithMiddleware(requestToProcess, true) + const clearRequestLoadingQueueWedgedTimer = startLoadingQueueWedgedTimer(requestToProcess); + let requestProcessingPromise: ReturnType; + try { + requestProcessingPromise = processWithMiddleware(requestToProcess, true); + } catch (error) { + clearRequestLoadingQueueWedgedTimer(); + throw error; + } + currentRequestPromise = requestProcessingPromise + .finally(clearRequestLoadingQueueWedgedTimer) .then((response) => { Log.info('[SequentialQueue] Request processed successfully', false, { command: requestToProcess.command, @@ -659,6 +700,7 @@ function waitForIdle(): Promise { * This is to prevent previous requests interfering with other tests */ function resetQueue(): void { + clearLoadingQueueWedgedTimer(); isSequentialQueueRunning = false; currentRequestPromise = null; isQueuePaused = false; diff --git a/tests/unit/SequentialQueueTest.ts b/tests/unit/SequentialQueueTest.ts index c434deb10852..79433603f2d0 100644 --- a/tests/unit/SequentialQueueTest.ts +++ b/tests/unit/SequentialQueueTest.ts @@ -1,4 +1,5 @@ import {resolveDuplicationConflictAction, resolveReconnectDuplicationConflictAction} from '@libs/actions/RequestConflictUtils'; +import Log from '@libs/Log'; import * as NetworkState from '@libs/NetworkState'; import {clear as clearPersistedRequests, getAll, getLength, getOngoingRequest, updateOngoingRequest} from '@userActions/PersistedRequests'; @@ -409,6 +410,197 @@ describe('SequentialQueue', () => { }); }); +describe('SequentialQueue loading queue diagnostics', () => { + const requestIndex = 123; + let logSpy: jest.SpyInstance>; + let processSpy: jest.SpyInstance; + + function createPendingAttempt() { + let resolve!: () => void; + let reject!: (error: Error) => void; + const promise = new Promise((promiseResolve, promiseReject) => { + resolve = promiseResolve; + reject = promiseReject; + }); + return {promise, reject, resolve}; + } + + function getWedgedLogs() { + return logSpy.mock.calls.filter(([message]) => message === 'loading_queue_wedged'); + } + + async function startAttempt() { + const attempt = createPendingAttempt(); + processSpy.mockReturnValueOnce(attempt.promise); + await SequentialQueue.push({command: 'ReconnectApp', requestIndex}); + await jest.advanceTimersByTimeAsync(0); + expect(processSpy).toHaveBeenCalledTimes(1); + return attempt; + } + + beforeEach(async () => { + SequentialQueue.resetQueue(); + SequentialQueue.sequentialQueueRequestThrottle.clear(); + await Onyx.set(ONYXKEYS.NETWORK, {shouldFailAllRequests: false, shouldForceOffline: false}); + await clearPersistedRequests(); + await waitForBatchedUpdates(); + jest.useFakeTimers(); + logSpy = jest.spyOn(Log, 'info'); + processSpy = jest.spyOn(RequestModule, 'processWithMiddleware'); + }); + + afterEach(() => { + jest.clearAllTimers(); + jest.useRealTimers(); + jest.restoreAllMocks(); + SequentialQueue.resetQueue(); + SequentialQueue.sequentialQueueRequestThrottle.clear(); + }); + + it('does not log below the threshold and clears the timer after success', async () => { + const attempt = await startAttempt(); + + jest.advanceTimersByTime(CONST.TELEMETRY.CONFIG.SKELETON_MIN_DURATION - 1); + expect(getWedgedLogs()).toHaveLength(0); + + attempt.resolve(); + await SequentialQueue.waitForIdle(); + jest.advanceTimersByTime(CONST.TELEMETRY.CONFIG.SKELETON_MIN_DURATION); + + expect(getWedgedLogs()).toHaveLength(0); + }); + + it('logs one diagnostic after the threshold for an active request', async () => { + const attempt = await startAttempt(); + + jest.advanceTimersByTime(CONST.TELEMETRY.CONFIG.SKELETON_MIN_DURATION); + + expect(getWedgedLogs()).toEqual([ + [ + 'loading_queue_wedged', + true, + { + command: 'ReconnectApp', + requestIndex, + elapsedTime: CONST.TELEMETRY.CONFIG.SKELETON_MIN_DURATION, + queueLength: 1, + isOffline: false, + isPaused: false, + }, + ], + ]); + + jest.advanceTimersByTime(CONST.TELEMETRY.CONFIG.SKELETON_MIN_DURATION); + expect(getWedgedLogs()).toHaveLength(1); + + attempt.resolve(); + await SequentialQueue.waitForIdle(); + }); + + it('uses the legacy request ID when the request index is missing', async () => { + const legacyRequestID = 456; + const attempt = createPendingAttempt(); + processSpy.mockReturnValueOnce(attempt.promise); + await SequentialQueue.push({command: 'ReconnectApp', requestID: legacyRequestID} as Request & {requestID: number}); + await jest.advanceTimersByTimeAsync(0); + + jest.advanceTimersByTime(CONST.TELEMETRY.CONFIG.SKELETON_MIN_DURATION); + + expect(getWedgedLogs()).toEqual([ + [ + 'loading_queue_wedged', + true, + expect.objectContaining({ + requestIndex: legacyRequestID, + queueLength: 1, + }), + ], + ]); + + attempt.resolve(); + await SequentialQueue.waitForIdle(); + }); + + it('does not let stale attempt cleanup clear a newer timer', async () => { + const firstAttempt = createPendingAttempt(); + const secondAttempt = createPendingAttempt(); + processSpy.mockReturnValueOnce(firstAttempt.promise).mockReturnValueOnce(secondAttempt.promise); + + await SequentialQueue.push({command: 'ReconnectApp', requestIndex}); + await jest.advanceTimersByTimeAsync(0); + expect(processSpy).toHaveBeenCalledTimes(1); + + SequentialQueue.resetQueue(); + SequentialQueue.flush(); + await jest.advanceTimersByTimeAsync(0); + expect(processSpy).toHaveBeenCalledTimes(2); + + firstAttempt.resolve(); + await jest.advanceTimersByTimeAsync(0); + jest.advanceTimersByTime(CONST.TELEMETRY.CONFIG.SKELETON_MIN_DURATION); + + expect(getWedgedLogs()).toEqual([ + [ + 'loading_queue_wedged', + true, + expect.objectContaining({ + requestIndex, + elapsedTime: CONST.TELEMETRY.CONFIG.SKELETON_MIN_DURATION, + }), + ], + ]); + + secondAttempt.resolve(); + await jest.advanceTimersByTimeAsync(0); + }); + + it('does not start the timer while a request is parked offline', async () => { + await Onyx.set(ONYXKEYS.NETWORK, {shouldFailAllRequests: false, shouldForceOffline: true}); + await SequentialQueue.push({command: 'ReconnectApp', requestIndex}); + + jest.advanceTimersByTime(CONST.TELEMETRY.CONFIG.SKELETON_MIN_DURATION); + + expect(processSpy).not.toHaveBeenCalled(); + expect(getWedgedLogs()).toHaveLength(0); + }); + + it('clears the timer after a terminal failure', async () => { + const attempt = await startAttempt(); + + attempt.reject(new Error(CONST.ERROR.DUPLICATE_RECORD)); + await SequentialQueue.waitForIdle(); + jest.advanceTimersByTime(CONST.TELEMETRY.CONFIG.SKELETON_MIN_DURATION); + + expect(getWedgedLogs()).toHaveLength(0); + }); + + it('clears the timer before rollback and retry', async () => { + const retryPromise = new Promise(() => {}); + const sleepSpy = jest.spyOn(SequentialQueue.sequentialQueueRequestThrottle, 'sleep').mockReturnValue(retryPromise); + const attempt = await startAttempt(); + + attempt.reject(new Error('retryable request failure')); + await jest.advanceTimersByTimeAsync(0); + expect(sleepSpy).toHaveBeenCalledTimes(1); + + jest.advanceTimersByTime(CONST.TELEMETRY.CONFIG.SKELETON_MIN_DURATION); + + expect(getWedgedLogs()).toHaveLength(0); + }); + + it('clears the timer after cancellation', async () => { + const attempt = await startAttempt(); + const cancellationError = new Error('request cancelled'); + cancellationError.name = CONST.ERROR.REQUEST_CANCELLED; + + attempt.reject(cancellationError); + await SequentialQueue.waitForIdle(); + jest.advanceTimersByTime(CONST.TELEMETRY.CONFIG.SKELETON_MIN_DURATION); + + expect(getWedgedLogs()).toHaveLength(0); + }); +}); + describe('SequentialQueue - reconnect coverage collapse', () => { // Build a ReconnectApp wired to the real resolver exactly as API.writeWithNoDuplicatesReconnectConflictAction // does, so these tests exercise the wiring, not a stand-in matcher. getOngoingRequest() is read inside the