Hello
I am quite new to Hadoop. I am trying to run Hadoop on top of a HPC
infrastructure using a solution called “myHadoop”. Basically what it does is
trying to allocate some nodes from HPC dynamically and run Hadoop(Use one as
NameNode, others as DataNode ). If anybody familiar with it that would be
perfect, but I think my problem is mostly the Hadoop part.
I am using Hadoop 1.2.1 do to the limited support of myHadoop.
Here is the log:
===
myHadoop: Using HADOOP_HOME=/home/hpc-ruhua/hadoop-stack/hadoop-1.2.1
myHadoop: Using MH_SCRATCH_DIR=/tmp/hpc-ruhua/4128
myHadoop: Using JAVA_HOME=/usr
myHadoop: Generating Hadoop configuration in directory in
/home/hpc-ruhua/hadoop/conf/hadoop-conf.4128...
myHadoop: Using directory /home/hpc-ruhua/hadoop/hdfs for persisting HDFS
state...
myHadoop: Designating cn53 as master node (namenode, secondary namenode, and
jobtracker)
myHadoop: The following nodes will be slaves (datanode, tasktracer):
cn53
cn54
cn55
cn56
Linking /home/hpc-ruhua/hadoop/hdfs/0 to /tmp/hpc-ruhua/4128/hdfs_data on cn53
Linking /home/hpc-ruhua/hadoop/hdfs/1 to /tmp/hpc-ruhua/4128/hdfs_data on cn54
Linking /home/hpc-ruhua/hadoop/hdfs/2 to /tmp/hpc-ruhua/4128/hdfs_data on cn55
Warning: Permanently added 'cn55,192.168.100.55' (RSA) to the list of known
hosts.
Linking /home/hpc-ruhua/hadoop/hdfs/3 to /tmp/hpc-ruhua/4128/hdfs_data on cn56
Warning: Permanently added 'cn56,192.168.100.56' (RSA) to the list of known
hosts.
starting namenode, logging to
/tmp/hpc-ruhua/4128/logs/hadoop-hpc-ruhua-namenode-cn53.out
cn53: starting datanode, logging to
/tmp/hpc-ruhua/4128/logs/hadoop-hpc-ruhua-datanode-cn53.out
cn54: starting datanode, logging to
/tmp/hpc-ruhua/4128/logs/hadoop-hpc-ruhua-datanode-cn54.out
cn55: starting datanode, logging to
/tmp/hpc-ruhua/4128/logs/hadoop-hpc-ruhua-datanode-cn55.out
cn56: starting datanode, logging to
/tmp/hpc-ruhua/4128/logs/hadoop-hpc-ruhua-datanode-cn56.out
cn53: starting secondarynamenode, logging to
/tmp/hpc-ruhua/4128/logs/hadoop-hpc-ruhua-secondarynamenode-cn53.out
starting jobtracker, logging to
/tmp/hpc-ruhua/4128/logs/hadoop-hpc-ruhua-jobtracker-cn53.out
cn53: starting tasktracker, logging to
/tmp/hpc-ruhua/4128/logs/hadoop-hpc-ruhua-tasktracker-cn53.out
cn56: starting tasktracker, logging to
/tmp/hpc-ruhua/4128/logs/hadoop-hpc-ruhua-tasktracker-cn56.out
cn55: starting tasktracker, logging to
/tmp/hpc-ruhua/4128/logs/hadoop-hpc-ruhua-tasktracker-cn55.out
cn54: starting tasktracker, logging to
/tmp/hpc-ruhua/4128/logs/hadoop-hpc-ruhua-tasktracker-cn54.out
mkdir: cannot create directory data: File exists
put: Target data/pg2701.txt already exists
Found 1 items
-rw-r--r-- 3 hpc-ruhua supergroup 0 2015-01-07 00:09
/user/hpc-ruhua/data/pg2701.txt
15/01/14 12:21:08 ERROR security.UserGroupInformation:
PriviledgedActionException as:hpc-ruhua
cause:org.apache.hadoop.ipc.RemoteException:
org.apache.hadoop.mapred.JobTrackerNotYetInitializedException: JobTracker is
not yet RUNNING
at
org.apache.hadoop.mapred.JobTracker.checkJobTrackerState(JobTracker.java:5199)
at org.apache.hadoop.mapred.JobTracker.getNewJobId(JobTracker.java:3543)
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:587)
at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:1432)
at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:1428)
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:1190)
at org.apache.hadoop.ipc.Server$Handler.run(Server.java:1426)
org.apache.hadoop.ipc.RemoteException:
org.apache.hadoop.mapred.JobTrackerNotYetInitializedException: JobTracker is
not yet RUNNING
at
org.apache.hadoop.mapred.JobTracker.checkJobTrackerState(JobTracker.java:5199)
at org.apache.hadoop.mapred.JobTracker.getNewJobId(JobTracker.java:3543)
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:587)
at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:1432)
at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:1428)
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:1190)
at org.apache.hadoop.ipc.Server$Handler.run(Server.java:1426)
at org.apache.hadoop.ipc.Client.call(Client.java:1113)
at org.apache.hadoop.ipc.RPC$Invoker.invoke(RPC.java:229)
at org.apache.hadoop.mapred.$Proxy2.getNewJobId(Unknown Source)
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.io.retry.RetryInvocationHandler.invokeMethod(RetryInvocationHandler.java:85)
at
org.apache.hadoop.io.retry.RetryInvocationHandler.invoke(RetryInvocationHandler.java:62)
at org.apache.hadoop.mapred.$Proxy2.getNewJobId(Unknown Source)
at org.apache.hadoop.mapred.JobClient$2.run(JobClient.java:944)
at org.apache.hadoop.mapred.JobClient$2.run(JobClient.java:936)
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:1190)
at
org.apache.hadoop.mapred.JobClient.submitJobInternal(JobClient.java:936)
at org.apache.hadoop.mapreduce.Job.submit(Job.java:550)
at org.apache.hadoop.mapreduce.Job.waitForCompletion(Job.java:580)
at org.apache.hadoop.examples.WordCount.main(WordCount.java:82)
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.util.ProgramDriver$ProgramDescription.invoke(ProgramDriver.java:68)
at org.apache.hadoop.util.ProgramDriver.driver(ProgramDriver.java:139)
at org.apache.hadoop.examples.ExampleDriver.main(ExampleDriver.java:64)
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.util.RunJar.main(RunJar.java:160)
ls: Cannot access wordcount-output: No such file or directory.
get: null
stopping jobtracker
cn54: stopping tasktracker
cn55: stopping tasktracker
cn53: stopping tasktracker
cn56: stopping tasktracker
stopping namenode
cn53: no datanode to stop
cn54: no datanode to stop
cn56: no datanode to stop
cn55: no datanode to stop
===
The erro is “ERROR security.UserGroupInformation: PriviledgedActionException
as:hpc-ruhua cause:org.apache.hadoop.ipc.RemoteException: “, anybody has an
idea of what might be the problem?
That’s the result of using “$HADOOP_HOME/bin/start-all.sh”
I tried to split the start phase to “
$HADOOP_HOME/bin/hadoop namenode
$HADOOP_HOME/bin/hadoop datanode
“
Below is the log:
myHadoop: Using HADOOP_HOME=/home/hpc-ruhua/hadoop-stack/hadoop-1.2.1
myHadoop: Using MH_SCRATCH_DIR=/tmp/hpc-ruhua/4178
myHadoop: Using JAVA_HOME=/usr
myHadoop: Generating Hadoop configuration in directory in
/home/hpc-ruhua/hadoop/conf/hadoop-conf.4178...
myHadoop: Using directory /home/hpc-ruhua/hadoop/hdfs for persisting HDFS
state...
myHadoop: Designating cn53 as master node (namenode, secondary namenode, and
jobtracker)
myHadoop: The following nodes will be slaves (datanode, tasktracer):
cn53
cn54
cn55
cn56
Linking /home/hpc-ruhua/hadoop/hdfs/0 to /tmp/hpc-ruhua/4178/hdfs_data on cn53
Linking /home/hpc-ruhua/hadoop/hdfs/1 to /tmp/hpc-ruhua/4178/hdfs_data on cn54
Linking /home/hpc-ruhua/hadoop/hdfs/2 to /tmp/hpc-ruhua/4178/hdfs_data on cn55
Linking /home/hpc-ruhua/hadoop/hdfs/3 to /tmp/hpc-ruhua/4178/hdfs_data on cn56
15/01/16 15:35:14 INFO namenode.NameNode: STARTUP_MSG:
/************************************************************
STARTUP_MSG: Starting NameNode
STARTUP_MSG: host = cn53/192.168.100.53
STARTUP_MSG: args = []
STARTUP_MSG: version = 1.2.1
STARTUP_MSG: build =
https://svn.apache.org/repos/asf/hadoop/common/branches/branch-1.2 -r 1503152;
compiled by 'mattf' on Mon Jul 22 15:23:09 PDT 2013
STARTUP_MSG: java = 1.7.0_71
************************************************************/
15/01/16 15:35:14 INFO impl.MetricsConfig: loaded properties from
hadoop-metrics2.properties
15/01/16 15:35:14 INFO impl.MetricsSourceAdapter: MBean for source
MetricsSystem,sub=Stats registered.
15/01/16 15:35:14 INFO impl.MetricsSystemImpl: Scheduled snapshot period at 10
second(s).
15/01/16 15:35:14 INFO impl.MetricsSystemImpl: NameNode metrics system started
15/01/16 15:35:14 INFO impl.MetricsSourceAdapter: MBean for source ugi
registered.
15/01/16 15:35:14 INFO impl.MetricsSourceAdapter: MBean for source jvm
registered.
15/01/16 15:35:14 INFO impl.MetricsSourceAdapter: MBean for source NameNode
registered.
15/01/16 15:35:14 INFO util.GSet: Computing capacity for map BlocksMap
15/01/16 15:35:14 INFO util.GSet: VM type = 64-bit
15/01/16 15:35:14 INFO util.GSet: 2.0% max memory = 932184064
15/01/16 15:35:14 INFO util.GSet: capacity = 2^21 = 2097152 entries
15/01/16 15:35:14 INFO util.GSet: recommended=2097152, actual=2097152
15/01/16 15:35:15 INFO namenode.FSNamesystem: fsOwner=hpc-ruhua
15/01/16 15:35:15 INFO namenode.FSNamesystem: supergroup=supergroup
15/01/16 15:35:15 INFO namenode.FSNamesystem: isPermissionEnabled=true
15/01/16 15:35:15 INFO namenode.FSNamesystem: dfs.block.invalidate.limit=100
15/01/16 15:35:15 INFO namenode.FSNamesystem: isAccessTokenEnabled=false
accessKeyUpdateInterval=0 min(s), accessTokenLifetime=0 min(s)
15/01/16 15:35:15 INFO namenode.FSNamesystem: Registered FSNamesystemStateMBean
and NameNodeMXBean
15/01/16 15:35:15 INFO namenode.FSEditLog: dfs.namenode.edits.toleration.length
= 0
15/01/16 15:35:15 INFO namenode.NameNode: Caching file names occuring more than
10 times
15/01/16 15:35:15 INFO common.Storage: Start loading image file
/tmp/hpc-ruhua/4178/namenode_data/current/fsimage
15/01/16 15:35:15 INFO common.Storage: Number of files = 28
15/01/16 15:35:15 INFO common.Storage: Number of files under construction = 1
15/01/16 15:35:15 INFO common.Storage: Image file
/tmp/hpc-ruhua/4178/namenode_data/current/fsimage of size 2996 bytes loaded in
0 seconds.
15/01/16 15:35:15 INFO namenode.FSEditLog: Start loading edits file
/tmp/hpc-ruhua/4178/namenode_data/current/edits
15/01/16 15:35:15 INFO namenode.FSEditLog: Invalid opcode, reached end of edit
log Number of transactions found: 32. Bytes read: 2579
15/01/16 15:35:15 INFO namenode.FSEditLog: Start checking end of edit log
(/tmp/hpc-ruhua/4178/namenode_data/current/edits) ...
15/01/16 15:35:15 INFO namenode.FSEditLog: Checked the bytes after the end of
edit log (/tmp/hpc-ruhua/4178/namenode_data/current/edits):
15/01/16 15:35:15 INFO namenode.FSEditLog: Padding position = 2579 (-1 means
padding not found)
15/01/16 15:35:15 INFO namenode.FSEditLog: Edit log length = 1048580
15/01/16 15:35:15 INFO namenode.FSEditLog: Read length = 2579
15/01/16 15:35:15 INFO namenode.FSEditLog: Corruption length = 0
15/01/16 15:35:15 INFO namenode.FSEditLog: Toleration length = 0 (=
dfs.namenode.edits.toleration.length)
15/01/16 15:35:15 INFO namenode.FSEditLog: Summary: |---------- Read=2579
----------|-- Corrupt=0 --|-- Pad=1046001 --|
15/01/16 15:35:15 INFO namenode.FSEditLog: Edits file
/tmp/hpc-ruhua/4178/namenode_data/current/edits of size 1048580 edits # 32
loaded in 0 seconds.
15/01/16 15:35:15 INFO common.Storage: Image file
/tmp/hpc-ruhua/4178/namenode_data/current/fsimage of size 3745 bytes saved in 0
seconds.
15/01/16 15:35:15 INFO namenode.FSEditLog: closing edit log: position=4,
editlog=/tmp/hpc-ruhua/4178/namenode_data/current/edits
15/01/16 15:35:15 INFO namenode.FSEditLog: close success: truncate to 4,
editlog=/tmp/hpc-ruhua/4178/namenode_data/current/edits
15/01/16 15:35:16 INFO namenode.NameCache: initialized with 0 entries 0 lookups
15/01/16 15:35:16 INFO namenode.FSNamesystem: Finished loading FSImage in 1162
msecs
15/01/16 15:35:16 INFO namenode.FSNamesystem: dfs.safemode.threshold.pct
= 0.9990000128746033
15/01/16 15:35:16 INFO namenode.FSNamesystem:
dfs.namenode.safemode.min.datanodes = 0
15/01/16 15:35:16 INFO namenode.FSNamesystem: dfs.safemode.extension
= 30000
15/01/16 15:35:16 INFO namenode.FSNamesystem: Number of blocks excluded by safe
block count: 0 total blocks: 0 and thus the safe blocks: 0
15/01/16 15:35:16 INFO namenode.FSNamesystem: Total number of blocks = 0
15/01/16 15:35:16 INFO namenode.FSNamesystem: Number of invalid blocks = 0
15/01/16 15:35:16 INFO namenode.FSNamesystem: Number of under-replicated blocks
= 0
15/01/16 15:35:16 INFO namenode.FSNamesystem: Number of over-replicated blocks
= 0
15/01/16 15:35:16 INFO hdfs.StateChange: STATE* Safe mode termination scan for
invalid, over- and under-replicated blocks completed in 7 msec
15/01/16 15:35:16 INFO hdfs.StateChange: STATE* Leaving safe mode after 1 secs
15/01/16 15:35:16 INFO hdfs.StateChange: STATE* Network topology has 0 racks
and 0 datanodes
15/01/16 15:35:16 INFO hdfs.StateChange: STATE* UnderReplicatedBlocks has 0
blocks
15/01/16 15:35:16 INFO util.HostsFileReader: Refreshing hosts (include/exclude)
list
15/01/16 15:35:16 INFO namenode.FSNamesystem: ReplicateQueue
QueueProcessingStatistics: First cycle completed 0 blocks in 0 msec
15/01/16 15:35:16 INFO namenode.FSNamesystem: ReplicateQueue
QueueProcessingStatistics: Queue flush completed 0 blocks in 0 msec processing
time, 0 msec clock time, 1 cycles
15/01/16 15:35:16 INFO namenode.FSNamesystem: InvalidateQueue
QueueProcessingStatistics: First cycle completed 0 blocks in 0 msec
15/01/16 15:35:16 INFO namenode.FSNamesystem: InvalidateQueue
QueueProcessingStatistics: Queue flush completed 0 blocks in 0 msec processing
time, 0 msec clock time, 1 cycles
15/01/16 15:35:16 INFO impl.MetricsSourceAdapter: MBean for source
FSNamesystemMetrics registered.
15/01/16 15:35:16 INFO ipc.Server: Starting SocketReader
15/01/16 15:35:16 INFO impl.MetricsSourceAdapter: MBean for source
RpcDetailedActivityForPort54310 registered.
15/01/16 15:35:16 INFO impl.MetricsSourceAdapter: MBean for source
RpcActivityForPort54310 registered.
15/01/16 15:35:16 INFO namenode.NameNode: Namenode up at:
cn53/192.168.100.53:54310
15/01/16 15:35:16 INFO mortbay.log: Logging to
org.slf4j.impl.Log4jLoggerAdapter(org.mortbay.log) via org.mortbay.log.Slf4jLog
15/01/16 15:35:16 INFO http.HttpServer: Added global filtersafety
(class=org.apache.hadoop.http.HttpServer$QuotingInputFilter)
15/01/16 15:35:16 INFO http.HttpServer: dfs.webhdfs.enabled = false
15/01/16 15:35:16 INFO http.HttpServer: Port returned by
webServer.getConnectors()[0].getLocalPort() before open() is -1. Opening the
listener on 50070
15/01/16 15:35:16 INFO http.HttpServer: listener.getLocalPort() returned 50070
webServer.getConnectors()[0].getLocalPort() returned 50070
15/01/16 15:35:16 INFO http.HttpServer: Jetty bound to port 50070
15/01/16 15:35:16 INFO mortbay.log: jetty-6.1.26
15/01/16 15:35:16 INFO mortbay.log: Started [email protected]:50070
15/01/16 15:35:16 INFO namenode.NameNode: Web-server up at: 0.0.0.0:50070
15/01/16 15:35:16 INFO ipc.Server: IPC Server Responder: starting
15/01/16 15:35:16 INFO ipc.Server: IPC Server listener on 54310: starting
15/01/16 15:35:16 INFO ipc.Server: IPC Server handler 0 on 54310: starting
15/01/16 15:35:16 INFO ipc.Server: IPC Server handler 1 on 54310: starting
15/01/16 15:35:16 INFO ipc.Server: IPC Server handler 2 on 54310: starting
15/01/16 15:35:16 INFO ipc.Server: IPC Server handler 3 on 54310: starting
15/01/16 15:35:16 INFO ipc.Server: IPC Server handler 4 on 54310: starting
15/01/16 15:35:16 INFO ipc.Server: IPC Server handler 5 on 54310: starting
15/01/16 15:35:16 INFO ipc.Server: IPC Server handler 6 on 54310: starting
15/01/16 15:35:16 INFO ipc.Server: IPC Server handler 8 on 54310: starting
15/01/16 15:35:16 INFO ipc.Server: IPC Server handler 7 on 54310: starting
15/01/16 15:35:16 INFO ipc.Server: IPC Server handler 9 on 54310: starting
==
I can also provide the script of running myHadoop or other system information
if that helps. I have been struggling with this problem for quite long time.
Could anyone help?
Best,
Ruhua
