Logging in Go

Who am I?

Damiano Petrungaro

Damiano Petrungaro

Italy

source: www.vidiani.com

Me everyday:

Logging

Challenges

Problem faced

Golog

Next steps and improvements

Problems faced

Logs should improve developer experience

Problems faced

Poor APIs and side effetcs

package main

import (
	"errors"
	"time"

	"github.com/sirupsen/logrus"
)

var (
	simple  = map[string]string{"1": "2"}
	complex = map[any]any{"1": map[struct{}]string{struct{}{}: "Dave"}}
)

func main() {
	logger := logrus.New()
	logger.Formatter = &logrus.JSONFormatter{}
	logger.WithFields(logrus.Fields{"data": simple}).Error("It works with multiple fields!")
	logger.WithField("data", simple).Error("It works with a single field!")
	logger.WithTime(time.Now().Add(120 * time.Hour)).Error("It works with changed time!")
	logger.WithError(errors.New("an error")).Error("It works with an error!")
	logger.WithField("data", complex).Error("It doesn't work!")
}

Problems faced

Poor APIs and side effetcs

{"data":{"1":"2"},"level":"error","msg":"It works with multiple fields!","time":"2022-08-01T18:03:33+02:00"}
{"data":{"1":"2"},"level":"error","msg":"It works with a single field!","time":"2022-08-01T18:03:33+02:00"}
{"level":"error","msg":"It works with changed time!","time":"2022-08-06T18:03:33+02:00"}
{"error":"an error","level":"error","msg":"It works with an error!","time":"2022-08-01T18:03:33+02:00"}
Failed to obtain reader, failed to marshal fields to JSON, json: unsupported type: map[interface {}]interface {}

Problems faced

Poor APIs and side effetcs

package main

import (
	"errors"

	"go.uber.org/zap"
)

var (
	simple  = map[string]string{"1": "2"}
	complex = map[any]any{"1": map[struct{}]string{struct{}{}: "Dave"}}
)

func main() {
	logger, err := zap.NewProduction()
	if err != nil {
		panic(err)
	}

	logger.Sugar().With("data", simple).Error("It works -sugar- with multiple fields!")
	logger.With(zap.Any("data", simple)).Error("It works with changed time!")
	logger.Sugar().Errorw("It works -sugar- with a single field!", "data", simple)
	logger.With(zap.Error(errors.New("an error"))).Error("It works with an error!")
	logger.Sugar().With("data", simple, "even :P").Error("It doesn't work!")
	logger.Sugar().With("data", complex).Error("It doesn't work!")
}

Problems faced

Poor APIs and side effetcs

{"level":"error","ts":1659370852.775622,"caller":"example/main.go:20","msg":"It works -sugar- with multiple fields!","data":{"1":"2"},"stacktrace":"main.main\n\t/path/to/example/main.go:20\nruntime.main\n\t/Users/damianopetrungaro/go/go1.18.3/src/runtime/proc.go:250"}
{"level":"error","ts":1659370852.775764,"caller":"example/main.go:21","msg":"It works with changed time!","data":{"1":"2"},"stacktrace":"main.main\n\t/path/to/example/main.go:21\nruntime.main\n\t/Users/damianopetrungaro/go/go1.18.3/src/runtime/proc.go:250"}
{"level":"error","ts":1659370852.775794,"caller":"example/main.go:22","msg":"It works -sugar- with a single field!","data":{"1":"2"},"stacktrace":"main.main\n\t/path/to/example/main.go:22\nruntime.main\n\t/Users/damianopetrungaro/go/go1.18.3/src/runtime/proc.go:250"}
{"level":"error","ts":1659370852.775834,"caller":"example/main.go:23","msg":"It works with an error!","error":"an error","stacktrace":"main.main\n\t/path/to/example/main.go:23\nruntime.main\n\t/Users/damianopetrungaro/go/go1.18.3/src/runtime/proc.go:250"}
{"level":"dpanic","ts":1659370852.775881,"caller":"example/main.go:24","msg":"Ignored key without a value.","ignored":"even :P","stacktrace":"main.main\n\t/path/to/example/main.go:24\nruntime.main\n\t/Users/damianopetrungaro/go/go1.18.3/src/runtime/proc.go:250"}
{"level":"error","ts":1659370852.7759511,"caller":"example/main.go:24","msg":"It doesn't work!","data":{"1":"2"},"stacktrace":"main.main\n\t/path/to/example/main.go:24\nruntime.main\n\t/Users/damianopetrungaro/go/go1.18.3/src/runtime/proc.go:250"}
{"level":"error","ts":1659370852.776012,"caller":"example/main.go:25","msg":"It doesn't work!","dataError":"json: unsupported type: map[interface {}]interface {}","stacktrace":"main.main\n\t/path/to/example/main.go:25\nruntime.main\n\t/Users/damianopetrungaro/go/go1.18.3/src/runtime/proc.go:250"}

