한동안 회사 업무 및 앱 개발에 신경을 쓰느라 Hadoop 학습을 좀 등한시 했었다.
그래도 오며 가며 출퇴근 길에 새롭게 HBase (HBase 완벽 가이드) 서적을 읽기 시작했고.
책을 다 읽지는 않았지만 우선 HBase나 설치를 좀 해보자 하고 한동안 잠자고 있던 Hadoop을 깨웠다.
그런데...
이게 웬일인가...
start-all.sh를 통해 dfs와 mapred를 모두 실행을 시켰는데
namenode쪽에서는 모든 서비스가 다 기동이 되었는데 datanode쪽에서는 tasktracker만 올라오고
datanode가 안올라오는 것이다. 이거야말로
고, 고갱님. 다, 당황하셨어요~
아~물론 당황하고 말고...
가장 마지막에 실행시켰을 때만해도 이상없이 잘 작동하던 놈이었으니...
일단 데이터노드가 올라오지 않으니 데이터노드쪽 로그부터 살폈다.
대략 다음과 같은 로그가 찍혀있었다.
2013-10-15 12:56:22,538 INFO org.apache.hadoop.ipc.Client: Retrying connect to server: NAMENODE.local/192.168.10.15:9000. Already tried 0 time(s).
2013-10-15 12:56:23,541 INFO org.apache.hadoop.ipc.Client: Retrying connect to server: NAMENODE.local/192.168.10.15:9000. Already tried 1 time(s).
2013-10-15 12:56:24,544 INFO org.apache.hadoop.ipc.Client: Retrying connect to server: NAMENODE.local/192.168.10.15:9000. Already tried 2 time(s).
2013-10-15 12:56:25,546 INFO org.apache.hadoop.ipc.Client: Retrying connect to server: NAMENODE.local/192.168.10.15:9000. Already tried 3 time(s).
2013-10-15 12:56:26,549 INFO org.apache.hadoop.ipc.Client: Retrying connect to server: NAMENODE.local/192.168.10.15:9000. Already tried 4 time(s).
2013-10-15 12:56:27,552 INFO org.apache.hadoop.ipc.Client: Retrying connect to server: NAMENODE.local/192.168.10.15:9000. Already tried 5 time(s).
2013-10-15 12:56:28,555 INFO org.apache.hadoop.ipc.Client: Retrying connect to server: NAMENODE.local/192.168.10.15:9000. Already tried 6 time(s).
2013-10-15 12:56:29,558 INFO org.apache.hadoop.ipc.Client: Retrying connect to server: NAMENODE.local/192.168.10.15:9000. Already tried 7 time(s).
2013-10-15 12:56:30,561 INFO org.apache.hadoop.ipc.Client: Retrying connect to server: NAMENODE.local/192.168.10.15:9000. Already tried 8 time(s).
2013-10-15 12:56:31,564 INFO org.apache.hadoop.ipc.Client: Retrying connect to server: NAMENODE.local/192.168.10.15:9000. Already tried 9 time(s).
2013-10-15 12:56:31,566 WARN org.apache.hadoop.hdfs.server.datanode.DataNode: java.net.ConnectException: Call to NAMENODE.local/192.168.10.15:9000 failed on connection exception: java.net.ConnectException: Connection refused
at org.apache.hadoop.ipc.Client.wrapException(Client.java:1099)
at org.apache.hadoop.ipc.Client.call(Client.java:1075)
at org.apache.hadoop.ipc.RPC$Invoker.invoke(RPC.java:225)
at com.sun.proxy.$Proxy5.sendHeartbeat(Unknown Source)
at org.apache.hadoop.hdfs.server.datanode.DataNode.offerService(DataNode.java:904)
at org.apache.hadoop.hdfs.server.datanode.DataNode.run(DataNode.java:1458)
at java.lang.Thread.run(Thread.java:724)
Caused by: java.net.ConnectException: Connection refused
at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:708)
at org.apache.hadoop.net.SocketIOWithTimeout.connect(SocketIOWithTimeout.java:206)
at org.apache.hadoop.net.NetUtils.connect(NetUtils.java:489)
at org.apache.hadoop.ipc.Client$Connection.setupConnection(Client.java:434)
at org.apache.hadoop.ipc.Client$Connection.setupIOstreams(Client.java:560)
at org.apache.hadoop.ipc.Client$Connection.access$2000(Client.java:184)
at org.apache.hadoop.ipc.Client.getConnection(Client.java:1206)
at org.apache.hadoop.ipc.Client.call(Client.java:1050)
... 5 more
얼핏 보니 네트워크상에 9000포트가 안열렸나 싶다...
얼른 공유기를 살폈더니 9000포트가 이상없이 설정되어있었다.
한동안 이 데이터노드 로그만 가지고 씨름을 하였다.
더 헷갈리게 다음과 같은 오류도 있었다.
2013-10-15 12:56:18,533 WARN org.apache.hadoop.hdfs.server.datanode.DataNode: java.io.IOException: Call to NAMENODE.local/192.168.10.15:9000 failed on local exception: java.io.EOFException
at org.apache.hadoop.ipc.Client.wrapException(Client.java:1107)
at org.apache.hadoop.ipc.Client.call(Client.java:1075)
at org.apache.hadoop.ipc.RPC$Invoker.invoke(RPC.java:225)
at com.sun.proxy.$Proxy5.sendHeartbeat(Unknown Source)
at org.apache.hadoop.hdfs.server.datanode.DataNode.offerService(DataNode.java:904)
at org.apache.hadoop.hdfs.server.datanode.DataNode.run(DataNode.java:1458)
at java.lang.Thread.run(Thread.java:724)
Caused by: java.io.EOFException
at java.io.DataInputStream.readInt(DataInputStream.java:392)
at org.apache.hadoop.ipc.Client$Connection.receiveResponse(Client.java:804)
at org.apache.hadoop.ipc.Client$Connection.run(Client.java:749)
자세히 보면 역시 네트워크상의 스트림을 읽다가 오류가 난것이니 모두 네트워크 문제인 것 같은데...
미련하게 데이터노드만 쳐다보다가 한참만에 '네임노드에서 커넥션 리퓨즈가 났으니 네임노드도 봐야겠구나!' 하는 생각이
들었다...-.-
어쨌든 네임노드의 로그를 살피니 다음과 같은 로그가 찍혀있다.
2013-10-15 12:42:54,406 ERROR org.apache.hadoop.security.UserGroupInformation: PriviledgedActionException as:mazdah cause:org.apache.hadoop.hdfs.server.namenode.SafeModeException: Cannot delete /hadoop-data/mapred/system. Name node is in safe mode.
The ratio of reported blocks 1.0000 has reached the threshold 0.9990. Safe mode will be turned off automatically in 26 seconds.
2013-10-15 12:42:54,408 INFO org.apache.hadoop.ipc.Server: IPC Server handler 3 on 9000, call delete(/hadoop-data/mapred/system, true) from 192.168.10.15:50942: error: org.apache.hadoop.hdfs.server.namenode.SafeModeException: Cannot delete /hadoop-data/mapred/system. Name node is in safe mode.
The ratio of reported blocks 1.0000 has reached the threshold 0.9990. Safe mode will be turned off automatically in 26 seconds.
org.apache.hadoop.hdfs.server.namenode.SafeModeException: Cannot delete /hadoop-data/mapred/system. Name node is in safe mode.
The ratio of reported blocks 1.0000 has reached the threshold 0.9990. Safe mode will be turned off automatically in 26 seconds.
at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.deleteInternal(FSNamesystem.java:1994)
at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.delete(FSNamesystem.java:1974)
at org.apache.hadoop.hdfs.server.namenode.NameNode.delete(NameNode.java:792)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:563)
at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:1388)
at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:1384)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.Subject.doAs(Subject.java:415)
at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1121)
at org.apache.hadoop.ipc.Server$Handler.run(Server.java:1382)
일단 SafeModeException이란다. 구글링을 했다.
네임노드가 처음 시작할 때 혹은 Hadoop이 비정상 종료된 후 실행시키면 Safe mode에서 돌아간단다.
여기서 빠져나오려면 다음과 같이 해야 한단다.
mazdah$ hadoop dfsadmin -safemode leave
그런데 암만 이 명령을 실행해도 동일한 오류가 계속 발생을 한다.
이 시점에서 '네임노드를 다시 포맷을 하고 재실행 해보자' 하는 생각이 들었다.
그리고 어처구니없고 매우 당황스러운 상황을 겪게된다.
mazdah$ ./hadoop namenode -format
11/08/22 18:08:58 INFO namenode.NameNode: STARTUP_MSG:
/************************************************************
STARTUP_MSG: Starting NameNode
STARTUP_MSG: host = nhn-PC/10.64.49.213
STARTUP_MSG: args = [-format]
STARTUP_MSG: version = 0.20.203.0
STARTUP_MSG: build = http://svn.apache.org/repos/asf/hadoop/common/branches/br
anch-0.20-security-203 -r 1099333; compiled by 'oom' on Wed May 4 07:57:50 PDT
2011
************************************************************/
Re-format filesystem in \tmp\hadoop-nhn\dfs\name ? (Y or N)
hadoop namenode -format을 입력하고 엔터를 치면 위 내용이 나온다.
그리고 이미 이전에 파일 시스템이 구축되어 포맷을 한 적이 있기에 마지막줄처럼 다시 포맷할 것인가 묻는 내용이
나오는데...
아무리 y를 쳐도 계속 format aborted가 나오면서 포맷이 안되는 것이다...ㅠㅠ
나중에 안 사실이지만 이놈이 대소문자를 가리는 놈이었다...ㅠㅠ
즉, Y를 쳤어야 하는 것이다.
어쨌든 결국 포맷에 성공을 하고 데이터노드의 hadoop-data/node01, node02, node03 모두 삭제해주고
다시 한 번 차근차근 해보기로했다.
- 우선 start-all.sh로 모두 실행을 시켜주고
- hadoop dfsadmin -safemode leave로 safe mode에서 나오고(사실 이부분은 이 시점에서는 필요 없는 부분이었다)
- 데이터노드에서 jps로 프로세스를 확인 - 여전히 datanode는 안올라왔다.
- 데이터노드에서 hadoop datanode를 수행하여 개별적으로 데이터노드를 시작시킨다.
여기서 다시 한 번 오류로그를 확인할 수 있었다.
이번엔 비교적 명확한 오류...
데이터 저장소인 hadoop-data/node01(이 경로는 사용자마다 다르다)의 권한이 755(rwxr-xr-x)여야 하는데
777(rwxrwxrwx)로 되어있었던 것이다.
이렇게 해서 최종적으로 디렉토리의 권한을 수정한 후 다시 네임노드에서 재시작을 했더니 드디어 프로세스들이 모두
정상적으로 올라왔다.
연이어 start-hbase.sh를 통해 HBase를 시작하니 역시 정상적으로 프로세스가 시작되었다.
아무래도 나같은 일반 개발자들은 분산 환경을 경험하기가 쉽지 않아 실제 분산환경에서 발생하는 오류를 만나게 되니
문제의 시작점이 어디이고 또 어떤 문제가 원인이고 어떤 문제가 파생된 것인지를 찾기가 쉽지가 않다.
문제를 처음 만났을 때도 그저 프로세스가 올라오지 않은 데이터노드에서만 문제를 확인하려고만 했지 네임노드에 대한
생각은 까맣게 잊고 있었다.
사실 이 문제도 그저 단순하게
네임노드에서 start-all.sh로 시작하고
hadoop dfsadmin -safemode leave로 세이프모드 나간다음
데이터노드에서 hadoop datanode를 실행해보기만 했어도 쉽게 해결할 수있었을지 모른다.
앞으로는 당황하지 말고 차근차근 노드간의 관계를 염두에 두면서 해결책을 찾아봐야겠다.