[
https://issues.apache.org/jira/browse/SOLR-18506?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Nick Shanin updated SOLR-18506:
-------------------------------
Description:
#AI-generated, human-approved text below.
Summary
org.apache.solr.search.TestThinCache.testSimple fails intermittently with
"AssertionError: expected:<0> but was:<1>" at TestThinCache.java:170, together
with a
classMethod teardown error reporting 3 unreleased SolrMetricsContext objects.
The test is the
only coverage of ThinCache, the per-searcher scope over a shared node-level
cache introduced
in SOLR-16654. The failure has been recorded 14 times in the last 30 days
across unrelated
pull requests (list below), including 10 times on branch_9x. It is a test
defect, not a
product defect: no production code is involved.
Failure signature
- TestThinCache.testSimple: expected:<0> but was:<1> at TestThinCache.java:170
(the second
cache's evictions metric). The value is exactly 1 on every recorded
occurrence.
- classMethod teardown: 3 unreleased SolrMetricsContext objects (knock-on, see
root cause).
- Recorded occurrences (GitHub "Solr Tests via Crave" runs, 2026-09-09 to
2026-10-04):
PR #4894 (seed C4077EAB80AE9E50), PR #4939 (60B12BB09380AC51), PR #4943
(E58B5E1FFDEBA340),
PR #5013 (30A1B1A830109349), and PR #4976 on branch_9x ten times
(E4DD10799981D14B,
2E53727468DE4DF1, 391A297131D7D9C1, D8FD97BF9A8A48B0, FCA68807697335BA,
861F48CD4DFF5F51,
D5B22838079384ED, 6E0A7AD71C551639, 7A1C354A4C7E10DC, FA416BA281EBD0DF).
Reproduction
Locally, the failure does not reproduce with the recorded seeds: all 14
recorded seeds were
run against current main with forced re-execution (cleanTest), plus
default-seed runs, and
every run passed. That is expected under the verified mechanism below: the
outcome does not
depend on the test seed, so no seed can reproduce it. It reproduces
statistically instead.
A standalone model of the test's put/get sequence against Caffeine 3.2.4 (the
version this
tree pins), run with 200,000 trials per configuration, fails the evictions
assertion in
1,243 trials (0.62 percent) at the test's capacity of 100 and in none at the
fixed capacity
of 200.
Root cause
Eviction counting in ThinCache is per scope. A ThinCache counts an eviction
only in
onRemoval, dispatched through the backing cache's removal listener registry,
and a scope
registers with that registry only in initForSearcher, called from
initialSearcher and warm.
testSimple wires the first cache by hand and never triggers that registration
for it, so the
first cache's eviction counter is always 0, and the priorEvictions that warm
copies into the
second cache is always 0.
The second cache registers at warm. warm performs its 25 warming puts first and
only then
resets the eviction counter, so evictions counted during warming are erased;
the only
operation that can leave a count afterwards is the test's put of key 103, and
one put evicts
at most one entry. That is why the failure value is always exactly 1.
Until the fix, warming and the put of key 103 ran against a backing cache still
at capacity
100 and already full, so each put evicted one entry. Which entry Caffeine picks
as the victim
depends on key hashes. ScopedKey.hashCode is Objects.hash(scope, key) and the
test's scopes
are plain new Object() instances, so the hashes come from identity hash codes:
they vary per
JVM and do not follow the test seed. Usually the victim is a first-cache entry,
which is
never counted. Occasionally (about 0.6 percent of runs in the model) the victim
is one of the
second cache's own entries, the count becomes 1, and the assertion fails.
There is no notification timing race. CaffeineCache defaults async to true and
then sets a
same-thread executor (Runnable::run); the test's backing.init passes only size
and
initialSize, so evictions and their removal notifications complete
synchronously inside the
put that triggers them. In the model, the phase-1 eviction was already
delivered when the
101st put returned in 200,000 of 200,000 trials, no listener call ran off the
calling thread,
and a later cleanUp() never delivered anything.
The teardown leak is a knock-on: the failed assertion skips the test's closing
of its
SolrMetricsContext, and the framework reports the context and its two per-cache
children as
unreleased.
Record of corrections: this ticket's original description located the race at
warm's copy of
the first cache's counter and proposed expecting an inherited value of 1.
Building that fix
falsified it (the first cache's counter reads 0 deterministically, because it
never
registers). The replacement account then kept a delivery-timing race in the
second phase;
review of the shipped PR falsified that too, by the synchronous-executor
evidence above and
by the model. The mechanism stated here is the verified one.
Fix
Shipped in PR #5029 ([https://github.com/apache/solr/pull/5029]), test-only:
after the first
cache's assertions, enlarge the shared backing cache to 200 through its public
setMaxSize.
The test puts 127 keys in total and holds at most 126 at once, so at capacity
200 the second
phase cannot evict under any interleaving, and the eviction assertion keeps its
original
expected value of 0. Proof is the structural argument (capacity above the held
count), with
the 200,000-trial model as consistency evidence (0.62 percent failures at
capacity 100, none
at 200) and 32 forced full-class runs at the PR head as a regression check.
One residual is deliberately left: assertNull(lfuCache.get(1)) in the first
phase depends on
the same victim choice (the phase-1 eviction occasionally picks a victim other
than key 1)
and can still fail very rarely, about 1 run in 10,000 in the model, with or
without this fix.
This PR does not address it, and the test is not claimed to be deterministic.
#AI assistance
AI agents assisted with research, implementation, review, and drafting. Nick
Shanin directed
the work and takes responsibility for this contribution.
was:
#AI-generated, human-approved text below.
Summary
org.apache.solr.search.TestThinCache.testSimple fails intermittently with
"AssertionError: expected:<0> but was:<1>" at TestThinCache.java:170, together
with a classMethod teardown error reporting 3 unreleased SolrMetricsContext
objects. The test is the only coverage of ThinCache, the per-searcher scope
over a shared node-level cache introduced in SOLR-16654. The failure has been
recorded 14 times in the last 30 days across unrelated pull requests (list
below), including 10 times on branch_9x. It is a test defect, not a product
defect: no production code is involved in the race.
Failure signature
- TestThinCache.testSimple: expected:<0> but was:<1> at TestThinCache.java:170
(the second cache's evictions metric). The value is exactly 1 on every recorded
occurrence.
- classMethod teardown: 3 unreleased SolrMetricsContext objects (knock-on, see
root cause).
- Recorded occurrences (GitHub "Solr Tests via Crave" runs, 2026-09-09 to
2026-10-04): PR #4894 (seed C4077EAB80AE9E50), PR #4939 (60B12BB09380AC51), PR
#4943 (E58B5E1FFDEBA340), PR #5013 (30A1B1A830109349), and PR #4976 on
branch_9x ten times (E4DD10799981D14B, 2E53727468DE4DF1, 391A297131D7D9C1,
D8FD97BF9A8A48B0, FCA68807697335BA, 861F48CD4DFF5F51, D5B22838079384ED,
6E0A7AD71C551639, 7A1C354A4C7E10DC, FA416BA281EBD0DF).
Reproduction
Locally, the failure does not reproduce: all 14 recorded seeds were run against
current main with forced re-execution (cleanTest), plus default-seed runs, and
every run passed (17 runs). The #5013 seed also passed earlier on pre-merge
main, current main, and the PR head. The race needs the timing of a loaded CI
runner; the mechanism below is established from the code and from the invariant
failure value.
Root cause
testSimple puts 101 entries through a first ThinCache into a shared backing
cache of capacity 100, creating exactly one physical eviction, then warms a
second ThinCache from the first and keeps putting (25 warmed puts, then put
103) against the backing cache, which is still at capacity 100.
Eviction counting is per scope. A ThinCache counts an eviction only in
onRemoval, dispatched through the backing cache's removal listener registry,
and a scope registers with that registry only in initForSearcher, called from
initialSearcher and warm. testSimple never triggers that registration for the
first cache, so the first cache's eviction counter is always 0, and the
priorEvictions that warm copies into the second cache is always 0.
The second cache does register, at warm, and warm resets its eviction counter
after copying the priors. The warming phase that follows can itself evict,
because the backing is still at capacity 100. An eviction during that phase
whose victim sits in the second cache's scope is counted, if Caffeine has
delivered the removal notification by the time the assertion at line 170
samples the metric; if delivery lags, the sample reads 0. That delivery timing
is the whole race, and it is why the failure value is always exactly 1. The
teardown leak is a knock-on: the failed assertion skips the test's closing of
its SolrMetricsContext, and the framework reports the context and its two
per-cache children as unreleased.
An earlier draft of this ticket located the race at warm's copy of the first
cache's counter and proposed correcting the expected value to an inherited 1.
Building that fix falsified it: the first cache's counter reads 0
deterministically (it never registers), so there is no inherited 1. The
corrected mechanism above is what the shipped fix addresses.
Fix
Test-only, in PR #5029 ([https://github.com/apache/solr/pull/5029]): after the
first cache's assertions, enlarge the shared backing cache to 200 through its
public setMaxSize. The test never puts more than 126 distinct entries, so at
capacity 200 the warming phase cannot evict under any interleaving, and the
assertion keeps its original expected value of 0. Proof at the PR head: 32
forced full-class runs pass, covering all 14 recorded seeds, default-seed runs,
repeats of four seeds, and runs under CPU load; tidy, Error Prone and the
module check are green. No before/after pair is claimed, since the failure
never reproduced locally on unmodified main.
#AI assistance
AI agents assisted with research, implementation, review, and drafting. Nick
Shanin directed the work and takes responsibility for this contribution.
> TestThinCache.testSimple is flaky: a warming-phase eviction can hit the
> second cache's own scope
> ------------------------------------------------------------------------------------------------
>
> Key: SOLR-18506
> URL: https://issues.apache.org/jira/browse/SOLR-18506
> Project: Solr
> Issue Type: Bug
> Reporter: Nick Shanin
> Priority: Minor
> Labels: pull-request-available
> Time Spent: 10m
> Remaining Estimate: 0h
>
> #AI-generated, human-approved text below.
> Summary
> org.apache.solr.search.TestThinCache.testSimple fails intermittently with
> "AssertionError: expected:<0> but was:<1>" at TestThinCache.java:170,
> together with a
> classMethod teardown error reporting 3 unreleased SolrMetricsContext objects.
> The test is the
> only coverage of ThinCache, the per-searcher scope over a shared node-level
> cache introduced
> in SOLR-16654. The failure has been recorded 14 times in the last 30 days
> across unrelated
> pull requests (list below), including 10 times on branch_9x. It is a test
> defect, not a
> product defect: no production code is involved.
> Failure signature
> - TestThinCache.testSimple: expected:<0> but was:<1> at
> TestThinCache.java:170 (the second
> cache's evictions metric). The value is exactly 1 on every recorded
> occurrence.
> - classMethod teardown: 3 unreleased SolrMetricsContext objects (knock-on,
> see root cause).
> - Recorded occurrences (GitHub "Solr Tests via Crave" runs, 2026-09-09 to
> 2026-10-04):
> PR #4894 (seed C4077EAB80AE9E50), PR #4939 (60B12BB09380AC51), PR #4943
> (E58B5E1FFDEBA340),
> PR #5013 (30A1B1A830109349), and PR #4976 on branch_9x ten times
> (E4DD10799981D14B,
> 2E53727468DE4DF1, 391A297131D7D9C1, D8FD97BF9A8A48B0, FCA68807697335BA,
> 861F48CD4DFF5F51,
> D5B22838079384ED, 6E0A7AD71C551639, 7A1C354A4C7E10DC, FA416BA281EBD0DF).
> Reproduction
> Locally, the failure does not reproduce with the recorded seeds: all 14
> recorded seeds were
> run against current main with forced re-execution (cleanTest), plus
> default-seed runs, and
> every run passed. That is expected under the verified mechanism below: the
> outcome does not
> depend on the test seed, so no seed can reproduce it. It reproduces
> statistically instead.
> A standalone model of the test's put/get sequence against Caffeine 3.2.4 (the
> version this
> tree pins), run with 200,000 trials per configuration, fails the evictions
> assertion in
> 1,243 trials (0.62 percent) at the test's capacity of 100 and in none at the
> fixed capacity
> of 200.
> Root cause
> Eviction counting in ThinCache is per scope. A ThinCache counts an eviction
> only in
> onRemoval, dispatched through the backing cache's removal listener registry,
> and a scope
> registers with that registry only in initForSearcher, called from
> initialSearcher and warm.
> testSimple wires the first cache by hand and never triggers that registration
> for it, so the
> first cache's eviction counter is always 0, and the priorEvictions that warm
> copies into the
> second cache is always 0.
> The second cache registers at warm. warm performs its 25 warming puts first
> and only then
> resets the eviction counter, so evictions counted during warming are erased;
> the only
> operation that can leave a count afterwards is the test's put of key 103, and
> one put evicts
> at most one entry. That is why the failure value is always exactly 1.
> Until the fix, warming and the put of key 103 ran against a backing cache
> still at capacity
> 100 and already full, so each put evicted one entry. Which entry Caffeine
> picks as the victim
> depends on key hashes. ScopedKey.hashCode is Objects.hash(scope, key) and the
> test's scopes
> are plain new Object() instances, so the hashes come from identity hash
> codes: they vary per
> JVM and do not follow the test seed. Usually the victim is a first-cache
> entry, which is
> never counted. Occasionally (about 0.6 percent of runs in the model) the
> victim is one of the
> second cache's own entries, the count becomes 1, and the assertion fails.
> There is no notification timing race. CaffeineCache defaults async to true
> and then sets a
> same-thread executor (Runnable::run); the test's backing.init passes only
> size and
> initialSize, so evictions and their removal notifications complete
> synchronously inside the
> put that triggers them. In the model, the phase-1 eviction was already
> delivered when the
> 101st put returned in 200,000 of 200,000 trials, no listener call ran off the
> calling thread,
> and a later cleanUp() never delivered anything.
> The teardown leak is a knock-on: the failed assertion skips the test's
> closing of its
> SolrMetricsContext, and the framework reports the context and its two
> per-cache children as
> unreleased.
> Record of corrections: this ticket's original description located the race at
> warm's copy of
> the first cache's counter and proposed expecting an inherited value of 1.
> Building that fix
> falsified it (the first cache's counter reads 0 deterministically, because it
> never
> registers). The replacement account then kept a delivery-timing race in the
> second phase;
> review of the shipped PR falsified that too, by the synchronous-executor
> evidence above and
> by the model. The mechanism stated here is the verified one.
> Fix
> Shipped in PR #5029 ([https://github.com/apache/solr/pull/5029]), test-only:
> after the first
> cache's assertions, enlarge the shared backing cache to 200 through its
> public setMaxSize.
> The test puts 127 keys in total and holds at most 126 at once, so at capacity
> 200 the second
> phase cannot evict under any interleaving, and the eviction assertion keeps
> its original
> expected value of 0. Proof is the structural argument (capacity above the
> held count), with
> the 200,000-trial model as consistency evidence (0.62 percent failures at
> capacity 100, none
> at 200) and 32 forced full-class runs at the PR head as a regression check.
> One residual is deliberately left: assertNull(lfuCache.get(1)) in the first
> phase depends on
> the same victim choice (the phase-1 eviction occasionally picks a victim
> other than key 1)
> and can still fail very rarely, about 1 run in 10,000 in the model, with or
> without this fix.
> This PR does not address it, and the test is not claimed to be deterministic.
> #AI assistance
> AI agents assisted with research, implementation, review, and drafting. Nick
> Shanin directed
> the work and takes responsibility for this contribution.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
