2016-05-18 02:54:38,023 INFO platform.PlatformRunner (PlatformRunner.java:getPlatformClassesFromClasspath(197)) - found 1 test platforms from classpath
2016-05-18 02:54:38,049 INFO platform.PlatformRunner (PlatformRunner.java:addPlatform(246)) - adding test: cascading.cascade.RiffleCascadePlatformTest, with platform: hadoop2-mr1
2016-05-18 02:54:38,085 INFO hadoop2.Hadoop2MR1Platform (Hadoop2MR1Platform.java:setUp(119)) - not using cluster
2016-05-18 02:54:38,689 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 02:54:38,863 INFO platform.TestPlatform (TestPlatform.java:getGlobalProperties(75)) - platform property overrides:
2016-05-18 02:54:38,921 INFO property.AppProps (AppProps.java:getAppID(177)) - using app.id: DFA36662B66E44BE99183A74978578AC
2016-05-18 02:54:38,965 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output//hadoop2-mr1/rifflecascadeplatform/testProcessFlowWithChildCounters/children/first
2016-05-18 02:54:38,977 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output//hadoop2-mr1/rifflecascadeplatform/testProcessFlowFlowListenerExceptionHandlingInStop/stopException/first
2016-05-18 02:54:39,060 INFO util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-18 02:54:39,063 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 02:54:39,279 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [first] executed rule registry: MapReduceHadoopRuleRegistry, completed as: SUCCESS, in: 00:00.082
2016-05-18 02:54:39,282 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [first] rule registry: MapReduceHadoopRuleRegistry, supports assembly with steps: 1, nodes: 1
2016-05-18 02:54:39,282 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [first] rule registry: MapReduceHadoopRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-05-18 02:54:39,416 INFO util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-18 02:54:39,417 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 02:54:39,473 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [second] executed rule registry: MapReduceHadoopRuleRegistry, completed as: SUCCESS, in: 00:00.046
2016-05-18 02:54:39,476 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [second] rule registry: MapReduceHadoopRuleRegistry, supports assembly with steps: 1, nodes: 1
2016-05-18 02:54:39,476 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [second] rule registry: MapReduceHadoopRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-05-18 02:54:39,515 INFO util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-18 02:54:39,516 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 02:54:39,564 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [third] executed rule registry: MapReduceHadoopRuleRegistry, completed as: SUCCESS, in: 00:00.041
2016-05-18 02:54:39,565 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [third] rule registry: MapReduceHadoopRuleRegistry, supports assembly with steps: 1, nodes: 1
2016-05-18 02:54:39,566 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [third] rule registry: MapReduceHadoopRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-05-18 02:54:39,598 INFO util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-18 02:54:39,599 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 02:54:39,652 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [fourth] executed rule registry: MapReduceHadoopRuleRegistry, completed as: SUCCESS, in: 00:00.044
2016-05-18 02:54:39,654 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [fourth] rule registry: MapReduceHadoopRuleRegistry, supports assembly with steps: 1, nodes: 1
2016-05-18 02:54:39,655 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [fourth] rule registry: MapReduceHadoopRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-05-18 02:54:39,771 INFO util.Version (Version.java:printBanner(82)) - Concurrent, Inc - Cascading 3.1.0
2016-05-18 02:54:39,773 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [first] starting
2016-05-18 02:54:39,773 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [first] source: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/classes/test/data/ips.20.txt"]
2016-05-18 02:54:39,774 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [first] sink: Hfs["TextDelimited[['ip']]"]["/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output/hadoop2-mr1/rifflecascadeplatform/testSimpleRiffle/perpetual/first"]
2016-05-18 02:54:39,774 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [first] parallel execution of steps is enabled: false
2016-05-18 02:54:39,774 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [first] executing total steps: 1
2016-05-18 02:54:39,775 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [first] allocating management threads: 1
2016-05-18 02:54:39,776 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [first] starting step: (1/1) ...pleRiffle/perpetual/first
2016-05-18 02:54:40,313 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/tmp/cascading/staging/teamcity2096694444/.staging/job_local2096694444_0001/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2016-05-18 02:54:40,319 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/tmp/cascading/staging/teamcity2096694444/.staging/job_local2096694444_0001/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2016-05-18 02:54:40,498 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local2096694444_0001/job_local2096694444_0001.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2016-05-18 02:54:40,504 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local2096694444_0001/job_local2096694444_0001.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2016-05-18 02:54:40,513 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [first] submitted hadoop job: job_local2096694444_0001
2016-05-18 02:54:40,513 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [first] tracking url: http://localhost:8080/
2016-05-18 02:54:40,618 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/classes/test/data/ips.20.txt
2016-05-18 02:54:40,644 INFO hadoop.FlowMapper (FlowMapper.java:configure(75)) - cascading version: 3.1.0
2016-05-18 02:54:40,644 INFO hadoop.FlowMapper (FlowMapper.java:configure(76)) - child jvm opts: -Xmx200m
2016-05-18 02:54:40,658 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - flow node id: B8AB1A64F8C6453CAF7BEB1723E8116E, ordinal: 0
2016-05-18 02:54:40,697 INFO hadoop.FlowMapper (FlowMapper.java:configure(94)) - sourcing from: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/classes/test/data/ips.20.txt"]
2016-05-18 02:54:40,697 INFO hadoop.FlowMapper (FlowMapper.java:configure(97)) - sinking to: Hfs["TextDelimited[['ip']]"]["/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output/hadoop2-mr1/rifflecascadeplatform/testSimpleRiffle/perpetual/first"]
2016-05-18 02:54:40,699 INFO hadoop.FlowMapper (LogUtil.java:logMemory(59)) - flow node id: B8AB1A64F8C6453CAF7BEB1723E8116E, mem on start (mb), free: 165, total: 223, max: 672
2016-05-18 02:54:40,712 INFO hadoop.FlowMapper (LogUtil.java:logMemory(59)) - flow node id: B8AB1A64F8C6453CAF7BEB1723E8116E, mem on close (mb), free: 164, total: 223, max: 672
2016-05-18 02:54:40,750 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(226)) - deleting temp path /opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output/hadoop2-mr1/rifflecascadeplatform/testSimpleRiffle/perpetual/first/_temporary
2016-05-18 02:54:40,751 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [first] completed in: 00:00.977
2016-05-18 02:54:40,753 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [second] starting
2016-05-18 02:54:40,753 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [second] source: Hfs["TextDelimited[['ip']]"]["/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output/hadoop2-mr1/rifflecascadeplatform/testSimpleRiffle/perpetual/first"]
2016-05-18 02:54:40,753 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [second] sink: Hfs["TextDelimited[['first', 'second', 'third', 'fourth']]"]["/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output/hadoop2-mr1/rifflecascadeplatform/testSimpleRiffle/perpetual/second"]
2016-05-18 02:54:40,754 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [second] parallel execution of steps is enabled: false
2016-05-18 02:54:40,754 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [second] executing total steps: 1
2016-05-18 02:54:40,754 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [second] allocating management threads: 1
2016-05-18 02:54:40,756 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [second] starting step: (1/1) ...leRiffle/perpetual/second
2016-05-18 02:54:40,858 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/tmp/cascading/staging/teamcity2001376222/.staging/job_local2001376222_0002/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2016-05-18 02:54:40,859 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/tmp/cascading/staging/teamcity2001376222/.staging/job_local2001376222_0002/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2016-05-18 02:54:40,926 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local2001376222_0002/job_local2001376222_0002.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2016-05-18 02:54:40,930 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local2001376222_0002/job_local2001376222_0002.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2016-05-18 02:54:40,931 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [second] submitted hadoop job: job_local2001376222_0002
2016-05-18 02:54:40,931 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [second] tracking url: http://localhost:8080/
2016-05-18 02:54:40,939 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output/hadoop2-mr1/rifflecascadeplatform/testSimpleRiffle/perpetual/first/part-00000
2016-05-18 02:54:40,949 INFO hadoop.FlowMapper (FlowMapper.java:configure(75)) - cascading version: 3.1.0
2016-05-18 02:54:40,949 INFO hadoop.FlowMapper (FlowMapper.java:configure(76)) - child jvm opts: -Xmx200m
2016-05-18 02:54:40,959 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - flow node id: A78C19965E0548C4B9090B7665592077, ordinal: 0
2016-05-18 02:54:40,960 INFO hadoop.FlowMapper (FlowMapper.java:configure(94)) - sourcing from: Hfs["TextDelimited[['ip']]"]["/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output/hadoop2-mr1/rifflecascadeplatform/testSimpleRiffle/perpetual/first"]
2016-05-18 02:54:40,960 INFO hadoop.FlowMapper (FlowMapper.java:configure(97)) - sinking to: Hfs["TextDelimited[['first', 'second', 'third', 'fourth']]"]["/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output/hadoop2-mr1/rifflecascadeplatform/testSimpleRiffle/perpetual/second"]
2016-05-18 02:54:40,961 INFO hadoop.FlowMapper (LogUtil.java:logMemory(59)) - flow node id: A78C19965E0548C4B9090B7665592077, mem on start (mb), free: 190, total: 223, max: 672
2016-05-18 02:54:40,967 INFO hadoop.FlowMapper (LogUtil.java:logMemory(59)) - flow node id: A78C19965E0548C4B9090B7665592077, mem on close (mb), free: 189, total: 223, max: 672
2016-05-18 02:54:40,985 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(226)) - deleting temp path /opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output/hadoop2-mr1/rifflecascadeplatform/testSimpleRiffle/perpetual/second/_temporary
2016-05-18 02:54:40,986 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [second] completed in: 00:00.232
2016-05-18 02:54:40,988 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [third] starting
2016-05-18 02:54:40,989 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [third] source: Hfs["TextDelimited[['first', 'second', 'third', 'fourth']]"]["/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output/hadoop2-mr1/rifflecascadeplatform/testSimpleRiffle/perpetual/second"]
2016-05-18 02:54:40,989 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [third] sink: Hfs["TextDelimited[['mangled']]"]["/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output/hadoop2-mr1/rifflecascadeplatform/testSimpleRiffle/perpetual/third"]
2016-05-18 02:54:40,989 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [third] parallel execution of steps is enabled: false
2016-05-18 02:54:40,990 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [third] executing total steps: 1
2016-05-18 02:54:40,990 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [third] allocating management threads: 1
2016-05-18 02:54:40,990 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [third] starting step: (1/1) ...pleRiffle/perpetual/third
2016-05-18 02:54:41,095 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/tmp/cascading/staging/teamcity920353983/.staging/job_local920353983_0003/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2016-05-18 02:54:41,096 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/tmp/cascading/staging/teamcity920353983/.staging/job_local920353983_0003/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2016-05-18 02:54:41,142 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local920353983_0003/job_local920353983_0003.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2016-05-18 02:54:41,144 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local920353983_0003/job_local920353983_0003.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2016-05-18 02:54:41,145 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [third] submitted hadoop job: job_local920353983_0003
2016-05-18 02:54:41,145 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [third] tracking url: http://localhost:8080/
2016-05-18 02:54:41,155 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output/hadoop2-mr1/rifflecascadeplatform/testSimpleRiffle/perpetual/second/part-00000
2016-05-18 02:54:41,164 INFO hadoop.FlowMapper (FlowMapper.java:configure(75)) - cascading version: 3.1.0
2016-05-18 02:54:41,164 INFO hadoop.FlowMapper (FlowMapper.java:configure(76)) - child jvm opts: -Xmx200m
2016-05-18 02:54:41,175 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - flow node id: F890DF277D92459EB4D20322073154EB, ordinal: 0
2016-05-18 02:54:41,175 INFO hadoop.FlowMapper (FlowMapper.java:configure(94)) - sourcing from: Hfs["TextDelimited[['first', 'second', 'third', 'fourth']]"]["/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output/hadoop2-mr1/rifflecascadeplatform/testSimpleRiffle/perpetual/second"]
2016-05-18 02:54:41,176 INFO hadoop.FlowMapper (FlowMapper.java:configure(97)) - sinking to: Hfs["TextDelimited[['mangled']]"]["/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output/hadoop2-mr1/rifflecascadeplatform/testSimpleRiffle/perpetual/third"]
2016-05-18 02:54:41,176 INFO hadoop.FlowMapper (LogUtil.java:logMemory(59)) - flow node id: F890DF277D92459EB4D20322073154EB, mem on start (mb), free: 159, total: 223, max: 672
2016-05-18 02:54:41,181 INFO hadoop.FlowMapper (LogUtil.java:logMemory(59)) - flow node id: F890DF277D92459EB4D20322073154EB, mem on close (mb), free: 159, total: 223, max: 672
2016-05-18 02:54:41,200 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(226)) - deleting temp path /opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output/hadoop2-mr1/rifflecascadeplatform/testSimpleRiffle/perpetual/third/_temporary
2016-05-18 02:54:41,201 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [third] completed in: 00:00.212
2016-05-18 02:54:41,203 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [fourth] starting
2016-05-18 02:54:41,204 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [fourth] source: Hfs["TextDelimited[['mangled']]"]["/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output/hadoop2-mr1/rifflecascadeplatform/testSimpleRiffle/perpetual/third"]
2016-05-18 02:54:41,204 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [fourth] sink: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output/hadoop2-mr1/rifflecascadeplatform/testSimpleRiffle/perpetual/fourth"]
2016-05-18 02:54:41,204 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [fourth] parallel execution of steps is enabled: false
2016-05-18 02:54:41,204 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [fourth] executing total steps: 1
2016-05-18 02:54:41,205 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [fourth] allocating management threads: 1
2016-05-18 02:54:41,205 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [fourth] starting step: (1/1) ...leRiffle/perpetual/fourth
2016-05-18 02:54:41,332 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/tmp/cascading/staging/teamcity995375885/.staging/job_local995375885_0004/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2016-05-18 02:54:41,333 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/tmp/cascading/staging/teamcity995375885/.staging/job_local995375885_0004/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2016-05-18 02:54:41,384 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local995375885_0004/job_local995375885_0004.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2016-05-18 02:54:41,386 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local995375885_0004/job_local995375885_0004.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2016-05-18 02:54:41,386 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [fourth] submitted hadoop job: job_local995375885_0004
2016-05-18 02:54:41,387 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [fourth] tracking url: http://localhost:8080/
2016-05-18 02:54:41,394 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output/hadoop2-mr1/rifflecascadeplatform/testSimpleRiffle/perpetual/third/part-00000
2016-05-18 02:54:41,403 INFO hadoop.FlowMapper (FlowMapper.java:configure(75)) - cascading version: 3.1.0
2016-05-18 02:54:41,404 INFO hadoop.FlowMapper (FlowMapper.java:configure(76)) - child jvm opts: -Xmx200m
2016-05-18 02:54:41,414 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - flow node id: FE4688BEA42742E4A2B48EEE24CE88B3, ordinal: 0
2016-05-18 02:54:41,414 INFO hadoop.FlowMapper (FlowMapper.java:configure(94)) - sourcing from: Hfs["TextDelimited[['mangled']]"]["/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output/hadoop2-mr1/rifflecascadeplatform/testSimpleRiffle/perpetual/third"]
2016-05-18 02:54:41,415 INFO hadoop.FlowMapper (FlowMapper.java:configure(97)) - sinking to: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output/hadoop2-mr1/rifflecascadeplatform/testSimpleRiffle/perpetual/fourth"]
2016-05-18 02:54:41,415 INFO hadoop.FlowMapper (LogUtil.java:logMemory(59)) - flow node id: FE4688BEA42742E4A2B48EEE24CE88B3, mem on start (mb), free: 243, total: 281, max: 672
2016-05-18 02:54:41,418 INFO hadoop.FlowMapper (LogUtil.java:logMemory(59)) - flow node id: FE4688BEA42742E4A2B48EEE24CE88B3, mem on close (mb), free: 243, total: 281, max: 672
2016-05-18 02:54:41,444 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(226)) - deleting temp path /opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output/hadoop2-mr1/rifflecascadeplatform/testSimpleRiffle/perpetual/fourth/_temporary
2016-05-18 02:54:41,444 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [fourth] completed in: 00:00.240
2016-05-18 02:54:41,498 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output//hadoop2-mr1/rifflecascadeplatform/testSimpleRiffle/perpetual/first
2016-05-18 02:54:41,498 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output//hadoop2-mr1/rifflecascadeplatform/testSimpleRiffle/perpetual/third
2016-05-18 02:54:41,498 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output//hadoop2-mr1/rifflecascadeplatform/testSimpleRiffle/perpetual/second
2016-05-18 02:54:41,499 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output//hadoop2-mr1/rifflecascadeplatform/testSimpleRiffle/perpetual/fourth
2016-05-18 02:54:41,526 INFO util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-18 02:54:41,527 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 02:54:41,573 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [first] executed rule registry: MapReduceHadoopRuleRegistry, completed as: SUCCESS, in: 00:00.038
2016-05-18 02:54:41,574 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [first] rule registry: MapReduceHadoopRuleRegistry, supports assembly with steps: 1, nodes: 1
2016-05-18 02:54:41,575 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [first] rule registry: MapReduceHadoopRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-05-18 02:54:41,602 INFO util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-18 02:54:41,603 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 02:54:41,650 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [second] executed rule registry: MapReduceHadoopRuleRegistry, completed as: SUCCESS, in: 00:00.039
2016-05-18 02:54:41,652 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [second] rule registry: MapReduceHadoopRuleRegistry, supports assembly with steps: 1, nodes: 1
2016-05-18 02:54:41,652 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [second] rule registry: MapReduceHadoopRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-05-18 02:54:41,685 INFO util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-18 02:54:41,686 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 02:54:41,716 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [third] executed rule registry: MapReduceHadoopRuleRegistry, completed as: SUCCESS, in: 00:00.026
2016-05-18 02:54:41,718 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [third] rule registry: MapReduceHadoopRuleRegistry, supports assembly with steps: 1, nodes: 1
2016-05-18 02:54:41,718 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [third] rule registry: MapReduceHadoopRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-05-18 02:54:41,741 INFO util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-18 02:54:41,741 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 02:54:41,771 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [fourth] executed rule registry: MapReduceHadoopRuleRegistry, completed as: SUCCESS, in: 00:00.025
2016-05-18 02:54:41,772 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [fourth] rule registry: MapReduceHadoopRuleRegistry, supports assembly with steps: 1, nodes: 1
2016-05-18 02:54:41,772 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [fourth] rule registry: MapReduceHadoopRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-05-18 02:54:41,799 INFO cascade.Cascade (BaseCascade.java:logInfo(860)) - [fourth+second+first+third] starting
2016-05-18 02:54:41,800 INFO cascade.Cascade (BaseCascade.java:logInfo(860)) - [fourth+second+first+third] parallel execution of flows is enabled: false
2016-05-18 02:54:41,800 INFO cascade.Cascade (BaseCascade.java:logInfo(860)) - [fourth+second+first+third] executing total flows: 4
2016-05-18 02:54:41,801 INFO cascade.Cascade (BaseCascade.java:logInfo(860)) - [fourth+second+first+third] allocating management threads: 1
2016-05-18 02:54:41,801 INFO cascade.Cascade (BaseCascade.java:logInfo(860)) - [fourth+second+first+third] starting flow: first
2016-05-18 02:54:41,802 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [first] at least one sink is marked for delete
2016-05-18 02:54:41,805 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [first] sink oldest modified date: Wed Dec 31 23:59:59 UTC 1969
2016-05-18 02:54:41,809 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [first] starting
2016-05-18 02:54:41,809 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [first] source: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/classes/test/data/ips.20.txt"]
2016-05-18 02:54:41,809 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [first] sink: Hfs["TextDelimited[['ip']]"]["/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output/hadoop2-mr1/rifflecascadeplatform/testSimpleRiffleCascade/perpetualcascade/first"]
2016-05-18 02:54:41,809 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [first] parallel execution of steps is enabled: false
2016-05-18 02:54:41,810 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [first] executing total steps: 1
2016-05-18 02:54:41,810 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [first] allocating management threads: 1
2016-05-18 02:54:41,811 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [first] starting step: (1/1) ...de/perpetualcascade/first
2016-05-18 02:54:41,882 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/tmp/cascading/staging/teamcity605907302/.staging/job_local605907302_0005/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2016-05-18 02:54:41,883 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/tmp/cascading/staging/teamcity605907302/.staging/job_local605907302_0005/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2016-05-18 02:54:41,934 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local605907302_0005/job_local605907302_0005.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2016-05-18 02:54:41,935 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local605907302_0005/job_local605907302_0005.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2016-05-18 02:54:41,935 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [first] submitted hadoop job: job_local605907302_0005
2016-05-18 02:54:41,937 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [first] tracking url: http://localhost:8080/
2016-05-18 02:54:41,943 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/classes/test/data/ips.20.txt
2016-05-18 02:54:41,951 INFO hadoop.FlowMapper (FlowMapper.java:configure(75)) - cascading version: 3.1.0
2016-05-18 02:54:41,952 INFO hadoop.FlowMapper (FlowMapper.java:configure(76)) - child jvm opts: -Xmx200m
2016-05-18 02:54:41,964 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - flow node id: D94BDBB8CA1644BD9E1E2F20101CA494, ordinal: 0
2016-05-18 02:54:41,965 INFO hadoop.FlowMapper (FlowMapper.java:configure(94)) - sourcing from: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/classes/test/data/ips.20.txt"]
2016-05-18 02:54:41,965 INFO hadoop.FlowMapper (FlowMapper.java:configure(97)) - sinking to: Hfs["TextDelimited[['ip']]"]["/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output/hadoop2-mr1/rifflecascadeplatform/testSimpleRiffleCascade/perpetualcascade/first"]
2016-05-18 02:54:41,965 INFO hadoop.FlowMapper (LogUtil.java:logMemory(59)) - flow node id: D94BDBB8CA1644BD9E1E2F20101CA494, mem on start (mb), free: 176, total: 281, max: 672
2016-05-18 02:54:41,969 INFO hadoop.FlowMapper (LogUtil.java:logMemory(59)) - flow node id: D94BDBB8CA1644BD9E1E2F20101CA494, mem on close (mb), free: 176, total: 281, max: 672
2016-05-18 02:54:41,992 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(226)) - deleting temp path /opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output/hadoop2-mr1/rifflecascadeplatform/testSimpleRiffleCascade/perpetualcascade/first/_temporary
2016-05-18 02:54:41,993 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [first] completed in: 00:00.183
2016-05-18 02:54:41,993 INFO cascade.Cascade (BaseCascade.java:logInfo(860)) - [fourth+second+first+third] completed flow: first
2016-05-18 02:54:41,994 INFO cascade.Cascade (BaseCascade.java:logInfo(860)) - [fourth+second+first+third] starting flow: second
2016-05-18 02:54:41,994 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [second] at least one sink is marked for delete
2016-05-18 02:54:41,994 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [second] sink oldest modified date: Wed Dec 31 23:59:59 UTC 1969
2016-05-18 02:54:42,001 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [second] starting
2016-05-18 02:54:42,002 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [second] source: Hfs["TextDelimited[['ip']]"]["/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output/hadoop2-mr1/rifflecascadeplatform/testSimpleRiffleCascade/perpetualcascade/first"]
2016-05-18 02:54:42,002 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [second] sink: Hfs["TextDelimited[['first', 'second', 'third', 'fourth']]"]["/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output/hadoop2-mr1/rifflecascadeplatform/testSimpleRiffleCascade/perpetualcascade/second"]
2016-05-18 02:54:42,004 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [second] parallel execution of steps is enabled: false
2016-05-18 02:54:42,004 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [second] executing total steps: 1
2016-05-18 02:54:42,004 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [second] allocating management threads: 1
2016-05-18 02:54:42,005 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [second] starting step: (1/1) ...e/perpetualcascade/second
2016-05-18 02:54:42,085 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/tmp/cascading/staging/teamcity712756713/.staging/job_local712756713_0006/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2016-05-18 02:54:42,086 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/tmp/cascading/staging/teamcity712756713/.staging/job_local712756713_0006/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2016-05-18 02:54:42,148 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local712756713_0006/job_local712756713_0006.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2016-05-18 02:54:42,149 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local712756713_0006/job_local712756713_0006.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2016-05-18 02:54:42,149 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [second] submitted hadoop job: job_local712756713_0006
2016-05-18 02:54:42,149 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [second] tracking url: http://localhost:8080/
2016-05-18 02:54:42,156 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output/hadoop2-mr1/rifflecascadeplatform/testSimpleRiffleCascade/perpetualcascade/first/part-00000
2016-05-18 02:54:42,163 INFO hadoop.FlowMapper (FlowMapper.java:configure(75)) - cascading version: 3.1.0
2016-05-18 02:54:42,164 INFO hadoop.FlowMapper (FlowMapper.java:configure(76)) - child jvm opts: -Xmx200m
2016-05-18 02:54:42,172 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - flow node id: FC8A4ACCB2AE4060B98CA22C4A8ADCC4, ordinal: 0
2016-05-18 02:54:42,173 INFO hadoop.FlowMapper (FlowMapper.java:configure(94)) - sourcing from: Hfs["TextDelimited[['ip']]"]["/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output/hadoop2-mr1/rifflecascadeplatform/testSimpleRiffleCascade/perpetualcascade/first"]
2016-05-18 02:54:42,173 INFO hadoop.FlowMapper (FlowMapper.java:configure(97)) - sinking to: Hfs["TextDelimited[['first', 'second', 'third', 'fourth']]"]["/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output/hadoop2-mr1/rifflecascadeplatform/testSimpleRiffleCascade/perpetualcascade/second"]
2016-05-18 02:54:42,173 INFO hadoop.FlowMapper (LogUtil.java:logMemory(59)) - flow node id: FC8A4ACCB2AE4060B98CA22C4A8ADCC4, mem on start (mb), free: 257, total: 281, max: 672
2016-05-18 02:54:42,176 INFO hadoop.FlowMapper (LogUtil.java:logMemory(59)) - flow node id: FC8A4ACCB2AE4060B98CA22C4A8ADCC4, mem on close (mb), free: 257, total: 281, max: 672
2016-05-18 02:54:42,197 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(226)) - deleting temp path /opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output/hadoop2-mr1/rifflecascadeplatform/testSimpleRiffleCascade/perpetualcascade/second/_temporary
2016-05-18 02:54:42,197 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [second] completed in: 00:00.195
2016-05-18 02:54:42,197 INFO cascade.Cascade (BaseCascade.java:logInfo(860)) - [fourth+second+first+third] completed flow: second
2016-05-18 02:54:42,198 INFO cascade.Cascade (BaseCascade.java:logInfo(860)) - [fourth+second+first+third] starting flow: third
2016-05-18 02:54:42,199 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [third] at least one sink is marked for delete
2016-05-18 02:54:42,199 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [third] sink oldest modified date: Wed Dec 31 23:59:59 UTC 1969
2016-05-18 02:54:42,202 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [third] starting
2016-05-18 02:54:42,203 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [third] source: Hfs["TextDelimited[['first', 'second', 'third', 'fourth']]"]["/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output/hadoop2-mr1/rifflecascadeplatform/testSimpleRiffleCascade/perpetualcascade/second"]
2016-05-18 02:54:42,203 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [third] sink: Hfs["TextDelimited[['mangled']]"]["/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output/hadoop2-mr1/rifflecascadeplatform/testSimpleRiffleCascade/perpetualcascade/third"]
2016-05-18 02:54:42,204 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [third] parallel execution of steps is enabled: false
2016-05-18 02:54:42,204 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [third] executing total steps: 1
2016-05-18 02:54:42,205 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [third] allocating management threads: 1
2016-05-18 02:54:42,206 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [third] starting step: (1/1) ...de/perpetualcascade/third
2016-05-18 02:54:42,279 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/tmp/cascading/staging/teamcity661516190/.staging/job_local661516190_0007/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2016-05-18 02:54:42,280 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/tmp/cascading/staging/teamcity661516190/.staging/job_local661516190_0007/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2016-05-18 02:54:42,324 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local661516190_0007/job_local661516190_0007.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2016-05-18 02:54:42,325 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local661516190_0007/job_local661516190_0007.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2016-05-18 02:54:42,326 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [third] submitted hadoop job: job_local661516190_0007
2016-05-18 02:54:42,327 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [third] tracking url: http://localhost:8080/
2016-05-18 02:54:42,332 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output/hadoop2-mr1/rifflecascadeplatform/testSimpleRiffleCascade/perpetualcascade/second/part-00000
2016-05-18 02:54:42,339 INFO hadoop.FlowMapper (FlowMapper.java:configure(75)) - cascading version: 3.1.0
2016-05-18 02:54:42,339 INFO hadoop.FlowMapper (FlowMapper.java:configure(76)) - child jvm opts: -Xmx200m
2016-05-18 02:54:42,347 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - flow node id: AA8922E73FA3470EBC7DCA194864E812, ordinal: 0
2016-05-18 02:54:42,348 INFO hadoop.FlowMapper (FlowMapper.java:configure(94)) - sourcing from: Hfs["TextDelimited[['first', 'second', 'third', 'fourth']]"]["/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output/hadoop2-mr1/rifflecascadeplatform/testSimpleRiffleCascade/perpetualcascade/second"]
2016-05-18 02:54:42,349 INFO hadoop.FlowMapper (FlowMapper.java:configure(97)) - sinking to: Hfs["TextDelimited[['mangled']]"]["/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output/hadoop2-mr1/rifflecascadeplatform/testSimpleRiffleCascade/perpetualcascade/third"]
2016-05-18 02:54:42,349 INFO hadoop.FlowMapper (LogUtil.java:logMemory(59)) - flow node id: AA8922E73FA3470EBC7DCA194864E812, mem on start (mb), free: 223, total: 281, max: 672
2016-05-18 02:54:42,353 INFO hadoop.FlowMapper (LogUtil.java:logMemory(59)) - flow node id: AA8922E73FA3470EBC7DCA194864E812, mem on close (mb), free: 222, total: 281, max: 672
2016-05-18 02:54:42,373 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(226)) - deleting temp path /opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output/hadoop2-mr1/rifflecascadeplatform/testSimpleRiffleCascade/perpetualcascade/third/_temporary
2016-05-18 02:54:42,373 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [third] completed in: 00:00.170
2016-05-18 02:54:42,374 INFO cascade.Cascade (BaseCascade.java:logInfo(860)) - [fourth+second+first+third] completed flow: third
2016-05-18 02:54:42,374 INFO cascade.Cascade (BaseCascade.java:logInfo(860)) - [fourth+second+first+third] starting flow: fourth
2016-05-18 02:54:42,374 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [fourth] at least one sink is marked for delete
2016-05-18 02:54:42,375 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [fourth] sink oldest modified date: Wed Dec 31 23:59:59 UTC 1969
2016-05-18 02:54:42,378 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [fourth] starting
2016-05-18 02:54:42,379 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [fourth] source: Hfs["TextDelimited[['mangled']]"]["/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output/hadoop2-mr1/rifflecascadeplatform/testSimpleRiffleCascade/perpetualcascade/third"]
2016-05-18 02:54:42,379 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [fourth] sink: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output/hadoop2-mr1/rifflecascadeplatform/testSimpleRiffleCascade/perpetualcascade/fourth"]
2016-05-18 02:54:42,380 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [fourth] parallel execution of steps is enabled: false
2016-05-18 02:54:42,380 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [fourth] executing total steps: 1
2016-05-18 02:54:42,380 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [fourth] allocating management threads: 1
2016-05-18 02:54:42,382 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [fourth] starting step: (1/1) ...e/perpetualcascade/fourth
2016-05-18 02:54:42,447 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/tmp/cascading/staging/teamcity1889217663/.staging/job_local1889217663_0008/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2016-05-18 02:54:42,448 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/tmp/cascading/staging/teamcity1889217663/.staging/job_local1889217663_0008/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2016-05-18 02:54:42,484 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1889217663_0008/job_local1889217663_0008.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2016-05-18 02:54:42,485 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1889217663_0008/job_local1889217663_0008.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2016-05-18 02:54:42,486 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [fourth] submitted hadoop job: job_local1889217663_0008
2016-05-18 02:54:42,487 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [fourth] tracking url: http://localhost:8080/
2016-05-18 02:54:42,492 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output/hadoop2-mr1/rifflecascadeplatform/testSimpleRiffleCascade/perpetualcascade/third/part-00000
2016-05-18 02:54:42,500 INFO hadoop.FlowMapper (FlowMapper.java:configure(75)) - cascading version: 3.1.0
2016-05-18 02:54:42,500 INFO hadoop.FlowMapper (FlowMapper.java:configure(76)) - child jvm opts: -Xmx200m
2016-05-18 02:54:42,507 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - flow node id: F0BA89C105DC4CEBB9702FB22E27337F, ordinal: 0
2016-05-18 02:54:42,508 INFO hadoop.FlowMapper (FlowMapper.java:configure(94)) - sourcing from: Hfs["TextDelimited[['mangled']]"]["/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output/hadoop2-mr1/rifflecascadeplatform/testSimpleRiffleCascade/perpetualcascade/third"]
2016-05-18 02:54:42,508 INFO hadoop.FlowMapper (FlowMapper.java:configure(97)) - sinking to: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output/hadoop2-mr1/rifflecascadeplatform/testSimpleRiffleCascade/perpetualcascade/fourth"]
2016-05-18 02:54:42,508 INFO hadoop.FlowMapper (LogUtil.java:logMemory(59)) - flow node id: F0BA89C105DC4CEBB9702FB22E27337F, mem on start (mb), free: 188, total: 281, max: 672
2016-05-18 02:54:42,510 INFO hadoop.FlowMapper (LogUtil.java:logMemory(59)) - flow node id: F0BA89C105DC4CEBB9702FB22E27337F, mem on close (mb), free: 188, total: 281, max: 672
2016-05-18 02:54:42,532 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(226)) - deleting temp path /opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output/hadoop2-mr1/rifflecascadeplatform/testSimpleRiffleCascade/perpetualcascade/fourth/_temporary
2016-05-18 02:54:42,533 INFO flow.Flow (BaseFlow.java:logInfo(1504)) - [fourth] completed in: 00:00.153
2016-05-18 02:54:42,533 INFO cascade.Cascade (BaseCascade.java:logInfo(860)) - [fourth+second+first+third] completed flow: fourth
2016-05-18 02:54:42,568 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output//hadoop2-mr1/rifflecascadeplatform/testSimpleRiffleCascade/perpetualcascade/second
2016-05-18 02:54:42,569 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output//hadoop2-mr1/rifflecascadeplatform/testSimpleRiffleCascade/perpetualcascade/third
2016-05-18 02:54:42,569 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output//hadoop2-mr1/rifflecascadeplatform/testSimpleRiffleCascade/perpetualcascade/fourth
2016-05-18 02:54:42,569 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output//hadoop2-mr1/rifflecascadeplatform/testSimpleRiffleCascade/perpetualcascade/first
2016-05-18 02:54:42,577 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output//hadoop2-mr1/rifflecascadeplatform/testProcessFlowWithCounters/counter/first
2016-05-18 02:54:42,581 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output//hadoop2-mr1/rifflecascadeplatform/testProcessFlowFlowListenerExceptionHandlingInComplete/completeException/first
2016-05-18 02:54:42,585 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/9c1cc778dcd1fc2f/apache-2.4.x/build/test/output//hadoop2-mr1/rifflecascadeplatform/testProcessFlowFlowListenerExceptionHandlingInStart/startException/first