Erlang (OTP 21+) Logger Console Output Question (Garbled Prompt)

[Brett Hemes]

While developing I often use console prints as debugging/verification tools.  In the past I have used io:format for this purpose but I would like to use the new OTP logger to do this and then be able to filter based on severity and/or send them to a file instead of the console as the project matures.  However, I am having trouble currently preventing logger’s output from destroying my console interactivity.  I have logger setup to use the console for output but **the logging prints output AT the current cursor position and thus destroy any input-in-progress** making interaction during busy logging near impossible.  In contrast, using io:format performs as desired where the output happens (and scrolls) right ABOVE the cursor line (i.e., without destroying the prompt).  Is this known behavior and/or is there any way to fix it (e.g., with some sys.config settings)?

 

For example,

 

With io:format:

    37> some_intput.

    some_info_i_would_like_to_display

    some_more_info

    info_etc

    38> my-next-input.<enter>

    39> <enter>

    39>

 

With logger:

    37> some_input.

    38> some_info_i_would_like_to_display

    my-nexsome_more_info

    t-input.<enter>

   

    39> info_etc<enter>

   

    39>

 

 

 

I would very much like to figure this out.

 

Thanks,

Brett

[Lukas Larsson]

Hello!

This issue has to do with which group_leader that the process that is writing the output has.

When doing `io:format` in a process that either is a shell (or is started by a shell) the group_leader is set to a process that is aware of the shell and can rewrite it when output comes its way.

However, since logger does not use the group_leader of the calling process to print log messages, those messages get sent directly to the `user` process which has no notion of whether a shell is actually running or not, so it cannot rewrite the output.

It is not only logger that has this problem, if you do an `io:format` in a process started as part of an application hierarchy you will see the same behaviour. (or by doing `spawn(fun F() -> timer:sleep(1000), io:format(user,"hello hello~n",[]), F() end)`)

I'm not sure how easy it is to do anything about this, as it would require different parts of the group_leader hierarchy to interact in ways that I do not think it does today.

A possibly short-term solution for you might be hitting "ctrl-l" (ctrl and non-capital L) when the situation happens. That should rewrite the current line so that you can see what you are doing.

Lukas

[Nicolas Martyanoff]

Lukas Larsson <lu...@erlang.org> writes:
> However, since logger does not use the group_leader of the calling process
> to print log messages, those messages get sent directly to the `user`
> process which has no notion of whether a shell is actually running or not,
> so it cannot rewrite the output.

If I'm not mistaken, this is also the reason eunit tests do not capture
logger messages, making it hard to understand what was logged by a
specific failing test.

Is there something on the roadmap to try to address this issue ? It
affects both shell and eunit in non-trivial ways. The only workaround is
to ignore logger in applications and to write another log system which
uses the group leader, so it would make sense to fix logger.

--
Nicolas Martyanoff
http://snowsyn.net
kha...@gmail.com

[Lukas Larsson]

On Mon, May 10, 2021 at 8:08 AM Nicolas Martyanoff <kha...@gmail.com> wrote:

Lukas Larsson <lu...@erlang.org> writes:
> However, since logger does not use the group_leader of the calling process
> to print log messages, those messages get sent directly to the `user`
> process which has no notion of whether a shell is actually running or not,
> so it cannot rewrite the output.

If I'm not mistaken, this is also the reason eunit tests do not capture
logger messages, making it hard to understand what was logged by a
specific failing test.

I'm not really familiar with how eunit handles input/output during testcases, but this together with the fact that applications log to `user` will make it hard for eunit to get the output it needs.

 

Is there something on the roadmap to try to address this issue ? It
affects both shell and eunit in non-trivial ways. The only workaround is
to ignore logger in applications and to write another log system which
uses the group leader, so it would make sense to fix logger.

There is no need to write another log system, you only need to write a logger backend that outputs to the group_leader of the calling process instead of `user`.

Similar functionality is already available in common_test as cth_log_redirect, http://erlang.org/doc/apps/common_test/ct_hooks_chapter.html#built-in-cths. I believe that rebar3 does something similar for their common_test logs.

I suppose that the big question is whether we can change the default behaviour of logger to be that it should output to the `standard_io` of the calling process instead of `user`.

Lukas

[Stanislav Ledenev]

If I'm not mistaken, this is also the reason eunit tests do not capture
logger messages, making it hard to understand what was logged by a
specific failing test.

What do you mean by "eunit doesn't capture logger messages"?
Is it some specific case?
I have had some problems with capturing messages but it was my fault -
I misspointed the config file with logger_level set higher than the category of my messages.
And another issue was with common_test.

