From e63a97196850556958fa1682de49e3d81aa73a75 Mon Sep 17 00:00:00 2001 From: Mohamed Boudra Date: Mon, 29 Jun 2026 17:31:11 +0200 Subject: [PATCH] Make daemon shutdowns easier to diagnose (#1790) * fix(daemon): log stop reasons and client identity Record websocket client identity, process memory/uptime, and shutdown reasons across CLI, desktop, supervisor, and worker paths so daemon drops can be traced from the triggering client to worker termination. * fix(daemon): keep shutdown diagnostics in sync Test drift: supervisor and relay tests still asserted the old log text and metadata shape after shutdown diagnostics started logging structured reasons and relay connection ids. Update those assertions to the new diagnostic contract. Also centralize client lifecycle reason normalization and derive desktop daemon stop reasons from one tuple so future changes cannot silently drift. --- .../app/src/desktop/daemon/desktop-daemon.ts | 14 +- .../hooks/use-built-in-daemon-management.ts | 2 +- .../app/src/screens/settings/host-page.tsx | 2 +- .../cli/src/commands/daemon/local-daemon.ts | 15 ++ packages/cli/src/commands/daemon/stop.ts | 4 + .../tests/22-daemon-stop-supervisor.test.ts | 20 ++- .../25-daemon-restart-supervisor.test.ts | 10 +- .../tests/33-daemon-stop-tree-kill.test.ts | 6 + .../desktop/src/daemon/daemon-manager.test.ts | 64 ++++++- packages/desktop/src/daemon/daemon-manager.ts | 118 +++++++++++-- packages/desktop/src/main.ts | 2 +- .../server/scripts/supervisor.logging.test.ts | 17 ++ packages/server/scripts/supervisor.ts | 39 +++-- packages/server/src/server/bootstrap.ts | 3 +- packages/server/src/server/daemon-worker.ts | 31 +++- .../server/src/server/lifecycle-reasons.ts | 6 + .../server/src/server/process-diagnostics.ts | 38 ++++ .../server/src/server/relay-transport.test.ts | 1 + packages/server/src/server/relay-transport.ts | 1 + packages/server/src/server/session.ts | 20 ++- .../daemon-self-update-session-controller.ts | 2 +- .../session/daemon/daemon-session.test.ts | 12 ++ .../server/session/daemon/daemon-session.ts | 2 +- .../src/server/session/daemon/diagnostics.ts | 10 ++ .../websocket-server.relay-reconnect.test.ts | 48 +++++- .../server/src/server/websocket-server.ts | 163 +++++++++++++++--- .../src/server/websocket/runtime-metrics.ts | 3 + 27 files changed, 567 insertions(+), 86 deletions(-) create mode 100644 packages/server/src/server/lifecycle-reasons.ts create mode 100644 packages/server/src/server/process-diagnostics.ts diff --git a/packages/app/src/desktop/daemon/desktop-daemon.ts b/packages/app/src/desktop/daemon/desktop-daemon.ts index cabd81388..3c8e0a7ae 100644 --- a/packages/app/src/desktop/daemon/desktop-daemon.ts +++ b/packages/app/src/desktop/daemon/desktop-daemon.ts @@ -2,6 +2,14 @@ import { getDesktopHost, isElectronRuntime } from "@/desktop/host"; import { invokeDesktopCommand } from "@/desktop/electron/invoke"; export type DesktopDaemonState = "starting" | "running" | "stopped" | "errored"; +export type DesktopDaemonStopReason = + | "manual_ipc" + | "settings" + | "host_remove" + | "quit" + | "app_update" + | "version_mismatch" + | "restart"; export interface DesktopDaemonStatus { serverId: string; @@ -122,8 +130,10 @@ export async function startDesktopDaemon(): Promise { return parseDesktopDaemonStatus(await invokeDesktopCommand("start_desktop_daemon")); } -export async function stopDesktopDaemon(): Promise { - return parseDesktopDaemonStatus(await invokeDesktopCommand("stop_desktop_daemon")); +export async function stopDesktopDaemon( + reason: DesktopDaemonStopReason = "manual_ipc", +): Promise { + return parseDesktopDaemonStatus(await invokeDesktopCommand("stop_desktop_daemon", { reason })); } export async function restartDesktopDaemon(): Promise { diff --git a/packages/app/src/desktop/hooks/use-built-in-daemon-management.ts b/packages/app/src/desktop/hooks/use-built-in-daemon-management.ts index 2f8f30360..cb2e2e392 100644 --- a/packages/app/src/desktop/hooks/use-built-in-daemon-management.ts +++ b/packages/app/src/desktop/hooks/use-built-in-daemon-management.ts @@ -60,7 +60,7 @@ export function useBuiltInDaemonManagement( }), persistSettings: (next) => updateSettings(next) as Promise, startDaemon: startDesktopDaemon, - stopDaemon: stopDesktopDaemon, + stopDaemon: () => stopDesktopDaemon("settings"), }); if (result.kind === "enabled") { const upsertResult = await upsertDesktopDaemonConnection( diff --git a/packages/app/src/screens/settings/host-page.tsx b/packages/app/src/screens/settings/host-page.tsx index 8f39fd0be..ddefea1e9 100644 --- a/packages/app/src/screens/settings/host-page.tsx +++ b/packages/app/src/screens/settings/host-page.tsx @@ -1244,7 +1244,7 @@ function RemoveHostSection({ await updateSettings({ daemon: { manageBuiltInDaemon: false } }); didDisableDaemonManagement = true; if (daemonStatus?.status === "running" && daemonStatus.desktopManaged) { - setStatus(await stopDesktopDaemon()); + setStatus(await stopDesktopDaemon("host_remove")); didStopDaemon = true; } await removeHost(host.serverId); diff --git a/packages/cli/src/commands/daemon/local-daemon.ts b/packages/cli/src/commands/daemon/local-daemon.ts index 7423c275c..06f124e13 100644 --- a/packages/cli/src/commands/daemon/local-daemon.ts +++ b/packages/cli/src/commands/daemon/local-daemon.ts @@ -59,6 +59,8 @@ export interface StopLocalDaemonResult { home: string; pid: number | null; forced: boolean; + usedLifecycleRpc: boolean; + reason: "not_running" | "lifecycle_shutdown_rpc" | "owner_pid_signal" | "owner_pid_sigkill"; message: string; } @@ -230,6 +232,15 @@ function resolveStopMessage( return fallbackMessage ?? "Daemon stopped via owner PID signal"; } +function resolveStopReason( + forced: boolean, + lifecycleRequested: boolean, +): StopLocalDaemonResult["reason"] { + if (forced) return "owner_pid_sigkill"; + if (lifecycleRequested) return "lifecycle_shutdown_rpc"; + return "owner_pid_signal"; +} + function readPidFile(pidPath: string): LocalDaemonPidInfo | null { try { const parsed = JSON.parse(readFileSync(pidPath, "utf-8")) as Record; @@ -421,6 +432,8 @@ function createNotRunningStopResult( home: state.home, pid, forced: false, + usedLifecycleRpc: false, + reason: "not_running", message, }; } @@ -741,6 +754,8 @@ export async function stopLocalDaemon( home: state.home, pid, forced, + usedLifecycleRpc: lifecycleRequested, + reason: resolveStopReason(forced, lifecycleRequested), message: resolveStopMessage(forced, lifecycleRequested, fallbackMessage), }; } diff --git a/packages/cli/src/commands/daemon/stop.ts b/packages/cli/src/commands/daemon/stop.ts index b893f6677..76351bb07 100644 --- a/packages/cli/src/commands/daemon/stop.ts +++ b/packages/cli/src/commands/daemon/stop.ts @@ -16,6 +16,8 @@ interface StopResult { home: string; pid: string; forced: boolean; + usedLifecycleRpc: boolean; + reason: "not_running" | "lifecycle_shutdown_rpc" | "owner_pid_signal" | "owner_pid_sigkill"; message: string; } @@ -75,6 +77,8 @@ export async function runStopCommand( home: result.home, pid: result.pid === null ? "-" : String(result.pid), forced: result.forced, + usedLifecycleRpc: result.usedLifecycleRpc, + reason: result.reason, message: result.message, }, schema: stopResultSchema, diff --git a/packages/cli/tests/22-daemon-stop-supervisor.test.ts b/packages/cli/tests/22-daemon-stop-supervisor.test.ts index 1dc2abb91..277e9fd4a 100644 --- a/packages/cli/tests/22-daemon-stop-supervisor.test.ts +++ b/packages/cli/tests/22-daemon-stop-supervisor.test.ts @@ -84,6 +84,11 @@ async function readDaemonStatus(paseoHome: string): Promise { } } +async function readCapturedSupervisorLogs(paseoHome: string, recentLogs: string): Promise { + const durableLogs = await readFile(join(paseoHome, "daemon.log"), "utf8").catch(() => ""); + return `${recentLogs}\n${durableLogs}`; +} + async function waitFor( check: () => Promise | boolean, timeoutMs: number, @@ -206,13 +211,20 @@ try { "stopped", "daemon should remain stopped after stop command", ); + const capturedSupervisorLogs = await readCapturedSupervisorLogs(paseoHome, recentSupervisorLogs); assert( - recentSupervisorLogs.includes("Shutdown requested by worker. Stopping worker..."), - `stop should request lifecycle shutdown from daemon worker, logs:\n${recentSupervisorLogs}`, + capturedSupervisorLogs.includes('"msg":"Worker requested shutdown"') && + capturedSupervisorLogs.includes('"reason":"client_shutdown_rpc"'), + `stop should log lifecycle shutdown reason from daemon worker, logs:\n${capturedSupervisorLogs}`, ); assert( - !recentSupervisorLogs.includes("cli_shutdown"), - `supervisor logs should not route shutdown by reason string:\n${recentSupervisorLogs}`, + capturedSupervisorLogs.includes('"msg":"Supervisor sending signal to worker"') && + capturedSupervisorLogs.includes('"signal":"SIGTERM"'), + `stop should log supervisor signal dispatch, logs:\n${capturedSupervisorLogs}`, + ); + assert( + !capturedSupervisorLogs.includes("cli_shutdown"), + `supervisor logs should not route shutdown by reason string:\n${capturedSupervisorLogs}`, ); console.log("✓ stop leaves supervised daemon stopped (no respawn)\n"); } finally { diff --git a/packages/cli/tests/25-daemon-restart-supervisor.test.ts b/packages/cli/tests/25-daemon-restart-supervisor.test.ts index 4feb337f5..10e559a2d 100644 --- a/packages/cli/tests/25-daemon-restart-supervisor.test.ts +++ b/packages/cli/tests/25-daemon-restart-supervisor.test.ts @@ -229,8 +229,14 @@ try { ); const capturedSupervisorLogs = await readCapturedSupervisorLogs(paseoHome, recentSupervisorLogs); assert( - capturedSupervisorLogs.includes("Restart requested by worker. Stopping worker for restart..."), - `restart should route through supervisor restart intent, logs:\n${capturedSupervisorLogs}`, + capturedSupervisorLogs.includes('"msg":"Worker requested restart"') && + capturedSupervisorLogs.includes('"reason":"settings_update"'), + `restart should log lifecycle restart reason from daemon worker, logs:\n${capturedSupervisorLogs}`, + ); + assert( + capturedSupervisorLogs.includes('"msg":"Supervisor sending signal to worker"') && + capturedSupervisorLogs.includes('"signal":"SIGTERM"'), + `restart should log supervisor signal dispatch, logs:\n${capturedSupervisorLogs}`, ); console.log("✓ app-style restart keeps daemon healthy and restarts worker\n"); } finally { diff --git a/packages/cli/tests/33-daemon-stop-tree-kill.test.ts b/packages/cli/tests/33-daemon-stop-tree-kill.test.ts index 8a60fbcb9..5ee8af7b6 100644 --- a/packages/cli/tests/33-daemon-stop-tree-kill.test.ts +++ b/packages/cli/tests/33-daemon-stop-tree-kill.test.ts @@ -144,17 +144,23 @@ try { const parsed = JSON.parse(stopResult.stdout) as { action?: unknown; forced?: unknown; + usedLifecycleRpc?: unknown; + reason?: unknown; message?: unknown; }; assert.deepStrictEqual( { action: parsed.action, forced: parsed.forced, + usedLifecycleRpc: parsed.usedLifecycleRpc, + reason: parsed.reason, message: parsed.message, }, { action: "stopped", forced: true, + usedLifecycleRpc: false, + reason: "owner_pid_sigkill", message: "Daemon owner process was force-stopped", }, `stop should report forced tree cleanup: ${stopResult.stdout}`, diff --git a/packages/desktop/src/daemon/daemon-manager.test.ts b/packages/desktop/src/daemon/daemon-manager.test.ts index 443e9f9fb..695fbf72a 100644 --- a/packages/desktop/src/daemon/daemon-manager.test.ts +++ b/packages/desktop/src/daemon/daemon-manager.test.ts @@ -17,6 +17,8 @@ const mocks = vi.hoisted(() => ({ runExternalCliJsonCommand: vi.fn(), runExternalCliTextCommand: vi.fn(), spawnProcess: vi.fn(), + logInfo: vi.fn(), + logError: vi.fn(), })); vi.mock("electron", () => ({ @@ -30,7 +32,7 @@ vi.mock("electron", () => ({ })); vi.mock("electron-log/main", () => ({ - default: { info: vi.fn(), error: vi.fn() }, + default: { info: mocks.logInfo, error: mocks.logError }, })); vi.mock("@getpaseo/server", () => ({ @@ -101,6 +103,8 @@ describe("daemon-manager commands", () => { mocks.runExternalCliJsonCommand.mockReset(); mocks.runExternalCliTextCommand.mockReset(); mocks.spawnProcess.mockReset(); + mocks.logInfo.mockReset(); + mocks.logError.mockReset(); rmSync(mocks.paseoHome, { recursive: true, force: true }); }); @@ -194,6 +198,31 @@ describe("daemon-manager commands", () => { "status", "--json", ]); + expect(mocks.logInfo).toHaveBeenCalledWith( + "[desktop daemon]", + "desktop daemon stop requested", + expect.objectContaining({ + reason: "manual_ipc", + statusBefore: expect.objectContaining({ + status: "running", + pid: 4242, + serverId: "server-1", + desktopManaged: true, + }), + }), + ); + expect(mocks.logInfo).toHaveBeenCalledWith( + "[desktop daemon]", + "desktop daemon stop completed", + expect.objectContaining({ + reason: "manual_ipc", + cliResult: { action: "stopped" }, + statusAfter: expect.objectContaining({ + status: "stopped", + serverId: null, + }), + }), + ); }); it("routes stale reachable desktop daemon stops through external CLI daemon stop", async () => { @@ -239,6 +268,39 @@ describe("daemon-manager commands", () => { ]); }); + it("records the renderer stop reason when stopping the desktop daemon", async () => { + mocks.runExternalCliJsonCommand + .mockResolvedValueOnce({ + localDaemon: "running", + serverId: "server-1", + pid: 4242, + listen: "127.0.0.1:6767", + desktopManaged: true, + }) + .mockResolvedValueOnce({ action: "stopped", reason: "lifecycle_shutdown_rpc" }) + .mockResolvedValueOnce({ + localDaemon: "stopped", + serverId: "", + }); + const handlers = createDaemonCommandHandlers(); + + await handlers.stop_desktop_daemon({ reason: "host_remove" }); + + expect(mocks.logInfo).toHaveBeenCalledWith( + "[desktop daemon]", + "desktop daemon stop requested", + expect.objectContaining({ reason: "host_remove" }), + ); + expect(mocks.logInfo).toHaveBeenCalledWith( + "[desktop daemon]", + "desktop daemon stop completed", + expect.objectContaining({ + reason: "host_remove", + cliResult: { action: "stopped", reason: "lifecycle_shutdown_rpc" }, + }), + ); + }); + it("uses a stale reachable desktop daemon when the version matches", async () => { mocks.runExternalCliJsonCommand.mockResolvedValue({ localDaemon: "stale_pid", diff --git a/packages/desktop/src/daemon/daemon-manager.ts b/packages/desktop/src/daemon/daemon-manager.ts index a80899076..10bae9a95 100644 --- a/packages/desktop/src/daemon/daemon-manager.ts +++ b/packages/desktop/src/daemon/daemon-manager.ts @@ -46,6 +46,19 @@ const STARTUP_POLL_MAX_ATTEMPTS = 150; const DETACHED_STARTUP_GRACE_MS = 1200; type DesktopDaemonState = "starting" | "running" | "stopped" | "errored"; +const DESKTOP_DAEMON_STOP_REASON_VALUES = [ + "manual_ipc", + "settings", + "host_remove", + "quit", + "app_update", + "version_mismatch", + "restart", +] as const; +export type DesktopDaemonStopReason = (typeof DESKTOP_DAEMON_STOP_REASON_VALUES)[number]; + +const DESKTOP_DAEMON_STOP_REASONS = new Set(DESKTOP_DAEMON_STOP_REASON_VALUES); +const DEFAULT_DESKTOP_DAEMON_STOP_REASON: DesktopDaemonStopReason = "manual_ipc"; export interface DesktopDaemonStatus { serverId: string; @@ -88,6 +101,16 @@ function parseAppUpdateCheckIntent( return args?.intent === "manual" ? "manual" : "automatic"; } +function parseDesktopDaemonStopReason( + args: Record | undefined, +): DesktopDaemonStopReason { + const reason = args?.reason; + if (typeof reason === "string" && DESKTOP_DAEMON_STOP_REASONS.has(reason)) { + return reason as DesktopDaemonStopReason; + } + return DEFAULT_DESKTOP_DAEMON_STOP_REASON; +} + // --------------------------------------------------------------------------- // Utilities // --------------------------------------------------------------------------- @@ -112,17 +135,62 @@ export function isDesktopManagedDaemonRunningSync(): boolean { } } -export async function stopDesktopDaemonViaCli(): Promise { - await runExternalCliJsonCommand([ - "daemon", - "stop", - "--json", - "--timeout", - "5", - "--force", - "--kill-timeout", - "5", - ]); +function summarizeDesktopDaemonStatus(status: DesktopDaemonStatus): Record { + return { + status: status.status, + pid: status.pid, + listen: status.listen, + serverId: status.serverId || null, + version: status.version, + desktopManaged: status.desktopManaged, + error: status.error, + }; +} + +const DESKTOP_DAEMON_STOP_CLI_ARGS = [ + "daemon", + "stop", + "--json", + "--timeout", + "5", + "--force", + "--kill-timeout", + "5", +]; + +async function runDesktopDaemonStopViaCli({ + reason, + statusBefore, + resolveStatusAfter = false, +}: { + reason: DesktopDaemonStopReason; + statusBefore?: DesktopDaemonStatus | null; + resolveStatusAfter?: boolean; +}): Promise<{ + cliResult: unknown; + statusAfter: DesktopDaemonStatus | null; +}> { + logDesktopDaemonLifecycle("desktop daemon stop requested", { + reason, + statusBefore: statusBefore ? summarizeDesktopDaemonStatus(statusBefore) : null, + }); + + const cliResult = await runExternalCliJsonCommand(DESKTOP_DAEMON_STOP_CLI_ARGS); + const statusAfter = resolveStatusAfter ? await resolveDesktopDaemonStatus() : null; + + logDesktopDaemonLifecycle("desktop daemon stop completed", { + reason, + cliResult, + statusAfter: statusAfter ? summarizeDesktopDaemonStatus(statusAfter) : null, + }); + + return { cliResult, statusAfter }; +} + +export async function stopDesktopDaemonViaCli( + reason: DesktopDaemonStopReason = DEFAULT_DESKTOP_DAEMON_STOP_REASON, +): Promise { + await runDesktopDaemonStopViaCli({ reason }); } function isProcessRunning(pid: number): boolean { @@ -317,7 +385,7 @@ async function startDaemon(): Promise { appVersion: normalizeVersion(resolveDesktopAppVersion()), daemonVersion: normalizeVersion(current.version), }); - await stopDesktopDaemon(); + await stopDesktopDaemon("version_mismatch"); } else { return current; } @@ -405,17 +473,29 @@ async function startDaemon(): Promise { return pollForRunningDaemon(); } -export async function stopDesktopDaemon(): Promise { +export async function stopDesktopDaemon( + reason: DesktopDaemonStopReason = DEFAULT_DESKTOP_DAEMON_STOP_REASON, +): Promise { const status = await resolveDesktopDaemonStatus(); - if (status.status !== "running") return status; + if (status.status !== "running") { + logDesktopDaemonLifecycle("desktop daemon stop skipped", { + reason, + statusBefore: summarizeDesktopDaemonStatus(status), + }); + return status; + } - await stopDesktopDaemonViaCli(); - return await resolveDesktopDaemonStatus(); + const { statusAfter } = await runDesktopDaemonStopViaCli({ + reason, + statusBefore: status, + resolveStatusAfter: true, + }); + return statusAfter ?? (await resolveDesktopDaemonStatus()); } async function restartDaemon(): Promise { assertBuiltInDaemonManagementEnabled(await getDesktopSettingsStore().get()); - await stopDesktopDaemon(); + await stopDesktopDaemon("restart"); return startDaemon(); } @@ -491,7 +571,7 @@ export function createDaemonCommandHandlers(): Record resolveDesktopDaemonStatus(), start_desktop_daemon: () => startDaemon(), - stop_desktop_daemon: () => stopDesktopDaemon(), + stop_desktop_daemon: (args) => stopDesktopDaemon(parseDesktopDaemonStopReason(args)), restart_desktop_daemon: () => restartDaemon(), desktop_daemon_logs: () => getDaemonLogs(), desktop_daemon_pairing: () => getDaemonPairing(), @@ -532,7 +612,7 @@ export function createDaemonCommandHandlers(): Record { - await stopDesktopDaemon(); + await stopDesktopDaemon("app_update"); }, ); }, diff --git a/packages/desktop/src/main.ts b/packages/desktop/src/main.ts index 4f4cdedbc..ac9ba73eb 100644 --- a/packages/desktop/src/main.ts +++ b/packages/desktop/src/main.ts @@ -755,7 +755,7 @@ app.on( stopDesktopManagedDaemonOnQuitIfNeeded({ settingsStore: getDesktopSettingsStore(), isDesktopManagedDaemonRunning: isDesktopManagedDaemonRunningSync, - stopDaemon: stopDesktopDaemonViaCli, + stopDaemon: () => stopDesktopDaemonViaCli("quit"), showShutdownFeedback: showDaemonShutdownDialog, }), onStopError: (error) => { diff --git a/packages/server/scripts/supervisor.logging.test.ts b/packages/server/scripts/supervisor.logging.test.ts index 3d42179fd..3d1d926f6 100644 --- a/packages/server/scripts/supervisor.logging.test.ts +++ b/packages/server/scripts/supervisor.logging.test.ts @@ -169,6 +169,23 @@ describe("supervisor durable logging", () => { expect(result.log).toContain("raw stderr line\n"); }); + test("logs the worker shutdown reason before signaling the worker", async () => { + const result = await runSupervisorFixture({ + workerSource: ` + process.send?.({ type: "paseo:shutdown", reason: "client_shutdown_rpc" }); + setInterval(() => {}, 1000); + `, + }); + + expect(result.code).toBe(0); + expect(result.signal).toBeNull(); + expect(result.log).toContain('"msg":"Worker requested shutdown"'); + expect(result.log).toContain('"reason":"client_shutdown_rpc"'); + expect(result.log).toContain('"msg":"Supervisor sending signal to worker"'); + expect(result.log).toContain('"signal":"SIGTERM"'); + expect(result.log).toContain('"workerPid":'); + }); + // POSIX-only: Windows reports the worker self-kill as an exit code, not SIGKILL. test.skipIf(isPlatform("win32"))( "logs worker signal exits even when the worker cannot log", diff --git a/packages/server/scripts/supervisor.ts b/packages/server/scripts/supervisor.ts index 1f8a78656..6e7c1b032 100644 --- a/packages/server/scripts/supervisor.ts +++ b/packages/server/scripts/supervisor.ts @@ -14,6 +14,7 @@ interface SupervisorLogFileOptions { type WorkerLifecycleMessage = | { type: "paseo:shutdown"; + reason?: string; } | { type: "paseo:ready"; @@ -56,7 +57,11 @@ function parseLifecycleMessage(msg: unknown): WorkerLifecycleMessage | null { } const type = (msg as { type?: unknown }).type; if (type === "paseo:shutdown") { - return { type: "paseo:shutdown" }; + const reason = (msg as { reason?: unknown }).reason; + return { + type: "paseo:shutdown", + ...(typeof reason === "string" && reason.trim().length > 0 ? { reason } : {}), + }; } if (type === "paseo:ready") { const listen = (msg as { listen?: unknown }).listen; @@ -236,16 +241,15 @@ export function runSupervisor(options: SupervisorOptions): void { } if (lifecycleMessage.type === "paseo:shutdown") { - writeLifecycleLog("Worker requested shutdown"); - requestShutdown("Shutdown requested by worker"); + const reason = lifecycleMessage.reason ?? "worker_requested_shutdown"; + writeLifecycleLog("Worker requested shutdown", { reason }); + requestShutdown(reason); return; } - writeLifecycleLog( - "Worker requested restart", - lifecycleMessage.reason ? { reason: lifecycleMessage.reason } : {}, - ); - requestRestart("Restart requested by worker"); + const reason = lifecycleMessage.reason ?? "worker_requested_restart"; + writeLifecycleLog("Worker requested restart", { reason }); + requestRestart(reason); }); child.on("close", (code, signal) => { @@ -279,6 +283,19 @@ export function runSupervisor(options: SupervisorOptions): void { }); }; + const signalWorker = (signal: NodeJS.Signals, reason: string): void => { + if (!child) { + return; + } + writeLifecycleLog("Supervisor sending signal to worker", { + reason, + signal, + supervisorPid: process.pid, + workerPid: child.pid ?? null, + }); + child.kill(signal); + }; + const requestRestart = (reason: string) => { if (!child || restarting || shuttingDown) { return; @@ -286,7 +303,7 @@ export function runSupervisor(options: SupervisorOptions): void { restarting = true; writeLifecycleLog("Restart requested", { reason }); log(`${reason}. Stopping worker for restart...`); - child.kill("SIGTERM"); + signalWorker("SIGTERM", reason); }; const requestShutdown = (reason: string) => { @@ -301,11 +318,11 @@ export function runSupervisor(options: SupervisorOptions): void { exitSupervisor(0); return; } - child.kill("SIGTERM"); + signalWorker("SIGTERM", reason); }; const forwardSignal = (signal: NodeJS.Signals) => { - requestShutdown(`Received ${signal}`); + requestShutdown(`supervisor_received_${signal}`); }; process.on("SIGINT", () => forwardSignal("SIGINT")); diff --git a/packages/server/src/server/bootstrap.ts b/packages/server/src/server/bootstrap.ts index 87690c564..f704c3992 100644 --- a/packages/server/src/server/bootstrap.ts +++ b/packages/server/src/server/bootstrap.ts @@ -311,12 +311,13 @@ export type DaemonLifecycleIntent = type: "shutdown"; clientId: string; requestId: string; + reason: string; } | { type: "restart"; clientId: string; requestId: string; - reason?: string; + reason: string; }; export interface PaseoDaemonConfig { diff --git a/packages/server/src/server/daemon-worker.ts b/packages/server/src/server/daemon-worker.ts index 188b9b35e..b0909f048 100644 --- a/packages/server/src/server/daemon-worker.ts +++ b/packages/server/src/server/daemon-worker.ts @@ -5,12 +5,14 @@ import { loadConfig } from "./config.js"; import { resolvePaseoHome } from "./paseo-home.js"; import { createRootLogger } from "./logger.js"; import type { DaemonLifecycleIntent } from "./bootstrap.js"; +import { getProcessDiagnostics } from "./process-diagnostics.js"; process.title = "Paseo Daemon"; type SupervisorLifecycleMessage = | { type: "paseo:shutdown"; + reason: string; } | { type: "paseo:ready"; @@ -123,15 +125,23 @@ async function main() { const beginShutdown = ( signal: string, options?: { + reason?: string; successExitCode?: number; }, ) => { + const reason = options?.reason ?? `worker_received_${signal}`; if (!shutdownPromise) { - logger.info(`${signal} received, shutting down gracefully...`); + logger.info( + { signal, reason, ...getProcessDiagnostics() }, + `${signal} received, shutting down gracefully...`, + ); shutdownPromise = (async () => { const forceExit = setTimeout(() => { - logger.warn("Forcing shutdown - HTTP server didn't close in time"); + logger.warn( + { signal, reason, ...getProcessDiagnostics() }, + "Forcing shutdown - HTTP server didn't close in time", + ); process.exit(1); }, 10000); @@ -152,7 +162,10 @@ async function main() { } })(); } else { - logger.info(`${signal} received while shutdown is already in progress`); + logger.info( + { signal, reason, ...getProcessDiagnostics() }, + `${signal} received while shutdown is already in progress`, + ); } installExitHook(); @@ -174,13 +187,13 @@ async function main() { const handleLifecycleIntent = (intent: DaemonLifecycleIntent) => { if (intent.type === "shutdown") { logger.warn( - { clientId: intent.clientId, requestId: intent.requestId }, + { clientId: intent.clientId, requestId: intent.requestId, reason: intent.reason }, "Shutdown requested via websocket", ); - if (sendSupervisorLifecycleMessage({ type: "paseo:shutdown" })) { + if (sendSupervisorLifecycleMessage({ type: "paseo:shutdown", reason: intent.reason })) { return; } - beginShutdown("shutdown lifecycle intent"); + beginShutdown("shutdown lifecycle intent", { reason: intent.reason }); return; } @@ -196,7 +209,10 @@ async function main() { ) { return; } - beginShutdown("restart lifecycle intent", { successExitCode: 0 }); + beginShutdown("restart lifecycle intent", { + reason: intent.reason, + successExitCode: 0, + }); }; const installSupervisorLivenessGuard = () => { @@ -215,6 +231,7 @@ async function main() { writeWorkerLifecycleLog(paseoHome, "Supervisor liveness lost; worker exiting", { reason, + ...getProcessDiagnostics(), supervisorPid, currentParentPid: process.ppid, ipcConnected: typeof process.connected === "boolean" ? process.connected : null, diff --git a/packages/server/src/server/lifecycle-reasons.ts b/packages/server/src/server/lifecycle-reasons.ts new file mode 100644 index 000000000..08c620db2 --- /dev/null +++ b/packages/server/src/server/lifecycle-reasons.ts @@ -0,0 +1,6 @@ +export const CLIENT_SHUTDOWN_RPC_REASON = "client_shutdown_rpc"; +export const DEFAULT_CLIENT_RESTART_RPC_REASON = "client_restart_rpc"; + +export function normalizeClientRestartRpcReason(reason: string | undefined): string { + return reason?.trim() || DEFAULT_CLIENT_RESTART_RPC_REASON; +} diff --git a/packages/server/src/server/process-diagnostics.ts b/packages/server/src/server/process-diagnostics.ts new file mode 100644 index 000000000..fbb78181c --- /dev/null +++ b/packages/server/src/server/process-diagnostics.ts @@ -0,0 +1,38 @@ +export interface ProcessMemoryDiagnostics { + rss: number; + heapTotal: number; + heapUsed: number; + external: number; + arrayBuffers: number; +} + +export interface ProcessDiagnostics { + pid: number; + ppid: number; + uptimeSeconds: number; + memory: ProcessMemoryDiagnostics; +} + +export function getProcessMemoryDiagnostics(): ProcessMemoryDiagnostics { + const memory = process.memoryUsage(); + return { + rss: memory.rss, + heapTotal: memory.heapTotal, + heapUsed: memory.heapUsed, + external: memory.external, + arrayBuffers: memory.arrayBuffers, + }; +} + +export function getProcessUptimeSeconds(): number { + return Math.round(process.uptime() * 1000) / 1000; +} + +export function getProcessDiagnostics(): ProcessDiagnostics { + return { + pid: process.pid, + ppid: process.ppid, + uptimeSeconds: getProcessUptimeSeconds(), + memory: getProcessMemoryDiagnostics(), + }; +} diff --git a/packages/server/src/server/relay-transport.test.ts b/packages/server/src/server/relay-transport.test.ts index c4e40f6c8..fb1ddfe4b 100644 --- a/packages/server/src/server/relay-transport.test.ts +++ b/packages/server/src/server/relay-transport.test.ts @@ -234,6 +234,7 @@ describe("relay-transport control lifecycle", () => { { transport: "relay", externalSessionKey: "session:clt_test", + relayConnectionId: "clt_test", }, ]); }); diff --git a/packages/server/src/server/relay-transport.ts b/packages/server/src/server/relay-transport.ts index fcd4fad79..4aeca54f3 100644 --- a/packages/server/src/server/relay-transport.ts +++ b/packages/server/src/server/relay-transport.ts @@ -387,6 +387,7 @@ export function startRelayTransport({ const externalMetadata: ExternalSocketMetadata = { transport: "relay", externalSessionKey: `session:${connectionId}`, + relayConnectionId: connectionId, }; if (daemonKeyPair) { void attachEncryptedSocket( diff --git a/packages/server/src/server/session.ts b/packages/server/src/server/session.ts index 91df7536a..7b7a0931d 100644 --- a/packages/server/src/server/session.ts +++ b/packages/server/src/server/session.ts @@ -61,6 +61,10 @@ import { getErrorMessage, getErrorMessageOr } from "@getpaseo/protocol/error-uti import { getAgentStatusPriority } from "@getpaseo/protocol/agent-state-bucket"; import { getParentAgentIdFromLabels } from "@getpaseo/protocol/agent-labels"; import type { WorkspaceGitRuntimeSnapshot, WorkspaceGitService } from "./workspace-git-service.js"; +import { + CLIENT_SHUTDOWN_RPC_REASON, + normalizeClientRestartRpcReason, +} from "./lifecycle-reasons.js"; import { AgentManager } from "./agent/agent-manager.js"; import { ProviderSnapshotManager } from "./agent/provider-snapshot-manager.js"; @@ -472,12 +476,13 @@ export type SessionLifecycleIntent = type: "shutdown"; clientId: string; requestId: string; + reason: string; } | { type: "restart"; clientId: string; requestId: string; - reason?: string; + reason: string; }; function parseClientCapabilities( @@ -1731,6 +1736,10 @@ export class Session { this.peakInflightRequests = this.inflightRequests; } + public getSessionId(): string { + return this.sessionId; + } + public async handleBinaryFrame(binaryFrame: BinaryFrame): Promise { if (binaryFrame.kind === "file_transfer") { await this.workspaceFilesSession.handleFileTransferFrame(binaryFrame.frame); @@ -1740,6 +1749,7 @@ export class Session { } private async handleRestartServerRequest(requestId: string, reason?: string): Promise { + const lifecycleReason = normalizeClientRestartRpcReason(reason); const payload: { status: string } & Record = { status: "restart_requested", clientId: this.clientId, @@ -1749,7 +1759,7 @@ export class Session { } payload.requestId = requestId; - this.sessionLogger.warn({ reason }, "Restart requested via websocket"); + this.sessionLogger.warn({ reason: lifecycleReason }, "Restart requested via websocket"); this.emit({ type: "status", payload, @@ -1759,12 +1769,13 @@ export class Session { type: "restart", clientId: this.clientId, requestId, - ...(reason ? { reason } : {}), + reason: lifecycleReason, }); } private async handleShutdownServerRequest(requestId: string): Promise { - this.sessionLogger.warn("Shutdown requested via websocket"); + const reason = CLIENT_SHUTDOWN_RPC_REASON; + this.sessionLogger.warn({ reason }, "Shutdown requested via websocket"); this.emit({ type: "status", payload: { @@ -1778,6 +1789,7 @@ export class Session { type: "shutdown", clientId: this.clientId, requestId, + reason, }); } diff --git a/packages/server/src/server/session/daemon/daemon-self-update-session-controller.ts b/packages/server/src/server/session/daemon/daemon-self-update-session-controller.ts index 9f7975e1c..0cfb6a43d 100644 --- a/packages/server/src/server/session/daemon/daemon-self-update-session-controller.ts +++ b/packages/server/src/server/session/daemon/daemon-self-update-session-controller.ts @@ -18,7 +18,7 @@ interface DaemonSelfUpdateRestartIntent { type: "restart"; clientId: string; requestId: string; - reason?: string; + reason: string; } export interface DaemonSelfUpdateSessionControllerOptions { diff --git a/packages/server/src/server/session/daemon/daemon-session.test.ts b/packages/server/src/server/session/daemon/daemon-session.test.ts index 22ca4c43d..9417a17ed 100644 --- a/packages/server/src/server/session/daemon/daemon-session.test.ts +++ b/packages/server/src/server/session/daemon/daemon-session.test.ts @@ -261,6 +261,14 @@ describe("DaemonSession", () => { getWebSocketRuntimeMetrics: () => ({ collectedAt: "2026-01-02T03:04:05.000Z", windowMs: 30_000, + uptimeSeconds: 12.345, + memory: { + rss: 1024 * 1024 * 64, + heapTotal: 1024 * 1024 * 32, + heapUsed: 1024 * 1024 * 12, + external: 1024 * 1024 * 3, + arrayBuffers: 1024 * 512, + }, final: false, sessions: { activeConnections: 2, @@ -349,6 +357,10 @@ describe("DaemonSession", () => { } expect(message.payload.diagnostic).toContain("WebSocket runtime metrics"); expect(message.payload.diagnostic).toContain("Collected at: 2026-01-02T03:04:05.000Z"); + expect(message.payload.diagnostic).toContain("Process uptime: 12s"); + expect(message.payload.diagnostic).toContain( + "Process memory: rss=64.0 MiB, heap=12.0 MiB / 32.0 MiB", + ); expect(message.payload.diagnostic).toContain( "Sessions: active=2, externalKeys=3, reconnectGrace=1", ); diff --git a/packages/server/src/server/session/daemon/daemon-session.ts b/packages/server/src/server/session/daemon/daemon-session.ts index 2669afdc0..bc9e89dec 100644 --- a/packages/server/src/server/session/daemon/daemon-session.ts +++ b/packages/server/src/server/session/daemon/daemon-session.ts @@ -29,7 +29,7 @@ export interface DaemonSessionHost { type: "restart"; clientId: string; requestId: string; - reason?: string; + reason: string; }): void; } diff --git a/packages/server/src/server/session/daemon/diagnostics.ts b/packages/server/src/server/session/daemon/diagnostics.ts index 468e1aac1..eccffcd23 100644 --- a/packages/server/src/server/session/daemon/diagnostics.ts +++ b/packages/server/src/server/session/daemon/diagnostics.ts @@ -248,6 +248,16 @@ function collectWebSocketRuntimeEntries(options: DaemonDiagnosticsOptions): Diag return [ { label: "Collected at", value: snapshot.collectedAt }, { label: "Window", value: formatDurationMs(snapshot.windowMs) }, + { label: "Process uptime", value: formatDurationMs(snapshot.uptimeSeconds * 1000) }, + { + label: "Process memory", + value: [ + `rss=${formatBytes(snapshot.memory.rss)}`, + `heap=${formatBytes(snapshot.memory.heapUsed)} / ${formatBytes(snapshot.memory.heapTotal)}`, + `external=${formatBytes(snapshot.memory.external)}`, + `arrayBuffers=${formatBytes(snapshot.memory.arrayBuffers)}`, + ].join(", "), + }, { label: "Final", value: String(snapshot.final) }, { label: "Sessions", diff --git a/packages/server/src/server/websocket-server.relay-reconnect.test.ts b/packages/server/src/server/websocket-server.relay-reconnect.test.ts index d4a456ada..22e7787bf 100644 --- a/packages/server/src/server/websocket-server.relay-reconnect.test.ts +++ b/packages/server/src/server/websocket-server.relay-reconnect.test.ts @@ -52,6 +52,7 @@ const sessionMock = vi.hoisted(() => { handleBinaryFrame = vi.fn((_frame: unknown) => {}); supports = vi.fn((capability: string) => this.args.clientCapabilities?.[capability] === true); getClientActivity = vi.fn(() => null); + getSessionId = vi.fn(() => "mock-session-id"); resetPeakInflight = vi.fn(() => {}); getRuntimeMetrics = vi.fn(() => ({ checkoutDiffTargetCount: 0, @@ -214,14 +215,18 @@ function createLogger() { return logger; } -function createServer(options?: { speechReadiness?: SpeechReadinessSnapshot | null }) { +function createServer(options?: { + speechReadiness?: SpeechReadinessSnapshot | null; + logger?: ReturnType; +}) { const speechReadiness = options?.speechReadiness ?? null; const daemonConfigStore = { onChange: vi.fn(() => () => {}), }; + const logger = options?.logger ?? createLogger(); return new VoiceAssistantWebSocketServer( createStub({}), - createStub(createLogger()), + createStub(logger), "srv_test", createStub({ subscribe: vi.fn(() => () => {}), @@ -596,6 +601,45 @@ describe("relay external socket reconnect behavior", () => { await server.close(); }); + test("logs control RPCs with the socket identity", async () => { + const logger = createLogger(); + const server = createServer({ logger }); + const socket = new MockSocket(); + + await server.attachExternalSocket(socket, { + transport: "relay", + relayConnectionId: "relay-conn-1", + }); + socket.emit("message", JSON.stringify(createHelloMessage("cid-control-log"))); + socket.emit( + "message", + JSON.stringify({ + type: "session", + message: { + type: "shutdown_server_request", + requestId: "shutdown-1", + }, + }), + ); + await Promise.resolve(); + + expect(logger.warn).toHaveBeenCalledWith( + expect.objectContaining({ + connectionId: expect.stringMatching(/^conn_/), + transport: "relay", + relayConnectionId: "relay-conn-1", + clientId: "cid-control-log", + sessionId: "mock-session-id", + requestType: "shutdown_server_request", + requestId: "shutdown-1", + reason: "client_shutdown_rpc", + }), + "ws_control_rpc_received", + ); + + await server.close(); + }); + test("responds to top-level ping while provider diagnostic is still running", async () => { const server = createServer(); const socket = new MockSocket(); diff --git a/packages/server/src/server/websocket-server.ts b/packages/server/src/server/websocket-server.ts index 91f64db92..d9ccaccae 100644 --- a/packages/server/src/server/websocket-server.ts +++ b/packages/server/src/server/websocket-server.ts @@ -2,6 +2,7 @@ import { WebSocket, WebSocketServer } from "ws"; import type { IncomingMessage, Server as HTTPServer } from "http"; import { basename, join } from "path"; import { hostname as getHostname } from "node:os"; +import { randomUUID } from "node:crypto"; import { monitorEventLoopDelay } from "node:perf_hooks"; import type { AgentManager, AgentMetricsSnapshot } from "./agent/agent-manager.js"; import type { AgentStorage } from "./agent/agent-storage.js"; @@ -63,17 +64,37 @@ import { type WebSocketRuntimeDiagnosticSnapshot, } from "./websocket/runtime-metrics.js"; import { ProviderUsageService } from "../services/quota-fetcher/service.js"; +import { getProcessMemoryDiagnostics, getProcessUptimeSeconds } from "./process-diagnostics.js"; +import { + CLIENT_SHUTDOWN_RPC_REASON, + normalizeClientRestartRpcReason, +} from "./lifecycle-reasons.js"; const WS_CLOSE_DAEMON_AUTH_FAILED = 4401; export interface ExternalSocketMetadata { transport: "relay"; externalSessionKey?: string; + relayConnectionId?: string; } interface PendingConnection { connectionLogger: pino.Logger; helloTimeout: ReturnType | null; + identity: WebSocketConnectionIdentity; +} + +interface WebSocketConnectionIdentity { + connectionId: string; + transport: "direct" | "relay"; + host?: string; + origin?: string; + userAgent?: string; + remoteAddress?: string; + relayConnectionId?: string; + clientId?: string; + sessionId?: string; + appVersion?: string; } interface WebSocketServerConfig { @@ -355,6 +376,7 @@ export class VoiceAssistantWebSocketServer { private readonly wss: WebSocketServer; private readonly pendingConnections: Map = new Map(); private readonly sessions: Map = new Map(); + private readonly socketIdentities: Map = new Map(); private readonly externalSessionsByKey: Map = new Map(); private readonly serverId: string; private readonly daemonVersion: string; @@ -818,6 +840,7 @@ export class VoiceAssistantWebSocketServer { this.workspaceGitService.dispose(); this.pendingConnections.clear(); this.sessions.clear(); + this.socketIdentities.clear(); this.externalSessionsByKey.clear(); this.wss.close(); } @@ -867,26 +890,14 @@ export class VoiceAssistantWebSocketServer { metadata?: ExternalSocketMetadata, ): Promise { const requestMetadata = extractSocketRequestMetadata(request); - const connectionLoggerFields: Record = { - transport: metadata?.transport === "relay" ? "relay" : "direct", - }; - if (requestMetadata.host) { - connectionLoggerFields.host = requestMetadata.host; - } - if (requestMetadata.origin) { - connectionLoggerFields.origin = requestMetadata.origin; - } - if (requestMetadata.userAgent) { - connectionLoggerFields.userAgent = requestMetadata.userAgent; - } - if (requestMetadata.remoteAddress) { - connectionLoggerFields.remoteAddress = requestMetadata.remoteAddress; - } - const connectionLogger = this.logger.child(connectionLoggerFields); + const identity = createWebSocketConnectionIdentity(requestMetadata, metadata); + this.socketIdentities.set(ws, identity); + const connectionLogger = this.logger.child(toConnectionLogFields(identity)); const pending: PendingConnection = { connectionLogger, helloTimeout: null, + identity, }; const timeout = setTimeout(() => { if (this.pendingConnections.get(ws) !== pending) { @@ -895,7 +906,7 @@ export class VoiceAssistantWebSocketServer { pending.helloTimeout = null; this.pendingConnections.delete(ws); pending.connectionLogger.warn( - { timeoutMs: HELLO_TIMEOUT_MS }, + { ...toConnectionLogFields(identity), timeoutMs: HELLO_TIMEOUT_MS }, "Closing connection due to missing hello", ); try { @@ -911,8 +922,9 @@ export class VoiceAssistantWebSocketServer { this.incrementRuntimeCounter("connectedAwaitingHello"); this.bindSocketHandlers(ws); - pending.connectionLogger.trace( + pending.connectionLogger.info( { + ...toConnectionLogFields(identity), totalPendingConnections: this.pendingConnections.size, }, "Client connected; awaiting hello", @@ -1089,6 +1101,10 @@ export class VoiceAssistantWebSocketServer { } this.clearPendingConnection(ws); + pending.identity.clientId = clientId; + if (message.appVersion) { + pending.identity.appVersion = message.appVersion; + } const existing = this.externalSessionsByKey.get(clientId); if (existing) { this.incrementRuntimeCounter("helloResumed"); @@ -1111,10 +1127,11 @@ export class VoiceAssistantWebSocketServer { } existing.sockets.add(ws); this.sessions.set(ws, existing); + pending.identity.sessionId = existing.session.getSessionId(); this.sendToClient(ws, this.createServerInfoMessage()); - existing.connectionLogger.trace( + pending.connectionLogger.info( { - clientId, + ...toConnectionLogFields(pending.identity), resumed: true, totalSessions: this.sessions.size, }, @@ -1134,10 +1151,11 @@ export class VoiceAssistantWebSocketServer { }); this.sessions.set(ws, connection); this.externalSessionsByKey.set(clientId, connection); + pending.identity.sessionId = connection.session.getSessionId(); this.sendToClient(ws, this.createServerInfoMessage()); - connection.connectionLogger.trace( + connection.connectionLogger.info( { - clientId, + ...toConnectionLogFields(pending.identity), resumed: false, totalSessions: this.sessions.size, }, @@ -1256,26 +1274,42 @@ export class VoiceAssistantWebSocketServer { error?: Error; }, ): Promise { + const identity = this.socketIdentities.get(ws); + const identityFields = identity ? toConnectionLogFields(identity) : {}; const pending = this.clearPendingConnection(ws); if (pending) { this.incrementRuntimeCounter("pendingDisconnected"); - pending.connectionLogger.trace( + pending.connectionLogger.info( { + ...identityFields, code: details.code, reason: stringifyCloseReason(details.reason), }, "Pending client disconnected", ); + this.socketIdentities.delete(ws); return; } const connection = this.sessions.get(ws); if (!connection) { + if (identity) { + this.logger.info( + { + ...identityFields, + code: details.code, + reason: stringifyCloseReason(details.reason), + }, + "Client socket closed without active session", + ); + this.socketIdentities.delete(ws); + } return; } this.sessions.delete(ws); connection.sockets.delete(ws); + this.socketIdentities.delete(ws); if (connection.sockets.size === 0) { this.incrementRuntimeCounter("sessionDisconnectedWaitingReconnect"); @@ -1291,9 +1325,9 @@ export class VoiceAssistantWebSocketServer { }, EXTERNAL_SESSION_DISCONNECT_GRACE_MS); connection.externalDisconnectCleanupTimeout = timeout; - connection.connectionLogger.trace( + connection.connectionLogger.info( { - clientId: connection.clientId, + ...identityFields, code: details.code, reason: stringifyCloseReason(details.reason), reconnectGraceMs: EXTERNAL_SESSION_DISCONNECT_GRACE_MS, @@ -1305,9 +1339,9 @@ export class VoiceAssistantWebSocketServer { if (connection.sockets.size > 0) { this.incrementRuntimeCounter("sessionSocketDisconnectedAttached"); - connection.connectionLogger.trace( + connection.connectionLogger.info( { - clientId: connection.clientId, + ...identityFields, remainingSockets: connection.sockets.size, code: details.code, reason: stringifyCloseReason(details.reason), @@ -1332,6 +1366,7 @@ export class VoiceAssistantWebSocketServer { for (const socket of connection.sockets) { this.sessions.delete(socket); + this.socketIdentities.delete(socket); } connection.sockets.clear(); const existing = this.externalSessionsByKey.get(connection.clientId); @@ -1562,7 +1597,7 @@ export class VoiceAssistantWebSocketServer { } if (message.type === "session") { - void this.dispatchSessionMessage(activeConnection, message).catch((error: unknown) => { + void this.dispatchSessionMessage(ws, activeConnection, message).catch((error: unknown) => { this.handleRawMessageError({ ws, data, error, log: activeConnection.connectionLogger }); }); } @@ -1572,10 +1607,22 @@ export class VoiceAssistantWebSocketServer { } private async dispatchSessionMessage( + ws: WebSocketLike, activeConnection: SessionConnection, message: Extract, ): Promise { this.recordInboundSessionRequestType(message.message.type); + const controlRpc = getControlRpcLogInfo(message.message); + if (controlRpc) { + const identity = this.socketIdentities.get(ws); + activeConnection.connectionLogger.warn( + { + ...(identity ? toConnectionLogFields(identity) : { clientId: activeConnection.clientId }), + ...controlRpc, + }, + "ws_control_rpc_received", + ); + } const startMs = performance.now(); await activeConnection.session.handleMessage(message.message); const durationMs = performance.now() - startMs; @@ -1750,6 +1797,8 @@ export class VoiceAssistantWebSocketServer { outboundBinaryFrameTypesTop: runtimeMetrics.outboundBinaryFrameTypesTop, bufferedAmount: runtimeMetrics.bufferedAmount, eventLoopDelay: this.snapshotEventLoopDelay(), + uptimeSeconds: getProcessUptimeSeconds(), + memory: getProcessMemoryDiagnostics(), runtime: sessionMetrics, latency: runtimeMetrics.latency, agents: agentSnapshot, @@ -1926,6 +1975,36 @@ interface SocketRequestMetadata { remoteAddress?: string; } +function createWebSocketConnectionIdentity( + requestMetadata: SocketRequestMetadata, + metadata: ExternalSocketMetadata | undefined, +): WebSocketConnectionIdentity { + return { + connectionId: `conn_${randomUUID().replaceAll("-", "")}`, + transport: metadata?.transport === "relay" ? "relay" : "direct", + ...(requestMetadata.host ? { host: requestMetadata.host } : {}), + ...(requestMetadata.origin ? { origin: requestMetadata.origin } : {}), + ...(requestMetadata.userAgent ? { userAgent: requestMetadata.userAgent } : {}), + ...(requestMetadata.remoteAddress ? { remoteAddress: requestMetadata.remoteAddress } : {}), + ...(metadata?.relayConnectionId ? { relayConnectionId: metadata.relayConnectionId } : {}), + }; +} + +function toConnectionLogFields(identity: WebSocketConnectionIdentity): Record { + return { + connectionId: identity.connectionId, + transport: identity.transport, + ...(identity.host ? { host: identity.host } : {}), + ...(identity.origin ? { origin: identity.origin } : {}), + ...(identity.userAgent ? { userAgent: identity.userAgent } : {}), + ...(identity.remoteAddress ? { remoteAddress: identity.remoteAddress } : {}), + ...(identity.relayConnectionId ? { relayConnectionId: identity.relayConnectionId } : {}), + ...(identity.clientId ? { clientId: identity.clientId } : {}), + ...(identity.sessionId ? { sessionId: identity.sessionId } : {}), + ...(identity.appVersion ? { appVersion: identity.appVersion } : {}), + }; +} + function extractSocketRequestMetadata(request: unknown): SocketRequestMetadata { if (!request || typeof request !== "object") { return {}; @@ -2091,6 +2170,34 @@ function stringifyCloseReason(reason: unknown): string | null { return text.length > 0 ? text : null; } +function getControlRpcLogInfo( + message: Extract["message"], +): { requestType: string; requestId: string; reason?: string } | null { + if (message.type === "shutdown_server_request") { + return { + requestType: message.type, + requestId: message.requestId, + reason: CLIENT_SHUTDOWN_RPC_REASON, + }; + } + if (message.type === "restart_server_request") { + const reason = normalizeClientRestartRpcReason(message.reason); + return { + requestType: message.type, + requestId: message.requestId, + reason, + }; + } + if (message.type === "daemon.update.request") { + return { + requestType: message.type, + requestId: message.requestId, + reason: "daemon_update", + }; + } + return null; +} + function extractRequestInfoFromUnknownWsInbound( payload: unknown, ): { requestId: string; requestType?: string } | null { diff --git a/packages/server/src/server/websocket/runtime-metrics.ts b/packages/server/src/server/websocket/runtime-metrics.ts index 214d7449a..fbb31210f 100644 --- a/packages/server/src/server/websocket/runtime-metrics.ts +++ b/packages/server/src/server/websocket/runtime-metrics.ts @@ -1,4 +1,5 @@ import type { SessionOutboundMessage, WSOutboundMessage } from "../messages.js"; +import type { ProcessMemoryDiagnostics } from "../process-diagnostics.js"; export interface WebSocketRuntimeCounters { connectedAwaitingHello: number; @@ -62,6 +63,8 @@ export interface WebSocketRuntimeDiagnosticSnapshot< p99Ms: number; maxMs: number; } | null; + uptimeSeconds: number; + memory: ProcessMemoryDiagnostics; runtime: TRuntime; agents: TAgents; }