You signed in with another tab or window. Reload to refresh your session.You signed out in another tab or window. Reload to refresh your session.You switched accounts on another tab or window. Reload to refresh your session.Dismiss alert
bulk-submit ingest: a mid-body stream error completes the manifest with rows missing; the lease dies behind a WAL checkpoint and forces a full re-walk; Elasticsearch idles through the whole import #1127
When an input file's body breaks mid-stream, HFS abandons the rest of that file, writes one file-level error artifact, and still publishes the manifest as completed — with no WARN in the log. Measured: 4–8 files per run lose their last 20–130 KB. At corpus scale that is thousands of clinical resources missing from a run the operator was told succeeded.
A real, but much smaller, time win
Indexing into Elasticsearch during ingest instead of rebuilding after the manifest. #1156 (merged 2026-09-16, closed #1125) fixed the rebuild this comparison used to be built on: it now completes in 145 s, one generation, 0 errors, 11,704 / 11,704 Provenance indexed (measured on #937 with HFS_ELASTICSEARCH_WRITE_REFRESH=wait_for and HFS_ELASTICSEARCH_REINDEX_REFRESH=false). So the honest comparison on the 1 % cut today is ingest ~151 s + rebuild ~145 s ≈ 296 s against the prototype's 225 s with indexing folded into ingest — roughly 1.3×, not the 4.4–6.9× this issue claimed while the rebuild was still failing. The structural win survives: the separate rebuild phase disappears altogether, and at 19M a serial rebuild may scale worse than ingest does (hypothesis — the full corpus has not been re-run since #1156). See §5.
One slow secondary costs a full re-walk
The real run lost its lease after ~7 h and re-read all 24 files: +11 h, 18 h 31 min total (measured, older code). Reproduced independently with a saturated Elasticsearch. With a non-terminal submission this can loop indefinitely (#998).
The status report cannot be trusted
Replay rewrites byte-identical resources as new versions (measured: DB 3.9 → 7.8 GB, history ×2) and total_entries accumulates across passes (37,911,730 reported for 18,955,865 receipts). The submission status poll is also O(N) over a table that reaches one row per ingested resource.
Cost of not doing it
Every corpus-scale sqlite-es import risks silent data loss, an 11 h penalty and a multi-hour rebuild, and produces numbers nobody can validate.
Effort / risk
Prototyped, compiled and tested on branch exp/937-perf, in the commits feat(bulk-submit): index into Elasticsearch during ingest, fix(bulk-submit): keep the lease alive across WAL checkpoints, perf(bulk-submit): cut the per-entry ingest work and fix(bulk-submit): report the cause of a mid-body file stream failure (rebased on #1093). Index-during-ingest is opt-in (default off); the lease fix keeps today's defaults. Only the fetcher Range retry is still to write. Medium-large effort, low risk.
All line references are against origin/main at 05aeba427 (git show origin/main:<path>; includes #1093, #1081, #1097, #1113 and #1109, merged 2026-09-15 as 2be460f50). Runs M1c (main before #1109) and M3b (prototype) were measured on 7967a483e (1 % cut = 228,580 resources, release R4-only build, isolated Elasticsearch 8.15.0 with a 4 GB heap, corpus served by a real static server, idle machine, no stall cutoff); database sizes come from earlier same-method runs on eae3d6fef; run M1e was measured on PR #1109's head 2cfde9b94 in the same environment. M1c and M1e are pre-#1156 history: #1156 (merged 2026-09-16, closed #1125) rewrote the _bulk path, and the rebuild now completes in 145 s with 0 errors, so neither run describes current main's rebuild any more (§5). Line references were re-checked against origin/main after #1156. Every figure is labelled measured, estimated or inferred.
1. Silent tail loss (the headline)
What the operator sees. The submission card reaches Completed. The manifest's error artifact contains one line per broken file, and the message it carries today is the useless error decoding response body — because reqwest's Display drops the source chain. The log says nothing at warn or above. The counts look plausible, because nobody knows what the exact count should be. The database is simply missing the tail of 4–8 files.
The actual error, only visible via {e:?}:
hyper::Error(Body, Os { code: 10054, kind: ConnectionReset,
message: "An existing connection was forcibly closed by the remote host." })
Mechanism.
crates/rest/src/bulk_submit_fetcher.rs:49 builds the client as reqwest::Client::new() — no request timeout, no read timeout, no retry, no Range resume.
:346-348 maps a body-stream failure straight into an io::Error using Display: std::io::Error::other(format!("reading file {owned_url}: {e}")).
The SQLite ingest engine turns that into a storage error at crates/persistence/src/backends/sqlite/bulk_submit.rs:1393: internal_error(format!("Failed to read line: {}", e)). Because read_line returned Err, process_ndjson_stream (:1365) returns immediately — every remaining line of that file is abandoned, while the batches already committed stay.
The worker catches it at crates/persistence/src/core/bulk_submit_worker.rs:1395-1411: it writes one file-level error artifact (failed to ingest file {url}: …, :1401), bumps failed by 1 (:1405), adds add_manifest_progress(lease_ref, 0, 1, 0) (:1408) — and moves on to the next file.
Nothing consults that counter when the manifest goes terminal: :1593-1602 unconditionally publishes ManifestPublicationStatus::Completed (fail_manifest exists, :371, but is not reached from here).
The shape is already pinned by a test — the outcome is not. PR #1081 added test_worker_reports_batches_committed_before_a_file_fails (bulk_submit_worker.rs:4240-4283): a file whose stream breaks after two full batches reports both batches to the write observer and leaves exactly 200 of its 250 Patients in storage. It asserts that the committed batches survive a broken file; nothing asserts what the manifest's terminal status is in that situation, so "200 of 250, manifest completed" is known-shaped but unguarded.
Measured. Corpus served by python -m http.server, both the default HTTP/1.0 and -p HTTP/1.1: 4–8 files per run truncated, 20–130 KB each, manifest completed every time. Same corpus from a ~20-line Node static server: 0 losses, and ~10× faster. The original 19M run did not hit it only because the debug binary read slowly enough.
Precedent on MongoDB.#1096 (merged 2026-09-13) added transient-retry and per-batch containment to the MongoDB bulk-submit path and left as follow-up "a 'completed with N unrecoverable entries' status signal". This is the same class of gap on SQLite, where there is no signal at all: the manifest ends completed with rows missing.
Fix. Three parts, in increasing order of work:
Diagnostic (already in the prototype commit fix(bulk-submit): report the cause of a mid-body file stream failure) — make the cause reachable at all:
The URL must be redacted (query string stripped) before it goes anywhere — in error messages, not only in the log. On main a presigned input URL, signature included, already reaches the manifest's error artifact: the fetcher embeds {url} in its errors (bulk_submit_fetcher.rs:313, :328, and owned_url at :348), and the worker writes failed to ingest file {url}: {e} into the artifact (bulk_submit_worker.rs:1401). The prototype's {e:?} would carry the same URL into one more place.
Bounded retries with Range: bytes=<consumed>- on a body error, tracking bytes consumed per file, plus a request/read timeout on the client.
A file that cannot be completed fails the manifest (fail_manifest) instead of publishing Completed. A loud failure is strictly better than a quiet partial import.
2. Lease starvation → a second full pass over the corpus
What the operator sees. After ~7 h of a clean-looking ingest, one line:
WARN bulk-submit run abandoned while writing result receipts: its lease is no longer held
(bulk_submit_worker.rs:1581-1590) — and then the sibling worker starts again at file 1. Measured (older code): all 24 files re-read, +11 h, 18 h 31 min of ingest in total, total_entries 37,911,730 for 18,955,865 receipts, and the bulk_submissions row never reached a terminal state.
The heartbeat (sqlite/bulk_submit.rs:1762-1796) is wrapped in retry_bookkeeping_on_busy("heartbeat", lease_retry_budget(lease), …) (:1770; helper at :124-152), and that helper calls each attempt synchronously (attempt() at :135; only the back-off between attempts awaits, :146). Each attempt is a blocking rusqlite UPDATE executed directly on a runtime thread — this, not the checkpoint, is the piece that blocks the runtime. With busy_timeout at its 30 s default (sqlite/backend.rs:206-215), a single attempt parks that runtime thread for up to 30 s with no await point.
The keeper guards it with tokio::time::timeout(left, jobs.heartbeat(&lease)) (bulk_submit_worker.rs:810) — a timeout that cannot fire while an attempt is blocked, because the future it wraps is blocking rather than pending.
When the UPDATE finally lands, lease_expiry has passed, a sibling worker has re-claimed the manifest, and the status/worker_id/fencing_token fence no longer matches: 0 rows affected → lease_lost. And that is swallowed (bulk_submit_worker.rs:815-821):
// Already reclaimed by another worker — expected, and the run aborts quietly.Ok(Err(LeaseError::LeaseLost{ .. })) => {let _ = flag.send(true);return;}
(A warn does exist for the other exit — "bulk-submit lease could not be renewed before it expired", :835-845 — but only when the loop runs out of time without an answer; a LeaseLost answer takes the silent path above.)
It is not only the WAL. Reproduced independently with a saturated Elasticsearch (the 1,000-shard wall): ES rejected writes → the unbounded secondary flush waited 40 min → the heartbeat could not get the SQLite write lock for 4.5 min (database is locked, 8 retries logged) → the lease expired (all measured, older code). Any slow secondary can cost a full re-walk.
Fix (prototype commit fix(bulk-submit): keep the lease alive across WAL checkpoints, 18 tests): PASSIVE checkpoint first, then TRUNCATE under a 1 s busy_timeout, logging WAL bytes/frames and duration at info (warn past 5 s); heartbeat the lease immediately before the checkpoint so the copy starts with a full lease in hand; run each heartbeat attempt on a blocking thread (retry_bookkeeping_on_busy_async) so the keeper's timeout works; and warn! on LeaseLost, heartbeat timeout and reclaim — a lost lease must never be silent.
3. Replaying a manifest is not idempotent
Nothing compares content, so re-submitting the same manifest rewrites byte-identical resources as new versions (the update path, sqlite/bulk_submit.rs:1283-1302). Measured (same database, same manifest, twice, 1 % cut, older code): 211 s → 321 s, fhir.db3.9 → 7.8 GB, resource_history doubled to 458,539 rows. Combined with §2 this is what made the 19M run cost 18 h 31 min for ~7 h of real work.
The counters compound it: sqlite/bulk_submit.rs:938 does total_entries = total_entries + ?1, so every pass adds the whole file again — hence 37,911,730 for 18,955,865 receipts, which is what made the status report unreadable.
Contrast with #1081. Its new dashboard counters already handle a re-walk correctly: a re-ingested existing resource is reported with created = false (sqlite/bulk_submit.rs:1296-1301), BatchCountsReporter tallies it as an update (bulk_submit_worker.rs:559-584), and DashboardCountsObserver records only +created/-deleted — "updates change no count" (crates/rest/src/handlers/dashboard_counts.rs:13-15, :60-81). So after a replay the Home dashboard shows the right resource count while the submission's total_entries shows double. Two views of the same run now disagree.
#1096 (merged 2026-09-13) made replay idempotent on MongoDB (content-identical resources are skipped); on SQLite it is not, as measured above. SQLite and Postgres want the same treatment (opt-in), plus a total_entries that reports the manifest's entries rather than the sum over passes.
4. HFS_BULK_SUBMIT_BATCH_SIZE is a dead knob
It is parsed at crates/rest/src/config.rs:844 (batch_size: env_u32("HFS_BULK_SUBMIT_BATCH_SIZE", d.batch_size), documented default 1000) and then never reaches the ingest: the worker builds its options at core/bulk_submit_worker.rs:1144-1148 as BulkProcessingOptions::new().with_import_mode(…).with_defer_indexing(…).with_byte_progress(…).with_cancel(…) (plus #1081's with_batch_observer, :1151-1156) — no batch size — so every run uses default_submit_batch_size() = 100 (core/bulk_submit.rs:964-966). The setter exists — BulkProcessingOptions::with_batch_size (core/bulk_submit.rs:1064-1067) — but the server worker never calls it; outside tests only the benchmark does (crates/persistence/examples/bulk_submit_bench.rs:308).
This also qualifies #947, which describes its measurements as "batch 1,000": through the server worker the real batch is 100 unless the worker was patched locally (inferred).
Note the measurement before "fixing" it by raising the default: with the ingest sink enabled, batch 1000 was worse — 382 s vs 252 s for batch 100 (measured, 1 % cut, older code). The fix is to honour the knob, not to change the default.
5. Index into Elasticsearch during ingest instead of rebuilding afterwards (a smaller win since #1156)
Current design. With HFS_BULK_SUBMIT_DEFER_INDEXING=true (default since #946) on sqlite-es, composite_submit_jobs (crates/hfs/src/main.rs:1851-1864, called at :2295-2300) picks the raw primary as the job store:
if defer_indexing && has_reindex_hook { primary }else{/* CompositeSubmitJobs wrapper */}
(:1857), so the composite wrapper is bypassed and sync_ingested falls back to its default no-op (core/bulk_submit_worker.rs:381-384, Ok(IngestSyncReport::default())). Elasticsearch receives nothing at all during ingest; it is filled only by the deferred reindex hook fired after the manifest is terminal (bulk_submit_worker.rs:1604-1610).
The rebuild this section used to measure against is now fixed (#1156). Pre-#1156 history: on main before #1109 (7967a483e, 1 % cut) that rebuild failed twice — 403 s, then an automatic retry of all 24 types for 441 s, both ending with 2500 resource errors — and gave up 995 s after the import started, logging deferred reindex failed twice; run $reindex manually, with 226,080 of 228,580 documents in Elasticsearch: 2,500 Provenance resources stayed unindexed (measured, M1c). On #1109's head 2cfde9b94 the higher nested_objects.limit made each Provenance document carry far more nested objects, and 0 of 11,704 Provenance were indexed in a 1,551 s generation, every error reading backend unavailable: elasticsearch, retryable: true, with the whole 24-type rebuild repeating (measured, M1e). The cause was a defect in the Elasticsearch bulk-indexing path: _bulk was chunked by operation count with no byte cap, so a 500-operation Provenance request exceeded the client's 30 s request timeout and was failed chunk-wide. #1156 (merged 2026-09-16, closed #1125) fixed exactly that: byte-capped _bulk chunking (chunk_ranges, 10 MiB default via HFS_ELASTICSEARCH_BULK_MAX_BYTES), recursive half-split of a chunk on timeout/413/408/504 down to a single document, and 429 exponential backoff, all inside send_bulk_index (crates/persistence/src/backends/elasticsearch/storage.rs). The rebuild now completes in 145 s, one generation, 0 errors, 11,704 / 11,704 Provenance (228,590 / 228,590 root documents) with HFS_ELASTICSEARCH_WRITE_REFRESH=wait_for + HFS_ELASTICSEARCH_REINDEX_REFRESH=false — measured on the same 1 % cut and reported on #937, 2026-09-16.
What that leaves of this issue — the headline claim is withdrawn. The comparison this section used to make (995 s of a failing rebuild against 225 s of the prototype, "4.4×", and "≥ 6.9×" against M1e's failed generation) no longer describes anything on main, because the rebuild it counted is no longer broken or slow. Against a fixed rebuild the arithmetic on the 1 % cut is ~151 s ingest + ~145 s rebuild ≈ 296 s versus 225 s for the prototype with indexing folded in: about 1.3×. Two things still argue for the design. First, it removes the rebuild phase rather than making it fast — no second serial pass over everything just written, no window in which the manifest reads completed while search is still incomplete, no $reindex to babysit. Second (hypothesis, not measured): that second pass is a full re-read and re-index of the whole corpus, so at 19M resources it may scale worse than ingest does even after #1156 — 145 s at 228k says little about 19M, and nobody has re-run the full corpus since #1156. If that holds, the benefit at corpus scale is larger than the 1 % cut's 1.3× suggests; if it does not, this is a modest optimisation and should be scheduled as one. History, older code and pre-#1156: the real 19M run rebuilt at 93 res/s, ~53 h projected (measured rate, estimated projection) — that projection is now obsolete.
Proposed design (prototype commit feat(bulk-submit): index into Elasticsearch during ingest, 7 tests, opt-in): the engine calls batch_committedright after a batch transaction commits — never before, so the sink only sees what the primary durably holds — handing the batch to N writer tasks behind bounded queues, FIFO per resource by hash(type, id) so a late duplicate cannot overwrite a newer version. The worker drains the sink before writing receipts (#1007), so a receipt never reads success for a resource search cannot find; what the sink rejects is marked unindexed and only those types get the deferred reindex. (#1081 has since added an upstream post-commit hook at the same point — notify_batch_committed, sqlite/bulk_submit.rs:978 — which the sink can share.)
The bulk-writing half of this design no longer has to be built. The prototype shipped its own 10 MiB byte chunker because main had none; origin/main now has that logic in send_bulk_index (elasticsearch/storage.rs, from #1156) — byte-capped chunking, half-split of a request on timeout/413/408/504, 429 backoff, transient reclassification. An index-during-ingest sink should hand it pages and inherit all of it rather than reimplement any of it, which removes the riskiest part of the original proposal.
Measured (1 % cut). The first two rows are pre-#1156 history, on 7967a483e (main before #1109); the third is current main as measured and reported on #937 after #1156:
M3b's ingest is slower than M1c's because it includes the indexing; Elasticsearch is complete when those 225 s end, with no warnings or errors — which is still the best number on the table, by roughly 1.3×. Database size was part of the old argument too (measured earlier on eae3d6fef: 6,517 MB on main vs 3,941 MB with the prototype); that gap has largely closed, because #1156 also stops sqlite-es writing the dead SQLite search_index (890,350 rows → 0) and takes the same cut from 4,739 MB to 3,772 MB on main (measured, #1125) — the prototype's range. Opt-in via HFS_BULK_SUBMIT_INDEX_DURING_INGEST (default off), shaped by HFS_BULK_SUBMIT_INDEX_QUEUE (16), _CONCURRENCY (4–8), _COALESCE (4). History, older code: end-to-end 37 min → ~4 min (measured).
Critical detail learned by measurement (older code): the flush must be bounded and the sink pages small. Raising coalescing from 4 to 16 took ingest 245 → 329 s (+34 %), and a queue of 32 on top of that took it to 548 s (+65 % more) — and an unbounded flush is precisely what starved the lease in §2. A slow secondary must degrade to unindexed, never block the writer.
6. Cheap reporting fixes
The submission status poll is O(N) in ingested resources. crates/rest/src/handlers/bulk_submit.rs:879 calls jobs.get_submission, whose SQLite implementation (sqlite/bulk_submit.rs:219, query at :276-288) runs, per poll:
SELECTCOUNT(*), SUM(CASE WHEN outcome ='success' …), … FROM bulk_entry_results
WHERE tenant_id = ?1AND submitter = ?2AND submission_id = ?3
bulk_entry_results grows to one row per ingested resource — 19M by the end — so the poll gets steadily more expensive and competes with the ingest writer for the same SQLite file; in the real run the UI's 5 s refresh visibly stretched to minutes (measured, older code).
What #1081 changed, and what it did not. The Home dashboard is now memory-served: page loads never query storage, and its job counts come from a background refresh (crates/rest/src/dashboard.rs:1325-1328, count_active_submissions at :1365). That caveat is gone. The submission status poll is unchanged — it is still the query above, and the UI's bulk-import tracking still drives it through $bulk-submit-status (crates/ui/src/bulk_import.rs:874-878).
The manifest row already carries the counters: serve the summary from bulk_manifests and keep the scan for an explicit detail call. Alongside it: stop accumulating total_entries (§3) and close the bulk_submissions row (#998).
7. Context that bounds the ambition — do not re-do this work
On older code the ingest loop was a single serial tokio task at ~2,300–2,700 resources/s (measured). A full producer/consumer rewrite (batched existence probes, moved instead of cloned JSON, multi-row bookkeeping, 1 MB read buffer, commit in spawn_blocking; kept on exp/937-perf as perf(bulk-submit): optional producer/consumer ingest pipeline) was implemented and A/B-measured on the same binary: 245 s reference → 248 s serial, 267 s pipelined, 235 s pipelined with 8 writers — ±8 % (measured, older code). #1093 has since parallelised index preparation and brought the fast-load ingest of the 1 % cut to 151–157 s (measured: 157 s on eae3d6fef, 151 s in M1c on 7967a483e). An independent measurement agrees: with the phase timers merged in #1113, angela-helios reported on #947 (Linux, inline indexing, 133k resources) commit at 45 %, search_index_insert at 26.5 %, bookkeeping at 9.3 % (entry_results 8.1 %) and clones at 2.3 % of ingest time — so bookkeeping and clones, the per-entry work a rewrite can remove, bound that gain to roughly 12 % (the timers still need a --cfg perf_phases build plus HFS_PERF_PHASES=1). The commit share is what #1114 (open) addresses by making synchronous=NORMAL the default under WAL, with no environment variable; the prototype's HFS_SQLITE_SYNCHRONOUS knob used in the history table below is prototype-only and superseded by #1114. Once indexing happens during ingest, the secondary write path, not the ingest loop, is the ceiling. The remaining lever is the Elasticsearch page writer (FHIRPath extraction and repeated serialization per page); that belongs to a separate defect in the Elasticsearch write path (filed separately), with its own measured PR.
Pre-#1156 history — main before #1109 (7967a483e, R4-only release build, no stall cutoff), plus M1e on #1109's head 2cfde9b94. Neither M1c nor M1e describes current main: since #1156 the rebuild completes in 145 s with 0 errors (last row, §5).
Configuration
Ingest
Search ready
Total
M1c main before #1109, pre-#1156 (deferred rebuild)
151 s
+403 s failed rebuild, +441 s failed retry; gives up at 226,080 / 228,580 docs
HFS_BULK_SUBMIT_BULK_INDEX_REBUILD=true is not listed: per the code (begin/end_bulk_index_rebuild return early on is_search_offloaded()), it cannot activate on sqlite-es.
Index during ingest + HFS_SQLITE_SYNCHRONOUS=normal (prototype-only knob; superseded by #1114)
211–245 s
0 s
~4 min
Index during ingest, batch 1000
382 s
0 s
the knob would be a regression
Index during ingest, coalesce 16 / + queue 32
329 s / 548 s
0 s
unbounded flush starves the lease
Manifest replayed on the same database
321 s
—
DB 3.9 → 7.8 GB, history ×2
19M projection: ~2.3 h (estimated on older code: ~2.3k res/s ingest plus the fixed ~2.5 min Provenance cost; not re-derived from M3b), against >70 h measured for the original run.
Acceptance criteria
A file truncated mid-stream is retried with Range; if it still cannot be completed, the manifest goes failed, never completed, and the stream error is logged at warn with its source chain.
Regression test: an input server that closes the body mid-file yields a non-completed manifest and a receipt count that is either complete or explicitly short (extending test_worker_reports_batches_committed_before_a_file_fails to assert the terminal status).
Under an adversarial lease (10 s lease, 2 workers, forced multi-GB WAL) the manifest is never reclaimed; any LeaseLost, heartbeat timeout or reclaim appears at warn; checkpoint duration and WAL frames are logged.
A secondary that stops accepting writes degrades the batch to unindexed within a bounded time and does not expire the lease.
HFS_BULK_SUBMIT_BATCH_SIZE=N changes the observed batch size; the default stays 100.
Replaying a manifest leaves database size and resource_history count ~unchanged, and total_entries equals the manifest's entry count, not a multiple of it (consistent with the dashboard counters).
With HFS_BULK_SUBMIT_INDEX_DURING_INGEST=true, the Elasticsearch document count equals the receipt count at the instant ingest ends, and no deferred rebuild runs unless something was rejected.
The submission status poll's cost does not grow with the number of ingested resources.
Related: #969, #998, #1001, #1096, #1007, #947 (and #1113, its phase timers: independent per-phase breakdown, §7), #1114 (open: synchronous=NORMAL by default under WAL, supersedes the prototype's HFS_SQLITE_SYNCHRONOUS), #978 / #1025 (origin of the per-file wal_checkpoint(TRUNCATE), §2), #1081, #1093, #1050 (closed), #1109 (merged 2be460f50), #1156 (merged 2026-09-16, closed #1125 — fixes the deferred rebuild §5 used to measure against, and provides the send_bulk_index chunking an ingest-time sink should reuse), #1161 (open: rolling back or aborting a deferred bulk submit leaves orphaned documents in Elasticsearch — the same family as §1 and §6, a submission whose reported outcome does not match what storage holds), #937 (the manual test pass this came from).
Why this matters
errorartifact, and still publishes the manifest ascompleted— with no WARN in the log. Measured: 4–8 files per run lose their last 20–130 KB. At corpus scale that is thousands of clinical resources missing from a run the operator was told succeeded.HFS_ELASTICSEARCH_WRITE_REFRESH=wait_forandHFS_ELASTICSEARCH_REINDEX_REFRESH=false). So the honest comparison on the 1 % cut today is ingest ~151 s + rebuild ~145 s ≈ 296 s against the prototype's 225 s with indexing folded into ingest — roughly 1.3×, not the 4.4–6.9× this issue claimed while the rebuild was still failing. The structural win survives: the separate rebuild phase disappears altogether, and at 19M a serial rebuild may scale worse than ingest does (hypothesis — the full corpus has not been re-run since #1156). See §5.total_entriesaccumulates across passes (37,911,730 reported for 18,955,865 receipts). The submission status poll is also O(N) over a table that reaches one row per ingested resource.sqlite-esimport risks silent data loss, an 11 h penalty and a multi-hour rebuild, and produces numbers nobody can validate.exp/937-perf, in the commitsfeat(bulk-submit): index into Elasticsearch during ingest,fix(bulk-submit): keep the lease alive across WAL checkpoints,perf(bulk-submit): cut the per-entry ingest workandfix(bulk-submit): report the cause of a mid-body file stream failure(rebased on #1093). Index-during-ingest is opt-in (default off); the lease fix keeps today's defaults. Only the fetcherRangeretry is still to write. Medium-large effort, low risk.All line references are against
origin/mainat05aeba427(git show origin/main:<path>; includes #1093, #1081, #1097, #1113 and #1109, merged 2026-09-15 as2be460f50). Runs M1c (mainbefore #1109) and M3b (prototype) were measured on7967a483e(1 % cut = 228,580 resources, release R4-only build, isolated Elasticsearch 8.15.0 with a 4 GB heap, corpus served by a real static server, idle machine, no stall cutoff); database sizes come from earlier same-method runs oneae3d6fef; run M1e was measured on PR #1109's head2cfde9b94in the same environment. M1c and M1e are pre-#1156 history: #1156 (merged 2026-09-16, closed #1125) rewrote the_bulkpath, and the rebuild now completes in 145 s with 0 errors, so neither run describes currentmain's rebuild any more (§5). Line references were re-checked againstorigin/mainafter #1156. Every figure is labelled measured, estimated or inferred.1. Silent tail loss (the headline)
What the operator sees. The submission card reaches Completed. The manifest's
errorartifact contains one line per broken file, and the message it carries today is the uselesserror decoding response body— becausereqwest'sDisplaydrops the source chain. The log says nothing atwarnor above. The counts look plausible, because nobody knows what the exact count should be. The database is simply missing the tail of 4–8 files.The actual error, only visible via
{e:?}:Mechanism.
crates/rest/src/bulk_submit_fetcher.rs:49builds the client asreqwest::Client::new()— no request timeout, no read timeout, no retry, noRangeresume.:346-348maps a body-stream failure straight into anio::ErrorusingDisplay:std::io::Error::other(format!("reading file {owned_url}: {e}")).crates/persistence/src/backends/sqlite/bulk_submit.rs:1393:internal_error(format!("Failed to read line: {}", e)). Becauseread_linereturnedErr,process_ndjson_stream(:1365) returns immediately — every remaining line of that file is abandoned, while the batches already committed stay.crates/persistence/src/core/bulk_submit_worker.rs:1395-1411: it writes one file-levelerrorartifact (failed to ingest file {url}: …,:1401), bumpsfailedby 1 (:1405), addsadd_manifest_progress(lease_ref, 0, 1, 0)(:1408) — and moves on to the next file.:1593-1602unconditionally publishesManifestPublicationStatus::Completed(fail_manifestexists,:371, but is not reached from here).The shape is already pinned by a test — the outcome is not. PR #1081 added
test_worker_reports_batches_committed_before_a_file_fails(bulk_submit_worker.rs:4240-4283): a file whose stream breaks after two full batches reports both batches to the write observer and leaves exactly 200 of its 250 Patients in storage. It asserts that the committed batches survive a broken file; nothing asserts what the manifest's terminal status is in that situation, so "200 of 250, manifestcompleted" is known-shaped but unguarded.Measured. Corpus served by
python -m http.server, both the default HTTP/1.0 and-p HTTP/1.1: 4–8 files per run truncated, 20–130 KB each, manifestcompletedevery time. Same corpus from a ~20-line Node static server: 0 losses, and ~10× faster. The original 19M run did not hit it only because the debug binary read slowly enough.Precedent on MongoDB. #1096 (merged 2026-09-13) added transient-retry and per-batch containment to the MongoDB bulk-submit path and left as follow-up "a 'completed with N unrecoverable entries' status signal". This is the same class of gap on SQLite, where there is no signal at all: the manifest ends
completedwith rows missing.Fix. Three parts, in increasing order of work:
fix(bulk-submit): report the cause of a mid-body file stream failure) — make the cause reachable at all:The URL must be redacted (query string stripped) before it goes anywhere — in error messages, not only in the log. On
maina presigned input URL, signature included, already reaches the manifest'serrorartifact: the fetcher embeds{url}in its errors (bulk_submit_fetcher.rs:313,:328, andowned_urlat:348), and the worker writesfailed to ingest file {url}: {e}into the artifact (bulk_submit_worker.rs:1401). The prototype's{e:?}would carry the same URL into one more place.Range: bytes=<consumed>-on a body error, tracking bytes consumed per file, plus a request/read timeout on the client.fail_manifest) instead of publishingCompleted. A loud failure is strictly better than a quiet partial import.2. Lease starvation → a second full pass over the corpus
What the operator sees. After ~7 h of a clean-looking ingest, one line:
(
bulk_submit_worker.rs:1581-1590) — and then the sibling worker starts again at file 1. Measured (older code): all 24 files re-read, +11 h, 18 h 31 min of ingest in total,total_entries37,911,730 for 18,955,865 receipts, and thebulk_submissionsrow never reached a terminal state.Mechanism.
checkpoint_after_file(sqlite/bulk_submit.rs:2226-2243, called at every file boundary frombulk_submit_worker.rs:1414-1416) runs a barePRAGMA wal_checkpoint(TRUNCATE);(:2239), introduced per file by persistence(sqlite): WAL auto-checkpoint starves under sustained bulk ingest — 7.3 GB WAL measured, reads degrade with depth #978/perf(sqlite): checkpoint the WAL at each bulk-submit file boundary #1025. It runs insidespawn_blocking(:2237), so the checkpoint itself does not block a runtime thread; the problem is the lock it holds.TRUNCATEholds the WAL write lock for the whole copy; by that point in the run the WAL was multi-gigabyte, so the copy takes minutes — and every other writer, the heartbeat included, waits behind it.sqlite/bulk_submit.rs:1762-1796) is wrapped inretry_bookkeeping_on_busy("heartbeat", lease_retry_budget(lease), …)(:1770; helper at:124-152), and that helper calls each attempt synchronously (attempt()at:135; only the back-off between attempts awaits,:146). Each attempt is a blocking rusqliteUPDATEexecuted directly on a runtime thread — this, not the checkpoint, is the piece that blocks the runtime. Withbusy_timeoutat its 30 s default (sqlite/backend.rs:206-215), a single attempt parks that runtime thread for up to 30 s with no await point.tokio::time::timeout(left, jobs.heartbeat(&lease))(bulk_submit_worker.rs:810) — a timeout that cannot fire while an attempt is blocked, because the future it wraps is blocking rather than pending.UPDATEfinally lands,lease_expiryhas passed, a sibling worker has re-claimed the manifest, and thestatus/worker_id/fencing_tokenfence no longer matches: 0 rows affected →lease_lost. And that is swallowed (bulk_submit_worker.rs:815-821):(A
warndoes exist for the other exit — "bulk-submit lease could not be renewed before it expired",:835-845— but only when the loop runs out of time without an answer; aLeaseLostanswer takes the silent path above.)It is not only the WAL. Reproduced independently with a saturated Elasticsearch (the 1,000-shard wall): ES rejected writes → the unbounded secondary
flushwaited 40 min → the heartbeat could not get the SQLite write lock for 4.5 min (database is locked, 8 retries logged) → the lease expired (all measured, older code). Any slow secondary can cost a full re-walk.Fix (prototype commit
fix(bulk-submit): keep the lease alive across WAL checkpoints, 18 tests):PASSIVEcheckpoint first, thenTRUNCATEunder a 1 sbusy_timeout, logging WAL bytes/frames and duration atinfo(warnpast 5 s); heartbeat the lease immediately before the checkpoint so the copy starts with a full lease in hand; run each heartbeat attempt on a blocking thread (retry_bookkeeping_on_busy_async) so the keeper's timeout works; andwarn!onLeaseLost, heartbeat timeout and reclaim — a lost lease must never be silent.3. Replaying a manifest is not idempotent
Nothing compares content, so re-submitting the same manifest rewrites byte-identical resources as new versions (the update path,
sqlite/bulk_submit.rs:1283-1302). Measured (same database, same manifest, twice, 1 % cut, older code): 211 s → 321 s,fhir.db3.9 → 7.8 GB,resource_historydoubled to 458,539 rows. Combined with §2 this is what made the 19M run cost 18 h 31 min for ~7 h of real work.The counters compound it:
sqlite/bulk_submit.rs:938doestotal_entries = total_entries + ?1, so every pass adds the whole file again — hence 37,911,730 for 18,955,865 receipts, which is what made the status report unreadable.Contrast with #1081. Its new dashboard counters already handle a re-walk correctly: a re-ingested existing resource is reported with
created = false(sqlite/bulk_submit.rs:1296-1301),BatchCountsReportertallies it as an update (bulk_submit_worker.rs:559-584), andDashboardCountsObserverrecords only+created/-deleted— "updates change no count" (crates/rest/src/handlers/dashboard_counts.rs:13-15,:60-81). So after a replay the Home dashboard shows the right resource count while the submission'stotal_entriesshows double. Two views of the same run now disagree.#1096 (merged 2026-09-13) made replay idempotent on MongoDB (content-identical resources are skipped); on SQLite it is not, as measured above. SQLite and Postgres want the same treatment (opt-in), plus a
total_entriesthat reports the manifest's entries rather than the sum over passes.4.
HFS_BULK_SUBMIT_BATCH_SIZEis a dead knobIt is parsed at
crates/rest/src/config.rs:844(batch_size: env_u32("HFS_BULK_SUBMIT_BATCH_SIZE", d.batch_size), documented default 1000) and then never reaches the ingest: the worker builds its options atcore/bulk_submit_worker.rs:1144-1148asBulkProcessingOptions::new().with_import_mode(…).with_defer_indexing(…).with_byte_progress(…).with_cancel(…)(plus #1081'swith_batch_observer,:1151-1156) — no batch size — so every run usesdefault_submit_batch_size() = 100(core/bulk_submit.rs:964-966). The setter exists —BulkProcessingOptions::with_batch_size(core/bulk_submit.rs:1064-1067) — but the server worker never calls it; outside tests only the benchmark does (crates/persistence/examples/bulk_submit_bench.rs:308).This also qualifies #947, which describes its measurements as "batch 1,000": through the server worker the real batch is 100 unless the worker was patched locally (inferred).
Note the measurement before "fixing" it by raising the default: with the ingest sink enabled, batch 1000 was worse — 382 s vs 252 s for batch 100 (measured, 1 % cut, older code). The fix is to honour the knob, not to change the default.
5. Index into Elasticsearch during ingest instead of rebuilding afterwards (a smaller win since #1156)
Current design. With
HFS_BULK_SUBMIT_DEFER_INDEXING=true(default since #946) onsqlite-es,composite_submit_jobs(crates/hfs/src/main.rs:1851-1864, called at:2295-2300) picks the raw primary as the job store:(
:1857), so the composite wrapper is bypassed andsync_ingestedfalls back to its default no-op (core/bulk_submit_worker.rs:381-384,Ok(IngestSyncReport::default())). Elasticsearch receives nothing at all during ingest; it is filled only by the deferred reindex hook fired after the manifest is terminal (bulk_submit_worker.rs:1604-1610).The rebuild this section used to measure against is now fixed (#1156). Pre-#1156 history: on
mainbefore #1109 (7967a483e, 1 % cut) that rebuild failed twice — 403 s, then an automatic retry of all 24 types for 441 s, both ending with2500 resource errors— and gave up 995 s after the import started, loggingdeferred reindex failed twice; run $reindex manually, with 226,080 of 228,580 documents in Elasticsearch: 2,500 Provenance resources stayed unindexed (measured, M1c). On #1109's head2cfde9b94the highernested_objects.limitmade each Provenance document carry far more nested objects, and 0 of 11,704 Provenance were indexed in a 1,551 s generation, every error readingbackend unavailable: elasticsearch,retryable: true, with the whole 24-type rebuild repeating (measured, M1e). The cause was a defect in the Elasticsearch bulk-indexing path:_bulkwas chunked by operation count with no byte cap, so a 500-operation Provenance request exceeded the client's 30 s request timeout and was failed chunk-wide. #1156 (merged 2026-09-16, closed #1125) fixed exactly that: byte-capped_bulkchunking (chunk_ranges, 10 MiB default viaHFS_ELASTICSEARCH_BULK_MAX_BYTES), recursive half-split of a chunk on timeout/413/408/504 down to a single document, and 429 exponential backoff, all insidesend_bulk_index(crates/persistence/src/backends/elasticsearch/storage.rs). The rebuild now completes in 145 s, one generation, 0 errors, 11,704 / 11,704 Provenance (228,590 / 228,590 root documents) withHFS_ELASTICSEARCH_WRITE_REFRESH=wait_for+HFS_ELASTICSEARCH_REINDEX_REFRESH=false— measured on the same 1 % cut and reported on #937, 2026-09-16.What that leaves of this issue — the headline claim is withdrawn. The comparison this section used to make (995 s of a failing rebuild against 225 s of the prototype, "4.4×", and "≥ 6.9×" against M1e's failed generation) no longer describes anything on
main, because the rebuild it counted is no longer broken or slow. Against a fixed rebuild the arithmetic on the 1 % cut is ~151 s ingest + ~145 s rebuild ≈ 296 s versus 225 s for the prototype with indexing folded in: about 1.3×. Two things still argue for the design. First, it removes the rebuild phase rather than making it fast — no second serial pass over everything just written, no window in which the manifest readscompletedwhile search is still incomplete, no$reindexto babysit. Second (hypothesis, not measured): that second pass is a full re-read and re-index of the whole corpus, so at 19M resources it may scale worse than ingest does even after #1156 — 145 s at 228k says little about 19M, and nobody has re-run the full corpus since #1156. If that holds, the benefit at corpus scale is larger than the 1 % cut's 1.3× suggests; if it does not, this is a modest optimisation and should be scheduled as one. History, older code and pre-#1156: the real 19M run rebuilt at 93 res/s, ~53 h projected (measured rate, estimated projection) — that projection is now obsolete.Proposed design (prototype commit
feat(bulk-submit): index into Elasticsearch during ingest, 7 tests, opt-in): the engine callsbatch_committedright after a batch transaction commits — never before, so the sink only sees what the primary durably holds — handing the batch to N writer tasks behind bounded queues, FIFO per resource byhash(type, id)so a late duplicate cannot overwrite a newer version. The worker drains the sink before writing receipts (#1007), so a receipt never readssuccessfor a resource search cannot find; what the sink rejects is markedunindexedand only those types get the deferred reindex. (#1081 has since added an upstream post-commit hook at the same point —notify_batch_committed,sqlite/bulk_submit.rs:978— which the sink can share.)The bulk-writing half of this design no longer has to be built. The prototype shipped its own 10 MiB byte chunker because
mainhad none;origin/mainnow has that logic insend_bulk_index(elasticsearch/storage.rs, from #1156) — byte-capped chunking, half-split of a request on timeout/413/408/504, 429 backoff, transient reclassification. An index-during-ingest sink should hand it pages and inherit all of it rather than reimplement any of it, which removes the riskiest part of the original proposal.Measured (1 % cut). The first two rows are pre-#1156 history, on
7967a483e(mainbefore #1109); the third is currentmainas measured and reported on #937 after #1156:mainbefore #1109 (pre-#1156)mainbefore #1109 + prototypemain, after #1156 (2026-09-16)M3b's ingest is slower than M1c's because it includes the indexing; Elasticsearch is complete when those 225 s end, with no warnings or errors — which is still the best number on the table, by roughly 1.3×. Database size was part of the old argument too (measured earlier on
eae3d6fef: 6,517 MB onmainvs 3,941 MB with the prototype); that gap has largely closed, because #1156 also stopssqlite-eswriting the dead SQLitesearch_index(890,350 rows → 0) and takes the same cut from 4,739 MB to 3,772 MB onmain(measured, #1125) — the prototype's range. Opt-in viaHFS_BULK_SUBMIT_INDEX_DURING_INGEST(default off), shaped byHFS_BULK_SUBMIT_INDEX_QUEUE(16),_CONCURRENCY(4–8),_COALESCE(4). History, older code: end-to-end 37 min → ~4 min (measured).Critical detail learned by measurement (older code): the flush must be bounded and the sink pages small. Raising coalescing from 4 to 16 took ingest 245 → 329 s (+34 %), and a queue of 32 on top of that took it to 548 s (+65 % more) — and an unbounded flush is precisely what starved the lease in §2. A slow secondary must degrade to
unindexed, never block the writer.6. Cheap reporting fixes
The submission status poll is O(N) in ingested resources.
crates/rest/src/handlers/bulk_submit.rs:879callsjobs.get_submission, whose SQLite implementation (sqlite/bulk_submit.rs:219, query at:276-288) runs, per poll:bulk_entry_resultsgrows to one row per ingested resource — 19M by the end — so the poll gets steadily more expensive and competes with the ingest writer for the same SQLite file; in the real run the UI's 5 s refresh visibly stretched to minutes (measured, older code).What #1081 changed, and what it did not. The Home dashboard is now memory-served: page loads never query storage, and its job counts come from a background refresh (
crates/rest/src/dashboard.rs:1325-1328,count_active_submissionsat:1365). That caveat is gone. The submission status poll is unchanged — it is still the query above, and the UI's bulk-import tracking still drives it through$bulk-submit-status(crates/ui/src/bulk_import.rs:874-878).The manifest row already carries the counters: serve the summary from
bulk_manifestsand keep the scan for an explicit detail call. Alongside it: stop accumulatingtotal_entries(§3) and close thebulk_submissionsrow (#998).7. Context that bounds the ambition — do not re-do this work
On older code the ingest loop was a single serial tokio task at ~2,300–2,700 resources/s (measured). A full producer/consumer rewrite (batched existence probes, moved instead of cloned JSON, multi-row bookkeeping, 1 MB read buffer, commit in
spawn_blocking; kept onexp/937-perfasperf(bulk-submit): optional producer/consumer ingest pipeline) was implemented and A/B-measured on the same binary: 245 s reference → 248 s serial, 267 s pipelined, 235 s pipelined with 8 writers — ±8 % (measured, older code). #1093 has since parallelised index preparation and brought the fast-load ingest of the 1 % cut to 151–157 s (measured: 157 s oneae3d6fef, 151 s in M1c on7967a483e). An independent measurement agrees: with the phase timers merged in #1113, angela-helios reported on #947 (Linux, inline indexing, 133k resources) commit at 45 %,search_index_insertat 26.5 %, bookkeeping at 9.3 % (entry_results8.1 %) and clones at 2.3 % of ingest time — so bookkeeping and clones, the per-entry work a rewrite can remove, bound that gain to roughly 12 % (the timers still need a--cfg perf_phasesbuild plusHFS_PERF_PHASES=1). The commit share is what #1114 (open) addresses by makingsynchronous=NORMALthe default under WAL, with no environment variable; the prototype'sHFS_SQLITE_SYNCHRONOUSknob used in the history table below is prototype-only and superseded by #1114. Once indexing happens during ingest, the secondary write path, not the ingest loop, is the ceiling. The remaining lever is the Elasticsearch page writer (FHIRPath extraction and repeated serialization per page); that belongs to a separate defect in the Elasticsearch write path (filed separately), with its own measured PR.Measured results (1 % cut = 228,580 resources, release binary, isolated ES)
Pre-#1156 history —
mainbefore #1109 (7967a483e, R4-only release build, no stall cutoff), plus M1e on #1109's head2cfde9b94. Neither M1c nor M1e describes currentmain: since #1156 the rebuild completes in 145 s with 0 errors (last row, §5).mainbefore #1109, pre-#1156 (deferred rebuild)7967a483e(index during ingest)mainafter #1156 (deferred rebuild), measured on #937 2026-09-16HFS_BULK_SUBMIT_BULK_INDEX_REBUILD=trueis not listed: per the code (begin/end_bulk_index_rebuildreturn early onis_search_offloaded()), it cannot activate onsqlite-es.History, older code (before #1093; 4 GB ES heap):
wait_for,synchronous)HFS_SQLITE_SYNCHRONOUS=normal(prototype-only knob; superseded by #1114)19M projection: ~2.3 h (estimated on older code: ~2.3k res/s ingest plus the fixed ~2.5 min Provenance cost; not re-derived from M3b), against >70 h measured for the original run.
Acceptance criteria
Range; if it still cannot be completed, the manifest goesfailed, nevercompleted, and the stream error is logged atwarnwith its source chain.completedmanifest and a receipt count that is either complete or explicitly short (extendingtest_worker_reports_batches_committed_before_a_file_failsto assert the terminal status).LeaseLost, heartbeat timeout or reclaim appears atwarn; checkpoint duration and WAL frames are logged.unindexedwithin a bounded time and does not expire the lease.HFS_BULK_SUBMIT_BATCH_SIZE=Nchanges the observed batch size; the default stays 100.resource_historycount ~unchanged, andtotal_entriesequals the manifest's entry count, not a multiple of it (consistent with the dashboard counters).HFS_BULK_SUBMIT_INDEX_DURING_INGEST=true, the Elasticsearch document count equals the receipt count at the instant ingest ends, and no deferred rebuild runs unless something was rejected.bulk_submissionsrow reaches a terminal state (bulk-submit: a submission can never reach a terminal state — status poll and Mark completed both time out, and the import re-ingests forever #998).Related: #969, #998, #1001, #1096, #1007, #947 (and #1113, its phase timers: independent per-phase breakdown, §7), #1114 (open:
synchronous=NORMALby default under WAL, supersedes the prototype'sHFS_SQLITE_SYNCHRONOUS), #978 / #1025 (origin of the per-filewal_checkpoint(TRUNCATE), §2), #1081, #1093, #1050 (closed), #1109 (merged2be460f50), #1156 (merged 2026-09-16, closed #1125 — fixes the deferred rebuild §5 used to measure against, and provides thesend_bulk_indexchunking an ingest-time sink should reuse), #1161 (open: rolling back or aborting a deferred bulk submit leaves orphaned documents in Elasticsearch — the same family as §1 and §6, a submission whose reported outcome does not match what storage holds), #937 (the manual test pass this came from).