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