You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@hadoop.apache.org by Ruhua Jiang <ru...@gmail.com> on 2015/01/16 21:55:21 UTC
Start Hadoop, ERROR security.UserGroupInformation: PriviledgedActionException
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 SelectChannelConnector@0.0.0.0: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
Re: Start Hadoop, ERROR security.UserGroupInformation: PriviledgedActionException
Posted by Ruhua Jiang <ru...@gmail.com>.
Thanks Ted!
Ruhua
On Jan 16, 2015, at 4:08 PM, Ted Yu <yu...@gmail.com> wrote:
> Have you looked at:
> http://sourceforge.net/p/myhadoop/mailman/?source=navbar
>
> Cheers
>
> On Fri, Jan 16, 2015 at 12:55 PM, Ruhua Jiang <ru...@gmail.com> wrote:
> 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 SelectChannelConnector@0.0.0.0: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
>
>
>
>
>
Re: Start Hadoop, ERROR security.UserGroupInformation: PriviledgedActionException
Posted by Ruhua Jiang <ru...@gmail.com>.
Thanks Ted!
Ruhua
On Jan 16, 2015, at 4:08 PM, Ted Yu <yu...@gmail.com> wrote:
> Have you looked at:
> http://sourceforge.net/p/myhadoop/mailman/?source=navbar
>
> Cheers
>
> On Fri, Jan 16, 2015 at 12:55 PM, Ruhua Jiang <ru...@gmail.com> wrote:
> 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 SelectChannelConnector@0.0.0.0: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
>
>
>
>
>
Re: Start Hadoop, ERROR security.UserGroupInformation: PriviledgedActionException
Posted by Ruhua Jiang <ru...@gmail.com>.
Thanks Ted!
Ruhua
On Jan 16, 2015, at 4:08 PM, Ted Yu <yu...@gmail.com> wrote:
> Have you looked at:
> http://sourceforge.net/p/myhadoop/mailman/?source=navbar
>
> Cheers
>
> On Fri, Jan 16, 2015 at 12:55 PM, Ruhua Jiang <ru...@gmail.com> wrote:
> 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 SelectChannelConnector@0.0.0.0: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
>
>
>
>
>
Re: Start Hadoop, ERROR security.UserGroupInformation: PriviledgedActionException
Posted by Ruhua Jiang <ru...@gmail.com>.
Thanks Ted!
Ruhua
On Jan 16, 2015, at 4:08 PM, Ted Yu <yu...@gmail.com> wrote:
> Have you looked at:
> http://sourceforge.net/p/myhadoop/mailman/?source=navbar
>
> Cheers
>
> On Fri, Jan 16, 2015 at 12:55 PM, Ruhua Jiang <ru...@gmail.com> wrote:
> 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 SelectChannelConnector@0.0.0.0: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
>
>
>
>
>
Re: Start Hadoop, ERROR security.UserGroupInformation: PriviledgedActionException
Posted by Ted Yu <yu...@gmail.com>.
Have you looked at:
http://sourceforge.net/p/myhadoop/mailman/?source=navbar
Cheers
On Fri, Jan 16, 2015 at 12:55 PM, Ruhua Jiang <ru...@gmail.com> wrote:
> 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 SelectChannelConnector@0.0.0.0
> :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
>
>
>
>
>
Re: Start Hadoop, ERROR security.UserGroupInformation: PriviledgedActionException
Posted by Alexander Alten-Lorenz <wg...@gmail.com>.
Jobtracker isn’t running, the log said. Check if your script startup one.
BR,
AL
> On 16 Jan 2015, at 21:55, Ruhua Jiang <ru...@gmail.com> wrote:
>
> 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
Re: Start Hadoop, ERROR security.UserGroupInformation: PriviledgedActionException
Posted by Alexander Alten-Lorenz <wg...@gmail.com>.
Jobtracker isn’t running, the log said. Check if your script startup one.
BR,
AL
> On 16 Jan 2015, at 21:55, Ruhua Jiang <ru...@gmail.com> wrote:
>
> 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
Re: Start Hadoop, ERROR security.UserGroupInformation: PriviledgedActionException
Posted by Ted Yu <yu...@gmail.com>.
Have you looked at:
http://sourceforge.net/p/myhadoop/mailman/?source=navbar
Cheers
On Fri, Jan 16, 2015 at 12:55 PM, Ruhua Jiang <ru...@gmail.com> wrote:
> 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 SelectChannelConnector@0.0.0.0
> :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
>
>
>
>
>
Re: Start Hadoop, ERROR security.UserGroupInformation: PriviledgedActionException
Posted by Ted Yu <yu...@gmail.com>.
Have you looked at:
http://sourceforge.net/p/myhadoop/mailman/?source=navbar
Cheers
On Fri, Jan 16, 2015 at 12:55 PM, Ruhua Jiang <ru...@gmail.com> wrote:
> 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 SelectChannelConnector@0.0.0.0
> :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
>
>
>
>
>
Re: Start Hadoop, ERROR security.UserGroupInformation: PriviledgedActionException
Posted by Ted Yu <yu...@gmail.com>.
Have you looked at:
http://sourceforge.net/p/myhadoop/mailman/?source=navbar
Cheers
On Fri, Jan 16, 2015 at 12:55 PM, Ruhua Jiang <ru...@gmail.com> wrote:
> 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 SelectChannelConnector@0.0.0.0
> :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
>
>
>
>
>
Re: Start Hadoop, ERROR security.UserGroupInformation: PriviledgedActionException
Posted by Alexander Alten-Lorenz <wg...@gmail.com>.
Jobtracker isn’t running, the log said. Check if your script startup one.
BR,
AL
> On 16 Jan 2015, at 21:55, Ruhua Jiang <ru...@gmail.com> wrote:
>
> 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
Re: Start Hadoop, ERROR security.UserGroupInformation: PriviledgedActionException
Posted by Alexander Alten-Lorenz <wg...@gmail.com>.
Jobtracker isn’t running, the log said. Check if your script startup one.
BR,
AL
> On 16 Jan 2015, at 21:55, Ruhua Jiang <ru...@gmail.com> wrote:
>
> 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