Coverage is broken for multiline logging call

[arcusfelis]

Describe the bug
If we have logging like that:

            ?LOG_WARNING(#{
                what => wrong_leader,
                server => Server,
                operation => Op,
                called_leader => Leader,
                expected_leader => ExpectedLeader
            }),

The last line would report 0 coverage.
Even if first line is called and reported.

Probably happens because LOG_WARNING has case statement inside.

Picture to describe the issue (line 420 should not be reported at all, but reported as red):

To Reproduce
Write a test module with multiline logging, check what kind of log report is gathered.
Single line logging works correctly though.

Expected behavior

Only first line should go into the coverage report, other lines should be reported as "line which is not counted" (i.e. same behaviour as for empty lines).

Affected versions
25, probably higher too.

Additional context

It is a standard logger:

-include_lib("kernel/include/logger.hrl").

[bjorng]

This is not a bug in the cover tool. Because of the case in the definition of the macro, there is an executable line that is not covered by your tests. The macro expansion will produce code similar to the following:

    case logger:allow(error, t) of
        true -> apply(logger, macro_log, [#{mfa => {t, ll, 4}, line => 8, file => "t.erl"}, error, #{what => wrong_leader,
                     server => Server,
                     operation => Op,
                     called_leader => Leader,
                     expected_leader => ExpectedLeader
                     }]); false -> ok
    end.

The false clause will be covered if the call to logger:allow/2 ever returns false.

It would probably be possible to rewrite the logger macros so that they force the entire case statement onto a single line. I am not sure whether that should be done.

[arcusfelis]

Interesting, thanks. So I could just run my tests twice with logging disabled and logging enabled to fix the code coverage. wt., 22 sie 2023, 07:11 użytkownik Björn Gustavsson < ***@***.***> napisał:

…

This is not a bug in the cover tool. Because of the case in the definition of the macro, there is an executable line that is not covered by your tests. The macro expansion will produce code similar to the following: case logger:allow(error, t) of true -> apply(logger, macro_log, [#{mfa => {t, ll, 4}, line => 8, file => "t.erl"}, error, #{what => wrong_leader, server => Server, operation => Op, called_leader => Leader, expected_leader => ExpectedLeader }]); false -> ok end. The false clause will be covered if the call to logger:allow/2 ever returns false. It would probably be possible to rewrite the logger macros so that they force the entire case statement onto a single line. I am not sure whether that should be done. — Reply to this email directly, view it on GitHub <#7531 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAE4GNGJOUOWZBQ26IO7CEDXWQ5PDANCNFSM6AAAAAA3B6PGDA> . You are receiving this because you authored the thread.Message ID: ***@***.***>

[Alberdi]

In case it helps, the three workarounds I found for this were:

1. Call logger:warning/2 instead of using the macro.
2. Ensure that the macro call only takes one line.
3. Do a test with the logs disabled.

I never consider using the first one, to be honest. And when the second option doesn't seem natural, I usually lean to the third one with code similar to:

do_test_no_log(_Conf) ->
    ok = logger:set_module_level(tested_module, none),
    do_the_test(),
    ok = logger:unset_module_level(tested_module).

[arcusfelis]

My current workaround was:

    Log = #{
        what => drop_remote_op,
        from => From,
        remote_join_ref => RemoteJoinRef,
        join_ref => JoinRef,
        op => Op
    },
    ?LOG_ERROR(Log),

But this is ugly, and VM is probably not smart enough to optimize the term construction (or move it into inside the case statement).

Sadly, one liner is not an option, because of formatters.

Though I like set_module_level approach, could be done with groups in Common Tests.

[arcusfelis]

Ok, will close the issue, there are workarounds.

---

A couple of thoughts.

We could probably rewrite this:

-define(DO_LOG(Level,Args),
        case logger:allow(Level,?MODULE) of
            true ->
                erlang:apply(logger,macro_log,[?LOCATION,Level|Args]);
            false ->
                ok
        end).
-endif.

as

-define(DO_LOG(Level,Args),
        case logger:allow(Level,?MODULE) of false -> ok; 
        true ->  erlang:apply(logger,macro_log,[?LOCATION,Level|Args]) end).

But it is ugly and I've not tested that it helps :)

Or if we are true evil:

-define(DO_LOG(Level,Args),
        [erlang:apply(logger,macro_log,[?LOCATION,Level|Args])
         || logger:allow(Level,?MODULE)]).

or

% I kinda like this one though
-define(DO_LOG(Level,Args),
        logger:allow(Level,?MODULE)
            andalso erlang:apply(logger,macro_log,[?LOCATION,Level|Args])).