mirror of
https://github.com/rustfs/rustfs.git
synced 2026-08-03 20:07:42 +00:00
3ed682be42
* feat(log-analyzer): add crate skeleton and unified event model
Implements LA-1 (rustfs/backlog#1282) of the log fault-analysis system
(rustfs/backlog#1281): new synchronous rustfs-log-analyzer crate with the
LogEvent/LogLevel/SourceRef/EventKind/ParseStats model shared by all
later stages. No tokio, no rustfs-* internal deps by design.
Note: thiserror listed in the issue is deferred until a stage actually
defines error types (LA-3/LA-4) to avoid an unused dependency.
* feat(log-analyzer): add line parsing layer
Implements LA-2 (rustfs/backlog#1283): four parse channels tried in order
per line — native tracing JSON, container-prefix stripping (K8s CRI /
docker compose / journald) with JSON retry, multi-line Rust panic block
folding (both pre- and post-1.65 formats, stderr has no JSON logger), and
a plain-text fallback that never fails. Parse accounting feeds the report
parse-ratio disclosure.
* feat(log-analyzer): add ingest layer for directories and archives
Implements LA-3 (rustfs/backlog#1284): expands customer inputs (files,
directories, zip/tar/tar.gz/.zst/.gz, stdin-like readers) into parsed
events. Magic-byte detection with extension fallback, recursive archive
walking with depth/entry/byte/memory caps (every capped input disclosed
in IngestReport.skipped), first-level directory names become node labels,
and nothing is ever extracted to disk so hostile entry paths are inert.
Adds tar 0.4 to workspace deps (sync; the async astral-tokio-tar used by
rustfs-zip does not fit this crate's no-tokio contract).
* feat(log-analyzer): add rule model, matching engine, and finding aggregation
Implements LA-4 (rustfs/backlog#1285): owned serde-round-trippable Rule/
Matcher/Severity types (external JSON rules deserialize into the same
types later), fail-fast RuleSet validation that reports every problem at
once, a linear-scan engine with regexes compiled once, and an
order-independent FindingsCollector (commutative aggregates only; the
test asserts byte-identical output across shuffled input orders).
* feat(log-analyzer): add built-in seed rule library (68 rules, 12 categories)
Implements LA-5 (rustfs/backlog#1286): the 2026-07 repository-wide
failure-log survey distilled into rules across disk health, erasure/
bitrot, quorum, network/RPC, distributed locks, heal, scanner, IAM,
startup/config/TLS, capacity, decommission/rebalance, and process panics.
Every anchor was verified verbatim against the source tree (94/94 hits,
zero corrections needed). Quorum rules pre-fill implies_root_cause for
the Phase-2 folding (rustfs/backlog#1290); client-side rules carry burst
thresholds (min_count) so isolated client mistakes don't clutter reports.
Tests: one realistic positive sample per rule (table-driven), exact-set
smoke samples including the intentional internode/client signature
double-hit, and negative cases.
* feat(log-analyzer): add analysis orchestration, report rendering, and redaction
Implements LA-6 (rustfs/backlog#1287): a single-pass Analyzer that does
rule matching, minute-bucket timelines (gap-filled, merged to <=60
buckets), unmatched WARN/ERROR template clustering (placeholders for
numbers/uuids/paths/addresses/quotes, 5000-template cap disclosed as
<overflow>), mixed-UTC-offset detection, and below-min_count demotion to
a low-confidence section. Renderers: pipe-friendly terminal text, stable
JSON (schema_version=1), and ticket-pasteable Markdown. --redact hashes
customer identifiers (stable h:sha256[..8]) in samples/evidence/messages
while keeping rule ids, targets, and panic locations intact.
* feat(rustfs): add 'rustfs diagnose' subcommand for offline log fault analysis
Implements LA-7 (rustfs/backlog#1288): wires rustfs-log-analyzer into the
main binary as a diagnose subcommand that short-circuits before
observability/storage init (same pattern as 'info' / 'tls inspect') so
the report on stdout is never wrapped by the JSON logger.
rustfs diagnose <paths>... [--format text|json|md] [--since 24h]
[--until ...] [--min-level warn] [--redact] [--top N] [--samples N]
Accepts files, directories, archives (.zip/.tar/.tar.gz/.zst/.gz) and '-'
for stdin. Exit codes: 0 = diagnosis completed (findings never fail the
process), 2 = bad arguments / no readable input.
diagnose_e2e covers the six MVP acceptance scenarios from
rustfs/backlog#1281 (directory+zst archive, multi-node zip attribution,
CRI-prefixed kubectl logs, panic folding, stable JSON schema, CLI parsing
incl. the legacy 'rustfs <volume>' preprocessor regression); the
full-binary smoke test is #[ignore]d (run with -- --ignored).
Usage doc: docs/operations/log-diagnose.md.
* ci(log-analyzer): guard rule anchors against log-message drift
Implements LA-8 (rustfs/backlog#1289): every seed-rule anchor must exist
verbatim in the rustfs source tree, so changing a log message without
updating its rule fails the gate instead of silently killing the rule.
- la-dump-anchors bin emits 'rule_id<TAB>anchor' TSV;
- scripts/check_log_analyzer_rules.sh greps each anchor (fixed-string,
*.rs only, excluding crates/log-analyzer itself to avoid self-matches);
- RuleSet::new now rejects anchors that are blank, contain tab/newline,
or are shorter than 8 bytes (no discriminating power); the '[FATAL]'
anchor gained its trailing space to meet the floor while still matching
the emit_fatal_stderr format string;
- wired as log-analyzer-rules-check into the pre-pr gate (it compiles the
crate, so it stays out of the fast pre-commit set).
Negative self-test: breaking an anchor makes the script exit 1 naming the
rule ('MISSING anchor for rule inconsistent-drive: zzz-not-exist-anchor').
* refactor(log-analyzer): use root-relative provenance for directory inputs
Binary smoke run showed report samples citing full absolute paths, which
drowns the useful part. Directory inputs now label sources as
"<root-name>/<relative-path>" (e.g. "smoke-logs/node1/rustfs.log");
archives and single files keep their existing provenance.
* chore(log-analyzer): reword comment to satisfy the typos gate
* fix(log-analyzer): declare chrono serde feature locally after workspace feature localization
* fix(log-analyzer): bound line reads so a newline-less input cannot bypass the byte cap
read_until grew the line buffer with the entire remaining stream before the
max_total_bytes check ran, so a single multi-GB line (decompression bomb or
corrupt file) could allocate unboundedly. Replace it with a capped reader that
enforces the remaining global budget chunk-by-chunk and adds a per-line cap
(IngestOptions::max_line_bytes, default 1 MiB); over-cap tails are discarded
but still charged, and truncation is disclosed once per file as the new
line_too_long skip reason. Flagged by Codex review on #4876.
* fix(log-analyzer): redact field-shaped identifiers inside message text and widen the hash to 64 bits
--redact only hashed IPv4 literals in unstructured message text, so
bucket/object/access-key values embedded in messages (access_key=AK123,
'bucket: media, object: private/a.bin') leaked into reports documented as
safe to forward. Apply the SENSITIVE_FIELDS list to key=value / key: value
shapes in message text with the same hash as structured fields, and extend
the hash from 8 to 16 hex chars so cross-identifier collisions stay
negligible. Flagged by Codex and Copilot review on #4876.
* fix(log-analyzer): strip collector prefixes before panic-block absorption
An open panic block tested continuation lines against absorbs() before their
CRI/compose/journald prefix was stripped, so containerized panics stored the
prefix in the payload and split into a truncated panic plus text noise as soon
as the note/backtrace lines arrived. Stripping now happens once at the top of
feed() and every channel judges the payload. Flagged by Codex review on #4876.
* fix(log-analyzer): remove two input-order dependencies in representative selection
The unmatched-cluster target stayed pinned to the first-seen event while the
representative sample could be replaced, so sample and target could come from
different events and vary with input order; the pair now updates together by
lexicographic (sample, target) min. Sample selection tie-broke on line number
alone, which is only unique within one file; the key now includes the source
file. Flagged by Copilot review on #4876.
* fix(rustfs): reject negative relative times in diagnose --since/--until
parse_time_arg accepted "-24h" and produced a future timestamp, contradicting
the documented 'counted back from now' semantics. The amount now parses as
unsigned, so a leading '-' fails with the usual invalid-time error. Flagged by
Copilot review on #4876.
* feat(log-analyzer): Phase 2 — causal folding, timeline anomalies, external rules (LA-9) (#4942)
* feat(log-analyzer): collapse cascade symptoms under their root-cause finding
Phase-2 sub-item A (rustfs/backlog#1290): a finding whose rule declares
implies_root_cause edges folds under a qualifying root — root.first_seen <=
symptom.first_seen + 5min and root.last_seen >= symptom.first_seen - 30min,
existence-based when either side has no timestamps (pure stderr panics).
Findings gain collapsed_into/caused; text/markdown render the root block with
an indented cascade line and stop listing collapsed symptoms flat, while JSON
keeps every finding. Roots are promoted to the most severe position among
their block so the report top still answers 'the most likely cause'.
* feat(log-analyzer): detect timeline/clock anomalies (schema v2)
Phase-2 sub-item B (rustfs/backlog#1290): three deterministic hints rendered
between the summary and findings — mixed UTC offsets (with a clock-skew note
when signature-mismatch findings coexist), per-node time ranges that do not
overlap at all (both nodes >100 timestamped events), and log gaps of at least
max(15min, 3x bucket width) after >=3 consecutive active minutes, upgraded to
restart evidence when a startup-class finding begins within 5min after the
gap. JSON gains timeline_anomalies and schema_version bumps to 2.
* feat(diagnose): load external rules with --rules <file.json>
Phase-2 sub-item C (rustfs/backlog#1290): an external JSON rule file
({schema_version: 1, rules: [Rule...]}, the exact serde shape of the built-in
rules) merges over the seed library, with same-id rules replacing built-ins so
the support team can hotfix a misfiring rule without a release. The merged set
validates as a whole and any problem (bad regex, duplicate id, empty matcher
group, wrong schema version) prints every error and exits 2 — analysis never
runs on a half-broken set. External anchors are exempt from the CI anchor
guard, documented as author-owned quality. Adds the custom-rules section to
docs/operations/log-diagnose.md.
* fix(log-analyzer): address PR #4876 review (redaction coverage, order-independence, guards)
Redaction (--redact) now honours its "forwardable" intent across every report surface instead of a 15-name field whitelist applied over a subset:
- redact_event scrubs the full fields map (sensitive names hashed whole, every other value run through redact_text) plus provenance, so the JSON/Markdown full-sample dump no longer leaks non-whitelisted fields (client_ip, url, user, ...).
- node labels are hashed once at ingestion, so summary.nodes, per-node timeline ranges, samples and timeline anomalies stay consistent and correlatable under one stable hash.
- evidence values, unmatched-cluster templates and skipped-input paths are now redacted; peer/disk/drive/volume/node/user added to the sensitive set; IPv6 literals are hashed (without touching `rust::paths` or HH:MM:SS clocks); provenance keeps the leaf filename and hashes the customer directory/archive prefix.
- redact.rs and docs/operations/log-diagnose.md reworded to "best-effort identifier scrubbing", not an anonymization guarantee.
Order-independence (the crate's headline contract):
- the evidence value cap keeps the lexicographically smallest N distinct values instead of the first-N-by-arrival (previously order-dependent).
- first_seen/last_seen break equal-instant ties on the offset, so the serialized RFC3339 offset no longer depends on input order.
Parsing:
- a new-format panic header no longer swallows the line immediately after it when that line is itself a JSON event or a second panic header (previously dropped an interleaved ERROR in merged stdout/stderr, or merged a panic-during-panic); trailing "note: ..." backtrace lines now fold into the block.
CLI:
- diagnose --since/--until reject absurd relative amounts via checked_sub_signed instead of panicking; the exit-code doc now matches actual behaviour.
CI:
- check_log_analyzer_rules.sh is wired into the ci.yml test-and-lint job (it was only in make pre-pr, so anchor drift from other PRs could merge green).
Markdown table cells escape '|' so customer log text cannot break the table structure.
---------
Co-authored-by: houseme <housemecn@gmail.com>
1165 lines
48 KiB
Rust
1165 lines
48 KiB
Rust
// Copyright 2024 RustFS Team
|
||
//
|
||
// Licensed under the Apache License, Version 2.0 (the "License");
|
||
// you may not use this file except in compliance with the License.
|
||
// You may obtain a copy of the License at
|
||
//
|
||
// http://www.apache.org/licenses/LICENSE-2.0
|
||
//
|
||
// Unless required by applicable law or agreed to in writing, software
|
||
// distributed under the License is distributed on an "AS IS" BASIS,
|
||
// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
|
||
// See the License for the specific language governing permissions and
|
||
// limitations under the License.
|
||
|
||
//! Analysis orchestration (rustfs/backlog#1287): one pass over the event
|
||
//! stream does rule matching, timeline bucketing, and unmatched-pattern
|
||
//! clustering at once. All aggregates stay order-independent.
|
||
|
||
use crate::ingest::{IngestReport, SkipReason};
|
||
use crate::model::{EventKind, LogEvent, LogLevel, ParseStats};
|
||
use crate::redact;
|
||
use crate::rules::{Finding, FindingsCollector, RuleEngine, Severity};
|
||
use chrono::{DateTime, Duration, FixedOffset, Utc};
|
||
use regex::Regex;
|
||
use serde::Serialize;
|
||
use std::collections::{BTreeMap, BTreeSet, HashMap};
|
||
use std::sync::LazyLock;
|
||
|
||
const UNMATCHED_DISTINCT_CAP: usize = 5000;
|
||
const OVERFLOW_TEMPLATE: &str = "<overflow>";
|
||
const SAMPLE_TEXT_CAP: usize = 500;
|
||
/// Bucket widths (minutes) tried in order until <= 60 buckets span the range.
|
||
const BUCKET_WIDTHS_MIN: [i64; 6] = [1, 5, 15, 60, 360, 1440];
|
||
|
||
#[derive(Debug, Clone)]
|
||
pub struct AnalyzeOptions {
|
||
/// Keep events at/after this time. Timestamp-less events always pass.
|
||
pub since: Option<DateTime<FixedOffset>>,
|
||
/// Keep events at/before this time. Timestamp-less events always pass.
|
||
pub until: Option<DateTime<FixedOffset>>,
|
||
/// Drop events below this level; level-less events always pass.
|
||
pub min_level: Option<LogLevel>,
|
||
pub max_samples: usize,
|
||
pub top_unmatched: usize,
|
||
pub redact: bool,
|
||
}
|
||
|
||
impl Default for AnalyzeOptions {
|
||
fn default() -> Self {
|
||
Self {
|
||
since: None,
|
||
until: None,
|
||
min_level: None,
|
||
max_samples: 3,
|
||
top_unmatched: 20,
|
||
redact: false,
|
||
}
|
||
}
|
||
}
|
||
|
||
#[derive(Debug, Clone, Serialize)]
|
||
pub struct Summary {
|
||
pub events_total: u64,
|
||
pub events_after_filter: u64,
|
||
/// "ERROR" -> n, …, "no_level" -> n.
|
||
pub level_counts: BTreeMap<String, u64>,
|
||
pub time_range: Option<(DateTime<FixedOffset>, DateTime<FixedOffset>)>,
|
||
pub nodes: Vec<String>,
|
||
pub parse: ParseStats,
|
||
pub files_parsed: u64,
|
||
pub bytes_fed: u64,
|
||
/// Distinct UTC offsets observed (e.g. ["+08:00", "Z"]); more than one
|
||
/// means cross-node clock/timezone comparison needs care.
|
||
pub distinct_offsets: Vec<String>,
|
||
}
|
||
|
||
#[derive(Debug, Clone, Serialize)]
|
||
pub struct UnmatchedCluster {
|
||
/// Normalized message template (numbers/uuids/paths/... placeholders).
|
||
pub template: String,
|
||
pub count: u64,
|
||
pub level: String,
|
||
/// One raw sample message (lexicographic min, capped at 500 chars).
|
||
pub sample: String,
|
||
pub target: Option<String>,
|
||
}
|
||
|
||
#[derive(Debug, Clone, Serialize)]
|
||
pub struct TimeBucket {
|
||
/// Bucket start, normalized to UTC.
|
||
pub start: DateTime<Utc>,
|
||
pub error: u64,
|
||
pub warn: u64,
|
||
pub other: u64,
|
||
}
|
||
|
||
/// One deterministic timeline heuristic hit (rustfs/backlog#1290 sub-item
|
||
/// B). All three kinds are hints, not verdicts.
|
||
#[derive(Debug, Clone, Serialize)]
|
||
pub struct TimelineAnomaly {
|
||
/// "mixed_offsets" | "node_ranges_disjoint" | "log_gap".
|
||
pub kind: String,
|
||
/// Operator-facing description.
|
||
pub message: String,
|
||
/// Involved node labels (node_ranges_disjoint); empty otherwise.
|
||
pub nodes: Vec<String>,
|
||
/// Gap boundaries in UTC (log_gap); null otherwise.
|
||
pub gap_start: Option<DateTime<Utc>>,
|
||
pub gap_end: Option<DateTime<Utc>>,
|
||
/// log_gap only: a startup-class finding begins within 5min after the gap.
|
||
pub restart_evidence: bool,
|
||
}
|
||
|
||
#[derive(Debug, Serialize)]
|
||
pub struct AnalysisReport {
|
||
/// Stability contract for JSON consumers.
|
||
pub schema_version: u32,
|
||
pub summary: Summary,
|
||
/// Sorted findings at/above their rule's min_count.
|
||
pub findings: Vec<Finding>,
|
||
/// Findings below their rule's min_count (low-confidence hints).
|
||
pub low_confidence: Vec<Finding>,
|
||
pub unmatched_top: Vec<UnmatchedCluster>,
|
||
pub timeline: Vec<TimeBucket>,
|
||
/// Timeline/clock heuristics (schema v2, rustfs/backlog#1290).
|
||
pub timeline_anomalies: Vec<TimelineAnomaly>,
|
||
/// Pass-through of every skipped input (no silent caps).
|
||
pub skipped_inputs: Vec<(String, SkipReason)>,
|
||
}
|
||
|
||
/// (min ts, max ts, timestamped event count) for one node label.
|
||
type NodeRange = (DateTime<FixedOffset>, DateTime<FixedOffset>, u64);
|
||
|
||
#[derive(Default)]
|
||
struct BucketCounts {
|
||
error: u64,
|
||
warn: u64,
|
||
other: u64,
|
||
}
|
||
|
||
struct ClusterAcc {
|
||
count: u64,
|
||
/// Highest level seen (order-independent max).
|
||
level: LogLevel,
|
||
/// Lexicographic-min raw sample (order-independent).
|
||
sample: String,
|
||
target: Option<String>,
|
||
}
|
||
|
||
pub struct Analyzer {
|
||
engine: RuleEngine,
|
||
opts: AnalyzeOptions,
|
||
collector: FindingsCollector,
|
||
events_total: u64,
|
||
events_after_filter: u64,
|
||
level_counts: BTreeMap<String, u64>,
|
||
time_range: Option<(DateTime<FixedOffset>, DateTime<FixedOffset>)>,
|
||
nodes: BTreeSet<String>,
|
||
offsets: BTreeSet<String>,
|
||
/// node label -> (min ts, max ts, timestamped event count); feeds the
|
||
/// disjoint-node-ranges heuristic.
|
||
node_ranges: BTreeMap<String, NodeRange>,
|
||
/// unix-minute -> counts.
|
||
minute_buckets: BTreeMap<i64, BucketCounts>,
|
||
unmatched: HashMap<String, ClusterAcc>,
|
||
unmatched_overflow: u64,
|
||
}
|
||
|
||
impl Analyzer {
|
||
pub fn new(engine: RuleEngine, opts: AnalyzeOptions) -> Self {
|
||
Self {
|
||
engine,
|
||
collector: FindingsCollector::new(opts.max_samples),
|
||
opts,
|
||
events_total: 0,
|
||
events_after_filter: 0,
|
||
level_counts: BTreeMap::new(),
|
||
time_range: None,
|
||
nodes: BTreeSet::new(),
|
||
offsets: BTreeSet::new(),
|
||
node_ranges: BTreeMap::new(),
|
||
minute_buckets: BTreeMap::new(),
|
||
unmatched: HashMap::new(),
|
||
unmatched_overflow: 0,
|
||
}
|
||
}
|
||
|
||
/// Wire this directly as the ingest `on_event` callback.
|
||
pub fn observe(&mut self, mut event: LogEvent) {
|
||
self.events_total += 1;
|
||
|
||
if let Some(ts) = event.timestamp
|
||
&& (self.opts.since.is_some_and(|since| ts < since) || self.opts.until.is_some_and(|until| ts > until))
|
||
{
|
||
return;
|
||
}
|
||
if let (Some(min), Some(level)) = (self.opts.min_level, event.level)
|
||
&& level < min
|
||
{
|
||
return;
|
||
}
|
||
self.events_after_filter += 1;
|
||
|
||
// Under --redact, hash the node label once here so every downstream
|
||
// surface (summary.nodes, per-node timeline ranges, samples, timeline
|
||
// anomalies) shows the same stable hash rather than the raw hostname.
|
||
if self.opts.redact
|
||
&& let Some(node) = event.node.as_deref()
|
||
{
|
||
event.node = Some(std::sync::Arc::from(redact::hash_value(node).as_str()));
|
||
}
|
||
|
||
let level_key = event.level.map_or_else(|| "no_level".to_string(), |l| l.to_string());
|
||
*self.level_counts.entry(level_key).or_insert(0) += 1;
|
||
|
||
if let Some(node) = event.node.as_deref() {
|
||
self.nodes.insert(node.to_string());
|
||
}
|
||
|
||
if let Some(ts) = event.timestamp {
|
||
self.time_range = Some(match self.time_range {
|
||
None => (ts, ts),
|
||
Some((first, last)) => (first.min(ts), last.max(ts)),
|
||
});
|
||
self.offsets.insert(format_offset(&ts));
|
||
if let Some(node) = event.node.as_deref() {
|
||
self.node_ranges
|
||
.entry(node.to_string())
|
||
.and_modify(|(min, max, count)| {
|
||
*min = (*min).min(ts);
|
||
*max = (*max).max(ts);
|
||
*count += 1;
|
||
})
|
||
.or_insert((ts, ts, 1));
|
||
}
|
||
let bucket = self.minute_buckets.entry(ts.timestamp().div_euclid(60)).or_default();
|
||
match event.level {
|
||
Some(LogLevel::Error) => bucket.error += 1,
|
||
Some(LogLevel::Warn) => bucket.warn += 1,
|
||
_ => bucket.other += 1,
|
||
}
|
||
}
|
||
|
||
let hits = self.engine.matches(&event);
|
||
if hits.is_empty() {
|
||
// Unmatched WARN/ERROR feeds the "unknown patterns" section —
|
||
// the input for rule-library iteration. Panics have their own rule.
|
||
if event.kind != EventKind::Panic && matches!(event.level, Some(LogLevel::Warn) | Some(LogLevel::Error)) {
|
||
self.cluster_unmatched(&event);
|
||
}
|
||
return;
|
||
}
|
||
for idx in hits {
|
||
let rule = &self.engine.rules()[idx];
|
||
self.collector.observe(rule, idx, &event);
|
||
}
|
||
}
|
||
|
||
pub fn finalize(self, ingest: IngestReport) -> AnalysisReport {
|
||
let mut findings = Vec::new();
|
||
let mut low_confidence = Vec::new();
|
||
for finding in self.collector.into_findings() {
|
||
if finding.below_min_count {
|
||
low_confidence.push(finding);
|
||
} else {
|
||
findings.push(finding);
|
||
}
|
||
}
|
||
collapse_findings(&mut findings);
|
||
|
||
let mut unmatched_top: Vec<UnmatchedCluster> = self
|
||
.unmatched
|
||
.into_iter()
|
||
.map(|(template, acc)| UnmatchedCluster {
|
||
template,
|
||
count: acc.count,
|
||
level: acc.level.to_string(),
|
||
sample: acc.sample,
|
||
target: acc.target,
|
||
})
|
||
.collect();
|
||
if self.unmatched_overflow > 0 {
|
||
unmatched_top.push(UnmatchedCluster {
|
||
template: OVERFLOW_TEMPLATE.to_string(),
|
||
count: self.unmatched_overflow,
|
||
level: LogLevel::Warn.to_string(),
|
||
sample: format!("(+{} events beyond the {UNMATCHED_DISTINCT_CAP}-template cap)", self.unmatched_overflow),
|
||
target: None,
|
||
});
|
||
}
|
||
unmatched_top.sort_by(|a, b| b.count.cmp(&a.count).then(a.template.cmp(&b.template)));
|
||
unmatched_top.truncate(self.opts.top_unmatched);
|
||
|
||
let (timeline, bucket_width_min) = merge_timeline(&self.minute_buckets);
|
||
let timeline_anomalies = detect_timeline_anomalies(
|
||
&self.offsets,
|
||
&self.node_ranges,
|
||
&self.minute_buckets,
|
||
bucket_width_min,
|
||
&findings,
|
||
&low_confidence,
|
||
);
|
||
|
||
let mut report = AnalysisReport {
|
||
schema_version: 2,
|
||
summary: Summary {
|
||
events_total: self.events_total,
|
||
events_after_filter: self.events_after_filter,
|
||
level_counts: self.level_counts,
|
||
time_range: self.time_range,
|
||
nodes: self.nodes.into_iter().collect(),
|
||
parse: ingest.stats,
|
||
files_parsed: ingest.files_parsed,
|
||
bytes_fed: ingest.bytes_fed,
|
||
distinct_offsets: self.offsets.into_iter().collect(),
|
||
},
|
||
findings,
|
||
low_confidence,
|
||
unmatched_top,
|
||
timeline,
|
||
timeline_anomalies,
|
||
skipped_inputs: ingest.skipped,
|
||
};
|
||
|
||
if self.opts.redact {
|
||
redact_report(&mut report);
|
||
}
|
||
report
|
||
}
|
||
|
||
fn cluster_unmatched(&mut self, event: &LogEvent) {
|
||
let template = normalize_template(&event.message);
|
||
if !self.unmatched.contains_key(&template) && self.unmatched.len() >= UNMATCHED_DISTINCT_CAP {
|
||
self.unmatched_overflow += 1;
|
||
return;
|
||
}
|
||
let level = event.level.unwrap_or(LogLevel::Warn);
|
||
let mut sample: String = event.message.chars().take(SAMPLE_TEXT_CAP).collect();
|
||
if event.message.chars().count() > SAMPLE_TEXT_CAP {
|
||
sample.push('…');
|
||
}
|
||
let entry = self.unmatched.entry(template).or_insert_with(|| ClusterAcc {
|
||
count: 0,
|
||
level,
|
||
sample: sample.clone(),
|
||
target: event.target.clone(),
|
||
});
|
||
entry.count += 1;
|
||
entry.level = entry.level.max(level);
|
||
// Lexicographic min on (sample, target) keeps the representative
|
||
// order-independent and the shown target from that same event.
|
||
if (sample.as_str(), &event.target) < (entry.sample.as_str(), &entry.target) {
|
||
entry.sample = sample;
|
||
entry.target = event.target.clone();
|
||
}
|
||
}
|
||
}
|
||
|
||
fn format_offset(ts: &DateTime<FixedOffset>) -> String {
|
||
let seconds = ts.offset().local_minus_utc();
|
||
if seconds == 0 {
|
||
return "Z".to_string();
|
||
}
|
||
let sign = if seconds < 0 { '-' } else { '+' };
|
||
let abs = seconds.abs();
|
||
format!("{sign}{:02}:{:02}", abs / 3600, (abs % 3600) / 60)
|
||
}
|
||
|
||
/// Returns the merged display buckets and the chosen bucket width (minutes);
|
||
/// the width also parameterizes the log-gap heuristic threshold.
|
||
fn merge_timeline(minute_buckets: &BTreeMap<i64, BucketCounts>) -> (Vec<TimeBucket>, i64) {
|
||
let (Some((&first, _)), Some((&last, _))) = (minute_buckets.first_key_value(), minute_buckets.last_key_value()) else {
|
||
return (Vec::new(), 1);
|
||
};
|
||
let span = last - first + 1;
|
||
let width = BUCKET_WIDTHS_MIN
|
||
.into_iter()
|
||
.find(|w| (span as u64).div_ceil(*w as u64) <= 60)
|
||
.unwrap_or(*BUCKET_WIDTHS_MIN.last().expect("non-empty"));
|
||
|
||
let start_slot = first.div_euclid(width);
|
||
let end_slot = last.div_euclid(width);
|
||
let mut merged: BTreeMap<i64, BucketCounts> = (start_slot..=end_slot).map(|slot| (slot, BucketCounts::default())).collect();
|
||
for (&minute, counts) in minute_buckets {
|
||
let slot = merged.get_mut(&minute.div_euclid(width)).expect("slot within range");
|
||
slot.error += counts.error;
|
||
slot.warn += counts.warn;
|
||
slot.other += counts.other;
|
||
}
|
||
let buckets = merged
|
||
.into_iter()
|
||
.map(|(slot, counts)| TimeBucket {
|
||
start: DateTime::<Utc>::from_timestamp(slot * width * 60, 0).expect("valid timestamp"),
|
||
error: counts.error,
|
||
warn: counts.warn,
|
||
other: counts.other,
|
||
})
|
||
.collect();
|
||
(buckets, width)
|
||
}
|
||
|
||
/// Finding ids whose presence right after a log gap upgrades it to restart
|
||
/// evidence, and ids that make mixed offsets a likely signature root cause.
|
||
const STARTUP_RULE_IDS: [&str; 3] = ["startup-fatal", "runtime-failed", "endpoint-resolve-failed"];
|
||
const SIGNATURE_RULE_IDS: [&str; 2] = ["client-signature-mismatch", "internode-signature-mismatch"];
|
||
|
||
/// Timeline/clock heuristics (rustfs/backlog#1290 sub-item B). Three
|
||
/// deterministic hints — mixed UTC offsets, disjoint per-node time ranges,
|
||
/// and gaps in an otherwise continuous timeline — each phrased as a hint,
|
||
/// never a verdict.
|
||
fn detect_timeline_anomalies(
|
||
offsets: &BTreeSet<String>,
|
||
node_ranges: &BTreeMap<String, NodeRange>,
|
||
minute_buckets: &BTreeMap<i64, BucketCounts>,
|
||
bucket_width_min: i64,
|
||
findings: &[Finding],
|
||
low_confidence: &[Finding],
|
||
) -> Vec<TimelineAnomaly> {
|
||
let mut anomalies = Vec::new();
|
||
let has_finding = |ids: &[&str]| {
|
||
findings
|
||
.iter()
|
||
.chain(low_confidence)
|
||
.any(|f| ids.contains(&f.rule_id.as_str()))
|
||
};
|
||
|
||
// 1. Mixed UTC offsets: nodes disagree on timezone or clock source.
|
||
if offsets.len() > 1 {
|
||
let mut message = format!(
|
||
"日志包含多个 UTC 偏移({}):节点时区/时钟源可能不一致,跨节点排序前先归一到 UTC。",
|
||
offsets.iter().cloned().collect::<Vec<_>>().join(" / ")
|
||
);
|
||
if has_finding(&SIGNATURE_RULE_IDS) {
|
||
message.push_str("同时检测到签名不匹配类 finding,时钟偏移是其高概率根因。");
|
||
}
|
||
anomalies.push(TimelineAnomaly {
|
||
kind: "mixed_offsets".to_string(),
|
||
message,
|
||
nodes: Vec::new(),
|
||
gap_start: None,
|
||
gap_end: None,
|
||
restart_evidence: false,
|
||
});
|
||
}
|
||
|
||
// 2. Per-node time ranges that do not overlap at all (both sides with a
|
||
// meaningful sample size): clocks are wrong or collection windows differ.
|
||
let sizable: Vec<(&String, &NodeRange)> = node_ranges.iter().filter(|(_, (_, _, count))| *count > 100).collect();
|
||
for (i, (node_a, (min_a, max_a, _))) in sizable.iter().enumerate() {
|
||
for (node_b, (min_b, max_b, _)) in sizable.iter().skip(i + 1) {
|
||
if max_a < min_b || max_b < min_a {
|
||
anomalies.push(TimelineAnomaly {
|
||
kind: "node_ranges_disjoint".to_string(),
|
||
message: format!(
|
||
"节点 {node_a} 与 {node_b} 的日志时间范围完全不重叠({node_a}: {} → {},{node_b}: {} → {}):时钟错乱或采集不同期。",
|
||
min_a.to_rfc3339(),
|
||
max_a.to_rfc3339(),
|
||
min_b.to_rfc3339(),
|
||
max_b.to_rfc3339(),
|
||
),
|
||
nodes: vec![(*node_a).clone(), (*node_b).clone()],
|
||
gap_start: None,
|
||
gap_end: None,
|
||
restart_evidence: false,
|
||
});
|
||
}
|
||
}
|
||
}
|
||
|
||
// 3. Log gaps: >= 3 consecutive non-empty minutes, then a zero-event
|
||
// span of at least max(15min, 3x display bucket width), then activity
|
||
// again — the shape of a process restart or hang.
|
||
let threshold = (3 * bucket_width_min).max(15);
|
||
let startup_after_gap = |gap_end: DateTime<Utc>| {
|
||
findings.iter().chain(low_confidence).find_map(|f| {
|
||
if !STARTUP_RULE_IDS.contains(&f.rule_id.as_str()) {
|
||
return None;
|
||
}
|
||
let first = f.first_seen?.with_timezone(&Utc);
|
||
(first >= gap_end && first <= gap_end + Duration::minutes(5)).then(|| f.rule_id.clone())
|
||
})
|
||
};
|
||
let minutes: Vec<i64> = minute_buckets.keys().copied().collect();
|
||
let mut run_len = 1i64;
|
||
for window in minutes.windows(2) {
|
||
let (prev, next) = (window[0], window[1]);
|
||
let delta = next - prev;
|
||
if delta == 1 {
|
||
run_len += 1;
|
||
continue;
|
||
}
|
||
if run_len >= 3 && delta > threshold {
|
||
let gap_start = DateTime::<Utc>::from_timestamp((prev + 1) * 60, 0).expect("valid timestamp");
|
||
let gap_end = DateTime::<Utc>::from_timestamp(next * 60, 0).expect("valid timestamp");
|
||
let restart = startup_after_gap(gap_end);
|
||
let span = human_duration_minutes(delta - 1);
|
||
let message = match &restart {
|
||
Some(rule_id) => format!(
|
||
"时间线断档 {} → {}(约 {span}),断档后 5 分钟内出现 {rule_id}:重启证据。",
|
||
gap_start.to_rfc3339(),
|
||
gap_end.to_rfc3339(),
|
||
),
|
||
None => format!(
|
||
"时间线断档 {} → {}(约 {span}),此前有连续活动:疑似进程重启或挂起区间。",
|
||
gap_start.to_rfc3339(),
|
||
gap_end.to_rfc3339(),
|
||
),
|
||
};
|
||
anomalies.push(TimelineAnomaly {
|
||
kind: "log_gap".to_string(),
|
||
message,
|
||
nodes: Vec::new(),
|
||
gap_start: Some(gap_start),
|
||
gap_end: Some(gap_end),
|
||
restart_evidence: restart.is_some(),
|
||
});
|
||
}
|
||
run_len = 1;
|
||
}
|
||
anomalies
|
||
}
|
||
|
||
fn human_duration_minutes(minutes: i64) -> String {
|
||
if minutes >= 60 {
|
||
format!("{:.1}h", minutes as f64 / 60.0)
|
||
} else {
|
||
format!("{minutes}min")
|
||
}
|
||
}
|
||
|
||
/// Causal folding (rustfs/backlog#1290 sub-item A): a symptom finding
|
||
/// collapses under a root-cause finding named by its rule's
|
||
/// `implies_root_cause` edges when the root plausibly precedes it
|
||
/// (`root.first_seen <= symptom.first_seen + 5min`) and is not a
|
||
/// long-finished historical episode (`root.last_seen >= symptom.first_seen -
|
||
/// 30min`). A timestamp-less side (pure stderr panics) associates by
|
||
/// existence. Only confirmed findings participate — folding real symptoms
|
||
/// under a low-confidence root would hide them behind shaky evidence.
|
||
///
|
||
/// Findings are then re-sorted so a root block is promoted to the most
|
||
/// severe position among itself and its collapsed symptoms, weighted by the
|
||
/// block's combined count: the report top keeps answering "the most likely
|
||
/// cause" even when the root itself is a lower-severity finding.
|
||
fn collapse_findings(findings: &mut [Finding]) {
|
||
let index_of: HashMap<String, usize> = findings.iter().enumerate().map(|(i, f)| (f.rule_id.clone(), i)).collect();
|
||
// Among several qualifying roots pick the earliest first_seen;
|
||
// timestamp-less roots come last, rule id breaks remaining ties.
|
||
let root_key = |f: &Finding| (f.first_seen.is_none(), f.first_seen, f.rule_id.clone());
|
||
|
||
let mut chosen: Vec<Option<usize>> = vec![None; findings.len()];
|
||
for (i, symptom) in findings.iter().enumerate() {
|
||
for root_id in &symptom.implies_root_cause {
|
||
let Some(&r) = index_of.get(root_id) else { continue };
|
||
if r == i {
|
||
continue;
|
||
}
|
||
let root = &findings[r];
|
||
let qualifies = match (root.first_seen, symptom.first_seen) {
|
||
(Some(root_first), Some(symptom_first)) => {
|
||
root_first <= symptom_first + Duration::minutes(5)
|
||
&& root.last_seen.unwrap_or(root_first) >= symptom_first - Duration::minutes(30)
|
||
}
|
||
_ => true,
|
||
};
|
||
if qualifies && chosen[i].is_none_or(|cur| root_key(&findings[r]) < root_key(&findings[cur])) {
|
||
chosen[i] = Some(r);
|
||
}
|
||
}
|
||
}
|
||
|
||
// Follow chains so a symptom never points at a root that is itself
|
||
// collapsed (external rules may build A -> B -> C edges); the visited
|
||
// guard stops on adversarial cycles.
|
||
let resolve = |mut r: usize| {
|
||
let mut seen = vec![false; chosen.len()];
|
||
while let Some(next) = chosen[r] {
|
||
if seen[r] {
|
||
break;
|
||
}
|
||
seen[r] = true;
|
||
r = next;
|
||
}
|
||
r
|
||
};
|
||
|
||
let mut caused: Vec<Vec<String>> = vec![Vec::new(); findings.len()];
|
||
for i in 0..findings.len() {
|
||
let Some(first) = chosen[i] else { continue };
|
||
let root = resolve(first);
|
||
if root == i {
|
||
continue;
|
||
}
|
||
let root_id = findings[root].rule_id.clone();
|
||
findings[i].collapsed_into = Some(root_id);
|
||
caused[root].push(findings[i].rule_id.clone());
|
||
}
|
||
for (i, mut list) in caused.into_iter().enumerate() {
|
||
list.sort();
|
||
findings[i].caused = list;
|
||
}
|
||
// A cycle can leave a "root" both collapsed and carrying symptoms; keep
|
||
// it visible rather than folding every participant out of the report.
|
||
for finding in findings.iter_mut() {
|
||
if !finding.caused.is_empty() {
|
||
finding.collapsed_into = None;
|
||
}
|
||
}
|
||
|
||
let mut effective: HashMap<String, (Severity, u64)> =
|
||
findings.iter().map(|f| (f.rule_id.clone(), (f.severity, f.count))).collect();
|
||
for finding in findings.iter() {
|
||
if let Some(root) = &finding.collapsed_into {
|
||
let entry = effective.get_mut(root).expect("collapse target exists");
|
||
entry.0 = entry.0.min(finding.severity);
|
||
entry.1 += finding.count;
|
||
}
|
||
}
|
||
findings.sort_by(|a, b| {
|
||
let (severity_a, count_a) = effective[&a.rule_id];
|
||
let (severity_b, count_b) = effective[&b.rule_id];
|
||
severity_a
|
||
.cmp(&severity_b)
|
||
.then(count_b.cmp(&count_a))
|
||
.then(a.rule_id.cmp(&b.rule_id))
|
||
});
|
||
}
|
||
|
||
fn redact_report(report: &mut AnalysisReport) {
|
||
for finding in report.findings.iter_mut().chain(report.low_confidence.iter_mut()) {
|
||
// Samples carry the full event (message + every field + provenance);
|
||
// node labels are already hashed at ingestion time.
|
||
for sample in &mut finding.samples {
|
||
redact::redact_event(sample);
|
||
}
|
||
// Evidence values: sensitive-named fields hash whole, everything else
|
||
// is scrubbed for embedded IPs / key=value identifiers.
|
||
for (field, values) in &mut finding.evidence {
|
||
let redacted: BTreeSet<String> = values
|
||
.values
|
||
.iter()
|
||
.map(|v| redact::redact_evidence_value(field, v))
|
||
.collect();
|
||
values.values = redacted;
|
||
}
|
||
}
|
||
for cluster in &mut report.unmatched_top {
|
||
cluster.template = redact::redact_text(&cluster.template);
|
||
cluster.sample = redact::redact_text(&cluster.sample);
|
||
if let Some(target) = cluster.target.take() {
|
||
cluster.target = Some(redact::redact_text(&target));
|
||
}
|
||
}
|
||
// Skipped-input provenance (customer archive names / absolute paths).
|
||
for (path, _) in &mut report.skipped_inputs {
|
||
*path = redact::redact_provenance(path);
|
||
}
|
||
// summary.nodes and every node label inside timeline_anomalies derive from
|
||
// event.node, hashed at ingestion, so no separate pass is needed here.
|
||
}
|
||
|
||
// Template normalization, applied in order (rustfs/backlog#1287 §2).
|
||
static RE_UUID: LazyLock<Regex> = LazyLock::new(|| {
|
||
Regex::new(r"[0-9a-fA-F]{8}-[0-9a-fA-F]{4}-[0-9a-fA-F]{4}-[0-9a-fA-F]{4}-[0-9a-fA-F]{12}").expect("static regex")
|
||
});
|
||
static RE_HEX: LazyLock<Regex> = LazyLock::new(|| Regex::new(r"\b[0-9a-fA-F]{16,}\b").expect("static regex"));
|
||
static RE_TS: LazyLock<Regex> =
|
||
LazyLock::new(|| Regex::new(r"\d{4}-\d{2}-\d{2}T[0-9:.]+(?:Z|[+-]\d{2}:\d{2})?").expect("static regex"));
|
||
static RE_ADDR: LazyLock<Regex> =
|
||
LazyLock::new(|| Regex::new(r"\b\d{1,3}\.\d{1,3}\.\d{1,3}\.\d{1,3}(?::\d+)?\b").expect("static regex"));
|
||
static RE_PATH: LazyLock<Regex> = LazyLock::new(|| Regex::new(r"(^|\s)/\S+").expect("static regex"));
|
||
static RE_NUM: LazyLock<Regex> = LazyLock::new(|| Regex::new(r"\d+").expect("static regex"));
|
||
static RE_BACKTICK: LazyLock<Regex> = LazyLock::new(|| Regex::new("`[^`]*`").expect("static regex"));
|
||
static RE_SINGLE: LazyLock<Regex> = LazyLock::new(|| Regex::new(r"'[^']*'").expect("static regex"));
|
||
static RE_DOUBLE: LazyLock<Regex> = LazyLock::new(|| Regex::new(r#""[^"]*""#).expect("static regex"));
|
||
|
||
fn normalize_template(message: &str) -> String {
|
||
let s = RE_UUID.replace_all(message, "<uuid>");
|
||
let s = RE_HEX.replace_all(&s, "<hex>");
|
||
let s = RE_TS.replace_all(&s, "<ts>");
|
||
let s = RE_ADDR.replace_all(&s, "<addr>");
|
||
let s = RE_PATH.replace_all(&s, "$1<path>");
|
||
let s = RE_NUM.replace_all(&s, "<n>");
|
||
let s = RE_BACKTICK.replace_all(&s, "`<q>`");
|
||
let s = RE_SINGLE.replace_all(&s, "'<q>'");
|
||
let s = RE_DOUBLE.replace_all(&s, "\"<q>\"");
|
||
s.into_owned()
|
||
}
|
||
|
||
#[cfg(test)]
|
||
mod tests {
|
||
use super::*;
|
||
use crate::model::SourceRef;
|
||
use crate::rules::seed_rule_set;
|
||
use std::sync::Arc;
|
||
|
||
fn analyzer(opts: AnalyzeOptions) -> Analyzer {
|
||
Analyzer::new(RuleEngine::new(seed_rule_set()), opts)
|
||
}
|
||
|
||
fn event(message: &str, level: Option<LogLevel>, ts: Option<&str>) -> LogEvent {
|
||
LogEvent {
|
||
timestamp: ts.map(|t| DateTime::parse_from_rfc3339(t).expect("ts")),
|
||
level,
|
||
target: Some("rustfs::server::http".to_string()),
|
||
message: message.to_string(),
|
||
fields: serde_json::Map::new(),
|
||
source: SourceRef {
|
||
file: Arc::from("rustfs.log"),
|
||
line: 1,
|
||
},
|
||
node: None,
|
||
kind: EventKind::Json,
|
||
}
|
||
}
|
||
|
||
#[test]
|
||
fn normalize_template_collapses_variable_parts() {
|
||
assert_eq!(
|
||
normalize_template("upload 12/34 failed for /data/x9 after 5 retries"),
|
||
normalize_template("upload 7/9 failed for /mnt/disk1/obj after 2 retries"),
|
||
);
|
||
assert_eq!(
|
||
normalize_template("upload 12/34 failed for /data/x9 after 5 retries"),
|
||
"upload <n>/<n> failed for <path> after <n> retries"
|
||
);
|
||
assert_eq!(normalize_template("lock 'media/a.bin' timed out"), "lock '<q>' timed out");
|
||
assert_eq!(normalize_template("peer 10.0.0.2:9000 down"), "peer <addr> down");
|
||
}
|
||
|
||
#[test]
|
||
fn end_to_end_pipeline_produces_findings_and_clusters() {
|
||
let mut a = analyzer(AnalyzeOptions::default());
|
||
for i in 0..3 {
|
||
a.observe(event(
|
||
"erasure write quorum (required=8, achieved=5)",
|
||
Some(LogLevel::Error),
|
||
Some(&format!("2026-07-15T03:0{i}:00+08:00")),
|
||
));
|
||
}
|
||
for suffix in ["a", "b"] {
|
||
a.observe(event(
|
||
&format!("failed to sync /data/{suffix} after 5 retries"),
|
||
Some(LogLevel::Error),
|
||
Some("2026-07-15T03:05:00+08:00"),
|
||
));
|
||
}
|
||
a.observe(event("request ok", Some(LogLevel::Info), Some("2026-07-15T03:06:00+08:00")));
|
||
|
||
let report = a.finalize(IngestReport::default());
|
||
assert_eq!(report.summary.events_total, 6);
|
||
assert_eq!(report.summary.events_after_filter, 6);
|
||
assert_eq!(report.summary.level_counts["ERROR"], 5);
|
||
assert_eq!(report.findings.len(), 1);
|
||
assert_eq!(report.findings[0].rule_id, "ec-write-quorum");
|
||
assert_eq!(report.findings[0].count, 3);
|
||
assert_eq!(report.unmatched_top.len(), 1);
|
||
assert_eq!(report.unmatched_top[0].count, 2);
|
||
assert_eq!(report.unmatched_top[0].template, "failed to sync <path> after <n> retries");
|
||
assert_eq!(report.summary.distinct_offsets, vec!["+08:00"]);
|
||
}
|
||
|
||
#[test]
|
||
fn disjoint_node_ranges_are_flagged() {
|
||
let mut a = analyzer(AnalyzeOptions::default());
|
||
// node1: 101 events across 00:00-01:40; node2: 101 events across
|
||
// 03:00-04:40 — completely disjoint windows, both sizable.
|
||
for (node, base_hour) in [("node1", 0), ("node2", 3)] {
|
||
for i in 0..101 {
|
||
let mut ev = event(
|
||
"request ok",
|
||
Some(LogLevel::Info),
|
||
Some(&format!("2026-07-15T{:02}:{:02}:00Z", base_hour + i / 60, i % 60)),
|
||
);
|
||
ev.node = Some(Arc::from(node));
|
||
a.observe(ev);
|
||
}
|
||
}
|
||
let report = a.finalize(IngestReport::default());
|
||
let disjoint: Vec<_> = report
|
||
.timeline_anomalies
|
||
.iter()
|
||
.filter(|a| a.kind == "node_ranges_disjoint")
|
||
.collect();
|
||
assert_eq!(disjoint.len(), 1, "{:?}", report.timeline_anomalies);
|
||
assert_eq!(disjoint[0].nodes, vec!["node1".to_string(), "node2".to_string()]);
|
||
assert!(disjoint[0].message.contains("完全不重叠"));
|
||
|
||
// Below the >100-events bar the heuristic stays quiet.
|
||
let mut a = analyzer(AnalyzeOptions::default());
|
||
for (node, hour) in [("node1", 0), ("node2", 3)] {
|
||
for i in 0..5 {
|
||
let mut ev = event("request ok", Some(LogLevel::Info), Some(&format!("2026-07-15T0{hour}:0{i}:00Z")));
|
||
ev.node = Some(Arc::from(node));
|
||
a.observe(ev);
|
||
}
|
||
}
|
||
let report = a.finalize(IngestReport::default());
|
||
assert!(report.timeline_anomalies.iter().all(|a| a.kind != "node_ranges_disjoint"));
|
||
}
|
||
|
||
#[test]
|
||
fn log_gap_is_flagged_and_upgrades_on_startup_finding() {
|
||
let mut a = analyzer(AnalyzeOptions::default());
|
||
// 4 consecutive active minutes, a 40min hole, then activity again.
|
||
for minute in 0..4 {
|
||
a.observe(event("x", Some(LogLevel::Error), Some(&format!("2026-07-15T03:0{minute}:00Z"))));
|
||
}
|
||
a.observe(event(
|
||
"[FATAL] Observability initialization failed: collector unavailable",
|
||
Some(LogLevel::Error),
|
||
Some("2026-07-15T03:44:30Z"),
|
||
));
|
||
let report = a.finalize(IngestReport::default());
|
||
let gaps: Vec<_> = report.timeline_anomalies.iter().filter(|a| a.kind == "log_gap").collect();
|
||
assert_eq!(gaps.len(), 1, "{:?}", report.timeline_anomalies);
|
||
assert!(gaps[0].restart_evidence, "startup-fatal right after the gap: {:?}", gaps[0]);
|
||
assert!(gaps[0].message.contains("重启证据"));
|
||
assert_eq!(gaps[0].gap_start.expect("start").to_rfc3339(), "2026-07-15T03:04:00+00:00");
|
||
assert_eq!(gaps[0].gap_end.expect("end").to_rfc3339(), "2026-07-15T03:44:00+00:00");
|
||
|
||
// Same hole but no startup finding afterwards: still a gap, no upgrade.
|
||
let mut a = analyzer(AnalyzeOptions::default());
|
||
for minute in 0..4 {
|
||
a.observe(event("x", Some(LogLevel::Error), Some(&format!("2026-07-15T03:0{minute}:00Z"))));
|
||
}
|
||
a.observe(event("x", Some(LogLevel::Error), Some("2026-07-15T03:44:30Z")));
|
||
let report = a.finalize(IngestReport::default());
|
||
let gaps: Vec<_> = report.timeline_anomalies.iter().filter(|a| a.kind == "log_gap").collect();
|
||
assert_eq!(gaps.len(), 1);
|
||
assert!(!gaps[0].restart_evidence);
|
||
assert!(gaps[0].message.contains("疑似进程重启或挂起"));
|
||
|
||
// A short 3-minute lull is not a gap.
|
||
let mut a = analyzer(AnalyzeOptions::default());
|
||
for minute in 0..4 {
|
||
a.observe(event("x", Some(LogLevel::Error), Some(&format!("2026-07-15T03:0{minute}:00Z"))));
|
||
}
|
||
a.observe(event("x", Some(LogLevel::Error), Some("2026-07-15T03:07:00Z")));
|
||
let report = a.finalize(IngestReport::default());
|
||
assert!(report.timeline_anomalies.iter().all(|a| a.kind != "log_gap"));
|
||
}
|
||
|
||
#[test]
|
||
fn mixed_offsets_anomaly_requires_multiple_offsets() {
|
||
// Single offset: quiet.
|
||
let mut a = analyzer(AnalyzeOptions::default());
|
||
a.observe(event("x", Some(LogLevel::Error), Some("2026-07-15T03:00:00+08:00")));
|
||
a.observe(event("x", Some(LogLevel::Error), Some("2026-07-15T04:00:00+08:00")));
|
||
let report = a.finalize(IngestReport::default());
|
||
assert!(report.timeline_anomalies.iter().all(|a| a.kind != "mixed_offsets"));
|
||
|
||
// Mixed offsets plus a signature finding: flagged with the clock note.
|
||
let mut a = analyzer(AnalyzeOptions::default());
|
||
a.observe(event("x", Some(LogLevel::Error), Some("2026-07-15T03:00:00+08:00")));
|
||
a.observe(event("SignatureDoesNotMatch", Some(LogLevel::Error), Some("2026-07-15T03:00:00Z")));
|
||
let report = a.finalize(IngestReport::default());
|
||
let mixed: Vec<_> = report
|
||
.timeline_anomalies
|
||
.iter()
|
||
.filter(|a| a.kind == "mixed_offsets")
|
||
.collect();
|
||
assert_eq!(mixed.len(), 1);
|
||
assert!(mixed[0].message.contains("+08:00"));
|
||
assert!(mixed[0].message.contains("签名不匹配"), "signature note missing: {}", mixed[0].message);
|
||
}
|
||
|
||
#[test]
|
||
fn causal_collapse_folds_quorum_under_disk_faulty() {
|
||
let mut a = analyzer(AnalyzeOptions::default());
|
||
// Root: disk faulty at t0 (P2). Symptom: write quorum at t0+2min (P1).
|
||
for minute in [0, 1] {
|
||
a.observe(event(
|
||
"Disk health check marked disk faulty",
|
||
Some(LogLevel::Error),
|
||
Some(&format!("2026-07-15T03:0{minute}:00+08:00")),
|
||
));
|
||
}
|
||
for second in 0..3 {
|
||
a.observe(event(
|
||
"erasure write quorum (required=8, achieved=5)",
|
||
Some(LogLevel::Error),
|
||
Some(&format!("2026-07-15T03:02:0{second}+08:00")),
|
||
));
|
||
}
|
||
let report = a.finalize(IngestReport::default());
|
||
|
||
let quorum = report
|
||
.findings
|
||
.iter()
|
||
.find(|f| f.rule_id == "ec-write-quorum")
|
||
.expect("quorum");
|
||
assert_eq!(quorum.collapsed_into.as_deref(), Some("disk-marked-faulty"));
|
||
let disk = report
|
||
.findings
|
||
.iter()
|
||
.find(|f| f.rule_id == "disk-marked-faulty")
|
||
.expect("disk");
|
||
assert_eq!(disk.caused, vec!["ec-write-quorum".to_string()]);
|
||
// The P2 root is promoted to the collapsed P1 symptom's position.
|
||
assert_eq!(report.findings[0].rule_id, "disk-marked-faulty");
|
||
|
||
let mut out = Vec::new();
|
||
crate::report::render(&report, crate::report::ReportFormat::Text, &mut out).expect("render");
|
||
let text = String::from_utf8(out).expect("utf8");
|
||
assert!(text.contains("级联症状: ec-write-quorum ×3"), "missing cascade line:\n{text}");
|
||
assert!(
|
||
!text.contains("[P1 服务不可用] ec-write-quorum"),
|
||
"collapsed symptom must not render flat:\n{text}"
|
||
);
|
||
}
|
||
|
||
#[test]
|
||
fn causal_collapse_respects_the_time_window() {
|
||
let mut a = analyzer(AnalyzeOptions::default());
|
||
// Root appears 2h AFTER the symptom: outside the 5min precedence window.
|
||
a.observe(event(
|
||
"erasure write quorum (required=8, achieved=5)",
|
||
Some(LogLevel::Error),
|
||
Some("2026-07-15T03:00:00+08:00"),
|
||
));
|
||
a.observe(event(
|
||
"Disk health check marked disk faulty",
|
||
Some(LogLevel::Error),
|
||
Some("2026-07-15T05:00:00+08:00"),
|
||
));
|
||
let report = a.finalize(IngestReport::default());
|
||
let quorum = report
|
||
.findings
|
||
.iter()
|
||
.find(|f| f.rule_id == "ec-write-quorum")
|
||
.expect("quorum");
|
||
assert_eq!(quorum.collapsed_into, None);
|
||
assert!(report.findings.iter().all(|f| f.caused.is_empty()));
|
||
}
|
||
|
||
#[test]
|
||
fn causal_collapse_uses_existence_for_timestamp_less_roots() {
|
||
let mut a = analyzer(AnalyzeOptions::default());
|
||
a.observe(event(
|
||
"rwlock IAM cache poisoned, recovering",
|
||
Some(LogLevel::Error),
|
||
Some("2026-07-15T03:00:00+08:00"),
|
||
));
|
||
let mut panic_ev = event("thread 'main' panicked at src/main.rs:1:1: boom", Some(LogLevel::Error), None);
|
||
panic_ev.kind = EventKind::Panic;
|
||
a.observe(panic_ev);
|
||
|
||
let report = a.finalize(IngestReport::default());
|
||
let poisoned = report
|
||
.findings
|
||
.iter()
|
||
.find(|f| f.rule_id == "rwlock-poisoned")
|
||
.expect("poisoned");
|
||
assert_eq!(poisoned.collapsed_into.as_deref(), Some("process-panic"));
|
||
let panic = report.findings.iter().find(|f| f.rule_id == "process-panic").expect("panic");
|
||
assert_eq!(panic.caused, vec!["rwlock-poisoned".to_string()]);
|
||
}
|
||
|
||
#[test]
|
||
fn json_keeps_collapsed_findings_with_relation_fields() {
|
||
let mut a = analyzer(AnalyzeOptions::default());
|
||
a.observe(event(
|
||
"Disk health check marked disk faulty",
|
||
Some(LogLevel::Error),
|
||
Some("2026-07-15T03:00:00+08:00"),
|
||
));
|
||
a.observe(event(
|
||
"erasure write quorum (required=8, achieved=5)",
|
||
Some(LogLevel::Error),
|
||
Some("2026-07-15T03:02:00+08:00"),
|
||
));
|
||
let report = a.finalize(IngestReport::default());
|
||
let value = serde_json::to_value(&report).expect("json");
|
||
let findings = value["findings"].as_array().expect("array");
|
||
let ids: Vec<&str> = findings.iter().map(|f| f["rule_id"].as_str().expect("id")).collect();
|
||
assert!(ids.contains(&"ec-write-quorum"), "collapsed finding stays in JSON: {ids:?}");
|
||
let quorum = findings.iter().find(|f| f["rule_id"] == "ec-write-quorum").expect("quorum");
|
||
assert_eq!(quorum["collapsed_into"], "disk-marked-faulty");
|
||
let disk = findings.iter().find(|f| f["rule_id"] == "disk-marked-faulty").expect("disk");
|
||
assert_eq!(disk["caused"][0], "ec-write-quorum");
|
||
}
|
||
|
||
#[test]
|
||
fn unmatched_cluster_representative_is_order_independent() {
|
||
let mk = |msg: &str, target: &str| {
|
||
let mut ev = event(msg, Some(LogLevel::Error), None);
|
||
ev.target = Some(target.to_string());
|
||
ev
|
||
};
|
||
// Same template, different messages and targets.
|
||
let a = mk("failed to sync /data/a after 5 retries", "rustfs::sync::a");
|
||
let b = mk("failed to sync /data/b after 2 retries", "rustfs::sync::b");
|
||
|
||
let representative = |events: &[&LogEvent]| {
|
||
let mut an = analyzer(AnalyzeOptions::default());
|
||
for ev in events {
|
||
an.observe((*ev).clone());
|
||
}
|
||
let report = an.finalize(IngestReport::default());
|
||
let cluster = &report.unmatched_top[0];
|
||
(cluster.sample.clone(), cluster.target.clone())
|
||
};
|
||
let forward = representative(&[&a, &b]);
|
||
let reverse = representative(&[&b, &a]);
|
||
assert_eq!(forward, reverse);
|
||
// Sample and target must come from the same event.
|
||
assert_eq!(forward.0, "failed to sync /data/a after 5 retries");
|
||
assert_eq!(forward.1.as_deref(), Some("rustfs::sync::a"));
|
||
}
|
||
|
||
#[test]
|
||
fn since_until_filters_timestamped_events_only() {
|
||
let mut a = analyzer(AnalyzeOptions {
|
||
since: Some(DateTime::parse_from_rfc3339("2026-07-15T03:00:00+08:00").expect("ts")),
|
||
..Default::default()
|
||
});
|
||
a.observe(event("Disk full", Some(LogLevel::Error), Some("2026-07-15T02:00:00+08:00")));
|
||
a.observe(event("Disk full", Some(LogLevel::Error), Some("2026-07-15T04:00:00+08:00")));
|
||
let mut panic_ev = event("thread 'main' panicked at src/main.rs:1:1: boom", Some(LogLevel::Error), None);
|
||
panic_ev.kind = EventKind::Panic;
|
||
a.observe(panic_ev);
|
||
|
||
let report = a.finalize(IngestReport::default());
|
||
assert_eq!(report.summary.events_total, 3);
|
||
assert_eq!(report.summary.events_after_filter, 2);
|
||
let ids: Vec<_> = report.findings.iter().map(|f| f.rule_id.as_str()).collect();
|
||
assert!(ids.contains(&"disk-full"));
|
||
assert!(ids.contains(&"process-panic"), "timestamp-less panic must survive --since");
|
||
assert_eq!(report.findings.iter().find(|f| f.rule_id == "disk-full").expect("f").count, 1);
|
||
}
|
||
|
||
#[test]
|
||
fn timeline_buckets_are_gap_filled_and_merged() {
|
||
let mut a = analyzer(AnalyzeOptions::default());
|
||
// 10h span -> 15m buckets (600/15 = 40 <= 60).
|
||
a.observe(event("x", Some(LogLevel::Error), Some("2026-07-15T00:00:30Z")));
|
||
a.observe(event("x", Some(LogLevel::Warn), Some("2026-07-15T10:00:30Z")));
|
||
let report = a.finalize(IngestReport::default());
|
||
assert_eq!(report.timeline.len(), 41);
|
||
assert_eq!(report.timeline[0].error, 1);
|
||
assert_eq!(report.timeline.last().expect("last").warn, 1);
|
||
assert!(report.timeline[1..40].iter().all(|b| b.error + b.warn + b.other == 0));
|
||
|
||
// Single event -> a single 1m bucket.
|
||
let mut a = analyzer(AnalyzeOptions::default());
|
||
a.observe(event("x", Some(LogLevel::Error), Some("2026-07-15T00:00:30Z")));
|
||
assert_eq!(a.finalize(IngestReport::default()).timeline.len(), 1);
|
||
}
|
||
|
||
#[test]
|
||
fn redaction_hashes_identifiers_consistently() {
|
||
let make = |redact: bool| {
|
||
let mut a = analyzer(AnalyzeOptions {
|
||
redact,
|
||
..Default::default()
|
||
});
|
||
let mut ev = event(
|
||
"erasure write quorum (required=8) peer 10.0.0.2:9000",
|
||
Some(LogLevel::Error),
|
||
Some("2026-07-15T03:00:00+08:00"),
|
||
);
|
||
ev.fields
|
||
.insert("bucket".to_string(), serde_json::Value::String("media".into()));
|
||
a.observe(ev.clone());
|
||
a.observe(ev);
|
||
a.finalize(IngestReport::default())
|
||
};
|
||
|
||
let plain = make(false);
|
||
let sample = &plain.findings[0].samples[0];
|
||
assert!(sample.message.contains("10.0.0.2"));
|
||
assert_eq!(sample.field_str("bucket"), Some("media"));
|
||
|
||
let redacted = make(true);
|
||
let sample = &redacted.findings[0].samples[0];
|
||
assert!(!sample.message.contains("10.0.0.2"));
|
||
let hashed = sample.field_str("bucket").expect("bucket").to_string();
|
||
assert!(hashed.starts_with("h:"));
|
||
// Same value -> same hash across samples.
|
||
assert_eq!(redacted.findings[0].samples[1].field_str("bucket"), Some(hashed.as_str()));
|
||
}
|
||
|
||
#[test]
|
||
fn redaction_covers_evidence_provenance_node_and_template() {
|
||
let mut a = analyzer(AnalyzeOptions {
|
||
redact: true,
|
||
..Default::default()
|
||
});
|
||
|
||
// Matched rule that captures a `peer` evidence field (not a whitelisted
|
||
// name before the fix), on a customer node label + provenance path,
|
||
// with an IPv6 peer in the message.
|
||
let mut ev = event(
|
||
"peer_connection_marked_offline dial fe80::dead:9 failed",
|
||
Some(LogLevel::Error),
|
||
Some("2026-07-15T03:00:00+08:00"),
|
||
);
|
||
ev.fields
|
||
.insert("peer".into(), serde_json::Value::String("10.0.0.99:9000".into()));
|
||
ev.node = Some(Arc::from("prod-node-01"));
|
||
ev.source = SourceRef {
|
||
file: Arc::from("/home/acme-corp/bundle/prod-node-01/rustfs.log"),
|
||
line: 42,
|
||
};
|
||
a.observe(ev);
|
||
|
||
// Unmatched ERROR whose message carries a field-shaped bucket name.
|
||
let mut un = event("GetObject failed bucket: topsecret down", Some(LogLevel::Error), None);
|
||
un.node = Some(Arc::from("prod-node-01"));
|
||
a.observe(un);
|
||
|
||
let report = a.finalize(IngestReport::default());
|
||
let mut out = Vec::new();
|
||
crate::report::render(&report, crate::report::ReportFormat::Text, &mut out).expect("render");
|
||
let text = String::from_utf8(out).expect("utf8");
|
||
|
||
assert!(!text.contains("10.0.0.99"), "peer evidence leaked:\n{text}");
|
||
assert!(!text.contains("fe80::dead"), "IPv6 in sample leaked:\n{text}");
|
||
assert!(!text.contains("prod-node-01"), "node label leaked:\n{text}");
|
||
assert!(!text.contains("acme-corp"), "provenance prefix leaked:\n{text}");
|
||
assert!(!text.contains("topsecret"), "unmatched template bucket leaked:\n{text}");
|
||
// Node stays correlatable via a stable hash.
|
||
assert_eq!(report.summary.nodes.len(), 1);
|
||
assert!(report.summary.nodes[0].starts_with("h:"), "node not hashed: {:?}", report.summary.nodes);
|
||
// The JSON renderer dumps the whole sample event — it must not leak the
|
||
// raw peer field either.
|
||
let mut jout = Vec::new();
|
||
crate::report::render(&report, crate::report::ReportFormat::Json, &mut jout).expect("json");
|
||
let json = String::from_utf8(jout).expect("utf8");
|
||
assert!(!json.contains("10.0.0.99"), "JSON fields dump leaked peer:\n{json}");
|
||
assert!(!json.contains("prod-node-01"), "JSON leaked node:\n{json}");
|
||
}
|
||
|
||
#[test]
|
||
fn mixed_offsets_are_reported() {
|
||
let mut a = analyzer(AnalyzeOptions::default());
|
||
a.observe(event("x", Some(LogLevel::Error), Some("2026-07-15T03:00:00+08:00")));
|
||
a.observe(event("x", Some(LogLevel::Error), Some("2026-07-15T03:00:00Z")));
|
||
let report = a.finalize(IngestReport::default());
|
||
assert_eq!(report.summary.distinct_offsets, vec!["+08:00", "Z"]);
|
||
}
|
||
|
||
#[test]
|
||
fn empty_input_produces_a_renderable_report() {
|
||
let report = analyzer(AnalyzeOptions::default()).finalize(IngestReport::default());
|
||
assert_eq!(report.summary.events_total, 0);
|
||
assert!(report.findings.is_empty());
|
||
assert!(report.timeline.is_empty());
|
||
assert!(serde_json::to_string(&report).is_ok());
|
||
}
|
||
|
||
#[test]
|
||
fn low_confidence_findings_are_split_out() {
|
||
let mut a = analyzer(AnalyzeOptions::default());
|
||
// client-signature-mismatch has min_count 10; feed 3.
|
||
for _ in 0..3 {
|
||
a.observe(event("SignatureDoesNotMatch", Some(LogLevel::Error), None));
|
||
}
|
||
let report = a.finalize(IngestReport::default());
|
||
assert!(report.findings.is_empty());
|
||
assert_eq!(report.low_confidence.len(), 1);
|
||
assert_eq!(report.low_confidence[0].rule_id, "client-signature-mismatch");
|
||
}
|
||
}
|