sllm

package module
v3.0.0 Latest Latest
Warning

This package is not in the latest version of its module.

 Go to latest Published: Feb 23, 2024 License: MIT Imports: 8 Imported by: 6

README

sllm – Structured Logging Lightweight Markup

Build Status codecov Go Report Card Go Reference

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 qblog ≥v0.13.0.

Usage:

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

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 pseudocode:

…
// 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 a real log, everything would be on a single 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 extract 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 perfect 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 personal 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 recognized 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 these 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 with quite decent performance.

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
BenchmarkSllmAppend-16       	10492954   116.0 ns/op    0 B/op   0 allocs/op
BenchmarkSllmByteBuffer-16   	 8785130   119.2 ns/op    0 B/op   0 allocs/op
BenchmarkSllmStringBuilder-16	 3096673   410.0 ns/op  360 B/op   6 allocs/op
BenchmarkGoJSONDynamic-16    	  659040  1644   ns/op  760 B/op  15 allocs/op
BenchmarkGoJSONStatic-16     	 2714055   437.3 ns/op  224 B/op   2 allocs/op
BenchmarkJSONiterDynamic-16  	  712359  1687   ns/op  950 B/op  14 allocs/op
BenchmarkJSONiterStatic-16   	 2494083   488.5 ns/op  224 B/op   2 allocs/op
Parsing Messages
BenchmarkSllmParseDynamic-16       1621568   644.9 ns/op  693 B/op  10 allocs/op
BenchmarkGoJSONparseDynamic-16      545088  2977   ns/op  560 B/op  28 allocs/op
BenchmarkGoJSONparseStatic-16       657501  1935   ns/op  296 B/op   9 allocs/op
BenchmarkGoJSONiterParseDynamic-16  916117  1262   ns/op  344 B/op  24 allocs/op
BenchmarkGoJSONiterParseStatic-16  2122716   551.0 ns/op  112 B/op   9 allocs/op

Documentation

Overview

