go structured logging

comparing structured logging libraries in go

SEAN K.H. LIAO

go structured logging

comparing structured logging libraries in go

structured logging

who wants to read a mess of words anyways

tldr

use github.com/rs/zerolog because I like the api and the output format

about

criteria

Benchmark

code gist

 1» go test -bench . -benchmem
 2goos: linux
 3goarch: amd64
 4pkg: t
 5BenchmarkApexTxt-4                     305184              3541 ns/op            1228 B/op              20 allocs/op
 6BenchmarkApexJSON-4                    275408              4287 ns/op            1568 B/op              23 allocs/op
 7BenchmarkGokitTxt-4                   1000000              1154 ns/op             468 B/op               5 allocs/op
 8BenchmarkGokitJSON-4                   319072              3619 ns/op            1232 B/op              22 allocs/op
 9BenchmarkLog15JSON-4                   172742              7028 ns/op            2208 B/op              33 allocs/op
10BenchmarkLog15Txt-4                    324510              3578 ns/op            1376 B/op              20 allocs/op
11BenchmarkLogrusJSON-4                  203190              5791 ns/op            1974 B/op              35 allocs/op
12BenchmarkLogrusTxt-4                   260695              4694 ns/op            1056 B/op              23 allocs/op
13BenchmarkZapJSON-4                    1000000              1057 ns/op             256 B/op               1 allocs/op
14BenchmarkZapTxt-4                      724332              1560 ns/op             368 B/op               5 allocs/op
15BenchmarkZapSugarJSON-4                750585              1370 ns/op             512 B/op               1 allocs/op
16BenchmarkZapSugarTxt-4                 605372              1855 ns/op             624 B/op               5 allocs/op
17BenchmarkZerologJSON-4                2005058               588 ns/op               0 B/op               0 allocs/op
18BenchmarkZerologTxt-4                   98937             11678 ns/op            2873 B/op              93 allocs/op
19BenchmarkKlogInterface-4               736012              1631 ns/op             216 B/op               2 allocs/op
20BenchmarkKlogFormat-4                  797425              1501 ns/op             216 B/op               2 allocs/op
21BenchmarkStdlibInterface-4            1978610               607 ns/op              48 B/op               1 allocs/op
22BenchmarkStdlibFormat-4               2119566               565 ns/op              48 B/op               1 allocs/op
23PASS
24ok          t        23.216s

loggers

not structured:

apex

code:

 1import (
 2        apex "github.com/apex/log"
 3        "github.com/apex/log/handlers/json"
 4        "github.com/apex/log/handlers/logfmt"
 5)
 6
 7func Apex() {
 8        fmt.Println("\nApex")
 9        l := &apex.Logger{Handler: json.New(os.Stdout), Level: apex.InfoLevel}
10        l.WithFields(apex.Fields{"bool": true, "int": 1, "str": "s", "err": err}).Info("apex json")
11
12        l = &apex.Logger{Handler: logfmt.New(os.Stdout), Level: apex.InfoLevel}
13        l.WithFields(apex.Fields{"bool": true, "int": 1, "str": "s", "err": err}).Info("apex txt")
14}

output:

1Apex
2{"fields":{"bool":true,"err":{},"int":1,"str":"s"},"level":"info","timestamp":"2020-04-12T22:58:32.105258571+02:00","message":"apex json"}
3timestamp=2020-04-12T22:58:32.105372627+02:00 level=info message="apex txt" bool=true err="an err" int=1 str=s
Gokit

code:

 1import (
 2        kitlog "github.com/go-kit/kit/log"
 3)
 4
 5func Gokit() {
 6        fmt.Println("\nGokit")
 7        l := kitlog.NewJSONLogger(os.Stdout)
 8        l.Log("gokit json", "bool", true, "int", 1, "str", "s", "err", err)
 9
10        l = kitlog.NewLogfmtLogger(os.Stdout)
11        l.Log("gokit txt", "bool", true, "int", 1, "str", "s", "err", err)
12}

output:

1Gokit
2{"1":"str","an err":"(MISSING)","gokit json":"bool","s":"err","true":"int"}
3gokittxt=bool true=int 1=str s=err
Log15

code:

 1import (
 2        "github.com/inconshreveable/log15"
 3)
 4
 5func Log15() {
 6        fmt.Println("\nLog15")
 7        l := log15.New()
 8        l.SetHandler(log15.StreamHandler(os.Stdout, log15.JsonFormat()))
 9        l.Info("log15 json", "bool", true, "int", 1, "str", "s", "err", err)
10
11        l = log15.New()
12        l.SetHandler(log15.StreamHandler(os.Stdout, log15.LogfmtFormat()))
13        l.Info("log15 json", "bool", true, "int", 1, "str", "s", "err", err)
14}

output:

1Log15
2{"bool":true,"err":"an err","int":1,"lvl":"info","msg":"log15 json","str":"s","t":"2020-04-12T22:58:32.105473094+02:00"}
3t=2020-04-12T22:58:32+0200 lvl=info msg="log15 json" bool=true int=1 str=s err="an err"
Logrus

