Check the log charge against every code point (closes #172)
check / check (push) Waiting to run
check / check (push) Waiting to run
The access log's 2,560-byte line ceiling holds only if logfield.EncodedBytes charges each code point at least what the log handlers write for it, and the test checked that on a sample. TestEncodedBytes_ChargesAtLeastWhatTheHandlersEmit now covers every code point, surrogates aside, for both handlers. Below U+1000, where the handlers' escaping varies, each code point is measured alone, both in a bare value and in a quoted one, so undercharging any of them, DEL included, fails and names it. From U+1000 up it compares batch sums, which the doc comment says can hide one JSON-only overcharge. Reverting the astral charge to 6 fails the test. It adds under 2 seconds under -race. Model: opus-5-5
This commit was merged in pull request #442.
This commit is contained in:
@@ -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,48 @@ 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, 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)
|
||||
}
|
||||
|
||||
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,
|
||||
// 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
|
||||
|
||||
keep := func(r rune) {
|
||||
if r >= surrogateLo && r <= surrogateHi {
|
||||
return
|
||||
for _, r := range s {
|
||||
charge := logfield.EncodedBytes(r)
|
||||
if emittedBytes(newHandler, "", string(r)) <= charge &&
|
||||
emittedBytes(newHandler, " ", string(r)) <= charge {
|
||||
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 +113,93 @@ 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. 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. 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,
|
||||
)
|
||||
}
|
||||
})
|
||||
|
||||
Reference in New Issue
Block a user