flatlog

A custom formatter for the logger application that turns maps into single line text logs

Why?

Structured logging is a better approach to logging in general. Fields are more clearly defined, tool-assisted parsing and consuming of logs is simpler, and the structure is amenable to good filtering in global or handler filters for the Erlang logger library.

You could, for example, emit all your logs as structured logs (just maps), and set up multiple handlers for them:

• an audit handler, for all critical issues and configuration changes, which get stored on disk and remotely for long periods of time
• an info log for users, which gets a shorter term durability
• an error log for support tickets, which may instead have a targeted retention for a few weeks
• a special handler that parses the structured logs and forwards them to a distributed tracing framework such as opencensus
• extract or hide metrics from logs if you integrate with such a system, and do it cheaply by just nesting (or removing) a metrics map in the overall report.

This can be done transparently and after the fact, without major structural impact to the call site. It lets you far more easily decouple log generation from its consumption at no heavy cost.

This formatter focuses on providing a text-based single-line format for structured logs, which can be human-readable, while being useful to people who use grep or awk to process logs, or want to forward them to a consumer like syslogd.

Usage

It is recommended that if you are providing a library, you do not add this project as a dependency. A code formatter of this kind should be added to a project in its release repository as a top-level final presentational concern.

Once the project is added, replace the formatter of the default handler (or add a custom handler) for structured logging to your sys.config file:

[
 {kernel, [
    {logger, [
        {handler, default, logger_std_h,
         #{formatter => {flatlog, #{
            map_depth => 3,
            term_depth => 50
          }}}
        }
    ]},
    {logger_level, info}
 ]}
].

The logging output will then be supported. Calling the logger like:

?LOG_ERROR(
    #{type => event, in => config, user => #{name => <<"bobby">>, id => 12345},
      action => change_password, result => error, details => {entropy, too_low},
      txt => <<"user password not strong enough">>}
)

Will produce a single log line like:

when=2018-11-15T18:16:03.411822+00:00 level=error pid=<0.134.0>
at=config:update/3:450 user_name=bobby user_id=12345 type=event
txt="user password not strong enough" result=error in=config
details={entropy,too_low} action=change_password

Do note that the user map gets flattened such that #{user => #{name => bobby}} gets turned into user_name=bobby, ensuring that various subfields in distinct maps will not clash.

The default template supplied with the library also includes optional fields for identifiers as used in distributed tracing framework which can be set in the metadata for the logger framework, either explicitly or as a process state. The fields are:

• id for individual request identifiers
• parent_id for the event or command that initially caused the current logging event to happen
• correlation_id for groupings of related events

Logs that are not reports (maps) are going to be formatted and handled such that they can be put inside a structured log. For example:

?LOG_INFO("hello ~s", ["world"])

Will result in:

when=2018-11-15T18:16:03.411822+00:00 level=info pid=<0.134.0>
at=some:code/0:15 unstructured_log="hello world"

Do note that if you are building a release, you will need to manually add the flatlog dependency to your relx configuration, since it is technically not a direct dependency of any application in your system.

Test

$ rebar3 check

Features

• Printing rules similar to the default Erlang logger formatter, but extended for binary values that can be represented as text. I.e. rather than <<"hello">>, the value hello will be output. A non-representable value will revert to <<...>>
• Linebreaks are escaped to ensure all logs are always on one line, and strings that contain spaces or equal signs ( and =) are quoted such that "key=name"="hello world" to be clear.
• Term depth applies on a per-term basis before a data structure is elided with ...
• Map depth is controllable independently to deal with recursion vs. complexity of terms
• Colored output can be enabled with colored => true. One can color certain parts of the output using colored_start and colored_end in template. Per-level colors can be configured with colored_{log level}.

Caveats

• No max line length is enforced at the formatter level, since the ordering of terms in maps is not defined and it could be risky to cut logs early. If a max line length is to be enforced, you should wrap this formatter into your own.
• Escaping of keys does not carry well to nested maps. I.e. the map #{a_b => #{"c d" => x}} is not well supported: a_b_"c d"=x will be returned, which is nonsensical. For nested maps, you have the responsibility of ensuring composability.
• The transformations to the log line format is not lossless; it is not serialization. Information is lost regarding whether the initial term was a binary, a string, or an atom. Similarly, naming a key user_password may make it seem like the user map leaks a password field, but it is an unrelated field that looks similar due to flattening. If this is unacceptable, you might want to choose another structured log format such as JSON.

Roadmap

• integration tests
• add example basic usage
• add example usage with optional tracing for IDs
• clean up test suites
• incorporating lager's safer truncating logic (might be a breaking change prior to 1.0.0)

Changelog

• 0.1.1: added optionally colored logs (thanks @pfenoll)