Exceptions and stack traces

[yrashk]

I have a strong suspicion that we need to improve our exception raising with regards to stack traces. I am observing less than optimal behaviour with our current implementation.

Basically, I suspect that the root of the problem is in the fact that Kernel.raise is a set of functions, not macros, and they are ultimately creating a problem by messing up the stack.

Observe this:

defmodule X do

 defexception E, message: "x"

 def t do
   raise E
 end

end
iex(3)> X.t
** (X.E) x
    erl_eval.erl:569: :erl_eval.do_apply/6
    src/elixir.erl:138: :elixir.eval_forms/3

Nowhere here you can actually see where the raise is happening. I "discovered" this problem in the real system we're developing when I started paying more attention to logs — our logging shows this every day — and now we have to guess where a lot of errors come from. That's quite painful :)

I made a proof of concept patch for v0.10.2 (didn't have a chance to upgrade to master yet), and I am getting very positive results:

iex(2)> X.t
** (X.E) x
    iex:6: X.t/0
    erl_eval.erl:569: :erl_eval.do_apply/6
    src/elixir.erl:138: :elixir.eval_forms/3

As you can see, it actually properly invluces X.t/0 into the stacktrace.
Is there any interest to fix this? My patch is not perfect, but it was useful in illustrating the potential in fixing this problem.

P..S. My quick-n-dirty patch:

diff --git a/lib/elixir/lib/kernel.ex b/lib/elixir/lib/kernel.ex
index 2cf8c29..e70c813 100644
--- a/lib/elixir/lib/kernel.ex
+++ b/lib/elixir/lib/kernel.ex
@@ -1,5 +1,3 @@
-import Kernel, except: [raise: 1, raise: 2]
-
 defmodule Kernel do
   @moduledoc """
   `Kernel` provides the default macros and functions
@@ -2015,8 +2013,7 @@ defmodule Kernel do

     case is_atom(expanded) do
       false ->
-        raise ArgumentError,
-          message: "invalid arguments for use, expected an atom or alias as argument"
+        :erlang.error ArgumentError.exception(message: "invalid arguments for use, expected an atom or alias as argument")
       true ->
         quote do
           require unquote(expanded)
@@ -2652,8 +2649,8 @@ defmodule Kernel do
     new_acc =
       case condition do
         { :_, _, atom } when is_atom(atom) ->
-          raise ArgumentError, message: <<"unbound variable _ inside cond. ",
-            "If you want the last clause to match, you probably meant to use true ->">>
+          :erlang.error ArgumentError.exception(message: <<"unbound variable _ inside cond. ",
+            "If you want the last clause to match, you probably meant to use true ->">>)
         x when is_atom(x) and not x in [false, nil] ->
           clause
         _ ->
@@ -3095,7 +3092,7 @@ defmodule Kernel do
   end

   defp pipeline_op(_, arg) do
-    raise ArgumentError, message: "unsupported expression in pipeline |> operator: #{Macro.to_string arg}"
+    :erlang.error ArgumentError.exception(message: "unsupported expression in pipeline |> operator: #{Macro.to_string arg}")
   end

   @doc """
@@ -3120,12 +3117,10 @@ defmodule Kernel do

   """
   @spec raise(binary | atom | tuple) :: no_return
-  def raise(msg) when is_binary(msg) do
-    :erlang.error RuntimeError[message: msg]
-  end
-
-  def raise(exception) do
-    raise(exception, [])
+  defmacro raise(msg) when is_binary(msg) do
+    quote do
+      :erlang.error RuntimeError[message: unquote(msg)]
+    end
   end

   @doc """
@@ -3146,8 +3141,15 @@ defmodule Kernel do

   """
   @spec raise(tuple | atom, list) :: no_return
-  def raise(exception, args) do
-    :erlang.error exception.exception(args)
+  defmacro raise(exception, args // []) do
+    quote do
+      case unquote(exception) do
+        e when is_binary(e) ->
+          :erlang.error RuntimeError.new(message: unquote(exception))
+        _ ->
+          :erlang.error unquote(exception).exception(unquote(args))
+      end
+    end
   end

   @doc """
@@ -3288,15 +3290,15 @@ defmodule Kernel do
                 { :error, _ } ->
                   :elixir_aliases.ensure_loaded(caller.line, caller.file, atom, caller.context_modules)
                 _ ->
-                  raise ArgumentError, message: "cannot use module #{inspect atom} in access protocol because it does not export __record__/1"
+                  :erlang.error ArgumentError.exception(message: "cannot use module #{inspect atom} in access protocol because it does not export __record__/1")
               end
           end

         Record.access(atom, fields, args, caller)
       false ->
         case caller.in_match? do
-          true  -> raise ArgumentError, message: << "the access protocol cannot be used inside match clauses ",
-                     "(for example, on the left hand side of a match or in function signatures)" >>
+          true  -> :erlang.error ArgumentError.exception(message: << "the access protocol cannot be used inside match clauses ",
+                     "(for example, on the left hand side of a match or in function signatures)" >>)
           false -> quote do: Access.access(unquote(element), unquote(args))
         end
     end
@@ -3347,14 +3349,14 @@ defmodule Kernel do
     funs = Macro.escape(funs, unquote: true)
     quote bind_quoted: [funs: funs, opts: opts] do
       target = Keyword.get(opts, :to) ||
-        raise(ArgumentError, message: "Expected to: to be given as argument")
+        :erlang.error ArgumentError.exception(message: "Expected to: to be given as argument")

       append_first = Keyword.get(opts, :append_first, false)

       lc fun inlist List.wrap(funs) do
         case Macro.extract_args(fun) do
           { name, args } -> :ok
-          :error -> raise ArgumentError, message: "invalid syntax in defdelegate #{Macro.to_string(fun)}"
+          :error -> :erlang.error ArgumentError.exception(message: "invalid syntax in defdelegate #{Macro.to_string(fun)}")
         end

         actual_args =
@@ -3616,7 +3618,7 @@ defmodule Kernel do
         IO.write "%w()b is deprecated, please use %w()s instead\n#{Exception.format_stacktrace}"
         ?s
       [mod] when mod in [?s, ?a, ?c] -> mod
-      _else -> raise ArgumentError, message: "modifier must be one of: s, a, c"
+      _else -> :erlang.error ArgumentError.exception(message: "modifier must be one of: s, a, c")
     end

     case is_binary(string) do
diff --git a/lib/elixir/test/elixir/exception_test.exs b/lib/elixir/test/elixir/exception_test.exs
index cd10fea..e38ef34 100644
--- a/lib/elixir/test/elixir/exception_test.exs
+++ b/lib/elixir/test/elixir/exception_test.exs
@@ -84,6 +84,19 @@ defmodule Kernel.ExceptionTest do
     assert ErlangError.new(original: :sample).message == "erlang error: :sample"
   end

+  test :raise_preserves_the_stacktrace do
+    stacktrace =
+    try do
+      raise "a"
+    rescue _ -> 
+      [top|_] = System.stacktrace
+      top
+    end
+    file = to_char_list(__FILE__)
+    assert {Kernel.ExceptionTest, :test_raise_preserves_the_stacktrace, _,
+           [file: ^file, line: 90]} = stacktrace # line #90 is sensitive
+  end
+
   defp empty_tuple, do: {}
   defp a_tuple, do: { :foo, :bar, :baz }
   defp a_list,  do: [ :foo, :bar, :baz ]

Tests pass. I can send a PR if necessary

[meh]

👍

[krestenkrab]

On a related note ... I noticed in the code generation that something like the following is relatively often generated from Elixir code:

try
    try Expression
    catch C:M -> ...
    end
catch C:E -> erlang:raise(C,E,erlang:get_stacktrace())
end

This has several problems

1. The latter catch clause is dead code which Erjang borked on because we didn't handle unreachable exception handlers (or rather, we did eliminate the code in the handler, but not the meta-data to tell the VM where to go in case of an exception).
2. Calling erlang:raise/3 is much more inefficient than the built-in re-raise, because it needs to reify the stack.

I don't know the elixir codebase well enough to see what causes this, but it's just a little sub-optimal thing.

[josevalim]

@krestenkrab do you have an example of code when this is generated? There is a chance this is a bug. :)

[josevalim]

@yrashk Great find. Your patch is almost perfect, just your raise/2 implementation is unquoting exception more than once. The proper implementation would be:

• defmacro raise(exception, args // []) do
• quote do

•  exception = unquote(exception)
  

•  case exception do
  

•    e when is_binary(e) ->
  

•      :erlang.error RuntimeError.new(message: exception)
  

•    _ ->
  

•      :erlang.error exception.exception(unquote(args))
  

•  end
  

• end

Could you please send a pull request or commit your fixes straight to master? :) Thanks!

[yrashk]

Will send an updated PR