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 // is too slow for the suite 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: the // width of a line carrying s twice, less that of a line carrying it // once. Both values hold the same runes, so the text handler quotes // both or neither, and the quotes cancel along with everything else on // the line. func emittedBytes( newHandler func(io.Writer) slog.Handler, s string, ) int { return renderedWidth(newHandler, s+s) - renderedWidth(newHandler, 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, // so 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 { if emittedBytes(newHandler, string(r)) <= logfield.EncodedBytes(r) { 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. // // 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. Under -race -cover this // takes 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) } }