Class cascading.TypedFieldedPipesPlatformTest

12

tests

0

failures

0

ignored

7.046s

duration

100%

successful

Tests

Test Duration Result
testCoGroupComparableTypes 0.819s passed
testCoGroupComparableTypesDeclared 0.386s passed
testCoGroupIncomparableTypes 0.205s passed
testCoGroupIncomparableTypesDeclared 0.146s passed
testFieldTypeCheck 3.072s passed
testGroupByComparableTypes 0.254s passed
testGroupByIncomparableTypes 0.080s passed
testHashJoinComparableTypes 0.215s passed
testHashJoinComparableTypesDeclared 0.178s passed
testHashJoinIncomparableTypes 1.513s passed
testHashJoinIncomparableTypesDeclared 0.090s passed
testMergeIncomparableTypes 0.088s passed

Standard output

2016-05-18 01:21:01,548 INFO  platform.PlatformRunner (PlatformRunner.java:getPlatformClassesFromClasspath(197)) - found 1 test platforms from classpath
2016-05-18 01:21:01,581 INFO  platform.PlatformRunner (PlatformRunner.java:addPlatform(246)) - adding test: cascading.TypedFieldedPipesPlatformTest, with platform: hadoop2-tez
2016-05-18 01:21:01,617 INFO  tez.Hadoop2TezPlatform (Hadoop2TezPlatform.java:setUp(136)) - not using cluster
2016-05-18 01:21:02,189 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:21:02,527 INFO  platform.TestPlatform (TestPlatform.java:getGlobalProperties(75)) - platform property overrides: 
2016-05-18 01:21:02,803 INFO  util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-18 01:21:02,805 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:21:02,898 INFO  property.AppProps (AppProps.java:getAppID(177)) - using app.id: 6D518F1E6E2E474F9CBE6D4C309491F5
2016-05-18 01:21:03,089 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: UNSUPPORTED, in: 00:00.042
2016-05-18 01:21:03,124 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: ILLEGAL, in: 00:00.078
2016-05-18 01:21:03,125 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, does not support assembly
2016-05-18 01:21:03,126 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] rule registry: HashJoinHadoop2TezRuleRegistry, found assembly to be malformed
2016-05-18 01:21:03,126 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/typedfieldedpipesplatform/testHashJoinIncomparableTypes/testHashJoinIncomparableTypes
2016-05-18 01:21:03,214 INFO  util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-18 01:21:03,214 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:21:03,314 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: ILLEGAL, in: 00:00.023
2016-05-18 01:21:03,332 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: ILLEGAL, in: 00:00.041
2016-05-18 01:21:03,332 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, found assembly to be malformed
2016-05-18 01:21:03,333 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] rule registry: HashJoinHadoop2TezRuleRegistry, found assembly to be malformed
2016-05-18 01:21:03,333 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/typedfieldedpipesplatform/testCoGroupIncomparableTypes/testCoGroupIncomparableTypes
2016-05-18 01:21:03,415 INFO  util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-18 01:21:03,416 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:21:03,529 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.061
2016-05-18 01:21:03,556 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.088
2016-05-18 01:21:03,558 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 3
2016-05-18 01:21:03,559 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] rule registry: HashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 3
2016-05-18 01:21:03,560 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-05-18 01:21:03,699 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] 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/rhs.txt
2016-05-18 01:21:03,839 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] 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/lhs.txt
2016-05-18 01:21:03,887 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] 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/typedfieldedpipesplatform/testCoGroupComparableTypes/testCoGroupComparableTypes
2016-05-18 01:21:04,152 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/typedfieldedpipesplatform/testCoGroupComparableTypes/testCoGroupComparableTypes
2016-05-18 01:21:04,222 INFO  util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-18 01:21:04,222 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:21:04,288 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: ILLEGAL, in: 00:00.015
2016-05-18 01:21:04,297 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: ILLEGAL, in: 00:00.024
2016-05-18 01:21:04,298 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, found assembly to be malformed
2016-05-18 01:21:04,298 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] rule registry: HashJoinHadoop2TezRuleRegistry, found assembly to be malformed
2016-05-18 01:21:04,299 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/typedfieldedpipesplatform/testCoGroupIncomparableTypesDeclared/testCoGroupIncomparableTypesDeclared
2016-05-18 01:21:04,363 INFO  util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-18 01:21:04,364 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:21:04,440 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.033
2016-05-18 01:21:04,460 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.053
2016-05-18 01:21:04,461 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 3
2016-05-18 01:21:04,461 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] rule registry: HashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 3
2016-05-18 01:21:04,462 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-05-18 01:21:04,486 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] 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/rhs.txt
2016-05-18 01:21:04,503 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] 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/lhs.txt
2016-05-18 01:21:04,525 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] 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/typedfieldedpipesplatform/testCoGroupComparableTypesDeclared/testCoGroupComparableTypesDeclared
2016-05-18 01:21:04,684 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/typedfieldedpipesplatform/testCoGroupComparableTypesDeclared/testCoGroupComparableTypesDeclared
2016-05-18 01:21:04,723 INFO  util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-18 01:21:04,724 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:21:04,766 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: UNSUPPORTED, in: 00:00.000
2016-05-18 01:21:04,801 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.036
2016-05-18 01:21:04,802 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, does not support assembly
2016-05-18 01:21:04,803 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] rule registry: HashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 1
2016-05-18 01:21:04,803 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] rule registry: HashJoinHadoop2TezRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-05-18 01:21:04,883 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] 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/rhs.txt
2016-05-18 01:21:04,884 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] 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/lhs.txt
2016-05-18 01:21:04,885 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] 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/typedfieldedpipesplatform/testHashJoinComparableTypes/testHashJoinComparableTypes
2016-05-18 01:21:04,900 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/typedfieldedpipesplatform/testHashJoinComparableTypes/testHashJoinComparableTypes
2016-05-18 01:21:04,948 INFO  util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-18 01:21:04,949 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:21:05,008 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs+rhs] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.025
2016-05-18 01:21:05,030 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs+rhs] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.047
2016-05-18 01:21:05,031 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs+rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 3
2016-05-18 01:21:05,032 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs+rhs] rule registry: HashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 3
2016-05-18 01:21:05,032 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs+rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-05-18 01:21:05,057 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs+rhs] 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/lhs.txt
2016-05-18 01:21:05,067 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs+rhs] 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/rhs.txt
2016-05-18 01:21:05,076 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs+rhs] 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/typedfieldedpipesplatform/testGroupByComparableTypes/testGroupByComparableTypes
2016-05-18 01:21:05,154 INFO  tez.Hadoop2TezFlowStep (Hadoop2TezFlowStep.java:createDAG(265)) - adding grouped edge between: C0ED7F88F22E42A28EEBDFD621D083A3,D77E064ED455434089793782EA054F06 and E4E3D6685EAF4658A49244D2C492AE2F
2016-05-18 01:21:05,155 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/typedfieldedpipesplatform/testGroupByComparableTypes/testGroupByComparableTypes
2016-05-18 01:21:05,190 INFO  util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-18 01:21:05,190 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:21:05,225 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: UNSUPPORTED, in: 00:00.001
2016-05-18 01:21:05,241 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: ILLEGAL, in: 00:00.017
2016-05-18 01:21:05,243 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, does not support assembly
2016-05-18 01:21:05,244 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] rule registry: HashJoinHadoop2TezRuleRegistry, found assembly to be malformed
2016-05-18 01:21:05,244 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/typedfieldedpipesplatform/testHashJoinIncomparableTypesDeclared/testHashJoinIncomparableTypesDeclared
2016-05-18 01:21:05,280 INFO  util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-18 01:21:05,281 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:21:05,317 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: UNSUPPORTED, in: 00:00.001
2016-05-18 01:21:05,344 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.028
2016-05-18 01:21:05,345 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, does not support assembly
2016-05-18 01:21:05,345 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] rule registry: HashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 1
2016-05-18 01:21:05,346 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] rule registry: HashJoinHadoop2TezRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-05-18 01:21:05,404 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] 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/rhs.txt
2016-05-18 01:21:05,406 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] 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/lhs.txt
2016-05-18 01:21:05,407 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs*rhs] 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/typedfieldedpipesplatform/testHashJoinComparableTypesDeclared/testHashJoinComparableTypesDeclared
2016-05-18 01:21:05,423 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/typedfieldedpipesplatform/testHashJoinComparableTypesDeclared/testHashJoinComparableTypesDeclared
2016-05-18 01:21:05,461 INFO  util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-18 01:21:05,462 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:21:05,503 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs+rhs] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: ILLEGAL, in: 00:00.007
2016-05-18 01:21:05,512 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs+rhs] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: ILLEGAL, in: 00:00.016
2016-05-18 01:21:05,512 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs+rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, found assembly to be malformed
2016-05-18 01:21:05,512 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs+rhs] rule registry: HashJoinHadoop2TezRuleRegistry, found assembly to be malformed
2016-05-18 01:21:05,513 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/typedfieldedpipesplatform/testMergeIncomparableTypes/testMergeIncomparableTypes
2016-05-18 01:21:05,749 INFO  util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-18 01:21:05,749 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:21:05,829 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.035
2016-05-18 01:21:05,847 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.053
2016-05-18 01:21:05,848 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [] rule registry: NoHashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 3
2016-05-18 01:21:05,848 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [] rule registry: HashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 3
2016-05-18 01:21:05,848 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [] rule registry: NoHashJoinHadoop2TezRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-05-18 01:21:05,881 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [] 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-clean.10.txt
2016-05-18 01:21:05,907 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [] 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-clean.10.txt
2016-05-18 01:21:05,924 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [] 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/typedfieldedpipesplatform/testFieldTypeCheck/testFieldTypeCheck
2016-05-18 01:21:06,103 INFO  util.Version (Version.java:printBanner(82)) - Concurrent, Inc - Cascading 3.1.0
2016-05-18 01:21:06,110 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [] starting
2016-05-18 01:21:06,110 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - []  source: Hfs["TextDelimited[['ip', 'client', 'user', 'date', 'request', 'code', 'bytes', 'referrer', 'agent', 'na' | String, String, String, String, String, int, long, String, String, String]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache-clean.10.txt"]
2016-05-18 01:21:06,111 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - []  source: Hfs["TextDelimited[['ip', 'client', 'user', 'date', 'request', 'code', 'bytes', 'referrer', 'agent', 'na' | String, String, String, DateType{dateFormatString='dd/MMM/yyyy:HH:mm:ss Z',canonicalType='long'}, String, int, long, String, String, String]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache-clean.10.txt"]
2016-05-18 01:21:06,111 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - []  sink: Hfs["TextDelimited[['ip', 'client', 'user', 'date', 'request', 'code', 'bytes', 'referrer', 'agent', 'na', 10:19 | String, String, String, DateType{dateFormatString='dd/MMM/yyyy:HH:mm:ss Z',canonicalType='long'}, String, int, long, String, String, String, String, String, String, Long, String, int, long, String, String, String]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output/hadoop2-tez/typedfieldedpipesplatform/testFieldTypeCheck/testFieldTypeCheck"]
2016-05-18 01:21:06,111 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - []  parallel execution of steps is enabled: false
2016-05-18 01:21:06,112 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - []  executing total steps: 1
2016-05-18 01:21:06,112 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - []  allocating management threads: 1
2016-05-18 01:21:06,113 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [] starting step: (1/1) ...eCheck/testFieldTypeCheck
2016-05-18 01:21:06,114 WARN  flow.Flow (BaseFlow.java:logWarn(1516)) - [] '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:21:06,134 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [] tez session mode enabled: true
2016-05-18 01:21:06,271 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:21:06,280 INFO  client.TezClient (TezClient.java:start(394)) - Session mode. Starting session.
2016-05-18 01:21:06,280 INFO  client.TezClientUtils (TezClientUtils.java:setupTezJarsLocalResources(164)) - Ignoring 'tez.lib.uris' since  'tez.ignore.lib.uris' is set to true
2016-05-18 01:21:06,347 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/D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453/.tez/application_1463534466279_0001 doesn't exist and is created
2016-05-18 01:21:06,429 INFO  client.LocalClient (LocalClient.java:createDAGAppMaster(332)) - DAGAppMaster thread has been created
2016-05-18 01:21:06,429 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-05-18 01:21:06,431 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/D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453/.tez/application_1463534466279_0001_wd
2016-05-18 01:21:06,497 INFO  app.DAGAppMaster (DAGAppMaster.java:<init>(363)) - Created DAGAppMaster for application appattempt_1463534466279_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:21:06,511 INFO  shim.HadoopShimsLoader (HadoopShimsLoader.java:<init>(80)) - Trying to locate HadoopShimProvider for hadoopVersion=2.7.2, majorVersion=2, minorVersion=7
2016-05-18 01:21:06,511 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:21:06,514 INFO  app.DAGAppMaster (DAGAppMaster.java:serviceInit(436)) - AM Level configured TaskSchedulers: [0:TezUber:null]
2016-05-18 01:21:06,514 INFO  app.DAGAppMaster (DAGAppMaster.java:serviceInit(437)) - AM Level configured ContainerLaunchers: [0:TezUber:null]
2016-05-18 01:21:06,514 INFO  app.DAGAppMaster (DAGAppMaster.java:serviceInit(438)) - AM Level configured TaskCommunicators: [0:TezUber:null]
2016-05-18 01:21:06,514 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:21:06,529 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: NEW
2016-05-18 01:21:06,530 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(238)) - DAGAppMaster is not started wait for 100ms...
2016-05-18 01:21:06,530 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-05-18 01:21:06,536 INFO  app.TaskCommunicatorManager (TaskCommunicatorManager.java:createUberTaskCommunicator(192)) - Creating Default Local Task Communicator
2016-05-18 01:21:06,556 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:21:06,558 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:21:06,559 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:21:06,560 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:21:06,560 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:21:06,561 INFO  app.DAGAppMaster (DAGAppMaster.java:serviceInit(529)) - Using concurrent dispatcher: false
2016-05-18 01:21:06,562 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:21:06,563 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:21:06,564 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:21:06,564 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:21:06,573 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:21:06,579 INFO  launcher.TezContainerLauncherImpl (ContainerLauncherManager.java:createUberContainerLauncher(134)) - Creating LocalContainerLauncher
2016-05-18 01:21:06,594 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:21:06,596 INFO  node.AMNodeTracker (AMNodeTracker.java:serviceInit(78)) - blacklistDisablePercent is 33, blacklistingEnabled: false, maxTaskFailuresPerNode: 1, nodeUpdatesRescheduleEnabled: false
2016-05-18 01:21:06,597 INFO  history.HistoryEventHandler (HistoryEventHandler.java:serviceInit(57)) - Initializing HistoryEventHandler withrecoveryEnabled=true, historyServiceClassName=org.apache.tez.dag.history.logging.impl.SimpleHistoryLoggingService
2016-05-18 01:21:06,600 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/D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453/.tez/application_1463534466279_0001_wd/localmode-log-dir
2016-05-18 01:21:06,601 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/D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453/.tez/application_1463534466279_0001_wd/localmode-log-dir/history.txt.appattempt_1463534466279_0001_000000, maxErrors=10
2016-05-18 01:21:06,601 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/D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453/.tez/application_1463534466279_0001/recovery/0, bufferSize(bytes)=8192, flushInterval(s)=30, maxUnflushedEvents=100
2016-05-18 01:21:06,603 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:N/A][Event:AM_LAUNCHED]: appAttemptId=appattempt_1463534466279_0001_000000, appSubmitTime=1463534466478, launchTime=1463534466496
2016-05-18 01:21:06,617 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStart(95)) - Starting SimpleHistoryLoggingService
2016-05-18 01:21:06,630 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: INITED
2016-05-18 01:21:06,630 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(240)) - DAGAppMaster is not startetd wait for 100ms...
2016-05-18 01:21:06,630 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-05-18 01:21:06,673 INFO  client.DAGClientServer (DAGClientServer.java:serviceStart(91)) - Instantiated DAGClientRPCServer at ip-10-123-148-208.ec2.internal/10.123.148.208:51659
2016-05-18 01:21:06,675 INFO  rm.TaskSchedulerManager (TaskSchedulerManager.java:createUberTaskScheduler(557)) - Creating TaskScheduler: Local TaskScheduler with clusterIdentifier=1463534466279
2016-05-18 01:21:06,690 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:N/A][Event:AM_STARTED]: appAttemptId=appattempt_1463534466279_0001_000000, startTime=1463534466689
2016-05-18 01:21:06,690 INFO  app.DAGAppMaster (DAGAppMaster.java:serviceStart(1945)) - In Session mode. Waiting for DAG over RPC
2016-05-18 01:21:06,731 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: IDLE
2016-05-18 01:21:06,746 INFO  client.TezClient (TezClient.java:start(428)) - The url to track the Tez Session: N/A
2016-05-18 01:21:06,746 INFO  client.TezClient (TezClient.java:submitDAGSession(470)) - Submitting dag to TezSession, sessionName=(1/1) ...eCheck/testFieldTypeCheck, applicationId=application_1463534466279_0001, dagName=[D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453] null/(1/1) ...eCheck/testFieldTypeCheck
2016-05-18 01:21:06,946 INFO  app.DAGAppMaster (DAGAppMaster.java:submitDAGToAppMaster(1351)) - Starting DAG submitted via RPC: [D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453] null/(1/1) ...eCheck/testFieldTypeCheck
2016-05-18 01:21:06,955 INFO  app.DAGAppMaster (DAGAppMaster.java:createDAG(985)) - Merging AM credentials into DAG credentials
2016-05-18 01:21:07,010 INFO  app.DAGAppMaster (DAGAppMaster.java:generateDAGVizFile(1076)) - Generating DAG graphviz file, dagId=dag_1463534466279_0001_1, filePath=/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453/.tez/application_1463534466279_0001_wd/localmode-log-dir/dag_1463534466279_0001_1.dot
2016-05-18 01:21:07,015 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/D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453/.tez/application_1463534466279_0001_wd/localmode-log-dir/dag_1463534466279_0001_1-tez-dag.pb.txt
2016-05-18 01:21:07,064 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend: dag_1463534466279_0001_1
2016-05-18 01:21:07,065 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 01:21:07,065 INFO  app.DAGAppMaster (DAGAppMaster.java:startDAG(2399)) - Running DAG: [D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453] null/(1/1) ...eCheck/testFieldTypeCheck
2016-05-18 01:21:07 Running Dag: dag_1463534466279_0001_1
2016-05-18 01:21:07,096 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:DAG_SUBMITTED]: dagID=dag_1463534466279_0001_1, submitTime=1463534466947
2016-05-18 01:21:07,138 INFO  impl.VertexImpl (VertexImpl.java:<init>(928)) - Default container context for vertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D]=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/D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453/.tez/application_1463534466279_0001/tez-conf.pb" } size: 40992 timestamp: 1463534466000 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_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D], Default Resources=<memory:1024, vCores:1>
2016-05-18 01:21:07,138 INFO  impl.VertexImpl (VertexImpl.java:setAdditionalInputs(3978)) - Setting 1 additional inputs for vertexvertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D]
2016-05-18 01:21:07,139 INFO  impl.VertexImpl (VertexImpl.java:<init>(1016)) - Running vertex: vertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D] : TaskScheduler=0:TezUber, ContainerLauncher=0:TezUber, TaskCommunicator=0:TezUber
2016-05-18 01:21:07,140 INFO  impl.VertexImpl (VertexImpl.java:<init>(928)) - Default container context for vertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38]=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/D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453/.tez/application_1463534466279_0001/tez-conf.pb" } size: 40992 timestamp: 1463534466000 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_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38], Default Resources=<memory:1024, vCores:1>
2016-05-18 01:21:07,140 INFO  impl.VertexImpl (VertexImpl.java:setAdditionalInputs(3978)) - Setting 1 additional inputs for vertexvertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38]
2016-05-18 01:21:07,141 INFO  impl.VertexImpl (VertexImpl.java:<init>(1016)) - Running vertex: vertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38] : TaskScheduler=0:TezUber, ContainerLauncher=0:TezUber, TaskCommunicator=0:TezUber
2016-05-18 01:21:07,141 INFO  impl.VertexImpl (VertexImpl.java:<init>(928)) - Default container context for vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD]=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/D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453/.tez/application_1463534466279_0001/tez-conf.pb" } size: 40992 timestamp: 1463534466000 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_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD], Default Resources=<memory:1024, vCores:1>
2016-05-18 01:21:07,142 INFO  impl.VertexImpl (VertexImpl.java:setAdditionalOutputs(4023)) - Setting 1 additional outputs for vertex vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD]
2016-05-18 01:21:07,142 INFO  impl.VertexImpl (VertexImpl.java:<init>(1016)) - Running vertex: vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD] : TaskScheduler=0:TezUber, ContainerLauncher=0:TezUber, TaskCommunicator=0:TezUber
2016-05-18 01:21:07,150 INFO  impl.DAGImpl (DAGImpl.java:assignDAGScheduler(1593)) - Using DAG Scheduler: org.apache.tez.dag.app.dag.impl.DAGSchedulerNaturalOrderControlled
2016-05-18 01:21:07,152 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:DAG_INITIALIZED]: dagID=dag_1463534466279_0001_1, initTime=1463534467152
2016-05-18 01:21:07,153 INFO  impl.DAGImpl (DAGImpl.java:handle(1170)) - dag_1463534466279_0001_1 transitioned from NEW to INITED due to event DAG_INIT
2016-05-18 01:21:07,155 INFO  impl.DAGImpl (DAGImpl.java:transition(1768)) - Added additional resources : [[]] to classpath
2016-05-18 01:21:07,158 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:DAG_STARTED]: dagID=dag_1463534466279_0001_1, startTime=1463534467158
2016-05-18 01:21:07,158 INFO  impl.DAGImpl (DAGImpl.java:handle(1170)) - dag_1463534466279_0001_1 transitioned from INITED to RUNNING due to event DAG_START
2016-05-18 01:21:07,158 INFO  impl.VertexImpl (VertexImpl.java:setupVertex(2400)) - Root Inputs exist for Vertex: BEE015666FD14D0DB72C662D3BB75E38 : {991A05C15F1D48B1A414FE0BBA7F95B5={InputName=991A05C15F1D48B1A414FE0BBA7F95B5}, {Descriptor=ClassName=org.apache.tez.mapreduce.input.MRInput, hasPayload=true}, {ControllerDescriptor=ClassName=org.apache.tez.mapreduce.common.MRInputAMSplitGenerator, hasPayload=false}}
2016-05-18 01:21:07,159 INFO  impl.VertexImpl (VertexImpl.java:setupVertex(2410)) - Starting root input initializer for input: 991A05C15F1D48B1A414FE0BBA7F95B5, with class: [org.apache.tez.mapreduce.common.MRInputAMSplitGenerator]
2016-05-18 01:21:07,159 INFO  impl.VertexImpl (VertexImpl.java:assignVertexManager(2550)) - Setting vertexManager to RootInputVertexManager for vertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38]
2016-05-18 01:21:07,166 INFO  client.TezClient (TezClient.java:submitDAGSession(545)) - Submitted dag to TezSession, sessionName=(1/1) ...eCheck/testFieldTypeCheck, applicationId=application_1463534466279_0001, dagName=[D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453] null/(1/1) ...eCheck/testFieldTypeCheck
2016-05-18 01:21:07,168 INFO  impl.VertexImpl (VertexImpl.java:handleInitEvent(2721)) - Num tasks is -1. Expecting VertexManager/InputInitializers/1-1 split to set #tasks for the vertex vertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38]
2016-05-18 01:21:07,168 INFO  impl.VertexImpl (VertexImpl.java:handleInitEvent(2726)) - Vertex will initialize from input initializer. vertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38]
2016-05-18 01:21:07,169 INFO  impl.VertexImpl (VertexImpl.java:setupInputInitializerManager(3893)) - Starting 1 inputInitializers for vertex vertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38]
2016-05-18 01:21:07,175 INFO  dag.RootInputInitializerManager (RootInputInitializerManager.java:run(272)) - Starting InputInitializer for Input: 991A05C15F1D48B1A414FE0BBA7F95B5 on vertex vertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38]
2016-05-18 01:21:07,189 INFO  impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38] transitioned from NEW to INITIALIZING due to event V_INIT
2016-05-18 01:21:07,189 INFO  impl.VertexImpl (VertexImpl.java:setupVertex(2400)) - Root Inputs exist for Vertex: D71EBA5E0D814A4EAD95DED1BB0DD35D : {142AFC53D536492BBB48F028C4D54415={InputName=142AFC53D536492BBB48F028C4D54415}, {Descriptor=ClassName=org.apache.tez.mapreduce.input.MRInput, hasPayload=true}, {ControllerDescriptor=ClassName=org.apache.tez.mapreduce.common.MRInputAMSplitGenerator, hasPayload=false}}
2016-05-18 01:21:07,190 INFO  impl.VertexImpl (VertexImpl.java:setupVertex(2410)) - Starting root input initializer for input: 142AFC53D536492BBB48F028C4D54415, with class: [org.apache.tez.mapreduce.common.MRInputAMSplitGenerator]
2016-05-18 01:21:07,190 INFO  impl.VertexImpl (VertexImpl.java:assignVertexManager(2550)) - Setting vertexManager to RootInputVertexManager for vertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D]
2016-05-18 01:21:07,190 INFO  impl.VertexImpl (VertexImpl.java:handleInitEvent(2721)) - Num tasks is -1. Expecting VertexManager/InputInitializers/1-1 split to set #tasks for the vertex vertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D]
2016-05-18 01:21:07,191 INFO  impl.VertexImpl (VertexImpl.java:handleInitEvent(2726)) - Vertex will initialize from input initializer. vertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D]
2016-05-18 01:21:07,191 INFO  impl.VertexImpl (VertexImpl.java:setupInputInitializerManager(3893)) - Starting 1 inputInitializers for vertex vertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D]
2016-05-18 01:21:07,192 INFO  impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D] transitioned from NEW to INITIALIZING due to event V_INIT
2016-05-18 01:21:07,192 INFO  impl.VertexImpl (VertexImpl.java:assignVertexManager(2562)) - Setting vertexManager to ShuffleVertexManager for vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD]
2016-05-18 01:21:07,196 INFO  common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(109)) - Input 991A05C15F1D48B1A414FE0BBA7F95B5 asking for 1 tasks. Headroom: 672 Task Resource: 1024 waves: 1.7, groupingEnabled: true
2016-05-18 01:21:07,198 INFO  dag.RootInputInitializerManager (RootInputInitializerManager.java:run(272)) - Starting InputInitializer for Input: 142AFC53D536492BBB48F028C4D54415 on vertex vertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D]
2016-05-18 01:21:07,212 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:21:07,213 INFO  impl.VertexImpl (VertexImpl.java:handleInitEvent(2760)) - Creating 1 tasks for vertex: vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD]
2016-05-18 01:21:07,218 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [] submitted tez dag to app master: application_1463534466279_0001, with dag id: dag_1463534466279_0001_1
2016-05-18 01:21:07,217 INFO  common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(109)) - Input 142AFC53D536492BBB48F028C4D54415 asking for 1 tasks. Headroom: 672 Task Resource: 1024 waves: 1.7, groupingEnabled: true
2016-05-18 01:21:07,238 INFO  grouper.TezSplitGrouper (TezSplitGrouper.java:getGroupedSplits(168)) - Grouping splits in Tez
2016-05-18 01:21:07,238 INFO  grouper.TezSplitGrouper (TezSplitGrouper.java:getGroupedSplits(168)) - Grouping splits in Tez
2016-05-18 01:21:07,239 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:21:07,239 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:21:07,240 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:21:07,241 INFO  grouper.TezSplitGrouper (TezSplitGrouper.java:getGroupedSplits(539)) - Number of splits desired: 1 created: 1 splitsProcessed: 2
2016-05-18 01:21:07,240 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:21:07,241 INFO  grouper.TezSplitGrouper (TezSplitGrouper.java:getGroupedSplits(539)) - Number of splits desired: 1 created: 1 splitsProcessed: 2
2016-05-18 01:21:07,245 INFO  impl.VertexImpl (VertexImpl.java:handleInitEvent(2779)) - Directly initializing vertex: vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD]
2016-05-18 01:21:07,251 INFO  dag.RootInputInitializerManager (RootInputInitializerManager.java:onSuccess(308)) - Succeeded InputInitializer for Input: 142AFC53D536492BBB48F028C4D54415 on vertex vertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D]
2016-05-18 01:21:07,251 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:VERTEX_CONFIGURE_DONE]: vertexId=vertex_1463534466279_0001_1_02, reconfigureDoneTime=0, numTasks=1, vertexLocationHint=null, edgeManagersCount=2, rootInputSpecUpdateCount=0, setParallelismCalledFlag=false
2016-05-18 01:21:07,252 INFO  impl.VertexImpl (VertexImpl.java:initializeCommitters(2187)) - Setting up committers for vertex vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD], numAdditionalOutputs=1
2016-05-18 01:21:07,252 INFO  dag.RootInputInitializerManager (RootInputInitializerManager.java:onSuccess(308)) - Succeeded InputInitializer for Input: 991A05C15F1D48B1A414FE0BBA7F95B5 on vertex vertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38]
2016-05-18 01:21:07,255 INFO  impl.VertexImpl (VertexImpl.java:initializeCommitters(2202)) - Instantiating committer for output=A24A65E16249416EBE5023A2128E2CD9, vertex=vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD], committerClass=org.apache.tez.mapreduce.committer.MROutputCommitter
2016-05-18 01:21:07,268 INFO  committer.MROutputCommitter (MROutputCommitter.java:getOutputCommitter(121)) - Committer for FCA327A24AE447C8B29F99C6C8C9BEFD:A24A65E16249416EBE5023A2128E2CD9 using oldmapred API
2016-05-18 01:21:07,269 INFO  committer.MROutputCommitter (MROutputCommitter.java:getOutputCommitter(146)) - OutputCommitter for outputName=A24A65E16249416EBE5023A2128E2CD9, vertexName=FCA327A24AE447C8B29F99C6C8C9BEFD, outputCommitterClass=org.apache.hadoop.mapred.FileOutputCommitter
2016-05-18 01:21:07,279 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:VERTEX_INITIALIZED]: vertexName=FCA327A24AE447C8B29F99C6C8C9BEFD, vertexId=vertex_1463534466279_0001_1_02, initRequestedTime=1463534467192, initedTime=1463534467252, numTasks=1, processorName=cascading.flow.tez.FlowProcessor, additionalInputsCount=0, initGeneratedEventsCount=0
2016-05-18 01:21:07,280 INFO  impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD] transitioned from NEW to INITED due to event V_INIT
2016-05-18 01:21:07,285 INFO  impl.VertexImpl (VertexImpl.java:canInitVertex(2972)) - Cannot init vertex: vertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D] numTasks: -1 numUnitializedEdges: 0 numInitializedInputs: 1 initWaitsForRootInitializers: true
2016-05-18 01:21:07,286 INFO  impl.VertexImpl (VertexImpl.java:canInitVertex(2972)) - Cannot init vertex: vertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38] numTasks: -1 numUnitializedEdges: 0 numInitializedInputs: 1 initWaitsForRootInitializers: true
2016-05-18 01:21:07,288 INFO  impl.VertexImpl (VertexImpl.java:setParallelismWrapper(1644)) - Got updated RootInputsSpecs: {142AFC53D536492BBB48F028C4D54415=forAllWorkUnits=true, update=[1]}
2016-05-18 01:21:07,290 INFO  impl.VertexImpl (VertexImpl.java:setParallelismWrapper(1644)) - Got updated RootInputsSpecs: {991A05C15F1D48B1A414FE0BBA7F95B5=forAllWorkUnits=true, update=[1]}
2016-05-18 01:21:07,290 INFO  impl.VertexImpl (VertexImpl.java:setParallelismWrapper(1664)) - Vertex vertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D] parallelism set to 1
2016-05-18 01:21:07,290 INFO  impl.VertexImpl (VertexImpl.java:canInitVertex(2972)) - Cannot init vertex: vertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D] numTasks: 1 numUnitializedEdges: 0 numInitializedInputs: 1 initWaitsForRootInitializers: true
2016-05-18 01:21:07,292 INFO  impl.VertexImpl (VertexImpl.java:setParallelismWrapper(1664)) - Vertex vertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38] parallelism set to 1
2016-05-18 01:21:07,293 INFO  impl.VertexImpl (VertexImpl.java:canInitVertex(2972)) - Cannot init vertex: vertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38] numTasks: 1 numUnitializedEdges: 0 numInitializedInputs: 1 initWaitsForRootInitializers: true
2016-05-18 01:21:07,301 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:VERTEX_INITIALIZED]: vertexName=BEE015666FD14D0DB72C662D3BB75E38, vertexId=vertex_1463534466279_0001_1_01, initRequestedTime=1463534467158, initedTime=1463534467301, numTasks=1, processorName=cascading.flow.tez.FlowProcessor, additionalInputsCount=1, initGeneratedEventsCount=1
2016-05-18 01:21:07,302 INFO  impl.VertexImpl (VertexImpl.java:startIfPossible(2814)) - Triggering start event for vertex: vertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38] with distanceFromRoot: 0
2016-05-18 01:21:07,302 INFO  impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38] transitioned from INITIALIZING to INITED due to event V_INPUT_DATA_INFORMATION
2016-05-18 01:21:07,302 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:VERTEX_INITIALIZED]: vertexName=D71EBA5E0D814A4EAD95DED1BB0DD35D, vertexId=vertex_1463534466279_0001_1_00, initRequestedTime=1463534467189, initedTime=1463534467302, numTasks=1, processorName=cascading.flow.tez.FlowProcessor, additionalInputsCount=1, initGeneratedEventsCount=1
2016-05-18 01:21:07,302 INFO  impl.VertexImpl (VertexImpl.java:startIfPossible(2814)) - Triggering start event for vertex: vertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D] with distanceFromRoot: 0
2016-05-18 01:21:07,302 INFO  impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D] transitioned from INITIALIZING to INITED due to event V_INPUT_DATA_INFORMATION
2016-05-18 01:21:07,303 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:VERTEX_STARTED]: vertexId=vertex_1463534466279_0001_1_01, startRequestedTime=1463534467192, startedTime=1463534467302
2016-05-18 01:21:07,304 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:VERTEX_CONFIGURE_DONE]: vertexId=vertex_1463534466279_0001_1_01, reconfigureDoneTime=0, numTasks=1, vertexLocationHint=org.apache.tez.dag.api.VertexLocationHint@b8338fe7, edgeManagersCount=0, rootInputSpecUpdateCount=1, setParallelismCalledFlag=true
2016-05-18 01:21:07,306 INFO  impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38] transitioned from INITED to RUNNING due to event V_START
2016-05-18 01:21:07,306 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:VERTEX_STARTED]: vertexId=vertex_1463534466279_0001_1_00, startRequestedTime=1463534467192, startedTime=1463534467306
2016-05-18 01:21:07,307 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:VERTEX_CONFIGURE_DONE]: vertexId=vertex_1463534466279_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:21:07,307 INFO  impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D] transitioned from INITED to RUNNING due to event V_START
2016-05-18 01:21:07,307 INFO  impl.VertexImpl (VertexImpl.java:transition(2932)) - Source vertex started: vertex_1463534466279_0001_1_01 for vertex: vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD] numStartedSources: 1 numSources: 2
2016-05-18 01:21:07,308 INFO  impl.ImmediateStartVertexManager (ImmediateStartVertexManager.java:scheduleTasks(100)) - Starting 1 in D71EBA5E0D814A4EAD95DED1BB0DD35D
2016-05-18 01:21:07,308 INFO  impl.VertexImpl (VertexImpl.java:transition(2937)) - Cannot start vertex: vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD] numStartedSources: 1 numSources: 2
2016-05-18 01:21:07,308 INFO  impl.VertexImpl (VertexImpl.java:transition(2932)) - Source vertex started: vertex_1463534466279_0001_1_00 for vertex: vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD] numStartedSources: 2 numSources: 2
2016-05-18 01:21:07,308 INFO  impl.VertexImpl (VertexImpl.java:startIfPossible(2814)) - Triggering start event for vertex: vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD] with distanceFromRoot: 1
2016-05-18 01:21:07,309 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:VERTEX_STARTED]: vertexId=vertex_1463534466279_0001_1_02, startRequestedTime=1463534467308, startedTime=1463534467309
2016-05-18 01:21:07,309 INFO  impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD] transitioned from INITED to RUNNING due to event V_START
2016-05-18 01:21:07,308 INFO  impl.VertexImpl (VertexImpl.java:unsetTasksNotYetScheduled(1466)) - Routing pending task events for vertex: vertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D]
2016-05-18 01:21:07,309 INFO  impl.ImmediateStartVertexManager (ImmediateStartVertexManager.java:scheduleTasks(100)) - Starting 1 in BEE015666FD14D0DB72C662D3BB75E38
2016-05-18 01:21:07,310 INFO  impl.VertexImpl (VertexImpl.java:unsetTasksNotYetScheduled(1466)) - Routing pending task events for vertex: vertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38]
2016-05-18 01:21:07,318 INFO  vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:onVertexStarted(519)) - OnVertexStarted vertex: FCA327A24AE447C8B29F99C6C8C9BEFD with 0 source tasks and 1 pending tasks
2016-05-18 01:21:07,319 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:TASK_STARTED]: vertexName=D71EBA5E0D814A4EAD95DED1BB0DD35D, taskId=task_1463534466279_0001_1_00_000000, scheduledTime=1463534467318, launchTime=1463534467318
2016-05-18 01:21:07,321 INFO  vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:handleVertexStateUpdate(1051)) - Received configured notification : CONFIGURED for vertex: BEE015666FD14D0DB72C662D3BB75E38 in vertex: FCA327A24AE447C8B29F99C6C8C9BEFD numBipartiteSourceTasks: 1
2016-05-18 01:21:07,329 INFO  vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:handleVertexStateUpdate(1051)) - Received configured notification : CONFIGURED for vertex: D71EBA5E0D814A4EAD95DED1BB0DD35D in vertex: FCA327A24AE447C8B29F99C6C8C9BEFD numBipartiteSourceTasks: 2
2016-05-18 01:21:07,342 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:TASK_STARTED]: vertexName=BEE015666FD14D0DB72C662D3BB75E38, taskId=task_1463534466279_0001_1_01_000000, scheduledTime=1463534467342, launchTime=1463534467342
2016-05-18 01:21:07,347 INFO  impl.DAGSchedulerNaturalOrderControlled (DAGSchedulerNaturalOrderControlled.java:scheduleTaskEx(106)) - Scheduled vertex: vertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D]
2016-05-18 01:21:07,347 INFO  impl.DAGSchedulerNaturalOrderControlled (DAGSchedulerNaturalOrderControlled.java:scheduleTaskEx(106)) - Scheduled vertex: vertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38]
2016-05-18 01:21:07,393 INFO  node.PerSourceNodeTracker (PerSourceNodeTracker.java:nodeSeen(74)) - Adding new node 127.0.0.1:0 to nodeTracker 0
2016-05-18 01:21:07,413 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:N/A][Event:CONTAINER_LAUNCHED]: containerId=container_1463534466279_0001_00_000001, launchTime=1463534467413
2016-05-18 01:21:07,413 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:N/A][Event:CONTAINER_LAUNCHED]: containerId=container_1463534466279_0001_00_000002, launchTime=1463534467413
2016-05-18 01:21:07,418 INFO  task.ContainerReporter (ContainerReporter.java:callInternal(57)) - Attempting to fetch new task for container container_1463534466279_0001_00_000002
2016-05-18 01:21:07,418 INFO  task.ContainerReporter (ContainerReporter.java:callInternal(57)) - Attempting to fetch new task for container container_1463534466279_0001_00_000001
2016-05-18 01:21:07,422 INFO  task.ContainerReporter (ContainerReporter.java:callInternal(67)) - Got TaskUpdate for containerId= container_1463534466279_0001_00_000002: 0 ms after starting to poll. TaskInfo: shouldDie: false, currentTaskAttemptId: attempt_1463534466279_0001_1_01_000000_0
2016-05-18 01:21:07 Starting to run new task attempt: attempt_1463534466279_0001_1_01_000000_0
2016-05-18 01:21:07,424 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1322)) - TaskAttempt: [attempt_1463534466279_0001_1_01_000000_0] started. Is using containerId: [container_1463534466279_0001_00_000002] on NM: [127.0.0.1:0]
2016-05-18 01:21:07,424 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend: attempt_1463534466279_0001_1_01_000000_0
2016-05-18 01:21:07,425 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 01:21:07,426 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:TASK_ATTEMPT_STARTED]: vertexName=BEE015666FD14D0DB72C662D3BB75E38, taskAttemptId=attempt_1463534466279_0001_1_01_000000_0, startTime=1463534467422, containerId=container_1463534466279_0001_00_000002, nodeId=127.0.0.1:0
2016-05-18 01:21:07,426 INFO  task.TezChild (TezChild.java:handleNewTaskCredentials(306)) - Refreshing UGI since Credentials have changed. Credentials : #Tokens=1, #SecretKeys=0
2016-05-18 01:21:07,427 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1322)) - TaskAttempt: [attempt_1463534466279_0001_1_00_000000_0] started. Is using containerId: [container_1463534466279_0001_00_000001] on NM: [127.0.0.1:0]
2016-05-18 01:21:07,428 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:TASK_ATTEMPT_STARTED]: vertexName=D71EBA5E0D814A4EAD95DED1BB0DD35D, taskAttemptId=attempt_1463534466279_0001_1_00_000000_0, startTime=1463534467427, containerId=container_1463534466279_0001_00_000001, nodeId=127.0.0.1:0
2016-05-18 01:21:07,429 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:21:07,437 INFO  task.ContainerReporter (ContainerReporter.java:callInternal(67)) - Got TaskUpdate for containerId= container_1463534466279_0001_00_000001: 0 ms after starting to poll. TaskInfo: shouldDie: false, currentTaskAttemptId: attempt_1463534466279_0001_1_00_000000_0
2016-05-18 01:21:07 Starting to run new task attempt: attempt_1463534466279_0001_1_00_000000_0
2016-05-18 01:21:07,440 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend: attempt_1463534466279_0001_1_00_000000_0
2016-05-18 01:21:07,440 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 01:21:07,440 INFO  task.TezChild (TezChild.java:handleNewTaskCredentials(306)) - Refreshing UGI since Credentials have changed. Credentials : #Tokens=1, #SecretKeys=0
2016-05-18 01:21:07,445 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:<init>(166)) - Initializing LogicalIOProcessorRuntimeTask with TaskSpec: DAGName : [D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453] null/(1/1) ...eCheck/testFieldTypeCheck, VertexName: D71EBA5E0D814A4EAD95DED1BB0DD35D, VertexParallelism: 1, TaskAttemptID:attempt_1463534466279_0001_1_00_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=142AFC53D536492BBB48F028C4D54415, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=FCA327A24AE447C8B29F99C6C8C9BEFD, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }}, ]
2016-05-18 01:21:07,445 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:<init>(166)) - Initializing LogicalIOProcessorRuntimeTask with TaskSpec: DAGName : [D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453] null/(1/1) ...eCheck/testFieldTypeCheck, VertexName: BEE015666FD14D0DB72C662D3BB75E38, VertexParallelism: 1, TaskAttemptID:attempt_1463534466279_0001_1_01_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=991A05C15F1D48B1A414FE0BBA7F95B5, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=FCA327A24AE447C8B29F99C6C8C9BEFD, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }}, ]
2016-05-18 01:21:07,447 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:21:07,447 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:21:07,451 INFO  task.TaskRunner2Callable (TaskRunner2Callable.java:run(65)) - Initializing task, taskAttemptId=attempt_1463534466279_0001_1_01_000000_0
2016-05-18 01:21:07,451 INFO  task.TaskRunner2Callable (TaskRunner2Callable.java:run(65)) - Initializing task, taskAttemptId=attempt_1463534466279_0001_1_00_000000_0
2016-05-18 01:21:07,463 INFO  impl.TaskImpl (TaskImpl.java:getTaskAttemptTezEvents(496)) - TaskAttempt:attempt_1463534466279_0001_1_01_000000_0 sent events: (0-1).
2016-05-18 01:21:07,463 INFO  impl.TaskImpl (TaskImpl.java:getTaskAttemptTezEvents(496)) - TaskAttempt:attempt_1463534466279_0001_1_00_000000_0 sent events: (0-1).
2016-05-18 01:21:07,465 INFO  task.TaskReporter (TaskReporter.java:heartbeat(292)) - Routing events from heartbeat response to task, currentTaskAttemptId=attempt_1463534466279_0001_1_01_000000_0, eventCount=1 fromEventId=0 nextFromEventId=0
2016-05-18 01:21:07,465 INFO  task.TaskReporter (TaskReporter.java:heartbeat(292)) - Routing events from heartbeat response to task, currentTaskAttemptId=attempt_1463534466279_0001_1_00_000000_0, eventCount=1 fromEventId=0 nextFromEventId=0
2016-05-18 01:21:07,480 INFO  tez.FlowProcessor (FlowProcessor.java:initialize(88)) - cascading version: 3.1.0
2016-05-18 01:21:07,483 INFO  tez.FlowProcessor (FlowProcessor.java:initialize(88)) - cascading version: 3.1.0
2016-05-18 01:21:07,491 INFO  input.MRInput (MRInput.java:initialize(440)) - 142AFC53D536492BBB48F028C4D54415 using newmapreduce API=false, split via event=true, numPhysicalInputs=1
2016-05-18 01:21:07,498 INFO  input.MRInput (MRInput.java:initializeInternal(494)) - Initialized MRInput: 142AFC53D536492BBB48F028C4D54415
2016-05-18 01:21:07,491 INFO  input.MRInput (MRInput.java:initialize(440)) - 991A05C15F1D48B1A414FE0BBA7F95B5 using newmapreduce API=false, split via event=true, numPhysicalInputs=1
2016-05-18 01:21:07,499 INFO  input.MRInput (MRInput.java:initializeInternal(494)) - Initialized MRInput: 991A05C15F1D48B1A414FE0BBA7F95B5
2016-05-18 01:21:07,513 INFO  tez.FlowProcessor (FlowProcessor.java:initialize(94)) - flow node id: BEE015666FD14D0DB72C662D3BB75E38, ordinal: 0
2016-05-18 01:21:07,514 INFO  tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: BEE015666FD14D0DB72C662D3BB75E38, mem on start (mb), free: 242, total: 397, max: 672
2016-05-18 01:21:07,514 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(562)) - Initialized processor
2016-05-18 01:21:07,514 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(239)) - Waiting for 2 initializers to finish
2016-05-18 01:21:07,514 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(239)) - Waiting for 1 initializers to finish
2016-05-18 01:21:07,514 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(252)) - All initializers finished
2016-05-18 01:21:07,514 INFO  resources.MemoryDistributor (MemoryDistributor.java:logInitialRequests(275)) - InitialRequests=[991A05C15F1D48B1A414FE0BBA7F95B5:INPUT:0:org.apache.tez.mapreduce.input.MRInput], [FCA327A24AE447C8B29F99C6C8C9BEFD:OUTPUT:104857600:org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput]
2016-05-18 01:21:07,517 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:21:07,520 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:computeReservedFraction(266)) - InitialReservationFraction=0.3, AdditionalReservationFractionForIOs=0.03, finalReserveFractionUsed=0.32999999999999996
2016-05-18 01:21:07,520 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:21:07,520 INFO  resources.MemoryDistributor (MemoryDistributor.java:logFinalAllocations(297)) - Allocations=[991A05C15F1D48B1A414FE0BBA7F95B5:org.apache.tez.mapreduce.input.MRInput:INPUT:0:0], [FCA327A24AE447C8B29F99C6C8C9BEFD:org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput:OUTPUT:104857600:104857600]
2016-05-18 01:21:07,520 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(274)) - Starting Inputs/Outputs
2016-05-18 01:21:07,522 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:_callInternal(474)) - Started Input with src edge: 991A05C15F1D48B1A414FE0BBA7F95B5
2016-05-18 01:21:07,522 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(287)) - Input: 991A05C15F1D48B1A414FE0BBA7F95B5 being auto started by the framework. Subsequent instances will not be auto-started
2016-05-18 01:21:07,522 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(308)) - Num IOs determined for AutoStart: 1
2016-05-18 01:21:07,523 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(310)) - Waiting for 1 IOs to start
2016-05-18 01:21:07,523 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(323)) - AutoStartComplete
2016-05-18 01:21:07,524 INFO  task.TaskRunner2Callable (TaskRunner2Callable.java:run(70)) - Running task, taskAttemptId=attempt_1463534466279_0001_1_01_000000_0
2016-05-18 01:21:07,526 INFO  tez.FlowProcessor (FlowProcessor.java:initialize(94)) - flow node id: D71EBA5E0D814A4EAD95DED1BB0DD35D, ordinal: 1
2016-05-18 01:21:07,527 INFO  tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: D71EBA5E0D814A4EAD95DED1BB0DD35D, mem on start (mb), free: 239, total: 397, max: 672
2016-05-18 01:21:07,527 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(562)) - Initialized processor
2016-05-18 01:21:07,527 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(239)) - Waiting for 2 initializers to finish
2016-05-18 01:21:07,527 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(239)) - Waiting for 1 initializers to finish
2016-05-18 01:21:07,528 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(252)) - All initializers finished
2016-05-18 01:21:07,528 INFO  resources.MemoryDistributor (MemoryDistributor.java:logInitialRequests(275)) - InitialRequests=[142AFC53D536492BBB48F028C4D54415:INPUT:0:org.apache.tez.mapreduce.input.MRInput], [FCA327A24AE447C8B29F99C6C8C9BEFD:OUTPUT:104857600:org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput]
2016-05-18 01:21:07,528 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:21:07,529 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:computeReservedFraction(266)) - InitialReservationFraction=0.3, AdditionalReservationFractionForIOs=0.03, finalReserveFractionUsed=0.32999999999999996
2016-05-18 01:21:07,529 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:21:07,530 INFO  resources.MemoryDistributor (MemoryDistributor.java:logFinalAllocations(297)) - Allocations=[142AFC53D536492BBB48F028C4D54415:org.apache.tez.mapreduce.input.MRInput:INPUT:0:0], [FCA327A24AE447C8B29F99C6C8C9BEFD:org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput:OUTPUT:104857600:104857600]
2016-05-18 01:21:07,530 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(274)) - Starting Inputs/Outputs
2016-05-18 01:21:07,530 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:_callInternal(474)) - Started Input with src edge: 142AFC53D536492BBB48F028C4D54415
2016-05-18 01:21:07,530 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(287)) - Input: 142AFC53D536492BBB48F028C4D54415 being auto started by the framework. Subsequent instances will not be auto-started
2016-05-18 01:21:07,531 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(308)) - Num IOs determined for AutoStart: 1
2016-05-18 01:21:07,531 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(310)) - Waiting for 1 IOs to start
2016-05-18 01:21:07,532 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(323)) - AutoStartComplete
2016-05-18 01:21:07,532 INFO  task.TaskRunner2Callable (TaskRunner2Callable.java:run(70)) - Running task, taskAttemptId=attempt_1463534466279_0001_1_00_000000_0
2016-05-18 01:21:07,544 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-clean.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-clean.10.txt:724+725], wrappedInputFormatName='org.apache.hadoop.mapred.TextInputFormat', locations=[localhost], rack='null', length=1449}
2016-05-18 01:21:07,544 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-clean.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-clean.10.txt:724+725], wrappedInputFormatName='org.apache.hadoop.mapred.TextInputFormat', locations=[localhost], rack='null', length=1449}
2016-05-18 01:21:07,545 INFO  input.MRInput (MRInput.java:initFromEventInternal(653)) - 142AFC53D536492BBB48F028C4D54415 initialized RecordReader from event
2016-05-18 01:21:07,545 INFO  input.MRInput (MRInput.java:initFromEventInternal(653)) - 991A05C15F1D48B1A414FE0BBA7F95B5 initialized RecordReader from event
2016-05-18 01:21:07,557 INFO  graph.Hadoop2TezStreamGraph (Hadoop2TezStreamGraph.java:buildGraph(151)) - using streamed source: Hfs["TextDelimited[['ip', 'client', 'user', 'date', 'request', 'code', 'bytes', 'referrer', 'agent', 'na' | String, String, String, String, String, int, long, String, String, String]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache-clean.10.txt"]
2016-05-18 01:21:07,571 INFO  graph.Hadoop2TezStreamGraph (Hadoop2TezStreamGraph.java:buildGraph(151)) - using streamed source: Hfs["TextDelimited[['ip', 'client', 'user', 'date', 'request', 'code', 'bytes', 'referrer', 'agent', 'na' | String, String, String, DateType{dateFormatString='dd/MMM/yyyy:HH:mm:ss Z',canonicalType='long'}, String, int, long, String, String, String]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache-clean.10.txt"]
2016-05-18 01:21:07,586 INFO  tez.FlowProcessor (FlowProcessor.java:run(121)) - sourcing from: Hfs["TextDelimited[['ip', 'client', 'user', 'date', 'request', 'code', 'bytes', 'referrer', 'agent', 'na' | String, String, String, DateType{dateFormatString='dd/MMM/yyyy:HH:mm:ss Z',canonicalType='long'}, String, int, long, String, String, String]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache-clean.10.txt"] streamed: true, id: 991A05C15F1D48B1A414FE0BBA7F95B5
2016-05-18 01:21:07,586 INFO  tez.FlowProcessor (FlowProcessor.java:run(124)) - sinking to: CoGroup(lhs*rhs)[by: lhs:[{1}:'date'] rhs:[{1}:'date']], id: 5323050D5774404998ACF069DB614D85
2016-05-18 01:21:07,587 INFO  element.TezGroupGate (TezGroupGate.java:prepare(98)) - calling OrderedPartitionedKVOutput#start() on: CoGroup(lhs*rhs)[by: lhs:[{1}:'date'] rhs:[{1}:'date']] 5323050D5774404998ACF069DB614D85
2016-05-18 01:21:07,587 INFO  tez.FlowProcessor (FlowProcessor.java:run(121)) - sourcing from: Hfs["TextDelimited[['ip', 'client', 'user', 'date', 'request', 'code', 'bytes', 'referrer', 'agent', 'na' | String, String, String, String, String, int, long, String, String, String]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache-clean.10.txt"] streamed: true, id: 142AFC53D536492BBB48F028C4D54415
2016-05-18 01:21:07,587 INFO  tez.FlowProcessor (FlowProcessor.java:run(124)) - sinking to: CoGroup(lhs*rhs)[by: lhs:[{1}:'date'] rhs:[{1}:'date']], id: 5323050D5774404998ACF069DB614D85
2016-05-18 01:21:07,588 INFO  element.TezGroupGate (TezGroupGate.java:prepare(98)) - calling OrderedPartitionedKVOutput#start() on: CoGroup(lhs*rhs)[by: lhs:[{1}:'date'] rhs:[{1}:'date']] 5323050D5774404998ACF069DB614D85
2016-05-18 01:21:07,610 INFO  util.BaseTupleComparator (BaseTupleComparator.java:setConf(57)) - enabling raw byte comparison and ordering
2016-05-18 01:21:07,610 INFO  util.BaseTupleComparator (BaseTupleComparator.java:setConf(57)) - enabling raw byte comparison and ordering
2016-05-18 01:21:07,614 INFO  hadoop.TupleSerialization (TupleSerialization.java:areTypesRequired(287)) - types are being enforced during serialization
2016-05-18 01:21:07,614 INFO  hadoop.TupleSerialization (TupleSerialization.java:areTypesRequired(287)) - types are being enforced during serialization
2016-05-18 01:21:07,631 INFO  util.BaseTupleComparator (BaseTupleComparator.java:setConf(57)) - enabling raw byte comparison and ordering
2016-05-18 01:21:07,631 INFO  impl.ExternalSorter (ExternalSorter.java:<init>(199)) - FCA327A24AE447C8B29F99C6C8C9BEFD using: memoryMb=100, keySerializerClass=class cascading.tuple.io.KeyTuple, valueSerializerClass=cascading.tuple.hadoop.io.ValueTupleSerializer@680f39c5, comparator=cascading.tuple.hadoop.util.TupleComparator@11ca150d, 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:21:07,635 INFO  util.BaseTupleComparator (BaseTupleComparator.java:setConf(57)) - enabling raw byte comparison and ordering
2016-05-18 01:21:07,635 INFO  impl.ExternalSorter (ExternalSorter.java:<init>(199)) - FCA327A24AE447C8B29F99C6C8C9BEFD using: memoryMb=100, keySerializerClass=class cascading.tuple.io.KeyTuple, valueSerializerClass=cascading.tuple.hadoop.io.ValueTupleSerializer@3f99e9e2, comparator=cascading.tuple.hadoop.util.TupleComparator@671a7db9, 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:21:07,638 INFO  impl.PipelinedSorter (PipelinedSorter.java:<init>(170)) - Setting up PipelinedSorter for FCA327A24AE447C8B29F99C6C8C9BEFD: , UsingHashComparator=false
2016-05-18 01:21:07,638 INFO  impl.PipelinedSorter (PipelinedSorter.java:<init>(170)) - Setting up PipelinedSorter for FCA327A24AE447C8B29F99C6C8C9BEFD: , UsingHashComparator=false
2016-05-18 01:21:07,679 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:21:07,679 INFO  impl.PipelinedSorter (PipelinedSorter.java:<init>(189)) - Pre allocating rest of memory buffers upfront
2016-05-18 01:21:07,680 INFO  impl.PipelinedSorter (PipelinedSorter.java:<init>(207)) - Setting up PipelinedSorter for FCA327A24AE447C8B29F99C6C8C9BEFD: , 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:21:07,680 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:21:07,680 INFO  impl.PipelinedSorter (PipelinedSorter.java:<init>(189)) - Pre allocating rest of memory buffers upfront
2016-05-18 01:21:07,680 INFO  impl.PipelinedSorter (PipelinedSorter.java:<init>(207)) - Setting up PipelinedSorter for FCA327A24AE447C8B29F99C6C8C9BEFD: , 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:21:07,682 INFO  impl.PipelinedSorter (PipelinedSorter.java:<init>(882)) - FCA327A24AE447C8B29F99C6C8C9BEFD: reserved.remaining()=104857600, reserved.metasize=16777216
2016-05-18 01:21:07,682 INFO  impl.PipelinedSorter (PipelinedSorter.java:<init>(882)) - FCA327A24AE447C8B29F99C6C8C9BEFD: reserved.remaining()=104857600, reserved.metasize=16777216
2016-05-18 01:21:07,773 INFO  element.TezSourceStage (TezSourceStage.java:prepare(63)) - calling MRInput#start() on: Hfs["TextDelimited[['ip', 'client', 'user', 'date', 'request', 'code', 'bytes', 'referrer', 'agent', 'na' | String, String, String, String, String, int, long, String, String, String]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache-clean.10.txt"]
2016-05-18 01:21:07,773 INFO  element.TezSourceStage (TezSourceStage.java:prepare(63)) - calling MRInput#start() on: Hfs["TextDelimited[['ip', 'client', 'user', 'date', 'request', 'code', 'bytes', 'referrer', 'agent', 'na' | String, String, String, DateType{dateFormatString='dd/MMM/yyyy:HH:mm:ss Z',canonicalType='long'}, String, int, long, String, String, String]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/classes/test/data/apache-clean.10.txt"]
2016-05-18 01:21:07,775 INFO  tez.FlowProcessor (FlowProcessor.java:waitForInputsReady(202)) - flow node id: D71EBA5E0D814A4EAD95DED1BB0DD35D, all 1 inputs ready in: 00:00:00.001
2016-05-18 01:21:07,775 INFO  tez.FlowProcessor (FlowProcessor.java:waitForInputsReady(202)) - flow node id: BEE015666FD14D0DB72C662D3BB75E38, all 1 inputs ready in: 00:00:00.001
2016-05-18 01:21:07,789 INFO  task.TaskRunner2Callable (TaskRunner2Callable.java:run(79)) - Closing task, taskAttemptId=attempt_1463534466279_0001_1_00_000000_0
2016-05-18 01:21:07,789 INFO  task.TaskRunner2Callable (TaskRunner2Callable.java:run(79)) - Closing task, taskAttemptId=attempt_1463534466279_0001_1_01_000000_0
2016-05-18 01:21:07,790 INFO  tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: BEE015666FD14D0DB72C662D3BB75E38, mem on close (mb), free: 140, total: 379, max: 672
2016-05-18 01:21:07,790 INFO  tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: D71EBA5E0D814A4EAD95DED1BB0DD35D, mem on close (mb), free: 140, total: 379, max: 672
2016-05-18 01:21:07,791 INFO  impl.PipelinedSorter (PipelinedSorter.java:flush(629)) - FCA327A24AE447C8B29F99C6C8C9BEFD: Starting flush of map output
2016-05-18 01:21:07,791 INFO  impl.PipelinedSorter (PipelinedSorter.java:flush(629)) - FCA327A24AE447C8B29F99C6C8C9BEFD: Starting flush of map output
2016-05-18 01:21:07,792 INFO  impl.PipelinedSorter (PipelinedSorter.java:end(995)) - FCA327A24AE447C8B29F99C6C8C9BEFD: Span0.length = 10, perItem = 132
2016-05-18 01:21:07,792 INFO  impl.PipelinedSorter (PipelinedSorter.java:end(995)) - FCA327A24AE447C8B29F99C6C8C9BEFD: Span0.length = 10, perItem = 133
2016-05-18 01:21:07,792 INFO  impl.PipelinedSorter (PipelinedSorter.java:sort(904)) - FCA327A24AE447C8B29F99C6C8C9BEFD: done sorting span=0, length=10, time=0
2016-05-18 01:21:07,792 INFO  impl.PipelinedSorter (PipelinedSorter.java:sort(904)) - FCA327A24AE447C8B29F99C6C8C9BEFD: done sorting span=0, length=10, time=0
2016-05-18 01:21:07,796 INFO  impl.PipelinedSorter (PipelinedSorter.java:ready(1297)) - FCA327A24AE447C8B29F99C6C8C9BEFD: Heap = SpanIterator<0:9> (span=Span[16777216,1339]),
2016-05-18 01:21:07,796 INFO  impl.PipelinedSorter (PipelinedSorter.java:ready(1297)) - FCA327A24AE447C8B29F99C6C8C9BEFD: Heap = SpanIterator<0:9> (span=Span[16777216,1329]),
2016-05-18 01:21:07,801 INFO  impl.PipelinedSorter (PipelinedSorter.java:spill(546)) - FCA327A24AE447C8B29F99C6C8C9BEFD: Spilling to /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453/.tez/application_1463534466279_0001_wd/localmode-local-dir/output/attempt_1463534466279_0001_1_01_000000_0_10004_0/file.out
2016-05-18 01:21:07,801 INFO  impl.PipelinedSorter (PipelinedSorter.java:spill(546)) - FCA327A24AE447C8B29F99C6C8C9BEFD: Spilling to /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/tmp/.staging/D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453/.tez/application_1463534466279_0001_wd/localmode-local-dir/output/attempt_1463534466279_0001_1_00_000000_0_10005_0/file.out
2016-05-18 01:21:07,805 INFO  hadoop.TupleSerialization (TupleSerialization.java:areTypesRequired(287)) - types are being enforced during serialization
2016-05-18 01:21:07,808 INFO  hadoop.TupleSerialization (TupleSerialization.java:areTypesRequired(287)) - types are being enforced during serialization
2016-05-18 01:21:08,205 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:close(387)) - Joining on EventRouter
2016-05-18 01:21:08,206 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:close(387)) - Joining on EventRouter
2016-05-18 01:21:08 Completed running task attempt: attempt_1463534466279_0001_1_00_000000_0
2016-05-18 01:21:08,207 INFO  task.TaskRunner2Callable (TaskRunner2Callable.java:run(86)) - Task completed, taskAttemptId=attempt_1463534466279_0001_1_00_000000_0, askedToStop=false
2016-05-18 01:21:08 Completed running task attempt: attempt_1463534466279_0001_1_01_000000_0
2016-05-18 01:21:08,208 INFO  task.TaskRunner2Callable (TaskRunner2Callable.java:run(86)) - Task completed, taskAttemptId=attempt_1463534466279_0001_1_01_000000_0, askedToStop=false
2016-05-18 01:21:08,210 INFO  task.TaskRunner2Callable (TaskRunner2Callable.java:callInternal(104)) - Cleaning up task attempt_1463534466279_0001_1_00_000000_0, stopRequested=false
2016-05-18 01:21:08,211 INFO  task.TaskRunner2Callable (TaskRunner2Callable.java:callInternal(104)) - Cleaning up task attempt_1463534466279_0001_1_01_000000_0, stopRequested=false
2016-05-18 01:21:08,213 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:cleanup(813)) - Final Counters for attempt_1463534466279_0001_1_01_000000_0: Counters: 18 [[org.apache.tez.common.counters.TaskCounter SPILLED_RECORDS=10, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=10, OUTPUT_BYTES=1329, OUTPUT_BYTES_WITH_OVERHEAD=1346, OUTPUT_BYTES_PHYSICAL=1350, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=0, ADDITIONAL_SPILL_COUNT=0, SHUFFLE_CHUNK_COUNT=1][cascading.flow.SliceCounters Process_Begin_Time=1463534467775, Process_Duration=14, Process_End_Time=1463534467789, Read_Duration=1, Tuples_Read=10, Tuples_Written=10, Write_Duration=1][cascading.flow.StepCounters Tuples_Read=10]]
2016-05-18 01:21:08,213 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:cleanup(813)) - Final Counters for attempt_1463534466279_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=1339, OUTPUT_BYTES_WITH_OVERHEAD=1354, OUTPUT_BYTES_PHYSICAL=1358, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=0, ADDITIONAL_SPILL_COUNT=0, SHUFFLE_CHUNK_COUNT=1][cascading.flow.SliceCounters Process_Begin_Time=1463534467775, Process_Duration=14, Process_End_Time=1463534467789, Read_Duration=1, Tuples_Read=10, Tuples_Written=10, Write_Duration=3][cascading.flow.StepCounters Tuples_Read=10]]
2016-05-18 01:21:08,220 INFO  task.TezTaskRunner2 (TezTaskRunner2.java:logAndReturnEndResult(473)) - TaskRunnerResult for attempt_1463534466279_0001_1_00_000000_0 : TaskRunner2Result{endReason=SUCCESS, error=null, containerShutdownRequested=false}  
2016-05-18 01:21:08,220 INFO  task.TezChild (TezChild.java:run(265)) - TaskRunner2Result: TaskRunner2Result{endReason=SUCCESS, error=null, containerShutdownRequested=false}
2016-05-18 01:21:08,220 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=D71EBA5E0D814A4EAD95DED1BB0DD35D, taskAttemptId=attempt_1463534466279_0001_1_00_000000_0, creationTime=1463534467338, allocationTime=1463534467405, startTime=1463534467427, finishTime=1463534468219, timeTaken=792, status=SUCCEEDED, errorEnum=, diagnostics=
2016-05-18 01:21:08,221 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend: 
2016-05-18 01:21:08,221 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 01:21:08,221 INFO  task.ContainerReporter (ContainerReporter.java:callInternal(57)) - Attempting to fetch new task for container container_1463534466279_0001_00_000001
2016-05-18 01:21:08,221 INFO  task.TezTaskRunner2 (TezTaskRunner2.java:logAndReturnEndResult(473)) - TaskRunnerResult for attempt_1463534466279_0001_1_01_000000_0 : TaskRunner2Result{endReason=SUCCESS, error=null, containerShutdownRequested=false}  
2016-05-18 01:21:08,222 INFO  task.TezChild (TezChild.java:run(265)) - TaskRunner2Result: TaskRunner2Result{endReason=SUCCESS, error=null, containerShutdownRequested=false}
2016-05-18 01:21:08,223 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend: 
2016-05-18 01:21:08,223 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 01:21:08,223 INFO  task.ContainerReporter (ContainerReporter.java:callInternal(57)) - Attempting to fetch new task for container container_1463534466279_0001_00_000002
2016-05-18 01:21:08,227 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=BEE015666FD14D0DB72C662D3BB75E38, taskAttemptId=attempt_1463534466279_0001_1_01_000000_0, creationTime=1463534467343, allocationTime=1463534467407, startTime=1463534467422, finishTime=1463534468226, timeTaken=804, status=SUCCEEDED, errorEnum=, diagnostics=
2016-05-18 01:21:08,237 INFO  impl.TaskImpl (TaskImpl.java:transition(1057)) - Task succeeded with attempt attempt_1463534466279_0001_1_00_000000_0
2016-05-18 01:21:08,242 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:TASK_FINISHED]: vertexName=D71EBA5E0D814A4EAD95DED1BB0DD35D, taskId=task_1463534466279_0001_1_00_000000, startTime=1463534467427, finishTime=1463534468238, timeTaken=811, status=SUCCEEDED, successfulAttemptID=attempt_1463534466279_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=1339, OUTPUT_BYTES_WITH_OVERHEAD=1354, OUTPUT_BYTES_PHYSICAL=1358, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=0, ADDITIONAL_SPILL_COUNT=0, SHUFFLE_CHUNK_COUNT=1, cascading.flow.SliceCounters, Process_Begin_Time=1463534467775, Process_Duration=14, Process_End_Time=1463534467789, Read_Duration=1, Tuples_Read=10, Tuples_Written=10, Write_Duration=3, cascading.flow.StepCounters, Tuples_Read=10
2016-05-18 01:21:08,246 INFO  impl.TaskImpl (TaskImpl.java:transition(1057)) - Task succeeded with attempt attempt_1463534466279_0001_1_01_000000_0
2016-05-18 01:21:08,261 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:TASK_FINISHED]: vertexName=BEE015666FD14D0DB72C662D3BB75E38, taskId=task_1463534466279_0001_1_01_000000, startTime=1463534467422, finishTime=1463534468247, timeTaken=825, status=SUCCEEDED, successfulAttemptID=attempt_1463534466279_0001_1_01_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=1329, OUTPUT_BYTES_WITH_OVERHEAD=1346, OUTPUT_BYTES_PHYSICAL=1350, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=0, ADDITIONAL_SPILL_COUNT=0, SHUFFLE_CHUNK_COUNT=1, cascading.flow.SliceCounters, Process_Begin_Time=1463534467775, Process_Duration=14, Process_End_Time=1463534467789, Read_Duration=1, Tuples_Read=10, Tuples_Written=10, Write_Duration=1, cascading.flow.StepCounters, Tuples_Read=10
2016-05-18 01:21:08,267 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:CONTAINER_STOPPED]: containerId=container_1463534466279_0001_00_000001, stoppedTime=1463534468266, exitStatus=0
2016-05-18 01:21:08,270 INFO  impl.VertexImpl (VertexImpl.java:checkTasksForCompletion(2024)) - Task Completion: vertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D], tasks=1, failed=0, killed=0, success=1, completed=1, commits=0, err=null
2016-05-18 01:21:08,270 INFO  impl.VertexImpl (VertexImpl.java:checkTasksForCompletion(2037)) - All tasks have succeeded, vertex:vertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D]
2016-05-18 01:21:08,280 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:VERTEX_FINISHED]: vertexName=D71EBA5E0D814A4EAD95DED1BB0DD35D, vertexId=vertex_1463534466279_0001_1_00, initRequestedTime=1463534467189, initedTime=1463534467302, startRequestedTime=1463534467192, startedTime=1463534467306, finishTime=1463534468271, timeTaken=965, 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=1339, OUTPUT_BYTES_WITH_OVERHEAD=1354, OUTPUT_BYTES_PHYSICAL=1358, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=0, ADDITIONAL_SPILL_COUNT=0, SHUFFLE_CHUNK_COUNT=1, cascading.flow.SliceCounters, Process_Begin_Time=1463534467775, Process_Duration=14, Process_End_Time=1463534467789, Read_Duration=1, Tuples_Read=10, Tuples_Written=10, Write_Duration=3, cascading.flow.StepCounters, Tuples_Read=10, vertexStats=firstTaskStartTime=1463534467427, firstTasksToStart=[ task_1463534466279_0001_1_00_000000 ], lastTaskFinishTime=1463534468219, lastTasksToFinish=[ task_1463534466279_0001_1_00_000000 ], minTaskDuration=792, maxTaskDuration=792, avgTaskDuration=792.0, numSuccessfulTasks=1, shortestDurationTasks=[ task_1463534466279_0001_1_00_000000 ], longestDurationTasks=[ task_1463534466279_0001_1_00_000000 ], vertexTaskStats={numFailedTasks=0, numSucceededTasks=1, numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0, numCompletedTasks=1}
2016-05-18 01:21:08,282 INFO  impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2016-05-18 01:21:08,282 INFO  app.TezTaskCommunicatorImpl (TezTaskCommunicatorImpl.java:getContainerTask(416)) - Container with id: container_1463534466279_0001_00_000001 is valid, but no longer registered, and will be killed
2016-05-18 01:21:08,283 INFO  task.ContainerReporter (ContainerReporter.java:callInternal(67)) - Got TaskUpdate for containerId= container_1463534466279_0001_00_000001: 61 ms after starting to poll. TaskInfo: shouldDie: true
2016-05-18 01:21:08,283 INFO  task.TezChild (TezChild.java:run(235)) - ContainerTask returned shouldDie=true for container container_1463534466279_0001_00_000001, Exiting
2016-05-18 01:21:08,283 INFO  task.TezChild (TezChild.java:shutdown(381)) - Shutdown invoked for container container_1463534466279_0001_00_000001
2016-05-18 01:21:08,283 INFO  task.TezChild (TezChild.java:shutdown(383)) - Shutting down container container_1463534466279_0001_00_000001
2016-05-18 01:21:08,284 INFO  impl.VertexImpl (VertexImpl.java:checkTasksForCompletion(2024)) - Task Completion: vertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38], tasks=1, failed=0, killed=0, success=1, completed=1, commits=0, err=null
2016-05-18 01:21:08,285 INFO  impl.VertexImpl (VertexImpl.java:checkTasksForCompletion(2037)) - All tasks have succeeded, vertex:vertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38]
2016-05-18 01:21:08,286 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(285)) - ContainerExecutionResult for: container_1463534466279_0001_00_000001 = ContainerExecutionResult{exitStatus=SUCCESS, throwable=null, errorMessage='Asked to die by the AM'}
2016-05-18 01:21:08,286 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(289)) - Container: container_1463534466279_0001_00_000001 completed successfully
2016-05-18 01:21:08,288 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:VERTEX_FINISHED]: vertexName=BEE015666FD14D0DB72C662D3BB75E38, vertexId=vertex_1463534466279_0001_1_01, initRequestedTime=1463534467158, initedTime=1463534467301, startRequestedTime=1463534467192, startedTime=1463534467302, finishTime=1463534468286, timeTaken=984, 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=1329, OUTPUT_BYTES_WITH_OVERHEAD=1346, OUTPUT_BYTES_PHYSICAL=1350, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=0, ADDITIONAL_SPILL_COUNT=0, SHUFFLE_CHUNK_COUNT=1, cascading.flow.SliceCounters, Process_Begin_Time=1463534467775, Process_Duration=14, Process_End_Time=1463534467789, Read_Duration=1, Tuples_Read=10, Tuples_Written=10, Write_Duration=1, cascading.flow.StepCounters, Tuples_Read=10, vertexStats=firstTaskStartTime=1463534467422, firstTasksToStart=[ task_1463534466279_0001_1_01_000000 ], lastTaskFinishTime=1463534468226, lastTasksToFinish=[ task_1463534466279_0001_1_01_000000 ], minTaskDuration=804, maxTaskDuration=804, avgTaskDuration=804.0, numSuccessfulTasks=1, shortestDurationTasks=[ task_1463534466279_0001_1_01_000000 ], longestDurationTasks=[ task_1463534466279_0001_1_01_000000 ], vertexTaskStats={numFailedTasks=0, numSucceededTasks=1, numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0, numCompletedTasks=1}
2016-05-18 01:21:08,288 INFO  impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2016-05-18 01:21:08,289 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:CONTAINER_STOPPED]: containerId=container_1463534466279_0001_00_000002, stoppedTime=1463534468289, exitStatus=0
2016-05-18 01:21:08,289 INFO  impl.VertexImpl (VertexImpl.java:transition(3279)) - Source task attempt completed for vertex: vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD] attempt: attempt_1463534466279_0001_1_00_000000_0 with state: SUCCEEDED vertexState: RUNNING
2016-05-18 01:21:08,290 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:stop(260)) - Ignoring stop request for containerId: container_1463534466279_0001_00_000001
2016-05-18 01:21:08,290 INFO  impl.DAGImpl (DAGImpl.java:transition(1927)) - Vertex vertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D] completed., numCompletedVertices=1, numSuccessfulVertices=1, numFailedVertices=0, numKilledVertices=0, numVertices=3
2016-05-18 01:21:08,291 INFO  impl.DAGImpl (DAGImpl.java:checkVerticesForCompletion(1261)) - Checking vertices for DAG completion, numCompletedVertices=1, numSuccessfulVertices=1, numFailedVertices=0, numKilledVertices=0, numVertices=3, commitInProgress=0, terminationCause=null
2016-05-18 01:21:08,291 INFO  impl.VertexImpl (VertexImpl.java:transition(3279)) - Source task attempt completed for vertex: vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD] attempt: attempt_1463534466279_0001_1_01_000000_0 with state: SUCCEEDED vertexState: RUNNING
2016-05-18 01:21:08,292 INFO  vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:schedulePendingTasks(920)) - All source tasks assigned. Ramping up 1 remaining tasks for vertex: FCA327A24AE447C8B29F99C6C8C9BEFD
2016-05-18 01:21:08,292 INFO  impl.DAGImpl (DAGImpl.java:transition(1927)) - Vertex vertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38] completed., numCompletedVertices=2, numSuccessfulVertices=2, numFailedVertices=0, numKilledVertices=0, numVertices=3
2016-05-18 01:21:08,292 INFO  impl.DAGImpl (DAGImpl.java:checkVerticesForCompletion(1261)) - Checking vertices for DAG completion, numCompletedVertices=2, numSuccessfulVertices=2, numFailedVertices=0, numKilledVertices=0, numVertices=3, commitInProgress=0, terminationCause=null
2016-05-18 01:21:08,293 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:stop(262)) - Ignoring stop request for containerId container_1463534466279_0001_00_000002. Relying on regular task shutdown for it to end
2016-05-18 01:21:08,293 INFO  impl.Edge (Edge.java:routingToBegin(232)) - Routing to begin for edge: EdgeInfo: sourceVertexName=D71EBA5E0D814A4EAD95DED1BB0DD35D, destinationVertexName=FCA327A24AE447C8B29F99C6C8C9BEFD. 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:21:08,293 INFO  impl.Edge (Edge.java:routingToBegin(232)) - Routing to begin for edge: EdgeInfo: sourceVertexName=BEE015666FD14D0DB72C662D3BB75E38, destinationVertexName=FCA327A24AE447C8B29F99C6C8C9BEFD. 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:21:08,293 INFO  impl.VertexImpl (VertexImpl.java:unsetTasksNotYetScheduled(1466)) - Routing pending task events for vertex: vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD]
2016-05-18 01:21:08,294 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:TASK_STARTED]: vertexName=FCA327A24AE447C8B29F99C6C8C9BEFD, taskId=task_1463534466279_0001_1_02_000000, scheduledTime=1463534468294, launchTime=1463534468294
2016-05-18 01:21:08,295 INFO  impl.DAGSchedulerNaturalOrderControlled (DAGSchedulerNaturalOrderControlled.java:scheduleTaskEx(106)) - Scheduled vertex: vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD]
2016-05-18 01:21:08,297 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:N/A][Event:CONTAINER_LAUNCHED]: containerId=container_1463534466279_0001_00_000003, launchTime=1463534468297
2016-05-18 01:21:08,299 INFO  task.ContainerReporter (ContainerReporter.java:callInternal(57)) - Attempting to fetch new task for container container_1463534466279_0001_00_000003
2016-05-18 01:21:08,300 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1322)) - TaskAttempt: [attempt_1463534466279_0001_1_02_000000_0] started. Is using containerId: [container_1463534466279_0001_00_000003] on NM: [127.0.0.1:0]
2016-05-18 01:21:08,301 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:TASK_ATTEMPT_STARTED]: vertexName=FCA327A24AE447C8B29F99C6C8C9BEFD, taskAttemptId=attempt_1463534466279_0001_1_02_000000_0, startTime=1463534468300, containerId=container_1463534466279_0001_00_000003, nodeId=127.0.0.1:0
2016-05-18 01:21:08,304 INFO  task.ContainerReporter (ContainerReporter.java:callInternal(67)) - Got TaskUpdate for containerId= container_1463534466279_0001_00_000003: 0 ms after starting to poll. TaskInfo: shouldDie: false, currentTaskAttemptId: attempt_1463534466279_0001_1_02_000000_0
2016-05-18 01:21:08 Starting to run new task attempt: attempt_1463534466279_0001_1_02_000000_0
2016-05-18 01:21:08,305 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend: attempt_1463534466279_0001_1_02_000000_0
2016-05-18 01:21:08,305 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 01:21:08,305 INFO  task.TezChild (TezChild.java:handleNewTaskCredentials(306)) - Refreshing UGI since Credentials have changed. Credentials : #Tokens=1, #SecretKeys=0
2016-05-18 01:21:08,306 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:<init>(166)) - Initializing LogicalIOProcessorRuntimeTask with TaskSpec: DAGName : [D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453] null/(1/1) ...eCheck/testFieldTypeCheck, VertexName: FCA327A24AE447C8B29F99C6C8C9BEFD, VertexParallelism: 1, TaskAttemptID:attempt_1463534466279_0001_1_02_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=2, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=D71EBA5E0D814A4EAD95DED1BB0DD35D, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }}, {{ sourceVertexName=BEE015666FD14D0DB72C662D3BB75E38, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }}, ], outputSpecList=[{{ destinationVertexName=A24A65E16249416EBE5023A2128E2CD9, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }}, ]
2016-05-18 01:21:08,306 INFO  resources.MemoryDistributor (MemoryDistributor.java:<init>(93)) - InitialMemoryDistributor (isEnabled=true) invoked with: numInputs=2, numOutputs=1, JVM.maxFree=768081920, allocatorClassName=org.apache.tez.runtime.library.resources.WeightedScalingMemoryDistributor
2016-05-18 01:21:08,306 INFO  task.TaskRunner2Callable (TaskRunner2Callable.java:run(65)) - Initializing task, taskAttemptId=attempt_1463534466279_0001_1_02_000000_0
2016-05-18 01:21:08,309 INFO  impl.VertexImpl (VertexImpl.java:getTaskAttemptTezEvents(3662)) - Sending attempt_1463534466279_0001_1_02_000000_0 2 events [0,2) total 2 vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD]
2016-05-18 01:21:08,309 INFO  task.TaskReporter (TaskReporter.java:heartbeat(292)) - Routing events from heartbeat response to task, currentTaskAttemptId=attempt_1463534466279_0001_1_02_000000_0, eventCount=2 fromEventId=0 nextFromEventId=2
2016-05-18 01:21:08,312 INFO  tez.FlowProcessor (FlowProcessor.java:initialize(88)) - cascading version: 3.1.0
2016-05-18 01:21:08,322 INFO  orderedgrouped.MergeManager (MergeManager.java:getInitialMemoryRequirement(339)) - Initial Memory required for SHUFFLE_BUFFER=230424576 based on INPUT_BUFFER_FACTOR=0.9,  for final merged output=0, using factor: 0.0
2016-05-18 01:21:08,322 INFO  orderedgrouped.MergeManager (MergeManager.java:getInitialMemoryRequirement(339)) - Initial Memory required for SHUFFLE_BUFFER=230424576 based on INPUT_BUFFER_FACTOR=0.9,  for final merged output=0, using factor: 0.0
2016-05-18 01:21:08,330 INFO  app.TezTaskCommunicatorImpl (TezTaskCommunicatorImpl.java:getContainerTask(416)) - Container with id: container_1463534466279_0001_00_000002 is valid, but no longer registered, and will be killed
2016-05-18 01:21:08,331 INFO  task.ContainerReporter (ContainerReporter.java:callInternal(67)) - Got TaskUpdate for containerId= container_1463534466279_0001_00_000002: 108 ms after starting to poll. TaskInfo: shouldDie: true
2016-05-18 01:21:08,331 INFO  task.TezChild (TezChild.java:run(235)) - ContainerTask returned shouldDie=true for container container_1463534466279_0001_00_000002, Exiting
2016-05-18 01:21:08,331 INFO  task.TezChild (TezChild.java:shutdown(381)) - Shutdown invoked for container container_1463534466279_0001_00_000002
2016-05-18 01:21:08,332 INFO  task.TezChild (TezChild.java:shutdown(383)) - Shutting down container container_1463534466279_0001_00_000002
2016-05-18 01:21:08,332 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(285)) - ContainerExecutionResult for: container_1463534466279_0001_00_000002 = ContainerExecutionResult{exitStatus=SUCCESS, throwable=null, errorMessage='Asked to die by the AM'}
2016-05-18 01:21:08,332 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(289)) - Container: container_1463534466279_0001_00_000002 completed successfully
2016-05-18 01:21:08,336 INFO  tez.FlowProcessor (FlowProcessor.java:initialize(94)) - flow node id: FCA327A24AE447C8B29F99C6C8C9BEFD, ordinal: 2
2016-05-18 01:21:08,336 INFO  tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: FCA327A24AE447C8B29F99C6C8C9BEFD, mem on start (mb), free: 480, total: 732, max: 732
2016-05-18 01:21:08,336 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(562)) - Initialized processor
2016-05-18 01:21:08,336 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(239)) - Waiting for 3 initializers to finish
2016-05-18 01:21:08,336 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(239)) - Waiting for 2 initializers to finish
2016-05-18 01:21:08,336 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(239)) - Waiting for 1 initializers to finish
2016-05-18 01:21:08,342 INFO  output.MROutput (MROutput.java:initialize(421)) - A24A65E16249416EBE5023A2128E2CD9: outputFormat=org.apache.hadoop.mapred.TextOutputFormat, using newmapreduce API=false
2016-05-18 01:21:08,342 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(252)) - All initializers finished
2016-05-18 01:21:08,342 INFO  resources.MemoryDistributor (MemoryDistributor.java:logInitialRequests(275)) - InitialRequests=[A24A65E16249416EBE5023A2128E2CD9:OUTPUT:0:org.apache.tez.mapreduce.output.MROutput], [D71EBA5E0D814A4EAD95DED1BB0DD35D:INPUT:230424576:org.apache.tez.runtime.library.input.OrderedGroupedKVInput], [BEE015666FD14D0DB72C662D3BB75E38:INPUT:230424576:org.apache.tez.runtime.library.input.OrderedGroupedKVInput]
2016-05-18 01:21:08,343 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:21:08,343 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:computeReservedFraction(266)) - InitialReservationFraction=0.3, AdditionalReservationFractionForIOs=0.045, finalReserveFractionUsed=0.345
2016-05-18 01:21:08,343 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:assignMemory(126)) - Scaling Requests. NumRequests: 3, numScaledRequests: 25, TotalRequested: 460849152, TotalRequestedScaled: 2.2120759295999998E8, TotalJVMHeap: 768081920, TotalAvailable: 503093657, TotalRequested/TotalJVMHeap:0.60
2016-05-18 01:21:08,343 INFO  resources.MemoryDistributor (MemoryDistributor.java:logFinalAllocations(297)) - Allocations=[A24A65E16249416EBE5023A2128E2CD9:org.apache.tez.mapreduce.output.MROutput:OUTPUT:0:0], [D71EBA5E0D814A4EAD95DED1BB0DD35D:org.apache.tez.runtime.library.input.OrderedGroupedKVInput:INPUT:230424576:230424576], [BEE015666FD14D0DB72C662D3BB75E38:org.apache.tez.runtime.library.input.OrderedGroupedKVInput:INPUT:230424576:230424576]
2016-05-18 01:21:08,343 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(274)) - Starting Inputs/Outputs
2016-05-18 01:21:08,344 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(287)) - Input: D71EBA5E0D814A4EAD95DED1BB0DD35D being auto started by the framework. Subsequent instances will not be auto-started
2016-05-18 01:21:08,344 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(287)) - Input: BEE015666FD14D0DB72C662D3BB75E38 being auto started by the framework. Subsequent instances will not be auto-started
2016-05-18 01:21:08,345 INFO  orderedgrouped.Shuffle (Shuffle.java:<init>(147)) - BEE015666FD14D0DB72C662D3BB75E38: Shuffle assigned with 1 inputs, codec: None, ifileReadAhead: true
2016-05-18 01:21:08,345 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(308)) - Num IOs determined for AutoStart: 2
2016-05-18 01:21:08,345 INFO  orderedgrouped.Shuffle (Shuffle.java:<init>(147)) - D71EBA5E0D814A4EAD95DED1BB0DD35D: Shuffle assigned with 1 inputs, codec: None, ifileReadAhead: true
2016-05-18 01:21:08,347 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(310)) - Waiting for 2 IOs to start
2016-05-18 01:21:08,348 INFO  orderedgrouped.MergeManager (MergeManager.java:<init>(273)) - BEE015666FD14D0DB72C662D3BB75E38: MergerManager: memoryLimit=230424576, maxSingleShuffleLimit=57606144, mergeThreshold=207382112, ioSortFactor=100, postMergeMem=0, memToMemMergeOutputsThreshold=100
2016-05-18 01:21:08,348 INFO  orderedgrouped.MergeManager (MergeManager.java:<init>(273)) - D71EBA5E0D814A4EAD95DED1BB0DD35D: MergerManager: memoryLimit=230424576, maxSingleShuffleLimit=57606144, mergeThreshold=207382112, ioSortFactor=100, postMergeMem=0, memToMemMergeOutputsThreshold=100
2016-05-18 01:21:08,365 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:<init>(353)) - ShuffleScheduler running for sourceVertex: D71EBA5E0D814A4EAD95DED1BB0DD35D 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:21:08,365 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:<init>(353)) - ShuffleScheduler running for sourceVertex: BEE015666FD14D0DB72C662D3BB75E38 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:21:08,373 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:_callInternal(474)) - Started Input with src edge: D71EBA5E0D814A4EAD95DED1BB0DD35D
2016-05-18 01:21:08,373 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:_callInternal(474)) - Started Input with src edge: BEE015666FD14D0DB72C662D3BB75E38
2016-05-18 01:21:08,373 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(310)) - Waiting for 1 IOs to start
2016-05-18 01:21:08,373 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(323)) - AutoStartComplete
2016-05-18 01:21:08,374 INFO  task.TaskRunner2Callable (TaskRunner2Callable.java:run(70)) - Running task, taskAttemptId=attempt_1463534466279_0001_1_02_000000_0
2016-05-18 01:21:08,380 INFO  orderedgrouped.ShuffleInputEventHandlerOrderedGrouped (ShuffleInputEventHandlerOrderedGrouped.java:logProgress(76)) - D71EBA5E0D814A4EAD95DED1BB0DD35D: numDmeEventsSeen=1, numDmeEventsSeenWithNoData=0, numObsoletionEventsSeen=0
2016-05-18 01:21:08,380 INFO  orderedgrouped.ShuffleInputEventHandlerOrderedGrouped (ShuffleInputEventHandlerOrderedGrouped.java:logProgress(76)) - BEE015666FD14D0DB72C662D3BB75E38: numDmeEventsSeen=1, numDmeEventsSeenWithNoData=0, numObsoletionEventsSeen=0
2016-05-18 01:21:08,382 INFO  graph.Hadoop2TezStreamGraph (Hadoop2TezStreamGraph.java:buildGraph(151)) - using streamed source: CoGroup(lhs*rhs)[by: lhs:[{1}:'date'] rhs:[{1}:'date']]
2016-05-18 01:21:08,389 INFO  tez.FlowProcessor (FlowProcessor.java:run(121)) - sourcing from: CoGroup(lhs*rhs)[by: lhs:[{1}:'date'] rhs:[{1}:'date']] streamed: true, id: 5323050D5774404998ACF069DB614D85
2016-05-18 01:21:08,390 INFO  tez.FlowProcessor (FlowProcessor.java:run(124)) - sinking to: Hfs["TextDelimited[['ip', 'client', 'user', 'date', 'request', 'code', 'bytes', 'referrer', 'agent', 'na', 10:19 | String, String, String, DateType{dateFormatString='dd/MMM/yyyy:HH:mm:ss Z',canonicalType='long'}, String, int, long, String, String, String, String, String, String, Long, String, int, long, String, String, String]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output/hadoop2-tez/typedfieldedpipesplatform/testFieldTypeCheck/testFieldTypeCheck"], id: A24A65E16249416EBE5023A2128E2CD9
2016-05-18 01:21:08,390 INFO  orderedgrouped.ShuffleScheduler (ShuffleUtils.java:logIndividualFetchComplete(489)) - Completed fetch for attempt: {0, 0, attempt_1463534466279_0001_1_00_000000_0_10005} to DISK_DIRECT, csize=1358, dsize=1354, EndTime=1463534468390, TimeTaken=5, Rate=0.26 MB/s
2016-05-18 01:21:08,391 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:copySucceeded(551)) - All inputs fetched for input vertex : D71EBA5E0D814A4EAD95DED1BB0DD35D
2016-05-18 01:21:08,391 INFO  element.TezSinkStage (TezSinkStage.java:prepare(57)) - calling MROutput#start() on: Hfs["TextDelimited[['ip', 'client', 'user', 'date', 'request', 'code', 'bytes', 'referrer', 'agent', 'na', 10:19 | String, String, String, DateType{dateFormatString='dd/MMM/yyyy:HH:mm:ss Z',canonicalType='long'}, String, int, long, String, String, String, String, String, String, Long, String, int, long, String, String, String]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.7.x-tez-0.8.x/build/test/output/hadoop2-tez/typedfieldedpipesplatform/testFieldTypeCheck/testFieldTypeCheck"]
2016-05-18 01:21:08,392 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:21:08,391 INFO  orderedgrouped.ShuffleScheduler (ShuffleUtils.java:logIndividualFetchComplete(489)) - Completed fetch for attempt: {0, 0, attempt_1463534466279_0001_1_01_000000_0_10004} to DISK_DIRECT, csize=1350, dsize=1346, EndTime=1463534468391, TimeTaken=2, Rate=0.64 MB/s
2016-05-18 01:21:08,393 INFO  element.TezGroupGate (TezGroupGate.java:prepare(90)) - calling OrderedGroupedKVInput#start() on: CoGroup(lhs*rhs)[by: lhs:[{1}:'date'] rhs:[{1}:'date']] 5323050D5774404998ACF069DB614D85, for 2 inputs
2016-05-18 01:21:08,393 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:callInternal(1289)) - Shutting down FetchScheduler for input: D71EBA5E0D814A4EAD95DED1BB0DD35D, wasInterrupted=false
2016-05-18 01:21:08,393 INFO  element.TezGroupGate (TezGroupGate.java:prepare(90)) - calling OrderedGroupedKVInput#start() on: CoGroup(lhs*rhs)[by: lhs:[{1}:'date'] rhs:[{1}:'date']] 5323050D5774404998ACF069DB614D85, for 2 inputs
2016-05-18 01:21:08,394 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:21:08,393 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:copySucceeded(551)) - All inputs fetched for input vertex : BEE015666FD14D0DB72C662D3BB75E38
2016-05-18 01:21:08,394 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:21:08,395 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:callInternal(1289)) - Shutting down FetchScheduler for input: BEE015666FD14D0DB72C662D3BB75E38, wasInterrupted=false
2016-05-18 01:21:08,396 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:21:08,396 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:21:08,398 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:21:08,400 INFO  util.BaseTupleComparator (BaseTupleComparator.java:setConf(57)) - enabling raw byte comparison and ordering
2016-05-18 01:21:08,400 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/D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453/.tez/application_1463534466279_0001_wd/localmode-local-dir/output/attempt_1463534466279_0001_1_01_000000_0_10004/file.out, len=1350, isLocal=true
2016-05-18 01:21:08,401 INFO  util.BaseTupleComparator (BaseTupleComparator.java:setConf(57)) - enabling raw byte comparison and ordering
2016-05-18 01:21:08,401 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/D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453/.tez/application_1463534466279_0001_wd/localmode-local-dir/output/attempt_1463534466279_0001_1_00_000000_0_10005/file.out, len=1358, isLocal=true
2016-05-18 01:21:08,401 INFO  orderedgrouped.MergeManager (MergeManager.java:finalMerge(1115)) - Merging 1 files, 1350 bytes from disk
2016-05-18 01:21:08,401 INFO  orderedgrouped.MergeManager (MergeManager.java:finalMerge(1115)) - Merging 1 files, 1358 bytes from disk
2016-05-18 01:21:08,402 INFO  orderedgrouped.MergeManager (MergeManager.java:finalMerge(1130)) - Merging 0 segments, 0 bytes from memory into reduce
2016-05-18 01:21:08,402 INFO  orderedgrouped.MergeManager (MergeManager.java:finalMerge(1130)) - Merging 0 segments, 0 bytes from memory into reduce
2016-05-18 01:21:08,405 INFO  impl.TezMerger (TezMerger.java:merge(644)) - Merging 1 sorted segments
2016-05-18 01:21:08,405 INFO  impl.TezMerger (TezMerger.java:merge(644)) - Merging 1 sorted segments
2016-05-18 01:21:08,407 INFO  collect.SpillableTupleList (SpillableTupleList.java:getCodecClass(89)) - attempting to load codec: org.apache.hadoop.io.compress.GzipCodec
2016-05-18 01:21:08,410 INFO  collect.SpillableTupleList (SpillableTupleList.java:getCodecClass(94)) - found codec: org.apache.hadoop.io.compress.GzipCodec
2016-05-18 01:21:08,412 INFO  impl.TezMerger (TezMerger.java:merge(749)) - Down to the last merge-pass, with 1 segments left of total size: 1340 bytes
2016-05-18 01:21:08,413 INFO  orderedgrouped.Shuffle (Shuffle.java:callInternal(332)) - merge complete for input vertex : D71EBA5E0D814A4EAD95DED1BB0DD35D
2016-05-18 01:21:08,412 INFO  impl.TezMerger (TezMerger.java:merge(749)) - Down to the last merge-pass, with 1 segments left of total size: 1333 bytes
2016-05-18 01:21:08,413 INFO  orderedgrouped.Shuffle (Shuffle.java:onSuccess(417)) - D71EBA5E0D814A4EAD95DED1BB0DD35D: Shuffle Runner thread complete
2016-05-18 01:21:08,413 INFO  orderedgrouped.Shuffle (Shuffle.java:callInternal(332)) - merge complete for input vertex : BEE015666FD14D0DB72C662D3BB75E38
2016-05-18 01:21:08,414 INFO  orderedgrouped.Shuffle (Shuffle.java:onSuccess(417)) - BEE015666FD14D0DB72C662D3BB75E38: Shuffle Runner thread complete
2016-05-18 01:21:08,416 INFO  tez.FlowProcessor (FlowProcessor.java:waitForInputsReady(202)) - flow node id: FCA327A24AE447C8B29F99C6C8C9BEFD, all 2 inputs ready in: 00:00:00.000
2016-05-18 01:21:08,417 INFO  util.BaseTupleComparator (BaseTupleComparator.java:setConf(57)) - enabling raw byte comparison and ordering
2016-05-18 01:21:08,417 INFO  input.OrderedGroupedKVInput (OrderedGroupedKVInput.java:createValuesIterator(292)) - BEE015666FD14D0DB72C662D3BB75E38: creating ValuesIterator with comparator=cascading.tuple.hadoop.util.TupleComparator, keyClass=cascading.tuple.io.KeyTuple, valClass=cascading.tuple.io.ValueTuple
2016-05-18 01:21:08,421 INFO  hadoop.TupleSerialization (TupleSerialization.java:areTypesRequired(287)) - types are being enforced during serialization
2016-05-18 01:21:08,432 INFO  util.BaseTupleComparator (BaseTupleComparator.java:setConf(57)) - enabling raw byte comparison and ordering
2016-05-18 01:21:08,432 INFO  input.OrderedGroupedKVInput (OrderedGroupedKVInput.java:createValuesIterator(292)) - D71EBA5E0D814A4EAD95DED1BB0DD35D: creating ValuesIterator with comparator=cascading.tuple.hadoop.util.TupleComparator, keyClass=cascading.tuple.io.KeyTuple, valClass=cascading.tuple.io.ValueTuple
2016-05-18 01:21:08,435 INFO  hadoop.TupleSerialization (TupleSerialization.java:areTypesRequired(287)) - types are being enforced during serialization
2016-05-18 01:21:08,452 INFO  output.MROutput (MROutput.java:close(526)) - A24A65E16249416EBE5023A2128E2CD9 closed
2016-05-18 01:21:08,453 INFO  impl.TaskImpl (TaskImpl.java:canCommit(671)) - attempt_1463534466279_0001_1_02_000000_0 given a go for committing the task output.
2016-05-18 01:21:08,454 INFO  task.TaskRunner2Callable (TaskRunner2Callable.java:run(79)) - Closing task, taskAttemptId=attempt_1463534466279_0001_1_02_000000_0
2016-05-18 01:21:08,454 INFO  tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: FCA327A24AE447C8B29F99C6C8C9BEFD, mem on close (mb), free: 470, total: 732, max: 732
2016-05-18 01:21:08,454 INFO  orderedgrouped.Shuffle (Shuffle.java:shutdown(278)) - Shutting down Shuffle for source: D71EBA5E0D814A4EAD95DED1BB0DD35D
2016-05-18 01:21:08,454 INFO  orderedgrouped.ShuffleInputEventHandlerOrderedGrouped (ShuffleInputEventHandlerOrderedGrouped.java:logProgress(76)) - D71EBA5E0D814A4EAD95DED1BB0DD35D: numDmeEventsSeen=1, numDmeEventsSeenWithNoData=0, numObsoletionEventsSeen=0, updateOnClose
2016-05-18 01:21:08,455 INFO  orderedgrouped.Shuffle (Shuffle.java:shutdown(278)) - Shutting down Shuffle for source: BEE015666FD14D0DB72C662D3BB75E38
2016-05-18 01:21:08,455 INFO  orderedgrouped.ShuffleInputEventHandlerOrderedGrouped (ShuffleInputEventHandlerOrderedGrouped.java:logProgress(76)) - BEE015666FD14D0DB72C662D3BB75E38: numDmeEventsSeen=1, numDmeEventsSeenWithNoData=0, numObsoletionEventsSeen=0, updateOnClose
2016-05-18 01:21:08,456 INFO  output.MROutput (MROutput.java:close(526)) - A24A65E16249416EBE5023A2128E2CD9 closed
2016-05-18 01:21:08,456 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:close(387)) - Joining on EventRouter
2016-05-18 01:21:08 Completed running task attempt: attempt_1463534466279_0001_1_02_000000_0
2016-05-18 01:21:08,457 INFO  task.TaskRunner2Callable (TaskRunner2Callable.java:run(86)) - Task completed, taskAttemptId=attempt_1463534466279_0001_1_02_000000_0, askedToStop=false
2016-05-18 01:21:08,457 INFO  task.TaskRunner2Callable (TaskRunner2Callable.java:callInternal(104)) - Cleaning up task attempt_1463534466279_0001_1_02_000000_0, stopRequested=false
2016-05-18 01:21:08,458 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:cleanup(813)) - Final Counters for attempt_1463534466279_0001_1_02_000000_0: Counters: 36 [[org.apache.tez.common.counters.TaskCounter REDUCE_INPUT_GROUPS=16, REDUCE_INPUT_RECORDS=20, COMBINE_INPUT_RECORDS=0, SPILLED_RECORDS=20, NUM_SHUFFLED_INPUTS=2, NUM_SKIPPED_INPUTS=0, NUM_FAILED_SHUFFLE_INPUTS=0, MERGED_MAP_OUTPUTS=2, OUTPUT_RECORDS=15, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=2708, SHUFFLE_BYTES=2708, SHUFFLE_BYTES_DECOMPRESSED=2700, SHUFFLE_BYTES_TO_MEM=0, SHUFFLE_BYTES_TO_DISK=0, SHUFFLE_BYTES_DISK_DIRECT=2708, NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=98, MERGE_PHASE_TIME=135, FIRST_EVENT_RECEIVED=69, LAST_EVENT_RECEIVED=69][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=1463534468416, Process_Duration=38, Process_End_Time=1463534468454, Read_Duration=1, Tuples_Read=20, Tuples_Written=14, Write_Duration=1][cascading.flow.StepCounters Tuples_Written=14]]
2016-05-18 01:21:08,460 INFO  task.TezTaskRunner2 (TezTaskRunner2.java:logAndReturnEndResult(473)) - TaskRunnerResult for attempt_1463534466279_0001_1_02_000000_0 : TaskRunner2Result{endReason=SUCCESS, error=null, containerShutdownRequested=false}  
2016-05-18 01:21:08,460 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=FCA327A24AE447C8B29F99C6C8C9BEFD, taskAttemptId=attempt_1463534466279_0001_1_02_000000_0, creationTime=1463534468295, allocationTime=1463534468296, startTime=1463534468300, finishTime=1463534468460, timeTaken=160, status=SUCCEEDED, errorEnum=, diagnostics=
2016-05-18 01:21:08,460 INFO  task.TezChild (TezChild.java:run(265)) - TaskRunner2Result: TaskRunner2Result{endReason=SUCCESS, error=null, containerShutdownRequested=false}
2016-05-18 01:21:08,461 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend: 
2016-05-18 01:21:08,461 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 01:21:08,461 INFO  impl.TaskImpl (TaskImpl.java:transition(1057)) - Task succeeded with attempt attempt_1463534466279_0001_1_02_000000_0
2016-05-18 01:21:08,461 INFO  task.ContainerReporter (ContainerReporter.java:callInternal(57)) - Attempting to fetch new task for container container_1463534466279_0001_00_000003
2016-05-18 01:21:08,463 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:TASK_FINISHED]: vertexName=FCA327A24AE447C8B29F99C6C8C9BEFD, taskId=task_1463534466279_0001_1_02_000000, startTime=1463534468300, finishTime=1463534468462, timeTaken=162, status=SUCCEEDED, successfulAttemptID=attempt_1463534466279_0001_1_02_000000_0, diagnostics=, counters=Counters: 36, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=16, REDUCE_INPUT_RECORDS=20, COMBINE_INPUT_RECORDS=0, SPILLED_RECORDS=20, NUM_SHUFFLED_INPUTS=2, NUM_SKIPPED_INPUTS=0, NUM_FAILED_SHUFFLE_INPUTS=0, MERGED_MAP_OUTPUTS=2, OUTPUT_RECORDS=15, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=2708, SHUFFLE_BYTES=2708, SHUFFLE_BYTES_DECOMPRESSED=2700, SHUFFLE_BYTES_TO_MEM=0, SHUFFLE_BYTES_TO_DISK=0, SHUFFLE_BYTES_DISK_DIRECT=2708, NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=98, MERGE_PHASE_TIME=135, FIRST_EVENT_RECEIVED=69, LAST_EVENT_RECEIVED=69, 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=1463534468416, Process_Duration=38, Process_End_Time=1463534468454, Read_Duration=1, Tuples_Read=20, Tuples_Written=14, Write_Duration=1, cascading.flow.StepCounters, Tuples_Written=14
2016-05-18 01:21:08,466 INFO  impl.VertexImpl (VertexImpl.java:checkTasksForCompletion(2024)) - Task Completion: vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD], tasks=1, failed=0, killed=0, success=1, completed=1, commits=0, err=null
2016-05-18 01:21:08,466 INFO  impl.VertexImpl (VertexImpl.java:checkTasksForCompletion(2037)) - All tasks have succeeded, vertex:vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD]
2016-05-18 01:21:08,468 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:VERTEX_FINISHED]: vertexName=FCA327A24AE447C8B29F99C6C8C9BEFD, vertexId=vertex_1463534466279_0001_1_02, initRequestedTime=1463534467192, initedTime=1463534467252, startRequestedTime=1463534467308, startedTime=1463534467309, finishTime=1463534468466, timeTaken=1157, status=SUCCEEDED, diagnostics=, counters=Counters: 36, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=16, REDUCE_INPUT_RECORDS=20, COMBINE_INPUT_RECORDS=0, SPILLED_RECORDS=20, NUM_SHUFFLED_INPUTS=2, NUM_SKIPPED_INPUTS=0, NUM_FAILED_SHUFFLE_INPUTS=0, MERGED_MAP_OUTPUTS=2, OUTPUT_RECORDS=15, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=2708, SHUFFLE_BYTES=2708, SHUFFLE_BYTES_DECOMPRESSED=2700, SHUFFLE_BYTES_TO_MEM=0, SHUFFLE_BYTES_TO_DISK=0, SHUFFLE_BYTES_DISK_DIRECT=2708, NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=98, MERGE_PHASE_TIME=135, FIRST_EVENT_RECEIVED=69, LAST_EVENT_RECEIVED=69, 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=1463534468416, Process_Duration=38, Process_End_Time=1463534468454, Read_Duration=1, Tuples_Read=20, Tuples_Written=14, Write_Duration=1, cascading.flow.StepCounters, Tuples_Written=14, vertexStats=firstTaskStartTime=1463534468300, firstTasksToStart=[ task_1463534466279_0001_1_02_000000 ], lastTaskFinishTime=1463534468460, lastTasksToFinish=[ task_1463534466279_0001_1_02_000000 ], minTaskDuration=160, maxTaskDuration=160, avgTaskDuration=160.0, numSuccessfulTasks=1, shortestDurationTasks=[ task_1463534466279_0001_1_02_000000 ], longestDurationTasks=[ task_1463534466279_0001_1_02_000000 ], vertexTaskStats={numFailedTasks=0, numSucceededTasks=1, numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0, numCompletedTasks=1}
2016-05-18 01:21:08,468 INFO  impl.VertexImpl (VertexImpl.java:handle(1823)) - vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2016-05-18 01:21:08,469 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:CONTAINER_STOPPED]: containerId=container_1463534466279_0001_00_000003, stoppedTime=1463534468469, exitStatus=0
2016-05-18 01:21:08,469 INFO  impl.DAGImpl (DAGImpl.java:transition(1927)) - Vertex vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD] completed., numCompletedVertices=3, numSuccessfulVertices=3, numFailedVertices=0, numKilledVertices=0, numVertices=3
2016-05-18 01:21:08,469 INFO  impl.DAGImpl (DAGImpl.java:checkVerticesForCompletion(1261)) - Checking vertices for DAG completion, numCompletedVertices=3, numSuccessfulVertices=3, numFailedVertices=0, numKilledVertices=0, numVertices=3, commitInProgress=0, terminationCause=null
2016-05-18 01:21:08,471 INFO  impl.DAGImpl (DAGImpl.java:commitOrFinish(1051)) - No output committers for vertex: vertex_1463534466279_0001_1_01 [BEE015666FD14D0DB72C662D3BB75E38]
2016-05-18 01:21:08,472 INFO  impl.DAGImpl (DAGImpl.java:commitOrFinish(1051)) - No output committers for vertex: vertex_1463534466279_0001_1_00 [D71EBA5E0D814A4EAD95DED1BB0DD35D]
2016-05-18 01:21:08,472 INFO  impl.DAGImpl (DAGImpl.java:commitOrFinish(1098)) - Start writing dag commit event, dag_1463534466279_0001_1
2016-05-18 01:21:08,473 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:DAG_COMMIT_STARTED]: dagID=dag_1463534466279_0001_1
2016-05-18 01:21:08,474 INFO  impl.DAGImpl (DAGImpl.java:handle(1170)) - dag_1463534466279_0001_1 transitioned from RUNNING to COMMITTING due to event DAG_VERTEX_COMPLETED
2016-05-18 01:21:08,474 INFO  app.TezTaskCommunicatorImpl (TezTaskCommunicatorImpl.java:getContainerTask(416)) - Container with id: container_1463534466279_0001_00_000003 is valid, but no longer registered, and will be killed
2016-05-18 01:21:08,474 INFO  impl.DAGImpl (DAGImpl.java:call(1083)) - Committing output: A24A65E16249416EBE5023A2128E2CD9 for vertex: vertex_1463534466279_0001_1_02 [FCA327A24AE447C8B29F99C6C8C9BEFD], outputName: A24A65E16249416EBE5023A2128E2CD9
2016-05-18 01:21:08,478 INFO  task.ContainerReporter (ContainerReporter.java:callInternal(67)) - Got TaskUpdate for containerId= container_1463534466279_0001_00_000003: 15 ms after starting to poll. TaskInfo: shouldDie: true
2016-05-18 01:21:08,474 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:stop(262)) - Ignoring stop request for containerId container_1463534466279_0001_00_000003. Relying on regular task shutdown for it to end
2016-05-18 01:21:08,480 INFO  task.TezChild (TezChild.java:run(235)) - ContainerTask returned shouldDie=true for container container_1463534466279_0001_00_000003, Exiting
2016-05-18 01:21:08,480 INFO  task.TezChild (TezChild.java:shutdown(381)) - Shutdown invoked for container container_1463534466279_0001_00_000003
2016-05-18 01:21:08,480 INFO  task.TezChild (TezChild.java:shutdown(383)) - Shutting down container container_1463534466279_0001_00_000003
2016-05-18 01:21:08,481 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(285)) - ContainerExecutionResult for: container_1463534466279_0001_00_000003 = ContainerExecutionResult{exitStatus=SUCCESS, throwable=null, errorMessage='Asked to die by the AM'}
2016-05-18 01:21:08,481 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(289)) - Container: container_1463534466279_0001_00_000003 completed successfully
2016-05-18 01:21:08,492 INFO  impl.DAGImpl (DAGImpl.java:commitCompleted(2192)) - Commit succeeded for output:outputName:A24A65E16249416EBE5023A2128E2CD9 of vertex/vertexGroup:FCA327A24AE447C8B29F99C6C8C9BEFD isVertexGroupOutput:false
2016-05-18 01:21:08,492 INFO  impl.DAGImpl (DAGImpl.java:checkCommitsForCompletion(1313)) - Checking commits for DAG completion, numCompletedVertices=3, numSuccessfulVertices=3, numFailedVertices=0, numKilledVertices=0, numVertices=3, commitInProgress=0, terminationCause=null
2016-05-18 01:21:08,499 INFO  recovery.RecoveryService (RecoveryService.java:handle(327)) - DAG completed, dagId=dag_1463534466279_0001_1, queueSize=0
2016-05-18 01:21:08,501 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115)) - [HISTORY][DAG:dag_1463534466279_0001_1][Event:DAG_FINISHED]: dagId=dag_1463534466279_0001_1, startTime=1463534467155, finishTime=1463534468492, timeTaken=1337, status=SUCCEEDED, diagnostics=, counters=Counters: 48, org.apache.tez.common.counters.DAGCounter, NUM_SUCCEEDED_TASKS=3, TOTAL_LAUNCHED_TASKS=3, RACK_LOCAL_TASKS=2, AM_CPU_MILLISECONDS=3360, AM_GC_TIME_MILLIS=381, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=16, REDUCE_INPUT_RECORDS=20, COMBINE_INPUT_RECORDS=0, SPILLED_RECORDS=40, NUM_SHUFFLED_INPUTS=2, NUM_SKIPPED_INPUTS=0, NUM_FAILED_SHUFFLE_INPUTS=0, MERGED_MAP_OUTPUTS=2, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=35, OUTPUT_BYTES=2668, OUTPUT_BYTES_WITH_OVERHEAD=2700, OUTPUT_BYTES_PHYSICAL=2708, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=2708, ADDITIONAL_SPILL_COUNT=0, SHUFFLE_CHUNK_COUNT=2, SHUFFLE_BYTES=2708, SHUFFLE_BYTES_DECOMPRESSED=2700, SHUFFLE_BYTES_TO_MEM=0, SHUFFLE_BYTES_TO_DISK=0, SHUFFLE_BYTES_DISK_DIRECT=2708, NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=98, MERGE_PHASE_TIME=135, FIRST_EVENT_RECEIVED=69, LAST_EVENT_RECEIVED=69, 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=4390603403966, Process_Duration=66, Process_End_Time=4390603404032, Read_Duration=3, Tuples_Read=40, Tuples_Written=34, Write_Duration=5, cascading.flow.StepCounters, Tuples_Read=20, Tuples_Written=14
2016-05-18 01:21:08,502 INFO  impl.DAGImpl (DAGImpl.java:finished(1405)) - DAG: dag_1463534466279_0001_1 finished with state: SUCCEEDED
2016-05-18 01:21:08,502 INFO  impl.DAGImpl (DAGImpl.java:handle(1170)) - dag_1463534466279_0001_1 transitioned from COMMITTING to SUCCEEDED due to event DAG_COMMIT_COMPLETED
2016-05-18 01:21:08 Completed Dag: dag_1463534466279_0001_1
2016-05-18 01:21:08,504 INFO  app.DAGAppMaster (DAGAppMaster.java:handle(751)) - DAG completed, dagId=dag_1463534466279_0001_1, dagState=SUCCEEDED
2016-05-18 01:21:08,506 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(188)) - Redirecting log file based on addend: dag_1463534466279_0001_1_post
2016-05-18 01:21:08,506 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(203)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-18 01:21:08,506 INFO  app.DAGAppMaster (DAGAppMaster.java:handle(800)) - Central Dispatcher queue size after DAG completion, before cleanup: 0
2016-05-18 01:21:08,506 INFO  app.DAGAppMaster (DAGAppMaster.java:handle(802)) - Waiting for next DAG to be submitted.
2016-05-18 01:21:08,507 INFO  app.DAGAppMaster (DAGAppMaster.java:handle(842)) - Cleaning up DAG: name=[D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453] null/(1/1) ...eCheck/testFieldTypeCheck, with id=dag_1463534466279_0001_1
2016-05-18 01:21:08,512 INFO  app.DAGAppMaster (DAGAppMaster.java:handle(852)) - Completed cleanup for DAG: name=[D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453] null/(1/1) ...eCheck/testFieldTypeCheck, with id=dag_1463534466279_0001_1
2016-05-18 01:21:08,514 INFO  client.TezClient (TezClient.java:stop(566)) - Shutting down Tez Session, sessionName=(1/1) ...eCheck/testFieldTypeCheck, applicationId=application_1463534466279_0001
2016-05-18 01:21:08,520 INFO  client.DAGClientHandler (DAGClientHandler.java:shutdownAM(124)) - Received message to shutdown AM
2016-05-18 01:21:08,520 INFO  rm.TaskSchedulerManager (TaskSchedulerManager.java:setShouldUnregisterFlag(895)) - TaskScheduler notified that it should unregister from RM
2016-05-18 01:21:08,520 INFO  app.DAGAppMaster (DAGAppMaster.java:shutdownTezAM(1301)) - No current running DAG, shutting down the AM
2016-05-18 01:21:08,520 INFO  app.DAGAppMaster (DAGAppMaster.java:shutdown(907)) - DAGAppMasterShutdownHandler invoked
2016-05-18 01:21:08,520 INFO  app.DAGAppMaster (DAGAppMaster.java:shutdown(916)) - Handling DAGAppMaster shutdown
2016-05-18 01:21:08,522 INFO  app.DAGAppMaster (DAGAppMaster.java:run(936)) - Sleeping for 5 seconds before shutting down
2016-05-18 01:21:08,524 INFO  history.HistoryEventHandler (HistoryEventHandler.java:serviceStop(84)) - Stopping HistoryEventHandler
2016-05-18 01:21:08,524 INFO  recovery.RecoveryService (RecoveryService.java:serviceStop(196)) - Stopping RecoveryService
2016-05-18 01:21:08,524 INFO  recovery.RecoveryService (RecoveryService.java:serviceStop(199)) - Handle the remaining events in queue, queue size=0
2016-05-18 01:21:08,524 INFO  recovery.RecoveryService (RecoveryService.java:run(173)) - EventQueue take interrupted. Returning
2016-05-18 01:21:08,524 INFO  recovery.RecoveryService (RecoveryService.java:serviceStop(221)) - Closing Summary Stream
2016-05-18 01:21:08,525 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStop(118)) - Stopping SimpleHistoryLoggingService, eventQueueBacklog=0
2016-05-18 01:21:08,525 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:run(105)) - EventQueue take interrupted. Returning
2016-05-18 01:21:08,527 INFO  rm.TaskSchedulerManager (TaskSchedulerManager.java:serviceStop(678)) - Shutting down AppCallbackExecutor
2016-05-18 01:21:08,531 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/D866DE3DC38D49F18DF4150A10172997/C54186EC20D040CBBE501C85F021E453/.tez/application_1463534466279_0001
2016-05-18 01:21:08,533 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/typedfieldedpipesplatform/testFieldTypeCheck/testFieldTypeCheck/_temporary
2016-05-18 01:21:08,533 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - []  completed in: 00:02.422
2016-05-18 01:21:08,586 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/typedfieldedpipesplatform/testFieldTypeCheck/testFieldTypeCheck
2016-05-18 01:21:08,621 INFO  util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-18 01:21:08,622 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:21:08,663 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs+rhs] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: ILLEGAL, in: 00:00.009
2016-05-18 01:21:08,666 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs+rhs] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: ILLEGAL, in: 00:00.011
2016-05-18 01:21:08,666 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs+rhs] rule registry: NoHashJoinHadoop2TezRuleRegistry, found assembly to be malformed
2016-05-18 01:21:08,666 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [lhs+rhs] rule registry: HashJoinHadoop2TezRuleRegistry, found assembly to be malformed
2016-05-18 01:21:08,666 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/typedfieldedpipesplatform/testGroupByIncomparableTypes/testGroupByIncomparableTypes

Standard error

2016-05-18 01:21:07 Running Dag: dag_1463534466279_0001_1
2016-05-18 01:21:07 Starting to run new task attempt: attempt_1463534466279_0001_1_01_000000_0
2016-05-18 01:21:07 Starting to run new task attempt: attempt_1463534466279_0001_1_00_000000_0
2016-05-18 01:21:08 Completed running task attempt: attempt_1463534466279_0001_1_00_000000_0
2016-05-18 01:21:08 Completed running task attempt: attempt_1463534466279_0001_1_01_000000_0
2016-05-18 01:21:08 Starting to run new task attempt: attempt_1463534466279_0001_1_02_000000_0
2016-05-18 01:21:08 Completed running task attempt: attempt_1463534466279_0001_1_02_000000_0
2016-05-18 01:21:08 Completed Dag: dag_1463534466279_0001_1