Merge pull request #746 from DougReeder/health-controller-exceptions

Health probe failures log useful message

Author: Exairnous

README.md

@@ -61,6 +61,17 @@ Run the following commands at the root of the reticulum directory:
 
 Run `scripts/run.sh` if you have the hubs secret repo cloned. Otherwise `iex -S mix phx.server`
 
+## Development Aids
+
+### Environment Variables [INCOMPLETE]
+
+* STACKTRACE
+   * For errors logged using `log_our_code_location/3`, controls output verbosity.
+   * Valid values:
+      * `FULL`: prints a full stack trace in addition to the location in project code
+      * undefined or any other value: prints only the location in project code
+
+
 ## Run Hubs Against a Local Reticulum Instance
 
 ### 1. Setup the `hubs.local` hostname

config/test.exs

@@ -11,7 +11,7 @@ config :ret, RetWeb.Endpoint,
   server: false
 
 # Print only warnings and errors during test
-config :logger, level: :warn
+config :logger, level: :warning
 
 config :ret, Ret.AppConfig, caching?: false
 

lib/ret_web/controllers/controller_helpers.ex

@@ -2,6 +2,7 @@ defmodule RetWeb.ControllerHelpers do
   import Plug.Conn
   import Phoenix.Controller
   import RetWeb.ErrorHelpers
+  require Logger
 
   def render_error_json(conn, status, params) do
     conn
@@ -21,4 +22,62 @@ defmodule RetWeb.ControllerHelpers do
     reason = Plug.Conn.Status.reason_phrase(code)
     render_error_json(conn, status, reason)
   end
+
+  def log_our_code_location(stacktrace, error, description \\ "Failure") do
+    {filename, line, function} =
+      try do
+        ind =
+          Enum.find_index(stacktrace, fn
+            {module, _function, _arity, [file: filepath, line: _line]} ->
+              filepath = List.to_string(filepath)
+
+              is_not_dependency =
+                !String.contains?(filepath, "/deps/") && !String.contains?(filepath, "deps/")
+
+              is_reticulum_module = String.starts_with?(to_string(module), "Elixir.Ret")
+              is_not_dependency && is_reticulum_module
+
+            # if stacktrace entry isn't in usual format, skips it
+            _ ->
+              false
+              # if no matching entry found, returns first entry
+          end) || 0
+
+        {_module, _function, _arity, location} = Enum.at(stacktrace, ind)
+        filepath = Keyword.get(location, :file)
+        line = Keyword.get(location, :line, 0)
+        filename = if filepath, do: Path.basename(List.to_string(filepath)), else: "<unknown>"
+
+        function =
+          if ind > 0 do
+            {module, function, _ar, _location} = Enum.at(stacktrace, ind - 1)
+            "#{String.replace_prefix(to_string(module), "Elixir.", "")}.#{function}"
+          else
+            :unknown
+          end
+
+        {filename, line, function}
+      rescue
+        _coding_error ->
+          {"<malformed stacktrace>", 0, :unknown}
+      end
+
+    Logger.error("#{description} at #{filename}:#{line} calling #{function}: #{inspect(error)}")
+
+    if System.get_env("STACKTRACE") === "FULL" or filename === "<unknown>" or
+         filename === "<malformed stacktrace>" do
+      try do
+        Logger.error(
+          "Stack trace (most recent call first):\n" <> Exception.format_stacktrace(stacktrace)
+        )
+      rescue
+        _ ->
+          Logger.error("Stack trace (nonstandard):\n" <> inspect(stacktrace))
+      end
+    else
+      Logger.info("For full stacktraces, set the environment variable STACKTRACE to FULL.")
+    end
+
+    {filename, line, function}
+  end
 end

lib/ret_web/controllers/health_controller.ex

@@ -3,20 +3,27 @@ defmodule RetWeb.HealthController do
   import Ecto.Query
 
   def index(conn, _params) do
