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)
```
--
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]
