Merge pull request #372 from getsentry/no-logger-logging

No logger logging

Author: mitchellhenke

lib/mix/tasks/sentry.send_test_event.ex

@@ -58,8 +58,8 @@ defmodule Mix.Tasks.Sentry.SendTestEvent do
         {:ok, id} ->
           Mix.shell().info("Test event sent!  Event ID: #{id}")
 
-        :error ->
-          Mix.shell().info("Error sending event!")
+        {:error, reason} ->
+          Mix.shell().info("Error sending event: #{inspect(reason)}")
 
         :excluded ->
           Mix.shell().info("No test event was sent because the event was excluded by a filter")

lib/sentry/client.ex

@@ -41,8 +41,8 @@ defmodule Sentry.Client do
   require Logger
 
   @type send_event_result ::
-          {:ok, Task.t() | String.t() | pid()} | :error | :unsampled | :excluded
-  @type dsn :: {String.t(), String.t(), String.t()} | :error
+          {:ok, Task.t() | String.t() | pid()} | {:error, any()} | :unsampled | :excluded
+  @type dsn :: {String.t(), String.t(), String.t()}
   @type result :: :sync | :none | :async
   @sentry_version 5
   @max_attempts 4
@@ -56,6 +56,7 @@ defmodule Sentry.Client do
   Attempts to send the event to the Sentry API up to 4 times with exponential backoff.
 
   The event is dropped if it all retries fail.
+  Errors will be logged unless the source is the Sentry.LoggerBackend, which can deadlock by logging within a logger.
 
   ### Options
   * `:result` - Allows specifying how the result should be returned. Options include `:sync`, `:none`, and `:async`.  `:sync` will make the API call synchronously, and return `{:ok, event_id}` if successful.  `:none` sends the event from an unlinked child process under `Sentry.TaskSupervisor` and will return `{:ok, ""}` regardless of the result.  `:async` will start an unlinked task and return a tuple of `{:ok, Task.t}` on success where the Task can be awaited upon to receive the result asynchronously.  When used in an OTP behaviour like GenServer, the task will send a message that needs to be matched with `GenServer.handle_info/2`.  See `Task.Supervisor.async_nolink/2` for more information.  `:async` is the default.
@@ -66,6 +67,7 @@ defmodule Sentry.Client do
   def send_event(%Event{} = event, opts \\ []) do
     result = Keyword.get(opts, :result, :async)
     sample_rate = Keyword.get(opts, :sample_rate) || Config.sample_rate()
+    should_log = event.event_source != :logger
 
     event = maybe_call_before_send_event(event)
 
@@ -77,97 +79,96 @@ defmodule Sentry.Client do
         :unsampled
 
       {%Event{}, true} ->
-        encode_and_send(event, result)
+        encode_and_send(event, result, should_log)
     end
   end
 
-  @spec encode_and_send(Event.t(), result()) :: send_event_result()
-  defp encode_and_send(event, result) do
+  @spec encode_and_send(Event.t(), result(), boolean()) :: send_event_result()
+  defp encode_and_send(event, result, should_log) do
     json_library = Config.json_library()
 
     render_event(event)
     |> json_library.encode()
     |> case do
       {:ok, body} ->
-        do_send_event(event, body, result)
+        result = do_send_event(event, body, result)
+
+        if should_log do
+          maybe_log_result(result)
+        end
+
+        result
 
       {:error, error} ->
-        log_api_error("Unable to encode Sentry error - #{inspect(error)}")
-        :error
+        {:error, {:invalid_json, error}}
     end
   end
 
-  @spec do_send_event(Event.t(), map(), :async) :: {:ok, Task.t()} | :error
+  @spec do_send_event(Event.t(), map(), :async) :: {:ok, Task.t()} | {:error, any()}
   defp do_send_event(event, body, :async) do
     case get_headers_and_endpoint() do
-      {endpoint, auth_headers} ->
+      {endpoint, auth_headers} when is_binary(endpoint) ->
         {:ok,
          Task.Supervisor.async_nolink(Sentry.TaskSupervisor, fn ->
            try_request(endpoint, auth_headers, {event, body})
            |> maybe_call_after_send_event(event)
          end)}
 
-      _ ->
-        :error
+      {:error, :invalid_dsn} ->
+        {:error, :invalid_dsn}
     end
   end
 
-  @spec do_send_event(Event.t(), map(), :sync) :: {:ok, String.t()} | :error
+  @spec do_send_event(Event.t(), map(), :sync) :: {:ok, String.t()} | {:error, any()}
   defp do_send_event(event, body, :sync) do
     case get_headers_and_endpoint() do
