fix(log): never rotate a log file another live process is writing; qbzd logs to qbzd.log

open_log_file_at renamed the live file to .prev on every open, so a second
qbz launch (the #749 two-line qbz.log) or a qbzd in the same directory took
the running process's log away. Writers now hold a shared advisory lock on
<name>.lock; an opener that cannot take it exclusively appends instead of
rotating. The daemon gets its own qbzd.log.

cc
This commit is contained in:
vicrodh committed 2026-09-13 03:36:50 -06:00
1 parent e9b02cdedb
commit d58fdf45b0
4 files changed
+163 -62

No files matched your search

+140 -56
View File
@@ -1,43 +1,52 @@
//! One-shot logger installation + the on-disk file sink (open / rotate).
use std::fs::File;
use std::fs::{File, OpenOptions, TryLockError};
use std::io::BufWriter;
use std::path::PathBuf;
use std::path::{Path, PathBuf};
use std::sync::atomic::{AtomicBool, Ordering};
use crate::tee::TeeLogger;
static INSTALLED: AtomicBool = AtomicBool::new(false);
/// Install the [`TeeLogger`] as the global `log` logger.
/// The desktop app's log file name.
pub const DEFAULT_LOG_FILE: &str = "qbz.log";
/// The on-disk sink plus the advisory lock that marks this process as a live
/// writer of that file (see [`open_log_file_at`]). Dropping it releases both.
pub(crate) struct FileSink {
pub(crate) writer: BufWriter<File>,
pub(crate) lock: Option<File>,
}
/// Install the [`TeeLogger`] as the global `log` logger, writing to
/// [`DEFAULT_LOG_FILE`].
///
/// Builds the inner `env_logger` logger from `RUST_LOG` (falling back to `default_level`),
/// opens/rotates the on-disk file, then sets the boxed logger + max level. Idempotent:
/// a second call is a guarded no-op (it neither rotates the file again nor panics).
pub fn install(default_level: &str) {
install_with_file_sink(default_level, true);
install_with_file_sink(default_level, Some(DEFAULT_LOG_FILE));
}
/// Same as [`install`], but to `file_name` inside the same logs directory.
/// `qbzd` uses `qbzd.log` so a daemon never shares (or rotates) the desktop
/// app's file.
pub fn install_named(default_level: &str, file_name: &str) {
install_with_file_sink(default_level, Some(file_name));
}
/// Same as [`install`], but with the on-disk file sink DISABLED (stderr + ring only).
///
/// For an internal, disposable child process that re-enters the same `main`.
/// [`open_log_file`] rotates `qbz.log` to `qbz.log.prev` and creates a fresh
/// file on every call, so a child running it MID-RUN renames the live log out
/// from under the parent — which keeps writing to the renamed inode — and
/// leaves `qbz.log` holding nothing but the child's own first lines.
///
/// Field-reported in #749: on Linux every launch spawns the presentation /
/// GPU preflight child, so `~/.local/share/qbz/logs/qbz.log` ended at two
/// lines on EVERY run while the app itself was healthy and its whole log went
/// to `qbz.log.prev`. The user's log file, the first thing a bug report
/// attaches, was structurally useless. A child's output is already captured
/// by the parent (proof line on stdout, `preflight_output_tail` on failure),
/// so it loses nothing by staying off the file.
/// For an internal, disposable child process that re-enters the same `main`
/// (presentation / GPU preflight, #749). A child's output is already captured
/// by the parent, so it loses nothing by staying off the file — and it never
/// has to touch the parent's file at all.
pub fn install_without_file_sink(default_level: &str) {
install_with_file_sink(default_level, false);
install_with_file_sink(default_level, None);
}
fn install_with_file_sink(default_level: &str, file_sink: bool) {
fn install_with_file_sink(default_level: &str, file_name: Option<&str>) {
// True one-shot guard: avoid re-rotating the log file or fighting an already-set logger.
if INSTALLED.swap(true, Ordering::SeqCst) {
return;
@@ -57,10 +66,10 @@ fn install_with_file_sink(default_level: &str, file_sink: bool) {
)
.build();
let level = inner.filter();
let file = if file_sink { open_log_file() } else { None };
let sink = file_name.and_then(open_log_file);
// Ignore the Err if a logger was somehow already set elsewhere.
if log::set_boxed_logger(Box::new(TeeLogger::new(inner, file))).is_ok() {
if log::set_boxed_logger(Box::new(TeeLogger::new(inner, sink))).is_ok() {
log::set_max_level(level);
}
}
@@ -70,35 +79,74 @@ pub fn set_level(level: log::LevelFilter) {
log::set_max_level(level);
}
/// Path to the current-run log file (`~/.local/share/qbz/logs/qbz.log`), if a data dir exists.
/// `~/.local/share/qbz/logs`, if a data dir exists.
fn logs_dir() -> Option<PathBuf> {
Some(dirs::data_dir()?.join("qbz").join("logs"))
}
/// Path to the desktop app's current-run log file (`~/.local/share/qbz/logs/qbz.log`).
pub fn log_file_path() -> Option<PathBuf> {
Some(dirs::data_dir()?.join("qbz").join("logs").join("qbz.log"))
log_file_path_named(DEFAULT_LOG_FILE)
}
/// 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<BufWriter<File>> {
open_log_file_at(&log_file_path()?)
/// Path to `file_name` inside the logs directory (`qbzd.log` for the daemon).
pub fn log_file_path_named(file_name: &str) -> Option<PathBuf> {
Some(logs_dir()?.join(file_name))
}
/// [`open_log_file`] against an explicit path, so the rotation contract is
/// testable without a real data dir.
fn open_log_file(file_name: &str) -> Option<FileSink> {
open_log_file_at(&log_file_path_named(file_name)?)
}
/// Open the run's log file at `path`.
///
/// NOTE the hazard this encodes: every call renames the CURRENT file away and
/// starts an empty one. That is right once per process run and wrong for
/// anything else — see [`install_without_file_sink`].
fn open_log_file_at(path: &std::path::Path) -> Option<BufWriter<File>> {
/// Rotation (`<name>` → `<name>.prev`, then a fresh file) happens ONLY when no
/// live process is writing the file. Liveness is an advisory lock on the
/// sidecar `<name>.lock`: every writer holds it shared for its lifetime; an
/// opener probes it with a non-blocking exclusive lock and, when that is
/// refused, APPENDS to the live file instead of renaming it away. That is
/// what a second `qbz` launch, a `qbzd` sharing the directory, or any future
/// caller of [`install`] used to do to a running process (#749, and the
/// 2026-09 static review). The lock lives on the sidecar, never on the log
/// itself, so it can never interfere with writes (a shared `LockFileEx`
/// would, on Windows). Returns `None` (file sink disabled, gracefully) on any
/// filesystem error.
fn open_log_file_at(path: &Path) -> Option<FileSink> {
let dir = path.parent()?;
std::fs::create_dir_all(dir).ok()?;
let name = path.file_name()?.to_string_lossy().into_owned();
if path.exists() {
let prev = dir.join("qbz.log.prev");
// Best-effort rotation; a failure here must not disable logging.
let _ = std::fs::rename(path, &prev);
let lock = OpenOptions::new()
.create(true)
.read(true)
.write(true)
.open(dir.join(format!("{name}.lock")))
.ok();
let live_writer = match lock.as_ref().map(File::try_lock) {
Some(Err(TryLockError::WouldBlock)) => true,
// Granted, unsupported (exotic filesystem) or no sidecar: nobody we
// can see is live — keep the historical rotate behaviour.
Some(Ok(())) | Some(Err(TryLockError::Error(_))) | None => false,
};
if let Some(lock) = lock.as_ref() {
// Join the live writers (downgrade the probe if we held it).
let _ = lock.unlock();
let _ = lock.lock_shared();
}
let file = File::create(path).ok()?;
Some(BufWriter::new(file))
let file = if live_writer && path.exists() {
OpenOptions::new().append(true).open(path).ok()?
} else {
if path.exists() {
// Best-effort rotation; a failure here must not disable logging.
let _ = std::fs::rename(path, dir.join(format!("{name}.prev")));
}
File::create(path).ok()?
};
Some(FileSink {
writer: BufWriter::new(file),
lock,
})
}
#[cfg(test)]
@@ -106,32 +154,68 @@ mod tests {
use super::*;
use std::io::Write;
/// The rotation contract, and the reason a child process must never run it:
/// a second open renames the live file to `qbz.log.prev` and leaves an
/// empty `qbz.log` behind. This is #749 in three lines.
#[test]
fn a_second_open_rotates_the_live_file_away() {
let dir = std::env::temp_dir().join(format!("qbz-log-rotate-{}", std::process::id()));
fn fresh_dir(tag: &str) -> PathBuf {
let dir = std::env::temp_dir().join(format!("qbz-log-{tag}-{}", std::process::id()));
let _ = std::fs::remove_dir_all(&dir);
dir
}
/// #749 was a child process renaming the live log away; a second `qbz`
/// launch or a `qbzd` in the same directory did the same. A live writer
/// holds the sidecar lock, so a second opener APPENDS.
#[test]
fn a_second_open_while_the_first_writer_is_live_appends() {
let dir = fresh_dir("live");
let path = dir.join("qbz.log");
let mut first = open_log_file_at(&path).expect("first open");
writeln!(first, "parent line").unwrap();
first.flush().unwrap();
assert_eq!(std::fs::read_to_string(&path).unwrap(), "parent line\n");
writeln!(first.writer, "parent line").unwrap();
first.writer.flush().unwrap();
// A second process (the preflight child) installing its own logger.
let mut second = open_log_file_at(&path).expect("second open");
writeln!(second, "child line").unwrap();
second.flush().unwrap();
writeln!(second.writer, "second-instance line").unwrap();
second.writer.flush().unwrap();
assert_eq!(std::fs::read_to_string(&path).unwrap(), "child line\n");
assert_eq!(
std::fs::read_to_string(dir.join("qbz.log.prev")).unwrap(),
"parent line\n",
"the parent's log survives only under .prev"
std::fs::read_to_string(&path).unwrap(),
"parent line\nsecond-instance line\n"
);
assert!(!dir.join("qbz.log.prev").exists(), "nothing was rotated");
drop(second);
drop(first);
let _ = std::fs::remove_dir_all(&dir);
}
/// With no live writer the historical contract holds: rotate to
/// `<name>.prev` and start fresh. The prev name follows the file name.
#[test]
fn open_after_the_previous_writer_closed_rotates_to_prev() {
let dir = fresh_dir("rotate");
let path = dir.join("qbzd.log");
{
let mut first = open_log_file_at(&path).expect("first open");
writeln!(first.writer, "run one").unwrap();
first.writer.flush().unwrap();
}
let mut second = open_log_file_at(&path).expect("second open");
writeln!(second.writer, "run two").unwrap();
second.writer.flush().unwrap();
assert_eq!(std::fs::read_to_string(&path).unwrap(), "run two\n");
assert_eq!(
std::fs::read_to_string(dir.join("qbzd.log.prev")).unwrap(),
"run one\n"
);
drop(second);
let _ = std::fs::remove_dir_all(&dir);
}
#[test]
fn named_log_paths_share_the_logs_directory() {
let Some(default) = log_file_path() else { return };
let daemon = log_file_path_named("qbzd.log").unwrap();
assert_eq!(default.parent(), daemon.parent());
assert_eq!(default.file_name().unwrap(), DEFAULT_LOG_FILE);
assert_eq!(daemon.file_name().unwrap(), "qbzd.log");
}
}
+3 -2
View File
@@ -4,7 +4,8 @@
//! `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).
//! 3. an **on-disk file** (`~/.local/share/qbz/logs/qbz.log`; `qbzd.log` for the daemon),
//! prev-rotated at startup unless another live process is writing it.
//!
//! 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.
@@ -26,6 +27,6 @@ pub mod tee;
pub use bundle::{format_diagnostics_bundle, DiagFields};
pub use fatal::install as install_fatal_signal_reporter;
pub use install::{install, install_without_file_sink, set_level};
pub use install::{install, install_named, install_without_file_sink, set_level};
pub use line::LogLine;
pub use redact::{redact, register_secret};
+17 -2
View File
@@ -7,6 +7,7 @@ use std::time::Instant;
use log::{Log, Metadata, Record};
use crate::install::FileSink;
use crate::line::LogLine;
use crate::repeat::ConsecutiveRecords;
use crate::{redact, ring};
@@ -25,15 +26,23 @@ pub struct TeeLogger {
struct Output {
file: Option<BufWriter<File>>,
/// Held for the process lifetime: marks this process as a live writer of
/// the log file (see `install::open_log_file_at`).
_lock: Option<File>,
consecutive: ConsecutiveRecords,
}
impl TeeLogger {
pub(crate) fn new(inner: env_logger::Logger, file: Option<BufWriter<File>>) -> Self {
pub(crate) fn new(inner: env_logger::Logger, sink: Option<FileSink>) -> Self {
let (file, lock) = match sink {
Some(sink) => (Some(sink.writer), sink.lock),
None => (None, None),
};
Self {
inner,
output: Mutex::new(Output {
file,
_lock: lock,
consecutive: ConsecutiveRecords::default(),
}),
}
@@ -140,7 +149,13 @@ mod tests {
let inner = env_logger::Builder::new()
.filter_level(log::LevelFilter::Info)
.build();
let logger = TeeLogger::new(inner, Some(BufWriter::new(file)));
let logger = TeeLogger::new(
inner,
Some(FileSink {
writer: BufWriter::new(file),
lock: None,
}),
);
logger.log(
&Record::builder()
.level(Level::Info)