mirror of
https://github.com/narrrl/proton-drive-linux.git
synced 2026-11-03 16:41:26 +01:00
fix(fuse): join the worker pool before the runtime goes away, and log deep queues
Teardown flagged the FUSE worker pool closed but never joined it, so the process could drop the tokio runtime while a worker was still inside a job — which is where 2026-09-18's "A Tokio 1.x context was found, but it is being shutdown" panic came from. `Workers::stop_and_join` now waits for the jobs in flight, bounded at 10 s so a worker wedged on the network cannot hold the stop the user asked for; what is still stuck is named in the log and shutdown continues around it. The queues stay unbounded — the only caller that could feel backpressure is fuser's dispatch loop, and blocking that is the stall the pool exists to avoid — but a lane now logs its depth every 256 jobs, so a queue that keeps climbing is visible before it is reported as a slow mount. Documents the hang as B91, with the journal evidence, what made it undiagnosable, and the candidates the evidence does not yet separate.
This commit is contained in:
1 parent
bee15ee7cf
commit
cf0d495f8c
4 files changed
+217
-9
No files matched your search
@@ -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<std::thread::Jo
|
||||
warn!("a background worker panicked before shutdown");
|
||||
}
|
||||
}
|
||||
// The FUSE worker pool last, and *before* the caller drops the tokio
|
||||
// runtime: a worker still inside a job when the runtime goes away panics on
|
||||
// its next timer with "A Tokio 1.x context was found, but it is being
|
||||
// shutdown" (seen 2026-09-18 09:58:35). Bounded, so a worker wedged on the
|
||||
// network cannot hold the stop the user asked for.
|
||||
core.workers.stop_and_join(WORKER_JOIN_DEADLINE);
|
||||
debug!("background workers stopped");
|
||||
}
|
||||
|
||||
|
||||
@@ -53,6 +53,16 @@ pub(crate) const FUSE_WORKERS: usize = 11;
|
||||
/// exactly the blocking this split exists to prevent.
|
||||
const META_WORKERS: usize = 3;
|
||||
|
||||
/// Queue depth that gets a line in the log, and the step at which it repeats.
|
||||
/// Every job holds a `Reply` and a few fields, so depth is cheap — but a lane
|
||||
/// this far behind is worth knowing about before the user reports a slow mount.
|
||||
const QUEUE_WARN_STEP: usize = 256;
|
||||
|
||||
/// Whether a queue reaching `depth` is one of the depths worth logging.
|
||||
fn crosses_warn_step(depth: usize) -> bool {
|
||||
depth >= QUEUE_WARN_STEP && depth.is_multiple_of(QUEUE_WARN_STEP)
|
||||
}
|
||||
|
||||
type Job = Box<dyn FnOnce() + Send + 'static>;
|
||||
|
||||
/// 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<Pool>,
|
||||
/// 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<Vec<std::thread::JoinHandle<()>>>,
|
||||
}
|
||||
|
||||
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<String> = 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]
|
||||
|
||||
@@ -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
|
||||
|
||||
@@ -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
|
||||
|
||||
Reference in new issue
Block a user