Log Elixir test result for investigation and include this log file in travis for troubleshooting failed tests

.travis.yml

@@ -59,6 +59,7 @@ after_script:
   - find logs -name suite.log -exec cat '{}' ';'
 
 after_failure:
+  - find logs -name exunit.log -exec cat '{}' ';'
   # Try checking Riak database logs
   - tail -n 100000 /var/log/riak/*.log
   - find logs -name ejabberd.log -exec cat '{}' ';'

lib/ct_formatter.ex

@@ -0,0 +1,130 @@
+defmodule ExUnit.CTFormatter do
+  @moduledoc false
+
+  use GenEvent
+
+  import ExUnit.Formatter, only: [format_time: 2, format_filters: 2, format_test_failure: 5,
+                                  format_test_case_failure: 5]
+
+  def init(opts) do
+    file = File.open! "exunit.log", [:append]
+    # We do not print filter in log file as exclusion of test with tag
+    # pending: true is always done
+    config = %{
+      file: file,
+      seed: opts[:seed],
+      trace: opts[:trace],
+      colors: Keyword.put_new(opts[:colors], :enabled, false),
+      width: 80,
+      tests_counter: 0,
+      failures_counter: 0,
+      skipped_counter: 0,
+      invalids_counter: 0
+    }
+    {:ok, config}
+  end
+
+  def handle_event({:suite_started, _opts}, config) do
+    {:ok, config}
+  end
+
+  def handle_event({:suite_finished, run_us, load_us}, config) do
+    print_suite(config, run_us, load_us)
+    File.close config[:file]
+    :remove_handler
+  end
+
+  def handle_event({:test_started, %ExUnit.Test{} = test}, config) do
+    if config.tests_counter == 0, do: IO.binwrite config[:file], "== Running #{test.case} ==\n\n"
+    {:ok, config}
+  end
+
+  def handle_event({:test_finished, %ExUnit.Test{state: nil} = _test}, config) do
+    IO.binwrite config[:file], "."
+    {:ok, %{config | tests_counter: config.tests_counter + 1}}
+  end
+
+  def handle_event({:test_finished, %ExUnit.Test{state: {:skip, _}} = _test}, config) do
+    {:ok, %{config | tests_counter: config.tests_counter + 1,
+                     skipped_counter: config.skipped_counter + 1}}
+  end
+
+  def handle_event({:test_finished, %ExUnit.Test{state: {:invalid, _}} = _test}, config) do
+    IO.binwrite config[:file], "?"
+    {:ok, %{config | tests_counter: config.tests_counter + 1,
+                     invalids_counter: config.invalids_counter + 1}}
+  end
+
+  def handle_event({:test_finished, %ExUnit.Test{state: {:failed, failures}} = test}, config) do
+    formatted = format_test_failure(test, failures, config.failures_counter + 1,
+                                    config.width, &formatter(&1, &2, config))
+    print_failure(formatted, config)
+    print_logs(test.logs)
+
+    {:ok, %{config | tests_counter: config.tests_counter + 1,
+                     failures_counter: config.failures_counter + 1}}
+  end
+
+  def handle_event({:case_started, %ExUnit.TestCase{}}, config) do
+    {:ok, config}
+  end
+
+  def handle_event({:case_finished, %ExUnit.TestCase{state: nil}}, config) do
+    {:ok, config}
+  end
+
+  def handle_event({:case_finished, %ExUnit.TestCase{state: {:failed, failures}} = test_case}, config) do
+    formatted = format_test_case_failure(test_case, failures, config.failures_counter + 1,
+                                         config.width, &formatter(&1, &2, config))
+    print_failure(formatted, config)
+    {:ok, %{config | failures_counter: config.failures_counter + 1}}
+  end
+
+  ## Printing
+
+  defp print_suite(config, run_us, load_us) do
+    IO.binwrite config[:file], "\n\n"
+    IO.binwrite config[:file], format_time(run_us, load_us)
+    IO.binwrite config[:file], "\n\n"
+
+    # singular/plural
+    test_pl = pluralize(config.tests_counter, "test", "tests")
+    failure_pl = pluralize(config.failures_counter, "failure", "failures")
+
+    message =
+      "#{config.tests_counter} #{test_pl}, #{config.failures_counter} #{failure_pl}"
+      |> if_true(config.skipped_counter > 0, & &1 <> ", #{config.skipped_counter} skipped")
+      |> if_true(config.invalids_counter > 0, & &1 <> ", #{config.invalids_counter} invalid")
+
+    cond do
+      config.failures_counter > 0 -> IO.binwrite config[:file], message
+      config.invalids_counter > 0 -> IO.binwrite config[:file], message
+      true                        -> IO.binwrite config[:file], message
+    end
+
+    IO.binwrite config[:file], "\nRandomized with seed #{config.seed}\n\n\n\n"
+  end
+
+  defp if_true(value, false, _fun), do: value
+  defp if_true(value, true, fun), do: fun.(value)
+
+  defp print_failure(formatted, config) do
+    IO.binwrite config[:file], "\n"
+    IO.binwrite config[:file], formatted
+    IO.binwrite config[:file], "\n"
+  end
+
+  defp formatter(_,  msg, _config),
+    do: msg
+
+  defp pluralize(1, singular, _plural), do: singular
+  defp pluralize(_, _singular, plural), do: plural
+
+  defp print_logs(""), do: nil
+
+  defp print_logs(output) do
+    indent = "\n     "
+    output = String.replace(output, "\n", indent)
+    IO.puts(["     The following output was logged:", indent | output])
+  end
+end

test/elixir_SUITE.erl

@@ -30,7 +30,7 @@ all() ->
     case is_elixir_available() of
 	true ->
 	    Dir = test_dir(),
-	    filelib:fold_files(Dir, ".*\.exs$", false,
+	    filelib:fold_files(Dir, ".*test\.exs$", false,
 			       fun(Filename, Acc) -> [list_to_atom(filename:basename(Filename)) | Acc] end,
 			       []);
 	false ->
@@ -68,7 +68,7 @@ undefined_function(Module, Func, Args) ->
 run_elixir_test(Func) ->
     %% Elixir tests can be tagged as follow to be ignored (place before test start)
     %% @tag pending: true
-    'Elixir.ExUnit':start([{exclude, [{pending, true}]}]),
+    'Elixir.ExUnit':start([{exclude, [{pending, true}]}, {formatters, ['Elixir.ExUnit.CLIFormatter', 'Elixir.ExUnit.CTFormatter']}]),
 
     filelib:fold_files(test_dir(), ".*mock\.exs\$", true,
                        fun (File, N) ->
@@ -84,8 +84,9 @@ run_elixir_test(Func) ->
             %% Zero failures
             ok;
         {ok, Failures} ->
-            ct:print("Elixir test failed in module '~p': ~.10B~nSee logs for details", [Func, Failures]),
+            ct:print("Tests failed in module '~s': ~.10B failures.~nSee logs for details", [Func, Failures]),
-            ct:fail(elixir_test_failure)
+            ct:fail(elixir_test_failure),
+            error
     end.
 
 test_dir() ->