Repository: newrelic/elixir_agent (elixir)

Issue:
Error on Oban instrumentation
**Describe the bug**
I've got the following exception after bumping `new_relic_agent` from 1.30.0 to 1.31.0:

```
GenServer #PID<0.219306.0> terminating
** (FunctionClauseError) no function clause matching in NewRelic.Transaction.Complete.transform_time_attrs/1
    (new_relic_agent 1.31.0) lib/new_relic/transaction/complete.ex:44: NewRelic.Transaction.Complete.transform_time_attrs(%{"oban.job.args.REDACTED" => true, :"oban.job.attempt" => 1, :datastore_duration_ms => 225.92000000000002, :"datastore.REDACTED.duration_ms" => 3.413, :"function.REDACTED.call_count" => 1, :"oban.queue" => "REDACTED", :"oban.job.attempted_by" => "REDACTED", :"datastore.public.oban_jobs.duration_ms" => 114.524, :transaction_metrics => [{{:external, "REDACTED", "Finch", "POST"}, [duration_s: 1.087]}, {{:datastore, "Postgres", "REDACTED", :select}, [duration_s: 0.005644]}, {{:datastore, "Postgres", "REDACTED", :select}, [duration_s: 0.004305]}, {{:function, "REDACTED"}, [duration_s: 9.91e-4, exclusive_time_s: 9.91e-4]}, {{:datastore, "Postgres", "REDACTED", :insert}, [duration_s: 0.008619]}, {{:datastore, "Postgres", "REDACTED", :insert}, [duration_s: 0.010648]}, {{:datastore, "Postgres", "REDACTED", :insert}, [duration_s: 0.008532999999999999]}, {{:datastore, "Postgres", "REDACTED", :insert}, [duration_s: 0.010208]}, {{:datastore, "Postgres", "REDACTED", :insert}, [duration_s: 0.011470000000000001]}, {{:datastore, "Postgres", "REDACTED", :insert}, [duration_s: 0.004399]}, {{:datastore, "Postgres", "REDACTED", :insert}, [duration_s: 0.004714]}, {{:datastore, "Postgres", "REDACTED", :insert}, [duration_s: 0.011891]}, {{:datastore, "Postgres", "REDACTED", :insert}, [duration_s: 0.007983]}, {{:datastore, "Postgres", "REDACTED", :select}, [duration_s: 0.0024300000000000003]}, {{:datastore, "Postgres", :other, :commit}, [duration_s: 0.001758]}, {{:datastore, "Postgres", "public.oban_jobs", :update}, [duration_s: 0.114524]}, {{:datastore, "Postgres", :other, :begin}, [duration_s: 0.00177]}, {{:datastore, "Postgres", "REDACTED", :select}, [duration_s: 0.002926]}, {{:datastore, "Postgres", "REDACTED", :select}, [duration_s: 0.008797000000000001]}, {{:datastore, "Postgres", "REDACTED", :select}, [duration_s: 0.003413]}, {{:datastore, "Postgres", "REDACTED", :select}, [duration_s: 0.001888]}], :traceId => "662ac000b16d30dcb466f8c053371f67", :"datastore.REDACTED.duration_ms" => 2.926, :guid => "5b162a394ed1b7b3", :"external.REDACTED.duration_ms" => 1087, :"oban.worker" => "REDACTED", :"oban.job.tags" => "REDACTED", "oban.job.args.REDACTED" => false, "oban.job.args.REDACTED" => "sms", :datastore_call_count => 19, :name => "Oban/REDACTED", "oban.job.args.REDACTED" => false, :"datastore.other.call_count" => 2, :pid => "#PID<0.219305.0>", :"datastore.REDACTED.duration_ms" => 14.441, "oban.job.args.REDACTED" => "a5bd248e-c6a4-4feb-b412-acbc65624657", :sampled => false, :databaseDuration => 0.22591999999999998, :other_transaction_name => "Oban/REDACTED", :"datastore.REDACTED.call_count" => 2, :"external.REDACTED.call_count" => 1, :"oban.job.priority" => 0, :"datastore.REDACTED.duration_ms" => 85.19999999999999, :"datastore.other.duration_ms" => 3.528, :databaseCallCount => 19, :"datastore.REDACTED.call_count" => 1, :priority => 0.407053, "oban.job.args.REDACTED" => 7, :process_spawns => [{#PID<0.223911.0>, 1737037874740, #PID<0.219305.0>, nil}, {#PID<0.223360.0>, 1737037873652, #PID<0.219305.0>, nil}], :"oban.job.max_attempts" => 20, "oban.job.args.REDACTED" => true, "oban.job.args.REDACTED" => true, :"datastore.REDACTED.call_count" => 11, :function_segments => [%{attributes: %{}, id: {{"POST", :https, "REDACTED", "REDACTED"}, #Reference<0.3831579455.3896770564.92959>}, pid: #PID<0.223360.0>, start_time: 1737037873652036926, parent_id: :root, end_time_mono: -576459554182704873, start_time_mono: -576459555269797339, ...}, %{attributes: %{host: "REDACTED", operation: :select, sql: "REDACTED", collection: "REDACTED", database_name: "REDACTED", ...}, id: {:ecto_sql_query, #Reference<0.3831579455.3896770564.92946>}, pid: "#PID<0.219305.0>", start_time: 1737037873645.237, parent_id: :root, end_time: 1737037873650.881, ...}, %{attributes: %{host: "REDACTED", operation: :select, sql: "REDACTED", collection: "REDACTED", ...}, id: {:ecto_sql_query, #Reference<0.3831579455.3897032706.134070>}, pid: "#PID<0.219305.0>", start_time: 1737037873640.7031, parent_id: :root, ...}, %{args: "[\"655b8ba0ee\" <> ...]", arity: 1, function: :get_by_id, id: {...}, ...}, %{attributes: %{host: "REDACTED", operation: :insert, ...}, id: {:ecto_sql_query, ...}, pid: "#PID<0.219305.0>", ...}, %{attributes: %{host: "REDACTED", ...}, id: {...}, ...}, %{attributes: %{...}, ...}, %{...}, ...], :"datastore.public.oban_jobs.call_count" => 1, :"datastore.REDACTED.call_count" => 1, :"function.REDACTED.duration_ms" => 0.991, :"datastore.REDACTED.call_count" => 1, :system_time => 1737037869108188648, :"datastore.REDACTED.duration_ms" => 1.888, :process_exits => [{...}], :end_time_mono => -576459554109160636})
    (new_relic_agent 1.31.0) lib/new_relic/transaction/complete.ex:13: NewRelic.Transaction.Complete.run/2
    (new_relic_agent 1.31.0) lib/new_relic/transaction/sidecar.ex:224: NewRelic.Transaction.Sidecar.handle_continue/2
    (stdlib 5.2.3.2) gen_server.erl:1085: :gen_server.try_handle_continue/3
    (stdlib 5.2.3.2) gen_server.erl:995: :gen_server.loop/7
    (stdlib 5.2.3.2) proc_lib.erl:241: :proc_lib.init_p_do_apply/3
Last message: {:continue, :complete}
```

