diff --git a/crates/pdfs-fuse/src/mount.rs b/crates/pdfs-fuse/src/mount.rs index dca09a6..d7e3c46 100644 --- a/crates/pdfs-fuse/src/mount.rs +++ b/crates/pdfs-fuse/src/mount.rs @@ -686,6 +686,11 @@ pub fn mount( Ok(outcome) } +/// How long teardown waits for the FUSE worker pool before proceeding without +/// it. Long enough for an in-flight block to finish, short enough that +/// `systemctl --user stop` still returns inside `TimeoutStopSec`. +const WORKER_JOIN_DEADLINE: Duration = Duration::from_secs(10); + /// Signal every background loop, wake the ones that are blocked, and join them. /// /// The mount used to return with its drain workers, sync engine, sweep, online @@ -717,6 +722,12 @@ fn stop_workers(core: &Core, control_socket: &Path, workers: Vec bool { + depth >= QUEUE_WARN_STEP && depth.is_multiple_of(QUEUE_WARN_STEP) +} + type Job = Box; /// A queued job and the name its caller gave it, so a job that never finishes @@ -170,6 +180,12 @@ impl Pool { /// on-demand sync folder), so the bound is per daemon rather than per mount. pub(crate) struct Workers { inner: Arc, + /// Kept so teardown can *join* the workers, not merely flag them. A worker + /// still inside a job when the process drops its tokio runtime panics with + /// "A Tokio 1.x context was found, but it is being shutdown" (seen + /// 2026-09-18 09:58:35), which is a teardown ordering bug rather than a real + /// failure. + handles: Mutex>>, } impl Workers { @@ -198,10 +214,11 @@ impl Workers { .collect(), started: Instant::now(), }); + let mut handles = Vec::with_capacity(n); for (i, name) in names.iter().enumerate() { let inner = inner.clone(); let meta_only = i < meta_workers; - std::thread::Builder::new() + let handle = std::thread::Builder::new() .name(name.clone()) .spawn(move || { let cv = if meta_only { @@ -277,8 +294,58 @@ impl Workers { }; } })?; + handles.push(handle); } - Ok(Self { inner }) + Ok(Self { + inner, + handles: Mutex::new(handles), + }) + } + + /// Stop accepting work, wake every worker, and wait up to `deadline` for the + /// jobs in flight to finish. + /// + /// Bounded because a join is only worth what it costs: a worker wedged on a + /// network call would otherwise hold the whole teardown, and the user asked + /// for the daemon to stop. What is stuck gets named in the log, and the + /// process continues shutting down around it. + pub(crate) fn stop_and_join(&self, deadline: std::time::Duration) { + self.close(); + let handles: Vec<_> = std::mem::take(&mut *self.handles.lock()); + if handles.is_empty() { + return; + } + let (tx, rx) = std::sync::mpsc::channel(); + let joiner = std::thread::Builder::new() + .name("pdfs-fuse-join".into()) + .spawn(move || { + for handle in handles { + let _ = handle.join(); + } + let _ = tx.send(()); + }); + if joiner.is_err() { + return; + } + if rx.recv_timeout(deadline).is_err() { + let busy: Vec = self + .snapshot() + .workers + .into_iter() + .filter(|worker| worker.busy) + .map(|worker| format!("{}={}", worker.name, worker.label)) + .collect(); + warn!( + stuck = busy.join(","), + "fuse workers did not finish in time; shutting down around them" + ); + } + } + + fn close(&self) { + self.inner.queues.lock().closed = true; + self.inner.meta_cv.notify_all(); + self.inner.general_cv.notify_all(); } /// Queue `job` in `lane`. @@ -289,6 +356,12 @@ impl Workers { /// a pending job holds a `Reply` and a few fields, while the 4 MiB block /// buffer is allocated inside the job once it runs, and the SDK's in-flight /// semaphore is what bounds how many of those exist at once. + /// The queue is *not* bounded, and the depth warning above is deliberately + /// all this does about it: the only caller able to feel backpressure here is + /// fuser's dispatch loop, and blocking that is the stall the whole module + /// exists to avoid. A depth that keeps climbing is a symptom to read in the + /// log, not something to fix by stopping the mount. + /// /// `label` names the work for the diagnostics (`pdfs diagnostics`) and for /// the stall warnings: it is what a hung daemon reports instead of "busy". pub(crate) fn run(&self, lane: Lane, label: &'static str, job: impl FnOnce() + Send + 'static) { @@ -305,17 +378,27 @@ impl Workers { label, job: Box::new(job), }; - match lane { + let depth = match lane { Lane::Meta => { q.meta.push_back(queued); - self.inner.meta_queued.fetch_add(1, Ordering::Relaxed); + self.inner.meta_queued.fetch_add(1, Ordering::Relaxed) + 1 } Lane::Transfer => { q.transfer.push_back(queued); - self.inner.transfer_queued.fetch_add(1, Ordering::Relaxed); + self.inner.transfer_queued.fetch_add(1, Ordering::Relaxed) + 1 } - } + }; drop(q); + if crosses_warn_step(depth) { + warn!( + lane = if matches!(lane, Lane::Meta) { + "meta" + } else { + "transfer" + }, + depth, label, "fuse worker queue is deep" + ); + } match lane { // Either class can serve metadata, and only one of them needs to: // whichever wakes first takes it, and the other finds the queue @@ -369,10 +452,12 @@ impl Workers { } impl Drop for Workers { + /// A backstop for the paths that never call + /// [`stop_and_join`](Workers::stop_and_join) — tests, and a mount that fails + /// before teardown is wired up. Flag and wake only: a `Drop` that blocks on + /// a network call is worse than a worker outliving its pool by a moment. fn drop(&mut self) { - self.inner.queues.lock().closed = true; - self.inner.meta_cv.notify_all(); - self.inner.general_cv.notify_all(); + self.close(); } } @@ -382,6 +467,35 @@ mod tests { use std::sync::mpsc; use std::time::Duration; + /// The depth warning fires on the step, and only on the step: a lane that + /// oscillates around the threshold must not log on every single job. + #[test] + fn queue_depth_warns_on_each_step() { + assert!(!crosses_warn_step(1)); + assert!(!crosses_warn_step(QUEUE_WARN_STEP - 1)); + assert!(crosses_warn_step(QUEUE_WARN_STEP)); + assert!(!crosses_warn_step(QUEUE_WARN_STEP + 1)); + assert!(crosses_warn_step(QUEUE_WARN_STEP * 3)); + } + + /// Teardown must return even while a job is running, and must not leave the + /// pool accepting work. + #[test] + fn stopping_is_bounded_and_closes_the_pool() { + let pool = Workers::new(2).unwrap(); + let (tx, rx) = mpsc::channel(); + pool.run(Lane::Meta, "test", move || tx.send(()).unwrap()); + rx.recv_timeout(Duration::from_secs(5)).expect("it runs"); + + pool.stop_and_join(Duration::from_secs(5)); + + // A job queued after the stop runs inline rather than disappearing. + let (tx, rx) = mpsc::channel(); + pool.run(Lane::Meta, "test", move || tx.send(()).unwrap()); + rx.recv_timeout(Duration::from_secs(5)) + .expect("a closed pool serves inline"); + } + /// A diagnostic is only useful if it names the work. A running job must show /// up under its label, and the queue behind it must show up as depth. #[test] diff --git a/docs/BUGS.md b/docs/BUGS.md index 7801ebe..71ac367 100644 --- a/docs/BUGS.md +++ b/docs/BUGS.md @@ -12,6 +12,76 @@ Conventions: --- +## B91 — The daemon hung overnight, and nothing could say what it was waiting on + +**Status:** Open — the hang itself is undiagnosed. What is fixed (unverified) is the +*undiagnosability*: the daemon now reports what it is doing, warns when it stops making progress, +and is restarted by systemd when it stops answering. +**Found:** 2026-09-18, from a user report — the mount stopped responding and only came back after +`systemctl --user restart`. +**Where:** `crates/pdfs-fuse/src/{workers.rs,diagnostics.rs,supervisor.rs,systemd.rs,mount.rs}`, +`packaging/proton-drive.service`. + +**Symptom.** The mount stops answering. The process is alive and is not spinning; there is no +panic, no error, and no log line after the moment it stopped. The accounting for the hung run: + +``` +Consumed 43min 39.045s CPU time over 20h 8min 15.733s wall clock time, +5.2G memory peak, 65.7M memory swap peak +``` + +It went silent at 17:10 and stayed that way until the manual stop at 13:18:54 the next day. A +restart picked everything back up, which rules out corrupt local state. + +**What made it undiagnosable.** Nothing in the daemon could be asked what it was doing: + +- the worker pool published no state at all — not which threads were busy, not with what, not for + how long, not how deep the queues were; +- control requests were not tracked, so a handler that never returned looked exactly like a + handler that was never asked for; +- there was no watchdog, so a daemon that stopped answering stayed "active (running)" for twenty + hours; +- resident size was never sampled, so the 5.2 G peak was only visible in systemd's post-mortem. + +**Related, and a real bug on its own.** At 2026-09-18 09:58:35 a meta worker panicked during +shutdown: + +``` +thread 'pdfs-fuse-meta-0' (3044) panicked at ...: +A Tokio 1.x context was found, but it is being shutdown. +``` + +The pool was flagged closed at teardown but never joined, so the process could drop the tokio +runtime while a worker was still inside a job. `catch_unwind` caught it, which is why it was only +ever a log line — but it is teardown ordering, not an error. + +**What changed.** + +- `Workers` publishes per-thread state (busy, job label, age) plus queue depths and per-lane + completion counts, all outside the queue lock, and every FUSE handler labels the job it hands + over. +- `Request::Diagnostics` / `pdfs diagnostics` reports that, the in-flight control requests with + their ages, the handler count against its limit, resident size and the pending-op count. It is + built to answer while the daemon is wedged: atomics and `try_lock` only, with the one database + read on a throwaway thread behind a 500 ms deadline. +- A supervisor thread WARNs when a worker has held one job for 120 s, when a control request has + run that long, or when a lane has a queue but completed nothing since the last tick; it samples + RSS every 5 minutes. +- The supervisor answers the systemd watchdog, but only after a real round trip over the control + socket — so the ping means "a client can still talk to this daemon" rather than "a thread is + still scheduled". `WatchdogSec=120` and `Restart=always` turn the next hang into a restart + instead of a morning of downtime, and `MemoryHigh=2G`/`MemoryMax=6G` bound the growth. +- Teardown joins the worker pool, with a 10 s deadline, before the caller drops the runtime. + +**Still open.** None of this says *why* it hung. The candidates the evidence does not yet separate: +the 5.2 G working set (a leak, or a legitimately huge listing retained), a lock held across an +await somewhere in the control plane, and the ~150 `rt.block_on` sites on the control path that +have no op-level deadline of their own — each individual HTTP call is bounded by the SDK's 30 s +API / 300 s storage timeouts, but a sequence of them is not. The next occurrence should be a +one-line answer from `pdfs diagnostics` or from the stall WARN. + +--- + ## B90 — The local-file indexer walks into foreign FUSE mounts, and a dead one makes the daemon unkillable **Status:** Fixed (unverified) — the walker no longer stats a nested mountpoint. The stuck-daemon diff --git a/docs/CHANGELOG.md b/docs/CHANGELOG.md index 963ce13..8f79332 100644 --- a/docs/CHANGELOG.md +++ b/docs/CHANGELOG.md @@ -22,7 +22,20 @@ Schema: **29** (`trash.parent_uid`); SDK bumped to `proton-sdk` / `proton-drive- children, and each node is still restored individually, so one node the server refuses does not cancel the rest. +### Added +- **`pdfs diagnostics`.** Reports what the daemon is doing right now: every worker thread with the job + it holds and for how long, queue depths per lane, the control requests still in flight, resident + size and the pending-op count. Answers even while the daemon is wedged, which is the only time + anyone asks (B91). +- **A stall watchdog.** The daemon warns in the journal when a worker has held one job for two + minutes, when a control request has run that long, or when a queue is not draining — and it now + answers the systemd watchdog, but only after a real round trip over its own control socket. A + daemon that stops answering is restarted instead of sitting there looking healthy (B91). + ### Fixed +- **A worker no longer panics during shutdown (B91).** The FUSE worker pool is joined before the + tokio runtime is dropped, so a worker still inside a job does not find a runtime that is going + away underneath it. - **A permanently rejected block upload is no longer retried (SDK 0.6.5).** The SDK now knows which API errors are worth replaying: 4xx is permanent, except 404, 408 and 429. - **Long downloads no longer fail on expired block URLs (SDK 0.6.5).** A download whose block