Merge branch 'fix/db-errors-not-offline' into fix/diagnose-coverage

# Conflicts:
#	docs/BUGS.md

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 `<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));
+    }
+}

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);
@@ -2375,12 +2384,21 @@ where
 /// an external unmount triggers a remount; errors back off and retry. This is
 /// the entry point for the systemd user service.
 fn cmd_daemon(mountpoint: Option<PathBuf>) -> Result<()> {
+    let state_dir = AppDirs::new()?.state_dir();
+    // A failure an earlier daemon recorded is not this one's.
+    pdfs_core::mountfail::clear(&state_dir);
+    let mut failure: Option<pdfs_core::mountfail::MountFailure> = None;
     loop {
         // Wait until a session is stored. The GUI enables this service on login,
         // but the service may also start at boot before the user has logged in.
         wait_for_session(auth::ready, pdfs_fuse::idle_sleep)?;
 
-        match mount_once(mountpoint.clone()) {
+        let outcome = mount_once(mountpoint.clone());
+        if outcome.is_ok() {
+            // The mount came up, so the next failure starts a new run of them.
+            failure = None;
+        }
+        match outcome {
             Ok(pdfs_fuse::MountOutcome::Shutdown) => {
                 tracing::info!("daemon stopping");
                 return Ok(());
@@ -2395,13 +2413,51 @@ fn cmd_daemon(mountpoint: Option<PathBuf>) -> Result<()> {
             Err(e) => {
                 // `{:#}` so the whole anyhow chain lands in the log — the top
                 // context alone ("mount failed") never says *why*.
-                tracing::error!(error = format!("{e:#}"), "mount failed; retrying in 5s");
-                pdfs_fuse::idle_sleep(std::time::Duration::from_secs(5));
+                let error = format!("{e:#}");
+                let now = unix_now();
+                let attempts = failure.as_ref().map_or(1, |f| f.attempts.saturating_add(1));
+                let delay = mount_retry_delay(attempts);
+                tracing::error!(
+                    error,
+                    attempts,
+                    retry_secs = delay.as_secs(),
+                    "mount failed; retrying"
+                );
+                let record = pdfs_core::mountfail::MountFailure {
+                    error: error.clone(),
+                    since: failure.as_ref().map_or(now, |f| f.since),
+                    attempts,
+                    next_attempt: now + delay.as_secs() as i64,
+                };
+                if let Err(e) = pdfs_core::mountfail::record(&state_dir, &record) {
+                    tracing::warn!(error = %e, "could not record the mount failure");
+                }
+                pdfs_fuse::notify_status(&format!("Mount failing: {error}"));
+                failure = Some(record);
+                pdfs_fuse::idle_sleep(delay);
             }
         }
     }
 }
 
+/// How long to wait before mount attempt `attempts + 1`, after `attempts`
+/// failures in a row.
+///
+/// Doubles from 5 s to a 2-minute ceiling. A flat 5 s retry sent about four
+/// requests to Proton per attempt, tens of thousands a day from an account
+/// whose mount fails on a key, which no retry fixes (`docs/BUGS.md` B263). The
+/// ceiling stays at minutes because a cold start without a network fails the
+/// same way, and must mount soon after the network returns.
+fn mount_retry_delay(attempts: u32) -> std::time::Duration {
+    const BASE_SECS: u64 = 5;
+    const MAX_SECS: u64 = 120;
+
+    let factor = 1u64
+        .checked_shl(attempts.saturating_sub(1))
+        .unwrap_or(u64::MAX);
+    std::time::Duration::from_secs(BASE_SECS.saturating_mul(factor).min(MAX_SECS))
+}
+
 /// One mount run: resume the session, mount, and block until the mount ends
 /// (clean shutdown or external unmount). Returns the [`MountOutcome`] so the
 /// daemon loop can decide whether to exit or remount.
@@ -3096,6 +3152,24 @@ fn human_secs(secs: u64) -> String {
     }
 }
 
+/// The sync engine's line in `pdfs diagnostics`: whether it runs, and which
+/// folder's pass it is on.
+fn sync_engine_line(sync: &pdfs_core::control::SyncEngineState) -> String {
+    let mut line = match (sync.running, sync.pass_folder) {
+        (false, _) => "STOPPED; synced folders do not sync until the daemon restarts".to_string(),
+        (true, None) => "idle".to_string(),
+        (true, Some(folder)) => format!(
+            "pass on folder {folder} for {}, last progress {} ago",
+            human_secs(sync.pass_age_secs),
+            human_secs(sync.pass_idle_secs),
+        ),
+    };
+    if sync.panics > 0 {
+        line.push_str(&format!("; {} pass(es) panicked", sync.panics));
+    }
+    line
+}
+
 fn cmd_diagnostics() -> Result<()> {
     let response = control_request(CtlRequest::Diagnostics)?;
     if emit_json(&response)? {
@@ -3131,6 +3205,9 @@ fn cmd_diagnostics() -> Result<()> {
                     human_secs(worker.age_secs)
                 );
             }
+            if let Some(sync) = &d.sync {
+                println!("sync engine: {}", sync_engine_line(sync));
+            }
             if d.inflight.is_empty() {
                 println!("in-flight requests: none");
             } else {
@@ -3962,7 +4039,23 @@ fn cmd_diagnose() -> Result<()> {
                 "  daemon responding",
                 format!("stopped or unreachable: {e:#}"),
             );
-            println!("         (start it with `systemctl --user start proton-drive.service`)");
+            match pdfs_core::mountfail::read(&dirs.state_dir()) {
+                // A daemon whose mount keeps failing never opens the socket,
+                // so this is the only place its reason shows (B263).
+                Some(failure) => report.finding(
+                    DiagnoseLevel::Fail,
+                    "  mount",
+                    format!(
+                        "failing for {}, {} attempt(s): {}",
+                        human_secs(unix_now().saturating_sub(failure.since).max(0) as u64),
+                        failure.attempts,
+                        failure.error
+                    ),
+                ),
+                None => println!(
+                    "         (start it with `systemctl --user start proton-drive.service`)"
+                ),
+            }
         }
     }
 
@@ -4166,6 +4259,15 @@ mod diagnose_tests {
 #[cfg(test)]
 mod login_wait_tests {
     use super::*;
+
+    /// The mount retry backs off from 5 s to a ceiling of minutes, rather than
+    /// asking Proton every 5 s forever (`docs/BUGS.md` B263).
+    #[test]
+    fn a_failing_mount_backs_off_to_a_ceiling() {
+        let secs: Vec<u64> = (1..=8).map(|n| mount_retry_delay(n).as_secs()).collect();
+        assert_eq!(secs, [5, 10, 20, 40, 80, 120, 120, 120]);
+        assert_eq!(mount_retry_delay(u32::MAX).as_secs(), 120);
+    }
     use std::time::Duration;
 
     #[test]