Log probe status and errors to the integration log

Get more insights into the operation of the minutely probes by logging
what it's doing (which probes it's running) and if it encounters an
error.

These logs follow the same format as the Ruby gem.

Resolves #754 because it now logs when it times out a probe.

.changesets/add-logs-to-probes.md

@@ -0,0 +1,6 @@
+---
+bump: patch
+type: change
+---
+
+Add debug and error logs to probes to better track what it's doing. This is helpful when debugging issues with the minutely probes system.

config/config.exs

@@ -5,6 +5,7 @@ if Mix.env() in [:bench, :test, :test_no_nif] do
   config :appsignal, appsignal_nif: Appsignal.FakeNif
   config :appsignal, appsignal_diagnose_report: Appsignal.Diagnose.FakeReport
   config :appsignal, appsignal: Appsignal.FakeAppsignal
+  config :appsignal, appsignal_integration_logger: Appsignal.FakeIntegrationLogger
   config :appsignal, appsignal_transmitter: Appsignal.FakeTransmitter
   config :appsignal, inet: FakeInet
   config :appsignal, io: FakeIO

lib/appsignal/probes/probes.ex

@@ -2,6 +2,13 @@ defmodule Appsignal.Probes do
   @moduledoc false
   use GenServer
   require Logger
+  require Appsignal.Utils
+
+  @integration_logger Appsignal.Utils.compile_env(
+                        :appsignal,
+                        :appsignal_integration_logger,
+                        Appsignal.IntegrationLogger
+                      )
 
   def start_link do
     GenServer.start_link(__MODULE__, [], name: __MODULE__)
@@ -73,17 +80,22 @@ defmodule Appsignal.Probes do
   def handle_info(:run_probes, {probes, states}) do
     states =
       if Appsignal.Config.minutely_probes_enabled?() do
+        @integration_logger.debug("Gathering minutely metrics with #{Enum.count(probes)} probes")
+
         stream =
           Task.async_stream(
             probes,
             fn {name, probe} ->
+              @integration_logger.debug("Gathering minutely metrics with '#{name}' probe")
               state = Map.get(states, name)
 
               try do
                 {name, call_probe(probe, state)}
               rescue
                 e ->
-                  Logger.error("Error while calling probe #{name}: #{inspect(e)}")
+                  "Error in minutely probe '#{name}': #{inspect(e)}"
+                  |> @integration_logger.error()
+
                   {name, state}
               end
             end,
@@ -94,8 +106,15 @@ defmodule Appsignal.Probes do
 
         Enum.reduce(stream, states, fn result, states ->
           case result do
-            {:ok, {name, state}} -> Map.put(states, name, state)
-            {:exit, :timeout} -> states
+            {:ok, {name, state}} ->
+              Map.put(states, name, state)
+
+            {:exit, :timeout} ->
+              @integration_logger.error(
+                "A minutely probe took more than 30 seconds and was timed out."
+              )
+
+              states
           end
         end)
       else

test/appsignal/probes/probes_test.exs

@@ -1,15 +1,19 @@
 defmodule Appsignal.Probes.ProbesTest do
+  alias Appsignal.FakeIntegrationLogger
   alias Appsignal.Probes
   alias FakeProbe
   import AppsignalTest.Utils
   use ExUnit.Case
 
   setup do
+    fake_integration_logger = start_supervised!(FakeIntegrationLogger)
+
     on_exit(fn ->
       Probes.unregister(:test_probe)
+      FakeIntegrationLogger.clear()
     end)
 
-    [fun: fn state -> state + 1 end]
+    [fun: fn state -> state + 1 end, fake_integration_logger: fake_integration_logger]
   end
 
   describe "with a registered probe" do
@@ -22,8 +26,14 @@ defmodule Appsignal.Probes.ProbesTest do
       assert Probes.probes()[:test_probe] == fun
     end
 
-    test "calls the probe automatically" do
+    test "calls the probe automatically", %{fake_integration_logger: fake_integration_logger} do
       until(fn -> assert Probes.states()[:test_probe] > 0 end)
+
+      assert FakeIntegrationLogger.logged?(
+               fake_integration_logger,
+               :debug,
+               "Gathering minutely metrics with 'test_probe' probe"
+             )
     end
 
     test "increments internal state" do
@@ -88,13 +98,27 @@ defmodule Appsignal.Probes.ProbesTest do
     setup %{fun: fun} do
       :ok = Probes.register(:broken_probe, fn -> raise "Probe exception!" end, 0)
       :ok = Probes.register(:not_broken_probe, fun, 1)
+
+      on_exit(fn ->
+        Probes.unregister(:broken_probe)
+        Probes.unregister(:not_broken_probe)
+      end)
+
       [fun: fun]
     end
 
-    test "calls the probe without crashing the probes" do
+    test "calls the probe without crashing the probes", %{
+      fake_integration_logger: fake_integration_logger
+    } do
       run_probes()
 
       until(fn -> assert Probes.states()[:not_broken_probe] > 1 end)
+
+      assert FakeIntegrationLogger.logged?(
+               fake_integration_logger,
+               :error,
+               "Error in minutely probe 'broken_probe': %RuntimeError{message: \"Probe exception!\"}"
+             )
     end
   end
 end

test/support/appsignal/fake_integration_logger.ex

@@ -0,0 +1,53 @@
+defmodule Appsignal.FakeIntegrationLogger do
+  use TestAgent, %{
+    logs: []
+  }
+
+  def trace(message) do
+    add(:logs, [:trace, message])
+  end
+
+  def debug(message) do
+    add(:logs, [:debug, message])
+  end
+
+  def info(message) do
+    add(:logs, [:info, message])
+  end
+
+  def warn(message) do
+    add(:logs, [:warn, message])
+  end
+
+  def error(message) do
+    add(:logs, [:error, message])
+  end
+
+  def logged?(pid_or_module, type, message) do
+    Enum.any?(get(pid_or_module, :logs), fn element ->
+      match?([^type, ^message], element)
+    end)
+  end
+
+  def get_logs(pid_or_module, type) do
+    Enum.filter(get(pid_or_module, :logs), fn element ->
+      match?([^type, _], element)
+    end)
+  end
+
+  def clear do
+    if alive?() do
+      Agent.update(__MODULE__, fn state ->
+        Map.update!(state, :logs, fn _ -> [] end)
+      end)
+    end
+  end
+
+  defp add(key, event) do
+    if alive?() do
+      Agent.update(__MODULE__, fn state ->
+        Map.update!(state, key, fn current -> [event | current] end)
+      end)
+    end
+  end
+end