**Environment**
elixir 1.17.3-otp-26
erlang 26.2.5.5

Pull request:
Fixes: Transaction timing, bandit, span macro
This PR contains fixes for a few issues with the `1.31.0` release

* A fix for another instance where the bandit start telemetry doesn't include the `conn` in an error case
* A fix for the `NewRelic.span` macro that was just introduced, but not exercised in tests (oops)
* Wires up Transaction reporting so that we will always have a full set of timing attributes, even if we don't get timing attributes from the instrumentation due to some kind of error. There was a bug revealed when an `Oban` job process exited w/o emitting telemetry, so when we went to "complete" it, it didn't have a needed attribute. This PR fixes this by ensuring the agent automatically put timing attributes on all Transactions. If instrumentation provides more accurate timing attributes, we prefer those over the ones captured by the agent. 

Timing attribute precedence:
* `start_time :: native, duration :: native` (passed by `telemetry` instrumentation)
* `system_time :: native, start_time_mono :: native, end_time_mono :: native` (passed by `Transaction.Reporter`)



Fixes #482 

Patch:
diff --git a/examples/apps/oban_example/lib/oban_example/worker.ex b/examples/apps/oban_example/lib/oban_example/worker.ex
index da356c7..8a5cad4 100644
--- a/examples/apps/oban_example/lib/oban_example/worker.ex
+++ b/examples/apps/oban_example/lib/oban_example/worker.ex
@@ -7,7 +7,7 @@ defmodule ObanExample.Worker do
   end
 
   def perform(%Oban.Job{args: _args}) do
