Skip to content

Commit fd85b67

Browse files
donislawdevclaude
andcommitted
format: a log can be six shapes, and it knows what time it is
Adds entry_format to the log format, with apache-combined staying the default, and six more settings beside it: timestamps, rate, methods, status_mix, ip_version and line_ending. The text group had no settings at all until now, so this is the first of them and the shape the rest will copy. Every template came from a real file rather than from a specification recalled, and two of them would have been wrong otherwise. A real nginx writes one more quoted field than "combined" does, because its default log_format ends with $http_x_forwarded_for. Apache's own default is common, with no referrer and no agent at all. A third thing, less obvious: a syslog FILE carries no priority in angle brackets - that belongs on the wire - and no line in the RFC 3164 style exists on this machine at all, so the ISO form is what a tester actually sees. Sources and samples are in docs/MVP-FORMATS.md section 5.1a. The clock advances now, which moves the bytes of every log and is listed under Breaking. timestamps=fixed reproduces the old file to the byte, and there is a pinned hash for it rather than a promise - the value log_8kib carried before this change is now log_8kib_the_way_back. A setting that could do nothing for the chosen shape is refused, naming both halves, rather than accepted and ignored. What "asked for" means took a correction, below. The structural checker is handed a format id and a path and never a recipe, so it takes the shape from the first entry and holds every other line to that one. Asking each line only to be valid on its own would pass a file that changed shape half way down. Five deliberate breakages, five caught: a truncated line, two shapes in one file, mixed endings, a missing final newline and an octet above 255. JSON lines is checked by Python's own json module, which gives this format its first reader that is not a regular expression of ours. Three defects found after the code was written, each worth its own note: A window could not produce syslog or JSON lines AT ALL. A menu cannot be empty - it opens on its declared default - so a window sends every setting it draws, and the first version refused a setting that could do nothing whenever the KEY arrived. The command line never showed it, because there an unset flag is an absent key, and every test written before the report had the command line's shape. A value equal to the default is not something anybody asked for, and it cannot disagree with the shape. The folded summary line listed the format's whole declaration rather than what somebody chose, for the same reason. Nobody noticed while formats declared one or two settings. With seven the line ran off the edge of the window. Boxes people type into are left as they were: there an empty box and a typed default really do differ. syslog missed its size in about one file in ten. The line counted its process id as four digits always, and it runs from 100 to 9998. Only the last entry is built to a length, so the miss needed that entry to draw a short pid. Measured before the repair: 35 files out of 360, and this project's own size guard could not see it because it asks each format with its settings left alone. Nine mutations, all caught, including one for each of those three. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
1 parent b0cd084 commit fd85b67

20 files changed

Lines changed: 1647 additions & 179 deletions

File tree

‎.gitignore‎

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -56,6 +56,12 @@ files.jsonl
5656
/dist/
5757
/build/
5858

59+
# What the tool itself writes. The window proposes this directory by default,
60+
# so running the program from a checkout fills it with generated files - and
61+
# this is a file generator, so its own repository fills up faster than any
62+
# other would.
63+
/tfg-out/
64+
5965
# ---------------------------------------------------------------------------
6066
# Test and coverage artifacts
6167
# ---------------------------------------------------------------------------

‎CHANGELOG.md‎

Lines changed: 37 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -16,6 +16,19 @@ because it turns other people's test suites red.
1616

1717
### Breaking
1818

19+
- **A generated log now advances through time, so its bytes are different.**
20+
Every entry used to carry the same instant. Ten thousand requests all landing
21+
at one moment is not a log anybody can test a time window, a rate alert or a
22+
rotation against, and it was obvious the moment you looked at a file.
23+
24+
Entries are now one second apart by default, and `rate` sets how many arrive
25+
a second. The bytes of every log change, so a suite pinning their hashes will
26+
go red.
27+
28+
**The way back is `--set timestamps=fixed`**, or `timestamps: fixed` on a
29+
target in a recipe. That holds the clock still and writes the same bytes this
30+
tool wrote before, to the byte - there is a pinned hash proving it.
31+
1932
- **A generated GIF now moves, so its bytes are different.** A GIF is the one
2033
picture format here that can hold more than one frame, and a still one told
2134
you nothing about how the system under test treats an animation - whether it
@@ -34,6 +47,30 @@ because it turns other people's test suites red.
3447

3548
### Added
3649

