mirror of
https://github.com/openclaw/openclaw.git
synced 2026-08-12 21:53:00 -06:00
test(qa): cover remote logging boundaries (#118951)
* test(qa): cover remote logging boundaries * test(qa): tolerate gateway log interleaving * test(qa): satisfy logging type guards * test(qa): always stop log follow child
This commit is contained in:
@@ -0,0 +1,30 @@
|
||||
title: Remote gateway log tailing
|
||||
|
||||
scenario:
|
||||
id: remote-log-tailing
|
||||
surface: cli
|
||||
coverage:
|
||||
primary:
|
||||
- cli.remote-log-tailing
|
||||
- observability.gateway-rpc-logs-tail
|
||||
- observability.openclaw-logs
|
||||
objective: Verify authenticated remote log tailing through the real Gateway and packaged CLI.
|
||||
successCriteria:
|
||||
- The Gateway logs.tail RPC honors line, byte, and cursor bounds.
|
||||
- The packaged CLI accepts an explicit remote URL and token and emits JSON records.
|
||||
- Follow mode receives a later record and exits after the QA owner sends SIGINT.
|
||||
docsRefs:
|
||||
- docs/cli/logs.md
|
||||
- docs/gateway/index.md
|
||||
codeRefs:
|
||||
- src/cli/logs-cli.ts
|
||||
- src/gateway/server-methods/logs.ts
|
||||
- src/logging/log-tail.ts
|
||||
- test/e2e/qa-lab/runtime/remote-log-tailing-runtime.ts
|
||||
execution:
|
||||
kind: script
|
||||
path: test/e2e/qa-lab/runtime/remote-log-tailing-runtime.ts
|
||||
summary: Starts an authenticated Gateway and exercises logs.tail through RPC and the packaged CLI.
|
||||
args:
|
||||
- --artifact-base
|
||||
- ${outputDir}
|
||||
@@ -0,0 +1,26 @@
|
||||
title: Logging file boundary
|
||||
|
||||
scenario:
|
||||
id: logging-file-boundary
|
||||
surface: runtime
|
||||
coverage:
|
||||
primary:
|
||||
- observability.rolling-gateway-jsonl-file-logs
|
||||
- observability.trace-correlation-fields
|
||||
objective: Verify the actual file logger rotates bounded JSONL while preserving diagnostic trace correlation.
|
||||
successCriteria:
|
||||
- A tiny configured file limit rotates the active JSONL log into the .1 archive.
|
||||
- Every retained line in the active and archived files is valid JSON.
|
||||
- Trace, span, parent, and flags fields survive in the file record and match the linked diagnostic event.
|
||||
codeRefs:
|
||||
- src/logging/logger.ts
|
||||
- src/logging/logger-file-transport.ts
|
||||
- src/infra/diagnostic-trace-context.ts
|
||||
- test/e2e/qa-lab/runtime/logging-file-boundary-runtime.ts
|
||||
execution:
|
||||
kind: script
|
||||
path: test/e2e/qa-lab/runtime/logging-file-boundary-runtime.ts
|
||||
summary: Runs the real logger with a tiny file cap and validates JSONL rotation and trace correlation.
|
||||
args:
|
||||
- --artifact-base
|
||||
- ${outputDir}
|
||||
@@ -0,0 +1,21 @@
|
||||
import { afterEach, describe, expect, it } from "vitest";
|
||||
import { useAutoCleanupTempDirTracker } from "../../../helpers/temp-dir.js";
|
||||
import { runLoggingFileBoundary } from "./logging-file-boundary-runtime.js";
|
||||
|
||||
const tempDirs = useAutoCleanupTempDirTracker(afterEach);
|
||||
|
||||
describe("logging file boundary runtime", () => {
|
||||
it("rotates valid JSONL and preserves linked trace fields", async () => {
|
||||
const root = tempDirs.make("openclaw-logging-boundary-");
|
||||
const result = await runLoggingFileBoundary(root);
|
||||
|
||||
expect(result.currentRecords).toBeGreaterThan(0);
|
||||
expect(result.archivedRecords).toBeGreaterThan(0);
|
||||
expect(result.trace).toEqual({
|
||||
traceId: "4bf92f3577b34da6a3ce929d0e0e4736",
|
||||
spanId: "00f067aa0ba902b7",
|
||||
parentSpanId: "1111111111111111",
|
||||
traceFlags: "01",
|
||||
});
|
||||
});
|
||||
});
|
||||
@@ -0,0 +1,136 @@
|
||||
import { readFile, mkdir } from "node:fs/promises";
|
||||
import path from "node:path";
|
||||
import {
|
||||
onInternalDiagnosticEvent,
|
||||
resetDiagnosticEventsForTest,
|
||||
type DiagnosticEventPayload,
|
||||
} from "../../../../src/infra/diagnostic-events.js";
|
||||
import {
|
||||
createDiagnosticTraceContext,
|
||||
runWithDiagnosticTraceContext,
|
||||
} from "../../../../src/infra/diagnostic-trace-context.js";
|
||||
import {
|
||||
getChildLogger,
|
||||
resetLogger,
|
||||
setLoggerOverride,
|
||||
testApi,
|
||||
} from "../../../../src/logging/logger.js";
|
||||
import { createQaScriptEvidenceWriter } from "./script-evidence.js";
|
||||
|
||||
function artifactBase(argv: readonly string[]): string {
|
||||
const index = argv.indexOf("--artifact-base");
|
||||
const value = index >= 0 ? argv[index + 1] : undefined;
|
||||
if (!value) {
|
||||
throw new Error("--artifact-base is required");
|
||||
}
|
||||
return path.resolve(value);
|
||||
}
|
||||
|
||||
function rotatedPath(file: string): string {
|
||||
const ext = path.extname(file);
|
||||
return `${file.slice(0, -ext.length)}.1${ext}`;
|
||||
}
|
||||
|
||||
export async function runLoggingFileBoundary(outputRoot: string) {
|
||||
await mkdir(outputRoot, { recursive: true });
|
||||
const logPath = path.join(outputRoot, "openclaw.jsonl");
|
||||
const trace = createDiagnosticTraceContext({
|
||||
traceId: "4bf92f3577b34da6a3ce929d0e0e4736",
|
||||
spanId: "00f067aa0ba902b7",
|
||||
parentSpanId: "1111111111111111",
|
||||
traceFlags: "01",
|
||||
});
|
||||
const diagnostics: Extract<DiagnosticEventPayload, { type: "log.record" }>[] = [];
|
||||
resetDiagnosticEventsForTest();
|
||||
resetLogger();
|
||||
testApi.resetFileLogTransportForTests();
|
||||
setLoggerOverride({ level: "info", file: logPath, maxFileBytes: 512 });
|
||||
const unsubscribe = onInternalDiagnosticEvent((event) => {
|
||||
if (event.type === "log.record") {
|
||||
diagnostics.push(event);
|
||||
}
|
||||
});
|
||||
try {
|
||||
runWithDiagnosticTraceContext(trace, () => {
|
||||
const logger = getChildLogger({ subsystem: "qa-file-boundary" });
|
||||
logger.info(`rotation-fill-${"x".repeat(700)}`);
|
||||
logger.info({ marker: "correlated" }, "qa-correlated-record");
|
||||
});
|
||||
await testApi.flushFileLogQueueForTests();
|
||||
await new Promise<void>((resolve) => {
|
||||
setImmediate(resolve);
|
||||
});
|
||||
const current = (await readFile(logPath, "utf8"))
|
||||
.trim()
|
||||
.split("\n")
|
||||
.map((line) => JSON.parse(line));
|
||||
const archived = (await readFile(rotatedPath(logPath), "utf8"))
|
||||
.trim()
|
||||
.split("\n")
|
||||
.map((line) => JSON.parse(line));
|
||||
const fileRecord = current.find(
|
||||
(record: Record<string, unknown>) => record.message === "qa-correlated-record",
|
||||
) as Record<string, unknown> | undefined;
|
||||
const diagnostic = diagnostics.find((event) => event.message === "qa-correlated-record");
|
||||
if (!fileRecord || !diagnostic) {
|
||||
throw new Error("correlated file and diagnostic records were not both emitted");
|
||||
}
|
||||
const expected = {
|
||||
traceId: trace.traceId,
|
||||
spanId: trace.spanId,
|
||||
parentSpanId: trace.parentSpanId,
|
||||
traceFlags: trace.traceFlags,
|
||||
};
|
||||
for (const [key, value] of Object.entries(expected)) {
|
||||
if (fileRecord[key] !== value || diagnostic.trace?.[key as keyof typeof expected] !== value) {
|
||||
throw new Error(`trace correlation mismatch for ${key}`);
|
||||
}
|
||||
}
|
||||
return { currentRecords: current.length, archivedRecords: archived.length, trace: expected };
|
||||
} finally {
|
||||
unsubscribe();
|
||||
setLoggerOverride(null);
|
||||
resetLogger();
|
||||
testApi.resetFileLogTransportForTests();
|
||||
resetDiagnosticEventsForTest();
|
||||
}
|
||||
}
|
||||
|
||||
async function main() {
|
||||
const repoRoot = process.cwd();
|
||||
const outputRoot = artifactBase(process.argv.slice(2));
|
||||
const startedAt = Date.now();
|
||||
const writer = createQaScriptEvidenceWriter({
|
||||
artifactBase: outputRoot,
|
||||
logFileName: "logging-file-boundary.log",
|
||||
primaryModel: "none",
|
||||
providerMode: "mock-openai",
|
||||
repoRoot,
|
||||
target: {
|
||||
id: "logging-file-boundary",
|
||||
sourcePath: "qa/scenarios/runtime/logging-file-boundary.yaml",
|
||||
title: "Logging file boundary",
|
||||
codeRefs: [
|
||||
"test/e2e/qa-lab/runtime/logging-file-boundary-runtime.ts",
|
||||
"src/logging/logger-file-transport.ts",
|
||||
],
|
||||
},
|
||||
});
|
||||
try {
|
||||
const result = await runLoggingFileBoundary(outputRoot);
|
||||
writer.appendLog(`${JSON.stringify(result)}\n`);
|
||||
await writer.write({ durationMs: Date.now() - startedAt, status: "pass" });
|
||||
} catch (error) {
|
||||
writer.appendLog(`${String(error)}\n`);
|
||||
await writer.write({
|
||||
details: error instanceof Error ? error.message : String(error),
|
||||
durationMs: Date.now() - startedAt,
|
||||
status: "fail",
|
||||
});
|
||||
throw error;
|
||||
}
|
||||
}
|
||||
|
||||
if (import.meta.url === new URL(process.argv[1] ?? "", "file:").href) {
|
||||
await main();
|
||||
}
|
||||
@@ -0,0 +1,36 @@
|
||||
import { spawn } from "node:child_process";
|
||||
import { once } from "node:events";
|
||||
import { readFileSync } from "node:fs";
|
||||
import path from "node:path";
|
||||
import { describe, expect, it } from "vitest";
|
||||
import { withOwnedFollowChild } from "./remote-log-tailing-runtime.js";
|
||||
|
||||
describe("remote log tailing scenario", () => {
|
||||
it("declares packaged CLI, RPC bounds, cursor, follow, and owned SIGINT proof", () => {
|
||||
const source = readFileSync(
|
||||
path.join(process.cwd(), "test/e2e/qa-lab/runtime/remote-log-tailing-runtime.ts"),
|
||||
"utf8",
|
||||
);
|
||||
expect(source).toContain('"logs.tail"');
|
||||
expect(source).toContain("first.cursor");
|
||||
expect(source).toContain('"--max-bytes"');
|
||||
expect(source).toContain('"--follow"');
|
||||
expect(source).toContain("withOwnedFollowChild(child");
|
||||
expect(source).toContain('path.join(repoRoot, "dist", "index.js")');
|
||||
});
|
||||
|
||||
it("stops and awaits the follow child when the owned operation fails", async () => {
|
||||
const child = spawn(process.execPath, ["-e", "setInterval(() => {}, 1000)"], {
|
||||
stdio: "ignore",
|
||||
});
|
||||
await once(child, "spawn");
|
||||
|
||||
await expect(
|
||||
withOwnedFollowChild(child, async () => {
|
||||
throw new Error("forced follow failure");
|
||||
}),
|
||||
).rejects.toThrow("forced follow failure");
|
||||
|
||||
expect(child.signalCode).not.toBeNull();
|
||||
});
|
||||
});
|
||||
@@ -0,0 +1,234 @@
|
||||
import { spawn, type ChildProcess } from "node:child_process";
|
||||
import { appendFile, mkdir } from "node:fs/promises";
|
||||
import path from "node:path";
|
||||
import { startQaGatewayChild } from "../../../../extensions/qa-lab/api.js";
|
||||
import { createQaScriptEvidenceWriter } from "./script-evidence.js";
|
||||
|
||||
const SOURCE_PATH = "test/e2e/qa-lab/runtime/remote-log-tailing-runtime.ts";
|
||||
|
||||
function artifactBase(argv: readonly string[]): string {
|
||||
const index = argv.indexOf("--artifact-base");
|
||||
const value = index >= 0 ? argv[index + 1] : undefined;
|
||||
if (!value) {
|
||||
throw new Error("--artifact-base is required");
|
||||
}
|
||||
return path.resolve(value);
|
||||
}
|
||||
|
||||
function logLine(message: string): string {
|
||||
return `${JSON.stringify({
|
||||
time: new Date().toISOString(),
|
||||
level: "info",
|
||||
subsystem: "qa-remote-logs",
|
||||
message,
|
||||
})}\n`;
|
||||
}
|
||||
|
||||
function hasExited(child: ChildProcess): boolean {
|
||||
return child.exitCode !== null || child.signalCode !== null;
|
||||
}
|
||||
|
||||
function waitForClose(child: ChildProcess, timeoutMs: number): Promise<void> {
|
||||
if (hasExited(child)) {
|
||||
return Promise.resolve();
|
||||
}
|
||||
return new Promise((resolve, reject) => {
|
||||
const onClose = () => {
|
||||
clearTimeout(timer);
|
||||
resolve();
|
||||
};
|
||||
const timer = setTimeout(() => {
|
||||
child.off("close", onClose);
|
||||
reject(new Error("follow child did not close before timeout"));
|
||||
}, timeoutMs);
|
||||
child.once("close", onClose);
|
||||
});
|
||||
}
|
||||
|
||||
async function stopFollowChild(child: ChildProcess): Promise<void> {
|
||||
if (hasExited(child)) {
|
||||
return;
|
||||
}
|
||||
child.kill("SIGINT");
|
||||
try {
|
||||
await waitForClose(child, 5_000);
|
||||
} catch {
|
||||
if (hasExited(child)) {
|
||||
return;
|
||||
}
|
||||
child.kill("SIGKILL");
|
||||
await waitForClose(child, 5_000);
|
||||
}
|
||||
}
|
||||
|
||||
export async function withOwnedFollowChild<T>(
|
||||
child: ChildProcess,
|
||||
operation: () => Promise<T>,
|
||||
): Promise<T> {
|
||||
try {
|
||||
return await operation();
|
||||
} finally {
|
||||
await stopFollowChild(child);
|
||||
}
|
||||
}
|
||||
|
||||
export async function runRemoteLogTailing(repoRoot: string, outputRoot: string) {
|
||||
const logPath = path.join(outputRoot, "gateway.jsonl");
|
||||
await mkdir(outputRoot, { recursive: true });
|
||||
const gateway = await startQaGatewayChild({
|
||||
repoRoot,
|
||||
command: {
|
||||
executablePath: process.execPath,
|
||||
argsPrefix: [path.join(repoRoot, "dist", "index.js")],
|
||||
cwd: repoRoot,
|
||||
usePackagedPlugins: true,
|
||||
},
|
||||
transportBaseUrl: "http://127.0.0.1:9",
|
||||
controlUiEnabled: false,
|
||||
mutateConfig: (config) => ({
|
||||
...config,
|
||||
logging: { ...config.logging, file: logPath, level: "info" },
|
||||
}),
|
||||
});
|
||||
try {
|
||||
await appendFile(logPath, logLine("qa-line-one"));
|
||||
await appendFile(logPath, logLine("qa-line-two"));
|
||||
await appendFile(logPath, logLine("qa-line-three"));
|
||||
|
||||
const first = (await gateway.call("logs.tail", { limit: 2, maxBytes: 4096 })) as {
|
||||
cursor: number;
|
||||
lines: string[];
|
||||
truncated: boolean;
|
||||
};
|
||||
if (first.lines.length !== 2 || !first.lines.some((line) => line.includes("qa-line-three"))) {
|
||||
throw new Error(`logs.tail did not honor limit: ${JSON.stringify(first)}`);
|
||||
}
|
||||
const bounded = (await gateway.call("logs.tail", { limit: 20, maxBytes: 96 })) as {
|
||||
cursor: number;
|
||||
lines: string[];
|
||||
truncated: boolean;
|
||||
};
|
||||
if (!bounded.truncated || bounded.cursor <= 0) {
|
||||
throw new Error(`logs.tail did not honor maxBytes: ${JSON.stringify(bounded)}`);
|
||||
}
|
||||
await appendFile(logPath, logLine("qa-cursor-line"));
|
||||
const cursorTail = (await gateway.call("logs.tail", {
|
||||
cursor: first.cursor,
|
||||
limit: 20,
|
||||
maxBytes: 4096,
|
||||
})) as { lines: string[] };
|
||||
if (
|
||||
!cursorTail.lines.some((line) => line.includes("qa-cursor-line")) ||
|
||||
cursorTail.lines.some((line) => /qa-line-(?:one|two|three)/.test(line))
|
||||
) {
|
||||
throw new Error(`logs.tail did not honor cursor: ${JSON.stringify(cursorTail)}`);
|
||||
}
|
||||
|
||||
const cliJson = await gateway.runCli([
|
||||
"logs",
|
||||
"--url",
|
||||
gateway.wsUrl,
|
||||
"--token",
|
||||
gateway.token,
|
||||
"--json",
|
||||
"--limit",
|
||||
"2",
|
||||
"--max-bytes",
|
||||
"4096",
|
||||
]);
|
||||
const cliRecords = cliJson
|
||||
.trim()
|
||||
.split("\n")
|
||||
.map((line) => JSON.parse(line) as { type?: string; message?: string });
|
||||
if (!cliRecords.some((record) => record.type === "meta")) {
|
||||
throw new Error(`packaged logs CLI omitted metadata: ${cliJson}`);
|
||||
}
|
||||
if (!cliRecords.some((record) => record.message === "qa-cursor-line")) {
|
||||
throw new Error(`packaged logs CLI omitted the tailed record: ${cliJson}`);
|
||||
}
|
||||
|
||||
const child = spawn(
|
||||
process.execPath,
|
||||
[
|
||||
path.join(repoRoot, "dist", "index.js"),
|
||||
"logs",
|
||||
"--url",
|
||||
gateway.wsUrl,
|
||||
"--token",
|
||||
gateway.token,
|
||||
"--json",
|
||||
"--follow",
|
||||
"--interval",
|
||||
"50",
|
||||
"--limit",
|
||||
"1",
|
||||
"--max-bytes",
|
||||
"4096",
|
||||
],
|
||||
{ cwd: repoRoot, env: gateway.runtimeEnv, stdio: ["ignore", "pipe", "pipe"] },
|
||||
);
|
||||
let stdout = "";
|
||||
let stderr = "";
|
||||
child.stdout.on("data", (chunk) => {
|
||||
stdout += String(chunk);
|
||||
});
|
||||
child.stderr.on("data", (chunk) => {
|
||||
stderr += String(chunk);
|
||||
});
|
||||
const followOutput = await withOwnedFollowChild(child, async () => {
|
||||
await new Promise<void>((resolve) => {
|
||||
setTimeout(resolve, 250);
|
||||
});
|
||||
await appendFile(logPath, logLine("qa-follow-line"));
|
||||
const deadline = Date.now() + 10_000;
|
||||
while (!stdout.includes("qa-follow-line") && Date.now() < deadline) {
|
||||
await new Promise<void>((resolve) => {
|
||||
setTimeout(resolve, 50);
|
||||
});
|
||||
}
|
||||
if (!stdout.includes("qa-follow-line")) {
|
||||
throw new Error(`follow did not receive appended record: ${stderr}`);
|
||||
}
|
||||
return stdout;
|
||||
});
|
||||
return { first, bounded, cursorTail, cliRecords, followOutput };
|
||||
} finally {
|
||||
await gateway.stop();
|
||||
}
|
||||
}
|
||||
|
||||
async function main() {
|
||||
const repoRoot = process.cwd();
|
||||
const outputRoot = artifactBase(process.argv.slice(2));
|
||||
const startedAt = Date.now();
|
||||
const writer = createQaScriptEvidenceWriter({
|
||||
artifactBase: outputRoot,
|
||||
logFileName: "remote-log-tailing.log",
|
||||
primaryModel: "none",
|
||||
providerMode: "mock-openai",
|
||||
repoRoot,
|
||||
target: {
|
||||
id: "remote-log-tailing",
|
||||
sourcePath: "qa/scenarios/cli/remote-log-tailing.yaml",
|
||||
title: "Remote gateway log tailing",
|
||||
codeRefs: [SOURCE_PATH, "src/cli/logs-cli.ts", "src/gateway/server-methods/logs.ts"],
|
||||
},
|
||||
});
|
||||
try {
|
||||
const result = await runRemoteLogTailing(repoRoot, outputRoot);
|
||||
writer.appendLog(`${JSON.stringify(result)}\n`);
|
||||
await writer.write({ durationMs: Date.now() - startedAt, status: "pass" });
|
||||
} catch (error) {
|
||||
writer.appendLog(`${String(error)}\n`);
|
||||
await writer.write({
|
||||
details: error instanceof Error ? error.message : String(error),
|
||||
durationMs: Date.now() - startedAt,
|
||||
status: "fail",
|
||||
});
|
||||
throw error;
|
||||
}
|
||||
}
|
||||
|
||||
if (import.meta.url === new URL(process.argv[1] ?? "", "file:").href) {
|
||||
await main();
|
||||
}
|
||||
Reference in New Issue
Block a user