Package sllm is the 3rd 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
FprintIdx(os.Stdout, "added `count` ⨉ `item` to shopping cart by `user`\n",
	7, "Hat", "John Doe",
)
// Named arguments
Fprint(os.Stdout, "added `count` ⨉ `item` to shopping cart by `user`\n",
	NmArgs(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

Examples

Constants

View Source 
const TDefault = TimeFormat(0)

Variables

This section is empty.

Functions

func Append 

func Append(to []byte, tmpl string, args ArgsFunc) ([]byte, error)
Example (IdxArgs) 
args := IdxArgsDefault("???", testSvc, testSig, testProc, testName, testNow)
var buf []byte
buf, _ = Append(buf, testTmpl, args)
os.Stdout.Write(buf)
fmt.Println()

Output:

`service:rsyslog`: Sent `signal:SIGHUP` to main `process:1611` (`name:rsyslogd`) on client request `at:11-27 Mo 21:30:00+00`.
Example (NmArgs) 
args := NmArgs(map[string]any{
	"service": testSvc,
	"signal":  testSig,
	"process": testProc,
	"name":    testName,
	"at":      testNow,
})
var buf []byte
buf, _ = Append(buf, testTmpl, args)
os.Stdout.Write(buf)
fmt.Println()

Output:

`service:rsyslog`: Sent `signal:SIGHUP` to main `process:1611` (`name:rsyslogd`) on client request `at:11-27 Mo 21:30:00+00`.
Example (TestArgsN) 
var buf []byte
buf, _ = Append(buf, testTmpl, testArgsN)
os.Stdout.Write(buf)
fmt.Println()

Output:

`service:rsyslog`: Sent `signal:SIGHUP` to main `process:1611` (`name:rsyslogd`) on client request `at:11-27 Mo 21:30:00+00`.
Example (Time) 
t := time.Date(2023, 11, 27, 21, 30, 00, 0, time.UTC)
buf, _ := Append(nil, "`its`", IdxArgs(t))
os.Stdout.Write(buf)
fmt.Println()

Output:

`its:2023-11-27 21:30:00 +0000 UTC`

func AppendArg 

func AppendArg(to []byte, v any) []byte

func Error 

func Error(tmpl string, args ArgsFunc) error

func ErrorIdx 

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

func EscBytes 

func EscBytes(to, val []byte) []byte

func EscString 

func EscString(to []byte, val string) []byte

func Fprint 

func Fprint(w io.Writer, tmpl string, args ArgsFunc) (int, error)

func FprintIdx 

func FprintIdx(w io.Writer, tmpl string, args ...any) (int, error)

func IdxArgs 

func IdxArgs(args ...any) func([]byte, int, string) ([]byte, error)

func IdxArgsDefault 

func IdxArgsDefault(d any, args ...any) func([]byte, int, string) ([]byte, error)

func NmArgs 

func NmArgs(args map[string]any) func([]byte, int, string) ([]byte, error)

func NmArgsDefault 

func NmArgsDefault(d any, args map[string]any) func([]byte, int, string) ([]byte, error)

func Parameters 

func Parameters(tmpl string, a []string) ([]string, error)

Parameters extracs the parameter names from template tmpl and appends them to a.

func Parse 

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

Parse parses a sllm message create by Append 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][]any, 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
args, _ := ParseMap(
	"added `count:7` ⨉ `item:Hat` to shopping cart by `user:John Doe`",
	&tmpl,
)
fmt.Println(tmpl.String())
for k, v := range args {
	fmt.Printf("%s:[%s]\n", k, v)
}

Output:

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

func String 

func String(tmpl string, args ArgsFunc) (string, error)

func StringIdx 

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

Types

type Appender 

type Appender interface {
	AppendSllm([]byte) []byte
}

type ArgError 

type ArgError struct {
	Index int
	Name  string
	Err   error
}

func (ArgError) Error 

func (e ArgError) Error() string

func (ArgError) Unwrap 

func (e ArgError) Unwrap() error

type ArgErrors 

type ArgErrors []error

func (ArgErrors) Error 

func (e ArgErrors) Error() string

func (ArgErrors) Is 

func (e ArgErrors) Is(err error) bool

func (ArgErrors) Unwrap 

func (e ArgErrors) Unwrap() []error

type ArgsFunc 

type ArgsFunc func(buf []byte, i int, n string) ([]byte, error)

ArgsFunc appends the escaped argument i with name n to the buffer buff and returns the resulting buffer. Even in case of error, buf must be returned. To escape an argument implementers should use EscString or EscBytes.

type TimeFormat 

type TimeFormat int32
Example 
tz := time.FixedZone("West", -int((3 * time.Hour).Seconds()))
t := time.Date(2023, 05, 04, 21, 43, 1, 2003000, tz)

os.Stdout.Write(TimeFormat(0).Fmt(t).AppendSllm(nil))
fmt.Print("\n\n")

os.Stdout.Write(TUTC.Fmt(t).AppendSllm(nil))
fmt.Println()
os.Stdout.Write(TNoDate.Fmt(t).AppendSllm(nil))
fmt.Println()
os.Stdout.Write(TNoWeekday.Fmt(t).AppendSllm(nil))
fmt.Println()
os.Stdout.Write(TYear.Fmt(t).AppendSllm(nil))
fmt.Println()
os.Stdout.Write(TNoClock.Fmt(t).AppendSllm(nil))
fmt.Println()
os.Stdout.Write(TMillis.Fmt(t).AppendSllm(nil))
fmt.Println()
os.Stdout.Write(TMicros.Fmt(t).AppendSllm(nil))
fmt.Println()

Output:

05-04 Th 21:43:01-03

05-05 Fr 00:43:01
21:43:01-03
05-04 21:43:01-03
2023-05-04 Th 21:43:01-03
05-04 Th -03
05-04 Th 21:43:01.002-03
05-04 Th 21:43:01.002003-03

const (
	TUTC TimeFormat = 1 << iota
	TNoDate
	TNoWeekday
	TYear
	TNoClock
	TMillis
	TMicros
)

func (TimeFormat) Append 

func (tf TimeFormat) Append(buf []byte, t time.Time) []byte

func (TimeFormat) Fmt 

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

Source Files

View all Source files

Jump to

Keyboard shortcuts

? : This menu
/ : Search site
f or F : Jump to
y or Y : Canonical URL
go.dev uses cookies from Google to deliver and enhance the quality of its services and to analyze traffic. Learn more.