Skip to content

HDDS-15966. Fix flaky TestScmHAFinalization#testSnapshotFinalization - #11200

Open
errose28 wants to merge 6 commits into
apache:HDDS-14496-zdufrom
errose28:worktree/flaky-scm-test
Open

HDDS-15966. Fix flaky TestScmHAFinalization#testSnapshotFinalization#11200
errose28 wants to merge 6 commits into
apache:HDDS-14496-zdufrom
errose28:worktree/flaky-scm-test

Conversation

@errose28

@errose28 errose28 commented Sep 3, 2026

Copy link
Copy Markdown
Contributor

What changes were proposed in this pull request?

This failure is unique to the ZDU branch. 200 runs on master passed, but 200 runs on the base ZDU branch (f535d5dabec700be68733241461b1f483d0c359e) showed some failures. Two types of failures showed up in this run on the ZDU branch:

Failure 1: DB is closed during read (6/200 times)

Problem

Tests run: 1, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 41.47 s <<< FAILURE! -- in org.apache.hadoop.hdds.upgrade.TestScmHAFinalization
org.apache.hadoop.hdds.upgrade.TestScmHAFinalization.testSnapshotFinalization -- Time elapsed: 41.37 s <<< ERROR!
java.lang.RuntimeException: org.apache.hadoop.hdds.utils.db.RocksDatabaseException: Rocks Database is closed
	at org.apache.hadoop.hdds.upgrade.HddsUpgradeTestUtils.isScmFinalized(HddsUpgradeTestUtils.java:136)
	at org.apache.hadoop.hdds.upgrade.HddsUpgradeTestUtils.lambda$waitForScmToFinalize$0(HddsUpgradeTestUtils.java:125)
	at org.apache.ozone.test.GenericTestUtils.waitFor(GenericTestUtils.java:127)
	at org.apache.hadoop.hdds.upgrade.HddsUpgradeTestUtils.waitForScmToFinalize(HddsUpgradeTestUtils.java:125)
	at org.apache.hadoop.hdds.upgrade.TestScmHAFinalization.testSnapshotFinalization(TestScmHAFinalization.java:195)
	at java.base/java.lang.reflect.Method.invoke(Method.java:565)
	at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:511)
	at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1450)
	at java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:2019)
	at java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:187)
Caused by: org.apache.hadoop.hdds.utils.db.RocksDatabaseException: Rocks Database is closed
	at org.apache.hadoop.hdds.utils.db.RocksDatabase.acquire(RocksDatabase.java:434)
	at org.apache.hadoop.hdds.utils.db.RocksDatabase.get(RocksDatabase.java:700)
	at org.apache.hadoop.hdds.utils.db.RDBTable.get(RDBTable.java:126)
	at org.apache.hadoop.hdds.utils.db.TypedTable.lambda$getFromTable$0(TypedTable.java:296)
	at org.apache.hadoop.hdds.utils.db.CodecBuffer.putFromSource(CodecBuffer.java:500)
	at org.apache.hadoop.hdds.utils.db.TypedTable.getFromTable(TypedTable.java:295)
	at org.apache.hadoop.hdds.utils.db.TypedTable.getFromTable(TypedTable.java:326)
	at org.apache.hadoop.hdds.utils.db.TypedTable.getFromTable(TypedTable.java:301)
	at org.apache.hadoop.hdds.utils.db.TypedTable.get(TypedTable.java:215)
	at org.apache.hadoop.hdds.upgrade.HddsUpgradeTestUtils.isScmFinalized(HddsUpgradeTestUtils.java:134)
	... 9 more

As soon as the stopped SCM is restarted and expected to install a snapshot, we begin polling its DB to see if the finalization key has been written yet as an indication that it has finalized. Snapshot install requires closing the DB and opening a new one, so there is a window where this call can fail before snapshot install finished.

Solution

Ignore transient errors while waiting for the DB status. If the DB is successfully installed but still produces errors for other reasons, the test will still fail with a timeout and log the stack traces.

Failure 2: Follower SCM fails to exit safemode (1/200 times)

Problem

