Merge branch 'fix/diagnose-coverage' into fix/restore-outcome-and-walk-gaps

# 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);
@@ -2379,12 +2388,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(());
@@ -2399,13 +2417,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.
@@ -3100,6 +3156,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)? {
@@ -3135,6 +3209,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 {
@@ -3373,6 +3450,79 @@ fn cmd_sync_limit(up: Option<u64>, down: Option<u64>) -> Result<()> {
     })?)
 }
 
+/// How long the oldest write may wait to upload before `diagnose` calls it
+/// out. Under a day it is a slow link or a big file; past it, something is
+/// holding the queue.
+const STAGED_STALE_SECS: u64 = 86_400;
+
+/// `diagnose` findings for the queue and the pause, from the `Status` reply.
+/// `paused_for` is how long a timed pause still runs, in seconds.
+fn sync_health(
+    failing_ops: u64,
+    failing_error: Option<&str>,
+    staged_bytes: u64,
+    staged_oldest_secs: u64,
+    paused: bool,
+    paused_for: Option<i64>,
+) -> Vec<(DiagnoseLevel, &'static str, String)> {
+    let mut findings = Vec::new();
+    if failing_ops > 0 {
+        findings.push((
+            DiagnoseLevel::Warn,
+            "  failing writes",
+            match failing_error {
+                Some(error) => format!("{failing_ops} keep failing; the last error: {error}"),
+                None => format!("{failing_ops} keep failing"),
+            },
+        ));
+    }
+    if staged_bytes > 0 && staged_oldest_secs >= STAGED_STALE_SECS {
+        findings.push((
+            DiagnoseLevel::Warn,
+            "  oldest unsent write",
+            format!(
+                "{} old, {} only on this computer",
+                human_secs(staged_oldest_secs),
+                human_bytes(staged_bytes)
+            ),
+        ));
+    }
+    if paused {
+        findings.push((
+            DiagnoseLevel::Warn,
+            "  sync",
+            match paused_for {
+                Some(left) if left > 0 => {
+                    format!("paused for another {}", human_secs(left as u64))
+                }
+                _ => "paused until resumed (`pdfs sync resume`)".to_string(),
+            },
+        ));
+    }
+    findings
+}
+
+/// `diagnose` findings for the synced folders that need someone to look.
+fn folder_health(
+    folders: &[pdfs_core::control::SyncFolderInfo],
+) -> Vec<(DiagnoseLevel, String, String)> {
+    folders
+        .iter()
+        .filter_map(|folder| {
+            let what = match folder.state.as_str() {
+                "error" => "sync error; `pdfs sync list` and the activity feed say more",
+                "conflict" => "conflict copies to look at",
+                _ => return None,
+            };
+            Some((
+                DiagnoseLevel::Warn,
+                format!("  synced folder [{}]", folder.id),
+                format!("{}: {what}", folder.local_path),
+            ))
+        })
+        .collect()
+}
+
 fn unix_now() -> i64 {
     std::time::SystemTime::now()
         .duration_since(std::time::UNIX_EPOCH)
@@ -3709,21 +3859,26 @@ fn cmd_diagnose() -> Result<()> {
     let socket_exists = socket.exists();
     let socket_kind_ok =
         std::fs::symlink_metadata(&socket).is_ok_and(|m| m.file_type().is_socket());
+    // A stale socket file with no listener is the common failure, so the reply
+    // is what decides this rather than the file's existence.
+    let status = control_request(CtlRequest::Status);
     report.finding(
         if socket_exists && !socket_kind_ok {
             DiagnoseLevel::Fail
-        } else if socket_exists {
+        } else if socket_exists && status.is_ok() {
             DiagnoseLevel::Ok
         } else {
             DiagnoseLevel::Warn
         },
         "  control socket",
-        socket.display().to_string(),
+        if socket_exists && socket_kind_ok && status.is_err() {
+            format!("{} (left over; nothing listens on it)", socket.display())
+        } else {
+            socket.display().to_string()
+        },
     );
-    // A stale socket file with no listener is the common failure, so the reply
-    // is what decides this rather than the file's existence.
     let mut daemon_responding = false;
-    match control_request(CtlRequest::Status) {
+    match status {
         Ok(CtlResponse::Status {
             mountpoint,
             online,
@@ -3731,6 +3886,12 @@ fn cmd_diagnose() -> Result<()> {
             tokens_unsaved,
             pending_uploads,
             pending_changes,
+            failing_ops,
+            failing_error,
+            staged_bytes,
+            staged_oldest_secs,
+            paused,
+            paused_until,
             version,
             ..
         }) => {
@@ -3805,6 +3966,27 @@ fn cmd_diagnose() -> Result<()> {
                     format!("{pending} waiting to upload")
                 },
             );
+            // The rest of the daemon's state that the report used to drop:
+            // writes that keep failing, a pause, a folder in error. Each of
+            // them stops changes from reaching Drive while everything above
+            // reads as fine (`docs/BUGS.md` B268).
+            for (level, check, detail) in sync_health(
+                failing_ops,
+                failing_error.as_deref(),
+                staged_bytes,
+                staged_oldest_secs,
+                paused,
+                paused_until.map(|until| until - unix_now()),
+            ) {
+                report.finding(level, check, detail);
+            }
+            if let Ok(CtlResponse::SyncFolders { items }) =
+                control_request(CtlRequest::ListSyncFolders)
+            {
+                for (level, check, detail) in folder_health(&items) {
+                    report.finding(level, &check, detail);
+                }
+            }
             match await_integrity_check() {
                 Ok(CtlResponse::CacheReport {
                     integrity_problems,
@@ -3861,7 +4043,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`)"
+                ),
+            }
         }
     }
 
@@ -3986,6 +4184,50 @@ mod pause_tests {
 mod diagnose_tests {
     use super::*;
 
+    /// A healthy queue says nothing; writes that keep failing, an old unsent
+    /// write and a pause each say so (`docs/BUGS.md` B268).
+    #[test]
+    fn a_stuck_queue_or_a_pause_is_reported() {
+        assert!(sync_health(0, None, 0, 0, false, None).is_empty());
+        assert!(sync_health(0, None, 4096, STAGED_STALE_SECS - 1, false, None).is_empty());
+        let checks: Vec<&str> = sync_health(
+            2,
+            Some("upload a.txt: quota"),
+            4096,
+            STAGED_STALE_SECS,
+            true,
+            Some(600),
+        )
+        .into_iter()
+        .map(|(level, check, _)| {
+            assert!(matches!(level, DiagnoseLevel::Warn));
+            check.trim()
+        })
+        .collect();
+        assert_eq!(checks, ["failing writes", "oldest unsent write", "sync"]);
+    }
+
+    /// Issue #53: a folder that would not sync, and `diagnose` found nothing.
+    #[test]
+    fn a_synced_folder_in_error_is_reported() {
+        let folder = |id: i64, state: &str| pdfs_core::control::SyncFolderInfo {
+            id,
+            local_path: format!("/home/u/f{id}"),
+            remote_uid: "vol~link".into(),
+            mode: "mirror".into(),
+            state: state.into(),
+            last_sync: 0,
+            pending_mode: None,
+            progress: None,
+            paused: false,
+        };
+        let findings =
+            folder_health(&[folder(1, "idle"), folder(2, "error"), folder(3, "syncing")]);
+        assert_eq!(findings.len(), 1);
+        assert_eq!(findings[0].1.trim(), "synced folder [2]");
+        assert!(findings[0].2.starts_with("/home/u/f2: sync error"));
+    }
+
     #[test]
     fn finding_severity_is_counted_centrally() {
         let mut report = DiagnoseReport::default();
@@ -4021,6 +4263,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]