sllm

README

sllm – Structured Logging Lightweight Markup

A human readable approach to make parameters from an actual log message machine-readable.

Disclaimer: sllm is not a logging 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.

Usage:

import "git.fractalqb.de/fractalqb/sllm/v2"

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.

Benchmarks

Benchmarks from https://github.com/fractalqb/go-sllm-benchmark – go there for details.

Ran on: cpu: AMD Ryzen 7 5800X 8-Core Processor

Writing Messages

BenchmarkSllmExpand-16      7523715	   208.0 ns/op   24 B/op   1 allocs/op
BenchmarkSllmByteBuffer-16  6041648	   191.7 ns/op   24 B/op   1 allocs/op
BenchmarkSllmPrint-16       4525854	   272.6 ns/op   48 B/op   2 allocs/op
BenchmarkGoJSONdynamic-16    662958	  1871   ns/op  760 B/op  15 allocs/op
BenchmarkGoJSONstatic-16    2580258	   487.6 ns/op  224 B/op   2 allocs/op
BenchmarkJSONiterDynamic-16  700167	  1705   ns/op  950 B/op  14 allocs/op
BenchmarkJSONiterStatic-16  2453310	   469.8 ns/op  224 B/op   2 allocs/op

Parsing Messages

BenchmarkSllmParseSynamic-16        2813646   427.9 ns/op  654 B/op   6 allocs/op
BenchmarkGoJSONparseDynamic-16       380229  3296   ns/op  560 B/op	28 allocs/op
BenchmarkGoJSONparseStatic-16        932494  1940   ns/op  296 B/op	 9 allocs/op
BenchmarkGoJSONiterParseDynamic-16   985543  1285   ns/op  344 B/op	24 allocs/op
BenchmarkGoJSONiterParseStatic-16   2051349   601.1 ns/op  112 B/op	 9 allocs/op

Documentation

Overview

Package sllm is the 2nd iteration of the reference implementation for the Structured Logging Lightweight Markup format.

The goal is to create a human-readable format for the message part of log entries that also makes the parameters in the log message reliably machine-readable. This is a task generally performed by markup languages. However, sllm is intended to be much less intrusive than, for example, XML or JSON. The traditional log message:

2019/01/11 19:32:44 added 7 ⨉ Hat to shopping cart by John Doe

would become something like (depending on the choice of parameter names)

2019/01/11 19:32:44 added `count:7` ⨉ `item:Hat` to shopping cart by `user:John Doe`

This is still readable by humans but can also be parsed reliably by machines. Machine reading would not fail even if the message template changes the order of the parameters. Careful choice of parameter names can make the messages even more meaningful.

This package is no logging library—it provides functions to create and parse sllm messages.

Example

// Positional arguments
Fprint(os.Stdout, "added `count` ⨉ `item` to shopping cart by `user`\n",
	Argv("", 7, "Hat", "John Doe"),
)
// Named arguments
Fprint(os.Stdout, "added `count` ⨉ `item` to shopping cart by `user`\n",
	Named("", map[string]any{
		"count": 7,
		"item":  "Hat",
		"user":  "John Doe",
	}),
)

Output:

added `count:7` ⨉ `item:Hat` to shopping cart by `user:John Doe`
added `count:7` ⨉ `item:Hat` to shopping cart by `user:John Doe`

Index

• Constants
• func Bprint(wr *bytes.Buffer, tmpl string, args ArgPrintFunc) (int, error)
• func Error(tmpl string, args ...any) error
• func Expand(buf []byte, tmpl string, args ArgPrintFunc) ([]byte, error)
• func ExtractParams(appendTo []string, tmpl string) ([]string, error)
• func Fprint(wr io.Writer, tmpl string, args ArgPrintFunc) (int, error)
• func Parse(msg string, tmpl *bytes.Buffer, onArg func(name, value string) error) error
• func ParseMap(msg string, tmpl *bytes.Buffer) (map[string][]string, error)
• func Sprint(tmpl string, args ArgPrintFunc) (string, error)
• type ArgPrintFunc
  • func Argv(u string, av ...any) ArgPrintFunc
  • func Named(u string, m map[string]any) ArgPrintFunc
• type ArgWriter
  • func (w *ArgWriter) Write(p []byte) (n int, err error)
  • func (w *ArgWriter) WriteInt(i int) (n int, err error)
  • func (w *ArgWriter) WriteInt64(i int64) (n int, err error)
  • func (w *ArgWriter) WriteString(s string) (n int, err error)
  • func (w *ArgWriter) WriteTime(t time.Time, f TimeFormat) (n int, err error)
• type IllegalArgIndex
  • func (err IllegalArgIndex) Error() string
• type SyntaxError
  • func (err SyntaxError) Error() string
• type TimeFormat
  • func (tf TimeFormat) Format(t time.Time) timeFormatter
• type UndefinedArg
  • func (err UndefinedArg) Error() string

Examples

• Package
• ArgWriter
• Error
• ParseMap
• TimeFormat

Constants

const Tdefault = Tdate

Functions

func Bprint

func Bprint(wr *bytes.Buffer, tmpl string, args ArgPrintFunc) (int, error)

Bprint uses Expand to print the sllm message to an in-memory buffer. Bprint is somewhat faster than Print.

func Error

func Error(tmpl string, args ...any) error

Example

fmt.Println(Error("this is just `an` message with missing `param`", "error"))
fmt.Println(Error("this will `fail", "dummy"))