-    # Check database
-    if module_config(:check_repo) do
-      Ret.Repo.all(from Ret.Hub, limit: 0)
-    end
+    try do
+      # Check database
+      if module_config(:check_repo) do
+        Ret.Repo.all(from Ret.Hub, limit: 0)
+      end
+
+      # Check page cache
+      true = Cachex.get(:page_chunks, {:hubs, "index.html"}) |> elem(1) |> Enum.count() > 0
+      true = Cachex.get(:page_chunks, {:hubs, "hub.html"}) |> elem(1) |> Enum.count() > 0
+      true = Cachex.get(:page_chunks, {:spoke, "index.html"}) |> elem(1) |> Enum.count() > 0
 
-    # Check page cache
-    true = Cachex.get(:page_chunks, {:hubs, "index.html"}) |> elem(1) |> Enum.count() > 0
-    true = Cachex.get(:page_chunks, {:hubs, "hub.html"}) |> elem(1) |> Enum.count() > 0
-    true = Cachex.get(:page_chunks, {:spoke, "index.html"}) |> elem(1) |> Enum.count() > 0
+      # Check room routing
+      true = Ret.RoomAssigner.get_available_host("") != nil
 
-    # Check room routing
-    true = Ret.RoomAssigner.get_available_host("") != nil
+      send_resp(conn, 200, "ok")
+    rescue
+      error ->
+        log_our_code_location(__STACKTRACE__, error, "Health check failed")
 
-    send_resp(conn, 200, "ok")
+        send_resp(conn, 500, "error")
+    end
   end
 
   defp module_config(key) do

test/ret_web/controllers/controller_helpers_test.exs

