[
https://issues.apache.org/jira/browse/TEZ-2342?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14504295#comment-14504295
]
TezQA commented on TEZ-2342:
----------------------------
{color:green}+1 overall{color}. Here are the results of testing the latest
attachment
http://issues.apache.org/jira/secure/attachment/12726767/TEZ-2342-1.patch
against master revision db0a50c.
{color:green}+1 @author{color}. The patch does not contain any @author
tags.
{color:green}+1 tests included{color}. The patch appears to include 1 new
or modified test files.
{color:green}+1 javac{color}. The applied patch does not increase the
total number of javac compiler warnings.
{color:green}+1 javadoc{color}. There were no new javadoc warning messages.
{color:green}+1 findbugs{color}. The patch does not introduce any new
Findbugs (version 2.0.3) warnings.
{color:green}+1 release audit{color}. The applied patch does not increase
the total number of release audit warnings.
{color:green}+1 core tests{color}. The patch passed unit tests in .
Test results: https://builds.apache.org/job/PreCommit-TEZ-Build/497//testReport/
Console output: https://builds.apache.org/job/PreCommit-TEZ-Build/497//console
This message is automatically generated.
> TestFaultTolerance.testRandomFailingTasks fails due to timeout
> --------------------------------------------------------------
>
> Key: TEZ-2342
> URL: https://issues.apache.org/jira/browse/TEZ-2342
> Project: Apache Tez
> Issue Type: Bug
> Reporter: Jeff Zhang
> Assignee: Jeff Zhang
> Priority: Minor
> Attachments: TEZ-2342-1.patch, syslog_dag_1429582868137_0001_1
>
>
> {code}
> Error Message
> test timed out after 120000 milliseconds
> Stacktrace
> java.lang.Exception: test timed out after 120000 milliseconds
> at java.lang.Thread.sleep(Native Method)
> at
> org.apache.tez.test.TestFaultTolerance.runDAGAndVerify(TestFaultTolerance.java:126)
> at
> org.apache.tez.test.TestFaultTolerance.runDAGAndVerify(TestFaultTolerance.java:114)
> at
> org.apache.tez.test.TestFaultTolerance.testRandomFailingTasks(TestFaultTolerance.java:723)
> Standard Output
> 2015-04-17 07:46:10,952 INFO [main] test.TestFaultTolerance
> (TestFaultTolerance.java:setup(65)) - Starting mini clusters
> 2015-04-17 07:46:11,508 INFO [main] hdfs.MiniDFSCluster
> (MiniDFSCluster.java:<init>(446)) - starting cluster: numNameNodes=1,
> numDataNodes=1
> Formatting using clusterid: testClusterID
> 2015-04-17 07:46:12,919 INFO [main] namenode.FSNamesystem
> (FSNamesystem.java:<init>(716)) - No KeyProvider found.
> 2015-04-17 07:46:12,920 INFO [main] namenode.FSNamesystem
> (FSNamesystem.java:<init>(726)) - fsLock is fair:true
> 2015-04-17 07:46:13,021 INFO [main] Configuration.deprecation
> (Configuration.java:warnOnceIfDeprecated(1173)) -
> hadoop.configured.node.mapping is deprecated. Instead, use
> net.topology.configured.node.mapping
> 2015-04-17 07:46:13,021 INFO [main] blockmanagement.DatanodeManager
> (DatanodeManager.java:<init>(239)) - dfs.block.invalidate.limit=1000
> 2015-04-17 07:46:13,022 INFO [main] blockmanagement.DatanodeManager
> (DatanodeManager.java:<init>(245)) -
> dfs.namenode.datanode.registration.ip-hostname-check=true
> 2015-04-17 07:46:13,022 INFO [main] blockmanagement.BlockManager
> (InvalidateBlocks.java:printBlockDeletionTime(71)) -
> dfs.namenode.startup.delay.block.deletion.sec is set to 000:00:00:00.000
> 2015-04-17 07:46:13,025 INFO [main] blockmanagement.BlockManager
> (InvalidateBlocks.java:printBlockDeletionTime(76)) - The block deletion will
> start around 2015 Apr 17 07:46:13
> 2015-04-17 07:46:13,029 INFO [main] util.GSet
> (LightWeightGSet.java:computeCapacity(354)) - Computing capacity for map
> BlocksMap
> 2015-04-17 07:46:13,030 INFO [main] util.GSet
> (LightWeightGSet.java:computeCapacity(355)) - VM type = 64-bit
> 2015-04-17 07:46:13,032 INFO [main] util.GSet
> (LightWeightGSet.java:computeCapacity(356)) - 2.0% max memory 910.3 MB = 18.2
> MB
> 2015-04-17 07:46:13,033 INFO [main] util.GSet
> (LightWeightGSet.java:computeCapacity(361)) - capacity = 2^21 = 2097152
> entries
> 2015-04-17 07:46:13,079 INFO [main] blockmanagement.BlockManager
> (BlockManager.java:createBlockTokenSecretManager(365)) -
> dfs.block.access.token.enable=false
> 2015-04-17 07:46:13,080 INFO [main] blockmanagement.BlockManager
> (BlockManager.java:<init>(350)) - defaultReplication = 1
> 2015-04-17 07:46:13,080 INFO [main] blockmanagement.BlockManager
> (BlockManager.java:<init>(351)) - maxReplication = 512
> 2015-04-17 07:46:13,083 INFO [main] blockmanagement.BlockManager
> (BlockManager.java:<init>(352)) - minReplication = 1
> 2015-04-17 07:46:13,083 INFO [main] blockmanagement.BlockManager
> (BlockManager.java:<init>(353)) - maxReplicationStreams = 2
> 2015-04-17 07:46:13,083 INFO [main] blockmanagement.BlockManager
> (BlockManager.java:<init>(354)) - shouldCheckForEnoughRacks = false
> 2015-04-17 07:46:13,084 INFO [main] blockmanagement.BlockManager
> (BlockManager.java:<init>(355)) - replicationRecheckInterval = 3000
> 2015-04-17 07:46:13,084 INFO [main] blockmanagement.BlockManager
> (BlockManager.java:<init>(356)) - encryptDataTransfer = false
> 2015-04-17 07:46:13,084 INFO [main] blockmanagement.BlockManager
> (BlockManager.java:<init>(357)) - maxNumBlocksToLog = 1000
> 2015-04-17 07:46:13,115 INFO [main] namenode.FSNamesystem
> (FSNamesystem.java:<init>(746)) - fsOwner = jenkins (auth:SIMPLE)
> 2015-04-17 07:46:13,116 INFO [main] namenode.FSNamesystem
> (FSNamesystem.java:<init>(747)) - supergroup = supergroup
> 2015-04-17 07:46:13,116 INFO [main] namenode.FSNamesystem
> (FSNamesystem.java:<init>(748)) - isPermissionEnabled = true
> 2015-04-17 07:46:13,116 INFO [main] namenode.FSNamesystem
> (FSNamesystem.java:<init>(759)) - HA Enabled: false
> 2015-04-17 07:46:13,120 INFO [main] namenode.FSNamesystem
> (FSNamesystem.java:<init>(796)) - Append Enabled: true
> 2015-04-17 07:46:13,475 INFO [main] util.GSet
> (LightWeightGSet.java:computeCapacity(354)) - Computing capacity for map
> INodeMap
> 2015-04-17 07:46:13,475 INFO [main] util.GSet
> (LightWeightGSet.java:computeCapacity(355)) - VM type = 64-bit
> 2015-04-17 07:46:13,475 INFO [main] util.GSet
> (LightWeightGSet.java:computeCapacity(356)) - 1.0% max memory 910.3 MB = 9.1
> MB
> 2015-04-17 07:46:13,476 INFO [main] util.GSet
> (LightWeightGSet.java:computeCapacity(361)) - capacity = 2^20 = 1048576
> entries
> 2015-04-17 07:46:13,477 INFO [main] namenode.FSDirectory
> (FSDirectory.java:<init>(234)) - ACLs enabled? false
> 2015-04-17 07:46:13,477 INFO [main] namenode.FSDirectory
> (FSDirectory.java:<init>(238)) - XAttrs enabled? true
> 2015-04-17 07:46:13,477 INFO [main] namenode.FSDirectory
> (FSDirectory.java:<init>(246)) - Maximum size of an xattr: 16384
> 2015-04-17 07:46:13,478 INFO [main] namenode.NameNode
> (FSDirectory.java:<init>(294)) - Caching file names occuring more than 10
> times
> 2015-04-17 07:46:13,489 INFO [main] util.GSet
> (LightWeightGSet.java:computeCapacity(354)) - Computing capacity for map
> cachedBlocks
> 2015-04-17 07:46:13,489 INFO [main] util.GSet
> (LightWeightGSet.java:computeCapacity(355)) - VM type = 64-bit
> 2015-04-17 07:46:13,490 INFO [main] util.GSet
> (LightWeightGSet.java:computeCapacity(356)) - 0.25% max memory 910.3 MB = 2.3
> MB
> 2015-04-17 07:46:13,490 INFO [main] util.GSet
> (LightWeightGSet.java:computeCapacity(361)) - capacity = 2^18 = 262144
> entries
> 2015-04-17 07:46:13,493 INFO [main] namenode.FSNamesystem
> (FSNamesystem.java:<init>(5160)) - dfs.namenode.safemode.threshold-pct =
> 0.9990000128746033
> 2015-04-17 07:46:13,493 INFO [main] namenode.FSNamesystem
> (FSNamesystem.java:<init>(5161)) - dfs.namenode.safemode.min.datanodes = 0
> 2015-04-17 07:46:13,493 INFO [main] namenode.FSNamesystem
> (FSNamesystem.java:<init>(5162)) - dfs.namenode.safemode.extension = 0
> 2015-04-17 07:46:13,499 INFO [main] metrics.TopMetrics
> (TopMetrics.java:logConf(65)) - NNTop conf:
> dfs.namenode.top.window.num.buckets = 10
> 2015-04-17 07:46:13,499 INFO [main] metrics.TopMetrics
> (TopMetrics.java:logConf(67)) - NNTop conf: dfs.namenode.top.num.users = 10
> 2015-04-17 07:46:13,499 INFO [main] metrics.TopMetrics
> (TopMetrics.java:logConf(69)) - NNTop conf: dfs.namenode.top.windows.minutes
> = 1,5,25
> 2015-04-17 07:46:13,502 INFO [main] namenode.FSNamesystem
> (FSNamesystem.java:initRetryCache(905)) - Retry cache on namenode is enabled
> 2015-04-17 07:46:13,502 INFO [main] namenode.FSNamesystem
> (FSNamesystem.java:initRetryCache(913)) - Retry cache will use 0.03 of total
> heap and retry cache entry expiry time is 600000 millis
> 2015-04-17 07:46:13,508 INFO [main] util.GSet
> (LightWeightGSet.java:computeCapacity(354)) - Computing capacity for map
> NameNodeRetryCache
> 2015-04-17 07:46:13,508 INFO [main] util.GSet
> (LightWeightGSet.java:computeCapacity(355)) - VM type = 64-bit
> 2015-04-17 07:46:13,508 INFO [main] util.GSet
> (LightWeightGSet.java:computeCapacity(356)) - 0.029999999329447746% max
> memory 910.3 MB = 279.6 KB
> 2015-04-17 07:46:13,509 INFO [main] util.GSet
> (LightWeightGSet.java:computeCapacity(361)) - capacity = 2^15 = 32768
> entries
> 2015-04-17 07:46:13,704 INFO [main] namenode.FSImage
> (FSImage.java:format(158)) - Allocated new BlockPoolId:
> BP-725016459-10.79.60.8-1429281973548
> 2015-04-17 07:46:13,732 INFO [main] common.Storage
> (NNStorage.java:format(552)) - Storage directory
> D:\w\tez\tez-tests\target\org.apache.tez.test.TestFaultTolerance-tmpDir\name1
> has been successfully formatted.
> 2015-04-17 07:46:13,761 INFO [main] common.Storage
> (NNStorage.java:format(552)) - Storage directory
> D:\w\tez\tez-tests\target\org.apache.tez.test.TestFaultTolerance-tmpDir\name2
> has been successfully formatted.
> 2015-04-17 07:46:14,163 INFO [main] namenode.NNStorageRetentionManager
> (NNStorageRetentionManager.java:getImageTxIdToRetain(203)) - Going to retain
> 1 images with txid >= 0
> 2015-04-17 07:46:14,210 INFO [main] namenode.NameNode
> (NameNode.java:createNameNode(1416)) - createNameNode []
> 2015-04-17 07:46:14,278 WARN [main] impl.MetricsConfig
> (MetricsConfig.java:loadFirst(125)) - Cannot locate configuration: tried
> hadoop-metrics2-namenode.properties,hadoop-metrics2.properties
> 2015-04-17 07:46:14,363 INFO [main] impl.MetricsSystemImpl
> (MetricsSystemImpl.java:startTimer(377)) - Scheduled snapshot period at 10
> second(s).
> 2015-04-17 07:46:14,364 INFO [main] impl.MetricsSystemImpl
> (MetricsSystemImpl.java:start(192)) - NameNode metrics system started
> 2015-04-17 07:46:14,368 INFO [main] namenode.NameNode
> (NameNode.java:setClientNamenodeAddress(397)) - fs.defaultFS is
> hdfs://127.0.0.1:0
> 2015-04-17 07:46:14,429 INFO [main] hdfs.DFSUtil
> (DFSUtil.java:httpServerTemplateForNNAndJN(1703)) - Starting Web-server for
> hdfs at: http://127.0.0.1:0
> 2015-04-17 07:46:14,566 INFO [main] mortbay.log (Slf4jLog.java:info(67)) -
> Logging to org.slf4j.impl.Log4jLoggerAdapter(org.mortbay.log) via
> org.mortbay.log.Slf4jLog
> 2015-04-17 07:46:14,586 INFO [main] server.AuthenticationFilter
> (AuthenticationFilter.java:constructSecretProvider(282)) - Unable to
> initialize FileSignerSecretProvider, falling back to use random secrets.
> 2015-04-17 07:46:14,601 INFO [main] http.HttpRequestLog
> (HttpRequestLog.java:getRequestLog(80)) - Http request log for
> http.requests.namenode is not defined
> 2015-04-17 07:46:14,614 INFO [main] http.HttpServer2
> (HttpServer2.java:addGlobalFilter(710)) - Added global filter 'safety'
> (class=org.apache.hadoop.http.HttpServer2$QuotingInputFilter)
> 2015-04-17 07:46:14,619 INFO [main] http.HttpServer2
> (HttpServer2.java:addFilter(685)) - Added filter static_user_filter
> (class=org.apache.hadoop.http.lib.StaticUserWebFilter$StaticUserFilter) to
> context hdfs
> 2015-04-17 07:46:14,619 INFO [main] http.HttpServer2
> (HttpServer2.java:addFilter(693)) - Added filter static_user_filter
> (class=org.apache.hadoop.http.lib.StaticUserWebFilter$StaticUserFilter) to
> context static
> 2015-04-17 07:46:14,664 INFO [main] http.HttpServer2
> (NameNodeHttpServer.java:initWebHdfs(86)) - Added filter
> 'org.apache.hadoop.hdfs.web.AuthFilter'
> (class=org.apache.hadoop.hdfs.web.AuthFilter)
> 2015-04-17 07:46:14,665 INFO [main] http.HttpServer2
> (HttpServer2.java:addJerseyResourcePackage(609)) - addJerseyResourcePackage:
> packageName=org.apache.hadoop.hdfs.server.namenode.web.resources;org.apache.hadoop.hdfs.web.resources,
> pathSpec=/webhdfs/v1/*
> 2015-04-17 07:46:14,708 INFO [main] http.HttpServer2
> (HttpServer2.java:openListeners(915)) - Jetty bound to port 60602
> 2015-04-17 07:46:14,708 INFO [main] mortbay.log (Slf4jLog.java:info(67)) -
> jetty-6.1.26
> 2015-04-17 07:46:14,760 INFO [main] mortbay.log (Slf4jLog.java:info(67)) -
> Extract
> jar:file:/D:/dal-UT/.m2/repository/org/apache/hadoop/hadoop-hdfs/2.5.0.2858/hadoop-hdfs-2.5.0.2858-tests.jar!/webapps/hdfs
> to D:\tmp\tez-dal\Jetty_127_0_0_1_60602_hdfs____.6o51sx\webapp
> 2015-04-17 07:46:15,019 INFO [main] mortbay.log (Slf4jLog.java:info(67)) -
> Started HttpServer2$SelectChannelConnectorWithSafeStartup@127.0.0.1:60602
> 2015-04-17 07:46:15,029 INFO [main] namenode.FSNamesystem
> (FSNamesystem.java:<init>(716)) - No KeyProvider found.
> 2015-04-17 07:46:15,029 INFO [main] namenode.FSNamesystem
> (FSNamesystem.java:<init>(726)) - fsLock is fair:true
> 2015-04-17 07:46:15,030 INFO [main] blockmanagement.DatanodeManager
> (DatanodeManager.java:<init>(239)) - dfs.block.invalidate.limit=1000
> 2015-04-17 07:46:15,030 INFO [main] blockmanagement.DatanodeManager
> (DatanodeManager.java:<init>(245)) -
> dfs.namenode.datanode.registration.ip-hostname-check=true
> 2015-04-17 07:46:15,030 INFO [main] blockmanagement.BlockManager
> (InvalidateBlocks.java:printBlockDeletionTime(71)) -
> dfs.namenode.startup.delay.block.deletion.sec is set to 000:00:00:00.000
> 2015-04-17 07:46:15,031 INFO [main] blockmanagement.BlockManager
> (InvalidateBlocks.java:printBlockDeletionTime(76)) - The block deletion will
> start around 2015 Apr 17 07:46:15
> 2015-04-17 07:46:15,031 INFO [main] util.GSet
> (LightWeightGSet.java:computeCapacity(354)) - Computing capacity for map
> BlocksMap
> 2015-04-17 07:46:15,031 INFO [main] util.GSet
> (LightWeightGSet.java:computeCapacity(355)) - VM type = 64-bit
> 2015-04-17 07:46:15,032 INFO [main] util.GSet
> (LightWeightGSet.java:computeCapacity(356)) - 2.0% max memory 910.3 MB = 18.2
> MB
> 2015-04-17 07:46:15,032 INFO [main] util.GSet
> (LightWeightGSet.java:computeCapacity(361)) - capacity = 2^21 = 2097152
> entries
> 2015-04-17 07:46:15,059 INFO [main] blockmanagement.BlockManager
> (BlockManager.java:createBlockTokenSecretManager(365)) -
> dfs.block.access.token.enable=false
> 2015-04-17 07:46:15,060 INFO [main] blockmanagement.BlockManager
> (BlockManager.java:<init>(350)) - defaultReplication = 1
> 2015-04-17 07:46:15,062 INFO [main] blockmanagement.BlockManager
> (BlockManager.java:<init>(351)) - maxReplication = 512
> 2015-04-17 07:46:15,062 INFO [main] blockmanagement.BlockManager
> (BlockManager.java:<init>(352)) - minReplication = 1
> 2015-04-17 07:46:15,063 INFO [main] blockmanagement.BlockManager
> (BlockManager.java:<init>(353)) - maxReplicationStreams = 2
> 2015-04-17 07:46:15,064 INFO [main] blockmanagement.BlockManager
> (BlockManager.java:<init>(354)) - shouldCheckForEnoughRacks = false
> 2015-04-17 07:46:15,064 INFO [main] blockmanagement.BlockManager
> (BlockManager.java:<init>(355)) - replicationRecheckInterval = 3000
> 2015-04-17 07:46:15,064 INFO [main] blockmanagement.BlockManager
> (BlockManager.java:<init>(356)) - encryptDataTransfer = false
> 2015-04-17 07:46:15,065 INFO [main] blockmanagement.BlockManager
> (BlockManager.java:<init>(357)) - maxNumBlocksToLog = 1000
> 2015-04-17 07:46:15,066 INFO [main] namenode.FSNamesystem
> (FSNamesystem.java:<init>(746)) - fsOwner = jenkins (auth:SIMPLE)
> 2015-04-17 07:46:15,066 INFO [main] namenode.FSNamesystem
> (FSNamesystem.java:<init>(747)) - supergroup = supergroup
> 2015-04-17 07:46:15,066 INFO [main] namenode.FSNamesystem
> (FSNamesystem.java:<init>(748)) - isPermissionEnabled = true
> 2015-04-17 07:46:15,067 INFO [main] namenode.FSNamesystem
> (FSNamesystem.java:<init>(759)) - HA Enabled: false
> 2015-04-17 07:46:15,067 INFO [main] namenode.FSNamesystem
> (FSNamesystem.java:<init>(796)) - Append Enabled: true
> 2015-04-17 07:46:15,067 INFO [main] util.GSet
> (LightWeightGSet.java:computeCapacity(354)) - Computing capacity for map
> INodeMap
> 2015-04-17 07:46:15,068 INFO [main] util.GSet
> (LightWeightGSet.java:computeCapacity(355)) - VM type = 64-bit
> 2015-04-17 07:46:15,068 INFO [main] util.GSet
> (LightWeightGSet.java:computeCapacity(356)) - 1.0% max memory 910.3 MB = 9.1
> MB
> 2015-04-17 07:46:15,068 INFO [main] util.GSet
> (LightWeightGSet.java:computeCapacity(361)) - capacity = 2^20 = 1048576
> entries
> 2015-04-17 07:46:15,068 INFO [main] namenode.FSDirectory
> (FSDirectory.java:<init>(234)) - ACLs enabled? false
> 2015-04-17 07:46:15,069 INFO [main] namenode.FSDirectory
> (FSDirectory.java:<init>(238)) - XAttrs enabled? true
> 2015-04-17 07:46:15,069 INFO [main] namenode.FSDirectory
> (FSDirectory.java:<init>(246)) - Maximum size of an xattr: 16384
> 2015-04-17 07:46:15,069 INFO [main] namenode.NameNode
> (FSDirectory.java:<init>(294)) - Caching file names occuring more than 10
> times
> 2015-04-17 07:46:15,069 INFO [main] util.GSet
> (LightWeightGSet.java:computeCapacity(354)) - Computing capacity for map
> cachedBlocks
> 2015-04-17 07:46:15,070 INFO [main] util.GSet
> (LightWeightGSet.java:computeCapacity(355)) - VM type = 64-bit
> 2015-04-17 07:46:15,070 INFO [main] util.GSet
> (LightWeightGSet.java:computeCapacity(356)) - 0.25% max memory 910.3 MB = 2.3
> MB
> 2015-04-17 07:46:15,070 INFO [main] util.GSet
> (LightWeightGSet.java:computeCapacity(361)) - capacity = 2^18 = 262144
> entries
> 2015-04-17 07:46:15,071 INFO [main] namenode.FSNamesystem
> (FSNamesystem.java:<init>(5160)) - dfs.namenode.safemode.threshold-pct =
> 0.9990000128746033
> 2015-04-17 07:46:15,071 INFO [main] namenode.FSNamesystem
> (FSNamesystem.java:<init>(5161)) - dfs.namenode.safemode.min.datanodes = 0
> 2015-04-17 07:46:15,071 INFO [main] namenode.FSNamesystem
> (FSNamesystem.java:<init>(5162)) - dfs.namenode.safemode.extension = 0
> 2015-04-17 07:46:15,072 INFO [main] metrics.TopMetrics
> (TopMetrics.java:logConf(65)) - NNTop conf:
> dfs.namenode.top.window.num.buckets = 10
> 2015-04-17 07:46:15,074 INFO [main] metrics.TopMetrics
> (TopMetrics.java:logConf(67)) - NNTop conf: dfs.namenode.top.num.users = 10
> 2015-04-17 07:46:15,075 INFO [main] metrics.TopMetrics
> (TopMetrics.java:logConf(69)) - NNTop conf: dfs.namenode.top.windows.minutes
> = 1,5,25
> 2015-04-17 07:46:15,075 INFO [main] namenode.FSNamesystem
> (FSNamesystem.java:initRetryCache(905)) - Retry cache on namenode is enabled
> 2015-04-17 07:46:15,076 INFO [main] namenode.FSNamesystem
> (FSNamesystem.java:initRetryCache(913)) - Retry cache will use 0.03 of total
> heap and retry cache entry expiry time is 600000 millis
> 2015-04-17 07:46:15,076 INFO [main] util.GSet
> (LightWeightGSet.java:computeCapacity(354)) - Computing capacity for map
> NameNodeRetryCache
> 2015-04-17 07:46:15,076 INFO [main] util.GSet
> (LightWeightGSet.java:computeCapacity(355)) - VM type = 64-bit
> 2015-04-17 07:46:15,076 INFO [main] util.GSet
> (LightWeightGSet.java:computeCapacity(356)) - 0.029999999329447746% max
> memory 910.3 MB = 279.6 KB
> 2015-04-17 07:46:15,076 INFO [main] util.GSet
> (LightWeightGSet.java:computeCapacity(361)) - capacity = 2^15 = 32768
> entries
> 2015-04-17 07:46:15,091 INFO [main] common.Storage
> (Storage.java:tryLock(715)) - Lock on
> D:\w\tez\tez-tests\target\org.apache.tez.test.TestFaultTolerance-tmpDir\name1\in_use.lock
> acquired by nodename 2544@sijenkins-win-3
> 2015-04-17 07:46:15,098 INFO [main] common.Storage
> (Storage.java:tryLock(715)) - Lock on
> D:\w\tez\tez-tests\target\org.apache.tez.test.TestFaultTolerance-tmpDir\name2\in_use.lock
> acquired by nodename 2544@sijenkins-win-3
> 2015-04-17 07:46:15,102 INFO [main] namenode.FileJournalManager
> (FileJournalManager.java:recoverUnfinalizedSegments(362)) - Recovering
> unfinalized segments in
> D:\w\tez\tez-tests\target\org.apache.tez.test.TestFaultTolerance-tmpDir\name1\current
> 2015-04-17 07:46:15,102 INFO [main] namenode.FileJournalManager
> (FileJournalManager.java:recoverUnfinalizedSegments(362)) - Recovering
> unfinalized segments in
> D:\w\tez\tez-tests\target\org.apache.tez.test.TestFaultTolerance-tmpDir\name2\current
> 2015-04-17 07:46:15,103 INFO [main] namenode.FSImage
> (FSImage.java:loadFSImage(669)) - No edit log streams selected.
> 2015-04-17 07:46:15,123 INFO [main] namenode.FSImageFormatPBINode
> (FSImageFormatPBINode.java:loadINodeSection(255)) - Loading 1 INodes.
> 2015-04-17 07:46:15,134 INFO [main] namenode.FSImageFormatProtobuf
> (FSImageFormatProtobuf.java:load(181)) - Loaded FSImage in 0 seconds.
> 2015-04-17 07:46:15,134 INFO [main] namenode.FSImage
> (FSImage.java:loadFSImage(972)) - Loaded image for txid 0 from
> D:\w\tez\tez-tests\target\org.apache.tez.test.TestFaultTolerance-tmpDir\name1\current\fsimage_0000000000000000000
> 2015-04-17 07:46:15,142 INFO [main] namenode.FSNamesystem
> (FSNamesystem.java:loadFSImage(982)) - Need to save fs image? false
> (staleImage=false, haEnabled=false, isRollingUpgrade=false)
> 2015-04-17 07:46:15,143 INFO [main] namenode.FSEditLog
> (FSEditLog.java:startLogSegment(1214)) - Starting log segment at 1
> 2015-04-17 07:46:15,187 INFO [main] namenode.NameCache
> (NameCache.java:initialized(143)) - initialized with 0 entries 0 lookups
> 2015-04-17 07:46:15,187 INFO [main] namenode.FSNamesystem
> (FSNamesystem.java:loadFromDisk(688)) - Finished loading FSImage in 145 msecs
> 2015-04-17 07:46:15,506 INFO [main] namenode.NameNode
> (NameNodeRpcServer.java:<init>(341)) - RPC server is binding to 127.0.0.1:0
> 2015-04-17 07:46:15,522 INFO [main] ipc.CallQueueManager
> (CallQueueManager.java:<init>(53)) - Using callQueue class
> java.util.concurrent.LinkedBlockingQueue
> 2015-04-17 07:46:15,543 INFO [Socket Reader #1 for port 60605] ipc.Server
> (Server.java:run(606)) - Starting Socket Reader #1 for port 60605
> 2015-04-17 07:46:15,599 INFO [main] namenode.NameNode
> (NameNode.java:initialize(651)) - Clients are to use 127.0.0.1:60605 to
> access this namenode/service.
> 2015-04-17 07:46:15,602 INFO [main] namenode.FSNamesystem
> (FSNamesystem.java:registerMBean(6025)) - Registered FSNamesystemState MBean
> 2015-04-17 07:46:15,613 INFO [main] namenode.LeaseManager
> (LeaseManager.java:getNumUnderConstructionBlocks(132)) - Number of blocks
> under construction: 0
> 2015-04-17 07:46:15,614 INFO [main] namenode.LeaseManager
> (LeaseManager.java:getNumUnderConstructionBlocks(132)) - Number of blocks
> under construction: 0
> 2015-04-17 07:46:15,614 INFO [main] namenode.FSNamesystem
> (FSNamesystem.java:initializeReplQueues(1182)) - initializing replication
> queues
> 2015-04-17 07:46:15,614 INFO [main] hdfs.StateChange
> (FSNamesystem.java:leave(5235)) - STATE* Leaving safe mode after 0 secs
> 2015-04-17 07:46:15,614 INFO [main] hdfs.StateChange
> (FSNamesystem.java:leave(5247)) - STATE* Network topology has 0 racks and 0
> datanodes
> 2015-04-17 07:46:15,615 INFO [main] hdfs.StateChange
> (FSNamesystem.java:leave(5250)) - STATE* UnderReplicatedBlocks has 0 blocks
> 2015-04-17 07:46:15,629 INFO [main] blockmanagement.DatanodeDescriptor
> (DatanodeDescriptor.java:updateHeartbeatState(450)) - Number of failed
> storage changes from 0 to 0
> 2015-04-17 07:46:15,630 INFO [Replication Queue Initializer]
> blockmanagement.BlockManager
> (BlockManager.java:processMisReplicatesAsync(2754)) - Total number of blocks
> = 0
> 2015-04-17 07:46:15,630 INFO [Replication Queue Initializer]
> blockmanagement.BlockManager
> (BlockManager.java:processMisReplicatesAsync(2755)) - Number of invalid
> blocks = 0
> 2015-04-17 07:46:15,630 INFO [Replication Queue Initializer]
> blockmanagement.BlockManager
> (BlockManager.java:processMisReplicatesAsync(2756)) - Number of
> under-replicated blocks = 0
> 2015-04-17 07:46:15,631 INFO [Replication Queue Initializer]
> blockmanagement.BlockManager
> (BlockManager.java:processMisReplicatesAsync(2757)) - Number of
> over-replicated blocks = 0
> 2015-04-17 07:46:15,632 INFO [Replication Queue Initializer]
> blockmanagement.BlockManager
> (BlockManager.java:processMisReplicatesAsync(2759)) - Number of blocks being
> written = 0
> 2015-04-17 07:46:15,632 INFO [Replication Queue Initializer]
> hdfs.StateChange (BlockManager.java:processMisReplicatesAsync(2760)) - STATE*
> Replication Queue initialization scan for invalid, over- and under-replicated
> blocks completed in 17 msec
> 2015-04-17 07:46:15,694 INFO [IPC Server listener on 60605] ipc.Server
> (Server.java:run(676)) - IPC Server listener on 60605: starting
> 2015-04-17 07:46:15,693 INFO [IPC Server Responder] ipc.Server
> (Server.java:run(836)) - IPC Server Responder: starting
> 2015-04-17 07:46:15,877 INFO [main] namenode.NameNode
> (NameNode.java:startCommonServices(694)) - NameNode RPC up at:
> 127.0.0.1/127.0.0.1:60605
> 2015-04-17 07:46:15,877 INFO [main] namenode.FSNamesystem
> (FSNamesystem.java:startActiveServices(1103)) - Starting services required
> for active state
> 2015-04-17 07:46:15,883 INFO [CacheReplicationMonitor(481446731)]
> blockmanagement.CacheReplicationMonitor
> (CacheReplicationMonitor.java:run(160)) - Starting CacheReplicationMonitor
> with interval 30000 milliseconds
> 2015-04-17 07:46:15,896 INFO [main] hdfs.MiniDFSCluster
> (MiniDFSCluster.java:startDataNodes(1413)) - Starting DataNode 0 with
> dfs.datanode.data.dir:
> [DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data1,[DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data2
> 2015-04-17 07:46:16,011 INFO [main] impl.MetricsSystemImpl
> (MetricsSystemImpl.java:init(159)) - DataNode metrics system started (again)
> 2015-04-17 07:46:16,016 INFO [main] datanode.BlockScanner
> (BlockScanner.java:<init>(151)) - Disabled block scanner.
> 2015-04-17 07:46:16,017 INFO [main] datanode.DataNode
> (DataNode.java:<init>(436)) - Configured hostname is 127.0.0.1
> 2015-04-17 07:46:16,023 INFO [main] datanode.DataNode
> (DataNode.java:startDataNode(1134)) - Starting DataNode with maxLockedMemory
> = 0
> 2015-04-17 07:46:16,056 INFO [main] datanode.DataNode
> (DataNode.java:initDataXceiver(933)) - Opened streaming server at
> /127.0.0.1:60612
> 2015-04-17 07:46:16,059 INFO [main] datanode.DataNode
> (DataXceiverServer.java:<init>(76)) - Balancing bandwith is 1048576 bytes/s
> 2015-04-17 07:46:16,060 INFO [main] datanode.DataNode
> (DataXceiverServer.java:<init>(77)) - Number threads for balancing is 5
> 2015-04-17 07:46:16,070 INFO [main] server.AuthenticationFilter
> (AuthenticationFilter.java:constructSecretProvider(282)) - Unable to
> initialize FileSignerSecretProvider, falling back to use random secrets.
> 2015-04-17 07:46:16,078 INFO [main] http.HttpRequestLog
> (HttpRequestLog.java:getRequestLog(80)) - Http request log for
> http.requests.datanode is not defined
> 2015-04-17 07:46:16,079 INFO [main] http.HttpServer2
> (HttpServer2.java:addGlobalFilter(710)) - Added global filter 'safety'
> (class=org.apache.hadoop.http.HttpServer2$QuotingInputFilter)
> 2015-04-17 07:46:16,082 INFO [main] http.HttpServer2
> (HttpServer2.java:addFilter(685)) - Added filter static_user_filter
> (class=org.apache.hadoop.http.lib.StaticUserWebFilter$StaticUserFilter) to
> context datanode
> 2015-04-17 07:46:16,082 INFO [main] http.HttpServer2
> (HttpServer2.java:addFilter(693)) - Added filter static_user_filter
> (class=org.apache.hadoop.http.lib.StaticUserWebFilter$StaticUserFilter) to
> context static
> 2015-04-17 07:46:16,089 INFO [main] http.HttpServer2
> (HttpServer2.java:openListeners(915)) - Jetty bound to port 60613
> 2015-04-17 07:46:16,089 INFO [main] mortbay.log (Slf4jLog.java:info(67)) -
> jetty-6.1.26
> 2015-04-17 07:46:16,096 INFO [main] mortbay.log (Slf4jLog.java:info(67)) -
> Extract
> jar:file:/D:/dal-UT/.m2/repository/org/apache/hadoop/hadoop-hdfs/2.5.0.2858/hadoop-hdfs-2.5.0.2858-tests.jar!/webapps/datanode
> to D:\tmp\tez-dal\Jetty_localhost_60613_datanode____.sikda3\webapp
> 2015-04-17 07:46:16,254 INFO [main] mortbay.log (Slf4jLog.java:info(67)) -
> Started HttpServer2$SelectChannelConnectorWithSafeStartup@localhost:60613
> 2015-04-17 07:46:16,539 INFO [main] web.DatanodeHttpServer
> (DatanodeHttpServer.java:start(150)) - Listening HTTP traffic on
> /127.0.0.1:60632
> 2015-04-17 07:46:16,541 INFO [main] datanode.DataNode
> (DataNode.java:startDataNode(1151)) - dnUserName = jenkins
> 2015-04-17 07:46:16,541 INFO [main] datanode.DataNode
> (DataNode.java:startDataNode(1152)) - supergroup = supergroup
> 2015-04-17 07:46:16,564 INFO [main] ipc.CallQueueManager
> (CallQueueManager.java:<init>(53)) - Using callQueue class
> java.util.concurrent.LinkedBlockingQueue
> 2015-04-17 07:46:16,566 INFO [Socket Reader #1 for port 60633] ipc.Server
> (Server.java:run(606)) - Starting Socket Reader #1 for port 60633
> 2015-04-17 07:46:16,575 INFO [main] datanode.DataNode
> (DataNode.java:initIpcServer(852)) - Opened IPC server at /127.0.0.1:60633
> 2015-04-17 07:46:16,589 INFO [main] datanode.DataNode
> (BlockPoolManager.java:refreshNamenodes(152)) - Refresh request received for
> nameservices: null
> 2015-04-17 07:46:16,596 INFO [main] datanode.DataNode
> (BlockPoolManager.java:doRefreshNamenodes(197)) - Starting BPOfferServices
> for nameservices: <default>
> 2015-04-17 07:46:16,607 INFO [DataNode:
> [[[DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data1/,
>
> [DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data2/]]
> heartbeating to /127.0.0.1:60605] datanode.DataNode
> (BPServiceActor.java:run(845)) - Block pool <registering> (Datanode Uuid
> unassigned) service to /127.0.0.1:60605 starting to offer service
> 2015-04-17 07:46:16,616 INFO [IPC Server Responder] ipc.Server
> (Server.java:run(836)) - IPC Server Responder: starting
> 2015-04-17 07:46:16,617 INFO [IPC Server listener on 60633] ipc.Server
> (Server.java:run(676)) - IPC Server listener on 60633: starting
> 2015-04-17 07:46:17,034 INFO [DataNode:
> [[[DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data1/,
>
> [DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data2/]]
> heartbeating to /127.0.0.1:60605] common.Storage
> (Storage.java:tryLock(715)) - Lock on
> D:\w\tez\tez-tests\target\org.apache.tez.test.TestFaultTolerance-tmpDir\data\data1\in_use.lock
> acquired by nodename 2544@sijenkins-win-3
> 2015-04-17 07:46:17,034 INFO [DataNode:
> [[[DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data1/,
>
> [DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data2/]]
> heartbeating to /127.0.0.1:60605] common.Storage
> (DataStorage.java:loadStorageDirectory(273)) - Storage directory
> D:\w\tez\tez-tests\target\org.apache.tez.test.TestFaultTolerance-tmpDir\data\data1
> is not formatted for BP-725016459-10.79.60.8-1429281973548
> 2015-04-17 07:46:17,034 INFO [DataNode:
> [[[DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data1/,
>
> [DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data2/]]
> heartbeating to /127.0.0.1:60605] common.Storage
> (DataStorage.java:loadStorageDirectory(275)) - Formatting ...
> 2015-04-17 07:46:17,235 INFO [DataNode:
> [[[DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data1/,
>
> [DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data2/]]
> heartbeating to /127.0.0.1:60605] common.Storage
> (BlockPoolSliceStorage.java:recoverTransitionRead(241)) - Analyzing storage
> directories for bpid BP-725016459-10.79.60.8-1429281973548
> 2015-04-17 07:46:17,235 INFO [DataNode:
> [[[DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data1/,
>
> [DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data2/]]
> heartbeating to /127.0.0.1:60605] common.Storage (Storage.java:lock(675)) -
> Locking is disabled for
> D:\w\tez\tez-tests\target\org.apache.tez.test.TestFaultTolerance-tmpDir\data\data1\current\BP-725016459-10.79.60.8-1429281973548
> 2015-04-17 07:46:17,236 INFO [DataNode:
> [[[DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data1/,
>
> [DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data2/]]
> heartbeating to /127.0.0.1:60605] common.Storage
> (BlockPoolSliceStorage.java:loadStorageDirectory(158)) - Block pool storage
> directory
> D:\w\tez\tez-tests\target\org.apache.tez.test.TestFaultTolerance-tmpDir\data\data1\current\BP-725016459-10.79.60.8-1429281973548
> is not formatted for BP-725016459-10.79.60.8-1429281973548
> 2015-04-17 07:46:17,236 INFO [DataNode:
> [[[DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data1/,
>
> [DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data2/]]
> heartbeating to /127.0.0.1:60605] common.Storage
> (BlockPoolSliceStorage.java:loadStorageDirectory(160)) - Formatting ...
> 2015-04-17 07:46:17,237 INFO [DataNode:
> [[[DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data1/,
>
> [DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data2/]]
> heartbeating to /127.0.0.1:60605] common.Storage
> (BlockPoolSliceStorage.java:format(267)) - Formatting block pool
> BP-725016459-10.79.60.8-1429281973548 directory
> D:\w\tez\tez-tests\target\org.apache.tez.test.TestFaultTolerance-tmpDir\data\data1\current\BP-725016459-10.79.60.8-1429281973548\current
> 2015-04-17 07:46:17,243 INFO [DataNode:
> [[[DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data1/,
>
> [DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data2/]]
> heartbeating to /127.0.0.1:60605] common.Storage
> (BlockPoolSliceStorage.java:doTransition(359)) - Restored 0 block files from
> trash.
> 2015-04-17 07:46:17,255 INFO [DataNode:
> [[[DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data1/,
>
> [DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data2/]]
> heartbeating to /127.0.0.1:60605] common.Storage
> (Storage.java:tryLock(715)) - Lock on
> D:\w\tez\tez-tests\target\org.apache.tez.test.TestFaultTolerance-tmpDir\data\data2\in_use.lock
> acquired by nodename 2544@sijenkins-win-3
> 2015-04-17 07:46:17,255 INFO [DataNode:
> [[[DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data1/,
>
> [DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data2/]]
> heartbeating to /127.0.0.1:60605] common.Storage
> (DataStorage.java:loadStorageDirectory(273)) - Storage directory
> D:\w\tez\tez-tests\target\org.apache.tez.test.TestFaultTolerance-tmpDir\data\data2
> is not formatted for BP-725016459-10.79.60.8-1429281973548
> 2015-04-17 07:46:17,255 INFO [DataNode:
> [[[DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data1/,
>
> [DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data2/]]
> heartbeating to /127.0.0.1:60605] common.Storage
> (DataStorage.java:loadStorageDirectory(275)) - Formatting ...
> 2015-04-17 07:46:17,318 INFO [DataNode:
> [[[DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data1/,
>
> [DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data2/]]
> heartbeating to /127.0.0.1:60605] common.Storage
> (BlockPoolSliceStorage.java:recoverTransitionRead(241)) - Analyzing storage
> directories for bpid BP-725016459-10.79.60.8-1429281973548
> 2015-04-17 07:46:17,318 INFO [DataNode:
> [[[DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data1/,
>
> [DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data2/]]
> heartbeating to /127.0.0.1:60605] common.Storage (Storage.java:lock(675)) -
> Locking is disabled for
> D:\w\tez\tez-tests\target\org.apache.tez.test.TestFaultTolerance-tmpDir\data\data2\current\BP-725016459-10.79.60.8-1429281973548
> 2015-04-17 07:46:17,318 INFO [DataNode:
> [[[DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data1/,
>
> [DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data2/]]
> heartbeating to /127.0.0.1:60605] common.Storage
> (BlockPoolSliceStorage.java:loadStorageDirectory(158)) - Block pool storage
> directory
> D:\w\tez\tez-tests\target\org.apache.tez.test.TestFaultTolerance-tmpDir\data\data2\current\BP-725016459-10.79.60.8-1429281973548
> is not formatted for BP-725016459-10.79.60.8-1429281973548
> 2015-04-17 07:46:17,318 INFO [DataNode:
> [[[DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data1/,
>
> [DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data2/]]
> heartbeating to /127.0.0.1:60605] common.Storage
> (BlockPoolSliceStorage.java:loadStorageDirectory(160)) - Formatting ...
> 2015-04-17 07:46:17,319 INFO [DataNode:
> [[[DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data1/,
>
> [DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data2/]]
> heartbeating to /127.0.0.1:60605] common.Storage
> (BlockPoolSliceStorage.java:format(267)) - Formatting block pool
> BP-725016459-10.79.60.8-1429281973548 directory
> D:\w\tez\tez-tests\target\org.apache.tez.test.TestFaultTolerance-tmpDir\data\data2\current\BP-725016459-10.79.60.8-1429281973548\current
> 2015-04-17 07:46:17,327 INFO [DataNode:
> [[[DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data1/,
>
> [DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data2/]]
> heartbeating to /127.0.0.1:60605] common.Storage
> (BlockPoolSliceStorage.java:doTransition(359)) - Restored 0 block files from
> trash.
> 2015-04-17 07:46:17,327 INFO [main] hdfs.MiniDFSCluster
> (MiniDFSCluster.java:shouldWait(2303)) - dnInfo.length != numDataNodes
> 2015-04-17 07:46:17,331 INFO [main] hdfs.MiniDFSCluster
> (MiniDFSCluster.java:waitActive(2255)) - Waiting for cluster to become active
> 2015-04-17 07:46:17,337 INFO [DataNode:
> [[[DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data1/,
>
> [DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data2/]]
> heartbeating to /127.0.0.1:60605] datanode.DataNode
> (DataNode.java:initStorage(1398)) - Setting up storage:
> nsid=95952740;bpid=BP-725016459-10.79.60.8-1429281973548;lv=-56;nsInfo=lv=-63;cid=testClusterID;nsid=95952740;c=0;bpid=BP-725016459-10.79.60.8-1429281973548;dnuuid=null
> 2015-04-17 07:46:17,358 INFO [DataNode:
> [[[DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data1/,
>
> [DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data2/]]
> heartbeating to /127.0.0.1:60605] datanode.DataNode
> (DataNode.java:checkDatanodeUuid(1227)) - Generated and persisted new
> Datanode UUID 3139557f-6bc1-4529-937f-81657d6baf32
> 2015-04-17 07:46:17,479 INFO [main] hdfs.MiniDFSCluster
> (MiniDFSCluster.java:shouldWait(2303)) - dnInfo.length != numDataNodes
> 2015-04-17 07:46:17,506 INFO [main] hdfs.MiniDFSCluster
> (MiniDFSCluster.java:waitActive(2255)) - Waiting for cluster to become active
> 2015-04-17 07:46:17,590 INFO [DataNode:
> [[[DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data1/,
>
> [DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data2/]]
> heartbeating to /127.0.0.1:60605] impl.FsDatasetImpl
> (FsVolumeList.java:addVolume(303)) - Added new volume:
> DS-da6bd8c8-924e-43d2-9f85-75c88cb0c4fe
> 2015-04-17 07:46:17,590 INFO [DataNode:
> [[[DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data1/,
>
> [DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data2/]]
> heartbeating to /127.0.0.1:60605] impl.FsDatasetImpl
> (FsDatasetImpl.java:addVolume(380)) - Added volume -
> D:\w\tez\tez-tests\target\org.apache.tez.test.TestFaultTolerance-tmpDir\data\data1\current,
> StorageType: DISK
> 2015-04-17 07:46:17,590 INFO [DataNode:
> [[[DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data1/,
>
> [DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data2/]]
> heartbeating to /127.0.0.1:60605] impl.FsDatasetImpl
> (FsVolumeList.java:addVolume(303)) - Added new volume:
> DS-ef534adf-3270-4cb7-b038-16dc61f3f409
> 2015-04-17 07:46:17,590 INFO [DataNode:
> [[[DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data1/,
>
> [DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data2/]]
> heartbeating to /127.0.0.1:60605] impl.FsDatasetImpl
> (FsDatasetImpl.java:addVolume(380)) - Added volume -
> D:\w\tez\tez-tests\target\org.apache.tez.test.TestFaultTolerance-tmpDir\data\data2\current,
> StorageType: DISK
> 2015-04-17 07:46:17,599 INFO [DataNode:
> [[[DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data1/,
>
> [DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data2/]]
> heartbeating to /127.0.0.1:60605] impl.FsDatasetImpl
> (FsDatasetImpl.java:registerMBean(2028)) - Registered FSDatasetState MBean
> 2015-04-17 07:46:17,604 INFO [DataNode:
> [[[DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data1/,
>
> [DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data2/]]
> heartbeating to /127.0.0.1:60605] datanode.DirectoryScanner
> (DirectoryScanner.java:start(332)) - Periodic Directory Tree Verification
> scan starting at 1429293531604 with interval 21600000
> 2015-04-17 07:46:17,606 INFO [DataNode:
> [[[DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data1/,
>
> [DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data2/]]
> heartbeating to /127.0.0.1:60605] impl.FsDatasetImpl
> (FsDatasetImpl.java:addBlockPool(2474)) - Adding block pool
> BP-725016459-10.79.60.8-1429281973548
> 2015-04-17 07:46:17,607 INFO [Thread-58] impl.FsDatasetImpl
> (FsVolumeList.java:run(402)) - Scanning block pool
> BP-725016459-10.79.60.8-1429281973548 on volume
> D:\w\tez\tez-tests\target\org.apache.tez.test.TestFaultTolerance-tmpDir\data\data1\current...
> 2015-04-17 07:46:17,607 INFO [Thread-59] impl.FsDatasetImpl
> (FsVolumeList.java:run(402)) - Scanning block pool
> BP-725016459-10.79.60.8-1429281973548 on volume
> D:\w\tez\tez-tests\target\org.apache.tez.test.TestFaultTolerance-tmpDir\data\data2\current...
> 2015-04-17 07:46:17,611 INFO [main] hdfs.MiniDFSCluster
> (MiniDFSCluster.java:shouldWait(2303)) - dnInfo.length != numDataNodes
> 2015-04-17 07:46:17,612 INFO [main] hdfs.MiniDFSCluster
> (MiniDFSCluster.java:waitActive(2255)) - Waiting for cluster to become active
> 2015-04-17 07:46:17,620 INFO [Thread-59] impl.FsDatasetImpl
> (FsVolumeList.java:run(407)) - Time taken to scan block pool
> BP-725016459-10.79.60.8-1429281973548 on
> D:\w\tez\tez-tests\target\org.apache.tez.test.TestFaultTolerance-tmpDir\data\data2\current:
> 13ms
> 2015-04-17 07:46:17,620 INFO [Thread-58] impl.FsDatasetImpl
> (FsVolumeList.java:run(407)) - Time taken to scan block pool
> BP-725016459-10.79.60.8-1429281973548 on
> D:\w\tez\tez-tests\target\org.apache.tez.test.TestFaultTolerance-tmpDir\data\data1\current:
> 13ms
> 2015-04-17 07:46:17,620 INFO [DataNode:
> [[[DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data1/,
>
> [DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data2/]]
> heartbeating to /127.0.0.1:60605] impl.FsDatasetImpl
> (FsVolumeList.java:addBlockPool(433)) - Total time to scan all replicas for
> block pool BP-725016459-10.79.60.8-1429281973548: 16ms
> 2015-04-17 07:46:17,621 INFO [Thread-60] impl.FsDatasetImpl
> (FsVolumeList.java:run(189)) - Adding replicas to map for block pool
> BP-725016459-10.79.60.8-1429281973548 on volume
> D:\w\tez\tez-tests\target\org.apache.tez.test.TestFaultTolerance-tmpDir\data\data1\current...
> 2015-04-17 07:46:17,622 INFO [Thread-61] impl.FsDatasetImpl
> (FsVolumeList.java:run(189)) - Adding replicas to map for block pool
> BP-725016459-10.79.60.8-1429281973548 on volume
> D:\w\tez\tez-tests\target\org.apache.tez.test.TestFaultTolerance-tmpDir\data\data2\current...
> 2015-04-17 07:46:17,622 INFO [Thread-60] impl.FsDatasetImpl
> (FsVolumeList.java:run(194)) - Time to add replicas to map for block pool
> BP-725016459-10.79.60.8-1429281973548 on volume
> D:\w\tez\tez-tests\target\org.apache.tez.test.TestFaultTolerance-tmpDir\data\data1\current:
> 0ms
> 2015-04-17 07:46:17,622 INFO [Thread-61] impl.FsDatasetImpl
> (FsVolumeList.java:run(194)) - Time to add replicas to map for block pool
> BP-725016459-10.79.60.8-1429281973548 on volume
> D:\w\tez\tez-tests\target\org.apache.tez.test.TestFaultTolerance-tmpDir\data\data2\current:
> 0ms
> 2015-04-17 07:46:17,622 INFO [DataNode:
> [[[DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data1/,
>
> [DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data2/]]
> heartbeating to /127.0.0.1:60605] impl.FsDatasetImpl
> (FsVolumeList.java:getAllVolumesMap(220)) - Total time to add all replicas to
> map: 2ms
> 2015-04-17 07:46:17,625 INFO [DataNode:
> [[[DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data1/,
>
> [DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data2/]]
> heartbeating to /127.0.0.1:60605] datanode.DataNode
> (BPServiceActor.java:register(800)) - Block pool
> BP-725016459-10.79.60.8-1429281973548 (Datanode Uuid null) service to
> /127.0.0.1:60605 beginning handshake with NN
> 2015-04-17 07:46:17,639 INFO [IPC Server handler 3 on 60605]
> hdfs.StateChange (DatanodeManager.java:registerDatanode(879)) - BLOCK*
> registerDatanode: from DatanodeRegistration(127.0.0.1:60612,
> datanodeUuid=3139557f-6bc1-4529-937f-81657d6baf32, infoPort=60632,
> infoSecurePort=0, ipcPort=60633,
> storageInfo=lv=-56;cid=testClusterID;nsid=95952740;c=0) storage
> 3139557f-6bc1-4529-937f-81657d6baf32
> 2015-04-17 07:46:17,639 INFO [IPC Server handler 3 on 60605]
> blockmanagement.DatanodeDescriptor
> (DatanodeDescriptor.java:updateHeartbeatState(450)) - Number of failed
> storage changes from 0 to 0
> 2015-04-17 07:46:17,640 INFO [IPC Server handler 3 on 60605]
> net.NetworkTopology (NetworkTopology.java:add(419)) - Adding a new node:
> /default-rack/127.0.0.1:60612
> 2015-04-17 07:46:17,649 INFO [DataNode:
> [[[DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data1/,
>
> [DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data2/]]
> heartbeating to /127.0.0.1:60605] datanode.DataNode
> (BPServiceActor.java:register(818)) - Block pool Block pool
> BP-725016459-10.79.60.8-1429281973548 (Datanode Uuid null) service to
> /127.0.0.1:60605 successfully registered with NN
> 2015-04-17 07:46:17,649 INFO [DataNode:
> [[[DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data1/,
>
> [DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data2/]]
> heartbeating to /127.0.0.1:60605] datanode.DataNode
> (BPServiceActor.java:offerService(676)) - For namenode /127.0.0.1:60605 using
> DELETEREPORT_INTERVAL of 300000 msec BLOCKREPORT_INTERVAL of 21600000msec
> CACHEREPORT_INTERVAL of 10000msec Initial delay: 0msec; heartBeatInterval=3000
> 2015-04-17 07:46:17,666 INFO [IPC Server handler 6 on 60605]
> blockmanagement.DatanodeDescriptor
> (DatanodeDescriptor.java:updateHeartbeatState(450)) - Number of failed
> storage changes from 0 to 0
> 2015-04-17 07:46:17,667 INFO [IPC Server handler 6 on 60605]
> blockmanagement.DatanodeDescriptor
> (DatanodeDescriptor.java:updateStorage(856)) - Adding new storage ID
> DS-da6bd8c8-924e-43d2-9f85-75c88cb0c4fe for DN 127.0.0.1:60612
> 2015-04-17 07:46:17,668 INFO [IPC Server handler 6 on 60605]
> blockmanagement.DatanodeDescriptor
> (DatanodeDescriptor.java:updateStorage(856)) - Adding new storage ID
> DS-ef534adf-3270-4cb7-b038-16dc61f3f409 for DN 127.0.0.1:60612
> 2015-04-17 07:46:17,682 INFO [DataNode:
> [[[DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data1/,
>
> [DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data2/]]
> heartbeating to /127.0.0.1:60605] datanode.DataNode
> (BPOfferService.java:updateActorStatesFromHeartbeat(507)) - Namenode Block
> pool BP-725016459-10.79.60.8-1429281973548 (Datanode Uuid
> 3139557f-6bc1-4529-937f-81657d6baf32) service to /127.0.0.1:60605 trying to
> claim ACTIVE state with txid=1
> 2015-04-17 07:46:17,682 INFO [DataNode:
> [[[DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data1/,
>
> [DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data2/]]
> heartbeating to /127.0.0.1:60605] datanode.DataNode
> (BPOfferService.java:updateActorStatesFromHeartbeat(519)) - Acknowledging
> ACTIVE Namenode Block pool BP-725016459-10.79.60.8-1429281973548 (Datanode
> Uuid 3139557f-6bc1-4529-937f-81657d6baf32) service to /127.0.0.1:60605
> 2015-04-17 07:46:17,700 INFO [IPC Server handler 2 on 60605]
> BlockStateChange (BlockManager.java:processReport(1857)) - BLOCK*
> processReport: from storage DS-da6bd8c8-924e-43d2-9f85-75c88cb0c4fe node
> DatanodeRegistration(127.0.0.1:60612,
> datanodeUuid=3139557f-6bc1-4529-937f-81657d6baf32, infoPort=60632,
> infoSecurePort=0, ipcPort=60633,
> storageInfo=lv=-56;cid=testClusterID;nsid=95952740;c=0), blocks: 0,
> hasStaleStorage: true, processing time: 1 msecs
> 2015-04-17 07:46:17,700 INFO [IPC Server handler 2 on 60605]
> BlockStateChange (BlockManager.java:processReport(1857)) - BLOCK*
> processReport: from storage DS-ef534adf-3270-4cb7-b038-16dc61f3f409 node
> DatanodeRegistration(127.0.0.1:60612,
> datanodeUuid=3139557f-6bc1-4529-937f-81657d6baf32, infoPort=60632,
> infoSecurePort=0, ipcPort=60633,
> storageInfo=lv=-56;cid=testClusterID;nsid=95952740;c=0), blocks: 0,
> hasStaleStorage: false, processing time: 0 msecs
> 2015-04-17 07:46:17,724 INFO [main] hdfs.MiniDFSCluster
> (MiniDFSCluster.java:waitActive(2286)) - Cluster is active
> 2015-04-17 07:46:17,728 INFO [DataNode:
> [[[DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data1/,
>
> [DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data2/]]
> heartbeating to /127.0.0.1:60605] datanode.DataNode
> (BPServiceActor.java:blockReport(524)) - Successfully sent block report
> 0x90ef08c8e154, containing 2 storage report(s), of which we sent 2. The
> reports had 0 total blocks and used 1 RPC(s). This took 4 msec to generate
> and 42 msecs for RPC and NN processing. Got back one command:
> FinalizeCommand/5.
> 2015-04-17 07:46:17,728 INFO [DataNode:
> [[[DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data1/,
>
> [DISK]file:/D:/w/tez/tez-tests/target/org.apache.tez.test.TestFaultTolerance-tmpDir/data/data2/]]
> heartbeating to /127.0.0.1:60605] datanode.DataNode
> (BPOfferService.java:processCommandFromActive(690)) - Got finalize command
> for block pool BP-725016459-10.79.60.8-1429281973548
> 2015-04-17 07:46:18,270 INFO [main] test.MiniTezCluster
> (MiniTezCluster.java:serviceInit(119)) - Using Tez AppJar:
> D:\w\tez\tez-tests\target\test-dir\hadoop-3789028744640582056.jar
> 2015-04-17 07:46:18,293 INFO [IPC Server handler 0 on 60605]
> FSNamesystem.audit (FSNamesystem.java:logAuditMessage(8234)) - allowed=true
> ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo
> src=/user/jenkins/target/org.apache.tez.test.TestFaultTolerance-tmpDir/TezAppJar.jar
> dst=null perm=null proto=rpc
> 2015-04-17 07:46:18,351 INFO [IPC Server handler 1 on 60605]
> FSNamesystem.audit (FSNamesystem.java:logAuditMessage(8234)) - allowed=true
> ugi=jenkins (auth:SIMPLE) ip=/127.0.0.1 cmd=create
> src=/user/jenkins/target/org.apache.tez.test.TestFaultTolerance-tmpDir/TezAppJar.jar
> dst=null perm=jenkins:supergroup:rw-r--r-- proto=rpc
> 2015-04
> ...[truncated 654785 chars]...
> entQueue (ParentQueue.java:assignContainersToChildQueues(591)) - Re-sorting
> assigned queue: root.default stats: default: capacity=1.0,
> absoluteCapacity=1.0, usedResources=<memory:9216, vCores:9>,
> usedCapacity=0.5625, absoluteUsedCapacity=0.5625, numApps=1, numContainers=9
> 2015-04-17 07:48:16,517 INFO [ResourceManager Event Processor]
> capacity.ParentQueue (ParentQueue.java:assignContainers(428)) -
> assignedContainer queue=root usedCapacity=0.5625 absoluteUsedCapacity=0.5625
> used=<memory:9216, vCores:9> cluster=<memory:16384, vCores:32>
> 2015-04-17 07:48:16,517 INFO [AsyncDispatcher event handler]
> application.ApplicationImpl (ApplicationImpl.java:transition(304)) - Adding
> container_1429281980667_0001_01_000041 to application
> application_1429281980667_0001
> 2015-04-17 07:48:16,518 INFO [AsyncDispatcher event handler]
> container.ContainerImpl (ContainerImpl.java:handle(1123)) - Container
> container_1429281980667_0001_01_000041 transitioned from NEW to LOCALIZING
> 2015-04-17 07:48:16,518 INFO [AsyncDispatcher event handler]
> containermanager.AuxServices (AuxServices.java:handle(196)) - Got event
> CONTAINER_INIT for appId application_1429281980667_0001
> 2015-04-17 07:48:16,518 INFO [AsyncDispatcher event handler]
> containermanager.AuxServices (AuxServices.java:handle(196)) - Got event
> APPLICATION_INIT for appId application_1429281980667_0001
> 2015-04-17 07:48:16,518 INFO [AsyncDispatcher event handler]
> containermanager.AuxServices (AuxServices.java:handle(200)) - Got
> APPLICATION_INIT for service mapreduce_shuffle
> 2015-04-17 07:48:16,518 INFO [AsyncDispatcher event handler]
> mapred.ShuffleHandler (ShuffleHandler.java:addJobToken(560)) - Added token
> for job_1429281980667_0001
> 2015-04-17 07:48:16,519 INFO [AsyncDispatcher event handler]
> container.ContainerImpl (ContainerImpl.java:handle(1123)) - Container
> container_1429281980667_0001_01_000041 transitioned from LOCALIZING to
> LOCALIZED
> 2015-04-17 07:48:16,584 INFO [ContainersLauncher #1]
> launcher.ContainerLaunch (ContainerLaunch.java:call(346)) - Container
> container_1429281980667_0001_01_000038 succeeded
> 2015-04-17 07:48:16,589 INFO [Socket Reader #1 for port 60720] ipc.Server
> (Server.java:saslProcess(1316)) - Auth successful for
> appattempt_1429281980667_0001_000001 (auth:SIMPLE)
> 2015-04-17 07:48:16,596 INFO [IPC Server handler 3 on 60752]
> containermanager.ContainerManagerImpl
> (ContainerManagerImpl.java:startContainerInternal(816)) - Start request for
> container_1429281980667_0001_01_000042 by user jenkins
> 2015-04-17 07:48:16,597 INFO [IPC Server handler 3 on 60752]
> nodemanager.NMAuditLogger (NMAuditLogger.java:logSuccess(89)) - USER=jenkins
> IP=10.79.60.8 OPERATION=Start Container Request
> TARGET=ContainerManageImpl RESULT=SUCCESS
> APPID=application_1429281980667_0001
> CONTAINERID=container_1429281980667_0001_01_000042
> 2015-04-17 07:48:16,598 INFO [Thread-440] test.TestFaultTolerance
> (TestFaultTolerance.java:runDAGAndVerify(122)) - Waiting for dag to complete.
> Sleeping for 500ms. DAG name: testRandomFailingTasks DAG appContext:
> Executing on YARN cluster with App id application_1429281980667_0001 Current
> state: RUNNING
> 2015-04-17 07:48:16,600 INFO [IPC Server handler 7 on 60720]
> containermanager.ContainerManagerImpl
> (ContainerManagerImpl.java:startContainerInternal(816)) - Start request for
> container_1429281980667_0001_01_000040 by user jenkins
> 2015-04-17 07:48:16,600 INFO [IPC Server handler 7 on 60720]
> nodemanager.NMAuditLogger (NMAuditLogger.java:logSuccess(89)) - USER=jenkins
> IP=10.79.60.8 OPERATION=Start Container Request
> TARGET=ContainerManageImpl RESULT=SUCCESS
> APPID=application_1429281980667_0001
> CONTAINERID=container_1429281980667_0001_01_000040
> 2015-04-17 07:48:16,601 INFO [AsyncDispatcher event handler]
> application.ApplicationImpl (ApplicationImpl.java:transition(304)) - Adding
> container_1429281980667_0001_01_000040 to application
> application_1429281980667_0001
> 2015-04-17 07:48:16,601 INFO [AsyncDispatcher event handler]
> container.ContainerImpl (ContainerImpl.java:handle(1123)) - Container
> container_1429281980667_0001_01_000040 transitioned from NEW to LOCALIZING
> 2015-04-17 07:48:16,601 INFO [AsyncDispatcher event handler]
> containermanager.AuxServices (AuxServices.java:handle(196)) - Got event
> CONTAINER_INIT for appId application_1429281980667_0001
> 2015-04-17 07:48:16,601 INFO [AsyncDispatcher event handler]
> containermanager.AuxServices (AuxServices.java:handle(196)) - Got event
> APPLICATION_INIT for appId application_1429281980667_0001
> 2015-04-17 07:48:16,601 INFO [AsyncDispatcher event handler]
> containermanager.AuxServices (AuxServices.java:handle(200)) - Got
> APPLICATION_INIT for service mapreduce_shuffle
> 2015-04-17 07:48:16,601 INFO [AsyncDispatcher event handler]
> mapred.ShuffleHandler (ShuffleHandler.java:addJobToken(560)) - Added token
> for job_1429281980667_0001
> 2015-04-17 07:48:16,602 INFO [AsyncDispatcher event handler]
> container.ContainerImpl (ContainerImpl.java:handle(1123)) - Container
> container_1429281980667_0001_01_000040 transitioned from LOCALIZING to
> LOCALIZED
> 2015-04-17 07:48:16,722 INFO [AsyncDispatcher event handler]
> container.ContainerImpl (ContainerImpl.java:handle(1123)) - Container
> container_1429281980667_0001_01_000040 transitioned from LOCALIZED to RUNNING
> 2015-04-17 07:48:16,722 INFO [AsyncDispatcher event handler]
> util.ProcfsBasedProcessTree (ProcfsBasedProcessTree.java:isAvailable(192)) -
> ProcfsBasedProcessTree currently is supported only on Linux.
> 2015-04-17 07:48:16,734 INFO [AsyncDispatcher event handler]
> container.ContainerImpl (ContainerImpl.java:handle(1123)) - Container
> container_1429281980667_0001_01_000041 transitioned from LOCALIZED to RUNNING
> 2015-04-17 07:48:16,736 INFO [AsyncDispatcher event handler]
> util.ProcfsBasedProcessTree (ProcfsBasedProcessTree.java:isAvailable(192)) -
> ProcfsBasedProcessTree currently is supported only on Linux.
> 2015-04-17 07:48:16,762 INFO [AsyncDispatcher event handler]
> container.ContainerImpl (ContainerImpl.java:handle(1123)) - Container
> container_1429281980667_0001_01_000038 transitioned from KILLING to
> EXITED_WITH_SUCCESS
> 2015-04-17 07:48:16,763 INFO [AsyncDispatcher event handler]
> application.ApplicationImpl (ApplicationImpl.java:transition(304)) - Adding
> container_1429281980667_0001_01_000042 to application
> application_1429281980667_0001
> 2015-04-17 07:48:16,764 INFO [AsyncDispatcher event handler]
> container.ContainerImpl (ContainerImpl.java:handle(1123)) - Container
> container_1429281980667_0001_01_000042 transitioned from NEW to LOCALIZING
> 2015-04-17 07:48:16,765 INFO [AsyncDispatcher event handler]
> nodemanager.NMAuditLogger (NMAuditLogger.java:logSuccess(89)) - USER=jenkins
> OPERATION=Container Finished - Succeeded TARGET=ContainerImpl
> RESULT=SUCCESS APPID=application_1429281980667_0001
> CONTAINERID=container_1429281980667_0001_01_000038
> 2015-04-17 07:48:16,765 INFO [AsyncDispatcher event handler]
> container.ContainerImpl (ContainerImpl.java:handle(1123)) - Container
> container_1429281980667_0001_01_000038 transitioned from EXITED_WITH_SUCCESS
> to DONE
> 2015-04-17 07:48:16,765 INFO [AsyncDispatcher event handler]
> containermanager.AuxServices (AuxServices.java:handle(196)) - Got event
> CONTAINER_INIT for appId application_1429281980667_0001
> 2015-04-17 07:48:16,765 INFO [AsyncDispatcher event handler]
> containermanager.AuxServices (AuxServices.java:handle(196)) - Got event
> APPLICATION_INIT for appId application_1429281980667_0001
> 2015-04-17 07:48:16,766 INFO [AsyncDispatcher event handler]
> containermanager.AuxServices (AuxServices.java:handle(200)) - Got
> APPLICATION_INIT for service mapreduce_shuffle
> 2015-04-17 07:48:16,767 INFO [AsyncDispatcher event handler]
> mapred.ShuffleHandler (ShuffleHandler.java:addJobToken(560)) - Added token
> for job_1429281980667_0001
> 2015-04-17 07:48:16,767 INFO [AsyncDispatcher event handler]
> application.ApplicationImpl (ApplicationImpl.java:transition(347)) - Removing
> container_1429281980667_0001_01_000038 from application
> application_1429281980667_0001
> 2015-04-17 07:48:16,767 INFO [AsyncDispatcher event handler]
> util.ProcfsBasedProcessTree (ProcfsBasedProcessTree.java:isAvailable(192)) -
> ProcfsBasedProcessTree currently is supported only on Linux.
> 2015-04-17 07:48:16,769 INFO [ContainersLauncher #1]
> nodemanager.DefaultContainerExecutor
> (DefaultContainerExecutor.java:buildCommandExecutor(267)) - launchContainer:
> [D:\w\tez\HADOOP_LATEST\bin\winutils.exe, task, create, -m, -1, -c, -1,
> container_1429281980667_0001_01_000040, cmd /c
> D:/tmp/tez-dal/1429281978218/org.apache.tez.test.TestFaultTolerance-localDir-nm-0_0/usercache/jenkins/appcache/application_1429281980667_0001/container_1429281980667_0001_01_000040/default_container_executor.cmd]
> 2015-04-17 07:48:16,770 INFO [DeletionService #1]
> nodemanager.DefaultContainerExecutor
> (DefaultContainerExecutor.java:deleteAsUser(457)) - Deleting absolute path :
> D:/tmp/tez-dal/1429281978218/org.apache.tez.test.TestFaultTolerance-localDir-nm-2_0/usercache/jenkins/appcache/application_1429281980667_0001/container_1429281980667_0001_01_000038
> 2015-04-17 07:48:16,776 INFO [Thread-440] test.TestFaultTolerance
> (TestFaultTolerance.java:runDAGAndVerify(122)) - Waiting for dag to complete.
> Sleeping for 500ms. DAG name: testRandomFailingTasks DAG appContext:
> Executing on YARN cluster with App id application_1429281980667_0001 Current
> state: RUNNING
> 2015-04-17 07:48:16,820 INFO [AsyncDispatcher event handler]
> monitor.ContainersMonitorImpl (ContainersMonitorImpl.java:isEnabled(192)) -
> Neither virutal-memory nor physical-memory monitoring is needed. Not running
> the monitor-thread
> 2015-04-17 07:48:16,831 INFO [ContainersLauncher #2]
> nodemanager.DefaultContainerExecutor
> (DefaultContainerExecutor.java:buildCommandExecutor(267)) - launchContainer:
> [D:\w\tez\HADOOP_LATEST\bin\winutils.exe, task, create, -m, -1, -c, -1,
> container_1429281980667_0001_01_000041, cmd /c
> D:/tmp/tez-dal/1429281978218/org.apache.tez.test.TestFaultTolerance-localDir-nm-1_0/usercache/jenkins/appcache/application_1429281980667_0001/container_1429281980667_0001_01_000041/default_container_executor.cmd]
> 2015-04-17 07:48:16,843 INFO [ContainersLauncher #2]
> launcher.ContainerLaunch (ContainerLaunch.java:call(346)) - Container
> container_1429281980667_0001_01_000037 succeeded
> 2015-04-17 07:48:16,856 INFO [AsyncDispatcher event handler]
> monitor.ContainersMonitorImpl (ContainersMonitorImpl.java:isEnabled(192)) -
> Neither virutal-memory nor physical-memory monitoring is needed. Not running
> the monitor-thread
> 2015-04-17 07:48:16,857 INFO [AsyncDispatcher event handler]
> containermanager.AuxServices (AuxServices.java:handle(196)) - Got event
> CONTAINER_STOP for appId application_1429281980667_0001
> 2015-04-17 07:48:16,857 INFO [AsyncDispatcher event handler]
> container.ContainerImpl (ContainerImpl.java:handle(1123)) - Container
> container_1429281980667_0001_01_000042 transitioned from LOCALIZING to
> LOCALIZED
> 2015-04-17 07:48:16,896 INFO [AsyncDispatcher event handler]
> container.ContainerImpl (ContainerImpl.java:handle(1123)) - Container
> container_1429281980667_0001_01_000037 transitioned from KILLING to
> EXITED_WITH_SUCCESS
> 2015-04-17 07:48:16,898 INFO [AsyncDispatcher event handler]
> nodemanager.NMAuditLogger (NMAuditLogger.java:logSuccess(89)) - USER=jenkins
> OPERATION=Container Finished - Succeeded TARGET=ContainerImpl
> RESULT=SUCCESS APPID=application_1429281980667_0001
> CONTAINERID=container_1429281980667_0001_01_000037
> 2015-04-17 07:48:16,898 INFO [AsyncDispatcher event handler]
> container.ContainerImpl (ContainerImpl.java:handle(1123)) - Container
> container_1429281980667_0001_01_000037 transitioned from EXITED_WITH_SUCCESS
> to DONE
> 2015-04-17 07:48:16,898 INFO [AsyncDispatcher event handler]
> application.ApplicationImpl (ApplicationImpl.java:transition(347)) - Removing
> container_1429281980667_0001_01_000037 from application
> application_1429281980667_0001
> 2015-04-17 07:48:16,898 INFO [AsyncDispatcher event handler]
> util.ProcfsBasedProcessTree (ProcfsBasedProcessTree.java:isAvailable(192)) -
> ProcfsBasedProcessTree currently is supported only on Linux.
> 2015-04-17 07:48:16,899 INFO [DeletionService #1]
> nodemanager.DefaultContainerExecutor
> (DefaultContainerExecutor.java:deleteAsUser(457)) - Deleting absolute path :
> D:/tmp/tez-dal/1429281978218/org.apache.tez.test.TestFaultTolerance-localDir-nm-3_0/usercache/jenkins/appcache/application_1429281980667_0001/container_1429281980667_0001_01_000037
> 2015-04-17 07:48:16,913 INFO [Thread-440] test.TestFaultTolerance
> (TestFaultTolerance.java:runDAGAndVerify(122)) - Waiting for dag to complete.
> Sleeping for 500ms. DAG name: testRandomFailingTasks DAG appContext:
> Executing on YARN cluster with App id application_1429281980667_0001 Current
> state: RUNNING
> 2015-04-17 07:48:16,961 INFO [AsyncDispatcher event handler]
> monitor.ContainersMonitorImpl (ContainersMonitorImpl.java:isEnabled(192)) -
> Neither virutal-memory nor physical-memory monitoring is needed. Not running
> the monitor-thread
> 2015-04-17 07:48:16,962 INFO [AsyncDispatcher event handler]
> container.ContainerImpl (ContainerImpl.java:handle(1123)) - Container
> container_1429281980667_0001_01_000042 transitioned from LOCALIZED to RUNNING
> 2015-04-17 07:48:16,962 INFO [AsyncDispatcher event handler]
> util.ProcfsBasedProcessTree (ProcfsBasedProcessTree.java:isAvailable(192)) -
> ProcfsBasedProcessTree currently is supported only on Linux.
> 2015-04-17 07:48:16,976 INFO [ContainersLauncher #1]
> nodemanager.DefaultContainerExecutor
> (DefaultContainerExecutor.java:buildCommandExecutor(267)) - launchContainer:
> [D:\w\tez\HADOOP_LATEST\bin\winutils.exe, task, create, -m, -1, -c, -1,
> container_1429281980667_0001_01_000042, cmd /c
> D:/tmp/tez-dal/1429281978218/org.apache.tez.test.TestFaultTolerance-localDir-nm-2_0/usercache/jenkins/appcache/application_1429281980667_0001/container_1429281980667_0001_01_000042/default_container_executor.cmd]
> 2015-04-17 07:48:16,998 INFO [AsyncDispatcher event handler]
> monitor.ContainersMonitorImpl (ContainersMonitorImpl.java:isEnabled(192)) -
> Neither virutal-memory nor physical-memory monitoring is needed. Not running
> the monitor-thread
> 2015-04-17 07:48:16,998 INFO [AsyncDispatcher event handler]
> containermanager.AuxServices (AuxServices.java:handle(196)) - Got event
> CONTAINER_STOP for appId application_1429281980667_0001
> 2015-04-17 07:48:17,015 INFO [Thread-440] test.TestFaultTolerance
> (TestFaultTolerance.java:runDAGAndVerify(122)) - Waiting for dag to complete.
> Sleeping for 500ms. DAG name: testRandomFailingTasks DAG appContext:
> Executing on YARN cluster with App id application_1429281980667_0001 Current
> state: RUNNING
> 2015-04-17 07:48:17,065 INFO [AsyncDispatcher event handler]
> monitor.ContainersMonitorImpl (ContainersMonitorImpl.java:isEnabled(192)) -
> Neither virutal-memory nor physical-memory monitoring is needed. Not running
> the monitor-thread
> 2015-04-17 07:48:17,179 INFO [Thread-440] test.TestFaultTolerance
> (TestFaultTolerance.java:runDAGAndVerify(122)) - Waiting for dag to complete.
> Sleeping for 500ms. DAG name: testRandomFailingTasks DAG appContext:
> Executing on YARN cluster with App id application_1429281980667_0001 Current
> state: RUNNING
> 2015-04-17 07:48:17,186 INFO [Socket Reader #1 for port 60752] ipc.Server
> (Server.java:saslProcess(1316)) - Auth successful for
> appattempt_1429281980667_0001_000001 (auth:SIMPLE)
> 2015-04-17 07:48:17,190 INFO [IPC Server handler 2 on 60752]
> containermanager.ContainerManagerImpl
> (ContainerManagerImpl.java:stopContainerInternal(966)) - Stopping container
> with container Id: container_1429281980667_0001_01_000029
> 2015-04-17 07:48:17,190 INFO [AsyncDispatcher event handler]
> container.ContainerImpl (ContainerImpl.java:handle(1123)) - Container
> container_1429281980667_0001_01_000029 transitioned from RUNNING to KILLING
> 2015-04-17 07:48:17,190 INFO [AsyncDispatcher event handler]
> launcher.ContainerLaunch (ContainerLaunch.java:cleanupContainer(370)) -
> Cleaning up container container_1429281980667_0001_01_000029
> 2015-04-17 07:48:17,191 INFO [IPC Server handler 2 on 60752]
> nodemanager.NMAuditLogger (NMAuditLogger.java:logSuccess(89)) - USER=jenkins
> IP=10.79.60.8 OPERATION=Stop Container Request
> TARGET=ContainerManageImpl RESULT=SUCCESS
> APPID=application_1429281980667_0001
> CONTAINERID=container_1429281980667_0001_01_000029
> 2015-04-17 07:48:17,208 INFO [ResourceManager Event Processor]
> rmcontainer.RMContainerImpl (RMContainerImpl.java:handle(384)) -
> container_1429281980667_0001_01_000042 Container Transitioned from ACQUIRED
> to RUNNING
> 2015-04-17 07:48:17,208 INFO [ResourceManager Event Processor]
> capacity.CapacityScheduler (CapacityScheduler.java:completedContainer(1282))
> - Null container completed...
> 2015-04-17 07:48:17,314 INFO [Thread-440] test.TestFaultTolerance
> (TestFaultTolerance.java:runDAGAndVerify(122)) - Waiting for dag to complete.
> Sleeping for 500ms. DAG name: testRandomFailingTasks DAG appContext:
> Executing on YARN cluster with App id application_1429281980667_0001 Current
> state: RUNNING
> 2015-04-17 07:48:17,440 INFO [ContainersLauncher #2]
> launcher.ContainerLaunch (ContainerLaunch.java:call(346)) - Container
> container_1429281980667_0001_01_000029 succeeded
> 2015-04-17 07:48:17,554 INFO [ResourceManager Event Processor]
> rmcontainer.RMContainerImpl (RMContainerImpl.java:handle(384)) -
> container_1429281980667_0001_01_000040 Container Transitioned from ACQUIRED
> to RUNNING
> 2015-04-17 07:48:17,556 INFO [Thread-440] test.TestFaultTolerance
> (TestFaultTolerance.java:runDAGAndVerify(122)) - Waiting for dag to complete.
> Sleeping for 500ms. DAG name: testRandomFailingTasks DAG appContext:
> Executing on YARN cluster with App id application_1429281980667_0001 Current
> state: RUNNING
> 2015-04-17 07:48:17,569 INFO [Socket Reader #1 for port 60696] ipc.Server
> (Server.java:saslProcess(1316)) - Auth successful for
> appattempt_1429281980667_0001_000001 (auth:SIMPLE)
> 2015-04-17 07:48:17,718 INFO [ResourceManager Event Processor]
> rmcontainer.RMContainerImpl (RMContainerImpl.java:handle(384)) -
> container_1429281980667_0001_01_000037 Container Transitioned from RUNNING to
> COMPLETED
> 2015-04-17 07:48:17,719 INFO [ResourceManager Event Processor]
> fica.FiCaSchedulerApp (FiCaSchedulerApp.java:containerCompleted(113)) -
> Completed container: container_1429281980667_0001_01_000037 in state:
> COMPLETED event:FINISHED
> 2015-04-17 07:48:17,720 INFO [ResourceManager Event Processor]
> resourcemanager.RMAuditLogger (RMAuditLogger.java:logSuccess(106)) -
> USER=jenkins OPERATION=AM Released Container TARGET=SchedulerApp
> RESULT=SUCCESS APPID=application_1429281980667_0001
> CONTAINERID=container_1429281980667_0001_01_000037
> 2015-04-17 07:48:17,720 INFO [ResourceManager Event Processor]
> scheduler.SchedulerNode (SchedulerNode.java:releaseContainer(216)) - Released
> container container_1429281980667_0001_01_000037 of capacity <memory:1024,
> vCores:1> on host
> sijenkins-win-3.sijenkinsservice.d3.internal.cloudapp.net:60774, which
> currently has 1 containers, <memory:1024, vCores:1> used and <memory:3072,
> vCores:7> available, release resources=true
> 2015-04-17 07:48:17,720 INFO [ResourceManager Event Processor]
> capacity.LeafQueue (LeafQueue.java:releaseResource(1780)) - default
> used=<memory:8192, vCores:8> numContainers=8 user=jenkins
> user-resources=<memory:8192, vCores:8>
> 2015-04-17 07:48:17,738 INFO [AsyncDispatcher event handler]
> container.ContainerImpl (ContainerImpl.java:handle(1123)) - Container
> container_1429281980667_0001_01_000029 transitioned from KILLING to
> EXITED_WITH_SUCCESS
> 2015-04-17 07:48:17,739 INFO [DeletionService #2]
> nodemanager.DefaultContainerExecutor
> (DefaultContainerExecutor.java:deleteAsUser(457)) - Deleting absolute path :
> D:/tmp/tez-dal/1429281978218/org.apache.tez.test.TestFaultTolerance-localDir-nm-2_0/usercache/jenkins/appcache/application_1429281980667_0001/container_1429281980667_0001_01_000029
> 2015-04-17 07:48:17,981 INFO [ResourceManager Event Processor]
> capacity.LeafQueue (LeafQueue.java:completedContainer(1731)) -
> completedContainer container=Container: [ContainerId:
> container_1429281980667_0001_01_000037, NodeId:
> sijenkins-win-3.sijenkinsservice.d3.internal.cloudapp.net:60774,
> NodeHttpAddress:
> sijenkins-win-3.sijenkinsservice.d3.internal.cloudapp.net:60789, Resource:
> <memory:1024, vCores:1>, Priority: 4, Token: Token { kind: ContainerToken,
> service: 10.79.60.8:60774 }, ] queue=default: capacity=1.0,
> absoluteCapacity=1.0, usedResources=<memory:8192, vCores:8>,
> usedCapacity=0.5, absoluteUsedCapacity=0.5, numApps=1, numContainers=8
> cluster=<memory:16384, vCores:32>
> 2015-04-17 07:48:17,983 INFO [ResourceManager Event Processor]
> capacity.ParentQueue (ParentQueue.java:completedContainer(636)) -
> completedContainer queue=root usedCapacity=0.5 absoluteUsedCapacity=0.5
> used=<memory:8192, vCores:8> cluster=<memory:16384, vCores:32>
> 2015-04-17 07:48:17,983 INFO [ResourceManager Event Processor]
> capacity.ParentQueue (ParentQueue.java:completedContainer(653)) - Re-sorting
> completed queue: root.default stats: default: capacity=1.0,
> absoluteCapacity=1.0, usedResources=<memory:8192, vCores:8>,
> usedCapacity=0.5, absoluteUsedCapacity=0.5, numApps=1, numContainers=8
> 2015-04-17 07:48:17,983 INFO [ResourceManager Event Processor]
> capacity.CapacityScheduler (CapacityScheduler.java:completedContainer(1307))
> - Application attempt appattempt_1429281980667_0001_000001 released container
> container_1429281980667_0001_01_000037 on node: host:
> sijenkins-win-3.sijenkinsservice.d3.internal.cloudapp.net:60774 #containers=1
> available=<memory:3072, vCores:7> used=<memory:1024, vCores:1> with event:
> FINISHED
> 2015-04-17 07:48:17,983 INFO [ResourceManager Event Processor]
> rmcontainer.RMContainerImpl (RMContainerImpl.java:handle(384)) -
> container_1429281980667_0001_01_000041 Container Transitioned from ACQUIRED
> to RUNNING
> 2015-04-17 07:48:17,982 INFO [AsyncDispatcher event handler]
> nodemanager.NMAuditLogger (NMAuditLogger.java:logSuccess(89)) - USER=jenkins
> OPERATION=Container Finished - Succeeded TARGET=ContainerImpl
> RESULT=SUCCESS APPID=application_1429281980667_0001
> CONTAINERID=container_1429281980667_0001_01_000029
> 2015-04-17 07:48:17,986 INFO [Thread-440] test.TestFaultTolerance
> (TestFaultTolerance.java:runDAGAndVerify(122)) - Waiting for dag to complete.
> Sleeping for 500ms. DAG name: testRandomFailingTasks DAG appContext:
> Executing on YARN cluster with App id application_1429281980667_0001 Current
> state: RUNNING
> 2015-04-17 07:48:17,986 INFO [IPC Server handler 14 on 60696]
> rmcontainer.RMContainerImpl (RMContainerImpl.java:handle(384)) -
> container_1429281980667_0001_01_000029 Container Transitioned from RUNNING to
> RELEASED
> 2015-04-17 07:48:17,987 INFO [IPC Server handler 14 on 60696]
> fica.FiCaSchedulerApp (FiCaSchedulerApp.java:containerCompleted(113)) -
> Completed container: container_1429281980667_0001_01_000029 in state:
> RELEASED event:RELEASED
> 2015-04-17 07:48:17,987 INFO [IPC Server handler 14 on 60696]
> resourcemanager.RMAuditLogger (RMAuditLogger.java:logSuccess(106)) -
> USER=jenkins IP=10.79.60.8 OPERATION=AM Released Container
> TARGET=SchedulerApp RESULT=SUCCESS APPID=application_1429281980667_0001
> CONTAINERID=container_1429281980667_0001_01_000029
> 2015-04-17 07:48:17,986 INFO [AsyncDispatcher event handler]
> container.ContainerImpl (ContainerImpl.java:handle(1123)) - Container
> container_1429281980667_0001_01_000029 transitioned from EXITED_WITH_SUCCESS
> to DONE
> 2015-04-17 07:48:17,988 INFO [AsyncDispatcher event handler]
> application.ApplicationImpl (ApplicationImpl.java:transition(347)) - Removing
> container_1429281980667_0001_01_000029 from application
> application_1429281980667_0001
> 2015-04-17 07:48:17,988 INFO [AsyncDispatcher event handler]
> util.ProcfsBasedProcessTree (ProcfsBasedProcessTree.java:isAvailable(192)) -
> ProcfsBasedProcessTree currently is supported only on Linux.
> 2015-04-17 07:48:17,987 INFO [IPC Server handler 14 on 60696]
> scheduler.SchedulerNode (SchedulerNode.java:releaseContainer(216)) - Released
> container container_1429281980667_0001_01_000029 of capacity <memory:1024,
> vCores:1> on host
> sijenkins-win-3.sijenkinsservice.d3.internal.cloudapp.net:60752, which
> currently has 2 containers, <memory:2048, vCores:2> used and <memory:2048,
> vCores:6> available, release resources=true
> 2015-04-17 07:48:17,992 INFO [IPC Server handler 14 on 60696]
> capacity.LeafQueue (LeafQueue.java:releaseResource(1780)) - default
> used=<memory:7168, vCores:7> numContainers=7 user=jenkins
> user-resources=<memory:7168, vCores:7>
> 2015-04-17 07:48:18,054 INFO [IPC Server handler 14 on 60696]
> capacity.LeafQueue (LeafQueue.java:completedContainer(1731)) -
> completedContainer container=Container: [ContainerId:
> container_1429281980667_0001_01_000029, NodeId:
> sijenkins-win-3.sijenkinsservice.d3.internal.cloudapp.net:60752,
> NodeHttpAddress:
> sijenkins-win-3.sijenkinsservice.d3.internal.cloudapp.net:60767, Resource:
> <memory:1024, vCores:1>, Priority: 1, Token: Token { kind: ContainerToken,
> service: 10.79.60.8:60752 }, ] queue=default: capacity=1.0,
> absoluteCapacity=1.0, usedResources=<memory:7168, vCores:7>,
> usedCapacity=0.4375, absoluteUsedCapacity=0.4375, numApps=1, numContainers=7
> cluster=<memory:16384, vCores:32>
> 2015-04-17 07:48:18,055 INFO [IPC Server handler 14 on 60696]
> capacity.ParentQueue (ParentQueue.java:completedContainer(636)) -
> completedContainer queue=root usedCapacity=0.4375 absoluteUsedCapacity=0.4375
> used=<memory:7168, vCores:7> cluster=<memory:16384, vCores:32>
> 2015-04-17 07:48:18,055 INFO [IPC Server handler 14 on 60696]
> capacity.ParentQueue (ParentQueue.java:completedContainer(653)) - Re-sorting
> completed queue: root.default stats: default: capacity=1.0,
> absoluteCapacity=1.0, usedResources=<memory:7168, vCores:7>,
> usedCapacity=0.4375, absoluteUsedCapacity=0.4375, numApps=1, numContainers=7
> 2015-04-17 07:48:18,055 INFO [IPC Server handler 14 on 60696]
> capacity.CapacityScheduler (CapacityScheduler.java:completedContainer(1307))
> - Application attempt appattempt_1429281980667_0001_000001 released container
> container_1429281980667_0001_01_000029 on node: host:
> sijenkins-win-3.sijenkinsservice.d3.internal.cloudapp.net:60752 #containers=2
> available=<memory:2048, vCores:6> used=<memory:2048, vCores:2> with event:
> RELEASED
> 2015-04-17 07:48:18,056 INFO [IPC Server handler 14 on 60696]
> scheduler.AbstractYarnScheduler
> (AbstractYarnScheduler.java:releaseContainers(472)) -
> container_1429281980667_0001_01_000037 doesn't exist. Add the container to
> the release request cache as it maybe on recovery.
> 2015-04-17 07:48:18,056 INFO [IPC Server handler 14 on 60696]
> capacity.CapacityScheduler (CapacityScheduler.java:completedContainer(1282))
> - Null container completed...
> 2015-04-17 07:48:18,056 INFO [IPC Server handler 14 on 60696]
> scheduler.AppSchedulingInfo
> (AppSchedulingInfo.java:updateResourceRequests(181)) - checking for
> deactivate of application :application_1429281980667_0001
> 2015-04-17 07:48:18,056 INFO [IPC Server handler 14 on 60696]
> scheduler.AppSchedulingInfo
> (AppSchedulingInfo.java:updateResourceRequests(181)) - checking for
> deactivate of application :application_1429281980667_0001
> 2015-04-17 07:48:18,058 INFO [IPC Server handler 14 on 60696]
> rmcontainer.RMContainerImpl (RMContainerImpl.java:handle(384)) -
> container_1429281980667_0001_01_000043 Container Transitioned from ALLOCATED
> to ACQUIRED
> 2015-04-17 07:48:18,059 INFO [IPC Server handler 14 on 60696]
> rmcontainer.RMContainerImpl (RMContainerImpl.java:handle(384)) -
> container_1429281980667_0001_01_000044 Container Transitioned from ALLOCATED
> to ACQUIRED
> 2015-04-17 07:48:18,386 INFO [Node Status Updater]
> nodemanager.NodeStatusUpdaterImpl
> (NodeStatusUpdaterImpl.java:removeOrTrackCompletedContainersFromContext(482))
> - Removed completed containers from NM context:
> [container_1429281980667_0001_01_000038]
> 2015-04-17 07:48:18,442 INFO [Thread-440] test.TestFaultTolerance
> (TestFaultTolerance.java:runDAGAndVerify(122)) - Waiting for dag to complete.
> Sleeping for 500ms. DAG name: testRandomFailingTasks DAG appContext:
> Executing on YARN cluster with App id application_1429281980667_0001 Current
> state: RUNNING
> 2015-04-17 07:48:18,442 INFO [ResourceManager Event Processor]
> capacity.CapacityScheduler (CapacityScheduler.java:completedContainer(1282))
> - Null container completed...
> 2015-04-17 07:48:18,444 INFO [AsyncDispatcher event handler]
> monitor.ContainersMonitorImpl (ContainersMonitorImpl.java:isEnabled(192)) -
> Neither virutal-memory nor physical-memory monitoring is needed. Not running
> the monitor-thread
> 2015-04-17 07:48:18,444 INFO [AsyncDispatcher event handler]
> containermanager.AuxServices (AuxServices.java:handle(196)) - Got event
> CONTAINER_STOP for appId application_1429281980667_0001
> 2015-04-17 07:48:18,450 INFO [ResourceManager Event Processor]
> rmcontainer.RMContainerImpl (RMContainerImpl.java:handle(384)) -
> container_1429281980667_0001_01_000045 Container Transitioned from NEW to
> ALLOCATED
> 2015-04-17 07:48:18,451 INFO [ResourceManager Event Processor]
> resourcemanager.RMAuditLogger (RMAuditLogger.java:logSuccess(106)) -
> USER=jenkins OPERATION=AM Allocated Container TARGET=SchedulerApp
> RESULT=SUCCESS APPID=application_1429281980667_0001
> CONTAINERID=container_1429281980667_0001_01_000045
> 2015-04-17 07:48:18,451 INFO [ResourceManager Event Processor]
> scheduler.SchedulerNode (SchedulerNode.java:allocateContainer(153)) -
> Assigned container container_1429281980667_0001_01_000045 of capacity
> <memory:1024, vCores:1> on host
> sijenkins-win-3.sijenkinsservice.d3.internal.cloudapp.net:60752, which has 3
> containers, <memory:3072, vCores:3> used and <memory:1024, vCores:5>
> available after allocation
> 2015-04-17 07:48:18,451 INFO [ResourceManager Event Processor]
> capacity.LeafQueue (LeafQueue.java:assignContainer(1628)) - assignedContainer
> application attempt=appattempt_1429281980667_0001_000001 container=Container:
> [ContainerId: container_1429281980667_0001_01_000045, NodeId:
> sijenkins-win-3.sijenkinsservice.d3.internal.cloudapp.net:60752,
> NodeHttpAddress:
> sijenkins-win-3.sijenkinsservice.d3.internal.cloudapp.net:60767, Resource:
> <memory:1024, vCores:1>, Priority: 16, Token: null, ] queue=default:
> capacity=1.0, absoluteCapacity=1.0, usedResources=<memory:7168, vCores:7>,
> usedCapacity=0.4375, absoluteUsedCapacity=0.4375, numApps=1, numContainers=7
> clusterResource=<memory:16384, vCores:32>
> 2015-04-17 07:48:18,453 INFO [ResourceManager Event Processor]
> capacity.ParentQueue (ParentQueue.java:assignContainersToChildQueues(591)) -
> Re-sorting assigned queue: root.default stats: default: capacity=1.0,
> absoluteCapacity=1.0, usedResources=<memory:8192, vCores:8>,
> usedCapacity=0.5, absoluteUsedCapacity=0.5, numApps=1, numContainers=8
> 2015-04-17 07:48:18,455 INFO [ResourceManager Event Processor]
> capacity.ParentQueue (ParentQueue.java:assignContainers(428)) -
> assignedContainer queue=root usedCapacity=0.5 absoluteUsedCapacity=0.5
> used=<memory:8192, vCores:8> cluster=<memory:16384, vCores:32>
> 2015-04-17 07:48:18,463 INFO [Socket Reader #1 for port 60736] ipc.Server
> (Server.java:saslProcess(1316)) - Auth successful for
> appattempt_1429281980667_0001_000001 (auth:SIMPLE)
> 2015-04-17 07:48:18,465 INFO [Node Status Updater]
> nodemanager.NodeStatusUpdaterImpl
> (NodeStatusUpdaterImpl.java:removeOrTrackCompletedContainersFromContext(482))
> - Removed completed containers from NM context:
> [container_1429281980667_0001_01_000035,
> container_1429281980667_0001_01_000021]
> 2015-04-17 07:48:18,490 INFO [IPC Server handler 0 on 60736]
> containermanager.ContainerManagerImpl
> (ContainerManagerImpl.java:startContainerInternal(816)) - Start request for
> container_1429281980667_0001_01_000043 by user jenkins
> 2015-04-17 07:48:18,491 INFO [IPC Server handler 0 on 60736]
> nodemanager.NMAuditLogger (NMAuditLogger.java:logSuccess(89)) - USER=jenkins
> IP=10.79.60.8 OPERATION=Start Container Request
> TARGET=ContainerManageImpl RESULT=SUCCESS
> APPID=application_1429281980667_0001
> CONTAINERID=container_1429281980667_0001_01_000043
> 2015-04-17 07:48:18,492 INFO [AsyncDispatcher event handler]
> application.ApplicationImpl (ApplicationImpl.java:transition(304)) - Adding
> container_1429281980667_0001_01_000043 to application
> application_1429281980667_0001
> 2015-04-17 07:48:18,492 INFO [AsyncDispatcher event handler]
> container.ContainerImpl (ContainerImpl.java:handle(1123)) - Container
> container_1429281980667_0001_01_000043 transitioned from NEW to LOCALIZING
> 2015-04-17 07:48:18,492 INFO [AsyncDispatcher event handler]
> containermanager.AuxServices (AuxServices.java:handle(196)) - Got event
> CONTAINER_INIT for appId application_1429281980667_0001
> 2015-04-17 07:48:18,492 INFO [AsyncDispatcher event handler]
> containermanager.AuxServices (AuxServices.java:handle(196)) - Got event
> APPLICATION_INIT for appId application_1429281980667_0001
> 2015-04-17 07:48:18,493 INFO [AsyncDispatcher event handler]
> containermanager.AuxServices (AuxServices.java:handle(200)) - Got
> APPLICATION_INIT for service mapreduce_shuffle
> 2015-04-17 07:48:18,494 INFO [AsyncDispatcher event handler]
> mapred.ShuffleHandler (ShuffleHandler.java:addJobToken(560)) - Added token
> for job_1429281980667_0001
> 2015-04-17 07:48:18,495 INFO [AsyncDispatcher event handler]
> container.ContainerImpl (ContainerImpl.java:handle(1123)) - Container
> container_1429281980667_0001_01_000043 transitioned from LOCALIZING to
> LOCALIZED
> 2015-04-17 07:48:18,680 INFO [Node Status Updater]
> nodemanager.NodeStatusUpdaterImpl
> (NodeStatusUpdaterImpl.java:removeOrTrackCompletedContainersFromContext(482))
> - Removed completed containers from NM context:
> [container_1429281980667_0001_01_000033]
> 2015-04-17 07:48:18,681 INFO [AsyncDispatcher event handler]
> container.ContainerImpl (ContainerImpl.java:handle(1123)) - Container
> container_1429281980667_0001_01_000043 transitioned from LOCALIZED to RUNNING
> 2015-04-17 07:48:18,681 INFO [AsyncDispatcher event handler]
> util.ProcfsBasedProcessTree (ProcfsBasedProcessTree.java:isAvailable(192)) -
> ProcfsBasedProcessTree currently is supported only on Linux.
> 2015-04-17 07:48:18,690 INFO [ContainersLauncher #1]
> nodemanager.DefaultContainerExecutor
> (DefaultContainerExecutor.java:buildCommandExecutor(267)) - launchContainer:
> [D:\w\tez\HADOOP_LATEST\bin\winutils.exe, task, create, -m, -1, -c, -1,
> container_1429281980667_0001_01_000043, cmd /c
> D:/tmp/tez-dal/1429281978218/org.apache.tez.test.TestFaultTolerance-localDir-nm-1_0/usercache/jenkins/appcache/application_1429281980667_0001/container_1429281980667_0001_01_000043/default_container_executor.cmd]
> 2015-04-17 07:48:18,691 INFO [ResourceManager Event Processor]
> rmcontainer.RMContainerImpl (RMContainerImpl.java:handle(384)) -
> container_1429281980667_0001_01_000043 Container Transitioned from ACQUIRED
> to RUNNING
> 2015-04-17 07:48:19,123 INFO [Thread-440] test.TestFaultTolerance
> (TestFaultTolerance.java:runDAGAndVerify(122)) - Waiting for dag to complete.
> Sleeping for 500ms. DAG name: testRandomFailingTasks DAG appContext:
> Executing on YARN cluster with App id application_1429281980667_0001 Current
> state: RUNNING
> 2015-04-17 07:48:19,138 INFO [AsyncDispatcher event handler]
> monitor.ContainersMonitorImpl (ContainersMonitorImpl.java:isEnabled(192)) -
> Neither virutal-memory nor physical-memory monitoring is needed. Not running
> the monitor-thread
> 2015-04-17 07:48:19,143 INFO [Socket Reader #1 for port 60696] ipc.Server
> (Server.java:saslProcess(1316)) - Auth successful for
> appattempt_1429281980667_0001_000001 (auth:SIMPLE)
> 2015-04-17 07:48:19,146 INFO [IPC Server handler 35 on 60696]
> rmcontainer.RMContainerImpl (RMContainerImpl.java:handle(384)) -
> container_1429281980667_0001_01_000044 Container Transitioned from ACQUIRED
> to RELEASED
> 2015-04-17 07:48:19,147 INFO [IPC Server handler 35 on 60696]
> fica.FiCaSchedulerApp (FiCaSchedulerApp.java:containerCompleted(113)) -
> Completed container: container_1429281980667_0001_01_000044 in state:
> RELEASED event:RELEASED
> 2015-04-17 07:48:19,147 INFO [IPC Server handler 35 on 60696]
> resourcemanager.RMAuditLogger (RMAuditLogger.java:logSuccess(106)) -
> USER=jenkins IP=10.79.60.8 OPERATION=AM Released Container
> TARGET=SchedulerApp RESULT=SUCCESS APPID=application_1429281980667_0001
> CONTAINERID=container_1429281980667_0001_01_000044
> 2015-04-17 07:48:19,147 INFO [IPC Server handler 35 on 60696]
> scheduler.SchedulerNode (SchedulerNode.java:releaseContainer(216)) - Released
> container container_1429281980667_0001_01_000044 of capacity <memory:1024,
> vCores:1> on host
> sijenkins-win-3.sijenkinsservice.d3.internal.cloudapp.net:60774, which
> currently has 0 containers, <memory:0, vCores:0> used and <memory:4096,
> vCores:8> available, release resources=true
> 2015-04-17 07:48:19,148 INFO [IPC Server handler 35 on 60696]
> capacity.LeafQueue (LeafQueue.java:releaseResource(1780)) - default
> used=<memory:7168, vCores:7> numContainers=7 user=jenkins
> user-resources=<memory:7168, vCores:7>
> 2015-04-17 07:48:19,148 INFO [IPC Server handler 35 on 60696]
> capacity.LeafQueue (LeafQueue.java:completedContainer(1731)) -
> completedContainer container=Container: [ContainerId:
> container_1429281980667_0001_01_000044, NodeId:
> sijenkins-win-3.sijenkinsservice.d3.internal.cloudapp.net:60774,
> NodeHttpAddress:
> sijenkins-win-3.sijenkinsservice.d3.internal.cloudapp.net:60789, Resource:
> <memory:1024, vCores:1>, Priority: 17, Token: Token { kind: ContainerToken,
> service: 10.79.60.8:60774 }, ] queue=default: capacity=1.0,
> absoluteCapacity=1.0, usedResources=<memory:7168, vCores:7>,
> usedCapacity=0.4375, absoluteUsedCapacity=0.4375, numApps=1, numContainers=7
> cluster=<memory:16384, vCores:32>
> 2015-04-17 07:48:19,148 INFO [IPC Server handler 35 on 60696]
> capacity.ParentQueue (ParentQueue.java:completedContainer(636)) -
> completedContainer queue=root usedCapacity=0.4375 absoluteUsedCapacity=0.4375
> used=<memory:7168, vCores:7> cluster=<memory:16384, vCores:32>
> 2015-04-17 07:48:19,148 INFO [IPC Server handler 35 on 60696]
> capacity.ParentQueue (ParentQueue.java:completedContainer(653)) - Re-sorting
> completed queue: root.default stats: default: capacity=1.0,
> absoluteCapacity=1.0, usedResources=<memory:7168, vCores:7>,
> usedCapacity=0.4375, absoluteUsedCapacity=0.4375, numApps=1, numContainers=7
> 2015-04-17 07:48:19,149 INFO [IPC Server handler 35 on 60696]
> capacity.CapacityScheduler (CapacityScheduler.java:completedContainer(1307))
> - Application attempt appattempt_1429281980667_0001_000001 released container
> container_1429281980667_0001_01_000044 on node: host:
> sijenkins-win-3.sijenkinsservice.d3.internal.cloudapp.net:60774 #containers=0
> available=<memory:4096, vCores:8> used=<memory:0, vCores:0> with event:
> RELEASED
> 2015-04-17 07:48:19,150 INFO [IPC Server handler 35 on 60696]
> scheduler.AppSchedulingInfo
> (AppSchedulingInfo.java:updateResourceRequests(181)) - checking for
> deactivate of application :application_1429281980667_0001
> 2015-04-17 07:48:19,161 INFO [IPC Server handler 35 on 60696]
> rmcontainer.RMContainerImpl (RMContainerImpl.java:handle(384)) -
> container_1429281980667_0001_01_000045 Container Transitioned from ALLOCATED
> to ACQUIRED
> 2015-04-17 07:48:19,299 INFO [Thread-440] test.TestFaultTolerance
> (TestFaultTolerance.java:runDAGAndVerify(122)) - Waiting for dag to complete.
> Sleeping for 500ms. DAG name: testRandomFailingTasks DAG appContext:
> Executing on YARN cluster with App id application_1429281980667_0001 Current
> state: RUNNING
> 2015-04-17 07:48:19,436 INFO [Node Status Updater]
> nodemanager.NodeStatusUpdaterImpl
> (NodeStatusUpdaterImpl.java:removeOrTrackCompletedContainersFromContext(482))
> - Removed completed containers from NM context:
> [container_1429281980667_0001_01_000029]
> 2015-04-17 07:48:19,502 INFO [Thread-440] test.TestFaultTolerance
> (TestFaultTolerance.java:runDAGAndVerify(122)) - Waiting for dag to complete.
> Sleeping for 500ms. DAG name: testRandomFailingTasks DAG appContext:
> Executing on YARN cluster with App id application_1429281980667_0001 Current
> state: RUNNING
> 2015-04-17 07:48:19,872 INFO [Node Status Updater]
> nodemanager.NodeStatusUpdaterImpl
> (NodeStatusUpdaterImpl.java:removeOrTrackCompletedContainersFromContext(482))
> - Removed completed containers from NM context:
> [container_1429281980667_0001_01_000037]
> 2015-04-17 07:48:19,878 WARN [AsyncDispatcher event handler]
> containermanager.ContainerManagerImpl
> (ContainerManagerImpl.java:handle(1080)) - Event EventType: KILL_CONTAINER
> sent to absent container container_1429281980667_0001_01_000044
> 2015-04-17 07:48:19,879 INFO [Thread-440] test.TestFaultTolerance
> (TestFaultTolerance.java:runDAGAndVerify(122)) - Waiting for dag to complete.
> Sleeping for 500ms. DAG name: testRandomFailingTasks DAG appContext:
> Executing on YARN cluster with App id application_1429281980667_0001 Current
> state: RUNNING
> 2015-04-17 07:48:20,386 INFO [Socket Reader #1 for port 60696] ipc.Server
> (Server.java:saslProcess(1316)) - Auth successful for
> appattempt_1429281980667_0001_000001 (auth:SIMPLE)
> 2015-04-17 07:48:20,580 INFO [Thread-440] test.TestFaultTolerance
> (TestFaultTolerance.java:runDAGAndVerify(122)) - Waiting for dag to complete.
> Sleeping for 500ms. DAG name: testRandomFailingTasks DAG appContext:
> Executing on YARN cluster with App id application_1429281980667_0001 Current
> state: RUNNING
> 2015-04-17 07:48:20,652 INFO [IPC Server handler 35 on 60696]
> rmcontainer.RMContainerImpl (RMContainerImpl.java:handle(384)) -
> container_1429281980667_0001_01_000045 Container Transitioned from ACQUIRED
> to RELEASED
> 2015-04-17 07:48:20,652 INFO [IPC Server handler 35 on 60696]
> fica.FiCaSchedulerApp (FiCaSchedulerApp.java:containerCompleted(113)) -
> Completed container: container_1429281980667_0001_01_000045 in state:
> RELEASED event:RELEASED
> 2015-04-17 07:48:20,653 INFO [IPC Server handler 35 on 60696]
> resourcemanager.RMAuditLogger (RMAuditLogger.java:logSuccess(106)) -
> USER=jenkins IP=10.79.60.8 OPERATION=AM Released Container
> TARGET=SchedulerApp RESULT=SUCCESS APPID=application_1429281980667_0001
> CONTAINERID=container_1429281980667_0001_01_000045
> 2015-04-17 07:48:20,653 INFO [IPC Server handler 35 on 60696]
> scheduler.SchedulerNode (SchedulerNode.java:releaseContainer(216)) - Released
> container container_1429281980667_0001_01_000045 of capacity <memory:1024,
> vCores:1> on host
> sijenkins-win-3.sijenkinsservice.d3.internal.cloudapp.net:60752, which
> currently has 2 containers, <memory:2048, vCores:2> used and <memory:2048,
> vCores:6> available, release resources=true
> 2015-04-17 07:48:20,653 INFO [IPC Server handler 35 on 60696]
> capacity.LeafQueue (LeafQueue.java:releaseResource(1780)) - default
> used=<memory:6144, vCores:6> numContainers=6 user=jenkins
> user-resources=<memory:6144, vCores:6>
> 2015-04-17 07:48:20,654 INFO [IPC Server handler 35 on 60696]
> capacity.LeafQueue (LeafQueue.java:completedContainer(1731)) -
> completedContainer container=Container: [ContainerId:
> container_1429281980667_0001_01_000045, NodeId:
> sijenkins-win-3.sijenkinsservice.d3.internal.cloudapp.net:60752,
> NodeHttpAddress:
> sijenkins-win-3.sijenkinsservice.d3.internal.cloudapp.net:60767, Resource:
> <memory:1024, vCores:1>, Priority: 16, Token: Token { kind: ContainerToken,
> service: 10.79.60.8:60752 }, ] queue=default: capacity=1.0,
> absoluteCapacity=1.0, usedResources=<memory:6144, vCores:6>,
> usedCapacity=0.375, absoluteUsedCapacity=0.375, numApps=1, numContainers=6
> cluster=<memory:16384, vCores:32>
> 2015-04-17 07:48:20,711 INFO [IPC Server handler 35 on 60696]
> capacity.ParentQueue (ParentQueue.java:completedContainer(636)) -
> completedContainer queue=root usedCapacity=0.375 absoluteUsedCapacity=0.375
> used=<memory:6144, vCores:6> cluster=<memory:16384, vCores:32>
> 2015-04-17 07:48:20,711 INFO [IPC Server handler 35 on 60696]
> capacity.ParentQueue (ParentQueue.java:completedContainer(653)) - Re-sorting
> completed queue: root.default stats: default: capacity=1.0,
> absoluteCapacity=1.0, usedResources=<memory:6144, vCores:6>,
> usedCapacity=0.375, absoluteUsedCapacity=0.375, numApps=1, numContainers=6
> 2015-04-17 07:48:20,711 INFO [IPC Server handler 35 on 60696]
> capacity.CapacityScheduler (CapacityScheduler.java:completedContainer(1307))
> - Application attempt appattempt_1429281980667_0001_000001 released container
> container_1429281980667_0001_01_000045 on node: host:
> sijenkins-win-3.sijenkinsservice.d3.internal.cloudapp.net:60752 #containers=2
> available=<memory:2048, vCores:6> used=<memory:2048, vCores:2> with event:
> RELEASED
> 2015-04-17 07:48:20,898 WARN [AsyncDispatcher event handler]
> containermanager.ContainerManagerImpl
> (ContainerManagerImpl.java:handle(1080)) - Event EventType: KILL_CONTAINER
> sent to absent container container_1429281980667_0001_01_000045
> 2015-04-17 07:48:21,297 INFO [Thread-440] test.TestFaultTolerance
> (TestFaultTolerance.java:runDAGAndVerify(122)) - Waiting for dag to complete.
> Sleeping for 500ms. DAG name: testRandomFailingTasks DAG appContext:
> Executing on YARN cluster with App id application_1429281980667_0001 Current
> state: RUNNING
> 2015-04-17 07:48:21,479 INFO [Thread-440] test.TestFaultTolerance
> (TestFaultTolerance.java:runDAGAndVerify(122)) - Waiting for dag to complete.
> Sleeping for 500ms. DAG name: testRandomFailingTasks DAG appContext:
> Executing on YARN cluster with App id application_1429281980667_0001 Current
> state: RUNNING
> 2015-04-17 07:48:21,972 INFO [Socket Reader #1 for port 60696] ipc.Server
> (Server.java:saslProcess(1316)) - Auth successful for
> appattempt_1429281980667_0001_000001 (auth:SIMPLE)
> 2015-04-17 07:48:22,085 INFO [Thread-440] test.TestFaultTolerance
> (TestFaultTolerance.java:runDAGAndVerify(122)) - Waiting for dag to complete.
> Sleeping for 500ms. DAG name: testRandomFailingTasks DAG appContext:
> Executing on YARN cluster with App id application_1429281980667_0001 Current
> state: RUNNING
> 2015-04-17 07:48:22,460 INFO [Thread-440] test.TestFaultTolerance
> (TestFaultTolerance.java:runDAGAndVerify(122)) - Waiting for dag to complete.
> Sleeping for 500ms. DAG name: testRandomFailingTasks DAG appContext:
> Executing on YARN cluster with App id application_1429281980667_0001 Current
> state: RUNNING
> 2015-04-17 07:48:23,366 INFO [Thread-440] test.TestFaultTolerance
> (TestFaultTolerance.java:runDAGAndVerify(122)) - Waiting for dag to complete.
> Sleeping for 500ms. DAG name: testRandomFailingTasks DAG appContext:
> Executing on YARN cluster with App id application_1429281980667_0001 Current
> state: RUNNING
> 2015-04-17 07:48:23,429 INFO [Socket Reader #1 for port 60696] ipc.Server
> (Server.java:saslProcess(1316)) - Auth successful for
> appattempt_1429281980667_0001_000001 (auth:SIMPLE)
> 2015-04-17 07:48:23,546 INFO [Thread-440] test.TestFaultTolerance
> (TestFaultTolerance.java:runDAGAndVerify(122)) - Waiting for dag to complete.
> Sleeping for 500ms. DAG name: testRandomFailingTasks DAG appContext:
> Executing on YARN cluster with App id application_1429281980667_0001 Current
> state: RUNNING
> 2015-04-17 07:48:23,796 INFO [Thread-440] test.TestFaultTolerance
> (TestFaultTolerance.java:runDAGAndVerify(122)) - Waiting for dag to complete.
> Sleeping for 500ms. DAG name: testRandomFailingTasks DAG appContext:
> Executing on YARN cluster with App id application_1429281980667_0001 Current
> state: RUNNING
> 2015-04-17 07:48:23,979 INFO [Thread-440] test.TestFaultTolerance
> (TestFaultTolerance.java:runDAGAndVerify(122)) - Waiting for dag to complete.
> Sleeping for 500ms. DAG name: testRandomFailingTasks DAG appContext:
> Executing on YARN cluster with App id application_1429281980667_0001 Current
> state: RUNNING
> 2015-04-17 07:48:24,392 INFO [Thread-440] test.TestFaultTolerance
> (TestFaultTolerance.java:runDAGAndVerify(122)) - Waiting for dag to complete.
> Sleeping for 500ms. DAG name: testRandomFailingTasks DAG appContext:
> Executing on YARN cluster with App id application_1429281980667_0001 Current
> state: RUNNING
> 2015-04-17 07:48:24,809 INFO [Thread-440] test.TestFaultTolerance
> (TestFaultTolerance.java:runDAGAndVerify(122)) - Waiting for dag to complete.
> Sleeping for 500ms. DAG name: testRandomFailingTasks DAG appContext:
> Executing on YARN cluster with App id application_1429281980667_0001 Current
> state: RUNNING
> 2015-04-17 07:48:24,819 INFO [Socket Reader #1 for port 60696] ipc.Server
> (Server.java:saslProcess(1316)) - Auth successful for
> appattempt_1429281980667_0001_000001 (auth:SIMPLE)
> 2015-04-17 07:48:26,533 INFO [Thread-440] test.TestFaultTolerance
> (TestFaultTolerance.java:runDAGAndVerify(122)) - Waiting for dag to complete.
> Sleeping for 500ms. DAG name: testRandomFailingTasks DAG appContext:
> Executing on YARN cluster with App id application_1429281980667_0001 Current
> state: RUNNING
> 2015-04-17 07:48:26,552 INFO [Socket Reader #1 for port 60696] ipc.Server
> (Server.java:saslProcess(1316)) - Auth successful for
> appattempt_1429281980667_0001_000001 (auth:SIMPLE)
> 2015-04-17 07:48:26,666 INFO [Thread-440] test.TestFaultTolerance
> (TestFaultTolerance.java:runDAGAndVerify(122)) - Waiting for dag to complete.
> Sleeping for 500ms. DAG name: testRandomFailingTasks DAG appContext:
> Executing on YARN cluster with App id application_1429281980667_0001 Current
> state: RUNNING
> 2015-04-17 07:48:26,870 INFO [Thread-440] test.TestFaultTolerance
> (TestFaultTolerance.java:runDAGAndVerify(122)) - Waiting for dag to complete.
> Sleeping for 500ms. DAG name: testRandomFailingTasks DAG appContext:
> Executing on YARN cluster with App id application_1429281980667_0001 Current
> state: RUNNING
> 2015-04-17 07:48:27,002 INFO [Thread-440] test.TestFaultTolerance
> (TestFaultTolerance.java:runDAGAndVerify(122)) - Waiting for dag to complete.
> Sleeping for 500ms. DAG name: testRandomFailingTasks DAG appContext:
> Executing on YARN cluster with App id application_1429281980667_0001 Current
> state: RUNNING
> 2015-04-17 07:48:27,209 INFO [Thread-440] test.TestFaultTolerance
> (TestFaultTolerance.java:runDAGAndVerify(122)) - Waiting for dag to complete.
> Sleeping for 500ms. DAG name: testRandomFailingTasks DAG appContext:
> Executing on YARN cluster with App id application_1429281980667_0001 Current
> state: RUNNING
> 2015-04-17 07:48:27,346 INFO [Thread-440] test.TestFaultTolerance
> (TestFaultTolerance.java:runDAGAndVerify(122)) - Waiting for dag to complete.
> Sleeping for 500ms. DAG name: testRandomFailingTasks DAG appContext:
> Executing on YARN cluster with App id application_1429281980667_0001 Current
> state: RUNNING
> Standard Error
> Apr 17, 2015 7:46:22 AM
> com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory register
> INFO: Registering
> org.apache.hadoop.yarn.server.resourcemanager.webapp.JAXBContextResolver as a
> provider class
> Apr 17, 2015 7:46:22 AM
> com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory register
> INFO: Registering
> org.apache.hadoop.yarn.server.resourcemanager.webapp.RMWebServices as a root
> resource class
> Apr 17, 2015 7:46:22 AM
> com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory register
> INFO: Registering org.apache.hadoop.yarn.webapp.GenericExceptionHandler as a
> provider class
> Apr 17, 2015 7:46:22 AM
> com.sun.jersey.server.impl.application.WebApplicationImpl _initiate
> INFO: Initiating Jersey application, version 'Jersey: 1.9 09/02/2011 11:17 AM'
> Apr 17, 2015 7:46:22 AM
> com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory
> getComponentProvider
> INFO: Binding
> org.apache.hadoop.yarn.server.resourcemanager.webapp.JAXBContextResolver to
> GuiceManagedComponentProvider with the scope "Singleton"
> Apr 17, 2015 7:46:23 AM
> com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory
> getComponentProvider
> INFO: Binding org.apache.hadoop.yarn.webapp.GenericExceptionHandler to
> GuiceManagedComponentProvider with the scope "Singleton"
> Apr 17, 2015 7:46:24 AM
> com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory
> getComponentProvider
> INFO: Binding
> org.apache.hadoop.yarn.server.resourcemanager.webapp.RMWebServices to
> GuiceManagedComponentProvider with the scope "Singleton"
> Apr 17, 2015 7:46:24 AM 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.
> Apr 17, 2015 7:46:24 AM 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.
> Apr 17, 2015 7:46:24 AM
> com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory register
> INFO: Registering
> org.apache.hadoop.yarn.server.nodemanager.webapp.NMWebServices as a root
> resource class
> Apr 17, 2015 7:46:24 AM
> com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory register
> INFO: Registering org.apache.hadoop.yarn.webapp.GenericExceptionHandler as a
> provider class
> Apr 17, 2015 7:46:24 AM
> com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory register
> INFO: Registering
> org.apache.hadoop.yarn.server.nodemanager.webapp.JAXBContextResolver as a
> provider class
> Apr 17, 2015 7:46:24 AM
> com.sun.jersey.server.impl.application.WebApplicationImpl _initiate
> INFO: Initiating Jersey application, version 'Jersey: 1.9 09/02/2011 11:17 AM'
> Apr 17, 2015 7:46:24 AM
> com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory
> getComponentProvider
> INFO: Binding
> org.apache.hadoop.yarn.server.nodemanager.webapp.JAXBContextResolver to
> GuiceManagedComponentProvider with the scope "Singleton"
> Apr 17, 2015 7:46:24 AM
> com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory
> getComponentProvider
> INFO: Binding org.apache.hadoop.yarn.webapp.GenericExceptionHandler to
> GuiceManagedComponentProvider with the scope "Singleton"
> Apr 17, 2015 7:46:24 AM
> com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory
> getComponentProvider
> INFO: Binding org.apache.hadoop.yarn.server.nodemanager.webapp.NMWebServices
> to GuiceManagedComponentProvider with the scope "Singleton"
> Apr 17, 2015 7:46:24 AM 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.
> Apr 17, 2015 7:46:25 AM
> com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory register
> INFO: Registering
> org.apache.hadoop.yarn.server.nodemanager.webapp.NMWebServices as a root
> resource class
> Apr 17, 2015 7:46:25 AM
> com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory register
> INFO: Registering org.apache.hadoop.yarn.webapp.GenericExceptionHandler as a
> provider class
> Apr 17, 2015 7:46:25 AM
> com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory register
> INFO: Registering
> org.apache.hadoop.yarn.server.nodemanager.webapp.JAXBContextResolver as a
> provider class
> Apr 17, 2015 7:46:25 AM
> com.sun.jersey.server.impl.application.WebApplicationImpl _initiate
> INFO: Initiating Jersey application, version 'Jersey: 1.9 09/02/2011 11:17 AM'
> Apr 17, 2015 7:46:25 AM
> com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory
> getComponentProvider
> INFO: Binding
> org.apache.hadoop.yarn.server.nodemanager.webapp.JAXBContextResolver to
> GuiceManagedComponentProvider with the scope "Singleton"
> Apr 17, 2015 7:46:25 AM
> com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory
> getComponentProvider
> INFO: Binding org.apache.hadoop.yarn.webapp.GenericExceptionHandler to
> GuiceManagedComponentProvider with the scope "Singleton"
> Apr 17, 2015 7:46:25 AM
> com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory
> getComponentProvider
> INFO: Binding org.apache.hadoop.yarn.server.nodemanager.webapp.NMWebServices
> to GuiceManagedComponentProvider with the scope "Singleton"
> Apr 17, 2015 7:46:25 AM 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.
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
