Merge pull request #1347 from katafrakt/telemetry-for-batch-timeout

Proposal: Telemetry event instead of predefined log message on batch timeout

Author: benwilson512

CHANGELOG.md

@@ -5,6 +5,21 @@
 - Feature: [Add async option to Absinthe.Subscription](https://github.com/absinthe-graphql/absinthe/pull/1329)
 - Bug Fix: [Avoid table scans on registry](https://github.com/absinthe-graphql/absinthe/pull/1330)
 - Big Fix: [Unregsiter duplicate (listening to the same topic) subscriptions individually](https://github.com/absinthe-graphql/absinthe/pull/1336)
+- POTENTIALLY BREAKING Feature: [Add telemetry event on batch timeout](https://github.com/absinthe-graphql/absinthe/pull/1347). If you want to keep the behavior from 1.7.8, define a telemetry handler and attach it. For example:
+
+```elixir
+defmodule MyApp.Telemetry do
+  require Logger
+
+  def log_absinthe([:absinthe, :middleware, :batch, :timeout], _, metadata, _) do
+    Logger.error("Failed to get batching result in #{metadata.timeout}ms for\nfn: #{inspect(metadata.fn)}")
+  end
+end
+
+# attach
+
+:telemetry.attach("absinthe-batch-timeout", [:absinthe, :middleware, :batch, :timeout], &MyApp.Telemetry.log_absinthe/4, nil)
+```
 
 ## 1.7.8
 

guides/telemetry.md

@@ -13,6 +13,7 @@ handler function to any of the following event names:
 - `[:absinthe, :resolve, :field, :stop]` when field resolution finishes
 - `[:absinthe, :middleware, :batch, :start]` when the batch processing starts
 - `[:absinthe, :middleware, :batch, :stop]` when the batch processing finishes
+- `[:absinthe, :middleware, :batch, :timeout]` whe the batch processing times out
 
 Telemetry handlers are called with `measurements` and `metadata`. For details on
 what is passed, checkout `Absinthe.Phase.Telemetry`, `Absinthe.Middleware.Telemetry`,

lib/absinthe/middleware/batch.ex

@@ -162,16 +162,14 @@ defmodule Absinthe.Middleware.Batch do
         result
 
       _ ->
-        Logger.error(
-          "Failed to get batching result in #{timeout}ms for\nfn: #{inspect(batch_fun)}"
-        )
-
+        emit_timeout_event(batch_fun, timeout)
         Process.exit(self(), :timeout)
     end
   end
 
   @batch_start [:absinthe, :middleware, :batch, :start]
   @batch_stop [:absinthe, :middleware, :batch, :stop]
+  @batch_timeout [:absinthe, :middleware, :batch, :timeout]
   defp emit_start_event(system_time, batch_fun, batch_opts, batch_data) do
     id = :erlang.unique_integer()
 
@@ -200,6 +198,15 @@ defmodule Absinthe.Middleware.Batch do
     )
   end
 
+  defp emit_timeout_event(batch_fun, timeout) do
+    metadata = %{
+      fn: inspect(batch_fun),
+      timeout: timeout
+    }
+
+    :telemetry.execute(@batch_timeout, %{}, metadata)
+  end
+
   defp call_batch_fun({module, fun}, batch_data) do
     call_batch_fun({module, fun, []}, batch_data)
   end

test/absinthe/middleware/batch_test.exs

@@ -1,8 +1,6 @@
 defmodule Absinthe.Middleware.BatchTest do
   use Absinthe.Case, async: true
 
-  import ExUnit.CaptureLog
-
   defmodule TimeoutModule do
     def arbitrary_fn_name(_, _) do
       :timer.sleep(2000)
@@ -170,20 +168,33 @@ defmodule Absinthe.Middleware.BatchTest do
     assert {:ok, %{data: %{"ctx" => "some_value"}}} == Absinthe.run(doc, Schema)
   end
 
-  test "when batch task timeouts it logs batching options" do
+  test "when batch task timeouts it emits telemetry event", %{test: test} do
     doc = """
     {timeout}
     """
 
-    assert capture_log(fn ->
-             pid =
-               spawn(fn ->
-                 Absinthe.run(doc, Schema)
-               end)
+    :ok =
+      :telemetry.attach(
+        "#{test}",
+        [:absinthe, :middleware, :batch, :timeout],
+        &Absinthe.TestTelemetryHelper.send_to_pid/4,
+        pid: self()
+      )
+
+    pid =
+      spawn(fn ->
+        Absinthe.run(doc, Schema)
+      end)
 
-             wait_for_process_to_exit(pid)
-           end) =~
-             "fn: {Absinthe.Middleware.BatchTest.TimeoutModule, :arbitrary_fn_name, %{arbitrary: :data}}"
+    wait_for_process_to_exit(pid)
+
+    assert_receive {:telemetry_event,
+                    {[:absinthe, :middleware, :batch, :timeout], %{},
+                     %{
+                       fn:
+                         "{Absinthe.Middleware.BatchTest.TimeoutModule, :arbitrary_fn_name, %{arbitrary: :data}}",
+                       timeout: 1
+                     }, _}}
   end
 
   defp wait_for_process_to_exit(pid) do