You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@oozie.apache.org by "Yesha Vora (JIRA)" <ji...@apache.org> on 2017/12/01 20:19:01 UTC
[jira] [Created] (OOZIE-3138) TestSparkMain.testMain UT fails
Yesha Vora created OOZIE-3138:
---------------------------------
Summary: TestSparkMain.testMain UT fails
Key: OOZIE-3138
URL: https://issues.apache.org/jira/browse/OOZIE-3138
Project: Oozie
Issue Type: Test
Reporter: Yesha Vora
TestSparkMain.testMain UT fails with below error
{code}
Error Message
java.lang.RuntimeException: Unable to instantiate org.apache.hive.hcatalog.common.HiveClientCache$CacheableHiveMetaStoreClient
Stacktrace
com.google.common.util.concurrent.UncheckedExecutionException: java.lang.RuntimeException: Unable to instantiate org.apache.hive.hcatalog.common.HiveClientCache$CacheableHiveMetaStoreClient
at com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2263)
at com.google.common.cache.LocalCache.get(LocalCache.java:4000)
at com.google.common.cache.LocalCache$LocalManualCache.get(LocalCache.java:4789)
at org.apache.hive.hcatalog.common.HiveClientCache.getOrCreate(HiveClientCache.java:291)
at org.apache.hive.hcatalog.common.HiveClientCache.get(HiveClientCache.java:273)
at org.apache.hive.hcatalog.common.HCatUtil.getHiveMetastoreClient(HCatUtil.java:558)
at org.apache.hive.hcatalog.api.HCatClientHMSImpl.initialize(HCatClientHMSImpl.java:823)
at org.apache.hive.hcatalog.api.HCatClient.create(HCatClient.java:71)
at org.apache.oozie.test.MiniHCatServer.start(MiniHCatServer.java:87)
at org.apache.oozie.test.XTestCase.setupHCatalogServer(XTestCase.java:998)
at org.apache.oozie.test.XTestCase.setUp(XTestCase.java:405)
at org.apache.oozie.test.XTestCase.setUp(XTestCase.java:281)
at org.apache.oozie.test.XFsTestCase.setUp(XFsTestCase.java:61)
at junit.framework.TestCase.runBare(TestCase.java:132)
at junit.framework.TestResult$1.protect(TestResult.java:110)
at junit.framework.TestResult.runProtected(TestResult.java:128)
at junit.framework.TestResult.run(TestResult.java:113)
at junit.framework.TestCase.run(TestCase.java:124)
at junit.framework.TestSuite.runTest(TestSuite.java:243)
at junit.framework.TestSuite.run(TestSuite.java:238)
at org.junit.internal.runners.JUnit38ClassRunner.run(JUnit38ClassRunner.java:83)
at org.junit.runners.Suite.runChild(Suite.java:128)
at org.junit.runners.Suite.runChild(Suite.java:24)
at org.junit.runners.ParentRunner$3.run(ParentRunner.java:231)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.RuntimeException: Unable to instantiate org.apache.hive.hcatalog.common.HiveClientCache$CacheableHiveMetaStoreClient
at org.apache.hadoop.hive.metastore.MetaStoreUtils.newInstance(MetaStoreUtils.java:1566)
at org.apache.hadoop.hive.metastore.RetryingMetaStoreClient.<init>(RetryingMetaStoreClient.java:92)
at org.apache.hadoop.hive.metastore.RetryingMetaStoreClient.getProxy(RetryingMetaStoreClient.java:138)
at org.apache.hadoop.hive.metastore.RetryingMetaStoreClient.getProxy(RetryingMetaStoreClient.java:124)
at org.apache.hive.hcatalog.common.HiveClientCache$5.call(HiveClientCache.java:295)
at org.apache.hive.hcatalog.common.HiveClientCache$5.call(HiveClientCache.java:291)
at com.google.common.cache.LocalCache$LocalManualCache$1.load(LocalCache.java:4792)
at com.google.common.cache.LocalCache$LoadingValueReference.loadFuture(LocalCache.java:3599)
at com.google.common.cache.LocalCache$Segment.loadSync(LocalCache.java:2379)
at com.google.common.cache.LocalCache$Segment.lockedGetOrLoad(LocalCache.java:2342)
at com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2257)
... 28 more
Caused by: java.lang.reflect.InvocationTargetException
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
at org.apache.hadoop.hive.metastore.MetaStoreUtils.newInstance(MetaStoreUtils.java:1564)
... 38 more
Caused by: MetaException(message:Could not connect to meta store using any of the URIs provided. Most recent failure: org.apache.thrift.transport.TTransportException: java.net.ConnectException: Connection refused
at org.apache.thrift.transport.TSocket.open(TSocket.java:187)
at org.apache.hadoop.hive.metastore.HiveMetaStoreClient.open(HiveMetaStoreClient.java:487)
at org.apache.hadoop.hive.metastore.HiveMetaStoreClient.<init>(HiveMetaStoreClient.java:282)
at org.apache.hadoop.hive.metastore.HiveMetaStoreClient.<init>(HiveMetaStoreClient.java:188)
at org.apache.hive.hcatalog.common.HiveClientCache$CacheableHiveMetaStoreClient.<init>(HiveClientCache.java:406)
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
at org.apache.hadoop.hive.metastore.MetaStoreUtils.newInstance(MetaStoreUtils.java:1564)
at org.apache.hadoop.hive.metastore.RetryingMetaStoreClient.<init>(RetryingMetaStoreClient.java:92)
at org.apache.hadoop.hive.metastore.RetryingMetaStoreClient.getProxy(RetryingMetaStoreClient.java:138)
at org.apache.hadoop.hive.metastore.RetryingMetaStoreClient.getProxy(RetryingMetaStoreClient.java:124)
at org.apache.hive.hcatalog.common.HiveClientCache$5.call(HiveClientCache.java:295)
at org.apache.hive.hcatalog.common.HiveClientCache$5.call(HiveClientCache.java:291)
at com.google.common.cache.LocalCache$LocalManualCache$1.load(LocalCache.java:4792)
at com.google.common.cache.LocalCache$LoadingValueReference.loadFuture(LocalCache.java:3599)
at com.google.common.cache.LocalCache$Segment.loadSync(LocalCache.java:2379)
at com.google.common.cache.LocalCache$Segment.lockedGetOrLoad(LocalCache.java:2342)
at com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2257)
at com.google.common.cache.LocalCache.get(LocalCache.java:4000)
at com.google.common.cache.LocalCache$LocalManualCache.get(LocalCache.java:4789)
at org.apache.hive.hcatalog.common.HiveClientCache.getOrCreate(HiveClientCache.java:291)
at org.apache.hive.hcatalog.common.HiveClientCache.get(HiveClientCache.java:273)
at org.apache.hive.hcatalog.common.HCatUtil.getHiveMetastoreClient(HCatUtil.java:558)
at org.apache.hive.hcatalog.api.HCatClientHMSImpl.initialize(HCatClientHMSImpl.java:823)
at org.apache.hive.hcatalog.api.HCatClient.create(HCatClient.java:71)
at org.apache.oozie.test.MiniHCatServer.start(MiniHCatServer.java:87)
at org.apache.oozie.test.XTestCase.setupHCatalogServer(XTestCase.java:998)
at org.apache.oozie.test.XTestCase.setUp(XTestCase.java:405)
at org.apache.oozie.test.XTestCase.setUp(XTestCase.java:281)
at org.apache.oozie.test.XFsTestCase.setUp(XFsTestCase.java:61)
at junit.framework.TestCase.runBare(TestCase.java:132)
at junit.framework.TestResult$1.protect(TestResult.java:110)
at junit.framework.TestResult.runProtected(TestResult.java:128)
at junit.framework.TestResult.run(TestResult.java:113)
at junit.framework.TestCase.run(TestCase.java:124)
at junit.framework.TestSuite.runTest(TestSuite.java:243)
at junit.framework.TestSuite.run(TestSuite.java:238)
at org.junit.internal.runners.JUnit38ClassRunner.run(JUnit38ClassRunner.java:83)
at org.junit.runners.Suite.runChild(Suite.java:128)
at org.junit.runners.Suite.runChild(Suite.java:24)
at org.junit.runners.ParentRunner$3.run(ParentRunner.java:231)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
Caused by: java.net.ConnectException: Connection refused
at java.net.PlainSocketImpl.socketConnect(Native Method)
at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
at java.net.Socket.connect(Socket.java:589)
at org.apache.thrift.transport.TSocket.open(TSocket.java:182)
... 47 more
)
at org.apache.hadoop.hive.metastore.HiveMetaStoreClient.open(HiveMetaStoreClient.java:534)
at org.apache.hadoop.hive.metastore.HiveMetaStoreClient.<init>(HiveMetaStoreClient.java:282)
at org.apache.hadoop.hive.metastore.HiveMetaStoreClient.<init>(HiveMetaStoreClient.java:188)
at org.apache.hive.hcatalog.common.HiveClientCache$CacheableHiveMetaStoreClient.<init>(HiveClientCache.java:406)
... 43 more
Standard Output
Setting testcase work dir[/grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/target/test-data/oozietests/org.apache.oozie.action.hadoop.TestSparkMain/testMain]
2017-11-28 15:41:48,529 WARN [pool-1-thread-1] conf.Configuration (Configuration.java:<clinit>(664)) - DEPRECATED: hadoop-site.xml found in the classpath. Usage of hadoop-site.xml is deprecated. Instead use core-site.xml, mapred-site.xml and hdfs-site.xml to override properties of core-default.xml, mapred-default.xml and hdfs-default.xml respectively
2017-11-28 15:41:48,961 INFO [pool-1-thread-1] Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1194)) - mapred.tasktracker.map.tasks.maximum is deprecated. Instead, use mapreduce.tasktracker.map.tasks.maximum
2017-11-28 15:41:48,962 INFO [pool-1-thread-1] Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1194)) - mapred.tasktracker.reduce.tasks.maximum is deprecated. Instead, use mapreduce.tasktracker.reduce.tasks.maximum
2017-11-28 15:41:49,139 WARN [pool-1-thread-1] util.NativeCodeLoader (NativeCodeLoader.java:<clinit>(62)) - Unable to load native-hadoop library for your platform... using builtin-java classes where applicable
Formatting using clusterid: testClusterID
2017-11-28 15:41:49,576 INFO [pool-1-thread-1] namenode.FSEditLog (FSEditLog.java:newInstance(225)) - Edit logging is async:false
2017-11-28 15:41:49,582 INFO [pool-1-thread-1] namenode.FSNamesystem (FSNamesystem.java:<init>(758)) - No KeyProvider found.
2017-11-28 15:41:49,583 INFO [pool-1-thread-1] namenode.FSNamesystem (FSNamesystem.java:<init>(768)) - fsLock is fair:true
2017-11-28 15:41:49,644 INFO [pool-1-thread-1] common.Util (Util.java:isDiskStatsEnabled(111)) - dfs.datanode.fileio.profiling.sampling.percentage set to 0. Disabling file IO profiling
2017-11-28 15:41:49,653 INFO [pool-1-thread-1] Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1194)) - hadoop.configured.node.mapping is deprecated. Instead, use net.topology.configured.node.mapping
2017-11-28 15:41:49,653 INFO [pool-1-thread-1] blockmanagement.DatanodeManager (DatanodeManager.java:<init>(274)) - dfs.block.invalidate.limit=1000
2017-11-28 15:41:49,653 INFO [pool-1-thread-1] blockmanagement.DatanodeManager (DatanodeManager.java:<init>(280)) - dfs.namenode.datanode.registration.ip-hostname-check=true
2017-11-28 15:41:49,658 INFO [pool-1-thread-1] blockmanagement.BlockManager (InvalidateBlocks.java:printBlockDeletionTime(71)) - dfs.namenode.startup.delay.block.deletion.sec is set to 000:00:00:00.000
2017-11-28 15:41:49,660 INFO [pool-1-thread-1] blockmanagement.BlockManager (InvalidateBlocks.java:printBlockDeletionTime(76)) - The block deletion will start around 2017 Nov 28 15:41:49
2017-11-28 15:41:49,664 INFO [pool-1-thread-1] util.GSet (LightWeightGSet.java:computeCapacity(395)) - Computing capacity for map BlocksMap
2017-11-28 15:41:49,664 INFO [pool-1-thread-1] util.GSet (LightWeightGSet.java:computeCapacity(396)) - VM type = 64-bit
2017-11-28 15:41:49,667 INFO [pool-1-thread-1] util.GSet (LightWeightGSet.java:computeCapacity(397)) - 2.0% max memory 981.5 MB = 19.6 MB
2017-11-28 15:41:49,668 INFO [pool-1-thread-1] util.GSet (LightWeightGSet.java:computeCapacity(402)) - capacity = 2^21 = 2097152 entries
2017-11-28 15:41:49,697 INFO [pool-1-thread-1] blockmanagement.BlockManager (BlockManager.java:createBlockTokenSecretManager(409)) - dfs.block.access.token.enable=false
2017-11-28 15:41:49,701 INFO [pool-1-thread-1] blockmanagement.BlockManager (BlockManager.java:<init>(395)) - defaultReplication = 2
2017-11-28 15:41:49,701 INFO [pool-1-thread-1] blockmanagement.BlockManager (BlockManager.java:<init>(396)) - maxReplication = 512
2017-11-28 15:41:49,701 INFO [pool-1-thread-1] blockmanagement.BlockManager (BlockManager.java:<init>(397)) - minReplication = 1
2017-11-28 15:41:49,701 INFO [pool-1-thread-1] blockmanagement.BlockManager (BlockManager.java:<init>(398)) - maxReplicationStreams = 2
2017-11-28 15:41:49,701 INFO [pool-1-thread-1] blockmanagement.BlockManager (BlockManager.java:<init>(399)) - replicationRecheckInterval = 3000
2017-11-28 15:41:49,701 INFO [pool-1-thread-1] blockmanagement.BlockManager (BlockManager.java:<init>(400)) - encryptDataTransfer = false
2017-11-28 15:41:49,702 INFO [pool-1-thread-1] blockmanagement.BlockManager (BlockManager.java:<init>(401)) - maxNumBlocksToLog = 1000
2017-11-28 15:41:49,754 INFO [pool-1-thread-1] namenode.FSNamesystem (FSNamesystem.java:<init>(789)) - fsOwner = nobody (auth:SIMPLE)
2017-11-28 15:41:49,754 INFO [pool-1-thread-1] namenode.FSNamesystem (FSNamesystem.java:<init>(790)) - supergroup = supergroup
2017-11-28 15:41:49,754 INFO [pool-1-thread-1] namenode.FSNamesystem (FSNamesystem.java:<init>(791)) - isPermissionEnabled = true
2017-11-28 15:41:49,755 INFO [pool-1-thread-1] namenode.FSNamesystem (FSNamesystem.java:<init>(802)) - HA Enabled: false
2017-11-28 15:41:49,759 INFO [pool-1-thread-1] namenode.FSNamesystem (FSNamesystem.java:<init>(839)) - Append Enabled: true
2017-11-28 15:41:49,995 INFO [pool-1-thread-1] util.GSet (LightWeightGSet.java:computeCapacity(395)) - Computing capacity for map INodeMap
2017-11-28 15:41:49,995 INFO [pool-1-thread-1] util.GSet (LightWeightGSet.java:computeCapacity(396)) - VM type = 64-bit
2017-11-28 15:41:49,996 INFO [pool-1-thread-1] util.GSet (LightWeightGSet.java:computeCapacity(397)) - 1.0% max memory 981.5 MB = 9.8 MB
2017-11-28 15:41:49,996 INFO [pool-1-thread-1] util.GSet (LightWeightGSet.java:computeCapacity(402)) - capacity = 2^20 = 1048576 entries
2017-11-28 15:41:49,999 INFO [pool-1-thread-1] namenode.FSDirectory (FSDirectory.java:<init>(256)) - ACLs enabled? false
2017-11-28 15:41:50,000 INFO [pool-1-thread-1] namenode.FSDirectory (FSDirectory.java:<init>(260)) - XAttrs enabled? true
2017-11-28 15:41:50,000 INFO [pool-1-thread-1] namenode.FSDirectory (FSDirectory.java:<init>(268)) - Maximum size of an xattr: 16384
2017-11-28 15:41:50,000 INFO [pool-1-thread-1] namenode.NameNode (FSDirectory.java:<init>(321)) - Caching file names occuring more than 10 times
2017-11-28 15:41:50,013 INFO [pool-1-thread-1] util.GSet (LightWeightGSet.java:computeCapacity(395)) - Computing capacity for map cachedBlocks
2017-11-28 15:41:50,013 INFO [pool-1-thread-1] util.GSet (LightWeightGSet.java:computeCapacity(396)) - VM type = 64-bit
2017-11-28 15:41:50,014 INFO [pool-1-thread-1] util.GSet (LightWeightGSet.java:computeCapacity(397)) - 0.25% max memory 981.5 MB = 2.5 MB
2017-11-28 15:41:50,014 INFO [pool-1-thread-1] util.GSet (LightWeightGSet.java:computeCapacity(402)) - capacity = 2^18 = 262144 entries
2017-11-28 15:41:50,016 INFO [pool-1-thread-1] namenode.FSNamesystem (FSNamesystem.java:<init>(5574)) - dfs.namenode.safemode.threshold-pct = 0.9990000128746033
2017-11-28 15:41:50,017 INFO [pool-1-thread-1] namenode.FSNamesystem (FSNamesystem.java:<init>(5575)) - dfs.namenode.safemode.min.datanodes = 0
2017-11-28 15:41:50,017 INFO [pool-1-thread-1] namenode.FSNamesystem (FSNamesystem.java:<init>(5576)) - dfs.namenode.safemode.extension = 0
2017-11-28 15:41:50,023 INFO [pool-1-thread-1] metrics.TopMetrics (TopMetrics.java:logConf(76)) - NNTop conf: dfs.namenode.top.window.num.buckets = 10
2017-11-28 15:41:50,023 INFO [pool-1-thread-1] metrics.TopMetrics (TopMetrics.java:logConf(78)) - NNTop conf: dfs.namenode.top.num.users = 10
2017-11-28 15:41:50,023 INFO [pool-1-thread-1] metrics.TopMetrics (TopMetrics.java:logConf(80)) - NNTop conf: dfs.namenode.top.windows.minutes = 1,5,25
2017-11-28 15:41:50,091 INFO [pool-1-thread-1] namenode.FSNamesystem (FSNamesystem.java:initRetryCache(967)) - Retry cache on namenode is enabled
2017-11-28 15:41:50,092 INFO [pool-1-thread-1] namenode.FSNamesystem (FSNamesystem.java:initRetryCache(975)) - Retry cache will use 0.03 of total heap and retry cache entry expiry time is 600000 millis
2017-11-28 15:41:50,096 INFO [pool-1-thread-1] util.GSet (LightWeightGSet.java:computeCapacity(395)) - Computing capacity for map NameNodeRetryCache
2017-11-28 15:41:50,096 INFO [pool-1-thread-1] util.GSet (LightWeightGSet.java:computeCapacity(396)) - VM type = 64-bit
2017-11-28 15:41:50,096 INFO [pool-1-thread-1] util.GSet (LightWeightGSet.java:computeCapacity(397)) - 0.029999999329447746% max memory 981.5 MB = 301.5 KB
2017-11-28 15:41:50,096 INFO [pool-1-thread-1] util.GSet (LightWeightGSet.java:computeCapacity(402)) - capacity = 2^15 = 32768 entries
2017-11-28 15:41:50,180 INFO [pool-1-thread-1] namenode.FSImage (FSImage.java:format(153)) - Allocated new BlockPoolId: BP-1089370620-172.27.58.198-1511883710117
2017-11-28 15:41:50,195 INFO [pool-1-thread-1] common.Storage (NNStorage.java:format(566)) - Storage directory /grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/name1 has been successfully formatted.
2017-11-28 15:41:50,197 INFO [pool-1-thread-1] common.Storage (NNStorage.java:format(566)) - Storage directory /grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/name2 has been successfully formatted.
2017-11-28 15:41:50,214 INFO [FSImageSaver for /grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/name2 of type IMAGE_AND_EDITS] namenode.FSImageFormatProtobuf (FSImageFormatProtobuf.java:save(413)) - Saving image file /grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/name2/current/fsimage.ckpt_0000000000000000000 using no compression
2017-11-28 15:41:50,214 INFO [FSImageSaver for /grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/name1 of type IMAGE_AND_EDITS] namenode.FSImageFormatProtobuf (FSImageFormatProtobuf.java:save(413)) - Saving image file /grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/name1/current/fsimage.ckpt_0000000000000000000 using no compression
2017-11-28 15:41:50,335 INFO [FSImageSaver for /grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/name1 of type IMAGE_AND_EDITS] namenode.FSImageFormatProtobuf (FSImageFormatProtobuf.java:save(416)) - Image file /grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/name1/current/fsimage.ckpt_0000000000000000000 of size 323 bytes saved in 0 seconds.
2017-11-28 15:41:50,338 INFO [FSImageSaver for /grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/name2 of type IMAGE_AND_EDITS] namenode.FSImageFormatProtobuf (FSImageFormatProtobuf.java:save(416)) - Image file /grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/name2/current/fsimage.ckpt_0000000000000000000 of size 323 bytes saved in 0 seconds.
2017-11-28 15:41:50,353 INFO [pool-1-thread-1] namenode.NNStorageRetentionManager (NNStorageRetentionManager.java:getImageTxIdToRetain(203)) - Going to retain 1 images with txid >= 0
2017-11-28 15:41:50,357 INFO [pool-1-thread-1] namenode.NameNode (NameNode.java:createNameNode(1624)) - createNameNode []
2017-11-28 15:41:50,407 WARN [pool-1-thread-1] impl.MetricsConfig (MetricsConfig.java:loadFirst(125)) - Cannot locate configuration: tried hadoop-metrics2-namenode.properties,hadoop-metrics2.properties
2017-11-28 15:41:50,495 INFO [pool-1-thread-1] impl.MetricsSystemImpl (MetricsSystemImpl.java:startTimer(376)) - Scheduled snapshot period at 10 second(s).
2017-11-28 15:41:50,496 INFO [pool-1-thread-1] impl.MetricsSystemImpl (MetricsSystemImpl.java:start(192)) - NameNode metrics system started
2017-11-28 15:41:50,500 INFO [pool-1-thread-1] namenode.NameNode (NameNode.java:setClientNamenodeAddress(450)) - fs.defaultFS is hdfs://127.0.0.1:0
2017-11-28 15:41:50,535 INFO [org.apache.hadoop.util.JvmPauseMonitor$Monitor@77b45849] util.JvmPauseMonitor (JvmPauseMonitor.java:run(179)) - Starting JVM pause monitor
2017-11-28 15:41:50,561 INFO [pool-1-thread-1] hdfs.DFSUtil (DFSUtil.java:httpServerTemplateForNNAndJN(1803)) - Starting Web-server for hdfs at: http://localhost:0
2017-11-28 15:41:50,727 INFO [pool-1-thread-1] mortbay.log (Slf4jLog.java:info(67)) - Logging to org.slf4j.impl.Log4jLoggerAdapter(org.mortbay.log) via org.mortbay.log.Slf4jLog
2017-11-28 15:41:50,742 INFO [pool-1-thread-1] server.AuthenticationFilter (AuthenticationFilter.java:constructSecretProvider(296)) - Unable to initialize FileSignerSecretProvider, falling back to use random secrets.
2017-11-28 15:41:50,752 WARN [pool-1-thread-1] http.HttpRequestLog (HttpRequestLog.java:getRequestLog(100)) - Jetty request log can only be enabled using Log4j
2017-11-28 15:41:50,763 INFO [pool-1-thread-1] http.HttpServer2 (HttpServer2.java:addGlobalFilter(791)) - Added global filter 'safety' (class=org.apache.hadoop.http.HttpServer2$QuotingInputFilter)
2017-11-28 15:41:50,767 INFO [pool-1-thread-1] http.HttpServer2 (HttpServer2.java:addFilter(766)) - Added filter static_user_filter (class=org.apache.hadoop.http.lib.StaticUserWebFilter$StaticUserFilter) to context hdfs
2017-11-28 15:41:50,767 INFO [pool-1-thread-1] http.HttpServer2 (HttpServer2.java:addFilter(774)) - Added filter static_user_filter (class=org.apache.hadoop.http.lib.StaticUserWebFilter$StaticUserFilter) to context static
2017-11-28 15:41:50,771 INFO [pool-1-thread-1] http.HttpServer2 (HttpServer2.java:addFilter(774)) - Added filter static_user_filter (class=org.apache.hadoop.http.lib.StaticUserWebFilter$StaticUserFilter) to context logs
2017-11-28 15:41:50,771 INFO [pool-1-thread-1] security.HttpCrossOriginFilterInitializer (HttpCrossOriginFilterInitializer.java:initFilter(49)) - CORS filter not enabled. Please set hadoop.http.cross-origin.enabled to 'true' to enable it
2017-11-28 15:41:50,965 INFO [pool-1-thread-1] http.HttpServer2 (NameNodeHttpServer.java:initWebHdfs(93)) - Added filter 'org.apache.hadoop.hdfs.web.AuthFilter' (class=org.apache.hadoop.hdfs.web.AuthFilter)
2017-11-28 15:41:50,969 INFO [pool-1-thread-1] http.HttpServer2 (HttpServer2.java:addJerseyResourcePackage(690)) - addJerseyResourcePackage: packageName=org.apache.hadoop.hdfs.server.namenode.web.resources;org.apache.hadoop.hdfs.web.resources, pathSpec=/webhdfs/v1/*
2017-11-28 15:41:50,997 INFO [pool-1-thread-1] http.HttpServer2 (HttpServer2.java:bindListener(989)) - Jetty bound to port 46377
2017-11-28 15:41:50,998 INFO [pool-1-thread-1] mortbay.log (Slf4jLog.java:info(67)) - jetty-6.1.14
2017-11-28 15:41:51,039 INFO [pool-1-thread-1] mortbay.log (Slf4jLog.java:info(67)) - Extract jar:file:/grid/0/nobody/.m2/repository/org/apache/hadoop/hadoop-hdfs/2.7.3.2.6.4.0-SNAPSHOT/hadoop-hdfs-2.7.3.2.6.4.0-SNAPSHOT-tests.jar!/webapps/hdfs to /tmp/Jetty_localhost_46377_hdfs____kc669n/webapp
2017-11-28 15:41:51,282 INFO [pool-1-thread-1] mortbay.log (Slf4jLog.java:info(67)) - Started HttpServer2$SelectChannelConnectorWithSafeStartup@localhost:46377
2017-11-28 15:41:51,288 INFO [pool-1-thread-1] namenode.FSEditLog (FSEditLog.java:newInstance(225)) - Edit logging is async:false
2017-11-28 15:41:51,289 INFO [pool-1-thread-1] namenode.FSNamesystem (FSNamesystem.java:<init>(758)) - No KeyProvider found.
2017-11-28 15:41:51,289 INFO [pool-1-thread-1] namenode.FSNamesystem (FSNamesystem.java:<init>(768)) - fsLock is fair:true
2017-11-28 15:41:51,289 INFO [pool-1-thread-1] common.Util (Util.java:isDiskStatsEnabled(111)) - dfs.datanode.fileio.profiling.sampling.percentage set to 0. Disabling file IO profiling
2017-11-28 15:41:51,290 INFO [pool-1-thread-1] blockmanagement.DatanodeManager (DatanodeManager.java:<init>(274)) - dfs.block.invalidate.limit=1000
2017-11-28 15:41:51,290 INFO [pool-1-thread-1] blockmanagement.DatanodeManager (DatanodeManager.java:<init>(280)) - dfs.namenode.datanode.registration.ip-hostname-check=true
2017-11-28 15:41:51,290 INFO [pool-1-thread-1] blockmanagement.BlockManager (InvalidateBlocks.java:printBlockDeletionTime(71)) - dfs.namenode.startup.delay.block.deletion.sec is set to 000:00:00:00.000
2017-11-28 15:41:51,291 INFO [pool-1-thread-1] blockmanagement.BlockManager (InvalidateBlocks.java:printBlockDeletionTime(76)) - The block deletion will start around 2017 Nov 28 15:41:51
2017-11-28 15:41:51,291 INFO [pool-1-thread-1] util.GSet (LightWeightGSet.java:computeCapacity(395)) - Computing capacity for map BlocksMap
2017-11-28 15:41:51,291 INFO [pool-1-thread-1] util.GSet (LightWeightGSet.java:computeCapacity(396)) - VM type = 64-bit
2017-11-28 15:41:51,291 INFO [pool-1-thread-1] util.GSet (LightWeightGSet.java:computeCapacity(397)) - 2.0% max memory 910.5 MB = 18.2 MB
2017-11-28 15:41:51,292 INFO [pool-1-thread-1] util.GSet (LightWeightGSet.java:computeCapacity(402)) - capacity = 2^21 = 2097152 entries
2017-11-28 15:41:51,295 INFO [pool-1-thread-1] blockmanagement.BlockManager (BlockManager.java:createBlockTokenSecretManager(409)) - dfs.block.access.token.enable=false
2017-11-28 15:41:51,295 INFO [pool-1-thread-1] blockmanagement.BlockManager (BlockManager.java:<init>(395)) - defaultReplication = 2
2017-11-28 15:41:51,295 INFO [pool-1-thread-1] blockmanagement.BlockManager (BlockManager.java:<init>(396)) - maxReplication = 512
2017-11-28 15:41:51,295 INFO [pool-1-thread-1] blockmanagement.BlockManager (BlockManager.java:<init>(397)) - minReplication = 1
2017-11-28 15:41:51,296 INFO [pool-1-thread-1] blockmanagement.BlockManager (BlockManager.java:<init>(398)) - maxReplicationStreams = 2
2017-11-28 15:41:51,296 INFO [pool-1-thread-1] blockmanagement.BlockManager (BlockManager.java:<init>(399)) - replicationRecheckInterval = 3000
2017-11-28 15:41:51,296 INFO [pool-1-thread-1] blockmanagement.BlockManager (BlockManager.java:<init>(400)) - encryptDataTransfer = false
2017-11-28 15:41:51,296 INFO [pool-1-thread-1] blockmanagement.BlockManager (BlockManager.java:<init>(401)) - maxNumBlocksToLog = 1000
2017-11-28 15:41:51,296 INFO [pool-1-thread-1] namenode.FSNamesystem (FSNamesystem.java:<init>(789)) - fsOwner = nobody (auth:SIMPLE)
2017-11-28 15:41:51,296 INFO [pool-1-thread-1] namenode.FSNamesystem (FSNamesystem.java:<init>(790)) - supergroup = supergroup
2017-11-28 15:41:51,296 INFO [pool-1-thread-1] namenode.FSNamesystem (FSNamesystem.java:<init>(791)) - isPermissionEnabled = true
2017-11-28 15:41:51,297 INFO [pool-1-thread-1] namenode.FSNamesystem (FSNamesystem.java:<init>(802)) - HA Enabled: false
2017-11-28 15:41:51,297 INFO [pool-1-thread-1] namenode.FSNamesystem (FSNamesystem.java:<init>(839)) - Append Enabled: true
2017-11-28 15:41:51,297 INFO [pool-1-thread-1] util.GSet (LightWeightGSet.java:computeCapacity(395)) - Computing capacity for map INodeMap
2017-11-28 15:41:51,297 INFO [pool-1-thread-1] util.GSet (LightWeightGSet.java:computeCapacity(396)) - VM type = 64-bit
2017-11-28 15:41:51,298 INFO [pool-1-thread-1] util.GSet (LightWeightGSet.java:computeCapacity(397)) - 1.0% max memory 910.5 MB = 9.1 MB
2017-11-28 15:41:51,298 INFO [pool-1-thread-1] util.GSet (LightWeightGSet.java:computeCapacity(402)) - capacity = 2^20 = 1048576 entries
2017-11-28 15:41:51,299 INFO [pool-1-thread-1] namenode.FSDirectory (FSDirectory.java:<init>(256)) - ACLs enabled? false
2017-11-28 15:41:51,300 INFO [pool-1-thread-1] namenode.FSDirectory (FSDirectory.java:<init>(260)) - XAttrs enabled? true
2017-11-28 15:41:51,300 INFO [pool-1-thread-1] namenode.FSDirectory (FSDirectory.java:<init>(268)) - Maximum size of an xattr: 16384
2017-11-28 15:41:51,300 INFO [pool-1-thread-1] namenode.NameNode (FSDirectory.java:<init>(321)) - Caching file names occuring more than 10 times
2017-11-28 15:41:51,300 INFO [pool-1-thread-1] util.GSet (LightWeightGSet.java:computeCapacity(395)) - Computing capacity for map cachedBlocks
2017-11-28 15:41:51,300 INFO [pool-1-thread-1] util.GSet (LightWeightGSet.java:computeCapacity(396)) - VM type = 64-bit
2017-11-28 15:41:51,300 INFO [pool-1-thread-1] util.GSet (LightWeightGSet.java:computeCapacity(397)) - 0.25% max memory 910.5 MB = 2.3 MB
2017-11-28 15:41:51,301 INFO [pool-1-thread-1] util.GSet (LightWeightGSet.java:computeCapacity(402)) - capacity = 2^18 = 262144 entries
2017-11-28 15:41:51,301 INFO [pool-1-thread-1] namenode.FSNamesystem (FSNamesystem.java:<init>(5574)) - dfs.namenode.safemode.threshold-pct = 0.9990000128746033
2017-11-28 15:41:51,302 INFO [pool-1-thread-1] namenode.FSNamesystem (FSNamesystem.java:<init>(5575)) - dfs.namenode.safemode.min.datanodes = 0
2017-11-28 15:41:51,302 INFO [pool-1-thread-1] namenode.FSNamesystem (FSNamesystem.java:<init>(5576)) - dfs.namenode.safemode.extension = 0
2017-11-28 15:41:51,302 INFO [pool-1-thread-1] metrics.TopMetrics (TopMetrics.java:logConf(76)) - NNTop conf: dfs.namenode.top.window.num.buckets = 10
2017-11-28 15:41:51,302 INFO [pool-1-thread-1] metrics.TopMetrics (TopMetrics.java:logConf(78)) - NNTop conf: dfs.namenode.top.num.users = 10
2017-11-28 15:41:51,302 INFO [pool-1-thread-1] metrics.TopMetrics (TopMetrics.java:logConf(80)) - NNTop conf: dfs.namenode.top.windows.minutes = 1,5,25
2017-11-28 15:41:51,302 INFO [pool-1-thread-1] namenode.FSNamesystem (FSNamesystem.java:initRetryCache(967)) - Retry cache on namenode is enabled
2017-11-28 15:41:51,303 INFO [pool-1-thread-1] namenode.FSNamesystem (FSNamesystem.java:initRetryCache(975)) - Retry cache will use 0.03 of total heap and retry cache entry expiry time is 600000 millis
2017-11-28 15:41:51,303 INFO [pool-1-thread-1] util.GSet (LightWeightGSet.java:computeCapacity(395)) - Computing capacity for map NameNodeRetryCache
2017-11-28 15:41:51,303 INFO [pool-1-thread-1] util.GSet (LightWeightGSet.java:computeCapacity(396)) - VM type = 64-bit
2017-11-28 15:41:51,303 INFO [pool-1-thread-1] util.GSet (LightWeightGSet.java:computeCapacity(397)) - 0.029999999329447746% max memory 910.5 MB = 279.7 KB
2017-11-28 15:41:51,303 INFO [pool-1-thread-1] util.GSet (LightWeightGSet.java:computeCapacity(402)) - capacity = 2^15 = 32768 entries
2017-11-28 15:41:51,308 INFO [pool-1-thread-1] common.Storage (Storage.java:tryLock(776)) - Lock on /grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/name1/in_use.lock acquired by nodename 159376@ctr-e134-1499953498516-345856-01-000007.hwx.site
2017-11-28 15:41:51,311 INFO [pool-1-thread-1] common.Storage (Storage.java:tryLock(776)) - Lock on /grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/name2/in_use.lock acquired by nodename 159376@ctr-e134-1499953498516-345856-01-000007.hwx.site
2017-11-28 15:41:51,314 INFO [pool-1-thread-1] namenode.FileJournalManager (FileJournalManager.java:recoverUnfinalizedSegments(388)) - Recovering unfinalized segments in /grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/name1/current
2017-11-28 15:41:51,314 INFO [pool-1-thread-1] namenode.FileJournalManager (FileJournalManager.java:recoverUnfinalizedSegments(388)) - Recovering unfinalized segments in /grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/name2/current
2017-11-28 15:41:51,314 INFO [pool-1-thread-1] namenode.FSImage (FSImage.java:loadFSImage(664)) - No edit log streams selected.
2017-11-28 15:41:51,314 INFO [pool-1-thread-1] namenode.FSImage (FSImage.java:loadFSImageFile(731)) - Planning to load image: FSImageFile(file=/grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/name1/current/fsimage_0000000000000000000, cpktTxId=0000000000000000000)
2017-11-28 15:41:51,331 INFO [pool-1-thread-1] namenode.FSImageFormatPBINode (FSImageFormatPBINode.java:loadINodeSection(257)) - Loading 1 INodes.
2017-11-28 15:41:51,340 INFO [pool-1-thread-1] namenode.FSImageFormatProtobuf (FSImageFormatProtobuf.java:load(184)) - Loaded FSImage in 0 seconds.
2017-11-28 15:41:51,340 INFO [pool-1-thread-1] namenode.FSImage (FSImage.java:loadFSImage(897)) - Loaded image for txid 0 from /grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/name1/current/fsimage_0000000000000000000
2017-11-28 15:41:51,345 INFO [pool-1-thread-1] namenode.FSNamesystem (FSNamesystem.java:loadFSImage(1079)) - Need to save fs image? false (staleImage=false, haEnabled=false, isRollingUpgrade=false)
2017-11-28 15:41:51,345 INFO [pool-1-thread-1] namenode.FSEditLog (FSEditLog.java:startLogSegment(1294)) - Starting log segment at 1
2017-11-28 15:41:51,372 INFO [pool-1-thread-1] namenode.NameCache (NameCache.java:initialized(143)) - initialized with 0 entries 0 lookups
2017-11-28 15:41:51,372 INFO [pool-1-thread-1] namenode.FSNamesystem (FSNamesystem.java:loadFromDisk(730)) - Finished loading FSImage in 68 msecs
2017-11-28 15:41:51,638 INFO [pool-1-thread-1] namenode.NameNode (NameNodeRpcServer.java:<init>(428)) - RPC server is binding to localhost:0
2017-11-28 15:41:51,649 INFO [pool-1-thread-1] ipc.CallQueueManager (CallQueueManager.java:<init>(75)) - Using callQueue: class java.util.concurrent.LinkedBlockingQueue scheduler: class org.apache.hadoop.ipc.DefaultRpcScheduler
2017-11-28 15:41:51,671 INFO [Socket Reader #1 for port 38503] ipc.Server (Server.java:run(821)) - Starting Socket Reader #1 for port 38503
2017-11-28 15:41:51,772 INFO [pool-1-thread-1] namenode.NameNode (NameNode.java:initialize(772)) - Clients are to use localhost:38503 to access this namenode/service.
2017-11-28 15:41:51,774 INFO [pool-1-thread-1] namenode.FSNamesystem (FSNamesystem.java:registerMBean(6509)) - Registered FSNamesystemState MBean
2017-11-28 15:41:51,794 INFO [pool-1-thread-1] namenode.LeaseManager (LeaseManager.java:getNumUnderConstructionBlocks(139)) - Number of blocks under construction: 0
2017-11-28 15:41:51,795 INFO [pool-1-thread-1] namenode.FSNamesystem (FSNamesystem.java:initializeReplQueues(1271)) - initializing replication queues
2017-11-28 15:41:51,795 INFO [pool-1-thread-1] hdfs.StateChange (FSNamesystem.java:leave(5661)) - STATE* Leaving safe mode after 0 secs
2017-11-28 15:41:51,795 INFO [pool-1-thread-1] hdfs.StateChange (FSNamesystem.java:leave(5673)) - STATE* Network topology has 0 racks and 0 datanodes
2017-11-28 15:41:51,795 INFO [pool-1-thread-1] hdfs.StateChange (FSNamesystem.java:leave(5676)) - STATE* UnderReplicatedBlocks has 0 blocks
2017-11-28 15:41:51,806 INFO [pool-1-thread-1] blockmanagement.DatanodeDescriptor (DatanodeDescriptor.java:updateHeartbeatState(401)) - Number of failed storage changes from 0 to 0
2017-11-28 15:41:51,809 INFO [Replication Queue Initializer] blockmanagement.BlockManager (BlockManager.java:processMisReplicatesAsync(2936)) - Total number of blocks = 0
2017-11-28 15:41:51,809 INFO [Replication Queue Initializer] blockmanagement.BlockManager (BlockManager.java:processMisReplicatesAsync(2937)) - Number of invalid blocks = 0
2017-11-28 15:41:51,809 INFO [Replication Queue Initializer] blockmanagement.BlockManager (BlockManager.java:processMisReplicatesAsync(2938)) - Number of under-replicated blocks = 0
2017-11-28 15:41:51,809 INFO [Replication Queue Initializer] blockmanagement.BlockManager (BlockManager.java:processMisReplicatesAsync(2939)) - Number of over-replicated blocks = 0
2017-11-28 15:41:51,809 INFO [Replication Queue Initializer] blockmanagement.BlockManager (BlockManager.java:processMisReplicatesAsync(2941)) - Number of blocks being written = 0
2017-11-28 15:41:51,809 INFO [Replication Queue Initializer] hdfs.StateChange (BlockManager.java:processMisReplicatesAsync(2943)) - STATE* Replication Queue initialization scan for invalid, over- and under-replicated blocks completed in 15 msec
2017-11-28 15:41:51,810 INFO [org.apache.hadoop.hdfs.server.blockmanagement.BlockManager$ReplicationMonitor@23383605] BlockStateChange (BlockManager.java:computeReplicationWorkForBlocks(1653)) - BLOCK* neededReplications = 0, pendingReplications = 0.
2017-11-28 15:41:51,846 INFO [IPC Server listener on 38503] ipc.Server (Server.java:run(900)) - IPC Server listener on 38503: starting
2017-11-28 15:41:51,846 INFO [IPC Server Responder] ipc.Server (Server.java:run(1064)) - IPC Server Responder: starting
2017-11-28 15:41:51,850 INFO [pool-1-thread-1] namenode.NameNode (NameNode.java:startCommonServices(885)) - NameNode RPC up at: localhost/127.0.0.1:38503
2017-11-28 15:41:51,850 WARN [pool-1-thread-1] namenode.NameNode (NameNode.java:makeMetricsLoggerAsync(828)) - Metrics logging will not be async since the logger is not log4j
2017-11-28 15:41:51,851 INFO [pool-1-thread-1] namenode.FSNamesystem (FSNamesystem.java:startActiveServices(1187)) - Starting services required for active state
2017-11-28 15:41:51,851 INFO [pool-1-thread-1] namenode.FSDirectory (FSDirectory.java:updateCountForQuota(708)) - Initializing quota with 4 thread(s)
2017-11-28 15:41:51,855 INFO [pool-1-thread-1] namenode.FSDirectory (FSDirectory.java:updateCountForQuota(717)) - Quota initialization completed in 3 milliseconds
name space=1
storage space=0
storage types=RAM_DISK=0, SSD=0, DISK=0, ARCHIVE=0
2017-11-28 15:41:51,859 INFO [CacheReplicationMonitor(503514335)] blockmanagement.CacheReplicationMonitor (CacheReplicationMonitor.java:run(161)) - Starting CacheReplicationMonitor with interval 30000 milliseconds
2017-11-28 15:41:51,865 INFO [pool-1-thread-1] hdfs.MiniDFSCluster (MiniDFSCluster.java:startDataNodes(1458)) - Starting DataNode 0 with dfs.datanode.data.dir: [DISK]file:/grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data1,[DISK]file:/grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data2
2017-11-28 15:41:52,185 INFO [pool-1-thread-1] checker.ThrottledAsyncChecker (ThrottledAsyncChecker.java:schedule(122)) - Scheduling a check for [DISK]file:/grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data1/
2017-11-28 15:41:52,208 INFO [pool-1-thread-1] checker.ThrottledAsyncChecker (ThrottledAsyncChecker.java:schedule(122)) - Scheduling a check for [DISK]file:/grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data2/
2017-11-28 15:41:52,269 INFO [pool-1-thread-1] impl.MetricsSystemImpl (MetricsSystemImpl.java:init(159)) - DataNode metrics system started (again)
2017-11-28 15:41:52,273 INFO [pool-1-thread-1] datanode.BlockScanner (BlockScanner.java:<init>(180)) - Initialized block scanner with targetBytesPerSec 1048576
2017-11-28 15:41:52,277 INFO [pool-1-thread-1] common.Util (Util.java:isDiskStatsEnabled(111)) - dfs.datanode.fileio.profiling.sampling.percentage set to 0. Disabling file IO profiling
2017-11-28 15:41:52,281 INFO [pool-1-thread-1] datanode.DataNode (DataNode.java:<init>(455)) - Configured hostname is 127.0.0.1
2017-11-28 15:41:52,282 INFO [pool-1-thread-1] common.Util (Util.java:isDiskStatsEnabled(111)) - dfs.datanode.fileio.profiling.sampling.percentage set to 0. Disabling file IO profiling
2017-11-28 15:41:52,282 WARN [pool-1-thread-1] conf.Configuration (Configuration.java:getTimeDurationHelper(1592)) - No unit for dfs.datanode.outliers.report.interval(1800000) assuming MILLISECONDS
2017-11-28 15:41:52,287 INFO [pool-1-thread-1] datanode.DataNode (DataNode.java:startDataNode(1251)) - Starting DataNode with maxLockedMemory = 0
2017-11-28 15:41:52,299 INFO [pool-1-thread-1] datanode.DataNode (DataNode.java:initDataXceiver(1028)) - Opened streaming server at /127.0.0.1:37352
2017-11-28 15:41:52,303 INFO [pool-1-thread-1] datanode.DataNode (DataXceiverServer.java:<init>(78)) - Balancing bandwith is 1048576 bytes/s
2017-11-28 15:41:52,304 INFO [pool-1-thread-1] datanode.DataNode (DataXceiverServer.java:<init>(79)) - Number threads for balancing is 5
2017-11-28 15:41:52,316 INFO [pool-1-thread-1] server.AuthenticationFilter (AuthenticationFilter.java:constructSecretProvider(296)) - Unable to initialize FileSignerSecretProvider, falling back to use random secrets.
2017-11-28 15:41:52,317 WARN [pool-1-thread-1] http.HttpRequestLog (HttpRequestLog.java:getRequestLog(100)) - Jetty request log can only be enabled using Log4j
2017-11-28 15:41:52,318 INFO [pool-1-thread-1] http.HttpServer2 (HttpServer2.java:addGlobalFilter(791)) - Added global filter 'safety' (class=org.apache.hadoop.http.HttpServer2$QuotingInputFilter)
2017-11-28 15:41:52,319 INFO [pool-1-thread-1] http.HttpServer2 (HttpServer2.java:addFilter(766)) - Added filter static_user_filter (class=org.apache.hadoop.http.lib.StaticUserWebFilter$StaticUserFilter) to context datanode
2017-11-28 15:41:52,319 INFO [pool-1-thread-1] http.HttpServer2 (HttpServer2.java:addFilter(774)) - Added filter static_user_filter (class=org.apache.hadoop.http.lib.StaticUserWebFilter$StaticUserFilter) to context logs
2017-11-28 15:41:52,319 INFO [pool-1-thread-1] http.HttpServer2 (HttpServer2.java:addFilter(774)) - Added filter static_user_filter (class=org.apache.hadoop.http.lib.StaticUserWebFilter$StaticUserFilter) to context static
2017-11-28 15:41:52,319 INFO [pool-1-thread-1] security.HttpCrossOriginFilterInitializer (HttpCrossOriginFilterInitializer.java:initFilter(49)) - CORS filter not enabled. Please set hadoop.http.cross-origin.enabled to 'true' to enable it
2017-11-28 15:41:52,326 INFO [pool-1-thread-1] http.HttpServer2 (HttpServer2.java:bindListener(989)) - Jetty bound to port 36342
2017-11-28 15:41:52,326 INFO [pool-1-thread-1] mortbay.log (Slf4jLog.java:info(67)) - jetty-6.1.14
2017-11-28 15:41:52,331 INFO [pool-1-thread-1] mortbay.log (Slf4jLog.java:info(67)) - Extract jar:file:/grid/0/nobody/.m2/repository/org/apache/hadoop/hadoop-hdfs/2.7.3.2.6.4.0-SNAPSHOT/hadoop-hdfs-2.7.3.2.6.4.0-SNAPSHOT-tests.jar!/webapps/datanode to /tmp/Jetty_localhost_36342_datanode____.s94vhn/webapp
2017-11-28 15:41:52,465 INFO [pool-1-thread-1] mortbay.log (Slf4jLog.java:info(67)) - Started HttpServer2$SelectChannelConnectorWithSafeStartup@localhost:36342
2017-11-28 15:41:52,611 INFO [pool-1-thread-1] web.DatanodeHttpServer (DatanodeHttpServer.java:start(233)) - Listening HTTP traffic on /127.0.0.1:38743
2017-11-28 15:41:52,611 INFO [org.apache.hadoop.util.JvmPauseMonitor$Monitor@2f3cec05] util.JvmPauseMonitor (JvmPauseMonitor.java:run(179)) - Starting JVM pause monitor
2017-11-28 15:41:52,613 INFO [pool-1-thread-1] datanode.DataNode (DataNode.java:startDataNode(1277)) - dnUserName = nobody
2017-11-28 15:41:52,613 INFO [pool-1-thread-1] datanode.DataNode (DataNode.java:startDataNode(1278)) - supergroup = supergroup
2017-11-28 15:41:52,632 INFO [pool-1-thread-1] ipc.CallQueueManager (CallQueueManager.java:<init>(75)) - Using callQueue: class java.util.concurrent.LinkedBlockingQueue scheduler: class org.apache.hadoop.ipc.DefaultRpcScheduler
2017-11-28 15:41:52,633 INFO [Socket Reader #1 for port 41421] ipc.Server (Server.java:run(821)) - Starting Socket Reader #1 for port 41421
2017-11-28 15:41:52,647 INFO [pool-1-thread-1] datanode.DataNode (DataNode.java:initIpcServer(941)) - Opened IPC server at /127.0.0.1:41421
2017-11-28 15:41:52,660 INFO [pool-1-thread-1] datanode.DataNode (BlockPoolManager.java:refreshNamenodes(152)) - Refresh request received for nameservices: null
2017-11-28 15:41:52,663 INFO [pool-1-thread-1] datanode.DataNode (BlockPoolManager.java:doRefreshNamenodes(201)) - Starting BPOfferServices for nameservices: <default>
2017-11-28 15:41:52,676 INFO [DataNode: [[[DISK]file:/grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data1/, [DISK]file:/grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data2/]] heartbeating to localhost/127.0.0.1:38503] datanode.DataNode (BPServiceActor.java:run(761)) - Block pool <registering> (Datanode Uuid unassigned) service to localhost/127.0.0.1:38503 starting to offer service
2017-11-28 15:41:52,683 INFO [IPC Server Responder] ipc.Server (Server.java:run(1064)) - IPC Server Responder: starting
2017-11-28 15:41:52,683 INFO [IPC Server listener on 41421] ipc.Server (Server.java:run(900)) - IPC Server listener on 41421: starting
2017-11-28 15:41:52,687 INFO [pool-1-thread-1] hdfs.MiniDFSCluster (MiniDFSCluster.java:startDataNodes(1458)) - Starting DataNode 1 with dfs.datanode.data.dir: [DISK]file:/grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data3,[DISK]file:/grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data4
2017-11-28 15:41:52,688 INFO [pool-1-thread-1] checker.ThrottledAsyncChecker (ThrottledAsyncChecker.java:schedule(122)) - Scheduling a check for [DISK]file:/grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data3/
2017-11-28 15:41:52,689 INFO [pool-1-thread-1] checker.ThrottledAsyncChecker (ThrottledAsyncChecker.java:schedule(122)) - Scheduling a check for [DISK]file:/grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data4/
2017-11-28 15:41:52,705 INFO [pool-1-thread-1] impl.MetricsSystemImpl (MetricsSystemImpl.java:init(159)) - DataNode metrics system started (again)
2017-11-28 15:41:52,705 INFO [pool-1-thread-1] datanode.BlockScanner (BlockScanner.java:<init>(180)) - Initialized block scanner with targetBytesPerSec 1048576
2017-11-28 15:41:52,705 INFO [pool-1-thread-1] common.Util (Util.java:isDiskStatsEnabled(111)) - dfs.datanode.fileio.profiling.sampling.percentage set to 0. Disabling file IO profiling
2017-11-28 15:41:52,706 INFO [pool-1-thread-1] datanode.DataNode (DataNode.java:<init>(455)) - Configured hostname is 127.0.0.1
2017-11-28 15:41:52,706 INFO [pool-1-thread-1] common.Util (Util.java:isDiskStatsEnabled(111)) - dfs.datanode.fileio.profiling.sampling.percentage set to 0. Disabling file IO profiling
2017-11-28 15:41:52,706 WARN [pool-1-thread-1] conf.Configuration (Configuration.java:getTimeDurationHelper(1592)) - No unit for dfs.datanode.outliers.report.interval(1800000) assuming MILLISECONDS
2017-11-28 15:41:52,706 INFO [pool-1-thread-1] datanode.DataNode (DataNode.java:startDataNode(1251)) - Starting DataNode with maxLockedMemory = 0
2017-11-28 15:41:52,707 INFO [pool-1-thread-1] datanode.DataNode (DataNode.java:initDataXceiver(1028)) - Opened streaming server at /127.0.0.1:41272
2017-11-28 15:41:52,707 INFO [pool-1-thread-1] datanode.DataNode (DataXceiverServer.java:<init>(78)) - Balancing bandwith is 1048576 bytes/s
2017-11-28 15:41:52,707 INFO [pool-1-thread-1] datanode.DataNode (DataXceiverServer.java:<init>(79)) - Number threads for balancing is 5
2017-11-28 15:41:52,710 INFO [pool-1-thread-1] server.AuthenticationFilter (AuthenticationFilter.java:constructSecretProvider(296)) - Unable to initialize FileSignerSecretProvider, falling back to use random secrets.
2017-11-28 15:41:52,711 WARN [pool-1-thread-1] http.HttpRequestLog (HttpRequestLog.java:getRequestLog(100)) - Jetty request log can only be enabled using Log4j
2017-11-28 15:41:52,712 INFO [pool-1-thread-1] http.HttpServer2 (HttpServer2.java:addGlobalFilter(791)) - Added global filter 'safety' (class=org.apache.hadoop.http.HttpServer2$QuotingInputFilter)
2017-11-28 15:41:52,713 INFO [pool-1-thread-1] http.HttpServer2 (HttpServer2.java:addFilter(766)) - Added filter static_user_filter (class=org.apache.hadoop.http.lib.StaticUserWebFilter$StaticUserFilter) to context datanode
2017-11-28 15:41:52,713 INFO [pool-1-thread-1] http.HttpServer2 (HttpServer2.java:addFilter(774)) - Added filter static_user_filter (class=org.apache.hadoop.http.lib.StaticUserWebFilter$StaticUserFilter) to context static
2017-11-28 15:41:52,713 INFO [pool-1-thread-1] http.HttpServer2 (HttpServer2.java:addFilter(774)) - Added filter static_user_filter (class=org.apache.hadoop.http.lib.StaticUserWebFilter$StaticUserFilter) to context logs
2017-11-28 15:41:52,713 INFO [pool-1-thread-1] security.HttpCrossOriginFilterInitializer (HttpCrossOriginFilterInitializer.java:initFilter(49)) - CORS filter not enabled. Please set hadoop.http.cross-origin.enabled to 'true' to enable it
2017-11-28 15:41:52,714 INFO [pool-1-thread-1] http.HttpServer2 (HttpServer2.java:bindListener(989)) - Jetty bound to port 44682
2017-11-28 15:41:52,714 INFO [pool-1-thread-1] mortbay.log (Slf4jLog.java:info(67)) - jetty-6.1.14
2017-11-28 15:41:52,719 INFO [pool-1-thread-1] mortbay.log (Slf4jLog.java:info(67)) - Extract jar:file:/grid/0/nobody/.m2/repository/org/apache/hadoop/hadoop-hdfs/2.7.3.2.6.4.0-SNAPSHOT/hadoop-hdfs-2.7.3.2.6.4.0-SNAPSHOT-tests.jar!/webapps/datanode to /tmp/Jetty_localhost_44682_datanode____.inx2i1/webapp
2017-11-28 15:41:52,856 INFO [pool-1-thread-1] mortbay.log (Slf4jLog.java:info(67)) - Started HttpServer2$SelectChannelConnectorWithSafeStartup@localhost:44682
2017-11-28 15:41:52,871 INFO [pool-1-thread-1] web.DatanodeHttpServer (DatanodeHttpServer.java:start(233)) - Listening HTTP traffic on /127.0.0.1:45542
2017-11-28 15:41:52,872 INFO [pool-1-thread-1] datanode.DataNode (DataNode.java:startDataNode(1277)) - dnUserName = nobody
2017-11-28 15:41:52,872 INFO [org.apache.hadoop.util.JvmPauseMonitor$Monitor@376961fa] util.JvmPauseMonitor (JvmPauseMonitor.java:run(179)) - Starting JVM pause monitor
2017-11-28 15:41:52,872 INFO [pool-1-thread-1] datanode.DataNode (DataNode.java:startDataNode(1278)) - supergroup = supergroup
2017-11-28 15:41:52,872 INFO [pool-1-thread-1] ipc.CallQueueManager (CallQueueManager.java:<init>(75)) - Using callQueue: class java.util.concurrent.LinkedBlockingQueue scheduler: class org.apache.hadoop.ipc.DefaultRpcScheduler
2017-11-28 15:41:52,873 INFO [Socket Reader #1 for port 46351] ipc.Server (Server.java:run(821)) - Starting Socket Reader #1 for port 46351
2017-11-28 15:41:52,879 INFO [pool-1-thread-1] datanode.DataNode (DataNode.java:initIpcServer(941)) - Opened IPC server at /127.0.0.1:46351
2017-11-28 15:41:52,882 INFO [pool-1-thread-1] datanode.DataNode (BlockPoolManager.java:refreshNamenodes(152)) - Refresh request received for nameservices: null
2017-11-28 15:41:52,883 INFO [pool-1-thread-1] datanode.DataNode (BlockPoolManager.java:doRefreshNamenodes(201)) - Starting BPOfferServices for nameservices: <default>
2017-11-28 15:41:52,883 INFO [DataNode: [[[DISK]file:/grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data3/, [DISK]file:/grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data4/]] heartbeating to localhost/127.0.0.1:38503] datanode.DataNode (BPServiceActor.java:run(761)) - Block pool <registering> (Datanode Uuid unassigned) service to localhost/127.0.0.1:38503 starting to offer service
2017-11-28 15:41:52,884 INFO [IPC Server listener on 46351] ipc.Server (Server.java:run(900)) - IPC Server listener on 46351: starting
2017-11-28 15:41:52,885 INFO [IPC Server Responder] ipc.Server (Server.java:run(1064)) - IPC Server Responder: starting
2017-11-28 15:41:53,105 INFO [DataNode: [[[DISK]file:/grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data3/, [DISK]file:/grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data4/]] heartbeating to localhost/127.0.0.1:38503] common.Storage (DataStorage.java:getParallelVolumeLoadThreadsNum(384)) - Using 2 threads to upgrade data directories (dfs.datanode.parallel.volumes.load.threads.num=2, dataDirs=2)
2017-11-28 15:41:53,105 INFO [DataNode: [[[DISK]file:/grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data1/, [DISK]file:/grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data2/]] heartbeating to localhost/127.0.0.1:38503] common.Storage (DataStorage.java:getParallelVolumeLoadThreadsNum(384)) - Using 2 threads to upgrade data directories (dfs.datanode.parallel.volumes.load.threads.num=2, dataDirs=2)
2017-11-28 15:41:53,107 INFO [DataNode: [[[DISK]file:/grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data1/, [DISK]file:/grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data2/]] heartbeating to localhost/127.0.0.1:38503] common.Storage (Storage.java:tryLock(776)) - Lock on /grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data1/in_use.lock acquired by nodename 159376@ctr-e134-1499953498516-345856-01-000007.hwx.site
2017-11-28 15:41:53,107 INFO [DataNode: [[[DISK]file:/grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data3/, [DISK]file:/grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data4/]] heartbeating to localhost/127.0.0.1:38503] common.Storage (Storage.java:tryLock(776)) - Lock on /grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data3/in_use.lock acquired by nodename 159376@ctr-e134-1499953498516-345856-01-000007.hwx.site
2017-11-28 15:41:53,108 INFO [DataNode: [[[DISK]file:/grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data1/, [DISK]file:/grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data2/]] heartbeating to localhost/127.0.0.1:38503] common.Storage (DataStorage.java:loadStorageDirectory(309)) - Storage directory /grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data1 is not formatted for namespace 1907606034. Formatting...
2017-11-28 15:41:53,108 INFO [DataNode: [[[DISK]file:/grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data3/, [DISK]file:/grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data4/]] heartbeating to localhost/127.0.0.1:38503] common.Storage (DataStorage.java:loadStorageDirectory(309)) - Storage directory /grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data3 is not formatted for namespace 1907606034. Formatting...
2017-11-28 15:41:53,110 INFO [DataNode: [[[DISK]file:/grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data1/, [DISK]file:/grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data2/]] heartbeating to localhost/127.0.0.1:38503] common.Storage (DataStorage.java:createStorageID(187)) - Generated new storageID DS-f0a27a63-d51e-48b5-aef1-2782ed1194d8 for directory /grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data1
2017-11-28 15:41:53,110 INFO [DataNode: [[[DISK]file:/grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data3/, [DISK]file:/grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data4/]] heartbeating to localhost/127.0.0.1:38503] common.Storage (DataStorage.java:createStorageID(187)) - Generated new storageID DS-207ff42e-e232-4cb0-91e1-6c983d9187b2 for directory /grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data3
2017-11-28 15:41:53,114 INFO [DataNode: [[[DISK]file:/grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data1/, [DISK]file:/grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data2/]] heartbeating to localhost/127.0.0.1:38503] common.Storage (Storage.java:tryLock(776)) - Lock on /grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data2/in_use.lock acquired by nodename 159376@ctr-e134-1499953498516-345856-01-000007.hwx.site
2017-11-28 15:41:53,114 INFO [DataNode: [[[DISK]file:/grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data3/, [DISK]file:/grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data4/]] heartbeating to localhost/127.0.0.1:38503] common.Storage (Storage.java:tryLock(776)) - Lock on /grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data4/in_use.lock acquired by nodename 159376@ctr-e134-1499953498516-345856-01-000007.hwx.site
2017-11-28 15:41:53,115 INFO [DataNode: [[[DISK]file:/grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data1/, [DISK]file:/grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data2/]] heartbeating to localhost/127.0.0.1:38503] common.Storage (DataStorage.java:loadStorageDirectory(309)) - Storage directory /grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data2 is not formatted for namespace 1907606034. Formatting...
2017-11-28 15:41:53,116 INFO [DataNode: [[[DISK]file:/grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data3/, [DISK]file:/grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data4/]] heartbeating to localhost/127.0.0.1:38503] common.Storage (DataStorage.java:loadStorageDirectory(309)) - Storage directory /grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data4 is not formatted for namespace 1907606034. Formatting...
2017-11-28 15:41:53,116 INFO [DataNode: [[[DISK]file:/grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data1/, [DISK]file:/grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/build/test/data/dfs/data/data2/]] heartbeating to localhost/127.0.0.1:38503] common.Storage (DataStorage.java:createStorageID(187)) - Generated new storageID DS-e9f121ff-b694-4e58-abaa-fdf4ac80b386 for directory /grid/0/nobody/workspace/build-support/SOURCES/oozie/
...[truncated 5183895 chars]...
pAttemptImpl:809 - appattempt_1511883728609_0005_000001 State change from LAUNCHED to RUNNING
16:04:00,539 INFO RMAppImpl:779 - application_1511883728609_0005 State change from ACCEPTED to RUNNING
16:04:00,578 INFO FSEditLog:771 - Number of transactions: 7405 Total time for transactions(ms): 205 Number of transactions batched in Syncs: 2919 Number of syncs: 4486 SyncTimes(ms): 235 79
16:04:00,579 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=create src=/tmp/hadoop-yarn/staging/nobody/.staging/job_1511883728609_0005/job_1511883728609_0005_1.jhist dst=null perm=nobody:supergroup:rw-rw-rw- proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:00,659 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=create src=/tmp/hadoop-yarn/staging/nobody/.staging/job_1511883728609_0005/job_1511883728609_0005_1_conf.xml dst=null perm=nobody:supergroup:rw-rw-rw- proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:00,808 INFO StateChange:3862 - BLOCK* allocate blk_1073743269_2445, replicas=127.0.0.1:41272, 127.0.0.1:37352 for /tmp/hadoop-yarn/staging/nobody/.staging/job_1511883728609_0005/job_1511883728609_0005_1_conf.xml
16:04:00,894 INFO DataNode:669 - Receiving BP-1089370620-172.27.58.198-1511883710117:blk_1073743269_2445 src: /127.0.0.1:44658 dest: /127.0.0.1:41272
16:04:00,895 INFO DataNode:669 - Receiving BP-1089370620-172.27.58.198-1511883710117:blk_1073743269_2445 src: /127.0.0.1:51170 dest: /127.0.0.1:37352
16:04:00,938 INFO clienttrace:1490 - src: /127.0.0.1:51170, dest: /127.0.0.1:37352, bytes: 141926, op: HDFS_WRITE, cliID: DFSClient_NONMAPREDUCE_-1622970731_1, offset: 0, srvID: c355628b-02f4-4102-9823-149c581be5bc, blockid: BP-1089370620-172.27.58.198-1511883710117:blk_1073743269_2445, duration: 41616333
16:04:00,938 INFO DataNode:1463 - PacketResponder: BP-1089370620-172.27.58.198-1511883710117:blk_1073743269_2445, type=LAST_IN_PIPELINE terminating
16:04:00,939 INFO clienttrace:1490 - src: /127.0.0.1:44658, dest: /127.0.0.1:41272, bytes: 141926, op: HDFS_WRITE, cliID: DFSClient_NONMAPREDUCE_-1622970731_1, offset: 0, srvID: 47252ceb-afae-4640-acde-3a2b425713b6, blockid: BP-1089370620-172.27.58.198-1511883710117:blk_1073743269_2445, duration: 42980160
16:04:00,939 INFO DataNode:1463 - PacketResponder: BP-1089370620-172.27.58.198-1511883710117:blk_1073743269_2445, type=HAS_DOWNSTREAM_IN_PIPELINE, downstreams=1:[127.0.0.1:37352] terminating
16:04:00,944 INFO StateChange:3755 - DIR* completeFile: /tmp/hadoop-yarn/staging/nobody/.staging/job_1511883728609_0005/job_1511883728609_0005_1_conf.xml is closed by DFSClient_NONMAPREDUCE_-1622970731_1
16:04:01,039 INFO BlockManager:1660 - Blocks chosen but could not be replicated = 1; of which 1 have no target, 0 have no source, 0 are UC, 0 are abandoned, 0 already have enough replicas.
16:04:02,077 INFO RMContainerImpl:422 - container_1511883728609_0005_01_000002 Container Transitioned from NEW to ALLOCATED
16:04:02,077 INFO RMAuditLogger:141 - USER=nobody OPERATION=AM Allocated Container TARGET=SchedulerApp RESULT=SUCCESS APPID=application_1511883728609_0005 CONTAINERID=container_1511883728609_0005_01_000002
16:04:02,077 INFO SchedulerNode:152 - Assigned container container_1511883728609_0005_01_000002 of capacity <memory:1024, vCores:1> on host ctr-e134-1499953498516-345856-01-000007.hwx.site:43216, which has 1 containers, <memory:1024, vCores:1> used and <memory:3072, vCores:7> available after allocation
16:04:02,077 INFO AbstractContainerAllocator:89 - assignedContainer application attempt=appattempt_1511883728609_0005_000001 container=container_1511883728609_0005_01_000002 queue=org.apache.hadoop.yarn.server.resourcemanager.scheduler.capacity.allocator.RegularContainerAllocator@7a8629b9 clusterResource=<memory:8192, vCores:16> type=OFF_SWITCH
16:04:02,078 INFO ParentQueue:475 - assignedContainer queue=root usedCapacity=0.375 absoluteUsedCapacity=0.375 used=<memory:3072, vCores:2> cluster=<memory:8192, vCores:16>
16:04:02,612 INFO NMTokenSecretManagerInRM:200 - Sending NMToken for nodeId : ctr-e134-1499953498516-345856-01-000007.hwx.site:43216 for container : container_1511883728609_0005_01_000002
16:04:02,613 INFO RMContainerImpl:422 - container_1511883728609_0005_01_000002 Container Transitioned from ALLOCATED to ACQUIRED
16:04:02,693 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/tmp/hadoop-yarn/staging/nobody/.staging/job_1511883728609_0005/job.xml dst=null perm=null proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:02,694 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/tmp/hadoop-yarn/staging/nobody/.staging/job_1511883728609_0005/job.xml dst=null perm=null proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:02,714 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/nobody/target/MiniMRCluster_900807203-tmpDir/MRAppJar.jar dst=null perm=null proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:02,716 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/nobody/target/MiniMRCluster_900807203-tmpDir/hadoop-mapreduce-client-jobclient-2.7.3.2.6.4.0-SNAPSHOT-tests.jar dst=null perm=null proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:02,718 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/test/649db0c8-4d79-4881-9a59-c3dbdd439c30/app/lib/other.zip dst=null perm=null proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:02,719 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/test/649db0c8-4d79-4881-9a59-c3dbdd439c30/app/lib/myfunctions.py dst=null perm=null proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:02,720 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/test/649db0c8-4d79-4881-9a59-c3dbdd439c30/app/lib/py4j-0.9-src.zip dst=null perm=null proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:02,722 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/test/649db0c8-4d79-4881-9a59-c3dbdd439c30/app/lib/pyspark.zip dst=null perm=null proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:02,723 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/test/649db0c8-4d79-4881-9a59-c3dbdd439c30/app/lib/pi.py dst=null perm=null proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:02,762 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/nobody/target/MiniMRCluster_900807203-tmpDir/MRAppJar.jar dst=null perm=null proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:02,763 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/nobody/target/MiniMRCluster_900807203-tmpDir/hadoop-mapreduce-client-jobclient-2.7.3.2.6.4.0-SNAPSHOT-tests.jar dst=null perm=null proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:02,764 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/test/649db0c8-4d79-4881-9a59-c3dbdd439c30/app/lib/other.zip dst=null perm=null proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:02,765 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/test/649db0c8-4d79-4881-9a59-c3dbdd439c30/app/lib/myfunctions.py dst=null perm=null proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:02,766 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/test/649db0c8-4d79-4881-9a59-c3dbdd439c30/app/lib/py4j-0.9-src.zip dst=null perm=null proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:02,768 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/test/649db0c8-4d79-4881-9a59-c3dbdd439c30/app/lib/pyspark.zip dst=null perm=null proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:02,769 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/test/649db0c8-4d79-4881-9a59-c3dbdd439c30/app/lib/pi.py dst=null perm=null proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:02,770 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/nobody/target/MiniMRCluster_900807203-tmpDir/MRAppJar.jar dst=null perm=null proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:02,771 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/nobody/target/MiniMRCluster_900807203-tmpDir/hadoop-mapreduce-client-jobclient-2.7.3.2.6.4.0-SNAPSHOT-tests.jar dst=null perm=null proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:02,772 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/nobody/target/MiniMRCluster_900807203-tmpDir/MRAppJar.jar dst=null perm=null proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:02,773 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/nobody/target/MiniMRCluster_900807203-tmpDir/hadoop-mapreduce-client-jobclient-2.7.3.2.6.4.0-SNAPSHOT-tests.jar dst=null perm=null proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:02,774 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/test/649db0c8-4d79-4881-9a59-c3dbdd439c30/app/lib/other.zip dst=null perm=null proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:02,775 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/test/649db0c8-4d79-4881-9a59-c3dbdd439c30/app/lib/myfunctions.py dst=null perm=null proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:02,777 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/test/649db0c8-4d79-4881-9a59-c3dbdd439c30/app/lib/py4j-0.9-src.zip dst=null perm=null proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:02,779 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/test/649db0c8-4d79-4881-9a59-c3dbdd439c30/app/lib/pyspark.zip dst=null perm=null proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:02,780 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/test/649db0c8-4d79-4881-9a59-c3dbdd439c30/app/lib/pi.py dst=null perm=null proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:02,781 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/nobody/target/MiniMRCluster_900807203-tmpDir/MRAppJar.jar dst=null perm=null proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:02,782 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/nobody/target/MiniMRCluster_900807203-tmpDir/hadoop-mapreduce-client-jobclient-2.7.3.2.6.4.0-SNAPSHOT-tests.jar dst=null perm=null proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:02,901 INFO ContainerManagerImpl:810 - Start request for container_1511883728609_0005_01_000002 by user nobody
16:04:02,903 INFO ContainerManagerImpl:850 - Creating a new application reference for app application_1511883728609_0005
16:04:02,904 INFO NMAuditLogger:89 - USER=nobody IP=172.27.58.198 OPERATION=Start Container Request TARGET=ContainerManageImpl RESULT=SUCCESS APPID=application_1511883728609_0005 CONTAINERID=container_1511883728609_0005_01_000002
16:04:02,904 INFO ApplicationImpl:464 - Application application_1511883728609_0005 transitioned from NEW to INITING
16:04:02,904 INFO ApplicationImpl:304 - Adding container_1511883728609_0005_01_000002 to application application_1511883728609_0005
16:04:02,904 INFO ApplicationImpl:464 - Application application_1511883728609_0005 transitioned from INITING to RUNNING
16:04:02,905 INFO ContainerImpl:1163 - Container container_1511883728609_0005_01_000002 transitioned from NEW to LOCALIZING
16:04:02,905 INFO AuxServices:215 - Got event CONTAINER_INIT for appId application_1511883728609_0005
16:04:02,905 INFO AuxServices:215 - Got event APPLICATION_INIT for appId application_1511883728609_0005
16:04:02,905 INFO AuxServices:219 - Got APPLICATION_INIT for service mapreduce_shuffle
16:04:02,905 INFO ShuffleHandler:681 - Added token for job_1511883728609_0005
16:04:02,905 INFO LocalizedResource:203 - Resource hdfs://localhost:38503/user/test/649db0c8-4d79-4881-9a59-c3dbdd439c30/app/lib/pyspark.zip transitioned from INIT to DOWNLOADING
16:04:02,905 INFO LocalizedResource:203 - Resource hdfs://localhost:38503/user/test/649db0c8-4d79-4881-9a59-c3dbdd439c30/app/lib/pi.py transitioned from INIT to DOWNLOADING
16:04:02,905 INFO LocalizedResource:203 - Resource hdfs://localhost:38503/user/test/649db0c8-4d79-4881-9a59-c3dbdd439c30/app/lib/py4j-0.9-src.zip transitioned from INIT to DOWNLOADING
16:04:02,906 INFO LocalizedResource:203 - Resource hdfs://localhost:38503/tmp/hadoop-yarn/staging/nobody/.staging/job_1511883728609_0005/job.xml transitioned from INIT to DOWNLOADING
16:04:02,906 INFO ResourceLocalizationService:784 - Downloading public rsrc:{ hdfs://localhost:38503/user/test/649db0c8-4d79-4881-9a59-c3dbdd439c30/app/lib/pyspark.zip, 1511885030140, FILE, null }
16:04:02,989 INFO ResourceLocalizationService:784 - Downloading public rsrc:{ hdfs://localhost:38503/user/test/649db0c8-4d79-4881-9a59-c3dbdd439c30/app/lib/pi.py, 1511885030145, FILE, null }
16:04:03,017 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/test/649db0c8-4d79-4881-9a59-c3dbdd439c30/app/lib/pyspark.zip dst=null perm=null proto=rpc
16:04:03,018 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/test/649db0c8-4d79-4881-9a59-c3dbdd439c30/app/lib dst=null perm=null proto=rpc
16:04:03,019 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/test/649db0c8-4d79-4881-9a59-c3dbdd439c30/app dst=null perm=null proto=rpc
16:04:03,019 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/test/649db0c8-4d79-4881-9a59-c3dbdd439c30 dst=null perm=null proto=rpc
16:04:03,020 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/test dst=null perm=null proto=rpc
16:04:03,020 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user dst=null perm=null proto=rpc
16:04:03,021 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/ dst=null perm=null proto=rpc
16:04:03,022 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=open src=/user/test/649db0c8-4d79-4881-9a59-c3dbdd439c30/app/lib/pyspark.zip dst=null perm=null proto=rpc
16:04:03,072 INFO LocalizedResource:203 - Resource hdfs://localhost:38503/user/test/649db0c8-4d79-4881-9a59-c3dbdd439c30/app/lib/pyspark.zip(->/grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/target/MiniMRCluster_900807203/MiniMRCluster_900807203-localDir-nm-0_0/filecache/18/pyspark.zip) transitioned from DOWNLOADING to LOCALIZED
16:04:03,073 INFO ResourceLocalizationService:784 - Downloading public rsrc:{ hdfs://localhost:38503/user/test/649db0c8-4d79-4881-9a59-c3dbdd439c30/app/lib/py4j-0.9-src.zip, 1511885030130, FILE, null }
16:04:03,076 INFO RMContainerImpl:422 - container_1511883728609_0005_01_000002 Container Transitioned from ACQUIRED to RUNNING
16:04:03,101 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/test/649db0c8-4d79-4881-9a59-c3dbdd439c30/app/lib/pi.py dst=null perm=null proto=rpc
16:04:03,102 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=open src=/user/test/649db0c8-4d79-4881-9a59-c3dbdd439c30/app/lib/pi.py dst=null perm=null proto=rpc
16:04:03,149 INFO LocalizedResource:203 - Resource hdfs://localhost:38503/user/test/649db0c8-4d79-4881-9a59-c3dbdd439c30/app/lib/pi.py(->/grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/target/MiniMRCluster_900807203/MiniMRCluster_900807203-localDir-nm-0_3/filecache/19/pi.py) transitioned from DOWNLOADING to LOCALIZED
16:04:03,155 INFO ResourceLocalizationService:712 - Created localizer for container_1511883728609_0005_01_000002
16:04:03,171 INFO ResourceLocalizationService:1194 - Writing credentials to the nmPrivate file /grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/target/MiniMRCluster_900807203/MiniMRCluster_900807203-localDir-nm-0_1/nmPrivate/container_1511883728609_0005_01_000002.tokens. Credentials list:
16:04:03,183 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/test/649db0c8-4d79-4881-9a59-c3dbdd439c30/app/lib/py4j-0.9-src.zip dst=null perm=null proto=rpc
16:04:03,184 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=open src=/user/test/649db0c8-4d79-4881-9a59-c3dbdd439c30/app/lib/py4j-0.9-src.zip dst=null perm=null proto=rpc
16:04:03,229 INFO LocalizedResource:203 - Resource hdfs://localhost:38503/user/test/649db0c8-4d79-4881-9a59-c3dbdd439c30/app/lib/py4j-0.9-src.zip(->/grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/target/MiniMRCluster_900807203/MiniMRCluster_900807203-localDir-nm-0_3/filecache/20/py4j-0.9-src.zip) transitioned from DOWNLOADING to LOCALIZED
16:04:03,248 INFO DefaultContainerExecutor:644 - Initializing user nobody
16:04:03,299 INFO DefaultContainerExecutor:126 - Copying from /grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/target/MiniMRCluster_900807203/MiniMRCluster_900807203-localDir-nm-0_1/nmPrivate/container_1511883728609_0005_01_000002.tokens to /grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/target/MiniMRCluster_900807203/MiniMRCluster_900807203-localDir-nm-0_1/usercache/nobody/appcache/application_1511883728609_0005/container_1511883728609_0005_01_000002.tokens
16:04:03,300 INFO DefaultContainerExecutor:133 - Localizer CWD set to /grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/target/MiniMRCluster_900807203/MiniMRCluster_900807203-localDir-nm-0_1/usercache/nobody/appcache/application_1511883728609_0005 = file:/grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/target/MiniMRCluster_900807203/MiniMRCluster_900807203-localDir-nm-0_1/usercache/nobody/appcache/application_1511883728609_0005
16:04:03,384 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/tmp/hadoop-yarn/staging/nobody/.staging/job_1511883728609_0005/job.xml dst=null perm=null proto=rpc
16:04:03,386 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=open src=/tmp/hadoop-yarn/staging/nobody/.staging/job_1511883728609_0005/job.xml dst=null perm=null proto=rpc
16:04:03,424 INFO LocalizedResource:203 - Resource hdfs://localhost:38503/tmp/hadoop-yarn/staging/nobody/.staging/job_1511883728609_0005/job.xml(->/grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/target/MiniMRCluster_900807203/MiniMRCluster_900807203-localDir-nm-0_1/usercache/nobody/appcache/application_1511883728609_0005/filecache/10/job.xml) transitioned from DOWNLOADING to LOCALIZED
16:04:03,424 INFO ContainerImpl:1163 - Container container_1511883728609_0005_01_000002 transitioned from LOCALIZING to LOCALIZED
16:04:03,474 INFO ContainerImpl:1163 - Container container_1511883728609_0005_01_000002 transitioned from LOCALIZED to RUNNING
16:04:03,474 INFO ContainersMonitorImpl:222 - Neither virutal-memory nor physical-memory monitoring is needed. Not running the monitor-thread
16:04:03,570 INFO DefaultContainerExecutor:291 - launchContainer: [bash, /grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/target/MiniMRCluster_900807203/MiniMRCluster_900807203-localDir-nm-0_1/usercache/nobody/appcache/application_1511883728609_0005/container_1511883728609_0005_01_000002/default_container_executor.sh]
16:04:03,635 INFO AppSchedulingInfo:220 - checking for deactivate of application :application_1511883728609_0005
16:04:04,039 INFO BlockManager:1660 - Blocks chosen but could not be replicated = 1; of which 1 have no target, 0 have no source, 0 are UC, 0 are abandoned, 0 already have enough replicas.
16:04:06,823 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=open src=/tmp/hadoop-yarn/staging/nobody/.staging/job_1511883728609_0005/job.split dst=null perm=null proto=rpc callerContext=mr_attempt_1511883728609_0005_m_000000_0
16:04:07,001 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/test/oozie-nobo/0000003-171128160232232-oozie-nobo-W/spark-action--spark/0000003-171128160232232-oozie-nobo-W@spark-action dst=null perm=null proto=rpc callerContext=mr_attempt_1511883728609_0005_m_000000_0
16:04:07,020 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=create src=/user/test/oozie-nobo/0000003-171128160232232-oozie-nobo-W/spark-action--spark/0000003-171128160232232-oozie-nobo-W@spark-action dst=null perm=nobody:supergroup:rw-rw-rw- proto=rpc callerContext=mr_attempt_1511883728609_0005_m_000000_0
16:04:07,040 INFO BlockManager:1660 - Blocks chosen but could not be replicated = 1; of which 1 have no target, 0 have no source, 0 are UC, 0 are abandoned, 0 already have enough replicas.
16:04:07,056 INFO StateChange:3862 - BLOCK* allocate blk_1073743270_2446, replicas=127.0.0.1:41272, 127.0.0.1:37352 for /user/test/oozie-nobo/0000003-171128160232232-oozie-nobo-W/spark-action--spark/0000003-171128160232232-oozie-nobo-W@spark-action
16:04:07,129 INFO DataNode:669 - Receiving BP-1089370620-172.27.58.198-1511883710117:blk_1073743270_2446 src: /127.0.0.1:44760 dest: /127.0.0.1:41272
16:04:07,131 INFO DataNode:669 - Receiving BP-1089370620-172.27.58.198-1511883710117:blk_1073743270_2446 src: /127.0.0.1:51272 dest: /127.0.0.1:37352
16:04:07,170 INFO clienttrace:1490 - src: /127.0.0.1:51272, dest: /127.0.0.1:37352, bytes: 22, op: HDFS_WRITE, cliID: DFSClient_attempt_1511883728609_0005_m_000000_0_1423302170_1, offset: 0, srvID: c355628b-02f4-4102-9823-149c581be5bc, blockid: BP-1089370620-172.27.58.198-1511883710117:blk_1073743270_2446, duration: 38575862
16:04:07,170 INFO DataNode:1463 - PacketResponder: BP-1089370620-172.27.58.198-1511883710117:blk_1073743270_2446, type=LAST_IN_PIPELINE terminating
16:04:07,171 INFO clienttrace:1490 - src: /127.0.0.1:44760, dest: /127.0.0.1:41272, bytes: 22, op: HDFS_WRITE, cliID: DFSClient_attempt_1511883728609_0005_m_000000_0_1423302170_1, offset: 0, srvID: 47252ceb-afae-4640-acde-3a2b425713b6, blockid: BP-1089370620-172.27.58.198-1511883710117:blk_1073743270_2446, duration: 39157631
16:04:07,171 INFO DataNode:1463 - PacketResponder: BP-1089370620-172.27.58.198-1511883710117:blk_1073743270_2446, type=HAS_DOWNSTREAM_IN_PIPELINE, downstreams=1:[127.0.0.1:37352] terminating
16:04:07,174 INFO StateChange:3755 - DIR* completeFile: /user/test/oozie-nobo/0000003-171128160232232-oozie-nobo-W/spark-action--spark/0000003-171128160232232-oozie-nobo-W@spark-action is closed by DFSClient_attempt_1511883728609_0005_m_000000_0_1423302170_1
16:04:07,190 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/test/oozie-nobo/0000003-171128160232232-oozie-nobo-W/spark-action--spark/action.xml dst=null perm=null proto=rpc callerContext=mr_attempt_1511883728609_0005_m_000000_0
16:04:07,192 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=open src=/user/test/oozie-nobo/0000003-171128160232232-oozie-nobo-W/spark-action--spark/action.xml dst=null perm=null proto=rpc callerContext=mr_attempt_1511883728609_0005_m_000000_0
16:04:10,040 INFO BlockManager:1660 - Blocks chosen but could not be replicated = 1; of which 1 have no target, 0 have no source, 0 are UC, 0 are abandoned, 0 already have enough replicas.
16:04:13,041 INFO BlockManager:1660 - Blocks chosen but could not be replicated = 1; of which 1 have no target, 0 have no source, 0 are UC, 0 are abandoned, 0 already have enough replicas.
16:04:16,042 INFO BlockManager:1660 - Blocks chosen but could not be replicated = 1; of which 1 have no target, 0 have no source, 0 are UC, 0 are abandoned, 0 already have enough replicas.
16:04:16,092 INFO ContainerManagerImpl:960 - Stopping container with container Id: container_1511883728609_0005_01_000002
16:04:16,092 INFO NMAuditLogger:89 - USER=nobody IP=172.27.58.198 OPERATION=Stop Container Request TARGET=ContainerManageImpl RESULT=SUCCESS APPID=application_1511883728609_0005 CONTAINERID=container_1511883728609_0005_01_000002
16:04:16,092 INFO ContainerImpl:1163 - Container container_1511883728609_0005_01_000002 transitioned from RUNNING to KILLING
16:04:16,092 INFO ContainerLaunch:541 - Cleaning up container container_1511883728609_0005_01_000002
16:04:16,111 WARN DefaultContainerExecutor:249 - Exit code from container container_1511883728609_0005_01_000002 is : 143
16:04:16,115 INFO StateChange:3862 - BLOCK* allocate blk_1073743271_2447, replicas=127.0.0.1:37352, 127.0.0.1:41272 for /tmp/hadoop-yarn/staging/nobody/.staging/job_1511883728609_0005/job_1511883728609_0005_1.jhist
16:04:16,119 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=create src=/tmp/hadoop-yarn/staging/nobody/.staging/job_1511883728609_0005/COMMIT_STARTED dst=null perm=nobody:supergroup:rw-rw-rw- proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:16,120 INFO DataNode:669 - Receiving BP-1089370620-172.27.58.198-1511883710117:blk_1073743271_2447 src: /127.0.0.1:51420 dest: /127.0.0.1:37352
16:04:16,120 INFO StateChange:3755 - DIR* completeFile: /tmp/hadoop-yarn/staging/nobody/.staging/job_1511883728609_0005/COMMIT_STARTED is closed by DFSClient_NONMAPREDUCE_-1622970731_1
16:04:16,121 INFO DataNode:669 - Receiving BP-1089370620-172.27.58.198-1511883710117:blk_1073743271_2447 src: /127.0.0.1:44914 dest: /127.0.0.1:41272
16:04:16,122 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=create src=/tmp/hadoop-yarn/staging/nobody/.staging/job_1511883728609_0005/COMMIT_SUCCESS dst=null perm=nobody:supergroup:rw-rw-rw- proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:16,124 INFO StateChange:3755 - DIR* completeFile: /tmp/hadoop-yarn/staging/nobody/.staging/job_1511883728609_0005/COMMIT_SUCCESS is closed by DFSClient_NONMAPREDUCE_-1622970731_1
16:04:16,127 INFO StateChange:4299 - BLOCK* fsync: /tmp/hadoop-yarn/staging/nobody/.staging/job_1511883728609_0005/job_1511883728609_0005_1.jhist for DFSClient_NONMAPREDUCE_-1622970731_1
16:04:16,137 INFO ContainerImpl:1163 - Container container_1511883728609_0005_01_000002 transitioned from KILLING to CONTAINER_CLEANEDUP_AFTER_KILL
16:04:16,138 INFO DefaultContainerExecutor:492 - Deleting absolute path : /grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/target/MiniMRCluster_900807203/MiniMRCluster_900807203-localDir-nm-0_0/usercache/nobody/appcache/application_1511883728609_0005/container_1511883728609_0005_01_000002
16:04:16,139 INFO DefaultContainerExecutor:492 - Deleting absolute path : /grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/target/MiniMRCluster_900807203/MiniMRCluster_900807203-localDir-nm-0_1/usercache/nobody/appcache/application_1511883728609_0005/container_1511883728609_0005_01_000002
16:04:16,141 INFO DefaultContainerExecutor:492 - Deleting absolute path : /grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/target/MiniMRCluster_900807203/MiniMRCluster_900807203-localDir-nm-0_2/usercache/nobody/appcache/application_1511883728609_0005/container_1511883728609_0005_01_000002
16:04:16,142 INFO DefaultContainerExecutor:492 - Deleting absolute path : /grid/0/nobody/workspace/build-support/SOURCES/oozie/sharelib/spark/target/MiniMRCluster_900807203/MiniMRCluster_900807203-localDir-nm-0_3/usercache/nobody/appcache/application_1511883728609_0005/container_1511883728609_0005_01_000002
16:04:16,142 INFO NMAuditLogger:89 - USER=nobody OPERATION=Container Finished - Killed TARGET=ContainerImpl RESULT=SUCCESS APPID=application_1511883728609_0005 CONTAINERID=container_1511883728609_0005_01_000002
16:04:16,144 INFO ContainerImpl:1163 - Container container_1511883728609_0005_01_000002 transitioned from CONTAINER_CLEANEDUP_AFTER_KILL to DONE
16:04:16,144 INFO ApplicationImpl:347 - Removing container_1511883728609_0005_01_000002 from application application_1511883728609_0005
16:04:16,144 INFO ContainersMonitorImpl:222 - Neither virutal-memory nor physical-memory monitoring is needed. Not running the monitor-thread
16:04:16,145 INFO AuxServices:215 - Got event CONTAINER_STOP for appId application_1511883728609_0005
16:04:16,145 INFO RMContainerImpl:422 - container_1511883728609_0005_01_000002 Container Transitioned from RUNNING to COMPLETED
16:04:16,145 INFO RMAuditLogger:141 - USER=nobody OPERATION=AM Released Container TARGET=SchedulerApp RESULT=SUCCESS APPID=application_1511883728609_0005 CONTAINERID=container_1511883728609_0005_01_000002
16:04:16,145 INFO SchedulerNode:220 - Released container container_1511883728609_0005_01_000002 of capacity <memory:1024, vCores:1> on host ctr-e134-1499953498516-345856-01-000007.hwx.site:43216, which currently has 0 containers, <memory:0, vCores:0> used and <memory:4096, vCores:8> available, release resources=true
16:04:16,153 INFO clienttrace:1490 - src: /127.0.0.1:44914, dest: /127.0.0.1:41272, bytes: 21320, op: HDFS_WRITE, cliID: DFSClient_NONMAPREDUCE_-1622970731_1, offset: 0, srvID: 47252ceb-afae-4640-acde-3a2b425713b6, blockid: BP-1089370620-172.27.58.198-1511883710117:blk_1073743271_2447, duration: 30652455
16:04:16,153 INFO DataNode:1463 - PacketResponder: BP-1089370620-172.27.58.198-1511883710117:blk_1073743271_2447, type=LAST_IN_PIPELINE terminating
16:04:16,155 INFO clienttrace:1490 - src: /127.0.0.1:51420, dest: /127.0.0.1:37352, bytes: 21320, op: HDFS_WRITE, cliID: DFSClient_NONMAPREDUCE_-1622970731_1, offset: 0, srvID: c355628b-02f4-4102-9823-149c581be5bc, blockid: BP-1089370620-172.27.58.198-1511883710117:blk_1073743271_2447, duration: 32389529
16:04:16,155 INFO DataNode:1463 - PacketResponder: BP-1089370620-172.27.58.198-1511883710117:blk_1073743271_2447, type=HAS_DOWNSTREAM_IN_PIPELINE, downstreams=1:[127.0.0.1:41272] terminating
16:04:16,156 INFO StateChange:3755 - DIR* completeFile: /tmp/hadoop-yarn/staging/nobody/.staging/job_1511883728609_0005/job_1511883728609_0005_1.jhist is closed by DFSClient_NONMAPREDUCE_-1622970731_1
16:04:16,158 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=create src=/tmp/hadoop-yarn/staging/history/done_intermediate/nobody/job_1511883728609_0005.summary_tmp dst=null perm=nobody:supergroup:rw-rw-rw- proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:16,161 INFO StateChange:3862 - BLOCK* allocate blk_1073743272_2448, replicas=127.0.0.1:37352, 127.0.0.1:41272 for /tmp/hadoop-yarn/staging/history/done_intermediate/nobody/job_1511883728609_0005.summary_tmp
16:04:16,163 INFO DataNode:669 - Receiving BP-1089370620-172.27.58.198-1511883710117:blk_1073743272_2448 src: /127.0.0.1:51426 dest: /127.0.0.1:37352
16:04:16,164 INFO DataNode:669 - Receiving BP-1089370620-172.27.58.198-1511883710117:blk_1073743272_2448 src: /127.0.0.1:44920 dest: /127.0.0.1:41272
16:04:16,167 INFO clienttrace:1490 - src: /127.0.0.1:44920, dest: /127.0.0.1:41272, bytes: 416, op: HDFS_WRITE, cliID: DFSClient_NONMAPREDUCE_-1622970731_1, offset: 0, srvID: 47252ceb-afae-4640-acde-3a2b425713b6, blockid: BP-1089370620-172.27.58.198-1511883710117:blk_1073743272_2448, duration: 2041105
16:04:16,167 INFO DataNode:1463 - PacketResponder: BP-1089370620-172.27.58.198-1511883710117:blk_1073743272_2448, type=LAST_IN_PIPELINE terminating
16:04:16,167 INFO clienttrace:1490 - src: /127.0.0.1:51426, dest: /127.0.0.1:37352, bytes: 416, op: HDFS_WRITE, cliID: DFSClient_NONMAPREDUCE_-1622970731_1, offset: 0, srvID: c355628b-02f4-4102-9823-149c581be5bc, blockid: BP-1089370620-172.27.58.198-1511883710117:blk_1073743272_2448, duration: 2401053
16:04:16,168 INFO DataNode:1463 - PacketResponder: BP-1089370620-172.27.58.198-1511883710117:blk_1073743272_2448, type=HAS_DOWNSTREAM_IN_PIPELINE, downstreams=1:[127.0.0.1:41272] terminating
16:04:16,168 INFO StateChange:3755 - DIR* completeFile: /tmp/hadoop-yarn/staging/history/done_intermediate/nobody/job_1511883728609_0005.summary_tmp is closed by DFSClient_NONMAPREDUCE_-1622970731_1
16:04:16,174 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=setPermission src=/tmp/hadoop-yarn/staging/history/done_intermediate/nobody/job_1511883728609_0005.summary_tmp dst=null perm=nobody:supergroup:rwxrwx--- proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:16,183 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/tmp/hadoop-yarn/staging/nobody/.staging/job_1511883728609_0005/job_1511883728609_0005_1.jhist dst=null perm=null proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:16,184 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/tmp/hadoop-yarn/staging/history/done_intermediate/nobody/job_1511883728609_0005-1511885033094-nobody-oozie%3Alauncher%3AT%3Dspark%3AW%3DtestApp%3AA%3Ds-1511885056125-1-0-SUCCEEDED-default-1511885040566.jhist_tmp dst=null perm=null proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:16,189 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/tmp/hadoop-yarn/staging/nobody/.staging/job_1511883728609_0005/job_1511883728609_0005_1.jhist dst=null perm=null proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:16,191 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/tmp/hadoop-yarn/staging/history/done_intermediate/nobody/job_1511883728609_0005-1511885033094-nobody-oozie%3Alauncher%3AT%3Dspark%3AW%3DtestApp%3AA%3Ds-1511885056125-1-0-SUCCEEDED-default-1511885040566.jhist_tmp dst=null perm=null proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:16,192 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=open src=/tmp/hadoop-yarn/staging/nobody/.staging/job_1511883728609_0005/job_1511883728609_0005_1.jhist dst=null perm=null proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:16,194 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=create src=/tmp/hadoop-yarn/staging/history/done_intermediate/nobody/job_1511883728609_0005-1511885033094-nobody-oozie%3Alauncher%3AT%3Dspark%3AW%3DtestApp%3AA%3Ds-1511885056125-1-0-SUCCEEDED-default-1511885040566.jhist_tmp dst=null perm=nobody:supergroup:rw-rw-rw- proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:16,199 INFO StateChange:3862 - BLOCK* allocate blk_1073743273_2449, replicas=127.0.0.1:41272, 127.0.0.1:37352 for /tmp/hadoop-yarn/staging/history/done_intermediate/nobody/job_1511883728609_0005-1511885033094-nobody-oozie%3Alauncher%3AT%3Dspark%3AW%3DtestApp%3AA%3Ds-1511885056125-1-0-SUCCEEDED-default-1511885040566.jhist_tmp
16:04:16,201 INFO DataNode:669 - Receiving BP-1089370620-172.27.58.198-1511883710117:blk_1073743273_2449 src: /127.0.0.1:44924 dest: /127.0.0.1:41272
16:04:16,202 INFO DataNode:669 - Receiving BP-1089370620-172.27.58.198-1511883710117:blk_1073743273_2449 src: /127.0.0.1:51434 dest: /127.0.0.1:37352
16:04:16,205 INFO clienttrace:1490 - src: /127.0.0.1:51434, dest: /127.0.0.1:37352, bytes: 21320, op: HDFS_WRITE, cliID: DFSClient_NONMAPREDUCE_-1622970731_1, offset: 0, srvID: c355628b-02f4-4102-9823-149c581be5bc, blockid: BP-1089370620-172.27.58.198-1511883710117:blk_1073743273_2449, duration: 2115381
16:04:16,205 INFO DataNode:1463 - PacketResponder: BP-1089370620-172.27.58.198-1511883710117:blk_1073743273_2449, type=LAST_IN_PIPELINE terminating
16:04:16,205 INFO clienttrace:1490 - src: /127.0.0.1:44924, dest: /127.0.0.1:41272, bytes: 21320, op: HDFS_WRITE, cliID: DFSClient_NONMAPREDUCE_-1622970731_1, offset: 0, srvID: 47252ceb-afae-4640-acde-3a2b425713b6, blockid: BP-1089370620-172.27.58.198-1511883710117:blk_1073743273_2449, duration: 2464775
16:04:16,205 INFO DataNode:1463 - PacketResponder: BP-1089370620-172.27.58.198-1511883710117:blk_1073743273_2449, type=HAS_DOWNSTREAM_IN_PIPELINE, downstreams=1:[127.0.0.1:37352] terminating
16:04:16,206 INFO StateChange:3755 - DIR* completeFile: /tmp/hadoop-yarn/staging/history/done_intermediate/nobody/job_1511883728609_0005-1511885033094-nobody-oozie%3Alauncher%3AT%3Dspark%3AW%3DtestApp%3AA%3Ds-1511885056125-1-0-SUCCEEDED-default-1511885040566.jhist_tmp is closed by DFSClient_NONMAPREDUCE_-1622970731_1
16:04:16,207 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=setPermission src=/tmp/hadoop-yarn/staging/history/done_intermediate/nobody/job_1511883728609_0005-1511885033094-nobody-oozie%3Alauncher%3AT%3Dspark%3AW%3DtestApp%3AA%3Ds-1511885056125-1-0-SUCCEEDED-default-1511885040566.jhist_tmp dst=null perm=nobody:supergroup:rwxrwx--- proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:16,208 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/tmp/hadoop-yarn/staging/nobody/.staging/job_1511883728609_0005/job_1511883728609_0005_1_conf.xml dst=null perm=null proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:16,209 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/tmp/hadoop-yarn/staging/history/done_intermediate/nobody/job_1511883728609_0005_conf.xml_tmp dst=null perm=null proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:16,210 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/tmp/hadoop-yarn/staging/nobody/.staging/job_1511883728609_0005/job_1511883728609_0005_1_conf.xml dst=null perm=null proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:16,210 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/tmp/hadoop-yarn/staging/history/done_intermediate/nobody/job_1511883728609_0005_conf.xml_tmp dst=null perm=null proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:16,212 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=open src=/tmp/hadoop-yarn/staging/nobody/.staging/job_1511883728609_0005/job_1511883728609_0005_1_conf.xml dst=null perm=null proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:16,213 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=create src=/tmp/hadoop-yarn/staging/history/done_intermediate/nobody/job_1511883728609_0005_conf.xml_tmp dst=null perm=nobody:supergroup:rw-rw-rw- proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:16,218 INFO StateChange:3862 - BLOCK* allocate blk_1073743274_2450, replicas=127.0.0.1:41272, 127.0.0.1:37352 for /tmp/hadoop-yarn/staging/history/done_intermediate/nobody/job_1511883728609_0005_conf.xml_tmp
16:04:16,219 INFO DataNode:669 - Receiving BP-1089370620-172.27.58.198-1511883710117:blk_1073743274_2450 src: /127.0.0.1:44928 dest: /127.0.0.1:41272
16:04:16,220 INFO DataNode:669 - Receiving BP-1089370620-172.27.58.198-1511883710117:blk_1073743274_2450 src: /127.0.0.1:51438 dest: /127.0.0.1:37352
16:04:16,224 INFO clienttrace:1490 - src: /127.0.0.1:51438, dest: /127.0.0.1:37352, bytes: 141926, op: HDFS_WRITE, cliID: DFSClient_NONMAPREDUCE_-1622970731_1, offset: 0, srvID: c355628b-02f4-4102-9823-149c581be5bc, blockid: BP-1089370620-172.27.58.198-1511883710117:blk_1073743274_2450, duration: 4058119
16:04:16,225 INFO DataNode:1463 - PacketResponder: BP-1089370620-172.27.58.198-1511883710117:blk_1073743274_2450, type=LAST_IN_PIPELINE terminating
16:04:16,225 INFO clienttrace:1490 - src: /127.0.0.1:44928, dest: /127.0.0.1:41272, bytes: 141926, op: HDFS_WRITE, cliID: DFSClient_NONMAPREDUCE_-1622970731_1, offset: 0, srvID: 47252ceb-afae-4640-acde-3a2b425713b6, blockid: BP-1089370620-172.27.58.198-1511883710117:blk_1073743274_2450, duration: 4303796
16:04:16,225 INFO DataNode:1463 - PacketResponder: BP-1089370620-172.27.58.198-1511883710117:blk_1073743274_2450, type=HAS_DOWNSTREAM_IN_PIPELINE, downstreams=1:[127.0.0.1:37352] terminating
16:04:16,226 INFO StateChange:3755 - DIR* completeFile: /tmp/hadoop-yarn/staging/history/done_intermediate/nobody/job_1511883728609_0005_conf.xml_tmp is closed by DFSClient_NONMAPREDUCE_-1622970731_1
16:04:16,229 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=setPermission src=/tmp/hadoop-yarn/staging/history/done_intermediate/nobody/job_1511883728609_0005_conf.xml_tmp dst=null perm=nobody:supergroup:rwxrwx--- proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:16,234 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=rename src=/tmp/hadoop-yarn/staging/history/done_intermediate/nobody/job_1511883728609_0005.summary_tmp dst=/tmp/hadoop-yarn/staging/history/done_intermediate/nobody/job_1511883728609_0005.summary perm=nobody:supergroup:rwxrwx--- proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:16,241 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=rename src=/tmp/hadoop-yarn/staging/history/done_intermediate/nobody/job_1511883728609_0005_conf.xml_tmp dst=/tmp/hadoop-yarn/staging/history/done_intermediate/nobody/job_1511883728609_0005_conf.xml perm=nobody:supergroup:rwxrwx--- proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:16,243 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=rename src=/tmp/hadoop-yarn/staging/history/done_intermediate/nobody/job_1511883728609_0005-1511885033094-nobody-oozie%3Alauncher%3AT%3Dspark%3AW%3DtestApp%3AA%3Ds-1511885056125-1-0-SUCCEEDED-default-1511885040566.jhist_tmp dst=/tmp/hadoop-yarn/staging/history/done_intermediate/nobody/job_1511883728609_0005-1511885033094-nobody-oozie%3Alauncher%3AT%3Dspark%3AW%3DtestApp%3AA%3Ds-1511885056125-1-0-SUCCEEDED-default-1511885040566.jhist perm=nobody:supergroup:rwxrwx--- proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:16,258 INFO RMAppAttemptImpl:1209 - Updating application attempt appattempt_1511883728609_0005_000001 with final state: FINISHING, and exit status: -1000
16:04:16,259 INFO RMAppAttemptImpl:809 - appattempt_1511883728609_0005_000001 State change from RUNNING to FINAL_SAVING
16:04:16,259 INFO RMAppImpl:1124 - Updating application application_1511883728609_0005 with final state: FINISHING
16:04:16,259 INFO RMAppImpl:779 - application_1511883728609_0005 State change from RUNNING to FINAL_SAVING
16:04:16,259 INFO RMStateStore:228 - Updating info for app: application_1511883728609_0005
16:04:16,259 INFO RMAppAttemptImpl:809 - appattempt_1511883728609_0005_000001 State change from FINAL_SAVING to FINISHING
16:04:16,259 INFO RMAppImpl:779 - application_1511883728609_0005 State change from FINAL_SAVING to FINISHING
16:04:17,263 INFO ApplicationMasterService:360 - application_1511883728609_0005 unregistered successfully.
16:04:17,271 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=delete src=/tmp/hadoop-yarn/staging/nobody/.staging/job_1511883728609_0005 dst=null perm=null proto=rpc callerContext=mr_appmaster_appattempt_1511883728609_0005_000001
16:04:17,326 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=listStatus src=/tmp/hadoop-yarn/staging/history/done_intermediate dst=null perm=null proto=rpc
16:04:17,328 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=listStatus src=/tmp/hadoop-yarn/staging/history/done_intermediate/nobody dst=null perm=null proto=rpc
16:04:17,330 INFO CompletedJob:95 - Loading job: job_1511883728609_0005 from file: hdfs://localhost:38503/tmp/hadoop-yarn/staging/history/done_intermediate/nobody/job_1511883728609_0005-1511885033094-nobody-oozie%3Alauncher%3AT%3Dspark%3AW%3DtestApp%3AA%3Ds-1511885056125-1-0-SUCCEEDED-default-1511885040566.jhist
16:04:17,330 INFO CompletedJob:336 - Loading history file: [hdfs://localhost:38503/tmp/hadoop-yarn/staging/history/done_intermediate/nobody/job_1511883728609_0005-1511885033094-nobody-oozie%3Alauncher%3AT%3Dspark%3AW%3DtestApp%3AA%3Ds-1511885056125-1-0-SUCCEEDED-default-1511885040566.jhist]
16:04:17,331 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=open src=/tmp/hadoop-yarn/staging/history/done_intermediate/nobody/job_1511883728609_0005-1511885033094-nobody-oozie%3Alauncher%3AT%3Dspark%3AW%3DtestApp%3AA%3Ds-1511885056125-1-0-SUCCEEDED-default-1511885040566.jhist dst=null perm=null proto=rpc
16:04:17,343 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/tmp/hadoop-yarn/staging/history/done_intermediate/nobody/job_1511883728609_0005.summary dst=null perm=null proto=rpc
16:04:17,344 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=open src=/tmp/hadoop-yarn/staging/history/done_intermediate/nobody/job_1511883728609_0005.summary dst=null perm=null proto=rpc
16:04:17,346 INFO JobSummary:421 - jobId=job_1511883728609_0005,submitTime=1511885033094,launchTime=1511885040566,firstMapTaskLaunchTime=1511885042919,firstReduceTaskLaunchTime=0,finishTime=1511885056125,resourcesPerMap=1024,resourcesPerReduce=0,numMaps=1,numReduces=0,user=nobody,queue=default,status=SUCCEEDED,mapSlotSeconds=13,reduceSlotSeconds=0,jobName=oozie:launcher:T\=spark:W\=testApp:A\=spark-action:ID\=0000003-171128160232232-oozie-nobo-W
16:04:17,346 INFO HistoryFileManager:422 - Deleting JobSummary file: [hdfs://localhost:38503/tmp/hadoop-yarn/staging/history/done_intermediate/nobody/job_1511883728609_0005.summary]
16:04:17,347 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=delete src=/tmp/hadoop-yarn/staging/history/done_intermediate/nobody/job_1511883728609_0005.summary dst=null perm=null proto=rpc
16:04:17,349 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/tmp/hadoop-yarn/staging/history/done/2017/11/28/000000 dst=null perm=null proto=rpc
16:04:17,350 INFO HistoryFileManager:1015 - Moving hdfs://localhost:38503/tmp/hadoop-yarn/staging/history/done_intermediate/nobody/job_1511883728609_0005-1511885033094-nobody-oozie%3Alauncher%3AT%3Dspark%3AW%3DtestApp%3AA%3Ds-1511885056125-1-0-SUCCEEDED-default-1511885040566.jhist to hdfs://localhost:38503/tmp/hadoop-yarn/staging/history/done/2017/11/28/000000/job_1511883728609_0005-1511885033094-nobody-oozie%3Alauncher%3AT%3Dspark%3AW%3DtestApp%3AA%3Ds-1511885056125-1-0-SUCCEEDED-default-1511885040566.jhist
16:04:17,351 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=rename (options=[TO_TRASH]) src=/tmp/hadoop-yarn/staging/history/done_intermediate/nobody/job_1511883728609_0005-1511885033094-nobody-oozie%3Alauncher%3AT%3Dspark%3AW%3DtestApp%3AA%3Ds-1511885056125-1-0-SUCCEEDED-default-1511885040566.jhist dst=/tmp/hadoop-yarn/staging/history/done/2017/11/28/000000/job_1511883728609_0005-1511885033094-nobody-oozie%3Alauncher%3AT%3Dspark%3AW%3DtestApp%3AA%3Ds-1511885056125-1-0-SUCCEEDED-default-1511885040566.jhist perm=nobody:supergroup:rwxrwx--- proto=rpc
16:04:17,351 INFO HistoryFileManager:1015 - Moving hdfs://localhost:38503/tmp/hadoop-yarn/staging/history/done_intermediate/nobody/job_1511883728609_0005_conf.xml to hdfs://localhost:38503/tmp/hadoop-yarn/staging/history/done/2017/11/28/000000/job_1511883728609_0005_conf.xml
16:04:17,352 INFO audit:8930 - allowed=true ugi=nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=rename (options=[TO_TRASH]) src=/tmp/hadoop-yarn/staging/history/done_intermediate/nobody/job_1511883728609_0005_conf.xml dst=/tmp/hadoop-yarn/staging/history/done/2017/11/28/000000/job_1511883728609_0005_conf.xml perm=nobody:supergroup:rwxrwx--- proto=rpc
16:04:17,383 INFO audit:8930 - allowed=true ugi=test (auth:PROXY) via nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/test/oozie-nobo/0000003-171128160232232-oozie-nobo-W/spark-action--spark/action-data.seq dst=null perm=null proto=rpc
16:04:17,384 INFO audit:8930 - allowed=true ugi=test (auth:PROXY) via nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=listStatus src=/user/test/oozie-nobo/0000003-171128160232232-oozie-nobo-W/spark-action--spark dst=null perm=null proto=rpc
16:04:17,398 INFO audit:8930 - allowed=true ugi=test (auth:PROXY) via nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo src=/user/test/oozie-nobo/0000003-171128160232232-oozie-nobo-W/spark-action--spark dst=null perm=null proto=rpc
16:04:17,399 INFO audit:8930 - allowed=true ugi=test (auth:PROXY) via nobody (auth:SIMPLE) ip=/127.0.0.1 cmd=delete src=/user/test/oozie-nobo/0000003-171128160232232-oozie-nobo-W/spark-action--spark dst=null perm=null proto=rpc
Standard Error
Nov 28, 2017 3:42:06 PM com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory register
INFO: Registering org.apache.hadoop.mapreduce.v2.hs.webapp.HsWebServices as a root resource class
Nov 28, 2017 3:42:06 PM com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory register
INFO: Registering org.apache.hadoop.mapreduce.v2.hs.webapp.JAXBContextResolver as a provider class
Nov 28, 2017 3:42:06 PM com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory register
INFO: Registering org.apache.hadoop.yarn.webapp.GenericExceptionHandler as a provider class
Nov 28, 2017 3:42:06 PM com.sun.jersey.server.impl.application.WebApplicationImpl _initiate
INFO: Initiating Jersey application, version 'Jersey: 1.9 09/02/2011 11:17 AM'
Nov 28, 2017 3:42:06 PM com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory getComponentProvider
INFO: Binding org.apache.hadoop.mapreduce.v2.hs.webapp.JAXBContextResolver to GuiceManagedComponentProvider with the scope "Singleton"
Nov 28, 2017 3:42:06 PM com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory getComponentProvider
INFO: Binding org.apache.hadoop.yarn.webapp.GenericExceptionHandler to GuiceManagedComponentProvider with the scope "Singleton"
Nov 28, 2017 3:42:07 PM com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory getComponentProvider
INFO: Binding org.apache.hadoop.mapreduce.v2.hs.webapp.HsWebServices to GuiceManagedComponentProvider with the scope "PerRequest"
Nov 28, 2017 3:42:08 PM com.google.inject.servlet.GuiceFilter setPipeline
WARNING: Multiple Servlet injectors detected. This is a warning indicating that you have more than one GuiceFilter running in your web application. If this is deliberate, you may safely ignore this message. If this is NOT deliberate however, your application may not work as expected.
Nov 28, 2017 3:42:09 PM com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory register
INFO: Registering org.apache.hadoop.yarn.server.resourcemanager.webapp.JAXBContextResolver as a provider class
Nov 28, 2017 3:42:09 PM com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory register
INFO: Registering org.apache.hadoop.yarn.server.resourcemanager.webapp.RMWebServices as a root resource class
Nov 28, 2017 3:42:09 PM com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory register
INFO: Registering org.apache.hadoop.yarn.webapp.GenericExceptionHandler as a provider class
Nov 28, 2017 3:42:09 PM com.sun.jersey.server.impl.application.WebApplicationImpl _initiate
INFO: Initiating Jersey application, version 'Jersey: 1.9 09/02/2011 11:17 AM'
Nov 28, 2017 3:42:09 PM com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory getComponentProvider
INFO: Binding org.apache.hadoop.yarn.server.resourcemanager.webapp.JAXBContextResolver to GuiceManagedComponentProvider with the scope "Singleton"
Nov 28, 2017 3:42:09 PM com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory getComponentProvider
INFO: Binding org.apache.hadoop.yarn.webapp.GenericExceptionHandler to GuiceManagedComponentProvider with the scope "Singleton"
Nov 28, 2017 3:42:09 PM com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory getComponentProvider
INFO: Binding org.apache.hadoop.yarn.server.resourcemanager.webapp.RMWebServices to GuiceManagedComponentProvider with the scope "Singleton"
Nov 28, 2017 3:42:09 PM com.google.inject.servlet.GuiceFilter setPipeline
WARNING: Multiple Servlet injectors detected. This is a warning indicating that you have more than one GuiceFilter running in your web application. If this is deliberate, you may safely ignore this message. If this is NOT deliberate however, your application may not work as expected.
Nov 28, 2017 3:42:09 PM com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory register
INFO: Registering org.apache.hadoop.yarn.server.nodemanager.webapp.NMWebServices as a root resource class
Nov 28, 2017 3:42:09 PM com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory register
INFO: Registering org.apache.hadoop.yarn.webapp.GenericExceptionHandler as a provider class
Nov 28, 2017 3:42:09 PM com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory register
INFO: Registering org.apache.hadoop.yarn.server.nodemanager.webapp.JAXBContextResolver as a provider class
Nov 28, 2017 3:42:09 PM com.sun.jersey.server.impl.application.WebApplicationImpl _initiate
INFO: Initiating Jersey application, version 'Jersey: 1.9 09/02/2011 11:17 AM'
Nov 28, 2017 3:42:09 PM com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory getComponentProvider
INFO: Binding org.apache.hadoop.yarn.server.nodemanager.webapp.JAXBContextResolver to GuiceManagedComponentProvider with the scope "Singleton"
Nov 28, 2017 3:42:09 PM com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory getComponentProvider
INFO: Binding org.apache.hadoop.yarn.webapp.GenericExceptionHandler to GuiceManagedComponentProvider with the scope "Singleton"
Nov 28, 2017 3:42:10 PM com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory getComponentProvider
INFO: Binding org.apache.hadoop.yarn.server.nodemanager.webapp.NMWebServices to GuiceManagedComponentProvider with the scope "Singleton"
Nov 28, 2017 3:42:10 PM com.google.inject.servlet.GuiceFilter setPipeline
WARNING: Multiple Servlet injectors detected. This is a warning indicating that you have more than one GuiceFilter running in your web application. If this is deliberate, you may safely ignore this message. If this is NOT deliberate however, your application may not work as expected.
Nov 28, 2017 3:42:10 PM com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory register
INFO: Registering org.apache.hadoop.yarn.server.nodemanager.webapp.NMWebServices as a root resource class
Nov 28, 2017 3:42:10 PM com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory register
INFO: Registering org.apache.hadoop.yarn.webapp.GenericExceptionHandler as a provider class
Nov 28, 2017 3:42:10 PM com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory register
INFO: Registering org.apache.hadoop.yarn.server.nodemanager.webapp.JAXBContextResolver as a provider class
Nov 28, 2017 3:42:10 PM com.sun.jersey.server.impl.application.WebApplicationImpl _initiate
INFO: Initiating Jersey application, version 'Jersey: 1.9 09/02/2011 11:17 AM'
Nov 28, 2017 3:42:10 PM com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory getComponentProvider
INFO: Binding org.apache.hadoop.yarn.server.nodemanager.webapp.JAXBContextResolver to GuiceManagedComponentProvider with the scope "Singleton"
Nov 28, 2017 3:42:10 PM com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory getComponentProvider
INFO: Binding org.apache.hadoop.yarn.webapp.GenericExceptionHandler to GuiceManagedComponentProvider with the scope "Singleton"
Nov 28, 2017 3:42:10 PM com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory getComponentProvider
INFO: Binding org.apache.hadoop.yarn.server.nodemanager.webapp.NMWebServices to GuiceManagedComponentProvider with the scope "Singleton"
MetaException(message:javax.jdo.JDOFatalUserException: There is no available StoreManager of type "rdbms". Make sure that you have put the relevant DataNucleus store plugin in your CLASSPATH and if defining a connection via JNDI or DataSource you also need to provide persistence property "datanucleus.storeManagerType"
at org.datanucleus.api.jdo.NucleusJDOHelper.getJDOExceptionForNucleusException(NucleusJDOHelper.java:616)
at org.datanucleus.api.jdo.JDOPersistenceManagerFactory.freezeConfiguration(JDOPersistenceManagerFactory.java:834)
at org.datanucleus.api.jdo.JDOPersistenceManagerFactory.createPersistenceManagerFactory(JDOPersistenceManagerFactory.java:338)
at org.datanucleus.api.jdo.JDOPersistenceManagerFactory.getPersistenceManagerFactory(JDOPersistenceManagerFactory.java:217)
at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at javax.jdo.JDOHelper$16.run(JDOHelper.java:1975)
at java.security.AccessController.doPrivileged(Native Method)
at javax.jdo.JDOHelper.invoke(JDOHelper.java:1970)
at javax.jdo.JDOHelper.invokeGetPersistenceManagerFactoryOnImplementation(JDOHelper.java:1177)
at javax.jdo.JDOHelper.getPersistenceManagerFactory(JDOHelper.java:814)
at javax.jdo.JDOHelper.getPersistenceManagerFactory(JDOHelper.java:702)
at org.apache.hadoop.hive.metastore.ObjectStore.getPMF(ObjectStore.java:495)
at org.apache.hadoop.hive.metastore.ObjectStore.getPersistenceManager(ObjectStore.java:524)
at org.apache.hadoop.hive.metastore.ObjectStore.initializeHelper(ObjectStore.java:385)
at org.apache.hadoop.hive.metastore.ObjectStore.initialize(ObjectStore.java:322)
at org.apache.hadoop.hive.metastore.ObjectStore.setConf(ObjectStore.java:283)
at org.apache.hadoop.util.ReflectionUtils.setConf(ReflectionUtils.java:76)
at org.apache.hadoop.util.ReflectionUtils.newInstance(ReflectionUtils.java:136)
at org.apache.hadoop.hive.metastore.RawStoreProxy.<init>(RawStoreProxy.java:60)
at org.apache.hadoop.hive.metastore.RawStoreProxy.getProxy(RawStoreProxy.java:69)
at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.newRawStoreForConf(HiveMetaStore.java:620)
at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.getMSForConf(HiveMetaStore.java:599)
at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.getMS(HiveMetaStore.java:593)
at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.createDefaultDB(HiveMetaStore.java:651)
at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.init(HiveMetaStore.java:433)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.apache.hadoop.hive.metastore.RetryingHMSHandler.invokeInternal(RetryingHMSHandler.java:147)
at org.apache.hadoop.hive.metastore.RetryingHMSHandler.invoke(RetryingHMSHandler.java:105)
at org.apache.hadoop.hive.metastore.RetryingHMSHandler.<init>(RetryingHMSHandler.java:78)
at org.apache.hadoop.hive.metastore.RetryingHMSHandler.getProxy(RetryingHMSHandler.java:91)
at org.apache.hadoop.hive.metastore.HiveMetaStore.newRetryingHMSHandler(HiveMetaStore.java:6396)
at org.apache.hadoop.hive.metastore.HiveMetaStore.newRetryingHMSHandler(HiveMetaStore.java:6391)
at org.apache.hadoop.hive.metastore.HiveMetaStore.startMetaStore(HiveMetaStore.java:6658)
at org.apache.hadoop.hive.metastore.HiveMetaStore.startMetaStore(HiveMetaStore.java:6606)
at org.apache.oozie.test.MiniHCatServer$1.run(MiniHCatServer.java:141)
at java.lang.Thread.run(Thread.java:745)
NestedThrowablesStackTrace:
There is no available StoreManager of type "rdbms". Make sure that you have put the relevant DataNucleus store plugin in your CLASSPATH and if defining a connection via JNDI or DataSource you also need to provide persistence property "datanucleus.storeManagerType"
org.datanucleus.exceptions.NucleusUserException: There is no available StoreManager of type "rdbms". Make sure that you have put the relevant DataNucleus store plugin in your CLASSPATH and if defining a connection via JNDI or DataSource you also need to provide persistence property "datanucleus.storeManagerType"
at org.datanucleus.NucleusContextHelper.createStoreManagerForProperties(NucleusContextHelper.java:162)
at org.datanucleus.PersistenceNucleusContextImpl.initialise(PersistenceNucleusContextImpl.java:420)
at org.datanucleus.api.jdo.JDOPersistenceManagerFactory.freezeConfiguration(JDOPersistenceManagerFactory.java:821)
at org.datanucleus.api.jdo.JDOPersistenceManagerFactory.createPersistenceManagerFactory(JDOPersistenceManagerFactory.java:338)
at org.datanucleus.api.jdo.JDOPersistenceManagerFactory.getPersistenceManagerFactory(JDOPersistenceManagerFactory.java:217)
at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at javax.jdo.JDOHelper$16.run(JDOHelper.java:1975)
at java.security.AccessController.doPrivileged(Native Method)
at javax.jdo.JDOHelper.invoke(JDOHelper.java:1970)
at javax.jdo.JDOHelper.invokeGetPersistenceManagerFactoryOnImplementation(JDOHelper.java:1177)
at javax.jdo.JDOHelper.getPersistenceManagerFactory(JDOHelper.java:814)
at javax.jdo.JDOHelper.getPersistenceManagerFactory(JDOHelper.java:702)
at org.apache.hadoop.hive.metastore.ObjectStore.getPMF(ObjectStore.java:495)
at org.apache.hadoop.hive.metastore.ObjectStore.getPersistenceManager(ObjectStore.java:524)
at org.apache.hadoop.hive.metastore.ObjectStore.initializeHelper(ObjectStore.java:385)
at org.apache.hadoop.hive.metastore.ObjectStore.initialize(ObjectStore.java:322)
at org.apache.hadoop.hive.metastore.ObjectStore.setConf(ObjectStore.java:283)
at org.apache.hadoop.util.ReflectionUtils.setConf(ReflectionUtils.java:76)
at org.apache.hadoop.util.ReflectionUtils.newInstance(ReflectionUtils.java:136)
at org.apache.hadoop.hive.metastore.RawStoreProxy.<init>(RawStoreProxy.java:60)
at org.apache.hadoop.hive.metastore.RawStoreProxy.getProxy(RawStoreProxy.java:69)
at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.newRawStoreForConf(HiveMetaStore.java:620)
at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.getMSForConf(HiveMetaStore.java:599)
at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.getMS(HiveMetaStore.java:593)
at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.createDefaultDB(HiveMetaStore.java:651)
at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.init(HiveMetaStore.java:433)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.apache.hadoop.hive.metastore.RetryingHMSHandler.invokeInternal(RetryingHMSHandler.java:147)
at org.apache.hadoop.hive.metastore.RetryingHMSHandler.invoke(RetryingHMSHandler.java:105)
at org.apache.hadoop.hive.metastore.RetryingHMSHandler.<init>(RetryingHMSHandler.java:78)
at org.apache.hadoop.hive.metastore.RetryingHMSHandler.getProxy(RetryingHMSHandler.java:91)
at org.apache.hadoop.hive.metastore.HiveMetaStore.newRetryingHMSHandler(HiveMetaStore.java:6396)
at org.apache.hadoop.hive.metastore.HiveMetaStore.newRetryingHMSHandler(HiveMetaStore.java:6391)
at org.apache.hadoop.hive.metastore.HiveMetaStore.startMetaStore(HiveMetaStore.java:6658)
at org.apache.hadoop.hive.metastore.HiveMetaStore.startMetaStore(HiveMetaStore.java:6606)
at org.apache.oozie.test.MiniHCatServer$1.run(MiniHCatServer.java:141)
at java.lang.Thread.run(Thread.java:745)
) at org.apache.hadoop.hive.metastore.RetryingHMSHandler.<init>(RetryingHMSHandler.java:82) at org.apache.hadoop.hive.metastore.RetryingHMSHandler.getProxy(RetryingHMSHandler.java:91) at org.apache.hadoop.hive.metastore.HiveMetaStore.newRetryingHMSHandler(HiveMetaStore.java:6396) at org.apache.hadoop.hive.metastore.HiveMetaStore.newRetryingHMSHandler(HiveMetaStore.java:6391) at org.apache.hadoop.hive.metastore.HiveMetaStore.startMetaStore(HiveMetaStore.java:6658) at org.apache.hadoop.hive.metastore.HiveMetaStore.startMetaStore(HiveMetaStore.java:6606) at org.apache.oozie.test.MiniHCatServer$1.run(MiniHCatServer.java:141) at java.lang.Thread.run(Thread.java:745)Caused by: MetaException(message:javax.jdo.JDOFatalUserException: There is no available StoreManager of type "rdbms". Make sure that you have put the relevant DataNucleus store plugin in your CLASSPATH and if defining a connection via JNDI or DataSource you also need to provide persistence property "datanucleus.storeManagerType"
at org.datanucleus.api.jdo.NucleusJDOHelper.getJDOExceptionForNucleusException(NucleusJDOHelper.java:616)
at org.datanucleus.api.jdo.JDOPersistenceManagerFactory.freezeConfiguration(JDOPersistenceManagerFactory.java:834)
at org.datanucleus.api.jdo.JDOPersistenceManagerFactory.createPersistenceManagerFactory(JDOPersistenceManagerFactory.java:338)
at org.datanucleus.api.jdo.JDOPersistenceManagerFactory.getPersistenceManagerFactory(JDOPersistenceManagerFactory.java:217)
at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at javax.jdo.JDOHelper$16.run(JDOHelper.java:1975)
at java.security.AccessController.doPrivileged(Native Method)
at javax.jdo.JDOHelper.invoke(JDOHelper.java:1970)
at javax.jdo.JDOHelper.invokeGetPersistenceManagerFactoryOnImplementation(JDOHelper.java:1177)
at javax.jdo.JDOHelper.getPersistenceManagerFactory(JDOHelper.java:814)
at javax.jdo.JDOHelper.getPersistenceManagerFactory(JDOHelper.java:702)
at org.apache.hadoop.hive.metastore.ObjectStore.getPMF(ObjectStore.java:495)
at org.apache.hadoop.hive.metastore.ObjectStore.getPersistenceManager(ObjectStore.java:524)
at org.apache.hadoop.hive.metastore.ObjectStore.initializeHelper(ObjectStore.java:385)
at org.apache.hadoop.hive.metastore.ObjectStore.initialize(ObjectStore.java:322)
at org.apache.hadoop.hive.metastore.ObjectStore.setConf(ObjectStore.java:283)
at org.apache.hadoop.util.ReflectionUtils.setConf(ReflectionUtils.java:76)
at org.apache.hadoop.util.ReflectionUtils.newInstance(ReflectionUtils.java:136)
at org.apache.hadoop.hive.metastore.RawStoreProxy.<init>(RawStoreProxy.java:60)
at org.apache.hadoop.hive.metastore.RawStoreProxy.getProxy(RawStoreProxy.java:69)
at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.newRawStoreForConf(HiveMetaStore.java:620)
at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.getMSForConf(HiveMetaStore.java:599)
at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.getMS(HiveMetaStore.java:593)
at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.createDefaultDB(HiveMetaStore.java:651)
at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.init(HiveMetaStore.java:433)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.apache.hadoop.hive.metastore.RetryingHMSHandler.invokeInternal(RetryingHMSHandler.java:147)
at org.apache.hadoop.hive.metastore.RetryingHMSHandler.invoke(RetryingHMSHandler.java:105)
at org.apache.hadoop.hive.metastore.RetryingHMSHandler.<init>(RetryingHMSHandler.java:78)
at org.apache.hadoop.hive.metastore.RetryingHMSHandler.getProxy(RetryingHMSHandler.java:91)
at org.apache.hadoop.hive.metastore.HiveMetaStore.newRetryingHMSHandler(HiveMetaStore.java:6396)
at org.apache.hadoop.hive.metastore.HiveMetaStore.newRetryingHMSHandler(HiveMetaStore.java:6391)
at org.apache.hadoop.hive.metastore.HiveMetaStore.startMetaStore(HiveMetaStore.java:6658)
at org.apache.hadoop.hive.metastore.HiveMetaStore.startMetaStore(HiveMetaStore.java:6606)
at org.apache.oozie.test.MiniHCatServer$1.run(MiniHCatServer.java:141)
at java.lang.Thread.run(Thread.java:745)
NestedThrowablesStackTrace:
There is no available StoreManager of type "rdbms". Make sure that you have put the relevant DataNucleus store plugin in your CLASSPATH and if defining a connection via JNDI or DataSource you also need to provide persistence property "datanucleus.storeManagerType"
org.datanucleus.exceptions.NucleusUserException: There is no available StoreManager of type "rdbms". Make sure that you have put the relevant DataNucleus store plugin in your CLASSPATH and if defining a connection via JNDI or DataSource you also need to provide persistence property "datanucleus.storeManagerType"
at org.datanucleus.NucleusContextHelper.createStoreManagerForProperties(NucleusContextHelper.java:162)
at org.datanucleus.PersistenceNucleusContextImpl.initialise(PersistenceNucleusContextImpl.java:420)
at org.datanucleus.api.jdo.JDOPersistenceManagerFactory.freezeConfiguration(JDOPersistenceManagerFactory.java:821)
at org.datanucleus.api.jdo.JDOPersistenceManagerFactory.createPersistenceManagerFactory(JDOPersistenceManagerFactory.java:338)
at org.datanucleus.api.jdo.JDOPersistenceManagerFactory.getPersistenceManagerFactory(JDOPersistenceManagerFactory.java:217)
at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at javax.jdo.JDOHelper$16.run(JDOHelper.java:1975)
at java.security.AccessController.doPrivileged(Native Method)
at javax.jdo.JDOHelper.invoke(JDOHelper.java:1970)
at javax.jdo.JDOHelper.invokeGetPersistenceManagerFactoryOnImplementation(JDOHelper.java:1177)
at javax.jdo.JDOHelper.getPersistenceManagerFactory(JDOHelper.java:814)
at javax.jdo.JDOHelper.getPersistenceManagerFactory(JDOHelper.java:702)
at org.apache.hadoop.hive.metastore.ObjectStore.getPMF(ObjectStore.java:495)
at org.apache.hadoop.hive.metastore.ObjectStore.getPersistenceManager(ObjectStore.java:524)
at org.apache.hadoop.hive.metastore.ObjectStore.initializeHelper(ObjectStore.java:385)
at org.apache.hadoop.hive.metastore.ObjectStore.initialize(ObjectStore.java:322)
at org.apache.hadoop.hive.metastore.ObjectStore.setConf(ObjectStore.java:283)
at org.apache.hadoop.util.ReflectionUtils.setConf(ReflectionUtils.java:76)
at org.apache.hadoop.util.ReflectionUtils.newInstance(ReflectionUtils.java:136)
at org.apache.hadoop.hive.metastore.RawStoreProxy.<init>(RawStoreProxy.java:60)
at org.apache.hadoop.hive.metastore.RawStoreProxy.getProxy(RawStoreProxy.java:69)
at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.newRawStoreForConf(HiveMetaStore.java:620)
at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.getMSForConf(HiveMetaStore.java:599)
at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.getMS(HiveMetaStore.java:593)
at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.createDefaultDB(HiveMetaStore.java:651)
at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.init(HiveMetaStore.java:433)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.apache.hadoop.hive.metastore.RetryingHMSHandler.invokeInternal(RetryingHMSHandler.java:147)
at org.apache.hadoop.hive.metastore.RetryingHMSHandler.invoke(RetryingHMSHandler.java:105)
at org.apache.hadoop.hive.metastore.RetryingHMSHandler.<init>(RetryingHMSHandler.java:78)
at org.apache.hadoop.hive.metastore.RetryingHMSHandler.getProxy(RetryingHMSHandler.java:91)
at org.apache.hadoop.hive.metastore.HiveMetaStore.newRetryingHMSHandler(HiveMetaStore.java:6396)
at org.apache.hadoop.hive.metastore.HiveMetaStore.newRetryingHMSHandler(HiveMetaStore.java:6391)
at org.apache.hadoop.hive.metastore.HiveMetaStore.startMetaStore(HiveMetaStore.java:6658)
at org.apache.hadoop.hive.metastore.HiveMetaStore.startMetaStore(HiveMetaStore.java:6606)
at org.apache.oozie.test.MiniHCatServer$1.run(MiniHCatServer.java:141)
at java.lang.Thread.run(Thread.java:745)
) at org.apache.hadoop.hive.metastore.RetryingHMSHandler.invokeInternal(RetryingHMSHandler.java:212) at org.apache.hadoop.hive.metastore.RetryingHMSHandler.invoke(RetryingHMSHandler.java:105) at org.apache.hadoop.hive.metastore.RetryingHMSHandler.<init>(RetryingHMSHandler.java:78) ... 7 more{code}
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)