errose28 opened a new pull request, #11200: URL: https://github.com/apache/ozone/pull/11200
## What changes were proposed in this pull request? This failure is unique to the ZDU branch. 200 runs on master [passed](https://github.com/errose28/ozone/actions/runs/33209406389), but 200 runs on the base ZDU branch (`f535d5dabec700be68733241461b1f483d0c359e`) [showed some failures](https://github.com/errose28/ozone/actions/runs/33191082082/job/98917400243). 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](https://github.com/apache/ozone/blob/4cd5c364dfb8d17cf87245bd41e24b27d0a9dd95/hadoop-ozone/integration-test/src/test/java/org/apache/hadoop/hdds/upgrade/HddsUpgradeTestUtils.java#L134) 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 [email protected]/java.lang.Thread.dumpThreads(Native Method) at [email protected]/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](https://github.com/apache/ozone/blob/4cd5c364dfb8d17cf87245bd41e24b27d0a9dd95/hadoop-ozone/integration-test/src/test/java/org/apache/hadoop/hdds/upgrade/HddsUpgradeTestUtils.java#L146). 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](https://github.com/apache/ozone/blob/71a27e3fc1f7feebf3fd1ffe8fca051055bdd1b3/hadoop-hdds/container-service/src/main/java/org/apache/hadoop/ozone/container/common/transport/server/ratis/XceiverServerRatis.java#L953). - 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](https://github.com/apache/ozone/blob/4779634ab4f87cdf12928e360ab3022c4619f384/hadoop-hdds/server-scm/src/main/java/org/apache/hadoop/hdds/scm/pipeline/PipelineReportHandler.java#L126) 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](https://github.com/apache/ozone/blob/3ee57e60521347a6b6900f8b6e66050415084f03/hadoop-hdds/container-service/src/main/java/org/apache/hadoop/ozone/container/common/report/PipelineReportPublisher.java#L59) 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](https://github.com/errose28/ozone/actions/runs/33792911962/job/100774968560) which reproduced the issue with [additional logging added](https://github.com/errose28/ozone/commit/28dd5adc8517b68b9fa6f5a0827628793d17f578). 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](https://github.com/apache/ozone/blob/8acc0413a9548462df8a699133d009a230dff2c5/hadoop-ozone/mini-cluster/src/main/java/org/apache/hadoop/ozone/MiniOzoneClusterImpl.java#L197), 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](https://github.com/apache/ozone/blob/396e875943ac9f421b31022dcfb1f7b5bc84d50a/hadoop-hdds/server-scm/src/main/java/org/apache/hadoop/hdds/scm/safemode/HealthyPipelineSafeModeRule.java#L127) 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? - With both fixes in place the entire `TestScmHAFinalization` suite passed [400 times on my fork](https://github.com/errose28/ozone/actions/runs/33679809869) -- This is an automated message from the Apache Git Service. To respond to the message, please log on to GitHub and use the URL above to go to the specific comment. To unsubscribe, e-mail: [email protected] For queries about this service, please contact Infrastructure at: [email protected] --------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
