Structured logging

[kocolosk]

I’d like to change the way we generate and format log messages inside CouchDB. Currently we use “printf” style invocations of the form couch_log:Level(Format, Args) where Level is one of the standard syslog levels. In production I find that this approach makes it rather difficult to quickly find log messages that match some criterion. We have multi-line messages, individual values in messages aren’t always labeled, etc. I’ll sometimes end up grep'ing for a bit of text that I know to be unique for a particular message type, but … really? We can do better.

The idea behind structured logging is that the application sends along a set of key-value pairs as an entry to the logging framework. The logger can then invoke one or more handlers to generate different message formats. A dev handler might write out the key-value pairs in a readable key=value format, while in production you might turn on a handler that produces newline-delimited JSON messages which can be easily consumed by any decent logging solution.

I plan to take a pass at converting our existing logging invocations to a more structured format, then see about making the couch_log framework less printf-focused in its handler API interface. Comments and ideas welcome.

[kocolosk]

Some comments after musing on this topic for a day:

• We'll need an interface that keeps the current lazy evaluation behavior so that we're not sitting around generating debug messages that won't get sent. The current printf style is efficient in this respect.
• The reason I'm worried about the above is that a future JSON formatter won't be happy receiving aribtrary Erlang terms, so I was trying to figure out the right place to transform them. Doing it at the point of the logging invocation runs the risk of wasted effort if the log level is set higher.
• We exhumed lager from the codebase a few years ago. Why? Was it simply that we thought it was a lot of unnecessary code?
• Erlang 21 adds a new logger inspired by lager: http://erlang.org/documentation/doc-10.0-rc1/lib/kernel-6.0/doc/html/logger_chapter.html. The new Erlang logger does allow for maps and/or key-value lists to be logged directly.
• The legacy error_logger also has the concept of a report which is a list of atoms and 2-tuples. A report is not necessarily JSON-compatible because each value is an arbitrary term.

Lazy evaluation could be as simple as wrapping every log invocation in a fun() -> ... end and only invoking the function once we've checked the log level. That should be efficient and cheap, but probably means reverting to macros instead of direct M:F/A calls ...

[iilyak]

What if we would change our logging statements to something like:

couch_log:Level(FormatWhichSupportsBindings, MetaData, Bindings).

Metadata would include data about location of the call and some context such as:

• nonce
• user
• namespace (if available)
• full URL of the request (if available)
• component

Here is one example which illustrates the idea:

