diff --git a/.github/workflows/e2e-tests.yml b/.github/workflows/e2e-tests.yml index efb94370e8e..c97971dd008 100644 --- a/.github/workflows/e2e-tests.yml +++ b/.github/workflows/e2e-tests.yml @@ -48,7 +48,8 @@ on: jobs: test: name: Run E2E Tests - runs-on: ubuntu-latest + # Playwright 1.57 has no browser/ffmpeg support for Ubuntu 26.04. + runs-on: ubuntu-24.04 strategy: fail-fast: false diff --git a/apps/webapp/__mocks__/@wireapp/core.ts b/apps/webapp/__mocks__/@wireapp/core.ts index ef293db93b1..27d8410f093 100644 --- a/apps/webapp/__mocks__/@wireapp/core.ts +++ b/apps/webapp/__mocks__/@wireapp/core.ts @@ -21,6 +21,13 @@ import {TaskScheduler} from '@wireapp/core/lib/util'; import {EventEmitter} from 'stream'; +export enum ConnectionState { + CLOSED = 'closed', + CONNECTING = 'connecting', + PROCESSING_NOTIFICATIONS = 'processing_notifications', + LIVE = 'live', +} + export class Account extends EventEmitter { backendFeatures = { federationEndpoints: true, diff --git a/apps/webapp/src/script/main/app.ts b/apps/webapp/src/script/main/app.ts index be85e02796e..a3342d346e3 100644 --- a/apps/webapp/src/script/main/app.ts +++ b/apps/webapp/src/script/main/app.ts @@ -274,7 +274,9 @@ export class App { serverTimeHandler, ); - repositories.eventTracker = new EventTrackingRepository(repositories.message); + repositories.eventTracker = new EventTrackingRepository(repositories.message, undefined, undefined, { + webSocket: this.apiClient.transport.ws, + }); repositories.backup = new BackupRepository(new BackupService(), repositories.conversation); diff --git a/apps/webapp/src/script/repositories/event/EventRepository.ts b/apps/webapp/src/script/repositories/event/EventRepository.ts index fe5c860f278..0d351adc61b 100644 --- a/apps/webapp/src/script/repositories/event/EventRepository.ts +++ b/apps/webapp/src/script/repositories/event/EventRepository.ts @@ -23,12 +23,14 @@ import { ConversationOtrMessageAddEvent, ConversationMLSMessageAddEvent, } from '@wireapp/api-client/lib/event'; +import {BackendError} from '@wireapp/api-client/lib/http'; import {NotificationSource, HandledEventPayload} from '@wireapp/core/lib/notification'; import {amplify} from 'amplify'; import ko from 'knockout'; import {container} from 'tsyringe'; -import {Account, ConnectionState, ProcessedEventPayload} from '@wireapp/core'; +import {Runtime} from '@wireapp/commons'; +import {Account, ConnectionState, ProcessedEventPayload, type WebSocketConnectionContext} from '@wireapp/core'; import {PromiseQueue} from '@wireapp/promise-queue'; import {WebAppEvents} from '@wireapp/webapp-events'; @@ -38,6 +40,7 @@ import {EventName} from 'Repositories/tracking/EventName'; import {UserState} from 'Repositories/user/UserState'; import {getLogger, Logger} from 'Util/Logger'; import {TIME_IN_MILLIS} from 'Util/TimeUtil'; +import {isAxiosError} from 'Util/TypePredicateUtil'; import {ClientEvent} from './Client'; import {EventMiddleware, EventProcessor, IncomingEvent} from './EventProcessor'; @@ -55,6 +58,40 @@ import {EventError} from '../../error/EventError'; import type {ServerTimeHandler} from '../../time/serverTimeHandler'; import {Warnings} from '../../view_model/WarningsContainer'; +type WebSocketConnectTrigger = + | 'initial' + | 'online' + | 'focus' + | 'visibility' + | 'heartbeat-closed' + | 'heartbeat-unhealthy'; + +type ReadinessClock = { + readonly setTimeout: (callback: () => void, delayMilliseconds: number) => number; + readonly clearTimeout: (identifier: number) => void; +}; + +function getNotificationHandlingStateName(notificationHandlingState: NOTIFICATION_HANDLING_STATE): string { + return notificationHandlingState.split('.').at(-1) ?? notificationHandlingState; +} + +function isRecoverableConnectionSetupFailure(error: unknown): boolean { + if (isAxiosError(error) && error.response === undefined) { + return ['ERR_NETWORK', 'ECONNABORTED', 'ETIMEDOUT', 'ECONNRESET', 'ENOTFOUND', 'EAI_AGAIN'].includes( + error.code ?? '', + ); + } + const statusCode = + error instanceof BackendError ? error.code : isAxiosError(error) ? error.response?.status : undefined; + + return ( + statusCode === 408 || + statusCode === 420 || + statusCode === 429 || + (statusCode !== undefined && statusCode >= 500 && statusCode < 600) + ); +} + export class EventRepository { logger: Logger; notificationHandlingState = ko.observable(NOTIFICATION_HANDLING_STATE.STREAM); @@ -68,6 +105,8 @@ export class EventRepository { static get CONFIG() { return { E_CALL_EVENT_LIFETIME: TIME_IN_MILLIS.SECOND * 30, + HEARTBEAT_INTERVAL: TIME_IN_MILLIS.SECOND * 30, + INITIAL_CONNECTION_TIMEOUT: TIME_IN_MILLIS.MINUTE * 5, IGNORED_ERRORS: [ CryptographyError.TYPE.IGNORED_ASSET, CryptographyError.TYPE.IGNORED_PREVIEW, @@ -99,6 +138,7 @@ export class EventRepository { readonly notificationService: NotificationService, private readonly serverTimeHandler: ServerTimeHandler, private readonly userState = container.resolve(UserState), + private readonly readinessClock: ReadinessClock = window, ) { this.logger = getLogger('EventRepository'); @@ -145,6 +185,7 @@ export class EventRepository { return; } case ConnectionState.CLOSED: { + this.notificationHandlingState(NOTIFICATION_HANDLING_STATE.CLOSED); Warnings.showWarning(Warnings.TYPE.NO_INTERNET); return; } @@ -168,7 +209,7 @@ export class EventRepository { await this.handleEvent(payload, source); } catch (error) { if (source === EventSource.NOTIFICATION_STREAM) { - this.logger.warn(`Failed to handle event of type "${event.type}": ${error.message}`, error); + this.logger.warn('Failed to handle a notification stream event'); } else { throw error; } @@ -201,17 +242,116 @@ export class EventRepository { onNotificationStreamProgress: (currentProcessingNotificationTimestamp: string) => void, dryRun = false, ): Promise { - await this.handleTimeDrift(); - const connect = () => { - // We make sure there is only be a single active connection to the WebSocket. - this.disconnectWebSocket?.(); - return new Promise(async resolve => { - this.disconnectWebSocket = await account.listen({ + this.disconnectWebSocket(); + + const cleanupHandlers: Array<() => void> = []; + let connectionAttemptLifetime: AbortController | undefined; + let disposed = false; + let readinessSettled = false; + let resolveReadiness: () => void = () => {}; + let rejectReadiness: (error: Error) => void = () => {}; + const readiness = new Promise((resolve, reject) => { + resolveReadiness = resolve; + rejectReadiness = reject; + }); + const readinessTimeout = this.readinessClock.setTimeout(() => { + failInitialization(new Error('WebSocket notification synchronization timed out')); + }, EventRepository.CONFIG.INITIAL_CONNECTION_TIMEOUT); + const readinessClock = this.readinessClock; + let actualDisconnect: () => void = () => {}; + let connectionInProgress = false; + let healthCheckInProgress = false; + let currentConnectionState: ConnectionState | undefined; + let connectCycleId = 0; + + function completeInitialization(): void { + if (readinessSettled === false) { + readinessSettled = true; + readinessClock.clearTimeout(readinessTimeout); + resolveReadiness(); + } + } + + function disconnect(): void { + if (disposed === true) { + return; + } + disposed = true; + connectionAttemptLifetime?.abort(); + cleanupHandlers.forEach(cleanup => { + cleanup(); + }); + actualDisconnect(); + if (readinessSettled === false) { + readinessSettled = true; + readinessClock.clearTimeout(readinessTimeout); + rejectReadiness(new Error('WebSocket initialization was cancelled')); + } + } + + function failInitialization(error: Error): void { + if (readinessSettled === false) { + readinessSettled = true; + readinessClock.clearTimeout(readinessTimeout); + rejectReadiness(error); + disconnect(); + } + } + this.disconnectWebSocket = disconnect; + + const notificationHandlingState = this.notificationHandlingState; + function getBrowserConnectionContext(): string { + return `connectCycleId=${connectCycleId} connectionInProgress=${connectionInProgress} notificationState=${getNotificationHandlingStateName(notificationHandlingState())} navigatorOnline=${navigator.onLine} visibility=${document.visibilityState} focused=${document.hasFocus()}`; + } + + const connect = async (trigger: WebSocketConnectTrigger) => { + if (disposed === true || connectionInProgress) { + this.logger.debug( + `[WebSocketLifecycle] layer=event-repository event=connect-skip trigger=${trigger} ${getBrowserConnectionContext()} reason=connection-in-progress`, + ); + return; + } + + connectCycleId += 1; + const currentConnectCycleId = connectCycleId; + this.logger.info( + `[WebSocketLifecycle] layer=event-repository event=connect-start trigger=${trigger} connectCycleId=${currentConnectCycleId} ${getBrowserConnectionContext()}`, + ); + connectionInProgress = true; + connectionAttemptLifetime?.abort(); + actualDisconnect(); + actualDisconnect = () => {}; + const attemptLifetime = new AbortController(); + connectionAttemptLifetime = attemptLifetime; + let setupCompleted = false; + try { + const disconnectAttempt = await account.listen({ useLegacy, - onConnectionStateChanged: connectionState => { + signal: attemptLifetime.signal, + onSessionExpired: () => { + if (disposed === false && currentConnectCycleId === connectCycleId) { + failInitialization(new Error('WebSocket session expired during initialization')); + disconnect(); + } + }, + onConnectionStateChanged: ( + connectionState: ConnectionState, + connectionContext: WebSocketConnectionContext | undefined, + ) => { + if (disposed === true || currentConnectCycleId !== connectCycleId) { + return; + } + currentConnectionState = connectionState; this.updateConnectivitityStatus(connectionState); - if (connectionState === ConnectionState.LIVE) { - resolve(); + const lifecycleConnectionContext = + connectionContext === undefined + ? '' + : ` attemptId=${connectionContext.attemptId} wrapperGeneration=${connectionContext.wrapperGeneration}`; + this.logger.info( + `[WebSocketLifecycle] layer=event-repository event=connection-state-change connectCycleId=${currentConnectCycleId} state=${connectionState.toUpperCase()}${lifecycleConnectionContext}`, + ); + if (connectionState === ConnectionState.LIVE && setupCompleted === true) { + completeInitialization(); } }, onEvent: this.handleIncomingEvent, @@ -219,21 +359,196 @@ export class EventRepository { onNotificationStreamProgress: onNotificationStreamProgress, dryRun, }); - }); + if (attemptLifetime.signal.aborted === true || currentConnectCycleId !== connectCycleId) { + disconnectAttempt(); + return; + } + actualDisconnect = disconnectAttempt; + setupCompleted = true; + if (currentConnectionState === ConnectionState.LIVE) { + completeInitialization(); + } + this.logger.info( + `[WebSocketLifecycle] layer=event-repository event=connect-setup-success trigger=${trigger} connectCycleId=${currentConnectCycleId}`, + ); + } catch (error: unknown) { + if (attemptLifetime.signal.aborted === true || currentConnectCycleId !== connectCycleId) { + return; + } + attemptLifetime.abort(); + actualDisconnect = () => {}; + currentConnectionState = ConnectionState.CLOSED; + if (disposed === false) { + this.updateConnectivitityStatus(ConnectionState.CLOSED); + } + this.logger.warn( + `[WebSocketLifecycle] layer=event-repository event=connect-failure trigger=${trigger} connectCycleId=${currentConnectCycleId}`, + ); + if (isRecoverableConnectionSetupFailure(error) === false) { + failInitialization(new Error('WebSocket initialization failed')); + disconnect(); + } + } finally { + if (currentConnectCycleId === connectCycleId) { + connectionInProgress = false; + } + } }; - window.addEventListener('online', () => { + const handleOnline = () => { + if (!navigator.onLine) { + return; + } + this.logger.info('Internet connection regained. Re-establishing WebSocket connection...'); - connect(); - }); + void verifyConnectionHealthAndReconnect('online'); + }; - window.addEventListener('offline', () => { + const verifyConnectionHealthAndReconnect = async (trigger: 'focus' | 'visibility' | 'heartbeat' | 'online') => { + if (disposed === true) { + return; + } + if (!navigator.onLine) { + this.logger.debug( + `[WebSocketLifecycle] layer=event-repository event=health-check-skip trigger=${trigger} reason=offline ${getBrowserConnectionContext()}`, + ); + return; + } + + if (connectionInProgress) { + this.logger.debug( + `[WebSocketLifecycle] layer=event-repository event=health-check-skip trigger=${trigger} reason=connection-in-progress ${getBrowserConnectionContext()}`, + ); + return; + } + + const isTransitioningConnectionState = + currentConnectionState === ConnectionState.CONNECTING || + currentConnectionState === ConnectionState.PROCESSING_NOTIFICATIONS; + if (isTransitioningConnectionState) { + this.logger.debug( + `[WebSocketLifecycle] layer=event-repository event=health-check-skip trigger=${trigger} reason=connection-transitioning connectionState=${currentConnectionState?.toUpperCase() ?? 'UNKNOWN'} ${getBrowserConnectionContext()}`, + ); + return; + } + + if (this.notificationHandlingState() === NOTIFICATION_HANDLING_STATE.CLOSED) { + this.logger.info( + `[WebSocketLifecycle] layer=event-repository event=reconnect-requested trigger=${trigger === 'heartbeat' ? 'heartbeat-closed' : trigger} connectCycleId=${connectCycleId + 1}`, + ); + await connect(`${trigger === 'heartbeat' ? 'heartbeat-closed' : trigger}`); + return; + } + + if (healthCheckInProgress) { + this.logger.debug( + `[WebSocketLifecycle] layer=event-repository event=health-check-skip trigger=${trigger} reason=health-check-in-progress ${getBrowserConnectionContext()}`, + ); + return; + } + + healthCheckInProgress = true; + const checkedConnectCycleId = connectCycleId; + try { + this.logger.debug( + `[WebSocketLifecycle] layer=event-repository event=health-check-start trigger=${trigger} connectCycleId=${connectCycleId}`, + ); + let isHealthy: boolean; + try { + isHealthy = await account.isWebsocketHealthy(); + } catch { + isHealthy = false; + } + if (isHealthy) { + this.logger.debug( + `[WebSocketLifecycle] layer=event-repository event=health-check-result trigger=${trigger} connectCycleId=${connectCycleId} healthy=true`, + ); + } else { + this.logger.warn( + `[WebSocketLifecycle] layer=event-repository event=health-check-result trigger=${trigger} connectCycleId=${connectCycleId} healthy=false`, + ); + } + if (!isHealthy && disposed === false && checkedConnectCycleId === connectCycleId) { + const reconnectTrigger: WebSocketConnectTrigger = trigger === 'heartbeat' ? 'heartbeat-unhealthy' : trigger; + this.logger.info( + `[WebSocketLifecycle] layer=event-repository event=reconnect-requested trigger=${reconnectTrigger} connectCycleId=${connectCycleId + 1}`, + ); + await connect(reconnectTrigger); + } + } finally { + healthCheckInProgress = false; + } + }; + + const handleOffline = () => { this.logger.warn('Internet connection lost'); - this.disconnectWebSocket(); + connectCycleId += 1; + connectionAttemptLifetime?.abort(); + actualDisconnect(); + actualDisconnect = () => {}; + connectionInProgress = false; + currentConnectionState = ConnectionState.CLOSED; + this.updateConnectivitityStatus(ConnectionState.CLOSED); Warnings.showWarning(Warnings.TYPE.NO_INTERNET); + }; + + if (Runtime.isElectron()) { + // In Electron, use window focus events instead of visibilitychange + const handleFocus = () => { + if (navigator.onLine) { + this.logger.info('Window focused, verifying connection...'); + void verifyConnectionHealthAndReconnect('focus'); + } + }; + + window.addEventListener('focus', handleFocus); + cleanupHandlers.push(() => window.removeEventListener('focus', handleFocus)); + } else { + // In browser, use visibilitychange + const handleVisibilityChange = () => { + if (document.visibilityState === 'visible' && navigator.onLine) { + this.logger.info('Tab became visible, verifying connection...'); + void verifyConnectionHealthAndReconnect('visibility'); + } + }; + + document.addEventListener('visibilitychange', handleVisibilityChange); + cleanupHandlers.push(() => { + document.removeEventListener('visibilitychange', handleVisibilityChange); + }); + } + + // Online/Offline handlers work for both environments + window.addEventListener('online', handleOnline); + window.addEventListener('offline', handleOffline); + + cleanupHandlers.push(() => { + window.removeEventListener('online', handleOnline); + window.removeEventListener('offline', handleOffline); + }); + + // Heartbeat intentionally verifies connection health while online, even when the + // connection is not CLOSED, to detect stale "open-but-unhealthy" websocket states. + const heartbeatInterval = window.setInterval(() => { + void verifyConnectionHealthAndReconnect('heartbeat'); + }, EventRepository.CONFIG.HEARTBEAT_INTERVAL); + + cleanupHandlers.push(() => { + window.clearInterval(heartbeatInterval); }); - return connect(); + const repository = this; + async function initialize(): Promise { + try { + await repository.handleTimeDrift(); + await connect('initial'); + } catch { + failInitialization(new Error('WebSocket initialization failed')); + } + } + void initialize(); + + return readiness; } /** @@ -385,7 +700,7 @@ export class EventRepository { return event; } case EventValidation.OUTDATED_TIMESTAMP: { - this.logger.warn(`Ignored outdated event type: '${event.type}'`); + this.logger.warn('Ignored an outdated notification event'); return event; } case EventValidation.VALID: @@ -407,13 +722,7 @@ export class EventRepository { source: EventSource, ): Promise { if (decryptionError) { - this.logger.warn(`Decryption Error: '${event.type}'`, { - source, - eventType: event.type, - date: event.time, - code: decryptionError.code, - message: decryptionError.message, - }); + this.logger.warn('Failed to decrypt a notification event'); const ignoredCodes = [ 208, // Outated event decyption error (see https://github.com/wireapp/wire-web-core/blob/5c8c56097eadfa55e79856cd6745087f0fd12e24/packages/proteus/README.md#decryption-errors) @@ -452,7 +761,7 @@ export class EventRepository { } } catch (error) { if (error instanceof EventValidationError) { - this.logger.warn(`Event validation failed: ${error.message}`, error); + this.logger.warn('Notification event validation failed'); return; } throw error; diff --git a/apps/webapp/src/script/repositories/event/EventRepository.websocket.test.ts b/apps/webapp/src/script/repositories/event/EventRepository.websocket.test.ts new file mode 100644 index 00000000000..e254272e6ef --- /dev/null +++ b/apps/webapp/src/script/repositories/event/EventRepository.websocket.test.ts @@ -0,0 +1,428 @@ +/* + * Wire + * Copyright (C) 2018 Wire Swiss GmbH + * + * This program is free software: you can redistribute it and/or modify + * it under the terms of the GNU General Public License as published by + * the Free Software Foundation, either version 3 of the License, or + * (at your option) any later version. + * + * This program is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU General Public License for more details. + * + * You should have received a copy of the GNU General Public License + * along with this program. If not, see http://www.gnu.org/licenses/. + * + */ + +import {Runtime} from '@wireapp/commons'; +import {Account, ConnectionState, WebSocketConnectionContext} from '@wireapp/core'; +import {InvalidTokenError} from '@wireapp/api-client/lib/auth'; +import {BackendError} from '@wireapp/api-client/lib/http'; + +import {Warnings} from '../../view_model/WarningsContainer'; +import {EventRepository} from './EventRepository'; +import {NOTIFICATION_HANDLING_STATE} from './NotificationHandlingState'; + +type RepositoryInputs = ConstructorParameters; +type ListenOptions = Parameters[0]; + +function noop(): void {} + +async function flushConnectionCallbacks(): Promise { + for (let turn = 0; turn < 20; turn += 1) { + await Promise.resolve(); + } +} + +describe('WebSocket recovery orchestration', () => { + let repository: EventRepository; + let connectionStateChanged: ((state: ConnectionState, context?: WebSocketConnectionContext) => void) | undefined; + let heartbeat: (() => void) | undefined; + let automaticallySynchronize = true; + let readinessDeadline: (() => void) | undefined; + const clearReadinessTimeout = jest.fn(); + const disconnect = jest.fn(); + const listen = jest.fn void>, [ListenOptions]>(); + const isWebsocketHealthy = jest.fn, []>(); + const account = {listen, isWebsocketHealthy} as unknown as Account; + + beforeEach(() => { + clearReadinessTimeout.mockClear(); + connectionStateChanged = undefined; + heartbeat = undefined; + automaticallySynchronize = true; + disconnect.mockReset(); + listen.mockReset().mockImplementation(async options => { + connectionStateChanged = options.onConnectionStateChanged; + if (automaticallySynchronize === true) { + connectionStateChanged?.(ConnectionState.LIVE); + } + + return disconnect; + }); + isWebsocketHealthy.mockReset().mockResolvedValue(true); + jest.spyOn(Runtime, 'isElectron').mockReturnValue(false); + jest.spyOn(navigator, 'onLine', 'get').mockReturnValue(true); + jest.spyOn(document, 'visibilityState', 'get').mockReturnValue('visible'); + jest.spyOn(window, 'setInterval').mockImplementation(callback => { + if (typeof callback !== 'function') { + throw new Error('Expected heartbeat callback'); + } + heartbeat = callback as () => void; + + return 123; + }); + jest.spyOn(window, 'clearInterval'); + jest.spyOn(Warnings, 'showWarning').mockImplementation(noop); + jest.spyOn(Warnings, 'hideWarning').mockImplementation(noop); + repository = new EventRepository( + {} as RepositoryInputs[0], + {getServerTime: jest.fn().mockResolvedValue('2026-01-01T00:00:00Z')} as unknown as RepositoryInputs[1], + {computeTimeOffset: noop} as unknown as RepositoryInputs[2], + {} as RepositoryInputs[3], + { + setTimeout(callback): number { readinessDeadline = callback; return 456; }, + clearTimeout: clearReadinessTimeout, + }, + ); + }); + + afterEach(() => { + repository.disconnectWebSocket(); + jest.restoreAllMocks(); + }); + + function setConnectionState(state: ConnectionState): void { + if (connectionStateChanged === undefined) { + throw new Error('Expected connection-state subscription'); + } + connectionStateChanged(state); + } + + function runHeartbeat(): void { + if (heartbeat === undefined) { + throw new Error('Expected registered heartbeat'); + } + heartbeat(); + } + + async function connect(): Promise { + await repository.connectWebSocket(account, true, noop); + setConnectionState(ConnectionState.LIVE); + automaticallySynchronize = false; + listen.mockClear(); + } + + it('reconnects a CLOSED connection without probing it', async () => { + await connect(); + setConnectionState(ConnectionState.CLOSED); + + document.dispatchEvent(new Event('visibilitychange')); + await flushConnectionCallbacks(); + + expect(repository.notificationHandlingState()).toBe(NOTIFICATION_HANDLING_STATE.CLOSED); + expect(isWebsocketHealthy).not.toHaveBeenCalled(); + expect(listen).toHaveBeenCalledTimes(1); + expect(disconnect).toHaveBeenCalledTimes(1); + }); + + it.each([ConnectionState.CONNECTING, ConnectionState.PROCESSING_NOTIFICATIONS])( + 'does not interrupt a connection in %s', + async state => { + await connect(); + setConnectionState(state); + + runHeartbeat(); + document.dispatchEvent(new Event('visibilitychange')); + await flushConnectionCallbacks(); + + expect(isWebsocketHealthy).not.toHaveBeenCalled(); + expect(listen).not.toHaveBeenCalled(); + }, + ); + + it('reconnects an unhealthy connection on heartbeat', async () => { + await connect(); + isWebsocketHealthy.mockResolvedValue(false); + + runHeartbeat(); + await flushConnectionCallbacks(); + + expect(isWebsocketHealthy).toHaveBeenCalledTimes(1); + expect(listen).toHaveBeenCalledTimes(1); + }); + + it('keeps a healthy connection when the tab becomes visible', async () => { + await connect(); + + document.dispatchEvent(new Event('visibilitychange')); + await flushConnectionCallbacks(); + + expect(isWebsocketHealthy).toHaveBeenCalledTimes(1); + expect(listen).not.toHaveBeenCalled(); + }); + + it('recovers when the health probe rejects', async () => { + await connect(); + isWebsocketHealthy.mockRejectedValue(new Error('Probe failed')); + + runHeartbeat(); + await flushConnectionCallbacks(); + + expect(listen).toHaveBeenCalledTimes(1); + }); + + it('deduplicates concurrent visibility and heartbeat health checks', async () => { + await connect(); + let resolveHealthCheck: ((healthy: boolean) => void) | undefined; + isWebsocketHealthy.mockReturnValue( + new Promise(resolve => { + resolveHealthCheck = resolve; + }), + ); + + document.dispatchEvent(new Event('visibilitychange')); + runHeartbeat(); + document.dispatchEvent(new Event('visibilitychange')); + if (resolveHealthCheck === undefined) { + throw new Error('Expected pending health check'); + } + resolveHealthCheck(false); + await flushConnectionCallbacks(); + + expect(isWebsocketHealthy).toHaveBeenCalledTimes(1); + expect(listen).toHaveBeenCalledTimes(1); + }); + + it('uses focus recovery in Electron', async () => { + jest.spyOn(Runtime, 'isElectron').mockReturnValue(true); + await connect(); + isWebsocketHealthy.mockResolvedValue(false); + + window.dispatchEvent(new Event('focus')); + await flushConnectionCallbacks(); + + expect(listen).toHaveBeenCalledTimes(1); + }); + + it('does not reconnect while offline', async () => { + await connect(); + jest.spyOn(navigator, 'onLine', 'get').mockReturnValue(false); + + runHeartbeat(); + window.dispatchEvent(new Event('online')); + await flushConnectionCallbacks(); + + expect(isWebsocketHealthy).not.toHaveBeenCalled(); + expect(listen).not.toHaveBeenCalled(); + }); + + it('removes event subscriptions and heartbeat on disconnect', async () => { + await connect(); + repository.disconnectWebSocket(); + window.dispatchEvent(new Event('online')); + document.dispatchEvent(new Event('visibilitychange')); + await flushConnectionCallbacks(); + + expect(window.clearInterval).toHaveBeenCalledWith(123); + expect(listen).not.toHaveBeenCalled(); + expect(isWebsocketHealthy).not.toHaveBeenCalled(); + }); + it('correlates application recovery cycles with the transport context', async () => { + const information = jest.spyOn(repository.logger, 'info'); + await connect(); + connectionStateChanged?.(ConnectionState.CLOSED, {attemptId: 12, wrapperGeneration: 4}); + runHeartbeat(); + await flushConnectionCallbacks(); + + expect(information).toHaveBeenCalledWith(expect.stringContaining('connectCycleId=1 state=CLOSED attemptId=12 wrapperGeneration=4')); + expect(information).toHaveBeenCalledWith(expect.stringContaining('event=connect-start trigger=heartbeat-closed connectCycleId=2')); + expect(listen).toHaveBeenCalledTimes(1); + }); + + it('logs setup failures without serializing their sensitive contents', async () => { + const warning = jest.spyOn(repository.logger, 'warn'); + listen.mockRejectedValue(new Error('private-notification Cookie: secret-cookie')); + await expect(repository.connectWebSocket(account, true, noop)).rejects.toThrow('WebSocket initialization failed'); + + expect(warning).toHaveBeenCalledWith(expect.stringContaining('event=connect-failure trigger=initial connectCycleId=1')); + expect(JSON.stringify(warning.mock.calls)).not.toMatch(/private-notification|secret-cookie/); + }); + + it.each([true, false])('waits for notification synchronization with useLegacy=%s', async useLegacy => { + listen.mockImplementation(async options => { + connectionStateChanged = options.onConnectionStateChanged; + connectionStateChanged?.(ConnectionState.PROCESSING_NOTIFICATIONS); + return disconnect; + }); + let ready = false; + async function initialize(): Promise { + await repository.connectWebSocket(account, useLegacy, noop); + ready = true; + } + const initialization = initialize(); + await flushConnectionCallbacks(); + expect(ready).toBe(false); + setConnectionState(ConnectionState.LIVE); + await initialization; + expect(ready).toBe(true); + expect(clearReadinessTimeout).toHaveBeenCalledWith(456); + }); + + it.each([true, false])('allows transport recovery during initialization with useLegacy=%s', async useLegacy => { + listen.mockImplementation(async options => { + connectionStateChanged = options.onConnectionStateChanged; + return disconnect; + }); + const initialization = repository.connectWebSocket(account, useLegacy, noop); + const completed = expect(initialization).resolves.toBeUndefined(); + await flushConnectionCallbacks(); + setConnectionState(ConnectionState.CLOSED); + setConnectionState(ConnectionState.CONNECTING); + runHeartbeat(); + await flushConnectionCallbacks(); + expect(listen).toHaveBeenCalledTimes(1); + expect(disconnect).not.toHaveBeenCalled(); + setConnectionState(ConnectionState.PROCESSING_NOTIFICATIONS); + expect(clearReadinessTimeout).not.toHaveBeenCalled(); + setConnectionState(ConnectionState.LIVE); + await completed; + }); + + it.each([{isAxiosError: true, code: 'ERR_NETWORK'}, new BackendError('Unavailable', undefined, 503)])( + 'recovers transient setup failure without competing attempts: %s', async failure => { + listen.mockRejectedValueOnce(failure); + const initialization = repository.connectWebSocket(account, false, noop); + const completed = expect(initialization).resolves.toBeUndefined(); + await flushConnectionCallbacks(); + expect(clearReadinessTimeout).not.toHaveBeenCalled(); + runHeartbeat(); + window.dispatchEvent(new Event('online')); + await completed; + expect(listen).toHaveBeenCalledTimes(2); + expect(listen.mock.calls[0]?.[0].signal?.aborted).toBe(true); + }, + ); + + it('rejects an invalid-session setup failure without retrying', async () => { + listen.mockRejectedValueOnce(new InvalidTokenError('Session expired')); + await expect(repository.connectWebSocket(account, true, noop)).rejects.toThrow('WebSocket initialization failed'); + runHeartbeat(); + window.dispatchEvent(new Event('online')); + await flushConnectionCallbacks(); + expect(listen).toHaveBeenCalledTimes(1); + expect(window.clearInterval).toHaveBeenCalledWith(123); + }); + + it('terminates startup when an established listener reports an invalid session', async () => { + automaticallySynchronize = false; + const initialization = repository.connectWebSocket(account, false, noop); + const rejected = expect(initialization).rejects.toThrow('session expired'); + await flushConnectionCallbacks(); + listen.mock.calls[0]?.[0].onSessionExpired?.(); + await rejected; + runHeartbeat(); + await flushConnectionCallbacks(); + expect(listen).toHaveBeenCalledTimes(1); + expect(disconnect).toHaveBeenCalledTimes(1); + }); + + it('recovers after going offline during setup and ignores the obsolete setup result', async () => { + let finishFirstSetup: (cleanup: () => void) => void = noop; + const obsoleteDisconnect = jest.fn(); + listen.mockImplementationOnce(async options => { + connectionStateChanged = options.onConnectionStateChanged; + + return new Promise(resolve => { finishFirstSetup = resolve; }); + }); + const initialization = repository.connectWebSocket(account, true, noop); + const completed = expect(initialization).resolves.toBeUndefined(); + await flushConnectionCallbacks(); + window.dispatchEvent(new Event('offline')); + expect(listen.mock.calls[0]?.[0].signal?.aborted).toBe(true); + window.dispatchEvent(new Event('online')); + await completed; + finishFirstSetup(obsoleteDisconnect); + await flushConnectionCallbacks(); + expect(listen).toHaveBeenCalledTimes(2); + expect(obsoleteDisconnect).toHaveBeenCalledTimes(1); + expect(disconnect).not.toHaveBeenCalled(); + }); + + it('cancels pending startup recovery and removes all recovery sources', async () => { + listen.mockRejectedValueOnce({isAxiosError: true, code: 'ERR_NETWORK'}); + const initialization = repository.connectWebSocket(account, true, noop); + const cancelled = expect(initialization).rejects.toThrow('cancelled'); + await flushConnectionCallbacks(); + repository.disconnectWebSocket(); + await cancelled; + runHeartbeat(); + window.dispatchEvent(new Event('online')); + document.dispatchEvent(new Event('visibilitychange')); + await flushConnectionCallbacks(); + expect(listen).toHaveBeenCalledTimes(1); + expect(clearReadinessTimeout).toHaveBeenCalledWith(456); + expect(window.clearInterval).toHaveBeenCalledWith(123); + }); + + it('rejects a stalled setup at the injected readiness deadline and ignores late LIVE', async () => { + listen.mockImplementation(async options => { + connectionStateChanged = options.onConnectionStateChanged; + return new Promise<() => void>(() => {}); + }); + const initialization = repository.connectWebSocket(account, false, noop); + const rejected = expect(initialization).rejects.toThrow('timed out'); + await flushConnectionCallbacks(); + readinessDeadline?.(); + await rejected; + setConnectionState(ConnectionState.LIVE); + expect(repository.notificationHandlingState()).not.toBe(NOTIFICATION_HANDLING_STATE.WEB_SOCKET); + expect(listen.mock.calls[0]?.[0].signal?.aborted).toBe(true); + expect(window.clearInterval).toHaveBeenCalledWith(123); + runHeartbeat(); + window.dispatchEvent(new Event('online')); + await flushConnectionCallbacks(); + expect(listen).toHaveBeenCalledTimes(1); + }); + + it('cancels overlapping initialization and ignores obsolete connection callbacks', async () => { + const callbacks: ListenOptions[] = []; + listen.mockImplementation(async options => { + callbacks.push(options); + return disconnect; + }); + const first = repository.connectWebSocket(account, true, noop); + const firstRejected = expect(first).rejects.toThrow('cancelled'); + await flushConnectionCallbacks(); + let secondReady = false; + async function initializeSecond(): Promise { + await repository.connectWebSocket(account, false, noop); + secondReady = true; + } + const second = initializeSecond(); + await firstRejected; + await flushConnectionCallbacks(); + callbacks[0]?.onConnectionStateChanged?.(ConnectionState.LIVE); + await flushConnectionCallbacks(); + expect(secondReady).toBe(false); + expect(callbacks[0]?.signal?.aborted).toBe(true); + callbacks[1]?.onConnectionStateChanged?.(ConnectionState.LIVE); + await second; + expect(secondReady).toBe(true); + }); + + it('does not reconnect after a pending health check completes following disconnect', async () => { + await connect(); + let finishProbe: (healthy: boolean) => void = noop; + isWebsocketHealthy.mockReturnValue(new Promise(resolve => { finishProbe = resolve; })); + runHeartbeat(); + repository.disconnectWebSocket(); + finishProbe(false); + await flushConnectionCallbacks(); + expect(listen).not.toHaveBeenCalled(); + }); + +}); diff --git a/apps/webapp/src/script/repositories/event/NotificationHandlingState.ts b/apps/webapp/src/script/repositories/event/NotificationHandlingState.ts index d87997e2ecb..5a10888319a 100644 --- a/apps/webapp/src/script/repositories/event/NotificationHandlingState.ts +++ b/apps/webapp/src/script/repositories/event/NotificationHandlingState.ts @@ -18,6 +18,7 @@ */ export enum NOTIFICATION_HANDLING_STATE { + CLOSED = 'z.event.NOTIFICATION_HANDLING_STATE.CLOSED', RECOVERY = 'z.event.NOTIFICATION_HANDLING_STATE.RECOVERY', STREAM = 'z.event.NOTIFICATION_HANDLING_STATE.STREAM', WEB_SOCKET = 'z.event.NOTIFICATION_HANDLING_STATE.WEB_SOCKET', diff --git a/apps/webapp/src/script/repositories/tracking/EventName.ts b/apps/webapp/src/script/repositories/tracking/EventName.ts index d73279ce917..b7dee411d7e 100644 --- a/apps/webapp/src/script/repositories/tracking/EventName.ts +++ b/apps/webapp/src/script/repositories/tracking/EventName.ts @@ -33,6 +33,9 @@ export const EventName = { PRESS_SPACE_TO_UNMUTE: 'calling.press_space_to_unmute', }, CONTRIBUTED: 'contributed', + CONNECTIVITY: { + RETRYING_FOR_ONE_MINUTE: 'connectivity.retrying_for_one_minute', + }, E2EE: { FAILED_MESSAGE_DECRYPTION: 'e2ee.failed_message_decryption', }, diff --git a/apps/webapp/src/script/repositories/tracking/EventTrackingRepository.test.ts b/apps/webapp/src/script/repositories/tracking/EventTrackingRepository.test.ts new file mode 100644 index 00000000000..304a81e31d7 --- /dev/null +++ b/apps/webapp/src/script/repositories/tracking/EventTrackingRepository.test.ts @@ -0,0 +1,251 @@ +/* + * Wire + * Copyright (C) 2018 Wire Swiss GmbH + * + * This program is free software: you can redistribute it and/or modify + * it under the terms of the GNU General Public License as published by + * the Free Software Foundation, either version 3 of the License, or + * (at your option) any later version. + * + * This program is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU General Public License for more details. + * + * You should have received a copy of the GNU General Public License + * along with this program. If not, see http://www.gnu.org/licenses/. + * + */ + +import {WebSocketClient} from '@wireapp/api-client/lib/tcp'; +import {amplify} from 'amplify'; +import {EventEmitter} from 'events'; + +import {WebAppEvents} from '@wireapp/webapp-events'; + +import {Config} from '../../Config'; +import {EventName} from './EventName'; +import {EventTrackingRepository} from './EventTrackingRepository'; +import {disableForcedErrorReporting} from './Telemetry.helpers'; + +type TrackingConstructorInputs = ConstructorParameters; + +describe('WebSocket retry product reporting', () => { + const webSocket = new EventEmitter(); + const retryDetails = {retryCount: 9, retryDurationInMilliseconds: 65_000}; + const telemetry = { + isLoaded: jest.fn(), + changeDeviceId: jest.fn(), + addAllConsentFeatures: jest.fn(), + removeAllConsentFeatures: jest.fn(), + initialize: jest.fn(), + disableOfflineMode: jest.fn(), + endSession: jest.fn(), + beginSession: jest.fn(), + setUserData: jest.fn(), + trackEvent: jest.fn(), + }; + let configuration: ReturnType; + + beforeEach(() => { + disableForcedErrorReporting(); + webSocket.removeAllListeners(); + Object.values(telemetry).forEach(mock => {mock.mockReset();}); + telemetry.isLoaded.mockReturnValue(true); + configuration = { + ...Config.getConfig(), + COUNTLY_API_KEY: 'test-key', + COUNTLY_ALLOWED_BACKEND: 'https://backend.example.test', + BACKEND_REST: 'https://backend.example.test', + COUNTLY_FORCE_REPORTING: false, + }; + jest.spyOn(Config, 'getConfig').mockImplementation(() => {return configuration;}); + window.history.replaceState({}, '', '/?tracking=true'); + }); + + afterEach(() => { + webSocket.removeAllListeners(); + amplify.unsubscribeAll(WebAppEvents.USER.EVENT_FROM_BACKEND); + amplify.unsubscribeAll(WebAppEvents.PROPERTIES.UPDATE.PRIVACY.TELEMETRY_SHARING); + amplify.unsubscribeAll(WebAppEvents.ANALYTICS.EVENT); + amplify.unsubscribeAll(WebAppEvents.LIFECYCLE.SIGNED_OUT); + disableForcedErrorReporting(); + window.history.replaceState({}, '', '/'); + jest.restoreAllMocks(); + }); + + function createRepository(): EventTrackingRepository { + return new EventTrackingRepository( + {sendCountlySync: jest.fn().mockResolvedValue(undefined)} as unknown as TrackingConstructorInputs[0], + {isTeam: () => {return false;}} as TrackingConstructorInputs[1], + {connectedUsers: () => {return [];}} as unknown as TrackingConstructorInputs[2], + {webSocket, telemetry}, + ); + } + + function emitRetry(): void { + webSocket.emit(WebSocketClient.TOPIC.ON_LONG_RUNNING_RETRY, retryDetails); + } + + it('reports the transport retry information through existing product reporting', async () => { + const repository = createRepository(); + await repository.init(true); + telemetry.trackEvent.mockClear(); + + emitRetry(); + + expect(telemetry.trackEvent).toHaveBeenCalledTimes(1); + expect(telemetry.trackEvent).toHaveBeenCalledWith({ + name: EventName.CONNECTIVITY.RETRYING_FOR_ONE_MINUTE, + segmentation: expect.objectContaining({ + retry_count: 9, + retry_duration_in_milliseconds: 65_000, + transport: 'websocket', + }), + }); + expect(telemetry.setUserData).toHaveBeenCalled(); + }); + + it('does not subscribe or report without consent', async () => { + const repository = createRepository(); + await repository.init(false); + emitRetry(); + + expect(webSocket.listenerCount(WebSocketClient.TOPIC.ON_LONG_RUNNING_RETRY)).toBe(0); + expect(telemetry.trackEvent).not.toHaveBeenCalled(); + expect(telemetry.removeAllConsentFeatures).toHaveBeenCalledTimes(1); + }); + + it('does not enable retry reporting during a device-ID migration without consent', async () => { + const repository = createRepository(); + await repository.init(false); + telemetry.changeDeviceId.mockImplementation(() => { + expect(webSocket.listenerCount(WebSocketClient.TOPIC.ON_LONG_RUNNING_RETRY)).toBe(0); + emitRetry(); + }); + + await repository.migrateDeviceId('replacement-tracking-id'); + + expect(telemetry.changeDeviceId).toHaveBeenCalled(); + expect(telemetry.trackEvent).not.toHaveBeenCalledWith(expect.objectContaining({ + name: EventName.CONNECTIVITY.RETRYING_FOR_ONE_MINUTE, + })); + }); + + it('removes the retry subscription on consent withdrawal and rejects an already dispatched callback', async () => { + const repository = createRepository(); + await repository.init(true); + const retryListener = webSocket.listeners(WebSocketClient.TOPIC.ON_LONG_RUNNING_RETRY)[0]; + if (retryListener === undefined) { + throw new Error('Expected active retry subscription'); + } + await repository.init(false); + telemetry.trackEvent.mockClear(); + + emitRetry(); + retryListener(retryDetails); + + expect(webSocket.listenerCount(WebSocketClient.TOPIC.ON_LONG_RUNNING_RETRY)).toBe(0); + expect(telemetry.trackEvent).not.toHaveBeenCalled(); + expect(telemetry.endSession).toHaveBeenCalledTimes(1); + }); + + it('initializes and subscribes once across concurrent and repeated initialization', async () => { + const subscriptions = jest.spyOn(amplify, 'subscribe'); + const repository = createRepository(); + await Promise.all([repository.init(true), repository.init(true)]); + await repository.init(true); + telemetry.trackEvent.mockClear(); + + emitRetry(); + + expect(webSocket.listenerCount(WebSocketClient.TOPIC.ON_LONG_RUNNING_RETRY)).toBe(1); + expect(telemetry.initialize).toHaveBeenCalledTimes(1); + expect(telemetry.beginSession).toHaveBeenCalledTimes(1); + expect(telemetry.trackEvent).toHaveBeenCalledTimes(1); + expect(subscriptions.mock.calls.filter(call => { + return call[0] === WebAppEvents.PROPERTIES.UPDATE.PRIVACY.TELEMETRY_SHARING; + })).toHaveLength(1); + }); + + it('resubscribes once after disable and re-enable', async () => { + const repository = createRepository(); + await repository.init(true); + await repository.init(false); + await repository.init(true); + await repository.init(true); + telemetry.trackEvent.mockClear(); + + emitRetry(); + + expect(webSocket.listenerCount(WebSocketClient.TOPIC.ON_LONG_RUNNING_RETRY)).toBe(1); + expect(telemetry.trackEvent).toHaveBeenCalledTimes(1); + expect(telemetry.initialize).toHaveBeenCalledTimes(1); + expect(telemetry.beginSession).toHaveBeenCalledTimes(2); + }); + + it('honors consent changes delivered by the existing privacy event', async () => { + const repository = createRepository(); + await repository.init(true); + amplify.publish(WebAppEvents.PROPERTIES.UPDATE.PRIVACY.TELEMETRY_SHARING, false); + telemetry.trackEvent.mockClear(); + + emitRetry(); + + expect(webSocket.listenerCount(WebSocketClient.TOPIC.ON_LONG_RUNNING_RETRY)).toBe(0); + expect(telemetry.trackEvent).not.toHaveBeenCalled(); + }); + + it('does not subscribe on a backend outside the telemetry allowlist', async () => { + configuration = {...configuration, COUNTLY_ALLOWED_BACKEND: 'https://other.example.test'}; + await createRepository().init(true); + emitRetry(); + + expect(webSocket.listenerCount(WebSocketClient.TOPIC.ON_LONG_RUNNING_RETRY)).toBe(0); + expect(telemetry.initialize).not.toHaveBeenCalled(); + expect(telemetry.trackEvent).not.toHaveBeenCalled(); + }); + + it('honors domain tracking restrictions even with consent', async () => { + window.history.replaceState({}, '', '/?tracking=false'); + await createRepository().init(true); + emitRetry(); + + expect(webSocket.listenerCount(WebSocketClient.TOPIC.ON_LONG_RUNNING_RETRY)).toBe(0); + expect(telemetry.trackEvent).not.toHaveBeenCalled(); + }); + + it('does not subscribe when telemetry is unavailable', async () => { + telemetry.isLoaded.mockReturnValue(false); + await createRepository().init(true); + emitRetry(); + + expect(webSocket.listenerCount(WebSocketClient.TOPIC.ON_LONG_RUNNING_RETRY)).toBe(0); + expect(telemetry.trackEvent).not.toHaveBeenCalled(); + }); + + it('preserves Q2 forced reporting in configured environments', async () => { + configuration = {...configuration, COUNTLY_FORCE_REPORTING: true}; + const repository = createRepository(); + await repository.init(false); + telemetry.trackEvent.mockClear(); + emitRetry(); + + expect(webSocket.listenerCount(WebSocketClient.TOPIC.ON_LONG_RUNNING_RETRY)).toBe(1); + expect(telemetry.trackEvent).toHaveBeenCalledTimes(1); + }); + + it('can initialize after an earlier attempt lacked a Countly key', async () => { + configuration = {...configuration, COUNTLY_API_KEY: '', COUNTLY_FORCE_REPORTING: true}; + const repository = createRepository(); + await repository.init(true); + expect(webSocket.listenerCount(WebSocketClient.TOPIC.ON_LONG_RUNNING_RETRY)).toBe(0); + configuration = {...configuration, COUNTLY_API_KEY: 'test-key'}; + await repository.init(true); + telemetry.trackEvent.mockClear(); + emitRetry(); + + expect(webSocket.listenerCount(WebSocketClient.TOPIC.ON_LONG_RUNNING_RETRY)).toBe(1); + expect(telemetry.trackEvent).toHaveBeenCalledTimes(1); + }); +}); diff --git a/apps/webapp/src/script/repositories/tracking/EventTrackingRepository.ts b/apps/webapp/src/script/repositories/tracking/EventTrackingRepository.ts index 4e7e61996cd..017ab379fb8 100644 --- a/apps/webapp/src/script/repositories/tracking/EventTrackingRepository.ts +++ b/apps/webapp/src/script/repositories/tracking/EventTrackingRepository.ts @@ -17,6 +17,8 @@ * */ +import {WebSocketClient} from '@wireapp/api-client/lib/tcp'; +import type {LongRunningRetryDetails} from '@wireapp/api-client/lib/tcp/ReconnectingWebsocket'; import {amplify} from 'amplify'; import {container} from 'tsyringe'; @@ -46,14 +48,38 @@ import {UserData} from './UserData'; import {URLParameter} from '../../auth/URLParameter'; import {Config} from '../../Config'; +type ProductReportingTelemetry = Pick< + typeof telemetry, + | 'isLoaded' + | 'changeDeviceId' + | 'addAllConsentFeatures' + | 'removeAllConsentFeatures' + | 'initialize' + | 'disableOfflineMode' + | 'endSession' + | 'beginSession' + | 'setUserData' + | 'trackEvent' +>; + +type EventTrackingDependencies = { + readonly webSocket?: Pick; + readonly telemetry?: ProductReportingTelemetry; +}; + const TEAM_SIZE_THRESHOLD_VALUE = 6; export class EventTrackingRepository { private isProductReportingActivated: boolean = false; + private isProductReportingRequested = false; private sendAppOpenEvent: boolean = true; private telemetryDeviceId: string | undefined; private readonly logger: Logger = getLogger('EventTrackingRepository'); private readonly telemetryLogger: Logger = getLogger('Telemetry'); private telemetryInitialized: boolean = false; + private productEventSubscriptionsActive = false; + private readonly telemetry: ProductReportingTelemetry; + private readonly webSocket: EventTrackingDependencies['webSocket']; + private readonly onLongRunningWebSocketRetry = this.trackLongRunningWebSocketRetry.bind(this); isErrorReportingActivated: boolean = false; static get CONFIG() { @@ -74,7 +100,10 @@ export class EventTrackingRepository { private readonly messageRepository: MessageRepository, private readonly teamState = container.resolve(TeamState), private readonly userState = container.resolve(UserState), + dependencies: EventTrackingDependencies = {}, ) { + this.telemetry = dependencies.telemetry ?? telemetry; + this.webSocket = dependencies.webSocket; amplify.subscribe(WebAppEvents.USER.EVENT_FROM_BACKEND, this.onUserEvent); amplify.subscribe(WebAppEvents.PROPERTIES.UPDATE.PRIVACY.TELEMETRY_SHARING, this.toggleTelemetry); initForcedErrorReporting(); @@ -92,7 +121,7 @@ export class EventTrackingRepository { }; public migrateDeviceId = async (newId: string) => { - if (!telemetry.isLoaded()) { + if (!this.telemetry.isLoaded()) { this.telemetryLogger.warn('Telemetry is not available'); return; } @@ -108,7 +137,7 @@ export class EventTrackingRepository { await this.startProductReporting(this.telemetryDeviceId); stopOnFinish = true; } - telemetry.changeDeviceId(newId); + this.telemetry.changeDeviceId(newId); storeValue(EventTrackingRepository.CONFIG.USER_ANALYTICS.COUNTLY_DEVICE_ID_LOCAL_STORAGE_KEY, newId); this.telemetryLogger.info(`Telemetry tracking id has been changed from ${this.telemetryDeviceId} to ${newId}`); this.telemetryDeviceId = newId; @@ -183,20 +212,21 @@ export class EventTrackingRepository { this.logger.info(`Initialize analytics and error reporting: ${isConsentGiven}`); - amplify.subscribe(WebAppEvents.PROPERTIES.UPDATE.PRIVACY.TELEMETRY_SHARING, this.toggleTelemetry); await this.toggleTelemetry(isConsentGiven); } private readonly toggleTelemetry = async (isEnabled: boolean) => { + this.isProductReportingRequested = isEnabled || getForcedErrorReportingStatus(); if (isEnabled && this.isDomainAllowedForAnalytics()) { - telemetry.addAllConsentFeatures(); + this.telemetry.addAllConsentFeatures(); this.telemetryLogger.info('Consent was given due to user preferences'); await this.startProductReporting(); } else { - telemetry.removeAllConsentFeatures(); + this.telemetry.removeAllConsentFeatures(); this.telemetryLogger.info('Consent was removed due to user preferences'); this.stopProductReporting(); } + this.updateWebSocketRetrySubscription(); }; private stopProductReporting(): void { @@ -206,13 +236,13 @@ export class EventTrackingRepository { } this.logger.debug('Analytics was disabled due to user preferences'); - this.isProductReportingActivated = false; this.stopProductReportingSession(); + this.isProductReportingActivated = false; this.unsubscribeFromProductTrackingEvents(); } private async startProductReporting(trackingId: string = ''): Promise { - if (!telemetry.isLoaded()) { + if (!this.telemetry.isLoaded()) { return; } @@ -221,8 +251,6 @@ export class EventTrackingRepository { return; } - this.isProductReportingActivated = true; - const {COUNTLY_ENABLE_LOGGING, VERSION, COUNTLY_API_KEY, COUNTLY_SERVER_URL} = Config.getConfig(); // Initialize telemetry if it is not initialized yet @@ -232,7 +260,7 @@ export class EventTrackingRepository { return; } - telemetry.initialize({ + this.telemetry.initialize({ appVersion: VERSION, provider: { apiKey: COUNTLY_API_KEY, @@ -261,11 +289,12 @@ export class EventTrackingRepository { return; } - telemetry.changeDeviceId(device_id); - telemetry.disableOfflineMode(device_id); + this.telemetry.changeDeviceId(device_id); + this.telemetry.disableOfflineMode(device_id); this.telemetryLogger.info(`Telemetry tracking id is now ${device_id}`); + this.isProductReportingActivated = true; this.startProductReportingSession(); this.subscribeToProductEvents(); } @@ -285,7 +314,7 @@ export class EventTrackingRepository { } private readonly stopProductReportingSession = (): void => { - if (!telemetry.isLoaded()) { + if (!this.telemetry.isLoaded()) { this.telemetryLogger.warn('Telemetry is not available'); return; } @@ -296,11 +325,15 @@ export class EventTrackingRepository { } if (this.isProductReportingActivated === true) { - telemetry.endSession(); + this.telemetry.endSession(); } }; private subscribeToProductEvents(): void { + if (this.productEventSubscriptionsActive === true) { + return; + } + this.productEventSubscriptionsActive = true; amplify.subscribe( WebAppEvents.ANALYTICS.EVENT, this, @@ -312,14 +345,44 @@ export class EventTrackingRepository { amplify.subscribe(WebAppEvents.LIFECYCLE.SIGNED_OUT, this.stopProductReportingSession); } + private updateWebSocketRetrySubscription(): void { + this.webSocket?.removeListener(WebSocketClient.TOPIC.ON_LONG_RUNNING_RETRY, this.onLongRunningWebSocketRetry); + // Q2 temporarily starts sessions for device-ID migration without product-reporting consent. + if ( + this.isProductReportingActivated === true && + this.isProductReportingRequested === true && + isTelemetryEnabledAtCurrentEnvironment() === true && + this.isDomainAllowedForAnalytics() === true + ) { + this.webSocket?.on(WebSocketClient.TOPIC.ON_LONG_RUNNING_RETRY, this.onLongRunningWebSocketRetry); + } + } + + private trackLongRunningWebSocketRetry(retryDetails: LongRunningRetryDetails): void { + if ( + this.isProductReportingActivated === false || + this.isProductReportingRequested === false || + isTelemetryEnabledAtCurrentEnvironment() === false || + this.isDomainAllowedForAnalytics() === false + ) { + return; + } + + this.trackProductReportingEvent(EventName.CONNECTIVITY.RETRYING_FOR_ONE_MINUTE, { + [Segmentation.CONNECTIVITY.RETRY_COUNT]: retryDetails.retryCount, + [Segmentation.CONNECTIVITY.RETRY_DURATION_IN_MILLISECONDS]: retryDetails.retryDurationInMilliseconds, + [Segmentation.CONNECTIVITY.TRANSPORT]: 'websocket', + }); + } + private startProductReportingSession(): void { - if (!telemetry.isLoaded()) { + if (!this.telemetry.isLoaded()) { this.telemetryLogger.warn('Telemetry is not available'); return; } if (this.isProductReportingActivated === true || getForcedErrorReportingStatus()) { - telemetry.beginSession(); + this.telemetry.beginSession(); if (this.sendAppOpenEvent) { this.sendAppOpenEvent = false; this.trackProductReportingEvent(EventName.APP_OPEN); @@ -349,7 +412,7 @@ export class EventTrackingRepository { } private trackProductReportingEvent(eventName: string, customSegmentations?: ContributedSegmentations): void { - if (!telemetry.isLoaded()) { + if (!this.telemetry.isLoaded()) { this.telemetryLogger.warn('Telemetry is not available'); return; } @@ -357,7 +420,7 @@ export class EventTrackingRepository { if (this.isProductReportingActivated === true || getForcedErrorReportingStatus()) { const userData = this.getUserData(); - telemetry.setUserData(userData); + this.telemetry.setUserData(userData); this.telemetryLogger.info(`Reporting user data for product event ${eventName}@${JSON.stringify(userData)}`); @@ -369,7 +432,7 @@ export class EventTrackingRepository { ...customSegmentations, }; - telemetry.trackEvent({ + this.telemetry.trackEvent({ name: eventName, segmentation, }); @@ -384,6 +447,9 @@ export class EventTrackingRepository { private unsubscribeFromProductTrackingEvents(): void { this.logger.debug('Unsubscribing from product tracking events'); + this.webSocket?.removeListener(WebSocketClient.TOPIC.ON_LONG_RUNNING_RETRY, this.onLongRunningWebSocketRetry); + amplify.unsubscribe(WebAppEvents.LIFECYCLE.SIGNED_OUT, this.stopProductReportingSession); + this.productEventSubscriptionsActive = false; amplify.unsubscribeAll(WebAppEvents.ANALYTICS.EVENT); } } diff --git a/apps/webapp/src/script/repositories/tracking/Segmentation.ts b/apps/webapp/src/script/repositories/tracking/Segmentation.ts index 88f467442d1..cd04ed07840 100644 --- a/apps/webapp/src/script/repositories/tracking/Segmentation.ts +++ b/apps/webapp/src/script/repositories/tracking/Segmentation.ts @@ -18,6 +18,11 @@ */ export const Segmentation = { + CONNECTIVITY: { + RETRY_COUNT: 'retry_count', + RETRY_DURATION_IN_MILLISECONDS: 'retry_duration_in_milliseconds', + TRANSPORT: 'transport', + }, APP_OPEN: { DESKTOP_APP: 'app_desktop_app', APP_VERSION: 'app_version', diff --git a/libraries/api-client/package.json b/libraries/api-client/package.json index bece9578c39..4b123f825d3 100644 --- a/libraries/api-client/package.json +++ b/libraries/api-client/package.json @@ -21,7 +21,7 @@ "axios-retry": "4.5.0", "cells-sdk-ts": "0.1.1-alpha18", "pako": "2.1.0", - "reconnecting-websocket": "4.4.0", + "partysocket": "1.3.0", "spark-md5": "3.0.2", "tough-cookie": "4.1.4", "ws": "8.19.0" diff --git a/libraries/api-client/src/auth/AccessTokenStore.ts b/libraries/api-client/src/auth/AccessTokenStore.ts index f736ebb2bf4..ea5d09b3947 100644 --- a/libraries/api-client/src/auth/AccessTokenStore.ts +++ b/libraries/api-client/src/auth/AccessTokenStore.ts @@ -79,7 +79,7 @@ export class AccessTokenStore extends EventEmitter { public getNextMarkerToken = (): string => { const newMarkerToken = uuidv4(); - this.logger.info('Generated new marker token:', newMarkerToken, 'Previous marker token:', this.markerToken); + this.logger.info('Generated new WebSocket synchronization marker'); this.markerToken = newMarkerToken; return this.markerToken; }; diff --git a/libraries/api-client/src/client/ClientAPI.test.ts b/libraries/api-client/src/client/ClientAPI.test.ts new file mode 100644 index 00000000000..51e310c08fd --- /dev/null +++ b/libraries/api-client/src/client/ClientAPI.test.ts @@ -0,0 +1,47 @@ +/* + * Wire + * Copyright (C) 2018 Wire Swiss GmbH + * + * This program is free software: you can redistribute it and/or modify + * it under the terms of the GNU General Public License as published by + * the Free Software Foundation, either version 3 of the License, or + * (at your option) any later version. + * + * This program is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU General Public License for more details. + * + * You should have received a copy of the GNU General Public License + * along with this program. If not, see http://www.gnu.org/licenses/. + * + */ + +import {HttpClient} from '../http'; +import {ClientAPI} from './ClientAPI'; + +describe('client capability updates before WebSocket connection', () => { + it('disables retries and propagates a failed update so connection setup can recover', async () => { + const updateFailure = new Error('Client capability update failed'); + const sendJSON = jest.fn().mockRejectedValue(updateFailure); + const clientApi = new ClientAPI({sendJSON} as unknown as HttpClient); + + await expect(clientApi.putClientCapabilities('test-client', {capabilities: []})).rejects.toBe(updateFailure); + expect(sendJSON).toHaveBeenCalledTimes(1); + expect(sendJSON).toHaveBeenCalledWith({ + data: {capabilities: []}, + method: 'put', + url: '/clients/test-client', + 'axios-retry': {retries: 0}, + }); + }); + + it.each([{prekeys: [{id: 1, key: 'prekey'}]}, {mls_public_keys: {ed25519: 'public-key'}}])( + 'preserves the default retry policy for ordinary client updates: %s', async update => { + const sendJSON = jest.fn().mockResolvedValue({data: {}}); + const clientApi = new ClientAPI({sendJSON} as unknown as HttpClient); + await clientApi.putClient('test-client', update); + expect(sendJSON).toHaveBeenCalledWith({data: update, method: 'put', url: '/clients/test-client'}); + }, + ); +}); diff --git a/libraries/api-client/src/client/ClientAPI.ts b/libraries/api-client/src/client/ClientAPI.ts index 13f0c1e4732..e566f0d63b8 100644 --- a/libraries/api-client/src/client/ClientAPI.ts +++ b/libraries/api-client/src/client/ClientAPI.ts @@ -50,6 +50,12 @@ export type GetMLSPublicKeysResponseData = { removal: MLSPublicKeyRecord; }; +type ClientUpdateOptions = { + readonly clientId: string; + readonly updatedClient: UpdateClientPayload; + readonly retryCount?: number; +}; + export class ClientAPI { constructor(private readonly client: HttpClient) {} @@ -76,10 +82,20 @@ export class ClientAPI { } public async putClient(clientId: string, updatedClient: UpdateClientPayload): Promise { + return this.updateClient({clientId, updatedClient}); + } + + public async putClientCapabilities(clientId: string, capabilities: ClientCapabilityData): Promise { + return this.updateClient({clientId, updatedClient: capabilities, retryCount: 0}); + } + + private async updateClient(options: ClientUpdateOptions): Promise { + const {clientId, updatedClient, retryCount} = options; const config: AxiosRequestConfig = { data: updatedClient, method: 'put', url: `${ClientAPI.URL.CLIENTS}/${clientId}`, + ...(retryCount === undefined ? {} : {'axios-retry': {retries: retryCount}}), }; try { diff --git a/libraries/api-client/src/http/HttpClient.test.ts b/libraries/api-client/src/http/HttpClient.test.ts index 208045ad1e6..d875f3a35f1 100644 --- a/libraries/api-client/src/http/HttpClient.test.ts +++ b/libraries/api-client/src/http/HttpClient.test.ts @@ -41,6 +41,72 @@ describe('HttpClient', () => { }; describe('"_sendRequest"', () => { + it('preserves a configured signal through automatic authentication recovery', async () => { + const client = new HttpClient(testConfig, new AccessTokenStore()); + const lifetime = new AbortController(); + let rejectRefresh: (error: unknown) => void = () => {}; + const unauthorized = {isAxiosError: true, response: {status: StatusCode.UNAUTHORIZED}}; + const request = jest.spyOn(client.client, 'request') + .mockRejectedValueOnce(unauthorized) + .mockImplementation(() => { + return new Promise((_resolve, reject) => { rejectRefresh = reject; }); + }); + const invalidSession = jest.fn(); + client.on(HttpClient.TOPIC.ON_INVALID_TOKEN, invalidSession); + const pending = client._sendRequest({config: {method: 'get', url: '/cookies', signal: lifetime.signal}}); + const rejected = expect(pending).rejects.toThrow('Cancelled request'); + await Promise.resolve(); + lifetime.abort(); + rejectRefresh(new Error('Cancelled request')); + await rejected; + expect(request).toHaveBeenCalledTimes(2); + expect(request).toHaveBeenNthCalledWith(2, expect.objectContaining({signal: lifetime.signal})); + expect(invalidSession).not.toHaveBeenCalled(); + }); + + it('does not recover authentication from a late response to a cancelled request', async () => { + const client = new HttpClient(testConfig, new AccessTokenStore()); + const lifetime = new AbortController(); + let rejectRequest: (error: unknown) => void = () => {}; + jest.spyOn(client.client, 'request').mockImplementation(() => { + return new Promise((_resolve, reject) => { rejectRequest = reject; }); + }); + const refresh = jest.spyOn(client, 'refreshAccessToken'); + const invalidSession = jest.fn(); + client.on(HttpClient.TOPIC.ON_INVALID_TOKEN, invalidSession); + const request = client._sendRequest({config: {method: 'get', url: '/cookies'}, abortController: lifetime}); + lifetime.abort(); + const responseFailure = {isAxiosError: true, response: {status: StatusCode.UNAUTHORIZED}}; + rejectRequest(responseFailure); + await expect(request).rejects.toBe(responseFailure); + expect(refresh).not.toHaveBeenCalled(); + expect(invalidSession).not.toHaveBeenCalled(); + }); + it('passes refresh cancellation to HTTP and does not save a late token', async () => { + const store = new AccessTokenStore(); + const client = new HttpClient(testConfig, store); + const lifetime = new AbortController(); + let finishRequest: () => void = () => {}; + const request = jest.spyOn(client.client, 'request').mockImplementation(async () => { + await new Promise(resolve => { finishRequest = resolve; }); + return {data: mockedAccessTokenStore.accessTokenData, headers: {}} as never; + }); + const refresh = client.refreshAccessToken(lifetime.signal); + lifetime.abort(); + finishRequest(); + await expect(refresh).rejects.toMatchObject({name: 'AbortError'}); + expect(request).toHaveBeenCalledWith(expect.objectContaining({signal: lifetime.signal})); + expect(store.accessTokenData).toBeUndefined(); + }); + + it('does not start a refresh request after cancellation', async () => { + const client = new HttpClient(testConfig, new AccessTokenStore()); + const lifetime = new AbortController(); + lifetime.abort(); + const request = jest.spyOn(client.client, 'request'); + await expect(client.refreshAccessToken(lifetime.signal)).rejects.toMatchObject({name: 'AbortError'}); + expect(request).not.toHaveBeenCalled(); + }); // eslint-disable-next-line jest/expect-expect it('retries on 403 token expired error', async () => { nock(testConfig.urls.rest).get(AuthAPI.URL.ACCESS).once().reply(StatusCode.FORBIDDEN, { diff --git a/libraries/api-client/src/http/HttpClient.ts b/libraries/api-client/src/http/HttpClient.ts index 485735ee568..4886e60260d 100644 --- a/libraries/api-client/src/http/HttpClient.ts +++ b/libraries/api-client/src/http/HttpClient.ts @@ -52,6 +52,18 @@ type SendRequest = { abortController?: AbortController; }; +type AccessTokenRequestOptions = { + readonly expiredAccessToken?: AccessTokenData; + readonly clientId?: string; + readonly signal?: AxiosRequestConfig['signal']; +}; + +function throwIfRequestAborted(signal: AxiosRequestConfig['signal']): void { + if (signal?.aborted === true) { + throw new DOMException('Access token refresh was cancelled', 'AbortError'); + } +} + export interface HttpClient { on(event: TOPIC.ON_CONNECTION_STATE_CHANGE, listener: (state: ConnectionState) => void): this; @@ -164,7 +176,7 @@ export class HttpClient extends EventEmitter { try { const response = await this.client.request({ ...config, - signal: abortController?.signal, + signal: abortController?.signal ?? config.signal, // We want to prefix all urls, except for the "access" endpoint url: config.url?.startsWith(AuthAPI.URL.ACCESS) ? config.url : `${this.versionPrefix}${config.url}`, maxBodyLength: FILE_SIZE_100_MB, @@ -175,9 +187,12 @@ export class HttpClient extends EventEmitter { return response; } catch (error) { + if (abortController?.signal.aborted === true || config.signal?.aborted === true) { + throw error; + } const retryWithTokenRefresh = async () => { - this.logger.warn(`Access token refresh triggered for "${config.method}" request to "${config.url}".`); - await this.refreshAccessToken(); + this.logger.warn('Access token refresh triggered by an authenticated request'); + await this.refreshAccessToken(abortController?.signal ?? config.signal); config['axios-retry'] = { retries: 0, }; @@ -209,10 +224,7 @@ export class HttpClient extends EventEmitter { mappedError instanceof MissingCookieAndTokenError) ) { // On invalid cookie the application is supposed to logout. - this.logger.warn( - `Cannot renew access token for "${config.method}" request to "${config.url}" because cookie/token is invalid: ${mappedError.message}`, - mappedError, - ); + this.logger.warn('Cannot renew access token because the session is invalid'); this.emit(HttpClient.TOPIC.ON_INVALID_TOKEN, mappedError); } @@ -248,13 +260,15 @@ export class HttpClient extends EventEmitter { return false; } - public async refreshAccessToken(): Promise { + public async refreshAccessToken(signal?: AxiosRequestConfig['signal']): Promise { + throwIfRequestAborted(signal); let expiredAccessToken: AccessTokenData | undefined; if (this.accessTokenStore.accessTokenData?.access_token) { expiredAccessToken = this.accessTokenStore.accessTokenData; } - const accessToken = await this.postAccess(expiredAccessToken); + const accessToken = await this.requestAccessToken({expiredAccessToken, signal}); + throwIfRequestAborted(signal); this.logger.info( `Received updated access token. It will expire in "${accessToken.expires_in}" seconds.`, ObfuscationUtil.obfuscateAccessToken(accessToken), @@ -263,7 +277,14 @@ export class HttpClient extends EventEmitter { } public async postAccess(expiredAccessToken?: AccessTokenData, clientId?: string): Promise { + return this.requestAccessToken({expiredAccessToken, clientId}); + } + + private async requestAccessToken(options: AccessTokenRequestOptions): Promise { + const {expiredAccessToken, clientId, signal} = options; const config: AxiosRequestConfig = { + signal, + ...(signal === undefined ? {} : {requestOptions: {skipLogout: true}}), headers: {}, method: 'post', url: `${AuthAPI.URL.ACCESS}`, diff --git a/libraries/api-client/src/tcp/ReconnectingWebsocket.backFromSleep.test.ts b/libraries/api-client/src/tcp/ReconnectingWebsocket.backFromSleep.test.ts new file mode 100644 index 00000000000..88dfa579d5b --- /dev/null +++ b/libraries/api-client/src/tcp/ReconnectingWebsocket.backFromSleep.test.ts @@ -0,0 +1,334 @@ +/* + * Wire + * Copyright (C) 2026 Wire Swiss GmbH + * + * This program is free software: you can redistribute it and/or modify + * it under the terms of the GNU General Public License as published by + * the Free Software Foundation, either version 3 of the License, or + * (at your option) any later version. + * + * This program is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU General Public License for more details. + * + * You should have received a copy of the GNU General Public License + * along with this program. If not, see http://www.gnu.org/licenses/. + * + */ + +import type {CloseEvent, ErrorEvent} from 'partysocket/ws'; + +import { + CloseEventCode, + ReconnectingWebsocket, + ReconnectingWebsocketWallClock, + WEBSOCKET_STATE, +} from './ReconnectingWebsocket'; + +type BackFromSleepRegistrationWithoutDisconnectedGate = { + readonly callback: () => void; +}; + +type BackFromSleepRegistrationWithDisconnectedGate = { + readonly callback: () => void; + readonly isDisconnected: () => boolean; +}; + +type BackFromSleepRegistration = + | BackFromSleepRegistrationWithoutDisconnectedGate + | BackFromSleepRegistrationWithDisconnectedGate; + +type BackFromSleepHandlerTestDependencies = { + readonly backFromSleepHandler: jest.Mock<() => void, [BackFromSleepRegistration]>; + readonly registrations: BackFromSleepRegistration[]; + readonly stopBackFromSleepHandler: jest.Mock; +}; + +type MockSocket = { + binaryType: BinaryType; + close: jest.Mock; + onclose: ((event: CloseEvent) => void) | null; + onerror: ((event: ErrorEvent) => void) | null; + onmessage: ((event: MessageEvent) => void) | null; + onopen: ((event: Event) => void) | null; + readyState: WEBSOCKET_STATE; + reconnect: jest.Mock; + send: jest.Mock; +}; + +type MockWebsocketFactory = jest.Mock; + +function createTestWallClock(currentTimestampInMilliseconds: number): ReconnectingWebsocketWallClock { + return { + clearInterval: globalThis.clearInterval.bind(globalThis), + clearTimeout: globalThis.clearTimeout.bind(globalThis), + + get currentTimestampInMilliseconds() { + return currentTimestampInMilliseconds; + }, + + setInterval: globalThis.setInterval.bind(globalThis), + setTimeout: globalThis.setTimeout.bind(globalThis), + }; +} + +function expectSocketHandlersToBeBound(socket: MockSocket): void { + expect(socket.onclose).toEqual(expect.any(Function)); + expect(socket.onerror).toEqual(expect.any(Function)); + expect(socket.onmessage).toEqual(expect.any(Function)); + expect(socket.onopen).toEqual(expect.any(Function)); +} + +function createMockSocket(readyState: WEBSOCKET_STATE): MockSocket { + return { + binaryType: 'blob', + close: jest.fn(), + onclose: null, + onerror: null, + onmessage: null, + onopen: null, + readyState, + reconnect: jest.fn(), + send: jest.fn(), + }; +} + +function createMockWebsocketFactory(...sockets: MockSocket[]): MockWebsocketFactory { + const websocketFactory = jest.fn(); + + sockets.forEach(socket => { + websocketFactory.mockReturnValueOnce(socket); + }); + + return websocketFactory; +} + +function createBackFromSleepHandlerTestDependencies(): BackFromSleepHandlerTestDependencies { + const registrations: BackFromSleepRegistration[] = []; + const stopBackFromSleepHandler = jest.fn(); + const backFromSleepHandler = jest.fn((registration: BackFromSleepRegistration) => { + registrations.push(registration); + return stopBackFromSleepHandler; + }); + + return { + backFromSleepHandler, + registrations, + stopBackFromSleepHandler, + }; +} + +function getLatestBackFromSleepRegistration(registrations: BackFromSleepRegistration[]): BackFromSleepRegistration { + const latestRegistration = registrations[registrations.length - 1]; + + if (!latestRegistration) { + throw new Error('Expected onBackFromSleep to have been called'); + } + + return latestRegistration; +} + +describe('ReconnectingWebsocket back from sleep handling', () => { + beforeEach(() => { + jest.clearAllMocks(); + }); + + it('registers onBackFromSleep without an isDisconnected gate', () => { + const {backFromSleepHandler, registrations} = createBackFromSleepHandlerTestDependencies(); + + new ReconnectingWebsocket(jest.fn(), { + backFromSleepHandler: backFromSleepHandler, + pingInterval: undefined, + wallClock: createTestWallClock(0), + websocketFactory: undefined, + }); + + expect(backFromSleepHandler).toHaveBeenCalledTimes(1); + expect(getLatestBackFromSleepRegistration(registrations)).not.toHaveProperty('isDisconnected'); + }); + + it('replaces the socket wrapper when back from sleep is detected while the socket is OPEN', () => { + const {backFromSleepHandler, registrations} = createBackFromSleepHandlerTestDependencies(); + const oldSocket = createMockSocket(WEBSOCKET_STATE.OPEN); + const newSocket = createMockSocket(WEBSOCKET_STATE.CONNECTING); + const websocketFactory = createMockWebsocketFactory(oldSocket, newSocket); + const websocket = new ReconnectingWebsocket(jest.fn(), { + backFromSleepHandler: backFromSleepHandler, + pingInterval: undefined, + wallClock: createTestWallClock(0), + websocketFactory: websocketFactory, + }); + websocket.connect(); + websocket['hasUnansweredPing'] = true; + + getLatestBackFromSleepRegistration(registrations).callback(); + + expect(oldSocket.close).toHaveBeenCalledTimes(1); + expect(oldSocket.close).toHaveBeenCalledWith(CloseEventCode.NORMAL_CLOSURE, 'Back from sleep'); + expect(oldSocket.reconnect).not.toHaveBeenCalled(); + expect(websocketFactory).toHaveBeenCalledTimes(2); + expect(websocket['socket']).toBe(newSocket); + expectSocketHandlersToBeBound(newSocket); + expect(websocket['hasUnansweredPing']).toBe(false); + }); + + it('replaces the socket wrapper when back from sleep is detected while the socket is CLOSED', () => { + const {backFromSleepHandler, registrations} = createBackFromSleepHandlerTestDependencies(); + const oldSocket = createMockSocket(WEBSOCKET_STATE.CLOSED); + const newSocket = createMockSocket(WEBSOCKET_STATE.CONNECTING); + const websocketFactory = createMockWebsocketFactory(oldSocket, newSocket); + const websocket = new ReconnectingWebsocket(jest.fn(), { + backFromSleepHandler: backFromSleepHandler, + pingInterval: undefined, + wallClock: createTestWallClock(0), + websocketFactory: websocketFactory, + }); + websocket.connect(); + + getLatestBackFromSleepRegistration(registrations).callback(); + + expect(oldSocket.close).toHaveBeenCalledTimes(1); + expect(oldSocket.close).toHaveBeenCalledWith(CloseEventCode.NORMAL_CLOSURE, 'Back from sleep'); + expect(oldSocket.reconnect).not.toHaveBeenCalled(); + expect(websocketFactory).toHaveBeenCalledTimes(2); + expect(websocket['socket']).toBe(newSocket); + }); + + it('replaces the socket wrapper when closing the stale socket after wake fails', () => { + const {backFromSleepHandler, registrations} = createBackFromSleepHandlerTestDependencies(); + const closeError = new Error('close failed'); + const oldSocket = createMockSocket(WEBSOCKET_STATE.CLOSED); + const newSocket = createMockSocket(WEBSOCKET_STATE.CONNECTING); + const websocketFactory = createMockWebsocketFactory(oldSocket, newSocket); + const websocket = new ReconnectingWebsocket(jest.fn(), { + backFromSleepHandler: backFromSleepHandler, + pingInterval: undefined, + wallClock: createTestWallClock(0), + websocketFactory: websocketFactory, + }); + oldSocket.close.mockImplementation(() => { + throw closeError; + }); + websocket.connect(); + + expect(() => getLatestBackFromSleepRegistration(registrations).callback()).not.toThrow(); + + expect(oldSocket.close).toHaveBeenCalledTimes(1); + expect(oldSocket.reconnect).not.toHaveBeenCalled(); + expect(websocketFactory).toHaveBeenCalledTimes(2); + expect(websocket['socket']).toBe(newSocket); + }); + + it('ignores late events from the stale socket after back-from-sleep replacement', () => { + const {backFromSleepHandler, registrations} = createBackFromSleepHandlerTestDependencies(); + const oldSocket = createMockSocket(WEBSOCKET_STATE.OPEN); + const newSocket = createMockSocket(WEBSOCKET_STATE.CONNECTING); + const websocketFactory = createMockWebsocketFactory(oldSocket, newSocket); + const onOpen = jest.fn(); + const onMessage = jest.fn(); + const openEvent = {type: 'open'} as Event; + const staleMessage = {data: Buffer.from('stale message', 'utf-8')} as MessageEvent; + const activeMessage = {data: Buffer.from('active message', 'utf-8')} as MessageEvent; + const websocket = new ReconnectingWebsocket(jest.fn(), { + backFromSleepHandler: backFromSleepHandler, + pingInterval: undefined, + wallClock: createTestWallClock(0), + websocketFactory: websocketFactory, + }); + websocket.setOnOpen(onOpen); + websocket.setOnMessage(onMessage); + websocket.connect(); + + getLatestBackFromSleepRegistration(registrations).callback(); + oldSocket.onopen?.(openEvent); + oldSocket.onmessage?.(staleMessage); + + expect(onOpen).not.toHaveBeenCalled(); + expect(onMessage).not.toHaveBeenCalled(); + + newSocket.onopen?.(openEvent); + newSocket.onmessage?.(activeMessage); + + expect(onOpen).toHaveBeenCalledTimes(1); + expect(onMessage).toHaveBeenCalledTimes(1); + expect(onMessage).toHaveBeenCalledWith('active message'); + }); + + it('does not throw or reconnect when back from sleep is detected without a socket instance', () => { + const {backFromSleepHandler, registrations} = createBackFromSleepHandlerTestDependencies(); + new ReconnectingWebsocket(jest.fn(), { + backFromSleepHandler: backFromSleepHandler, + pingInterval: undefined, + wallClock: createTestWallClock(0), + websocketFactory: undefined, + }); + + expect(() => getLatestBackFromSleepRegistration(registrations).callback()).not.toThrow(); + }); + + it('restarts the sleep handler after disconnect and does not register duplicates while active', () => { + const {backFromSleepHandler, stopBackFromSleepHandler} = createBackFromSleepHandlerTestDependencies(); + const socket = createMockSocket(WEBSOCKET_STATE.OPEN); + const websocket = new ReconnectingWebsocket(jest.fn(), { + backFromSleepHandler: backFromSleepHandler, + pingInterval: undefined, + wallClock: createTestWallClock(0), + websocketFactory: () => { + return socket; + }, + }); + + websocket.connect(); + + expect(backFromSleepHandler).toHaveBeenCalledTimes(1); + + websocket.disconnect(); + + expect(stopBackFromSleepHandler).toHaveBeenCalledTimes(1); + + socket.readyState = WEBSOCKET_STATE.CLOSED; + websocket.connect(); + websocket.connect(); + + expect(backFromSleepHandler).toHaveBeenCalledTimes(2); + expect(stopBackFromSleepHandler).toHaveBeenCalledTimes(1); + + websocket.disconnect(); + }); + it('correlates attempts across wrapper replacement and suppresses sensitive transport diagnostics', async () => { + const {backFromSleepHandler, registrations} = createBackFromSleepHandlerTestDependencies(); + const oldSocket = createMockSocket(WEBSOCKET_STATE.OPEN); + const nextSocket = createMockSocket(WEBSOCKET_STATE.OPEN); + const onReconnect = jest.fn().mockResolvedValue('wss://example.test?access_token=secret'); + const websocket = new ReconnectingWebsocket(onReconnect, { + backFromSleepHandler, + wallClock: createTestWallClock(10_000), + websocketFactory: createMockWebsocketFactory(oldSocket, nextSocket), + }); + const information = jest.spyOn(websocket['logger'], 'info'); + const warning = jest.spyOn(websocket['logger'], 'warn'); + const onOpen = jest.fn(); + websocket.setOnOpen(onOpen); + websocket.disablePinging(); + websocket.connect(); + await websocket['internalOnReconnect'](); + oldSocket.onopen?.(new Event('open')); + expect(onOpen).toHaveBeenLastCalledWith(expect.any(Event), expect.objectContaining({attemptId: 1, wrapperGeneration: 1})); + websocket['handleBackFromSleep']({expectedIntervalMilliseconds: 2000, observedIntervalMilliseconds: 10_000, suspensionDurationMilliseconds: 8000}); + await websocket['internalOnReconnect'](); + nextSocket.onopen?.(new Event('open')); + expect(onOpen).toHaveBeenLastCalledWith(expect.any(Event), expect.objectContaining({attemptId: 2, wrapperGeneration: 2})); + const numberOfLogs = information.mock.calls.length; + oldSocket.onopen?.(new Event('open')); + expect(information).toHaveBeenCalledTimes(numberOfLogs); + nextSocket.onerror?.({message: 'private-error access_token=secret'} as ErrorEvent); + nextSocket.onclose?.({code: 1006, reason: 'private-close Cookie: secret', wasClean: false} as CloseEvent); + websocket.disconnect('private-disconnect'); + expect(information).toHaveBeenCalledWith(expect.stringContaining('suspensionDurationMs=8000')); + expect(information).toHaveBeenCalledWith(expect.stringContaining('event=socket-open attemptId=2 wrapperGeneration=2')); + expect(JSON.stringify([...information.mock.calls, ...warning.mock.calls])).not.toMatch(/private-error|private-close|private-disconnect|access_token|Cookie:/); + expect(getLatestBackFromSleepRegistration(registrations)).toBeDefined(); + }); + +}); diff --git a/libraries/api-client/src/tcp/ReconnectingWebsocket.browserConstructor.test.ts b/libraries/api-client/src/tcp/ReconnectingWebsocket.browserConstructor.test.ts new file mode 100644 index 00000000000..4bc5c54063d --- /dev/null +++ b/libraries/api-client/src/tcp/ReconnectingWebsocket.browserConstructor.test.ts @@ -0,0 +1,53 @@ +/* + * Wire + * Copyright (C) 2026 Wire Swiss GmbH + * + * This program is free software: you can redistribute it and/or modify + * it under the terms of the GNU General Public License as published by + * the Free Software Foundation, either version 3 of the License, or + * (at your option) any later version. + * + * This program is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU General Public License for more details. + * + * You should have received a copy of the GNU General Public License + * along with this program. If not, see http://www.gnu.org/licenses/. + * + */ + +import {createPartysocketCompatibleWebSocketConstructor} from './ReconnectingWebsocket'; + +describe('createPartysocketCompatibleWebSocketConstructor', () => { + it('preserves an undefined constructor so browser builds can use the global WebSocket fallback', () => { + const constructorForPartysocket = createPartysocketCompatibleWebSocketConstructor(undefined); + + expect(constructorForPartysocket).toBeUndefined(); + }); + + it('does not wrap the browser global WebSocket constructor', () => { + const originalWebSocketDescriptor = Object.getOwnPropertyDescriptor(globalThis, 'WebSocket'); + + class BrowserWebSocket {} + + Object.defineProperty(globalThis, 'WebSocket', { + configurable: true, + value: BrowserWebSocket, + }); + + try { + const constructorForPartysocket = createPartysocketCompatibleWebSocketConstructor( + BrowserWebSocket as unknown as typeof globalThis.WebSocket, + ); + + expect(constructorForPartysocket).toBe(BrowserWebSocket); + } finally { + if (originalWebSocketDescriptor) { + Object.defineProperty(globalThis, 'WebSocket', originalWebSocketDescriptor); + } else { + delete (globalThis as Partial).WebSocket; + } + } + }); +}); diff --git a/libraries/api-client/src/tcp/ReconnectingWebsocket.test.ts b/libraries/api-client/src/tcp/ReconnectingWebsocket.test.ts index a74e2a1e34c..9bb3b291494 100644 --- a/libraries/api-client/src/tcp/ReconnectingWebsocket.test.ts +++ b/libraries/api-client/src/tcp/ReconnectingWebsocket.test.ts @@ -19,28 +19,137 @@ /* eslint-disable no-magic-numbers */ +import {once} from 'events'; +import type {CloseEvent, ErrorEvent} from 'partysocket/ws'; import {Server as WebSocketServer} from 'ws'; import {AddressInfo} from 'net'; -import {PingMessage, ReconnectingWebsocket, WEBSOCKET_STATE} from './ReconnectingWebsocket'; +import { + CloseEventCode, + PingMessage, + ReconnectingWebsocket, + ReconnectingWebsocketWallClock, + WEBSOCKET_STATE, +} from './ReconnectingWebsocket'; + +type TimeoutRegistration = { + readonly execute: () => void; + readonly executionTimestampInMilliseconds: number; +}; + +type DeterministicTimeoutWallClock = ReconnectingWebsocketWallClock & { + readonly advanceByMilliseconds: (delayInMilliseconds: number) => void; +}; + +type MockReconnectingWebsocketWrapper = { + binaryType: BinaryType; + close: jest.Mock; + onclose: ((event: CloseEvent) => void) | null; + onerror: ((event: ErrorEvent) => void) | null; + onmessage: ((event: MessageEvent) => void) | null; + onopen: ((event: Event) => void) | null; + readyState: WEBSOCKET_STATE; + reconnect: jest.Mock; + send: jest.Mock; +}; + +function createMockReconnectingWebsocketWrapper(readyState: WEBSOCKET_STATE): MockReconnectingWebsocketWrapper { + const socket: MockReconnectingWebsocketWrapper = { + binaryType: 'blob', + close: jest.fn(() => { + socket.readyState = WEBSOCKET_STATE.CLOSED; + }), + onclose: null, + onerror: null, + onmessage: null, + onopen: null, + readyState, + reconnect: jest.fn(), + send: jest.fn(), + }; -const reservedPorts: number[] = []; + return socket; +} -function startEchoServer(): WebSocketServer { - const getWebsocketPort = () => { - const WEBSOCKET_START_PORT = 8087; - let currentPort = WEBSOCKET_START_PORT; - while (currentPort++) { - if (!reservedPorts.includes(currentPort)) { - reservedPorts.push(currentPort); - break; - } - } - return currentPort; +function expectSocketHandlersToBeBound(socket: MockReconnectingWebsocketWrapper): void { + expect(socket.onclose).toEqual(expect.any(Function)); + expect(socket.onerror).toEqual(expect.any(Function)); + expect(socket.onmessage).toEqual(expect.any(Function)); + expect(socket.onopen).toEqual(expect.any(Function)); +} + +function createDeterministicTimeoutWallClock( + initialCurrentTimestampInMilliseconds: number, +): DeterministicTimeoutWallClock { + let currentTimestampInMilliseconds = initialCurrentTimestampInMilliseconds; + let nextTimeoutIdentifier = 0; + const timeoutRegistrations = new Map(); + + function runDueTimeoutRegistrations(): void { + const dueTimeoutRegistrations = Array.from(timeoutRegistrations.entries()) + .filter(([, timeoutRegistration]) => { + return timeoutRegistration.executionTimestampInMilliseconds <= currentTimestampInMilliseconds; + }) + .toSorted((firstTimeoutEntry, secondTimeoutEntry) => { + const [firstTimeoutIdentifier, firstTimeoutRegistration] = firstTimeoutEntry; + const [secondTimeoutIdentifier, secondTimeoutRegistration] = secondTimeoutEntry; + + if ( + firstTimeoutRegistration.executionTimestampInMilliseconds !== + secondTimeoutRegistration.executionTimestampInMilliseconds + ) { + return ( + firstTimeoutRegistration.executionTimestampInMilliseconds - + secondTimeoutRegistration.executionTimestampInMilliseconds + ); + } + + return firstTimeoutIdentifier - secondTimeoutIdentifier; + }); + + dueTimeoutRegistrations.forEach(([timeoutIdentifier, timeoutRegistration]) => { + timeoutRegistrations.delete(timeoutIdentifier); + timeoutRegistration.execute(); + }); + } + + return { + advanceByMilliseconds(delayInMilliseconds: number): void { + currentTimestampInMilliseconds += delayInMilliseconds; + runDueTimeoutRegistrations(); + }, + + clearInterval: globalThis.clearInterval.bind(globalThis), + + clearTimeout(timeoutIdentifier): void { + timeoutRegistrations.delete(timeoutIdentifier as unknown as number); + }, + + get currentTimestampInMilliseconds() { + return currentTimestampInMilliseconds; + }, + + setInterval: globalThis.setInterval.bind(globalThis), + + setTimeout(handler, delayInMilliseconds, ...handlerArguments) { + const timeoutIdentifier = nextTimeoutIdentifier; + nextTimeoutIdentifier += 1; + + timeoutRegistrations.set(timeoutIdentifier, { + execute: () => { + handler(...handlerArguments); + }, + executionTimestampInMilliseconds: currentTimestampInMilliseconds + delayInMilliseconds, + }); + + return timeoutIdentifier as unknown as ReturnType; + }, }; - const PORT = getWebsocketPort(); - const server = new WebSocketServer({port: PORT}); +} + +async function startEchoServer(): Promise { + const server = new WebSocketServer({host: '127.0.0.1', port: 0}); server.on('connection', ws => { ws.on('message', message => { server.clients.forEach(client => { @@ -63,31 +172,80 @@ function startEchoServer(): WebSocketServer { }); server.on('error', error => console.error(`Echo WebSocket server error: "${error.message}"`)); + await once(server, 'listening'); return server; } /* eslint-disable jest/no-done-callback */ describe('ReconnectingWebsocket', () => { + it('does not send health-check pings on async notification sockets', async () => { + const socket = createMockReconnectingWebsocketWrapper(WEBSOCKET_STATE.OPEN); + const websocket = new ReconnectingWebsocket( + async () => { + return 'wss://example.test/events'; + }, + { + websocketFactory: () => { + return socket; + }, + }, + ); + websocket.disablePinging(); + websocket.connect(); + + try { + expect(await websocket.checkHealth()).toBe(true); + expect(socket.send).not.toHaveBeenCalled(); + } finally { + websocket.disconnect(); + } + }); + let server: WebSocketServer | undefined; + let currentTimestampInMilliseconds = 1_000_000; const activeConnections: ReconnectingWebsocket[] = []; + const testWallClock = { + clearInterval: globalThis.clearInterval.bind(globalThis), + clearTimeout: globalThis.clearTimeout.bind(globalThis), + + get currentTimestampInMilliseconds() { + return currentTimestampInMilliseconds; + }, + + setInterval: globalThis.setInterval.bind(globalThis), + setTimeout: globalThis.setTimeout.bind(globalThis), + }; + const defaultReconnectingWebsocketTestOptions = { + backFromSleepHandler: undefined, + pingInterval: undefined, + wallClock: testWallClock, + websocketFactory: undefined, + }; const getServerAddress = () => { - if (server) { - const address: AddressInfo = server.address() as AddressInfo; + if (server !== undefined) { + const address = server.address(); + if (address === null || address === undefined || typeof address === 'string') { + throw new Error('Server address is unavailable'); + } return Promise.resolve(`ws://127.0.0.1:${address.port}`); } throw new Error('Server is undefined'); }; - const createRWS = (onReconnect: () => Promise, options?: {pingInterval?: number}) => { + function createRWS( + onReconnect: () => Promise, + options = defaultReconnectingWebsocketTestOptions, + ): ReconnectingWebsocket { const rws = new ReconnectingWebsocket(onReconnect, options); activeConnections.push(rws); return rws; - }; + } - beforeEach(() => { - server = startEchoServer(); + beforeEach(async () => { + currentTimestampInMilliseconds = 1_000_000; + server = await startEchoServer(); }); afterEach(done => { @@ -95,13 +253,13 @@ describe('ReconnectingWebsocket', () => { activeConnections.forEach(rws => { try { rws.disconnect(); - } catch (e) { + } catch (e: unknown) { // Ignore errors during cleanup } }); activeConnections.length = 0; - if (server) { + if (server !== undefined) { server.close(() => { server = undefined; done(); @@ -125,6 +283,504 @@ describe('ReconnectingWebsocket', () => { RWS.connect(); }); + it.each([ + {socketState: WEBSOCKET_STATE.OPEN, socketStateName: 'OPEN'}, + {socketState: WEBSOCKET_STATE.CONNECTING, socketStateName: 'CONNECTING'}, + {socketState: WEBSOCKET_STATE.CLOSING, socketStateName: 'CLOSING'}, + ])('reconnects the existing $socketStateName socket in place when connect is called again', ({socketState}) => { + const onReconnect = jest.fn().mockReturnValue(getServerAddress()); + const socket = createMockReconnectingWebsocketWrapper(socketState); + const websocketFactory = jest.fn(() => { + return socket; + }); + const RWS = createRWS(onReconnect, { + ...defaultReconnectingWebsocketTestOptions, + websocketFactory: websocketFactory, + }); + + RWS.connect(); + RWS.connect(); + + expect(websocketFactory).toHaveBeenCalledTimes(1); + expect(socket.reconnect).toHaveBeenCalledTimes(1); + expect(socket.reconnect).toHaveBeenCalledWith(CloseEventCode.NORMAL_CLOSURE); + expect(socket.close).not.toHaveBeenCalled(); + expect(RWS['socket']).toBe(socket); + + RWS.disconnect(); + }); + + it('creates a fresh wrapper when connect is called on an existing closed socket', () => { + const onReconnect = jest.fn().mockReturnValue(getServerAddress()); + const closedSocket = createMockReconnectingWebsocketWrapper(WEBSOCKET_STATE.CLOSED); + const nextSocket = createMockReconnectingWebsocketWrapper(WEBSOCKET_STATE.CONNECTING); + const sockets = [closedSocket, nextSocket]; + const websocketFactory = jest.fn(() => { + const socket = sockets[websocketFactory.mock.calls.length - 1]; + + if (!socket) { + throw new Error('Unexpected websocketFactory call'); + } + + return socket; + }); + const RWS = createRWS(onReconnect, { + ...defaultReconnectingWebsocketTestOptions, + websocketFactory: websocketFactory, + }); + + RWS.connect(); + expect(RWS['socket']).toBe(closedSocket); + + RWS.connect(); + + expect(closedSocket.reconnect).not.toHaveBeenCalled(); + expect(websocketFactory).toHaveBeenCalledTimes(2); + expect(RWS['socket']).toBe(nextSocket); + expectSocketHandlersToBeBound(nextSocket); + + RWS.disconnect(); + }); + + it('creates a fresh wrapper when reconnecting after disconnect left the existing socket closed', () => { + const onReconnect = jest.fn().mockReturnValue(getServerAddress()); + const firstSocket = createMockReconnectingWebsocketWrapper(WEBSOCKET_STATE.OPEN); + const secondSocket = createMockReconnectingWebsocketWrapper(WEBSOCKET_STATE.CONNECTING); + const sockets = [firstSocket, secondSocket]; + const websocketFactory = jest.fn(() => { + const socket = sockets[websocketFactory.mock.calls.length - 1]; + + if (!socket) { + throw new Error('Unexpected websocketFactory call'); + } + + return socket; + }); + const RWS = createRWS(onReconnect, { + ...defaultReconnectingWebsocketTestOptions, + websocketFactory: websocketFactory, + }); + + RWS.connect(); + RWS.disconnect(); + + expect(firstSocket.close).toHaveBeenCalledWith(CloseEventCode.NORMAL_CLOSURE, 'Closed by client'); + expect(firstSocket.readyState).toBe(WEBSOCKET_STATE.CLOSED); + + RWS.connect(); + + expect(firstSocket.reconnect).not.toHaveBeenCalled(); + expect(websocketFactory).toHaveBeenCalledTimes(2); + expect(RWS['socket']).toBe(secondSocket); + expectSocketHandlersToBeBound(secondSocket); + + RWS.disconnect(); + }); + + describe('connecting watchdog', () => { + const connectingTimeoutInMilliseconds = 20_000; + + function createSocketFactory( + ...sockets: MockReconnectingWebsocketWrapper[] + ): jest.Mock { + const websocketFactory = jest.fn(); + + sockets.forEach(socket => { + websocketFactory.mockReturnValueOnce(socket); + }); + + return websocketFactory; + } + + it('replaces the socket wrapper when it stays CONNECTING past the watchdog timeout', async () => { + const deterministicWallClock = createDeterministicTimeoutWallClock(0); + const firstSocket = createMockReconnectingWebsocketWrapper(WEBSOCKET_STATE.CONNECTING); + const secondSocket = createMockReconnectingWebsocketWrapper(WEBSOCKET_STATE.CONNECTING); + const websocketFactory = createSocketFactory(firstSocket, secondSocket); + const RWS = createRWS(jest.fn().mockResolvedValue('wss://example.invalid'), { + ...defaultReconnectingWebsocketTestOptions, + wallClock: deterministicWallClock, + websocketFactory: websocketFactory, + }); + + RWS.connect(); + await RWS['internalOnReconnect'](); + + deterministicWallClock.advanceByMilliseconds(connectingTimeoutInMilliseconds - 1); + + expect(websocketFactory).toHaveBeenCalledTimes(1); + expect(RWS['socket']).toBe(firstSocket); + expect(firstSocket.close).not.toHaveBeenCalled(); + + deterministicWallClock.advanceByMilliseconds(1); + + expect(firstSocket.close).toHaveBeenCalledTimes(1); + expect(firstSocket.close).toHaveBeenCalledWith(CloseEventCode.NORMAL_CLOSURE, 'Connecting timeout'); + expect(websocketFactory).toHaveBeenCalledTimes(2); + expect(RWS['socket']).toBe(secondSocket); + expectSocketHandlersToBeBound(secondSocket); + }); + + it('does not start the connecting watchdog while waiting for the reconnect URL', async () => { + const deterministicWallClock = createDeterministicTimeoutWallClock(0); + const firstSocket = createMockReconnectingWebsocketWrapper(WEBSOCKET_STATE.CONNECTING); + const secondSocket = createMockReconnectingWebsocketWrapper(WEBSOCKET_STATE.CONNECTING); + const websocketFactory = createSocketFactory(firstSocket, secondSocket); + let resolveReconnectUrl: (websocketUrl: string) => void = () => {}; + const reconnectUrlPromise = new Promise(resolve => { + resolveReconnectUrl = resolve; + }); + const RWS = createRWS( + jest.fn(() => reconnectUrlPromise), + { + ...defaultReconnectingWebsocketTestOptions, + wallClock: deterministicWallClock, + websocketFactory: websocketFactory, + }, + ); + + RWS.connect(); + const reconnectPromise = RWS['internalOnReconnect'](); + + deterministicWallClock.advanceByMilliseconds(connectingTimeoutInMilliseconds); + + expect(firstSocket.close).not.toHaveBeenCalled(); + expect(websocketFactory).toHaveBeenCalledTimes(1); + expect(RWS['socket']).toBe(firstSocket); + expect(RWS['connectingTimeoutId']).toBeUndefined(); + + resolveReconnectUrl('wss://example.invalid'); + await expect(reconnectPromise).resolves.toBe('wss://example.invalid'); + + expect(RWS['connectingTimeoutId']).toBeDefined(); + + deterministicWallClock.advanceByMilliseconds(connectingTimeoutInMilliseconds); + + expect(firstSocket.close).toHaveBeenCalledTimes(1); + expect(firstSocket.close).toHaveBeenCalledWith(CloseEventCode.NORMAL_CLOSURE, 'Connecting timeout'); + expect(websocketFactory).toHaveBeenCalledTimes(2); + expect(RWS['socket']).toBe(secondSocket); + }); + + it('rejects a delayed URL callback from a disconnected wrapper before authentication starts', async () => { + const socket = createMockReconnectingWebsocketWrapper(WEBSOCKET_STATE.CONNECTING); + let resolveUrl: (() => Promise) | undefined; + const authenticate = jest.fn().mockResolvedValue('wss://example.invalid'); + const transport = createRWS(authenticate, { + ...defaultReconnectingWebsocketTestOptions, + websocketFactory(provider) { resolveUrl = provider; return socket; }, + }); + transport.connect(); + transport.disconnect(); + if (resolveUrl === undefined) { throw new Error('Expected a URL provider'); } + await expect(resolveUrl()).rejects.toMatchObject({name: 'AbortError'}); + expect(authenticate).not.toHaveBeenCalled(); + }); + + it('does not arm a watchdog from a reconnect flow whose socket was replaced while waiting for the reconnect URL', async () => { + const deterministicWallClock = createDeterministicTimeoutWallClock(0); + const firstSocket = createMockReconnectingWebsocketWrapper(WEBSOCKET_STATE.CONNECTING); + const secondSocket = createMockReconnectingWebsocketWrapper(WEBSOCKET_STATE.CONNECTING); + const thirdSocket = createMockReconnectingWebsocketWrapper(WEBSOCKET_STATE.CONNECTING); + const websocketFactory = createSocketFactory(firstSocket, secondSocket, thirdSocket); + let resolveReconnectUrl: (websocketUrl: string) => void = () => {}; + const reconnectUrlPromise = new Promise(resolve => { + resolveReconnectUrl = resolve; + }); + const RWS = createRWS( + jest.fn(() => reconnectUrlPromise), + { + ...defaultReconnectingWebsocketTestOptions, + wallClock: deterministicWallClock, + websocketFactory: websocketFactory, + }, + ); + + RWS.connect(); + const reconnectPromise = RWS['internalOnReconnect'](); + + RWS['replaceSocketWrapper'](firstSocket, 'Manual replacement'); + + expect(RWS['socket']).toBe(secondSocket); + expect(RWS['connectingTimeoutId']).toBeUndefined(); + + resolveReconnectUrl('wss://example.invalid'); + await expect(reconnectPromise).rejects.toMatchObject({name: 'AbortError'}); + + expect(RWS['connectingTimeoutId']).toBeUndefined(); + + deterministicWallClock.advanceByMilliseconds(connectingTimeoutInMilliseconds); + + expect(websocketFactory).toHaveBeenCalledTimes(2); + expect(secondSocket.close).not.toHaveBeenCalled(); + expect(RWS['socket']).toBe(secondSocket); + expect(RWS['socket']).not.toBe(thirdSocket); + }); + + it('restarts the watchdog from internalOnReconnect after close stopped it', async () => { + const deterministicWallClock = createDeterministicTimeoutWallClock(0); + const firstSocket = createMockReconnectingWebsocketWrapper(WEBSOCKET_STATE.CONNECTING); + const secondSocket = createMockReconnectingWebsocketWrapper(WEBSOCKET_STATE.CONNECTING); + const websocketFactory = createSocketFactory(firstSocket, secondSocket); + const RWS = createRWS(jest.fn().mockResolvedValue('wss://example.invalid'), { + ...defaultReconnectingWebsocketTestOptions, + wallClock: deterministicWallClock, + websocketFactory: websocketFactory, + }); + + RWS.connect(); + + await RWS['internalOnReconnect'](); + + expect(RWS['connectingTimeoutId']).toBeDefined(); + + firstSocket.onclose?.({code: CloseEventCode.NORMAL_CLOSURE, reason: 'closed', wasClean: true} as CloseEvent); + + expect(RWS['connectingTimeoutId']).toBeUndefined(); + + firstSocket.readyState = WEBSOCKET_STATE.CONNECTING; + await RWS['internalOnReconnect'](); + + expect(RWS['connectingTimeoutId']).toBeDefined(); + + deterministicWallClock.advanceByMilliseconds(connectingTimeoutInMilliseconds); + + expect(firstSocket.close).toHaveBeenCalledTimes(1); + expect(firstSocket.close).toHaveBeenCalledWith(CloseEventCode.NORMAL_CLOSURE, 'Connecting timeout'); + expect(websocketFactory).toHaveBeenCalledTimes(2); + expect(RWS['socket']).toBe(secondSocket); + }); + + it('does not throw when internalOnReconnect runs before a socket is assigned', async () => { + const RWS = createRWS(jest.fn().mockResolvedValue('wss://example.invalid')); + + await expect(RWS['internalOnReconnect']()).resolves.toBe('wss://example.invalid'); + }); + + it('does not start the watchdog after internalOnReconnect resolves if the socket is already OPEN', async () => { + const deterministicWallClock = createDeterministicTimeoutWallClock(0); + const firstSocket = createMockReconnectingWebsocketWrapper(WEBSOCKET_STATE.OPEN); + const secondSocket = createMockReconnectingWebsocketWrapper(WEBSOCKET_STATE.CONNECTING); + const websocketFactory = createSocketFactory(firstSocket, secondSocket); + const RWS = createRWS(jest.fn().mockResolvedValue('wss://example.invalid'), { + ...defaultReconnectingWebsocketTestOptions, + wallClock: deterministicWallClock, + websocketFactory: websocketFactory, + }); + + RWS.connect(); + firstSocket.onopen?.({type: 'open'} as Event); + + expect(RWS['connectingTimeoutId']).toBeUndefined(); + + await RWS['internalOnReconnect'](); + + expect(RWS['connectingTimeoutId']).toBeUndefined(); + + deterministicWallClock.advanceByMilliseconds(connectingTimeoutInMilliseconds); + + expect(firstSocket.close).not.toHaveBeenCalled(); + expect(websocketFactory).toHaveBeenCalledTimes(1); + expect(RWS['socket']).toBe(firstSocket); + expect(RWS['connectingTimeoutId']).toBeUndefined(); + }); + + it('starts the watchdog when reconnecting in place', async () => { + const deterministicWallClock = createDeterministicTimeoutWallClock(0); + const firstSocket = createMockReconnectingWebsocketWrapper(WEBSOCKET_STATE.OPEN); + const secondSocket = createMockReconnectingWebsocketWrapper(WEBSOCKET_STATE.CONNECTING); + const websocketFactory = createSocketFactory(firstSocket, secondSocket); + firstSocket.reconnect.mockImplementation(() => { + firstSocket.readyState = WEBSOCKET_STATE.CONNECTING; + }); + const RWS = createRWS(jest.fn().mockResolvedValue('wss://example.invalid'), { + ...defaultReconnectingWebsocketTestOptions, + wallClock: deterministicWallClock, + websocketFactory: websocketFactory, + }); + + RWS.connect(); + firstSocket.onopen?.({type: 'open'} as Event); + + expect(RWS['connectingTimeoutId']).toBeUndefined(); + + RWS.connect(); + + expect(firstSocket.reconnect).toHaveBeenCalledTimes(1); + await RWS['internalOnReconnect'](); + expect(RWS['connectingTimeoutId']).toBeDefined(); + + deterministicWallClock.advanceByMilliseconds(connectingTimeoutInMilliseconds); + + expect(firstSocket.close).toHaveBeenCalledTimes(1); + expect(firstSocket.close).toHaveBeenCalledWith(CloseEventCode.NORMAL_CLOSURE, 'Connecting timeout'); + expect(websocketFactory).toHaveBeenCalledTimes(2); + expect(RWS['socket']).toBe(secondSocket); + }); + + it('does not let repeated internalOnReconnect watchdog timers replace a newer socket wrapper', async () => { + const deterministicWallClock = createDeterministicTimeoutWallClock(0); + let shouldClearTimeout = true; + const wallClockWithOptionalClear: DeterministicTimeoutWallClock = { + advanceByMilliseconds: deterministicWallClock.advanceByMilliseconds, + clearInterval: deterministicWallClock.clearInterval, + clearTimeout(timeoutIdentifier): void { + if (shouldClearTimeout) { + deterministicWallClock.clearTimeout(timeoutIdentifier); + } + }, + get currentTimestampInMilliseconds() { + return deterministicWallClock.currentTimestampInMilliseconds; + }, + setInterval: deterministicWallClock.setInterval, + setTimeout: deterministicWallClock.setTimeout, + }; + const firstSocket = createMockReconnectingWebsocketWrapper(WEBSOCKET_STATE.CONNECTING); + const secondSocket = createMockReconnectingWebsocketWrapper(WEBSOCKET_STATE.CONNECTING); + const websocketFactory = createSocketFactory(firstSocket, secondSocket); + const RWS = createRWS(jest.fn().mockResolvedValue('wss://example.invalid'), { + ...defaultReconnectingWebsocketTestOptions, + wallClock: wallClockWithOptionalClear, + websocketFactory: websocketFactory, + }); + + RWS.connect(); + firstSocket.onclose?.({code: CloseEventCode.NORMAL_CLOSURE, reason: 'closed', wasClean: true} as CloseEvent); + firstSocket.readyState = WEBSOCKET_STATE.CONNECTING; + shouldClearTimeout = false; + + await RWS['internalOnReconnect'](); + await RWS['internalOnReconnect'](); + + deterministicWallClock.advanceByMilliseconds(connectingTimeoutInMilliseconds / 2); + RWS['replaceSocketWrapper'](firstSocket, 'Manual replacement'); + + deterministicWallClock.advanceByMilliseconds(connectingTimeoutInMilliseconds / 2); + + expect(firstSocket.close).toHaveBeenCalledTimes(1); + expect(firstSocket.close).toHaveBeenCalledWith(CloseEventCode.NORMAL_CLOSURE, 'Manual replacement'); + expect(websocketFactory).toHaveBeenCalledTimes(2); + expect(RWS['socket']).toBe(secondSocket); + }); + + it('clears the watchdog when a socket opens after internalOnReconnect', async () => { + const deterministicWallClock = createDeterministicTimeoutWallClock(0); + const firstSocket = createMockReconnectingWebsocketWrapper(WEBSOCKET_STATE.CONNECTING); + const secondSocket = createMockReconnectingWebsocketWrapper(WEBSOCKET_STATE.CONNECTING); + const websocketFactory = createSocketFactory(firstSocket, secondSocket); + const RWS = createRWS(jest.fn().mockResolvedValue('wss://example.invalid'), { + ...defaultReconnectingWebsocketTestOptions, + wallClock: deterministicWallClock, + websocketFactory: websocketFactory, + }); + + RWS.connect(); + await RWS['internalOnReconnect'](); + firstSocket.readyState = WEBSOCKET_STATE.OPEN; + firstSocket.onopen?.({type: 'open'} as Event); + + expect(RWS['connectingTimeoutId']).toBeUndefined(); + + deterministicWallClock.advanceByMilliseconds(connectingTimeoutInMilliseconds); + + expect(websocketFactory).toHaveBeenCalledTimes(1); + expect(firstSocket.close).not.toHaveBeenCalled(); + expect(RWS['socket']).toBe(firstSocket); + }); + + it('does not replace the socket wrapper if it opens before the watchdog timeout', async () => { + const deterministicWallClock = createDeterministicTimeoutWallClock(0); + const socket = createMockReconnectingWebsocketWrapper(WEBSOCKET_STATE.CONNECTING); + const websocketFactory = createSocketFactory(socket); + const RWS = createRWS(jest.fn().mockResolvedValue('wss://example.invalid'), { + ...defaultReconnectingWebsocketTestOptions, + wallClock: deterministicWallClock, + websocketFactory: websocketFactory, + }); + + RWS.connect(); + await RWS['internalOnReconnect'](); + socket.readyState = WEBSOCKET_STATE.OPEN; + socket.onopen?.({type: 'open'} as Event); + + deterministicWallClock.advanceByMilliseconds(connectingTimeoutInMilliseconds); + + expect(websocketFactory).toHaveBeenCalledTimes(1); + expect(socket.close).not.toHaveBeenCalled(); + expect(RWS['socket']).toBe(socket); + }); + + it('does not let a stale watchdog replace a newer socket wrapper', async () => { + const deterministicWallClock = createDeterministicTimeoutWallClock(0); + const staleTimeoutWallClock: DeterministicTimeoutWallClock = { + ...deterministicWallClock, + clearTimeout: jest.fn(), + }; + const firstSocket = createMockReconnectingWebsocketWrapper(WEBSOCKET_STATE.CONNECTING); + const secondSocket = createMockReconnectingWebsocketWrapper(WEBSOCKET_STATE.CONNECTING); + const websocketFactory = createSocketFactory(firstSocket, secondSocket); + const RWS = createRWS(jest.fn().mockResolvedValue('wss://example.invalid'), { + ...defaultReconnectingWebsocketTestOptions, + wallClock: staleTimeoutWallClock, + websocketFactory: websocketFactory, + }); + + RWS.connect(); + await RWS['internalOnReconnect'](); + deterministicWallClock.advanceByMilliseconds(connectingTimeoutInMilliseconds / 2); + RWS['replaceSocketWrapper'](firstSocket, 'Manual replacement'); + + deterministicWallClock.advanceByMilliseconds(connectingTimeoutInMilliseconds / 2); + + expect(firstSocket.close).toHaveBeenCalledTimes(1); + expect(firstSocket.close).toHaveBeenCalledWith(CloseEventCode.NORMAL_CLOSURE, 'Manual replacement'); + expect(websocketFactory).toHaveBeenCalledTimes(2); + expect(RWS['socket']).toBe(secondSocket); + }); + + it('clears the connecting watchdog on disconnect', () => { + const deterministicWallClock = createDeterministicTimeoutWallClock(0); + const firstSocket = createMockReconnectingWebsocketWrapper(WEBSOCKET_STATE.CONNECTING); + const secondSocket = createMockReconnectingWebsocketWrapper(WEBSOCKET_STATE.CONNECTING); + const websocketFactory = createSocketFactory(firstSocket, secondSocket); + const RWS = createRWS(jest.fn(), { + ...defaultReconnectingWebsocketTestOptions, + wallClock: deterministicWallClock, + websocketFactory: websocketFactory, + }); + + RWS.connect(); + RWS.disconnect(); + deterministicWallClock.advanceByMilliseconds(connectingTimeoutInMilliseconds); + + expect(websocketFactory).toHaveBeenCalledTimes(1); + expect(RWS['socket']).toBe(firstSocket); + }); + + it('creates a fresh socket wrapper when closing the stale CONNECTING wrapper fails', async () => { + const deterministicWallClock = createDeterministicTimeoutWallClock(0); + const firstSocket = createMockReconnectingWebsocketWrapper(WEBSOCKET_STATE.CONNECTING); + const secondSocket = createMockReconnectingWebsocketWrapper(WEBSOCKET_STATE.CONNECTING); + const websocketFactory = createSocketFactory(firstSocket, secondSocket); + const RWS = createRWS(jest.fn().mockResolvedValue('wss://example.invalid'), { + ...defaultReconnectingWebsocketTestOptions, + wallClock: deterministicWallClock, + websocketFactory: websocketFactory, + }); + firstSocket.close.mockImplementation(() => { + throw new Error('close failed'); + }); + + RWS.connect(); + await RWS['internalOnReconnect'](); + + expect(() => deterministicWallClock.advanceByMilliseconds(connectingTimeoutInMilliseconds)).not.toThrow(); + expect(firstSocket.close).toHaveBeenCalledTimes(1); + expect(websocketFactory).toHaveBeenCalledTimes(2); + expect(RWS['socket']).toBe(secondSocket); + }); + }); + /** * Note that on a real interruption of the connection the ReconnectingWebsocket will not call "onClose" and "onOpen" again * but it will call "onReconnect" again. So this test checks at least the second call of "onReconnect". @@ -165,18 +821,71 @@ describe('ReconnectingWebsocket', () => { RWS.disconnect(); }); - it('returns false when socket is not in OPEN state', async () => { + it('returns false when socket is in CLOSED state', async () => { const onReconnect = jest.fn().mockReturnValue(getServerAddress()); const RWS = createRWS(onReconnect); - RWS.connect(); + // Inject a mock socket in CLOSED state (distinct from CONNECTING/CLOSING which return true) + RWS['socket'] = { + readyState: WEBSOCKET_STATE.CLOSED, + close: jest.fn(), + send: jest.fn(), + reconnect: jest.fn(), + onmessage: undefined, + onerror: undefined, + onopen: undefined, + onclose: undefined, + } as any; - // Check health while connecting (before open) const result = await RWS.checkHealth(); expect(result).toBe(false); + }); - RWS.disconnect(); + it('returns true and skips ping when socket is CONNECTING (transitioning guard)', async () => { + const onReconnect = jest.fn().mockReturnValue(getServerAddress()); + const RWS = createRWS(onReconnect); + const sendSpy = jest.spyOn(RWS, 'send'); + + // Inject a mock socket in CONNECTING state + RWS['socket'] = { + readyState: WEBSOCKET_STATE.CONNECTING, + close: jest.fn(), + send: jest.fn(), + reconnect: jest.fn(), + onmessage: undefined, + onerror: undefined, + onopen: undefined, + onclose: undefined, + } as any; + + const result = await RWS.checkHealth(); + + expect(result).toBe(true); + expect(sendSpy).not.toHaveBeenCalled(); + }); + + it('returns true and skips ping when socket is CLOSING (transitioning guard)', async () => { + const onReconnect = jest.fn().mockReturnValue(getServerAddress()); + const RWS = createRWS(onReconnect); + const sendSpy = jest.spyOn(RWS, 'send'); + + // Inject a mock socket in CLOSING state + RWS['socket'] = { + readyState: WEBSOCKET_STATE.CLOSING, + close: jest.fn(), + send: jest.fn(), + reconnect: jest.fn(), + onmessage: undefined, + onerror: undefined, + onopen: undefined, + onclose: undefined, + } as any; + + const result = await RWS.checkHealth(); + + expect(result).toBe(true); + expect(sendSpy).not.toHaveBeenCalled(); }); it('returns true when pong is received before timeout', done => { @@ -186,7 +895,7 @@ describe('ReconnectingWebsocket', () => { RWS.setOnOpen(async () => { // Mock the socket to respond with pong const originalSend = RWS.send.bind(RWS); - RWS.send = jest.fn((message: any) => { + RWS.send = jest.fn((message: string | Uint8Array) => { originalSend(message); if (message === PingMessage.PING) { // Simulate pong response @@ -230,19 +939,31 @@ describe('ReconnectingWebsocket', () => { it('uses default timeout of 10 seconds when not specified', done => { const onReconnect = jest.fn().mockReturnValue(getServerAddress()); - const RWS = createRWS(onReconnect); + const deterministicWallClock = createDeterministicTimeoutWallClock(currentTimestampInMilliseconds); + const RWS = createRWS(onReconnect, { + ...defaultReconnectingWebsocketTestOptions, + wallClock: deterministicWallClock, + }); RWS.setOnOpen(async () => { RWS.send = jest.fn(); - const startTime = Date.now(); - const result = await RWS.checkHealth(); - const duration = Date.now() - startTime; + const resultPromise = RWS.checkHealth(); + + let hasResolvedBeforeDefaultTimeout = false; + resultPromise.then(() => { + hasResolvedBeforeDefaultTimeout = true; + }); + + deterministicWallClock.advanceByMilliseconds(9_999); + await Promise.resolve(); + + expect(hasResolvedBeforeDefaultTimeout).toBe(false); + + deterministicWallClock.advanceByMilliseconds(1); + const result = await resultPromise; expect(result).toBe(false); - // Should be approximately 10000ms (with some tolerance) - expect(duration).toBeGreaterThanOrEqual(9900); - expect(duration).toBeLessThan(10500); RWS.disconnect(); done(); @@ -257,7 +978,7 @@ describe('ReconnectingWebsocket', () => { RWS.setOnOpen(async () => { const originalSend = RWS.send.bind(RWS); - RWS.send = jest.fn((message: any) => { + RWS.send = jest.fn((message: string | Uint8Array) => { originalSend(message); if (message === PingMessage.PING) { // Simulate pong response after 200ms @@ -287,13 +1008,19 @@ describe('ReconnectingWebsocket', () => { it('clears timeout when pong is received', done => { const onReconnect = jest.fn().mockReturnValue(getServerAddress()); - const RWS = createRWS(onReconnect); + const clearHealthCheckTimeout = jest.fn(globalThis.clearTimeout.bind(globalThis)); + const RWS = createRWS(onReconnect, { + ...defaultReconnectingWebsocketTestOptions, + wallClock: { + ...testWallClock, + clearTimeout: clearHealthCheckTimeout, + }, + }); RWS.setOnOpen(async () => { const originalSend = RWS.send.bind(RWS); - const clearTimeoutSpy = jest.spyOn(global, 'clearTimeout'); - RWS.send = jest.fn((message: any) => { + RWS.send = jest.fn((message: string | Uint8Array) => { originalSend(message); if (message === PingMessage.PING) { setTimeout(() => { @@ -305,9 +1032,8 @@ describe('ReconnectingWebsocket', () => { await RWS.checkHealth(1000); // clearTimeout should have been called when pong was received - expect(clearTimeoutSpy).toHaveBeenCalled(); + expect(clearHealthCheckTimeout).toHaveBeenCalled(); - clearTimeoutSpy.mockRestore(); RWS.disconnect(); done(); }); @@ -370,7 +1096,7 @@ describe('ReconnectingWebsocket', () => { const sendSpy = jest.spyOn(RWS, 'send'); // Simulate recent message activity (within 5 seconds) - RWS['lastMessageTimestamp'] = Date.now() - 1000; // 1 second ago + RWS['lastMessageTimestamp'] = currentTimestampInMilliseconds - 1_000; const result = await RWS.checkHealth(1000); @@ -394,7 +1120,7 @@ describe('ReconnectingWebsocket', () => { const sendSpy = jest.spyOn(RWS, 'send'); // Simulate idle connection (no messages for 6 seconds) - RWS['lastMessageTimestamp'] = Date.now() - 6000; // 6 seconds ago + RWS['lastMessageTimestamp'] = currentTimestampInMilliseconds - 6_000; const checkPromise = RWS.checkHealth(1000); @@ -431,7 +1157,7 @@ describe('ReconnectingWebsocket', () => { const updatedTimestamp = RWS['lastMessageTimestamp']; expect(updatedTimestamp).toBeGreaterThan(initialTimestamp); - expect(updatedTimestamp).toBeGreaterThan(Date.now() - 1000); + expect(updatedTimestamp).toBe(currentTimestampInMilliseconds); RWS.disconnect(); done(); @@ -468,7 +1194,7 @@ describe('ReconnectingWebsocket', () => { const sendSpy = jest.spyOn(RWS, 'send'); // Simulate high message activity - messages received very recently - RWS['lastMessageTimestamp'] = Date.now() - 500; // 500ms ago + RWS['lastMessageTimestamp'] = currentTimestampInMilliseconds - 500; // Even with a very short timeout, should still return true due to recent activity const result = await RWS.checkHealth(100); // Very short timeout @@ -492,7 +1218,7 @@ describe('ReconnectingWebsocket', () => { const sendSpy = jest.spyOn(RWS, 'send'); // Simulate idle connection - RWS['lastMessageTimestamp'] = Date.now() - 10000; // 10 seconds ago + RWS['lastMessageTimestamp'] = currentTimestampInMilliseconds - 10_000; // Don't mock pong response - should timeout const result = await RWS.checkHealth(200); @@ -520,14 +1246,14 @@ describe('ReconnectingWebsocket', () => { const sendSpy = jest.spyOn(RWS, 'send'); // Test 1: Recent activity - should be healthy without ping - RWS['lastMessageTimestamp'] = Date.now() - 1000; // 1 second ago + RWS['lastMessageTimestamp'] = currentTimestampInMilliseconds - 1_000; let result = await RWS.checkHealth(1000); expect(result).toBe(true); expect(sendSpy).not.toHaveBeenCalled(); sendSpy.mockClear(); // Test 2: Idle - should send ping - RWS['lastMessageTimestamp'] = Date.now() - 6000; // 6 seconds ago + RWS['lastMessageTimestamp'] = currentTimestampInMilliseconds - 6_000; const checkPromise = RWS.checkHealth(1000); expect(sendSpy).toHaveBeenCalledWith(PingMessage.PING); @@ -542,7 +1268,7 @@ describe('ReconnectingWebsocket', () => { sendSpy.mockRestore(); RWS.disconnect(); resolve(); - } catch (error) { + } catch (error: unknown) { reject(error); } }); @@ -554,7 +1280,12 @@ describe('ReconnectingWebsocket', () => { it('accepts custom pingInterval option', () => { const onReconnect = jest.fn().mockReturnValue(getServerAddress()); const customInterval = 10000; - const RWS = createRWS(onReconnect, {pingInterval: customInterval}); + const RWS = createRWS(onReconnect, { + backFromSleepHandler: undefined, + pingInterval: customInterval, + wallClock: testWallClock, + websocketFactory: undefined, + }); expect(RWS['PING_INTERVAL']).toBe(customInterval); RWS.disconnect(); @@ -746,7 +1477,12 @@ describe('ReconnectingWebsocket', () => { describe('ping mechanism', () => { it('sends ping automatically at intervals', done => { const onReconnect = jest.fn().mockReturnValue(getServerAddress()); - const RWS = createRWS(onReconnect, {pingInterval: 200}); + const RWS = createRWS(onReconnect, { + backFromSleepHandler: undefined, + pingInterval: 200, + wallClock: testWallClock, + websocketFactory: undefined, + }); RWS.setOnOpen(() => { const sendSpy = jest.spyOn(RWS, 'send'); @@ -761,17 +1497,26 @@ describe('ReconnectingWebsocket', () => { RWS.connect(); }, 2000); - it('closes socket after unanswered ping timeout', done => { + it('triggers reconnect after unanswered ping timeout', done => { const onReconnect = jest.fn().mockReturnValue(getServerAddress()); - const RWS = createRWS(onReconnect, {pingInterval: 100}); + const RWS = createRWS(onReconnect, { + backFromSleepHandler: undefined, + pingInterval: 100, + wallClock: testWallClock, + websocketFactory: undefined, + }); RWS.setOnOpen(() => { + const reconnectSpy = jest.spyOn(RWS['socket']!, 'reconnect'); RWS['hasUnansweredPing'] = true; - setTimeout(() => RWS['sendPing'](), 50); + setTimeout(() => { + RWS['sendPing'](); + expect(reconnectSpy).toHaveBeenCalledTimes(1); + RWS.disconnect(); + }, 50); }); - RWS.setOnClose(event => { - expect(event.reason).toBe('Ping timeout'); + RWS.setOnClose(() => { done(); }); diff --git a/libraries/api-client/src/tcp/ReconnectingWebsocket.ts b/libraries/api-client/src/tcp/ReconnectingWebsocket.ts index 460bfe75a1b..56274627f11 100644 --- a/libraries/api-client/src/tcp/ReconnectingWebsocket.ts +++ b/libraries/api-client/src/tcp/ReconnectingWebsocket.ts @@ -17,14 +17,16 @@ * */ +/* global globalThis */ + import logdown from 'logdown'; -import RWS, {CloseEvent, ErrorEvent, Event, Options} from 'reconnecting-websocket'; +import PartySocketWebSocket, {type CloseEvent, type ErrorEvent, type Options} from 'partysocket/ws'; import {LogFactory, TimeUtil} from '@wireapp/commons'; import * as buffer from '../shims/node/buffer'; import {WebSocketNode} from '../shims/node/websocket'; -import {onBackFromSleep} from '../utils/BackFromSleepHandler'; +import {BackFromSleepDetails, onBackFromSleep} from '../utils/BackFromSleepHandler'; export enum CloseEventCode { NORMAL_CLOSURE = 1000, @@ -45,9 +47,144 @@ export enum PingMessage { PONG = 'pong', } +export type LongRunningRetryDetails = { + readonly retryCount: number; + readonly retryDurationInMilliseconds: number; +}; + +export type WebSocketReconnectContext = { + readonly attemptId: number; + readonly wrapperGeneration: number; + readonly reconnectAttemptCount: number; + readonly reconnectSequenceRetryCount: number; +}; + +export type WebSocketErrorHandler = (error: ErrorEvent, reconnectContext: WebSocketReconnectContext) => void; + +type IntervalIdentifier = ReturnType; + +const longRunningRetryThresholdInMilliseconds = TimeUtil.TimeInMillis.MINUTE; +const connectingTimeoutInMilliseconds = TimeUtil.TimeInMillis.SECOND * 20; + +type BackFromSleepHandler = typeof onBackFromSleep; + +type ReconnectingWebsocketWrapper = Pick< + PartySocketWebSocket, + 'binaryType' | 'close' | 'onclose' | 'onerror' | 'onmessage' | 'onopen' | 'readyState' | 'reconnect' | 'send' +>; + +type TimeoutIdentifier = ReturnType; +type WebSocketEventListener = (event: Event) => void; +type WebSocketConstructor = new (url: string, protocols?: string | string[]) => WebSocket; +type WebSocketWithEventListeners = WebSocket & { + addEventListener: WebSocket['addEventListener']; + removeEventListener: WebSocket['removeEventListener']; +}; + +export type ReconnectingWebsocketWallClock = { + readonly currentTimestampInMilliseconds: number; + readonly setTimeout: (callback: () => void, delayInMilliseconds: number) => TimeoutIdentifier; + readonly clearTimeout: (timeoutIdentifier: TimeoutIdentifier) => void; + readonly setInterval: (callback: () => void, delayInMilliseconds: number) => IntervalIdentifier; + readonly clearInterval: (intervalIdentifier: IntervalIdentifier) => void; +}; + +type ReconnectingWebsocketOptions = { + readonly backFromSleepHandler?: BackFromSleepHandler; + readonly pingInterval?: number; + readonly wallClock: ReconnectingWebsocketWallClock; + readonly websocketFactory?: (resolveUrl: () => Promise) => ReconnectingWebsocketWrapper; +}; + +function getWebSocketStateName(state: WEBSOCKET_STATE): string { + return WEBSOCKET_STATE[state]; +} + +function normalizeMessageEventForPartysocket(event: Event): Event { + if (!('data' in event)) { + return event; + } + + if ((event as MessageEvent).ports !== null) { + return event; + } + + return { + data: (event as MessageEvent).data, + lastEventId: (event as MessageEvent).lastEventId, + origin: (event as MessageEvent).origin, + ports: [], + source: (event as MessageEvent).source, + type: event.type, + } as unknown as MessageEvent; +} + +export function createPartysocketCompatibleWebSocketConstructor( + WebSocketConstructor: WebSocketConstructor | undefined, +): WebSocketConstructor | undefined { + if (WebSocketConstructor === undefined || globalThis.WebSocket === WebSocketConstructor) { + return WebSocketConstructor; + } + + return function PartysocketCompatibleWebSocket(url: string, protocols?: string | string[]) { + const socket = ( + protocols === undefined ? new WebSocketConstructor(url) : new WebSocketConstructor(url, protocols) + ) as WebSocketWithEventListeners; + const originalAddEventListener = socket.addEventListener.bind(socket) as EventTarget['addEventListener']; + const originalRemoveEventListener = socket.removeEventListener.bind(socket) as EventTarget['removeEventListener']; + const wrappedMessageListeners = new WeakMap(); + + socket.addEventListener = (( + type: string, + listener: EventListenerOrEventListenerObject | null, + options?: boolean | AddEventListenerOptions, + ) => { + if (type !== 'message' || typeof listener !== 'function') { + originalAddEventListener(type, listener, options); + return; + } + + const wrappedListener = (event: Event) => { + listener(normalizeMessageEventForPartysocket(event)); + }; + wrappedMessageListeners.set(listener as WebSocketEventListener, wrappedListener); + originalAddEventListener(type, wrappedListener as EventListener, options); + }) as WebSocket['addEventListener']; + + socket.removeEventListener = (( + type: string, + listener: EventListenerOrEventListenerObject | null, + options?: boolean | EventListenerOptions, + ) => { + if (type !== 'message' || typeof listener !== 'function') { + originalRemoveEventListener(type, listener, options); + return; + } + + const wrappedListener = wrappedMessageListeners.get(listener as WebSocketEventListener); + originalRemoveEventListener(type, (wrappedListener ?? listener) as EventListener, options); + wrappedMessageListeners.delete(listener as WebSocketEventListener); + }) as WebSocket['removeEventListener']; + + return socket; + } as unknown as WebSocketConstructor; +} + +export function createWebSocketWallClock(): ReconnectingWebsocketWallClock { + return { + get currentTimestampInMilliseconds(): number { + return Date.now(); + }, + setTimeout: globalThis.setTimeout.bind(globalThis), + clearTimeout: globalThis.clearTimeout.bind(globalThis), + setInterval: globalThis.setInterval.bind(globalThis), + clearInterval: globalThis.clearInterval.bind(globalThis), + }; +} + export class ReconnectingWebsocket { private static readonly RECONNECTING_OPTIONS: Options = { - WebSocket: WebSocketNode, + WebSocket: createPartysocketCompatibleWebSocketConstructor(WebSocketNode), connectionTimeout: TimeUtil.TimeInMillis.SECOND * 4, debug: false, maxReconnectionDelay: TimeUtil.TimeInMillis.SECOND * 10, @@ -57,37 +194,61 @@ export class ReconnectingWebsocket { }; private readonly logger: logdown.Logger; - private socket?: RWS; - private pingerId?: NodeJS.Timeout; + private socket?: ReconnectingWebsocketWrapper; + private pingerId?: IntervalIdentifier; + private connectingTimeoutId?: TimeoutIdentifier; private readonly PING_INTERVAL = TimeUtil.TimeInMillis.SECOND * 20; private hasUnansweredPing: boolean; - private onOpen?: (event: Event) => void; + private onOpen?: (event: Event, reconnectContext: WebSocketReconnectContext) => void; private onMessage?: (data: string) => void; - private onError?: (error: ErrorEvent) => void; + private onError?: WebSocketErrorHandler; private onClose?: (event: CloseEvent) => void; + private onConnecting?: () => void; + private onLongRunningRetry?: (retryDetails: LongRunningRetryDetails) => void; /** * Cleanup function returned by onBackFromSleep to stop the sleep detection interval. * This prevents memory leaks by ensuring the interval is cleared when the WebSocket is disconnected. */ - private readonly stopBackFromSleepHandler?: () => void; + private stopBackFromSleepHandler?: () => void; private isPingingEnabled = true; private readonly pendingHealthChecks = new Set<(isHealthy: boolean) => void>(); private lastMessageTimestamp = 0; + private reconnectAttemptCount = 0; + private reconnectSequenceRetryCount = 0; + private reconnectSequenceStartTimestamp?: number; + private hasReportedLongRunningRetry = false; + + private connectionAttemptId = 0; + private wrapperGeneration = 0; + private activeConnectionAttemptId?: number; + private activeConnectionAttemptStartTimestamp?: number; + private activeWrapperGeneration?: number; + private wrapperLifetime = new AbortController(); + private reconnectLifetime?: AbortController; + + private readonly options: ReconnectingWebsocketOptions; constructor( - private readonly onReconnect: () => Promise, - options: { - pingInterval?: number; - } = {}, + private readonly onReconnect: (context: WebSocketReconnectContext, signal: AbortSignal) => Promise, + options: Partial = {}, ) { + this.options = {...options, wallClock: options.wallClock ?? createWebSocketWallClock()}; this.logger = LogFactory.getLogger('@wireapp/api-client/tcp/ReconnectingWebsocket'); - if (options.pingInterval) { + if (options.pingInterval !== undefined) { this.PING_INTERVAL = options.pingInterval; } this.hasUnansweredPing = false; + this.startBackFromSleepHandler(); + } + + private startBackFromSleepHandler(): void { + if (this.stopBackFromSleepHandler !== undefined) { + return; + } + /** * According to https://developer.mozilla.org/en-US/docs/Web/API/Navigator/onLine, navigator.onLine attribute and 'online' and 'offline' events are not reliable enough (especially when it's truthy). * We won't receive the 'offline' event when the system goes to sleep (e.g. closing the lid of a laptop). @@ -97,68 +258,133 @@ export class ReconnectingWebsocket { * IMPORTANT: Store the cleanup function returned by onBackFromSleep. This function clears * the internal setInterval and must be called when disconnecting to prevent memory leaks. * **/ - this.stopBackFromSleepHandler = onBackFromSleep({ - callback: () => { - if (!this.socket) { - this.logger.debug('WebSocket instance does not exist, skipping reconnect after sleep'); - return; - } - this.logger.debug('Back from sleep, reconnecting WebSocket'); - // Force reconnect even if the browser keeps the socket in OPEN state after sleep. - this.socket.reconnect(); - }, - }); + const backFromSleepHandler = this.options.backFromSleepHandler ?? onBackFromSleep; + const backFromSleepRegistration: Parameters[0] = { + callback: this.handleBackFromSleep, + }; + + this.stopBackFromSleepHandler = backFromSleepHandler(backFromSleepRegistration); } - private readonly internalOnError = (error: ErrorEvent) => { - this.logger.warn('WebSocket connection error', error); - if (this.onError) { - this.onError(error); + private readonly handleBackFromSleep = (details?: BackFromSleepDetails): void => { + this.logger.info( + `[WebSocketLifecycle] event=runtime-resumed observedIntervalMs=${details?.observedIntervalMilliseconds ?? 'unavailable'} expectedIntervalMs=${details?.expectedIntervalMilliseconds ?? 'unavailable'} suspensionDurationMs=${details?.suspensionDurationMilliseconds ?? 'unavailable'} state=${getWebSocketStateName(this.getState())} ${this.getActiveLifecycleContext()}`, + ); + const socket = this.socket; + if (socket === undefined) { + return; } + + this.stopPinging(); + this.hasUnansweredPing = false; + this.replaceSocketWrapper(socket, 'Back from sleep'); }; - private readonly internalOnMessage = (event: MessageEvent) => { - this.logger.debug('Incoming message'); + private readonly internalOnError = (error: ErrorEvent): void => { + const reconnectContext = this.getReconnectContext(); + // Error messages and close reasons are untrusted and may contain credentials or notification contents. + this.logger.warn(`[WebSocketLifecycle] event=socket-error ${this.getLifecycleContext(reconnectContext)}`); + if (this.onError !== undefined) { + this.onError(error, reconnectContext); + } + }; + private readonly internalOnMessage = (event: MessageEvent) => { const data = buffer.bufferToString(event.data); if (data === PingMessage.PONG) { - this.logger.debug('Received pong from WebSocket'); + this.logger.debug(`[WebSocketLifecycle] event=pong-received ${this.getActiveLifecycleContext()}`); this.hasUnansweredPing = false; + if (this.pendingHealthChecks.size > 0) { + this.logger.debug( + `[WebSocketLifecycle] event=health-check-pong state=${getWebSocketStateName(this.getState())} ${this.getActiveLifecycleContext()}`, + ); + } this.resolvePendingHealthChecks(true); return; } - this.lastMessageTimestamp = Date.now(); + this.logger.debug('Incoming message'); + this.lastMessageTimestamp = this.options.wallClock.currentTimestampInMilliseconds; this.onMessage?.(data); }; private readonly internalOnOpen = (event: Event) => { - this.logger.debug('WebSocket opened'); - if (this.socket) { + const reconnectContext = this.getReconnectContext(); + const durationInMilliseconds = this.getActiveAttemptDurationInMilliseconds(); + this.logger.info( + `[WebSocketLifecycle] event=socket-open ${this.getLifecycleContext(reconnectContext)} durationMs=${durationInMilliseconds} reconnectAttempt=${reconnectContext.reconnectAttemptCount} sequenceRetry=${reconnectContext.reconnectSequenceRetryCount}`, + ); + this.stopConnectingWatchdog('socket-opened'); + this.resetLongRunningRetrySequence(); + if (this.socket !== undefined) { this.socket.binaryType = 'arraybuffer'; } - if (this.onOpen) { - this.onOpen(event); + if (this.onOpen !== undefined) { + this.onOpen(event, reconnectContext); } }; private readonly internalOnReconnect = async (): Promise => { - this.logger.debug('Connecting to WebSocket'); + this.onConnecting?.(); + this.reconnectLifetime?.abort(); + const reconnectLifetime = new AbortController(); + this.reconnectLifetime = reconnectLifetime; + const nowInMilliseconds = this.options.wallClock.currentTimestampInMilliseconds; + this.connectionAttemptId += 1; + this.activeConnectionAttemptId = this.connectionAttemptId; + this.activeConnectionAttemptStartTimestamp = nowInMilliseconds; + this.recordReconnectAttempt(nowInMilliseconds); + const reconnectingSocket = this.socket; + const reconnectContext = this.getReconnectContext(); + + this.logger.info( + `[WebSocketLifecycle] event=reconnect-start ${this.getLifecycleContext(reconnectContext)} state=${getWebSocketStateName(this.getState())} reconnectAttempt=${reconnectContext.reconnectAttemptCount} sequenceRetry=${reconnectContext.reconnectSequenceRetryCount} pingEnabled=${this.isPingingEnabled} watchdogActive=${this.connectingTimeoutId !== undefined}`, + ); + // The ping is needed to keep the connection alive as long as possible. // Otherwise the connection would be closed after 1 min of inactivity and re-established. if (this.isPingingEnabled) { this.startPinging(); } - return this.onReconnect(); + + this.logger.debug(`[WebSocketLifecycle] event=url-resolution-start ${this.getLifecycleContext(reconnectContext)}`); + let websocketUrl: string; + try { + websocketUrl = await this.onReconnect(reconnectContext, reconnectLifetime.signal); + reconnectLifetime.signal.throwIfAborted(); + } catch (error: unknown) { + const durationInMilliseconds = this.options.wallClock.currentTimestampInMilliseconds - nowInMilliseconds; + this.logger.warn( + `[WebSocketLifecycle] event=url-resolution-failure ${this.getLifecycleContext(reconnectContext)} durationMs=${durationInMilliseconds}`, + ); + throw error; + } + this.logger.info( + `[WebSocketLifecycle] event=url-resolution-success ${this.getLifecycleContext(reconnectContext)} durationMs=${this.options.wallClock.currentTimestampInMilliseconds - nowInMilliseconds}`, + ); + const socket = reconnectingSocket; + + if (this.socket !== socket) { + return websocketUrl; + } + + if (socket !== undefined && socket.readyState === WEBSOCKET_STATE.CONNECTING) { + this.startConnectingWatchdog(socket, reconnectContext); + } + + return websocketUrl; }; private readonly internalOnClose = (event: CloseEvent) => { - this.logger.debug(`WebSocket closed with code: ${event?.code}${event?.reason ? `Reason: ${event?.reason}` : ''}`); + this.logger.info( + `[WebSocketLifecycle] event=socket-close ${this.getActiveLifecycleContext()} state=${getWebSocketStateName(this.getState())} code=${event?.code ?? 'unknown'} wasClean=${event?.wasClean ?? 'unknown'} durationMs=${this.getActiveAttemptDurationInMilliseconds()}`, + ); + this.stopConnectingWatchdog('socket-closed'); this.stopPinging(); this.resolvePendingHealthChecks(false); - if (this.onClose) { + if (this.onClose !== undefined) { this.onClose(event); } }; @@ -166,39 +392,184 @@ export class ReconnectingWebsocket { private startPinging(): void { this.stopPinging(); this.hasUnansweredPing = false; - this.pingerId = setInterval(this.sendPing, this.PING_INTERVAL); + this.pingerId = this.options.wallClock.setInterval(this.sendPing, this.PING_INTERVAL); } private stopPinging(): void { - if (this.pingerId) { - clearInterval(this.pingerId); + if (this.pingerId !== undefined) { + this.options.wallClock.clearInterval(this.pingerId); + this.pingerId = undefined; } } private readonly sendPing = (): void => { - if (!this.socket) { - this.logger.debug('WebSocket instance does not exist, skipping ping'); + if (this.socket === undefined) { + this.logger.debug(`[WebSocketLifecycle] event=ping-skip reason=no-wrapper ${this.getActiveLifecycleContext()}`); + return; + } + + if (this.socket.readyState !== WEBSOCKET_STATE.OPEN) { + this.logger.debug( + `[WebSocketLifecycle] event=ping-skip reason=not-open state=${getWebSocketStateName(this.socket.readyState)} ${this.getActiveLifecycleContext()}`, + ); return; } if (this.hasUnansweredPing) { - this.logger.warn('Ping interval check failed'); + this.logger.warn( + `[WebSocketLifecycle] event=ping-timeout ${this.getActiveLifecycleContext()} timeoutMs=${this.PING_INTERVAL} state=${getWebSocketStateName(this.getState())} lastMessageAgeMs=${this.getLastMessageAgeInMilliseconds()}`, + ); this.stopPinging(); - // Closing here intentionally triggers reconnecting-websocket's retry loop; it will call - // internalOnReconnect to build a fresh URL and re-open the socket. - this.socket.close(CloseEventCode.NORMAL_CLOSURE, 'Ping timeout'); + this.reconnectInPlace(this.socket); return; } + this.logger.debug( + `[WebSocketLifecycle] event=ping-send ${this.getActiveLifecycleContext()} lastMessageAgeMs=${this.getLastMessageAgeInMilliseconds()}`, + ); this.hasUnansweredPing = true; this.send(PingMessage.PING); }; + /** + * Reconnect on the existing ReconnectingWebSocket wrapper instead of allocating a new one. + * The library closes the current underlying WebSocket synchronously in `_disconnect` before + * opening the next, so we never leave two `/await` sessions alive from the app. + */ + private reconnectInPlace(socket: ReconnectingWebsocketWrapper): void { + this.onConnecting?.(); + this.reconnectLifetime?.abort(); + try { + socket.reconnect(CloseEventCode.NORMAL_CLOSURE); + } catch { + this.logger.warn(`[WebSocketLifecycle] event=reconnect-in-place-failure ${this.getActiveLifecycleContext()}`); + } + } + + private startConnectingWatchdog( + socket: ReconnectingWebsocketWrapper, + reconnectContext: WebSocketReconnectContext, + ): void { + this.stopConnectingWatchdog('watchdog-restarted'); + this.logger.debug( + `[WebSocketLifecycle] event=connecting-watchdog-start ${this.getLifecycleContext(reconnectContext)} state=${getWebSocketStateName(socket.readyState)} timeoutMs=${connectingTimeoutInMilliseconds}`, + ); + + this.connectingTimeoutId = this.options.wallClock.setTimeout(() => { + if (this.socket !== socket) { + return; + } + + this.connectingTimeoutId = undefined; + + if (socket.readyState !== WEBSOCKET_STATE.CONNECTING) { + return; + } + + this.logger.warn( + `[WebSocketLifecycle] event=connecting-watchdog-timeout ${this.getLifecycleContext(reconnectContext)} state=${getWebSocketStateName(socket.readyState)} durationMs=${connectingTimeoutInMilliseconds}`, + ); + + this.replaceSocketWrapper(socket, 'Connecting timeout'); + }, connectingTimeoutInMilliseconds); + } + + private stopConnectingWatchdog(reason: string): void { + if (this.connectingTimeoutId !== undefined) { + this.options.wallClock.clearTimeout(this.connectingTimeoutId); + this.connectingTimeoutId = undefined; + this.logger.debug( + `[WebSocketLifecycle] event=connecting-watchdog-stop ${this.getActiveLifecycleContext()} reason=${reason}`, + ); + } + } + + private replaceSocketWrapper( + socket: ReconnectingWebsocketWrapper, + closeReason: 'Back from sleep' | 'Connecting timeout', + ): void { + if (this.socket !== socket) { + return; + } + + this.stopPinging(); + this.hasUnansweredPing = false; + this.stopConnectingWatchdog('wrapper-replaced'); + + this.logger.info( + `[WebSocketLifecycle] event=wrapper-replace oldWrapperGeneration=${this.activeWrapperGeneration ?? 0} ${this.getActiveLifecycleContext()} reason=${closeReason} state=${getWebSocketStateName(socket.readyState)}`, + ); + + try { + socket.close(CloseEventCode.NORMAL_CLOSURE, closeReason); + } catch { + this.logger.warn( + `[WebSocketLifecycle] event=wrapper-close-failure ${this.getActiveLifecycleContext()} reason=${closeReason}`, + ); + } + + this.createAndBindSocketWrapper(closeReason); + } + public connect(): void { - this.socket = this.getReconnectingWebsocket(); - this.socket.onmessage = this.internalOnMessage; - this.socket.onerror = this.internalOnError; - this.socket.onopen = this.internalOnOpen; - this.socket.onclose = this.internalOnClose; + this.logger.info('[WebSocketLifecycle] event=connect-requested'); + this.startBackFromSleepHandler(); + this.resetLongRunningRetrySequence(); + this.stopPinging(); + + const existingSocket = this.socket; + + if (existingSocket !== undefined && !this.isExistingSocketClosed(existingSocket)) { + this.logger.warn( + `Existing WebSocket instance detected in state ${WEBSOCKET_STATE[existingSocket.readyState]} (${existingSocket.readyState}); reconnecting in place`, + ); + this.reconnectInPlace(existingSocket); + return; + } + + if (existingSocket !== undefined) { + this.logger.info('[WebSocketLifecycle] event=closed-wrapper-replacement'); + } + + this.createAndBindSocketWrapper(existingSocket === undefined ? 'initial-connect' : 'closed-wrapper'); + } + + private isExistingSocketClosed(socket: ReconnectingWebsocketWrapper): boolean { + return socket.readyState === WEBSOCKET_STATE.CLOSED; + } + + private createAndBindSocketWrapper(reason: string): void { + // Closing a wrapper does not always emit close (for example while already CLOSING). + // Invalidate the previous connection's processing before constructing its replacement. + this.onConnecting?.(); + this.wrapperLifetime.abort(); + this.reconnectLifetime?.abort(); + this.wrapperLifetime = new AbortController(); + const nextSocket = this.getReconnectingWebsocket(); + this.wrapperGeneration += 1; + this.activeWrapperGeneration = this.wrapperGeneration; + this.socket = nextSocket; + this.bindSocketHandlers(nextSocket); + this.logger.info( + `[WebSocketLifecycle] event=wrapper-created wrapperGeneration=${this.wrapperGeneration} state=${getWebSocketStateName(nextSocket.readyState)}`, + ); + } + + private bindSocketHandlers(socket: ReconnectingWebsocketWrapper): void { + socket.onmessage = this.runIfActiveSocket(socket, this.internalOnMessage); + socket.onerror = this.runIfActiveSocket(socket, this.internalOnError); + socket.onopen = this.runIfActiveSocket(socket, this.internalOnOpen); + socket.onclose = this.runIfActiveSocket(socket, this.internalOnClose); + } + + // Ignore late async events emitted by a previously replaced socket instance. + // This prevents stale callbacks from mutating state that now belongs to a newer socket. + private runIfActiveSocket(socket: ReconnectingWebsocketWrapper, handler: (event: T) => void): (event: T) => void { + return event => { + if (this.socket !== socket) { + return; + } + handler(event); + }; } public send(message: any): void { @@ -206,7 +577,7 @@ export class ReconnectingWebsocket { } public getState(): WEBSOCKET_STATE { - return this.socket ? this.socket.readyState : WEBSOCKET_STATE.CLOSED; + return this.socket !== undefined ? this.socket.readyState : WEBSOCKET_STATE.CLOSED; } /** @@ -216,50 +587,87 @@ export class ReconnectingWebsocket { * it considers the connection healthy without sending a ping, as message processing * indicates the connection is working properly. * - * If the WebSocket is idle, it sends a ping and expects a pong within the timeout. + * If the WebSocket is idle and its protocol supports application pings, it sends + * a ping and expects a pong within the timeout. * This approach prevents false failures during high-load scenarios where pong responses * get queued behind many other messages. * + * Async /events does not support these pings. For that protocol an OPEN result + * only confirms local socket state, not end-to-end liveness. An idle connection + * may legitimately receive no notifications, so silence is not a failure signal. + * Recovery still relies on close/error events, wake detection and the connecting + * watchdog; callers must not interpret this probe as a server acknowledgement. + * * Does not close or reconnect the socket; callers can decide how to react to failures. */ public checkHealth(timeoutMs = TimeUtil.TimeInMillis.SECOND * 10): Promise { - if (!this.socket || this.getState() !== WEBSOCKET_STATE.OPEN) { + const state = this.getState(); + if (this.socket === undefined) { + this.logger.debug( + `[WebSocketLifecycle] event=health-check-no-wrapper state=${getWebSocketStateName(state)} ${this.getActiveLifecycleContext()}`, + ); return Promise.resolve(false); } - const now = Date.now(); + if (state === WEBSOCKET_STATE.CONNECTING || state === WEBSOCKET_STATE.CLOSING) { + this.logger.debug( + `[WebSocketLifecycle] event=health-check-transitioning state=${getWebSocketStateName(state)} ${this.getActiveLifecycleContext()}`, + ); + return Promise.resolve(true); + } + + if (state !== WEBSOCKET_STATE.OPEN) { + this.logger.debug( + `[WebSocketLifecycle] event=health-check-not-open state=${getWebSocketStateName(state)} ${this.getActiveLifecycleContext()}`, + ); + return Promise.resolve(false); + } + + // Async notification sockets do not accept application-level ping messages. + if (this.isPingingEnabled === false) { + return Promise.resolve(true); + } + + const now = this.options.wallClock.currentTimestampInMilliseconds; const timeSinceLastMessage = now - this.lastMessageTimestamp; // If we're actively processing messages during the last 5 seconds, consider the connection healthy if (timeSinceLastMessage < TimeUtil.TimeInMillis.SECOND * 5) { this.logger.debug( - `WebSocket is actively processing messages (last: ${timeSinceLastMessage}ms ago), considering healthy`, + `[WebSocketLifecycle] event=health-check-active-messages state=${getWebSocketStateName(state)} ${this.getActiveLifecycleContext()} lastMessageAgeMs=${timeSinceLastMessage}`, ); return Promise.resolve(true); } // If idle, use ping/pong to verify connection return new Promise(resolve => { - const timeoutId = setTimeout(() => { + const timeoutId = this.options.wallClock.setTimeout(() => { this.pendingHealthChecks.delete(resolveHealthCheck); - this.logger.debug('Health check timeout - no pong received within timeout'); + this.logger.warn( + `[WebSocketLifecycle] event=health-check-timeout state=${getWebSocketStateName(this.getState())} ${this.getActiveLifecycleContext()} lastMessageAgeMs=${this.getLastMessageAgeInMilliseconds()} timeoutMs=${timeoutMs}`, + ); resolve(false); }, timeoutMs); const resolveHealthCheck = (isHealthy: boolean) => { - clearTimeout(timeoutId); + this.options.wallClock.clearTimeout(timeoutId); resolve(isHealthy); }; this.pendingHealthChecks.add(resolveHealthCheck); - this.logger.debug('WebSocket is idle, sending ping for health check'); + this.logger.debug( + `[WebSocketLifecycle] event=health-check-ping-start state=${getWebSocketStateName(state)} ${this.getActiveLifecycleContext()} lastMessageAgeMs=${timeSinceLastMessage} timeoutMs=${timeoutMs}`, + ); this.send(PingMessage.PING); }); } public disconnect(reason = 'Closed by client'): void { - if (this.socket) { - this.logger.info(`Disconnecting from WebSocket (reason: "${reason}")`); + this.wrapperLifetime.abort(); + this.reconnectLifetime?.abort(); + this.resetLongRunningRetrySequence(); + if (this.socket !== undefined) { + this.logger.info(`[WebSocketLifecycle] event=disconnect-requested ${this.getActiveLifecycleContext()}`); this.socket.close(CloseEventCode.NORMAL_CLOSURE, reason); } // Always cleanup resources even if socket doesn't exist @@ -276,12 +684,26 @@ export class ReconnectingWebsocket { */ private cleanup(): void { this.stopPinging(); - // Clear the sleep detection interval if it exists - this.stopBackFromSleepHandler?.(); + this.stopConnectingWatchdog('disconnect'); + if (this.stopBackFromSleepHandler !== undefined) { + this.stopBackFromSleepHandler(); + } + this.stopBackFromSleepHandler = undefined; } - private getReconnectingWebsocket(): RWS { - return new RWS(this.internalOnReconnect, undefined, ReconnectingWebsocket.RECONNECTING_OPTIONS); + private getReconnectingWebsocket(): ReconnectingWebsocketWrapper { + const wrapperSignal = this.wrapperLifetime.signal; + const transport = this; + async function resolveUrl(): Promise { + wrapperSignal.throwIfAborted(); + + return transport.internalOnReconnect(); + } + if (this.options.websocketFactory !== undefined) { + return this.options.websocketFactory(resolveUrl); + } + + return new PartySocketWebSocket(resolveUrl, undefined, ReconnectingWebsocket.RECONNECTING_OPTIONS); } private resolvePendingHealthChecks(isHealthy: boolean) { @@ -289,7 +711,7 @@ export class ReconnectingWebsocket { this.pendingHealthChecks.clear(); } - public setOnOpen(onOpen: (event: Event) => void): void { + public setOnOpen(onOpen: (event: Event, reconnectContext: WebSocketReconnectContext) => void): void { this.onOpen = onOpen; } @@ -297,7 +719,7 @@ export class ReconnectingWebsocket { this.onMessage = onMessage; } - public setOnError(onError: (error: ErrorEvent) => void): void { + public setOnError(onError: WebSocketErrorHandler): void { this.onError = onError; } @@ -305,8 +727,98 @@ export class ReconnectingWebsocket { this.onClose = onClose; } + public setOnConnecting(onConnecting: () => void): void { + this.onConnecting = onConnecting; + } + + public setOnLongRunningRetry(onLongRunningRetry: (retryDetails: LongRunningRetryDetails) => void): void { + this.onLongRunningRetry = onLongRunningRetry; + } + public disablePinging(): void { this.isPingingEnabled = false; this.stopPinging(); } + + private recordReconnectAttempt(nowInMilliseconds: number): void { + this.reconnectAttemptCount += 1; + + if (this.reconnectAttemptCount === 1) { + return; + } + + if (this.reconnectSequenceStartTimestamp === undefined) { + this.reconnectSequenceStartTimestamp = nowInMilliseconds; + } + + this.reconnectSequenceRetryCount += 1; + this.reportLongRunningRetryIfNeeded(nowInMilliseconds); + } + + private reportLongRunningRetryIfNeeded(nowInMilliseconds: number): void { + if (this.hasReportedLongRunningRetry) { + return; + } + + const reconnectSequenceStartTimestamp = this.reconnectSequenceStartTimestamp; + + if (typeof reconnectSequenceStartTimestamp !== 'number') { + return; + } + + const retryDurationInMilliseconds = nowInMilliseconds - reconnectSequenceStartTimestamp; + + if (retryDurationInMilliseconds < longRunningRetryThresholdInMilliseconds) { + return; + } + + this.hasReportedLongRunningRetry = true; + this.logger.warn( + `[WebSocketLifecycle] event=long-running-reconnect ${this.getActiveLifecycleContext()} sequenceRetry=${this.reconnectSequenceRetryCount} durationMs=${retryDurationInMilliseconds}`, + ); + this.onLongRunningRetry?.({ + retryCount: this.reconnectSequenceRetryCount, + retryDurationInMilliseconds, + }); + } + + private resetLongRunningRetrySequence(): void { + this.hasReportedLongRunningRetry = false; + this.reconnectAttemptCount = 0; + this.reconnectSequenceRetryCount = 0; + this.reconnectSequenceStartTimestamp = undefined; + } + + private getReconnectContext(): WebSocketReconnectContext { + return { + attemptId: this.activeConnectionAttemptId ?? 0, + reconnectAttemptCount: this.reconnectAttemptCount, + reconnectSequenceRetryCount: this.reconnectSequenceRetryCount, + wrapperGeneration: this.activeWrapperGeneration ?? 0, + }; + } + + private getActiveLifecycleContext(): string { + return this.getLifecycleContext(this.getReconnectContext()); + } + + private getLifecycleContext(reconnectContext: WebSocketReconnectContext): string { + return `attemptId=${reconnectContext.attemptId} wrapperGeneration=${reconnectContext.wrapperGeneration}`; + } + + private getActiveAttemptDurationInMilliseconds(): string { + const startTimestampInMilliseconds = this.activeConnectionAttemptStartTimestamp; + + return startTimestampInMilliseconds === undefined + ? 'unavailable' + : String(this.options.wallClock.currentTimestampInMilliseconds - startTimestampInMilliseconds); + } + + private getLastMessageAgeInMilliseconds(): number | string { + if (this.lastMessageTimestamp === 0) { + return 'unavailable'; + } + + return this.options.wallClock.currentTimestampInMilliseconds - this.lastMessageTimestamp; + } } diff --git a/libraries/api-client/src/tcp/WebSocketClient.test.ts b/libraries/api-client/src/tcp/WebSocketClient.test.ts index a608ef54bd0..80362c365fe 100644 --- a/libraries/api-client/src/tcp/WebSocketClient.test.ts +++ b/libraries/api-client/src/tcp/WebSocketClient.test.ts @@ -20,12 +20,15 @@ /* eslint-disable dot-notation */ import {WebSocketClient} from './WebSocketClient'; +import {ReconnectingWebsocketWallClock} from './ReconnectingWebsocket'; import {InvalidTokenError} from '../auth/AuthenticationError'; import {MINIMUM_API_VERSION} from '../Config'; import {TEAM_EVENT} from '../event/'; import {ConsumableEvent, ConsumableNotification} from '../notification/ConsumableNotification'; +function noop(): void {} + const accessTokenPayload = { access_token: 'iJCRCjc8oROO-dkrkqCXOade997oa8Jhbz6awMUQPBQo80VenWqp_oNvfY6AnU5BxEsdDPOBfBP-uz_b0gAKBQ==.v=1.k=1.d=1498600993.t=a.l=.u=aaf9a833-ef30-4c22-86a0-9adc8a15b3b4.c=15037015562284012115', @@ -34,12 +37,15 @@ const accessTokenPayload = { user: 'aaf9a833-ef30-4c22-86a0-9adc8a15b3b4', }; +const reconnectPendingMarker = 'reconnect-pending'; + const fakeHttpClient: any = { accessTokenStore: { accessToken: accessTokenPayload, }, refreshAccessToken: () => Promise.resolve(accessTokenPayload), hasValidAccessToken: () => true, + sendRequest: () => Promise.resolve({data: {}}), }; const invalidTokenHttpClient: any = { @@ -48,6 +54,7 @@ const invalidTokenHttpClient: any = { }, refreshAccessToken: () => Promise.reject(new InvalidTokenError('Invalid token')), hasValidAccessToken: () => true, + sendRequest: () => Promise.resolve({data: {}}), }; const fakeSocket = { @@ -58,16 +65,136 @@ const fakeSocket = { onopen: () => {}, }; +let currentTimestampInMilliseconds = 1_000_000; + +const testWallClock: ReconnectingWebsocketWallClock = { + clearInterval(intervalIdentifier) { + return globalThis.clearInterval(intervalIdentifier); + }, + clearTimeout(timeoutIdentifier) { + return globalThis.clearTimeout(timeoutIdentifier); + }, + + get currentTimestampInMilliseconds() { + return currentTimestampInMilliseconds; + }, + + setInterval(callback, delayInMilliseconds) { + return globalThis.setInterval(callback, delayInMilliseconds); + }, + setTimeout(callback, delayInMilliseconds) { + return globalThis.setTimeout(callback, delayInMilliseconds); + }, +}; + +type WebSocketHttpClient = ConstructorParameters[1]; +type WebSocketReconnectHttpClient = Pick< + WebSocketHttpClient, + 'accessTokenStore' | 'refreshAccessToken' | 'hasValidAccessToken' | 'sendRequest' +>; +type WebSocketReconnectHttpClientOptions = Pick< + WebSocketReconnectHttpClient, + 'refreshAccessToken' | 'hasValidAccessToken' | 'sendRequest' +>; +type RetryDelayCallback = () => void; +type ManualRetryWallClock = { + readonly pendingTimeoutCount: () => number; + readonly retryDelaysInMilliseconds: number[]; + readonly runNextRetryDelay: () => void; + readonly wallClock: ReconnectingWebsocketWallClock; +}; +type ManualRetryTimeoutIdentifier = ReturnType; + +function createWebSocketClient( + baseUrl: string, + client: WebSocketHttpClient, + wallClock: ReconnectingWebsocketWallClock, +): WebSocketClient { + return new WebSocketClient(baseUrl, client, { + wallClock, + }); +} + +function createWebSocketClientWithTestWallClock(baseUrl: string, client: WebSocketHttpClient): WebSocketClient { + return createWebSocketClient(baseUrl, client, testWallClock); +} + +function createWebSocketReconnectHttpClient( + webSocketReconnectHttpClient: WebSocketReconnectHttpClientOptions, +): WebSocketHttpClient { + const httpClient: WebSocketReconnectHttpClient = { + accessTokenStore: fakeHttpClient.accessTokenStore, + refreshAccessToken: webSocketReconnectHttpClient.refreshAccessToken, + hasValidAccessToken: webSocketReconnectHttpClient.hasValidAccessToken, + sendRequest: webSocketReconnectHttpClient.sendRequest, + }; + + return httpClient as WebSocketHttpClient; +} + +function createManualRetryTimeoutIdentifier(): ManualRetryTimeoutIdentifier { + const timeoutIdentifier = testWallClock.setTimeout(noop, 0); + + testWallClock.clearTimeout(timeoutIdentifier); + + return timeoutIdentifier; +} + +function createManualRetryWallClock(): ManualRetryWallClock { + const retryDelayCallbacks = new Map(); + const retryDelaysInMilliseconds: number[] = []; + const wallClock: ReconnectingWebsocketWallClock = { + clearInterval: testWallClock.clearInterval, + clearTimeout(identifier): void { retryDelayCallbacks.delete(identifier); }, + + get currentTimestampInMilliseconds() { + return currentTimestampInMilliseconds; + }, + + setInterval: testWallClock.setInterval, + setTimeout: (callback, delayInMilliseconds) => { + const identifier = createManualRetryTimeoutIdentifier(); + retryDelayCallbacks.set(identifier, callback); + retryDelaysInMilliseconds.push(delayInMilliseconds); + + return identifier; + }, + }; + + return { + pendingTimeoutCount(): number { return retryDelayCallbacks.size; }, + retryDelaysInMilliseconds, + runNextRetryDelay: () => { + const next = retryDelayCallbacks.entries().next().value; + if (next !== undefined) { + retryDelayCallbacks.delete(next[0]); + next[1](); + } + }, + wallClock, + }; +} + +async function flushPromises(): Promise { + for (let turn = 0; turn < 20; turn += 1) { + await Promise.resolve(); + } +} + const webSocketClients: WebSocketClient[] = []; describe('WebSocketClient', () => { + beforeEach(() => { + currentTimestampInMilliseconds = 1_000_000; + }); + afterAll(() => { webSocketClients.forEach(client => client.disconnect()); }); describe('handler', () => { it('calls "onOpen" when WebSocket opens', async () => { - const websocketClient = new WebSocketClient('ws://url', fakeHttpClient); + const websocketClient = createWebSocketClientWithTestWallClock('wss://url', fakeHttpClient); webSocketClients.push(websocketClient); const onOpenSpy = jest.spyOn(websocketClient as any, 'onOpen'); const socket = websocketClient['socket']; @@ -80,7 +207,7 @@ describe('WebSocketClient', () => { }); it('calls "onClose" when WebSocket closes', async () => { - const websocketClient = new WebSocketClient('ws://url', fakeHttpClient); + const websocketClient = createWebSocketClientWithTestWallClock('wss://url', fakeHttpClient); webSocketClients.push(websocketClient); const onCloseSpy = jest.spyOn(websocketClient as any, 'onClose'); const socket = websocketClient['socket']; @@ -93,7 +220,7 @@ describe('WebSocketClient', () => { }); it('calls "onError" when WebSocket received error', async () => { - const websocketClient = new WebSocketClient('ws://url', fakeHttpClient); + const websocketClient = createWebSocketClientWithTestWallClock('wss://url', fakeHttpClient); webSocketClients.push(websocketClient); const onErrorSpy = jest.spyOn(websocketClient as any, 'onError'); const refreshTokenSpy = jest.spyOn(websocketClient as any, 'refreshAccessToken'); @@ -109,7 +236,7 @@ describe('WebSocketClient', () => { it('calls "onMessage" when WebSocket received message', async () => { const message = {type: ConsumableEvent.MISSED}; - const websocketClient = new WebSocketClient('ws://url', fakeHttpClient); + const websocketClient = createWebSocketClientWithTestWallClock('wss://url', fakeHttpClient); webSocketClients.push(websocketClient); const onMessageSpy = jest.spyOn(websocketClient as any, 'onMessage'); const socket = websocketClient['socket']; @@ -126,7 +253,7 @@ describe('WebSocketClient', () => { const onConnect = () => { return onConnectResult(); }; - const websocketClient = new WebSocketClient('ws://url', fakeHttpClient); + const websocketClient = createWebSocketClientWithTestWallClock('wss://url', fakeHttpClient); webSocketClients.push(websocketClient); const socket = websocketClient['socket']; jest.spyOn(socket as any, 'getReconnectingWebsocket').mockReturnValue(fakeSocket); @@ -140,9 +267,67 @@ describe('WebSocketClient', () => { }); describe('refreshAccessToken', () => { + it('clears a pending retry delay on disconnect and does not refresh again', async () => { + const clock = createManualRetryWallClock(); + const refreshAccessToken = jest.fn().mockRejectedValue(new Error('Temporary failure')); + const httpClient = createWebSocketReconnectHttpClient({refreshAccessToken, hasValidAccessToken: () => false, sendRequest: jest.fn()}); + const client = createWebSocketClient('wss://example.invalid', httpClient, clock.wallClock); + webSocketClients.push(client); + client.on(WebSocketClient.TOPIC.ON_ERROR, noop); + const reconnect = client['onReconnect'](); + const cancelled = expect(reconnect).rejects.toMatchObject({name: 'AbortError'}); + await flushPromises(); + expect(clock.pendingTimeoutCount()).toBe(1); + client.disconnect(); + await cancelled; + expect(clock.pendingTimeoutCount()).toBe(0); + clock.runNextRetryDelay(); + await flushPromises(); + expect(refreshAccessToken).toHaveBeenCalledTimes(1); + }); + + it('cancels an active refresh without emitting a late invalid-session event', async () => { + let rejectRefresh: (error: Error) => void = noop; + const refreshAccessToken = jest.fn(() => { return new Promise((_resolve, reject) => { rejectRefresh = reject; }); }); + const sendRequest = jest.fn(); + const httpClient = createWebSocketReconnectHttpClient({refreshAccessToken, hasValidAccessToken: () => false, sendRequest}); + const client = createWebSocketClientWithTestWallClock('wss://example.invalid', httpClient); + webSocketClients.push(client); + const invalidSession = jest.fn(); + client.on(WebSocketClient.TOPIC.ON_INVALID_TOKEN, invalidSession); + const reconnect = client['onReconnect'](); + const cancelled = expect(reconnect).rejects.toMatchObject({name: 'AbortError'}); + client.disconnect(); + await cancelled; + rejectRefresh(new InvalidTokenError('Expired session')); + await flushPromises(); + expect(invalidSession).not.toHaveBeenCalled(); + expect(sendRequest).not.toHaveBeenCalled(); + expect(refreshAccessToken).toHaveBeenCalledTimes(1); + }); + + it('aborts authenticated preflight before URL construction on disconnect', async () => { + let finishPreflight: () => void = noop; + const sendRequest = jest.fn(() => { return new Promise(resolve => { finishPreflight = resolve; }); }); + const httpClient = createWebSocketReconnectHttpClient({refreshAccessToken: jest.fn(), hasValidAccessToken: () => true, sendRequest: sendRequest as unknown as WebSocketHttpClient['sendRequest']}); + const client = createWebSocketClientWithTestWallClock('wss://example.invalid', httpClient); + webSocketClients.push(client); + const buildUrl = jest.spyOn(client, 'buildWebSocketUrl'); + const reconnect = client['onReconnect'](); + const cancelled = expect(reconnect).rejects.toMatchObject({name: 'AbortError'}); + await flushPromises(); + client.disconnect(); + await cancelled; + finishPreflight(); + await flushPromises(); + expect(buildUrl).not.toHaveBeenCalled(); + const request = (sendRequest.mock.calls as unknown as Array<[unknown, boolean, AbortController]>)[0]; + expect(request?.[2].signal.aborted).toBe(true); + }); + // eslint-disable-next-line jest/expect-expect it('emits the correct message for invalid tokens', async () => { - const websocketClient = new WebSocketClient('ws://url', invalidTokenHttpClient); + const websocketClient = createWebSocketClientWithTestWallClock('wss://url', invalidTokenHttpClient); webSocketClients.push(websocketClient); const socket = websocketClient['socket']; jest.spyOn(socket as any, 'getReconnectingWebsocket').mockReturnValue(fakeSocket); @@ -157,6 +342,291 @@ describe('WebSocketClient', () => { }); }); + describe('onReconnect', () => { + it('waits for the same in-flight access-token refresh before building reconnect URLs', async () => { + let resolveRefreshAccessToken: () => void = noop; + const refreshAccessTokenPromise = new Promise(resolve => { + resolveRefreshAccessToken = resolve; + }); + let accessTokenIsValid = false; + const refreshAccessToken = jest.fn(async () => { + await refreshAccessTokenPromise; + accessTokenIsValid = true; + return accessTokenPayload; + }); + const httpClient = createWebSocketReconnectHttpClient({ + refreshAccessToken, + hasValidAccessToken: () => accessTokenIsValid, + sendRequest: jest.fn().mockResolvedValue({data: {}}), + }); + const websocketClient = createWebSocketClientWithTestWallClock('wss://url', httpClient); + webSocketClients.push(websocketClient); + const buildWebSocketUrl = jest.spyOn(websocketClient, 'buildWebSocketUrl').mockReturnValue('wss://url/await'); + + const firstReconnect = websocketClient['onReconnect'](); + const firstCancelled = expect(firstReconnect).rejects.toMatchObject({name: 'AbortError'}); + const secondReconnect = websocketClient['onReconnect'](); + + await Promise.resolve(); + + expect(refreshAccessToken).toHaveBeenCalledTimes(1); + expect(buildWebSocketUrl).not.toHaveBeenCalled(); + + resolveRefreshAccessToken(); + + await firstCancelled; + await expect(secondReconnect).resolves.toBe('wss://url/await'); + expect(buildWebSocketUrl).toHaveBeenCalledTimes(1); + }); + + it('retries transient refresh failures without rejecting reconnect before building a WebSocket URL', async () => { + const refreshError = new Error('Network changed'); + const manualRetryWallClock = createManualRetryWallClock(); + let accessTokenIsValid = false; + const refreshAccessToken = jest + .fn() + .mockRejectedValueOnce(refreshError) + .mockImplementationOnce(async () => { + accessTokenIsValid = true; + return accessTokenPayload; + }); + const httpClient = createWebSocketReconnectHttpClient({ + refreshAccessToken, + hasValidAccessToken: () => accessTokenIsValid, + sendRequest: jest.fn().mockResolvedValue({data: {}}), + }); + const websocketClient = createWebSocketClient('wss://url', httpClient, manualRetryWallClock.wallClock); + webSocketClients.push(websocketClient); + const buildWebSocketUrl = jest.spyOn(websocketClient, 'buildWebSocketUrl').mockReturnValue('wss://url/await'); + + const reconnectPromise = websocketClient['onReconnect'](); + + await flushPromises(); + + expect(refreshAccessToken).toHaveBeenCalledTimes(1); + await expect(Promise.race([reconnectPromise, Promise.resolve(reconnectPendingMarker)])).resolves.toBe( + reconnectPendingMarker, + ); + expect(buildWebSocketUrl).not.toHaveBeenCalled(); + expect(manualRetryWallClock.retryDelaysInMilliseconds).toEqual([1_000]); + + manualRetryWallClock.runNextRetryDelay(); + + await expect(reconnectPromise).resolves.toBe('wss://url/await'); + expect(refreshAccessToken).toHaveBeenCalledTimes(2); + expect(buildWebSocketUrl).toHaveBeenCalledTimes(1); + }); + + it('does not run authenticated HTTP preflight when token refresh fails with invalid token', async () => { + const invalidTokenError = new InvalidTokenError('Invalid token'); + const sendRequest = jest.fn(); + const httpClient = createWebSocketReconnectHttpClient({ + refreshAccessToken: jest.fn().mockRejectedValue(invalidTokenError), + hasValidAccessToken: () => false, + sendRequest, + }); + const websocketClient = createWebSocketClientWithTestWallClock('wss://url', httpClient); + webSocketClients.push(websocketClient); + const buildWebSocketUrl = jest.spyOn(websocketClient, 'buildWebSocketUrl').mockReturnValue('wss://url/await'); + const invalidTokenListener = jest.fn(); + + websocketClient.on(WebSocketClient.TOPIC.ON_INVALID_TOKEN, invalidTokenListener); + + await expect(websocketClient['onReconnect']()).rejects.toBe(invalidTokenError); + + expect(invalidTokenListener).toHaveBeenCalledTimes(1); + expect(invalidTokenListener).toHaveBeenCalledWith(invalidTokenError); + expect(sendRequest).not.toHaveBeenCalled(); + expect(buildWebSocketUrl).not.toHaveBeenCalled(); + }); + + it('runs authenticated HTTP preflight before building WebSocket URL', async () => { + const refreshAccessToken = jest.fn().mockResolvedValue(accessTokenPayload); + const sendRequest = jest.fn().mockResolvedValue({data: {}}); + const httpClient = createWebSocketReconnectHttpClient({ + refreshAccessToken, + hasValidAccessToken: () => true, + sendRequest, + }); + const websocketClient = createWebSocketClientWithTestWallClock('wss://url', httpClient); + webSocketClients.push(websocketClient); + const buildWebSocketUrl = jest.spyOn(websocketClient, 'buildWebSocketUrl').mockReturnValue('wss://url/await'); + + await expect(websocketClient['onReconnect']()).resolves.toBe('wss://url/await'); + + expect(refreshAccessToken).not.toHaveBeenCalled(); + expect(sendRequest).toHaveBeenCalledTimes(1); + expect(sendRequest).toHaveBeenCalledWith({ + method: 'get', + url: '/cookies', + requestOptions: {skipLogout: true}, + }, false, expect.any(AbortController)); + expect(buildWebSocketUrl).toHaveBeenCalledTimes(1); + expect(sendRequest.mock.invocationCallOrder[0]).toBeLessThan(buildWebSocketUrl.mock.invocationCallOrder[0]); + }); + + it('refreshes invalid local token before running authenticated HTTP preflight', async () => { + const refreshAccessToken = jest.fn().mockResolvedValue(accessTokenPayload); + const hasValidAccessToken = jest.fn().mockReturnValueOnce(false).mockReturnValue(true); + const sendRequest = jest.fn().mockResolvedValue({data: {}}); + const httpClient = createWebSocketReconnectHttpClient({ + refreshAccessToken, + hasValidAccessToken, + sendRequest, + }); + const websocketClient = createWebSocketClientWithTestWallClock('wss://url', httpClient); + webSocketClients.push(websocketClient); + const buildWebSocketUrl = jest.spyOn(websocketClient, 'buildWebSocketUrl').mockReturnValue('wss://url/await'); + + await expect(websocketClient['onReconnect']()).resolves.toBe('wss://url/await'); + + expect(refreshAccessToken).toHaveBeenCalledTimes(1); + expect(sendRequest).toHaveBeenCalledTimes(1); + expect(buildWebSocketUrl).toHaveBeenCalledTimes(1); + expect(refreshAccessToken.mock.invocationCallOrder[0]).toBeLessThan(sendRequest.mock.invocationCallOrder[0]); + expect(sendRequest.mock.invocationCallOrder[0]).toBeLessThan(buildWebSocketUrl.mock.invocationCallOrder[0]); + }); + + it('does not build WebSocket URL when authenticated HTTP preflight fails', async () => { + const preflightError = new Error('Authenticated session verification failed'); + const sendRequest = jest.fn().mockRejectedValue(preflightError); + const httpClient = createWebSocketReconnectHttpClient({ + refreshAccessToken: jest.fn().mockResolvedValue(accessTokenPayload), + hasValidAccessToken: () => true, + sendRequest, + }); + const websocketClient = createWebSocketClientWithTestWallClock('wss://url', httpClient); + webSocketClients.push(websocketClient); + const buildWebSocketUrl = jest.spyOn(websocketClient, 'buildWebSocketUrl').mockReturnValue('wss://url/await'); + + await expect(websocketClient['onReconnect']()).rejects.toBe(preflightError); + + expect(sendRequest).toHaveBeenCalledTimes(1); + expect(buildWebSocketUrl).not.toHaveBeenCalled(); + }); + + it('builds a WebSocket URL without refreshing when the access token is already valid', async () => { + const refreshAccessToken = jest.fn().mockResolvedValue(accessTokenPayload); + const sendRequest = jest.fn().mockResolvedValue({data: {}}); + const httpClient = createWebSocketReconnectHttpClient({ + refreshAccessToken, + hasValidAccessToken: () => true, + sendRequest, + }); + const websocketClient = createWebSocketClientWithTestWallClock('wss://url', httpClient); + webSocketClients.push(websocketClient); + const buildWebSocketUrl = jest.spyOn(websocketClient, 'buildWebSocketUrl').mockReturnValue('wss://url/await'); + + await expect(websocketClient['onReconnect']()).resolves.toBe('wss://url/await'); + + expect(refreshAccessToken).not.toHaveBeenCalled(); + expect(sendRequest).toHaveBeenCalledTimes(1); + expect(buildWebSocketUrl).toHaveBeenCalledTimes(1); + }); + }); + + function createHttpClientWithWebSocketTokens(accessToken: string, nextMarkerToken: string): WebSocketHttpClient { + return { + ...fakeHttpClient, + accessTokenStore: { + getAccessToken: () => {return accessToken;}, + getNextMarkerToken: () => {return nextMarkerToken;}, + }, + }; + } + + describe('buildWebSocketUrl', () => { + it('builds a legacy await WebSocket URL without the async sync marker', () => { + const websocketClient = createWebSocketClientWithTestWallClock( + 'wss://websocket.example.test', + createHttpClientWithWebSocketTokens('access-token', 'marker-token'), + ); + webSocketClients.push(websocketClient); + + websocketClient.useVersion(MINIMUM_API_VERSION); + websocketClient['clientId'] = 'client-id'; + + expect(websocketClient.buildWebSocketUrl()).toBe( + 'wss://websocket.example.test/await?access_token=access-token&client=client-id', + ); + }); + + it('builds an async events WebSocket URL with the sync marker', () => { + const websocketClient = createWebSocketClientWithTestWallClock( + 'wss://websocket.example.test', + createHttpClientWithWebSocketTokens('access-token', 'marker-token'), + ); + webSocketClients.push(websocketClient); + + websocketClient.useVersion(MINIMUM_API_VERSION); + websocketClient.useAsyncNotificationsSocket(); + websocketClient['clientId'] = 'client-id'; + + expect(websocketClient.buildWebSocketUrl()).toBe( + `wss://websocket.example.test/v${MINIMUM_API_VERSION}/events?access_token=access-token&sync_marker=marker-token&client=client-id`, + ); + }); + }); + + describe('lifecycle diagnostics', () => { + const reconnectContext = {attemptId: 12, wrapperGeneration: 4, reconnectAttemptCount: 3, reconnectSequenceRetryCount: 2}; + + it('correlates authenticated preflight failures without exposing untrusted errors', async () => { + const failure = new Error('private-notification Cookie: secret-cookie https://user:password@example.test?secret=value'); + const httpClient = createWebSocketReconnectHttpClient({ + refreshAccessToken: jest.fn(), + hasValidAccessToken: () => {return true;}, + sendRequest: jest.fn().mockRejectedValue(failure), + }); + const client = createWebSocketClientWithTestWallClock('wss://example.test', httpClient); + webSocketClients.push(client); + const warning = jest.spyOn(client['logger'], 'warn'); + const buildUrl = jest.spyOn(client, 'buildWebSocketUrl'); + + await expect(client['onReconnect'](reconnectContext)).rejects.toBe(failure); + + expect(buildUrl).not.toHaveBeenCalled(); + expect(warning).toHaveBeenCalledWith(expect.stringContaining('event=auth-preflight-failure attemptId=12 wrapperGeneration=4')); + expect(warning.mock.calls.every(call => {return call.length === 1 && typeof call[0] === 'string';})).toBe(true); + expect(JSON.stringify(warning.mock.calls)).not.toMatch(/private-notification|secret-cookie|password|secret=value/); + }); + + it('logs only endpoint and presence flags while preserving the complete async URL', () => { + const client = createWebSocketClientWithTestWallClock('wss://user:password@example.test', + createHttpClientWithWebSocketTokens('secret-access', 'secret-marker')); + webSocketClients.push(client); + client.useVersion(MINIMUM_API_VERSION); + client.useAsyncNotificationsSocket(); + client['clientId'] = 'secret-client'; + const information = jest.spyOn(client['logger'], 'info'); + + const address = client.buildWebSocketUrl(reconnectContext); + + expect(address).toContain('access_token=secret-access&sync_marker=secret-marker&client=secret-client'); + expect(information).toHaveBeenCalledWith(expect.stringContaining('attemptId=12 wrapperGeneration=4 endpoint=async-events accessTokenPresent=true clientPresent=true markerIncluded=true')); + expect(JSON.stringify(information.mock.calls)).not.toMatch(/secret-access|secret-marker|secret-client|password|example.test/); + }); + + it('preserves invalid-session events while keeping socket-error diagnostics private', async () => { + const failure = new InvalidTokenError('arbitrary-private-content'); + const client = createWebSocketClientWithTestWallClock('wss://example.test', createWebSocketReconnectHttpClient({ + refreshAccessToken: jest.fn().mockRejectedValue(failure), + hasValidAccessToken: () => {return true;}, + sendRequest: jest.fn(), + })); + webSocketClients.push(client); + const invalidSession = jest.fn(); + client.on(WebSocketClient.TOPIC.ON_INVALID_TOKEN, invalidSession); + const warning = jest.spyOn(client['logger'], 'warn'); + + await client['onError']({message: 'private-socket-error'} as ErrorEvent, reconnectContext); + + expect(invalidSession).toHaveBeenCalledWith(failure); + expect(warning).toHaveBeenCalledWith(expect.stringContaining('source=socket-error attemptId=12 wrapperGeneration=4 fatal=true')); + expect(JSON.stringify(warning.mock.calls)).not.toMatch(/arbitrary-private-content|private-socket-error/); + }); + }); + describe('connect', () => { const fakeNotification: ConsumableNotification = { type: ConsumableEvent.EVENT, @@ -179,7 +649,7 @@ describe('WebSocketClient', () => { }; it('does not lock websocket by default', async () => { - const websocketClient = new WebSocketClient('ws://url', fakeHttpClient); + const websocketClient = createWebSocketClientWithTestWallClock('wss://url', fakeHttpClient); webSocketClients.push(websocketClient); const onMessageSpy = jest.spyOn(websocketClient as any, 'onMessage'); const socket = websocketClient['socket']; @@ -200,7 +670,7 @@ describe('WebSocketClient', () => { }); it('emits buffered messages when unlocked', async () => { - const websocketClient = new WebSocketClient('ws://url', fakeHttpClient); + const websocketClient = createWebSocketClientWithTestWallClock('wss://url', fakeHttpClient); webSocketClients.push(websocketClient); const onMessageSpy = jest.spyOn(websocketClient as any, 'onMessage'); const socket = websocketClient['socket']; @@ -223,5 +693,51 @@ describe('WebSocketClient', () => { websocketClient.unlock(); }); }); + + it('emits a long-running retry event once reconnect retries reach one minute', async () => { + const websocketClient = createWebSocketClientWithTestWallClock('wss://url', fakeHttpClient); + webSocketClients.push(websocketClient); + const retryDetailsListener = jest.fn(); + const socket = websocketClient['socket']; + + websocketClient.useVersion(MINIMUM_API_VERSION); + websocketClient.on(WebSocketClient.TOPIC.ON_LONG_RUNNING_RETRY, retryDetailsListener); + jest.spyOn(socket as any, 'getReconnectingWebsocket').mockReturnValue(fakeSocket); + + currentTimestampInMilliseconds = 0; + websocketClient.connect(); + await socket['internalOnReconnect'](); + currentTimestampInMilliseconds = 1_000; + await socket['internalOnReconnect'](); + currentTimestampInMilliseconds = 61_000; + await socket['internalOnReconnect'](); + + expect(retryDetailsListener).toHaveBeenCalledTimes(1); + expect(retryDetailsListener).toHaveBeenCalledWith({ + retryCount: 2, + retryDurationInMilliseconds: 60000, + }); + }); + + it('does not emit a long-running retry event before reconnect retries reach one minute', async () => { + const websocketClient = createWebSocketClientWithTestWallClock('wss://url', fakeHttpClient); + webSocketClients.push(websocketClient); + const retryDetailsListener = jest.fn(); + const socket = websocketClient['socket']; + + websocketClient.useVersion(MINIMUM_API_VERSION); + websocketClient.on(WebSocketClient.TOPIC.ON_LONG_RUNNING_RETRY, retryDetailsListener); + jest.spyOn(socket as any, 'getReconnectingWebsocket').mockReturnValue(fakeSocket); + + currentTimestampInMilliseconds = 0; + websocketClient.connect(); + await socket['internalOnReconnect'](); + currentTimestampInMilliseconds = 1_000; + await socket['internalOnReconnect'](); + currentTimestampInMilliseconds = 60_000; + await socket['internalOnReconnect'](); + + expect(retryDetailsListener).not.toHaveBeenCalled(); + }); }); }); diff --git a/libraries/api-client/src/tcp/WebSocketClient.ts b/libraries/api-client/src/tcp/WebSocketClient.ts index e942af5976e..be0dbec7944 100644 --- a/libraries/api-client/src/tcp/WebSocketClient.ts +++ b/libraries/api-client/src/tcp/WebSocketClient.ts @@ -18,16 +18,23 @@ */ import logdown from 'logdown'; -import {ErrorEvent} from 'reconnecting-websocket'; +import type {ErrorEvent} from 'partysocket/ws'; import {EventEmitter} from 'events'; import {LogFactory} from '@wireapp/commons'; import {AcknowledgeType} from './AcknowledgeEvent.types'; -import {ReconnectingWebsocket, WEBSOCKET_STATE} from './ReconnectingWebsocket'; - -import {InvalidTokenError, MissingCookieAndTokenError, MissingCookieError} from '../auth/'; +import { + createWebSocketWallClock, + LongRunningRetryDetails, + ReconnectingWebsocket, + ReconnectingWebsocketWallClock, + WebSocketReconnectContext, + WEBSOCKET_STATE, +} from './ReconnectingWebsocket'; + +import {AuthAPI, InvalidTokenError, MissingCookieAndTokenError, MissingCookieError} from '../auth/'; import {MINIMUM_API_VERSION} from '../Config'; import {HttpClient, NetworkError} from '../http/'; import {Notification} from '../notification'; @@ -41,25 +48,63 @@ import { enum TOPIC { ON_ERROR = 'WebSocketClient.TOPIC.ON_ERROR', ON_INVALID_TOKEN = 'WebSocketClient.TOPIC.ON_INVALID_TOKEN', + ON_LONG_RUNNING_RETRY = 'WebSocketClient.TOPIC.ON_LONG_RUNNING_RETRY', ON_MESSAGE = 'WebSocketClient.TOPIC.ON_MESSAGE', ON_STATE_CHANGE = 'WebSocketClient.TOPIC.ON_STATE_CHANGE', } +const accessTokenRefreshRetryInitialDelayInMilliseconds = 1_000; +const accessTokenRefreshRetryMaximumDelayInMilliseconds = 10_000; +const accessTokenRefreshRetryBackoffFactor = 2; +const firstRetryAttemptOffset = 1; + +async function waitForReconnectOperation(operation: Promise, signal: AbortSignal): Promise { + signal.throwIfAborted(); + + return new Promise((resolve, reject) => { + function abort(): void { + reject(signal.reason); + } + signal.addEventListener('abort', abort, {once: true}); + async function complete(): Promise { + try { + const value = await operation; + signal.throwIfAborted(); + resolve(value); + } catch (error: unknown) { + reject(error); + } finally { + signal.removeEventListener('abort', abort); + } + } + void complete(); + }); +} + export interface WebSocketClient { on(event: TOPIC.ON_ERROR, listener: (error: Error | ErrorEvent) => void): this; on(event: TOPIC.ON_INVALID_TOKEN, listener: (error: InvalidTokenError | MissingCookieError) => void): this; + on(event: TOPIC.ON_LONG_RUNNING_RETRY, listener: (retryDetails: LongRunningRetryDetails) => void): this; on(event: TOPIC.ON_MESSAGE, listener: (notification: Notification | ConsumableNotification) => void): this; on(event: TOPIC.ON_STATE_CHANGE, listener: (state: WEBSOCKET_STATE) => void): this; } -export type OnConnect = (abortHandler: AbortController) => void; +export type OnConnect = (abortHandler: AbortController, reconnectContext: WebSocketReconnectContext) => void; + +export type WebSocketClientOptions = { + readonly wallClock: ReconnectingWebsocketWallClock; +}; export class WebSocketClient extends EventEmitter { private clientId?: string; - private isRefreshingAccessToken: boolean; + private accessTokenRefreshPromise?: Promise; + private accessTokenRefreshLifetime?: AbortController; + private reconnectLifetime = new AbortController(); + private readonly refreshConsumers = new Set(); private readonly baseUrl: string; private readonly logger: logdown.Logger; private readonly socket: ReconnectingWebsocket; + private readonly wallClock: ReconnectingWebsocketWallClock; private websocketState: WEBSOCKET_STATE; public client: HttpClient; private isSocketLocked: boolean; @@ -71,15 +116,24 @@ export class WebSocketClient extends EventEmitter { private useLegacySocket: boolean = true; - constructor(baseUrl: string, client: HttpClient) { + constructor( + baseUrl: string, + client: HttpClient, + options: WebSocketClientOptions = {wallClock: createWebSocketWallClock()}, + ) { super(); this.bufferedMessages = []; this.isSocketLocked = false; this.baseUrl = baseUrl; this.client = client; - this.isRefreshingAccessToken = false; - this.socket = new ReconnectingWebsocket(this.onReconnect); + this.wallClock = options.wallClock; + this.socket = new ReconnectingWebsocket(this.onReconnect, { + backFromSleepHandler: undefined, + pingInterval: undefined, + wallClock: options.wallClock, + websocketFactory: undefined, + }); this.websocketState = this.socket.getState(); this.logger = LogFactory.getLogger('@wireapp/api-client/tcp/WebSocketClient'); @@ -100,7 +154,7 @@ export class WebSocketClient extends EventEmitter { } private readonly onMessage = (data: string) => { - if (!data) { + if (!Boolean(data)) { this.logger.warn('Received empty message from WebSocket'); return; } @@ -115,18 +169,48 @@ export class WebSocketClient extends EventEmitter { } }; - private readonly onError = async (error: ErrorEvent) => { + private readonly onError = async (error: ErrorEvent, reconnectContext: WebSocketReconnectContext) => { + if (this.reconnectLifetime.signal.aborted === true) { + return; + } this.onStateChange(this.socket.getState()); this.emit(WebSocketClient.TOPIC.ON_ERROR, error); - await this.refreshAccessToken(); + try { + await this.refreshAccessToken(this.reconnectLifetime.signal); + } catch (refreshError: unknown) { + this.logger.warn( + `[WebSocketLifecycle] event=token-refresh-failure source=socket-error attemptId=${reconnectContext.attemptId} wrapperGeneration=${reconnectContext.wrapperGeneration} fatal=${this.isInvalidSessionError(refreshError)}`, + ); + } }; - private readonly onReconnect = async () => { - if (!this.client.hasValidAccessToken()) { - // before we try any connection, we first refresh the access token to make sure we will avoid concurrent accessToken refreshes - await this.refreshAccessToken(); + private readonly onReconnect = async ( + reconnectContext: WebSocketReconnectContext = { + attemptId: 0, + wrapperGeneration: 0, + reconnectAttemptCount: 0, + reconnectSequenceRetryCount: 0, + }, + signal?: AbortSignal, + ): Promise => { + this.reconnectLifetime.abort(); + const lifetime = new AbortController(); + this.reconnectLifetime = lifetime; + function abort(): void { + lifetime.abort(); + } + signal?.addEventListener('abort', abort, {once: true}); + try { + signal?.throwIfAborted(); + await this.waitForValidAccessTokenBeforeReconnect(reconnectContext, lifetime.signal); + await this.verifyAuthenticatedSessionBeforeReconnect(reconnectContext, lifetime); + // URL construction creates the marker: cancellation must be checked before this side effect. + lifetime.signal.throwIfAborted(); + + return this.buildWebSocketUrl(reconnectContext); + } finally { + signal?.removeEventListener('abort', abort); } - return this.buildWebSocketUrl(); }; private readonly onOpen = () => { @@ -134,9 +218,18 @@ export class WebSocketClient extends EventEmitter { }; private readonly onClose = () => { + this.abortNotificationProcessing(); + this.onStateChange(WEBSOCKET_STATE.CLOSED); + }; + + private abortNotificationProcessing(): void { this.abortHandler?.abort(); + this.abortHandler = undefined; this.bufferedMessages = []; - this.onStateChange(this.socket.getState()); + } + + private readonly onLongRunningRetry = (retryDetails: LongRunningRetryDetails) => { + this.emit(WebSocketClient.TOPIC.ON_LONG_RUNNING_RETRY, retryDetails); }; /** @@ -157,53 +250,216 @@ export class WebSocketClient extends EventEmitter { this.onStateChange(WEBSOCKET_STATE.CONNECTING); this.socket.setOnMessage(this.onMessage); this.socket.setOnError(this.onError); - this.socket.setOnOpen(() => { + this.socket.setOnLongRunningRetry(this.onLongRunningRetry); + this.socket.setOnOpen((_event, reconnectContext) => { + this.abortNotificationProcessing(); this.onOpen(); - if (onConnect) { + if (onConnect !== undefined) { this.abortHandler = new AbortController(); - void onConnect(this.abortHandler); + void onConnect(this.abortHandler, reconnectContext); } }); this.socket.setOnClose(this.onClose); + this.socket.setOnConnecting(() => { + this.abortNotificationProcessing(); + this.onStateChange(WEBSOCKET_STATE.CONNECTING); + }); this.socket.connect(); return this; } - private async refreshAccessToken(): Promise { - if (this.isRefreshingAccessToken) { - return; + private async refreshAccessToken(signal: AbortSignal): Promise { + signal.throwIfAborted(); + this.refreshConsumers.add(signal); + if (this.accessTokenRefreshPromise === undefined || this.accessTokenRefreshLifetime?.signal.aborted === true) { + const refreshLifetime = new AbortController(); + this.accessTokenRefreshLifetime = refreshLifetime; + this.accessTokenRefreshPromise = this.refreshAccessTokenWithCleanup(refreshLifetime); + } + try { + await waitForReconnectOperation(this.accessTokenRefreshPromise, signal); + } finally { + this.refreshConsumers.delete(signal); } - this.isRefreshingAccessToken = true; + } + private async waitForValidAccessTokenBeforeReconnect( + reconnectContext: WebSocketReconnectContext, + signal: AbortSignal, + ): Promise { + let retryCount = 0; + const tokenValidationStartTimestampInMilliseconds = this.wallClock.currentTimestampInMilliseconds; + this.logger.debug( + `[WebSocketLifecycle] event=token-validation-start attemptId=${reconnectContext.attemptId} wrapperGeneration=${reconnectContext.wrapperGeneration} refreshInFlight=${this.accessTokenRefreshPromise !== undefined}`, + ); + + while (!this.client.hasValidAccessToken()) { + signal.throwIfAborted(); + const refreshStartTimestampInMilliseconds = this.wallClock.currentTimestampInMilliseconds; + this.logger.debug( + `[WebSocketLifecycle] event=token-refresh-start attemptId=${reconnectContext.attemptId} wrapperGeneration=${reconnectContext.wrapperGeneration} retry=${retryCount}`, + ); + + try { + await this.refreshAccessToken(signal); + } catch (error: unknown) { + signal.throwIfAborted(); + if (this.isInvalidSessionError(error)) { + this.logger.warn( + `[WebSocketLifecycle] event=token-refresh-failure attemptId=${reconnectContext.attemptId} wrapperGeneration=${reconnectContext.wrapperGeneration} fatal=true`, + ); + throw error; + } + + retryCount += 1; + const nextRetryDelayInMilliseconds = this.getAccessTokenRefreshRetryDelayInMilliseconds(retryCount); + this.logger.warn( + `[WebSocketLifecycle] event=token-refresh-retry attemptId=${reconnectContext.attemptId} wrapperGeneration=${reconnectContext.wrapperGeneration} retry=${retryCount} nextDelayMs=${nextRetryDelayInMilliseconds}`, + ); + await this.waitForNextAccessTokenRefreshRetry(nextRetryDelayInMilliseconds, signal); + continue; + } + + if (this.client.hasValidAccessToken()) { + this.logger.info( + `[WebSocketLifecycle] event=token-refresh-success attemptId=${reconnectContext.attemptId} wrapperGeneration=${reconnectContext.wrapperGeneration} retry=${retryCount} durationMs=${this.wallClock.currentTimestampInMilliseconds - refreshStartTimestampInMilliseconds}`, + ); + this.logger.info( + `[WebSocketLifecycle] event=token-validation-success attemptId=${reconnectContext.attemptId} wrapperGeneration=${reconnectContext.wrapperGeneration} refreshed=true durationMs=${this.wallClock.currentTimestampInMilliseconds - tokenValidationStartTimestampInMilliseconds}`, + ); + return; + } + + retryCount += 1; + const nextRetryDelayInMilliseconds = this.getAccessTokenRefreshRetryDelayInMilliseconds(retryCount); + this.logger.warn( + `[WebSocketLifecycle] event=token-refresh-retry attemptId=${reconnectContext.attemptId} wrapperGeneration=${reconnectContext.wrapperGeneration} retry=${retryCount} nextDelayMs=${nextRetryDelayInMilliseconds} errorName=InvalidAccessTokenState errorMessage="Token remains invalid after refresh"`, + ); + await this.waitForNextAccessTokenRefreshRetry(nextRetryDelayInMilliseconds, signal); + } + this.logger.info( + `[WebSocketLifecycle] event=token-validation-success attemptId=${reconnectContext.attemptId} wrapperGeneration=${reconnectContext.wrapperGeneration} durationMs=${this.wallClock.currentTimestampInMilliseconds - tokenValidationStartTimestampInMilliseconds}`, + ); + } + + private async verifyAuthenticatedSessionBeforeReconnect( + reconnectContext: WebSocketReconnectContext, + lifetime: AbortController, + ): Promise { + lifetime.signal.throwIfAborted(); + const preflightStartTimestampInMilliseconds = this.wallClock.currentTimestampInMilliseconds; + this.logger.debug( + `[WebSocketLifecycle] event=auth-preflight-start attemptId=${reconnectContext.attemptId} wrapperGeneration=${reconnectContext.wrapperGeneration} endpoint=cookies`, + ); + + try { + await waitForReconnectOperation( + this.client.sendRequest( + { + method: 'get', + url: AuthAPI.URL.COOKIES, + requestOptions: {skipLogout: true}, + }, + false, + lifetime, + ), + lifetime.signal, + ); + } catch (error: unknown) { + lifetime.signal.throwIfAborted(); + if (this.isInvalidSessionError(error)) { + this.emit(WebSocketClient.TOPIC.ON_INVALID_TOKEN, error); + } + this.logger.warn( + `[WebSocketLifecycle] event=auth-preflight-failure attemptId=${reconnectContext.attemptId} wrapperGeneration=${reconnectContext.wrapperGeneration} durationMs=${this.wallClock.currentTimestampInMilliseconds - preflightStartTimestampInMilliseconds}`, + ); + throw error; + } + + this.logger.info( + `[WebSocketLifecycle] event=auth-preflight-success attemptId=${reconnectContext.attemptId} wrapperGeneration=${reconnectContext.wrapperGeneration} durationMs=${this.wallClock.currentTimestampInMilliseconds - preflightStartTimestampInMilliseconds}`, + ); + } + + private isInvalidSessionError(error: unknown): boolean { + return ( + error instanceof InvalidTokenError || + error instanceof MissingCookieError || + error instanceof MissingCookieAndTokenError + ); + } + + private getAccessTokenRefreshRetryDelayInMilliseconds(retryCount: number): number { + const delayInMilliseconds = + accessTokenRefreshRetryInitialDelayInMilliseconds * + accessTokenRefreshRetryBackoffFactor ** (retryCount - firstRetryAttemptOffset); + + return Math.min(delayInMilliseconds, accessTokenRefreshRetryMaximumDelayInMilliseconds); + } + + private waitForNextAccessTokenRefreshRetry(delayInMilliseconds: number, signal: AbortSignal): Promise { + signal.throwIfAborted(); + const wallClock = this.wallClock; + + return new Promise((resolve, reject) => { + function abort(): void { + wallClock.clearTimeout(timeoutIdentifier); + reject(signal.reason); + } + const timeoutIdentifier = wallClock.setTimeout(() => { + signal.removeEventListener('abort', abort); + resolve(); + }, delayInMilliseconds); + signal.addEventListener('abort', abort, {once: true}); + }); + } + + private async refreshAccessTokenWithCleanup(lifetime: AbortController): Promise { + try { + await this.refreshAccessTokenOnce(lifetime.signal); + } finally { + if (this.accessTokenRefreshLifetime === lifetime) { + this.accessTokenRefreshPromise = undefined; + this.accessTokenRefreshLifetime = undefined; + } + } + } + + private async refreshAccessTokenOnce(signal: AbortSignal): Promise { try { - await this.client.refreshAccessToken(); - } catch (error) { - if (error instanceof NetworkError) { - this.logger.warn(error); - } else if ( + await this.client.refreshAccessToken(signal); + } catch (error: unknown) { + signal.throwIfAborted(); + const hasActiveConsumer = Array.from(this.refreshConsumers).some(signal => { + return signal.aborted === false; + }); + if (hasActiveConsumer === false) { + throw error; + } + if ( error instanceof InvalidTokenError || error instanceof MissingCookieError || error instanceof MissingCookieAndTokenError ) { // On invalid cookie the application is supposed to logout. - this.logger.warn( - `[WebSocket] Cannot renew access token because cookie/token is invalid: ${error.message}`, - error, - ); this.emit(WebSocketClient.TOPIC.ON_INVALID_TOKEN, error); - } else { + } else if (!(error instanceof NetworkError)) { this.emit(WebSocketClient.TOPIC.ON_ERROR, error); } - } finally { - this.isRefreshingAccessToken = false; + + throw error; } } public disconnect(reason?: string): void { - if (this.socket) { + this.reconnectLifetime.abort(); + this.accessTokenRefreshLifetime?.abort(); + this.abortNotificationProcessing(); + if (this.socket !== undefined) { this.socket.disconnect(reason); } + this.onStateChange(WEBSOCKET_STATE.CLOSED); } /** @@ -235,18 +491,15 @@ export class WebSocketClient extends EventEmitter { return this.isSocketLocked; } - public buildWebSocketUrl(): string { + public buildWebSocketUrl(reconnectContext?: WebSocketReconnectContext): string { const { accessTokenStore: {getAccessToken, getNextMarkerToken}, } = this.client; const accessToken = getAccessToken?.() ?? ''; - const markerToken = getNextMarkerToken?.(); - - if (!accessToken) { - this.logger.warn('Reconnecting WebSocket with unset token'); - } + const markerToken = getNextMarkerToken?.() ?? ''; + const markerIncluded = !this.useLegacySocket && markerToken.length > 0; - if (!this.versionPrefix) { + if (!Boolean(this.versionPrefix)) { throw new Error('Missing backend API version: cannot establish WebSocket connection'); } @@ -254,7 +507,7 @@ export class WebSocketClient extends EventEmitter { access_token: accessToken, }); - if (markerToken && !this.useLegacySocket) { + if (markerIncluded) { queryParams.append('sync_marker', markerToken); } @@ -262,7 +515,7 @@ export class WebSocketClient extends EventEmitter { * @note If no client ID is given, then the WebSocket connection * will receive all notifications for all clients of the connected user */ - if (this.clientId) { + if (this.clientId !== undefined && this.clientId.length > 0) { queryParams.append('client', this.clientId); } @@ -272,7 +525,19 @@ export class WebSocketClient extends EventEmitter { ? `${this.baseUrl}/await?${queryString}` : `${this.baseUrl}${this.versionPrefix}/events?${queryString}`; - this.logger.info(`WebSocket URL: ${websocketAddress}`); + const attemptId = reconnectContext?.attemptId ?? 0; + const wrapperGeneration = reconnectContext?.wrapperGeneration ?? 0; + const endpoint = this.useLegacySocket ? 'legacy-await' : 'async-events'; + const accessTokenPresent = accessToken.length > 0; + const clientPresent = this.clientId !== undefined && this.clientId.length > 0; + if (!accessTokenPresent) { + this.logger.warn( + `[WebSocketLifecycle] event=url-created-without-access-token attemptId=${attemptId} wrapperGeneration=${wrapperGeneration} endpoint=${endpoint} clientPresent=${clientPresent} markerIncluded=${markerIncluded}`, + ); + } + this.logger.info( + `[WebSocketLifecycle] event=url-created attemptId=${attemptId} wrapperGeneration=${wrapperGeneration} endpoint=${endpoint} accessTokenPresent=${accessTokenPresent} clientPresent=${clientPresent} markerIncluded=${markerIncluded}`, + ); return websocketAddress; } diff --git a/libraries/api-client/src/utils/BackFromSleepHandler/BackFromSleepHandler.ts b/libraries/api-client/src/utils/BackFromSleepHandler/BackFromSleepHandler.ts index 52bf81a38f1..c920237f8dc 100644 --- a/libraries/api-client/src/utils/BackFromSleepHandler/BackFromSleepHandler.ts +++ b/libraries/api-client/src/utils/BackFromSleepHandler/BackFromSleepHandler.ts @@ -20,6 +20,12 @@ const CHECK_INTERVAL = 2000; const TOLERANCE = CHECK_INTERVAL * 2; +export type BackFromSleepDetails = { + readonly expectedIntervalMilliseconds: number; + readonly observedIntervalMilliseconds: number; + readonly suspensionDurationMilliseconds: number; +}; + /** * This function will call the callback when the system has very likely woken up from sleep. * It will ignore small delays and will only call the callback if the system was disconnected during sleep. @@ -42,7 +48,7 @@ export const onBackFromSleep = ({ callback, isDisconnected: isDisconnectedCallback, }: { - callback: () => void; + callback: (details?: BackFromSleepDetails) => void; isDisconnected?: () => boolean; }) => { let lastTime = new Date().getTime(); @@ -50,9 +56,10 @@ export const onBackFromSleep = ({ const tid = setInterval(() => { const currentTime = new Date().getTime(); + const observedIntervalMilliseconds = currentTime - lastTime; // The interval did not run for a while, so we assume the system was sleeping - const wasAsleep = currentTime > lastTime + TOLERANCE; + const wasAsleep = observedIntervalMilliseconds > TOLERANCE; lastTime = currentTime; @@ -63,7 +70,11 @@ export const onBackFromSleep = ({ if (wasAsleep) { if (!isDisconnectedCallback || wasDisconnected) { wasDisconnected = false; - callback(); + callback({ + expectedIntervalMilliseconds: CHECK_INTERVAL, + observedIntervalMilliseconds, + suspensionDurationMilliseconds: Math.max(0, observedIntervalMilliseconds - CHECK_INTERVAL), + }); } } }, CHECK_INTERVAL); diff --git a/libraries/core/src/Account.test.ts b/libraries/core/src/Account.test.ts index df6789f1d4a..37a2ac0b6f6 100644 --- a/libraries/core/src/Account.test.ts +++ b/libraries/core/src/Account.test.ts @@ -27,12 +27,13 @@ import { } from '@wireapp/api-client/lib/client'; import {MINIMUM_API_VERSION} from '@wireapp/api-client/lib/Config'; import {ConversationAPI} from '@wireapp/api-client/lib/conversation'; -import {BackendEvent} from '@wireapp/api-client/lib/event'; +import {BackendEvent, USER_EVENT} from '@wireapp/api-client/lib/event'; import {BackendError, BackendErrorLabel} from '@wireapp/api-client/lib/http'; import {NotificationAPI} from '@wireapp/api-client/lib/notification'; -import {ConsumableEvent} from '@wireapp/api-client/lib/notification/ConsumableNotification'; +import {ConsumableEvent, ConsumableNotificationEvent} from '@wireapp/api-client/lib/notification/ConsumableNotification'; import {Self, SelfAPI} from '@wireapp/api-client/lib/self'; -import {ReconnectingWebsocket} from '@wireapp/api-client/lib/tcp/ReconnectingWebsocket'; +import {WebSocketClient} from '@wireapp/api-client/lib/tcp'; +import {ReconnectingWebsocket, WEBSOCKET_STATE} from '@wireapp/api-client/lib/tcp/ReconnectingWebsocket'; import {StatusCodes as HTTP_STATUS} from 'http-status-codes'; import {WS} from 'jest-websocket-mock'; import nock, {cleanAll} from 'nock'; @@ -57,7 +58,7 @@ jest.mock('./conversation', () => { }); import {Account, ConnectionState} from './Account'; -import {NotificationSource} from './notification'; +import {HandledEventPayload, NotificationSource} from './notification'; const BASE_URL = 'mock-backend.wire.com'; const MOCK_BACKEND = { @@ -68,6 +69,43 @@ const MOCK_BACKEND = { const apiClients: APIClient[] = []; +type ControlledSocket = ReturnType & { + readonly open: () => void; + readonly beginClose: () => void; + readonly receive: (notification: unknown) => void; +}; + +function createControlledSocket(): ControlledSocket { + let state = WEBSOCKET_STATE.CONNECTING; + const socket: ControlledSocket = { + binaryType: 'blob', + get readyState(): WEBSOCKET_STATE { return state; }, + close: jest.fn(() => { state = WEBSOCKET_STATE.CLOSED; }), + reconnect: jest.fn(), + send: jest.fn(), + onopen: null, + onclose: null, + onerror: null, + onmessage: null, + open(): void { + state = WEBSOCKET_STATE.OPEN; + socket.onopen?.(new Event('open')); + }, + beginClose(): void { state = WEBSOCKET_STATE.CLOSING; }, + receive(notification): void { + socket.onmessage?.({data: JSON.stringify(notification)} as MessageEvent); + }, + }; + + return socket; +} + +async function flushNotificationCallbacks(): Promise { + for (let turn = 0; turn < 30; turn += 1) { + await Promise.resolve(); + } +} + async function createAccount(): Promise<{account: Account; apiClient: APIClient}> { const apiClient = new APIClient({urls: MOCK_BACKEND}); apiClients.push(apiClient); @@ -123,6 +161,9 @@ describe('Account', () => { const websocketServerAddress = `${MOCK_BACKEND.ws}/v${MINIMUM_API_VERSION}/events?access_token=${accessTokenData.access_token}&marker=${markerId}`; beforeEach(() => { + nock(MOCK_BACKEND.rest).get(AuthAPI.URL.COOKIES).reply(HTTP_STATUS.OK, {}).persist(); + nock(MOCK_BACKEND.rest).get(`/v${MINIMUM_API_VERSION}${AuthAPI.URL.COOKIES}`).reply(HTTP_STATUS.OK, {}).persist(); + nock(MOCK_BACKEND.rest) .post(AuthAPI.URL.LOGIN, body => body.email && body.password) .query(() => true) @@ -288,6 +329,7 @@ describe('Account', () => { describe('Websocket connection', () => { let dependencies: {account: Account; apiClient: APIClient}; let server: WS; + let synchronizeOnConnect = true; const mockNotifications = (size: number) => { const notifications = Array.from(new Array(size)).map(() => ({ @@ -318,8 +360,19 @@ describe('Account', () => { beforeEach(async () => { server = new WS(websocketServerAddress); // isolate per test + synchronizeOnConnect = true; dependencies = await createAccount(); + dependencies.apiClient.transport.http.accessTokenStore.markerToken = markerId; + server.on('connection', socket => { + if (dependencies.apiClient.transport.ws['useLegacySocket'] === true || synchronizeOnConnect === false) { + return; + } + socket.send(JSON.stringify({ + type: ConsumableEvent.SYNCHRONIZATION, + data: {marker_id: dependencies.apiClient.transport.http.accessTokenStore.markerToken, delivery_tag: 1}, + })); + }); const {account} = dependencies; await account.login({ clientType: ClientType.TEMPORARY, @@ -348,6 +401,386 @@ describe('Account', () => { }); describe('listen', () => { + it('cancels legacy catch-up when replacing a closing wrapper before its close event', async () => { + const {account, apiClient} = dependencies; + const firstSocket = createControlledSocket(); + const replacementSocket = createControlledSocket(); + const transport = apiClient.transport.ws['socket']; + jest.spyOn(transport as unknown as {getReconnectingWebsocket: () => ControlledSocket}, 'getReconnectingWebsocket') + .mockReturnValueOnce(firstSocket).mockReturnValue(replacementSocket); + jest.spyOn(account.service!.client, 'putClientCapabilities').mockResolvedValue(undefined); + const catchupSignals: Array = []; + const finishCatchups: Array<() => void> = []; + const deliverCatchups: Array<() => Promise> = []; + const deliverMissedNotifications: Array<() => void> = []; + jest.spyOn(account.service!.notification, 'legacyProcessNotificationStream').mockImplementation(async (onNotification, onMissed, lifetime) => { + catchupSignals.push(lifetime?.signal); + deliverMissedNotifications.push(() => { onMissed('obsolete-notification'); }); + deliverCatchups.push(async () => { + await onNotification({id: 'late-notification', payload: []}, NotificationSource.NOTIFICATION_STREAM); + }); + await new Promise(resolve => { finishCatchups.push(resolve); }); + + return {total: 0, success: 0, error: 0}; + }); + const stateChanged = jest.fn(); + const missedNotifications = jest.fn(); + const unlock = jest.spyOn(apiClient.transport.ws, 'unlock'); + const disconnect = await account.listen({useLegacy: true, onConnectionStateChanged: stateChanged, onMissedNotifications: missedNotifications}); + firstSocket.open(); + firstSocket.beginClose(); + transport['handleBackFromSleep'](); + expect(catchupSignals[0]?.aborted).toBe(true); + expect(stateChanged).toHaveBeenLastCalledWith(ConnectionState.CONNECTING, expect.any(Object)); + replacementSocket.open(); + const handleNotification = jest.spyOn(account.service!.notification, 'handleNotification'); + await deliverCatchups[0]?.(); + deliverMissedNotifications[0]?.(); + finishCatchups[0]?.(); + await flushNotificationCallbacks(); + expect(handleNotification).not.toHaveBeenCalled(); + expect(missedNotifications).not.toHaveBeenCalled(); + expect(unlock).not.toHaveBeenCalled(); + expect(stateChanged.mock.calls.some(call => { return call[0] === ConnectionState.LIVE; })).toBe(false); + expect(catchupSignals[1]?.aborted).toBe(false); + finishCatchups[1]?.(); + await flushNotificationCallbacks(); + expect(unlock).toHaveBeenCalledTimes(1); + expect(stateChanged).toHaveBeenLastCalledWith(ConnectionState.LIVE, expect.any(Object)); + disconnect(); + expect(catchupSignals[1]?.aborted).toBe(true); + }); + + it.each([true, false])('rejects obsolete async processing and accepts the replacement marker when decryption yields=%s', async yieldsNotification => { + const {account, apiClient} = dependencies; + const firstSocket = createControlledSocket(); + const replacementSocket = createControlledSocket(); + const transport = apiClient.transport.ws['socket']; + jest.spyOn(transport as unknown as {getReconnectingWebsocket: () => ControlledSocket}, 'getReconnectingWebsocket') + .mockReturnValueOnce(firstSocket).mockReturnValue(replacementSocket); + jest.spyOn(account.service!.client, 'putClientCapabilities').mockResolvedValue(undefined); + jest.spyOn(account, 'getClientCapabilities').mockReturnValue([ClientCapability.CONSUMABLE_NOTIFICATIONS]); + let finishDecryption: () => void = () => {}; + const decryption = new Promise(resolve => { finishDecryption = resolve; }); + const obsoleteEvent: BackendEvent = { + type: USER_EVENT.DELETE, + id: 'obsolete-user', + qualified_id: {id: 'obsolete-user', domain: 'example.invalid'}, + }; + async function* decryptObsoleteNotification(): AsyncGenerator { + await decryption; + if (yieldsNotification === true) { + yield {event: obsoleteEvent}; + } + } + const decryptNotification = jest.spyOn(account.service!.notification, 'handleNotification') + .mockImplementation(decryptObsoleteNotification); + const eventReceived = jest.fn(); + const stateChanged = jest.fn(); + const acknowledge = jest.spyOn(apiClient.transport.ws, 'acknowledgeNotification'); + const acknowledgeMarker = jest.spyOn(apiClient.transport.ws, 'acknowledgeConsumableNotificationSynchronization'); + const disconnect = await account.listen({useLegacy: false, onEvent: eventReceived, onConnectionStateChanged: stateChanged}); + firstSocket.open(); + firstSocket.receive({type: ConsumableEvent.EVENT, data: {delivery_tag: 1, event: {id: 'obsolete', payload: [obsoleteEvent]}}}); + firstSocket.receive({type: ConsumableEvent.SYNCHRONIZATION, data: {delivery_tag: 2, marker_id: markerId}}); + await flushNotificationCallbacks(); + expect(decryptNotification).toHaveBeenCalledTimes(1); + firstSocket.beginClose(); + transport['handleBackFromSleep'](); + replacementSocket.open(); + apiClient.transport.http.accessTokenStore.markerToken = 'replacement-marker'; + const replacementMarker = {type: ConsumableEvent.SYNCHRONIZATION, data: {delivery_tag: 3, marker_id: 'replacement-marker'}}; + replacementSocket.receive(replacementMarker); + finishDecryption(); + await flushNotificationCallbacks(); + expect(eventReceived).not.toHaveBeenCalled(); + expect(acknowledge).not.toHaveBeenCalled(); + expect(acknowledgeMarker).toHaveBeenCalledTimes(1); + expect(acknowledgeMarker).toHaveBeenCalledWith(replacementMarker); + expect(stateChanged).toHaveBeenLastCalledWith(ConnectionState.LIVE, expect.any(Object)); + disconnect(); + }); + + it('preserves external subscriptions and cleans up each lifetime across repeated replacements', async () => { + const {account, apiClient} = dependencies; + const transport = apiClient.transport.ws['socket']; + const sockets: ControlledSocket[] = []; + jest.spyOn(transport as unknown as {getReconnectingWebsocket: () => ControlledSocket}, 'getReconnectingWebsocket') + .mockImplementation(() => { + const socket = createControlledSocket(); + sockets.push(socket); + + return socket; + }); + jest.spyOn(account.service!.client, 'putClientCapabilities').mockResolvedValue(undefined); + jest.spyOn(account, 'getClientCapabilities').mockReturnValue([ClientCapability.CONSUMABLE_NOTIFICATIONS]); + const retryReported = jest.fn(); + const cancelled = jest.fn(); + apiClient.transport.ws.on(WebSocketClient.TOPIC.ON_LONG_RUNNING_RETRY, retryReported); + const initialMessageListeners = apiClient.transport.ws.listenerCount(WebSocketClient.TOPIC.ON_MESSAGE); + const disconnect = await account.listen({useLegacy: false}); + for (let replacement = 0; replacement < 3; replacement += 1) { + const socket = sockets.at(-1); + if (socket === undefined) { throw new Error('Expected active wrapper'); } + socket.open(); + apiClient.transport.ws['abortHandler']?.signal.addEventListener('abort', cancelled); + socket.beginClose(); + transport['handleBackFromSleep'](); + expect(socket.close).toHaveBeenCalledTimes(1); + expect(apiClient.transport.ws.listenerCount(WebSocketClient.TOPIC.ON_MESSAGE)).toBe(initialMessageListeners + 1); + } + expect(cancelled).toHaveBeenCalledTimes(3); + disconnect(); + disconnect(); + expect(sockets.at(-1)?.close).toHaveBeenCalledTimes(1); + expect(apiClient.transport.ws.listenerCount(WebSocketClient.TOPIC.ON_MESSAGE)).toBe(initialMessageListeners); + apiClient.transport.ws.emit(WebSocketClient.TOPIC.ON_LONG_RUNNING_RETRY, {retryCount: 1, retryDurationInMilliseconds: 60_000}); + expect(retryReported).toHaveBeenCalledTimes(1); + apiClient.transport.ws.removeListener(WebSocketClient.TOPIC.ON_LONG_RUNNING_RETRY, retryReported); + }); + + it('keeps the active marker and reaches LIVE when authenticated attempts finish in reverse order', async () => { + const {account, apiClient} = dependencies; + const webSocket = apiClient.transport.ws; + jest.spyOn(webSocket, 'buildWebSocketUrl').mockRestore(); + webSocket.useAsyncNotificationsSocket(); + jest.spyOn(apiClient.transport.http, 'hasValidAccessToken').mockReturnValue(true); + let finishFirst: () => void = () => {}; + let finishSecond: () => void = () => {}; + const firstPreflight = new Promise(resolve => { finishFirst = resolve; }); + const secondPreflight = new Promise(resolve => { finishSecond = resolve; }); + const sendRequest = jest.spyOn(apiClient.transport.http, 'sendRequest') + .mockImplementationOnce(async () => { await firstPreflight; return {data: {}} as never; }) + .mockImplementationOnce(async () => { await secondPreflight; return {data: {}} as never; }); + const transport = webSocket['socket']; + const first = transport['internalOnReconnect'](); + const firstCancelled = expect(first).rejects.toMatchObject({name: 'AbortError'}); + await Promise.resolve(); + const second = transport['internalOnReconnect'](); + await Promise.resolve(); + expect(sendRequest).toHaveBeenCalledTimes(2); + finishSecond(); + const activeUrl = new URL(await second); + const activeMarker = activeUrl.searchParams.get('sync_marker'); + expect(activeMarker).toEqual(expect.any(String)); + finishFirst(); + await firstCancelled; + await Promise.resolve(); + expect(apiClient.transport.http.accessTokenStore.markerToken).toBe(activeMarker); + if (activeMarker === null) { throw new Error('Expected active synchronization marker'); } + const stateChanged = jest.fn(); + await account['handleSynchronizationNotification']({ + notification: {type: ConsumableEvent.SYNCHRONIZATION, data: {marker_id: activeMarker, delivery_tag: 1}}, + onConnectionStateChanged: stateChanged, + }); + expect(stateChanged).toHaveBeenCalledWith(ConnectionState.LIVE); + webSocket.disconnect(); + }); + it('preserves external listeners across repeated capability failures and a successful connection', async () => { + const {account, apiClient} = dependencies; + const webSocket = apiClient.transport.ws; + const capabilityUpdate = jest.spyOn(account.service!.client, 'putClientCapabilities'); + const connect = jest.spyOn(apiClient, 'connect').mockReturnValue(webSocket); + const externalMessage = jest.fn(); + const externalRetry = jest.fn(); + webSocket.on(WebSocketClient.TOPIC.ON_MESSAGE, externalMessage); + webSocket.on(WebSocketClient.TOPIC.ON_LONG_RUNNING_RETRY, externalRetry); + const stateListenerCount = webSocket.listenerCount(WebSocketClient.TOPIC.ON_STATE_CHANGE); + const logoutListenerCount = apiClient.listenerCount(APIClient.TOPIC.ON_LOGOUT); + capabilityUpdate.mockRejectedValue(new Error('Capability update failed')); + for (let attempt = 0; attempt < 3; attempt += 1) { + await expect(account.listen({useLegacy: true})).rejects.toThrow('Capability update failed'); + expect(webSocket.listenerCount(WebSocketClient.TOPIC.ON_MESSAGE)).toBe(1); + expect(webSocket.listenerCount(WebSocketClient.TOPIC.ON_STATE_CHANGE)).toBe(stateListenerCount); + expect(apiClient.listenerCount(APIClient.TOPIC.ON_LOGOUT)).toBe(logoutListenerCount); + } + expect(connect).not.toHaveBeenCalled(); + capabilityUpdate.mockResolvedValue(undefined); + const disconnect = await account.listen({useLegacy: true}); + expect(webSocket.listenerCount(WebSocketClient.TOPIC.ON_MESSAGE)).toBe(2); + disconnect(); + webSocket.emit(WebSocketClient.TOPIC.ON_MESSAGE, {id: 'external', payload: []}); + webSocket.emit(WebSocketClient.TOPIC.ON_LONG_RUNNING_RETRY, {retryCount: 1, retryDurationInMilliseconds: 60_000}); + expect(externalMessage).toHaveBeenCalledTimes(1); + expect(externalRetry).toHaveBeenCalledTimes(1); + expect(webSocket.listenerCount(WebSocketClient.TOPIC.ON_STATE_CHANGE)).toBe(stateListenerCount); + expect(apiClient.listenerCount(APIClient.TOPIC.ON_LOGOUT)).toBe(logoutListenerCount); + }); + + it('reports an expired session and removes only its owned logout subscription', async () => { + const {account, apiClient} = dependencies; + jest.spyOn(account.service!.client, 'putClientCapabilities').mockResolvedValue(undefined); + jest.spyOn(apiClient, 'connect').mockReturnValue(apiClient.transport.ws); + const externalLogout = jest.fn(); + const sessionExpired = jest.fn(); + apiClient.on(APIClient.TOPIC.ON_LOGOUT, externalLogout); + const originalListenerCount = apiClient.listenerCount(APIClient.TOPIC.ON_LOGOUT); + const disconnect = await account.listen({useLegacy: true, onSessionExpired: sessionExpired}); + apiClient.emit(APIClient.TOPIC.ON_LOGOUT); + disconnect(); + expect(sessionExpired).toHaveBeenCalledTimes(1); + expect(externalLogout).toHaveBeenCalledTimes(1); + expect(apiClient.listenerCount(APIClient.TOPIC.ON_LOGOUT)).toBe(originalListenerCount); + expect(apiClient.transport.ws.listenerCount(WebSocketClient.TOPIC.ON_MESSAGE)).toBe(0); + apiClient.removeListener(APIClient.TOPIC.ON_LOGOUT, externalLogout); + }); + + it('does not connect after capability setup is cancelled', async () => { + const {account, apiClient} = dependencies; + let finishUpdate: () => void = () => {}; + jest.spyOn(account.service!.client, 'putClientCapabilities').mockReturnValue(new Promise(resolve => { finishUpdate = resolve; })); + const connect = jest.spyOn(apiClient, 'connect'); + const stateChanged = jest.fn(); + const lifetime = new AbortController(); + const listening = account.listen({useLegacy: true, signal: lifetime.signal, onConnectionStateChanged: stateChanged}); + lifetime.abort(); + finishUpdate(); + await expect(listening).rejects.toThrow(); + expect(connect).not.toHaveBeenCalled(); + expect(stateChanged).not.toHaveBeenCalled(); + expect(apiClient.transport.ws.listenerCount(WebSocketClient.TOPIC.ON_MESSAGE)).toBe(0); + }); + + it('cleans up if final legacy migration or transport setup fails', async () => { + const {account, apiClient} = dependencies; + jest.spyOn(account.service!.client, 'putClientCapabilities').mockResolvedValue(undefined); + jest.spyOn(account.service!.notification, 'legacyProcessNotificationStream').mockRejectedValue(new Error('Migration failed')); + await expect(account.listen({useLegacy: false})).rejects.toThrow('Migration failed'); + expect(apiClient.transport.ws.listenerCount(WebSocketClient.TOPIC.ON_MESSAGE)).toBe(0); + jest.spyOn(apiClient, 'connect').mockImplementation(() => { throw new Error('Transport setup failed'); }); + await expect(account.listen({useLegacy: true})).rejects.toThrow('Transport setup failed'); + expect(apiClient.transport.ws.listenerCount(WebSocketClient.TOPIC.ON_MESSAGE)).toBe(0); + }); + + it('does not report LIVE for the pre-socket legacy migration', async () => { + const {account, apiClient} = dependencies; + jest.spyOn(account.service!.client, 'putClientCapabilities').mockResolvedValue(undefined); + jest.spyOn(account.service!.notification, 'legacyProcessNotificationStream').mockResolvedValue({total: 0, success: 0, error: 0}); + jest.spyOn(apiClient, 'connect').mockReturnValue(apiClient.transport.ws); + const stateChanged = jest.fn(); + const disconnect = await account.listen({useLegacy: false, onConnectionStateChanged: stateChanged}); + expect(stateChanged).not.toHaveBeenCalledWith(ConnectionState.LIVE); + disconnect(); + }); + + it('ignores aborted legacy catch-up even when fetching succeeds', async () => { + const {account, apiClient} = dependencies; + const lifetime = new AbortController(); + jest.spyOn(account.service!.notification, 'legacyProcessNotificationStream').mockImplementation(async () => { + lifetime.abort(); + return {total: 0, success: 0, error: 0}; + }); + const stateChanged = jest.fn(); + const unlock = jest.spyOn(apiClient.transport.ws, 'unlock'); + const processStream = account['createLegacyNotificationStreamProcessor']({ + handleLegacyNotification: async () => {}, + handleMissedNotifications: async () => {}, + onConnectionStateChanged: stateChanged, + }); + await expect(processStream(lifetime)).rejects.toThrow(); + expect(stateChanged).not.toHaveBeenCalledWith(ConnectionState.LIVE); + expect(unlock).not.toHaveBeenCalled(); + }); + it('acknowledges an async notification with an empty payload', async () => { + const notification: ConsumableNotificationEvent = { + type: ConsumableEvent.EVENT, + data: {delivery_tag: 7, event: {id: 'empty-notification', payload: []}}, + }; + const acknowledge = jest.spyOn(dependencies.apiClient.transport.ws, 'acknowledgeNotification'); + const onNotificationStreamProgress = jest.fn(); + const handleEvent = jest.fn(); + // Exercise the real timestamp reader rather than this suite's general timestamp stub. + jest.spyOn(dependencies.account, 'getNotificationEventTime').mockRestore(); + + await dependencies.account['decryptAckEmitNotification']({ + notification, + handleEvent, + source: NotificationSource.WEBSOCKET, + onNotificationStreamProgress, + }); + + expect(acknowledge).toHaveBeenCalledWith(notification); + expect(handleEvent).not.toHaveBeenCalled(); + expect(onNotificationStreamProgress).not.toHaveBeenCalled(); + }); + + it('passes an empty legacy notification to processing without reading an absent timestamp', async () => { + const notificationService = dependencies.account.service?.notification; + if (notificationService === undefined) { + throw new Error('Expected initialized notification service'); + } + const processNotification = jest.spyOn(notificationService, 'handleNotification'); + const onNotificationStreamProgress = jest.fn(); + const notification = {id: 'empty-notification', payload: []}; + jest.spyOn(dependencies.account, 'getNotificationEventTime').mockRestore(); + dependencies.account.resumeNotificationQueue(); + const handleNotification = dependencies.account['createLegacyNotificationHandler']({ + handleEvent: jest.fn(), + onNotificationStreamProgress, + getCurrentWebSocketConnectionContext: () => {return undefined;}, + }); + + await handleNotification(notification, NotificationSource.NOTIFICATION_STREAM); + await waitFor(() => { + expect(processNotification).toHaveBeenCalledWith(notification, NotificationSource.NOTIFICATION_STREAM); + }); + + expect(onNotificationStreamProgress).not.toHaveBeenCalled(); + }); + + it('removes only account listeners so retry reporting survives application reconnects', async () => { + const webSocket = dependencies.apiClient.transport.ws; + const clientService = dependencies.account.service?.client; + if (clientService === undefined) { + throw new Error('Expected initialized client service'); + } + jest.spyOn(clientService, 'putClientCapabilities').mockResolvedValue(undefined); + jest.spyOn(dependencies.apiClient, 'connect').mockReturnValue(webSocket); + const retryListener = jest.fn(); + const externalStateListener = jest.fn(); + webSocket.on(WebSocketClient.TOPIC.ON_LONG_RUNNING_RETRY, retryListener); + webSocket.on(WebSocketClient.TOPIC.ON_STATE_CHANGE, externalStateListener); + const existingStateListeners = webSocket.listenerCount(WebSocketClient.TOPIC.ON_STATE_CHANGE); + + const disconnect = await dependencies.account.listen({useLegacy: true}); + expect(webSocket.listenerCount(WebSocketClient.TOPIC.ON_STATE_CHANGE)).toBe(existingStateListeners + 1); + disconnect(); + disconnect(); + expect(webSocket.listenerCount(WebSocketClient.TOPIC.ON_STATE_CHANGE)).toBe(existingStateListeners); + expect(webSocket.listenerCount(WebSocketClient.TOPIC.ON_MESSAGE)).toBe(0); + + const disconnectAgain = await dependencies.account.listen({useLegacy: true}); + webSocket.emit(WebSocketClient.TOPIC.ON_LONG_RUNNING_RETRY, {retryCount: 9, retryDurationInMilliseconds: 65_000}); + disconnectAgain(); + + expect(retryListener).toHaveBeenCalledTimes(1); + expect(webSocket.listenerCount(WebSocketClient.TOPIC.ON_LONG_RUNNING_RETRY)).toBe(1); + expect(webSocket.listenerCount(WebSocketClient.TOPIC.ON_STATE_CHANGE)).toBe(existingStateListeners); + }); + + it.each([true, false])('keeps synchronization marker contents private when matched=%s', async markerMatches => { + const marker = 'private-synchronization-marker'; + dependencies.apiClient.transport.http.accessTokenStore.markerToken = markerMatches ? marker : 'other-marker'; + const information = jest.spyOn(dependencies.account['logger'], 'info'); + const acknowledge = jest.spyOn(dependencies.apiClient.transport.ws, 'acknowledgeConsumableNotificationSynchronization'); + const stateChanged = jest.fn(); + const notification = { + type: ConsumableEvent.SYNCHRONIZATION, + data: {marker_id: marker, delivery_tag: 7}, + } as const; + + await dependencies.account['handleSynchronizationNotification']({ + notification, + onConnectionStateChanged: stateChanged, + connectionContext: {attemptId: 12, wrapperGeneration: 4}, + }); + + expect(acknowledge).toHaveBeenCalledWith(notification); + expect(stateChanged).toHaveBeenCalledTimes(markerMatches ? 1 : 0); + expect(information).toHaveBeenCalledWith(expect.stringContaining(`markerMatched=${markerMatches} attemptId=12 wrapperGeneration=4`)); + expect(JSON.stringify(information.mock.calls)).not.toMatch(/private-synchronization-marker|other-marker|delivery_tag/); + }); + it('connects to websocket after the notification stream has been processed', async () => { jest .spyOn(dependencies.account, 'getClientCapabilities') @@ -403,7 +836,7 @@ describe('Account', () => { // Expect all states to have been called in order expect(onConnectionStateChanged).toHaveBeenNthCalledWith(1, ConnectionState.PROCESSING_NOTIFICATIONS); expect(onConnectionStateChanged).toHaveBeenNthCalledWith(2, ConnectionState.CONNECTING); - expect(onConnectionStateChanged).toHaveBeenNthCalledWith(3, ConnectionState.LIVE); + expect(onConnectionStateChanged).toHaveBeenNthCalledWith(3, ConnectionState.LIVE, expect.objectContaining({attemptId: 1, wrapperGeneration: 1})); resolve(); break; } @@ -414,7 +847,7 @@ describe('Account', () => { onConnectionStateChanged, }); - await waitFor(() => expect(onConnectionStateChanged).toHaveBeenCalledWith(ConnectionState.LIVE)); + await waitFor(() => expect(onConnectionStateChanged).toHaveBeenCalledWith(ConnectionState.LIVE, expect.objectContaining({attemptId: 1, wrapperGeneration: 1}))); disconnect(); }); @@ -471,7 +904,37 @@ describe('Account', () => { }); }); + it('reports CLOSED without unlocking when legacy catch-up fails after WebSocket open', async () => { + const notificationService = dependencies.account.service?.notification; + if (notificationService === undefined) { + throw new Error('Account notification service must be initialized'); + } + + jest + .spyOn(notificationService, 'legacyProcessNotificationStream') + .mockRejectedValue(new Error('private-notification access_token=secret-token Cookie: secret-cookie')); + const lifecycleWarning = jest.spyOn(dependencies.account['logger'], 'warn'); + const unlock = jest.spyOn(dependencies.apiClient.transport.ws, 'unlock'); + const onConnectionStateChanged = jest.fn(); + const disconnect = await dependencies.account.listen({useLegacy: true, onConnectionStateChanged}); + + try { + await waitFor(() => { + expect(onConnectionStateChanged).toHaveBeenCalledWith(ConnectionState.CLOSED, expect.objectContaining({attemptId: 1, wrapperGeneration: 1})); + }); + expect(onConnectionStateChanged).toHaveBeenCalledWith(ConnectionState.PROCESSING_NOTIFICATIONS, expect.objectContaining({attemptId: 1, wrapperGeneration: 1})); + expect(onConnectionStateChanged.mock.calls.some(call => {return call[0] === ConnectionState.LIVE;})).toBe(false); + expect(lifecycleWarning).toHaveBeenCalledWith(expect.stringContaining('event=legacy-catchup-failure')); + expect(lifecycleWarning).toHaveBeenCalledWith(expect.stringContaining('attemptId=1 wrapperGeneration=1')); + expect(JSON.stringify(lifecycleWarning.mock.calls)).not.toMatch(/private-notification|secret-token|secret-cookie/); + expect(unlock).not.toHaveBeenCalled(); + } finally { + disconnect(); + } + }); + it('does stop processing messages if websocket connection is aborted', async () => { + synchronizeOnConnect = false; jest .spyOn(dependencies.account, 'getClientCapabilities') .mockReturnValue([ClientCapability.LEGAL_HOLD_IMPLICIT_CONSENT, ClientCapability.CONSUMABLE_NOTIFICATIONS]); diff --git a/libraries/core/src/Account.ts b/libraries/core/src/Account.ts index bc2c1342032..c829ebbfd57 100644 --- a/libraries/core/src/Account.ts +++ b/libraries/core/src/Account.ts @@ -39,7 +39,7 @@ import { ConsumableNotificationSynchronization, } from '@wireapp/api-client/lib/notification/ConsumableNotification'; import {WebSocketClient} from '@wireapp/api-client/lib/tcp/'; -import {WEBSOCKET_STATE} from '@wireapp/api-client/lib/tcp/ReconnectingWebsocket'; +import {type WebSocketReconnectContext, WEBSOCKET_STATE} from '@wireapp/api-client/lib/tcp/ReconnectingWebsocket'; import {FEATURE_KEY, FEATURE_STATUS} from '@wireapp/api-client/lib/team'; import {QualifiedId} from '@wireapp/api-client/lib/user'; import {TimeInMillis} from '@wireapp/commons/lib/util/TimeUtil'; @@ -95,6 +95,17 @@ import {LocalStorageStore} from './util/LocalStorageStore'; import {RecurringTaskScheduler} from './util/RecurringTaskScheduler'; export type ProcessedEventPayload = HandledEventPayload; +export type WebSocketConnectionContext = Pick; + +function getWebSocketLifecycleContext(connectionContext: WebSocketConnectionContext | undefined): string { + return connectionContext === undefined + ? '' + : ` attemptId=${connectionContext.attemptId} wrapperGeneration=${connectionContext.wrapperGeneration}`; +} + +function isNotificationProcessingAborted(signal: AbortSignal | undefined): boolean { + return signal?.aborted === true; +} export enum ConnectionState { /** The WebSocket is closed and no notifications are being processed */ @@ -110,6 +121,27 @@ export enum ConnectionState { LIVE = 'live', } +type NotificationHandlingOptions = { + readonly handleEvent: (payload: HandledEventPayload, source: NotificationSource) => Promise; + readonly onNotificationStreamProgress: (currentProcessingNotificationTimestamp: string) => void; + readonly getCurrentWebSocketConnectionContext: () => WebSocketConnectionContext | undefined; + readonly getNotificationProcessingSignal?: () => AbortSignal; +}; +type ConsumableNotificationHandlingOptions = NotificationHandlingOptions & { + readonly onConnectionStateChanged: (state: ConnectionState) => void; +}; +type SynchronizationNotificationOptions = { + readonly notification: ConsumableNotificationSynchronization; + readonly onConnectionStateChanged: (state: ConnectionState) => void; + readonly connectionContext?: WebSocketConnectionContext; +}; +type DecryptNotificationOptions = Pick & { + readonly notification: ConsumableNotificationEvent; + readonly source: NotificationSource; + readonly connectionContext?: WebSocketConnectionContext; + readonly signal?: AbortSignal; +}; + export type CreateStoreFn = (storeName: string, key: Uint8Array) => undefined | Promise; interface AccountOptions { @@ -664,6 +696,8 @@ export class Account extends TypedEventEmitter { onConnectionStateChanged: onConnectionStateChangedCallBack = () => {}, onNotificationStreamProgress = () => {}, onMissedNotifications = () => {}, + onSessionExpired = () => {}, + signal, }: { /** * Called when a new event arrives from backend @@ -680,7 +714,7 @@ export class Account extends TypedEventEmitter { /** * called when the connection state with the backend has changed */ - onConnectionStateChanged?: (state: ConnectionState) => void; + onConnectionStateChanged?: (state: ConnectionState, connectionContext?: WebSocketConnectionContext) => void; /** * called when we detect lost notification from backend. @@ -695,6 +729,10 @@ export class Account extends TypedEventEmitter { * When set to true, will use the legacy notification stream instead of the new async notifications. */ useLegacy?: boolean; + /** Cancels setup and the listener owned by this call. */ + signal?: AbortSignal; + /** Called when authentication invalidates the session, rather than for a transient socket closure. */ + onSessionExpired?: () => void; /** * When set will not decrypt and not store the last notification ID. This is useful if you only want to subscribe to unencrypted backend events @@ -710,111 +748,212 @@ export class Account extends TypedEventEmitter { throw new Error('use of legacy notifications must be explicitly set to true or false'); } - const onConnectionStateChanged = this.createConnectionStateChangedHandler(onConnectionStateChangedCallBack); + signal?.throwIfAborted(); + const lifetime = new AbortController(); + let removeWebSocketListeners = (): void => {}; + let connected = false; + let notificationQueueStarted = false; + let cleanedUp = false; + const account = this; + function disconnect(): void { + if (cleanedUp === true) { + return; + } + cleanedUp = true; + lifetime.abort(); + signal?.removeEventListener('abort', disconnect); + account.apiClient.removeListener(APIClient.TOPIC.ON_LOGOUT, handleSessionExpired); + removeWebSocketListeners(); + if (connected === true || notificationQueueStarted === true) { + flushProposalsQueue(); + account.pauseAndFlushNotificationQueue(); + } + if (connected === true) { + account.apiClient.disconnect(); + updateConnectionState(ConnectionState.CLOSED); + } + } + signal?.addEventListener('abort', disconnect, {once: true}); + + let currentWebSocketConnectionContext: WebSocketConnectionContext | undefined; + let notificationProcessingSignal = lifetime.signal; + function getNotificationProcessingSignal(): AbortSignal { + return notificationProcessingSignal; + } + function getCurrentWebSocketConnectionContext(): WebSocketConnectionContext | undefined { + return currentWebSocketConnectionContext; + } + const updateConnectionState = this.createConnectionStateChangedHandler( + onConnectionStateChangedCallBack, + getCurrentWebSocketConnectionContext, + ); + function onConnectionStateChanged(state: ConnectionState): void { + if (lifetime.signal.aborted === false) { + updateConnectionState(state); + } + } + function handleSessionExpired(): void { + if (cleanedUp === false) { + onSessionExpired(); + disconnect(); + } + } + this.apiClient.on(APIClient.TOPIC.ON_LOGOUT, handleSessionExpired); const handleEvent = this.createEventHandler(onEvent); - const handleLegacyNotification = this.createLegacyNotificationHandler(handleEvent, onNotificationStreamProgress); - const handleNotification = this.createNotificationHandler( + const handleLegacyNotification = this.createLegacyNotificationHandler({ + handleEvent, + onNotificationStreamProgress, + getCurrentWebSocketConnectionContext, + getNotificationProcessingSignal, + }); + const handleNotification = this.createNotificationHandler({ handleEvent, onNotificationStreamProgress, onConnectionStateChanged, - ); + getCurrentWebSocketConnectionContext, + getNotificationProcessingSignal, + }); const handleMissedNotifications = this.createLegacyMissedNotificationsHandler(onMissedNotifications); const legacyProcessNotificationStream = this.createLegacyNotificationStreamProcessor({ handleLegacyNotification, handleMissedNotifications, onConnectionStateChanged, + getCurrentWebSocketConnectionContext, }); - this.setupWebSocketListeners(onConnectionStateChanged, handleNotification, handleLegacyNotification, useLegacy); - - const isClientCapableOfConsumableNotifications = this.getClientCapabilities().includes( - ClientCapability.CONSUMABLE_NOTIFICATIONS, - ); - - const capabilities = [ClientCapability.LEGAL_HOLD_IMPLICIT_CONSENT]; + try { + const isClientCapableOfConsumableNotifications = this.getClientCapabilities().includes( + ClientCapability.CONSUMABLE_NOTIFICATIONS, + ); - if (!useLegacy) { - // let the backend now client is capable of consumable notifications - capabilities.push(ClientCapability.CONSUMABLE_NOTIFICATIONS); - this.apiClient.transport.ws.useAsyncNotificationsSocket(); - } + const capabilities = [ClientCapability.LEGAL_HOLD_IMPLICIT_CONSENT]; - this.logger.info(`Client is using the ${useLegacy ? 'legacy' : 'async'} notification stream`); - - await this.service?.client.putClientCapabilities(this.currentClient.id, {capabilities}); - - /* - * When enabling async notifications, be aware that the backend maintains a separate queue - * for new async notifications (/events weboscket endpoint), which only starts populating *after* the client declares support - * for async notifications. - * - * Therefore, after declaring support, it's necessary to perform one final fetch from the legacy - * system to ensure no notifications are missed—since older notifications won't - * appear in the new queue. - * - * These two systems are separate, and the transition timing - * is important to avoid missing any messages during the switch. - * - * @todo This can be removed when all clients are capable of consumable notifications. - */ - if (!isClientCapableOfConsumableNotifications && !useLegacy) { - // do the last legacy sync without connecting to any websockets - await legacyProcessNotificationStream(); - this.logger.info('Completed final legacy notification stream processing after enabling async notifications'); - } + if (!useLegacy) { + // let the backend now client is capable of consumable notifications + capabilities.push(ClientCapability.CONSUMABLE_NOTIFICATIONS); + this.apiClient.transport.ws.useAsyncNotificationsSocket(); + } - if (useLegacy) { - /** - * immediately lock the websocket to prevent any new messages from being received - * before legacy notifications endpoint is fetched otherwise it'll update the last notification ID - * and fetching legacy notifications will return an empty list - */ - this.apiClient.transport.ws.lock(); - } - this.apiClient.connect(async abortController => { - // this call back is called every single time the websocket connection is (re)established - this.logger.info('Connection established with websocket, starting notification stream processing'); - /** - * This is to avoid passing proposals too early to core crypto - * @See WPB-18995 + this.logger.info(`Client is using the ${useLegacy ? 'legacy' : 'async'} notification stream`); + + await this.service?.client.putClientCapabilities(this.currentClient.id, {capabilities}); + lifetime.signal.throwIfAborted(); + + /* + * When enabling async notifications, be aware that the backend maintains a separate queue + * for new async notifications (/events weboscket endpoint), which only starts populating *after* the client declares support + * for async notifications. + * + * Therefore, after declaring support, it's necessary to perform one final fetch from the legacy + * system to ensure no notifications are missed—since older notifications won't + * appear in the new queue. + * + * These two systems are separate, and the transition timing + * is important to avoid missing any messages during the switch. + * + * @todo This can be removed when all clients are capable of consumable notifications. */ - pauseProposalProcessing(); - pauseMessageSending(); // pause message sending while processing notifications, it will be resumed once the processing is done and we have the marker token - pauseRejoiningMLSConversations(); // We want to avoid triggering rejoins of out-of-sync MLS conversations while we are processing the notification stream - /** - * resume the notification processing queue - * it will start processing notifications immediately and pause if web socket connection drops - * we should start decryption and therefore acknowledging the notifications in order for the backend to - * send us the next batch of notifications, currently total size of notifications coming from web socket is limited to 500 - * so we need to acknowledge the notifications to let the backend know we are ready for the next batch - */ - this.notificationProcessingQueue.resume(); + if (!isClientCapableOfConsumableNotifications && !useLegacy) { + // do the last legacy sync without connecting to any websockets + notificationQueueStarted = true; + this.notificationProcessingQueue.resume(); + await legacyProcessNotificationStream(lifetime, false); + lifetime.signal.throwIfAborted(); + this.logger.info('Completed final legacy notification stream processing after enabling async notifications'); + } + removeWebSocketListeners = this.setupWebSocketListeners( + onConnectionStateChanged, + handleNotification, + handleLegacyNotification, + useLegacy, + ); if (useLegacy) { - await legacyProcessNotificationStream(abortController); + /** + * immediately lock the websocket to prevent any new messages from being received + * before legacy notifications endpoint is fetched otherwise it'll update the last notification ID + * and fetching legacy notifications will return an empty list + */ + this.apiClient.transport.ws.lock(); } - }); + connected = true; + this.apiClient.connect(async (abortController, reconnectContext) => { + if (lifetime.signal.aborted === true || Boolean(abortController.signal.aborted) === true) { + return; + } + currentWebSocketConnectionContext = reconnectContext; + notificationProcessingSignal = abortController.signal; + // this call back is called every single time the websocket connection is (re)established + this.logger.info( + `[WebSocketLifecycle] layer=account event=websocket-open-processing-start useLegacy=${useLegacy} aborted=${abortController.signal.aborted}${getWebSocketLifecycleContext(reconnectContext)}`, + ); + /** + * This is to avoid passing proposals too early to core crypto + * @See WPB-18995 + */ + pauseProposalProcessing(); + pauseMessageSending(); // pause message sending while processing notifications, it will be resumed once the processing is done and we have the marker token + pauseRejoiningMLSConversations(); // We want to avoid triggering rejoins of out-of-sync MLS conversations while we are processing the notification stream + /** + * resume the notification processing queue + * it will start processing notifications immediately and pause if web socket connection drops + * we should start decryption and therefore acknowledging the notifications in order for the backend to + * send us the next batch of notifications, currently total size of notifications coming from web socket is limited to 500 + * so we need to acknowledge the notifications to let the backend know we are ready for the next batch + */ + this.notificationProcessingQueue.resume(); - return () => { - this.logger.info('Disconnecting from backend as requested by consumer'); - flushProposalsQueue(); - this.pauseAndFlushNotificationQueue(); - this.apiClient.disconnect(); - onConnectionStateChanged(ConnectionState.CLOSED); - this.apiClient.transport.ws.removeAllListeners(); - }; + if (useLegacy) { + this.logger.info( + `[WebSocketLifecycle] layer=account event=legacy-catchup-start aborted=${abortController.signal.aborted}${getWebSocketLifecycleContext(reconnectContext)}`, + ); + try { + await legacyProcessNotificationStream(abortController); + this.logger.info( + `[WebSocketLifecycle] layer=account event=legacy-catchup-success aborted=${abortController.signal.aborted} live=${this.connectionState === ConnectionState.LIVE}${getWebSocketLifecycleContext(reconnectContext)}`, + ); + } catch { + this.logger.warn( + `[WebSocketLifecycle] layer=account event=legacy-catchup-failure aborted=${abortController.signal.aborted} live=${this.connectionState === ConnectionState.LIVE}${getWebSocketLifecycleContext(reconnectContext)}`, + ); + + if (abortController.signal.aborted === true) { + return; + } + + this.pauseAndFlushNotificationQueue(); + onConnectionStateChanged(ConnectionState.CLOSED); + } + } + }); + + return disconnect; + } catch (error: unknown) { + disconnect(); + throw error; + } }; private readonly createConnectionStateChangedHandler = ( - onConnectionStateChanged: (state: ConnectionState) => void, + onConnectionStateChanged: (state: ConnectionState, connectionContext?: WebSocketConnectionContext) => void, + getCurrentWebSocketConnectionContext: () => WebSocketConnectionContext | undefined, ): ((state: ConnectionState) => void) => { + let previousConnectionState = this.connectionState; return (state: ConnectionState): void => { + const connectionContext = getCurrentWebSocketConnectionContext(); this.connectionState = state; - onConnectionStateChanged(state); - this.logger.info(`Connection state changed to: ${state}`); + if (connectionContext === undefined) { + onConnectionStateChanged(state); + } else { + onConnectionStateChanged(state, connectionContext); + } + this.logger.info( + `[WebSocketLifecycle] layer=account event=connection-state-change previousState=${previousConnectionState.toUpperCase()} nextState=${state.toUpperCase()}${getWebSocketLifecycleContext(connectionContext)}`, + ); + previousConnectionState = state; }; }; @@ -851,19 +990,30 @@ export class Account extends TypedEventEmitter { * It can be replaced with the new notification handling system using `ConsumableNotification` * when all clients are capable of handling consumable notifications. */ - private readonly createLegacyNotificationHandler = ( - handleEvent: (payload: HandledEventPayload, source: NotificationSource) => Promise, - onNotificationStreamProgress: (currentProcessingNotificationTimestamp: string) => void, - ) => { + private readonly createLegacyNotificationHandler = (options: NotificationHandlingOptions) => { + const { + handleEvent, + onNotificationStreamProgress, + getCurrentWebSocketConnectionContext, + getNotificationProcessingSignal, + } = options; return async (notification: Notification, source: NotificationSource): Promise => { + const signal = getNotificationProcessingSignal?.(); void this.notificationProcessingQueue .push(async () => { try { + if (isNotificationProcessingAborted(signal)) { + return; + } const start = Date.now(); - const notificationTime = this.getNotificationEventTime(notification.payload[0]); - this.logger.info(`Processing legacy notification "${notification.id}" at ${notificationTime}`, { - notification, - }); + const firstNotificationPayload = notification.payload[0]; + const notificationTime = + firstNotificationPayload === undefined + ? undefined + : this.getNotificationEventTime(firstNotificationPayload); + this.logger.info( + `[WebSocketLifecycle] layer=account event=legacy-notification-start${getWebSocketLifecycleContext(getCurrentWebSocketConnectionContext())}`, + ); this.logger.info(`Total notifications queue length: ${this.notificationProcessingQueue.getLength()}`); this.logger.info(`Total pending proposals queue length: ${getProposalQueueLength()}`); if (notificationTime) { @@ -873,14 +1023,25 @@ export class Account extends TypedEventEmitter { const messages = this.service!.notification.handleNotification(notification, source); for await (const message of messages) { + if (isNotificationProcessingAborted(signal)) { + return; + } await handleEvent(message, source); + if (isNotificationProcessingAborted(signal)) { + return; + } + } + + if (isNotificationProcessingAborted(signal)) { + return; } - this.logger.info(`Finished processing legacy notification "${notification.id}" in ${Date.now() - start}ms`); - } catch (error) { + this.logger.info( + `[WebSocketLifecycle] layer=account event=legacy-notification-success durationMs=${Date.now() - start}${getWebSocketLifecycleContext(getCurrentWebSocketConnectionContext())}`, + ); + } catch { this.logger.error( - `Failed to handle legacy notification "${notification.id}": ${(error as any).message}`, - error, + `[WebSocketLifecycle] layer=account event=legacy-notification-failure${getWebSocketLifecycleContext(getCurrentWebSocketConnectionContext())}`, ); } }) @@ -888,13 +1049,22 @@ export class Account extends TypedEventEmitter { }; }; - private readonly createNotificationHandler = ( - handleEvent: (payload: HandledEventPayload, source: NotificationSource) => Promise, - onNotificationStreamProgress: (currentProcessingNotificationTimestamp: string) => void, - onConnectionStateChanged: (state: ConnectionState) => void, - ) => { + private readonly createNotificationHandler = (options: ConsumableNotificationHandlingOptions) => { + const { + handleEvent, + onNotificationStreamProgress, + onConnectionStateChanged, + getCurrentWebSocketConnectionContext, + getNotificationProcessingSignal, + } = options; return async (notification: ConsumableNotification, source: NotificationSource): Promise => { - this.logger.info(`Received consumable notification of type "${notification.type}"`, {notification}); + const signal = getNotificationProcessingSignal?.(); + if (isNotificationProcessingAborted(signal)) { + return; + } + this.logger.info( + `[WebSocketLifecycle] layer=account event=consumable-notification-received${getWebSocketLifecycleContext(getCurrentWebSocketConnectionContext())}`, + ); try { if (notification.type === ConsumableEvent.MISSED) { this.reactToMissedNotification(); @@ -903,16 +1073,36 @@ export class Account extends TypedEventEmitter { if (notification.type === ConsumableEvent.SYNCHRONIZATION) { this.notificationProcessingQueue - .push(() => this.handleSynchronizationNotification(notification, onConnectionStateChanged)) + .push(async () => { + if (isNotificationProcessingAborted(signal)) { + return; + } + await this.handleSynchronizationNotification({ + notification, + onConnectionStateChanged, + connectionContext: getCurrentWebSocketConnectionContext(), + }); + }) .catch(this.handleNotificationQueueError); return; } this.notificationProcessingQueue - .push(() => this.decryptAckEmitNotification(notification, handleEvent, source, onNotificationStreamProgress)) + .push(() => { + return this.decryptAckEmitNotification({ + notification, + handleEvent, + source, + onNotificationStreamProgress, + connectionContext: getCurrentWebSocketConnectionContext(), + signal, + }); + }) .catch(this.handleNotificationQueueError); - } catch (error) { - this.logger.error(`Failed to handle notification "${notification.type}": ${(error as any).message}`, error); + } catch { + this.logger.error( + `[WebSocketLifecycle] layer=account event=consumable-notification-handling-failure${getWebSocketLifecycleContext(getCurrentWebSocketConnectionContext())}`, + ); } }; }; @@ -924,10 +1114,10 @@ export class Account extends TypedEventEmitter { switch (error.cause) { case PromiseQueue.ERROR_CAUSES.TIMEOUT: - this.logger.warn('Notification decryption task timed out', error); + this.logger.warn('Notification decryption task timed out'); break; case PromiseQueue.ERROR_CAUSES.FLUSHED: - this.logger.info('Notification processing queue was flushed, ignoring error', error); + this.logger.info('Notification processing queue was flushed, ignoring error'); break; } }; @@ -936,18 +1126,18 @@ export class Account extends TypedEventEmitter { this.apiClient.transport.ws.acknowledgeConsumableNotificationSynchronization(notification); }; - private readonly handleSynchronizationNotification = async ( - notification: ConsumableNotificationSynchronization, - onConnectionStateChanged: (state: ConnectionState) => void, - ) => { - this.logger.info('acknowledging synchronization notification', {notification}); + private readonly handleSynchronizationNotification = async (options: SynchronizationNotificationOptions) => { + const {notification, onConnectionStateChanged, connectionContext} = options; + this.logger.info( + `[WebSocketLifecycle] layer=account event=async-sync-marker-received markerPresent=${notification.data.marker_id.length > 0}${getWebSocketLifecycleContext(connectionContext)}`, + ); this.acknowledgeSynchronizationNotification(notification); const markerId = notification.data.marker_id; const currentMarkerId = this.apiClient.transport.http.accessTokenStore.markerToken; this.logger.info( - `Handling synchronization notification with marker ID: ${markerId} current marker ID: ${currentMarkerId}`, + `[WebSocketLifecycle] layer=account event=async-sync-marker-compared markerMatched=${markerId === currentMarkerId}${getWebSocketLifecycleContext(connectionContext)}`, ); /** * There is a chance that there might be multiple synchronization notifications (markers) @@ -956,36 +1146,59 @@ export class Account extends TypedEventEmitter { * if the marker ID matches the current marker ID. */ if (markerId === currentMarkerId) { + this.logger.info( + `[WebSocketLifecycle] layer=account event=live-transition-start${getWebSocketLifecycleContext(connectionContext)}`, + ); resumeProposalProcessing(); resumeMessageSending(); resumeRejoiningMLSConversations(); onConnectionStateChanged(ConnectionState.LIVE); + this.logger.info( + `[WebSocketLifecycle] layer=account event=live-transition-success${getWebSocketLifecycleContext(connectionContext)}`, + ); } }; - private readonly decryptAckEmitNotification = async ( - notification: ConsumableNotificationEvent, - handleEvent: (payload: HandledEventPayload, source: NotificationSource) => Promise, - source: NotificationSource, - onNotificationStreamProgress: (currentProcessingNotificationTimestamp: string) => void, - ): Promise => { + private readonly decryptAckEmitNotification = async (options: DecryptNotificationOptions): Promise => { + const {notification, handleEvent, source, onNotificationStreamProgress, connectionContext, signal} = options; try { - this.logger.info(`Sending consumable notification for decryption`, notification.data.event.id); + if (isNotificationProcessingAborted(signal)) { + return; + } + this.logger.info( + `[WebSocketLifecycle] layer=account event=consumable-notification-decryption-start${getWebSocketLifecycleContext(connectionContext)}`, + ); const payloads = this.service!.notification.handleNotification(notification.data.event, source); - const notificationTime = this.getNotificationEventTime(notification.data.event.payload[0]); + const firstNotificationPayload = notification.data.event.payload[0]; + const notificationTime = + firstNotificationPayload === undefined ? undefined : this.getNotificationEventTime(firstNotificationPayload); if (this.connectionState !== ConnectionState.LIVE && notificationTime) { onNotificationStreamProgress(notificationTime); } for await (const payload of payloads ?? []) { + if (isNotificationProcessingAborted(signal)) { + return; + } await handleEvent(payload, source); + if (isNotificationProcessingAborted(signal)) { + return; + } } - this.logger.info(`Acknowledging consumable notification on the backend "${notification.data.delivery_tag}"`); + if (isNotificationProcessingAborted(signal)) { + return; + } + + this.logger.info( + `[WebSocketLifecycle] layer=account event=consumable-notification-acknowledging${getWebSocketLifecycleContext(connectionContext)}`, + ); this.apiClient.transport.ws.acknowledgeNotification(notification); - } catch (err) { - this.logger.error(`Failed to process notification ${notification.data.delivery_tag}`, err); + } catch { + this.logger.error( + `[WebSocketLifecycle] layer=account event=consumable-notification-processing-failure${getWebSocketLifecycleContext(connectionContext)}`, + ); } }; @@ -1035,40 +1248,64 @@ export class Account extends TypedEventEmitter { handleLegacyNotification, handleMissedNotifications, onConnectionStateChanged, + getCurrentWebSocketConnectionContext = () => { + return undefined; + }, }: { handleLegacyNotification: (notification: Notification, source: NotificationSource) => Promise; handleMissedNotifications: (notificationId: string) => Promise; onConnectionStateChanged: (state: ConnectionState) => void; + getCurrentWebSocketConnectionContext?: () => WebSocketConnectionContext | undefined; }) => { - return async (abortController?: AbortController) => { + return async (abortController?: AbortController, completeSynchronization = true) => { + abortController?.signal.throwIfAborted(); this.apiClient.transport.ws.lock(); pauseProposalProcessing(); pauseMessageSending(); pauseRejoiningMLSConversations(); onConnectionStateChanged(ConnectionState.PROCESSING_NOTIFICATIONS); - const results = await this.service!.notification.legacyProcessNotificationStream( + await this.service!.notification.legacyProcessNotificationStream( async (notification, source) => { + if (abortController?.signal.aborted === true) { + return; + } await handleLegacyNotification(notification, source); }, - handleMissedNotifications, + async notificationId => { + if (abortController?.signal.aborted === true) { + return; + } + await handleMissedNotifications(notificationId); + }, abortController, ); + abortController?.signal.throwIfAborted(); - this.logger.info( - 'Finished inserting notifications for decryption from the legacy endpoint to the process queue', - results, - ); + this.logger.info('Finished inserting notifications for decryption from the legacy endpoint to the process queue'); // We need to wait for the notification stream to be fully handled before releasing the message sending queue. // This is due to the nature of how message are encrypted, any change in mls epoch needs to happen before we start encrypting any kind of messages - void this.notificationProcessingQueue + await this.notificationProcessingQueue .push(async () => { - this.logger.info(`Resuming message sending. ${getQueueLength()} messages to be sent`); + if (abortController?.signal.aborted === true) { + return; + } + if (completeSynchronization === false) { + this.apiClient.transport.ws.unlock(); + return; + } + const connectionContext = getCurrentWebSocketConnectionContext(); + this.logger.info( + `[WebSocketLifecycle] layer=account event=live-transition-start pendingMessageCount=${getQueueLength()}${getWebSocketLifecycleContext(connectionContext)}`, + ); resumeProposalProcessing(); resumeMessageSending(); resumeRejoiningMLSConversations(); onConnectionStateChanged(ConnectionState.LIVE); + this.logger.info( + `[WebSocketLifecycle] layer=account event=live-transition-success${getWebSocketLifecycleContext(connectionContext)}`, + ); this.apiClient.transport.ws.unlock(); }) .catch(this.handleNotificationQueueError); @@ -1109,20 +1346,21 @@ export class Account extends TypedEventEmitter { handleNotification: (notification: ConsumableNotification, source: NotificationSource) => Promise, handleLegacyNotification: (notification: Notification, source: NotificationSource) => Promise, useLegacy: boolean, - ) => { + ): (() => void) => { this.logger.info('Setting up WebSocket listeners'); - this.apiClient.transport.ws.removeAllListeners(WebSocketClient.TOPIC.ON_MESSAGE); + const account = this; + const webSocket = this.apiClient.transport.ws; - this.apiClient.transport.ws.on(WebSocketClient.TOPIC.ON_MESSAGE, notification => { - this.logger.info('Received new notification from backend', {notification}); + function onNotification(notification: Notification | ConsumableNotification): void { + account.logger.info('Received new notification from backend'); if (Account.checkIsConsumable(notification)) { void handleNotification(notification, NotificationSource.WEBSOCKET); return; } void handleLegacyNotification(notification, NotificationSource.WEBSOCKET); - }); + } - this.apiClient.transport.ws.on(WebSocketClient.TOPIC.ON_STATE_CHANGE, wsState => { + function onWebSocketStateChanged(wsState: WEBSOCKET_STATE): void { const mapping: Partial> = { [WEBSOCKET_STATE.CLOSED]: ConnectionState.CLOSED, [WEBSOCKET_STATE.CONNECTING]: ConnectionState.CONNECTING, @@ -1130,18 +1368,26 @@ export class Account extends TypedEventEmitter { const connectionState = mapping[wsState]; - if (connectionState === ConnectionState.CLOSED) { + if (connectionState === ConnectionState.CLOSED || connectionState === ConnectionState.CONNECTING) { flushProposalsQueue(); - this.pauseAndFlushNotificationQueue(); + account.pauseAndFlushNotificationQueue(); if (useLegacy) { - this.apiClient.transport.ws.lock(); + webSocket.lock(); } } if (connectionState) { onConnectionStateChanged(connectionState); } - }); + } + + webSocket.on(WebSocketClient.TOPIC.ON_MESSAGE, onNotification); + webSocket.on(WebSocketClient.TOPIC.ON_STATE_CHANGE, onWebSocketStateChanged); + + return function removeWebSocketListeners(): void { + webSocket.removeListener(WebSocketClient.TOPIC.ON_MESSAGE, onNotification); + webSocket.removeListener(WebSocketClient.TOPIC.ON_STATE_CHANGE, onWebSocketStateChanged); + }; }; /** diff --git a/libraries/core/src/client/ClientBackendRepository.ts b/libraries/core/src/client/ClientBackendRepository.ts index 6e2c0532dec..a185d9b4ee3 100644 --- a/libraries/core/src/client/ClientBackendRepository.ts +++ b/libraries/core/src/client/ClientBackendRepository.ts @@ -17,7 +17,12 @@ * */ -import {CreateClientPayload, RegisteredClient, UpdateClientPayload} from '@wireapp/api-client/lib/client/'; +import { + ClientCapabilityData, + CreateClientPayload, + RegisteredClient, + UpdateClientPayload, +} from '@wireapp/api-client/lib/client/'; import {APIClient} from '@wireapp/api-client'; @@ -36,6 +41,10 @@ export class ClientBackendRepository { return this.apiClient.api.client.putClient(clientId, updates); } + public putClientCapabilities(clientId: string, capabilities: ClientCapabilityData): Promise { + return this.apiClient.api.client.putClientCapabilities(clientId, capabilities); + } + public deleteClient(clientId: string, password?: string): Promise { return this.apiClient.api.client.deleteClient(clientId, password); } diff --git a/libraries/core/src/client/ClientService.ts b/libraries/core/src/client/ClientService.ts index b988f33ebd2..f4e54cf9c1b 100644 --- a/libraries/core/src/client/ClientService.ts +++ b/libraries/core/src/client/ClientService.ts @@ -144,7 +144,7 @@ export class ClientService { } public putClientCapabilities(clientId: string, capabilities: ClientCapabilityData): Promise { - return this.backend.putClient(clientId, capabilities); + return this.backend.putClientCapabilities(clientId, capabilities); } /** diff --git a/libraries/core/src/index.ts b/libraries/core/src/index.ts index 2a0bf863bba..e0c649b9a75 100644 --- a/libraries/core/src/index.ts +++ b/libraries/core/src/index.ts @@ -17,7 +17,7 @@ * */ -export {Account, ConnectionState, ProcessedEventPayload} from './Account'; +export {Account, ConnectionState, ProcessedEventPayload, WebSocketConnectionContext} from './Account'; export * as auth from './auth/'; export * from './conversation/'; export {CoreError} from './CoreError'; diff --git a/libraries/core/src/notification/NotificationService.ts b/libraries/core/src/notification/NotificationService.ts index 4438ce74531..524f848810d 100644 --- a/libraries/core/src/notification/NotificationService.ts +++ b/libraries/core/src/notification/NotificationService.ts @@ -161,7 +161,7 @@ export class NotificationService extends TypedEventEmitter { const results = {total: notifications.length, error: 0, success: 0}; const logMessage = notifications.length > 0 - ? `Start processing ${notifications.length} notifications since notification id ${lastNotificationId}` + ? `Start processing ${notifications.length} notifications` : `No notification to process from the stream`; this.logger.log(logMessage); for (const [index, notification] of notifications.entries()) { @@ -178,9 +178,8 @@ export class NotificationService extends TypedEventEmitter { total: notifications.length, }); results.success++; - } catch (error) { - const message = error instanceof Error ? error.message : error; - this.logger.error(`Error while processing notification ${notification.id}: ${message}`, error); + } catch { + this.logger.error('Error while processing a notification'); results.error++; } } @@ -212,7 +211,7 @@ export class NotificationService extends TypedEventEmitter { source: NotificationSource, ): AsyncGenerator { for (const event of notification.payload) { - this.logger.debug(`Handling event of type "${event.type}"`, event); + this.logger.debug('Handling a notification event'); let lastEventDate: Date | undefined = undefined; try { lastEventDate = await this.database.getLastEventDate(); @@ -220,7 +219,7 @@ export class NotificationService extends TypedEventEmitter { // Ignore errors when fetching last event date } if ('time' in event && this.isOutdatedEvent(event, source, lastEventDate)) { - this.logger.info(`Ignored outdated event type: '${event.type}'`); + this.logger.info('Ignored an outdated notification event'); continue; } try { @@ -229,10 +228,7 @@ export class NotificationService extends TypedEventEmitter { yield handledEventResult.payload; } } catch (error) { - this.logger.error( - `There was an error with notification ID "${notification.id}": ${(error as Error).message}`, - error, - ); + this.logger.error('Failed to handle a notification event'); const notificationError: NotificationError = { error: error as Error, notification, diff --git a/yarn.lock b/yarn.lock index acb59a96157..b6514185f08 100644 --- a/yarn.lock +++ b/yarn.lock @@ -10547,9 +10547,9 @@ __metadata: concurrently: "npm:9.2.1" jest: "npm:^29.7.0" pako: "npm:2.1.0" + partysocket: "npm:1.3.0" react: "npm:18.3.1" react-dom: "npm:18.3.1" - reconnecting-websocket: "npm:4.4.0" spark-md5: "npm:3.0.2" tough-cookie: "npm:4.1.4" ts-node: "npm:^10.9.2" @@ -15669,6 +15669,13 @@ __metadata: languageName: node linkType: hard +"event-target-polyfill@npm:^0.0.4": + version: 0.0.4 + resolution: "event-target-polyfill@npm:0.0.4" + checksum: 10/465f7abfc7d4716365cae732f6940732b0c48315358b228df80d13c85d1b55f2ff8c02c6c98bd1d474fe9e21119d40ff4d907dffe8387ae89ee8a09608365bf9 + languageName: node + linkType: hard + "event-target-shim@npm:^5.0.0": version: 5.0.1 resolution: "event-target-shim@npm:5.0.1" @@ -22180,6 +22187,20 @@ __metadata: languageName: node linkType: hard +"partysocket@npm:1.3.0": + version: 1.3.0 + resolution: "partysocket@npm:1.3.0" + dependencies: + event-target-polyfill: "npm:^0.0.4" + peerDependencies: + react: ">=17" + peerDependenciesMeta: + react: + optional: true + checksum: 10/9e5566a87377b4337b2554d55c2a6586b5810bbf3db53de2196fc3f8132fe86253e2d3d16f90237f377f9ec24bde59b511798e80e3a5bfde12c2604d006684fe + languageName: node + linkType: hard + "pascal-case@npm:^3.1.2": version: 3.1.2 resolution: "pascal-case@npm:3.1.2" @@ -24711,13 +24732,6 @@ __metadata: languageName: node linkType: hard -"reconnecting-websocket@npm:4.4.0": - version: 4.4.0 - resolution: "reconnecting-websocket@npm:4.4.0" - checksum: 10/542b09b4604c4050833017e9602867d2dd76631de1790d46238e5a5857a41183e09faf38d373406e4ed7fef8614b43bf43c89aac677104997ccbbf6fa071338c - languageName: node - linkType: hard - "redent@npm:^3.0.0": version: 3.0.0 resolution: "redent@npm:3.0.0"