-    Process.sleep(:rand.uniform(50))
+    Process.sleep(15 + :rand.uniform(50))
     :ok
   end
 end
diff --git a/lib/new_relic.ex b/lib/new_relic.ex
index 91d75eb..54de7e8 100644
--- a/lib/new_relic.ex
+++ b/lib/new_relic.ex
@@ -258,7 +258,7 @@ defmodule NewRelic do
   defmacro span(name, attributes \\ [], do: block) do
     quote do
       id = make_ref()
-      NewRelic.Tracer.Direct.start_span(id, name: unquote(name), attributes: unquote(attributes))
+      NewRelic.Tracer.Direct.start_span(id, unquote(name), attributes: unquote(attributes))
       res = unquote(block)
       NewRelic.Tracer.Direct.stop_span(id)
       res
diff --git a/lib/new_relic/telemetry/finch.ex b/lib/new_relic/telemetry/finch.ex
index 7c65259..57d274a 100644
--- a/lib/new_relic/telemetry/finch.ex
+++ b/lib/new_relic/telemetry/finch.ex
@@ -56,7 +56,7 @@ defmodule NewRelic.Telemetry.Finch do
 
   def handle_event(
         @finch_request_start,
-        %{monotonic_time: monotonic_time, system_time: system_time},
+        %{system_time: start_time},
         %{request: request},
         config
       ) do
