From 9cd87aaf13b7e5a2da1f9b5be8230db9a095ec1f Mon Sep 17 00:00:00 2001 From: DonislawDev Date: Tue, 1 Sep 2026 20:29:37 +0200 Subject: [PATCH] format: a log can be made quiet, or full of errors Adds level_mix to the log format, with realistic, quiet, errors and debug to choose from. It decides which severities appear, the way status_mix already decides which response codes do. The default is realistic, the mix these logs have always carried, so no existing file changes by a byte - checked against a binary built from main, six shapes by three seeds, eighteen of eighteen identical. Only the plain and json-lines shapes carry a severity, so asking for a mix beside one of the other four is refused by a message naming both settings rather than accepted in silence. The refusal fires on a real choice and not on the key arriving, because a window sends every setting it draws and a value equal to the default was never stated. The part that is not obvious from reading the declaration: the chosen set moves the MINIMUM. The shortest entry a shape can write has to leave room for the longest severity it might draw, and quiet draws only INFO, which is a shorter word than ERROR. Measured: plain 41 B against 40, json-lines 83 against 82. An arithmetic reading the whole vocabulary instead of the set in force would be wrong in the safe direction - a floor the format can beat, announced as if it could not - so neither the size guard nor the determinism guard would ever see it. longestLevel takes the options for that reason, and the guard asks for the announced minimum and for one byte below it rather than repeating the arithmetic. That closes the log format. The two settings still listed as missing have recorded reasons rather than no time behind them: an entry count disagrees with the exact size contract, and a start and end pair cannot work when the run does not know the entry count in advance. Co-Authored-By: Claude Opus 5 --- CHANGELOG.md | 17 +++ internal/format/logfile/address.go | 6 +- internal/format/logfile/log.go | 42 +++++++- internal/format/logfile/options.go | 35 +++++- internal/format/logfile/shapes.go | 17 +-- internal/guard/logshapes_test.go | 167 +++++++++++++++++++++++++++++ internal/guard/parity_test.go | 1 + web/public/formats/index.html | 5 + web/public/pl/formaty/index.html | 5 + 9 files changed, 286 insertions(+), 9 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 3ca79d5..fda1b44 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -70,6 +70,23 @@ because it turns other people's test suites red. ### Added +- **A log can be made quiet, or full of errors.** `--set level_mix=errors` on + a `log`, with `realistic`, `quiet`, `errors` and `debug` to choose from. It + decides which severities appear, the way `status_mix` already decides which + response codes do. + + Only the `plain` and `json-lines` entry formats carry a severity at all. Ask + for a mix beside one of the other four and the tool says so and stops, + naming both settings, rather than accepting a setting that would do nothing. + + One thing worth knowing before you pick `quiet`: it draws only `INFO`, which + is a shorter word than `ERROR`, so the smallest log it can write is one byte + smaller than the other mixes. The tool tells you the floor for the settings + you gave it. + + The default is `realistic`, the mix these logs have always had, so **no + existing file changes by a byte**. + - **An archive can compress what it holds.** `--set compression=best` on a `zip` or a `targz`, with `none`, `fast`, `default` and `best` to choose from. diff --git a/internal/format/logfile/address.go b/internal/format/logfile/address.go index cc2580e..fda3729 100644 --- a/internal/format/logfile/address.go +++ b/internal/format/logfile/address.go @@ -152,10 +152,14 @@ func longestAddress(o options) int { return v4Longest } +// longestLevel reads the SET IN FORCE rather than every level this format +// knows, because that is what the minimum entry has to leave room for. Reading +// the whole vocabulary instead would be wrong in the safe direction - a floor +// one byte too high - but it would announce a minimum the format can beat. +func longestLevel(o options) int { return longest(o.levels) } func longestMethod(o options) int { return longest(o.methods) } func longestAgent() int { return longest(agents) } func longestTag() int { return longest(tags) } -func longestLevel() int { return longest(levels) } func longest(xs []string) int { n := 0 diff --git a/internal/format/logfile/log.go b/internal/format/logfile/log.go index df122ad..594a44b 100644 --- a/internal/format/logfile/log.go +++ b/internal/format/logfile/log.go @@ -104,6 +104,11 @@ func properties() []format.Property { Choices: []string{"realistic", "success", "client-errors", "server-errors"}, Default: "realistic", Detail: "Which response codes appear. Realistic is mostly success with a tail of errors.", }, + { + Name: "level_mix", Kind: format.PropertyChoice, + Choices: levelMixIDs, Default: "realistic", + Detail: "Which severities appear. Only the plain and json-lines shapes carry one, and asking for it beside another shape is refused.", + }, { Name: "ip_version", Kind: format.PropertyChoice, Choices: []string{"v4", "v6", "mixed"}, Default: "v4", @@ -169,6 +174,9 @@ func (generator) Plan(r format.Request) (format.Plan, error) { if opt.shape.web || opt.shape.id == "json-lines" { p.Properties["status_mix"] = opt.statusMix } + if opt.shape.levelled { + p.Properties["level_mix"] = opt.levelMix + } m := memo{seed: r.Seed, opt: opt} if r.Label { @@ -277,4 +285,36 @@ const ( var tags = []string{"sshd", "cron", "systemd", "kernel", "nginx", "dockerd"} -var levels = []string{"INFO", "INFO", "INFO", "WARN", "ERROR", "DEBUG"} +// levelSets are the severity mixes, drawn from one vocabulary on purpose. +// +// Every set here is built from DEBUG, INFO, WARN and ERROR and nothing else, +// so the longest level in any of them is five bytes. That is not tidiness: the +// shortest entry a shape can write leaves room for the longest level it might +// draw, so a set carrying a longer word would move the minimum for plain and +// JSON lines. Adding CRITICAL later is allowed, it just has to be a decision +// about the minimum rather than a word slipped into a list. +// +// Repeats are the weighting. There is no separate share for each level because +// a list with three INFOs in it says the same thing and is what the draw +// already reads. +var levelSets = map[string][]string{ + // realistic is the mix this format has always written, in the order it has + // always been in. D11 rests on that: the same seed has to draw the same + // levels it did before this setting existed, so this slice is the old + // variable moved rather than rewritten. + "realistic": {"INFO", "INFO", "INFO", "WARN", "ERROR", "DEBUG"}, + // quiet is the boring baseline - a service with nothing to report. Useful + // as the control when a reader is being tested for what it does with the + // levels rather than for whether it parses. + "quiet": {"INFO"}, + // errors is a service having a bad day, for a reader whose error handling + // is what is under test. + "errors": {"ERROR", "ERROR", "ERROR", "WARN", "WARN", "INFO"}, + // debug is a build left verbose, which is how a log gets large in the first + // place. + "debug": {"DEBUG", "DEBUG", "DEBUG", "INFO", "INFO", "WARN"}, +} + +// levelMixIDs is the closed set the registry offers, in one order so that +// every surface lists them the same way. +var levelMixIDs = []string{"realistic", "quiet", "errors", "debug"} diff --git a/internal/format/logfile/options.go b/internal/format/logfile/options.go index 2f9cd8a..a22caed 100644 --- a/internal/format/logfile/options.go +++ b/internal/format/logfile/options.go @@ -46,6 +46,9 @@ type options struct { statusMix string statuses []int + levelMix string + levels []string + ipVersion string ipv6 bool ipMixed bool @@ -63,6 +66,8 @@ func defaultOptions() options { methods: methodSets["get"], statusMix: "realistic", statuses: statusSets["realistic"], + levelMix: "realistic", + levels: levelSets["realistic"], ipVersion: "v4", } return o @@ -94,7 +99,7 @@ func parseOptions(props map[string]string) (options, error) { o := defaultOptions() for _, read := range []func(map[string]string, *options) error{ readShape, readLineEnding, readTimestamps, readRate, - readMethods, readStatusMix, readIPVersion, + readMethods, readStatusMix, readLevelMix, readIPVersion, } { if err := read(props, &o); err != nil { return options{}, err @@ -205,6 +210,34 @@ func readStatusMix(props map[string]string, o *options) error { return nil } +// readLevelMix reads the severity mix, which only two shapes carry. +// +// Unlike status_mix, the set chosen here can move the MINIMUM: the shortest +// entry a shape can write has to leave room for the longest level it might +// draw, and quiet draws only INFO. That is why the set is settled here and +// read back out of options by longestLevel, rather than either of them +// reaching for the vocabulary directly. +func readLevelMix(props map[string]string, o *options) error { + v, ok := value(props, "level_mix") + if !ok { + return nil + } + set, known := levelSets[v] + if !known { + return badValue("level_mix", v, "it has to be realistic, quiet, errors or debug") + } + // Only a real choice can disagree with the shape - see asked. A window + // sends this key on every run, so refusing whenever it arrived would put + // the four shapes without a level out of reach from the window entirely, + // which is the defect reported from a screenshot on 2026-08-31. + if _, chosen := asked(props, "level_mix", "realistic"); chosen && !o.shape.levelled { + return conflict("level_mix and entry_format", v, + "the "+o.shape.id+" shape carries no severity") + } + o.levelMix, o.levels = v, set + return nil +} + func readIPVersion(props map[string]string, o *options) error { v, ok := value(props, "ip_version") if !ok { diff --git a/internal/format/logfile/shapes.go b/internal/format/logfile/shapes.go index dbd07d8..0ebae3b 100644 --- a/internal/format/logfile/shapes.go +++ b/internal/format/logfile/shapes.go @@ -38,6 +38,11 @@ type shape struct { // if the method, status and address settings mean anything for it. A // setting that would do nothing is refused rather than ignored. web bool + // levelled says whether this shape carries a severity, which decides the + // same thing for level_mix. Separate from web rather than derived from it, + // because the two do not line up: no web shape carries a level, and of the + // three that are not web, only two do. + levelled bool // appendTo writes one entry. want below zero means whatever length it // comes out. Any other value is the exact length the line must have, its // terminator included, and the stretchable field reaches it. @@ -65,8 +70,8 @@ var shapes = map[string]*shape{ "apache-combined": {id: "apache-combined", web: true, appendTo: appendApacheCombined, shortest: shortestApacheCombined, label: hashLabel}, "nginx": {id: "nginx", web: true, appendTo: appendNginx, shortest: shortestNginx, label: hashLabel}, "syslog": {id: "syslog", web: false, appendTo: appendSyslog, shortest: shortestSyslog, label: hashLabel}, - "plain": {id: "plain", web: false, appendTo: appendPlain, shortest: shortestPlain, label: hashLabel}, - "json-lines": {id: "json-lines", web: false, appendTo: appendJSONLine, shortest: shortestJSONLine, label: jsonLabel}, + "plain": {id: "plain", web: false, levelled: true, appendTo: appendPlain, shortest: shortestPlain, label: hashLabel}, + "json-lines": {id: "json-lines", web: false, levelled: true, appendTo: appendJSONLine, shortest: shortestJSONLine, label: jsonLabel}, } // shapeIDs is the closed set the registry offers, in one order so that every @@ -253,7 +258,7 @@ func pidWidth(pid int) int { // most home grown loggers write and the one with the least agreement about it, // so this is the plainest reading of it. func appendPlain(dst []byte, st *state, want int64) []byte { - level := pick(st.rng, levels) + level := pick(st.rng, st.opt.levels) at := st.clock.tick() base := int64(len(isoTime)+1+len(level)+1) + int64(len(st.opt.eol)) @@ -266,7 +271,7 @@ func appendPlain(dst []byte, st *state, want int64) []byte { } func shortestPlain(o options) int64 { - return int64(len(isoTime)+1+longestLevel()+1) + int64(len(o.eol)) + 1 + return int64(len(isoTime)+1+longestLevel(o)+1) + int64(len(o.eol)) + 1 } // JSON lines: one object a line, which is what makes it the one shape here @@ -277,7 +282,7 @@ func shortestPlain(o options) int64 { // nothing in it ever needs escaping - which matters, because an escape would // make the line longer than the arithmetic said. func appendJSONLine(dst []byte, st *state, want int64) []byte { - level := pick(st.rng, levels) + level := pick(st.rng, st.opt.levels) status := pick(st.rng, st.opt.statuses) at := st.clock.tick() @@ -302,7 +307,7 @@ func appendJSONLine(dst []byte, st *state, want int64) []byte { func shortestJSONLine(o options) int64 { return int64(len(`{"time":"","level":"","status":,"msg":""}`)+ - len(isoTime)+longestLevel()+statusWidth) + int64(len(o.eol)) + 1 + len(isoTime)+longestLevel(o)+statusWidth) + int64(len(o.eol)) + 1 } // appendMessage writes the sentence the message shapes end with, stretched to diff --git a/internal/guard/logshapes_test.go b/internal/guard/logshapes_test.go index 5559f19..10ca4b6 100644 --- a/internal/guard/logshapes_test.go +++ b/internal/guard/logshapes_test.go @@ -4,6 +4,7 @@ import ( "bytes" "context" "encoding/json" + "errors" "fmt" "regexp" "strings" @@ -287,6 +288,8 @@ func TestALogRefusesASettingThatWouldChangeNothing(t *testing.T) { {map[string]string{"entry_format": "syslog", "ip_version": "v6"}}, {map[string]string{"entry_format": "plain", "status_mix": "success"}}, {map[string]string{"timestamps": "fixed", "rate": "5"}}, + {map[string]string{"entry_format": "nginx", "level_mix": "quiet"}}, + {map[string]string{"entry_format": "syslog", "level_mix": "errors"}}, } for _, c := range cases { t.Run(fmt.Sprint(c.props), func(t *testing.T) { @@ -339,3 +342,167 @@ func TestTheLogLabelIsALineItsOwnReaderAccepts(t *testing.T) { t.Errorf("the syslog label is not a hash comment, so the one line that is not an entry does not say so") } } + +// The severity mix is the set that gets drawn, and it moves the minimum. +// +// Two things could be wrong here and they fail differently. +// +// The first is the setting doing nothing: level_mix is read, stored, and then +// the draw reaches for the whole vocabulary anyway. Nothing else would see it - +// the size stays exact, every line still parses, and the manifest still says +// which mix was asked for. So this asks the FILE which severities are in it. +// +// The second is subtler and is why this guard exists at all. The shortest entry +// a shape can write has to leave room for the LONGEST severity it might draw, +// because the closing entry is built to an exact length and the unluckiest draw +// has to fit. quiet draws only INFO, four bytes, where realistic can draw ERROR +// or DEBUG at five. If the arithmetic reads the whole vocabulary instead of the +// set in force, the minimum is one byte too high for quiet - a floor the format +// can actually beat, announced as if it could not. That is checked by asking +// for the announced minimum and for one byte below it, rather than by repeating +// the arithmetic here, which would only prove the guard agrees with itself. +func TestTheLogSeverityMixIsDrawnAndSetsTheMinimum(t *testing.T) { + d, err := format.Get("log") + if err != nil { + t.Fatal(err) + } + + // What each declared mix is allowed to contain. Stated here on purpose: + // this guard is outside the package, so it says what the contract is rather + // than reading it back out of the thing under test. A mix added to the + // registry without a line here stops the guard instead of slipping past it. + allowed := map[string]map[string]bool{ + "realistic": {"DEBUG": true, "INFO": true, "WARN": true, "ERROR": true}, + "quiet": {"INFO": true}, + "errors": {"INFO": true, "WARN": true, "ERROR": true}, + "debug": {"DEBUG": true, "INFO": true, "WARN": true}, + } + + var mixes []string + for _, p := range d.Properties { + if p.Name == "level_mix" { + mixes = p.Choices + } + } + if len(mixes) == 0 { + t.Fatal("the log format declares no level_mix, so this guard would check nothing") + } + for _, m := range mixes { + if allowed[m] == nil { + t.Fatalf("level_mix offers %q and this guard does not say what may be in it. "+ + "Add the line rather than deleting this check - a mix nobody described is a mix nobody verified.", m) + } + } + + // Which shapes carry a severity is asked of the product, not listed here. + // A shape reports level_mix in its plan exactly when it has one. + var levelled, flat []string + for _, shape := range logShapes(t) { + p, err := d.Generator.Plan(format.Request{Bytes: 20 << 10, Seed: 7741, Label: true, + Properties: map[string]string{"entry_format": shape}}) + if err != nil { + t.Fatalf("%s would not plan at its defaults: %v", shape, err) + } + if _, ok := p.Properties["level_mix"]; ok { + levelled = append(levelled, shape) + } else { + flat = append(flat, shape) + } + } + if len(levelled) == 0 || len(flat) == 0 { + t.Fatalf("found %d shapes with a severity and %d without, so this guard is walking nothing", + len(levelled), len(flat)) + } + + severity := regexp.MustCompile(`\b(DEBUG|INFO|WARN|ERROR)\b`) + minimum := func(shape, mix string) int64 { + t.Helper() + props := map[string]string{"entry_format": shape, "level_mix": mix} + _, err := d.Generator.Plan(format.Request{Bytes: 1, Seed: 7741, Label: true, Properties: props}) + var below *format.BelowMinimumError + if !errors.As(err, &below) { + t.Fatalf("%s/%s took a one byte log, or refused it without saying what the floor is: %v", shape, mix, err) + } + return below.Minimum + } + + for _, shape := range levelled { + for _, mix := range mixes { + t.Run(shape+"/"+mix, func(t *testing.T) { + props := map[string]string{"entry_format": shape, "level_mix": mix} + + // The file, not the manifest, says which severities are in it. + body := writeLog(t, 64<<10, props) + seen := map[string]bool{} + for _, m := range severity.FindAllString(string(body), -1) { + seen[m] = true + } + if len(seen) == 0 { + t.Fatalf("no severity at all in 64 kB of %s, so nothing here is being read", shape) + } + for level := range seen { + if !allowed[mix][level] { + t.Errorf("%s is in a %s log and that mix does not offer it, "+ + "so the setting was stored and then the draw ignored it", level, mix) + } + } + + // The floor it announces is the floor it takes, and one below is + // refused. This is where a minimum read off the whole vocabulary + // rather than off this mix goes red. + n := minimum(shape, mix) + if _, err := d.Generator.Plan(format.Request{Bytes: n, Seed: 7741, Label: true, + Properties: props}); err != nil { + t.Errorf("%s/%s announces %d B as its minimum and then refuses it: %v", shape, mix, n, err) + } + if _, err := d.Generator.Plan(format.Request{Bytes: n - 1, Seed: 7741, Label: true, + Properties: props}); err == nil { + t.Errorf("%s/%s took %d B, one below the %d B it calls its minimum", shape, mix, n-1, n) + } + + // Exact to the byte at every seed, because the closing entry is + // built to a length and the severity is part of that arithmetic. + for seed := int64(1); seed <= 8; seed++ { + for _, size := range []int64{n, n + 1, 777, 4 << 10} { + if size < n { + continue + } + p, err := d.Generator.Plan(format.Request{Bytes: size, Seed: uint64(seed), + Label: true, Properties: props}) + if err != nil { + t.Fatalf("seed %d, %d B: %v", seed, size, err) + } + var buf bytes.Buffer + if err := d.Generator.Write(context.Background(), &buf, p); err != nil { + t.Fatalf("seed %d, %d B: %v", seed, size, err) + } + if int64(buf.Len()) != size { + t.Fatalf("seed %d asked for %d B and got %d", seed, size, buf.Len()) + } + } + } + }) + } + + // The mixes are not all the same thing under different names, and the + // arithmetic reads the one in force. quiet draws only INFO, which is + // shorter than the longest severity realistic can draw, so its floor + // has to be lower. Without this the whole test above would still pass + // on a build where every mix was realistic. + q, r := minimum(shape, "quiet"), minimum(shape, "realistic") + if q >= r { + t.Errorf("%s: the quiet floor is %d B and the realistic one %d B. quiet draws only INFO, "+ + "which is shorter than ERROR, so a floor that did not move was measured against "+ + "every severity this format knows rather than against the mix that was chosen.", shape, q, r) + } + } + + // And the shapes with no severity keep refusing a mix that was really + // chosen, so the guard cannot pass by accepting everything. + for _, shape := range flat { + if _, err := d.Generator.Plan(format.Request{Bytes: 4096, Seed: 7741, Label: true, + Properties: map[string]string{"entry_format": shape, "level_mix": "quiet"}}); err == nil { + t.Errorf("%s carries no severity and took level_mix anyway, so the setting does nothing there", shape) + } + } +} diff --git a/internal/guard/parity_test.go b/internal/guard/parity_test.go index 54da9d3..73e39f3 100644 --- a/internal/guard/parity_test.go +++ b/internal/guard/parity_test.go @@ -115,6 +115,7 @@ var reachableFromTheWindow = []string{ "property:jpg.width", "property:log.entry_format", "property:log.ip_version", + "property:log.level_mix", "property:log.line_ending", "property:log.methods", "property:log.rate", diff --git a/web/public/formats/index.html b/web/public/formats/index.html index 08ed11d..01013f4 100644 --- a/web/public/formats/index.html +++ b/web/public/formats/index.html @@ -430,6 +430,11 @@

Settings each format accepts

status_mix client-errors, realistic, server-errors, success + + + level_mix + debug, errors, quiet, realistic + ip_version diff --git a/web/public/pl/formaty/index.html b/web/public/pl/formaty/index.html index 5477955..ce10c68 100644 --- a/web/public/pl/formaty/index.html +++ b/web/public/pl/formaty/index.html @@ -430,6 +430,11 @@

Ustawienia, które przyjmuje każdy format

status_mix client-errors, realistic, server-errors, success + + + level_mix + debug, errors, quiet, realistic + ip_version