Bandit: Start span when connection starts rather than retroactively

This ensures that spans created in application code are correctly
parented to the request span.

instrumentation/opentelemetry_bandit/lib/opentelemetry_bandit.ex

@@ -3,20 +3,31 @@ defmodule OpentelemetryBandit do
   OpentelemetryBandit uses [telemetry](https://hexdocs.pm/telemetry/) handlers to create `OpenTelemetry` spans.
 
   Supported:
-  1. :bandit, :request, :stop
+  1. :bandit, :request, :start
-  2. :bandit, :request, :exception
+  2. :bandit, :request, :stop
-  3. :bandit, :websocket, :stop
+  3. :bandit, :request, :exception
+  4. :bandit, :websocket, :start
+  5. :bandit, :websocket, :stop
   """
 
   alias OpenTelemetry.SemanticConventions.Trace
   require Trace
   require OpenTelemetry.Tracer
 
+  @tracer_id __MODULE__
+
   @doc """
   Initializes and configures the telemetry handlers.
   """
   @spec setup(any) :: :ok
   def setup(_opts \\ []) do
+    :telemetry.attach(
+      {__MODULE__, :request_start},
+      [:bandit, :request, :start],
+      &__MODULE__.handle_request_start/4,
+      %{}
+    )
+
     :telemetry.attach(
       {__MODULE__, :request_stop},
       [:bandit, :request, :stop],
@@ -31,6 +42,13 @@ defmodule OpentelemetryBandit do
       %{}
     )
 
+    :telemetry.attach(
+      {__MODULE__, :websocket_start},
+      [:bandit, :websocket, :start],
+      &__MODULE__.handle_websocket_start/4,
+      %{}
+    )
+
     :telemetry.attach(
       {__MODULE__, :websocket_stop},
       [:bandit, :websocket, :stop],
@@ -39,11 +57,8 @@ defmodule OpentelemetryBandit do
     )
   end
 
-  def handle_request_stop(_event, measurements, meta, _config) do
+  def handle_request_start(_event, measurements, meta, _config) do
     conn = Map.get(meta, :conn)
-    duration = measurements.duration
-    end_time = :opentelemetry.timestamp()
-    start_time = end_time - duration
 
     url = extract_url(meta, conn)
     request_path = extract_request_path(meta, conn)
@@ -52,10 +67,8 @@ defmodule OpentelemetryBandit do
       if Map.has_key?(meta, :error) do
         %{
           Trace.http_url() => url,
-          Trace.http_method() => conn.method,
+          Trace.http_method() => Map.get(conn, :method),
-          Trace.net_transport() => :"IP.TCP",
+          Trace.net_transport() => :"IP.TCP"
-          Trace.http_response_content_length() => Map.get(measurements, :resp_body_bytes),
-          Trace.http_status_code() => conn.status
         }
       else
         %{
@@ -66,8 +79,6 @@ defmodule OpentelemetryBandit do
           Trace.net_peer_port() => conn.port,
           Trace.http_target() => conn.request_path,
           Trace.http_method() => conn.method,
-          Trace.http_status_code() => conn.status,
-          Trace.http_response_content_length() => Map.get(measurements, :resp_body_bytes),
           Trace.net_transport() => :"IP.TCP",
           Trace.http_user_agent() => user_agent(conn)
         }
@@ -77,59 +88,78 @@ defmodule OpentelemetryBandit do
 
     span_id = "HTTP #{conn.method} #{request_path}" |> String.trim()
 
-    OpenTelemetry.Tracer.start_span(span_id, %{
+    OpentelemetryTelemetry.start_telemetry_span(@tracer_id, span_id, meta, %{
       attributes: attributes,
-      start_time: start_time,
+      start_time: measurements.monotonic_time,
-      end_time: end_time,
       kind: span_kind
     })
-    |> set_span_status(meta, Map.get(meta, :error, ""))
+  end
-    |> OpenTelemetry.Span.end_span()
 
-    OpenTelemetry.Ctx.clear()
+  def handle_request_stop(_event, measurements, meta, _config) do
+    conn = Map.get(meta, :conn)
+
+    OpentelemetryTelemetry.set_current_telemetry_span(@tracer_id, meta)
+
+    attributes =
+      if Map.has_key?(meta, :error) do
+        %{}
+      else
+        %{
+          Trace.http_status_code() => Map.get(conn, :status),
+          Trace.http_response_content_length() => Map.get(measurements, :resp_body_bytes)
+        }
+      end
+
+    attributes = Map.put(attributes, :duration, measurements.duration)
+
+    OpenTelemetry.Tracer.set_attributes(attributes)
+
+    if Map.get(attributes, Trace.http_status_code()) >= 500 do
+      OpenTelemetry.Tracer.set_status(OpenTelemetry.status(:error))
+    end
+
+    OpentelemetryTelemetry.end_telemetry_span(@tracer_id, meta)
   end
 
   def handle_request_exception(_event, _measurements, meta, _config) do
-    OpenTelemetry.Tracer.start_span("HTTP exception #{inspect(meta.exception.__struct__)}", %{
+    OpentelemetryTelemetry.set_current_telemetry_span(@tracer_id, meta)
-      kind: :error,
-      status: :error
-    })
-    |> set_span_status(meta, inspect(meta.stacktrace))
-    |> OpenTelemetry.Span.end_span()
 
-    OpenTelemetry.Ctx.clear()
+    OpenTelemetry.Tracer.set_status(OpenTelemetry.status(:error))
+    OpenTelemetry.Tracer.record_exception(meta.exception, meta.stacktrace)
+
+    OpentelemetryTelemetry.end_telemetry_span(@tracer_id, meta)
   end
 
-  def handle_websocket_stop(_event, measurements, meta, _config) do
+  def handle_websocket_start(_event, measurements, meta, _config) do
-    duration = measurements.duration
-    end_time = :opentelemetry.timestamp()
-    start_time = end_time - duration
-
     attributes = %{
-      :"websocket.recv.binary.frame.bytes" => Map.get(measurements, :send_binary_frame_bytes, 0),
-      :"websocket.send.binary.frame.bytes" => Map.get(measurements, :recv_binary_frame_bytes, 0),
       Trace.net_transport() => :websocket
     }
 
     span_kind = if Map.has_key?(meta, :error), do: :error, else: :server
 
-    OpenTelemetry.Tracer.start_span("Websocket", %{
+    OpentelemetryTelemetry.start_telemetry_span(@tracer_id, "Websocket", meta, %{
       attributes: attributes,
-      start_time: start_time,
+      start_time: measurements.monotonic_time,
-      end_time: end_time,
       kind: span_kind
     })
-    |> set_span_status(meta, Map.get(meta, :error, ""))
-    |> OpenTelemetry.Span.end_span()
-
-    OpenTelemetry.Ctx.clear()
   end
 
-  defp set_span_status(span, meta, message) do
+  def handle_websocket_stop(_event, measurements, meta, _config) do
-    status = if Map.has_key?(meta, :error) || message != "", do: :error, else: :ok
+    OpentelemetryTelemetry.set_current_telemetry_span(@tracer_id, meta)
 
-    OpenTelemetry.Span.set_status(span, OpenTelemetry.status(status, message))
+    attributes = %{
-    span
+      :"websocket.recv.binary.frame.bytes" => Map.get(measurements, :send_binary_frame_bytes, 0),
+      :"websocket.send.binary.frame.bytes" => Map.get(measurements, :recv_binary_frame_bytes, 0),
+      :duration => measurements.duration
+    }
+
+    OpenTelemetry.Tracer.set_attributes(attributes)
+
+    if Map.has_key?(meta, :error) do
+      OpenTelemetry.Tracer.set_status(OpenTelemetry.status(:error, meta.error))
+    end
+
+    OpentelemetryTelemetry.end_telemetry_span(@tracer_id, meta)
   end
 
   defp extract_url(%{error: _} = meta, _conn) do

instrumentation/opentelemetry_phoenix/lib/opentelemetry_phoenix.ex

@@ -161,7 +161,7 @@ defmodule OpentelemetryPhoenix do
         cowboy2_start()
 
       :bandit ->
-        bandit_start()
+        :ok
 
       _ ->
         default_start(meta)
@@ -173,11 +173,6 @@ defmodule OpentelemetryPhoenix do
     |> OpenTelemetry.Ctx.attach()
   end
 
-  defp bandit_start() do
-    OpentelemetryProcessPropagator.fetch_parent_ctx()
-    |> OpenTelemetry.Ctx.attach()
-  end
-
   defp default_start(meta) do
     %{conn: conn} = meta
     :otel_propagator_text_map.extract(conn.req_headers)