Output:

this is just `an:error` message with missing `param:<?>`
[sllm:syntax error in `tmpl:this will ``fail`:`pos:11`:`desc:unterminated argument`]

func Expand

func Expand(buf []byte, tmpl string, args ArgPrintFunc) ([]byte, error)

Expand appends a message to buf by expanding all arguments of the given template tmpl. The actual process of expanding an argument is left to ArgPrintFunc args.

See also Args and Map

func ExtractParams

func ExtractParams(appendTo []string, tmpl string) ([]string, error)

ExtractParams extracs the parameter names from template tmpl and appends them to appendTo.

func Fprint

func Fprint(wr io.Writer, tmpl string, args ArgPrintFunc) (int, error)

Fprint uses Expand to print the sllm message to wr.

func Parse

func Parse(msg string, tmpl *bytes.Buffer, onArg func(name, value string) error) error

Parse parses a sllm message create by Expand and calls onArg for every `name:value` parameter it finds in the message. When a non-nil buffer is passed as tmpl Parse will also reconstruct the original template into the buffer. Note that the template is appended to tmpl's content.

func ParseMap

func ParseMap(msg string, tmpl *bytes.Buffer) (map[string][]string, error)

ParseMap uses Parse to create a map with all parameters assigned to an argument in the passed message msg. ParseMap can also reconstruct the template when passing a Buffer to tmpl.

Example

var tmpl bytes.Buffer
m, _ := ParseMap(
	"added `count:7` ⨉ `item:Hat` to shopping cart by `user:John Doe`",
	&tmpl,
)
fmt.Println(tmpl.String())
for k, v := range m {
	fmt.Printf("%s:[%s]\n", k, v)
}

Output:

added `count` ⨉ `item` to shopping cart by `user`
count:[[7]]
item:[[Hat]]
user:[[John Doe]]

func Sprint

func Sprint(tmpl string, args ArgPrintFunc) (string, error)

Sprint uses Expand to return the sllm message as a string.

Types

type ArgPrintFunc

type ArgPrintFunc = func(wr *ArgWriter, idx int, name string) (int, error)

ArgPrintFunc is used by the Expand function to process an argument when it appears in the expand process of a template. Expand will pass the index idx and the name of the argument to expand, i.e. write into the writer wr. A ArgPrintFunc returns the number of bytes writen and—just in case—an error.

NOTE: The writer wr of type ArgWriter will escape whatever ArgPrintFunc writes so that the template escape symbol '`' remains recognizable.

See also Args and Map

func Argv

func Argv(u string, av ...any) ArgPrintFunc

func Named

func Named(u string, m map[string]any) ArgPrintFunc

type ArgWriter

type ArgWriter []byte

ArgWriter is used by Expand to escape the argument when written as a value of a parameter. It is assumed that a user of this package should not use this type directly. However the type will be needed if one wants to provide an own ArgPrintFunc.

Example

var ew ArgWriter
ew.Write([]byte("foo"))
fmt.Println(string(ew))
ew = ew[:0]
ew.Write([]byte("`bar`"))
fmt.Println(string(ew))
ew = ew[:0]
ew.Write([]byte("b`az"))
fmt.Println(string(ew))

Output:

foo
``bar``
b``az

func (*ArgWriter) Write

func (w *ArgWriter) Write(p []byte) (n int, err error)

Write escapes the content so that it can be reliably recognized in a sllm message, i.e. replace each single backtick '`' with two backticks.

func (*ArgWriter) WriteInt

func (w *ArgWriter) WriteInt(i int) (n int, err error)

func (*ArgWriter) WriteInt64

func (w *ArgWriter) WriteInt64(i int64) (n int, err error)

func (*ArgWriter) WriteString

func (w *ArgWriter) WriteString(s string) (n int, err error)

func (*ArgWriter) WriteTime

func (w *ArgWriter) WriteTime(t time.Time, f TimeFormat) (n int, err error)

type IllegalArgIndex

type IllegalArgIndex int

func (IllegalArgIndex) Error

func (err IllegalArgIndex) Error() string

type SyntaxError

type SyntaxError struct {
	// Tmpl is the errornous template string
	Tmpl string
	// Pas is the byte position within the template string
	Pos int
	// Err is the description of the error
	Err string
}

SyntaxError describes errors of the sllm template syntax in a message template.

func (SyntaxError) Error

func (err SyntaxError) Error() string

type TimeFormat

type TimeFormat int

Example

t := time.Date(2023, 05, 04, 21, 43, 1, 2003000, time.UTC)
buf := ArgWriter([]byte{})
buf.WriteTime(t, Tdefault)
fmt.Println(string(buf))
buf = buf[:0]
buf.WriteTime(t, Tdate|Tyear|Tmicros)
fmt.Println(string(buf))
buf = buf[:0]
buf.WriteTime(t, Tdate|Tyear|Tmillis)
fmt.Println(string(buf))

Output:

May 04 21:43:01
2023 May 04 21:43:01.002003
2023 May 04 21:43:01.002

const (
	Tdate TimeFormat = 1 << iota
	Tyear
	TUTC
	Tmillis
	Tmicros
)

func (TimeFormat) Format

func (tf TimeFormat) Format(t time.Time) timeFormatter

type UndefinedArg

type UndefinedArg string

func (UndefinedArg) Error

func (err UndefinedArg) Error() string