[TEZ-2342] TestFaultTolerance.testRandomFailingTasks fails due to timeout - ASF JIRA

Agile Board

Attach files

Attach Screenshot

Voters

Watch issue

Watchers

Create sub-task

Link

Clone

Update Comment Author

Replace String in Comment

Update Comment Visibility

Delete Comments

XML

Word

Printable

JSON

Details

Type: Bug
Status: Closed
Priority: Minor
Resolution: Fixed
Affects Version/s: None
Fix Version/s: 0.7.0
Component/s: None
Labels:
None

Target Version/s:

0.7.0

Description

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.

Attachments

TEZ-2342-1.patch
21/Apr/15 03:27
1 kB
Jeff Zhang
syslog_dag_1429582868137_0001_1
21/Apr/15 03:02
951 kB
Jeff Zhang

Activity

Comment

This comment will be Viewable by All Users Viewable by All Users

Cancel

People

Assignee:: Jeff Zhang

Reporter:: Jeff Zhang

Votes:: 0 Vote for this issue

Watchers:: 3 Start watching this issue

Dates

Created:: 20/Apr/15 13:31

Updated:: 30/Jun/15 04:53

Resolved:: 27/Apr/15 19:01

Agile

View on Board

TestFaultTolerance.testRandomFailingTasks fails due to timeout

Details

Description

Attachments

Attachments

Activity

People

Dates

Agile

Slack

Issue deployment