KevinWikant commented on PR #7179: URL: https://github.com/apache/hadoop/pull/7179#issuecomment-2561182680
## Unit Test Failure - testDecommissionWithUCBlocksFeatureEnabledAndBackoffMonitor When I run `mvn -Dtest=TestDecommission test -o` locally, I am seeing about 1 in 5 cases where `testDecommissionWithUCBlocksFeatureEnabledAndBackoffMonitor` fails. The root cause is as follows: - one of the datanodes gets blocked in decommissioning state due to an Under Construction block replica (on the affected datanode) being tracked in `UnderConstructionBlocks` - logs show that the relevant Under Construction block replica was removed from `UnderConstructionBlocks`, but then was re-added very shortly after - the block replica was reported 2 times in FINALIZED state in short succession (i.e. a duplicate 2nd block report was generated for some reason with the same replica in the same state on the same datanode). - when the block replica is reported a 2nd time in FINALIZED state, the "`block.findStorageInfo(storageInfo) < 0`"" part of [this condition](https://github.com/apache/hadoop/blob/290ff093d220ca7fa86c6260c207fac7299116af/hadoop-hdfs-project/hadoop-hdfs/src/main/java/org/apache/hadoop/hdfs/server/blockmanagement/BlockManager.java#L3736) evaluates to false which causes the else condition to be executed Relevant logs: ``` [ERROR] testDecommissionWithUCBlocksFeatureEnabledAndBackoffMonitor(org.apache.hadoop.hdfs.TestDecommission) Time elapsed: 43.735 s <<< FAILURE! java.lang.AssertionError: Datanodes did not enter DECOMMISSIONED as expected at org.junit.Assert.fail(Assert.java:89) at org.apache.hadoop.hdfs.TestDecommission.testDecommissionWithUnderConstructionBlocksFeatureEnabled(TestDecommission.java:2487) at org.apache.hadoop.hdfs.TestDecommission.testDecommissionWithUCBlocksFeatureEnabledAndBackoffMonitor(TestDecommission.java:2346) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59) at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12) at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56) at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17) at org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:299) at org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:293) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.lang.Thread.run(Thread.java:750) ``` ``` 2024-12-23 19:11:18,180 [Time-limited test] DEBUG blockmanagement.UnderConstructionBlocks (UnderConstructionBlocks.java:getUnderConstructionBlocksByDatanode(448)) - Under Construction block counts: [{}] 2024-12-23 19:11:18,682 [Time-limited test] DEBUG blockmanagement.UnderConstructionBlocks (UnderConstructionBlocks.java:getUnderConstructionBlocksByDatanode(448)) - Under Construction block counts: [{}] ... 2024-12-23 19:11:19,184 [Time-limited test] INFO hdfs.TestDecommission (TestDecommission.java:testDecommissionWithUnderConstructionBlocksFeatureEnabled(2423)) - Decommission node 127.0.0.1:59384 with the UC replica 2024-12-23 19:11:19,259 [Time-limited test] INFO hdfs.TestDecommission (TestDecommission.java:testDecommissionWithUnderConstructionBlocksFeatureEnabled(2423)) - Decommission node 127.0.0.1:59371 with the UC replica ... 2024-12-23 19:11:22,710 [DatanodeAdminMonitor-0] DEBUG blockmanagement.UnderConstructionBlocks (UnderConstructionBlocks.java:getUnderConstructionBlocksByDatanode(448)) - Under Construction block counts: [{127.0.0.1:59384=1,127.0.0.1:59371=1}] 2024-12-23 19:11:22,823 [DatanodeAdminMonitor-0] DEBUG blockmanagement.UnderConstructionBlocks (UnderConstructionBlocks.java:getUnderConstructionBlocksByDatanode(448)) - Under Construction block counts: [{127.0.0.1:59384=1,127.0.0.1:59371=1}] ... 2024-12-23 19:11:22,711 [DatanodeAdminMonitor-0] INFO blockmanagement.DatanodeAdminBackoffMonitor (DatanodeAdminBackoffMonitor.java:processCompletedNodes(385)) - Cannot decommission datanode 127.0.0.1:59384 with 1 UC blocks: [blk_1073741825_1001] 2024-12-23 19:11:22,711 [DatanodeAdminMonitor-0] INFO blockmanagement.DatanodeAdminBackoffMonitor (DatanodeAdminBackoffMonitor.java:processCompletedNodes(385)) - Cannot decommission datanode 127.0.0.1:59371 with 1 UC blocks: [blk_1073741825_1001] 2024-12-23 19:11:22,711 [DatanodeAdminMonitor-0] INFO blockmanagement.DatanodeAdminBackoffMonitor (DatanodeAdminBackoffMonitor.java:run(229)) - Checked 0 blocks this tick. 2 nodes are now in maintenance or transitioning state. 0 nodes pending. 0 nodes waiting to be cancelled. ... 2024-12-23 19:11:29,384 [DatanodeAdminMonitor-0] DEBUG blockmanagement.UnderConstructionBlocks (UnderConstructionBlocks.java:getUnderConstructionBlocksByDatanode(448)) - Under Construction block counts: [{127.0.0.1:59384=1,127.0.0.1:59371=1}] 2024-12-23 19:11:29,888 [DatanodeAdminMonitor-0] DEBUG blockmanagement.UnderConstructionBlocks (UnderConstructionBlocks.java:getUnderConstructionBlocksByDatanode(448)) - Under Construction block counts: [{127.0.0.1:59384=1,127.0.0.1:59371=1}] ... 2024-12-23 19:11:30,912 [Block report processor] DEBUG blockmanagement.BlockManager (BlockManager.java:processReportedBlock(3449)) - Reported block blk_1073741825_1001 on 127.0.0.1:59371 size 1536 replicaState = FINALIZED 2024-12-23 19:11:30,912 [Block report processor] DEBUG blockmanagement.UnderConstructionBlocks (UnderConstructionBlocks.java:removeUcBlockFromSet(265)) - Removed UC block [blk_1073741825_1001->blk_1073741825_1001] from 127.0.0.1:59371, new total is [replicas=1 / blocks=1] 2024-12-23 19:11:30,912 [Block report processor] INFO BlockStateChange (BlockManager.java:addStoredBlock(3828)) - BLOCK* addStoredBlock: 127.0.0.1:59371 is added to blk_1073741825_1001 (size=1536) ... 2024-12-23 19:11:30,921 [Block report processor] DEBUG blockmanagement.BlockManager (BlockManager.java:processReportedBlock(3449)) - Reported block blk_1073741825_1001 on 127.0.0.1:59384 size 1536 replicaState = FINALIZED 2024-12-23 19:11:30,922 [Block report processor] DEBUG blockmanagement.UnderConstructionBlocks (UnderConstructionBlocks.java:removeUcBlockFromSet(265)) - Removed UC block [blk_1073741825_1001->blk_1073741825_1001] from 127.0.0.1:59384, new total is [replicas=0 / blocks=0] 2024-12-23 19:11:30,922 [Block report processor] INFO BlockStateChange (BlockManager.java:addStoredBlock(3828)) - BLOCK* addStoredBlock: 127.0.0.1:59384 is added to blk_1073741825_1001 (size=1536) ... 2024-12-23 19:11:30,922 [Block report processor] DEBUG blockmanagement.BlockManager (BlockManager.java:processReportedBlock(3449)) - Reported block blk_1073741825_1001 on 127.0.0.1:59371 size 1536 replicaState = FINALIZED 2024-12-23 19:11:30,923 [Block report processor] DEBUG blockmanagement.UnderConstructionBlocks (UnderConstructionBlocks.java:addUcBlockToSet(407)) - Add UC block blk_1073741825_1001 to 127.0.0.1:59371, new total is [replicas=1 / blocks=1] ... 2024-12-23 19:11:32,718 [DatanodeAdminMonitor-0] DEBUG blockmanagement.UnderConstructionBlocks (UnderConstructionBlocks.java:getUnderConstructionBlocksByDatanode(448)) - Under Construction block counts: [{127.0.0.1:59371=1}] ... 2024-12-23 19:11:32,718 [DatanodeAdminMonitor-0] INFO blockmanagement.DatanodeAdminBackoffMonitor (DatanodeAdminBackoffMonitor.java:processCompletedNodes(414)) - Node 127.0.0.1:59384 is sufficiently replicated and healthy, marked as Decommissioned. 2024-12-23 19:11:32,718 [DatanodeAdminMonitor-0] INFO blockmanagement.DatanodeAdminBackoffMonitor (DatanodeAdminBackoffMonitor.java:processCompletedNodes(385)) - Cannot decommission datanode 127.0.0.1:59371 with 1 UC blocks: [blk_1073741825_1001] ... 2024-12-23 19:11:37,723 [DatanodeAdminMonitor-0] DEBUG blockmanagement.UnderConstructionBlocks (UnderConstructionBlocks.java:getUnderConstructionBlocksByDatanode(448)) - Under Construction block counts: [{127.0.0.1:59371=1}] ... ``` Note how on datanode `127.0.0.1:59384` the replica is reported in FINALIZED state once & there are no issues. However, on `127.0.0.1:59371` the replica is reported in FINALIZED state twice & on the 2nd time it gets re-added to `UnderConstructionBlocks` erroneously. The solution I have implemented is to only add the replica to `UnderConstructionBlocks` if its reported in state `ReplicaState.RBW`. This way: - if the replica is reported in `ReplicaState.RBW` multiple times, then `addUcBlock` will be invoked multiple times with subsequent attempts being a no-op. - if the replica is reported in `ReplicaState.FINALIZED` (or other) multiple times, then `addUcBlock` will not be invoked erroneously on subsequent reports. - if there is an out-of-order state reporting for a replica (i.e. reported in `ReplicaState.FINALIZED` then erroneously reported in `ReplicaState.RBW` afterwards), then this scenario will lead to issues. But this should not be possible in practice per my understanding. -- 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]
