2016-05-18 00:38:53,977 INFO platform.PlatformRunner (PlatformRunner.java:getPlatformClassesFromClasspath(197)) - found 1 test platforms from classpath
2016-05-18 00:38:54,007 INFO platform.PlatformRunner (PlatformRunner.java:addPlatform(246)) - adding test: cascading.flow.AssemblyPlannerPlatformTest, with platform: hadoop2-mr1
2016-05-18 00:38:54,038 INFO hadoop2.Hadoop2MR1Platform (Hadoop2MR1Platform.java:setUp(119)) - not using cluster
2016-05-18 00:38:54,593 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 00:38:54,763 INFO platform.TestPlatform (TestPlatform.java:getGlobalProperties(75)) - platform property overrides:
2016-05-18 00:38:54,871 INFO util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-18 00:38:54,874 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(176)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/3.1.0/fdadb6ac788ea19f3412b9569a43a7635318b0c5/cascading-hadoop2-mr1-3.1.0.jar
2016-05-18 00:38:54,987 INFO property.AppProps (AppProps.java:getAppID(177)) - using app.id: 84FEC3B6F9FF4EC592E099677E7EB445
2016-05-18 00:38:55,167 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [] executed rule registry: MapReduceHadoopRuleRegistry, completed as: SUCCESS, in: 00:00.116
2016-05-18 00:38:55,170 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [] rule registry: MapReduceHadoopRuleRegistry, supports assembly with steps: 1, nodes: 2
2016-05-18 00:38:55,171 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [] rule registry: MapReduceHadoopRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-05-18 00:38:55,336 INFO util.Version (Version.java:printBanner(82)) - Concurrent, Inc - Cascading 3.1.0
2016-05-18 00:38:55,340 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [] starting
2016-05-18 00:38:55,341 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.3.x/build/classes/test/data/apache.10.txt"]
2016-05-18 00:38:55,342 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [] sink: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.3.x/build/test/output/hadoop2-mr1/assemblyplannerplatform/testCompositeAssembly/composite"]
2016-05-18 00:38:55,342 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [] parallel execution of steps is enabled: false
2016-05-18 00:38:55,344 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [] executing total steps: 1
2016-05-18 00:38:55,344 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [] allocating management threads: 1
2016-05-18 00:38:55,345 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [] starting step: (1/1) ...mpositeAssembly/composite
2016-05-18 00:38:55,847 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.3.x/build/tmp/cascading/staging/teamcity56455193/.staging/job_local56455193_0001/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2016-05-18 00:38:55,857 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.3.x/build/tmp/cascading/staging/teamcity56455193/.staging/job_local56455193_0001/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2016-05-18 00:38:56,041 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local56455193_0001/job_local56455193_0001.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2016-05-18 00:38:56,042 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local56455193_0001/job_local56455193_0001.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2016-05-18 00:38:56,057 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [] submitted hadoop job: job_local56455193_0001
2016-05-18 00:38:56,057 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [] tracking url: http://localhost:8080/
2016-05-18 00:38:56,156 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.3.x/build/classes/test/data/apache.10.txt
2016-05-18 00:38:56,309 INFO hadoop.FlowMapper (FlowMapper.java:configure(75)) - cascading version: 3.1.0
2016-05-18 00:38:56,309 INFO hadoop.FlowMapper (FlowMapper.java:configure(76)) - child jvm opts: -Xmx200m
2016-05-18 00:38:56,329 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - flow node id: EB9B3F3B46F04EE5AEB687908120C0AA, ordinal: 0
2016-05-18 00:38:56,368 INFO hadoop.FlowMapper (FlowMapper.java:configure(94)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.3.x/build/classes/test/data/apache.10.txt"]
2016-05-18 00:38:56,368 INFO hadoop.FlowMapper (FlowMapper.java:configure(97)) - sinking to: GroupBy(test)[by:[{1}:'ip']]
2016-05-18 00:38:56,369 INFO hadoop.FlowMapper (LogUtil.java:logMemory(59)) - flow node id: EB9B3F3B46F04EE5AEB687908120C0AA, mem on start (mb), free: 87, total: 223, max: 672
2016-05-18 00:38:56,378 INFO hadoop.FlowMapper (LogUtil.java:logMemory(59)) - flow node id: EB9B3F3B46F04EE5AEB687908120C0AA, mem on close (mb), free: 86, total: 223, max: 672
2016-05-18 00:38:56,494 INFO hadoop.FlowReducer (FlowReducer.java:configure(83)) - cascading version: 3.1.0
2016-05-18 00:38:56,495 INFO hadoop.FlowReducer (FlowReducer.java:configure(84)) - child jvm opts: -Xmx200m
2016-05-18 00:38:56,510 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - flow node id: A8897676DA26427B8AA6C0E1F6559405, ordinal: 1
2016-05-18 00:38:56,513 INFO hadoop.FlowReducer (FlowReducer.java:configure(104)) - sourcing from: GroupBy(test)[by:[{1}:'ip']]
2016-05-18 00:38:56,514 INFO hadoop.FlowReducer (FlowReducer.java:configure(107)) - sinking to: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.3.x/build/test/output/hadoop2-mr1/assemblyplannerplatform/testCompositeAssembly/composite"]
2016-05-18 00:38:56,514 INFO hadoop.FlowReducer (LogUtil.java:logMemory(59)) - flow node id: A8897676DA26427B8AA6C0E1F6559405, mem on start (mb), free: 76, total: 223, max: 672
2016-05-18 00:38:56,534 INFO hadoop.FlowReducer (LogUtil.java:logMemory(59)) - flow node id: A8897676DA26427B8AA6C0E1F6559405, mem on close (mb), free: 75, total: 223, max: 672
2016-05-18 00:38:56,567 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(226)) - deleting temp path /opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.3.x/build/test/output/hadoop2-mr1/assemblyplannerplatform/testCompositeAssembly/composite/_temporary
2016-05-18 00:38:56,567 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [] completed in: 00:01.225
2016-05-18 00:38:56,597 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.3.x/build/test/output//hadoop2-mr1/assemblyplannerplatform/testCompositeAssembly/composite
2016-05-18 00:38:56,617 INFO util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-18 00:38:56,618 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(176)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/3.1.0/fdadb6ac788ea19f3412b9569a43a7635318b0c5/cascading-hadoop2-mr1-3.1.0.jar
2016-05-18 00:38:56,697 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [] executed rule registry: MapReduceHadoopRuleRegistry, completed as: SUCCESS, in: 00:00.067
2016-05-18 00:38:56,699 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [] rule registry: MapReduceHadoopRuleRegistry, supports assembly with steps: 1, nodes: 2
2016-05-18 00:38:56,699 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [] rule registry: MapReduceHadoopRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-05-18 00:38:56,727 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [] starting
2016-05-18 00:38:56,727 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.3.x/build/classes/test/data/apache.10.txt"]
2016-05-18 00:38:56,728 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [] sink: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.3.x/build/test/output/hadoop2-mr1/assemblyplannerplatform/testSimpleAssembly/simple"]
2016-05-18 00:38:56,728 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [] parallel execution of steps is enabled: false
2016-05-18 00:38:56,729 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [] executing total steps: 1
2016-05-18 00:38:56,729 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [] allocating management threads: 1
2016-05-18 00:38:56,730 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [] starting step: (1/1) ...testSimpleAssembly/simple
2016-05-18 00:38:56,819 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.3.x/build/tmp/cascading/staging/teamcity1090832832/.staging/job_local1090832832_0002/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2016-05-18 00:38:56,822 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.3.x/build/tmp/cascading/staging/teamcity1090832832/.staging/job_local1090832832_0002/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2016-05-18 00:38:56,889 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1090832832_0002/job_local1090832832_0002.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2016-05-18 00:38:56,890 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1090832832_0002/job_local1090832832_0002.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2016-05-18 00:38:56,892 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [] submitted hadoop job: job_local1090832832_0002
2016-05-18 00:38:56,892 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [] tracking url: http://localhost:8080/
2016-05-18 00:38:56,900 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.3.x/build/classes/test/data/apache.10.txt
2016-05-18 00:38:57,003 INFO hadoop.FlowMapper (FlowMapper.java:configure(75)) - cascading version: 3.1.0
2016-05-18 00:38:57,003 INFO hadoop.FlowMapper (FlowMapper.java:configure(76)) - child jvm opts: -Xmx200m
2016-05-18 00:38:57,013 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - flow node id: D21A550C035040119C51B2E5BBB4FD2F, ordinal: 0
2016-05-18 00:38:57,013 INFO hadoop.FlowMapper (FlowMapper.java:configure(94)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.3.x/build/classes/test/data/apache.10.txt"]
2016-05-18 00:38:57,014 INFO hadoop.FlowMapper (FlowMapper.java:configure(97)) - sinking to: GroupBy(test)[by:[{1}:'ip']]
2016-05-18 00:38:57,014 INFO hadoop.FlowMapper (LogUtil.java:logMemory(59)) - flow node id: D21A550C035040119C51B2E5BBB4FD2F, mem on start (mb), free: 94, total: 323, max: 672
2016-05-18 00:38:57,017 INFO hadoop.FlowMapper (LogUtil.java:logMemory(59)) - flow node id: D21A550C035040119C51B2E5BBB4FD2F, mem on close (mb), free: 94, total: 323, max: 672
2016-05-18 00:38:57,036 INFO hadoop.FlowReducer (FlowReducer.java:configure(83)) - cascading version: 3.1.0
2016-05-18 00:38:57,036 INFO hadoop.FlowReducer (FlowReducer.java:configure(84)) - child jvm opts: -Xmx200m
2016-05-18 00:38:57,054 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - flow node id: C96774414B7B462FBB014D9CA5DD1556, ordinal: 1
2016-05-18 00:38:57,056 INFO hadoop.FlowReducer (FlowReducer.java:configure(104)) - sourcing from: GroupBy(test)[by:[{1}:'ip']]
2016-05-18 00:38:57,056 INFO hadoop.FlowReducer (FlowReducer.java:configure(107)) - sinking to: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.3.x/build/test/output/hadoop2-mr1/assemblyplannerplatform/testSimpleAssembly/simple"]
2016-05-18 00:38:57,056 INFO hadoop.FlowReducer (LogUtil.java:logMemory(59)) - flow node id: C96774414B7B462FBB014D9CA5DD1556, mem on start (mb), free: 91, total: 323, max: 672
2016-05-18 00:38:57,067 INFO hadoop.FlowReducer (LogUtil.java:logMemory(59)) - flow node id: C96774414B7B462FBB014D9CA5DD1556, mem on close (mb), free: 90, total: 323, max: 672
2016-05-18 00:38:57,093 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(226)) - deleting temp path /opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.3.x/build/test/output/hadoop2-mr1/assemblyplannerplatform/testSimpleAssembly/simple/_temporary
2016-05-18 00:38:57,094 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [] completed in: 00:00.366
2016-05-18 00:38:57,127 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.3.x/build/test/output//hadoop2-mr1/assemblyplannerplatform/testSimpleAssembly/simple