From fa45bfa69cfdff4cc9af9a188299906f732f9afc Mon Sep 17 00:00:00 2001 From: Abhijeet Prasad Date: Mon, 19 Oct 2026 14:06:46 -0700 Subject: [PATCH 1/6] feat(logs): add application logging and console capture Send application messages to Braintrust alongside your traces. Use the logger returned by initLogger() directly, or capture future console calls with wrapConsole(). Each call records one complete log event without a follow-up update. Existing console output stays visible. ## Public API ```js import { initLogger, wrapConsole } from "braintrust"; const logger = initLogger({ projectName: "application-logs" }); ``` | API | Behavior | | --- | --- | | logger.trace(body, options?) | Record a trace-level message; does not start a trace. | | logger.debug(body, options?) | Record a debug-level message. | | logger.info(body, options?) | Record an info-level message. | | logger.warn(body, options?) | Record a warning. | | logger.error(body, options?) | Record an error-level message. | | logger.fatal(body, options?) | Record a fatal-level message. | | logger.fmt`text ${value}` | Prepare a message that preserves its template and values. | | wrapConsole(target = console, { logger } = {}) | Capture future console calls; return a cleanup function. | | await logger.flush() | Wait for queued messages to upload. | Bodies can be strings or JSON-serializable values. All severity methods accept { metadata: { ... } } as their second argument. By default they return a row ID immediately. With initLogger({ asyncFlush: false, ... }), they return a promise that resolves to the row ID after uploading. ## Track request activity with structured messages ```js await logger.traced(async () => { logger.info("Checkout started", { metadata: { request_id: "req_123", customer_id: "customer_456" }, }); logger.warn({ event: "payment_retry", attempt: 2 }); }, { name: "checkout" }); await logger.flush(); ``` Messages emitted inside an active Braintrust or compatible OpenTelemetry span share its span and trace IDs, while retaining their own log row IDs. They do not create child spans or change the active span. Outside an active span, messages from a logger share that logger's baseline trace ID. ## Keep templates for grouping related messages ```js const userId = "user_123"; const amount = 12.5; logger.info(logger.fmt`User ${userId} paid ${amount.toFixed(2)}`, { metadata: { source: "checkout" }, }); ``` The displayed message is "User user_123 paid 12.50". JavaScript evaluates each expression normally, so use expressions such as amount.toFixed(2) for formatting. The native template tag preserves these metadata fields: | Metadata key | Value | | --- | --- | | braintrust.template | User ${0} paid ${1} | | braintrust.template.parameter.0 | "user_123" | | braintrust.template.parameter.1 | "12.50" | | source | "checkout" | Parameters use positional keys because JavaScript template tags receive values, not variable names. JSON-compatible values retain their types; undefined and bigint become strings. Ordinary strings, including interpolated strings passed without logger.fmt, are recorded verbatim without template metadata. ## Capture an application's existing console calls ```js const stopCapturing = wrapConsole(console, { logger }); console.log("Worker started"); console.warn("Payment %s will retry", "pay_123"); stopCapturing(); await logger.flush(); ``` | Console method | Braintrust severity | | --- | --- | | log, info | info | | trace | trace | | debug | debug | | warn | warn | | error | error | wrapConsole() without arguments instruments the global console and uses the current project logger at call time. Before a logger is initialized, console calls keep their normal output without uploading logs. Pass a console instance and { logger } to select a specific destination. Node uses its native console message formatter. Other runtimes preserve the arguments as text in Braintrust while the original console retains its native rendering. SDK diagnostics and internal HTTP transport logs are excluded from capture to prevent recursion. Repeated wrapping does not duplicate messages. The cleanup function is safe to call repeatedly and does not disable a newer wrap or reactivate an older wrap. It stops future forwarding; messages already queued still upload, and direct logger calls remain available. ## Possible extensions These are future directions, not APIs included in this change: | Extension | Use case | | --- | --- | | Minimum severity filters | Reduce verbose production logs while retaining warnings and errors. | | Child loggers with shared metadata | Attach request, tenant, or worker context to every message. | | Adapters for Pino and Winston | Forward existing structured logs without changing application call sites. | | Log processing hooks | Redact sensitive fields or enrich messages before upload. | --- js/src/debug-logger.ts | 39 +- js/src/exports.ts | 2 + js/src/framework.ts | 245 +++++------ js/src/isomorph.ts | 1 + js/src/logger.ts | 165 +++++++- js/src/logs/console-interceptor.ts | 55 +++ js/src/logs/context.ts | 40 ++ js/src/logs/index.ts | 128 ++++++ js/src/logs/logs.test.ts | 627 +++++++++++++++++++++++++++++ js/src/logs/templates.ts | 59 +++ js/src/node/config.ts | 3 +- js/src/reporters/progress.ts | 7 +- js/src/wrappers/shared/flush.ts | 7 +- 13 files changed, 1221 insertions(+), 157 deletions(-) create mode 100644 js/src/logs/console-interceptor.ts create mode 100644 js/src/logs/context.ts create mode 100644 js/src/logs/index.ts create mode 100644 js/src/logs/logs.test.ts create mode 100644 js/src/logs/templates.ts diff --git a/js/src/debug-logger.ts b/js/src/debug-logger.ts index 6b4b6b17c..3e874bf59 100644 --- a/js/src/debug-logger.ts +++ b/js/src/debug-logger.ts @@ -1,4 +1,5 @@ import iso from "./isomorph"; +import { suppressApplicationLogs } from "./logs/context"; import { setGlobalHookErrorReporter } from "./global-instrumentation-hooks"; export type DebugLogLevel = "error" | "warn" | "info" | "debug"; @@ -45,10 +46,12 @@ function warnInvalidEnvValue(value: string) { return; } hasWarnedAboutInvalidEnvValue = true; - // eslint-disable-next-line no-restricted-properties -- preserving intentional console usage. - console.warn( - PREFIX, - `Invalid BRAINTRUST_DEBUG_LOG_LEVEL value "${value}". Expected "error", "warn", "info", or "debug".`, + suppressApplicationLogs(() => + // eslint-disable-next-line no-restricted-properties -- preserving intentional console usage. + console.warn( + PREFIX, + `Invalid BRAINTRUST_DEBUG_LOG_LEVEL value "${value}". Expected "error", "warn", "info", or "debug".`, + ), ); } @@ -155,19 +158,21 @@ function emit( return false; } - if (method === "info") { - // eslint-disable-next-line no-restricted-properties -- preserving intentional console usage. - console.log(PREFIX, ...args); - } else if (method === "debug") { - // eslint-disable-next-line no-restricted-properties -- preserving intentional console usage. - console.debug(PREFIX, ...args); - } else if (method === "warn") { - // eslint-disable-next-line no-restricted-properties -- preserving intentional console usage. - console.warn(PREFIX, ...args); - } else { - // eslint-disable-next-line no-restricted-properties -- preserving intentional console usage. - console.error(PREFIX, ...args); - } + suppressApplicationLogs(() => { + if (method === "info") { + // eslint-disable-next-line no-restricted-properties -- preserving intentional console usage. + console.log(PREFIX, ...args); + } else if (method === "debug") { + // eslint-disable-next-line no-restricted-properties -- preserving intentional console usage. + console.debug(PREFIX, ...args); + } else if (method === "warn") { + // eslint-disable-next-line no-restricted-properties -- preserving intentional console usage. + console.warn(PREFIX, ...args); + } else { + // eslint-disable-next-line no-restricted-properties -- preserving intentional console usage. + console.error(PREFIX, ...args); + } + }); return true; } diff --git a/js/src/exports.ts b/js/src/exports.ts index 98c512d01..1e4d2449e 100644 --- a/js/src/exports.ts +++ b/js/src/exports.ts @@ -44,6 +44,8 @@ export type { WithTransactionId, } from "./logger"; +export { wrapConsole } from "./logs"; + export type { SandboxConfig, RegisterSandboxOptions, diff --git a/js/src/framework.ts b/js/src/framework.ts index b150c6a7b..698858409 100644 --- a/js/src/framework.ts +++ b/js/src/framework.ts @@ -20,6 +20,7 @@ import { v5 as uuidv5 } from "uuid"; import iso from "./isomorph"; import { debugLogger } from "./debug-logger"; +import { suppressApplicationLogs } from "./logs/context"; import { GenericFunction } from "./framework-types"; import { CodeFunction, CodePrompt, CodeParameters } from "./framework2"; import { Trace, LocalTrace } from "./trace"; @@ -1786,13 +1787,15 @@ export const error = (text: string) => `Error: ${text}`; export const warning = (text: string) => `Warning: ${text}`; export function logError(e: unknown, verbose: boolean) { - if (!verbose) { - // eslint-disable-next-line no-restricted-properties -- preserving intentional console usage. - console.error(`${e}`); - } else { - // eslint-disable-next-line no-restricted-properties -- preserving intentional console usage. - console.error(e); - } + suppressApplicationLogs(() => { + if (!verbose) { + // eslint-disable-next-line no-restricted-properties -- user-facing evaluation error output is independent of SDK diagnostics. + console.error(`${e}`); + } else { + // eslint-disable-next-line no-restricted-properties -- user-facing evaluation error output is independent of SDK diagnostics. + console.error(e); + } + }); } type ScoreAccumulator = { @@ -1865,40 +1868,42 @@ export function reportFailures< failingResults: EvalResult[], { verbose, jsonl }: ReporterOpts, ) { - if (failingResults.length > 0) { - // TODO: We may want to support a non-strict mode (and make this the "strict" behavior), so that - // users can still log imperfect evaluations. In the meantime, they should handle these cases inside - // of their tasks. - // eslint-disable-next-line no-restricted-properties -- preserving intentional console usage. - console.error( - warning( - `Evaluator ${evaluator.evalName} failed with ${failingResults.length} error${failingResults.length === 1 ? "" : "s"}. This evaluation ("${evaluator.evalName}") will not be fully logged.`, - ), - ); - if (jsonl) { - // eslint-disable-next-line no-restricted-properties -- preserving intentional console usage. - console.log( - JSON.stringify({ - evaluatorName: evaluator.evalName, - errors: failingResults.map( - (r) => `${r.error instanceof Error ? r.error.stack : r.error}`, - ), - }), - ); - } else { - for (const result of failingResults) { - logError(result.error, verbose); - } - } - if (!verbose && !jsonl) { - // eslint-disable-next-line no-restricted-properties -- preserving intentional console usage. + suppressApplicationLogs(() => { + if (failingResults.length > 0) { + // TODO: We may want to support a non-strict mode (and make this the "strict" behavior), so that + // users can still log imperfect evaluations. In the meantime, they should handle these cases inside + // of their tasks. + // eslint-disable-next-line no-restricted-properties -- user-facing evaluation report output is independent of SDK diagnostics. console.error( warning( - "Use --debug-logging debug to see full stack traces and troubleshooting details.", + `Evaluator ${evaluator.evalName} failed with ${failingResults.length} error${failingResults.length === 1 ? "" : "s"}. This evaluation ("${evaluator.evalName}") will not be fully logged.`, ), ); + if (jsonl) { + // eslint-disable-next-line no-restricted-properties -- user-facing evaluation report output is independent of SDK diagnostics. + console.log( + JSON.stringify({ + evaluatorName: evaluator.evalName, + errors: failingResults.map( + (r) => `${r.error instanceof Error ? r.error.stack : r.error}`, + ), + }), + ); + } else { + for (const result of failingResults) { + logError(result.error, verbose); + } + } + if (!verbose && !jsonl) { + // eslint-disable-next-line no-restricted-properties -- user-facing evaluation report output is independent of SDK diagnostics. + console.error( + warning( + "Use --debug-logging debug to see full stack traces and troubleshooting details.", + ), + ); + } } - } + }); } /** @@ -1918,110 +1923,114 @@ const defaultReporter: ReporterDef = { result: EvalResultWithSummary, { verbose, jsonl }: ReporterOpts, ) { - const { results, summary } = result; - const failingResults = results.filter( - (r: { error: unknown }) => r.error !== undefined, - ); - - if (failingResults.length > 0) { - reportFailures(evaluator, failingResults, { verbose, jsonl }); - } - - if (jsonl) { - iso.writeln(JSON.stringify(summary)); - } else { - // Simple plain-text output without fancy formatting - iso.writeln("Experiment summary"); - iso.writeln("=================="); + return suppressApplicationLogs(() => { + const { results, summary } = result; + const failingResults = results.filter( + (r: { error: unknown }) => r.error !== undefined, + ); - if (summary.comparisonExperimentName) { - iso.writeln( - `${summary.comparisonExperimentName} (baseline) <- ${summary.experimentName} (comparison)`, - ); - iso.writeln(""); + if (failingResults.length > 0) { + reportFailures(evaluator, failingResults, { verbose, jsonl }); } - const hasScores = Object.keys(summary.scores).length > 0; - const hasMetrics = Object.keys(summary.metrics ?? {}).length > 0; - const hasComparison = !!summary.comparisonExperimentName; + if (jsonl) { + iso.writeln(JSON.stringify(summary)); + } else { + // Simple plain-text output without fancy formatting + iso.writeln("Experiment summary"); + iso.writeln("=================="); - if (hasScores || hasMetrics) { - if (hasComparison) { + if (summary.comparisonExperimentName) { iso.writeln( - "Name Value Change Improvements Regressions", - ); - iso.writeln( - "----------------------------------------------------------------", + `${summary.comparisonExperimentName} (baseline) <- ${summary.experimentName} (comparison)`, ); + iso.writeln(""); } - // Scores - for (const score of Object.values(summary.scores)) { - const scorePercent = (score.score * 100).toFixed(2); - const scoreValue = `${scorePercent}%`; + const hasScores = Object.keys(summary.scores).length > 0; + const hasMetrics = Object.keys(summary.metrics ?? {}).length > 0; + const hasComparison = !!summary.comparisonExperimentName; + if (hasScores || hasMetrics) { if (hasComparison) { - let diffString = "-"; - if (!isEmpty(score.diff)) { - const diffPercent = (score.diff! * 100).toFixed(2); - const diffSign = score.diff! > 0 ? "+" : ""; - diffString = `${diffSign}${diffPercent}%`; - } - - const improvements = - score.improvements > 0 ? score.improvements.toString() : "-"; - const regressions = - score.regressions > 0 ? score.regressions.toString() : "-"; - iso.writeln( - `${score.name.padEnd(18)} ${scoreValue.padStart(10)} ${diffString.padStart(10)} ${improvements.padStart(12)} ${regressions.padStart(11)}`, + "Name Value Change Improvements Regressions", + ); + iso.writeln( + "----------------------------------------------------------------", ); - } else { - iso.writeln(`${score.name.padEnd(20)} ${scoreValue.padStart(15)}`); } - } - // Metrics - for (const metric of Object.values(summary.metrics ?? {})) { - const fractionDigits = Number.isInteger(metric.metric) ? 0 : 2; - const formattedValue = metric.metric.toFixed(fractionDigits); - const metricValue = - metric.unit === "$" - ? `${metric.unit}${formattedValue}` - : `${formattedValue}${metric.unit}`; + // Scores + for (const score of Object.values(summary.scores)) { + const scorePercent = (score.score * 100).toFixed(2); + const scoreValue = `${scorePercent}%`; + + if (hasComparison) { + let diffString = "-"; + if (!isEmpty(score.diff)) { + const diffPercent = (score.diff! * 100).toFixed(2); + const diffSign = score.diff! > 0 ? "+" : ""; + diffString = `${diffSign}${diffPercent}%`; + } - if (hasComparison) { - let diffString = "-"; - if (!isEmpty(metric.diff)) { - const diffPercent = (metric.diff! * 100).toFixed(2); - const diffSign = metric.diff! > 0 ? "+" : ""; - diffString = `${diffSign}${diffPercent}%`; + const improvements = + score.improvements > 0 ? score.improvements.toString() : "-"; + const regressions = + score.regressions > 0 ? score.regressions.toString() : "-"; + + iso.writeln( + `${score.name.padEnd(18)} ${scoreValue.padStart(10)} ${diffString.padStart(10)} ${improvements.padStart(12)} ${regressions.padStart(11)}`, + ); + } else { + iso.writeln( + `${score.name.padEnd(20)} ${scoreValue.padStart(15)}`, + ); } + } - const improvements = - metric.improvements > 0 ? metric.improvements.toString() : "-"; - const regressions = - metric.regressions > 0 ? metric.regressions.toString() : "-"; + // Metrics + for (const metric of Object.values(summary.metrics ?? {})) { + const fractionDigits = Number.isInteger(metric.metric) ? 0 : 2; + const formattedValue = metric.metric.toFixed(fractionDigits); + const metricValue = + metric.unit === "$" + ? `${metric.unit}${formattedValue}` + : `${formattedValue}${metric.unit}`; + + if (hasComparison) { + let diffString = "-"; + if (!isEmpty(metric.diff)) { + const diffPercent = (metric.diff! * 100).toFixed(2); + const diffSign = metric.diff! > 0 ? "+" : ""; + diffString = `${diffSign}${diffPercent}%`; + } - iso.writeln( - `${metric.name.padEnd(18)} ${metricValue.padStart(10)} ${diffString.padStart(10)} ${improvements.padStart(12)} ${regressions.padStart(11)}`, - ); - } else { - iso.writeln( - `${metric.name.padEnd(20)} ${metricValue.padStart(15)}`, - ); + const improvements = + metric.improvements > 0 ? metric.improvements.toString() : "-"; + const regressions = + metric.regressions > 0 ? metric.regressions.toString() : "-"; + + iso.writeln( + `${metric.name.padEnd(18)} ${metricValue.padStart(10)} ${diffString.padStart(10)} ${improvements.padStart(12)} ${regressions.padStart(11)}`, + ); + } else { + iso.writeln( + `${metric.name.padEnd(20)} ${metricValue.padStart(15)}`, + ); + } } } - } - if (summary.experimentUrl) { - iso.writeln(""); - iso.writeln(`View results for ${summary.experimentName}`); - iso.writeln(`See results at ${summary.experimentUrl}`); + if (summary.experimentUrl) { + iso.writeln(""); + iso.writeln(`View results for ${summary.experimentName}`); + iso.writeln(`See results at ${summary.experimentUrl}`); + } } - } - iso.writeln(""); - return failingResults.length === 0; + iso.writeln(""); + return failingResults.length === 0; + }); }, async reportRun(evalReports: boolean[]) { return evalReports.every((r) => r); diff --git a/js/src/isomorph.ts b/js/src/isomorph.ts index 354adf2cb..ea49549ce 100644 --- a/js/src/isomorph.ts +++ b/js/src/isomorph.ts @@ -41,6 +41,7 @@ interface Common { getEnv: (name: string) => string | undefined; getBraintrustApiKey: () => Promise; getCallerLocation: () => CallerLocation | undefined; + formatLogMessage?: (...args: unknown[]) => string; newAsyncLocalStorage: () => IsoAsyncLocalStorage; // eslint-disable-next-line @typescript-eslint/no-explicit-any processOn: (event: string, handler: (code: any) => void) => void; diff --git a/js/src/logger.ts b/js/src/logger.ts index c70661482..64079f1af 100644 --- a/js/src/logger.ts +++ b/js/src/logger.ts @@ -1,6 +1,14 @@ /// import { DecisionAttachmentProcessor } from "./decision-attachments"; +import { internalFetch } from "./logs/context"; +import { + formatLogTemplate, + renderLogBody, + type ApplicationLogLevel, + type ApplicationLogOptions, + type ApplicationLogTemplate, +} from "./logs/templates"; import { v4 as uuidv4 } from "uuid"; @@ -1631,11 +1639,11 @@ class HTTPConnection { this.headers = {}; this._reset(); - this.fetch = fetch; + this.fetch = internalFetch(fetch); } public setFetch(fetch: typeof globalThis.fetch) { - this.fetch = fetch; + this.fetch = internalFetch(fetch); } async ping() { @@ -2058,7 +2066,7 @@ export class Attachment extends BaseAttachment { try { objectStoreResponse = await withRetry(async () => checkResponse( - await fetch(signedUrl, { + await internalFetch(fetch)(signedUrl, { method: "PUT" satisfies RequestInit["method"], headers, body: data, @@ -2333,7 +2341,7 @@ export class ReadonlyAttachment { ); } - const objResponse = await fetch(downloadUrl); + const objResponse = await internalFetch(fetch)(downloadUrl); if (objResponse.status !== 200) { const error = await objResponse.text(); throw new Error(`Couldn't download attachment: ${error}`); @@ -2900,6 +2908,7 @@ export class Logger implements Exportable { private lastStartTime: number; private lazyId: LazyValue; private calledStartSpan: boolean; + private readonly baselineTraceId: string; // For type identification. public kind = "logger" as const; @@ -2917,6 +2926,7 @@ export class Logger implements Exportable { this.lazyId = new LazyValue(async () => await this.id); this.calledStartSpan = false; this.state = state; + this.baselineTraceId = state.idGenerator.getTraceId(); } public get org_id(): Promise { @@ -2983,6 +2993,121 @@ export class Logger implements Exportable { } } + /** + * Capture an application log as one complete row, correlated with the active + * Braintrust or OpenTelemetry span. Without an active span, logs from this + * logger share a baseline trace ID. + */ + private emitLog( + body: unknown, + level: ApplicationLogLevel, + options?: ApplicationLogOptions, + ): PromiseUnless { + const rendered = renderLogBody(body, options); + const timestamp = getCurrentUnixTimestamp(); + const current = this.state.contextManager.getParentSpanIds(); + // Supply all fields in the initial write. Calling span.end() here would + // enqueue an unnecessary second write for this instantaneous event. + const span = new SpanImpl({ + state: this.state, + parentObjectType: this.parentObjectType(), + parentObjectId: this.lazyId, + parentComputeObjectMetadataArgs: this.computeMetadataArgs, + parentSpanIds: { + rootSpanId: current?.rootSpanId ?? this.baselineTraceId, + parentSpanIds: [], + }, + spanId: current?.spanParents[0], + name: "Log", + spanAttributes: { name: null, type: "log", log_level: level }, + startTime: timestamp, + event: { + output: rendered.body, + metadata: rendered.metadata, + metrics: { end: timestamp }, + }, + }); + type Ret = PromiseUnless; + if (this.asyncFlush === true) return span.id as Ret; + return this.flush().then(() => span.id) as Ret; + } + + /** + * Preserve a native JavaScript template literal and its interpolation values. + * Format values with JavaScript expressions, such as `${amount.toFixed(2)}`. + * Pass the result to any application-log severity method. + * + * @example + * logger.info(logger.fmt`User ${userId} paid ${amount.toFixed(2)}`, { + * metadata: { source: "checkout" }, + * }); + */ + public fmt( + strings: TemplateStringsArray, + ...values: unknown[] + ): ApplicationLogTemplate { + return formatLogTemplate(strings, values); + } + + /** Capture a trace-level application log. Does not start a trace. */ + public trace( + body: unknown, + options?: ApplicationLogOptions, + ): PromiseUnless { + return this.emitLog(body, "trace", options); + } + + /** Capture a debug-level application log. Supports {@link Logger.fmt} templates. */ + public debug( + body: unknown, + options?: ApplicationLogOptions, + ): PromiseUnless { + return this.emitLog(body, "debug", options); + } + + /** + * Capture an info-level application log. Bodies may be any JSON-serializable value. + * Logs share the active span's IDs, or a baseline trace ID for this logger. + * Use {@link Logger.fmt} to preserve a native JavaScript template and its values + * in `braintrust.template` metadata fields. + * Returns the row ID, or a promise resolving after flush when asyncFlush is false. + * + * @example + * logger.info(logger.fmt`User ${userId} paid ${amount.toFixed(2)}`, { + * metadata: { source: "checkout" }, + * }); + */ + public info( + body: unknown, + options?: ApplicationLogOptions, + ): PromiseUnless { + return this.emitLog(body, "info", options); + } + + /** Capture a warn-level application log. Supports {@link Logger.fmt} templates. */ + public warn( + body: unknown, + options?: ApplicationLogOptions, + ): PromiseUnless { + return this.emitLog(body, "warn", options); + } + + /** Capture an error-level application log. Supports {@link Logger.fmt} templates. */ + public error( + body: unknown, + options?: ApplicationLogOptions, + ): PromiseUnless { + return this.emitLog(body, "error", options); + } + + /** Capture a fatal-level application log. Supports {@link Logger.fmt} templates. */ + public fatal( + body: unknown, + options?: ApplicationLogOptions, + ): PromiseUnless { + return this.emitLog(body, "fatal", options); + } + /** * Create a new toplevel span underneath the logger. The name defaults to "root". * @@ -5948,13 +6073,16 @@ async function loginToLoaderRequestState({ } else { let loginResponse: Response; try { - loginResponse = await fetch(_urljoin(appUrl, `/api/apikey/login`), { - method: "POST", - headers: { - "Content-Type": "application/json", - Authorization: `Bearer ${apiKey}`, + loginResponse = await internalFetch(fetch)( + _urljoin(appUrl, `/api/apikey/login`), + { + method: "POST", + headers: { + "Content-Type": "application/json", + Authorization: `Bearer ${apiKey}`, + }, }, - }); + ); } catch (error) { throw new HTTPTransportError(error); } @@ -6031,14 +6159,17 @@ export async function loginToState(options: LoginOptions = {}) { // cancellation, so a stalled request cannot block subsequent logins. info = await Promise.race([ (async () => { - const response = await fetch(_urljoin(appUrl, `/api/apikey/login`), { - method: "POST", - headers: { - "Content-Type": "application/json", - Authorization: `Bearer ${apiKey}`, + const response = await internalFetch(fetch)( + _urljoin(appUrl, `/api/apikey/login`), + { + method: "POST", + headers: { + "Content-Type": "application/json", + Authorization: `Bearer ${apiKey}`, + }, + signal: controller.signal, }, - signal: controller.signal, - }); + ); return readJSONResponse(await checkResponse(response)); })(), new Promise((_, reject) => { diff --git a/js/src/logs/console-interceptor.ts b/js/src/logs/console-interceptor.ts new file mode 100644 index 000000000..2e7fcf165 --- /dev/null +++ b/js/src/logs/console-interceptor.ts @@ -0,0 +1,55 @@ +import { + channel, + defineInterceptor, +} from "../instrumentation/core/interceptor-definitions"; + +export const consoleMethods = [ + "log", + "trace", + "debug", + "info", + "warn", + "error", +] as const; +export type ConsoleMethod = (typeof consoleMethods)[number]; +export type LogConsole = Pick; + +export const consoleHooks = defineInterceptor("console", { + write: channel< + unknown[], + void, + { registration: object; method: ConsoleMethod } + >({ channelName: "write" }), +}); + +const WRAPPED = Symbol.for("braintrust.consoleWrapped"); + +/** Install invocation hooks in place. The registration token is opaque to wrapping. */ +export function wrapConsoleMethods( + target: LogConsole, + registration: object, +): void { + for (const method of consoleMethods) { + const original = target[method]; + if (typeof original !== "function") continue; + const existing: unknown = Reflect.get(original, WRAPPED); + if ( + typeof existing === "object" && + existing !== null && + "registration" in existing + ) { + existing.registration = registration; + continue; + } + const state = { registration }; + target[method] = Object.assign( + function (...args: unknown[]) { + return consoleHooks.write.invoke(original, target, args, { + registration: state.registration, + method, + }); + }, + { [WRAPPED]: state }, + ); + } +} diff --git a/js/src/logs/context.ts b/js/src/logs/context.ts new file mode 100644 index 000000000..0c495287d --- /dev/null +++ b/js/src/logs/context.ts @@ -0,0 +1,40 @@ +import iso, { type IsoAsyncLocalStorage } from "../isomorph"; + +const LOG_CONTEXT = Symbol.for("braintrust.applicationLogContext"); +type LogContext = { store?: IsoAsyncLocalStorage; depth: number }; + +function context(): LogContext { + // Shared across SDK copies so wrappers cannot capture another copy's transport logs. + // eslint-disable-next-line @typescript-eslint/consistent-type-assertions + const global = globalThis as typeof globalThis & { + [LOG_CONTEXT]?: LogContext; + }; + const current = (global[LOG_CONTEXT] ??= { depth: 0 }); + // Bootstrap diagnostics use synchronous suppression until platform-specific + // async context storage is available. Do not cache the no-op default store. + if (!current.store && iso.buildType !== "unknown") { + current.store = iso.newAsyncLocalStorage(); + } + return current; +} + +export function isApplicationLogSuppressed(): boolean { + const current = context(); + return current.depth > 0 || current.store?.getStore() === true; +} + +export function suppressApplicationLogs(callback: () => R): R { + const current = context(); + current.depth++; + try { + return current.store ? current.store.run(true, callback) : callback(); + } finally { + current.depth--; + } +} + +export function internalFetch( + fetch: typeof globalThis.fetch, +): typeof globalThis.fetch { + return (...args) => suppressApplicationLogs(() => fetch(...args)); +} diff --git a/js/src/logs/index.ts b/js/src/logs/index.ts new file mode 100644 index 000000000..cf78c703d --- /dev/null +++ b/js/src/logs/index.ts @@ -0,0 +1,128 @@ +import { currentLogger, type Logger } from "../logger"; +import iso from "../isomorph"; +import { debugLogger } from "../debug-logger"; +import { + consoleHooks, + wrapConsoleMethods, + type ConsoleMethod, + type LogConsole, +} from "./console-interceptor"; +import { isApplicationLogSuppressed, suppressApplicationLogs } from "./context"; +import type { ApplicationLogLevel } from "./templates"; + +function display(value: unknown): string { + if (value instanceof Error) return value.stack ?? value.message; + if (typeof value === "string") return value; + return JSON.stringify(value) ?? String(value); +} + +function formatConsoleUnsafe(args: unknown[]): string { + if (iso.formatLogMessage) return iso.formatLogMessage(...args); + // Browsers expose no API for obtaining their rendered console message. Keep + // the arguments as text rather than implementing another formatting language. + // The original console still receives the untouched arguments for rendering. + return args.map(display).join(" "); +} + +function formatConsole(args: unknown[]): string { + try { + return formatConsoleUnsafe(args); + } catch { + // Console accepts circular objects and objects whose serializers throw. + return "[Unformattable console message]"; + } +} + +/** Forward one console call, keeping message extraction independent of hook registration. */ +function forwardConsoleCall( + call: () => void, + logger: Logger | undefined, + method: ConsoleMethod, + args: unknown[], +): void { + if (logger && !isApplicationLogSuppressed()) { + suppressApplicationLogs(() => { + const body = formatConsole(args); + const metadata: Record = { "logger.name": "console" }; + if (typeof args[0] === "string" && args.length > 1) { + metadata["braintrust.template"] = args[0]; + args.slice(1).forEach((value, index) => { + metadata[`braintrust.template.parameter.${index}`] = + value === null || + ["string", "number", "boolean"].includes(typeof value) + ? value + : formatConsole([value]); + }); + } + const level: ApplicationLogLevel = method === "log" ? "info" : method; + const result = logger[level](body, { metadata }); + if (result instanceof Promise) { + void result.catch((error) => + debugLogger.error("Application log flush failed:", error), + ); + } + }); + } + // Native console implementations and nested wrappers can call other console + // methods. Only the outermost wrapped call should emit an application log. + return suppressApplicationLogs(call); +} + +type WrapConsoleOptions = { + /** Destination for console logs. Defaults to the current project logger at call time. */ + logger?: Logger; +}; + +const consoleRegistrations = new WeakMap(); +let consoleForwardingEnabled = false; + +function enableConsoleForwarding(): void { + if (consoleForwardingEnabled) return; + consoleForwardingEnabled = true; + consoleHooks.write.intercept((target, receiver, args, additional) => { + const call = () => Reflect.apply(target, receiver, args); + const registration = consoleRegistrations.get(additional.registration); + if (registration === undefined) return call(); + // A disabled outer wrapper must not reactivate older wrappers that another + // console patch may still invoke. Null also releases the destination logger. + if (registration === null) return suppressApplicationLogs(call); + return forwardConsoleCall( + call, + registration.logger ?? currentLogger(), + additional.method, + args, + ); + }); +} + +/** + * Instrument future console.log/trace/debug/info/warn/error calls in place. + * log maps to info; other methods retain their severity. Existing console output + * is preserved. Repeated calls update the destination without duplicating logs. + * + * When no logger is supplied, each call uses the current project logger. Before + * a logger is initialized, calls produce their normal console output only. + * Returns an idempotent cleanup function that stops forwarding for this wrap. + * Cleanup does not disable a later wrap or flush already captured logs. + * + * @example + * const logger = initLogger({ projectName: "application-logs" }); + * const uninstrument = wrapConsole(); + * console.info("Payment %s started", "pay_123"); + * logger.info("Worker started"); + * uninstrument(); + * await logger.flush(); + */ +export function wrapConsole( + target: LogConsole = console, + options: WrapConsoleOptions = {}, +): () => void { + const registration = {}; + consoleRegistrations.set(registration, { logger: options.logger }); + enableConsoleForwarding(); + wrapConsoleMethods(target, registration); + return () => { + // Each wrap owns a distinct token, so stale cleanup cannot disable a newer wrap. + consoleRegistrations.set(registration, null); + }; +} diff --git a/js/src/logs/logs.test.ts b/js/src/logs/logs.test.ts new file mode 100644 index 000000000..7f9d31984 --- /dev/null +++ b/js/src/logs/logs.test.ts @@ -0,0 +1,627 @@ +import { afterEach, describe, expect, test, vi } from "vitest"; +import { inspect } from "node:util"; +import { + BraintrustState, + Logger, + TestBackgroundLogger, + _internalGetGlobalState, +} from "../logger"; +import { LazyValue } from "../util"; +import { wrapConsole } from "./index"; +import { consoleMethods } from "./console-interceptor"; +import { configureNode } from "../node/config"; +import iso from "../isomorph"; +import type { ExperimentEvent } from "../util"; +import { debugLogger } from "../debug-logger"; +import { isApplicationLogSuppressed, suppressApplicationLogs } from "./context"; + +configureNode(); + +async function drain( + background: TestBackgroundLogger, +): Promise { + return (await background.drain()) as ExperimentEvent[]; +} + +function setup(asyncFlush: Async) { + const state = new BraintrustState({}); + const background = new TestBackgroundLogger(); + vi.spyOn(state, "bgLogger").mockReturnValue(background); + const enqueue = vi.spyOn(background, "log"); + const logger = new Logger( + state, + new LazyValue(async () => ({ + org_id: "org", + project: { id: "project", name: "application-logs", fullInfo: {} }, + })), + { asyncFlush }, + ); + return { state, background, logger, enqueue }; +} + +function fakeConsole() { + return { + log: vi.fn(), + trace: vi.fn(), + debug: vi.fn(), + info: vi.fn(), + warn: vi.fn(), + error: vi.fn(), + }; +} + +afterEach(() => { + vi.restoreAllMocks(); +}); + +describe("application logs", () => { + test("uploads each SDK and console log once with no follow-up merge", async () => { + const rows: ExperimentEvent[] = []; + const fetch = vi.fn(async (input, init) => { + if (String(input).endsWith("/logs3")) { + rows.push(...JSON.parse(String(init?.body)).rows); + } + return Response.json({}); + }); + const state = new BraintrustState({ fetch, noExitFlush: true }); + state.apiUrl = "https://api.test"; + state.orgId = "org"; + state.httpLogger().syncFlush = true; + const logger = new Logger( + state, + new LazyValue(async () => ({ + org_id: "org", + project: { id: "project", name: "test", fullInfo: {} }, + })), + { asyncFlush: true }, + ); + const target = fakeConsole(); + const uninstrument = wrapConsole(target, { logger }); + const id = logger.info(logger.fmt`User ${"Ada"}`); + await logger.flush(); + target.warn("Retry %d", 2); + uninstrument(); + target.warn("Console output only"); + await logger.flush(); + await logger.flush(); + expect(rows).toHaveLength(2); + expect(rows[0]).toMatchObject({ + id, + output: "User Ada", + _is_merge: false, + }); + expect(rows[1]).toMatchObject({ output: "Retry 2", _is_merge: false }); + expect(rows[1].id).not.toBe(id); + for (const row of rows) { + expect(row.metrics?.end).toBe(row.metrics?.start); + expect(row.span_attributes?.type).toBe("log"); + } + }); + + test.each(["trace", "debug", "info", "warn", "error", "fatal"] as const)( + "%s enqueues exactly one complete row", + async (level) => { + const { logger, background, enqueue } = setup(true); + const timestamp = new Date("2026-01-02T03:04:05.000Z"); + vi.useFakeTimers(); + vi.setSystemTime(timestamp); + try { + const id = logger[level](logger.fmt`Worker ${3} started`, { + metadata: { worker_id: "worker-1" }, + }); + expect(enqueue).toHaveBeenCalledTimes(1); + expect(enqueue.mock.calls[0][0]).toHaveLength(1); + // Inspect the raw initial write before TestBackgroundLogger can merge updates. + const row = await enqueue.mock.calls[0][0][0].get(); + expect(row).toMatchObject({ + id, + project_id: "project", + output: "Worker 3 started", + _is_merge: false, + span_attributes: { type: "log", name: null, log_level: level }, + metadata: { + worker_id: "worker-1", + "braintrust.template": "Worker ${0} started", + "braintrust.template.parameter.0": 3, + }, + created: timestamp.toISOString(), + metrics: { + start: timestamp.getTime() / 1000, + end: timestamp.getTime() / 1000, + }, + }); + await logger.flush(); + expect(await drain(background)).toHaveLength(1); + expect(enqueue).toHaveBeenCalledTimes(1); + } finally { + vi.useRealTimers(); + } + }, + ); + + test("logs ordinary JSON bodies verbatim without interpreting template-like text", async () => { + const { logger, background } = setup(true); + const metadata = Object.freeze({ source: "app" }); + const bodies = [ + null, + true, + 42, + [1, "two"], + { event: "started" }, + "User {name} paid {amount:.2f}", + ]; + for (const body of bodies) logger.info(body, { metadata }); + const rows = await drain(background); + expect(rows.map((row) => row.output)).toEqual(bodies); + expect(rows.map((row) => row.metadata)).toEqual(bodies.map(() => metadata)); + }); + + test("fmt captures stable templates and values without emitting or mutating metadata", async () => { + const { logger, background, enqueue } = setup(true); + const metadata = Object.freeze({ + source: "checkout", + "braintrust.template": "old", + }); + const events = [ + { userId: "user_123", amount: 12.5 }, + { userId: "user_456", amount: 8 }, + ]; + for (const [index, { userId, amount }] of events.entries()) { + const formatted = logger.fmt`User ${userId} paid ${amount.toFixed(2)}`; + expect(enqueue).toHaveBeenCalledTimes(index); + logger.info(formatted, { metadata }); + } + const rows = await drain(background); + expect(rows.map((row) => row.output)).toEqual([ + "User user_123 paid 12.50", + "User user_456 paid 8.00", + ]); + for (const [index, row] of rows.entries()) { + expect(row.metadata).toEqual({ + source: "checkout", + "braintrust.template": "User ${0} paid ${1}", + "braintrust.template.parameter.0": events[index].userId, + "braintrust.template.parameter.1": events[index].amount.toFixed(2), + }); + } + expect(metadata["braintrust.template"]).toBe("old"); + }); + + test("fmt preserves cooked text, escaped placeholders, and interpolation boundaries", async () => { + const { logger, background } = setup(true); + const count = 3; + logger.info(logger.fmt`line\n\t${count * 2}\\end`); + logger.info(logger.fmt`literal \${value} and {braces} ${count}`); + logger.info(logger.fmt`${"a"}${"b"}`); + logger.info(logger.fmt`literal {braces} and no parameters`); + const rows = await drain(background); + expect( + rows.map((row) => ({ + output: row.output, + template: row.metadata?.["braintrust.template"], + })), + ).toEqual([ + { output: "line\n\t6\\end", template: "line\n\t${0}\\end" }, + { + output: "literal ${value} and {braces} 3", + template: "literal ${value} and {braces} ${0}", + }, + { output: "ab", template: "${0}${1}" }, + { + output: "literal {braces} and no parameters", + template: "literal {braces} and no parameters", + }, + ]); + }); + + test("fmt retains JSON parameter values and encodes undefined and bigint as text", async () => { + const { logger, background } = setup(true); + const values = [Object.freeze({ id: 42 }), false, null, 0, undefined, 123n]; + for (const value of values) logger.info(logger.fmt`${value}`); + const rows = await drain(background); + expect(rows.map((row) => row.output)).toEqual([ + "[object Object]", + "false", + "null", + "0", + "undefined", + "123", + ]); + expect( + rows.map((row) => row.metadata?.["braintrust.template.parameter.0"]), + ).toEqual([{ id: 42 }, false, null, 0, "undefined", "123"]); + }); + + test("fmt coerces each interpolation only once", async () => { + const { logger, background } = setup(true); + const coerce = vi.fn(() => "custom value"); + logger.info(logger.fmt`value=${{ [Symbol.toPrimitive]: coerce }}`); + expect(coerce).toHaveBeenCalledExactlyOnceWith("string"); + expect((await drain(background))[0].output).toBe("value=custom value"); + }); + + test("groups standalone messages per logger with independent row and span IDs", async () => { + const { logger, background, state } = setup(true); + logger.info("one"); + logger.warn("two"); + const other = new Logger( + state, + new LazyValue(async () => ({ + org_id: "org", + project: { id: "project", name: "test", fullInfo: {} }, + })), + { asyncFlush: true }, + ); + other.info("three"); + const [one, two, three] = await drain(background); + expect(one.id).not.toBe(two.id); + expect(one.span_id).not.toBe(two.span_id); + expect(one.root_span_id).toBe(two.root_span_id); + expect(three.root_span_id).not.toBe(one.root_span_id); + expect(one.span_parents).toEqual([]); + }); + + test("correlates SDK and console logs across awaits without modifying the active span", async () => { + const { logger, background, state } = setup(true); + const target = fakeConsole(); + const uninstrument = wrapConsole(target, { logger }); + const root = logger.startSpan({ name: "request" }); + await state.contextManager.runInContext(root, async () => { + logger.info("one"); + await Promise.resolve(); + target.error("two"); + expect(state.contextManager.getCurrentSpan()).toBe(root); + }); + root.end(); + const rows = await drain(background); + const logs = rows.filter((row) => row.span_attributes?.type === "log"); + expect(logs).toHaveLength(2); + for (const log of logs) { + expect(log.id).not.toBe(root.id); + expect(log.span_id).toBe(root.spanId); + expect(log.root_span_id).toBe(root.rootSpanId); + expect(log.span_parents).toEqual([]); + } + expect(state.contextManager.getCurrentSpan()).toBeUndefined(); + expect(rows.find((row) => row.id === root.id)?.span_attributes?.name).toBe( + "request", + ); + uninstrument(); + // Application log methods remain usable after span APIs have been used. + expect(() => logger.info("outside")).not.toThrow(); + }); + + test("uses context-manager IDs even without a native Braintrust span", async () => { + const { logger, background, state } = setup(true); + vi.spyOn(state.contextManager, "getParentSpanIds").mockReturnValue({ + rootSpanId: "otel-trace", + spanParents: ["otel-span"], + }); + logger.info("otel"); + expect((await drain(background))[0]).toMatchObject({ + root_span_id: "otel-trace", + span_id: "otel-span", + }); + }); + + test("waits for flush when asyncFlush is false", async () => { + const { logger, background, enqueue } = setup(false); + let finishFlush!: () => void; + const flush = vi.spyOn(background, "flush").mockReturnValue( + new Promise((resolve) => { + finishFlush = resolve; + }), + ); + const pending = logger.info("synchronous"); + let settled = false; + void pending.then(() => { + settled = true; + }); + await Promise.resolve(); + expect(settled).toBe(false); + finishFlush(); + const id = await pending; + expect(flush).toHaveBeenCalledTimes(1); + expect(enqueue).toHaveBeenCalledTimes(1); + expect((await drain(background))[0].id).toBe(id); + }); +}); + +describe("wrapConsole", () => { + test.each([ + ["log", "info"], + ["trace", "trace"], + ["debug", "debug"], + ["info", "info"], + ["warn", "warn"], + ["error", "error"], + ] as const)( + "maps console.%s to %s and preserves output before and after cleanup", + async (method, level) => { + const { logger, background, enqueue } = setup(true); + const target = fakeConsole(); + const original = target[method]; + const uninstrument = wrapConsole(target, { logger }); + target[method]("message"); + expect(original).toHaveBeenCalledExactlyOnceWith("message"); + expect(original.mock.contexts[0]).toBe(target); + expect(enqueue).toHaveBeenCalledTimes(1); + expect((await drain(background))[0]).toMatchObject({ + output: "message", + span_attributes: { log_level: level }, + }); + uninstrument(); + target[method]("console only"); + expect(original).toHaveBeenCalledTimes(2); + expect(original).toHaveBeenLastCalledWith("console only"); + expect(enqueue).toHaveBeenCalledTimes(1); + }, + ); + + test("wrapConsole() follows logger initialization and replacement until cleanup", async () => { + const first = setup(false); + const second = setup(false); + const state = _internalGetGlobalState(); + const previousLogger = state.currentLogger; + const methods = consoleMethods.map( + (method) => [method, console[method]] as const, + ); + const original = vi.spyOn(console, "info").mockImplementation(() => {}); + try { + state.currentLogger = undefined; + const uninstrument = wrapConsole(); + console.info("before initialization"); + expect(first.enqueue).not.toHaveBeenCalled(); + state.currentLogger = first.logger; + console.info("captured by first logger"); + state.currentLogger = second.logger; + console.info("captured by second logger"); + expect(first.enqueue).toHaveBeenCalledTimes(1); + expect(second.enqueue).toHaveBeenCalledTimes(1); + expect(original).toHaveBeenCalledTimes(3); + expect((await drain(first.background)).map((row) => row.output)).toEqual([ + "captured by first logger", + ]); + expect((await drain(second.background))[0].output).toBe( + "captured by second logger", + ); + uninstrument(); + console.info("Console output only"); + expect(original).toHaveBeenCalledTimes(4); + expect(second.enqueue).toHaveBeenCalledTimes(1); + } finally { + state.currentLogger = previousLogger; + for (const [method, original] of methods) console[method] = original; + } + }); + + test("an older cleanup cannot disable a newer wrap or resume an older destination", async () => { + const first = setup(true); + const second = setup(true); + const target = fakeConsole(); + const original = target.info; + const stopFirst = wrapConsole(target, { logger: first.logger }); + target.info("first"); + const wrapped = target.info; + const stopSecond = wrapConsole(target, { logger: second.logger }); + expect(target.info).toBe(wrapped); + stopFirst(); + stopFirst(); + target.info("second"); + stopSecond(); + stopSecond(); + target.info("console only"); + expect(original).toHaveBeenCalledTimes(3); + expect((await drain(first.background)).map((row) => row.output)).toEqual([ + "first", + ]); + expect((await drain(second.background)).map((row) => row.output)).toEqual([ + "second", + ]); + }); + + test("wrapping after cleanup re-enables forwarding without replacing the installed methods", async () => { + const { logger, background, enqueue } = setup(true); + const target = fakeConsole(); + const stopFirst = wrapConsole(target, { logger }); + const wrapped = target.info; + stopFirst(); + const stopSecond = wrapConsole(target, { logger }); + expect(target.info).toBe(wrapped); + stopFirst(); + target.info("captured again"); + stopSecond(); + target.info("console only"); + expect(enqueue).toHaveBeenCalledTimes(1); + expect((await drain(background))[0].output).toBe("captured again"); + }); + + test("cleanup affects only its console; direct logging and unrelated methods stay enabled", async () => { + const first = setup(true); + const second = setup(true); + const time = vi.fn(); + const firstConsole = { ...fakeConsole(), time }; + const secondConsole = fakeConsole(); + const stopFirst = wrapConsole(firstConsole, { logger: first.logger }); + const stopSecond = wrapConsole(secondConsole, { logger: second.logger }); + expect(firstConsole.time).toBe(time); + stopFirst(); + firstConsole.info("console only"); + secondConsole.info("other console"); + first.logger.info("direct logger call"); + stopSecond(); + expect((await drain(first.background)).map((row) => row.output)).toEqual([ + "direct logger call", + ]); + expect((await drain(second.background)).map((row) => row.output)).toEqual([ + "other console", + ]); + }); + + test("nested wrapping captures once and cleanup preserves third-party patches without reviving older capture", () => { + const first = setup(true); + const second = setup(true); + const target = fakeConsole(); + const original = target.info; + const stopFirst = wrapConsole(target, { logger: first.logger }); + const firstWrapper = target.info; + target.info = vi.fn((...args) => firstWrapper(...args)); + const stopSecond = wrapConsole(target, { logger: second.logger }); + target.info("captured once"); + expect(first.enqueue).not.toHaveBeenCalled(); + expect(second.enqueue).toHaveBeenCalledTimes(1); + const secondWrapper = target.info; + const thirdParty = vi.fn((...args) => secondWrapper(...args)); + target.info = thirdParty; + stopSecond(); + expect(target.info).toBe(thirdParty); + target.info("console only"); + expect(thirdParty).toHaveBeenCalledExactlyOnceWith("console only"); + expect(original).toHaveBeenCalledTimes(2); + expect(original).toHaveBeenLastCalledWith("console only"); + expect(first.enqueue).not.toHaveBeenCalled(); + expect(second.enqueue).toHaveBeenCalledTimes(1); + stopFirst(); + }); + + test("does not duplicate calls when native console methods call one another", () => { + const { logger, enqueue } = setup(true); + const target = fakeConsole(); + target.trace.mockImplementation((...args) => target.error(...args)); + wrapConsole(target, { logger }); + target.trace("one log"); + expect(enqueue).toHaveBeenCalledTimes(1); + }); + + test("preserves native exceptions and does not retry the console call", () => { + const { logger } = setup(true); + const target = fakeConsole(); + const error = new Error("console failure"); + const original = target.info.mockImplementation(() => { + throw error; + }); + wrapConsole(target, { logger }); + expect(() => target.info("test")).toThrow(error); + expect(original).toHaveBeenCalledTimes(1); + }); + + test("preserves console formatting, parameters, errors, and unformattable arguments", async () => { + const { logger, background } = setup(true); + const target = fakeConsole(); + wrapConsole(target, { logger }); + target.info("Payment %s attempt %d", "pay_123", 2); + target.error(new Error("payment failed")); + const circular: Record = {}; + circular.self = circular; + target.info("value %o", circular); + target.info("value %o", { + [inspect.custom]() { + throw new Error("bad inspector"); + }, + }); + const rows = await drain(background); + expect(rows).toHaveLength(4); + expect(rows[0]).toMatchObject({ + output: "Payment pay_123 attempt 2", + metadata: { + "logger.name": "console", + "braintrust.template": "Payment %s attempt %d", + "braintrust.template.parameter.0": "pay_123", + "braintrust.template.parameter.1": 2, + }, + }); + expect(rows[1].output).toContain("Error: payment failed"); + expect(rows[2].output).toContain("Circular"); + expect(rows[3].output).toBe("[Unformattable console message]"); + }); + + test("preserves console arguments as text when there is no native formatter", async () => { + const { logger, background } = setup(true); + const target = fakeConsole(); + wrapConsole(target, { logger }); + const format = iso.formatLogMessage; + iso.formatLogMessage = undefined; + try { + target.info("Payment %s %d %%", "pay_123", 2, { attempt: 1 }); + } finally { + iso.formatLogMessage = format; + } + expect((await drain(background))[0].output).toBe( + 'Payment %s %d %% pay_123 2 {"attempt":1}', + ); + }); + + test("SDK diagnostics are printed without becoming application logs", () => { + const { logger, enqueue } = setup(true); + const sdkState = _internalGetGlobalState(); + vi.spyOn(sdkState, "getDebugLogLevel").mockReturnValue("warn"); + vi.spyOn(sdkState, "hasDebugLogLevelOverride").mockReturnValue(true); + const methods = consoleMethods.map( + (method) => [method, console[method]] as const, + ); + const original = vi.spyOn(console, "warn").mockImplementation(() => {}); + const uninstrument = wrapConsole(console, { logger }); + try { + debugLogger.warn("SDK warning"); + expect(debugLogger.notice.warn("SDK notice")).toBe(true); + expect(original).toHaveBeenCalledTimes(2); + expect(original).toHaveBeenCalledWith("[braintrust]", "SDK warning"); + expect(original).toHaveBeenCalledWith("[braintrust]", "SDK notice"); + expect(enqueue).not.toHaveBeenCalled(); + console.warn("application log"); + expect(enqueue).toHaveBeenCalledTimes(1); + } finally { + uninstrument(); + for (const [method, original] of methods) console[method] = original; + } + }); + + test("bootstrap diagnostics do not prevent async suppression after platform initialization", async () => { + const key = Symbol.for("braintrust.applicationLogContext"); + const previousContext = Object.getOwnPropertyDescriptor(globalThis, key); + const previousBuildType = iso.buildType; + Reflect.deleteProperty(globalThis, key); + try { + iso.buildType = "unknown"; + suppressApplicationLogs(() => + expect(isApplicationLogSuppressed()).toBe(true), + ); + expect(isApplicationLogSuppressed()).toBe(false); + iso.buildType = previousBuildType; + await suppressApplicationLogs(async () => { + await Promise.resolve(); + expect(isApplicationLogSuppressed()).toBe(true); + }); + expect(isApplicationLogSuppressed()).toBe(false); + } finally { + iso.buildType = previousBuildType; + if (previousContext) + Object.defineProperty(globalThis, key, previousContext); + else Reflect.deleteProperty(globalThis, key); + } + }); + + test("ignores console logs inside SDK HTTP transport across awaits but captures concurrent application logs", async () => { + const { logger, background, state } = setup(true); + const target = fakeConsole(); + wrapConsole(target, { logger }); + let release!: () => void; + const pending = new Promise((resolve) => { + release = resolve; + }); + state.setFetch(async () => { + target.debug("transport start"); + await pending; + target.debug("transport end"); + return new Response("{}", { status: 200 }); + }); + state.apiUrl = "https://example.com"; + const response = state.apiConn().post("logs3", {}); + target.info("application"); + release(); + await response; + const rows = await drain(background); + expect(rows).toHaveLength(1); + expect(rows[0].output).toBe("application"); + }); +}); diff --git a/js/src/logs/templates.ts b/js/src/logs/templates.ts new file mode 100644 index 000000000..3e53fc5be --- /dev/null +++ b/js/src/logs/templates.ts @@ -0,0 +1,59 @@ +export type ApplicationLogOptions = { + metadata?: Record; +}; + +const LOG_TEMPLATE = Symbol.for("braintrust.logTemplate"); + +export type ApplicationLogTemplate = { + readonly [LOG_TEMPLATE]: true; + readonly body: string; + readonly metadata: Record; +}; + +/** Use JavaScript's native interpolation on the cooked template segments. */ +export function formatLogTemplate( + strings: TemplateStringsArray, + values: readonly unknown[], +): ApplicationLogTemplate { + const placeholders = values.map((_, index) => `\${${index}}`); + return { + [LOG_TEMPLATE]: true, + body: String.raw({ raw: strings }, ...values), + metadata: { + "braintrust.template": String.raw({ raw: strings }, ...placeholders), + ...Object.fromEntries( + values.map((value, index) => [ + `braintrust.template.parameter.${index}`, + // Retain primitives that JSON cannot represent using their native text. + value === undefined || typeof value === "bigint" + ? String(value) + : value, + ]), + ), + }, + }; +} + +function isLogTemplate(body: unknown): body is ApplicationLogTemplate { + return ( + typeof body === "object" && + body !== null && + Object.getOwnPropertyDescriptor(body, LOG_TEMPLATE)?.value === true + ); +} + +export function renderLogBody(body: unknown, options?: ApplicationLogOptions) { + if (!isLogTemplate(body)) return { body, metadata: options?.metadata }; + return { + body: body.body, + metadata: { ...options?.metadata, ...body.metadata }, + }; +} + +export type ApplicationLogLevel = + | "trace" + | "debug" + | "info" + | "warn" + | "error" + | "fatal"; diff --git a/js/src/node/config.ts b/js/src/node/config.ts index 6b3f37802..e8a95acaf 100644 --- a/js/src/node/config.ts +++ b/js/src/node/config.ts @@ -4,7 +4,7 @@ import * as fs from "node:fs/promises"; import * as os from "node:os"; import * as fsSync from "node:fs"; import * as crypto from "node:crypto"; -import { promisify } from "node:util"; +import { format, promisify } from "node:util"; import * as zlib from "node:zlib"; import * as dotenv from "dotenv"; @@ -108,6 +108,7 @@ export function configureNode() { return undefined; }; iso.getCallerLocation = getCallerLocation; + iso.formatLogMessage = format; iso.newAsyncLocalStorage = () => new AsyncLocalStorage(); iso.processOn = (event: string, handler: (code: unknown) => void) => { process.on(event, handler); diff --git a/js/src/reporters/progress.ts b/js/src/reporters/progress.ts index d1a8e5303..5d4ec3f3c 100644 --- a/js/src/reporters/progress.ts +++ b/js/src/reporters/progress.ts @@ -1,9 +1,12 @@ +import { suppressApplicationLogs } from "../logs/context"; import type { ProgressReporter } from "./types"; export class SimpleProgressReporter implements ProgressReporter { public start(name: string, _total: number) { - // eslint-disable-next-line no-restricted-properties -- preserving intentional console usage. - console.log(`Running evaluator ${name}`); + suppressApplicationLogs(() => { + // eslint-disable-next-line no-restricted-properties -- user-facing progress output is independent of SDK diagnostics. + console.log(`Running evaluator ${name}`); + }); } public stop() {} public increment(_name: string) {} diff --git a/js/src/wrappers/shared/flush.ts b/js/src/wrappers/shared/flush.ts index ab5e89028..a044806c4 100644 --- a/js/src/wrappers/shared/flush.ts +++ b/js/src/wrappers/shared/flush.ts @@ -1,3 +1,4 @@ +import { suppressApplicationLogs } from "../../logs/context"; import type { Experiment } from "../../logger"; import { formatExperimentSummary } from "./format"; @@ -17,6 +18,8 @@ export async function summarizeAndFlush( } const summary = await experiment.summarize(); - // eslint-disable-next-line no-restricted-properties -- preserving intentional console usage. - console.log(formatExperimentSummary(summary)); + suppressApplicationLogs(() => { + // eslint-disable-next-line no-restricted-properties -- user-requested summary output is independent of SDK diagnostics. + console.log(formatExperimentSummary(summary)); + }); } From 7cf7a4322269bc59636560388f9084a3e6daa637 Mon Sep 17 00:00:00 2001 From: Abhijeet Prasad Date: Mon, 19 Oct 2026 14:22:31 -0700 Subject: [PATCH 2/6] fix(logs): defer baseline trace ids until first standalone log Honor late OpenTelemetry setup when choosing the baseline trace ID, and add a minor changeset for application logging and console capture. --- .changeset/application-logging.md | 11 +++++++++++ js/src/logger.ts | 9 ++++++--- js/src/logs/logs.test.ts | 33 +++++++++++++++++++++++++++++++ 3 files changed, 50 insertions(+), 3 deletions(-) create mode 100644 .changeset/application-logging.md diff --git a/.changeset/application-logging.md b/.changeset/application-logging.md new file mode 100644 index 000000000..275b045f3 --- /dev/null +++ b/.changeset/application-logging.md @@ -0,0 +1,11 @@ +--- +"braintrust": minor +--- + +feat(logs): add application logging and console capture + +Record application messages with `logger.trace()`, `debug()`, `info()`, `warn()`, +`error()`, and `fatal()`. Preserve native JavaScript message templates with +`logger.fmt` and capture future console calls with `wrapConsole()`, which returns +a cleanup function. Logs share the active span's context and upload as a single +complete event. diff --git a/js/src/logger.ts b/js/src/logger.ts index 64079f1af..84d5cf9d7 100644 --- a/js/src/logger.ts +++ b/js/src/logger.ts @@ -2908,7 +2908,7 @@ export class Logger implements Exportable { private lastStartTime: number; private lazyId: LazyValue; private calledStartSpan: boolean; - private readonly baselineTraceId: string; + private baselineTraceId?: string; // For type identification. public kind = "logger" as const; @@ -2926,7 +2926,6 @@ export class Logger implements Exportable { this.lazyId = new LazyValue(async () => await this.id); this.calledStartSpan = false; this.state = state; - this.baselineTraceId = state.idGenerator.getTraceId(); } public get org_id(): Promise { @@ -3014,7 +3013,11 @@ export class Logger implements Exportable { parentObjectId: this.lazyId, parentComputeObjectMetadataArgs: this.computeMetadataArgs, parentSpanIds: { - rootSpanId: current?.rootSpanId ?? this.baselineTraceId, + // Late OpenTelemetry setup can replace the ID generator. Resolve the + // baseline only when a standalone log first needs it. + rootSpanId: + current?.rootSpanId ?? + (this.baselineTraceId ??= this.state.idGenerator.getTraceId()), parentSpanIds: [], }, spanId: current?.spanParents[0], diff --git a/js/src/logs/logs.test.ts b/js/src/logs/logs.test.ts index 7f9d31984..56e87643e 100644 --- a/js/src/logs/logs.test.ts +++ b/js/src/logs/logs.test.ts @@ -13,6 +13,7 @@ import { configureNode } from "../node/config"; import iso from "../isomorph"; import type { ExperimentEvent } from "../util"; import { debugLogger } from "../debug-logger"; +import { OTELIDGenerator } from "../id-gen"; import { isApplicationLogSuppressed, suppressApplicationLogs } from "./context"; configureNode(); @@ -261,6 +262,38 @@ describe("application logs", () => { expect(one.span_parents).toEqual([]); }); + test("uses the current ID generator for the first standalone log after late OpenTelemetry setup", async () => { + vi.stubEnv("BRAINTRUST_LEGACY_IDS", "true"); + vi.stubEnv("BRAINTRUST_OTEL_COMPAT", undefined); + vi.stubGlobal("BRAINTRUST_ID_GENERATOR", undefined); + try { + const { logger, background, state } = setup(true); + const root = logger.startSpan({ name: "before-otel" }); + state.contextManager.runInContext(root, () => logger.info("inside span")); + root.end(); + expect(root.rootSpanId).toContain("-"); + + // Match setupOtelCompat(): install the hex generator and reset the cache. + vi.stubGlobal("BRAINTRUST_ID_GENERATOR", OTELIDGenerator); + state.resetIdGenState(); + logger.info("first standalone log"); + logger.warn("second standalone log"); + + const logs = (await drain(background)).filter( + (row) => row.span_attributes?.type === "log", + ); + expect(logs).toHaveLength(3); + expect(logs[0].root_span_id).toBe(root.rootSpanId); + expect(logs[1].root_span_id).toMatch(/^[0-9a-f]{32}$/); + expect(logs[1].span_id).toMatch(/^[0-9a-f]{16}$/); + expect(logs[2].root_span_id).toBe(logs[1].root_span_id); + expect(logs[2].span_id).toMatch(/^[0-9a-f]{16}$/); + } finally { + vi.unstubAllGlobals(); + vi.unstubAllEnvs(); + } + }); + test("correlates SDK and console logs across awaits without modifying the active span", async () => { const { logger, background, state } = setup(true); const target = fakeConsole(); From f5fbd228be5d36b2fba474b076049b0d57b2d296 Mon Sep 17 00:00:00 2001 From: Abhijeet Prasad Date: Mon, 19 Oct 2026 14:44:47 -0700 Subject: [PATCH 3/6] ref(logs): use saved console methods for sdk output Save console methods before instrumentation and share the original references across SDK copies. Route SDK diagnostics and evaluation output through those references so they stay visible without being captured as application logs. Remove async suppression and fetch wrappers. Keep a synchronous reentrancy guard so nested console calls emit a single log and cleanup preserves later wraps. Console calls from custom transports follow normal application logging behavior. --- js/src/debug-logger.ts | 27 +-- js/src/framework.ts | 249 +++++++++++------------ js/src/isomorph.ts | 5 +- js/src/logger.ts | 41 ++-- js/src/logs/console-interceptor.ts | 18 +- js/src/logs/console.ts | 68 +++++++ js/src/logs/context.ts | 40 ---- js/src/logs/index.ts | 75 ++++--- js/src/logs/logs.test.ts | 309 ++++++++++++----------------- js/src/reporters/progress.ts | 7 +- js/src/wrappers/shared/flush.ts | 7 +- 11 files changed, 383 insertions(+), 463 deletions(-) create mode 100644 js/src/logs/console.ts delete mode 100644 js/src/logs/context.ts diff --git a/js/src/debug-logger.ts b/js/src/debug-logger.ts index 3e874bf59..8fa3a0c49 100644 --- a/js/src/debug-logger.ts +++ b/js/src/debug-logger.ts @@ -1,5 +1,5 @@ import iso from "./isomorph"; -import { suppressApplicationLogs } from "./logs/context"; +import { sdkConsole } from "./logs/console"; import { setGlobalHookErrorReporter } from "./global-instrumentation-hooks"; export type DebugLogLevel = "error" | "warn" | "info" | "debug"; @@ -46,12 +46,9 @@ function warnInvalidEnvValue(value: string) { return; } hasWarnedAboutInvalidEnvValue = true; - suppressApplicationLogs(() => - // eslint-disable-next-line no-restricted-properties -- preserving intentional console usage. - console.warn( - PREFIX, - `Invalid BRAINTRUST_DEBUG_LOG_LEVEL value "${value}". Expected "error", "warn", "info", or "debug".`, - ), + sdkConsole.warn( + PREFIX, + `Invalid BRAINTRUST_DEBUG_LOG_LEVEL value "${value}". Expected "error", "warn", "info", or "debug".`, ); } @@ -158,21 +155,7 @@ function emit( return false; } - suppressApplicationLogs(() => { - if (method === "info") { - // eslint-disable-next-line no-restricted-properties -- preserving intentional console usage. - console.log(PREFIX, ...args); - } else if (method === "debug") { - // eslint-disable-next-line no-restricted-properties -- preserving intentional console usage. - console.debug(PREFIX, ...args); - } else if (method === "warn") { - // eslint-disable-next-line no-restricted-properties -- preserving intentional console usage. - console.warn(PREFIX, ...args); - } else { - // eslint-disable-next-line no-restricted-properties -- preserving intentional console usage. - console.error(PREFIX, ...args); - } - }); + sdkConsole[method === "info" ? "log" : method](PREFIX, ...args); return true; } diff --git a/js/src/framework.ts b/js/src/framework.ts index 698858409..a56f0d693 100644 --- a/js/src/framework.ts +++ b/js/src/framework.ts @@ -1,3 +1,4 @@ +import { sdkConsole } from "./logs/console"; import { makeScorerPropagatedEvent, Classification, @@ -20,7 +21,6 @@ import { v5 as uuidv5 } from "uuid"; import iso from "./isomorph"; import { debugLogger } from "./debug-logger"; -import { suppressApplicationLogs } from "./logs/context"; import { GenericFunction } from "./framework-types"; import { CodeFunction, CodePrompt, CodeParameters } from "./framework2"; import { Trace, LocalTrace } from "./trace"; @@ -894,11 +894,9 @@ export async function Eval< return ret; } finally { if (experiment) { - // eslint-disable-next-line no-restricted-properties -- preserving intentional console usage. - await experiment.flush().catch(console.error); + await experiment.flush().catch(sdkConsole.error); } else if (options.parent) { - // eslint-disable-next-line no-restricted-properties -- preserving intentional console usage. - await flush({ state: evaluator.state }).catch(console.error); + await flush({ state: evaluator.state }).catch(sdkConsole.error); } } } finally { @@ -1787,15 +1785,11 @@ export const error = (text: string) => `Error: ${text}`; export const warning = (text: string) => `Warning: ${text}`; export function logError(e: unknown, verbose: boolean) { - suppressApplicationLogs(() => { - if (!verbose) { - // eslint-disable-next-line no-restricted-properties -- user-facing evaluation error output is independent of SDK diagnostics. - console.error(`${e}`); - } else { - // eslint-disable-next-line no-restricted-properties -- user-facing evaluation error output is independent of SDK diagnostics. - console.error(e); - } - }); + if (!verbose) { + sdkConsole.error(`${e}`); + } else { + sdkConsole.error(e); + } } type ScoreAccumulator = { @@ -1868,42 +1862,37 @@ export function reportFailures< failingResults: EvalResult[], { verbose, jsonl }: ReporterOpts, ) { - suppressApplicationLogs(() => { - if (failingResults.length > 0) { - // TODO: We may want to support a non-strict mode (and make this the "strict" behavior), so that - // users can still log imperfect evaluations. In the meantime, they should handle these cases inside - // of their tasks. - // eslint-disable-next-line no-restricted-properties -- user-facing evaluation report output is independent of SDK diagnostics. - console.error( + if (failingResults.length > 0) { + // TODO: We may want to support a non-strict mode (and make this the "strict" behavior), so that + // users can still log imperfect evaluations. In the meantime, they should handle these cases inside + // of their tasks. + sdkConsole.error( + warning( + `Evaluator ${evaluator.evalName} failed with ${failingResults.length} error${failingResults.length === 1 ? "" : "s"}. This evaluation ("${evaluator.evalName}") will not be fully logged.`, + ), + ); + if (jsonl) { + sdkConsole.log( + JSON.stringify({ + evaluatorName: evaluator.evalName, + errors: failingResults.map( + (r) => `${r.error instanceof Error ? r.error.stack : r.error}`, + ), + }), + ); + } else { + for (const result of failingResults) { + logError(result.error, verbose); + } + } + if (!verbose && !jsonl) { + sdkConsole.error( warning( - `Evaluator ${evaluator.evalName} failed with ${failingResults.length} error${failingResults.length === 1 ? "" : "s"}. This evaluation ("${evaluator.evalName}") will not be fully logged.`, + "Use --debug-logging debug to see full stack traces and troubleshooting details.", ), ); - if (jsonl) { - // eslint-disable-next-line no-restricted-properties -- user-facing evaluation report output is independent of SDK diagnostics. - console.log( - JSON.stringify({ - evaluatorName: evaluator.evalName, - errors: failingResults.map( - (r) => `${r.error instanceof Error ? r.error.stack : r.error}`, - ), - }), - ); - } else { - for (const result of failingResults) { - logError(result.error, verbose); - } - } - if (!verbose && !jsonl) { - // eslint-disable-next-line no-restricted-properties -- user-facing evaluation report output is independent of SDK diagnostics. - console.error( - warning( - "Use --debug-logging debug to see full stack traces and troubleshooting details.", - ), - ); - } } - }); + } } /** @@ -1923,114 +1912,110 @@ const defaultReporter: ReporterDef = { result: EvalResultWithSummary, { verbose, jsonl }: ReporterOpts, ) { - return suppressApplicationLogs(() => { - const { results, summary } = result; - const failingResults = results.filter( - (r: { error: unknown }) => r.error !== undefined, - ); + const { results, summary } = result; + const failingResults = results.filter( + (r: { error: unknown }) => r.error !== undefined, + ); + + if (failingResults.length > 0) { + reportFailures(evaluator, failingResults, { verbose, jsonl }); + } + + if (jsonl) { + iso.writeln(JSON.stringify(summary)); + } else { + // Simple plain-text output without fancy formatting + iso.writeln("Experiment summary"); + iso.writeln("=================="); - if (failingResults.length > 0) { - reportFailures(evaluator, failingResults, { verbose, jsonl }); + if (summary.comparisonExperimentName) { + iso.writeln( + `${summary.comparisonExperimentName} (baseline) <- ${summary.experimentName} (comparison)`, + ); + iso.writeln(""); } - if (jsonl) { - iso.writeln(JSON.stringify(summary)); - } else { - // Simple plain-text output without fancy formatting - iso.writeln("Experiment summary"); - iso.writeln("=================="); + const hasScores = Object.keys(summary.scores).length > 0; + const hasMetrics = Object.keys(summary.metrics ?? {}).length > 0; + const hasComparison = !!summary.comparisonExperimentName; - if (summary.comparisonExperimentName) { + if (hasScores || hasMetrics) { + if (hasComparison) { iso.writeln( - `${summary.comparisonExperimentName} (baseline) <- ${summary.experimentName} (comparison)`, + "Name Value Change Improvements Regressions", + ); + iso.writeln( + "----------------------------------------------------------------", ); - iso.writeln(""); } - const hasScores = Object.keys(summary.scores).length > 0; - const hasMetrics = Object.keys(summary.metrics ?? {}).length > 0; - const hasComparison = !!summary.comparisonExperimentName; + // Scores + for (const score of Object.values(summary.scores)) { + const scorePercent = (score.score * 100).toFixed(2); + const scoreValue = `${scorePercent}%`; - if (hasScores || hasMetrics) { if (hasComparison) { + let diffString = "-"; + if (!isEmpty(score.diff)) { + const diffPercent = (score.diff! * 100).toFixed(2); + const diffSign = score.diff! > 0 ? "+" : ""; + diffString = `${diffSign}${diffPercent}%`; + } + + const improvements = + score.improvements > 0 ? score.improvements.toString() : "-"; + const regressions = + score.regressions > 0 ? score.regressions.toString() : "-"; + iso.writeln( - "Name Value Change Improvements Regressions", - ); - iso.writeln( - "----------------------------------------------------------------", + `${score.name.padEnd(18)} ${scoreValue.padStart(10)} ${diffString.padStart(10)} ${improvements.padStart(12)} ${regressions.padStart(11)}`, ); + } else { + iso.writeln(`${score.name.padEnd(20)} ${scoreValue.padStart(15)}`); } + } - // Scores - for (const score of Object.values(summary.scores)) { - const scorePercent = (score.score * 100).toFixed(2); - const scoreValue = `${scorePercent}%`; - - if (hasComparison) { - let diffString = "-"; - if (!isEmpty(score.diff)) { - const diffPercent = (score.diff! * 100).toFixed(2); - const diffSign = score.diff! > 0 ? "+" : ""; - diffString = `${diffSign}${diffPercent}%`; - } - - const improvements = - score.improvements > 0 ? score.improvements.toString() : "-"; - const regressions = - score.regressions > 0 ? score.regressions.toString() : "-"; + // Metrics + for (const metric of Object.values(summary.metrics ?? {})) { + const fractionDigits = Number.isInteger(metric.metric) ? 0 : 2; + const formattedValue = metric.metric.toFixed(fractionDigits); + const metricValue = + metric.unit === "$" + ? `${metric.unit}${formattedValue}` + : `${formattedValue}${metric.unit}`; - iso.writeln( - `${score.name.padEnd(18)} ${scoreValue.padStart(10)} ${diffString.padStart(10)} ${improvements.padStart(12)} ${regressions.padStart(11)}`, - ); - } else { - iso.writeln( - `${score.name.padEnd(20)} ${scoreValue.padStart(15)}`, - ); + if (hasComparison) { + let diffString = "-"; + if (!isEmpty(metric.diff)) { + const diffPercent = (metric.diff! * 100).toFixed(2); + const diffSign = metric.diff! > 0 ? "+" : ""; + diffString = `${diffSign}${diffPercent}%`; } - } - - // Metrics - for (const metric of Object.values(summary.metrics ?? {})) { - const fractionDigits = Number.isInteger(metric.metric) ? 0 : 2; - const formattedValue = metric.metric.toFixed(fractionDigits); - const metricValue = - metric.unit === "$" - ? `${metric.unit}${formattedValue}` - : `${formattedValue}${metric.unit}`; - - if (hasComparison) { - let diffString = "-"; - if (!isEmpty(metric.diff)) { - const diffPercent = (metric.diff! * 100).toFixed(2); - const diffSign = metric.diff! > 0 ? "+" : ""; - diffString = `${diffSign}${diffPercent}%`; - } - const improvements = - metric.improvements > 0 ? metric.improvements.toString() : "-"; - const regressions = - metric.regressions > 0 ? metric.regressions.toString() : "-"; + const improvements = + metric.improvements > 0 ? metric.improvements.toString() : "-"; + const regressions = + metric.regressions > 0 ? metric.regressions.toString() : "-"; - iso.writeln( - `${metric.name.padEnd(18)} ${metricValue.padStart(10)} ${diffString.padStart(10)} ${improvements.padStart(12)} ${regressions.padStart(11)}`, - ); - } else { - iso.writeln( - `${metric.name.padEnd(20)} ${metricValue.padStart(15)}`, - ); - } + iso.writeln( + `${metric.name.padEnd(18)} ${metricValue.padStart(10)} ${diffString.padStart(10)} ${improvements.padStart(12)} ${regressions.padStart(11)}`, + ); + } else { + iso.writeln( + `${metric.name.padEnd(20)} ${metricValue.padStart(15)}`, + ); } } + } - if (summary.experimentUrl) { - iso.writeln(""); - iso.writeln(`View results for ${summary.experimentName}`); - iso.writeln(`See results at ${summary.experimentUrl}`); - } + if (summary.experimentUrl) { + iso.writeln(""); + iso.writeln(`View results for ${summary.experimentName}`); + iso.writeln(`See results at ${summary.experimentUrl}`); } - iso.writeln(""); - return failingResults.length === 0; - }); + } + iso.writeln(""); + return failingResults.length === 0; }, async reportRun(evalReports: boolean[]) { return evalReports.every((r) => r); diff --git a/js/src/isomorph.ts b/js/src/isomorph.ts index ea49549ce..0b6cdcde8 100644 --- a/js/src/isomorph.ts +++ b/js/src/isomorph.ts @@ -1,3 +1,5 @@ +import { sdkConsole } from "./logs/console"; + import { type GitMetadataSettingsType as GitMetadataSettings, type RepoInfoType as RepoInfo, @@ -103,7 +105,6 @@ const iso: Common = { processOn: (_0, _1) => {}, basename: (filepath: string) => filepath.split(/[\\/]/).pop() || filepath, - // eslint-disable-next-line no-restricted-properties -- preserving intentional console usage. - writeln: (text: string) => console.log(text), + writeln: (text: string) => sdkConsole.log(text), }; export default iso; diff --git a/js/src/logger.ts b/js/src/logger.ts index 84d5cf9d7..afe0c8d24 100644 --- a/js/src/logger.ts +++ b/js/src/logger.ts @@ -1,7 +1,6 @@ /// import { DecisionAttachmentProcessor } from "./decision-attachments"; -import { internalFetch } from "./logs/context"; import { formatLogTemplate, renderLogBody, @@ -1639,11 +1638,11 @@ class HTTPConnection { this.headers = {}; this._reset(); - this.fetch = internalFetch(fetch); + this.fetch = fetch; } public setFetch(fetch: typeof globalThis.fetch) { - this.fetch = internalFetch(fetch); + this.fetch = fetch; } async ping() { @@ -2066,7 +2065,7 @@ export class Attachment extends BaseAttachment { try { objectStoreResponse = await withRetry(async () => checkResponse( - await internalFetch(fetch)(signedUrl, { + await fetch(signedUrl, { method: "PUT" satisfies RequestInit["method"], headers, body: data, @@ -2341,7 +2340,7 @@ export class ReadonlyAttachment { ); } - const objResponse = await internalFetch(fetch)(downloadUrl); + const objResponse = await fetch(downloadUrl); if (objResponse.status !== 200) { const error = await objResponse.text(); throw new Error(`Couldn't download attachment: ${error}`); @@ -6076,16 +6075,13 @@ async function loginToLoaderRequestState({ } else { let loginResponse: Response; try { - loginResponse = await internalFetch(fetch)( - _urljoin(appUrl, `/api/apikey/login`), - { - method: "POST", - headers: { - "Content-Type": "application/json", - Authorization: `Bearer ${apiKey}`, - }, + loginResponse = await fetch(_urljoin(appUrl, `/api/apikey/login`), { + method: "POST", + headers: { + "Content-Type": "application/json", + Authorization: `Bearer ${apiKey}`, }, - ); + }); } catch (error) { throw new HTTPTransportError(error); } @@ -6162,17 +6158,14 @@ export async function loginToState(options: LoginOptions = {}) { // cancellation, so a stalled request cannot block subsequent logins. info = await Promise.race([ (async () => { - const response = await internalFetch(fetch)( - _urljoin(appUrl, `/api/apikey/login`), - { - method: "POST", - headers: { - "Content-Type": "application/json", - Authorization: `Bearer ${apiKey}`, - }, - signal: controller.signal, + const response = await fetch(_urljoin(appUrl, `/api/apikey/login`), { + method: "POST", + headers: { + "Content-Type": "application/json", + Authorization: `Bearer ${apiKey}`, }, - ); + signal: controller.signal, + }); return readJSONResponse(await checkResponse(response)); })(), new Promise((_, reject) => { diff --git a/js/src/logs/console-interceptor.ts b/js/src/logs/console-interceptor.ts index 2e7fcf165..9be9660a0 100644 --- a/js/src/logs/console-interceptor.ts +++ b/js/src/logs/console-interceptor.ts @@ -2,17 +2,12 @@ import { channel, defineInterceptor, } from "../instrumentation/core/interceptor-definitions"; - -export const consoleMethods = [ - "log", - "trace", - "debug", - "info", - "warn", - "error", -] as const; -export type ConsoleMethod = (typeof consoleMethods)[number]; -export type LogConsole = Pick; +import { + consoleMethods, + saveConsoleMethods, + type ConsoleMethod, + type LogConsole, +} from "./console"; export const consoleHooks = defineInterceptor("console", { write: channel< @@ -29,6 +24,7 @@ export function wrapConsoleMethods( target: LogConsole, registration: object, ): void { + saveConsoleMethods(target); for (const method of consoleMethods) { const original = target[method]; if (typeof original !== "function") continue; diff --git a/js/src/logs/console.ts b/js/src/logs/console.ts new file mode 100644 index 000000000..c5e564da0 --- /dev/null +++ b/js/src/logs/console.ts @@ -0,0 +1,68 @@ +export const consoleMethods = [ + "log", + "trace", + "debug", + "info", + "warn", + "error", +] as const; +export type ConsoleMethod = (typeof consoleMethods)[number]; +export type LogConsole = Pick; + +const CONSOLE_STATE = Symbol.for("braintrust.consoleState"); +type ConsoleState = { + originals: WeakMap; + inConsoleCall: boolean; +}; + +function state(): ConsoleState { + // Share originals and the synchronous reentrancy guard across SDK copies. + // eslint-disable-next-line @typescript-eslint/consistent-type-assertions + const global = globalThis as typeof globalThis & { + [CONSOLE_STATE]?: ConsoleState; + }; + return (global[CONSOLE_STATE] ??= { + originals: new WeakMap(), + inConsoleCall: false, + }); +} + +export function saveConsoleMethods(target: LogConsole): void { + const { originals } = state(); + if (originals.has(target)) return; + originals.set(target, { + log: target.log, + trace: target.trace, + debug: target.debug, + info: target.info, + warn: target.warn, + error: target.error, + }); +} + +/** Only the outermost synchronous console call should be captured. */ +export function runConsoleCall(callback: (nested: boolean) => R): R { + const current = state(); + const nested = current.inConsoleCall; + current.inConsoleCall = true; + try { + return callback(nested); + } finally { + current.inConsoleCall = nested; + } +} + +function writeOriginal(method: ConsoleMethod, args: unknown[]): void { + const original = (state().originals.get(console) ?? console)[method]; + runConsoleCall(() => Reflect.apply(original, console, args)); +} + +/** SDK-owned output bypasses Braintrust's console wrappers. */ +export const sdkConsole: LogConsole = { + log: (...args) => writeOriginal("log", args), + trace: (...args) => writeOriginal("trace", args), + debug: (...args) => writeOriginal("debug", args), + info: (...args) => writeOriginal("info", args), + warn: (...args) => writeOriginal("warn", args), + error: (...args) => writeOriginal("error", args), +}; diff --git a/js/src/logs/context.ts b/js/src/logs/context.ts deleted file mode 100644 index 0c495287d..000000000 --- a/js/src/logs/context.ts +++ /dev/null @@ -1,40 +0,0 @@ -import iso, { type IsoAsyncLocalStorage } from "../isomorph"; - -const LOG_CONTEXT = Symbol.for("braintrust.applicationLogContext"); -type LogContext = { store?: IsoAsyncLocalStorage; depth: number }; - -function context(): LogContext { - // Shared across SDK copies so wrappers cannot capture another copy's transport logs. - // eslint-disable-next-line @typescript-eslint/consistent-type-assertions - const global = globalThis as typeof globalThis & { - [LOG_CONTEXT]?: LogContext; - }; - const current = (global[LOG_CONTEXT] ??= { depth: 0 }); - // Bootstrap diagnostics use synchronous suppression until platform-specific - // async context storage is available. Do not cache the no-op default store. - if (!current.store && iso.buildType !== "unknown") { - current.store = iso.newAsyncLocalStorage(); - } - return current; -} - -export function isApplicationLogSuppressed(): boolean { - const current = context(); - return current.depth > 0 || current.store?.getStore() === true; -} - -export function suppressApplicationLogs(callback: () => R): R { - const current = context(); - current.depth++; - try { - return current.store ? current.store.run(true, callback) : callback(); - } finally { - current.depth--; - } -} - -export function internalFetch( - fetch: typeof globalThis.fetch, -): typeof globalThis.fetch { - return (...args) => suppressApplicationLogs(() => fetch(...args)); -} diff --git a/js/src/logs/index.ts b/js/src/logs/index.ts index cf78c703d..9e0c56e4d 100644 --- a/js/src/logs/index.ts +++ b/js/src/logs/index.ts @@ -1,13 +1,8 @@ import { currentLogger, type Logger } from "../logger"; import iso from "../isomorph"; import { debugLogger } from "../debug-logger"; -import { - consoleHooks, - wrapConsoleMethods, - type ConsoleMethod, - type LogConsole, -} from "./console-interceptor"; -import { isApplicationLogSuppressed, suppressApplicationLogs } from "./context"; +import { consoleHooks, wrapConsoleMethods } from "./console-interceptor"; +import { runConsoleCall, type ConsoleMethod, type LogConsole } from "./console"; import type { ApplicationLogLevel } from "./templates"; function display(value: unknown): string { @@ -40,32 +35,28 @@ function forwardConsoleCall( method: ConsoleMethod, args: unknown[], ): void { - if (logger && !isApplicationLogSuppressed()) { - suppressApplicationLogs(() => { - const body = formatConsole(args); - const metadata: Record = { "logger.name": "console" }; - if (typeof args[0] === "string" && args.length > 1) { - metadata["braintrust.template"] = args[0]; - args.slice(1).forEach((value, index) => { - metadata[`braintrust.template.parameter.${index}`] = - value === null || - ["string", "number", "boolean"].includes(typeof value) - ? value - : formatConsole([value]); - }); - } - const level: ApplicationLogLevel = method === "log" ? "info" : method; - const result = logger[level](body, { metadata }); - if (result instanceof Promise) { - void result.catch((error) => - debugLogger.error("Application log flush failed:", error), - ); - } - }); + if (logger) { + const body = formatConsole(args); + const metadata: Record = { "logger.name": "console" }; + if (typeof args[0] === "string" && args.length > 1) { + metadata["braintrust.template"] = args[0]; + args.slice(1).forEach((value, index) => { + metadata[`braintrust.template.parameter.${index}`] = + value === null || + ["string", "number", "boolean"].includes(typeof value) + ? value + : formatConsole([value]); + }); + } + const level: ApplicationLogLevel = method === "log" ? "info" : method; + const result = logger[level](body, { metadata }); + if (result instanceof Promise) { + void result.catch((error) => + debugLogger.error("Application log flush failed:", error), + ); + } } - // Native console implementations and nested wrappers can call other console - // methods. Only the outermost wrapped call should emit an application log. - return suppressApplicationLogs(call); + return call(); } type WrapConsoleOptions = { @@ -83,15 +74,17 @@ function enableConsoleForwarding(): void { const call = () => Reflect.apply(target, receiver, args); const registration = consoleRegistrations.get(additional.registration); if (registration === undefined) return call(); - // A disabled outer wrapper must not reactivate older wrappers that another - // console patch may still invoke. Null also releases the destination logger. - if (registration === null) return suppressApplicationLogs(call); - return forwardConsoleCall( - call, - registration.logger ?? currentLogger(), - additional.method, - args, - ); + // A disabled outer wrapper must not reactivate an older wrapper kept alive + // by another console patch. Null also releases the destination logger. + return runConsoleCall((nested) => { + if (nested || registration === null) return call(); + return forwardConsoleCall( + call, + registration.logger ?? currentLogger(), + additional.method, + args, + ); + }); }); } diff --git a/js/src/logs/logs.test.ts b/js/src/logs/logs.test.ts index 56e87643e..f30013ac1 100644 --- a/js/src/logs/logs.test.ts +++ b/js/src/logs/logs.test.ts @@ -8,13 +8,14 @@ import { } from "../logger"; import { LazyValue } from "../util"; import { wrapConsole } from "./index"; -import { consoleMethods } from "./console-interceptor"; +import { consoleMethods } from "./console"; import { configureNode } from "../node/config"; import iso from "../isomorph"; import type { ExperimentEvent } from "../util"; import { debugLogger } from "../debug-logger"; import { OTELIDGenerator } from "../id-gen"; -import { isApplicationLogSuppressed, suppressApplicationLogs } from "./context"; +import { logError } from "../framework"; +import { SimpleProgressReporter } from "../reporters/progress"; configureNode(); @@ -51,8 +52,15 @@ function fakeConsole() { }; } +function mockGlobalConsole() { + const target = { ...console, ...fakeConsole() }; + vi.stubGlobal("console", target); + return target; +} + afterEach(() => { vi.restoreAllMocks(); + vi.unstubAllGlobals(); }); describe("application logs", () => { @@ -77,84 +85,92 @@ describe("application logs", () => { { asyncFlush: true }, ); const target = fakeConsole(); + const originals = { ...target }; const uninstrument = wrapConsole(target, { logger }); const id = logger.info(logger.fmt`User ${"Ada"}`); await logger.flush(); - target.warn("Retry %d", 2); + for (const method of consoleMethods) { + target[method](`console.${method}`); + expect(originals[method]).toHaveBeenCalledExactlyOnceWith( + `console.${method}`, + ); + expect(originals[method].mock.contexts[0]).toBe(target); + } uninstrument(); - target.warn("Console output only"); + for (const method of consoleMethods) { + target[method]("console only"); + expect(originals[method]).toHaveBeenCalledTimes(2); + expect(originals[method]).toHaveBeenLastCalledWith("console only"); + } await logger.flush(); await logger.flush(); - expect(rows).toHaveLength(2); + expect(rows).toHaveLength(7); expect(rows[0]).toMatchObject({ id, output: "User Ada", _is_merge: false, }); - expect(rows[1]).toMatchObject({ output: "Retry 2", _is_merge: false }); - expect(rows[1].id).not.toBe(id); + expect(rows.slice(1).map((row) => row.output)).toEqual( + consoleMethods.map((method) => `console.${method}`), + ); + expect(rows.slice(1).map((row) => row.span_attributes?.log_level)).toEqual([ + "info", + "trace", + "debug", + "info", + "warn", + "error", + ]); + expect(new Set(rows.map((row) => row.id)).size).toBe(7); for (const row of rows) { + expect(row._is_merge).toBe(false); expect(row.metrics?.end).toBe(row.metrics?.start); expect(row.span_attributes?.type).toBe("log"); } }); - test.each(["trace", "debug", "info", "warn", "error", "fatal"] as const)( - "%s enqueues exactly one complete row", - async (level) => { - const { logger, background, enqueue } = setup(true); - const timestamp = new Date("2026-01-02T03:04:05.000Z"); - vi.useFakeTimers(); - vi.setSystemTime(timestamp); - try { - const id = logger[level](logger.fmt`Worker ${3} started`, { + test("severity methods each enqueue one complete initial row", async () => { + const { logger, background, enqueue } = setup(true); + const timestamp = new Date("2026-01-02T03:04:05.000Z"); + const levels = [ + "trace", + "debug", + "info", + "warn", + "error", + "fatal", + ] as const; + vi.useFakeTimers(); + vi.setSystemTime(timestamp); + try { + for (const [index, level] of levels.entries()) { + const id = logger[level]("Worker {id} started", { metadata: { worker_id: "worker-1" }, }); - expect(enqueue).toHaveBeenCalledTimes(1); - expect(enqueue.mock.calls[0][0]).toHaveLength(1); - // Inspect the raw initial write before TestBackgroundLogger can merge updates. - const row = await enqueue.mock.calls[0][0][0].get(); + expect(enqueue).toHaveBeenCalledTimes(index + 1); + expect(enqueue.mock.calls[index][0]).toHaveLength(1); + // Inspect initial writes before TestBackgroundLogger can merge updates. + const row = await enqueue.mock.calls[index][0][0].get(); expect(row).toMatchObject({ id, project_id: "project", - output: "Worker 3 started", + output: "Worker {id} started", _is_merge: false, span_attributes: { type: "log", name: null, log_level: level }, - metadata: { - worker_id: "worker-1", - "braintrust.template": "Worker ${0} started", - "braintrust.template.parameter.0": 3, - }, + metadata: { worker_id: "worker-1" }, created: timestamp.toISOString(), metrics: { start: timestamp.getTime() / 1000, end: timestamp.getTime() / 1000, }, }); - await logger.flush(); - expect(await drain(background)).toHaveLength(1); - expect(enqueue).toHaveBeenCalledTimes(1); - } finally { - vi.useRealTimers(); } - }, - ); - - test("logs ordinary JSON bodies verbatim without interpreting template-like text", async () => { - const { logger, background } = setup(true); - const metadata = Object.freeze({ source: "app" }); - const bodies = [ - null, - true, - 42, - [1, "two"], - { event: "started" }, - "User {name} paid {amount:.2f}", - ]; - for (const body of bodies) logger.info(body, { metadata }); - const rows = await drain(background); - expect(rows.map((row) => row.output)).toEqual(bodies); - expect(rows.map((row) => row.metadata)).toEqual(bodies.map(() => metadata)); + await logger.flush(); + expect(await drain(background)).toHaveLength(levels.length); + expect(enqueue).toHaveBeenCalledTimes(levels.length); + } finally { + vi.useRealTimers(); + } }); test("fmt captures stable templates and values without emitting or mutating metadata", async () => { @@ -233,18 +249,10 @@ describe("application logs", () => { ).toEqual([{ id: 42 }, false, null, 0, "undefined", "123"]); }); - test("fmt coerces each interpolation only once", async () => { - const { logger, background } = setup(true); - const coerce = vi.fn(() => "custom value"); - logger.info(logger.fmt`value=${{ [Symbol.toPrimitive]: coerce }}`); - expect(coerce).toHaveBeenCalledExactlyOnceWith("string"); - expect((await drain(background))[0].output).toBe("value=custom value"); - }); - test("groups standalone messages per logger with independent row and span IDs", async () => { const { logger, background, state } = setup(true); logger.info("one"); - logger.warn("two"); + logger.warn({ event: "two" }); const other = new Logger( state, new LazyValue(async () => ({ @@ -255,6 +263,7 @@ describe("application logs", () => { ); other.info("three"); const [one, two, three] = await drain(background); + expect(two.output).toEqual({ event: "two" }); expect(one.id).not.toBe(two.id); expect(one.span_id).not.toBe(two.span_id); expect(one.root_span_id).toBe(two.root_span_id); @@ -361,45 +370,13 @@ describe("application logs", () => { }); describe("wrapConsole", () => { - test.each([ - ["log", "info"], - ["trace", "trace"], - ["debug", "debug"], - ["info", "info"], - ["warn", "warn"], - ["error", "error"], - ] as const)( - "maps console.%s to %s and preserves output before and after cleanup", - async (method, level) => { - const { logger, background, enqueue } = setup(true); - const target = fakeConsole(); - const original = target[method]; - const uninstrument = wrapConsole(target, { logger }); - target[method]("message"); - expect(original).toHaveBeenCalledExactlyOnceWith("message"); - expect(original.mock.contexts[0]).toBe(target); - expect(enqueue).toHaveBeenCalledTimes(1); - expect((await drain(background))[0]).toMatchObject({ - output: "message", - span_attributes: { log_level: level }, - }); - uninstrument(); - target[method]("console only"); - expect(original).toHaveBeenCalledTimes(2); - expect(original).toHaveBeenLastCalledWith("console only"); - expect(enqueue).toHaveBeenCalledTimes(1); - }, - ); - test("wrapConsole() follows logger initialization and replacement until cleanup", async () => { + const target = mockGlobalConsole(); const first = setup(false); const second = setup(false); const state = _internalGetGlobalState(); const previousLogger = state.currentLogger; - const methods = consoleMethods.map( - (method) => [method, console[method]] as const, - ); - const original = vi.spyOn(console, "info").mockImplementation(() => {}); + const original = target.info; try { state.currentLogger = undefined; const uninstrument = wrapConsole(); @@ -424,11 +401,10 @@ describe("wrapConsole", () => { expect(second.enqueue).toHaveBeenCalledTimes(1); } finally { state.currentLogger = previousLogger; - for (const [method, original] of methods) console[method] = original; } }); - test("an older cleanup cannot disable a newer wrap or resume an older destination", async () => { + test("rewrapping and cleanup preserve the current destination without reactivating older wraps", async () => { const first = setup(true); const second = setup(true); const target = fakeConsole(); @@ -444,31 +420,22 @@ describe("wrapConsole", () => { stopSecond(); stopSecond(); target.info("console only"); - expect(original).toHaveBeenCalledTimes(3); + const stopThird = wrapConsole(target, { logger: second.logger }); + expect(target.info).toBe(wrapped); + stopSecond(); + target.info("captured again"); + stopThird(); + target.info("console only again"); + expect(original).toHaveBeenCalledTimes(5); expect((await drain(first.background)).map((row) => row.output)).toEqual([ "first", ]); expect((await drain(second.background)).map((row) => row.output)).toEqual([ "second", + "captured again", ]); }); - test("wrapping after cleanup re-enables forwarding without replacing the installed methods", async () => { - const { logger, background, enqueue } = setup(true); - const target = fakeConsole(); - const stopFirst = wrapConsole(target, { logger }); - const wrapped = target.info; - stopFirst(); - const stopSecond = wrapConsole(target, { logger }); - expect(target.info).toBe(wrapped); - stopFirst(); - target.info("captured again"); - stopSecond(); - target.info("console only"); - expect(enqueue).toHaveBeenCalledTimes(1); - expect((await drain(background))[0].output).toBe("captured again"); - }); - test("cleanup affects only its console; direct logging and unrelated methods stay enabled", async () => { const first = setup(true); const second = setup(true); @@ -517,25 +484,26 @@ describe("wrapConsole", () => { stopFirst(); }); - test("does not duplicate calls when native console methods call one another", () => { - const { logger, enqueue } = setup(true); + test("nested console calls capture once and native exceptions do not leave the guard active", async () => { + const { logger, background, enqueue } = setup(true); const target = fakeConsole(); target.trace.mockImplementation((...args) => target.error(...args)); - wrapConsole(target, { logger }); - target.trace("one log"); - expect(enqueue).toHaveBeenCalledTimes(1); - }); - - test("preserves native exceptions and does not retry the console call", () => { - const { logger } = setup(true); - const target = fakeConsole(); const error = new Error("console failure"); const original = target.info.mockImplementation(() => { throw error; }); wrapConsole(target, { logger }); - expect(() => target.info("test")).toThrow(error); + target.trace("nested"); + expect(enqueue).toHaveBeenCalledTimes(1); + expect(() => target.info("failure")).toThrow(error); expect(original).toHaveBeenCalledTimes(1); + target.warn("after failure"); + expect(enqueue).toHaveBeenCalledTimes(3); + expect((await drain(background)).map((row) => row.output)).toEqual([ + "nested", + "failure", + "after failure", + ]); }); test("preserves console formatting, parameters, errors, and unformattable arguments", async () => { @@ -584,77 +552,56 @@ describe("wrapConsole", () => { ); }); - test("SDK diagnostics are printed without becoming application logs", () => { + test("SDK output uses saved console methods across awaits, rewrapping, and cleanup", async () => { + const target = mockGlobalConsole(); const { logger, enqueue } = setup(true); const sdkState = _internalGetGlobalState(); vi.spyOn(sdkState, "getDebugLogLevel").mockReturnValue("warn"); vi.spyOn(sdkState, "hasDebugLogLevelOverride").mockReturnValue(true); - const methods = consoleMethods.map( - (method) => [method, console[method]] as const, - ); - const original = vi.spyOn(console, "warn").mockImplementation(() => {}); - const uninstrument = wrapConsole(console, { logger }); + // Before wrapping, SDK output still uses the current console. + debugLogger.warn("before wrapping"); + const originals = { + warn: target.warn, + error: target.error, + log: target.log, + }; + const stopFirst = wrapConsole(console, { logger }); + const firstWrapper = console.warn; + const thirdParty = vi.fn((...args) => firstWrapper(...args)); + console.warn = thirdParty; + const stopSecond = wrapConsole(console, { logger }); try { + await Promise.resolve(); debugLogger.warn("SDK warning"); expect(debugLogger.notice.warn("SDK notice")).toBe(true); - expect(original).toHaveBeenCalledTimes(2); - expect(original).toHaveBeenCalledWith("[braintrust]", "SDK warning"); - expect(original).toHaveBeenCalledWith("[braintrust]", "SDK notice"); + logError("evaluation error", false); + new SimpleProgressReporter().start("evaluation", 1); + expect(originals.warn).toHaveBeenCalledTimes(3); + expect(originals.warn).toHaveBeenCalledWith( + "[braintrust]", + "SDK warning", + ); + expect(originals.warn).toHaveBeenCalledWith("[braintrust]", "SDK notice"); + expect(originals.warn.mock.contexts[0]).toBe(console); + expect(originals.error).toHaveBeenCalledWith("evaluation error"); + expect(originals.log).toHaveBeenCalledWith( + "Running evaluator evaluation", + ); + expect(thirdParty).not.toHaveBeenCalled(); expect(enqueue).not.toHaveBeenCalled(); console.warn("application log"); + expect(thirdParty).toHaveBeenCalledTimes(1); expect(enqueue).toHaveBeenCalledTimes(1); - } finally { - uninstrument(); - for (const [method, original] of methods) console[method] = original; - } - }); - - test("bootstrap diagnostics do not prevent async suppression after platform initialization", async () => { - const key = Symbol.for("braintrust.applicationLogContext"); - const previousContext = Object.getOwnPropertyDescriptor(globalThis, key); - const previousBuildType = iso.buildType; - Reflect.deleteProperty(globalThis, key); - try { - iso.buildType = "unknown"; - suppressApplicationLogs(() => - expect(isApplicationLogSuppressed()).toBe(true), + stopSecond(); + debugLogger.warn("after cleanup"); + expect(originals.warn).toHaveBeenLastCalledWith( + "[braintrust]", + "after cleanup", ); - expect(isApplicationLogSuppressed()).toBe(false); - iso.buildType = previousBuildType; - await suppressApplicationLogs(async () => { - await Promise.resolve(); - expect(isApplicationLogSuppressed()).toBe(true); - }); - expect(isApplicationLogSuppressed()).toBe(false); + expect(enqueue).toHaveBeenCalledTimes(1); } finally { - iso.buildType = previousBuildType; - if (previousContext) - Object.defineProperty(globalThis, key, previousContext); - else Reflect.deleteProperty(globalThis, key); + stopFirst(); + stopSecond(); } }); - - test("ignores console logs inside SDK HTTP transport across awaits but captures concurrent application logs", async () => { - const { logger, background, state } = setup(true); - const target = fakeConsole(); - wrapConsole(target, { logger }); - let release!: () => void; - const pending = new Promise((resolve) => { - release = resolve; - }); - state.setFetch(async () => { - target.debug("transport start"); - await pending; - target.debug("transport end"); - return new Response("{}", { status: 200 }); - }); - state.apiUrl = "https://example.com"; - const response = state.apiConn().post("logs3", {}); - target.info("application"); - release(); - await response; - const rows = await drain(background); - expect(rows).toHaveLength(1); - expect(rows[0].output).toBe("application"); - }); }); diff --git a/js/src/reporters/progress.ts b/js/src/reporters/progress.ts index 5d4ec3f3c..54746a8dd 100644 --- a/js/src/reporters/progress.ts +++ b/js/src/reporters/progress.ts @@ -1,12 +1,9 @@ -import { suppressApplicationLogs } from "../logs/context"; +import { sdkConsole } from "../logs/console"; import type { ProgressReporter } from "./types"; export class SimpleProgressReporter implements ProgressReporter { public start(name: string, _total: number) { - suppressApplicationLogs(() => { - // eslint-disable-next-line no-restricted-properties -- user-facing progress output is independent of SDK diagnostics. - console.log(`Running evaluator ${name}`); - }); + sdkConsole.log(`Running evaluator ${name}`); } public stop() {} public increment(_name: string) {} diff --git a/js/src/wrappers/shared/flush.ts b/js/src/wrappers/shared/flush.ts index a044806c4..53aea44be 100644 --- a/js/src/wrappers/shared/flush.ts +++ b/js/src/wrappers/shared/flush.ts @@ -1,4 +1,4 @@ -import { suppressApplicationLogs } from "../../logs/context"; +import { sdkConsole } from "../../logs/console"; import type { Experiment } from "../../logger"; import { formatExperimentSummary } from "./format"; @@ -18,8 +18,5 @@ export async function summarizeAndFlush( } const summary = await experiment.summarize(); - suppressApplicationLogs(() => { - // eslint-disable-next-line no-restricted-properties -- user-requested summary output is independent of SDK diagnostics. - console.log(formatExperimentSummary(summary)); - }); + sdkConsole.log(formatExperimentSummary(summary)); } From fe965891036a49478f18c16b90dcc79fe2d3e729 Mon Sep 17 00:00:00 2001 From: Abhijeet Prasad Date: Mon, 19 Oct 2026 14:54:45 -0700 Subject: [PATCH 4/6] fix(logs): skip custom inspectors during console capture Capture structural object text without invoking application inspectors for messages or metadata. Forward original arguments so native console rendering still runs its custom inspector once. --- js/src/logs/logs.test.ts | 47 +++++++++++++++++++++++++++++++++++++--- js/src/node/config.ts | 7 ++++-- 2 files changed, 49 insertions(+), 5 deletions(-) diff --git a/js/src/logs/logs.test.ts b/js/src/logs/logs.test.ts index f30013ac1..331d28bb9 100644 --- a/js/src/logs/logs.test.ts +++ b/js/src/logs/logs.test.ts @@ -1,5 +1,7 @@ import { afterEach, describe, expect, test, vi } from "vitest"; import { inspect } from "node:util"; +import { Console } from "node:console"; +import { Writable } from "node:stream"; import { BraintrustState, Logger, @@ -506,6 +508,45 @@ describe("wrapConsole", () => { ]); }); + test("custom inspectors run only in the native console, not during message or metadata capture", async () => { + const { logger, background } = setup(true); + const output: string[] = []; + const stdout = new Writable({ + write(chunk, _encoding, callback) { + output.push(String(chunk)); + callback(); + }, + }); + const target = new Console({ stdout, stderr: stdout, colorMode: false }); + const stop = wrapConsole(target, { logger }); + let inspections = 0; + const customInspect = vi.fn(() => `custom-${++inspections}`); + const value = { id: 42, [inspect.custom]: customInspect }; + const calls = [[value], ["value %o", value], ["value %s", value]]; + try { + for (const [index, args] of calls.entries()) { + target.info(...args); + expect(customInspect).toHaveBeenCalledTimes(index + 1); + } + expect(output).toEqual([ + "custom-1\n", + "value custom-2\n", + "value custom-3\n", + ]); + const rows = await drain(background); + expect(rows).toHaveLength(3); + for (const row of rows) expect(row.output).toContain("id: 42"); + for (const row of rows.slice(1)) { + expect(row.metadata?.["braintrust.template.parameter.0"]).toContain( + "id: 42", + ); + } + } finally { + stop(); + stdout.destroy(); + } + }); + test("preserves console formatting, parameters, errors, and unformattable arguments", async () => { const { logger, background } = setup(true); const target = fakeConsole(); @@ -515,9 +556,9 @@ describe("wrapConsole", () => { const circular: Record = {}; circular.self = circular; target.info("value %o", circular); - target.info("value %o", { - [inspect.custom]() { - throw new Error("bad inspector"); + target.info("value %j", { + toJSON() { + throw new Error("bad serializer"); }, }); const rows = await drain(background); diff --git a/js/src/node/config.ts b/js/src/node/config.ts index e8a95acaf..fb9e37626 100644 --- a/js/src/node/config.ts +++ b/js/src/node/config.ts @@ -4,7 +4,7 @@ import * as fs from "node:fs/promises"; import * as os from "node:os"; import * as fsSync from "node:fs"; import * as crypto from "node:crypto"; -import { format, promisify } from "node:util"; +import { formatWithOptions, promisify } from "node:util"; import * as zlib from "node:zlib"; import * as dotenv from "dotenv"; @@ -108,7 +108,10 @@ export function configureNode() { return undefined; }; iso.getCallerLocation = getCallerLocation; - iso.formatLogMessage = format; + // Capture structural text without invoking application-defined inspectors. + // The native console receives the original arguments and runs its own hooks. + iso.formatLogMessage = (...args) => + formatWithOptions({ customInspect: false }, ...args); iso.newAsyncLocalStorage = () => new AsyncLocalStorage(); iso.processOn = (event: string, handler: (code: unknown) => void) => { process.on(event, handler); From 047606121a3e398749c935a7332fc6aece4a349b Mon Sep 17 00:00:00 2001 From: Abhijeet Prasad Date: Tue, 20 Oct 2026 09:42:39 -0700 Subject: [PATCH 5/6] fix(logs): serialize browser console arguments once Reuse formatted browser arguments in both messages and template metadata so toJSON runs once per argument. Preserve BigInt values as text before JSON serialization. --- js/src/logs/index.ts | 10 ++++++++-- js/src/logs/logs.test.ts | 25 +++++++++++++++++++++---- 2 files changed, 29 insertions(+), 6 deletions(-) diff --git a/js/src/logs/index.ts b/js/src/logs/index.ts index 9e0c56e4d..fb7d1f9c9 100644 --- a/js/src/logs/index.ts +++ b/js/src/logs/index.ts @@ -8,6 +8,7 @@ import type { ApplicationLogLevel } from "./templates"; function display(value: unknown): string { if (value instanceof Error) return value.stack ?? value.message; if (typeof value === "string") return value; + if (typeof value === "bigint") return String(value); return JSON.stringify(value) ?? String(value); } @@ -36,7 +37,12 @@ function forwardConsoleCall( args: unknown[], ): void { if (logger) { - const body = formatConsole(args); + // Browser fallback serialization can invoke toJSON. Reuse each argument's + // text for the body and metadata so those hooks run only once per argument. + const formattedArgs = iso.formatLogMessage + ? undefined + : args.map((value) => formatConsole([value])); + const body = formattedArgs ? formattedArgs.join(" ") : formatConsole(args); const metadata: Record = { "logger.name": "console" }; if (typeof args[0] === "string" && args.length > 1) { metadata["braintrust.template"] = args[0]; @@ -45,7 +51,7 @@ function forwardConsoleCall( value === null || ["string", "number", "boolean"].includes(typeof value) ? value - : formatConsole([value]); + : (formattedArgs?.[index + 1] ?? formatConsole([value])); }); } const level: ApplicationLogLevel = method === "log" ? "info" : method; diff --git a/js/src/logs/logs.test.ts b/js/src/logs/logs.test.ts index 331d28bb9..f92c44ffe 100644 --- a/js/src/logs/logs.test.ts +++ b/js/src/logs/logs.test.ts @@ -577,20 +577,37 @@ describe("wrapConsole", () => { expect(rows[3].output).toBe("[Unformattable console message]"); }); - test("preserves console arguments as text when there is no native formatter", async () => { + test("fallback formatting serializes parameters once and preserves BigInt arguments", async () => { const { logger, background } = setup(true); const target = fakeConsole(); wrapConsole(target, { logger }); + let serializations = 0; + const toJSON = vi.fn(() => ({ serialization: ++serializations })); const format = iso.formatLogMessage; iso.formatLogMessage = undefined; try { target.info("Payment %s %d %%", "pay_123", 2, { attempt: 1 }); + target.info("value %s", { toJSON }); + target.info("count", 1n); + target.info(2n); } finally { iso.formatLogMessage = format; } - expect((await drain(background))[0].output).toBe( - 'Payment %s %d %% pay_123 2 {"attempt":1}', - ); + const rows = await drain(background); + expect.soft(toJSON).toHaveBeenCalledTimes(1); + expect + .soft(rows.map((row) => row.output)) + .toEqual([ + 'Payment %s %d %% pay_123 2 {"attempt":1}', + 'value %s {"serialization":1}', + "count 1", + "2", + ]); + expect.soft(rows[1].metadata).toMatchObject({ + "braintrust.template": "value %s", + "braintrust.template.parameter.0": '{"serialization":1}', + }); + expect(rows[2].metadata?.["braintrust.template.parameter.0"]).toBe("1"); }); test("SDK output uses saved console methods across awaits, rewrapping, and cleanup", async () => { From cc87ba02c362c9329b8a4f8e5894546b2b991516 Mon Sep 17 00:00:00 2001 From: Abhijeet Prasad Date: Tue, 20 Oct 2026 09:53:53 -0700 Subject: [PATCH 6/6] fix(logs): avoid node coercion hooks during capture Render object and function parameters structurally before format substitution, leaving toString, valueOf, and toJSON execution to the native console. Preserve original console arguments and primitive formatting. --- js/src/logs/logs.test.ts | 34 +++++++++++++++++++++++++--------- js/src/node/config.ts | 19 +++++++++++++++---- 2 files changed, 40 insertions(+), 13 deletions(-) diff --git a/js/src/logs/logs.test.ts b/js/src/logs/logs.test.ts index f92c44ffe..ee61847fd 100644 --- a/js/src/logs/logs.test.ts +++ b/js/src/logs/logs.test.ts @@ -508,7 +508,7 @@ describe("wrapConsole", () => { ]); }); - test("custom inspectors run only in the native console, not during message or metadata capture", async () => { + test("object formatting hooks run only in the native console, not during capture", async () => { const { logger, background } = setup(true); const output: string[] = []; const stdout = new Writable({ @@ -523,19 +523,35 @@ describe("wrapConsole", () => { const customInspect = vi.fn(() => `custom-${++inspections}`); const value = { id: 42, [inspect.custom]: customInspect }; const calls = [[value], ["value %o", value], ["value %s", value]]; + let stringCalls = 0; + let numberCalls = 0; + let jsonCalls = 0; + const toString = vi.fn(() => `string-${++stringCalls}`); + const valueOf = vi.fn(() => ++numberCalls); + const toJSON = vi.fn(() => ({ serialization: ++jsonCalls })); try { for (const [index, args] of calls.entries()) { target.info(...args); expect(customInspect).toHaveBeenCalledTimes(index + 1); } + target.info("%s", { id: 42, toString }); + target.info("%d", { id: 42, valueOf }); + target.info("%j", { id: 42, toJSON }); + expect.soft(toString).toHaveBeenCalledTimes(1); + expect.soft(valueOf).toHaveBeenCalledTimes(1); + expect.soft(toJSON).toHaveBeenCalledTimes(1); expect(output).toEqual([ "custom-1\n", "value custom-2\n", "value custom-3\n", + "string-1\n", + "1\n", + '{"serialization":1}\n', ]); const rows = await drain(background); - expect(rows).toHaveLength(3); - for (const row of rows) expect(row.output).toContain("id: 42"); + expect(rows).toHaveLength(6); + for (const row of rows.slice(0, 4)) + expect(row.output).toContain("id: 42"); for (const row of rows.slice(1)) { expect(row.metadata?.["braintrust.template.parameter.0"]).toContain( "id: 42", @@ -547,7 +563,7 @@ describe("wrapConsole", () => { } }); - test("preserves console formatting, parameters, errors, and unformattable arguments", async () => { + test("preserves primitive formatting, parameters, errors, and circular objects without calling toJSON", async () => { const { logger, background } = setup(true); const target = fakeConsole(); wrapConsole(target, { logger }); @@ -556,11 +572,10 @@ describe("wrapConsole", () => { const circular: Record = {}; circular.self = circular; target.info("value %o", circular); - target.info("value %j", { - toJSON() { - throw new Error("bad serializer"); - }, + const toJSON = vi.fn(() => { + throw new Error("bad serializer"); }); + target.info("value %j", { id: 42, toJSON }); const rows = await drain(background); expect(rows).toHaveLength(4); expect(rows[0]).toMatchObject({ @@ -574,7 +589,8 @@ describe("wrapConsole", () => { }); expect(rows[1].output).toContain("Error: payment failed"); expect(rows[2].output).toContain("Circular"); - expect(rows[3].output).toBe("[Unformattable console message]"); + expect(toJSON).not.toHaveBeenCalled(); + expect(rows[3].output).toContain("id: 42"); }); test("fallback formatting serializes parameters once and preserves BigInt arguments", async () => { diff --git a/js/src/node/config.ts b/js/src/node/config.ts index fb9e37626..329989c3c 100644 --- a/js/src/node/config.ts +++ b/js/src/node/config.ts @@ -4,7 +4,7 @@ import * as fs from "node:fs/promises"; import * as os from "node:os"; import * as fsSync from "node:fs"; import * as crypto from "node:crypto"; -import { formatWithOptions, promisify } from "node:util"; +import { formatWithOptions, inspect, promisify } from "node:util"; import * as zlib from "node:zlib"; import * as dotenv from "dotenv"; @@ -108,10 +108,21 @@ export function configureNode() { return undefined; }; iso.getCallerLocation = getCallerLocation; - // Capture structural text without invoking application-defined inspectors. - // The native console receives the original arguments and runs its own hooks. + // Inspect object parameters before substitution: customInspect alone does not + // prevent %s/%d/%j from invoking toString/valueOf/toJSON. The first argument + // stays intact because Node only treats a leading string as a format string. + // Native console output still receives the original arguments and hooks. iso.formatLogMessage = (...args) => - formatWithOptions({ customInspect: false }, ...args); + formatWithOptions( + { customInspect: false }, + ...args.map((value, index) => + index > 0 && + value !== null && + (typeof value === "object" || typeof value === "function") + ? inspect(value, { customInspect: false }) + : value, + ), + ); iso.newAsyncLocalStorage = () => new AsyncLocalStorage(); iso.processOn = (event: string, handler: (code: unknown) => void) => { process.on(event, handler);