fix(eve): skip span writes after the span has ended

.changeset/lucky-pugs-listen.md

@@ -0,0 +1,5 @@
+---
+"eve": patch
+---
+
+Fixed non-fatal "Operation attempted on ended Span" errors on long-running self-hosted deployments. Error logs emitted after a turn's OpenTelemetry span ended are now dropped instead of writing to the ended span.

packages/eve/scripts/vendor-compiled/declarations/@opentelemetry/api.d.ts

@@ -8,6 +8,7 @@ export interface SpanContext {
 export interface Span {
   addEvent(name: string, attributes?: Record<string, unknown>): this;
   end(): void;
+  isRecording(): boolean;
   recordException(exception: unknown): void;
   setAttribute(key: string, value: unknown): this;
   setStatus(status: { code: SpanStatusCode; message?: string | undefined }): this;

packages/eve/src/internal/logging.test.ts

@@ -1,14 +1,28 @@
 import { afterEach, beforeEach, describe, expect, it, vi } from "vitest";
 
+import type { Span } from "#compiled/@opentelemetry/api/index.js";
+import { SpanStatusCode } from "#compiled/@opentelemetry/api/index.js";
 import {
   createErrorId,
   createLogger,
   formatError,
   logError,
+  recordErrorOnSpan,
   setLogRecordSubscriber,
   type LogRecord,
 } from "#internal/logging.js";
 
+/** Active span seen by the logger; `undefined` keeps span recording off. */
+let activeSpan: Span | undefined;
+
+vi.mock("#compiled/@opentelemetry/api/index.js", async (importOriginal) => {
+  const actual = await importOriginal<typeof import("#compiled/@opentelemetry/api/index.js")>();
+  return {
+    ...actual,
+    trace: { ...actual.trace, getActiveSpan: () => activeSpan },
+  };
+});
+
 // ---------------------------------------------------------------------------
 // createErrorId
 // ---------------------------------------------------------------------------
@@ -297,3 +311,115 @@ describe("logError", () => {
     });
   });
 });
+
+// ---------------------------------------------------------------------------
+// span recording guard
+// ---------------------------------------------------------------------------
+
+interface FakeSpan {
+  addEvent: ReturnType<typeof vi.fn>;
+  recordException: ReturnType<typeof vi.fn>;
+  setStatus: ReturnType<typeof vi.fn>;
+  span: Span;
+}
+
+/**
+ * Mirrors the OTel SDK: a span that has ended is no longer recording, and
+ * mutating it logs "Operation attempted on ended Span" — modeled here as a
+ * throw so any unguarded write fails the test loudly.
+ */
+function makeFakeSpan(isRecording: boolean): FakeSpan {
+  const mutate = (name: string) =>
+    vi.fn((..._args: unknown[]) => {
+      if (!isRecording) {
+        throw new Error(`Operation attempted on ended Span: ${name}`);
+      }
+    });
+  const addEvent = mutate("addEvent");
+  const recordException = mutate("recordException");
+  const setStatus = mutate("setStatus");
+  const setAttribute = mutate("setAttribute");
+
+  const span: Span = {
+    addEvent(name, attributes) {
+      addEvent(name, attributes);
+      return this;
+    },
+    end() {},
+    isRecording: () => isRecording,
+    recordException(exception) {
+      recordException(exception);
+    },
+    setAttribute(key, value) {
+      setAttribute(key, value);
+      return this;
+    },
+    setStatus(status) {
+      setStatus(status);
+      return this;
+    },
+    spanContext: () => ({ spanId: "span-id", traceFlags: 1, traceId: "trace-id" }),
+  };
+
+  return { addEvent, recordException, setStatus, span };
+}
+
+describe("span recording guard", () => {
+  beforeEach(() => {
+    vi.spyOn(console, "error").mockImplementation(() => {});
+  });
+
+  afterEach(() => {
+    activeSpan = undefined;
+    vi.restoreAllMocks();
+  });
+
+  it("skips writes to an ended active span", () => {
+    const span = makeFakeSpan(false);
+    activeSpan = span.span;
+
+    expect(() => createLogger("ns").error("boom", { error: new Error("x") })).not.toThrow();
+
+    expect(span.setStatus).not.toHaveBeenCalled();
+    expect(span.recordException).not.toHaveBeenCalled();
+    expect(span.addEvent).not.toHaveBeenCalled();
+  });
+
+  it("skips writes to an ended span passed directly", () => {
+    const span = makeFakeSpan(false);
+
+    expect(() => recordErrorOnSpan(span.span, new Error("x"))).not.toThrow();
+
+    expect(span.setStatus).not.toHaveBeenCalled();
+    expect(span.recordException).not.toHaveBeenCalled();
+  });
+
+  it("still records an error on a recording active span", () => {
+    const span = makeFakeSpan(true);
+    activeSpan = span.span;
+
+    createLogger("ns").error("boom", { error: new Error("x") });
+
+    expect(span.setStatus).toHaveBeenCalledWith({ code: SpanStatusCode.ERROR, message: "x" });
+    expect(span.recordException).toHaveBeenCalledTimes(1);
+  });
+
+  it("still adds an event on a recording active span when no error is present", () => {
+    const span = makeFakeSpan(true);
+    activeSpan = span.span;
+
+    createLogger("ns").error("plain", { foo: "bar" });
+
+    expect(span.addEvent).toHaveBeenCalledWith("plain", { foo: "bar" });
+    expect(span.setStatus).not.toHaveBeenCalled();
+  });
+
+  it("still records on a recording span passed directly", () => {
+    const span = makeFakeSpan(true);
+
+    recordErrorOnSpan(span.span, new Error("x"));
+
+    expect(span.setStatus).toHaveBeenCalledWith({ code: SpanStatusCode.ERROR, message: "x" });
+    expect(span.recordException).toHaveBeenCalledTimes(1);
+  });
+});

packages/eve/src/internal/logging.ts

@@ -228,6 +228,13 @@ function truncateForDisplay(value: string, maxChars = 160): string {
  * non-active span should be annotated.
  */
 export function recordErrorOnSpan(span: Span, error: unknown): void {
+  // The harness turn span is ended in a `finally` while still the active
+  // span, so an error log scheduled on a late continuation can reach here
+  // after the end. Writing then makes the OTel SDK log at error level (#776).
+  if (!span.isRecording()) {
+    return;
+  }
+
   const message = error instanceof Error ? error.message : getErrorMessage(error);
   const name = error instanceof Error ? error.name : "Error";
 
@@ -351,7 +358,7 @@ function renderFields(fields: LogFields): JsonObject {
 
 function recordOnActiveSpan(message: string, fields?: LogFields): void {
   const span = trace.getActiveSpan();
-  if (span === undefined) {
+  if (span === undefined || !span.isRecording()) {
     return;
   }