webhooker/internal/logfield/logfield_test.go

package logfield_test

import (
	"bytes"
	"io"
	"log/slog"
	"strings"
	"sync"
	"testing"
	"unicode/utf8"

	"github.com/stretchr/testify/assert"
	"github.com/stretchr/testify/require"
	"sneak.berlin/go/webhooker/internal/logfield"
)

// budget is the field budget these tests spend. Small enough that a
// cut is unambiguous, large enough to hold several runes of every
// width.
const budget = 64

// batchRunes is how many consecutive code points the charge test logs
// in one value from U+1000 up. Logging each of those on its own line
// was too slow for the suite when it ran under the race detector;
// 4,096 at a time is 271 batches, each logged on two lines, so 542
// lines per handler.
const batchRunes = 4096

// newHandlers are the two handlers internal/logger can install. Time
// is dropped so a line's width is a function of its value alone —
// RFC3339Nano trims trailing zeros, so two consecutive timestamps do
// not render to the same number of bytes.
func newHandlers() map[string]func(io.Writer) slog.Handler {
	opts := &slog.HandlerOptions{
		Level: slog.LevelDebug,
		ReplaceAttr: func(_ []string, a slog.Attr) slog.Attr {
			if a.Key == slog.TimeKey {
				return slog.Attr{}
			}

			return a
		},
	}

	return map[string]func(io.Writer) slog.Handler{
		"json": func(w io.Writer) slog.Handler {
			return slog.NewJSONHandler(w, opts)
		},
		"text": func(w io.Writer) slog.Handler {
			return slog.NewTextHandler(w, opts)
		},
	}
}

// renderedWidth is the number of bytes a handler writes for a line
// carrying value in a single attribute.
func renderedWidth(
	newHandler func(io.Writer) slog.Handler,
	value string,
) int {
	buf := new(bytes.Buffer)
	slog.New(newHandler(buf)).Info("m", "v", value)

	return buf.Len()
}

// emittedBytes is what a handler writes for the runes of s alone, in a
// value that starts with prefix: the width of a line carrying prefix
// and then s twice, less that of a line carrying prefix and s once.
// Both values start the same way and hold the same runes, so the text
// handler quotes both or neither, and the quotes cancel along with the
// prefix and everything else on the line.
func emittedBytes(
	newHandler func(io.Writer) slog.Handler,
	prefix, s string,
) int {
	return renderedWidth(newHandler, prefix+s+s) -
		renderedWidth(newHandler, prefix+s)
}

// firstUndercharged returns the first rune in s that the handler
// writes in more bytes than EncodedBytes charges for it, and how many
// runes in s are undercharged that way. It measures one rune per line,
// in a value of that rune alone and again after a space, which makes
// the text handler quote the value. The charge test calls it on the
// code points below U+1000, and from there up only on a batch that has
// already failed, to name the code points rather than just their range.
func firstUndercharged(
	newHandler func(io.Writer) slog.Handler,
	s string,
) (rune, int) {
	first, count := rune(-1), 0

	for _, r := range s {
		charge := logfield.EncodedBytes(r)
		if emittedBytes(newHandler, "", string(r)) <= charge &&
			emittedBytes(newHandler, " ", string(r)) <= charge {
			continue
		}

		if count == 0 {
			first = r
		}

		count++
	}

	return first, count
}

