DataNode连接错误Retrying connect to server

http://blog.csdn.net/liuxinghao/article/details/40121945

  在Hadoop分布式模式部署完成后，通过start-dfs.sh启动NameNode、DataNode、SecondaryNameNode，在master节点通过jps命令查看，看到NameNode、SecondaryNameNode已启动，在slave节点通过jps命令查看，DataNode也已经启动。（此时颇为欣喜，首次完全分布式部署即成功，但是。。。）

1 发现问题

  准备好WordCount测试用例所需文件，通过hadoop fs -put file /命令上传文件，发现居然报错，这可是在单节点伪分布模式中操作无数次的命令啊>_<

[plain] view plain copy

1. 14/10/13 14:40:25 WARN hdfs.DFSClient: DataStreamer Exception  
2. org.apache.hadoop.ipc.RemoteException(java.io.IOException): File /input/test._COPYING_ could only be replicated to 0 nodes instead of minReplication (=1).  There are 0 datanode(s) running and no node(s) are excluded in this operation.  
3.     at org.apache.hadoop.hdfs.server.blockmanagement.BlockManager.chooseTarget(BlockManager.java:1441)  
4.     at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.getAdditionalBlock(FSNamesystem.java:2702)  
5.     at org.apache.hadoop.hdfs.server.namenode.NameNodeRpcServer.addBlock(NameNodeRpcServer.java:584)  
6.     at org.apache.hadoop.hdfs.protocolPB.ClientNamenodeProtocolServerSideTranslatorPB.addBlock(ClientNamenodeProtocolServerSideTranslatorPB.java:440)  
7.     at org.apache.hadoop.hdfs.protocol.proto.ClientNamenodeProtocolProtos$ClientNamenodeProtocol$2.callBlockingMethod(ClientNamenodeProtocolProtos.java)  
8.     at org.apache.hadoop.ipc.ProtobufRpcEngine$Server$ProtoBufRpcInvoker.call(ProtobufRpcEngine.java:585)  
9.     at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:928)  
10.     at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2013)  
11.     at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2009)  
12.     at java.security.AccessController.doPrivileged(Native Method)  
13.     at javax.security.auth.Subject.doAs(Subject.java:396)  
14.     at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1556)  
15.     at org.apache.hadoop.ipc.Server$Handler.run(Server.java:2007)  
16.   
17.     at org.apache.hadoop.ipc.Client.call(Client.java:1410)  
18.     at org.apache.hadoop.ipc.Client.call(Client.java:1363)  
19.     at org.apache.hadoop.ipc.ProtobufRpcEngine$Invoker.invoke(ProtobufRpcEngine.java:206)  
20.     at com.sun.proxy.$Proxy14.addBlock(Unknown Source)  
21.     at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)  
22.     at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)  
23.     at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)  
24.     at java.lang.reflect.Method.invoke(Method.java:597)  
25.     at org.apache.hadoop.io.retry.RetryInvocationHandler.invokeMethod(RetryInvocationHandler.java:190)  
26.     at org.apache.hadoop.io.retry.RetryInvocationHandler.invoke(RetryInvocationHandler.java:103)  
27.     at com.sun.proxy.$Proxy14.addBlock(Unknown Source)  
28.     at org.apache.hadoop.hdfs.protocolPB.ClientNamenodeProtocolTranslatorPB.addBlock(ClientNamenodeProtocolTranslatorPB.java:361)  
29.     at org.apache.hadoop.hdfs.DFSOutputStream$DataStreamer.locateFollowingBlock(DFSOutputStream.java:1439)  
30.     at org.apache.hadoop.hdfs.DFSOutputStream$DataStreamer.nextBlockOutputStream(DFSOutputStream.java:1261)  
31.     at org.apache.hadoop.hdfs.DFSOutputStream$DataStreamer.run(DFSOutputStream.java:525)  
32. put: File /input/test._COPYING_ could only be replicated to 0 nodes instead of minReplication (=1).  There are 0 datanode(s) running and no node(s) are excluded in this operation.  

  仔细看看错误，could only be replicated to 0 nodes，居然是0个节点。

  通过访问http://master:50070通过web ui查看节点状态，发现Live Nodes为0，Dead Nodes也为0，说明slave节点的DataNode节点虽然启动正常，但是与master通信失败，查看slave上的datanode的日志，发现出现信息发送失败的日志：

