Skip to content

Commit f3eb8e9

Browse files
joshavantjoshavant
authored
Fix OTLP log trace correlation (#92276)
* fix diagnostics otel log trace correlation * test diagnostics trace provenance contract
1 parent f80f472 commit f3eb8e9

8 files changed

Lines changed: 134 additions & 30 deletions

File tree

‎extensions/diagnostics-otel/src/service.test.ts‎

Lines changed: 33 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -171,6 +171,7 @@ import {
171171
type DiagnosticEventPrivateData,
172172
} from "openclaw/plugin-sdk/diagnostic-runtime";
173173
import {
174+
emitDiagnosticEventWithTrustedTraceContext,
174175
emitInternalDiagnosticEventForTest,
175176
logMessageDispatchStarted,
176177
logMessageProcessed,
@@ -362,15 +363,23 @@ function histogramCreateOptions(name: string) {
362363

363364
async function emitAndCaptureLog(
364365
event: Omit<Extract<Parameters<typeof emitDiagnosticEvent>[0], { type: "log.record" }>, "type">,
365-
options: { captureContent?: OtelContextFlags["captureContent"]; trusted?: boolean } = {},
366+
options: {
367+
captureContent?: OtelContextFlags["captureContent"];
368+
trusted?: boolean;
369+
trustedTraceContext?: boolean;
370+
} = {},
366371
) {
367372
const service = createDiagnosticsOtelService();
368373
const ctx = createOtelContext(OTEL_TEST_ENDPOINT, {
369374
logs: true,
370375
...(options.captureContent !== undefined ? { captureContent: options.captureContent } : {}),
371376
});
372377
await service.start(ctx);
373-
const emit = options.trusted ? emitTrustedDiagnosticEvent : emitDiagnosticEvent;
378+
const emit = options.trusted
379+
? emitTrustedDiagnosticEvent
380+
: options.trustedTraceContext
381+
? emitDiagnosticEventWithTrustedTraceContext
382+
: emitDiagnosticEvent;
374383
emit({
375384
type: "log.record",
376385
...event,
@@ -1391,6 +1400,28 @@ describe("diagnostics-otel service", () => {
13911400
expect(emitCall?.context).toBeUndefined();
13921401
});
13931402

1403+
test("attaches trace-only trusted context to exported logs", async () => {
1404+
const emitCall = await emitAndCaptureLog(
1405+
{
1406+
level: "INFO",
1407+
message: "traceable log",
1408+
trace: {
1409+
traceId: TRACE_ID,
1410+
spanId: SPAN_ID,
1411+
traceFlags: "01",
1412+
},
1413+
},
1414+
{ trustedTraceContext: true },
1415+
);
1416+
1417+
expect(emitCall?.body).toBe("log");
1418+
expect(telemetryState.tracer.setSpanContext).toHaveBeenCalledTimes(1);
1419+
const emitContext = emitCall?.context as { spanContext?: Record<string, unknown> } | undefined;
1420+
const emitSpanContext = emitContext?.spanContext;
1421+
expect(emitSpanContext?.traceId).toBe(TRACE_ID);
1422+
expect(emitSpanContext?.spanId).toBe(SPAN_ID);
1423+
});
1424+
13941425
test("attaches trusted diagnostic trace context to exported logs", async () => {
13951426
const emitCall = await emitAndCaptureLog(
13961427
{

‎extensions/diagnostics-otel/src/service.ts‎

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -1031,7 +1031,9 @@ function contextForTrustedTraceContext(
10311031
evt: DiagnosticEventPayload,
10321032
metadata: DiagnosticEventMetadata,
10331033
) {
1034-
return metadata.trusted ? contextForTraceContext(evt.trace) : undefined;
1034+
return metadata.trusted || metadata.trustedTraceContext === true
1035+
? contextForTraceContext(evt.trace)
1036+
: undefined;
10351037
}
10361038

10371039
function addTraceAttributes(
@@ -1626,7 +1628,7 @@ export function createDiagnosticsOtelService(): OpenClawPluginService {
16261628
if (evt.code?.functionName) {
16271629
assignOtelLogAttribute(attributes, "code.function", evt.code.functionName);
16281630
}
1629-
if (metadata.trusted) {
1631+
if (metadata.trusted || metadata.trustedTraceContext === true) {
16301632
addTraceAttributes(attributes, evt.trace);
16311633
}
16321634

‎scripts/qa-otel-smoke.ts‎

Lines changed: 18 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -79,6 +79,8 @@ type CapturedMetric = {
7979

8080
type CapturedLogRecord = {
8181
body: string | number | boolean | string[];
82+
spanId: string;
83+
traceId: string;
8284
};
8385

8486
const DEFAULT_SCENARIO_ID = "otel-trace-smoke";
@@ -646,15 +648,21 @@ function decodeMetricRequest(body: Buffer): CapturedMetric[] {
646648
function decodeLogRecord(message: Uint8Array): CapturedLogRecord {
647649
const reader = new ProtoReader(message);
648650
let body: string | number | boolean | string[] = "";
651+
let traceId = "";
652+
let spanId = "";
649653
while (!reader.done()) {
650654
const { field, wire } = reader.tag();
651655
if (field === 5 && wire === 2) {
652656
body = normalizeOtlpValue(decodeAnyValue(reader.bytes()));
657+
} else if (field === 9 && wire === 2) {
658+
traceId = Buffer.from(reader.bytes()).toString("hex");
659+
} else if (field === 10 && wire === 2) {
660+
spanId = Buffer.from(reader.bytes()).toString("hex");
653661
} else {
654662
reader.skip(wire);
655663
}
656664
}
657-
return { body };
665+
return { body, spanId, traceId };
658666
}
659667

660668
function decodeScopeLogs(message: Uint8Array): CapturedLogRecord[] {
@@ -1439,6 +1447,12 @@ function assertSmoke(params: {
14391447
if (rawLogBodies.length > 0) {
14401448
failures.push(`OTLP log records exported ${rawLogBodies.length} non-placeholder bodies`);
14411449
}
1450+
const correlatedLogRecords = params.logRecords.filter(
1451+
(record) => record.traceId && record.spanId,
1452+
);
1453+
if (correlatedLogRecords.length === 0) {
1454+
failures.push("no OTLP log records included trace/span correlation ids");
1455+
}
14421456

14431457
const attributeKeys = collectAttributeKeys(params.spans);
14441458
const disallowed = [...DISALLOWED_ATTRIBUTE_KEYS].filter((key) => attributeKeys.has(key));
@@ -1568,6 +1582,9 @@ async function main() {
15681582
spanCount: receiver.capturedSpans.length,
15691583
metricCount: receiver.capturedMetrics.length,
15701584
logRecordCount: receiver.capturedLogRecords.length,
1585+
logRecordsWithTraceContext: receiver.capturedLogRecords.filter(
1586+
(record) => record.traceId && record.spanId,
1587+
).length,
15711588
spanNames: assertion.spanNames,
15721589
metricNames: assertion.metricNames,
15731590
signalRequestCounts: assertion.signalRequestCounts,

‎src/infra/diagnostic-events.test.ts‎

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -240,6 +240,12 @@ describe("diagnostic-events", () => {
240240

241241
expect(traceparents).toEqual([undefined, `00-${trace.traceId}-${trace.spanId}-01`]);
242242
expect(formatDiagnosticTraceparentForPropagation({ trace }, { trusted: true })).toBeUndefined();
243+
expect(
244+
formatDiagnosticTraceparentForPropagation(
245+
{ trace },
246+
{ trusted: false, trustedTraceContext: true },
247+
),
248+
).toBeUndefined();
243249
});
244250

245251
it("shares diagnostic state across duplicate module instances", async () => {

‎src/infra/diagnostic-events.ts‎

Lines changed: 12 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -704,6 +704,7 @@ export type DiagnosticEventInput = DiagnosticEventPayload extends infer Event
704704

705705
export type DiagnosticEventMetadata = Readonly<{
706706
internal?: boolean;
707+
trustedTraceContext?: boolean;
707708
trusted: boolean;
708709
}>;
709710

@@ -1068,6 +1069,7 @@ function createInternalDiagnosticMetadata(trusted: boolean): DiagnosticEventMeta
10681069
type EmitDiagnosticEventOptions = {
10691070
internal?: boolean;
10701071
privateData?: DiagnosticEventPrivateData;
1072+
trustedTraceContext?: boolean;
10711073
};
10721074

10731075
function emitDiagnosticEventWithTrust(
@@ -1082,7 +1084,11 @@ function emitDiagnosticEventWithTrust(
10821084

10831085
const enriched = enrichDiagnosticEvent(state, event);
10841086
const { internal = false, privateData } = options;
1085-
const metadata = internal ? createInternalDiagnosticMetadata(trusted) : { trusted };
1087+
const trustedTraceContext = options.trustedTraceContext === true;
1088+
const metadata = {
1089+
...(internal ? createInternalDiagnosticMetadata(trusted) : { trusted }),
1090+
...(trustedTraceContext ? { trustedTraceContext } : {}),
1091+
};
10861092

10871093
if (ASYNC_DIAGNOSTIC_EVENT_TYPES.has(enriched.type)) {
10881094
if (state.asyncQueue.length >= MAX_ASYNC_DIAGNOSTIC_EVENTS) {
@@ -1108,6 +1114,11 @@ export function emitDiagnosticEvent(event: DiagnosticEventInput) {
11081114
emitDiagnosticEventWithTrust(event, false);
11091115
}
11101116

1117+
/** Emits an untrusted event whose trace context came from OpenClaw-owned scope. */
1118+
export function emitDiagnosticEventWithTrustedTraceContext(event: DiagnosticEventInput) {
1119+
emitDiagnosticEventWithTrust(event, false, { trustedTraceContext: true });
1120+
}
1121+
11111122
/** Emits an untrusted diagnostic event tagged as internal dispatcher provenance. */
11121123
export function emitInternalDiagnosticEvent(event: DiagnosticEventInput) {
11131124
emitDiagnosticEventWithTrust(event, false, { internal: true });

‎src/logging/diagnostic-log-events.test.ts‎

Lines changed: 21 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -3,6 +3,7 @@ import { afterEach, beforeEach, describe, expect, it } from "vitest";
33
import {
44
onInternalDiagnosticEvent,
55
resetDiagnosticEventsForTest,
6+
type DiagnosticEventMetadata,
67
type DiagnosticEventPayload,
78
} from "../infra/diagnostic-events.js";
89
import {
@@ -37,10 +38,13 @@ afterEach(() => {
3738

3839
describe("diagnostic log events", () => {
3940
it("emits structured log records through diagnostics", async () => {
40-
const received: Array<Extract<DiagnosticEventPayload, { type: "log.record" }>> = [];
41-
const unsubscribe = onInternalDiagnosticEvent((evt) => {
41+
const received: Array<{
42+
event: Extract<DiagnosticEventPayload, { type: "log.record" }>;
43+
metadata: DiagnosticEventMetadata;
44+
}> = [];
45+
const unsubscribe = onInternalDiagnosticEvent((evt, metadata) => {
4246
if (evt.type === "log.record") {
43-
received.push(evt);
47+
received.push({ event: evt, metadata });
4448
}
4549
});
4650

@@ -53,10 +57,11 @@ describe("diagnostic log events", () => {
5357
unsubscribe();
5458

5559
expect(received).toHaveLength(1);
56-
const [event] = received;
57-
if (!event) {
60+
const [record] = received;
61+
if (!record) {
5862
throw new Error("missing diagnostic log event");
5963
}
64+
const { event, metadata } = record;
6065
expect(event.type).toBe("log.record");
6166
expect(event.level).toBe("INFO");
6267
expect(event.message).toBe("hello diagnostic logs");
@@ -68,17 +73,22 @@ describe("diagnostic log events", () => {
6873
traceId: TRACE_ID,
6974
spanId: SPAN_ID,
7075
});
76+
expect(metadata.trusted).toBe(false);
77+
expect(metadata.trustedTraceContext).toBeUndefined();
7178
});
7279

7380
it("uses active request trace context for unbound log records", async () => {
7481
const trace = createDiagnosticTraceContext({
7582
traceId: TRACE_ID,
7683
spanId: SPAN_ID,
7784
});
78-
const received: Array<Extract<DiagnosticEventPayload, { type: "log.record" }>> = [];
79-
const unsubscribe = onInternalDiagnosticEvent((evt) => {
85+
const received: Array<{
86+
event: Extract<DiagnosticEventPayload, { type: "log.record" }>;
87+
metadata: DiagnosticEventMetadata;
88+
}> = [];
89+
const unsubscribe = onInternalDiagnosticEvent((evt, metadata) => {
8090
if (evt.type === "log.record") {
81-
received.push(evt);
91+
received.push({ event: evt, metadata });
8292
}
8393
});
8494

@@ -90,7 +100,9 @@ describe("diagnostic log events", () => {
90100
unsubscribe();
91101

92102
expect(received).toHaveLength(1);
93-
expect(received[0]?.trace).toEqual(trace);
103+
expect(received[0]?.event.trace).toEqual(trace);
104+
expect(received[0]?.metadata.trusted).toBe(false);
105+
expect(received[0]?.metadata.trustedTraceContext).toBe(true);
94106
});
95107

96108
it("redacts and bounds internal log records before diagnostic emission", async () => {

‎src/logging/logger.ts‎

Lines changed: 36 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -4,7 +4,10 @@ import os from "node:os";
44
import path from "node:path";
55
import { Logger as TsLogger } from "tslog";
66
import type { OpenClawConfig } from "../config/types.js";
7-
import { emitDiagnosticEvent } from "../infra/diagnostic-events.js";
7+
import {
8+
emitDiagnosticEvent,
9+
emitDiagnosticEventWithTrustedTraceContext,
10+
} from "../infra/diagnostic-events.js";
811
import {
912
getActiveDiagnosticTraceContext,
1013
isValidDiagnosticSpanId,
@@ -359,9 +362,23 @@ function findLogTraceContext(
359362
return undefined;
360363
}
361364

365+
function resolveLogTraceContext(
366+
bindings: Record<string, unknown> | undefined,
367+
numericArgs: readonly unknown[],
368+
): { trace?: DiagnosticTraceContext; trustedTraceContext: boolean } {
369+
const explicitTrace = findLogTraceContext(bindings, numericArgs);
370+
if (explicitTrace) {
371+
return { trace: explicitTrace, trustedTraceContext: false };
372+
}
373+
const activeTrace = getActiveDiagnosticTraceContext();
374+
return activeTrace
375+
? { trace: activeTrace, trustedTraceContext: true }
376+
: { trustedTraceContext: false };
377+
}
378+
362379
function buildTraceFileLogFields(logObj: TsLogRecord): Record<string, string> | undefined {
363380
const { bindings, args } = extractLogBindingPrefix(getSortedNumericLogArgs(logObj));
364-
const trace = findLogTraceContext(bindings, args) ?? getActiveDiagnosticTraceContext();
381+
const { trace } = resolveLogTraceContext(bindings, args);
365382
if (!trace) {
366383
return undefined;
367384
}
@@ -410,7 +427,7 @@ function buildDiagnosticLogRecord(logObj: TsLogRecord) {
410427
| undefined;
411428
const { bindings, args: numericArgs } = extractLogBindingPrefix(getSortedNumericLogArgs(logObj));
412429

413-
const trace = findLogTraceContext(bindings, numericArgs) ?? getActiveDiagnosticTraceContext();
430+
const { trace, trustedTraceContext } = resolveLogTraceContext(bindings, numericArgs);
414431
const structuredArg = numericArgs[0];
415432
const structuredBindings = isPlainLogRecordObject(structuredArg) ? structuredArg : undefined;
416433
if (structuredBindings) {
@@ -456,14 +473,17 @@ function buildDiagnosticLogRecord(logObj: TsLogRecord) {
456473
.filter((name): name is string => Boolean(name));
457474

458475
return {
459-
type: "log.record" as const,
460-
level: meta?.logLevelName ?? "INFO",
461-
message,
462-
...(loggerName ? { loggerName } : {}),
463-
...(loggerParents?.length ? { loggerParents } : {}),
464-
...(Object.keys(attributes).length > 0 ? { attributes } : {}),
465-
...(Object.keys(code).length > 0 ? { code } : {}),
466-
...(trace ? { trace } : {}),
476+
event: {
477+
type: "log.record" as const,
478+
level: meta?.logLevelName ?? "INFO",
479+
message,
480+
...(loggerName ? { loggerName } : {}),
481+
...(loggerParents?.length ? { loggerParents } : {}),
482+
...(Object.keys(attributes).length > 0 ? { attributes } : {}),
483+
...(Object.keys(code).length > 0 ? { code } : {}),
484+
...(trace ? { trace } : {}),
485+
},
486+
trustedTraceContext,
467487
};
468488
}
469489

@@ -478,9 +498,11 @@ function redactLogRecordForTransport<T extends LogObj>(record: T): T {
478498
function attachDiagnosticEventTransport(logger: TsLogger<LogObj>): void {
479499
logger.attachTransport((logObj: LogObj) => {
480500
try {
481-
emitDiagnosticEvent(
482-
buildDiagnosticLogRecord(redactLogRecordForTransport(logObj) as TsLogRecord),
483-
);
501+
const record = buildDiagnosticLogRecord(redactLogRecordForTransport(logObj) as TsLogRecord);
502+
const emit = record.trustedTraceContext
503+
? emitDiagnosticEventWithTrustedTraceContext
504+
: emitDiagnosticEvent;
505+
emit(record.event);
484506
} catch {
485507
// never block on logging failures
486508
}

‎src/plugin-sdk/plugin-test-runtime.ts‎

Lines changed: 4 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -14,7 +14,10 @@ export {
1414
resolveWebSearchProviderContractEntriesForPluginId,
1515
} from "../plugins/contracts/registry.js";
1616
export { loadPluginManifestRegistry } from "../plugins/manifest-registry.js";
17-
export { emitInternalDiagnosticEvent as emitInternalDiagnosticEventForTest } from "../infra/diagnostic-events.js";
17+
export {
18+
emitDiagnosticEventWithTrustedTraceContext,
19+
emitInternalDiagnosticEvent as emitInternalDiagnosticEventForTest,
20+
} from "../infra/diagnostic-events.js";
1821
export { runWithDiagnosticTraceContext } from "../infra/diagnostic-trace-context.js";
1922
export { logMessageDispatchStarted, logMessageProcessed } from "../logging/diagnostic.js";
2023
export { resolveBundledExplicitProviderContractsFromPublicArtifacts } from "../plugins/provider-contract-public-artifacts.js";

0 commit comments

Comments
 (0)