50+
- **A log can now be six shapes rather than one, and seven settings shape it.**
51+
`tfg generate --format log --set entry_format=nginx` writes an nginx access
52+
log. The others are `apache-combined` (the default, and what this format has
53+
always written), `apache-common`, `syslog`, `plain` and `json-lines`.
54+
55+
Every template was taken from a real file rather than from a specification
56+
remembered: a real nginx and a real Apache, and rsyslog on a real machine. Two
57+
of them would have been wrong otherwise. An nginx line carries one more
58+
quoted field than "combined" does, and Apache's own default is `common`, with
59+
no referrer and no agent at all.
60+
61+
The rest of the settings: `timestamps` and `rate` for the clock, `methods` for
62+
which verbs appear, `status_mix` for which response codes, `ip_version` to put
63+
IPv6 addresses in front of a reader that may not expect them, and
64+
`line_ending` for a log written by a Windows service.
65+
66+
**A setting that could not do anything is refused rather than ignored.**
67+
Asking for `methods` beside `entry_format=syslog` is an error naming both,
68+
because a syslog line carries no request - and a setting that silently does
69+
nothing is worse than one that is not offered.
70+
71+
Every shape still hits the size to the byte, and every line is still a whole
72+
entry. `tfg formats log` lists all of it.
73+
3774
- **JPEG XL, the twenty fourth format.** One frame, 8 bit, RGB.
3875
`tfg generate --format jxl --size 300kb` writes a JPEG XL picture in the
3976
container the format defines for it. `width`, `height` and `quality` can be

‎internal/format/logfile/address.go‎

Lines changed: 159 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,159 @@
1+
// Addresses, and the rule that keeps the way back exact.
2+
//
3+
// Every draw here is made in the same order and from the same ranges the
4+
// generator used before entry formats existed. That is not tidiness: with
5+
// timestamps=fixed and the settings left alone, the file has to come out byte
6+
// for byte as it did, and a single extra call to the generator would shift
7+
// every entry after it.
8+
//
9+
// Which is why pick does not draw when there is only one thing to choose. A
10+
// list of one is not a choice, and asking for one costs a number out of the
11+
// stream that the old code never spent.
12+
package logfile
13+
14+
import (
15+
// nosemgrep: go.lang.security.audit.crypto.math_random.math-random-used
16+
"math/rand/v2"
17+
"strconv"
18+
)
19+
20+
// pick chooses one of a list, without spending a draw on a list of one.
21+
func pick[T any](rng *rand.Rand, xs []T) T {
22+
if len(xs) == 1 {
23+
return xs[0]
24+
}
25+
return xs[rng.IntN(len(xs))]
26+
}
27+
28+
const (
29+
// v4Longest is 255.255.255.255 and v6Longest is eight groups of four hex
30+
// digits with seven colons. Both are the worst case, which is what the
31+
// minimum has to be built from.
32+
v4Longest = 15
33+
v6Longest = 39
34+
)
35+
36+
// address is one client address, drawn but not yet written.
37+
//
38+
// A value rather than a string, because a log of any size is millions of
39+
// entries and one string per entry is a multiple of the file in garbage. The
40+
// resource guard measures exactly that.
41+
type address struct {
42+
v6 bool
43+
parts [8]uint32
44+
}
45+
46+
func drawAddress(rng *rand.Rand, o options) address {
47+
v6 := o.ipv6
48+
if o.ipMixed {
49+
// One draw, so the stream stays predictable, and it is only ever
50+
// reached when the settings asked for a mixture.
51+
v6 = rng.IntN(2) == 1
52+
}
53+
var a address
54+
a.v6 = v6
55+
if !v6 {
56+
// The same ranges, in the same order, as before entry formats
57+
// existed. Nothing here may change or the way back stops being exact.
58+
a.parts[0] = uint32(10 + rng.IntN(240))
59+
a.parts[1] = uint32(rng.IntN(256))
60+
a.parts[2] = uint32(rng.IntN(256))
61+
a.parts[3] = uint32(1 + rng.IntN(254))
62+
return a
63+
}
64+
// Documentation range, so a generated log never names somebody's real
65+
// network. Groups are written the way a reader sees them, with leading
66+
// zeros suppressed, which is why the length varies.
67+
a.parts[0], a.parts[1] = 0x2001, 0x0db8
68+
for i := 2; i < 8; i++ {
69+
a.parts[i] = uint32(rng.IntN(0x10000))
70+
}
71+
return a
72+
}
73+
74+
// length is how many bytes this address takes when written.
75+
func (a address) length() int {
76+
if !a.v6 {
77+
return decDigits(a.parts[0]) + decDigits(a.parts[1]) +
78+
decDigits(a.parts[2]) + decDigits(a.parts[3]) + 3
79+
}
80+
n := 7 // the colons
81+
for _, p := range a.parts {
82+
n += hexDigits(p)
83+
}
84+
return n
85+
}
86+
87+
func (a address) append(dst []byte) []byte {
88+
if !a.v6 {
89+
// No leading zeros. Padding octets to three digits made the line
90+
// length trivial to predict and produced addresses no real log
91+
// contains - and a leading zero is read as octal by some address
92+
// parsers, where 069 is not even valid octal.
93+
for i := 0; i < 4; i++ {
94+
if i > 0 {
95+
dst = append(dst, '.')
96+
}
97+
dst = strconv.AppendInt(dst, int64(a.parts[i]), 10)
98+
}
99+
return dst
100+
}
101+
for i, p := range a.parts {
102+
if i > 0 {
103+
dst = append(dst, ':')
104+
}
105+
dst = strconv.AppendInt(dst, int64(p), 16)
106+
}
107+
return dst
108+
}
109+
110+
// decDigits is how many characters a byte sized number takes.
111+
func decDigits(n uint32) int {
112+
switch {
113+
case n < 10:
114+
return 1
115+
case n < 100:
116+
return 2
117+
default:
118+
return 3
119+
}
120+
}
121+
122+
// hexDigits is how many characters a sixteen bit group takes in hex, written
123+
// without leading zeros the way every reader shows it.
124+
func hexDigits(n uint32) int {
125+
switch {
126+
case n < 0x10:
127+
return 1
128+
case n < 0x100:
129+
return 2
130+
case n < 0x1000:
131+
return 3
132+
default:
133+
return 4
134+
}
135+
}
136+
137+
// longestAddress is the worst case for the settings in force, which is what
138+
// the minimum entry has to leave room for.
139+
func longestAddress(o options) int {
140+
if o.ipv6 || o.ipMixed {
141+
return v6Longest
142+
}
143+
return v4Longest
144+
}
145+
146+
func longestMethod(o options) int { return longest(o.methods) }
147+
func longestAgent() int { return longest(agents) }
148+
func longestTag() int { return longest(tags) }
149+
func longestLevel() int { return longest(levels) }
150+
151+
func longest(xs []string) int {
152+
n := 0
153+
for _, x := range xs {
154+
if len(x) > n {
155+
n = len(x)
156+
}
157+
}
158+
return n
159+
}

