2014-08-22 22:16:06,420 INFO platform.PlatformRunner (PlatformRunner.java:getPlatformClassesFromClasspath(187)) - found 1 test platforms from classpath
2014-08-22 22:16:06,491 INFO platform.PlatformRunner (PlatformRunner.java:addPlatform(237)) - installing platform: hadoop2-mr1
2014-08-22 22:16:06,491 INFO platform.PlatformRunner (PlatformRunner.java:addPlatform(238)) - running test: cascading.RegressionPipesPlatformTest
2014-08-22 22:16:06,534 INFO hadoop2.Hadoop2MR1Platform (Hadoop2MR1Platform.java:setUp(106)) - not using cluster
2014-08-22 22:16:07,178 WARN util.NativeCodeLoader (NativeCodeLoader.java:<clinit>(62)) - Unable to load native-hadoop library for your platform... using builtin-java classes where applicable
2014-08-22 22:16:07,488 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 22:16:07,490 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.5.6/31997f144a2e73eebf04d45ed31402ee30118b2/cascading-hadoop2-mr1-2.5.6.jar
2014-08-22 22:16:07,503 INFO property.AppProps (AppProps.java:getAppID(162)) - using app.id: B6C72139649B4793BB69E8CA986BE868
2014-08-22 22:16:07,581 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 22:16:07,622 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 22:16:07,626 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 22:16:07,756 INFO util.Version (Version.java:printBanner(78)) - Concurrent, Inc - Cascading 2.5.6
2014-08-22 22:16:07,759 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting
2014-08-22 22:16:07,760 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] source: Hfs["TextDelimited[['num', 'char']]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lhs.txt"]
2014-08-22 22:16:07,760 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] sink: Hfs["TextDelimited[['num', 'char']]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/regression/complexlogicor"]
2014-08-22 22:16:07,761 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] parallel execution is enabled: false
2014-08-22 22:16:07,763 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting jobs: 1
2014-08-22 22:16:07,763 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] allocating threads: 1
2014-08-22 22:16:07,765 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...regression/complexlogicor
2014-08-22 22:16:07,790 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - session.id is deprecated. Instead, use dfs.metrics.session-id
2014-08-22 22:16:07,791 INFO jvm.JvmMetrics (JvmMetrics.java:init(76)) - Initializing JVM Metrics with processName=JobTracker, sessionId=
2014-08-22 22:16:07,816 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 22:16:08,176 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 22:16:08,218 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 22:16:08,380 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local50124112_0001
2014-08-22 22:16:08,435 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity50124112/.staging/job_local50124112_0001/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 22:16:08,447 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity50124112/.staging/job_local50124112_0001/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 22:16:08,638 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local50124112_0001/job_local50124112_0001.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 22:16:08,646 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local50124112_0001/job_local50124112_0001.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 22:16:08,652 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 22:16:08,654 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 22:16:08,656 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local50124112_0001
2014-08-22 22:16:08,657 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2014-08-22 22:16:08,657 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 22:16:08,715 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 22:16:08,720 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local50124112_0001_m_000000_0
2014-08-22 22:16:08,763 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 22:16:08,774 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lhs.txt
2014-08-22 22:16:08,775 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@19852a81
2014-08-22 22:16:08,785 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 0
2014-08-22 22:16:08,803 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 22:16:08,803 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 22:16:08,852 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.task.partition is deprecated. Instead, use mapreduce.task.partition
2014-08-22 22:16:08,860 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextDelimited[['num', 'char']]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lhs.txt"]
2014-08-22 22:16:08,861 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: Hfs["TextDelimited[['num', 'char']]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/regression/complexlogicor"]
2014-08-22 22:16:08,884 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 22:16:08,884 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local50124112_0001_m_000000_0 is done. And is in the process of committing
2014-08-22 22:16:08,894 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 22:16:08,895 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local50124112_0001_m_000000_0 is allowed to commit now
2014-08-22 22:16:08,896 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local50124112_0001_m_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/regression/complexlogicor/_temporary/0/task_local50124112_0001_m_000000
2014-08-22 22:16:08,898 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lhs.txt:0+52
2014-08-22 22:16:08,898 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local50124112_0001_m_000000_0' done.
2014-08-22 22:16:08,898 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local50124112_0001_m_000000_0
2014-08-22 22:16:08,899 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 22:16:08,945 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/regression/complexlogicor/_temporary
2014-08-22 22:16:08,990 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 22:16:08,996 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output//hadoop2-mr1/regressionpipesplatform/regression/complexlogicor
2014-08-22 22:16:09,032 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 22:16:09,033 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.5.6/31997f144a2e73eebf04d45ed31402ee30118b2/cascading-hadoop2-mr1-2.5.6.jar
2014-08-22 22:16:09,048 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 22:16:09,055 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 22:16:09,056 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 22:16:09,068 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [split] starting
2014-08-22 22:16:09,068 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [split] source: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower.txt"]
2014-08-22 22:16:09,069 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [split] sink: Hfs["TextDelimited[['num', 'char']]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/intermediate"]
2014-08-22 22:16:09,069 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [split] parallel execution is enabled: false
2014-08-22 22:16:09,069 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [split] starting jobs: 1
2014-08-22 22:16:09,069 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [split] allocating threads: 1
2014-08-22 22:16:09,070 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [split] starting step: (1/1) ...ipesplatform/intermediate
2014-08-22 22:16:09,072 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 22:16:09,074 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 22:16:09,106 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 22:16:09,131 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 22:16:09,167 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1559120754_0002
2014-08-22 22:16:09,189 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1559120754/.staging/job_local1559120754_0002/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 22:16:09,190 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1559120754/.staging/job_local1559120754_0002/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 22:16:09,270 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1559120754_0002/job_local1559120754_0002.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 22:16:09,273 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1559120754_0002/job_local1559120754_0002.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 22:16:09,274 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 22:16:09,274 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [split] submitted hadoop job: job_local1559120754_0002
2014-08-22 22:16:09,274 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 22:16:09,274 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [split] tracking url: http://localhost:8080/
2014-08-22 22:16:09,274 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 22:16:09,278 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 22:16:09,279 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1559120754_0002_m_000000_0
2014-08-22 22:16:09,281 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 22:16:09,283 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower.txt
2014-08-22 22:16:09,283 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@111edceb
2014-08-22 22:16:09,285 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 0
2014-08-22 22:16:09,296 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 22:16:09,296 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 22:16:09,309 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower.txt"]
2014-08-22 22:16:09,309 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: Hfs["TextDelimited[['num', 'char']]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/intermediate"]
2014-08-22 22:16:09,313 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 22:16:09,314 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1559120754_0002_m_000000_0 is done. And is in the process of committing
2014-08-22 22:16:09,315 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 22:16:09,316 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1559120754_0002_m_000000_0 is allowed to commit now
2014-08-22 22:16:09,317 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1559120754_0002_m_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/intermediate/_temporary/0/task_local1559120754_0002_m_000000
2014-08-22 22:16:09,318 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower.txt:0+19
2014-08-22 22:16:09,318 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1559120754_0002_m_000000_0' done.
2014-08-22 22:16:09,319 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1559120754_0002_m_000000_0
2014-08-22 22:16:09,319 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 22:16:09,340 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/intermediate/_temporary
2014-08-22 22:16:09,381 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 22:16:09,382 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.5.6/31997f144a2e73eebf04d45ed31402ee30118b2/cascading-hadoop2-mr1-2.5.6.jar
2014-08-22 22:16:09,405 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 22:16:09,411 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 22:16:09,412 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 22:16:09,437 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [lhs*rhs] starting
2014-08-22 22:16:09,438 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [lhs*rhs] source: Hfs["TextDelimited[['num', 'char']]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/intermediate"]
2014-08-22 22:16:09,439 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [lhs*rhs] sink: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/cogroupsplit"]
2014-08-22 22:16:09,439 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [lhs*rhs] parallel execution is enabled: false
2014-08-22 22:16:09,439 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [lhs*rhs] starting jobs: 1
2014-08-22 22:16:09,440 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [lhs*rhs] allocating threads: 1
2014-08-22 22:16:09,441 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [lhs*rhs] starting step: (1/1) ...ipesplatform/cogroupsplit
2014-08-22 22:16:09,442 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 22:16:09,444 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 22:16:09,492 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 22:16:09,516 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 22:16:09,564 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1229854290_0003
2014-08-22 22:16:09,610 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1229854290/.staging/job_local1229854290_0003/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 22:16:09,614 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1229854290/.staging/job_local1229854290_0003/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 22:16:09,738 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1229854290_0003/job_local1229854290_0003.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 22:16:09,742 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1229854290_0003/job_local1229854290_0003.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 22:16:09,743 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 22:16:09,744 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 22:16:09,745 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 22:16:09,744 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [lhs*rhs] submitted hadoop job: job_local1229854290_0003
2014-08-22 22:16:09,746 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [lhs*rhs] tracking url: http://localhost:8080/
2014-08-22 22:16:09,749 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 22:16:09,749 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1229854290_0003_m_000000_0
2014-08-22 22:16:09,752 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 22:16:09,754 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/intermediate/part-00000
2014-08-22 22:16:09,754 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@44091520
2014-08-22 22:16:09,756 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 22:16:09,763 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 22:16:09,910 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 22:16:09,911 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 22:16:09,911 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 22:16:09,911 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 22:16:09,911 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 22:16:09,935 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 22:16:09,935 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 22:16:09,958 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextDelimited[['num', 'char']]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/intermediate"]
2014-08-22 22:16:09,958 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: CoGroup(lhs*rhs)[by: lhs:[{1}:'num'] rhs:[{1}:'num2']]
2014-08-22 22:16:09,964 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 22:16:09,965 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2014-08-22 22:16:09,965 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2014-08-22 22:16:09,965 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 140; bufvoid = 104857600
2014-08-22 22:16:09,965 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214360(104857440); length = 37/6553600
2014-08-22 22:16:09,981 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2014-08-22 22:16:09,985 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1229854290_0003_m_000000_0 is done. And is in the process of committing
2014-08-22 22:16:09,988 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/intermediate/part-00000:0+20
2014-08-22 22:16:09,988 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1229854290_0003_m_000000_0' done.
2014-08-22 22:16:09,988 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1229854290_0003_m_000000_0
2014-08-22 22:16:09,988 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 22:16:09,991 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 22:16:09,991 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1229854290_0003_r_000000_0
2014-08-22 22:16:09,999 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 22:16:10,002 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@5d1d20d3
2014-08-22 22:16:10,018 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 22:16:10,025 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1229854290_0003_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 22:16:10,058 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#1 about to shuffle output of map attempt_local1229854290_0003_m_000000_0 decomp: 162 len: 166 to MEMORY
2014-08-22 22:16:10,061 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 162 bytes from map-output for attempt_local1229854290_0003_m_000000_0
2014-08-22 22:16:10,102 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 162, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->162
2014-08-22 22:16:10,104 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 22:16:10,106 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 22:16:10,106 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 22:16:10,116 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 22:16:10,117 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 152 bytes
2014-08-22 22:16:10,120 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 162 bytes to disk to satisfy reduce memory limit
2014-08-22 22:16:10,121 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 166 bytes from disk
2014-08-22 22:16:10,122 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 22:16:10,122 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 22:16:10,123 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 152 bytes
2014-08-22 22:16:10,124 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 22:16:10,126 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 22:16:10,126 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 22:16:10,142 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: CoGroup(lhs*rhs)[by: lhs:[{1}:'num'] rhs:[{1}:'num2']]
2014-08-22 22:16:10,143 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/cogroupsplit"]
2014-08-22 22:16:10,164 INFO collect.SpillableTupleList (SpillableTupleList.java:getCodecClass(105)) - attempting to load codec: org.apache.hadoop.io.compress.GzipCodec
2014-08-22 22:16:10,164 INFO collect.SpillableTupleList (SpillableTupleList.java:getCodecClass(110)) - found codec: org.apache.hadoop.io.compress.GzipCodec
2014-08-22 22:16:10,178 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1229854290_0003_r_000000_0 is done. And is in the process of committing
2014-08-22 22:16:10,180 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 22:16:10,180 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1229854290_0003_r_000000_0 is allowed to commit now
2014-08-22 22:16:10,182 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1229854290_0003_r_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/cogroupsplit/_temporary/0/task_local1229854290_0003_r_000000
2014-08-22 22:16:10,183 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 22:16:10,183 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1229854290_0003_r_000000_0' done.
2014-08-22 22:16:10,184 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1229854290_0003_r_000000_0
2014-08-22 22:16:10,184 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 22:16:10,218 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/cogroupsplit/_temporary
2014-08-22 22:16:10,258 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 22:16:10,304 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 22:16:10,306 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output//hadoop2-mr1/regressionpipesplatform/intermediate
2014-08-22 22:16:10,307 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output//hadoop2-mr1/regressionpipesplatform/cogroupsplit
2014-08-22 22:16:10,343 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 22:16:10,344 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.5.6/31997f144a2e73eebf04d45ed31402ee30118b2/cascading-hadoop2-mr1-2.5.6.jar
2014-08-22 22:16:10,362 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 22:16:10,367 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 22:16:10,368 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 22:16:10,382 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting
2014-08-22 22:16:10,382 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower+upper.txt"]
2014-08-22 22:16:10,383 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] sink: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/none-unknown"]
2014-08-22 22:16:10,383 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] parallel execution is enabled: false
2014-08-22 22:16:10,383 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting jobs: 1
2014-08-22 22:16:10,383 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] allocating threads: 1
2014-08-22 22:16:10,384 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...ipesplatform/none-unknown
2014-08-22 22:16:10,388 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 22:16:10,390 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 22:16:10,428 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 22:16:10,454 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 22:16:10,481 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1215516610_0004
2014-08-22 22:16:10,528 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1215516610/.staging/job_local1215516610_0004/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 22:16:10,532 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1215516610/.staging/job_local1215516610_0004/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 22:16:10,593 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1215516610_0004/job_local1215516610_0004.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 22:16:10,594 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1215516610_0004/job_local1215516610_0004.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 22:16:10,595 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 22:16:10,596 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local1215516610_0004
2014-08-22 22:16:10,596 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 22:16:10,596 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 22:16:10,596 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2014-08-22 22:16:10,600 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 22:16:10,601 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1215516610_0004_m_000000_0
2014-08-22 22:16:10,604 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 22:16:10,606 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower+upper.txt
2014-08-22 22:16:10,606 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@1adbbe8b
2014-08-22 22:16:10,609 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 22:16:10,609 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 22:16:10,757 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 22:16:10,758 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 22:16:10,758 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 22:16:10,758 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 22:16:10,758 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 22:16:10,762 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 22:16:10,763 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 22:16:10,776 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower+upper.txt"]
2014-08-22 22:16:10,776 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{?}:NONE]]
2014-08-22 22:16:10,780 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 22:16:10,780 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2014-08-22 22:16:10,780 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2014-08-22 22:16:10,781 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 135; bufvoid = 104857600
2014-08-22 22:16:10,781 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214380(104857520); length = 17/6553600
2014-08-22 22:16:10,785 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2014-08-22 22:16:10,788 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1215516610_0004_m_000000_0 is done. And is in the process of committing
2014-08-22 22:16:10,790 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower+upper.txt:0+30
2014-08-22 22:16:10,791 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1215516610_0004_m_000000_0' done.
2014-08-22 22:16:10,791 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1215516610_0004_m_000000_0
2014-08-22 22:16:10,791 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 22:16:10,792 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 22:16:10,792 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1215516610_0004_r_000000_0
2014-08-22 22:16:10,795 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 22:16:10,795 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@1ad997f9
2014-08-22 22:16:10,796 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 22:16:10,797 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1215516610_0004_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 22:16:10,800 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#2 about to shuffle output of map attempt_local1215516610_0004_m_000000_0 decomp: 147 len: 151 to MEMORY
2014-08-22 22:16:10,800 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 147 bytes from map-output for attempt_local1215516610_0004_m_000000_0
2014-08-22 22:16:10,801 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 147, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->147
2014-08-22 22:16:10,801 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 22:16:10,803 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 22:16:10,803 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 22:16:10,806 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 22:16:10,806 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 137 bytes
2014-08-22 22:16:10,808 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 147 bytes to disk to satisfy reduce memory limit
2014-08-22 22:16:10,808 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 151 bytes from disk
2014-08-22 22:16:10,809 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 22:16:10,809 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 22:16:10,809 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 137 bytes
2014-08-22 22:16:10,810 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 22:16:10,811 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 22:16:10,811 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 22:16:10,820 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{?}:NONE]]
2014-08-22 22:16:10,820 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/none-unknown"]
2014-08-22 22:16:10,834 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1215516610_0004_r_000000_0 is done. And is in the process of committing
2014-08-22 22:16:10,836 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 22:16:10,836 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1215516610_0004_r_000000_0 is allowed to commit now
2014-08-22 22:16:10,837 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1215516610_0004_r_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/none-unknown/_temporary/0/task_local1215516610_0004_r_000000
2014-08-22 22:16:10,838 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 22:16:10,839 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1215516610_0004_r_000000_0' done.
2014-08-22 22:16:10,839 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1215516610_0004_r_000000_0
2014-08-22 22:16:10,839 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 22:16:10,864 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/none-unknown/_temporary
2014-08-22 22:16:10,898 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 22:16:10,901 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output//hadoop2-mr1/regressionpipesplatform/none-unknown
2014-08-22 22:16:10,924 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 22:16:10,925 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.5.6/31997f144a2e73eebf04d45ed31402ee30118b2/cascading-hadoop2-mr1-2.5.6.jar
2014-08-22 22:16:10,933 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 22:16:10,939 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 22:16:10,940 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 22:16:10,955 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting
2014-08-22 22:16:10,955 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2014-08-22 22:16:10,955 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] sink: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/oomepre"]
2014-08-22 22:16:10,956 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] parallel execution is enabled: false
2014-08-22 22:16:10,956 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting jobs: 1
2014-08-22 22:16:10,956 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] allocating threads: 1
2014-08-22 22:16:10,957 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...sionpipesplatform/oomepre
2014-08-22 22:16:10,958 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 22:16:10,959 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 22:16:10,990 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 22:16:11,011 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 22:16:11,045 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local778671909_0005
2014-08-22 22:16:11,066 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity778671909/.staging/job_local778671909_0005/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 22:16:11,067 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity778671909/.staging/job_local778671909_0005/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 22:16:11,129 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local778671909_0005/job_local778671909_0005.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 22:16:11,131 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local778671909_0005/job_local778671909_0005.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 22:16:11,131 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 22:16:11,133 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local778671909_0005
2014-08-22 22:16:11,133 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 22:16:11,133 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2014-08-22 22:16:11,134 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 22:16:11,137 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 22:16:11,138 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local778671909_0005_m_000000_0
2014-08-22 22:16:11,140 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 22:16:11,142 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/apache.10.txt
2014-08-22 22:16:11,142 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@382b7bd9
2014-08-22 22:16:11,144 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 0
2014-08-22 22:16:11,153 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 22:16:11,153 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 22:16:11,161 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2014-08-22 22:16:11,162 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/oomepre"]
2014-08-22 22:16:11,164 ERROR stream.TrapHandler (TrapHandler.java:handleReThrowableException(103)) - caught OutOfMemoryException, will not trap, rethrowing
java.lang.OutOfMemoryError: fake error
at cascading.RegressionPipesPlatformTest$1.throwIntentionalException(RegressionPipesPlatformTest.java:593)
at cascading.TestFunction.operate(TestFunction.java:74)
at cascading.flow.stream.FunctionEachStage.receive(FunctionEachStage.java:99)
at cascading.flow.stream.FunctionEachStage.receive(FunctionEachStage.java:39)
at cascading.flow.stream.SourceStage.map(SourceStage.java:102)
at cascading.flow.stream.SourceStage.run(SourceStage.java:58)
at cascading.flow.hadoop.FlowMapper.run(FlowMapper.java:130)
at org.apache.hadoop.mapred.MapTask.runOldMapper(MapTask.java:430)
at org.apache.hadoop.mapred.MapTask.run(MapTask.java:342)
at org.apache.hadoop.mapred.LocalJobRunner$Job$MapTaskRunnable.run(LocalJobRunner.java:243)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:439)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
at java.lang.Thread.run(Thread.java:662)
2014-08-22 22:16:11,167 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 22:16:11,168 WARN mapred.LocalJobRunner (LocalJobRunner.java:run(560)) - job_local778671909_0005
java.lang.Exception: java.lang.OutOfMemoryError: fake error
at org.apache.hadoop.mapred.LocalJobRunner$Job.runTasks(LocalJobRunner.java:462)
at org.apache.hadoop.mapred.LocalJobRunner$Job.run(LocalJobRunner.java:522)
Caused by: java.lang.OutOfMemoryError: fake error
at cascading.RegressionPipesPlatformTest$1.throwIntentionalException(RegressionPipesPlatformTest.java:593)
at cascading.TestFunction.operate(TestFunction.java:74)
at cascading.flow.stream.FunctionEachStage.receive(FunctionEachStage.java:99)
at cascading.flow.stream.FunctionEachStage.receive(FunctionEachStage.java:39)
at cascading.flow.stream.SourceStage.map(SourceStage.java:102)
at cascading.flow.stream.SourceStage.run(SourceStage.java:58)
at cascading.flow.hadoop.FlowMapper.run(FlowMapper.java:130)
at org.apache.hadoop.mapred.MapTask.runOldMapper(MapTask.java:430)
at org.apache.hadoop.mapred.MapTask.run(MapTask.java:342)
at org.apache.hadoop.mapred.LocalJobRunner$Job$MapTaskRunnable.run(LocalJobRunner.java:243)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:439)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
at java.lang.Thread.run(Thread.java:662)
2014-08-22 22:16:11,175 WARN flow.FlowStep (BaseFlowStep.java:logWarn(839)) - [test] hadoop job job_local778671909_0005 state at FAILED
2014-08-22 22:16:11,177 WARN flow.FlowStep (BaseFlowStep.java:logWarn(839)) - [test] failure info: NA
2014-08-22 22:16:11,178 WARN flow.FlowStep (BaseFlowStep.java:logWarn(839)) - [test] task completion events identify failed tasks
2014-08-22 22:16:11,178 WARN flow.FlowStep (BaseFlowStep.java:logWarn(839)) - [test] task completion events count: 0
2014-08-22 22:16:11,179 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] stopping all jobs
2014-08-22 22:16:11,180 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] stopping: (1/1) ...sionpipesplatform/oomepre
2014-08-22 22:16:11,181 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] stopped all jobs
2014-08-22 22:16:11,181 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/oomepre/_temporary
exception = cascading.flow.FlowException: local step failed
2014-08-22 22:16:11,183 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output//hadoop2-mr1/regressionpipesplatform/oomepre
2014-08-22 22:16:11,213 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 22:16:11,214 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.5.6/31997f144a2e73eebf04d45ed31402ee30118b2/cascading-hadoop2-mr1-2.5.6.jar
2014-08-22 22:16:11,222 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 22:16:11,226 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 22:16:11,227 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 22:16:11,232 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting
2014-08-22 22:16:11,233 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower+upper.txt"]
2014-08-22 22:16:11,233 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] sink: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/copy"]
2014-08-22 22:16:11,234 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] parallel execution is enabled: false
2014-08-22 22:16:11,234 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting jobs: 1
2014-08-22 22:16:11,234 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] allocating threads: 1
2014-08-22 22:16:11,235 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...ressionpipesplatform/copy
2014-08-22 22:16:11,237 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 22:16:11,238 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 22:16:11,267 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 22:16:11,288 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 22:16:11,305 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1692320349_0006
2014-08-22 22:16:11,324 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1692320349/.staging/job_local1692320349_0006/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 22:16:11,325 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1692320349/.staging/job_local1692320349_0006/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 22:16:11,378 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1692320349_0006/job_local1692320349_0006.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 22:16:11,380 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1692320349_0006/job_local1692320349_0006.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 22:16:11,380 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 22:16:11,381 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local1692320349_0006
2014-08-22 22:16:11,381 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2014-08-22 22:16:11,381 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 22:16:11,381 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 22:16:11,385 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 22:16:11,386 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1692320349_0006_m_000000_0
2014-08-22 22:16:11,388 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 22:16:11,390 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower+upper.txt
2014-08-22 22:16:11,390 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@1acfb11f
2014-08-22 22:16:11,392 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 0
2014-08-22 22:16:11,400 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 22:16:11,401 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 22:16:11,406 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower+upper.txt"]
2014-08-22 22:16:11,407 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/copy"]
2014-08-22 22:16:11,410 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 22:16:11,410 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1692320349_0006_m_000000_0 is done. And is in the process of committing
2014-08-22 22:16:11,412 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 22:16:11,412 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1692320349_0006_m_000000_0 is allowed to commit now
2014-08-22 22:16:11,413 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1692320349_0006_m_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/copy/_temporary/0/task_local1692320349_0006_m_000000
2014-08-22 22:16:11,415 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower+upper.txt:0+30
2014-08-22 22:16:11,415 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1692320349_0006_m_000000_0' done.
2014-08-22 22:16:11,415 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1692320349_0006_m_000000_0
2014-08-22 22:16:11,415 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 22:16:11,437 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/copy/_temporary
2014-08-22 22:16:11,471 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 22:16:11,473 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output//hadoop2-mr1/regressionpipesplatform/copy
2014-08-22 22:16:11,498 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 22:16:11,498 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.5.6/31997f144a2e73eebf04d45ed31402ee30118b2/cascading-hadoop2-mr1-2.5.6.jar
2014-08-22 22:16:11,509 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 22:16:11,513 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 22:16:11,513 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 22:16:11,524 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting
2014-08-22 22:16:11,524 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] source: Hfs["TextDelimited[[UNKNOWN]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower+upper.txt"]
2014-08-22 22:16:11,525 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] sink: Hfs["TextDelimited[[UNKNOWN]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/unknown-replace"]
2014-08-22 22:16:11,525 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] parallel execution is enabled: false
2014-08-22 22:16:11,525 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting jobs: 1
2014-08-22 22:16:11,525 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] allocating threads: 1
2014-08-22 22:16:11,526 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...splatform/unknown-replace
2014-08-22 22:16:11,526 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 22:16:11,528 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 22:16:11,557 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 22:16:11,577 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 22:16:11,600 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1517546255_0007
2014-08-22 22:16:11,624 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1517546255/.staging/job_local1517546255_0007/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 22:16:11,625 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1517546255/.staging/job_local1517546255_0007/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 22:16:11,694 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1517546255_0007/job_local1517546255_0007.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 22:16:11,695 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1517546255_0007/job_local1517546255_0007.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 22:16:11,696 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 22:16:11,697 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local1517546255_0007
2014-08-22 22:16:11,697 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 22:16:11,697 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2014-08-22 22:16:11,697 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 22:16:11,701 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 22:16:11,701 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1517546255_0007_m_000000_0
2014-08-22 22:16:11,704 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 22:16:11,707 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower+upper.txt
2014-08-22 22:16:11,708 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@1dacecf3
2014-08-22 22:16:11,709 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 0
2014-08-22 22:16:11,719 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 22:16:11,719 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 22:16:11,730 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextDelimited[[UNKNOWN]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower+upper.txt"]
2014-08-22 22:16:11,730 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: Hfs["TextDelimited[[UNKNOWN]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/unknown-replace"]
2014-08-22 22:16:11,734 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 22:16:11,734 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1517546255_0007_m_000000_0 is done. And is in the process of committing
2014-08-22 22:16:11,738 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 22:16:11,738 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1517546255_0007_m_000000_0 is allowed to commit now
2014-08-22 22:16:11,740 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1517546255_0007_m_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/unknown-replace/_temporary/0/task_local1517546255_0007_m_000000
2014-08-22 22:16:11,742 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower+upper.txt:0+30
2014-08-22 22:16:11,742 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1517546255_0007_m_000000_0' done.
2014-08-22 22:16:11,743 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1517546255_0007_m_000000_0
2014-08-22 22:16:11,744 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 22:16:11,764 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/unknown-replace/_temporary
2014-08-22 22:16:11,801 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 22:16:11,839 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 22:16:11,842 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output//hadoop2-mr1/regressionpipesplatform/unknown-replace
2014-08-22 22:16:11,871 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 22:16:11,871 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.5.6/31997f144a2e73eebf04d45ed31402ee30118b2/cascading-hadoop2-mr1-2.5.6.jar
2014-08-22 22:16:11,885 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 22:16:11,889 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 22:16:11,890 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 22:16:11,900 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting
2014-08-22 22:16:11,900 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] source: Hfs["TextDelimited[['num', 'char']]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lhs.txt"]
2014-08-22 22:16:11,901 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] sink: Hfs["TextDelimited[['num', 'char']]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/regression/complexlogicand"]
2014-08-22 22:16:11,901 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] parallel execution is enabled: false
2014-08-22 22:16:11,901 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting jobs: 1
2014-08-22 22:16:11,901 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] allocating threads: 1
2014-08-22 22:16:11,902 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...egression/complexlogicand
2014-08-22 22:16:11,903 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 22:16:11,904 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 22:16:11,940 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 22:16:11,962 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 22:16:11,983 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local880930632_0008
2014-08-22 22:16:12,009 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity880930632/.staging/job_local880930632_0008/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 22:16:12,011 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity880930632/.staging/job_local880930632_0008/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 22:16:12,068 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local880930632_0008/job_local880930632_0008.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 22:16:12,070 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local880930632_0008/job_local880930632_0008.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 22:16:12,071 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 22:16:12,072 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local880930632_0008
2014-08-22 22:16:12,073 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2014-08-22 22:16:12,072 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 22:16:12,075 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 22:16:12,079 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 22:16:12,079 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local880930632_0008_m_000000_0
2014-08-22 22:16:12,082 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 22:16:12,086 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lhs.txt
2014-08-22 22:16:12,087 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@67d479cf
2014-08-22 22:16:12,090 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 0
2014-08-22 22:16:12,100 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 22:16:12,101 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 22:16:12,113 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextDelimited[['num', 'char']]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lhs.txt"]
2014-08-22 22:16:12,113 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: Hfs["TextDelimited[['num', 'char']]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/regression/complexlogicand"]
2014-08-22 22:16:12,118 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 22:16:12,119 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local880930632_0008_m_000000_0 is done. And is in the process of committing
2014-08-22 22:16:12,121 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 22:16:12,122 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local880930632_0008_m_000000_0 is allowed to commit now
2014-08-22 22:16:12,123 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local880930632_0008_m_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/regression/complexlogicand/_temporary/0/task_local880930632_0008_m_000000
2014-08-22 22:16:12,125 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lhs.txt:0+52
2014-08-22 22:16:12,125 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local880930632_0008_m_000000_0' done.
2014-08-22 22:16:12,126 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local880930632_0008_m_000000_0
2014-08-22 22:16:12,127 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 22:16:12,150 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/regression/complexlogicand/_temporary
2014-08-22 22:16:12,182 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 22:16:12,185 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output//hadoop2-mr1/regressionpipesplatform/regression/complexlogicand
2014-08-22 22:16:12,210 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 22:16:12,211 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.5.6/31997f144a2e73eebf04d45ed31402ee30118b2/cascading-hadoop2-mr1-2.5.6.jar
2014-08-22 22:16:12,222 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 22:16:12,226 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 22:16:12,227 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 22:16:12,236 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting
2014-08-22 22:16:12,237 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] source: Hfs["TextDelimited[['num', 'char']]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lhs.txt"]
2014-08-22 22:16:12,238 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] sink: Hfs["TextDelimited[['num', 'char']]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/regression/complexlogicxor"]
2014-08-22 22:16:12,238 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] parallel execution is enabled: false
2014-08-22 22:16:12,238 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting jobs: 1
2014-08-22 22:16:12,239 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] allocating threads: 1
2014-08-22 22:16:12,240 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...egression/complexlogicxor
2014-08-22 22:16:12,240 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 22:16:12,241 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 22:16:12,271 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 22:16:12,292 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 22:16:12,311 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1011130970_0009
2014-08-22 22:16:12,335 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1011130970/.staging/job_local1011130970_0009/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 22:16:12,337 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1011130970/.staging/job_local1011130970_0009/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 22:16:12,395 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1011130970_0009/job_local1011130970_0009.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 22:16:12,397 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1011130970_0009/job_local1011130970_0009.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 22:16:12,398 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 22:16:12,398 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 22:16:12,399 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 22:16:12,399 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local1011130970_0009
2014-08-22 22:16:12,400 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2014-08-22 22:16:12,402 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 22:16:12,402 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1011130970_0009_m_000000_0
2014-08-22 22:16:12,404 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 22:16:12,406 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lhs.txt
2014-08-22 22:16:12,406 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@6f548414
2014-08-22 22:16:12,408 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 0
2014-08-22 22:16:12,417 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 22:16:12,417 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 22:16:12,427 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextDelimited[['num', 'char']]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lhs.txt"]
2014-08-22 22:16:12,427 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: Hfs["TextDelimited[['num', 'char']]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/regression/complexlogicxor"]
2014-08-22 22:16:12,432 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 22:16:12,432 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1011130970_0009_m_000000_0 is done. And is in the process of committing
2014-08-22 22:16:12,434 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 22:16:12,434 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1011130970_0009_m_000000_0 is allowed to commit now
2014-08-22 22:16:12,435 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1011130970_0009_m_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/regression/complexlogicxor/_temporary/0/task_local1011130970_0009_m_000000
2014-08-22 22:16:12,439 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lhs.txt:0+52
2014-08-22 22:16:12,440 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1011130970_0009_m_000000_0' done.
2014-08-22 22:16:12,440 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1011130970_0009_m_000000_0
2014-08-22 22:16:12,441 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 22:16:12,457 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/regression/complexlogicxor/_temporary
2014-08-22 22:16:12,490 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 22:16:12,492 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output//hadoop2-mr1/regressionpipesplatform/regression/complexlogicxor
2014-08-22 22:16:12,514 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 22:16:12,515 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.5.6/31997f144a2e73eebf04d45ed31402ee30118b2/cascading-hadoop2-mr1-2.5.6.jar
2014-08-22 22:16:12,532 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 22:16:12,537 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 22:16:12,537 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 22:16:12,548 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [lower*upper] starting
2014-08-22 22:16:12,548 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [lower*upper] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/upper.txt"]
2014-08-22 22:16:12,549 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [lower*upper] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower.txt"]
2014-08-22 22:16:12,549 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [lower*upper] sink: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/oomepost"]
2014-08-22 22:16:12,549 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [lower*upper] parallel execution is enabled: false
2014-08-22 22:16:12,549 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [lower*upper] starting jobs: 1
2014-08-22 22:16:12,549 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [lower*upper] allocating threads: 1
2014-08-22 22:16:12,550 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [lower*upper] starting step: (1/1) ...ionpipesplatform/oomepost
2014-08-22 22:16:12,551 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 22:16:12,553 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 22:16:12,581 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 22:16:12,583 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 22:16:12,605 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:2
2014-08-22 22:16:12,626 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1706291977_0010
2014-08-22 22:16:12,645 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1706291977/.staging/job_local1706291977_0010/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 22:16:12,646 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1706291977/.staging/job_local1706291977_0010/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 22:16:12,713 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1706291977_0010/job_local1706291977_0010.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 22:16:12,715 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1706291977_0010/job_local1706291977_0010.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 22:16:12,716 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 22:16:12,717 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [lower*upper] submitted hadoop job: job_local1706291977_0010
2014-08-22 22:16:12,717 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [lower*upper] tracking url: http://localhost:8080/
2014-08-22 22:16:12,717 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 22:16:12,717 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 22:16:12,721 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 22:16:12,721 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1706291977_0010_m_000000_0
2014-08-22 22:16:12,723 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 22:16:12,725 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower.txt
2014-08-22 22:16:12,725 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@62b92dc2
2014-08-22 22:16:12,726 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 22:16:12,727 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 22:16:12,751 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 22:16:12,751 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 22:16:12,751 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 22:16:12,752 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 22:16:12,752 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 22:16:12,753 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 22:16:12,753 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 22:16:12,764 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower.txt"]
2014-08-22 22:16:12,765 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: CoGroup(lower*upper)[by: lower:[{1}:'num'] upper:[{1}:'num']]
2014-08-22 22:16:12,768 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 22:16:12,768 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2014-08-22 22:16:12,768 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2014-08-22 22:16:12,768 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 85; bufvoid = 104857600
2014-08-22 22:16:12,768 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214380(104857520); length = 17/6553600
2014-08-22 22:16:12,772 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2014-08-22 22:16:12,775 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1706291977_0010_m_000000_0 is done. And is in the process of committing
2014-08-22 22:16:12,778 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower.txt:0+19
2014-08-22 22:16:12,778 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1706291977_0010_m_000000_0' done.
2014-08-22 22:16:12,778 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1706291977_0010_m_000000_0
2014-08-22 22:16:12,778 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1706291977_0010_m_000001_0
2014-08-22 22:16:12,780 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 22:16:12,782 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/upper.txt
2014-08-22 22:16:12,783 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@da4a1c9
2014-08-22 22:16:12,784 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 22:16:12,784 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 22:16:12,926 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 22:16:12,927 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 22:16:12,927 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 22:16:12,927 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 22:16:12,927 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 22:16:12,928 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 22:16:12,929 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 22:16:12,940 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/upper.txt"]
2014-08-22 22:16:12,941 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: CoGroup(lower*upper)[by: lower:[{1}:'num'] upper:[{1}:'num']]
2014-08-22 22:16:12,944 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 22:16:12,944 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2014-08-22 22:16:12,944 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2014-08-22 22:16:12,944 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 85; bufvoid = 104857600
2014-08-22 22:16:12,944 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214380(104857520); length = 17/6553600
2014-08-22 22:16:12,948 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2014-08-22 22:16:12,951 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1706291977_0010_m_000001_0 is done. And is in the process of committing
2014-08-22 22:16:12,954 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/upper.txt:0+19
2014-08-22 22:16:12,955 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1706291977_0010_m_000001_0' done.
2014-08-22 22:16:12,955 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1706291977_0010_m_000001_0
2014-08-22 22:16:12,955 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 22:16:12,956 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 22:16:12,956 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1706291977_0010_r_000000_0
2014-08-22 22:16:12,958 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 22:16:12,958 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@45a27a8f
2014-08-22 22:16:12,960 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 22:16:12,961 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1706291977_0010_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 22:16:12,965 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#3 about to shuffle output of map attempt_local1706291977_0010_m_000000_0 decomp: 97 len: 101 to MEMORY
2014-08-22 22:16:12,965 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 97 bytes from map-output for attempt_local1706291977_0010_m_000000_0
2014-08-22 22:16:12,965 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 97, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->97
2014-08-22 22:16:12,968 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#3 about to shuffle output of map attempt_local1706291977_0010_m_000001_0 decomp: 97 len: 101 to MEMORY
2014-08-22 22:16:12,969 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 97 bytes from map-output for attempt_local1706291977_0010_m_000001_0
2014-08-22 22:16:12,969 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 97, inMemoryMapOutputs.size() -> 2, commitMemory -> 97, usedMemory ->194
2014-08-22 22:16:12,970 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 22:16:12,971 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 2 / 2 copied.
2014-08-22 22:16:12,972 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 2 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 22:16:12,975 INFO mapred.Merger (Merger.java:merge(589)) - Merging 2 sorted segments
2014-08-22 22:16:12,975 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 2 segments left of total size: 174 bytes
2014-08-22 22:16:12,978 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 2 segments, 194 bytes to disk to satisfy reduce memory limit
2014-08-22 22:16:12,978 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 196 bytes from disk
2014-08-22 22:16:12,979 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 22:16:12,979 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 22:16:12,980 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 182 bytes
2014-08-22 22:16:12,981 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 2 / 2 copied.
2014-08-22 22:16:12,982 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 22:16:12,982 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 22:16:12,993 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: CoGroup(lower*upper)[by: lower:[{1}:'num'] upper:[{1}:'num']]
2014-08-22 22:16:12,993 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/oomepost"]
2014-08-22 22:16:13,004 INFO collect.SpillableTupleList (SpillableTupleList.java:getCodecClass(105)) - attempting to load codec: org.apache.hadoop.io.compress.GzipCodec
2014-08-22 22:16:13,004 INFO collect.SpillableTupleList (SpillableTupleList.java:getCodecClass(110)) - found codec: org.apache.hadoop.io.compress.GzipCodec
2014-08-22 22:16:13,006 ERROR stream.TrapHandler (TrapHandler.java:handleReThrowableException(103)) - caught OutOfMemoryException, will not trap, rethrowing
java.lang.OutOfMemoryError: fake error
at cascading.RegressionPipesPlatformTest$2.throwIntentionalException(RegressionPipesPlatformTest.java:643)
at cascading.TestFunction.operate(TestFunction.java:74)
at cascading.flow.stream.FunctionEachStage.receive(FunctionEachStage.java:99)
at cascading.flow.stream.FunctionEachStage.receive(FunctionEachStage.java:39)
at cascading.flow.stream.OpenDuct.receive(OpenDuct.java:45)
at cascading.flow.stream.OpenDuct.receive(OpenDuct.java:28)
at cascading.flow.hadoop.stream.HadoopGroupGate.run(HadoopGroupGate.java:93)
at cascading.flow.hadoop.FlowReducer.reduce(FlowReducer.java:136)
at org.apache.hadoop.mapred.ReduceTask.runOldReducer(ReduceTask.java:444)
at org.apache.hadoop.mapred.ReduceTask.run(ReduceTask.java:392)
at org.apache.hadoop.mapred.LocalJobRunner$Job$ReduceTaskRunnable.run(LocalJobRunner.java:319)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:439)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
at java.lang.Thread.run(Thread.java:662)
2014-08-22 22:16:13,011 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 22:16:13,014 WARN mapred.LocalJobRunner (LocalJobRunner.java:run(560)) - job_local1706291977_0010
java.lang.Exception: java.lang.OutOfMemoryError: fake error
at org.apache.hadoop.mapred.LocalJobRunner$Job.runTasks(LocalJobRunner.java:462)
at org.apache.hadoop.mapred.LocalJobRunner$Job.run(LocalJobRunner.java:529)
Caused by: java.lang.OutOfMemoryError: fake error
at cascading.RegressionPipesPlatformTest$2.throwIntentionalException(RegressionPipesPlatformTest.java:643)
at cascading.TestFunction.operate(TestFunction.java:74)
at cascading.flow.stream.FunctionEachStage.receive(FunctionEachStage.java:99)
at cascading.flow.stream.FunctionEachStage.receive(FunctionEachStage.java:39)
at cascading.flow.stream.OpenDuct.receive(OpenDuct.java:45)
at cascading.flow.stream.OpenDuct.receive(OpenDuct.java:28)
at cascading.flow.hadoop.stream.HadoopGroupGate.run(HadoopGroupGate.java:93)
at cascading.flow.hadoop.FlowReducer.reduce(FlowReducer.java:136)
at org.apache.hadoop.mapred.ReduceTask.runOldReducer(ReduceTask.java:444)
at org.apache.hadoop.mapred.ReduceTask.run(ReduceTask.java:392)
at org.apache.hadoop.mapred.LocalJobRunner$Job$ReduceTaskRunnable.run(LocalJobRunner.java:319)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:439)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
at java.lang.Thread.run(Thread.java:662)
2014-08-22 22:16:13,024 WARN flow.FlowStep (BaseFlowStep.java:logWarn(839)) - [lower*upper] hadoop job job_local1706291977_0010 state at FAILED
2014-08-22 22:16:13,024 WARN flow.FlowStep (BaseFlowStep.java:logWarn(839)) - [lower*upper] failure info: NA
2014-08-22 22:16:13,024 WARN flow.FlowStep (BaseFlowStep.java:logWarn(839)) - [lower*upper] task completion events identify failed tasks
2014-08-22 22:16:13,024 WARN flow.FlowStep (BaseFlowStep.java:logWarn(839)) - [lower*upper] task completion events count: 0
2014-08-22 22:16:13,035 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [lower*upper] stopping all jobs
2014-08-22 22:16:13,036 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [lower*upper] stopping: (1/1) ...ionpipesplatform/oomepost
2014-08-22 22:16:13,037 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [lower*upper] stopped all jobs
2014-08-22 22:16:13,037 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/oomepost/_temporary
exception = cascading.flow.FlowException: local step failed
2014-08-22 22:16:13,038 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output//hadoop2-mr1/regressionpipesplatform/oomepost
2014-08-22 22:16:13,063 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 22:16:13,064 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.5.6/31997f144a2e73eebf04d45ed31402ee30118b2/cascading-hadoop2-mr1-2.5.6.jar
2014-08-22 22:16:13,075 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 22:16:13,078 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 22:16:13,079 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 22:16:13,085 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting
2014-08-22 22:16:13,086 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2014-08-22 22:16:13,086 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] sink: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/lasteachmodified"]
2014-08-22 22:16:13,086 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] parallel execution is enabled: false
2014-08-22 22:16:13,086 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting jobs: 1
2014-08-22 22:16:13,086 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] allocating threads: 1
2014-08-22 22:16:13,087 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...platform/lasteachmodified
2014-08-22 22:16:13,088 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 22:16:13,090 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 22:16:13,117 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 22:16:13,140 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 22:16:13,162 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local958791691_0011
2014-08-22 22:16:13,189 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity958791691/.staging/job_local958791691_0011/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 22:16:13,190 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity958791691/.staging/job_local958791691_0011/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 22:16:13,259 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local958791691_0011/job_local958791691_0011.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 22:16:13,260 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local958791691_0011/job_local958791691_0011.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 22:16:13,261 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 22:16:13,262 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local958791691_0011
2014-08-22 22:16:13,262 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 22:16:13,262 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2014-08-22 22:16:13,262 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 22:16:13,266 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 22:16:13,266 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local958791691_0011_m_000000_0
2014-08-22 22:16:13,268 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 22:16:13,270 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/apache.10.txt
2014-08-22 22:16:13,271 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@21dc7b3e
2014-08-22 22:16:13,272 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 22:16:13,272 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 22:16:13,411 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 22:16:13,411 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 22:16:13,411 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 22:16:13,411 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 22:16:13,411 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 22:16:13,413 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 22:16:13,413 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 22:16:13,422 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2014-08-22 22:16:13,422 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:'insert']]
2014-08-22 22:16:13,426 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 22:16:13,426 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2014-08-22 22:16:13,426 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2014-08-22 22:16:13,426 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 160; bufvoid = 104857600
2014-08-22 22:16:13,426 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214360(104857440); length = 37/6553600
2014-08-22 22:16:13,430 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2014-08-22 22:16:13,433 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local958791691_0011_m_000000_0 is done. And is in the process of committing
2014-08-22 22:16:13,435 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/apache.10.txt:0+1449
2014-08-22 22:16:13,435 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local958791691_0011_m_000000_0' done.
2014-08-22 22:16:13,436 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local958791691_0011_m_000000_0
2014-08-22 22:16:13,436 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 22:16:13,437 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 22:16:13,437 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local958791691_0011_r_000000_0
2014-08-22 22:16:13,440 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 22:16:13,440 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@309b3e5e
2014-08-22 22:16:13,441 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 22:16:13,442 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local958791691_0011_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 22:16:13,444 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#4 about to shuffle output of map attempt_local958791691_0011_m_000000_0 decomp: 182 len: 186 to MEMORY
2014-08-22 22:16:13,445 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 182 bytes from map-output for attempt_local958791691_0011_m_000000_0
2014-08-22 22:16:13,445 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 182, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->182
2014-08-22 22:16:13,446 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 22:16:13,447 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 22:16:13,447 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 22:16:13,449 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 22:16:13,449 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 166 bytes
2014-08-22 22:16:13,451 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 182 bytes to disk to satisfy reduce memory limit
2014-08-22 22:16:13,452 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 186 bytes from disk
2014-08-22 22:16:13,452 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 22:16:13,452 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 22:16:13,453 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 166 bytes
2014-08-22 22:16:13,454 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 22:16:13,454 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 22:16:13,454 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 22:16:13,462 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:'insert']]
2014-08-22 22:16:13,462 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/lasteachmodified"]
2014-08-22 22:16:13,475 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local958791691_0011_r_000000_0 is done. And is in the process of committing
2014-08-22 22:16:13,477 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 22:16:13,477 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local958791691_0011_r_000000_0 is allowed to commit now
2014-08-22 22:16:13,478 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local958791691_0011_r_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/lasteachmodified/_temporary/0/task_local958791691_0011_r_000000
2014-08-22 22:16:13,480 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 22:16:13,480 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local958791691_0011_r_000000_0' done.
2014-08-22 22:16:13,480 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local958791691_0011_r_000000_0
2014-08-22 22:16:13,480 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 22:16:13,513 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/lasteachmodified/_temporary
2014-08-22 22:16:13,545 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 22:16:13,547 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output//hadoop2-mr1/regressionpipesplatform/lasteachmodified
2014-08-22 22:16:13,569 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 22:16:13,569 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.5.6/31997f144a2e73eebf04d45ed31402ee30118b2/cascading-hadoop2-mr1-2.5.6.jar
2014-08-22 22:16:13,579 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 22:16:13,582 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 22:16:13,582 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 22:16:13,589 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting
2014-08-22 22:16:13,590 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower+upper.txt"]
2014-08-22 22:16:13,590 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] sink: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/unknown"]
2014-08-22 22:16:13,590 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] parallel execution is enabled: false
2014-08-22 22:16:13,591 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting jobs: 1
2014-08-22 22:16:13,591 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] allocating threads: 1
2014-08-22 22:16:13,593 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...sionpipesplatform/unknown
2014-08-22 22:16:13,593 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 22:16:13,594 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 22:16:13,620 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 22:16:13,641 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 22:16:13,658 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local517490423_0012
2014-08-22 22:16:13,679 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity517490423/.staging/job_local517490423_0012/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 22:16:13,680 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity517490423/.staging/job_local517490423_0012/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 22:16:13,734 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local517490423_0012/job_local517490423_0012.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 22:16:13,736 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local517490423_0012/job_local517490423_0012.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 22:16:13,736 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 22:16:13,737 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local517490423_0012
2014-08-22 22:16:13,737 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 22:16:13,737 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2014-08-22 22:16:13,737 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 22:16:13,740 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 22:16:13,741 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local517490423_0012_m_000000_0
2014-08-22 22:16:13,743 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 22:16:13,744 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower+upper.txt
2014-08-22 22:16:13,745 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@25c20c74
2014-08-22 22:16:13,746 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 0
2014-08-22 22:16:13,754 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 22:16:13,754 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 22:16:13,762 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower+upper.txt"]
2014-08-22 22:16:13,762 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/unknown"]
2014-08-22 22:16:13,766 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 22:16:13,766 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local517490423_0012_m_000000_0 is done. And is in the process of committing
2014-08-22 22:16:13,768 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 22:16:13,768 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local517490423_0012_m_000000_0 is allowed to commit now
2014-08-22 22:16:13,769 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local517490423_0012_m_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/unknown/_temporary/0/task_local517490423_0012_m_000000
2014-08-22 22:16:13,770 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower+upper.txt:0+30
2014-08-22 22:16:13,770 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local517490423_0012_m_000000_0' done.
2014-08-22 22:16:13,770 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local517490423_0012_m_000000_0
2014-08-22 22:16:13,770 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 22:16:13,792 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/unknown/_temporary
2014-08-22 22:16:13,823 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 22:16:13,825 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output//hadoop2-mr1/regressionpipesplatform/unknown
2014-08-22 22:16:13,847 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 22:16:13,848 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.5.6/31997f144a2e73eebf04d45ed31402ee30118b2/cascading-hadoop2-mr1-2.5.6.jar
2014-08-22 22:16:13,856 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 22:16:13,858 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 22:16:13,859 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 22:16:13,868 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting
2014-08-22 22:16:13,868 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/critics.txt"]
2014-08-22 22:16:13,868 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] sink: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/varwidth"]
2014-08-22 22:16:13,869 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] parallel execution is enabled: false
2014-08-22 22:16:13,869 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting jobs: 1
2014-08-22 22:16:13,869 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] allocating threads: 1
2014-08-22 22:16:13,870 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...ionpipesplatform/varwidth
2014-08-22 22:16:13,871 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 22:16:13,872 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 22:16:13,897 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 22:16:13,917 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 22:16:13,932 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local893848535_0013
2014-08-22 22:16:13,951 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity893848535/.staging/job_local893848535_0013/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 22:16:13,952 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity893848535/.staging/job_local893848535_0013/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 22:16:13,999 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local893848535_0013/job_local893848535_0013.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 22:16:14,001 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local893848535_0013/job_local893848535_0013.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 22:16:14,001 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 22:16:14,002 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local893848535_0013
2014-08-22 22:16:14,002 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 22:16:14,002 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2014-08-22 22:16:14,002 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 22:16:14,005 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 22:16:14,005 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local893848535_0013_m_000000_0
2014-08-22 22:16:14,008 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 22:16:14,010 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/critics.txt
2014-08-22 22:16:14,010 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@2fdb3aac
2014-08-22 22:16:14,012 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 0
2014-08-22 22:16:14,020 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 22:16:14,020 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 22:16:14,028 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/critics.txt"]
2014-08-22 22:16:14,028 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/varwidth"]
2014-08-22 22:16:14,032 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 22:16:14,032 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local893848535_0013_m_000000_0 is done. And is in the process of committing
2014-08-22 22:16:14,034 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 22:16:14,034 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local893848535_0013_m_000000_0 is allowed to commit now
2014-08-22 22:16:14,035 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local893848535_0013_m_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/varwidth/_temporary/0/task_local893848535_0013_m_000000
2014-08-22 22:16:14,036 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/critics.txt:0+828
2014-08-22 22:16:14,036 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local893848535_0013_m_000000_0' done.
2014-08-22 22:16:14,036 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local893848535_0013_m_000000_0
2014-08-22 22:16:14,037 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 22:16:14,057 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/varwidth/_temporary
2014-08-22 22:16:14,088 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 22:16:14,089 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output//hadoop2-mr1/regressionpipesplatform/varwidth
2014-08-22 22:16:14,460 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 22:16:14,461 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.5.6/31997f144a2e73eebf04d45ed31402ee30118b2/cascading-hadoop2-mr1-2.5.6.jar
2014-08-22 22:16:14,972 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 22:16:14,975 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 22:16:14,976 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 22:16:15,112 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [pipeline] starting
2014-08-22 22:16:15,113 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [pipeline] source: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/apache.200.txt"]
2014-08-22 22:16:15,113 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [pipeline] sink: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/deeppipline"]
2014-08-22 22:16:15,113 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [pipeline] parallel execution is enabled: false
2014-08-22 22:16:15,113 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [pipeline] starting jobs: 1
2014-08-22 22:16:15,113 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [pipeline] allocating threads: 1
2014-08-22 22:16:15,114 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [pipeline] starting step: (1/1) ...pipesplatform/deeppipline
2014-08-22 22:16:15,115 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 22:16:15,116 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 22:16:15,154 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 22:16:15,173 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 22:16:15,189 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1740818795_0014
2014-08-22 22:16:15,209 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1740818795/.staging/job_local1740818795_0014/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 22:16:15,210 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1740818795/.staging/job_local1740818795_0014/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 22:16:15,258 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1740818795_0014/job_local1740818795_0014.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 22:16:15,259 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1740818795_0014/job_local1740818795_0014.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 22:16:15,260 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 22:16:15,261 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 22:16:15,261 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [pipeline] submitted hadoop job: job_local1740818795_0014
2014-08-22 22:16:15,261 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 22:16:15,262 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [pipeline] tracking url: http://localhost:8080/
2014-08-22 22:16:15,264 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 22:16:15,264 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1740818795_0014_m_000000_0
2014-08-22 22:16:15,266 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 22:16:15,268 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/apache.200.txt
2014-08-22 22:16:15,268 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@2e4e3801
2014-08-22 22:16:15,269 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 22:16:15,270 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 22:16:15,290 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 22:16:15,291 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 22:16:15,291 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 22:16:15,291 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 22:16:15,291 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 22:16:15,293 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 22:16:15,293 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 22:16:15,536 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/apache.200.txt"]
2014-08-22 22:16:15,537 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(pipeline)[by:[{1}:'hash']]
2014-08-22 22:16:15,818 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 22:16:15,819 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2014-08-22 22:16:15,819 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2014-08-22 22:16:15,819 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 35385; bufvoid = 104857600
2014-08-22 22:16:15,819 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26213600(104854400); length = 797/6553600
2014-08-22 22:16:15,848 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2014-08-22 22:16:15,851 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1740818795_0014_m_000000_0 is done. And is in the process of committing
2014-08-22 22:16:15,853 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/apache.200.txt:0+32599
2014-08-22 22:16:15,853 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1740818795_0014_m_000000_0' done.
2014-08-22 22:16:15,853 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1740818795_0014_m_000000_0
2014-08-22 22:16:15,853 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 22:16:15,854 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 22:16:15,854 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1740818795_0014_r_000000_0
2014-08-22 22:16:15,856 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 22:16:15,856 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@63d8aaba
2014-08-22 22:16:15,857 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=526417920, maxSingleShuffleLimit=131604480, mergeThreshold=347435840, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 22:16:15,858 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1740818795_0014_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 22:16:15,860 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#5 about to shuffle output of map attempt_local1740818795_0014_m_000000_0 decomp: 35984 len: 35988 to MEMORY
2014-08-22 22:16:15,861 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 35984 bytes from map-output for attempt_local1740818795_0014_m_000000_0
2014-08-22 22:16:15,861 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 35984, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->35984
2014-08-22 22:16:15,863 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 22:16:15,864 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 22:16:15,864 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 22:16:15,866 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 22:16:15,866 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 35975 bytes
2014-08-22 22:16:15,871 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 35984 bytes to disk to satisfy reduce memory limit
2014-08-22 22:16:15,872 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 35988 bytes from disk
2014-08-22 22:16:15,872 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 22:16:15,872 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 22:16:15,872 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 35975 bytes
2014-08-22 22:16:15,874 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 22:16:15,874 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 22:16:15,874 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 22:16:16,019 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(pipeline)[by:[{1}:'hash']]
2014-08-22 22:16:16,019 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/deeppipline"]
2014-08-22 22:16:16,573 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1740818795_0014_r_000000_0 is done. And is in the process of committing
2014-08-22 22:16:16,575 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 22:16:16,575 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1740818795_0014_r_000000_0 is allowed to commit now
2014-08-22 22:16:16,576 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1740818795_0014_r_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/deeppipline/_temporary/0/task_local1740818795_0014_r_000000
2014-08-22 22:16:16,578 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 22:16:16,578 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1740818795_0014_r_000000_0' done.
2014-08-22 22:16:16,578 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1740818795_0014_r_000000_0
2014-08-22 22:16:16,578 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 22:16:16,597 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/deeppipline/_temporary
2014-08-22 22:16:16,598 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output//hadoop2-mr1/regressionpipesplatform/deeppipline
2014-08-22 22:16:16,621 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 22:16:16,622 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.5.6/31997f144a2e73eebf04d45ed31402ee30118b2/cascading-hadoop2-mr1-2.5.6.jar
2014-08-22 22:16:16,629 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 22:16:16,631 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 22:16:16,632 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 22:16:16,636 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [split] starting
2014-08-22 22:16:16,636 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [split] source: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower.txt"]
2014-08-22 22:16:16,637 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [split] sink: Hfs["TextDelimited[['num', 'char']]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/splitintermediate"]
2014-08-22 22:16:16,637 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [split] parallel execution is enabled: false
2014-08-22 22:16:16,637 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [split] starting jobs: 1
2014-08-22 22:16:16,637 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [split] allocating threads: 1
2014-08-22 22:16:16,638 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [split] starting step: (1/1) ...latform/splitintermediate
2014-08-22 22:16:16,639 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 22:16:16,640 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 22:16:16,666 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 22:16:16,686 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 22:16:16,707 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local2080451941_0015
2014-08-22 22:16:16,729 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity2080451941/.staging/job_local2080451941_0015/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 22:16:16,731 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity2080451941/.staging/job_local2080451941_0015/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 22:16:16,794 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local2080451941_0015/job_local2080451941_0015.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 22:16:16,796 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local2080451941_0015/job_local2080451941_0015.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 22:16:16,796 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 22:16:16,797 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [split] submitted hadoop job: job_local2080451941_0015
2014-08-22 22:16:16,797 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 22:16:16,797 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [split] tracking url: http://localhost:8080/
2014-08-22 22:16:16,798 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 22:16:16,801 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 22:16:16,802 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local2080451941_0015_m_000000_0
2014-08-22 22:16:16,804 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 22:16:16,807 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower.txt
2014-08-22 22:16:16,807 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@614b5446
2014-08-22 22:16:16,809 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 0
2014-08-22 22:16:16,818 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 22:16:16,818 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 22:16:16,823 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower.txt"]
2014-08-22 22:16:16,823 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: Hfs["TextDelimited[['num', 'char']]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/splitintermediate"]
2014-08-22 22:16:16,826 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 22:16:16,827 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local2080451941_0015_m_000000_0 is done. And is in the process of committing
2014-08-22 22:16:16,828 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 22:16:16,828 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local2080451941_0015_m_000000_0 is allowed to commit now
2014-08-22 22:16:16,829 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local2080451941_0015_m_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/splitintermediate/_temporary/0/task_local2080451941_0015_m_000000
2014-08-22 22:16:16,830 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower.txt:0+19
2014-08-22 22:16:16,831 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local2080451941_0015_m_000000_0' done.
2014-08-22 22:16:16,831 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local2080451941_0015_m_000000_0
2014-08-22 22:16:16,831 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 22:16:16,853 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/splitintermediate/_temporary
2014-08-22 22:16:16,875 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 22:16:16,876 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.5.6/31997f144a2e73eebf04d45ed31402ee30118b2/cascading-hadoop2-mr1-2.5.6.jar
2014-08-22 22:16:16,886 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 22:16:16,888 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 22:16:16,889 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 22:16:16,893 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [lhs+rhs] starting
2014-08-22 22:16:16,894 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [lhs+rhs] source: Hfs["TextDelimited[['num', 'char']]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/splitintermediate"]
2014-08-22 22:16:16,894 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [lhs+rhs] sink: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/groupbysplit"]
2014-08-22 22:16:16,894 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [lhs+rhs] parallel execution is enabled: false
2014-08-22 22:16:16,894 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [lhs+rhs] starting jobs: 1
2014-08-22 22:16:16,894 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [lhs+rhs] allocating threads: 1
2014-08-22 22:16:16,895 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [lhs+rhs] starting step: (1/1) ...ipesplatform/groupbysplit
2014-08-22 22:16:16,896 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 22:16:16,897 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 22:16:16,950 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 22:16:16,968 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 22:16:16,983 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local754188975_0016
2014-08-22 22:16:17,002 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity754188975/.staging/job_local754188975_0016/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 22:16:17,003 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity754188975/.staging/job_local754188975_0016/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 22:16:17,050 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local754188975_0016/job_local754188975_0016.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 22:16:17,052 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local754188975_0016/job_local754188975_0016.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 22:16:17,052 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 22:16:17,052 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [lhs+rhs] submitted hadoop job: job_local754188975_0016
2014-08-22 22:16:17,053 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [lhs+rhs] tracking url: http://localhost:8080/
2014-08-22 22:16:17,053 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 22:16:17,053 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 22:16:17,056 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 22:16:17,056 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local754188975_0016_m_000000_0
2014-08-22 22:16:17,059 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 22:16:17,060 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/splitintermediate/part-00000
2014-08-22 22:16:17,061 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@4a65d816
2014-08-22 22:16:17,063 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 22:16:17,063 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 22:16:17,082 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 22:16:17,083 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 22:16:17,083 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 22:16:17,083 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 22:16:17,083 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 22:16:17,085 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 22:16:17,086 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 22:16:17,091 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextDelimited[['num', 'char']]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/splitintermediate"]
2014-08-22 22:16:17,091 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(lhs+rhs)[by: lhs:[{1}:'num'] rhs:[{1}:'num']]
2014-08-22 22:16:17,094 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 22:16:17,094 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2014-08-22 22:16:17,094 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2014-08-22 22:16:17,095 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 150; bufvoid = 104857600
2014-08-22 22:16:17,095 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214360(104857440); length = 37/6553600
2014-08-22 22:16:17,098 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2014-08-22 22:16:17,100 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local754188975_0016_m_000000_0 is done. And is in the process of committing
2014-08-22 22:16:17,102 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/splitintermediate/part-00000:0+20
2014-08-22 22:16:17,102 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local754188975_0016_m_000000_0' done.
2014-08-22 22:16:17,102 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local754188975_0016_m_000000_0
2014-08-22 22:16:17,102 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 22:16:17,103 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 22:16:17,103 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local754188975_0016_r_000000_0
2014-08-22 22:16:17,105 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 22:16:17,105 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@7ddc5f7
2014-08-22 22:16:17,106 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=515361984, maxSingleShuffleLimit=128840496, mergeThreshold=340138912, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 22:16:17,106 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local754188975_0016_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 22:16:17,108 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#6 about to shuffle output of map attempt_local754188975_0016_m_000000_0 decomp: 172 len: 176 to MEMORY
2014-08-22 22:16:17,109 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 172 bytes from map-output for attempt_local754188975_0016_m_000000_0
2014-08-22 22:16:17,109 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 172, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->172
2014-08-22 22:16:17,110 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 22:16:17,110 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 22:16:17,111 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 22:16:17,113 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 22:16:17,113 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 163 bytes
2014-08-22 22:16:17,114 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 172 bytes to disk to satisfy reduce memory limit
2014-08-22 22:16:17,115 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 176 bytes from disk
2014-08-22 22:16:17,115 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 22:16:17,115 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 22:16:17,115 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 163 bytes
2014-08-22 22:16:17,116 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 22:16:17,116 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 22:16:17,117 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 22:16:17,121 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(lhs+rhs)[by: lhs:[{1}:'num'] rhs:[{1}:'num']]
2014-08-22 22:16:17,121 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/groupbysplit"]
2014-08-22 22:16:17,133 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local754188975_0016_r_000000_0 is done. And is in the process of committing
2014-08-22 22:16:17,135 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 22:16:17,135 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local754188975_0016_r_000000_0 is allowed to commit now
2014-08-22 22:16:17,136 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local754188975_0016_r_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/groupbysplit/_temporary/0/task_local754188975_0016_r_000000
2014-08-22 22:16:17,137 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 22:16:17,137 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local754188975_0016_r_000000_0' done.
2014-08-22 22:16:17,137 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local754188975_0016_r_000000_0
2014-08-22 22:16:17,138 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 22:16:17,141 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/apache.10.txt:0+1449 > map
2014-08-22 22:16:17,162 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/groupbysplit/_temporary
2014-08-22 22:16:17,191 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 22:16:17,222 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 22:16:17,226 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output//hadoop2-mr1/regressionpipesplatform/splitintermediate
2014-08-22 22:16:17,227 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output//hadoop2-mr1/regressionpipesplatform/groupbysplit
2014-08-22 22:16:17,251 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 22:16:17,251 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.5.6/31997f144a2e73eebf04d45ed31402ee30118b2/cascading-hadoop2-mr1-2.5.6.jar
2014-08-22 22:16:17,263 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 22:16:17,264 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 22:16:17,272 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 22:16:17,276 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [**&%&%bar:bar@foo://bl...] starting
2014-08-22 22:16:17,277 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [**&%&%bar:bar@foo://bl...] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower+upper.txt"]
2014-08-22 22:16:17,277 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [**&%&%bar:bar@foo://bl...] sink: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/illegalchars"]
2014-08-22 22:16:17,278 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [**&%&%bar:bar@foo://bl...] parallel execution is enabled: false
2014-08-22 22:16:17,278 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [**&%&%bar:bar@foo://bl...] starting jobs: 2
2014-08-22 22:16:17,278 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [**&%&%bar:bar@foo://bl...] allocating threads: 1
2014-08-22 22:16:17,279 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [**&%&%bar:bar@foo://bl...] starting step: (1/2)
2014-08-22 22:16:17,280 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 22:16:17,281 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 22:16:17,305 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 22:16:17,325 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 22:16:17,346 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1667054952_0017
2014-08-22 22:16:17,366 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1667054952/.staging/job_local1667054952_0017/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 22:16:17,367 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1667054952/.staging/job_local1667054952_0017/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 22:16:17,418 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1667054952_0017/job_local1667054952_0017.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 22:16:17,419 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1667054952_0017/job_local1667054952_0017.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 22:16:17,419 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 22:16:17,420 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [**&%&%bar:bar@foo://bl...] submitted hadoop job: job_local1667054952_0017
2014-08-22 22:16:17,420 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 22:16:17,420 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [**&%&%bar:bar@foo://bl...] tracking url: http://localhost:8080/
2014-08-22 22:16:17,420 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 22:16:17,423 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 22:16:17,423 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1667054952_0017_m_000000_0
2014-08-22 22:16:17,424 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 22:16:17,426 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower+upper.txt
2014-08-22 22:16:17,426 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@7dd7b855
2014-08-22 22:16:17,427 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 22:16:17,427 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 22:16:17,457 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 22:16:17,457 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 22:16:17,457 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 22:16:17,458 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 22:16:17,458 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 22:16:17,459 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 22:16:17,459 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 22:16:17,464 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower+upper.txt"]
2014-08-22 22:16:17,464 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(**&%&%bar:bar@foo://blah/ (*(**^**&%&%^@#@&&() :::: ///\\ illegal chars in it)[by:[{1}:0]]
2014-08-22 22:16:17,467 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 22:16:17,467 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2014-08-22 22:16:17,467 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2014-08-22 22:16:17,467 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 65; bufvoid = 104857600
2014-08-22 22:16:17,467 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214380(104857520); length = 17/6553600
2014-08-22 22:16:17,470 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2014-08-22 22:16:17,472 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1667054952_0017_m_000000_0 is done. And is in the process of committing
2014-08-22 22:16:17,474 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower+upper.txt:0+30
2014-08-22 22:16:17,475 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1667054952_0017_m_000000_0' done.
2014-08-22 22:16:17,475 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1667054952_0017_m_000000_0
2014-08-22 22:16:17,475 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 22:16:17,476 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 22:16:17,476 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1667054952_0017_r_000000_0
2014-08-22 22:16:17,478 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 22:16:17,478 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@60e86e8a
2014-08-22 22:16:17,479 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=522564384, maxSingleShuffleLimit=130641096, mergeThreshold=344892512, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 22:16:17,479 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1667054952_0017_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 22:16:17,481 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#7 about to shuffle output of map attempt_local1667054952_0017_m_000000_0 decomp: 77 len: 81 to MEMORY
2014-08-22 22:16:17,482 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 77 bytes from map-output for attempt_local1667054952_0017_m_000000_0
2014-08-22 22:16:17,482 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 77, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->77
2014-08-22 22:16:17,483 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 22:16:17,484 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 22:16:17,484 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 22:16:17,486 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 22:16:17,486 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 64 bytes
2014-08-22 22:16:17,488 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 77 bytes to disk to satisfy reduce memory limit
2014-08-22 22:16:17,488 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 81 bytes from disk
2014-08-22 22:16:17,488 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 22:16:17,488 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 22:16:17,489 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 64 bytes
2014-08-22 22:16:17,489 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 22:16:17,490 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 22:16:17,490 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 22:16:17,494 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(**&%&%bar:bar@foo://blah/ (*(**^**&%&%^@#@&&() :::: ///\\ illegal chars in it)[by:[{1}:0]]
2014-08-22 22:16:17,494 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: TempHfs["SequenceFile[[UNKNOWN]->[ALL]]"][5626878957/__&%&%bar:bar@foo:_blah_/]
2014-08-22 22:16:17,517 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1667054952_0017_r_000000_0 is done. And is in the process of committing
2014-08-22 22:16:17,519 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 22:16:17,519 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1667054952_0017_r_000000_0 is allowed to commit now
2014-08-22 22:16:17,520 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1667054952_0017_r_000000_0' to file:/tmp/hadoop-teamcity/5626878957____bar_bar_foo__blah__4912FBFA38E54351AC8115B344FA379C/_temporary/0/task_local1667054952_0017_r_000000
2014-08-22 22:16:17,521 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 22:16:17,521 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1667054952_0017_r_000000_0' done.
2014-08-22 22:16:17,521 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1667054952_0017_r_000000_0
2014-08-22 22:16:17,521 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 22:16:17,540 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [**&%&%bar:bar@foo://bl...] starting step: (2/2) ...ipesplatform/illegalchars
2014-08-22 22:16:17,541 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 22:16:17,542 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 22:16:17,577 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 22:16:17,596 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 22:16:17,606 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 22:16:17,606 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 22:16:17,612 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1722934273_0018
2014-08-22 22:16:17,629 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1722934273/.staging/job_local1722934273_0018/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 22:16:17,630 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1722934273/.staging/job_local1722934273_0018/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 22:16:17,676 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1722934273_0018/job_local1722934273_0018.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 22:16:17,677 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1722934273_0018/job_local1722934273_0018.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 22:16:17,678 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 22:16:17,678 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [**&%&%bar:bar@foo://bl...] submitted hadoop job: job_local1722934273_0018
2014-08-22 22:16:17,678 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 22:16:17,679 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [**&%&%bar:bar@foo://bl...] tracking url: http://localhost:8080/
2014-08-22 22:16:17,679 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 22:16:17,681 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 22:16:17,682 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1722934273_0018_m_000000_0
2014-08-22 22:16:17,683 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 22:16:17,685 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/tmp/hadoop-teamcity/5626878957____bar_bar_foo__blah__4912FBFA38E54351AC8115B344FA379C/part-00000
2014-08-22 22:16:17,685 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@72fccde
2014-08-22 22:16:17,696 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 22:16:17,696 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 22:16:17,726 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 22:16:17,726 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 22:16:17,726 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 22:16:17,726 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 22:16:17,727 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 22:16:17,728 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 22:16:17,729 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 22:16:17,733 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: TempHfs["SequenceFile[[UNKNOWN]->[ALL]]"][5626878957/__&%&%bar:bar@foo:_blah_/]
2014-08-22 22:16:17,733 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(**&%&%bar:bar@foo://blah/ (*(**^**&%&%^@#@&&() :::: ///\\ illegal chars in it)[by:[{1}:0]]
2014-08-22 22:16:17,736 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 22:16:17,737 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2014-08-22 22:16:17,737 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2014-08-22 22:16:17,737 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 65; bufvoid = 104857600
2014-08-22 22:16:17,737 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214380(104857520); length = 17/6553600
2014-08-22 22:16:17,740 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2014-08-22 22:16:17,742 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1722934273_0018_m_000000_0 is done. And is in the process of committing
2014-08-22 22:16:17,743 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/tmp/hadoop-teamcity/5626878957____bar_bar_foo__blah__4912FBFA38E54351AC8115B344FA379C/part-00000:0+170
2014-08-22 22:16:17,744 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1722934273_0018_m_000000_0' done.
2014-08-22 22:16:17,744 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1722934273_0018_m_000000_0
2014-08-22 22:16:17,744 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 22:16:17,744 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 22:16:17,745 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1722934273_0018_r_000000_0
2014-08-22 22:16:17,746 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 22:16:17,746 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@42d81aaf
2014-08-22 22:16:17,747 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=523252512, maxSingleShuffleLimit=130813128, mergeThreshold=345346656, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 22:16:17,748 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1722934273_0018_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 22:16:17,750 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#8 about to shuffle output of map attempt_local1722934273_0018_m_000000_0 decomp: 77 len: 81 to MEMORY
2014-08-22 22:16:17,750 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 77 bytes from map-output for attempt_local1722934273_0018_m_000000_0
2014-08-22 22:16:17,750 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 77, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->77
2014-08-22 22:16:17,751 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 22:16:17,752 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 22:16:17,752 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 22:16:17,757 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 22:16:17,757 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 64 bytes
2014-08-22 22:16:17,758 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 77 bytes to disk to satisfy reduce memory limit
2014-08-22 22:16:17,759 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 81 bytes from disk
2014-08-22 22:16:17,759 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 22:16:17,759 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 22:16:17,760 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 64 bytes
2014-08-22 22:16:17,761 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 22:16:17,761 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 22:16:17,761 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 22:16:17,766 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(**&%&%bar:bar@foo://blah/ (*(**^**&%&%^@#@&&() :::: ///\\ illegal chars in it)[by:[{1}:0]]
2014-08-22 22:16:17,766 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/illegalchars"]
2014-08-22 22:16:17,776 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1722934273_0018_r_000000_0 is done. And is in the process of committing
2014-08-22 22:16:17,777 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 22:16:17,777 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1722934273_0018_r_000000_0 is allowed to commit now
2014-08-22 22:16:17,778 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1722934273_0018_r_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/illegalchars/_temporary/0/task_local1722934273_0018_r_000000
2014-08-22 22:16:17,780 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 22:16:17,780 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1722934273_0018_r_000000_0' done.
2014-08-22 22:16:17,780 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1722934273_0018_r_000000_0
2014-08-22 22:16:17,780 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 22:16:17,798 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/illegalchars/_temporary
2014-08-22 22:16:17,829 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 22:16:17,831 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output//hadoop2-mr1/regressionpipesplatform/illegalchars
2014-08-22 22:16:17,851 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 22:16:17,851 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.5.6/31997f144a2e73eebf04d45ed31402ee30118b2/cascading-hadoop2-mr1-2.5.6.jar
2014-08-22 22:16:17,857 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 22:16:17,859 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 22:16:17,859 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 22:16:17,864 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting
2014-08-22 22:16:17,864 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower+upper.txt"]
2014-08-22 22:16:17,864 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] sink: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/ungrouped-unknown-nondeterministic"]
2014-08-22 22:16:17,865 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] parallel execution is enabled: false
2014-08-22 22:16:17,865 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting jobs: 1
2014-08-22 22:16:17,865 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] allocating threads: 1
2014-08-22 22:16:17,866 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...-unknown-nondeterministic
2014-08-22 22:16:17,867 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 22:16:17,868 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 22:16:17,891 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 22:16:17,909 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 22:16:17,925 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1791646815_0019
2014-08-22 22:16:17,942 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1791646815/.staging/job_local1791646815_0019/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 22:16:17,944 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1791646815/.staging/job_local1791646815_0019/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 22:16:17,990 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1791646815_0019/job_local1791646815_0019.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 22:16:17,991 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1791646815_0019/job_local1791646815_0019.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 22:16:17,992 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 22:16:17,992 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local1791646815_0019
2014-08-22 22:16:17,992 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2014-08-22 22:16:17,993 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 22:16:17,993 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 22:16:17,996 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 22:16:17,996 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1791646815_0019_m_000000_0
2014-08-22 22:16:17,997 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 22:16:17,999 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower+upper.txt
2014-08-22 22:16:17,999 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@5263cbef
2014-08-22 22:16:18,000 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 0
2014-08-22 22:16:18,007 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 22:16:18,008 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 22:16:18,012 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower+upper.txt"]
2014-08-22 22:16:18,012 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/ungrouped-unknown-nondeterministic"]
2014-08-22 22:16:18,016 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 22:16:18,016 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1791646815_0019_m_000000_0 is done. And is in the process of committing
2014-08-22 22:16:18,017 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 22:16:18,017 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1791646815_0019_m_000000_0 is allowed to commit now
2014-08-22 22:16:18,018 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1791646815_0019_m_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/ungrouped-unknown-nondeterministic/_temporary/0/task_local1791646815_0019_m_000000
2014-08-22 22:16:18,019 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower+upper.txt:0+30
2014-08-22 22:16:18,020 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1791646815_0019_m_000000_0' done.
2014-08-22 22:16:18,020 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1791646815_0019_m_000000_0
2014-08-22 22:16:18,020 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 22:16:18,038 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/regressionpipesplatform/ungrouped-unknown-nondeterministic/_temporary
2014-08-22 22:16:18,068 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 22:16:18,070 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output//hadoop2-mr1/regressionpipesplatform/ungrouped-unknown-nondeterministic