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/debug-logger.ts b/js/src/debug-logger.ts index 6b4b6b17c..8fa3a0c49 100644 --- a/js/src/debug-logger.ts +++ b/js/src/debug-logger.ts @@ -1,4 +1,5 @@ import iso from "./isomorph"; +import { sdkConsole } from "./logs/console"; import { setGlobalHookErrorReporter } from "./global-instrumentation-hooks"; export type DebugLogLevel = "error" | "warn" | "info" | "debug"; @@ -45,8 +46,7 @@ function warnInvalidEnvValue(value: string) { return; } hasWarnedAboutInvalidEnvValue = true; - // eslint-disable-next-line no-restricted-properties -- preserving intentional console usage. - console.warn( + sdkConsole.warn( PREFIX, `Invalid BRAINTRUST_DEBUG_LOG_LEVEL value "${value}". Expected "error", "warn", "info", or "debug".`, ); @@ -155,19 +155,7 @@ 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); - } + sdkConsole[method === "info" ? "log" : method](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..a56f0d693 100644 --- a/js/src/framework.ts +++ b/js/src/framework.ts @@ -1,3 +1,4 @@ +import { sdkConsole } from "./logs/console"; import { makeScorerPropagatedEvent, Classification, @@ -893,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,11 +1786,9 @@ 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}`); + sdkConsole.error(`${e}`); } else { - // eslint-disable-next-line no-restricted-properties -- preserving intentional console usage. - console.error(e); + sdkConsole.error(e); } } @@ -1869,15 +1866,13 @@ export function reportFailures< // 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( + 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) { - // eslint-disable-next-line no-restricted-properties -- preserving intentional console usage. - console.log( + sdkConsole.log( JSON.stringify({ evaluatorName: evaluator.evalName, errors: failingResults.map( @@ -1891,8 +1886,7 @@ export function reportFailures< } } if (!verbose && !jsonl) { - // eslint-disable-next-line no-restricted-properties -- preserving intentional console usage. - console.error( + sdkConsole.error( warning( "Use --debug-logging debug to see full stack traces and troubleshooting details.", ), diff --git a/js/src/isomorph.ts b/js/src/isomorph.ts index 354adf2cb..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, @@ -41,6 +43,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; @@ -102,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 c70661482..afe0c8d24 100644 --- a/js/src/logger.ts +++ b/js/src/logger.ts @@ -1,6 +1,13 @@ /// import { DecisionAttachmentProcessor } from "./decision-attachments"; +import { + formatLogTemplate, + renderLogBody, + type ApplicationLogLevel, + type ApplicationLogOptions, + type ApplicationLogTemplate, +} from "./logs/templates"; import { v4 as uuidv4 } from "uuid"; @@ -2900,6 +2907,7 @@ export class Logger implements Exportable { private lastStartTime: number; private lazyId: LazyValue; private calledStartSpan: boolean; + private baselineTraceId?: string; // For type identification. public kind = "logger" as const; @@ -2983,6 +2991,125 @@ 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: { + // 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], + 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". * diff --git a/js/src/logs/console-interceptor.ts b/js/src/logs/console-interceptor.ts new file mode 100644 index 000000000..9be9660a0 --- /dev/null +++ b/js/src/logs/console-interceptor.ts @@ -0,0 +1,51 @@ +import { + channel, + defineInterceptor, +} from "../instrumentation/core/interceptor-definitions"; +import { + consoleMethods, + saveConsoleMethods, + type ConsoleMethod, + type LogConsole, +} from "./console"; + +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 { + saveConsoleMethods(target); + 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/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/index.ts b/js/src/logs/index.ts new file mode 100644 index 000000000..fb7d1f9c9 --- /dev/null +++ b/js/src/logs/index.ts @@ -0,0 +1,127 @@ +import { currentLogger, type Logger } from "../logger"; +import iso from "../isomorph"; +import { debugLogger } from "../debug-logger"; +import { consoleHooks, wrapConsoleMethods } from "./console-interceptor"; +import { runConsoleCall, type ConsoleMethod, type LogConsole } from "./console"; +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); +} + +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) { + // 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]; + args.slice(1).forEach((value, index) => { + metadata[`braintrust.template.parameter.${index}`] = + value === null || + ["string", "number", "boolean"].includes(typeof value) + ? value + : (formattedArgs?.[index + 1] ?? 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), + ); + } + } + return 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 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, + ); + }); + }); +} + +/** + * 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..ee61847fd --- /dev/null +++ b/js/src/logs/logs.test.ts @@ -0,0 +1,681 @@ +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, + TestBackgroundLogger, + _internalGetGlobalState, +} from "../logger"; +import { LazyValue } from "../util"; +import { wrapConsole } from "./index"; +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 { logError } from "../framework"; +import { SimpleProgressReporter } from "../reporters/progress"; + +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(), + }; +} + +function mockGlobalConsole() { + const target = { ...console, ...fakeConsole() }; + vi.stubGlobal("console", target); + return target; +} + +afterEach(() => { + vi.restoreAllMocks(); + vi.unstubAllGlobals(); +}); + +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 originals = { ...target }; + const uninstrument = wrapConsole(target, { logger }); + const id = logger.info(logger.fmt`User ${"Ada"}`); + await logger.flush(); + for (const method of consoleMethods) { + target[method](`console.${method}`); + expect(originals[method]).toHaveBeenCalledExactlyOnceWith( + `console.${method}`, + ); + expect(originals[method].mock.contexts[0]).toBe(target); + } + uninstrument(); + 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(7); + expect(rows[0]).toMatchObject({ + id, + output: "User Ada", + _is_merge: false, + }); + 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("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(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 {id} started", + _is_merge: false, + span_attributes: { type: "log", name: null, log_level: level }, + 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(levels.length); + expect(enqueue).toHaveBeenCalledTimes(levels.length); + } finally { + vi.useRealTimers(); + } + }); + + 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("groups standalone messages per logger with independent row and span IDs", async () => { + const { logger, background, state } = setup(true); + logger.info("one"); + logger.warn({ event: "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(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); + expect(three.root_span_id).not.toBe(one.root_span_id); + 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(); + 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("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 original = target.info; + 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; + } + }); + + test("rewrapping and cleanup preserve the current destination without reactivating older wraps", 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"); + 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("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("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)); + const error = new Error("console failure"); + const original = target.info.mockImplementation(() => { + throw error; + }); + wrapConsole(target, { logger }); + 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("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({ + 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]]; + 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(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", + ); + } + } finally { + stop(); + stdout.destroy(); + } + }); + + test("preserves primitive formatting, parameters, errors, and circular objects without calling toJSON", 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); + 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({ + 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(toJSON).not.toHaveBeenCalled(); + expect(rows[3].output).toContain("id: 42"); + }); + + 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; + } + 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 () => { + const target = mockGlobalConsole(); + const { logger, enqueue } = setup(true); + const sdkState = _internalGetGlobalState(); + vi.spyOn(sdkState, "getDebugLogLevel").mockReturnValue("warn"); + vi.spyOn(sdkState, "hasDebugLogLevelOverride").mockReturnValue(true); + // 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); + 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); + stopSecond(); + debugLogger.warn("after cleanup"); + expect(originals.warn).toHaveBeenLastCalledWith( + "[braintrust]", + "after cleanup", + ); + expect(enqueue).toHaveBeenCalledTimes(1); + } finally { + stopFirst(); + stopSecond(); + } + }); +}); 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..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 { promisify } from "node:util"; +import { formatWithOptions, inspect, promisify } from "node:util"; import * as zlib from "node:zlib"; import * as dotenv from "dotenv"; @@ -108,6 +108,21 @@ export function configureNode() { return undefined; }; iso.getCallerLocation = getCallerLocation; + // 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.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); diff --git a/js/src/reporters/progress.ts b/js/src/reporters/progress.ts index d1a8e5303..54746a8dd 100644 --- a/js/src/reporters/progress.ts +++ b/js/src/reporters/progress.ts @@ -1,9 +1,9 @@ +import { sdkConsole } from "../logs/console"; 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}`); + 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 ab5e89028..53aea44be 100644 --- a/js/src/wrappers/shared/flush.ts +++ b/js/src/wrappers/shared/flush.ts @@ -1,3 +1,4 @@ +import { sdkConsole } from "../../logs/console"; import type { Experiment } from "../../logger"; import { formatExperimentSummary } from "./format"; @@ -17,6 +18,5 @@ export async function summarizeAndFlush( } const summary = await experiment.summarize(); - // eslint-disable-next-line no-restricted-properties -- preserving intentional console usage. - console.log(formatExperimentSummary(summary)); + sdkConsole.log(formatExperimentSummary(summary)); }