From 8d4a005aa21376efe9a821b727682f8cbd194fb6 Mon Sep 17 00:00:00 2001 From: Nils Pukropp Date: Sat, 31 Oct 2026 09:54:07 +0100 Subject: [PATCH] fix(cli): give journald each log line's priority journald stored every daemon line at info, so journalctl -p warning, which TROUBLESHOOTING.md asks reporters for, was always empty (B258). When fd 1 is the journal stream, prefix lines with and drop colours. --- crates/pdfs-cli/src/journal.rs | 122 +++++++++++++++++++++++++++++++++ crates/pdfs-cli/src/main.rs | 27 +++++--- docs/BUGS.md | 15 ++-- 3 files changed, 151 insertions(+), 13 deletions(-) create mode 100644 crates/pdfs-cli/src/journal.rs diff --git a/crates/pdfs-cli/src/journal.rs b/crates/pdfs-cli/src/journal.rs new file mode 100644 index 0000000..a689a09 --- /dev/null +++ b/crates/pdfs-cli/src/journal.rs @@ -0,0 +1,122 @@ +//! Log priorities for journald. +//! +//! journald files each line a service writes at the unit's default priority, +//! info, unless the line opens with a syslog `` prefix. Without one every +//! WARN and ERROR the daemon logs is stored as info, and the +//! `journalctl -p warning` that the troubleshooting guide asks for shows +//! nothing (`docs/BUGS.md` B258). + +use std::fmt; +use std::os::unix::fs::MetadataExt; + +use tracing::{Event, Level, Subscriber}; +use tracing_subscriber::fmt::format::Writer; +use tracing_subscriber::fmt::{FmtContext, FormatEvent, FormatFields}; +use tracing_subscriber::registry::LookupSpan; + +/// Whether standard output is the journal stream systemd connected this +/// process to. +/// +/// `JOURNAL_STREAM` alone does not say so: a terminal started from a user unit +/// inherits it, and every `pdfs` run in that terminal would print the +/// prefixes. systemd sets it to the stream's `device:inode`, so it is compared +/// against what fd 1 actually is. +pub(crate) fn stdout_is_journal() -> bool { + let Some(stream) = std::env::var_os("JOURNAL_STREAM") else { + return false; + }; + let Ok(stdout) = std::fs::metadata("/proc/self/fd/1") else { + return false; + }; + stream + .to_str() + .is_some_and(|value| names_stream(value, stdout.dev(), stdout.ino())) +} + +/// Whether a `JOURNAL_STREAM` value names the file `dev`:`ino`. +fn names_stream(value: &str, dev: u64, ino: u64) -> bool { + value + .split_once(':') + .is_some_and(|(d, i)| d.parse() == Ok(dev) && i.parse() == Ok(ino)) +} + +/// The syslog priority journald should file a `level` line at. +fn priority(level: &Level) -> u8 { + match *level { + Level::ERROR => 3, + Level::WARN => 4, + Level::INFO => 6, + Level::DEBUG | Level::TRACE => 7, + } +} + +/// An event format that opens each line with its `` priority, then writes +/// the line as `F` would. +pub(crate) struct Prioritized(pub(crate) F); + +impl FormatEvent for Prioritized +where + S: Subscriber + for<'a> LookupSpan<'a>, + N: for<'a> FormatFields<'a> + 'static, + F: FormatEvent, +{ + fn format_event( + &self, + ctx: &FmtContext<'_, S, N>, + mut writer: Writer<'_>, + event: &Event<'_>, + ) -> fmt::Result { + write!(writer, "<{}>", priority(event.metadata().level()))?; + self.0.format_event(ctx, writer, event) + } +} + +#[cfg(test)] +mod tests { + use super::*; + use std::io; + use std::sync::{Arc, Mutex}; + + #[derive(Clone)] + struct Buf(Arc>>); + + impl io::Write for Buf { + fn write(&mut self, bytes: &[u8]) -> io::Result { + self.0.lock().unwrap().extend_from_slice(bytes); + Ok(bytes.len()) + } + fn flush(&mut self) -> io::Result<()> { + Ok(()) + } + } + + #[test] + fn each_line_opens_with_the_priority_of_its_level() { + let buf = Buf(Arc::new(Mutex::new(Vec::new()))); + let writer = buf.clone(); + let subscriber = tracing_subscriber::fmt() + .with_max_level(Level::DEBUG) + .with_ansi(false) + .with_writer(move || writer.clone()) + .event_format(Prioritized(tracing_subscriber::fmt::format())) + .finish(); + tracing::subscriber::with_default(subscriber, || { + tracing::error!("e"); + tracing::warn!("w"); + tracing::info!("i"); + tracing::debug!("d"); + }); + let out = String::from_utf8(buf.0.lock().unwrap().clone()).unwrap(); + let prefixes: Vec<&str> = out.lines().map(|line| &line[..3]).collect(); + assert_eq!(prefixes, ["<3>", "<4>", "<6>", "<7>"]); + } + + #[test] + fn journal_stream_must_name_the_same_file() { + assert!(names_stream("8:12345", 8, 12345)); + assert!(!names_stream("8:12345", 8, 54321)); + assert!(!names_stream("9:12345", 8, 12345)); + assert!(!names_stream("8", 8, 12345)); + assert!(!names_stream("", 8, 12345)); + } +} diff --git a/crates/pdfs-cli/src/main.rs b/crates/pdfs-cli/src/main.rs index 75f6e3b..fa9b400 100644 --- a/crates/pdfs-cli/src/main.rs +++ b/crates/pdfs-cli/src/main.rs @@ -20,6 +20,8 @@ use pdfs_core::control::{ use pdfs_core::db::Db; use pdfs_core::service; +mod journal; + /// `println!` for this binary, shadowing std's, which panics when stdout is /// closed: `pdfs ls | head` ended in a "Broken pipe" panic once `head` had its /// lines. This one hands the failure to [`stdout_written`] instead. @@ -879,15 +881,22 @@ fn cli_error(kind: ErrorKind, message: &str) -> String { } fn main() -> Result<()> { - tracing_subscriber::fmt() - .with_env_filter( - tracing_subscriber::EnvFilter::try_from_default_env() - // `pgp` logs a benign WARN when it re-serializes a Proton secret-key - // packet with a longer (but equivalent) length encoding than the - // original; drop it to error so normal runs stay quiet. - .unwrap_or_else(|_| "info,pgp=error".into()), - ) - .init(); + let filter = tracing_subscriber::EnvFilter::try_from_default_env() + // `pgp` logs a benign WARN when it re-serializes a Proton secret-key + // packet with a longer (but equivalent) length encoding than the + // original; drop it to error so normal runs stay quiet. + .unwrap_or_else(|_| "info,pgp=error".into()); + if journal::stdout_is_journal() { + // journalctl colours lines by the priority the prefix gives them, so + // the escape codes would only be noise in the stored text. + tracing_subscriber::fmt() + .with_env_filter(filter) + .with_ansi(false) + .event_format(journal::Prioritized(tracing_subscriber::fmt::format())) + .init(); + } else { + tracing_subscriber::fmt().with_env_filter(filter).init(); + } let cli = Cli::parse(); JSON_OUTPUT.store(cli.json, std::sync::atomic::Ordering::Relaxed); diff --git a/docs/BUGS.md b/docs/BUGS.md index 319b4ca..55b86bd 100644 --- a/docs/BUGS.md +++ b/docs/BUGS.md @@ -83,7 +83,6 @@ original wording. | [B261](#b261--a-folder-that-has-never-synced-reads-up-to-date) | A folder that has never synced reads "up to date" | Not fixed | | [B260](#b260--the-poll-pushes-a-new-folders-first-sync-behind-every-other-folder) | The poll pushes a new folder's first sync behind every other folder | Not fixed | | [B259](#b259--the-sync-engine-can-die-or-hang-and-nothing-shows-it-until-a-restart) | The sync engine can die or hang, and nothing shows it until a restart | Not fixed; the trigger in #53 is not known | -| [B258](#b258--journalctl--p-warning-shows-nothing-whatever-the-daemon-logged) | `journalctl -p warning` shows nothing, whatever the daemon logged | Not fixed | | [B134](#b134--a-file-deleted-online-while-the-drain-checks-its-write-is-kept-as-a-conflict-copy) | A file deleted online while the drain checks its write is kept as a conflict copy | Only with `local_first` off | | [B91](#b91--the-daemon-hung-overnight-and-nothing-could-say-what-it-was-waiting-on) | The daemon hung overnight, and nothing could say what it was waiting on | The cause is not diagnosed; the daemon now reports where it is stuck and is restarted | | [B67](#b67--fresh-state-restore-can-silently-select-a-new-device-high-22) | Fresh-state restore can silently select a new device (HIGH-22) | An ambiguous device after a loss of local state is not asked about | @@ -116,6 +115,7 @@ a live account since. | Entry | Title | |---|---| +| [B258](#b258--journalctl--p-warning-shows-nothing-whatever-the-daemon-logged) | `journalctl -p warning` shows nothing, whatever the daemon logged | | [B256](#b256--pdfs-copy-right-after-a-save-copies-the-old-version) | `pdfs copy` right after a save copies the old version | | [B255](#b255--a-synced-folder-whose-files-are-all-gone-here-is-stuck-for-good) | A synced folder whose files are all gone here is stuck for good | | [B254](#b254--an-edit-in-the-same-second-as-a-new-upload-never-arrives) | An edit in the same second as a new upload never arrives | @@ -712,7 +712,7 @@ the pass age and the queue in `Diagnostics`. ### B258 — `journalctl -p warning` shows nothing, whatever the daemon logged -**Status:** Open +**Status:** Fixed, not verified live **Found:** 2026-10-31, issue #53: the reporter ran `journalctl --user -u proton-drive.service -b -p warning`, as `docs/TROUBLESHOOTING.md` tells them to, and got `-- No entries --`. **Where:** `main` in `crates/pdfs-cli/src/main.rs`; `packaging/proton-drive.service` @@ -725,8 +725,15 @@ stores every line of a service's output at the unit's default priority, info, un starts with a `` prefix. So every `WARN` and `ERROR` line is stored as info, and the troubleshooting guide's filter hides all of them. -**Fix.** Not done. When `JOURNAL_STREAM` says the output goes to journald, start each line with -the `` prefix for its level. +**Fix.** When standard output is the journal stream (`JOURNAL_STREAM` names the same +device and inode as fd 1), each line starts with the `` prefix for its level, and ANSI colours +are off. A terminal that merely inherited `JOURNAL_STREAM` keeps the plain format +(`crates/pdfs-cli/src/journal.rs`). + +**Test:** `each_line_opens_with_the_priority_of_its_level` and +`journal_stream_must_name_the_same_file` in `pdfs-cli`. On 2026-10-31, `pdfs diagnose` run with +`RUST_LOG=debug` under `systemd-run --user -p StandardOutput=journal` stored its debug lines at +`PRIORITY=7` and its report at 6. ---