feat(jest): emit test logs as otel logs

README.md

@@ -76,6 +76,11 @@ Test spans include `dagger.io/ui.boundary` plus OpenTelemetry test semantic conv
 
 Suite spans include `dagger.io/ui.boundary`, `test.suite.name`, and `test.suite.run.status`.
 
+### Test output
+
+Console output emitted with `console.log`, `console.info`, `console.debug`, `console.warn`,
+and `console.error` is exported as OpenTelemetry logs on the active test span.
+
 ### Installation
 
 Install `@dagger.io/jest` in your project

jest.dang

@@ -68,6 +68,7 @@ type Jest {
 
     # mount and install the otel library and then execute the tests
     runtime
+      .withEnvVariable("DAGGER_JEST_CACHE_BUSTER", UUID.v7)
       .withExec(["npx", "jest"] + flags + files)
       .sync
 

package.json

@@ -59,6 +59,7 @@
   "homepage": "https://github.com/dagger/jest",
   "dependencies": {
     "@dagger.io/telemetry": "^0.0.5",
+    "@opentelemetry/api-logs": "^0.209.0",
     "@opentelemetry/sdk-node": "^0.209.0",
     "@opentelemetry/semantic-conventions": "^1.29.0",
     "jest-environment-node": "^30.2.0",

src/wrapper.ts

@@ -1,8 +1,10 @@
+import { format } from "node:util";
 import { OtelSDK } from "@dagger.io/telemetry";
 import type { EnvironmentContext, JestEnvironmentConfig } from "@jest/environment";
 import type { Circus } from "@jest/types";
 import type { Attributes, Context, Span } from "@opentelemetry/api";
-import { context, SpanStatusCode, trace } from "@opentelemetry/api";
+import { context, isSpanContextValid, SpanStatusCode, trace } from "@opentelemetry/api";
+import { logs, SeverityNumber } from "@opentelemetry/api-logs";
 import {
   ATTR_TEST_CASE_NAME,
   ATTR_TEST_CASE_RESULT_STATUS,
@@ -16,10 +18,92 @@ import {
 } from "@opentelemetry/semantic-conventions/incubating";
 import type { TestEnvironment } from "jest-environment-node";
 
-const tracer = trace.getTracer("dagger.io/jest");
+__prepareLogExporterEnv();
 
 const JEST_ROOT_BLOCK_NAME = "ROOT_DESCRIBE_BLOCK";
 const ATTR_UI_BOUNDARY = "dagger.io/ui.boundary";
+const STDIO_STREAM_ATTR = "stdio.stream";
+const STDIO_STREAM_STDOUT = 1;
+const STDIO_STREAM_STDERR = 2;
+const __PATCHED_CONSOLE_METHOD = Symbol.for("dagger.io/jest.console.telemetry");
+let __emittingConsoleTelemetry = false;
+
+type ConsoleMethodName = "debug" | "error" | "info" | "log" | "warn";
+type ConsoleStream = "stderr" | "stdout";
+
+function __prepareLogExporterEnv(): void {
+  if (!process.env.OTEL_EXPORTER_OTLP_ENDPOINT) {
+    __setEnvIfUnset(
+      "OTEL_EXPORTER_OTLP_LOGS_ENDPOINT",
+      __logEndpoint(process.env.OTEL_EXPORTER_OTLP_TRACES_ENDPOINT),
+    );
+  }
+
+  __setEnvIfUnset(
+    "OTEL_EXPORTER_OTLP_LOGS_PROTOCOL",
+    process.env.OTEL_EXPORTER_OTLP_TRACES_PROTOCOL ?? process.env.OTEL_EXPORTER_OTLP_PROTOCOL,
+  );
+}
+
+function __setEnvIfUnset(name: string, value?: string): void {
+  if (process.env[name] === undefined && value !== undefined) {
+    process.env[name] = value;
+  }
+}
+
+function __logEndpoint(endpoint?: string): string | undefined {
+  const logEndpoint = endpoint?.replace(/\/v1\/traces\/?$/, "/v1/logs");
+  return logEndpoint !== endpoint ? logEndpoint : undefined;
+}
+
+function __tracer() {
+  return trace.getTracer("dagger.io/jest");
+}
+
+function __logger() {
+  return logs.getLogger("dagger.io/jest");
+}
+
+function __consoleTypeStream(type: string): ConsoleStream | undefined {
+  if (type === "error" || type === "warn") {
+    return "stderr";
+  }
+  if (type === "debug" || type === "info" || type === "log") {
+    return "stdout";
+  }
+  return undefined;
+}
+
+function __emitConsoleTelemetry(stream: ConsoleStream, body: string): void {
+  if (__emittingConsoleTelemetry) {
+    return;
+  }
+
+  const activeContext = context.active();
+  const activeSpan = trace.getSpan(activeContext);
+  if (!activeSpan || !isSpanContextValid(activeSpan.spanContext())) {
+    return;
+  }
+
+  __emittingConsoleTelemetry = true;
+  try {
+    __logger().emit({
+      timestamp: Date.now(),
+      observedTimestamp: Date.now(),
+      severityNumber: stream === "stderr" ? SeverityNumber.ERROR : SeverityNumber.INFO,
+      severityText: stream === "stderr" ? "ERROR" : "INFO",
+      body,
+      attributes: {
+        [STDIO_STREAM_ATTR]: stream === "stderr" ? STDIO_STREAM_STDERR : STDIO_STREAM_STDOUT,
+      },
+      context: activeContext,
+    });
+  } catch {
+    // Do not let telemetry log emission affect the test run.
+  } finally {
+    __emittingConsoleTelemetry = false;
+  }
+}
 
 // A function that take any jest environment and add otel instrumentation on existing tests.
 export function wrapEnvironmentClass(BaseEnv: typeof TestEnvironment): any {
@@ -76,8 +160,10 @@ export function wrapEnvironmentClass(BaseEnv: typeof TestEnvironment): any {
       const apiKey = Symbol.for("opentelemetry.js.api.1");
       (this.global as any)[apiKey] = (globalThis as any)[apiKey];
 
+      this.patchConsoleTelemetry();
+
       // Create a testspan and root context based on the test filename.
-      this.__topLevelSpan = tracer.startSpan(
+      this.__topLevelSpan = __tracer().startSpan(
         this.__testfile,
         {
           attributes: {
@@ -99,9 +185,11 @@ export function wrapEnvironmentClass(BaseEnv: typeof TestEnvironment): any {
       // the test span context so any span created inside it will be correctly
       // nested.
       if (event.name === "test_start") {
+        this.patchConsoleTelemetry();
+
         const ctx = this.getOrCreateContext(event.test.parent);
 
-        const testSpan = tracer.startSpan(
+        const testSpan = __tracer().startSpan(
           event.test.name,
           { attributes: this.testSpanAttributes(event.test) },
           ctx,
@@ -173,7 +261,7 @@ export function wrapEnvironmentClass(BaseEnv: typeof TestEnvironment): any {
         event.describeBlock.name !== JEST_ROOT_BLOCK_NAME
       ) {
         const ctx = this.getOrCreateContext(event.describeBlock.parent);
-        const span = tracer.startSpan(
+        const span = __tracer().startSpan(
           event.describeBlock.name,
           { attributes: this.testSuiteSpanAttributes(event.describeBlock) },
           ctx,
@@ -246,6 +334,116 @@ export function wrapEnvironmentClass(BaseEnv: typeof TestEnvironment): any {
     // Utility functions
     //////
 
+    patchConsoleTelemetry(): void {
+      const testConsole = (this.global as any).console;
+      if (!testConsole) {
+        return;
+      }
+
+      if (this.patchBufferedConsole(testConsole)) {
+        return;
+      }
+
+      if (this.patchJestConsole(testConsole)) {
+        return;
+      }
+
+      this.patchConsoleMethod(testConsole, "debug", "stdout");
+      this.patchConsoleMethod(testConsole, "info", "stdout");
+      this.patchConsoleMethod(testConsole, "log", "stdout");
+      this.patchConsoleMethod(testConsole, "warn", "stderr");
+      this.patchConsoleMethod(testConsole, "error", "stderr");
+    }
+
+    patchBufferedConsole(testConsole: any): boolean {
+      const consoleCtor = testConsole.constructor as
+        | { write?: ((...args: any[]) => any) & { [__PATCHED_CONSOLE_METHOD]?: boolean } }
+        | undefined;
+      const current = consoleCtor?.write;
+
+      if (!consoleCtor || typeof current !== "function") {
+        return false;
+      }
+      if (current[__PATCHED_CONSOLE_METHOD]) {
+        return true;
+      }
+
+      const patched = function patchedBufferedConsoleWrite(this: any, ...args: any[]) {
+        const [, type, message] = args;
+        const stream = __consoleTypeStream(String(type));
+        if (stream) {
+          __emitConsoleTelemetry(
+            stream,
+            `${typeof message === "string" ? message : format(message)}\n`,
+          );
+        }
+        return current.apply(this, args);
+      } as typeof current;
+
+      patched[__PATCHED_CONSOLE_METHOD] = true;
+      consoleCtor.write = patched;
+      return true;
+    }
+
+    patchJestConsole(testConsole: any): boolean {
+      let patched = false;
+      patched = this.patchJestConsoleMethod(testConsole, "_log", "stdout") || patched;
+      patched = this.patchJestConsoleMethod(testConsole, "_logError", "stderr") || patched;
+      return patched;
+    }
+
+    patchJestConsoleMethod(
+      testConsole: any,
+      method: string,
+      fallbackStream: ConsoleStream,
+    ): boolean {
+      const current = testConsole[method] as
+        | (((...args: any[]) => any) & {
+            [__PATCHED_CONSOLE_METHOD]?: boolean;
+          })
+        | undefined;
+
+      if (typeof current !== "function") {
+        return false;
+      }
+      if (current[__PATCHED_CONSOLE_METHOD]) {
+        return true;
+      }
+
+      const patched = function patchedJestConsoleMethod(this: any, ...args: any[]) {
+        const [type, message] = args;
+        const stream = __consoleTypeStream(String(type)) ?? fallbackStream;
+        __emitConsoleTelemetry(
+          stream,
+          `${typeof message === "string" ? message : format(message)}\n`,
+        );
+        return current.apply(this, args);
+      } as typeof current;
+
+      patched[__PATCHED_CONSOLE_METHOD] = true;
+      testConsole[method] = patched;
+      return true;
+    }
+
+    patchConsoleMethod(testConsole: any, method: ConsoleMethodName, stream: ConsoleStream): void {
+      const current = testConsole[method] as
+        | (((...args: any[]) => void) & { [__PATCHED_CONSOLE_METHOD]?: boolean })
+        | undefined;
+
+      if (typeof current !== "function" || current[__PATCHED_CONSOLE_METHOD]) {
+        return;
+      }
+
+      const original = current.bind(testConsole);
+      const patched = ((...args: any[]) => {
+        __emitConsoleTelemetry(stream, `${format(...args)}\n`);
+        return original(...args);
+      }) as typeof current;
+
+      patched[__PATCHED_CONSOLE_METHOD] = true;
+      testConsole[method] = patched;
+    }
+
     /**
      * Return the attributes for a Jest test case span.
      */

tests/log_output_toolchain_local/dagger.json

@@ -0,0 +1,16 @@
+{
+  "name": "jest-log-output",
+  "engineVersion": "v0.19.10",
+  "toolchains": [
+    {
+      "name": "jest",
+      "source": "../../",
+      "customizations": [
+        {
+          "argument": "source",
+          "defaultPath": "/tests/log_output_toolchain_local"
+        }
+      ]
+    }
+  ]
+}

tests/log_output_toolchain_local/log-output.test.js

@@ -0,0 +1,26 @@
+const delay = (ms) => new Promise((resolve) => setTimeout(resolve, ms));
+
+describe("OTel log routing example", () => {
+  test("routes stdout and stderr to the first test", () => {
+    console.log("[otel-log-routing:first] stdout from first test");
+    console.error("[otel-log-routing:first] stderr from first test");
+
+    expect(true).toBe(true);
+  });
+
+  test("routes async logs to the second test", async () => {
+    console.log("[otel-log-routing:second] stdout before await");
+    await delay(25);
+    console.error("[otel-log-routing:second] stderr after await");
+
+    expect(1 + 1).toBe(2);
+  });
+
+  describe("nested suite", () => {
+    test("keeps nested test logs under the nested test", () => {
+      console.log("[otel-log-routing:nested] stdout from nested test");
+
+      expect("nested").toContain("nest");
+    });
+  });
+});

tests/log_output_toolchain_local/package.json

@@ -0,0 +1,13 @@
+{
+  "name": "jest-log-output-example",
+  "version": "1.0.0",
+  "private": true,
+  "type": "module",
+  "scripts": {
+    "test": "NODE_OPTIONS=\"$NODE_OPTIONS --experimental-vm-modules --import @dagger.io/jest/register\" jest"
+  },
+  "devDependencies": {
+    "@dagger.io/jest": "file:../..",
+    "jest": "^30.2.0"
+  }
+}