-      {endpoint, auth_headers} ->
+      {endpoint, auth_headers} when is_binary(endpoint) ->
         try_request(endpoint, auth_headers, {event, body})
         |> maybe_call_after_send_event(event)
 
-      _ ->
-        :error
+      {:error, :invalid_dsn} ->
+        {:error, :invalid_dsn}
     end
   end
 
   @spec do_send_event(Event.t(), map(), :none) ::
-          {:ok, DynamicSupervisor.on_start_child()} | :error
+          {:ok, DynamicSupervisor.on_start_child()} | {:error, any()}
   defp do_send_event(event, body, :none) do
     case get_headers_and_endpoint() do
-      {endpoint, auth_headers} ->
+      {endpoint, auth_headers} when is_binary(endpoint) ->
         Task.Supervisor.start_child(Sentry.TaskSupervisor, fn ->
           try_request(endpoint, auth_headers, {event, body})
           |> maybe_call_after_send_event(event)
         end)
 
         {:ok, ""}
 
-      _ ->
-        :error
+      {:error, :invalid_dsn} ->
+        {:error, :invalid_dsn}
     end
   end
 
   @spec try_request(
           String.t(),
           list({String.t(), String.t()}),
           {Event.t(), String.t()},
-          pos_integer()
-        ) :: {:ok, String.t()} | :error
-  defp try_request(url, headers, event_body_tuple, current_attempt \\ 1)
+          {pos_integer(), any()}
+        ) :: {:ok, String.t()} | {:error, {:request_failure, any()}}
+  defp try_request(url, headers, event_body_tuple, current_attempt_and_error \\ {1, nil})
 
-  defp try_request(_, _, _, current_attempt)
+  defp try_request(_url, _headers, {_event, _body}, {current_attempt, last_error})
        when current_attempt > @max_attempts,
-       do: :error
+       do: {:error, {:request_failure, last_error}}
 
-  defp try_request(url, headers, {event, body}, current_attempt) do
+  defp try_request(url, headers, {event, body}, {current_attempt, _last_error}) do
     case request(url, headers, body) do
       {:ok, id} ->
         {:ok, id}
 
       {:error, error} ->
-        if(current_attempt == 1) do
-          log_api_error("Event ID: #{event.event_id} - #{inspect(error)} - #{body}")
-        else
-          log_api_error("Event ID: #{event.event_id} - #{inspect(error)}")
-        end
-
         if current_attempt < @max_attempts, do: sleep(current_attempt)
 
-        try_request(url, headers, {event, body}, current_attempt + 1)
+        try_request(url, headers, {event, body}, {current_attempt + 1, error})
     end
   end
 
@@ -225,20 +226,12 @@ defmodule Sentry.Client do
     "Sentry " <> query
   end
 
-  @spec authorization_headers(String.t(), String.t()) :: list({String.t(), String.t()})
-  defp authorization_headers(public_key, secret_key) do
-    [
-      {"User-Agent", @sentry_client},
-      {"X-Sentry-Auth", authorization_header(public_key, secret_key)}
-    ]
-  end
-
   @doc """
   Get a Sentry DSN which is simply a URI.
 
   {PROTOCOL}://{PUBLIC_KEY}[:{SECRET_KEY}]@{HOST}/{PATH}{PROJECT_ID}
   """
-  @spec get_dsn :: dsn
+  @spec get_dsn :: dsn | {:error, :invalid_dsn}
   def get_dsn do
     dsn = Config.dsn()
 
@@ -252,8 +245,7 @@ defmodule Sentry.Client do
       {endpoint, public_key, secret_key}
     else
       _ ->
-        log_api_error("Cannot send event because of invalid DSN")
-        :error
+        {:error, :invalid_dsn}
     end
   end
 
@@ -338,6 +330,43 @@ defmodule Sentry.Client do
     end
   end
 
+  def maybe_log_result(result) do
+    message =
+      case result do
+        {:error, :invalid_dsn} ->
+          "Cannot send Sentry event because of invalid DSN"
+
+        {:error, {:invalid_json, error}} ->
+          "Unable to encode JSON Sentry error - #{inspect(error)}"
+
+        {:error, {:request_failure, last_error}} ->
+          "Error in HTTP Request to Sentry - #{inspect(last_error)}"
+
+        {:error, error} ->
+          inspect(error)
+
+        _ ->
+          nil
+      end
+
+    if message != nil do
+      Logger.log(
+        Config.log_level(),
+        fn ->
+          ["Failed to send Sentry event.", message]
+        end
+      )
+    end
+  end
+
+  @spec authorization_headers(String.t(), String.t()) :: list({String.t(), String.t()})
+  defp authorization_headers(public_key, secret_key) do
+    [
+      {"User-Agent", @sentry_client},
+      {"X-Sentry-Auth", authorization_header(public_key, secret_key)}
+    ]
+  end
+
   defp keys_from_userinfo(userinfo) do
     case String.split(userinfo, ":", parts: 2) do
       [public, secret] -> [public, secret]
