From 96108dbd3c3ecaa5576069989a766265743d278a Mon Sep 17 00:00:00 2001 From: Adam Horodyski Date: Tue, 18 Aug 2026 16:25:04 +0200 Subject: [PATCH] Stop the pong watchdog from reconnecting Pusher The watchdog compared wall-clock time against a 60 second threshold while the real PING cadence in production is also about 60 seconds, because browsers throttle setInterval in background tabs. The threshold equalled the cadence of the signal it watched, so it fired on timer jitter: 516 users produced 31,518 "presumed dead" fires per 4 hours while receiving about 118 PONGs each. The probe cannot answer the question either way. The PING goes out over HTTP and the PONG comes back over the websocket, so a missing PONG does not say which of the two failed, and the request has no retry on a failed fetch. Every Pusher SDK already detects a dead socket with a websocket ping frame answered on the connection under test, and reconnects itself: pusher-js 8.3.0 (120s/30s), PusherSwift 10.1.6 (server activity_timeout/30s), pusher-java-client 2.4.4 (120s/30s). The only cost of deferring to them is reaction time. The log line stays, restated, so the old string falling to zero is the proof and the new string sizes whatever the SDKs do not cover. Pusher.reconnect() itself stays: PusherConnectionManager and Session both still call it. The staleness check now rides the existing 30 second PING interval instead of a second timer with its own delayed start, which also removes the delay that read 60 milliseconds where it meant 60 seconds. Co-Authored-By: Claude Opus 5 (1M context) --- src/libs/actions/User.ts | 55 ++++---------------------------- tests/unit/PusherPingPongTest.ts | 49 ++++++---------------------- 2 files changed, 15 insertions(+), 89 deletions(-) diff --git a/src/libs/actions/User.ts b/src/libs/actions/User.ts index cda775647ca3..a2a82908cc9b 100644 --- a/src/libs/actions/User.ts +++ b/src/libs/actions/User.ts @@ -800,7 +800,6 @@ function playSoundForMessageType(pushJSON: Array {}); Log.info(`[Pusher PINGPONG] Sending a PING to the server: ${pingID} timestamp: ${pingTimestamp}`); -} - -function checkForLatePongReplies() { - if (getIsOffline()) { - Log.info('[Pusher PINGPONG] Skipping checkForLatePongReplies because the client is offline'); - return; - } - // A reconnect just happened, so give the fresh socket one full check interval to deliver a PONG - if (shouldSkipCheckAfterReconnect) { - shouldSkipCheckAfterReconnect = false; - return; - } - - const now = Date.now(); - const timeSinceLastPongReceived = now - lastPongReceivedTimestamp; - - // A missing PONG while HTTP still works (the client is not offline) means the socket is presumed dead, so reconnect Pusher - if (timeSinceLastPongReceived > SOCKET_PRESUMED_DEAD_THRESHOLD_IN_SECONDS * 1000) { - Log.info(`[Pusher PINGPONG] The server has not sent a PONG in ${timeSinceLastPongReceived} ms so the socket is presumed dead and Pusher is being reconnected`); - - // Retries stay unbounded: one reconnect every second check tick (~2 minutes) while PONGs are missing - shouldSkipCheckAfterReconnect = true; - Pusher.reconnect(); - } else { - Log.info(`[Pusher PINGPONG] Last PONG event was ${timeSinceLastPongReceived} ms ago so the socket is presumed alive`); + const timeSinceLastPongReceived = pingTimestamp - lastPongReceivedTimestamp; + if (timeSinceLastPongReceived > MISSING_PONG_THRESHOLD_IN_SECONDS * 1000) { + Log.info(`[Pusher PINGPONG] The server has not sent a PONG in ${timeSinceLastPongReceived} ms, leaving recovery to the Pusher SDK`); } } let pingPusherIntervalID: ReturnType; -let checkForLatePongRepliesIntervalID: ReturnType; function initializePusherPingPong(currentUserAccountID: number) { // Only run the ping pong from the leader client if (!ActiveClientManager.isClientTheLeader()) { @@ -892,6 +859,8 @@ function initializePusherPingPong(currentUserAccountID: number) { Log.info(`[Pusher PINGPONG] Starting Pusher PING PONG and pinging every ${PING_INTERVAL_LENGTH_IN_SECONDS} seconds`); + lastPongReceivedTimestamp = Date.now(); + // Subscribe to the pong event from Pusher. Unfortunately, there is no way of knowing when the client is actually subscribed // so there could be a little delay before the client is actually listening to this event. subscribeToPusherPong(currentUserAccountID); @@ -901,19 +870,7 @@ function initializePusherPingPong(currentUserAccountID: number) { clearInterval(pingPusherIntervalID); } - // Send a ping to pusher on a regular interval pingPusherIntervalID = setInterval(pingPusher, PING_INTERVAL_LENGTH_IN_SECONDS * 1000); - - // Delay the start of this by double the length of PING_INTERVAL_LENGTH_IN_SECONDS to give a chance for the first - // events to be sent and received - setTimeout(() => { - // If things are initializing again (which is fine because it will reinitialize each time Pusher authenticates), clear the old intervals - if (checkForLatePongRepliesIntervalID) { - clearInterval(checkForLatePongRepliesIntervalID); - } - // Check for any missing pong events on a regular interval - checkForLatePongRepliesIntervalID = setInterval(checkForLatePongReplies, CHECK_LATE_PONG_INTERVAL_LENGTH_IN_SECONDS * 1000); - }, PING_INTERVAL_LENGTH_IN_SECONDS * 2); } /** diff --git a/tests/unit/PusherPingPongTest.ts b/tests/unit/PusherPingPongTest.ts index 7b9714af0704..1213201e24bc 100644 --- a/tests/unit/PusherPingPongTest.ts +++ b/tests/unit/PusherPingPongTest.ts @@ -1,9 +1,9 @@ import {subscribeToUserEvents} from '@libs/actions/User'; import * as API from '@libs/API'; import {SIDE_EFFECT_REQUEST_COMMANDS} from '@libs/API/types'; +import Log from '@libs/Log'; import type * as NetworkStateModule from '@libs/NetworkState'; import Pusher from '@libs/Pusher'; -import PusherUtils from '@libs/PusherUtils'; import ONYXKEYS from '@src/ONYXKEYS'; @@ -23,14 +23,12 @@ jest.mock('@libs/NetworkState', () => ({ getIsOffline: () => false, })); -// The watchdog checks every 60s; each reconnect skips the following check, so while PONGs stay missing it fires on every second check tick (~2 minutes) -const CHECK_INTERVAL_MS = 60_000; - const PING_INTERVAL_MS = 30_000; +const MISSING_PONG_THRESHOLD_MS = 60_000; -describe('Pusher PINGPONG watchdog', () => { +describe('Pusher PINGPONG', () => { let reconnectSpy: jest.SpyInstance; - let pongCallback: Parameters[2]; + let logSpy: jest.SpyInstance; beforeAll(() => { // jest/setupAfterEnv.ts calls jest.useRealTimers() after the globally-enabled fake timers are installed, @@ -38,54 +36,25 @@ describe('Pusher PINGPONG watchdog', () => { jest.useFakeTimers(); Onyx.init({keys: ONYXKEYS}); reconnectSpy = jest.spyOn(Pusher, 'reconnect').mockImplementation(() => {}); + logSpy = jest.spyOn(Log, 'info').mockImplementation(() => {}); // The automock returns undefined, and pingPusher chains a .catch on the returned promise mockAPI.makeRequestWithSideEffects.mockResolvedValue(undefined); subscribeToUserEvents(123, 'test@example.com', () => undefined); - - const callback = jest.mocked(PusherUtils.subscribeToPrivateUserChannelEvent).mock.calls.find(([eventName]) => eventName === Pusher.TYPE.PONG)?.[2]; - if (!callback) { - throw new Error('The PONG subscription was not registered'); - } - pongCallback = callback; }); afterAll(() => { reconnectSpy.mockRestore(); + logSpy.mockRestore(); jest.useRealTimers(); }); - // Both tests share one continuous fake-timer timeline and must run in file order - - it('reconnects once past the threshold and keeps retrying every second check tick while PONGs stay missing', async () => { - await jest.advanceTimersByTimeAsync(CHECK_INTERVAL_MS + 1_000); - expect(reconnectSpy).toHaveBeenCalledTimes(1); - - // The check tick right after a reconnect is skipped - await jest.advanceTimersByTimeAsync(CHECK_INTERVAL_MS); - expect(reconnectSpy).toHaveBeenCalledTimes(1); - - await jest.advanceTimersByTimeAsync(CHECK_INTERVAL_MS); - expect(reconnectSpy).toHaveBeenCalledTimes(2); - - await jest.advanceTimersByTimeAsync(2 * CHECK_INTERVAL_MS); - expect(reconnectSpy).toHaveBeenCalledTimes(3); - }); - - it('defers the next reconnect when a PONG arrives', async () => { - reconnectSpy.mockClear(); + it('logs a missing PONG without reconnecting, leaving recovery to the Pusher SDK', async () => { + await jest.advanceTimersByTimeAsync(5 * MISSING_PONG_THRESHOLD_MS); - // Let the skipped check tick pass, then deliver a PONG - await jest.advanceTimersByTimeAsync(CHECK_INTERVAL_MS); - pongCallback({pingID: '1', pingTimestamp: Date.now()}); - - // Without the PONG resetting the clock, this next check tick would reconnect - await jest.advanceTimersByTimeAsync(CHECK_INTERVAL_MS); expect(reconnectSpy).not.toHaveBeenCalled(); - - await jest.advanceTimersByTimeAsync(CHECK_INTERVAL_MS); - expect(reconnectSpy).toHaveBeenCalledTimes(1); + expect(logSpy).toHaveBeenCalledWith(expect.stringContaining('leaving recovery to the Pusher SDK')); }); it('sends the PING off the durable write queue', async () => {