From 176112a9cbfa94236bd61b2b00e636cd0eab6cf6 Mon Sep 17 00:00:00 2001 From: Nils Pukropp Date: Sat, 31 Oct 2026 19:09:23 +0100 Subject: [PATCH 1/2] fix(cli): leave the runtime running on a stop so stragglers cannot panic A stop shut the tokio runtime down after joining the workers it owns. Threads it never joins, such as a size lookup or a profile backup that a request started during the stop, then panicked on their next timer with "A Tokio 1.x context was found, but it is being shutdown". The process exits right after a stop, so the runtime is now left for the exit to end. A mount that is retried still shuts its runtime down with the 2 s limit. The acceptance journal check now counts panics, and no longer counts the ENOENT reply errors a stop causes by aborting its FUSE connections. docs/BUGS.md B276. --- crates/pdfs-cli/src/main.rs | 63 +++++++++++++++++++++++++++++++++++-- docs/BUGS.md | 60 +++++++++++++++++++++++++++++++++++ docs/TESTING.md | 2 +- scripts/fuse-acceptance.py | 34 +++++++++++++++++--- 4 files changed, 150 insertions(+), 9 deletions(-) diff --git a/crates/pdfs-cli/src/main.rs b/crates/pdfs-cli/src/main.rs index 75f6e3b..7d15520 100644 --- a/crates/pdfs-cli/src/main.rs +++ b/crates/pdfs-cli/src/main.rs @@ -2467,14 +2467,30 @@ fn mount_once(mountpoint: Option) -> Result { "could not save the refreshed session tokens; the next start may need `pdfs login`" ); } - // Dropping the runtime waits for every blocking task, however long; a call - // still stuck on Drive would hold the stop until systemd kills it (B165). - rt.shutdown_timeout(std::time::Duration::from_secs(2)); + release_runtime(rt, matches!(result, Ok(pdfs_fuse::MountOutcome::Shutdown))); let outcome = result.context("mount failed")?; Ok(outcome) } +/// Let go of a mount's runtime once the mount has ended. +/// +/// On a stop the process exits right after, so the runtime is left running +/// for it to end with. Shutting it down first broke every thread the mount +/// does not join, such as a size lookup or a profile backup a request started +/// during the stop: its next call to Drive panicked with "A Tokio 1.x context +/// was found, but it is being shutdown" (`docs/BUGS.md` B276). A mount that +/// is about to be tried again does shut it down, because a new runtime +/// replaces it. Dropping it would wait for every blocking task, however long; +/// a call still stuck on Drive would hold the retry (B165). +fn release_runtime(rt: tokio::runtime::Runtime, exiting: bool) { + if exiting { + std::mem::forget(rt); + } else { + rt.shutdown_timeout(std::time::Duration::from_secs(2)); + } +} + fn cmd_pin(path: PathBuf) -> Result<()> { match control_request(CtlRequest::Pin { path: path_arg(&path)?, @@ -3944,6 +3960,47 @@ fn control_request(req: CtlRequest) -> Result { .with_context(|| format!("talk to mount daemon at {}", socket.display())) } +#[cfg(test)] +mod release_runtime_tests { + use super::*; + use std::time::Duration; + + /// A thread the mount never joined still reaches Drive after a stop. It + /// used to panic on its first timer once the runtime was shut down. + #[test] + fn a_thread_left_running_at_a_stop_can_still_use_the_runtime() { + let rt = tokio::runtime::Runtime::new().unwrap(); + let handle = rt.handle().clone(); + let (released_tx, released_rx) = std::sync::mpsc::channel(); + let straggler = std::thread::spawn(move || { + released_rx.recv().unwrap(); + handle.block_on(async { + tokio::time::sleep(Duration::from_millis(1)).await; + 7 + }) + }); + release_runtime(rt, true); + released_tx.send(()).unwrap(); + assert_eq!(straggler.join().expect("the thread must not panic"), 7); + } + + #[test] + fn a_mount_tried_again_shuts_its_runtime_down() { + let rt = tokio::runtime::Runtime::new().unwrap(); + let (done_tx, done_rx) = std::sync::mpsc::channel::<()>(); + rt.spawn(async move { + let _done = done_tx; + std::future::pending::<()>().await; + }); + release_runtime(rt, false); + // The task is dropped with the runtime, and its sender with it. + assert_eq!( + done_rx.recv_timeout(Duration::from_secs(5)), + Err(std::sync::mpsc::RecvTimeoutError::Disconnected) + ); + } +} + #[cfg(test)] mod pause_tests { use super::*; diff --git a/docs/BUGS.md b/docs/BUGS.md index 319b4ca..933905a 100644 --- a/docs/BUGS.md +++ b/docs/BUGS.md @@ -116,6 +116,7 @@ a live account since. | Entry | Title | |---|---| +| [B276](#b276--a-stop-can-end-with-a-panic-in-a-thread-the-stop-never-waited-for) | A stop can end with a panic in a thread the stop never waited for | | [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 | @@ -375,6 +376,65 @@ a live account since. Newest first. +### B276 — A stop can end with a panic in a thread the stop never waited for + +**Status:** Fixed, not verified live +**Found:** 2026-10-31, by an account run of `scripts/fuse-acceptance.sh --journal-check +--durability` against the audit branches. Every case passed, and the run still failed. During +the restart in the durability case on My files, the journal had three +`ERROR fuser::reply: Failed to send FUSE reply: No such file or directory (os error 2)` lines, +and after them a panic that the check did not report: + +``` +thread '' (1536340) panicked at .../tokio-1.53.1/src/runtime/time/entry.rs:539:9: +A Tokio 1.x context was found, but it is being shutdown. +``` + +The same panic is in the journal of a 3.6.0 stop on 2026-10-28, twice. B91 first saw it in a +meta worker. + +**Where:** `mount_once` and `release_runtime` in `crates/pdfs-cli/src/main.rs`; +`JournalWatch` and `journal_problems` in `scripts/fuse-acceptance.py`. + +**Cause.** A stop joins the drain workers, the sync engine and the FUSE worker pool, and then +`mount_once` shut the tokio runtime down. Other threads also use the runtime and are never +joined: a size lookup for a listing, a profile backup, a control request, a database vacuum. +A request still in progress when the stop began can start one of them. The thread id here is +nine below the next daemon's pid, so this thread started during the stop. Once the runtime is +shut down, that thread's next timer panics. Every call to Drive has a timer, because each one is +bounded. + +The three `fuser::reply` lines are part of a correct stop. The stop aborts each mount's FUSE +connection so the unmount cannot hang. A request that was still running replies after that, +and the kernel answers a reply on an aborted connection with `ENOENT`. + +The journal check matched only the `ERROR` token. A panic goes to stderr with no tracing level, +so the check did not see it. + +**Fix.** + +- On a stop, `release_runtime` leaves the runtime running for the process to end with, instead + of shutting it down. The process exits right after, so a thread the stop did not wait for + can finish its call or be ended by the exit, but it cannot panic. A mount that is about to + be tried again still shuts its runtime down with the 2 s limit from B165, because a new + runtime replaces it. +- The journal check counts `panicked at` lines. +- The journal check ignores the `ENOENT` reply error between the connection abort and the end + of that stop ("daemon stopping", or "control socket listening" for a mount that comes back). + At any other time the error still counts. + +Making the bounded call helpers refuse new calls once the stop flag is set was rejected. The +stop sets that flag before it waits up to 10 s for the drain workers, so the refusal would cut +off the second half of an upload the stop is waiting for. + +**Test:** `a_thread_left_running_at_a_stop_can_still_use_the_runtime` and +`a_mount_tried_again_shuts_its_runtime_down` in `crates/pdfs-cli/src/main.rs`. With the old +shutdown, the first one fails with the same panic at `entry.rs:539`. The new journal +filter was run on the journal of the run that found this: the three reply errors are no longer +counted, and the panic is. + +--- + ### B273 — A restore proposes another computer's paths when the two share a hostname **Status:** Open diff --git a/docs/TESTING.md b/docs/TESTING.md index b28db6a..7b8d849 100644 --- a/docs/TESTING.md +++ b/docs/TESTING.md @@ -246,7 +246,7 @@ remaining cases are skipped. Cases that make many round trips by design get twic | `--report-json PATH` | Every result and recorded observation. Attach it to a bug report | | `--report-junit PATH` | JUnit XML. `known` is reported as skipped | | `--budget SECONDS` | Flags cases that pass but take longer (`PDFS_ACCEPTANCE_BUDGET`) | -| `--journal-check` | Fails the run if `proton-drive.service` logged an error during it, or the warnings "queued write conflicts; keeping a conflict copy" and "a fuse worker has held the same job for a long time" | +| `--journal-check` | Fails the run if `proton-drive.service` logged an error or a panic during it, or the warnings "queued write conflicts; keeping a conflict copy" and "a fuse worker has held the same job for a long time". A `Failed to send FUSE reply: No such file or directory` during a stop does not count: it is a request answering after the stop aborted its connection | | `--durability` | Restarts the service mid-suite and checks the bytes written before it. Proves the queue survives a restart. `PDFS_ACCEPTANCE_UNIT` names another unit | | `--fail-fast` | Stops at the first failure | | `--list` | Prints every case and its targets | diff --git a/scripts/fuse-acceptance.py b/scripts/fuse-acceptance.py index 263ed1d..38f4e16 100755 --- a/scripts/fuse-acceptance.py +++ b/scripts/fuse-acceptance.py @@ -3561,8 +3561,36 @@ JOURNAL_WARNINGS = ( "queued write conflicts; keeping a conflict copy", "a fuse worker has held the same job for a long time", "re-interned an authority missing from the local tree", + # A Rust panic goes to stderr without a tracing level, so the ERROR match + # does not see it (`docs/BUGS.md` B276). + "panicked at", ) +# A stop aborts each mount's FUSE connection so the unmount cannot hang. A +# request still running then replies into a connection the kernel has +# closed, and the kernel refuses that reply with ENOENT. While a stop is in +# progress that error is expected (`docs/BUGS.md` B276); at any other time it +# still counts. +STOP_STARTED = "aborted FUSE connection to unblock unmount" +STOP_ENDED = ("daemon stopping", "control socket listening") +LATE_REPLY = "Failed to send FUSE reply: No such file or directory" + + +def journal_problems(lines: list[str]) -> list[str]: + """The lines of `lines` that count as problems.""" + problems = [] + stopping = False + for line in lines: + if STOP_STARTED in line: + stopping = True + elif any(marker in line for marker in STOP_ENDED): + stopping = False + if stopping and LATE_REPLY in line: + continue + if ERROR_LEVEL.search(line) or any(warning in line for warning in JOURNAL_WARNINGS): + problems.append(line) + return problems + def read_journal(unit: str, since: float) -> list[str] | None: """The unit's journal lines since `since`, or None without journalctl. @@ -3621,11 +3649,7 @@ class JournalWatch: # Filtering on syslog priority (`-p err`) finds nothing: the daemon writes # tracing levels as text on stdout, which journald files at the unit's # default priority. Match the level token instead. - return [ - line - for line in lines - if ERROR_LEVEL.search(line) or any(warning in line for warning in JOURNAL_WARNINGS) - ] + return journal_problems(lines) # -------------------------------------------------------------------------- From b3ea564c6b41d1a0ad0af4289ee6080c4d829e7d Mon Sep 17 00:00:00 2001 From: Nils Pukropp Date: Sat, 31 Oct 2026 19:29:29 +0100 Subject: [PATCH 2/2] docs(bugs): keep the index newest first --- docs/BUGS.md | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/docs/BUGS.md b/docs/BUGS.md index 653d528..be15515 100644 --- a/docs/BUGS.md +++ b/docs/BUGS.md @@ -110,13 +110,13 @@ a live account since. | Entry | Title | |---|---| | [B276](#b276--a-stop-can-end-with-a-panic-in-a-thread-the-stop-never-waited-for) | A stop can end with a panic in a thread the stop never waited for | -| [B265](#b265--address-keys-whose-token-is-for-an-inactive-account-key-never-open) | Address keys whose token is for an inactive account key never open | | [B274](#b274--opening-a-file-for-writing-fails-with-eio-while-its-queued-revision-lands) | Opening a file for writing fails with EIO while its queued revision lands | +| [B272](#b272--after-a-folder-is-removed-and-added-again-its-file-events-go-to-the-old-id) | After a folder is removed and added again, its file events go to the old id | | [B271](#b271--one-failed-listing-makes-a-large-first-sync-start-over-from-nothing) | One failed listing makes a large first sync start over from nothing | | [B266](#b266--pin-unpin-search-and-node-loads-report-a-database-error-as-offline) | Pin, unpin, search and node loads report a database error as "offline" | +| [B265](#b265--address-keys-whose-token-is-for-an-inactive-account-key-never-open) | Address keys whose token is for an inactive account key never open | | [B264](#b264--a-mount-that-fails-after-starting-its-workers-leaves-them-running) | A mount that fails after starting its workers leaves them running | | [B261](#b261--a-folder-that-has-never-synced-reads-up-to-date) | A folder that has never synced reads "up to date" | -| [B272](#b272--after-a-folder-is-removed-and-added-again-its-file-events-go-to-the-old-id) | After a folder is removed and added again, its file events go to the old id | | [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 | | [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 |