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.
This commit is contained in:
Mohamed Boudra
2026-06-29 23:31:11 +08:00
committed by GitHub
parent b613bea9f6
commit e63a971968
27 changed files with 567 additions and 86 deletions
@@ -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<DesktopDaemonStatus> {
return parseDesktopDaemonStatus(await invokeDesktopCommand("start_desktop_daemon"));
}
export async function stopDesktopDaemon(): Promise<DesktopDaemonStatus> {
return parseDesktopDaemonStatus(await invokeDesktopCommand("stop_desktop_daemon"));
export async function stopDesktopDaemon(
reason: DesktopDaemonStopReason = "manual_ipc",
): Promise<DesktopDaemonStatus> {
return parseDesktopDaemonStatus(await invokeDesktopCommand("stop_desktop_daemon", { reason }));
}
export async function restartDesktopDaemon(): Promise<DesktopDaemonStatus> {
@@ -60,7 +60,7 @@ export function useBuiltInDaemonManagement(
}),
persistSettings: (next) => updateSettings(next) as Promise<void>,
startDaemon: startDesktopDaemon,
stopDaemon: stopDesktopDaemon,
stopDaemon: () => stopDesktopDaemon("settings"),
});
if (result.kind === "enabled") {
const upsertResult = await upsertDesktopDaemonConnection(
@@ -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);
@@ -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<string, unknown>;
@@ -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),
};
}
+4
View File
@@ -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,
@@ -84,6 +84,11 @@ async function readDaemonStatus(paseoHome: string): Promise<DaemonStatus> {
}
}
async function readCapturedSupervisorLogs(paseoHome: string, recentLogs: string): Promise<string> {
const durableLogs = await readFile(join(paseoHome, "daemon.log"), "utf8").catch(() => "");
return `${recentLogs}\n${durableLogs}`;
}
async function waitFor(
check: () => Promise<boolean> | 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 {
@@ -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 {
@@ -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}`,
@@ -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",
+99 -19
View File
@@ -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<string>(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<string, unknown> | 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<void> {
await runExternalCliJsonCommand([
"daemon",
"stop",
"--json",
"--timeout",
"5",
"--force",
"--kill-timeout",
"5",
]);
function summarizeDesktopDaemonStatus(status: DesktopDaemonStatus): Record<string, unknown> {
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<void> {
await runDesktopDaemonStopViaCli({ reason });
}
function isProcessRunning(pid: number): boolean {
@@ -317,7 +385,7 @@ async function startDaemon(): Promise<DesktopDaemonStatus> {
appVersion: normalizeVersion(resolveDesktopAppVersion()),
daemonVersion: normalizeVersion(current.version),
});
await stopDesktopDaemon();
await stopDesktopDaemon("version_mismatch");
} else {
return current;
}
@@ -405,17 +473,29 @@ async function startDaemon(): Promise<DesktopDaemonStatus> {
return pollForRunningDaemon();
}
export async function stopDesktopDaemon(): Promise<DesktopDaemonStatus> {
export async function stopDesktopDaemon(
reason: DesktopDaemonStopReason = DEFAULT_DESKTOP_DAEMON_STOP_REASON,
): Promise<DesktopDaemonStatus> {
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<DesktopDaemonStatus> {
assertBuiltInDaemonManagementEnabled(await getDesktopSettingsStore().get());
await stopDesktopDaemon();
await stopDesktopDaemon("restart");
return startDaemon();
}
@@ -491,7 +571,7 @@ export function createDaemonCommandHandlers(): Record<string, DesktopCommandHand
}),
desktop_daemon_status: () => 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<string, DesktopCommandHand
return downloadAndInstallUpdate(
{ currentVersion, releaseChannel: await resolveRequestedReleaseChannel(args) },
async () => {
await stopDesktopDaemon();
await stopDesktopDaemon("app_update");
},
);
},
+1 -1
View File
@@ -755,7 +755,7 @@ app.on(
stopDesktopManagedDaemonOnQuitIfNeeded({
settingsStore: getDesktopSettingsStore(),
isDesktopManagedDaemonRunning: isDesktopManagedDaemonRunningSync,
stopDaemon: stopDesktopDaemonViaCli,
stopDaemon: () => stopDesktopDaemonViaCli("quit"),
showShutdownFeedback: showDaemonShutdownDialog,
}),
onStopError: (error) => {
@@ -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",
+28 -11
View File
@@ -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"));
+2 -1
View File
@@ -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 {
+24 -7
View File
@@ -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,
@@ -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;
}
@@ -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(),
};
}
@@ -234,6 +234,7 @@ describe("relay-transport control lifecycle", () => {
{
transport: "relay",
externalSessionKey: "session:clt_test",
relayConnectionId: "clt_test",
},
]);
});
@@ -387,6 +387,7 @@ export function startRelayTransport({
const externalMetadata: ExternalSocketMetadata = {
transport: "relay",
externalSessionKey: `session:${connectionId}`,
relayConnectionId: connectionId,
};
if (daemonKeyPair) {
void attachEncryptedSocket(
+16 -4
View File
@@ -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<void> {
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<void> {
const lifecycleReason = normalizeClientRestartRpcReason(reason);
const payload: { status: string } & Record<string, unknown> = {
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<void> {
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,
});
}
@@ -18,7 +18,7 @@ interface DaemonSelfUpdateRestartIntent {
type: "restart";
clientId: string;
requestId: string;
reason?: string;
reason: string;
}
export interface DaemonSelfUpdateSessionControllerOptions {
@@ -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",
);
@@ -29,7 +29,7 @@ export interface DaemonSessionHost {
type: "restart";
clientId: string;
requestId: string;
reason?: string;
reason: string;
}): void;
}
@@ -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",
@@ -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<typeof createLogger>;
}) {
const speechReadiness = options?.speechReadiness ?? null;
const daemonConfigStore = {
onChange: vi.fn(() => () => {}),
};
const logger = options?.logger ?? createLogger();
return new VoiceAssistantWebSocketServer(
createStub<HTTPServer>({}),
createStub<pino.Logger>(createLogger()),
createStub<pino.Logger>(logger),
"srv_test",
createStub<AgentManager>({
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();
+135 -28
View File
@@ -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<typeof setTimeout> | 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<WebSocketLike, PendingConnection> = new Map();
private readonly sessions: Map<WebSocketLike, SessionConnection> = new Map();
private readonly socketIdentities: Map<WebSocketLike, WebSocketConnectionIdentity> = new Map();
private readonly externalSessionsByKey: Map<string, SessionConnection> = 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<void> {
const requestMetadata = extractSocketRequestMetadata(request);
const connectionLoggerFields: Record<string, string> = {
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<void> {
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<WSInboundMessage, { type: "session" }>,
): Promise<void> {
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<string, string> {
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<WSInboundMessage, { type: "session" }>["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 {
@@ -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;
}