mirror of
https://github.com/narrrl/proton-drive-linux.git
synced 2026-11-03 16:41:26 +01:00
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.
This commit is contained in:
1 parent
9460c93b50
commit
176112a9cb
4 files changed
+150
-9
No files matched your search
@@ -2467,14 +2467,30 @@ fn mount_once(mountpoint: Option<PathBuf>) -> Result<pdfs_fuse::MountOutcome> {
|
|||||||
"could not save the refreshed session tokens; the next start may need `pdfs login`"
|
"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
|
release_runtime(rt, matches!(result, Ok(pdfs_fuse::MountOutcome::Shutdown)));
|
||||||
// still stuck on Drive would hold the stop until systemd kills it (B165).
|
|
||||||
rt.shutdown_timeout(std::time::Duration::from_secs(2));
|
|
||||||
|
|
||||||
let outcome = result.context("mount failed")?;
|
let outcome = result.context("mount failed")?;
|
||||||
Ok(outcome)
|
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<()> {
|
fn cmd_pin(path: PathBuf) -> Result<()> {
|
||||||
match control_request(CtlRequest::Pin {
|
match control_request(CtlRequest::Pin {
|
||||||
path: path_arg(&path)?,
|
path: path_arg(&path)?,
|
||||||
@@ -3944,6 +3960,47 @@ fn control_request(req: CtlRequest) -> Result<CtlResponse> {
|
|||||||
.with_context(|| format!("talk to mount daemon at {}", socket.display()))
|
.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)]
|
#[cfg(test)]
|
||||||
mod pause_tests {
|
mod pause_tests {
|
||||||
use super::*;
|
use super::*;
|
||||||
|
|||||||
@@ -116,6 +116,7 @@ a live account since.
|
|||||||
|
|
||||||
| Entry | Title |
|
| 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 |
|
| [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 |
|
| [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 |
|
| [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.
|
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 '<unnamed>' (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
|
### B273 — A restore proposes another computer's paths when the two share a hostname
|
||||||
|
|
||||||
**Status:** Open
|
**Status:** Open
|
||||||
|
|||||||
+1
-1
@@ -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-json PATH` | Every result and recorded observation. Attach it to a bug report |
|
||||||
| `--report-junit PATH` | JUnit XML. `known` is reported as skipped |
|
| `--report-junit PATH` | JUnit XML. `known` is reported as skipped |
|
||||||
| `--budget SECONDS` | Flags cases that pass but take longer (`PDFS_ACCEPTANCE_BUDGET`) |
|
| `--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 |
|
| `--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 |
|
| `--fail-fast` | Stops at the first failure |
|
||||||
| `--list` | Prints every case and its targets |
|
| `--list` | Prints every case and its targets |
|
||||||
|
|||||||
@@ -3561,8 +3561,36 @@ JOURNAL_WARNINGS = (
|
|||||||
"queued write conflicts; keeping a conflict copy",
|
"queued write conflicts; keeping a conflict copy",
|
||||||
"a fuse worker has held the same job for a long time",
|
"a fuse worker has held the same job for a long time",
|
||||||
"re-interned an authority missing from the local tree",
|
"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:
|
def read_journal(unit: str, since: float) -> list[str] | None:
|
||||||
"""The unit's journal lines since `since`, or None without journalctl.
|
"""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
|
# Filtering on syslog priority (`-p err`) finds nothing: the daemon writes
|
||||||
# tracing levels as text on stdout, which journald files at the unit's
|
# tracing levels as text on stdout, which journald files at the unit's
|
||||||
# default priority. Match the level token instead.
|
# default priority. Match the level token instead.
|
||||||
return [
|
return journal_problems(lines)
|
||||||
line
|
|
||||||
for line in lines
|
|
||||||
if ERROR_LEVEL.search(line) or any(warning in line for warning in JOURNAL_WARNINGS)
|
|
||||||
]
|
|
||||||
|
|
||||||
|
|
||||||
# --------------------------------------------------------------------------
|
# --------------------------------------------------------------------------
|
||||||
|
|||||||
Reference in new issue
Block a user