package logfield_test import ( "bytes" "io" "log/slog" "strings" "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 // sampleRunes is how many runes wide the values in the charge test // are. The handlers add a constant per field — a pair of quotes when // the value needs quoting — so the per-rune charge is only visible // once it is amortised over a run of them. const sampleRunes = 64 // quotingSlack is that constant: the pair of quotes a handler adds to // a value that needs them and omits from one that does not. const quotingSlack = 2 // 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() } // chargeTestRunes is the set of code points the charge test measures: // every rune in the first two planes' worth of the BMP that the // handlers are most likely to treat specially, the separators that // only slog's JSON handler escapes, and a stratified sample across // the rest of Unicode so the astral charge is exercised on more than // one hand-picked rune. func chargeTestRunes() []rune { const ( denseCeiling = 0x800 stride = 1021 surrogateLo = 0xD800 surrogateHi = 0xDFFF ) var runes []rune keep := func(r rune) { if r >= surrogateLo && r <= surrogateHi { return } runes = append(runes, r) } for r := range rune(denseCeiling) { keep(r) } for _, r := range []rune{ 0x2028, 0x2029, 0x200B, 0x4E00, 0xE000, 0xFFFD, 0x1000C, 0x1F600, 0xE0001, 0x10FFFF, } { keep(r) } for r := rune(denseCeiling); r <= utf8.MaxRune; r += stride { keep(r) } return runes } // 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. func TestEncodedBytes_ChargesAtLeastWhatTheHandlersEmit(t *testing.T) { t.Parallel() for name, newHandler := range newHandlers() { t.Run(name, func(t *testing.T) { t.Parallel() // 'a' is a printable ASCII rune, charged exactly one // byte, so it is the zero point the other runes are // measured against. base := renderedWidth( newHandler, strings.Repeat("a", sampleRunes), ) for _, r := range chargeTestRunes() { got := renderedWidth( newHandler, strings.Repeat(string(r), sampleRunes), ) charged := sampleRunes * (logfield.EncodedBytes(r) - 1) require.LessOrEqual( t, got-base, charged+quotingSlack, "U+%04X costs more on the line than "+ "EncodedBytes charges for it", r, ) } }) } } // 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", "/source/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) } }