mirror of
https://github.com/openclaw/openclaw.git
synced 2026-05-08 20:40:43 +00:00
fix(diagnostics-otel): export logs from diagnostic events
Export diagnostics OTEL logs through bounded diagnostic log events while keeping core log records off the public plugin diagnostic stream.\n\nIncludes security hardening for log payload redaction, bounded attributes, prototype-pollution keys, OTEL export failure reporting, and extension SDK seam usage.
This commit is contained in:
Vincent Koc
143
src/logging/diagnostic-log-events.test.ts
Normal file
143
src/logging/diagnostic-log-events.test.ts
Normal file
@@ -0,0 +1,143 @@
|
||||
import { afterEach, beforeEach, describe, expect, it } from "vitest";
|
||||
import {
|
||||
onInternalDiagnosticEvent,
|
||||
resetDiagnosticEventsForTest,
|
||||
type DiagnosticEventPayload,
|
||||
} from "../infra/diagnostic-events.js";
|
||||
import { getChildLogger, resetLogger, setLoggerOverride } from "./logger.js";
|
||||
|
||||
const TRACE_ID = "4bf92f3577b34da6a3ce929d0e0e4736";
|
||||
const SPAN_ID = "00f067aa0ba902b7";
|
||||
const PROTO_KEY = "__proto__";
|
||||
|
||||
function flushDiagnosticEvents() {
|
||||
return new Promise<void>((resolve) => setImmediate(resolve));
|
||||
}
|
||||
|
||||
beforeEach(() => {
|
||||
resetDiagnosticEventsForTest();
|
||||
resetLogger();
|
||||
setLoggerOverride({ level: "info" });
|
||||
});
|
||||
|
||||
afterEach(() => {
|
||||
resetDiagnosticEventsForTest();
|
||||
setLoggerOverride(null);
|
||||
resetLogger();
|
||||
});
|
||||
|
||||
describe("diagnostic log events", () => {
|
||||
it("emits structured log records through diagnostics", async () => {
|
||||
const received: Array<Extract<DiagnosticEventPayload, { type: "log.record" }>> = [];
|
||||
const unsubscribe = onInternalDiagnosticEvent((evt) => {
|
||||
if (evt.type === "log.record") {
|
||||
received.push(evt);
|
||||
}
|
||||
});
|
||||
|
||||
const logger = getChildLogger({
|
||||
subsystem: "diagnostic",
|
||||
trace: { traceId: TRACE_ID, spanId: SPAN_ID },
|
||||
});
|
||||
logger.info({ runId: "run-1" }, "hello diagnostic logs");
|
||||
await flushDiagnosticEvents();
|
||||
unsubscribe();
|
||||
|
||||
expect(received).toHaveLength(1);
|
||||
expect(received[0]).toMatchObject({
|
||||
type: "log.record",
|
||||
level: "INFO",
|
||||
message: "hello diagnostic logs",
|
||||
attributes: {
|
||||
subsystem: "diagnostic",
|
||||
runId: "run-1",
|
||||
},
|
||||
trace: {
|
||||
traceId: TRACE_ID,
|
||||
spanId: SPAN_ID,
|
||||
},
|
||||
});
|
||||
});
|
||||
|
||||
it("redacts and bounds internal log records before diagnostic emission", async () => {
|
||||
const received: Array<Extract<DiagnosticEventPayload, { type: "log.record" }>> = [];
|
||||
const unsubscribe = onInternalDiagnosticEvent((evt) => {
|
||||
if (evt.type === "log.record") {
|
||||
received.push(evt);
|
||||
}
|
||||
});
|
||||
|
||||
const secret = "ghp_abcdefghijklmnopqrstuvwxyz123456"; // pragma: allowlist secret
|
||||
const logger = getChildLogger({
|
||||
subsystem: "diagnostic",
|
||||
trace: { traceId: TRACE_ID, spanId: SPAN_ID },
|
||||
});
|
||||
logger.info(
|
||||
{
|
||||
token: secret,
|
||||
longValue: "x".repeat(5000),
|
||||
nested: { secret },
|
||||
"bad key": "drop-me",
|
||||
},
|
||||
{ raw: secret },
|
||||
`secret=${secret} ${"y".repeat(5000)}`,
|
||||
);
|
||||
await flushDiagnosticEvents();
|
||||
unsubscribe();
|
||||
|
||||
expect(received).toHaveLength(1);
|
||||
const [event] = received;
|
||||
expect(event.message).not.toContain(secret);
|
||||
expect(event.message.length).toBeLessThanOrEqual(4200);
|
||||
expect(event.attributes?.token).not.toBe(secret);
|
||||
expect(String(event.attributes?.token)).toContain("…");
|
||||
expect(String(event.attributes?.longValue).length).toBeLessThanOrEqual(2100);
|
||||
expect(event.attributes).toEqual(
|
||||
expect.not.objectContaining({
|
||||
nested: expect.anything(),
|
||||
"bad key": expect.anything(),
|
||||
}),
|
||||
);
|
||||
expect(event).toEqual(
|
||||
expect.not.objectContaining({
|
||||
argsJson: expect.anything(),
|
||||
}),
|
||||
);
|
||||
});
|
||||
|
||||
it("drops sensitive, blocked, and excess log attribute keys without copying large objects", async () => {
|
||||
const received: Array<Extract<DiagnosticEventPayload, { type: "log.record" }>> = [];
|
||||
const unsubscribe = onInternalDiagnosticEvent((evt) => {
|
||||
if (evt.type === "log.record") {
|
||||
received.push(evt);
|
||||
}
|
||||
});
|
||||
|
||||
const structured = Object.create(null) as Record<string, unknown>;
|
||||
structured.safe = "ok";
|
||||
structured[PROTO_KEY] = "pollute";
|
||||
structured["constructor"] = "pollute";
|
||||
structured["prototype"] = "pollute";
|
||||
structured["sk-1234567890abcdef1234567890abcdef"] = "secret-key"; // pragma: allowlist secret
|
||||
for (let index = 0; index < 1000; index += 1) {
|
||||
structured[`extra${index}`] = index;
|
||||
}
|
||||
|
||||
const logger = getChildLogger({
|
||||
subsystem: "diagnostic",
|
||||
trace: { traceId: TRACE_ID, spanId: SPAN_ID },
|
||||
});
|
||||
logger.info(structured, "bounded attrs");
|
||||
await flushDiagnosticEvents();
|
||||
unsubscribe();
|
||||
|
||||
expect(received).toHaveLength(1);
|
||||
expect(received[0].attributes?.safe).toBe("ok");
|
||||
expect(Object.keys(received[0].attributes ?? {})).toHaveLength(32);
|
||||
const attributes = received[0].attributes ?? {};
|
||||
expect(Object.hasOwn(attributes, PROTO_KEY)).toBe(false);
|
||||
expect(Object.hasOwn(attributes, "constructor")).toBe(false);
|
||||
expect(Object.hasOwn(attributes, "prototype")).toBe(false);
|
||||
expect(Object.hasOwn(attributes, "sk-1234567890abcdef1234567890abcdef")).toBe(false); // pragma: allowlist secret
|
||||
});
|
||||
});
|
||||
@@ -275,6 +275,10 @@ function sanitizeDiagnosticEvent(event: DiagnosticEventPayload): DiagnosticStabi
|
||||
record.durationMs = event.durationMs;
|
||||
assignReasonCode(record, event.errorCategory);
|
||||
break;
|
||||
case "log.record":
|
||||
record.level = event.level;
|
||||
record.source = event.loggerName;
|
||||
break;
|
||||
case "diagnostic.memory.sample":
|
||||
record.memory = copyMemory(event.memory);
|
||||
break;
|
||||
|
||||
@@ -2,6 +2,14 @@ import fs from "node:fs";
|
||||
import path from "node:path";
|
||||
import { Logger as TsLogger } from "tslog";
|
||||
import type { OpenClawConfig } from "../config/types.js";
|
||||
import { emitDiagnosticEvent } from "../infra/diagnostic-events.js";
|
||||
import {
|
||||
isValidDiagnosticSpanId,
|
||||
isValidDiagnosticTraceFlags,
|
||||
isValidDiagnosticTraceId,
|
||||
type DiagnosticTraceContext,
|
||||
} from "../infra/diagnostic-trace-context.js";
|
||||
import { isBlockedObjectKey } from "../infra/prototype-keys.js";
|
||||
import {
|
||||
POSIX_OPENCLAW_TMP_DIR,
|
||||
resolvePreferredOpenClawTmpDir,
|
||||
@@ -10,6 +18,7 @@ import { readLoggingConfig, shouldSkipMutatingLoggingConfigRead } from "./config
|
||||
import { resolveEnvLogLevelOverride } from "./env-log-level.js";
|
||||
import { type LogLevel, levelToMinLevel, normalizeLogLevel } from "./levels.js";
|
||||
import { resolveNodeRequireFromMeta } from "./node-require.js";
|
||||
import { redactSensitiveText } from "./redact.js";
|
||||
import { loggingState } from "./state.js";
|
||||
import { formatTimestamp } from "./timestamps.js";
|
||||
import type { LoggerSettings } from "./types.js";
|
||||
@@ -64,6 +73,20 @@ export type LogTransport = (logObj: LogTransportRecord) => void;
|
||||
|
||||
const externalTransports = new Set<LogTransport>();
|
||||
|
||||
type DiagnosticLogCode = {
|
||||
line?: number;
|
||||
functionName?: string;
|
||||
};
|
||||
|
||||
const MAX_DIAGNOSTIC_LOG_BINDINGS_JSON_CHARS = 8 * 1024;
|
||||
const MAX_DIAGNOSTIC_LOG_MESSAGE_CHARS = 4 * 1024;
|
||||
const MAX_DIAGNOSTIC_LOG_ATTRIBUTE_COUNT = 32;
|
||||
const MAX_DIAGNOSTIC_LOG_ATTRIBUTE_VALUE_CHARS = 2 * 1024;
|
||||
const MAX_DIAGNOSTIC_LOG_NAME_CHARS = 120;
|
||||
const DIAGNOSTIC_LOG_ATTRIBUTE_KEY_RE = /^[A-Za-z0-9_.:-]{1,64}$/u;
|
||||
|
||||
type DiagnosticLogAttributes = Record<string, string | number | boolean>;
|
||||
|
||||
function attachExternalTransport(logger: TsLogger<LogObj>, transport: LogTransport): void {
|
||||
logger.attachTransport((logObj: LogObj) => {
|
||||
if (!externalTransports.has(transport)) {
|
||||
@@ -77,6 +100,248 @@ function attachExternalTransport(logger: TsLogger<LogObj>, transport: LogTranspo
|
||||
});
|
||||
}
|
||||
|
||||
function clampDiagnosticLogText(value: string, maxChars: number): string {
|
||||
return value.length > maxChars ? `${value.slice(0, maxChars)}...(truncated)` : value;
|
||||
}
|
||||
|
||||
function sanitizeDiagnosticLogText(value: string, maxChars: number): string {
|
||||
return clampDiagnosticLogText(
|
||||
redactSensitiveText(clampDiagnosticLogText(value, maxChars)),
|
||||
maxChars,
|
||||
);
|
||||
}
|
||||
|
||||
function normalizeDiagnosticLogName(value: string | undefined): string | undefined {
|
||||
if (!value || value.trim().startsWith("{")) {
|
||||
return undefined;
|
||||
}
|
||||
const sanitized = sanitizeDiagnosticLogText(value.trim(), MAX_DIAGNOSTIC_LOG_NAME_CHARS);
|
||||
return DIAGNOSTIC_LOG_ATTRIBUTE_KEY_RE.test(sanitized) ? sanitized : undefined;
|
||||
}
|
||||
|
||||
function assignDiagnosticLogAttribute(
|
||||
attributes: DiagnosticLogAttributes,
|
||||
state: { count: number },
|
||||
key: string,
|
||||
value: unknown,
|
||||
): void {
|
||||
if (state.count >= MAX_DIAGNOSTIC_LOG_ATTRIBUTE_COUNT) {
|
||||
return;
|
||||
}
|
||||
const normalizedKey = key.trim();
|
||||
if (isBlockedObjectKey(normalizedKey)) {
|
||||
return;
|
||||
}
|
||||
if (redactSensitiveText(normalizedKey) !== normalizedKey) {
|
||||
return;
|
||||
}
|
||||
if (!DIAGNOSTIC_LOG_ATTRIBUTE_KEY_RE.test(normalizedKey)) {
|
||||
return;
|
||||
}
|
||||
if (typeof value === "string") {
|
||||
attributes[normalizedKey] = sanitizeDiagnosticLogText(
|
||||
value,
|
||||
MAX_DIAGNOSTIC_LOG_ATTRIBUTE_VALUE_CHARS,
|
||||
);
|
||||
state.count += 1;
|
||||
return;
|
||||
}
|
||||
if (typeof value === "number" && Number.isFinite(value)) {
|
||||
attributes[normalizedKey] = value;
|
||||
state.count += 1;
|
||||
return;
|
||||
}
|
||||
if (typeof value === "boolean") {
|
||||
attributes[normalizedKey] = value;
|
||||
state.count += 1;
|
||||
}
|
||||
}
|
||||
|
||||
function addDiagnosticLogAttributesFrom(
|
||||
attributes: DiagnosticLogAttributes,
|
||||
state: { count: number },
|
||||
source: Record<string, unknown> | undefined,
|
||||
): void {
|
||||
if (!source) {
|
||||
return;
|
||||
}
|
||||
for (const key in source) {
|
||||
if (state.count >= MAX_DIAGNOSTIC_LOG_ATTRIBUTE_COUNT) {
|
||||
break;
|
||||
}
|
||||
if (!Object.hasOwn(source, key) || key === "trace") {
|
||||
continue;
|
||||
}
|
||||
assignDiagnosticLogAttribute(attributes, state, key, source[key]);
|
||||
}
|
||||
}
|
||||
|
||||
function isPlainLogRecordObject(value: unknown): value is Record<string, unknown> {
|
||||
if (!value || typeof value !== "object" || Array.isArray(value)) {
|
||||
return false;
|
||||
}
|
||||
const prototype = Object.getPrototypeOf(value);
|
||||
return prototype === Object.prototype || prototype === null;
|
||||
}
|
||||
|
||||
function normalizeTraceContext(value: unknown): DiagnosticTraceContext | undefined {
|
||||
if (!value || typeof value !== "object" || Array.isArray(value)) {
|
||||
return undefined;
|
||||
}
|
||||
const candidate = value as Partial<DiagnosticTraceContext>;
|
||||
if (!isValidDiagnosticTraceId(candidate.traceId)) {
|
||||
return undefined;
|
||||
}
|
||||
if (candidate.spanId !== undefined && !isValidDiagnosticSpanId(candidate.spanId)) {
|
||||
return undefined;
|
||||
}
|
||||
if (candidate.parentSpanId !== undefined && !isValidDiagnosticSpanId(candidate.parentSpanId)) {
|
||||
return undefined;
|
||||
}
|
||||
if (candidate.traceFlags !== undefined && !isValidDiagnosticTraceFlags(candidate.traceFlags)) {
|
||||
return undefined;
|
||||
}
|
||||
return {
|
||||
traceId: candidate.traceId,
|
||||
...(candidate.spanId ? { spanId: candidate.spanId } : {}),
|
||||
...(candidate.parentSpanId ? { parentSpanId: candidate.parentSpanId } : {}),
|
||||
...(candidate.traceFlags ? { traceFlags: candidate.traceFlags } : {}),
|
||||
};
|
||||
}
|
||||
|
||||
function extractTraceContext(value: unknown): DiagnosticTraceContext | undefined {
|
||||
const direct = normalizeTraceContext(value);
|
||||
if (direct) {
|
||||
return direct;
|
||||
}
|
||||
if (!value || typeof value !== "object" || Array.isArray(value)) {
|
||||
return undefined;
|
||||
}
|
||||
return normalizeTraceContext((value as { trace?: unknown }).trace);
|
||||
}
|
||||
|
||||
function findLogTraceContext(
|
||||
bindings: Record<string, unknown> | undefined,
|
||||
numericArgs: readonly unknown[],
|
||||
): DiagnosticTraceContext | undefined {
|
||||
const fromBindings = extractTraceContext(bindings);
|
||||
if (fromBindings) {
|
||||
return fromBindings;
|
||||
}
|
||||
for (const arg of numericArgs) {
|
||||
const fromArg = extractTraceContext(arg);
|
||||
if (fromArg) {
|
||||
return fromArg;
|
||||
}
|
||||
}
|
||||
return undefined;
|
||||
}
|
||||
|
||||
function buildDiagnosticLogRecord(logObj: LogTransportRecord) {
|
||||
const meta = logObj._meta as
|
||||
| {
|
||||
logLevelName?: string;
|
||||
date?: Date;
|
||||
name?: string;
|
||||
parentNames?: string[];
|
||||
path?: {
|
||||
filePath?: string;
|
||||
fileLine?: string;
|
||||
fileColumn?: string;
|
||||
filePathWithLine?: string;
|
||||
method?: string;
|
||||
};
|
||||
}
|
||||
| undefined;
|
||||
const numericArgs = Object.entries(logObj)
|
||||
.filter(([key]) => /^\d+$/.test(key))
|
||||
.toSorted((a, b) => Number(a[0]) - Number(b[0]))
|
||||
.map(([, value]) => value);
|
||||
|
||||
let bindings: Record<string, unknown> | undefined;
|
||||
if (
|
||||
typeof numericArgs[0] === "string" &&
|
||||
numericArgs[0].length <= MAX_DIAGNOSTIC_LOG_BINDINGS_JSON_CHARS &&
|
||||
numericArgs[0].trim().startsWith("{")
|
||||
) {
|
||||
try {
|
||||
const parsed = JSON.parse(numericArgs[0]);
|
||||
if (parsed && typeof parsed === "object" && !Array.isArray(parsed)) {
|
||||
bindings = parsed as Record<string, unknown>;
|
||||
numericArgs.shift();
|
||||
}
|
||||
} catch {
|
||||
// ignore malformed json bindings
|
||||
}
|
||||
}
|
||||
|
||||
const trace = findLogTraceContext(bindings, numericArgs);
|
||||
const structuredArg = numericArgs[0];
|
||||
const structuredBindings = isPlainLogRecordObject(structuredArg) ? structuredArg : undefined;
|
||||
if (structuredBindings) {
|
||||
numericArgs.shift();
|
||||
}
|
||||
|
||||
let message = "";
|
||||
if (numericArgs.length > 0 && typeof numericArgs[numericArgs.length - 1] === "string") {
|
||||
message = sanitizeDiagnosticLogText(
|
||||
String(numericArgs.pop()),
|
||||
MAX_DIAGNOSTIC_LOG_MESSAGE_CHARS,
|
||||
);
|
||||
} else if (
|
||||
numericArgs.length === 1 &&
|
||||
(typeof numericArgs[0] === "number" || typeof numericArgs[0] === "boolean")
|
||||
) {
|
||||
message = String(numericArgs[0]);
|
||||
numericArgs.length = 0;
|
||||
}
|
||||
if (!message) {
|
||||
message = "log";
|
||||
}
|
||||
|
||||
const attributes: DiagnosticLogAttributes = Object.create(null) as DiagnosticLogAttributes;
|
||||
const attributeState = { count: 0 };
|
||||
addDiagnosticLogAttributesFrom(attributes, attributeState, bindings);
|
||||
addDiagnosticLogAttributesFrom(attributes, attributeState, structuredBindings);
|
||||
|
||||
const code: DiagnosticLogCode = {};
|
||||
if (meta?.path?.fileLine) {
|
||||
const line = Number(meta.path.fileLine);
|
||||
if (Number.isFinite(line)) {
|
||||
code.line = line;
|
||||
}
|
||||
}
|
||||
if (meta?.path?.method) {
|
||||
code.functionName = sanitizeDiagnosticLogText(meta.path.method, MAX_DIAGNOSTIC_LOG_NAME_CHARS);
|
||||
}
|
||||
|
||||
const loggerName = normalizeDiagnosticLogName(meta?.name);
|
||||
const loggerParents = meta?.parentNames
|
||||
?.map(normalizeDiagnosticLogName)
|
||||
.filter((name): name is string => Boolean(name));
|
||||
|
||||
return {
|
||||
type: "log.record" as const,
|
||||
level: meta?.logLevelName ?? "INFO",
|
||||
message,
|
||||
...(loggerName ? { loggerName } : {}),
|
||||
...(loggerParents?.length ? { loggerParents } : {}),
|
||||
...(Object.keys(attributes).length > 0 ? { attributes } : {}),
|
||||
...(Object.keys(code).length > 0 ? { code } : {}),
|
||||
...(trace ? { trace } : {}),
|
||||
};
|
||||
}
|
||||
|
||||
function attachDiagnosticEventTransport(logger: TsLogger<LogObj>): void {
|
||||
logger.attachTransport((logObj: LogObj) => {
|
||||
try {
|
||||
emitDiagnosticEvent(buildDiagnosticLogRecord(logObj as LogTransportRecord));
|
||||
} catch {
|
||||
// never block on logging failures
|
||||
}
|
||||
});
|
||||
}
|
||||
|
||||
function canUseSilentVitestFileLogFastPath(envLevel: LogLevel | undefined): boolean {
|
||||
return (
|
||||
process.env.VITEST === "true" &&
|
||||
@@ -159,6 +424,7 @@ function buildLogger(settings: ResolvedSettings): TsLogger<LogObj> {
|
||||
|
||||
// Silent logging does not write files; skip all filesystem setup in this path.
|
||||
if (settings.level === "silent") {
|
||||
attachDiagnosticEventTransport(logger);
|
||||
for (const transport of externalTransports) {
|
||||
attachExternalTransport(logger, transport);
|
||||
}
|
||||
@@ -203,6 +469,7 @@ function buildLogger(settings: ResolvedSettings): TsLogger<LogObj> {
|
||||
// never block on logging failures
|
||||
}
|
||||
});
|
||||
attachDiagnosticEventTransport(logger);
|
||||
for (const transport of externalTransports) {
|
||||
attachExternalTransport(logger, transport);
|
||||
}
|
||||
|
||||
Reference in New Issue
Block a user