doctests replace the actual test stack trace on failure

[amuino]

The problem

When a doctest fails, the information provided just points to the function declaration and does not include a useful stacktrace to locate the source of the error. This is in contrast with a standard ExUnit test.

This is an example of a doctest failure:

  1) test doc at StringCalculator.add/2 (3) (StringCalculatorTest)
     test/string_calculator_test.exs:3
     Doctest failed: got ArgumentError with message argument error
     code:  StringCalculator.add("1,,2")
            StringCalculator.add("11,22")
     stacktrace:
       lib/string_calculator.ex:52: StringCalculator (module)

And here is the output of the same test in a normal ExUnit test:

  2) test FAIL: consecutive separators (StringCalculatorTest)
     test/string_calculator_test.exs:5
     ** (ArgumentError) argument error
     stacktrace:
       :erlang.binary_to_integer("")
       (string_calculator) lib/string_calculator.ex:85: StringCalculator.to_integer/1
       (elixir) lib/enum.ex:977: anonymous fn/3 in Enum.map/2
       (elixir) lib/enum.ex:1261: Enum."-reduce/3-lists^foldl/2-0-"/3
       (elixir) lib/enum.ex:977: Enum.map/2
       (string_calculator) lib/string_calculator.ex:63: StringCalculator.add/2
       test/string_calculator_test.exs:6

Looking at doc_test.ex on version 1.0.5, the function gen_code_for_tests is replacing the original exception with a synthetic one, less informative.

Simply commenting that stack/exception handling, makes the error reports equally informative as a normal ExUnit test.

The hack

As a quick hack, I copied the file in the project root as an exs and modified the function: _doctest.exs

  defp gen_code_for_tests(tests, whole_expr, stack) do
    quote do
      # stack = unquote(stack)
      # try do
        # Put all tests into one context
        unquote_splicing(tests)
      # rescue
      #   e in [ExUnit.AssertionError] ->
      #     reraise e, stack

      #   error ->
      #     reraise ExUnit.AssertionError,
      #       [message: "Doctest failed: got #{inspect(error.__struct__)} with message #{Exception.message(error)}",
      #        expr: unquote(whole_expr)],
      #       stack
      # end
    end
  end

Then run the tests again, loading this modified version. Note that the bottom of the stack points to the same line as the synthetic exception raised previously, so no information seems to be lost:

$ iex -r doctest.exs -S mix test
[..]
  1) test doc at StringCalculator.add/2 (3) (StringCalculatorTest)
     test/string_calculator_test.exs:3
     ** (ArgumentError) argument error
     stacktrace:
       :erlang.binary_to_integer("")
       (string_calculator) lib/string_calculator.ex:85: StringCalculator.to_integer/1
       (elixir) lib/enum.ex:977: anonymous fn/3 in Enum.map/2
       (elixir) lib/enum.ex:1261: Enum."-reduce/3-lists^foldl/2-0-"/3
       (elixir) lib/enum.ex:977: Enum.map/2
       (string_calculator) lib/string_calculator.ex:63: StringCalculator.add/2
       (for doctest at) lib/string_calculator.ex:52
[..]

Next

I'm quite new to Elixir, so I'd like someone to review this and, it the change makes sense, I can submit a PR.

There are similar changes to be made (I think) for test_case_content, but I had not investigated those properly yet.

[fishcakez]

You have definitely hit on an issue however I think removing the ExUnit.Assertion is undesirable because we lose information about the error (the formatter can not provide the code). A very similar issue occurs for the ex_unit assertion assert_raise, when a different exception is raised than expected. Again the stacktrace is lost.

One possibility would be to add the exception and stacktrace of the caught exception to the ExUnit.Assertion exception map. The formatter could then print the full information if its present in the map using Exception.format/3.

[amuino]

What do you think about capturing the original stacktrace and using it? (I've added comments near the changes)

  defp gen_code_for_tests(tests, whole_expr, stack) do
    quote do
      stack = unquote(stack)
      try do
        # Put all tests into one context
        unquote_splicing(tests)
      rescue
        e in [ExUnit.AssertionError] ->
          reraise e, stack

        error ->
          # ↓ The line below is new ↓
          original_stack = System.stacktrace
          reraise ExUnit.AssertionError,
            [message: "Doctest failed: got #{inspect(error.__struct__)} with message #{Exception.message(error)}",
             expr: unquote(whole_expr)],
            original_stack #  ⃪ replace the synthetic stack with the actual one
      end
    end
  end

The stack is preserved, and so is the doctest code.

  2) test doc at StringCalculator.add/2 (3) (StringCalculatorTest)
     test/string_calculator_test.exs:3
     Doctest failed: got ArgumentError with message argument error
     code:  StringCalculator.add("1,,2")
            StringCalculator.add("11,22")
     stacktrace:
       :erlang.binary_to_integer("")
       (string_calculator) lib/string_calculator.ex:85: StringCalculator.to_integer/1
       (elixir) lib/enum.ex:977: anonymous fn/3 in Enum.map/2
       (elixir) lib/enum.ex:1261: Enum."-reduce/3-lists^foldl/2-0-"/3
       (elixir) lib/enum.ex:977: Enum.map/2
       (string_calculator) lib/string_calculator.ex:63: StringCalculator.add/2
       (for doctest at) lib/string_calculator.ex:52

[fishcakez]

I am not keen on it because we should not alter the source of an exception. :erlang.binary_to_integer/1 can not raise ExUnit.Assertion. We should provide the same solution here as to the assert_raise issue I mentioned briefly:

For example:

defmodule AssertRaiseTest do
  use ExUnit.Case

  test "wrong exceptions" do
    assert_raise ArgumentError, fn() -> other_fun() end
  end

  defp other_fun(), do: raise "oops"
