Skip to content

Commit 5338a29

Browse files
committed
fix(cli): avoid blocking follow log streams
Signed-off-by: Yimo Jiang <yimoj@nvidia.com>
1 parent 7c41ab0 commit 5338a29

2 files changed

Lines changed: 171 additions & 21 deletions

File tree

src/nemoclaw.ts

Lines changed: 92 additions & 21 deletions
Original file line numberDiff line numberDiff line change
@@ -1908,12 +1908,13 @@ async function sandboxStatus(sandboxName: string) {
19081908
}
19091909

19101910
function sandboxLogs(sandboxName: string, follow: boolean) {
1911-
enableSandboxAuditLogs(sandboxName);
19121911
if (follow) {
19131912
streamSandboxFollowLogs(sandboxName);
1913+
enableSandboxAuditLogsInBackground(sandboxName);
19141914
return;
19151915
}
19161916

1917+
enableSandboxAuditLogs(sandboxName);
19171918
runOpenclawGatewayLogs(sandboxName, false);
19181919
const args = buildSandboxLogsArgs(sandboxName, false);
19191920
const result = runOpenshell(args, {
@@ -1980,6 +1981,8 @@ function streamSandboxFollowLogs(sandboxName: string): void {
19801981
let exiting = false;
19811982
let completedSources = 0;
19821983
let finalStatus = 0;
1984+
let requestedExitCode: number | null = null;
1985+
let forcedExitTimer: NodeJS.Timeout | null = null;
19831986

19841987
const stopChildren = (signal: NodeJS.Signals) => {
19851988
for (const { child } of sources) {
@@ -1988,6 +1991,16 @@ function streamSandboxFollowLogs(sandboxName: string): void {
19881991
}
19891992
}
19901993
};
1994+
const maybeExit = () => {
1995+
if (completedSources !== sources.length) {
1996+
return;
1997+
}
1998+
if (forcedExitTimer) {
1999+
clearTimeout(forcedExitTimer);
2000+
forcedExitTimer = null;
2001+
}
2002+
process.exit(requestedExitCode ?? finalStatus);
2003+
};
19912004
const exitFromSignal = (signal: NodeJS.Signals | null): number => {
19922005
if (!signal) return 1;
19932006
const signalNumber = os.constants.signals[signal];
@@ -1998,30 +2011,33 @@ function streamSandboxFollowLogs(sandboxName: string): void {
19982011
status: number,
19992012
detail: string | null = null,
20002013
) => {
2001-
if (source.done || exiting) return;
2014+
if (source.done) return;
20022015
source.done = true;
20032016
completedSources += 1;
20042017
if (status !== 0 && finalStatus === 0) {
20052018
finalStatus = status;
20062019
}
2007-
if (completedSources < sources.length) {
2020+
if (completedSources < sources.length && !exiting) {
20082021
const suffix = detail || `exit ${status}`;
20092022
console.error(` ${source.label} stopped (${suffix}); continuing with remaining log source.`);
20102023
}
2011-
if (completedSources === sources.length) {
2012-
process.exit(finalStatus);
2013-
}
2024+
maybeExit();
2025+
};
2026+
const requestExitAfterSignal = (signal: NodeJS.Signals, exitCode: number) => {
2027+
if (requestedExitCode !== null) return;
2028+
exiting = true;
2029+
requestedExitCode = exitCode;
2030+
stopChildren(signal);
2031+
forcedExitTimer = setTimeout(() => process.exit(exitCode), 2000);
2032+
forcedExitTimer.unref?.();
2033+
maybeExit();
20142034
};
20152035

20162036
process.once("SIGINT", () => {
2017-
exiting = true;
2018-
stopChildren("SIGINT");
2019-
process.exit(130);
2037+
requestExitAfterSignal("SIGINT", 130);
20202038
});
20212039
process.once("SIGTERM", () => {
2022-
exiting = true;
2023-
stopChildren("SIGTERM");
2024-
process.exit(143);
2040+
requestExitAfterSignal("SIGTERM", 143);
20252041
});
20262042

20272043
for (const source of sources) {
@@ -2035,23 +2051,78 @@ function streamSandboxFollowLogs(sandboxName: string): void {
20352051
}
20362052

20372053
function enableSandboxAuditLogs(sandboxName: string) {
2038-
const args = ["settings", "set", sandboxName, "--key", "ocsf_json_enabled", "--value", "true"];
2054+
const args = buildEnableSandboxAuditLogsArgs(sandboxName);
20392055
const result = runOpenshell(args, {
20402056
stdio: ["ignore", "ignore", "pipe"],
20412057
ignoreError: true,
20422058
timeout: getLogsProbeTimeoutMs(),
20432059
});
20442060
if (result.status !== 0) {
2045-
const stderr = String(result.stderr || "").trim();
2046-
console.error(
2047-
` Warning: failed to enable OpenShell audit logs for sandbox '${sandboxName}' ` +
2048-
`(${describeLogProbeResult(result)}): openshell ${args.join(" ")}`,
2049-
);
2050-
if (stderr) {
2051-
console.error(` ${stderr}`);
2061+
warnSandboxAuditLogsUnavailable(sandboxName, args, result);
2062+
}
2063+
}
2064+
2065+
function enableSandboxAuditLogsInBackground(sandboxName: string): void {
2066+
const args = buildEnableSandboxAuditLogsArgs(sandboxName);
2067+
const child = spawn(getOpenshellBinary(), args, {
2068+
cwd: ROOT,
2069+
env: process.env,
2070+
stdio: ["ignore", "ignore", "pipe"],
2071+
});
2072+
let stderr = "";
2073+
let timedOut = false;
2074+
let reported = false;
2075+
const timeout = setTimeout(() => {
2076+
timedOut = true;
2077+
child.kill("SIGTERM");
2078+
}, getLogsProbeTimeoutMs());
2079+
timeout.unref?.();
2080+
2081+
child.stderr?.on("data", (chunk: Buffer | string) => {
2082+
stderr += chunk.toString();
2083+
});
2084+
child.on("error", (error: Error) => {
2085+
clearTimeout(timeout);
2086+
reported = true;
2087+
warnSandboxAuditLogsUnavailable(sandboxName, args, {
2088+
status: null,
2089+
stderr,
2090+
error,
2091+
});
2092+
});
2093+
child.on("close", (code: number | null, signal: NodeJS.Signals | null) => {
2094+
clearTimeout(timeout);
2095+
if (reported || code === 0) {
2096+
return;
20522097
}
2053-
console.error(" Policy denial events may be missing from OpenShell logs.");
2098+
reported = true;
2099+
warnSandboxAuditLogsUnavailable(sandboxName, args, {
2100+
status: code,
2101+
stderr,
2102+
signal,
2103+
error: timedOut ? new Error(`openshell ${args.join(" ")} timed out`) : undefined,
2104+
});
2105+
});
2106+
}
2107+
2108+
function warnSandboxAuditLogsUnavailable(
2109+
sandboxName: string,
2110+
args: string[],
2111+
result: SpawnLikeResult,
2112+
): void {
2113+
const stderr = String(result.stderr || "").trim();
2114+
console.error(
2115+
` Warning: failed to enable OpenShell audit logs for sandbox '${sandboxName}' ` +
2116+
`(${describeLogProbeResult(result)}): openshell ${args.join(" ")}`,
2117+
);
2118+
if (stderr) {
2119+
console.error(` ${stderr}`);
20542120
}
2121+
console.error(" Policy denial events may be missing from OpenShell logs.");
2122+
}
2123+
2124+
function buildEnableSandboxAuditLogsArgs(sandboxName: string): string[] {
2125+
return ["settings", "set", sandboxName, "--key", "ocsf_json_enabled", "--value", "true"];
20552126
}
20562127

20572128
function buildSandboxOpenclawGatewayLogsArgs(sandboxName: string, follow: boolean): string[] {

test/cli.test.ts

Lines changed: 79 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -538,6 +538,23 @@ describe("CLI dispatch", () => {
538538
expect(r.out).toContain(FAKE_OPENSHELL_LOG_LINE);
539539
});
540540

541+
it("starts logs --follow streams before audit enable completes", () => {
542+
const setup = createLogsTestSetup("nemoclaw-cli-logs-follow-audit-slow-", [
543+
'if [ "$1" = "settings" ]; then',
544+
" sleep 2",
545+
" exit 0",
546+
"fi",
547+
]);
548+
549+
const start = Date.now();
550+
const r = setup.runLogs("alpha logs --follow", { NEMOCLAW_LOGS_PROBE_TIMEOUT_MS: "500" });
551+
552+
expect(Date.now() - start).toBeLessThan(1500);
553+
expect(r.code).toBe(0);
554+
expect(r.out).toContain(FAKE_OPENCLAW_LOG_LINE);
555+
expect(r.out).toContain(FAKE_OPENSHELL_LOG_LINE);
556+
});
557+
541558
it("keeps logs --follow running when one log source exits", { timeout: 15000 }, async () => {
542559
const home = fs.mkdtempSync(path.join(os.tmpdir(), "nemoclaw-cli-logs-follow-source-exit-"));
543560
const localBin = path.join(home, "bin");
@@ -622,6 +639,68 @@ describe("CLI dispatch", () => {
622639
}
623640
});
624641

642+
it("waits for logs --follow children to stop after SIGTERM", { timeout: 15000 }, async () => {
643+
const home = fs.mkdtempSync(path.join(os.tmpdir(), "nemoclaw-cli-logs-follow-sigterm-wait-"));
644+
const localBin = path.join(home, "bin");
645+
const markerFile = path.join(home, "logs-follow-sigterm-wait-args");
646+
fs.mkdirSync(localBin, { recursive: true });
647+
writeSandboxRegistry(home);
648+
fs.writeFileSync(
649+
path.join(localBin, "openshell"),
650+
[
651+
"#!/usr/bin/env bash",
652+
`marker_file=${JSON.stringify(markerFile)}`,
653+
'printf \'%s\\n\' "$*" >> "$marker_file"',
654+
'if [ "$1" = "settings" ]; then',
655+
" exit 0",
656+
"fi",
657+
'if [ "$1" = "logs" ] || [ "$1" = "sandbox" ]; then',
658+
" trap 'sleep 0.3; exit 0' TERM INT",
659+
" while true; do sleep 1; done",
660+
"fi",
661+
"exit 0",
662+
].join("\n"),
663+
{ mode: 0o755 },
664+
);
665+
666+
const child = spawn(process.execPath, [CLI, "alpha", "logs", "--follow"], {
667+
cwd: path.join(import.meta.dirname, ".."),
668+
env: { ...process.env, HOME: home, PATH: `${localBin}:${process.env.PATH || ""}` },
669+
stdio: "ignore",
670+
});
671+
const exitPromise = new Promise<number | null>((resolve) => {
672+
child.once("exit", (code) => resolve(code));
673+
});
674+
const readCalls = () =>
675+
fs.existsSync(markerFile) ? fs.readFileSync(markerFile, "utf8").trim().split(/\n/) : [];
676+
677+
try {
678+
let calls: string[] = [];
679+
const deadline = Date.now() + 10000;
680+
while (Date.now() < deadline) {
681+
calls = readCalls();
682+
if (
683+
calls.includes("logs alpha -n 200 --source all --tail") &&
684+
calls.includes("sandbox exec -n alpha -- tail -n 200 -f /tmp/gateway.log")
685+
) {
686+
break;
687+
}
688+
await new Promise((resolve) => setTimeout(resolve, 100));
689+
}
690+
child.kill("SIGTERM");
691+
const exitedEarly = await Promise.race([
692+
exitPromise.then(() => true),
693+
new Promise<boolean>((resolve) => setTimeout(() => resolve(false), 100)),
694+
]);
695+
expect(exitedEarly).toBe(false);
696+
expect(await exitPromise).toBe(143);
697+
} finally {
698+
if (child.exitCode === null) {
699+
child.kill("SIGKILL");
700+
}
701+
}
702+
});
703+
625704
it("uses named sandbox exec for bridge status helpers", () => {
626705
const home = fs.mkdtempSync(path.join(os.tmpdir(), "nemoclaw-cli-status-messaging-"));
627706
const localBin = path.join(home, "bin");

0 commit comments

Comments
 (0)