rclone/docs/plans/001-protondrive-tier1-workspace/task-21f-report.md

Task 21f report: read-after-write lag after commit/create

Diagnosis (verified, refined)

Both live failures come from the single read of the node in uploadDraft (upload.go) after the commit:

1. vfs revision is active, not X: the read returned the new file still as a draft (no active revision, so RevisionID == ""); the commit had returned success, so the code fell through to errUploadSuperseded.
2. fs/operations TestPurge object not found: the read returned not found; uploadDraft returned read the uploaded file: get node X: not found, which wraps errNotFound, and translateError turns any wrapped errNotFound into the bare fs.ErrorObjectNotFound. That explains why the message had no upload "one": prefix. The dircache folder creates are not the cause with caching on (default): createFolder caches its own node, so targetFolder never reads it from the server. With enable_caching = false it does read it, and the same lag breaks targetFolder. Both reproduced exactly on the fake (see RED).

What changed

• protontest: Server.SetReadLag(reads int, missing bool). After a folder create, a copy or a commit, the next reads reads of that node through POST /drive/v2/volumes/{id}/links leave the node out (new node, or missing) or return its wire form from before the commit. Off by default. Listings are not lagged.
• nodes.go: client.readBack(ctx, id, shows) reads with backoff (100 ms doubling to 2 s, readBackAttempts = 8, about 7 s), honouring ctx, while shows says the change isn't visible yet. client.readBackDelay can be lowered by tests. Used by:
  • uploadDraft, through draft.lagging: retry while not found, active with an empty revision, or (only when the commit returned success) still as before the commit (notCommitted: draft for a new file, base revision for a new revision). errUploadSuperseded now only means a non-empty revision that is neither ours nor the base.
  • copyNode: the read of the copy retries while not found.
  • targetFolder: retries while not found only when the cache is disabled. With caching on, a folder the client made is cached, so a miss means it is gone. A first version retried always, and that added 7 s to TestCreateFolder/TestMove (writing into a missing folder).
• Lag outlasting the retries after a successful commit gives the new errUploadUnconfirmed. Nothing is deleted (committed=true), and translateError maps it to NoLowLevelRetryError like errUploadOutcomeUnknown. Logged at DEBUG.
• A failed commit (commitErr != nil) keeps ruling 11. Retrying is only added for not-found and empty-revision reads, which already gave "outcome unknown", so no new deletion path.

Policy decision (recorded in docs/DECISIONS.md)

You leaned to returning success with an object built from what was committed. I didn't do that. The returned node is used directly by Object.Open (openWhole/open need n.keys, n.link.File content key packet, revision ID), and by Move/rename (link passphrase and name hash). The draft's node keyring is cleared when upload returns. A made-up node would therefore have to make up decrypted keys and server metadata, and it would be cached and acted on. So I return errUploadUnconfirmed: nothing is deleted, there is no immediate retry, and a later sync pass reads the file. If you prefer success, it is a contained change in the commitErr == nil && d.lagging(...) case of uploadDraft.

TDD evidence

RED (RCLONE_CONFIG=/notfound go test ./backend/protondrive/ -run 'ReadBackLag' -count=1, with the tests and fake lag in place, before any client change):

--- FAIL: TestUploadIntoNewFolderReadBackLag
    create folder "B1": get node 5d3b...: not found
--- FAIL: TestCopyReadBackLag
    copy "f.txt" to "copy.txt" in 0bee...: get node 4f12...: not found
--- FAIL: TestUploadReadBackLag/NewFileStale
    upload "f": upload committed, but the file now has another revision (revision  is active, not 1e97...)
--- FAIL: TestUploadReadBackLag/NewRevisionMissing
    upload "f": read the uploaded file: get node 1af9...: not found
--- FAIL: TestUploadReadBackLag/NewFileMissing
    upload "f": read the uploaded file: get node 3420...: not found
--- FAIL: TestUploadReadBackLag/NewRevisionStale
    upload "f": upload committed, but the file now has another revision (revision d623... is active, not 4e7b...)

TestPutNestedReadBackLag (Fs.Put of A1/B1/C1/one, caching on): object not found. NewFileStale is symptom 1 byte for byte, and TestPutNestedReadBackLag is symptom 2.

GREEN: same command → ok github.com/rclone/rclone/backend/protondrive 1.757s. I wrote TestUploadReadBackLagOutlasted (both stale and missing; asserts errUploadUnconfirmed, not superseded, exactly 8 link reads, no deletes, content on server) and the errUploadUnconfirmed row of TestTranslateError after the fix. I didn't watch those fail first.

Verification

• go build ./...: ok
• go vet ./backend/protondrive/...: ok
• golangci-lint run ./backend/protondrive/...: 0 issues
• RCLONE_CONFIG=/notfound go test -race -count=1 ./backend/protondrive/...: all ok (protondrive, protontest, protonfake); budget tests unchanged (lag is off by default, so no extra reads).

Files

backend/protondrive/{nodes.go,upload.go,protondrive.go,upload_internal_test.go, nodes_internal_test.go,protondrive_internal_test.go}, backend/protondrive/protontest/{server.go,drive.go,mutate.go,upload.go}, docs/TODO.md, docs/DECISIONS.md.

Concerns / not fixed (logged in docs/TODO.md)

