[
https://issues.apache.org/jira/browse/HDFS-16664?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17601373#comment-17601373
]
ASF GitHub Bot commented on HDFS-16664:
---------------------------------------
KevinWikant commented on PR #4568:
URL: https://github.com/apache/hadoop/pull/4568#issuecomment-1239579333
## Concrete Reproduce Steps
- Create a Hadoop cluster with:
- single Namenode (i.e. non-HA)
- 5 datanodes (DN1, DN2, DN3, DN4, DN5)
- dfs.namenode.corrupt.block.delete.immediately.enabled = false
- dfs.replication = 3
- Create the block with 3 replicas
```
echo "hello" > /tmp/test;
export HADOOP_USER_NAME=hdfs;
hdfs dfs -put /tmp/test /tmp/test;
hdfs dfs -ls /tmp/test;
```
- Determine the block locations of the 3 replicas
```
> hdfs fsck /tmp/test -files -blocks -locations;
...
0. BP-452161995-NN-1662558403599:blk_1073741825_1001 len=6 Live_repl=3
[DatanodeInfoWithStorage[DN1:9866,DS-XXX,DISK],
DatanodeInfoWithStorage[DN2:9866,DS-XXX,DISK],
DatanodeInfoWithStorage[DN3:9866,DS-XXX,DISK]]
...
```
- Stop DN1 & DN2
```
sudo systemctl disable hadoop-hdfs-datanode.service;
sudo systemctl stop hadoop-hdfs-datanode.service;
```
- Append the block which will cause it to be written to 2 new block locations
```
> hdfs dfs -appendToFile /tmp/test /tmp/test;
2022-09-07 13:49:58,779 INFO hdfs.DataStreamer: Exception in
createBlockOutputStream blk_1073741825_1001
java.net.ConnectException: Connection refused
at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
at
sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:716)
at
org.apache.hadoop.net.SocketIOWithTimeout.connect(SocketIOWithTimeout.java:206)
at org.apache.hadoop.net.NetUtils.connect(NetUtils.java:533)
at
org.apache.hadoop.hdfs.DataStreamer.createSocketForPipeline(DataStreamer.java:253)
at
org.apache.hadoop.hdfs.DataStreamer.createBlockOutputStream(DataStreamer.java:1725)
at
org.apache.hadoop.hdfs.DataStreamer.setupPipelineInternal(DataStreamer.java:1507)
at
org.apache.hadoop.hdfs.DataStreamer.setupPipelineForAppendOrRecovery(DataStreamer.java:1481)
at org.apache.hadoop.hdfs.DataStreamer.run(DataStreamer.java:720)
2022-09-07 13:49:58,783 WARN hdfs.DataStreamer: Error Recovery for
BP-452161995-NN-1662558403599:blk_1073741825_1001 in pipeline
[DatanodeInfoWithStorage[DN1:9866,DS-XXX,DISK],
DatanodeInfoWithStorage[DN2:9866,DS-XXX,DISK],
DatanodeInfoWithStorage[DN3:9866,DS-XXX,DISK]]: datanode
0(DatanodeInfoWithStorage[DN1:9866,DS-XXX,DISK]) is bad.
2022-09-07 13:49:58,808 WARN hdfs.DFSClient: Error transferring data from
DatanodeInfoWithStorage[DN2:9866,DS-XXX,DISK] to
DatanodeInfoWithStorage[DN4:9866,DS-XXX,DISK]: Connection refused
2022-09-07 13:49:58,996 INFO hdfs.DataStreamer: Exception in
createBlockOutputStream blk_1073741825_1001
java.net.ConnectException: Connection refused
at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
at
sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:716)
at
org.apache.hadoop.net.SocketIOWithTimeout.connect(SocketIOWithTimeout.java:206)
at org.apache.hadoop.net.NetUtils.connect(NetUtils.java:533)
at
org.apache.hadoop.hdfs.DataStreamer.createSocketForPipeline(DataStreamer.java:253)
at
org.apache.hadoop.hdfs.DataStreamer.createBlockOutputStream(DataStreamer.java:1725)
at
org.apache.hadoop.hdfs.DataStreamer.setupPipelineInternal(DataStreamer.java:1507)
at
org.apache.hadoop.hdfs.DataStreamer.setupPipelineForAppendOrRecovery(DataStreamer.java:1481)
at org.apache.hadoop.hdfs.DataStreamer.run(DataStreamer.java:720)
2022-09-07 13:49:58,996 WARN hdfs.DataStreamer: Error Recovery for
BP-452161995-NN-1662558403599:blk_1073741825_1001 in pipeline
[DatanodeInfoWithStorage[DN2:9866,DS-XXX,DISK],
DatanodeInfoWithStorage[DN3:9866,DS-XXX,DISK],
DatanodeInfoWithStorage[DN5:9866,DS-XXX,DISK]]: datanode
0(DatanodeInfoWithStorage[DN2:9866,DS-XXX,DISK]) is bad.
> hdfs dfs -cat /tmp/test;
hello
hello
```
- Determine the new block locations of the 3 replicas
```
> hdfs fsck /tmp/test -files -blocks -locations;
...
0. BP-452161995-NN-1662558403599:blk_1073741825_1004 len=12 Live_repl=3
[DatanodeInfoWithStorage[DN3:9866,DS-XXX,DISK],
DatanodeInfoWithStorage[DN4:9866,DS-XXX,DISK],
DatanodeInfoWithStorage[DN5:9866,DS-XXX,DISK]]
...
```
- Restart the Namenode so that the [block replicas are marked as
"stale"](https://code.amazon.com/packages/Aws157HadoopGit/blobs/c89b29bd421152f0e7e16936f18d9e852895c37a/--/hadoop-hdfs-project/hadoop-hdfs/src/main/java/org/apache/hadoop/hdfs/server/blockmanagement/DatanodeStorageInfo.java#L120)
- enable Namenode BlockManager DEBUG logging by setting Log4J
configuration "log4j.logger.BlockStateChange=DEBUG"
```
sudo systemctl restart hadoop-hdfs-namenode.service;
```
- Restart DN1 & DN2
```
sudo systemctl start hadoop-hdfs-datanode.service;
```
- Check the Namenode logs to confirm the block invalidation is postponed
```
2022-09-07 13:50:58,194 DEBUG BlockStateChange (Block report processor):
BLOCK* invalidateBlocks: postponing invalidation of
blk_1073741825_1001(stored=blk_1073741825_1004) on DN2:9866 because 1
replica(s) are located on nodes with potentially out-of-date block reports
2022-09-07 13:51:06,780 DEBUG BlockStateChange (Block report processor):
BLOCK* invalidateBlocks: postponing invalidation of
blk_1073741825_1001(stored=blk_1073741825_1004) on DN1:9866 because 1
replica(s) are located on nodes with potentially out-of-date block reports
```
- Restart any of DN3, DN4, or DN5 so that they send a block report
- note that the [block must be sufficiently replicated for this code path
to
occur](https://github.com/apache/hadoop/blob/a5adc27c99ffa0ee4f274276afd38f0e7367b9d2/hadoop-hdfs-project/hadoop-hdfs/src/main/java/org/apache/hadoop/hdfs/server/blockmanagement/BlockManager.java#L3693)
```
sudo systemctl start hadoop-hdfs-datanode.service;
```
- Check the Namenode logs to validate the invalidation requests were sent to
DN1 & DN2
```
2022-09-07 13:52:07,729 INFO org.apache.hadoop.hdfs.StateChange (IPC Server
handler 26 on default port 8020): BLOCK* registerDatanode: from
DatanodeRegistration(DN4:9866,
datanodeUuid=2792b414-8c97-4a36-bb3c-1bda67ea9f28, infoPort=9864,
infoSecurePort=0, ipcPort=9867,
storageInfo=lv=-57;cid=CID-4227a61e-3071-4e90-a8bd-0ca0ded28a9f;nsid=1332362960;c=1662558403599)
storage 2792b414-8c97-4a36-bb3c-1bda67ea9f28
2022-09-07 13:52:07,729 INFO org.apache.hadoop.net.NetworkTopology (IPC
Server handler 26 on default port 8020): Removing a node: /default-rack/DN4:9866
2022-09-07 13:52:07,730 INFO org.apache.hadoop.net.NetworkTopology (IPC
Server handler 26 on default port 8020): Adding a new node:
/default-rack/DN4:9866
2022-09-07 13:52:07,792 DEBUG BlockStateChange (IPC Server handler 22 on
default port 8020): *BLOCK* NameNode.blockReport: from
DatanodeRegistration(DN4:9866,
datanodeUuid=2792b414-8c97-4a36-bb3c-1bda67ea9f28, infoPort=9864,
infoSecurePort=0, ipcPort=9867,
storageInfo=lv=-57;cid=CID-4227a61e-3071-4e90-a8bd-0ca0ded28a9f;nsid=1332362960;c=1662558403599),
reports.length=2
2022-09-07 13:52:07,793 INFO BlockStateChange (Block report processor):
BLOCK* processReport 0x5b965acbde378e45: Processing first storage report for
DS-XXX from datanode 2792b414-8c97-4a36-bb3c-1bda67ea9f28
2022-09-07 13:52:07,793 DEBUG BlockStateChange (Block report processor):
BLOCK* addStoredBlock: Redundant addStoredBlock request received for
blk_1073741825_1004 on node DN4:9866 size 12
2022-09-07 13:52:07,793 DEBUG BlockStateChange (Block report processor):
BLOCK* invalidateBlock: blk_1073741825_1004(stored=blk_1073741825_1004) on
DN1:9866
2022-09-07 13:52:07,793 DEBUG BlockStateChange (Block report processor):
BLOCK* InvalidateBlocks: add blk_1073741825_1004 to DN1:9866
2022-09-07 13:52:07,793 DEBUG BlockStateChange (Block report processor):
BLOCK* removeStoredBlock: blk_1073741825_1004 from DN1:9866
2022-09-07 13:52:07,795 DEBUG BlockStateChange (Block report processor):
BLOCK* invalidateBlocks: blk_1073741825_1004(stored=blk_1073741825_1004) on
DN1:9866 listed for deletion.
2022-09-07 13:52:07,795 DEBUG BlockStateChange (Block report processor):
BLOCK* invalidateBlock: blk_1073741825_1004(stored=blk_1073741825_1004) on
DN2:9866
2022-09-07 13:52:07,795 DEBUG BlockStateChange (Block report processor):
BLOCK* InvalidateBlocks: add blk_1073741825_1004 to DN2:9866
2022-09-07 13:52:07,795 DEBUG BlockStateChange (Block report processor):
BLOCK* removeStoredBlock: blk_1073741825_1004 from DN2:9866
2022-09-07 13:52:07,795 DEBUG BlockStateChange (Block report processor):
BLOCK* invalidateBlocks: blk_1073741825_1004(stored=blk_1073741825_1004) on
DN2:9866 listed for deletion.
2022-09-07 13:52:07,795 INFO BlockStateChange (Block report processor):
BLOCK* processReport 0x5b965acbde378e45: from storage DS-XXX node
DatanodeRegistration(DN4:9866,
datanodeUuid=2792b414-8c97-4a36-bb3c-1bda67ea9f28, infoPort=9864,
infoSecurePort=0, ipcPort=9867,
storageInfo=lv=-57;cid=CID-4227a61e-3071-4e90-a8bd-0ca0ded28a9f;nsid=1332362960;c=1662558403599),
blocks: 1, hasStaleStorage: false, processing time: 2 msecs,
invalidatedBlocks: 0
2022-09-07 13:52:07,795 INFO BlockStateChange (Block report processor):
BLOCK* processReport 0x5b965acbde378e45: Processing first storage report for
DS-617e1346-8e62-40f0-a35a-5999c3fb2f64 from datanode
2792b414-8c97-4a36-bb3c-1bda67ea9f28
2022-09-07 13:52:07,795 INFO BlockStateChange (Block report processor):
BLOCK* processReport 0x5b965acbde378e45: from storage
DS-617e1346-8e62-40f0-a35a-5999c3fb2f64 node DatanodeRegistration(DN4:9866,
datanodeUuid=2792b414-8c97-4a36-bb3c-1bda67ea9f28, infoPort=9864,
infoSecurePort=0, ipcPort=9867,
storageInfo=lv=-57;cid=CID-4227a61e-3071-4e90-a8bd-0ca0ded28a9f;nsid=1332362960;c=1662558403599),
blocks: 0, hasStaleStorage: false, processing time: 0 msecs,
invalidatedBlocks: 0
2022-09-07 13:52:09,128 DEBUG BlockStateChange (RedundancyMonitor): BLOCK*
neededReconstruction = 0 pendingReconstruction = 0
2022-09-07 13:52:09,128 DEBUG BlockStateChange (RedundancyMonitor): BLOCK*
BlockManager: ask DN2:9866 to delete [blk_1073741825_1004]
2022-09-07 13:52:09,128 DEBUG BlockStateChange (RedundancyMonitor): BLOCK*
BlockManager: ask DN1:9866 to delete [blk_1073741825_1004]
```
- Check the datanode logs (for DN1 & DN2) to validate the "GenerationStamp
not matched" exception occurs
```
2022-09-07 13:50:58,206 INFO org.apache.hadoop.hdfs.server.datanode.DataNode
(BP-452161995-NN-1662558403599 heartbeating to NN/NN:8020): Successfully sent
block report 0x65d28e4f71df62a6, containing 2 storage report(s), of which we
sent 2. The reports had 1 total blocks and used 1 RPC(s). This took 3 msec to
generate and 19 msecs for RPC and NN processing. Got back one command:
FinalizeCommand/5.
2022-09-07 13:50:58,206 INFO org.apache.hadoop.hdfs.server.datanode.DataNode
(BP-452161995-NN-1662558403599 heartbeating to NN/NN:8020): Got finalize
command for block pool BP-452161995-NN-1662558403599
2022-09-07 13:52:10,159 WARN org.apache.hadoop.hdfs.server.datanode.DataNode
(BP-452161995-NN-1662558403599 heartbeating to NN/NN:8020): Error processing
datanode Command
java.io.IOException: Failed to delete 1 (out of 1) replica(s):
0) Failed to delete replica blk_1073741825_1004: GenerationStamp not
matched, existing replica is blk_1073741825_1001
at
org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.FsDatasetImpl.invalidate(FsDatasetImpl.java:2135)
at
org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.FsDatasetImpl.invalidate(FsDatasetImpl.java:2034)
at
org.apache.hadoop.hdfs.server.datanode.BPOfferService.processCommandFromActive(BPOfferService.java:734)
at
org.apache.hadoop.hdfs.server.datanode.BPOfferService.processCommandFromActor(BPOfferService.java:680)
at
org.apache.hadoop.hdfs.server.datanode.BPServiceActor.processCommand(BPServiceActor.java:883)
at
org.apache.hadoop.hdfs.server.datanode.BPServiceActor.offerService(BPServiceActor.java:678)
at
org.apache.hadoop.hdfs.server.datanode.BPServiceActor.run(BPServiceActor.java:849)
at java.lang.Thread.run(Thread.java:750)
```
```
2022-09-07 13:51:06,797 INFO org.apache.hadoop.hdfs.server.datanode.DataNode
(BP-452161995-NN-1662558403599 heartbeating to NN/NN:8020): Successfully sent
block report 0x43c9d07e94b8c90b, containing 2 storage report(s), of which we
sent 2. The reports had 1 total blocks and used 1 RPC(s). This took 4 msec to
generate and 26 msecs for RPC and NN processing. Got back one command:
FinalizeCommand/5.
2022-09-07 13:51:06,797 INFO org.apache.hadoop.hdfs.server.datanode.DataNode
(BP-452161995-NN-1662558403599 heartbeating to NN/NN:8020): Got finalize
command for block pool BP-452161995-NN-1662558403599
2022-09-07 13:52:09,738 WARN org.apache.hadoop.hdfs.server.datanode.DataNode
(BP-452161995-NN-1662558403599 heartbeating to NN/NN:8020): Error processing
datanode Command
java.io.IOException: Failed to delete 1 (out of 1) replica(s):
0) Failed to delete replica blk_1073741825_1004: GenerationStamp not
matched, existing replica is blk_1073741825_1001
at
org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.FsDatasetImpl.invalidate(FsDatasetImpl.java:2135)
at
org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.FsDatasetImpl.invalidate(FsDatasetImpl.java:2034)
at
org.apache.hadoop.hdfs.server.datanode.BPOfferService.processCommandFromActive(BPOfferService.java:734)
at
org.apache.hadoop.hdfs.server.datanode.BPOfferService.processCommandFromActor(BPOfferService.java:680)
at
org.apache.hadoop.hdfs.server.datanode.BPServiceActor.processCommand(BPServiceActor.java:883)
at
org.apache.hadoop.hdfs.server.datanode.BPServiceActor.offerService(BPServiceActor.java:678)
at
org.apache.hadoop.hdfs.server.datanode.BPServiceActor.run(BPServiceActor.java:849)
at java.lang.Thread.run(Thread.java:750)
```
> Use correct GenerationStamp when invalidating corrupt block replicas
> --------------------------------------------------------------------
>
> Key: HDFS-16664
> URL: https://issues.apache.org/jira/browse/HDFS-16664
> Project: Hadoop HDFS
> Issue Type: Bug
> Reporter: Kevin Wikant
> Priority: Major
> Labels: pull-request-available
> Time Spent: 2h 20m
> Remaining Estimate: 0h
>
> While trying to backport HDFS-16064 to an older Hadoop version, the new unit
> test "testDeleteCorruptReplicaForUnderReplicatedBlock" started failing
> unexpectedly.
> Upon deep diving this unit test failure, I identified a bug in HDFS corrupt
> replica invalidation which results in the following datanode exception:
> {quote}2022-07-16 08:07:52,041 [BP-958471676-X-1657973243350 heartbeating to
> localhost/127.0.0.1:61365] WARN datanode.DataNode
> (BPServiceActor.java:processCommand(887)) - Error processing datanode Command
> java.io.IOException: Failed to delete 1 (out of 1) replica(s):
> 0) Failed to delete replica blk_1073741825_1005: GenerationStamp not matched,
> existing replica is blk_1073741825_1001
> at
> org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.FsDatasetImpl.invalidate(FsDatasetImpl.java:2139)
> at
> org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.FsDatasetImpl.invalidate(FsDatasetImpl.java:2034)
> at
> org.apache.hadoop.hdfs.server.datanode.BPOfferService.processCommandFromActive(BPOfferService.java:735)
> at
> org.apache.hadoop.hdfs.server.datanode.BPOfferService.processCommandFromActor(BPOfferService.java:680)
> at
> org.apache.hadoop.hdfs.server.datanode.BPServiceActor.processCommand(BPServiceActor.java:883)
> at
> org.apache.hadoop.hdfs.server.datanode.BPServiceActor.offerService(BPServiceActor.java:678)
> at
> org.apache.hadoop.hdfs.server.datanode.BPServiceActor.run(BPServiceActor.java:849)
> at java.lang.Thread.run(Thread.java:750)
> {quote}
> The issue is that the Namenode is sending wrong generationStamp to the
> datanode. By adding some additional logs, I was able to determine the root
> cause for this:
> * the generationStamp sent in the DNA_INVALIDATE is based on the
> [generationStamp of the block sent in the block
> report|https://github.com/apache/hadoop/blob/8774f178686487007dcf8c418c989b785a529000/hadoop-hdfs-project/hadoop-hdfs/src/main/java/org/apache/hadoop/hdfs/server/blockmanagement/BlockManager.java#L3733]
> * the problem is that the datanode with the corrupt block replica (that
> receives the DNA_INVALIDATE) is not necissarily the same datanode that sent
> the block report
> * this can cause the above exception when the corrupt block replica on the
> datanode receiving the DNA_INVALIDATE & the block replica on the datanode
> that sent the block report have different generationStamps
> The solution is to store the corrupt replicas generationStamp in the
> CorruptReplicasMap, then to extract this correct generationStamp value when
> sending the DNA_INVALIDATE to the datanode
>
> h2. Failed Test - Before the fix
> {quote}> mvn test
> -Dtest=TestDecommission#testDeleteCorruptReplicaForUnderReplicatedBlock
>
> [INFO] Results:
> [INFO]
> [ERROR] Failures:
> [ERROR]
> TestDecommission.testDeleteCorruptReplicaForUnderReplicatedBlock:2035 Node
> 127.0.0.1:61366 failed to complete decommissioning. numTrackedNodes=1 ,
> numPendingNodes=0 , adminState=Decommission In Progress ,
> nodesWithReplica=[127.0.0.1:61366, 127.0.0.1:61419]
> {quote}
> Logs:
> {quote}> cat
> target/surefire-reports/org.apache.hadoop.hdfs.TestDecommission-output.txt |
> grep 'Expected Replicas:|XXX|FINALIZED|Block now|Failed to delete'
> 2022-07-16 08:07:45,891 [Listener at localhost/61378] INFO
> hdfs.TestDecommission
> (TestDecommission.java:testDeleteCorruptReplicaForUnderReplicatedBlock(1942))
> - Block now has 2 corrupt replicas on [127.0.0.1:61370 , 127.0.0.1:61375] and
> 1 live replica on 127.0.0.1:61366
> 2022-07-16 08:07:45,913 [Listener at localhost/61378] INFO
> hdfs.TestDecommission
> (TestDecommission.java:testDeleteCorruptReplicaForUnderReplicatedBlock(1974))
> - Block now has 2 corrupt replicas on [127.0.0.1:61370 , 127.0.0.1:61375] and
> 1 decommissioning replica on 127.0.0.1:61366
> XXX invalidateBlock dn=127.0.0.1:61415 , blk=1073741825_1001
> XXX postponeBlock dn=127.0.0.1:61415 , blk=1073741825_1001
> XXX invalidateBlock dn=127.0.0.1:61419 , blk=1073741825_1003
> XXX addToInvalidates dn=127.0.0.1:61419 , blk=1073741825_1003
> XXX addBlocksToBeInvalidated dn=127.0.0.1:61419 , blk=1073741825_1003
> XXX rescanPostponedMisreplicatedBlocks blk=1073741825_1005
> XXX DNA_INVALIDATE dn=/127.0.0.1:61419 , blk=1073741825_1003
> XXX invalidate(on DN) dn=/127.0.0.1:61419 , invalidBlk=blk_1073741825_1003 ,
> blkByIdAndGenStamp = FinalizedReplica, blk_1073741825_1003, FINALIZED
> 2022-07-16 08:07:49,084 [BP-958471676-X-1657973243350 heartbeating to
> localhost/127.0.0.1:61365] INFO impl.FsDatasetAsyncDiskService
> (FsDatasetAsyncDiskService.java:deleteAsync(226)) - Scheduling
> blk_1073741825_1003 replica FinalizedReplica, blk_1073741825_1003, FINALIZED
> XXX addBlock dn=127.0.0.1:61419 , blk=1073741825_1005 *<<< block report is
> coming from 127.0.0.1:61419 which has genStamp=1005*
> XXX invalidateCorruptReplicas dn=127.0.0.1:61415 ,
> reported_blk=1073741825_1005 *<<< corrupt replica is on 127.0.0.1:61415
> which is expecting genStamp=1001*
> XXX addToInvalidates dn=127.0.0.1:61415 , blk=1073741825_1005
> 2022-07-16 08:07:49,431 [DatanodeAdminMonitor-0] INFO BlockStateChange
> (DatanodeAdminManager.java:logBlockReplicationInfo(417)) - Block:
> blk_1073741825_1005, Expected Replicas: 2, live replicas: 1, corrupt
> replicas: 0, decommissioned replicas: 0, decommissioning replicas: 1,
> maintenance replicas: 0, live entering maintenance replicas: 0, excess
> replicas: 0, Is Open File: false, Datanodes having this block:
> 127.0.0.1:61366 127.0.0.1:61419 , Current Datanode: 127.0.0.1:61366, Is
> current datanode decommissioning: true, Is current datanode entering
> maintenance: false
> XXX addBlocksToBeInvalidated dn=127.0.0.1:61415 , blk=1073741825_1005 *<<<
> Namenode sends wrong genStamp to 127.0.0.1:61415*
> XXX DNA_INVALIDATE dn=/127.0.0.1:61415 , blk=1073741825_1005
> XXX invalidate(on DN) dn=/127.0.0.1:61415 , invalidBlk=blk_1073741825_1005 ,
> blkByIdAndGenStamp = null
> XXX invalidate(on DN) dn=/127.0.0.1:61415 , invalidBlk=blk_1073741825_1005 ,
> blkById = FinalizedReplica, blk_1073741825_1001, FINALIZED
> 2022-07-16 08:07:52,041 [BP-958471676-X-1657973243350 heartbeating to
> localhost/127.0.0.1:61365] WARN datanode.DataNode
> (BPServiceActor.java:processCommand(887)) - Error processing datanode Command
> java.io.IOException: Failed to delete 1 (out of 1) replica(s):
> 0) Failed to delete replica blk_1073741825_1005: GenerationStamp not matched,
> existing replica is blk_1073741825_1001
> at
> org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.FsDatasetImpl.invalidate(FsDatasetImpl.java:2139)
> at
> org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.FsDatasetImpl.invalidate(FsDatasetImpl.java:2034)
> at
> org.apache.hadoop.hdfs.server.datanode.BPOfferService.processCommandFromActive(BPOfferService.java:735)
> at
> org.apache.hadoop.hdfs.server.datanode.BPOfferService.processCommandFromActor(BPOfferService.java:680)
> at
> org.apache.hadoop.hdfs.server.datanode.BPServiceActor.processCommand(BPServiceActor.java:883)
> at
> org.apache.hadoop.hdfs.server.datanode.BPServiceActor.offerService(BPServiceActor.java:678)
> at
> org.apache.hadoop.hdfs.server.datanode.BPServiceActor.run(BPServiceActor.java:849)
> at java.lang.Thread.run(Thread.java:750)
> 2022-07-16 08:07:52,384 [DataXceiver for client at /127.0.0.1:61434
> [Receiving block BP-958471676-X-1657973243350:blk_1073741825_1005]] INFO
> datanode.DataNode (DataXceiver.java:writeBlock(939)) - opWriteBlock
> BP-958471676-X-1657973243350:blk_1073741825_1005 received exception
> org.apache.hadoop.hdfs.server.datanode.ReplicaAlreadyExistsException: Block
> BP-958471676-X-1657973243350:blk_1073741825_1005 already exists in state
> FINALIZED and thus cannot be created.
> 2022-07-16 08:07:52,385 [DataXceiver for client at /127.0.0.1:61434
> [Receiving block BP-958471676-X-1657973243350:blk_1073741825_1005]] INFO
> datanode.DataNode (DataXceiver.java:run(307)) - 127.0.0.1:61415:DataXceiver
> error processing WRITE_BLOCK operation src: /127.0.0.1:61434 dst:
> /127.0.0.1:61415;
> org.apache.hadoop.hdfs.server.datanode.ReplicaAlreadyExistsException: Block
> BP-958471676-X-1657973243350:blk_1073741825_1005 already exists in state
> FINALIZED and thus cannot be created.
> 2022-07-16 08:07:54,422 [DatanodeAdminMonitor-0] INFO BlockStateChange
> (DatanodeAdminManager.java:logBlockReplicationInfo(417)) - Block:
> blk_1073741825_1005, Expected Replicas: 2, live replicas: 1, corrupt
> replicas: 0, decommissioned replicas: 0, decommissioning replicas: 1,
> maintenance replicas: 0, live entering maintenance replicas: 0, excess
> replicas: 0, Is Open File: false, Datanodes having this block:
> 127.0.0.1:61366 127.0.0.1:61419 , Current Datanode: 127.0.0.1:61366, Is
> current datanode decommissioning: true, Is current datanode entering
> maintenance: false
> ...
> 2022-07-16 08:08:24,426 [DatanodeAdminMonitor-0] INFO BlockStateChange
> (DatanodeAdminManager.java:logBlockReplicationInfo(417)) - Block:
> blk_1073741825_1005, Expected Replicas: 2, live replicas: 1, corrupt
> replicas: 0, decommissioned replicas: 0, decommissioning replicas: 1,
> maintenance replicas: 0, live entering maintenance replicas: 0, excess
> replicas: 0, Is Open File: false, Datanodes having this block:
> 127.0.0.1:61366 127.0.0.1:61419 , Current Datanode: 127.0.0.1:61366, Is
> current datanode decommissioning: true, Is current datanode entering
> maintenance: false
> {quote}
> Note the inline comments above which illustrate the bug
> h2. Successful Test - After the fix
> {quote}> mvn test
> -Dtest=TestDecommission#testDeleteCorruptReplicaForUnderReplicatedBlock
> [INFO] Results:
> [INFO]
> [INFO] Tests run: 1, Failures: 0, Errors: 0, Skipped: 0
> {quote}
> Logs:
> {quote}> cat
> target/surefire-reports/org.apache.hadoop.hdfs.TestDecommission-output.txt |
> grep 'Expected Replicas:|XXX|FINALIZED|Block now|Failed to delete'
> 2022-07-16 07:54:30,648 [Listener at localhost/60376] INFO
> hdfs.TestDecommission
> (TestDecommission.java:testDeleteCorruptReplicaForUnderReplicatedBlock(1942))
> - Block now has 2 corrupt replicas on [127.0.0.1:60364 , 127.0.0.1:60368] and
> 1 live replica on 127.0.0.1:60373
> 2022-07-16 07:54:30,669 [Listener at localhost/60376] INFO
> hdfs.TestDecommission
> (TestDecommission.java:testDeleteCorruptReplicaForUnderReplicatedBlock(1974))
> - Block now has 2 corrupt replicas on [127.0.0.1:60364 , 127.0.0.1:60368] and
> 1 decommissioning replica on 127.0.0.1:60373
> XXX invalidateBlock dn=127.0.0.1:60423 , blk=1073741825_1001
> XXX postponeBlock dn=127.0.0.1:60423 , blk=1073741825_1001
> XXX invalidateBlock dn=127.0.0.1:60427 , blk=1073741825_1003
> XXX addToInvalidates dn=127.0.0.1:60427 , blk=1073741825_1003
> XXX addBlocksToBeInvalidated dn=127.0.0.1:60427 , blk=1073741825_1003
> XXX rescanPostponedMisreplicatedBlocks blk=1073741825_1005
> XXX DNA_INVALIDATE dn=/127.0.0.1:60427 , blk=1073741825_1003
> XXX invalidate(on DN) dn=/127.0.0.1:60427 , invalidBlk=blk_1073741825_1003 ,
> blkByIdAndGenStamp = FinalizedReplica, blk_1073741825_1003, FINALIZED
> 2022-07-16 07:54:32,831 [BP-1469857843-X-1657972447604 heartbeating to
> localhost/127.0.0.1:60363] INFO impl.FsDatasetAsyncDiskService
> (FsDatasetAsyncDiskService.java:deleteAsync(226)) - Scheduling
> blk_1073741825_1003 replica FinalizedReplica, blk_1073741825_1003, FINALIZED
> 2022-07-16 07:54:33,772 [DatanodeAdminMonitor-0] INFO BlockStateChange
> (DatanodeAdminManager.java:logBlockReplicationInfo(417)) - Block:
> blk_1073741825_1005, Expected Replicas: 2, live replicas: 0, corrupt
> replicas: 1, decommissioned replicas: 0, decommissioning replicas: 1,
> maintenance replicas: 0, live entering maintenance replicas: 0, excess
> replicas: 0, Is Open File: false, Datanodes having this block:
> 127.0.0.1:60373 127.0.0.1:60423 , Current Datanode: 127.0.0.1:60373, Is
> current datanode decommissioning: true, Is current datanode entering
> maintenance: false
> XXX addBlock dn=127.0.0.1:60427 , blk=1073741825_1005
> XXX invalidateCorruptReplicas dn=127.0.0.1:60423 ,
> reported_blk=1073741825_1005
> XXX getCorruptReplicaGenerationStamp dn=127.0.0.1:60423 , genStamp=1001
> XXX addToInvalidates dn=127.0.0.1:60423 , blk=1073741825_1001
> XXX addBlocksToBeInvalidated dn=127.0.0.1:60423 , blk=1073741825_1001
> XXX DNA_INVALIDATE dn=/127.0.0.1:60423 , blk=1073741825_1001
> XXX invalidate(on DN) dn=/127.0.0.1:60423 , invalidBlk=blk_1073741825_1001 ,
> blkByIdAndGenStamp = FinalizedReplica, blk_1073741825_1001, FINALIZED
> 2022-07-16 07:54:35,796 [BP-1469857843-X-1657972447604 heartbeating to
> localhost/127.0.0.1:60363] INFO impl.FsDatasetAsyncDiskService
> (FsDatasetAsyncDiskService.java:deleteAsync(226)) - Scheduling
> blk_1073741825_1001 replica FinalizedReplica, blk_1073741825_1001, FINALIZED
> XXX addBlock dn=127.0.0.1:60423 , blk=1073741825_1005
> 2022-07-16 07:54:40,768 [Listener at localhost/60430] INFO
> hdfs.TestDecommission
> (TestDecommission.java:testDeleteCorruptReplicaForUnderReplicatedBlock(2050))
> - Block now has 2 live replicas on [127.0.0.1:60423 , 127.0.0.1:60427] and 1
> decommissioned replica on 127.0.0.1:60373
> {quote}
> Using "getCorruptReplicaGenerationStamp" allows the Namenode to get the
> correct generationStamp for the corrupt block replica
>
> h2. Why does unit test failure not reproduce in Hadoop trunk?
> In trunk the block invalidation does not get [postponed
> here|https://github.com/apache/hadoop/blob/8774f178686487007dcf8c418c989b785a529000/hadoop-hdfs-project/hadoop-hdfs/src/main/java/org/apache/hadoop/hdfs/server/blockmanagement/BlockManager.java#L1986]
> Instead, both corrupt replicas are invalidated immediately during the first
> block report:
> {quote}> cat
> target/surefire-reports/org.apache.hadoop.hdfs.TestDecommission-output.txt |
> grep XXX
> XXX addToInvalidates dn=127.0.0.1:57051 , blk=1073741825_1001
> XXX addToInvalidates dn=127.0.0.1:57055 , blk=1073741825_1003
> {quote}
> The reason for this difference in behavior is not clear at this point
> h2. Additional Info
> * stack trace for when corrupt replica gets immediately invalidated on
> datanode restart (i.e. first block report)
>
> {quote}java.lang.Thread.getStackTrace(Thread.java:1564)
> org.apache.hadoop.hdfs.server.blockmanagement.BlockManager.addToInvalidates(BlockManager.java:1670)
> org.apache.hadoop.hdfs.server.blockmanagement.BlockManager.invalidateBlock(BlockManager.java:1850)
> org.apache.hadoop.hdfs.server.blockmanagement.BlockManager.markBlockAsCorrupt(BlockManager.java:1816)
> org.apache.hadoop.hdfs.server.blockmanagement.BlockManager.processFirstBlockReport(BlockManager.java:2929)
> org.apache.hadoop.hdfs.server.blockmanagement.BlockManager.processReport(BlockManager.java:2665)
> org.apache.hadoop.hdfs.server.namenode.NameNodeRpcServer.lambda$blockReport$0(NameNodeRpcServer.java:1588)
> java.util.concurrent.FutureTask.run(FutureTask.java:266)
> org.apache.hadoop.hdfs.server.blockmanagement.BlockManager$BlockReportProcessingThread.processQueue(BlockManager.java:5066)
> org.apache.hadoop.hdfs.server.blockmanagement.BlockManager$BlockReportProcessingThread.run(BlockManager.java:5045)
> {quote}
>
> * stack trace for after corrupt replica is removed from datanode & datanode
> notifies namenode (i.e. incremental block report)
> ** this is where the issue begins because the DN which sends the IBR is not
> the same as the DN with the remaining corrupt replica
> {quote}java.lang.Thread.getStackTrace(Thread.java:1564)
> org.apache.hadoop.hdfs.server.blockmanagement.BlockManager.addToInvalidates(BlockManager.java:1670)
> org.apache.hadoop.hdfs.server.blockmanagement.BlockManager.invalidateBlock(BlockManager.java:1850)
> org.apache.hadoop.hdfs.server.blockmanagement.BlockManager.invalidateCorruptReplicas(BlockManager.java:3477)
> org.apache.hadoop.hdfs.server.blockmanagement.BlockManager.addStoredBlock(BlockManager.java:3436)
> org.apache.hadoop.hdfs.server.blockmanagement.BlockManager.processAndHandleReportedBlock(BlockManager.java:4094)
> org.apache.hadoop.hdfs.server.blockmanagement.BlockManager.addBlock(BlockManager.java:4023)
> org.apache.hadoop.hdfs.server.blockmanagement.BlockManager.processIncrementalBlockReport(BlockManager.java:4151)
> org.apache.hadoop.hdfs.server.blockmanagement.BlockManager.processIncrementalBlockReport(BlockManager.java:4118)
> org.apache.hadoop.hdfs.server.namenode.FSNamesystem.processIncrementalBlockReport(FSNamesystem.java:4800)
> org.apache.hadoop.hdfs.server.namenode.NameNodeRpcServer$1.run(NameNodeRpcServer.java:1643)
> org.apache.hadoop.hdfs.server.blockmanagement.BlockManager$BlockReportProcessingThread.processQueue(BlockManager.java:5066)
> org.apache.hadoop.hdfs.server.blockmanagement.BlockManager$BlockReportProcessingThread.run(BlockManager.java:5045)
> {quote}
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
---------------------------------------------------------------------
To unsubscribe, e-mail: hdfs-issues-unsubscr...@hadoop.apache.org
For additional commands, e-mail: hdfs-issues-h...@hadoop.apache.org
