Skip to content

[No QA] stop the pong watchdog from reconnecting Pusher #98884

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
mountiny merged 1 commit into from
Aug 19, 2026
Merged

[No QA] stop the pong watchdog from reconnecting Pusher #98884

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
55 changes: 6 additions & 49 deletions src/libs/actions/User.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -800,7 +800,6 @@ function playSoundForMessageType<TKey extends OnyxKey>(pushJSON: Array<OnyxServe

let lastPingSentTimestamp = Date.now();
let lastPongReceivedTimestamp = Date.now();
let shouldSkipCheckAfterReconnect = false;
function subscribeToPusherPong(currentUserAccountID: number) {
// If there is no user accountID yet (because the app isn't fully setup yet), the channel can't be subscribed to so return early
if (!currentUserAccountID) {
Expand All @@ -811,30 +810,21 @@ function subscribeToPusherPong(currentUserAccountID: number) {
Log.info(`[Pusher PINGPONG] Received a PONG event from the server`, false, pushJSON);
lastPongReceivedTimestamp = Date.now();

// Calculate the latency between the client and the server
const pongEvent = pushJSON as PingPongEvent;
const latency = Date.now() - Number(pongEvent.pingTimestamp);
Log.info(`[Pusher PINGPONG] The event took ${latency} ms`);
});
}

// Specify how long between each PING event to the server
const PING_INTERVAL_LENGTH_IN_SECONDS = 30;

// Specify how long between each check for missing PONG events
const CHECK_LATE_PONG_INTERVAL_LENGTH_IN_SECONDS = 60;

// Specify how long before a PING event is considered to be missing a PONG event, at which point the socket is presumed dead
const SOCKET_PRESUMED_DEAD_THRESHOLD_IN_SECONDS = 2 * PING_INTERVAL_LENGTH_IN_SECONDS;
const MISSING_PONG_THRESHOLD_IN_SECONDS = 2 * PING_INTERVAL_LENGTH_IN_SECONDS;

function pingPusher() {
if (getIsOffline()) {
Log.info('[Pusher PINGPONG] Skipping PING because the client is offline');
return;
}
// Send a PING event to the server with a specific ID and timestamp
// The server will respond with a PONG event with the same ID and timestamp
// Then we can calculate the latency between the client and the server (or if the server never replies)
const pingID = NumberUtils.rand64();
const pingTimestamp = Date.now();

Expand All @@ -852,37 +842,14 @@ function pingPusher() {
// eslint-disable-next-line rulesdir/no-api-side-effects-method
API.makeRequestWithSideEffects(SIDE_EFFECT_REQUEST_COMMANDS.PUSHER_PING, parameters).catch(() => {});
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<typeof setInterval>;
let checkForLatePongRepliesIntervalID: ReturnType<typeof setInterval>;
function initializePusherPingPong(currentUserAccountID: number) {
// Only run the ping pong from the leader client
if (!ActiveClientManager.isClientTheLeader()) {
Expand All @@ -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);
Expand All @@ -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);
}

/**
Expand Down
49 changes: 9 additions & 40 deletions tests/unit/PusherPingPongTest.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -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';

Expand All @@ -23,69 +23,38 @@ 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<typeof PusherUtils.subscribeToPrivateUserChannelEvent>[2];
let logSpy: jest.SpyInstance;

beforeAll(() => {
// jest/setupAfterEnv.ts calls jest.useRealTimers() after the globally-enabled fake timers are installed,
// so they must be re-installed here for setInterval/setTimeout in User.ts to be controllable
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 () => {
Expand Down
Loading