Tests run: 1, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 96.81 s <<< FAILURE! -- in org.apache.hadoop.hdds.upgrade.TestScmHAFinalization
org.apache.hadoop.hdds.upgrade.TestScmHAFinalization.testSnapshotFinalization -- Time elapsed: 96.72 s <<< ERROR!
java.util.concurrent.TimeoutException: 
Timed out waiting for condition. Thread diagnostics:
Timestamp: 2026-08-28 05:01:13,218
...
"ForkJoinPool-1-worker-1" daemon prio=5 tid=36 runnable
java.lang.Thread.State: RUNNABLE
        at java.base@25.0.4.1/java.lang.Thread.dumpThreads(Native Method)
        at java.base@25.0.4.1/java.lang.Thread.getAllStackTraces(Thread.java:2246)
        at app//org.apache.ozone.test.TimedOutTestsListener.buildThreadDump(TimedOutTestsListener.java:81)
        at app//org.apache.ozone.test.TimedOutTestsListener.buildThreadDiagnosticString(TimedOutTestsListener.java:67)
        at app//org.apache.ozone.test.GenericTestUtils.waitFor(GenericTestUtils.java:137)
        at app//org.apache.hadoop.hdds.upgrade.HddsUpgradeTestUtils.waitForScmToFinalize(HddsUpgradeTestUtils.java:125)
        at app//org.apache.hadoop.hdds.upgrade.HddsUpgradeTestUtils.waitForScmsToFinalize(HddsUpgradeTestUtils.java:119)
        at app//org.apache.hadoop.hdds.upgrade.TestScmHAFinalization.testSnapshotFinalization(TestScmHAFinalization.java:174)

Test logs show the SCMs had the following roles:

  • scm1: leader
  • scm2: follower
  • scm3: initially inactive follower receiving the snapshot
2693 2026-08-28 17:00:08,878 [ForkJoinPool-1-worker-1] INFO  upgrade.TestScmHAFinalization (TestScmHAFinalization.java:testSnapshotFinalization(158)) - Inactive SCM node ID: scmNode-3

The test failed waiting for scm2. It is the only one whose logs show up in the finalization polling loop:

$ grep -e 'Waiting for SCM' org.apache.hadoop.hdds.upgrade.TestScmHAFinalization-output.txt | wc -l                                                             
31

$ grep -e 'Waiting for SCM scmNode-2' org.apache.hadoop.hdds.upgrade.TestScmHAFinalization-output.txt | wc -l 
31

However, the finalization condition currently checks for both finalization and safemode exit. The test logs further show that scm2 did finalize, but failed to exit safemode, which stalled the test:

2026-08-28 17:01:13,218 [ForkJoinPool-1-worker-1] INFO  upgrade.HddsUpgradeTestUtils (HddsUpgradeTestUtils.java:isScmFinalized(139)) - Waiting for SCM scmNode-2 (leader? false) to finalize.
Exited safemode? false
version manager finalized? true
DB key flushed? true
Requiring DB key to flush? false

Digging further, we see that the pipeline safemode rule is the only one that did not validate:

2026-08-28 17:00:59,619 [scmNode-2-SCM-SafeMode-Log-0] INFO  safemode.SCMSafeModeManager (SCMSafeModeManager.java:logSafeModeStatus(355)) - 
SCM SafeMode Status | state=PRE_CHECKS_PASSED preCheckComplete=true validatedPreCheckRules=1/1 validatedRules=6/7
SCM SafeMode Status | DataNodeSafeModeRule (validated) registered datanodes (=3) >= required datanodes (=3)
SCM SafeMode Status | RatisContainerSafeModeRule (validated) 100.00% of [RATIS] Containers(0 / 0) with at least N reported replica (=1.00) >= safeModeCutoff (=0.99)
SCM SafeMode Status | HealthyPipelineSafeModeRule (waiting) healthy RATIS/THREE pipelines (=0) >= healthyPipelineThresholdCount (=1)
SCM SafeMode Status | StateMachineReadyRule (validated) Refreshed SCM State Machine after leader ready: true
SCM SafeMode Status | OneReplicaPipelineSafeModeRule (validated) reported RATIS/THREE pipelines with at least one datanode (=0) >= threshold (=0)
SCM SafeMode Status | ECMinDataNodeSafeModeRule (validated) ECMinDataNodeSafeModeRule is not applicable (default replication is not EC)
SCM SafeMode Status | ECContainerSafeModeRule (validated) 100.00% of [EC] Containers(0 / 0) with at least N reported replica (=1.00) >= safeModeCutoff (=0.99)

So the test failure was caused by the pipeline safemode rule failing to validate in 1 minute on an SCM that is not the main one under test.

