Intermittent false-negative prefix_index reads under load (raft state machine, apply-order vs ReadIndex)

[gtema]

Summary

Under concurrent load against the raft-backed distributed storage, get_ruleset_by_source (and likely other prefix_index-based lookups) intermittently returns "not found" for an entry that is definitely already committed and present. Observed via the ScimSync loadtest scenario (tests/loadtest/src/v4/scim_sync.rs) hammering /SCIM/v2/{domain_id}/Users: ~0.6-0.8% of otherwise-valid, already-successfully-authenticated API Key requests get rejected with 401 Unauthorized because ApiKeyAuth's mapping-ruleset lookup (hydrate_ephemeral_context in crates/core/src/api/api_key_auth.rs) comes back empty.

Reproduction

tools/run-loadtest-local.sh --scenarios ScimSync,ScimRealmRead --users 4 --hatch-rate 4 --run-time 25s

(or against a 2-node skaffold/k3s keystone-rs StatefulSet, --host http://keystone-rs.local)

Failure rate in a 25s / 4-VU run: 135-136 401s out of ~16-25k GET /SCIM/v2/{domain_id}/Users requests, plus 1-2 on the immediately-following POST (create).

Root-cause trail

1. Initial hypothesis was a follower serving a stale local read after ensure_linearizable(ReadPolicy::ReadIndex) on get_by_key/prefix/prefix_index (crates/storage/src/app.rs) got ForwardToLeader and the client-side forward RPC failed, falling back to an unguarded local read. Fixed regardless (real bug, described below) but did not reduce the failure rate — ruled out as the cause of this specific flakiness.

2. Also found: the leader-side gRPC handlers for forwarded reads (forwarded_get, forwarded_prefix, forwarded_prefix_index in crates/storage/src/grpc/storage_service.rs) never re-confirmed their own current leadership/read-index before serving a forwarded request — a former leader could still answer a forward with an unguaranteed-linearizable local read. Fixed (also did not reduce the failure rate on its own).

3. Confirmed via debug logging + x_request_id tracing (kubectl exec ... /var/log/keystone/keystone.log, debug = true in keystone.conf): the failure reproduces with zero raft forwarding involved — a request served directly by the current leader (keystone-rs-1), where ensure_linearizable{read_policy=ReadIndex} succeeds locally on both the api_key lookup and the get_ruleset_by_source prefix_index scan, still returns an empty index scan for an entry that is otherwise stable and present (all other concurrent requests against the same ruleset succeed).

   Example trace (req-62b887e6815d4d20956f48c243402a93, keystone-rs-1, no ForwardToLeader anywhere in the span):

   ensure_linearizable{read_policy=ReadIndex} ... receives result is error: false
   get_ruleset_by_source{domain_id="default" source=ApiClient { provider_id: "loadtest-scim-realm" }}
     ensure_linearizable{read_policy=ReadIndex} ... receives result is error: false
   error=The request you have made requires authentication.
   

   i.e. AuthenticationError::Unauthorized from hydrate_ephemeral_context's .ok_or(AuthenticationError::Unauthorized)? on the ruleset lookup (crates/core/src/api/api_key_auth.rs), with no forwarding, no rate-limit, no IP-block, no bad-secret branch involved (all four are now instrumented with debug! and none fired for these failures).

Leading theory (unverified)

apply() in crates/storage/src/store/state_machine.rs writes the primary resource key and its MutationInner::SetIndex secondary-index entry into the same Fjall batch (self.db.batch()), which should be atomic and immediately visible on commit(). The remaining open question is whether OpenRaft's own "applied index" bookkeeping (what ensure_linearizable(ReadPolicy::ReadIndex) checks against) can advance to log index N before this function's batch.commit() for entry N has actually finished/become visible to a concurrent index() iterator -- i.e. a race between OpenRaft marking an entry "applied" (driven by consuming it off the apply<Strm> stream) and this code's own commit of that entry's mutations actually landing. This needs someone with OpenRaft internals + Fjall batch/visibility semantics to confirm or rule out; I could not verify it further without instrumenting the state machine itself, which felt like too high a blast-radius change to make blind against a shared dev cluster.

What's already fixed (this session, not blocking this issue)

• crates/core/src/api/api_key_auth.rs: timing oracle in the ip_allowed rejection branch (didn't burn the same Argon2id cost as the other rejection branches, ADR 0021 Invariant 7) — fixed.
• crates/storage/src/app.rs: get_by_key/prefix/prefix_index no longer silently fall back to an unguarded local read when the leader-forward RPC fails — now return an error.
• crates/storage/src/grpc/storage_service.rs: forwarded_get/forwarded_prefix/forwarded_prefix_index now re-confirm current leadership (ensure_linearizable) before serving.
• tests/loadtest/src/seed.rs: idempotent against a pre-existing SCIM realm/IdP (409) instead of aborting the whole seed step.

Diagnostic debug! logging is still in place in api_key_auth.rs distinguishing not-found / inactive / IP-blocked / wrong-secret rejection branches -- useful for whoever picks this up to re-confirm against a fresh repro.

Suggested next steps

1. Get someone familiar with the OpenRaft RaftStateMachine::apply contract to confirm whether "applied index" visibility to ensure_linearizable is guaranteed to happen only after this function's per-entry batch.commit() returns, or whether there's a decoupling (e.g. via the EntryResponder/stream-consumption timing).
2. If confirmed, likely fix is either awaiting/fencing on the batch commit before advancing internal apply tracking, or a per-entry read barrier keyed on this state machine's own commit completion rather than OpenRaft's log-consumption position.
3. Re-run the ScimSync loadtest scenario after any fix to confirm the 401 rate drops to 0 (currently 0.6-0.8% at 4 VUs / ~25s against a 2-node cluster).