• The real lag's length is unmeasured. 7 s is a guess, and a longer lag still fails the upload, now with a clear "committed" error.
• activeNode (Update/Move/Copy/DirMove of an object just written) has no lag tolerance. It is the most likely next live symptom ("object not found" while the node is missing or still a draft). I left it alone because tolerating lag there would delay every genuine not-found by 7 s.
• Move's read of the moved node may be stale (it can't be not found).
• After a commit that failed, a stale read showing the draft or the old revision still counts as proof and the draft is deleted. That is the pre-existing ruling 11 risk, now known to be real under lag. Retrying there would slow every refused commit by 7 s.
• The retry loop uses the upload's cancel-detached read ctx (30 s cap), so cancelling during lag after a successful commit still waits up to about 7 s.
• Listing lag is neither modelled nor handled.

Fix round 1

Critical: deletion after an ambiguous commit failure (coordinator ruling)

• uploadDraft (upload.go) now sends the commit through c.pacedCall(ctx, c.apiPacer, ...) and counts attempts. A draft is deleted only when the commit failed on its single attempt with refusedCommit: an *api.Error with a 4xx status, not 408, and a Proton code. In that case the file is not read back at all. session.call's own resend after a 401 refresh doesn't count, because a 401 attempt was never processed. 429 is retried by the pacer, so it ends up as "unknown".
• Every other failure (5xx, network, timeout, cancelled ctx, resent attempts, a 4xx without a code) gives errUploadOutcomeUnknown and deletes nothing. The read after such a failure can only turn it into a success, when it shows our revision. draft.notCommitted is gone, and its states are now among those lagging keeps retrying through.
• After a failed commit, the read goes through lag while the caller's ctx is live. If ctx is already done it reads once, detached, as before; this keeps TestUploadCancelDuringCommit's "active commit is a success".

Minors

• Empty-revision lag state: SetReadLag(reads, view LagView) now takes LagBefore, LagMissing or LagNoRevision. LagNoRevision serves the file as it is but with ActiveRevision nil. Tests NewFileNoRevision, NewRevisionNoRevision and the Outlasted view=2 case cover it.
• Ctrl-C: on the success path the read-back uses the caller's ctx, not a detached one. A done ctx stops the waits and returns errUploadUnconfirmed, with nothing deleted. Note that a ctx cancelled while the commit response is in flight still makes the pacer report the commit as context.Canceled, so that is the "unknown" path, which is also non-deleting.
• --retries duplicate revision: added to docs/TODO.md. Orphan drafts after ambiguous failures, and CleanUp / server expiry: also in TODO.
• DECISIONS: a new entry supersedes the read-back half of ruling 11. Handoff section 7 ruling 11 is rewritten.

Changed existing tests (expectations follow the new rule)

• TestUploadCancel/commit: a commit cancelled in flight now leaves its draft (1 draft, no file). It used to expect the draft deleted.
• TestUploadCommitOutcomeUnknown: the commit fault is now a 422 without a Proton code (ambiguous). A coded 422 on one attempt is now an explicit refusal and deletes, which TestUploadCommitRefused covers.

TDD evidence

RED, on top of 1b2fcbd21 with the new tests and the fake change only:

--- FAIL: TestUploadAmbiguousCommitFailureUnderLag/ResentThenRefused/existing=false   draft deletion sent
--- FAIL: .../ResentThenRefused/existing=true    revision deletion sent
--- FAIL: .../ConnectionLost/existing=false      draft deletion sent
--- FAIL: .../ConnectionLost/existing=true       revision deletion sent
  (fake log: "only drafts can be deleted" / "Draft revision not found":
   the deletes hit the committed file / active revision)
--- FAIL: TestUploadCommittedThenCancelledUnderLag   not errUploadUnconfirmed
--- FAIL: TestUploadCommitRefusedNoReadBack/existing={false,true}   file read back

ResentThenRefused is the reviewer's scenario: a 502 after the real handler commits, then the resent commit gets a 422 injected after the real handler ran, under SetReadLag(LagBefore). ConnectionLost is the same but with a single attempt that ends in a dropped connection.

GREEN: go test ./backend/protondrive/ -run 'Upload|Lag|Commit|Draft' → ok.

Mutation checks, for the tests never seen failing:

• Removing the errUploadUnconfirmed case fails TestUploadReadBackLagOutlasted (all 3 views).
• Removing the empty-revision case of lagging fails NewFileNoRevision, NewRevisionNoRevision and Outlasted/view=2.
• Removing errUploadUnconfirmed from translateError fails its TestTranslateError row. All mutations were reverted afterwards.

Verification (fix round)

go build ./... ok; go vet ./backend/protondrive/... ok; golangci-lint run ./backend/protondrive/... 0 issues; RCLONE_CONFIG=/notfound go test -race -count=1 ./backend/protondrive/... — see below. Race suite result: ok backend/protondrive 315.0s, ok protontest 36.4s, ok protonfake 1.4s. (After it ran I changed only a comment, re-wrapping the upload godoc; build and lint were re-run on it.)

Concerns (fix round)

• The real server's answer to a resent commit is unknown, which doesn't matter now because a resend is always "unknown". The real lag length is still unmeasured.
• Ambiguous failures now leave orphan drafts. They are logged in TODO (CleanUp / server expiry).
• A server that commits and then answers a coded 4xx on a single attempt would still get a delete. The rule takes that answer at face value.