Root Cause

The order of operations to cause the failure is:

  • Datanodes register with leader and follower SCMs
  • Leader creates ALLOCATED pipelines on all SCMs via Ratis, and instructs Datanodes to create them.
  • Datanodes create the pipelines and report them as soon as a pipeline leader is elected.
  • Follower scm2 receives the report of the healthy pipeline, but the pipeline state is still tracked as ALLOCATED .
    • Pipeline state is controlled by the leader only.
  • Follower scm2 enters this block and calls PipelineManager#openPipeline, which delegates to a @Replicate method that will through NotLeaderException.
    • This prevents the OPEN_PIPELINE event from firing.
  • Leader scm1 gets the pipeline report and follows the same flow as the follower, but as the leader its PipelineManager#openPipeline call succeeds, firing the OPEN_PIPELINE event and moving it out of safemode.
  • Follower scm2 gets the leader's Ratis transaction to move the pipeline from ALLOCATED to OPEN, but this does not trigger any reprocessing of the active pipelines to affect the safemode rule.
  • Follower scm2 must then wait 60-120 seconds for the next pipeline report to validate the pipeline safemode rule against its newly peristed open pipeline state from the leader.
    • This elapses the test's safemode timeout

This is supported by another test run which reproduced the issue with additional logging added. Here we can see the Ratis three pipelines reach the call to open the pipeline on the scm2, but do not make it past that. Only the Attempting to open messages are present

cat ./org.apache.hadoop.hdds.upgrade.TestScmHAFinalization-output.txt | grep -e 'Attempting to open pipeline' -e 'Opened pipeline' | grep -e 'scmNode-2' | grep -e 'RATIS/THREE'
2026-09-03 19:13:49,711 [scmNode-2-EventQueue-PipelineReportForPipelineReportHandler] INFO  pipeline.PipelineReportHandler (PipelineReportHandler.java:processPipelineReport(135)) - Attempting to open pipeline Pipeline{ Id: cda462c9-e65a-480a-8754-cb3b4e228a65, Nodes: [ {3ba8f679-e713-47bc-9046-326e55102910(localhost/127.0.0.1), ReplicaIndex: 0}, {3dbbc103-67dd-41d7-a978-f23ed6e23d67(localhost/127.0.0.1), ReplicaIndex: 0}, {03bb2d51-ca1d-4409-9a45-3e43ea6ae5dd(localhost/127.0.0.1), ReplicaIndex: 0},], ReplicationConfig: RATIS/THREE, State:ALLOCATED, leaderId:3ba8f679-e713-47bc-9046-326e55102910, CreationTimestamp2026-09-03T19:13:45.839Z[Etc/UTC]} on scmNode-2
2026-09-03 19:13:49,713 [scmNode-2-EventQueue-PipelineReportForPipelineReportHandler] INFO  pipeline.PipelineReportHandler (PipelineReportHandler.java:processPipelineReport(135)) - Attempting to open pipeline Pipeline{ Id: c207d06d-e25e-459d-a4d6-b1b63b653f79, Nodes: [ {3ba8f679-e713-47bc-9046-326e55102910(localhost/127.0.0.1), ReplicaIndex: 0}, {3dbbc103-67dd-41d7-a978-f23ed6e23d67(localhost/127.0.0.1), ReplicaIndex: 0}, {03bb2d51-ca1d-4409-9a45-3e43ea6ae5dd(localhost/127.0.0.1), ReplicaIndex: 0},], ReplicationConfig: RATIS/THREE, State:ALLOCATED, leaderId:3dbbc103-67dd-41d7-a978-f23ed6e23d67, CreationTimestamp2026-09-03T19:13:45.834Z[Etc/UTC]} on scmNode-2
2026-09-03 19:13:49,716 [scmNode-2-EventQueue-PipelineReportForPipelineReportHandler] INFO  pipeline.PipelineReportHandler (PipelineReportHandler.java:processPipelineReport(135)) - Attempting to open pipeline Pipeline{ Id: cda462c9-e65a-480a-8754-cb3b4e228a65, Nodes: [ {3ba8f679-e713-47bc-9046-326e55102910(localhost/127.0.0.1), ReplicaIndex: 0}, {3dbbc103-67dd-41d7-a978-f23ed6e23d67(localhost/127.0.0.1), ReplicaIndex: 0}, {03bb2d51-ca1d-4409-9a45-3e43ea6ae5dd(localhost/127.0.0.1), ReplicaIndex: 0},], ReplicationConfig: RATIS/THREE, State:ALLOCATED, leaderId:3ba8f679-e713-47bc-9046-326e55102910, CreationTimestamp2026-09-03T19:13:45.839Z[Etc/UTC]} on scmNode-2