Problems faced

A poor log stream

// ...
{
  "message": "2022/08/01 15:01:59 max retry time elapsed: rpc error: code = Unavailable desc = connection error: desc = \"transport: Error while dialing dial tcp 127.0.0.1:4317: connect: connection refused\"",
  "trace": "4fffc4bf-92aa-4269-a2a7-ccbe5b86c388"
},
{
  "message": "2022/08/01 15:02:01 could not ca lculate company 62add854-4206-4ea1-a371-de3b27fc061d balance for the monthly billing",
   "level": "WARN",
   "time": "2022-08-01T15:02:01.065710951Z"
},
{
  "message": "2022/08/01 15:02:01 could not validate user data from JWT: could not find user 9a4dab99-8e5f-458e-ad41-ba9fa9892f5a in data: ERROR 1045 (28000): Access denied for user 'foo'@'::1' (using password: NO)",
  "level": "ERROR"
},
// ...

Problems faced

A better log stream

// ...
{
  "message": "could not query tax-service: max retry time elapsed",
  "level": "error",
  "time": "2022-08-01T15:02:01.065710951Z",
  "fields": [
	"error": "transport: Error while dialing dial tcp 127.0.0.1:4317: connect: connection refused",
	"trace_id": "4fffc4bf-92aa-4269-a2a7-ccbe5b86c388",
	"span_id": "6fffc4bf-92aa-4269-a2a7-ccbe5b86c388"
  ]
},
{
  "message": "could not calculate company balance for the monthly billing",
  "level": "warning",
  "time": "2022-08-01T15:02:02.065710951Z",
  "fields": [
	"error": "could not find tax information",
	"company_id": "62add854-4206-4ea1-a371-de3b27fc061d",
	"trace_id": "4fffc4bf-92aa-4269-a2a7-ccbe5b86c388",
	"span_id": "7fffc4bf-92aa-4269-a2a7-ccbe5b86c388"
  ]
},
{
  "message": "could not validate user data from JWT",
  "level": "warning",
  "time": "2022-08-01T15:02:03.065710951Z",
  "fields":[
	"error": "could not find user in storage",
	"user_id": "9a4dab99-8e5f-458e-ad41-ba9fa9892f5a",
	"trace_id": "c3d637e3-4a65-4eea-8567-53cd027759f3",
	"span_id": "a3d637e3-4a65-4eea-8567-53cd027759f3"
  ]
},
// ...

TO MOVE LATER

Golog

Why?

Golog

Tracing

Importanza dei tracing (e non solo)

Golog

Tracing

Comparazione con Logrus e Zap

Golog

APIs

PII e specifici tipi accettati

Golog

APIs

Safety e possibilità di convertire i dati in tutti i fomrati
(es: ma[any]any puo non funzionare)

Golog

Extensibility

Decorators

Golog

Extensibility

Checkers

Challenges

package context

var (
	background = new(emptyCtx)
	todo       = new(emptyCtx)
)

func Background() Context {
	return background
}

func TODO() Context {
	return todo
}

sirupsen/logrus

Next steps and improvements

package context

type emptyCtx int

func (*emptyCtx) Deadline() (deadline time.Time, ok bool) {
	return
}

func (*emptyCtx) Done() <-chan struct{} {
	return nil
}

func (*emptyCtx) Err() error {
	return nil
}

func (*emptyCtx) Value(key interface{}) interface{} {
	return nil
}

Recap

(key = value)

timer

emptyCtx

valueCtx

cancelCtx

timerCtx

twitter: @damiano_dev
email: damianopetrungaro@gmail.com

Logging in Go

By Damiano Petrungaro

Logging in Go

Writing a logger can be tricky, and performance issues are hidden and tricky to find. Since I wrote a logger in Go, I want to share the knowledge I gained out of that by coding a session (inspired by the open-source one I wrote) to show bottlenecks from a performance and design perspective. The deep dive will involve writing benchmarks for encoding the log entry and profiling the whole logger design to determine where it could be improved.

  • 344