[
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(),
[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.
was:
{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.
> 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(),
> [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)
