Confusing behaviour with eunit tests

[richmeta]

Hello,

I'd like to include lager logging for eunit tests but I'm having problems with even simple configuration. I'd like to see all logs in "log/tests.log" so I have one file handler set to debug.

However with this configuration nothing is logged. But if I add a lager:error line in the test then some logging (but not all) appears.

My theory is the lager parse transform isn't working correctly with eunit which itself uses a parse_transform for exporting test functions.

Anyway, I've done a minimal sample application to demostrate (Erlang R21.3).

%% rebar.config
{deps, [{lager, "3.9.2"}]}.

{erl_opts, [
    debug_info,
    {parse_transform, lager_transform},
    nowarn_export_all
]}.

{eunit_opts, [{sys_config, "config/test.config"}]}.

%% config/test.config
[
    {hello, [
        {name, bob}
    ]},

    {lager, [
        {log_root, "log"},
        {handlers, [
            {lager_file_backend, [{file, "tests.log"}, {level, debug}]}
        ]},
        {async_threshold, undefined}
    ]}
].

%% src/hello.erl
-module(hello).
-export([hello/0]).

hello() -> 
    {ok, Name} = application:get_env(hello, name),
    lager:info("HELLO ~s", [Name]),
    ok.

%% test/hello_tests.erl
-module(hello_tests).
-include_lib("eunit/include/eunit.hrl").

hello_test() ->
    lager:start(),
    lager:error("starting test", []),            %% weird!  without this nothing is logged
    Result = hello:hello(),
    lager:debug("Result = ~p", [Result]),
    ?assertEqual(ok, Result).

then rebar3 eunit.

This gives me the output:

2022-06-21 14:19:23.384 [debug] <0.209.0>@lager_handler_watcher:127 Lager installed handler {lager_file_backend,"tests.log"} into lager_event
2022-06-21 14:19:23.386 [debug] <0.215.0>@lager_handler_watcher:127 Lager installed handler error_logger_lager_h into error_logger
2022-06-21 14:19:23.419 [error] <0.188.0>@hello_tests:hello_test:6

but no output without the "starting test" line, and neither info or debug events are ever logged.