@@ -70,8 +70,7 @@ defmodule NewRelic.Telemetry.Finch do
       Process.put(
         config.handler_id,
         %{
-          start_time_mono: monotonic_time,
-          system_time: system_time,
+          start_time: start_time,
           span: span,
           previous_span: previous_span,
           previous_span_attrs: previous_span_attrs
@@ -82,85 +81,83 @@ defmodule NewRelic.Telemetry.Finch do
 
   def handle_event(
         @finch_request_stop,
-        %{monotonic_time: end_time_mono, duration: duration},
+        %{duration: duration},
         %{name: finch_pool, request: request, result: result},
         config
       ) do
     if instrument?() do
-      %{
-        start_time_mono: start_time_mono,
-        system_time: start_time,
-        span: span,
-        previous_span: previous_span,
-        previous_span_attrs: previous_span_attrs
-      } = Process.delete(config.handler_id)
-
-      metric_name = "External/#{request.host}/Finch/#{request.method}"
-      secondary_name = "#{request.host} - Finch/#{request.method}"
-
-      duration_ms = System.convert_time_unit(duration, :native, :millisecond)
-      duration_s = duration_ms / 1000
-
-      id = span
-      parent_id = previous_span || :root
-
-      url =
-        URI.to_string(%URI{scheme: "#{request.scheme}", host: request.host, path: request.path})
-
-      result_attrs =
-        case result do
-          {:ok, %{__struct__: Finch.Response} = response} -> %{"response.status": response.status}
-          {:ok, _acc} -> %{}
-          {:error, exception} -> %{error: true, "error.message": Exception.message(exception)}
-        end
-
-      NewRelic.Transaction.Reporter.add_trace_segment(%{
-        primary_name: metric_name,
-        secondary_name: secondary_name,
-        attributes: %{},
-        pid: self(),
-        id: span,
-        parent_id: parent_id,
-        start_time: start_time,
-        start_time_mono: start_time_mono,
-        end_time_mono: end_time_mono
-      })
-
-      NewRelic.report_span(
-        timestamp_ms: System.convert_time_unit(start_time, :native, :millisecond),
-        duration_s: duration_s,
-        name: metric_name,
-        edge: [span: id, parent: parent_id],
-        category: "http",
-        attributes:
-          %{
-            "request.url": url,
-            "request.method": request.method,
-            "request.client": "Finch",
-            "finch.pool": finch_pool
-          }
-          |> Map.merge(result_attrs)
-      )
+      with %{
+             start_time: start_time,
+             span: span,
+             previous_span: previous_span,
+             previous_span_attrs: previous_span_attrs
+           } <- Process.delete(config.handler_id) do
+        metric_name = "External/#{request.host}/Finch/#{request.method}"
+        secondary_name = "#{request.host} - Finch/#{request.method}"
+
+        duration_ms = System.convert_time_unit(duration, :native, :millisecond)
+        duration_s = duration_ms / 1000
+
+        id = span
+        parent_id = previous_span || :root
+
+        url =
+          URI.to_string(%URI{scheme: "#{request.scheme}", host: request.host, path: request.path})
+
+        result_attrs =
+          case result do
+            {:ok, %{__struct__: Finch.Response} = response} -> %{"response.status": response.status}
+            {:ok, _acc} -> %{}
+            {:error, exception} -> %{error: true, "error.message": Exception.message(exception)}
+          end
+
+        NewRelic.Transaction.Reporter.add_trace_segment(%{
+          primary_name: metric_name,
+          secondary_name: secondary_name,
+          attributes: %{},
+          pid: self(),
+          id: span,
+          parent_id: parent_id,
+          start_time: start_time,
+          duration: duration
+        })
+
+        NewRelic.report_span(
+          timestamp_ms: System.convert_time_unit(start_time, :native, :millisecond),
+          duration_s: duration_s,
+          name: metric_name,
+          edge: [span: id, parent: parent_id],
+          category: "http",
+          attributes:
+            %{
+              "request.url": url,
+              "request.method": request.method,
+              "request.client": "Finch",
+              "finch.pool": finch_pool
+            }
+            |> Map.merge(result_attrs)
+        )
 
-      NewRelic.incr_attributes(
-        "external.#{request.host}.call_count": 1,
-        "external.#{request.host}.duration_ms": duration_ms
-      )
+        NewRelic.incr_attributes(
+          "external.#{request.host}.call_count": 1,
+          "external.#{request.host}.duration_ms": duration_ms
+        )
 
-      NewRelic.report_metric(
-        {:external, url, "Finch", request.method},
-        duration_s: duration_s
-      )
+        NewRelic.report_metric(
+          {:external, url, "Finch", request.method},
+          duration_s: duration_s
+        )
 
-      NewRelic.Transaction.Reporter.track_metric({
-        {:external, url, "Finch", request.method},
-        duration_s: duration_s
-      })
+        NewRelic.Transaction.Reporter.track_metric({
+          {:external, url, "Finch", request.method},
+          duration_s: duration_s
+        })
 
-      NewRelic.DistributedTrace.reset_span(
-        previous_span: previous_span,
-        previous_span_attrs: previous_span_attrs
-      )
+        NewRelic.DistributedTrace.reset_span(
+          previous_span: previous_span,
+          previous_span_attrs: previous_span_attrs
+        )
+      end
     end
   end
 
@@ -171,46 +168,45 @@ defmodule NewRelic.Telemetry.Finch do
         config
       ) do
     if instrument?() do
-      %{
-        system_time: start_time,
-        span: span,
-        previous_span: previous_span,
-        previous_span_attrs: previous_span_attrs
-      } = Process.delete(config.handler_id)
-
-      metric_name = "External/#{request.host}/Finch/#{request.method}"
-
-      duration_ms = System.convert_time_unit(duration, :native, :millisecond)
-      duration_s = duration_ms / 1000
-
-      id = span
-      parent_id = previous_span || :root
-
-      url =
-        URI.to_string(%URI{scheme: "#{request.scheme}", host: request.host, path: request.path})
-
-      error_message = NewRelic.Util.Error.format_reason(kind, reason)
-
-      NewRelic.report_span(
-        timestamp_ms: System.convert_time_unit(start_time, :native, :millisecond),
-        duration_s: duration_s,
-        name: metric_name,
-        edge: [span: id, parent: parent_id],
-        category: "http",
-        attributes: %{
-          error: true,
-          "error.message": error_message,
-          "request.url": url,
-          "request.method": request.method,
-          "request.client": "Finch",
-          "finch.pool": finch_pool
-        }
-      )
+      with %{
+             start_time: start_time,
+             span: span,
+             previous_span: previous_span,
+             previous_span_attrs: previous_span_attrs
+           } <- Process.delete(config.handler_id) do
+        metric_name = "External/#{request.host}/Finch/#{request.method}"
+
+        duration_ms = System.convert_time_unit(duration, :native, :millisecond)
+        duration_s = duration_ms / 1000
+
+        id = span
+        parent_id = previous_span || :root
+
+        url = URI.to_string(%URI{scheme: "#{request.scheme}", host: request.host, path: request.path})
+
+        error_message = NewRelic.Util.Error.format_reason(kind, reason)
+
+        NewRelic.report_span(
+          timestamp_ms: System.convert_time_unit(start_time, :native, :millisecond),
+          duration_s: duration_s,
+          name: metric_name,
+          edge: [span: id, parent: parent_id],
+          category: "http",
+          attributes: %{
+            error: true,
+            "error.message": error_message,
+            "request.url": url,
+            "request.method": request.method,
+            "request.client": "Finch",
+            "finch.pool": finch_pool
+          }
+        )
 
-      NewRelic.DistributedTrace.reset_span(
-        previous_span: previous_span,
-        previous_span_attrs: previous_span_attrs
-      )
+        NewRelic.DistributedTrace.reset_span(
+          previous_span: previous_span,
+          previous_span_attrs: previous_span_attrs
+        )
+      end
     end
   end
 
diff --git a/lib/new_relic/telemetry/oban.ex b/lib/new_relic/telemetry/oban.ex
index 41196d0..77136a8 100644
--- a/lib/new_relic/telemetry/oban.ex
+++ b/lib/new_relic/telemetry/oban.ex
@@ -61,14 +61,14 @@ defmodule NewRelic.Telemetry.Oban do
   @doc false
   def handle_event(
         @oban_start,
-        %{system_time: system_time},
+        %{system_time: start_time},
         meta,
         _config
       ) do
     Transaction.Reporter.start_transaction(:other)
     NewRelic.DistributedTrace.start(:other)
 
-    add_start_attrs(meta, system_time)
+    add_start_attrs(meta, start_time)
   end
 
   def handle_event(
@@ -99,10 +99,10 @@ defmodule NewRelic.Telemetry.Oban do
     :ignore
   end
 
-  defp add_start_attrs(meta, system_time) do
+  defp add_start_attrs(meta, start_time) do
     [
       pid: inspect(self()),
-      system_time: system_time,
+      start_time: start_time,
       other_transaction_name: "Oban/#{meta.queue}/#{meta.worker}/perform",
       "oban.worker": meta.worker,
       "oban.queue": meta.queue,
diff --git a/lib/new_relic/telemetry/plug.ex b/lib/new_relic/telemetry/plug.ex
index 562e5c2..2eaf315 100644
--- a/lib/new_relic/telemetry/plug.ex
+++ b/lib/new_relic/telemetry/plug.ex
@@ -140,7 +140,7 @@ defmodule NewRelic.Telemetry.Plug do
   defp add_start_attrs(meta, meas, headers, :cowboy) do
     [
       pid: inspect(self()),
-      system_time: meas[:system_time],
+      start_time: meas[:system_time],
       host: meta.req.host,
       path: meta.req.path,
       remote_ip: meta.req.peer |> elem(0) |> :inet_parse.ntoa() |> to_string(),
@@ -152,17 +152,25 @@ defmodule NewRelic.Telemetry.Plug do
     |> NewRelic.add_attributes()
   end
 
-  defp add_start_attrs(meta, meas, headers, :bandit) do
+  defp add_start_attrs(%{conn: conn}, meas, headers, :bandit) do
     [
       pid: inspect(self()),
-      system_time: meas[:system_time],
-      host: meta.conn.host,
-      path: meta.conn.request_path,
-      remote_ip: meta.conn.remote_ip |> :inet_parse.ntoa() |> to_string(),
+      start_time: meas[:system_time],
+      host: conn.host,
+      path: conn.request_path,
+      remote_ip: conn.remote_ip |> :inet_parse.ntoa() |> to_string(),
       referer: headers["referer"],
       user_agent: headers["user-agent"],
       content_type: headers["content-type"],
-      request_method: meta.conn.method
+      request_method: conn.method
+    ]
+    |> NewRelic.add_attributes()
+  end
+
+  defp add_start_attrs(_meta, meas, _headers, :bandit) do
+    [
+      pid: inspect(self()),
+      start_time: meas[:system_time]
     ]
     |> NewRelic.add_attributes()
   end
@@ -277,6 +285,8 @@ defmodule NewRelic.Telemetry.Plug do
     status
   end
 
+  defp status_code(_), do: nil
+
   defp plug_name(conn, match_path) do
     "/Plug/#{conn.method}/#{match_path}"
     |> String.replace("/*glob", "")
diff --git a/lib/new_relic/tracer/direct.ex b/lib/new_relic/tracer/direct.ex
index 4b22d68..02e1ee9 100644
--- a/lib/new_relic/tracer/direct.ex
+++ b/lib/new_relic/tracer/direct.ex
@@ -3,7 +3,7 @@ defmodule NewRelic.Tracer.Direct do
 
   @max_open_span_count Application.compile_env(:new_relic, :max_open_span_count, 20)
 
-  def start_span(id, name, options) do
+  def start_span(id, name, options \\ []) do
     case Process.get(:nr_open_span_count, 0) do
       over when over >= @max_open_span_count ->
         Process.put(:nr_open_span_count, over + 1)
@@ -30,7 +30,7 @@ defmodule NewRelic.Tracer.Direct do
     :ok
   end
 
-  def stop_span(id, options) do
+  def stop_span(id, options \\ []) do
     case Process.get({:nr_span, id}) do
       nil ->
         :no_such_span
@@ -66,7 +66,7 @@ defmodule NewRelic.Tracer.Direct do
           pid: self(),
           id: span,
           parent_id: previous_span || :root,
-          system_time: start_time,
+          start_time: start_time,
           duration: duration
         })
 
diff --git a/lib/new_relic/tracer/report.ex b/lib/new_relic/tracer/report.ex
index 657b835..4b3618e 100644
--- a/lib/new_relic/tracer/report.ex
+++ b/lib/new_relic/tracer/report.ex
@@ -37,7 +37,7 @@ defmodule NewRelic.Tracer.Report do
          name,
          pid,
          {id, parent_id},
-         {start_time, start_time_mono, end_time_mono, _child_duration_ms, reductions}
+         {system_time, start_time_mono, end_time_mono, _child_duration_ms, reductions}
        ) do
     duration_ms = duration_ms(start_time_mono, end_time_mono)
     duration_s = duration_ms / 1000
@@ -62,13 +62,13 @@ defmodule NewRelic.Tracer.Report do
           pid: pid,
           id: id,
           parent_id: parent_id,
-          start_time: start_time,
+          system_time: system_time,
           start_time_mono: start_time_mono,
           end_time_mono: end_time_mono
         })
 
         NewRelic.report_span(
-          timestamp_ms: System.convert_time_unit(start_time, :native, :millisecond),
+          timestamp_ms: System.convert_time_unit(system_time, :native, :millisecond),
           duration_s: duration_s,
           name: metric_name,
           edge: [span: id, parent: parent_id],
@@ -105,13 +105,13 @@ defmodule NewRelic.Tracer.Report do
           pid: pid,
           id: id,
           parent_id: parent_id,
-          start_time: start_time,
+          system_time: system_time,
           start_time_mono: start_time_mono,
           end_time_mono: end_time_mono
         })
 
         NewRelic.report_span(
-          timestamp_ms: System.convert_time_unit(start_time, :native, :millisecond),
+          timestamp_ms: System.convert_time_unit(system_time, :native, :millisecond),
           duration_s: duration_s,
           name: function_arity_name,
           edge: [span: id, parent: parent_id],
@@ -155,7 +155,7 @@ defmodule NewRelic.Tracer.Report do
          name,
          pid,
          {id, parent_id},
-         {start_time, start_time_mono, end_time_mono, child_duration_ms, reductions}
+         {system_time, start_time_mono, end_time_mono, child_duration_ms, reductions}
        ) do
     duration_ms = duration_ms(start_time_mono, end_time_mono)
     duration_s = duration_ms / 1000
