vaultik/internal/log/tty_handler_test.go

package log_test

import (
	"bytes"
	"context"
	"encoding/json"
	"fmt"
	"log/slog"
	"math"
	"regexp"
	"sort"
	"strconv"
	"strings"
	"sync"
	"testing"

	"github.com/stretchr/testify/assert"
	"github.com/stretchr/testify/require"
	"sneak.berlin/go/vaultik/internal/log"
)

// ansiEscape matches the SGR sequences TTYHandler wraps every field in.
// Stripping them is what lets a test compare TTYHandler's rendering with
// slog.JSONHandler's.
var ansiEscape = regexp.MustCompile(`\x1b\[[0-9;]*m`)

// countKey is an attribute key reused across the comparison cases.
const countKey = "count"

// debugHandlerOptions enables every level, so a test never has to reason
// about the default level while reasoning about attributes.
func debugHandlerOptions() *slog.HandlerOptions {
	return &slog.HandlerOptions{Level: slog.LevelDebug}
}

// ttyAttrs renders one record through a TTYHandler and returns its
// attributes as key -> value, with color stripped.
//
// TTYHandler emits " key=value" per attribute after the message, and the
// message itself is the last thing before the first attribute, so
// splitting on spaces and keeping the tokens containing "=" recovers the
// attribute set. Test values below therefore avoid spaces and "=".
func ttyAttrs(t *testing.T, derive func(*slog.Logger) *slog.Logger,
	msg string, args ...any,
) map[string]string {
	t.Helper()

	var buf bytes.Buffer

	logger := slog.New(log.NewTTYHandler(&buf, debugHandlerOptions()))
	derive(logger).Info(msg, args...)

	line := ansiEscape.ReplaceAllString(buf.String(), "")
	attrs := make(map[string]string)

	for token := range strings.FieldsSeq(line) {
		key, value, found := strings.Cut(token, "=")
		if !found {
			continue
		}

		attrs[key] = value
	}

	return attrs
}

// jsonAttrs renders one record through slog.JSONHandler and returns its
// attributes flattened to the same dotted-key form TTYHandler uses, so
// the two are directly comparable. The built-in time/level/msg fields
// are dropped: they are the record, not its attributes.
func jsonAttrs(t *testing.T, derive func(*slog.Logger) *slog.Logger,
	msg string, args ...any,
) map[string]string {
	t.Helper()

	var buf bytes.Buffer

	logger := slog.New(slog.NewJSONHandler(&buf, debugHandlerOptions()))
	derive(logger).Info(msg, args...)

	var decoded map[string]any

	require.NoError(t, json.Unmarshal(buf.Bytes(), &decoded))

	delete(decoded, slog.TimeKey)
	delete(decoded, slog.LevelKey)
	delete(decoded, slog.MessageKey)

	attrs := make(map[string]string)
	flattenJSON(attrs, "", decoded)

	return attrs
}

// flattenJSON turns JSONHandler's nested group objects into the dotted
// keys TTYHandler writes.
func flattenJSON(dst map[string]string, prefix string, src map[string]any) {
	for key, value := range src {
		full := key
		if prefix != "" {
			full = prefix + "." + key
		}

		nested, ok := value.(map[string]any)
		if ok {
			flattenJSON(dst, full, nested)

			continue
		}

		dst[full] = valueString(value)
	}
}

// valueString renders a decoded JSON scalar the way slog.Value.String
// renders the corresponding Go value, so the two handlers' outputs can
// be compared as strings. encoding/json decodes every number as
// float64, so an integral one is rendered back as an integer — which is
// what the Go value that produced it was.
func valueString(v any) string {
	switch typed := v.(type) {
	case string:
		return typed
	case bool:
		return strconv.FormatBool(typed)
	case float64:
		if typed == math.Trunc(typed) {
			return strconv.FormatInt(int64(typed), 10)
		}

		return strconv.FormatFloat(typed, 'g', -1, 64)
	default:
		return fmt.Sprint(v)
	}
}

// TestTTYHandlerWithAttrsEmitsAttributes is the direct regression test
// for the reported defect: WithAttrs discarded its argument, so an
// attribute attached to a logger never reached the output.
func TestTTYHandlerWithAttrsEmitsAttributes(t *testing.T) {
	t.Parallel()

	attrs := ttyAttrs(t, func(l *slog.Logger) *slog.Logger {
		return l.With("key", "value")
	}, "hello")

	assert.Equal(t, "value", attrs["key"],
		"an attribute attached with With must appear on every record")
}