couch_log:Level("Something {db_name} something else {view}", 
   [{line, ?LINE}, {module, ?MODULE}, {user, #user_ctx.name}],
   [{
       {db_name, DbName},
       {view, View}
   }]).

We can define macro to include ?LINE and ?MODULE for convenience if we want to.

Since all of the arguments are key-value pairs we can use any serialization format (depending on logging infrastructure used):

• JSON
• message pack
• BSON
• Cap’n Proto
• plain string as we currently use

There might be a need to define expected format for every argument. For example in which format we would send dates? We need to think about it we we design the FormatWhichSupportsBindings language or choosing the library.

[iilyak]

The metadata inclusion is inspired by Elixir logger. Which has following fields: https://hexdocs.pm/logger/Logger.html#module-metadata

• application - the current application
• module - the current module
• function - the current function
• file - the current file
• line - the current line
• pid - the current process identifier
• crash_reason - a two-element tuple with the throw/error/exit reason as first argument and the stacktrace as second. A throw will always be {:nocatch, term}. An error is always an Exception struct. All other entries are exits. The console backend ignores this metadata by default but it can be useful to other backends, such as the ones that report errors to third-party services
• initial_call - the initial call that started the process
• registered_name - the process registered name as an atom

We can include {commit, ?COUCHDB_GIT_SHA} as well.

[iilyak]

We also need to include timestamp in metadata or pass it as a separate argument. In order to have exact timestamps which correspond to the time when log function is executed rather then when we format the message in the logging backend.

[wohali]

@iilyak have you looked at the Erlang 21 logger library? It seems like a decent target.

[iilyak]

API for Erlang 21 logger looks good.

Logging macros

?LOG_ERROR(FunOrFormat,Args[,Metadata])

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

LOG_ERROR macro injects additional info to provided Metadata map. The injected info:

-define(LOCATION,#{mfa=>{?MODULE,?FUNCTION_NAME,?FUNCTION_ARITY},
                   line=>?LINE,
file=>?FILE}).

As you can see the logging macro uses case to find out if the event needs to be logged.

Additional features

• Process specific metadata can be added using logger:set_process_metadata(Meta).
  Which is implemented using process dictionary (good).
  We can use it to set full uri used by the user to access endpoint.
• There is concept of filters. Filters can be applied to logger and to logger handler
• There is some overload protection in few default handlers which is based on message queue size (drop on the flour)
• There is a notion of formatters to be able to use existent handlers (file or stdout)
  Formatters are called as Formatter:format(Log,FormatterConfig) (see logger_h_common.erl)

Implementation details

1. the log statements is wrapped in a case to check if it needs to be logged (ets:lookup)
2. then we dispatch it to logger_backend.erl via logger.erl
3. logger_backend.erl does the following:
   • logger_config:get(Tid,primary) (ets:lookup)
   • apply filters
   • call handlers. Every handler does
     • logger_config:get(Tid,Id,Level) (ets:lookup)
     • apply filters
     • dispatch the call using Module:log(Log1,Config1)
     • if the call to Module fail the handler is automatically removed from configuration
     • it is up to the handler to decide how to log event (single process or parallel and in which format)

Default handlers are implemented as gen_servers.

Overload protection

Default handlers (logger_disk_log_h and logger_std_h) has overload protection. Which is implemented here.

If the handler process is getting overloaded, the log event
will be send synchronously (to the handler process) instead of
asynchronous (slows down the logging tempo of a process doing
lots of logging. If the handler is choked, drop mode is set and
no event will be sent (to the handler process).

The logger_h_common provides helper function for gen_server based handlers to flash all log events from the message queue in case of overload. It also provides functions to detect overload case.

Conclusion

The Logger library has good API and useful features. Implementation is robust and should provide good performance. The only place which could be optimized further (based on one hour review) is configuration module. Since it is implemented using ets which is the second fastest way (the fastest way is generated module).

[eiri]

@kocolosk wrote:

• We exhumed lager from the codebase a few years ago. Why? Was it simply that we thought it was a lot of unnecessary code?
• Erlang 21 adds a new logger inspired by lager:..

iirc we switched from lager because 1) it was too coupled with couch codebase and we wanted ability to change backends (apache/couchdb-couch-log#4) 2) we didn't want lager's overload protection, not with how it handle it with just quietly dropping the messages 3) and it was cumbersome to deal with all together, with its use of parse_transform and none-intuitive buffers and handlers

I like the idea of structured logging, but I'm not keen on proposed here change to couch_log:Level(FormatWhichSupportsBindings, MetaData, Bindings). I don't see benefits in introducing two separate bins to hold attributes and then also enforce change on both formatting template and arguments' switch from list to proplist.

I don't know how Elixir logger works, but personally I like how logrus went about idea of structured logging. They keep all meta or "fields" separate from a message and encourage to simplify the message itself, so it wouldn't need to include meta info. Quoting: "We've found this API forces you to think about logging in a way that produces much more useful logging messages.". Sure one still can use sprintf if necessary.
There are also idea of configurable implicit default fields, akin of mentioned ?LINE and ?MODULE and automatic treatment of level, time and msg as just another fields.

This is how I'd go about adding structured logging to couch_log:

• Extract formatting out of writers and make it into own entity. I.e. this function will be in its own module and accept not a record #log_entry, but a map or a proplist. Depending on a formatter the output would be the same log message string as we have now, JSON object or a message + key=value pairs (this called TextFormatter in logrus).
• Add function couch_log:Level(Format, Args, Meta) to allow to pass additional fields. To emphasize - formatter doesn't modify msg - the message is a message, not a template.
• Formatters will be configurable in [log] section with a default to what we have now. Or default can be dictated by a writer module, I'm thinking about couch_log_writer_syslog case
• ...
• Profit!

A bonus section:

• Macros sounds like a good idea, maybe not a complete switch everywhere, but they'd be nice to have. I'm using following two in my dev a lot, I've added them to my local couch_db.hrl, so they available almost everywhere.

+-define(l(F, A), couch_log:info("~p:~b - " ++ F, [?MODULE,?LINE] ++ A)).
+-define(r2kv(Rec, Name),
+    lists:zip(record_info(fields, Name), tl(tuple_to_list(Rec)))).
+

• We can make should_log more sfisticated to turn things on and off based on meta. Something like dropping a function to logger server state and then use it as a predicate for lists:all/2 to run over meta.

[iilyak]

@eiri
Add function couch_log:Level(Format, Args, Meta) to allow to pass additional fields. To emphasize - formatter doesn't modify msg - the message is a message, not a template.

Can you clarify how you are planing to use Args? Is it the same as we currently do:

couch_log:debug("Something ~p~n", [Term], Meta).

[eiri]

@iilyak yes, exactly. If we think about message as just another attribute in log's meta, then it's not formatter's job to modify attributes, but to format the whole event to a string, JSON, key=vals or whatnot.

For lazy evaluation and reduce cost of io:format call we can match Args with empty list and\or go with @kocolosk idea of wrapping that Fmt + Args into fun and call that after should_log evaluation.

[iilyak]

I am trying to understand what JSON formatter would do with Args and how we can access them in splunk (or any other system)?

[eiri]

You seems to miss my point, so I'll try again.

Log message is just another attribute in log data, nothing more. It's not some special thing that every formatter have to know how to modify, that modification would happened before passing data to formatter, around the same step where we'll have time, level and the rest of auto-attributes injected. Formatter then only responsible for representation of log message.

If you want some attribute been concatenated into message it need to be presented in both Args and Meta, but the point of structured logging is that you don't need to do that to get informative logging.

For example for text formatting instead of log message "Compaction started by pid <0.11.0> for shard \"shards/00-ff/mystic.123456\"" you'll get "Compaction started. pid=<0.11.0> shard=\"shards/00-ff/mystic.123456\"" - it's still readable and actually better greppable and you don't need to deal with io:format's Fmt Compaction started by ~p for shard ~s. Then as JSON it'll be just {"msg": "Compaction started ", "pid": "<0.11.0>", "shard": "shards/00-ff/mystic.123456"}

I hope that makes sense.

[iilyak]

Thank you @eiri. In order to make it work we would need to forbid ~ in the Msg. Either technically or enforce it on review stage. This means that Format needs to renamed. Maybe proposed API would be better described as follows:

couch_log:Level(MessageTag, Args, Meta).

@eiri but the point of structured logging is that you don't need to do that to get informative logging.

Only if we agree to pass key-value list in Args.

[eiri]

I'm seems to be very bad at explaining :(

No, we do not forbid or change anything, quite the opposite! couch_log:Level/2 stays exactly as it is, we just have a a step at which we are creating proplist with (this is pseudo code!) [{level, Level}, {msg: io_lib:format(Fmt, Args)}, {time, os:now()}... ] and then passing this proplist to configured formatter.

Default formatter then essentially is this step extracted and it gives back to a writer the same string as we have now to write. JSON formatter serialize the proplist and gives writer JSON to write. key=val formatter creates a string similar to my example above and passes it to writer. And so on.

We also adding a new function couch_log:Level(MessageTag, Args, Meta) which is different in just one aspect - it has Meta proplist to be merged into our "auto" proplist.

With this we have a transparent migration, turning structured logging "on" is just a question of configuration and we can update existing code moving attributes from log message into Meta at our pace. Where with format forbidding or semantics changing approach we are facing a massive update of all log calls across the whole codebase which doesn't sounds very appealing.

[iilyak]

I think I understand you proposal. There is one contradiction in your description which prevents me from understanding it 100%. You've said that we would pass [.... {msg: io_lib(Fmt, Args), ..} to configured formatter. Then you mention that default formatter would do the step we currently do.
Which also includes the call to io_lib(Fmt, Args). Also I think one of the goals of your proposal is to avoid modifying all places where we call logger. I don't think it is a big deal. We always can write scripts to update all callers in semiautomatic manner.