end

Results in:

  1) test wrong exceptions (AssertRaiseTest)
     test/assert_raise_test.exs:4
     Expected exception ArgumentError but got RuntimeError (oops)
     stacktrace:
       test/assert_raise_test.exs:5

It would be good to know way that RuntimeError came from.

[amuino]

For the sake of the argument the doctests can not raise ArgumentError either.

Note that the whole stacktrace is already being replaced by a synthetic one. Elixir is already altering the source of the exception.

So by using the actual stacktrace, it is my understanding that ExUnit will "tell a lesser lie".

I haven't explored the issue with assert_raise, but I'm inclined to believe that it is different since there is no asymmetry between the result of a doctest and a plain test.

But since I'm just dabbling in Elixir, I'll take a step back :-)

[fishcakez]

It is using a synthetic one so we get the best possible stacktrace for the new exception. Yes, it is naughty but it is better than an unhelpful one that would be generated by raising directly. The lesser of two evils, exactly :see_no_evil:.

The assert_raise rescue and raise is done here: https://github.com/elixir-lang/elixir/blob/e934e3c92edbc9c83da7795ec3a028ff86218c4b/lib/ex_unit/lib/ex_unit/assertions.ex#L359. flunk raises an ExUnit.AssertionError with the message passed to it.

The issues are not identical, but in both cases an exception is being caught and a new ExUnit.AssertionError is being raised. In both cases the old stacktrace for the original exception is lost and when the exception is caught and then formatted the new stacktrace is used and the source of the original exception is unknown. It would be nice if the solution could carry over.

When we re-raise the ExUnit.AssertionError in the doc tests: https://github.com/elixir-lang/elixir/blob/e934e3c92edbc9c83da7795ec3a028ff86218c4b/lib/ex_unit/lib/ex_unit/doc_test.ex#L261, I think we have another bug and should use the old stacktrace, as thats where the exception came from: System.stacktrace().

I think you are being a bit modest, if we are calling it dabbling you are certainly dabbling very well to have picked these issues up. Please feel free to step back up if you have time :).

[josevalim]

@fishcakez should we just append the source stacktrace (the one we are passing in) to the runtime one? The source one contains only one entry and the goal is to make it point to the function definition.

Another idea is to include the source information in the AssertionError somehow so we don't mess up with the original one. For example:

  1) test doc at StringCalculator.add/2 (3) (StringCalculatorTest)
     test/string_calculator_test.exs:3
     Doctest for StringCalculator (module) (lib/string_calculator.ex:52)
     failed with ArgumentError and message argument error
     code:  StringCalculator.add("1,,2")
            StringCalculator.add("11,22")
     stacktrace:
       :erlang.binary_to_integer("")
       (string_calculator) lib/string_calculator.ex:85: StringCalculator.to_integer/1
       (elixir) lib/enum.ex:977: anonymous fn/3 in Enum.map/2
       (elixir) lib/enum.ex:1261: Enum."-reduce/3-lists^foldl/2-0-"/3
       (elixir) lib/enum.ex:977: Enum.map/2
       (string_calculator) lib/string_calculator.ex:63: StringCalculator.add/2
       test/string_calculator_test.exs:6

There is a lot of information here and there are probably better ways to show it but I think it shows the point well.

[josevalim]

Here is how it could look like if we append the stacktrace:

  1) test doc at StringCalculator.add/2 (3) (StringCalculatorTest)
     test/string_calculator_test.exs:3
     Doctest failed: got ArgumentError with message argument error
     code:  StringCalculator.add("1,,2")
            StringCalculator.add("11,22")
     stacktrace:
       :erlang.binary_to_integer("")
       (string_calculator) lib/string_calculator.ex:85: StringCalculator.to_integer/1
       (elixir) lib/enum.ex:977: anonymous fn/3 in Enum.map/2
       (elixir) lib/enum.ex:1261: Enum."-reduce/3-lists^foldl/2-0-"/3
       (elixir) lib/enum.ex:977: Enum.map/2
       (string_calculator) lib/string_calculator.ex:63: StringCalculator.add/2
       (string_calculator) from doctest at lib/string_calculator.ex:52: StringCalculator (module)

[fishcakez]

I think I prefer passing it in the exception itself because lying about the stacktrace can lead to confusion. It also allows us to solve the related issue with assert_raise. But any improvement would be great.

On Friday, 7 August 2015, José Valim notifications@github.com wrote:

Here is how it could look like if we append the stacktrace:

1) test doc at StringCalculator.add/2 (3) (StringCalculatorTest) test/string_calculator_test.exs:3 Doctest failed: got ArgumentError with message argument error code: StringCalculator.add("1,,2") StringCalculator.add("11,22") stacktrace: :erlang.binary_to_integer("") (string_calculator) lib/string_calculator.ex:85: StringCalculator.to_integer/1 (elixir) lib/enum.ex:977: anonymous fn/3 in Enum.map/2 (elixir) lib/enum.ex:1261: Enum."-reduce/3-lists^foldl/2-0-"/3 (elixir) lib/enum.ex:977: Enum.map/2 (string_calculator) lib/string_calculator.ex:63: StringCalculator.add/2 (string calculator) (from doctest) lib/string_calculator.ex:52: StringCalculator (module)

— Reply to this email directly or view it on GitHub https://github.com/elixir-lang/elixir/issues/3555#issuecomment-128808937 .

[amuino]

I've submitted a PR just to make it easier to compare the solutions (specially diffing).

@fishcakez I'm not being modest… I've only been learning Elixir for about 2 weeks, going through the getting started guide. So beware! :-)