Properly manage nested spans (#40)

examples/otel/test/otel_test.exs

@@ -21,6 +21,37 @@ defmodule OtelTest do
 
     assert log =~ "[warning] Unexpected throttle setting for group `:weather_reports` → nil"
 
+    # nested span
+    assert_receive {:span,
+                    {:span, _, _, {:tracestate, []}, link, "otel.do_f_to_c", :internal, _, _,
+                     {:attributes, 128, :infinity, 0,
+                      %{
+                        "args_fahrenheit" => 451,
+                        "context_conditional" => nil,
+                        "context_options_group" => :weather_reports,
+                        "context_options_level" => :info,
+                        "env_file" => _,
+                        "env_line" => 13,
+                        "env_module" => Otel,
+                        "result" => 232.77777777777777,
+                        "measurements_consumed" => _,
+                        "measurements_system_time_monotonic" => _,
+                        "measurements_system_time_system" => _,
+                        "telemetria_group" => :weather_reports
+                      }},
+                     {:events, 128, 128, :infinity, 0,
+                      [
+                        {:event, _, "otel.do_f_to_c@" <> _, {:attributes, 128, :infinity, 0, %{}}}
+                      ]},
+                     {:links, 128, 128, :infinity, 0,
+                      [
+                        {:link, _, _, {:attributes, 128, :infinity, 0, %{}}, {:tracestate, []}}
+                      ]}, :undefined, 1, false,
+                     {:instrumentation_scope, "telemetria", _, :undefined}}}
+                   when is_integer(link),
+                   1000
+
+    # parent span
     assert_receive {:span,
                     {:span, _, _, {:tracestate, []}, :undefined, "otel.f_to_c", :internal, _, _,
                      {:attributes, 128, :infinity, 0,
@@ -43,7 +74,7 @@ defmodule OtelTest do
                      {:events, 128, 128, :infinity, 0,
                       [
                         {:event, _, "otel.f_to_c@" <> _, {:attributes, 128, :infinity, 0, %{}}}
-                      ]}, {:links, 128, 128, :infinity, 0, []}, :undefined, 1, false,
+                      ]}, {:links, 128, 128, :infinity, 1, []}, :undefined, 1, false,
                      {:instrumentation_scope, "telemetria", _, :undefined}}},
                    1000
   end

lib/telemetria.ex

@@ -375,6 +375,8 @@ defmodule Telemetria do
               unquote(group),
               {block_ctx, %{system_time: now, consumed: benchmark}, attributes, unquote(reshape)}
             )
+
+            Backend.exit(block_ctx)
           end
 
           result

lib/telemetria/backend.ex

@@ -23,13 +23,16 @@ defmodule Telemetria.Backend do
   @type block_metadata :: map()
 
   @doc "The implementation will be called when the block gets entered"
-  @callback entry(block_id()) :: block_context()
+  @callback entry(block_id()) :: block_context() | [block_context()]
 
   @doc "The implementation will be called when the block gets exited / executed"
-  @callback return(block_context(), block_context()) :: :ok
+  @callback return(block_context(), block_context()) :: block_context() | [block_context()]
 
   @doc "The implementation will be called when the block context is to be updated"
-  @callback update(block_context(), block_metadata()) :: block_context()
+  @callback update(block_context(), block_metadata()) :: block_context() | [block_context()]
+
+  @doc "The implementation will be called when the block context is to be exited"
+  @callback exit(block_context()) :: :ok
 
   @doc "The implementation will be called to reshape the event before sending it to the actual handler"
   @callback reshape(block_metadata()) :: block_metadata()
@@ -47,6 +50,9 @@ defmodule Telemetria.Backend do
       @doc false
       defdelegate update(block_context, updates), to: @implementation
       @doc false
+      defdelegate exit(block_context), to: @implementation
+      @doc false
+      # credo:disable-for-lines:4 Credo.Check.Refactor.Apply
       def reshape(updates) do
         if function_exported?(@implementation, :reshape, 1),
           do: apply(@implementation, :reshape, [updates]),
@@ -60,15 +66,19 @@ defmodule Telemetria.Backend do
 
       @doc false
       def entry(block_id),
-        do: Enum.each(@implementation, & &1.entry(block_id))
+        do: Enum.map(@implementation, & &1.entry(block_id))
 
       @doc false
       def return(block_context, context),
-        do: Enum.each(@implementation, & &1.return(block_context, context))
+        do: Enum.map(@implementation, & &1.return(block_context, context))
 
       @doc false
       def update(block_context, updates),
-        do: Enum.each(@implementation, & &1.update(block_context, updates))
+        do: Enum.map(@implementation, & &1.update(block_context, updates))
+
+      @doc false
+      def exit(block_context),
+        do: Enum.each(@implementation, & &1.exit(block_context))
 
       @doc false
       def reshape(updates), do: updates

lib/telemetria/backend/open_telemetry.ex

@@ -13,13 +13,18 @@ case {Telemetria.Application.open_telemetry?(), Code.ensure_compiled(OpenTelemet
 
       @impl true
       def entry(block_id) do
-        OpenTelemetry.Ctx.get_current()
-        |> OpenTelemetry.Ctx.attach()
+        # https://opentelemetry.io/docs/languages/erlang/instrumentation/
+        token = OpenTelemetry.Ctx.get_current() |> OpenTelemetry.Ctx.attach()
+        parent = OpenTelemetry.Tracer.current_span_ctx()
+        link = OpenTelemetry.link(parent)
 
-        block_id
-        |> fix_block_id()
-        |> Tracer.start_span()
-        |> tap(&Tracer.set_current_span/1)
+        block_ctx =
+          block_id
+          |> fix_block_id()
+          |> Tracer.start_span(%{links: [link]})
+          |> tap(&Tracer.set_current_span/1)
+
+        {token, parent, block_ctx}
       end
 
       @impl true
@@ -34,14 +39,19 @@ case {Telemetria.Application.open_telemetry?(), Code.ensure_compiled(OpenTelemet
       end
 
       @impl true
-      def return(block_ctx, context) do
+      def return({_token, _parent, block_ctx}, context) do
         Span.set_attributes(block_ctx, context)
         Span.end_span(block_ctx)
-        OpenTelemetry.Ctx.detach(block_ctx)
 
         :ok
       end
 
+      @impl true
+      def exit({token, parent, _block_ctx}) do
+        OpenTelemetry.Ctx.detach(token)
+        Tracer.set_current_span(parent)
+      end
+
       @impl true
       def reshape(updates),
         do: Estructura.Flattenable.flatten(updates, jsonify: true)

lib/telemetria/backend/telemetry.ex

@@ -19,6 +19,9 @@ case {Telemetria.Application.telemetry?(), Code.ensure_compiled(:telemetry)} do
         :telemetry.execute(block_id, measurements, metadata)
       end
 
+      @impl true
+      def exit(_block_id), do: :ok
+
       @impl true
       def reshape(updates), do: updates
     end