Add logs to first propagated span (#5710)

Author: mikearnaldi

.changeset/fast-shoes-appear.md

@@ -0,0 +1,17 @@
+---
+"@effect/opentelemetry": patch
+"effect": patch
+---
+
+Add logs to first propagated span, in the following case before this fix the log would not be added to the `p` span because `Effect.fn` adds a fake span for the purpose of adding a stack frame.
+
+```ts
+import { Effect } from "effect"
+
+const f = Effect.fn(function* () {
+  yield* Effect.logWarning("FooBar")
+  return yield* Effect.fail("Oops")
+})
+
+const p = f().pipe(Effect.withSpan("p"))
+```

.changeset/violet-years-stare.md

@@ -0,0 +1,5 @@
+---
+"effect": minor
+---
+
+Fix annotateCurrentSpan, add Effect.currentPropagatedSpan

packages/effect/src/Effect.ts

@@ -12998,6 +12998,12 @@ export const annotateCurrentSpan: {
  */
 export const currentSpan: Effect<Tracer.Span, Cause.NoSuchElementException> = effect.currentSpan
 
+/**
+ * @since 3.20.0
+ * @category Tracing
+ */
+export const currentPropagatedSpan: Effect<Tracer.Span, Cause.NoSuchElementException> = effect.currentPropagatedSpan
+
 /**
  * @since 2.0.0
  * @category Tracing

packages/effect/src/internal/core-effect.ts

@@ -1966,7 +1966,7 @@ export const annotateCurrentSpan: {
 } = function(): Effect.Effect<void> {
   const args = arguments
   return ignore(core.flatMap(
-    currentSpan,
+    currentPropagatedSpan,
     (span) =>
       core.sync(() => {
         if (typeof args[0] === "string") {
@@ -2041,6 +2041,16 @@ export const currentSpan: Effect.Effect<Tracer.Span, Cause.NoSuchElementExceptio
   }
 )
 
+export const currentPropagatedSpan: Effect.Effect<Tracer.Span, Cause.NoSuchElementException> = core.flatMap(
+  core.context<never>(),
+  (context) => {
+    const span = filterDisablePropagation(Context.getOption(context, internalTracer.spanTag))
+    return span._tag === "Some" && span.value._tag === "Span"
+      ? core.succeed(span.value)
+      : core.fail(new core.NoSuchElementException())
+  }
+)
+
 /* @internal */
 export const linkSpans = dual<
   (
@@ -2070,12 +2080,13 @@ export const linkSpans = dual<
 
 const bigint0 = BigInt(0)
 
-const filterDisablePropagation: (self: Option.Option<Tracer.AnySpan>) => Option.Option<Tracer.AnySpan> = Option.flatMap(
-  (span) =>
-    Context.get(span.context, internalTracer.DisablePropagation)
-      ? span._tag === "Span" ? filterDisablePropagation(span.parent) : Option.none()
-      : Option.some(span)
-)
+export const filterDisablePropagation: (self: Option.Option<Tracer.AnySpan>) => Option.Option<Tracer.AnySpan> = Option
+  .flatMap(
+    (span) =>
+      Context.get(span.context, internalTracer.DisablePropagation)
+        ? span._tag === "Span" ? filterDisablePropagation(span.parent) : Option.none()
+        : Option.some(span)
+  )
 
 /** @internal */
 export const unsafeMakeSpan = <XA, XE>(

packages/effect/src/internal/fiberRuntime.ts

@@ -1517,13 +1517,15 @@ export const tracerLogger = globalValue(
       logLevel,
       message
     }) => {
-      const span = Context.getOption(
+      const span = internalEffect.filterDisablePropagation(Context.getOption(
         fiberRefs.getOrDefault(context, core.currentContext),
         tracer.spanTag
-      )
+      ))
+
       if (span._tag === "None" || span.value._tag === "ExternalSpan") {
         return
       }
+
       const clockService = Context.unsafeGet(
         fiberRefs.getOrDefault(context, defaultServices.currentServices),
         clock.clockTag

packages/opentelemetry/test/Tracer.test.ts

@@ -4,16 +4,27 @@ import { assert, describe, expect, it } from "@effect/vitest"
 import * as OtelApi from "@opentelemetry/api"
 import { AsyncHooksContextManager } from "@opentelemetry/context-async-hooks"
 import { InMemorySpanExporter, SimpleSpanProcessor } from "@opentelemetry/sdk-trace-base"
+import * as Console from "effect/Console"
 import * as Effect from "effect/Effect"
+import * as FiberRef from "effect/FiberRef"
+import * as Layer from "effect/Layer"
 import * as Runtime from "effect/Runtime"
 import { OtelSpan } from "../src/internal/tracer.js"
 
-const TracingLive = NodeSdk.layer(Effect.sync(() => ({
-  resource: {
-    serviceName: "test"
-  },
-  spanProcessor: [new SimpleSpanProcessor(new InMemorySpanExporter())]
-})))
+class Exporter extends Effect.Service<Exporter>()("Exporter", {
+  effect: Effect.sync(() => ({ exporter: new InMemorySpanExporter() }))
+}) {}
+
+const TracingLive = Layer.unwrapEffect(Effect.gen(function*() {
+  const { exporter } = yield* Exporter
+
+  return NodeSdk.layer(Effect.sync(() => ({
+    resource: {
+      serviceName: "test"
+    },
+    spanProcessor: [new SimpleSpanProcessor(exporter)]
+  })))
+})).pipe(Layer.provideMerge(Exporter.Default))
 
 // needed to test context propagation
 const contextManager = new AsyncHooksContextManager()
@@ -123,4 +134,59 @@ describe("Tracer", () => {
         })
       ))
   })
+
+  describe("Log Attributes", () => {
+    it.effect("propagates attributes with Effect.fnUntraced", () =>
+      Effect.gen(function*() {
+        const f = Effect.fnUntraced(function*() {
+          yield* Effect.logWarning("FooBar")
+          return yield* Effect.fail("Oops")
+        })
+
+        const p = f().pipe(Effect.withSpan("p"))
+
+        yield* Effect.ignore(p)
+
+        const { exporter } = yield* Exporter
+
+        assert.isNotEmpty(exporter.getFinishedSpans()[0].events.filter((_) => _.name === "FooBar"))
+        assert.isNotEmpty(exporter.getFinishedSpans()[0].events.filter((_) => _.name === "exception"))
+      }).pipe(Effect.provide(TracingLive)))
+
+    it.effect("propagates attributes with Effect.fn(name)", () =>
+      Effect.gen(function*() {
+        const f = Effect.fn("f")(function*() {
+          yield* Effect.logWarning("FooBar")
+          return yield* Effect.fail("Oops")
+        })
+
+        const p = f().pipe(Effect.withSpan("p"))
+
+        yield* Effect.ignore(p)
+
+        const { exporter } = yield* Exporter
+
+        assert.isNotEmpty(exporter.getFinishedSpans()[0].events.filter((_) => _.name === "FooBar"))
+        assert.isNotEmpty(exporter.getFinishedSpans()[0].events.filter((_) => _.name === "exception"))
+      }).pipe(Effect.provide(TracingLive)))
+
+    it.effect("propagates attributes with Effect.fn", () =>
+      Effect.gen(function*() {
+        const f = Effect.fn(function*() {
+          yield* Effect.logWarning("FooBar")
+          return yield* Effect.fail("Oops")
+        })
+
+        const p = f().pipe(Effect.withSpan("p"))
+
+        yield* Effect.ignore(p)
+
+        const { exporter } = yield* Exporter
+
+        yield* Console.log(Array.from(yield* FiberRef.get(FiberRef.currentLoggers)))
+
+        assert.isNotEmpty(exporter.getFinishedSpans()[0].events.filter((_) => _.name === "FooBar"))
+        assert.isNotEmpty(exporter.getFinishedSpans()[0].events.filter((_) => _.name === "exception"))
+      }).pipe(Effect.provide(TracingLive)))
+  })
 })