Class cascading.flow.FlowStrategiesPlatformTest

3

tests

0

failures

0

ignored

5.569s

duration

100%

successful

Tests

Test Duration Result
testFlowStepStrategy 1.101s passed
testSkipStrategiesKeep 0.770s passed
testSkipStrategiesReplace 3.698s passed

Standard output

2016-01-14 17:08:19,090 INFO  platform.PlatformRunner (PlatformRunner.java:getPlatformClassesFromClasspath(195)) - found 1 test platforms from classpath
2016-01-14 17:08:19,113 INFO  platform.PlatformRunner (PlatformRunner.java:addPlatform(244)) - adding test: cascading.flow.FlowStrategiesPlatformTest, with platform: hadoop2-tez
2016-01-14 17:08:19,146 INFO  tez.Hadoop2TezPlatform (Hadoop2TezPlatform.java:setUp(136)) - not using cluster
2016-01-14 17:08:19,541 WARN  util.NativeCodeLoader (NativeCodeLoader.java:<clinit>(62)) - Unable to load native-hadoop library for your platform... using builtin-java classes where applicable
2016-01-14 17:08:19,895 INFO  platform.TestPlatform (TestPlatform.java:getGlobalProperties(73)) - platform property overrides: 
2016-01-14 17:08:20,098 INFO  util.Util (Util.java:findMainClass(1327)) - using default application jar, may cause class not found exceptions on the cluster
2016-01-14 17:08:20,100 INFO  planner.Hadoop2TezPlanner (Hadoop2TezPlanner.java:initialize(149)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-tez/3.0.4/561447ee876073bb61fddc52e2ad157f45c8edd/cascading-hadoop2-tez-3.0.4.jar
2016-01-14 17:08:20,215 INFO  property.AppProps (AppProps.java:getAppID(177)) - using app.id: B09D52508F65484AB6BF29DE29F7D017
2016-01-14 17:08:20,408 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.073
2016-01-14 17:08:20,420 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.086
2016-01-14 17:08:20,421 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test] rule registry: NoHashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 1
2016-01-14 17:08:20,422 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test] rule registry: HashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 1
2016-01-14 17:08:20,423 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test] rule registry: NoHashJoinHadoop2TezRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-01-14 17:08:20,576 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/classes/test/data/apache.10.txt
2016-01-14 17:08:20,580 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/output/hadoop2-tez/flowstrategiesplatform/testSkipStrategiesReplace/replace
2016-01-14 17:08:20,781 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test] at least one sink is marked for delete
2016-01-14 17:08:20,787 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test] sink oldest modified date: Wed Dec 31 23:59:59 UTC 1969
2016-01-14 17:08:20,788 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test] at least one sink is marked for delete
2016-01-14 17:08:20,789 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test] sink oldest modified date: Wed Dec 31 23:59:59 UTC 1969
2016-01-14 17:08:20,820 INFO  util.Version (Version.java:printBanner(82)) - Concurrent, Inc - Cascading 3.0.4
2016-01-14 17:08:20,821 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test] starting
2016-01-14 17:08:20,821 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test]  source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/classes/test/data/apache.10.txt"]
2016-01-14 17:08:20,822 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test]  sink: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/output/hadoop2-tez/flowstrategiesplatform/testSkipStrategiesReplace/replace"]
2016-01-14 17:08:20,822 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test]  parallel execution of steps is enabled: false
2016-01-14 17:08:20,822 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test]  executing total steps: 1
2016-01-14 17:08:20,823 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test]  allocating management threads: 1
2016-01-14 17:08:20,824 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test] starting step: (1/1) ...StrategiesReplace/replace
2016-01-14 17:08:20,824 WARN  flow.Flow (BaseFlow.java:logWarn(1445)) - [test] 'yarn.timeline-service.enabled' is disabled, please enable to capture detailed metrics of completed flows, this may require starting the YARN timeline server daemon
2016-01-14 17:08:20,855 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test] tez session mode enabled: true
2016-01-14 17:08:21,020 INFO  client.TezClient (TezClient.java:<init>(153)) - Tez Client Version: [ component=tez-api, version=0.6.2, revision=c04283bf91fd96823eec37056d5c8b1a92728265, SCM-URL=scm:git:https://git-wip-us.apache.org/repos/asf/tez.git, buildTime=20150804-1436 ]
2016-01-14 17:08:21,026 INFO  client.TezClient (TezClient.java:start(333)) - Session mode. Starting session.
2016-01-14 17:08:21,027 INFO  client.TezClientUtils (TezClientUtils.java:setupTezJarsLocalResources(159)) - Ignoring 'tez.lib.uris' since  'tez.ignore.lib.uris' is set to true
2016-01-14 17:08:21,075 INFO  client.TezClient (TezCommonUtils.java:createTezSystemStagingPath(118)) - Tez system stage directory file:/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/1E43515C97744D998F07322857EBCDB1/A3F922810955485A83E86883CFD6CEC5/.tez/application_1452791301026_0001 doesn't exist and is created
2016-01-14 17:08:21,153 INFO  client.LocalClient (LocalClient.java:createDAGAppMaster(328)) - DAGAppMaster thread has been created
2016-01-14 17:08:21,154 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-01-14 17:08:21,155 INFO  client.LocalClient (LocalClient.java:run(275)) - Using staging directory: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/1E43515C97744D998F07322857EBCDB1/A3F922810955485A83E86883CFD6CEC5/.tez/application_1452791301026_0001
2016-01-14 17:08:21,187 INFO  app.DAGAppMaster (DAGAppMaster.java:<init>(309)) - Created DAGAppMaster for application appattempt_1452791301026_0001_000000, versionInfo=[ component=tez-dag, version=0.6.2, revision=c04283bf91fd96823eec37056d5c8b1a92728265, SCM-URL=scm:git:https://git-wip-us.apache.org/repos/asf/tez.git, buildTime=20150804-1436 ]
2016-01-14 17:08:21,229 INFO  app.DAGAppMaster (DAGAppMaster.java:serviceInit(333)) - Comparing client version with AM version, clientVersion=0.6.2, AMVersion=0.6.2
2016-01-14 17:08:21,244 INFO  app.DAGAppMaster (DAGAppMaster.java:serviceInit(386)) - Adding session token to jobTokenSecretManager for application
2016-01-14 17:08:21,254 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: NEW
2016-01-14 17:08:21,255 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(238)) - DAGAppMaster is not started wait for 100ms...
2016-01-14 17:08:21,255 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-01-14 17:08:21,272 INFO  node.AMNodeTracker (AMNodeTracker.java:serviceInit(77)) - blacklistDisablePercent is 33, blacklistingEnabled: false, maxTaskFailuresPerNode: 1
2016-01-14 17:08:21,277 INFO  history.HistoryEventHandler (HistoryEventHandler.java:serviceInit(50)) - Initializing HistoryEventHandler
2016-01-14 17:08:21,281 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceInit(66)) - Log file location for SimpleHistoryLoggingService not specified, defaulting to containerLogDir=/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/1E43515C97744D998F07322857EBCDB1/A3F922810955485A83E86883CFD6CEC5/.tez/application_1452791301026_0001/localmode-log-dir
2016-01-14 17:08:21,281 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceInit(88)) - Initializing SimpleHistoryLoggingService, logFileLocation=/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/1E43515C97744D998F07322857EBCDB1/A3F922810955485A83E86883CFD6CEC5/.tez/application_1452791301026_0001/localmode-log-dir/history.txt.appattempt_1452791301026_0001_000000, maxErrors=10
2016-01-14 17:08:21,282 INFO  recovery.RecoveryService (RecoveryService.java:serviceInit(109)) - Initializing RecoveryService
2016-01-14 17:08:21,284 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:N/A][Event:AM_LAUNCHED]: appAttemptId=appattempt_1452791301026_0001_000000, appSubmitTime=1452791301173, launchTime=1452791301186
2016-01-14 17:08:21,289 INFO  history.HistoryEventHandler (HistoryEventHandler.java:serviceStart(73)) - Starting HistoryEventHandler
2016-01-14 17:08:21,289 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStart(95)) - Starting SimpleHistoryLoggingService
2016-01-14 17:08:21,292 INFO  recovery.RecoveryService (RecoveryService.java:serviceStart(127)) - Starting RecoveryService
2016-01-14 17:08:21,292 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event AM_LAUNCHED to history file
2016-01-14 17:08:21,355 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: INITED
2016-01-14 17:08:21,356 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(240)) - DAGAppMaster is not startetd wait for 100ms...
2016-01-14 17:08:21,356 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-01-14 17:08:21,361 INFO  client.DAGClientServer (DAGClientServer.java:serviceStart(91)) - Instantiated DAGClientRPCServer at ip-10-187-41-40.ec2.internal/10.187.41.40:35107
2016-01-14 17:08:21,404 WARN  impl.MetricsConfig (MetricsConfig.java:loadFirst(124)) - Cannot locate configuration: tried hadoop-metrics2-dagappmaster.properties,hadoop-metrics2.properties
2016-01-14 17:08:21,456 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: INITED
2016-01-14 17:08:21,456 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(240)) - DAGAppMaster is not startetd wait for 100ms...
2016-01-14 17:08:21,456 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-01-14 17:08:21,483 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event AM_STARTED to history file
2016-01-14 17:08:21,484 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:N/A][Event:AM_STARTED]: appAttemptId=appattempt_1452791301026_0001_000000, startTime=1452791301482
2016-01-14 17:08:21,484 INFO  app.DAGAppMaster (DAGAppMaster.java:serviceStart(1644)) - In Session mode. Waiting for DAG over RPC
2016-01-14 17:08:21,557 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: IDLE
2016-01-14 17:08:21,573 INFO  client.TezClient (TezClient.java:start(367)) - The url to track the Tez Session: N/A
2016-01-14 17:08:21,573 INFO  client.TezClient (TezClient.java:submitDAGSession(405)) - Submitting dag to TezSession, sessionName=(1/1) ...StrategiesReplace/replace, applicationId=application_1452791301026_0001, dagName=[1E43515C97744D998F07322857EBCDB1/A3F922810955485A83E86883CFD6CEC5] test/(1/1) ...StrategiesReplace/replace
2016-01-14 17:08:21,785 INFO  app.DAGAppMaster (DAGAppMaster.java:submitDAGToAppMaster(1126)) - Starting DAG submitted via RPC: [1E43515C97744D998F07322857EBCDB1/A3F922810955485A83E86883CFD6CEC5] test/(1/1) ...StrategiesReplace/replace
2016-01-14 17:08:21,914 INFO  app.DAGAppMaster (DAGAppMaster.java:generateDAGVizFile(870)) - Generating DAG graphviz file, dagId=dag_1452791301026_0001_1, filePath=/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/1E43515C97744D998F07322857EBCDB1/A3F922810955485A83E86883CFD6CEC5/.tez/application_1452791301026_0001/localmode-log-dir/dag_1452791301026_0001_1.dot
2016-01-14 17:08:21,918 INFO  app.DAGAppMaster (DAGAppMaster.java:writePBTextFile(887)) - Writing DAG plan to: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/1E43515C97744D998F07322857EBCDB1/A3F922810955485A83E86883CFD6CEC5/.tez/application_1452791301026_0001/localmode-log-dir/dag_1452791301026_0001_1-tez-dag.pb.txt
2016-01-14 17:08:22,012 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: dag_1452791301026_0001_1
2016-01-14 17:08:22,012 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 17:08:22,012 INFO  app.DAGAppMaster (DAGAppMaster.java:startDAG(2051)) - Running DAG: [1E43515C97744D998F07322857EBCDB1/A3F922810955485A83E86883CFD6CEC5] test/(1/1) ...StrategiesReplace/replace
2016-01-14 17:08:22 Running Dag: dag_1452791301026_0001_1
2016-01-14 17:08:22,048 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_SUBMITTED to history file
2016-01-14 17:08:22,049 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791301026_0001_1][Event:DAG_SUBMITTED]: dagID=dag_1452791301026_0001_1, submitTime=1452791301785
2016-01-14 17:08:22,093 INFO  impl.VertexImpl (VertexImpl.java:setAdditionalOutputs(4033)) - setting additional outputs for vertex D46BA8546B5C4D1E8D22B18346820211
2016-01-14 17:08:22,096 INFO  impl.DAGImpl (DAGImpl.java:assignDAGScheduler(1381)) - Using DAG Scheduler: org.apache.tez.dag.app.dag.impl.DAGSchedulerNaturalOrderControlled
2016-01-14 17:08:22,100 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791301026_0001_1][Event:DAG_INITIALIZED]: dagID=dag_1452791301026_0001_1, initTime=1452791302050
2016-01-14 17:08:22,101 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_INITIALIZED to history file
2016-01-14 17:08:22,101 INFO  impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1452791301026_0001_1 transitioned from NEW to INITED due to event DAG_INIT
2016-01-14 17:08:22,104 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791301026_0001_1][Event:DAG_STARTED]: dagID=dag_1452791301026_0001_1, startTime=1452791302103
2016-01-14 17:08:22,104 INFO  impl.DAGImpl (DAGImpl.java:transition(1614)) - Added additional resources : [[]] to classpath
2016-01-14 17:08:22,106 INFO  impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1452791301026_0001_1 transitioned from INITED to RUNNING due to event DAG_START
2016-01-14 17:08:22,106 INFO  impl.VertexImpl (VertexImpl.java:setupVertex(2068)) - Root Inputs exist for Vertex: D46BA8546B5C4D1E8D22B18346820211 : {986749740DC14EB7958754DFE7685F30={InputName=986749740DC14EB7958754DFE7685F30}, {Descriptor=ClassName=org.apache.tez.mapreduce.input.MRInput, hasPayload=true}, {ControllerDescriptor=ClassName=org.apache.tez.mapreduce.common.MRInputAMSplitGenerator, hasPayload=false}}
2016-01-14 17:08:22,106 INFO  impl.VertexImpl (VertexImpl.java:setupVertex(2078)) - Starting root input initializer for input: 986749740DC14EB7958754DFE7685F30, with class: [org.apache.tez.mapreduce.common.MRInputAMSplitGenerator]
2016-01-14 17:08:22,107 INFO  impl.VertexImpl (VertexImpl.java:assignVertexManager(2191)) - Setting vertexManager to RootInputVertexManager for vertex_1452791301026_0001_1_00 [D46BA8546B5C4D1E8D22B18346820211]
2016-01-14 17:08:22,107 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_STARTED to history file
2016-01-14 17:08:22,115 INFO  impl.VertexImpl (VertexImpl.java:handleInitEvent(2983)) - Num tasks is -1. Expecting VertexManager/InputInitializers/1-1 split to set #tasks for the vertex vertex_1452791301026_0001_1_00 [D46BA8546B5C4D1E8D22B18346820211]
2016-01-14 17:08:22,116 INFO  impl.VertexImpl (VertexImpl.java:handleInitEvent(2987)) - Vertex will initialize from input initializer. vertex_1452791301026_0001_1_00 [D46BA8546B5C4D1E8D22B18346820211]
2016-01-14 17:08:22,116 INFO  client.TezClient (TezClient.java:submitDAGSession(478)) - Submitted dag to TezSession, sessionName=(1/1) ...StrategiesReplace/replace, applicationId=application_1452791301026_0001, dagName=[1E43515C97744D998F07322857EBCDB1/A3F922810955485A83E86883CFD6CEC5] test/(1/1) ...StrategiesReplace/replace
2016-01-14 17:08:22,119 INFO  impl.VertexImpl (VertexImpl.java:setupInputInitializerManager(3933)) - Vertex will initialize via inputInitializers vertex_1452791301026_0001_1_00 [D46BA8546B5C4D1E8D22B18346820211]. Starting root input initializers: 1
2016-01-14 17:08:22,137 INFO  dag.RootInputInitializerManager (RootInputInitializerManager.java:run(242)) - Starting InputInitializer for Input: 986749740DC14EB7958754DFE7685F30 on vertex vertex_1452791301026_0001_1_00 [D46BA8546B5C4D1E8D22B18346820211]
2016-01-14 17:08:22,144 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452791301026_0001_1_00 [D46BA8546B5C4D1E8D22B18346820211] transitioned from NEW to INITIALIZING due to event V_INIT
2016-01-14 17:08:22,157 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test] submitted tez dag to app master: application_1452791301026_0001, with dag id: dag_1452791301026_0001_1
2016-01-14 17:08:22,161 INFO  common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(92)) - Emitting serialized splits: true
2016-01-14 17:08:22,165 INFO  common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(110)) - Input 986749740DC14EB7958754DFE7685F30 asking for 1 tasks. Headroom: 672 Task Resource: 1024 waves: 1.7
2016-01-14 17:08:22,166 INFO  common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(121)) - Grouping input splits
2016-01-14 17:08:22,166 INFO  hadoop.MRInputHelpers (MRInputHelpers.java:generateInputSplitsToMem(294)) - Generating mapred api input splits
2016-01-14 17:08:22,209 INFO  hadoop.MRInputHelpers (MRInputHelpers.java:generateInputSplitsToMem(300)) - NumSplits: 1, SerializedSize: 408
2016-01-14 17:08:22,212 INFO  dag.RootInputInitializerManager (RootInputInitializerManager.java:onSuccess(272)) - Succeeded InputInitializer for Input: 986749740DC14EB7958754DFE7685F30 on vertex vertex_1452791301026_0001_1_00 [D46BA8546B5C4D1E8D22B18346820211]
2016-01-14 17:08:22,213 INFO  impl.VertexImpl (VertexImpl.java:canInitVertex(3195)) - Cannot init vertex: vertex_1452791301026_0001_1_00 [D46BA8546B5C4D1E8D22B18346820211] numTasks: -1 numUnitializedEdges: 0 numInitializedInputs: 0 initWaitsForRootInitializers: true
2016-01-14 17:08:22,213 INFO  impl.VertexImpl (VertexImpl.java:setParallelism(1374)) - Got updated RootInputsSpecs: {986749740DC14EB7958754DFE7685F30=forAllWorkUnits=true, update=[1]}
2016-01-14 17:08:22,228 INFO  impl.VertexImpl (VertexImpl.java:setParallelism(1393)) - Vertex vertex_1452791301026_0001_1_00 [D46BA8546B5C4D1E8D22B18346820211] parallelism set to 1
2016-01-14 17:08:22,228 INFO  impl.VertexImpl (VertexImpl.java:canInitVertex(3195)) - Cannot init vertex: vertex_1452791301026_0001_1_00 [D46BA8546B5C4D1E8D22B18346820211] numTasks: 1 numUnitializedEdges: 0 numInitializedInputs: 0 initWaitsForRootInitializers: true
2016-01-14 17:08:22,237 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791301026_0001_1][Event:VERTEX_DATA_MOVEMENT_EVENTS_GENERATED]: vertexId=vertex_1452791301026_0001_1_00, eventCount=1
2016-01-14 17:08:22,241 INFO  impl.VertexImpl (VertexImpl.java:initializeCommitters(1915)) - Invoking committer inits for vertex, vertexId=vertex_1452791301026_0001_1_00 [D46BA8546B5C4D1E8D22B18346820211]
2016-01-14 17:08:22,241 INFO  impl.VertexImpl (VertexImpl.java:initializeCommitters(1927)) - Instantiating committer for output=DB9B44C15FAF4AE591DE3D4F4570E18D, vertexId=vertex_1452791301026_0001_1_00 [D46BA8546B5C4D1E8D22B18346820211], committerClass=org.apache.tez.mapreduce.committer.MROutputCommitter
2016-01-14 17:08:22,246 INFO  impl.VertexImpl (VertexImpl.java:run(1945)) - Invoking committer init for output=DB9B44C15FAF4AE591DE3D4F4570E18D, vertexId=vertex_1452791301026_0001_1_00 [D46BA8546B5C4D1E8D22B18346820211]
2016-01-14 17:08:22,266 INFO  committer.MROutputCommitter (MROutputCommitter.java:getOutputCommitter(145)) - OutputCommitter for outputName=DB9B44C15FAF4AE591DE3D4F4570E18D, vertexName=D46BA8546B5C4D1E8D22B18346820211, outputCommitterClass=org.apache.hadoop.mapred.FileOutputCommitter
2016-01-14 17:08:22,274 INFO  impl.VertexImpl (VertexImpl.java:run(1949)) - Invoking committer setup for output=DB9B44C15FAF4AE591DE3D4F4570E18D, vertexId=vertex_1452791301026_0001_1_00 [D46BA8546B5C4D1E8D22B18346820211]
2016-01-14 17:08:22,278 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_INITIALIZED to history file
2016-01-14 17:08:22,278 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791301026_0001_1][Event:VERTEX_INITIALIZED]: vertexName=D46BA8546B5C4D1E8D22B18346820211, vertexId=vertex_1452791301026_0001_1_00, initRequestedTime=1452791302106, initedTime=1452791302277, numTasks=1, processorName=cascading.flow.tez.FlowProcessor, additionalInputsCount=1
2016-01-14 17:08:22,279 INFO  impl.VertexImpl (VertexImpl.java:startIfPossible(3061)) - Triggering start event for vertex: vertex_1452791301026_0001_1_00 [D46BA8546B5C4D1E8D22B18346820211] with distanceFromRoot: 0
2016-01-14 17:08:22,281 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452791301026_0001_1_00 [D46BA8546B5C4D1E8D22B18346820211] transitioned from INITIALIZING to INITED due to event V_ROOT_INPUT_INITIALIZED
2016-01-14 17:08:22,284 INFO  impl.ImmediateStartVertexManager (ImmediateStartVertexManager.java:scheduleTasks(99)) - Starting 1 in D46BA8546B5C4D1E8D22B18346820211
2016-01-14 17:08:22,284 INFO  impl.VertexImpl (VertexImpl.java:scheduleTasks(1250)) - Routing pending task events for vertex: vertex_1452791301026_0001_1_00 [D46BA8546B5C4D1E8D22B18346820211]
2016-01-14 17:08:22,286 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_STARTED to history file
2016-01-14 17:08:22,286 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791301026_0001_1][Event:VERTEX_STARTED]: vertexId=vertex_1452791301026_0001_1_00, startRequestedTime=1452791302283, startedTime=1452791302283
2016-01-14 17:08:22,288 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452791301026_0001_1_00 [D46BA8546B5C4D1E8D22B18346820211] transitioned from INITED to RUNNING due to event V_START
2016-01-14 17:08:22,312 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_STARTED to history file
2016-01-14 17:08:22,312 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791301026_0001_1][Event:TASK_STARTED]: vertexName=D46BA8546B5C4D1E8D22B18346820211, taskId=task_1452791301026_0001_1_00_000000, scheduledTime=1452791302310, launchTime=1452791302310
2016-01-14 17:08:22,312 INFO  impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452791301026_0001_1_00_000000 Task Transitioned from NEW to SCHEDULED due to event T_SCHEDULE
2016-01-14 17:08:22,314 INFO  impl.DAGSchedulerNaturalOrderControlled (DAGSchedulerNaturalOrderControlled.java:scheduleTask(111)) - Scheduled vertex: vertex_1452791301026_0001_1_00 [D46BA8546B5C4D1E8D22B18346820211]
2016-01-14 17:08:22,318 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1014)) - remoteTaskSpec:DAGName : [1E43515C97744D998F07322857EBCDB1/A3F922810955485A83E86883CFD6CEC5] test/(1/1) ...StrategiesReplace/replace, VertexName: D46BA8546B5C4D1E8D22B18346820211, VertexParallelism: 1, TaskAttemptID:attempt_1452791301026_0001_1_00_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=986749740DC14EB7958754DFE7685F30, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=DB9B44C15FAF4AE591DE3D4F4570E18D, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }}, ]
2016-01-14 17:08:22,320 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452791301026_0001_1_00_000000_0 TaskAttempt Transitioned from NEW to START_WAIT due to event TA_SCHEDULE
2016-01-14 17:08:22,321 INFO  rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_LAUNCH_REQUEST
2016-01-14 17:08:22,359 INFO  node.AMNodeTracker (AMNodeTracker.java:nodeSeen(91)) - Adding new node: 127.0.0.1:0
2016-01-14 17:08:22,362 INFO  container.AMContainerHelpers (AMContainerHelpers.java:createCommonContainerLaunchContext(112)) - Adding #1 tokens and #0 secret keys for NM use for launching container
2016-01-14 17:08:22,362 INFO  container.AMContainerHelpers (AMContainerHelpers.java:createCommonContainerLaunchContext(122)) - Putting shuffle token in serviceData
2016-01-14 17:08:22,368 INFO  container.AMContainerImpl (AMContainerImpl.java:transition(521)) - Sending Launch Request for Container with id: container_1452791301026_0001_00_000001
2016-01-14 17:08:22,368 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791301026_0001_00_000001 transitioned from ALLOCATED to LAUNCHING via event C_LAUNCH_REQUEST
2016-01-14 17:08:22,378 INFO  task.TezChild (TezChild.java:newTezChild(432)) - PID, containerIdentifier:  null, container_1452791301026_0001_00_000001
2016-01-14 17:08:22,378 WARN  impl.MetricsSystemImpl (MetricsSystemImpl.java:init(145)) - DAGAppMaster metrics system already initialized!
2016-01-14 17:08:22,382 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791301026_0001_00_000001 transitioned from LAUNCHING to IDLE via event C_LAUNCHED
2016-01-14 17:08:22,383 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_LAUNCHED to history file
2016-01-14 17:08:22,383 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791301026_0001_1][Event:CONTAINER_LAUNCHED]: containerId=container_1452791301026_0001_00_000001, launchTime=1452791302382
2016-01-14 17:08:22,385 INFO  task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1452791301026_0001_00_000001
2016-01-14 17:08:22,389 INFO  container.AMContainerImpl (AMContainerImpl.java:transition(827)) - Assigned taskAttempt + [attempt_1452791301026_0001_1_00_000000_0] to container: [container_1452791301026_0001_00_000001]
2016-01-14 17:08:22,389 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791301026_0001_00_000001 transitioned from IDLE to RUNNING via event C_PULL_TA
2016-01-14 17:08:22,391 INFO  app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(240)) - Container with id: container_1452791301026_0001_00_000001 given task: attempt_1452791301026_0001_1_00_000000_0
2016-01-14 17:08:22,391 INFO  task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1452791301026_0001_00_000001: 0 ms after starting to poll. TaskInfo: shouldDie: false, currentTaskAttemptId: attempt_1452791301026_0001_1_00_000000_0
2016-01-14 17:08:22 Starting to run new task attempt: attempt_1452791301026_0001_1_00_000000_0
2016-01-14 17:08:22,392 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: attempt_1452791301026_0001_1_00_000000_0
2016-01-14 17:08:22,392 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 17:08:22,394 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1146)) - TaskAttempt: [attempt_1452791301026_0001_1_00_000000_0] started. Is using containerId: [container_1452791301026_0001_00_000001] on NM: [127.0.0.1:0]
2016-01-14 17:08:22,394 INFO  task.TezChild (TezChild.java:handleNewTaskCredentials(273)) - Refreshing UGI since Credentials have changed
2016-01-14 17:08:22,394 INFO  task.TezChild (TezChild.java:handleNewTaskCredentials(276)) - Credentials : #Tokens=1, #SecretKeys=0
2016-01-14 17:08:22,396 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791301026_0001_1][Event:TASK_ATTEMPT_STARTED]: vertexName=D46BA8546B5C4D1E8D22B18346820211, taskAttemptId=attempt_1452791301026_0001_1_00_000000_0, startTime=1452791302391, containerId=container_1452791301026_0001_00_000001, nodeId=127.0.0.1:0, inProgressLogs=127.0.0.1:0/node/containerlogs/container_1452791301026_0001_00_000001/teamcity, completedLogs=
2016-01-14 17:08:22,396 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_STARTED to history file
2016-01-14 17:08:22,397 INFO  task.TezChild (TezChild.java:handleNewTaskLocalResources(302)) - Localizing additional local resources for Task : {}
2016-01-14 17:08:22,398 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452791301026_0001_1_00_000000_0 TaskAttempt Transitioned from START_WAIT to RUNNING due to event TA_STARTED_REMOTELY
2016-01-14 17:08:22,399 INFO  counters.Limits (Limits.java:ensureInitialized(59)) - Counter limits initialized with parameters:  GROUP_NAME_MAX=128, MAX_GROUPS=500, COUNTER_NAME_MAX=64, MAX_COUNTERS=1200
2016-01-14 17:08:22,401 INFO  task.TezChild (TezChild.java:handleNewTaskLocalResources(312)) - Done localizing additional resources
2016-01-14 17:08:22,404 INFO  impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452791301026_0001_1_00_000000 Task Transitioned from SCHEDULED to RUNNING due to event T_ATTEMPT_LAUNCHED
2016-01-14 17:08:22,428 INFO  metrics.TaskCounterUpdater (TaskCounterUpdater.java:initResourceCalculatorPlugin(148)) -  Using ResourceCalculatorProcessTree : [ ]
2016-01-14 17:08:22,428 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:<init>(149)) - Initializing LogicalIOProcessorRuntimeTask with TaskSpec: DAGName : [1E43515C97744D998F07322857EBCDB1/A3F922810955485A83E86883CFD6CEC5] test/(1/1) ...StrategiesReplace/replace, VertexName: D46BA8546B5C4D1E8D22B18346820211, VertexParallelism: 1, TaskAttemptID:attempt_1452791301026_0001_1_00_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=986749740DC14EB7958754DFE7685F30, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=DB9B44C15FAF4AE591DE3D4F4570E18D, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }}, ]
2016-01-14 17:08:22,430 INFO  resources.MemoryDistributor (MemoryDistributor.java:<init>(85)) - InitialMemoryDistributor (isEnabled=true) invoked with: numInputs=1, numOutputs=1, JVM.maxFree=704643072
2016-01-14 17:08:22,435 INFO  task.TezTaskRunner (TezTaskRunner.java:run(172)) - Initializing task, taskAttemptId=attempt_1452791301026_0001_1_00_000000_0
2016-01-14 17:08:22,436 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(191)) - Initializing LogicalProcessorIORuntimeTask
2016-01-14 17:08:22,436 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(195)) - Creating processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 17:08:22,438 INFO  impl.TaskImpl (TaskImpl.java:getTaskAttemptTezEvents(481)) - TaskAttempt:attempt_1452791301026_0001_1_00_000000_0 sent events: (0-1)
2016-01-14 17:08:22,442 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(389)) - Initializing Input using InputSpec: { sourceVertexName=986749740DC14EB7958754DFE7685F30, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }
2016-01-14 17:08:22,444 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(488)) - Initializing processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 17:08:22,446 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(438)) - Initializing Output using OutputSpec: { destinationVertexName=DB9B44C15FAF4AE591DE3D4F4570E18D, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }
2016-01-14 17:08:22,446 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createInput(537)) - Creating Input
2016-01-14 17:08:22,450 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(397)) - Initializing Input with src edge: 986749740DC14EB7958754DFE7685F30
2016-01-14 17:08:22,449 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createOutput(565)) - Creating Output
2016-01-14 17:08:22,451 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(446)) - Initializing Output with dest edge: DB9B44C15FAF4AE591DE3D4F4570E18D
2016-01-14 17:08:22,452 INFO  output.MROutput (MROutput.java:initialize(347)) - Initializing Simple Output
2016-01-14 17:08:22,456 INFO  resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 0, type: INPUT, componentVertexName: 986749740DC14EB7958754DFE7685F30
2016-01-14 17:08:22,457 INFO  resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 0, type: OUTPUT, componentVertexName: DB9B44C15FAF4AE591DE3D4F4570E18D
2016-01-14 17:08:22,466 INFO  tez.FlowProcessor (FlowProcessor.java:initialize(88)) - cascading version: 3.0.4
2016-01-14 17:08:22,488 INFO  input.MRInput (MRInput.java:initialize(440)) - Using New mapreduce API: false, split information via event: true
2016-01-14 17:08:22,489 INFO  input.MRInput (MRInput.java:initializeInternal(493)) - Initialzed MRInput: 986749740DC14EB7958754DFE7685F30
2016-01-14 17:08:22,490 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(403)) - Initialized Input with src edge: 986749740DC14EB7958754DFE7685F30
2016-01-14 17:08:22,493 INFO  tez.FlowProcessor (FlowProcessor.java:initialize(94)) - flow node id: D46BA8546B5C4D1E8D22B18346820211, ordinal: 0
2016-01-14 17:08:22,494 INFO  tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: D46BA8546B5C4D1E8D22B18346820211, mem on start (mb), free: 164, total: 223, max: 672
2016-01-14 17:08:22,494 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(491)) - Initialized processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 17:08:22,495 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 2 initializers to finish
2016-01-14 17:08:22,495 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 1 initializers to finish
2016-01-14 17:08:22,507 INFO  output.MROutput (MROutput.java:initialize(418)) - Initialized Simple Output, using_new_api: false
2016-01-14 17:08:22,507 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(452)) - Initialized Output with dest edge: DB9B44C15FAF4AE591DE3D4F4570E18D
2016-01-14 17:08:22,507 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(233)) - All initializers finished
2016-01-14 17:08:22,508 INFO  resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(124)) - Using Allocator class: org.apache.tez.runtime.library.resources.WeightedScalingMemoryDistributor
2016-01-14 17:08:22,516 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:getRequestTypeForClass(197)) - Falling back to RequestType.OTHER for class: org.apache.tez.mapreduce.input.MRInput
2016-01-14 17:08:22,517 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 1, for type: OTHER
2016-01-14 17:08:22,517 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:getRequestTypeForClass(197)) - Falling back to RequestType.OTHER for class: org.apache.tez.mapreduce.output.MROutput
2016-01-14 17:08:22,517 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 1, for type: OTHER
2016-01-14 17:08:22,518 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:computeReservedFraction(262)) - InitialReservationFraction=0.3, AdditionalReservationFractionForIOs=0.03, finalReserveFractionUsed=0.32999999999999996
2016-01-14 17:08:22,518 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:assignMemory(126)) - Scaling Requests. NumRequests: 2, numScaledRequests: 2, TotalRequested: 0, TotalRequestedScaled: 0.0, TotalJVMHeap: 704643072, TotalAvailable: 472110858, TotalRequested/TotalJVMHeap:0.00
2016-01-14 17:08:22,519 INFO  resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: INPUT, 986749740DC14EB7958754DFE7685F30, org.apache.tez.mapreduce.input.MRInput: requested=0, allocated=0
2016-01-14 17:08:22,519 INFO  resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: OUTPUT, DB9B44C15FAF4AE591DE3D4F4570E18D, org.apache.tez.mapreduce.output.MROutput: requested=0, allocated=0
2016-01-14 17:08:22,520 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(255)) - Starting Inputs/Outputs
2016-01-14 17:08:22,521 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(268)) - Input: 986749740DC14EB7958754DFE7685F30 being auto started by the framework. Subsequent instances will not be auto-started
2016-01-14 17:08:22,521 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(419)) - Starting Input with src edge: 986749740DC14EB7958754DFE7685F30
2016-01-14 17:08:22,522 INFO  input.MRInput (MRInput.java:start(450)) - MRInput setup to received events1
2016-01-14 17:08:22,522 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(421)) - Started Input with src edge: 986749740DC14EB7958754DFE7685F30
2016-01-14 17:08:22,522 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(289)) - Num IOs determined for AutoStart: 1
2016-01-14 17:08:22,523 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(291)) - Waiting for 1 IOs to start
2016-01-14 17:08:22,523 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(304)) - AutoStartComplete
2016-01-14 17:08:22,525 INFO  task.TezTaskRunner (TezTaskRunner.java:run(175)) - Running task, taskAttemptId=attempt_1452791301026_0001_1_00_000000_0
2016-01-14 17:08:22,529 INFO  input.MRInput (MRInput.java:initFromEventInternal(619)) - Initializing RecordReader from event
2016-01-14 17:08:22,538 INFO  input.MRInput (MRInput.java:initFromEventInternal(630)) - Split Details -> SplitClass: org.apache.hadoop.mapred.split.TezGroupedSplit, OldSplit: org.apache.hadoop.mapred.split.TezGroupedSplit@6017f095
2016-01-14 17:08:22,549 INFO  lib.MRReaderMapred (MRReaderMapred.java:setIncrementalConfigParams(163)) - Processing split: org.apache.hadoop.mapred.split.TezGroupedSplit@6017f095
2016-01-14 17:08:22,549 INFO  input.MRInput (MRInput.java:initFromEventInternal(634)) - Initialized RecordReader from event
2016-01-14 17:08:22,550 INFO  input.MRInput (MRInput.java:processSplitEvent(586)) - Notifying on RecordReader Initialized
2016-01-14 17:08:22,556 INFO  graph.Hadoop2TezStreamGraph (Hadoop2TezStreamGraph.java:buildGraph(151)) - using streamed source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/classes/test/data/apache.10.txt"]
2016-01-14 17:08:22,578 INFO  tez.FlowProcessor (FlowProcessor.java:run(121)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/classes/test/data/apache.10.txt"] streamed: true, id: 986749740DC14EB7958754DFE7685F30
2016-01-14 17:08:22,578 INFO  tez.FlowProcessor (FlowProcessor.java:run(124)) - sinking to: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/output/hadoop2-tez/flowstrategiesplatform/testSkipStrategiesReplace/replace"], id: DB9B44C15FAF4AE591DE3D4F4570E18D
2016-01-14 17:08:22,578 INFO  element.TezSinkStage (TezSinkStage.java:prepare(57)) - calling MROutput#start() on: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/output/hadoop2-tez/flowstrategiesplatform/testSkipStrategiesReplace/replace"]
2016-01-14 17:08:22,580 INFO  element.TezSourceStage (TezSourceStage.java:prepare(63)) - calling MRInput#start() on: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/classes/test/data/apache.10.txt"]
2016-01-14 17:08:22,580 INFO  input.MRInput (MRInput.java:start(450)) - MRInput setup to received events1
2016-01-14 17:08:22,584 INFO  tez.FlowProcessor (FlowProcessor.java:waitForInputsReady(202)) - flow node id: D46BA8546B5C4D1E8D22B18346820211, all 1 inputs ready in: 00:00:00.003
2016-01-14 17:08:22,591 INFO  output.MROutput (MROutput.java:flush(534)) - Flushing Simple Output
2016-01-14 17:08:22,591 INFO  output.MROutput (MROutput.java:flush(544)) - Flushed Simple Output
2016-01-14 17:08:22,592 INFO  app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:canCommit(353)) - Commit go/no-go request from attempt_1452791301026_0001_1_00_000000_0
2016-01-14 17:08:22,593 INFO  impl.TaskImpl (TaskImpl.java:canCommit(750)) - attempt_1452791301026_0001_1_00_000000_0 given a go for committing the task output.
2016-01-14 17:08:22,594 INFO  task.TezTaskRunner (TezTaskRunner.java:run(177)) - Closing task, taskAttemptId=attempt_1452791301026_0001_1_00_000000_0
2016-01-14 17:08:22,594 INFO  tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: D46BA8546B5C4D1E8D22B18346820211, mem on close (mb), free: 157, total: 223, max: 672
2016-01-14 17:08:22 Completed running task attempt: attempt_1452791301026_0001_1_00_000000_0
2016-01-14 17:08:22,603 INFO  task.TezTaskRunner (TezTaskRunner.java:run(181)) - Task completed, taskAttemptId=attempt_1452791301026_0001_1_00_000000_0, fatalErrorOccurred=false
2016-01-14 17:08:22,605 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_FINISHED to history file
2016-01-14 17:08:22,613 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791301026_0001_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=D46BA8546B5C4D1E8D22B18346820211, taskAttemptId=attempt_1452791301026_0001_1_00_000000_0, startTime=1452791302391, finishTime=1452791302604, timeTaken=213, status=SUCCEEDED, errorEnum=, diagnostics=, counters=Counters: 22, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=2174, FILE_BYTES_WRITTEN=672, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=233832448, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=10, cascading.flow.SliceCounters, Process_Begin_Time=1452791302584, Process_Duration=10, Process_End_Time=1452791302594, Read_Duration=2, Tuples_Read=10, Tuples_Written=10, Write_Duration=0, cascading.flow.StepCounters, Tuples_Read=10, Tuples_Written=10
2016-01-14 17:08:22,614 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452791301026_0001_1_00_000000_0 TaskAttempt Transitioned from RUNNING to SUCCEEDED due to event TA_DONE
2016-01-14 17:08:22,614 INFO  rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_ENDED
2016-01-14 17:08:22,616 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:cleanup(712)) - Final Counters : Counters: 22 [[org.apache.tez.common.counters.DAGCounter RACK_LOCAL_TASKS=1][File System Counters FILE_BYTES_READ=2174, FILE_BYTES_WRITTEN=672, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0][org.apache.tez.common.counters.TaskCounter GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=233832448, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=10][cascading.flow.SliceCounters Process_Begin_Time=1452791302584, Process_Duration=10, Process_End_Time=1452791302594, Read_Duration=2, Tuples_Read=10, Tuples_Written=10, Write_Duration=0][cascading.flow.StepCounters Tuples_Read=10, Tuples_Written=10]]
2016-01-14 17:08:22,616 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: 
2016-01-14 17:08:22,616 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 17:08:22,619 INFO  impl.TaskImpl (TaskImpl.java:transition(1052)) - Task succeeded with attempt attempt_1452791301026_0001_1_00_000000_0
2016-01-14 17:08:22,619 INFO  task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1452791301026_0001_00_000001
2016-01-14 17:08:22,622 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_FINISHED to history file
2016-01-14 17:08:22,628 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791301026_0001_1][Event:TASK_FINISHED]: vertexName=D46BA8546B5C4D1E8D22B18346820211, taskId=task_1452791301026_0001_1_00_000000, startTime=1452791302391, finishTime=1452791302620, timeTaken=229, status=SUCCEEDED, successfulAttemptID=attempt_1452791301026_0001_1_00_000000_0, diagnostics=, counters=Counters: 22, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=2174, FILE_BYTES_WRITTEN=672, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=233832448, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=10, cascading.flow.SliceCounters, Process_Begin_Time=1452791302584, Process_Duration=10, Process_End_Time=1452791302594, Read_Duration=2, Tuples_Read=10, Tuples_Written=10, Write_Duration=0, cascading.flow.StepCounters, Tuples_Read=10, Tuples_Written=10
2016-01-14 17:08:22,636 INFO  impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452791301026_0001_1_00_000000 Task Transitioned from RUNNING to SUCCEEDED due to event T_ATTEMPT_SUCCEEDED
2016-01-14 17:08:22,637 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791301026_0001_00_000001 transitioned from RUNNING to IDLE via event C_TA_SUCCEEDED
2016-01-14 17:08:22,639 INFO  impl.VertexImpl (VertexImpl.java:transition(3536)) - Num completed Tasks for vertex_1452791301026_0001_1_00 [D46BA8546B5C4D1E8D22B18346820211] : 1
2016-01-14 17:08:22,639 INFO  impl.VertexImpl (VertexImpl.java:checkVertexForCompletion(1674)) - Vertex succeeded: vertex_1452791301026_0001_1_00 [D46BA8546B5C4D1E8D22B18346820211]
2016-01-14 17:08:22,645 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_FINISHED to history file
2016-01-14 17:08:22,650 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791301026_0001_1][Event:VERTEX_FINISHED]: vertexName=D46BA8546B5C4D1E8D22B18346820211, vertexId=vertex_1452791301026_0001_1_00, initRequestedTime=1452791302106, initedTime=1452791302277, startRequestedTime=1452791302283, startedTime=1452791302283, finishTime=1452791302640, timeTaken=357, status=SUCCEEDED, diagnostics=, counters=Counters: 22, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=2174, FILE_BYTES_WRITTEN=672, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=233832448, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=10, cascading.flow.SliceCounters, Process_Begin_Time=1452791302584, Process_Duration=10, Process_End_Time=1452791302594, Read_Duration=2, Tuples_Read=10, Tuples_Written=10, Write_Duration=0, cascading.flow.StepCounters, Tuples_Read=10, Tuples_Written=10, vertexStats=firstTaskStartTime=1452791302391, firstTasksToStart=[ task_1452791301026_0001_1_00_000000 ], lastTaskFinishTime=1452791302604, lastTasksToFinish=[ task_1452791301026_0001_1_00_000000 ], minTaskDuration=213, maxTaskDuration=213, avgTaskDuration=213.0, numSuccessfulTasks=1, shortestDurationTasks=[ task_1452791301026_0001_1_00_000000 ], longestDurationTasks=[ task_1452791301026_0001_1_00_000000 ], vertexTaskStats={numFailedTasks=0, numSucceededTasks=1, numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0, numCompletedTasks=1}
2016-01-14 17:08:22,651 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452791301026_0001_1_00 [D46BA8546B5C4D1E8D22B18346820211] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2016-01-14 17:08:22,652 INFO  app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(213)) - Container with id: container_1452791301026_0001_00_000001 is valid, but no longer registered, and will be killed
2016-01-14 17:08:22,652 INFO  task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1452791301026_0001_00_000001: 31 ms after starting to poll. TaskInfo: shouldDie: true
2016-01-14 17:08:22,653 INFO  task.TezChild (TezChild.java:run(207)) - ContainerTask returned shouldDie=true for container container_1452791301026_0001_00_000001, Exiting
2016-01-14 17:08:22,653 INFO  task.TezChild (TezChild.java:shutdown(343)) - Shutdown invoked for container container_1452791301026_0001_00_000001
2016-01-14 17:08:22,653 INFO  task.TezChild (TezChild.java:shutdown(345)) - Shutting down container container_1452791301026_0001_00_000001
2016-01-14 17:08:22,655 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_STOPPED to history file
2016-01-14 17:08:22,655 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791301026_0001_1][Event:CONTAINER_STOPPED]: containerId=container_1452791301026_0001_00_000001, stoppedTime=1452791302655, exitStatus=0
2016-01-14 17:08:22,656 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791301026_0001_00_000001 transitioned from IDLE to STOP_REQUESTED via event C_STOP_REQUEST
2016-01-14 17:08:22,656 INFO  impl.DAGImpl (DAGImpl.java:transition(1747)) - Vertex vertex_1452791301026_0001_1_00 [D46BA8546B5C4D1E8D22B18346820211] completed., numCompletedVertices=1, numSuccessfulVertices=1, numFailedVertices=0, numKilledVertices=0, numVertices=1
2016-01-14 17:08:22,657 INFO  impl.DAGImpl (DAGImpl.java:commitOrAbortOutputs(831)) - Calling DAG commit/abort for dag: dag_1452791301026_0001_1
2016-01-14 17:08:22,657 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791301026_0001_1][Event:DAG_COMMIT_STARTED]: dagID=dag_1452791301026_0001_1
2016-01-14 17:08:22,656 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(270)) - ContainerExecutionResult for: container_1452791301026_0001_00_000001 = ContainerExecutionResult{exitStatus=SUCCESS, throwable=null, errorMessage='Asked to die by the AM'}
2016-01-14 17:08:22,658 INFO  impl.DAGImpl (DAGImpl.java:commitOrAbortOutputs(892)) - Committing output: DB9B44C15FAF4AE591DE3D4F4570E18D for vertex: vertex_1452791301026_0001_1_00 [D46BA8546B5C4D1E8D22B18346820211]
2016-01-14 17:08:22,658 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(274)) - Container: container_1452791301026_0001_00_000001 completed successfully
2016-01-14 17:08:22,676 INFO  recovery.RecoveryService (RecoveryService.java:handle(306)) - DAG completed, dagId=dag_1452791301026_0001_1, queueSize=0
2016-01-14 17:08:22,676 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_FINISHED to history file
2016-01-14 17:08:22,678 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791301026_0001_1][Event:DAG_FINISHED]: dagId=dag_1452791301026_0001_1, startTime=1452791302103, finishTime=1452791302670, timeTaken=567, status=SUCCEEDED, diagnostics=, counters=Counters: 24, org.apache.tez.common.counters.DAGCounter, NUM_SUCCEEDED_TASKS=1, TOTAL_LAUNCHED_TASKS=1, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=2174, FILE_BYTES_WRITTEN=672, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=233832448, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=10, cascading.flow.SliceCounters, Process_Begin_Time=1452791302584, Process_Duration=10, Process_End_Time=1452791302594, Read_Duration=2, Tuples_Read=10, Tuples_Written=10, Write_Duration=0, cascading.flow.StepCounters, Tuples_Read=10, Tuples_Written=10
2016-01-14 17:08:22,679 INFO  impl.DAGImpl (DAGImpl.java:finished(1180)) - DAG: dag_1452791301026_0001_1 finished with state: SUCCEEDED
2016-01-14 17:08:22,681 INFO  impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1452791301026_0001_1 transitioned from RUNNING to SUCCEEDED due to event DAG_VERTEX_COMPLETED
2016-01-14 17:08:22,681 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:stop(242)) - Ignoring stop request for containerId: container_1452791301026_0001_00_000001
2016-01-14 17:08:22,681 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791301026_0001_00_000001 transitioned from STOP_REQUESTED to COMPLETED via event C_COMPLETED
2016-01-14 17:08:22 Completed Dag: dag_1452791301026_0001_1
2016-01-14 17:08:22,686 INFO  app.DAGAppMaster (DAGAppMaster.java:handle(579)) - DAG completed, dagId=dag_1452791301026_0001_1, dagState=SUCCEEDED
2016-01-14 17:08:22,687 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: dag_1452791301026_0001_1_post
2016-01-14 17:08:22,688 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 17:08:22,689 INFO  app.DAGAppMaster (DAGAppMaster.java:handle(625)) - Waiting for next DAG to be submitted.
2016-01-14 17:08:22,694 INFO  client.TezClient (TezClient.java:stop(495)) - Shutting down Tez Session, sessionName=(1/1) ...StrategiesReplace/replace, applicationId=application_1452791301026_0001
2016-01-14 17:08:22,702 INFO  client.DAGClientHandler (DAGClientHandler.java:shutdownAM(117)) - Received message to shutdown AM
2016-01-14 17:08:22,702 INFO  rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:setShouldUnregisterFlag(580)) - TaskScheduler notified that it should unregister from RM
2016-01-14 17:08:22,702 INFO  app.DAGAppMaster (DAGAppMaster.java:shutdownTezAM(1088)) - No current running DAG, shutting down the AM
2016-01-14 17:08:22,702 INFO  app.DAGAppMaster (DAGAppMaster.java:shutdown(692)) - DAGAppMasterShutdownHandler invoked
2016-01-14 17:08:22,702 INFO  app.DAGAppMaster (DAGAppMaster.java:shutdown(701)) - Handling DAGAppMaster shutdown
2016-01-14 17:08:22,704 INFO  app.DAGAppMaster (DAGAppMaster.java:run(721)) - Sleeping for 5 seconds before shutting down
2016-01-14 17:08:22,705 INFO  history.HistoryEventHandler (HistoryEventHandler.java:serviceStop(79)) - Stopping HistoryEventHandler
2016-01-14 17:08:22,706 INFO  recovery.RecoveryService (RecoveryService.java:serviceStop(189)) - Stopping RecoveryService
2016-01-14 17:08:22,706 INFO  recovery.RecoveryService (RecoveryService.java:serviceStop(192)) - Handle the remaining events in queue, queue size=0
2016-01-14 17:08:22,706 INFO  recovery.RecoveryService (RecoveryService.java:run(166)) - EventQueue take interrupted. Returning
2016-01-14 17:08:22,706 INFO  recovery.RecoveryService (RecoveryService.java:serviceStop(214)) - Closing Summary Stream
2016-01-14 17:08:22,706 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStop(118)) - Stopping SimpleHistoryLoggingService, eventQueueBacklog=0
2016-01-14 17:08:22,707 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:run(105)) - EventQueue take interrupted. Returning
2016-01-14 17:08:22,744 INFO  app.DAGAppMaster (DAGAppMaster.java:run(1773)) - Completed deletion of tez scratch data dir, path=file:/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/1E43515C97744D998F07322857EBCDB1/A3F922810955485A83E86883CFD6CEC5/.tez/application_1452791301026_0001
2016-01-14 17:08:22,745 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test]  completed in: 00:01.923
2016-01-14 17:08:22,745 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test] at least one sink is marked for delete
2016-01-14 17:08:22,746 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test] sink oldest modified date: Wed Dec 31 23:59:59 UTC 1969
2016-01-14 17:08:22,746 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test] at least one sink is marked for delete
2016-01-14 17:08:22,746 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test] sink oldest modified date: Wed Dec 31 23:59:59 UTC 1969
2016-01-14 17:08:22,841 INFO  cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/output//hadoop2-tez/flowstrategiesplatform/testSkipStrategiesReplace/replace
2016-01-14 17:08:22,895 INFO  util.Util (Util.java:findMainClass(1327)) - using default application jar, may cause class not found exceptions on the cluster
2016-01-14 17:08:22,895 INFO  planner.Hadoop2TezPlanner (Hadoop2TezPlanner.java:initialize(149)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-tez/3.0.4/561447ee876073bb61fddc52e2ad157f45c8edd/cascading-hadoop2-tez-3.0.4.jar
2016-01-14 17:08:22,977 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.029
2016-01-14 17:08:23,000 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.054
2016-01-14 17:08:23,001 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test] rule registry: NoHashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 1
2016-01-14 17:08:23,001 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test] rule registry: HashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 1
2016-01-14 17:08:23,002 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test] rule registry: NoHashJoinHadoop2TezRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-01-14 17:08:23,024 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/classes/test/data/apache.10.txt
2016-01-14 17:08:23,025 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/output/hadoop2-tez/flowstrategiesplatform/testSkipStrategiesKeep/keep
2016-01-14 17:08:23,056 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test] at least one sink does not exist
2016-01-14 17:08:23,058 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test] at least one sink does not exist
2016-01-14 17:08:23,059 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test] starting
2016-01-14 17:08:23,060 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test]  source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/classes/test/data/apache.10.txt"]
2016-01-14 17:08:23,060 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test]  sink: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/output/hadoop2-tez/flowstrategiesplatform/testSkipStrategiesKeep/keep"]
2016-01-14 17:08:23,062 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test]  parallel execution of steps is enabled: false
2016-01-14 17:08:23,062 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test]  executing total steps: 1
2016-01-14 17:08:23,062 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test]  allocating management threads: 1
2016-01-14 17:08:23,063 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test] starting step: (1/1) ...stSkipStrategiesKeep/keep
2016-01-14 17:08:23,064 WARN  flow.Flow (BaseFlow.java:logWarn(1445)) - [test] 'yarn.timeline-service.enabled' is disabled, please enable to capture detailed metrics of completed flows, this may require starting the YARN timeline server daemon
2016-01-14 17:08:23,082 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test] tez session mode enabled: true
2016-01-14 17:08:23,087 INFO  client.TezClient (TezClient.java:<init>(153)) - Tez Client Version: [ component=tez-api, version=0.6.2, revision=c04283bf91fd96823eec37056d5c8b1a92728265, SCM-URL=scm:git:https://git-wip-us.apache.org/repos/asf/tez.git, buildTime=20150804-1436 ]
2016-01-14 17:08:23,088 INFO  client.TezClient (TezClient.java:start(333)) - Session mode. Starting session.
2016-01-14 17:08:23,088 INFO  client.TezClientUtils (TezClientUtils.java:setupTezJarsLocalResources(159)) - Ignoring 'tez.lib.uris' since  'tez.ignore.lib.uris' is set to true
2016-01-14 17:08:23,099 INFO  client.TezClient (TezCommonUtils.java:createTezSystemStagingPath(118)) - Tez system stage directory file:/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/DC3C38CB5A2B4257A57B68E50C589500/D0404757EABE4E1897C617AF30BF8AA4/.tez/application_1452791303088_0001 doesn't exist and is created
2016-01-14 17:08:23,126 INFO  client.LocalClient (LocalClient.java:createDAGAppMaster(328)) - DAGAppMaster thread has been created
2016-01-14 17:08:23,126 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-01-14 17:08:23,128 INFO  client.LocalClient (LocalClient.java:run(275)) - Using staging directory: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/DC3C38CB5A2B4257A57B68E50C589500/D0404757EABE4E1897C617AF30BF8AA4/.tez/application_1452791303088_0001
2016-01-14 17:08:23,132 INFO  app.DAGAppMaster (DAGAppMaster.java:<init>(309)) - Created DAGAppMaster for application appattempt_1452791303088_0001_000000, versionInfo=[ component=tez-dag, version=0.6.2, revision=c04283bf91fd96823eec37056d5c8b1a92728265, SCM-URL=scm:git:https://git-wip-us.apache.org/repos/asf/tez.git, buildTime=20150804-1436 ]
2016-01-14 17:08:23,151 INFO  app.DAGAppMaster (DAGAppMaster.java:serviceInit(333)) - Comparing client version with AM version, clientVersion=0.6.2, AMVersion=0.6.2
2016-01-14 17:08:23,152 INFO  app.DAGAppMaster (DAGAppMaster.java:serviceInit(386)) - Adding session token to jobTokenSecretManager for application
2016-01-14 17:08:23,154 INFO  node.AMNodeTracker (AMNodeTracker.java:serviceInit(77)) - blacklistDisablePercent is 33, blacklistingEnabled: false, maxTaskFailuresPerNode: 1
2016-01-14 17:08:23,154 INFO  history.HistoryEventHandler (HistoryEventHandler.java:serviceInit(50)) - Initializing HistoryEventHandler
2016-01-14 17:08:23,154 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceInit(66)) - Log file location for SimpleHistoryLoggingService not specified, defaulting to containerLogDir=/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/DC3C38CB5A2B4257A57B68E50C589500/D0404757EABE4E1897C617AF30BF8AA4/.tez/application_1452791303088_0001/localmode-log-dir
2016-01-14 17:08:23,154 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceInit(88)) - Initializing SimpleHistoryLoggingService, logFileLocation=/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/DC3C38CB5A2B4257A57B68E50C589500/D0404757EABE4E1897C617AF30BF8AA4/.tez/application_1452791303088_0001/localmode-log-dir/history.txt.appattempt_1452791303088_0001_000000, maxErrors=10
2016-01-14 17:08:23,154 INFO  recovery.RecoveryService (RecoveryService.java:serviceInit(109)) - Initializing RecoveryService
2016-01-14 17:08:23,155 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:N/A][Event:AM_LAUNCHED]: appAttemptId=appattempt_1452791303088_0001_000000, appSubmitTime=1452791303132, launchTime=1452791303132
2016-01-14 17:08:23,161 INFO  history.HistoryEventHandler (HistoryEventHandler.java:serviceStart(73)) - Starting HistoryEventHandler
2016-01-14 17:08:23,163 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStart(95)) - Starting SimpleHistoryLoggingService
2016-01-14 17:08:23,166 INFO  recovery.RecoveryService (RecoveryService.java:serviceStart(127)) - Starting RecoveryService
2016-01-14 17:08:23,166 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event AM_LAUNCHED to history file
2016-01-14 17:08:23,168 INFO  client.DAGClientServer (DAGClientServer.java:serviceStart(91)) - Instantiated DAGClientRPCServer at ip-10-187-41-40.ec2.internal/10.187.41.40:32810
2016-01-14 17:08:23,170 WARN  impl.MetricsConfig (MetricsConfig.java:loadFirst(124)) - Cannot locate configuration: tried hadoop-metrics2-dagappmaster.properties,hadoop-metrics2.properties
2016-01-14 17:08:23,173 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event AM_STARTED to history file
2016-01-14 17:08:23,173 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:N/A][Event:AM_STARTED]: appAttemptId=appattempt_1452791303088_0001_000000, startTime=1452791303172
2016-01-14 17:08:23,173 INFO  app.DAGAppMaster (DAGAppMaster.java:serviceStart(1644)) - In Session mode. Waiting for DAG over RPC
2016-01-14 17:08:23,226 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: IDLE
2016-01-14 17:08:23,227 INFO  client.TezClient (TezClient.java:start(367)) - The url to track the Tez Session: N/A
2016-01-14 17:08:23,227 INFO  client.TezClient (TezClient.java:submitDAGSession(405)) - Submitting dag to TezSession, sessionName=(1/1) ...stSkipStrategiesKeep/keep, applicationId=application_1452791303088_0001, dagName=[DC3C38CB5A2B4257A57B68E50C589500/D0404757EABE4E1897C617AF30BF8AA4] test/(1/1) ...stSkipStrategiesKeep/keep
2016-01-14 17:08:23,257 INFO  app.DAGAppMaster (DAGAppMaster.java:submitDAGToAppMaster(1126)) - Starting DAG submitted via RPC: [DC3C38CB5A2B4257A57B68E50C589500/D0404757EABE4E1897C617AF30BF8AA4] test/(1/1) ...stSkipStrategiesKeep/keep
2016-01-14 17:08:23,260 INFO  app.DAGAppMaster (DAGAppMaster.java:generateDAGVizFile(870)) - Generating DAG graphviz file, dagId=dag_1452791303088_0001_1, filePath=/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/DC3C38CB5A2B4257A57B68E50C589500/D0404757EABE4E1897C617AF30BF8AA4/.tez/application_1452791303088_0001/localmode-log-dir/dag_1452791303088_0001_1.dot
2016-01-14 17:08:23,261 INFO  app.DAGAppMaster (DAGAppMaster.java:writePBTextFile(887)) - Writing DAG plan to: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/DC3C38CB5A2B4257A57B68E50C589500/D0404757EABE4E1897C617AF30BF8AA4/.tez/application_1452791303088_0001/localmode-log-dir/dag_1452791303088_0001_1-tez-dag.pb.txt
2016-01-14 17:08:23,288 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: dag_1452791303088_0001_1
2016-01-14 17:08:23,288 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 17:08:23,288 INFO  app.DAGAppMaster (DAGAppMaster.java:startDAG(2051)) - Running DAG: [DC3C38CB5A2B4257A57B68E50C589500/D0404757EABE4E1897C617AF30BF8AA4] test/(1/1) ...stSkipStrategiesKeep/keep
2016-01-14 17:08:23 Running Dag: dag_1452791303088_0001_1
2016-01-14 17:08:23,304 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791303088_0001_1][Event:DAG_SUBMITTED]: dagID=dag_1452791303088_0001_1, submitTime=1452791303257
2016-01-14 17:08:23,304 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_SUBMITTED to history file
2016-01-14 17:08:23,305 INFO  impl.VertexImpl (VertexImpl.java:setAdditionalOutputs(4033)) - setting additional outputs for vertex D45A4D434A614EE3BDE8A46A1CA33180
2016-01-14 17:08:23,306 INFO  impl.DAGImpl (DAGImpl.java:assignDAGScheduler(1381)) - Using DAG Scheduler: org.apache.tez.dag.app.dag.impl.DAGSchedulerNaturalOrderControlled
2016-01-14 17:08:23,306 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_INITIALIZED to history file
2016-01-14 17:08:23,306 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791303088_0001_1][Event:DAG_INITIALIZED]: dagID=dag_1452791303088_0001_1, initTime=1452791303305
2016-01-14 17:08:23,307 INFO  impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1452791303088_0001_1 transitioned from NEW to INITED due to event DAG_INIT
2016-01-14 17:08:23,308 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791303088_0001_1][Event:DAG_STARTED]: dagID=dag_1452791303088_0001_1, startTime=1452791303308
2016-01-14 17:08:23,309 INFO  impl.DAGImpl (DAGImpl.java:transition(1614)) - Added additional resources : [[]] to classpath
2016-01-14 17:08:23,309 INFO  impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1452791303088_0001_1 transitioned from INITED to RUNNING due to event DAG_START
2016-01-14 17:08:23,309 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_STARTED to history file
2016-01-14 17:08:23,309 INFO  impl.VertexImpl (VertexImpl.java:setupVertex(2068)) - Root Inputs exist for Vertex: D45A4D434A614EE3BDE8A46A1CA33180 : {7CFF6D0300B043F489FE6AD570E91CCF={InputName=7CFF6D0300B043F489FE6AD570E91CCF}, {Descriptor=ClassName=org.apache.tez.mapreduce.input.MRInput, hasPayload=true}, {ControllerDescriptor=ClassName=org.apache.tez.mapreduce.common.MRInputAMSplitGenerator, hasPayload=false}}
2016-01-14 17:08:23,309 INFO  impl.VertexImpl (VertexImpl.java:setupVertex(2078)) - Starting root input initializer for input: 7CFF6D0300B043F489FE6AD570E91CCF, with class: [org.apache.tez.mapreduce.common.MRInputAMSplitGenerator]
2016-01-14 17:08:23,309 INFO  impl.VertexImpl (VertexImpl.java:assignVertexManager(2191)) - Setting vertexManager to RootInputVertexManager for vertex_1452791303088_0001_1_00 [D45A4D434A614EE3BDE8A46A1CA33180]
2016-01-14 17:08:23,310 INFO  impl.VertexImpl (VertexImpl.java:handleInitEvent(2983)) - Num tasks is -1. Expecting VertexManager/InputInitializers/1-1 split to set #tasks for the vertex vertex_1452791303088_0001_1_00 [D45A4D434A614EE3BDE8A46A1CA33180]
2016-01-14 17:08:23,310 INFO  impl.VertexImpl (VertexImpl.java:handleInitEvent(2987)) - Vertex will initialize from input initializer. vertex_1452791303088_0001_1_00 [D45A4D434A614EE3BDE8A46A1CA33180]
2016-01-14 17:08:23,309 INFO  client.TezClient (TezClient.java:submitDAGSession(478)) - Submitted dag to TezSession, sessionName=(1/1) ...stSkipStrategiesKeep/keep, applicationId=application_1452791303088_0001, dagName=[DC3C38CB5A2B4257A57B68E50C589500/D0404757EABE4E1897C617AF30BF8AA4] test/(1/1) ...stSkipStrategiesKeep/keep
2016-01-14 17:08:23,310 INFO  impl.VertexImpl (VertexImpl.java:setupInputInitializerManager(3933)) - Vertex will initialize via inputInitializers vertex_1452791303088_0001_1_00 [D45A4D434A614EE3BDE8A46A1CA33180]. Starting root input initializers: 1
2016-01-14 17:08:23,314 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452791303088_0001_1_00 [D45A4D434A614EE3BDE8A46A1CA33180] transitioned from NEW to INITIALIZING due to event V_INIT
2016-01-14 17:08:23,315 INFO  dag.RootInputInitializerManager (RootInputInitializerManager.java:run(242)) - Starting InputInitializer for Input: 7CFF6D0300B043F489FE6AD570E91CCF on vertex vertex_1452791303088_0001_1_00 [D45A4D434A614EE3BDE8A46A1CA33180]
2016-01-14 17:08:23,322 INFO  common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(92)) - Emitting serialized splits: true
2016-01-14 17:08:23,322 INFO  common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(110)) - Input 7CFF6D0300B043F489FE6AD570E91CCF asking for 1 tasks. Headroom: 672 Task Resource: 1024 waves: 1.7
2016-01-14 17:08:23,324 INFO  common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(121)) - Grouping input splits
2016-01-14 17:08:23,325 INFO  hadoop.MRInputHelpers (MRInputHelpers.java:generateInputSplitsToMem(294)) - Generating mapred api input splits
2016-01-14 17:08:23,328 INFO  hadoop.MRInputHelpers (MRInputHelpers.java:generateInputSplitsToMem(300)) - NumSplits: 1, SerializedSize: 408
2016-01-14 17:08:23,330 INFO  dag.RootInputInitializerManager (RootInputInitializerManager.java:onSuccess(272)) - Succeeded InputInitializer for Input: 7CFF6D0300B043F489FE6AD570E91CCF on vertex vertex_1452791303088_0001_1_00 [D45A4D434A614EE3BDE8A46A1CA33180]
2016-01-14 17:08:23,332 INFO  impl.VertexImpl (VertexImpl.java:canInitVertex(3195)) - Cannot init vertex: vertex_1452791303088_0001_1_00 [D45A4D434A614EE3BDE8A46A1CA33180] numTasks: -1 numUnitializedEdges: 0 numInitializedInputs: 0 initWaitsForRootInitializers: true
2016-01-14 17:08:23,332 INFO  impl.VertexImpl (VertexImpl.java:setParallelism(1374)) - Got updated RootInputsSpecs: {7CFF6D0300B043F489FE6AD570E91CCF=forAllWorkUnits=true, update=[1]}
2016-01-14 17:08:23,333 INFO  impl.VertexImpl (VertexImpl.java:setParallelism(1393)) - Vertex vertex_1452791303088_0001_1_00 [D45A4D434A614EE3BDE8A46A1CA33180] parallelism set to 1
2016-01-14 17:08:23,333 INFO  impl.VertexImpl (VertexImpl.java:canInitVertex(3195)) - Cannot init vertex: vertex_1452791303088_0001_1_00 [D45A4D434A614EE3BDE8A46A1CA33180] numTasks: 1 numUnitializedEdges: 0 numInitializedInputs: 0 initWaitsForRootInitializers: true
2016-01-14 17:08:23,334 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791303088_0001_1][Event:VERTEX_DATA_MOVEMENT_EVENTS_GENERATED]: vertexId=vertex_1452791303088_0001_1_00, eventCount=1
2016-01-14 17:08:23,334 INFO  impl.VertexImpl (VertexImpl.java:initializeCommitters(1915)) - Invoking committer inits for vertex, vertexId=vertex_1452791303088_0001_1_00 [D45A4D434A614EE3BDE8A46A1CA33180]
2016-01-14 17:08:23,334 INFO  impl.VertexImpl (VertexImpl.java:initializeCommitters(1927)) - Instantiating committer for output=7FD5AE420D364A58BB8BD562A086D0DE, vertexId=vertex_1452791303088_0001_1_00 [D45A4D434A614EE3BDE8A46A1CA33180], committerClass=org.apache.tez.mapreduce.committer.MROutputCommitter
2016-01-14 17:08:23,334 INFO  impl.VertexImpl (VertexImpl.java:run(1945)) - Invoking committer init for output=7FD5AE420D364A58BB8BD562A086D0DE, vertexId=vertex_1452791303088_0001_1_00 [D45A4D434A614EE3BDE8A46A1CA33180]
2016-01-14 17:08:23,340 INFO  committer.MROutputCommitter (MROutputCommitter.java:getOutputCommitter(145)) - OutputCommitter for outputName=7FD5AE420D364A58BB8BD562A086D0DE, vertexName=D45A4D434A614EE3BDE8A46A1CA33180, outputCommitterClass=org.apache.hadoop.mapred.FileOutputCommitter
2016-01-14 17:08:23,341 INFO  impl.VertexImpl (VertexImpl.java:run(1949)) - Invoking committer setup for output=7FD5AE420D364A58BB8BD562A086D0DE, vertexId=vertex_1452791303088_0001_1_00 [D45A4D434A614EE3BDE8A46A1CA33180]
2016-01-14 17:08:23,341 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test] submitted tez dag to app master: application_1452791303088_0001, with dag id: dag_1452791303088_0001_1
2016-01-14 17:08:23,343 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_INITIALIZED to history file
2016-01-14 17:08:23,344 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791303088_0001_1][Event:VERTEX_INITIALIZED]: vertexName=D45A4D434A614EE3BDE8A46A1CA33180, vertexId=vertex_1452791303088_0001_1_00, initRequestedTime=1452791303309, initedTime=1452791303343, numTasks=1, processorName=cascading.flow.tez.FlowProcessor, additionalInputsCount=1
2016-01-14 17:08:23,344 INFO  impl.VertexImpl (VertexImpl.java:startIfPossible(3061)) - Triggering start event for vertex: vertex_1452791303088_0001_1_00 [D45A4D434A614EE3BDE8A46A1CA33180] with distanceFromRoot: 0
2016-01-14 17:08:23,344 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452791303088_0001_1_00 [D45A4D434A614EE3BDE8A46A1CA33180] transitioned from INITIALIZING to INITED due to event V_ROOT_INPUT_INITIALIZED
2016-01-14 17:08:23,345 INFO  impl.ImmediateStartVertexManager (ImmediateStartVertexManager.java:scheduleTasks(99)) - Starting 1 in D45A4D434A614EE3BDE8A46A1CA33180
2016-01-14 17:08:23,345 INFO  impl.VertexImpl (VertexImpl.java:scheduleTasks(1250)) - Routing pending task events for vertex: vertex_1452791303088_0001_1_00 [D45A4D434A614EE3BDE8A46A1CA33180]
2016-01-14 17:08:23,346 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_STARTED to history file
2016-01-14 17:08:23,346 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791303088_0001_1][Event:VERTEX_STARTED]: vertexId=vertex_1452791303088_0001_1_00, startRequestedTime=1452791303345, startedTime=1452791303345
2016-01-14 17:08:23,347 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452791303088_0001_1_00 [D45A4D434A614EE3BDE8A46A1CA33180] transitioned from INITED to RUNNING due to event V_START
2016-01-14 17:08:23,348 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_STARTED to history file
2016-01-14 17:08:23,349 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791303088_0001_1][Event:TASK_STARTED]: vertexName=D45A4D434A614EE3BDE8A46A1CA33180, taskId=task_1452791303088_0001_1_00_000000, scheduledTime=1452791303348, launchTime=1452791303348
2016-01-14 17:08:23,350 INFO  impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452791303088_0001_1_00_000000 Task Transitioned from NEW to SCHEDULED due to event T_SCHEDULE
2016-01-14 17:08:23,351 INFO  impl.DAGSchedulerNaturalOrderControlled (DAGSchedulerNaturalOrderControlled.java:scheduleTask(111)) - Scheduled vertex: vertex_1452791303088_0001_1_00 [D45A4D434A614EE3BDE8A46A1CA33180]
2016-01-14 17:08:23,352 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1014)) - remoteTaskSpec:DAGName : [DC3C38CB5A2B4257A57B68E50C589500/D0404757EABE4E1897C617AF30BF8AA4] test/(1/1) ...stSkipStrategiesKeep/keep, VertexName: D45A4D434A614EE3BDE8A46A1CA33180, VertexParallelism: 1, TaskAttemptID:attempt_1452791303088_0001_1_00_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=7CFF6D0300B043F489FE6AD570E91CCF, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=7FD5AE420D364A58BB8BD562A086D0DE, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }}, ]
2016-01-14 17:08:23,353 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452791303088_0001_1_00_000000_0 TaskAttempt Transitioned from NEW to START_WAIT due to event TA_SCHEDULE
2016-01-14 17:08:23,353 INFO  rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_LAUNCH_REQUEST
2016-01-14 17:08:23,354 INFO  node.AMNodeTracker (AMNodeTracker.java:nodeSeen(91)) - Adding new node: 127.0.0.1:0
2016-01-14 17:08:23,357 INFO  container.AMContainerHelpers (AMContainerHelpers.java:createCommonContainerLaunchContext(112)) - Adding #1 tokens and #0 secret keys for NM use for launching container
2016-01-14 17:08:23,357 INFO  container.AMContainerHelpers (AMContainerHelpers.java:createCommonContainerLaunchContext(122)) - Putting shuffle token in serviceData
2016-01-14 17:08:23,357 INFO  container.AMContainerImpl (AMContainerImpl.java:transition(521)) - Sending Launch Request for Container with id: container_1452791303088_0001_00_000001
2016-01-14 17:08:23,357 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791303088_0001_00_000001 transitioned from ALLOCATED to LAUNCHING via event C_LAUNCH_REQUEST
2016-01-14 17:08:23,361 INFO  task.TezChild (TezChild.java:newTezChild(432)) - PID, containerIdentifier:  null, container_1452791303088_0001_00_000001
2016-01-14 17:08:23,361 WARN  impl.MetricsSystemImpl (MetricsSystemImpl.java:init(145)) - DAGAppMaster metrics system already initialized!
2016-01-14 17:08:23,362 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791303088_0001_00_000001 transitioned from LAUNCHING to IDLE via event C_LAUNCHED
2016-01-14 17:08:23,362 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791303088_0001_1][Event:CONTAINER_LAUNCHED]: containerId=container_1452791303088_0001_00_000001, launchTime=1452791303362
2016-01-14 17:08:23,362 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_LAUNCHED to history file
2016-01-14 17:08:23,363 INFO  task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1452791303088_0001_00_000001
2016-01-14 17:08:23,364 INFO  container.AMContainerImpl (AMContainerImpl.java:transition(827)) - Assigned taskAttempt + [attempt_1452791303088_0001_1_00_000000_0] to container: [container_1452791303088_0001_00_000001]
2016-01-14 17:08:23,364 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791303088_0001_00_000001 transitioned from IDLE to RUNNING via event C_PULL_TA
2016-01-14 17:08:23,364 INFO  app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(240)) - Container with id: container_1452791303088_0001_00_000001 given task: attempt_1452791303088_0001_1_00_000000_0
2016-01-14 17:08:23,364 INFO  task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1452791303088_0001_00_000001: 0 ms after starting to poll. TaskInfo: shouldDie: false, currentTaskAttemptId: attempt_1452791303088_0001_1_00_000000_0
2016-01-14 17:08:23,365 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1146)) - TaskAttempt: [attempt_1452791303088_0001_1_00_000000_0] started. Is using containerId: [container_1452791303088_0001_00_000001] on NM: [127.0.0.1:0]
2016-01-14 17:08:23 Starting to run new task attempt: attempt_1452791303088_0001_1_00_000000_0
2016-01-14 17:08:23,366 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: attempt_1452791303088_0001_1_00_000000_0
2016-01-14 17:08:23,366 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791303088_0001_1][Event:TASK_ATTEMPT_STARTED]: vertexName=D45A4D434A614EE3BDE8A46A1CA33180, taskAttemptId=attempt_1452791303088_0001_1_00_000000_0, startTime=1452791303364, containerId=container_1452791303088_0001_00_000001, nodeId=127.0.0.1:0, inProgressLogs=127.0.0.1:0/node/containerlogs/container_1452791303088_0001_00_000001/teamcity, completedLogs=
2016-01-14 17:08:23,366 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_STARTED to history file
2016-01-14 17:08:23,367 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 17:08:23,367 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452791303088_0001_1_00_000000_0 TaskAttempt Transitioned from START_WAIT to RUNNING due to event TA_STARTED_REMOTELY
2016-01-14 17:08:23,368 INFO  impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452791303088_0001_1_00_000000 Task Transitioned from SCHEDULED to RUNNING due to event T_ATTEMPT_LAUNCHED
2016-01-14 17:08:23,368 INFO  task.TezChild (TezChild.java:handleNewTaskCredentials(273)) - Refreshing UGI since Credentials have changed
2016-01-14 17:08:23,368 INFO  task.TezChild (TezChild.java:handleNewTaskCredentials(276)) - Credentials : #Tokens=1, #SecretKeys=0
2016-01-14 17:08:23,368 INFO  task.TezChild (TezChild.java:handleNewTaskLocalResources(302)) - Localizing additional local resources for Task : {}
2016-01-14 17:08:23,368 INFO  task.TezChild (TezChild.java:handleNewTaskLocalResources(312)) - Done localizing additional resources
2016-01-14 17:08:23,369 INFO  metrics.TaskCounterUpdater (TaskCounterUpdater.java:initResourceCalculatorPlugin(148)) -  Using ResourceCalculatorProcessTree : [ ]
2016-01-14 17:08:23,369 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:<init>(149)) - Initializing LogicalIOProcessorRuntimeTask with TaskSpec: DAGName : [DC3C38CB5A2B4257A57B68E50C589500/D0404757EABE4E1897C617AF30BF8AA4] test/(1/1) ...stSkipStrategiesKeep/keep, VertexName: D45A4D434A614EE3BDE8A46A1CA33180, VertexParallelism: 1, TaskAttemptID:attempt_1452791303088_0001_1_00_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=7CFF6D0300B043F489FE6AD570E91CCF, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=7FD5AE420D364A58BB8BD562A086D0DE, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }}, ]
2016-01-14 17:08:23,370 INFO  resources.MemoryDistributor (MemoryDistributor.java:<init>(85)) - InitialMemoryDistributor (isEnabled=true) invoked with: numInputs=1, numOutputs=1, JVM.maxFree=704643072
2016-01-14 17:08:23,372 INFO  task.TezTaskRunner (TezTaskRunner.java:run(172)) - Initializing task, taskAttemptId=attempt_1452791303088_0001_1_00_000000_0
2016-01-14 17:08:23,372 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(191)) - Initializing LogicalProcessorIORuntimeTask
2016-01-14 17:08:23,373 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(195)) - Creating processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 17:08:23,374 INFO  impl.TaskImpl (TaskImpl.java:getTaskAttemptTezEvents(481)) - TaskAttempt:attempt_1452791303088_0001_1_00_000000_0 sent events: (0-1)
2016-01-14 17:08:23,375 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(488)) - Initializing processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 17:08:23,375 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(438)) - Initializing Output using OutputSpec: { destinationVertexName=7FD5AE420D364A58BB8BD562A086D0DE, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }
2016-01-14 17:08:23,375 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(389)) - Initializing Input using InputSpec: { sourceVertexName=7CFF6D0300B043F489FE6AD570E91CCF, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }
2016-01-14 17:08:23,376 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createOutput(565)) - Creating Output
2016-01-14 17:08:23,376 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(446)) - Initializing Output with dest edge: 7FD5AE420D364A58BB8BD562A086D0DE
2016-01-14 17:08:23,376 INFO  output.MROutput (MROutput.java:initialize(347)) - Initializing Simple Output
2016-01-14 17:08:23,377 INFO  resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 0, type: OUTPUT, componentVertexName: 7FD5AE420D364A58BB8BD562A086D0DE
2016-01-14 17:08:23,377 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createInput(537)) - Creating Input
2016-01-14 17:08:23,377 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(397)) - Initializing Input with src edge: 7CFF6D0300B043F489FE6AD570E91CCF
2016-01-14 17:08:23,378 INFO  resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 0, type: INPUT, componentVertexName: 7CFF6D0300B043F489FE6AD570E91CCF
2016-01-14 17:08:23,384 INFO  input.MRInput (MRInput.java:initialize(440)) - Using New mapreduce API: false, split information via event: true
2016-01-14 17:08:23,385 INFO  input.MRInput (MRInput.java:initializeInternal(493)) - Initialzed MRInput: 7CFF6D0300B043F489FE6AD570E91CCF
2016-01-14 17:08:23,385 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(403)) - Initialized Input with src edge: 7CFF6D0300B043F489FE6AD570E91CCF
2016-01-14 17:08:23,391 INFO  tez.FlowProcessor (FlowProcessor.java:initialize(88)) - cascading version: 3.0.4
2016-01-14 17:08:23,402 INFO  output.MROutput (MROutput.java:initialize(418)) - Initialized Simple Output, using_new_api: false
2016-01-14 17:08:23,403 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(452)) - Initialized Output with dest edge: 7FD5AE420D364A58BB8BD562A086D0DE
2016-01-14 17:08:23,404 INFO  tez.FlowProcessor (FlowProcessor.java:initialize(94)) - flow node id: D45A4D434A614EE3BDE8A46A1CA33180, ordinal: 0
2016-01-14 17:08:23,405 INFO  tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: D45A4D434A614EE3BDE8A46A1CA33180, mem on start (mb), free: 185, total: 281, max: 672
2016-01-14 17:08:23,405 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(491)) - Initialized processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 17:08:23,405 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 2 initializers to finish
2016-01-14 17:08:23,405 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 1 initializers to finish
2016-01-14 17:08:23,405 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(233)) - All initializers finished
2016-01-14 17:08:23,406 INFO  resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(124)) - Using Allocator class: org.apache.tez.runtime.library.resources.WeightedScalingMemoryDistributor
2016-01-14 17:08:23,406 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:getRequestTypeForClass(197)) - Falling back to RequestType.OTHER for class: org.apache.tez.mapreduce.output.MROutput
2016-01-14 17:08:23,406 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 1, for type: OTHER
2016-01-14 17:08:23,406 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:getRequestTypeForClass(197)) - Falling back to RequestType.OTHER for class: org.apache.tez.mapreduce.input.MRInput
2016-01-14 17:08:23,406 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 1, for type: OTHER
2016-01-14 17:08:23,407 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:computeReservedFraction(262)) - InitialReservationFraction=0.3, AdditionalReservationFractionForIOs=0.03, finalReserveFractionUsed=0.32999999999999996
2016-01-14 17:08:23,407 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:assignMemory(126)) - Scaling Requests. NumRequests: 2, numScaledRequests: 2, TotalRequested: 0, TotalRequestedScaled: 0.0, TotalJVMHeap: 704643072, TotalAvailable: 472110858, TotalRequested/TotalJVMHeap:0.00
2016-01-14 17:08:23,408 INFO  resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: OUTPUT, 7FD5AE420D364A58BB8BD562A086D0DE, org.apache.tez.mapreduce.output.MROutput: requested=0, allocated=0
2016-01-14 17:08:23,408 INFO  resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: INPUT, 7CFF6D0300B043F489FE6AD570E91CCF, org.apache.tez.mapreduce.input.MRInput: requested=0, allocated=0
2016-01-14 17:08:23,408 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(255)) - Starting Inputs/Outputs
2016-01-14 17:08:23,408 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(419)) - Starting Input with src edge: 7CFF6D0300B043F489FE6AD570E91CCF
2016-01-14 17:08:23,409 INFO  input.MRInput (MRInput.java:start(450)) - MRInput setup to received events1
2016-01-14 17:08:23,409 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(421)) - Started Input with src edge: 7CFF6D0300B043F489FE6AD570E91CCF
2016-01-14 17:08:23,409 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(268)) - Input: 7CFF6D0300B043F489FE6AD570E91CCF being auto started by the framework. Subsequent instances will not be auto-started
2016-01-14 17:08:23,410 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(289)) - Num IOs determined for AutoStart: 1
2016-01-14 17:08:23,410 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(291)) - Waiting for 1 IOs to start
2016-01-14 17:08:23,411 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(304)) - AutoStartComplete
2016-01-14 17:08:23,411 INFO  task.TezTaskRunner (TezTaskRunner.java:run(175)) - Running task, taskAttemptId=attempt_1452791303088_0001_1_00_000000_0
2016-01-14 17:08:23,411 INFO  input.MRInput (MRInput.java:initFromEventInternal(619)) - Initializing RecordReader from event
2016-01-14 17:08:23,413 INFO  input.MRInput (MRInput.java:initFromEventInternal(630)) - Split Details -> SplitClass: org.apache.hadoop.mapred.split.TezGroupedSplit, OldSplit: org.apache.hadoop.mapred.split.TezGroupedSplit@eee9aab
2016-01-14 17:08:23,414 INFO  lib.MRReaderMapred (MRReaderMapred.java:setIncrementalConfigParams(163)) - Processing split: org.apache.hadoop.mapred.split.TezGroupedSplit@eee9aab
2016-01-14 17:08:23,415 INFO  input.MRInput (MRInput.java:initFromEventInternal(634)) - Initialized RecordReader from event
2016-01-14 17:08:23,416 INFO  input.MRInput (MRInput.java:processSplitEvent(586)) - Notifying on RecordReader Initialized
2016-01-14 17:08:23,422 INFO  graph.Hadoop2TezStreamGraph (Hadoop2TezStreamGraph.java:buildGraph(151)) - using streamed source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/classes/test/data/apache.10.txt"]
2016-01-14 17:08:23,423 INFO  tez.FlowProcessor (FlowProcessor.java:run(121)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/classes/test/data/apache.10.txt"] streamed: true, id: 7CFF6D0300B043F489FE6AD570E91CCF
2016-01-14 17:08:23,423 INFO  tez.FlowProcessor (FlowProcessor.java:run(124)) - sinking to: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/output/hadoop2-tez/flowstrategiesplatform/testSkipStrategiesKeep/keep"], id: 7FD5AE420D364A58BB8BD562A086D0DE
2016-01-14 17:08:23,423 INFO  element.TezSinkStage (TezSinkStage.java:prepare(57)) - calling MROutput#start() on: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/output/hadoop2-tez/flowstrategiesplatform/testSkipStrategiesKeep/keep"]
2016-01-14 17:08:23,424 INFO  element.TezSourceStage (TezSourceStage.java:prepare(63)) - calling MRInput#start() on: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/classes/test/data/apache.10.txt"]
2016-01-14 17:08:23,424 INFO  input.MRInput (MRInput.java:start(450)) - MRInput setup to received events1
2016-01-14 17:08:23,425 INFO  tez.FlowProcessor (FlowProcessor.java:waitForInputsReady(202)) - flow node id: D45A4D434A614EE3BDE8A46A1CA33180, all 1 inputs ready in: 00:00:00.000
2016-01-14 17:08:23,429 INFO  output.MROutput (MROutput.java:flush(534)) - Flushing Simple Output
2016-01-14 17:08:23,430 INFO  output.MROutput (MROutput.java:flush(544)) - Flushed Simple Output
2016-01-14 17:08:23,431 INFO  app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:canCommit(353)) - Commit go/no-go request from attempt_1452791303088_0001_1_00_000000_0
2016-01-14 17:08:23,431 INFO  impl.TaskImpl (TaskImpl.java:canCommit(750)) - attempt_1452791303088_0001_1_00_000000_0 given a go for committing the task output.
2016-01-14 17:08:23,432 INFO  task.TezTaskRunner (TezTaskRunner.java:run(177)) - Closing task, taskAttemptId=attempt_1452791303088_0001_1_00_000000_0
2016-01-14 17:08:23,432 INFO  tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: D45A4D434A614EE3BDE8A46A1CA33180, mem on close (mb), free: 183, total: 281, max: 672
2016-01-14 17:08:23 Completed running task attempt: attempt_1452791303088_0001_1_00_000000_0
2016-01-14 17:08:23,433 INFO  task.TezTaskRunner (TezTaskRunner.java:run(181)) - Task completed, taskAttemptId=attempt_1452791303088_0001_1_00_000000_0, fatalErrorOccurred=false
2016-01-14 17:08:23,435 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:cleanup(712)) - Final Counters : Counters: 21 [[File System Counters FILE_BYTES_READ=2174, FILE_BYTES_WRITTEN=152, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0][org.apache.tez.common.counters.TaskCounter GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=295174144, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=10][cascading.flow.SliceCounters Process_Begin_Time=1452791303425, Process_Duration=7, Process_End_Time=1452791303432, Read_Duration=3, Tuples_Read=10, Tuples_Written=10, Write_Duration=0][cascading.flow.StepCounters Tuples_Read=10, Tuples_Written=10]]
2016-01-14 17:08:23,440 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791303088_0001_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=D45A4D434A614EE3BDE8A46A1CA33180, taskAttemptId=attempt_1452791303088_0001_1_00_000000_0, startTime=1452791303364, finishTime=1452791303435, timeTaken=71, status=SUCCEEDED, errorEnum=, diagnostics=, counters=Counters: 22, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=2174, FILE_BYTES_WRITTEN=152, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=295174144, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=10, cascading.flow.SliceCounters, Process_Begin_Time=1452791303425, Process_Duration=7, Process_End_Time=1452791303432, Read_Duration=3, Tuples_Read=10, Tuples_Written=10, Write_Duration=0, cascading.flow.StepCounters, Tuples_Read=10, Tuples_Written=10
2016-01-14 17:08:23,441 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452791303088_0001_1_00_000000_0 TaskAttempt Transitioned from RUNNING to SUCCEEDED due to event TA_DONE
2016-01-14 17:08:23,441 INFO  impl.TaskImpl (TaskImpl.java:transition(1052)) - Task succeeded with attempt attempt_1452791303088_0001_1_00_000000_0
2016-01-14 17:08:23,442 INFO  rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_ENDED
2016-01-14 17:08:23,439 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_FINISHED to history file
2016-01-14 17:08:23,443 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791303088_0001_1][Event:TASK_FINISHED]: vertexName=D45A4D434A614EE3BDE8A46A1CA33180, taskId=task_1452791303088_0001_1_00_000000, startTime=1452791303364, finishTime=1452791303441, timeTaken=77, status=SUCCEEDED, successfulAttemptID=attempt_1452791303088_0001_1_00_000000_0, diagnostics=, counters=Counters: 22, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=2174, FILE_BYTES_WRITTEN=152, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=295174144, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=10, cascading.flow.SliceCounters, Process_Begin_Time=1452791303425, Process_Duration=7, Process_End_Time=1452791303432, Read_Duration=3, Tuples_Read=10, Tuples_Written=10, Write_Duration=0, cascading.flow.StepCounters, Tuples_Read=10, Tuples_Written=10
2016-01-14 17:08:23,440 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: 
2016-01-14 17:08:23,445 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_FINISHED to history file
2016-01-14 17:08:23,445 INFO  impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452791303088_0001_1_00_000000 Task Transitioned from RUNNING to SUCCEEDED due to event T_ATTEMPT_SUCCEEDED
2016-01-14 17:08:23,446 INFO  impl.VertexImpl (VertexImpl.java:transition(3536)) - Num completed Tasks for vertex_1452791303088_0001_1_00 [D45A4D434A614EE3BDE8A46A1CA33180] : 1
2016-01-14 17:08:23,446 INFO  impl.VertexImpl (VertexImpl.java:checkVertexForCompletion(1674)) - Vertex succeeded: vertex_1452791303088_0001_1_00 [D45A4D434A614EE3BDE8A46A1CA33180]
2016-01-14 17:08:23,445 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 17:08:23,447 INFO  task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1452791303088_0001_00_000001
2016-01-14 17:08:23,448 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_FINISHED to history file
2016-01-14 17:08:23,450 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791303088_0001_1][Event:VERTEX_FINISHED]: vertexName=D45A4D434A614EE3BDE8A46A1CA33180, vertexId=vertex_1452791303088_0001_1_00, initRequestedTime=1452791303309, initedTime=1452791303343, startRequestedTime=1452791303345, startedTime=1452791303345, finishTime=1452791303446, timeTaken=101, status=SUCCEEDED, diagnostics=, counters=Counters: 22, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=2174, FILE_BYTES_WRITTEN=152, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=295174144, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=10, cascading.flow.SliceCounters, Process_Begin_Time=1452791303425, Process_Duration=7, Process_End_Time=1452791303432, Read_Duration=3, Tuples_Read=10, Tuples_Written=10, Write_Duration=0, cascading.flow.StepCounters, Tuples_Read=10, Tuples_Written=10, vertexStats=firstTaskStartTime=1452791303364, firstTasksToStart=[ task_1452791303088_0001_1_00_000000 ], lastTaskFinishTime=1452791303435, lastTasksToFinish=[ task_1452791303088_0001_1_00_000000 ], minTaskDuration=71, maxTaskDuration=71, avgTaskDuration=71.0, numSuccessfulTasks=1, shortestDurationTasks=[ task_1452791303088_0001_1_00_000000 ], longestDurationTasks=[ task_1452791303088_0001_1_00_000000 ], vertexTaskStats={numFailedTasks=0, numSucceededTasks=1, numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0, numCompletedTasks=1}
2016-01-14 17:08:23,451 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452791303088_0001_1_00 [D45A4D434A614EE3BDE8A46A1CA33180] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2016-01-14 17:08:23,452 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791303088_0001_00_000001 transitioned from RUNNING to IDLE via event C_TA_SUCCEEDED
2016-01-14 17:08:23,454 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_STOPPED to history file
2016-01-14 17:08:23,454 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791303088_0001_1][Event:CONTAINER_STOPPED]: containerId=container_1452791303088_0001_00_000001, stoppedTime=1452791303454, exitStatus=0
2016-01-14 17:08:23,455 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791303088_0001_00_000001 transitioned from IDLE to STOP_REQUESTED via event C_STOP_REQUEST
2016-01-14 17:08:23,456 INFO  impl.DAGImpl (DAGImpl.java:transition(1747)) - Vertex vertex_1452791303088_0001_1_00 [D45A4D434A614EE3BDE8A46A1CA33180] completed., numCompletedVertices=1, numSuccessfulVertices=1, numFailedVertices=0, numKilledVertices=0, numVertices=1
2016-01-14 17:08:23,456 INFO  impl.DAGImpl (DAGImpl.java:commitOrAbortOutputs(831)) - Calling DAG commit/abort for dag: dag_1452791303088_0001_1
2016-01-14 17:08:23,457 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791303088_0001_1][Event:DAG_COMMIT_STARTED]: dagID=dag_1452791303088_0001_1
2016-01-14 17:08:23,457 INFO  impl.DAGImpl (DAGImpl.java:commitOrAbortOutputs(892)) - Committing output: 7FD5AE420D364A58BB8BD562A086D0DE for vertex: vertex_1452791303088_0001_1_00 [D45A4D434A614EE3BDE8A46A1CA33180]
2016-01-14 17:08:23,458 INFO  app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(213)) - Container with id: container_1452791303088_0001_00_000001 is valid, but no longer registered, and will be killed
2016-01-14 17:08:23,458 INFO  task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1452791303088_0001_00_000001: 11 ms after starting to poll. TaskInfo: shouldDie: true
2016-01-14 17:08:23,459 INFO  task.TezChild (TezChild.java:run(207)) - ContainerTask returned shouldDie=true for container container_1452791303088_0001_00_000001, Exiting
2016-01-14 17:08:23,459 INFO  task.TezChild (TezChild.java:shutdown(343)) - Shutdown invoked for container container_1452791303088_0001_00_000001
2016-01-14 17:08:23,459 INFO  task.TezChild (TezChild.java:shutdown(345)) - Shutting down container container_1452791303088_0001_00_000001
2016-01-14 17:08:23,462 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(270)) - ContainerExecutionResult for: container_1452791303088_0001_00_000001 = ContainerExecutionResult{exitStatus=SUCCESS, throwable=null, errorMessage='Asked to die by the AM'}
2016-01-14 17:08:23,462 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(274)) - Container: container_1452791303088_0001_00_000001 completed successfully
2016-01-14 17:08:23,473 INFO  recovery.RecoveryService (RecoveryService.java:handle(306)) - DAG completed, dagId=dag_1452791303088_0001_1, queueSize=0
2016-01-14 17:08:23,473 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_FINISHED to history file
2016-01-14 17:08:23,475 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791303088_0001_1][Event:DAG_FINISHED]: dagId=dag_1452791303088_0001_1, startTime=1452791303308, finishTime=1452791303471, timeTaken=163, status=SUCCEEDED, diagnostics=, counters=Counters: 24, org.apache.tez.common.counters.DAGCounter, NUM_SUCCEEDED_TASKS=1, TOTAL_LAUNCHED_TASKS=1, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=2174, FILE_BYTES_WRITTEN=152, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=295174144, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=10, cascading.flow.SliceCounters, Process_Begin_Time=1452791303425, Process_Duration=7, Process_End_Time=1452791303432, Read_Duration=3, Tuples_Read=10, Tuples_Written=10, Write_Duration=0, cascading.flow.StepCounters, Tuples_Read=10, Tuples_Written=10
2016-01-14 17:08:23,475 INFO  impl.DAGImpl (DAGImpl.java:finished(1180)) - DAG: dag_1452791303088_0001_1 finished with state: SUCCEEDED
2016-01-14 17:08:23,476 INFO  impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1452791303088_0001_1 transitioned from RUNNING to SUCCEEDED due to event DAG_VERTEX_COMPLETED
2016-01-14 17:08:23,476 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791303088_0001_00_000001 transitioned from STOP_REQUESTED to COMPLETED via event C_COMPLETED
2016-01-14 17:08:23,478 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:stop(242)) - Ignoring stop request for containerId: container_1452791303088_0001_00_000001
2016-01-14 17:08:23 Completed Dag: dag_1452791303088_0001_1
2016-01-14 17:08:23,479 INFO  app.DAGAppMaster (DAGAppMaster.java:handle(579)) - DAG completed, dagId=dag_1452791303088_0001_1, dagState=SUCCEEDED
2016-01-14 17:08:23,479 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: dag_1452791303088_0001_1_post
2016-01-14 17:08:23,479 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 17:08:23,479 INFO  app.DAGAppMaster (DAGAppMaster.java:handle(625)) - Waiting for next DAG to be submitted.
2016-01-14 17:08:23,484 INFO  client.TezClient (TezClient.java:stop(495)) - Shutting down Tez Session, sessionName=(1/1) ...stSkipStrategiesKeep/keep, applicationId=application_1452791303088_0001
2016-01-14 17:08:23,486 INFO  client.DAGClientHandler (DAGClientHandler.java:shutdownAM(117)) - Received message to shutdown AM
2016-01-14 17:08:23,486 INFO  rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:setShouldUnregisterFlag(580)) - TaskScheduler notified that it should unregister from RM
2016-01-14 17:08:23,487 INFO  app.DAGAppMaster (DAGAppMaster.java:shutdownTezAM(1088)) - No current running DAG, shutting down the AM
2016-01-14 17:08:23,487 INFO  app.DAGAppMaster (DAGAppMaster.java:shutdown(692)) - DAGAppMasterShutdownHandler invoked
2016-01-14 17:08:23,487 INFO  app.DAGAppMaster (DAGAppMaster.java:shutdown(701)) - Handling DAGAppMaster shutdown
2016-01-14 17:08:23,487 INFO  app.DAGAppMaster (DAGAppMaster.java:run(721)) - Sleeping for 5 seconds before shutting down
2016-01-14 17:08:23,487 INFO  history.HistoryEventHandler (HistoryEventHandler.java:serviceStop(79)) - Stopping HistoryEventHandler
2016-01-14 17:08:23,488 INFO  recovery.RecoveryService (RecoveryService.java:serviceStop(189)) - Stopping RecoveryService
2016-01-14 17:08:23,488 INFO  recovery.RecoveryService (RecoveryService.java:serviceStop(192)) - Handle the remaining events in queue, queue size=0
2016-01-14 17:08:23,488 INFO  recovery.RecoveryService (RecoveryService.java:run(166)) - EventQueue take interrupted. Returning
2016-01-14 17:08:23,489 INFO  recovery.RecoveryService (RecoveryService.java:serviceStop(214)) - Closing Summary Stream
2016-01-14 17:08:23,489 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStop(118)) - Stopping SimpleHistoryLoggingService, eventQueueBacklog=0
2016-01-14 17:08:23,489 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:run(105)) - EventQueue take interrupted. Returning
2016-01-14 17:08:23,494 INFO  app.DAGAppMaster (DAGAppMaster.java:run(1773)) - Completed deletion of tez scratch data dir, path=file:/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/DC3C38CB5A2B4257A57B68E50C589500/D0404757EABE4E1897C617AF30BF8AA4/.tez/application_1452791303088_0001
2016-01-14 17:08:23,496 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test]  completed in: 00:00.436
2016-01-14 17:08:23,499 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test] sink oldest modified date: Thu Jan 14 17:08:23 UTC 2016
2016-01-14 17:08:23,503 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test] source modification date at: Thu Jan 14 16:15:35 UTC 2016
2016-01-14 17:08:23,506 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test] sink oldest modified date: Thu Jan 14 17:08:23 UTC 2016
2016-01-14 17:08:23,613 INFO  cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/output//hadoop2-tez/flowstrategiesplatform/testSkipStrategiesKeep/keep
2016-01-14 17:08:23,664 INFO  util.Util (Util.java:findMainClass(1327)) - using default application jar, may cause class not found exceptions on the cluster
2016-01-14 17:08:23,664 INFO  planner.Hadoop2TezPlanner (Hadoop2TezPlanner.java:initialize(149)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-tez/3.0.4/561447ee876073bb61fddc52e2ad157f45c8edd/cascading-hadoop2-tez-3.0.4.jar
2016-01-14 17:08:23,776 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.042
2016-01-14 17:08:23,796 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.060
2016-01-14 17:08:23,798 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test] rule registry: NoHashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 2
2016-01-14 17:08:23,798 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test] rule registry: HashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 2
2016-01-14 17:08:23,799 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test] rule registry: NoHashJoinHadoop2TezRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-01-14 17:08:23,822 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/classes/test/data/apache.10.txt
2016-01-14 17:08:23,846 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/output/hadoop2-tez/flowstrategiesplatform/testFlowStepStrategy/simple
2016-01-14 17:08:23,933 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test] starting
2016-01-14 17:08:23,933 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test]  source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/classes/test/data/apache.10.txt"]
2016-01-14 17:08:23,934 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test]  sink: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/output/hadoop2-tez/flowstrategiesplatform/testFlowStepStrategy/simple"]
2016-01-14 17:08:23,934 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test]  parallel execution of steps is enabled: false
2016-01-14 17:08:23,935 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test]  executing total steps: 1
2016-01-14 17:08:23,935 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test]  allocating management threads: 1
2016-01-14 17:08:23,937 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test] starting step: (1/1) ...stFlowStepStrategy/simple
2016-01-14 17:08:23,938 WARN  flow.Flow (BaseFlow.java:logWarn(1445)) - [test] 'yarn.timeline-service.enabled' is disabled, please enable to capture detailed metrics of completed flows, this may require starting the YARN timeline server daemon
2016-01-14 17:08:23,956 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test] tez session mode enabled: true
2016-01-14 17:08:23,962 INFO  client.TezClient (TezClient.java:<init>(153)) - Tez Client Version: [ component=tez-api, version=0.6.2, revision=c04283bf91fd96823eec37056d5c8b1a92728265, SCM-URL=scm:git:https://git-wip-us.apache.org/repos/asf/tez.git, buildTime=20150804-1436 ]
2016-01-14 17:08:23,962 INFO  client.TezClient (TezClient.java:start(333)) - Session mode. Starting session.
2016-01-14 17:08:23,962 INFO  client.TezClientUtils (TezClientUtils.java:setupTezJarsLocalResources(159)) - Ignoring 'tez.lib.uris' since  'tez.ignore.lib.uris' is set to true
2016-01-14 17:08:23,972 INFO  client.TezClient (TezCommonUtils.java:createTezSystemStagingPath(118)) - Tez system stage directory file:/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/3FF5F23BC43146E0984CE9835D6621EC/F0F48D52C0C74352AFD1058514FCC56B/.tez/application_1452791303962_0001 doesn't exist and is created
2016-01-14 17:08:23,992 INFO  client.LocalClient (LocalClient.java:createDAGAppMaster(328)) - DAGAppMaster thread has been created
2016-01-14 17:08:23,992 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-01-14 17:08:23,993 INFO  client.LocalClient (LocalClient.java:run(275)) - Using staging directory: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/3FF5F23BC43146E0984CE9835D6621EC/F0F48D52C0C74352AFD1058514FCC56B/.tez/application_1452791303962_0001
2016-01-14 17:08:23,997 INFO  app.DAGAppMaster (DAGAppMaster.java:<init>(309)) - Created DAGAppMaster for application appattempt_1452791303962_0001_000000, versionInfo=[ component=tez-dag, version=0.6.2, revision=c04283bf91fd96823eec37056d5c8b1a92728265, SCM-URL=scm:git:https://git-wip-us.apache.org/repos/asf/tez.git, buildTime=20150804-1436 ]
2016-01-14 17:08:24,014 INFO  app.DAGAppMaster (DAGAppMaster.java:serviceInit(333)) - Comparing client version with AM version, clientVersion=0.6.2, AMVersion=0.6.2
2016-01-14 17:08:24,016 INFO  app.DAGAppMaster (DAGAppMaster.java:serviceInit(386)) - Adding session token to jobTokenSecretManager for application
2016-01-14 17:08:24,018 INFO  node.AMNodeTracker (AMNodeTracker.java:serviceInit(77)) - blacklistDisablePercent is 33, blacklistingEnabled: false, maxTaskFailuresPerNode: 1
2016-01-14 17:08:24,019 INFO  history.HistoryEventHandler (HistoryEventHandler.java:serviceInit(50)) - Initializing HistoryEventHandler
2016-01-14 17:08:24,019 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceInit(66)) - Log file location for SimpleHistoryLoggingService not specified, defaulting to containerLogDir=/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/3FF5F23BC43146E0984CE9835D6621EC/F0F48D52C0C74352AFD1058514FCC56B/.tez/application_1452791303962_0001/localmode-log-dir
2016-01-14 17:08:24,020 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceInit(88)) - Initializing SimpleHistoryLoggingService, logFileLocation=/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/3FF5F23BC43146E0984CE9835D6621EC/F0F48D52C0C74352AFD1058514FCC56B/.tez/application_1452791303962_0001/localmode-log-dir/history.txt.appattempt_1452791303962_0001_000000, maxErrors=10
2016-01-14 17:08:24,020 INFO  recovery.RecoveryService (RecoveryService.java:serviceInit(109)) - Initializing RecoveryService
2016-01-14 17:08:24,021 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:N/A][Event:AM_LAUNCHED]: appAttemptId=appattempt_1452791303962_0001_000000, appSubmitTime=1452791303997, launchTime=1452791303997
2016-01-14 17:08:24,031 INFO  history.HistoryEventHandler (HistoryEventHandler.java:serviceStart(73)) - Starting HistoryEventHandler
2016-01-14 17:08:24,034 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStart(95)) - Starting SimpleHistoryLoggingService
2016-01-14 17:08:24,035 INFO  client.DAGClientServer (DAGClientServer.java:serviceStart(91)) - Instantiated DAGClientRPCServer at ip-10-187-41-40.ec2.internal/10.187.41.40:39182
2016-01-14 17:08:24,037 INFO  recovery.RecoveryService (RecoveryService.java:serviceStart(127)) - Starting RecoveryService
2016-01-14 17:08:24,038 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event AM_LAUNCHED to history file
2016-01-14 17:08:24,039 WARN  impl.MetricsConfig (MetricsConfig.java:loadFirst(124)) - Cannot locate configuration: tried hadoop-metrics2-dagappmaster.properties,hadoop-metrics2.properties
2016-01-14 17:08:24,043 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event AM_STARTED to history file
2016-01-14 17:08:24,043 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:N/A][Event:AM_STARTED]: appAttemptId=appattempt_1452791303962_0001_000000, startTime=1452791304043
2016-01-14 17:08:24,044 INFO  app.DAGAppMaster (DAGAppMaster.java:serviceStart(1644)) - In Session mode. Waiting for DAG over RPC
2016-01-14 17:08:24,093 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: IDLE
2016-01-14 17:08:24,093 INFO  client.TezClient (TezClient.java:start(367)) - The url to track the Tez Session: N/A
2016-01-14 17:08:24,093 INFO  client.TezClient (TezClient.java:submitDAGSession(405)) - Submitting dag to TezSession, sessionName=(1/1) ...stFlowStepStrategy/simple, applicationId=application_1452791303962_0001, dagName=[3FF5F23BC43146E0984CE9835D6621EC/F0F48D52C0C74352AFD1058514FCC56B] test/(1/1) ...stFlowStepStrategy/simple
2016-01-14 17:08:24,115 INFO  app.DAGAppMaster (DAGAppMaster.java:submitDAGToAppMaster(1126)) - Starting DAG submitted via RPC: [3FF5F23BC43146E0984CE9835D6621EC/F0F48D52C0C74352AFD1058514FCC56B] test/(1/1) ...stFlowStepStrategy/simple
2016-01-14 17:08:24,117 INFO  app.DAGAppMaster (DAGAppMaster.java:generateDAGVizFile(870)) - Generating DAG graphviz file, dagId=dag_1452791303962_0001_1, filePath=/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/3FF5F23BC43146E0984CE9835D6621EC/F0F48D52C0C74352AFD1058514FCC56B/.tez/application_1452791303962_0001/localmode-log-dir/dag_1452791303962_0001_1.dot
2016-01-14 17:08:24,118 INFO  app.DAGAppMaster (DAGAppMaster.java:writePBTextFile(887)) - Writing DAG plan to: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/3FF5F23BC43146E0984CE9835D6621EC/F0F48D52C0C74352AFD1058514FCC56B/.tez/application_1452791303962_0001/localmode-log-dir/dag_1452791303962_0001_1-tez-dag.pb.txt
2016-01-14 17:08:24,147 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: dag_1452791303962_0001_1
2016-01-14 17:08:24,147 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 17:08:24,147 INFO  app.DAGAppMaster (DAGAppMaster.java:startDAG(2051)) - Running DAG: [3FF5F23BC43146E0984CE9835D6621EC/F0F48D52C0C74352AFD1058514FCC56B] test/(1/1) ...stFlowStepStrategy/simple
2016-01-14 17:08:24 Running Dag: dag_1452791303962_0001_1
2016-01-14 17:08:24,166 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791303962_0001_1][Event:DAG_SUBMITTED]: dagID=dag_1452791303962_0001_1, submitTime=1452791304115
2016-01-14 17:08:24,166 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_SUBMITTED to history file
2016-01-14 17:08:24,167 INFO  impl.VertexImpl (VertexImpl.java:setAdditionalOutputs(4033)) - setting additional outputs for vertex B3E81D26ECA145F880D0FDBEB399F97B
2016-01-14 17:08:24,172 INFO  impl.DAGImpl (DAGImpl.java:assignDAGScheduler(1381)) - Using DAG Scheduler: org.apache.tez.dag.app.dag.impl.DAGSchedulerNaturalOrderControlled
2016-01-14 17:08:24,173 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791303962_0001_1][Event:DAG_INITIALIZED]: dagID=dag_1452791303962_0001_1, initTime=1452791304166
2016-01-14 17:08:24,173 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_INITIALIZED to history file
2016-01-14 17:08:24,174 INFO  impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1452791303962_0001_1 transitioned from NEW to INITED due to event DAG_INIT
2016-01-14 17:08:24,175 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791303962_0001_1][Event:DAG_STARTED]: dagID=dag_1452791303962_0001_1, startTime=1452791304175
2016-01-14 17:08:24,175 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_STARTED to history file
2016-01-14 17:08:24,175 INFO  impl.DAGImpl (DAGImpl.java:transition(1614)) - Added additional resources : [[]] to classpath
2016-01-14 17:08:24,176 INFO  impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1452791303962_0001_1 transitioned from INITED to RUNNING due to event DAG_START
2016-01-14 17:08:24,176 INFO  impl.VertexImpl (VertexImpl.java:setupVertex(2068)) - Root Inputs exist for Vertex: ECD480AA034C4CD2B200E09E382C9072 : {0155163657B84D39856AE77E83F9EC42={InputName=0155163657B84D39856AE77E83F9EC42}, {Descriptor=ClassName=org.apache.tez.mapreduce.input.MRInput, hasPayload=true}, {ControllerDescriptor=ClassName=org.apache.tez.mapreduce.common.MRInputAMSplitGenerator, hasPayload=false}}
2016-01-14 17:08:24,176 INFO  impl.VertexImpl (VertexImpl.java:setupVertex(2078)) - Starting root input initializer for input: 0155163657B84D39856AE77E83F9EC42, with class: [org.apache.tez.mapreduce.common.MRInputAMSplitGenerator]
2016-01-14 17:08:24,176 INFO  impl.VertexImpl (VertexImpl.java:assignVertexManager(2191)) - Setting vertexManager to RootInputVertexManager for vertex_1452791303962_0001_1_00 [ECD480AA034C4CD2B200E09E382C9072]
2016-01-14 17:08:24,176 INFO  impl.VertexImpl (VertexImpl.java:handleInitEvent(2983)) - Num tasks is -1. Expecting VertexManager/InputInitializers/1-1 split to set #tasks for the vertex vertex_1452791303962_0001_1_00 [ECD480AA034C4CD2B200E09E382C9072]
2016-01-14 17:08:24,176 INFO  impl.VertexImpl (VertexImpl.java:handleInitEvent(2987)) - Vertex will initialize from input initializer. vertex_1452791303962_0001_1_00 [ECD480AA034C4CD2B200E09E382C9072]
2016-01-14 17:08:24,177 INFO  impl.VertexImpl (VertexImpl.java:setupInputInitializerManager(3933)) - Vertex will initialize via inputInitializers vertex_1452791303962_0001_1_00 [ECD480AA034C4CD2B200E09E382C9072]. Starting root input initializers: 1
2016-01-14 17:08:24,179 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452791303962_0001_1_00 [ECD480AA034C4CD2B200E09E382C9072] transitioned from NEW to INITIALIZING due to event V_INIT
2016-01-14 17:08:24,179 INFO  dag.RootInputInitializerManager (RootInputInitializerManager.java:run(242)) - Starting InputInitializer for Input: 0155163657B84D39856AE77E83F9EC42 on vertex vertex_1452791303962_0001_1_00 [ECD480AA034C4CD2B200E09E382C9072]
2016-01-14 17:08:24,179 INFO  client.TezClient (TezClient.java:submitDAGSession(478)) - Submitted dag to TezSession, sessionName=(1/1) ...stFlowStepStrategy/simple, applicationId=application_1452791303962_0001, dagName=[3FF5F23BC43146E0984CE9835D6621EC/F0F48D52C0C74352AFD1058514FCC56B] test/(1/1) ...stFlowStepStrategy/simple
2016-01-14 17:08:24,179 INFO  impl.VertexImpl (VertexImpl.java:assignVertexManager(2203)) - Setting vertexManager to ShuffleVertexManager for vertex_1452791303962_0001_1_01 [B3E81D26ECA145F880D0FDBEB399F97B]
2016-01-14 17:08:24,181 INFO  common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(92)) - Emitting serialized splits: true
2016-01-14 17:08:24,181 INFO  common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(110)) - Input 0155163657B84D39856AE77E83F9EC42 asking for 1 tasks. Headroom: 672 Task Resource: 1024 waves: 1.7
2016-01-14 17:08:24,184 INFO  common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(121)) - Grouping input splits
2016-01-14 17:08:24,184 INFO  hadoop.MRInputHelpers (MRInputHelpers.java:generateInputSplitsToMem(294)) - Generating mapred api input splits
2016-01-14 17:08:24,187 INFO  hadoop.MRInputHelpers (MRInputHelpers.java:generateInputSplitsToMem(300)) - NumSplits: 1, SerializedSize: 408
2016-01-14 17:08:24,187 INFO  dag.RootInputInitializerManager (RootInputInitializerManager.java:onSuccess(272)) - Succeeded InputInitializer for Input: 0155163657B84D39856AE77E83F9EC42 on vertex vertex_1452791303962_0001_1_00 [ECD480AA034C4CD2B200E09E382C9072]
2016-01-14 17:08:24,188 INFO  vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:initialize(696)) - Shuffle Vertex Manager: settings minFrac:0.25 maxFrac:0.75 auto:false desiredTaskIput:104857600 minTasks:1
2016-01-14 17:08:24,189 INFO  impl.VertexImpl (VertexImpl.java:handleInitEvent(3014)) - Creating 1 tasks for vertex: vertex_1452791303962_0001_1_01 [B3E81D26ECA145F880D0FDBEB399F97B]
2016-01-14 17:08:24,189 INFO  impl.VertexImpl (VertexImpl.java:handleInitEvent(3026)) - Directly initializing vertex: vertex_1452791303962_0001_1_01 [B3E81D26ECA145F880D0FDBEB399F97B]
2016-01-14 17:08:24,190 INFO  impl.VertexImpl (VertexImpl.java:initializeCommitters(1915)) - Invoking committer inits for vertex, vertexId=vertex_1452791303962_0001_1_01 [B3E81D26ECA145F880D0FDBEB399F97B]
2016-01-14 17:08:24,190 INFO  impl.VertexImpl (VertexImpl.java:initializeCommitters(1927)) - Instantiating committer for output=E46656297BDC43819B606E5CABE51C22, vertexId=vertex_1452791303962_0001_1_01 [B3E81D26ECA145F880D0FDBEB399F97B], committerClass=org.apache.tez.mapreduce.committer.MROutputCommitter
2016-01-14 17:08:24,190 INFO  impl.VertexImpl (VertexImpl.java:run(1945)) - Invoking committer init for output=E46656297BDC43819B606E5CABE51C22, vertexId=vertex_1452791303962_0001_1_01 [B3E81D26ECA145F880D0FDBEB399F97B]
2016-01-14 17:08:24,193 INFO  committer.MROutputCommitter (MROutputCommitter.java:getOutputCommitter(145)) - OutputCommitter for outputName=E46656297BDC43819B606E5CABE51C22, vertexName=B3E81D26ECA145F880D0FDBEB399F97B, outputCommitterClass=org.apache.hadoop.mapred.FileOutputCommitter
2016-01-14 17:08:24,193 INFO  impl.VertexImpl (VertexImpl.java:run(1949)) - Invoking committer setup for output=E46656297BDC43819B606E5CABE51C22, vertexId=vertex_1452791303962_0001_1_01 [B3E81D26ECA145F880D0FDBEB399F97B]
2016-01-14 17:08:24,196 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_INITIALIZED to history file
2016-01-14 17:08:24,199 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791303962_0001_1][Event:VERTEX_INITIALIZED]: vertexName=B3E81D26ECA145F880D0FDBEB399F97B, vertexId=vertex_1452791303962_0001_1_01, initRequestedTime=1452791304179, initedTime=1452791304196, numTasks=1, processorName=cascading.flow.tez.FlowProcessor, additionalInputsCount=0
2016-01-14 17:08:24,199 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452791303962_0001_1_01 [B3E81D26ECA145F880D0FDBEB399F97B] transitioned from NEW to INITED due to event V_INIT
2016-01-14 17:08:24,200 INFO  impl.VertexImpl (VertexImpl.java:canInitVertex(3195)) - Cannot init vertex: vertex_1452791303962_0001_1_00 [ECD480AA034C4CD2B200E09E382C9072] numTasks: -1 numUnitializedEdges: 0 numInitializedInputs: 0 initWaitsForRootInitializers: true
2016-01-14 17:08:24,201 INFO  impl.VertexImpl (VertexImpl.java:setParallelism(1374)) - Got updated RootInputsSpecs: {0155163657B84D39856AE77E83F9EC42=forAllWorkUnits=true, update=[1]}
2016-01-14 17:08:24,201 INFO  impl.VertexImpl (VertexImpl.java:setParallelism(1393)) - Vertex vertex_1452791303962_0001_1_00 [ECD480AA034C4CD2B200E09E382C9072] parallelism set to 1
2016-01-14 17:08:24,202 INFO  impl.VertexImpl (VertexImpl.java:canInitVertex(3195)) - Cannot init vertex: vertex_1452791303962_0001_1_00 [ECD480AA034C4CD2B200E09E382C9072] numTasks: 1 numUnitializedEdges: 0 numInitializedInputs: 0 initWaitsForRootInitializers: true
2016-01-14 17:08:24,203 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test] submitted tez dag to app master: application_1452791303962_0001, with dag id: dag_1452791303962_0001_1
2016-01-14 17:08:24,203 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791303962_0001_1][Event:VERTEX_DATA_MOVEMENT_EVENTS_GENERATED]: vertexId=vertex_1452791303962_0001_1_00, eventCount=1
2016-01-14 17:08:24,206 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_INITIALIZED to history file
2016-01-14 17:08:24,206 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791303962_0001_1][Event:VERTEX_INITIALIZED]: vertexName=ECD480AA034C4CD2B200E09E382C9072, vertexId=vertex_1452791303962_0001_1_00, initRequestedTime=1452791304176, initedTime=1452791304205, numTasks=1, processorName=cascading.flow.tez.FlowProcessor, additionalInputsCount=1
2016-01-14 17:08:24,206 INFO  impl.VertexImpl (VertexImpl.java:startIfPossible(3061)) - Triggering start event for vertex: vertex_1452791303962_0001_1_00 [ECD480AA034C4CD2B200E09E382C9072] with distanceFromRoot: 0
2016-01-14 17:08:24,207 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452791303962_0001_1_00 [ECD480AA034C4CD2B200E09E382C9072] transitioned from INITIALIZING to INITED due to event V_ROOT_INPUT_INITIALIZED
2016-01-14 17:08:24,208 INFO  impl.ImmediateStartVertexManager (ImmediateStartVertexManager.java:scheduleTasks(99)) - Starting 1 in ECD480AA034C4CD2B200E09E382C9072
2016-01-14 17:08:24,208 INFO  impl.VertexImpl (VertexImpl.java:scheduleTasks(1250)) - Routing pending task events for vertex: vertex_1452791303962_0001_1_00 [ECD480AA034C4CD2B200E09E382C9072]
2016-01-14 17:08:24,212 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_STARTED to history file
2016-01-14 17:08:24,212 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791303962_0001_1][Event:VERTEX_STARTED]: vertexId=vertex_1452791303962_0001_1_00, startRequestedTime=1452791304208, startedTime=1452791304208
2016-01-14 17:08:24,213 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452791303962_0001_1_00 [ECD480AA034C4CD2B200E09E382C9072] transitioned from INITED to RUNNING due to event V_START
2016-01-14 17:08:24,220 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_STARTED to history file
2016-01-14 17:08:24,220 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791303962_0001_1][Event:TASK_STARTED]: vertexName=ECD480AA034C4CD2B200E09E382C9072, taskId=task_1452791303962_0001_1_00_000000, scheduledTime=1452791304217, launchTime=1452791304217
2016-01-14 17:08:24,220 INFO  impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452791303962_0001_1_00_000000 Task Transitioned from NEW to SCHEDULED due to event T_SCHEDULE
2016-01-14 17:08:24,220 INFO  impl.VertexImpl (VertexImpl.java:transition(3155)) - Source vertex started: vertex_1452791303962_0001_1_00 for vertex: vertex_1452791303962_0001_1_01 [B3E81D26ECA145F880D0FDBEB399F97B] numStartedSources: 1 numSources: 1
2016-01-14 17:08:24,221 INFO  impl.VertexImpl (VertexImpl.java:startIfPossible(3061)) - Triggering start event for vertex: vertex_1452791303962_0001_1_01 [B3E81D26ECA145F880D0FDBEB399F97B] with distanceFromRoot: 1
2016-01-14 17:08:24,221 INFO  impl.DAGSchedulerNaturalOrderControlled (DAGSchedulerNaturalOrderControlled.java:scheduleTask(111)) - Scheduled vertex: vertex_1452791303962_0001_1_00 [ECD480AA034C4CD2B200E09E382C9072]
2016-01-14 17:08:24,224 INFO  vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:handleVertexStateUpdate(720)) - Received configured notification : CONFIGURED for vertex: ECD480AA034C4CD2B200E09E382C9072 in vertex: B3E81D26ECA145F880D0FDBEB399F97B
2016-01-14 17:08:24,226 INFO  vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:onVertexStarted(355)) - OnVertexStarted vertex: B3E81D26ECA145F880D0FDBEB399F97B with 1 source tasks and 1 pending tasks
2016-01-14 17:08:24,226 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_STARTED to history file
2016-01-14 17:08:24,226 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791303962_0001_1][Event:VERTEX_STARTED]: vertexId=vertex_1452791303962_0001_1_01, startRequestedTime=1452791304222, startedTime=1452791304222
2016-01-14 17:08:24,227 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452791303962_0001_1_01 [B3E81D26ECA145F880D0FDBEB399F97B] transitioned from INITED to RUNNING due to event V_START
2016-01-14 17:08:24,228 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1014)) - remoteTaskSpec:DAGName : [3FF5F23BC43146E0984CE9835D6621EC/F0F48D52C0C74352AFD1058514FCC56B] test/(1/1) ...stFlowStepStrategy/simple, VertexName: ECD480AA034C4CD2B200E09E382C9072, VertexParallelism: 1, TaskAttemptID:attempt_1452791303962_0001_1_00_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=0155163657B84D39856AE77E83F9EC42, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=B3E81D26ECA145F880D0FDBEB399F97B, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }}, ]
2016-01-14 17:08:24,228 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452791303962_0001_1_00_000000_0 TaskAttempt Transitioned from NEW to START_WAIT due to event TA_SCHEDULE
2016-01-14 17:08:24,229 INFO  rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_LAUNCH_REQUEST
2016-01-14 17:08:24,230 INFO  node.AMNodeTracker (AMNodeTracker.java:nodeSeen(91)) - Adding new node: 127.0.0.1:0
2016-01-14 17:08:24,230 INFO  container.AMContainerHelpers (AMContainerHelpers.java:createCommonContainerLaunchContext(112)) - Adding #1 tokens and #0 secret keys for NM use for launching container
2016-01-14 17:08:24,231 INFO  container.AMContainerHelpers (AMContainerHelpers.java:createCommonContainerLaunchContext(122)) - Putting shuffle token in serviceData
2016-01-14 17:08:24,231 INFO  container.AMContainerImpl (AMContainerImpl.java:transition(521)) - Sending Launch Request for Container with id: container_1452791303962_0001_00_000001
2016-01-14 17:08:24,232 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791303962_0001_00_000001 transitioned from ALLOCATED to LAUNCHING via event C_LAUNCH_REQUEST
2016-01-14 17:08:24,234 INFO  task.TezChild (TezChild.java:newTezChild(432)) - PID, containerIdentifier:  null, container_1452791303962_0001_00_000001
2016-01-14 17:08:24,234 WARN  impl.MetricsSystemImpl (MetricsSystemImpl.java:init(145)) - DAGAppMaster metrics system already initialized!
2016-01-14 17:08:24,235 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791303962_0001_00_000001 transitioned from LAUNCHING to IDLE via event C_LAUNCHED
2016-01-14 17:08:24,235 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791303962_0001_1][Event:CONTAINER_LAUNCHED]: containerId=container_1452791303962_0001_00_000001, launchTime=1452791304235
2016-01-14 17:08:24,235 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_LAUNCHED to history file
2016-01-14 17:08:24,236 INFO  task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1452791303962_0001_00_000001
2016-01-14 17:08:24,237 INFO  container.AMContainerImpl (AMContainerImpl.java:transition(827)) - Assigned taskAttempt + [attempt_1452791303962_0001_1_00_000000_0] to container: [container_1452791303962_0001_00_000001]
2016-01-14 17:08:24,237 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791303962_0001_00_000001 transitioned from IDLE to RUNNING via event C_PULL_TA
2016-01-14 17:08:24,238 INFO  app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(240)) - Container with id: container_1452791303962_0001_00_000001 given task: attempt_1452791303962_0001_1_00_000000_0
2016-01-14 17:08:24,238 INFO  task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1452791303962_0001_00_000001: 0 ms after starting to poll. TaskInfo: shouldDie: false, currentTaskAttemptId: attempt_1452791303962_0001_1_00_000000_0
2016-01-14 17:08:24,238 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1146)) - TaskAttempt: [attempt_1452791303962_0001_1_00_000000_0] started. Is using containerId: [container_1452791303962_0001_00_000001] on NM: [127.0.0.1:0]
2016-01-14 17:08:24,239 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_STARTED to history file
2016-01-14 17:08:24,239 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791303962_0001_1][Event:TASK_ATTEMPT_STARTED]: vertexName=ECD480AA034C4CD2B200E09E382C9072, taskAttemptId=attempt_1452791303962_0001_1_00_000000_0, startTime=1452791304238, containerId=container_1452791303962_0001_00_000001, nodeId=127.0.0.1:0, inProgressLogs=127.0.0.1:0/node/containerlogs/container_1452791303962_0001_00_000001/teamcity, completedLogs=
2016-01-14 17:08:24 Starting to run new task attempt: attempt_1452791303962_0001_1_00_000000_0
2016-01-14 17:08:24,240 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452791303962_0001_1_00_000000_0 TaskAttempt Transitioned from START_WAIT to RUNNING due to event TA_STARTED_REMOTELY
2016-01-14 17:08:24,240 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: attempt_1452791303962_0001_1_00_000000_0
2016-01-14 17:08:24,240 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 17:08:24,240 INFO  impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452791303962_0001_1_00_000000 Task Transitioned from SCHEDULED to RUNNING due to event T_ATTEMPT_LAUNCHED
2016-01-14 17:08:24,240 INFO  task.TezChild (TezChild.java:handleNewTaskCredentials(273)) - Refreshing UGI since Credentials have changed
2016-01-14 17:08:24,240 INFO  task.TezChild (TezChild.java:handleNewTaskCredentials(276)) - Credentials : #Tokens=1, #SecretKeys=0
2016-01-14 17:08:24,240 INFO  task.TezChild (TezChild.java:handleNewTaskLocalResources(302)) - Localizing additional local resources for Task : {}
2016-01-14 17:08:24,241 INFO  task.TezChild (TezChild.java:handleNewTaskLocalResources(312)) - Done localizing additional resources
2016-01-14 17:08:24,241 INFO  metrics.TaskCounterUpdater (TaskCounterUpdater.java:initResourceCalculatorPlugin(148)) -  Using ResourceCalculatorProcessTree : [ ]
2016-01-14 17:08:24,241 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:<init>(149)) - Initializing LogicalIOProcessorRuntimeTask with TaskSpec: DAGName : [3FF5F23BC43146E0984CE9835D6621EC/F0F48D52C0C74352AFD1058514FCC56B] test/(1/1) ...stFlowStepStrategy/simple, VertexName: ECD480AA034C4CD2B200E09E382C9072, VertexParallelism: 1, TaskAttemptID:attempt_1452791303962_0001_1_00_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=0155163657B84D39856AE77E83F9EC42, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=B3E81D26ECA145F880D0FDBEB399F97B, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }}, ]
2016-01-14 17:08:24,241 INFO  resources.MemoryDistributor (MemoryDistributor.java:<init>(85)) - InitialMemoryDistributor (isEnabled=true) invoked with: numInputs=1, numOutputs=1, JVM.maxFree=704643072
2016-01-14 17:08:24,244 INFO  task.TezTaskRunner (TezTaskRunner.java:run(172)) - Initializing task, taskAttemptId=attempt_1452791303962_0001_1_00_000000_0
2016-01-14 17:08:24,244 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(191)) - Initializing LogicalProcessorIORuntimeTask
2016-01-14 17:08:24,245 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(195)) - Creating processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 17:08:24,247 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(488)) - Initializing processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 17:08:24,247 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(438)) - Initializing Output using OutputSpec: { destinationVertexName=B3E81D26ECA145F880D0FDBEB399F97B, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }
2016-01-14 17:08:24,248 INFO  impl.TaskImpl (TaskImpl.java:getTaskAttemptTezEvents(481)) - TaskAttempt:attempt_1452791303962_0001_1_00_000000_0 sent events: (0-1)
2016-01-14 17:08:24,249 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(389)) - Initializing Input using InputSpec: { sourceVertexName=0155163657B84D39856AE77E83F9EC42, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }
2016-01-14 17:08:24,249 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createInput(537)) - Creating Input
2016-01-14 17:08:24,250 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(397)) - Initializing Input with src edge: 0155163657B84D39856AE77E83F9EC42
2016-01-14 17:08:24,250 INFO  resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 0, type: INPUT, componentVertexName: 0155163657B84D39856AE77E83F9EC42
2016-01-14 17:08:24,251 INFO  tez.FlowProcessor (FlowProcessor.java:initialize(88)) - cascading version: 3.0.4
2016-01-14 17:08:24,254 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createOutput(565)) - Creating Output
2016-01-14 17:08:24,255 INFO  input.MRInput (MRInput.java:initialize(440)) - Using New mapreduce API: false, split information via event: true
2016-01-14 17:08:24,255 INFO  input.MRInput (MRInput.java:initializeInternal(493)) - Initialzed MRInput: 0155163657B84D39856AE77E83F9EC42
2016-01-14 17:08:24,256 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(403)) - Initialized Input with src edge: 0155163657B84D39856AE77E83F9EC42
2016-01-14 17:08:24,261 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(446)) - Initializing Output with dest edge: B3E81D26ECA145F880D0FDBEB399F97B
2016-01-14 17:08:24,264 INFO  impl.ExternalSorter (ExternalSorter.java:getInitialMemoryRequirement(293)) - Requested SortBufferSize (tez.runtime.io.sort.mb): 100
2016-01-14 17:08:24,264 INFO  resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 104857600, type: OUTPUT, componentVertexName: B3E81D26ECA145F880D0FDBEB399F97B
2016-01-14 17:08:24,266 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(452)) - Initialized Output with dest edge: B3E81D26ECA145F880D0FDBEB399F97B
2016-01-14 17:08:24,268 INFO  tez.FlowProcessor (FlowProcessor.java:initialize(94)) - flow node id: ECD480AA034C4CD2B200E09E382C9072, ordinal: 0
2016-01-14 17:08:24,268 INFO  tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: ECD480AA034C4CD2B200E09E382C9072, mem on start (mb), free: 199, total: 281, max: 672
2016-01-14 17:08:24,268 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(491)) - Initialized processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 17:08:24,268 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 2 initializers to finish
2016-01-14 17:08:24,268 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 1 initializers to finish
2016-01-14 17:08:24,268 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(233)) - All initializers finished
2016-01-14 17:08:24,268 INFO  resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(124)) - Using Allocator class: org.apache.tez.runtime.library.resources.WeightedScalingMemoryDistributor
2016-01-14 17:08:24,269 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:getRequestTypeForClass(197)) - Falling back to RequestType.OTHER for class: org.apache.tez.mapreduce.input.MRInput
2016-01-14 17:08:24,269 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 1, for type: OTHER
2016-01-14 17:08:24,269 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 12, for type: SORTED_OUTPUT
2016-01-14 17:08:24,270 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:computeReservedFraction(262)) - InitialReservationFraction=0.3, AdditionalReservationFractionForIOs=0.03, finalReserveFractionUsed=0.32999999999999996
2016-01-14 17:08:24,270 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:assignMemory(126)) - Scaling Requests. NumRequests: 2, numScaledRequests: 13, TotalRequested: 104857600, TotalRequestedScaled: 9.679163076923077E7, TotalJVMHeap: 704643072, TotalAvailable: 472110858, TotalRequested/TotalJVMHeap:0.15
2016-01-14 17:08:24,271 INFO  resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: INPUT, 0155163657B84D39856AE77E83F9EC42, org.apache.tez.mapreduce.input.MRInput: requested=0, allocated=0
2016-01-14 17:08:24,272 INFO  resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: OUTPUT, B3E81D26ECA145F880D0FDBEB399F97B, org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput: requested=104857600, allocated=104857600
2016-01-14 17:08:24,273 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(255)) - Starting Inputs/Outputs
2016-01-14 17:08:24,274 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(268)) - Input: 0155163657B84D39856AE77E83F9EC42 being auto started by the framework. Subsequent instances will not be auto-started
2016-01-14 17:08:24,274 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(289)) - Num IOs determined for AutoStart: 1
2016-01-14 17:08:24,275 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(291)) - Waiting for 1 IOs to start
2016-01-14 17:08:24,274 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(419)) - Starting Input with src edge: 0155163657B84D39856AE77E83F9EC42
2016-01-14 17:08:24,276 INFO  input.MRInput (MRInput.java:start(450)) - MRInput setup to received events1
2016-01-14 17:08:24,276 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(421)) - Started Input with src edge: 0155163657B84D39856AE77E83F9EC42
2016-01-14 17:08:24,276 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(304)) - AutoStartComplete
2016-01-14 17:08:24,277 INFO  task.TezTaskRunner (TezTaskRunner.java:run(175)) - Running task, taskAttemptId=attempt_1452791303962_0001_1_00_000000_0
2016-01-14 17:08:24,277 INFO  input.MRInput (MRInput.java:initFromEventInternal(619)) - Initializing RecordReader from event
2016-01-14 17:08:24,278 INFO  input.MRInput (MRInput.java:initFromEventInternal(630)) - Split Details -> SplitClass: org.apache.hadoop.mapred.split.TezGroupedSplit, OldSplit: org.apache.hadoop.mapred.split.TezGroupedSplit@b042d00
2016-01-14 17:08:24,279 INFO  lib.MRReaderMapred (MRReaderMapred.java:setIncrementalConfigParams(163)) - Processing split: org.apache.hadoop.mapred.split.TezGroupedSplit@b042d00
2016-01-14 17:08:24,279 INFO  input.MRInput (MRInput.java:initFromEventInternal(634)) - Initialized RecordReader from event
2016-01-14 17:08:24,279 INFO  input.MRInput (MRInput.java:processSplitEvent(586)) - Notifying on RecordReader Initialized
2016-01-14 17:08:24,281 INFO  graph.Hadoop2TezStreamGraph (Hadoop2TezStreamGraph.java:buildGraph(151)) - using streamed source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/classes/test/data/apache.10.txt"]
2016-01-14 17:08:24,291 INFO  tez.FlowProcessor (FlowProcessor.java:run(121)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/classes/test/data/apache.10.txt"] streamed: true, id: 0155163657B84D39856AE77E83F9EC42
2016-01-14 17:08:24,291 INFO  tez.FlowProcessor (FlowProcessor.java:run(124)) - sinking to: GroupBy(test)[by:[{1}:'ip']], id: CA0F0264A3204B7BB86FA2C1FC19C947
2016-01-14 17:08:24,291 INFO  element.TezGroupGate (TezGroupGate.java:prepare(96)) - calling OrderedPartitionedKVOutput#start() on: GroupBy(test)[by:[{1}:'ip']] CA0F0264A3204B7BB86FA2C1FC19C947
2016-01-14 17:08:24,308 INFO  impl.ExternalSorter (ExternalSorter.java:<init>(167)) - keySerializer=cascading.tuple.hadoop.io.TupleSerializer@5c9a9d06; valueSerializer=cascading.tuple.hadoop.io.TupleSerializer@2abb2469; comparator=cascading.tuple.hadoop.util.TupleComparator@64537f69; conf=cascading.tuple.hadoop.TupleSerialization,org.apache.hadoop.io.serializer.WritableSerialization,org.apache.hadoop.io.serializer.avro.AvroSpecificSerialization,org.apache.hadoop.io.serializer.avro.AvroReflectSerialization
2016-01-14 17:08:24,311 INFO  impl.ExternalSorter (ExternalSorter.java:<init>(224)) - Instantiating Partitioner: [cascading.tuple.tez.util.TuplePartitioner]
2016-01-14 17:08:24,314 INFO  common.TezRuntimeUtils (TezRuntimeUtils.java:instantiatePartitioner(109)) - Using partitioner class: cascading.tuple.tez.util.TuplePartitioner
2016-01-14 17:08:24,314 INFO  common.TezRuntimeUtils (TezRuntimeUtils.java:instantiateCombiner(65)) - No combiner specified via tez.runtime.combiner.class. Combiner will not be used
2016-01-14 17:08:24,432 INFO  dflt.DefaultSorter (DefaultSorter.java:setEquator(328)) - (EQUATOR) 0 kvi 26214396(104857584)
2016-01-14 17:08:24,432 INFO  dflt.DefaultSorter (DefaultSorter.java:<init>(150)) - tez.runtime.io.sort.mb: 100
2016-01-14 17:08:24,432 INFO  dflt.DefaultSorter (DefaultSorter.java:<init>(151)) - soft limit at 83886080
2016-01-14 17:08:24,433 INFO  dflt.DefaultSorter (DefaultSorter.java:<init>(152)) - bufstart = 0; bufvoid = 104857600
2016-01-14 17:08:24,433 INFO  dflt.DefaultSorter (DefaultSorter.java:<init>(153)) - kvstart = 26214396; length = 6553600
2016-01-14 17:08:24,438 INFO  element.TezSourceStage (TezSourceStage.java:prepare(63)) - calling MRInput#start() on: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/classes/test/data/apache.10.txt"]
2016-01-14 17:08:24,438 INFO  input.MRInput (MRInput.java:start(450)) - MRInput setup to received events1
2016-01-14 17:08:24,438 INFO  tez.FlowProcessor (FlowProcessor.java:waitForInputsReady(202)) - flow node id: ECD480AA034C4CD2B200E09E382C9072, all 1 inputs ready in: 00:00:00.000
2016-01-14 17:08:24,442 INFO  task.TezTaskRunner (TezTaskRunner.java:run(177)) - Closing task, taskAttemptId=attempt_1452791303962_0001_1_00_000000_0
2016-01-14 17:08:24,442 INFO  tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: ECD480AA034C4CD2B200E09E382C9072, mem on close (mb), free: 94, total: 281, max: 672
2016-01-14 17:08:24,442 INFO  dflt.DefaultSorter (DefaultSorter.java:flush(589)) - Starting flush of map output
2016-01-14 17:08:24,442 INFO  dflt.DefaultSorter (DefaultSorter.java:flush(607)) - Sorting & Spilling map output
2016-01-14 17:08:24,443 INFO  dflt.DefaultSorter (DefaultSorter.java:flush(608)) - bufstart = 0; bufend = 210; bufvoid = 104857600
2016-01-14 17:08:24,443 INFO  dflt.DefaultSorter (DefaultSorter.java:flush(610)) - kvstart = 26214396(104857584); kvend = 26214360(104857440); length = 37/6553600
2016-01-14 17:08:24,459 INFO  dflt.DefaultSorter (DefaultSorter.java:spill(829)) - Finished spill 0
2016-01-14 17:08:24 Completed running task attempt: attempt_1452791303962_0001_1_00_000000_0
2016-01-14 17:08:24,474 INFO  task.TezTaskRunner (TezTaskRunner.java:run(181)) - Task completed, taskAttemptId=attempt_1452791303962_0001_1_00_000000_0, fatalErrorOccurred=false
2016-01-14 17:08:24,475 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:cleanup(712)) - Final Counters : Counters: 27 [[File System Counters FILE_BYTES_READ=2206, FILE_BYTES_WRITTEN=236, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0][org.apache.tez.common.counters.TaskCounter SPILLED_RECORDS=10, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=295174144, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=10, OUTPUT_BYTES=210, OUTPUT_BYTES_WITH_OVERHEAD=200, OUTPUT_BYTES_PHYSICAL=204, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=0, ADDITIONAL_SPILL_COUNT=0][cascading.flow.SliceCounters Process_Begin_Time=1452791304438, Process_Duration=4, Process_End_Time=1452791304442, Read_Duration=2, Tuples_Read=10, Tuples_Written=10, Write_Duration=1][cascading.flow.StepCounters Tuples_Read=10]]
2016-01-14 17:08:24,475 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791303962_0001_1][Event:VERTEX_DATA_MOVEMENT_EVENTS_GENERATED]: vertexId=vertex_1452791303962_0001_1_00, eventCount=1
2016-01-14 17:08:24,475 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: 
2016-01-14 17:08:24,476 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 17:08:24,476 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_FINISHED to history file
2016-01-14 17:08:24,477 INFO  task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1452791303962_0001_00_000001
2016-01-14 17:08:24,478 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791303962_0001_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=ECD480AA034C4CD2B200E09E382C9072, taskAttemptId=attempt_1452791303962_0001_1_00_000000_0, startTime=1452791304238, finishTime=1452791304476, timeTaken=238, status=SUCCEEDED, errorEnum=, diagnostics=, counters=Counters: 28, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=2206, FILE_BYTES_WRITTEN=236, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, SPILLED_RECORDS=10, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=295174144, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=10, OUTPUT_BYTES=210, OUTPUT_BYTES_WITH_OVERHEAD=200, OUTPUT_BYTES_PHYSICAL=204, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=0, ADDITIONAL_SPILL_COUNT=0, cascading.flow.SliceCounters, Process_Begin_Time=1452791304438, Process_Duration=4, Process_End_Time=1452791304442, Read_Duration=2, Tuples_Read=10, Tuples_Written=10, Write_Duration=1, cascading.flow.StepCounters, Tuples_Read=10
2016-01-14 17:08:24,479 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452791303962_0001_1_00_000000_0 TaskAttempt Transitioned from RUNNING to SUCCEEDED due to event TA_DONE
2016-01-14 17:08:24,479 INFO  rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_ENDED
2016-01-14 17:08:24,479 INFO  impl.TaskImpl (TaskImpl.java:transition(1052)) - Task succeeded with attempt attempt_1452791303962_0001_1_00_000000_0
2016-01-14 17:08:24,480 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_FINISHED to history file
2016-01-14 17:08:24,481 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791303962_0001_1][Event:TASK_FINISHED]: vertexName=ECD480AA034C4CD2B200E09E382C9072, taskId=task_1452791303962_0001_1_00_000000, startTime=1452791304238, finishTime=1452791304480, timeTaken=242, status=SUCCEEDED, successfulAttemptID=attempt_1452791303962_0001_1_00_000000_0, diagnostics=, counters=Counters: 28, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=2206, FILE_BYTES_WRITTEN=236, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, SPILLED_RECORDS=10, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=295174144, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=10, OUTPUT_BYTES=210, OUTPUT_BYTES_WITH_OVERHEAD=200, OUTPUT_BYTES_PHYSICAL=204, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=0, ADDITIONAL_SPILL_COUNT=0, cascading.flow.SliceCounters, Process_Begin_Time=1452791304438, Process_Duration=4, Process_End_Time=1452791304442, Read_Duration=2, Tuples_Read=10, Tuples_Written=10, Write_Duration=1, cascading.flow.StepCounters, Tuples_Read=10
2016-01-14 17:08:24,481 INFO  impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452791303962_0001_1_00_000000 Task Transitioned from RUNNING to SUCCEEDED due to event T_ATTEMPT_SUCCEEDED
2016-01-14 17:08:24,482 INFO  impl.VertexImpl (VertexImpl.java:transition(3536)) - Num completed Tasks for vertex_1452791303962_0001_1_00 [ECD480AA034C4CD2B200E09E382C9072] : 1
2016-01-14 17:08:24,483 INFO  impl.VertexImpl (VertexImpl.java:checkVertexForCompletion(1674)) - Vertex succeeded: vertex_1452791303962_0001_1_00 [ECD480AA034C4CD2B200E09E382C9072]
2016-01-14 17:08:24,485 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_FINISHED to history file
2016-01-14 17:08:24,486 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791303962_0001_1][Event:VERTEX_FINISHED]: vertexName=ECD480AA034C4CD2B200E09E382C9072, vertexId=vertex_1452791303962_0001_1_00, initRequestedTime=1452791304176, initedTime=1452791304205, startRequestedTime=1452791304208, startedTime=1452791304208, finishTime=1452791304484, timeTaken=276, status=SUCCEEDED, diagnostics=, counters=Counters: 28, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=2206, FILE_BYTES_WRITTEN=236, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, SPILLED_RECORDS=10, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=295174144, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=10, OUTPUT_BYTES=210, OUTPUT_BYTES_WITH_OVERHEAD=200, OUTPUT_BYTES_PHYSICAL=204, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=0, ADDITIONAL_SPILL_COUNT=0, cascading.flow.SliceCounters, Process_Begin_Time=1452791304438, Process_Duration=4, Process_End_Time=1452791304442, Read_Duration=2, Tuples_Read=10, Tuples_Written=10, Write_Duration=1, cascading.flow.StepCounters, Tuples_Read=10, vertexStats=firstTaskStartTime=1452791304238, firstTasksToStart=[ task_1452791303962_0001_1_00_000000 ], lastTaskFinishTime=1452791304476, lastTasksToFinish=[ task_1452791303962_0001_1_00_000000 ], minTaskDuration=238, maxTaskDuration=238, avgTaskDuration=238.0, numSuccessfulTasks=1, shortestDurationTasks=[ task_1452791303962_0001_1_00_000000 ], longestDurationTasks=[ task_1452791303962_0001_1_00_000000 ], vertexTaskStats={numFailedTasks=0, numSucceededTasks=1, numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0, numCompletedTasks=1}
2016-01-14 17:08:24,486 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452791303962_0001_1_00 [ECD480AA034C4CD2B200E09E382C9072] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2016-01-14 17:08:24,487 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791303962_0001_00_000001 transitioned from RUNNING to IDLE via event C_TA_SUCCEEDED
2016-01-14 17:08:24,487 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791303962_0001_1][Event:CONTAINER_STOPPED]: containerId=container_1452791303962_0001_00_000001, stoppedTime=1452791304487, exitStatus=0
2016-01-14 17:08:24,487 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791303962_0001_00_000001 transitioned from IDLE to STOP_REQUESTED via event C_STOP_REQUEST
2016-01-14 17:08:24,488 INFO  impl.VertexImpl (VertexImpl.java:transition(3477)) - Source task attempt completed for vertex: vertex_1452791303962_0001_1_01 [B3E81D26ECA145F880D0FDBEB399F97B] attempt: attempt_1452791303962_0001_1_00_000000_0 with state: SUCCEEDED vertexState: RUNNING
2016-01-14 17:08:24,489 INFO  vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:schedulePendingTasks(608)) - All source tasks assigned. Ramping up 1 remaining tasks for vertex: B3E81D26ECA145F880D0FDBEB399F97B
2016-01-14 17:08:24,489 INFO  impl.VertexImpl (VertexImpl.java:scheduleTasks(1250)) - Routing pending task events for vertex: vertex_1452791303962_0001_1_01 [B3E81D26ECA145F880D0FDBEB399F97B]
2016-01-14 17:08:24,489 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_STOPPED to history file
2016-01-14 17:08:24,490 INFO  app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(213)) - Container with id: container_1452791303962_0001_00_000001 is valid, but no longer registered, and will be killed
2016-01-14 17:08:24,490 INFO  task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1452791303962_0001_00_000001: 11 ms after starting to poll. TaskInfo: shouldDie: true
2016-01-14 17:08:24,490 INFO  task.TezChild (TezChild.java:run(207)) - ContainerTask returned shouldDie=true for container container_1452791303962_0001_00_000001, Exiting
2016-01-14 17:08:24,490 INFO  task.TezChild (TezChild.java:shutdown(343)) - Shutdown invoked for container container_1452791303962_0001_00_000001
2016-01-14 17:08:24,490 INFO  task.TezChild (TezChild.java:shutdown(345)) - Shutting down container container_1452791303962_0001_00_000001
2016-01-14 17:08:24,493 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(270)) - ContainerExecutionResult for: container_1452791303962_0001_00_000001 = ContainerExecutionResult{exitStatus=SUCCESS, throwable=null, errorMessage='Asked to die by the AM'}
2016-01-14 17:08:24,493 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(274)) - Container: container_1452791303962_0001_00_000001 completed successfully
2016-01-14 17:08:24,493 INFO  impl.DAGImpl (DAGImpl.java:transition(1747)) - Vertex vertex_1452791303962_0001_1_00 [ECD480AA034C4CD2B200E09E382C9072] completed., numCompletedVertices=1, numSuccessfulVertices=1, numFailedVertices=0, numKilledVertices=0, numVertices=2
2016-01-14 17:08:24,494 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:stop(242)) - Ignoring stop request for containerId: container_1452791303962_0001_00_000001
2016-01-14 17:08:24,494 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_STARTED to history file
2016-01-14 17:08:24,494 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791303962_0001_1][Event:TASK_STARTED]: vertexName=B3E81D26ECA145F880D0FDBEB399F97B, taskId=task_1452791303962_0001_1_01_000000, scheduledTime=1452791304494, launchTime=1452791304494
2016-01-14 17:08:24,495 INFO  impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452791303962_0001_1_01_000000 Task Transitioned from NEW to SCHEDULED due to event T_SCHEDULE
2016-01-14 17:08:24,495 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791303962_0001_00_000001 transitioned from STOP_REQUESTED to COMPLETED via event C_COMPLETED
2016-01-14 17:08:24,495 INFO  impl.DAGSchedulerNaturalOrderControlled (DAGSchedulerNaturalOrderControlled.java:scheduleTask(111)) - Scheduled vertex: vertex_1452791303962_0001_1_01 [B3E81D26ECA145F880D0FDBEB399F97B]
2016-01-14 17:08:24,496 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1014)) - remoteTaskSpec:DAGName : [3FF5F23BC43146E0984CE9835D6621EC/F0F48D52C0C74352AFD1058514FCC56B] test/(1/1) ...stFlowStepStrategy/simple, VertexName: B3E81D26ECA145F880D0FDBEB399F97B, VertexParallelism: 1, TaskAttemptID:attempt_1452791303962_0001_1_01_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=ECD480AA034C4CD2B200E09E382C9072, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }}, ], outputSpecList=[{{ destinationVertexName=E46656297BDC43819B606E5CABE51C22, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }}, ]
2016-01-14 17:08:24,496 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452791303962_0001_1_01_000000_0 TaskAttempt Transitioned from NEW to START_WAIT due to event TA_SCHEDULE
2016-01-14 17:08:24,496 INFO  rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_LAUNCH_REQUEST
2016-01-14 17:08:24,497 INFO  container.AMContainerImpl (AMContainerImpl.java:transition(521)) - Sending Launch Request for Container with id: container_1452791303962_0001_00_000002
2016-01-14 17:08:24,498 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791303962_0001_00_000002 transitioned from ALLOCATED to LAUNCHING via event C_LAUNCH_REQUEST
2016-01-14 17:08:24,500 INFO  task.TezChild (TezChild.java:newTezChild(432)) - PID, containerIdentifier:  null, container_1452791303962_0001_00_000002
2016-01-14 17:08:24,501 WARN  impl.MetricsConfig (MetricsConfig.java:loadFirst(124)) - Cannot locate configuration: tried hadoop-metrics2-teztask.properties,hadoop-metrics2.properties
2016-01-14 17:08:24,503 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791303962_0001_00_000002 transitioned from LAUNCHING to IDLE via event C_LAUNCHED
2016-01-14 17:08:24,503 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_LAUNCHED to history file
2016-01-14 17:08:24,504 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791303962_0001_1][Event:CONTAINER_LAUNCHED]: containerId=container_1452791303962_0001_00_000002, launchTime=1452791304503
2016-01-14 17:08:24,504 INFO  task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1452791303962_0001_00_000002
2016-01-14 17:08:24,506 INFO  container.AMContainerImpl (AMContainerImpl.java:transition(827)) - Assigned taskAttempt + [attempt_1452791303962_0001_1_01_000000_0] to container: [container_1452791303962_0001_00_000002]
2016-01-14 17:08:24,506 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791303962_0001_00_000002 transitioned from IDLE to RUNNING via event C_PULL_TA
2016-01-14 17:08:24,506 INFO  app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(240)) - Container with id: container_1452791303962_0001_00_000002 given task: attempt_1452791303962_0001_1_01_000000_0
2016-01-14 17:08:24,506 INFO  task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1452791303962_0001_00_000002: 0 ms after starting to poll. TaskInfo: shouldDie: false, currentTaskAttemptId: attempt_1452791303962_0001_1_01_000000_0
2016-01-14 17:08:24,507 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1146)) - TaskAttempt: [attempt_1452791303962_0001_1_01_000000_0] started. Is using containerId: [container_1452791303962_0001_00_000002] on NM: [127.0.0.1:0]
2016-01-14 17:08:24,507 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791303962_0001_1][Event:TASK_ATTEMPT_STARTED]: vertexName=B3E81D26ECA145F880D0FDBEB399F97B, taskAttemptId=attempt_1452791303962_0001_1_01_000000_0, startTime=1452791304506, containerId=container_1452791303962_0001_00_000002, nodeId=127.0.0.1:0, inProgressLogs=127.0.0.1:0/node/containerlogs/container_1452791303962_0001_00_000002/teamcity, completedLogs=
2016-01-14 17:08:24,507 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452791303962_0001_1_01_000000_0 TaskAttempt Transitioned from START_WAIT to RUNNING due to event TA_STARTED_REMOTELY
2016-01-14 17:08:24,507 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_STARTED to history file
2016-01-14 17:08:24,507 INFO  impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452791303962_0001_1_01_000000 Task Transitioned from SCHEDULED to RUNNING due to event T_ATTEMPT_LAUNCHED
2016-01-14 17:08:24 Starting to run new task attempt: attempt_1452791303962_0001_1_01_000000_0
2016-01-14 17:08:24,508 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: attempt_1452791303962_0001_1_01_000000_0
2016-01-14 17:08:24,508 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 17:08:24,510 INFO  task.TezChild (TezChild.java:handleNewTaskCredentials(273)) - Refreshing UGI since Credentials have changed
2016-01-14 17:08:24,510 INFO  task.TezChild (TezChild.java:handleNewTaskCredentials(276)) - Credentials : #Tokens=1, #SecretKeys=0
2016-01-14 17:08:24,510 INFO  task.TezChild (TezChild.java:handleNewTaskLocalResources(302)) - Localizing additional local resources for Task : {}
2016-01-14 17:08:24,510 INFO  task.TezChild (TezChild.java:handleNewTaskLocalResources(312)) - Done localizing additional resources
2016-01-14 17:08:24,510 INFO  metrics.TaskCounterUpdater (TaskCounterUpdater.java:initResourceCalculatorPlugin(148)) -  Using ResourceCalculatorProcessTree : [ ]
2016-01-14 17:08:24,511 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:<init>(149)) - Initializing LogicalIOProcessorRuntimeTask with TaskSpec: DAGName : [3FF5F23BC43146E0984CE9835D6621EC/F0F48D52C0C74352AFD1058514FCC56B] test/(1/1) ...stFlowStepStrategy/simple, VertexName: B3E81D26ECA145F880D0FDBEB399F97B, VertexParallelism: 1, TaskAttemptID:attempt_1452791303962_0001_1_01_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=ECD480AA034C4CD2B200E09E382C9072, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }}, ], outputSpecList=[{{ destinationVertexName=E46656297BDC43819B606E5CABE51C22, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }}, ]
2016-01-14 17:08:24,511 INFO  resources.MemoryDistributor (MemoryDistributor.java:<init>(85)) - InitialMemoryDistributor (isEnabled=true) invoked with: numInputs=1, numOutputs=1, JVM.maxFree=704643072
2016-01-14 17:08:24,512 INFO  task.TezTaskRunner (TezTaskRunner.java:run(172)) - Initializing task, taskAttemptId=attempt_1452791303962_0001_1_01_000000_0
2016-01-14 17:08:24,513 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(191)) - Initializing LogicalProcessorIORuntimeTask
2016-01-14 17:08:24,514 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(195)) - Creating processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 17:08:24,512 INFO  impl.TaskImpl (TaskImpl.java:getTaskAttemptTezEvents(481)) - TaskAttempt:attempt_1452791303962_0001_1_01_000000_0 sent events: (0-1)
2016-01-14 17:08:24,515 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(488)) - Initializing processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 17:08:24,516 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(389)) - Initializing Input using InputSpec: { sourceVertexName=ECD480AA034C4CD2B200E09E382C9072, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }
2016-01-14 17:08:24,516 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(438)) - Initializing Output using OutputSpec: { destinationVertexName=E46656297BDC43819B606E5CABE51C22, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }
2016-01-14 17:08:24,517 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createInput(537)) - Creating Input
2016-01-14 17:08:24,517 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createOutput(565)) - Creating Output
2016-01-14 17:08:24,518 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(446)) - Initializing Output with dest edge: E46656297BDC43819B606E5CABE51C22
2016-01-14 17:08:24,518 INFO  output.MROutput (MROutput.java:initialize(347)) - Initializing Simple Output
2016-01-14 17:08:24,518 INFO  resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 0, type: OUTPUT, componentVertexName: E46656297BDC43819B606E5CABE51C22
2016-01-14 17:08:24,519 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(397)) - Initializing Input with src edge: ECD480AA034C4CD2B200E09E382C9072
2016-01-14 17:08:24,520 INFO  tez.FlowProcessor (FlowProcessor.java:initialize(88)) - cascading version: 3.0.4
2016-01-14 17:08:24,529 INFO  orderedgrouped.MergeManager (MergeManager.java:getInitialMemoryRequirement(310)) - Initial Shuffle Memory Required: 634178752, based on INPUT_BUFFER_factor: 0.9
2016-01-14 17:08:24,530 INFO  orderedgrouped.MergeManager (MergeManager.java:getInitialMemoryRequirement(320)) - Initial Memory required for final merged output: 0, using factor: 0.0
2016-01-14 17:08:24,530 INFO  resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 634178752, type: INPUT, componentVertexName: ECD480AA034C4CD2B200E09E382C9072
2016-01-14 17:08:24,532 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(403)) - Initialized Input with src edge: ECD480AA034C4CD2B200E09E382C9072
2016-01-14 17:08:24,534 INFO  output.MROutput (MROutput.java:initialize(418)) - Initialized Simple Output, using_new_api: false
2016-01-14 17:08:24,534 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(452)) - Initialized Output with dest edge: E46656297BDC43819B606E5CABE51C22
2016-01-14 17:08:24,538 INFO  tez.FlowProcessor (FlowProcessor.java:initialize(94)) - flow node id: B3E81D26ECA145F880D0FDBEB399F97B, ordinal: 1
2016-01-14 17:08:24,538 INFO  tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: B3E81D26ECA145F880D0FDBEB399F97B, mem on start (mb), free: 84, total: 281, max: 672
2016-01-14 17:08:24,538 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(491)) - Initialized processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 17:08:24,538 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 2 initializers to finish
2016-01-14 17:08:24,539 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 1 initializers to finish
2016-01-14 17:08:24,539 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(233)) - All initializers finished
2016-01-14 17:08:24,539 INFO  resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(124)) - Using Allocator class: org.apache.tez.runtime.library.resources.WeightedScalingMemoryDistributor
2016-01-14 17:08:24,539 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:getRequestTypeForClass(197)) - Falling back to RequestType.OTHER for class: org.apache.tez.mapreduce.output.MROutput
2016-01-14 17:08:24,539 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 1, for type: OTHER
2016-01-14 17:08:24,540 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 12, for type: SORTED_MERGED_INPUT
2016-01-14 17:08:24,540 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:computeReservedFraction(262)) - InitialReservationFraction=0.3, AdditionalReservationFractionForIOs=0.03, finalReserveFractionUsed=0.32999999999999996
2016-01-14 17:08:24,540 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:assignMemory(126)) - Scaling Requests. NumRequests: 2, numScaledRequests: 13, TotalRequested: 634178752, TotalRequestedScaled: 5.853957710769231E8, TotalJVMHeap: 704643072, TotalAvailable: 472110858, TotalRequested/TotalJVMHeap:0.90
2016-01-14 17:08:24,540 INFO  resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: OUTPUT, E46656297BDC43819B606E5CABE51C22, org.apache.tez.mapreduce.output.MROutput: requested=0, allocated=0
2016-01-14 17:08:24,540 INFO  resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: INPUT, ECD480AA034C4CD2B200E09E382C9072, org.apache.tez.runtime.library.input.OrderedGroupedKVInput: requested=634178752, allocated=472110858
2016-01-14 17:08:24,540 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(255)) - Starting Inputs/Outputs
2016-01-14 17:08:24,541 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(268)) - Input: ECD480AA034C4CD2B200E09E382C9072 being auto started by the framework. Subsequent instances will not be auto-started
2016-01-14 17:08:24,541 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(289)) - Num IOs determined for AutoStart: 1
2016-01-14 17:08:24,541 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(291)) - Waiting for 1 IOs to start
2016-01-14 17:08:24,541 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(419)) - Starting Input with src edge: ECD480AA034C4CD2B200E09E382C9072
2016-01-14 17:08:24,549 INFO  common.TezRuntimeUtils (TezRuntimeUtils.java:instantiateCombiner(65)) - No combiner specified via tez.runtime.combiner.class. Combiner will not be used
2016-01-14 17:08:24,550 INFO  orderedgrouped.Shuffle (Shuffle.java:<init>(182)) - Shuffle assigned with 1 inputs, codec: NoneifileReadAhead: true
2016-01-14 17:08:24,554 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:<init>(158)) - ShuffleScheduler running for sourceVertex: ECD480AA034C4CD2B200E09E382C9072 with configuration: maxFetchFailuresBeforeReporting=5, reportReadErrorImmediately=true, maxFailedUniqueFetches=1, abortFailureLimit=30, maxMapRuntime=0, maxTaskOutputAtOnce=20
2016-01-14 17:08:24,556 INFO  orderedgrouped.MergeManager (MergeManager.java:<init>(221)) - InitialRequest: ShuffleMem=634178752, postMergeMem=0, RuntimeTotalAvailable=472110858. Updated to: ShuffleMem=472110858, postMergeMem: 0
2016-01-14 17:08:24,556 INFO  orderedgrouped.MergeManager (MergeManager.java:<init>(252)) - MergerManager: memoryLimit=472110858, maxSingleShuffleLimit=118027712, mergeThreshold=424899744, ioSortFactor=100, memToMemMergeOutputsThreshold=100
2016-01-14 17:08:24,560 INFO  orderedgrouped.Shuffle (Shuffle.java:<init>(233)) - Num fetchers being started: 1
2016-01-14 17:08:24,565 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(421)) - Started Input with src edge: ECD480AA034C4CD2B200E09E382C9072
2016-01-14 17:08:24,565 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(304)) - AutoStartComplete
2016-01-14 17:08:24,565 INFO  task.TezTaskRunner (TezTaskRunner.java:run(175)) - Running task, taskAttemptId=attempt_1452791303962_0001_1_01_000000_0
2016-01-14 17:08:24,566 INFO  orderedgrouped.ShuffleInputEventHandlerOrderedGrouped (ShuffleInputEventHandlerOrderedGrouped.java:processDataMovementEvent(84)) - DME srcIdx: 0, targetIdx: 0, attemptNum: 0, payload: [host: ip-10-187-41-40, port: 0, pathComponent: attempt_1452791303962_0001_1_00_000000_0_10008, runDuration: 202125, ]
2016-01-14 17:08:24,573 INFO  graph.Hadoop2TezStreamGraph (Hadoop2TezStreamGraph.java:buildGraph(151)) - using streamed source: GroupBy(test)[by:[{1}:'ip']]
2016-01-14 17:08:24,576 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:logIndividualFetchComplete(250)) - Completed fetch for attempt: InputAttemptIdentifier [inputIdentifier=InputIdentifier [inputIndex=0], attemptNumber=0, pathComponent=attempt_1452791303962_0001_1_00_000000_0_10008] to DISK_DIRECT, CompressedSize=204, DecompressedSize=200,EndTime=1452791304576, TimeTaken=2, Rate=0.10 MB/s
2016-01-14 17:08:24,577 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:copySucceeded(213)) - All inputs fetched for input vertex : ECD480AA034C4CD2B200E09E382C9072
2016-01-14 17:08:24,577 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:logProgress(263)) - copy(1 of 1. Transfer rate (CumulativeDataFetched/TimeSinceInputStarted)) 0.00 MB/s)
2016-01-14 17:08:24,578 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:freeHost(529)) - ip-10-187-41-40:0 freed by fetcher [ECD480AA034C4CD2B200E09E382C9072] #1 in 4ms
2016-01-14 17:08:24,578 INFO  tez.FlowProcessor (FlowProcessor.java:run(121)) - sourcing from: GroupBy(test)[by:[{1}:'ip']] streamed: true, id: CA0F0264A3204B7BB86FA2C1FC19C947
2016-01-14 17:08:24,578 INFO  tez.FlowProcessor (FlowProcessor.java:run(124)) - sinking to: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/output/hadoop2-tez/flowstrategiesplatform/testFlowStepStrategy/simple"], id: E46656297BDC43819B606E5CABE51C22
2016-01-14 17:08:24,579 INFO  element.TezSinkStage (TezSinkStage.java:prepare(57)) - calling MROutput#start() on: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/output/hadoop2-tez/flowstrategiesplatform/testFlowStepStrategy/simple"]
2016-01-14 17:08:24,578 INFO  orderedgrouped.Shuffle (Shuffle.java:cleanupFetchers(394)) - Shutdown..fetcher [ECD480AA034C4CD2B200E09E382C9072] #1, status:false, isInterrupted:false
2016-01-14 17:08:24,579 INFO  element.TezGroupGate (TezGroupGate.java:prepare(88)) - calling OrderedGroupedKVInput#start() on: GroupBy(test)[by:[{1}:'ip']] CA0F0264A3204B7BB86FA2C1FC19C947, for 1 inputs
2016-01-14 17:08:24,581 INFO  orderedgrouped.MergeManager (MergeManager.java:finalMerge(854)) - finalMerge called with 0 in-memory map-outputs and 1 on-disk map-outputs
2016-01-14 17:08:24,584 INFO  orderedgrouped.MergeManager (MergeManager.java:finalMerge(951)) - Merging 1 files, 204 bytes from disk
2016-01-14 17:08:24,586 INFO  orderedgrouped.MergeManager (MergeManager.java:finalMerge(966)) - Merging 0 segments, 0 bytes from memory into reduce
2016-01-14 17:08:24,590 INFO  impl.TezMerger (TezMerger.java:merge(560)) - Merging 1 sorted segments
2016-01-14 17:08:24,593 INFO  impl.TezMerger (TezMerger.java:merge(665)) - Down to the last merge-pass, with 1 segments left of total size: 175 bytes
2016-01-14 17:08:24,593 INFO  orderedgrouped.Shuffle (Shuffle.java:call(381)) - merge complete for input vertex : ECD480AA034C4CD2B200E09E382C9072
2016-01-14 17:08:24,594 INFO  tez.FlowProcessor (FlowProcessor.java:waitForInputsReady(202)) - flow node id: B3E81D26ECA145F880D0FDBEB399F97B, all 1 inputs ready in: 00:00:00.013
2016-01-14 17:08:24,594 INFO  orderedgrouped.Shuffle (Shuffle.java:onSuccess(488)) - Shuffle Runner thread complete
2016-01-14 17:08:24,598 INFO  common.ValuesIterator (ValuesIterator.java:<init>(83)) - keyDeserializer=cascading.tuple.hadoop.io.TupleDeserializer@2034da9; valueDeserializer=cascading.tuple.hadoop.io.TupleDeserializer@26df9347
2016-01-14 17:08:24,606 INFO  output.MROutput (MROutput.java:flush(534)) - Flushing Simple Output
2016-01-14 17:08:24,607 INFO  output.MROutput (MROutput.java:flush(544)) - Flushed Simple Output
2016-01-14 17:08:24,608 INFO  app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:canCommit(353)) - Commit go/no-go request from attempt_1452791303962_0001_1_01_000000_0
2016-01-14 17:08:24,608 INFO  impl.TaskImpl (TaskImpl.java:canCommit(750)) - attempt_1452791303962_0001_1_01_000000_0 given a go for committing the task output.
2016-01-14 17:08:24,610 INFO  task.TezTaskRunner (TezTaskRunner.java:run(177)) - Closing task, taskAttemptId=attempt_1452791303962_0001_1_01_000000_0
2016-01-14 17:08:24,610 INFO  tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: B3E81D26ECA145F880D0FDBEB399F97B, mem on close (mb), free: 78, total: 281, max: 672
2016-01-14 17:08:24,610 INFO  orderedgrouped.Shuffle (Shuffle.java:shutdown(320)) - Shutting down Shuffle for source: ECD480AA034C4CD2B200E09E382C9072
2016-01-14 17:08:24,611 INFO  orderedgrouped.MergeManager (MergeManager.java:finalMerge(854)) - finalMerge called with 0 in-memory map-outputs and 0 on-disk map-outputs
2016-01-14 17:08:24,611 INFO  orderedgrouped.MergeManager (MergeManager.java:finalMerge(951)) - Merging 0 files, 0 bytes from disk
2016-01-14 17:08:24,611 INFO  orderedgrouped.MergeManager (MergeManager.java:finalMerge(966)) - Merging 0 segments, 0 bytes from memory into reduce
2016-01-14 17:08:24,611 INFO  impl.TezMerger (TezMerger.java:merge(560)) - Merging 0 sorted segments
2016-01-14 17:08:24,612 INFO  impl.TezMerger (TezMerger.java:merge(562)) - Nothing to merge. Returning an empty iterator
2016-01-14 17:08:24 Completed running task attempt: attempt_1452791303962_0001_1_01_000000_0
2016-01-14 17:08:24,614 INFO  task.TezTaskRunner (TezTaskRunner.java:run(181)) - Task completed, taskAttemptId=attempt_1452791303962_0001_1_01_000000_0, fatalErrorOccurred=false
2016-01-14 17:08:24,617 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_FINISHED to history file
2016-01-14 17:08:24,617 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:cleanup(712)) - Final Counters : Counters: 46 [[File System Counters FILE_BYTES_READ=236, FILE_BYTES_WRITTEN=140, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0][org.apache.tez.common.counters.TaskCounter REDUCE_INPUT_GROUPS=7, REDUCE_INPUT_RECORDS=10, COMBINE_INPUT_RECORDS=0, SPILLED_RECORDS=10, NUM_SHUFFLED_INPUTS=1, NUM_SKIPPED_INPUTS=0, NUM_FAILED_SHUFFLE_INPUTS=0, MERGED_MAP_OUTPUTS=1, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=295174144, OUTPUT_RECORDS=8, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=204, SHUFFLE_BYTES=204, SHUFFLE_BYTES_DECOMPRESSED=200, SHUFFLE_BYTES_TO_MEM=0, SHUFFLE_BYTES_TO_DISK=0, SHUFFLE_BYTES_DISK_DIRECT=204, NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=28, MERGE_PHASE_TIME=43, FIRST_EVENT_RECEIVED=24, LAST_EVENT_RECEIVED=24][Shuffle Errors BAD_ID=0, CONNECTION=0, IO_ERROR=0, WRONG_LENGTH=0, WRONG_MAP=0, WRONG_REDUCE=0][cascading.flow.SliceCounters Process_Begin_Time=1452791304594, Process_Duration=16, Process_End_Time=1452791304610, Read_Duration=2, Tuples_Read=10, Tuples_Written=8, Write_Duration=0][cascading.flow.StepCounters Tuples_Written=8]]
2016-01-14 17:08:24,617 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791303962_0001_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=B3E81D26ECA145F880D0FDBEB399F97B, taskAttemptId=attempt_1452791303962_0001_1_01_000000_0, startTime=1452791304506, finishTime=1452791304616, timeTaken=110, status=SUCCEEDED, errorEnum=, diagnostics=, counters=Counters: 46, File System Counters, FILE_BYTES_READ=236, FILE_BYTES_WRITTEN=140, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=7, REDUCE_INPUT_RECORDS=10, COMBINE_INPUT_RECORDS=0, SPILLED_RECORDS=10, NUM_SHUFFLED_INPUTS=1, NUM_SKIPPED_INPUTS=0, NUM_FAILED_SHUFFLE_INPUTS=0, MERGED_MAP_OUTPUTS=1, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=295174144, OUTPUT_RECORDS=8, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=204, SHUFFLE_BYTES=204, SHUFFLE_BYTES_DECOMPRESSED=200, SHUFFLE_BYTES_TO_MEM=0, SHUFFLE_BYTES_TO_DISK=0, SHUFFLE_BYTES_DISK_DIRECT=204, NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=28, MERGE_PHASE_TIME=43, FIRST_EVENT_RECEIVED=24, LAST_EVENT_RECEIVED=24, Shuffle Errors, BAD_ID=0, CONNECTION=0, IO_ERROR=0, WRONG_LENGTH=0, WRONG_MAP=0, WRONG_REDUCE=0, cascading.flow.SliceCounters, Process_Begin_Time=1452791304594, Process_Duration=16, Process_End_Time=1452791304610, Read_Duration=2, Tuples_Read=10, Tuples_Written=8, Write_Duration=0, cascading.flow.StepCounters, Tuples_Written=8
2016-01-14 17:08:24,618 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452791303962_0001_1_01_000000_0 TaskAttempt Transitioned from RUNNING to SUCCEEDED due to event TA_DONE
2016-01-14 17:08:24,618 INFO  impl.TaskImpl (TaskImpl.java:transition(1052)) - Task succeeded with attempt attempt_1452791303962_0001_1_01_000000_0
2016-01-14 17:08:24,618 INFO  rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_ENDED
2016-01-14 17:08:24,619 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791303962_0001_1][Event:TASK_FINISHED]: vertexName=B3E81D26ECA145F880D0FDBEB399F97B, taskId=task_1452791303962_0001_1_01_000000, startTime=1452791304506, finishTime=1452791304618, timeTaken=112, status=SUCCEEDED, successfulAttemptID=attempt_1452791303962_0001_1_01_000000_0, diagnostics=, counters=Counters: 46, File System Counters, FILE_BYTES_READ=236, FILE_BYTES_WRITTEN=140, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=7, REDUCE_INPUT_RECORDS=10, COMBINE_INPUT_RECORDS=0, SPILLED_RECORDS=10, NUM_SHUFFLED_INPUTS=1, NUM_SKIPPED_INPUTS=0, NUM_FAILED_SHUFFLE_INPUTS=0, MERGED_MAP_OUTPUTS=1, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=295174144, OUTPUT_RECORDS=8, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=204, SHUFFLE_BYTES=204, SHUFFLE_BYTES_DECOMPRESSED=200, SHUFFLE_BYTES_TO_MEM=0, SHUFFLE_BYTES_TO_DISK=0, SHUFFLE_BYTES_DISK_DIRECT=204, NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=28, MERGE_PHASE_TIME=43, FIRST_EVENT_RECEIVED=24, LAST_EVENT_RECEIVED=24, Shuffle Errors, BAD_ID=0, CONNECTION=0, IO_ERROR=0, WRONG_LENGTH=0, WRONG_MAP=0, WRONG_REDUCE=0, cascading.flow.SliceCounters, Process_Begin_Time=1452791304594, Process_Duration=16, Process_End_Time=1452791304610, Read_Duration=2, Tuples_Read=10, Tuples_Written=8, Write_Duration=0, cascading.flow.StepCounters, Tuples_Written=8
2016-01-14 17:08:24,619 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_FINISHED to history file
2016-01-14 17:08:24,619 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: 
2016-01-14 17:08:24,620 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 17:08:24,619 INFO  impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452791303962_0001_1_01_000000 Task Transitioned from RUNNING to SUCCEEDED due to event T_ATTEMPT_SUCCEEDED
2016-01-14 17:08:24,621 INFO  impl.VertexImpl (VertexImpl.java:transition(3536)) - Num completed Tasks for vertex_1452791303962_0001_1_01 [B3E81D26ECA145F880D0FDBEB399F97B] : 1
2016-01-14 17:08:24,621 INFO  impl.VertexImpl (VertexImpl.java:checkVertexForCompletion(1674)) - Vertex succeeded: vertex_1452791303962_0001_1_01 [B3E81D26ECA145F880D0FDBEB399F97B]
2016-01-14 17:08:24,622 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_FINISHED to history file
2016-01-14 17:08:24,623 INFO  task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1452791303962_0001_00_000002
2016-01-14 17:08:24,623 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791303962_0001_1][Event:VERTEX_FINISHED]: vertexName=B3E81D26ECA145F880D0FDBEB399F97B, vertexId=vertex_1452791303962_0001_1_01, initRequestedTime=1452791304179, initedTime=1452791304196, startRequestedTime=1452791304222, startedTime=1452791304222, finishTime=1452791304621, timeTaken=399, status=SUCCEEDED, diagnostics=, counters=Counters: 46, File System Counters, FILE_BYTES_READ=236, FILE_BYTES_WRITTEN=140, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=7, REDUCE_INPUT_RECORDS=10, COMBINE_INPUT_RECORDS=0, SPILLED_RECORDS=10, NUM_SHUFFLED_INPUTS=1, NUM_SKIPPED_INPUTS=0, NUM_FAILED_SHUFFLE_INPUTS=0, MERGED_MAP_OUTPUTS=1, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=295174144, OUTPUT_RECORDS=8, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=204, SHUFFLE_BYTES=204, SHUFFLE_BYTES_DECOMPRESSED=200, SHUFFLE_BYTES_TO_MEM=0, SHUFFLE_BYTES_TO_DISK=0, SHUFFLE_BYTES_DISK_DIRECT=204, NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=28, MERGE_PHASE_TIME=43, FIRST_EVENT_RECEIVED=24, LAST_EVENT_RECEIVED=24, Shuffle Errors, BAD_ID=0, CONNECTION=0, IO_ERROR=0, WRONG_LENGTH=0, WRONG_MAP=0, WRONG_REDUCE=0, cascading.flow.SliceCounters, Process_Begin_Time=1452791304594, Process_Duration=16, Process_End_Time=1452791304610, Read_Duration=2, Tuples_Read=10, Tuples_Written=8, Write_Duration=0, cascading.flow.StepCounters, Tuples_Written=8, vertexStats=firstTaskStartTime=1452791304506, firstTasksToStart=[ task_1452791303962_0001_1_01_000000 ], lastTaskFinishTime=1452791304616, lastTasksToFinish=[ task_1452791303962_0001_1_01_000000 ], minTaskDuration=110, maxTaskDuration=110, avgTaskDuration=110.0, numSuccessfulTasks=1, shortestDurationTasks=[ task_1452791303962_0001_1_01_000000 ], longestDurationTasks=[ task_1452791303962_0001_1_01_000000 ], vertexTaskStats={numFailedTasks=0, numSucceededTasks=1, numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0, numCompletedTasks=1}
2016-01-14 17:08:24,626 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452791303962_0001_1_01 [B3E81D26ECA145F880D0FDBEB399F97B] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2016-01-14 17:08:24,626 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791303962_0001_00_000002 transitioned from RUNNING to IDLE via event C_TA_SUCCEEDED
2016-01-14 17:08:24,626 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_STOPPED to history file
2016-01-14 17:08:24,627 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791303962_0001_1][Event:CONTAINER_STOPPED]: containerId=container_1452791303962_0001_00_000002, stoppedTime=1452791304626, exitStatus=0
2016-01-14 17:08:24,628 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791303962_0001_00_000002 transitioned from IDLE to STOP_REQUESTED via event C_STOP_REQUEST
2016-01-14 17:08:24,628 INFO  impl.DAGImpl (DAGImpl.java:transition(1747)) - Vertex vertex_1452791303962_0001_1_01 [B3E81D26ECA145F880D0FDBEB399F97B] completed., numCompletedVertices=2, numSuccessfulVertices=2, numFailedVertices=0, numKilledVertices=0, numVertices=2
2016-01-14 17:08:24,628 INFO  impl.DAGImpl (DAGImpl.java:commitOrAbortOutputs(831)) - Calling DAG commit/abort for dag: dag_1452791303962_0001_1
2016-01-14 17:08:24,629 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791303962_0001_1][Event:DAG_COMMIT_STARTED]: dagID=dag_1452791303962_0001_1
2016-01-14 17:08:24,629 INFO  impl.DAGImpl (DAGImpl.java:commitOrAbortOutputs(892)) - Committing output: E46656297BDC43819B606E5CABE51C22 for vertex: vertex_1452791303962_0001_1_01 [B3E81D26ECA145F880D0FDBEB399F97B]
2016-01-14 17:08:24,636 INFO  app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(213)) - Container with id: container_1452791303962_0001_00_000002 is valid, but no longer registered, and will be killed
2016-01-14 17:08:24,636 INFO  task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1452791303962_0001_00_000002: 11 ms after starting to poll. TaskInfo: shouldDie: true
2016-01-14 17:08:24,636 INFO  task.TezChild (TezChild.java:run(207)) - ContainerTask returned shouldDie=true for container container_1452791303962_0001_00_000002, Exiting
2016-01-14 17:08:24,636 INFO  task.TezChild (TezChild.java:shutdown(343)) - Shutdown invoked for container container_1452791303962_0001_00_000002
2016-01-14 17:08:24,636 INFO  task.TezChild (TezChild.java:shutdown(345)) - Shutting down container container_1452791303962_0001_00_000002
2016-01-14 17:08:24,637 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(270)) - ContainerExecutionResult for: container_1452791303962_0001_00_000002 = ContainerExecutionResult{exitStatus=SUCCESS, throwable=null, errorMessage='Asked to die by the AM'}
2016-01-14 17:08:24,638 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(274)) - Container: container_1452791303962_0001_00_000002 completed successfully
2016-01-14 17:08:24,642 INFO  impl.DAGImpl (DAGImpl.java:commitOrAbortOutputs(871)) - No output committers for vertex: vertex_1452791303962_0001_1_00 [ECD480AA034C4CD2B200E09E382C9072]
2016-01-14 17:08:24,644 INFO  recovery.RecoveryService (RecoveryService.java:handle(306)) - DAG completed, dagId=dag_1452791303962_0001_1, queueSize=0
2016-01-14 17:08:24,645 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_FINISHED to history file
2016-01-14 17:08:24,645 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791303962_0001_1][Event:DAG_FINISHED]: dagId=dag_1452791303962_0001_1, startTime=1452791304175, finishTime=1452791304642, timeTaken=467, status=SUCCEEDED, diagnostics=, counters=Counters: 55, org.apache.tez.common.counters.DAGCounter, NUM_SUCCEEDED_TASKS=2, TOTAL_LAUNCHED_TASKS=2, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=2442, FILE_BYTES_WRITTEN=376, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=7, REDUCE_INPUT_RECORDS=10, COMBINE_INPUT_RECORDS=0, SPILLED_RECORDS=20, NUM_SHUFFLED_INPUTS=1, NUM_SKIPPED_INPUTS=0, NUM_FAILED_SHUFFLE_INPUTS=0, MERGED_MAP_OUTPUTS=1, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=590348288, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=18, OUTPUT_BYTES=210, OUTPUT_BYTES_WITH_OVERHEAD=200, OUTPUT_BYTES_PHYSICAL=204, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=204, ADDITIONAL_SPILL_COUNT=0, SHUFFLE_BYTES=204, SHUFFLE_BYTES_DECOMPRESSED=200, SHUFFLE_BYTES_TO_MEM=0, SHUFFLE_BYTES_TO_DISK=0, SHUFFLE_BYTES_DISK_DIRECT=204, NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=28, MERGE_PHASE_TIME=43, FIRST_EVENT_RECEIVED=24, LAST_EVENT_RECEIVED=24, Shuffle Errors, BAD_ID=0, CONNECTION=0, IO_ERROR=0, WRONG_LENGTH=0, WRONG_MAP=0, WRONG_REDUCE=0, cascading.flow.SliceCounters, Process_Begin_Time=2905582609032, Process_Duration=20, Process_End_Time=2905582609052, Read_Duration=4, Tuples_Read=20, Tuples_Written=18, Write_Duration=1, cascading.flow.StepCounters, Tuples_Read=10, Tuples_Written=8
2016-01-14 17:08:24,645 INFO  impl.DAGImpl (DAGImpl.java:finished(1180)) - DAG: dag_1452791303962_0001_1 finished with state: SUCCEEDED
2016-01-14 17:08:24,647 INFO  impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1452791303962_0001_1 transitioned from RUNNING to SUCCEEDED due to event DAG_VERTEX_COMPLETED
2016-01-14 17:08:24,648 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:stop(242)) - Ignoring stop request for containerId: container_1452791303962_0001_00_000002
2016-01-14 17:08:24,649 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791303962_0001_00_000002 transitioned from STOP_REQUESTED to COMPLETED via event C_COMPLETED
2016-01-14 17:08:24 Completed Dag: dag_1452791303962_0001_1
2016-01-14 17:08:24,650 INFO  app.DAGAppMaster (DAGAppMaster.java:handle(579)) - DAG completed, dagId=dag_1452791303962_0001_1, dagState=SUCCEEDED
2016-01-14 17:08:24,651 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: dag_1452791303962_0001_1_post
2016-01-14 17:08:24,651 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 17:08:24,651 INFO  app.DAGAppMaster (DAGAppMaster.java:handle(625)) - Waiting for next DAG to be submitted.
2016-01-14 17:08:24,657 INFO  client.TezClient (TezClient.java:stop(495)) - Shutting down Tez Session, sessionName=(1/1) ...stFlowStepStrategy/simple, applicationId=application_1452791303962_0001
2016-01-14 17:08:24,661 INFO  client.DAGClientHandler (DAGClientHandler.java:shutdownAM(117)) - Received message to shutdown AM
2016-01-14 17:08:24,661 INFO  rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:setShouldUnregisterFlag(580)) - TaskScheduler notified that it should unregister from RM
2016-01-14 17:08:24,661 INFO  app.DAGAppMaster (DAGAppMaster.java:shutdownTezAM(1088)) - No current running DAG, shutting down the AM
2016-01-14 17:08:24,661 INFO  app.DAGAppMaster (DAGAppMaster.java:shutdown(692)) - DAGAppMasterShutdownHandler invoked
2016-01-14 17:08:24,661 INFO  app.DAGAppMaster (DAGAppMaster.java:shutdown(701)) - Handling DAGAppMaster shutdown
2016-01-14 17:08:24,663 INFO  app.DAGAppMaster (DAGAppMaster.java:run(721)) - Sleeping for 5 seconds before shutting down
2016-01-14 17:08:24,663 INFO  history.HistoryEventHandler (HistoryEventHandler.java:serviceStop(79)) - Stopping HistoryEventHandler
2016-01-14 17:08:24,663 INFO  recovery.RecoveryService (RecoveryService.java:serviceStop(189)) - Stopping RecoveryService
2016-01-14 17:08:24,664 INFO  recovery.RecoveryService (RecoveryService.java:serviceStop(192)) - Handle the remaining events in queue, queue size=0
2016-01-14 17:08:24,664 INFO  recovery.RecoveryService (RecoveryService.java:run(166)) - EventQueue take interrupted. Returning
2016-01-14 17:08:24,665 INFO  recovery.RecoveryService (RecoveryService.java:serviceStop(214)) - Closing Summary Stream
2016-01-14 17:08:24,665 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStop(118)) - Stopping SimpleHistoryLoggingService, eventQueueBacklog=0
2016-01-14 17:08:24,666 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:run(105)) - EventQueue take interrupted. Returning
2016-01-14 17:08:24,673 INFO  app.DAGAppMaster (DAGAppMaster.java:run(1773)) - Completed deletion of tez scratch data dir, path=file:/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/3FF5F23BC43146E0984CE9835D6621EC/F0F48D52C0C74352AFD1058514FCC56B/.tez/application_1452791303962_0001
2016-01-14 17:08:24,674 INFO  flow.Flow (BaseFlow.java:logInfo(1433)) - [test]  completed in: 00:00.741
2016-01-14 17:08:24,714 INFO  cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/output//hadoop2-tez/flowstrategiesplatform/testFlowStepStrategy/simple

