diff --git a/extensions/src/platform-scripture-editor/src/types/paratext-bible-send-receive.d.ts b/extensions/src/platform-scripture-editor/src/types/paratext-bible-send-receive.d.ts index 7b88ba5e24d..194282fc346 100644 --- a/extensions/src/platform-scripture-editor/src/types/paratext-bible-send-receive.d.ts +++ b/extensions/src/platform-scripture-editor/src/types/paratext-bible-send-receive.d.ts @@ -259,6 +259,25 @@ declare module 'papi-shared-types' { * this command (e.g., Paratext 10 Studio) */ 'paratextBibleSendReceive.syncProjects': (projectIds?: string[]) => Promise; + /** + * Runs the Send/Receive sync scheduled for a session boundary ("On startup/shutdown") for the + * projects the user scheduled for that boundary. The extension owns the schedule, running the + * sync, and — on startup only — raising/clearing the block on editing a project while it is + * syncing; core only triggers it at the corresponding session boundary. + * + * Handles its own errors internally and always resolves (never rejects for an internal + * failure), reporting the outcome via the return value so the triggering side can log it + * truthfully. + * + * @param boundary Which session boundary is being triggered. + * @returns `'synced'` if a scheduled sync ran and completed, `'failed'` if one ran but did not + * complete successfully, or `'skipped'` if nothing ran (nothing scheduled, not due, or + * another sync already in progress). + * @experimental This command is unstable and may change or disappear without notice + */ + 'paratextBibleSendReceive.runScheduledSessionSync': ( + boundary: 'startup' | 'shutdown', + ) => Promise<'synced' | 'failed' | 'skipped'>; /** * Accepts a project id, and returns a RevisionInfo[] of all revisions for the given project. * diff --git a/lib/papi-dts/papi.d.ts b/lib/papi-dts/papi.d.ts index 92e9a81bc08..99acdc533e4 100644 --- a/lib/papi-dts/papi.d.ts +++ b/lib/papi-dts/papi.d.ts @@ -1022,6 +1022,22 @@ declare module 'shared/data/rpc.model' { } from 'json-rpc-2.0'; /** Port to use for the WebSocket */ export const WEBSOCKET_PORT = 8876; + /** + * How many times to try sending a request before giving up if the request is not yet registered. + * Exported so callers that layer their own retry policy on top of {@link requestWithRetry}'s cadence + * (e.g. the Power-mode startup sync's boot-race loop) can derive from this shared policy instead of + * re-declaring the literal and silently diverging if it is ever retuned. + * + * @experimental + */ + export const MAX_REQUEST_ATTEMPTS = 10; + /** + * How long in ms to wait between request attempts if the request is not yet registered. Exported + * for the same derive-don't-duplicate reason as {@link MAX_REQUEST_ATTEMPTS}. + * + * @experimental + */ + export const REQUEST_ATTEMPT_WAIT_TIME_MS = 1000; /** * Whether an RPC object is setting up or has finished setting up its connection and is ready to * communicate on the network @@ -1152,6 +1168,30 @@ declare module 'shared/data/rpc.model' { export const GET_METHODS = 'rpc.discover'; /** Prefix on requests that indicates that the request is a command */ export const CATEGORY_COMMAND = 'command'; + /** + * Builds the exact prefix that `network.service`'s `doRequest` embeds in the message it throws for + * a JSON-RPC _error response_ with the given `code` — the full thrown message is this prefix + * followed by `: `. + * + * Exported so the few callers that must classify these thrown errors by message (there is no richer + * machine-readable marker for a "method not found" response) derive the format from this single + * producer instead of hand-copying the literal. Hand-copied copies silently drift: reformat the + * producer and a separate matcher/fixture keeps matching its old string while real errors stop + * matching, and the tests stay green. Everything routing through this function stays in lockstep. + * + * @param code The JSON-RPC error code from the error response being classified + * @returns The exact message prefix `doRequest` uses for an error response with that `code` + * @experimental + */ + export function getJsonRpcRequestErrorMessagePrefix(code: number): string; + /** + * Prefix that `network.service`'s `doRequest` embeds in the message it throws when a request times + * out client-side before any response arrives. Exported for the same drift-prevention reason as + * {@link getJsonRpcRequestErrorMessagePrefix}. + * + * @experimental + */ + export const JSON_RPC_REQUEST_TIMED_OUT_MESSAGE_PREFIX = 'JSON-RPC Request timed out:'; } declare module 'shared/models/openrpc.model' { import type { JSONSchema7 } from 'json-schema'; diff --git a/src/main/main.ts b/src/main/main.ts index 154bf009177..cd19a8e0934 100644 --- a/src/main/main.ts +++ b/src/main/main.ts @@ -229,13 +229,29 @@ async function main() { // TODO (maybe): Wait for signal from the extension host process that it is ready (except 'getWebView') // We could then wait for the renderer to be ready and signal the extension host - // Fire-and-forget startup tasks (e.g. simple-mode initial S/R). Must not block window creation. - // The S/R command is registered by the .NET data provider, which may not yet be reachable; - // performStartupTasks uses retrying sendCommand semantics and swallows failures internally. + // Signals for the fire-and-forget startup tasks: an abort controller so the Power-mode boot-race + // retry loop stops the moment the app begins quitting (wired below), and a window-interactive + // clock so a startup sync that only registers late isn't fired onto an editor the user is already + // using (see performStartupTasks / STARTUP_SYNC_FRESHNESS_WINDOW_MS). + const startupTasksAbort = new AbortController(); + let mainWindowInteractiveAt: number | undefined; + + // Fire-and-forget startup tasks (initial S/R). Must not block window creation. In Simple mode the + // S/R command is served by the .NET data provider and is driven through the retrying + // `commandService.sendCommand`. In Power mode the trigger is `runScheduledSessionSync`, which the + // send-receive extension registers in the extension host (not the .NET data provider) and which + // performStartupTasks drives via `requestNoRetry` inside its own bounded 120 s boot-race loop — + // deliberately NOT sendCommand's retry semantics. Either way failures are swallowed internally. // Wrapped in an async IIFE per code-style preference for try/catch over `.catch()` chains. (async () => { try { - await performStartupTasks(); + await performStartupTasks({ + abortSignal: startupTasksAbort.signal, + getWindowInteractiveElapsedMs: () => + mainWindowInteractiveAt === undefined + ? undefined + : performance.now() - mainWindowInteractiveAt, + }); } catch (e) { logger.warn(`performStartupTasks threw unexpectedly: ${getErrorMessage(e)}`); } @@ -476,6 +492,10 @@ async function main() { mainWindow.on('ready-to-show', async () => { logger.info('mainWindow is ready to show'); + // Anchor the startup-sync freshness clock to when the window first becomes interactive (see + // the startup-tasks signals above): a late-registering startup sync is only fired if the user + // hasn't yet had the window long enough to be editing. + mainWindowInteractiveAt ??= performance.now(); if (!mainWindow) throw new Error('"mainWindow" is not defined'); if (process.env.START_MINIMIZED) { logger.info('mainWindow is starting minimized due to START_MINIMIZED env variable'); @@ -555,13 +575,20 @@ async function main() { // the window until the sync completes. let isWindowClosing = false; mainWindow.on('close', async (event) => { - // Prevents a "double close" when the user tries to press the close window button a second - // time + // A second close click while the first shutdown is still running falls through to Electron's + // default close on purpose: with the shutdown sync's request timeout disabled by the + // extension, the bounded wait below can hold the window up to SHUTDOWN_SYNC_TIME_OUT_MS with + // no feedback, and this fall-through is the user's only escape hatch until a real + // feedback/cancel UX exists (tracked on the shutdown-cancel follow-up ticket). It abandons + // the in-flight sync mid-flight — same risk profile as force-quitting the app. if (isWindowClosing) return; // Prevents the main window from initially closing event.preventDefault(); isWindowClosing = true; + // The app is on its way down: stop the startup boot-race retry loop so it can't fire a startup + // sync after this shutdown sync, or reach a network connection that is about to be torn down. + startupTasksAbort.abort(); try { await performShutdownTasks(); @@ -802,6 +829,9 @@ async function main() { app.on('will-quit', async (e) => { if (!isAppQuitting) { logger.info('Main process is quitting'); + // Stop the startup boot-race retry loop before networkService.shutdown() tears down the + // connection, so a late retry can't resurrect it (a no-op if the window close already aborted). + startupTasksAbort.abort(); // Prevent closing before graceful shutdown is complete. // Also, in the future, this should allow a "are you sure?" dialog to display. diff --git a/src/main/scheduled-session-sync.util.ts b/src/main/scheduled-session-sync.util.ts new file mode 100644 index 00000000000..76f5a875b05 --- /dev/null +++ b/src/main/scheduled-session-sync.util.ts @@ -0,0 +1,44 @@ +import { CATEGORY_COMMAND } from '@shared/data/rpc.model'; +import { serializeRequestType } from '@shared/utils/util'; + +/** + * Fully-qualified name of the S/R extension command that runs the sync scheduled for a session + * boundary ("On startup/shutdown"). Shared by the startup and shutdown task modules so the two call + * sites can't drift apart: a typo in one bare string literal compiles cleanly and both suites still + * pass (they only assert `stringContaining('runScheduledSessionSync')`), so a single source for the + * name is the only thing that actually pins them together. + * + * This is deliberately NOT wired through the typed `commandService.sendCommand`. That path always + * applies the shared network retry policy, which both call sites exist specifically to avoid — the + * shutdown call wants no retry at all, and the startup call has its own longer boot-race budget. + * Typing the name here (via the extension's vendored `CommandHandlers` declaration) would buy the + * name check at the cost of the retry semantics `networkService.requestNoRetry` is chosen for, so + * this shared constant gives the name safety without giving up the raw request path. + */ +export const RUN_SCHEDULED_SESSION_SYNC_COMMAND = + 'paratextBibleSendReceive.runScheduledSessionSync'; + +/** Serialized request type for {@link RUN_SCHEDULED_SESSION_SYNC_COMMAND}. */ +export const RUN_SCHEDULED_SESSION_SYNC_REQUEST_TYPE = serializeRequestType( + CATEGORY_COMMAND, + RUN_SCHEDULED_SESSION_SYNC_COMMAND, +); + +/** The two session boundaries at which a scheduled sync can be triggered. */ +export type SessionSyncBoundary = 'startup' | 'shutdown'; + +/** + * Result the S/R extension's `runScheduledSessionSync` command resolves with. The command handles + * its own errors internally and always resolves (it never rejects for an internal failure), so core + * distinguishes the three real outcomes from this value rather than from resolve-vs-reject: + * + * - `synced`: a scheduled sync ran and completed successfully. + * - `failed`: a scheduled sync ran but did not complete successfully (the extension logged detail). + * - `skipped`: nothing ran — nothing was scheduled for this boundary, it wasn't due, or another sync + * was already in progress (the common default state until the user schedules something). + * + * A rejection from the call still means the command couldn't be reached/executed at all (not + * registered yet, or a request timeout); callers treat that separately from these settled + * outcomes. + */ +export type ScheduledSessionSyncResult = 'synced' | 'failed' | 'skipped'; diff --git a/src/main/shutdown-tasks.test.ts b/src/main/shutdown-tasks.test.ts index 7f07df80283..e80b7933eb2 100644 --- a/src/main/shutdown-tasks.test.ts +++ b/src/main/shutdown-tasks.test.ts @@ -1,7 +1,9 @@ import { vi } from 'vitest'; +import { SHUTDOWN_SYNC_TIME_OUT_MS } from '@shared/data/platform.data'; import { settingsService } from '@shared/services/settings.service'; import * as networkService from '@shared/services/network.service'; import { networkObjectService } from '@shared/services/network-object.service'; +import { logger } from '@shared/services/logger.service'; import { performShutdownTasks } from './shutdown-tasks'; vi.mock('@shared/services/settings.service', () => ({ @@ -17,12 +19,18 @@ vi.mock('@shared/services/network-object.service', () => ({ })); vi.mock('@shared/services/logger.service', () => ({ - logger: { info: vi.fn(), warn: vi.fn(), error: vi.fn() }, + // `debug` matches the sibling startup-tasks.test.ts mock; logShutdownSyncOutcome logs a scheduled + // skip at debug, so leaving it out would throw "logger.debug is not a function". + logger: { debug: vi.fn(), info: vi.fn(), warn: vi.fn(), error: vi.fn() }, })); const mockSettingsGet = vi.mocked(settingsService.get); const mockRequestNoRetry = vi.mocked(networkService.requestNoRetry); const mockNetworkObjectGet = vi.mocked(networkObjectService.get); +const mockLoggerDebug = vi.mocked(logger.debug); +const mockLoggerInfo = vi.mocked(logger.info); +const mockLoggerWarn = vi.mocked(logger.warn); +const mockLoggerError = vi.mocked(logger.error); function makeWebViewService(defs: object[]) { return { @@ -37,10 +45,74 @@ beforeEach(() => { }); describe('performShutdownTasks', () => { - it('returns without any network calls when interface mode is not simple', async () => { + it('fires runScheduledSessionSync("shutdown") and logs "complete" when the command reports "synced"', async () => { mockSettingsGet.mockResolvedValue('power'); + mockRequestNoRetry.mockResolvedValue('synced'); await performShutdownTasks(); - expect(mockRequestNoRetry).not.toHaveBeenCalled(); + expect(mockRequestNoRetry).toHaveBeenCalledWith( + expect.stringContaining('runScheduledSessionSync'), + 'shutdown', + ); + // Power mode selects by schedule, not open editors/cancelSync — neither Simple-mode call fires. + expect(mockRequestNoRetry.mock.calls.map(([cmd]) => cmd)).not.toContainEqual( + expect.stringContaining('cancelSync'), + ); + expect(mockNetworkObjectGet).not.toHaveBeenCalled(); + // A reported "synced" is the only thing that produces the truthful "complete" log. + expect(mockLoggerInfo).toHaveBeenCalledWith('Sync on shutdown complete'); + }); + + it('treats a legacy void resolution as "synced" (logs "complete")', async () => { + mockSettingsGet.mockResolvedValue('power'); + mockRequestNoRetry.mockResolvedValue(undefined); + await performShutdownTasks(); + expect(mockLoggerInfo).toHaveBeenCalledWith('Sync on shutdown complete'); + }); + + it('warns (does not log "complete") when the command reports "failed"', async () => { + mockSettingsGet.mockResolvedValue('power'); + mockRequestNoRetry.mockResolvedValue('failed'); + await performShutdownTasks(); + expect(mockLoggerWarn).toHaveBeenCalledWith(expect.stringContaining('reported failure')); + expect(mockLoggerInfo).not.toHaveBeenCalledWith('Sync on shutdown complete'); + }); + + it('logs a debug-only skip (no info, no warn) when the command reports "skipped"', async () => { + mockSettingsGet.mockResolvedValue('power'); + mockRequestNoRetry.mockResolvedValue('skipped'); + await performShutdownTasks(); + expect(mockLoggerDebug).toHaveBeenCalledWith(expect.stringContaining('skipped')); + expect(mockLoggerInfo).not.toHaveBeenCalledWith('Sync on shutdown complete'); + expect(mockLoggerWarn).not.toHaveBeenCalled(); + }); + + it('swallows a missing/failing runScheduledSessionSync command in power mode without throwing, and does not log "complete"', async () => { + mockSettingsGet.mockResolvedValue('power'); + mockRequestNoRetry.mockRejectedValue(new Error('command not registered')); + await expect(performShutdownTasks()).resolves.toBeUndefined(); + // The bounded wait settled (the rejection was caught, not a timeout), so the failure is warned + // and the misleading "complete" is never logged. + expect(mockLoggerWarn).toHaveBeenCalledWith(expect.stringContaining('failed or skipped')); + expect(mockLoggerInfo).not.toHaveBeenCalledWith('Sync on shutdown complete'); + }); + + it('returns after the timeout when runScheduledSessionSync never settles, logs the timeout, and never logs "complete"', async () => { + mockSettingsGet.mockResolvedValue('power'); + // Never-resolving promise: simulates a genuinely hung sync. `performSync` never settles, so the + // AsyncVariable's timeout rejects `syncComplete.promise` and runBoundedShutdownSync takes its + // `timedOut` branch — the one path SHUTDOWN_SYNC_TIME_OUT_MS exists to bound. (An unregistered + // command does NOT reach here; it rejects fast and settles as `failed`, covered above.) + mockRequestNoRetry.mockImplementation(() => new Promise(() => {})); + vi.useFakeTimers(); + try { + const shutdownPromise = performShutdownTasks(); + await vi.advanceTimersByTimeAsync(SHUTDOWN_SYNC_TIME_OUT_MS); + await expect(shutdownPromise).resolves.toBeUndefined(); + } finally { + vi.useRealTimers(); + } + expect(mockLoggerWarn).toHaveBeenCalledWith(expect.stringContaining('timed out')); + expect(mockLoggerInfo).not.toHaveBeenCalledWith(expect.stringContaining('complete')); }); it('cancels sync but skips S/R when no Scripture Editor is open', async () => { @@ -97,7 +169,9 @@ describe('performShutdownTasks', () => { ); }); - it('proceeds with S/R (simple-mode fallback) when settings service throws', async () => { + it('skips the automatic shutdown S/R and warns when settings service throws (no open-editor fallback)', async () => { + // Symmetric with startup: an unreadable mode must not fall through to Simple's open-editor S/R, + // which could sync a project a Power user excluded from their schedule. Do nothing and warn. mockSettingsGet.mockRejectedValue(new Error('settings unavailable')); mockNetworkObjectGet.mockResolvedValue( makeWebViewService([ @@ -109,20 +183,36 @@ describe('performShutdownTasks', () => { ]), ); await performShutdownTasks(); - expect(mockRequestNoRetry).toHaveBeenCalledWith(expect.stringContaining('cancelSync')); - expect(mockRequestNoRetry).toHaveBeenCalledWith( - expect.stringContaining('sendReceiveProjects'), - ['fallback-project'], + expect(mockRequestNoRetry).not.toHaveBeenCalled(); + expect(mockNetworkObjectGet).not.toHaveBeenCalled(); + expect(mockLoggerWarn).toHaveBeenCalledWith( + expect.stringContaining('Could not read platform.interfaceMode'), ); }); - it('swallows unexpected errors and does not throw', async () => { + it('swallows unexpected errors and does not throw (exercises the outer try/catch)', async () => { mockSettingsGet.mockResolvedValue('simple'); - mockNetworkObjectGet.mockResolvedValue(makeWebViewService([])); - // Force an unexpected throw deep inside by making cancelSync throw a non-Error value - mockRequestNoRetry.mockImplementation(() => { - throw new Error('unexpected non-error throw'); + // A WRITABLE editor so the flow runs past the `if (!projectId) return` early return and into + // performSimpleModeShutdownSync's unguarded region (an empty list would return early and never + // exercise the outer catch — the whole point of this test). + mockNetworkObjectGet.mockResolvedValue( + makeWebViewService([ + { + webViewType: 'platformScriptureEditor.react', + state: { isReadOnly: false }, + projectId: 'p1', + }, + ]), + ); + // Inject an unexpected error from an UNGUARDED spot — the "Syncing project on shutdown..." log, + // which is not wrapped in an inner try/catch. It escapes the inner handlers so that only + // performShutdownTasks's outer try/catch can swallow it. (Verified falsifiable: deleting that + // outer try/catch makes performShutdownTasks reject and this `resolves` assertion fail.) + mockLoggerInfo.mockImplementationOnce(() => { + throw new Error('unexpected logging failure'); }); await expect(performShutdownTasks()).resolves.toBeUndefined(); + // The outer catch handled it via logger.error. + expect(mockLoggerError).toHaveBeenCalled(); }); }); diff --git a/src/main/shutdown-tasks.ts b/src/main/shutdown-tasks.ts index c429286f157..508d89886a2 100644 --- a/src/main/shutdown-tasks.ts +++ b/src/main/shutdown-tasks.ts @@ -10,7 +10,38 @@ import { } from '@shared/services/web-view.service-model'; import { serializeRequestType } from '@shared/utils/util'; import { SCRIPTURE_EDITOR_WEBVIEW_TYPE } from '@shared/models/web-view.model'; -import { AsyncVariable } from 'platform-bible-utils'; +import { + RUN_SCHEDULED_SESSION_SYNC_REQUEST_TYPE, + type ScheduledSessionSyncResult, + type SessionSyncBoundary, +} from '@main/scheduled-session-sync.util'; +import type { SettingTypes } from 'papi-shared-types'; +import { AsyncVariable, getErrorMessage } from 'platform-bible-utils'; + +/** + * Behaviour-driving outcome of a bounded shutdown sync. The extension reports its own result, so + * this carries what actually happened and {@link logShutdownSyncOutcome} can log it truthfully + * rather than always claiming "complete": + * + * - `synced`: the sync ran and completed (Simple: the S/R resolved; Power: the command returned + * `'synced'`). + * - `failed`: the sync ran but did not succeed (Power: the command returned `'failed'`). Warned. + * - `skipped`: nothing ran — nothing scheduled, not due, or already syncing (Power: `'skipped'`). + * - `unreachable`: the S/R call rejected before the timeout (e.g. the command isn't registered). The + * failure detail was already warned inside {@link runBoundedShutdownSync}. + * - `timed-out`: neither settled within {@link SHUTDOWN_SYNC_TIME_OUT_MS} (also already warned there). + */ +type ShutdownSyncOutcome = 'synced' | 'failed' | 'skipped' | 'unreachable' | 'timed-out'; + +/** + * How a {@link runBoundedShutdownSync} bounded wait settled, before the mode-specific caller maps it + * to a {@link ShutdownSyncOutcome}: `performSync` resolved (its value is in `result`), rejected + * (already warned), or the wait timed out (already warned). + */ +type BoundedSyncSettlement = + | { status: 'completed'; result: T } + | { status: 'failed' } + | { status: 'timedOut' }; /** * Runs cleanup tasks (e.g., syncing projects) when the user closes the main window. @@ -19,7 +50,18 @@ import { AsyncVariable } from 'platform-bible-utils'; * project. All errors are swallowed — extension may not be installed, or may fail — shutdown must * never be permanently blocked. * - * In Power mode (or any non-Simple mode): returns immediately with no automatic S/R. + * In Power mode: S/Rs the projects scheduled "On startup/shutdown" via the S/R extension's + * `runScheduledSessionSync` command. Same error-swallowing contract — if the command isn't + * registered (e.g. plain Platform.Bible with no S/R extension), this is a logged no-op, never a + * crash or a wedged shutdown. No edit-block and no conflict surfacing here: the app is closing, so + * there is nothing left to protect and no UI to show a result in — conflicts are surfaced again on + * next startup instead. + * + * If the interface-mode setting can't be read: skips the automatic shutdown S/R entirely and warns, + * rather than falling through to Simple mode's open-editor S/R. The read can fail exactly when the + * app is closing (the extension host may already be tearing down), and Simple mode would S/R + * whichever writable editor happens to be open — for a Power user, possibly a project they + * deliberately excluded from their schedule. Symmetric with {@link performStartupTasks}. */ export async function performShutdownTasks(): Promise { try { @@ -30,18 +72,33 @@ export async function performShutdownTasks(): Promise { } async function performShutdownTasksInternal(): Promise { - // Power mode: close immediately — no automatic S/R on shutdown. - // If the setting can't be read, default to simple mode to avoid skipping S/R and risking data loss. - let interfaceMode: string | undefined; + // An unreadable mode must NOT fall through to Simple mode's open-editor S/R (symmetric with + // startup): the read can fail exactly when the app is closing, and Simple mode S/Rs whatever + // writable editor happens to be open — for a Power user, possibly a project they excluded from + // their schedule. When we can't tell the mode, skip the automatic shutdown S/R and warn. + let interfaceMode: SettingTypes['platform.interfaceMode'] | undefined; try { interfaceMode = await settingsService.get('platform.interfaceMode'); - } catch { - /* settings service unavailable — treat as simple mode to avoid data loss */ + } catch (e) { + logger.warn( + `Could not read platform.interfaceMode; skipping automatic shutdown sync: ${getErrorMessage(e)}`, + ); + return; } - if (interfaceMode !== undefined && interfaceMode !== 'simple') return; - // Simple mode: cancel any in-progress sync first (e.g. a first-sync on startup), then S/R - // the active project. + if (interfaceMode === 'power') { + await performPowerModeShutdownSync(); + return; + } + + // The setting's type and its runtime validator close the union to 'simple' | 'power', so 'simple' + // is the only value left here — Simple mode is the fall-through, not a checked branch. A future + // third mode would be a compile error here, not a silent no-S/R. + await performSimpleModeShutdownSync(); +} + +async function performSimpleModeShutdownSync(): Promise { + // Cancel any in-progress sync first (e.g. a first-sync on startup), then S/R the active project. try { await networkService.requestNoRetry( serializeRequestType(CATEGORY_COMMAND, 'paratextBibleSendReceive.cancelSync'), @@ -58,8 +115,10 @@ async function performShutdownTasksInternal(): Promise { NETWORK_OBJECT_NAME_WEB_VIEW_SERVICE, ); const openDefs = await webViewService?.getAllOpenWebViewDefinitions(); - // Simple mode allows at most one writable Scripture Editor at a time, so find() is sufficient. - // Power mode can have multiple — revisit this if S/R on shutdown is ever extended to Power mode. + // Only genuine Simple mode reaches here — Power mode selects by schedule (see + // performPowerModeShutdownSync) and an unreadable mode now returns early above rather than + // falling through. Simple mode allows at most one writable Scripture Editor at a time, so find() + // is sufficient. const activeEditor = openDefs?.find( (def) => def.webViewType === SCRIPTURE_EDITOR_WEBVIEW_TYPE && !def.state?.isReadOnly, ); @@ -71,26 +130,134 @@ async function performShutdownTasksInternal(): Promise { if (!projectId) return; logger.info('Syncing project on shutdown...'); - - // Copy to a const so TypeScript knows the type is string inside the async IIFE below. + // Copy to a const so TypeScript knows the type is string inside the bounded-wait callback. const syncProjectId = projectId; - const syncComplete = new AsyncVariable('shutdown sync', SHUTDOWN_SYNC_TIME_OUT_MS); + const settlement = await runBoundedShutdownSync('shutdown sync', () => + networkService.requestNoRetry( + serializeRequestType(CATEGORY_COMMAND, 'paratextBibleSendReceive.sendReceiveProjects'), + [syncProjectId], + ), + ); + // Simple mode has no "skipped" state: reaching here means a writable project was selected, so a + // resolution is a completed S/R. + let outcome: ShutdownSyncOutcome; + if (settlement.status === 'timedOut') outcome = 'timed-out'; + else if (settlement.status === 'failed') outcome = 'unreachable'; + else outcome = 'synced'; + logShutdownSyncOutcome(outcome); +} + +/** + * Power mode: triggers the S/R extension's session-boundary sync for the projects scheduled "On + * startup/shutdown". The extension owns selecting that subset (from its schedule store), running + * the sync, and — deliberately — NOT surfacing conflicts, since the app is closing and there's no + * UI left to show them in (PT9 parity). Core only triggers it and bounds the wait with the same + * scaffold Simple mode uses, logging the reported outcome. + * + * There is deliberately no boot-race retry here, unlike startup + * (`requestSessionSyncWithBootRetry`). A shutdown boot race is near-impossible: this only runs when + * the user closes the window, which in normal use is long after the extension host has activated + * and registered its commands — the cold-boot activation window the startup retry exists to absorb + * has closed by the time anyone quits. If the command genuinely isn't registered (e.g. no S/R + * extension), it rejects fast and this is a logged no-op, the right outcome at shutdown anyway; + * retrying would only fight the window hang below, since the window is already held open waiting on + * this one sync. + * + * {@link SHUTDOWN_SYNC_TIME_OUT_MS} is the ONLY real bound on this call: the S/R extension registers + * `runScheduledSessionSync` with its per-request timeout disabled (a scheduled sync can + * legitimately run long), so `requestNoRetry` has no client-side timeout of its own here. If the + * extension ever stopped disabling that timeout, this would silently become a ~30 s truncation that + * could kill a real sync mid-flight — so that cross-repo dependency is called out on purpose. + */ +async function performPowerModeShutdownSync(): Promise { + const settlement = await runBoundedShutdownSync('power-mode shutdown session sync', () => + networkService.requestNoRetry<[SessionSyncBoundary], ScheduledSessionSyncResult | undefined>( + RUN_SCHEDULED_SESSION_SYNC_REQUEST_TYPE, + 'shutdown', + ), + ); + let outcome: ShutdownSyncOutcome; + if (settlement.status === 'timedOut') outcome = 'timed-out'; + else if (settlement.status === 'failed') outcome = 'unreachable'; + // Tolerate a legacy void resolution (an older extension that returned `Promise`): treat a + // missing result as a completed sync. + else outcome = settlement.result ?? 'synced'; + logShutdownSyncOutcome(outcome); +} + +/** + * Logs a {@link ShutdownSyncOutcome} truthfully — "complete" only when a sync actually ran and + * succeeded. A sync that ran but reported failure warns; a deliberate skip (nothing scheduled) is + * debug-only; and the already-warned cases (`unreachable`, `timed-out`) add nothing here. + */ +function logShutdownSyncOutcome(outcome: ShutdownSyncOutcome): void { + switch (outcome) { + case 'synced': + logger.info('Sync on shutdown complete'); + break; + case 'failed': + logger.warn('Sync on shutdown ran but reported failure'); + break; + case 'skipped': + logger.debug('Sync on shutdown skipped (nothing scheduled, not due, or already syncing)'); + break; + case 'unreachable': + case 'timed-out': + // The failure detail was already logged inside runBoundedShutdownSync; nothing truthful to add. + break; + default: + break; + } +} + +/** + * Runs `performSync` in the background and waits for it to settle, bounded by + * {@link SHUTDOWN_SYNC_TIME_OUT_MS} so a genuinely hung sync can never wedge shutdown open forever. + * The timeout is load-bearing for a _hung_ sync specifically: an unregistered command does NOT hang + * — it rejects fast with MethodNotFound, which surfaces as a `failed` settlement (this is exactly + * what startup's retry loop is built on). What the bound actually guards against is that the S/R + * extension registers `runScheduledSessionSync` with its per-request timeout disabled (see + * {@link performPowerModeShutdownSync}), so `requestNoRetry` has no client-side timeout of its own. + * + * Failures from `performSync` are warned and swallowed here; the caller maps the returned + * settlement to a {@link ShutdownSyncOutcome} for the truthful summary log. + * + * This is the one bounded-wait mechanism for shutdown; both Simple mode's `sendReceiveProjects` and + * Power mode's `runScheduledSessionSync` go through it rather than each inventing their own. + */ +async function runBoundedShutdownSync( + variableName: string, + performSync: () => Promise, +): Promise> { + const syncComplete = new AsyncVariable>( + variableName, + SHUTDOWN_SYNC_TIME_OUT_MS, + ); (async () => { + let settlement: BoundedSyncSettlement; try { - await networkService.requestNoRetry( - serializeRequestType(CATEGORY_COMMAND, 'paratextBibleSendReceive.sendReceiveProjects'), - [syncProjectId], - ); - if (!syncComplete.hasTimedOut) syncComplete.resolveToValue(undefined); - } catch { - // sync failed — settle anyway - if (!syncComplete.hasTimedOut) syncComplete.resolveToValue(undefined); + settlement = { status: 'completed', result: await performSync() }; + } catch (e) { + logger.warn(`${variableName} failed or skipped: ${getErrorMessage(e)}`); + settlement = { status: 'failed' }; } + // `resolveToValue` is a no-op (not a throw) once the timeout already settled the variable, so no + // `hasTimedOut` guard is needed to avoid a double-settle here. + syncComplete.resolveToValue(settlement); })(); try { - await syncComplete.promise; - logger.info('Sync on shutdown complete'); - } catch { - /* timed out */ + return await syncComplete.promise; + } catch (e) { + // Branch on `hasTimedOut` rather than assuming every rejection is the timeout: the AsyncVariable + // timer is the only rejection path today, but a future cancel-on-quit path shouldn't be + // mislabelled as a 10-minute timeout. + if (syncComplete.hasTimedOut) { + logger.warn( + `${variableName} timed out after ${SHUTDOWN_SYNC_TIME_OUT_MS} ms; continuing shutdown`, + ); + return { status: 'timedOut' }; + } + logger.warn(`${variableName} did not complete: ${getErrorMessage(e)}`); + return { status: 'failed' }; } } diff --git a/src/main/startup-tasks.test.ts b/src/main/startup-tasks.test.ts index 1d72c26d3b2..b2583b93e08 100644 --- a/src/main/startup-tasks.test.ts +++ b/src/main/startup-tasks.test.ts @@ -1,7 +1,16 @@ import { vi } from 'vitest'; +import { JSONRPCErrorCode } from 'json-rpc-2.0'; +import { + getJsonRpcRequestErrorMessagePrefix, + JSON_RPC_REQUEST_TIMED_OUT_MESSAGE_PREFIX, + MAX_REQUEST_ATTEMPTS, + REQUEST_ATTEMPT_WAIT_TIME_MS, +} from '@shared/data/rpc.model'; import { settingsService } from '@shared/services/settings.service'; import * as commandService from '@shared/services/command.service'; -import { performStartupTasks } from './startup-tasks'; +import * as networkService from '@shared/services/network.service'; +import { logger } from '@shared/services/logger.service'; +import { performStartupTasks, STARTUP_SYNC_RETRY_BUDGET_MS } from './startup-tasks'; vi.mock('@shared/services/settings.service', () => ({ settingsService: { get: vi.fn() }, @@ -11,22 +20,54 @@ vi.mock('@shared/services/command.service', () => ({ sendCommand: vi.fn(), })); +vi.mock('@shared/services/network.service', () => ({ + requestNoRetry: vi.fn(), +})); + vi.mock('@shared/services/logger.service', () => ({ logger: { debug: vi.fn(), info: vi.fn(), warn: vi.fn(), error: vi.fn() }, })); const mockSettingsGet = vi.mocked(settingsService.get); const mockSendCommand = vi.mocked(commandService.sendCommand); +const mockRequestNoRetry = vi.mocked(networkService.requestNoRetry); +const mockLoggerDebug = vi.mocked(logger.debug); +const mockLoggerWarn = vi.mocked(logger.warn); + +/** + * Builds a rejection shaped like what `networkService`'s request plumbing actually throws for a + * JSON-RPC "method not found" response (see `doRequest` in `network.service.ts`). The message + * prefix is derived from `getJsonRpcRequestErrorMessagePrefix` — the same producer `doRequest` uses + * — rather than hand-copied, so if that format is ever reformatted this fixture (and the matcher) + * move with it and can't silently stop matching real errors while the test stays green. + */ +function methodNotFoundError() { + return new Error( + `${getJsonRpcRequestErrorMessagePrefix(JSONRPCErrorCode.MethodNotFound)}: 'command:paratextBibleSendReceive.runScheduledSessionSync' not found`, + ); +} + +/** Builds a rejection shaped like a client-side request timeout, derived from the same producer. */ +function requestTimedOutError() { + return new Error( + `${JSON_RPC_REQUEST_TIMED_OUT_MESSAGE_PREFIX} command:paratextBibleSendReceive.runScheduledSessionSync ["startup"]`, + ); +} beforeEach(() => { vi.clearAllMocks(); mockSendCommand.mockResolvedValue(undefined); + mockRequestNoRetry.mockResolvedValue(undefined); }); describe('performStartupTasks', () => { - it('returns without firing sync when interface mode is power', async () => { + it('fires runScheduledSessionSync("startup") when interface mode is power', async () => { mockSettingsGet.mockResolvedValue('power'); await performStartupTasks(); + expect(mockRequestNoRetry).toHaveBeenCalledWith( + expect.stringContaining('runScheduledSessionSync'), + 'startup', + ); expect(mockSendCommand).not.toHaveBeenCalled(); }); @@ -37,14 +78,19 @@ describe('performStartupTasks', () => { 'paratextBibleSendReceive.syncProjects', undefined, ); + expect(mockRequestNoRetry).not.toHaveBeenCalled(); }); - it('fires syncProjects (simple-mode fallback) when settings service throws', async () => { + it('skips the automatic startup sync and warns when settings service throws (no sync-everything fallback)', async () => { + // An unreadable mode must not fall through to Simple's no-ID syncProjects (= S/R every shared + // project), which would override a Power user's schedule under the exact slow-boot conditions + // the read fails in. Do nothing this session and warn instead. mockSettingsGet.mockRejectedValue(new Error('settings unavailable')); await performStartupTasks(); - expect(mockSendCommand).toHaveBeenCalledWith( - 'paratextBibleSendReceive.syncProjects', - undefined, + expect(mockSendCommand).not.toHaveBeenCalled(); + expect(mockRequestNoRetry).not.toHaveBeenCalled(); + expect(mockLoggerWarn).toHaveBeenCalledWith( + expect.stringContaining('Could not read platform.interfaceMode'), ); }); @@ -61,4 +107,184 @@ describe('performStartupTasks', () => { }); await expect(performStartupTasks()).resolves.toBeUndefined(); }); + + describe('power-mode startup sync outcome', () => { + it('warns (not "complete") when the command reports "failed"', async () => { + mockSettingsGet.mockResolvedValue('power'); + mockRequestNoRetry.mockResolvedValue('failed'); + await performStartupTasks(); + expect(mockLoggerWarn).toHaveBeenCalledWith(expect.stringContaining('reported failure')); + }); + + it('logs a debug-only skip (no warn) when the command reports "skipped"', async () => { + mockSettingsGet.mockResolvedValue('power'); + mockRequestNoRetry.mockResolvedValue('skipped'); + await performStartupTasks(); + expect(mockLoggerWarn).not.toHaveBeenCalled(); + expect(mockLoggerDebug).toHaveBeenCalledWith(expect.stringContaining('skipped')); + }); + + it('treats a legacy void resolution as "synced" (no warn)', async () => { + mockSettingsGet.mockResolvedValue('power'); + mockRequestNoRetry.mockResolvedValue(undefined); + await performStartupTasks(); + expect(mockLoggerWarn).not.toHaveBeenCalled(); + expect(mockLoggerDebug).toHaveBeenCalledWith( + expect.stringContaining('Power-mode startup sync complete'), + ); + }); + + it('drops a stale startup trigger without firing when the window has been interactive too long', async () => { + mockSettingsGet.mockResolvedValue('power'); + // The command is registered, but the user has had the window well past the freshness window, + // so firing now would raise the edit-block on an editor they are already using. + await performStartupTasks({ getWindowInteractiveElapsedMs: () => 10 * 60 * 1000 }); + expect(mockRequestNoRetry).not.toHaveBeenCalled(); + expect(mockLoggerWarn).not.toHaveBeenCalled(); + expect(mockLoggerDebug).toHaveBeenCalledWith(expect.stringContaining('no longer fresh')); + }); + + it('fires the sync when the window has been interactive for less than the freshness window', async () => { + mockSettingsGet.mockResolvedValue('power'); + // Counterpart to the stale-drop test above: main.ts always supplies this signal in + // production, so without this case an inverted freshness gate (or a zeroed window) would + // silently drop every real boot's startup sync while the suite stays green. + await performStartupTasks({ getWindowInteractiveElapsedMs: () => 1_000 }); + expect(mockRequestNoRetry).toHaveBeenCalledWith( + expect.stringContaining('runScheduledSessionSync'), + 'startup', + ); + expect(mockLoggerWarn).not.toHaveBeenCalled(); + }); + + it('does not fire (or warn) when the app is already quitting before the command registers', async () => { + mockSettingsGet.mockResolvedValue('power'); + const abort = new AbortController(); + abort.abort(); + await performStartupTasks({ abortSignal: abort.signal }); + expect(mockRequestNoRetry).not.toHaveBeenCalled(); + expect(mockLoggerWarn).not.toHaveBeenCalled(); + expect(mockLoggerDebug).toHaveBeenCalledWith(expect.stringContaining('quitting')); + }); + }); + + // #region Boot-race retry: distinguishes "not registered yet" (retry) from a genuine + // handler failure (don't retry), and bounds the retry budget so startup is never blocked. + + describe('power-mode startup sync boot-race retry', () => { + // Retry cadence (see startup-tasks.ts): the first INITIAL_RETRY_ATTEMPTS waits are + // INITIAL_RETRY_INTERVAL_MS; every wait after that is EXTENDED_RETRY_INTERVAL_MS (2s). The + // initial phase derives from the shared rpc.model constants — the same source startup-tasks.ts + // aliases — so a retune of the shared retry policy flows through both without silent drift. + const INITIAL_RETRY_ATTEMPTS = MAX_REQUEST_ATTEMPTS; + const INITIAL_RETRY_INTERVAL_MS = REQUEST_ATTEMPT_WAIT_TIME_MS; + const EXTENDED_RETRY_INTERVAL_MS = 2000; + + it('keeps retrying MethodNotFound past the shared ~9s ceiling and pins the two-phase backoff cadence', async () => { + mockSettingsGet.mockResolvedValue('power'); + // Succeed on a deliberately NON-symmetric attempt so the two-phase cadence is observable: 10 + // waits @1s + 4 waits @2s before the 15th attempt = 18s. Deleting the backoff (all @1s = 14s) + // or inverting the phases (@2s then @1s = 22s) both change this elapsed time and fail below. + const SUCCEED_ON_CALL = 15; + const EXPECTED_ELAPSED_MS = + INITIAL_RETRY_ATTEMPTS * INITIAL_RETRY_INTERVAL_MS + + (SUCCEED_ON_CALL - 1 - INITIAL_RETRY_ATTEMPTS) * EXTENDED_RETRY_INTERVAL_MS; // 18_000 + let callCount = 0; + mockRequestNoRetry.mockImplementation(async () => { + callCount += 1; + if (callCount < SUCCEED_ON_CALL) throw methodNotFoundError(); + return undefined; + }); + + vi.useFakeTimers(); + try { + const startupPromise = performStartupTasks(); + // 1ms before the expected time the succeeding attempt has not fired yet. + await vi.advanceTimersByTimeAsync(EXPECTED_ELAPSED_MS - 1); + expect(callCount).toBe(SUCCEED_ON_CALL - 1); + // Crossing the expected elapsed time triggers exactly the succeeding attempt. + await vi.advanceTimersByTimeAsync(1); + await expect(startupPromise).resolves.toBeUndefined(); + } finally { + vi.useRealTimers(); + } + + expect(callCount).toBe(SUCCEED_ON_CALL); + // A successful retry never reaches the "failed or skipped" warn. + expect(mockLoggerWarn).not.toHaveBeenCalled(); + }); + + it('retries a client-side request timeout (not just MethodNotFound) and succeeds when it clears', async () => { + // A request timeout at cold boot is a "not ready yet" condition, not a genuine failure (e.g. + // the extension's timeout override hasn't propagated yet), so it must be retried within budget. + mockSettingsGet.mockResolvedValue('power'); + let callCount = 0; + mockRequestNoRetry.mockImplementation(async () => { + callCount += 1; + if (callCount === 1) throw requestTimedOutError(); + return undefined; + }); + + vi.useFakeTimers(); + try { + const startupPromise = performStartupTasks(); + await vi.advanceTimersByTimeAsync(5_000); + await expect(startupPromise).resolves.toBeUndefined(); + } finally { + vi.useRealTimers(); + } + + expect(callCount).toBe(2); + expect(mockLoggerWarn).not.toHaveBeenCalled(); + }); + + it('does NOT retry a non-MethodNotFound error (a real handler failure) and warns immediately', async () => { + mockSettingsGet.mockResolvedValue('power'); + mockRequestNoRetry.mockRejectedValue(new Error('handler threw: something went wrong')); + + await expect(performStartupTasks()).resolves.toBeUndefined(); + + // Exactly one attempt: blindly retrying a genuine handler error would just repeat it. + expect(mockRequestNoRetry).toHaveBeenCalledTimes(1); + expect(mockLoggerWarn).toHaveBeenCalledTimes(1); + // A registered handler that threw is a real failure — the message must not blame missing + // registration (it says "failed", not "never registered"). + expect(mockLoggerWarn).toHaveBeenCalledWith( + expect.stringContaining('Power-mode startup sync failed'), + ); + }); + + it('honors the retry budget: retries on the expected cadence up to ~66 attempts, then stops and warns once', async () => { + mockSettingsGet.mockResolvedValue('power'); + mockRequestNoRetry.mockRejectedValue(methodNotFoundError()); + + vi.useFakeTimers(); + try { + const startupPromise = performStartupTasks(); + // Comfortably past the full retry budget so the deadline check is guaranteed to trip. + await vi.advanceTimersByTimeAsync(STARTUP_SYNC_RETRY_BUDGET_MS + 10_000); + // Startup itself was never blocked: this resolves once fake time is past the budget. + await expect(startupPromise).resolves.toBeUndefined(); + } finally { + vi.useRealTimers(); + } + + // Cadence over the 120s budget: attempts 1-10 fire through t=9s (their 10 waits are @1s), then + // one every 2s from t=10s. The deadline check is `>=`, so the attempt landing exactly at the + // t=120s deadline still fires before the loop gives up — 10 @1s + 56 @2s = 66 attempts. Pinning + // the count (rather than just ">1") is what makes an `if (attempt >= 2) throw` mutation — or any + // budget that ignores STARTUP_SYNC_RETRY_BUDGET_MS — fail this test. + const EXPECTED_ATTEMPTS = + INITIAL_RETRY_ATTEMPTS + + (STARTUP_SYNC_RETRY_BUDGET_MS - INITIAL_RETRY_ATTEMPTS * INITIAL_RETRY_INTERVAL_MS) / + EXTENDED_RETRY_INTERVAL_MS + + 1; // 66 (the final attempt lands on the deadline itself) + expect(mockRequestNoRetry).toHaveBeenCalledTimes(EXPECTED_ATTEMPTS); + expect(mockLoggerWarn).toHaveBeenCalledTimes(1); + // Budget exhausted on MethodNotFound means the command never registered — the message says so. + expect(mockLoggerWarn).toHaveBeenCalledWith(expect.stringContaining('never registered')); + }); + }); + + // #endregion }); diff --git a/src/main/startup-tasks.ts b/src/main/startup-tasks.ts index 8055a327246..6801f3d94b2 100644 --- a/src/main/startup-tasks.ts +++ b/src/main/startup-tasks.ts @@ -1,7 +1,106 @@ +import { + getJsonRpcRequestErrorMessagePrefix, + JSON_RPC_REQUEST_TIMED_OUT_MESSAGE_PREFIX, + MAX_REQUEST_ATTEMPTS, + REQUEST_ATTEMPT_WAIT_TIME_MS, +} from '@shared/data/rpc.model'; import * as commandService from '@shared/services/command.service'; import { logger } from '@shared/services/logger.service'; +import * as networkService from '@shared/services/network.service'; import { settingsService } from '@shared/services/settings.service'; -import { getErrorMessage } from 'platform-bible-utils'; +import { + RUN_SCHEDULED_SESSION_SYNC_REQUEST_TYPE, + type ScheduledSessionSyncResult, + type SessionSyncBoundary, +} from '@main/scheduled-session-sync.util'; +import { JSONRPCErrorCode } from 'json-rpc-2.0'; +import type { SettingTypes } from 'papi-shared-types'; +import { getErrorMessage, wait } from 'platform-bible-utils'; + +/** + * How long (ms) to keep retrying `runScheduledSessionSync` while it's still unregistered before + * giving up. Boot-appropriate budget: live E2E testing (2026-07-16) observed the extension host + * take longer than the shared `networkService.request` retry policy's ~9 s ceiling + * ({@link MAX_REQUEST_ATTEMPTS} × {@link REQUEST_ATTEMPT_WAIT_TIME_MS}) to activate the send-receive + * extension — all 10 attempts got back a "method not found" response, and the startup sync silently + * never ran even though the extension activated moments later. That shared policy is tuned for + * steady-state requests against handlers that are normally already registered; it isn't meant to + * (and shouldn't, for every other caller's sake) absorb the much longer, one-time race against + * extension-host activation at cold boot. Hence this module keeps its own longer, gentler retry + * budget locally instead of changing the shared default. + * + * Exported so the retry tests can drive fake timers by the exact same duration rather than + * duplicating the literal (mirrors `SHUTDOWN_SYNC_TIME_OUT_MS` in `shutdown-tasks.ts`). + */ +export const STARTUP_SYNC_RETRY_BUDGET_MS = 120_000; + +/** + * How long (ms) after the main window becomes interactive a still-pending "startup" sync may still + * be fired. The boot-race loop keeps retrying up to {@link STARTUP_SYNC_RETRY_BUDGET_MS}, but a + * trigger that only lands well into the session is no longer a "startup" moment: firing it would + * raise the S/R extension's editing-block — the guard that blocks editing a project while it is + * syncing — on an editor the user has by now opened and started typing in, with no apparent cause. + * Past this window the trigger is dropped (those projects sync at the next session boundary + * instead). + * + * Anchored to window-interactive time (supplied by main via + * {@link StartupTasksSignals.getWindowInteractiveElapsedMs}), not process start, so a slow _window_ + * boot still gets its startup sync — only a slow _user_ does not — and the full retry budget stays + * usable when the window itself comes up late. Shorter than the budget so the block-raising window + * is bounded even though the budget is longer. + */ +const STARTUP_SYNC_FRESHNESS_WINDOW_MS = 30_000; + +/** + * Cadence (ms) for the first {@link INITIAL_RETRY_ATTEMPTS} retry attempts. Aliased from the shared + * `requestWithRetry` cadence ({@link REQUEST_ATTEMPT_WAIT_TIME_MS}) — rather than re-declaring the + * literal — so the common case (the extension activates within the first few seconds) behaves the + * same as the shared policy, including if that policy is ever retuned; only the long tail beyond + * that gets the gentler {@link EXTENDED_RETRY_INTERVAL_MS} cadence. + */ +const INITIAL_RETRY_INTERVAL_MS = REQUEST_ATTEMPT_WAIT_TIME_MS; + +/** + * Number of attempts at {@link INITIAL_RETRY_INTERVAL_MS} before backing off to the gentler + * {@link EXTENDED_RETRY_INTERVAL_MS} cadence for the remainder of + * {@link STARTUP_SYNC_RETRY_BUDGET_MS}. Aliased from the shared {@link MAX_REQUEST_ATTEMPTS} for the + * same stay-in-lockstep reason as {@link INITIAL_RETRY_INTERVAL_MS}. + */ +const INITIAL_RETRY_ATTEMPTS = MAX_REQUEST_ATTEMPTS; + +/** Cadence (ms) for retry attempts once {@link INITIAL_RETRY_ATTEMPTS} is exhausted. */ +const EXTENDED_RETRY_INTERVAL_MS = 2000; + +/** + * Optional signals `performStartupTasks` receives from the main process. Both are omitted where + * there is no boot-race loop to steer (Simple mode) or in unit tests that drive the loop directly, + * in which case behavior is unchanged (never aborts, never goes stale). + */ +export interface StartupTasksSignals { + /** + * Aborts the Power-mode boot-race retry loop once the app has begun quitting. Stops it from (a) + * firing `runScheduledSessionSync('startup')` after `('shutdown')` already fired and (b) issuing + * a request that would resurrect the network connection `networkService.shutdown()` is tearing + * down. Wired to `will-quit` and the window close in `main.ts`. + */ + abortSignal?: AbortSignal; + /** + * How long (ms) the main window has been interactive, or `undefined` if it has not been shown + * yet. The freshness anchor for {@link STARTUP_SYNC_FRESHNESS_WINDOW_MS}. + */ + getWindowInteractiveElapsedMs?: () => number | undefined; +} + +/** + * Why {@link requestSessionSyncWithBootRetry} stopped without throwing, so + * {@link performPowerModeStartupSync} can log each case truthfully: + * + * - One of {@link ScheduledSessionSyncResult} — the command ran and reported that result; + * - `'skipped-stale'` — the startup moment went stale before the command registered, so the trigger + * was dropped rather than fired late onto an active editor; + * - `'aborted'` — the app began quitting before the command registered. + */ +type StartupSyncTriggerOutcome = ScheduledSessionSyncResult | 'skipped-stale' | 'aborted'; /** * Runs initialization tasks (currently: triggering an initial project sync) shortly after the app @@ -12,32 +111,54 @@ import { getErrorMessage } from 'platform-bible-utils'; * installed (e.g. Platform.Bible), the command may not yet be registered, or the sync may fail. * Startup must never be blocked or visibly affected by this. * - * In Power mode (or any non-Simple mode): returns immediately with no automatic sync. Power-mode - * users manage Send/Receive manually. Mirrors the mode gating in {@link performShutdownTasks}. + * In Power mode: requests a sync of just the projects scheduled "On startup/shutdown" via the S/R + * extension's `runScheduledSessionSync` command. Same error-swallowing contract as Simple mode — if + * the S/R extension hasn't registered the command yet (or at all, e.g. plain Platform.Bible), this + * is a logged no-op, never a crash or a blocked startup. + * + * If the interface-mode setting can't be read: skips the automatic startup sync entirely and warns, + * rather than falling through to Simple mode's "sync everything". The read can fail under the same + * slow-cold-boot conditions the Power retry budget exists for, and Simple's no-ID `syncProjects` + * would S/R every locally-known shared project — overriding a Power user's schedule. Mirrors the + * symmetric gating in {@link performShutdownTasks}. */ -export async function performStartupTasks(): Promise { +export async function performStartupTasks(signals?: StartupTasksSignals): Promise { try { - await performStartupTasksInternal(); + await performStartupTasksInternal(signals); } catch (e) { logger.warn(`Unexpected error during startup tasks: ${getErrorMessage(e)}`); } } -async function performStartupTasksInternal(): Promise { +async function performStartupTasksInternal(signals?: StartupTasksSignals): Promise { logger.debug('performStartupTasks invoked'); - // Power mode: no automatic sync on startup. - // If the setting can't be read, default to simple mode to avoid skipping sync. - let interfaceMode: string | undefined; + // An unreadable mode must NOT fall through to Simple mode's "sync everything": the read can fail + // under exactly the slow-cold-boot conditions the Power retry budget exists to tolerate, and + // Simple's no-ID `syncProjects` fires an S/R of every locally-known shared project, overriding a + // Power user's schedule and syncing projects they deliberately excluded. When we can't tell the + // mode, the safe default is to skip the automatic startup sync this session and warn. + let interfaceMode: SettingTypes['platform.interfaceMode'] | undefined; try { interfaceMode = await settingsService.get('platform.interfaceMode'); } catch (e) { logger.warn( - `Could not read platform.interfaceMode; defaulting to simple-mode behavior: ${getErrorMessage(e)}`, + `Could not read platform.interfaceMode; skipping automatic startup sync: ${getErrorMessage(e)}`, ); + return; } logger.debug(`performStartupTasks: interfaceMode=${interfaceMode}`); - if (interfaceMode !== undefined && interfaceMode !== 'simple') return; + + if (interfaceMode === 'power') { + await performPowerModeStartupSync(signals); + return; + } + + // The setting's type and its runtime validator (`interfaceModeValidator`) close the union to + // 'simple' | 'power', so once 'power' is handled and an unreadable mode has already returned + // above, 'simple' is the only value left — hence Simple mode is the fall-through rather than a + // checked branch. A future third mode would be a compile error here (interfaceMode is typed from + // the setting), not a silent no-sync. // Simple mode: sync all locally-known shared projects (no project IDs = "sync all" per the // C# `String[]? projectIds` contract). The C# S/R command registers asynchronously during @@ -54,3 +175,206 @@ async function performStartupTasksInternal(): Promise { ); } } + +/** + * Power mode: triggers the S/R extension's session-boundary sync for the projects scheduled "On + * startup/shutdown". The extension owns everything else — reading its schedule store for the + * `onStartupShutdown` subset, running the sync, raising/clearing the editing-block for its + * duration, stamping `lastRunAt`, and opening the results view on conflicts/errors. Core only + * triggers it and logs the reported outcome; startup is never blocked or failed by it. + * + * Goes through `requestSessionSyncWithBootRetry` (raw `networkService.requestNoRetry` under its own + * boot-race budget) rather than the typed `commandService.sendCommand`. The reason is retry + * semantics, not typing: `sendCommand` always applies the shared network retry policy, whose fixed + * ~9 s ceiling loses the cold-boot race against extension-host activation (see + * `requestSessionSyncWithBootRetry`). The command name and boundary come from the shared + * {@link RUN_SCHEDULED_SESSION_SYNC_REQUEST_TYPE} / {@link SessionSyncBoundary} contract so this raw + * call still can't drift from the shutdown call site. + * + * Logs the command's self-reported {@link ScheduledSessionSyncResult} truthfully — a real failure + * warns; a deliberate skip (nothing scheduled, stale startup, or app quitting) is debug-only — so + * the log never claims a sync that didn't happen. + */ +async function performPowerModeStartupSync(signals?: StartupTasksSignals): Promise { + logger.debug('Power-mode startup sync starting'); + let outcome: StartupSyncTriggerOutcome; + try { + outcome = await requestSessionSyncWithBootRetry(signals); + } catch (e) { + // The loop only throws for a non-retryable error or an exhausted budget. Branch the message on + // which: a MethodNotFound at the deadline means the command never registered within the budget + // (e.g. no S/R extension installed); anything else means the command was present but the call + // failed (a request timeout, or a registered handler that threw) — so don't blame missing + // registration for a failure that isn't one. + if (isMethodNotFoundError(e)) + logger.warn( + `Power-mode startup sync skipped: runScheduledSessionSync never registered within the boot retry budget: ${getErrorMessage(e)}`, + ); + else logger.warn(`Power-mode startup sync failed: ${getErrorMessage(e)}`); + return; + } + switch (outcome) { + case 'synced': + logger.debug('Power-mode startup sync complete'); + break; + case 'failed': + logger.warn('Power-mode startup sync ran but reported failure'); + break; + case 'skipped': + logger.debug( + 'Power-mode startup sync skipped (nothing scheduled, not due, or already syncing)', + ); + break; + case 'skipped-stale': + logger.debug( + 'Power-mode startup sync skipped: startup no longer fresh; a late trigger would block an active editor', + ); + break; + case 'aborted': + logger.debug('Power-mode startup sync aborted: app is quitting'); + break; + default: + break; + } +} + +/** + * Whether `error` is what `networkService`'s request plumbing (`doRequest` in `network.service.ts`) + * throws for a JSON-RPC "method not found" response — i.e. no handler for the requested command has + * registered yet anywhere on the network (see the `createErrorResponse(..., + * JSONRPCErrorCode.MethodNotFound)` calls in `rpc-server.ts` / `rpc-websocket-listener.ts`). + * + * This is the one thing that needs distinguishing here: "not registered yet" is worth retrying, but + * a registered handler that threw is a real failure and must NOT be retried blindly. Getting that + * distinction wrong the other way — treating every failure as retryable — would silently repeat a + * genuine handler error for up to {@link STARTUP_SYNC_RETRY_BUDGET_MS} before reporting it. + * + * `networkService` does not expose the raw JSON-RPC error code to callers for this to key off of + * directly: `doRequest` flattens every RPC-level error — method-not-found and a handler throwing + * alike — into a thrown value whose `message` is `JSON-RPC Request error (${code}): ${message}`, + * with no other machine-readable marker distinguishing the two (the richer `platformErrorCode` + * field is populated only for C# `PlatformErrorCodes.WithCode` throws, which a "no handler yet" + * response never carries — it has no `error.data` at all). Matching the numeric JSON-RPC code + * embedded in that message is therefore the only signal available today. This mirrors the same + * message-substring-matching pattern already used by + * `isErrorMessageAboutParatextBlockingInternetAccess` / `isErrorMessageAboutRegistryAuthFailure` in + * `platform-bible-utils` for the same reason (no richer signal exposed). The exact format comes + * from {@link getJsonRpcRequestErrorMessagePrefix}, the same producer `doRequest` builds the message + * with, so a reformat there can't silently stop this matcher (and its test fixture) from matching. + */ +function isMethodNotFoundError(error: unknown): boolean { + return getErrorMessage(error).includes( + getJsonRpcRequestErrorMessagePrefix(JSONRPCErrorCode.MethodNotFound), + ); +} + +/** + * Whether `error` is what `networkService`'s request plumbing throws when a request times out + * client-side before any response arrives (`doRequest` in `network.service.ts` builds `JSON-RPC + * Request timed out: ` when its per-request `AsyncVariable` fires). + * + * At cold boot a timeout is the same "not ready yet" condition as a missing handler, not a genuine + * failure, so it belongs in the retryable set. Concretely, the S/R extension registers + * `runScheduledSessionSync` with its request timeout disabled (a scheduled sync can legitimately + * run long); until that override propagates to this process, `doRequest` still applies the default + * 30 s timeout, so a slow-but-registered first sync can trip it. Excluding that from retry would + * collapse the whole boot budget to a single attempt against a handler that is present and + * working. + * + * Matches by message substring for the same reason as {@link isMethodNotFoundError}, deriving the + * format from the same producer ({@link JSON_RPC_REQUEST_TIMED_OUT_MESSAGE_PREFIX}). + */ +function isRequestTimedOutError(error: unknown): boolean { + return getErrorMessage(error).includes(JSON_RPC_REQUEST_TIMED_OUT_MESSAGE_PREFIX); +} + +/** + * Whether `error` from a `runScheduledSessionSync` attempt is a boot-race condition worth retrying + * within the budget rather than a genuine handler failure. Both retryable shapes mean "the handler + * isn't answering yet", not "the handler ran and failed": a {@link isMethodNotFoundError} (no + * handler registered anywhere on the network yet) or a {@link isRequestTimedOutError} (a handler may + * be present but hasn't responded in time this early in boot). Anything else — a registered handler + * that threw — is a real failure and must NOT be retried blindly. + */ +function isRetryableBootRaceError(error: unknown): boolean { + return isMethodNotFoundError(error) || isRequestTimedOutError(error); +} + +/** + * Retries `paratextBibleSendReceive.runScheduledSessionSync('startup')` on its own boot-appropriate + * schedule (see {@link STARTUP_SYNC_RETRY_BUDGET_MS}), using `networkService.requestNoRetry` for + * each individual attempt rather than the shared retrying `networkService.request` — whose fixed ~9 + * s retry ceiling lost the race against extension host activation in live E2E testing (2026-07-16; + * see {@link STARTUP_SYNC_RETRY_BUDGET_MS}'s doc for the observed timing). + * + * Only {@link isRetryableBootRaceError} failures are retried — a missing handler or an early request + * timeout, both meaning "not answering yet"; any other error — the command exists but its handler + * threw — is NOT retried and is rethrown immediately, since blindly retrying a genuine handler + * failure would just repeat it for no benefit and delay reporting it to the caller (who logs it as + * a warning and moves on). + * + * This is deliberately a narrow, local retry loop rather than a new per-call retry option on + * `networkService.request`: it only serves this one boot-time race, and the shared retry policy + * other callers rely on should stay as-is. The cleaner long-term shape would be the S/R extension + * self-triggering its own startup sync at the end of its own activation, so core never has to race + * extension-host startup at all; that is a larger cross-repo change and is out of scope here (core + * has no signal today for "a method just registered" — the RPC registry set is not surfaced as an + * event; see the standing `TODO (maybe): Wait for signal from the extension host` in `main.ts`). + * + * Returns a {@link StartupSyncTriggerOutcome} for the cases the caller logs as non-failures (the + * command ran and reported a result, the startup went stale, or the app is quitting), and throws + * for a genuine failure (a non-retryable handler error, or the budget exhausted with the command + * never registering) so the caller can warn with the right cause. + * + * Uses a monotonic `performance.now()` deadline rather than wall-clock `Date.now()`: this runs + * during OS cold boot, exactly when the wall clock gets stepped (fresh boot / dual-boot RTC skew / + * VM resume), which would otherwise make the loop give up early or overrun its budget. + */ +async function requestSessionSyncWithBootRetry( + signals?: StartupTasksSignals, +): Promise { + const deadline = performance.now() + STARTUP_SYNC_RETRY_BUDGET_MS; + let attempt = 0; + for (;;) { + // Stop before firing if the app is quitting: a late fire could run `('startup')` after + // `('shutdown')` already fired and would try to reach a network connection being torn down + // (network.service `initialize` refuses to reconnect post-shutdown as a backstop). + if (signals?.abortSignal?.aborted) return 'aborted'; + + // Freshness gate, checked BEFORE firing because firing is what raises the editing-block: if the + // window has been interactive long enough that the user is likely editing, drop a still-pending + // startup trigger rather than block them (see STARTUP_SYNC_FRESHNESS_WINDOW_MS). + const windowInteractiveMs = signals?.getWindowInteractiveElapsedMs?.(); + if ( + windowInteractiveMs !== undefined && + windowInteractiveMs >= STARTUP_SYNC_FRESHNESS_WINDOW_MS + ) + return 'skipped-stale'; + + attempt += 1; + try { + // Intentionally awaiting inside the loop so we attempt once at a time (mirrors + // `requestWithRetry` in rpc.model.ts). + // eslint-disable-next-line no-await-in-loop + const result = await networkService.requestNoRetry< + [SessionSyncBoundary], + ScheduledSessionSyncResult | undefined + >(RUN_SCHEDULED_SESSION_SYNC_REQUEST_TYPE, 'startup'); + // Tolerate a legacy void resolution (an older extension that returned `Promise`): treat + // a missing result as a completed sync. + return result ?? 'synced'; + } catch (e) { + if (!isRetryableBootRaceError(e)) throw e; + if (performance.now() >= deadline) throw e; + + logger.debug( + `Power-mode startup sync: runScheduledSessionSync not answering on attempt ${attempt}; retrying`, + ); + const intervalMs = + attempt <= INITIAL_RETRY_ATTEMPTS ? INITIAL_RETRY_INTERVAL_MS : EXTENDED_RETRY_INTERVAL_MS; + // Intentionally awaiting inside the loop so we wait a bit before retrying. + // eslint-disable-next-line no-await-in-loop + await wait(intervalMs); + } + } +} diff --git a/src/shared/data/rpc.model.ts b/src/shared/data/rpc.model.ts index 39b37349725..9886754599f 100644 --- a/src/shared/data/rpc.model.ts +++ b/src/shared/data/rpc.model.ts @@ -13,10 +13,22 @@ import { deserialize, getErrorMessage, serialize, wait } from 'platform-bible-ut /** Port to use for the WebSocket */ export const WEBSOCKET_PORT = 8876; -/** How many times to try sending a request before giving up if the request is not yet registered */ -const MAX_REQUEST_ATTEMPTS = 10; -/** How long in ms to wait between request attempts if the request is not yet registered */ -const REQUEST_ATTEMPT_WAIT_TIME_MS = 1000; +/** + * How many times to try sending a request before giving up if the request is not yet registered. + * Exported so callers that layer their own retry policy on top of {@link requestWithRetry}'s cadence + * (e.g. the Power-mode startup sync's boot-race loop) can derive from this shared policy instead of + * re-declaring the literal and silently diverging if it is ever retuned. + * + * @experimental + */ +export const MAX_REQUEST_ATTEMPTS = 10; +/** + * How long in ms to wait between request attempts if the request is not yet registered. Exported + * for the same derive-don't-duplicate reason as {@link MAX_REQUEST_ATTEMPTS}. + * + * @experimental + */ +export const REQUEST_ATTEMPT_WAIT_TIME_MS = 1000; /** * Whether an RPC object is setting up or has finished setting up its connection and is ready to @@ -256,3 +268,31 @@ export const GET_METHODS = 'rpc.discover'; /** Prefix on requests that indicates that the request is a command */ export const CATEGORY_COMMAND = 'command'; + +/** + * Builds the exact prefix that `network.service`'s `doRequest` embeds in the message it throws for + * a JSON-RPC _error response_ with the given `code` — the full thrown message is this prefix + * followed by `: `. + * + * Exported so the few callers that must classify these thrown errors by message (there is no richer + * machine-readable marker for a "method not found" response) derive the format from this single + * producer instead of hand-copying the literal. Hand-copied copies silently drift: reformat the + * producer and a separate matcher/fixture keeps matching its old string while real errors stop + * matching, and the tests stay green. Everything routing through this function stays in lockstep. + * + * @param code The JSON-RPC error code from the error response being classified + * @returns The exact message prefix `doRequest` uses for an error response with that `code` + * @experimental + */ +export function getJsonRpcRequestErrorMessagePrefix(code: number): string { + return `JSON-RPC Request error (${code})`; +} + +/** + * Prefix that `network.service`'s `doRequest` embeds in the message it throws when a request times + * out client-side before any response arrives. Exported for the same drift-prevention reason as + * {@link getJsonRpcRequestErrorMessagePrefix}. + * + * @experimental + */ +export const JSON_RPC_REQUEST_TIMED_OUT_MESSAGE_PREFIX = 'JSON-RPC Request timed out:'; diff --git a/src/shared/services/network.service.test.ts b/src/shared/services/network.service.test.ts new file mode 100644 index 00000000000..2d1e29ece0f --- /dev/null +++ b/src/shared/services/network.service.test.ts @@ -0,0 +1,89 @@ +import { vi } from 'vitest'; +import { createRpcHandler } from '@shared/services/rpc-handler.factory'; + +vi.mock('@shared/services/rpc-handler.factory', () => ({ + createRpcHandler: vi.fn(), +})); + +vi.mock('@shared/services/shared-store.service', () => ({ + sharedStoreService: { + get: vi.fn(), + set: vi.fn(), + remove: vi.fn(), + isInitialized: vi.fn().mockReturnValue(true), + }, +})); + +vi.mock('@shared/services/logger.service', () => ({ + logger: { debug: vi.fn(), info: vi.fn(), warn: vi.fn(), error: vi.fn() }, +})); + +const mockCreateRpcHandler = vi.mocked(createRpcHandler); + +/** Minimal fake RPC handler so `initialize()` can succeed where a test needs a live connection. */ +function fakeRpcHandler() { + // The service only touches the members below in these tests; the cast keeps the fake minimal + // instead of implementing the full IRpcMethodRegistrar surface. + // eslint-disable-next-line no-type-assertion/no-type-assertion + return { + connect: vi.fn().mockResolvedValue(true), + disconnect: vi.fn().mockResolvedValue(undefined), + request: vi.fn(), + registerMethod: vi.fn(), + unregisterMethod: vi.fn(), + registerEvent: vi.fn(), + unregisterEvent: vi.fn(), + } as unknown as Awaited>; +} + +/** + * `hasShutDown` and `jsonRpc` are module-level state, so re-import a fresh copy of the service for + * every test rather than letting one test's shutdown latch leak into the next. + */ +async function importNetworkService() { + return import('@shared/services/network.service'); +} + +beforeEach(() => { + vi.resetModules(); + vi.clearAllMocks(); + mockCreateRpcHandler.mockResolvedValue(fakeRpcHandler()); +}); + +// The shutdown latch is the backstop that stops a late boot-race request (e.g. the Power-mode +// startup sync retry loop) from resurrecting a torn-down connection mid-quit. These tests pin the +// ordering it depends on: `shutdown()` sets the latch before anything else, and `initialize()` +// checks it before creating a connection. +describe('network service shutdown latch', () => { + it('refuses to initialize after shutdown() has begun (never initialized before)', async () => { + const networkService = await importNetworkService(); + + await networkService.shutdown(); + + await expect(networkService.initialize()).rejects.toThrow(/shut down/); + expect(mockCreateRpcHandler).not.toHaveBeenCalled(); + }); + + it('rejects a request issued after shutdown() instead of resurrecting the connection', async () => { + const networkService = await importNetworkService(); + + await networkService.shutdown(); + + await expect(networkService.requestNoRetry('command:test.command')).rejects.toThrow( + /shut down/, + ); + expect(mockCreateRpcHandler).not.toHaveBeenCalled(); + }); + + it('refuses to re-initialize a connection that was already torn down', async () => { + const networkService = await importNetworkService(); + + await networkService.initialize(); + expect(mockCreateRpcHandler).toHaveBeenCalledTimes(1); + + await networkService.shutdown(); + + await expect(networkService.initialize()).rejects.toThrow(/shut down/); + expect(mockCreateRpcHandler).toHaveBeenCalledTimes(1); + }); +}); diff --git a/src/shared/services/network.service.ts b/src/shared/services/network.service.ts index 7b4cd188195..0019fad2e2c 100644 --- a/src/shared/services/network.service.ts +++ b/src/shared/services/network.service.ts @@ -9,7 +9,9 @@ import { EventHandler, fixupResponse, GET_METHODS, + getJsonRpcRequestErrorMessagePrefix, InternalRequestHandler, + JSON_RPC_REQUEST_TIMED_OUT_MESSAGE_PREFIX, } from '@shared/data/rpc.model'; import { AsyncVariable, @@ -86,11 +88,23 @@ const handleEventFromNetwork: EventHandler = (eventType: string, event: T) => const connectionMutex = new Mutex(); let jsonRpc: IRpcMethodRegistrar | undefined; +// Set once {@link shutdown} has begun so {@link initialize} refuses to re-open a torn-down +// connection. `jsonRpc` alone can't distinguish "not initialized yet" from "already shut down" — +// both leave it `undefined` — so a late request after shutdown would otherwise re-connect. +let hasShutDown = false; export async function initialize(): Promise { if (jsonRpc) return; + // Once shutdown has begun (app quit), never re-open the connection. Without this a request still + // in flight at quit — e.g. the Power-mode startup boot-race retry loop — would reach + // `doRequest` -> `initialize()` after `shutdown()` set `jsonRpc = undefined`, and the `if (jsonRpc)` + // guards below would be false, so it would call `createRpcHandler()`/`connect()` again and + // resurrect the connection mid-quit. + if (hasShutDown) throw new Error('Network service has shut down; not reconnecting'); await connectionMutex.runExclusive(async () => { if (jsonRpc) return; + // Re-check inside the mutex in case shutdown ran while we awaited it. + if (hasShutDown) throw new Error('Network service has shut down; not reconnecting'); try { jsonRpc = await createRpcHandler(); @@ -105,6 +119,9 @@ export async function initialize(): Promise { /** Closes the network services gracefully */ export const shutdown = async () => { + // Mark shutdown as begun before anything else so a concurrent {@link initialize} can't race in and + // re-open the connection we're about to tear down. + hasShutDown = true; if (!jsonRpc) return; await connectionMutex.runExclusive(async () => { if (!jsonRpc) return; @@ -255,13 +272,13 @@ async function doRequest, TReturn>( if (isJsonRpcResponse(response)) { if (!response.error) return response.result; platformErrorCode = response.error.data?.data?.platformErrorCode; - response = `JSON-RPC Request error (${response.error.code}): ${response.error.message}`; + response = `${getJsonRpcRequestErrorMessagePrefix(response.error.code)}: ${response.error.message}`; } else if (isPlatformError(response)) { logger.debug(response.message); throw response; } else { response = responseAsyncVariable.hasTimedOut - ? `JSON-RPC Request timed out: ${requestType} ${JSON.stringify(args)}` + ? `${JSON_RPC_REQUEST_TIMED_OUT_MESSAGE_PREFIX} ${requestType} ${JSON.stringify(args)}` : `Invalid JSON-RPC Response: ${response}`; } logger.debug(response);