??在Hadoop分布式模式部署完畢后，通過 start-dfs.sh 啟動 NameNode 、 DataNode 、 SecondaryNameNode ，在 master 節點通過 jps 命令查看，看到 NameNode 、 SecondaryNameNode 已啟動，在 slave 節點通過 jps 命令查看， DataNode 也已經啟動。（此時頗為欣喜，首次全然分布式部署即成功，可是。。。）

1 發現問題

??準備好 WordCount 測試用例所需文件，通過 hadoop fs -put file / 命令上傳文件，發現竟然報錯，這但是在單節點偽分布模式中操作無數次的命令啊>_<

      14/10/13 14:40:25 WARN hdfs.DFSClient: DataStreamer Exception
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.
    at org.apache.hadoop.hdfs.server.blockmanagement.BlockManager.chooseTarget(BlockManager.java:1441)
    at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.getAdditionalBlock(FSNamesystem.java:2702)
    at org.apache.hadoop.hdfs.server.namenode.NameNodeRpcServer.addBlock(NameNodeRpcServer.java:584)
    at org.apache.hadoop.hdfs.protocolPB.ClientNamenodeProtocolServerSideTranslatorPB.addBlock(ClientNamenodeProtocolServerSideTranslatorPB.java:440)
    at org.apache.hadoop.hdfs.protocol.proto.ClientNamenodeProtocolProtos$ClientNamenodeProtocol$2.callBlockingMethod(ClientNamenodeProtocolProtos.java)
    at org.apache.hadoop.ipc.ProtobufRpcEngine$Server$ProtoBufRpcInvoker.call(ProtobufRpcEngine.java:585)
    at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:928)
    at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2013)
    at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2009)
    at java.security.AccessController.doPrivileged(Native Method)
    at javax.security.auth.Subject.doAs(Subject.java:396)
    at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1556)
    at org.apache.hadoop.ipc.Server$Handler.run(Server.java:2007)

    at org.apache.hadoop.ipc.Client.call(Client.java:1410)
    at org.apache.hadoop.ipc.Client.call(Client.java:1363)
    at org.apache.hadoop.ipc.ProtobufRpcEngine$Invoker.invoke(ProtobufRpcEngine.java:206)
    at com.sun.proxy.$Proxy14.addBlock(Unknown Source)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    at java.lang.reflect.Method.invoke(Method.java:597)
    at org.apache.hadoop.io.retry.RetryInvocationHandler.invokeMethod(RetryInvocationHandler.java:190)
    at org.apache.hadoop.io.retry.RetryInvocationHandler.invoke(RetryInvocationHandler.java:103)
    at com.sun.proxy.$Proxy14.addBlock(Unknown Source)
    at org.apache.hadoop.hdfs.protocolPB.ClientNamenodeProtocolTranslatorPB.addBlock(ClientNamenodeProtocolTranslatorPB.java:361)
    at org.apache.hadoop.hdfs.DFSOutputStream$DataStreamer.locateFollowingBlock(DFSOutputStream.java:1439)
    at org.apache.hadoop.hdfs.DFSOutputStream$DataStreamer.nextBlockOutputStream(DFSOutputStream.java:1261)
    at org.apache.hadoop.hdfs.DFSOutputStream$DataStreamer.run(DFSOutputStream.java:525)
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 的日志，發現出現信息發送失敗的日志：

      2014-10-13 14:04:46,379 INFO org.apache.hadoop.ipc.Server: Starting Socket Reader #1 for port 50020
2014-10-13 14:04:46,496 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Opened IPC server at /0.0.0.0:50020
2014-10-13 14:04:46,531 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Refresh request received for nameservices: null
2014-10-13 14:04:46,856 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Starting BPOfferServices for nameservices: <default>
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
2014-10-13 14:04:46,970 INFO org.apache.hadoop.ipc.Server: IPC Server listener on 50020: starting
2014-10-13 14:04:46,967 INFO org.apache.hadoop.ipc.Server: IPC Server Responder: starting
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)
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)
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)
。。。
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)
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無password登錄、.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

      Table: filter
