Event logging is one of the three pillars of observability (traces and metrics being the other two).

A log entry is a timestamped record about the application’s activity, which can be used for troubleshooting, monitoring or auditing purposes.

Logs may have different formats:

  • unstructured or plain text: similar to print statements, free-form text
  • semi-structured: some values have a structure and the remaining data free-form
  • structured: there is a well-defined and consistent format, such as: W3C Log Format, NCSA Log Format, Key/Value Pair, CSV or JSON, among others. Structured logs can be easily machine parsed, which simplifies analytics, filtering and aggregation.

This article is a non-exhaustive walkthrough of logging in Go.

Unstructured logging

The log package allows the unstructured log writing:

package main

import (
	"log"
	"os"
)

func main() {
	logger := log.New(os.Stderr, "", log.LstdFlags)
	logger.Println("Hello world!")
}

Where LstdFlags is a subset of the semi-structured flags available:

const (
	Ldate         = 1 << iota     // the date in the local time zone: 2009/01/23
	Ltime                         // the time in the local time zone: 01:23:23
	Lmicroseconds                 // microsecond resolution: 01:23:23.123123.  assumes Ltime.
	Llongfile                     // full file name and line number: /a/b/c/d.go:23
	Lshortfile                    // final file name element and line number: d.go:23. overrides Llongfile
	LUTC                          // if Ldate or Ltime is set, use UTC rather than the local time zone
	Lmsgprefix                    // move the "prefix" from the beginning of the line to before the message
	LstdFlags     = Ldate |  Ltime // initial values for the standard logger
)

Although there are some structured flags available, most logging still happens in free-form format.

Structured logging

There are multiple libraries in Go that support structured logging, one of the most used is logrus:

package main

import (
	log "github.com/sirupsen/logrus"
)

func main() {
	log.SetFormatter(&log.JSONFormatter{})
	
	log.WithFields(log.Fields{
		"animal": "walrus",
	}).Info("A walrus appears")
}

// outputs:
// {"animal":"walrus","level":"info","msg":"A walrus appears","time":"2023-01-01T09:00:00+01:00"}

Logging can impact the application performance, specially if the logging overhead starts to be noticeable.

There are two libraries in the ecosystem with performance as a main feature: zap and zerolog.

According to the benchmarks provided by the zap project:

Package Time Time % to zap Objects Allocated
⚡ zap 1744 ns/op +0% 5 allocs/op
⚡ zap (sugared) 2483 ns/op +42% 10 allocs/op
zerolog 918 ns/op -47% 1 allocs/op
go-kit 5590 ns/op +221% 57 allocs/op
slog 5640 ns/op +223% 40 allocs/op
apex/log 21184 ns/op +1115% 63 allocs/op
logrus 24338 ns/op +1296% 79 allocs/op
log15 26054 ns/op +1394% 74 allocs/op

Looking at the benchmark it is evident that logging can impact heavily both latency and memory/gc by several order of magnitude.

Using zerolog as an example, the API is still user-friendly:

package main  
  
import (
	"os"
	
	"github.com/rs/zerolog"
)  
  
func main() {  
    logger := zerolog.New(os.Stderr).With().Timestamp().Logger()  
    logger.Info().Msg("hello world")  
}
// outputs:
// {"level":"info","time":"2023-01-01T09:00:00+01:00","message":"hello world"}

Abstraction

Given the multiple structured logging libraries available, it is common practice to create an agnostic abstraction to avoid being tied to implementation specifics.

A starting point could be something like:

type Logger interface {
	Info(ctx context.Context, msg string, keysAndValues ...any)
	Error(ctx context.Context, msg string, keysAndValues ...any)
	...
}

Another option could be using logr, which provides an API without being tied to a specific implementation and without dependencies.

The API is not an interface, but a concrete type for performance reasons:

type Logger struct {
	sink  LogSink
	level int
}

Where the LogSink looks similar to a hypothetical logging interface:

// LogSink represents a logging implementation.  End-users will generally not
// interact with this type.
type LogSink interface {
	Info(level int, msg string, keysAndValues ...any)

	// Error logs an error, with the given message and key/value pairs as
	// context.  See Logger.Error for more details.
	Error(err error, msg string, keysAndValues ...any)

	// WithValues returns a new LogSink with additional key/value pairs.  See
	// Logger.WithValues for more details.
	WithValues(keysAndValues ...any) LogSink
}

In practice, using zerolog as the LogSink:

package main

import (
	"os"

	"github.com/go-logr/zerologr"
	"github.com/rs/zerolog"
)

func main() {
	zl := zerolog.New(os.Stderr).With().Timestamp().Logger()

	logger := zerologr.New(&zl)

	logger.WithValues("a", 42).Info("hello world")
	
	// alternative
	logger.Info("hello world", "a", 42)
}

