sllm

sllm – Structured Logging Leightweight Markup

A human readable approach to make parameters from an actual log message recognizable for machines.

Disclaimer: sllm is not a loggin library. Its a concept to make log messages human- and machine-readable at the same time. There are some examples in the Go reference docs. For a Go logging lib that uses sllm see qbsllm.

Rationale

Logging is subject to two conflicting requirements. Log entries should be understandable and easy to read. On the other hand, they should be able to be reliably processed automatically, i.e. to extract relevant data from the entry. Current technologies force a decision for one of the two requirements.

To decide for either human readability or machine processing means that significant cutbacks are made to the other requirement. sllm picks up the idea of "markup", which is typically intended to bring human readability and machine processing together. At the same time, sllm remains simple and unobtrusive—unlike XML or even JSON.

Let's take the example of a standard log message that states some business relevant event and might be generated from the following pseudo-code:

…
// code that knows something about transaction:
DC.put("tx.id", tx.getId());
…
// down the stack: an actual business related message:
log.Info("added {} x {} to shopping cart by {}", 7, "Hat", "John Doe");
…
// finally(!) when climbing up the stack:
DC.clear();
…

Besides the message the log entry contains some standard fields time, thread, level and module and some Diagnostic Context information to give a more complete picture.

How would the output of such a scenario look like? – Either one gets a visually pleasant message that is rather good to read or you get output that is easy to be consumed by computers. Currently one has to make a choice. But, can't we have both in one?

Note that sllm focuses on the log message. We do not propose how to handle other pieces of information! So lets have a look what sllm would do with some decent log formats. We use ↩/↪ only to avoid very long lines on this page. In real logs things would be on one line!

Classic log output

2018-07-02 20:52:39 [main] INFO sllm.Example - added 7 x Hat to ↩
↪ shopping cart by John Doe - tx.id=4711

This message is nice to read for humans. Especially the message part is easy to understand because humans are used to gain some understanding from natural language. However, the relevant parameters— i.e. the number of items, which type of item and the respective user—is not easy to extract from the text by machines. Even if you do, simple changes of the text template can easily break the mechanism to extrac those parameters.

With sllm message:

2018-07-02 20:52:39 [main] INFO sllm.Example - added `count:7` x ↩
↪ `item:Hat` to shopping cart by `user:John Doe` - tx.id=4711

The sllm'ed format is still quite readable but lets one reliably identify the business relevant values.

logfmt

time=2018-07-02T20:52:39 thread=main level=INFO module=sllm.Example ↩
↪ ix.id=4711 number=7 item=Hat user=John_Doe tag=fill_shopping_cart

The logftm page itself states that the human readability of logftm is far from perferct and encourages the approach to include a human readable message with every log line:

time=2018-07-02T20:52:39 thread=main level=INFO module=sllm.Example ↩
↪ ix.id=4711 msg="added 7 x Hat to shopping cart by John Doe" ↩
↪ number=7 item=Hat user=John_Doe tag=fill_shopping_cart

Once you find the message by skimming the log entry its meaning is not subject of presonal interpretation of technical key/value pairs any more. That's fine! But there is still a significant amount of “visual noise”. However the result is quite acceptable. But one still may ask if the redundancy in the log entry is necessary. With a “slim” message you don't need that redundancy.

With sllm message:

time=2018-07-02T20:52:39 thread=main level=INFO module=sllm.Example ↩
↪ ix.id=4711 msg=added `count:7` x `item:Hat` to shopping cart by ↩
↪ `user:John Doe`

JSON Lines

{"time":"2018-07-02T20:52:39","thread":"main","level":"INFO", ↩
↪ "module":"sllm.Example","ix.id"="4711","number":"7","item":"Hat", ↩
↪ "user":"John Doe","tag":"fill_shopping_cart"}

Obviously, JSON is the least readable format. However, JSON has an outstanding advantage: JSON can display structured data. Structured data is deliberately avoided with sllm. Taking this path would inevitably lead to something with the complexity of XML.

However, similar to the logfmt example, you can use sllm to insert a machine-readable message into the entry.

With sllm message:

{"time":"2018-07-02T20:52:39","thread":"main","level":"INFO", ↩
↪ "module":"sllm.Example","ix.id"="4711","msg":"added `count:7` x ↩
↪ `item:Hat` to shopping cart by `user:John Doe`"}

About the Markup Rules

The markup is simple and sticks to the following requirements:

1. No support for multi-line messages

   Spreading a single log entry over multiple lines is considered a bad practice. However there may be use cases, e.g. logging a stack trace, that justify the multi-line approach. But in any case the message of a log entry shall not exceed a single line!

2. Message arguments are unstructured character sequences

   sllm works on the text level. There is no type system implied by sllm. As such the arguments of a sllm message are simply sub-strings of the message string.

3. Arguments are identified by a parameter name

   Within a message each argument is identified by its parameter name. A parameter name also is a sub-strings of the message string.

4. Reliable and robust recognition of parameters and arguments

   The argument and the parameter can be uniquely recognised within a message. Changes of a message that do not affect neither the parameters nor the arguments do not break the recognition.

5. Be transparent, simple and unobtrusive

   A message shall be human readable so that the meaning of the message is easy to get. The system must be transparent in the sense that even the human reader can easily recognize the parameters with their arguments.

   Note that the readability of a message also depends to a certain extent on its author.

With this requirements, why was the backtick '`' chosen for markup? – The backtick is a rarely used character from the ASCII characters set, i.e. it is also compatible with UTF-8. The fact that it is rarely used implies that we don't have to escape it often. This affects backticks in the message template and the arguments. In parameter names backticks are simply not allowed.

And last but not least: Simpler markup rules make simpler software implementations (as long as it is not too simple). Besides many advantages this gives room for efficient implementations. Part of this repository is a Go implementation that does not strive so much for efficiency but for hackability.