Chain INPUT (policy ACCEPT)
num  target     prot opt source               destination         
1    ACCEPT     all  --  0.0.0.0/0            0.0.0.0/0           state RELATED,ESTABLISHED 
2    ACCEPT     icmp --  0.0.0.0/0            0.0.0.0/0           
3    ACCEPT     all  --  0.0.0.0/0            0.0.0.0/0           
4    ACCEPT     tcp  --  0.0.0.0/0            0.0.0.0/0           state NEW tcp dpt:22 
5    REJECT     all  --  0.0.0.0/0            0.0.0.0/0           reject-with icmp-host-prohibited 

Chain FORWARD (policy ACCEPT)
num  target     prot opt source               destination         
1    REJECT     all  --  0.0.0.0/0            0.0.0.0/0           reject-with icmp-host-prohibited 

Chain OUTPUT (policy ACCEPT)
num  target     prot opt source               destination         

    

??通過 /etc/init.d/iptables stop 命令直接關閉防火墻，在查看 slave 的 DataNode 日志：

      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
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
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
2014-10-13 14:56:23,791 INFO org.apache.hadoop.hdfs.server.common.Storage: Locking is disabled
2014-10-13 14:56:23,791 INFO org.apache.hadoop.hdfs.server.common.Storage: Restored 0 block files from trash.
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
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
2014-10-13 14:56:23,951 INFO org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.FsDatasetImpl: Registered FSDatasetState MBean
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
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
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...
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
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
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...
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
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
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
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
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
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
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
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
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
2014-10-13 14:56:24,369 INFO org.apache.hadoop.util.GSet: Computing capacity for map BlockMap
2014-10-13 14:56:24,370 INFO org.apache.hadoop.util.GSet: VM type       = 64-bit
2014-10-13 14:56:24,373 INFO org.apache.hadoop.util.GSet: 0.5% max memory 966.7 MB = 4.8 MB
2014-10-13 14:56:24,375 INFO org.apache.hadoop.util.GSet: capacity      = 2^19 = 524288 entries
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
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 日志：

      2014-10-13 14:57:45,119 WARN org.apache.hadoop.hdfs.server.datanode.DataNode: IOException in offerService
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
    at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)
    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
    at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
    at org.apache.hadoop.net.NetUtils.wrapWithMessage(NetUtils.java:783)
    at org.apache.hadoop.net.NetUtils.wrapException(NetUtils.java:749)
    at org.apache.hadoop.ipc.Client.call(Client.java:1414)
    at org.apache.hadoop.ipc.Client.call(Client.java:1363)
    at org.apache.hadoop.ipc.ProtobufRpcEngine$Invoker.invoke(ProtobufRpcEngine.java:206)
    at com.sun.proxy.$Proxy14.sendHeartbeat(Unknown Source)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    at java.lang.reflect.Method.invoke(Method.java:597)
    at org.apache.hadoop.io.retry.RetryInvocationHandler.invokeMethod(RetryInvocationHandler.java:190)
    at org.apache.hadoop.io.retry.RetryInvocationHandler.invoke(RetryInvocationHandler.java:103)
    at com.sun.proxy.$Proxy14.sendHeartbeat(Unknown Source)
    at org.apache.hadoop.hdfs.protocolPB.DatanodeProtocolClientSideTranslatorPB.sendHeartbeat(DatanodeProtocolClientSideTranslatorPB.java:178)
    at org.apache.hadoop.hdfs.server.datanode.BPServiceActor.sendHeartBeat(BPServiceActor.java:570)
    at org.apache.hadoop.hdfs.server.datanode.BPServiceActor.offerService(BPServiceActor.java:668)
    at org.apache.hadoop.hdfs.server.datanode.BPServiceActor.run(BPServiceActor.java:838)
    at java.lang.Thread.run(Thread.java:662)
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]
    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 java.io.FilterInputStream.read(FilterInputStream.java:116)
    at java.io.FilterInputStream.read(FilterInputStream.java:116)
    at org.apache.hadoop.ipc.Client$Connection$PingInputStream.read(Client.java:510)
    at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
    at java.io.BufferedInputStream.read(BufferedInputStream.java:237)
    at java.io.DataInputStream.readInt(DataInputStream.java:370)
    at org.apache.hadoop.ipc.Client$Connection.receiveRpcResponse(Client.java:1054)
    at org.apache.hadoop.ipc.Client$Connection.run(Client.java:949)
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)
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 的9000port，而不是關閉防火墻。由于我是在虛擬機中進行的測試環境，所以直接關閉，并且還通過 chkconfig iptables off 命令，使防火墻開機不啟動了。