SEANK.H.LIAO

logging revisited

another look at logging

logging revisited

last time i looked i chose rs/zerolog as my preferred logging library.

Having used it for 6 months, I have complaints :)

complaints

Inefficient / unordered logfmt: zerolog efficiently creates json, but unmarshals it into a map for logfmt, losing order and efficiency.

Timestamp is at the end: Creating a logger with timestamp adds the timestamp as the last field, understandable since zerolog needs to pass along partially created json for a potentially long time, but still annoying to read as a human.

Long log chains: I liked this api, it was strictly typed, but logging even a few things result in very long lines with low density.

Interop with stdlib logger: Some things net/http.Server take a standard log.Logger and it's somewhat not straightforward to create one from zerolog.

criteria

choosing things again:

levelled: I realise I basically only use INFO and ERROR. Occasionally i'll use DEBUG or TRACE interchangeably. Maybe if combined with Dave Cheney's blog post I'll someday be convinced to just do levelled logging (v=0,1,2), but I still like seeing the distinction between purely informational and error handling lines.

structured: I still want both json and logfmt output

speed: less concerned about efficiency, more about getting the output I want

color: don't really care for this to be built in, it's going to get disabled when run in a remote system anyway, better to get a local colorizer

list

Selected from awesome-go#logging

hashicorp/logutils looks interesting, basically just adding filtering to stdlib log, less efficient in that you actually have to create the entire log line first.

 1lf := &logutils.LevelFilter{
 2        Levels: []logutils.Level{"DEBUG", "INFO", "ERROR"},
 3        MinLevel: "INFO",
 4        Write: os.Stderr,
 5}
 6
 7log.SetOutput(lf)
 8log.Printf("[INFO] oops err=%v", err)
 9
10// alternative
11debug := log.New(lf, "[DEBUG]", log.Ldate|log.Ltime|log.Lmsgprefix)
12info := log.New(lf, "[INFO]", log.Ldate|log.Ltime|log.Lmsgprefix)
13
14debug.Printf("oops err=%v", err)
15info.Printf("hmm val=%v", 1)

k8s.io/klog/v2 klog v2 gains structured logging with the *S variants

1klog.InfoS("hello world", "foo", "bar", "x", 1)
2Info.ErrorS(err, "oops", "foo", "bar", "y", 2)

output, still need to get used to Lmmdd hh:mm:ss.uuuuuu threadid file:line], especially the unbalanced ] and the threadid is useless in go

1I1012 20:32:36.250791   24371 main.go:11] "hello world" foo="bar" x=1
2E1012 20:32:36.250878   24371 main.go:12] "oops" err="an error" foo="bar" y=2

idea

my basic implementation: go.seankhliao.com/slog

1l := slog.NewText(os.Stderr)
2l.Info("hello", "foo", "bar")
3l.Error(errors.New("an error"), "oops", "hello", "world")
4
5l = slog.NewJSON(os.Stderr)
6l.Info("hello", "foo", "bar")
7l.Error(errors.New("an error"), "oops", "hello", "world")

output

12020-10-12T22:05:04+02:00 INF msg="hello" foo="bar"
22020-10-12T22:05:04+02:00 ERR msg="oops" err="an error" hello="world"
3{"time":"2020-10-12T22:05:04+02:00", "level":"INF", "msg":"hello", "foo":"bar"}
4{"time":"2020-10-12T22:05:04+02:00", "level":"ERR", "msg":"oops", "err":"an error", "hello":"world"}