Aman Poonia created HBASE-30275:
-----------------------------------
Summary:
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: 2.6.6, 3.0.0-beta-1, 4.0.0-alpha-1
Reporter: Aman Poonia
Assignee: Aman Poonia
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());
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