// TestTTYHandlerWithAttrsPersistsAcrossRecords checks that the
// attributes are retained rather than emitted once. A handler that
// stored them but consumed them would pass the test above.
func TestTTYHandlerWithAttrsPersistsAcrossRecords(t *testing.T) {
	t.Parallel()

	var buf bytes.Buffer

	logger := slog.New(log.NewTTYHandler(&buf, debugHandlerOptions())).
		With("request", "abc123")

	logger.Info("first")
	logger.Info("second")

	plain := ansiEscape.ReplaceAllString(buf.String(), "")
	lines := strings.Split(strings.TrimSuffix(plain, "\n"), "\n")

	require.Len(t, lines, 2)

	for _, line := range lines {
		assert.Contains(t, line, "request=abc123")
	}
}

// TestTTYHandlerWithGroupQualifiesKeys checks that WithGroup does
// something real rather than being discarded. This format has no
// nesting, so grouping shows up as a dotted key prefix.
func TestTTYHandlerWithGroupQualifiesKeys(t *testing.T) {
	t.Parallel()

	attrs := ttyAttrs(t, func(l *slog.Logger) *slog.Logger {
		return l.WithGroup("db").With("rows", 3)
	}, "queried", "table", "chunks")

	assert.Equal(t, "3", attrs["db.rows"],
		"an attribute added under a group must be qualified by it")
	assert.Equal(t, "chunks", attrs["db.table"],
		"a record attribute must also be qualified by the open group")
	assert.NotContains(t, attrs, "rows")
}

// TestTTYHandlerByteFormattingSurvivesGrouping guards the interaction
// between the two features. The human-readable rendering of a "bytes"
// attribute is selected by comparing the key, and keys reaching that
// comparison are group-qualified, so a "bytes" attribute logged under an
// open group arrived as "transfer.bytes" and fell back to a bare number.
// No caller groups a byte count today, which is exactly why this needs a
// test rather than a bug report.
func TestTTYHandlerByteFormattingSurvivesGrouping(t *testing.T) {
	t.Parallel()

	const oneAndAHalfKiB = 1536

	for name, testCase := range map[string]struct {
		derive func(*slog.Logger) *slog.Logger
		key    string
	}{
		"ungrouped": {
			derive: func(l *slog.Logger) *slog.Logger { return l },
			key:    "bytes",
		},
		"grouped": {
			derive: func(l *slog.Logger) *slog.Logger {
				return l.WithGroup("transfer")
			},
			key: "transfer.bytes",
		},
	} {
		t.Run(name, func(t *testing.T) {
			t.Parallel()

			var buf bytes.Buffer

			logger := slog.New(log.NewTTYHandler(&buf, debugHandlerOptions()))
			testCase.derive(logger).Info("uploaded", "bytes", oneAndAHalfKiB)

			line := ansiEscape.ReplaceAllString(buf.String(), "")

			assert.Contains(t, line, testCase.key+"=1.5 KB",
				"a byte count must be human-readable however it is qualified")
			assert.NotContains(t, line, strconv.Itoa(oneAndAHalfKiB),
				"the raw number must not survive the formatting")
		})
	}
}

// TestTTYHandlerMatchesJSONHandlerAttributes is the drift guard. The
// handler is chosen by TTY-ness, so a difference between these two is
// invisible in whichever environment the developer is not in — which is
// how the original defect survived: attributes vanished on a terminal
// and were correct in CI.
func TestTTYHandlerMatchesJSONHandlerAttributes(t *testing.T) {
	t.Parallel()

	cases := []struct {
		name   string
		derive func(*slog.Logger) *slog.Logger
		args   []any
	}{
		{
			name:   "record attributes only",
			derive: func(l *slog.Logger) *slog.Logger { return l },
			args:   []any{"path", "/etc/vaultik", countKey, 7},
		},
		{
			name: "handler attributes",
			derive: func(l *slog.Logger) *slog.Logger {
				return l.With("host", "alpha")
			},
			args: []any{countKey, 7},
		},
		{
			name: "handler attributes accumulate",
			derive: func(l *slog.Logger) *slog.Logger {
				return l.With("host", "alpha").With("snapshot", "s1")
			},
			args: []any{countKey, 7},
		},
		{
			name: "group qualifies later attributes",
			derive: func(l *slog.Logger) *slog.Logger {
				return l.WithGroup("db").With("rows", 3)
			},
			args: []any{"table", "chunks"},
		},
		{
			name: "nested groups",
			derive: func(l *slog.Logger) *slog.Logger {
				return l.WithGroup("outer").WithGroup("inner").
					With("leaf", "v")
			},
			args: []any{"other", "w"},
		},
		{
			name: "attributes before and after a group",
			derive: func(l *slog.Logger) *slog.Logger {
				return l.With("top", "t").WithGroup("g").With("in", "i")
			},
			args: []any{"rec", "r"},
		},
		{
			name:   "inline group value on the record",
			derive: func(l *slog.Logger) *slog.Logger { return l },
			args: []any{slog.Group("net",
				slog.String("proto", "s3"), slog.Int("retries", 2))},
		},
	}

	for _, testCase := range cases {
		t.Run(testCase.name, func(t *testing.T) {
			t.Parallel()

			tty := ttyAttrs(t, testCase.derive, "message", testCase.args...)
			js := jsonAttrs(t, testCase.derive, "message", testCase.args...)

			assert.Equal(t, sortedKeys(js), sortedKeys(tty),
				"TTY and JSON handlers must emit the same attribute keys")
			assert.Equal(t, js, tty,
				"TTY and JSON handlers must emit the same attribute values")
		})
	}
}

