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 <N> and drop colours.
This commit is contained in:
nvrl committed 2026-10-31 09:54:07 +01:00
1 parent 9460c93b50
commit 8d4a005aa2
3 files changed
+147 -9

No files matched your search

+122
View File
@@ -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 `<N>` 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 `<N>` priority, then writes
/// the line as `F` would.
pub(crate) struct Prioritized<F>(pub(crate) F);
impl<S, N, F> FormatEvent<S, N> for Prioritized<F>
where
S: Subscriber + for<'a> LookupSpan<'a>,
N: for<'a> FormatFields<'a> + 'static,
F: FormatEvent<S, N>,
{
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<Mutex<Vec<u8>>>);
impl io::Write for Buf {
fn write(&mut self, bytes: &[u8]) -> io::Result<usize> {
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));
}
}
+14 -5
View File
@@ -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()
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()),
)
.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);
+11 -4
View File
@@ -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 `<N>` 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 `<N>` 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 `<N>` 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.
---