// TestEncodedBytes_ChargesAtLeastWhatTheHandlersEmit is the property
// the whole capping scheme rests on: a rune may not cost more on the
// line than the budget was charged for it. An undercharged rune is
// how a stated ceiling becomes false without any test noticing, so
// the charge is measured against what the handlers actually write
// rather than against the escaping rules as read.
//
// Every code point below U+1000 is checked on its own, for both
// handlers. That range holds the quote, the backslash and the control
// characters the handlers escape, next to code points each handler
// writes in fewer bytes than their charge, which in a sum would cover
// a neighbour charged too little. Each is measured in a value of it
// alone and again in one the text handler quotes, because that handler
// writes U+007F as one raw byte in a value it leaves bare but as \x7f,
// four bytes, in one it quotes.
//
// From U+1000 up the text handler writes every code point in exactly
// its charge, so the rest of Unicode is checked batchRunes at a time:
// each batch's summed charge must cover what the handler writes for
// the whole batch. The sums there can miss the JSON handler alone
// writing one code point in more bytes than its charge, when it writes
// others in the same batch in fewer.
func TestEncodedBytes_ChargesAtLeastWhatTheHandlersEmit(t *testing.T) {
	t.Parallel()

	var below strings.Builder
	for r := range rune(0x1000) {
		below.WriteRune(r)
	}

	var batches []string

	for lo := rune(0x1000); lo <= utf8.MaxRune; lo += batchRunes {
		var batch strings.Builder

		for r := lo; r < lo+batchRunes; r++ {
			// Surrogate halves are not runes a string can carry.
			if utf8.ValidRune(r) {
				batch.WriteRune(r)
			}
		}

		batches = append(batches, batch.String())
	}

	// What EncodedBytes charges for each batch. When the suite ran
	// under -race -cover this took longer than logging the batches, so
	// it is worked out once, by whichever handler finishes logging
	// first, while the other is still logging.
	charged := sync.OnceValue(func() []int {
		costs := make([]int, len(batches))

		for i, batch := range batches {
			for _, r := range batch {
				costs[i] += logfield.EncodedBytes(r)
			}
		}

		return costs
	})

	for name, newHandler := range newHandlers() {
		t.Run(name, func(t *testing.T) {
			t.Parallel()

			if first, count := firstUndercharged(newHandler, below.String()); count > 0 {
				t.Errorf(
					"%d code points below U+1000 cost more than "+
						"EncodedBytes charges, the first U+%04X",
					count, first,
				)
			}

			emitted := make([]int, len(batches))
			for i, batch := range batches {
				emitted[i] = emittedBytes(newHandler, "", batch)
			}

			for i, cost := range charged() {
				if emitted[i] <= cost {
					continue
				}

				lo := rune(0x1000 + i*batchRunes)
				first, count := firstUndercharged(
					newHandler, batches[i],
				)
				t.Errorf(
					"U+%04X to U+%04X emit %d bytes but are "+
						"charged %d; %d of them cost more than "+
						"EncodedBytes charges, the first U+%04X",
					lo, lo+batchRunes-1, emitted[i], cost,
					count, first,
				)
			}
		})
	}
}

