Class cascading.BufferPipesPlatformTest

6

tests

0

failures

6.071s

duration

100%

successful

Tests

Test Duration Result
testIdentityBuffer 3.106s passed
testJoinerClosure 0.873s passed
testJoinerClosureFail 0.039s passed
testSimpleBuffer 0.727s passed
testSimpleBuffer2 0.562s passed
testSimpleBuffer3 0.764s passed

Standard output

2015-02-10 20:22:46,617 INFO  platform.PlatformRunner (PlatformRunner.java:getPlatformClassesFromClasspath(187)) - found 1 test platforms from classpath
2015-02-10 20:22:46,685 INFO  platform.PlatformRunner (PlatformRunner.java:addPlatform(237)) - installing platform: hadoop2-mr1
2015-02-10 20:22:46,685 INFO  platform.PlatformRunner (PlatformRunner.java:addPlatform(238)) - running test: cascading.BufferPipesPlatformTest
2015-02-10 20:22:46,717 INFO  hadoop2.Hadoop2MR1Platform (Hadoop2MR1Platform.java:setUp(105)) - not using cluster
2015-02-10 20:22:47,350 WARN  util.NativeCodeLoader (NativeCodeLoader.java:<clinit>(62)) - Unable to load native-hadoop library for your platform... using builtin-java classes where applicable
2015-02-10 20:22:47,648 INFO  util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 20:22:47,651 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.6.3/9ae016e2b8d246b9c1de9168e715d9f1b971aa4a/cascading-hadoop2-mr1-2.6.3.jar
2015-02-10 20:22:47,664 INFO  property.AppProps (AppProps.java:getAppID(169)) - using app.id: E449C9DC30364179AA42B651407F62FC
2015-02-10 20:22:47,745 INFO  Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 20:22:47,785 INFO  Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 20:22:47,788 INFO  Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 20:22:47,917 INFO  util.Version (Version.java:printBanner(82)) - Concurrent, Inc - Cascading 2.6.3
2015-02-10 20:22:47,920 INFO  flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting
2015-02-10 20:22:47,920 INFO  flow.Flow (BaseFlow.java:logInfo(1378)) - [test]  source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/classes/test/data/lhs.txt"]
2015-02-10 20:22:47,921 INFO  flow.Flow (BaseFlow.java:logInfo(1378)) - [test]  sink: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/test/output/hadoop2-mr1/bufferpipesplatform/identity"]
2015-02-10 20:22:47,921 INFO  flow.Flow (BaseFlow.java:logInfo(1378)) - [test]  parallel execution is enabled: false
2015-02-10 20:22:47,923 INFO  flow.Flow (BaseFlow.java:logInfo(1378)) - [test]  starting jobs: 1
2015-02-10 20:22:47,923 INFO  flow.Flow (BaseFlow.java:logInfo(1378)) - [test]  allocating threads: 1
2015-02-10 20:22:47,924 INFO  flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...ferpipesplatform/identity
2015-02-10 20:22:47,951 INFO  Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - session.id is deprecated. Instead, use dfs.metrics.session-id
2015-02-10 20:22:47,953 INFO  jvm.JvmMetrics (JvmMetrics.java:init(76)) - Initializing JVM Metrics with processName=JobTracker, sessionId=
2015-02-10 20:22:47,981 INFO  jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 20:22:48,592 INFO  mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2015-02-10 20:22:48,634 INFO  mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 20:22:48,795 INFO  mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1857576131_0001
2015-02-10 20:22:48,845 WARN  conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/tmp/cascading/staging/teamcity1857576131/.staging/job_local1857576131_0001/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval;  Ignoring.
2015-02-10 20:22:48,846 WARN  conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/tmp/cascading/staging/teamcity1857576131/.staging/job_local1857576131_0001/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts;  Ignoring.
2015-02-10 20:22:49,040 WARN  conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1857576131_0001/job_local1857576131_0001.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval;  Ignoring.
2015-02-10 20:22:49,041 WARN  conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1857576131_0001/job_local1857576131_0001.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts;  Ignoring.
2015-02-10 20:22:49,053 INFO  mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 20:22:49,056 INFO  mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 20:22:49,060 INFO  flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local1857576131_0001
2015-02-10 20:22:49,060 INFO  mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 20:22:49,060 INFO  flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2015-02-10 20:22:49,129 INFO  mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 20:22:49,132 INFO  mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1857576131_0001_m_000000_0
2015-02-10 20:22:49,174 INFO  mapred.Task (Task.java:initialize(581)) -  Using ResourceCalculatorProcessTree : [ ]
2015-02-10 20:22:49,184 INFO  io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/classes/test/data/lhs.txt
2015-02-10 20:22:49,185 INFO  mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@6b248979
2015-02-10 20:22:49,195 INFO  mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-10 20:22:49,202 INFO  mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-10 20:22:49,354 INFO  mapred.MapTask (MapTask.java:setEquator(1181)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-10 20:22:49,355 INFO  mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-10 20:22:49,355 INFO  mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-10 20:22:49,355 INFO  mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-10 20:22:49,355 INFO  mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-10 20:22:49,379 INFO  hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 20:22:49,379 INFO  hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 20:22:49,429 INFO  Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.task.partition is deprecated. Instead, use mapreduce.task.partition
2015-02-10 20:22:49,448 INFO  hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/classes/test/data/lhs.txt"]
2015-02-10 20:22:49,449 INFO  hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:'num']]
2015-02-10 20:22:49,465 INFO  mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 
2015-02-10 20:22:49,466 INFO  mapred.MapTask (MapTask.java:flush(1435)) - Starting flush of map output
2015-02-10 20:22:49,466 INFO  mapred.MapTask (MapTask.java:flush(1453)) - Spilling map output
2015-02-10 20:22:49,466 INFO  mapred.MapTask (MapTask.java:flush(1454)) - bufstart = 0; bufend = 195; bufvoid = 104857600
2015-02-10 20:22:49,466 INFO  mapred.MapTask (MapTask.java:flush(1456)) - kvstart = 26214396(104857584); kvend = 26214348(104857392); length = 49/6553600
2015-02-10 20:22:49,481 INFO  mapred.MapTask (MapTask.java:sortAndSpill(1639)) - Finished spill 0
2015-02-10 20:22:49,485 INFO  mapred.Task (Task.java:done(995)) - Task:attempt_local1857576131_0001_m_000000_0 is done. And is in the process of committing
2015-02-10 20:22:49,496 INFO  mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/classes/test/data/lhs.txt:0+52
2015-02-10 20:22:49,496 INFO  mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1857576131_0001_m_000000_0' done.
2015-02-10 20:22:49,496 INFO  mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1857576131_0001_m_000000_0
2015-02-10 20:22:49,497 INFO  mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 20:22:49,500 INFO  mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2015-02-10 20:22:49,500 INFO  mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1857576131_0001_r_000000_0
2015-02-10 20:22:49,508 INFO  mapred.Task (Task.java:initialize(581)) -  Using ResourceCalculatorProcessTree : [ ]
2015-02-10 20:22:49,512 INFO  mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@2224ea85
2015-02-10 20:22:49,526 INFO  reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2015-02-10 20:22:49,530 INFO  reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1857576131_0001_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2015-02-10 20:22:49,568 INFO  reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#1 about to shuffle output of map attempt_local1857576131_0001_m_000000_0 decomp: 223 len: 227 to MEMORY
2015-02-10 20:22:49,573 INFO  reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 223 bytes from map-output for attempt_local1857576131_0001_m_000000_0
2015-02-10 20:22:49,614 INFO  reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 223, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->223
2015-02-10 20:22:49,615 INFO  reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2015-02-10 20:22:49,617 INFO  mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 20:22:49,617 INFO  reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2015-02-10 20:22:49,627 INFO  mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2015-02-10 20:22:49,627 INFO  mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 214 bytes
2015-02-10 20:22:49,630 INFO  reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 223 bytes to disk to satisfy reduce memory limit
2015-02-10 20:22:49,631 INFO  reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 227 bytes from disk
2015-02-10 20:22:49,631 INFO  reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2015-02-10 20:22:49,631 INFO  mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2015-02-10 20:22:49,632 INFO  mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 214 bytes
2015-02-10 20:22:49,633 INFO  mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 20:22:49,634 INFO  hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.6.3
2015-02-10 20:22:49,635 INFO  hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2015-02-10 20:22:49,651 INFO  hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:'num']]
2015-02-10 20:22:49,652 INFO  hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/test/output/hadoop2-mr1/bufferpipesplatform/identity"]
2015-02-10 20:22:49,680 INFO  mapred.Task (Task.java:done(995)) - Task:attempt_local1857576131_0001_r_000000_0 is done. And is in the process of committing
2015-02-10 20:22:49,682 INFO  mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 20:22:49,682 INFO  mapred.Task (Task.java:commit(1156)) - Task attempt_local1857576131_0001_r_000000_0 is allowed to commit now
2015-02-10 20:22:49,684 INFO  output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1857576131_0001_r_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/test/output/hadoop2-mr1/bufferpipesplatform/identity/_temporary/0/task_local1857576131_0001_r_000000
2015-02-10 20:22:49,685 INFO  mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2015-02-10 20:22:49,685 INFO  mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1857576131_0001_r_000000_0' done.
2015-02-10 20:22:49,686 INFO  mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1857576131_0001_r_000000_0
2015-02-10 20:22:49,686 INFO  mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2015-02-10 20:22:49,732 INFO  util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/test/output/hadoop2-mr1/bufferpipesplatform/identity/_temporary
2015-02-10 20:22:49,774 INFO  mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2015-02-10 20:22:49,817 INFO  mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2015-02-10 20:22:49,820 INFO  cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/test/output//hadoop2-mr1/bufferpipesplatform/identity
2015-02-10 20:22:49,853 INFO  util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 20:22:49,853 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.6.3/9ae016e2b8d246b9c1de9168e715d9f1b971aa4a/cascading-hadoop2-mr1-2.6.3.jar
2015-02-10 20:22:49,873 INFO  Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 20:22:49,879 INFO  Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 20:22:49,880 INFO  Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 20:22:49,895 INFO  flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting
2015-02-10 20:22:49,896 INFO  flow.Flow (BaseFlow.java:logInfo(1378)) - [test]  source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/classes/test/data/lhs.txt"]
2015-02-10 20:22:49,897 INFO  flow.Flow (BaseFlow.java:logInfo(1378)) - [test]  sink: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/test/output/hadoop2-mr1/bufferpipesplatform/simple"]
2015-02-10 20:22:49,897 INFO  flow.Flow (BaseFlow.java:logInfo(1378)) - [test]  parallel execution is enabled: false
2015-02-10 20:22:49,898 INFO  flow.Flow (BaseFlow.java:logInfo(1378)) - [test]  starting jobs: 1
2015-02-10 20:22:49,899 INFO  flow.Flow (BaseFlow.java:logInfo(1378)) - [test]  allocating threads: 1
2015-02-10 20:22:49,900 INFO  flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...ufferpipesplatform/simple
2015-02-10 20:22:49,902 INFO  jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 20:22:49,903 INFO  jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 20:22:49,938 INFO  mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2015-02-10 20:22:49,963 INFO  mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 20:22:50,018 INFO  mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1867959527_0002
2015-02-10 20:22:50,045 WARN  conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/tmp/cascading/staging/teamcity1867959527/.staging/job_local1867959527_0002/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval;  Ignoring.
2015-02-10 20:22:50,046 WARN  conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/tmp/cascading/staging/teamcity1867959527/.staging/job_local1867959527_0002/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts;  Ignoring.
2015-02-10 20:22:50,129 WARN  conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1867959527_0002/job_local1867959527_0002.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval;  Ignoring.
2015-02-10 20:22:50,130 WARN  conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1867959527_0002/job_local1867959527_0002.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts;  Ignoring.
2015-02-10 20:22:50,132 INFO  mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 20:22:50,133 INFO  mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 20:22:50,133 INFO  mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 20:22:50,134 INFO  flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local1867959527_0002
2015-02-10 20:22:50,135 INFO  flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2015-02-10 20:22:50,138 INFO  mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 20:22:50,138 INFO  mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1867959527_0002_m_000000_0
2015-02-10 20:22:50,141 INFO  mapred.Task (Task.java:initialize(581)) -  Using ResourceCalculatorProcessTree : [ ]
2015-02-10 20:22:50,143 INFO  io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/classes/test/data/lhs.txt
2015-02-10 20:22:50,143 INFO  mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@1e883644
2015-02-10 20:22:50,145 INFO  mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-10 20:22:50,145 INFO  mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-10 20:22:50,289 INFO  mapred.MapTask (MapTask.java:setEquator(1181)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-10 20:22:50,290 INFO  mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-10 20:22:50,290 INFO  mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-10 20:22:50,290 INFO  mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-10 20:22:50,290 INFO  mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-10 20:22:50,292 INFO  hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 20:22:50,292 INFO  hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 20:22:50,305 INFO  hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/classes/test/data/lhs.txt"]
2015-02-10 20:22:50,306 INFO  hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:'num']]
2015-02-10 20:22:50,310 INFO  mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 
2015-02-10 20:22:50,310 INFO  mapred.MapTask (MapTask.java:flush(1435)) - Starting flush of map output
2015-02-10 20:22:50,311 INFO  mapred.MapTask (MapTask.java:flush(1453)) - Spilling map output
2015-02-10 20:22:50,311 INFO  mapred.MapTask (MapTask.java:flush(1454)) - bufstart = 0; bufend = 195; bufvoid = 104857600
2015-02-10 20:22:50,311 INFO  mapred.MapTask (MapTask.java:flush(1456)) - kvstart = 26214396(104857584); kvend = 26214348(104857392); length = 49/6553600
2015-02-10 20:22:50,316 INFO  mapred.MapTask (MapTask.java:sortAndSpill(1639)) - Finished spill 0
2015-02-10 20:22:50,320 INFO  mapred.Task (Task.java:done(995)) - Task:attempt_local1867959527_0002_m_000000_0 is done. And is in the process of committing
2015-02-10 20:22:50,322 INFO  mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/classes/test/data/lhs.txt:0+52
2015-02-10 20:22:50,323 INFO  mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1867959527_0002_m_000000_0' done.
2015-02-10 20:22:50,323 INFO  mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1867959527_0002_m_000000_0
2015-02-10 20:22:50,323 INFO  mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 20:22:50,324 INFO  mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2015-02-10 20:22:50,324 INFO  mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1867959527_0002_r_000000_0
2015-02-10 20:22:50,327 INFO  mapred.Task (Task.java:initialize(581)) -  Using ResourceCalculatorProcessTree : [ ]
2015-02-10 20:22:50,327 INFO  mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@2d58497c
2015-02-10 20:22:50,328 INFO  reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2015-02-10 20:22:50,329 INFO  reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1867959527_0002_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2015-02-10 20:22:50,332 INFO  reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#2 about to shuffle output of map attempt_local1867959527_0002_m_000000_0 decomp: 223 len: 227 to MEMORY
2015-02-10 20:22:50,369 INFO  reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 223 bytes from map-output for attempt_local1867959527_0002_m_000000_0
2015-02-10 20:22:50,370 INFO  reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 223, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->223
2015-02-10 20:22:50,370 INFO  reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2015-02-10 20:22:50,372 INFO  mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 20:22:50,372 INFO  reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2015-02-10 20:22:50,375 INFO  mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2015-02-10 20:22:50,376 INFO  mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 214 bytes
2015-02-10 20:22:50,378 INFO  reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 223 bytes to disk to satisfy reduce memory limit
2015-02-10 20:22:50,379 INFO  reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 227 bytes from disk
2015-02-10 20:22:50,379 INFO  reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2015-02-10 20:22:50,379 INFO  mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2015-02-10 20:22:50,380 INFO  mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 214 bytes
2015-02-10 20:22:50,380 INFO  mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 20:22:50,381 INFO  hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.6.3
2015-02-10 20:22:50,382 INFO  hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2015-02-10 20:22:50,394 INFO  hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:'num']]
2015-02-10 20:22:50,394 INFO  hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/test/output/hadoop2-mr1/bufferpipesplatform/simple"]
2015-02-10 20:22:50,410 INFO  mapred.Task (Task.java:done(995)) - Task:attempt_local1867959527_0002_r_000000_0 is done. And is in the process of committing
2015-02-10 20:22:50,412 INFO  mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 20:22:50,413 INFO  mapred.Task (Task.java:commit(1156)) - Task attempt_local1867959527_0002_r_000000_0 is allowed to commit now
2015-02-10 20:22:50,414 INFO  output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1867959527_0002_r_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/test/output/hadoop2-mr1/bufferpipesplatform/simple/_temporary/0/task_local1867959527_0002_r_000000
2015-02-10 20:22:50,415 INFO  mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2015-02-10 20:22:50,415 INFO  mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1867959527_0002_r_000000_0' done.
2015-02-10 20:22:50,416 INFO  mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1867959527_0002_r_000000_0
2015-02-10 20:22:50,416 INFO  mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2015-02-10 20:22:50,441 INFO  util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/test/output/hadoop2-mr1/bufferpipesplatform/simple/_temporary
2015-02-10 20:22:50,487 INFO  mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2015-02-10 20:22:50,546 INFO  mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2015-02-10 20:22:50,550 INFO  cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/test/output//hadoop2-mr1/bufferpipesplatform/simple
2015-02-10 20:22:50,584 INFO  util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 20:22:50,584 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.6.3/9ae016e2b8d246b9c1de9168e715d9f1b971aa4a/cascading-hadoop2-mr1-2.6.3.jar
2015-02-10 20:22:50,608 INFO  Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 20:22:50,617 INFO  Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 20:22:50,618 INFO  Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 20:22:50,636 INFO  flow.Flow (BaseFlow.java:logInfo(1378)) - [lower*upper] starting
2015-02-10 20:22:50,637 INFO  flow.Flow (BaseFlow.java:logInfo(1378)) - [lower*upper]  source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/classes/test/data/upper.txt"]
2015-02-10 20:22:50,637 INFO  flow.Flow (BaseFlow.java:logInfo(1378)) - [lower*upper]  source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/classes/test/data/lower.txt"]
2015-02-10 20:22:50,637 INFO  flow.Flow (BaseFlow.java:logInfo(1378)) - [lower*upper]  sink: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/test/output/hadoop2-mr1/bufferpipesplatform/cogroup"]
2015-02-10 20:22:50,638 INFO  flow.Flow (BaseFlow.java:logInfo(1378)) - [lower*upper]  parallel execution is enabled: false
2015-02-10 20:22:50,638 INFO  flow.Flow (BaseFlow.java:logInfo(1378)) - [lower*upper]  starting jobs: 1
2015-02-10 20:22:50,638 INFO  flow.Flow (BaseFlow.java:logInfo(1378)) - [lower*upper]  allocating threads: 1
2015-02-10 20:22:50,639 INFO  flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [lower*upper] starting step: (1/1) ...fferpipesplatform/cogroup
2015-02-10 20:22:50,640 INFO  jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 20:22:50,641 INFO  jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 20:22:50,679 INFO  mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2015-02-10 20:22:50,682 INFO  mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2015-02-10 20:22:50,707 INFO  mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:2
2015-02-10 20:22:50,749 INFO  mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local212848937_0003
2015-02-10 20:22:50,776 WARN  conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/tmp/cascading/staging/teamcity212848937/.staging/job_local212848937_0003/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval;  Ignoring.
2015-02-10 20:22:50,776 WARN  conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/tmp/cascading/staging/teamcity212848937/.staging/job_local212848937_0003/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts;  Ignoring.
2015-02-10 20:22:50,868 WARN  conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local212848937_0003/job_local212848937_0003.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval;  Ignoring.
2015-02-10 20:22:50,868 WARN  conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local212848937_0003/job_local212848937_0003.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts;  Ignoring.
2015-02-10 20:22:50,870 INFO  mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 20:22:50,870 INFO  flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [lower*upper] submitted hadoop job: job_local212848937_0003
2015-02-10 20:22:50,870 INFO  flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [lower*upper] tracking url: http://localhost:8080/
2015-02-10 20:22:50,872 INFO  mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 20:22:50,872 INFO  mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 20:22:50,878 INFO  mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 20:22:50,878 INFO  mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local212848937_0003_m_000000_0
2015-02-10 20:22:50,881 INFO  mapred.Task (Task.java:initialize(581)) -  Using ResourceCalculatorProcessTree : [ ]
2015-02-10 20:22:50,883 INFO  io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/classes/test/data/lower.txt
2015-02-10 20:22:50,883 INFO  mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@11e3c2c6
2015-02-10 20:22:50,885 INFO  mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-10 20:22:50,886 INFO  mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-10 20:22:51,029 INFO  mapred.MapTask (MapTask.java:setEquator(1181)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-10 20:22:51,029 INFO  mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-10 20:22:51,029 INFO  mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-10 20:22:51,030 INFO  mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-10 20:22:51,030 INFO  mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-10 20:22:51,032 INFO  hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 20:22:51,033 INFO  hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 20:22:51,047 INFO  hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/classes/test/data/lower.txt"]
2015-02-10 20:22:51,047 INFO  hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: CoGroup(lower*upper)[by: lower:[{1}:'num'] upper:[{1}:'num']]
2015-02-10 20:22:51,050 INFO  mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 
2015-02-10 20:22:51,051 INFO  mapred.MapTask (MapTask.java:flush(1435)) - Starting flush of map output
2015-02-10 20:22:51,051 INFO  mapred.MapTask (MapTask.java:flush(1453)) - Spilling map output
2015-02-10 20:22:51,051 INFO  mapred.MapTask (MapTask.java:flush(1454)) - bufstart = 0; bufend = 85; bufvoid = 104857600
2015-02-10 20:22:51,051 INFO  mapred.MapTask (MapTask.java:flush(1456)) - kvstart = 26214396(104857584); kvend = 26214380(104857520); length = 17/6553600
2015-02-10 20:22:51,055 INFO  mapred.MapTask (MapTask.java:sortAndSpill(1639)) - Finished spill 0
2015-02-10 20:22:51,058 INFO  mapred.Task (Task.java:done(995)) - Task:attempt_local212848937_0003_m_000000_0 is done. And is in the process of committing
2015-02-10 20:22:51,061 INFO  mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/classes/test/data/lower.txt:0+19
2015-02-10 20:22:51,061 INFO  mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local212848937_0003_m_000000_0' done.
2015-02-10 20:22:51,061 INFO  mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local212848937_0003_m_000000_0
2015-02-10 20:22:51,061 INFO  mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local212848937_0003_m_000001_0
2015-02-10 20:22:51,064 INFO  mapred.Task (Task.java:initialize(581)) -  Using ResourceCalculatorProcessTree : [ ]
2015-02-10 20:22:51,067 INFO  io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/classes/test/data/upper.txt
2015-02-10 20:22:51,067 INFO  mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@3e7c609
2015-02-10 20:22:51,069 INFO  mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-10 20:22:51,069 INFO  mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-10 20:22:51,212 INFO  mapred.MapTask (MapTask.java:setEquator(1181)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-10 20:22:51,212 INFO  mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-10 20:22:51,213 INFO  mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-10 20:22:51,213 INFO  mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-10 20:22:51,213 INFO  mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-10 20:22:51,216 INFO  hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 20:22:51,216 INFO  hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 20:22:51,229 INFO  hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/classes/test/data/upper.txt"]
2015-02-10 20:22:51,229 INFO  hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: CoGroup(lower*upper)[by: lower:[{1}:'num'] upper:[{1}:'num']]
2015-02-10 20:22:51,232 INFO  mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 
2015-02-10 20:22:51,233 INFO  mapred.MapTask (MapTask.java:flush(1435)) - Starting flush of map output
2015-02-10 20:22:51,233 INFO  mapred.MapTask (MapTask.java:flush(1453)) - Spilling map output
2015-02-10 20:22:51,233 INFO  mapred.MapTask (MapTask.java:flush(1454)) - bufstart = 0; bufend = 85; bufvoid = 104857600
2015-02-10 20:22:51,233 INFO  mapred.MapTask (MapTask.java:flush(1456)) - kvstart = 26214396(104857584); kvend = 26214380(104857520); length = 17/6553600
2015-02-10 20:22:51,237 INFO  mapred.MapTask (MapTask.java:sortAndSpill(1639)) - Finished spill 0
2015-02-10 20:22:51,240 INFO  mapred.Task (Task.java:done(995)) - Task:attempt_local212848937_0003_m_000001_0 is done. And is in the process of committing
2015-02-10 20:22:51,243 INFO  mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/classes/test/data/upper.txt:0+19
2015-02-10 20:22:51,243 INFO  mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local212848937_0003_m_000001_0' done.
2015-02-10 20:22:51,243 INFO  mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local212848937_0003_m_000001_0
2015-02-10 20:22:51,243 INFO  mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 20:22:51,244 INFO  mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2015-02-10 20:22:51,244 INFO  mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local212848937_0003_r_000000_0
2015-02-10 20:22:51,247 INFO  mapred.Task (Task.java:initialize(581)) -  Using ResourceCalculatorProcessTree : [ ]
2015-02-10 20:22:51,247 INFO  mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@69c5a33b
2015-02-10 20:22:51,248 INFO  reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2015-02-10 20:22:51,249 INFO  reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local212848937_0003_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2015-02-10 20:22:51,253 INFO  reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#3 about to shuffle output of map attempt_local212848937_0003_m_000000_0 decomp: 97 len: 101 to MEMORY
2015-02-10 20:22:51,253 INFO  reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 97 bytes from map-output for attempt_local212848937_0003_m_000000_0
2015-02-10 20:22:51,254 INFO  reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 97, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->97
2015-02-10 20:22:51,257 INFO  reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#3 about to shuffle output of map attempt_local212848937_0003_m_000001_0 decomp: 97 len: 101 to MEMORY
2015-02-10 20:22:51,258 INFO  reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 97 bytes from map-output for attempt_local212848937_0003_m_000001_0
2015-02-10 20:22:51,258 INFO  reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 97, inMemoryMapOutputs.size() -> 2, commitMemory -> 97, usedMemory ->194
2015-02-10 20:22:51,258 INFO  reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2015-02-10 20:22:51,260 INFO  mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 2 / 2 copied.
2015-02-10 20:22:51,260 INFO  reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 2 in-memory map-outputs and 0 on-disk map-outputs
2015-02-10 20:22:51,263 INFO  mapred.Merger (Merger.java:merge(589)) - Merging 2 sorted segments
2015-02-10 20:22:51,263 INFO  mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 2 segments left of total size: 174 bytes
2015-02-10 20:22:51,266 INFO  reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 2 segments, 194 bytes to disk to satisfy reduce memory limit
2015-02-10 20:22:51,266 INFO  reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 196 bytes from disk
2015-02-10 20:22:51,266 INFO  reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2015-02-10 20:22:51,266 INFO  mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2015-02-10 20:22:51,267 INFO  mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 182 bytes
2015-02-10 20:22:51,268 INFO  mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 2 / 2 copied.
2015-02-10 20:22:51,268 INFO  hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.6.3
2015-02-10 20:22:51,269 INFO  hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2015-02-10 20:22:51,279 INFO  hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: CoGroup(lower*upper)[by: lower:[{1}:'num'] upper:[{1}:'num']]
2015-02-10 20:22:51,279 INFO  hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/test/output/hadoop2-mr1/bufferpipesplatform/cogroup"]
2015-02-10 20:22:51,297 INFO  collect.SpillableTupleList (SpillableTupleList.java:getCodecClass(105)) - attempting to load codec: org.apache.hadoop.io.compress.GzipCodec
2015-02-10 20:22:51,298 INFO  collect.SpillableTupleList (SpillableTupleList.java:getCodecClass(110)) - found codec: org.apache.hadoop.io.compress.GzipCodec
2015-02-10 20:22:51,306 INFO  mapred.Task (Task.java:done(995)) - Task:attempt_local212848937_0003_r_000000_0 is done. And is in the process of committing
2015-02-10 20:22:51,308 INFO  mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 2 / 2 copied.
2015-02-10 20:22:51,309 INFO  mapred.Task (Task.java:commit(1156)) - Task attempt_local212848937_0003_r_000000_0 is allowed to commit now
2015-02-10 20:22:51,310 INFO  output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local212848937_0003_r_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/test/output/hadoop2-mr1/bufferpipesplatform/cogroup/_temporary/0/task_local212848937_0003_r_000000
2015-02-10 20:22:51,312 INFO  mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2015-02-10 20:22:51,312 INFO  mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local212848937_0003_r_000000_0' done.
2015-02-10 20:22:51,313 INFO  mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local212848937_0003_r_000000_0
2015-02-10 20:22:51,313 INFO  mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2015-02-10 20:22:51,345 INFO  util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/test/output/hadoop2-mr1/bufferpipesplatform/cogroup/_temporary
2015-02-10 20:22:51,383 INFO  mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2015-02-10 20:22:51,422 INFO  mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2015-02-10 20:22:51,424 INFO  cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/test/output//hadoop2-mr1/bufferpipesplatform/cogroup
2015-02-10 20:22:51,451 INFO  util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 20:22:51,452 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.6.3/9ae016e2b8d246b9c1de9168e715d9f1b971aa4a/cascading-hadoop2-mr1-2.6.3.jar
2015-02-10 20:22:51,467 INFO  Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 20:22:51,472 INFO  Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 20:22:51,473 INFO  Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 20:22:51,483 INFO  flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting
2015-02-10 20:22:51,483 INFO  flow.Flow (BaseFlow.java:logInfo(1378)) - [test]  source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/classes/test/data/lhs.txt"]
2015-02-10 20:22:51,483 INFO  flow.Flow (BaseFlow.java:logInfo(1378)) - [test]  sink: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/test/output/hadoop2-mr1/bufferpipesplatform/simple2"]
2015-02-10 20:22:51,484 INFO  flow.Flow (BaseFlow.java:logInfo(1378)) - [test]  parallel execution is enabled: false
2015-02-10 20:22:51,484 INFO  flow.Flow (BaseFlow.java:logInfo(1378)) - [test]  starting jobs: 1
2015-02-10 20:22:51,484 INFO  flow.Flow (BaseFlow.java:logInfo(1378)) - [test]  allocating threads: 1
2015-02-10 20:22:51,485 INFO  flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...fferpipesplatform/simple2
2015-02-10 20:22:51,486 INFO  jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 20:22:51,487 INFO  jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 20:22:51,531 INFO  mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2015-02-10 20:22:51,553 INFO  mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 20:22:51,572 INFO  mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local224075379_0004
2015-02-10 20:22:51,595 WARN  conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/tmp/cascading/staging/teamcity224075379/.staging/job_local224075379_0004/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval;  Ignoring.
2015-02-10 20:22:51,595 WARN  conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/tmp/cascading/staging/teamcity224075379/.staging/job_local224075379_0004/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts;  Ignoring.
2015-02-10 20:22:51,654 WARN  conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local224075379_0004/job_local224075379_0004.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval;  Ignoring.
2015-02-10 20:22:51,654 WARN  conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local224075379_0004/job_local224075379_0004.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts;  Ignoring.
2015-02-10 20:22:51,655 INFO  mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 20:22:51,656 INFO  flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local224075379_0004
2015-02-10 20:22:51,656 INFO  mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 20:22:51,656 INFO  flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2015-02-10 20:22:51,656 INFO  mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 20:22:51,661 INFO  mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 20:22:51,661 INFO  mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local224075379_0004_m_000000_0
2015-02-10 20:22:51,663 INFO  mapred.Task (Task.java:initialize(581)) -  Using ResourceCalculatorProcessTree : [ ]
2015-02-10 20:22:51,665 INFO  io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/classes/test/data/lhs.txt
2015-02-10 20:22:51,665 INFO  mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@5262667
2015-02-10 20:22:51,667 INFO  mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-10 20:22:51,668 INFO  mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-10 20:22:51,810 INFO  mapred.MapTask (MapTask.java:setEquator(1181)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-10 20:22:51,810 INFO  mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-10 20:22:51,810 INFO  mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-10 20:22:51,811 INFO  mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-10 20:22:51,811 INFO  mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-10 20:22:51,812 INFO  hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 20:22:51,812 INFO  hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 20:22:51,823 INFO  hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/classes/test/data/lhs.txt"]
2015-02-10 20:22:51,823 INFO  hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:'num']]
2015-02-10 20:22:51,827 INFO  mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 
2015-02-10 20:22:51,827 INFO  mapred.MapTask (MapTask.java:flush(1435)) - Starting flush of map output
2015-02-10 20:22:51,828 INFO  mapred.MapTask (MapTask.java:flush(1453)) - Spilling map output
2015-02-10 20:22:51,828 INFO  mapred.MapTask (MapTask.java:flush(1454)) - bufstart = 0; bufend = 195; bufvoid = 104857600
2015-02-10 20:22:51,828 INFO  mapred.MapTask (MapTask.java:flush(1456)) - kvstart = 26214396(104857584); kvend = 26214348(104857392); length = 49/6553600
2015-02-10 20:22:51,832 INFO  mapred.MapTask (MapTask.java:sortAndSpill(1639)) - Finished spill 0
2015-02-10 20:22:51,835 INFO  mapred.Task (Task.java:done(995)) - Task:attempt_local224075379_0004_m_000000_0 is done. And is in the process of committing
2015-02-10 20:22:51,838 INFO  mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/classes/test/data/lhs.txt:0+52
2015-02-10 20:22:51,838 INFO  mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local224075379_0004_m_000000_0' done.
2015-02-10 20:22:51,838 INFO  mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local224075379_0004_m_000000_0
2015-02-10 20:22:51,838 INFO  mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 20:22:51,839 INFO  mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2015-02-10 20:22:51,839 INFO  mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local224075379_0004_r_000000_0
2015-02-10 20:22:51,842 INFO  mapred.Task (Task.java:initialize(581)) -  Using ResourceCalculatorProcessTree : [ ]
2015-02-10 20:22:51,842 INFO  mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@12133926
2015-02-10 20:22:51,843 INFO  reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2015-02-10 20:22:51,844 INFO  reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local224075379_0004_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2015-02-10 20:22:51,846 INFO  reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#4 about to shuffle output of map attempt_local224075379_0004_m_000000_0 decomp: 223 len: 227 to MEMORY
2015-02-10 20:22:51,847 INFO  reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 223 bytes from map-output for attempt_local224075379_0004_m_000000_0
2015-02-10 20:22:51,847 INFO  reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 223, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->223
2015-02-10 20:22:51,848 INFO  reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2015-02-10 20:22:51,849 INFO  mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 20:22:51,849 INFO  reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2015-02-10 20:22:51,852 INFO  mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2015-02-10 20:22:51,852 INFO  mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 214 bytes
2015-02-10 20:22:51,854 INFO  reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 223 bytes to disk to satisfy reduce memory limit
2015-02-10 20:22:51,855 INFO  reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 227 bytes from disk
2015-02-10 20:22:51,855 INFO  reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2015-02-10 20:22:51,855 INFO  mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2015-02-10 20:22:51,855 INFO  mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 214 bytes
2015-02-10 20:22:51,856 INFO  mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 20:22:51,857 INFO  hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.6.3
2015-02-10 20:22:51,857 INFO  hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2015-02-10 20:22:51,867 INFO  hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:'num']]
2015-02-10 20:22:51,867 INFO  hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/test/output/hadoop2-mr1/bufferpipesplatform/simple2"]
2015-02-10 20:22:51,881 INFO  mapred.Task (Task.java:done(995)) - Task:attempt_local224075379_0004_r_000000_0 is done. And is in the process of committing
2015-02-10 20:22:51,883 INFO  mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 20:22:51,883 INFO  mapred.Task (Task.java:commit(1156)) - Task attempt_local224075379_0004_r_000000_0 is allowed to commit now
2015-02-10 20:22:51,884 INFO  output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local224075379_0004_r_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/test/output/hadoop2-mr1/bufferpipesplatform/simple2/_temporary/0/task_local224075379_0004_r_000000
2015-02-10 20:22:51,886 INFO  mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2015-02-10 20:22:51,886 INFO  mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local224075379_0004_r_000000_0' done.
2015-02-10 20:22:51,886 INFO  mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local224075379_0004_r_000000_0
2015-02-10 20:22:51,887 INFO  mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2015-02-10 20:22:51,910 INFO  util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/test/output/hadoop2-mr1/bufferpipesplatform/simple2/_temporary
2015-02-10 20:22:51,945 INFO  mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2015-02-10 20:22:51,984 INFO  mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2015-02-10 20:22:51,987 INFO  cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/test/output//hadoop2-mr1/bufferpipesplatform/simple2
2015-02-10 20:22:52,016 INFO  util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 20:22:52,017 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.6.3/9ae016e2b8d246b9c1de9168e715d9f1b971aa4a/cascading-hadoop2-mr1-2.6.3.jar
2015-02-10 20:22:52,032 INFO  Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 20:22:52,036 INFO  Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 20:22:52,037 INFO  Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 20:22:52,046 INFO  flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting
2015-02-10 20:22:52,047 INFO  flow.Flow (BaseFlow.java:logInfo(1378)) - [test]  source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/classes/test/data/lower+upper.txt"]
2015-02-10 20:22:52,047 INFO  flow.Flow (BaseFlow.java:logInfo(1378)) - [test]  sink: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/test/output/hadoop2-mr1/bufferpipesplatform/simple3"]
2015-02-10 20:22:52,048 INFO  flow.Flow (BaseFlow.java:logInfo(1378)) - [test]  parallel execution is enabled: false
2015-02-10 20:22:52,048 INFO  flow.Flow (BaseFlow.java:logInfo(1378)) - [test]  starting jobs: 1
2015-02-10 20:22:52,048 INFO  flow.Flow (BaseFlow.java:logInfo(1378)) - [test]  allocating threads: 1
2015-02-10 20:22:52,049 INFO  flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...fferpipesplatform/simple3
2015-02-10 20:22:52,050 INFO  jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 20:22:52,052 INFO  jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 20:22:52,083 INFO  mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2015-02-10 20:22:52,105 INFO  mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 20:22:52,411 INFO  mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1590671927_0005
2015-02-10 20:22:52,435 WARN  conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/tmp/cascading/staging/teamcity1590671927/.staging/job_local1590671927_0005/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval;  Ignoring.
2015-02-10 20:22:52,436 WARN  conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/tmp/cascading/staging/teamcity1590671927/.staging/job_local1590671927_0005/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts;  Ignoring.
2015-02-10 20:22:52,498 WARN  conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1590671927_0005/job_local1590671927_0005.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval;  Ignoring.
2015-02-10 20:22:52,499 WARN  conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1590671927_0005/job_local1590671927_0005.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts;  Ignoring.
2015-02-10 20:22:52,500 INFO  mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 20:22:52,500 INFO  flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local1590671927_0005
2015-02-10 20:22:52,500 INFO  mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 20:22:52,500 INFO  flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2015-02-10 20:22:52,501 INFO  mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 20:22:52,505 INFO  mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 20:22:52,505 INFO  mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1590671927_0005_m_000000_0
2015-02-10 20:22:52,507 INFO  mapred.Task (Task.java:initialize(581)) -  Using ResourceCalculatorProcessTree : [ ]
2015-02-10 20:22:52,509 INFO  io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/classes/test/data/lower+upper.txt
2015-02-10 20:22:52,509 INFO  mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@6fb9658e
2015-02-10 20:22:52,511 INFO  mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-10 20:22:52,511 INFO  mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-10 20:22:52,580 INFO  mapred.MapTask (MapTask.java:setEquator(1181)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-10 20:22:52,580 INFO  mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-10 20:22:52,580 INFO  mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-10 20:22:52,580 INFO  mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-10 20:22:52,580 INFO  mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-10 20:22:52,583 INFO  hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 20:22:52,584 INFO  hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 20:22:52,594 INFO  hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/classes/test/data/lower+upper.txt"]
2015-02-10 20:22:52,595 INFO  hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:'num']]
2015-02-10 20:22:52,598 INFO  mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 
2015-02-10 20:22:52,598 INFO  mapred.MapTask (MapTask.java:flush(1435)) - Starting flush of map output
2015-02-10 20:22:52,598 INFO  mapred.MapTask (MapTask.java:flush(1453)) - Spilling map output
2015-02-10 20:22:52,599 INFO  mapred.MapTask (MapTask.java:flush(1454)) - bufstart = 0; bufend = 105; bufvoid = 104857600
2015-02-10 20:22:52,599 INFO  mapred.MapTask (MapTask.java:flush(1456)) - kvstart = 26214396(104857584); kvend = 26214380(104857520); length = 17/6553600
2015-02-10 20:22:52,603 INFO  mapred.MapTask (MapTask.java:sortAndSpill(1639)) - Finished spill 0
2015-02-10 20:22:52,606 INFO  mapred.Task (Task.java:done(995)) - Task:attempt_local1590671927_0005_m_000000_0 is done. And is in the process of committing
2015-02-10 20:22:52,609 INFO  mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/classes/test/data/lower+upper.txt:0+30
2015-02-10 20:22:52,609 INFO  mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1590671927_0005_m_000000_0' done.
2015-02-10 20:22:52,610 INFO  mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1590671927_0005_m_000000_0
2015-02-10 20:22:52,610 INFO  mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 20:22:52,611 INFO  mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2015-02-10 20:22:52,611 INFO  mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1590671927_0005_r_000000_0
2015-02-10 20:22:52,613 INFO  mapred.Task (Task.java:initialize(581)) -  Using ResourceCalculatorProcessTree : [ ]
2015-02-10 20:22:52,613 INFO  mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@6c5c90f6
2015-02-10 20:22:52,614 INFO  reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2015-02-10 20:22:52,615 INFO  reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1590671927_0005_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2015-02-10 20:22:52,617 INFO  reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#5 about to shuffle output of map attempt_local1590671927_0005_m_000000_0 decomp: 117 len: 121 to MEMORY
2015-02-10 20:22:52,618 INFO  reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 117 bytes from map-output for attempt_local1590671927_0005_m_000000_0
2015-02-10 20:22:52,618 INFO  reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 117, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->117
2015-02-10 20:22:52,619 INFO  reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2015-02-10 20:22:52,620 INFO  mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 20:22:52,620 INFO  reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2015-02-10 20:22:52,624 INFO  mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2015-02-10 20:22:52,624 INFO  mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 108 bytes
2015-02-10 20:22:52,626 INFO  reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 117 bytes to disk to satisfy reduce memory limit
2015-02-10 20:22:52,626 INFO  reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 121 bytes from disk
2015-02-10 20:22:52,627 INFO  reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2015-02-10 20:22:52,627 INFO  mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2015-02-10 20:22:52,627 INFO  mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 108 bytes
2015-02-10 20:22:52,628 INFO  mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 20:22:52,628 INFO  hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.6.3
2015-02-10 20:22:52,629 INFO  hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2015-02-10 20:22:52,638 INFO  hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:'num']]
2015-02-10 20:22:52,639 INFO  hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/test/output/hadoop2-mr1/bufferpipesplatform/simple3"]
2015-02-10 20:22:52,651 INFO  mapred.Task (Task.java:done(995)) - Task:attempt_local1590671927_0005_r_000000_0 is done. And is in the process of committing
2015-02-10 20:22:52,653 INFO  mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 20:22:52,654 INFO  mapred.Task (Task.java:commit(1156)) - Task attempt_local1590671927_0005_r_000000_0 is allowed to commit now
2015-02-10 20:22:52,655 INFO  output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1590671927_0005_r_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/test/output/hadoop2-mr1/bufferpipesplatform/simple3/_temporary/0/task_local1590671927_0005_r_000000
2015-02-10 20:22:52,657 INFO  mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2015-02-10 20:22:52,658 INFO  mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1590671927_0005_r_000000_0' done.
2015-02-10 20:22:52,658 INFO  mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1590671927_0005_r_000000_0
2015-02-10 20:22:52,659 INFO  mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2015-02-10 20:22:52,682 INFO  util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/test/output/hadoop2-mr1/bufferpipesplatform/simple3/_temporary
2015-02-10 20:22:52,715 INFO  mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2015-02-10 20:22:52,750 INFO  mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2015-02-10 20:22:52,752 INFO  cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.3.x/build/test/output//hadoop2-mr1/bufferpipesplatform/simple3
2015-02-10 20:22:52,777 INFO  util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 20:22:52,778 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.6.3/9ae016e2b8d246b9c1de9168e715d9f1b971aa4a/cascading-hadoop2-mr1-2.6.3.jar