search

erlang / rebar3

Erlang build tool that makes it easy to compile and test Erlang applications and releases.
http://www.rebar3.org
Apache License 2.0
1.7k stars 518 forks source link

Common test error on OTP 21.2 #2063

Closed larshesel closed 5 years ago

larshesel commented 5 years ago

Pre-Check

Environment

./rebar3 report do eunit, ct
Rebar3 report
 version 3.10.0
 generated at 2019-05-02T14:19:13+00:00
=================
Please submit this along with your issue at https://github.com/erlang/rebar3/issues (and feel free to edit out private information, if any)
-----------------
Task: doeunit,ct
Entered as:
  doeunit,ct
-----------------
Operating System: x86_64-unknown-linux-gnu
ERTS: Erlang/OTP 21 [erts-10.2] [source] [64-bit] [smp:4:4] [ds:4:4:10] [async-threads:1] [hipe]
Root Directory: /home/opt/erlang/erlang21.2
Library directory: /home/opt/erlang/erlang21.2/lib
-----------------
Loaded Applications:
bbmustache: 1.6.1
certifi: 2.5.1
cf: 0.2.2
common_test: 1.16.1
compiler: 7.3
crypto: 4.4
cth_readable: 1.4.3
dialyzer: 3.3.1
edoc: 0.9.4
erlware_commons: 1.3.1
eunit: 2.3.7
eunit_formatters: 0.5.0
getopt: 0.8.2
hipe: 3.18.2
inets: 7.0.3
kernel: 6.2
providers: 1.7.0
public_key: 1.6.4
relx: 3.31.0
sasl: 3.3
snmp: 5.2.12
ssl_verify_fun: 1.1.4
stdlib: 3.7
syntax_tools: 2.1.6
tools: 3.0.2

-----------------
Escript path: /home/lhc/dev/octavolabs/vernemq/rebar3
Providers:
  app_discovery as clean compile compile cover ct deps dialyzer do edoc escriptize eunit get-deps help install install_deps list lock new path pkgs release release relup report repos shell state tar tar tree unlock update upgrade upgrade upgrade version xref

Current behaviour

When running rebar3 do eunit, ct on VerneMQ master (https://github.com/vernemq/vernemq/) we end up with the following error:

===> Error running tests:
  "Failed to start CTH, see the CT Log for details"

It should be noted no errors occur if running simply rebar3 ct. Also, if run with --readable=false no error happens, this is similar to #1778, but since that was fixed this is probably something else.

The above error also happens with the rebar3 version on master (3.9.1)

The DEBUG=1 output can be found in this gist: https://gist.github.com/larshesel/4422fb3d13a51c9940473c1d0601d4a6

And the output from the CT Log:

*** CT 2019-05-02 16:30:45.449 *** Suite Hook
Failed to start a CTH: error:{{case_clause,{error,{not_found,default}}},
                              [{cth_readable_failonly,
                                maybe_steal_logger_config,0,
                                [{file,
                                  "/opt/rebar3-3.10.0/_build/default/lib/cth_readable/src/cth_readable_failonly.erl"},
                                 {line,300}]},
                               {cth_readable_failonly,init,2,
                                [{file,
                                  "/opt/rebar3-3.10.0/_build/default/lib/cth_readable/src/cth_readable_failonly.erl"},
                                 {line,89}]},
                               {ct_hooks,call_init,3,
                                [{file,"ct_hooks.erl"},{line,157}]},
                               {ct_hooks,call,4,
                                [{file,"ct_hooks.erl"},{line,237}]},
                               {ct_hooks,call,4,
                                [{file,"ct_hooks.erl"},{line,240}]},
                               {ct_hooks,call,4,
                                [{file,"ct_hooks.erl"},{line,225}]},
                               {ct_util,do_start,4,
                                [{file,"ct_util.erl"},{line,204}]}]}

*** CT 2019-05-02 16:30:45.551 *** Suite Hook
Call to CTH failed: error:{function_clause,
                           [{cth_readable_failonly,terminate,
                             [[]],
                             [{file,
                               "/opt/rebar3-3.10.0/_build/default/lib/cth_readable/src/cth_readable_failonly.erl"},
                              {line,193}]},
                            {ct_hooks,catch_apply,3,
                             [{file,"ct_hooks.erl"},{line,413}]},
                            {ct_hooks,call_terminate,3,
                             [{file,"ct_hooks.erl"},{line,172}]},
                            {ct_hooks,call,4,
                             [{file,"ct_hooks.erl"},{line,237}]},
                            {ct_hooks,call,4,
                             [{file,"ct_hooks.erl"},{line,240}]},
                            {ct_hooks,terminate,1,
                             [{file,"ct_hooks.erl"},{line,55}]},
                            {ct_util,loop,3,
                             [{file,"ct_util.erl"},{line,460}]}]}

*** CT 2019-05-02 16:30:45.570 *** Common Test Logger finished

Expected behaviour

running rebar3 do eunit, ct should work without errors.

ferd commented 5 years ago

So the error appears to be due to no default configuration being found for the logger.

It would be simple to add a case that handles the error value and returns undefined in https://github.com/ferd/cth_readable/blob/d9cefd0abb31c151c6dbda53e249f65c225bd7df/src/cth_readable_failonly.erl#L300-L305 (although that may cause breakage in other parts of the setup and might need to force a skipping of logger forwarding altogether)

But I'd like to know if you have any special configurations or changes that are made such that you do not have a default value for logger. That's definitely weird, but might possibly happen in cases where your own tests change a bunch of values, delete them, or something to that effect.

larshesel commented 5 years ago

So I think I found out what the problem is, simply starting lager has the effect of removing the default logger: 

1> application:ensure_all_started(lager).
{ok,[syntax_tools,compiler,goldrush,lager]}
2> logger:get_handler_config().          
[#{filter_default => log,filters => [],
   formatter => {logger_formatter,#{}},
   id => error_logger,level => info,module => error_logger}]

And we do start lager in the eunit tests, which then trips over when the common tests are started. I found this over on the lager repo: https://github.com/erlang-lager/lager/pull/488, so this is on purpose.

Do you know if there are any conventions on which logger should / must be available? Is rebar3making an (un)reasonable assumption that there's a default handler or is lager?

ferd commented 5 years ago

There is no standard about anything. I'm just guessing as I go trying to support people's setup, and it's all very reactive. Lager didn't use to have support for logger and therefore wouldn't impact it, so that's a new thing to take into consideration that did not exist before.

ferd commented 5 years ago

https://github.com/ferd/cth_readable/pull/23 might patch it. I'm tired though so I'll double-check tomorrow before publishing and opening a PR here.

aboroska commented 5 years ago

Tested with:

and the reported problem seems to be fixed by the patch. Thank you @ferd!

larshesel commented 5 years ago

I just tested your patch and common test no longer crashes. Thanks a lot!