// TestTruncate_SpendsNoMoreThanTheBudget holds the result to the
// budget in ENCODED bytes, which is the unit the budget is stated in.
// A raw-byte cap passes the ASCII case here and fails every other
// one.
func TestTruncate_SpendsNoMoreThanTheBudget(t *testing.T) {
	t.Parallel()

	for name, fill := range map[string]string{
		"plain":     "x",
		"quote":     `"`,
		"backslash": `\`,
		"tab":       "\t",
		"newline":   "\n",
		"control":   "\x01",
		"astral":    "\U0001000C",
		// U+4E00, a printable multi-byte rune, charged its three
		// UTF-8 bytes rather than an escape. Spelled numerically
		// because gosmopolitan rejects Han in a string literal.
		"cjk": string(rune(0x4E00)),
	} {
		t.Run(name, func(t *testing.T) {
			t.Parallel()

			got := logfield.Truncate(
				strings.Repeat(fill, budget*8), budget,
			)

			require.True(
				t, strings.HasSuffix(
					got, logfield.TruncationMarker,
				),
				"an oversized value must be marked as cut",
			)

			spent := 0
			for _, r := range strings.TrimSuffix(
				got, logfield.TruncationMarker,
			) {
				spent += logfield.EncodedBytes(r)
			}

			assert.LessOrEqual(t, spent, budget)
			assert.True(t, utf8.ValidString(got))
		})
	}
}

// TestTruncate_LeavesShortValuesAlone keeps the marker meaningful: a
// value that fits comes back byte for byte, so a marked value is
// always a cut one.
func TestTruncate_LeavesShortValuesAlone(t *testing.T) {
	t.Parallel()

	for _, s := range []string{
		"", "GET", "/hook/abc/edit", "Mozilla/5.0 (X11)",
	} {
		assert.Equal(t, s, logfield.Truncate(s, budget))
	}
}

// TestTruncate_DropsInvalidUTF8 covers the bytes a header can carry
// that were never valid UTF-8. Keeping them would make the encoder
// spend six bytes apiece replacing them, which is exactly the
// amplification the budget exists to prevent.
func TestTruncate_DropsInvalidUTF8(t *testing.T) {
	t.Parallel()

	got := logfield.Truncate("a\xffb\xfe\xfec", budget)

	assert.Equal(t, "abc", got)
	assert.True(t, utf8.ValidString(got))
}

// encodedCost is what a whole string costs on a line, by the same
// accounting Truncate spends its budget with.
func encodedCost(s string) int {
	total := 0
	for _, r := range s {
		total += logfield.EncodedBytes(r)
	}

	return total
}

// TestTruncate_SpendsEncodedBytesNotRawBytes is the zero-headroom
// version of TestTruncate_SpendsNoMoreThanTheBudget above, and of the
// line-length assertions elsewhere.
//
// A line ceiling has slack in it by construction, and a LessOrEqual
// against the budget cannot tell a budget spent exactly from one
// spent under. Here the budget is checked against exactly what it
// bought: a value built from a single rune must keep exactly
// MaxBytes/EncodedBytes(r) of them, with nothing spare. A raw-byte
// budget — cost := utf8.RuneLen(r) — fails this for every rune the
// handlers escape.
func TestTruncate_SpendsEncodedBytesNotRawBytes(t *testing.T) {
	t.Parallel()

	for name, r := range map[string]rune{
		"plain":           'x',
		"quote":           '"',
		"backslash":       '\\',
		"tab":             '\t',
		"newline":         '\n',
		"carriage_return": '\r',
		"c0_control":      '\x01',
		"del":             '\x7f',
		// U+2028 LINE SEPARATOR, which only the JSON handler
		// escapes.
		"line_separator":      '
',
		"astral_nonprintable": '\U0001000C',
		"multibyte_printable": 'é',
		// U+20AC, a three-byte printable rune, charged its own
		// UTF-8 bytes rather than an escape.
		"three_byte_printable": '€',
		"emoji_printable":      '\U0001F600',
	} {
		t.Run(name, func(t *testing.T) {
			t.Parallel()

			cost := logfield.EncodedBytes(r)
			want := logfield.MaxBytes / cost

			// Far past the budget under either accounting.
			in := strings.Repeat(string(r), logfield.MaxBytes*2)

			got := logfield.Truncate(in, logfield.MaxBytes)

			require.True(
				t, strings.HasSuffix(
					got, logfield.TruncationMarker,
				),
				"a value past the budget must be marked",
			)

			kept := strings.TrimSuffix(
				got, logfield.TruncationMarker,
			)

			assert.Equal(
				t, want, utf8.RuneCountInString(kept),
				"budget bought the wrong number of runes at "+
					"%d encoded bytes each", cost,
			)
			assert.LessOrEqual(
				t, encodedCost(kept), logfield.MaxBytes,
			)
		})
	}
}

// TestTruncate_NeverSplitsARune covers a cut landing inside a
// multi-byte encoding rather than between two of them.
func TestTruncate_NeverSplitsARune(t *testing.T) {
	t.Parallel()

	// U+20AC, three bytes and printable, so a small budget lands
	// inside an encoding rather than on a boundary.
	in := strings.Repeat("€", logfield.MaxBytes)

	for b := 1; b <= 16; b++ {
		got := strings.TrimSuffix(
			logfield.Truncate(in, b), logfield.TruncationMarker,
		)

		assert.True(
			t, utf8.ValidString(got),
			"budget %d produced invalid UTF-8", b,
		)
		assert.LessOrEqual(t, encodedCost(got), b)
	}
}