[
https://issues.apache.org/jira/browse/HBASE-30275?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Aman Poonia updated HBASE-30275:
--------------------------------
Description:
{noformat}
{noformat}
testBucketCacheRecoveryWithAllocationInconsistencies fails intermittently under
CI load with:
expected:<[blockType=DATA, fileOffset=8192, ...]> but was:<null>
Root Cause
BucketCache startup uses a background thread (startPersistenceRetriever) to
recover from the persistence file. Inside retrieveFromFile(),
[backingMapValidated.set(true) is called at line
1604|https://github.com/apache/hbase/blob/3c446d70274/hbase-server/src/main/java/org/apache/hadoop/hbase/io/hfile/bucket/BucketCache.java#L1604]
when the backing map has been validated. However, [cacheState is only set to
ENABLED at line
419|https://github.com/apache/hbase/blob/3c446d70274/hbase-server/src/main/java/org/apache/hadoop/hbase/io/hfile/bucket/BucketCache.java#L419]
in the finally block that follows, after retrieveFromFile()
returns.
[getBlock() gates on isCacheEnabled() at line
672|https://github.com/apache/hbase/blob/3c446d70274/hbase-server/src/main/java/org/apache/hadoop/hbase/io/hfile/bucket/BucketCache.java#L672]
(which checks cacheState ==
ENABLED), not on backingMapValidated. The [original test waited only on
backingMapValidated at lines
254-255|https://github.com/apache/hbase/blob/3c446d70274/hbase-server/src/test/java/org/apache/hadoop/hbase/io/hfile/bucket/TestRecoveryPersistentBucketCache.java#L254-L255]:
{code:java}
while (!newBucketCache.getBackingMapValidated().get()) {
Thread.sleep(10);
}
{code}
This leaves a race window: the test thread can wake from Thread.sleep(10),
observe backingMapValidated == true, call getBlock(), and hit "if
(!isCacheEnabled()) return null" — because cacheState is still INITIALIZING in
the gap between the two state transitions.
Evidence from CI
The surefire output for the failing test shows the background thread (Thread-8)
completing the two state transitions 1ms apart:
{code:java}
2026-07-04T23:41:25,196 INFO [Thread-8] bucket.BucketCache(1625): Bucket
cache retrieved from file successfully with size: 5
2026-07-04T23:41:25,197 INFO [Thread-8] bucket.BucketCache(392): Persistent
bucket cache recovery from .../bucket.persistence is complete.
{code}
Line 1625 is inside retrieveFromFile() — this is where
backingMapValidated.set(true) is called. Line 392 is in the finally block —
this is where cacheState = ENABLED is set. The two transitions are 1ms apart.
Under CI load (1360 concurrent tests), the OS can preempt Thread-8 in this 1ms
window. The test thread wakes from Thread.sleep(10), observes
backingMapValidated == true, and calls getBlock() — which silently returns null
because cacheState is still INITIALIZING.
The silent null return is further confirmed by the absence of
"BucketCache(671): bucket entry for key" debug log lines after the recovery —
those lines only appear when getBlock() gets past the isCacheEnabled() gate. For
comparison, a passing test in the same run (testBucketCacheRecovery, 32 MB
cache) shows those lines clearly:
{code:java}
2026-07-04T23:41:25,845 DEBUG [Time-limited test] bucket.BucketCache(671):
bucket entry for key 7642056151232044987_0: null
2026-07-04T23:41:25,854 DEBUG [Time-limited test] bucket.BucketCache(671):
bucket entry for key -596935897395116358_0: 33537024
2026-07-04T23:41:25,858 DEBUG [Time-limited test] bucket.BucketCache(671):
bucket entry for key 2901490290241531270_0: 33527808
{code}
For the failing test, no such lines appear at all — getBlock() exited before
reaching line 671.
The failure was reproduced in two consecutive builds (#18 and #19), confirming
it is a real race and not a flake.
Fix
Use Awaitility to wait for both conditions atomically before calling getBlock():
{code:java}
await().atMost(Duration.ofSeconds(30)).until(
() -> newBucketCache.getBackingMapValidated().get() &&
newBucketCache.isCacheEnabled());
{code}
This eliminates the race window by ensuring the test thread only proceeds once
cacheState == ENABLED is visible, which is the same gate that getBlock() checks.
was:
testBucketCacheRecoveryWithAllocationInconsistencies fails intermittently under
CI load with:
expected:<[blockType=DATA, fileOffset=8192, ...]> but was:<null>
Root Cause
BucketCache startup uses a background thread (startPersistenceRetriever) to
recover from the persistence file. Inside retrieveFromFile(),
backingMapValidated.set(true) is called at line 1604 when the backing map has
been
validated. However, cacheState is only set to ENABLED at line 419 in the
finally block that follows, after retrieveFromFile() returns.
getBlock() gates on isCacheEnabled() at line 672 (which checks cacheState ==
ENABLED), not on backingMapValidated. The original test waited only on
backingMapValidated at lines 254–255:
while (!newBucketCache.getBackingMapValidated().get()) {
Thread.sleep(10);
}
This leaves a race window: the test thread can wake from Thread.sleep(10),
observe backingMapValidated == true, call getBlock(), and hit if
(!isCacheEnabled()) return null — because cacheState is still INITIALIZING in
the
gap between the two state transitions.
*Evidence from CI*
The surefire output for the failing test shows the background thread
(Thread-8) completing the two state transitions 1ms apart:
2026-07-04T23:41:25,196 INFO [Thread-8] bucket.BucketCache(1625): Bucket
cache retrieved from file successfully with size: 5
2026-07-04T23:41:25,197 INFO [Thread-8] bucket.BucketCache(392): Persistent
bucket cache recovery from .../bucket.persistence is complete.
Line 1625 is inside retrieveFromFile() — this is where
backingMapValidated.set(true) is called. Line 392 is in the finally block —
this is where cacheState = ENABLED is set. The two transitions are 1ms apart.
Under CI load (1360 concurrent tests), the OS can preempt Thread-8 in this
1ms window. The test thread wakes from Thread.sleep(10), observes
backingMapValidated == true, and calls getBlock() — which silently returns null
because cacheState is still INITIALIZING.
The silent null return is further confirmed by the absence of
BucketCache(671): bucket entry for key debug log lines after the recovery —
those lines only appear when getBlock() gets past the isCacheEnabled() gate. For
comparison, a passing test in the same run (testBucketCacheRecovery, 32 MB
cache) shows those lines clearly:
2026-07-04T23:41:25,845 DEBUG [Time-limited test] bucket.BucketCache(671):
bucket entry for key 7642056151232044987_0: null
2026-07-04T23:41:25,854 DEBUG [Time-limited test] bucket.BucketCache(671):
bucket entry for key -596935897395116358_0: 33537024
2026-07-04T23:41:25,858 DEBUG [Time-limited test] bucket.BucketCache(671):
bucket entry for key 2901490290241531270_0: 33527808
For the failing test, no such lines appear at all — getBlock() exited before
reaching line 671.
The failure was reproduced in two consecutive builds (#18 and #19),
confirming it is a real race and not a flake.
Fix
Use Awaitility to wait for both conditions atomically before calling
getBlock():
await().atMost(Duration.ofSeconds(30)).until(
() -> newBucketCache.getBackingMapValidated().get() &&
newBucketCache.isCacheEnabled());
> TestRecoveryPersistentBucketCache#testBucketCacheRecoveryWithAllocationInconsistencies
> has a race condition between backingMapValidated and cacheState=ENABLED
> --------------------------------------------------------------------------------------------------------------------------------------------------------------
>
> Key: HBASE-30275
> URL: https://issues.apache.org/jira/browse/HBASE-30275
> Project: HBase
> Issue Type: Bug
> Affects Versions: 3.0.0-beta-1, 4.0.0-alpha-1, 2.6.6
> Reporter: Aman Poonia
> Assignee: Aman Poonia
> Priority: Minor
>
> {noformat}
> {noformat}
> testBucketCacheRecoveryWithAllocationInconsistencies fails intermittently
> under CI load with:
> expected:<[blockType=DATA, fileOffset=8192, ...]> but was:<null>
> Root Cause
> BucketCache startup uses a background thread (startPersistenceRetriever) to
> recover from the persistence file. Inside retrieveFromFile(),
> [backingMapValidated.set(true) is called at line
> 1604|https://github.com/apache/hbase/blob/3c446d70274/hbase-server/src/main/java/org/apache/hadoop/hbase/io/hfile/bucket/BucketCache.java#L1604]
> when the backing map has been validated. However, [cacheState is only set to
> ENABLED at line
> 419|https://github.com/apache/hbase/blob/3c446d70274/hbase-server/src/main/java/org/apache/hadoop/hbase/io/hfile/bucket/BucketCache.java#L419]
> in the finally block that follows, after retrieveFromFile()
> returns.
> [getBlock() gates on isCacheEnabled() at line
> 672|https://github.com/apache/hbase/blob/3c446d70274/hbase-server/src/main/java/org/apache/hadoop/hbase/io/hfile/bucket/BucketCache.java#L672]
> (which checks cacheState ==
> ENABLED), not on backingMapValidated. The [original test waited only on
> backingMapValidated at lines
> 254-255|https://github.com/apache/hbase/blob/3c446d70274/hbase-server/src/test/java/org/apache/hadoop/hbase/io/hfile/bucket/TestRecoveryPersistentBucketCache.java#L254-L255]:
> {code:java}
> while (!newBucketCache.getBackingMapValidated().get()) {
> Thread.sleep(10);
> }
> {code}
> This leaves a race window: the test thread can wake from Thread.sleep(10),
> observe backingMapValidated == true, call getBlock(), and hit "if
> (!isCacheEnabled()) return null" — because cacheState is still INITIALIZING in
> the gap between the two state transitions.
> Evidence from CI
> The surefire output for the failing test shows the background thread
> (Thread-8) completing the two state transitions 1ms apart:
> {code:java}
> 2026-07-04T23:41:25,196 INFO [Thread-8] bucket.BucketCache(1625): Bucket
> cache retrieved from file successfully with size: 5
> 2026-07-04T23:41:25,197 INFO [Thread-8] bucket.BucketCache(392):
> Persistent bucket cache recovery from .../bucket.persistence is complete.
> {code}
> Line 1625 is inside retrieveFromFile() — this is where
> backingMapValidated.set(true) is called. Line 392 is in the finally block —
> this is where cacheState = ENABLED is set. The two transitions are 1ms apart.
> Under CI load (1360 concurrent tests), the OS can preempt Thread-8 in this
> 1ms window. The test thread wakes from Thread.sleep(10), observes
> backingMapValidated == true, and calls getBlock() — which silently returns
> null
> because cacheState is still INITIALIZING.
> The silent null return is further confirmed by the absence of
> "BucketCache(671): bucket entry for key" debug log lines after the recovery —
> those lines only appear when getBlock() gets past the isCacheEnabled() gate.
> For
> comparison, a passing test in the same run (testBucketCacheRecovery, 32 MB
> cache) shows those lines clearly:
> {code:java}
> 2026-07-04T23:41:25,845 DEBUG [Time-limited test] bucket.BucketCache(671):
> bucket entry for key 7642056151232044987_0: null
> 2026-07-04T23:41:25,854 DEBUG [Time-limited test] bucket.BucketCache(671):
> bucket entry for key -596935897395116358_0: 33537024
> 2026-07-04T23:41:25,858 DEBUG [Time-limited test] bucket.BucketCache(671):
> bucket entry for key 2901490290241531270_0: 33527808
> {code}
> For the failing test, no such lines appear at all — getBlock() exited before
> reaching line 671.
> The failure was reproduced in two consecutive builds (#18 and #19),
> confirming it is a real race and not a flake.
> Fix
> Use Awaitility to wait for both conditions atomically before calling
> getBlock():
> {code:java}
> await().atMost(Duration.ofSeconds(30)).until(
> () -> newBucketCache.getBackingMapValidated().get() &&
> newBucketCache.isCacheEnabled());
> {code}
> This eliminates the race window by ensuring the test thread only proceeds
> once cacheState == ENABLED is visible, which is the same gate that getBlock()
> checks.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
