Repository: whitfin/cachex (elixir)

Issue:
Use original stacktrace on errors that happen in Cachex.fetch! fallbacks
Sometimes the fallback function logic can be quite complex and call a lot of functions, when these functions raise unexpectedly raise errors Cachex just returns `Cachex.ExecutionError` with the error message copied from the exception. I've been in multiple situations when the error message is not enough to identify where the issue happens and you have to check the all executed code manually or comment out the fetch and try to reproduce the issue without caching.

It would be much faster do debug some issues if original stacktrace was available (currently the stacktrace in exceptions cachex throws just ends at `Cachex.unwrap_unsafe`). I wrote a proof of concept patch that does just that https://github.com/whitfin/cachex/commit/f03beed0bdff15581b9bb8080e34b1a215f7e027 , here is how it looks:

![20200909_18h53m04s_grim](https://user-images.githubusercontent.com/37929071/92622582-e0aef000-f2cd-11ea-9505-22cdbefa354e.png)


 If you think this feature makes sense upstream, I will finish the TODOs and submit a PR. 

Pull request:
Surface inner stacktraces from calls to fetch
This fixes #252.

This is based on the awesome work of @rinpatch in that thread, but as they didn't have time to roll it into a full PR, I figured I'd pick it up to get it merged. 

The basic issue is that before this change, calls to fetch which crashed would mask errors, leaving them hard to debug:

```elixir
iex(1)> Cachex.start(:test_cache)
{:ok, #PID<0.694.0>}
iex(2)> Cachex.fetch!(:test_cache, "1.1.1.1", fn key -> :inet.parse_ipv4_address(key) end)
** (Cachex.ExecutionError) no function clause matching in :inet_parse.ipv4_addr/2
    (cachex 3.4.0) lib/cachex.ex:1407: Cachex.unwrap_unsafe/1
```

But with the changes in this PR, we now get much better information and stack traces:

```elixir
iex(1)> Cachex.start(:test_cache)
{:ok, #PID<0.570.0>}
iex(2)> Cachex.fetch!(:test_cache, "1.1.1.1", fn key -> :inet.parse_ipv4_address(key) end)
** (Cachex.ExecutionError) no function clause matching in :inet_parse.ipv4_addr/2
    (kernel 8.1) inet_parse.erl:511: :inet_parse.ipv4_addr("1.1.1.1", [])
    (kernel 8.1) inet_parse.erl:495: :inet_parse.ipv4_addr/1
    (kernel 8.1) inet_parse.erl:486: :inet_parse.ipv4_address/1
    (cachex 3.4.0) lib/cachex/services/courier.ex:76: anonymous fn/5 in Cachex.Services.Courier.handle_call/3
    (cachex 3.4.0) lib/cachex/services/courier.ex:44: Cachex.Services.Courier.dispatch/3
    (cachex 3.4.0) lib/cachex.ex:679: Cachex.fetch/4
    (cachex 3.4.0) lib/cachex.ex:1: Cachex.fetch!/3
```

I tweaked the `ExecutionError` to allow a substack, which can then be re-raised properly. I did this because it might be that transactions also need this loving later on, not sure. There is a decent chunk of overhead to fetch calls now (when they have to actually fetch a resource), because of the loading and passing of the stack. This is the tradeoff for better debugging though, so I'm fairly confident that it's worth it.

This is sort-of a breaking change to the contract of `fetch` in case of errors, but the return type was already `any` as it's controlled by the error of the developer. So I think this is alright to drop in a minor without waiting for a major, especially as the value will generally just be logged (etc) in case of `:error` status. 

Patch:
diff --git a/lib/cachex.ex b/lib/cachex.ex
index b2da970..46c86ce 100644
--- a/lib/cachex.ex
+++ b/lib/cachex.ex
@@ -1405,6 +1405,8 @@ defmodule Cachex do
     do: raise ExecutionError, message: Errors.long_form(value)
   defp unwrap_unsafe({ :error, value }) when is_binary(value),
     do: raise ExecutionError, message: value
+  defp unwrap_unsafe({ :error, %ExecutionError { stack: stack } = e }),
+    do: reraise e, stack
   defp unwrap_unsafe({ _state, value }),
     do: value
 end
diff --git a/lib/cachex/execution_error.ex b/lib/cachex/execution_error.ex
index 55ae5ca..f1b57e6 100644
--- a/lib/cachex/execution_error.ex
+++ b/lib/cachex/execution_error.ex
@@ -14,5 +14,5 @@ defmodule Cachex.ExecutionError do
   The default error message should always be overridden with a long
   error formas displayed inside `Cachex.Errors`.
   """
-  defexception message: "Error during action execution"
+  defexception message: "Error during action execution", stack: nil
 end
diff --git a/lib/cachex/services/courier.ex b/lib/cachex/services/courier.ex
index 50c88d6..d00cc51 100644
--- a/lib/cachex/services/courier.ex
+++ b/lib/cachex/services/courier.ex
@@ -19,6 +19,7 @@ defmodule Cachex.Services.Courier do
 
   # add some aliases
   alias Cachex.Actions.Put
+  alias Cachex.ExecutionError
 
   ##############
   # Public API #
@@ -40,7 +41,7 @@ defmodule Cachex.Services.Courier do
   """
   @spec dispatch(Spec.cache, any, (() -> any)) :: any
   def dispatch(cache() = cache, key, task) when is_function(task, 0),
-    do: service_call(cache, :courier, { :dispatch, key, task })
+    do: service_call(cache, :courier, { :dispatch, key, task, local_stack() })
 
   ####################
   # Server Callbacks #
@@ -64,7 +65,7 @@ defmodule Cachex.Services.Courier do
   # Due to the nature of the async behaviour, this call will return before
   # the task has been completed, and the :notify callback will receive the
   # results from the task after completion (regardless of outcome).
-  def handle_call({ :dispatch, key, task }, caller, { cache, tasks }) do
+  def handle_call({ :dispatch, key, task, stack }, caller, { cache, tasks }) do
     references =
       case Map.get(tasks, key, []) do
         [] ->
@@ -74,7 +75,13 @@ defmodule Cachex.Services.Courier do
               try do
                 task.()
               rescue
-                e -> { :error, Exception.message(e) }
+                e -> {
+                  :error,
+                  %ExecutionError {
+                    message: Exception.message(e),
+                    stack: stack_compat() ++ stack
+                  }
+                }
               end
 
             normalized = normalize_commit(result)
@@ -105,4 +112,17 @@ defmodule Cachex.Services.Courier do
 
     { :noreply, { cache, Map.delete(tasks, key) } }
   end
+
+  ###############
+  # Private API #
+  ###############
+
+  # Generates a stack trace prior to dispatch.
+  defp local_stack do
+    self()
+    |> Process.info(:current_stacktrace)
+    |> elem(1)
+    |> tl
+    |> tl
+  end
 end
diff --git a/lib/cachex/spec.ex b/lib/cachex/spec.ex
index 6067ce7..7f086f4 100644
--- a/lib/cachex/spec.ex
+++ b/lib/cachex/spec.ex
@@ -464,6 +464,18 @@ defmodule Cachex.Spec do
   defmacro via(action, options),
     do: quote(do: [ { :via, unquote(action) } | unquote(options) ])
 
+  @doc """
+  Retrieves the currently handled stacktrace.
+  """
+  @spec stack_compat :: any
+  defmacro stack_compat() do
+    if Version.match?(System.version(), ">= 1.7.0") do
+      quote(do: __STACKTRACE__)
+    else
+      quote(do: System.stacktrace())
+    end
+  end
+
   @doc """
   Wraps a value inside a tagged Tuple using the provided tag.
   """


Test patch:
diff --git a/test/cachex/services/courier_test.exs b/test/cachex/services/courier_test.exs
index 511a2d7..5bf3621 100644
--- a/test/cachex/services/courier_test.exs
+++ b/test/cachex/services/courier_test.exs
@@ -66,7 +66,8 @@ defmodule Cachex.Services.CourierTest do
       raise ArgumentError
     end)
 
-    # check the returned value
-    assert result == { :error, "argument error" }
+    # check the returned value contains the error and the stack trace
+    assert match?({ :error, %Cachex.ExecutionError{ } }, result)
+    assert elem(result, 1).message == "argument error"
   end
 end
diff --git a/test/cachex_test.exs b/test/cachex_test.exs
index 43f6c17..1691e73 100644
--- a/test/cachex_test.exs
+++ b/test/cachex_test.exs
@@ -210,5 +210,12 @@ defmodule CachexTest do
         raise RuntimeError, message: "Ding dong! The witch is dead!"
       end)
     end)
+
+     # validate an unsafe call to fetch handling
+    assert_raise(Cachex.ExecutionError, fn ->
+      Cachex.fetch!(cache, "key", fn(_key) ->
+        raise RuntimeError, message: "Which old witch? The wicked witch!"
+      end)
+    end)
   end
 end