From 72188171e3ae508cf9f3aaf63a45e6c8672dcd19 Mon Sep 17 00:00:00 2001 From: Torstein Tauno Svendsen Date: Mon, 7 Sep 2026 00:16:46 +0200 Subject: [PATCH] A tally store is stamped with the buckets, not the clock MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A chunk's window is now the min/max of the bucket stamps in it, so both of a tally store's clocks are the minutes its lines are about and `--from`/`--to` selects its chunks exactly. It stamped the moment of computation before, which put the two axes a bucket and a grace apart. That gap was what `logline_lag` existed to bridge, and it goes with it: the manifest key, its parse-check, the widening that consulted it, the derivation on every provisioned store, and the prose. `WIDEN_MS` is the minute of widening it always was, unchanged for every store on disk. The knob was not worth having. Set too low it selects no chunk and answers nothing, which reads exactly like a quiet minute; set wide enough for a backfill it prunes nothing and every query is a full scan. Its one reliable value was the one tally derived, and tally no longer needs it. The remaining case — an arrival-stamped store whose lines carry earlier stamps — is the ROADMAP's zone-map sidecar, which answers it exactly. ⚠ `timberfs tally | timberfs append` is stamped on arrival, as any pipe is, so a logline window over that store finds nothing. Documented where that pipeline is shown; the VM test asserts the window over a store a PROVISIONING wrote, which is the path that has to work. --- README.md | 7 -- docs/deployment.md | 20 ++--- docs/design.md | 6 +- docs/plans/tally.md | 72 +++++++----------- packaging/timberfs.1 | 51 +++++-------- src/bark.rs | 43 ----------- src/query.rs | 63 +++------------- src/tally.rs | 162 ++++++++++++++++++++++++++--------------- tests/vm/test-in-vm.sh | 40 +++++----- 9 files changed, 191 insertions(+), 273 deletions(-) diff --git a/README.md b/README.md index 3fa7ab7..142b360 100644 --- a/README.md +++ b/README.md @@ -213,9 +213,6 @@ time the log talks about: chunks are selected on the store's clock, then every entry is verified against its own logline stamp. Where a producer's two clocks diverge — Apache logs a request's start time and writes the line when the request completes — that selection leans on a widening of about a minute. -A store whose two clocks sit further apart says so: `timberfs set -logline_lag=8h` widens the selection by what that store actually needs -instead of by the guess. See [Two clocks](docs/deployment.md#two-clocks-and-when-they-diverge). ## Beyond the getting-started path @@ -660,10 +657,6 @@ my-gc-extractor | timberfs tally --fold --width 60s | timberfs append --into ... `man timberfs`, **tally**, is the reference; the schema is `docs/tally-extractor.schema.json`. -⚠ Declare `logline_lag` on the tally store. Its lines are numbers about a minute -that closed some minutes ago, so its two clocks sit far apart, and a -logline-time window over it otherwise selects no chunk and answers nothing. - ## Replicating to another timberfs (`frames-send`) OTLP above ships **entries** to anything that speaks the protocol. When the far diff --git a/docs/deployment.md b/docs/deployment.md index c4f571a..e06adb7 100644 --- a/docs/deployment.md +++ b/docs/deployment.md @@ -1277,8 +1277,8 @@ tally store, because outliving the log is the entire point. A `DECLARE` that has drifted from what is on disk is reported, never rewritten over an operator's `timberfs set`. -⚠ `logline_lag` is derived, not typed, and `class!=tally` is folded into the -selection so a provisioning cannot end up measuring its own output. +⚠ `class!=tally` is folded into the selection, so a provisioning cannot end up +measuring its own output. Try one against a real file before deploying it: @@ -1300,14 +1300,20 @@ their own, one per source store: timberfs create /var/log/timberfs/apache-access-tally/apache-access-tally.log \ --index --retain 730d \ --set class=tally --set service=apache-access --set host="$(hostname -s)" \ - --set derived_op=tally --set logline_lag=1h + --set derived_op=tally timberfs query --records apache-access --from '13:00' \ | timberfs tally --extractor /usr/lib/timberfs/tally.extractors.d \ | timberfs append --into /var/log/timberfs/apache-access-tally/apache-access-tally.log ``` -Three of those declarations are load-bearing: +⚠ Shown for the mechanics; prefer `--provision` for a store you will keep. +`append` stamps arrival, as it does for any pipe, so this store's chunks carry +the moment the numbers were computed rather than the minutes they are about, +and `--from`/`--to` over it will not find them. A tally store the provisioning +writes carries the buckets, and needs nothing declared to be queried by them. + +Two of those declarations are load-bearing: - **`class=tally`** is how a reader tells the numbers from the log. It matters the other way round too: a tally store inherits the source's labels, so @@ -1315,12 +1321,6 @@ Three of those declarations are load-bearing: onward would start shipping tally lines. Narrow such a selection with `class!=tally` — an absent key reads as the empty string, so that already excludes every store on disk today. -- **`logline_lag`** is how far a line's own stamp may sit from the moment it was - written: the bucket width plus `grace` for a live tally, and however old the - data is for a backfill. Chunk selection is widened by it in place of the one-minute guess, - and without it a logline-time window over the buckets selects no chunk at all - and answers nothing — which reads exactly like a quiet minute. `timberfs info` - reports the declared value, because that failure is otherwise silent. - **`retain`** is the whole point of materialising: the tally store keeps its numbers long after the log they came from has been head-dropped. Size it in years where the log is sized in weeks. diff --git a/docs/design.md b/docs/design.md index 991b77c..d4efcb8 100644 --- a/docs/design.md +++ b/docs/design.md @@ -214,9 +214,6 @@ object — the label on the timber. Plain enough to read by eye; changed with "timestamp_regex": "^(...)", // content: exotic line-timestamp format, declared once "timestamp_format": "%m/%d/%Y %H:%M:%S", // (import flags persist these; inherits) "timestamp_utc": true, // zoneless line stamps are UTC, not local time - "logline_lag": "8h", // how far a line's stamp may sit from its - // WRITE time — widens chunk selection in - // place of the one-minute guess "name": "apache-error", // what it is CALLED, where the path is opaque "derived_from": "41d0…", // lineage: source store's id "derived_op": "export", // …and how: export (copy), rotate (move) or @@ -272,8 +269,7 @@ head-drops, travels on rename, and ships inside `.timber` bundles. **Chunk selection** is the write-time index's job and is deliberately coarse: every chunk whose write-time window overlaps the requested range -(widened by the store's `logline_lag`, or about a minute where it declares -none, to catch buffered stragglers) is read in full. +(widened by about a minute to catch buffered stragglers) is read in full. Chunk windows are bounded by `--flush-age` (default 5 s) for slow writers and by `--chunk-size` (default 256 KiB) for fast ones, so that is the slop the index alone would leave at the edges. diff --git a/docs/plans/tally.md b/docs/plans/tally.md index a4530ed..a2a3fa8 100644 --- a/docs/plans/tally.md +++ b/docs/plans/tally.md @@ -249,44 +249,26 @@ still resolve a window before answering it. Bounded by series × buckets, not by entries. A **`--follow` of a tally store delivers unresolved lines and must say so**, exactly as a live-edge entry carries no chunk number. -## A tally store has two clocks too, and they are FAR apart - -The bucket stamp is on the declared axis; the store's own chunks are stamped -when the line was appended. So `axis: "write"` asks *when was this computed* -and `axis: "logline"` asks *which minute is this about* — and a revision -written an hour late is findable on the first. - -⚠ **That gap breaks the read path, and building it is what showed how.** Chunk -selection runs on the write clock and is widened by a guess of a minute before -each entry is verified against its own stamp — which assumes the two clocks are -close. A tally store's are close only by accident: its lines are numbers about -a minute that closed `GRACE` ago, a revision's are older still, and a -backfill's are about last month. Measured on the first tally store built here: -a logline-time query for the minute the numbers describe read **0 of 1 chunks** -and answered nothing, which is indistinguishable from an empty minute. - -The fix is a declaration rather than a bigger guess: **`logline_lag` in the -`.bark`** says how far a line's own stamp may sit from the moment it was -written, and chunk selection is widened by that instead of by `WIDEN_MS`. -Declaring `logline_lag=8h` on that same store made the same query read the -chunk and answer exactly. It is general, not tally's: the roadmap's -zone-map entry describes the same failure for an arrival-stamped Apache store -whose lines carry request-START times, and today that leans on the same guess. -Widening both ways only ever costs I/O — the per-entry verification keeps the -output exact — and the per-chunk logline range the zone-map sidecar would add -makes the declaration unnecessary rather than wrong. - -A tally writer knows its own lag exactly (`grace`, plus the width of the bucket -being closed), so it should declare it on the store it creates. - -⚠ **A BACKFILL's lag is unbounded** — its lines are about whenever the source -data is from — so a store that has been backfilled must declare a lag wide -enough to cover it, and a wide lag means chunk selection prunes nothing and -every logline-time query becomes a full scan of the tape. That is the honest -cost of a declaration standing in for an index, and it is the argument for the -zone-map sidecar: a per-chunk logline range answers the same question exactly, -and would make the declaration unnecessary rather than merely generous. -`info` reports the declared lag, because its failure mode is silent. +## A tally store's chunks are stamped with the buckets + +A chunk's window is the min/max of the bucket stamps in it, not the moment the +lines were folded. So both of a tally store's clocks are the minutes its lines +are about, and `--from`/`--to` selects its chunks exactly — a backfill of last +month lands in chunks stamped last month, where selection prunes. + +⚠ The alternative was measured and is why this is written down: stamping the +moment of computation put the two axes a bucket and a grace apart, and a query +for the minute the numbers describe read **0 of 1 chunks** and answered +nothing — indistinguishable from an empty minute. A backfill made it +unbounded. + +The same rule the receive intakes follow: they stamp the sender's event time, +so a received store has no arrival axis of its own either. + +⚠ **A tally piped through `append` is stamped on arrival**, as any pipe is, so +a logline-time window over such a store finds nothing. That is `append`'s +meaning and not tally's — a store you will query by the minutes it describes +is written by a provisioning. ⚠ **`AXIS=write` buckets at CHUNK granularity**, because the only arrival stamp an entry carries is its chunk's write window. On a busy log a chunk is a second @@ -488,10 +470,6 @@ Five rules fall out: permissive than "one tally follower per store" and exactly as safe — and it is checkable at load, where overlapping input selections are not decidable in general. -* ⚠ **`logline_lag` is DERIVED, not typed.** It is the `width + grace` of the - applied extractors, and the provisioning knows both. Making an operator write - it invites precisely the failure this note records twice. `DECLARE` may - override it, which is what a backfill needs. * **Provisioning CONVERGES and does not cascade.** A source store appearing gets its tally store on the next tick (`--check` to declare and say what resolved, as `file-intake` does). A source store being DELETED does not take @@ -1037,8 +1015,8 @@ loss, recorded exactly — the same rule retention already follows. * **The follower half**: fanning out per source store, the watermark rule (`Roller::safe_offset` is already the answer — the oldest byte any held bucket still depends on, so a restart re-derives identical lines), creating - the tally store with its labels, lineage and `logline_lag`, and writing the - `!gap` marker from the registry's GAP. + the tally store with its labels and lineage, and writing the `!gap` marker + from the registry's GAP. * **The `!gap` marker** — the registry reports a GAP when retention dropped chunks a follower had not read, and nothing writes it into the tally store yet. Until it does, a hole in the numbers and a quiet period look alike. @@ -1066,7 +1044,7 @@ loss, recorded exactly — the same rule retention already follows. ## What must change elsewhere when this ships -Done with the first slice: `timberfs.1` gains **tally** and `logline_lag`, the +Done with the first slice: `timberfs.1` gains **tally**, the completions gain the verb, and `packaging/extractors/` holds the shipped documents with their fixtures under `tests/extractors/`. @@ -1074,7 +1052,7 @@ Done with the extractor half: `timberfs.1`'s **tally** section, the README, the deployment guide, the published schema, and the shipped extractors with their fixtures. Still owed: a `timberfs-tally-extractor(5)` for the document; `use-cases.md`'s "No aggregation, no dashboards, no alerting" (two of three survive); `concepts.md` gains **tally**, -**observation**, **bucket**, **revision**, **logline lag**; `design.md` gains -the line format and the `logline_lag` manifest key; a `timberfs-tally(5)` and a +**observation** and **bucket**; `design.md` gains the line format; a +`timberfs-tally(5)` and a `tally.d` section in `deployment.md`; and `timberfs-query-document(5)` gains `series`, `step` and the `samples` kind. diff --git a/packaging/timberfs.1 b/packaging/timberfs.1 index b95ceff..82a9788 100644 --- a/packaging/timberfs.1 +++ b/packaging/timberfs.1 @@ -293,10 +293,9 @@ neither. Known settings are parse-checked .RI ( "an absolute directory, SUPERSEDED by the follower registry \(em see" .BR FOLLOWERS )); .BR timestamp_regex , -.BR timestamp_format , -.B timestamp_utc +.B timestamp_format and -.B logline_lag +.B timestamp_utc are parse-checked too (see THE TWO CLOCKS); anything else is free-form provenance .RB ( host =...), @@ -1610,16 +1609,12 @@ somebody ran .B timberfs set and meant it. .PP -.B logline_lag -is DERIVED from the applied extractors (their width plus their grace) and -declared on every tally store, because a logline window narrower than the -distance between its two clocks selects no chunk and answers nothing. -So is -.BR wal=true , -because losing a minute's numbers silently is worse than the fsync it -costs on a store that takes a handful of lines a minute. Naming either in +.B wal=true +is declared on every tally store, because losing a minute's numbers +silently is worse than the fsync it costs on a store that takes a handful +of lines a minute. Naming it in .B DECLARE -overrides it, which is what a backfill needs. +overrides that. .PP .B FOLLOW_FROM is @@ -1689,12 +1684,13 @@ the that would have been needed to keep the worst of them \(em which is the number to act on. .PP -⚠ A tally store's two clocks sit far apart BY CONSTRUCTION \(em its -lines are numbers about a minute that closed some minutes ago \(em so -declare -.B logline_lag -on it (see THE TWO CLOCKS) or a logline-time window will select no chunk -and answer nothing. +⚠ A tally store's chunks are stamped with the BUCKETS, so both its clocks +are the minutes its lines are about and +.BR \-\-from / \-\-to +selects them exactly. A tally piped through +.B append +instead is stamped on arrival, as any pipe is, and a logline-time window +over that store finds nothing. .SS list .TP .BI \-\-select " EXPR" @@ -3692,19 +3688,12 @@ Do not backfill historical data through .B append (its index gets today's write times): import the file instead. .PP -The minute of widening is a GUESS, and a store that knows better says so: -.B logline_lag -declares how far a line's own stamp may sit from the moment it was -written, and chunk selection is widened by that instead. It exists -because the guess has a class of store it cannot cover \(em one whose -producer stamps a line long before writing it. A TALLY store is the -clearest case: its lines are numbers about a minute that closed some -minutes earlier (its width, plus the sealing grace), and a backfilled -one's are about last month. Without the -declaration a logline-time window over such a store selects no chunk at -all and answers nothing, which reads exactly like an empty minute. -Widening both ways only ever costs I/O \(em the per-entry verification -keeps the output exactly inside the window asked for. +The minute of widening is a GUESS, and it only ever costs I/O \(em the +per-entry verification keeps the output exactly inside the window asked +for. It covers a producer that writes a line slightly after the stamp it +carries; a store whose two clocks sit further apart than that is written +by an intake that stamps the line's own time, so its axes coincide and +there is nothing to bridge. .SH TIME FORMATS .I TIME arguments accept RFC 3339 diff --git a/src/bark.rs b/src/bark.rs index 2c9b50c..3933823 100644 --- a/src/bark.rs +++ b/src/bark.rs @@ -291,7 +291,6 @@ pub const NOT_PROVENANCE: &[&str] = &[ "timestamp_regex", "timestamp_format", "timestamp_utc", - "logline_lag", "command", "pattern", // Which tape this pair holds — an ADDRESS, not provenance, and the @@ -345,22 +344,6 @@ pub fn origin_id(map: &Map) -> Option { /// exactly as declared — flattening a dotted key like `service.name` is a /// consumer's concern (Loki requires it, timberfs does not), and doing it /// here would lose the key the operator actually wrote. -/// How far a line's own stamp may sit from the moment it was written, -/// as the store declares it. -/// -/// Chunk selection is on the WRITE clock and a logline window is -/// verified per entry, so the two are bridged by widening the selection -/// — a guess of a minute where nothing says otherwise. A store whose -/// producer stamps a line long before it writes it can say so instead, -/// and the commonest such store is a TALLY: its lines are numbers about -/// a minute that closed some minutes earlier, and a backfill's are about -/// last month. Widening both ways only ever costs I/O; the per-entry -/// verification keeps the answer exact. -pub fn logline_lag_ms(map: Option<&Map>) -> Option { - let v = map?.get("logline_lag")?.as_str()?; - crate::append::parse_duration_ms(v).ok() -} - pub fn provenance(map: &Map) -> Map { map.iter() .filter(|(k, _)| !NOT_PROVENANCE.contains(&k.as_str())) @@ -388,7 +371,6 @@ const NON_INHERITED: &[&str] = &[ "retain", "retain_size", "retain_unconsumed", - "logline_lag", ]; /// Window bounds are operation facts, recorded as RFC3339 UTC. @@ -902,10 +884,6 @@ pub fn declare( crate::append::parse_size_bytes(&v)?; Value::String(v) } - "logline_lag" => { - crate::append::parse_duration_ms(&v)?; - Value::String(v) - } _ if BOOLEAN_KEYS.contains(&k) => declared_value(k, &v)?, "timestamp_regex" => { let re = regex::Regex::new(&v) @@ -964,26 +942,6 @@ mod tests { .collect() } - #[test] - fn a_declared_logline_lag_is_read_and_a_bad_one_is_not_guessed_at() { - // Absent and unreadable must reach the caller the same way — as - // "nothing declared" — so the guess stands rather than a widening - // of zero, which would silently answer a window with nothing. - assert_eq!( - logline_lag_ms(Some(&map(&[("logline_lag", Value::String("8h".into()))]))), - Some(8 * 3_600_000) - ); - assert_eq!(logline_lag_ms(Some(&map(&[]))), None); - assert_eq!( - logline_lag_ms(Some(&map(&[("logline_lag", Value::String("soon".into()))]))), - None - ); - assert_eq!( - logline_lag_ms(Some(&map(&[("logline_lag", Value::Bool(true))]))), - None - ); - } - #[test] fn provenance_is_where_the_entries_came_from_not_what_the_store_is() { let m = map(&[ @@ -998,7 +956,6 @@ mod tests { ("retain_unconsumed", Value::Bool(true)), ("cursors", Value::String("/var/lib/timberfs".into())), ("timestamp_utc", Value::Bool(true)), - ("logline_lag", Value::String("1h".into())), ("wal", Value::Bool(true)), // One hop's bookkeeping, not provenance: under fan-in these // name only ONE of the origins. diff --git a/src/query.rs b/src/query.rs index efbdae4..1d7fee7 100644 --- a/src/query.rs +++ b/src/query.rs @@ -445,26 +445,15 @@ pub fn select_chunks( /// can verify entries exactly: catches lines written slightly before or /// after the stamps they carry (buffered producers), while the filter /// keeps the OUTPUT exactly inside the asked window. -/// -/// The DEFAULT, and a guess. A store that knows the distance declares -/// `logline_lag` and this is not consulted — see -/// `bark::logline_lag_ms`. pub(crate) const WIDEN_MS: u64 = 60_000; -/// The window CHUNK selection runs on: what was asked, widened by the -/// distance this store's two clocks may sit apart. -/// -/// `WIDEN_MS` is the guess for a store that says nothing. One that -/// declares `logline_lag` is taken at its word — a tally store's lines -/// are numbers about a minute that closed some minutes earlier, and a -/// backfilled one's are about last month, which no guess can cover. -pub(crate) fn widened( - from_ms: u64, - to_ms: u64, - bark: Option<&serde_json::Map>, -) -> (u64, u64) { - let widen = crate::bark::logline_lag_ms(bark).unwrap_or(WIDEN_MS); - (from_ms.saturating_sub(widen), to_ms.saturating_add(widen)) +/// The window CHUNK selection runs on: what was asked, widened so a line +/// written a little before or after the stamp it carries is still read. +pub(crate) fn widened(from_ms: u64, to_ms: u64) -> (u64, u64) { + ( + from_ms.saturating_sub(WIDEN_MS), + to_ms.saturating_add(WIDEN_MS), + ) } /// A whole search, as one value. @@ -1113,7 +1102,7 @@ fn query_entries( crate::import::Extractor::new(tf.regex.as_deref(), tf.format.as_deref(), tf.utc)?; // Widened selection, then a probe: can this store's lines be // parsed at all? If not, no filter — and no widening either. - let (widened_from, widened_to) = widened(from_ms, to_ms, source.bark.as_ref()); + let (widened_from, widened_to) = widened(from_ms, to_ms); let (selected, _) = select_chunks( f, &source.records, @@ -3026,18 +3015,11 @@ pub fn cmd_info(input: &Path, json: bool) -> anyhow::Result<()> { } else if let Some(pt) = &pattern { println!(" pattern {pt}"); } - // The declared lag is reported because its failure is SILENT: a - // window narrower than the distance between the two clocks selects - // no chunk, and reads exactly like a quiet minute. - let lag = bark.get("logline_lag").and_then(|v| v.as_str()); - if !provenance.is_empty() || index_declared || lag.is_some() { + if !provenance.is_empty() || index_declared { let mut parts: Vec = provenance.iter().map(|(k, v)| format!("{k}={v}")).collect(); if index_declared { parts.push("index declared".to_string()); } - if let Some(lag) = lag { - parts.push(format!("logline lag {lag}")); - } println!(" manifest {}", parts.join(", ")); } if chunks == 0 { @@ -3549,33 +3531,6 @@ mod numbering_tests { mod tests { use super::*; - #[test] - fn a_store_may_declare_how_far_its_two_clocks_sit_apart() { - // Chunk selection runs on the WRITE clock and a logline window is - // verified per entry, so a store whose lines are stamped long - // before they are written is pruned by the guess that bridges - // them. A TALLY store is exactly that store — its lines are - // numbers about a minute that closed some minutes ago, and a - // backfill's are about last month — so it says the distance - // rather than being guessed at. - let hour = 3_600_000u64; - let (from, to) = (10 * hour, 11 * hour); - - let (a, b) = widened(from, to, None); - assert_eq!((a, b), (from - WIDEN_MS, to + WIDEN_MS), "the guess stands"); - - let mut bark = serde_json::Map::new(); - bark.insert("logline_lag".to_string(), serde_json::json!("8h")); - let (a, b) = widened(from, to, Some(&bark)); - assert_eq!((a, b), (from - 8 * hour, to + 8 * hour)); - - // A value that does not parse is not a licence to read nothing: - // fall back to the guess rather than to zero widening. - bark.insert("logline_lag".to_string(), serde_json::json!("later")); - let (a, b) = widened(from, to, Some(&bark)); - assert_eq!((a, b), (from - WIDEN_MS, to + WIDEN_MS)); - } - #[test] fn an_omitted_field_means_unbounded_not_empty() { // The semantics a `--query` document inherits: a member left out diff --git a/src/tally.rs b/src/tally.rs index d70935c..73905dd 100644 --- a/src/tally.rs +++ b/src/tally.rs @@ -1369,9 +1369,9 @@ pub fn fold_stream( ); } roller.add(&s); - emit(out, roller.drain(false))?; + let _ = emit(out, roller.drain(false))?; } - emit(out, roller.drain(true))?; + let _ = emit(out, roller.drain(true))?; Ok(()) } @@ -1605,8 +1605,9 @@ impl Run { axis: Axis, out: &mut impl Write, observations: bool, - ) -> anyhow::Result<()> { + ) -> anyhow::Result> { let mut batch: Vec = Vec::new(); + let mut meta: Option<(u64, u64)> = None; for l in self.live.iter_mut() { let ts = match axis { Axis::Logline => e.ts, @@ -1637,6 +1638,7 @@ impl Run { if !l.announced { l.announced = true; if let Some(u) = &l.unit { + meta = span(meta, Some((ts, ts))); writeln!( out, "{}", @@ -1660,12 +1662,12 @@ impl Run { batch.extend(l.roller.drain(false)); } } - emit(out, batch) + Ok(span(meta, emit(out, batch)?)) } /// Let wall clock stand in for event time on a quiet stream, and /// write whatever that seals. - fn idle(&mut self, by_ms: u64, out: &mut impl Write) -> anyhow::Result<()> { + fn idle(&mut self, by_ms: u64, out: &mut impl Write) -> anyhow::Result> { let mut batch: Vec = Vec::new(); for l in self.live.iter_mut() { if l.roller.watermark() == 0 { @@ -1679,9 +1681,13 @@ impl Run { emit(out, batch) } - fn finish(&mut self, out: &mut impl Write, observations: bool) -> anyhow::Result<()> { + fn finish( + &mut self, + out: &mut impl Write, + observations: bool, + ) -> anyhow::Result> { if observations { - return Ok(()); + return Ok(None); } let mut batch: Vec = Vec::new(); for l in self.live.iter_mut() { @@ -1758,7 +1764,9 @@ pub fn cmd_tally(opts: &TallyOpts) -> anyhow::Result<()> { let mut ended = false; while let Some(rec) = reader.next_rec()? { match rec { - crate::records::Rec::Entry(e) => run.feed(&e, axis, &mut out, opts.observations)?, + crate::records::Rec::Entry(e) => { + run.feed(&e, axis, &mut out, opts.observations)?; + } crate::records::Rec::End(_) => ended = true, _ => {} } @@ -1868,12 +1876,27 @@ fn entries_of_text(text: &[u8]) -> anyhow::Result> } /// One batch of sealed buckets, in time order. -fn emit(out: &mut impl Write, mut batch: Vec) -> anyhow::Result<()> { +/// +/// Reports the BUCKET WINDOW it wrote, which is what stamps the chunk: +/// a tally store's write axis is the minutes its lines are about. +fn emit(out: &mut impl Write, mut batch: Vec) -> anyhow::Result> { batch.sort_by(|a, b| (a.ts, &a.metric, &a.labels).cmp(&(b.ts, &b.metric, &b.labels))); + let window = match (batch.first(), batch.last()) { + (Some(f), Some(l)) => Some((f.ts, l.ts)), + _ => None, + }; for s in batch { writeln!(out, "{}", s.render())?; } - Ok(()) + Ok(window) +} + +/// Two windows as one, either of which may be absent. +fn span(a: Option<(u64, u64)>, b: Option<(u64, u64)>) -> Option<(u64, u64)> { + match (a, b) { + (Some((af, al)), Some((bf, bl))) => Some((af.min(bf), al.max(bl))), + (some, None) | (None, some) => some, + } } /// ⚠ Stamped with the ENTRY's own time where there is one. Charging it @@ -2228,13 +2251,9 @@ pub struct Planned { /// writers. Overlapping selections are not decidable in general, and two /// names being equal is. pub fn plan(p: &Provision, etc: &Path, dirs: &[PathBuf]) -> anyhow::Result> { - let extractors = p.extractors(etc)?; - let lag_ms = extractors - .iter() - .map(|e| p.width_ms.unwrap_or(e.window.width_ms) + e.window.grace_ms) - .max() - .unwrap_or(0); - + // Resolved for its refusals: a provisioning naming an extractor this + // host does not have is a plan that cannot run. + let _ = p.extractors(etc)?; let sel = crate::select::Selector::parse(&p.selector()?)?; let mut out: Vec = Vec::new(); let mut claimed: BTreeMap = BTreeMap::new(); @@ -2263,11 +2282,6 @@ pub fn plan(p: &Provision, etc: &Path, dirs: &[PathBuf]) -> anyhow::Result anyhow::Result<()> { + fn write(&mut self, lines: &[u8], window: Option<(u64, u64)>) -> anyhow::Result<()> { if lines.is_empty() { return Ok(()); } + let Some((first_ms, last_ms)) = window else { + bail!("tally lines carrying no bucket window — every rendered line has a stamp"); + }; let cfg = self.store.cfg; let f = self .store .files .get_mut(&self.name) .expect("the store was created with this name"); - // Stamped NOW, which is what makes a tally store's write axis - // "when this was computed" and its logline axis "which minute - // this is about". - f.append_stamped(lines, now_ms, &cfg)?; + // ⚠ Stamped with the BUCKETS, not the clock: a tally store's two + // axes are the same minutes, so a logline-time query selects + // chunks exactly. Stamping the moment of computation instead put + // the axes GRACE apart and made every such query miss its own + // chunks. Both receive intakes stamp the sender's event time for + // the same reason. + f.append_windowed(lines, first_ms, last_ms, &cfg)?; // ⚠ Flushed here rather than left to an age timer this loop does // not run: a tally batch is one bucket sealing, arriving a // minute apart, so nothing would become a chunk — and a minute's @@ -2595,15 +2615,16 @@ pub fn cmd_run(set: &str, opts: &RunOpts) -> anyhow::Result<()> { Err(std::sync::mpsc::RecvTimeoutError::Disconnected) => break, Err(std::sync::mpsc::RecvTimeoutError::Timeout) => { quiet += 1; - let now = crate::store::now_ms(); for (id, sink) in sinks.iter_mut() { let mut lines: Vec = Vec::new(); - if quiet == QUIET_TICKS { - sink.run.finish(&mut lines, false)?; + let window = if quiet == QUIET_TICKS { + sink.run.finish(&mut lines, false)? } else if quiet < QUIET_TICKS { - sink.run.idle(IDLE_TICK.as_millis() as u64, &mut lines)?; - } - sink.write(&lines, now)?; + sink.run.idle(IDLE_TICK.as_millis() as u64, &mut lines)? + } else { + None + }; + sink.write(&lines, window)?; report(&mut reports, id, sink)?; } continue; @@ -2647,9 +2668,8 @@ pub fn cmd_run(set: &str, opts: &RunOpts) -> anyhow::Result<()> { } let sink = sinks.get_mut(&id).expect("just inserted"); let mut lines: Vec = Vec::new(); - sink.run.feed(&e, axis, &mut lines, false)?; - let now = crate::store::now_ms(); - sink.write(&lines, now)?; + let window = sink.run.feed(&e, axis, &mut lines, false)?; + sink.write(&lines, window)?; if let Some(off) = e.offset { sink.delivered_to = Some(off + e.payload.len() as u64); } @@ -2664,9 +2684,8 @@ pub fn cmd_run(set: &str, opts: &RunOpts) -> anyhow::Result<()> { // no half-counted minute behind. for (id, sink) in sinks.iter_mut() { let mut lines: Vec = Vec::new(); - sink.run.finish(&mut lines, false)?; - let now = crate::store::now_ms(); - sink.write(&lines, now)?; + let window = sink.run.finish(&mut lines, false)?; + sink.write(&lines, window)?; let cfg = sink.store.cfg; if let Some(f) = sink.store.files.get_mut(&sink.name) { f.flush_chunk(&cfg)?; @@ -2725,7 +2744,7 @@ fn open_sink( // A store that appeared since the provisioning last ran is the // case this exists for: an intake mints stores on first sight, // and a metric that waited for a human would miss the day. - let declare = declared_for(p, docs, id, labels); + let declare = declared_for(p, id, labels); crate::bark::cmd_create(&dest, false, false, None, None, false, &declare, true)?; } @@ -2757,17 +2776,7 @@ fn open_sink( /// The bark a tally store declares: its source's provenance, the facts /// only a provisioning knows, then whatever it declares itself. -fn declared_for( - p: &Provision, - docs: &[(PathBuf, Extractor)], - id: &str, - labels: &Map, -) -> Vec { - let lag_ms = docs - .iter() - .map(|(_, e)| p.width_ms.unwrap_or(e.window.width_ms) + e.window.grace_ms) - .max() - .unwrap_or(0); +fn declared_for(p: &Provision, id: &str, labels: &Map) -> Vec { let mut declare: Vec = crate::bark::provenance(labels) .iter() .filter_map(|(k, v)| v.as_str().map(|v| format!("{k}={v}"))) @@ -2775,7 +2784,6 @@ fn declared_for( declare.push("class=tally".to_string()); declare.push("derived_op=tally".to_string()); declare.push(format!("derived_from={id}")); - declare.push(format!("logline_lag={}s", lag_ms.div_ceil(1000))); // ⚠ A tally store is worth a WAL where a log may not be: recomputing // a lost minute means re-reading the source from a reset position, // and losing one silently is worse than the second of fsync it costs @@ -3555,12 +3563,10 @@ mod tests { #[test] fn a_tally_store_declares_what_only_the_provisioning_knows() { let p = provision("SELECT=[]\nAPPLY=x\nDECLARE=retain=30d wal=false\n").unwrap(); - let doc = parsed(r#"{"name":"m","measure":[{"count":true}]}"#).unwrap(); - let docs = vec![(PathBuf::from("t"), doc)]; let mut labels = Map::new(); labels.insert("service".into(), serde_json::json!("apache-access")); labels.insert("index".into(), serde_json::json!(true)); - let got = declared_for(&p, &docs, "src-id", &labels); + let got = declared_for(&p, "src-id", &labels); assert!(got.contains(&"class=tally".to_string())); assert!(got.contains(&"derived_from=src-id".to_string())); @@ -3571,9 +3577,6 @@ mod tests { // A SETTING is not provenance and must not be inherited: the // source's index choice is not the tally store's. assert!(!got.iter().any(|k| k == "index=true"), "{got:?}"); - // ⚠ DERIVED — width 60s + grace 120s. Typed, it would be wrong - // the first time somebody changed a window. - assert!(got.contains(&"logline_lag=180s".to_string()), "{got:?}"); // …and DECLARE has the last word, even over a default this // thinks is a good idea. assert!(got.contains(&"retain=30d".to_string())); @@ -3581,6 +3584,49 @@ mod tests { assert!(!got.iter().any(|k| k == "wal=true"), "{got:?}"); } + #[test] + fn what_is_written_reports_the_minutes_it_is_about() { + // The window this returns is what stamps the chunk, so a tally + // store's write axis is the minutes its lines describe and a + // logline-time query selects its chunks exactly. Stamping the + // moment of computation instead put the two axes a bucket and a + // grace apart, and a query for the minute the numbers describe + // then read no chunk at all — which reads like a quiet minute. + let docs = vec![( + PathBuf::from("t"), + parsed(r#"{"name":"m","measure":[{"count":true,"unit":"x"}]}"#).unwrap(), + )]; + let opts = TallyOpts::for_run(None); + let mut run = Run::new(&docs, &opts).unwrap(); + let mut out: Vec = Vec::new(); + + // Nothing has sealed, but the `!meta` line went out and carries a + // stamp — so the window must cover it or the chunk holding it is + // stamped from somewhere else entirely. + let first = entries_of_text(b"2026-09-06T13:37:10.000Z hello\n").unwrap(); + let meta = run.feed(&first[0], Axis::Logline, &mut out, false).unwrap(); + assert_eq!( + meta, + Some(( + crate::query::parse_time("2026-09-06T13:37:10Z").unwrap(), + crate::query::parse_time("2026-09-06T13:37:10Z").unwrap() + )) + ); + + // Two buckets seal at the end: the window is the first and the + // last, not the moment they were folded. + let later = entries_of_text(b"2026-09-06T13:39:10.000Z hello\n").unwrap(); + run.feed(&later[0], Axis::Logline, &mut out, false).unwrap(); + let sealed = run.finish(&mut out, false).unwrap(); + assert_eq!( + sealed, + Some(( + crate::query::parse_time("2026-09-06T13:37:00Z").unwrap(), + crate::query::parse_time("2026-09-06T13:39:00Z").unwrap() + )) + ); + } + #[test] fn wall_clock_stands_in_for_event_time_only_when_asked() { // A backfill never goes quiet before its end, so it never diff --git a/tests/vm/test-in-vm.sh b/tests/vm/test-in-vm.sh index 48aa59f..c5b41c6 100755 --- a/tests/vm/test-in-vm.sh +++ b/tests/vm/test-in-vm.sh @@ -5365,11 +5365,7 @@ tally_derives_metrics_that_are_a_store_like_any_other() { } CONF - # The distance this store's two clocks sit apart, without which a - # logline window selects no chunk at all. GRACE + REVISE for a live - # tally; for a BACKFILL like this one, however old the data is. timberfs create "$d/vmtally.log" --set class=tally --index >/dev/null 2>&1 || return 1 - timberfs set "$d/vmtally.log" logline_lag=520w >/dev/null 2>&1 || return 1 timberfs query --records "$s/vmtallysrc.log" 2>/dev/null \ | timberfs tally --extractor /etc/timberfs/tally.d/vm.json 2>/tmp/vmtally.err \ @@ -5384,17 +5380,11 @@ CONF timberfs query "$d/vmtally.log" >&2 return 1 } - # …and the bucket is findable by the minute it DESCRIBES, which is the - # half the declared lag buys. - # RFC3339 with the zone spelled out: a NAIVE stamp is parsed in the - # READER's timezone, so this would pass in a UTC VM and fail anywhere - # else — the store's stamps are UTC whatever the host is set to. - timberfs query "$d/vmtally.log" \ - --from '2026-09-06T10:02:00Z' --to '2026-09-06T10:03:00Z' 2>/dev/null \ - | grep -q 'count=1' || { - echo "a logline window over the buckets found nothing" >&2 - return 1 - } + # ⚠ No logline window is asked of THIS store. The tally went through + # `append`, which stamps arrival like any pipe does, so its chunks + # carry the moment they were appended and not the minutes they are + # about. A tally store written by a PROVISIONING carries the buckets + # — see tally_provisioning_end_to_end. rm -rf "$d" "$s" /etc/timberfs/tally.d/vm.json /tmp/vmtally.log } @@ -5438,9 +5428,7 @@ CONF return 1 } grep -q 'CREATE' /tmp/vmprov.out || { cat /tmp/vmprov.out >&2; return 1; } - # ⚠ Derived, not typed: a logline window narrower than the distance - # between a tally store's two clocks answers nothing. - jq -e '.class == "tally" and .logline_lag == "180s" and .derived_op == "tally"' \ + jq -e '.class == "tally" and .derived_op == "tally"' \ "$d/vmprov-tally.log.bark" >/dev/null || { cat "$d/vmprov-tally.log.bark" >&2 return 1 @@ -5465,6 +5453,22 @@ CONF cat /tmp/vmprov.tally >&2 return 1 } + # ⚠ The buckets are findable by the MINUTE THEY ARE ABOUT, with + # nothing declared. The source lines are from 2026-09-06 and this ran + # today, so a store stamped when the numbers were computed would need + # a declared lag of however old the data is — which is why the chunk + # carries the bucket window instead. + # + # RFC3339 with the zone spelled out: a NAIVE stamp is parsed in the + # READER's timezone, so this would pass in a UTC VM and fail anywhere + # else — the store's stamps are UTC whatever the host is set to. + timberfs query "$d/vmprov-tally.log" \ + --from '2026-09-06T10:00:00Z' --to '2026-09-06T10:01:00Z' 2>/dev/null \ + | grep -q 'http_requests method=GET status=200 count=2' || { + echo "a logline window over the buckets found nothing" >&2 + timberfs query "$d/vmprov-tally.log" >&2 + return 1 + } # ⚠ A second pass must not recount: the position is the follower's. local before after