2016-05-18 01:58:46,447 INFO platform.PlatformRunner (PlatformRunner.java:getPlatformClassesFromClasspath(197)) - found 1 test platforms from classpath
2016-05-18 01:58:46,471 INFO platform.PlatformRunner (PlatformRunner.java:addPlatform(246)) - adding test: cascading.flow.FlowStrategiesPlatformTest, with platform: hadoop2-tez
2016-05-18 01:58:46,495 INFO tez.Hadoop2TezPlatform (Hadoop2TezPlatform.java:setUp(136)) - not using cluster
2016-05-18 01:58:47,135 WARN util.NativeCodeLoader (NativeCodeLoader.java:<clinit>(62)) - Unable to load native-hadoop library for your platform... using builtin-java classes where applicable
2016-05-18 01:58:47,504 INFO platform.TestPlatform (TestPlatform.java:getGlobalProperties(75)) - platform property overrides:
2016-05-18 01:58:47,771 INFO util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-18 01:58:47,773 INFO planner.Hadoop2TezPlanner (Hadoop2TezPlanner.java:initialize(151)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-tez/3.1.0/226af02e24d5195c60e4ebe911d0c7c9780f59f0/cascading-hadoop2-tez-3.1.0.jar
2016-05-18 01:58:47,875 INFO property.AppProps (AppProps.java:getAppID(177)) - using app.id: C66A3C773EAE441AB4C3767849841F51
2016-05-18 01:58:48,119 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.093
2016-05-18 01:58:48,132 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.106
2016-05-18 01:58:48,133 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] rule registry: NoHashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 1
2016-05-18 01:58:48,133 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] rule registry: HashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 1
2016-05-18 01:58:48,134 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] rule registry: NoHashJoinHadoop2TezRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-05-18 01:58:48,319 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache.10.txt
2016-05-18 01:58:48,325 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output/hadoop2-tez/flowstrategiesplatform/testSkipStrategiesReplace/replace
2016-05-18 01:58:48,505 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] at least one sink is marked for delete
2016-05-18 01:58:48,509 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] sink oldest modified date: Wed Dec 31 23:59:59 UTC 1969
2016-05-18 01:58:48,510 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] at least one sink is marked for delete
2016-05-18 01:58:48,510 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] sink oldest modified date: Wed Dec 31 23:59:59 UTC 1969
2016-05-18 01:58:48,541 INFO util.Version (Version.java:printBanner(82)) - Concurrent, Inc - Cascading 3.1.0
2016-05-18 01:58:48,542 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] starting
2016-05-18 01:58:48,543 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] source: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache.10.txt"]
2016-05-18 01:58:48,543 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] sink: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output/hadoop2-tez/flowstrategiesplatform/testSkipStrategiesReplace/replace"]
2016-05-18 01:58:48,544 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] parallel execution of steps is enabled: false
2016-05-18 01:58:48,544 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] executing total steps: 1
2016-05-18 01:58:48,544 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] allocating management threads: 1
2016-05-18 01:58:48,545 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] starting step: (1/1) ...StrategiesReplace/replace
2016-05-18 01:58:48,546 WARN flow.Flow (BaseFlow.java:logWarn(1516)) - [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-05-18 01:58:48,569 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] tez session mode enabled: true
2016-05-18 01:58:48,762 INFO client.TezClient (TezClient.java:<init>(174)) - Tez Client Version: [ component=tez-api, version=0.8.2, revision=2d46dcefa492a6957cfa972007039f7e188760ce, SCM-URL=scm:git:https://git-wip-us.apache.org/repos/asf/tez.git, buildTime=20160112-1834 ]
2016-05-18 01:58:48,772 INFO client.TezClient (TezClient.java:start(394)) - Session mode. Starting session.
2016-05-18 01:58:48,772 INFO client.TezClientUtils (TezClientUtils.java:setupTezJarsLocalResources(164)) - Ignoring 'tez.lib.uris' since 'tez.ignore.lib.uris' is set to true
2016-05-18 01:58:48,837 INFO client.TezClient (TezCommonUtils.java:createTezSystemStagingPath(122)) - Tez system stage directory file:/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/91A25304858B45908BE1086FB8BA5FAD/F8721E8789C54E30A4998B3BE25F3882/.tez/application_1463536728771_0001 doesn't exist and is created
2016-05-18 01:58:48,919 INFO client.LocalClient (LocalClient.java:createDAGAppMaster(332)) - DAGAppMaster thread has been created
2016-05-18 01:58:48,920 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-05-18 01:58:48,921 INFO client.LocalClient (LocalClient.java:run(282)) - Using working directory: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/91A25304858B45908BE1086FB8BA5FAD/F8721E8789C54E30A4998B3BE25F3882/.tez/application_1463536728771_0001_wd
2016-05-18 01:58:48,986 INFO app.DAGAppMaster (DAGAppMaster.java:<init>(363)) - Created DAGAppMaster for application appattempt_1463536728771_0001_000000, versionInfo=[ component=tez-dag, version=0.8.2, revision=2d46dcefa492a6957cfa972007039f7e188760ce, SCM-URL=scm:git:https://git-wip-us.apache.org/repos/asf/tez.git, buildTime=20160112-1834 ]
2016-05-18 01:58:49,000 INFO shim.HadoopShimsLoader (HadoopShimsLoader.java:<init>(80)) - Trying to locate HadoopShimProvider for hadoopVersion=2.7.2, majorVersion=2, minorVersion=7
2016-05-18 01:58:49,001 INFO shim.HadoopShimsLoader (HadoopShimsLoader.java:<init>(139)) - Picked HadoopShim org.apache.tez.hadoop.shim.DefaultHadoopShim, providerName=null, overrideProviderViaConfig=null, hadoopVersion=2.7.2, majorVersion=2, minorVersion=7
2016-05-18 01:58:49,012 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(436)) - AM Level configured TaskSchedulers: [0:TezUber:null]
2016-05-18 01:58:49,012 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(437)) - AM Level configured ContainerLaunchers: [0:TezUber:null]
2016-05-18 01:58:49,012 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(438)) - AM Level configured TaskCommunicators: [0:TezUber:null]
2016-05-18 01:58:49,012 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(447)) - Comparing client version with AM version, clientVersion=0.8.2, AMVersion=0.8.2
2016-05-18 01:58:49,020 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: NEW
2016-05-18 01:58:49,020 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(238)) - DAGAppMaster is not started wait for 100ms...
2016-05-18 01:58:49,020 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-05-18 01:58:49,035 INFO app.TaskCommunicatorManager (TaskCommunicatorManager.java:createUberTaskCommunicator(192)) - Creating Default Local Task Communicator
2016-05-18 01:58:49,059 INFO common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.rm.container.AMContainerEventType for class org.apache.tez.dag.app.rm.container.AMContainerMap
2016-05-18 01:58:49,060 INFO common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.rm.node.AMNodeEventType for class org.apache.tez.dag.app.rm.node.AMNodeTracker
2016-05-18 01:58:49,062 INFO common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.dag.event.DAGAppMasterEventType for class org.apache.tez.dag.app.DAGAppMaster$DAGAppMasterEventHandler
2016-05-18 01:58:49,063 INFO common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.dag.event.DAGEventType for class org.apache.tez.dag.app.DAGAppMaster$DagEventDispatcher
2016-05-18 01:58:49,063 INFO common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.dag.event.VertexEventType for class org.apache.tez.dag.app.DAGAppMaster$VertexEventDispatcher
2016-05-18 01:58:49,063 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(529)) - Using concurrent dispatcher: false
2016-05-18 01:58:49,064 INFO common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.dag.event.TaskEventType for class org.apache.tez.dag.app.DAGAppMaster$TaskEventDispatcher
2016-05-18 01:58:49,065 INFO common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.dag.event.TaskAttemptEventType for class org.apache.tez.dag.app.DAGAppMaster$TaskAttemptEventDispatcher
2016-05-18 01:58:49,066 INFO common.AsyncDispatcher (AsyncDispatcher.java:registerAndCreateDispatcher(262)) - Registering class org.apache.tez.dag.app.dag.event.SpeculatorEventType for independent dispatch using: class org.apache.tez.dag.app.DAGAppMaster$SpeculatorEventHandler
2016-05-18 01:58:49,066 INFO common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.dag.event.SpeculatorEventType for class org.apache.tez.dag.app.DAGAppMaster$SpeculatorEventHandler
2016-05-18 01:58:49,075 INFO common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.rm.AMSchedulerEventType for class org.apache.tez.dag.app.rm.TaskSchedulerManager
2016-05-18 01:58:49,079 INFO launcher.TezContainerLauncherImpl (ContainerLauncherManager.java:createUberContainerLauncher(134)) - Creating LocalContainerLauncher
2016-05-18 01:58:49,098 INFO common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.rm.ContainerLauncherEventType for class org.apache.tez.dag.app.launcher.ContainerLauncherManager
2016-05-18 01:58:49,101 INFO node.AMNodeTracker (AMNodeTracker.java:serviceInit(78)) - blacklistDisablePercent is 33, blacklistingEnabled: false, maxTaskFailuresPerNode: 1, nodeUpdatesRescheduleEnabled: false
2016-05-18 01:58:49,101 INFO history.HistoryEventHandler (HistoryEventHandler.java:serviceInit(57)) - Initializing HistoryEventHandler withrecoveryEnabled=true, historyServiceClassName=org.apache.tez.dag.history.logging.impl.SimpleHistoryLoggingService
2016-05-18 01:58:49,105 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceInit(66)) - Log file location for SimpleHistoryLoggingService not specified, defaulting to containerLogDir=/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/91A25304858B45908BE1086FB8BA5FAD/F8721E8789C54E30A4998B3BE25F3882/.tez/application_1463536728771_0001_wd/localmode-log-dir
2016-05-18 01:58:49,105 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceInit(88)) - Initializing SimpleHistoryLoggingService, logFileLocation=/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/91A25304858B45908BE1086FB8BA5FAD/F8721E8789C54E30A4998B3BE25F3882/.tez/application_1463536728771_0001_wd/localmode-log-dir/history.txt.appattempt_1463536728771_0001_000000, maxErrors=10
2016-05-18 01:58:49,106 INFO recovery.RecoveryService (RecoveryService.java:serviceInit(124)) - RecoveryService initialized with recoveryPath=file:/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/91A25304858B45908BE1086FB8BA5FAD/F8721E8789C54E30A4998B3BE25F3882/.tez/application_1463536728771_0001/recovery/0, bufferSize(bytes)=8192, flushInterval(s)=30, maxUnflushedEvents=100
2016-05-18 01:58:49,107 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:N/A][Event:AM_LAUNCHED]: appAttemptId=appattempt_1463536728771_0001_000000, appSubmitTime=1463536728967, launchTime=1463536728984
2016-05-18 01:58:49,113 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStart(95)) - Starting SimpleHistoryLoggingService
2016-05-18 01:58:49,121 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: INITED
2016-05-18 01:58:49,121 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(240)) - DAGAppMaster is not startetd wait for 100ms...
2016-05-18 01:58:49,121 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-05-18 01:58:49,176 INFO client.DAGClientServer (DAGClientServer.java:serviceStart(91)) - Instantiated DAGClientRPCServer at ip-10-123-148-208.ec2.internal/10.123.148.208:39682
2016-05-18 01:58:49,178 INFO rm.TaskSchedulerManager (TaskSchedulerManager.java:createUberTaskScheduler(557)) - Creating TaskScheduler: Local TaskScheduler with clusterIdentifier=1463536728771
2016-05-18 01:58:49,199 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:N/A][Event:AM_STARTED]: appAttemptId=appattempt_1463536728771_0001_000000, startTime=1463536729198
2016-05-18 01:58:49,199 INFO app.DAGAppMaster (DAGAppMaster.java:serviceStart(1945)) - In Session mode. Waiting for DAG over RPC
2016-05-18 01:58:49,221 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: IDLE
2016-05-18 01:58:49,241 INFO client.TezClient (TezClient.java:start(428)) - The url to track the Tez Session: N/A
2016-05-18 01:58:49,242 INFO client.TezClient (TezClient.java:submitDAGSession(470)) - Submitting dag to TezSession, sessionName=(1/1) ...StrategiesReplace/replace, applicationId=application_1463536728771_0001, dagName=[91A25304858B45908BE1086FB8BA5FAD/F8721E8789C54E30A4998B3BE25F3882] test/(1/1) ...StrategiesReplace/replace
2016-05-18 01:58:49,474 INFO app.DAGAppMaster (DAGAppMaster.java:submitDAGToAppMaster(1351)) - Starting DAG submitted via RPC: [91A25304858B45908BE1086FB8BA5FAD/F8721E8789C54E30A4998B3BE25F3882] test/(1/1) ...StrategiesReplace/replace
2016-05-18 01:58:49,484 INFO app.DAGAppMaster (DAGAppMaster.java:createDAG(985)) - Merging AM credentials into DAG credentials
2016-05-18 01:58:49,547 INFO app.DAGAppMaster (DAGAppMaster.java:generateDAGVizFile(1076)) - Generating DAG graphviz file, dagId=dag_1463536728771_0001_1, filePath=/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/91A25304858B45908BE1086FB8BA5FAD/F8721E8789C54E30A4998B3BE25F3882/.tez/application_1463536728771_0001_wd/localmode-log-dir/dag_1463536728771_0001_1.dot
2016-05-18 01:58:49,553 INFO app.DAGAppMaster (DAGAppMaster.java:writePBTextFile(1093)) - Writing DAG plan to: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/91A25304858B45908BE1086FB8BA5FAD/F8721E8789C54E30A4998B3BE25F3882/.tez/application_1463536728771_0001_wd/localmode-log-dir/dag_1463536728771_0001_1-tez-dag.pb.txt
2016-05-18 01:58:49,595 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend: dag_1463536728771_0001_1
2016-05-18 01:58:49,596 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 01:58:49,596 INFO app.DAGAppMaster (DAGAppMaster.java:startDAG(2399)) - Running DAG: [91A25304858B45908BE1086FB8BA5FAD/F8721E8789C54E30A4998B3BE25F3882] test/(1/1) ...StrategiesReplace/replace
2016-05-18 01:58:49 Running Dag: dag_1463536728771_0001_1
2016-05-18 01:58:49,629 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536728771_0001_1][Event:DAG_SUBMITTED]: dagID=dag_1463536728771_0001_1, submitTime=1463536729475
2016-05-18 01:58:49,681 INFO impl.VertexImpl (VertexImpl.java:<init>(928)) - Default container context for vertex_1463536728771_0001_1_00 [D444857D8A2F4A0AA50707FBA05FE775]=LocalResources: [[ name=tez-conf.pb, value=resource { scheme: "file" port: -1 file: "/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/91A25304858B45908BE1086FB8BA5FAD/F8721E8789C54E30A4998B3BE25F3882/.tez/application_1463536728771_0001/tez-conf.pb" } size: 40950 timestamp: 1463536728000 type: FILE visibility: APPLICATION],], environment: [[ CLASSPATH=$PWD/cascading-hadoop2-tez-3.1.0.jar/:$PWD/cascading-hadoop2-tez-3.1.0.jar/classes/:$PWD/cascading-hadoop2-tez-3.1.0.jar/lib/*::$PWD:$PWD/*:$HADOOP_CONF_DIR: ],[ LD_LIBRARY_PATH=$PWD:$PWD:$HADOOP_COMMON_HOME/lib/native/ ],], credentials(token kinds): [tez.job,], javaOpts: -server -Djava.net.preferIPv4Stack=true -Dhadoop.metrics.log.level=WARN -XX:+PrintGCDetails -verbose:gc -XX:+PrintGCTimeStamps -XX:+UseNUMA -XX:+UseParallelGC -Dlog4j.configuratorClass=org.apache.tez.common.TezLog4jConfigurator -Dlog4j.configuration=tez-container-log4j.properties -Dyarn.app.container.log.dir=<LOG_DIR> -Dtez.root.logger=INFO,CLA, vertex: vertex_1463536728771_0001_1_00 [D444857D8A2F4A0AA50707FBA05FE775], Default Resources=<memory:1024, vCores:1>
2016-05-18 01:58:49,682 INFO impl.VertexImpl (VertexImpl.java:setAdditionalInputs(3978)) - Setting 1 additional inputs for vertexvertex_1463536728771_0001_1_00 [D444857D8A2F4A0AA50707FBA05FE775]
2016-05-18 01:58:49,682 INFO impl.VertexImpl (VertexImpl.java:setAdditionalOutputs(4023)) - Setting 1 additional outputs for vertex vertex_1463536728771_0001_1_00 [D444857D8A2F4A0AA50707FBA05FE775]
2016-05-18 01:58:49,683 INFO impl.VertexImpl (VertexImpl.java:<init>(1016)) - Running vertex: vertex_1463536728771_0001_1_00 [D444857D8A2F4A0AA50707FBA05FE775] : TaskScheduler=0:TezUber, ContainerLauncher=0:TezUber, TaskCommunicator=0:TezUber
2016-05-18 01:58:49,684 INFO impl.DAGImpl (DAGImpl.java:assignDAGScheduler(1593)) - Using DAG Scheduler: org.apache.tez.dag.app.dag.impl.DAGSchedulerNaturalOrderControlled
2016-05-18 01:58:49,688 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536728771_0001_1][Event:DAG_INITIALIZED]: dagID=dag_1463536728771_0001_1, initTime=1463536729687
2016-05-18 01:58:49,689 INFO impl.DAGImpl (DAGImpl.java:handle(1170)) - dag_1463536728771_0001_1 transitioned from NEW to INITED due to event DAG_INIT
2016-05-18 01:58:49,690 INFO impl.DAGImpl (DAGImpl.java:transition(1768)) - Added additional resources : [[]] to classpath
2016-05-18 01:58:49,693 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536728771_0001_1][Event:DAG_STARTED]: dagID=dag_1463536728771_0001_1, startTime=1463536729693
2016-05-18 01:58:49,693 INFO impl.DAGImpl (DAGImpl.java:handle(1170)) - dag_1463536728771_0001_1 transitioned from INITED to RUNNING due to event DAG_START
2016-05-18 01:58:49,694 INFO impl.VertexImpl (VertexImpl.java:setupVertex(2400)) - Root Inputs exist for Vertex: D444857D8A2F4A0AA50707FBA05FE775 : {D13653B5B4974D898431F6F68277ACB2={InputName=D13653B5B4974D898431F6F68277ACB2}, {Descriptor=ClassName=org.apache.tez.mapreduce.input.MRInput, hasPayload=true}, {ControllerDescriptor=ClassName=org.apache.tez.mapreduce.common.MRInputAMSplitGenerator, hasPayload=false}}
2016-05-18 01:58:49,694 INFO impl.VertexImpl (VertexImpl.java:setupVertex(2410)) - Starting root input initializer for input: D13653B5B4974D898431F6F68277ACB2, with class: [org.apache.tez.mapreduce.common.MRInputAMSplitGenerator]
2016-05-18 01:58:49,694 INFO impl.VertexImpl (VertexImpl.java:assignVertexManager(2550)) - Setting vertexManager to RootInputVertexManager for vertex_1463536728771_0001_1_00 [D444857D8A2F4A0AA50707FBA05FE775]
2016-05-18 01:58:49,703 INFO client.TezClient (TezClient.java:submitDAGSession(545)) - Submitted dag to TezSession, sessionName=(1/1) ...StrategiesReplace/replace, applicationId=application_1463536728771_0001, dagName=[91A25304858B45908BE1086FB8BA5FAD/F8721E8789C54E30A4998B3BE25F3882] test/(1/1) ...StrategiesReplace/replace
2016-05-18 01:58:49,705 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(2721)) - Num tasks is -1. Expecting VertexManager/InputInitializers/1-1 split to set #tasks for the vertex vertex_1463536728771_0001_1_00 [D444857D8A2F4A0AA50707FBA05FE775]
2016-05-18 01:58:49,706 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(2726)) - Vertex will initialize from input initializer. vertex_1463536728771_0001_1_00 [D444857D8A2F4A0AA50707FBA05FE775]
2016-05-18 01:58:49,708 INFO impl.VertexImpl (VertexImpl.java:setupInputInitializerManager(3893)) - Starting 1 inputInitializers for vertex vertex_1463536728771_0001_1_00 [D444857D8A2F4A0AA50707FBA05FE775]
2016-05-18 01:58:49,716 INFO dag.RootInputInitializerManager (RootInputInitializerManager.java:run(272)) - Starting InputInitializer for Input: D13653B5B4974D898431F6F68277ACB2 on vertex vertex_1463536728771_0001_1_00 [D444857D8A2F4A0AA50707FBA05FE775]
2016-05-18 01:58:49,731 INFO impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463536728771_0001_1_00 [D444857D8A2F4A0AA50707FBA05FE775] transitioned from NEW to INITIALIZING due to event V_INIT
2016-05-18 01:58:49,746 INFO common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(109)) - Input D13653B5B4974D898431F6F68277ACB2 asking for 1 tasks. Headroom: 672 Task Resource: 1024 waves: 1.7, groupingEnabled: true
2016-05-18 01:58:49,748 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] submitted tez dag to app master: application_1463536728771_0001, with dag id: dag_1463536728771_0001_1
2016-05-18 01:58:49,825 INFO grouper.TezSplitGrouper (TezSplitGrouper.java:getGroupedSplits(168)) - Grouping splits in Tez
2016-05-18 01:58:49,825 INFO grouper.TezSplitGrouper (TezSplitGrouper.java:getGroupedSplits(226)) - Desired splits: 1 too large. Desired splitLength: 1449 Min splitLength: 52428800 New desired splits: 1 Total length: 1449 Original splits: 2
2016-05-18 01:58:49,826 INFO grouper.TezSplitGrouper (TezSplitGrouper.java:getGroupedSplits(321)) - Desired numSplits: 1 lengthPerGroup: 1449 numLocations: 1 numSplitsPerLocation: 2 numSplitsInGroup: 2 totalLength: 1449 numOriginalSplits: 2 . Grouping by length: true count: false nodeLocalOnly: false
2016-05-18 01:58:49,827 INFO grouper.TezSplitGrouper (TezSplitGrouper.java:getGroupedSplits(539)) - Number of splits desired: 1 created: 1 splitsProcessed: 2
2016-05-18 01:58:49,838 INFO dag.RootInputInitializerManager (RootInputInitializerManager.java:onSuccess(308)) - Succeeded InputInitializer for Input: D13653B5B4974D898431F6F68277ACB2 on vertex vertex_1463536728771_0001_1_00 [D444857D8A2F4A0AA50707FBA05FE775]
2016-05-18 01:58:49,841 INFO impl.VertexImpl (VertexImpl.java:canInitVertex(2972)) - Cannot init vertex: vertex_1463536728771_0001_1_00 [D444857D8A2F4A0AA50707FBA05FE775] numTasks: -1 numUnitializedEdges: 0 numInitializedInputs: 1 initWaitsForRootInitializers: true
2016-05-18 01:58:49,841 INFO impl.VertexImpl (VertexImpl.java:setParallelismWrapper(1644)) - Got updated RootInputsSpecs: {D13653B5B4974D898431F6F68277ACB2=forAllWorkUnits=true, update=[1]}
2016-05-18 01:58:49,853 INFO impl.VertexImpl (VertexImpl.java:setParallelismWrapper(1664)) - Vertex vertex_1463536728771_0001_1_00 [D444857D8A2F4A0AA50707FBA05FE775] parallelism set to 1
2016-05-18 01:58:49,853 INFO impl.VertexImpl (VertexImpl.java:canInitVertex(2972)) - Cannot init vertex: vertex_1463536728771_0001_1_00 [D444857D8A2F4A0AA50707FBA05FE775] numTasks: 1 numUnitializedEdges: 0 numInitializedInputs: 1 initWaitsForRootInitializers: true
2016-05-18 01:58:49,861 INFO impl.VertexImpl (VertexImpl.java:initializeCommitters(2187)) - Setting up committers for vertex vertex_1463536728771_0001_1_00 [D444857D8A2F4A0AA50707FBA05FE775], numAdditionalOutputs=1
2016-05-18 01:58:49,861 INFO impl.VertexImpl (VertexImpl.java:initializeCommitters(2202)) - Instantiating committer for output=6E9F78DC240F4000B1EFE1F473A34613, vertex=vertex_1463536728771_0001_1_00 [D444857D8A2F4A0AA50707FBA05FE775], committerClass=org.apache.tez.mapreduce.committer.MROutputCommitter
2016-05-18 01:58:49,872 INFO committer.MROutputCommitter (MROutputCommitter.java:getOutputCommitter(121)) - Committer for D444857D8A2F4A0AA50707FBA05FE775:6E9F78DC240F4000B1EFE1F473A34613 using oldmapred API
2016-05-18 01:58:49,873 INFO committer.MROutputCommitter (MROutputCommitter.java:getOutputCommitter(146)) - OutputCommitter for outputName=6E9F78DC240F4000B1EFE1F473A34613, vertexName=D444857D8A2F4A0AA50707FBA05FE775, outputCommitterClass=org.apache.hadoop.mapred.FileOutputCommitter
2016-05-18 01:58:49,884 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536728771_0001_1][Event:VERTEX_INITIALIZED]: vertexName=D444857D8A2F4A0AA50707FBA05FE775, vertexId=vertex_1463536728771_0001_1_00, initRequestedTime=1463536729694, initedTime=1463536729861, numTasks=1, processorName=cascading.flow.tez.FlowProcessor, additionalInputsCount=1, initGeneratedEventsCount=1
2016-05-18 01:58:49,884 INFO impl.VertexImpl (VertexImpl.java:startIfPossible(2814)) - Triggering start event for vertex: vertex_1463536728771_0001_1_00 [D444857D8A2F4A0AA50707FBA05FE775] with distanceFromRoot: 0
2016-05-18 01:58:49,884 INFO impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463536728771_0001_1_00 [D444857D8A2F4A0AA50707FBA05FE775] transitioned from INITIALIZING to INITED due to event V_INPUT_DATA_INFORMATION
2016-05-18 01:58:49,886 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536728771_0001_1][Event:VERTEX_STARTED]: vertexId=vertex_1463536728771_0001_1_00, startRequestedTime=1463536729731, startedTime=1463536729885
2016-05-18 01:58:49,889 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536728771_0001_1][Event:VERTEX_CONFIGURE_DONE]: vertexId=vertex_1463536728771_0001_1_00, reconfigureDoneTime=0, numTasks=1, vertexLocationHint=org.apache.tez.dag.api.VertexLocationHint@b8338fe7, edgeManagersCount=0, rootInputSpecUpdateCount=1, setParallelismCalledFlag=true
2016-05-18 01:58:49,889 INFO impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463536728771_0001_1_00 [D444857D8A2F4A0AA50707FBA05FE775] transitioned from INITED to RUNNING due to event V_START
2016-05-18 01:58:49,891 INFO impl.ImmediateStartVertexManager (ImmediateStartVertexManager.java:scheduleTasks(100)) - Starting 1 in D444857D8A2F4A0AA50707FBA05FE775
2016-05-18 01:58:49,891 INFO impl.VertexImpl (VertexImpl.java:unsetTasksNotYetScheduled(1466)) - Routing pending task events for vertex: vertex_1463536728771_0001_1_00 [D444857D8A2F4A0AA50707FBA05FE775]
2016-05-18 01:58:49,897 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536728771_0001_1][Event:TASK_STARTED]: vertexName=D444857D8A2F4A0AA50707FBA05FE775, taskId=task_1463536728771_0001_1_00_000000, scheduledTime=1463536729896, launchTime=1463536729896
2016-05-18 01:58:49,917 INFO impl.DAGSchedulerNaturalOrderControlled (DAGSchedulerNaturalOrderControlled.java:scheduleTaskEx(106)) - Scheduled vertex: vertex_1463536728771_0001_1_00 [D444857D8A2F4A0AA50707FBA05FE775]
2016-05-18 01:58:49,959 INFO node.PerSourceNodeTracker (PerSourceNodeTracker.java:nodeSeen(74)) - Adding new node 127.0.0.1:0 to nodeTracker 0
2016-05-18 01:58:49,976 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:N/A][Event:CONTAINER_LAUNCHED]: containerId=container_1463536728771_0001_00_000001, launchTime=1463536729975
2016-05-18 01:58:49,983 INFO task.ContainerReporter (ContainerReporter.java:callInternal(57)) - Attempting to fetch new task for container container_1463536728771_0001_00_000001
2016-05-18 01:58:49,989 INFO task.ContainerReporter (ContainerReporter.java:callInternal(67)) - Got TaskUpdate for containerId= container_1463536728771_0001_00_000001: 0 ms after starting to poll. TaskInfo: shouldDie: false, currentTaskAttemptId: attempt_1463536728771_0001_1_00_000000_0
2016-05-18 01:58:49,989 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1322)) - TaskAttempt: [attempt_1463536728771_0001_1_00_000000_0] started. Is using containerId: [container_1463536728771_0001_00_000001] on NM: [127.0.0.1:0]
2016-05-18 01:58:49 Starting to run new task attempt: attempt_1463536728771_0001_1_00_000000_0
2016-05-18 01:58:49,990 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend: attempt_1463536728771_0001_1_00_000000_0
2016-05-18 01:58:49,990 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 01:58:49,991 INFO task.TezChild (TezChild.java:handleNewTaskCredentials(306)) - Refreshing UGI since Credentials have changed. Credentials : #Tokens=1, #SecretKeys=0
2016-05-18 01:58:49,992 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536728771_0001_1][Event:TASK_ATTEMPT_STARTED]: vertexName=D444857D8A2F4A0AA50707FBA05FE775, taskAttemptId=attempt_1463536728771_0001_1_00_000000_0, startTime=1463536729987, containerId=container_1463536728771_0001_00_000001, nodeId=127.0.0.1:0
2016-05-18 01:58:49,993 INFO counters.Limits (Limits.java:ensureInitialized(60)) - Counter limits initialized with parameters: GROUP_NAME_MAX=256, MAX_GROUPS=500, COUNTER_NAME_MAX=64, MAX_COUNTERS=1200
2016-05-18 01:58:50,005 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:<init>(166)) - Initializing LogicalIOProcessorRuntimeTask with TaskSpec: DAGName : [91A25304858B45908BE1086FB8BA5FAD/F8721E8789C54E30A4998B3BE25F3882] test/(1/1) ...StrategiesReplace/replace, VertexName: D444857D8A2F4A0AA50707FBA05FE775, VertexParallelism: 1, TaskAttemptID:attempt_1463536728771_0001_1_00_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=D13653B5B4974D898431F6F68277ACB2, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=6E9F78DC240F4000B1EFE1F473A34613, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }}, ]
2016-05-18 01:58:50,007 INFO resources.MemoryDistributor (MemoryDistributor.java:<init>(93)) - InitialMemoryDistributor (isEnabled=true) invoked with: numInputs=1, numOutputs=1, JVM.maxFree=704643072, allocatorClassName=org.apache.tez.runtime.library.resources.WeightedScalingMemoryDistributor
2016-05-18 01:58:50,012 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:run(65)) - Initializing task, taskAttemptId=attempt_1463536728771_0001_1_00_000000_0
2016-05-18 01:58:50,017 INFO impl.TaskImpl (TaskImpl.java:getTaskAttemptTezEvents(496)) - TaskAttempt:attempt_1463536728771_0001_1_00_000000_0 sent events: (0-1).
2016-05-18 01:58:50,018 INFO task.TaskReporter (TaskReporter.java:heartbeat(292)) - Routing events from heartbeat response to task, currentTaskAttemptId=attempt_1463536728771_0001_1_00_000000_0, eventCount=1 fromEventId=0 nextFromEventId=0
2016-05-18 01:58:50,040 INFO tez.FlowProcessor (FlowProcessor.java:initialize(88)) - cascading version: 3.1.0
2016-05-18 01:58:50,045 INFO input.MRInput (MRInput.java:initialize(440)) - D13653B5B4974D898431F6F68277ACB2 using newmapreduce API=false, split via event=true, numPhysicalInputs=1
2016-05-18 01:58:50,048 INFO input.MRInput (MRInput.java:initializeInternal(494)) - Initialized MRInput: D13653B5B4974D898431F6F68277ACB2
2016-05-18 01:58:50,063 INFO tez.FlowProcessor (FlowProcessor.java:initialize(94)) - flow node id: D444857D8A2F4A0AA50707FBA05FE775, ordinal: 0
2016-05-18 01:58:50,064 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: D444857D8A2F4A0AA50707FBA05FE775, mem on start (mb), free: 235, total: 281, max: 672
2016-05-18 01:58:50,064 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(562)) - Initialized processor
2016-05-18 01:58:50,064 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(239)) - Waiting for 2 initializers to finish
2016-05-18 01:58:50,065 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(239)) - Waiting for 1 initializers to finish
2016-05-18 01:58:50,066 INFO output.MROutput (MROutput.java:initialize(421)) - 6E9F78DC240F4000B1EFE1F473A34613: outputFormat=org.apache.hadoop.mapred.TextOutputFormat, using newmapreduce API=false
2016-05-18 01:58:50,066 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(252)) - All initializers finished
2016-05-18 01:58:50,066 INFO resources.MemoryDistributor (MemoryDistributor.java:logInitialRequests(275)) - InitialRequests=[6E9F78DC240F4000B1EFE1F473A34613:OUTPUT:0:org.apache.tez.mapreduce.output.MROutput], [D13653B5B4974D898431F6F68277ACB2:INPUT:0:org.apache.tez.mapreduce.input.MRInput]
2016-05-18 01:58:50,070 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:populateTypeScaleMap(239)) - ScaleRatiosUsed=[PARTITIONED_UNSORTED_OUTPUT:1][UNSORTED_OUTPUT:1][UNSORTED_INPUT:1][SORTED_OUTPUT:12][SORTED_MERGED_INPUT:12][PROCESSOR:1][OTHER:1]
2016-05-18 01:58:50,074 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:computeReservedFraction(266)) - InitialReservationFraction=0.3, AdditionalReservationFractionForIOs=0.03, finalReserveFractionUsed=0.32999999999999996
2016-05-18 01:58:50,074 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-05-18 01:58:50,075 INFO resources.MemoryDistributor (MemoryDistributor.java:logFinalAllocations(297)) - Allocations=[6E9F78DC240F4000B1EFE1F473A34613:org.apache.tez.mapreduce.output.MROutput:OUTPUT:0:0], [D13653B5B4974D898431F6F68277ACB2:org.apache.tez.mapreduce.input.MRInput:INPUT:0:0]
2016-05-18 01:58:50,075 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(274)) - Starting Inputs/Outputs
2016-05-18 01:58:50,077 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(287)) - Input: D13653B5B4974D898431F6F68277ACB2 being auto started by the framework. Subsequent instances will not be auto-started
2016-05-18 01:58:50,077 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:_callInternal(474)) - Started Input with src edge: D13653B5B4974D898431F6F68277ACB2
2016-05-18 01:58:50,077 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(308)) - Num IOs determined for AutoStart: 1
2016-05-18 01:58:50,077 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(310)) - Waiting for 1 IOs to start
2016-05-18 01:58:50,078 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(323)) - AutoStartComplete
2016-05-18 01:58:50,080 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:run(70)) - Running task, taskAttemptId=attempt_1463536728771_0001_1_00_000000_0
2016-05-18 01:58:50,104 INFO lib.MRReaderMapred (MRReaderMapred.java:setIncrementalConfigParams(174)) - Processing split: TezGroupedSplit{wrappedSplits=[file:/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache.10.txt:0+724, file:/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache.10.txt:724+725], wrappedInputFormatName='org.apache.hadoop.mapred.TextInputFormat', locations=[localhost], rack='null', length=1449}
2016-05-18 01:58:50,105 INFO input.MRInput (MRInput.java:initFromEventInternal(653)) - D13653B5B4974D898431F6F68277ACB2 initialized RecordReader from event
2016-05-18 01:58:50,126 INFO graph.Hadoop2TezStreamGraph (Hadoop2TezStreamGraph.java:buildGraph(151)) - using streamed source: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache.10.txt"]
2016-05-18 01:58:50,154 INFO tez.FlowProcessor (FlowProcessor.java:run(121)) - sourcing from: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache.10.txt"] streamed: true, id: D13653B5B4974D898431F6F68277ACB2
2016-05-18 01:58:50,154 INFO tez.FlowProcessor (FlowProcessor.java:run(124)) - sinking to: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output/hadoop2-tez/flowstrategiesplatform/testSkipStrategiesReplace/replace"], id: 6E9F78DC240F4000B1EFE1F473A34613
2016-05-18 01:58:50,155 INFO element.TezSinkStage (TezSinkStage.java:prepare(57)) - calling MROutput#start() on: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output/hadoop2-tez/flowstrategiesplatform/testSkipStrategiesReplace/replace"]
2016-05-18 01:58:50,158 INFO element.TezSourceStage (TezSourceStage.java:prepare(63)) - calling MRInput#start() on: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache.10.txt"]
2016-05-18 01:58:50,159 INFO tez.FlowProcessor (FlowProcessor.java:waitForInputsReady(202)) - flow node id: D444857D8A2F4A0AA50707FBA05FE775, all 1 inputs ready in: 00:00:00.001
2016-05-18 01:58:50,167 INFO output.MROutput (MROutput.java:close(526)) - 6E9F78DC240F4000B1EFE1F473A34613 closed
2016-05-18 01:58:50,169 INFO impl.TaskImpl (TaskImpl.java:canCommit(671)) - attempt_1463536728771_0001_1_00_000000_0 given a go for committing the task output.
2016-05-18 01:58:50,170 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:run(79)) - Closing task, taskAttemptId=attempt_1463536728771_0001_1_00_000000_0
2016-05-18 01:58:50,170 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: D444857D8A2F4A0AA50707FBA05FE775, mem on close (mb), free: 228, total: 281, max: 672
2016-05-18 01:58:50,171 INFO output.MROutput (MROutput.java:close(526)) - 6E9F78DC240F4000B1EFE1F473A34613 closed
2016-05-18 01:58:50,172 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:close(387)) - Joining on EventRouter
2016-05-18 01:58:50 Completed running task attempt: attempt_1463536728771_0001_1_00_000000_0
2016-05-18 01:58:50,172 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:run(86)) - Task completed, taskAttemptId=attempt_1463536728771_0001_1_00_000000_0, askedToStop=false
2016-05-18 01:58:50,173 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:callInternal(104)) - Cleaning up task attempt_1463536728771_0001_1_00_000000_0, stopRequested=false
2016-05-18 01:58:50,176 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:cleanup(813)) - Final Counters for attempt_1463536728771_0001_1_00_000000_0: Counters: 11 [[org.apache.tez.common.counters.TaskCounter INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=10][cascading.flow.SliceCounters Process_Begin_Time=1463536730159, Process_Duration=11, Process_End_Time=1463536730170, Read_Duration=2, Tuples_Read=10, Tuples_Written=10, Write_Duration=0][cascading.flow.StepCounters Tuples_Read=10, Tuples_Written=10]]
2016-05-18 01:58:50,181 INFO task.TezTaskRunner2 (TezTaskRunner2.java:logAndReturnEndResult(473)) - TaskRunnerResult for attempt_1463536728771_0001_1_00_000000_0 : TaskRunner2Result{endReason=SUCCESS, error=null, containerShutdownRequested=false}
2016-05-18 01:58:50,182 INFO task.TezChild (TezChild.java:run(265)) - TaskRunner2Result: TaskRunner2Result{endReason=SUCCESS, error=null, containerShutdownRequested=false}
2016-05-18 01:58:50,183 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend:
2016-05-18 01:58:50,183 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 01:58:50,183 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536728771_0001_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=D444857D8A2F4A0AA50707FBA05FE775, taskAttemptId=attempt_1463536728771_0001_1_00_000000_0, creationTime=1463536729912, allocationTime=1463536729967, startTime=1463536729987, finishTime=1463536730181, timeTaken=194, status=SUCCEEDED, errorEnum=, diagnostics=
2016-05-18 01:58:50,184 INFO task.ContainerReporter (ContainerReporter.java:callInternal(57)) - Attempting to fetch new task for container container_1463536728771_0001_00_000001
2016-05-18 01:58:50,193 INFO impl.TaskImpl (TaskImpl.java:transition(1057)) - Task succeeded with attempt attempt_1463536728771_0001_1_00_000000_0
2016-05-18 01:58:50,197 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536728771_0001_1][Event:TASK_FINISHED]: vertexName=D444857D8A2F4A0AA50707FBA05FE775, taskId=task_1463536728771_0001_1_00_000000, startTime=1463536729987, finishTime=1463536730195, timeTaken=208, status=SUCCEEDED, successfulAttemptID=attempt_1463536728771_0001_1_00_000000_0, diagnostics=, counters=Counters: 12, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, org.apache.tez.common.counters.TaskCounter, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=10, cascading.flow.SliceCounters, Process_Begin_Time=1463536730159, Process_Duration=11, Process_End_Time=1463536730170, Read_Duration=2, Tuples_Read=10, Tuples_Written=10, Write_Duration=0, cascading.flow.StepCounters, Tuples_Read=10, Tuples_Written=10
2016-05-18 01:58:50,207 INFO impl.VertexImpl (VertexImpl.java:checkTasksForCompletion(2024)) - Task Completion: vertex_1463536728771_0001_1_00 [D444857D8A2F4A0AA50707FBA05FE775], tasks=1, failed=0, killed=0, success=1, completed=1, commits=0, err=null
2016-05-18 01:58:50,208 INFO impl.VertexImpl (VertexImpl.java:checkTasksForCompletion(2037)) - All tasks have succeeded, vertex:vertex_1463536728771_0001_1_00 [D444857D8A2F4A0AA50707FBA05FE775]
2016-05-18 01:58:50,222 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536728771_0001_1][Event:VERTEX_FINISHED]: vertexName=D444857D8A2F4A0AA50707FBA05FE775, vertexId=vertex_1463536728771_0001_1_00, initRequestedTime=1463536729694, initedTime=1463536729861, startRequestedTime=1463536729731, startedTime=1463536729885, finishTime=1463536730208, timeTaken=323, status=SUCCEEDED, diagnostics=, counters=Counters: 12, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, org.apache.tez.common.counters.TaskCounter, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=10, cascading.flow.SliceCounters, Process_Begin_Time=1463536730159, Process_Duration=11, Process_End_Time=1463536730170, Read_Duration=2, Tuples_Read=10, Tuples_Written=10, Write_Duration=0, cascading.flow.StepCounters, Tuples_Read=10, Tuples_Written=10, vertexStats=firstTaskStartTime=1463536729987, firstTasksToStart=[ task_1463536728771_0001_1_00_000000 ], lastTaskFinishTime=1463536730181, lastTasksToFinish=[ task_1463536728771_0001_1_00_000000 ], minTaskDuration=194, maxTaskDuration=194, avgTaskDuration=194.0, numSuccessfulTasks=1, shortestDurationTasks=[ task_1463536728771_0001_1_00_000000 ], longestDurationTasks=[ task_1463536728771_0001_1_00_000000 ], vertexTaskStats={numFailedTasks=0, numSucceededTasks=1, numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0, numCompletedTasks=1}
2016-05-18 01:58:50,223 INFO impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463536728771_0001_1_00 [D444857D8A2F4A0AA50707FBA05FE775] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2016-05-18 01:58:50,225 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536728771_0001_1][Event:CONTAINER_STOPPED]: containerId=container_1463536728771_0001_00_000001, stoppedTime=1463536730224, exitStatus=0
2016-05-18 01:58:50,226 INFO impl.DAGImpl (DAGImpl.java:transition(1927)) - Vertex vertex_1463536728771_0001_1_00 [D444857D8A2F4A0AA50707FBA05FE775] completed., numCompletedVertices=1, numSuccessfulVertices=1, numFailedVertices=0, numKilledVertices=0, numVertices=1
2016-05-18 01:58:50,226 INFO impl.DAGImpl (DAGImpl.java:checkVerticesForCompletion(1261)) - Checking vertices for DAG completion, numCompletedVertices=1, numSuccessfulVertices=1, numFailedVertices=0, numKilledVertices=0, numVertices=1, commitInProgress=0, terminationCause=null
2016-05-18 01:58:50,228 INFO impl.DAGImpl (DAGImpl.java:commitOrFinish(1098)) - Start writing dag commit event, dag_1463536728771_0001_1
2016-05-18 01:58:50,228 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536728771_0001_1][Event:DAG_COMMIT_STARTED]: dagID=dag_1463536728771_0001_1
2016-05-18 01:58:50,229 INFO impl.DAGImpl (DAGImpl.java:handle(1170)) - dag_1463536728771_0001_1 transitioned from RUNNING to COMMITTING due to event DAG_VERTEX_COMPLETED
2016-05-18 01:58:50,229 INFO impl.DAGImpl (DAGImpl.java:call(1083)) - Committing output: 6E9F78DC240F4000B1EFE1F473A34613 for vertex: vertex_1463536728771_0001_1_00 [D444857D8A2F4A0AA50707FBA05FE775], outputName: 6E9F78DC240F4000B1EFE1F473A34613
2016-05-18 01:58:50,229 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:stop(262)) - Ignoring stop request for containerId container_1463536728771_0001_00_000001. Relying on regular task shutdown for it to end
2016-05-18 01:58:50,243 INFO impl.DAGImpl (DAGImpl.java:commitCompleted(2192)) - Commit succeeded for output:outputName:6E9F78DC240F4000B1EFE1F473A34613 of vertex/vertexGroup:D444857D8A2F4A0AA50707FBA05FE775 isVertexGroupOutput:false
2016-05-18 01:58:50,244 INFO impl.DAGImpl (DAGImpl.java:checkCommitsForCompletion(1313)) - Checking commits for DAG completion, numCompletedVertices=1, numSuccessfulVertices=1, numFailedVertices=0, numKilledVertices=0, numVertices=1, commitInProgress=0, terminationCause=null
2016-05-18 01:58:50,250 INFO recovery.RecoveryService (RecoveryService.java:handle(327)) - DAG completed, dagId=dag_1463536728771_0001_1, queueSize=0
2016-05-18 01:58:50,252 INFO app.TezTaskCommunicatorImpl (TezTaskCommunicatorImpl.java:getContainerTask(416)) - Container with id: container_1463536728771_0001_00_000001 is valid, but no longer registered, and will be killed
2016-05-18 01:58:50,252 INFO task.ContainerReporter (ContainerReporter.java:callInternal(67)) - Got TaskUpdate for containerId= container_1463536728771_0001_00_000001: 63 ms after starting to poll. TaskInfo: shouldDie: true
2016-05-18 01:58:50,252 INFO task.TezChild (TezChild.java:run(235)) - ContainerTask returned shouldDie=true for container container_1463536728771_0001_00_000001, Exiting
2016-05-18 01:58:50,252 INFO task.TezChild (TezChild.java:shutdown(381)) - Shutdown invoked for container container_1463536728771_0001_00_000001
2016-05-18 01:58:50,253 INFO task.TezChild (TezChild.java:shutdown(383)) - Shutting down container container_1463536728771_0001_00_000001
2016-05-18 01:58:50,253 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536728771_0001_1][Event:DAG_FINISHED]: dagId=dag_1463536728771_0001_1, startTime=1463536729690, finishTime=1463536730244, timeTaken=554, status=SUCCEEDED, diagnostics=, counters=Counters: 16, org.apache.tez.common.counters.DAGCounter, NUM_SUCCEEDED_TASKS=1, TOTAL_LAUNCHED_TASKS=1, RACK_LOCAL_TASKS=1, AM_CPU_MILLISECONDS=1300, AM_GC_TIME_MILLIS=30, org.apache.tez.common.counters.TaskCounter, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=10, cascading.flow.SliceCounters, Process_Begin_Time=1463536730159, Process_Duration=11, Process_End_Time=1463536730170, Read_Duration=2, Tuples_Read=10, Tuples_Written=10, Write_Duration=0, cascading.flow.StepCounters, Tuples_Read=10, Tuples_Written=10
2016-05-18 01:58:50,254 INFO impl.DAGImpl (DAGImpl.java:finished(1405)) - DAG: dag_1463536728771_0001_1 finished with state: SUCCEEDED
2016-05-18 01:58:50,254 INFO impl.DAGImpl (DAGImpl.java:handle(1170)) - dag_1463536728771_0001_1 transitioned from COMMITTING to SUCCEEDED due to event DAG_COMMIT_COMPLETED
2016-05-18 01:58:50 Completed Dag: dag_1463536728771_0001_1
2016-05-18 01:58:50,256 INFO app.DAGAppMaster (DAGAppMaster.java:handle(751)) - DAG completed, dagId=dag_1463536728771_0001_1, dagState=SUCCEEDED
2016-05-18 01:58:50,256 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend: dag_1463536728771_0001_1_post
2016-05-18 01:58:50,257 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 01:58:50,257 INFO app.DAGAppMaster (DAGAppMaster.java:handle(800)) - Central Dispatcher queue size after DAG completion, before cleanup: 0
2016-05-18 01:58:50,258 INFO app.DAGAppMaster (DAGAppMaster.java:handle(802)) - Waiting for next DAG to be submitted.
2016-05-18 01:58:50,260 INFO app.DAGAppMaster (DAGAppMaster.java:handle(842)) - Cleaning up DAG: name=[91A25304858B45908BE1086FB8BA5FAD/F8721E8789C54E30A4998B3BE25F3882] test/(1/1) ...StrategiesReplace/replace, with id=dag_1463536728771_0001_1
2016-05-18 01:58:50,270 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(285)) - ContainerExecutionResult for: container_1463536728771_0001_00_000001 = ContainerExecutionResult{exitStatus=SUCCESS, throwable=null, errorMessage='Asked to die by the AM'}
2016-05-18 01:58:50,271 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(289)) - Container: container_1463536728771_0001_00_000001 completed successfully
2016-05-18 01:58:50,273 INFO app.DAGAppMaster (DAGAppMaster.java:handle(852)) - Completed cleanup for DAG: name=[91A25304858B45908BE1086FB8BA5FAD/F8721E8789C54E30A4998B3BE25F3882] test/(1/1) ...StrategiesReplace/replace, with id=dag_1463536728771_0001_1
2016-05-18 01:58:50,274 INFO client.TezClient (TezClient.java:stop(566)) - Shutting down Tez Session, sessionName=(1/1) ...StrategiesReplace/replace, applicationId=application_1463536728771_0001
2016-05-18 01:58:50,281 INFO client.DAGClientHandler (DAGClientHandler.java:shutdownAM(124)) - Received message to shutdown AM
2016-05-18 01:58:50,281 INFO rm.TaskSchedulerManager (TaskSchedulerManager.java:setShouldUnregisterFlag(895)) - TaskScheduler notified that it should unregister from RM
2016-05-18 01:58:50,281 INFO app.DAGAppMaster (DAGAppMaster.java:shutdownTezAM(1301)) - No current running DAG, shutting down the AM
2016-05-18 01:58:50,281 INFO app.DAGAppMaster (DAGAppMaster.java:shutdown(907)) - DAGAppMasterShutdownHandler invoked
2016-05-18 01:58:50,281 INFO app.DAGAppMaster (DAGAppMaster.java:shutdown(916)) - Handling DAGAppMaster shutdown
2016-05-18 01:58:50,282 INFO app.DAGAppMaster (DAGAppMaster.java:run(936)) - Sleeping for 5 seconds before shutting down
2016-05-18 01:58:50,286 INFO history.HistoryEventHandler (HistoryEventHandler.java:serviceStop(84)) - Stopping HistoryEventHandler
2016-05-18 01:58:50,286 INFO recovery.RecoveryService (RecoveryService.java:serviceStop(196)) - Stopping RecoveryService
2016-05-18 01:58:50,286 INFO recovery.RecoveryService (RecoveryService.java:serviceStop(199)) - Handle the remaining events in queue, queue size=0
2016-05-18 01:58:50,286 INFO recovery.RecoveryService (RecoveryService.java:run(173)) - EventQueue take interrupted. Returning
2016-05-18 01:58:50,286 INFO recovery.RecoveryService (RecoveryService.java:serviceStop(221)) - Closing Summary Stream
2016-05-18 01:58:50,287 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStop(118)) - Stopping SimpleHistoryLoggingService, eventQueueBacklog=0
2016-05-18 01:58:50,287 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:run(105)) - EventQueue take interrupted. Returning
2016-05-18 01:58:50,288 INFO rm.TaskSchedulerManager (TaskSchedulerManager.java:serviceStop(678)) - Shutting down AppCallbackExecutor
2016-05-18 01:58:50,292 INFO app.DAGAppMaster (DAGAppMaster.java:run(2084)) - Completed deletion of tez scratch data dir, path=file:/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/91A25304858B45908BE1086FB8BA5FAD/F8721E8789C54E30A4998B3BE25F3882/.tez/application_1463536728771_0001
2016-05-18 01:58:50,294 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(226)) - deleting temp path /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output/hadoop2-tez/flowstrategiesplatform/testSkipStrategiesReplace/replace/_temporary
2016-05-18 01:58:50,295 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] completed in: 00:01.751
2016-05-18 01:58:50,295 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] at least one sink is marked for delete
2016-05-18 01:58:50,295 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] sink oldest modified date: Wed Dec 31 23:59:59 UTC 1969
2016-05-18 01:58:50,295 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] at least one sink is marked for delete
2016-05-18 01:58:50,295 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] sink oldest modified date: Wed Dec 31 23:59:59 UTC 1969
2016-05-18 01:58:50,399 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output//hadoop2-tez/flowstrategiesplatform/testSkipStrategiesReplace/replace
2016-05-18 01:58:50,444 INFO util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-18 01:58:50,445 INFO planner.Hadoop2TezPlanner (Hadoop2TezPlanner.java:initialize(151)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-tez/3.1.0/226af02e24d5195c60e4ebe911d0c7c9780f59f0/cascading-hadoop2-tez-3.1.0.jar
2016-05-18 01:58:50,527 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.036
2016-05-18 01:58:50,548 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.059
2016-05-18 01:58:50,549 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] rule registry: NoHashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 1
2016-05-18 01:58:50,549 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] rule registry: HashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 1
2016-05-18 01:58:50,550 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] rule registry: NoHashJoinHadoop2TezRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-05-18 01:58:50,575 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache.10.txt
2016-05-18 01:58:50,576 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output/hadoop2-tez/flowstrategiesplatform/testSkipStrategiesKeep/keep
2016-05-18 01:58:50,616 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] at least one sink does not exist
2016-05-18 01:58:50,618 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] at least one sink does not exist
2016-05-18 01:58:50,620 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] starting
2016-05-18 01:58:50,620 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] source: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache.10.txt"]
2016-05-18 01:58:50,621 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] sink: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output/hadoop2-tez/flowstrategiesplatform/testSkipStrategiesKeep/keep"]
2016-05-18 01:58:50,623 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] parallel execution of steps is enabled: false
2016-05-18 01:58:50,623 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] executing total steps: 1
2016-05-18 01:58:50,624 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] allocating management threads: 1
2016-05-18 01:58:50,624 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] starting step: (1/1) ...stSkipStrategiesKeep/keep
2016-05-18 01:58:50,625 WARN flow.Flow (BaseFlow.java:logWarn(1516)) - [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-05-18 01:58:50,652 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] tez session mode enabled: true
2016-05-18 01:58:50,658 INFO client.TezClient (TezClient.java:<init>(174)) - Tez Client Version: [ component=tez-api, version=0.8.2, revision=2d46dcefa492a6957cfa972007039f7e188760ce, SCM-URL=scm:git:https://git-wip-us.apache.org/repos/asf/tez.git, buildTime=20160112-1834 ]
2016-05-18 01:58:50,658 INFO client.TezClient (TezClient.java:start(394)) - Session mode. Starting session.
2016-05-18 01:58:50,659 INFO client.TezClientUtils (TezClientUtils.java:setupTezJarsLocalResources(164)) - Ignoring 'tez.lib.uris' since 'tez.ignore.lib.uris' is set to true
2016-05-18 01:58:50,669 INFO client.TezClient (TezCommonUtils.java:createTezSystemStagingPath(122)) - Tez system stage directory file:/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/6449838E816B44AE8BF18D263FD3A5F3/E25EAB9390F04D198980E668BEAC1C94/.tez/application_1463536730658_0001 doesn't exist and is created
2016-05-18 01:58:50,702 INFO client.LocalClient (LocalClient.java:createDAGAppMaster(332)) - DAGAppMaster thread has been created
2016-05-18 01:58:50,702 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-05-18 01:58:50,704 INFO client.LocalClient (LocalClient.java:run(282)) - Using working directory: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/6449838E816B44AE8BF18D263FD3A5F3/E25EAB9390F04D198980E668BEAC1C94/.tez/application_1463536730658_0001_wd
2016-05-18 01:58:50,721 INFO app.DAGAppMaster (DAGAppMaster.java:<init>(363)) - Created DAGAppMaster for application appattempt_1463536730658_0001_000000, versionInfo=[ component=tez-dag, version=0.8.2, revision=2d46dcefa492a6957cfa972007039f7e188760ce, SCM-URL=scm:git:https://git-wip-us.apache.org/repos/asf/tez.git, buildTime=20160112-1834 ]
2016-05-18 01:58:50,722 INFO shim.HadoopShimsLoader (HadoopShimsLoader.java:<init>(80)) - Trying to locate HadoopShimProvider for hadoopVersion=2.7.2, majorVersion=2, minorVersion=7
2016-05-18 01:58:50,722 INFO shim.HadoopShimsLoader (HadoopShimsLoader.java:<init>(139)) - Picked HadoopShim org.apache.tez.hadoop.shim.DefaultHadoopShim, providerName=null, overrideProviderViaConfig=null, hadoopVersion=2.7.2, majorVersion=2, minorVersion=7
2016-05-18 01:58:50,727 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(436)) - AM Level configured TaskSchedulers: [0:TezUber:null]
2016-05-18 01:58:50,727 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(437)) - AM Level configured ContainerLaunchers: [0:TezUber:null]
2016-05-18 01:58:50,727 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(438)) - AM Level configured TaskCommunicators: [0:TezUber:null]
2016-05-18 01:58:50,727 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(447)) - Comparing client version with AM version, clientVersion=0.8.2, AMVersion=0.8.2
2016-05-18 01:58:50,728 INFO app.TaskCommunicatorManager (TaskCommunicatorManager.java:createUberTaskCommunicator(192)) - Creating Default Local Task Communicator
2016-05-18 01:58:50,732 INFO common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.rm.container.AMContainerEventType for class org.apache.tez.dag.app.rm.container.AMContainerMap
2016-05-18 01:58:50,732 INFO common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.rm.node.AMNodeEventType for class org.apache.tez.dag.app.rm.node.AMNodeTracker
2016-05-18 01:58:50,732 INFO common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.dag.event.DAGAppMasterEventType for class org.apache.tez.dag.app.DAGAppMaster$DAGAppMasterEventHandler
2016-05-18 01:58:50,733 INFO common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.dag.event.DAGEventType for class org.apache.tez.dag.app.DAGAppMaster$DagEventDispatcher
2016-05-18 01:58:50,733 INFO common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.dag.event.VertexEventType for class org.apache.tez.dag.app.DAGAppMaster$VertexEventDispatcher
2016-05-18 01:58:50,733 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(529)) - Using concurrent dispatcher: false
2016-05-18 01:58:50,733 INFO common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.dag.event.TaskEventType for class org.apache.tez.dag.app.DAGAppMaster$TaskEventDispatcher
2016-05-18 01:58:50,733 INFO common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.dag.event.TaskAttemptEventType for class org.apache.tez.dag.app.DAGAppMaster$TaskAttemptEventDispatcher
2016-05-18 01:58:50,734 INFO common.AsyncDispatcher (AsyncDispatcher.java:registerAndCreateDispatcher(262)) - Registering class org.apache.tez.dag.app.dag.event.SpeculatorEventType for independent dispatch using: class org.apache.tez.dag.app.DAGAppMaster$SpeculatorEventHandler
2016-05-18 01:58:50,734 INFO common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.dag.event.SpeculatorEventType for class org.apache.tez.dag.app.DAGAppMaster$SpeculatorEventHandler
2016-05-18 01:58:50,734 INFO common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.rm.AMSchedulerEventType for class org.apache.tez.dag.app.rm.TaskSchedulerManager
2016-05-18 01:58:50,734 INFO launcher.TezContainerLauncherImpl (ContainerLauncherManager.java:createUberContainerLauncher(134)) - Creating LocalContainerLauncher
2016-05-18 01:58:50,740 INFO common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.rm.ContainerLauncherEventType for class org.apache.tez.dag.app.launcher.ContainerLauncherManager
2016-05-18 01:58:50,741 INFO node.AMNodeTracker (AMNodeTracker.java:serviceInit(78)) - blacklistDisablePercent is 33, blacklistingEnabled: false, maxTaskFailuresPerNode: 1, nodeUpdatesRescheduleEnabled: false
2016-05-18 01:58:50,741 INFO history.HistoryEventHandler (HistoryEventHandler.java:serviceInit(57)) - Initializing HistoryEventHandler withrecoveryEnabled=true, historyServiceClassName=org.apache.tez.dag.history.logging.impl.SimpleHistoryLoggingService
2016-05-18 01:58:50,741 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceInit(66)) - Log file location for SimpleHistoryLoggingService not specified, defaulting to containerLogDir=/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/6449838E816B44AE8BF18D263FD3A5F3/E25EAB9390F04D198980E668BEAC1C94/.tez/application_1463536730658_0001_wd/localmode-log-dir
2016-05-18 01:58:50,742 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceInit(88)) - Initializing SimpleHistoryLoggingService, logFileLocation=/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/6449838E816B44AE8BF18D263FD3A5F3/E25EAB9390F04D198980E668BEAC1C94/.tez/application_1463536730658_0001_wd/localmode-log-dir/history.txt.appattempt_1463536730658_0001_000000, maxErrors=10
2016-05-18 01:58:50,742 INFO recovery.RecoveryService (RecoveryService.java:serviceInit(124)) - RecoveryService initialized with recoveryPath=file:/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/6449838E816B44AE8BF18D263FD3A5F3/E25EAB9390F04D198980E668BEAC1C94/.tez/application_1463536730658_0001/recovery/0, bufferSize(bytes)=8192, flushInterval(s)=30, maxUnflushedEvents=100
2016-05-18 01:58:50,743 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:N/A][Event:AM_LAUNCHED]: appAttemptId=appattempt_1463536730658_0001_000000, appSubmitTime=1463536730721, launchTime=1463536730721
2016-05-18 01:58:50,750 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStart(95)) - Starting SimpleHistoryLoggingService
2016-05-18 01:58:50,752 INFO client.DAGClientServer (DAGClientServer.java:serviceStart(91)) - Instantiated DAGClientRPCServer at ip-10-123-148-208.ec2.internal/10.123.148.208:46652
2016-05-18 01:58:50,755 INFO rm.TaskSchedulerManager (TaskSchedulerManager.java:createUberTaskScheduler(557)) - Creating TaskScheduler: Local TaskScheduler with clusterIdentifier=1463536730658
2016-05-18 01:58:50,766 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:N/A][Event:AM_STARTED]: appAttemptId=appattempt_1463536730658_0001_000000, startTime=1463536730766
2016-05-18 01:58:50,767 INFO app.DAGAppMaster (DAGAppMaster.java:serviceStart(1945)) - In Session mode. Waiting for DAG over RPC
2016-05-18 01:58:50,803 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: IDLE
2016-05-18 01:58:50,803 INFO client.TezClient (TezClient.java:start(428)) - The url to track the Tez Session: N/A
2016-05-18 01:58:50,803 INFO client.TezClient (TezClient.java:submitDAGSession(470)) - Submitting dag to TezSession, sessionName=(1/1) ...stSkipStrategiesKeep/keep, applicationId=application_1463536730658_0001, dagName=[6449838E816B44AE8BF18D263FD3A5F3/E25EAB9390F04D198980E668BEAC1C94] test/(1/1) ...stSkipStrategiesKeep/keep
2016-05-18 01:58:50,826 INFO app.DAGAppMaster (DAGAppMaster.java:submitDAGToAppMaster(1351)) - Starting DAG submitted via RPC: [6449838E816B44AE8BF18D263FD3A5F3/E25EAB9390F04D198980E668BEAC1C94] test/(1/1) ...stSkipStrategiesKeep/keep
2016-05-18 01:58:50,826 INFO app.DAGAppMaster (DAGAppMaster.java:createDAG(985)) - Merging AM credentials into DAG credentials
2016-05-18 01:58:50,828 INFO app.DAGAppMaster (DAGAppMaster.java:generateDAGVizFile(1076)) - Generating DAG graphviz file, dagId=dag_1463536730658_0001_1, filePath=/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/6449838E816B44AE8BF18D263FD3A5F3/E25EAB9390F04D198980E668BEAC1C94/.tez/application_1463536730658_0001_wd/localmode-log-dir/dag_1463536730658_0001_1.dot
2016-05-18 01:58:50,829 INFO app.DAGAppMaster (DAGAppMaster.java:writePBTextFile(1093)) - Writing DAG plan to: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/6449838E816B44AE8BF18D263FD3A5F3/E25EAB9390F04D198980E668BEAC1C94/.tez/application_1463536730658_0001_wd/localmode-log-dir/dag_1463536730658_0001_1-tez-dag.pb.txt
2016-05-18 01:58:50,833 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend: dag_1463536730658_0001_1
2016-05-18 01:58:50,833 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 01:58:50,833 INFO app.DAGAppMaster (DAGAppMaster.java:startDAG(2399)) - Running DAG: [6449838E816B44AE8BF18D263FD3A5F3/E25EAB9390F04D198980E668BEAC1C94] test/(1/1) ...stSkipStrategiesKeep/keep
2016-05-18 01:58:50 Running Dag: dag_1463536730658_0001_1
2016-05-18 01:58:50,876 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536730658_0001_1][Event:DAG_SUBMITTED]: dagID=dag_1463536730658_0001_1, submitTime=1463536730826
2016-05-18 01:58:50,879 INFO impl.VertexImpl (VertexImpl.java:<init>(928)) - Default container context for vertex_1463536730658_0001_1_00 [FD9BD3980D234B38A1162690C409B789]=LocalResources: [[ name=tez-conf.pb, value=resource { scheme: "file" port: -1 file: "/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/6449838E816B44AE8BF18D263FD3A5F3/E25EAB9390F04D198980E668BEAC1C94/.tez/application_1463536730658_0001/tez-conf.pb" } size: 40950 timestamp: 1463536730000 type: FILE visibility: APPLICATION],], environment: [[ CLASSPATH=$PWD/cascading-hadoop2-tez-3.1.0.jar/:$PWD/cascading-hadoop2-tez-3.1.0.jar/classes/:$PWD/cascading-hadoop2-tez-3.1.0.jar/lib/*::$PWD:$PWD/*:$HADOOP_CONF_DIR: ],[ LD_LIBRARY_PATH=$PWD:$PWD:$HADOOP_COMMON_HOME/lib/native/ ],], credentials(token kinds): [tez.job,], javaOpts: -server -Djava.net.preferIPv4Stack=true -Dhadoop.metrics.log.level=WARN -XX:+PrintGCDetails -verbose:gc -XX:+PrintGCTimeStamps -XX:+UseNUMA -XX:+UseParallelGC -Dlog4j.configuratorClass=org.apache.tez.common.TezLog4jConfigurator -Dlog4j.configuration=tez-container-log4j.properties -Dyarn.app.container.log.dir=<LOG_DIR> -Dtez.root.logger=INFO,CLA, vertex: vertex_1463536730658_0001_1_00 [FD9BD3980D234B38A1162690C409B789], Default Resources=<memory:1024, vCores:1>
2016-05-18 01:58:50,879 INFO impl.VertexImpl (VertexImpl.java:setAdditionalInputs(3978)) - Setting 1 additional inputs for vertexvertex_1463536730658_0001_1_00 [FD9BD3980D234B38A1162690C409B789]
2016-05-18 01:58:50,879 INFO impl.VertexImpl (VertexImpl.java:setAdditionalOutputs(4023)) - Setting 1 additional outputs for vertex vertex_1463536730658_0001_1_00 [FD9BD3980D234B38A1162690C409B789]
2016-05-18 01:58:50,880 INFO impl.VertexImpl (VertexImpl.java:<init>(1016)) - Running vertex: vertex_1463536730658_0001_1_00 [FD9BD3980D234B38A1162690C409B789] : TaskScheduler=0:TezUber, ContainerLauncher=0:TezUber, TaskCommunicator=0:TezUber
2016-05-18 01:58:50,880 INFO impl.DAGImpl (DAGImpl.java:assignDAGScheduler(1593)) - Using DAG Scheduler: org.apache.tez.dag.app.dag.impl.DAGSchedulerNaturalOrderControlled
2016-05-18 01:58:50,880 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536730658_0001_1][Event:DAG_INITIALIZED]: dagID=dag_1463536730658_0001_1, initTime=1463536730880
2016-05-18 01:58:50,881 INFO impl.DAGImpl (DAGImpl.java:handle(1170)) - dag_1463536730658_0001_1 transitioned from NEW to INITED due to event DAG_INIT
2016-05-18 01:58:50,882 INFO impl.DAGImpl (DAGImpl.java:transition(1768)) - Added additional resources : [[]] to classpath
2016-05-18 01:58:50,882 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536730658_0001_1][Event:DAG_STARTED]: dagID=dag_1463536730658_0001_1, startTime=1463536730882
2016-05-18 01:58:50,882 INFO impl.DAGImpl (DAGImpl.java:handle(1170)) - dag_1463536730658_0001_1 transitioned from INITED to RUNNING due to event DAG_START
2016-05-18 01:58:50,883 INFO impl.VertexImpl (VertexImpl.java:setupVertex(2400)) - Root Inputs exist for Vertex: FD9BD3980D234B38A1162690C409B789 : {5D6C4E0CFB1D40F3B080489D885AFB4D={InputName=5D6C4E0CFB1D40F3B080489D885AFB4D}, {Descriptor=ClassName=org.apache.tez.mapreduce.input.MRInput, hasPayload=true}, {ControllerDescriptor=ClassName=org.apache.tez.mapreduce.common.MRInputAMSplitGenerator, hasPayload=false}}
2016-05-18 01:58:50,883 INFO impl.VertexImpl (VertexImpl.java:setupVertex(2410)) - Starting root input initializer for input: 5D6C4E0CFB1D40F3B080489D885AFB4D, with class: [org.apache.tez.mapreduce.common.MRInputAMSplitGenerator]
2016-05-18 01:58:50,883 INFO impl.VertexImpl (VertexImpl.java:assignVertexManager(2550)) - Setting vertexManager to RootInputVertexManager for vertex_1463536730658_0001_1_00 [FD9BD3980D234B38A1162690C409B789]
2016-05-18 01:58:50,883 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(2721)) - Num tasks is -1. Expecting VertexManager/InputInitializers/1-1 split to set #tasks for the vertex vertex_1463536730658_0001_1_00 [FD9BD3980D234B38A1162690C409B789]
2016-05-18 01:58:50,883 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(2726)) - Vertex will initialize from input initializer. vertex_1463536730658_0001_1_00 [FD9BD3980D234B38A1162690C409B789]
2016-05-18 01:58:50,884 INFO impl.VertexImpl (VertexImpl.java:setupInputInitializerManager(3893)) - Starting 1 inputInitializers for vertex vertex_1463536730658_0001_1_00 [FD9BD3980D234B38A1162690C409B789]
2016-05-18 01:58:50,885 INFO client.TezClient (TezClient.java:submitDAGSession(545)) - Submitted dag to TezSession, sessionName=(1/1) ...stSkipStrategiesKeep/keep, applicationId=application_1463536730658_0001, dagName=[6449838E816B44AE8BF18D263FD3A5F3/E25EAB9390F04D198980E668BEAC1C94] test/(1/1) ...stSkipStrategiesKeep/keep
2016-05-18 01:58:50,885 INFO impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463536730658_0001_1_00 [FD9BD3980D234B38A1162690C409B789] transitioned from NEW to INITIALIZING due to event V_INIT
2016-05-18 01:58:50,885 INFO dag.RootInputInitializerManager (RootInputInitializerManager.java:run(272)) - Starting InputInitializer for Input: 5D6C4E0CFB1D40F3B080489D885AFB4D on vertex vertex_1463536730658_0001_1_00 [FD9BD3980D234B38A1162690C409B789]
2016-05-18 01:58:50,895 INFO common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(109)) - Input 5D6C4E0CFB1D40F3B080489D885AFB4D asking for 1 tasks. Headroom: 672 Task Resource: 1024 waves: 1.7, groupingEnabled: true
2016-05-18 01:58:50,902 INFO grouper.TezSplitGrouper (TezSplitGrouper.java:getGroupedSplits(168)) - Grouping splits in Tez
2016-05-18 01:58:50,903 INFO grouper.TezSplitGrouper (TezSplitGrouper.java:getGroupedSplits(226)) - Desired splits: 1 too large. Desired splitLength: 1449 Min splitLength: 52428800 New desired splits: 1 Total length: 1449 Original splits: 2
2016-05-18 01:58:50,903 INFO grouper.TezSplitGrouper (TezSplitGrouper.java:getGroupedSplits(321)) - Desired numSplits: 1 lengthPerGroup: 1449 numLocations: 1 numSplitsPerLocation: 2 numSplitsInGroup: 2 totalLength: 1449 numOriginalSplits: 2 . Grouping by length: true count: false nodeLocalOnly: false
2016-05-18 01:58:50,904 INFO grouper.TezSplitGrouper (TezSplitGrouper.java:getGroupedSplits(539)) - Number of splits desired: 1 created: 1 splitsProcessed: 2
2016-05-18 01:58:50,905 INFO dag.RootInputInitializerManager (RootInputInitializerManager.java:onSuccess(308)) - Succeeded InputInitializer for Input: 5D6C4E0CFB1D40F3B080489D885AFB4D on vertex vertex_1463536730658_0001_1_00 [FD9BD3980D234B38A1162690C409B789]
2016-05-18 01:58:50,908 INFO impl.VertexImpl (VertexImpl.java:canInitVertex(2972)) - Cannot init vertex: vertex_1463536730658_0001_1_00 [FD9BD3980D234B38A1162690C409B789] numTasks: -1 numUnitializedEdges: 0 numInitializedInputs: 1 initWaitsForRootInitializers: true
2016-05-18 01:58:50,909 INFO impl.VertexImpl (VertexImpl.java:setParallelismWrapper(1644)) - Got updated RootInputsSpecs: {5D6C4E0CFB1D40F3B080489D885AFB4D=forAllWorkUnits=true, update=[1]}
2016-05-18 01:58:50,911 INFO impl.VertexImpl (VertexImpl.java:setParallelismWrapper(1664)) - Vertex vertex_1463536730658_0001_1_00 [FD9BD3980D234B38A1162690C409B789] parallelism set to 1
2016-05-18 01:58:50,911 INFO impl.VertexImpl (VertexImpl.java:canInitVertex(2972)) - Cannot init vertex: vertex_1463536730658_0001_1_00 [FD9BD3980D234B38A1162690C409B789] numTasks: 1 numUnitializedEdges: 0 numInitializedInputs: 1 initWaitsForRootInitializers: true
2016-05-18 01:58:50,911 INFO impl.VertexImpl (VertexImpl.java:initializeCommitters(2187)) - Setting up committers for vertex vertex_1463536730658_0001_1_00 [FD9BD3980D234B38A1162690C409B789], numAdditionalOutputs=1
2016-05-18 01:58:50,912 INFO impl.VertexImpl (VertexImpl.java:initializeCommitters(2202)) - Instantiating committer for output=3F7E91E63D064AB4A11A47237B98C42C, vertex=vertex_1463536730658_0001_1_00 [FD9BD3980D234B38A1162690C409B789], committerClass=org.apache.tez.mapreduce.committer.MROutputCommitter
2016-05-18 01:58:50,917 INFO committer.MROutputCommitter (MROutputCommitter.java:getOutputCommitter(121)) - Committer for FD9BD3980D234B38A1162690C409B789:3F7E91E63D064AB4A11A47237B98C42C using oldmapred API
2016-05-18 01:58:50,917 INFO committer.MROutputCommitter (MROutputCommitter.java:getOutputCommitter(146)) - OutputCommitter for outputName=3F7E91E63D064AB4A11A47237B98C42C, vertexName=FD9BD3980D234B38A1162690C409B789, outputCommitterClass=org.apache.hadoop.mapred.FileOutputCommitter
2016-05-18 01:58:50,919 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536730658_0001_1][Event:VERTEX_INITIALIZED]: vertexName=FD9BD3980D234B38A1162690C409B789, vertexId=vertex_1463536730658_0001_1_00, initRequestedTime=1463536730883, initedTime=1463536730911, numTasks=1, processorName=cascading.flow.tez.FlowProcessor, additionalInputsCount=1, initGeneratedEventsCount=1
2016-05-18 01:58:50,920 INFO impl.VertexImpl (VertexImpl.java:startIfPossible(2814)) - Triggering start event for vertex: vertex_1463536730658_0001_1_00 [FD9BD3980D234B38A1162690C409B789] with distanceFromRoot: 0
2016-05-18 01:58:50,920 INFO impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463536730658_0001_1_00 [FD9BD3980D234B38A1162690C409B789] transitioned from INITIALIZING to INITED due to event V_INPUT_DATA_INFORMATION
2016-05-18 01:58:50,921 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536730658_0001_1][Event:VERTEX_STARTED]: vertexId=vertex_1463536730658_0001_1_00, startRequestedTime=1463536730885, startedTime=1463536730921
2016-05-18 01:58:50,922 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536730658_0001_1][Event:VERTEX_CONFIGURE_DONE]: vertexId=vertex_1463536730658_0001_1_00, reconfigureDoneTime=0, numTasks=1, vertexLocationHint=org.apache.tez.dag.api.VertexLocationHint@b8338fe7, edgeManagersCount=0, rootInputSpecUpdateCount=1, setParallelismCalledFlag=true
2016-05-18 01:58:50,922 INFO impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463536730658_0001_1_00 [FD9BD3980D234B38A1162690C409B789] transitioned from INITED to RUNNING due to event V_START
2016-05-18 01:58:50,922 INFO impl.ImmediateStartVertexManager (ImmediateStartVertexManager.java:scheduleTasks(100)) - Starting 1 in FD9BD3980D234B38A1162690C409B789
2016-05-18 01:58:50,923 INFO impl.VertexImpl (VertexImpl.java:unsetTasksNotYetScheduled(1466)) - Routing pending task events for vertex: vertex_1463536730658_0001_1_00 [FD9BD3980D234B38A1162690C409B789]
2016-05-18 01:58:50,924 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536730658_0001_1][Event:TASK_STARTED]: vertexName=FD9BD3980D234B38A1162690C409B789, taskId=task_1463536730658_0001_1_00_000000, scheduledTime=1463536730924, launchTime=1463536730924
2016-05-18 01:58:50,926 INFO impl.DAGSchedulerNaturalOrderControlled (DAGSchedulerNaturalOrderControlled.java:scheduleTaskEx(106)) - Scheduled vertex: vertex_1463536730658_0001_1_00 [FD9BD3980D234B38A1162690C409B789]
2016-05-18 01:58:50,928 INFO node.PerSourceNodeTracker (PerSourceNodeTracker.java:nodeSeen(74)) - Adding new node 127.0.0.1:0 to nodeTracker 0
2016-05-18 01:58:50,930 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] submitted tez dag to app master: application_1463536730658_0001, with dag id: dag_1463536730658_0001_1
2016-05-18 01:58:50,933 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:N/A][Event:CONTAINER_LAUNCHED]: containerId=container_1463536730658_0001_00_000001, launchTime=1463536730932
2016-05-18 01:58:50,936 INFO task.ContainerReporter (ContainerReporter.java:callInternal(57)) - Attempting to fetch new task for container container_1463536730658_0001_00_000001
2016-05-18 01:58:50,939 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1322)) - TaskAttempt: [attempt_1463536730658_0001_1_00_000000_0] started. Is using containerId: [container_1463536730658_0001_00_000001] on NM: [127.0.0.1:0]
2016-05-18 01:58:50,940 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536730658_0001_1][Event:TASK_ATTEMPT_STARTED]: vertexName=FD9BD3980D234B38A1162690C409B789, taskAttemptId=attempt_1463536730658_0001_1_00_000000_0, startTime=1463536730939, containerId=container_1463536730658_0001_00_000001, nodeId=127.0.0.1:0
2016-05-18 01:58:50,941 INFO task.ContainerReporter (ContainerReporter.java:callInternal(67)) - Got TaskUpdate for containerId= container_1463536730658_0001_00_000001: 0 ms after starting to poll. TaskInfo: shouldDie: false, currentTaskAttemptId: attempt_1463536730658_0001_1_00_000000_0
2016-05-18 01:58:50 Starting to run new task attempt: attempt_1463536730658_0001_1_00_000000_0
2016-05-18 01:58:50,942 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend: attempt_1463536730658_0001_1_00_000000_0
2016-05-18 01:58:50,942 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 01:58:50,943 INFO task.TezChild (TezChild.java:handleNewTaskCredentials(306)) - Refreshing UGI since Credentials have changed. Credentials : #Tokens=1, #SecretKeys=0
2016-05-18 01:58:50,944 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:<init>(166)) - Initializing LogicalIOProcessorRuntimeTask with TaskSpec: DAGName : [6449838E816B44AE8BF18D263FD3A5F3/E25EAB9390F04D198980E668BEAC1C94] test/(1/1) ...stSkipStrategiesKeep/keep, VertexName: FD9BD3980D234B38A1162690C409B789, VertexParallelism: 1, TaskAttemptID:attempt_1463536730658_0001_1_00_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=5D6C4E0CFB1D40F3B080489D885AFB4D, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=3F7E91E63D064AB4A11A47237B98C42C, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }}, ]
2016-05-18 01:58:50,944 INFO resources.MemoryDistributor (MemoryDistributor.java:<init>(93)) - InitialMemoryDistributor (isEnabled=true) invoked with: numInputs=1, numOutputs=1, JVM.maxFree=704643072, allocatorClassName=org.apache.tez.runtime.library.resources.WeightedScalingMemoryDistributor
2016-05-18 01:58:50,946 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:run(65)) - Initializing task, taskAttemptId=attempt_1463536730658_0001_1_00_000000_0
2016-05-18 01:58:50,953 INFO impl.TaskImpl (TaskImpl.java:getTaskAttemptTezEvents(496)) - TaskAttempt:attempt_1463536730658_0001_1_00_000000_0 sent events: (0-1).
2016-05-18 01:58:50,954 INFO task.TaskReporter (TaskReporter.java:heartbeat(292)) - Routing events from heartbeat response to task, currentTaskAttemptId=attempt_1463536730658_0001_1_00_000000_0, eventCount=1 fromEventId=0 nextFromEventId=0
2016-05-18 01:58:50,962 INFO input.MRInput (MRInput.java:initialize(440)) - 5D6C4E0CFB1D40F3B080489D885AFB4D using newmapreduce API=false, split via event=true, numPhysicalInputs=1
2016-05-18 01:58:50,962 INFO input.MRInput (MRInput.java:initializeInternal(494)) - Initialized MRInput: 5D6C4E0CFB1D40F3B080489D885AFB4D
2016-05-18 01:58:50,967 INFO tez.FlowProcessor (FlowProcessor.java:initialize(88)) - cascading version: 3.1.0
2016-05-18 01:58:50,982 INFO tez.FlowProcessor (FlowProcessor.java:initialize(94)) - flow node id: FD9BD3980D234B38A1162690C409B789, ordinal: 0
2016-05-18 01:58:50,982 INFO output.MROutput (MROutput.java:initialize(421)) - 3F7E91E63D064AB4A11A47237B98C42C: outputFormat=org.apache.hadoop.mapred.TextOutputFormat, using newmapreduce API=false
2016-05-18 01:58:50,983 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: FD9BD3980D234B38A1162690C409B789, mem on start (mb), free: 353, total: 397, max: 672
2016-05-18 01:58:50,984 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(562)) - Initialized processor
2016-05-18 01:58:50,984 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(239)) - Waiting for 2 initializers to finish
2016-05-18 01:58:50,985 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(239)) - Waiting for 1 initializers to finish
2016-05-18 01:58:50,985 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(252)) - All initializers finished
2016-05-18 01:58:50,986 INFO resources.MemoryDistributor (MemoryDistributor.java:logInitialRequests(275)) - InitialRequests=[5D6C4E0CFB1D40F3B080489D885AFB4D:INPUT:0:org.apache.tez.mapreduce.input.MRInput], [3F7E91E63D064AB4A11A47237B98C42C:OUTPUT:0:org.apache.tez.mapreduce.output.MROutput]
2016-05-18 01:58:50,986 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:populateTypeScaleMap(239)) - ScaleRatiosUsed=[PARTITIONED_UNSORTED_OUTPUT:1][UNSORTED_OUTPUT:1][UNSORTED_INPUT:1][SORTED_OUTPUT:12][SORTED_MERGED_INPUT:12][PROCESSOR:1][OTHER:1]
2016-05-18 01:58:50,987 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:computeReservedFraction(266)) - InitialReservationFraction=0.3, AdditionalReservationFractionForIOs=0.03, finalReserveFractionUsed=0.32999999999999996
2016-05-18 01:58:50,987 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-05-18 01:58:50,988 INFO resources.MemoryDistributor (MemoryDistributor.java:logFinalAllocations(297)) - Allocations=[5D6C4E0CFB1D40F3B080489D885AFB4D:org.apache.tez.mapreduce.input.MRInput:INPUT:0:0], [3F7E91E63D064AB4A11A47237B98C42C:org.apache.tez.mapreduce.output.MROutput:OUTPUT:0:0]
2016-05-18 01:58:50,988 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(274)) - Starting Inputs/Outputs
2016-05-18 01:58:50,989 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(287)) - Input: 5D6C4E0CFB1D40F3B080489D885AFB4D being auto started by the framework. Subsequent instances will not be auto-started
2016-05-18 01:58:50,989 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:_callInternal(474)) - Started Input with src edge: 5D6C4E0CFB1D40F3B080489D885AFB4D
2016-05-18 01:58:50,989 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(308)) - Num IOs determined for AutoStart: 1
2016-05-18 01:58:50,990 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(310)) - Waiting for 1 IOs to start
2016-05-18 01:58:50,990 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(323)) - AutoStartComplete
2016-05-18 01:58:50,991 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:run(70)) - Running task, taskAttemptId=attempt_1463536730658_0001_1_00_000000_0
2016-05-18 01:58:50,994 INFO lib.MRReaderMapred (MRReaderMapred.java:setIncrementalConfigParams(174)) - Processing split: TezGroupedSplit{wrappedSplits=[file:/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache.10.txt:0+724, file:/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache.10.txt:724+725], wrappedInputFormatName='org.apache.hadoop.mapred.TextInputFormat', locations=[localhost], rack='null', length=1449}
2016-05-18 01:58:50,994 INFO input.MRInput (MRInput.java:initFromEventInternal(653)) - 5D6C4E0CFB1D40F3B080489D885AFB4D initialized RecordReader from event
2016-05-18 01:58:51,000 INFO graph.Hadoop2TezStreamGraph (Hadoop2TezStreamGraph.java:buildGraph(151)) - using streamed source: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache.10.txt"]
2016-05-18 01:58:51,001 INFO tez.FlowProcessor (FlowProcessor.java:run(121)) - sourcing from: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache.10.txt"] streamed: true, id: 5D6C4E0CFB1D40F3B080489D885AFB4D
2016-05-18 01:58:51,001 INFO tez.FlowProcessor (FlowProcessor.java:run(124)) - sinking to: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output/hadoop2-tez/flowstrategiesplatform/testSkipStrategiesKeep/keep"], id: 3F7E91E63D064AB4A11A47237B98C42C
2016-05-18 01:58:51,002 INFO element.TezSinkStage (TezSinkStage.java:prepare(57)) - calling MROutput#start() on: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output/hadoop2-tez/flowstrategiesplatform/testSkipStrategiesKeep/keep"]
2016-05-18 01:58:51,003 INFO element.TezSourceStage (TezSourceStage.java:prepare(63)) - calling MRInput#start() on: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache.10.txt"]
2016-05-18 01:58:51,004 INFO tez.FlowProcessor (FlowProcessor.java:waitForInputsReady(202)) - flow node id: FD9BD3980D234B38A1162690C409B789, all 1 inputs ready in: 00:00:00.000
2016-05-18 01:58:51,007 INFO output.MROutput (MROutput.java:close(526)) - 3F7E91E63D064AB4A11A47237B98C42C closed
2016-05-18 01:58:51,008 INFO impl.TaskImpl (TaskImpl.java:canCommit(671)) - attempt_1463536730658_0001_1_00_000000_0 given a go for committing the task output.
2016-05-18 01:58:51,010 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:run(79)) - Closing task, taskAttemptId=attempt_1463536730658_0001_1_00_000000_0
2016-05-18 01:58:51,010 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: FD9BD3980D234B38A1162690C409B789, mem on close (mb), free: 350, total: 397, max: 672
2016-05-18 01:58:51,011 INFO output.MROutput (MROutput.java:close(526)) - 3F7E91E63D064AB4A11A47237B98C42C closed
2016-05-18 01:58:51,011 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:close(387)) - Joining on EventRouter
2016-05-18 01:58:51 Completed running task attempt: attempt_1463536730658_0001_1_00_000000_0
2016-05-18 01:58:51,012 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:run(86)) - Task completed, taskAttemptId=attempt_1463536730658_0001_1_00_000000_0, askedToStop=false
2016-05-18 01:58:51,013 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:callInternal(104)) - Cleaning up task attempt_1463536730658_0001_1_00_000000_0, stopRequested=false
2016-05-18 01:58:51,013 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:cleanup(813)) - Final Counters for attempt_1463536730658_0001_1_00_000000_0: Counters: 11 [[org.apache.tez.common.counters.TaskCounter INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=10][cascading.flow.SliceCounters Process_Begin_Time=1463536731004, Process_Duration=6, Process_End_Time=1463536731010, Read_Duration=1, Tuples_Read=10, Tuples_Written=10, Write_Duration=0][cascading.flow.StepCounters Tuples_Read=10, Tuples_Written=10]]
2016-05-18 01:58:51,015 INFO task.TezTaskRunner2 (TezTaskRunner2.java:logAndReturnEndResult(473)) - TaskRunnerResult for attempt_1463536730658_0001_1_00_000000_0 : TaskRunner2Result{endReason=SUCCESS, error=null, containerShutdownRequested=false}
2016-05-18 01:58:51,015 INFO task.TezChild (TezChild.java:run(265)) - TaskRunner2Result: TaskRunner2Result{endReason=SUCCESS, error=null, containerShutdownRequested=false}
2016-05-18 01:58:51,015 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536730658_0001_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=FD9BD3980D234B38A1162690C409B789, taskAttemptId=attempt_1463536730658_0001_1_00_000000_0, creationTime=1463536730926, allocationTime=1463536730931, startTime=1463536730939, finishTime=1463536731015, timeTaken=76, status=SUCCEEDED, errorEnum=, diagnostics=
2016-05-18 01:58:51,015 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend:
2016-05-18 01:58:51,016 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 01:58:51,016 INFO impl.TaskImpl (TaskImpl.java:transition(1057)) - Task succeeded with attempt attempt_1463536730658_0001_1_00_000000_0
2016-05-18 01:58:51,017 INFO task.ContainerReporter (ContainerReporter.java:callInternal(57)) - Attempting to fetch new task for container container_1463536730658_0001_00_000001
2016-05-18 01:58:51,019 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536730658_0001_1][Event:TASK_FINISHED]: vertexName=FD9BD3980D234B38A1162690C409B789, taskId=task_1463536730658_0001_1_00_000000, startTime=1463536730939, finishTime=1463536731017, timeTaken=78, status=SUCCEEDED, successfulAttemptID=attempt_1463536730658_0001_1_00_000000_0, diagnostics=, counters=Counters: 12, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, org.apache.tez.common.counters.TaskCounter, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=10, cascading.flow.SliceCounters, Process_Begin_Time=1463536731004, Process_Duration=6, Process_End_Time=1463536731010, Read_Duration=1, Tuples_Read=10, Tuples_Written=10, Write_Duration=0, cascading.flow.StepCounters, Tuples_Read=10, Tuples_Written=10
2016-05-18 01:58:51,019 INFO impl.VertexImpl (VertexImpl.java:checkTasksForCompletion(2024)) - Task Completion: vertex_1463536730658_0001_1_00 [FD9BD3980D234B38A1162690C409B789], tasks=1, failed=0, killed=0, success=1, completed=1, commits=0, err=null
2016-05-18 01:58:51,019 INFO impl.VertexImpl (VertexImpl.java:checkTasksForCompletion(2037)) - All tasks have succeeded, vertex:vertex_1463536730658_0001_1_00 [FD9BD3980D234B38A1162690C409B789]
2016-05-18 01:58:51,024 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536730658_0001_1][Event:VERTEX_FINISHED]: vertexName=FD9BD3980D234B38A1162690C409B789, vertexId=vertex_1463536730658_0001_1_00, initRequestedTime=1463536730883, initedTime=1463536730911, startRequestedTime=1463536730885, startedTime=1463536730921, finishTime=1463536731019, timeTaken=98, status=SUCCEEDED, diagnostics=, counters=Counters: 12, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, org.apache.tez.common.counters.TaskCounter, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=10, cascading.flow.SliceCounters, Process_Begin_Time=1463536731004, Process_Duration=6, Process_End_Time=1463536731010, Read_Duration=1, Tuples_Read=10, Tuples_Written=10, Write_Duration=0, cascading.flow.StepCounters, Tuples_Read=10, Tuples_Written=10, vertexStats=firstTaskStartTime=1463536730939, firstTasksToStart=[ task_1463536730658_0001_1_00_000000 ], lastTaskFinishTime=1463536731015, lastTasksToFinish=[ task_1463536730658_0001_1_00_000000 ], minTaskDuration=76, maxTaskDuration=76, avgTaskDuration=76.0, numSuccessfulTasks=1, shortestDurationTasks=[ task_1463536730658_0001_1_00_000000 ], longestDurationTasks=[ task_1463536730658_0001_1_00_000000 ], vertexTaskStats={numFailedTasks=0, numSucceededTasks=1, numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0, numCompletedTasks=1}
2016-05-18 01:58:51,024 INFO impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463536730658_0001_1_00 [FD9BD3980D234B38A1162690C409B789] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2016-05-18 01:58:51,025 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536730658_0001_1][Event:CONTAINER_STOPPED]: containerId=container_1463536730658_0001_00_000001, stoppedTime=1463536731025, exitStatus=0
2016-05-18 01:58:51,025 INFO impl.DAGImpl (DAGImpl.java:transition(1927)) - Vertex vertex_1463536730658_0001_1_00 [FD9BD3980D234B38A1162690C409B789] completed., numCompletedVertices=1, numSuccessfulVertices=1, numFailedVertices=0, numKilledVertices=0, numVertices=1
2016-05-18 01:58:51,026 INFO impl.DAGImpl (DAGImpl.java:checkVerticesForCompletion(1261)) - Checking vertices for DAG completion, numCompletedVertices=1, numSuccessfulVertices=1, numFailedVertices=0, numKilledVertices=0, numVertices=1, commitInProgress=0, terminationCause=null
2016-05-18 01:58:51,027 INFO impl.DAGImpl (DAGImpl.java:commitOrFinish(1098)) - Start writing dag commit event, dag_1463536730658_0001_1
2016-05-18 01:58:51,030 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536730658_0001_1][Event:DAG_COMMIT_STARTED]: dagID=dag_1463536730658_0001_1
2016-05-18 01:58:51,029 INFO app.TezTaskCommunicatorImpl (TezTaskCommunicatorImpl.java:getContainerTask(416)) - Container with id: container_1463536730658_0001_00_000001 is valid, but no longer registered, and will be killed
2016-05-18 01:58:51,031 INFO task.ContainerReporter (ContainerReporter.java:callInternal(67)) - Got TaskUpdate for containerId= container_1463536730658_0001_00_000001: 14 ms after starting to poll. TaskInfo: shouldDie: true
2016-05-18 01:58:51,031 INFO impl.DAGImpl (DAGImpl.java:call(1083)) - Committing output: 3F7E91E63D064AB4A11A47237B98C42C for vertex: vertex_1463536730658_0001_1_00 [FD9BD3980D234B38A1162690C409B789], outputName: 3F7E91E63D064AB4A11A47237B98C42C
2016-05-18 01:58:51,031 INFO task.TezChild (TezChild.java:run(235)) - ContainerTask returned shouldDie=true for container container_1463536730658_0001_00_000001, Exiting
2016-05-18 01:58:51,031 INFO task.TezChild (TezChild.java:shutdown(381)) - Shutdown invoked for container container_1463536730658_0001_00_000001
2016-05-18 01:58:51,031 INFO task.TezChild (TezChild.java:shutdown(383)) - Shutting down container container_1463536730658_0001_00_000001
2016-05-18 01:58:51,033 INFO impl.DAGImpl (DAGImpl.java:handle(1170)) - dag_1463536730658_0001_1 transitioned from RUNNING to COMMITTING due to event DAG_VERTEX_COMPLETED
2016-05-18 01:58:51,034 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:stop(262)) - Ignoring stop request for containerId container_1463536730658_0001_00_000001. Relying on regular task shutdown for it to end
2016-05-18 01:58:51,035 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(285)) - ContainerExecutionResult for: container_1463536730658_0001_00_000001 = ContainerExecutionResult{exitStatus=SUCCESS, throwable=null, errorMessage='Asked to die by the AM'}
2016-05-18 01:58:51,036 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(289)) - Container: container_1463536730658_0001_00_000001 completed successfully
2016-05-18 01:58:51,046 INFO impl.DAGImpl (DAGImpl.java:commitCompleted(2192)) - Commit succeeded for output:outputName:3F7E91E63D064AB4A11A47237B98C42C of vertex/vertexGroup:FD9BD3980D234B38A1162690C409B789 isVertexGroupOutput:false
2016-05-18 01:58:51,046 INFO impl.DAGImpl (DAGImpl.java:checkCommitsForCompletion(1313)) - Checking commits for DAG completion, numCompletedVertices=1, numSuccessfulVertices=1, numFailedVertices=0, numKilledVertices=0, numVertices=1, commitInProgress=0, terminationCause=null
2016-05-18 01:58:51,048 INFO recovery.RecoveryService (RecoveryService.java:handle(327)) - DAG completed, dagId=dag_1463536730658_0001_1, queueSize=0
2016-05-18 01:58:51,049 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536730658_0001_1][Event:DAG_FINISHED]: dagId=dag_1463536730658_0001_1, startTime=1463536730882, finishTime=1463536731046, timeTaken=164, status=SUCCEEDED, diagnostics=, counters=Counters: 16, org.apache.tez.common.counters.DAGCounter, NUM_SUCCEEDED_TASKS=1, TOTAL_LAUNCHED_TASKS=1, RACK_LOCAL_TASKS=1, AM_CPU_MILLISECONDS=420, AM_GC_TIME_MILLIS=0, org.apache.tez.common.counters.TaskCounter, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=10, cascading.flow.SliceCounters, Process_Begin_Time=1463536731004, Process_Duration=6, Process_End_Time=1463536731010, Read_Duration=1, Tuples_Read=10, Tuples_Written=10, Write_Duration=0, cascading.flow.StepCounters, Tuples_Read=10, Tuples_Written=10
2016-05-18 01:58:51,049 INFO impl.DAGImpl (DAGImpl.java:finished(1405)) - DAG: dag_1463536730658_0001_1 finished with state: SUCCEEDED
2016-05-18 01:58:51,050 INFO impl.DAGImpl (DAGImpl.java:handle(1170)) - dag_1463536730658_0001_1 transitioned from COMMITTING to SUCCEEDED due to event DAG_COMMIT_COMPLETED
2016-05-18 01:58:51 Completed Dag: dag_1463536730658_0001_1
2016-05-18 01:58:51,050 INFO app.DAGAppMaster (DAGAppMaster.java:handle(751)) - DAG completed, dagId=dag_1463536730658_0001_1, dagState=SUCCEEDED
2016-05-18 01:58:51,052 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend: dag_1463536730658_0001_1_post
2016-05-18 01:58:51,052 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 01:58:51,052 INFO app.DAGAppMaster (DAGAppMaster.java:handle(800)) - Central Dispatcher queue size after DAG completion, before cleanup: 0
2016-05-18 01:58:51,053 INFO app.DAGAppMaster (DAGAppMaster.java:handle(802)) - Waiting for next DAG to be submitted.
2016-05-18 01:58:51,053 INFO app.DAGAppMaster (DAGAppMaster.java:handle(842)) - Cleaning up DAG: name=[6449838E816B44AE8BF18D263FD3A5F3/E25EAB9390F04D198980E668BEAC1C94] test/(1/1) ...stSkipStrategiesKeep/keep, with id=dag_1463536730658_0001_1
2016-05-18 01:58:51,053 INFO app.DAGAppMaster (DAGAppMaster.java:handle(852)) - Completed cleanup for DAG: name=[6449838E816B44AE8BF18D263FD3A5F3/E25EAB9390F04D198980E668BEAC1C94] test/(1/1) ...stSkipStrategiesKeep/keep, with id=dag_1463536730658_0001_1
2016-05-18 01:58:51,062 INFO client.TezClient (TezClient.java:stop(566)) - Shutting down Tez Session, sessionName=(1/1) ...stSkipStrategiesKeep/keep, applicationId=application_1463536730658_0001
2016-05-18 01:58:51,066 INFO client.DAGClientHandler (DAGClientHandler.java:shutdownAM(124)) - Received message to shutdown AM
2016-05-18 01:58:51,066 INFO rm.TaskSchedulerManager (TaskSchedulerManager.java:setShouldUnregisterFlag(895)) - TaskScheduler notified that it should unregister from RM
2016-05-18 01:58:51,067 INFO app.DAGAppMaster (DAGAppMaster.java:shutdownTezAM(1301)) - No current running DAG, shutting down the AM
2016-05-18 01:58:51,067 INFO app.DAGAppMaster (DAGAppMaster.java:shutdown(907)) - DAGAppMasterShutdownHandler invoked
2016-05-18 01:58:51,067 INFO app.DAGAppMaster (DAGAppMaster.java:shutdown(916)) - Handling DAGAppMaster shutdown
2016-05-18 01:58:51,068 INFO app.DAGAppMaster (DAGAppMaster.java:run(936)) - Sleeping for 5 seconds before shutting down
2016-05-18 01:58:51,068 INFO history.HistoryEventHandler (HistoryEventHandler.java:serviceStop(84)) - Stopping HistoryEventHandler
2016-05-18 01:58:51,069 INFO recovery.RecoveryService (RecoveryService.java:serviceStop(196)) - Stopping RecoveryService
2016-05-18 01:58:51,069 INFO recovery.RecoveryService (RecoveryService.java:serviceStop(199)) - Handle the remaining events in queue, queue size=0
2016-05-18 01:58:51,070 INFO recovery.RecoveryService (RecoveryService.java:run(173)) - EventQueue take interrupted. Returning
2016-05-18 01:58:51,070 INFO recovery.RecoveryService (RecoveryService.java:serviceStop(221)) - Closing Summary Stream
2016-05-18 01:58:51,071 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStop(118)) - Stopping SimpleHistoryLoggingService, eventQueueBacklog=0
2016-05-18 01:58:51,071 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:run(105)) - EventQueue take interrupted. Returning
2016-05-18 01:58:51,073 INFO rm.TaskSchedulerManager (TaskSchedulerManager.java:serviceStop(678)) - Shutting down AppCallbackExecutor
2016-05-18 01:58:51,076 INFO app.DAGAppMaster (DAGAppMaster.java:run(2084)) - Completed deletion of tez scratch data dir, path=file:/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/6449838E816B44AE8BF18D263FD3A5F3/E25EAB9390F04D198980E668BEAC1C94/.tez/application_1463536730658_0001
2016-05-18 01:58:51,077 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(226)) - deleting temp path /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output/hadoop2-tez/flowstrategiesplatform/testSkipStrategiesKeep/keep/_temporary
2016-05-18 01:58:51,078 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] completed in: 00:00.457
2016-05-18 01:58:51,081 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] sink oldest modified date: Wed May 18 01:58:51 UTC 2016
2016-05-18 01:58:51,083 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] source modification date at: Wed May 18 01:05:32 UTC 2016
2016-05-18 01:58:51,085 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] sink oldest modified date: Wed May 18 01:58:51 UTC 2016
2016-05-18 01:58:51,176 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output//hadoop2-tez/flowstrategiesplatform/testSkipStrategiesKeep/keep
2016-05-18 01:58:51,217 INFO util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-18 01:58:51,218 INFO planner.Hadoop2TezPlanner (Hadoop2TezPlanner.java:initialize(151)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-tez/3.1.0/226af02e24d5195c60e4ebe911d0c7c9780f59f0/cascading-hadoop2-tez-3.1.0.jar
2016-05-18 01:58:51,296 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.038
2016-05-18 01:58:51,331 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.074
2016-05-18 01:58:51,332 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] rule registry: NoHashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 2
2016-05-18 01:58:51,332 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] rule registry: HashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 2
2016-05-18 01:58:51,333 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] rule registry: NoHashJoinHadoop2TezRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-05-18 01:58:51,356 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache.10.txt
2016-05-18 01:58:51,382 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output/hadoop2-tez/flowstrategiesplatform/testFlowStepStrategy/simple
2016-05-18 01:58:51,479 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] starting
2016-05-18 01:58:51,479 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache.10.txt"]
2016-05-18 01:58:51,480 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] sink: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output/hadoop2-tez/flowstrategiesplatform/testFlowStepStrategy/simple"]
2016-05-18 01:58:51,480 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] parallel execution of steps is enabled: false
2016-05-18 01:58:51,480 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] executing total steps: 1
2016-05-18 01:58:51,481 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] allocating management threads: 1
2016-05-18 01:58:51,481 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] starting step: (1/1) ...stFlowStepStrategy/simple
2016-05-18 01:58:51,482 WARN flow.Flow (BaseFlow.java:logWarn(1516)) - [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-05-18 01:58:51,498 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] tez session mode enabled: true
2016-05-18 01:58:51,503 INFO client.TezClient (TezClient.java:<init>(174)) - Tez Client Version: [ component=tez-api, version=0.8.2, revision=2d46dcefa492a6957cfa972007039f7e188760ce, SCM-URL=scm:git:https://git-wip-us.apache.org/repos/asf/tez.git, buildTime=20160112-1834 ]
2016-05-18 01:58:51,503 INFO client.TezClient (TezClient.java:start(394)) - Session mode. Starting session.
2016-05-18 01:58:51,504 INFO client.TezClientUtils (TezClientUtils.java:setupTezJarsLocalResources(164)) - Ignoring 'tez.lib.uris' since 'tez.ignore.lib.uris' is set to true
2016-05-18 01:58:51,513 INFO client.TezClient (TezCommonUtils.java:createTezSystemStagingPath(122)) - Tez system stage directory file:/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/8090403D23CD4686823D236257799FC3/AD02C915FBC5461A8F28E861BE1F6B7E/.tez/application_1463536731503_0001 doesn't exist and is created
2016-05-18 01:58:51,542 INFO client.LocalClient (LocalClient.java:createDAGAppMaster(332)) - DAGAppMaster thread has been created
2016-05-18 01:58:51,543 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-05-18 01:58:51,544 INFO client.LocalClient (LocalClient.java:run(282)) - Using working directory: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/8090403D23CD4686823D236257799FC3/AD02C915FBC5461A8F28E861BE1F6B7E/.tez/application_1463536731503_0001_wd
2016-05-18 01:58:51,560 INFO app.DAGAppMaster (DAGAppMaster.java:<init>(363)) - Created DAGAppMaster for application appattempt_1463536731503_0001_000000, versionInfo=[ component=tez-dag, version=0.8.2, revision=2d46dcefa492a6957cfa972007039f7e188760ce, SCM-URL=scm:git:https://git-wip-us.apache.org/repos/asf/tez.git, buildTime=20160112-1834 ]
2016-05-18 01:58:51,561 INFO shim.HadoopShimsLoader (HadoopShimsLoader.java:<init>(80)) - Trying to locate HadoopShimProvider for hadoopVersion=2.7.2, majorVersion=2, minorVersion=7
2016-05-18 01:58:51,561 INFO shim.HadoopShimsLoader (HadoopShimsLoader.java:<init>(139)) - Picked HadoopShim org.apache.tez.hadoop.shim.DefaultHadoopShim, providerName=null, overrideProviderViaConfig=null, hadoopVersion=2.7.2, majorVersion=2, minorVersion=7
2016-05-18 01:58:51,564 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(436)) - AM Level configured TaskSchedulers: [0:TezUber:null]
2016-05-18 01:58:51,565 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(437)) - AM Level configured ContainerLaunchers: [0:TezUber:null]
2016-05-18 01:58:51,565 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(438)) - AM Level configured TaskCommunicators: [0:TezUber:null]
2016-05-18 01:58:51,565 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(447)) - Comparing client version with AM version, clientVersion=0.8.2, AMVersion=0.8.2
2016-05-18 01:58:51,566 INFO app.TaskCommunicatorManager (TaskCommunicatorManager.java:createUberTaskCommunicator(192)) - Creating Default Local Task Communicator
2016-05-18 01:58:51,569 INFO common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.rm.container.AMContainerEventType for class org.apache.tez.dag.app.rm.container.AMContainerMap
2016-05-18 01:58:51,569 INFO common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.rm.node.AMNodeEventType for class org.apache.tez.dag.app.rm.node.AMNodeTracker
2016-05-18 01:58:51,569 INFO common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.dag.event.DAGAppMasterEventType for class org.apache.tez.dag.app.DAGAppMaster$DAGAppMasterEventHandler
2016-05-18 01:58:51,569 INFO common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.dag.event.DAGEventType for class org.apache.tez.dag.app.DAGAppMaster$DagEventDispatcher
2016-05-18 01:58:51,570 INFO common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.dag.event.VertexEventType for class org.apache.tez.dag.app.DAGAppMaster$VertexEventDispatcher
2016-05-18 01:58:51,570 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(529)) - Using concurrent dispatcher: false
2016-05-18 01:58:51,570 INFO common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.dag.event.TaskEventType for class org.apache.tez.dag.app.DAGAppMaster$TaskEventDispatcher
2016-05-18 01:58:51,571 INFO common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.dag.event.TaskAttemptEventType for class org.apache.tez.dag.app.DAGAppMaster$TaskAttemptEventDispatcher
2016-05-18 01:58:51,571 INFO common.AsyncDispatcher (AsyncDispatcher.java:registerAndCreateDispatcher(262)) - Registering class org.apache.tez.dag.app.dag.event.SpeculatorEventType for independent dispatch using: class org.apache.tez.dag.app.DAGAppMaster$SpeculatorEventHandler
2016-05-18 01:58:51,571 INFO common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.dag.event.SpeculatorEventType for class org.apache.tez.dag.app.DAGAppMaster$SpeculatorEventHandler
2016-05-18 01:58:51,572 INFO common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.rm.AMSchedulerEventType for class org.apache.tez.dag.app.rm.TaskSchedulerManager
2016-05-18 01:58:51,573 INFO launcher.TezContainerLauncherImpl (ContainerLauncherManager.java:createUberContainerLauncher(134)) - Creating LocalContainerLauncher
2016-05-18 01:58:51,575 INFO common.AsyncDispatcher (AsyncDispatcher.java:register(236)) - Registering class org.apache.tez.dag.app.rm.ContainerLauncherEventType for class org.apache.tez.dag.app.launcher.ContainerLauncherManager
2016-05-18 01:58:51,576 INFO node.AMNodeTracker (AMNodeTracker.java:serviceInit(78)) - blacklistDisablePercent is 33, blacklistingEnabled: false, maxTaskFailuresPerNode: 1, nodeUpdatesRescheduleEnabled: false
2016-05-18 01:58:51,576 INFO history.HistoryEventHandler (HistoryEventHandler.java:serviceInit(57)) - Initializing HistoryEventHandler withrecoveryEnabled=true, historyServiceClassName=org.apache.tez.dag.history.logging.impl.SimpleHistoryLoggingService
2016-05-18 01:58:51,576 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceInit(66)) - Log file location for SimpleHistoryLoggingService not specified, defaulting to containerLogDir=/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/8090403D23CD4686823D236257799FC3/AD02C915FBC5461A8F28E861BE1F6B7E/.tez/application_1463536731503_0001_wd/localmode-log-dir
2016-05-18 01:58:51,576 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceInit(88)) - Initializing SimpleHistoryLoggingService, logFileLocation=/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/8090403D23CD4686823D236257799FC3/AD02C915FBC5461A8F28E861BE1F6B7E/.tez/application_1463536731503_0001_wd/localmode-log-dir/history.txt.appattempt_1463536731503_0001_000000, maxErrors=10
2016-05-18 01:58:51,576 INFO recovery.RecoveryService (RecoveryService.java:serviceInit(124)) - RecoveryService initialized with recoveryPath=file:/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/8090403D23CD4686823D236257799FC3/AD02C915FBC5461A8F28E861BE1F6B7E/.tez/application_1463536731503_0001/recovery/0, bufferSize(bytes)=8192, flushInterval(s)=30, maxUnflushedEvents=100
2016-05-18 01:58:51,577 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:N/A][Event:AM_LAUNCHED]: appAttemptId=appattempt_1463536731503_0001_000000, appSubmitTime=1463536731560, launchTime=1463536731560
2016-05-18 01:58:51,584 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStart(95)) - Starting SimpleHistoryLoggingService
2016-05-18 01:58:51,589 INFO client.DAGClientServer (DAGClientServer.java:serviceStart(91)) - Instantiated DAGClientRPCServer at ip-10-123-148-208.ec2.internal/10.123.148.208:36143
2016-05-18 01:58:51,589 INFO rm.TaskSchedulerManager (TaskSchedulerManager.java:createUberTaskScheduler(557)) - Creating TaskScheduler: Local TaskScheduler with clusterIdentifier=1463536731503
2016-05-18 01:58:51,592 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:N/A][Event:AM_STARTED]: appAttemptId=appattempt_1463536731503_0001_000000, startTime=1463536731592
2016-05-18 01:58:51,593 INFO app.DAGAppMaster (DAGAppMaster.java:serviceStart(1945)) - In Session mode. Waiting for DAG over RPC
2016-05-18 01:58:51,644 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: IDLE
2016-05-18 01:58:51,644 INFO client.TezClient (TezClient.java:start(428)) - The url to track the Tez Session: N/A
2016-05-18 01:58:51,644 INFO client.TezClient (TezClient.java:submitDAGSession(470)) - Submitting dag to TezSession, sessionName=(1/1) ...stFlowStepStrategy/simple, applicationId=application_1463536731503_0001, dagName=[8090403D23CD4686823D236257799FC3/AD02C915FBC5461A8F28E861BE1F6B7E] test/(1/1) ...stFlowStepStrategy/simple
2016-05-18 01:58:51,667 INFO app.DAGAppMaster (DAGAppMaster.java:submitDAGToAppMaster(1351)) - Starting DAG submitted via RPC: [8090403D23CD4686823D236257799FC3/AD02C915FBC5461A8F28E861BE1F6B7E] test/(1/1) ...stFlowStepStrategy/simple
2016-05-18 01:58:51,667 INFO app.DAGAppMaster (DAGAppMaster.java:createDAG(985)) - Merging AM credentials into DAG credentials
2016-05-18 01:58:51,669 INFO app.DAGAppMaster (DAGAppMaster.java:generateDAGVizFile(1076)) - Generating DAG graphviz file, dagId=dag_1463536731503_0001_1, filePath=/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/8090403D23CD4686823D236257799FC3/AD02C915FBC5461A8F28E861BE1F6B7E/.tez/application_1463536731503_0001_wd/localmode-log-dir/dag_1463536731503_0001_1.dot
2016-05-18 01:58:51,670 INFO app.DAGAppMaster (DAGAppMaster.java:writePBTextFile(1093)) - Writing DAG plan to: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/8090403D23CD4686823D236257799FC3/AD02C915FBC5461A8F28E861BE1F6B7E/.tez/application_1463536731503_0001_wd/localmode-log-dir/dag_1463536731503_0001_1-tez-dag.pb.txt
2016-05-18 01:58:51,680 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend: dag_1463536731503_0001_1
2016-05-18 01:58:51,680 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 01:58:51,680 INFO app.DAGAppMaster (DAGAppMaster.java:startDAG(2399)) - Running DAG: [8090403D23CD4686823D236257799FC3/AD02C915FBC5461A8F28E861BE1F6B7E] test/(1/1) ...stFlowStepStrategy/simple
2016-05-18 01:58:51 Running Dag: dag_1463536731503_0001_1
2016-05-18 01:58:51,696 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536731503_0001_1][Event:DAG_SUBMITTED]: dagID=dag_1463536731503_0001_1, submitTime=1463536731667
2016-05-18 01:58:51,697 INFO impl.VertexImpl (VertexImpl.java:<init>(928)) - Default container context for vertex_1463536731503_0001_1_00 [E7C971B4B571417091AC8210D140EDDF]=LocalResources: [[ name=tez-conf.pb, value=resource { scheme: "file" port: -1 file: "/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/8090403D23CD4686823D236257799FC3/AD02C915FBC5461A8F28E861BE1F6B7E/.tez/application_1463536731503_0001/tez-conf.pb" } size: 40950 timestamp: 1463536731000 type: FILE visibility: APPLICATION],], environment: [[ CLASSPATH=$PWD/cascading-hadoop2-tez-3.1.0.jar/:$PWD/cascading-hadoop2-tez-3.1.0.jar/classes/:$PWD/cascading-hadoop2-tez-3.1.0.jar/lib/*::$PWD:$PWD/*:$HADOOP_CONF_DIR: ],[ LD_LIBRARY_PATH=$PWD:$PWD:$HADOOP_COMMON_HOME/lib/native/ ],], credentials(token kinds): [tez.job,], javaOpts: -server -Djava.net.preferIPv4Stack=true -Dhadoop.metrics.log.level=WARN -XX:+PrintGCDetails -verbose:gc -XX:+PrintGCTimeStamps -XX:+UseNUMA -XX:+UseParallelGC -Dlog4j.configuratorClass=org.apache.tez.common.TezLog4jConfigurator -Dlog4j.configuration=tez-container-log4j.properties -Dyarn.app.container.log.dir=<LOG_DIR> -Dtez.root.logger=INFO,CLA, vertex: vertex_1463536731503_0001_1_00 [E7C971B4B571417091AC8210D140EDDF], Default Resources=<memory:1024, vCores:1>
2016-05-18 01:58:51,697 INFO impl.VertexImpl (VertexImpl.java:setAdditionalInputs(3978)) - Setting 1 additional inputs for vertexvertex_1463536731503_0001_1_00 [E7C971B4B571417091AC8210D140EDDF]
2016-05-18 01:58:51,697 INFO impl.VertexImpl (VertexImpl.java:<init>(1016)) - Running vertex: vertex_1463536731503_0001_1_00 [E7C971B4B571417091AC8210D140EDDF] : TaskScheduler=0:TezUber, ContainerLauncher=0:TezUber, TaskCommunicator=0:TezUber
2016-05-18 01:58:51,698 INFO impl.VertexImpl (VertexImpl.java:<init>(928)) - Default container context for vertex_1463536731503_0001_1_01 [A0829C073E9E44098DD1A72483606FB0]=LocalResources: [[ name=tez-conf.pb, value=resource { scheme: "file" port: -1 file: "/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/8090403D23CD4686823D236257799FC3/AD02C915FBC5461A8F28E861BE1F6B7E/.tez/application_1463536731503_0001/tez-conf.pb" } size: 40950 timestamp: 1463536731000 type: FILE visibility: APPLICATION],], environment: [[ CLASSPATH=$PWD/cascading-hadoop2-tez-3.1.0.jar/:$PWD/cascading-hadoop2-tez-3.1.0.jar/classes/:$PWD/cascading-hadoop2-tez-3.1.0.jar/lib/*::$PWD:$PWD/*:$HADOOP_CONF_DIR: ],[ LD_LIBRARY_PATH=$PWD:$PWD:$HADOOP_COMMON_HOME/lib/native/ ],], credentials(token kinds): [tez.job,], javaOpts: -server -Djava.net.preferIPv4Stack=true -Dhadoop.metrics.log.level=WARN -XX:+PrintGCDetails -verbose:gc -XX:+PrintGCTimeStamps -XX:+UseNUMA -XX:+UseParallelGC -Dlog4j.configuratorClass=org.apache.tez.common.TezLog4jConfigurator -Dlog4j.configuration=tez-container-log4j.properties -Dyarn.app.container.log.dir=<LOG_DIR> -Dtez.root.logger=INFO,CLA, vertex: vertex_1463536731503_0001_1_01 [A0829C073E9E44098DD1A72483606FB0], Default Resources=<memory:1024, vCores:1>
2016-05-18 01:58:51,698 INFO impl.VertexImpl (VertexImpl.java:setAdditionalOutputs(4023)) - Setting 1 additional outputs for vertex vertex_1463536731503_0001_1_01 [A0829C073E9E44098DD1A72483606FB0]
2016-05-18 01:58:51,698 INFO impl.VertexImpl (VertexImpl.java:<init>(1016)) - Running vertex: vertex_1463536731503_0001_1_01 [A0829C073E9E44098DD1A72483606FB0] : TaskScheduler=0:TezUber, ContainerLauncher=0:TezUber, TaskCommunicator=0:TezUber
2016-05-18 01:58:51,704 INFO impl.DAGImpl (DAGImpl.java:assignDAGScheduler(1593)) - Using DAG Scheduler: org.apache.tez.dag.app.dag.impl.DAGSchedulerNaturalOrderControlled
2016-05-18 01:58:51,705 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536731503_0001_1][Event:DAG_INITIALIZED]: dagID=dag_1463536731503_0001_1, initTime=1463536731704
2016-05-18 01:58:51,706 INFO impl.DAGImpl (DAGImpl.java:handle(1170)) - dag_1463536731503_0001_1 transitioned from NEW to INITED due to event DAG_INIT
2016-05-18 01:58:51,706 INFO impl.DAGImpl (DAGImpl.java:transition(1768)) - Added additional resources : [[]] to classpath
2016-05-18 01:58:51,707 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536731503_0001_1][Event:DAG_STARTED]: dagID=dag_1463536731503_0001_1, startTime=1463536731707
2016-05-18 01:58:51,707 INFO impl.DAGImpl (DAGImpl.java:handle(1170)) - dag_1463536731503_0001_1 transitioned from INITED to RUNNING due to event DAG_START
2016-05-18 01:58:51,707 INFO impl.VertexImpl (VertexImpl.java:setupVertex(2400)) - Root Inputs exist for Vertex: E7C971B4B571417091AC8210D140EDDF : {C61443163A094AEFB6051887F4703DD2={InputName=C61443163A094AEFB6051887F4703DD2}, {Descriptor=ClassName=org.apache.tez.mapreduce.input.MRInput, hasPayload=true}, {ControllerDescriptor=ClassName=org.apache.tez.mapreduce.common.MRInputAMSplitGenerator, hasPayload=false}}
2016-05-18 01:58:51,707 INFO impl.VertexImpl (VertexImpl.java:setupVertex(2410)) - Starting root input initializer for input: C61443163A094AEFB6051887F4703DD2, with class: [org.apache.tez.mapreduce.common.MRInputAMSplitGenerator]
2016-05-18 01:58:51,707 INFO impl.VertexImpl (VertexImpl.java:assignVertexManager(2550)) - Setting vertexManager to RootInputVertexManager for vertex_1463536731503_0001_1_00 [E7C971B4B571417091AC8210D140EDDF]
2016-05-18 01:58:51,708 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(2721)) - Num tasks is -1. Expecting VertexManager/InputInitializers/1-1 split to set #tasks for the vertex vertex_1463536731503_0001_1_00 [E7C971B4B571417091AC8210D140EDDF]
2016-05-18 01:58:51,708 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(2726)) - Vertex will initialize from input initializer. vertex_1463536731503_0001_1_00 [E7C971B4B571417091AC8210D140EDDF]
2016-05-18 01:58:51,708 INFO impl.VertexImpl (VertexImpl.java:setupInputInitializerManager(3893)) - Starting 1 inputInitializers for vertex vertex_1463536731503_0001_1_00 [E7C971B4B571417091AC8210D140EDDF]
2016-05-18 01:58:51,709 INFO impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463536731503_0001_1_00 [E7C971B4B571417091AC8210D140EDDF] transitioned from NEW to INITIALIZING due to event V_INIT
2016-05-18 01:58:51,709 INFO dag.RootInputInitializerManager (RootInputInitializerManager.java:run(272)) - Starting InputInitializer for Input: C61443163A094AEFB6051887F4703DD2 on vertex vertex_1463536731503_0001_1_00 [E7C971B4B571417091AC8210D140EDDF]
2016-05-18 01:58:51,709 INFO impl.VertexImpl (VertexImpl.java:assignVertexManager(2562)) - Setting vertexManager to ShuffleVertexManager for vertex_1463536731503_0001_1_01 [A0829C073E9E44098DD1A72483606FB0]
2016-05-18 01:58:51,711 INFO client.TezClient (TezClient.java:submitDAGSession(545)) - Submitted dag to TezSession, sessionName=(1/1) ...stFlowStepStrategy/simple, applicationId=application_1463536731503_0001, dagName=[8090403D23CD4686823D236257799FC3/AD02C915FBC5461A8F28E861BE1F6B7E] test/(1/1) ...stFlowStepStrategy/simple
2016-05-18 01:58:51,712 INFO common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(109)) - Input C61443163A094AEFB6051887F4703DD2 asking for 1 tasks. Headroom: 672 Task Resource: 1024 waves: 1.7, groupingEnabled: true
2016-05-18 01:58:51,718 INFO vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:initialize(1022)) - Shuffle Vertex Manager: settings minFrac:0.25 maxFrac:0.75 auto:false desiredTaskIput:104857600 minTasks:1
2016-05-18 01:58:51,719 INFO grouper.TezSplitGrouper (TezSplitGrouper.java:getGroupedSplits(168)) - Grouping splits in Tez
2016-05-18 01:58:51,719 INFO grouper.TezSplitGrouper (TezSplitGrouper.java:getGroupedSplits(226)) - Desired splits: 1 too large. Desired splitLength: 1449 Min splitLength: 52428800 New desired splits: 1 Total length: 1449 Original splits: 2
2016-05-18 01:58:51,719 INFO grouper.TezSplitGrouper (TezSplitGrouper.java:getGroupedSplits(321)) - Desired numSplits: 1 lengthPerGroup: 1449 numLocations: 1 numSplitsPerLocation: 2 numSplitsInGroup: 2 totalLength: 1449 numOriginalSplits: 2 . Grouping by length: true count: false nodeLocalOnly: false
2016-05-18 01:58:51,719 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(2760)) - Creating 1 tasks for vertex: vertex_1463536731503_0001_1_01 [A0829C073E9E44098DD1A72483606FB0]
2016-05-18 01:58:51,719 INFO grouper.TezSplitGrouper (TezSplitGrouper.java:getGroupedSplits(539)) - Number of splits desired: 1 created: 1 splitsProcessed: 2
2016-05-18 01:58:51,720 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(2779)) - Directly initializing vertex: vertex_1463536731503_0001_1_01 [A0829C073E9E44098DD1A72483606FB0]
2016-05-18 01:58:51,723 INFO dag.RootInputInitializerManager (RootInputInitializerManager.java:onSuccess(308)) - Succeeded InputInitializer for Input: C61443163A094AEFB6051887F4703DD2 on vertex vertex_1463536731503_0001_1_00 [E7C971B4B571417091AC8210D140EDDF]
2016-05-18 01:58:51,727 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536731503_0001_1][Event:VERTEX_CONFIGURE_DONE]: vertexId=vertex_1463536731503_0001_1_01, reconfigureDoneTime=0, numTasks=1, vertexLocationHint=null, edgeManagersCount=1, rootInputSpecUpdateCount=0, setParallelismCalledFlag=false
2016-05-18 01:58:51,727 INFO impl.VertexImpl (VertexImpl.java:initializeCommitters(2187)) - Setting up committers for vertex vertex_1463536731503_0001_1_01 [A0829C073E9E44098DD1A72483606FB0], numAdditionalOutputs=1
2016-05-18 01:58:51,728 INFO impl.VertexImpl (VertexImpl.java:initializeCommitters(2202)) - Instantiating committer for output=6548438F7D3C439C9C6CE1FEFC6B66D9, vertex=vertex_1463536731503_0001_1_01 [A0829C073E9E44098DD1A72483606FB0], committerClass=org.apache.tez.mapreduce.committer.MROutputCommitter
2016-05-18 01:58:51,733 INFO committer.MROutputCommitter (MROutputCommitter.java:getOutputCommitter(121)) - Committer for A0829C073E9E44098DD1A72483606FB0:6548438F7D3C439C9C6CE1FEFC6B66D9 using oldmapred API
2016-05-18 01:58:51,733 INFO committer.MROutputCommitter (MROutputCommitter.java:getOutputCommitter(146)) - OutputCommitter for outputName=6548438F7D3C439C9C6CE1FEFC6B66D9, vertexName=A0829C073E9E44098DD1A72483606FB0, outputCommitterClass=org.apache.hadoop.mapred.FileOutputCommitter
2016-05-18 01:58:51,735 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536731503_0001_1][Event:VERTEX_INITIALIZED]: vertexName=A0829C073E9E44098DD1A72483606FB0, vertexId=vertex_1463536731503_0001_1_01, initRequestedTime=1463536731709, initedTime=1463536731727, numTasks=1, processorName=cascading.flow.tez.FlowProcessor, additionalInputsCount=0, initGeneratedEventsCount=0
2016-05-18 01:58:51,737 INFO impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463536731503_0001_1_01 [A0829C073E9E44098DD1A72483606FB0] transitioned from NEW to INITED due to event V_INIT
2016-05-18 01:58:51,739 INFO impl.VertexImpl (VertexImpl.java:canInitVertex(2972)) - Cannot init vertex: vertex_1463536731503_0001_1_00 [E7C971B4B571417091AC8210D140EDDF] numTasks: -1 numUnitializedEdges: 0 numInitializedInputs: 1 initWaitsForRootInitializers: true
2016-05-18 01:58:51,740 INFO impl.VertexImpl (VertexImpl.java:setParallelismWrapper(1644)) - Got updated RootInputsSpecs: {C61443163A094AEFB6051887F4703DD2=forAllWorkUnits=true, update=[1]}
2016-05-18 01:58:51,743 INFO impl.VertexImpl (VertexImpl.java:setParallelismWrapper(1664)) - Vertex vertex_1463536731503_0001_1_00 [E7C971B4B571417091AC8210D140EDDF] parallelism set to 1
2016-05-18 01:58:51,743 INFO impl.VertexImpl (VertexImpl.java:canInitVertex(2972)) - Cannot init vertex: vertex_1463536731503_0001_1_00 [E7C971B4B571417091AC8210D140EDDF] numTasks: 1 numUnitializedEdges: 0 numInitializedInputs: 1 initWaitsForRootInitializers: true
2016-05-18 01:58:51,743 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536731503_0001_1][Event:VERTEX_INITIALIZED]: vertexName=E7C971B4B571417091AC8210D140EDDF, vertexId=vertex_1463536731503_0001_1_00, initRequestedTime=1463536731707, initedTime=1463536731743, numTasks=1, processorName=cascading.flow.tez.FlowProcessor, additionalInputsCount=1, initGeneratedEventsCount=1
2016-05-18 01:58:51,743 INFO impl.VertexImpl (VertexImpl.java:startIfPossible(2814)) - Triggering start event for vertex: vertex_1463536731503_0001_1_00 [E7C971B4B571417091AC8210D140EDDF] with distanceFromRoot: 0
2016-05-18 01:58:51,743 INFO impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463536731503_0001_1_00 [E7C971B4B571417091AC8210D140EDDF] transitioned from INITIALIZING to INITED due to event V_INPUT_DATA_INFORMATION
2016-05-18 01:58:51,744 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536731503_0001_1][Event:VERTEX_STARTED]: vertexId=vertex_1463536731503_0001_1_00, startRequestedTime=1463536731709, startedTime=1463536731744
2016-05-18 01:58:51,744 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536731503_0001_1][Event:VERTEX_CONFIGURE_DONE]: vertexId=vertex_1463536731503_0001_1_00, reconfigureDoneTime=0, numTasks=1, vertexLocationHint=org.apache.tez.dag.api.VertexLocationHint@b8338fe7, edgeManagersCount=0, rootInputSpecUpdateCount=1, setParallelismCalledFlag=true
2016-05-18 01:58:51,745 INFO impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463536731503_0001_1_00 [E7C971B4B571417091AC8210D140EDDF] transitioned from INITED to RUNNING due to event V_START
2016-05-18 01:58:51,745 INFO impl.VertexImpl (VertexImpl.java:transition(2932)) - Source vertex started: vertex_1463536731503_0001_1_00 for vertex: vertex_1463536731503_0001_1_01 [A0829C073E9E44098DD1A72483606FB0] numStartedSources: 1 numSources: 1
2016-05-18 01:58:51,745 INFO impl.VertexImpl (VertexImpl.java:startIfPossible(2814)) - Triggering start event for vertex: vertex_1463536731503_0001_1_01 [A0829C073E9E44098DD1A72483606FB0] with distanceFromRoot: 1
2016-05-18 01:58:51,746 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] submitted tez dag to app master: application_1463536731503_0001, with dag id: dag_1463536731503_0001_1
2016-05-18 01:58:51,747 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536731503_0001_1][Event:VERTEX_STARTED]: vertexId=vertex_1463536731503_0001_1_01, startRequestedTime=1463536731745, startedTime=1463536731745
2016-05-18 01:58:51,748 INFO impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463536731503_0001_1_01 [A0829C073E9E44098DD1A72483606FB0] transitioned from INITED to RUNNING due to event V_START
2016-05-18 01:58:51,750 INFO impl.ImmediateStartVertexManager (ImmediateStartVertexManager.java:scheduleTasks(100)) - Starting 1 in E7C971B4B571417091AC8210D140EDDF
2016-05-18 01:58:51,750 INFO impl.VertexImpl (VertexImpl.java:unsetTasksNotYetScheduled(1466)) - Routing pending task events for vertex: vertex_1463536731503_0001_1_00 [E7C971B4B571417091AC8210D140EDDF]
2016-05-18 01:58:51,753 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536731503_0001_1][Event:TASK_STARTED]: vertexName=E7C971B4B571417091AC8210D140EDDF, taskId=task_1463536731503_0001_1_00_000000, scheduledTime=1463536731752, launchTime=1463536731752
2016-05-18 01:58:51,753 INFO impl.DAGSchedulerNaturalOrderControlled (DAGSchedulerNaturalOrderControlled.java:scheduleTaskEx(106)) - Scheduled vertex: vertex_1463536731503_0001_1_00 [E7C971B4B571417091AC8210D140EDDF]
2016-05-18 01:58:51,758 INFO node.PerSourceNodeTracker (PerSourceNodeTracker.java:nodeSeen(74)) - Adding new node 127.0.0.1:0 to nodeTracker 0
2016-05-18 01:58:51,757 INFO vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:onVertexStarted(519)) - OnVertexStarted vertex: A0829C073E9E44098DD1A72483606FB0 with 0 source tasks and 1 pending tasks
2016-05-18 01:58:51,763 INFO vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:handleVertexStateUpdate(1051)) - Received configured notification : CONFIGURED for vertex: E7C971B4B571417091AC8210D140EDDF in vertex: A0829C073E9E44098DD1A72483606FB0 numBipartiteSourceTasks: 1
2016-05-18 01:58:51,765 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:N/A][Event:CONTAINER_LAUNCHED]: containerId=container_1463536731503_0001_00_000001, launchTime=1463536731764
2016-05-18 01:58:51,767 INFO task.ContainerReporter (ContainerReporter.java:callInternal(57)) - Attempting to fetch new task for container container_1463536731503_0001_00_000001
2016-05-18 01:58:51,768 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1322)) - TaskAttempt: [attempt_1463536731503_0001_1_00_000000_0] started. Is using containerId: [container_1463536731503_0001_00_000001] on NM: [127.0.0.1:0]
2016-05-18 01:58:51,768 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536731503_0001_1][Event:TASK_ATTEMPT_STARTED]: vertexName=E7C971B4B571417091AC8210D140EDDF, taskAttemptId=attempt_1463536731503_0001_1_00_000000_0, startTime=1463536731767, containerId=container_1463536731503_0001_00_000001, nodeId=127.0.0.1:0
2016-05-18 01:58:51,769 INFO task.ContainerReporter (ContainerReporter.java:callInternal(67)) - Got TaskUpdate for containerId= container_1463536731503_0001_00_000001: 0 ms after starting to poll. TaskInfo: shouldDie: false, currentTaskAttemptId: attempt_1463536731503_0001_1_00_000000_0
2016-05-18 01:58:51 Starting to run new task attempt: attempt_1463536731503_0001_1_00_000000_0
2016-05-18 01:58:51,771 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend: attempt_1463536731503_0001_1_00_000000_0
2016-05-18 01:58:51,771 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 01:58:51,771 INFO task.TezChild (TezChild.java:handleNewTaskCredentials(306)) - Refreshing UGI since Credentials have changed. Credentials : #Tokens=1, #SecretKeys=0
2016-05-18 01:58:51,772 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:<init>(166)) - Initializing LogicalIOProcessorRuntimeTask with TaskSpec: DAGName : [8090403D23CD4686823D236257799FC3/AD02C915FBC5461A8F28E861BE1F6B7E] test/(1/1) ...stFlowStepStrategy/simple, VertexName: E7C971B4B571417091AC8210D140EDDF, VertexParallelism: 1, TaskAttemptID:attempt_1463536731503_0001_1_00_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=C61443163A094AEFB6051887F4703DD2, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=A0829C073E9E44098DD1A72483606FB0, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }}, ]
2016-05-18 01:58:51,773 INFO resources.MemoryDistributor (MemoryDistributor.java:<init>(93)) - InitialMemoryDistributor (isEnabled=true) invoked with: numInputs=1, numOutputs=1, JVM.maxFree=704643072, allocatorClassName=org.apache.tez.runtime.library.resources.WeightedScalingMemoryDistributor
2016-05-18 01:58:51,773 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:run(65)) - Initializing task, taskAttemptId=attempt_1463536731503_0001_1_00_000000_0
2016-05-18 01:58:51,779 INFO impl.TaskImpl (TaskImpl.java:getTaskAttemptTezEvents(496)) - TaskAttempt:attempt_1463536731503_0001_1_00_000000_0 sent events: (0-1).
2016-05-18 01:58:51,780 INFO task.TaskReporter (TaskReporter.java:heartbeat(292)) - Routing events from heartbeat response to task, currentTaskAttemptId=attempt_1463536731503_0001_1_00_000000_0, eventCount=1 fromEventId=0 nextFromEventId=0
2016-05-18 01:58:51,785 INFO tez.FlowProcessor (FlowProcessor.java:initialize(88)) - cascading version: 3.1.0
2016-05-18 01:58:51,791 INFO input.MRInput (MRInput.java:initialize(440)) - C61443163A094AEFB6051887F4703DD2 using newmapreduce API=false, split via event=true, numPhysicalInputs=1
2016-05-18 01:58:51,792 INFO input.MRInput (MRInput.java:initializeInternal(494)) - Initialized MRInput: C61443163A094AEFB6051887F4703DD2
2016-05-18 01:58:51,805 INFO tez.FlowProcessor (FlowProcessor.java:initialize(94)) - flow node id: E7C971B4B571417091AC8210D140EDDF, ordinal: 0
2016-05-18 01:58:51,805 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: E7C971B4B571417091AC8210D140EDDF, mem on start (mb), free: 229, total: 397, max: 672
2016-05-18 01:58:51,805 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(562)) - Initialized processor
2016-05-18 01:58:51,805 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(239)) - Waiting for 2 initializers to finish
2016-05-18 01:58:51,805 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(239)) - Waiting for 1 initializers to finish
2016-05-18 01:58:51,805 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(252)) - All initializers finished
2016-05-18 01:58:51,805 INFO resources.MemoryDistributor (MemoryDistributor.java:logInitialRequests(275)) - InitialRequests=[C61443163A094AEFB6051887F4703DD2:INPUT:0:org.apache.tez.mapreduce.input.MRInput], [A0829C073E9E44098DD1A72483606FB0:OUTPUT:104857600:org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput]
2016-05-18 01:58:51,806 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:populateTypeScaleMap(239)) - ScaleRatiosUsed=[PARTITIONED_UNSORTED_OUTPUT:1][UNSORTED_OUTPUT:1][UNSORTED_INPUT:1][SORTED_OUTPUT:12][SORTED_MERGED_INPUT:12][PROCESSOR:1][OTHER:1]
2016-05-18 01:58:51,807 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:computeReservedFraction(266)) - InitialReservationFraction=0.3, AdditionalReservationFractionForIOs=0.03, finalReserveFractionUsed=0.32999999999999996
2016-05-18 01:58:51,808 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-05-18 01:58:51,808 INFO resources.MemoryDistributor (MemoryDistributor.java:logFinalAllocations(297)) - Allocations=[C61443163A094AEFB6051887F4703DD2:org.apache.tez.mapreduce.input.MRInput:INPUT:0:0], [A0829C073E9E44098DD1A72483606FB0:org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput:OUTPUT:104857600:104857600]
2016-05-18 01:58:51,808 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(274)) - Starting Inputs/Outputs
2016-05-18 01:58:51,808 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(287)) - Input: C61443163A094AEFB6051887F4703DD2 being auto started by the framework. Subsequent instances will not be auto-started
2016-05-18 01:58:51,809 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:_callInternal(474)) - Started Input with src edge: C61443163A094AEFB6051887F4703DD2
2016-05-18 01:58:51,809 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(308)) - Num IOs determined for AutoStart: 1
2016-05-18 01:58:51,809 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(310)) - Waiting for 1 IOs to start
2016-05-18 01:58:51,809 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(323)) - AutoStartComplete
2016-05-18 01:58:51,810 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:run(70)) - Running task, taskAttemptId=attempt_1463536731503_0001_1_00_000000_0
2016-05-18 01:58:51,813 INFO lib.MRReaderMapred (MRReaderMapred.java:setIncrementalConfigParams(174)) - Processing split: TezGroupedSplit{wrappedSplits=[file:/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache.10.txt:0+724, file:/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache.10.txt:724+725], wrappedInputFormatName='org.apache.hadoop.mapred.TextInputFormat', locations=[localhost], rack='null', length=1449}
2016-05-18 01:58:51,813 INFO input.MRInput (MRInput.java:initFromEventInternal(653)) - C61443163A094AEFB6051887F4703DD2 initialized RecordReader from event
2016-05-18 01:58:51,818 INFO graph.Hadoop2TezStreamGraph (Hadoop2TezStreamGraph.java:buildGraph(151)) - using streamed source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache.10.txt"]
2016-05-18 01:58:51,833 INFO tez.FlowProcessor (FlowProcessor.java:run(121)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache.10.txt"] streamed: true, id: C61443163A094AEFB6051887F4703DD2
2016-05-18 01:58:51,833 INFO tez.FlowProcessor (FlowProcessor.java:run(124)) - sinking to: GroupBy(test)[by:[{1}:'ip']], id: E1A70AB8E28A4704BAAD16CD288A48BE
2016-05-18 01:58:51,833 INFO element.TezGroupGate (TezGroupGate.java:prepare(98)) - calling OrderedPartitionedKVOutput#start() on: GroupBy(test)[by:[{1}:'ip']] E1A70AB8E28A4704BAAD16CD288A48BE
2016-05-18 01:58:51,875 INFO impl.ExternalSorter (ExternalSorter.java:<init>(199)) - A0829C073E9E44098DD1A72483606FB0 using: memoryMb=100, keySerializerClass=class cascading.tuple.io.KeyTuple, valueSerializerClass=cascading.tuple.hadoop.io.ValueTupleSerializer@5097d220, comparator=cascading.tuple.hadoop.util.TupleComparator@1f645c36, partitioner=cascading.tuple.tez.util.TuplePartitioner, serialization=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-05-18 01:58:51,880 INFO impl.PipelinedSorter (PipelinedSorter.java:<init>(170)) - Setting up PipelinedSorter for A0829C073E9E44098DD1A72483606FB0: , UsingHashComparator=false
2016-05-18 01:58:51,916 INFO impl.PipelinedSorter (PipelinedSorter.java:allocateSpace(245)) - Newly allocated block size=104857600, index=0, Number of buffers=1, currentAllocatableMemory=0, currentBufferSize=104857600, total=104857600
2016-05-18 01:58:51,917 INFO impl.PipelinedSorter (PipelinedSorter.java:<init>(189)) - Pre allocating rest of memory buffers upfront
2016-05-18 01:58:51,920 INFO impl.PipelinedSorter (PipelinedSorter.java:<init>(207)) - Setting up PipelinedSorter for A0829C073E9E44098DD1A72483606FB0: , UsingHashComparator=false#blocks=1, maxMemUsage=104857600, lazyAllocateMem=false, minBlockSize=2097152000, initial BLOCK_SIZE=104857600, finalMergeEnabled=true, pipelinedShuffle=false, sendEmptyPartitions=true, tez.runtime.io.sort.mb=100
2016-05-18 01:58:51,927 INFO impl.PipelinedSorter (PipelinedSorter.java:<init>(882)) - A0829C073E9E44098DD1A72483606FB0: reserved.remaining()=104857600, reserved.metasize=16777216
2016-05-18 01:58:51,931 INFO element.TezSourceStage (TezSourceStage.java:prepare(63)) - calling MRInput#start() on: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache.10.txt"]
2016-05-18 01:58:51,932 INFO tez.FlowProcessor (FlowProcessor.java:waitForInputsReady(202)) - flow node id: E7C971B4B571417091AC8210D140EDDF, all 1 inputs ready in: 00:00:00.000
2016-05-18 01:58:51,936 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:run(79)) - Closing task, taskAttemptId=attempt_1463536731503_0001_1_00_000000_0
2016-05-18 01:58:51,936 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: E7C971B4B571417091AC8210D140EDDF, mem on close (mb), free: 265, total: 397, max: 672
2016-05-18 01:58:51,937 INFO impl.PipelinedSorter (PipelinedSorter.java:flush(629)) - A0829C073E9E44098DD1A72483606FB0: Starting flush of map output
2016-05-18 01:58:51,937 INFO impl.PipelinedSorter (PipelinedSorter.java:end(995)) - A0829C073E9E44098DD1A72483606FB0: Span0.length = 10, perItem = 21
2016-05-18 01:58:51,940 INFO impl.PipelinedSorter (PipelinedSorter.java:sort(904)) - A0829C073E9E44098DD1A72483606FB0: done sorting span=0, length=10, time=2
2016-05-18 01:58:51,942 INFO impl.PipelinedSorter (PipelinedSorter.java:ready(1297)) - A0829C073E9E44098DD1A72483606FB0: Heap = SpanIterator<0:9> (span=Span[16777216,210]),
2016-05-18 01:58:51,947 INFO impl.PipelinedSorter (PipelinedSorter.java:spill(546)) - A0829C073E9E44098DD1A72483606FB0: Spilling to /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/8090403D23CD4686823D236257799FC3/AD02C915FBC5461A8F28E861BE1F6B7E/.tez/application_1463536731503_0001_wd/localmode-local-dir/output/attempt_1463536731503_0001_1_00_000000_0_10009_0/file.out
2016-05-18 01:58:51,975 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:close(387)) - Joining on EventRouter
2016-05-18 01:58:51 Completed running task attempt: attempt_1463536731503_0001_1_00_000000_0
2016-05-18 01:58:51,976 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:run(86)) - Task completed, taskAttemptId=attempt_1463536731503_0001_1_00_000000_0, askedToStop=false
2016-05-18 01:58:51,976 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:callInternal(104)) - Cleaning up task attempt_1463536731503_0001_1_00_000000_0, stopRequested=false
2016-05-18 01:58:51,977 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:cleanup(813)) - Final Counters for attempt_1463536731503_0001_1_00_000000_0: Counters: 18 [[org.apache.tez.common.counters.TaskCounter SPILLED_RECORDS=10, 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, SHUFFLE_CHUNK_COUNT=1][cascading.flow.SliceCounters Process_Begin_Time=1463536731932, Process_Duration=4, Process_End_Time=1463536731936, Read_Duration=2, Tuples_Read=10, Tuples_Written=10, Write_Duration=1][cascading.flow.StepCounters Tuples_Read=10]]
2016-05-18 01:58:51,982 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536731503_0001_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=E7C971B4B571417091AC8210D140EDDF, taskAttemptId=attempt_1463536731503_0001_1_00_000000_0, creationTime=1463536731753, allocationTime=1463536731760, startTime=1463536731767, finishTime=1463536731980, timeTaken=213, status=SUCCEEDED, errorEnum=, diagnostics=
2016-05-18 01:58:51,982 INFO task.TezTaskRunner2 (TezTaskRunner2.java:logAndReturnEndResult(473)) - TaskRunnerResult for attempt_1463536731503_0001_1_00_000000_0 : TaskRunner2Result{endReason=SUCCESS, error=null, containerShutdownRequested=false}
2016-05-18 01:58:51,988 INFO task.TezChild (TezChild.java:run(265)) - TaskRunner2Result: TaskRunner2Result{endReason=SUCCESS, error=null, containerShutdownRequested=false}
2016-05-18 01:58:51,988 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend:
2016-05-18 01:58:51,988 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 01:58:51,987 INFO impl.TaskImpl (TaskImpl.java:transition(1057)) - Task succeeded with attempt attempt_1463536731503_0001_1_00_000000_0
2016-05-18 01:58:51,990 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536731503_0001_1][Event:TASK_FINISHED]: vertexName=E7C971B4B571417091AC8210D140EDDF, taskId=task_1463536731503_0001_1_00_000000, startTime=1463536731767, finishTime=1463536731989, timeTaken=222, status=SUCCEEDED, successfulAttemptID=attempt_1463536731503_0001_1_00_000000_0, diagnostics=, counters=Counters: 19, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, org.apache.tez.common.counters.TaskCounter, SPILLED_RECORDS=10, 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, SHUFFLE_CHUNK_COUNT=1, cascading.flow.SliceCounters, Process_Begin_Time=1463536731932, Process_Duration=4, Process_End_Time=1463536731936, Read_Duration=2, Tuples_Read=10, Tuples_Written=10, Write_Duration=1, cascading.flow.StepCounters, Tuples_Read=10
2016-05-18 01:58:51,991 INFO task.ContainerReporter (ContainerReporter.java:callInternal(57)) - Attempting to fetch new task for container container_1463536731503_0001_00_000001
2016-05-18 01:58:51,994 INFO impl.VertexImpl (VertexImpl.java:checkTasksForCompletion(2024)) - Task Completion: vertex_1463536731503_0001_1_00 [E7C971B4B571417091AC8210D140EDDF], tasks=1, failed=0, killed=0, success=1, completed=1, commits=0, err=null
2016-05-18 01:58:51,994 INFO impl.VertexImpl (VertexImpl.java:checkTasksForCompletion(2037)) - All tasks have succeeded, vertex:vertex_1463536731503_0001_1_00 [E7C971B4B571417091AC8210D140EDDF]
2016-05-18 01:58:52,000 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536731503_0001_1][Event:VERTEX_FINISHED]: vertexName=E7C971B4B571417091AC8210D140EDDF, vertexId=vertex_1463536731503_0001_1_00, initRequestedTime=1463536731707, initedTime=1463536731743, startRequestedTime=1463536731709, startedTime=1463536731744, finishTime=1463536731995, timeTaken=251, status=SUCCEEDED, diagnostics=, counters=Counters: 19, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, org.apache.tez.common.counters.TaskCounter, SPILLED_RECORDS=10, 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, SHUFFLE_CHUNK_COUNT=1, cascading.flow.SliceCounters, Process_Begin_Time=1463536731932, Process_Duration=4, Process_End_Time=1463536731936, Read_Duration=2, Tuples_Read=10, Tuples_Written=10, Write_Duration=1, cascading.flow.StepCounters, Tuples_Read=10, vertexStats=firstTaskStartTime=1463536731767, firstTasksToStart=[ task_1463536731503_0001_1_00_000000 ], lastTaskFinishTime=1463536731980, lastTasksToFinish=[ task_1463536731503_0001_1_00_000000 ], minTaskDuration=213, maxTaskDuration=213, avgTaskDuration=213.0, numSuccessfulTasks=1, shortestDurationTasks=[ task_1463536731503_0001_1_00_000000 ], longestDurationTasks=[ task_1463536731503_0001_1_00_000000 ], vertexTaskStats={numFailedTasks=0, numSucceededTasks=1, numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0, numCompletedTasks=1}
2016-05-18 01:58:52,000 INFO impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463536731503_0001_1_00 [E7C971B4B571417091AC8210D140EDDF] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2016-05-18 01:58:52,003 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536731503_0001_1][Event:CONTAINER_STOPPED]: containerId=container_1463536731503_0001_00_000001, stoppedTime=1463536732003, exitStatus=0
2016-05-18 01:58:52,003 INFO impl.VertexImpl (VertexImpl.java:transition(3279)) - Source task attempt completed for vertex: vertex_1463536731503_0001_1_01 [A0829C073E9E44098DD1A72483606FB0] attempt: attempt_1463536731503_0001_1_00_000000_0 with state: SUCCEEDED vertexState: RUNNING
2016-05-18 01:58:52,004 INFO impl.DAGImpl (DAGImpl.java:transition(1927)) - Vertex vertex_1463536731503_0001_1_00 [E7C971B4B571417091AC8210D140EDDF] completed., numCompletedVertices=1, numSuccessfulVertices=1, numFailedVertices=0, numKilledVertices=0, numVertices=2
2016-05-18 01:58:52,004 INFO impl.DAGImpl (DAGImpl.java:checkVerticesForCompletion(1261)) - Checking vertices for DAG completion, numCompletedVertices=1, numSuccessfulVertices=1, numFailedVertices=0, numKilledVertices=0, numVertices=2, commitInProgress=0, terminationCause=null
2016-05-18 01:58:52,005 INFO vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:schedulePendingTasks(920)) - All source tasks assigned. Ramping up 1 remaining tasks for vertex: A0829C073E9E44098DD1A72483606FB0
2016-05-18 01:58:52,006 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:stop(262)) - Ignoring stop request for containerId container_1463536731503_0001_00_000001. Relying on regular task shutdown for it to end
2016-05-18 01:58:52,006 INFO impl.Edge (Edge.java:routingToBegin(232)) - Routing to begin for edge: EdgeInfo: sourceVertexName=E7C971B4B571417091AC8210D140EDDF, destinationVertexName=A0829C073E9E44098DD1A72483606FB0. EdgeProperty: { SCATTER_GATHER : org.apache.tez.runtime.library.input.OrderedGroupedKVInput >> PERSISTED >> org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput >> NullEdgeManager } onDemandRouting: true
2016-05-18 01:58:52,007 INFO impl.VertexImpl (VertexImpl.java:unsetTasksNotYetScheduled(1466)) - Routing pending task events for vertex: vertex_1463536731503_0001_1_01 [A0829C073E9E44098DD1A72483606FB0]
2016-05-18 01:58:52,008 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536731503_0001_1][Event:TASK_STARTED]: vertexName=A0829C073E9E44098DD1A72483606FB0, taskId=task_1463536731503_0001_1_01_000000, scheduledTime=1463536732007, launchTime=1463536732007
2016-05-18 01:58:52,008 INFO impl.DAGSchedulerNaturalOrderControlled (DAGSchedulerNaturalOrderControlled.java:scheduleTaskEx(106)) - Scheduled vertex: vertex_1463536731503_0001_1_01 [A0829C073E9E44098DD1A72483606FB0]
2016-05-18 01:58:52,011 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:N/A][Event:CONTAINER_LAUNCHED]: containerId=container_1463536731503_0001_00_000002, launchTime=1463536732011
2016-05-18 01:58:52,011 INFO task.ContainerReporter (ContainerReporter.java:callInternal(57)) - Attempting to fetch new task for container container_1463536731503_0001_00_000002
2016-05-18 01:58:52,012 INFO task.ContainerReporter (ContainerReporter.java:callInternal(67)) - Got TaskUpdate for containerId= container_1463536731503_0001_00_000002: 0 ms after starting to poll. TaskInfo: shouldDie: false, currentTaskAttemptId: attempt_1463536731503_0001_1_01_000000_0
2016-05-18 01:58:52,013 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1322)) - TaskAttempt: [attempt_1463536731503_0001_1_01_000000_0] started. Is using containerId: [container_1463536731503_0001_00_000002] on NM: [127.0.0.1:0]
2016-05-18 01:58:52 Starting to run new task attempt: attempt_1463536731503_0001_1_01_000000_0
2016-05-18 01:58:52,013 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend: attempt_1463536731503_0001_1_01_000000_0
2016-05-18 01:58:52,013 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 01:58:52,013 INFO task.TezChild (TezChild.java:handleNewTaskCredentials(306)) - Refreshing UGI since Credentials have changed. Credentials : #Tokens=1, #SecretKeys=0
2016-05-18 01:58:52,013 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:<init>(166)) - Initializing LogicalIOProcessorRuntimeTask with TaskSpec: DAGName : [8090403D23CD4686823D236257799FC3/AD02C915FBC5461A8F28E861BE1F6B7E] test/(1/1) ...stFlowStepStrategy/simple, VertexName: A0829C073E9E44098DD1A72483606FB0, VertexParallelism: 1, TaskAttemptID:attempt_1463536731503_0001_1_01_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=E7C971B4B571417091AC8210D140EDDF, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }}, ], outputSpecList=[{{ destinationVertexName=6548438F7D3C439C9C6CE1FEFC6B66D9, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }}, ]
2016-05-18 01:58:52,014 INFO resources.MemoryDistributor (MemoryDistributor.java:<init>(93)) - InitialMemoryDistributor (isEnabled=true) invoked with: numInputs=1, numOutputs=1, JVM.maxFree=704643072, allocatorClassName=org.apache.tez.runtime.library.resources.WeightedScalingMemoryDistributor
2016-05-18 01:58:52,014 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:run(65)) - Initializing task, taskAttemptId=attempt_1463536731503_0001_1_01_000000_0
2016-05-18 01:58:52,015 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536731503_0001_1][Event:TASK_ATTEMPT_STARTED]: vertexName=A0829C073E9E44098DD1A72483606FB0, taskAttemptId=attempt_1463536731503_0001_1_01_000000_0, startTime=1463536732013, containerId=container_1463536731503_0001_00_000002, nodeId=127.0.0.1:0
2016-05-18 01:58:52,020 INFO tez.FlowProcessor (FlowProcessor.java:initialize(88)) - cascading version: 3.1.0
2016-05-18 01:58:52,023 INFO app.TezTaskCommunicatorImpl (TezTaskCommunicatorImpl.java:getContainerTask(416)) - Container with id: container_1463536731503_0001_00_000001 is valid, but no longer registered, and will be killed
2016-05-18 01:58:52,023 INFO task.ContainerReporter (ContainerReporter.java:callInternal(67)) - Got TaskUpdate for containerId= container_1463536731503_0001_00_000001: 31 ms after starting to poll. TaskInfo: shouldDie: true
2016-05-18 01:58:52,024 INFO task.TezChild (TezChild.java:run(235)) - ContainerTask returned shouldDie=true for container container_1463536731503_0001_00_000001, Exiting
2016-05-18 01:58:52,024 INFO task.TezChild (TezChild.java:shutdown(381)) - Shutdown invoked for container container_1463536731503_0001_00_000001
2016-05-18 01:58:52,024 INFO task.TezChild (TezChild.java:shutdown(383)) - Shutting down container container_1463536731503_0001_00_000001
2016-05-18 01:58:52,023 INFO impl.VertexImpl (VertexImpl.java:getTaskAttemptTezEvents(3662)) - Sending attempt_1463536731503_0001_1_01_000000_0 1 events [0,1) total 1 vertex_1463536731503_0001_1_01 [A0829C073E9E44098DD1A72483606FB0]
2016-05-18 01:58:52,025 INFO task.TaskReporter (TaskReporter.java:heartbeat(292)) - Routing events from heartbeat response to task, currentTaskAttemptId=attempt_1463536731503_0001_1_01_000000_0, eventCount=1 fromEventId=0 nextFromEventId=1
2016-05-18 01:58:52,027 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(285)) - ContainerExecutionResult for: container_1463536731503_0001_00_000001 = ContainerExecutionResult{exitStatus=SUCCESS, throwable=null, errorMessage='Asked to die by the AM'}
2016-05-18 01:58:52,027 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(289)) - Container: container_1463536731503_0001_00_000001 completed successfully
2016-05-18 01:58:52,037 INFO orderedgrouped.MergeManager (MergeManager.java:getInitialMemoryRequirement(339)) - Initial Memory required for SHUFFLE_BUFFER=211392912 based on INPUT_BUFFER_FACTOR=0.9, for final merged output=0, using factor: 0.0
2016-05-18 01:58:52,040 INFO tez.FlowProcessor (FlowProcessor.java:initialize(94)) - flow node id: A0829C073E9E44098DD1A72483606FB0, ordinal: 1
2016-05-18 01:58:52,040 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: A0829C073E9E44098DD1A72483606FB0, mem on start (mb), free: 254, total: 397, max: 672
2016-05-18 01:58:52,040 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(562)) - Initialized processor
2016-05-18 01:58:52,040 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(239)) - Waiting for 2 initializers to finish
2016-05-18 01:58:52,040 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(239)) - Waiting for 1 initializers to finish
2016-05-18 01:58:52,042 INFO output.MROutput (MROutput.java:initialize(421)) - 6548438F7D3C439C9C6CE1FEFC6B66D9: outputFormat=org.apache.hadoop.mapred.TextOutputFormat, using newmapreduce API=false
2016-05-18 01:58:52,043 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(252)) - All initializers finished
2016-05-18 01:58:52,043 INFO resources.MemoryDistributor (MemoryDistributor.java:logInitialRequests(275)) - InitialRequests=[6548438F7D3C439C9C6CE1FEFC6B66D9:OUTPUT:0:org.apache.tez.mapreduce.output.MROutput], [E7C971B4B571417091AC8210D140EDDF:INPUT:211392912:org.apache.tez.runtime.library.input.OrderedGroupedKVInput]
2016-05-18 01:58:52,043 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:populateTypeScaleMap(239)) - ScaleRatiosUsed=[PARTITIONED_UNSORTED_OUTPUT:1][UNSORTED_OUTPUT:1][UNSORTED_INPUT:1][SORTED_OUTPUT:12][SORTED_MERGED_INPUT:12][PROCESSOR:1][OTHER:1]
2016-05-18 01:58:52,043 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:computeReservedFraction(266)) - InitialReservationFraction=0.3, AdditionalReservationFractionForIOs=0.03, finalReserveFractionUsed=0.32999999999999996
2016-05-18 01:58:52,044 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:assignMemory(126)) - Scaling Requests. NumRequests: 2, numScaledRequests: 13, TotalRequested: 211392912, TotalRequestedScaled: 1.9513191876923078E8, TotalJVMHeap: 704643072, TotalAvailable: 472110858, TotalRequested/TotalJVMHeap:0.30
2016-05-18 01:58:52,044 INFO resources.MemoryDistributor (MemoryDistributor.java:logFinalAllocations(297)) - Allocations=[6548438F7D3C439C9C6CE1FEFC6B66D9:org.apache.tez.mapreduce.output.MROutput:OUTPUT:0:0], [E7C971B4B571417091AC8210D140EDDF:org.apache.tez.runtime.library.input.OrderedGroupedKVInput:INPUT:211392912:211392912]
2016-05-18 01:58:52,044 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(274)) - Starting Inputs/Outputs
2016-05-18 01:58:52,044 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(287)) - Input: E7C971B4B571417091AC8210D140EDDF being auto started by the framework. Subsequent instances will not be auto-started
2016-05-18 01:58:52,045 INFO orderedgrouped.Shuffle (Shuffle.java:<init>(147)) - E7C971B4B571417091AC8210D140EDDF: Shuffle assigned with 1 inputs, codec: None, ifileReadAhead: true
2016-05-18 01:58:52,046 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(308)) - Num IOs determined for AutoStart: 1
2016-05-18 01:58:52,047 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(310)) - Waiting for 1 IOs to start
2016-05-18 01:58:52,047 INFO orderedgrouped.MergeManager (MergeManager.java:<init>(273)) - E7C971B4B571417091AC8210D140EDDF: MergerManager: memoryLimit=211392912, maxSingleShuffleLimit=52848228, mergeThreshold=190253616, ioSortFactor=100, postMergeMem=0, memToMemMergeOutputsThreshold=100
2016-05-18 01:58:52,061 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:<init>(353)) - ShuffleScheduler running for sourceVertex: E7C971B4B571417091AC8210D140EDDF with configuration: maxFetchFailuresBeforeReporting=5, reportReadErrorImmediately=true, maxFailedUniqueFetches=1, abortFailureLimit=15, maxTaskOutputAtOnce=20, numFetchers=1, hostFailureFraction=0.2, minFailurePerHost=4, maxAllowedFailedFetchFraction=0.5, maxStallTimeFraction=0.5, minReqProgressFraction=0.5, checkFailedFetchSinceLastCompletion=true
2016-05-18 01:58:52,065 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:_callInternal(474)) - Started Input with src edge: E7C971B4B571417091AC8210D140EDDF
2016-05-18 01:58:52,065 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(323)) - AutoStartComplete
2016-05-18 01:58:52,066 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:run(70)) - Running task, taskAttemptId=attempt_1463536731503_0001_1_01_000000_0
2016-05-18 01:58:52,071 INFO graph.Hadoop2TezStreamGraph (Hadoop2TezStreamGraph.java:buildGraph(151)) - using streamed source: GroupBy(test)[by:[{1}:'ip']]
2016-05-18 01:58:52,073 INFO orderedgrouped.ShuffleInputEventHandlerOrderedGrouped (ShuffleInputEventHandlerOrderedGrouped.java:logProgress(76)) - E7C971B4B571417091AC8210D140EDDF: numDmeEventsSeen=1, numDmeEventsSeenWithNoData=0, numObsoletionEventsSeen=0
2016-05-18 01:58:52,076 INFO tez.FlowProcessor (FlowProcessor.java:run(121)) - sourcing from: GroupBy(test)[by:[{1}:'ip']] streamed: true, id: E1A70AB8E28A4704BAAD16CD288A48BE
2016-05-18 01:58:52,076 INFO tez.FlowProcessor (FlowProcessor.java:run(124)) - sinking to: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output/hadoop2-tez/flowstrategiesplatform/testFlowStepStrategy/simple"], id: 6548438F7D3C439C9C6CE1FEFC6B66D9
2016-05-18 01:58:52,077 INFO element.TezSinkStage (TezSinkStage.java:prepare(57)) - calling MROutput#start() on: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output/hadoop2-tez/flowstrategiesplatform/testFlowStepStrategy/simple"]
2016-05-18 01:58:52,077 INFO element.TezGroupGate (TezGroupGate.java:prepare(90)) - calling OrderedGroupedKVInput#start() on: GroupBy(test)[by:[{1}:'ip']] E1A70AB8E28A4704BAAD16CD288A48BE, for 1 inputs
2016-05-18 01:58:52,080 INFO orderedgrouped.ShuffleScheduler (ShuffleUtils.java:logIndividualFetchComplete(489)) - Completed fetch for attempt: {0, 0, attempt_1463536731503_0001_1_00_000000_0_10009} to DISK_DIRECT, csize=204, dsize=200, EndTime=1463536732080, TimeTaken=2, Rate=0.10 MB/s
2016-05-18 01:58:52,081 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:copySucceeded(551)) - All inputs fetched for input vertex : E7C971B4B571417091AC8210D140EDDF
2016-05-18 01:58:52,081 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:logProgress(618)) - copy(1 (spillsFetched=1) of 1. Transfer rate (CumulativeDataFetched/TimeSinceInputStarted)) 0.00 MB/s)
2016-05-18 01:58:52,081 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:callInternal(1289)) - Shutting down FetchScheduler for input: E7C971B4B571417091AC8210D140EDDF, wasInterrupted=false
2016-05-18 01:58:52,082 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:logProgress(618)) - copy(1 (spillsFetched=1) of 1. Transfer rate (CumulativeDataFetched/TimeSinceInputStarted)) 0.00 MB/s)
2016-05-18 01:58:52,083 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(1005)) - finalMerge called with 0 in-memory map-outputs and 1 on-disk map-outputs
2016-05-18 01:58:52,084 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(1103)) - Disk file=/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/8090403D23CD4686823D236257799FC3/AD02C915FBC5461A8F28E861BE1F6B7E/.tez/application_1463536731503_0001_wd/localmode-local-dir/output/attempt_1463536731503_0001_1_00_000000_0_10009/file.out, len=204, isLocal=true
2016-05-18 01:58:52,085 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(1115)) - Merging 1 files, 204 bytes from disk
2016-05-18 01:58:52,086 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(1130)) - Merging 0 segments, 0 bytes from memory into reduce
2016-05-18 01:58:52,090 INFO impl.TezMerger (TezMerger.java:merge(644)) - Merging 1 sorted segments
2016-05-18 01:58:52,093 INFO impl.TezMerger (TezMerger.java:merge(749)) - Down to the last merge-pass, with 1 segments left of total size: 175 bytes
2016-05-18 01:58:52,093 INFO orderedgrouped.Shuffle (Shuffle.java:callInternal(332)) - merge complete for input vertex : E7C971B4B571417091AC8210D140EDDF
2016-05-18 01:58:52,093 INFO tez.FlowProcessor (FlowProcessor.java:waitForInputsReady(202)) - flow node id: A0829C073E9E44098DD1A72483606FB0, all 1 inputs ready in: 00:00:00.015
2016-05-18 01:58:52,094 INFO orderedgrouped.Shuffle (Shuffle.java:onSuccess(417)) - E7C971B4B571417091AC8210D140EDDF: Shuffle Runner thread complete
2016-05-18 01:58:52,095 INFO input.OrderedGroupedKVInput (OrderedGroupedKVInput.java:createValuesIterator(292)) - E7C971B4B571417091AC8210D140EDDF: creating ValuesIterator with comparator=cascading.tuple.hadoop.util.TupleComparator, keyClass=cascading.tuple.io.KeyTuple, valClass=cascading.tuple.io.ValueTuple
2016-05-18 01:58:52,105 INFO output.MROutput (MROutput.java:close(526)) - 6548438F7D3C439C9C6CE1FEFC6B66D9 closed
2016-05-18 01:58:52,106 INFO impl.TaskImpl (TaskImpl.java:canCommit(671)) - attempt_1463536731503_0001_1_01_000000_0 given a go for committing the task output.
2016-05-18 01:58:52,107 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:run(79)) - Closing task, taskAttemptId=attempt_1463536731503_0001_1_01_000000_0
2016-05-18 01:58:52,107 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: A0829C073E9E44098DD1A72483606FB0, mem on close (mb), free: 247, total: 397, max: 672
2016-05-18 01:58:52,107 INFO orderedgrouped.Shuffle (Shuffle.java:shutdown(278)) - Shutting down Shuffle for source: E7C971B4B571417091AC8210D140EDDF
2016-05-18 01:58:52,108 INFO orderedgrouped.ShuffleInputEventHandlerOrderedGrouped (ShuffleInputEventHandlerOrderedGrouped.java:logProgress(76)) - E7C971B4B571417091AC8210D140EDDF: numDmeEventsSeen=1, numDmeEventsSeenWithNoData=0, numObsoletionEventsSeen=0, updateOnClose
2016-05-18 01:58:52,108 INFO output.MROutput (MROutput.java:close(526)) - 6548438F7D3C439C9C6CE1FEFC6B66D9 closed
2016-05-18 01:58:52,108 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:close(387)) - Joining on EventRouter
2016-05-18 01:58:52 Completed running task attempt: attempt_1463536731503_0001_1_01_000000_0
2016-05-18 01:58:52,109 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:run(86)) - Task completed, taskAttemptId=attempt_1463536731503_0001_1_01_000000_0, askedToStop=false
2016-05-18 01:58:52,109 INFO task.TaskRunner2Callable (TaskRunner2Callable.java:callInternal(104)) - Cleaning up task attempt_1463536731503_0001_1_01_000000_0, stopRequested=false
2016-05-18 01:58:52,110 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:cleanup(813)) - Final Counters for attempt_1463536731503_0001_1_01_000000_0: Counters: 36 [[org.apache.tez.common.counters.TaskCounter REDUCE_INPUT_GROUPS=8, 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, 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=37, MERGE_PHASE_TIME=48, FIRST_EVENT_RECEIVED=28, LAST_EVENT_RECEIVED=28][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=1463536732094, Process_Duration=13, Process_End_Time=1463536732107, Read_Duration=2, Tuples_Read=10, Tuples_Written=8, Write_Duration=0][cascading.flow.StepCounters Tuples_Written=8]]
2016-05-18 01:58:52,112 INFO task.TezTaskRunner2 (TezTaskRunner2.java:logAndReturnEndResult(473)) - TaskRunnerResult for attempt_1463536731503_0001_1_01_000000_0 : TaskRunner2Result{endReason=SUCCESS, error=null, containerShutdownRequested=false}
2016-05-18 01:58:52,112 INFO task.TezChild (TezChild.java:run(265)) - TaskRunner2Result: TaskRunner2Result{endReason=SUCCESS, error=null, containerShutdownRequested=false}
2016-05-18 01:58:52,112 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536731503_0001_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=A0829C073E9E44098DD1A72483606FB0, taskAttemptId=attempt_1463536731503_0001_1_01_000000_0, creationTime=1463536732008, allocationTime=1463536732010, startTime=1463536732013, finishTime=1463536732112, timeTaken=99, status=SUCCEEDED, errorEnum=, diagnostics=
2016-05-18 01:58:52,113 INFO impl.TaskImpl (TaskImpl.java:transition(1057)) - Task succeeded with attempt attempt_1463536731503_0001_1_01_000000_0
2016-05-18 01:58:52,112 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend:
2016-05-18 01:58:52,113 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 01:58:52,114 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536731503_0001_1][Event:TASK_FINISHED]: vertexName=A0829C073E9E44098DD1A72483606FB0, taskId=task_1463536731503_0001_1_01_000000, startTime=1463536732013, finishTime=1463536732113, timeTaken=100, status=SUCCEEDED, successfulAttemptID=attempt_1463536731503_0001_1_01_000000_0, diagnostics=, counters=Counters: 36, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=8, 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, 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=37, MERGE_PHASE_TIME=48, FIRST_EVENT_RECEIVED=28, LAST_EVENT_RECEIVED=28, 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=1463536732094, Process_Duration=13, Process_End_Time=1463536732107, Read_Duration=2, Tuples_Read=10, Tuples_Written=8, Write_Duration=0, cascading.flow.StepCounters, Tuples_Written=8
2016-05-18 01:58:52,114 INFO task.ContainerReporter (ContainerReporter.java:callInternal(57)) - Attempting to fetch new task for container container_1463536731503_0001_00_000002
2016-05-18 01:58:52,114 INFO impl.VertexImpl (VertexImpl.java:checkTasksForCompletion(2024)) - Task Completion: vertex_1463536731503_0001_1_01 [A0829C073E9E44098DD1A72483606FB0], tasks=1, failed=0, killed=0, success=1, completed=1, commits=0, err=null
2016-05-18 01:58:52,115 INFO impl.VertexImpl (VertexImpl.java:checkTasksForCompletion(2037)) - All tasks have succeeded, vertex:vertex_1463536731503_0001_1_01 [A0829C073E9E44098DD1A72483606FB0]
2016-05-18 01:58:52,116 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536731503_0001_1][Event:VERTEX_FINISHED]: vertexName=A0829C073E9E44098DD1A72483606FB0, vertexId=vertex_1463536731503_0001_1_01, initRequestedTime=1463536731709, initedTime=1463536731727, startRequestedTime=1463536731745, startedTime=1463536731745, finishTime=1463536732115, timeTaken=370, status=SUCCEEDED, diagnostics=, counters=Counters: 36, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=8, 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, 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=37, MERGE_PHASE_TIME=48, FIRST_EVENT_RECEIVED=28, LAST_EVENT_RECEIVED=28, 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=1463536732094, Process_Duration=13, Process_End_Time=1463536732107, Read_Duration=2, Tuples_Read=10, Tuples_Written=8, Write_Duration=0, cascading.flow.StepCounters, Tuples_Written=8, vertexStats=firstTaskStartTime=1463536732013, firstTasksToStart=[ task_1463536731503_0001_1_01_000000 ], lastTaskFinishTime=1463536732112, lastTasksToFinish=[ task_1463536731503_0001_1_01_000000 ], minTaskDuration=99, maxTaskDuration=99, avgTaskDuration=99.0, numSuccessfulTasks=1, shortestDurationTasks=[ task_1463536731503_0001_1_01_000000 ], longestDurationTasks=[ task_1463536731503_0001_1_01_000000 ], vertexTaskStats={numFailedTasks=0, numSucceededTasks=1, numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0, numCompletedTasks=1}
2016-05-18 01:58:52,116 INFO impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463536731503_0001_1_01 [A0829C073E9E44098DD1A72483606FB0] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2016-05-18 01:58:52,116 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536731503_0001_1][Event:CONTAINER_STOPPED]: containerId=container_1463536731503_0001_00_000002, stoppedTime=1463536732116, exitStatus=0
2016-05-18 01:58:52,117 INFO impl.DAGImpl (DAGImpl.java:transition(1927)) - Vertex vertex_1463536731503_0001_1_01 [A0829C073E9E44098DD1A72483606FB0] completed., numCompletedVertices=2, numSuccessfulVertices=2, numFailedVertices=0, numKilledVertices=0, numVertices=2
2016-05-18 01:58:52,117 INFO impl.DAGImpl (DAGImpl.java:checkVerticesForCompletion(1261)) - Checking vertices for DAG completion, numCompletedVertices=2, numSuccessfulVertices=2, numFailedVertices=0, numKilledVertices=0, numVertices=2, commitInProgress=0, terminationCause=null
2016-05-18 01:58:52,117 INFO impl.DAGImpl (DAGImpl.java:commitOrFinish(1051)) - No output committers for vertex: vertex_1463536731503_0001_1_00 [E7C971B4B571417091AC8210D140EDDF]
2016-05-18 01:58:52,117 INFO impl.DAGImpl (DAGImpl.java:commitOrFinish(1098)) - Start writing dag commit event, dag_1463536731503_0001_1
2016-05-18 01:58:52,118 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536731503_0001_1][Event:DAG_COMMIT_STARTED]: dagID=dag_1463536731503_0001_1
2016-05-18 01:58:52,118 INFO impl.DAGImpl (DAGImpl.java:handle(1170)) - dag_1463536731503_0001_1 transitioned from RUNNING to COMMITTING due to event DAG_VERTEX_COMPLETED
2016-05-18 01:58:52,118 INFO impl.DAGImpl (DAGImpl.java:call(1083)) - Committing output: 6548438F7D3C439C9C6CE1FEFC6B66D9 for vertex: vertex_1463536731503_0001_1_01 [A0829C073E9E44098DD1A72483606FB0], outputName: 6548438F7D3C439C9C6CE1FEFC6B66D9
2016-05-18 01:58:52,118 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:stop(262)) - Ignoring stop request for containerId container_1463536731503_0001_00_000002. Relying on regular task shutdown for it to end
2016-05-18 01:58:52,125 INFO app.TezTaskCommunicatorImpl (TezTaskCommunicatorImpl.java:getContainerTask(416)) - Container with id: container_1463536731503_0001_00_000002 is valid, but no longer registered, and will be killed
2016-05-18 01:58:52,125 INFO task.ContainerReporter (ContainerReporter.java:callInternal(67)) - Got TaskUpdate for containerId= container_1463536731503_0001_00_000002: 11 ms after starting to poll. TaskInfo: shouldDie: true
2016-05-18 01:58:52,125 INFO task.TezChild (TezChild.java:run(235)) - ContainerTask returned shouldDie=true for container container_1463536731503_0001_00_000002, Exiting
2016-05-18 01:58:52,125 INFO task.TezChild (TezChild.java:shutdown(381)) - Shutdown invoked for container container_1463536731503_0001_00_000002
2016-05-18 01:58:52,125 INFO task.TezChild (TezChild.java:shutdown(383)) - Shutting down container container_1463536731503_0001_00_000002
2016-05-18 01:58:52,126 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(285)) - ContainerExecutionResult for: container_1463536731503_0001_00_000002 = ContainerExecutionResult{exitStatus=SUCCESS, throwable=null, errorMessage='Asked to die by the AM'}
2016-05-18 01:58:52,126 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(289)) - Container: container_1463536731503_0001_00_000002 completed successfully
2016-05-18 01:58:52,131 INFO impl.DAGImpl (DAGImpl.java:commitCompleted(2192)) - Commit succeeded for output:outputName:6548438F7D3C439C9C6CE1FEFC6B66D9 of vertex/vertexGroup:A0829C073E9E44098DD1A72483606FB0 isVertexGroupOutput:false
2016-05-18 01:58:52,132 INFO impl.DAGImpl (DAGImpl.java:checkCommitsForCompletion(1313)) - Checking commits for DAG completion, numCompletedVertices=2, numSuccessfulVertices=2, numFailedVertices=0, numKilledVertices=0, numVertices=2, commitInProgress=0, terminationCause=null
2016-05-18 01:58:52,134 INFO recovery.RecoveryService (RecoveryService.java:handle(327)) - DAG completed, dagId=dag_1463536731503_0001_1, queueSize=0
2016-05-18 01:58:52,135 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463536731503_0001_1][Event:DAG_FINISHED]: dagId=dag_1463536731503_0001_1, startTime=1463536731706, finishTime=1463536732132, timeTaken=426, status=SUCCEEDED, diagnostics=, counters=Counters: 48, org.apache.tez.common.counters.DAGCounter, NUM_SUCCEEDED_TASKS=2, TOTAL_LAUNCHED_TASKS=2, RACK_LOCAL_TASKS=1, AM_CPU_MILLISECONDS=890, AM_GC_TIME_MILLIS=24, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=8, 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, 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_CHUNK_COUNT=1, 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=37, MERGE_PHASE_TIME=48, FIRST_EVENT_RECEIVED=28, LAST_EVENT_RECEIVED=28, 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=2927073464026, Process_Duration=17, Process_End_Time=2927073464043, Read_Duration=4, Tuples_Read=20, Tuples_Written=18, Write_Duration=1, cascading.flow.StepCounters, Tuples_Read=10, Tuples_Written=8
2016-05-18 01:58:52,136 INFO impl.DAGImpl (DAGImpl.java:finished(1405)) - DAG: dag_1463536731503_0001_1 finished with state: SUCCEEDED
2016-05-18 01:58:52,136 INFO impl.DAGImpl (DAGImpl.java:handle(1170)) - dag_1463536731503_0001_1 transitioned from COMMITTING to SUCCEEDED due to event DAG_COMMIT_COMPLETED
2016-05-18 01:58:52 Completed Dag: dag_1463536731503_0001_1
2016-05-18 01:58:52,137 INFO app.DAGAppMaster (DAGAppMaster.java:handle(751)) - DAG completed, dagId=dag_1463536731503_0001_1, dagState=SUCCEEDED
2016-05-18 01:58:52,137 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend: dag_1463536731503_0001_1_post
2016-05-18 01:58:52,137 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 01:58:52,137 INFO app.DAGAppMaster (DAGAppMaster.java:handle(800)) - Central Dispatcher queue size after DAG completion, before cleanup: 0
2016-05-18 01:58:52,138 INFO app.DAGAppMaster (DAGAppMaster.java:handle(802)) - Waiting for next DAG to be submitted.
2016-05-18 01:58:52,138 INFO app.DAGAppMaster (DAGAppMaster.java:handle(842)) - Cleaning up DAG: name=[8090403D23CD4686823D236257799FC3/AD02C915FBC5461A8F28E861BE1F6B7E] test/(1/1) ...stFlowStepStrategy/simple, with id=dag_1463536731503_0001_1
2016-05-18 01:58:52,138 INFO app.DAGAppMaster (DAGAppMaster.java:handle(852)) - Completed cleanup for DAG: name=[8090403D23CD4686823D236257799FC3/AD02C915FBC5461A8F28E861BE1F6B7E] test/(1/1) ...stFlowStepStrategy/simple, with id=dag_1463536731503_0001_1
2016-05-18 01:58:52,144 INFO client.TezClient (TezClient.java:stop(566)) - Shutting down Tez Session, sessionName=(1/1) ...stFlowStepStrategy/simple, applicationId=application_1463536731503_0001
2016-05-18 01:58:52,149 INFO client.DAGClientHandler (DAGClientHandler.java:shutdownAM(124)) - Received message to shutdown AM
2016-05-18 01:58:52,149 INFO rm.TaskSchedulerManager (TaskSchedulerManager.java:setShouldUnregisterFlag(895)) - TaskScheduler notified that it should unregister from RM
2016-05-18 01:58:52,149 INFO app.DAGAppMaster (DAGAppMaster.java:shutdownTezAM(1301)) - No current running DAG, shutting down the AM
2016-05-18 01:58:52,149 INFO app.DAGAppMaster (DAGAppMaster.java:shutdown(907)) - DAGAppMasterShutdownHandler invoked
2016-05-18 01:58:52,149 INFO app.DAGAppMaster (DAGAppMaster.java:shutdown(916)) - Handling DAGAppMaster shutdown
2016-05-18 01:58:52,150 INFO app.DAGAppMaster (DAGAppMaster.java:run(936)) - Sleeping for 5 seconds before shutting down
2016-05-18 01:58:52,152 INFO history.HistoryEventHandler (HistoryEventHandler.java:serviceStop(84)) - Stopping HistoryEventHandler
2016-05-18 01:58:52,152 INFO recovery.RecoveryService (RecoveryService.java:serviceStop(196)) - Stopping RecoveryService
2016-05-18 01:58:52,153 INFO recovery.RecoveryService (RecoveryService.java:serviceStop(199)) - Handle the remaining events in queue, queue size=0
2016-05-18 01:58:52,153 INFO recovery.RecoveryService (RecoveryService.java:run(173)) - EventQueue take interrupted. Returning
2016-05-18 01:58:52,153 INFO recovery.RecoveryService (RecoveryService.java:serviceStop(221)) - Closing Summary Stream
2016-05-18 01:58:52,154 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStop(118)) - Stopping SimpleHistoryLoggingService, eventQueueBacklog=0
2016-05-18 01:58:52,154 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:run(105)) - EventQueue take interrupted. Returning
2016-05-18 01:58:52,157 INFO rm.TaskSchedulerManager (TaskSchedulerManager.java:serviceStop(678)) - Shutting down AppCallbackExecutor
2016-05-18 01:58:52,162 INFO app.DAGAppMaster (DAGAppMaster.java:run(2084)) - Completed deletion of tez scratch data dir, path=file:/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/8090403D23CD4686823D236257799FC3/AD02C915FBC5461A8F28E861BE1F6B7E/.tez/application_1463536731503_0001
2016-05-18 01:58:52,163 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(226)) - deleting temp path /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output/hadoop2-tez/flowstrategiesplatform/testFlowStepStrategy/simple/_temporary
2016-05-18 01:58:52,164 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [test] completed in: 00:00.684
2016-05-18 01:58:52,209 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output//hadoop2-tez/flowstrategiesplatform/testFlowStepStrategy/simple