code:

 1import (
 2        "github.com/sirupsen/logrus"
 3)
 4
 5func Logrus() {
 6        fmt.Println("\nLogrus")
 7        l := &logrus.Logger{Out: os.Stdout, Formatter: &logrus.JSONFormatter{}, Level: logrus.InfoLevel}
 8        l.WithFields(logrus.Fields{"bool": true, "int": 1, "str": "s", "err": err}).Info("logrus json")
 9
10        l = &logrus.Logger{Out: os.Stdout, Formatter: &logrus.TextFormatter{}, Level: logrus.InfoLevel}
11        l.WithFields(logrus.Fields{"bool": true, "int": 1, "str": "s", "err": err}).Info("logrus txt")
12}

output:

1Logrus
2{"bool":true,"err":"an err","int":1,"level":"info","msg":"logrus json","str":"s","time":"2020-04-12T22:58:32+02:00"}
3INFO[0000] logrus txt                                    bool=true err="an err" int=1 str=s
Zap

code:

 1import(
 2        "go.uber.org/zap"
 3)
 4
 5func Zap() {
 6        fmt.Println("\nZap")
 7        l, _ := zap.NewProduction()
 8        l.Info("zap json", zap.Bool("bool", true), zap.Int("int", 1), zap.String("str", "s"), zap.Error(err))
 9
10        l, _ = zap.NewDevelopment()
11        l.Info("zap txt", zap.Bool("bool", true), zap.Int("int", 1), zap.String("str", "s"), zap.Error(err))
12}

output:

1Zap
2{"level":"info","ts":1586725112.1056206,"caller":"testrepo-82/main.go:78","msg":"zap json","bool":true,"int":1,"str":"s","error":"an err"}
32020-04-12T22:58:32.105+0200        INFO        testrepo-82/main.go:81        zap txt        {"bool": true, "int": 1, "str": "s", "error": "an err"}
Zap Sugared

code:

 1import(
 2        "go.uber.org/zap"
 3)
 4
 5func ZapSugar() {
 6        fmt.Println("\nZap Sugar")
 7        l, _ := zap.NewProduction()
 8        l.Sugar().Infow("zap sugar json", "bool", true, "int", 1, "str", "s", "err", err)
 9
10        l, _ = zap.NewDevelopment()
11        l.Sugar().Infow("zap sugar txt", "bool", true, "int", 1, "str", "s", "err", err)
12}

output:

1Zap Sugar
2{"level":"info","ts":1586725112.1056879,"caller":"testrepo-82/main.go:87","msg":"zap sugar json","bool":true,"int":1,"str":"s","err":"an err"}
32020-04-12T22:58:32.105+0200        INFO        testrepo-82/main.go:90        zap sugar txt        {"bool": true, "int": 1, "str": "s", "err": "an err"}
Zerolog

code:

 1import(
 2        "github.com/rs/zerolog"
 3)
 4
 5func Zerolog() {
 6        fmt.Println("\nZerolog")
 7        l := zerolog.New(os.Stdout).With().Timestamp().Logger()
 8        l.Info().Bool("bool", true).Int("int", 0).Str("str", "s").Err(err).Msg("zerolog json")
 9
10        l = zerolog.New(zerolog.ConsoleWriter{Out: os.Stdout, NoColor: true, TimeFormat: time.RFC3339}).With().Timestamp().Logger()
11        l.Info().Bool("bool", true).Int("int", 1).Str("str", "s").Err(err).Msg("zerolog txt")
12}

output:

1Zerolog
2{"level":"info","bool":true,"int":0,"str":"s","error":"an err","time":"2020-04-12T22:58:32+02:00","message":"zerolog json"}
32020-04-12T22:58:32+02:00 INF zerolog txt error="an err" bool=true int=1 str=s
Klog

code:

1import(
2        "k8s.io/klog"
3)
4
5func Klog() {
6        fmt.Println("\nKlog")
7        klog.Info("klog", "bool", true, "int", 1, "str", "s", "err", err)
8        klog.Infof("klog bool=%v int=%v str=%v err=%v\n", true, 1, "s", err)
9}
1Klog
2I0412 22:58:32.105824  258002 main.go:104] klogbooltrueint1strserran err
3I0412 22:58:32.105840  258002 main.go:105] klog bool=true int=1 str=s err=an err
Log

code:

1import(
2        "log"
3)
4
5func Std() {
6        fmt.Println("\nstdlib")
7        log.Println("stdlib", "bool", true, "int", 1, "str", "s", "err", err)
8        log.Printf("klog bool=%v int=%v str=%v err=%v\n", true, 1, "s", err)
9}

output:

1stdlib
22020/04/12 23:01:38 stdlib bool true int 1 str s err an err
32020/04/12 23:01:38 stdlib bool=true int=1 str=s err=an err