go / log

I use a custom K=V structured logger in my Go services instead of slog. The key idea is a Helper() registry that lets wrapper functions self-register so they don't appear in caller info — the testing.T.Helper() ergonomic applied to production logging.

The format

Splunk-style key=value pairs, one per line, written to stdout:

at=server.go:42 status=200 method=GET path=/health

Greppable as plain text. No jq, no JSON parser, no log aggregator required.

The package

log.go:

package log

import (
	"context"
	"fmt"
	"os"
	"strconv"
	"strings"
)

const (
	pairDelims      = " ,;|&\t\n\r"
	illegalKeyChars = pairDelims + `="`

	KeyCaller = "at"
	KeyError  = "error"
)

// Printkv prints a structured log entry. Keys and values
// alternate. The location of the caller is prepended as
// at=file:line, skipping any function that called Helper().
func Printkv(ctx context.Context, keyvals ...any) {
	Helper()
	if len(keyvals)%2 != 0 {
		keyvals = append(keyvals, "", "log-error", "odd number of params")
	}
	out := fmt.Sprintf("%s=%s", KeyCaller, caller())
	for i := 0; i < len(keyvals); i += 2 {
		out += " " + formatKey(keyvals[i]) + "=" + formatValue(keyvals[i+1])
	}
	fmt.Fprintln(os.Stdout, out)
}

// Fatalkv prints and exits 1.
func Fatalkv(ctx context.Context, keyvals ...any) {
	Helper()
	Printkv(ctx, keyvals...)
	os.Exit(1)
}

// Error prints err under the "error" key, with optional prefix args.
func Error(ctx context.Context, err error, a ...any) {
	Helper()
	if len(a) > 0 {
		err = fmt.Errorf("%s: %s", fmt.Sprint(a...), err)
	}
	Printkv(ctx, KeyError, err)
}

func formatKey(k any) string {
	s := fmt.Sprint(k)
	if s == "" {
		return "?"
	}
	for _, c := range illegalKeyChars {
		s = strings.Replace(s, string(c), "-", -1)
	}
	return s
}

func formatValue(v any) string {
	s := fmt.Sprint(v)
	if strings.ContainsAny(s, pairDelims) {
		return strconv.Quote(s)
	}
	return s
}

The Helper() registry

The novel piece. Helper() records the name of the calling function. caller() walks the stack and returns the first non-helper frame's file:line. Same idea as testing.T.Helper(), applied to production logging.

stack.go:

package log

import (
	"path/filepath"
	"runtime"
	"strconv"
	"sync"
)

var (
	helperMu   sync.RWMutex
	helperFunc = map[string]bool{}
)

// Helper marks the calling function as a log helper. Logs
// emitted from within it report the caller of the helper,
// not the helper itself. Safe for concurrent use.
func Helper() {
	if name := callerName(1); name != "" && !isHelper(name) {
		markHelper(name)
	}
}

func isHelper(name string) bool {
	helperMu.RLock()
	defer helperMu.RUnlock()
	return helperFunc[name]
}

func markHelper(name string) {
	helperMu.Lock()
	defer helperMu.Unlock()
	helperFunc[name] = true
}

func callerName(skip int) string {
	pc, _, _, ok := runtime.Caller(skip + 1)
	if !ok {
		return ""
	}
	return runtime.FuncForPC(pc).Name()
}

// caller returns "file:line" of the first non-helper frame
// on the calling goroutine's stack.
func caller() string {
	for i := 1; ; i++ {
		pc, file, line, ok := runtime.Caller(i)
		if !ok {
			return "?:?"
		}
		if !isHelper(runtime.FuncForPC(pc).Name()) {
			return filepath.Base(file) + ":" + strconv.Itoa(line)
		}
	}
}

Helpers self-register on first call, so adding a wrapper costs one line:

func logQueryError(ctx context.Context, err error, q string) {
	log.Helper()
	log.Printkv(ctx, "error", err, "query", q)
}

Wrappers must opt in: the library marks its own frames (Printkv, Fatalkv, Error), but it can't tell user forwarders apart from real call sites. Some functions that call Printkv are the call site you want logged.

slog solves the same problem with a static skip count threaded through each wrapper. The registry self-corrects when frames change.

HTTP middleware

loghttp emits one K=V line per request:

type respWriter struct {
	http.ResponseWriter
	status int
}

func (rw *respWriter) WriteHeader(code int) {
	rw.status = code
	rw.ResponseWriter.WriteHeader(code)
}

func loghttp(next http.Handler) http.Handler {
	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		start := time.Now()
		rw := &respWriter{ResponseWriter: w, status: http.StatusOK}
		next.ServeHTTP(rw, r)
		log.Printkv(r.Context(),
			"at", "http",
			"status", rw.status,
			"method", r.Method,
			"path", r.URL.Path,
			"ms", fmt.Sprintf("%.1f", float64(time.Since(start).Microseconds())/1000),
		)
	})
}

Wrap the mux:

http.ListenAndServe(":8080", loghttp(mux))

Why not slog

slog (Go 1.21+) is the modern stdlib answer and the right default for new projects that ship to a log aggregator, correlate with OpenTelemetry, or interoperate with third-party libraries that emit slog-formatted output.

For stdout-only services with grep-based pipelines, slog adds friction. JSON requires jq. Text quotes inconsistently. Caller-skip threads a fragile integer through every wrapper.

The package above is ~180 lines and has covered the services I've shipped. OpenTelemetry would be the trigger to migrate.

When to use

For request tracing across services, pair with reqid.

← All articles