diff --git a/README.md b/README.md index be746840..16359998 100644 --- a/README.md +++ b/README.md @@ -215,7 +215,7 @@ await esbuild.build({ ## Available Features -- **Sessions** — Session-based event grouping +- **Sessions** — Session-based event grouping, with [sampling](#sampling) and error-session capture - **RUM Views** — One view per main process instance - **RUM Errors** — Capture Node errors and crashes in main process, with sourcemap-ready stacks - **RUM Resources** — Capture RUM resources from main process network calls @@ -373,22 +373,77 @@ before the logout still resolve to the user who was logged in then. ### Configuration Options -| Option | Type | Required | Default | Description | -| ----------------------------- | ---------------------------------------- | -------- | ------------------------ | -------------------------------------------------------------------------------------------------------------------------------------- | -| `clientToken` | `string` | Yes | — | FlashCat client token | -| `applicationId` | `string` | Yes | — | RUM application ID | -| `site` | `string` | No | `browser.flashcat.cloud` | Intake host, used verbatim — e.g. `browser.flashcat.cloud` (production), `jira.flashcat.cloud` (staging), or your own host | -| `service` | `string` | Yes | — | Service name | -| `env` | `string` | No | — | Application environment | -| `version` | `string` | No | — | Application version | -| `telemetrySampleRate` | `number` | No | `20` | Telemetry sample rate (0–100) | -| `batchSize` | `'SMALL' \| 'MEDIUM' \| 'LARGE'` | No | — | Batch size for event uploads | -| `uploadFrequency` | `'RARE' \| 'NORMAL' \| 'FREQUENT'` | No | — | Upload frequency for event batches | -| `defaultPrivacyLevel` | `'mask' \| 'allow' \| 'mask-user-input'` | No | `'mask'` | Default privacy level for renderer session replay | -| `allowedWebViewHosts` | `string[]` | No | `[]` | Extra hostnames allowed for the renderer bridge (the window's own host is always allowed) | -| `proxy` | `string` | No | — | Proxy URL to upload through instead of `site`. See [Self-hosted deployments](#self-hosted-deployments) | -| `normalizeStackPaths` | `boolean` | No | `true` | Rewrite stack frame paths to `app:///`. See [Error stacks and sourcemaps](#error-stacks-and-sourcemaps) | -| `correctPrewarmedViewTimings` | `boolean` | No | `true` | Rebase FCP/LCP of pre-warmed windows onto the moment they became visible. See [Pre-warmed windows](#pre-warmed-windows) | +| Option | Type | Required | Default | Description | +| ----------------------------- | ---------------------------------------- | -------- | ------------------------ | ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| `clientToken` | `string` | Yes | — | FlashCat client token | +| `applicationId` | `string` | Yes | — | RUM application ID | +| `site` | `string` | No | `browser.flashcat.cloud` | Intake host, used verbatim — e.g. `browser.flashcat.cloud` (production), `jira.flashcat.cloud` (staging), or your own host | +| `service` | `string` | Yes | — | Service name | +| `env` | `string` | No | — | Application environment | +| `version` | `string` | No | — | Application version | +| `sessionSampleRate` | `number` | No | `100` | Percentage of sessions collected (0–100). An out-of-range value fails `init`. See [Sampling](#sampling) | +| `sessionOnError` | `boolean` | No | `false` | Keeps the sessions `sessionSampleRate` did not draw in memory; a withheld session uploads no RUM events unless it reports an error, not even at quit. See [Sampling](#sampling) | +| `telemetrySampleRate` | `number` | No | `20` | Telemetry sample rate (0–100) | +| `batchSize` | `'SMALL' \| 'MEDIUM' \| 'LARGE'` | No | — | Batch size for event uploads | +| `uploadFrequency` | `'RARE' \| 'NORMAL' \| 'FREQUENT'` | No | — | Upload frequency for event batches | +| `defaultPrivacyLevel` | `'mask' \| 'allow' \| 'mask-user-input'` | No | `'mask'` | Default privacy level for renderer session replay | +| `allowedWebViewHosts` | `string[]` | No | `[]` | Extra hostnames allowed for the renderer bridge (the window's own host is always allowed) | +| `proxy` | `string` | No | — | Proxy URL to upload through instead of `site`. See [Self-hosted deployments](#self-hosted-deployments) | +| `normalizeStackPaths` | `boolean` | No | `true` | Rewrite stack frame paths to `app:///`. See [Error stacks and sourcemaps](#error-stacks-and-sourcemaps) | +| `correctPrewarmedViewTimings` | `boolean` | No | `true` | Rebase FCP/LCP of pre-warmed windows onto the moment they became visible. See [Pre-warmed windows](#pre-warmed-windows) | + +### Sampling + +`sessionSampleRate` is drawn once per session, in the main process, and decides for the renderers +too: their events reach the intake through the main process, which drops those of a session it did +not draw. A session resumed after a restart keeps the decision it was created with, and reports the +rate it was drawn at. A renderer's own `sessionSampleRate` does not apply to the events it sends over +the bridge: the main process decides, and its rate is what every event reports. + +`sessionOnError` keeps the sessions the rate did not draw on standby instead of dropping them: + +- The session's events — main process and renderers alike — are held in memory: up to 60 seconds + of what preceded the error, subject to the limits (64 KiB of detail, 200 events, plus up to 50 + views). The buffer itself never touches the disk; what is persisted locally is the session's + state and the main-process view identifiers, which a native crash needs to be attributed on the + next launch. A withheld session uploads no RUM events unless it reports an error — not even at + quit. +- At the session's first error, what is held is handed to the upload batch together with the error, + 0–3 s later (spread per session, so that one outage does not make every client upload at once), + and the session then reports as it happens, like any drawn session. When the application may be + about to exit, a release already earned is written to disk before returning instead: on an + uncaught exception in the main process (provided the application's own `uncaughtException` + listener is registered after `await init(...)` has completed, so that the SDK's runs first), on + `before-quit` and `will-quit`, and on the process `exit` event, which `process.exit()` and + `app.exit()` still run. Queued events are written synchronously at each of these points, and + once the exit event has started every later event is written as it arrives; an asynchronous + append already in progress is not completed by the drain. A listener registered _before_ + `init()` that ends the process synchronously pre-empts the SDK's: nothing of that error is seen. +- A session that ends without an error is thrown away whole, late events included. + +Only errors the application reports count: an error a renderer's `beforeSend` dropped, or one the +SDK reports about itself, does not. A native crash counts too: it is reported on the next launch, +when the session's held events are long gone, so the crash comes with the view it happened in and +nothing before it. + +Such a session reports `session.sampled_for_error: true` on its views and a +`_dd.configuration.session_sample_rate` of `0` on every RUM event, so that it is counted as itself +rather than extrapolated by the rate. + +```ts +await init({ + // ... + sessionSampleRate: 0, // no session is collected unconditionally… + sessionOnError: true, // …but every session that reports an error is +}); +``` + +> **Session Replay is not withheld.** The renderer uploads its replay itself, past the main process. +> For a session the rate did not draw, renderers are told there is no session, so they record +> nothing. A session kept by `sessionOnError` cannot be hidden from them that way — its renderer +> events must reach the main process to be held — so with `sessionReplayDirectUpload` on, its replay +> is uploaded whether or not the session ever reports an error. Do not combine the two until the +> Browser SDK can withhold replay for a bridged session. ### Pre-warmed windows diff --git a/docs/ARCHITECTURE.md b/docs/ARCHITECTURE.md index d9e6fbf7..b8b961d4 100644 --- a/docs/ARCHITECTURE.md +++ b/docs/ARCHITECTURE.md @@ -17,7 +17,7 @@ graph TB end end - DD[(Datadog)] + DD[(FlashCat RUM ingest)] %% Browser SDK → Electron SDK via bridge BP -->|"RUM events
(IPC bridge)"| SDK @@ -28,7 +28,7 @@ graph TB %% Electron SDK internal sources SDK -->|"span → resource conversion
RUM data collection
RUM APIs
session + main process view"| SDK - %% Electron SDK → Datadog + %% Electron SDK → FlashCat RUM ingest SDK -->|"enriched events
(HTTP)"| DD %% Styling @@ -45,7 +45,7 @@ graph TB ### Main Process -The Electron SDK captures RUM sessions, collects RUM events, and forwards them to Datadog, enriching events from dd-trace and the Browser SDK with RUM and Electron context along the way. dd-trace instruments network requests, command executions, and IPC calls, then forwards spans to the Electron SDK through the `diagnostics_channel`. +The Electron SDK captures RUM sessions, collects RUM events, and forwards them to the FlashCat RUM ingest, enriching events from dd-trace and the Browser SDK with RUM and Electron context along the way. dd-trace instruments network requests, command executions, and IPC calls, then forwards spans to the Electron SDK through the `diagnostics_channel`. More details in the [How tracing works](#how-tracing-works) section. @@ -75,6 +75,7 @@ flowchart LR end subgraph Transport + WB[WithheldEventBuffer] BM[BatchManager] BP[BatchProducer] BC[BatchConsumer] @@ -83,10 +84,12 @@ flowchart LR RUM -- RawRumEvent --> COMBINE TEL -- RawTelemetryEvent --> COMBINE CC -. "application.id, service, ..." .-> HOOKS - SC -. "session.id" .-> HOOKS + SC -. "session.id, sampling" .-> HOOKS VC -. "view.id, view.name, ..." .-> HOOKS HOOKS --> COMBINE - COMBINE -- ServerEvent --> BM + COMBINE -- "ServerEvent (RUM)" --> WB + COMBINE -- "ServerEvent (telemetry)" --> BM + WB -- "released / not withheld" --> BM BM --> BP BM --> BC BP -. "write" .-> DISK[Disk] @@ -94,6 +97,29 @@ flowchart LR BC -. "send" .-> INT[HTTP intake] ``` +### Sampling and withheld sessions + +`SessionManager` draws each session once (`sessionSampleRate`, then `sessionOnError` for what the +rate missed) and persists the result, with the rate it was drawn at, with the session — in `_dd_s` +and in the session history — so a resumed session and a crash reported on the next launch are +judged, and reported, by the draw they were made under. +`SessionContext`'s RUM hook turns the draw into event attributes: it discards the events of a session +not drawn, and of a withheld session that ended without an error (its late events), and stamps +`session.sampled_for_error` and `_dd.configuration.session_sample_rate`. + +`WithheldEventBuffer` sits between assembly and the RUM batch, so it sees main-process and renderer +events alike, already final. It holds a withheld session's events and releases them at the session's +first error; telemetry bypasses it. `CrashCollection` releases the session of a crash reported on the +next launch itself, rebuilding the crashed view from the view history. When the application may be +about to exit (`APP_MAY_EXIT`: an uncaught exception in the main process, `before-quit`, `will-quit`, +and the process `exit` event), the buffer releases what has earned its release and `Transport` then +writes every queued event, and the session state, before returning, since the batch otherwise writes +on later turns of the event loop; an append already issued is not completed synchronously. Each pass +writes only what arrived since the one before, so an error reported between two of them is taken +along by the next; and once the process `exit` event has started — the last pass, after which +nothing runs — every event is released and written as it arrives. The session state and history files are replaced whole, through a temp file and a +rename, in the order the writes were requested (`StateFile`). See the JSDoc of each class. + ### Event Manager The `EventManager` provides a handler-based pipeline for processing events. @@ -254,7 +280,7 @@ Two pieces close it, and the order between them is what makes it work: `init-order.scenario.ts` pins both down — a window opened before the SDK is ready, and an application that never initializes at all. -**`''` is load-bearing, and is not the same as not implementing the getter.** The Browser SDK reads an empty answer as "the host has no session right now" and stops attributing data until the host answers with an id again; it only falls back to its own placeholder session id for a host too old to implement `getSessionId()` at all. That distinction is what keeps Session Replay off a fake session: the renderer uploads its segments itself instead of handing them to the main process, so nothing here can discard them after the fact, and a placeholder id is a constant every application built on this SDK would share. It also means the main process must never answer with the id an expired session used to have — that would attach segments to a session that has ended. `getActiveSessionId` in `src/index.ts` answers `''` for anything but an active session, and `bridge-window.scenario.ts` pins both the expiry and the renewal down. +**`''` is load-bearing, and is not the same as not implementing the getter.** The Browser SDK reads an empty answer as "the host has no session right now" and stops attributing data until the host answers with an id again; it only falls back to its own placeholder session id for a host too old to implement `getSessionId()` at all. That distinction is what keeps Session Replay off a fake session: the renderer uploads its segments itself instead of handing them to the main process, so nothing here can discard them after the fact, and a placeholder id is a constant every application built on this SDK would share. It also means the main process must never answer with the id an expired session used to have — that would attach segments to a session that has ended. `getActiveSessionId` in `src/index.ts` answers `''` for anything but an active session, and `bridge-window.scenario.ts` pins both the expiry and the renewal down. It answers `''` for a session the sampling draw did not keep, too, which is what keeps the renderer from recording it; a session withheld by `sessionOnError` is answered with its id, since its renderer events have to reach the main process — so the renderer's replay of such a session is not withheld (see README, Sampling). See `src/preload/`, `src/bridge/BridgeHandler.ts`, `src/domain/AnonymousId.ts`, `src/assembly/commonContext.ts`, `src/domain/tracing/`, `src/entries/instrument.ts`, `src/entries/vite-plugin.ts`, `src/entries/webpack-plugin.ts`, and `src/entries/esbuild-plugin.ts`. diff --git a/e2e/app/src/bridge-window.ts b/e2e/app/src/bridge-window.ts index 01274e6d..fa2c53ab 100644 --- a/e2e/app/src/bridge-window.ts +++ b/e2e/app/src/bridge-window.ts @@ -8,6 +8,9 @@ flashcatRum.init({ trackResources: true, trackLongTasks: true, trackUserInteractions: true, + // Lets a scenario report an error that `beforeSend` drops, which must not count as the session's + // error anywhere downstream. + beforeSend: (event) => !(event.type === 'error' && event.error.message.includes('dropped-by-beforeSend')), }); document.getElementById('status')!.textContent = 'bridge-ready'; diff --git a/e2e/app/src/global.d.ts b/e2e/app/src/global.d.ts index 14b3272d..a6ef7cda 100644 --- a/e2e/app/src/global.d.ts +++ b/e2e/app/src/global.d.ts @@ -10,6 +10,11 @@ declare global { generateTelemetryErrors: (count: number) => Promise; stopSession: () => Promise; generateUncaughtException: () => Promise; + generateUncaughtExceptionAndExit: () => Promise; + generateManualErrorAndExit: () => Promise; + generateManualErrorOnWillQuit: () => Promise; + generateManualErrorAndAppExit: () => Promise; + generateManualErrorOnProcessExit: () => Promise; generateUnhandledRejection: () => Promise; generateManualError: (startTime?: number) => Promise; crash: () => Promise; diff --git a/e2e/app/src/main.ts b/e2e/app/src/main.ts index 198b6a1b..661a570d 100644 --- a/e2e/app/src/main.ts +++ b/e2e/app/src/main.ts @@ -114,6 +114,40 @@ void app.whenReady().then(async () => { }); }); + // What many applications do: end the process on an uncaught exception. Registered after the + // SDK's own listener, so the SDK gets its turn first — and only that turn. + ipcMain.handle('generateUncaughtExceptionAndExit', () => { + process.on('uncaughtException', () => process.exit(1)); + setTimeout(() => { + throw new Error('test uncaught exception before exit'); + }); + }); + + // An error reported in the same turn as process.exit(): only the 'exit' listeners run after it. + ipcMain.handle('generateManualErrorAndExit', () => { + addError(new Error('manual error before process.exit')); + process.exit(1); + }); + + // An error reported while quitting, from a listener registered after the SDK's. + ipcMain.handle('generateManualErrorOnWillQuit', () => { + app.on('will-quit', () => addError(new Error('manual error on will-quit'))); + app.quit(); + }); + + // An error reported from the host's own exit listener, registered after the SDK's: it runs after + // the SDK's drain, and nothing at all runs after it. + ipcMain.handle('generateManualErrorOnProcessExit', () => { + process.on('exit', () => addError(new Error('manual error on process exit'))); + process.exit(1); + }); + + // app.exit() skips the quit events; what it leaves the SDK is what this scenario pins. + ipcMain.handle('generateManualErrorAndAppExit', () => { + addError(new Error('manual error before app.exit')); + app.exit(1); + }); + ipcMain.handle('generateUnhandledRejection', () => { void Promise.reject(new Error('test unhandled rejection')); }); diff --git a/e2e/app/src/preload.ts b/e2e/app/src/preload.ts index 4a6eafdb..def8fbf3 100644 --- a/e2e/app/src/preload.ts +++ b/e2e/app/src/preload.ts @@ -12,6 +12,11 @@ contextBridge.exposeInMainWorld('electronAPI', { getUser: () => ipcRenderer.invoke('getUser'), clearUser: () => ipcRenderer.invoke('clearUser'), generateUncaughtException: () => ipcRenderer.invoke('generateUncaughtException'), + generateUncaughtExceptionAndExit: () => ipcRenderer.invoke('generateUncaughtExceptionAndExit'), + generateManualErrorAndExit: () => ipcRenderer.invoke('generateManualErrorAndExit'), + generateManualErrorOnWillQuit: () => ipcRenderer.invoke('generateManualErrorOnWillQuit'), + generateManualErrorAndAppExit: () => ipcRenderer.invoke('generateManualErrorAndAppExit'), + generateManualErrorOnProcessExit: () => ipcRenderer.invoke('generateManualErrorOnProcessExit'), generateUnhandledRejection: () => ipcRenderer.invoke('generateUnhandledRejection'), generateManualError: (startTime?: number) => ipcRenderer.invoke('generateManualError', startTime), startOperation: (name: string, options?: Record) => diff --git a/e2e/lib/bridgeWindowPage.ts b/e2e/lib/bridgeWindowPage.ts index 025ba47f..39bd740c 100644 --- a/e2e/lib/bridgeWindowPage.ts +++ b/e2e/lib/bridgeWindowPage.ts @@ -7,6 +7,7 @@ interface BridgeWindow { getSessionId: () => string; getAnonymousId: () => string; getUser: () => string; + send: (msg: string) => void; }; } @@ -24,6 +25,14 @@ export class BridgeWindowPage { return new BridgeWindowPage(page); } + /** Hands the bridge a raw envelope, as a page script could. */ + async sendRaw(envelope: Record) { + await this.page.evaluate( + (json) => (globalThis as unknown as BridgeWindow).DatadogEventBridge.send(json), + JSON.stringify(envelope) + ); + } + async generateError(message: string) { await this.page.evaluate((msg) => { setTimeout(() => { diff --git a/e2e/lib/helpers.ts b/e2e/lib/helpers.ts index 93d1dd7c..46b3cf4c 100644 --- a/e2e/lib/helpers.ts +++ b/e2e/lib/helpers.ts @@ -49,6 +49,8 @@ export interface TestFixtures { intake: Intake; testServer: TestServer; rumBrowserSdk: Record | null; + /** Merged over the SDK configuration every scenario starts from. */ + sdkConfig: Partial; } /** @@ -78,9 +80,9 @@ export const test = base.extend({ { option: true }, ], - electronApp: async ({ intake, rumBrowserSdk }, use) => { + electronApp: async ({ intake, rumBrowserSdk, sdkConfig }, use) => { const userDataDir = await createUserDataDir(); - const electronApp = await launchApp(intake, userDataDir, rumBrowserSdk); + const electronApp = await launchApp(intake, userDataDir, rumBrowserSdk, 'await', sdkConfig); await use(electronApp); await electronApp.close(); await cleanupUserDataDir(userDataDir); @@ -99,6 +101,7 @@ export const test = base.extend({ }, rumBrowserSdk: [null, { option: true }], + sdkConfig: [{}, { option: true }], }); /** How the test app sequences `init()` against window creation. See `getInitMode` in its main.ts. */ @@ -108,7 +111,8 @@ async function launchApp( intake: Intake, userDataDir: string, rumBrowserSdk: Record | null = null, - initMode: InitMode = 'await' + initMode: InitMode = 'await', + sdkConfig: Partial = {} ): Promise { const env: Record = { FC_ELECTRON_SDK_INIT_MODE: initMode }; for (const key of HOST_ENV_ALLOWLIST) { @@ -136,6 +140,7 @@ async function launchApp( telemetrySampleRate: 100, defaultPrivacyLevel: 'mask', allowedWebViewHosts: [], + ...sdkConfig, }; env.FC_ELECTRON_SDK_CONFIG = JSON.stringify(electronSdkConfig); @@ -169,9 +174,10 @@ async function waitForWindowLoaded(electronApp: ElectronApplication): Promise<{ export async function launchAppManually( intake: Intake, userDataDir: string, - initMode: InitMode = 'await' + initMode: InitMode = 'await', + sdkConfig: Partial = {} ): Promise<{ electronApp: ElectronApplication; window: Page; mainPage: MainPage }> { - const electronApp = await launchApp(intake, userDataDir, null, initMode); + const electronApp = await launchApp(intake, userDataDir, null, initMode, sdkConfig); const { window } = await waitForWindowLoaded(electronApp); return { electronApp, window, mainPage: new MainPage(window) }; } diff --git a/e2e/lib/intake.ts b/e2e/lib/intake.ts index 651b594b..9441fa76 100644 --- a/e2e/lib/intake.ts +++ b/e2e/lib/intake.ts @@ -7,15 +7,19 @@ import * as http from 'node:http'; * `ddforward` query parameter carries the intake path the SDK would have used without a proxy, * so asserting on it is equivalent to asserting on the real request path. * - * Beyond storing events, this server validates the wire contract the FlashCat intake enforces. - * The real intake answers a breach with `400`, which the SDK retries forever — so a test that - * only looked at the parsed events could stay green while nothing was ever ingested. Breaches - * are therefore recorded and asserted explicitly by `intake-contract.scenario.ts`: + * Beyond storing events, this server validates the wire contract the FlashCat intake enforces, + * since a test that only looked at the parsed events could stay green while nothing was ever + * ingested. Breaches are recorded and asserted explicitly by `intake-contract.scenario.ts`. The + * real intake answers the request-level ones with `400`, which the SDK retries forever: * * - path is `/api/v2/rum` (the only track FlashCat exposes — there is no `/api/v2/spans`) * - `Content-Type: text/plain;charset=UTF-8` (`application/json` is rejected) * - body is newline-delimited JSON, one event per line (a JSON array is rejected) - * - every number is a whole number, except the few fields the intake really types as floats + * + * The event-level one it does not answer at all — the `202` is sent before the events are + * decoded, and an event that fails to decode is dropped silently: + * + * - every value at a path the intake decodes as an integer is a whole number */ export interface ReceivedEvent { timestamp: number; @@ -34,46 +38,124 @@ const RUM_TRACK_PATH = '/api/v2/rum'; const EXPECTED_CONTENT_TYPE = 'text/plain'; /** - * Event fields the intake decodes into a floating-point type. Everything else numeric is an - * `int64` over there, and Go's JSON decoder refuses a fractional number into an integer — it - * fails the whole event, silently, because the `202` is returned before decoding. + * The event fields the intake decodes as integers, by JSON path, per event type: anything but a + * whole number there — a fraction, a string, a boolean — fails the whole event on the real intake, + * silently, since the `202` is sent before decoding. A JavaScript mock parses such an event + * happily, so without this check the suite stays green while nothing is ingested. Only these paths + * are looked at; free-form attributes are stored as they are. * - * JavaScript has no such boundary, so a float slips through this mock unnoticed unless it is - * checked for explicitly. That is exactly how a fractional `date` (`fs.Stats.birthtimeMs` carries - * sub-millisecond precision) kept every native crash out of Error Tracking up to v0.1.0 while - * every test stayed green. - * - * Taken from `fc-rum/types/datadog/rum.go` — `grep 'float64 \`json:'`. + * A mirror of `src/tools/intakeNumbers.ts` — the e2e project cannot import `src` — taken from the + * integer-typed fields of the event structs for the six intake-supported types in + * `fc-rum/types/datadog/rum.go`, with Go's shadowing of embedded fields applied; `[]` stands for + * each element of an array, `*` for each value of a map. */ -const FRACTIONAL_FIELDS = new Set([ - 'average', - 'cpu_ticks_count', - 'cpu_ticks_per_second', - 'cumulative_layout_shift', - 'custom', - 'execution_start', - 'freeze_rate', - 'height', - 'max', - 'max_depth', - 'max_depth_scroll_top', - 'max_scroll_height', - 'memory_average', - 'memory_max', - 'metric_max', - 'min', - 'refresh_rate_average', - 'refresh_rate_min', - 'render_start', - 'rule_psr', - 'score', - 'session_replay_sample_rate', - 'session_sample_rate', - 'slow_frames_rate', - 'width', - 'x', - 'y', -]); +const COMMON = ['_dd.format_version', 'date']; +// Every event type declares its own `_dd`; only the view's lacks a `session`. +const SESSION_PLAN = '_dd.session.plan'; + +const INTAKE_INTEGER_PATHS: Record = { + action: [ + ...COMMON, + SESSION_PLAN, + '_dd.action.target.height', + '_dd.action.target.width', + 'action.crash.count', + 'action.error.count', + 'action.loading_time', + 'action.long_task.count', + 'action.resource.count', + ], + error: [...COMMON, SESSION_PLAN, 'error.resource.status_code', 'error.time_since_app_start', 'freeze.duration'], + long_task: [ + ...COMMON, + SESSION_PLAN, + 'long_task.blocking_duration', + 'long_task.duration', + 'long_task.first_ui_event_timestamp', + 'long_task.scripts[].duration', + 'long_task.scripts[].forced_style_and_layout_duration', + 'long_task.scripts[].pause_duration', + 'long_task.scripts[].source_char_position', + 'long_task.scripts[].start_time', + 'long_task.start_time', + 'long_task.style_and_layout_start', + ], + resource: [ + ...COMMON, + SESSION_PLAN, + 'resource.connect.duration', + 'resource.connect.start', + 'resource.decoded_body_size', + 'resource.dns.duration', + 'resource.dns.start', + 'resource.download.duration', + 'resource.download.start', + 'resource.duration', + 'resource.encoded_body_size', + 'resource.first_byte.duration', + 'resource.first_byte.start', + 'resource.redirect.duration', + 'resource.redirect.start', + 'resource.size', + 'resource.ssl.duration', + 'resource.ssl.start', + 'resource.status_code', + 'resource.transfer_size', + 'resource.worker.duration', + 'resource.worker.start', + ], + view: [ + ...COMMON, + '_dd.document_version', + '_dd.page_states[].start', + '_dd.replay_stats.records_count', + '_dd.replay_stats.segments_count', + '_dd.replay_stats.segments_total_raw_size', + 'display.scroll.max_scroll_height_time', + 'view.action.count', + 'view.app_launch', + 'view.crash.count', + 'view.cumulative_layout_shift_time', + 'view.custom_timings.*', + 'view.dom_complete', + 'view.dom_content_loaded', + 'view.dom_interactive', + 'view.error.count', + 'view.evaluate_script', + 'view.first_byte', + 'view.first_contentful_paint', + 'view.first_input_delay', + 'view.first_input_time', + 'view.first_render', + 'view.frozen_frame.count', + 'view.frustration.count', + 'view.in_foreground_periods[].duration', + 'view.in_foreground_periods[].start', + 'view.interaction_to_next_paint', + 'view.interaction_to_next_paint_time', + 'view.interaction_to_next_view_time', + 'view.largest_contentful_paint', + 'view.load_event', + 'view.loading_time', + 'view.long_task.count', + 'view.network_settled_time', + 'view.onload_to_onshow', + 'view.onshow_to_onready', + 'view.performance.cls.timestamp', + 'view.performance.fcp.timestamp', + 'view.performance.fid.duration', + 'view.performance.fid.timestamp', + 'view.performance.inp.duration', + 'view.performance.inp.timestamp', + 'view.performance.lcp.timestamp', + 'view.resource.count', + 'view.setdata.count', + 'view.setdata.duration', + 'view.slow_frame.count', + 'view.time_spent', + ], + vital: [...COMMON, SESSION_PLAN, 'vital.duration'], +}; const byType = (type: string) => (event: ReceivedEvent) => (event.body as { type?: string }).type === type; @@ -113,8 +195,8 @@ export class Intake { continue; } - for (const path of findFractionalFields(parsed)) { - this.addViolation('fractional number in an integer field', `${eventLabel(parsed)} → ${path}`); + for (const path of findInvalidIntegers(parsed)) { + this.addViolation('value the intake cannot decode into an integer', `${eventLabel(parsed)} → ${path}`); } this.rumEvents.push({ timestamp: Date.now(), body: parsed, headers }); @@ -275,21 +357,50 @@ function truncate(value: string, max = 200): string { return value.length > max ? `${value.slice(0, max)}…` : value; } -/** Dotted paths of every number the intake would fail to decode into an integer. */ -function findFractionalFields(value: unknown, path = ''): string[] { - if (typeof value === 'number') { - const field = path.split('.').pop() ?? ''; - return Number.isInteger(value) || FRACTIONAL_FIELDS.has(field) ? [] : [`${path} = ${value}`]; +/** Dotted paths of every value the intake would fail to decode into an integer, with the value. */ +function findInvalidIntegers(event: unknown): string[] { + const type = (event as { type?: unknown } | undefined)?.type; + const found: string[] = []; + for (const path of INTAKE_INTEGER_PATHS[typeof type === 'string' ? type : ''] ?? []) { + findInvalidIntegerAt(event, path.split('.'), '', found); } - if (Array.isArray(value)) { - return value.flatMap((item, index) => findFractionalFields(item, `${path}[${index}]`)); + return found; +} + +/** Whether the intake decodes `value` into an integer: absent, `null`, or a whole number it holds exactly. */ +function isIntakeInteger(value: unknown): boolean { + return value === undefined || value === null || (typeof value === 'number' && Number.isSafeInteger(value)); +} + +function findInvalidIntegerAt(value: unknown, segments: readonly string[], at: string, found: string[]): void { + if (segments.length === 0) { + if (!isIntakeInteger(value)) { + found.push(`${at} = ${JSON.stringify(value)}`); + } + return; } - if (value !== null && typeof value === 'object') { - return Object.entries(value).flatMap(([key, item]) => - findFractionalFields(item, path === '' ? key : `${path}.${key}`) - ); + const [segment, ...rest] = segments; + if (segment === '*') { + if (value === undefined || value === null) { + return; + } + if (typeof value !== 'object' || Array.isArray(value)) { + found.push(`${at} = ${JSON.stringify(value)}`); + return; + } + for (const [key, item] of Object.entries(value)) { + findInvalidIntegerAt(item, rest, `${at}.${key}`, found); + } + return; + } + const key = segment.endsWith('[]') ? segment.slice(0, -2) : segment; + const child = (value as Record | null | undefined)?.[key]; + const childPath = at === '' ? key : `${at}.${key}`; + if (!segment.endsWith('[]')) { + findInvalidIntegerAt(child, rest, childPath, found); + } else if (Array.isArray(child)) { + child.forEach((item, index) => findInvalidIntegerAt(item, rest, `${childPath}[${index}]`, found)); } - return []; } function eventLabel(event: unknown): string { diff --git a/e2e/lib/mainPage.ts b/e2e/lib/mainPage.ts index 69da336f..fc3acc07 100644 --- a/e2e/lib/mainPage.ts +++ b/e2e/lib/mainPage.ts @@ -23,6 +23,11 @@ interface ElectronAppWindow { openBridgeFileWindowNoIsolation: () => Promise; openBridgeHttpWindow: () => Promise; killBridgeWindowRenderer: () => Promise; + generateUncaughtExceptionAndExit: () => Promise; + generateManualErrorAndExit: () => Promise; + generateManualErrorOnWillQuit: () => Promise; + generateManualErrorAndAppExit: () => Promise; + generateManualErrorOnProcessExit: () => Promise; }; } @@ -66,6 +71,41 @@ export class MainPage { await this.page.locator('#generate-uncaught-exception').click(); } + /** Fire and forget: the process ends before the call could answer. */ + generateUncaughtExceptionAndExit() { + void this.page + .evaluate(() => (globalThis as unknown as ElectronAppWindow).electronAPI.generateUncaughtExceptionAndExit()) + .catch(() => undefined); + } + + /** Fire and forget, as above. */ + generateManualErrorAndExit() { + void this.page + .evaluate(() => (globalThis as unknown as ElectronAppWindow).electronAPI.generateManualErrorAndExit()) + .catch(() => undefined); + } + + /** Fire and forget, as above. */ + generateManualErrorOnWillQuit() { + void this.page + .evaluate(() => (globalThis as unknown as ElectronAppWindow).electronAPI.generateManualErrorOnWillQuit()) + .catch(() => undefined); + } + + /** Fire and forget, as above. */ + generateManualErrorOnProcessExit() { + void this.page + .evaluate(() => (globalThis as unknown as ElectronAppWindow).electronAPI.generateManualErrorOnProcessExit()) + .catch(() => undefined); + } + + /** Fire and forget, as above. */ + generateManualErrorAndAppExit() { + void this.page + .evaluate(() => (globalThis as unknown as ElectronAppWindow).electronAPI.generateManualErrorAndAppExit()) + .catch(() => undefined); + } + async generateUnhandledRejection() { await this.page.locator('#generate-unhandled-rejection').click(); } @@ -142,6 +182,15 @@ export class MainPage { return await this.page.evaluate(() => (globalThis as unknown as ElectronAppWindow).electronAPI.ping()); } + /** The session id the SDK's bridge answers renderers with: `''` when there is none to collect. */ + async getBridgeSessionId(): Promise { + return await this.page.evaluate(() => + ( + globalThis as unknown as { DatadogEventBridge: { getSessionId: () => string } } + ).DatadogEventBridge.getSessionId() + ); + } + async flushTransport() { await this.page.evaluate(() => (globalThis as unknown as ElectronAppWindow).electronAPI.flushTransport()); } diff --git a/e2e/scenarios/intake-contract.scenario.ts b/e2e/scenarios/intake-contract.scenario.ts index 8efc74b3..ed0db622 100644 --- a/e2e/scenarios/intake-contract.scenario.ts +++ b/e2e/scenarios/intake-contract.scenario.ts @@ -34,3 +34,26 @@ test('uploads to /api/v2/rum as newline-delimited JSON with a text/plain content expect(typeof event.body).toBe('object'); } }); + +test('flags a value the real intake would fail to decode into an integer, and nothing else', async ({ intake }) => { + // Straight to the fake intake, bypassing the SDK: this pins the oracle itself, not the bridge + // in front of it. Each line is one event, as the SDK sends them. + const events = [ + { type: 'error', date: '1700000000000', error: { message: 'string date' } }, + { type: 'view', date: 1700000000000, view: { id: 'v', custom_timings: { boot: 1.5 } } }, + { type: 'view', date: 1700000000000, view: { id: 'v', custom_timings: { boot: 15 } } }, + { type: 'error', date: 1700000000000, error: { message: 'priced' }, context: { price: 19.99 } }, + ]; + const response = await fetch(`http://127.0.0.1:${intake.getPort()}/api/v2/rum?ddforward=%2Fapi%2Fv2%2Frum`, { + method: 'POST', + headers: { 'content-type': 'text/plain;charset=UTF-8' }, + body: events.map((event) => JSON.stringify(event)).join('\n'), + }); + + expect(response.status).toBe(202); + expect(intake.getProtocolViolations().map((violation) => `${violation.reason}: ${violation.detail}`)).toEqual([ + 'value the intake cannot decode into an integer: unknown/error → date = "1700000000000"', + 'value the intake cannot decode into an integer: unknown/view → view.custom_timings.boot = 1.5', + ]); + intake.clear(); +}); diff --git a/e2e/scenarios/session-on-error.scenario.ts b/e2e/scenarios/session-on-error.scenario.ts new file mode 100644 index 00000000..75da43df --- /dev/null +++ b/e2e/scenarios/session-on-error.scenario.ts @@ -0,0 +1,546 @@ +import { mkdir, readdir, readFile, rm, writeFile } from 'node:fs/promises'; +import { join } from 'node:path'; +import type { RumErrorEvent, RumViewEvent } from '@flashcatcloud/electron-sdk'; +import { + test, + expect, + launchAppManually, + createUserDataDir, + cleanupUserDataDir, + waitForCrashDump, + ensureProcessGone, +} from '../lib/helpers'; +import type { Intake } from '../lib/intake'; +import type { MainPage } from '../lib/mainPage'; + +/** "Only error sessions": nothing is drawn by the plain rate, every session is kept on error. */ +const ON_ERROR_ONLY = { sessionSampleRate: 0, sessionOnError: true }; +/** Comfortably past the release jitter, which is at most 3 s. */ +const RELEASE_WAIT = 3_500; + +interface SessionEvent { + type: string; + date: number; + session: { id: string; sampled_for_error?: boolean }; + view: { id: string; is_active?: boolean }; + _dd?: { configuration?: { session_sample_rate?: number } }; +} + +/** Every RUM event received, telemetry aside: telemetry is not session data and is never withheld. */ +function rumEvents(intake: Intake): SessionEvent[] { + return intake + .getAllEvents() + .map((event) => event.body as SessionEvent) + .filter((body) => body.type !== 'telemetry'); +} + +/** Waits past the jitter, then flushes: the flush resolves once every pending batch is uploaded. */ +async function settle(mainPage: MainPage, waitMs = RELEASE_WAIT) { + await new Promise((resolve) => setTimeout(resolve, waitMs)); + await mainPage.flushTransport(); +} + +/** + * Optional evidence dump: with `FC_E2E_CAPTURE_DIR` set, every event the fake intake received is + * written there per scenario, so a run can be inspected after the fact. + */ +test.afterEach(async ({ intake }, testInfo) => { + const captureDir = process.env.FC_E2E_CAPTURE_DIR; + if (!captureDir) { + return; + } + await mkdir(captureDir, { recursive: true }); + const fileName = `${testInfo.titlePath + .slice(1) + .join(' - ') + .replace(/[^\w.-]+/g, '_')}.json`; + await writeFile(join(captureDir, fileName), JSON.stringify(intake.getAllEvents(), null, 2)); +}); + +test.describe('sessionOnError', () => { + test.use({ sdkConfig: ON_ERROR_ONLY, rumBrowserSdk: {} }); + // Each scenario sleeps past the release jitter more than once, which leaves little of the default + // budget for a loaded machine. + test.describe.configure({ timeout: 60_000 }); + + test('uploads nothing for a session that never reports an error', async ({ intake, mainPage, testServer }) => { + await mainPage.generateActivity(); + await mainPage.mainFetch(testServer.urlFor(200)); + await settle(mainPage); + + expect(rumEvents(intake)).toEqual([]); + }); + + test('releases the history of the main process and the renderer once an error is reported', async ({ + intake, + mainPage, + testServer, + }) => { + // Before the error: a renderer click (action) and a main-process request (resource). + await mainPage.generateActivity(); + await mainPage.mainFetch(testServer.urlFor(200)); + await settle(mainPage); + expect(rumEvents(intake)).toEqual([]); + + await mainPage.generateManualError(); + await settle(mainPage); + + const events = rumEvents(intake); + const types = new Set(events.map((event) => event.type)); + // A loaded machine can add a renderer long task, which is released along with the rest. + for (const type of ['view', 'action', 'resource', 'error']) { + expect(types).toContain(type); + } + + const sessionIds = new Set(events.map((event) => event.session.id)); + expect(sessionIds.size).toBe(1); + + // Both the main-process view and the renderer view, each marked as kept on error. + const views = events.filter((event) => event.type === 'view'); + expect(new Set(views.map((view) => view.view.id)).size).toBeGreaterThanOrEqual(2); + for (const view of views) { + expect(view.session.sampled_for_error).toBe(true); + } + // One session standing for itself, on every event of both processes. + for (const event of events) { + expect(event._dd?.configuration?.session_sample_rate).toBe(0); + } + // The first view to arrive is the earliest one: the backend builds the session from it. + const firstView = views[0]; + expect(Math.min(...views.map((view) => view.date))).toBe(firstView.date); + + const telemetry = intake + .getAllEvents() + .map((event) => event.body as { type: string; telemetry?: { message?: string } }) + .filter((body) => body.type === 'telemetry' && body.telemetry?.message === 'Error session event buffer released'); + expect(telemetry).toHaveLength(1); + expect(intake.getProtocolViolations()).toEqual([]); + + // After the release, events flow as they happen. + intake.clear(); + await mainPage.mainFetch(testServer.urlFor(200)); + await settle(mainPage, 0); + expect(rumEvents(intake).some((event) => event.type === 'resource')).toBe(true); + }); + + test('is released by a renderer error, and not by one the renderer beforeSend dropped', async ({ + intake, + mainPage, + electronApp, + }) => { + const bridgeWindow = await mainPage.openBridgeFileWindow(electronApp); + await bridgeWindow.generateError('dropped-by-beforeSend'); + await settle(mainPage); + expect(rumEvents(intake)).toEqual([]); + + await bridgeWindow.generateError('kept renderer error'); + await settle(mainPage); + + const errors = rumEvents(intake).filter((event) => event.type === 'error') as unknown as RumErrorEvent[]; + expect(errors.map((error) => error.error.message)).toEqual([expect.stringContaining('kept renderer error')]); + expect(rumEvents(intake).some((event) => event.type === 'view' && event.session.sampled_for_error)).toBe(true); + }); + + test('throws away a session that ends without an error, stragglers included', async ({ + intake, + mainPage, + testServer, + }) => { + await mainPage.generateActivity(); + await mainPage.mainFetch(testServer.urlFor(200)); + const bridgeSessionBefore = await mainPage.getBridgeSessionId(); + await mainPage.stopSession(); + await settle(mainPage); + expect(rumEvents(intake)).toEqual([]); + + // The next session is kept on error too; its error releases it, and only it. + await mainPage.generateActivity(); + await mainPage.generateManualError(); + await settle(mainPage); + + const sessionIds = new Set(rumEvents(intake).map((event) => event.session.id)); + expect(sessionIds.size).toBe(1); + expect(sessionIds.has(bridgeSessionBefore)).toBe(false); + }); + + test('reports the end of a session that was released', async ({ intake, mainPage }) => { + await mainPage.generateManualError(); + await settle(mainPage); + intake.clear(); + + await mainPage.stopSession(); + await settle(mainPage, 500); + + const views = rumEvents(intake).filter((event) => event.type === 'view'); + expect(views.some((view) => view.view.is_active === false && view.session.sampled_for_error)).toBe(true); + }); + + test('releases at once on an uncaught exception in the main process', async ({ intake, mainPage }) => { + await mainPage.generateActivity(); + await mainPage.generateUncaughtException(); + // No wait for the jitter: whatever the session's delay, it does not apply here. + await settle(mainPage, 200); + + const events = rumEvents(intake); + expect(events.some((event) => event.type === 'error')).toBe(true); + expect(events.some((event) => event.type === 'action')).toBe(true); + test.info().annotations.push({ + type: 'release-delay', + description: `jitter this session would otherwise wait: ${computeReleaseDelay(events[0].session.id)} ms`, + }); + }); +}); + +test.describe('sessionOnError, negative controls', () => { + test.use({ rumBrowserSdk: {} }); + + test('a session drawn by the plain rate reports as it happens, unmarked, with its rate', async ({ + intake, + mainPage, + }) => { + await mainPage.generateActivity(); + await settle(mainPage, 0); + + const views = rumEvents(intake).filter((event) => event.type === 'view'); + expect(views.length).toBeGreaterThan(0); + for (const view of views) { + expect(view.session.sampled_for_error).toBeUndefined(); + expect(view._dd?.configuration?.session_sample_rate).toBe(100); + } + expect(await mainPage.getBridgeSessionId()).not.toBe(''); + }); + + test.describe('without sessionOnError', () => { + test.use({ sdkConfig: { sessionSampleRate: 0 } }); + + test('a session the draw did not keep uploads nothing, errors included, and renderers see no session', async ({ + intake, + mainPage, + }) => { + await mainPage.generateActivity(); + await mainPage.generateManualError(); + await settle(mainPage); + + expect(rumEvents(intake)).toEqual([]); + // What keeps the renderer's own Session Replay from recording it. + expect(await mainPage.getBridgeSessionId()).toBe(''); + }); + }); +}); + +test.describe('sessionOnError, host exit on an uncaught exception', () => { + test.use({ sdkConfig: ON_ERROR_ONLY }); + + test('writes the released history and the fatal error to disk before the host ends the process', async ({ + intake, + sdkConfig, + }) => { + test.setTimeout(60_000); + const userDataDir = await createUserDataDir(); + const { electronApp, mainPage } = await launchAppManually(intake, userDataDir, 'await', sdkConfig); + try { + // A main-process operation: its vital is held the moment it is reported. + await mainPage.startOperation('checkout'); + // Taken now: the accessor is gone with the process. + const child = electronApp.process(); + + mainPage.generateUncaughtExceptionAndExit(); + await ensureProcessGone(child.pid); + // Ended by the host's listener, not by the harness giving up on it. + expect(child.exitCode).toBe(1); + + // The process ended from its own uncaughtException listener, with no later turn of the event + // loop: what is on disk is what the SDK wrote before returning from its listener. + const events = await readBatchEvents(join(userDataDir, 'rum')); + const types = events.map((event) => event.type); + expect(types).toContain('view'); + expect(types).toContain('vital'); + const errors = events.filter((event) => event.type === 'error') as unknown as RumErrorEvent[]; + expect(errors.map((error) => error.error.message)).toEqual([expect.stringContaining('before exit')]); + // Nothing had been uploaded: the upload cycle never got to run. + expect(rumEvents(intake)).toEqual([]); + } finally { + await electronApp.close().catch(() => undefined); + await cleanupUserDataDir(userDataDir); + } + }); +}); + +test.describe('sessionOnError, errors reported as the application leaves', () => { + test.use({ sdkConfig: ON_ERROR_ONLY }); + + for (const { title, leave, message, exitCode } of [ + { + title: 'reported in the same turn as process.exit()', + leave: (mainPage: MainPage) => mainPage.generateManualErrorAndExit(), + message: 'before process.exit', + exitCode: 1, + }, + { + title: 'reported from a will-quit listener registered after the SDK', + leave: (mainPage: MainPage) => mainPage.generateManualErrorOnWillQuit(), + message: 'on will-quit', + exitCode: 0, + }, + { + title: 'reported in the same turn as app.exit()', + leave: (mainPage: MainPage) => mainPage.generateManualErrorAndAppExit(), + message: 'before app.exit', + exitCode: 1, + }, + { + title: "reported from the host's own exit listener, registered after the SDK's", + leave: (mainPage: MainPage) => mainPage.generateManualErrorOnProcessExit(), + message: 'on process exit', + exitCode: 1, + }, + ]) { + test(`writes the error ${title}, and the history held before it, to disk`, async ({ intake, sdkConfig }) => { + test.setTimeout(60_000); + const userDataDir = await createUserDataDir(); + const { electronApp, mainPage } = await launchAppManually(intake, userDataDir, 'await', sdkConfig); + try { + await mainPage.startOperation('checkout'); + const child = electronApp.process(); + + leave(mainPage); + await ensureProcessGone(child.pid); + expect(child.exitCode).toBe(exitCode); + + const events = await readBatchEvents(join(userDataDir, 'rum')); + const types = events.map((event) => event.type); + expect(types).toContain('view'); + expect(types).toContain('vital'); + const errors = events.filter((event) => event.type === 'error') as unknown as RumErrorEvent[]; + expect(errors.map((error) => error.error.message)).toEqual([expect.stringContaining(message)]); + expect(rumEvents(intake)).toEqual([]); + } finally { + await electronApp.close().catch(() => undefined); + await cleanupUserDataDir(userDataDir); + } + }); + } +}); + +test.describe('sessionOnError, renderer envelopes', () => { + test.use({ sdkConfig: ON_ERROR_ONLY, rumBrowserSdk: {} }); + + test('is released by a renderer error whose free-form context holds a fraction', async ({ + intake, + mainPage, + electronApp, + }) => { + const bridgeWindow = await mainPage.openBridgeFileWindow(electronApp); + await bridgeWindow.sendRaw({ + eventType: 'rum', + event: { + type: 'error', + date: Date.now(), + error: { message: 'priced', source: 'source' }, + view: { id: 'v' }, + context: { price: 19.99 }, + }, + }); + await settle(mainPage); + + const errors = rumEvents(intake).filter((event) => event.type === 'error') as unknown as RumErrorEvent[]; + expect(errors.map((error) => error.error.message)).toEqual(['priced']); + expect((errors[0] as unknown as { context?: { price?: number } }).context?.price).toBe(19.99); + expect(intake.getProtocolViolations()).toEqual([]); + }); + + test('is not released by a renderer error the intake would drop for a fractional number', async ({ + intake, + mainPage, + electronApp, + }) => { + const bridgeWindow = await mainPage.openBridgeFileWindow(electronApp); + await bridgeWindow.sendRaw({ + eventType: 'rum', + event: { + type: 'error', + date: Date.now() + 0.5, + error: { message: 'fractional', source: 'source' }, + view: { id: 'v' }, + }, + }); + await settle(mainPage); + expect(rumEvents(intake)).toEqual([]); + + // Positive control: a well-formed renderer error releases the session; the dropped one is absent. + await bridgeWindow.generateError('kept renderer error'); + await settle(mainPage); + const errors = rumEvents(intake).filter((event) => event.type === 'error') as unknown as RumErrorEvent[]; + expect(errors.map((error) => error.error.message)).toEqual([expect.stringContaining('kept renderer error')]); + }); + + test('is not released by a renderer error the intake would reject for a wrongly typed number', async ({ + intake, + mainPage, + electronApp, + }) => { + const bridgeWindow = await mainPage.openBridgeFileWindow(electronApp); + await bridgeWindow.sendRaw({ + eventType: 'rum', + event: { + type: 'error', + date: Date.now(), + error: { message: 'typed', source: 'source', resource: { method: 'GET', status_code: '500', url: 'u' } }, + view: { id: 'v' }, + }, + }); + await settle(mainPage); + expect(rumEvents(intake)).toEqual([]); + + // Positive control: the same error with its status code as a number releases the session. + await bridgeWindow.sendRaw({ + eventType: 'rum', + event: { + type: 'error', + date: Date.now(), + error: { message: 'kept typed', source: 'source', resource: { method: 'GET', status_code: 500, url: 'u' } }, + view: { id: 'v' }, + }, + }); + await settle(mainPage); + const errors = rumEvents(intake).filter((event) => event.type === 'error') as unknown as RumErrorEvent[]; + expect(errors.map((error) => error.error.message)).toEqual(['kept typed']); + expect(intake.getProtocolViolations()).toEqual([]); + }); + + test('neither uploads nor is released by a renderer envelope that calls itself telemetry', async ({ + intake, + mainPage, + electronApp, + }) => { + const bridgeWindow = await mainPage.openBridgeFileWindow(electronApp); + await bridgeWindow.sendRaw({ + eventType: 'rum', + event: { type: 'telemetry', date: Date.now(), telemetry: { type: 'log', status: 'error', message: 'smuggled' } }, + }); + await settle(mainPage); + const telemetryMessages = () => + intake + .getAllEvents() + .map((event) => event.body as { type: string; telemetry?: { message?: string } }) + .filter((body) => body.type === 'telemetry') + .map((body) => body.telemetry?.message); + // The envelope went nowhere: no RUM event left, and nothing carries its text. What did leave + // is the SDK's own telemetry reporting the rejection, which is the proof of it. + expect(rumEvents(intake)).toEqual([]); + expect(telemetryMessages()).not.toContain('smuggled'); + expect(telemetryMessages()).toContainEqual( + expect.stringContaining('Dropped a renderer RUM event: unsupported type') + ); + + // Positive control: a genuine renderer error releases the session, and the envelope is not among it. + await bridgeWindow.generateError('kept renderer error'); + await settle(mainPage); + expect(rumEvents(intake).map((event) => event.type)).toContain('error'); + expect(telemetryMessages()).not.toContain('smuggled'); + }); +}); + +/** Every event in the RUM track's batch files, rotated or not. */ +async function readBatchEvents(trackDir: string): Promise { + const files = (await readdir(trackDir)).filter((file) => /\.(tmp|log)$/.test(file)).sort(); + const events: SessionEvent[] = []; + for (const file of files) { + const content = await readFile(join(trackDir, file), 'utf8'); + for (const line of content.split('\n').filter((line) => line.trim().length > 0)) { + events.push(JSON.parse(line) as SessionEvent); + } + } + return events; +} + +for (const { title, config, reported, viewHistory } of [ + { + title: 'reports the crash of a withheld session, with its view', + config: ON_ERROR_ONLY, + reported: true, + viewHistory: 'kept', + }, + { + title: 'reports the crash of a withheld session under a view of its own when the view history is gone', + config: ON_ERROR_ONLY, + reported: true, + viewHistory: 'lost', + }, + { + title: 'does not report the crash of a session the draw did not keep', + config: { sessionSampleRate: 0 }, + reported: false, + viewHistory: 'kept', + }, +]) { + test.describe('sessionOnError, native crash', () => { + // The app every scenario gets launched anyway runs with the same sampling, so it uploads nothing + // that could be mistaken for what the crashed app reports. + test.use({ sdkConfig: config }); + + test(title, async ({ intake, sdkConfig }) => { + test.setTimeout(90_000); + const userDataDir = await createUserDataDir(); + + const first = await launchAppManually(intake, userDataDir, 'await', sdkConfig); + await first.mainPage.flushTransport(); + const crashedPid = first.electronApp.process().pid; + first.mainPage.crash(); + await waitForCrashDump(userDataDir); + await ensureProcessGone(crashedPid); + // Nothing of the crashed launch was uploaded: the session never reported an error there. + expect(rumEvents(intake)).toEqual([]); + if (viewHistory === 'lost') { + // The SDK's own view history file, as written by the crashed launch. + await rm(join(userDataDir, '_dd_view_history'), { force: true }); + } + + const second = await launchAppManually(intake, userDataDir, 'await', sdkConfig); + try { + await second.mainPage.flushTransport(); + await new Promise((resolve) => setTimeout(resolve, 5_000)); + await settle(second.mainPage); + + const events = rumEvents(intake); + const crashes = events.filter( + (event) => event.type === 'error' && (event as unknown as RumErrorEvent).error.is_crash + ); + if (!reported) { + expect(events).toEqual([]); + return; + } + expect(crashes).toHaveLength(1); + const crash = crashes[0]; + expect(crash._dd?.configuration?.session_sample_rate).toBe(0); + expect(crash.session.id).toEqual(expect.any(String)); + expect(intake.getProtocolViolations()).toEqual([]); + if (viewHistory === 'lost') { + // A view of its own, which no view event describes: the crash is not lost for want of one. + expect(crash.view.id).toEqual(expect.any(String)); + expect(events.some((event) => event.type === 'view' && event.view.id === crash.view.id)).toBe(false); + return; + } + const crashedView = events.find((event) => event.type === 'view' && event.view.id === crash.view.id) as + | (SessionEvent & RumViewEvent) + | undefined; + expect(crashedView).toBeDefined(); + expect(crashedView!.session.sampled_for_error).toBe(true); + expect(crashedView!.view.is_active).toBe(false); + expect(crashedView!.session.id).toBe(crash.session.id); + } finally { + await second.electronApp.close(); + await cleanupUserDataDir(userDataDir); + } + }); + }); +} + +/** Same hash as the SDK's, to report which delay the immediate release skipped. */ +function computeReleaseDelay(sessionId: string) { + let hash = 0; + for (let i = 0; i < sessionId.length; i += 1) { + hash = Math.imul(hash, 31) + sessionId.charCodeAt(i); + } + return Math.abs(hash) % 3000; +} diff --git a/src/assembly/Assembly.spec.ts b/src/assembly/Assembly.spec.ts index 08cdc31f..7a5019ed 100644 --- a/src/assembly/Assembly.spec.ts +++ b/src/assembly/Assembly.spec.ts @@ -151,6 +151,63 @@ describe('Assembly — renderer events', () => { expect(data.ddtags).toBe('sdk_version:1.0.0'); }); + it("should report the main process's sampling on renderer events, keeping the renderer's other configuration", () => { + const { eventManager, hooks } = setup(); + hooks.registerRum(() => ({ + session: { sampled_for_error: true }, + _dd: { configuration: { session_sample_rate: 0 } }, + })); + const collected: ServerEvent[] = []; + eventManager.registerHandler({ + canHandle: (event): event is ServerEvent => event.kind === EventKind.SERVER, + handle: (event) => collected.push(event), + }); + + eventManager.notify({ + kind: EventKind.RAW, + source: EventSource.RENDERER, + format: EventFormat.RUM, + data: { + type: 'view', + source: 'browser', + view: { id: 'renderer-view-id' }, + session: { id: 'renderer-session-id', type: 'user' }, + application: { id: 'renderer-app-id' }, + _dd: { configuration: { session_sample_rate: 100, session_replay_sample_rate: 20 } }, + }, + } as unknown as RawRumEvent); + + const data = collected[0].data as RumEvent; + expect(data.session).toMatchObject({ id: 'main-session-id', sampled_for_error: true }); + expect(data._dd.configuration).toEqual({ session_sample_rate: 0, session_replay_sample_rate: 20 }); + }); + + it("should replace a renderer's own sampling marker with the main process's, absent included", () => { + const { eventManager } = setup(); + const collected: ServerEvent[] = []; + eventManager.registerHandler({ + canHandle: (event): event is ServerEvent => event.kind === EventKind.SERVER, + handle: (event) => collected.push(event), + }); + + eventManager.notify({ + kind: EventKind.RAW, + source: EventSource.RENDERER, + format: EventFormat.RUM, + data: { + type: 'view', + source: 'browser', + view: { id: 'renderer-view-id' }, + session: { id: 'renderer-session-id', type: 'user', sampled_for_error: true }, + application: { id: 'renderer-app-id' }, + }, + } as unknown as RawRumEvent); + + const data = collected[0].data as RumEvent; + expect(data.session.id).toBe('main-session-id'); + expect(data.session).not.toHaveProperty('sampled_for_error', true); + }); + it('should preserve renderer view attributes', () => { const { eventManager } = setup(); const collected: ServerEvent[] = []; diff --git a/src/assembly/Assembly.ts b/src/assembly/Assembly.ts index 2ec54cc4..9b429489 100644 --- a/src/assembly/Assembly.ts +++ b/src/assembly/Assembly.ts @@ -15,9 +15,9 @@ import { TelemetryEvent } from '../domain/telemetry'; * - **Main-process events**: fully assembled by combining raw data with all * registered hook results (commonContext, session, view). * - **Renderer events**: arrive pre-assembled by `@flashcatcloud/browser-rum` in - * the renderer process. Only `session.id` and `application.id` are - * overridden from the main process; the renderer's own view, source, - * service, and other attributes are preserved. + * the renderer process. Only `session.id`, `application.id` and the session's + * sampling attributes are overridden from the main process; the renderer's own + * view, source, service, and other attributes are preserved. */ export class Assembly { constructor( @@ -51,9 +51,10 @@ export class Assembly { /** * Renderer RUM events arrive already assembled by `@flashcatcloud/browser-rum`. - * Only `session.id` and `application.id` are overridden from the main - * process hooks, preserving the renderer's own view, source, and other - * attributes. + * Only `session.id`, `application.id` and the session's sampling attributes + * (`session.sampled_for_error`, `_dd.configuration.session_sample_rate`) are + * overridden from the main process hooks, preserving the renderer's own view, + * source, and other attributes. */ private assembleRendererRumEvent(event: RawRumEvent): ServerEvent | DISCARDED { const hookResult = this.hooks.triggerRum({ @@ -65,17 +66,22 @@ export class Assembly { return DISCARDED; } - const { session, application, view } = hookResult ?? {}; + const { session, application, view, _dd } = hookResult ?? {}; const mainProcessAttributes = { - session: { id: session?.id }, + // The main process draws the session, so the sampling it reports is the main process's too. + session: { id: session?.id, sampled_for_error: session?.sampled_for_error }, application: { id: application?.id }, container: { view: { id: view?.id }, source: 'electron' }, + _dd: { configuration: { session_sample_rate: _dd?.configuration?.session_sample_rate } }, }; // Note `usr` is not in `mainProcessAttributes`: the anonymous id must not be stamped here (the // renderer reads the same id off the bridge itself), and the identity needs replacing rather // than merging — see below. const data = combine(event.data, mainProcessAttributes) as RumEvent; + // Assigned rather than merged: `combine` keeps the renderer's value where the main process has + // none, and the marker is the main process's to set or clear. + data.session.sampled_for_error = session?.sampled_for_error; return { kind: EventKind.SERVER, @@ -130,6 +136,7 @@ export class Assembly { const hookResult = this.hooks.triggerRum({ eventType: event.data.type, startTime, + viewId: (event.data as { view?: { id?: string } }).view?.id, }); if (hookResult !== DISCARDED) { return { diff --git a/src/assembly/hooks.ts b/src/assembly/hooks.ts index 7a2fc681..84cc2fb9 100644 --- a/src/assembly/hooks.ts +++ b/src/assembly/hooks.ts @@ -9,6 +9,11 @@ export type RumEventType = RumEvent['type']; export interface RumAssembleParams { eventType: RumEventType; startTime: TimeStamp; + /** + * The view the raw event names itself, if any: a crash reported on the next launch whose view + * is gone from the history comes under a view of its own rather than not at all. + */ + viewId?: string; } export interface TelemetryAssembleParams { diff --git a/src/bridge/BridgeHandler.spec.ts b/src/bridge/BridgeHandler.spec.ts index b23f2750..14f1f494 100644 --- a/src/bridge/BridgeHandler.spec.ts +++ b/src/bridge/BridgeHandler.spec.ts @@ -1,6 +1,7 @@ import { beforeEach, describe, expect, it, vi } from 'vitest'; import { EventFormat, EventKind, EventManager, EventSource, LifecycleKind } from '../event'; import type { RawRumEvent } from '../event'; +import { Assembly, createFormatHooks } from '../assembly'; import { BridgeHandler } from './BridgeHandler'; import type { BridgeOptions } from './BridgeHandler'; import { BRIDGE_CHANNEL, CONFIG_CHANNEL, CONFIG_PUSH_CHANNEL } from '../common'; @@ -307,6 +308,141 @@ describe('BridgeHandler', () => { }); }); + it('should drop a rum envelope whose event is not a RUM event type, telemetry included', () => { + const notified: unknown[] = []; + eventManager.registerHandler({ + canHandle: (event) => event.kind === EventKind.RAW, + handle: (event) => notified.push(event), + }); + + simulateIpcMessage( + JSON.stringify({ eventType: 'rum', event: { type: 'telemetry', telemetry: { message: 'x' } } }) + ); + simulateIpcMessage(JSON.stringify({ eventType: 'rum', event: { type: 'logs', message: 'x' } })); + + expect(notified).toEqual([]); + }); + + it('should drop a renderer event carrying a fraction where the intake decodes an integer, and keep one where it decodes a float', () => { + const notified: unknown[] = []; + eventManager.registerHandler({ + canHandle: (event) => event.kind === EventKind.RAW, + handle: (event) => notified.push(event), + }); + + simulateIpcMessage( + JSON.stringify({ eventType: 'rum', event: { type: 'error', date: 1.5, error: { message: 'x' } } }) + ); + simulateIpcMessage( + JSON.stringify({ + eventType: 'rum', + event: { type: 'view', date: 1, view: { id: 'v', cumulative_layout_shift: 0.1 } }, + }) + ); + + expect(notified).toHaveLength(1); + expect((notified[0] as { data: { type: string } }).data.type).toBe('view'); + }); + + it('should drop an envelope that names a prototype property, so assembly never merges it into Object.prototype', () => { + new Assembly(eventManager, createFormatHooks()); + const collected: unknown[] = []; + eventManager.registerHandler({ + canHandle: (event) => event.kind === EventKind.SERVER, + handle: (event) => collected.push(event), + }); + // Built by hand: in an object literal `__proto__:` sets the prototype, while in JSON it is a + // key like any other — which is what JSON.parse hands the bridge. + const envelope = + '{"eventType":"rum","event":{"type":"view","date":1,"view":{"id":"v","__proto__":{"polluted":true}},"__proto__":{"polluted":true}}}'; + + try { + simulateIpcMessage(envelope); + + expect(({} as { polluted?: unknown }).polluted).toBeUndefined(); + expect(collected).toEqual([]); + } finally { + delete (Object.prototype as { polluted?: unknown }).polluted; + } + }); + + it('should drop an envelope that names a prototype property outside the event too', () => { + const notified: unknown[] = []; + eventManager.registerHandler({ + canHandle: (event) => event.kind === EventKind.RAW, + handle: (event) => notified.push(event), + }); + + try { + simulateIpcMessage( + '{"eventType":"rum","constructor":{"polluted":true},"event":{"type":"view","date":1,"view":{"id":"v"}}}' + ); + + expect(notified).toEqual([]); + expect(mockAddError).toHaveBeenCalledWith(expect.any(Error)); + } finally { + delete (Object.prototype as { polluted?: unknown }).polluted; + } + }); + + it('should drop a renderer event with a value of the wrong type where the intake decodes an integer', () => { + const notified: unknown[] = []; + eventManager.registerHandler({ + canHandle: (event) => event.kind === EventKind.RAW, + handle: (event) => notified.push(event), + }); + + simulateIpcMessage( + JSON.stringify({ + eventType: 'rum', + event: { type: 'error', date: 1, error: { message: 'x', resource: { status_code: '500' } } }, + }) + ); + + expect(notified).toEqual([]); + expect(mockAddError).toHaveBeenCalledWith(expect.any(Error)); + }); + + it('should keep a renderer event whose free-form context holds a fraction: the intake stores it as is', () => { + const notified: unknown[] = []; + eventManager.registerHandler({ + canHandle: (event) => event.kind === EventKind.RAW, + handle: (event) => notified.push(event), + }); + + simulateIpcMessage( + JSON.stringify({ + eventType: 'rum', + event: { type: 'error', date: 1, error: { message: 'x' }, context: { price: 19.99 }, usr: { score: 0.5 } }, + }) + ); + + expect(notified).toHaveLength(1); + }); + + it('should drop a renderer event with a fraction at a path the intake decodes as an integer', () => { + const notified: unknown[] = []; + eventManager.registerHandler({ + canHandle: (event) => event.kind === EventKind.RAW, + handle: (event) => notified.push(event), + }); + + simulateIpcMessage( + JSON.stringify({ eventType: 'rum', event: { type: 'view', date: 1, view: { id: 'v', time_spent: 1.5 } } }) + ); + + expect(notified).toEqual([]); + }); + + it('should report a message it cannot parse without any of its text', () => { + simulateIpcMessage('{"eventType":"rum","event":{"type":"error","error":{"message":"card 4111 1111"}}'); + + expect(mockAddError).toHaveBeenCalledWith(expect.any(Error)); + const message = (mockAddError.mock.calls[0][0] as Error).message; + expect(message).not.toContain('4111'); + expect(message).toContain('(80 characters)'); + }); + it('should apply the pre-warm timing correction before notifying', () => { const collected: RawRumEvent[] = []; eventManager.registerHandler({ @@ -372,8 +508,8 @@ describe('BridgeHandler', () => { }); it('should track each webContents separately', () => { - simulateIpcMessage(JSON.stringify({ eventType: 'rum', event: { view: { id: 'abc' } } }), 1); - simulateIpcMessage(JSON.stringify({ eventType: 'rum', event: { view: { id: 'def' } } }), 2); + simulateIpcMessage(JSON.stringify({ eventType: 'rum', event: { type: 'view', view: { id: 'abc' } } }), 1); + simulateIpcMessage(JSON.stringify({ eventType: 'rum', event: { type: 'view', view: { id: 'def' } } }), 2); expect(rendererRegistry.get(1)?.viewId).toBe('abc'); expect(rendererRegistry.get(2)?.viewId).toBe('def'); diff --git a/src/bridge/BridgeHandler.ts b/src/bridge/BridgeHandler.ts index f58fc672..0ff5eea7 100644 --- a/src/bridge/BridgeHandler.ts +++ b/src/bridge/BridgeHandler.ts @@ -2,8 +2,10 @@ import { ipcMain, webContents } from 'electron'; import type { IpcMainEvent } from 'electron'; import { EventKind, EventSource, EventFormat, LifecycleKind } from '../event'; import type { EventManager, LifecycleEvent, RawRumEvent } from '../event'; +import type { RumEvent } from '../domain/rum'; import { monitor, addError as addTelemetryError } from '../domain/telemetry'; import { BRIDGE_CHANNEL, CONFIG_CHANNEL, CONFIG_PUSH_CHANNEL } from '../common'; +import { findInvalidIntakeInteger, hasPrototypeKey } from '../tools/intakeNumbers'; import type { BridgeConfig } from '../common'; import type { RendererRegistry } from '../domain/RendererRegistry'; import type { User } from '../domain/UserContext'; @@ -12,6 +14,15 @@ import type { StackPathNormalizer } from '../domain/StackPathNormalizer'; type BridgeEventType = 'rum' | 'log' | 'internal_telemetry'; +const RUM_EVENT_TYPES = new Set([ + 'view', + 'action', + 'error', + 'resource', + 'long_task', + 'vital', +] satisfies RumEvent['type'][]); + interface BridgeEvent { eventType: BridgeEventType; event: unknown; @@ -99,12 +110,38 @@ export class BridgeHandler { try { bridgeEvent = JSON.parse(msg) as BridgeEvent; } catch { - addTelemetryError(new Error(`Failed to parse bridge message: ${msg}`)); + // The message is renderer text, and telemetry leaves the device: only its size is reported. + addTelemetryError(new Error(`Failed to parse bridge message (${msg.length} characters)`)); + return; + } + // A property named like a prototype's is not data: merged, `__proto__` reaches + // `Object.prototype` itself. Dropped whole rather than stripped — nothing honest sends one, + // and a message with a hole where a renderer put something is a message nobody asked for. + if (hasPrototypeKey(bridgeEvent)) { + addTelemetryError(new Error('Dropped a bridge message: forbidden property name')); return; } switch (bridgeEvent.eventType) { - case 'rum': + case 'rum': { + // Only the RUM event types the intake accepts: an envelope claiming to be telemetry, say, + // is neither a RUM event nor the SDK's own telemetry, and would bypass what applies to + // either. + const type = (bridgeEvent.event as { type?: unknown } | undefined)?.type; + if (!RUM_EVENT_TYPES.has(type)) { + addTelemetryError(new Error('Dropped a renderer RUM event: unsupported type')); + break; + } + // A value the intake cannot decode into an integer — a fraction, a string, a boolean — + // fails the whole event there, silently; and an error that would never land must not earn + // a session its release. Only the paths the intake decodes as integers are looked at; + // free-form attributes are the renderer's. + if (findInvalidIntakeInteger(bridgeEvent.event) !== undefined) { + addTelemetryError( + new Error('Dropped a renderer RUM event: a value the intake decodes as an integer is not a whole number') + ); + break; + } this.trackRenderer(bridgeEvent.event, webContentsId); // Both rewrite the event in place, before it is handed over: everything downstream // treats the bridged event as final. They are independent of one another and the order @@ -121,6 +158,7 @@ export class BridgeHandler { data: bridgeEvent.event, } as RawRumEvent); break; + } case 'log': // TODO(RUM-15047) break; diff --git a/src/config.spec.ts b/src/config.spec.ts index f1d6b52f..6c5d0857 100644 --- a/src/config.spec.ts +++ b/src/config.spec.ts @@ -5,6 +5,7 @@ import type { InitConfiguration } from './config'; import * as display from './tools/display'; vi.mock('./tools/display', () => ({ displayError: vi.fn(), + displayWarn: vi.fn(), })); describe('buildConfiguration', () => { @@ -449,4 +450,60 @@ describe('buildConfiguration', () => { expect(display.displayError).not.toHaveBeenCalled(); }); }); + + describe('sessionSampleRate validation', () => { + it('defaults to 100 when not provided', () => { + expect(buildConfiguration({ ...DEFAULT_CONFIG })?.sessionSampleRate).toBe(100); + }); + + it.each([0, 12.5, 100])('accepts valid value: %d', (value) => { + expect(buildConfiguration({ ...DEFAULT_CONFIG, sessionSampleRate: value })?.sessionSampleRate).toBe(value); + }); + + it.each([ + { value: -1, description: 'negative number' }, + { value: 101, description: 'greater than 100' }, + { value: '50', description: 'numeric string' }, + ])('fails initialization when $description, like the browser SDK', ({ value }) => { + const config = { ...DEFAULT_CONFIG, sessionSampleRate: value } as unknown as InitConfiguration; + + expect(buildConfiguration(config)).toBeUndefined(); + expect(display.displayError).toHaveBeenCalledWith( + "SDK initialization failed: 'sessionSampleRate' must be a finite number from 0 to 100" + ); + }); + + it('defaults to 100 when null (no error)', () => { + const config = { ...DEFAULT_CONFIG, sessionSampleRate: null } as unknown as InitConfiguration; + + expect(buildConfiguration(config)?.sessionSampleRate).toBe(100); + expect(display.displayError).not.toHaveBeenCalled(); + }); + }); + + describe('sessionOnError validation', () => { + it('defaults to false', () => { + expect(buildConfiguration({ ...DEFAULT_CONFIG })?.sessionOnError).toBe(false); + }); + + it('accepts true', () => { + expect( + buildConfiguration({ ...DEFAULT_CONFIG, sessionSampleRate: 0, sessionOnError: true })?.sessionOnError + ).toBe(true); + expect(display.displayWarn).not.toHaveBeenCalled(); + }); + + it('logs error and uses false when not a boolean', () => { + const config = { ...DEFAULT_CONFIG, sessionOnError: 'yes' } as unknown as InitConfiguration; + + expect(buildConfiguration(config)?.sessionOnError).toBe(false); + expect(display.displayError).toHaveBeenCalledWith("Configuration error: 'sessionOnError' must be a boolean"); + }); + + it('warns that it can never apply while sessionSampleRate is 100', () => { + buildConfiguration({ ...DEFAULT_CONFIG, sessionOnError: true }); + + expect(display.displayWarn).toHaveBeenCalledWith(expect.stringContaining('does not affect new sessions')); + }); + }); }); diff --git a/src/config.ts b/src/config.ts index 60fd173f..206aa07b 100644 --- a/src/config.ts +++ b/src/config.ts @@ -1,5 +1,11 @@ -import { ONE_KIBI_BYTE, ONE_MEBI_BYTE, ONE_SECOND, DefaultPrivacyLevel } from '@flashcatcloud/browser-core'; -import { displayError } from './tools/display'; +import { + ONE_KIBI_BYTE, + ONE_MEBI_BYTE, + ONE_SECOND, + DefaultPrivacyLevel, + isPercentage, +} from '@flashcatcloud/browser-core'; +import { displayError, displayWarn } from './tools/display'; /** * Intake host used when `site` is omitted. @@ -36,6 +42,22 @@ export interface InitConfiguration { applicationId: string; env?: string; version?: string; + /** + * Percentage of sessions collected (0–100). Defaults to `100`. Drawn once per session, in the main + * process, and it applies to the renderer events that reach it over the bridge too. + */ + sessionSampleRate?: number; + /** + * Keep collecting the sessions `sessionSampleRate` did not draw, but upload them only if they + * report an error. Defaults to `false`. + * + * Such a session holds the last minute of its events in memory and uploads nothing; at its first + * error it hands that minute to the upload batch along with the error, 0–3 s later, then reports + * as it happens like any other session. A session that ends without an error is thrown away + * whole. It only applies to what the plain rate missed, so with the default `sessionSampleRate` + * of 100 there is nothing left for it to apply to. + */ + sessionOnError?: boolean; telemetrySampleRate?: number; batchSize?: BatchSize; uploadFrequency?: UploadFrequency; @@ -90,6 +112,8 @@ export interface Configuration { env?: string; version?: string; proxy?: string; + sessionSampleRate: number; + sessionOnError: boolean; telemetrySampleRate: number; batchSize?: BatchSize; uploadFrequency?: UploadFrequency; @@ -132,6 +156,15 @@ function validateOptionalString(value: unknown): string | undefined { return value.length > 0 ? value : undefined; } +/** Same contract as the browser SDK: an out-of-range rate fails `init` rather than being guessed at. */ +function isValidSessionSampleRate(value: unknown): boolean { + if (value !== undefined && value !== null && !isPercentage(value)) { + displayError("SDK initialization failed: 'sessionSampleRate' must be a finite number from 0 to 100"); + return false; + } + return true; +} + function validateTelemetrySampleRate(value: unknown): number { if (value === undefined || value === null) { return 20; @@ -199,11 +232,24 @@ export function buildConfiguration(initConfig: InitConfiguration): Configuration const applicationId = validateRequiredString(initConfig.applicationId, 'applicationId'); const site = validateSite(initConfig.site); - if (service === undefined || clientToken === undefined || applicationId === undefined || site === undefined) { + if ( + service === undefined || + clientToken === undefined || + applicationId === undefined || + site === undefined || + !isValidSessionSampleRate(initConfig.sessionSampleRate) + ) { return undefined; } const proxy = validateOptionalString(initConfig.proxy); + const sessionSampleRate = initConfig.sessionSampleRate ?? 100; + const sessionOnError = validateOptionalBoolean(initConfig.sessionOnError, 'sessionOnError', false); + if (sessionOnError && sessionSampleRate === 100) { + displayWarn( + 'sessionOnError does not affect new sessions at sessionSampleRate 100. Resumed sessions retain their previous sampling decision.' + ); + } return { site, @@ -213,6 +259,8 @@ export function buildConfiguration(initConfig: InitConfiguration): Configuration env: validateOptionalString(initConfig.env), version: validateOptionalString(initConfig.version), proxy, + sessionSampleRate, + sessionOnError, telemetrySampleRate: validateTelemetrySampleRate(initConfig.telemetrySampleRate), defaultPrivacyLevel: validateDefaultPrivacyLevel(initConfig.defaultPrivacyLevel), allowedWebViewHosts: validateAllowedWebViewHosts(initConfig.allowedWebViewHosts), diff --git a/src/domain/UserContext.spec.ts b/src/domain/UserContext.spec.ts index 0d885701..ef1a3fd9 100644 --- a/src/domain/UserContext.spec.ts +++ b/src/domain/UserContext.spec.ts @@ -266,7 +266,11 @@ describe('UserContext', () => { context.set(ALICE); await vi.advanceTimersByTimeAsync(0); - expect(mfs.writeFile).toHaveBeenCalledWith('/mock/user/data/_dd_user_history', expect.any(String), 'utf-8'); + expect(mfs.writeFile).toHaveBeenCalledWith( + expect.stringContaining('/mock/user/data/_dd_user_history.'), + expect.any(String), + 'utf-8' + ); }); it('should resolve an identity recorded by a previous run', async () => { diff --git a/src/domain/rum/RumCollection.ts b/src/domain/rum/RumCollection.ts index 65ab408c..579a0264 100644 --- a/src/domain/rum/RumCollection.ts +++ b/src/domain/rum/RumCollection.ts @@ -2,9 +2,10 @@ import { EventManager } from '../../event'; import type { FormatHooks } from '../../assembly'; import { ErrorCollection, CrashCollection, ProcessGoneCollection } from './error'; import { OperationCollection } from './operation'; -import { ViewCollection } from './view'; +import { ViewCollection, ViewContext } from './view'; import type { RendererRegistry } from '../RendererRegistry'; import type { StackPathNormalizer } from '../StackPathNormalizer'; +import type { SessionManager } from '../session'; export class RumCollection { private constructor( @@ -18,13 +19,16 @@ export class RumCollection { eventManager: EventManager, hooks: FormatHooks, rendererRegistry: RendererRegistry, - stackPathNormalizer: StackPathNormalizer + stackPathNormalizer: StackPathNormalizer, + sessionManager: SessionManager, + writtenToDisk: () => Promise ): Promise { - const viewCollection = await ViewCollection.start(eventManager, hooks); + const viewContext = await ViewContext.init(hooks); + const viewCollection = ViewCollection.start(eventManager, viewContext); const errorCollection = new ErrorCollection(eventManager, stackPathNormalizer); const operationCollection = new OperationCollection(eventManager); const processGoneCollection = new ProcessGoneCollection(eventManager, rendererRegistry); - CrashCollection.start(eventManager); + CrashCollection.start(eventManager, sessionManager, (startTime) => viewContext.findView(startTime), writtenToDisk); return new RumCollection(viewCollection, errorCollection, operationCollection, processGoneCollection); } diff --git a/src/domain/rum/error/CrashCollection.spec.ts b/src/domain/rum/error/CrashCollection.spec.ts index 0f839f1c..5d9a8d90 100644 --- a/src/domain/rum/error/CrashCollection.spec.ts +++ b/src/domain/rum/error/CrashCollection.spec.ts @@ -36,12 +36,14 @@ import { describe, it, expect, vi, beforeEach, afterEach } from 'vitest'; import { crashReporter } from 'electron'; import { type TimeStamp } from '@flashcatcloud/browser-core'; import { CrashCollection } from './CrashCollection'; +import type { MainView } from '../view'; import { EventManager, EventKind, EventFormat, type RawRumEvent } from '../../../event'; import { processMinidump } from '../../../wasm'; import type { CrashReport } from '../../../wasm'; import type { RawRumError } from '../rawRumData.types'; import { displayError } from '../../../tools/display'; import { addError } from '../../telemetry'; +import { type SessionManager, type SessionRecord, TrackingType } from '../../session'; vi.mock('node:fs/promises'); const mfs = mockFs(); @@ -91,8 +93,35 @@ function mockDmpFile(name = 'crash.dmp', birthtimeMs = 0) { mfs.unlink.mockResolvedValue(undefined); } -async function startAndFlush(eventManager: EventManager) { - CrashCollection.start(eventManager); +/** A session that is always collected, and a main-process view that always exists. */ +const TRACKED_SESSION_MANAGER = { + findSession: () => ({ id: 'session-id', trackingType: TrackingType.TRACKED, sampleRate: 0 }), + getSession: () => ({ + id: 'session-id', + trackingType: TrackingType.TRACKED, + sampleRate: 0, + status: 'active' as const, + }), + setSessionHasError: vi.fn(), +}; + +function startCollection( + eventManager: EventManager, + sessionManager: Pick = TRACKED_SESSION_MANAGER +) { + return CrashCollection.start( + eventManager, + sessionManager, + () => ({ id: 'main-view-id', startTime: 0 as TimeStamp }), + () => Promise.resolve() + ); +} + +async function startAndFlush( + eventManager: EventManager, + sessionManager?: Pick +) { + startCollection(eventManager, sessionManager); resolveWhenReady(); await vi.advanceTimersToNextTimerAsync(); } @@ -121,7 +150,7 @@ describe('CrashCollection', () => { }); it('starts the native crash reporter', () => { - CrashCollection.start(eventManager); + startCollection(eventManager); // eslint-disable-next-line @typescript-eslint/unbound-method expect(crashReporter.start).toHaveBeenCalledWith({ uploadToServer: false, ignoreSystemCrashHandler: true }); @@ -782,4 +811,127 @@ describe('CrashCollection', () => { expect(first.error.fingerprint).toBe('SIGSEGV|MyApp|0x12ab3c'); expect(second.error.fingerprint).toBe(first.error.fingerprint); }); + + describe('a crash of a session kept by sessionOnError', () => { + const VIEW_START = 400 as TimeStamp; + const CRASH_TIME = 1000 as TimeStamp; + let calls: string[]; + + const WITHHELD: SessionRecord = { id: 'withheld', trackingType: TrackingType.TRACKED_ON_ERROR, sampleRate: 0 }; + const NEXT_SESSION: SessionRecord = { id: 'next', trackingType: TrackingType.TRACKED, sampleRate: 100 }; + + /** `session` is the one the crash happened in; `current` the one in force now. */ + function sessionManagerFor(session: SessionRecord | undefined, current: SessionRecord = NEXT_SESSION) { + return { + findSession: () => session, + getSession: () => ({ ...current, status: 'active' as const }), + setSessionHasError: vi.fn(() => calls.push('setSessionHasError')), + }; + } + + async function processCrash( + sessionManager: Pick, + findView: () => MainView | undefined = () => ({ id: 'crashed-view', startTime: VIEW_START }), + writtenToDisk: () => Promise = () => Promise.resolve() + ) { + mockDmpFile('crash.dmp', CRASH_TIME); + vi.mocked(processMinidump).mockResolvedValue(createMinidumpResult()); + eventManager.registerHandler({ + canHandle: (event): event is RawRumEvent => event.kind === EventKind.RAW, + handle: (event) => calls.push(event.data.type), + }); + CrashCollection.start(eventManager, sessionManager, findView, writtenToDisk); + resolveWhenReady(); + await vi.advanceTimersToNextTimerAsync(); + } + + beforeEach(() => { + calls = []; + }); + + it('releases a session that is over and had not reported an error, and rebuilds its view ahead of the crash', async () => { + const sessionManager = sessionManagerFor(WITHHELD); + + await processCrash(sessionManager); + + // Nothing of a session that is over is held, so the mark comes first: it is what lets the + // view and the crash pass assembly. + expect(sessionManager.setSessionHasError).toHaveBeenCalledWith('withheld', CRASH_TIME); + expect(calls).toEqual(['setSessionHasError', 'view', 'error']); + expect(rawRumEvents[0]).toMatchObject({ + startTime: VIEW_START, + data: { + type: 'view', + date: VIEW_START, + view: { id: 'crashed-view', is_active: false, error: { count: 1 }, time_spent: 600_000_000 }, + _dd: { document_version: 1 }, + }, + }); + expect((rawRumEvents[1].data as RawRumError).error.is_crash).toBe(true); + }); + + it('still releases the session and reports the crash, under a view of its own, when its view is gone from the history', async () => { + const sessionManager = sessionManagerFor(WITHHELD); + + await processCrash(sessionManager, () => undefined); + + expect(sessionManager.setSessionHasError).toHaveBeenCalledWith('withheld', CRASH_TIME); + expect(calls).toEqual(['setSessionHasError', 'error']); + const crash = rawRumEvents[0].data as RawRumError; + expect(crash.error.is_crash).toBe(true); + expect(typeof crash.view?.id).toBe('string'); + }); + + it('keeps the dump until its report is written to disk, and deletes it then', async () => { + let written!: () => void; + const writtenToDisk = () => new Promise((resolve) => (written = resolve)); + mfs.unlink.mockResolvedValue(undefined); + const processing = processCrash(sessionManagerFor(WITHHELD), undefined, writtenToDisk); + await vi.advanceTimersByTimeAsync(0); + + expect(calls).toContain('error'); + expect(mfs.unlink).not.toHaveBeenCalled(); + + written(); + await processing; + expect(mfs.unlink).toHaveBeenCalledWith('/mock/crash/dumps/crash.dmp'); + }); + + it('keeps the dump when its report could not be written, to report it on the next launch', async () => { + mfs.unlink.mockResolvedValue(undefined); + + await processCrash(sessionManagerFor(WITHHELD), undefined, () => Promise.reject(new Error('ENOSPC'))); + + expect(calls).toContain('error'); + expect(mfs.unlink).not.toHaveBeenCalled(); + }); + + it('leaves the mark to the release when the crashed session was resumed and is the current one', async () => { + const sessionManager = sessionManagerFor(WITHHELD, WITHHELD); + + await processCrash(sessionManager); + + // The rebuilt view and the crash join what this launch holds, and the mark lands when that + // is released — a mark now would say the view had reached the batch before it had. + expect(sessionManager.setSessionHasError).not.toHaveBeenCalled(); + expect(calls).toEqual(['view', 'error']); + }); + + it.each([ + ['a drawn session', { id: 'drawn', trackingType: TrackingType.TRACKED, sampleRate: 0 }], + [ + 'a session already released', + { id: 'released', trackingType: TrackingType.TRACKED_ON_ERROR, sampleRate: 0, hasError: true }, + ], + ['a session the draw did not keep', { id: 'not-kept', trackingType: TrackingType.NOT_TRACKED, sampleRate: 0 }], + ['no session at all', undefined], + ])('reports the crash alone for %s', async (_, session) => { + const sessionManager = sessionManagerFor(session as SessionRecord | undefined); + + await processCrash(sessionManager); + + expect(sessionManager.setSessionHasError).not.toHaveBeenCalled(); + expect(calls).toEqual(['error']); + }); + }); }); diff --git a/src/domain/rum/error/CrashCollection.ts b/src/domain/rum/error/CrashCollection.ts index 95a24c93..20be6a45 100644 --- a/src/domain/rum/error/CrashCollection.ts +++ b/src/domain/rum/error/CrashCollection.ts @@ -1,10 +1,12 @@ import * as path from 'node:path'; import * as fs from 'node:fs/promises'; -import { generateUUID, type TimeStamp } from '@flashcatcloud/browser-core'; +import { elapsed, generateUUID, toServerDuration, type TimeStamp } from '@flashcatcloud/browser-core'; import { app, crashReporter } from 'electron'; import { EventFormat, EventKind, EventManager, EventSource } from '../../../event'; import type { CrashReport } from '../../../wasm'; -import type { RawRumError } from '../rawRumData.types'; +import type { RawRumError, RawRumView } from '../rawRumData.types'; +import { type SessionManager, type SessionRecord, withholdsEvents } from '../../session'; +import type { MainView } from '../view'; import type { RumErrorEvent } from '../rumEvent.types'; import { displayError, displayInfo } from '../../../tools/display'; import { addError, monitor } from '../../telemetry'; @@ -19,11 +21,22 @@ import { toIntakeTimeStamp } from '../../../tools/intakeTimeStamp'; * - emits RUM error events */ export class CrashCollection { - private constructor(private readonly eventManager: EventManager) {} + private constructor( + private readonly eventManager: EventManager, + private readonly sessionManager: Pick, + private readonly findView: (startTime: TimeStamp) => MainView | undefined, + /** Resolves once everything handed to the transport so far is in a batch file. */ + private readonly writtenToDisk: () => Promise + ) {} - static start(eventManager: EventManager): CrashCollection { + static start( + eventManager: EventManager, + sessionManager: Pick, + findView: (startTime: TimeStamp) => MainView | undefined, + writtenToDisk: () => Promise + ): CrashCollection { crashReporter.start({ uploadToServer: false, ignoreSystemCrashHandler: true }); - const collection = new CrashCollection(eventManager); + const collection = new CrashCollection(eventManager, sessionManager, findView, writtenToDisk); // TODO(RUM-15046): wait for app to be stable (electron + browser windows) void app.whenReady().then(monitor(() => collection.processCrashFiles())); return collection; @@ -42,6 +55,12 @@ export class CrashCollection { displayInfo(`${dmpFiles.length} crash dumps to process`); for (const filePath of dmpFiles) { + // The dump is the only durable copy of the crash until its report is in a batch file: a + // dump whose report could not be written is kept for the next launch to report. The flush + // reports any append that failed since the last one, not this report's alone, so a kept + // dump may be one whose report did land — and the crash is then reported twice. A duplicate + // is preferred over losing it. + let reportWritten = true; try { const fileStat = await fs.stat(filePath); // birthtimeMs can be 0 on Linux (ext4), fall back to mtimeMs. @@ -51,22 +70,96 @@ export class CrashCollection { const bytes = new Uint8Array(await fs.readFile(filePath)); const crashReport = await processMinidump(bytes); + const session = this.sessionManager.findSession(crashTime); + const view = this.findView(crashTime); + this.releaseWithheldSession(session, view, crashTime); this.eventManager.notify({ kind: EventKind.RAW, source: EventSource.MAIN, format: EventFormat.RUM, - data: buildCrashErrorEvent(crashReport, crashTime), + // Under the view it happened in — or, when that view is gone from the history, under a + // view of its own: a session must not lose its crash for want of a container. + data: buildCrashErrorEvent(crashReport, crashTime, view?.id ?? generateUUID()), startTime: crashTime, }); + try { + await this.writtenToDisk(); + } catch (error) { + reportWritten = false; + throw error; + } } catch (error) { addError(error); displayError('Failed to process crash dump:', filePath, error); } finally { - await discardCrashFile(filePath); + if (reportWritten) { + await discardCrashFile(filePath); + } } } displayInfo(`Crash dump processing done.`); } + + /** + * A crash is reported a launch after it happened, by which time a session kept by `sessionOnError` + * has lost everything it held in memory — including the view the crash hangs from, which the + * backend needs to build the session at all. So when the crashed session had not reported an error + * by the time it crashed, the crash releases it, and its view is rebuilt from the view history to + * go with it. Judged as of the crash: an error the same session reported since, after a restart + * resumed it, released this launch's views, not the one the crash happened in. + * + * This is all the history such a crash gets: keeping the withheld buffer on disk instead would + * cost a session that never errors constant writes. When the view itself is gone from the + * history, the session is still released and the crash goes alone. + */ + private releaseWithheldSession( + session: SessionRecord | undefined, + view: MainView | undefined, + crashTime: TimeStamp + ): void { + if (!session || !withholdsEvents(session)) { + return; + } + const current = this.sessionManager.getSession(); + if (!(current.status === 'active' && current.id === session.id)) { + // A session that is over has nothing held for it, so the view and the crash go straight to + // the batch: marking it first is what lets them pass assembly, and it is as good as released. + // A session resumed since is another matter: what it holds, these two included, leaves at + // the release the crash earns it, and the mark belongs there — a mark written now would tell + // a crash of this launch that the view had reached the batch when it had not. + this.sessionManager.setSessionHasError(session.id, crashTime); + } + if (!view) { + return; + } + this.eventManager.notify({ + kind: EventKind.RAW, + source: EventSource.MAIN, + format: EventFormat.RUM, + data: buildMainViewEvent(view, crashTime), + startTime: view.startTime, + }); + } +} + +/** + * The crashed view as of the crash. Its earlier updates were never uploaded, so this is the first + * version the backend sees. + */ +function buildMainViewEvent(view: MainView, crashTime: TimeStamp): RawRumView { + return { + type: 'view', + date: view.startTime, + view: { + id: view.id, + time_spent: toServerDuration(elapsed(view.startTime, crashTime)), + is_active: false, + action: { count: 0 }, + error: { count: 1 }, + resource: { count: 0 }, + }, + _dd: { document_version: 1 }, + }; } /** @@ -118,7 +211,7 @@ function calculateMaxAddress(baseAddress: string | undefined, size: number | und * binary images and system info are all available, only the exception type, the * faulting address and the crashed thread are unknown. */ -function buildCrashErrorEvent(crashReport: CrashReport, crashTime: TimeStamp): RawRumError { +function buildCrashErrorEvent(crashReport: CrashReport, crashTime: TimeStamp, viewId: string): RawRumError { const threads = formatThreads(crashReport); const crashedThread = threads.find((t) => t.crashed); const exceptionType = crashReport.crash_info?.type; @@ -134,6 +227,7 @@ function buildCrashErrorEvent(crashReport: CrashReport, crashTime: TimeStamp): R return { date: crashTime, type: 'error', + view: { id: viewId }, error: { id: generateUUID(), message: 'Application crashed', diff --git a/src/domain/rum/error/ErrorCollection.spec.ts b/src/domain/rum/error/ErrorCollection.spec.ts index b66cadbc..8aa5820b 100644 --- a/src/domain/rum/error/ErrorCollection.spec.ts +++ b/src/domain/rum/error/ErrorCollection.spec.ts @@ -1,6 +1,6 @@ import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest'; import { ErrorCollection } from './ErrorCollection'; -import { EventFormat, EventKind, EventManager, type RawRumEvent } from '../../../event'; +import { type Event, EventFormat, EventKind, EventManager, LifecycleKind, type RawRumEvent } from '../../../event'; import type { RawRumError } from '../rawRumData.types'; import { StackPathNormalizer } from '../../StackPathNormalizer'; @@ -61,6 +61,35 @@ describe('ErrorCollection', () => { }); }); + describe('application exit', () => { + function collectLifecycle(): string[] { + const seen: string[] = []; + eventManager.registerHandler({ + canHandle: (event): event is Event => event.kind === EventKind.LIFECYCLE || event.kind === EventKind.RAW, + handle: (event) => seen.push(event.kind === EventKind.LIFECYCLE ? event.lifecycle : event.kind), + }); + return seen; + } + + it('announces that the application may exit after an uncaught exception, once the error is out', () => { + errorCollection = new ErrorCollection(eventManager, stackPathNormalizer); + const seen = collectLifecycle(); + + process.emit('uncaughtException', new Error('test error')); + + expect(seen).toEqual([EventKind.RAW, LifecycleKind.APP_MAY_EXIT]); + }); + + it('does not after an unhandled rejection', () => { + errorCollection = new ErrorCollection(eventManager, stackPathNormalizer); + const seen = collectLifecycle(); + + process.emit('unhandledRejection', new Error('test error'), Promise.resolve()); + + expect(seen).toEqual([EventKind.RAW]); + }); + }); + describe('unhandledRejection', () => { it('emits an error event with correct fields from an Error rejection', () => { errorCollection = new ErrorCollection(eventManager, stackPathNormalizer); diff --git a/src/domain/rum/error/ErrorCollection.ts b/src/domain/rum/error/ErrorCollection.ts index 5ddedb8e..d73787c9 100644 --- a/src/domain/rum/error/ErrorCollection.ts +++ b/src/domain/rum/error/ErrorCollection.ts @@ -6,7 +6,7 @@ import { timeStampNow, toStackTraceString, } from '@flashcatcloud/browser-core'; -import { EventFormat, EventKind, EventManager, EventSource } from '../../../event'; +import { EventFormat, EventKind, EventManager, EventSource, LifecycleKind } from '../../../event'; import type { RawRumError } from '../rawRumData.types'; import { monitor } from '../../telemetry'; import type { StackPathNormalizer } from '../../StackPathNormalizer'; @@ -32,6 +32,7 @@ export interface ErrorOptions { */ export class ErrorCollection { private readonly errorListener: (error: unknown) => void; + private readonly uncaughtExceptionListener: (error: unknown) => void; constructor( private readonly eventManager: EventManager, @@ -44,7 +45,12 @@ export class ErrorCollection { nonErrorPrefix: 'Uncaught', }) ); - process.on('uncaughtException', this.errorListener); + this.uncaughtExceptionListener = monitor((error: unknown) => { + this.errorListener(error); + // After the error itself, so that whatever it released is handed over with it. + this.eventManager.notify({ kind: EventKind.LIFECYCLE, lifecycle: LifecycleKind.APP_MAY_EXIT, terminal: false }); + }); + process.on('uncaughtException', this.uncaughtExceptionListener); process.on('unhandledRejection', this.errorListener); } @@ -61,7 +67,7 @@ export class ErrorCollection { } stop(): void { - process.off('uncaughtException', this.errorListener); + process.off('uncaughtException', this.uncaughtExceptionListener); process.off('unhandledRejection', this.errorListener); } diff --git a/src/domain/rum/view/ViewCollection.spec.ts b/src/domain/rum/view/ViewCollection.spec.ts index a06bff73..7093785d 100644 --- a/src/domain/rum/view/ViewCollection.spec.ts +++ b/src/domain/rum/view/ViewCollection.spec.ts @@ -13,6 +13,7 @@ vi.mock('../../../tools/display', () => ({ import { describe, it, expect, vi, beforeEach, afterEach } from 'vitest'; import { type TimeStamp } from '@flashcatcloud/browser-core'; import { ViewCollection, SESSION_KEEP_ALIVE_INTERVAL, VIEW_UPDATE_THROTTLE_DELAY } from './ViewCollection'; +import { ViewContext } from './ViewContext'; import { EventManager, EventKind, @@ -21,6 +22,7 @@ import { EventTrack, LifecycleKind, type RawRumEvent, + type ServerRumEvent, } from '../../../event'; import { createFormatHooks, type FormatHooks } from '../../../assembly'; import { createServerRumEvent, createServerRumView } from '../../../mocks.specUtil'; @@ -52,7 +54,7 @@ describe('ViewCollection', () => { handle: (event) => rawRumEvents.push(event), }); - viewCollection = await ViewCollection.start(eventManager, hooks); + viewCollection = ViewCollection.start(eventManager, await ViewContext.init(hooks)); }); afterEach(() => { @@ -106,7 +108,7 @@ describe('ViewCollection', () => { handle: (event) => emitted.push(event), }); - const racyCollection = await ViewCollection.start(racyEventManager, racyHooks); + const racyCollection = ViewCollection.start(racyEventManager, await ViewContext.init(racyHooks)); getTime.mockRestore(); try { @@ -232,6 +234,11 @@ describe('ViewCollection', () => { }); }); + /** The main view's own id: only its own events count towards it. */ + function currentViewId() { + return (rawRumEvents[0].data as RawRumView).view.id; + } + describe('event counters', () => { it.each(['action', 'error', 'resource'] as const)( 'increments %s counter on corresponding ServerRumEvent', @@ -240,7 +247,7 @@ describe('ViewCollection', () => { kind: EventKind.SERVER, track: EventTrack.RUM, source: EventSource.MAIN, - data: createServerRumEvent(type), + data: createServerRumEvent(type, { view: { id: currentViewId() } }), }); expect(rawRumEvents).toHaveLength(2); @@ -250,6 +257,31 @@ describe('ViewCollection', () => { } ); + it("does not count another view's events, as a crash reported on the next launch is the view it happened in's", () => { + eventManager.notify({ + kind: EventKind.SERVER, + track: EventTrack.RUM, + source: EventSource.MAIN, + data: createServerRumEvent('error', { view: { id: 'previous-launch-view' } }), + }); + + // Only the initial event, no update + expect(rawRumEvents).toHaveLength(1); + }); + + it('leaves a telemetry event alone, view or not, as one assembled after the view closed has none', () => { + expect(() => + eventManager.notify({ + kind: EventKind.SERVER, + track: EventTrack.RUM, + data: { type: 'telemetry', telemetry: { type: 'log', status: 'error', message: 'boom' } }, + } as unknown as ServerRumEvent) + ).not.toThrow(); + + // Only the initial event, no update + expect(rawRumEvents).toHaveLength(1); + }); + it('does not count view type ServerEvents', () => { eventManager.notify({ kind: EventKind.SERVER, @@ -267,7 +299,7 @@ describe('ViewCollection', () => { kind: EventKind.SERVER, track: EventTrack.RUM, source: EventSource.RENDERER, - data: createServerRumEvent('error'), + data: createServerRumEvent('error', { view: { id: currentViewId() } }), }); // Only the initial event, no update @@ -293,7 +325,7 @@ describe('ViewCollection', () => { kind: EventKind.SERVER, track: EventTrack.RUM, source: EventSource.MAIN, - data: createServerRumEvent(type), + data: createServerRumEvent(type, { view: { id: currentViewId() } }), }); } diff --git a/src/domain/rum/view/ViewCollection.ts b/src/domain/rum/view/ViewCollection.ts index 8176b60c..47a1896a 100644 --- a/src/domain/rum/view/ViewCollection.ts +++ b/src/domain/rum/view/ViewCollection.ts @@ -18,10 +18,9 @@ import { LifecycleKind, ServerRumEvent, } from '../../../event'; -import type { FormatHooks } from '../../../assembly'; import { setInterval, throttle } from '../../telemetry'; import type { RawRumView } from '../rawRumData.types'; -import { ViewContext } from './ViewContext'; +import type { ViewContext } from './ViewContext'; export const SESSION_KEEP_ALIVE_INTERVAL = 5 * ONE_MINUTE; // throttle view updates to avoid bursts @@ -45,7 +44,6 @@ interface ViewState { */ export class ViewCollection { private currentView!: ViewState; - private viewContext!: ViewContext; private keepAliveIntervalId: ReturnType | undefined; private scheduleViewUpdate!: () => void; private cancelScheduledViewUpdate!: () => void; @@ -54,21 +52,20 @@ export class ViewCollection { constructor( private readonly eventManager: EventManager, - private readonly hooks: FormatHooks + private readonly viewContext: ViewContext ) {} - static async start(eventManager: EventManager, hooks: FormatHooks): Promise { - const collection = new ViewCollection(eventManager, hooks); - await collection.init(); + static start(eventManager: EventManager, viewContext: ViewContext): ViewCollection { + const collection = new ViewCollection(eventManager, viewContext); + collection.init(); return collection; } - private async init(): Promise { + private init(): void { const { throttled, cancel } = throttle(() => this.emitViewUpdate(), VIEW_UPDATE_THROTTLE_DELAY); this.scheduleViewUpdate = throttled; this.cancelScheduledViewUpdate = cancel; - this.viewContext = await ViewContext.init(this.hooks); this.createNewView(); this.lifecycleSubscription = this.eventManager.registerHandler({ @@ -154,11 +151,17 @@ export class ViewCollection { } const type = event.data.type; - if (type === 'action' || type === 'error' || type === 'resource') { - this.currentView.counters[type].count++; - this.currentView.documentVersion++; - this.scheduleViewUpdate(); + if (type !== 'action' && type !== 'error' && type !== 'resource') { + return; } + // Only the current view's own: a crash reported on the next launch belongs to the view it + // happened in, which is rebuilt with its own count. + if (event.data.view.id !== this.currentView.id) { + return; + } + this.currentView.counters[type].count++; + this.currentView.documentVersion++; + this.scheduleViewUpdate(); } private keepSessionAlive(): void { diff --git a/src/domain/rum/view/ViewContext.spec.ts b/src/domain/rum/view/ViewContext.spec.ts index 938f35f3..f8a8a5ff 100644 --- a/src/domain/rum/view/ViewContext.spec.ts +++ b/src/domain/rum/view/ViewContext.spec.ts @@ -43,6 +43,15 @@ describe('ViewContext', () => { expect(hooks.triggerRum({ eventType: 'view', startTime: T0 })).toBe(DISCARDED); }); + it('RUM hook takes the view the event names itself, as a crash does when its view is gone from the history', async () => { + const hooks = createFormatHooks(); + await ViewContext.init(hooks, EXPIRE_DELAY); + + expect(hooks.triggerRum({ eventType: 'error', startTime: T0, viewId: 'crash-own-view' })).toMatchObject({ + view: { id: 'crash-own-view' }, + }); + }); + it('span hook returns DISCARDED', async () => { const hooks = createFormatHooks(); await ViewContext.init(hooks, EXPIRE_DELAY); @@ -70,6 +79,16 @@ describe('ViewContext', () => { }); }); + it('RUM hook prefers the view in force over the one the event names', async () => { + const hooks = createFormatHooks(); + const context = await ViewContext.init(hooks, EXPIRE_DELAY); + context.add('view-in-force', T0); + + expect(hooks.triggerRum({ eventType: 'error', startTime: T0, viewId: 'named' })).toMatchObject({ + view: { id: 'view-in-force' }, + }); + }); + it('span hook returns view id', async () => { const hooks = createFormatHooks(); const context = await ViewContext.init(hooks, EXPIRE_DELAY); diff --git a/src/domain/rum/view/ViewContext.ts b/src/domain/rum/view/ViewContext.ts index 8a7e6a4d..4b43a0d6 100644 --- a/src/domain/rum/view/ViewContext.ts +++ b/src/domain/rum/view/ViewContext.ts @@ -7,6 +7,11 @@ import { SESSION_TIME_OUT_DELAY } from '../../session'; export const VIEW_HISTORY_FILE_NAME = '_dd_view_history'; +export interface MainView { + id: string; + startTime: TimeStamp; +} + export class ViewContext { private readonly history: DiskValueHistory; @@ -14,7 +19,9 @@ export class ViewContext { this.history = history; hooks.registerRum((params) => { - const id = this.history.find(params.startTime); + // The view in force at the time, or the one the event names itself when none was: a crash + // reported on the next launch is not lost for want of its view. + const id = this.history.find(params.startTime) ?? params.viewId; if (id === undefined) return DISCARDED; return { view: { id, name: 'main process', url: 'electron://main-process' } }; // TODO(RUM-14657) improve name / url }); @@ -38,6 +45,12 @@ export class ViewContext { return new ViewContext(history, hooks); } + /** The main-process view in force at `startTime`, or `undefined` when there was none. */ + findView(startTime: TimeStamp): MainView | undefined { + const entry = this.history.findEntry(startTime); + return entry && { id: entry.value, startTime: entry.startTime }; + } + add(id: string, startTime: TimeStamp = timeStampNow()): void { this.history.add(id, startTime); } diff --git a/src/domain/rum/view/index.ts b/src/domain/rum/view/index.ts index d65b0515..084ed3eb 100644 --- a/src/domain/rum/view/index.ts +++ b/src/domain/rum/view/index.ts @@ -1 +1,2 @@ export * from './ViewCollection'; +export { ViewContext, type MainView } from './ViewContext'; diff --git a/src/domain/session/SessionContext.spec.ts b/src/domain/session/SessionContext.spec.ts index 16bb6e2d..c4d7afce 100644 --- a/src/domain/session/SessionContext.spec.ts +++ b/src/domain/session/SessionContext.spec.ts @@ -11,7 +11,7 @@ vi.mock('../../tools/display', () => ({ import { describe, it, expect, vi, beforeEach, afterEach } from 'vitest'; import { DISCARDED, type TimeStamp } from '@flashcatcloud/browser-core'; import { createFormatHooks } from '../../assembly'; -import { SessionContext } from './SessionContext'; +import { SessionContext, TrackingType, withholdsEvents } from './SessionContext'; vi.mock('node:fs/promises'); const mfs = mockFs(); @@ -62,7 +62,7 @@ describe('SessionContext', () => { const hooks = createFormatHooks(); const context = await SessionContext.init(hooks, EXPIRE_DELAY); - context.add('session-abc'); + context.add({ id: 'session-abc', trackingType: TrackingType.TRACKED, sampleRate: 100 }); expect(hooks.triggerRum({ eventType: 'view', startTime: T0 })).toMatchObject({ session: { id: 'session-abc' }, @@ -73,7 +73,7 @@ describe('SessionContext', () => { const hooks = createFormatHooks(); const context = await SessionContext.init(hooks, EXPIRE_DELAY); - context.add('session-abc'); + context.add({ id: 'session-abc', trackingType: TrackingType.TRACKED, sampleRate: 100 }); expect(hooks.triggerSpan({ startTime: T0 })).toMatchObject({ meta: { @@ -86,7 +86,7 @@ describe('SessionContext', () => { const hooks = createFormatHooks(); const context = await SessionContext.init(hooks, EXPIRE_DELAY); - context.add('session-abc'); + context.add({ id: 'session-abc', trackingType: TrackingType.TRACKED, sampleRate: 100 }); expect(hooks.triggerTelemetry({ startTime: T0 })).toMatchObject({ session: { id: 'session-abc' }, @@ -97,9 +97,9 @@ describe('SessionContext', () => { const hooks = createFormatHooks(); const context = await SessionContext.init(hooks, EXPIRE_DELAY); - context.add('session-first'); // at T0 + context.add({ id: 'session-first', trackingType: TrackingType.TRACKED, sampleRate: 100 }); // at T0 vi.advanceTimersByTime(10); // advance to T10 - context.add('session-second'); // at T10 + context.add({ id: 'session-second', trackingType: TrackingType.TRACKED, sampleRate: 100 }); // at T10 expect(hooks.triggerRum({ eventType: 'view', startTime: 10 as TimeStamp })).toMatchObject({ session: { id: 'session-second' }, @@ -112,7 +112,7 @@ describe('SessionContext', () => { const hooks = createFormatHooks(); const context = await SessionContext.init(hooks, EXPIRE_DELAY); - context.add('session-abc'); // at T0 = 0 + context.add({ id: 'session-abc', trackingType: TrackingType.TRACKED, sampleRate: 100 }); // at T0 = 0 vi.advanceTimersByTime(10); // time is now 10 context.close(); // closed at T10 @@ -127,7 +127,7 @@ describe('SessionContext', () => { const context = await SessionContext.init(hooks, EXPIRE_DELAY); vi.advanceTimersByTime(10); // advance to T10 - context.add('session-abc'); // session started at T10 + context.add({ id: 'session-abc', trackingType: TrackingType.TRACKED, sampleRate: 100 }); // session started at T10 context.close(); // event at T0 (before session started at T10) → DISCARDED @@ -138,7 +138,7 @@ describe('SessionContext', () => { const hooks = createFormatHooks(); const context = await SessionContext.init(hooks, EXPIRE_DELAY); - context.add('session-abc'); // at T0 = 0 + context.add({ id: 'session-abc', trackingType: TrackingType.TRACKED, sampleRate: 100 }); // at T0 = 0 vi.advanceTimersByTime(10); // time is now 10 context.close(); // closed at T10 @@ -155,7 +155,7 @@ describe('SessionContext', () => { const context = await SessionContext.init(hooks, EXPIRE_DELAY); vi.advanceTimersByTime(10); // advance to T10 - context.add('session-abc'); // session started at T10 + context.add({ id: 'session-abc', trackingType: TrackingType.TRACKED, sampleRate: 100 }); // session started at T10 context.close(); // event at T0 (before session started at T10) → DISCARDED @@ -166,7 +166,7 @@ describe('SessionContext', () => { const hooks = createFormatHooks(); const context = await SessionContext.init(hooks, EXPIRE_DELAY); - context.add('session-abc'); // at T0 = 0 + context.add({ id: 'session-abc', trackingType: TrackingType.TRACKED, sampleRate: 100 }); // at T0 = 0 vi.advanceTimersByTime(10); context.close(); @@ -179,7 +179,7 @@ describe('SessionContext', () => { const hooks = createFormatHooks(); const context = await SessionContext.init(hooks, EXPIRE_DELAY); - context.add('session-abc'); // at T0 + context.add({ id: 'session-abc', trackingType: TrackingType.TRACKED, sampleRate: 100 }); // at T0 vi.advanceTimersByTime(10); // now T10 context.close(); // closed at T10 @@ -187,4 +187,212 @@ describe('SessionContext', () => { expect(hooks.triggerRum({ eventType: 'view', startTime: 20 as TimeStamp })).toBe(DISCARDED); }); }); + + describe('sampling', () => { + async function init() { + const hooks = createFormatHooks(); + const context = await SessionContext.init(hooks, EXPIRE_DELAY); + return { hooks, context }; + } + + it('discards the RUM events of a session the draw did not keep, and attributes its telemetry to no session', async () => { + const { hooks, context } = await init(); + context.add({ id: 'session-abc', trackingType: TrackingType.NOT_TRACKED, sampleRate: 50 }); + + expect(hooks.triggerRum({ eventType: 'error', startTime: T0 })).toBe(DISCARDED); + expect(hooks.triggerTelemetry({ startTime: T0 })).toBeUndefined(); + }); + + it('still attributes the telemetry of a withheld session', async () => { + const { hooks, context } = await init(); + context.add({ id: 'session-abc', trackingType: TrackingType.TRACKED_ON_ERROR, sampleRate: 50 }); + + expect(hooks.triggerTelemetry({ startTime: T0 })).toMatchObject({ session: { id: 'session-abc' } }); + }); + + it('reports the rate a drawn session was drawn at, and no on-error marker', async () => { + const { hooks, context } = await init(); + context.add({ id: 'session-abc', trackingType: TrackingType.TRACKED, sampleRate: 12.5 }); + + const view = hooks.triggerRum({ eventType: 'view', startTime: T0 }); + + expect(view).toMatchObject({ _dd: { configuration: { session_sample_rate: 12.5 } } }); + expect(view).not.toHaveProperty('session.sampled_for_error', true); + }); + + it('marks the views of a session kept on error, and reports a rate of 0 on every event', async () => { + const { hooks, context } = await init(); + context.add({ id: 'session-abc', trackingType: TrackingType.TRACKED_ON_ERROR, sampleRate: 20 }); + + const view = hooks.triggerRum({ eventType: 'view', startTime: T0 }); + const action = hooks.triggerRum({ eventType: 'action', startTime: T0 }); + + expect(view).toMatchObject({ + session: { id: 'session-abc', sampled_for_error: true }, + _dd: { configuration: { session_sample_rate: 0 } }, + }); + expect(action).toMatchObject({ _dd: { configuration: { session_sample_rate: 0 } } }); + expect(action).not.toHaveProperty('session.sampled_for_error', true); + }); + + it('keeps the marker and the rate of 0 once the session is released', async () => { + const { hooks, context } = await init(); + context.add({ id: 'session-abc', trackingType: TrackingType.TRACKED_ON_ERROR, sampleRate: 20 }); + context.setHasError('session-abc', T0); + + expect(hooks.triggerRum({ eventType: 'view', startTime: T0 })).toMatchObject({ + session: { sampled_for_error: true }, + _dd: { configuration: { session_sample_rate: 0 } }, + }); + }); + + it('discards the stragglers of a withheld session that ended without an error', async () => { + const { hooks, context } = await init(); + context.add({ id: 'session-abc', trackingType: TrackingType.TRACKED_ON_ERROR, sampleRate: 100 }); + vi.advanceTimersByTime(10); + context.close(); + + expect(hooks.triggerRum({ eventType: 'resource', startTime: T0 })).toBe(DISCARDED); + }); + + it('lets the stragglers of a released session through', async () => { + const { hooks, context } = await init(); + context.add({ id: 'session-abc', trackingType: TrackingType.TRACKED_ON_ERROR, sampleRate: 100 }); + context.setHasError('session-abc', T0); + vi.advanceTimersByTime(10); + context.close(); + + expect(hooks.triggerRum({ eventType: 'resource', startTime: T0 })).toMatchObject({ + session: { id: 'session-abc' }, + }); + }); + + it('lets a crash of an earlier launch through once it is marked, after the session ended', async () => { + const { hooks, context } = await init(); + context.add({ id: 'session-abc', trackingType: TrackingType.TRACKED_ON_ERROR, sampleRate: 100 }); // at T0 + vi.advanceTimersByTime(10); + context.close(); + context.add({ id: 'session-next', trackingType: TrackingType.TRACKED, sampleRate: 100 }); // at T10 + + expect(hooks.triggerRum({ eventType: 'error', startTime: T0 })).toBe(DISCARDED); + context.setHasError('session-abc', T0); + expect(hooks.triggerRum({ eventType: 'error', startTime: T0 })).toMatchObject({ session: { id: 'session-abc' } }); + }); + + it('marks the entry in force at the time of the error only, one launch of a resumed session at a time', async () => { + const { context } = await init(); + const T10 = 10 as TimeStamp; + context.add({ id: 'session-abc', trackingType: TrackingType.TRACKED_ON_ERROR, sampleRate: 0 }); // first launch, at T0 + vi.advanceTimersByTime(10); + context.add({ id: 'session-abc', trackingType: TrackingType.TRACKED_ON_ERROR, sampleRate: 0 }); // resumed, at T10 + + // An error of the current launch says nothing about what the earlier launch uploaded. + context.setHasError('session-abc', T10); + expect(withholdsEvents(context.find(T10)!)).toBe(false); + expect(withholdsEvents(context.find(T0)!)).toBe(true); + + // A crash of the earlier launch, reported now, does. + context.setHasError('session-abc', T0); + expect(withholdsEvents(context.find(T0)!)).toBe(false); + }); + + it('releases the current launch too when a crash of an earlier launch releases the session it resumed', async () => { + const { hooks, context } = await init(); + const T10 = 10 as TimeStamp; + context.add({ id: 'session-abc', trackingType: TrackingType.TRACKED_ON_ERROR, sampleRate: 0 }); // first launch, at T0 + vi.advanceTimersByTime(10); + context.add({ id: 'session-abc', trackingType: TrackingType.TRACKED_ON_ERROR, sampleRate: 0 }); // resumed, at T10 + + // The crash is the session's error: from now on everything of it is uploaded, this launch's + // events included — so once the session ends, its final view must not be read as a straggler. + context.setHasError('session-abc', T0); + vi.advanceTimersByTime(10); + context.close(); + + expect(hooks.triggerRum({ eventType: 'view', startTime: T10 })).toMatchObject({ session: { id: 'session-abc' } }); + }); + + it('marks nothing when the session in force at the time is another one', async () => { + const { context } = await init(); + context.add({ id: 'session-abc', trackingType: TrackingType.TRACKED_ON_ERROR, sampleRate: 0 }); + + context.setHasError('session-other', T0); + + expect(withholdsEvents(context.find(T0)!)).toBe(true); + }); + + it('persists the error mark', async () => { + const { context } = await init(); + context.add({ id: 'session-abc', trackingType: TrackingType.TRACKED_ON_ERROR, sampleRate: 100 }); + await vi.advanceTimersByTimeAsync(0); + mfs.writeFile.mockClear(); + + context.setHasError('session-abc', T0); + await vi.advanceTimersByTimeAsync(0); + + expect(mfs.writeFile).toHaveBeenCalledWith( + expect.stringContaining('_dd_session_history.'), + expect.stringContaining('"hasError":true'), + 'utf-8' + ); + }); + + it('does not mark, nor write, a session that withholds nothing', async () => { + const { context } = await init(); + context.add({ id: 'session-abc', trackingType: TrackingType.TRACKED, sampleRate: 100 }); + await vi.advanceTimersByTimeAsync(0); + mfs.writeFile.mockClear(); + + context.setHasError('session-abc', T0); + await vi.advanceTimersByTimeAsync(0); + + expect(mfs.writeFile).not.toHaveBeenCalled(); + expect(context.find(T0)).not.toHaveProperty('hasError'); + }); + + it('restores the sampling of past sessions from disk, for a crash reported on the next launch', async () => { + mfs.readFile.mockResolvedValue( + JSON.stringify([ + { startTime: 0, endTime: 5, value: { id: 'crashed', trackingType: '4', sampleRate: 0, hasError: true } }, + ]) + ); + const { hooks } = await init(); + + expect(hooks.triggerRum({ eventType: 'error', startTime: T0 })).toMatchObject({ + session: { id: 'crashed' }, + _dd: { configuration: { session_sample_rate: 0 } }, + }); + }); + + it.each([ + [ + 'a string where the error mark should be a boolean', + { id: 'bad', trackingType: '4', sampleRate: 0, hasError: 'false' }, + ], + ['an unknown tracking type', { id: 'bad', trackingType: 7, sampleRate: 0 }], + ['a rate that is not a finite number', { id: 'bad', trackingType: '2', sampleRate: null }], + ['no id', { trackingType: '2', sampleRate: 100 }], + ['a rate above 100', { id: 'bad', trackingType: '2', sampleRate: 150 }], + ['a negative rate', { id: 'bad', trackingType: '2', sampleRate: -1 }], + ['a null tracking type', { id: 'bad', trackingType: null, sampleRate: 0 }], + ])( + 'discards the events of a session whose saved record is malformed (%s), rather than uploading them', + async (_, value) => { + mfs.readFile.mockResolvedValue(JSON.stringify([{ startTime: 0, endTime: 5, value }])); + const { hooks } = await init(); + + expect(hooks.triggerRum({ eventType: 'error', startTime: T0 })).toBe(DISCARDED); + } + ); + + it('reads an entry written before sessions were sampled as a session drawn at 100', async () => { + mfs.readFile.mockResolvedValue(JSON.stringify([{ startTime: 0, endTime: 5, value: 'legacy-session' }])); + const { hooks } = await init(); + + expect(hooks.triggerRum({ eventType: 'error', startTime: T0 })).toMatchObject({ + session: { id: 'legacy-session' }, + _dd: { configuration: { session_sample_rate: 100 } }, + }); + }); + }); }); diff --git a/src/domain/session/SessionContext.ts b/src/domain/session/SessionContext.ts index 5069a9ea..bc0c2f50 100644 --- a/src/domain/session/SessionContext.ts +++ b/src/domain/session/SessionContext.ts @@ -1,48 +1,181 @@ import { app } from 'electron'; import * as path from 'node:path'; -import { DISCARDED, SKIPPED, timeStampNow } from '@flashcatcloud/browser-core'; +import { DISCARDED, SKIPPED, timeStampNow, type TimeStamp } from '@flashcatcloud/browser-core'; import type { FormatHooks } from '../../assembly'; import { DiskValueHistory } from '../../tools/DiskValueHistory'; import { SESSION_TIME_OUT_DELAY } from './session.constants'; export const SESSION_HISTORY_FILE_NAME = '_dd_session_history'; -export class SessionContext { - private readonly history: DiskValueHistory; +/** + * What the sampling draw decided for a session. It is drawn once, when the session is created, and + * kept for the session's whole life — a session resumed after a restart keeps the decision it was + * created with. + * + * The values are the browser SDK's tracking types. The ones that involve Session Replay do not + * exist here: the main process does not record. + */ +export const TrackingType = { + /** Not drawn: nothing is collected. */ + NOT_TRACKED: '0', + /** Drawn by `sessionSampleRate`: collected and uploaded as it happens. */ + TRACKED: '2', + /** + * Missed by `sessionSampleRate` but kept by `sessionOnError`: collected, held in memory, and + * uploaded only once the session reports an error. + */ + TRACKED_ON_ERROR: '4', +} as const; +export type TrackingType = (typeof TrackingType)[keyof typeof TrackingType]; - private constructor(history: DiskValueHistory, hooks: FormatHooks) { - this.history = history; +export interface SessionRecord { + id: string; + trackingType: TrackingType; + /** + * The `sessionSampleRate` the session was drawn at. Kept with the session because it is what the + * backend extrapolates a drawn session by: a session resumed under a configuration that changed + * the rate still stands for `100 / rate` sessions of the rate that drew it. + */ + sampleRate: number; + /** + * Set once a `TRACKED_ON_ERROR` session reports its first error, which releases what it withheld. + * Never set on any other session. + */ + hasError?: boolean; +} +/** Whether what this session collects is still being held back, waiting for an error. */ +export function withholdsEvents(record: SessionRecord): boolean { + return record.trackingType === TrackingType.TRACKED_ON_ERROR && !record.hasError; +} + +/** + * Resolves which session an event belongs to, by the event's own start time, and stamps the + * sampling attributes the backend reads off it. + * + * The history is kept on disk so that a native crash, reported on the next launch, is attributed — + * and sampled — as the session it happened in. + */ +export class SessionContext { + private activeSessionId: string | undefined; + + private constructor( + private readonly history: DiskValueHistory, + hooks: FormatHooks + ) { hooks.registerRum((params) => { - const id = this.history.find(params.startTime); - if (id === undefined) return DISCARDED; - return { session: { id } }; + const record = this.find(params.startTime); + if (record === undefined || record.trackingType === TrackingType.NOT_TRACKED) return DISCARDED; + // A withheld session that ended without an error had everything it held thrown away. An event + // of it assembled afterwards — a request that completed late, the final view update — would + // store the very session the withholding avoided. + if (withholdsEvents(record) && record.id !== this.activeSessionId) return DISCARDED; + + const sampledForError = record.trackingType === TrackingType.TRACKED_ON_ERROR; + return { + session: { + id: record.id, + // Tells the backend this session's detail only starts where the buffer reached. Views + // only: the backend reads session attributes off them. + sampled_for_error: sampledForError && params.eventType === 'view' ? true : undefined, + }, + // A session kept only because it errored stands for itself, not for `100 / rate` sessions + // like a drawn one: 0 is what the backend reads as "do not extrapolate". Derived from the + // record, so a resumed session and a crash reported a launch later get it too. + _dd: { configuration: { session_sample_rate: sampledForError ? 0 : record.sampleRate } }, + }; }); hooks.registerTelemetry((params) => { - const id = this.history.find(params.startTime); - if (id === undefined) return SKIPPED; - return { session: { id } }; + const record = this.find(params.startTime); + // Telemetry is the SDK's own data and leaves either way; a session that is not collected is + // simply nothing to attribute it to, as in the browser SDK. + if (record === undefined || record.trackingType === TrackingType.NOT_TRACKED) return SKIPPED; + return { session: { id: record.id } }; }); hooks.registerSpan((params) => { - const id = this.history.find(params.startTime); - if (id === undefined) return DISCARDED; - return { meta: { '_dd.session.id': id } }; + const record = this.find(params.startTime); + if (record === undefined) return DISCARDED; + return { meta: { '_dd.session.id': record.id } }; }); } static async init(hooks: FormatHooks, expireDelay = SESSION_TIME_OUT_DELAY): Promise { const filePath = path.join(app.getPath('userData'), SESSION_HISTORY_FILE_NAME); - const history = await DiskValueHistory.init({ filePath, expireDelay }); + const history = await DiskValueHistory.init({ filePath, expireDelay }); return new SessionContext(history, hooks); } - add(sessionId: string): void { - this.history.add(sessionId, timeStampNow()); + /** The session in force at `startTime`, or `undefined` when there was none. */ + find(startTime: TimeStamp): SessionRecord | undefined { + return toSessionRecord(this.history.find(startTime)); + } + + /** Writes the history before returning, for a process that may be about to exit. */ + persistSync(): void { + this.history.persistSync(); + } + + add(record: SessionRecord): void { + this.activeSessionId = record.id; + this.history.add(record, timeStampNow()); } close(): void { + this.activeSessionId = undefined; this.history.closeActive(timeStampNow()); } + + /** + * Record that a withheld session reported an error at `errorTime`: on the entry in force then, + * and on the active entry when the session is the current one, since from now on everything of + * it is uploaded. + * + * Not on every entry of the session: a session resumed after a restart has one entry per launch, + * and whether the earlier launch's entry still withholds is what tells a crash reported now that + * nothing of that launch — the view the crash happened in, to begin with — ever reached the + * intake. An error of the current launch must not answer that question for the earlier one. + */ + setHasError(sessionId: string, errorTime: TimeStamp): void { + const entries = [this.history.find(errorTime)]; + if (sessionId === this.activeSessionId) { + entries.push(this.history.find(timeStampNow())); + } + let changed = false; + for (const record of entries.map(parseSessionRecord)) { + if (record?.id === sessionId && withholdsEvents(record)) { + record.hasError = true; + changed = true; + } + } + if (changed) { + this.history.persist(); + } + } +} + +/** + * Entries written before sessions were sampled hold the bare session id. Every session was + * collected then, and a session keeps the decision it was created with. Anything else must be a + * well-formed record: a malformed one — a corrupt file, a hand edit — is no session at all, so its + * events are discarded rather than uploaded under a draw that was never made. + */ +function toSessionRecord(value: unknown): SessionRecord | undefined { + return typeof value === 'string' + ? { id: value, trackingType: TrackingType.TRACKED, sampleRate: 100 } + : parseSessionRecord(value); +} + +const TRACKING_TYPES = new Set(Object.values(TrackingType)); + +/** The record `value` is, or `undefined` when it is not one: a non-empty id, a known type, a rate from 0 to 100, a boolean mark. */ +export function parseSessionRecord(value: unknown): SessionRecord | undefined { + if (typeof value !== 'object' || value === null) return undefined; + const { id, trackingType, sampleRate, hasError } = value as Record; + if (typeof id !== 'string' || id === '') return undefined; + if (!TRACKING_TYPES.has(trackingType)) return undefined; + if (typeof sampleRate !== 'number' || !(sampleRate >= 0 && sampleRate <= 100)) return undefined; + if (hasError !== undefined && typeof hasError !== 'boolean') return undefined; + return value as SessionRecord; } diff --git a/src/domain/session/SessionManager.spec.ts b/src/domain/session/SessionManager.spec.ts index 9d3e9d55..9ac7347d 100644 --- a/src/domain/session/SessionManager.spec.ts +++ b/src/domain/session/SessionManager.spec.ts @@ -1,5 +1,11 @@ import { mockFs } from '../../mocks.specUtil'; vi.mock('node:fs/promises'); +const { writeFileSync, renameSync, unlinkSync } = vi.hoisted(() => ({ + writeFileSync: vi.fn(), + renameSync: vi.fn(), + unlinkSync: vi.fn(), +})); +vi.mock('node:fs', () => ({ writeFileSync, renameSync, unlinkSync })); vi.mock('electron', () => ({ app: { getPath: vi.fn(() => '/mock/user/data'), @@ -11,12 +17,20 @@ vi.mock('../../tools/display', () => ({ displayError: vi.fn(), })); +vi.mock('../telemetry', async (importOriginal) => ({ + ...(await importOriginal()), + addError: vi.fn(), +})); + import { describe, it, expect, vi, beforeEach, afterEach } from 'vitest'; +import { addError } from '../telemetry'; import { type TimeStamp } from '@flashcatcloud/browser-core'; import { SessionManager, SESSION_EXPIRATION_DELAY, SESSION_FILE_NAME } from './SessionManager'; import { SESSION_TIME_OUT_DELAY } from './session.constants'; +import { TrackingType } from './SessionContext'; const T0 = 0 as TimeStamp; +const SAMPLING = { sessionSampleRate: 100, sessionOnError: false }; import { EventManager, EventKind, LifecycleKind, type LifecycleEvent } from '../../event'; import { createFormatHooks, type FormatHooks } from '../../assembly'; @@ -56,7 +70,7 @@ describe('sessionManager', () => { it('creates new session when no file exists', async () => { mockNoSessionFile(); - sessionManager = await SessionManager.start(eventManager, hooks); + sessionManager = await SessionManager.start(eventManager, hooks, SAMPLING); expect(sessionManager.getSession().id).toMatch(/^[0-9a-f-]+$/); expect(sessionManager.getSession().status).toBe('active'); @@ -80,7 +94,7 @@ describe('sessionManager', () => { mfs.readFile.mockResolvedValue(JSON.stringify(existingState)); - sessionManager = await SessionManager.start(eventManager, hooks); + sessionManager = await SessionManager.start(eventManager, hooks, SAMPLING); expect(sessionManager.getSession().id).toBe('existing-session-id'); expect(sessionManager.getSession().status).toBe('active'); @@ -96,7 +110,7 @@ describe('sessionManager', () => { mfs.readFile.mockResolvedValue(JSON.stringify(existingState)); - sessionManager = await SessionManager.start(eventManager, hooks); + sessionManager = await SessionManager.start(eventManager, hooks, SAMPLING); expect(sessionManager.getSession().id).not.toBe('expired-session-id'); expect(sessionManager.getSession().status).toBe('active'); @@ -112,7 +126,7 @@ describe('sessionManager', () => { mfs.readFile.mockResolvedValue(JSON.stringify(existingState)); - sessionManager = await SessionManager.start(eventManager, hooks); + sessionManager = await SessionManager.start(eventManager, hooks, SAMPLING); expect(sessionManager.getSession().id).not.toBe('timed-out-session-id'); expect(sessionManager.getSession().status).toBe('active'); @@ -130,7 +144,7 @@ describe('sessionManager', () => { .mockResolvedValueOnce(JSON.stringify(expiredState)) // _dd_s .mockResolvedValueOnce(JSON.stringify([{ startTime: 0, endTime: null, value: 'expired-session-id' }])); // _dd_session_history - sessionManager = await SessionManager.start(eventManager, hooks); + sessionManager = await SessionManager.start(eventManager, hooks, SAMPLING); const newSessionId = sessionManager.getSession().id; expect(newSessionId).not.toBe('expired-session-id'); @@ -151,14 +165,14 @@ describe('sessionManager', () => { it('expires session after inactivity delay', async () => { mockNoSessionFile(); - sessionManager = await SessionManager.start(eventManager, hooks); + sessionManager = await SessionManager.start(eventManager, hooks, SAMPLING); expect(sessionManager.getSession().status).toBe('active'); await vi.advanceTimersByTimeAsync(SESSION_EXPIRATION_DELAY); expect(sessionManager.getSession().status).toBe('expired'); - expect(mfs.unlink).toHaveBeenCalled(); + expect(unlinkSync).toHaveBeenCalled(); expect(lifecycleEvents).toContain(LifecycleKind.SESSION_EXPIRED); }); @@ -166,7 +180,7 @@ describe('sessionManager', () => { const now = Date.now(); mockNoSessionFile(); - sessionManager = await SessionManager.start(eventManager, hooks); + sessionManager = await SessionManager.start(eventManager, hooks, SAMPLING); const sessionId = sessionManager.getSession().id; @@ -200,7 +214,7 @@ describe('sessionManager', () => { const startTime = Date.now(); mockNoSessionFile(); - sessionManager = await SessionManager.start(eventManager, hooks); + sessionManager = await SessionManager.start(eventManager, hooks, SAMPLING); const sessionId = sessionManager.getSession().id; expect(sessionId).toBeDefined(); @@ -245,7 +259,7 @@ describe('sessionManager', () => { it('creates new session on activity when expired', async () => { mockNoSessionFile(); - sessionManager = await SessionManager.start(eventManager, hooks); + sessionManager = await SessionManager.start(eventManager, hooks, SAMPLING); const originalSessionId = sessionManager.getSession().id; expect(sessionManager.getSession().status).toBe('active'); @@ -275,7 +289,7 @@ describe('sessionManager', () => { mfs.access.mockResolvedValue(undefined); mfs.readFile.mockRejectedValue(new Error('Read error')); - sessionManager = await SessionManager.start(eventManager, hooks); + sessionManager = await SessionManager.start(eventManager, hooks, SAMPLING); // Should create a new session despite read error @@ -286,19 +300,19 @@ describe('sessionManager', () => { mockNoSessionFile(); mfs.writeFile.mockRejectedValue(new Error('Write error')); - sessionManager = await SessionManager.start(eventManager, hooks); + sessionManager = await SessionManager.start(eventManager, hooks, SAMPLING); // Session should still be created in memory expect(sessionManager.getSession().status).toBe('active'); - expect(display.displayError).toHaveBeenCalledWith('Failed to save session state:', expect.any(Error)); + expect(display.displayError).toHaveBeenCalledWith('Failed to write session state:', expect.any(Error)); }); it('handles JSON parse errors gracefully', async () => { mfs.access.mockResolvedValue(undefined); mfs.readFile.mockResolvedValue('invalid json'); - sessionManager = await SessionManager.start(eventManager, hooks); + sessionManager = await SessionManager.start(eventManager, hooks, SAMPLING); // Should create a new session despite parse error @@ -310,15 +324,17 @@ describe('sessionManager', () => { it('sets session status to expired and clears timers', async () => { mockNoSessionFile(); - sessionManager = await SessionManager.start(eventManager, hooks); + sessionManager = await SessionManager.start(eventManager, hooks, SAMPLING); expect(sessionManager.getSession().status).toBe('active'); sessionManager.expire(); expect(sessionManager.getSession().status).toBe('expired'); - expect(mfs.unlink).toHaveBeenCalled(); expect(lifecycleEvents).toContain(LifecycleKind.SESSION_EXPIRED); + // The delete waits its turn behind the queued writes. + await vi.advanceTimersByTimeAsync(0); + expect(unlinkSync).toHaveBeenCalled(); }); }); @@ -326,7 +342,7 @@ describe('sessionManager', () => { it('RUM hook returns session id immediately after start()', async () => { mockNoSessionFile(); - sessionManager = await SessionManager.start(eventManager, hooks); + sessionManager = await SessionManager.start(eventManager, hooks, SAMPLING); const result = hooks.triggerRum({ eventType: 'view', startTime: T0 }); expect(result).toMatchObject({ session: { id: sessionManager.getSession().id } }); @@ -335,7 +351,7 @@ describe('sessionManager', () => { it('telemetry hook returns session id immediately after start()', async () => { mockNoSessionFile(); - sessionManager = await SessionManager.start(eventManager, hooks); + sessionManager = await SessionManager.start(eventManager, hooks, SAMPLING); const result = hooks.triggerTelemetry({ startTime: T0 }); expect(result).toMatchObject({ session: { id: sessionManager.getSession().id } }); @@ -346,7 +362,7 @@ describe('sessionManager', () => { it('should not allow to mutate the current session', async () => { mockNoSessionFile(); - sessionManager = await SessionManager.start(eventManager, hooks); + sessionManager = await SessionManager.start(eventManager, hooks, SAMPLING); const session = sessionManager.getSession(); session.id = 'new-id'; @@ -354,4 +370,436 @@ describe('sessionManager', () => { expect(sessionManager.getSession().id).not.toBe('new-id'); }); }); + + describe('sampling', () => { + afterEach(() => { + vi.restoreAllMocks(); + }); + + function savedSessionStates(): Record[] { + return mfs.writeFile.mock.calls + .filter(([filePath]) => (filePath as string).includes(`/${SESSION_FILE_NAME}.`)) + .map(([, content]) => JSON.parse(content as string) as Record); + } + + it.each([ + { sessionSampleRate: 100, sessionOnError: false, random: 0.99, expected: TrackingType.TRACKED }, + { sessionSampleRate: 100, sessionOnError: true, random: 0.99, expected: TrackingType.TRACKED }, + { sessionSampleRate: 50, sessionOnError: true, random: 0.2, expected: TrackingType.TRACKED }, + { sessionSampleRate: 50, sessionOnError: true, random: 0.8, expected: TrackingType.TRACKED_ON_ERROR }, + { sessionSampleRate: 50, sessionOnError: false, random: 0.8, expected: TrackingType.NOT_TRACKED }, + { sessionSampleRate: 0, sessionOnError: true, random: 0, expected: TrackingType.TRACKED_ON_ERROR }, + { sessionSampleRate: 0, sessionOnError: false, random: 0, expected: TrackingType.NOT_TRACKED }, + ])( + 'draws $expected at rate $sessionSampleRate with sessionOnError $sessionOnError (random $random)', + async ({ sessionSampleRate, sessionOnError, random, expected }) => { + mockNoSessionFile(); + vi.spyOn(Math, 'random').mockReturnValue(random); + + sessionManager = await SessionManager.start(eventManager, hooks, { sessionSampleRate, sessionOnError }); + + expect(sessionManager.getSession()).toMatchObject({ trackingType: expected, sampleRate: sessionSampleRate }); + expect(savedSessionStates()[0]).toMatchObject({ trackingType: expected, sampleRate: sessionSampleRate }); + } + ); + + it('does not write back a state read before the session ended', async () => { + mockNoSessionFile(); + sessionManager = await SessionManager.start(eventManager, hooks, SAMPLING); + const { id } = sessionManager.getSession(); + let finishRead!: (content: string) => void; + mfs.access.mockResolvedValue(undefined); + mfs.readFile.mockImplementationOnce(() => new Promise((resolve) => (finishRead = resolve))); + mfs.unlink.mockResolvedValue(undefined); + mfs.writeFile.mockClear(); + + // An activity update starts reading the state, and the session ends before the read completes. + eventManager.notify({ kind: EventKind.LIFECYCLE, lifecycle: LifecycleKind.END_USER_ACTIVITY }); + await vi.advanceTimersByTimeAsync(0); + sessionManager.expire(); + finishRead( + JSON.stringify({ id, created: 0, lastActivity: 0, trackingType: TrackingType.TRACKED, sampleRate: 100 }) + ); + await vi.advanceTimersByTimeAsync(0); + + expect(savedSessionStates()).toEqual([]); + }); + + it('closes the previous launch of a resumed session in the history, so the file does not grow with every launch', async () => { + const now = Date.now(); + mfs.readFile.mockImplementation((filePath: string) => + Promise.resolve( + filePath.endsWith(SESSION_FILE_NAME) + ? JSON.stringify({ + id: 'existing', + created: now, + lastActivity: now, + trackingType: TrackingType.TRACKED, + sampleRate: 100, + }) + : JSON.stringify([ + { startTime: now - 10, endTime: null, value: { id: 'existing', trackingType: '2', sampleRate: 100 } }, + ]) + ) + ); + + sessionManager = await SessionManager.start(eventManager, hooks, SAMPLING); + await vi.advanceTimersByTimeAsync(0); + + const histories = mfs.writeFile.mock.calls + .filter(([filePath]) => (filePath as string).includes('/_dd_session_history.')) + .map(([, content]) => JSON.parse(content as string) as { endTime: number | null; startTime: number }[]); + const latest = histories[histories.length - 1]; + expect(latest).toHaveLength(2); + // Newest first: this launch's entry open, the previous launch's closed at this launch. + expect(latest[0]).toMatchObject({ startTime: now, endTime: null }); + expect(latest[1]).toMatchObject({ startTime: now - 10, endTime: now }); + // Events of the previous launch still resolve to it. + expect(hooks.triggerRum({ eventType: 'error', startTime: (now - 5) as TimeStamp })).toMatchObject({ + session: { id: 'existing' }, + }); + }); + + it('reports the rate a resumed session was drawn at, not the one configured since', async () => { + const now = Date.now(); + mfs.readFile.mockResolvedValue( + JSON.stringify({ + id: 'existing', + created: now, + lastActivity: now, + trackingType: TrackingType.TRACKED, + sampleRate: 10, + }) + ); + + sessionManager = await SessionManager.start(eventManager, hooks, SAMPLING); + + expect(hooks.triggerRum({ eventType: 'view', startTime: now as TimeStamp })).toMatchObject({ + _dd: { configuration: { session_sample_rate: 10 } }, + }); + }); + + it('keeps the decision a resumed session was created with, whatever the configuration says now', async () => { + const now = Date.now(); + mfs.readFile.mockResolvedValue( + JSON.stringify({ + id: 'existing', + created: now, + lastActivity: now, + trackingType: TrackingType.TRACKED_ON_ERROR, + sampleRate: 0, + }) + ); + + sessionManager = await SessionManager.start(eventManager, hooks, { + sessionSampleRate: 100, + sessionOnError: false, + }); + + expect(sessionManager.getSession()).toMatchObject({ + id: 'existing', + trackingType: TrackingType.TRACKED_ON_ERROR, + }); + // Derived from the tracking type on the restore path too, not from the configured rate. + expect(hooks.triggerRum({ eventType: 'view', startTime: now as TimeStamp })).toMatchObject({ + session: { id: 'existing', sampled_for_error: true }, + _dd: { configuration: { session_sample_rate: 0 } }, + }); + }); + + it('resumes a session that had already reported its error as released', async () => { + const now = Date.now(); + mfs.readFile.mockResolvedValue( + JSON.stringify({ + id: 'existing', + created: now, + lastActivity: now, + trackingType: TrackingType.TRACKED_ON_ERROR, + sampleRate: 0, + hasError: true, + }) + ); + + sessionManager = await SessionManager.start(eventManager, hooks, SAMPLING); + + expect(sessionManager.getSession().hasError).toBe(true); + }); + + it.each([ + [ + 'a string where the error mark should be a boolean', + { trackingType: TrackingType.TRACKED_ON_ERROR, hasError: 'false' }, + ], + ['a tracking type that is not one of the known ones', { trackingType: 0 }], + ['a rate that is not a finite number', { trackingType: TrackingType.TRACKED, sampleRate: 'NaN' }], + ['no id', { id: '' }], + ])('starts a fresh session rather than resuming a saved state with %s', async (_, malformed) => { + const now = Date.now(); + mfs.readFile.mockResolvedValue( + JSON.stringify({ id: 'existing', created: now, lastActivity: now, sampleRate: 100, ...malformed }) + ); + + sessionManager = await SessionManager.start(eventManager, hooks, { sessionSampleRate: 0, sessionOnError: true }); + + expect(sessionManager.getSession().id).not.toBe('existing'); + expect(sessionManager.getSession().trackingType).toBe(TrackingType.TRACKED_ON_ERROR); + }); + + it.each([ + ['a null tracking type next to a rate', { trackingType: null, sampleRate: 0 }], + ['a rate without a tracking type', { sampleRate: 0 }], + ['a tracking type without a rate', { trackingType: TrackingType.TRACKED }], + ['an error mark without any sampling field', { hasError: true }], + ['a negative rate', { trackingType: TrackingType.TRACKED, sampleRate: -10 }], + ['a rate above 100', { trackingType: TrackingType.TRACKED, sampleRate: 150 }], + ])('starts a fresh session rather than reading a damaged state as a legacy one (%s)', async (_, fields) => { + const now = Date.now(); + mfs.readFile.mockResolvedValue(JSON.stringify({ id: 'existing', created: now, lastActivity: now, ...fields })); + + sessionManager = await SessionManager.start(eventManager, hooks, { sessionSampleRate: 0, sessionOnError: true }); + + expect(sessionManager.getSession().id).not.toBe('existing'); + expect(sessionManager.getSession().trackingType).toBe(TrackingType.TRACKED_ON_ERROR); + }); + + it('resumes a session saved before sessions were sampled as a drawn one', async () => { + const now = Date.now(); + mfs.readFile.mockResolvedValue(JSON.stringify({ id: 'existing', created: now, lastActivity: now })); + + sessionManager = await SessionManager.start(eventManager, hooks, { + sessionSampleRate: 20, + sessionOnError: false, + }); + + expect(sessionManager.getSession()).toMatchObject({ id: 'existing', trackingType: TrackingType.TRACKED }); + // Every session was collected then: it stands for itself, not for five. + expect(hooks.triggerRum({ eventType: 'view', startTime: now as TimeStamp })).toMatchObject({ + _dd: { configuration: { session_sample_rate: 100 } }, + }); + }); + + it('skips, without reporting, a state read from disk that is older than the session in memory', async () => { + mockNoSessionFile(); + sessionManager = await SessionManager.start(eventManager, hooks, SAMPLING); + const previous = sessionManager.getSession().id; + vi.advanceTimersByTime(1_000); + sessionManager.expire(); + eventManager.notify({ kind: EventKind.LIFECYCLE, lifecycle: LifecycleKind.END_USER_ACTIVITY }); + await vi.advanceTimersByTimeAsync(0); + expect(sessionManager.getSession().id).not.toBe(previous); + // The renewal's delete and write have not landed yet: the file still holds the session before. + mfs.access.mockResolvedValue(undefined); + mfs.readFile.mockResolvedValue( + JSON.stringify({ + id: previous, + created: 0, + lastActivity: 0, + trackingType: TrackingType.TRACKED, + sampleRate: 100, + }) + ); + vi.mocked(addError).mockClear(); + + eventManager.notify({ kind: EventKind.LIFECYCLE, lifecycle: LifecycleKind.END_USER_ACTIVITY }); + await vi.advanceTimersByTimeAsync(0); + + expect(addError).not.toHaveBeenCalled(); + }); + + it('draws again when the session is renewed', async () => { + mockNoSessionFile(); + const random = vi.spyOn(Math, 'random').mockReturnValue(0.8); + sessionManager = await SessionManager.start(eventManager, hooks, { + sessionSampleRate: 50, + sessionOnError: false, + }); + expect(sessionManager.getSession().trackingType).toBe(TrackingType.NOT_TRACKED); + + sessionManager.expire(); + random.mockReturnValue(0.2); + eventManager.notify({ kind: EventKind.LIFECYCLE, lifecycle: LifecycleKind.END_USER_ACTIVITY }); + await vi.advanceTimersByTimeAsync(0); + + expect(sessionManager.getSession().trackingType).toBe(TrackingType.TRACKED); + }); + + describe('setSessionHasError', () => { + async function startWithheldSession() { + mockNoSessionFile(); + sessionManager = await SessionManager.start(eventManager, hooks, { + sessionSampleRate: 0, + sessionOnError: true, + }); + mfs.writeFile.mockClear(); + } + + it('takes effect in memory before anything is written', async () => { + await startWithheldSession(); + mfs.writeFile.mockReturnValue(new Promise(() => undefined)); + + sessionManager.setSessionHasError(sessionManager.getSession().id, T0); + + expect(sessionManager.getSession().hasError).toBe(true); + }); + + it('persists the mark with the session', async () => { + await startWithheldSession(); + + sessionManager.setSessionHasError(sessionManager.getSession().id, T0); + await vi.advanceTimersByTimeAsync(0); + + expect(savedSessionStates()).toContainEqual(expect.objectContaining({ hasError: true })); + }); + + it('is not undone by an activity update that read the state before the mark reached disk', async () => { + await startWithheldSession(); + const { id } = sessionManager.getSession(); + mfs.access.mockResolvedValue(undefined); + mfs.readFile.mockResolvedValue( + JSON.stringify({ + id, + created: 0, + lastActivity: 0, + trackingType: TrackingType.TRACKED_ON_ERROR, + sampleRate: 0, + }) + ); + + sessionManager.setSessionHasError(id, T0); + eventManager.notify({ kind: EventKind.LIFECYCLE, lifecycle: LifecycleKind.END_USER_ACTIVITY }); + await vi.advanceTimersByTimeAsync(0); + + const states = savedSessionStates(); + expect(states[states.length - 1]).toMatchObject({ hasError: true }); + }); + + it('writes one state at a time, so a slow earlier write cannot land over the mark', async () => { + await startWithheldSession(); + const { id } = sessionManager.getSession(); + mfs.access.mockResolvedValue(undefined); + mfs.readFile.mockResolvedValue( + JSON.stringify({ + id, + created: 0, + lastActivity: 0, + trackingType: TrackingType.TRACKED_ON_ERROR, + sampleRate: 0, + }) + ); + let finishActivityWrite!: () => void; + mfs.writeFile.mockImplementationOnce(() => new Promise((resolve) => (finishActivityWrite = resolve))); + + // An activity update starts writing the state it had before the error… + eventManager.notify({ kind: EventKind.LIFECYCLE, lifecycle: LifecycleKind.END_USER_ACTIVITY }); + await vi.advanceTimersByTimeAsync(0); + expect(savedSessionStates()).toHaveLength(1); + + // …and the mark has to wait for it rather than race it. + sessionManager.setSessionHasError(id, T0); + await vi.advanceTimersByTimeAsync(0); + expect(savedSessionStates()).toHaveLength(1); + + finishActivityWrite(); + await vi.advanceTimersByTimeAsync(0); + const states = savedSessionStates(); + expect(states).toHaveLength(2); + expect(states[1]).toMatchObject({ hasError: true }); + }); + + it('lets a write queued before the session ended finish before the file is deleted', async () => { + await startWithheldSession(); + let finishMarkWrite!: () => void; + mfs.writeFile.mockImplementation((filePath: string) => + filePath.includes(`/${SESSION_FILE_NAME}.`) + ? new Promise((resolve) => (finishMarkWrite = resolve)) + : Promise.resolve() + ); + mfs.unlink.mockResolvedValue(undefined); + sessionManager.setSessionHasError(sessionManager.getSession().id, T0); + await vi.advanceTimersByTimeAsync(0); + + // The session ends while the mark is still being written: deleting first would let the + // write recreate the file, and the next launch resume a session that had ended. + sessionManager.expire(); + await vi.advanceTimersByTimeAsync(0); + expect(unlinkSync).not.toHaveBeenCalled(); + + finishMarkWrite(); + await vi.advanceTimersByTimeAsync(0); + expect(unlinkSync).toHaveBeenCalled(); + }); + + it('writes nothing for a session that has ended, so the file it had cannot come back', async () => { + await startWithheldSession(); + const { id } = sessionManager.getSession(); + mfs.unlink.mockResolvedValue(undefined); + sessionManager.expire(); + await vi.advanceTimersByTimeAsync(0); + mfs.writeFile.mockClear(); + + // A crash of this session, processed after it ended. + sessionManager.setSessionHasError(id, T0); + await vi.advanceTimersByTimeAsync(0); + + expect(savedSessionStates()).toEqual([]); + // The history still learns of it: that is what lets the crash through assembly. + expect(hooks.triggerRum({ eventType: 'error', startTime: T0 })).toMatchObject({ session: { id } }); + }); + + it('writes the state and the history before returning when the application may exit', async () => { + await startWithheldSession(); + const { id } = sessionManager.getSession(); + writeFileSync.mockClear(); + mfs.writeFile.mockReturnValue(new Promise(() => undefined)); + sessionManager.setSessionHasError(id, T0); + + sessionManager.writePendingSync(); + + // Written to a file of its own and renamed into place, so that a write already issued cannot + // overwrite or interleave with it. + const written = writeFileSync.mock.calls.map(([filePath, content]) => [String(filePath), String(content)]); + expect(written.find(([filePath]) => filePath.includes(`/${SESSION_FILE_NAME}.`))?.[1]).toContain( + '"hasError":true' + ); + expect(written.find(([filePath]) => filePath.includes('/_dd_session_history.'))?.[1]).toContain( + '"hasError":true' + ); + expect(renameSync).toHaveBeenCalledWith( + expect.stringContaining(`/${SESSION_FILE_NAME}.`), + expect.stringMatching(/\/_dd_s$/) + ); + expect(renameSync).toHaveBeenCalledWith( + expect.stringContaining('/_dd_session_history.'), + expect.stringMatching(/_dd_session_history$/) + ); + }); + + it('deletes the file of a session that has ended rather than writing it, when the application may exit', async () => { + await startWithheldSession(); + // The queued delete has not run yet: the application is exiting right after stopSession(). + mfs.unlink.mockReturnValue(new Promise(() => undefined)); + sessionManager.expire(); + writeFileSync.mockClear(); + + sessionManager.writePendingSync(); + + expect(writeFileSync.mock.calls.map(([filePath]) => String(filePath))).not.toContainEqual( + expect.stringContaining(`/${SESSION_FILE_NAME}.`) + ); + expect(unlinkSync).toHaveBeenCalledWith(expect.stringMatching(new RegExp(`/${SESSION_FILE_NAME}$`))); + }); + + it('leaves a drawn session alone, and writes nothing', async () => { + mockNoSessionFile(); + sessionManager = await SessionManager.start(eventManager, hooks, SAMPLING); + mfs.writeFile.mockClear(); + + sessionManager.setSessionHasError(sessionManager.getSession().id, T0); + await vi.advanceTimersByTimeAsync(0); + + expect(sessionManager.getSession().hasError).toBeUndefined(); + expect(mfs.writeFile).not.toHaveBeenCalled(); + }); + }); + }); }); diff --git a/src/domain/session/SessionManager.ts b/src/domain/session/SessionManager.ts index babf5f45..94753a76 100644 --- a/src/domain/session/SessionManager.ts +++ b/src/domain/session/SessionManager.ts @@ -1,19 +1,32 @@ import { app } from 'electron'; import * as fs from 'node:fs/promises'; import * as path from 'node:path'; -import { deepClone, generateUUID, ONE_MINUTE, type Subscription } from '@flashcatcloud/browser-core'; +import { + deepClone, + generateUUID, + ONE_MINUTE, + performDraw, + type Subscription, + type TimeStamp, +} from '@flashcatcloud/browser-core'; +import type { Configuration } from '../../config'; import { type EndUserActivityEvent, EventKind, EventManager, LifecycleKind } from '../../event'; import type { FormatHooks } from '../../assembly'; import { addError, setTimeout } from '../telemetry'; -import { displayError } from '../../tools/display'; -import { SessionContext } from './SessionContext'; +import { + parseSessionRecord, + SessionContext, + type SessionRecord, + TrackingType, + withholdsEvents, +} from './SessionContext'; +import { StateFile } from '../../tools/StateFile'; import { SESSION_TIME_OUT_DELAY } from './session.constants'; export const SESSION_EXPIRATION_DELAY = 15 * ONE_MINUTE; export const SESSION_FILE_NAME = '_dd_s'; -export interface Session { - id: string; +export interface Session extends SessionRecord { status: SessionStatus; } @@ -22,12 +35,13 @@ export type SessionStatus = 'active' | 'expired'; /** * Session state stored on disk */ -interface SessionState { - id: string; +interface SessionState extends SessionRecord { created: number; lastActivity: number; } +export type SamplingConfiguration = Pick; + /** * Track session lifecycle * - store the Session on SESSION_FILE_NAME @@ -35,9 +49,15 @@ interface SessionState { * - after SESSION_EXPIRATION_DELAY without activity, expire the Session * - after SESSION_TIME_OUT_DELAY if the Session is still active, expire the Session * - on activity, if the Session is expired, create a new Session + * - when a Session is created, draw whether it is collected (see {@link TrackingType}); a resumed + * Session keeps the decision it was created with */ export class SessionManager { - private currentSession!: Session; + /** The current session as it is saved: the one copy of its id, draw and error mark. */ + private currentState!: SessionState; + private status: SessionStatus = 'active'; + /** `SESSION_FILE_NAME`: every write and delete of it lands in the order requested, see {@link StateFile}. */ + private readonly stateFile = new StateFile(getSessionFilePath(), 'session state'); private sessionContext!: SessionContext; private inactivityTimeoutId: ReturnType | undefined; private sessionTimeoutId: ReturnType | undefined; @@ -45,23 +65,65 @@ export class SessionManager { private constructor( private readonly eventManager: EventManager, - private readonly hooks: FormatHooks + private readonly hooks: FormatHooks, + private readonly sampling: SamplingConfiguration ) {} - static async start(eventManager: EventManager, hooks: FormatHooks): Promise { - const manager = new SessionManager(eventManager, hooks); + static async start( + eventManager: EventManager, + hooks: FormatHooks, + sampling: SamplingConfiguration + ): Promise { + const manager = new SessionManager(eventManager, hooks, sampling); await manager.init(); return manager; } getSession(): Session { - return deepClone(this.currentSession); + const { id, trackingType, sampleRate, hasError } = this.currentState; + return deepClone({ id, trackingType, sampleRate, hasError, status: this.status }); } expire(): void { this.expireSession(); } + /** The session in force at `startTime`, current or past, or `undefined` when there was none. */ + findSession(startTime: TimeStamp): SessionRecord | undefined { + return this.sessionContext.find(startTime); + } + + /** + * Record that a withheld session reported an error at `errorTime`, which releases what it held. A + * no-op for any other session: writing the mark there would only cost disk writes. + * + * Takes effect in memory at once, and reaches disk afterwards: "an error, then the application + * quits" is the case this exists for, and it must not wait on a write. + */ + setSessionHasError(sessionId: string, errorTime: TimeStamp): void { + // Only while active: an ended session's file is being deleted, and a write would bring it back. + if (this.status === 'active' && sessionId === this.currentState.id && withholdsEvents(this.currentState)) { + this.currentState.hasError = true; + void this.saveCurrentState(); + } + this.sessionContext.setHasError(sessionId, errorTime); + } + + /** + * Writes the session's state and history before returning, for a process that may be about to + * exit: the error mark a release just set reaches disk asynchronously otherwise, and a session + * resumed by the next launch would withhold again what this one already uploaded. + */ + writePendingSync(): void { + if (this.status === 'active') { + this.stateFile.writeSync(JSON.stringify(this.currentState)); + } else { + // Its delete is queued behind the writes; the next launch must not resume it. + this.stateFile.deleteSync(); + } + this.sessionContext.persistSync(); + } + stop(): void { this.clearTimers(); if (this.activitySubscription) { @@ -72,19 +134,21 @@ export class SessionManager { private async init(): Promise { const now = Date.now(); + this.stateFile.sweep(); const existingState = await loadSessionState(); this.sessionContext = await SessionContext.init(this.hooks); + // The previous launch's entry, resumed session or not: it never got to close itself, and an + // open entry is never pruned. A resumed session gets a new entry for this launch. + this.sessionContext.close(); if (existingState && isSessionValid(existingState, now)) { - this.currentSession = { id: existingState.id, status: 'active' }; - this.sessionContext.add(existingState.id); existingState.lastActivity = now; - await saveSessionState(existingState); + this.setCurrent(existingState); + await this.saveCurrentState(); this.scheduleInactivityTimeout(); this.scheduleSessionTimeout(existingState.created); } else { - this.sessionContext.close(); await this.createNewSession(); } @@ -101,45 +165,79 @@ export class SessionManager { const now = Date.now(); const state: SessionState = { id: generateUUID(), + trackingType: drawTrackingType(this.sampling), + sampleRate: this.sampling.sessionSampleRate, created: now, lastActivity: now, }; - this.currentSession = { id: state.id, status: 'active' }; - this.sessionContext.add(state.id); - await saveSessionState(state); + this.setCurrent(state); + await this.saveCurrentState(); this.scheduleInactivityTimeout(); this.scheduleSessionTimeout(state.created); } + private setCurrent(state: SessionState): void { + this.currentState = state; + this.status = 'active'; + const { id, trackingType, sampleRate, hasError } = state; + this.sessionContext.add({ id, trackingType, sampleRate, hasError }); + } + + /** + * Queue a write of the current state. Each write serializes the state as of when it runs, and they + * run one after another, so the last one on disk is always the latest state. + */ + private saveCurrentState(): Promise { + return this.stateFile.write(() => JSON.stringify(this.currentState)); + } + private expireSession(): void { this.clearTimers(); - this.currentSession.status = 'expired'; + this.status = 'expired'; this.sessionContext.close(); - deleteSessionFile().catch(addError); + // Behind the queued writes: a save queued just before — the error mark, say — would otherwise + // land after the delete and resurrect the ended session on the next launch. + void this.stateFile.delete(); this.eventManager.notify({ kind: EventKind.LIFECYCLE, lifecycle: LifecycleKind.SESSION_EXPIRED }); } private async updateActivity(): Promise { - if (this.currentSession.status === 'expired') { + if (this.isExpired()) { await this.createNewSession(); this.eventManager.notify({ kind: EventKind.LIFECYCLE, lifecycle: LifecycleKind.SESSION_RENEW }); return; } const state = await loadSessionState(); - if (!state || state.id !== this.currentSession.id) { + if (this.isExpired()) { + // Expired while the state was being read: writing it back would bring the session back. + return; + } + if (state?.id !== this.currentState.id) { + // The file still holds the session before this one: its delete and this one's write are + // queued, and an activity arrived in between. Nothing to report, nothing to write yet. + if (state && state.created < this.currentState.created) { + return; + } addError(new Error('SessionManager: Invalid session state')); return; } - state.lastActivity = Date.now(); - await saveSessionState(state); + // Written from memory rather than from what was just read: the error mark reaches memory first + // and disk afterwards, and writing the read state back could undo it. + this.currentState.lastActivity = Date.now(); + await this.saveCurrentState(); this.scheduleInactivityTimeout(); } + /** A method rather than a comparison in place: the status changes under an `await`. */ + private isExpired(): boolean { + return this.status === 'expired'; + } + private scheduleInactivityTimeout(): void { if (this.inactivityTimeoutId !== undefined) { clearTimeout(this.inactivityTimeoutId); @@ -169,6 +267,17 @@ export class SessionManager { } } +/** + * The plain rate first; `sessionOnError` only ever applies to what it missed, so a session is never + * counted by both. + */ +function drawTrackingType({ sessionSampleRate, sessionOnError }: SamplingConfiguration): TrackingType { + if (performDraw(sessionSampleRate)) { + return TrackingType.TRACKED; + } + return sessionOnError ? TrackingType.TRACKED_ON_ERROR : TrackingType.NOT_TRACKED; +} + function getSessionFilePath(): string { return path.join(app.getPath('userData'), SESSION_FILE_NAME); } @@ -183,27 +292,24 @@ async function loadSessionState(): Promise { try { const filePath = getSessionFilePath(); await fs.access(filePath); - const content = await fs.readFile(filePath, 'utf-8'); - return JSON.parse(content) as SessionState; + return parseSessionState(JSON.parse(await fs.readFile(filePath, 'utf-8'))); } catch { return undefined; } } -async function saveSessionState(state: SessionState): Promise { - try { - const filePath = getSessionFilePath(); - await fs.writeFile(filePath, JSON.stringify(state), 'utf-8'); - } catch (error) { - displayError('Failed to save session state:', error); - } -} - -async function deleteSessionFile(): Promise { - try { - const filePath = getSessionFilePath(); - await fs.unlink(filePath); - } catch { - // File might not exist, ignore error - } +/** + * The state `value` holds, or `undefined` when it is not one — a corrupt file, a hand edit — so that + * a fresh session is drawn rather than a draw that was never made resumed. A state written before + * sessions were sampled has none of the sampling fields: every session was collected then, and a + * session keeps the decision it was created with. A state with some of them is a damaged one, not + * a legacy one. + */ +function parseSessionState(value: unknown): SessionState | undefined { + if (typeof value !== 'object' || value === null) return undefined; + const { created, lastActivity, ...rest } = value as Record; + if (!Number.isFinite(created) || !Number.isFinite(lastActivity)) return undefined; + const legacy = !('trackingType' in rest) && !('sampleRate' in rest) && !('hasError' in rest); + const record = parseSessionRecord(legacy ? { ...rest, trackingType: TrackingType.TRACKED, sampleRate: 100 } : rest); + return record && { ...record, created: created as number, lastActivity: lastActivity as number }; } diff --git a/src/domain/session/index.ts b/src/domain/session/index.ts index 4dd787cb..885549d9 100644 --- a/src/domain/session/index.ts +++ b/src/domain/session/index.ts @@ -1,2 +1,3 @@ export * from './SessionManager'; export { SESSION_TIME_OUT_DELAY } from './session.constants'; +export { TrackingType, withholdsEvents, parseSessionRecord, type SessionRecord } from './SessionContext'; diff --git a/src/domain/telemetry/Telemetry.spec.ts b/src/domain/telemetry/Telemetry.spec.ts index 27609c73..f221aab4 100644 --- a/src/domain/telemetry/Telemetry.spec.ts +++ b/src/domain/telemetry/Telemetry.spec.ts @@ -1,8 +1,8 @@ import { afterEach, beforeEach, describe, expect, it } from 'vitest'; -import { addError, callMonitored, monitor, startTelemetry, stopTelemetry } from './Telemetry'; +import { addError, addTelemetryDebug, callMonitored, monitor, startTelemetry, stopTelemetry } from './Telemetry'; import { createTestConfiguration } from '../../mocks.specUtil'; import { EventManager, RawEvent, EventKind, LifecycleKind } from '../../event'; -import { RawTelemetryData } from './rawTelemetryData.types'; +import type { RawTelemetryData, RawTelemetryError } from './rawTelemetryData.types'; describe('telemetry', () => { let eventManager: EventManager; @@ -49,6 +49,29 @@ describe('telemetry', () => { }); }); + describe('addTelemetryDebug', () => { + it('notifies a debug log carrying its context', () => { + startTelemetry(eventManager, createTestConfiguration()); + + addTelemetryDebug('something happened', { 'buffer.views_count': 2 }); + + expect(notifiedEvents).toEqual([ + { + type: 'telemetry', + telemetry: { type: 'log', status: 'debug', message: 'something happened', 'buffer.views_count': 2 }, + }, + ]); + }); + + it('is sampled like errors', () => { + startTelemetry(eventManager, createTestConfiguration({ telemetrySampleRate: 0 })); + + addTelemetryDebug('something happened', {}); + + expect(notifiedEvents).toEqual([]); + }); + }); + describe('addError', () => { it('notifies with formatted event', () => { const config = createTestConfiguration(); @@ -59,7 +82,7 @@ describe('telemetry', () => { addError(testError); expect(notifiedEvents).toHaveLength(1); - const event = notifiedEvents[0]; + const event = notifiedEvents[0] as RawTelemetryError; expect(event.type).toBe('telemetry'); expect(event.telemetry.type).toBe('log'); @@ -92,6 +115,25 @@ describe('telemetry', () => { }); describe('sampling', () => { + it('does not format an error it will not send, so a value it cannot serialize costs nothing', () => { + startTelemetry(eventManager, createTestConfiguration({ telemetrySampleRate: 0 })); + + expect(() => addError(1n)).not.toThrow(); + + expect(notifiedEvents).toHaveLength(0); + }); + + it('does not format an error once capped either', () => { + startTelemetry(eventManager, createTestConfiguration({ telemetrySampleRate: 100 })); + for (let i = 0; i < 100; i += 1) { + addError(new Error(`error ${i}`)); + } + + expect(() => addError(1n)).not.toThrow(); + + expect(notifiedEvents).toHaveLength(100); + }); + it('does not notify when sample rate is 0', () => { const config = createTestConfiguration({ telemetrySampleRate: 0 }); startTelemetry(eventManager, config); diff --git a/src/domain/telemetry/Telemetry.ts b/src/domain/telemetry/Telemetry.ts index 5723ff14..a58dbae2 100644 --- a/src/domain/telemetry/Telemetry.ts +++ b/src/domain/telemetry/Telemetry.ts @@ -10,7 +10,7 @@ import { } from '@flashcatcloud/browser-core/cjs/tools/monitor'; import type { Configuration } from '../../config'; import { EventKind, EventSource, EventManager, SessionRenewEvent, LifecycleKind, EventFormat } from '../../event'; -import { RawTelemetryError } from './rawTelemetryData.types'; +import type { RawTelemetryData, RawTelemetryError } from './rawTelemetryData.types'; export { monitor, callMonitored }; @@ -43,11 +43,32 @@ class Telemetry { } addError(error: unknown): void { - if (!this.isEnabled || this.eventCount >= MAX_TELEMETRY_EVENTS_PER_SESSION) { + // Before formatting: a telemetry that is sampled out or capped must cost nothing, and must not + // throw on a value it cannot serialize, since its callers are error paths themselves. + if (!this.canSend()) { return; } + this.notify(this.createErrorEvent(error)); + } + + addDebug(message: string, context: Record): void { + if (!this.canSend()) { + return; + } + this.notify({ type: 'telemetry', telemetry: { type: 'log', status: 'debug', message, ...context } }); + } + + stop(): void { + resetMonitor(); + this.sessionRenewSubscription?.unsubscribe(); + } + + private canSend(): boolean { + return this.isEnabled && this.eventCount < MAX_TELEMETRY_EVENTS_PER_SESSION; + } + + private notify(data: RawTelemetryData): void { this.eventCount++; - const data = this.createErrorEvent(error); this.eventManager.notify({ kind: EventKind.RAW, source: EventSource.MAIN, @@ -56,11 +77,6 @@ class Telemetry { }); } - stop(): void { - resetMonitor(); - this.sessionRenewSubscription?.unsubscribe(); - } - private createErrorEvent(error: unknown): RawTelemetryError { const { message, stack, kind } = formatError(error); return { @@ -83,6 +99,11 @@ export function addError(error: unknown): void { telemetryInstance?.addError(error); } +/** Internal debug log, sampled and capped like the errors. `context` is spread into `telemetry`. */ +export function addTelemetryDebug(message: string, context: Record): void { + telemetryInstance?.addDebug(message, context); +} + export function stopTelemetry(): void { telemetryInstance?.stop(); telemetryInstance = undefined; diff --git a/src/domain/telemetry/rawTelemetryData.types.ts b/src/domain/telemetry/rawTelemetryData.types.ts index ac083881..f7598dc3 100644 --- a/src/domain/telemetry/rawTelemetryData.types.ts +++ b/src/domain/telemetry/rawTelemetryData.types.ts @@ -1,7 +1,7 @@ -import { TelemetryErrorEvent } from './telemetryEvent.types'; +import { TelemetryDebugEvent, TelemetryErrorEvent } from './telemetryEvent.types'; import { RecursivePartial } from '../../tools/coreCompat'; -export type RawTelemetryData = RawTelemetryError; +export type RawTelemetryData = RawTelemetryError | RawTelemetryDebug; export interface RawTelemetryError extends RecursivePartial { type: 'telemetry'; @@ -12,3 +12,13 @@ export interface RawTelemetryError extends RecursivePartial error?: { stack?: string; kind?: string }; }; } + +export interface RawTelemetryDebug extends RecursivePartial { + type: 'telemetry'; + telemetry: { + type: 'log'; + status: 'debug'; + message: string; + [k: string]: unknown; + }; +} diff --git a/src/event/event.constants.ts b/src/event/event.constants.ts index 9c0dc29e..1b913afc 100644 --- a/src/event/event.constants.ts +++ b/src/event/event.constants.ts @@ -27,4 +27,5 @@ export const LifecycleKind = { SESSION_EXPIRED: 'session_expired', SESSION_RENEW: 'session_renew', USER_CHANGED: 'user_changed', + APP_MAY_EXIT: 'app_may_exit', } as const; diff --git a/src/event/event.types.ts b/src/event/event.types.ts index 811d9f10..2e00bddd 100644 --- a/src/event/event.types.ts +++ b/src/event/event.types.ts @@ -70,7 +70,24 @@ export interface UserChangedEvent { lifecycle: typeof LifecycleKind.USER_CHANGED; } -export type LifecycleEvent = EndUserActivityEvent | SessionExpiredEvent | SessionRenewEvent | UserChangedEvent; +/** + * The main process hit an uncaught exception, after which applications commonly exit, or the + * application is quitting. Whatever is waiting to be written has to be written now rather than + * later. + */ +export interface AppMayExitEvent { + kind: typeof EventKind.LIFECYCLE; + lifecycle: typeof LifecycleKind.APP_MAY_EXIT; + /** The process is exiting: nothing runs after the current listeners, so nothing may be deferred. */ + terminal: boolean; +} + +export type LifecycleEvent = + | EndUserActivityEvent + | SessionExpiredEvent + | SessionRenewEvent + | UserChangedEvent + | AppMayExitEvent; export type Event = RawEvent | ServerEvent | LifecycleEvent; export interface EventHandler { diff --git a/src/index.ts b/src/index.ts index b03abbbe..3a94805a 100644 --- a/src/index.ts +++ b/src/index.ts @@ -3,7 +3,7 @@ import { Assembly, createFormatHooks, registerCommonContext } from './assembly'; import type { InitConfiguration } from './config'; import { buildConfiguration } from './config'; import { RumCollection } from './domain/rum'; -import { SessionManager } from './domain/session'; +import { SessionManager, TrackingType } from './domain/session'; import { initAnonymousId } from './domain/AnonymousId'; import { UserContext, type User } from './domain/UserContext'; import { UserActivityTracker } from './domain/UserActivityTracker'; @@ -53,7 +53,7 @@ export async function init(configuration: InitConfiguration): Promise { registerCommonContext(config, hooks, anonymousId, getUserAt); startTelemetry(eventManager, config); - const manager = await SessionManager.start(eventManager, hooks); + const manager = await SessionManager.start(eventManager, hooks, config); sessionManager = manager; const rendererRegistry = new RendererRegistry(); @@ -87,8 +87,11 @@ export async function init(configuration: InitConfiguration): Promise { new SpanProcessor(eventManager, hooks, config); } - transport = await Transport.create(config, eventManager); - const rum = await RumCollection.start(eventManager, hooks, rendererRegistry, stackPathNormalizer); + const createdTransport = await Transport.create(config, eventManager, manager); + transport = createdTransport; + const rum = await RumCollection.start(eventManager, hooks, rendererRegistry, stackPathNormalizer, manager, () => + createdTransport.flushToDisk() + ); rumApi = rum.getApi(); return true; @@ -97,10 +100,17 @@ export async function init(configuration: InitConfiguration): Promise { /** * Id of the session renderers should attribute their events to, or `''` while none is active — * an expired session must not keep collecting renderer data under its old id. + * + * A session the sampling draw did not keep is answered as none too. Its renderer events would be + * dropped on arrival anyway, and the renderer uploads its Session Replay straight to the intake, + * past the main process — `''` is the only way to keep it from recording a session that does not + * exist. A session withheld by `sessionOnError` is answered with its id: its renderer events have to + * reach the main process to be held, and the bridge has no way to ask for the events but not the + * replay. */ function getActiveSessionId(manager: SessionManager): string { const session = manager.getSession(); - return session.status === 'active' ? session.id : ''; + return session.status === 'active' && session.trackingType !== TrackingType.NOT_TRACKED ? session.id : ''; } /** diff --git a/src/mocks.specUtil.ts b/src/mocks.specUtil.ts index 45ca2352..7f4bdf3a 100644 --- a/src/mocks.specUtil.ts +++ b/src/mocks.specUtil.ts @@ -36,6 +36,8 @@ export function createTestConfiguration(overrides: Partial = {}): service: 'test-service', clientToken: 'test-token', applicationId: 'test-app-id', + sessionSampleRate: 100, + sessionOnError: false, telemetrySampleRate: 100, defaultPrivacyLevel: 'mask', allowedWebViewHosts: [], diff --git a/src/tools/DiskValueHistory.spec.ts b/src/tools/DiskValueHistory.spec.ts index d884e5c3..42fedc67 100644 --- a/src/tools/DiskValueHistory.spec.ts +++ b/src/tools/DiskValueHistory.spec.ts @@ -11,6 +11,8 @@ import { DiskValueHistory } from './DiskValueHistory'; import { TimeStampHistoryEntry } from './TimeStampValueHistory'; vi.mock('node:fs/promises'); +const { writeFileSync, renameSync } = vi.hoisted(() => ({ writeFileSync: vi.fn(), renameSync: vi.fn() })); +vi.mock('node:fs', () => ({ writeFileSync, renameSync })); const mfs = mockFs(); const FILE_PATH = '/test/history.json'; @@ -128,7 +130,7 @@ describe('DiskValueHistory', () => { await vi.advanceTimersByTimeAsync(0); expect(mfs.writeFile).toHaveBeenCalledWith( - FILE_PATH, + expect.stringContaining(`${FILE_PATH}.`), JSON.stringify([{ startTime: T0, endTime: null, value: 'session-a' }]), 'utf-8' ); @@ -162,6 +164,40 @@ describe('DiskValueHistory', () => { }); }); + describe('persist()', () => { + it('serializes the entries when the write runs, so a write queued earlier never lands an older state', async () => { + mfs.readFile.mockRejectedValue(new Error('ENOENT')); + mfs.writeFile.mockResolvedValue(undefined); + const history = await DiskValueHistory.init({ filePath: FILE_PATH, expireDelay: EXPIRE_DELAY }); + + history.add('session-a', T0); + history.closeActive(T10); + await vi.advanceTimersByTimeAsync(0); + + // Both writes carry the closed entry: the first one ran after the close. + for (const [, content] of mfs.writeFile.mock.calls as [string, string][]) { + expect((JSON.parse(content) as TimeStampHistoryEntry[])[0]).toMatchObject({ endTime: T10 }); + } + }); + + it('persistSync() writes the entries before returning', async () => { + mfs.readFile.mockRejectedValue(new Error('ENOENT')); + const history = await DiskValueHistory.init({ filePath: FILE_PATH, expireDelay: EXPIRE_DELAY }); + history.add('session-a', T0); + + history.persistSync(); + + // To a file of its own, renamed into place: a write already issued keeps writing to the file + // it opened and cannot interleave with this one. + expect(writeFileSync).toHaveBeenCalledWith( + expect.stringContaining(`${FILE_PATH}.`), + expect.stringContaining('"session-a"'), + 'utf-8' + ); + expect(renameSync).toHaveBeenCalledWith(expect.stringContaining(`${FILE_PATH}.`), FILE_PATH); + }); + }); + describe('find()', () => { it('delegates to underlying TimeStampValueHistory', async () => { mfs.readFile.mockRejectedValue(new Error('ENOENT')); diff --git a/src/tools/DiskValueHistory.ts b/src/tools/DiskValueHistory.ts index 5a9466a2..77b581c3 100644 --- a/src/tools/DiskValueHistory.ts +++ b/src/tools/DiskValueHistory.ts @@ -1,7 +1,7 @@ import * as fs from 'node:fs/promises'; import type { TimeStamp } from '@flashcatcloud/browser-core'; import { TimeStampValueHistory, type TimeStampHistoryEntry } from './TimeStampValueHistory'; -import { displayError } from './display'; +import { StateFile } from './StateFile'; /** * Disk-backed extension of TimeStampValueHistory. All in-memory operations delegate to an @@ -17,16 +17,17 @@ import { displayError } from './display'; * are restored as active (endTime = Infinity). * * Error handling: write failures are logged via displayError and do not throw. - * Read/parse failures leave the history empty (silent fallback). + * Read/parse failures leave the history empty (silent fallback); an entry whose times are not + * numbers is skipped. */ export class DiskValueHistory { private readonly history: TimeStampValueHistory; - private readonly filePath: string; - private pendingWrite: Promise = Promise.resolve(); + private readonly file: StateFile; private constructor(history: TimeStampValueHistory, filePath: string) { this.history = history; - this.filePath = filePath; + this.file = new StateFile(filePath, 'value history'); + this.file.sweep(); } static async init(opts: { filePath: string; expireDelay: number }): Promise> { @@ -48,6 +49,7 @@ export class DiskValueHistory { // Iterate oldest-to-newest to rebuild history in chronological order for (let i = rawEntries.length - 1; i >= 0; i--) { const entry = rawEntries[i]; + if (!isWellFormed(entry)) continue; // Skip entries that would be immediately pruned if (entry.endTime !== null && (entry.endTime as number) < expireThreshold) continue; history.add(entry.value, entry.startTime); @@ -61,28 +63,42 @@ export class DiskValueHistory { add(value: T, startTime: TimeStamp): void { this.history.add(value, startTime); - this.persistToDisk(); + this.persist(); } find(startTime: TimeStamp): T | undefined { return this.history.find(startTime); } + findEntry(startTime: TimeStamp): TimeStampHistoryEntry | undefined { + return this.history.findEntry(startTime); + } + closeActive(endTime: TimeStamp): void { this.history.closeActive(endTime); - this.persistToDisk(); + this.persist(); } getEntries(): readonly TimeStampHistoryEntry[] { return this.history.getEntries(); } - private persistToDisk(): void { - const snapshot = JSON.stringify(this.history.getEntries()); - this.pendingWrite = this.pendingWrite - .then(() => fs.writeFile(this.filePath, snapshot, 'utf-8')) - .catch((error) => { - displayError('Failed to persist value history:', error); - }); + /** + * Write the entries to disk. Called by `add()` and `closeActive()`, and after a value is updated + * in place. The entries are serialized when the write runs, not when it is queued, so a write + * still queued never lands a state older than one written since. + */ + persist(): void { + void this.file.write(() => JSON.stringify(this.history.getEntries())); + } + + /** `persist` before returning, for a process that may be about to exit. See {@link StateFile}. */ + persistSync(): void { + this.file.writeSync(JSON.stringify(this.history.getEntries())); } } + +function isWellFormed(entry: unknown): entry is TimeStampHistoryEntry { + const { startTime, endTime } = (entry ?? {}) as { startTime?: unknown; endTime?: unknown }; + return Number.isFinite(startTime) && (endTime === null || Number.isFinite(endTime)); +} diff --git a/src/tools/StateFile.spec.ts b/src/tools/StateFile.spec.ts new file mode 100644 index 00000000..a8d06a96 --- /dev/null +++ b/src/tools/StateFile.spec.ts @@ -0,0 +1,119 @@ +import { mockFs } from '../mocks.specUtil'; + +vi.mock('./display', () => ({ + displayError: vi.fn(), +})); + +import { describe, it, expect, vi, beforeEach, afterEach } from 'vitest'; +import { StateFile } from './StateFile'; + +vi.mock('node:fs/promises'); +const { writeFileSync, renameSync, unlinkSync, readdirSync } = vi.hoisted(() => ({ + writeFileSync: vi.fn(), + renameSync: vi.fn(), + unlinkSync: vi.fn(), + readdirSync: vi.fn(() => [] as string[]), +})); +vi.mock('node:fs', () => ({ writeFileSync, renameSync, unlinkSync, readdirSync })); +const mfs = mockFs(); + +const FILE_PATH = '/mock/user/data/_dd_state'; + +describe('StateFile', () => { + beforeEach(() => { + vi.useFakeTimers(); + mfs.writeFile.mockResolvedValue(undefined); + mfs.unlink.mockResolvedValue(undefined); + }); + + afterEach(() => { + vi.useRealTimers(); + vi.clearAllMocks(); + mfs.reset(); + readdirSync.mockReturnValue([]); + }); + + it('writes to a file of its own and renames it into place, asynchronously and synchronously alike', async () => { + const file = new StateFile(FILE_PATH, 'state'); + + await file.write(() => 'async'); + file.writeSync('sync'); + + expect(mfs.writeFile).toHaveBeenCalledWith(expect.stringContaining(`${FILE_PATH}.`), 'async', 'utf-8'); + expect(writeFileSync).toHaveBeenCalledWith(expect.stringContaining(`${FILE_PATH}.`), 'sync', 'utf-8'); + expect(renameSync).toHaveBeenCalledTimes(2); + expect(renameSync.mock.calls.every(([, to]) => to === FILE_PATH)).toBe(true); + }); + + it('never lets a write issued earlier replace a newer synchronous snapshot', async () => { + const file = new StateFile(FILE_PATH, 'state'); + let finishWrite!: () => void; + mfs.writeFile.mockImplementationOnce(() => new Promise((resolve) => (finishWrite = resolve))); + const stale = file.write(() => 'old'); + await vi.advanceTimersByTimeAsync(0); + + // The process may be about to exit: the newer state lands first. + file.writeSync('new'); + finishWrite(); + await stale; + + const committed = renameSync.mock.calls.map(([from]) => String(from)); + expect(committed).toHaveLength(1); + expect(writeFileSync).toHaveBeenCalledWith(committed[0], 'new', 'utf-8'); + // The stale temp file is not left behind. + expect(unlinkSync).toHaveBeenCalledWith(expect.stringContaining(`${FILE_PATH}.`)); + }); + + it('never lets a delete requested earlier remove a newer synchronous snapshot', async () => { + const file = new StateFile(FILE_PATH, 'state'); + let finishWrite!: () => void; + mfs.writeFile.mockImplementationOnce(() => new Promise((resolve) => (finishWrite = resolve))); + const earlier = file.write(() => 'old'); + const deleted = file.delete(); + await vi.advanceTimersByTimeAsync(0); + + file.writeSync('new'); + finishWrite(); + await earlier; + await deleted; + + expect(unlinkSync).not.toHaveBeenCalledWith(FILE_PATH); + expect(renameSync).toHaveBeenCalledTimes(1); + }); + + it('deletes synchronously, and a write issued earlier does not bring the file back', async () => { + const file = new StateFile(FILE_PATH, 'state'); + let finishWrite!: () => void; + mfs.writeFile.mockImplementationOnce(() => new Promise((resolve) => (finishWrite = resolve))); + const stale = file.write(() => 'old'); + await vi.advanceTimersByTimeAsync(0); + + file.deleteSync(); + finishWrite(); + await stale; + + expect(unlinkSync).toHaveBeenCalledWith(FILE_PATH); + expect(renameSync).not.toHaveBeenCalled(); + }); + + it('keeps writing after a write that failed', async () => { + const file = new StateFile(FILE_PATH, 'state'); + mfs.writeFile.mockRejectedValueOnce(new Error('EACCES')); + + await file.write(() => 'first'); + await file.write(() => 'second'); + + expect(renameSync).toHaveBeenCalledTimes(1); + }); + + it('sweeps the temp files an earlier launch left next to it', () => { + readdirSync.mockReturnValue(['_dd_state', '_dd_state.123.4.tmp', '_dd_state.123.5.tmp', 'other.1.1.tmp']); + + new StateFile(FILE_PATH, 'state').sweep(); + + expect(unlinkSync.mock.calls.map(([f]) => String(f))).toEqual([ + '/mock/user/data/_dd_state.123.4.tmp', + '/mock/user/data/_dd_state.123.5.tmp', + ]); + }); +}); diff --git a/src/tools/StateFile.ts b/src/tools/StateFile.ts new file mode 100644 index 00000000..a392c129 --- /dev/null +++ b/src/tools/StateFile.ts @@ -0,0 +1,124 @@ +import { readdirSync, renameSync, unlinkSync, writeFileSync } from 'node:fs'; +import * as fs from 'node:fs/promises'; +import * as path from 'node:path'; +import { displayError } from './display'; + +/** + * A file holding one JSON state, replaced whole on every write. + * + * Every write lands in one step — a temp file renamed into place — and every delete in one unlink, + * in the order they were requested: each gets a generation when requested, and lands only if + * nothing of a later generation has landed since. So a synchronous write made as the process exits + * can never be overwritten by an asynchronous write requested before it, whose `open()` may still + * be pending, nor undone by a delete requested before it. + * + * Asynchronous writes serialize when they run, not when they are requested, so the last to land + * carries the latest state. A failure is reported and does not stop later writes. + */ +export class StateFile { + private requested = 0; + private landed = 0; + private queue: Promise = Promise.resolve(); + + constructor( + private readonly filePath: string, + /** What the file holds, for error messages. */ + private readonly what: string + ) {} + + /** Removes the temp files an earlier launch left next to the file, ended between write and rename. */ + sweep(): void { + const dir = path.dirname(this.filePath); + const prefix = `${path.basename(this.filePath)}.`; + try { + for (const name of readdirSync(dir)) { + if (name.startsWith(prefix) && name.endsWith('.tmp')) { + unlinkSync(path.join(dir, name)); + } + } + } catch { + // Nothing to sweep, or nothing to be done about it. + } + } + + /** Queues a write of what `serialize` returns when the write runs, behind what was requested before. */ + write(serialize: () => string): Promise { + const generation = this.nextGeneration(); + this.queue = this.queue + .then(async () => { + if (generation < this.landed) { + // Superseded while queued: what landed since is newer than anything requested before it. + return; + } + const tmpPath = this.tempPath(generation); + await fs.writeFile(tmpPath, serialize(), 'utf-8'); + this.land( + generation, + () => renameSync(tmpPath, this.filePath), + () => unlinkSync(tmpPath) + ); + }) + .catch((error) => displayError(`Failed to write ${this.what}:`, error)); + return this.queue; + } + + /** Writes before returning, for a process that may be about to exit. */ + writeSync(content: string): void { + const generation = this.nextGeneration(); + const tmpPath = this.tempPath(generation); + try { + writeFileSync(tmpPath, content, 'utf-8'); + this.land(generation, () => renameSync(tmpPath, this.filePath)); + } catch (error) { + displayError(`Failed to write ${this.what}:`, error); + } + } + + /** Queues a delete, behind what was requested before. */ + delete(): Promise { + const generation = this.nextGeneration(); + this.queue = this.queue + .then(() => this.land(generation, () => this.unlink())) + .catch((error) => displayError(`Failed to delete ${this.what}:`, error)); + return this.queue; + } + + /** Deletes before returning, for a process that may be about to exit. */ + deleteSync(): void { + const generation = this.nextGeneration(); + try { + this.land(generation, () => this.unlink()); + } catch (error) { + displayError(`Failed to delete ${this.what}:`, error); + } + } + + private nextGeneration(): number { + this.requested += 1; + return this.requested; + } + + private tempPath(generation: number): string { + return `${this.filePath}.${process.pid}.${generation}.tmp`; + } + + /** Applies the change unless a later one has landed already, in which case it is discarded. */ + private land(generation: number, apply: () => void, discard?: () => void): void { + if (generation < this.landed) { + discard?.(); + return; + } + apply(); + this.landed = generation; + } + + private unlink(): void { + try { + unlinkSync(this.filePath); + } catch (error) { + if ((error as { code?: string } | undefined)?.code !== 'ENOENT') { + throw error; + } + } + } +} diff --git a/src/tools/TimeStampValueHistory.ts b/src/tools/TimeStampValueHistory.ts index 5d2c1cd8..bf9abdb2 100644 --- a/src/tools/TimeStampValueHistory.ts +++ b/src/tools/TimeStampValueHistory.ts @@ -36,10 +36,14 @@ export class TimeStampValueHistory { } find(startTime: TimeStamp): T | undefined { + return this.findEntry(startTime)?.value; + } + + findEntry(startTime: TimeStamp): TimeStampHistoryEntry | undefined { for (const entry of this.entries) { if (entry.startTime <= startTime) { if (startTime <= entry.endTime) { - return entry.value; + return entry; } break; } diff --git a/src/tools/intakeNumbers.spec.ts b/src/tools/intakeNumbers.spec.ts new file mode 100644 index 00000000..9366ca31 --- /dev/null +++ b/src/tools/intakeNumbers.spec.ts @@ -0,0 +1,89 @@ +import { describe, expect, it } from 'vitest'; +import { findInvalidIntakeInteger } from './intakeNumbers'; + +describe('findInvalidIntakeInteger', () => { + it('leaves free-form subtrees alone: the intake stores them as they are', () => { + const event = { + type: 'error', + date: 1, + context: { price: 19.99, nested: { ratio: 0.5 }, status_code: '500' }, + usr: { score: 0.25 }, + feature_flags: { rollout: 0.1 }, + error: { message: 'x', resource: { status_code: 500 } }, + }; + + expect(findInvalidIntakeInteger(event)).toBeUndefined(); + }); + + it('names a fraction where the intake decodes an integer', () => { + expect(findInvalidIntakeInteger({ type: 'error', date: 1.5 })).toBe('date'); + expect(findInvalidIntakeInteger({ type: 'view', date: 1, view: { time_spent: 1.5 } })).toBe('view.time_spent'); + expect(findInvalidIntakeInteger({ type: 'resource', date: 1, resource: { duration: 2.5 } })).toBe( + 'resource.duration' + ); + expect(findInvalidIntakeInteger({ type: 'view', date: 1, _dd: { document_version: 1.5 } })).toBe( + '_dd.document_version' + ); + }); + + it('names a value of the wrong type where the intake decodes an integer', () => { + expect(findInvalidIntakeInteger({ type: 'error', date: 1, error: { resource: { status_code: '500' } } })).toBe( + 'error.resource.status_code' + ); + expect(findInvalidIntakeInteger({ type: 'error', date: '1700000000000' })).toBe('date'); + expect(findInvalidIntakeInteger({ type: 'error', date: true })).toBe('date'); + expect(findInvalidIntakeInteger({ type: 'view', date: 1, view: { time_spent: {} } })).toBe('view.time_spent'); + expect(findInvalidIntakeInteger({ type: 'view', date: 1, view: { time_spent: [1] } })).toBe('view.time_spent'); + }); + + it('names a number that is not finite, or beyond what the intake can hold exactly', () => { + expect(findInvalidIntakeInteger({ type: 'error', date: Number.NaN })).toBe('date'); + expect(findInvalidIntakeInteger({ type: 'error', date: Number.POSITIVE_INFINITY })).toBe('date'); + expect(findInvalidIntakeInteger({ type: 'error', date: 2 ** 53 })).toBe('date'); + }); + + it('accepts an absent or null value: the intake decodes either as its zero', () => { + expect(findInvalidIntakeInteger({ type: 'error', date: 1 })).toBeUndefined(); + expect(findInvalidIntakeInteger({ type: 'error', date: 1, error: { resource: null } })).toBeUndefined(); + expect( + findInvalidIntakeInteger({ type: 'error', date: 1, error: { resource: { status_code: null } } }) + ).toBeUndefined(); + }); + + it('checks the values of a map the intake types as integers', () => { + const view = (custom_timings: unknown) => ({ type: 'view', date: 1, view: { custom_timings } }); + + expect(findInvalidIntakeInteger(view({ boot: 1.5 }))).toBe('view.custom_timings.boot'); + expect(findInvalidIntakeInteger(view({ boot: '15' }))).toBe('view.custom_timings.boot'); + expect(findInvalidIntakeInteger(view({ boot: 15, ready: 20 }))).toBeUndefined(); + expect(findInvalidIntakeInteger(view(undefined))).toBeUndefined(); + }); + + it('checks the session plan on every type but view, whose own `_dd` has none', () => { + expect(findInvalidIntakeInteger({ type: 'view', date: 1, _dd: { session: { plan: 1.5 } } })).toBeUndefined(); + expect(findInvalidIntakeInteger({ type: 'error', date: 1, _dd: { session: { plan: 1.5 } } })).toBe( + '_dd.session.plan' + ); + }); + + it('follows arrays on the way to an integer', () => { + const event = { + type: 'long_task', + date: 1, + long_task: { duration: 1, scripts: [{ duration: 1 }, { duration: 1.5 }] }, + }; + + expect(findInvalidIntakeInteger(event)).toBe('long_task.scripts[1].duration'); + }); + + it('accepts a float where the intake decodes one', () => { + const event = { + type: 'view', + date: 1, + view: { time_spent: 1, cumulative_layout_shift: 0.1 }, + _dd: { configuration: { session_sample_rate: 33.3 } }, + }; + + expect(findInvalidIntakeInteger(event)).toBeUndefined(); + }); +}); diff --git a/src/tools/intakeNumbers.ts b/src/tools/intakeNumbers.ts new file mode 100644 index 00000000..80e333e6 --- /dev/null +++ b/src/tools/intakeNumbers.ts @@ -0,0 +1,200 @@ +/** + * The event fields the intake decodes as integers, by JSON path, per event type. Go's decoder + * refuses anything but a whole number into an integer — a fraction, a string, a boolean, an + * object — and fails the whole event, silently, since the intake answers `202` before it decodes. + * See `toIntakeTimeStamp` for the timestamps the SDK rounds itself; this is for values the SDK + * did not produce. + * + * Only these paths are looked at. Everything else — `context`, `usr`, `feature_flags`, custom + * attributes — the intake stores as it is, and is never inspected here. + * + * Taken from the integer-typed fields of the event structs for the six intake-supported types in + * `fc-rum/types/datadog/rum.go`, walked by type with Go's shadowing of embedded fields applied; + * `[]` stands for each element of an array, `*` for each value of a map. The e2e intake keeps the + * same table to flag what a real intake would drop. + */ +const COMMON = ['_dd.format_version', 'date']; +// Every event type declares its own `_dd`; only the view's lacks a `session`. +const SESSION_PLAN = '_dd.session.plan'; + +const INTAKE_INTEGER_PATHS: Record = { + action: [ + ...COMMON, + SESSION_PLAN, + '_dd.action.target.height', + '_dd.action.target.width', + 'action.crash.count', + 'action.error.count', + 'action.loading_time', + 'action.long_task.count', + 'action.resource.count', + ], + error: [...COMMON, SESSION_PLAN, 'error.resource.status_code', 'error.time_since_app_start', 'freeze.duration'], + long_task: [ + ...COMMON, + SESSION_PLAN, + 'long_task.blocking_duration', + 'long_task.duration', + 'long_task.first_ui_event_timestamp', + 'long_task.scripts[].duration', + 'long_task.scripts[].forced_style_and_layout_duration', + 'long_task.scripts[].pause_duration', + 'long_task.scripts[].source_char_position', + 'long_task.scripts[].start_time', + 'long_task.start_time', + 'long_task.style_and_layout_start', + ], + resource: [ + ...COMMON, + SESSION_PLAN, + 'resource.connect.duration', + 'resource.connect.start', + 'resource.decoded_body_size', + 'resource.dns.duration', + 'resource.dns.start', + 'resource.download.duration', + 'resource.download.start', + 'resource.duration', + 'resource.encoded_body_size', + 'resource.first_byte.duration', + 'resource.first_byte.start', + 'resource.redirect.duration', + 'resource.redirect.start', + 'resource.size', + 'resource.ssl.duration', + 'resource.ssl.start', + 'resource.status_code', + 'resource.transfer_size', + 'resource.worker.duration', + 'resource.worker.start', + ], + view: [ + ...COMMON, + '_dd.document_version', + '_dd.page_states[].start', + '_dd.replay_stats.records_count', + '_dd.replay_stats.segments_count', + '_dd.replay_stats.segments_total_raw_size', + 'display.scroll.max_scroll_height_time', + 'view.action.count', + 'view.app_launch', + 'view.crash.count', + 'view.cumulative_layout_shift_time', + 'view.custom_timings.*', + 'view.dom_complete', + 'view.dom_content_loaded', + 'view.dom_interactive', + 'view.error.count', + 'view.evaluate_script', + 'view.first_byte', + 'view.first_contentful_paint', + 'view.first_input_delay', + 'view.first_input_time', + 'view.first_render', + 'view.frozen_frame.count', + 'view.frustration.count', + 'view.in_foreground_periods[].duration', + 'view.in_foreground_periods[].start', + 'view.interaction_to_next_paint', + 'view.interaction_to_next_paint_time', + 'view.interaction_to_next_view_time', + 'view.largest_contentful_paint', + 'view.load_event', + 'view.loading_time', + 'view.long_task.count', + 'view.network_settled_time', + 'view.onload_to_onshow', + 'view.onshow_to_onready', + 'view.performance.cls.timestamp', + 'view.performance.fcp.timestamp', + 'view.performance.fid.duration', + 'view.performance.fid.timestamp', + 'view.performance.inp.duration', + 'view.performance.inp.timestamp', + 'view.performance.lcp.timestamp', + 'view.resource.count', + 'view.setdata.count', + 'view.setdata.duration', + 'view.slow_frame.count', + 'view.time_spent', + ], + vital: [...COMMON, SESSION_PLAN, 'vital.duration'], +}; + +/** + * The path of the first value the intake could not decode into an integer, or `undefined` when + * every value at an integer path is one. An absent or `null` value is accepted: the intake + * decodes either as zero. An event of an unknown type has no such paths. + */ +export function findInvalidIntakeInteger(event: unknown): string | undefined { + const type = (event as { type?: unknown } | undefined)?.type; + for (const path of INTAKE_INTEGER_PATHS[typeof type === 'string' ? type : ''] ?? []) { + const found = findInvalidIntegerAt(event, path.split('.'), ''); + if (found !== undefined) { + return found; + } + } + return undefined; +} + +/** Whether the intake decodes `value` into an integer: absent, `null`, or a whole number it holds exactly. */ +function isIntakeInteger(value: unknown): boolean { + return value === undefined || value === null || (typeof value === 'number' && Number.isSafeInteger(value)); +} + +function findInvalidIntegerAt(value: unknown, segments: readonly string[], at: string): string | undefined { + if (segments.length === 0) { + return isIntakeInteger(value) ? undefined : at; + } + const [segment, ...rest] = segments; + if (segment === '*') { + if (value === undefined || value === null) { + return undefined; + } + if (typeof value !== 'object' || Array.isArray(value)) { + return at; + } + for (const [key, item] of Object.entries(value)) { + const found = findInvalidIntegerAt(item, rest, `${at}.${key}`); + if (found !== undefined) { + return found; + } + } + return undefined; + } + const key = segment.endsWith('[]') ? segment.slice(0, -2) : segment; + const child = (value as Record | null | undefined)?.[key]; + const childPath = at === '' ? key : `${at}.${key}`; + if (!segment.endsWith('[]')) { + return findInvalidIntegerAt(child, rest, childPath); + } + if (!Array.isArray(child)) { + return undefined; + } + for (const [index, item] of child.entries()) { + const found = findInvalidIntegerAt(item, rest, `${childPath}[${index}]`); + if (found !== undefined) { + return found; + } + } + return undefined; +} + +/** + * Whether `value` holds, anywhere, a property named like a prototype's. Such a key is not data: + * merged into an object, `__proto__` reaches that object's prototype — `Object.prototype`, for + * every object of the process. A payload carrying one is dropped whole. + */ +export function hasPrototypeKey(value: unknown): boolean { + if (Array.isArray(value)) { + return value.some(hasPrototypeKey); + } + if (value === null || typeof value !== 'object') { + return false; + } + return Object.keys(value).some( + (key) => PROTOTYPE_KEYS.has(key) || hasPrototypeKey((value as Record)[key]) + ); +} + +const PROTOTYPE_KEYS = new Set(['__proto__', 'constructor', 'prototype']); diff --git a/src/transport/Transport.spec.ts b/src/transport/Transport.spec.ts index ce3e8666..15697e91 100644 --- a/src/transport/Transport.spec.ts +++ b/src/transport/Transport.spec.ts @@ -1,26 +1,32 @@ -import { beforeEach, describe, expect, it, vi } from 'vitest'; +import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest'; import { BatchSizes, BatchUploadFrequencies } from '../config'; import type { RawEvent, ServerEvent } from '../event'; -import { EventKind, EventTrack, EventManager } from '../event'; +import { EventKind, EventTrack, EventManager, LifecycleKind } from '../event'; import { createTestConfiguration } from '../mocks.specUtil'; +import { type Session, type SessionManager, TrackingType } from '../domain/session'; import { Transport } from './Transport'; +import { app } from 'electron'; vi.mock('electron', () => ({ app: { getPath: vi.fn(() => '/mock/user/data'), + on: vi.fn(), + off: vi.fn(), }, })); -const { mockBatchPost, mockBatchFlush, mockBatchCreate } = vi.hoisted(() => { +const { mockBatchPost, mockBatchWritePendingSync, mockBatchFlush, mockBatchCreate } = vi.hoisted(() => { const mockBatchPost = vi.fn(); + const mockBatchWritePendingSync = vi.fn(); const mockBatchFlush = vi.fn().mockResolvedValue(undefined); const mockBatchCreate = vi.fn().mockResolvedValue({ post: mockBatchPost, + writePendingSync: mockBatchWritePendingSync, flush: mockBatchFlush, stop: vi.fn(), }); - return { mockBatchPost, mockBatchFlush, mockBatchCreate }; + return { mockBatchPost, mockBatchWritePendingSync, mockBatchFlush, mockBatchCreate }; }); vi.mock('./batch', () => ({ @@ -32,23 +38,43 @@ vi.mock('./batch', () => ({ describe('Transport', () => { let eventManager: EventManager; let config: ReturnType; + let session: Session; + let sessionManager: SessionManager; + + /** What `Transport` hooks on the process, captured rather than registered: the test process must not accumulate exit listeners. */ + let processListeners: Record void>; beforeEach(() => { vi.clearAllMocks(); + processListeners = {}; + vi.spyOn(process, 'on').mockImplementation(((name: string, listener: () => void) => { + processListeners[name] = listener; + return process; + }) as typeof process.on); eventManager = new EventManager(); config = createTestConfiguration(); + session = { id: 'session-id', status: 'active', trackingType: TrackingType.TRACKED, sampleRate: 100 }; + sessionManager = { + getSession: () => session, + setSessionHasError: vi.fn(), + writePendingSync: vi.fn(), + } as unknown as SessionManager; + }); + + afterEach(() => { + vi.restoreAllMocks(); }); describe('create', () => { it('should register event handlers for known tracks', async () => { const spy = vi.spyOn(eventManager, 'registerHandler'); - await Transport.create(config, eventManager); + await Transport.create(config, eventManager, sessionManager); expect(spy).toHaveBeenCalled(); }); it('should setup batch manager for known tracks', async () => { - await Transport.create(config, eventManager); + await Transport.create(config, eventManager, sessionManager); expect(mockBatchCreate).toHaveBeenCalled(); }); @@ -56,19 +82,227 @@ describe('Transport', () => { describe('event handling', () => { it('should handle SERVER events matching domain track type', async () => { - await Transport.create(config, eventManager); + await Transport.create(config, eventManager, sessionManager); + const data = { type: 'action', session: { id: 'session-id' }, view: { id: 'view-id' } }; eventManager.notify({ kind: EventKind.SERVER, track: EventTrack.RUM, - data: { test: 'data' }, + source: 'main-process', + data, + } as unknown as ServerEvent); + + expect(mockBatchPost).toHaveBeenCalledWith(data); + }); + + it('should hold the RUM events of a session withheld by sessionOnError', async () => { + session.trackingType = TrackingType.TRACKED_ON_ERROR; + await Transport.create(config, eventManager, sessionManager); + + const data = { type: 'action', session: { id: 'session-id' }, view: { id: 'view-id' } }; + eventManager.notify({ + kind: EventKind.SERVER, + track: EventTrack.RUM, + source: 'main-process', + data, + } as unknown as ServerEvent); + + expect(mockBatchPost).not.toHaveBeenCalled(); + }); + + it('should release a withheld session, then write what is pending, when the application may exit', async () => { + session.trackingType = TrackingType.TRACKED_ON_ERROR; + await Transport.create(config, eventManager, sessionManager); + const view = { type: 'view', date: 1, session: { id: 'session-id' }, view: { id: 'view-id', is_active: true } }; + const error = { + type: 'error', + error: { source: 'source' }, + session: { id: 'session-id' }, + view: { id: 'view-id' }, + }; + eventManager.notify({ + kind: EventKind.SERVER, + track: EventTrack.RUM, + source: 'main-process', + data: view, + } as unknown as ServerEvent); + eventManager.notify({ + kind: EventKind.SERVER, + track: EventTrack.RUM, + source: 'main-process', + data: error, + } as unknown as ServerEvent); + const calls: string[] = []; + const record = (name: string) => () => calls.push(name); + mockBatchPost.mockImplementationOnce(record('post:view')).mockImplementationOnce(record('post:error')); + mockBatchWritePendingSync.mockImplementationOnce(record('batch')); + // eslint-disable-next-line @typescript-eslint/unbound-method -- a mock's call list, not a method to call + vi.mocked(sessionManager.writePendingSync).mockImplementationOnce(record('session')); + + eventManager.notify({ kind: EventKind.LIFECYCLE, lifecycle: LifecycleKind.APP_MAY_EXIT, terminal: false }); + + // The release first, so that the write takes it along; the session's mark with it. + expect(calls).toEqual(['post:view', 'post:error', 'batch', 'session']); + }); + + it('should release and write an error reported after before-quit, on will-quit', async () => { + session.trackingType = TrackingType.TRACKED_ON_ERROR; + await Transport.create(config, eventManager, sessionManager); + const listeners: Record void> = Object.fromEntries( + // eslint-disable-next-line @typescript-eslint/unbound-method -- a mock's call list, not a method to call + vi.mocked(app.on).mock.calls as [string, () => void][] + ); + const view = { type: 'view', date: 1, session: { id: 'session-id' }, view: { id: 'view-id', is_active: true } }; + eventManager.notify({ + kind: EventKind.SERVER, + track: EventTrack.RUM, + source: 'main-process', + data: view, + } as unknown as ServerEvent); + listeners['before-quit'].call(undefined); + expect(mockBatchPost).not.toHaveBeenCalled(); + + // A host listener registered after the SDK's reports an error while quitting. + const error = { + type: 'error', + error: { source: 'source' }, + session: { id: 'session-id' }, + view: { id: 'view-id' }, + }; + eventManager.notify({ + kind: EventKind.SERVER, + track: EventTrack.RUM, + source: 'main-process', + data: error, + } as unknown as ServerEvent); + listeners['will-quit'].call(undefined); + + expect(mockBatchPost.mock.calls.map(([data]) => (data as { type: string }).type)).toEqual(['view', 'error']); + expect(mockBatchWritePendingSync).toHaveBeenCalled(); + }); + + it('should release and write an error reported right before the process exits', async () => { + session.trackingType = TrackingType.TRACKED_ON_ERROR; + await Transport.create(config, eventManager, sessionManager); + const view = { type: 'view', date: 1, session: { id: 'session-id' }, view: { id: 'view-id', is_active: true } }; + const error = { + type: 'error', + error: { source: 'source' }, + session: { id: 'session-id' }, + view: { id: 'view-id' }, + }; + eventManager.notify({ + kind: EventKind.SERVER, + track: EventTrack.RUM, + source: 'main-process', + data: view, + } as unknown as ServerEvent); + eventManager.notify({ + kind: EventKind.SERVER, + track: EventTrack.RUM, + source: 'main-process', + data: error, + } as unknown as ServerEvent); + + // `process.exit()` runs only the synchronous 'exit' listeners: no quit event, no later turn. + processListeners.exit.call(undefined); + + expect(mockBatchPost.mock.calls.map(([data]) => (data as { type: string }).type)).toEqual(['view', 'error']); + expect(mockBatchWritePendingSync).toHaveBeenCalled(); + }); + + it('should write an error reported from a later exit listener synchronously, with no timer to wait for', async () => { + session.trackingType = TrackingType.TRACKED_ON_ERROR; + await Transport.create(config, eventManager, sessionManager); + const view = { type: 'view', date: 1, session: { id: 'session-id' }, view: { id: 'view-id', is_active: true } }; + eventManager.notify({ + kind: EventKind.SERVER, + track: EventTrack.RUM, + source: 'main-process', + data: view, + } as unknown as ServerEvent); + processListeners.exit.call(undefined); + expect(mockBatchPost).not.toHaveBeenCalled(); + + // A host exit listener registered after the SDK's reports an error: nothing runs after it. + const error = { + type: 'error', + error: { source: 'source' }, + session: { id: 'session-id' }, + view: { id: 'view-id' }, + }; + mockBatchWritePendingSync.mockClear(); + eventManager.notify({ + kind: EventKind.SERVER, + track: EventTrack.RUM, + source: 'main-process', + data: error, + } as unknown as ServerEvent); + + expect(mockBatchPost.mock.calls.map(([data]) => (data as { type: string }).type)).toEqual(['view', 'error']); + expect(mockBatchWritePendingSync).toHaveBeenCalled(); + // eslint-disable-next-line @typescript-eslint/unbound-method -- a mock's call list, not a method to call + expect(sessionManager.writePendingSync).toHaveBeenCalled(); + }); + + it('should write the session state even when a batch write throws on exit', async () => { + await Transport.create(config, eventManager, sessionManager); + mockBatchWritePendingSync.mockImplementationOnce(() => { + throw new Error('EROFS'); + }); + + expect(() => + eventManager.notify({ kind: EventKind.LIFECYCLE, lifecycle: LifecycleKind.APP_MAY_EXIT, terminal: false }) + ).not.toThrow(); + + // eslint-disable-next-line @typescript-eslint/unbound-method -- a mock's call list, not a method to call + expect(sessionManager.writePendingSync).toHaveBeenCalled(); + }); + + it('should treat a quit as an exit', async () => { + await Transport.create(config, eventManager, sessionManager); + // eslint-disable-next-line @typescript-eslint/unbound-method -- a mock's call list, not a method to call + const beforeQuit = (vi.mocked(app.on).mock.calls as [string, () => void][]).find( + ([name]) => name === 'before-quit' + )![1]; + + beforeQuit(); + + expect(mockBatchWritePendingSync).toHaveBeenCalled(); + }); + + it('should hold a renderer event that calls itself telemetry like any other renderer event', async () => { + session.trackingType = TrackingType.TRACKED_ON_ERROR; + await Transport.create(config, eventManager, sessionManager); + + const data = { + type: 'telemetry', + telemetry: { status: 'error' }, + session: { id: 'session-id' }, + view: { id: 'v' }, + }; + eventManager.notify({ + kind: EventKind.SERVER, + track: EventTrack.RUM, + source: 'renderer', + data, } as unknown as ServerEvent); - expect(mockBatchPost).toHaveBeenCalledWith({ test: 'data' }); + expect(mockBatchPost).not.toHaveBeenCalled(); + }); + + it('should post telemetry straight to the batch, even while the session is withheld', async () => { + session.trackingType = TrackingType.TRACKED_ON_ERROR; + await Transport.create(config, eventManager, sessionManager); + + const data = { type: 'telemetry', telemetry: { status: 'error' } }; + eventManager.notify({ kind: EventKind.SERVER, track: EventTrack.RUM, data } as unknown as ServerEvent); + + expect(mockBatchPost).toHaveBeenCalledWith(data); }); it('should not handle events that do not match', async () => { - await Transport.create(config, eventManager); + await Transport.create(config, eventManager, sessionManager); eventManager.notify({ kind: EventKind.RAW, @@ -80,7 +314,7 @@ describe('Transport', () => { }); it('should not handle SERVER events with different track type', async () => { - await Transport.create(config, eventManager); + await Transport.create(config, eventManager, sessionManager); eventManager.notify({ kind: EventKind.SERVER, @@ -94,7 +328,7 @@ describe('Transport', () => { describe('flush', () => { it('should flush all batch managers', async () => { - const transport = await Transport.create(config, eventManager); + const transport = await Transport.create(config, eventManager, sessionManager); await transport.flush(); // FlashCat only has the RUM track (no spans intake), so exactly one batch manager. @@ -104,7 +338,7 @@ describe('Transport', () => { describe('batch configuration', () => { it('should use default batch size when not specified', async () => { - await Transport.create(config, eventManager); + await Transport.create(config, eventManager, sessionManager); expect(mockBatchCreate).toHaveBeenCalledWith( config, @@ -116,7 +350,7 @@ describe('Transport', () => { it('should use configured batch size', async () => { const configWithBatchSize = createTestConfiguration({ batchSize: 'SMALL' }); - await Transport.create(configWithBatchSize, eventManager); + await Transport.create(configWithBatchSize, eventManager, sessionManager); expect(mockBatchCreate).toHaveBeenCalledWith( configWithBatchSize, @@ -127,7 +361,7 @@ describe('Transport', () => { }); it('should use default upload frequency when not specified', async () => { - await Transport.create(config, eventManager); + await Transport.create(config, eventManager, sessionManager); expect(mockBatchCreate).toHaveBeenCalledWith( config, @@ -139,7 +373,7 @@ describe('Transport', () => { it('should use configured upload frequency', async () => { const configWithFrequency = createTestConfiguration({ uploadFrequency: 'FREQUENT' }); - await Transport.create(configWithFrequency, eventManager); + await Transport.create(configWithFrequency, eventManager, sessionManager); expect(mockBatchCreate).toHaveBeenCalledWith( configWithFrequency, diff --git a/src/transport/Transport.ts b/src/transport/Transport.ts index 705d975f..8657f088 100644 --- a/src/transport/Transport.ts +++ b/src/transport/Transport.ts @@ -1,12 +1,27 @@ import { app } from 'electron'; import { BatchSizes, BatchUploadFrequencies, type Configuration } from '../config'; -import { EventKind, EventTrack, type EventManager, type ServerEvent } from '../event'; +import { + EventKind, + EventTrack, + type AppMayExitEvent, + type EventManager, + LifecycleKind, + type ServerEvent, +} from '../event'; +import type { SessionManager } from '../domain/session'; +import { addError, monitor } from '../domain/telemetry'; import { BatchManager } from './batch'; +import { WithheldEventBuffer } from './WithheldEventBuffer'; /** * Orchestrates event transport by routing server events from registered domains * through dedicated {@link BatchManager} instances for disk-buffered delivery. + * + * When the application may be about to exit — an uncaught exception in the main process, or a quit + * — whatever is queued but not written yet is written before returning, the session state with it: + * the batch writes on later turns of the event loop, and an exit leaves none. An append already + * issued is not completed here. */ export class Transport { // FlashCat ingest only exposes the RUM track (POST /api/v2/rum). It has no @@ -17,21 +32,47 @@ export class Transport { private tracks: EventTrack[] = [EventTrack.RUM]; private batchManagers: BatchManager[] = []; private basePath: string; + /** + * The process is exiting: only the synchronous listeners of the `exit` event run from here on, so + * whatever arrives is written before returning rather than queued for a turn that never comes. + */ + private terminal = false; private constructor( private readonly config: Configuration, - private readonly eventManager: EventManager + private readonly eventManager: EventManager, + private readonly sessionManager: SessionManager ) { this.basePath = app.getPath('userData'); } /** Creates and fully initializes a Transport instance. */ - static async create(config: Configuration, eventManager: EventManager) { - const transport = new Transport(config, eventManager); + static async create(config: Configuration, eventManager: EventManager, sessionManager: SessionManager) { + const transport = new Transport(config, eventManager, sessionManager); for (const track of transport.tracks) { await transport.setupTrackBatching(track); } + // After the tracks, whose handlers release what an exit must take along, so this runs last. + eventManager.registerHandler({ + canHandle: (event): event is AppMayExitEvent => + event.kind === EventKind.LIFECYCLE && event.lifecycle === LifecycleKind.APP_MAY_EXIT, + handle: () => transport.writePendingSync(), + }); + // Every point a quit passes, and the last one a `process.exit()` runs: an error reported after + // one of them — by a later listener, while quitting — is still taken along by the next. Each + // pass writes only what arrived since the one before. The exit event is terminal: an error a + // later exit listener reports has no next pass, so from there on everything is written as it + // arrives. + const mayExit = (terminal: boolean) => + monitor(() => { + transport.terminal ||= terminal; + eventManager.notify({ kind: EventKind.LIFECYCLE, lifecycle: LifecycleKind.APP_MAY_EXIT, terminal }); + }); + app.on('before-quit', mayExit(false)); + app.on('will-quit', mayExit(false)); + process.on('exit', mayExit(true)); + return transport; } @@ -60,14 +101,32 @@ export class Transport { /** * Create a batch manager for a specific track * and register an event handler that forwards matching server events. + * + * RUM events go through a {@link WithheldEventBuffer} first, which holds those of a session kept by + * `sessionOnError` until it reports an error. Telemetry shares the track but is not session data, + * so it goes straight to the batch. */ private async setupTrackBatching(track: EventTrack) { const batchManager = await this.createBatchManager(track); + const withheldEventBuffer = + track === EventTrack.RUM + ? new WithheldEventBuffer(this.eventManager, this.sessionManager, (event) => batchManager.post(event)) + : undefined; this.eventManager.registerHandler({ canHandle: (event): event is ServerEvent => event.kind === EventKind.SERVER && event.track === track, handle: (event) => { - batchManager.post(event.data); + // By provenance, not by what the event calls itself: the SDK's own telemetry is assembled + // without a source, and is the one thing that bypasses the buffer. A renderer's event + // carries one whatever its `type` says. + if (withheldEventBuffer && event.track === EventTrack.RUM && 'source' in event) { + withheldEventBuffer.collect(event.data); + } else { + batchManager.post(event.data); + } + if (this.terminal) { + this.writePendingSync(); + } }, }); } @@ -76,4 +135,24 @@ export class Transport { async flush() { await Promise.all(this.batchManagers.map((m) => m.flush())); } + + /** Flushes all batch managers to disk, without uploading. */ + flushToDisk(): Promise { + return Promise.all(this.batchManagers.map((m) => m.flushToDisk())).then(() => undefined); + } + + private writePendingSync() { + for (const batchManager of this.batchManagers) { + try { + batchManager.writePendingSync(); + } catch (error) { + // A batch that cannot be written must not cost the session its state: that write is the + // one the next launch reads. + addError(error); + } + } + // After the batches: the release they carry has just marked the session, and the mark must + // reach disk with them. + this.sessionManager.writePendingSync(); + } } diff --git a/src/transport/WithheldEventBuffer.spec.ts b/src/transport/WithheldEventBuffer.spec.ts new file mode 100644 index 00000000..28b6aa11 --- /dev/null +++ b/src/transport/WithheldEventBuffer.spec.ts @@ -0,0 +1,662 @@ +vi.mock('electron', () => ({ + app: { getPath: vi.fn(() => '/mock/user/data') }, +})); + +vi.mock('../domain/telemetry', async (importOriginal) => ({ + ...(await importOriginal()), + addTelemetryDebug: vi.fn(), +})); + +import { afterEach, beforeEach, describe, expect, it, type Mock, vi } from 'vitest'; +import { generateUUID, type TimeStamp } from '@flashcatcloud/browser-core'; +import { EventKind, EventManager, LifecycleKind } from '../event'; +import type { RumEvent } from '../domain/rum'; +import { type Session, TrackingType } from '../domain/session'; +import { addTelemetryDebug } from '../domain/telemetry'; +import { + computeReleaseDelay, + WITHHELD_BUFFER_BYTES_LIMIT, + WITHHELD_BUFFER_DURATION, + WITHHELD_BUFFER_EVENTS_LIMIT, + WITHHELD_BUFFER_RELEASE_MAX_DELAY, + WITHHELD_BUFFER_VIEWS_LIMIT, + WithheldEventBuffer, +} from './WithheldEventBuffer'; + +const SESSION_ID = 'withheld-session-id'; +const RELEASE_DELAY = computeReleaseDelay(SESSION_ID); +const MAIN_VIEW = 'main-view'; + +let sequence = 0; + +function view(id: string, date: number, isActive = true, sessionId = SESSION_ID): RumEvent { + return { + type: 'view', + date, + session: { id: sessionId }, + view: { id, is_active: isActive }, + _dd: { document_version: ++sequence }, + } as unknown as RumEvent; +} + +function detail( + type: 'action' | 'error' | 'resource' | 'long_task', + attributes: Record = {}, + { viewId = MAIN_VIEW, sessionId = SESSION_ID } = {} +): RumEvent { + return { + type, + date: Date.now(), + session: { id: sessionId }, + view: { id: viewId }, + seq: ++sequence, + ...attributes, + } as unknown as RumEvent; +} + +function error(source = 'custom', attributes: Record = {}, viewId = MAIN_VIEW): RumEvent { + return detail('error', { error: { source, message: 'boom' }, ...attributes }, { viewId }); +} + +function resource(statusCode: number, attributes: Record = {}): RumEvent { + return detail('resource', { resource: { status_code: statusCode }, ...attributes }); +} + +/** Padding that makes a single event weigh about `bytes`. */ +function padding(bytes: number) { + return { context: { padding: 'x'.repeat(bytes) } }; +} + +describe('WithheldEventBuffer', () => { + let eventManager: EventManager; + let session: Session; + let setSessionHasError: Mock<(sessionId: string, errorTime: TimeStamp) => void>; + let forwarded: RumEvent[]; + let buffer: WithheldEventBuffer; + + beforeEach(() => { + // `performance` too: the buffer ages by the monotonic clock, which `setSystemTime` leaves alone. + vi.useFakeTimers({ toFake: ['setTimeout', 'clearTimeout', 'setInterval', 'clearInterval', 'Date', 'performance'] }); + vi.setSystemTime(1_000_000); + eventManager = new EventManager(); + session = { id: SESSION_ID, status: 'active', trackingType: TrackingType.TRACKED_ON_ERROR, sampleRate: 0 }; + setSessionHasError = vi.fn((sessionId: string) => { + if (sessionId === session.id) session.hasError = true; + }); + forwarded = []; + buffer = new WithheldEventBuffer( + eventManager, + { getSession: () => ({ ...session }), setSessionHasError }, + (event) => forwarded.push(event) + ); + }); + + afterEach(() => { + vi.useRealTimers(); + vi.clearAllMocks(); + }); + + function notifyLifecycle(lifecycle: (typeof LifecycleKind)[keyof typeof LifecycleKind]) { + eventManager.notify({ kind: EventKind.LIFECYCLE, lifecycle } as never); + } + + function expireSession() { + session.status = 'expired'; + notifyLifecycle(LifecycleKind.SESSION_EXPIRED); + } + + describe('a session drawn by the plain rate', () => { + it('forwards every event as it comes', () => { + session.trackingType = TrackingType.TRACKED; + const events = [view(MAIN_VIEW, 1), detail('action'), error()]; + + events.forEach((event) => buffer.collect(event)); + + expect(forwarded).toEqual(events); + expect(setSessionHasError).not.toHaveBeenCalled(); + }); + }); + + describe('a withheld session', () => { + it('forwards nothing until an error is reported', () => { + buffer.collect(view(MAIN_VIEW, 1)); + buffer.collect(detail('action')); + buffer.collect(resource(200)); + + vi.advanceTimersByTime(10 * WITHHELD_BUFFER_RELEASE_MAX_DELAY); + + expect(forwarded).toEqual([]); + }); + + it('is released by an error, after the per-session jitter', () => { + buffer.collect(view(MAIN_VIEW, 1)); + buffer.collect(detail('action')); + buffer.collect(error()); + + // Marked when released, not when the error arrives: until the release nothing of the session + // has reached the batch, which is what the mark means to a crash reported on the next launch. + expect(setSessionHasError).not.toHaveBeenCalled(); + if (RELEASE_DELAY > 0) { + vi.advanceTimersByTime(RELEASE_DELAY - 1); + expect(forwarded).toEqual([]); + } + vi.advanceTimersByTime(1); + + expect(forwarded.map((event) => event.type)).toEqual(['view', 'error', 'action']); + expect(setSessionHasError).toHaveBeenCalledWith(SESSION_ID, expect.any(Number)); + }); + + it('releases views oldest first, then errors, then the rest oldest first', () => { + const views = [view('renderer-view', 300), view(MAIN_VIEW, 100), view('other-window', 200)]; + const action1 = detail('action', {}, { viewId: 'renderer-view' }); + const resource1 = resource(200); + const firstError = error('source', {}, 'renderer-view'); + const action2 = detail('action', {}, { viewId: 'other-window' }); + const secondError = error(); + [views[0], action1, views[1], resource1, views[2]].forEach((event) => buffer.collect(event)); + + buffer.collect(firstError); + buffer.collect(action2); + buffer.collect(secondError); + vi.advanceTimersByTime(WITHHELD_BUFFER_RELEASE_MAX_DELAY); + + expect(forwarded).toEqual([views[1], views[2], views[0], firstError, secondError, action1, resource1, action2]); + }); + + it('keeps only the latest update of a view', () => { + const first = view(MAIN_VIEW, 1); + const latest = view(MAIN_VIEW, 1); + buffer.collect(first); + buffer.collect(latest); + buffer.collect(error()); + vi.advanceTimersByTime(WITHHELD_BUFFER_RELEASE_MAX_DELAY); + + expect(forwarded.filter((event) => event.type === 'view')).toEqual([latest]); + }); + + it('forwards the events that follow a release as they come', () => { + buffer.collect(view(MAIN_VIEW, 1)); + buffer.collect(error()); + vi.advanceTimersByTime(WITHHELD_BUFFER_RELEASE_MAX_DELAY); + forwarded = []; + + const next = detail('action'); + buffer.collect(next); + + expect(forwarded).toEqual([next]); + }); + + it('is released at once by a crash reported on the next launch: the batch cycle spreads that upload already', () => { + buffer.collect(view(MAIN_VIEW, 1)); + const crash = error('source', { error: { source: 'source', is_crash: true } }); + + buffer.collect(crash); + + expect(forwarded.map((event) => event.type)).toEqual(['view', 'error']); + expect(setSessionHasError).toHaveBeenCalledWith(SESSION_ID, expect.any(Number)); + }); + + it('is released by an error it cannot serialize, which goes on its own while the history follows', () => { + buffer.collect(view(MAIN_VIEW, 1)); + const history = detail('action'); + buffer.collect(history); + const unserializable = error('source', { context: { n: 1n } }); + + expect(() => buffer.collect(unserializable)).not.toThrow(); + vi.advanceTimersByTime(WITHHELD_BUFFER_RELEASE_MAX_DELAY); + + expect(forwarded).toContain(unserializable); + expect(forwarded).toContain(history); + }); + + it('releases synchronously once the process is exiting, as no timer will run', () => { + buffer.collect(view(MAIN_VIEW, 1)); + eventManager.notify({ + kind: EventKind.LIFECYCLE, + lifecycle: LifecycleKind.APP_MAY_EXIT, + terminal: true, + } as never); + expect(forwarded).toEqual([]); + + const late = error('source'); + buffer.collect(late); + + expect(forwarded.map((event) => event.type)).toEqual(['view', 'error']); + }); + + it('is released by an error whose text is not ASCII, as the main process has no window to count bytes with', () => { + buffer.collect(view(MAIN_VIEW, 1)); + buffer.collect(error('source', { error: { source: 'source', message: '支付失败 💥' } })); + vi.advanceTimersByTime(WITHHELD_BUFFER_RELEASE_MAX_DELAY); + + expect(forwarded.map((event) => event.type)).toEqual(['view', 'error']); + }); + + it('is not released by an error the SDK reported about itself', () => { + buffer.collect(view(MAIN_VIEW, 1)); + buffer.collect(error('agent')); + vi.advanceTimersByTime(10 * WITHHELD_BUFFER_RELEASE_MAX_DELAY); + + expect(forwarded).toEqual([]); + expect(setSessionHasError).not.toHaveBeenCalled(); + }); + + it('is released once the session is marked errored elsewhere, by its next event', () => { + buffer.collect(view(MAIN_VIEW, 1)); + // What `CrashCollection` does for a crash reported on the next launch. + session.hasError = true; + buffer.collect(detail('action')); + vi.advanceTimersByTime(WITHHELD_BUFFER_RELEASE_MAX_DELAY); + + expect(forwarded.map((event) => event.type)).toEqual(['view', 'action']); + }); + + it('is released by an error that carries no error object, and holds events that carry no resource or view', () => { + buffer.collect(view(MAIN_VIEW, 1)); + const bareResource = { + type: 'resource', + date: Date.now(), + session: { id: SESSION_ID }, + view: { id: MAIN_VIEW }, + } as unknown as RumEvent; + const viewlessAction = { type: 'action', date: Date.now(), session: { id: SESSION_ID } } as unknown as RumEvent; + const bareError = { + type: 'error', + date: Date.now(), + session: { id: SESSION_ID }, + view: { id: MAIN_VIEW }, + } as unknown as RumEvent; + expect(() => buffer.collect(bareResource)).not.toThrow(); + expect(() => buffer.collect(viewlessAction)).not.toThrow(); + expect(() => buffer.collect(bareError)).not.toThrow(); + vi.advanceTimersByTime(WITHHELD_BUFFER_RELEASE_MAX_DELAY); + + expect(forwarded).toContain(bareError); + expect(forwarded).toContain(viewlessAction); + expect(forwarded).toContain(bareResource); + }); + + it('never evicts the error that earned the release, even from a buffer full of errors that did not', () => { + buffer.collect(view(MAIN_VIEW, 1)); + for (let i = 0; i < WITHHELD_BUFFER_EVENTS_LIMIT; i += 1) { + buffer.collect(error('agent')); + } + const releasing = error('source'); + buffer.collect(releasing); + vi.advanceTimersByTime(WITHHELD_BUFFER_RELEASE_MAX_DELAY); + + expect(forwarded).toContain(releasing); + }); + + it('leaves the events of another session alone', () => { + buffer.collect(view(MAIN_VIEW, 1)); + const other = detail('action', {}, { sessionId: 'previous-session-id' }); + + buffer.collect(other); + + expect(forwarded).toEqual([other]); + }); + + it('reports the release through telemetry', () => { + buffer.collect(view(MAIN_VIEW, 1)); + buffer.collect(detail('action')); + buffer.collect(error()); + vi.advanceTimersByTime(WITHHELD_BUFFER_RELEASE_MAX_DELAY); + + expect(addTelemetryDebug).toHaveBeenCalledWith('Error session event buffer released', { + 'buffer.views_count': 1, + 'buffer.events_count': 2, + 'buffer.dropped_count': 0, + 'buffer.bytes': expect.any(Number) as number, + }); + }); + }); + + describe('window', () => { + it('keeps only the last minute of detail', () => { + buffer.collect(view(MAIN_VIEW, 1)); + const old = detail('action'); + buffer.collect(old); + vi.advanceTimersByTime(WITHHELD_BUFFER_DURATION + 1); + const recent = detail('action'); + buffer.collect(recent); + + buffer.collect(error()); + vi.advanceTimersByTime(WITHHELD_BUFFER_RELEASE_MAX_DELAY); + + expect(forwarded).toContain(recent); + expect(forwarded).not.toContain(old); + }); + + it('ages by the monotonic clock, so a wall-clock correction before the error does not prune the history', () => { + buffer.collect(view(MAIN_VIEW, 1)); + const history = detail('action'); + buffer.collect(history); + // The system clock jumps two minutes ahead; next to no time passes. + vi.setSystemTime(Date.now() + 2 * WITHHELD_BUFFER_DURATION); + buffer.collect(error()); + vi.advanceTimersByTime(WITHHELD_BUFFER_RELEASE_MAX_DELAY); + + expect(forwarded).toContain(history); + }); + + it('freezes the window when the release is scheduled, so a late timer does not prune the history', () => { + buffer.collect(view(MAIN_VIEW, 1)); + const beforeError = detail('action'); + buffer.collect(beforeError); + buffer.collect(error()); + + // A timer that fires long after it was due, as in a suspended process. + vi.setSystemTime(Date.now() + 2 * WITHHELD_BUFFER_DURATION); + vi.advanceTimersByTime(WITHHELD_BUFFER_RELEASE_MAX_DELAY); + + expect(forwarded).toContain(beforeError); + }); + + it('drops an ended view once no detail of it is left, but keeps an active one', () => { + buffer.collect(view(MAIN_VIEW, 1)); + buffer.collect(view('ended-view', 2, false)); + buffer.collect(view('active-view', 3, true)); + buffer.collect(detail('action')); + + vi.advanceTimersByTime(WITHHELD_BUFFER_DURATION + 1); + buffer.collect(error()); + vi.advanceTimersByTime(WITHHELD_BUFFER_RELEASE_MAX_DELAY); + + const viewIds = forwarded.filter((event) => event.type === 'view').map((event) => event.view.id); + expect(viewIds).toEqual([MAIN_VIEW, 'active-view']); + }); + + it('keeps an ended view that arrives ahead of its detail, as a crash reported on the next launch brings it', () => { + buffer.collect(view(MAIN_VIEW, 2)); + session.hasError = true; + const crashedView = view('crashed-view', 1, false); + buffer.collect(crashedView); + vi.advanceTimersByTime(WITHHELD_BUFFER_RELEASE_MAX_DELAY); + + expect(forwarded).toEqual([crashedView, expect.objectContaining({ view: { id: MAIN_VIEW, is_active: true } })]); + }); + + it('keeps an error whose view stopped receiving detail a while ago, as long as the view is active', () => { + buffer.collect(view(MAIN_VIEW, 1)); + buffer.collect(view('idle-window', 2, true)); + vi.advanceTimersByTime(5 * WITHHELD_BUFFER_DURATION); + + const idleWindowError = error('source', {}, 'idle-window'); + buffer.collect(idleWindowError); + vi.advanceTimersByTime(WITHHELD_BUFFER_RELEASE_MAX_DELAY); + + expect(forwarded).toContain(idleWindowError); + }); + }); + + describe('budget', () => { + it('evicts long tasks and successful requests first, then the rest, then errors newest first', () => { + buffer.collect(view(MAIN_VIEW, 1)); + const failedRequest = resource(500); + const firstErrorOfAgent = error('agent'); + const secondErrorOfAgent = error('agent'); + buffer.collect(failedRequest); + buffer.collect(firstErrorOfAgent); + buffer.collect(secondErrorOfAgent); + buffer.collect(detail('long_task')); + for (let i = 0; i < WITHHELD_BUFFER_EVENTS_LIMIT - 3; i += 1) { + buffer.collect(resource(200)); + } + buffer.collect(detail('action')); + + buffer.collect(error()); + vi.advanceTimersByTime(WITHHELD_BUFFER_RELEASE_MAX_DELAY); + + const types = forwarded.map((event) => event.type); + expect(types.filter((type) => type === 'long_task')).toEqual([]); + expect(types.filter((type) => type === 'error')).toHaveLength(3); + expect(forwarded).toContain(failedRequest); + expect(forwarded).toContain(firstErrorOfAgent); + expect(forwarded.length - 1).toBe(WITHHELD_BUFFER_EVENTS_LIMIT); + }); + + it('evicts the newest error when only errors are left, so the first error stays', () => { + buffer.collect(view(MAIN_VIEW, 1)); + const errors = Array.from({ length: WITHHELD_BUFFER_EVENTS_LIMIT + 5 }, () => error('agent')); + errors.forEach((event) => buffer.collect(event)); + // Releases through the mark rather than through an error, which would itself join the buffer. + session.hasError = true; + buffer.collect(view(MAIN_VIEW, 1)); + vi.advanceTimersByTime(WITHHELD_BUFFER_RELEASE_MAX_DELAY); + + const released = forwarded.filter((event) => event.type === 'error'); + expect(released).toEqual(errors.slice(0, WITHHELD_BUFFER_EVENTS_LIMIT)); + }); + + it('stays within the byte budget, dropping successful requests before failed ones', () => { + buffer.collect(view(MAIN_VIEW, 1)); + const failed = resource(0, padding(20 * 1024)); + buffer.collect(failed); + const successes = Array.from({ length: 4 }, () => resource(200, padding(20 * 1024))); + successes.forEach((event) => buffer.collect(event)); + + buffer.collect(error()); + vi.advanceTimersByTime(WITHHELD_BUFFER_RELEASE_MAX_DELAY); + + const bytes = forwarded + .filter((event) => event.type !== 'view') + .reduce((sum, event) => sum + JSON.stringify(event).length, 0); + expect(bytes).toBeLessThanOrEqual(WITHHELD_BUFFER_BYTES_LIMIT); + expect(forwarded).toContain(failed); + expect(forwarded).toContain(successes[successes.length - 1]); + expect(forwarded).not.toContain(successes[0]); + }); + + it('drops a view update larger than the whole budget, keeping the version held before it', () => { + const small = view(MAIN_VIEW, 1); + buffer.collect(small); + buffer.collect({ ...view(MAIN_VIEW, 1), ...padding(WITHHELD_BUFFER_BYTES_LIMIT) } as RumEvent); + buffer.collect({ ...view('huge-from-the-start', 2), ...padding(WITHHELD_BUFFER_BYTES_LIMIT) } as RumEvent); + buffer.collect(error()); + vi.advanceTimersByTime(WITHHELD_BUFFER_RELEASE_MAX_DELAY); + + expect(forwarded.filter((event) => event.type === 'view')).toEqual([small]); + }); + + it('drops a single detail larger than the whole budget, and keeps the history', () => { + buffer.collect(view(MAIN_VIEW, 1)); + const history = detail('action'); + buffer.collect(history); + buffer.collect(detail('action', padding(WITHHELD_BUFFER_BYTES_LIMIT))); + + buffer.collect(error()); + vi.advanceTimersByTime(WITHHELD_BUFFER_RELEASE_MAX_DELAY); + + expect(forwarded.map((event) => event.type)).toEqual(['view', 'error', 'action']); + expect(forwarded).toContain(history); + }); + + it('forwards a releasing error larger than the whole budget at once, and the history after the jitter', () => { + buffer.collect(view(MAIN_VIEW, 1)); + const history = detail('action'); + buffer.collect(history); + const largeError = error('custom', padding(WITHHELD_BUFFER_BYTES_LIMIT)); + + buffer.collect(largeError); + + expect(forwarded).toEqual([largeError]); + vi.advanceTimersByTime(WITHHELD_BUFFER_RELEASE_MAX_DELAY); + expect(forwarded.slice(1).map((event) => event.type)).toEqual(['view', 'action']); + }); + + it('evicts ended views first past the view limit, and still releases a detail whose view went', () => { + buffer.collect(view(MAIN_VIEW, 0)); + // An ended view arrives after its detail: its final update is emitted when it ends. + const orphan = detail('action', {}, { viewId: 'view-0' }); + buffer.collect(orphan); + buffer.collect(view('view-0', 1, false)); + for (let i = 1; i <= WITHHELD_BUFFER_VIEWS_LIMIT; i += 1) { + buffer.collect(detail('action', {}, { viewId: `view-${i}` })); + buffer.collect(view(`view-${i}`, i + 1, false)); + } + + buffer.collect(error()); + vi.advanceTimersByTime(WITHHELD_BUFFER_RELEASE_MAX_DELAY); + + const views = forwarded.filter((event) => event.type === 'view'); + expect(views).toHaveLength(WITHHELD_BUFFER_VIEWS_LIMIT); + expect(views[0].view.id).toBe(MAIN_VIEW); + // Views order the release; a detail is never lost for want of its view. + expect(forwarded).toContain(orphan); + }); + + it('releases every detail it holds, with the errors first, even those whose view was never held', () => { + buffer.collect(view(MAIN_VIEW, 0)); + const viewlessAction = detail('action', {}, { viewId: 'renderer-view-not-held' }); + const viewlessError = error('source', {}, 'renderer-view-not-held'); + buffer.collect(viewlessAction); + buffer.collect(viewlessError); + vi.advanceTimersByTime(WITHHELD_BUFFER_RELEASE_MAX_DELAY); + + expect(forwarded.map((event) => event.type)).toEqual(['view', 'error', 'action']); + expect(forwarded).toContain(viewlessError); + expect(addTelemetryDebug).toHaveBeenCalledWith( + 'Error session event buffer released', + expect.objectContaining({ 'buffer.events_count': 2, 'buffer.dropped_count': 0 }) + ); + }); + + it('keeps the view of the releasing error past the view limit, ended as it may be', () => { + buffer.collect(view(MAIN_VIEW, 0)); + buffer.collect(view('errored-view', 1)); + const releasingError = error('source', {}, 'errored-view'); + buffer.collect(releasingError); + buffer.collect(view('errored-view', 1, false)); + // During the jitter, more views than the limit allows arrive and end, every one of them + // updated after the errored view — the eviction order of ended views, were it the only rule. + for (let i = 1; i <= WITHHELD_BUFFER_VIEWS_LIMIT; i += 1) { + buffer.collect(view(`view-${i}`, i + 1, false)); + } + vi.advanceTimersByTime(WITHHELD_BUFFER_RELEASE_MAX_DELAY); + + expect(forwarded).toContain(releasingError); + expect(forwarded.filter((event) => event.type === 'view').map((event) => event.view.id)).toContain( + 'errored-view' + ); + }); + }); + + describe('budget, crash reported on the next launch', () => { + it('keeps the view a crash brings along past the view limit, until the crash arrives for it', () => { + for (let i = 1; i <= WITHHELD_BUFFER_VIEWS_LIMIT; i += 1) { + buffer.collect(view(`window-${i}`, i)); + } + // What CrashCollection emits, in this order: the crashed view ended, then the crash itself. + const crashedView = view('crashed-view', 0, false); + const crash = error('source', { error: { source: 'source', is_crash: true } }, 'crashed-view'); + session.hasError = true; + buffer.collect(crashedView); + buffer.collect(crash); + vi.advanceTimersByTime(WITHHELD_BUFFER_RELEASE_MAX_DELAY); + + expect(forwarded).toContain(crashedView); + expect(forwarded).toContain(crash); + }); + }); + + describe('budget, crash larger than the budget', () => { + it('keeps the view of a crash forwarded on its own past the view limit, until the release', () => { + for (let i = 1; i <= WITHHELD_BUFFER_VIEWS_LIMIT; i += 1) { + buffer.collect(view(`window-${i}`, i)); + } + const crashedView = view('crashed-view', 0, false); + const oversizeCrash = error( + 'source', + { error: { source: 'source', is_crash: true }, ...padding(WITHHELD_BUFFER_BYTES_LIMIT) }, + 'crashed-view' + ); + session.hasError = true; + buffer.collect(crashedView); + buffer.collect(oversizeCrash); + // A renderer view the crashed view had displaced comes back during the jitter. + buffer.collect(view('window-1', 1)); + vi.advanceTimersByTime(WITHHELD_BUFFER_RELEASE_MAX_DELAY); + + expect(forwarded).toContain(crashedView); + }); + }); + + describe('end of the session', () => { + it('throws away what never earned its release', () => { + buffer.collect(view(MAIN_VIEW, 1)); + buffer.collect(detail('action')); + + expireSession(); + vi.advanceTimersByTime(10 * WITHHELD_BUFFER_RELEASE_MAX_DELAY); + + expect(forwarded).toEqual([]); + }); + + it('releases at once what is waiting for the jitter', () => { + buffer.collect(view(MAIN_VIEW, 1)); + buffer.collect(error()); + + expireSession(); + + expect(forwarded.map((event) => event.type)).toEqual(['view', 'error']); + }); + + it('does not mistake the next session for the one that was thrown away', () => { + buffer.collect(view(MAIN_VIEW, 1)); + expireSession(); + session = { id: 'next-session-id', status: 'active', trackingType: TrackingType.TRACKED, sampleRate: 100 }; + + const next = detail('action', {}, { sessionId: 'next-session-id' }); + buffer.collect(next); + + expect(forwarded).toEqual([next]); + }); + }); + + describe('application exit', () => { + it('releases at once what is waiting for the jitter', () => { + buffer.collect(view(MAIN_VIEW, 1)); + buffer.collect(error()); + + notifyLifecycle(LifecycleKind.APP_MAY_EXIT); + + expect(forwarded.map((event) => event.type)).toEqual(['view', 'error']); + expect(setSessionHasError).toHaveBeenCalledWith(SESSION_ID, expect.any(Number)); + }); + + it('keeps what has not earned its release', () => { + buffer.collect(view(MAIN_VIEW, 1)); + const history = detail('action'); + buffer.collect(history); + + notifyLifecycle(LifecycleKind.APP_MAY_EXIT); + expect(forwarded).toEqual([]); + + buffer.collect(error()); + vi.advanceTimersByTime(WITHHELD_BUFFER_RELEASE_MAX_DELAY); + expect(forwarded).toContain(history); + }); + }); +}); + +describe('computeReleaseDelay', () => { + it('is deterministic per session', () => { + expect(computeReleaseDelay(SESSION_ID)).toBe(computeReleaseDelay(SESSION_ID)); + }); + + it('spreads sessions over the whole jitter window', () => { + const buckets = new Array(10).fill(0); + for (let i = 0; i < 1000; i += 1) { + const delay = computeReleaseDelay(generateUUID()); + expect(delay).toBeGreaterThanOrEqual(0); + expect(delay).toBeLessThan(WITHHELD_BUFFER_RELEASE_MAX_DELAY); + buckets[Math.floor(delay / (WITHHELD_BUFFER_RELEASE_MAX_DELAY / 10))] += 1; + } + + // 100 per bucket on average: a sum-of-char-codes hash would pile them into one or two. + for (const count of buckets) { + expect(count).toBeGreaterThan(50); + } + }); +}); diff --git a/src/transport/WithheldEventBuffer.ts b/src/transport/WithheldEventBuffer.ts new file mode 100644 index 00000000..8ec42a0d --- /dev/null +++ b/src/transport/WithheldEventBuffer.ts @@ -0,0 +1,417 @@ +import { ONE_KIBI_BYTE, ONE_SECOND, relativeNow, type TimeStamp, timeStampNow } from '@flashcatcloud/browser-core'; +import { EventKind, type EventManager, type LifecycleEvent, LifecycleKind } from '../event'; +import type { RumEvent } from '../domain/rum'; +import { type SessionManager, withholdsEvents } from '../domain/session'; +import { addTelemetryDebug, setTimeout } from '../domain/telemetry'; + +/** + * How much history a withheld session keeps: the minute leading up to its error. The browser SDK + * makes the same promise. + */ +export const WITHHELD_BUFFER_DURATION = 60 * ONE_SECOND; + +/** Memory bound. Above it the least valuable events are dropped first, see {@link EvictionTier}. */ +export const WITHHELD_BUFFER_BYTES_LIMIT = 64 * ONE_KIBI_BYTE; +export const WITHHELD_BUFFER_EVENTS_LIMIT = 200; + +/** + * A view is the container its events hang from: the backend builds the session row out of view + * events, so a detail released without its view would be unreachable. Views are kept out of the + * eviction budget for that reason, and this only bounds pathological navigation counts. + */ +export const WITHHELD_BUFFER_VIEWS_LIMIT = 50; + +/** + * Correlated errors make every client release at the same instant, right when whatever caused them + * is already under strain. Releases are spread over this window instead. + */ +export const WITHHELD_BUFFER_RELEASE_MAX_DELAY = 3 * ONE_SECOND; + +/** What gets dropped first when the buffer is over budget. Lower goes first. */ +const EvictionTier = { + /** Long tasks, and requests that succeeded without complaint. */ + FIRST: 0, + /** Actions, vitals, failed requests: they explain what led to the error. */ + LAST: 1, + /** + * Errors are the reason the session is kept at all, so they go only once nothing else is left — + * and even then the newest goes first, because the earliest error is the one that releases the + * buffer and the one the session is about. + */ + LAST_RESORT: 2, +} as const; +type EvictionTier = (typeof EvictionTier)[keyof typeof EvictionTier]; + +interface WithheldView { + event: RumEvent; + /** When its latest update arrived, on the monotonic clock: a wall-clock correction must not age the buffer. */ + time: number; +} + +interface WithheldEvent { + event: RumEvent; + viewId: string; + time: number; + bytes: number; + tier: EvictionTier; +} + +type SessionSource = Pick; + +type SettleCause = 'session-ended' | 'may-exit'; + +/** + * Holds the RUM events of a session kept by `sessionOnError` until it reports an error. + * + * It sits right before the batch, after assembly: main-process and renderer events alike reach it + * final, and a renderer error dropped by the renderer's `beforeSend` never gets here, so it cannot + * release anything. Nothing it holds is written to disk — a session that never errors leaves no + * trace — and only the last {@link WITHHELD_BUFFER_DURATION} is kept. + * + * The session's first error releases the buffer behind a per-session jitter: views oldest first, + * then errors, then everything else, oldest first. The session is marked as errored at that moment, + * not when the error arrives: the mark is what a crash reported on the next launch reads as "the + * crashed view reached the batch", and until the release it has not. From then on its events go + * straight to the batch. + * A session that ends without an error is thrown away with everything it held; its stragglers are + * discarded at assembly (see `SessionContext`). + * + * Unlike a browser page, the main process runs several views at once — its own, and the current + * one of every window — so "the current view", which is never pruned, is every view whose latest + * update still reports it active. An ended view is kept as long as its latest update or any of its + * detail is inside the window: a crash reported on the next launch brings its view along ended, and + * the crash itself, too large for the budget, does not join the buffer to hold the view in place. + */ +export class WithheldEventBuffer { + /** Latest event per view, in the order they were last updated. */ + private views = new Map(); + private details: WithheldEvent[] = []; + private bytes = 0; + private droppedCount = 0; + private withheldForSessionId: string | undefined; + /** Views of errors forwarded on their own for exceeding the budget: protected from eviction like a held error's. */ + private oversizeErrorViewIds = new Set(); + /** The error that earned the release: never evicted, whatever else the buffer holds. */ + private armingEvent: RumEvent | undefined; + /** The process is exiting: a release is made as it is earned, since no timer will run. */ + private terminal = false; + private releaseTimeoutId: ReturnType | undefined; + /** When the release was scheduled, on the monotonic clock: what freezes the window — see {@link prune}. */ + private releaseScheduledAt: number | undefined; + /** The same moment on the wall clock, which is what the session's history is kept in. */ + private releaseErrorTime: TimeStamp | undefined; + + constructor( + eventManager: EventManager, + private readonly sessionManager: SessionSource, + private readonly forward: (event: RumEvent) => void + ) { + eventManager.registerHandler({ + canHandle: (event): event is LifecycleEvent => + event.kind === EventKind.LIFECYCLE && + (event.lifecycle === LifecycleKind.SESSION_EXPIRED || event.lifecycle === LifecycleKind.APP_MAY_EXIT), + handle: (event) => { + if (event.lifecycle === LifecycleKind.APP_MAY_EXIT && event.terminal) { + this.terminal = true; + } + this.settle(event.lifecycle === LifecycleKind.SESSION_EXPIRED ? 'session-ended' : 'may-exit'); + }, + }); + } + + collect(event: RumEvent): void { + const session = this.sessionManager.getSession(); + const sessionId = event.session.id; + + if (session.status === 'active' && sessionId === session.id && withholdsEvents(session)) { + this.withheldForSessionId = sessionId; + if (!isReleasingError(event)) { + this.hold(event); + return; + } + // The session earns its release with this error, which then leaves with the rest, below. + } + + if (sessionId === this.withheldForSessionId) { + const bytes = event.type === 'error' ? computeEventBytes(event) : undefined; + if (this.releaseTimeoutId === undefined && event.type === 'error') { + this.armingEvent = event; + } + if (bytes !== undefined && bytes > WITHHELD_BUFFER_BYTES_LIMIT) { + // The session has earned its release, but an error larger than the whole budget would evict + // the history it is meant to come with. It goes to the batch on its own instead; the history + // still waits for the jitter, which exists for exactly the correlated outage at hand. + this.oversizeErrorViewIds.add(viewIdOf(event)); + this.forward(event); + } else { + // Typically the error itself: it joins what is held, so the whole history leaves in order. + this.hold(event, bytes); + } + this.scheduleRelease(); + return; + } + + this.forward(event); + } + + /** `measuredBytes` is the event's serialized size, when the caller already measured it. */ + private hold(event: RumEvent, measuredBytes?: number): void { + if (event.type === 'view') { + const viewId = event.view?.id; + if (viewId === undefined || computeEventBytes(event) > WITHHELD_BUFFER_BYTES_LIMIT) { + // A view without an id is no container for anything; an update larger than the whole + // budget is not worth holding, and the version held before it keeps the view's place. + this.droppedCount += 1; + return; + } + // Upsert: a view event is cumulative, so the latest one supersedes the ones before it. The + // delete moves it to the end, so the map stays ordered by last update. + this.views.delete(viewId); + this.views.set(viewId, { event, time: relativeNow() }); + this.evictViewsOverLimit(viewId); + this.prune(); + return; + } + + const bytes = measuredBytes ?? computeEventBytes(event); + if (bytes > WITHHELD_BUFFER_BYTES_LIMIT) { + // It could never be part of a release, and holding it would evict the entire minute before it + // to make room it will never fit into. + this.droppedCount += 1; + return; + } + this.details.push({ event, viewId: viewIdOf(event), time: relativeNow(), bytes, tier: getEvictionTier(event) }); + this.bytes += bytes; + + this.prune(); + while (this.details.length > WITHHELD_BUFFER_EVENTS_LIMIT || this.bytes > WITHHELD_BUFFER_BYTES_LIMIT) { + if (!this.evictOne()) { + break; + } + } + } + + /** + * Drops the oldest views past the limit: ended ones first, since an active one is still + * collecting, and never — while any other is left — a view that holds an error, nor the one just + * updated. A detail is released with or without its view (see {@link release}), but the error is + * what the session is kept for, and its view is what the backend hangs it from; the view just + * updated may be the one its error is about to arrive for, as a crash reported on the next launch + * brings its view first. + */ + private evictViewsOverLimit(justUpdatedViewId: string): void { + while (this.views.size > WITHHELD_BUFFER_VIEWS_LIMIT) { + const viewsWithError = new Set([ + ...this.oversizeErrorViewIds, + ...this.details.filter((held) => held.event.type === 'error').map((held) => held.viewId), + ]); + const cost = (viewId: string, view: WithheldView) => + (viewsWithError.has(viewId) ? 2 : 0) + (isActiveView(view.event) ? 1 : 0); + let evictedViewId: string | undefined; + for (const [viewId, view] of this.views) { + if (viewId === justUpdatedViewId) { + continue; + } + if (evictedViewId === undefined || cost(viewId, view) < cost(evictedViewId, this.views.get(evictedViewId)!)) { + evictedViewId = viewId; + } + } + this.views.delete(evictedViewId!); + } + } + + /** Drops what has aged out of the window, so the span kept is the one promised. */ + private prune(): void { + // Once a release is scheduled the window stops moving: a delayed timer must not throw away the + // very minute the release exists to deliver. + const oldestAllowed = (this.releaseScheduledAt ?? relativeNow()) - WITHHELD_BUFFER_DURATION; + let cutoff = 0; + while (cutoff < this.details.length && this.details[cutoff].time < oldestAllowed) { + this.bytes -= this.details[cutoff].bytes; + this.droppedCount += 1; + cutoff += 1; + } + if (cutoff > 0) { + this.details = this.details.slice(cutoff); + } + + // A view is kept as the container of its detail, so an ended view that aged out of the window + // with none of its detail left has nothing to contain. An active one stays: it is where the next + // error hangs from. + const viewsWithDetail = new Set(this.details.map((held) => held.viewId)); + for (const [viewId, view] of this.views) { + if (!isActiveView(view.event) && view.time < oldestAllowed && !viewsWithDetail.has(viewId)) { + this.views.delete(viewId); + } + } + } + + /** Removes one event of the least valuable tier present. Returns false when there is none left. */ + private evictOne(): boolean { + for (const tier of [EvictionTier.FIRST, EvictionTier.LAST]) { + const index = this.details.findIndex((held) => held.tier === tier); + if (index !== -1) { + this.evictAt(index); + return true; + } + } + // Only errors are left: the newest goes, so an error storm cannot push out the first error — + // and never the one that earned the release, whatever else is held. + for (let index = this.details.length - 1; index >= 0; index -= 1) { + if (this.details[index].event !== this.armingEvent) { + this.evictAt(index); + return true; + } + } + return false; + } + + private evictAt(index: number): void { + this.bytes -= this.details[index].bytes; + this.droppedCount += 1; + this.details.splice(index, 1); + } + + private scheduleRelease(): void { + if (this.releaseTimeoutId !== undefined) { + return; + } + this.releaseScheduledAt = relativeNow(); + this.releaseErrorTime = timeStampNow(); + if (this.terminal || isCrash(this.armingEvent)) { + // No timer will run once the process is exiting. A crash reported on the next launch has no + // storm to spread either: it reaches the intake with the next upload cycle, which spreads + // uploads already, and its dump is kept only until its report is on disk. + this.release(); + return; + } + this.releaseTimeoutId = setTimeout(() => this.release(), computeReleaseDelay(this.withheldForSessionId!)); + } + + /** + * Called when what is held may not get another chance to leave: the session ended (discarding + * what never earned its release), or the application may be about to exit (keeping it: a quit + * that does not happen leaves the session running, and a real one takes the buffer with it either + * way). Either way a session that reported its error is released now rather than after the + * jitter. The transport then writes what an exit would otherwise take along, see `Transport`. + */ + private settle(cause: SettleCause): void { + if (this.withheldForSessionId === undefined) { + return; + } + const session = this.sessionManager.getSession(); + const hasErrored = session.id === this.withheldForSessionId && !!session.hasError; + if (this.releaseTimeoutId !== undefined || hasErrored) { + this.release(); + } else if (cause === 'session-ended') { + this.clear(); + } + } + + private release(): void { + this.prune(); + // Marked as of when the error arrived, which is inside the session's entry even if the session + // ended since: a mark on the entry is what lets the session's final events through assembly. + this.sessionManager.setSessionHasError(this.withheldForSessionId!, this.releaseErrorTime ?? timeStampNow()); + + // Oldest first: the backend builds the session out of whichever of its views arrives first. + const views = [...this.views.values()].map((view) => view.event).sort((left, right) => left.date - right.date); + + views.forEach((view) => this.forward(view)); + // Every detail held, whether or not its view still is: an errored session must not lose its + // error or its history, and the views only order the release. The errors right behind the + // views, then the rest oldest first: if the application is about to exit, the first writes are + // the ones most likely to make it. + this.details.filter((held) => held.event.type === 'error').forEach((held) => this.forward(held.event)); + this.details.filter((held) => held.event.type !== 'error').forEach((held) => this.forward(held.event)); + + addTelemetryDebug('Error session event buffer released', { + 'buffer.views_count': views.length, + 'buffer.events_count': this.details.length, + 'buffer.dropped_count': this.droppedCount, + 'buffer.bytes': this.bytes, + }); + + this.clear(); + } + + private clear(): void { + clearTimeout(this.releaseTimeoutId); + this.releaseTimeoutId = undefined; + this.releaseScheduledAt = undefined; + this.releaseErrorTime = undefined; + this.views = new Map(); + this.details = []; + this.bytes = 0; + this.droppedCount = 0; + this.withheldForSessionId = undefined; + this.oversizeErrorViewIds = new Set(); + this.armingEvent = undefined; + } +} + +/** + * An error the application reported. The SDK's own failures are not: counting them would turn every + * session into an error session for any customer whose network blocks the intake. + */ +function isReleasingError(event: RumEvent): boolean { + return event.type === 'error' && event.error?.source !== 'agent'; +} + +function isActiveView(view: RumEvent): boolean { + return view.type === 'view' && view.view?.is_active !== false; +} + +/** A renderer may send an event without one; it is then held and released like any other, under no view. */ +function viewIdOf(event: RumEvent): string { + return event.view?.id ?? ''; +} + +function isCrash(event: RumEvent | undefined): boolean { + return event?.type === 'error' && event.error?.is_crash === true; +} + +/** + * Node's count: browser-core's reaches for `window.TextEncoder` on non-ASCII text, which the main + * process has not. An event that cannot be serialized — a BigInt in a context, say — counts as + * larger than any budget, so that it is dropped or forwarded on its own rather than throwing here. + */ +function computeEventBytes(event: RumEvent): number { + try { + return Buffer.byteLength(JSON.stringify(event), 'utf8'); + } catch { + return Infinity; + } +} + +function getEvictionTier(event: RumEvent): EvictionTier { + switch (event.type) { + case 'error': + return EvictionTier.LAST_RESORT; + case 'long_task': + return EvictionTier.FIRST; + case 'resource': { + // A request that failed is part of how the error happened; one that succeeded rarely is. An + // unknown status code is treated like an ordinary success. + const statusCode = event.resource?.status_code ?? -1; + return statusCode === 0 || statusCode >= 400 ? EvictionTier.LAST : EvictionTier.FIRST; + } + default: + return EvictionTier.LAST; + } +} + +/** + * Deterministic per session, so a client always spreads to the same offset. + * + * Multiplicative rather than a running sum: session ids are same-length strings drawn from the same + * small alphabet, so summing their character codes lands almost every session within a few hundred + * milliseconds of the same value — which delays the herd instead of spreading it. + */ +export function computeReleaseDelay(sessionId: string): number { + let hash = 0; + for (let i = 0; i < sessionId.length; i += 1) { + hash = Math.imul(hash, 31) + sessionId.charCodeAt(i); + } + return Math.abs(hash) % WITHHELD_BUFFER_RELEASE_MAX_DELAY; +} diff --git a/src/transport/batch/BatchManager.spec.ts b/src/transport/batch/BatchManager.spec.ts index 94ca0c1e..8344497c 100644 --- a/src/transport/batch/BatchManager.spec.ts +++ b/src/transport/batch/BatchManager.spec.ts @@ -117,20 +117,32 @@ describe('BatchManager', () => { expect(mockConsumerUpload).toHaveBeenCalled(); }); - it('should skip concurrent flush when one is already in progress', async () => { + it('runs the next cycle after one that failed, and reports the failure to the flush that ran it', async () => { + mockConsumerUpload.mockRejectedValueOnce(new Error('intake down')); + const manager = await BatchManager.create(config, batchConfig); + + await expect(manager.flush()).rejects.toThrow('intake down'); + await expect(manager.flush()).resolves.toBeUndefined(); + + expect(mockConsumerUpload).toHaveBeenCalledTimes(2); + }); + + it('runs a flush requested during another one after it, so that it covers what arrived since', async () => { let resolveFlush!: () => void; mockProducerFlush.mockReturnValueOnce(new Promise((resolve) => (resolveFlush = resolve))); const manager = await BatchManager.create(config, batchConfig); const firstFlush = manager.flush(); const secondFlush = manager.flush(); + await Promise.resolve(); + expect(mockProducerFlush).toHaveBeenCalledTimes(1); resolveFlush(); await firstFlush; await secondFlush; - expect(mockProducerFlush).toHaveBeenCalledTimes(1); - expect(mockConsumerUpload).toHaveBeenCalledTimes(1); + expect(mockProducerFlush).toHaveBeenCalledTimes(2); + expect(mockConsumerUpload).toHaveBeenCalledTimes(2); }); }); diff --git a/src/transport/batch/BatchManager.ts b/src/transport/batch/BatchManager.ts index eb593e7c..866be6c7 100644 --- a/src/transport/batch/BatchManager.ts +++ b/src/transport/batch/BatchManager.ts @@ -24,7 +24,8 @@ export class BatchManager { private consumer: BatchConsumer; private uploadFrequency: number; private timeoutId: ReturnType | null = null; - private isUploading = false; + /** Upload cycles run one after another: a `flush()` during a cycle waits for it, then runs its own. */ + private cycles: Promise = Promise.resolve(); private constructor(producer: BatchProducer, consumer: BatchConsumer, uploadFrequency: number) { this.producer = producer; @@ -54,6 +55,16 @@ export class BatchManager { this.producer.post(data); } + /** Writes what is posted but not written yet before returning. See {@link BatchProducer.writePendingSync}. */ + writePendingSync() { + this.producer.writePendingSync(); + } + + /** Drains the write queue and rotates the current batch, without uploading. */ + flushToDisk(): Promise { + return this.producer.flush(); + } + /** Drains the write queue, rotates the current batch, and uploads all pending files. */ async flush() { await this.triggerUploadCycle(); @@ -82,20 +93,15 @@ export class BatchManager { } /** Flushes the producer to rotate pending files, then uploads all ready batches. */ - private async triggerUploadCycle() { - if (this.isUploading) { - return; - } - - this.isUploading = true; - - try { + private triggerUploadCycle(): Promise { + const cycle = this.cycles.then(async () => { // Flush producer first to rotate any pending .tmp files to .log await this.producer.flush(); // Then upload all .log files await this.consumer.upload(); - } finally { - this.isUploading = false; - } + }); + // A failed cycle is its caller's to report; the next cycle runs regardless. + this.cycles = cycle.catch(() => undefined); + return cycle; } } diff --git a/src/transport/batch/BatchProducer.spec.ts b/src/transport/batch/BatchProducer.spec.ts index 5ff2d4a8..5c927aec 100644 --- a/src/transport/batch/BatchProducer.spec.ts +++ b/src/transport/batch/BatchProducer.spec.ts @@ -7,9 +7,19 @@ import { mockFs } from '../../mocks.specUtil'; vi.mock('node:fs/promises'); const fsMocks = mockFs(); +const { appendFileSync, existsSync, mkdirSync, renameSync } = vi.hoisted(() => ({ + appendFileSync: vi.fn(), + existsSync: vi.fn<(candidate: string) => boolean>(() => false), + mkdirSync: vi.fn(), + renameSync: vi.fn(), +})); +vi.mock('node:fs', () => ({ appendFileSync, existsSync, mkdirSync, renameSync })); + vi.mock('@flashcatcloud/browser-core', () => ({ dateNow: vi.fn(() => 1234567890), })); +const { addError } = vi.hoisted(() => ({ addError: vi.fn() })); +vi.mock('../../domain/telemetry', () => ({ addError })); function makeConfig(overrides: Partial = {}): ProducerConfig { return { @@ -24,9 +34,15 @@ describe('BatchProducer', () => { beforeEach(() => { fsMocks.reset(); + appendFileSync.mockReset(); + existsSync.mockReset().mockReturnValue(false); + mkdirSync.mockReset(); + renameSync.mockReset(); config = makeConfig(); fsMocks.access.mockResolvedValue(undefined); + // No `.log` exists unless a test says so. + fsMocks.stat.mockRejectedValue(new Error('ENOENT')); fsMocks.mkdir.mockResolvedValue(undefined); fsMocks.readdir.mockResolvedValue([]); fsMocks.appendFile.mockResolvedValue(undefined); @@ -54,6 +70,19 @@ describe('BatchProducer', () => { expect(fsMocks.mkdir).not.toHaveBeenCalled(); }); + it('never rotates an orphan onto a .log that exists', async () => { + fsMocks.readdir.mockResolvedValueOnce(['batch-111.tmp']); + // `batch-111.log` exists — an append in flight recreated the `.tmp` after a rotation. + fsMocks.stat.mockResolvedValueOnce({}).mockRejectedValueOnce(new Error('ENOENT')); + + await BatchProducer.create(config); + + expect(fsMocks.rename).toHaveBeenCalledWith( + path.join(config.trackPath, 'batch-111.tmp'), + path.join(config.trackPath, 'batch-111-1.log') + ); + }); + it('rotates orphaned .tmp files from previous sessions to .log', async () => { fsMocks.readdir.mockResolvedValueOnce(['batch-111.tmp', 'batch-222.tmp']); @@ -127,16 +156,245 @@ describe('BatchProducer', () => { expect(fsMocks.appendFile.mock.calls[2][1]).toBe(`{"order":3}\n`); }); - it('swallows appendFile errors and keeps queue processing subsequent posts', async () => { - fsMocks.appendFile.mockRejectedValueOnce(new Error('write failed')).mockResolvedValueOnce(undefined); + it('keeps draining after an unexpected throw, reporting it', async () => { + const producer = await BatchProducer.create(config); + const { dateNow } = await import('@flashcatcloud/browser-core'); + vi.mocked(dateNow).mockImplementationOnce(() => { + throw new Error('clock broken'); + }); + + producer.post({ a: 1 }); + await producer.flush().catch(() => undefined); + producer.post({ b: 2 }); + await producer.flush(); + + expect(fsMocks.appendFile.mock.calls.map(([, content]) => String(content))).toContain(`{"b":2}\n`); + expect(addError).toHaveBeenCalledWith(expect.any(Error)); + }); + + it('drops an item it cannot serialize and keeps writing the ones after it', async () => { + const producer = await BatchProducer.create(config); + + producer.post({ context: { id: 1n } }); + producer.post({ good: true }); + await producer.flush(); + + expect(fsMocks.appendFile).toHaveBeenCalledTimes(1); + expect(fsMocks.appendFile.mock.calls[0][1]).toBe(`{"good":true}\n`); + }); + + it('keeps writing after a failed append, and the next flush reports the failure once', async () => { + fsMocks.appendFile.mockRejectedValueOnce(new Error('write failed')).mockResolvedValue(undefined); const producer = await BatchProducer.create(config); producer.post({ bad: true }); producer.post({ good: true }); - await expect(producer.flush()).resolves.not.toThrow(); + // The queue went on: the good event was written. The flush says what was lost, so a caller + // that must know its events are on disk — crash reporting — does; the batch is rotated all + // the same, so what was written still uploads. + await expect(producer.flush()).rejects.toThrow('write failed'); expect(fsMocks.appendFile).toHaveBeenCalledTimes(2); + expect(fsMocks.rename).toHaveBeenCalledTimes(1); + producer.post({ later: true }); + await expect(producer.flush()).resolves.toBeUndefined(); + }); + }); + + describe('writePendingSync()', () => { + it('writes what is posted but not written yet before returning, and the queue does not write it again', async () => { + const producer = await BatchProducer.create(config); + producer.post({ a: 1 }); + producer.post({ b: 2 }); + + producer.writePendingSync(); + + const tmp = path.join(config.trackPath, 'batch-1234567890.tmp'); + expect(appendFileSync.mock.calls).toEqual([ + [tmp, `{"a":1}\n`, 'utf8'], + [tmp, `{"b":2}\n`, 'utf8'], + ]); + await producer.flush(); + expect(fsMocks.appendFile).not.toHaveBeenCalled(); + }); + + it('still writes an item the queue has taken up but not appended yet, and the queue then skips it', async () => { + const producer = await BatchProducer.create(config); + let finishDirectoryCheck!: () => void; + fsMocks.access.mockImplementationOnce(() => new Promise((resolve) => (finishDirectoryCheck = resolve))); + producer.post({ checking: true }); + await vi.waitFor(() => expect(fsMocks.access).toHaveBeenCalled()); + + // The queue is waiting on the directory check: the item is not on disk, and an exit now + // would lose it unless the synchronous write takes it. + producer.writePendingSync(); + + expect(appendFileSync).toHaveBeenCalledTimes(1); + expect(appendFileSync.mock.calls[0][1]).toBe(`{"checking":true}\n`); + finishDirectoryCheck(); + await producer.flush(); + expect(fsMocks.appendFile).not.toHaveBeenCalled(); + }); + + it('writes to a new batch while an append is in flight, which then rotates the batch it was writing', async () => { + const producer = await BatchProducer.create(config); + const { dateNow } = await import('@flashcatcloud/browser-core'); + vi.mocked(dateNow).mockReturnValueOnce(1000).mockReturnValueOnce(2000); + let finishAppend!: () => void; + fsMocks.appendFile.mockImplementationOnce(() => new Promise((resolve) => (finishAppend = resolve))); + producer.post({ large: 'x'.repeat(100) }); + await vi.waitFor(() => expect(fsMocks.appendFile).toHaveBeenCalledTimes(1)); + producer.post({ fatal: true }); + + // A large event is appended in chunks: a line written to the same file between two of them + // would corrupt both, so the exit flush starts a new batch instead. + producer.writePendingSync(); + + expect(appendFileSync).toHaveBeenCalledWith( + path.join(config.trackPath, 'batch-2000.tmp'), + `{"fatal":true}\n`, + 'utf8' + ); + expect(renameSync).not.toHaveBeenCalled(); + finishAppend(); + await producer.flush(); + // The append rotated its own batch once done; the flush rotated the current one. + const renamed = fsMocks.rename.mock.calls.map(([from]) => path.basename(String(from))); + expect(renamed).toEqual(['batch-1000.tmp', 'batch-2000.tmp']); + }); + + it('keeps the batch the exit flush started when an earlier rotation completes after it', async () => { + const producer = await BatchProducer.create(makeConfig({ batchSize: 20 })); + const { dateNow } = await import('@flashcatcloud/browser-core'); + vi.mocked(dateNow).mockReturnValueOnce(1000).mockReturnValueOnce(2000); + producer.post({ a: 'x'.repeat(10) }); + await producer.flush(); + vi.mocked(dateNow).mockReturnValueOnce(3000); + producer.post({ b: 'y'.repeat(10) }); + await vi.waitFor(() => expect(fsMocks.appendFile).toHaveBeenCalledTimes(2)); + let finishRename!: () => void; + fsMocks.rename.mockImplementationOnce(() => new Promise((resolve) => (finishRename = resolve))); + // The next event does not fit: the queue starts rotating batch 3000… + producer.post({ c: 'z'.repeat(10) }); + await vi.waitFor(() => expect(fsMocks.rename).toHaveBeenCalledTimes(2)); + // …and an exit flush rotates it itself and writes into the next batch meanwhile. + producer.writePendingSync(); + expect(appendFileSync).toHaveBeenCalledWith( + path.join(config.trackPath, 'batch-3000.tmp'), + `{"c":"zzzzzzzzzz"}\n`, + 'utf8' + ); + + finishRename(); + await producer.flush(); + + // That batch stayed the current one, so the flush rotated it rather than forgetting it. + expect(fsMocks.rename).toHaveBeenCalledWith( + path.join(config.trackPath, 'batch-3000.tmp'), + path.join(config.trackPath, 'batch-3000.log') + ); + }); + + it('writes to a new batch while a flush is rotating the current one, and that batch is rotated later', async () => { + const producer = await BatchProducer.create(config); + const { dateNow } = await import('@flashcatcloud/browser-core'); + vi.mocked(dateNow).mockReturnValueOnce(1000).mockReturnValueOnce(2000); + producer.post({ a: 1 }); + await vi.waitFor(() => expect(fsMocks.appendFile).toHaveBeenCalledTimes(1)); + let finishRename!: () => void; + fsMocks.rename.mockImplementationOnce(() => new Promise((resolve) => (finishRename = resolve))); + const flushed = producer.flush(); + await vi.waitFor(() => expect(fsMocks.rename).toHaveBeenCalledTimes(1)); + + // The batch being rotated is no longer the current one, so the exit flush opens a new batch + // rather than recreating the file the rename is taking away. + producer.post({ b: 2 }); + producer.writePendingSync(); + + expect(appendFileSync).toHaveBeenCalledWith(path.join(config.trackPath, 'batch-2000.tmp'), `{"b":2}\n`, 'utf8'); + finishRename(); + await flushed; + await producer.flush(); + expect(fsMocks.rename).toHaveBeenCalledWith( + path.join(config.trackPath, 'batch-2000.tmp'), + path.join(config.trackPath, 'batch-2000.log') + ); + }); + + it('creates the track directory once for a whole synchronous write, not per item', async () => { + const producer = await BatchProducer.create(config); + producer.post({ a: 1 }); + producer.post({ b: 2 }); + producer.post({ c: 3 }); + + producer.writePendingSync(); + + expect(mkdirSync).toHaveBeenCalledTimes(1); + }); + + it('leaves a write the queue already started to complete on its own', async () => { + const producer = await BatchProducer.create(config); + let finishWrite!: () => void; + fsMocks.appendFile.mockImplementationOnce(() => new Promise((resolve) => (finishWrite = resolve))); + producer.post({ started: true }); + await vi.waitFor(() => expect(fsMocks.appendFile).toHaveBeenCalledTimes(1)); + producer.post({ pending: true }); + + producer.writePendingSync(); + + expect(appendFileSync).toHaveBeenCalledTimes(1); + expect(appendFileSync.mock.calls[0][1]).toBe(`{"pending":true}\n`); + finishWrite(); + await producer.flush(); + expect(fsMocks.appendFile).toHaveBeenCalledTimes(1); + }); + + it('rotates in place when the batch size is exceeded, never onto the name of an earlier batch', async () => { + const producer = await BatchProducer.create(makeConfig({ batchSize: 20 })); + producer.post({ a: 'x'.repeat(10) }); + producer.post({ b: 'y'.repeat(10) }); + producer.post({ c: 'z'.repeat(10) }); + + producer.writePendingSync(); + + // Three batches within the same millisecond: each named after a later one than the last. + expect(renameSync.mock.calls).toEqual([ + [path.join(config.trackPath, 'batch-1234567890.tmp'), path.join(config.trackPath, 'batch-1234567890.log')], + [path.join(config.trackPath, 'batch-1234567891.tmp'), path.join(config.trackPath, 'batch-1234567891.log')], + ]); + expect(appendFileSync.mock.calls.map(([file]) => String(file))).toEqual([ + path.join(config.trackPath, 'batch-1234567890.tmp'), + path.join(config.trackPath, 'batch-1234567891.tmp'), + path.join(config.trackPath, 'batch-1234567892.tmp'), + ]); + }); + + it('never rotates onto a .log that exists, as one left by an earlier launch may share the name', async () => { + const producer = await BatchProducer.create(makeConfig({ batchSize: 20 })); + producer.post({ a: 'x'.repeat(10) }); + producer.post({ b: 'y'.repeat(10) }); + existsSync.mockImplementation((candidate) => candidate.endsWith('batch-1234567890.log')); + + producer.writePendingSync(); + + expect(renameSync).toHaveBeenCalledWith( + path.join(config.trackPath, 'batch-1234567890.tmp'), + path.join(config.trackPath, 'batch-1234567890-1.log') + ); + }); + + it('drops a write that fails, like the queue does', async () => { + const producer = await BatchProducer.create(config); + appendFileSync.mockImplementationOnce(() => { + throw new Error('EACCES'); + }); + producer.post({ a: 1 }); + producer.post({ b: 2 }); + + expect(() => producer.writePendingSync()).not.toThrow(); + + expect(appendFileSync).toHaveBeenCalledTimes(2); }); }); diff --git a/src/transport/batch/BatchProducer.ts b/src/transport/batch/BatchProducer.ts index 973d72aa..0726fca7 100644 --- a/src/transport/batch/BatchProducer.ts +++ b/src/transport/batch/BatchProducer.ts @@ -1,6 +1,8 @@ import { dateNow } from '@flashcatcloud/browser-core'; +import { appendFileSync, existsSync, mkdirSync, renameSync } from 'node:fs'; import fs from 'node:fs/promises'; import path from 'node:path'; +import { addError } from '../../domain/telemetry'; export interface ProducerConfig { trackPath: string; @@ -17,7 +19,20 @@ export class BatchProducer { private batchSize: number; private currentBatchFile: string | null = null; private currentBatchSize = 0; - private writeQueue: Promise = Promise.resolve(); + /** Posted, not written yet: the queue takes from the front, in order. */ + private pending: unknown[] = []; + private draining: Promise = Promise.resolve(); + /** The timestamp of the last batch file named, so that the next is named after a later one. */ + private lastBatchTimestamp = 0; + /** The first append that failed since the last flush, which reports it: a caller that must know its events are on disk does. */ + private writeFailure: Error | undefined; + /** + * The batch file an asynchronous append is writing to, if one is: `writePendingSync` must not + * write to it meanwhile — a large event is appended in several chunks, and a line written between + * two of them would corrupt both — so it moves on to a new batch and leaves that one to the + * append, which rotates it once done. + */ + private inFlightFile: string | null = null; private constructor(config: ProducerConfig) { this.trackPath = config.trackPath; @@ -33,19 +48,101 @@ export class BatchProducer { return producer; } - /** Enqueues data to be appended to the current batch file. Writes are serialized. */ + /** Enqueues data to be appended to the current batch file. Writes are serialized, in call order. */ post(data: unknown) { - this.writeQueue = this.writeQueue - .then(() => this.writeData(data)) - .catch(() => { - // Silently ignore write errors to ensure the queue continues processing - }); + this.pending.push(data); + // Reported and settled: a throw the drain did not expect must not leave the chain rejected, + // with every later post queued behind it for good. + this.draining = this.draining.then(() => this.drain()).catch((error) => addError(error)); } - /** Waits for pending writes to complete and rotates the current batch file. */ + /** + * Writes everything posted but not written yet before returning, for a process that may be about + * to exit: the queue only writes on later turns of the event loop, and there may be none. + * + * An append the queue has already issued is not completed here: it lands after these if the + * process lives long enough, and an exit before that loses it, or leaves a partial line the + * consumer skips. Every line written here is whole. A write that fails is dropped, as the queue + * drops it. + */ + writePendingSync() { + if (this.pending.length > 0) { + mkdirSync(this.trackPath, { recursive: true }); + } + while (this.pending.length > 0) { + const data = this.pending.shift(); + try { + this.writeDataSync(data); + } catch { + // Same contract as the queue: a write that fails is dropped. + } + } + } + + /** + * Waits for pending writes to complete and rotates the current batch file. Rejects if an append + * failed since the last flush — after rotating, so that what was written still uploads. + */ async flush() { - await this.writeQueue; + await this.draining; await this.rotateBatch(); + const failure = this.writeFailure; + this.writeFailure = undefined; + if (failure !== undefined) { + throw failure; + } + } + + /** + * An item leaves `pending` only once its append is issued: until then `writePendingSync` can + * still take it, and the asynchronous steps before the append (the directory check, a rotation) + * are where an exit would otherwise lose it. + */ + private async drain() { + while (this.pending.length > 0) { + const data = this.pending[0]; + let serialized: string; + try { + serialized = `${JSON.stringify(data)}\n`; + } catch { + // Not serializable (a BigInt in a context, say): dropped, like a write that fails. + this.pending.shift(); + continue; + } + const dataSize = Buffer.byteLength(serialized, 'utf8'); + try { + await this.ensureTrackDirectoryExists(); + if (this.currentBatchSize + dataSize > this.batchSize && this.currentBatchSize > 0) { + await this.rotateBatch(); + } + } catch { + // The append below reports its own failure. + } + if (this.pending[0] !== data) { + // Written synchronously in the meantime. + continue; + } + this.pending.shift(); + const filePath = this.getCurrentBatchPath(); + const file = this.currentBatchFile!; + this.inFlightFile = file; + try { + await fs.appendFile(filePath, serialized, 'utf8'); + if (this.currentBatchFile === file) { + this.currentBatchSize += dataSize; + } + } catch (error) { + // The queue goes on; the next flush reports it. + this.writeFailure ??= error instanceof Error ? error : new Error(String(error)); + } finally { + this.inFlightFile = null; + } + if (this.currentBatchFile !== file) { + // The batch moved on while this append was in flight: nothing else writes to this file, and + // only a rotation makes it uploadable. + await this.renameBatchFile(file); + } + } } /** Creates the track directory if it does not already exist. */ @@ -71,9 +168,14 @@ export class BatchProducer { } } - /** Generates a timestamp-based `.tmp` file name for a new batch. */ + /** + * Generates a timestamp-based `.tmp` file name for a new batch. Strictly increasing: two batches + * rotated within the same millisecond — a burst written before an exit, say — would otherwise + * share a name, and the second `.log` would replace the first. + */ private generateBatchFileName() { - return `batch-${dateNow()}.tmp`; + this.lastBatchTimestamp = Math.max(dateNow(), this.lastBatchTimestamp + 1); + return `batch-${this.lastBatchTimestamp}.tmp`; } /** Returns the full path to the current batch file, creating a new name if needed. */ @@ -86,40 +188,86 @@ export class BatchProducer { /** Renames the current `.tmp` batch file to `.log` and resets the batch state. */ private async rotateBatch() { + const file = this.currentBatchFile; + if (!file) { + return; + } + // Detached before the rename is awaited: a write meanwhile opens a new batch, rather than + // recreating the file the rename is taking away. + this.currentBatchFile = null; + this.currentBatchSize = 0; + await this.renameBatchFile(file); + } + + /** `drain`'s write of one item, for `writePendingSync`. */ + private writeDataSync(data: unknown) { + const serialized = `${JSON.stringify(data)}\n`; + const dataSize = Buffer.byteLength(serialized, 'utf8'); + if (this.inFlightFile !== null && this.inFlightFile === this.currentBatchFile) { + // See `inFlightFile`: the append rotates that file once it is done with it. + this.currentBatchFile = null; + this.currentBatchSize = 0; + } else if (this.currentBatchSize + dataSize > this.batchSize && this.currentBatchSize > 0) { + this.rotateBatchSync(); + } + appendFileSync(this.getCurrentBatchPath(), serialized, 'utf8'); + this.currentBatchSize += dataSize; + } + + /** `rotateBatch` for `writePendingSync`: the rename is attempted in place, and the state is reset either way. */ + private rotateBatchSync() { if (!this.currentBatchFile) { return; } - await this.renameBatchFile(this.currentBatchFile); + const tmpPath = path.join(this.trackPath, this.currentBatchFile); + try { + renameSync(tmpPath, freeLogPathSync(tmpPath.replace(/\.tmp$/, '.log'))); + } catch { + // File doesn't exist or rename failed - silently ignore + } this.currentBatchFile = null; this.currentBatchSize = 0; } - /** Renames a `.tmp` batch file to `.log` so the consumer can pick it up. */ + /** + * Renames a `.tmp` batch file to `.log` so the consumer can pick it up — never onto a `.log` + * that exists: a `.tmp` can share its name with one when an append still in flight recreated it + * after a synchronous rotation, and `rename` would replace the earlier batch with it. + */ private async renameBatchFile(file: string) { const tmpPath = path.join(this.trackPath, file); const logPath = tmpPath.replace(/\.tmp$/, '.log'); try { await fs.access(tmpPath); - await fs.rename(tmpPath, logPath); + await fs.rename(tmpPath, await this.freeLogPath(logPath)); } catch { // File doesn't exist or rename failed - silently ignore } } - /** Serializes data as a JSON line and appends it to the current batch file, rotating first if the size limit would be exceeded. */ - private async writeData(data: unknown) { - await this.ensureTrackDirectoryExists(); - - const serialized = `${JSON.stringify(data)}\n`; - const dataSize = Buffer.byteLength(serialized, 'utf8'); - - if (this.currentBatchSize + dataSize > this.batchSize && this.currentBatchSize > 0) { - await this.rotateBatch(); + private async freeLogPath(logPath: string): Promise { + for (let attempt = 0; ; attempt += 1) { + const candidate = logCandidate(logPath, attempt); + try { + await fs.stat(candidate); + } catch { + return candidate; + } } + } +} - const batchPath = this.getCurrentBatchPath(); - await fs.appendFile(batchPath, serialized, 'utf8'); - this.currentBatchSize += dataSize; +/** `freeLogPath` for the synchronous rotation: a `.log` left by an earlier launch may share the name. */ +function freeLogPathSync(logPath: string): string { + for (let attempt = 0; ; attempt += 1) { + const candidate = logCandidate(logPath, attempt); + if (!existsSync(candidate)) { + return candidate; + } } } + +function logCandidate(logPath: string, attempt: number): string { + return attempt === 0 ? logPath : logPath.replace(/\.log$/, `-${attempt}.log`); +}