Skip to content

gfngfn/a_strange_behavior_of_logger_formatter

Folders and files

NameName
Last commit message
Last commit date

Latest commit

 

History

3 Commits
 
 
 
 
 
 
 
 
 
 
 
 
 
 

Repository files navigation

This small application exemplifies a somewhat strange behavior of logger_formatter. It just counts up a number and emits logs every second.

The application has the following configuration for config/sys.config:

[
    {kernel, [
        {logger_level, debug},
        {logger, [
            {handler, default, logger_std_h, #{
                formatter =>
                    {logger_formatter, #{
                        template =>
                            %% The following does NOT work as intended:
                            [
                                {message_only,
                                    ["*", msg, "\n"],
                                    [time, " [", level, "] ", file, ":", line, " ", pid, " ", msg, "\n"]
                                }
                            ]
                            %% while the following does work:
                            %[
                            %   {message_only,
                            %       ["*"],
                            %       [time, " [", level, "] ", file, ":", line, " ", pid, " "]
                            %   },
                            %   msg, "\n"
                            %]
                    }}
            }}
        ]}
    ]}
].

As commented above, using the former list for the logger template does NOT work as intended, while the latter one does.

You can compile and run this application by:

$ rebar3 shell

and can see how logs are emitted. Using the former one, logs look like:

*
2022-05-31T09:58:33.889089+09:00 [info] : <0.142.0>
*
2022-05-31T09:58:35.890979+09:00 [info] : <0.142.0>
*
2022-05-31T09:58:37.892774+09:00 [info] : <0.142.0>
*
2022-05-31T09:58:39.894887+09:00 [info] : <0.142.0>

that is, msg is substituted with empty strings.

On the other hand, the latter template produces logs that look like:

*count: 1
2022-05-31T10:00:48.543986+09:00 [info] : <0.142.0> count: 2
*count: 3
2022-05-31T10:00:50.545941+09:00 [info] : <0.142.0> count: 4
*count: 5
2022-05-31T10:00:52.547992+09:00 [info] : <0.142.0> count: 6
*count: 7

which reflects the intention correctly.

This behavior reproduces under the following environment:

$ erl
Erlang/OTP 24 [erts-12.0.1] [source] [64-bit] [smp:4:4] [ds:4:4:10] [async-threads:1] [jit] [dtrace]

Eshell V12.0.1  (abort with ^G)
1> q().
ok
2>
$ rebar3 version
rebar 3.16.1 on Erlang/OTP 24 Erts 12.0.1