[
https://issues.apache.org/jira/browse/HDFS-15837?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17285488#comment-17285488
]
Udit Mehrotra commented on HDFS-15837:
--------------------------------------
[~kihwal] hadoop version is *2.8.5* running on EMR. So the block it seems was
successfully written with size *3554* and ultimately reported as a bad block.
Can you point to some of the probable causes for this that you have seen ?
Could this be due to high network load on the particular data node ?
Also, is there something we can do to avoid recurrence of this. At this time we
are investigating a strategy to distribute the network load to avoid data node
from being overwhelmed. But we still want to understand the root cause for this.
> Incorrect bytes causing block corruption after update pipeline and recovery
> failure
> -----------------------------------------------------------------------------------
>
> Key: HDFS-15837
> URL: https://issues.apache.org/jira/browse/HDFS-15837
> Project: Hadoop HDFS
> Issue Type: Bug
> Components: datanode, hdfs
> Affects Versions: 2.8.5
> Reporter: Udit Mehrotra
> Priority: Major
>
> We are seeing cases on HDFS blocks being marked as *bad* after the initial
> block receive fails during *update pipeline* followed by *HDFS* *recovery*
> for the block failing as well. Here is the life cycle of a block
> *{{blk_1342440165_272630578}}* that was ultimately marked as corrupt:
> 1. The block creation starts at name node as part of *update pipeline*
> process:
> {noformat}
> 2021-01-25 03:41:17,335 INFO
> org.apache.hadoop.hdfs.server.namenode.FSNamesystem (IPC Server handler 61 on
> 8020): updatePipeline(blk_1342440165_272500939 => blk_1342440165_272630578)
> success{noformat}
> 2. The block receiver on the data node fails with a socket timeout exception,
> and so do the retries:
> {noformat}
> 2021-01-25 03:42:22,525 INFO org.apache.hadoop.hdfs.server.datanode.DataNode
> (PacketResponder:
> BP-908477295-172.21.224.178-1606768078949:blk_1342440165_272630578,
> type=HAS_DOWNSTREAM_IN_PIPELINE, downstreams=1:[172.21.246.239:50010]):
> PacketResponder:
> BP-908477295-172.21.224.178-1606768078949:blk_1342440165_272630578,
> type=HAS_DOWNSTREAM_IN_PIPELINE, downstreams=1:[172.21.246.239:50010]
> java.net.SocketTimeoutException: 65000 millis timeout while waiting for
> channel to be ready for read. ch : java.nio.channels.SocketChannel[connected
> local=/172.21.226.26:56294 remote=/172.21.246.239:50010]
> at
> org.apache.hadoop.net.SocketIOWithTimeout.doIO(SocketIOWithTimeout.java:164)
> at
> org.apache.hadoop.net.SocketInputStream.read(SocketInputStream.java:161)
> at
> org.apache.hadoop.net.SocketInputStream.read(SocketInputStream.java:131)
> at
> org.apache.hadoop.net.SocketInputStream.read(SocketInputStream.java:118)
> at java.io.FilterInputStream.read(FilterInputStream.java:83)
> at java.io.FilterInputStream.read(FilterInputStream.java:83)
> at
> org.apache.hadoop.hdfs.protocolPB.PBHelperClient.vintPrefixed(PBHelperClient.java:400)
> at
> org.apache.hadoop.hdfs.protocol.datatransfer.PipelineAck.readFields(PipelineAck.java:213)
> at
> org.apache.hadoop.hdfs.server.datanode.BlockReceiver$PacketResponder.run(BlockReceiver.java:1305)
> at java.lang.Thread.run(Thread.java:748)
> 2021-01-25 03:42:22,526 WARN org.apache.hadoop.hdfs.server.datanode.DataNode
> (PacketResponder:
> BP-908477295-172.21.224.178-1606768078949:blk_1342440165_272630578,
> type=HAS_DOWNSTREAM_IN_PIPELINE, downstreams=1:[172.21.246.239:50010]):
> IOException in BlockReceiver.run():
> java.io.IOException: Connection reset by peer
> at sun.nio.ch.FileDispatcherImpl.write0(Native Method)
> at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47)
> at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93)
> at sun.nio.ch.IOUtil.write(IOUtil.java:65)
> at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:468)
> at
> org.apache.hadoop.net.SocketOutputStream$Writer.performIO(SocketOutputStream.java:63)
> at
> org.apache.hadoop.net.SocketIOWithTimeout.doIO(SocketIOWithTimeout.java:142)
> at
> org.apache.hadoop.net.SocketOutputStream.write(SocketOutputStream.java:159)
> at
> org.apache.hadoop.net.SocketOutputStream.write(SocketOutputStream.java:117)
> at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
> at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)
> at java.io.DataOutputStream.flush(DataOutputStream.java:123)
> at
> org.apache.hadoop.hdfs.server.datanode.BlockReceiver$PacketResponder.sendAckUpstreamUnprotected(BlockReceiver.java:1552)
> at
> org.apache.hadoop.hdfs.server.datanode.BlockReceiver$PacketResponder.sendAckUpstream(BlockReceiver.java:1489)
> at
> org.apache.hadoop.hdfs.server.datanode.BlockReceiver$PacketResponder.run(BlockReceiver.java:1402)
> at java.lang.Thread.run(Thread.java:748)
> 2021-01-25 03:42:22,526 INFO org.apache.hadoop.hdfs.server.datanode.DataNode
> (PacketResponder:
> BP-908477295-172.21.224.178-1606768078949:blk_1342440165_272630578,
> type=HAS_DOWNSTREAM_IN_PIPELINE, downstreams=1:[172.21.246.239:50010]):
> PacketResponder:
> BP-908477295-172.21.224.178-1606768078949:blk_1342440165_272630578,
> type=HAS_DOWNSTREAM_IN_PIPELINE, downstreams=1:[172.21.246.239:50010]
> java.io.IOException: Connection reset by peer
> at sun.nio.ch.FileDispatcherImpl.write0(Native Method)
> at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47)
> at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93)
> at sun.nio.ch.IOUtil.write(IOUtil.java:65)
> at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:468)
> at
> org.apache.hadoop.net.SocketOutputStream$Writer.performIO(SocketOutputStream.java:63)
> at
> org.apache.hadoop.net.SocketIOWithTimeout.doIO(SocketIOWithTimeout.java:142)
> at
> org.apache.hadoop.net.SocketOutputStream.write(SocketOutputStream.java:159)
> at
> org.apache.hadoop.net.SocketOutputStream.write(SocketOutputStream.java:117)
> at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
> at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)
> at java.io.DataOutputStream.flush(DataOutputStream.java:123)
> at
> org.apache.hadoop.hdfs.server.datanode.BlockReceiver$PacketResponder.sendAckUpstreamUnprotected(BlockReceiver.java:1552)
> at
> org.apache.hadoop.hdfs.server.datanode.BlockReceiver$PacketResponder.sendAckUpstream(BlockReceiver.java:1489)
> at
> org.apache.hadoop.hdfs.server.datanode.BlockReceiver$PacketResponder.run(BlockReceiver.java:1402)
> at java.lang.Thread.run(Thread.java:748){noformat}
> 3. The data node terminates the receiving of block and initiates recovery:
> {noformat}
> 2021-01-25 03:42:22,526 INFO org.apache.hadoop.hdfs.server.datanode.DataNode
> (PacketResponder:
> BP-908477295-172.21.224.178-1606768078949:blk_1342440165_272630578,
> type=HAS_DOWNSTREAM_IN_PIPELINE, downstreams=1:[172.21.246.239:50010]):
> PacketResponder:
> BP-908477295-172.21.224.178-1606768078949:blk_1342440165_272630578,
> type=HAS_DOWNSTREAM_IN_PIPELINE, downstreams=1:[172.21.246.239:50010]
> terminating
> 2021-01-25 03:42:22,529 INFO org.apache.hadoop.hdfs.server.datanode.DataNode
> (DataXceiver for client DFSClient_NONMAPREDUCE_390070548_42 at
> /172.21.240.31:60430 [Receiving block
> BP-908477295-172.21.224.178-1606768078949:blk_1342440165_272630578]):
> Receiving BP-908477295-172.21.224.178-1606768078949:blk_1342440165_272630578
> src: /172.21.240.31:60430 dest: /172.21.226.26:50010
> 2021-01-25 03:42:22,529 INFO
> org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.FsDatasetImpl
> (DataXceiver for client DFSClient_NONMAPREDUCE_390070548_42 at
> /172.21.240.31:60430 [Receiving block
> BP-908477295-172.21.224.178-1606768078949:blk_1342440165_272630578]): Recover
> RBW replica
> BP-908477295-172.21.224.178-1606768078949:blk_1342440165_272630578{noformat}
> 4. The recovery on the datanode for *{{blk_1342440165_272630578}}* fails with:
> {noformat}
> 2021-01-25 03:42:34,223 INFO org.apache.hadoop.hdfs.server.datanode.DataNode
> (DataXceiver for client DFSClient_NONMAPREDUCE_390070548_42 at
> /172.21.240.31:45918 [Receiving block
> BP-908477295-172.21.224.178-1606768078949:blk_1342440165_272500939]):
> Exception for
> BP-908477295-172.21.224.178-1606768078949:blk_1342440165_272630578
> java.nio.channels.ClosedByInterruptException
> at
> java.nio.channels.spi.AbstractInterruptibleChannel.end(AbstractInterruptibleChannel.java:202)
> at sun.nio.ch.FileChannelImpl.position(FileChannelImpl.java:269)
> at
> org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.FsDatasetImpl.adjustCrcChannelPosition(FsDatasetImpl.java:1716)
> at
> org.apache.hadoop.hdfs.server.datanode.BlockReceiver.adjustCrcFilePosition(BlockReceiver.java:1052)
> at
> org.apache.hadoop.hdfs.server.datanode.BlockReceiver.receivePacket(BlockReceiver.java:733)
> at
> org.apache.hadoop.hdfs.server.datanode.BlockReceiver.receiveBlock(BlockReceiver.java:923)
> at
> org.apache.hadoop.hdfs.server.datanode.DataXceiver.writeBlock(DataXceiver.java:854)
> at
> org.apache.hadoop.hdfs.protocol.datatransfer.Receiver.opWriteBlock(Receiver.java:166)
> at
> org.apache.hadoop.hdfs.protocol.datatransfer.Receiver.processOp(Receiver.java:103)
> at
> org.apache.hadoop.hdfs.server.datanode.DataXceiver.run(DataXceiver.java:288)
> at java.lang.Thread.run(Thread.java:748)
> 2021-01-25 03:42:34,223 INFO org.apache.hadoop.hdfs.server.datanode.DataNode
> (DataXceiver for client DFSClient_NONMAPREDUCE_390070548_42 at
> /172.21.240.31:45918 [Receiving block
> BP-908477295-172.21.224.178-1606768078949:blk_1342440165_272500939]):
> opWriteBlock
> BP-908477295-172.21.224.178-1606768078949:blk_1342440165_272630578 received
> exception java.nio.channels.ClosedByInterruptException
> 2021-01-25 03:42:34,223 ERROR org.apache.hadoop.hdfs.server.datanode.DataNode
> (DataXceiver for client DFSClient_NONMAPREDUCE_390070548_42 at
> /172.21.240.31:45918 [Receiving block
> BP-908477295-172.21.224.178-1606768078949:blk_1342440165_272500939]):
> ip-172-21-226-26.ec2.internal:50010:DataXceiver error processing WRITE_BLOCK
> operation src: /172.21.240.31:45918 dst: /172.21.226.26:50010
> java.nio.channels.ClosedByInterruptException
> at
> java.nio.channels.spi.AbstractInterruptibleChannel.end(AbstractInterruptibleChannel.java:202)
> at sun.nio.ch.FileChannelImpl.position(FileChannelImpl.java:269)
> at
> org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.FsDatasetImpl.adjustCrcChannelPosition(FsDatasetImpl.java:1716)
> at
> org.apache.hadoop.hdfs.server.datanode.BlockReceiver.adjustCrcFilePosition(BlockReceiver.java:1052)
> at
> org.apache.hadoop.hdfs.server.datanode.BlockReceiver.receivePacket(BlockReceiver.java:733)
> at
> org.apache.hadoop.hdfs.server.datanode.BlockReceiver.receiveBlock(BlockReceiver.java:923)
> at
> org.apache.hadoop.hdfs.server.datanode.DataXceiver.writeBlock(DataXceiver.java:854)
> at
> org.apache.hadoop.hdfs.protocol.datatransfer.Receiver.opWriteBlock(Receiver.java:166)
> at
> org.apache.hadoop.hdfs.protocol.datatransfer.Receiver.processOp(Receiver.java:103)
> at
> org.apache.hadoop.hdfs.server.datanode.DataXceiver.run(DataXceiver.java:288)
> at java.lang.Thread.run(Thread.java:748){noformat}
>
> 5. This is followed by the resetting of bytes on the data node to {{3072}}
> the correct length, which is an expected behavior based on
> https://issues.apache.org/jira/browse/hdfs-11472:
> {noformat}
> 2021-01-25 03:42:40,007 INFO
> org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.FsDatasetImpl
> (DataXceiver for client DFSClient_NONMAPREDUCE_390070548_42 at
> /172.21.240.31:60430 [Receiving block
> BP-908477295-172.21.224.178-1606768078949:blk_1342440165_272630578]): At
> ip-172-21-226-26.ec2.internal:50010, Recovering ReplicaBeingWritten,
> blk_1342440165_272630578, RBW
> getNumBytes() = 3072
> getBytesOnDisk() = 2678
> getVisibleLength()= 3072
> getVolume() = /mnt/hdfs/current
> getBlockFile() =
> /mnt/hdfs/current/BP-908477295-172.21.224.178-1606768078949/current/rbw/blk_1342440165
> bytesAcked=3072
> bytesOnDisk=2678
> 2021-01-25 03:42:40,011 INFO org.apache.hadoop.hdfs.server.datanode.DataNode
> (DataXceiver for client
> DFSClient_attempt_16089610225137_1287341_r_000139_0_392781198_30 at
> /172.21.244.117:34354 [Receiving block
> BP-908477295-172.21.224.178-1606768078949:blk_1342762434_272648220]):
> Receiving BP-908477295-172.21.224.178-1606768078949:blk_1342762434_272648220
> src: /172.21.244.117:34354 dest: /172.21.226.26:50010
> 2021-01-25 03:42:40,013 INFO
> org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.FsDatasetImpl
> (DataXceiver for client DFSClient_NONMAPREDUCE_390070548_42 at
> /172.21.240.31:60430 [Receiving block
> BP-908477295-172.21.224.178-1606768078949:blk_1342440165_272630578]):
> Resetting bytesOnDisk to match blockDataLength (=3072) for replica
> ReplicaBeingWritten, blk_1342440165_272630578, RBW
> getNumBytes() = 3072
> getBytesOnDisk() = 2678
> getVisibleLength()= 3072
> getVolume() = /mnt/hdfs/current
> getBlockFile() =
> /mnt/hdfs/current/BP-908477295-172.21.224.178-1606768078949/current/rbw/blk_1342440165
> bytesAcked=3072
> bytesOnDisk=2678{noformat}
> 6. Since recovery failed, the Name Node restarts the {{updatePipeline}} for
> the block by increasing the generation:
> {noformat}
> 2021-01-25 03:42:40,034 INFO
> org.apache.hadoop.hdfs.server.namenode.FSNamesystem (IPC Server handler 15 on
> 8020): updatePipeline(blk_1342440165_272630578, newGS=272645069,
> newLength=3072, newNodes=[172.21.226.26:50010],
> client=DFSClient_NONMAPREDUCE_390070548_42)
> 2021-01-25 03:42:40,034 INFO
> org.apache.hadoop.hdfs.server.namenode.FSNamesystem (IPC Server handler 15 on
> 8020): updatePipeline(blk_1342440165_272630578 => blk_1342440165_272645069)
> success{noformat}
> Notice how the correct *{{newLength}}* in sent in the above log from Name
> Node i.e. *{{3072}}*.
> 7. The data node then receives the new generation block of this block
> correctly:
> {noformat}
> 2021-01-25 03:46:40,066 INFO
> org.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace (PacketResponder:
> BP-908477295-172.21.224.178-1606768078949:blk_1342440165_272645069,
> type=LAST_IN_PIPELINE): src: /172.21.240.31:60430, dest:
> /172.21.226.26:50010, bytes: 3554, op: HDFS_WRITE, cliID:
> DFSClient_NONMAPREDUCE_390070548_42, offset: 0, srvID:
> 1a2ff556-73f5-4e10-b018-a0c2105b242e, blockid:
> BP-908477295-172.21.224.178-1606768078949:blk_1342440165_272645069, duration:
> 240052941459
> 2021-01-25 03:46:40,066 INFO org.apache.hadoop.hdfs.server.datanode.DataNode
> (PacketResponder:
> BP-908477295-172.21.224.178-1606768078949:blk_1342440165_272645069,
> type=LAST_IN_PIPELINE): PacketResponder:
> BP-908477295-172.21.224.178-1606768078949:blk_1342440165_272645069,
> type=LAST_IN_PIPELINE terminating{noformat}
> But here notice how bytes: *3554* which is different from what was sent from
> the Name Node i.e. *3072*.
> 8. The data node then does the successful downstream replication into another
> node for this block:
> {noformat}
> 2021-01-25 03:46:43,093 INFO org.apache.hadoop.hdfs.server.datanode.DataNode
> (BP-908477295-172.21.224.178-1606768078949 heartbeating to
> /172.21.238.225:8020): DatanodeRegistration(172.21.226.26:50010,
> datanodeUuid=1a2ff556-73f5-4e10-b018-a0c2105b242e, infoPort=50075,
> infoSecurePort=0, ipcPort=50020,
> storageInfo=lv=-57;cid=CID-7608840c-3634-4377-9ba0-1c710e6d08d5;nsid=2011779031;c=1606768078949)
> Starting thread to transfer
> BP-908477295-172.21.224.178-1606768078949:blk_1342440165_272645069 to
> 172.21.234.181:50010
> 2021-01-25 03:46:43,094 INFO org.apache.hadoop.hdfs.server.datanode.DataNode
> (org.apache.hadoop.hdfs.server.datanode.DataNode$DataTransfer@5cb29d58):
> DataTransfer, at ip-172-21-226-26.ec2.internal:50010: Transmitted
> BP-908477295-172.21.224.178-1606768078949:blk_1342440165_272645069
> (numBytes=3554) to /172.21.234.181:5001{noformat}
> 9. However, immediately after successful transmitting and replication the
> namenode declares the block as corrupt:
> {noformat}
> 2021-01-25 03:46:43,106 INFO org.apache.hadoop.hdfs.StateChange (IPC Server
> handler 46 on 8020): *DIR* reportBadBlocks for block:
> BP-908477295-172.21.224.178-1606768078949:blk_1342440165_272645069 on
> datanode: 172.21.226.26:50010{noformat}
>
> Any suggestions on what could cause this difference in the bytes communicated
> by the name node (3072) vs whats written on the the data node (3554) ?
>
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
---------------------------------------------------------------------
To unsubscribe, e-mail: hdfs-issues-unsubscr...@hadoop.apache.org
For additional commands, e-mail: hdfs-issues-h...@hadoop.apache.org