Standard error

2016-01-14 17:08:22 Running Dag: dag_1452791301026_0001_1
2016-01-14 17:08:22 Starting to run new task attempt: attempt_1452791301026_0001_1_00_000000_0
2016-01-14 17:08:22 Completed running task attempt: attempt_1452791301026_0001_1_00_000000_0
2016-01-14 17:08:22 Completed Dag: dag_1452791301026_0001_1
2016-01-14 17:08:23 Running Dag: dag_1452791303088_0001_1
2016-01-14 17:08:23 Starting to run new task attempt: attempt_1452791303088_0001_1_00_000000_0
2016-01-14 17:08:23 Completed running task attempt: attempt_1452791303088_0001_1_00_000000_0
2016-01-14 17:08:23 Completed Dag: dag_1452791303088_0001_1
2016-01-14 17:08:24 Running Dag: dag_1452791303962_0001_1
2016-01-14 17:08:24 Starting to run new task attempt: attempt_1452791303962_0001_1_00_000000_0
2016-01-14 17:08:24 Completed running task attempt: attempt_1452791303962_0001_1_00_000000_0
2016-01-14 17:08:24 Starting to run new task attempt: attempt_1452791303962_0001_1_01_000000_0
2016-01-14 17:08:24 Completed running task attempt: attempt_1452791303962_0001_1_01_000000_0
2016-01-14 17:08:24 Completed Dag: dag_1452791303962_0001_1