[plain] view plain copy

1. 2014-10-13 14:04:46,379 INFO org.apache.hadoop.ipc.Server: Starting Socket Reader #1 for port 50020  
2. 2014-10-13 14:04:46,496 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Opened IPC server at /0.0.0.0:50020  
3. 2014-10-13 14:04:46,531 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Refresh request received for nameservices: null  
4. 2014-10-13 14:04:46,856 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Starting BPOfferServices for nameservices: <default>  
5. 2014-10-13 14:04:46,905 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Block pool <registering> (Datanode Uuid unassigned) service to master/192.168.1.132:9000 starting to offer service  
6. 2014-10-13 14:04:46,970 INFO org.apache.hadoop.ipc.Server: IPC Server listener on 50020: starting  
7. 2014-10-13 14:04:46,967 INFO org.apache.hadoop.ipc.Server: IPC Server Responder: starting  
8. 2014-10-13 14:04:51,373 INFO org.apache.hadoop.ipc.Client: Retrying connect to server: master/192.168.1.132:9000. Already tried 0 time(s); retry policy is RetryUpToMaximumCountWithFixedSleep(maxRetries=10, sleepTime=1000 MILLISECONDS)  
9. 2014-10-13 14:04:52,375 INFO org.apache.hadoop.ipc.Client: Retrying connect to server: master/192.168.1.132:9000. Already tried 1 time(s); retry policy is RetryUpToMaximumCountWithFixedSleep(maxRetries=10, sleepTime=1000 MILLISECONDS)  
10. 2014-10-13 14:04:53,376 INFO org.apache.hadoop.ipc.Client: Retrying connect to server: master/192.168.1.132:9000. Already tried 2 time(s); retry policy is RetryUpToMaximumCountWithFixedSleep(maxRetries=10, sleepTime=1000 MILLISECONDS)  
11. 。。。  
12. 2014-10-13 14:05:00,394 INFO org.apache.hadoop.ipc.Client: Retrying connect to server: master/192.168.1.132:9000. Already tried 9 time(s); retry policy is RetryUpToMaximumCountWithFixedSleep(maxRetries=10, sleepTime=1000 MILLISECONDS)  
13. 2014-10-13 14:05:00,396 WARN org.apache.hadoop.hdfs.server.datanode.DataNode: Problem connecting to server: master/192.168.1.132:9000  

2 分析问题

  通过日志可以看出，slave节点的DataNode启动成功之后尝试向master传输心跳信息，每轮尝试10次，全部失败，然后继续向master传输信息。

  再次检查各种配置：/etc/hosts文件、slaves文件、ssh无密码登录、.bashrc中的环境变量、core-site.xml、hdfs-site.xml、mapred-site.xml、yarn-site.xml，检查结果为正常，所有配置无误。

  再分析，因为master向slave节点发送启动请求成功，slave启动DataNode，但是slave节点向master返回心跳失败。通过ping命令验证一番，master与slave互相能够平通，说明两个节点间通信正常。

  此时只剩下一种可能：防火墙。福尔摩斯说过，把所有不可能的情况剔除后，剩下的就是答案。

3 解决问题

  使用root用户查看master节点的防火墙是否启动：/etc/init.d/iptables status

[plain] view plain copy

