Compare commits

...
Author SHA1 Message Date
nvrl b3ea564c6b docs(bugs): keep the index newest first 2026-10-31 19:29:29 +01:00
nvrl 463c97a14d Merge branch 'chore/sdk-0.10.1' into fix/clean-stop-runtime
# Conflicts:
#	docs/BUGS.md
2026-10-31 19:29:05 +01:00
nvrl 40aa8016ea Merge branch 'fix/sim-flakes-and-open-race' into chore/sdk-0.10.1
# Conflicts:
#	docs/BUGS.md
2026-10-31 19:26:47 +01:00
nvrl 176112a9cb 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.
2026-10-31 19:09:23 +01:00
nvrl 7957e1ed59 chore(deps): bump proton-sdk and proton-drive-rs to 0.10.1
0.10.1 decrypts address key tokens with every account key that opens,
not only the active ones, and leaves out an address whose keys do not
open instead of failing the account. That is the likely cause of issue
#40, a mount that retried "missing key" forever (B265).
2026-10-31 13:48:01 +01:00
6 changed files with 170 additions and 20 deletions

No files matched your search

Generated
+4 -4
View File
@@ -3779,9 +3779,9 @@ dependencies = [
[[package]]
name = "proton-drive-rs"
version = "0.10.0"
version = "0.10.1"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "8f70318394b2815b009c52f804d75747086db93a338ceb6eae62541f2b25d5bf"
checksum = "a8fa2a88130883010b32035e208aaa36fb275f6d7d78ed44a1069b1d33d24481"
dependencies = [
"async-trait",
"base64 0.23.1",
@@ -3806,9 +3806,9 @@ dependencies = [
[[package]]
name = "proton-sdk"
version = "0.10.0"
version = "0.10.1"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "4196392032f56b3bbaac0bb1f24eea62fa7e2a0af72004de8d08e518d14720fb"
checksum = "af0bf8d50fa829d1a65b09c6855b606578d02734d4089874c971d1063c23c353"
dependencies = [
"aes-gcm 0.11.1",
"async-trait",
+2 -2
View File
@@ -15,8 +15,8 @@ keywords = ["proton", "drive", "fuse", "sync", "linux"]
categories = ["filesystem", "command-line-utilities"]
[workspace.dependencies]
proton-sdk = { version = "0.10.0" }
proton-drive-rs = { version = "0.10.0" }
proton-sdk = { version = "0.10.1" }
proton-drive-rs = { version = "0.10.1" }
# Internal crates.
pdfs-core = { path = "crates/pdfs-core" }
+60 -3
View File
@@ -2527,14 +2527,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`"
);
}
// 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)?,
@@ -4146,6 +4162,47 @@ fn control_request(req: CtlRequest) -> Result<CtlResponse> {
.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::*;
+74 -5
View File
@@ -72,7 +72,6 @@ original wording.
| [B273](#b273--a-restore-proposes-another-computers-paths-when-the-two-share-a-hostname) | A restore proposes another computer's paths when the two share a hostname | Not fixed |
| [B270](#b270--one-file-left-in-a-mirror-folder-clears-the-wipe-guard-for-all-the-others) | One file left in a mirror folder clears the wipe guard for all the others | Not fixed |
| [B267](#b267--a-key-failure-at-a-start-from-a-warm-cache-shows-as-offline-for-good) | A key failure at a start from a warm cache shows as offline for good | Not fixed |
| [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 | Needs an SDK change; not reproduced |
| [B134](#b134--a-file-deleted-online-while-the-drain-checks-its-write-is-kept-as-a-conflict-copy) | A file deleted online while the drain checks its write is kept as a conflict copy | Only with `local_first` off |
| [B91](#b91--the-daemon-hung-overnight-and-nothing-could-say-what-it-was-waiting-on) | The daemon hung overnight, and nothing could say what it was waiting on | The cause is not diagnosed; the daemon now reports where it is stuck and is restarted |
| [B67](#b67--fresh-state-restore-can-silently-select-a-new-device-high-22) | Fresh-state restore can silently select a new device (HIGH-22) | An ambiguous device after a loss of local state is not asked about |
@@ -110,12 +109,14 @@ 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 |
| [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 |
@@ -377,6 +378,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 '<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.
---
### B275 — On a slow link, a file's last write can land only in a conflict copy
**Status:** Open
@@ -618,7 +678,7 @@ error, reads as offline. That covers every caller at once, the database ones inc
### B265 — Address keys whose token is for an inactive account key never open
**Status:** Open
**Status:** Fixed, not verified live
**Found:** 2026-10-31, code audit after issue #40: a Duo account whose mount failed on every
start with `fetch My Files root: cryptography error: failed to decrypt: missing key`, after three
`failed to decrypt address key token` warnings. The web app worked. B210's fix does not apply,
@@ -635,8 +695,17 @@ already reports "token is for inactive account key", so the case is known. Separ
`addresses()` fails as a whole through `?` when one address has no usable primary key, which
takes the working addresses down with it.
**Fix.** Not done, and it belongs in the SDK. Use every account key that opens for decrypting
tokens, and only the active ones for signing. Skip and log an address that cannot be opened.
**Fix.** In `proton-sdk` 0.10.1 (narrrl/proton-sdk-rs#3). Tokens are tried with every account
key that opens, active ones first, and signing uses active keys only. An address that cannot be
opened is left out with a warning, and the others work; `addresses()` fails only when none
opens. When the left-out address is the default, `default_address` fails with the reason
rather than signing with another address. `key_report` walks the same chain, so `pdfs diagnose`
reports such a key as opening. Not verified against an account with an inactive key, since
none is at hand; issue #40's reporter can confirm.
**Test:** `an_address_key_whose_token_is_for_an_inactive_account_key_opens`,
`an_address_whose_keys_do_not_open_leaves_the_others_working` and
`an_account_whose_addresses_all_fail_to_open_is_an_error` in `proton-sdk`.
---
+1 -1
View File
@@ -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 |
+29 -5
View File
@@ -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)
# --------------------------------------------------------------------------