Files
proton-drive-linux/docs/bugs.md
2026-07-20 14:52:31 +02:00

56 KiB
Raw Permalink Blame History

Bugs & side findings

Running tracker for bugs and loose ends spotted while working on something else — so they don't get lost when the session that found them ends.

Conventions:

  • Open / Fixed (unverified) / Fixed / Won't fix
  • "Fixed (unverified)" means the code change is in but nobody has driven the real flow against it yet. It stays that way until someone does.
  • Record how it was found, not just what it is. The repro is the expensive part.

B1 — FUSE rename loses the file (data loss)

Status: Fixed (verified 2026-07-20) Found: 2026-07-19, user reported mv file.mkv dir/ on the mount deleted the file Verified: the exact repro below on the new daemon — mv returns 0, the file is present in the destination listing and reads back its content. Previously it was in neither directory. Where: crates/pdfs-fuse/src/lib.rs, Filesystem::rename

rename ended with:

st.forget(&uid);
st.children.remove(&newparent);   // memory only

forget() deletes the node's DB row (db.delete_node). children.remove() only drops the in-memory listing, leaving nodes.listed = 1 on the destination folder. The next ls goes through ensure_children, which takes the DB fast path (children_if_listed, lib.rs:722) and rebuilds the destination from the database — where the node no longer has a row.

Net effect: file gone from the source, absent from the destination, and rename(2) returned 0. Silent loss with a success code.

Severity is worse than "stale cache": listed is a DB column, so the bad state survives a daemon restart. Nothing clears it on its own — the affected folder keeps serving the listing that omits the file indefinitely, until an event invalidation or a manual refresh happens to hit it. Confirmed on the repro folders, which still read listed=1 with no child rows minutes later.

The data itself is believed intact server-side (the move succeeded; only the local view is wrong), but that was not verifiable without a daemon restart — see the status line.

Also hits plain in-place renames (mv a.txt b.txt), same mechanism — the parent is both source and destination there.

The control-socket Core::move_to path was always correct; it used invalidate_listing, which clears the DB flag as well. The FUSE path didn't.

Fix: use the same helper.

st.forget(&uid);
st.invalidate_listing(newparent);

Repro:

cd <mount> && mkdir d && echo hi > f.txt && mv f.txt d/
# renameat2(...) = 0, but f.txt is in neither directory,
# not in trash, and absent from the `nodes` table

Note on invalidate_listing: it early-returns when the folder isn't in the in-memory children map, so it won't clear a stale DB listed flag in that case. Safe on this path (both lookup_child and the explicit ensure_children(newparent) guarantee the listing is resident), but it's a sharp edge for other callers. See B4.


B2 — The reported .mkv went to trash, the repro vanished entirely

Status: Partly resolved — mv exonerated; trash origin still unattributed Found: 2026-07-19, while chasing B1

What was settled (2026-07-19)

mv never trashes. Three repros on the mount, all with the old (pre-B1-fix) daemon:

repro node state destination result
zz-claude-repro-src.txt create still queued fresh folder vanished, not trashed
zz-b2-settled.txt settled, real uid, landed listed folder vanished, not trashed
zz-b3 Movie Title.mkv settled folder named as the file's stem (the user's exact shape) vanished, not trashed

So B1 fully explains the disappearance, and nothing in the rename path trashes. The .mkv reaching the trash has a different cause.

The listing the user acted on was almost certainly stale. B1/B4 make stale listings persistent — listed = 1 lives in the DB and survives restarts — so ls showing the file at 15:57 is not evidence it still existed remotely. This is the most likely reading: it had been trashed earlier and the mount kept showing it.

Ruled out:

  • Sync engine. reconcile_folder gates on mode == "mirror"; ~/Videos was ondemand from 15:39:27. All three sync trash sites log, and no such rows exist.
  • Log pruning hiding the evidence. ACTIVITY_KEEP = 2000; the table is at the cap but its oldest row is Jul 17 18:03, so the whole window is covered. The .mkv's uid appears exactly once — an Upload at 06:07:56 — and never again.
  • Conflict machinery. keep_as_conflict_copy uploads a new file under an alternate name; it never trashes the original.
  • Eviction through the mount. Was the best theory: mirror→ondemand calls evict_dir_contents, which would issue one unlink(2) per file, and FUSE unlink trashes remotely. But apply_sync_folder_mode evicts before spawn_ondemand_mount, so the deletes hit the plain local directory. Dead.
  • Control-socket delete. CtlRequest::Delete logs on both success and failure.

What remains: trash_child (backing FUSE unlink/rmdir) was the only trash path that wrote no activity row — so an ordinary rm on the mount, at any point after 15:39:27 when ~/Videos became a FUSE mount, would produce exactly what we see and leave no trace. Note there is also a trashed folder of the same name (Evangelion 1.11 - You Are (Not) Alone, is_dir=1, content mtime 04:57:50), which suggests this mkdir-and-move dance had been attempted earlier — plausibly followed by a manual cleanup while B1 was making files appear to vanish.

That is a hypothesis, not a finding. It is not provable from the evidence that survives.

Fix applied

trash_child now logs to the activity feed on both success ("trashed from the mount") and failure, matching every other trash site. The next occurrence will be attributable — which is the part that actually mattered here.

If it recurs