// sortedKeys returns m's keys in order, for a stable comparison message.
func sortedKeys(m map[string]string) []string {
	keys := make([]string, 0, len(m))
	for key := range m {
		keys = append(keys, key)
	}

	sort.Strings(keys)

	return keys
}

// TestTTYHandlerWithAttrsDoesNotMutateReceiver checks that deriving does
// not write through to the parent or to a sibling. slog permits a
// handler to be shared, so a WithAttrs that appended into the receiver's
// state would leak attributes between unrelated loggers.
func TestTTYHandlerWithAttrsDoesNotMutateReceiver(t *testing.T) {
	t.Parallel()

	var buf bytes.Buffer

	base := slog.New(log.NewTTYHandler(&buf, debugHandlerOptions()))
	first := base.With("branch", "one")
	second := base.With("branch", "two")

	base.Info("base")
	first.Info("first")
	second.Info("second")

	plain := ansiEscape.ReplaceAllString(buf.String(), "")
	lines := strings.Split(strings.TrimSuffix(plain, "\n"), "\n")

	require.Len(t, lines, 3)

	assert.NotContains(t, lines[0], "branch=",
		"deriving must not add attributes to the handler derived from")
	assert.Contains(t, lines[1], "branch=one")
	assert.NotContains(t, lines[1], "branch=two")
	assert.Contains(t, lines[2], "branch=two")
	assert.NotContains(t, lines[2], "branch=one")
}

// TestTTYHandlerConcurrentDerivation exercises the same handler being
// derived from and written through by several goroutines at once, which
// is what slog permits and what a mutating WithAttrs would make a data
// race. Run under -race by script/test.
func TestTTYHandlerConcurrentDerivation(t *testing.T) {
	t.Parallel()

	const workers = 16

	var buf bytes.Buffer

	base := slog.New(log.NewTTYHandler(&buf, debugHandlerOptions())).
		With("shared", "yes")

	var group sync.WaitGroup

	group.Add(workers)

	for worker := range workers {
		go func() {
			defer group.Done()

			base.With("worker", worker).
				WithGroup("g").
				With("nested", worker).
				Info("concurrent")
		}()
	}

	group.Wait()

	plain := ansiEscape.ReplaceAllString(buf.String(), "")
	lines := strings.Split(strings.TrimSuffix(plain, "\n"), "\n")

	require.Len(t, lines, workers)

	for _, line := range lines {
		assert.Contains(t, line, "shared=yes")
		assert.Contains(t, line, "worker=")
		assert.Contains(t, line, "g.nested=")
	}
}

// TestTTYHandlerEmptyGroupAndAttrsAreNoOps covers the slog.Handler
// contract corners: WithGroup("") and WithAttrs(nil) change nothing, and
// an empty Attr is dropped rather than rendered as "=".
func TestTTYHandlerEmptyGroupAndAttrsAreNoOps(t *testing.T) {
	t.Parallel()

	var buf bytes.Buffer

	handler := log.NewTTYHandler(&buf, debugHandlerOptions())

	assert.Same(t, handler, handler.WithGroup(""),
		"an empty group name must not open a group")
	assert.Same(t, handler, handler.WithAttrs(nil),
		"deriving with no attributes must not allocate a handler")

	slog.New(handler).LogAttrs(context.Background(), slog.LevelInfo, "msg",
		slog.Attr{}, slog.String("kept", "yes"))

	plain := ansiEscape.ReplaceAllString(buf.String(), "")

	assert.Contains(t, plain, "kept=yes")
	assert.NotContains(t, plain, " =")
}