You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@tez.apache.org by "Jeff Zhang (JIRA)" <ji...@apache.org> on 2015/04/21 05:03:58 UTC
[jira] [Updated] (TEZ-2342)
TestFaultTolerance.testRandomFailingTasks fails due to timeout
[ https://issues.apache.org/jira/browse/TEZ-2342?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Jeff Zhang updated TEZ-2342:
----------------------------
Summary: TestFaultTolerance.testRandomFailingTasks fails due to timeout (was: TestFaultTolerance.testRandomFailingTasks fails on windows)
> 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
> Attachments: 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)