[
https://issues.apache.org/jira/browse/HBASE-30275?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
ASF GitHub Bot updated HBASE-30275:
-----------------------------------
Labels: pull-request-available (was: )
> 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
> Labels: pull-request-available
>
> {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(),
> [BucketCache.java#L1604|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,
> [BucketCache.java#L419|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
> [TestRecoveryPersistentBucketCache.java#L254-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)
