[
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 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.
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: eviction assertion races Caffeine removal
> notification delivery
> --------------------------------------------------------------------------------------------------
>
> 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 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.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