@@ -174,13 +174,13 @@ defmodule NewRelic.Tracer.Report do
       pid: pid,
       id: id,
       parent_id: parent_id,
-      start_time: start_time,
+      system_time: system_time,
       start_time_mono: start_time_mono,
       end_time_mono: end_time_mono
     })
 
     NewRelic.report_span(
-      timestamp_ms: System.convert_time_unit(start_time, :native, :millisecond),
+      timestamp_ms: System.convert_time_unit(system_time, :native, :millisecond),
       duration_s: duration_s,
       name: function_name,
       edge: [span: id, parent: parent_id],
diff --git a/lib/new_relic/transaction/complete.ex b/lib/new_relic/transaction/complete.ex
index 3967e00..a52840f 100644
--- a/lib/new_relic/transaction/complete.ex
+++ b/lib/new_relic/transaction/complete.ex
@@ -41,14 +41,15 @@ defmodule NewRelic.Transaction.Complete do
   defp identify_transaction_type(tx),
     do: Map.put(tx, :transactionType, :Web)
 
-  defp transform_time_attrs(%{system_time: system_time, duration: duration} = tx) do
-    start_time_ms = System.convert_time_unit(system_time, :native, :millisecond)
+  # instrumentation reports time via start_time :: native and duration :: native
+  defp transform_time_attrs(%{start_time: start_time, duration: duration} = tx) do
+    start_time_ms = System.convert_time_unit(start_time, :native, :millisecond)
     duration_us = System.convert_time_unit(duration, :native, :microsecond)
     duration_ms = duration_us / 1000
     duration_s = duration_ms / 1000
 
     tx
-    |> Map.drop([:system_time, :duration, :end_time_mono])
+    |> Map.drop([:system_time, :duration, :start_time_mono, :end_time_mono])
     |> Map.merge(%{
       start_time: start_time_ms,
       end_time: start_time_ms + duration_ms,
@@ -58,17 +59,17 @@ defmodule NewRelic.Transaction.Complete do
     })
   end
 
+  # sidecar reports time via system_time :: native, start_time_mono :: native, end_time_mono :: native
   defp transform_time_attrs(
-         %{start_time: start_time, end_time_mono: end_time_mono, start_time_mono: start_time_mono} =
-           tx
+         %{system_time: system_time, end_time_mono: end_time_mono, start_time_mono: start_time_mono} = tx
        ) do
-    start_time_ms = System.convert_time_unit(start_time, :native, :millisecond)
+    start_time_ms = System.convert_time_unit(system_time, :native, :millisecond)
     duration_us = System.convert_time_unit(end_time_mono - start_time_mono, :native, :microsecond)
     duration_ms = duration_us / 1000
     duration_s = duration_ms / 1000
 
     tx
-    |> Map.drop([:start_time_mono, :end_time_mono])
+    |> Map.drop([:system_time, :duration, :start_time_mono, :end_time_mono])
     |> Map.merge(%{
       start_time: start_time_ms,
       end_time: start_time_ms + duration_ms,
diff --git a/lib/new_relic/transaction/reporter.ex b/lib/new_relic/transaction/reporter.ex
index 79e2a35..264f1c1 100644
--- a/lib/new_relic/transaction/reporter.ex
+++ b/lib/new_relic/transaction/reporter.ex
@@ -27,24 +27,31 @@ defmodule NewRelic.Transaction.Reporter do
   end
 
   def start_transaction(:web, path) do
+    {system_time, start_time_mono} = {System.system_time(), System.monotonic_time()}
+
     if NewRelic.Util.path_match?(path, NewRelic.Config.ignore_paths()) do
       ignore_transaction()
       :ignore
     else
       Transaction.ErlangTrace.trace()
       Transaction.Sidecar.track(:web)
+      Transaction.Sidecar.add(system_time: system_time, start_time_mono: start_time_mono)
       :collect
     end
   end
 
   def start_transaction(:other) do
+    {system_time, start_time_mono} = {System.system_time(), System.monotonic_time()}
+
     unless Transaction.Sidecar.tracking?() do
       Transaction.ErlangTrace.trace()
       Transaction.Sidecar.track(:other)
+      Transaction.Sidecar.add(system_time: system_time, start_time_mono: start_time_mono)
     end
   end
 
   def stop_transaction(:web) do
+    Transaction.Sidecar.add(end_time_mono: System.monotonic_time())
     Transaction.Sidecar.complete()
   end
 


Test patch:
diff --git a/examples/apps/oban_example/test/oban_example_test.exs b/examples/apps/oban_example/test/oban_example_test.exs
index c9c2f62..e376519 100644
--- a/examples/apps/oban_example/test/oban_example_test.exs
+++ b/examples/apps/oban_example/test/oban_example_test.exs
@@ -23,7 +23,11 @@ defmodule ObanExampleTest do
            )
 
     assert [
-             %{:name => "OtherTransaction/Oban/default/ObanExample.Worker/perform"},
+             %{
+               :name => "OtherTransaction/Oban/default/ObanExample.Worker/perform",
+               :timestamp => timestamp,
+               :duration => duration
+             },
              %{
                :"oban.worker" => "ObanExample.Worker",
                :"oban.queue" => "default",
@@ -31,6 +35,9 @@ defmodule ObanExampleTest do
                :"oban.job.tags" => "foo,bar"
              }
            ] = event
+
+    assert timestamp |> is_number
+    assert duration >= 0.015
   end
 
   test "instruments a failed job" do
diff --git a/examples/apps/redix_example/test/redix_example_test.exs b/examples/apps/redix_example/test/redix_example_test.exs
index e621783..5a17363 100644
--- a/examples/apps/redix_example/test/redix_example_test.exs
+++ b/examples/apps/redix_example/test/redix_example_test.exs
@@ -60,6 +60,8 @@ defmodule RedixExampleTest do
     assert get_event[:"db.statement"] == "GET mykey"
     assert get_event[:"redix.connection"] =~ "PID"
     assert get_event[:"redix.connection_name"] == ":redix"
+    assert get_event[:timestamp] |> is_number
+    assert get_event[:duration] > 0.0
 
     [pipeline_event, _, _] =
       Enum.find(span_events, fn [ev, _, _] ->
diff --git a/test/span_event_test.exs b/test/span_event_test.exs
index f57b946..a89ba2f 100644
--- a/test/span_event_test.exs
+++ b/test/span_event_test.exs
@@ -118,6 +118,15 @@ defmodule SpanEventTest do
       Process.sleep(10)
       NewRelic.set_span(:generic, some: "attribute")
       NewRelic.add_span_attributes(another: "attr")
+
+      NewRelic.span "single.span" do
+        Process.sleep(5)
+      end
+
+      NewRelic.span "another.span", with: "an attribute" do
+        Process.sleep(5)
+      end
+
       http_request()
     end
 
@@ -146,6 +155,11 @@ defmodule SpanEventTest do
       send_resp(conn, 200, Traced.hello())
     end
 
+    get "/span_macro" do
+      Traced.function()
+      send_resp(conn, 200, "Yo.")
+    end
+
     get "/reset_span" do
       Traced.function()
       send_resp(conn, 200, "Yo.")
@@ -184,6 +198,32 @@ defmodule SpanEventTest do
     TestHelper.pause_harvest_cycle(Collector.TransactionEvent.HarvestCycle)
   end
 
+  test "span macro" do
+    TestHelper.restart_harvest_cycle(Collector.SpanEvent.HarvestCycle)
+
+    TestHelper.request(TestPlugApp, conn(:get, "/span_macro"))
+
+    span_events = TestHelper.gather_harvest(Collector.SpanEvent.Harvester)
+
+    [another_span, _, _] =
+      Enum.find(span_events, fn [ev, _, _] ->
+        ev[:name] == "another.span"
+      end)
+
+    assert another_span[:category] == "generic"
+    assert another_span[:with] == "an attribute"
+
+    [single_span, _, _] =
+      Enum.find(span_events, fn [ev, _, _] ->
+        ev[:name] == "single.span"
+      end)
+
+    assert single_span[:category] == "generic"
+
+    TestHelper.pause_harvest_cycle(Collector.SpanEvent.HarvestCycle)
+    TestHelper.pause_harvest_cycle(Collector.TransactionEvent.HarvestCycle)
+  end
+
   test "report span events via function tracer inside transaction inside a DT" do
     TestHelper.restart_harvest_cycle(Collector.SpanEvent.HarvestCycle)
     TestHelper.restart_harvest_cycle(Collector.TransactionEvent.HarvestCycle)
diff --git a/test/telemetry/finch_test.exs b/test/telemetry/finch_test.exs
index 95cb9ed..8199c57 100644
--- a/test/telemetry/finch_test.exs
+++ b/test/telemetry/finch_test.exs
@@ -5,7 +5,7 @@ defmodule NewRelic.Telemetry.FinchTest do
   setup do
     TestHelper.restart_harvest_cycle(Collector.Metric.HarvestCycle)
     TestHelper.restart_harvest_cycle(Collector.SpanEvent.HarvestCycle)
-    send(NewRelic.DistributedTrace.BackoffSampler, :reset)
+    NewRelic.DistributedTrace.BackoffSampler.reset()
 
     start_supervised({Finch, name: __MODULE__})