The activity log is now the first place to look. trash rows carry no trashed-at timestamp (the mtime column is the node's content mtime — for the .mkv it read 06:07:56, matching its upload, not its deletion), so the activity feed is the only ordering evidence there is.

Two different endings for what looked like the same operation, so B1 may not be the whole story:

  • User's Evangelion 1.11 - You Are (Not) Alone.mkv → trash, full size (1768670449) intact, recoverable via pdfs restore.
  • Clean repro (zz-claude-repro-src.txt) → gone entirely. Not in trash, no nodes row, nothing in the search index.

B1 explains the second. It does not explain a node reaching the trash — nothing in the FUSE rename path calls trash_nodes.

Leading theory: the trash came from the sync-conflict machinery, which is logged (ActivityKind::Trash rows exist with (sync-conflict <ts>) details). The ~/Videos folder is registered as a sync folder in ondemand mode, and had just been switched to ondemand shortly before. reconcile_folder gates on mode == "mirror", so it should have been inert — worth confirming that gate actually held, and that no pass was already in flight across the switch.

Note the file was a conflict-copy sibling of two files already carrying -003 / -004 suffixes, so the conflict path had definitely been active in that directory.

Next step: find the trash event's origin. The activity log had no row at the 15:58 mv, which points away from a logged (control-socket / sync) path — but the timestamp bug in B3 made that table hard to read, so re-check with correct scaling before trusting the absence.


B3 — Activity log timestamps written in seconds, read as milliseconds

Status: Not a bug — investigator error, kept as a record Found / retracted: 2026-07-19

Originally filed because every activity row rendered as 1970-01-21 …. That was an artifact of the ad-hoc debugging query, which divided by 1000; the code never does. Seconds are consistent end to end:

  • writer — log_activity uses now_secs() (pdfs-fuse/src/lib.rs)
  • schema / activity_list — pass the value through untouched
  • reader — activity_time calls glib::DateTime::from_unix_local(secs)

The correct manual query, for next time:

select datetime(time,'unixepoch','localtime'), kind, target, detail, ok
from activity order by time desc limit 40;

Worth noting because the bad query is what made the activity log look empty around the reported mv — which is evidence B2 leans on. That absence has since been re-checked with correct scaling and it does hold: no row at 15:58.


B4 — invalidate_listing silently skipped non-resident folders

Status: Fixed (verified 2026-07-20, via B1's repro — the FUSE rename path that depends on this helper now behaves correctly end to end) Found: 2026-07-19, reviewing the B1 fix Where: crates/pdfs-fuse/src/state.rs:257

if self.children.remove(&ino).is_none() {
    return;              // never clears the DB `listed` flag
}

The early return assumed "not in the hot cache ⇒ nothing to invalidate", which stopped being true once listings became DB-backed. A folder trimmed from the in-memory map but still listed = 1 in the DB could not be invalidated at all — callers thought they had dropped the listing, and ensure_children would happily rebuild the stale one.

Fix: drop the early return; always clear the flag. Costs one redundant UPDATE when nothing was cached.

Core::refresh_dir had been hand-rolling a workaround for exactly this (clearing the DB flag itself, then reaching into state.children directly, with a comment explaining why it couldn't use the helper). It now just calls invalidate_listing. Behaviour change worth knowing: refresh_dir used to propagate a DB write failure to the caller of CtlRequest::Refresh; it now warns and reports success, matching every other invalidation site.

Test: a_deleted_child_leaves_a_listed_parent_serving_a_stale_listing in pdfs-core/src/db/tests.rs pins the B1/B4 mechanism at the DB layer — a deleted child plus a still-listed parent yields a listing that silently omits it.


B5 — ls -l costs a network round trip per file (thumbnail xattr probes)

Status: Fixed (verified 2026-07-20) Found: 2026-07-19, investigating "exa -l is slow in the mounts, exa is fast"

Reproduced (2026-07-19)

All runs cold (35 s wait to clear the 30 s attr TTL). exa needs only readdir; exa -l stats every entry, so the delta is per-entry metadata cost:

mount entries exa exa -l delta per entry
primary ~/ProtonDrive/Installer 34 10 ms 11 ms 0.03 ms
on-demand ~/Documents 45 27 ms 54 ms 0.6 ms
on-demand ~/Videos/[Reaktor] FMA … 65 73 ms 193 ms 1.85 ms

Cause (2026-07-20): a network round trip per file per xattr name

strace -f -T on a cold exa -l of the 65-file .mkv directory:

lgetxattr(".../E01 ....mkv", "user.proton.thumbnail", NULL, 0) = -1 ENODATA <0.186435>

129 lgetxattr and 258 llistxattr calls for 65 entries, each lgetxattr ~186 ms. Three things compounded:

  1. listxattr advertised user.proton.thumbnail + user.proton.preview for every file, regardless of whether that file could have one. An xattr-aware lister then asks for each advertised name — two getxattr per entry.
  2. Core::thumbnail cached only success. download_thumbnail returning None — the normal answer for a .mkv — was never remembered, so every listing re-asked the API and was re-told nothing, forever.
  3. getxattr ran inline on fuser's dispatch loop, not on the Workers pool. lookup and readdir had been moved off it (PERF #1.0); this one was missed. So each 186 ms miss stalled every other op on the mount, which is why the concurrency exa does have bought nothing.

The mount-kind correlation was a red herring. It tracks file type, not the fork: ~/Videos is .mkv (Proton generates no thumbnail — always a miss), ~/ProtonDrive/Installer is installers whose probes were already warm. The fork_state theory in the previous write-up is wrong; forked and primary mounts run the same code and neither is at fault. Worth noting as a lesson — three measurements on different directories looked like a mount-kind effect because nobody had varied file type independently.

Fix

  • listxattr advertises the names only for image/* and video/* media types. getxattr still honours an explicit request for an unadvertised name, so nothing becomes unreachable. Everything else — documents, installers, archives — now costs zero round trips per listing.
  • Core::thumbnail remembers misses in no_thumbnail, keyed (uid, type) and validated against the node's mtime exactly as the positive side is. Bounded by clearing at MAX_THUMBNAIL_MISSES (8192).
  • getxattr hands off to Lane::Meta, so a miss can never block the dispatch loop.

A video directory still pays its misses once per revision (image/video is where a thumbnail plausibly exists, so the probe is legitimate) — but in parallel, and never again.

Verified (2026-07-20)

Cold runs (40 s wait each) on the restarted daemon:

measurement before after
~/Videos/…FMA… (65 .mkv) cold exa -l 193 ms 14 ms
~/Documents (45 entries) cold exa -l 54 ms 13 ms
user.proton.* probes over the 65 .mkv 130 0
~/Documents probe latency, 1st listing 124–395 ms 124–395 ms
~/Documents probe latency, 2nd listing 124–395 ms 0.26–0.67 ms

Each part of the fix is separately visible in the traces:

  • The advertising gate. The .mkv directory now issues zero user.proton.* probes; the only remaining lgetxattr is exa's own security.selinux at ~0.3 ms. Note this means Proton does not report those files as video/* — the gate is excluding them by media type, not because they are known to lack a thumbnail. A video whose media type is generic no longer advertises one even if it has it; getxattr still serves an explicit request, so it stays reachable. Worth revisiting if thumbnails ever go missing in a file manager.
  • The negative cache. ~/Documents holds 10 .png files, correctly still advertised, so it probes 20 times on both passes — but the second pass answers in 0.26–0.67 ms instead of going to the wire. That is the whole point: the probes that are legitimate stop being expensive after the first.
  • The worker handoff. Pass 1 on ~/Documents shows interleaved <... lgetxattr resumed> lines across several tids, i.e. the misses now overlap instead of serializing behind the dispatch loop.

Secondary finding (still open): lookup is O(n) per name

Where: crates/pdfs-fuse/src/lib.rs, serve_lookup

serve_lookup linear-scans the parent's children comparing names, and with no readdirplus that is one lookup per child — O(n²) name comparisons under the global state lock for a listing.

Real, but not what made this slow: it costs the same on both mount kinds and at 65 entries a linear scan is nanoseconds against a 186 ms round trip. Two candidate optimizations were considered and deliberately not applied, and that judgement still holds now the real cause is known:

  • Per-directory name -> ino map. A second structure that must stay in sync with children — the two-halves-of-one-cache shape that caused B1 and B4.
  • readdirplus (fuser 0.17 supports it; we return ENOSYS). The right shape long-term, but it is a rewrite of the directory-read path and it would have hidden this bug rather than explained it.

Measurement notes for next time

  • Cold requires a 35 s wait per run (30 s attr TTL). Warm runs show ~6 ms regardless and prove nothing.
  • strace -c on exa needs -f — exa is multithreaded, and without it the trace captures only main-thread startup (3 statx calls, no getdents).
  • -T (per-call durations) is what cracked this; -c summaries attribute time across threads in a way that hid the 186 ms constant.

B6 — Daemon sets no file modes: control.sock is an unguarded authority

Status: Fixed (verified 2026-07-20) Found: 2026-07-19, while writing the plaintext-at-rest threat model in docs/ARCHITECTURE.md §8. Not from a report — from checking a claim before asserting it in a doc. I had written "their default 0700 permissions protect them", went to verify, and found we set no modes at all. Where: crates/pdfs-fuse/src/lib.rs (UnixListener::bind(control_socket)), crates/pdfs-core/src/config.rs (create_dir_all on state/cache dirs)

grep -rn "set_permissions\|from_mode" crates/pdfs-core/src crates/pdfs-fuse/src returns exactly one hit, and it is shell.rs setting 0755 on a generated script. Nothing else sets a mode. So:

  • state and cache directories are created at 0777 & ~umask — typically 0755
  • control.sock is bound at the same, typically 0755

Anything that can connect to the socket drives the daemon with its authenticated session: enumerate the tree, read file contents, upload, trash, create public share links. No credential is required — the keyring is never consulted, because the daemon already holds the session.

The only thing preventing this today is that ~/.cache and ~/.local/state are conventionally 0700. That is a property of the user's system, not something we establish or check. It does not hold on a machine with a permissive umask, a group-shared home, or a home restored from a backup that flattened modes.

Severity: low on a single-user desktop, real on a shared or multi-user host. It is a privilege boundary rather than a data-at-rest issue, which is what makes it worth more than the cache-plaintext point it was found next to.

Fix: chmod 0600 on the socket immediately after bind (before the listener thread starts accepting), and 0700 on the state and cache directories at creation. Both are a few lines. Worth also asserting the socket mode in a test, since a regression here is silent.

Fixed 2026-07-19: AppDirs::ensure now sets 0700 on the state, cache, and config directories on every start (not just at creation, so an existing permissive directory is tightened), and config::restrict_socket sets 0600 on both the control socket and the tray socket immediately after bind. A socket whose mode cannot be set takes the daemon down rather than serving unguarded; the tray's is best-effort, since it only guards single-instancing. Unit tests in config.rs assert both modes.

Verified 2026-07-20 on the restarted daemon — all three directories now read drwx------ and both sockets srw-------, against drwxr-xr-x / srwxr-xr-x before.

Measured exposure at the time of the fix: the directories really were drwxr-xr-x and the live socket srwxr-xr-x, but ~/.cache and ~/.local were both 0700 on this machine, so nothing was reachable in practice. The bug was a latent dependency on those parents, not a live hole. Removing the dependency is the point.


B7 — renamed directory reads as missing until the entry TTL expires

Status: Fixed (verified 2026-07-20) Verified: mkdir "zz-b7 Old Name" with a file inside, mv to a new name, then an immediate ls and cat through the new name — both succeed with no wait. The directory used to return ENOENT until the entry TTL expired. Found: 2026-07-19, user renamed a folder on the mount with mv. ls of the parent listed the new name, but ls <newname>/ returned ENOENT — repeatedly, so not a one-shot race. It self-healed on its own a few minutes later, and the files were all intact: this is a visibility bug, not data loss. Where: crates/pdfs-fuse/src/state.rs, State::relocate

Cause: the online rename path ended with relocate, which called forget on the moved node. forget drops the node's by_uid mapping, so when the invalidated parent listing re-enumerated, intern_mem allocated it a fresh inode. But the kernel had already carried the renamed dentry over to the old inode number, and it holds that dentry for the entry TTL. Every lookup, getattr and opendir through it resolved to an inode entries no longer held:

entries.get(old_ino) -> None -> ENOENT

readdir of the parent went the other way — it walks children and reports the new inode — which is exactly why the directory listed fine but could not be entered. Once the TTL expired the kernel re-looked-up the name, got the new inode, and everything worked again.

Fix: relocate now rewrites the node in place (rename_in_place) and invalidates both parents' listings, instead of forgetting it. The inode is preserved, so the kernel's dentry stays valid and the re-enumeration reuses the same by_uid slot. Both relocate tests now assert inode stability; that property was untested, which is how this got through the B1 fix.

Note: dropping the forget also stops the moved node's DB row from being deleted and re-created on every move — the row is updated instead, which is what the B1 fix was working around from the other side.


B8 — no way to complete a CAPTCHA, so a gated sign-in is unrecoverable

Status: Implemented, partially verified — the bridge is proven, a real gate is not Found: 2026-07-19, user hit proton api error Unknown (http 422): For security reasons, please complete CAPTCHA and had no way to answer it. Where: SDK api.rs/http.rs/session.rs, pdfs-core/src/auth.rs, pdfs-gui/src/app/pages/verify.rs

Cause: three gaps stacked, none of which is a bug on its own.

  1. ResponseCode had no 9001, so the gate deserialized to Unknown — which is why the error read as an opaque failure rather than a recoverable prompt.
  2. Nothing read Details.HumanVerificationToken, and the client never sent the x-pm-human-verification-token{,-type} headers the retry needs.
  3. No UI could render Proton's hosted verification page.

Fix: HumanVerification (challenge) + HumanVerificationCredential (answer) in the SDK, header plumbing on the session-less login calls, and ProtonApiSession::begin_verified. pdfs-core promotes a solvable gate to Error::HumanVerificationRequired and auth::login_interactive re-runs the login with the earned token — the retry lives in core because the gated attempt burns its SRP handshake, which no front-end should have to know. The GUI hosts the page in a WebKitWebView (webkit6 0.4, pairs with the existing gtk4 0.9) and bridges the page's postMessage to a script message handler.

Deliberately not done: email/sms verification methods (the token arrives out of band, so the webview cannot complete them — such a gate stays a plain API error rather than opening a page the user cannot finish), HV on authenticated endpoints (only the login path is plumbed), and re-gating of the retry (a second challenge means the token was rejected; looping would trap the user).

Verified: the WebKit bridge end-to-end with a throwaway probe — handler registers, the page's postMessage arrives, non-completion messages are filtered, the completion token round-trips. Unit tests cover 9001 parsing, the challenge/Details shape, URL escaping, and message filtering.

Not verified: a real gated login against verify.proton.me. It cannot be triggered on demand, so the exact message shape Proton's page posts is taken from its documented contract, not observed. If verification appears to hang with the page solved, that is the first thing to check — extract_token in verify.rs is the single place that decides what counts as completion.

Note: the SDK half shipped as proton-sdk / proton-drive-rs 0.1.11. The workspace requirement was widened to "0.1" at the same time, so later 0.1.x releases are picked up by cargo update without an edit here.


B9 — Enter did not open the selected result in the launcher

Status: Fixed (verified) Found: 2026-07-19, user reported Enter doing nothing in pdfs-prompt while the arrow keys and Escape worked normally. Where: crates/pdfs-gui/src/prompt.rs, the window key controller

Cause: key-event phase, not key handling. gtk4::Entry — really its inner GtkText — binds Return to its own activate and consumes it. The launcher's EventControllerKey is attached to the window in the default bubble phase, so the focused entry saw Return first and the window handler was never reached. Escape and Up/Down worked precisely because GtkText has no bindings for them and they bubbled up as intended.

That asymmetry is the tell: when some keys reach a window-level controller and others silently don't, the ones that don't are being claimed by the focused widget.

Fix: Return moved off the window controller and onto entry.connect_activate. Enter while focus is in the results list was already handled by row_activated, so the two together cover both focus positions.

Rejected alternative: setting the window controller to PropagationPhase::Capture. It fixes the symptom by putting the handler ahead of the entry — but ahead of it for every keystroke, not just Return, which puts text input and IME composition behind a handler that has no business seeing them. The narrow fix has no such blast radius.

Verified: live. Pressing Enter logged opening path=…, the daemon hydrated the file, and xdg_open ran.


B10 — GLib critical when the launcher closes over an in-flight open

Status: Open (side finding) Found: 2026-07-19, seen in pdfs-prompt output immediately after a successful Enter-to-open while verifying B9.

GLib-GIO-CRITICAL: g_list_store_remove: assertion '!g_sequence_iter_is_end (it)' failed

What is known: it fires right after the opening path=… log line, i.e. during xdg_open + window.close(). It is a warning, not a crash — the open itself succeeded.

What it is not: the launcher's own row handling. Section::set_rows walks GtkListBox children (first_child/remove) and touches no GListStore, so the failing store belongs to GTK/libadwaita internals, most likely something teardown-ordering related in the app/window bookkeeping as the window is closed while a launch is still settling.

Why it was not chased: it appeared while verifying an unrelated fix and has no user-visible effect. Worth revisiting if the launcher ever misbehaves on close (a hang, a lost open, or a stale window), since an assertion firing during teardown is exactly the shape of bug that later turns into one of those.

Where to start: run pdfs-prompt under G_DEBUG=fatal-criticals to turn the warning into an abort and get a real backtrace naming the store.

B11 — a file moved while its create is still queued reads as empty

Status: Fixed (verified 2026-07-20) Found: 2026-07-20, while verifying B1 on the restarted daemon.

The B1 repro is echo hi > f.txt && mv f.txt d/, i.e. the move lands while the create is still queued for upload. Immediately after the mv, the file is present in the destination listing — B1 is genuinely fixed — but stats as 0 bytes and cat returns nothing:

-rw-r--r-- 1 narl narl 0 Jul 20 00:29 zz-b1-dst/zz-b1-src.txt

A few seconds later the same file reads correctly (3 bytes, hi). A control file created and read without an intervening mv was correct immediately.

Cause: State::intern_mem replaces an existing entry's node wholesale (e.node = node). A move invalidates both parents' listings (that is B7's fix, and it is correct), so the next ls re-enumerates — and the node that comes back, from the remote or from its DB row, carries the size of the revision the server holds. For a file whose write is still queued that is the pre-write size, usually 0. Interning it reverts the optimistic size record_pending_write had stamped.

Why an empty read rather than a short one: a file that stats as 0 bytes gets no read from the kernel at all. read_range would have served the staged blob quite happily; it is never asked. So the file reads as empty for as long as the stale size stands, and "empty file" is indistinguishable from "file whose contents were lost" to whatever is reading.

Core::hydrate already solved exactly this for the restart case — it stamps each pending write's size onto the node as entries materialize. The protection was simply missing on every live re-enumeration path.

Fix: Core::stamp_pending_sizes re-applies the optimistic size to a batch of nodes, called from both arms of ensure_children (the DB fast path and the network path) before the state lock is taken. It snapshots the pending map first and returns: no site in the daemon holds pending and state at once, and this is not the place to become the first — hydrate established that pattern for the same reason.

Scoped to ensure_children deliberately. The other intern sites are single-node and all authoritative by construction (mkdir, create, an upload that just landed); drain.rs's post-upload adoption is supposed to take the server's node, and already handles the queued case through rebaseline_pending.

Tests: pending_size_tests in pdfs-fuse/src/lib.rs covers the queued file keeping its size, a settled sibling keeping the server's, folders being left alone, and an empty pending map changing nothing.

Verified 2026-07-20 on the rebuilt daemon: echo hi > f.txt && mv f.txt d/ then an immediate ls -l and cat gives 3 bytes and hi, against 0 bytes and empty output before.


B12 — cold enumeration is slow per entry, and goes superlinear past ~500

Status: Both causes fixed and verified (2026-07-20); attr-invalidation follow-up unverified Found: 2026-07-20, measuring improvements.md P2.8 ("pipeline enumerate_nodes_detail") before implementing it, to decide whether the bottleneck was network or crypto.

Measured (cold; pdfs refresh <dir> then a timed ls -1)

entries time per entry
1–9 350–550 ms fixed cost
34 629 ms —
147 1.92 s 12.5 ms
251 3.18 s 12.4 ms
484 6.25 s 12.5 ms
793 38.8 s 48.9 ms

The 793 figure reproduces to ±100 ms across three runs. Marginal cost from 484 to 793 is 106.7 ms/entry, 8.5× the baseline.

perf record against the running daemon shows ~90 % of cycles inside the pdfs binary in both cases, and sample counts matching wall time (1022 samples ≈ 5.1 s, 7538 ≈ 37.9 s at 199 Hz) — so this is CPU-bound throughout, not waiting on the network. Symbols are unavailable (the installed binary is stripped), which is what blocks attribution.

Cause 1 (found, ~half the baseline): every FTS row is deleted by a full scan

nodes_fts declares uid as UNINDEXED:

CREATE VIRTUAL TABLE nodes_fts USING fts5(uid UNINDEXED, name, tokenize='trigram')

and Db::upsert_nodes (pdfs-core/src/db/nodes.rs) deletes by exactly that column on every node, because "FTS5 has no UPSERT":

DELETE FROM nodes_fts WHERE uid = ?1

An UNINDEXED FTS5 column is not searchable, so the predicate cannot use an index. EXPLAIN QUERY PLAN confirms it:

`--SCAN nodes_fts VIRTUAL TABLE INDEX 0:

One full scan of the FTS index per node written. Measured on a .backup copy of the live 171 MB DB (17 443 indexed nodes):

deletes time per delete
484 3.09 s 6.4 ms
793 5.26 s 6.6 ms

So ~6.5 ms of the 12.5 ms per-entry baseline is this one statement, and it gets worse for every user as their node count grows — the scan is over the whole index, so the cost of writing any listing scales with the size of the account. It is also paid by every sync pass and every event-driven refresh, not just ls.

Fix direction: delete by rowid instead. FTS5 deletes by rowid efficiently, so map nodes.rowid to the FTS rowid and drop the uid column from the index (or keep it UNINDEXED purely for retrieval). Needs a schema migration on a live 171 MB DB, so it wants its own change rather than being smuggled into this one.

Cause 2 (the dominant one): an S2K key derivation per file, to list a folder

Symbols came from the local unstripped build, not a new install. strip preserves both the build id and the text addresses, so when /usr/bin/pdfs and target/release/pdfs reported the same build id, the stripped binary was just a copy of the local one and perf buildid-cache -a target/release/pdfs was enough to symbolise a recording of the running daemon. Worth remembering — it turned a "needs another install + restart" into a five-second step.

Hot functions over a 793-entry cold enumerate:

% symbol
64.4 sha2::sha256::x86::digest_blocks
6.0 <D as digest::DynDigest>::update
5.7 sqlite3VdbeExec (cause 1, above)
4.0 sha2::sha256::compress256
1.5 pgp::types::s2k::StringToKey::derive_key

~74 % of the listing is SHA-256 inside PGP's S2K, i.e. the per-file node-key unlock that build_node does under NodeDetail::Full. derive_key itself shows 1.5 % because the time lands in its SHA leaf. Nothing downloads during an ls, so PGP is the only plausible source of that SHA.

The "cliff past ~500" framing was wrong

That was an inference from a single folder, not a measurement. An S2K's cost is set by the iteration count in the key packet, which is chosen by the client that uploaded the file — so it varies per file, not per listing size. Every folder measured sits at 12–16 ms/entry except Music/aC_ID.dll at 49 ms, and Music/ELDEN RING SOUNDTRACK (67 files, same parent tree) is ~16 ms/entry, so it is not "Music files are expensive" either. A 4× jump for a 1.6× change in n fits "those files were uploaded by a client using a costlier S2K" far better than a size threshold. n and folder identity are confounded in the data — there was only ever one folder above 500 entries.

Left unresolved deliberately: the fix below removes the per-file S2K from the listing path entirely, so which of the two explanations held stopped mattering. To settle it anyway, log the S2K iteration count per file across one enumerate of each folder.

Fix: enumerate cheap, upgrade sizes in the background

ensure_children now calls enumerate_nodes_light, which skips the file node-key unlock (folders are still unlocked — their keys are what the children decrypt with). The listing is served from that immediately.

Light returns no claimed_size, and ls -l wants sizes, so a naive split would just move the same S2K onto the first stat. Instead Core::spawn_size_upgrade fetches the full nodes for that folder on a worker, batched, after the listing has been answered, and adopts only the size — re-interning wholesale would clobber a name or parent that a concurrent rename/move had changed. It is single-flight per folder, because a stat of one entry in a fresh listing means a stat of all of them. Queued writes keep their optimistic size through it, via the same stamp_pending_sizes that B11 added.

Three entry points cover every way a provisional listing can appear: the network enumeration, the DB fast path (rows persisted before an upgrade ran), and getattr itself (a listing restored by hydrate on mount, which ensure_children returns early for).

Known tradeoff — sizes are provisional until the upgrade lands. node_size falls back to total_size_on_storage, the ciphertext size, so a stat in that window reads slightly too large. Reads are unaffected: the revision reader carries its own authoritative size. Deliberately not the B11 shape — that reported 0, which made the kernel skip reads entirely; too-large is cosmetic and self-corrects.

The window was longer than "a round trip", and that took a correction. The daemon has the real sizes quickly, but the kernel keeps the provisional attrs for the full 30 s entry TTL, so ls -l kept reporting them long after the DB was right. This nearly caused a misdiagnosis during verification: two successive ls -l runs agreed with each other and both disagreed with the truth by a constant +59 bytes, which reads exactly like "the upgrade never ran". Querying the DB directly is what separated "not computed" from "computed but not visible".

Closed by having spawn_size_upgrade call notifier.inval_inode for the inodes it corrected, after the DB write so a provoked re-getattr cannot race the persistence. That needed a Notifier on Core (a OnceLock, since the session is built from the Core), and a fresh one per on-demand fork — each fork has its own inode space, so notifying through the primary mount's channel would name inodes that session has never heard of.

Verified (2026-07-20)

folder before after
Music/aC_ID.dll (793) 38.8 s 4.48 s (8.7×)
InstantUpload/Camera (484) 6.25 s 2.91 s (2.1×)
Pictures/old (417) 5.10 s 2.25 s (2.3×)

Schema v15 migrated the live 171 MB DB on start (17 443 rows indexed). All 793 sizes converge to exactly their pre-change values, checked against a .backup copy taken before any of this landed. The +59-byte ciphertext delta is a precise probe for a provisional size, and is what the attr-invalidation follow-up should be tested with.

Original cause-2 ruling-out (kept — all still true)

Backing cause 1 out of the totals leaves per-node non-FTS cost at 6.2 ms at n=484 but 42 ms at n=793. Something gets ~7× more expensive per node, sharply, somewhere around 500–800 entries.

Ruled out so far:

  • Chunking / network. MAX_BATCH_COUNT = 150, so cost would rise in visible steps at 150/300/450; it is flat at 12.5 ms/entry straight through 484. The marginal cost would imply ~16 s per POST, which is absurd.
  • Composition. Both the 484 and 793 folders are 100 % files, no subfolders.
  • FOLDER_KEY_CACHE_CAP (512). Suspicious number, but folder_keys only holds folder keys and these children are all files, so nothing is inserted during the walk. resolve_parent_key_ctx caches each ancestor it derives, and all children share one parent, so it is a hit after the first child.
  • The entity cache. InMemoryCacheRepository is HashMap-backed, O(1) set.
  • FTS (cause 1). Linear — 3.1 s → 5.3 s where the cliff is 6.1 s → 38.8 s.

Next step: symbol-level profile. Needs an unstripped pdfs installed and the daemon restarted, then perf record -p <pid> across a 793-entry enumerate. Every cheaper avenue above has been spent. Note a second daemon is not an option for this: Proton refresh tokens are single-use, so a parallel session would fight the running daemon for them.

Do not implement improvements.md P2.8 before this is understood. Pipelining would parallelize the cliff rather than remove it, and at 793 entries the cliff is 33 s of the 38.8 s — far more than concurrency could win back.


B13 — rename over an existing destination fails instead of replacing it

Status: Fixed (unverified — needs a real rsync against the rebuilt daemon) Found: 2026-07-20, user ran rsync -rauLP ~/ProtonDrive/Music/... ~/Music/ (both are protondrive mounts) and every single file failed at the end of its transfer:

rsync: [receiver] rename ".../.Buunshin - heimwee (Original Mix).wav.b0akm3"
    -> ".../Buunshin - heimwee (Original Mix).wav": Input/output error (5)

Where: crates/pdfs-fuse/src/lib.rs, Filesystem::rename (~4380)

Daemon log, one per failed file:

ERROR pdfs_fuse: rename failed uid=… error=proton api error AlreadyExists (http 422):
    A file or folder with that name already exists
WARN  pdfs_fuse::drain: pending upload failed; will retry uid=… attempts=1
    error=proton api error DoesNotExist (http 422): File or folder not found

Cause: rename(2) is specified to atomically replace an existing destination. Our handler just calls client.rename_node, and Proton refuses a name that already exists — so the 422 becomes a blanket EIO. Nothing in the path ever looks up the destination name.

This breaks every write-to-temp-then-rename tool, which is most of them: rsync, editors doing atomic saves, mv -f, package managers. The failure is at the end of the transfer, so the bytes are uploaded and then thrown away — the user pays full upload cost for nothing.

Second-order damage: the failed rename leaves the temp node behind and its queued upload then fails with DoesNotExist and retries forever. So each failed file also leaves a poisoned entry in the drain queue.

Fix: rename now looks up newname under newparent and, if it resolves to a different node, removes it before the API call.

The order is forced by Proton: the name has to be free before rename_node will take it, so it is trash-then-rename, which means the operation is not atomic. Core::remove_replaced does the trashing and Core::restore_replaced puts the node back if the rename then fails — on every failing path, including the queued ones. If the restore also fails the node stays in the trash and says so loudly, because the alternative is a file the user believes was merely renamed sitting somewhere they will not look.

Deliberate details:

  • Refusals happen before anything is trashed. check_replaceable is a pure function for exactly this reason: every Err it returns is a case where the destination must survive, and a mistake there turns a refusal into deletion. EISDIR / ENOTDIR when the two ends disagree about being a directory, and ENOTEMPTY for a non-empty destination directory — Proton trashes a folder with its whole subtree, so allowing that would discard every file underneath without ever naming them.
  • RenameFlags is now read (it was _flags). RENAME_NOREPLACE returns EEXIST instead of replacing; RENAME_EXCHANGE returns EINVAL, since no Proton primitive swaps two names and emulating it would leave a window in which one of them does not exist.
  • A node whose own create is still queued never reached the server, so replacing it just discards its queued ops — no API call, and it works offline.
  • Renaming a node onto its own name stays a no-op rather than a self-replace.

Tests: replace_tests in pdfs-fuse/src/lib.rs covers all five decisions. The trash/restore half needs a live server and is not covered.

Repro: cd <mount> && echo a > x && echo b > y && mv y x → was EIO, should now succeed with x holding b.


B14 — provisional (ciphertext) sizes make rsync read short and abort the file

Status: Fixed (unverified — needs a cold folder on the rebuilt daemon) Found: 2026-07-20, same rsync run as B13. Alongside the receiver errors, the sender failed to read its own source files:

rsync: [sender] read errors mapping "/home/narl/ProtonDrive/Music/…/
    Buunshin - i think i feel... (Original Mix).wav": No data available (61)

Where: node_size (pdfs-fuse/src/lib.rs:3480) + Core::spawn_size_upgrade

Cause: this is B12's known tradeoff surfacing as a real transfer failure. Until the background size upgrade lands, node_size falls back to total_size_on_storage — the ciphertext size, which is larger than the plaintext (measured at +59 bytes on this account). B12 called that "cosmetic and self-corrects" because it only affects ls -l.

It does not only affect ls -l. ENODATA (61) is what rsync sets on a short read: map_ptr in fileio.c asks for the bytes stat promised, gets fewer, and marks the mapping ENODATA. So a reader that trusts st_size — rsync, anything using mmap, sendfile, or a sized read loop — sees a truncated file and errors out. That is the same class of bug as B11, just from the other direction: B11 reported too small (0) so the kernel skipped reads entirely; this reports too large so reads run off the end.

The 30 s attr TTL makes the window much wider than the upgrade's own latency (B12 documented this), so a cold rsync of a large tree is essentially guaranteed to hit it.

Why it looked fine afterwards: re-listing the same directory now shows every size correct, because the upgrade has long since landed. The bug is only visible cold. Reproducing it needs pdfs refresh <dir> immediately before the read.

Fix: a provisional size is never published. getattr on a file whose claimed_size is unknown now resolves it before replying, instead of replying with the ciphertext size and upgrading afterwards.

The cost is one batched round trip per folder, not one per file: ls -l is one getattr per entry, and they collapse onto a single upgrade. B12's split is still doing its job — a plain ls never reaches this path at all, which is where the 8.7× came from.

That required making the upgrade awaitable, which is most of the change:

  • size_upgrades went from HashSet<u64> to HashMap<u64, Arc<SizeUpgrade>>, a condvar per folder. Followers wait on it; there may be hundreds for one folder, so it releases all of them.
  • The leader does the fetch on its own thread rather than handing it to a worker. This is the part to not undo: getattr waits on Lane::Meta, so a leader that queued its fetch onto that same lane could have a wide enough ls -l fill the lane with threads waiting for a job that can never be scheduled.
  • SizeUpgrade::WAIT caps the wait at 10 s, falling back to the provisional size. A stat that never returns is worse than one that is briefly wrong.
  • upgrade_sizes owns the single-flight bookkeeping and has one exit path; apply_size_upgrade holds the body it used to inline, so a failed fetch still releases the waiters and leaves the folder retryable.

Tests: size_upgrade_tests covers the follower being released, a waiter arriving after finish (it checks the flag, not the notification, which it would miss), and all waiters waking.

Not covered, worth watching: Lane::Meta can now hold waiting getattrs. There is no deadlock — leaders never queue their own work — but a cold ls -l across many folders at once could occupy the lane. If metadata ops start feeling sticky under heavy cold listing, this is the first suspect.

Verified (2026-07-20) — correct, but expensive, and not completely closed

Two further holes turned up during verification; both are fixed, and the second is the one that mattered.

  1. upgrade_sizes_for_parent early-returned when the parent listing was not resident in children — and a rename invalidates exactly that, so a freshly renamed file always landed in the dead branch. stat read 67 bytes for a 16-byte file, and cat returned the 16 real bytes followed by 51 NULs. The same shape as B4: an early return that assumed the hot cache was authoritative. Now falls back to resolving the single node, keyed by its own inode.
  2. lookup replies with attrs and a TTL too. With no readdirplus, ls -l is one lookup per entry and zero getattr calls — so fixing only getattr fixed a path ls -l never takes. This is worth remembering: the first fix looked right and did nothing for the reported symptom. serve_lookup now resolves as well, taking an off_loop flag because lookup's warm path runs on the dispatch loop where it may not block (B5).
measurement before fix after fix
cold ls -l, 7-file wav folder ciphertext sizes exact settled sizes
renamed file stat / cat 67 B, 51 NULs 16 B, clean
cold plain ls, 793 entries 4.48 s 4.58 s (B12 intact)
cold ls -l, 793 entries ~4.5 s, wrong sizes 85.8 s, 785/793 correct

The cost, and the part still open

A cold ls -l of a 793-entry folder went from ~4.5 s to 85.8 s. That is not a flaw in the batching — it is B12's cause 2 arriving on schedule. A real claimed_size requires the per-file node-key unlock, i.e. one S2K per file, and that work is single-threaded. B12 removed it from the listing path; asking for sizes puts it back, because sizes are what it produces. Plain ls is untouched, which is why the split is still worth having.

8 of 793 entries still came back provisional, caught by diffing the cold listing against a settled one. Those are SizeUpgrade::WAIT timeouts: the leader takes ~80 s for the batch and a waiter gives up at 10 s. So the bug is rarer but not gone — it now needs a folder large enough that the batch outruns the cap.

Per-chunk wakeup (done, unverified)

The timeout gap is closed by releasing waiters per chunk instead of once at the end. SizeUpgrade carries a generation counter; run_size_upgrade fetches in SIZE_UPGRADE_CHUNK (150, the SDK's own MAX_BATCH_COUNT, so one chunk is one request), applies each chunk, and bumps the generation. A waiter re-checks whether its own node now has a real size and returns if so — it no longer waits on the other 792.

Two structural points worth keeping:

  • The batch runs on its own thread, not the Workers pool. Callers wait on Lane::Meta, so queueing the batch there could let a wide ls -l fill the lane with threads waiting for a job that can never be scheduled. Lane::Transfer would swap that deadlock for starvation behind bulk reads. One short-lived thread per folder, bounded by the single-flight, avoids both.
  • wait_for evaluates its predicate with no SizeUpgrade lock held. The predicate reads state, and the applying thread holds state before it signals; taking them in the other order would close the cycle.

This does not make a full cold ls -l faster — every size still has to be computed. It makes each individual stat return after its own chunk rather than after the whole folder, and removes the provisional-size fallback that the 10 s cap was producing.

Tests: size_upgrade_tests covers the resolving chunk releasing a waiter, an unrelated chunk not releasing one, finish releasing an unresolved waiter, the already-resolved and post-finish arrivals, all waiters waking, and the timeout backstop still firing.


Plan: parallelise the per-file S2K (the 85 s)

This is the only item that reduces the work rather than redistributing it, and it is the same bottleneck as improvements.md PERF #5 — approached from sizes rather than from cold navigation. Filed here because B12/B14 are what produced the measurements it needs.

The claim to be tested first, before any code. B12's profile of a 793-entry cold enumerate attributed 64.4 % of cycles to sha2::sha256::x86::digest_blocks and ~74 % overall to SHA-256 inside PGP's S2K, i.e. the per-file node-key unlock in build_node under NodeDetail::Full. If that still holds for the size upgrade path specifically — it is the same enumerate_nodes call, so it should — then the work is CPU-bound, embarrassingly parallel across files, and currently serialised on one thread.

Step 0 — confirm, do not assume. Re-profile against the size-upgrade path now that it is the thing on the critical path:

perf buildid-cache -a target/release/pdfs      # symbols; see B12's note on strip
perf record -p <daemon pid> -- sleep 90
# meanwhile: pdfs refresh Music/aC_ID.dll && ls -l Music/aC_ID.dll

Expect the same SHA-256 leaf. If it is not dominant, stop — the rest of this plan is aimed at the wrong thing.

Step 1 — establish the ceiling. The upgrade is enumerate_nodes over 793 uids. Measure single-node unlock cost directly (log the S2K iteration count and elapsed time per file across one folder — this also settles the question B12 left open, whether the 49 ms/entry folder is expensive because of n or because the uploading client chose a costlier S2K). Ideal speedup is bounded by core count and by how uneven those per-file costs are.

Step 2 — move the crypto off the async runtime. The decryption currently runs inline in the SDK's enumerate_nodes future. Blocking CPU work on a Tokio worker starves everything else sharing that runtime. Wrap the per-node unlock in spawn_blocking, or hand the whole chunk to a rayon pool and await the result. This is the change PERF #5 describes and is a proton-drive-rs change, not a pdfs one — which is why it was deferred: it needs an SDK release, and the workspace pins "0.1" so a cargo update picks it up.

Step 3 — parallelise across files within a chunk. 150 nodes per chunk, each independent once the parent key is resolved. resolve_parent_key_ctx caches the ancestor key and all children of a folder share one parent, so the parallel region needs read-only access to it — take the folder key once, then fan out. Watch FOLDER_KEY_CACHE_CAP/folder_keys (PERF #9 made it an LRU) for contention if the fan-out takes that lock per node.

Step 4 — re-measure the same three folders, which have before/after numbers already recorded above and in B12:

folder cold plain ls cold ls -l (today)
Music/aC_ID.dll (793) 4.58 s 85.8 s
InstantUpload/Camera (484) 2.91 s not measured
Pictures/old (417) 2.25 s not measured

Fill in the middle column's ls -l first — there is only one data point for the regression right now, and B12's "cliff past ~500" framing was wrong precisely because it generalised from a single folder. Do not repeat that mistake here.

What success looks like: cold ls -l on the 793-entry folder within ~2–3× of the plain ls, rather than 19×. Perfect scaling is not available — the request round trips are serial per chunk and only the crypto parallelises.

Explicitly out of scope: readdirplus. It would cut the number of calls (one reply per directory instead of one lookup per entry) and is the right long-term shape for the directory-read path, but it does not remove a single S2K — the sizes still have to be computed. It is a separate change and should not be bundled in, for the same reason B5 declined it: it would hide this bug rather than fix it.

Do not attempt to derive the plaintext size from total_size_on_storage instead. The delta is not a constant (+564 B on a 39 MB file, +51 B on a 16-byte one — it scales with block count), so the arithmetic would have to model Proton's block framing exactly, and being wrong in the small direction reproduces B11, where a short size made the kernel skip reads entirely.

Verify with: the ciphertext delta is the probe (+564 B on a 39 MB file, +51 B on a 16-byte one — it scales with block count, so it is not a constant). pdfs refresh a folder, then ls -l immediately and diff against a settled listing.


B15 — an empty-but-listed folder, and duplicated folder uids

Status: Open (side finding, unattributed). Originally filed as "a sync-folder listing came back empty"; that part was investigated and retracted — see below. Found: 2026-07-20, while confirming B13.

ls ~/Music/Buunshin/not everythin is your fault (wav)/ returns total 0 — no entries — even though the rename failures in B13 prove files existed under those names minutes earlier (Proton rejected the rename because the name was taken). The same folder read through the primary mount (~/ProtonDrive/Music/Buunshin/…) lists all seven .wav files correctly.

Checked (2026-07-20) — the "stale empty listing" reading was wrong. The folder not everythin is your fault (wav) that read empty has listed = 0 in nodes, so its ls was a real network enumeration, not a cached empty one. The files genuinely are not there: every rename in B13 failed and rsync discarded its temp files. B15 as originally filed does not exist.

What the query did turn up, and is worth keeping:

  1. A real B1-shaped row. not everything is your fault (no (wav)) reads listed = 1, trashed = 0 with zero child rows — the exact empty-but-listed state B1 was about, still present in the live DB, reached by some route the B1 fix does not cover. This one is worth chasing.
  2. Duplicated folders. Music and Buunshin each exist under two distinct uids, and the (wav) folder name appears twice as well — one copy populated (7 children), one empty. So the remote tree has picked up duplicate directories somewhere. Related to the self-conflict duplication already recorded in memory, but not yet attributed here.

Both are folder-identity problems rather than the mount disagreement originally suspected. Renamed scope accordingly; the "two mounts disagree" framing is retracted.