105 lines
5.4 KiB
Markdown
105 lines
5.4 KiB
Markdown
# 076 — `log stream` declared columns get contaminated with garbage on non-columnar lines
|
|
|
|
## Summary
|
|
|
|
Wishlist feedback, verbatim: "The `log stream` type whitespace-separated
|
|
formatting is not working at all. I have a session `suited-gyrfalcon`
|
|
running, please investigate."
|
|
|
|
Investigated directly against the live `suited-gyrfalcon` instance
|
|
(`ottyl sessions` → port 62059 → `/api/params`, `/api/logs`,
|
|
`/api/stats`; 236,069 ingested log lines, real `log stream` output).
|
|
Root cause confirmed — this is not a gap in header/column detection
|
|
(ticket 059's detector itself works correctly on genuine `log stream`
|
|
rows), it's that the *declared params* it produces get applied far too
|
|
broadly once they exist.
|
|
|
|
**What's actually happening:** `auto_declare_log_stream_params`
|
|
(`engine.rs:472-497`) correctly gates *declaration* on
|
|
`is_log_stream_line(text)` (`:484`) — so it only fires column
|
|
declarations the first time it sees a genuine columnar data row. But
|
|
the resulting `ParamDeclaration.message_match_regex` for each column is
|
|
a pure **fixed character-offset** pattern with no content anchor at all
|
|
— e.g. observed live: `Activity` → `^.{55}(?P<Activity>\S(?:.{0,19}\S)?)`,
|
|
`PID` → `^.{76}(?P<PID>\S(?:.{0,5}\S)?)`, `Thread` →
|
|
`^.{32}(?P<Thread>\S(?:.{0,9}\S)?)` (from `log_stream_column_pattern`,
|
|
`logfmt.rs:287-303`). Once declared, these are ordinary
|
|
`ParamDeclaration`s: the *general* per-line param-derivation path
|
|
(`auto_declare_params`/`extract_param_raw`) applies every declared
|
|
param's regex to **every** ingested line, with no re-check that the
|
|
line is actually log-stream-shaped — there's no gate equivalent to
|
|
`is_log_stream_line` at derivation time, only at first-declaration time.
|
|
|
|
Confirmed impact from the live instance:
|
|
- Sampling ~1000-line windows at several points across the 236k-line
|
|
stream, roughly **1-2% of lines get a garbage `Timestamp` value**
|
|
that isn't a real timestamp — e.g. line 306:
|
|
`"so_gencnt: 4042707 so_state: 0x0"` (a continuation line from a
|
|
wrapped multi-line network-stats dump, no relation to the columnar
|
|
format at all) got `Timestamp: "so_gencnt: 4042707 so_state: 0x0"`,
|
|
`Activity`/`PID`/etc sliced from arbitrary character offsets of that
|
|
unrelated text. Same for bracket/brace-only continuation lines
|
|
(`"}"`, `"]"`) inside pretty-printed dumps.
|
|
- Even the header line itself (sequence 0,
|
|
`"Timestamp Thread Type Activity PID TTL"`) ends up with
|
|
`Activity: "Activity"`, `Thread: "Thread"`, `Timestamp: "Timestamp"`,
|
|
`Type: "Type"` as its own param values — because ticket 052's
|
|
retroactive re-derivation (`engine.rs:540`, re-running
|
|
`auto_declare_params` over every retained line whenever a new param
|
|
is declared) re-applies the newly-declared fixed-offset regexes back
|
|
over already-ingested lines, including the header line, with no
|
|
exemption for it.
|
|
- This directly undermines ticket 074's "sorting is broken" complaint
|
|
too: sorting by `Timestamp` mixes ~1-2% garbage string values in among
|
|
otherwise lexically-sortable ISO timestamps, which would visibly
|
|
scramble ordering — worth re-checking ticket 074 once this is fixed,
|
|
the two may partially be the same underlying issue.
|
|
|
|
This explains "not working at all" better than a full parse failure
|
|
would: the common case (genuine columnar rows) parses fine — it's that
|
|
the contamination on the ~1-2% of non-columnar lines interleaved
|
|
throughout every real `log stream` capture (multi-line dumps are
|
|
common) makes every declared log-stream column look untrustworthy.
|
|
|
|
## Scope
|
|
|
|
- Make the per-column `message_match_regex` self-verifying, not purely
|
|
positional: either (a) prefix each generated column/message pattern
|
|
(`log_stream_column_pattern`/`log_stream_message_pattern`,
|
|
`logfmt.rs:287-320`) with the same shape check `is_log_stream_line`
|
|
uses so the regex only matches on a genuinely columnar line, or (b)
|
|
gate the general param-derivation path itself so a param declared via
|
|
`auto_declare_log_stream_params` is only evaluated against lines
|
|
where `is_log_stream_line` holds — (a) is likely simpler since it
|
|
keeps the gate local to the declaration rather than adding a
|
|
special case to the generic derivation path.
|
|
- Fix ticket 052's retroactive re-derivation (`engine.rs:540`) to
|
|
respect that same gate, so the header line (and any other
|
|
non-columnar retained line) doesn't retroactively pick up columnar
|
|
param values.
|
|
- Add a regression test using the real contaminated lines captured
|
|
above (continuation lines like `"so_gencnt: ... so_state: ..."` and
|
|
the header line itself) alongside the existing
|
|
`log_stream_sample.txt` fixture — the current fixture and its tests
|
|
don't include a multi-line-dump continuation line, which is why
|
|
ticket 059's tests passed despite this.
|
|
|
|
## Acceptance criteria
|
|
|
|
- Ingesting a `log stream` capture that includes multi-line
|
|
continuation content (network stat dumps, bracketed/braced
|
|
pretty-printed blocks) does not populate `Timestamp`/`Thread`/`Type`/
|
|
`Activity`/`PID`/`TTL` params on those continuation lines.
|
|
- The header line itself never ends up with its own column names as
|
|
values.
|
|
- Existing correctly-parsed columnar rows are unaffected.
|
|
- A regression test using real captured contamination examples (not
|
|
just the original fixture) passes.
|
|
|
|
## Depends on
|
|
|
|
Builds on ticket 059 (commit `de9ba6f`) and ticket 052's retroactive
|
|
re-derivation. Related to ticket 074 (timeline sort) — re-verify that
|
|
complaint after this fix lands, since garbage `Timestamp` values are a
|
|
plausible contributor to it.
|