1. Table: filter  
2. Chain INPUT (policy ACCEPT)  
3. num  target     prot opt source               destination           
4. 1    ACCEPT     all  --  0.0.0.0/0            0.0.0.0/0           state RELATED,ESTABLISHED   
5. 2    ACCEPT     icmp --  0.0.0.0/0            0.0.0.0/0             
6. 3    ACCEPT     all  --  0.0.0.0/0            0.0.0.0/0             
7. 4    ACCEPT     tcp  --  0.0.0.0/0            0.0.0.0/0           state NEW tcp dpt:22   
8. 5    REJECT     all  --  0.0.0.0/0            0.0.0.0/0           reject-with icmp-host-prohibited   
9.   
10. Chain FORWARD (policy ACCEPT)  
11. num  target     prot opt source               destination           
12. 1    REJECT     all  --  0.0.0.0/0            0.0.0.0/0           reject-with icmp-host-prohibited   
13.   
14. Chain OUTPUT (policy ACCEPT)  
15. num  target     prot opt source               destination           

  通过/etc/init.d/iptables stop命令直接关闭防火墙，在查看slave的DataNode日志：

[plain] view plain copy

1. 2014-10-13 14:56:23,646 INFO org.apache.hadoop.hdfs.server.common.Storage: Data-node version: -55 and name-node layout version: -56  
2. 2014-10-13 14:56:23,662 INFO org.apache.hadoop.hdfs.server.common.Storage: Lock on /home/lxh/hadoop/hdfs/data/in_use.lock acquired by nodename 2737@slave2  
3. 2014-10-13 14:56:23,790 INFO org.apache.hadoop.hdfs.server.common.Storage: Analyzing storage directories for bpid BP-480719120-192.168.1.132-1413164135404  
4. 2014-10-13 14:56:23,791 INFO org.apache.hadoop.hdfs.server.common.Storage: Locking is disabled  
5. 2014-10-13 14:56:23,791 INFO org.apache.hadoop.hdfs.server.common.Storage: Restored 0 block files from trash.  
6. 2014-10-13 14:56:23,793 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Setting up storage: nsid=161264755;bpid=BP-480719120-192.168.1.132-1413164135404;lv=-55;nsInfo=lv=-56;cid=CID-84fef657-142a-46c4-8329-3df7025286a0;nsid=161264755;c=0;bpid=BP-480719120-192.168.1.132-1413164135404;dnuuid=62322351-4f82-42eb-baa4-f3b38675234e  
7. 2014-10-13 14:56:23,815 INFO org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.FsDatasetImpl: Added volume - /home/lxh/hadoop/hdfs/data/current, StorageType: DISK  
8. 2014-10-13 14:56:23,951 INFO org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.FsDatasetImpl: Registered FSDatasetState MBean  
9. 2014-10-13 14:56:23,979 INFO org.apache.hadoop.hdfs.server.datanode.DirectoryScanner: Periodic Directory Tree Verification scan starting at 1413202418979 with interval 21600000  
10. 2014-10-13 14:56:23,984 INFO org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.FsDatasetImpl: Adding block pool BP-480719120-192.168.1.132-1413164135404  
11. 2014-10-13 14:56:23,986 INFO org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.FsDatasetImpl: Scanning block pool BP-480719120-192.168.1.132-1413164135404 on volume /home/lxh/hadoop/hdfs/data/current...  
12. 2014-10-13 14:56:24,047 INFO org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.FsDatasetImpl: Time taken to scan block pool BP-480719120-192.168.1.132-1413164135404 on /home/lxh/hadoop/hdfs/data/current: 59ms  
13. 2014-10-13 14:56:24,047 INFO org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.FsDatasetImpl: Total time to scan all replicas for block pool BP-480719120-192.168.1.132-1413164135404: 62ms  
14. 2014-10-13 14:56:24,049 INFO org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.FsDatasetImpl: Adding replicas to map for block pool BP-480719120-192.168.1.132-1413164135404 on volume /home/lxh/hadoop/hdfs/data/current...  
15. 2014-10-13 14:56:24,050 INFO org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.FsDatasetImpl: Time to add replicas to map for block pool BP-480719120-192.168.1.132-1413164135404 on volume /home/lxh/hadoop/hdfs/data/current: 0ms  
16. 2014-10-13 14:56:24,050 INFO org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.FsDatasetImpl: Total time to add all replicas to map: 3ms  
17. 2014-10-13 14:56:24,052 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Block pool BP-480719120-192.168.1.132-1413164135404 (Datanode Uuid null) service to master/192.168.1.132:9000 beginning handshake with NN  
18. 2014-10-13 14:56:24,109 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Block pool Block pool BP-480719120-192.168.1.132-1413164135404 (Datanode Uuid null) service to master/192.168.1.132:9000 successfully registered with NN  
19. 2014-10-13 14:56:24,109 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: For namenode master/192.168.1.132:9000 using DELETEREPORT_INTERVAL of 300000 msec  BLOCKREPORT_INTERVAL of 21600000msec CACHEREPORT_INTERVAL of 10000msec Initial delay: 0msec; heartBeatInterval=3000  
20. 2014-10-13 14:56:24,249 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Namenode Block pool BP-480719120-192.168.1.132-1413164135404 (Datanode Uuid 62322351-4f82-42eb-baa4-f3b38675234e) service to master/192.168.1.132:9000 trying to claim ACTIVE state with txid=430  
21. 2014-10-13 14:56:24,249 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Acknowledging ACTIVE Namenode Block pool BP-480719120-192.168.1.132-1413164135404 (Datanode Uuid 62322351-4f82-42eb-baa4-f3b38675234e) service to master/192.168.1.132:9000  
22. 2014-10-13 14:56:24,350 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Sent 1 blockreports 0 blocks total. Took 1 msec to generate and 100 msecs for RPC and NN processing.  Got back commands org.apache.hadoop.hdfs.server.protocol.FinalizeCommand@563b100c  
23. 2014-10-13 14:56:24,354 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Got finalize command for block pool BP-480719120-192.168.1.132-1413164135404  
24. 2014-10-13 14:56:24,369 INFO org.apache.hadoop.util.GSet: Computing capacity for map BlockMap  
25. 2014-10-13 14:56:24,370 INFO org.apache.hadoop.util.GSet: VM type       = 64-bit  
26. 2014-10-13 14:56:24,373 INFO org.apache.hadoop.util.GSet: 0.5% max memory 966.7 MB = 4.8 MB  
27. 2014-10-13 14:56:24,375 INFO org.apache.hadoop.util.GSet: capacity      = 2^19 = 524288 entries  
28. 2014-10-13 14:56:24,376 INFO org.apache.hadoop.hdfs.server.datanode.BlockPoolSliceScanner: Periodic Block Verification Scanner initialized with interval 504 hours for block pool BP-480719120-192.168.1.132-1413164135404  
29. 2014-10-13 14:56:24,389 INFO org.apache.hadoop.hdfs.server.datanode.DataBlockScanner: Added bpid=BP-480719120-192.168.1.132-1413164135404 to blockPoolScannerMap, new size=1  

