Add telemetry tests and docs

README.md

@@ -51,6 +51,76 @@ priority sampling documentation].
 
 [Datadog priority sampling documentation]: https://docs.datadoghq.com/tracing/getting_further/trace_sampling_and_storage/#priority-sampling-for-distributed-tracing
 
+## Telemetry
+
+This library includes [telemetry] events that can be used to inspect the
+performance and operations involved in sending trace data to Datadog. Please
+refer to the [telemetry] documentation to see how to attach to these events
+using the standard conventions. The following events are currently exposed:
+
+[telemetry]: https://github.com/beam-telemetry/telemetry
+
+### `[:spandex_datadog, :send_trace, :start]`
+
+This event is executed when the `SpandexDatadog.ApiServer.send_trace/2` API
+function is called, typically as a result of the `finish_trace/1` function
+being called on your `Tracer` implementation module.
+
+**NOTE:** This event is executed in the same process that is calling this API
+function, but at this point, the `Spandex.Trace` data has already been passed
+into the `send_trace` function, and thus the active trace can no longer be
+modified (for example, it is not possible to use this event to add a span to
+represent this API itself having been called).
+
+#### Measurements
+
+* `:system_time`: The time (in native units) this event executed.
+
+#### Metadata
+
+* `trace`: The current `Spandex.Trace` that is being sent to the `ApiServer`.
+
+### `[:spandex_datadog, :send_trace, :stop]`
+
+This event is executed when the `SpandexDatadog.ApiServer.send_trace/2` API
+function completes normally.
+
+**NOTE:** This event is executed in the same process that is calling this API
+function, but at this point, the `Spandex.Trace` data has already been passed
+into the `send_trace` function, and thus the active trace can no longer be
+modified (for example, it is not possible to use this event to add a span to
+represent this API itself having been called).
+
+#### Measurements
+
+* `:duration`: The time (in native units) spent servicing the API call.
+
+#### Metadata
+
+* `trace`: The `Spandex.Trace` that was sent to the `ApiServer`.
+
+### `[:spandex_datadog, :send_trace, :exception]`
+
+This event is executed when the `SpandexDatadog.ApiServer.send_trace/2` API
+function ends prematurely due to an error or exit.
+
+**NOTE:** This event is executed in the same process that is calling this API
+function, but at this point, the `Spandex.Trace` data has already been passed
+into the `send_trace` function, and thus the active trace can no longer be
+modified (for example, it is not possible to use this event to add a span to
+represent this API itself having been called).
+
+#### Measurements
+
+* `:duration`: The time (in native units) spent servicing the API call.
+
+#### Metadata
+
+* `trace`: The current `Spandex.Trace` that is being sent to the `ApiServer`.
+* `:kind`: The kind of exception raised.
+* `:error`: Error data associated with the relevant kind of exception.
+* `:stacktrace`: The stacktrace associated with the exception.
+
 ## API Sender Performance
 
 Originally, the library had an API server and spans were sent via

test/api_server_test.exs

@@ -1,5 +1,5 @@
 defmodule SpandexDatadog.ApiServerTest do
-  use ExUnit.Case
+  use ExUnit.Case, async: false
 
   import ExUnit.CaptureLog
 
@@ -24,6 +24,19 @@ defmodule SpandexDatadog.ApiServerTest do
     end
   end
 
+  defmodule TestSlowApiServer do
+    def put(_url, _body, _headers) do
+      Process.sleep(1)
+      {:error, :timeout}
+    end
+  end
+
+  defmodule TelemetryRecorderPDict do
+    def handle_event(event, measurements, metadata, _cfg) do
+      Process.put(event, {measurements, metadata})
+    end
+  end
+
   setup_all do
     {:ok, agent_pid} = Agent.start_link(fn -> 0 end)
     trace_id = 4_743_028_846_331_200_905
@@ -84,6 +97,65 @@ defmodule SpandexDatadog.ApiServerTest do
     }
   end
 
+  describe "ApiServer.send_trace/2" do
+    test "executes telemetry on success", %{trace: trace} do
+      :telemetry.attach_many(
+        "log-response-handler",
+        [
+          [:spandex_datadog, :send_trace, :start],
+          [:spandex_datadog, :send_trace, :stop],
+          [:spandex_datadog, :send_trace, :exception]
+        ],
+        &TelemetryRecorderPDict.handle_event/4,
+        nil
+      )
+
+      ApiServer.start_link(http: TestOkApiServer)
+
+      ApiServer.send_trace(trace)
+
+      {start_measurements, start_metadata} = Process.get([:spandex_datadog, :send_trace, :start])
+      assert start_measurements[:system_time]
+      assert trace == start_metadata[:trace]
+
+      {stop_measurements, stop_metadata} = Process.get([:spandex_datadog, :send_trace, :stop])
+      assert stop_measurements[:duration]
+      assert trace == stop_metadata[:trace]
+
+      refute Process.get([:spandex_datadog, :send_trace, :exception])
+    end
+
+    test "executes telemetry on exception", %{trace: trace} do
+      :telemetry.attach_many(
+        "log-response-handler",
+        [
+          [:spandex_datadog, :send_trace, :start],
+          [:spandex_datadog, :send_trace, :stop],
+          [:spandex_datadog, :send_trace, :exception]
+        ],
+        &TelemetryRecorderPDict.handle_event/4,
+        nil
+      )
+
+      ApiServer.start_link(http: TestSlowApiServer, batch_size: 1, verbose?: true)
+
+      catch_exit(ApiServer.send_trace(trace, timeout: 1))
+
+      {start_measurements, start_metadata} = Process.get([:spandex_datadog, :send_trace, :start])
+      assert start_measurements[:system_time]
+      assert trace == start_metadata[:trace]
+
+      refute Process.get([:spandex_datadog, :send_trace, :stop])
+
+      {exception_measurements, exception_metadata} = Process.get([:spandex_datadog, :send_trace, :exception])
+      assert exception_measurements[:duration]
+      assert trace == start_metadata[:trace]
+      assert :exit == exception_metadata[:kind]
+      assert nil == exception_metadata[:error]
+      assert is_list(exception_metadata[:stacktrace])
+    end
+  end
+
   describe "ApiServer.handle_call/3 - :send_trace" do
     test "doesn't log anything when verbose?: false", %{trace: trace, state: state, url: url} do
       log =