fix(log): compact consecutive repeated diagnostics
Group identical redacted diagnostics across stderr, file and the live ring. Flush repeat summaries on visible transitions, exports and shutdown while keeping periodic counts for sustained bursts. cx
This commit is contained in:
8 files changed
+345
-26
No files matched your search
@@ -4,7 +4,6 @@ use std::fs::File;
|
||||
use std::io::BufWriter;
|
||||
use std::path::PathBuf;
|
||||
use std::sync::atomic::{AtomicBool, Ordering};
|
||||
use std::sync::Mutex;
|
||||
|
||||
use crate::tee::TeeLogger;
|
||||
|
||||
@@ -29,15 +28,16 @@ pub fn install(default_level: &str) {
|
||||
// in #555 logs) — and each suppressed record now costs nothing, since
|
||||
// `log!` checks the filter before formatting. An explicit RUST_LOG still
|
||||
// replaces the whole default, so full zbus tracing stays one env var away.
|
||||
let inner = env_logger::Builder::from_env(env_logger::Env::default().default_filter_or(
|
||||
format!("{default_level},zbus=warn,tracing=warn"),
|
||||
))
|
||||
let inner = env_logger::Builder::from_env(
|
||||
env_logger::Env::default()
|
||||
.default_filter_or(format!("{default_level},zbus=warn,tracing=warn")),
|
||||
)
|
||||
.build();
|
||||
let level = inner.filter();
|
||||
let file = open_log_file();
|
||||
|
||||
// Ignore the Err if a logger was somehow already set elsewhere.
|
||||
if log::set_boxed_logger(Box::new(TeeLogger { inner, file })).is_ok() {
|
||||
if log::set_boxed_logger(Box::new(TeeLogger::new(inner, file))).is_ok() {
|
||||
log::set_max_level(level);
|
||||
}
|
||||
}
|
||||
@@ -54,7 +54,7 @@ pub fn log_file_path() -> Option<PathBuf> {
|
||||
|
||||
/// Open the log file for this run, rotating any previous one to `qbz.log.prev`.
|
||||
/// Returns `None` (file sink disabled, gracefully) on any filesystem error.
|
||||
fn open_log_file() -> Option<Mutex<BufWriter<File>>> {
|
||||
fn open_log_file() -> Option<BufWriter<File>> {
|
||||
let path = log_file_path()?;
|
||||
let dir = path.parent()?;
|
||||
std::fs::create_dir_all(dir).ok()?;
|
||||
@@ -66,5 +66,5 @@ fn open_log_file() -> Option<Mutex<BufWriter<File>>> {
|
||||
}
|
||||
|
||||
let file = File::create(&path).ok()?;
|
||||
Some(Mutex::new(BufWriter::new(file)))
|
||||
Some(BufWriter::new(file))
|
||||
}
|
||||
@@ -1,13 +1,17 @@
|
||||
//! `qbz-log` — frontend-agnostic logging core for the qbz desktop client.
|
||||
//!
|
||||
//! It owns a composite [`log::Log`] implementation ([`tee::TeeLogger`]) that wraps
|
||||
//! `env_logger`'s built `Logger` and fans every record out to three sinks:
|
||||
//! `env_logger`'s built `Logger` and fans visible records out to three sinks:
|
||||
//! 1. **stderr** (redacted text, same line format as the file sink),
|
||||
//! 2. a bounded **in-memory ring** ([`ring`], cap [`ring::RING_CAP`]), and
|
||||
//! 3. an **on-disk file** (`~/.local/share/qbz/logs/qbz.log`, prev-rotated at startup).
|
||||
//!
|
||||
//! Secret **redaction** ([`redact`]) is applied once at the single write choke point,
|
||||
//! so every downstream consumer (stderr, ring, file, clipboard, paste upload) gets clean text.
|
||||
//! Consecutive identical redacted records retain their first line and periodic
|
||||
//! count/duration summaries; any different visible record ends the run. All three
|
||||
//! sinks receive the same serialized sequence. Call `log::logger().flush()` before
|
||||
//! normal exit to emit a final pending summary and flush the file.
|
||||
//!
|
||||
//! This crate is network-free and UI-free: no `reqwest`, no `tokio`, no `slint`.
|
||||
|
||||
@@ -15,6 +19,7 @@ pub mod bundle;
|
||||
pub mod install;
|
||||
pub mod line;
|
||||
pub mod redact;
|
||||
mod repeat;
|
||||
pub mod ring;
|
||||
pub mod tee;
|
||||
|
||||
|
||||
@@ -0,0 +1,263 @@
|
||||
//! One bounded run of consecutive, already-redacted log records.
|
||||
|
||||
use std::time::{Duration, Instant};
|
||||
|
||||
use crate::line::LogLine;
|
||||
|
||||
/// Continuing bursts remain visible without printing every duplicate.
|
||||
const SUMMARY_INTERVAL: Duration = Duration::from_secs(5);
|
||||
|
||||
#[derive(Default)]
|
||||
pub(crate) struct ConsecutiveRecords {
|
||||
current: Option<RepeatRun>,
|
||||
}
|
||||
|
||||
struct RepeatRun {
|
||||
line: LogLine,
|
||||
period_started: Instant,
|
||||
last_seen: Instant,
|
||||
repeats: u64,
|
||||
}
|
||||
|
||||
impl RepeatRun {
|
||||
fn matches(&self, line: &LogLine) -> bool {
|
||||
self.line.level == line.level
|
||||
&& self.line.target == line.target
|
||||
&& self.line.message == line.message
|
||||
}
|
||||
|
||||
fn summary(&self) -> Option<LogLine> {
|
||||
(self.repeats > 0).then(|| LogLine {
|
||||
ts: self.line.ts,
|
||||
level: self.line.level,
|
||||
target: self.line.target.clone(),
|
||||
message: format!(
|
||||
"[log] previous message repeated {} additional times over {} ms: {}",
|
||||
self.repeats,
|
||||
self.last_seen
|
||||
.saturating_duration_since(self.period_started)
|
||||
.as_millis(),
|
||||
self.line.message,
|
||||
),
|
||||
})
|
||||
}
|
||||
}
|
||||
|
||||
impl ConsecutiveRecords {
|
||||
/// Accept only visible, already-redacted records. The caller serializes this
|
||||
/// state transition AND its output to every sink under the same lock.
|
||||
/// Output is at most the previous summary followed by the new record.
|
||||
pub(crate) fn push(&mut self, line: LogLine, now: Instant) -> [Option<LogLine>; 2] {
|
||||
if let Some(run) = self.current.as_mut().filter(|run| run.matches(&line)) {
|
||||
run.line.ts = line.ts;
|
||||
run.last_seen = now;
|
||||
run.repeats = run.repeats.saturating_add(1);
|
||||
if now.saturating_duration_since(run.period_started) >= SUMMARY_INTERVAL {
|
||||
let summary = run.summary();
|
||||
run.repeats = 0;
|
||||
run.period_started = now;
|
||||
return [summary, None];
|
||||
}
|
||||
return [None, None];
|
||||
}
|
||||
|
||||
let summary = self.flush();
|
||||
self.current = Some(RepeatRun {
|
||||
line: line.clone(),
|
||||
period_started: now,
|
||||
last_seen: now,
|
||||
repeats: 0,
|
||||
});
|
||||
[summary, Some(line)]
|
||||
}
|
||||
|
||||
/// Flush ends the run, so the next record is always visible in full.
|
||||
pub(crate) fn flush(&mut self) -> Option<LogLine> {
|
||||
self.current.take().and_then(|run| run.summary())
|
||||
}
|
||||
}
|
||||
|
||||
#[cfg(test)]
|
||||
mod tests {
|
||||
use super::*;
|
||||
use log::Level;
|
||||
|
||||
fn line(ts: i64, level: Level, target: &str, message: &str) -> LogLine {
|
||||
LogLine {
|
||||
ts,
|
||||
level,
|
||||
target: target.into(),
|
||||
message: message.into(),
|
||||
}
|
||||
}
|
||||
|
||||
fn info(ts: i64, message: &str) -> LogLine {
|
||||
line(ts, Level::Info, "qbz", message)
|
||||
}
|
||||
|
||||
fn messages(lines: [Option<LogLine>; 2]) -> Vec<String> {
|
||||
lines
|
||||
.into_iter()
|
||||
.flatten()
|
||||
.map(|line| line.message)
|
||||
.collect()
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn first_record_is_visible_and_consecutive_duplicates_are_counted() {
|
||||
let mut records = ConsecutiveRecords::default();
|
||||
let start = Instant::now();
|
||||
assert_eq!(
|
||||
messages(records.push(info(0, "loop mode"), start)),
|
||||
["loop mode"]
|
||||
);
|
||||
for ms in [90, 180, 270] {
|
||||
assert!(messages(records.push(
|
||||
info(ms, "loop mode"),
|
||||
start + Duration::from_millis(ms as u64),
|
||||
))
|
||||
.is_empty());
|
||||
}
|
||||
let output = records.push(
|
||||
info(300, "renderer changed"),
|
||||
start + Duration::from_millis(300),
|
||||
);
|
||||
assert_eq!(output[0].as_ref().unwrap().ts, 270);
|
||||
assert_eq!(
|
||||
messages(output),
|
||||
[
|
||||
"[log] previous message repeated 3 additional times over 270 ms: loop mode",
|
||||
"renderer changed",
|
||||
]
|
||||
);
|
||||
assert_eq!(
|
||||
messages(records.push(info(400, "loop mode"), start + Duration::from_millis(400))),
|
||||
["loop mode"]
|
||||
);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn level_and_target_changes_end_the_run_even_with_identical_text() {
|
||||
for (level, target) in [(Level::Warn, "qbz"), (Level::Info, "qconnect")] {
|
||||
let mut records = ConsecutiveRecords::default();
|
||||
let start = Instant::now();
|
||||
records.push(info(0, "same"), start);
|
||||
records.push(info(1, "same"), start + Duration::from_millis(1));
|
||||
let output = records.push(
|
||||
line(2, level, target, "same"),
|
||||
start + Duration::from_millis(2),
|
||||
);
|
||||
let summary = output[0].as_ref().unwrap();
|
||||
assert_eq!(summary.level, Level::Info);
|
||||
assert_eq!(summary.target, "qbz");
|
||||
let changed = output[1].as_ref().unwrap();
|
||||
assert_eq!(changed.level, level);
|
||||
assert_eq!(changed.target, target);
|
||||
assert_eq!(changed.message, "same");
|
||||
}
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn warning_and_error_runs_preserve_severity_and_counts() {
|
||||
for level in [Level::Warn, Level::Error] {
|
||||
let mut records = ConsecutiveRecords::default();
|
||||
let start = Instant::now();
|
||||
let output = records.push(line(0, level, "qbz", "failed"), start);
|
||||
assert_eq!(output[1].as_ref().unwrap().level, level);
|
||||
records.push(
|
||||
line(10, level, "qbz", "failed"),
|
||||
start + Duration::from_millis(10),
|
||||
);
|
||||
let summary = records.flush().unwrap();
|
||||
assert_eq!(summary.level, level);
|
||||
assert_eq!(
|
||||
summary.message,
|
||||
"[log] previous message repeated 1 additional times over 10 ms: failed"
|
||||
);
|
||||
}
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn periodic_summaries_count_only_new_repetitions_and_retain_the_key() {
|
||||
let mut records = ConsecutiveRecords::default();
|
||||
let start = Instant::now();
|
||||
records.push(info(0, "busy"), start);
|
||||
for second in 1..=11 {
|
||||
let output = messages(records.push(
|
||||
info(second * 1000, "busy"),
|
||||
start + Duration::from_secs(second as u64),
|
||||
));
|
||||
if second % 5 == 0 {
|
||||
assert_eq!(
|
||||
output,
|
||||
["[log] previous message repeated 5 additional times over 5000 ms: busy"]
|
||||
);
|
||||
} else {
|
||||
assert!(output.is_empty());
|
||||
}
|
||||
}
|
||||
assert_eq!(
|
||||
records.flush().unwrap().message,
|
||||
"[log] previous message repeated 1 additional times over 1000 ms: busy"
|
||||
);
|
||||
assert!(records.flush().is_none());
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn flush_resets_the_run_and_does_not_invent_duplicates() {
|
||||
let mut records = ConsecutiveRecords::default();
|
||||
let start = Instant::now();
|
||||
assert!(records.flush().is_none());
|
||||
records.push(info(0, "a"), start);
|
||||
assert!(records.flush().is_none());
|
||||
assert_eq!(messages(records.push(info(1, "a"), start)), ["a"]);
|
||||
records.push(info(2, "a"), start);
|
||||
assert!(records.flush().is_some());
|
||||
assert_eq!(messages(records.push(info(3, "a"), start)), ["a"]);
|
||||
assert_eq!(messages(records.push(info(4, "b"), start)), ["b"]);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn different_record_after_periodic_summary_does_not_repeat_the_count() {
|
||||
let mut records = ConsecutiveRecords::default();
|
||||
let start = Instant::now();
|
||||
records.push(info(0, "a"), start);
|
||||
let output = records.push(info(5000, "a"), start + Duration::from_secs(5));
|
||||
assert_eq!(messages(output).len(), 1);
|
||||
assert_eq!(
|
||||
messages(records.push(info(5001, "b"), start + Duration::from_millis(5001))),
|
||||
["b"]
|
||||
);
|
||||
assert!(records.flush().is_none());
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn duration_is_monotonic_and_ends_at_last_duplicate_not_later_message() {
|
||||
let mut records = ConsecutiveRecords::default();
|
||||
let start = Instant::now();
|
||||
records.push(info(1000, "a"), start);
|
||||
// A wall-clock correction must not produce a negative or giant interval.
|
||||
records.push(info(500, "a"), start + Duration::from_millis(90));
|
||||
let output = records.push(info(9000, "b"), start + Duration::from_secs(10));
|
||||
let summary = output[0].as_ref().unwrap();
|
||||
assert_eq!(summary.ts, 500);
|
||||
assert_eq!(
|
||||
summary.message,
|
||||
"[log] previous message repeated 1 additional times over 90 ms: a"
|
||||
);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn redacted_records_share_a_key_without_retaining_raw_secrets() {
|
||||
let mut records = ConsecutiveRecords::default();
|
||||
let start = Instant::now();
|
||||
let first = crate::redact("token=SEKRET_ONE");
|
||||
let second = crate::redact("token=SEKRET_TWO");
|
||||
assert_eq!(first, second);
|
||||
assert_eq!(messages(records.push(info(0, &first), start)), [first]);
|
||||
assert!(messages(records.push(info(1, &second), start)).is_empty());
|
||||
let summary = records.flush().unwrap();
|
||||
assert!(summary.message.contains("***REDACTED***"));
|
||||
assert!(!summary.message.contains("SEKRET"));
|
||||
}
|
||||
}
|
||||
+55
-18
@@ -3,18 +3,53 @@
|
||||
use std::fs::File;
|
||||
use std::io::{BufWriter, Write};
|
||||
use std::sync::Mutex;
|
||||
use std::time::Instant;
|
||||
|
||||
use log::{Log, Metadata, Record};
|
||||
|
||||
use crate::line::LogLine;
|
||||
use crate::repeat::ConsecutiveRecords;
|
||||
use crate::{redact, ring};
|
||||
|
||||
/// Wraps `env_logger`'s built `Logger` and tees every record to the in-memory ring and
|
||||
/// (optionally) the on-disk log file, with secret redaction applied once at this single
|
||||
/// write choke point. **All** sinks (ring, file, and stderr) receive the redacted text.
|
||||
/// Consecutive duplicate records are summarized with their original severity,
|
||||
/// target, redacted message, repetition count and monotonic elapsed time.
|
||||
pub struct TeeLogger {
|
||||
pub(crate) inner: env_logger::Logger,
|
||||
pub(crate) file: Option<Mutex<BufWriter<File>>>,
|
||||
inner: env_logger::Logger,
|
||||
// One lock covers grouping AND all sink writes: concurrent threads cannot
|
||||
// interleave a summary and its next record or reorder the file vs. the ring.
|
||||
output: Mutex<Output>,
|
||||
}
|
||||
|
||||
struct Output {
|
||||
file: Option<BufWriter<File>>,
|
||||
consecutive: ConsecutiveRecords,
|
||||
}
|
||||
|
||||
impl TeeLogger {
|
||||
pub(crate) fn new(inner: env_logger::Logger, file: Option<BufWriter<File>>) -> Self {
|
||||
Self {
|
||||
inner,
|
||||
output: Mutex::new(Output {
|
||||
file,
|
||||
consecutive: ConsecutiveRecords::default(),
|
||||
}),
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
impl Output {
|
||||
fn write(&mut self, line: LogLine) {
|
||||
let formatted = format_line(&line);
|
||||
ring::push(line);
|
||||
if let Some(writer) = &mut self.file {
|
||||
let _ = writeln!(writer, "{formatted}");
|
||||
}
|
||||
// Never delegate to inner.log(record): it would bypass redaction.
|
||||
let _ = writeln!(std::io::stderr(), "{formatted}");
|
||||
}
|
||||
}
|
||||
|
||||
fn now_epoch_ms() -> i64 {
|
||||
@@ -45,33 +80,35 @@ impl Log for TeeLogger {
|
||||
|
||||
// Redact ONCE; every downstream sink gets the cleaned text.
|
||||
let msg = redact::redact(&record.args().to_string());
|
||||
let mut output = self.output.lock().unwrap_or_else(|p| p.into_inner());
|
||||
let line = LogLine {
|
||||
ts: now_epoch_ms(),
|
||||
level: record.level(),
|
||||
target: record.target().to_owned(),
|
||||
message: msg.clone(),
|
||||
message: msg,
|
||||
};
|
||||
|
||||
ring::push(line.clone());
|
||||
|
||||
if let Some(file) = &self.file {
|
||||
if let Ok(mut writer) = file.lock() {
|
||||
let _ = writeln!(writer, "{}", format_line(&line));
|
||||
let [summary, first] = output.consecutive.push(line, Instant::now());
|
||||
let summarized = summary.is_some();
|
||||
for line in [summary, first].into_iter().flatten() {
|
||||
output.write(line);
|
||||
}
|
||||
// Compaction may no longer fill BufWriter for minutes. Make periodic
|
||||
// summaries visible to a live file tail as well as stderr/the ring.
|
||||
if summarized {
|
||||
if let Some(writer) = &mut output.file {
|
||||
let _ = writer.flush();
|
||||
}
|
||||
}
|
||||
|
||||
// stderr: write the redacted line ourselves. Delegating to
|
||||
// `self.inner.log(record)` would reprint the *original* Record args
|
||||
// and bypass redaction (terminal transcripts, CI logs, support dumps).
|
||||
let _ = writeln!(std::io::stderr(), "{}", format_line(&line));
|
||||
}
|
||||
|
||||
fn flush(&self) {
|
||||
self.inner.flush();
|
||||
if let Some(file) = &self.file {
|
||||
if let Ok(mut writer) = file.lock() {
|
||||
let _ = writer.flush();
|
||||
let mut output = self.output.lock().unwrap_or_else(|p| p.into_inner());
|
||||
if let Some(summary) = output.consecutive.flush() {
|
||||
output.write(summary);
|
||||
}
|
||||
self.inner.flush();
|
||||
if let Some(writer) = &mut output.file {
|
||||
let _ = writer.flush();
|
||||
}
|
||||
let _ = std::io::stderr().flush();
|
||||
}
|
||||
|
||||
@@ -202,6 +202,8 @@ pub fn set_auto_tail(on: bool) {
|
||||
/// The filtered view as plain redacted lines — what "Copy" puts on the
|
||||
/// clipboard.
|
||||
fn filtered_text() -> String {
|
||||
// Export the partial repeat count without resetting every auto-tail refresh.
|
||||
log::logger().flush();
|
||||
snapshot_doc()
|
||||
.rows
|
||||
.iter()
|
||||
@@ -237,6 +239,7 @@ pub fn copy_all() {
|
||||
/// takes the `log_upload` shape. The clipboard therefore lands one tick after
|
||||
/// the click.
|
||||
async fn bundle_text() -> String {
|
||||
log::logger().flush();
|
||||
let lines = qbz_log::ring::snapshot();
|
||||
let report = crate::diagnostics_qt::report_markdown().await;
|
||||
let fields = qbz_log::bundle::DiagFields {
|
||||
|
||||
@@ -3675,6 +3675,15 @@ pub(crate) fn arm_hard_exit_watchdog(source: &'static str) {
|
||||
|
||||
fn main() {
|
||||
qbz_log::install("info");
|
||||
// Declared first so normal/early returns flush after all later destructors,
|
||||
// including the final summary of a consecutive logging burst.
|
||||
struct FlushLogsOnExit;
|
||||
impl Drop for FlushLogsOnExit {
|
||||
fn drop(&mut self) {
|
||||
log::logger().flush();
|
||||
}
|
||||
}
|
||||
let _flush_logs = FlushLogsOnExit;
|
||||
cap_malloc_arenas();
|
||||
// Before even the disposable GPU-preflight QGuiApplication. A child
|
||||
// spawned later inherits the resolved factor and takes the same path.
|
||||
|
||||
@@ -913,6 +913,7 @@ fn diagnose_lock(e: LockError) -> String {
|
||||
eprintln!("error: qbzd is already running {who}");
|
||||
eprintln!(" → stop it first: systemctl --user stop qbzd");
|
||||
eprintln!(" → or inspect it: systemctl --user status qbzd");
|
||||
log::logger().flush();
|
||||
std::process::exit(3);
|
||||
}
|
||||
LockError::Io(msg) => {
|
||||
|
||||
@@ -566,6 +566,7 @@ async fn main() {
|
||||
tui::run(roots).await
|
||||
}
|
||||
};
|
||||
log::logger().flush();
|
||||
std::process::exit(code);
|
||||
}
|
||||
|
||||
|
||||
Reference in new issue
Block a user