fix(elasticsearch): a read of an index still being created waits for its primary shard (#1402) - #1430
Merged
Merged
Conversation
…path A read (`_search`, `_count`, `GET _doc`) of an index whose creation is still in flight is answered `503 no_shard_available_action_exception`: the index is in the cluster state from the moment the create request is accepted - so it is no longer an `index_not_found_exception`, which reads as an empty set - but its primary shard is started only later. The request that creates the index waits for the primary (`wait_for_active_shards=1`); a read from anyone else does not. In the composite's asynchronous sync mode that "anyone else" is every search that follows the first write of a resource type, because the sync worker creates the index behind the write. The read path retried that answer on the general transient schedule, 3 attempts over ~300 ms. Creation takes ~100-200 ms on an idle single node and longer than that on a loaded one, so the search failed with a 5xx. `es_integration_composite_bad_date_stays_searchable_in_every_sync_mode` polls a search right behind an asynchronous write and failed about one run in five under load. Give `no_shard_available_action_exception` alone its own bounded schedule: 8 retries, doubling from 100 ms and capped at 1 s, at most 5.5 s of waiting. 429/502/503/504 and the other transient answers keep the 3-attempt schedule, and a read that is past the general budget stops as soon as the cluster answers with one of those instead. Fixes #1402
…t started `ensure_index` never read the create-index response. The request waits for the primary shard by itself (`wait_for_active_shards=1` is the default, verified: 40 of 40 sequential create-then-search runs on 7.17.29 answered `shards_acknowledged: true` and the search `200`), so the write that follows does not race the allocation. When the wait passes the request's 30 s `timeout`, Elasticsearch still creates the index and answers `shards_acknowledged: false`; reads of that index then fail until the shard starts, with nothing in the log to say why. Log that case. It stays a success: the index exists, the index request waits for the primary again, and the read path now retries an unstarted shard. Refs #1402
Codecov Report✅ All modified and coverable lines are covered by tests. 📢 Thoughts on this report? Let us know! |
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Summary
A read of an Elasticsearch index whose creation is still in flight no longer fails with a 5xx.
no_shard_available_action_exception— and only that answer — gets its own bounded retry schedule on the read path (8 retries, at most 5.5 s of waiting) instead of the general 3 attempts over ~300 ms.ensure_indexnow also reads the create-index response and logs when the primary shard had not started by the time the request timed out.This removes the flake in
es_integration::es_integration_composite_bad_date_stays_searchable_in_every_sync_mode. No test and no test helper was changed.Fixes #1402
Observed pre-fix behavior
search … failed: internal error in elasticsearch: Search failed after 3 attempts (status 503): …no_shard_available_action_exception…, panicking in thefound_idshelper.Reproduction, in the order tried (all with Elasticsearch 7.17.29, 256 MB heap, as the harness uses):
yes > /dev/nullburners on a 32-core host (load average 45–57)elasticsearch_testsbinary,--test-threads 32, 32 burnersdocker update --cpus)--device-write-iops <docker disk>:60, 30 runsAsynchronousmodeSo the trigger is disk pressure, not CPU: the window is dominated by the cluster-state write and the new shard's first translog/segment fsync. That matches where the issue saw it (six ES binaries back to back, builds running) and why a quiet machine never shows it. With
curlalone against the throttled container the503window was 470–590 ms (one of 2.3 s); unthrottled it is under ~100–200 ms.For recipes 4 and 5 the harness was patched locally only to take an external ES address, and the pre-fix binary is this branch with
MAX_NO_SHARD_RETRIES = 2, i.e. the old schedule. Neither patch is in this PR.Root cause
The issue guessed that the test "creates a fresh tenant and index and searches it almost immediately" and that
ensure_indexmight not wait for the primary. That is not what happens:ensure_indexsends a plainPUT {index}; the defaultwait_for_active_shards=1holds the response until the primary is started. 40 / 40 sequential create → search runs returnedshards_acknowledged: trueand the search200, throttled or not. A write or search that follows a returnedensure_indexdoes not race the allocation. (InSynchronousandHybrid{sync_for_search}mode that is every search in the test — and those modes never failed.)index_not_found_exception(which HFS reads as an empty set) while its primary shard is not started yet. 20 / 20 searches sent while a create was in flight got503 no_shard_available_action_exceptionfor the whole window._countanswers identically, andGET _docwithno_shard_available_action_exceptioncaused byillegal_index_shard_state_exception [RECOVERING].Asynchronousmode the sync worker runsensure_index+ the index request behind the client's write, so the test's poll loop — and in production, any search that follows the first write of a resource type, or a second HFS instance — is exactly such a reader. Three attempts over ~300 ms do not outlast a 500 ms window.SearchProvider::search, which addresses the single index{prefix}_{tenant}_patient, and every test has its own UUID prefix, so no neighbour's allocating index can be matched. Noignore_unavailable/allow_partial_search_resultschange is made; dropping an unavailable index from a tenant-scoped search would return silently incomplete results, which is worse than the503.Fix
search_impl.rs:send_read_with_retry(search, count, get — the storage-side reads go through it too) takes its budget from the failure it just saw.no_shard_available_action_exception, under any status, getsMAX_NO_SHARD_RETRIES = 8with the doubling back-off capped at 1 s: waits of 100, 200, 400, 800, 1000 × 4 ms = 5.5 s worst case, plus the requests themselves. Every other transient answer (429, 502, 503, 504, rejected execution, circuit breaker, transport failure) keeps 3 attempts / 300 ms, and a read that is already past that general budget stops as soon as the cluster answers with one of those instead.schema.rs:ensure_indexreads the create response and logs a warning onshards_acknowledged: false(the create request's own 30 s wait expired). Still a success: the index exists, the index request waits for the primary again, and reads now retry. The hunk sits after the existing error handling and does not touch the fix(persistence): reconcile ES index mappings at startup and retry search_count (#1335) #1347 reconcile code.storage.rs) is unchanged: index requests wait for the primary by themselves and do not see this answer.Not done, deliberately: no
_cluster/health?wait_for_status=yellowpoll inensure_index(the creator already waits; the racing party is a different task, which such a poll would not help), and no test-only sleep or harness wait.Behavior changes clients can observe
after 9 attemptsin the message.Verification
Ran and passed (after merging
origin/main):cargo test -p helios-persistence --features elasticsearch,sqlite --test elasticsearch_tests— 140 passedelasticsearch_search_wiremock(12, 3 new),elasticsearch_bulk_wiremock(20),elasticsearch_schema_reconcile(7),elasticsearch_storage_read_wiremock(15),elasticsearch_storage_write_wiremock(19, 1 new),composite_polyglot_tests(14),composite_routing_tests(25),composite_read_your_writes(5)cargo test -p helios-persistence --lib --features elasticsearch,sqlite— 1399 passed (1 new: the schedule and its 5.5 s bound)cargo fmt -p helios-persistence -- --checkcargo +1.98.1 clippy -p helios-persistence --features elasticsearch,sqlite,postgres,mongodb --all-targets -- -D warningswith the CI allow-listcargo +1.98.1 check -p helios-persistence --all-features --all-targets(every FHIR version and every backend, all test targets of the crate this PR touches)Not completed:
cargo +1.98.1 test --workspace --all-features --no-run --exclude pysof. It was attempted twice and both times died withNo space left on deviceon the shared build disk (the second attempt'starget/reached 414 GB before the disk filled; it has been removed). Every error in the log is an I/O error — noerror[E…]— and thehelios-persistencetest binaries this PR touches (elasticsearch_tests,elasticsearch_search_wiremock) had linked under--all-featuresbefore it stopped. The touched files contain nocfg(all(feature…))code. CI's own run of that command is the remaining check.New wiremock tests assert exact request counts and no timings: a read that gets four
no_shardanswers (one more than the general budget) then200succeeds with 5 requests, for both_searchand_count; a shard that never starts is anInternalerror after exactly 9 requests; threeno_shardanswers followed by a plain503stop at 4 requests. The503body is a real 7.17.29 capture. With the old schedule (MAX_NO_SHARD_RETRIES = 2) all three fail.Found, not fixed
es_integration::es_system_qualified_tokens_in_chainsfailed once in 3 full-binary runs under CPU load, on the unmodified pre-fix binary:token_code_system_suite.rs:481positive controlsubject:Patient.gender=femalereturned{}. An empty result, not an error — a different flake (write visibility on the chained path, at a guess; not investigated).Stacking
Based on
main; no other PR's commits.