Skip to content

Commit 605a2c8

Browse files
steipetesteipete
committed
fix: carry gateway restart trace across respawn (#82396) (thanks @samzong)
1 parent 661362c commit 605a2c8

8 files changed

Lines changed: 296 additions & 51 deletions

File tree

‎src/cli/gateway-cli/run-loop.test.ts‎

Lines changed: 46 additions & 27 deletions
Original file line numberDiff line numberDiff line change
@@ -51,10 +51,14 @@ const waitForActiveTasks = vi.fn(async (_timeoutMs?: number) => ({ drained: true
5151
const resetAllLanes = vi.fn();
5252
const reloadTaskRegistryFromStore = vi.fn();
5353
const restartGatewayProcessWithFreshPid = vi.fn<
54-
() => { mode: "spawned" | "supervised" | "disabled" | "failed"; pid?: number; detail?: string }
54+
(_opts?: { env?: NodeJS.ProcessEnv }) => {
55+
mode: "spawned" | "supervised" | "disabled" | "failed";
56+
pid?: number;
57+
detail?: string;
58+
}
5559
>(() => ({ mode: "disabled" }));
5660
const respawnGatewayProcessForUpdate = vi.fn<
57-
() => {
61+
(_opts?: { env?: NodeJS.ProcessEnv }) => {
5862
mode: "spawned" | "supervised" | "disabled" | "failed";
5963
pid?: number;
6064
detail?: string;
@@ -110,8 +114,10 @@ vi.mock("../../infra/restart.js", () => ({
110114
}));
111115

112116
vi.mock("../../infra/process-respawn.js", () => ({
113-
respawnGatewayProcessForUpdate: () => respawnGatewayProcessForUpdate(),
114-
restartGatewayProcessWithFreshPid: () => restartGatewayProcessWithFreshPid(),
117+
respawnGatewayProcessForUpdate: (opts?: { env?: NodeJS.ProcessEnv }) =>
118+
respawnGatewayProcessForUpdate(opts),
119+
restartGatewayProcessWithFreshPid: (opts?: { env?: NodeJS.ProcessEnv }) =>
120+
restartGatewayProcessWithFreshPid(opts),
115121
}));
116122

117123
vi.mock("../../infra/restart-sentinel.js", () => ({
@@ -664,34 +670,47 @@ describe("runGatewayLoop", () => {
664670
it("releases the lock before exiting on spawned restart", async () => {
665671
vi.clearAllMocks();
666672
peekGatewaySigusr1RestartReason.mockReturnValue(undefined);
673+
const originalTraceEnv = process.env.OPENCLAW_GATEWAY_RESTART_TRACE;
674+
process.env.OPENCLAW_GATEWAY_RESTART_TRACE = "1";
667675

668-
await withIsolatedSignals(async ({ captureSignal }) => {
669-
const lockRelease = vi.fn(async () => {});
670-
acquireGatewayLock.mockResolvedValueOnce({
671-
release: lockRelease,
672-
});
676+
try {
677+
await withIsolatedSignals(async ({ captureSignal }) => {
678+
const lockRelease = vi.fn(async () => {});
679+
acquireGatewayLock.mockResolvedValueOnce({
680+
release: lockRelease,
681+
});
673682

674-
// Override process-respawn to return "spawned" mode
675-
restartGatewayProcessWithFreshPid.mockReturnValueOnce({
676-
mode: "spawned",
677-
pid: 9999,
678-
});
683+
// Override process-respawn to return "spawned" mode
684+
restartGatewayProcessWithFreshPid.mockReturnValueOnce({
685+
mode: "spawned",
686+
pid: 9999,
687+
});
679688

680-
const exitCallOrder: string[] = [];
681-
const { runtime, exited } = await createSignaledLoopHarness(exitCallOrder);
682-
const sigusr1 = captureSignal("SIGUSR1");
683-
lockRelease.mockImplementation(async () => {
684-
exitCallOrder.push("lockRelease");
685-
});
689+
const exitCallOrder: string[] = [];
690+
const { runtime, exited } = await createSignaledLoopHarness(exitCallOrder);
691+
const sigusr1 = captureSignal("SIGUSR1");
692+
lockRelease.mockImplementation(async () => {
693+
exitCallOrder.push("lockRelease");
694+
});
686695

687-
sigusr1();
696+
sigusr1();
688697

689-
await exited;
690-
expect(lockRelease).toHaveBeenCalledTimes(1);
691-
expect(runtime.exit).toHaveBeenCalledWith(0);
692-
expect(exitCallOrder).toEqual(["lockRelease", "exit"]);
693-
expect(writeGatewayRestartHandoffSync).not.toHaveBeenCalled();
694-
});
698+
await exited;
699+
expect(lockRelease).toHaveBeenCalledTimes(1);
700+
expect(runtime.exit).toHaveBeenCalledWith(0);
701+
expect(exitCallOrder).toEqual(["lockRelease", "exit"]);
702+
const [respawnOpts] = restartGatewayProcessWithFreshPid.mock.calls[0] ?? [];
703+
expect(respawnOpts?.env?.OPENCLAW_GATEWAY_RESTART_TRACE_STARTED_AT_MS).toMatch(/^\d/u);
704+
expect(respawnOpts?.env?.OPENCLAW_GATEWAY_RESTART_TRACE_LAST_AT_MS).toMatch(/^\d/u);
705+
expect(writeGatewayRestartHandoffSync).not.toHaveBeenCalled();
706+
});
707+
} finally {
708+
if (originalTraceEnv === undefined) {
709+
delete process.env.OPENCLAW_GATEWAY_RESTART_TRACE;
710+
} else {
711+
process.env.OPENCLAW_GATEWAY_RESTART_TRACE = originalTraceEnv;
712+
}
713+
}
695714
});
696715

697716
it("waits briefly before exiting on launchd supervised restart", async () => {

‎src/cli/gateway-cli/run-loop.ts‎

Lines changed: 23 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,8 @@
11
import { randomUUID } from "node:crypto";
22
import net from "node:net";
33
import {
4+
captureGatewayRestartTraceHandoff,
5+
createGatewayRestartTraceHandoffEnv,
46
measureGatewayRestartTrace,
57
markGatewayRestartTrace,
68
startGatewayRestartTrace,
@@ -152,7 +154,10 @@ export async function runGatewayLoop(params: {
152154
} = await loadGatewayLifecycleRuntimeModule();
153155

154156
if (isUpdateRestart) {
155-
const respawn = respawnGatewayProcessForUpdate();
157+
const restartTraceHandoff = captureGatewayRestartTraceHandoff();
158+
const respawn = respawnGatewayProcessForUpdate({
159+
env: createGatewayRestartTraceHandoffEnv(restartTraceHandoff),
160+
});
156161
if (respawn.mode === "spawned") {
157162
const port = params.lockPort;
158163
const healthy =
@@ -186,17 +191,18 @@ export async function runGatewayLoop(params: {
186191
}
187192
if (respawn.mode === "supervised") {
188193
const supervisorMode = detectRespawnSupervisor(process.env, process.platform);
194+
markGatewayRestartTrace("restart.full-process-handoff", [
195+
["kind", "update-process"],
196+
["mode", respawn.mode],
197+
["supervisorMode", supervisorMode ?? "external"],
198+
]);
189199
writeGatewayRestartHandoffSync({
190200
restartKind: "update-process",
191201
reason: restartReason,
192202
processInstanceId,
193203
supervisorMode: supervisorMode ?? "external",
204+
restartTrace: captureGatewayRestartTraceHandoff(),
194205
});
195-
markGatewayRestartTrace("restart.full-process-handoff", [
196-
["kind", "update-process"],
197-
["mode", respawn.mode],
198-
["supervisorMode", supervisorMode ?? "external"],
199-
]);
200206
gatewayLog.info("restart mode: update process respawn (supervisor restart)");
201207
if (supervisorMode === "launchd") {
202208
await new Promise((resolve) => {
@@ -227,7 +233,10 @@ export async function runGatewayLoop(params: {
227233
}
228234

229235
// Release the lock BEFORE spawning so the child can acquire it immediately.
230-
const respawn = restartGatewayProcessWithFreshPid();
236+
const restartTraceHandoff = captureGatewayRestartTraceHandoff();
237+
const respawn = restartGatewayProcessWithFreshPid({
238+
env: createGatewayRestartTraceHandoffEnv(restartTraceHandoff),
239+
});
231240
if (respawn.mode === "spawned" || respawn.mode === "supervised") {
232241
const supervisorMode =
233242
respawn.mode === "supervised"
@@ -237,20 +246,21 @@ export async function runGatewayLoop(params: {
237246
respawn.mode === "spawned"
238247
? `spawned pid ${respawn.pid ?? "unknown"}`
239248
: "supervisor restart";
249+
markGatewayRestartTrace("restart.full-process-handoff", [
250+
["kind", "full-process"],
251+
["mode", respawn.mode],
252+
["pid", respawn.mode === "spawned" ? (respawn.pid ?? "unknown") : "none"],
253+
["supervisorMode", supervisorMode ?? "none"],
254+
]);
240255
if (respawn.mode === "supervised") {
241256
writeGatewayRestartHandoffSync({
242257
restartKind: "full-process",
243258
reason: restartReason,
244259
processInstanceId,
245260
supervisorMode: supervisorMode ?? "external",
261+
restartTrace: captureGatewayRestartTraceHandoff(),
246262
});
247263
}
248-
markGatewayRestartTrace("restart.full-process-handoff", [
249-
["kind", "full-process"],
250-
["mode", respawn.mode],
251-
["pid", respawn.mode === "spawned" ? (respawn.pid ?? "unknown") : "none"],
252-
["supervisorMode", supervisorMode ?? "none"],
253-
]);
254264
gatewayLog.info(`restart mode: full process restart (${modeLabel})`);
255265
if (supervisorMode === "launchd") {
256266
// A short clean-exit pause keeps rapid SIGUSR1/config restarts from

‎src/gateway/restart-trace.test.ts‎

Lines changed: 19 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,19 @@
1+
import { describe, expect, it } from "vitest";
2+
import { createGatewayRestartTraceHandoffEnv } from "./restart-trace.js";
3+
4+
describe("gateway restart trace handoff", () => {
5+
it("keeps timing for slow but valid drains", () => {
6+
const startedAt = Date.now() - 305_000;
7+
const lastAt = startedAt + 300_000;
8+
9+
expect(
10+
createGatewayRestartTraceHandoffEnv({
11+
startedAt,
12+
lastAt,
13+
}),
14+
).toStrictEqual({
15+
OPENCLAW_GATEWAY_RESTART_TRACE_STARTED_AT_MS: String(startedAt),
16+
OPENCLAW_GATEWAY_RESTART_TRACE_LAST_AT_MS: String(lastAt),
17+
});
18+
});
19+
});

‎src/gateway/restart-trace.ts‎

Lines changed: 97 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -3,16 +3,27 @@ import { isTruthyEnvValue } from "../infra/env.js";
33
import { createSubsystemLogger } from "../logging/subsystem.js";
44

55
const restartTraceLog = createSubsystemLogger("gateway");
6+
const RESTART_TRACE_HANDOFF_STARTED_AT_ENV = "OPENCLAW_GATEWAY_RESTART_TRACE_STARTED_AT_MS";
7+
const RESTART_TRACE_HANDOFF_LAST_AT_ENV = "OPENCLAW_GATEWAY_RESTART_TRACE_LAST_AT_MS";
8+
const RESTART_TRACE_HANDOFF_MAX_AGE_MS = 10 * 60_000;
69

710
type RestartTraceMetricValue = boolean | number | string | null | undefined;
811
type RestartTraceMetrics =
912
| Readonly<Record<string, RestartTraceMetricValue>>
1013
| ReadonlyArray<readonly [string, RestartTraceMetricValue]>;
14+
export type GatewayRestartTraceHandoff = {
15+
startedAt: number;
16+
lastAt: number;
17+
};
1118

1219
let startedAt = 0;
1320
let lastAt = 0;
1421
let active = false;
1522

23+
function nowMs(): number {
24+
return performance.timeOrigin + performance.now();
25+
}
26+
1627
function isRestartTraceEnabled(): boolean {
1728
return isTruthyEnvValue(process.env.OPENCLAW_GATEWAY_RESTART_TRACE);
1829
}
@@ -91,7 +102,7 @@ export function startGatewayRestartTrace(name: string, metrics?: RestartTraceMet
91102
active = false;
92103
return;
93104
}
94-
const now = performance.now();
105+
const now = nowMs();
95106
startedAt = now;
96107
lastAt = now;
97108
active = true;
@@ -106,7 +117,7 @@ export function markGatewayRestartTrace(name: string, metrics?: RestartTraceMetr
106117
if (!isGatewayRestartTraceActive()) {
107118
return;
108119
}
109-
const now = performance.now();
120+
const now = nowMs();
110121
emitRestartTrace(name, now - lastAt, now - startedAt, metrics);
111122
lastAt = now;
112123
}
@@ -124,11 +135,11 @@ export async function measureGatewayRestartTrace<T>(
124135
if (!isGatewayRestartTraceActive()) {
125136
return await run();
126137
}
127-
const before = performance.now();
138+
const before = nowMs();
128139
try {
129140
return await run();
130141
} finally {
131-
const now = performance.now();
142+
const now = nowMs();
132143
emitRestartTrace(
133144
name,
134145
now - before,
@@ -147,7 +158,7 @@ export function recordGatewayRestartTrace(
147158
if (!isGatewayRestartTraceActive() || !Number.isFinite(durationMs)) {
148159
return;
149160
}
150-
const now = performance.now();
161+
const now = nowMs();
151162
emitRestartTrace(name, Math.max(0, durationMs), now - startedAt, metrics);
152163
lastAt = now;
153164
}
@@ -183,6 +194,87 @@ export function collectGatewayProcessMemoryUsageMb(): ReadonlyArray<readonly [st
183194
];
184195
}
185196

197+
function normalizeRestartTraceHandoff(value: unknown): GatewayRestartTraceHandoff | null {
198+
if (typeof value !== "object" || value === null || Array.isArray(value)) {
199+
return null;
200+
}
201+
const record = value as { startedAt?: unknown; lastAt?: unknown };
202+
if (
203+
typeof record.startedAt !== "number" ||
204+
!Number.isFinite(record.startedAt) ||
205+
typeof record.lastAt !== "number" ||
206+
!Number.isFinite(record.lastAt) ||
207+
record.startedAt <= 0 ||
208+
record.lastAt < record.startedAt ||
209+
record.lastAt - record.startedAt > RESTART_TRACE_HANDOFF_MAX_AGE_MS
210+
) {
211+
return null;
212+
}
213+
const now = nowMs();
214+
if (record.startedAt > now || now - record.startedAt > RESTART_TRACE_HANDOFF_MAX_AGE_MS) {
215+
return null;
216+
}
217+
return {
218+
startedAt: record.startedAt,
219+
lastAt: record.lastAt,
220+
};
221+
}
222+
223+
export function captureGatewayRestartTraceHandoff(): GatewayRestartTraceHandoff | undefined {
224+
if (!isGatewayRestartTraceActive()) {
225+
return undefined;
226+
}
227+
return { startedAt, lastAt };
228+
}
229+
230+
export function createGatewayRestartTraceHandoffEnv(
231+
handoff: GatewayRestartTraceHandoff | undefined = captureGatewayRestartTraceHandoff(),
232+
): NodeJS.ProcessEnv | undefined {
233+
const normalized = normalizeRestartTraceHandoff(handoff);
234+
if (!normalized) {
235+
return undefined;
236+
}
237+
return {
238+
[RESTART_TRACE_HANDOFF_STARTED_AT_ENV]: String(normalized.startedAt),
239+
[RESTART_TRACE_HANDOFF_LAST_AT_ENV]: String(normalized.lastAt),
240+
};
241+
}
242+
243+
export function resumeGatewayRestartTraceFromHandoff(
244+
handoff: unknown,
245+
metrics?: RestartTraceMetrics,
246+
): boolean {
247+
if (!isRestartTraceEnabled() || active) {
248+
return false;
249+
}
250+
const normalized = normalizeRestartTraceHandoff(handoff);
251+
if (!normalized) {
252+
return false;
253+
}
254+
startedAt = normalized.startedAt;
255+
lastAt = normalized.lastAt;
256+
active = true;
257+
markGatewayRestartTrace("restart.process-resume", metrics);
258+
return true;
259+
}
260+
261+
export function resumeGatewayRestartTraceFromEnv(
262+
env: NodeJS.ProcessEnv = process.env,
263+
metrics?: RestartTraceMetrics,
264+
): boolean {
265+
const startedRaw = env[RESTART_TRACE_HANDOFF_STARTED_AT_ENV];
266+
const lastRaw = env[RESTART_TRACE_HANDOFF_LAST_AT_ENV];
267+
delete env[RESTART_TRACE_HANDOFF_STARTED_AT_ENV];
268+
delete env[RESTART_TRACE_HANDOFF_LAST_AT_ENV];
269+
return resumeGatewayRestartTraceFromHandoff(
270+
{
271+
startedAt: Number(startedRaw),
272+
lastAt: Number(lastRaw),
273+
},
274+
metrics,
275+
);
276+
}
277+
186278
export function resetGatewayRestartTraceForTest(): void {
187279
startedAt = 0;
188280
lastAt = 0;

‎src/gateway/server.impl.ts‎

Lines changed: 11 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -32,6 +32,7 @@ import {
3232
} from "../infra/diagnostics-timeline.js";
3333
import { isTruthyEnvValue, isVitestRuntimeEnv, logAcceptedEnvOption } from "../infra/env.js";
3434
import { ensureOpenClawCliOnPath } from "../infra/path-env.js";
35+
import { readGatewayRestartHandoffSync } from "../infra/restart-handoff.js";
3536
import { setGatewaySigusr1RestartPolicy, setPreRestartDeferralCheck } from "../infra/restart.js";
3637
import { enqueueSystemEvent } from "../infra/system-events.js";
3738
import type { VoiceWakeRoutingConfig } from "../infra/voicewake-routing.js";
@@ -78,6 +79,8 @@ import {
7879
finishGatewayRestartTrace,
7980
recordGatewayRestartTraceDetail,
8081
recordGatewayRestartTraceSpan,
82+
resumeGatewayRestartTraceFromEnv,
83+
resumeGatewayRestartTraceFromHandoff,
8184
} from "./restart-trace.js";
8285
import { resolveGatewayControlUiRootState } from "./server-control-ui-root.js";
8386
import { createLazyGatewayCronState } from "./server-cron-lazy.js";
@@ -539,6 +542,14 @@ export async function startGatewayServer(
539542
key: "OPENCLAW_RAW_STREAM_PATH",
540543
description: "raw stream log path override",
541544
});
545+
if (!resumeGatewayRestartTraceFromEnv(process.env, [["source", "env"]])) {
546+
const restartHandoff = readGatewayRestartHandoffSync();
547+
resumeGatewayRestartTraceFromHandoff(restartHandoff?.restartTrace, [
548+
["source", restartHandoff?.source],
549+
["restartKind", restartHandoff?.restartKind],
550+
["supervisorMode", restartHandoff?.supervisorMode],
551+
]);
552+
}
542553
const startupTrace = createGatewayStartupTrace();
543554
const startupConfigModulePromise = import("./server-startup-config.js");
544555
const reloadHandlersModulePromise = import("./server-reload-handlers.js");

0 commit comments

Comments
 (0)