From 2900aa208f4481c600900f28fb19d71b5c898141 Mon Sep 17 00:00:00 2001 From: Mickael Remond Date: Wed, 6 Apr 2016 17:55:56 +0200 Subject: [PATCH] Log Elixir test result for investigation and include this log file in travis for troubleshooting failed tests --- .travis.yml | 1 + lib/ct_formatter.ex | 130 ++++++++++++++++++++++++++++++++++++++++++ test/elixir_SUITE.erl | 9 +-- 3 files changed, 136 insertions(+), 4 deletions(-) create mode 100644 lib/ct_formatter.ex diff --git a/.travis.yml b/.travis.yml index ce5aafe5a..0dd13892c 100644 --- a/.travis.yml +++ b/.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 '{}' ';' diff --git a/lib/ct_formatter.ex b/lib/ct_formatter.ex new file mode 100644 index 000000000..47c487ac4 --- /dev/null +++ b/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 diff --git a/test/elixir_SUITE.erl b/test/elixir_SUITE.erl index 7e2aa97a4..48cc94f8e 100644 --- a/test/elixir_SUITE.erl +++ b/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:fail(elixir_test_failure) + ct:print("Tests failed in module '~s': ~.10B failures.~nSee logs for details", [Func, Failures]), + ct:fail(elixir_test_failure), + error end. test_dir() ->