memby/server/internal/logging/console.go

package logging

import (
	"context"
	"io"
	"log/slog"
	"slices"
	"strconv"
	"strings"
	"sync"
	"time"
)

// levelWidth and messageWidth keep the fields of consecutive lines in the same columns,
// which is what makes a scrolling log readable at a glance. Both are minimums: a longer
// message pushes its fields right rather than being truncated.
const (
	levelWidth   = 5
	messageWidth = 30
)

// consoleHandler writes one aligned line per event — timestamp, level, message, fields.
//
// The timestamp leads the line rather than arriving as a `time=` field. Everything that
// reads these lines (docker compose logs, the admin page, a NAS console) already treats
// the start of a line as when it happened, so a labelled key there is noise sitting in
// front of the message.
type consoleHandler struct {
	// mu is shared by every derived handler: WithAttrs clones this struct, and two
	// clones writing to the same file must still produce whole lines.
	mu     *sync.Mutex
	w      io.Writer
	level  slog.Leveler
	attrs  []field
	groups []string
}

type field struct {
	key   string
	value string
}

func newConsoleHandler(w io.Writer, level slog.Leveler) *consoleHandler {
	return &consoleHandler{mu: &sync.Mutex{}, w: w, level: level}
}

func (h *consoleHandler) Enabled(_ context.Context, level slog.Level) bool {
	return level >= h.level.Level()
}

func (h *consoleHandler) Handle(_ context.Context, record slog.Record) error {
	fields := slices.Clone(h.attrs)
	record.Attrs(func(attr slog.Attr) bool {
		fields = appendField(fields, h.groups, attr)
		return true
	})
	orderFields(fields)

	var line strings.Builder
	line.WriteString(record.Time.UTC().Format(time.DateTime))
	line.WriteByte(' ')
	line.WriteString(pad(LevelName(record.Level), levelWidth))
	line.WriteByte(' ')
	line.WriteString(pad(record.Message, messageWidth))
	for _, f := range fields {
		line.WriteByte(' ')
		line.WriteString(f.key)
		line.WriteByte('=')
		line.WriteString(quote(f.value))
	}
	line.WriteByte('\n')

	h.mu.Lock()
	defer h.mu.Unlock()
	_, err := io.WriteString(h.w, line.String())
	return err
}

func (h *consoleHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
	clone := *h
	clone.attrs = slices.Clone(h.attrs)
	for _, attr := range attrs {
		clone.attrs = appendField(clone.attrs, h.groups, attr)
	}
	return &clone
}

func (h *consoleHandler) WithGroup(name string) slog.Handler {
	clone := *h
	clone.groups = append(slices.Clone(h.groups), name)
	return &clone
}

func appendField(target []field, groups []string, attr slog.Attr) []field {
	attr.Value = attr.Value.Resolve()
	if attr.Equal(slog.Attr{}) {
		return target
	}
	if attr.Value.Kind() == slog.KindGroup {
		for _, child := range attr.Value.Group() {
			target = appendField(target, append(groups, attr.Key), child)
		}
		return target
	}
	key := strings.Join(append(append([]string{}, groups...), attr.Key), ".")
	return append(target, field{key: key, value: safeAttribute(key, attributeValue(attr.Value))})
}

// fieldRank puts the fields that identify *who and where* first, in the same order on
// every line, so scanning a column answers "which TV, which user" without reading.
// Anything unranked keeps the order the caller wrote it in, which is usually the order
// that reads best for that particular event.
var fieldRank = map[string]int{
	"component": 1,
	"user":      2,
	// The person watching sits beside the account they watch through, because on a
	// household running viewers those are different answers and the line has to give both.
	"viewer":          3,
	"device":          4,
	"client":          5,
	"correlation":     6,
	"play_session_id": 7,
	"protocol":        8,
	"method":          9,
	"path":            10,
	"status":          11,
	"duration":        12,
	// Constant per process, so it belongs at the end of the line rather than in front
	// of the fields that differ between events.
	"version": 900,
	// An error is the reason for the line; keeping it last means it is never buried
	// between routine fields.
	"error": 1000,
}

func orderFields(fields []field) {
	rank := func(f field) int {
		if r, ok := fieldRank[f.key]; ok {
			return r
		}
		return 100
	}
	slices.SortStableFunc(fields, func(a, b field) int { return rank(a) - rank(b) })
}

func pad(value string, width int) string {
	if len(value) >= width {
		return value
	}
	return value + strings.Repeat(" ", width-len(value))
}

// quote only intervenes when a bare value would be ambiguous. Quoting everything would
// double the punctuation on a line whose whole purpose is to be read.
func quote(value string) string {
	if value == "" {
		return `""`
	}
	if strings.ContainsAny(value, " \t\"=\n") {
		return strconv.Quote(value)
	}
	return value
}

func attributeValue(value slog.Value) string {
	switch value.Kind() {
	case slog.KindDuration:
		return value.Duration().String()
	case slog.KindTime:
		return value.Time().UTC().Format(time.RFC3339)
	case slog.KindInt64:
		return strconv.FormatInt(value.Int64(), 10)
	default:
		return value.String()
	}
}