‎internal/format/logfile/clock.go‎

Lines changed: 69 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,69 @@
1+
// The clock: what time each entry says it happened.
2+
//
3+
// Until 2026-08-31 every entry in every log this tool wrote carried the same
4+
// instant, because the timestamp was a constant. That is a fidelity defect
5+
// rather than a missing setting, and docs/BACKLOG.md said so: a log where ten
6+
// thousand requests happen at one instant cannot be used to test a time window
7+
// query, a rate alert, or anything that rotates.
8+
//
9+
// It advances now, and that moves the bytes of every log, so `timestamps=fixed`
10+
// is kept as the way back and reproduces the old file exactly. Same shape as
11+
// `frames=1` for the still GIF, and there is a pinned hash for it too.
12+
package logfile
13+
14+
import "time"
15+
16+
// epoch is where every log starts. A constant, because D11 promises the same
17+
// bytes from the same seed and time.Now() would promise the opposite.
18+
//
19+
// It is the instant the fixed timestamp used to carry, so a run with
20+
// timestamps=fixed writes the bytes this tool wrote before this file existed.
21+
var epoch = time.Date(2026, time.August, 1, 12, 0, 0, 0, time.UTC)
22+
23+
const (
24+
// apacheTime is the layout the Apache family and nginx write, and
25+
// isoTime is what rsyslog and application logs write. Both are fixed
26+
// width for every instant with a four digit year, which is what lets an
27+
// entry's length be known before it is built.
28+
//
29+
// Measured on a real nginx and a real rsyslog on 2026-08-31 rather than
30+
// recalled - see docs/MVP-FORMATS.md.
31+
apacheTime = "02/Jan/2006:15:04:05 -0700"
32+
isoTime = "2006-01-02T15:04:05.000000-07:00"
33+
)
34+
35+
// clock hands out the instant for each entry in turn.
36+
//
37+
// It counts, so it is one of the builders core.Record.Discard exists for: the
38+
// filler builds one entry past the end to measure it and throws it away, and
39+
// without a way back the file would skip a tick. csv counts rows the same way.
40+
type clock struct {
41+
// step is how far the clock moves between entries. Zero holds it still,
42+
// which is what timestamps=fixed asks for.
43+
step time.Duration
44+
at time.Time
45+
}
46+
47+
func newClock(o options) clock {
48+
c := clock{at: epoch}
49+
if o.advancing {
50+
// Entries per second into a gap between entries. Integer division
51+
// rounds towards zero, so a rate above one second per entry still
52+
// moves - a step of nought would silently reproduce fixed.
53+
c.step = time.Second / time.Duration(o.rate)
54+
if c.step <= 0 {
55+
c.step = time.Nanosecond
56+
}
57+
}
58+
return c
59+
}
60+
61+
// tick returns the instant for this entry and moves on.
62+
func (c *clock) tick() time.Time {
63+
at := c.at
64+
c.at = c.at.Add(c.step)
65+
return at
66+
}
67+
68+
// back undoes one tick, for the entry that was built only to measure it.
69+
func (c *clock) back() { c.at = c.at.Add(-c.step) }

0 commit comments

Comments
 (0)