'Development/Hadoop and etc.'에 해당되는 글 1건

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


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


블로그 이미지

마즈다

이미 마흔을 넘어섰지만 아직도 꿈을 좇고 있습니다. 그래서 그 꿈에 다가가기 위한 단편들을 하나 둘 씩 모아가고 있지요. 이 곳에 그 단편들이 모일 겁니다...^^

티스토리 툴바