@@ -346,25 +375,18 @@ defmodule Sentry.Client do
     end
   end
 
+  @spec get_headers_and_endpoint ::
+          {String.t(), list({String.t(), String.t()})} | {:error, :invalid_dsn}
   defp get_headers_and_endpoint do
     case get_dsn() do
       {endpoint, public_key, secret_key} ->
         {endpoint, authorization_headers(public_key, secret_key)}
 
-      _ ->
-        :error
+      {:error, :invalid_dsn} ->
+        {:error, :invalid_dsn}
     end
   end
 
-  defp log_api_error(body) do
-    Logger.log(
-      Config.log_level(),
-      fn ->
-        ["Failed to send Sentry event.", inspect(body)]
-      end
-    )
-  end
-
   @spec sleep(pos_integer()) :: :ok
   defp sleep(1), do: :timer.sleep(2000)
   defp sleep(2), do: :timer.sleep(4000)

test/client_test.exs

@@ -44,41 +44,31 @@ defmodule Sentry.ClientTest do
   test "errors on bad public keys" do
     modify_env(:sentry, dsn: "https://app.getsentry.com/1")
 
-    capture_log(fn ->
-      assert :error = Sentry.Client.get_dsn()
-    end)
+    assert {:error, :invalid_dsn} = Sentry.Client.get_dsn()
   end
 
   test "errors on non-integer project_id" do
     modify_env(:sentry, dsn: "https://public:[email protected]/Mitchell")
 
-    capture_log(fn ->
-      assert :error = Sentry.Client.get_dsn()
-    end)
+    assert {:error, :invalid_dsn} = Sentry.Client.get_dsn()
   end
 
   test "errors on no project_id" do
     modify_env(:sentry, dsn: "https://public:[email protected]")
 
-    capture_log(fn ->
-      assert :error = Sentry.Client.get_dsn()
-    end)
+    assert {:error, :invalid_dsn} = Sentry.Client.get_dsn()
   end
 
   test "errors on nil dsn" do
     modify_env(:sentry, dsn: nil)
 
-    capture_log(fn ->
-      assert :error = Sentry.Client.get_dsn()
-    end)
+    assert {:error, :invalid_dsn} = Sentry.Client.get_dsn()
   end
 
   test "errors on atom dsn" do
     modify_env(:sentry, dsn: :error)
 
-    capture_log(fn ->
-      assert :error = Sentry.Client.get_dsn()
-    end)
+    assert {:error, :invalid_dsn} = Sentry.Client.get_dsn()
   end
 
   test "logs api errors" do
@@ -114,7 +104,7 @@ defmodule Sentry.ClientTest do
     unencodable_event = %Sentry.Event{message: "error", level: {:a, :b}}
 
     capture_log(fn ->
-      assert :error = Sentry.Client.send_event(unencodable_event)
+      assert {:error, {:invalid_json, _}} = Sentry.Client.send_event(unencodable_event)
     end)
   end
 

test/mix/sentry.send_test_event_test.exs

@@ -55,7 +55,7 @@ defmodule Mix.Tasks.Sentry.SendTestEventTest do
            """
   end
 
-  test "handles :error when Sentry server is failing" do
+  test "handles error when Sentry server is failing" do
     bypass = Bypass.open()
 
     Bypass.expect(bypass, fn conn ->
@@ -78,7 +78,7 @@ defmodule Mix.Tasks.Sentry.SendTestEventTest do
                     hackney_opts: [recv_timeout: 50]
 
                     Sending test event...
-                    Error sending event!
+                    Error sending event: "Received 500 from Sentry server: "
                     """
            end) =~ "Failed to send Sentry event"
   end

test/sentry_test.exs

@@ -55,9 +55,9 @@ defmodule SentryTest do
       dsn: "http://public:secret@localhost:#{bypass.port}/1"
     )
 
-    assert capture_log(fn ->
-             assert :error = Sentry.capture_message("error", [])
-           end) =~ "Failed to send Sentry event"
+    capture_log(fn ->
+      assert {:error, _} = Sentry.capture_message("error", [])
+    end)
 
     Bypass.pass(bypass)
   end

test/support/test_client.exs

@@ -26,7 +26,7 @@ defmodule Sentry.TestClient do
               end
             )
 
-            :error
+            {:error, error}
         end
 
       {:error, error} ->
@@ -35,7 +35,7 @@ defmodule Sentry.TestClient do
           "Error sending in Sentry.TestClient: #{inspect(error)}"
         )
 
-        :error
+        {:error, error}
     end
   end
 end