// outputs:
// {"level":"info","a":42,"v":0,"time":"2023-01-01T09:00:00+01:00","message":"hello world"}
// {"level":"info","v":0,"a":42,"time":"2023-01-01T09:00:00+01:00","message":"hello world"}

slog

The slog package introduces structured logging as a first class package in the standard library in Go version 1.21.0.

The design document is a good starting point on the decisions and trade-offs.

The library provides different ways to log:

package main

import (
	"context"
	"log/slog"
	"os"
)

func main() {
	logger := slog.New(slog.NewJSONHandler(os.Stdout, nil))

	logger.Info("hello world", "a", 5)

	// alternative
	logger.Info("hello world", slog.Int("a", 5))

	// alternative
	logger.LogAttrs(context.Background(),
		slog.LevelInfo, 
		"hello world",
		slog.Int("a", 5))
}

// outputs:
// {"time":"2023-01-01T09:00:00.000000+01:00","level":"INFO","msg":"hello world","a":5}
// {"time":"2023-01-01T09:00:00.000000+01:00","level":"INFO","msg":"hello world","a":5}
// {"time":"2023-01-01T09:00:00.000000+01:00","level":"INFO","msg":"hello world","a":5}

The LogValuer interface makes for an interesting addition:

// A LogValuer is any Go value that can convert itself into a Value for logging.
//  
// This mechanism may be used to defer expensive operations until they are  
// needed, or to expand a single value into a sequence of components.  
type LogValuer interface {  
  LogValue() Value  
}

Implementing the interface:

package main  
  
import (  
    "log/slog"  
    "os"    
    "time"
)  
  
type expensive struct{ arg int }  
  
func (e expensive) LogValue() slog.Value {  
    return slog.AnyValue(computeExpensiveValue(e.arg))  
}  
  
func computeExpensiveValue(arg int) any {  
    time.Sleep(time.Second * 10)  
    return arg  
}  
  
func main() {  
    logger := slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{  
       Level: slog.LevelInfo,  
    }))  
  
    start := time.Now()  
  
    logger.Debug("hello world", "a", 5, "b", expensive{5})  
  
    logger.Info("done", "took_seconds", time.Since(start).Seconds())  
}

// outputs:
// {"time":"2023-01-01T09:00:00.000000+01:00","level":"INFO","msg":"done","took_seconds":0.000001083}

In this case only Info or above is logged, the computeExpensiveValue is not called.

Another use case for the LogValuer is redacting sensible information:

func (t Token) LogValue() slog.Value {
	return slog.StringValue("REDACTED")
}

At slog core, the Handler interface log records produced by a Logger (comments omitted for brevity):

type Handler interface {
	Enabled(context.Context, Level) bool
	Handle(context.Context, Record) error
	WithAttrs(attrs []Attr) Handler
	WithGroup(name string) Handler
}

The slog package provides a TextHandler and JSONHandler, but a user can pick different implementations. It is possible to use slog with existing log libraries like zap:

package main

import (
	"context"
	"log/slog"
	"time"

	"go.uber.org/zap"
	"go.uber.org/zap/exp/zapslog"
	"go.uber.org/zap/zapcore"
)

var outputStderr = []string{"stdout"}

func main() {
	encoderConfig := zap.NewProductionEncoderConfig()
	encoderConfig.TimeKey = "time"
	encoderConfig.EncodeTime = func(t time.Time, enc zapcore.PrimitiveArrayEncoder) {
		enc.AppendString(t.Format(time.RFC3339Nano))
	}

	cfg := &zap.Config{
		Level:            zap.NewAtomicLevelAt(zap.InfoLevel),
		Encoding:         "json",
		EncoderConfig:    encoderConfig,
		OutputPaths:      outputStderr,
		ErrorOutputPaths: outputStderr,
	}

	zp, _ := cfg.Build()
	defer zp.Sync()

	logger := slog.New(zapslog.NewHandler(zp.Core(), nil))

	logger.Info("hello world", "a", 5)

	// alternative
	logger.Info("hello world", slog.Int("a", 5))

	// alternative
	logger.LogAttrs(context.Background(),
		slog.LevelInfo,
		"hello world",
		slog.Int("a", 5))
}

// outputs:
// {"level":"info","time":"2023-01-01T09:00:00.000000+01:00","msg":"hello world","a":5}
// {"level":"info","time":"2023-01-01T09:00:00.000000+01:00","msg":"hello world","a":5}
// {"level":"info","time":"2023-01-01T09:00:00.000000+01:00","msg":"hello world","a":5}

Conclusion

Writing structure logs in Go was massively simplified with the introduction of the log/slog package, with the advantage of removing the need for external dependencies.

The usage of packages like logr or creating custom logging interfaces is less relevant, given it is easier to create slog handlers.

The slog performance according to the zap project benchmarks is in a good enough place, although there is room for using zap or zerolog if performance and latency are critical.

Go “batteries included philosophy has therefore improved with the addition of slog.