问题解决。

  为了以防万一，再次把master的防火墙打开/etc/init.d/iptables start，再查看slave的DataNode日志：

[plain] view plain copy

1. 2014-10-13 14:57:45,119 WARN org.apache.hadoop.hdfs.server.datanode.DataNode: IOException in offerService  
2. java.net.SocketTimeoutException: Call From slave2/192.168.1.133 to master:9000 failed on socket timeout exception: java.net.SocketTimeoutException: 60000 millis timeout while waiting for channel to be ready for read. ch : java.nio.channels.SocketChannel[connected local=/192.168.1.133:39010 remote=master/192.168.1.132:9000]; For more details see:  http://wiki.apache.org/hadoop/SocketTimeout  
3.     at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)  
4.     at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)  
5.     at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)  
6.     at java.lang.reflect.Constructor.newInstance(Constructor.java:513)  
7.     at org.apache.hadoop.net.NetUtils.wrapWithMessage(NetUtils.java:783)  
8.     at org.apache.hadoop.net.NetUtils.wrapException(NetUtils.java:749)  
9.     at org.apache.hadoop.ipc.Client.call(Client.java:1414)  
10.     at org.apache.hadoop.ipc.Client.call(Client.java:1363)  
11.     at org.apache.hadoop.ipc.ProtobufRpcEngine$Invoker.invoke(ProtobufRpcEngine.java:206)  
12.     at com.sun.proxy.$Proxy14.sendHeartbeat(Unknown Source)  
13.     at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)  
14.     at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)  
15.     at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)  
16.     at java.lang.reflect.Method.invoke(Method.java:597)  
17.     at org.apache.hadoop.io.retry.RetryInvocationHandler.invokeMethod(RetryInvocationHandler.java:190)  
18.     at org.apache.hadoop.io.retry.RetryInvocationHandler.invoke(RetryInvocationHandler.java:103)  
19.     at com.sun.proxy.$Proxy14.sendHeartbeat(Unknown Source)  
20.     at org.apache.hadoop.hdfs.protocolPB.DatanodeProtocolClientSideTranslatorPB.sendHeartbeat(DatanodeProtocolClientSideTranslatorPB.java:178)  
21.     at org.apache.hadoop.hdfs.server.datanode.BPServiceActor.sendHeartBeat(BPServiceActor.java:570)  
22.     at org.apache.hadoop.hdfs.server.datanode.BPServiceActor.offerService(BPServiceActor.java:668)  
23.     at org.apache.hadoop.hdfs.server.datanode.BPServiceActor.run(BPServiceActor.java:838)  
24.     at java.lang.Thread.run(Thread.java:662)  
25. Caused by: java.net.SocketTimeoutException: 60000 millis timeout while waiting for channel to be ready for read. ch : java.nio.channels.SocketChannel[connected local=/192.168.1.133:39010 remote=master/192.168.1.132:9000]  
26.     at org.apache.hadoop.net.SocketIOWithTimeout.doIO(SocketIOWithTimeout.java:164)  
27.     at org.apache.hadoop.net.SocketInputStream.read(SocketInputStream.java:161)  
28.     at org.apache.hadoop.net.SocketInputStream.read(SocketInputStream.java:131)  
29.     at java.io.FilterInputStream.read(FilterInputStream.java:116)  
30.     at java.io.FilterInputStream.read(FilterInputStream.java:116)  
31.     at org.apache.hadoop.ipc.Client$Connection$PingInputStream.read(Client.java:510)  
32.     at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)  
33.     at java.io.BufferedInputStream.read(BufferedInputStream.java:237)  
34.     at java.io.DataInputStream.readInt(DataInputStream.java:370)  
35.     at org.apache.hadoop.ipc.Client$Connection.receiveRpcResponse(Client.java:1054)  
36.     at org.apache.hadoop.ipc.Client$Connection.run(Client.java:949)  
37. 2014-10-13 14:57:46,128 INFO org.apache.hadoop.ipc.Client: Retrying connect to server: master/192.168.1.132:9000. Already tried 0 time(s); retry policy is RetryUpToMaximumCountWithFixedSleep(maxRetries=10, sleepTime=1000 MILLISECONDS)  
38. 2014-10-13 14:57:47,129 INFO org.apache.hadoop.ipc.Client: Retrying connect to server: master/192.168.1.132:9000. Already tried 1 time(s); retry policy is RetryUpToMaximumCountWithFixedSleep(maxRetries=10, sleepTime=1000 MILLISECONDS)  

果然，引起错误的原因是master的防火墙。

4 总结问题

  因为master与slave之间通信正常，互相可以ping通，所以master的命令可以向slave下发，slave接收到启动命令，开始启动DataNode，并在启动成功后，向master节点发送心跳信息。在正常情况下，master接收到心跳信息，记录该节点的DataNode为正常，可以讲hdfs上的数据复制到该节点，并能够在该节点进行运算。

  但由于防火墙拦截，slave的心跳信息不能够传递给master，所以master认为该节点不存在，所以不会记录在Live Nodes和Dead Nodes中，对master来说，该节点就变成了消失的幽灵节点。

  在解决过程中，出于安全方面的考虑，应该开放master的9000端口，而不是关闭防火墙。因为我是在虚拟机中进行的测试环境，所以直接关闭，而且还通过chkconfig iptables off命令，使防火墙开机不启动了。