hadoop-hdfs-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Ted Yu <yuzhih...@gmail.com>
Subject Re: Start Hadoop, ERROR security.UserGroupInformation: PriviledgedActionException
Date Fri, 16 Jan 2015 21:08:59 GMT
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