The new logs show the cause is the NotLeaderException, which only occurs on scm2:

$ cat ./org.apache.hadoop.hdds.upgrade.TestScmHAFinalization-output.txt | grep -i -e 'NLE prevented pipeline'
2026-09-03 19:13:47,847 [scmNode-2-EventQueue-PipelineReportForPipelineReportHandler] INFO  pipeline.PipelineReportHandler (PipelineReportHandler.java:onMessage(89)) - NLE prevented pipeline from being processed on scmNode-2
2026-09-03 19:13:48,409 [scmNode-2-EventQueue-PipelineReportForPipelineReportHandler] INFO  pipeline.PipelineReportHandler (PipelineReportHandler.java:onMessage(89)) - NLE prevented pipeline from being processed on scmNode-2
2026-09-03 19:13:48,413 [scmNode-2-EventQueue-PipelineReportForPipelineReportHandler] INFO  pipeline.PipelineReportHandler (PipelineReportHandler.java:onMessage(89)) - NLE prevented pipeline from being processed on scmNode-2
2026-09-03 19:13:49,713 [scmNode-2-EventQueue-PipelineReportForPipelineReportHandler] INFO  pipeline.PipelineReportHandler (PipelineReportHandler.java:onMessage(89)) - NLE prevented pipeline from being processed on scmNode-2
2026-09-03 19:13:49,715 [scmNode-2-EventQueue-PipelineReportForPipelineReportHandler] INFO  pipeline.PipelineReportHandler (PipelineReportHandler.java:onMessage(89)) - NLE prevented pipeline from being processed on scmNode-2
2026-09-03 19:13:49,717 [scmNode-2-EventQueue-PipelineReportForPipelineReportHandler] INFO  pipeline.PipelineReportHandler (PipelineReportHandler.java:onMessage(89)) - NLE prevented pipeline from being processed on scmNode-2

Follow-up Questions and Answers

Why does it always affect scm2 (the follower installing the snapshot)?

The leader SCM is able to submit the ratis request to move the pipeline state, so every report of a pipeline with a leader and existing datanodes will trigger the OPEN_PIPELINE event on the SCM leader. The follower installing the snapshot is not started until later in the test, so the SCM DB and Datanode pipeline state have converged by the time it loads the snapshot. No Datanode reports on this follower are dropped due to pipelines still be ALLOCATED in SCM. This leaves scm2 as the only node able to hit the issue.

Why doesn't this happen in other mini ozone cluster tests?

Standard mini ozone cluster tests only wait for the leader to exit safemode, so if followers hit this issue it does not affect test execution unless the test adds an extra assertion on follower safemode status like this one. This is an existing issue that occurs with very low probability and was just exposed due to this test change on the ZDU branch.

Why didn't this happen on the master version of this test?

The non-rolling upgrade framework on master bypasses the pipeline safemode rule while the cluster is finalizing, so it passes trivially regardless of the pipeline reports since all pipelines are expected to be closed while Datanodes finalize.

Is this a production issue?

Not really, because a real cluster would still converge to the expected value in 1-2 minutes. Within this window there could be a case where the only the leader is out of safemode and the cluster goes back in safemode because a follower is elected leader, but this was a known issue anyways and can only happen briefly right after startup. It may be helpful to add better logging for this case though.

Solution

If safemode exit for all SCMs was actually a requirement in this test, we could reduce the pipeline reporting interval. However, safemode exit is no longer required for SCM finalization in the new upgrade framework. It is only required to instruct OMs to finalize which is not covered by this test. This means we can just remove the safemode exit check from the assertion.

What is the link to the Apache JIRA

HDDS-15966

How was this patch tested?

@errose28 errose28 added test zdu Pull requests for Zero Downtime Upgrade (ZDU) https://issues.apache.org/jira/browse/HDDS-14496 labels Sep 3, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

test zdu Pull requests for Zero Downtime Upgrade (ZDU) https://issues.apache.org/jira/browse/HDDS-14496

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant