Logging in Go
Who am I?
Damiano Petrungaro
Damiano Petrungaro
Italy
source: www.vidiani.com
source: www.greenparkmadama.it
source: www.milanotoday.it
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.
