From 48c24f51e7ebb69803d2ad7615749eae5fdd101b Mon Sep 17 00:00:00 2001 From: George Ng Date: Wed, 12 Aug 2026 01:20:32 -0700 Subject: [PATCH 01/13] [OTEL] Add structured log sink Add severity-aware Structured Logger events, bounded cycle-safe OTel body mapping, trace correlation, and defense-in-depth redaction. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> Copilot-Session: 67859676-8c6c-43f7-bfe4-ee784f8db79d --- .../architecture/telemetry/opentelemetry.md | 58 +- ts/packages/telemetry/src/indexNode.ts | 6 + ts/packages/telemetry/src/logger/logger.ts | 50 +- .../telemetry/src/logger/otelLoggerSink.ts | 603 ++++++++++ ts/packages/telemetry/test/logger.spec.ts | 150 +++ .../telemetry/test/otelLoggerSink.spec.ts | 1023 +++++++++++++++++ 6 files changed, 1884 insertions(+), 6 deletions(-) create mode 100644 ts/packages/telemetry/src/logger/otelLoggerSink.ts create mode 100644 ts/packages/telemetry/test/logger.spec.ts create mode 100644 ts/packages/telemetry/test/otelLoggerSink.spec.ts diff --git a/ts/docs/architecture/telemetry/opentelemetry.md b/ts/docs/architecture/telemetry/opentelemetry.md index 31ea7a8796..7c93f6a0c2 100644 --- a/ts/docs/architecture/telemetry/opentelemetry.md +++ b/ts/docs/architecture/telemetry/opentelemetry.md @@ -3,7 +3,7 @@ # OpenTelemetry in TypeAgent -**Status:** Settled design; implementation pending +**Status:** Settled design; implementation is landing in phases **Area:** `@typeagent/telemetry`, `aiclient`, dispatcher, RPC, and TypeAgent-owned Node hosts @@ -106,6 +106,11 @@ Logs require explicit composition: - Install the debug bridge to copy enabled TypeAgent debug output. - Installing an OTel SDK alone does neither. +The logger severity contract and `OtelLoggerSink` in this PR are library +foundation only. They do not attach the sink to a runtime logger or configure a +provider. A later host-wiring PR performs that composition in TypeAgent-owned +Node hosts. + The sink emits through the host's global Logs API and does not create a provider. Embeddable libraries never install a process-wide debug hook. A partner may install the adapter at its composition root and identify each `debug` module @@ -159,6 +164,50 @@ OTel body. It adds `eventName` and allowlisted scalar correlation attributes, but excludes nested or unbounded attributes. Existing debug and database sinks remain attached. +The Structured Logger `Logger.logEvent(eventName, entry, severity?)` contract +carries an optional severity of `info`, `warning`, or `error`. `OtelLoggerSink` +maps these onto the standard OTel severity buckets (`INFO`, `WARN`, `ERROR`); +`undefined` defaults to `INFO`. The sink never infers severity from the event +name or the event payload - the caller is the only signal. + +Before emit, the sink snapshots `LogEvent.event` with three bounds so a +misbehaving producer cannot hang or overflow the telemetry path: + +- **Depth** is a deterministic hard cap (currently 32). Nodes at depths 0 + through 31 are preserved; a node at depth 32 is replaced with a truncation + marker. +- **Cycles** are broken by a WeakSet-tracked visited path. A repeat visit within + the same recursion becomes a `cycle` truncation marker. +- **Allocation size** has an approximate cap (currently 60 KiB, measured in + UTF-16 code units as the walker descends). When the next value would exceed + the cap, that value and subsequent subtrees are replaced with a `size` + truncation marker. +- **Serialized size** has a hard cap (currently 64 KiB of UTF-8 JSON after + redaction). If the final body exceeds the cap or cannot be serialized, the + complete body is replaced with a root-level `size` marker. + +A truncated subtree is +`{"__typeagent_otel_truncated": "depth" | "cycle" | "size" | "unsupported"}`. +The `unsupported` marker replaces values outside the Structured Logger's +JSON-compatible contract. The sink always prefers a bounded/truncated body over +dropping the whole record. + +The OTel event name and each promoted correlation value are limited to 256 +Unicode code points. An oversized event name becomes a fixed marker, and an +oversized correlation value is omitted. The sink does not retain a prefix: +partial truncation could expose part of a secret that the complete value would +have matched. Redaction runs only after this bound and the result must also fit. + +Producers sanitize prompts, responses, user content, and PII at the source; +the sink applies known-secret and secret-format filtering as defense in depth, +covering the promoted correlation attributes and every string reachable in the +snapshotted body. + +Emit failures are isolated: the sink drops the OTel record and never re-enters +the `MultiSinkLogger` fan-out. Drop and error accounting is deliberately silent +in this PR; a follow-up PR wires a non-recursive diagnostics channel that +reports these events without looping back through the sink. + The debug bridge tees enabled `typeagent:*` calls into OTel without changing their original output: @@ -308,8 +357,13 @@ additive. A JSONL-only configuration creates only the logs provider. - Do not capture prompts, responses, user content, or known secrets by default. - Gate sensitive development capture behind an explicit setting. +- Sanitize data at the producer before creating a TypeAgent log record. The + producer decides whether content is appropriate to record; sink-level secret + filtering cannot make arbitrary prompts, responses, user content, or PII + safe to export. - Apply `filterSecrets`, `filterSecretsFromObject`, and registered - `SecretFilter` values before creating TypeAgent log records. + `SecretFilter` values at the OTel sink as defense in depth for recognizable + and registered secrets. - Filter non-allowlisted TypeAgent span attributes before `setAttribute()`. - Never put user content or secrets in metric attributes. diff --git a/ts/packages/telemetry/src/indexNode.ts b/ts/packages/telemetry/src/indexNode.ts index b0e0bee2c2..24540d64e9 100644 --- a/ts/packages/telemetry/src/indexNode.ts +++ b/ts/packages/telemetry/src/indexNode.ts @@ -7,6 +7,7 @@ export { ChildLogger, MultiSinkLogger, LogEvent, + LogEventSeverity, CosmosContainerClient, CosmosContainerClientFactory, CosmosPartitionKeyBuilder, @@ -25,6 +26,11 @@ export { DatabaseLoggerSinkOptions, } from "./logger/databaseLoggerSink.js"; export { createDebugLoggerSink } from "./logger/debugLoggerSink.js"; +export { + OtelLoggerSink, + OtelLoggerSinkOptions, + createOtelLoggerSink, +} from "./logger/otelLoggerSink.js"; export { PromptLogger, PromptLoggerOptions, diff --git a/ts/packages/telemetry/src/logger/logger.ts b/ts/packages/telemetry/src/logger/logger.ts index abe21408e9..7ba2cf6512 100644 --- a/ts/packages/telemetry/src/logger/logger.ts +++ b/ts/packages/telemetry/src/logger/logger.ts @@ -1,20 +1,50 @@ // Copyright (c) Microsoft Corporation. // Licensed under the MIT License. +/** + * Severity level attached to a Structured Logger event. The set is + * deliberately small (`info`, `warning`, `error`) so it maps cleanly onto + * the OTel Logs severity buckets without inference from the event name or + * payload. Callers omit the parameter for the default `info` case. + */ +export type LogEventSeverity = "info" | "warning" | "error"; + export type LogEvent = { eventName: string; timestamp: string; event: LogEventData; + /** + * Optional for compatibility with events constructed directly for a + * sink. A missing value means `info`. `MultiSinkLogger` materializes + * that default on the event it sends to its sinks. + */ + severity?: LogEventSeverity; }; export interface LogEventData { [key: string]: any; } export interface Logger { - logEvent(eventName: string, entry: T): void; + /** + * Record a Structured Logger event. + * + * `severity` is optional and defaults to `info` at every sink that + * carries a severity concept. Sinks must not infer severity from the + * event name or from the payload; the caller is the only signal. + */ + logEvent( + eventName: string, + entry: T, + severity?: LogEventSeverity, + ): void; } export interface LoggerSink { + /** + * Consume one event. The outer `LogEvent` wrapper is sink-local, but + * its caller-owned `event` payload may be shared with sibling sinks. + * Treat the payload as read-only. + */ logEvent(event: LogEvent): void; } @@ -24,7 +54,11 @@ export class ChildLogger implements Logger { private readonly name?: string, private readonly commonProperties?: LogEventData, ) {} - public logEvent(eventName: string, entry: T) { + public logEvent( + eventName: string, + entry: T, + severity: LogEventSeverity = "info", + ) { const event: LogEventData = {}; if (this.commonProperties) { for (const [key, value] of Object.entries(this.commonProperties)) { @@ -33,7 +67,7 @@ export class ChildLogger implements Logger { } Object.assign(event, entry); const name = this.name ? `${this.name}:${eventName}` : eventName; - this.parent.logEvent(name, event); + this.parent.logEvent(name, event, severity); } } @@ -42,12 +76,20 @@ export class MultiSinkLogger implements Logger { public addSink(sink: LoggerSink) { this.sinks.push(sink); } - public logEvent(eventName: string, event: T) { + public logEvent( + eventName: string, + event: T, + severity: LogEventSeverity = "info", + ) { for (const sink of this.sinks) { + // Preserve the existing per-sink wrapper isolation. A sink may + // mutate its LogEvent wrapper without changing what later sinks + // observe; the caller-owned payload remains shared as before. sink.logEvent({ eventName, timestamp: new Date().toISOString(), event, + severity, }); } } diff --git a/ts/packages/telemetry/src/logger/otelLoggerSink.ts b/ts/packages/telemetry/src/logger/otelLoggerSink.ts new file mode 100644 index 0000000000..6aefcee504 --- /dev/null +++ b/ts/packages/telemetry/src/logger/otelLoggerSink.ts @@ -0,0 +1,603 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +import { context as otelContext, type Context } from "@opentelemetry/api"; +import { + logs, + SeverityNumber, + type Logger as OtelApiLogger, + type LogRecord as OtelLogRecord, +} from "@opentelemetry/api-logs"; +import { Buffer } from "node:buffer"; + +import type { + LogEvent, + LogEventData, + LogEventSeverity, + LoggerSink, +} from "./logger.js"; +import { + INSTRUMENTATION_SCOPE_NAME, + INSTRUMENTATION_SCOPE_VERSION, +} from "../otel/instrumentation.js"; +import { TYPEAGENT_SPAN_ATTRIBUTES } from "../otel/traceContract.js"; +import { + redactObject, + redactText, + type RedactionOptions, +} from "../otel/redaction.js"; + +/** + * Options for {@link createOtelLoggerSink} / {@link OtelLoggerSink}. + * + * The sink pulls its logger from the global OTel logs API on demand; it + * never owns or configures a provider. The only knob currently exposed is + * a shared {@link RedactionOptions} secret filter that is threaded through + * every redaction call the sink makes. This filtering is defense in depth: + * producers remain responsible for excluding prompts, responses, user + * content, PII, and other data that is not appropriate to record. See + * `docs/architecture/telemetry/opentelemetry.md` for the privacy contract. + */ +export type OtelLoggerSinkOptions = RedactionOptions; + +/** + * Top-level string fields on `LogEvent.event` that are promoted to + * well-known OTel log attributes. Order is stable so tests can assert on + * the produced attribute bag deterministically. + * + * Only these keys are promoted. Everything else on `event.event` stays in + * the log body. `traceId` here is the caller's legacy correlation id; the + * canonical OTel trace id is derived by the SDK from the active context. + */ +const CORRELATION_FIELDS: ReadonlyArray< + readonly [keyof LogEventData & string, string] +> = [ + ["sessionId", TYPEAGENT_SPAN_ATTRIBUTES.SESSION_ID], + ["activationId", TYPEAGENT_SPAN_ATTRIBUTES.ACTIVATION_ID], + ["traceId", TYPEAGENT_SPAN_ATTRIBUTES.TRACE_ID], +]; + +/** + * Maximum object/array nesting depth the sink preserves when snapshotting + * the caller's payload. Deterministic bound: an entry sitting at depth + * greater than or equal to this value is replaced with + * {@link TRUNCATION_MARKER} carrying `depth`. Root is depth 0, its direct + * children are depth 1, etc. Chosen high enough that any realistic + * TypeAgent event (`ActionResult`, cache hit, translation, reasoning tool + * call) fits comfortably, but low enough that a runaway self-referential + * or generator-produced tree cannot exhaust the call stack. + */ +const BODY_MAX_DEPTH = 32; + +/** + * Approximate allocation cap for the snapshotted body, measured in UTF-16 + * code units as the sink walks the payload. JSON punctuation and escaped + * string lengths are included, but truncation markers and values that JSON + * does not represent directly can make the final serialized size differ. + * Once the running estimate would exceed the cap, the current and + * subsequent subtrees are replaced with a `size` marker. + */ +const BODY_MAX_APPROX_CHARS = 60 * 1024; + +/** + * Hard cap on the UTF-8 byte length of the JSON-serialized, redacted body. + * The final check catches multi-byte text, redaction expansion, and any + * difference from the traversal estimate. If the body exceeds this limit + * or cannot be serialized, the body becomes a root-level `size` marker so + * the OTel event is still emitted. + */ +const BODY_MAX_SERIALIZED_BYTES = 64 * 1024; + +/** Maximum Unicode code points retained in an OTel event name. */ +const EVENT_NAME_MAX_LENGTH = 256; + +/** Maximum Unicode code points retained in a promoted correlation value. */ +const CORRELATION_VALUE_MAX_LENGTH = 256; + +const TRUNCATED_EVENT_NAME = "typeagent.truncated_event_name"; + +/** + * Marker key attached to the truncated subtree when the sink refuses to + * preserve a payload node. The value is the reason so a reader can tell + * which limit was reached without cross-referencing constants. + */ +const TRUNCATION_MARKER_KEY = "__typeagent_otel_truncated"; + +type TruncationReason = "depth" | "cycle" | "size" | "unsupported"; + +function truncationMarker(reason: TruncationReason): Record { + return { [TRUNCATION_MARKER_KEY]: reason }; +} + +const TRUNCATION_MARKER_APPROX_CHARS: Readonly< + Record, number> +> = { + depth: JSON.stringify(truncationMarker("depth")).length, + cycle: JSON.stringify(truncationMarker("cycle")).length, + unsupported: JSON.stringify(truncationMarker("unsupported")).length, +}; + +/** + * Map a Structured Logger severity onto the OTel severity buckets. The + * sink never infers severity from the event name or from the payload; + * `undefined` (the caller-side default) becomes INFO here, matching the + * `Logger` contract documented in `logger.ts`. + */ +function mapSeverity(severity: LogEventSeverity | undefined): { + severityNumber: SeverityNumber; + severityText: "INFO" | "WARN" | "ERROR"; +} { + switch (severity) { + case "warning": + return { + severityNumber: SeverityNumber.WARN, + severityText: "WARN", + }; + case "error": + return { + severityNumber: SeverityNumber.ERROR, + severityText: "ERROR", + }; + case "info": + case undefined: + return { + severityNumber: SeverityNumber.INFO, + severityText: "INFO", + }; + default: { + // Exhaustiveness: an unknown severity string is safer as + // INFO than as a runtime throw from the telemetry path. + const _exhaustive: never = severity; + void _exhaustive; + return { + severityNumber: SeverityNumber.INFO, + severityText: "INFO", + }; + } + } +} + +/** + * A {@link LoggerSink} that forwards Structured Logger events as OTel log + * records via the global `@opentelemetry/api-logs` API. + * + * Contract: + * + * - Own no provider, processor, exporter, flush, or shutdown. The sink + * only reads the global logs API. + * - Never throw from `logEvent`. Failures (missing provider, misbehaving + * redaction, broken logger implementation, etc.) drop the OTel record + * only. No debug or Structured Logger calls happen in the catch, so + * the sink cannot recurse through a sibling sink. A follow-up PR wires + * a non-recursive diagnostics path that reports drops and errors; this + * PR keeps the surface silent to preserve the isolation guarantee. + * - Never mutate the caller's `LogEvent.event`; the emitted body is a + * detached snapshot produced by {@link boundedSnapshot} so a sibling + * sink still sees the original. The snapshot bounds depth + * ({@link BODY_MAX_DEPTH}, deterministic), cycles (WeakSet-based), and + * approximate allocation size ({@link BODY_MAX_APPROX_CHARS}). The + * redacted result also has a hard serialized UTF-8 limit + * ({@link BODY_MAX_SERIALIZED_BYTES}). When any bound is reached the + * offending subtree, or the root for the final byte check, is replaced with + * {@link TRUNCATION_MARKER_KEY} carrying `depth`, `cycle`, `size`, or + * `unsupported` instead of dropping the record. + * - Redact every string that reaches OTel through `redactText` / + * `redactObject`, including the promoted correlation attributes. This + * catches recognizable and registered secrets but does not make an + * arbitrary event body safe to export; producers sanitize content first. + * - Promote only non-empty root-level string fields listed in + * {@link CORRELATION_FIELDS}. Nested or non-string values stay in the + * body only. + * - Attach the OTel context active at emit time so the SDK derives the + * canonical trace/span ids. `LogEvent.timestamp` (the canonical + * Structured Logger timestamp produced by `Date.prototype.toISOString`) + * becomes the record timestamp; anything else is dropped from the + * record (the SDK defaults `hrTime`), never the record itself. Observed + * timestamp is left for the SDK to fill in. + * - Severity is read from `LogEvent.severity` and mapped by + * {@link mapSeverity}. `undefined` maps to INFO. The sink never infers + * severity from the event name or the payload. + * + * The sink does not cache the acquired OTel logger between calls. The + * pinned `@opentelemetry/api-logs` (0.221.0) `LogsAPI.getLogger()` is + * already a cheap `getLoggerProvider().getLogger(name, version)` lookup, + * and re-acquiring on every emit is what makes late provider registration + * *and* global provider replacement (e.g. `logs.disable()` followed by + * `setGlobalLoggerProvider(...)`) transparent to a sink created earlier. + * + * This class is the library foundation only. A later host-wiring PR + * composes it into TypeAgent-owned runtimes and configures providers. + */ +export class OtelLoggerSink implements LoggerSink { + private readonly options: OtelLoggerSinkOptions | undefined; + + constructor(options?: OtelLoggerSinkOptions) { + this.options = options; + } + + public logEvent(event: LogEvent): void { + try { + const logger = this.acquireLogger(); + if (logger === undefined) { + return; + } + + const activeContext = otelContext.active(); + const { severityNumber, severityText } = mapSeverity( + event.severity, + ); + + // A no-provider ProxyLogger reports `enabled() === false`, so + // this call is what preserves the no-provider guarantee and + // also skips work when a real provider is off. Guarded so a + // broken `enabled()` implementation still drops only this + // record. The enabled fast path runs before we build the + // snapshot, so a disabled provider costs nothing beyond the + // logger lookup and the (cheap) check. + if (!isLoggerEnabled(logger, activeContext, severityNumber)) { + return; + } + + const eventName = + sanitizeBoundedText( + event.eventName, + this.options, + EVENT_NAME_MAX_LENGTH, + ) ?? TRUNCATED_EVENT_NAME; + // Bounded, cycle-safe snapshot of the caller's payload before + // redaction. Guarantees an acyclic, depth-limited tree so the + // downstream `redactObject` recursion cannot hang or overflow + // regardless of what the caller passed. + const snapshot = boundedSnapshot(event.event); + // `redactObject` rebuilds every reachable container when it + // finds a string to redact, but short-circuits back to the + // caller's own reference when the payload has no strings. + // The bounded snapshot is already detached from the caller, + // so short-circuiting to it is safe. + const redactedBody: LogEventData = redactObject( + snapshot, + this.options, + ); + const body = enforceSerializedBodyLimit(redactedBody); + const attributes = collectCorrelationAttributes( + event.event, + this.options, + ); + const timestamp = parseTimestamp(event.timestamp); + + const record: OtelLogRecord = { + context: activeContext, + severityNumber, + severityText, + eventName, + body, + attributes, + ...(timestamp === undefined ? {} : { timestamp }), + }; + + logger.emit(record); + } catch { + // Failure isolation: never let a telemetry-side error escape + // into the caller. Intentionally no debug/logger call - that + // would recurse through the sibling sinks that share the same + // `MultiSinkLogger`. PR2 introduces a non-recursive + // diagnostics channel that reports these drops and errors. + } + } + + private acquireLogger(): OtelApiLogger | undefined { + try { + return logs.getLogger( + INSTRUMENTATION_SCOPE_NAME, + INSTRUMENTATION_SCOPE_VERSION, + ); + } catch { + return undefined; + } + } +} + +/** Factory that mirrors the other sinks in this package. */ +export function createOtelLoggerSink( + options?: OtelLoggerSinkOptions, +): OtelLoggerSink { + return new OtelLoggerSink(options); +} + +function isLoggerEnabled( + logger: OtelApiLogger, + activeContext: Context, + severityNumber: SeverityNumber, +): boolean { + try { + return logger.enabled({ + context: activeContext, + severityNumber, + }); + } catch { + return false; + } +} + +function collectCorrelationAttributes( + event: LogEventData | undefined, + options: OtelLoggerSinkOptions | undefined, +): Record { + const attributes: Record = {}; + if (event === null || typeof event !== "object") { + return attributes; + } + const source = event as Record; + for (const [sourceKey, attributeKey] of CORRELATION_FIELDS) { + const raw = source[sourceKey]; + if (typeof raw !== "string" || raw.length === 0) { + continue; + } + const redacted = sanitizeBoundedText( + raw, + options, + CORRELATION_VALUE_MAX_LENGTH, + ); + if (redacted === undefined || redacted.length === 0) { + continue; + } + attributes[attributeKey] = redacted; + } + return attributes; +} + +function sanitizeBoundedText( + text: string, + options: OtelLoggerSinkOptions | undefined, + maxLength: number, +): string | undefined { + if (exceedsCodePointLimit(text, maxLength)) { + return undefined; + } + const redacted = redactText(text, options); + return exceedsCodePointLimit(redacted, maxLength) ? undefined : redacted; +} + +function exceedsCodePointLimit(text: string, maxLength: number): boolean { + if (text.length <= maxLength) { + return false; + } + let count = 0; + for (const _codePoint of text) { + count++; + if (count > maxLength) { + return true; + } + } + return false; +} + +/** + * State threaded through the bounded traversal so cycle, depth, and + * approximate size limits can be enforced without a second pass. + * + * `visited` blocks reference cycles: an object is added before its + * children are cloned and removed after; a repeat visit within the same + * recursion path becomes a `cycle` marker. `approxChars` is the running + * estimate of the eventual JSON-serialized length, charged as the walker + * descends. `sizeTruncated` latches when the next charge would exceed + * {@link BODY_MAX_APPROX_CHARS} so any remaining subtree short-circuits + * to a `size` marker instead of continuing to allocate. + */ +interface BoundedTraversalState { + visited: WeakSet; + approxChars: number; + sizeTruncated: boolean; +} + +/** + * Produce a detached JSON-compatible clone of `value` bounded by + * {@link BODY_MAX_DEPTH}, cycle-safe via a WeakSet, and approximately + * bounded in serialized size by {@link BODY_MAX_APPROX_CHARS}. Nodes that + * hit a limit are replaced with a {@link TRUNCATION_MARKER_KEY}-tagged + * marker instead of dropping the record. JSON primitives pass through; + * arrays and plain objects are detached into JSON-compatible containers. + * Values outside the Structured Logger's JSON-compatible contract become + * `unsupported` markers instead of reaching the OTel SDK in an invalid body. + */ +function boundedSnapshot(value: LogEventData | undefined): LogEventData { + const state: BoundedTraversalState = { + visited: new WeakSet(), + approxChars: 0, + sizeTruncated: false, + }; + // Root is a plain-object `LogEventData` per the Structured Logger + // contract; falling through the object branch preserves that shape + // in the returned snapshot. A missing or non-object root would be a + // caller bug elsewhere in the pipeline; we still return an empty + // object so the record shape stays predictable. + if (value === null || typeof value !== "object") { + return {}; + } + const cloned = cloneBounded(value, 0, state) as LogEventData; + return cloned; +} + +function cloneBounded( + value: unknown, + depth: number, + state: BoundedTraversalState, +): unknown { + // Once the size cap has been crossed, everything downstream becomes + // a marker so partial containers stop growing. + if (state.sizeTruncated) { + return truncationMarker("size"); + } + + if (depth >= BODY_MAX_DEPTH) { + return boundedMarker("depth", state); + } + + // JSON-compatible primitives. + if ( + value === null || + typeof value === "string" || + typeof value === "boolean" || + (typeof value === "number" && Number.isFinite(value)) + ) { + if (!tryCharge(state, approxPrimitiveChars(value))) { + return truncationMarker("size"); + } + return value; + } + if (typeof value !== "object") { + return boundedMarker("unsupported", state); + } + + // Cycles. + if (state.visited.has(value as object)) { + return boundedMarker("cycle", state); + } + + state.visited.add(value as object); + try { + if (Array.isArray(value)) { + if (!tryCharge(state, 2)) { + return [truncationMarker("size")]; + } + const result: unknown[] = []; + for (let i = 0; i < value.length; i++) { + if (state.sizeTruncated) { + result.push(truncationMarker("size")); + break; + } + if (i > 0 && !tryCharge(state, 1)) { + result.push(truncationMarker("size")); + break; + } + result.push(cloneBounded(value[i], depth + 1, state)); + if (state.sizeTruncated) { + break; + } + } + return result; + } + + const prototype = Object.getPrototypeOf(value); + if (prototype !== Object.prototype && prototype !== null) { + return boundedMarker("unsupported", state); + } + + const source = value as Record; + const clone: Record = {}; + if (!tryCharge(state, 2)) { + setOwnValue(clone, TRUNCATION_MARKER_KEY, "size"); + return clone; + } + let first = true; + for (const [key, item] of Object.entries(source)) { + if (state.sizeTruncated) { + setOwnValue(clone, TRUNCATION_MARKER_KEY, "size"); + break; + } + const propertyChars = + (first ? 0 : 1) + approxPrimitiveChars(key) + 1; + if (!tryCharge(state, propertyChars)) { + setOwnValue(clone, TRUNCATION_MARKER_KEY, "size"); + break; + } + first = false; + setOwnValue(clone, key, cloneBounded(item, depth + 1, state)); + if (state.sizeTruncated) { + break; + } + } + return clone; + } finally { + state.visited.delete(value as object); + } +} + +function boundedMarker( + reason: Exclude, + state: BoundedTraversalState, +): Record { + if (!tryCharge(state, TRUNCATION_MARKER_APPROX_CHARS[reason])) { + return truncationMarker("size"); + } + return truncationMarker(reason); +} + +function setOwnValue( + target: Record, + key: string, + value: unknown, +): void { + Object.defineProperty(target, key, { + value, + enumerable: true, + configurable: true, + writable: true, + }); +} + +function tryCharge(state: BoundedTraversalState, chars: number): boolean { + if (state.approxChars + chars > BODY_MAX_APPROX_CHARS) { + state.sizeTruncated = true; + return false; + } + state.approxChars += chars; + return true; +} + +function approxPrimitiveChars(value: unknown): number { + if (typeof value === "string") { + // JSON.stringify gives the exact escaped UTF-16 length for a JSON + // string token without serializing the surrounding body. + return JSON.stringify(value).length; + } + if (typeof value === "number" || typeof value === "boolean") { + return String(value).length; + } + // null + return 4; +} + +function enforceSerializedBodyLimit(body: LogEventData): LogEventData { + try { + const serialized = JSON.stringify(body); + if ( + serialized !== undefined && + Buffer.byteLength(serialized, "utf8") <= BODY_MAX_SERIALIZED_BYTES + ) { + return body; + } + } catch { + // An unexpected non-JSON value (for example bigint) should not + // drop the OTel record. Replace the body with the bounded marker. + } + return truncationMarker("size"); +} + +/** + * Parse `LogEvent.timestamp` (the canonical Structured Logger timestamp, + * produced by `Date.prototype.toISOString()`) into a millisecond epoch + * that OTel accepts as `TimeInput`. + * + * Only strings that round-trip exactly through + * `new Date(timestamp).toISOString()` are accepted; anything else - + * invalid ISO, non-canonical form, rolled-over dates like + * `2024-02-30T00:00:00.000Z` - returns `undefined`. The caller drops the + * timestamp field only, not the whole record: the SDK then fills `hrTime` + * from `Date.now()`, which is a better signal than losing the event + * entirely. + */ +function parseTimestamp(timestamp: unknown): number | undefined { + if (typeof timestamp !== "string" || timestamp.length === 0) { + return undefined; + } + const date = new Date(timestamp); + const ms = date.getTime(); + if (!Number.isFinite(ms)) { + return undefined; + } + if (date.toISOString() !== timestamp) { + return undefined; + } + return ms; +} diff --git a/ts/packages/telemetry/test/logger.spec.ts b/ts/packages/telemetry/test/logger.spec.ts new file mode 100644 index 0000000000..4ead8ea24d --- /dev/null +++ b/ts/packages/telemetry/test/logger.spec.ts @@ -0,0 +1,150 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +import { + ChildLogger, + MultiSinkLogger, + type LogEvent, + type LogEventSeverity, + type Logger, + type LoggerSink, +} from "../src/logger/logger.js"; + +/** + * Minimal recording sink so the tests can assert on the actual + * `LogEvent` values that reached the fan-out edge, including severity. + */ +class RecordingSink implements LoggerSink { + public events: LogEvent[] = []; + public logEvent(event: LogEvent): void { + this.events.push(event); + } +} + +class RecordingLogger implements Logger { + public calls: Array<{ + eventName: string; + entry: Record; + severity: LogEventSeverity | undefined; + }> = []; + public logEvent>( + eventName: string, + entry: T, + severity?: LogEventSeverity, + ): void { + this.calls.push({ eventName, entry, severity }); + } +} + +describe("MultiSinkLogger", () => { + it("fans out to every sink with the caller's severity", () => { + const a = new RecordingSink(); + const b = new RecordingSink(); + const logger = new MultiSinkLogger([a, b]); + + logger.logEvent("boot", { ready: true }, "warning"); + + for (const sink of [a, b]) { + expect(sink.events).toHaveLength(1); + const [event] = sink.events; + expect(event.eventName).toBe("boot"); + expect(event.event).toEqual({ ready: true }); + expect(event.severity).toBe("warning"); + expect(typeof event.timestamp).toBe("string"); + } + }); + + it("gives each sink an independent LogEvent wrapper", () => { + const observed: LogEvent[] = []; + const mutatingSink: LoggerSink = { + logEvent(event) { + event.eventName = "mutated"; + event.severity = "error"; + }, + }; + const recordingSink: LoggerSink = { + logEvent(event) { + observed.push(event); + }, + }; + const logger = new MultiSinkLogger([mutatingSink, recordingSink]); + + logger.logEvent("original", { ready: true }, "warning"); + + expect(observed).toHaveLength(1); + expect(observed[0]!.eventName).toBe("original"); + expect(observed[0]!.severity).toBe("warning"); + }); + + it("defaults severity to info when the caller doesn't pass one", () => { + const sink = new RecordingSink(); + const logger = new MultiSinkLogger([sink]); + logger.logEvent("boot", { ready: true }); + + expect(sink.events).toHaveLength(1); + expect(sink.events[0]!.severity).toBe("info"); + }); + + it("addSink adds a sink that receives subsequent events", () => { + const initial = new RecordingSink(); + const later = new RecordingSink(); + const logger = new MultiSinkLogger([initial]); + logger.logEvent("first", { n: 1 }, "info"); + logger.addSink(later); + logger.logEvent("second", { n: 2 }, "error"); + + expect(initial.events.map((event) => event.eventName)).toEqual([ + "first", + "second", + ]); + expect(later.events.map((event) => event.eventName)).toEqual([ + "second", + ]); + expect(later.events[0]!.severity).toBe("error"); + }); +}); + +describe("ChildLogger", () => { + it("forwards severity to the parent logger", () => { + const parent = new RecordingLogger(); + const child = new ChildLogger(parent, "child"); + + child.logEvent("hit", { count: 1 }, "error"); + + expect(parent.calls).toHaveLength(1); + const [call] = parent.calls; + expect(call.eventName).toBe("child:hit"); + expect(call.entry).toEqual({ count: 1 }); + expect(call.severity).toBe("error"); + }); + + it("defaults severity to info before forwarding to the parent", () => { + const parent = new RecordingLogger(); + const child = new ChildLogger(parent, "child"); + + child.logEvent("hit", { count: 1 }); + + expect(parent.calls).toHaveLength(1); + expect(parent.calls[0]!.severity).toBe("info"); + }); + + it("merges common properties without dropping severity", () => { + const parent = new RecordingLogger(); + const child = new ChildLogger(parent, undefined, { + host: "test-host", + build: () => "v1", + }); + + child.logEvent("hit", { count: 2 }, "warning"); + + expect(parent.calls).toHaveLength(1); + const [call] = parent.calls; + expect(call.eventName).toBe("hit"); + expect(call.entry).toEqual({ + host: "test-host", + build: "v1", + count: 2, + }); + expect(call.severity).toBe("warning"); + }); +}); diff --git a/ts/packages/telemetry/test/otelLoggerSink.spec.ts b/ts/packages/telemetry/test/otelLoggerSink.spec.ts new file mode 100644 index 0000000000..88e99415ff --- /dev/null +++ b/ts/packages/telemetry/test/otelLoggerSink.spec.ts @@ -0,0 +1,1023 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +import { + context as otelContext, + trace, + ROOT_CONTEXT, +} from "@opentelemetry/api"; +import { + logs, + SeverityNumber, + type LogRecord as OtelLogRecord, +} from "@opentelemetry/api-logs"; +import { + InMemoryLogRecordExporter, + LoggerProvider, + SimpleLogRecordProcessor, + type ReadableLogRecord, +} from "@opentelemetry/sdk-logs"; +import { AsyncLocalStorageContextManager } from "@opentelemetry/context-async-hooks"; +import { NodeTracerProvider } from "@opentelemetry/sdk-trace-node"; +import { + InMemorySpanExporter, + SimpleSpanProcessor, +} from "@opentelemetry/sdk-trace-base"; + +import { createSecretFilter } from "@typeagent/common-utils"; + +import { + createOtelLoggerSink, + OtelLoggerSink, +} from "../src/logger/otelLoggerSink.js"; +import { + MultiSinkLogger, + type LogEvent, + type LoggerSink, +} from "../src/logger/logger.js"; +import { + INSTRUMENTATION_SCOPE_NAME, + INSTRUMENTATION_SCOPE_VERSION, +} from "../src/otel/instrumentation.js"; +import { TYPEAGENT_SPAN_ATTRIBUTES } from "../src/otel/traceContract.js"; + +interface LogFixture { + exporter: InMemoryLogRecordExporter; + provider: LoggerProvider; +} + +interface TraceFixture { + exporter: InMemorySpanExporter; + provider: NodeTracerProvider; +} + +/** + * Install a fresh OTel logs SDK backed by an in-memory exporter as the + * process-global provider. Every spec that installs one calls the paired + * `disposeLogFixture` in its own `afterEach` so the next spec sees clean + * globals. + */ +function installLogFixture(): LogFixture { + const exporter = new InMemoryLogRecordExporter(); + const provider = new LoggerProvider({ + processors: [new SimpleLogRecordProcessor({ exporter })], + }); + logs.setGlobalLoggerProvider(provider); + return { exporter, provider }; +} + +async function disposeLogFixture( + fixture: LogFixture | undefined, +): Promise { + if (fixture === undefined) { + return; + } + try { + await fixture.provider.forceFlush(); + } catch { + // ignore + } + try { + await fixture.provider.shutdown(); + } catch { + // ignore + } + logs.disable(); +} + +function installTraceFixture(): TraceFixture { + const exporter = new InMemorySpanExporter(); + const provider = new NodeTracerProvider({ + spanProcessors: [new SimpleSpanProcessor(exporter)], + }); + // Install a context manager so `startActiveSpan` actually propagates + // through the emitting code. Skip a global propagator - the sink + // relies only on `context.active()`. + const contextManager = new AsyncLocalStorageContextManager(); + otelContext.setGlobalContextManager(contextManager.enable()); + trace.setGlobalTracerProvider(provider); + return { exporter, provider }; +} + +async function disposeTraceFixture( + fixture: TraceFixture | undefined, +): Promise { + if (fixture === undefined) { + return; + } + try { + await fixture.provider.forceFlush(); + } catch { + // ignore + } + try { + await fixture.provider.shutdown(); + } catch { + // ignore + } + trace.disable(); + otelContext.disable(); +} + +function baseEvent(overrides?: Partial): LogEvent { + return { + eventName: "test.event", + timestamp: "2024-06-01T12:34:56.000Z", + event: {}, + ...overrides, + }; +} + +describe("OtelLoggerSink", () => { + let logFixture: LogFixture | undefined; + let traceFixture: TraceFixture | undefined; + + afterEach(async () => { + await disposeLogFixture(logFixture); + logFixture = undefined; + await disposeTraceFixture(traceFixture); + traceFixture = undefined; + }); + + it("maps a Structured Logger event to a complete OTel log record", () => { + logFixture = installLogFixture(); + const sink = createOtelLoggerSink(); + + sink.logEvent( + baseEvent({ + eventName: "translation.completed", + timestamp: "2024-06-01T12:34:56.789Z", + event: { + sessionId: "sess-1", + activationId: "act-1", + traceId: "trace-1", + stage: "translate", + tokens: 123, + }, + }), + ); + + const records = logFixture.exporter.getFinishedLogRecords(); + expect(records).toHaveLength(1); + const record = records[0]!; + + expect(record.eventName).toBe("translation.completed"); + expect(record.severityNumber).toBe(SeverityNumber.INFO); + expect(record.severityText).toBe("INFO"); + expect(record.instrumentationScope.name).toBe( + INSTRUMENTATION_SCOPE_NAME, + ); + expect(record.instrumentationScope.version).toBe( + INSTRUMENTATION_SCOPE_VERSION, + ); + expect(record.body).toEqual({ + sessionId: "sess-1", + activationId: "act-1", + traceId: "trace-1", + stage: "translate", + tokens: 123, + }); + // `hrTime` = [seconds, nanos]. 2024-06-01T12:34:56.789Z is + // 1717245296.789 seconds since the epoch. + expect(record.hrTime[0]).toBe(1717245296); + expect(record.hrTime[1]).toBe(789_000_000); + expect(record.hrTimeObserved[0]).toBeGreaterThan(0); + }); + + it("promotes only the allowlisted top-level string correlation fields", () => { + logFixture = installLogFixture(); + const sink = createOtelLoggerSink(); + + sink.logEvent( + baseEvent({ + event: { + sessionId: "sess-2", + activationId: "act-2", + traceId: "trace-2", + // Ignored: nested container (structure, not a scalar). + nested: { sessionId: "nested-sess" }, + // Ignored: not on the allowlist. + userText: "hello", + // Ignored: empty string. + emptyField: "", + // Ignored: non-string type. + count: 42, + }, + }), + ); + + const record = logFixture.exporter.getFinishedLogRecords()[0]!; + expect(record.attributes).toEqual({ + [TYPEAGENT_SPAN_ATTRIBUTES.SESSION_ID]: "sess-2", + [TYPEAGENT_SPAN_ATTRIBUTES.ACTIVATION_ID]: "act-2", + [TYPEAGENT_SPAN_ATTRIBUTES.TRACE_ID]: "trace-2", + }); + // No smuggled keys. + expect(Object.keys(record.attributes).sort()).toEqual( + [ + TYPEAGENT_SPAN_ATTRIBUTES.SESSION_ID, + TYPEAGENT_SPAN_ATTRIBUTES.ACTIVATION_ID, + TYPEAGENT_SPAN_ATTRIBUTES.TRACE_ID, + ].sort(), + ); + }); + + it("bounds the event name and promoted correlation values", () => { + logFixture = installLogFixture(); + const sink = createOtelLoggerSink(); + const oversized = "x".repeat(1_000); + + sink.logEvent( + baseEvent({ + eventName: oversized, + event: { + sessionId: oversized, + activationId: oversized, + traceId: oversized, + }, + }), + ); + + const record = logFixture.exporter.getFinishedLogRecords()[0]!; + expect(record.eventName).toBe("typeagent.truncated_event_name"); + expect(record.attributes).toEqual({}); + }); + + it("redacts secrets registered on the shared filter from body and attributes", () => { + logFixture = installLogFixture(); + const secretFilter = createSecretFilter(); + secretFilter.addValue("hunter2-registered"); + const sink = createOtelLoggerSink({ secretFilter }); + + sink.logEvent( + baseEvent({ + event: { + sessionId: "hunter2-registered", + activationId: "act", + message: "leak=hunter2-registered", + tokens: 7, + }, + }), + ); + + const record = logFixture.exporter.getFinishedLogRecords()[0]!; + // Attribute is redacted. + expect( + record.attributes[TYPEAGENT_SPAN_ATTRIBUTES.SESSION_ID], + ).not.toContain("hunter2-registered"); + expect(record.attributes[TYPEAGENT_SPAN_ATTRIBUTES.ACTIVATION_ID]).toBe( + "act", + ); + // Body is redacted. + const body = record.body as Record; + expect(body.sessionId).not.toContain("hunter2-registered"); + expect(String(body.message)).not.toContain("hunter2-registered"); + // Non-string values are preserved. + expect(body.tokens).toBe(7); + }); + + it("does not mutate the caller's LogEvent and detaches the emitted body", () => { + logFixture = installLogFixture(); + const secretFilter = createSecretFilter({ + initialValues: ["hunter2"], + }); + const sink = createOtelLoggerSink({ secretFilter }); + + const originalNested = { greeting: "hello", token: "hunter2" }; + const originalList: (string | number)[] = [1, 2, 3]; + const eventPayload = { + sessionId: "sess", + nested: originalNested, + values: originalList, + emptyObj: {}, + emptyArr: [] as unknown[], + }; + const event: LogEvent = { + eventName: "immutability", + timestamp: "2024-06-01T00:00:00.000Z", + event: eventPayload, + }; + const snapshot = JSON.parse(JSON.stringify(event)); + + sink.logEvent(event); + + expect(event).toEqual(snapshot); + // Reference identity preserved. + expect(event.event.nested).toBe(originalNested); + expect(event.event.values).toBe(originalList); + expect(originalNested.token).toBe("hunter2"); + + const record = logFixture.exporter.getFinishedLogRecords()[0]!; + const body = record.body as Record; + // Emitted body is a fresh detached snapshot. + expect(body).not.toBe(eventPayload); + expect(body.nested).not.toBe(originalNested); + expect(body.values).not.toBe(originalList); + expect(body.emptyObj).not.toBe(eventPayload.emptyObj); + expect(body.emptyArr).not.toBe(eventPayload.emptyArr); + // Structural equality of untouched containers. + expect(body.values).toEqual([1, 2, 3]); + // The registered secret is redacted in the emitted body. + expect((body.nested as { token: string }).token).not.toBe("hunter2"); + }); + + it("detaches every reachable container when the payload has no strings anywhere", () => { + // `redactObject` short-circuits back to the caller's own reference + // when it finds no strings to scrub, so the sink must clone JSON + // containers locally on that path. Exercise it with a payload that + // is deliberately string-free at every depth. + logFixture = installLogFixture(); + const sink = createOtelLoggerSink(); + + const originalNested: Record = { + count: 1, + flag: true, + nullField: null, + deeper: { level: 2, values: [10, 20] }, + }; + const originalList: unknown[] = [1, 2, 3, [4, 5]]; + const eventPayload: Record = { + count: 42, + flag: false, + nested: originalNested, + values: originalList, + }; + const event: LogEvent = { + eventName: "no.strings", + timestamp: "2024-06-01T00:00:00.000Z", + event: eventPayload, + }; + + sink.logEvent(event); + + const record = logFixture.exporter.getFinishedLogRecords()[0]!; + const body = record.body as Record; + // Root, nested object, and array are all fresh references. + expect(body).not.toBe(eventPayload); + expect(Object.getPrototypeOf(body)).toBe(Object.prototype); + expect(body.nested).not.toBe(originalNested); + expect(body.values).not.toBe(originalList); + const bodyNested = body.nested as Record; + expect(Object.getPrototypeOf(bodyNested)).toBe(Object.prototype); + const originalDeeper = originalNested.deeper as Record; + expect(bodyNested.deeper).not.toBe(originalDeeper); + expect((bodyNested.deeper as { values: unknown[] }).values).not.toBe( + originalDeeper.values, + ); + // Structural equality of the captured snapshot before any mutation. + expect(body).toEqual({ + count: 42, + flag: false, + nested: { + count: 1, + flag: true, + nullField: null, + deeper: { level: 2, values: [10, 20] }, + }, + values: [1, 2, 3, [4, 5]], + }); + + // Mutate every level of the caller's payload after emit. + eventPayload.count = 999; + eventPayload.newRootKey = "added"; + originalNested.count = 100; + (originalDeeper.values as number[]).push(30); + originalList.push(99); + + // Captured body still reflects the pre-emit values. + expect(body.count).toBe(42); + expect(body).not.toHaveProperty("newRootKey"); + expect((body.nested as Record).count).toBe(1); + expect( + ( + (body.nested as Record).deeper as { + values: number[]; + } + ).values, + ).toEqual([10, 20]); + expect(body.values).toEqual([1, 2, 3, [4, 5]]); + }); + + it("correlates the emitted record to the active span", () => { + traceFixture = installTraceFixture(); + logFixture = installLogFixture(); + const sink = createOtelLoggerSink(); + const tracer = trace.getTracer("test"); + + let expectedTraceId = ""; + let expectedSpanId = ""; + tracer.startActiveSpan("outer", (span) => { + expectedTraceId = span.spanContext().traceId; + expectedSpanId = span.spanContext().spanId; + sink.logEvent(baseEvent({ event: { sessionId: "sess" } })); + span.end(); + }); + + const record = logFixture.exporter.getFinishedLogRecords()[0]!; + expect(record.spanContext).toBeDefined(); + expect(record.spanContext!.traceId).toBe(expectedTraceId); + expect(record.spanContext!.spanId).toBe(expectedSpanId); + }); + + it("emits no record when no logs provider is registered", () => { + // No log fixture install: `logs.getLogger` returns a ProxyLogger + // whose delegate is the NoopLogger. + const sink = createOtelLoggerSink(); + expect(() => { + sink.logEvent(baseEvent({ event: { sessionId: "s" } })); + }).not.toThrow(); + // Nothing to inspect: NoopLogger.emit does nothing and any + // side effect (throw) would fail the test above. + }); + + it("emits after late provider registration for a sink constructed before it", () => { + // Construct the sink first (no provider yet). + const sink = createOtelLoggerSink(); + sink.logEvent(baseEvent({ event: { sessionId: "before" } })); + + // Register a provider *after* the sink was created and used. + logFixture = installLogFixture(); + + sink.logEvent(baseEvent({ event: { sessionId: "after" } })); + + const records = logFixture.exporter.getFinishedLogRecords(); + expect(records).toHaveLength(1); + const body = records[0]!.body as Record; + expect(body.sessionId).toBe("after"); + }); + + it("does not inspect or snapshot the body when the logger is disabled", () => { + let bodyReads = 0; + let emitCalls = 0; + logs.setGlobalLoggerProvider({ + getLogger: () => ({ + enabled: () => false, + emit: () => { + emitCalls++; + }, + }), + } as never); + try { + const sink = createOtelLoggerSink(); + const event = baseEvent(); + Object.defineProperty(event, "event", { + configurable: true, + get() { + bodyReads++; + throw new Error("disabled logger read the event body"); + }, + }); + + expect(() => sink.logEvent(event)).not.toThrow(); + expect(bodyReads).toBe(0); + expect(emitCalls).toBe(0); + } finally { + logs.disable(); + } + }); + + it("isolates emit failures from a sibling sink", () => { + // Install a stub provider whose logger throws in `emit()` so the + // sink actually reaches its failure guard. `enabled()` returns + // true so the sink does not short-circuit. Cannot layer this on + // top of `installLogFixture()`: `logs.setGlobalLoggerProvider` + // is first-writer-wins, so a second registration is silently + // dropped and the real fixture would win. + const brokenLogger = { + emit(_record: OtelLogRecord): void { + throw new Error("boom emit"); + }, + enabled(): boolean { + return true; + }, + }; + let emitCalls = 0; + const brokenProvider = { + getLogger: () => { + return { + emit(record: OtelLogRecord): void { + emitCalls++; + brokenLogger.emit(record); + }, + enabled: brokenLogger.enabled, + }; + }, + }; + logs.setGlobalLoggerProvider(brokenProvider as never); + try { + const sibling: LoggerSink & { events: LogEvent[] } = { + events: [], + logEvent(event: LogEvent) { + this.events.push(event); + }, + }; + const logger = new MultiSinkLogger([ + createOtelLoggerSink(), + sibling, + ]); + + const payload = { sessionId: "sib" }; + expect(() => logger.logEvent("test.event", payload)).not.toThrow(); + expect(emitCalls).toBe(1); + expect(sibling.events).toHaveLength(1); + expect(sibling.events[0]!.event).toBe(payload); + // The original event object is untouched. + expect(payload).toEqual({ sessionId: "sib" }); + } finally { + logs.disable(); + } + }); + + it("emits with the SDK-defaulted timestamp when LogEvent.timestamp is invalid", () => { + logFixture = installLogFixture(); + const sink = createOtelLoggerSink(); + const before = Date.now(); + + sink.logEvent( + baseEvent({ + timestamp: "not-a-real-timestamp", + event: { sessionId: "s" }, + }), + ); + + const after = Date.now(); + const records = logFixture.exporter.getFinishedLogRecords(); + expect(records).toHaveLength(1); + const record = records[0]!; + const emittedMs = hrTimeToMs(record.hrTime); + // Invalid timestamp is dropped; the SDK falls back to `Date.now()`. + // Allow a small slack for the SDK's own `Date.now()` call. + expect(emittedMs).toBeGreaterThanOrEqual(before - 10); + expect(emittedMs).toBeLessThanOrEqual(after + 10); + }); + + it("emits with the SDK-defaulted timestamp when LogEvent.timestamp is a rolled-over ISO date", () => { + // `2024-02-30` is not a real date. `new Date(...)` may either + // return an Invalid Date or roll over to `2024-03-01`; either + // way the round-trip through `toISOString()` no longer matches + // the input, so the sink must drop the timestamp field and let + // the SDK default `hrTime` from `Date.now()`. + logFixture = installLogFixture(); + const sink = createOtelLoggerSink(); + const before = Date.now(); + + sink.logEvent( + baseEvent({ + timestamp: "2024-02-30T00:00:00.000Z", + event: { sessionId: "s" }, + }), + ); + + const after = Date.now(); + const records = logFixture.exporter.getFinishedLogRecords(); + expect(records).toHaveLength(1); + const emittedMs = hrTimeToMs(records[0]!.hrTime); + expect(emittedMs).toBeGreaterThanOrEqual(before - 10); + expect(emittedMs).toBeLessThanOrEqual(after + 10); + }); + + it("survives an empty timestamp string without dropping the record", () => { + logFixture = installLogFixture(); + const sink = createOtelLoggerSink(); + sink.logEvent( + baseEvent({ + timestamp: "", + event: { sessionId: "s" }, + }), + ); + expect(logFixture.exporter.getFinishedLogRecords()).toHaveLength(1); + }); + + it("survives global provider cleanup between emits", async () => { + logFixture = installLogFixture(); + const sink = createOtelLoggerSink(); + + sink.logEvent(baseEvent({ event: { sessionId: "before-clean" } })); + expect(logFixture.exporter.getFinishedLogRecords()).toHaveLength(1); + + await disposeLogFixture(logFixture); + logFixture = undefined; + + // After teardown the sink must not throw and must not touch any + // still-registered provider. + expect(() => + sink.logEvent(baseEvent({ event: { sessionId: "after-clean" } })), + ).not.toThrow(); + + // Re-install a provider; the same sink must resume emitting into it. + logFixture = installLogFixture(); + sink.logEvent(baseEvent({ event: { sessionId: "after-reinstall" } })); + const records = logFixture.exporter.getFinishedLogRecords(); + expect(records).toHaveLength(1); + const body = records[0]!.body as Record; + expect(body.sessionId).toBe("after-reinstall"); + }); + + it("records use the frozen instrumentation scope constants", () => { + logFixture = installLogFixture(); + const sink: OtelLoggerSink = createOtelLoggerSink(); + sink.logEvent(baseEvent({ event: { sessionId: "s" } })); + const record = logFixture.exporter.getFinishedLogRecords()[0]!; + expect(record.instrumentationScope.name).toBe( + INSTRUMENTATION_SCOPE_NAME, + ); + expect(record.instrumentationScope.version).toBe( + INSTRUMENTATION_SCOPE_VERSION, + ); + }); + + it("passes the emit-time active OTel context to the SDK", () => { + traceFixture = installTraceFixture(); + + // Capture the raw LogRecord the sink emits, without an SDK + // provider in the way. The SDK strips `record.context` after + // deriving `_spanContext`, so an assertion on the ReadableLogRecord + // cannot distinguish `ROOT_CONTEXT` from the emit-time context. + const captured: OtelLogRecord[] = []; + const wrappingLogger = { + emit(record: OtelLogRecord): void { + captured.push(record); + }, + enabled(): boolean { + return true; + }, + }; + logs.setGlobalLoggerProvider({ + getLogger: () => wrappingLogger, + } as never); + try { + const sink = createOtelLoggerSink(); + const tracer = trace.getTracer("test"); + let expectedTraceId = ""; + let expectedSpanId = ""; + tracer.startActiveSpan("s", (span) => { + expectedTraceId = span.spanContext().traceId; + expectedSpanId = span.spanContext().spanId; + sink.logEvent(baseEvent({ event: {} })); + span.end(); + }); + + expect(captured).toHaveLength(1); + const record = captured[0]!; + expect(record.context).toBeDefined(); + expect(record.context).not.toBe(ROOT_CONTEXT); + const spanContext = trace.getSpanContext(record.context!); + expect(spanContext).toBeDefined(); + expect(spanContext!.traceId).toBe(expectedTraceId); + expect(spanContext!.spanId).toBe(expectedSpanId); + } finally { + logs.disable(); + } + }); + + describe("severity", () => { + it("defaults severity to INFO when LogEvent.severity is undefined", () => { + logFixture = installLogFixture(); + const sink = createOtelLoggerSink(); + sink.logEvent(baseEvent({ event: { sessionId: "s" } })); + const record = logFixture.exporter.getFinishedLogRecords()[0]!; + expect(record.severityNumber).toBe(SeverityNumber.INFO); + expect(record.severityText).toBe("INFO"); + }); + + it("passes through 'info' as OTel INFO", () => { + logFixture = installLogFixture(); + const sink = createOtelLoggerSink(); + sink.logEvent( + baseEvent({ + event: { sessionId: "s" }, + severity: "info", + }), + ); + const record = logFixture.exporter.getFinishedLogRecords()[0]!; + expect(record.severityNumber).toBe(SeverityNumber.INFO); + expect(record.severityText).toBe("INFO"); + }); + + it("maps 'warning' to OTel WARN", () => { + logFixture = installLogFixture(); + const sink = createOtelLoggerSink(); + sink.logEvent( + baseEvent({ + event: { sessionId: "s" }, + severity: "warning", + }), + ); + const record = logFixture.exporter.getFinishedLogRecords()[0]!; + expect(record.severityNumber).toBe(SeverityNumber.WARN); + expect(record.severityText).toBe("WARN"); + }); + + it("maps 'error' to OTel ERROR", () => { + logFixture = installLogFixture(); + const sink = createOtelLoggerSink(); + sink.logEvent( + baseEvent({ + event: { sessionId: "s" }, + severity: "error", + }), + ); + const record = logFixture.exporter.getFinishedLogRecords()[0]!; + expect(record.severityNumber).toBe(SeverityNumber.ERROR); + expect(record.severityText).toBe("ERROR"); + }); + + it("never infers severity from the event name or payload", () => { + // A payload that names or hints at 'error' must not upgrade + // the record severity. The only signal is `LogEvent.severity`. + logFixture = installLogFixture(); + const sink = createOtelLoggerSink(); + sink.logEvent( + baseEvent({ + eventName: "translation.error", + event: { + severity: "error", + level: "error", + message: "something failed", + }, + }), + ); + const record = logFixture.exporter.getFinishedLogRecords()[0]!; + expect(record.severityNumber).toBe(SeverityNumber.INFO); + expect(record.severityText).toBe("INFO"); + }); + }); + + describe("bounded body processing", () => { + it("replaces a self-referencing subtree with a cycle marker without throwing", () => { + logFixture = installLogFixture(); + const sink = createOtelLoggerSink(); + + const payload: Record = { + sessionId: "sess", + tag: "cycle", + }; + // Introduce a genuine reference cycle: payload.self -> payload. + payload.self = payload; + + expect(() => + sink.logEvent( + baseEvent({ + event: payload as { [key: string]: unknown }, + }), + ), + ).not.toThrow(); + + const records = logFixture.exporter.getFinishedLogRecords(); + expect(records).toHaveLength(1); + const body = records[0]!.body as Record; + // Non-cyclic siblings survive unchanged. + expect(body.sessionId).toBe("sess"); + expect(body.tag).toBe("cycle"); + // The self-reference collapses to a truncation marker. + expect(body.self).toEqual({ __typeagent_otel_truncated: "cycle" }); + }); + + it("preserves cross-references that are not actual cycles", () => { + // Two separate keys can point at the same shared inner object + // without forming a cycle; the traversal walks the tree, so + // both branches should be preserved without a cycle marker. + logFixture = installLogFixture(); + const sink = createOtelLoggerSink(); + + const shared = { name: "shared" }; + sink.logEvent( + baseEvent({ + event: { + a: shared, + b: shared, + }, + }), + ); + + const body = logFixture.exporter.getFinishedLogRecords()[0]! + .body as Record; + expect(body.a).toEqual({ name: "shared" }); + expect(body.b).toEqual({ name: "shared" }); + // Neither branch is a truncation marker. + expect(body.a).not.toHaveProperty("__typeagent_otel_truncated"); + expect(body.b).not.toHaveProperty("__typeagent_otel_truncated"); + }); + + it("caps nesting depth deterministically with a 'depth' marker", () => { + logFixture = installLogFixture(); + const sink = createOtelLoggerSink(); + + // Build a chain far deeper than the sink's cap. Each `next` + // hop is one depth level; the top-level object is depth 0. + const chainDepth = 200; + let deepest: { name: string } | Record = { + name: "bottom", + }; + for (let i = 0; i < chainDepth; i++) { + deepest = { next: deepest }; + } + sink.logEvent( + baseEvent({ + event: { root: deepest } as Record, + }), + ); + + const body = logFixture.exporter.getFinishedLogRecords()[0]!.body; + // Walk `next` and find a `__typeagent_otel_truncated: "depth"` + // marker somewhere before the (unreachable) bottom. + let cursor: unknown = body; + let steps = 0; + let sawDepthMarker = false; + while ( + cursor !== null && + typeof cursor === "object" && + steps < chainDepth + 10 + ) { + const rec = cursor as Record; + if (rec.__typeagent_otel_truncated === "depth") { + sawDepthMarker = true; + break; + } + cursor = rec.next ?? rec.root; + steps++; + } + expect(sawDepthMarker).toBe(true); + }); + + it("caps approximate serialized size and preserves a partial body with a 'size' marker", () => { + logFixture = installLogFixture(); + const sink = createOtelLoggerSink(); + + // Build a payload well past the 60 KiB approximate cap: + // ~200,000 short strings. + const values = new Array(200_000); + for (let i = 0; i < values.length; i++) { + values[i] = `item-${i}`; + } + sink.logEvent( + baseEvent({ + event: { sessionId: "sess", values } as Record< + string, + unknown + >, + }), + ); + + const records = logFixture.exporter.getFinishedLogRecords(); + // Whole record is preserved; only the body is truncated. + expect(records).toHaveLength(1); + const body = records[0]!.body as Record; + // Correlation-adjacent scalars stayed. + expect(body.sessionId).toBe("sess"); + expect(Array.isArray(body.values)).toBe(true); + const partial = body.values as unknown[]; + // Truncated well before the original length. + expect(partial.length).toBeLessThan(values.length); + // Last element is the size truncation marker. + expect(partial[partial.length - 1]).toEqual({ + __typeagent_otel_truncated: "size", + }); + }); + + it("replaces a single oversized value instead of retaining it whole", () => { + logFixture = installLogFixture(); + const sink = createOtelLoggerSink(); + const oversized = "x".repeat(100_000); + + sink.logEvent( + baseEvent({ + event: { + sessionId: "sess", + oversized, + }, + }), + ); + + const body = logFixture.exporter.getFinishedLogRecords()[0]! + .body as Record; + expect(body.sessionId).toBe("sess"); + expect(body.oversized).toEqual({ + __typeagent_otel_truncated: "size", + }); + expect(oversized).toHaveLength(100_000); + }); + + it("enforces the hard serialized UTF-8 byte limit after snapshotting", () => { + logFixture = installLogFixture(); + const sink = createOtelLoggerSink(); + + // 20,000 emoji occupy 40,000 UTF-16 code units, which fits + // the traversal budget, but 80,000 UTF-8 bytes, which exceeds + // the hard serialized-body limit. + sink.logEvent( + baseEvent({ + event: { text: "😀".repeat(20_000) }, + }), + ); + + expect( + logFixture.exporter.getFinishedLogRecords()[0]!.body, + ).toEqual({ + __typeagent_otel_truncated: "size", + }); + }); + + it("does not hang on a cycle even when the payload also contains strings that trigger redaction", () => { + logFixture = installLogFixture(); + const secretFilter = createSecretFilter({ + initialValues: ["cycle-secret"], + }); + const sink = createOtelLoggerSink({ secretFilter }); + + const payload: Record = { + sessionId: "sess", + token: "cycle-secret", + }; + payload.self = payload; + expect(() => + sink.logEvent( + baseEvent({ + event: payload as { [key: string]: unknown }, + }), + ), + ).not.toThrow(); + + const body = logFixture.exporter.getFinishedLogRecords()[0]! + .body as Record; + expect(String(body.token)).not.toContain("cycle-secret"); + expect(body.self).toEqual({ __typeagent_otel_truncated: "cycle" }); + }); + + it("does not mutate the caller when the body is truncated", () => { + logFixture = installLogFixture(); + const sink = createOtelLoggerSink(); + + const original: Record = { sessionId: "sess" }; + original.self = original; + const snapshot = { sessionId: "sess", self: original }; + // Sanity: identity check that the cycle is set up. + expect((snapshot.self as Record).self).toBe( + original, + ); + + sink.logEvent( + baseEvent({ + event: original as { [key: string]: unknown }, + }), + ); + + // Caller's payload keeps its cycle and every field. + expect(original.sessionId).toBe("sess"); + expect(original.self).toBe(original); + }); + + it("replaces values outside the JSON-compatible contract", () => { + logFixture = installLogFixture(); + const sink = createOtelLoggerSink(); + + sink.logEvent( + baseEvent({ + event: { + undefinedValue: undefined, + bigintValue: 1n, + nonFiniteNumber: Number.POSITIVE_INFINITY, + dateValue: new Date(0), + }, + }), + ); + + const body = logFixture.exporter.getFinishedLogRecords()[0]! + .body as Record; + for (const key of [ + "undefinedValue", + "bigintValue", + "nonFiniteNumber", + "dateValue", + ]) { + expect(body[key]).toEqual({ + __typeagent_otel_truncated: "unsupported", + }); + } + }); + + it("charges repeated unsupported markers against the size budget", () => { + logFixture = installLogFixture(); + const sink = createOtelLoggerSink(); + const values = new Array(200_000).fill(undefined); + + sink.logEvent( + baseEvent({ + event: { values }, + }), + ); + + const body = logFixture.exporter.getFinishedLogRecords()[0]! + .body as { values: unknown[] }; + expect(body.values.length).toBeLessThan(values.length); + expect(body.values[body.values.length - 1]).toEqual({ + __typeagent_otel_truncated: "size", + }); + }); + }); +}); + +function hrTimeToMs(hrTime: ReadableLogRecord["hrTime"]): number { + const [seconds, nanos] = hrTime; + return seconds * 1_000 + nanos / 1_000_000; +} From 79ebe6b0bb27a06ccea654c5358d9087a1af33e9 Mon Sep 17 00:00:00 2001 From: George Ng Date: Wed, 12 Aug 2026 01:38:46 -0700 Subject: [PATCH 02/13] [OTEL] Add local log diagnostics Add multi-instance debug bridging, bounded process-safe JSONL log export, configuration, failure diagnostics, and correlated local integration coverage. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> Copilot-Session: 67859676-8c6c-43f7-bfe4-ee784f8db79d --- ts/config.sample.yaml | 2 + .../architecture/telemetry/opentelemetry.md | 5 +- .../telemetry/src/logger/otelLoggerSink.ts | 36 +- ts/packages/telemetry/src/otel/bootstrap.ts | 64 ++- ts/packages/telemetry/src/otel/config.ts | 38 ++ ts/packages/telemetry/src/otel/debugBridge.ts | 150 +++++++ ts/packages/telemetry/src/otel/index.ts | 13 + .../telemetry/src/otel/jsonlLogExporter.ts | 235 +++++++++++ .../telemetry/test/otelBootstrap.spec.ts | 37 +- ts/packages/telemetry/test/otelConfig.spec.ts | 21 + .../test/otelLocalDiagnostics.spec.ts | 387 ++++++++++++++++++ .../telemetry/test/otelLoggerSink.spec.ts | 4 +- 12 files changed, 960 insertions(+), 32 deletions(-) create mode 100644 ts/packages/telemetry/src/otel/debugBridge.ts create mode 100644 ts/packages/telemetry/src/otel/jsonlLogExporter.ts create mode 100644 ts/packages/telemetry/test/otelLocalDiagnostics.spec.ts diff --git a/ts/config.sample.yaml b/ts/config.sample.yaml index bd4c175e41..34c9168ea2 100644 --- a/ts/config.sample.yaml +++ b/ts/config.sample.yaml @@ -401,6 +401,7 @@ typeagent: # - logFile local JSONL log file; enables the logs signal # independently of any OTLP endpoint. Leading # `~`/`~/`/`~\` expands to your home dir. +# - debugBridge copy enabled typeagent:* debug output to OTel logs # - tracesSampler one of always_on, always_off, traceidratio, # parentbased_always_on, parentbased_always_off, # parentbased_traceidratio @@ -409,5 +410,6 @@ typeagent: # telemetry: # otlpEndpoint: http://localhost:4318 # logFile: ~/.typeagent/logs/typeagent-{service}-{pid}.jsonl +# debugBridge: true # tracesSampler: parentbased_traceidratio # tracesSamplerArg: 0.1 diff --git a/ts/docs/architecture/telemetry/opentelemetry.md b/ts/docs/architecture/telemetry/opentelemetry.md index 7c93f6a0c2..72def308ae 100644 --- a/ts/docs/architecture/telemetry/opentelemetry.md +++ b/ts/docs/architecture/telemetry/opentelemetry.md @@ -204,9 +204,8 @@ covering the promoted correlation attributes and every string reachable in the snapshotted body. Emit failures are isolated: the sink drops the OTel record and never re-enters -the `MultiSinkLogger` fan-out. Drop and error accounting is deliberately silent -in this PR; a follow-up PR wires a non-recursive diagnostics channel that -reports these events without looping back through the sink. +the `MultiSinkLogger` fan-out. A rate-limited diagnostic writes directly to +stderr (or an injected non-recursive callback) without including event content. The debug bridge tees enabled `typeagent:*` calls into OTel without changing their original output: diff --git a/ts/packages/telemetry/src/logger/otelLoggerSink.ts b/ts/packages/telemetry/src/logger/otelLoggerSink.ts index 6aefcee504..55858f780b 100644 --- a/ts/packages/telemetry/src/logger/otelLoggerSink.ts +++ b/ts/packages/telemetry/src/logger/otelLoggerSink.ts @@ -38,7 +38,9 @@ import { * content, PII, and other data that is not appropriate to record. See * `docs/architecture/telemetry/opentelemetry.md` for the privacy contract. */ -export type OtelLoggerSinkOptions = RedactionOptions; +export interface OtelLoggerSinkOptions extends RedactionOptions { + readonly diagnostic?: (message: string) => void; +} /** * Top-level string fields on `LogEvent.event` that are promoted to @@ -168,9 +170,9 @@ function mapSeverity(severity: LogEventSeverity | undefined): { * - Never throw from `logEvent`. Failures (missing provider, misbehaving * redaction, broken logger implementation, etc.) drop the OTel record * only. No debug or Structured Logger calls happen in the catch, so - * the sink cannot recurse through a sibling sink. A follow-up PR wires - * a non-recursive diagnostics path that reports drops and errors; this - * PR keeps the surface silent to preserve the isolation guarantee. + * the sink cannot recurse through a sibling sink. Failures produce a + * rate-limited, content-free diagnostic through an injected callback or + * direct stderr output. * - Never mutate the caller's `LogEvent.event`; the emitted body is a * detached snapshot produced by {@link boundedSnapshot} so a sibling * sink still sees the original. The snapshot bounds depth @@ -210,6 +212,7 @@ function mapSeverity(severity: LogEventSeverity | undefined): { */ export class OtelLoggerSink implements LoggerSink { private readonly options: OtelLoggerSinkOptions | undefined; + private lastDiagnosticAt = 0; constructor(options?: OtelLoggerSinkOptions) { this.options = options; @@ -276,12 +279,12 @@ export class OtelLoggerSink implements LoggerSink { }; logger.emit(record); - } catch { + } catch (error) { // Failure isolation: never let a telemetry-side error escape // into the caller. Intentionally no debug/logger call - that // would recurse through the sibling sinks that share the same - // `MultiSinkLogger`. PR2 introduces a non-recursive - // diagnostics channel that reports these drops and errors. + // `MultiSinkLogger`. + this.reportFailure(error); } } @@ -295,6 +298,25 @@ export class OtelLoggerSink implements LoggerSink { return undefined; } } + + private reportFailure(error: unknown): void { + const now = Date.now(); + if (now - this.lastDiagnosticAt < 60_000) { + return; + } + this.lastDiagnosticAt = now; + const errorName = error instanceof Error ? error.name : "Error"; + const message = `OpenTelemetry structured log dropped (${errorName}).`; + try { + if (this.options?.diagnostic !== undefined) { + this.options.diagnostic(message); + } else { + process.stderr.write(`[typeagent:telemetry] ${message}\n`); + } + } catch { + // Diagnostics remain isolated from the request and logger fan-out. + } + } } /** Factory that mirrors the other sinks in this package. */ diff --git a/ts/packages/telemetry/src/otel/bootstrap.ts b/ts/packages/telemetry/src/otel/bootstrap.ts index fe48240b88..fc39bb031f 100644 --- a/ts/packages/telemetry/src/otel/bootstrap.ts +++ b/ts/packages/telemetry/src/otel/bootstrap.ts @@ -58,6 +58,12 @@ import { type TelemetryLifecycleOptions, } from "./lifecycle.js"; import { createProcessResource } from "./resources.js"; +import { + installDebugBridge, + type DebugBridgeOptions, + type DebugModule, +} from "./debugBridge.js"; +import { JsonlLogExporter } from "./jsonlLogExporter.js"; export type TelemetrySignal = "traces" | "metrics" | "logs"; @@ -121,6 +127,9 @@ export interface InitTelemetryOptions { /** Provider factories for tests or host-specific pipelines. */ readonly factories?: Partial; readonly lifecycle?: TelemetryLifecycleOptions; + /** Distinct debug module instances owned by this host. */ + readonly debugModules?: readonly DebugModule[]; + readonly debugBridge?: DebugBridgeOptions; } export interface TelemetryCoordinator { @@ -183,21 +192,38 @@ const DEFAULT_FACTORIES: TelemetryProviderFactories = { }, createLogProvider(config, resource) { + const processors = []; + if (config.otlp !== undefined) { + processors.push( + new BatchLogRecordProcessor({ + exporter: new OTLPLogExporter( + toExporterOptions(config.otlp), + ), + selfObsMeterProvider: metrics.getMeterProvider(), + }), + ); + } if (config.logFile !== undefined) { - throw new Error( - "Local OpenTelemetry JSONL output is not implemented by the default log provider. Supply a createLogProvider factory with a writer component.", + const configuredServiceName = resource.attributes["service.name"]; + const serviceName = + typeof configuredServiceName === "string" && + configuredServiceName.length > 0 + ? configuredServiceName + : "typeagent"; + processors.push( + new BatchLogRecordProcessor({ + exporter: new JsonlLogExporter({ + filePath: config.logFile, + serviceName, + }), + maxQueueSize: 2_048, + maxExportBatchSize: 256, + scheduledDelayMillis: 250, + exportTimeoutMillis: 5_000, + selfObsMeterProvider: metrics.getMeterProvider(), + }), ); } - const processors = - config.otlp === undefined - ? [] - : [ - new BatchLogRecordProcessor({ - exporter: new OTLPLogExporter( - toExporterOptions(config.otlp), - ), - }), - ]; return { provider: new LoggerProvider({ resource, processors }), }; @@ -296,6 +322,17 @@ export function createTelemetryCoordinator(): TelemetryCoordinator { registerLogProvider(bundle.provider); installedGlobals.logs = true; } + if ( + config.debugBridge === true && + options.debugModules !== undefined && + options.debugModules.length > 0 + ) { + const bridge = installDebugBridge( + options.debugModules, + options.debugBridge, + ); + lifecycle.register("debug bridge", () => bridge.shutdown()); + } } catch (error) { rollbackGlobals(installedGlobals); try { @@ -357,7 +394,8 @@ function isConfigured(config: TelemetryConfig): boolean { return ( config.traces !== undefined || config.metrics !== undefined || - config.logs !== undefined + config.logs !== undefined || + config.debugBridge === true ); } diff --git a/ts/packages/telemetry/src/otel/config.ts b/ts/packages/telemetry/src/otel/config.ts index 1fe3699cc9..beee9d2870 100644 --- a/ts/packages/telemetry/src/otel/config.ts +++ b/ts/packages/telemetry/src/otel/config.ts @@ -82,6 +82,8 @@ export interface TelemetryConfig { readonly traces?: TraceConfig; readonly metrics?: MetricConfig; readonly logs?: LogConfig; + /** Copy enabled TypeAgent debug output into the OTel logs pipeline. */ + readonly debugBridge?: boolean; } /* -------------------------------------------------------------------------- */ @@ -178,6 +180,10 @@ export function resolveTelemetryConfig( yaml.TELEMETRY_TRACESSAMPLERARG, "telemetry.tracesSamplerArg", ); + const yamlDebugBridge = parseBoolean( + yaml.TELEMETRY_DEBUGBRIDGE, + "telemetry.debugBridge", + ); // ---- Env values. const envGlobalEndpoint = requireNonEmpty( @@ -197,6 +203,10 @@ export function resolveTelemetryConfig( env.TYPEAGENT_OTEL_LOG_FILE, "TYPEAGENT_OTEL_LOG_FILE", ); + const envDebugBridge = parseBoolean( + env.TYPEAGENT_OTEL_DEBUG_BRIDGE, + "TYPEAGENT_OTEL_DEBUG_BRIDGE", + ); const signalEndpoints: Record = { traces: requireNonEmpty( @@ -290,6 +300,7 @@ export function resolveTelemetryConfig( traces?: TraceConfig; metrics?: MetricConfig; logs?: LogConfig; + debugBridge?: boolean; } = {}; if (tracesOtlp !== undefined) { @@ -319,6 +330,10 @@ export function resolveTelemetryConfig( } result.logs = logs; } + const debugBridge = envDebugBridge ?? yamlDebugBridge; + if (debugBridge !== undefined) { + result.debugBridge = debugBridge; + } return result; } @@ -376,6 +391,29 @@ function requireNonEmpty( return value; } +function parseBoolean( + value: string | undefined, + name: string, +): boolean | undefined { + if (value === undefined || value === "") { + return undefined; + } + switch (value.trim().toLowerCase()) { + case "true": + case "on": + case "1": + return true; + case "false": + case "off": + case "0": + return false; + default: + throw new Error( + `${name}="${value}" is invalid; expected true/false, on/off, or 1/0.`, + ); + } +} + /** * Parse the `OTEL_{TRACES,METRICS,LOGS}_EXPORTER` selector. Only `otlp` and * `none` are supported; any other value throws a clear error so users are diff --git a/ts/packages/telemetry/src/otel/debugBridge.ts b/ts/packages/telemetry/src/otel/debugBridge.ts new file mode 100644 index 0000000000..26f4fff76f --- /dev/null +++ b/ts/packages/telemetry/src/otel/debugBridge.ts @@ -0,0 +1,150 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +import { context as otelContext } from "@opentelemetry/api"; +import { logs, SeverityNumber } from "@opentelemetry/api-logs"; +import { isTracingSuppressed } from "@opentelemetry/core"; +import { format } from "node:util"; + +import { + INSTRUMENTATION_SCOPE_NAME, + INSTRUMENTATION_SCOPE_VERSION, +} from "./instrumentation.js"; +import { redactText, type RedactionOptions } from "./redaction.js"; + +export interface DebugModule { + log: (this: { namespace?: string }, ...args: unknown[]) => unknown; +} + +export interface DebugBridgeOptions extends RedactionOptions { + readonly excludedNamespacePrefixes?: readonly string[]; +} + +export interface DebugBridge { + shutdown(): void; +} + +interface InstalledBridge { + readonly priorLog: DebugModule["log"]; + readonly wrappedLog: DebugModule["log"]; + refCount: number; +} + +const installedBridges = new WeakMap(); +const DEFAULT_EXCLUSIONS = [ + "typeagent:logger:", + "typeagent:telemetry:debugBridge", + "typeagent:telemetry:promptLogger", +] as const; +const ANSI_ESCAPE = /\u001b\[[0-?]*[ -/]*[@-~]/g; +const MAX_BODY_LENGTH = 64 * 1024; +let emitting = false; + +export function installDebugBridge( + debugModules: readonly DebugModule[], + options: DebugBridgeOptions = {}, +): DebugBridge { + const installed: DebugModule[] = []; + for (const debugModule of new Set(debugModules)) { + const existing = installedBridges.get(debugModule); + if (existing !== undefined) { + existing.refCount++; + installed.push(debugModule); + continue; + } + + const priorLog = debugModule.log; + const exclusions = + options.excludedNamespacePrefixes ?? DEFAULT_EXCLUSIONS; + const wrappedLog: DebugModule["log"] = function ( + this: { namespace?: string }, + ...args: unknown[] + ): unknown { + const result = priorLog.apply(this, args); + const namespace = this?.namespace; + if ( + emitting || + namespace === undefined || + !namespace.startsWith("typeagent:") || + exclusions.some((prefix) => namespace.startsWith(prefix)) + ) { + return result; + } + const activeContext = otelContext.active(); + if (isTracingSuppressed(activeContext)) { + return result; + } + try { + emitting = true; + const logger = logs.getLogger( + INSTRUMENTATION_SCOPE_NAME, + INSTRUMENTATION_SCOPE_VERSION, + ); + if ( + logger.enabled({ + context: activeContext, + severityNumber: SeverityNumber.DEBUG, + }) + ) { + const rendered = format(...args).replace(ANSI_ESCAPE, ""); + const redacted = + rendered.length <= MAX_BODY_LENGTH + ? redactText(rendered, options) + : undefined; + const body = + redacted !== undefined && + redacted.length <= MAX_BODY_LENGTH + ? redacted + : "[typeagent debug output truncated]"; + logger.emit({ + context: activeContext, + severityNumber: SeverityNumber.DEBUG, + severityText: "DEBUG", + eventName: "debug", + body, + attributes: { + "debug.namespace": namespace, + }, + }); + } + } catch { + // The original debug output already ran. Bridge failures lose + // only the OTel copy and never recurse through diagnostics. + } finally { + emitting = false; + } + return result; + }; + debugModule.log = wrappedLog; + installedBridges.set(debugModule, { + priorLog, + wrappedLog, + refCount: 1, + }); + installed.push(debugModule); + } + + let shutdown = false; + return { + shutdown(): void { + if (shutdown) { + return; + } + shutdown = true; + for (const debugModule of installed) { + const state = installedBridges.get(debugModule); + if (state === undefined) { + continue; + } + state.refCount--; + if (state.refCount > 0) { + continue; + } + if (debugModule.log === state.wrappedLog) { + debugModule.log = state.priorLog; + } + installedBridges.delete(debugModule); + } + }, + }; +} diff --git a/ts/packages/telemetry/src/otel/index.ts b/ts/packages/telemetry/src/otel/index.ts index 2db96ab483..3f80720404 100644 --- a/ts/packages/telemetry/src/otel/index.ts +++ b/ts/packages/telemetry/src/otel/index.ts @@ -12,6 +12,19 @@ export { type ResolveTelemetryConfigOptions, } from "./config.js"; +export { + installDebugBridge, + type DebugBridge, + type DebugBridgeOptions, + type DebugModule, +} from "./debugBridge.js"; + +export { + JsonlLogExporter, + resolveJsonlLogPath, + type JsonlLogExporterOptions, +} from "./jsonlLogExporter.js"; + export { createTelemetryLifecycle, TelemetryLifecycleClosedError, diff --git a/ts/packages/telemetry/src/otel/jsonlLogExporter.ts b/ts/packages/telemetry/src/otel/jsonlLogExporter.ts new file mode 100644 index 0000000000..701664eb50 --- /dev/null +++ b/ts/packages/telemetry/src/otel/jsonlLogExporter.ts @@ -0,0 +1,235 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +import * as fs from "node:fs/promises"; +import * as path from "node:path"; +import { ExportResultCode, type ExportResult } from "@opentelemetry/core"; +import type { + LogRecordExporter, + ReadableLogRecord, +} from "@opentelemetry/sdk-logs"; + +export interface JsonlLogExporterOptions { + readonly filePath: string; + readonly serviceName: string; + readonly pid?: number; + readonly maxPendingRecords?: number; + readonly diagnostic?: (message: string, error?: unknown) => void; +} + +const activePaths = new Set(); +const DEFAULT_MAX_PENDING_RECORDS = 2_048; +const DIAGNOSTIC_INTERVAL_MS = 60_000; + +export class JsonlLogExporter implements LogRecordExporter { + public readonly filePath: string; + private readonly maxPendingRecords: number; + private readonly diagnostic: (message: string, error?: unknown) => void; + private tail: Promise = Promise.resolve(); + private pendingRecords = 0; + private droppedRecords = 0; + private stopped = false; + private lastDiagnosticAt = 0; + + constructor(options: JsonlLogExporterOptions) { + this.filePath = resolveJsonlLogPath( + options.filePath, + options.serviceName, + options.pid, + ); + this.maxPendingRecords = + options.maxPendingRecords ?? DEFAULT_MAX_PENDING_RECORDS; + if ( + !Number.isInteger(this.maxPendingRecords) || + this.maxPendingRecords <= 0 + ) { + throw new Error( + "JSONL maxPendingRecords must be a positive integer.", + ); + } + if (activePaths.has(this.filePath)) { + throw new Error( + `A JSONL log exporter already owns "${this.filePath}" in this process.`, + ); + } + activePaths.add(this.filePath); + this.diagnostic = options.diagnostic ?? writeDiagnostic; + this.reportDiagnostic(`OpenTelemetry JSONL logs: ${this.filePath}`); + } + + public export( + records: ReadableLogRecord[], + resultCallback: (result: ExportResult) => void, + ): void { + if (this.stopped) { + resultCallback({ + code: ExportResultCode.FAILED, + error: new Error("JSONL log exporter is shut down."), + }); + return; + } + + const capacity = Math.max( + 0, + this.maxPendingRecords - this.pendingRecords, + ); + const accepted = records.slice(0, capacity); + const dropped = records.length - accepted.length; + if (dropped > 0) { + this.droppedRecords += dropped; + this.reportRateLimited( + `OpenTelemetry JSONL queue full; dropped ${dropped} record(s), ${this.droppedRecords} total.`, + ); + } + if (accepted.length === 0) { + resultCallback({ code: ExportResultCode.SUCCESS }); + return; + } + + let content: string; + try { + content = accepted.map(serializeLogRecord).join(""); + } catch (error) { + this.droppedRecords += accepted.length; + this.reportRateLimited( + `OpenTelemetry JSONL serialization failed; dropped ${accepted.length} record(s).`, + error, + ); + resultCallback({ + code: ExportResultCode.FAILED, + error: asError(error), + }); + return; + } + + this.pendingRecords += accepted.length; + const operation = this.tail.then(async () => { + await fs.mkdir(path.dirname(this.filePath), { recursive: true }); + await fs.appendFile(this.filePath, content, "utf8"); + }); + this.tail = operation.catch(() => undefined); + void operation + .then( + () => resultCallback({ code: ExportResultCode.SUCCESS }), + (error) => { + this.droppedRecords += accepted.length; + this.reportRateLimited( + `OpenTelemetry JSONL write failed; dropped ${accepted.length} record(s).`, + error, + ); + resultCallback({ + code: ExportResultCode.FAILED, + error: asError(error), + }); + }, + ) + .finally(() => { + this.pendingRecords -= accepted.length; + }); + } + + public forceFlush(): Promise { + return this.tail; + } + + public async shutdown(): Promise { + if (this.stopped) { + await this.tail; + return; + } + this.stopped = true; + try { + await this.tail; + } finally { + activePaths.delete(this.filePath); + } + } + + public getDroppedRecordCount(): number { + return this.droppedRecords; + } + + private reportRateLimited(message: string, error?: unknown): void { + const now = Date.now(); + if (now - this.lastDiagnosticAt < DIAGNOSTIC_INTERVAL_MS) { + return; + } + this.lastDiagnosticAt = now; + this.reportDiagnostic(message, error); + } + + private reportDiagnostic(message: string, error?: unknown): void { + try { + this.diagnostic(message, error); + } catch { + // Diagnostics must never affect exporter ownership or requests. + } + } +} + +export function resolveJsonlLogPath( + template: string, + serviceName: string, + pid = process.pid, +): string { + if (!Number.isInteger(pid) || pid <= 0) { + throw new Error("JSONL pid must be a positive integer."); + } + const service = sanitizePathSegment(serviceName); + const hadPidPlaceholder = template.includes("{pid}"); + let resolved = template + .replaceAll("{service}", service) + .replaceAll("{pid}", String(pid)); + if (!hadPidPlaceholder) { + const parsed = path.parse(resolved); + resolved = path.join( + parsed.dir, + `${parsed.name}-${pid}${parsed.ext || ".jsonl"}`, + ); + } + return path.resolve(resolved); +} + +function sanitizePathSegment(value: string): string { + const sanitized = value + .replace(/[<>:"/\\|?*\u0000-\u001f]/g, "_") + .replace(/[. ]+$/g, "") + .slice(0, 64); + return sanitized || "typeagent"; +} + +function serializeLogRecord(record: ReadableLogRecord): string { + const serialized = JSON.stringify({ + timestamp: hrTimeToIso(record.hrTime), + observedTimestamp: hrTimeToIso(record.hrTimeObserved), + severityText: record.severityText, + severityNumber: record.severityNumber, + body: record.body, + resource: record.resource.attributes, + eventName: record.eventName, + traceId: record.spanContext?.traceId, + spanId: record.spanContext?.spanId, + traceFlags: record.spanContext?.traceFlags, + attributes: record.attributes, + instrumentationScope: { + name: record.instrumentationScope.name, + version: record.instrumentationScope.version, + attributes: record.instrumentationScope.attributes, + }, + droppedAttributesCount: record.droppedAttributesCount, + }); + return `${serialized}\n`; +} + +function hrTimeToIso([seconds, nanos]: readonly [number, number]): string { + return new Date(seconds * 1_000 + nanos / 1_000_000).toISOString(); +} + +function writeDiagnostic(message: string, error?: unknown): void { + const suffix = error === undefined ? "" : ` ${asError(error).message}`; + process.stderr.write(`[typeagent:telemetry] ${message}${suffix}\n`); +} + +function asError(error: unknown): Error { + return error instanceof Error ? error : new Error(String(error)); +} diff --git a/ts/packages/telemetry/test/otelBootstrap.spec.ts b/ts/packages/telemetry/test/otelBootstrap.spec.ts index 273771c5e5..61a870e930 100644 --- a/ts/packages/telemetry/test/otelBootstrap.spec.ts +++ b/ts/packages/telemetry/test/otelBootstrap.spec.ts @@ -1,6 +1,9 @@ // Copyright (c) Microsoft Corporation. // Licensed under the MIT License. +import * as fs from "node:fs"; +import * as os from "node:os"; +import * as path from "node:path"; import { context, metrics, propagation, trace } from "@opentelemetry/api"; import { logs } from "@opentelemetry/api-logs"; import { @@ -464,15 +467,33 @@ describe("telemetry bootstrap", () => { expect(resource?.attributes["service.name"]).toBe("typeagent"); }); - it("rejects the unsupported default JSONL writer path", async () => { + it("supports the default JSONL-only log provider", async () => { const coordinator = createCoordinator(); - - await expect( - coordinator.init({ - config: { logs: { logFile: "telemetry.jsonl" } }, - resource: resourceFromAttributes({}), - }), - ).rejects.toThrow(/JSONL output is not implemented/); + const dir = fs.mkdtempSync( + path.join(os.tmpdir(), "typeagent-otel-bootstrap-"), + ); + try { + await coordinator.init({ + config: { + logs: { + logFile: path.join(dir, "telemetry-{pid}.jsonl"), + }, + }, + serviceName: "bootstrap-test", + }); + const logger = logs.getLogger("bootstrap-test"); + logger.emit({ body: "jsonl works" }); + await coordinator.shutdown(); + + const files = fs.readdirSync(dir); + expect(files).toHaveLength(1); + const line = fs + .readFileSync(path.join(dir, files[0]!), "utf8") + .trim(); + expect(JSON.parse(line).body).toBe("jsonl works"); + } finally { + fs.rmSync(dir, { recursive: true, force: true }); + } }); it("refuses trace and log providers installed by other owners", async () => { diff --git a/ts/packages/telemetry/test/otelConfig.spec.ts b/ts/packages/telemetry/test/otelConfig.spec.ts index b3b8650d85..c56820be90 100644 --- a/ts/packages/telemetry/test/otelConfig.spec.ts +++ b/ts/packages/telemetry/test/otelConfig.spec.ts @@ -63,6 +63,27 @@ describe("resolveTelemetryConfig", () => { }); }); + it("resolves the debug bridge from YAML and environment", () => { + withTempWorkspace((root) => { + writeYaml( + root, + "config.local.yaml", + "telemetry:\n debugBridge: true\n", + ); + expect(resolve(root).debugBridge).toBe(true); + expect( + resolve(root, { + env: { TYPEAGENT_OTEL_DEBUG_BRIDGE: "off" }, + }).debugBridge, + ).toBe(false); + expect(() => + resolve(root, { + env: { TYPEAGENT_OTEL_DEBUG_BRIDGE: "sometimes" }, + }), + ).toThrow(/expected true\/false/); + }); + }); + /* ------------------------------------------------------------------ */ /* YAML endpoint */ /* ------------------------------------------------------------------ */ diff --git a/ts/packages/telemetry/test/otelLocalDiagnostics.spec.ts b/ts/packages/telemetry/test/otelLocalDiagnostics.spec.ts new file mode 100644 index 0000000000..ef37df8fc9 --- /dev/null +++ b/ts/packages/telemetry/test/otelLocalDiagnostics.spec.ts @@ -0,0 +1,387 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +import * as fs from "node:fs"; +import * as os from "node:os"; +import * as path from "node:path"; +import { context, trace } from "@opentelemetry/api"; +import { logs } from "@opentelemetry/api-logs"; +import { AsyncLocalStorageContextManager } from "@opentelemetry/context-async-hooks"; +import { ExportResultCode } from "@opentelemetry/core"; +import { resourceFromAttributes } from "@opentelemetry/resources"; +import { + InMemoryLogRecordExporter, + LoggerProvider, + SimpleLogRecordProcessor, + type ReadableLogRecord, +} from "@opentelemetry/sdk-logs"; +import { NodeTracerProvider } from "@opentelemetry/sdk-trace-node"; + +import { createOtelLoggerSink } from "../src/logger/otelLoggerSink.js"; +import { installDebugBridge } from "../src/otel/debugBridge.js"; +import type { DebugModule } from "../src/otel/debugBridge.js"; +import { + JsonlLogExporter, + resolveJsonlLogPath, +} from "../src/otel/jsonlLogExporter.js"; + +function makeTempDir(): string { + return fs.mkdtempSync(path.join(os.tmpdir(), "typeagent-otel-local-")); +} + +function createRecord(body: string): ReadableLogRecord { + return { + hrTime: [1_700_000_000, 0], + hrTimeObserved: [1_700_000_001, 0], + severityText: "INFO", + body, + resource: resourceFromAttributes({ "service.name": "test" }), + instrumentationScope: { name: "test", version: "1" }, + attributes: {}, + droppedAttributesCount: 0, + }; +} + +function exportRecords( + exporter: JsonlLogExporter, + records: ReadableLogRecord[], +): Promise { + return new Promise((resolve) => { + exporter.export(records, (result) => resolve(result.code)); + }); +} + +function createDebugModule( + output: Array<{ namespace: string | undefined; args: unknown[] }>, +): DebugModule { + return { + log(this: { namespace?: string }, ...args: unknown[]): void { + output.push({ namespace: this?.namespace, args }); + }, + }; +} + +describe("JsonlLogExporter", () => { + const tempDirs: string[] = []; + + afterEach(() => { + for (const dir of tempDirs.splice(0)) { + fs.rmSync(dir, { recursive: true, force: true }); + } + }); + + it("resolves a sanitized per-process path", () => { + const resolved = resolveJsonlLogPath( + path.join("logs", "typeagent-{service}.jsonl"), + "agent/server", + 1234, + ); + expect(resolved).toBe( + path.resolve("logs", "typeagent-agent_server-1234.jsonl"), + ); + }); + + it("writes independently valid JSON lines in accepted order", async () => { + const dir = makeTempDir(); + tempDirs.push(dir); + const exporter = new JsonlLogExporter({ + filePath: path.join(dir, "logs-{pid}.jsonl"), + serviceName: "test", + pid: 1001, + diagnostic: () => undefined, + }); + + expect( + await exportRecords(exporter, [ + createRecord("first"), + createRecord("second"), + ]), + ).toBe(ExportResultCode.SUCCESS); + await exporter.shutdown(); + + const lines = fs + .readFileSync(exporter.filePath, "utf8") + .trimEnd() + .split("\n") + .map((line) => JSON.parse(line) as { body: string }); + expect(lines.map((line) => line.body)).toEqual(["first", "second"]); + }); + + it("bounds pending records and accounts for drops", async () => { + const dir = makeTempDir(); + tempDirs.push(dir); + const exporter = new JsonlLogExporter({ + filePath: path.join(dir, "bounded-{pid}.jsonl"), + serviceName: "test", + pid: 1002, + maxPendingRecords: 2, + diagnostic: () => undefined, + }); + + await exportRecords(exporter, [ + createRecord("one"), + createRecord("two"), + createRecord("three"), + ]); + await exporter.shutdown(); + + expect(exporter.getDroppedRecordCount()).toBe(1); + expect( + fs.readFileSync(exporter.filePath, "utf8").trimEnd().split("\n"), + ).toHaveLength(2); + }); + + it("isolates write failures and releases path ownership on shutdown", async () => { + const dir = makeTempDir(); + tempDirs.push(dir); + const blockingFile = path.join(dir, "not-a-directory"); + fs.writeFileSync(blockingFile, "x"); + const template = path.join(blockingFile, "logs-{pid}.jsonl"); + const exporter = new JsonlLogExporter({ + filePath: template, + serviceName: "test", + pid: 1003, + diagnostic: () => undefined, + }); + expect( + () => + new JsonlLogExporter({ + filePath: template, + serviceName: "test", + pid: 1003, + diagnostic: () => undefined, + }), + ).toThrow(/already owns/); + + expect(await exportRecords(exporter, [createRecord("lost")])).toBe( + ExportResultCode.FAILED, + ); + expect(exporter.getDroppedRecordCount()).toBe(1); + await exporter.shutdown(); + + const replacement = new JsonlLogExporter({ + filePath: template, + serviceName: "test", + pid: 1003, + diagnostic: () => undefined, + }); + await replacement.shutdown(); + }); + + it("isolates diagnostic callback failures without leaking ownership", async () => { + const dir = makeTempDir(); + tempDirs.push(dir); + const template = path.join(dir, "diagnostic-{pid}.jsonl"); + const exporter = new JsonlLogExporter({ + filePath: template, + serviceName: "test", + pid: 1004, + diagnostic: () => { + throw new Error("diagnostic failed"); + }, + }); + await exporter.shutdown(); + + const replacement = new JsonlLogExporter({ + filePath: template, + serviceName: "test", + pid: 1004, + diagnostic: () => undefined, + }); + await replacement.shutdown(); + }); +}); + +describe("debug bridge", () => { + let provider: LoggerProvider | undefined; + + afterEach(async () => { + await provider?.shutdown(); + provider = undefined; + logs.disable(); + }); + + it("tees distinct debug modules exactly once and restores prior output", () => { + const exporter = new InMemoryLogRecordExporter(); + provider = new LoggerProvider({ + processors: [new SimpleLogRecordProcessor({ exporter })], + }); + logs.setGlobalLoggerProvider(provider); + const firstOutput: Array<{ + namespace: string | undefined; + args: unknown[]; + }> = []; + const secondOutput: Array<{ + namespace: string | undefined; + args: unknown[]; + }> = []; + const first = createDebugModule(firstOutput); + const second = createDebugModule(secondOutput); + const firstPrior = first.log; + const secondPrior = second.log; + const bridge = installDebugBridge([first, second, first]); + + first.log.call( + { namespace: "typeagent:first" }, + "\u001b[31mfirst\u001b[0m", + ); + second.log.call({ namespace: "typeagent:second" }, "second"); + first.log.call({ namespace: "other:first" }, "ignored"); + second.log.call({ namespace: "typeagent:logger:db" }, "excluded"); + + expect(firstOutput).toHaveLength(2); + expect(secondOutput).toHaveLength(2); + const records = exporter.getFinishedLogRecords(); + expect(records).toHaveLength(2); + expect(records.map((record) => record.body)).toEqual([ + "first", + "second", + ]); + expect( + records.map((record) => record.attributes["debug.namespace"]), + ).toEqual(["typeagent:first", "typeagent:second"]); + + bridge.shutdown(); + bridge.shutdown(); + expect(first.log).toBe(firstPrior); + expect(second.log).toBe(secondPrior); + }); + + it("does not overwrite a later owner during restoration", () => { + const debugModule = createDebugModule([]); + const bridge = installDebugBridge([debugModule]); + const replacement = () => undefined; + debugModule.log = replacement; + + bridge.shutdown(); + + expect(debugModule.log).toBe(replacement); + }); + + it("keeps the bridge installed until every installation shuts down", () => { + const debugModule = createDebugModule([]); + const prior = debugModule.log; + const first = installDebugBridge([debugModule]); + const wrapped = debugModule.log; + const second = installDebugBridge([debugModule]); + + first.shutdown(); + expect(debugModule.log).toBe(wrapped); + second.shutdown(); + expect(debugModule.log).toBe(prior); + }); + + it("suppresses reentrant debug output from the OTel logger path", () => { + const output: Array<{ + namespace: string | undefined; + args: unknown[]; + }> = []; + const debugModule = createDebugModule(output); + const bridge = installDebugBridge([debugModule]); + let emitCalls = 0; + logs.setGlobalLoggerProvider({ + getLogger() { + return { + enabled() { + debugModule.log.call( + { namespace: "typeagent:otel-internal" }, + "inner", + ); + return true; + }, + emit() { + emitCalls++; + }, + }; + }, + }); + + debugModule.log.call({ namespace: "typeagent:outer" }, "outer"); + + expect(output.map((entry) => entry.args[0])).toEqual([ + "outer", + "inner", + ]); + expect(emitCalls).toBe(1); + bridge.shutdown(); + }); +}); + +describe("local diagnostics correlation", () => { + it("writes structured and debug records with the same active span", async () => { + const dir = makeTempDir(); + const jsonlExporter = new JsonlLogExporter({ + filePath: path.join(dir, "correlated-{pid}.jsonl"), + serviceName: "test", + pid: 1005, + diagnostic: () => undefined, + }); + const logProvider = new LoggerProvider({ + processors: [ + new SimpleLogRecordProcessor({ exporter: jsonlExporter }), + ], + }); + const traceProvider = new NodeTracerProvider(); + const contextManager = new AsyncLocalStorageContextManager().enable(); + logs.setGlobalLoggerProvider(logProvider); + trace.setGlobalTracerProvider(traceProvider); + context.setGlobalContextManager(contextManager); + const debugModule = createDebugModule([]); + const bridge = installDebugBridge([debugModule]); + const sink = createOtelLoggerSink({ diagnostic: () => undefined }); + + let expectedTraceId = ""; + let expectedSpanId = ""; + try { + trace + .getTracer("local-diagnostics") + .startActiveSpan("correlated", (span) => { + expectedTraceId = span.spanContext().traceId; + expectedSpanId = span.spanContext().spanId; + sink.logEvent({ + eventName: "structured", + timestamp: new Date().toISOString(), + event: { sessionId: "session" }, + }); + debugModule.log.call( + { namespace: "typeagent:correlated" }, + "debug", + ); + span.end(); + }); + await logProvider.forceFlush(); + await logProvider.shutdown(); + + const records = fs + .readFileSync(jsonlExporter.filePath, "utf8") + .trimEnd() + .split("\n") + .map( + (line) => + JSON.parse(line) as { + eventName: string; + traceId: string; + spanId: string; + }, + ); + expect(records.map((record) => record.eventName)).toEqual([ + "structured", + "debug", + ]); + for (const record of records) { + expect(record.traceId).toBe(expectedTraceId); + expect(record.spanId).toBe(expectedSpanId); + } + } finally { + bridge.shutdown(); + await Promise.allSettled([ + logProvider.shutdown(), + traceProvider.shutdown(), + ]); + logs.disable(); + trace.disable(); + context.disable(); + fs.rmSync(dir, { recursive: true, force: true }); + } + }); +}); diff --git a/ts/packages/telemetry/test/otelLoggerSink.spec.ts b/ts/packages/telemetry/test/otelLoggerSink.spec.ts index 88e99415ff..fd84d6ef03 100644 --- a/ts/packages/telemetry/test/otelLoggerSink.spec.ts +++ b/ts/packages/telemetry/test/otelLoggerSink.spec.ts @@ -141,7 +141,9 @@ describe("OtelLoggerSink", () => { it("maps a Structured Logger event to a complete OTel log record", () => { logFixture = installLogFixture(); - const sink = createOtelLoggerSink(); + const sink = createOtelLoggerSink({ + diagnostic: () => undefined, + }); sink.logEvent( baseEvent({ From 6ec579beea1d06e774973152083853a4d4ccd243 Mon Sep 17 00:00:00 2001 From: George Ng <146492653+GeorgeNgMsft@users.noreply.github.com> Date: Wed, 12 Aug 2026 15:11:36 -0700 Subject: [PATCH 03/13] [OTEL] Wire logging into TypeAgent hosts (#2854) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ### Summary Builds on the previously-landed `OtelLoggerSink`, debug bridge, and JSONL exporter by **wiring them into every TypeAgent-owned Node host** and making structured-log export **explicitly opt-in**. No new telemetry primitives — this is composition, gating, and hardening. Existing `debug`/`DEBUG` output is unchanged. ### Changes **Configuration-driven structured logs** • Adds  telemetry.structuredLogs , defaulting to  false  because dispatcher event payloads may contain user data. • Supports the  TYPEAGENT_OTEL_STRUCTURED_LOGS  environment override. • Hosts resolve telemetry configuration once and pass the effective value into  DispatcherOptions.telemetry.structuredLogs . •  getLoggerSink  attaches  OtelLoggerSink  only when structured logging is enabled. Existing debug and database sinks are unchanged. • Agent server, API, and standalone shell apply the setting to the dispatchers they create. **Host telemetry and debug-bridge wiring** • Wires  initTelemetry({ config, debugModules, debugBridge })  into the agent server, API, and shell composition roots. • CLI entry points and agent subprocesses provide their  debug  module instances to telemetry initialization. • Agent-server hosts include the legacy  agent-server:*  namespace without renaming namespaces or breaking existing  DEBUG  configurations. • Prompt logger output remains intentionally excluded from the debug bridge. **Agent subprocess support** • Resolves an agent’s local  debug  package before telemetry initialization so separately installed module instances are bridged. • Uses CommonJS resolution rather than importing an absolute filesystem path, preserving Windows compatibility. • Extracts this behavior into  agentDebug.ts  with coverage for agent-local and shared module instances. **Debug-bridge hardening** • Adds configurable included namespace prefixes while retaining  typeagent:*  as the default. • Tracks effective bridge options for each installed module. • Rejects repeated installation with conflicting namespace or redaction options instead of silently ignoring the later policy. • Preserves idempotent, reference-counted installation when options match. **Tests** • Covers real  debug  instances created before and after bridge installation. • Covers multiple debug module instances, restoration, reference counting, and conflicting options. • Verifies legacy namespace inclusion and continued prompt logger exclusion. • Covers YAML and environment resolution for  telemetry.structuredLogs . • Covers Windows-safe agent-local debug module loading. --------- Copilot-Session: 6407aa6e-4d59-49ec-9fa4-5a321f2971ef --- ts/config.sample.yaml | 1 + .../architecture/telemetry/opentelemetry.md | 21 ++++- ts/packages/agentServer/server/src/server.ts | 12 ++- ts/packages/api/src/index.ts | 12 ++- ts/packages/api/src/typeAgentServer.ts | 7 +- ts/packages/api/src/webDispatcher.ts | 7 +- ts/packages/cli/bin/dev.js | 3 +- ts/packages/cli/bin/run.js | 3 +- .../src/context/commandHandlerContext.ts | 27 +++++-- .../src/agentProvider/process/agentDebug.ts | 26 +++++++ .../src/agentProvider/process/agentProcess.ts | 34 ++++---- .../nodeProviders/test/agentDebug.spec.ts | 45 +++++++++++ ts/packages/shell/src/main/index.ts | 15 +++- ts/packages/shell/src/main/instance.ts | 4 + .../telemetry/src/logger/otelLoggerSink.ts | 4 +- ts/packages/telemetry/src/otel/config.ts | 15 ++++ ts/packages/telemetry/src/otel/debugBridge.ts | 72 +++++++++++++++-- .../telemetry/test/otelBootstrap.spec.ts | 18 +++++ ts/packages/telemetry/test/otelConfig.spec.ts | 21 +++++ .../test/otelLocalDiagnostics.spec.ts | 78 +++++++++++++++++++ 20 files changed, 379 insertions(+), 46 deletions(-) create mode 100644 ts/packages/dispatcher/nodeProviders/src/agentProvider/process/agentDebug.ts create mode 100644 ts/packages/dispatcher/nodeProviders/test/agentDebug.spec.ts diff --git a/ts/config.sample.yaml b/ts/config.sample.yaml index 34c9168ea2..2f4ffdfd0f 100644 --- a/ts/config.sample.yaml +++ b/ts/config.sample.yaml @@ -411,5 +411,6 @@ typeagent: # otlpEndpoint: http://localhost:4318 # logFile: ~/.typeagent/logs/typeagent-{service}-{pid}.jsonl # debugBridge: true +# structuredLogs: true # tracesSampler: parentbased_traceidratio # tracesSamplerArg: 0.1 diff --git a/ts/docs/architecture/telemetry/opentelemetry.md b/ts/docs/architecture/telemetry/opentelemetry.md index 72def308ae..4e4746b059 100644 --- a/ts/docs/architecture/telemetry/opentelemetry.md +++ b/ts/docs/architecture/telemetry/opentelemetry.md @@ -106,10 +106,18 @@ Logs require explicit composition: - Install the debug bridge to copy enabled TypeAgent debug output. - Installing an OTel SDK alone does neither. -The logger severity contract and `OtelLoggerSink` in this PR are library -foundation only. They do not attach the sink to a runtime logger or configure a -provider. A later host-wiring PR performs that composition in TypeAgent-owned -Node hosts. +TypeAgent-owned Node composition roots attach `OtelLoggerSink` alongside the +existing debug and database sinks when `telemetry.structuredLogs` is enabled. +The setting defaults to false so embedded dispatcher consumers do not export +event payloads merely because another component installed a global OTel logs +provider. The environment override is +`TYPEAGENT_OTEL_STRUCTURED_LOGS=true`. Hosts also pass each process's `debug` +module instance to `initTelemetry()` so the optional bridge can preserve +existing output while copying eligible records into OTel. + +The dispatcher prompt logger is intentionally not connected to +`OtelLoggerSink`, and its debug namespace remains excluded from the bridge. +Prompt capture requires a separate explicit privacy-reviewed design. The sink emits through the host's global Logs API and does not create a provider. Embeddable libraries never install a process-wide debug hook. A partner may @@ -121,6 +129,11 @@ TypeAgent-owned Node hosts call `initTelemetry()` once and per enabled signal and exports directly. Libraries, agents, requests, and sessions do not create providers. +The bridge includes `typeagent:*` namespaces by default. TypeAgent-owned hosts +may explicitly include a stable legacy prefix that they own. Agent server hosts +include `agent-server:*` this way rather than renaming existing namespaces and +breaking current `DEBUG` configurations. + Global provider registration is first-writer-wins. TypeAgent bootstrap runs before instrumentation and reports an unexpected existing provider as a configuration conflict. Shutdown is idempotent but does not make telemetry diff --git a/ts/packages/agentServer/server/src/server.ts b/ts/packages/agentServer/server/src/server.ts index 3a85ca672b..8e07b8945e 100644 --- a/ts/packages/agentServer/server/src/server.ts +++ b/ts/packages/agentServer/server/src/server.ts @@ -178,7 +178,14 @@ process.once("message", (message) => { // Load config from YAML layers + Key Vault (replacing legacy dotenv). // vault.shared is auto-discovered from config.local.yaml / config.defaults.yaml. await loadConfig({ keyVault: {}, strict: false }); -const telemetryInit = otel.initTelemetry(); +const telemetryConfig = otel.resolveTelemetryConfig(); +const telemetryInit = otel.initTelemetry({ + config: telemetryConfig, + debugModules: [registerDebug], + debugBridge: { + includedNamespacePrefixes: ["typeagent:", "agent-server:"], + }, +}); // Snapshot whether this server's local config differs from the shared Key // Vault, so clients can be warned on connect (same delivery path as the @@ -340,6 +347,9 @@ async function main() { dblogging: true, developerMode, traceId, + telemetry: { + structuredLogs: telemetryConfig.structuredLogs === true, + }, indexingServiceRegistry: await getIndexingServiceRegistry( instanceDir, configName, diff --git a/ts/packages/api/src/index.ts b/ts/packages/api/src/index.ts index b43bf44c16..c539a181e1 100644 --- a/ts/packages/api/src/index.ts +++ b/ts/packages/api/src/index.ts @@ -4,6 +4,7 @@ import { TypeAgentServer } from "./typeAgentServer.js"; import { loadConfig } from "@typeagent/config"; import { otel } from "@typeagent/telemetry"; +import registerDebug from "debug"; let typeAgentServer: TypeAgentServer | undefined; let shutdownPromise: Promise | undefined; @@ -40,14 +41,21 @@ process.once("SIGTERM", () => { async function main(): Promise { // Load config from YAML layers + Key Vault (replacing legacy dotenv). await loadConfig({ keyVault: {}, strict: false }); - await otel.initTelemetry(); + const telemetryConfig = otel.resolveTelemetryConfig(); + await otel.initTelemetry({ + config: telemetryConfig, + debugModules: [registerDebug], + debugBridge: { + includedNamespacePrefixes: ["typeagent:", "agent-server:"], + }, + }); if (shutdownRequested) { return; } typeAgentServer = new TypeAgentServer((exitCode) => { void shutdownHost(exitCode); - }); + }, telemetryConfig.structuredLogs === true); await typeAgentServer.start(); } diff --git a/ts/packages/api/src/typeAgentServer.ts b/ts/packages/api/src/typeAgentServer.ts index 6af4506b0d..9eab7ea9d5 100644 --- a/ts/packages/api/src/typeAgentServer.ts +++ b/ts/packages/api/src/typeAgentServer.ts @@ -40,7 +40,10 @@ export class TypeAgentServer { private storageProvider: TypeAgentStorageProvider | undefined; private config: TypeAgentAPIServerConfig; - constructor(private readonly requestExit: (exitCode: number) => void) { + constructor( + private readonly requestExit: (exitCode: number) => void, + private readonly structuredLogs: boolean, + ) { // Build typed runtime Config from process.env (already populated // by loadConfig in the entry point) so aiclient consumers can // use the typed accessor; legacy callers still see the same @@ -83,7 +86,7 @@ export class TypeAgentServer { sw.stop("Downloaded Session Backup"); } - this.webDispatcher = await createWebDispatcher(); + this.webDispatcher = await createWebDispatcher(this.structuredLogs); debug("Web Dispatcher created."); // web server diff --git a/ts/packages/api/src/webDispatcher.ts b/ts/packages/api/src/webDispatcher.ts index 5288ac9414..16f46368ae 100644 --- a/ts/packages/api/src/webDispatcher.ts +++ b/ts/packages/api/src/webDispatcher.ts @@ -34,7 +34,9 @@ export interface WebDispatcher { handleAction(action: FullAction): Promise; } -export async function createWebDispatcher(): Promise { +export async function createWebDispatcher( + structuredLogs: boolean, +): Promise { let ws: WebSocket | null = null; const clientIOChannel = createChannelAdapter((message: any) => ws?.send( @@ -62,6 +64,9 @@ export async function createWebDispatcher(): Promise { metrics: true, dblogging: true, traceId: getTraceId(), + telemetry: { + structuredLogs, + }, clientIO: clientIO, constructionProvider: getDefaultConstructionProvider(), indexingServiceRegistry: await getIndexingServiceRegistry(instanceDir), diff --git a/ts/packages/cli/bin/dev.js b/ts/packages/cli/bin/dev.js index af7b9bbe4d..8b1cbe84e0 100755 --- a/ts/packages/cli/bin/dev.js +++ b/ts/packages/cli/bin/dev.js @@ -4,6 +4,7 @@ import { loadConfigSync } from "@typeagent/config"; import { otel } from "@typeagent/telemetry"; +import registerDebug from "debug"; import { registerEarlyTelemetrySignalHandlers } from "../src/telemetry.ts"; loadConfigSync(); @@ -15,7 +16,7 @@ async function main() { process.env.NODE_ENV = "development"; settings.debug = true; try { - await otel.initTelemetry(); + await otel.initTelemetry({ debugModules: [registerDebug] }); await run(process.argv.slice(2), import.meta.url); await flush(); await otel.shutdownTelemetry(); diff --git a/ts/packages/cli/bin/run.js b/ts/packages/cli/bin/run.js index 6502d20e01..e46cdaaf3a 100755 --- a/ts/packages/cli/bin/run.js +++ b/ts/packages/cli/bin/run.js @@ -4,6 +4,7 @@ import { loadConfigSync } from "@typeagent/config"; import { otel } from "@typeagent/telemetry"; +import registerDebug from "debug"; import { registerEarlyTelemetrySignalHandlers } from "../dist/telemetry.js"; loadConfigSync(); @@ -12,7 +13,7 @@ registerEarlyTelemetrySignalHandlers(); async function main() { const { flush, handle, run } = await import("@oclif/core"); try { - await otel.initTelemetry(); + await otel.initTelemetry({ debugModules: [registerDebug] }); await run(process.argv.slice(2), import.meta.url); await flush(); await otel.shutdownTelemetry(); diff --git a/ts/packages/dispatcher/dispatcher/src/context/commandHandlerContext.ts b/ts/packages/dispatcher/dispatcher/src/context/commandHandlerContext.ts index e98a744d39..2b4c4ccea0 100644 --- a/ts/packages/dispatcher/dispatcher/src/context/commandHandlerContext.ts +++ b/ts/packages/dispatcher/dispatcher/src/context/commandHandlerContext.ts @@ -13,6 +13,7 @@ import { MultiSinkLogger, createDebugLoggerSink, createDatabaseLoggerSink, + createOtelLoggerSink, CosmosContainerClientFactory, CosmosPartitionKeyBuilderFactory, PromptLogger, @@ -599,6 +600,11 @@ export type DispatcherOptions = DeepPartialUndefined & { * Default false: each request starts a new trace. */ joinActiveTrace?: boolean; + /** + * Export structured dispatcher events through the global OTel logs + * provider. Default false because event payloads may contain user data. + */ + structuredLogs?: boolean; }; // Additional integration options @@ -727,7 +733,11 @@ function getCosmosFactories(): PromptLoggerOptions { return result; } -function getLoggerSink(isDbEnabled: () => boolean, clientIO: ClientIO) { +function getLoggerSink( + isDbEnabled: () => boolean, + clientIO: ClientIO, + structuredLogs: boolean, +) { const debugLoggerSink = createDebugLoggerSink(); let dbLoggerSink: LoggerSink | undefined; @@ -759,11 +769,14 @@ function getLoggerSink(isDbEnabled: () => boolean, clientIO: ClientIO) { ); } - return new MultiSinkLogger( + const sinks = dbLoggerSink === undefined ? [debugLoggerSink] - : [debugLoggerSink, dbLoggerSink], - ); + : [debugLoggerSink, dbLoggerSink]; + if (structuredLogs) { + sinks.push(createOtelLoggerSink()); + } + return new MultiSinkLogger(sinks); } async function lockEmbeddingCacheDir(context: CommandHandlerContext) { @@ -1206,7 +1219,11 @@ export async function initializeCommandHandlerContext( const sessionDirPath = session.getSessionDirPath(); debug(`Session directory: ${sessionDirPath}`); const clientIO = options?.clientIO ?? nullClientIO; - const loggerSink = getLoggerSink(() => context.dblogging, clientIO); + const loggerSink = getLoggerSink( + () => context.dblogging, + clientIO, + options?.telemetry?.structuredLogs === true, + ); const activationId = randomUUID(); const traceId = options?.traceId; const logger = new ChildLogger(loggerSink, DispatcherName, { diff --git a/ts/packages/dispatcher/nodeProviders/src/agentProvider/process/agentDebug.ts b/ts/packages/dispatcher/nodeProviders/src/agentProvider/process/agentDebug.ts new file mode 100644 index 0000000000..9cdd1f3873 --- /dev/null +++ b/ts/packages/dispatcher/nodeProviders/src/agentProvider/process/agentDebug.ts @@ -0,0 +1,26 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +import registerDebug from "debug"; +import { createRequire } from "node:module"; + +export interface AgentDebugModule { + readonly debug: typeof registerDebug; + readonly path: string; +} + +export function loadAgentDebug( + modulePath: string, + hostDebug: typeof registerDebug, +): AgentDebugModule | undefined { + try { + const require = createRequire(modulePath); + const debugPath = require.resolve("debug"); + const agentDebug = require(debugPath) as typeof registerDebug; + return agentDebug === hostDebug + ? undefined + : { debug: agentDebug, path: debugPath }; + } catch { + return undefined; + } +} diff --git a/ts/packages/dispatcher/nodeProviders/src/agentProvider/process/agentProcess.ts b/ts/packages/dispatcher/nodeProviders/src/agentProvider/process/agentProcess.ts index ee8bf4adc5..fe065f99c4 100644 --- a/ts/packages/dispatcher/nodeProviders/src/agentProvider/process/agentProcess.ts +++ b/ts/packages/dispatcher/nodeProviders/src/agentProvider/process/agentProcess.ts @@ -9,8 +9,8 @@ import { createAgentRpcServer, } from "@typeagent/agent-rpc/server"; import { createChannelProvider } from "@typeagent/agent-rpc/channel"; -import { createRequire } from "node:module"; import { otel } from "@typeagent/telemetry"; +import { loadAgentDebug } from "./agentDebug.js"; //================================================================= // Get arguments from command line @@ -37,7 +37,6 @@ if (!isIPCProcess(process)) { } const ipcProcess = process; -const telemetryInit = otel.initTelemetry(); let exitPromise: Promise | undefined; function exitAgentProcess(exitCode: number, message: string): Promise { @@ -74,10 +73,22 @@ process.on("SIGINT", () => { }); async function startAgentProcess(): Promise { + const loadedAgentDebug = loadAgentDebug(modulePath, registerDebug); + const agentDebug = loadedAgentDebug?.debug; + if (loadedAgentDebug !== undefined) { + debug( + `'${agentName}': Agent debug trace loaded. ${loadedAgentDebug.path}`, + ); + } + const debugModules = + agentDebug === undefined + ? [registerDebug] + : [registerDebug, agentDebug]; + await otel.initTelemetry({ debugModules }); + //================================================================= // Load the module. //================================================================= - await telemetryInit; const module = await import(modulePath); if (typeof module.instantiate !== "function") { throw new Error( @@ -115,23 +126,6 @@ async function startAgentProcess(): Promise { //================================================================= // Set up debug trace coordination //================================================================= - async function getAgentDebug(): Promise { - try { - // get the "debug" package from the module. - const require = createRequire(modulePath); - const debugPath = require.resolve("debug"); - const agentDebug = (await import(debugPath)).default; - if (agentDebug === registerDebug) { - return undefined; - } - debug(`'${agentName}': Agent debug trace loaded. ${debugPath}`); - return agentDebug; - } catch { - return undefined; - } - } - - const agentDebug = await getAgentDebug(); const traceChannel = channelProvider.createChannel("trace"); traceChannel.on("message", (message) => { registerDebug.enable(message); diff --git a/ts/packages/dispatcher/nodeProviders/test/agentDebug.spec.ts b/ts/packages/dispatcher/nodeProviders/test/agentDebug.spec.ts new file mode 100644 index 0000000000..ca454d61b6 --- /dev/null +++ b/ts/packages/dispatcher/nodeProviders/test/agentDebug.spec.ts @@ -0,0 +1,45 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +import * as fs from "node:fs"; +import * as os from "node:os"; +import * as path from "node:path"; +import { fileURLToPath } from "node:url"; +import registerDebug from "debug"; + +import { loadAgentDebug } from "../src/agentProvider/process/agentDebug.js"; + +describe("loadAgentDebug", () => { + let tempDir: string; + + beforeEach(() => { + tempDir = fs.mkdtempSync(path.join(os.tmpdir(), "agent-debug-")); + }); + + afterEach(() => { + fs.rmSync(tempDir, { recursive: true, force: true }); + }); + + test("loads an agent-local CommonJS debug module by absolute path", () => { + const modulePath = path.join(tempDir, "agent.js"); + const debugDir = path.join(tempDir, "node_modules", "debug"); + fs.mkdirSync(debugDir, { recursive: true }); + fs.writeFileSync(modulePath, "export function instantiate() {}\n"); + fs.writeFileSync( + path.join(debugDir, "index.js"), + "module.exports = function agentDebug() {};\n", + ); + + const loaded = loadAgentDebug(modulePath, registerDebug); + + expect(loaded).toBeDefined(); + expect(loaded?.debug).not.toBe(registerDebug); + expect(loaded?.path).toBe(path.join(debugDir, "index.js")); + }); + + test("does not return the host debug module as a second instance", () => { + expect( + loadAgentDebug(fileURLToPath(import.meta.url), registerDebug), + ).toBe(undefined); + }); +}); diff --git a/ts/packages/shell/src/main/index.ts b/ts/packages/shell/src/main/index.ts index 59e50f770b..f87169d359 100644 --- a/ts/packages/shell/src/main/index.ts +++ b/ts/packages/shell/src/main/index.ts @@ -30,6 +30,7 @@ import { } from "./instance.js"; import { AGENT_SERVER_DEFAULT_PORT } from "@typeagent/agent-server-client"; import { otel } from "@typeagent/telemetry"; +import registerDebug from "debug"; import { isAllowedConfigFilePath, resolveLocalConfigPath, @@ -208,7 +209,15 @@ async function initialize() { const appPath = app.getAppPath(); await initializeKeys(appPath); - await otel.initTelemetry(); + const telemetryConfig = otel.resolveTelemetryConfig(); + await otel.initTelemetry({ + config: telemetryConfig, + debugModules: [registerDebug], + debugBridge: { + includedNamespacePrefixes: ["typeagent:", "agent-server:"], + }, + }); + structuredLogs = telemetryConfig.structuredLogs === true; // Standalone hosts the agent-server in-process, so warm up the aiclient // runtime config locally. The connect-only shell delegates all model work // to the remote server and never imports aiclient here. @@ -383,6 +392,7 @@ async function initialize() { parsedArgs.hidden, parsedArgs.idleTimeout, parsedArgs.resume, + structuredLogs, ); }); @@ -397,6 +407,7 @@ async function initialize() { parsedArgs.hidden, parsedArgs.idleTimeout, parsedArgs.resume, + structuredLogs, ); shellWindow.waitForReady().then(() => { @@ -432,6 +443,7 @@ process.on("unhandledRejection", (reason: any) => { }); let reloadingInstance = false; +let structuredLogs = false; export async function reloadInstance() { reloadingInstance = true; try { @@ -447,6 +459,7 @@ export async function reloadInstance() { parsedArgs.hidden, parsedArgs.idleTimeout, parsedArgs.resume, + structuredLogs, ); } finally { reloadingInstance = false; diff --git a/ts/packages/shell/src/main/instance.ts b/ts/packages/shell/src/main/instance.ts index 25c4f3de1e..a62e7880cc 100644 --- a/ts/packages/shell/src/main/instance.ts +++ b/ts/packages/shell/src/main/instance.ts @@ -631,6 +631,9 @@ async function initializeDispatcher( metrics: true, dblogging: true, traceId: getTraceId(), + telemetry: { + structuredLogs, + }, indexingServiceRegistry, constructionProvider: getDefaultConstructionProvider(), allowSharedLocalView: ["browser"], @@ -871,6 +874,7 @@ export function initializeInstance( hidden?: boolean, idleTimeout?: number, _resume?: boolean, // reserved: shell conversation resume not yet implemented + structuredLogs: boolean = false, ) { if (instance !== undefined) { throw new Error("Instance already initialized"); diff --git a/ts/packages/telemetry/src/logger/otelLoggerSink.ts b/ts/packages/telemetry/src/logger/otelLoggerSink.ts index 55858f780b..2e4b519967 100644 --- a/ts/packages/telemetry/src/logger/otelLoggerSink.ts +++ b/ts/packages/telemetry/src/logger/otelLoggerSink.ts @@ -207,8 +207,8 @@ function mapSeverity(severity: LogEventSeverity | undefined): { * *and* global provider replacement (e.g. `logs.disable()` followed by * `setGlobalLoggerProvider(...)`) transparent to a sink created earlier. * - * This class is the library foundation only. A later host-wiring PR - * composes it into TypeAgent-owned runtimes and configures providers. + * The sink does not own or configure a provider. TypeAgent-owned composition + * roots attach it to runtime loggers and configure providers separately. */ export class OtelLoggerSink implements LoggerSink { private readonly options: OtelLoggerSinkOptions | undefined; diff --git a/ts/packages/telemetry/src/otel/config.ts b/ts/packages/telemetry/src/otel/config.ts index beee9d2870..52a119240f 100644 --- a/ts/packages/telemetry/src/otel/config.ts +++ b/ts/packages/telemetry/src/otel/config.ts @@ -84,6 +84,8 @@ export interface TelemetryConfig { readonly logs?: LogConfig; /** Copy enabled TypeAgent debug output into the OTel logs pipeline. */ readonly debugBridge?: boolean; + /** Export structured dispatcher events into the OTel logs pipeline. */ + readonly structuredLogs?: boolean; } /* -------------------------------------------------------------------------- */ @@ -184,6 +186,10 @@ export function resolveTelemetryConfig( yaml.TELEMETRY_DEBUGBRIDGE, "telemetry.debugBridge", ); + const yamlStructuredLogs = parseBoolean( + yaml.TELEMETRY_STRUCTUREDLOGS, + "telemetry.structuredLogs", + ); // ---- Env values. const envGlobalEndpoint = requireNonEmpty( @@ -207,6 +213,10 @@ export function resolveTelemetryConfig( env.TYPEAGENT_OTEL_DEBUG_BRIDGE, "TYPEAGENT_OTEL_DEBUG_BRIDGE", ); + const envStructuredLogs = parseBoolean( + env.TYPEAGENT_OTEL_STRUCTURED_LOGS, + "TYPEAGENT_OTEL_STRUCTURED_LOGS", + ); const signalEndpoints: Record = { traces: requireNonEmpty( @@ -301,6 +311,7 @@ export function resolveTelemetryConfig( metrics?: MetricConfig; logs?: LogConfig; debugBridge?: boolean; + structuredLogs?: boolean; } = {}; if (tracesOtlp !== undefined) { @@ -334,6 +345,10 @@ export function resolveTelemetryConfig( if (debugBridge !== undefined) { result.debugBridge = debugBridge; } + const structuredLogs = envStructuredLogs ?? yamlStructuredLogs; + if (structuredLogs !== undefined) { + result.structuredLogs = structuredLogs; + } return result; } diff --git a/ts/packages/telemetry/src/otel/debugBridge.ts b/ts/packages/telemetry/src/otel/debugBridge.ts index 26f4fff76f..42c3c0467e 100644 --- a/ts/packages/telemetry/src/otel/debugBridge.ts +++ b/ts/packages/telemetry/src/otel/debugBridge.ts @@ -17,6 +17,7 @@ export interface DebugModule { } export interface DebugBridgeOptions extends RedactionOptions { + readonly includedNamespacePrefixes?: readonly string[]; readonly excludedNamespacePrefixes?: readonly string[]; } @@ -27,9 +28,15 @@ export interface DebugBridge { interface InstalledBridge { readonly priorLog: DebugModule["log"]; readonly wrappedLog: DebugModule["log"]; + readonly options: EffectiveDebugBridgeOptions; refCount: number; } +interface EffectiveDebugBridgeOptions extends RedactionOptions { + readonly includedNamespacePrefixes: readonly string[]; + readonly excludedNamespacePrefixes: readonly string[]; +} + const installedBridges = new WeakMap(); const DEFAULT_EXCLUSIONS = [ "typeagent:logger:", @@ -44,8 +51,31 @@ export function installDebugBridge( debugModules: readonly DebugModule[], options: DebugBridgeOptions = {}, ): DebugBridge { + const effectiveOptions: EffectiveDebugBridgeOptions = { + includedNamespacePrefixes: options.includedNamespacePrefixes ?? [ + "typeagent:", + ], + excludedNamespacePrefixes: + options.excludedNamespacePrefixes ?? DEFAULT_EXCLUSIONS, + ...(options.secretFilter === undefined + ? {} + : { secretFilter: options.secretFilter }), + }; + const uniqueModules = [...new Set(debugModules)]; + for (const debugModule of uniqueModules) { + const existing = installedBridges.get(debugModule); + if ( + existing !== undefined && + !hasEquivalentOptions(existing.options, effectiveOptions) + ) { + throw new Error( + "Cannot install a debug bridge with different options on an already bridged debug module.", + ); + } + } + const installed: DebugModule[] = []; - for (const debugModule of new Set(debugModules)) { + for (const debugModule of uniqueModules) { const existing = installedBridges.get(debugModule); if (existing !== undefined) { existing.refCount++; @@ -54,8 +84,6 @@ export function installDebugBridge( } const priorLog = debugModule.log; - const exclusions = - options.excludedNamespacePrefixes ?? DEFAULT_EXCLUSIONS; const wrappedLog: DebugModule["log"] = function ( this: { namespace?: string }, ...args: unknown[] @@ -65,8 +93,12 @@ export function installDebugBridge( if ( emitting || namespace === undefined || - !namespace.startsWith("typeagent:") || - exclusions.some((prefix) => namespace.startsWith(prefix)) + !effectiveOptions.includedNamespacePrefixes.some((prefix) => + namespace.startsWith(prefix), + ) || + effectiveOptions.excludedNamespacePrefixes.some((prefix) => + namespace.startsWith(prefix), + ) ) { return result; } @@ -89,7 +121,7 @@ export function installDebugBridge( const rendered = format(...args).replace(ANSI_ESCAPE, ""); const redacted = rendered.length <= MAX_BODY_LENGTH - ? redactText(rendered, options) + ? redactText(rendered, effectiveOptions) : undefined; const body = redacted !== undefined && @@ -119,6 +151,7 @@ export function installDebugBridge( installedBridges.set(debugModule, { priorLog, wrappedLog, + options: effectiveOptions, refCount: 1, }); installed.push(debugModule); @@ -148,3 +181,30 @@ export function installDebugBridge( }, }; } + +function hasEquivalentOptions( + left: EffectiveDebugBridgeOptions, + right: EffectiveDebugBridgeOptions, +): boolean { + return ( + left.secretFilter === right.secretFilter && + arraysEqual( + left.includedNamespacePrefixes, + right.includedNamespacePrefixes, + ) && + arraysEqual( + left.excludedNamespacePrefixes, + right.excludedNamespacePrefixes, + ) + ); +} + +function arraysEqual( + left: readonly string[], + right: readonly string[], +): boolean { + return ( + left.length === right.length && + left.every((value, index) => value === right[index]) + ); +} diff --git a/ts/packages/telemetry/test/otelBootstrap.spec.ts b/ts/packages/telemetry/test/otelBootstrap.spec.ts index 61a870e930..30a2b19859 100644 --- a/ts/packages/telemetry/test/otelBootstrap.spec.ts +++ b/ts/packages/telemetry/test/otelBootstrap.spec.ts @@ -117,6 +117,24 @@ describe("telemetry bootstrap", () => { expect(configReads).toBe(1); }); + it("installs and restores the configured debug bridge", async () => { + const coordinator = createCoordinator(); + const priorLog = () => undefined; + const debugModule = { log: priorLog }; + + await coordinator.init({ + config: { debugBridge: true }, + debugModules: [debugModule], + debugBridge: { + includedNamespacePrefixes: ["typeagent:", "agent-server:"], + }, + }); + + expect(debugModule.log).not.toBe(priorLog); + await coordinator.shutdown(); + expect(debugModule.log).toBe(priorLog); + }); + it("creates only requested signals and shares one resource", async () => { const coordinator = createCoordinator(); const resources: Resource[] = []; diff --git a/ts/packages/telemetry/test/otelConfig.spec.ts b/ts/packages/telemetry/test/otelConfig.spec.ts index c56820be90..a6c03d66c6 100644 --- a/ts/packages/telemetry/test/otelConfig.spec.ts +++ b/ts/packages/telemetry/test/otelConfig.spec.ts @@ -84,6 +84,27 @@ describe("resolveTelemetryConfig", () => { }); }); + it("resolves structured logs from YAML and environment", () => { + withTempWorkspace((root) => { + writeYaml( + root, + "config.local.yaml", + "telemetry:\n structuredLogs: true\n", + ); + expect(resolve(root).structuredLogs).toBe(true); + expect( + resolve(root, { + env: { TYPEAGENT_OTEL_STRUCTURED_LOGS: "off" }, + }).structuredLogs, + ).toBe(false); + expect(() => + resolve(root, { + env: { TYPEAGENT_OTEL_STRUCTURED_LOGS: "sometimes" }, + }), + ).toThrow(/expected true\/false/); + }); + }); + /* ------------------------------------------------------------------ */ /* YAML endpoint */ /* ------------------------------------------------------------------ */ diff --git a/ts/packages/telemetry/test/otelLocalDiagnostics.spec.ts b/ts/packages/telemetry/test/otelLocalDiagnostics.spec.ts index ef37df8fc9..908890d769 100644 --- a/ts/packages/telemetry/test/otelLocalDiagnostics.spec.ts +++ b/ts/packages/telemetry/test/otelLocalDiagnostics.spec.ts @@ -16,6 +16,7 @@ import { type ReadableLogRecord, } from "@opentelemetry/sdk-logs"; import { NodeTracerProvider } from "@opentelemetry/sdk-trace-node"; +import registerDebug from "debug"; import { createOtelLoggerSink } from "../src/logger/otelLoggerSink.js"; import { installDebugBridge } from "../src/otel/debugBridge.js"; @@ -247,6 +248,68 @@ describe("debug bridge", () => { expect(second.log).toBe(secondPrior); }); + it("can include host-owned legacy debug namespace prefixes", () => { + const exporter = new InMemoryLogRecordExporter(); + provider = new LoggerProvider({ + processors: [new SimpleLogRecordProcessor({ exporter })], + }); + logs.setGlobalLoggerProvider(provider); + const output: Array<{ + namespace: string | undefined; + args: unknown[]; + }> = []; + const debugModule = createDebugModule(output); + const bridge = installDebugBridge([debugModule], { + includedNamespacePrefixes: ["typeagent:", "agent-server:"], + }); + + debugModule.log.call({ namespace: "agent-server:startup" }, "ready"); + debugModule.log.call({ namespace: "other:startup" }, "ignored"); + debugModule.log.call( + { namespace: "typeagent:telemetry:promptLogger" }, + "prompt", + ); + + expect(exporter.getFinishedLogRecords()).toHaveLength(1); + expect( + exporter.getFinishedLogRecords()[0].attributes["debug.namespace"], + ).toBe("agent-server:startup"); + bridge.shutdown(); + }); + + it("captures real debug instances created before and after installation", () => { + const exporter = new InMemoryLogRecordExporter(); + provider = new LoggerProvider({ + processors: [new SimpleLogRecordProcessor({ exporter })], + }); + logs.setGlobalLoggerProvider(provider); + const priorNamespaces = registerDebug.disable(); + const priorLog = registerDebug.log; + registerDebug.log = () => undefined; + const before = registerDebug("typeagent:test:before"); + const bridge = installDebugBridge([registerDebug]); + + try { + registerDebug.enable("typeagent:test:*"); + const after = registerDebug("typeagent:test:after"); + before("created before installation"); + after("created after installation"); + + const records = exporter.getFinishedLogRecords(); + expect(records.map((record) => record.body)).toEqual([ + "created before installation", + "created after installation", + ]); + expect( + records.map((record) => record.attributes["debug.namespace"]), + ).toEqual(["typeagent:test:before", "typeagent:test:after"]); + } finally { + bridge.shutdown(); + registerDebug.log = priorLog; + registerDebug.enable(priorNamespaces); + } + }); + it("does not overwrite a later owner during restoration", () => { const debugModule = createDebugModule([]); const bridge = installDebugBridge([debugModule]); @@ -271,6 +334,21 @@ describe("debug bridge", () => { expect(debugModule.log).toBe(prior); }); + it("rejects conflicting options on an already bridged module", () => { + const debugModule = createDebugModule([]); + const first = installDebugBridge([debugModule]); + const wrapped = debugModule.log; + + expect(() => + installDebugBridge([debugModule], { + includedNamespacePrefixes: ["agent-server:"], + }), + ).toThrow(/different options/); + expect(debugModule.log).toBe(wrapped); + + first.shutdown(); + }); + it("suppresses reentrant debug output from the OTel logger path", () => { const output: Array<{ namespace: string | undefined; From 9c6412d2b0e1ebd26144dc14a8181fd396c06cc5 Mon Sep 17 00:00:00 2001 From: George Ng Date: Wed, 12 Aug 2026 16:13:32 -0700 Subject: [PATCH 04/13] Harden logging privacy, bounded payloads, severity handling,e tc --- .../architecture/telemetry/opentelemetry.md | 25 ++- ts/packages/cache/src/cache/cache.ts | 36 ++-- .../dispatcher/src/command/command.ts | 14 +- .../src/context/commandHandlerContext.ts | 8 +- .../handlers/requestCommandHandler.ts | 32 ++-- .../dispatcher/src/otel/structuredLogSink.ts | 119 ++++++++++++ .../dispatcher/src/queue/requestQueue.ts | 32 +++- .../test/queue/requestQueue.spec.ts | 37 ++++ .../dispatcher/test/structuredLogSink.spec.ts | 76 ++++++++ .../telemetry/src/logger/otelLoggerSink.ts | 11 +- ts/packages/telemetry/src/otel/debugBridge.ts | 179 +++++++++++------- .../telemetry/src/otel/jsonlLogExporter.ts | 120 +++++++++++- .../test/otelLocalDiagnostics.spec.ts | 33 ++++ .../telemetry/test/otelLoggerSink.spec.ts | 23 +++ 14 files changed, 617 insertions(+), 128 deletions(-) create mode 100644 ts/packages/dispatcher/dispatcher/src/otel/structuredLogSink.ts create mode 100644 ts/packages/dispatcher/dispatcher/test/structuredLogSink.spec.ts diff --git a/ts/docs/architecture/telemetry/opentelemetry.md b/ts/docs/architecture/telemetry/opentelemetry.md index 48bbd36295..9ef08ea8fb 100644 --- a/ts/docs/architecture/telemetry/opentelemetry.md +++ b/ts/docs/architecture/telemetry/opentelemetry.md @@ -211,10 +211,22 @@ oversized correlation value is omitted. The sink does not retain a prefix: partial truncation could expose part of a secret that the complete value would have matched. Redaction runs only after this bound and the result must also fit. -Producers sanitize prompts, responses, user content, and PII at the source; -the sink applies known-secret and secret-format filtering as defense in depth, -covering the promoted correlation attributes and every string reachable in the -snapshotted body. +The dispatcher places an allowlisted projection in front of `OtelLoggerSink`. +Only bounded correlation identifiers, agent/schema/action names, state and +reason fields, durations and counts, booleans, and command/schema-name arrays +reach OTel. Prompt and response text, history, action parameters, errors and +stacks, feedback comments and context, and all unknown fields are excluded. +Other producers that attach `OtelLoggerSink` remain responsible for an +equivalent source-specific projection. The sink applies known-secret and +secret-format filtering as defense in depth, covering the promoted correlation +attributes and every string reachable in the projected body. + +The local JSONL exporter restricts each file, and any leaf directory it creates, +to the current user before writing log content. It enforces `0700`/`0600` modes +on POSIX and replaces inherited Windows ACLs with current-user-only access. It +does not change an existing parent directory's permissions. If the file or a +new directory cannot be secured, the export fails closed and reports a +content-free diagnostic. Emit failures are isolated: the sink drops the OTel record and never re-enters the `MultiSinkLogger` fan-out. A rate-limited diagnostic writes directly to @@ -226,8 +238,9 @@ their original output: - Preserve `DEBUG`, `@trace`, stderr, colors, timestamps, and CLI interception. - Call the exact prior `debug.log` implementation, and restore it on shutdown only while the bridge still owns it. -- Derive the namespace from the debug instance; render the OTel body separately - without ANSI codes. +- Derive the namespace from the debug instance; capture arguments before + `debug` adds timestamps, namespace prefixes, colors, and elapsed time, then + render the OTel body separately without ANSI codes. - Cover each known distinct `debug` module instance. One hook is not assumed to cover the process. - Install idempotently, avoid wrapping an instance twice, and use reentrancy and diff --git a/ts/packages/cache/src/cache/cache.ts b/ts/packages/cache/src/cache/cache.ts index bb8d80046d..fdaf46d33b 100644 --- a/ts/packages/cache/src/cache/cache.ts +++ b/ts/packages/cache/src/cache/cache.ts @@ -498,11 +498,15 @@ export class AgentCache { message: `Grammar generation error: ${error.message}`, }; - this.logger?.logEvent("grammarGeneration", { - request: requestAction.request, - success: false, - error: error.message, - }); + this.logger?.logEvent( + "grammarGeneration", + { + request: requestAction.request, + success: false, + error: error.message, + }, + "error", + ); } } @@ -518,15 +522,19 @@ export class AgentCache { ...(grammarResult !== undefined && { grammarResult }), }; } catch (e: any) { - this.logger?.logEvent("error", { - request: requestAction.request, - actions: requestAction.actions, - history: requestAction.history, - cache, - options, - message: e.message, - stack: e.stack, - }); + this.logger?.logEvent( + "error", + { + request: requestAction.request, + actions: requestAction.actions, + history: requestAction.history, + cache, + options, + message: e.message, + stack: e.stack, + }, + "error", + ); throw e; } } diff --git a/ts/packages/dispatcher/dispatcher/src/command/command.ts b/ts/packages/dispatcher/dispatcher/src/command/command.ts index fb3c675d54..c919d902cf 100644 --- a/ts/packages/dispatcher/dispatcher/src/command/command.ts +++ b/ts/packages/dispatcher/dispatcher/src/command/command.ts @@ -392,11 +392,15 @@ export async function processCommandNoLock( ); debugCommandError(e.stack); - context?.logger?.logEvent("command:exception", { - request: originalInput, - message: e.message, - stack: e.stack, - }); + context?.logger?.logEvent( + "command:exception", + { + request: originalInput, + message: e.message, + stack: e.stack, + }, + "error", + ); } } diff --git a/ts/packages/dispatcher/dispatcher/src/context/commandHandlerContext.ts b/ts/packages/dispatcher/dispatcher/src/context/commandHandlerContext.ts index 2b4c4ccea0..11cd8296bf 100644 --- a/ts/packages/dispatcher/dispatcher/src/context/commandHandlerContext.ts +++ b/ts/packages/dispatcher/dispatcher/src/context/commandHandlerContext.ts @@ -13,7 +13,6 @@ import { MultiSinkLogger, createDebugLoggerSink, createDatabaseLoggerSink, - createOtelLoggerSink, CosmosContainerClientFactory, CosmosPartitionKeyBuilderFactory, PromptLogger, @@ -52,6 +51,7 @@ import { ensureDirectory, lockInstanceDir, } from "../utils/fsUtils.js"; +import { createDispatcherOtelLoggerSink } from "../otel/structuredLogSink.js"; import { ActionContext, AppAgentEvent, @@ -774,7 +774,7 @@ function getLoggerSink( ? [debugLoggerSink] : [debugLoggerSink, dbLoggerSink]; if (structuredLogs) { - sinks.push(createOtelLoggerSink()); + sinks.push(createDispatcherOtelLoggerSink()); } return new MultiSinkLogger(sinks); } @@ -1432,8 +1432,8 @@ export async function initializeCommandHandlerContext( }, context.logger ? { - logEvent: (name, data) => - context.logger?.logEvent(name, data as any), + logEvent: (name, data, severity) => + context.logger?.logEvent(name, data as any, severity), } : undefined, ); diff --git a/ts/packages/dispatcher/dispatcher/src/context/dispatcher/handlers/requestCommandHandler.ts b/ts/packages/dispatcher/dispatcher/src/context/dispatcher/handlers/requestCommandHandler.ts index aab39069c5..46f507239f 100644 --- a/ts/packages/dispatcher/dispatcher/src/context/dispatcher/handlers/requestCommandHandler.ts +++ b/ts/packages/dispatcher/dispatcher/src/context/dispatcher/handlers/requestCommandHandler.ts @@ -284,13 +284,17 @@ async function canTranslateWithoutContext( newActions, }); } catch (e: any) { - logger?.logEvent("contextlessTranslation", { - requestAction, - actions: oldActions, - history: requestAction.history, - newActions, - error: e.message, - }); + logger?.logEvent( + "contextlessTranslation", + { + requestAction, + actions: oldActions, + history: requestAction.history, + newActions, + error: e.message, + }, + "error", + ); throw e; } } @@ -824,11 +828,15 @@ export class RequestCommandHandler implements CommandHandler { DispatcherName, ); } - systemContext?.logger?.logEvent("request:exception", { - request, - message: e.message, - stack: e.stack, - }); + systemContext?.logger?.logEvent( + "request:exception", + { + request, + message: e.message, + stack: e.stack, + }, + "error", + ); throw e; } diff --git a/ts/packages/dispatcher/dispatcher/src/otel/structuredLogSink.ts b/ts/packages/dispatcher/dispatcher/src/otel/structuredLogSink.ts new file mode 100644 index 0000000000..56e23bb60c --- /dev/null +++ b/ts/packages/dispatcher/dispatcher/src/otel/structuredLogSink.ts @@ -0,0 +1,119 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +import { + createOtelLoggerSink, + type LogEvent, + type LoggerSink, +} from "@typeagent/telemetry"; + +const SAFE_STRING_FIELDS = [ + "sessionId", + "activationId", + "traceId", + "requestId", + "connectionId", + "appAgentName", + "schemaName", + "actionName", + "kind", + "strategy", + "classifier", + "state", + "status", + "reason", + "phase", + "position", +] as const; + +const SAFE_NUMBER_FIELDS = [ + "timestamp", + "elapsedMs", + "waitMs", + "runMs", + "totalMs", + "queuedAhead", + "queueDepth", + "depth", + "count", + "attachmentCount", +] as const; + +const SAFE_BOOLEAN_FIELDS = [ + "success", + "running", + "developerMode", + "includeContext", +] as const; + +const SAFE_STRING_ARRAY_FIELDS = ["schemaNames", "command"] as const; +const MAX_ARRAY_LENGTH = 64; +const MAX_STRING_LENGTH = 256; + +export function createDispatcherOtelLoggerSink( + sink: LoggerSink = createOtelLoggerSink(), +): LoggerSink { + return { + logEvent(event: LogEvent): void { + sink.logEvent({ + ...event, + event: projectDispatcherLogEvent(event.event), + }); + }, + }; +} + +function projectDispatcherLogEvent( + source: Readonly>, +): Record { + const projected: Record = {}; + + copyFields(source, projected, SAFE_STRING_FIELDS, isBoundedString); + copyFields( + source, + projected, + SAFE_NUMBER_FIELDS, + (value): value is number => + typeof value === "number" && Number.isFinite(value), + ); + copyFields( + source, + projected, + SAFE_BOOLEAN_FIELDS, + (value): value is boolean => typeof value === "boolean", + ); + copyFields( + source, + projected, + SAFE_STRING_ARRAY_FIELDS, + isBoundedStringArray, + ); + + return projected; +} + +function copyFields( + source: Readonly>, + target: Record, + fields: readonly string[], + isSafe: (value: unknown) => boolean, +): void { + for (const field of fields) { + const value = source[field]; + if (isSafe(value)) { + target[field] = value; + } + } +} + +function isBoundedString(value: unknown): value is string { + return typeof value === "string" && value.length <= MAX_STRING_LENGTH; +} + +function isBoundedStringArray(value: unknown): value is string[] { + return ( + Array.isArray(value) && + value.length <= MAX_ARRAY_LENGTH && + value.every(isBoundedString) + ); +} diff --git a/ts/packages/dispatcher/dispatcher/src/queue/requestQueue.ts b/ts/packages/dispatcher/dispatcher/src/queue/requestQueue.ts index bee1b69036..41b37fe555 100644 --- a/ts/packages/dispatcher/dispatcher/src/queue/requestQueue.ts +++ b/ts/packages/dispatcher/dispatcher/src/queue/requestQueue.ts @@ -44,7 +44,11 @@ export interface QueueBroadcaster { /** Optional telemetry sink. */ export interface QueueLogger { - logEvent(name: string, data: unknown): void; + logEvent( + name: string, + data: unknown, + severity?: "info" | "warning" | "error", + ): void; } /** @@ -523,11 +527,15 @@ export class RequestQueue { return out; } - private log(name: string, data: unknown): void { + private log( + name: string, + data: unknown, + severity: "info" | "warning" | "error" = "info", + ): void { try { debug(name, data); debugInternal(name, data); - this.logger?.logEvent(name, data); + this.logger?.logEvent(name, data, severity); } catch { // best-effort telemetry } @@ -635,13 +643,17 @@ export class RequestQueue { this.head = null; ++this.snapshotVersion; - this.log("requestQueue:complete", { - requestId: entry.requestId, - connectionId: entry.originatorConnectionId, - state: entry.state, - runMs: (entry.finishedAt ?? 0) - (entry.startedAt ?? 0), - totalMs: (entry.finishedAt ?? 0) - entry.submittedAt, - }); + this.log( + "requestQueue:complete", + { + requestId: entry.requestId, + connectionId: entry.originatorConnectionId, + state: entry.state, + runMs: (entry.finishedAt ?? 0) - (entry.startedAt ?? 0), + totalMs: (entry.finishedAt ?? 0) - entry.submittedAt, + }, + entry.state === "failed" ? "error" : "info", + ); this.safeBroadcast("queueStateChanged", () => this.broadcast.queueStateChanged(this.getSnapshot()), ); diff --git a/ts/packages/dispatcher/dispatcher/test/queue/requestQueue.spec.ts b/ts/packages/dispatcher/dispatcher/test/queue/requestQueue.spec.ts index 098618bafa..809029acc4 100644 --- a/ts/packages/dispatcher/dispatcher/test/queue/requestQueue.spec.ts +++ b/ts/packages/dispatcher/dispatcher/test/queue/requestQueue.spec.ts @@ -384,6 +384,43 @@ describe("RequestQueue", () => { expect(names).toContain("requestQueue:complete"); }); + it("logs failed requests with error severity", async () => { + const dispatcher = new ControllableDispatcher(); + const { broadcaster } = makeRecorder(); + const logged: Array<{ + name: string; + severity: string | undefined; + }> = []; + const queue = new RequestQueue( + (ctx) => + dispatcher.processCommand( + ctx.text, + ctx.clientRequestId, + ctx.attachments, + ctx.options, + ctx.requestId, + ), + broadcaster, + { + logEvent: (name, _data, severity) => + logged.push({ name, severity }), + }, + ); + + const entry = queue.submit({ + text: "x", + originatorConnectionId: "c1", + }); + await flush(); + dispatcher.calls[0].reject(new Error("failed")); + await expect(entry.completion).rejects.toThrow("failed"); + + expect(logged).toContainEqual({ + name: "requestQueue:complete", + severity: "error", + }); + }); + it("drainAndStop resolves after queue drains", async () => { const dispatcher = new ControllableDispatcher(); const { queue } = makeQueue(dispatcher); diff --git a/ts/packages/dispatcher/dispatcher/test/structuredLogSink.spec.ts b/ts/packages/dispatcher/dispatcher/test/structuredLogSink.spec.ts new file mode 100644 index 0000000000..84e73ce69b --- /dev/null +++ b/ts/packages/dispatcher/dispatcher/test/structuredLogSink.spec.ts @@ -0,0 +1,76 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +import type { LogEvent, LoggerSink } from "@typeagent/telemetry"; +import { createDispatcherOtelLoggerSink } from "../src/otel/structuredLogSink.js"; + +describe("dispatcher structured log projection", () => { + it("keeps bounded operational metadata and excludes user content", () => { + const captured: LogEvent[] = []; + const target: LoggerSink = { + logEvent(event) { + captured.push(event); + }, + }; + const sink = createDispatcherOtelLoggerSink(target); + + sink.logEvent({ + eventName: "translate", + timestamp: new Date().toISOString(), + severity: "error", + event: { + sessionId: "session", + requestId: "request", + elapsedMs: 42, + success: false, + schemaNames: ["calendar", "email"], + request: "PRIVATE_REQUEST_MARKER", + history: ["PRIVATE_HISTORY_MARKER"], + actions: [{ parameters: "PRIVATE_ACTION_MARKER" }], + message: "PRIVATE_ERROR_MARKER", + stack: "PRIVATE_STACK_MARKER", + comment: "PRIVATE_COMMENT_MARKER", + context: "PRIVATE_CONTEXT_MARKER", + unknown: "PRIVATE_UNKNOWN_MARKER", + }, + }); + + expect(captured).toEqual([ + { + eventName: "translate", + timestamp: expect.any(String), + severity: "error", + event: { + sessionId: "session", + requestId: "request", + elapsedMs: 42, + success: false, + schemaNames: ["calendar", "email"], + }, + }, + ]); + expect(JSON.stringify(captured)).not.toContain("PRIVATE_"); + }); + + it("drops oversized and incorrectly typed allowlisted values", () => { + const captured: LogEvent[] = []; + const sink = createDispatcherOtelLoggerSink({ + logEvent(event) { + captured.push(event); + }, + }); + + sink.logEvent({ + eventName: "requestQueue:complete", + timestamp: new Date().toISOString(), + event: { + requestId: "x".repeat(257), + runMs: Number.NaN, + running: "yes", + schemaNames: Array.from({ length: 65 }, () => "schema"), + }, + }); + + expect(captured[0]?.event).toEqual({}); + }); +}); diff --git a/ts/packages/telemetry/src/logger/otelLoggerSink.ts b/ts/packages/telemetry/src/logger/otelLoggerSink.ts index 2e4b519967..2f17b9d48b 100644 --- a/ts/packages/telemetry/src/logger/otelLoggerSink.ts +++ b/ts/packages/telemetry/src/logger/otelLoggerSink.ts @@ -512,7 +512,10 @@ function cloneBounded( return clone; } let first = true; - for (const [key, item] of Object.entries(source)) { + for (const key in source) { + if (!Object.prototype.hasOwnProperty.call(source, key)) { + continue; + } if (state.sizeTruncated) { setOwnValue(clone, TRUNCATION_MARKER_KEY, "size"); break; @@ -524,7 +527,11 @@ function cloneBounded( break; } first = false; - setOwnValue(clone, key, cloneBounded(item, depth + 1, state)); + setOwnValue( + clone, + key, + cloneBounded(source[key], depth + 1, state), + ); if (state.sizeTruncated) { break; } diff --git a/ts/packages/telemetry/src/otel/debugBridge.ts b/ts/packages/telemetry/src/otel/debugBridge.ts index 42c3c0467e..af79195a63 100644 --- a/ts/packages/telemetry/src/otel/debugBridge.ts +++ b/ts/packages/telemetry/src/otel/debugBridge.ts @@ -13,7 +13,8 @@ import { import { redactText, type RedactionOptions } from "./redaction.js"; export interface DebugModule { - log: (this: { namespace?: string }, ...args: unknown[]) => unknown; + log: DebugFunction; + formatArgs?: DebugFunction; } export interface DebugBridgeOptions extends RedactionOptions { @@ -26,12 +27,18 @@ export interface DebugBridge { } interface InstalledBridge { - readonly priorLog: DebugModule["log"]; - readonly wrappedLog: DebugModule["log"]; + readonly hook: "formatArgs" | "log"; + readonly prior: DebugFunction; + readonly wrapped: DebugFunction; readonly options: EffectiveDebugBridgeOptions; refCount: number; } +type DebugFunction = ( + this: { namespace?: string }, + ...args: unknown[] +) => unknown; + interface EffectiveDebugBridgeOptions extends RedactionOptions { readonly includedNamespacePrefixes: readonly string[]; readonly excludedNamespacePrefixes: readonly string[]; @@ -83,74 +90,41 @@ export function installDebugBridge( continue; } - const priorLog = debugModule.log; - const wrappedLog: DebugModule["log"] = function ( - this: { namespace?: string }, - ...args: unknown[] - ): unknown { - const result = priorLog.apply(this, args); - const namespace = this?.namespace; - if ( - emitting || - namespace === undefined || - !effectiveOptions.includedNamespacePrefixes.some((prefix) => - namespace.startsWith(prefix), - ) || - effectiveOptions.excludedNamespacePrefixes.some((prefix) => - namespace.startsWith(prefix), - ) - ) { - return result; - } - const activeContext = otelContext.active(); - if (isTracingSuppressed(activeContext)) { - return result; - } - try { - emitting = true; - const logger = logs.getLogger( - INSTRUMENTATION_SCOPE_NAME, - INSTRUMENTATION_SCOPE_VERSION, - ); - if ( - logger.enabled({ - context: activeContext, - severityNumber: SeverityNumber.DEBUG, - }) - ) { - const rendered = format(...args).replace(ANSI_ESCAPE, ""); - const redacted = - rendered.length <= MAX_BODY_LENGTH - ? redactText(rendered, effectiveOptions) - : undefined; - const body = - redacted !== undefined && - redacted.length <= MAX_BODY_LENGTH - ? redacted - : "[typeagent debug output truncated]"; - logger.emit({ - context: activeContext, - severityNumber: SeverityNumber.DEBUG, - severityText: "DEBUG", - eventName: "debug", - body, - attributes: { - "debug.namespace": namespace, - }, - }); - } - } catch { - // The original debug output already ran. Bridge failures lose - // only the OTel copy and never recurse through diagnostics. - } finally { - emitting = false; - } - return result; - }; - debugModule.log = wrappedLog; + const hook = + debugModule.formatArgs === undefined ? "log" : "formatArgs"; + const prior = debugModule[hook]!; + const wrapped: DebugFunction = + hook === "formatArgs" + ? function ( + this: { namespace?: string }, + ...callArgs: unknown[] + ): unknown { + const args = callArgs[0]; + if (!Array.isArray(args)) { + return prior.apply(this, callArgs); + } + const rawArgs = [...args]; + const result = prior.apply(this, callArgs); + emitDebugRecord( + this?.namespace, + rawArgs, + effectiveOptions, + ); + return result; + } + : function ( + this: { namespace?: string }, + ...args: unknown[] + ): unknown { + const result = prior.apply(this, args); + emitDebugRecord(this?.namespace, args, effectiveOptions); + return result; + }; + debugModule[hook] = wrapped; installedBridges.set(debugModule, { - priorLog, - wrappedLog, + hook, + prior, + wrapped, options: effectiveOptions, refCount: 1, }); @@ -173,8 +147,8 @@ export function installDebugBridge( if (state.refCount > 0) { continue; } - if (debugModule.log === state.wrappedLog) { - debugModule.log = state.priorLog; + if (debugModule[state.hook] === state.wrapped) { + debugModule[state.hook] = state.prior; } installedBridges.delete(debugModule); } @@ -182,6 +156,67 @@ export function installDebugBridge( }; } +function emitDebugRecord( + namespace: string | undefined, + args: unknown[], + options: EffectiveDebugBridgeOptions, +): void { + if ( + emitting || + namespace === undefined || + !options.includedNamespacePrefixes.some((prefix) => + namespace.startsWith(prefix), + ) || + options.excludedNamespacePrefixes.some((prefix) => + namespace.startsWith(prefix), + ) + ) { + return; + } + const activeContext = otelContext.active(); + if (isTracingSuppressed(activeContext)) { + return; + } + try { + emitting = true; + const logger = logs.getLogger( + INSTRUMENTATION_SCOPE_NAME, + INSTRUMENTATION_SCOPE_VERSION, + ); + if ( + logger.enabled({ + context: activeContext, + severityNumber: SeverityNumber.DEBUG, + }) + ) { + const rendered = format(...args).replace(ANSI_ESCAPE, ""); + const redacted = + rendered.length <= MAX_BODY_LENGTH + ? redactText(rendered, options) + : undefined; + const body = + redacted !== undefined && redacted.length <= MAX_BODY_LENGTH + ? redacted + : "[typeagent debug output truncated]"; + logger.emit({ + context: activeContext, + severityNumber: SeverityNumber.DEBUG, + severityText: "DEBUG", + eventName: "debug", + body, + attributes: { + "debug.namespace": namespace, + }, + }); + } + } catch { + // Bridge failures lose only the OTel copy and never recurse through + // diagnostics or affect the original debug output. + } finally { + emitting = false; + } +} + function hasEquivalentOptions( left: EffectiveDebugBridgeOptions, right: EffectiveDebugBridgeOptions, diff --git a/ts/packages/telemetry/src/otel/jsonlLogExporter.ts b/ts/packages/telemetry/src/otel/jsonlLogExporter.ts index 701664eb50..ce119db59f 100644 --- a/ts/packages/telemetry/src/otel/jsonlLogExporter.ts +++ b/ts/packages/telemetry/src/otel/jsonlLogExporter.ts @@ -3,6 +3,7 @@ import * as fs from "node:fs/promises"; import * as path from "node:path"; +import { execFile } from "node:child_process"; import { ExportResultCode, type ExportResult } from "@opentelemetry/core"; import type { LogRecordExporter, @@ -26,6 +27,7 @@ export class JsonlLogExporter implements LogRecordExporter { private readonly maxPendingRecords: number; private readonly diagnostic: (message: string, error?: unknown) => void; private tail: Promise = Promise.resolve(); + private destination: Promise | undefined; private pendingRecords = 0; private droppedRecords = 0; private stopped = false; @@ -104,8 +106,8 @@ export class JsonlLogExporter implements LogRecordExporter { this.pendingRecords += accepted.length; const operation = this.tail.then(async () => { - await fs.mkdir(path.dirname(this.filePath), { recursive: true }); - await fs.appendFile(this.filePath, content, "utf8"); + const file = await (this.destination ??= this.openDestination()); + await file.appendFile(content, "utf8"); }); this.tail = operation.catch(() => undefined); void operation @@ -141,7 +143,12 @@ export class JsonlLogExporter implements LogRecordExporter { try { await this.tail; } finally { - activePaths.delete(this.filePath); + try { + const file = await this.destination?.catch(() => undefined); + await file?.close(); + } finally { + activePaths.delete(this.filePath); + } } } @@ -165,6 +172,113 @@ export class JsonlLogExporter implements LogRecordExporter { // Diagnostics must never affect exporter ownership or requests. } } + + private async openDestination(): Promise { + const directory = path.dirname(this.filePath); + const createdDirectory = + (await fs.mkdir(directory, { + recursive: true, + mode: 0o700, + })) !== undefined; + const file = await fs.open(this.filePath, "a", 0o600); + try { + if (process.platform === "win32") { + await setPrivateWindowsAcl( + directory, + this.filePath, + createdDirectory, + ); + } else { + await Promise.all([ + ...(createdDirectory ? [fs.chmod(directory, 0o700)] : []), + file.chmod(0o600), + ]); + } + return file; + } catch (error) { + await file.close(); + throw error; + } + } +} + +const WINDOWS_ACL_SCRIPT = ` +$ErrorActionPreference = "Stop" +$identity = [System.Security.Principal.WindowsIdentity]::GetCurrent().User + +if ($env:TYPEAGENT_SECURE_LOG_DIRECTORY -eq "true") { + $directoryAcl = [System.Security.AccessControl.DirectorySecurity]::new() + $directoryAcl.SetOwner($identity) + $directoryAcl.SetAccessRuleProtection($true, $false) + $directoryRule = [System.Security.AccessControl.FileSystemAccessRule]::new( + $identity, + [System.Security.AccessControl.FileSystemRights]::FullControl, + [System.Security.AccessControl.InheritanceFlags]"ContainerInherit, ObjectInherit", + [System.Security.AccessControl.PropagationFlags]::None, + [System.Security.AccessControl.AccessControlType]::Allow + ) + $directoryAcl.AddAccessRule($directoryRule) + [System.IO.Directory]::SetAccessControl( + $env:TYPEAGENT_LOG_DIRECTORY, + $directoryAcl + ) +} + +$fileAcl = [System.Security.AccessControl.FileSecurity]::new() +$fileAcl.SetOwner($identity) +$fileAcl.SetAccessRuleProtection($true, $false) +$fileRule = [System.Security.AccessControl.FileSystemAccessRule]::new( + $identity, + [System.Security.AccessControl.FileSystemRights]::FullControl, + [System.Security.AccessControl.AccessControlType]::Allow +) +$fileAcl.AddAccessRule($fileRule) +[System.IO.File]::SetAccessControl($env:TYPEAGENT_LOG_FILE, $fileAcl) +`; + +function setPrivateWindowsAcl( + directory: string, + filePath: string, + secureDirectory: boolean, +): Promise { + const executable = path.join( + process.env.SystemRoot ?? "C:\\Windows", + "System32", + "WindowsPowerShell", + "v1.0", + "powershell.exe", + ); + const encodedCommand = Buffer.from(WINDOWS_ACL_SCRIPT, "utf16le").toString( + "base64", + ); + return new Promise((resolve, reject) => { + execFile( + executable, + [ + "-NoLogo", + "-NoProfile", + "-NonInteractive", + "-EncodedCommand", + encodedCommand, + ], + { + windowsHide: true, + env: { + ...process.env, + TYPEAGENT_LOG_DIRECTORY: directory, + TYPEAGENT_LOG_FILE: filePath, + TYPEAGENT_SECURE_LOG_DIRECTORY: String(secureDirectory), + }, + }, + (error) => { + if (error === null) { + resolve(); + } else { + reject(error); + } + }, + ); + }); } export function resolveJsonlLogPath( diff --git a/ts/packages/telemetry/test/otelLocalDiagnostics.spec.ts b/ts/packages/telemetry/test/otelLocalDiagnostics.spec.ts index 908890d769..8d03fbdc42 100644 --- a/ts/packages/telemetry/test/otelLocalDiagnostics.spec.ts +++ b/ts/packages/telemetry/test/otelLocalDiagnostics.spec.ts @@ -4,6 +4,7 @@ import * as fs from "node:fs"; import * as os from "node:os"; import * as path from "node:path"; +import { execFileSync } from "node:child_process"; import { context, trace } from "@opentelemetry/api"; import { logs } from "@opentelemetry/api-logs"; import { AsyncLocalStorageContextManager } from "@opentelemetry/context-async-hooks"; @@ -108,6 +109,38 @@ describe("JsonlLogExporter", () => { expect(lines.map((line) => line.body)).toEqual(["first", "second"]); }); + it("creates private directories and files", async () => { + const dir = makeTempDir(); + tempDirs.push(dir); + const exporter = new JsonlLogExporter({ + filePath: path.join(dir, "private", "logs-{pid}.jsonl"), + serviceName: "test", + pid: 1006, + diagnostic: () => undefined, + }); + + await exportRecords(exporter, [createRecord("private")]); + await exporter.shutdown(); + + if (process.platform === "win32") { + const directoryAcl = execFileSync( + "icacls.exe", + [path.dirname(exporter.filePath)], + { encoding: "utf8" }, + ); + const fileAcl = execFileSync("icacls.exe", [exporter.filePath], { + encoding: "utf8", + }); + expect(directoryAcl).not.toContain("(I)"); + expect(fileAcl).not.toContain("(I)"); + } else { + expect( + fs.statSync(path.dirname(exporter.filePath)).mode & 0o777, + ).toBe(0o700); + expect(fs.statSync(exporter.filePath).mode & 0o777).toBe(0o600); + } + }); + it("bounds pending records and accounts for drops", async () => { const dir = makeTempDir(); tempDirs.push(dir); diff --git a/ts/packages/telemetry/test/otelLoggerSink.spec.ts b/ts/packages/telemetry/test/otelLoggerSink.spec.ts index fd84d6ef03..5b4fe49cc1 100644 --- a/ts/packages/telemetry/test/otelLoggerSink.spec.ts +++ b/ts/packages/telemetry/test/otelLoggerSink.spec.ts @@ -877,6 +877,29 @@ describe("OtelLoggerSink", () => { }); }); + it("stops reading a wide object after reaching the size bound", () => { + logFixture = installLogFixture(); + const sink = createOtelLoggerSink(); + const payload: Record = {}; + let getterReads = 0; + for (let i = 0; i < 100_000; i++) { + Object.defineProperty(payload, `field-${i}`, { + enumerable: true, + get() { + getterReads++; + return "value"; + }, + }); + } + + sink.logEvent(baseEvent({ event: payload })); + + const body = logFixture.exporter.getFinishedLogRecords()[0]! + .body as Record; + expect(body.__typeagent_otel_truncated).toBe("size"); + expect(getterReads).toBeLessThan(10_000); + }); + it("replaces a single oversized value instead of retaining it whole", () => { logFixture = installLogFixture(); const sink = createOtelLoggerSink(); From 7585b1904723347ec5f6044647c683423bdb4f17 Mon Sep 17 00:00:00 2001 From: George Ng Date: Wed, 12 Aug 2026 17:35:00 -0700 Subject: [PATCH 05/13] Add local grafana quickstart scripts and command --- .../architecture/telemetry/opentelemetry.md | 191 +++++++++++ ts/package.json | 1 + ts/tools/scripts/startLocalTelemetry.mjs | 324 ++++++++++++++++++ 3 files changed, 516 insertions(+) create mode 100644 ts/tools/scripts/startLocalTelemetry.mjs diff --git a/ts/docs/architecture/telemetry/opentelemetry.md b/ts/docs/architecture/telemetry/opentelemetry.md index 9ef08ea8fb..85e5ca0708 100644 --- a/ts/docs/architecture/telemetry/opentelemetry.md +++ b/ts/docs/architecture/telemetry/opentelemetry.md @@ -395,6 +395,197 @@ diagnostic path that cannot recurse into the exporter. The OS or external tools manage rotation and retention. JSONL and OTLP are additive. A JSONL-only configuration creates only the logs provider. +## Local End-to-End Validation with Grafana + +This procedure runs the Grafana LGTM development stack locally, sends TypeAgent +telemetry to it over OTLP/HTTP, and writes the same OTel logs to JSONL. It +validates the complete path: + +```text +TypeAgent debug + Structured Logger + └─► OTel logs provider + ├─► local JSONL file + └─► OTLP/HTTP collector ─► Loki ─► Grafana + +TypeAgent spans ─► OTLP/HTTP collector ─► Tempo ─► Grafana +``` + +### Prerequisites + +Install the TypeAgent workspace dependencies with `pnpm run setup` from `ts/` +if the checkout has not already been provisioned. + +Docker Desktop is the only external prerequisite. On Windows and macOS, the +repository helper can install it explicitly: + +```powershell +pnpm run telemetry:grafana --install +``` + +This uses `winget` on Windows or Homebrew on macOS and may request elevation or +acceptance of the Docker Desktop installer. Linux developers should install +Docker Engine using their distribution's supported procedure. Docker Desktop +may require a restart or sign-out after its first installation. + +Docker Desktop may also be +[installed manually](https://docs.docker.com/desktop/) before running the +normal start command. + +The Grafana +[`otel-lgtm`](https://hub.docker.com/r/grafana/otel-lgtm) image contains an OTel +collector, Loki, Tempo, Prometheus, and Grafana with the data sources already +connected. + +### 1. Start Grafana LGTM + +Run the repository helper from `ts/`: + +```powershell +pnpm run telemetry:grafana +``` + +The helper: + +- Optionally installs Docker Desktop when `--install` is specified. +- Verifies that the Docker CLI is installed. +- Starts Docker Desktop when needed on Windows or macOS and waits for its + engine. +- Pulls `grafana/otel-lgtm:latest` when it is not already installed. +- Starts or reuses the `typeagent-otel` container. +- Waits for Grafana to become healthy. +- Publishes Grafana and both collector receivers on `127.0.0.1` only. + +The loopback binding keeps the services inaccessible from other machines on +the network. Do not publish these ports on all interfaces unless remote access +is intentional and protected separately. + +The relevant endpoints are: + +| Port | Endpoint | +| ---- | --------------------------------- | +| 3000 | Grafana UI | +| 4317 | OTel collector OTLP/gRPC | +| 4318 | OTel collector OTLP/HTTP/protobuf | + +Verify that Grafana is ready: + +```powershell +Invoke-RestMethod http://localhost:3000/api/health +``` + +### 2. Configure and Start TypeAgent + +From `ts/`, build the agent server and configure its process environment: + +```powershell +pnpm run build agent-server + +$env:OTEL_SERVICE_NAME = "typeagent-local" +$env:OTEL_EXPORTER_OTLP_ENDPOINT = "http://localhost:4318" +$env:OTEL_TRACES_SAMPLER = "always_on" +$env:TYPEAGENT_OTEL_LOG_FILE = "$HOME\.typeagent\logs\typeagent-{service}-{pid}.jsonl" +$env:TYPEAGENT_OTEL_DEBUG_BRIDGE = "true" +$env:TYPEAGENT_OTEL_STRUCTURED_LOGS = "true" +$env:DEBUG = "typeagent:*,agent-server:*" + +pnpm run start:agent-server +``` + +The environment settings enable: + +- OTLP export for configured signals. +- One local JSONL file per process. +- Copies of enabled `debug` namespaces in the OTel logs pipeline. +- Privacy-filtered dispatcher Structured Logger events. +- Full local trace sampling so every generated trace can be inspected. + +The equivalent settings may be placed under `telemetry` in +`config.local.yaml`. Environment variables are useful for validation because +they apply only to the current terminal and override YAML. + +Only enabled `DEBUG` namespaces are bridged. Existing terminal debug output is +unchanged. Structured logging must be enabled explicitly because dispatcher +events can originate from user requests. + +### 3. Generate Telemetry + +In another terminal, connect the CLI: + +```powershell +cd C:\path\to\TypeAgent\ts +pnpm cli +``` + +Run a supported `@` command and a normal TypeAgent request. Wait a few seconds +for the batch exporters, or stop the agent server with `Ctrl+C` to flush pending +telemetry. + +### 4. Inspect the Local JSONL Logs + +Find the most recently written process log: + +```powershell +$log = Get-ChildItem "$HOME\.typeagent\logs\typeagent-local-*.jsonl" | + Sort-Object LastWriteTime -Descending | + Select-Object -First 1 + +$log.FullName +Get-Content $log.FullName -Wait +``` + +Each line is a JSON object. Expected fields include `timestamp`, +`severityText`, `body`, `eventName`, `traceId`, `spanId`, `attributes`, and +`resource`. + +Structured dispatcher records include events such as `command` and +`requestQueue:start`. Bridged debug records include their debug namespace. +Prompt text, response text, action parameters, errors, stacks, and unknown +dispatcher fields are excluded by the dispatcher projection. + +### 5. Inspect the Same Logs in Grafana + +Open [http://localhost:3000](http://localhost:3000), select **Explore**, and +choose the **Loki** data source. Query all records from this validation run: + +```logql +{service_name="typeagent-local"} +``` + +Useful filters include: + +```logql +{service_name="typeagent-local"} |= "command" +``` + +```logql +{service_name="typeagent-local"} |= "requestQueue" +``` + +Expand a log entry to inspect its structured body, resource attributes, +severity, and trace correlation. The local JSONL and Loki records come from the +same OTel log pipeline, so event names, bodies, and correlation identifiers +should agree. + +### 6. Inspect the Correlated Trace + +In Grafana **Explore**, choose the **Tempo** data source and search for service +name `typeagent-local`. A log emitted inside an active span contains `traceId` +and `spanId`; use the trace ID from either Loki or the JSONL record to open the +corresponding request trace in Tempo. + +This demonstrates the tangible improvement over terminal-only debug output: +structured application events and familiar debug records are searchable in one +backend and can be correlated with the request trace that produced them. + +### 7. Stop the Local Stack + +Stop TypeAgent with `Ctrl+C` first so its telemetry providers flush, then stop +Grafana LGTM: + +```powershell +pnpm run telemetry:grafana --stop +``` + ## Privacy and Reliability - Do not capture prompts, responses, user content, or known secrets by default. diff --git a/ts/package.json b/ts/package.json index dfec421605..12106bf8c1 100644 --- a/ts/package.json +++ b/ts/package.json @@ -78,6 +78,7 @@ "start:agent-server:tunnel": "pnpm -C packages/agentServer/server run start:tunnel", "start:mcp": "pnpm -C packages/commandExecutor run start", "stop:agent-server": "pnpm -C packages/agentServer/server run stop", + "telemetry:grafana": "node tools/scripts/startLocalTelemetry.mjs", "test": "pnpm run test:local && pnpm run test:live && pnpm run shell:test", "test:keys": "npx tsx tools/scripts/testServiceKeys.ts", "test:live": "pnpm -r ---no-bail -no-sort --stream --workspace-concurrency=1 run test:live", diff --git a/ts/tools/scripts/startLocalTelemetry.mjs b/ts/tools/scripts/startLocalTelemetry.mjs new file mode 100644 index 0000000000..af38ac1a23 --- /dev/null +++ b/ts/tools/scripts/startLocalTelemetry.mjs @@ -0,0 +1,324 @@ +#!/usr/bin/env node +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +import fs from "node:fs"; +import path from "node:path"; +import { spawn, spawnSync } from "node:child_process"; + +const containerName = "typeagent-otel"; +const imageName = "grafana/otel-lgtm:latest"; +const dockerReadyTimeoutMs = 120_000; +const grafanaReadyTimeoutMs = 120_000; + +const args = new Set(process.argv.slice(2)); +if (args.has("--help") || args.has("-h")) { + console.log(`Usage: pnpm run telemetry:grafana [--install | --stop] + +Starts Docker Desktop when needed on Windows or macOS, then starts the local +Grafana LGTM OpenTelemetry stack with loopback-only ports: + Grafana: http://localhost:3000 + OTLP/gRPC: http://localhost:4317 + OTLP/HTTP: http://localhost:4318 + +Options: + --install Install Docker Desktop when it is missing, then start Grafana. + --stop Stop the local Grafana LGTM container. + --help Show this help.`); + process.exit(0); +} + +function findDockerExecutable() { + if (process.platform === "win32") { + const installedExecutable = path.join( + process.env.ProgramFiles ?? "C:\\Program Files", + "Docker", + "Docker", + "resources", + "bin", + "docker.exe", + ); + if (fs.existsSync(installedExecutable)) { + return installedExecutable; + } + } + + const result = spawnSync("docker", ["--version"], { + encoding: "utf8", + stdio: ["ignore", "pipe", "pipe"], + }); + return result.status === 0 ? "docker" : undefined; +} + +let dockerExecutable = findDockerExecutable(); + +function runDocker(dockerArgs, { capture = false, check = true } = {}) { + if (dockerExecutable === undefined) { + throw new Error("Docker CLI was not found."); + } + const result = spawnSync(dockerExecutable, dockerArgs, { + encoding: "utf8", + stdio: capture ? ["ignore", "pipe", "pipe"] : "inherit", + }); + if (check && result.status !== 0) { + const detail = capture ? result.stderr?.trim() : undefined; + throw new Error( + `docker ${dockerArgs.join(" ")} failed${detail ? `: ${detail}` : "."}`, + ); + } + return result; +} + +function isDockerInstalled() { + return dockerExecutable !== undefined; +} + +function isDockerReady() { + return ( + runDocker(["info", "--format", "{{.ServerVersion}}"], { + capture: true, + check: false, + }).status === 0 + ); +} + +function runInstaller(command, installerArgs) { + const result = spawnSync(command, installerArgs, { + stdio: "inherit", + }); + if (result.error?.code === "ENOENT") { + throw new Error(`${command} was not found.`); + } + if (result.status !== 0) { + throw new Error(`${command} installation failed (${result.status}).`); + } +} + +function installDockerDesktop() { + if (process.platform === "win32") { + console.log( + "[telemetry:grafana] Installing Docker Desktop with winget...", + ); + runInstaller("winget", [ + "install", + "--exact", + "--id", + "Docker.DockerDesktop", + "--accept-package-agreements", + "--accept-source-agreements", + ]); + } else if (process.platform === "darwin") { + console.log( + "[telemetry:grafana] Installing Docker Desktop with Homebrew...", + ); + runInstaller("brew", ["install", "--cask", "docker"]); + } else { + throw new Error( + "Automatic Docker installation is supported only on Windows and macOS. Install Docker Engine for this platform, then run the command again.", + ); + } + + dockerExecutable = findDockerExecutable(); + if (dockerExecutable === undefined) { + throw new Error( + "Docker Desktop was installed, but the Docker CLI is not available. Restart the terminal and run `pnpm run telemetry:grafana`.", + ); + } +} + +function startDockerDesktop() { + if (process.platform === "win32") { + const candidates = [ + path.join( + process.env.ProgramFiles ?? "C:\\Program Files", + "Docker", + "Docker", + "Docker Desktop.exe", + ), + path.join( + process.env.LOCALAPPDATA ?? "", + "Docker", + "Docker Desktop.exe", + ), + ]; + const executable = candidates.find((candidate) => + fs.existsSync(candidate), + ); + if (executable === undefined) { + throw new Error( + "Docker Desktop is installed but its executable could not be found.", + ); + } + const child = spawn(executable, [], { + detached: true, + stdio: "ignore", + }); + child.unref(); + return; + } + + if (process.platform === "darwin") { + const result = spawnSync("open", ["-a", "Docker"], { + stdio: "ignore", + }); + if (result.status !== 0) { + throw new Error("Docker Desktop could not be started."); + } + return; + } + + throw new Error( + "The Docker daemon is not running. Start it, then run this command again.", + ); +} + +async function waitFor(description, timeoutMs, probe) { + const deadline = Date.now() + timeoutMs; + while (Date.now() < deadline) { + if (await probe()) { + return; + } + await new Promise((resolve) => setTimeout(resolve, 2_000)); + } + throw new Error(`${description} did not become ready within 2 minutes.`); +} + +function getContainerId(all) { + const dockerArgs = ["ps", "-q"]; + if (all) { + dockerArgs.push("-a"); + } + dockerArgs.push("--filter", `name=^/${containerName}$`); + const result = runDocker(dockerArgs, { capture: true }); + return result.stdout.trim(); +} + +function hasLoopbackBindings() { + const result = runDocker( + [ + "inspect", + "--format", + "{{json .HostConfig.PortBindings}}", + containerName, + ], + { capture: true }, + ); + const bindings = JSON.parse(result.stdout); + return ["3000/tcp", "4317/tcp", "4318/tcp"].every((port) => { + const entries = bindings[port]; + return ( + Array.isArray(entries) && + entries.length === 1 && + entries[0]?.HostIp === "127.0.0.1" + ); + }); +} + +async function waitForGrafana() { + await waitFor("Grafana", grafanaReadyTimeoutMs, async () => { + try { + const response = await fetch("http://127.0.0.1:3000/api/health"); + return response.ok; + } catch { + return false; + } + }); +} + +async function stop() { + if (!isDockerInstalled()) { + throw new Error( + "Docker CLI was not found. Install Docker Desktop before using this command.", + ); + } + if (!isDockerReady()) { + console.log("[telemetry:grafana] Docker is not running."); + return; + } + if (getContainerId(true) === "") { + console.log("[telemetry:grafana] Grafana LGTM is not running."); + return; + } + runDocker(["stop", containerName]); +} + +async function start() { + if (!isDockerInstalled()) { + if (!args.has("--install")) { + throw new Error( + "Docker Desktop is not installed. Run `pnpm run telemetry:grafana --install` or install it manually from https://docs.docker.com/desktop/.", + ); + } + installDockerDesktop(); + } + + if (!isDockerReady()) { + console.log("[telemetry:grafana] Starting Docker Desktop..."); + startDockerDesktop(); + await waitFor("Docker Desktop", dockerReadyTimeoutMs, isDockerReady); + } + + if (getContainerId(true) !== "" && !hasLoopbackBindings()) { + console.log( + "[telemetry:grafana] Recreating the container with loopback-only ports...", + ); + runDocker(["rm", "--force", containerName]); + } + + if (getContainerId(false) !== "") { + console.log( + "[telemetry:grafana] Grafana LGTM is already running at http://localhost:3000", + ); + await waitForGrafana(); + return; + } + + if (getContainerId(true) !== "") { + console.log("[telemetry:grafana] Starting the existing container..."); + runDocker(["start", containerName]); + } else { + console.log( + "[telemetry:grafana] Pulling and starting Grafana LGTM as needed...", + ); + runDocker([ + "run", + "--detach", + "--rm", + "--name", + containerName, + "-p", + "127.0.0.1:3000:3000", + "-p", + "127.0.0.1:4317:4317", + "-p", + "127.0.0.1:4318:4318", + imageName, + ]); + } + + await waitForGrafana(); + console.log("[telemetry:grafana] Grafana: http://localhost:3000"); + console.log("[telemetry:grafana] OTLP/HTTP: http://localhost:4318"); + console.log("[telemetry:grafana] OTLP/gRPC: http://localhost:4317"); +} + +try { + for (const arg of args) { + if (arg !== "--install" && arg !== "--stop") { + throw new Error(`Unknown argument: ${arg}`); + } + } + if (args.has("--install") && args.has("--stop")) { + throw new Error("--install and --stop cannot be used together."); + } + if (args.has("--stop")) { + await stop(); + } else { + await start(); + } +} catch (error) { + console.error( + `[telemetry:grafana] ${error instanceof Error ? error.message : String(error)}`, + ); + process.exit(1); +} From 241a3af80d0e5fffc09d4a105004a86007156518 Mon Sep 17 00:00:00 2001 From: George Ng Date: Wed, 12 Aug 2026 21:32:19 -0700 Subject: [PATCH 06/13] Fix parameter flow for shell --- ts/docs/architecture/telemetry/opentelemetry.md | 12 ++++++++++-- ts/packages/shell/src/main/instance.ts | 2 ++ ts/packages/telemetry/src/otel/debugBridge.ts | 5 +---- 3 files changed, 13 insertions(+), 6 deletions(-) diff --git a/ts/docs/architecture/telemetry/opentelemetry.md b/ts/docs/architecture/telemetry/opentelemetry.md index 85e5ca0708..d97843a524 100644 --- a/ts/docs/architecture/telemetry/opentelemetry.md +++ b/ts/docs/architecture/telemetry/opentelemetry.md @@ -551,12 +551,20 @@ choose the **Loki** data source. Query all records from this validation run: {service_name="typeagent-local"} ``` -Useful filters include: +Set the Explore time range to cover the validation run. For the `@help` +example, this query matches both structured and bridged records containing +`help`: ```logql -{service_name="typeagent-local"} |= "command" +{service_name="typeagent-local"} |= "help" ``` +Use a distinctive, non-sensitive term from the command you ran when validating +a different request. Avoid copying PowerShell-escaped strings such as `\"` +into the Grafana query editor; LogQL strings use normal quotes there. + +To inspect queue bridge output: + ```logql {service_name="typeagent-local"} |= "requestQueue" ``` diff --git a/ts/packages/shell/src/main/instance.ts b/ts/packages/shell/src/main/instance.ts index 14a2012588..f9b931163e 100644 --- a/ts/packages/shell/src/main/instance.ts +++ b/ts/packages/shell/src/main/instance.ts @@ -89,6 +89,7 @@ async function initializeDispatcher( connect?: number, hidden?: boolean, idleTimeout?: number, + structuredLogs: boolean = false, ): Promise { if (cleanupP !== undefined) { // Make sure the previous cleanup is done. @@ -986,6 +987,7 @@ export function initializeInstance( connect, hidden, idleTimeout, + structuredLogs, ); const onChatViewReady = async (event: Electron.IpcMainEvent) => { diff --git a/ts/packages/telemetry/src/otel/debugBridge.ts b/ts/packages/telemetry/src/otel/debugBridge.ts index af79195a63..c7fde8e807 100644 --- a/ts/packages/telemetry/src/otel/debugBridge.ts +++ b/ts/packages/telemetry/src/otel/debugBridge.ts @@ -34,10 +34,7 @@ interface InstalledBridge { refCount: number; } -type DebugFunction = ( - this: { namespace?: string }, - ...args: unknown[] -) => unknown; +type DebugFunction = (this: any, ...args: any[]) => unknown; interface EffectiveDebugBridgeOptions extends RedactionOptions { readonly includedNamespacePrefixes: readonly string[]; From 918f147755436b3d027f1ed7cff74e7fa9f385f8 Mon Sep 17 00:00:00 2001 From: George Ng Date: Wed, 12 Aug 2026 21:42:33 -0700 Subject: [PATCH 07/13] Fix complexity warning --- .../architecture/telemetry/opentelemetry.md | 6 +- .../telemetry/src/logger/otelLoggerSink.ts | 193 +++++++++++------- ts/packages/telemetry/src/otel/debugBridge.ts | 47 +++-- 3 files changed, 158 insertions(+), 88 deletions(-) diff --git a/ts/docs/architecture/telemetry/opentelemetry.md b/ts/docs/architecture/telemetry/opentelemetry.md index d97843a524..011803991a 100644 --- a/ts/docs/architecture/telemetry/opentelemetry.md +++ b/ts/docs/architecture/telemetry/opentelemetry.md @@ -544,8 +544,10 @@ dispatcher fields are excluded by the dispatcher projection. ### 5. Inspect the Same Logs in Grafana -Open [http://localhost:3000](http://localhost:3000), select **Explore**, and -choose the **Loki** data source. Query all records from this validation run: +Open [http://localhost:3000](http://localhost:3000), select **Explore**, choose +the **Loki** data source, and switch the query editor to **Code** mode. Do not +use Logs Drilldown or its search box; those use a different search API rather +than executing the LogQL below. Query all records from this validation run: ```logql {service_name="typeagent-local"} diff --git a/ts/packages/telemetry/src/logger/otelLoggerSink.ts b/ts/packages/telemetry/src/logger/otelLoggerSink.ts index 2f17b9d48b..12d36cd974 100644 --- a/ts/packages/telemetry/src/logger/otelLoggerSink.ts +++ b/ts/packages/telemetry/src/logger/otelLoggerSink.ts @@ -445,101 +445,146 @@ function cloneBounded( depth: number, state: BoundedTraversalState, ): unknown { - // Once the size cap has been crossed, everything downstream becomes - // a marker so partial containers stop growing. if (state.sizeTruncated) { return truncationMarker("size"); } - if (depth >= BODY_MAX_DEPTH) { return boundedMarker("depth", state); } + if (value === null) { + return clonePrimitive(value, state); + } + if (isJsonPrimitive(value)) { + return clonePrimitive(value, state); + } + if (typeof value !== "object") { + return boundedMarker("unsupported", state); + } + if (state.visited.has(value)) { + return boundedMarker("cycle", state); + } - // JSON-compatible primitives. - if ( - value === null || + state.visited.add(value); + try { + return Array.isArray(value) + ? cloneArray(value, depth, state) + : cloneObject(value, depth, state); + } finally { + state.visited.delete(value); + } +} + +type JsonPrimitive = null | string | boolean | number; + +function isJsonPrimitive( + value: unknown, +): value is Exclude { + return ( typeof value === "string" || typeof value === "boolean" || (typeof value === "number" && Number.isFinite(value)) - ) { - if (!tryCharge(state, approxPrimitiveChars(value))) { - return truncationMarker("size"); + ); +} + +function clonePrimitive( + value: JsonPrimitive, + state: BoundedTraversalState, +): JsonPrimitive | Record { + return tryCharge(state, approxPrimitiveChars(value)) + ? value + : truncationMarker("size"); +} + +function cloneArray( + source: readonly unknown[], + depth: number, + state: BoundedTraversalState, +): unknown[] { + if (!tryCharge(state, 2)) { + return [truncationMarker("size")]; + } + + const clone: unknown[] = []; + for (let index = 0; index < source.length; index++) { + if (!chargeArraySeparator(index, state)) { + clone.push(truncationMarker("size")); + break; + } + clone.push(cloneBounded(source[index], depth + 1, state)); + if (state.sizeTruncated) { + break; } - return value; } - if (typeof value !== "object") { + return clone; +} + +function chargeArraySeparator( + index: number, + state: BoundedTraversalState, +): boolean { + return !state.sizeTruncated && (index === 0 || tryCharge(state, 1)); +} + +function cloneObject( + source: object, + depth: number, + state: BoundedTraversalState, +): Record { + if (!isPlainObject(source)) { return boundedMarker("unsupported", state); } - // Cycles. - if (state.visited.has(value as object)) { - return boundedMarker("cycle", state); + const clone: Record = {}; + if (!tryCharge(state, 2)) { + markObjectSizeTruncated(clone); + return clone; } - state.visited.add(value as object); - try { - if (Array.isArray(value)) { - if (!tryCharge(state, 2)) { - return [truncationMarker("size")]; - } - const result: unknown[] = []; - for (let i = 0; i < value.length; i++) { - if (state.sizeTruncated) { - result.push(truncationMarker("size")); - break; - } - if (i > 0 && !tryCharge(state, 1)) { - result.push(truncationMarker("size")); - break; - } - result.push(cloneBounded(value[i], depth + 1, state)); - if (state.sizeTruncated) { - break; - } - } - return result; - } - - const prototype = Object.getPrototypeOf(value); - if (prototype !== Object.prototype && prototype !== null) { - return boundedMarker("unsupported", state); + let propertyCount = 0; + for (const key in source) { + if (!Object.prototype.hasOwnProperty.call(source, key)) { + continue; } - - const source = value as Record; - const clone: Record = {}; - if (!tryCharge(state, 2)) { - setOwnValue(clone, TRUNCATION_MARKER_KEY, "size"); - return clone; + if (!chargeObjectProperty(key, propertyCount, state)) { + markObjectSizeTruncated(clone); + break; } - let first = true; - for (const key in source) { - if (!Object.prototype.hasOwnProperty.call(source, key)) { - continue; - } - if (state.sizeTruncated) { - setOwnValue(clone, TRUNCATION_MARKER_KEY, "size"); - break; - } - const propertyChars = - (first ? 0 : 1) + approxPrimitiveChars(key) + 1; - if (!tryCharge(state, propertyChars)) { - setOwnValue(clone, TRUNCATION_MARKER_KEY, "size"); - break; - } - first = false; - setOwnValue( - clone, - key, - cloneBounded(source[key], depth + 1, state), - ); - if (state.sizeTruncated) { - break; - } + propertyCount++; + setOwnValue( + clone, + key, + cloneBounded( + (source as Record)[key], + depth + 1, + state, + ), + ); + if (state.sizeTruncated) { + break; } - return clone; - } finally { - state.visited.delete(value as object); } + return clone; +} + +function isPlainObject(value: object): boolean { + const prototype = Object.getPrototypeOf(value); + return prototype === Object.prototype || prototype === null; +} + +function chargeObjectProperty( + key: string, + propertyCount: number, + state: BoundedTraversalState, +): boolean { + if (state.sizeTruncated) { + return false; + } + const separatorChars = propertyCount === 0 ? 0 : 1; + return tryCharge(state, separatorChars + approxPrimitiveChars(key) + 1); +} + +function markObjectSizeTruncated(target: Record): void { + setOwnValue(target, TRUNCATION_MARKER_KEY, "size"); } function boundedMarker( diff --git a/ts/packages/telemetry/src/otel/debugBridge.ts b/ts/packages/telemetry/src/otel/debugBridge.ts index c7fde8e807..06100ff64d 100644 --- a/ts/packages/telemetry/src/otel/debugBridge.ts +++ b/ts/packages/telemetry/src/otel/debugBridge.ts @@ -14,7 +14,7 @@ import { redactText, type RedactionOptions } from "./redaction.js"; export interface DebugModule { log: DebugFunction; - formatArgs?: DebugFunction; + formatArgs?: unknown; } export interface DebugBridgeOptions extends RedactionOptions { @@ -28,13 +28,16 @@ export interface DebugBridge { interface InstalledBridge { readonly hook: "formatArgs" | "log"; - readonly prior: DebugFunction; + readonly prior: Function; readonly wrapped: DebugFunction; readonly options: EffectiveDebugBridgeOptions; refCount: number; } -type DebugFunction = (this: any, ...args: any[]) => unknown; +type DebugFunction = ( + this: { namespace?: string }, + ...args: unknown[] +) => unknown; interface EffectiveDebugBridgeOptions extends RedactionOptions { readonly includedNamespacePrefixes: readonly string[]; @@ -87,9 +90,10 @@ export function installDebugBridge( continue; } - const hook = - debugModule.formatArgs === undefined ? "log" : "formatArgs"; - const prior = debugModule[hook]!; + const formatArgs = debugModule.formatArgs; + const hook = typeof formatArgs === "function" ? "formatArgs" : "log"; + const prior: Function = + typeof formatArgs === "function" ? formatArgs : debugModule.log; const wrapped: DebugFunction = hook === "formatArgs" ? function ( @@ -98,10 +102,10 @@ export function installDebugBridge( ): unknown { const args = callArgs[0]; if (!Array.isArray(args)) { - return prior.apply(this, callArgs); + return Reflect.apply(prior, this, callArgs); } const rawArgs = [...args]; - const result = prior.apply(this, callArgs); + const result = Reflect.apply(prior, this, callArgs); emitDebugRecord( this?.namespace, rawArgs, @@ -113,11 +117,11 @@ export function installDebugBridge( this: { namespace?: string }, ...args: unknown[] ): unknown { - const result = prior.apply(this, args); + const result = Reflect.apply(prior, this, args); emitDebugRecord(this?.namespace, args, effectiveOptions); return result; }; - debugModule[hook] = wrapped; + setDebugHook(debugModule, hook, wrapped); installedBridges.set(debugModule, { hook, prior, @@ -144,8 +148,8 @@ export function installDebugBridge( if (state.refCount > 0) { continue; } - if (debugModule[state.hook] === state.wrapped) { - debugModule[state.hook] = state.prior; + if (getDebugHook(debugModule, state.hook) === state.wrapped) { + setDebugHook(debugModule, state.hook, state.prior); } installedBridges.delete(debugModule); } @@ -153,6 +157,25 @@ export function installDebugBridge( }; } +function getDebugHook( + debugModule: DebugModule, + hook: "formatArgs" | "log", +): unknown { + return hook === "formatArgs" ? debugModule.formatArgs : debugModule.log; +} + +function setDebugHook( + debugModule: DebugModule, + hook: "formatArgs" | "log", + value: Function, +): void { + if (hook === "formatArgs") { + debugModule.formatArgs = value; + } else { + debugModule.log = value as DebugFunction; + } +} + function emitDebugRecord( namespace: string | undefined, args: unknown[], From bf28a7f11a3d5594c48aeabdaa8fddcaf7a2811a Mon Sep 17 00:00:00 2001 From: George Ng Date: Wed, 12 Aug 2026 23:06:50 -0700 Subject: [PATCH 08/13] Fix broken test --- ts/packages/dispatcher/nodeProviders/test/agentDebug.spec.ts | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/ts/packages/dispatcher/nodeProviders/test/agentDebug.spec.ts b/ts/packages/dispatcher/nodeProviders/test/agentDebug.spec.ts index ca454d61b6..6d61bcb7d9 100644 --- a/ts/packages/dispatcher/nodeProviders/test/agentDebug.spec.ts +++ b/ts/packages/dispatcher/nodeProviders/test/agentDebug.spec.ts @@ -34,7 +34,9 @@ describe("loadAgentDebug", () => { expect(loaded).toBeDefined(); expect(loaded?.debug).not.toBe(registerDebug); - expect(loaded?.path).toBe(path.join(debugDir, "index.js")); + expect(loaded && fs.realpathSync(loaded.path)).toBe( + fs.realpathSync(path.join(debugDir, "index.js")), + ); }); test("does not return the host debug module as a second instance", () => { From b4d411e3c645792a345159be2510b4bcc2d3888b Mon Sep 17 00:00:00 2001 From: George Ng Date: Wed, 12 Aug 2026 23:38:53 -0700 Subject: [PATCH 09/13] Name local telemetry logs by process role Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> Copilot-Session: 5d8cccd6-408a-4f05-90ae-71e254022055 --- ts/config.sample.yaml | 5 +++-- .../architecture/telemetry/opentelemetry.md | 17 ++++++++------- ts/packages/agentServer/server/src/server.ts | 1 + ts/packages/api/src/index.ts | 1 + ts/packages/cli/bin/dev.js | 5 ++++- ts/packages/cli/bin/run.js | 5 ++++- .../src/agentProvider/process/agentProcess.ts | 5 ++++- ts/packages/shell/src/main/index.ts | 1 + ts/packages/telemetry/src/otel/bootstrap.ts | 18 +++++++++++++++- ts/packages/telemetry/src/otel/config.ts | 8 +++---- ts/packages/telemetry/src/otel/index.ts | 1 + .../telemetry/src/otel/jsonlLogExporter.ts | 11 +++++++++- ts/packages/telemetry/src/otel/resources.ts | 8 +++++++ .../telemetry/test/otelBootstrap.spec.ts | 4 ++++ .../test/otelLocalDiagnostics.spec.ts | 21 ++++++++++++++++++- 15 files changed, 92 insertions(+), 19 deletions(-) diff --git a/ts/config.sample.yaml b/ts/config.sample.yaml index 2f4ffdfd0f..8368a68830 100644 --- a/ts/config.sample.yaml +++ b/ts/config.sample.yaml @@ -400,7 +400,8 @@ typeagent: # - otlpEndpoint fallback endpoint for traces + metrics + logs # - logFile local JSONL log file; enables the logs signal # independently of any OTLP endpoint. Leading -# `~`/`~/`/`~\` expands to your home dir. +# `~`/`~/`/`~\` expands to your home dir. Supports +# `{service}`, `{process}`, and `{pid}` placeholders. # - debugBridge copy enabled typeagent:* debug output to OTel logs # - tracesSampler one of always_on, always_off, traceidratio, # parentbased_always_on, parentbased_always_off, @@ -409,7 +410,7 @@ typeagent: # telemetry: # otlpEndpoint: http://localhost:4318 -# logFile: ~/.typeagent/logs/typeagent-{service}-{pid}.jsonl +# logFile: ~/.typeagent/logs/typeagent-{service}-{process}-{pid}.jsonl # debugBridge: true # structuredLogs: true # tracesSampler: parentbased_traceidratio diff --git a/ts/docs/architecture/telemetry/opentelemetry.md b/ts/docs/architecture/telemetry/opentelemetry.md index 011803991a..bad01fc90e 100644 --- a/ts/docs/architecture/telemetry/opentelemetry.md +++ b/ts/docs/architecture/telemetry/opentelemetry.md @@ -330,7 +330,7 @@ TypeAgent-owned processes support: ```yaml telemetry: otlpEndpoint: http://localhost:4318 - logFile: ~/.typeagent/logs/typeagent-{service}-{pid}.jsonl + logFile: ~/.typeagent/logs/typeagent-{service}-{process}-{pid}.jsonl debugBridge: true tracesSampler: always_on ``` @@ -358,7 +358,7 @@ Set `TYPEAGENT_OTEL_LOG_FILE` or YAML `telemetry.logFile` to write OTel logs directly, without OTLP, a collector, or a backend: ```powershell -$env:TYPEAGENT_OTEL_LOG_FILE = "$HOME\.typeagent\logs\typeagent-{service}-{pid}.jsonl" +$env:TYPEAGENT_OTEL_LOG_FILE = "$HOME\.typeagent\logs\typeagent-{service}-{process}-{pid}.jsonl" ``` For dispatcher PID 12345, the resolved path may be: @@ -387,10 +387,13 @@ The path is implemented as an OTel `LogRecordExporter` behind a bounded - Rate-limit diagnostics and disable or retry under a documented policy. - Apply redaction before enqueueing records. -Expand `~` before `path.resolve()`. Sanitize `{service}` and `{pid}`. If `{pid}` -is absent, insert it before the extension so processes never share a writer. -Create parent directories and report the resolved path once through a status or -diagnostic path that cannot recurse into the exporter. +Expand `~` before `path.resolve()`. Sanitize `{service}`, `{process}`, and +`{pid}`. TypeAgent-owned hosts identify their process role as `agent-server`, +`api-server`, `shell`, `cli`, or `agent-`. If `{process}` or `{pid}` is +absent, insert it before the extension so filenames remain identifiable and +processes never share a writer. Create parent directories and report the +resolved path once through a status or diagnostic path that cannot recurse into +the exporter. The OS or external tools manage rotation and retention. JSONL and OTLP are additive. A JSONL-only configuration creates only the logs provider. @@ -483,7 +486,7 @@ pnpm run build agent-server $env:OTEL_SERVICE_NAME = "typeagent-local" $env:OTEL_EXPORTER_OTLP_ENDPOINT = "http://localhost:4318" $env:OTEL_TRACES_SAMPLER = "always_on" -$env:TYPEAGENT_OTEL_LOG_FILE = "$HOME\.typeagent\logs\typeagent-{service}-{pid}.jsonl" +$env:TYPEAGENT_OTEL_LOG_FILE = "$HOME\.typeagent\logs\typeagent-{service}-{process}-{pid}.jsonl" $env:TYPEAGENT_OTEL_DEBUG_BRIDGE = "true" $env:TYPEAGENT_OTEL_STRUCTURED_LOGS = "true" $env:DEBUG = "typeagent:*,agent-server:*" diff --git a/ts/packages/agentServer/server/src/server.ts b/ts/packages/agentServer/server/src/server.ts index 2b5a1b9466..8c9b40a033 100644 --- a/ts/packages/agentServer/server/src/server.ts +++ b/ts/packages/agentServer/server/src/server.ts @@ -182,6 +182,7 @@ await loadConfig({ keyVault: {}, strict: false }); const telemetryConfig = otel.resolveTelemetryConfig(); const telemetryInit = otel.initTelemetry({ config: telemetryConfig, + processName: "agent-server", debugModules: [registerDebug], debugBridge: { includedNamespacePrefixes: ["typeagent:", "agent-server:"], diff --git a/ts/packages/api/src/index.ts b/ts/packages/api/src/index.ts index c539a181e1..a1c3fa3d71 100644 --- a/ts/packages/api/src/index.ts +++ b/ts/packages/api/src/index.ts @@ -44,6 +44,7 @@ async function main(): Promise { const telemetryConfig = otel.resolveTelemetryConfig(); await otel.initTelemetry({ config: telemetryConfig, + processName: "api-server", debugModules: [registerDebug], debugBridge: { includedNamespacePrefixes: ["typeagent:", "agent-server:"], diff --git a/ts/packages/cli/bin/dev.js b/ts/packages/cli/bin/dev.js index 8b1cbe84e0..6f89ca50ca 100755 --- a/ts/packages/cli/bin/dev.js +++ b/ts/packages/cli/bin/dev.js @@ -16,7 +16,10 @@ async function main() { process.env.NODE_ENV = "development"; settings.debug = true; try { - await otel.initTelemetry({ debugModules: [registerDebug] }); + await otel.initTelemetry({ + processName: "cli", + debugModules: [registerDebug], + }); await run(process.argv.slice(2), import.meta.url); await flush(); await otel.shutdownTelemetry(); diff --git a/ts/packages/cli/bin/run.js b/ts/packages/cli/bin/run.js index e46cdaaf3a..1be3dce799 100755 --- a/ts/packages/cli/bin/run.js +++ b/ts/packages/cli/bin/run.js @@ -13,7 +13,10 @@ registerEarlyTelemetrySignalHandlers(); async function main() { const { flush, handle, run } = await import("@oclif/core"); try { - await otel.initTelemetry({ debugModules: [registerDebug] }); + await otel.initTelemetry({ + processName: "cli", + debugModules: [registerDebug], + }); await run(process.argv.slice(2), import.meta.url); await flush(); await otel.shutdownTelemetry(); diff --git a/ts/packages/dispatcher/nodeProviders/src/agentProvider/process/agentProcess.ts b/ts/packages/dispatcher/nodeProviders/src/agentProvider/process/agentProcess.ts index fe065f99c4..9f5ba91ecb 100644 --- a/ts/packages/dispatcher/nodeProviders/src/agentProvider/process/agentProcess.ts +++ b/ts/packages/dispatcher/nodeProviders/src/agentProvider/process/agentProcess.ts @@ -84,7 +84,10 @@ async function startAgentProcess(): Promise { agentDebug === undefined ? [registerDebug] : [registerDebug, agentDebug]; - await otel.initTelemetry({ debugModules }); + await otel.initTelemetry({ + processName: `agent-${agentName}`, + debugModules, + }); //================================================================= // Load the module. diff --git a/ts/packages/shell/src/main/index.ts b/ts/packages/shell/src/main/index.ts index f87169d359..4a50a2565a 100644 --- a/ts/packages/shell/src/main/index.ts +++ b/ts/packages/shell/src/main/index.ts @@ -212,6 +212,7 @@ async function initialize() { const telemetryConfig = otel.resolveTelemetryConfig(); await otel.initTelemetry({ config: telemetryConfig, + processName: "shell", debugModules: [registerDebug], debugBridge: { includedNamespacePrefixes: ["typeagent:", "agent-server:"], diff --git a/ts/packages/telemetry/src/otel/bootstrap.ts b/ts/packages/telemetry/src/otel/bootstrap.ts index 7fdd206612..ace9b8948b 100644 --- a/ts/packages/telemetry/src/otel/bootstrap.ts +++ b/ts/packages/telemetry/src/otel/bootstrap.ts @@ -57,7 +57,10 @@ import { type TelemetryLifecycle, type TelemetryLifecycleOptions, } from "./lifecycle.js"; -import { createProcessResource } from "./resources.js"; +import { + createProcessResource, + TYPEAGENT_PROCESS_NAME_ATTRIBUTE, +} from "./resources.js"; import { installDebugBridge, type DebugBridgeOptions, @@ -124,6 +127,8 @@ export interface InitTelemetryOptions { /** Shared resource supplied to every requested signal provider. */ readonly resource?: Resource; readonly serviceName?: string; + /** Stable process role used in resource metadata and local log filenames. */ + readonly processName?: string; readonly serviceVersion?: string; readonly serviceInstanceId?: string; readonly deploymentEnvironment?: string; @@ -216,11 +221,19 @@ const DEFAULT_FACTORIES: TelemetryProviderFactories = { configuredServiceName.length > 0 ? configuredServiceName : "typeagent"; + const configuredProcessName = + resource.attributes[TYPEAGENT_PROCESS_NAME_ATTRIBUTE]; + const processName = + typeof configuredProcessName === "string" && + configuredProcessName.length > 0 + ? configuredProcessName + : "process"; processors.push( new BatchLogRecordProcessor({ exporter: new JsonlLogExporter({ filePath: config.logFile, serviceName, + processName, }), maxQueueSize: 2_048, maxExportBatchSize: 256, @@ -373,6 +386,9 @@ async function createDefaultTelemetryResource( options.serviceName ?? (options.configOptions?.env ?? process.env).OTEL_SERVICE_NAME ?? "typeagent", + ...(options.processName === undefined + ? {} + : { processName: options.processName }), ...(options.serviceVersion === undefined ? {} : { serviceVersion: options.serviceVersion }), diff --git a/ts/packages/telemetry/src/otel/config.ts b/ts/packages/telemetry/src/otel/config.ts index 52a119240f..38e32c163d 100644 --- a/ts/packages/telemetry/src/otel/config.ts +++ b/ts/packages/telemetry/src/otel/config.ts @@ -66,10 +66,10 @@ export interface LogConfig { readonly otlp?: OtlpExporterConfig; /** * Local file path for OTel log records, e.g. - * `"~/.typeagent/logs/typeagent-{service}-{pid}.jsonl"`. Template - * placeholders such as `{service}` and `{pid}` are preserved verbatim - * by the resolver; only a leading `~`, `~/`, or `~\` is expanded to - * the user's home directory. + * `"~/.typeagent/logs/typeagent-{service}-{process}-{pid}.jsonl"`. + * Template placeholders such as `{service}`, `{process}`, and `{pid}` are + * preserved verbatim by the resolver; only a leading `~`, `~/`, or `~\` + * is expanded to the user's home directory. */ readonly logFile?: string; } diff --git a/ts/packages/telemetry/src/otel/index.ts b/ts/packages/telemetry/src/otel/index.ts index 0fc0086da5..7b83fa34a2 100644 --- a/ts/packages/telemetry/src/otel/index.ts +++ b/ts/packages/telemetry/src/otel/index.ts @@ -50,6 +50,7 @@ export { export { createProcessResource, + TYPEAGENT_PROCESS_NAME_ATTRIBUTE, type ProcessResourceOptions, } from "./resources.js"; diff --git a/ts/packages/telemetry/src/otel/jsonlLogExporter.ts b/ts/packages/telemetry/src/otel/jsonlLogExporter.ts index ce119db59f..665fe7bbbc 100644 --- a/ts/packages/telemetry/src/otel/jsonlLogExporter.ts +++ b/ts/packages/telemetry/src/otel/jsonlLogExporter.ts @@ -13,6 +13,7 @@ import type { export interface JsonlLogExporterOptions { readonly filePath: string; readonly serviceName: string; + readonly processName?: string; readonly pid?: number; readonly maxPendingRecords?: number; readonly diagnostic?: (message: string, error?: unknown) => void; @@ -38,6 +39,7 @@ export class JsonlLogExporter implements LogRecordExporter { options.filePath, options.serviceName, options.pid, + options.processName, ); this.maxPendingRecords = options.maxPendingRecords ?? DEFAULT_MAX_PENDING_RECORDS; @@ -285,20 +287,27 @@ export function resolveJsonlLogPath( template: string, serviceName: string, pid = process.pid, + processName = "process", ): string { if (!Number.isInteger(pid) || pid <= 0) { throw new Error("JSONL pid must be a positive integer."); } const service = sanitizePathSegment(serviceName); + const processRole = sanitizePathSegment(processName); const hadPidPlaceholder = template.includes("{pid}"); + const hadProcessPlaceholder = template.includes("{process}"); + if (!hadProcessPlaceholder && hadPidPlaceholder) { + template = template.replaceAll("{pid}", "{process}-{pid}"); + } let resolved = template .replaceAll("{service}", service) + .replaceAll("{process}", processRole) .replaceAll("{pid}", String(pid)); if (!hadPidPlaceholder) { const parsed = path.parse(resolved); resolved = path.join( parsed.dir, - `${parsed.name}-${pid}${parsed.ext || ".jsonl"}`, + `${parsed.name}${hadProcessPlaceholder ? "" : `-${processRole}`}-${pid}${parsed.ext || ".jsonl"}`, ); } return path.resolve(resolved); diff --git a/ts/packages/telemetry/src/otel/resources.ts b/ts/packages/telemetry/src/otel/resources.ts index 312c7c883e..8baba72e8a 100644 --- a/ts/packages/telemetry/src/otel/resources.ts +++ b/ts/packages/telemetry/src/otel/resources.ts @@ -25,6 +25,7 @@ import { } from "@opentelemetry/semantic-conventions/incubating"; const PROCESS_INSTANCE_ID = randomUUID(); +export const TYPEAGENT_PROCESS_NAME_ATTRIBUTE = "typeagent.process.name"; /** * Constructs the process-level OTel {@link Resource} TypeAgent-owned hosts @@ -36,6 +37,8 @@ const PROCESS_INSTANCE_ID = randomUUID(); export interface ProcessResourceOptions { /** `service.name`. Required: every TypeAgent-owned process must set it. */ readonly serviceName: string; + /** Stable TypeAgent process role, such as `agent-server` or `shell`. */ + readonly processName?: string; /** `service.version`, when known. */ readonly serviceVersion?: string; /** VCS revision checked out in the running build. */ @@ -73,6 +76,7 @@ export function createProcessResource( options.serviceVersion, "serviceVersion", ); + const processName = normalizeOptional(options.processName, "processName"); const serviceInstanceId = normalizeOptional(options.serviceInstanceId, "serviceInstanceId") ?? PROCESS_INSTANCE_ID; @@ -101,6 +105,9 @@ export function createProcessResource( if (serviceVersion !== undefined) { identity[ATTR_SERVICE_VERSION] = serviceVersion; } + if (processName !== undefined) { + identity[TYPEAGENT_PROCESS_NAME_ATTRIBUTE] = processName; + } if (deploymentEnvironment !== undefined) { identity[ATTR_DEPLOYMENT_ENVIRONMENT_NAME] = deploymentEnvironment; } @@ -124,6 +131,7 @@ export function createProcessResource( ATTR_PROCESS_RUNTIME_VERSION, ATTR_VCS_REF_HEAD_REVISION, ATTR_VCS_REF_BASE_REVISION, + TYPEAGENT_PROCESS_NAME_ATTRIBUTE, ]) { delete attributes[key]; } diff --git a/ts/packages/telemetry/test/otelBootstrap.spec.ts b/ts/packages/telemetry/test/otelBootstrap.spec.ts index 250d2418fb..daf33bdbcd 100644 --- a/ts/packages/telemetry/test/otelBootstrap.spec.ts +++ b/ts/packages/telemetry/test/otelBootstrap.spec.ts @@ -148,6 +148,7 @@ describe("telemetry bootstrap", () => { logs: { logFile: "telemetry.jsonl" }, }, serviceName: "bootstrap-test", + processName: "agent-server", serviceVersion: "1.2.3", serviceInstanceId: "bootstrap-instance", deploymentEnvironment: "test", @@ -175,6 +176,9 @@ describe("telemetry bootstrap", () => { expect(resources).toHaveLength(2); expect(resources[0]).toBe(resources[1]); expect(resources[0].attributes["service.name"]).toBe("bootstrap-test"); + expect(resources[0].attributes["typeagent.process.name"]).toBe( + "agent-server", + ); expect(resources[0].attributes["service.version"]).toBe("1.2.3"); expect(resources[0].attributes["service.instance.id"]).toBe( "bootstrap-instance", diff --git a/ts/packages/telemetry/test/otelLocalDiagnostics.spec.ts b/ts/packages/telemetry/test/otelLocalDiagnostics.spec.ts index 8d03fbdc42..24fbc5a2b6 100644 --- a/ts/packages/telemetry/test/otelLocalDiagnostics.spec.ts +++ b/ts/packages/telemetry/test/otelLocalDiagnostics.spec.ts @@ -77,9 +77,28 @@ describe("JsonlLogExporter", () => { path.join("logs", "typeagent-{service}.jsonl"), "agent/server", 1234, + "agent-player", ); expect(resolved).toBe( - path.resolve("logs", "typeagent-agent_server-1234.jsonl"), + path.resolve( + "logs", + "typeagent-agent_server-agent-player-1234.jsonl", + ), + ); + }); + + it("adds the process role to legacy templates containing only a pid", () => { + const resolved = resolveJsonlLogPath( + path.join("logs", "typeagent-{service}-{pid}.jsonl"), + "typeagent-local", + 1234, + "agent-server", + ); + expect(resolved).toBe( + path.resolve( + "logs", + "typeagent-typeagent-local-agent-server-1234.jsonl", + ), ); }); From 2b2c120a0bc503b036ddfebfcf2850619057c068 Mon Sep 17 00:00:00 2001 From: George Ng Date: Thu, 13 Aug 2026 01:12:43 -0700 Subject: [PATCH 10/13] Fix Windows test path and teardown failures Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> Copilot-Session: 5d8cccd6-408a-4f05-90ae-71e254022055 --- .../lsp/test/serverIntegration.spec.ts | 23 +++++++++++-------- .../nodeProviders/test/agentDebug.spec.ts | 9 +++++--- 2 files changed, 19 insertions(+), 13 deletions(-) diff --git a/ts/examples/workflow/lsp/test/serverIntegration.spec.ts b/ts/examples/workflow/lsp/test/serverIntegration.spec.ts index 7151bfa4c9..ba28d6ef22 100644 --- a/ts/examples/workflow/lsp/test/serverIntegration.spec.ts +++ b/ts/examples/workflow/lsp/test/serverIntegration.spec.ts @@ -22,6 +22,8 @@ import { DefinitionRequest, RenameRequest, DocumentRangeFormattingRequest, + ShutdownRequest, + ExitNotification, StreamMessageReader, StreamMessageWriter, } from "vscode-languageserver-protocol/node.js"; @@ -67,16 +69,17 @@ async function startSession(debounceMs = 5) { server, publishes, cleanup: async () => { - // Add a small delay to let pending operations and error handlers complete - // before disposing connections. This prevents "Connection is disposed" errors - // when error handlers try to send notifications after test completion. - await new Promise((resolve) => setTimeout(resolve, 50)); - client.dispose(); - server.dispose(); - pipes.serverTransport.input.destroy(); - pipes.serverTransport.output.destroy(); - pipes.clientReader.dispose(); - pipes.clientWriter.dispose(); + try { + await client.sendRequest(ShutdownRequest.type); + await client.sendNotification(ExitNotification.type); + } finally { + server.dispose(); + client.dispose(); + pipes.clientReader.dispose(); + pipes.clientWriter.dispose(); + pipes.serverTransport.input.destroy(); + pipes.serverTransport.output.destroy(); + } }, }; } diff --git a/ts/packages/dispatcher/nodeProviders/test/agentDebug.spec.ts b/ts/packages/dispatcher/nodeProviders/test/agentDebug.spec.ts index 6d61bcb7d9..3a9fc79947 100644 --- a/ts/packages/dispatcher/nodeProviders/test/agentDebug.spec.ts +++ b/ts/packages/dispatcher/nodeProviders/test/agentDebug.spec.ts @@ -34,9 +34,12 @@ describe("loadAgentDebug", () => { expect(loaded).toBeDefined(); expect(loaded?.debug).not.toBe(registerDebug); - expect(loaded && fs.realpathSync(loaded.path)).toBe( - fs.realpathSync(path.join(debugDir, "index.js")), - ); + const loadedStat = loaded && fs.statSync(loaded.path, { bigint: true }); + const expectedStat = fs.statSync(path.join(debugDir, "index.js"), { + bigint: true, + }); + expect(loadedStat?.dev).toBe(expectedStat.dev); + expect(loadedStat?.ino).toBe(expectedStat.ino); }); test("does not return the host debug module as a second instance", () => { From 40685e7b14a92353abaf09261b9494e3bbb5e447 Mon Sep 17 00:00:00 2001 From: George Ng Date: Thu, 13 Aug 2026 01:52:57 -0700 Subject: [PATCH 11/13] Fix LSP test transport double disposal Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> Copilot-Session: 5d8cccd6-408a-4f05-90ae-71e254022055 --- ts/examples/workflow/lsp/test/serverIntegration.spec.ts | 4 ---- 1 file changed, 4 deletions(-) diff --git a/ts/examples/workflow/lsp/test/serverIntegration.spec.ts b/ts/examples/workflow/lsp/test/serverIntegration.spec.ts index ba28d6ef22..1c975defd7 100644 --- a/ts/examples/workflow/lsp/test/serverIntegration.spec.ts +++ b/ts/examples/workflow/lsp/test/serverIntegration.spec.ts @@ -75,10 +75,6 @@ async function startSession(debounceMs = 5) { } finally { server.dispose(); client.dispose(); - pipes.clientReader.dispose(); - pipes.clientWriter.dispose(); - pipes.serverTransport.input.destroy(); - pipes.serverTransport.output.destroy(); } }, }; From 2ea6febdff4ff660ac3d8e6c37dbf4176357bbbe Mon Sep 17 00:00:00 2001 From: George Ng Date: Thu, 13 Aug 2026 02:15:43 -0700 Subject: [PATCH 12/13] Fix studio event listener race Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> Copilot-Session: 5d8cccd6-408a-4f05-90ae-71e254022055 --- .../typeagent-studio/src/test/collisionsSource.spec.ts | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/ts/packages/typeagent-studio/src/test/collisionsSource.spec.ts b/ts/packages/typeagent-studio/src/test/collisionsSource.spec.ts index c152aade2c..1cdd035f3d 100644 --- a/ts/packages/typeagent-studio/src/test/collisionsSource.spec.ts +++ b/ts/packages/typeagent-studio/src/test/collisionsSource.spec.ts @@ -73,14 +73,12 @@ test("StudioServiceCollisionsSource delegates scan/clear and routes events", asy }); const source = new StudioServiceCollisionsSource(connection); try { - assert.equal(await connection.connect(), true); - // Register listeners BEFORE any awaited round-trips so the one-shot - // push (~20ms after subscribe) isn't missed. let collisions = 0; let agentLoads = 0; source.onCollisionDetected(() => (collisions += 1)); source.onAgentLoadChanged(() => (agentLoads += 1)); + assert.equal(await connection.connect(), true); const scan = await source.scanGrammarCollisions(); assert.deepEqual(scan.scanned, ["player"]); assert.equal(await source.clearCollisions(), 0); From 075c50a8eb2613de79fde6a4ef7bfd39bcdb8f68 Mon Sep 17 00:00:00 2001 From: George Ng Date: Thu, 13 Aug 2026 03:20:34 -0700 Subject: [PATCH 13/13] Fix studio event source listener races Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> Copilot-Session: 5d8cccd6-408a-4f05-90ae-71e254022055 --- ts/packages/typeagent-studio/src/test/eventLogSource.spec.ts | 3 +-- ts/packages/typeagent-studio/src/test/sandboxSource.spec.ts | 2 +- 2 files changed, 2 insertions(+), 3 deletions(-) diff --git a/ts/packages/typeagent-studio/src/test/eventLogSource.spec.ts b/ts/packages/typeagent-studio/src/test/eventLogSource.spec.ts index f3824e4d4c..e75c67e52b 100644 --- a/ts/packages/typeagent-studio/src/test/eventLogSource.spec.ts +++ b/ts/packages/typeagent-studio/src/test/eventLogSource.spec.ts @@ -86,11 +86,10 @@ test("StudioServiceEventSource (over the shared connection) seeds + fans out liv }); const source = new StudioServiceEventSource(connection); try { - assert.equal(await connection.connect(), true); const received: StudioEvent[] = []; - // Register before any awaited round-trip so the one-shot push isn't missed. const sub = source.onAnyEvent((e) => received.push(e)); + assert.equal(await connection.connect(), true); const seed = await source.queryRecentEvents(200); assert.deepEqual( seed.map((e) => e.type), diff --git a/ts/packages/typeagent-studio/src/test/sandboxSource.spec.ts b/ts/packages/typeagent-studio/src/test/sandboxSource.spec.ts index c29a7b10bd..397bf8ed97 100644 --- a/ts/packages/typeagent-studio/src/test/sandboxSource.spec.ts +++ b/ts/packages/typeagent-studio/src/test/sandboxSource.spec.ts @@ -66,10 +66,10 @@ test("StudioServiceSandboxSource delegates lifecycle + routes sandbox events", a }); const source = new StudioServiceSandboxSource(connection); try { - assert.equal(await connection.connect(), true); let changes = 0; source.onSandboxChanged(() => (changes += 1)); + assert.equal(await connection.connect(), true); assert.equal((await source.listSandboxes()).length, 1); const started = await source.startSandbox({ id: "s1" }); assert.equal(started.id, "s1");