feat(logs): add application logging and console capture

.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.

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;
 }
 

js/src/exports.ts

@@ -44,6 +44,8 @@ export type {
   WithTransactionId,
 } from "./logger";
 
+export { wrapConsole } from "./logs";
+
 export type {
   SandboxConfig,
   RegisterSandboxOptions,

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.",
         ),

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<string | undefined>;
   getCallerLocation: () => CallerLocation | undefined;
+  formatLogMessage?: (...args: unknown[]) => string;
   newAsyncLocalStorage: <T>() => IsoAsyncLocalStorage<T>;
   // 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;

js/src/logger.ts

@@ -1,6 +1,13 @@
 /// <reference lib="dom" />
 
 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<IsAsyncFlush extends boolean> implements Exportable {
   private lastStartTime: number;
   private lazyId: LazyValue<string>;
   private calledStartSpan: boolean;
+  private baselineTraceId?: string;
 
   // For type identification.
   public kind = "logger" as const;
@@ -2983,6 +2991,125 @@ export class Logger<IsAsyncFlush extends boolean> 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<IsAsyncFlush, string> {
+    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<IsAsyncFlush, string>;
+    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<IsAsyncFlush, string> {
+    return this.emitLog(body, "trace", options);
+  }
+
+  /** Capture a debug-level application log. Supports {@link Logger.fmt} templates. */
+  public debug(
+    body: unknown,
+    options?: ApplicationLogOptions,
+  ): PromiseUnless<IsAsyncFlush, string> {
+    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<IsAsyncFlush, string> {
+    return this.emitLog(body, "info", options);
+  }
+
+  /** Capture a warn-level application log. Supports {@link Logger.fmt} templates. */
+  public warn(
+    body: unknown,
+    options?: ApplicationLogOptions,
+  ): PromiseUnless<IsAsyncFlush, string> {
+    return this.emitLog(body, "warn", options);
+  }
+
+  /** Capture an error-level application log. Supports {@link Logger.fmt} templates. */
+  public error(
+    body: unknown,
+    options?: ApplicationLogOptions,
+  ): PromiseUnless<IsAsyncFlush, string> {
+    return this.emitLog(body, "error", options);
+  }
+
+  /** Capture a fatal-level application log. Supports {@link Logger.fmt} templates. */
+  public fatal(
+    body: unknown,
+    options?: ApplicationLogOptions,
+  ): PromiseUnless<IsAsyncFlush, string> {
+    return this.emitLog(body, "fatal", options);
+  }
+
   /**
    * Create a new toplevel span underneath the logger. The name defaults to "root".
    *

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 },
+    );
+  }
+}