Logger config is not loaded from sys.config when running CT tests

[bryanhughes]

Pre-Check

Spoke with Tristan and he said to file a bug. This appears to be a regression and related to issue 1861

Environment

Rebar3 report
 version 3.12.0
 generated at 2019-09-19T22:38:05+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: Logger
Entered as:
  Logger config is not loaded from sys.config when running CT tests
-----------------
Operating System: x86_64-unknown-linux-gnu
ERTS: Erlang/OTP 22 [erts-10.4.4] [source] [64-bit] [smp:12:12] [ds:12:12:10] [async-threads:1] [hipe]
Root Directory: /usr/lib/erlang
Library directory: /usr/lib/erlang/lib
-----------------
Loaded Applications:
bbmustache: 1.6.1
certifi: 2.5.1
cf: 0.2.2
common_test: 1.17.3
compiler: 7.4.4
crypto: 4.5.1
cth_readable: 1.4.5
dialyzer: 4.0.3
edoc: 0.11
erlware_commons: 1.3.1
eunit: 2.3.7
eunit_formatters: 0.5.0
getopt: 1.0.1
hipe: 3.19.1
inets: 7.0.9
kernel: 6.4.1
providers: 1.8.1
public_key: 1.6.7
relx: 3.33.0
sasl: 3.4
snmp: 5.3
ssl_verify_fun: 1.1.5
stdlib: 3.9.2
syntax_tools: 2.2
tools: 3.2

-----------------
Escript path: undefined
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 relup report repos run services shell state tar tree unlock update upgrade upgrade upgrade version xref 

Current behaviour

When running a CT test with rebar3 the logger formatting from sys.config is not being picked up. I am using an alias that includes the config:

{alias, [
    {services, [{ct, "--dir=test/gruvy_services --sys_config=config/sys.config --cover_export_name=core --name testrunner@127.0.0.1"}]}
]}.

My sys.config

[
    {kernel, [
        {logger, [
            {handler, default, logger_std_h,
             #{formatter => {logger_formatter, #{single_line => true,
                                                 template => [time," ",mfa,":",line," ",pid," [",level,"] ",msg,"\n"]}}}},
            {handler, disk_log, logger_disk_log_h,
             #{config => #{file => "logs/error",
                           type => wrap,
                           max_no_files => 10,
                           max_no_bytes => 52428800},
               level => error,
               formatter => {logger_formatter, #{single_line => true,
                                                 template => [time," ",mfa,":",line," ",pid," [",level,"] ",msg,"\n"]}}}}
        ]},
        {logger_level, info}
    ]},

   ...
].

When I run rebar3 services I get:

=INFO REPORT==== 19-Sep-2019::15:10:26.943267 ===

--------------------------------------------- New Launch ---------------------------------------------
=INFO REPORT==== 19-Sep-2019::15:10:26.943386 ===
Version: <<"1.0.12">>
=INFO REPORT==== 19-Sep-2019::15:10:26.943501 ===
Starting core supervisor.
=INFO REPORT==== 19-Sep-2019::15:10:26.943615 ===
pgo -> []
=INFO REPORT==== 19-Sep-2019::15:10:26.943693 ===
Finished starting...
=INFO REPORT==== 19-Sep-2019::15:10:26.944544 ===
SSL options: {ssl_opts,undefined} from []
=INFO REPORT==== 19-Sep-2019::15:10:26.944641 ===
Starting "http" listener on port: 8080
=PROGRESS REPORT==== 19-Sep-2019::15:10:26.958728 ===
    supervisor: {local,kernel_safe_sup}
    started: [{pid,<0.915.0>},
              {id,timer_server},
              {mfargs,{timer,start_link,[]}},
              {restart_type,permanent},
              {shutdown,1000},
              {child_type,worker}]
=PROGRESS REPORT==== 19-Sep-2019::15:10:26.962216 ===
    supervisor: {local,gruvy_services_sup}
    started: [{pid,<0.913.0>},
              {id,gruvy_http},
              {mfargs,
                  {elli,start_link,
                      [[{callback,elli_middleware},
                        {callback_args,
                            [{mods,[{elli_date,[]},{gruvy_http,[]}]}]},
                        {port,8080},
                        {request_timeout,65000}]]}},
              {restart_type,permanent},
              {shutdown,5000},
              {child_type,worker}]
=INFO REPORT==== 19-Sep-2019::15:10:26.963395 ===
Starting router. PID=<0.938.0>

Expected behaviour

When I run rebar3 shell I get the correct formatting:

2019-09-19T15:19:03.692332-07:00 gruvy_core_sup:init/0:38 <0.1441.0> [info] Version: <<"1.0.12">>
2019-09-19T15:19:03.692380-07:00 gruvy_core_sup:init/0:39 <0.1441.0> [info] Starting core supervisor.
2019-09-19T15:19:03.692461-07:00 gruvy_core_sup:init/0:42 <0.1441.0> [info] pgo -> []
2019-09-19T15:19:03.692553-07:00 gruvy_core_sup:init/0:47 <0.1441.0> [info] Finished starting...
2019-09-19T15:19:03.699446-07:00 gruvy_services_sup:init/0:35 <0.1443.0> [info] SSL options: {ssl_opts,undefined} from []
2019-09-19T15:19:03.699543-07:00 gruvy_services_sup:init/0:40 <0.1443.0> [info] Starting "http" listener on port: 8080
2019-09-19T15:19:03.718296-07:00 supervisor:report_progress/2:1419 <0.1443.0> [info] supervisor: {local,gruvy_services_sup}, started: [{pid,<0.1444.0>},{id,gruvy_http},{mfargs,{elli,start_link,[[{callback,elli_middleware},{callback_args,[{mods,[{elli_date,[]},{gruvy_http,[]}]}]},{port,8080},{request_timeout,65000}]]}},{restart_type,permanent},{shutdown,5000},{child_type,worker}]
2019-09-19T15:19:03.719023-07:00 gruvy_router:init/0:89 <0.1466.0> [info] Starting router. PID=<0.1466.0>

[keynslug]

Yeah, part of the issue you're describing here is what I was trying to address with ferd/cth_readable#26. I believe another part is that rebar3 is skipping dynamic logger reconfiguration when running common tests.

[ferd]

See https://github.com/erlang/rebar3/pull/2165

[keynslug]

Great work!