hadoop-mapreduce-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Ruhua Jiang <ruhua.ji...@gmail.com>
Subject Re: Start Hadoop, ERROR security.UserGroupInformation: PriviledgedActionException
Date Sat, 17 Jan 2015 17:10:36 GMT
Thanks Ted!

Ruhua
On Jan 16, 2015, at 4:08 PM, Ted Yu <yuzhihong@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 <ruhua.jiang@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
> 
> 
> 
> 
> 


Mime
View raw message