diff --git a/.changeset/lucky-pugs-listen.md b/.changeset/lucky-pugs-listen.md new file mode 100644 index 000000000..e12911a68 --- /dev/null +++ b/.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. diff --git a/packages/eve/scripts/vendor-compiled/declarations/@opentelemetry/api.d.ts b/packages/eve/scripts/vendor-compiled/declarations/@opentelemetry/api.d.ts index 0e34fca17..f66a3f894 100644 --- a/packages/eve/scripts/vendor-compiled/declarations/@opentelemetry/api.d.ts +++ b/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): this; end(): void; + isRecording(): boolean; recordException(exception: unknown): void; setAttribute(key: string, value: unknown): this; setStatus(status: { code: SpanStatusCode; message?: string | undefined }): this; diff --git a/packages/eve/src/internal/logging.test.ts b/packages/eve/src/internal/logging.test.ts index 8b1871580..d9817c8dd 100644 --- a/packages/eve/src/internal/logging.test.ts +++ b/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(); + return { + ...actual, + trace: { ...actual.trace, getActiveSpan: () => activeSpan }, + }; +}); + // --------------------------------------------------------------------------- // createErrorId // --------------------------------------------------------------------------- @@ -297,3 +311,115 @@ describe("logError", () => { }); }); }); + +// --------------------------------------------------------------------------- +// span recording guard +// --------------------------------------------------------------------------- + +interface FakeSpan { + addEvent: ReturnType; + recordException: ReturnType; + setStatus: ReturnType; + 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); + }); +}); diff --git a/packages/eve/src/internal/logging.ts b/packages/eve/src/internal/logging.ts index bda9fa52e..3f92dea45 100644 --- a/packages/eve/src/internal/logging.ts +++ b/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; }