This commit is contained in:
2026-08-04 10:26:54 -05:00
parent 96a37a495e
commit da3f8434a1
11 changed files with 926 additions and 77 deletions

114
README.md
View File

@@ -116,6 +116,25 @@ silently misreport when it was last refreshed.
Anything that writes files (NDA filing) must point `NDA_ROOT` at a scratch
directory for the run; never let a test write into the real NAS tree.
### The Dropbox Sign stub
`scripts/ds-stub.mjs` serves the two endpoints the inbox uses and reproduces
the property that broke the refresh: **its search index lags its list.** A
fixture entry is `{request, indexed}` — the truth the plain list and the per-id
endpoint hand out, and the possibly stale (or entirely missing) copy that
`query=` searches. It parses the range syntax for real, so `[a TO b]` and
`{a TO b}` genuinely differ. Point `DROPBOX_SIGN_BASE_URL` at it.
`node scripts/acceptance-nda-refresh.mjs` is the acceptance run: it starts the
real server against the stub and the real development database and asserts that
an incremental refresh picks up a request the index does not have yet and an
old pending one signed since, that a full reload includes the boundary day,
that a sync leaves `ds_last_refresh_at` untouched, and that `covers_from` never
narrows. It snapshots every `ds_*` key in `app_meta` and writes it back
afterwards, deletes its `req-*` rows, and runs with
`SYNC_PENDING_MAX_AGE_DAYS=0` so the sync cannot start re-fetching the real
mirror row by row.
## NAS mount
Mount it on the host via NFS, e.g. in `/etc/fstab`:
@@ -348,9 +367,13 @@ are mirrored into `ds_request` by a background task, and
* `covers_from` is how far back the mirror actually reaches. A walk stopped by
the `MAX_PAGES` cap covers less than it was asked for, so it records the
oldest date it got to and the inbox says "showing data from …" instead of
presenting a short list as complete. Coverage only ever widens: an
incremental walk reaching back two days does not un-mirror what a full reload
fetched last week.
presenting a short list as complete. **Coverage only ever widens**: the value
is written as `LEAST(stored, reached)` in one conditional upsert, so no walk
and no race can make the mirror claim *less* than it holds. It had drifted to
a date two months later than the mirror's own oldest row;
`008_covers_from_widen.sql` corrects the stored value once from
`min(created_at)` of `ds_request`. Only a full reload writes it at all — an
incremental pass reads the newest pages and establishes no window.
* `POST /api/nda-inbox/refresh` starts the walk and returns `202` immediately,
or `409` when one is already running — the slot is claimed with a conditional
upsert on `app_meta`, so two clicks cannot start two walks. A `running` state
@@ -361,37 +384,84 @@ are mirrored into `ds_request` by a background task, and
refresh feel slow in production — the button then said Refresh but did a full
reload every time. The button reflects this: *Refresh* vs *Reload window*.
The task **searches server-side** rather than paging through everything and
discarding most of it. It sends
#### Two walks, because the endpoint has two behaviours
| mode | when | what it reads |
| --- | --- | --- |
| `incremental` | every plain Refresh | pages 1-2 of the **unfiltered** list, no query, no cutoff |
| `full` | first run, or an explicit `?since=` | the two title queries over the whole window |
**The search index lags the list.** A request created two minutes ago is on
page 1 of the plain list and in *no* filtered result at all. An incremental
walk that searched therefore mirrored nothing while reporting a clean run —
which is how the mirror sat four days behind while every refresh looked
successful. So the incremental pass does not search. It reads the first two
pages as they come (200 requests, two calls) and keeps whatever passes the
title checks — **both** formats, since recent activity reaches back over the
rename.
That works because **the list is ordered by last activity, not by creation**:
verified live, a request created 30 July and signed 3 August sits above ones
created 3 August. So the same two pages carry the brand-new requests *and* the
old pending ones that were signed since — one pass, no per-id fetching. That is
what makes the sync's per-id re-check a backstop rather than the only way an
old row ever updates.
A **full reload searches server-side** rather than paging through everything
and discarding most of it, which turns a 13k-request account into the ~360 that
are ours:
```
query=title:"Buyer Forms - NDA" AND created:{<cutoff-date> TO *}
query=title:"Buyer Forms - NDA" AND created:[<cutoff-date> TO *]
```
which turns a 13k-request account into the ~360 that are ours. The two
client-side filters are kept as safety nets: a title that should not have come
back is filtered out *and logged as a warning*, and the exact-timestamp check
catches rows from the cutoff day itself, since the API's date clause is only
day-granular. If the query were ever ignored, the mirror would still be correct
— just slow again, and the log would say so.
The bounds are **inclusive** (`[…]`, not `{…}`): the exclusive form dropped
every request created on the cutoff day itself. Index lag is irrelevant here —
the window reaches months past it. The two client-side filters are kept as
safety nets: a title that should not have come back is filtered out *and logged
as a warning*, and the timestamp check drops anything older than midnight of
the cutoff day, since the API's date clause is only day-granular.
It pages through that filtered set with a 500 ms pause between calls; re-walking
is how a row that was pending last time is picked up as signed or declined.
Both walks pause 500 ms between calls. On `429`/`409` they honour `Retry-After`
but wait at least 10 s, retry a page up to three times, and log the response
body once per run at warn level — we still do not know what Dropbox means by
the `409` it sometimes sends.
Measured against the live account:
| | pages | seen | stored | duration |
| --- | --- | --- | --- | --- |
| full 90-day reload | 4 | 359 | 359 | 33 s |
| incremental, seconds later | 1 | 43 | 43 | 5 s |
| incremental, six days behind | 2 | 200 | 187 | 3 s |
| incremental, up to date | 2 | 200 | ~15 new | 3 s |
`seen` and `stored` now match. The old gap (≈1000 seen, ≈360 stored, 10 pages,
a minute) *was* the problem: 97% of what it fetched was thrown away. On `429`/`409` it honours
`Retry-After` but waits at least 10s, retries a page up to three times, and
logs the response body once per run at warn level — we still do not know what
Dropbox means by the `409` it sometimes sends. `app_meta` holds
`ds_last_refresh_at` and `ds_refresh_state` (`idle` | `running` |
`error:<msg>`).
`seen` is now the unfiltered page count, so it is always `100 × pages` — an
incremental pass re-storing rows it already has is free (the upsert is
idempotent) and cheaper than any attempt to be clever about it.
**Every walk logs one line**, which is what makes the next anomaly readable
without a debugger:
```
[nda-refresh] walk mode=incremental query=unfiltered window=none (newest activity first, no cutoff) pages=2 seen=200 stored=187
[nda-refresh] walk mode=full leg=current format query="title:\"Buyer Forms - NDA\" AND created:[2026-05-01 TO *]" window=[2026-05-01 TO *] pages=1 seen=2 stored=2
```
#### The two jobs' meta keys are disjoint, and nothing shares a write
`app_meta` holds `ds_refresh_state` (`idle` | `running` | `error:<msg>`),
`ds_last_refresh_at`, `ds_last_refresh_result` and `ds_mirror_covers_from` for
the refresh, and `ds_sync_state` / `ds_last_sync_at` / `ds_last_sync_result`
for the sync. They never cross: the sync *reads* `ds_last_refresh_at` to bound
its candidate set and must not write it.
`ds_last_refresh_at` is not a "the job ran" stamp — it is the boundary the sync
uses to decide which rows the walk can no longer reach, so it may only be
written by a **completed walk that stored what it found**. The shared
`startTask()` therefore no longer stamps `lastAt` for its caller: a helper that
writes "this ran at" on every resolved job is exactly how the marker moved
forward over data nobody had mirrored. Each job writes its own key at the point
where its work is done.
Import and sync are unchanged and still address one `signature_request_id` at a
time. Nothing re-fetches a request per id unnecessarily: sync's candidate set