diff --git a/internal/logfield/logfield_test.go b/internal/logfield/logfield_test.go index 689b22c..25b46dc 100644 --- a/internal/logfield/logfield_test.go +++ b/internal/logfield/logfield_test.go @@ -5,6 +5,7 @@ import ( "io" "log/slog" "strings" + "sync" "testing" "unicode/utf8" @@ -18,15 +19,11 @@ import ( // 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 +// 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 — @@ -66,46 +63,43 @@ func renderedWidth( 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 - ) +// 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) +} - var runes []rune +// 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 - keep := func(r rune) { - if r >= surrogateLo && r <= surrogateHi { - return + for _, r := range s { + if emittedBytes(newHandler, string(r)) <= logfield.EncodedBytes(r) { + continue } - runes = append(runes, r) + if count == 0 { + first = r + } + + count++ } - 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 + return first, count } // TestEncodedBytes_ChargesAtLeastWhatTheHandlersEmit is the property @@ -114,33 +108,90 @@ func chargeTestRunes() []rune { // 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() - // '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), + 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, ) - 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, + 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, ) } })