You must enable verbose output to be able to see messages. 

пн, 10 мая 2021 г. в 09:24, Lukas Larsson <lu...@erlang.org>:

[Nicolas Martyanoff]

Stanislav Ledenev <s.le...@gmail.com> writes:

>>
>> If I'm not mistaken, this is also the reason eunit tests do not capture
>> logger messages, making it hard to understand what was logged by a
>> specific failing test.
>
> What do you mean by "eunit doesn't capture logger messages"?
> Is it some specific case?
> I have had some problems with capturing messages but it was my fault -
> I misspointed the config file with logger_level set higher than the
> category of my messages.
> And another issue was with common_test.
> You must enable verbose output to be able to see messages.

Eunit introduces its own group leader for each test case, capturing
printed messages, and displaying them in a small section associated with
each failing test. This is really useful when trying to understand why a
specific test failed.

But logger messages are not directly sent to the group leader, therefore
they are not captured by eunit and are logged in all cases. This is a
problem because it is now really hard to understand what was logged
(especially which errors) in each failing test.

This is clearly a design issue: eunit was not taken into account when
logger was introduced.

I tried to work around it with custom log handlers in the past, but
could never make it work, and I remember talking about it on #erlang,
but the conclusion was that it was not fixable without patching eunit
and/or logger.

[Lukas Larsson]

On Mon, May 10, 2021 at 10:13 AM Nicolas Martyanoff <kha...@gmail.com> wrote:

I tried to work around it with custom log handlers in the past, but
could never make it work, and I remember talking about it on #erlang,
but the conclusion was that it was not fixable without patching eunit
and/or logger.

I spent some time and came up with this solution: https://gist.github.com/garazdawi/6319ef80d3b969ebbed5633f11a807b1

I might have missed some detail though as I'm not very familiar with what eunit does and how it is used.

Lukas

[Stanislav Ledenev]

But logger messages are not directly sent to the group leader, therefore
they are not captured by eunit and are logged in all cases. 

"...not captured by eunit and are logged in all cases". It appears that "all cases"
is the key here. Perhaps your tests are more complicated than mine cause I've
never had any such problems.

I sketch out a simple example and everything works as expected:
-module(mylib).

-export([addition/2, subtraction/2]).

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

addition(X, Y) ->
    ?LOG_NOTICE("Addition enter."),
    X + Y.

subtraction(X, Y) ->
    ?LOG_NOTICE("Subtraction enter."),
    X - Y.

addition_test() ->
    ?LOG_NOTICE("Testing addition."),
    ?assertEqual(addition(2, 3), 6).
   
subtraction_test() ->
    ?LOG_NOTICE("Testing subtraction."),
    ?assertEqual(subtraction(6, 5), 1).
   
Output:
G:\Projects\_Erlang\mylib> rebar3 eunit
===> Verifying dependencies...
===> Analyzing applications...
===> Compiling mylib
===> Performing EUnit tests...
=NOTICE REPORT==== 10-May-2021::12:29:19.477000 ===
Testing addition.
=NOTICE REPORT==== 10-May-2021::12:29:19.499000 ===
Addition enter.
=NOTICE REPORT==== 10-May-2021::12:29:19.515000 ===
Testing subtraction.
=NOTICE REPORT==== 10-May-2021::12:29:19.515000 ===
Subtraction enter.
F.      
Failures:

  1) mylib:addition_test/0
     Failure/Error: ?assertEqual(5, 6)
       expected: 5
            got: 6
     %% eunit_proc.erl:337:in `eunit_proc:with_timeout/3`
     Output:
     Output:

Finished in 0.187 seconds
2 tests, 1 failures
===> Error running tests
   
   

пн, 10 мая 2021 г. в 11:13, Nicolas Martyanoff <kha...@gmail.com>:

[Nicolas Martyanoff]

Lukas Larsson <lu...@erlang.org> writes:

> On Mon, May 10, 2021 at 10:13 AM Nicolas Martyanoff <kha...@gmail.com>
> wrote:
>
>>
>> I tried to work around it with custom log handlers in the past, but
>> could never make it work, and I remember talking about it on #erlang,
>> but the conclusion was that it was not fixable without patching eunit
>> and/or logger.
>>
>
> I spent some time and came up with this solution:
> https://gist.github.com/garazdawi/6319ef80d3b969ebbed5633f11a807b1

Using a custom handle seems to be a good way to fix the problem, I will
give it a try.

The only problem is that is means tests will not use the same handlers
as the project, so it is a workaround.

Thank you !