@@ -0,0 +1,149 @@
+defmodule RetWeb.ControllerHelpersTest do
+  use ExUnit.Case, async: true
+
+  alias RetWeb.ControllerHelpers
+  import ExUnit.CaptureLog
+  require Logger
+
+  setup_all do
+    Logger.configure(level: :info)
+    :ok
+  end
+
+  describe "log_our_code_location/3" do
+    @tag :error_logging
+    test "ignores dependency modules and finds innermost project module" do
+      log =
+        capture_log([level: :info], fn ->
+          stacktrace = [
+            {Bamboo.Email, :new_email, 0,
+             [file: ~c"_build/test/lib/bamboo/ebin/Elixir.Bamboo.Email.beam", line: 190]},
+            {RetWeb.Email, :auth_email, 2, [file: ~c"lib/ret_web/email.ex", line: 19]},
+            {RetWeb.Endpoint, :get_cors_origins, 0,
+             [file: ~c"lib/ret_web/endpoint.ex", line: 10]},
+            {RetWeb.Endpoint, :allowed_origin?, 1, [file: ~c"lib/ret_web/endpoint.ex", line: 16]}
+          ]
+
+          ControllerHelpers.log_our_code_location(stacktrace, :email_error, "Pseudo-failure")
+        end)
+
+      assert log =~ "Pseudo-failure"
+      assert log =~ "at email.ex:19"
+      assert log =~ "calling Bamboo.Email.new_email"
+      assert log =~ ":email_error"
+      assert log =~ "For full stacktraces, set the environment variable STACKTRACE to FULL."
+      refute log =~ "Stack trace (most recent call first)"
+    end
+
+    @tag :error_logging
+    test "falls back to the first entry if no project module is found" do
+      log =
+        capture_log([level: :info], fn ->
+          stacktrace = [
+            {Plug.Conn, :send_resp, 3, [file: ~c"deps/plug/lib/plug/spam.ex", line: 400]},
+            {Phoenix.Controller, :render, 3,
+             [file: ~c"deps/phoenix/lib/phoenix/controller.ex", line: 100]}
+          ]
+
+          ControllerHelpers.log_our_code_location(stacktrace, :another_error)
+        end)
+
+      assert log =~ "Failure"
+      assert log =~ "at spam.ex:400"
+      assert log =~ "calling unknown"
+      assert log =~ ":another_error"
+      assert log =~ "For full stacktraces, set the environment variable STACKTRACE to FULL."
+      refute log =~ "Stack trace (most recent call first)"
+    end
+
+    @tag :error_logging
+    test "handles malformed stacktrace entries by logging full stack trace" do
+      log =
+        capture_log([level: :info], fn ->
+          # This should trigger the rescue block because pattern doesn't match
+          stacktrace = [
+            {:not, :a, :standard, :entry}
+          ]
+
+          ControllerHelpers.log_our_code_location(stacktrace, :spam_error, "Probe failure")
+        end)
+
+      assert log =~ "Probe failure"
+      assert log =~ "at <malformed stacktrace>:0"
+      assert log =~ "calling unknown"
+      assert log =~ ":spam_error"
+      refute log =~ "For full stacktraces, set the environment variable STACKTRACE to FULL."
+      assert log =~ "Stack trace (nonstandard)"
+    end
+
+    @tag :error_logging
+    test "handles empty stacktrace by logging full stacktrace" do
+      log =
+        capture_log([level: :info], fn ->
+          # This should trigger the rescue block because there's no entry to match
+          ControllerHelpers.log_our_code_location([], :strange_error, "Weird failure")
+        end)
+
+      assert log =~ "Weird failure"
+      assert log =~ "at <malformed stacktrace>:0"
+      assert log =~ "calling unknown"
+      assert log =~ ":strange_error"
+      refute log =~ "For full stacktraces, set the environment variable STACKTRACE to FULL."
+      assert log =~ "Stack trace (most recent call first)"
+    end
+
+    @tag :error_logging
+    test "logs full stacktrace when STACKTRACE environment variable is set to FULL" do
+      # Note: manipulation of this environment variable within async tests is deemed safe because it only relates to this module.
+      System.put_env("STACKTRACE", "FULL")
+
+      on_exit(fn ->
+        System.delete_env("STACKTRACE")
+      end)
+
+      log =
+        capture_log([level: :info], fn ->
+          stacktrace = [
+            {RetWeb.Email, :auth_email, 2, [file: ~c"lib/ret_web/email.ex", line: 19]},
+            {RetWeb.Endpoint, :get_cors_origins, 0, [file: ~c"lib/ret_web/endpoint.ex", line: 10]}
+          ]
+
+          ControllerHelpers.log_our_code_location(stacktrace, :full_error, "Full failure")
+        end)
+
+      assert log =~ "Full failure"
+      assert log =~ "at email.ex:19"
+      assert log =~ "calling unknown"
+      assert log =~ ":full_error"
+      refute log =~ "For full stacktraces, set the environment variable STACKTRACE to FULL."
+      assert log =~ "Stack trace (most recent call first)"
+      assert log =~ "RetWeb.Email.auth_email/2"
+      assert log =~ "RetWeb.Endpoint.get_cors_origins/0"
+    end
+
+    @tag :error_logging
+    test "handles stacktrace entry without filepath by returning <unknown>" do
+      log =
+        capture_log([level: :info], fn ->
+          # Entry with arity but no location information
+          stacktrace = [
+            {RetWeb.HealthController, :index, 2, []}
+          ]
+
+          ControllerHelpers.log_our_code_location(
+            stacktrace,
+            :no_filepath_error,
+            "No-filepath failure"
+          )
+        end)
+
+      assert log =~ "No-filepath failure"
+      assert log =~ "at <unknown>:0"
+      assert log =~ "calling unknown"
+      assert log =~ ":no_filepath_error"
+      refute log =~ "For full stacktraces, set the environment variable STACKTRACE to FULL."
+      assert log =~ "Stack trace (most recent call first)"
+      assert log =~ "RetWeb.HealthController.index/2"
+    end
+  end
+end

test/ret_web/controllers/health_controller_test.exs

@@ -0,0 +1,23 @@
+defmodule RetWeb.HealthControllerTest do
+  use RetWeb.ConnCase
+
+  import ExUnit.CaptureLog
+  require Logger
+
+  @tag :error_logging
+  test "GET /health, when a check fails, returns 500 and logs error & location", %{conn: conn} do
+    log =
+      capture_log([level: :error], fn ->
+        # Cachex and RoomAssigner aren't mocked so this will fail.
+        resp = conn |> get("/health")
+        assert resp.status === 500
+        assert resp.resp_body === "error"
+      end)
+
+    # It should log health_controller.ex (reticulum code) even if the error
+    # occurs inside a library (like Enum or Cachex).
+    assert log =~ "Health check failed"
+    assert log =~ "at health_controller.ex:13"
+    assert log =~ "calling Enum.count"
+  end
+end