한동안 회사 업무 및 앱 개발에 신경을 쓰느라 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를 실행해보기만 했어도 쉽게 해결할 수있었을지 모른다.


앞으로는 당황하지 말고 차근차근 노드간의 관계를 염두에 두면서 해결책을 찾아봐야겠다.


저작자 표시
신고

+ Recent posts

티스토리 툴바