You are viewing a plain text version of this content. The canonical link for it is here.
Posted to common-issues@hadoop.apache.org by GitBox <gi...@apache.org> on 2022/09/07 15:53:35 UTC
[GitHub] [hadoop] KevinWikant commented on pull request #4568: HDFS-16664. Use correct GenerationStamp when invalidating corrupt block replicas
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: common-issues-unsubscribe@hadoop.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: common-issues-unsubscribe@hadoop.apache.org
For additional commands, e-mail: common-issues-help@hadoop.apache.org