2014-08-22 20:56:17,031 INFO platform.PlatformRunner (PlatformRunner.java:getPlatformClassesFromClasspath(187)) - found 1 test platforms from classpath
2014-08-22 20:56:17,094 INFO platform.PlatformRunner (PlatformRunner.java:addPlatform(237)) - installing platform: hadoop2-mr1
2014-08-22 20:56:17,094 INFO platform.PlatformRunner (PlatformRunner.java:addPlatform(238)) - running test: cascading.BufferPipesPlatformTest
2014-08-22 20:56:17,123 INFO hadoop2.Hadoop2MR1Platform (Hadoop2MR1Platform.java:setUp(106)) - not using cluster
2014-08-22 20:56:17,752 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 20:56:18,036 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 20:56:18,038 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 20:56:18,051 INFO property.AppProps (AppProps.java:getAppID(162)) - using app.id: 37461C3072BE4F128C44D05C0F5E3146
2014-08-22 20:56:18,128 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 20:56:18,166 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 20:56:18,169 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 20:56:18,291 INFO util.Version (Version.java:printBanner(78)) - Concurrent, Inc - Cascading 2.5.6
2014-08-22 20:56:18,294 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting
2014-08-22 20:56:18,295 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/lhs.txt"]
2014-08-22 20:56:18,296 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] sink: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/bufferpipesplatform/identity"]
2014-08-22 20:56:18,297 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] parallel execution is enabled: false
2014-08-22 20:56:18,299 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting jobs: 1
2014-08-22 20:56:18,299 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] allocating threads: 1
2014-08-22 20:56:18,301 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...ferpipesplatform/identity
2014-08-22 20:56:18,329 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - session.id is deprecated. Instead, use dfs.metrics.session-id
2014-08-22 20:56:18,332 INFO jvm.JvmMetrics (JvmMetrics.java:init(76)) - Initializing JVM Metrics with processName=JobTracker, sessionId=
2014-08-22 20:56:18,359 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:56:18,739 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:56:18,782 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 20:56:18,942 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1982688717_0001
2014-08-22 20:56:18,983 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity1982688717/.staging/job_local1982688717_0001/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:56:18,984 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity1982688717/.staging/job_local1982688717_0001/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:56:19,166 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1982688717_0001/job_local1982688717_0001.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:56:19,167 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1982688717_0001/job_local1982688717_0001.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:56:19,174 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 20:56:19,176 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 20:56:19,177 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local1982688717_0001
2014-08-22 20:56:19,177 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2014-08-22 20:56:19,180 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 20:56:19,248 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 20:56:19,253 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1982688717_0001_m_000000_0
2014-08-22 20:56:19,295 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:56:19,306 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/lhs.txt
2014-08-22 20:56:19,306 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@355c6c8d
2014-08-22 20:56:19,316 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 20:56:19,323 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 20:56:19,475 INFO mapred.MapTask (MapTask.java:setEquator(1181)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 20:56:19,476 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 20:56:19,477 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 20:56:19,478 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 20:56:19,478 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 20:56:19,502 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 20:56:19,502 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 20:56:19,553 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.task.partition is deprecated. Instead, use mapreduce.task.partition
2014-08-22 20:56:19,572 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/lhs.txt"]
2014-08-22 20:56:19,573 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:'num']]
2014-08-22 20:56:19,590 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 20:56:19,590 INFO mapred.MapTask (MapTask.java:flush(1435)) - Starting flush of map output
2014-08-22 20:56:19,591 INFO mapred.MapTask (MapTask.java:flush(1453)) - Spilling map output
2014-08-22 20:56:19,591 INFO mapred.MapTask (MapTask.java:flush(1454)) - bufstart = 0; bufend = 195; bufvoid = 104857600
2014-08-22 20:56:19,592 INFO mapred.MapTask (MapTask.java:flush(1456)) - kvstart = 26214396(104857584); kvend = 26214348(104857392); length = 49/6553600
2014-08-22 20:56:19,606 INFO mapred.MapTask (MapTask.java:sortAndSpill(1639)) - Finished spill 0
2014-08-22 20:56:19,611 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1982688717_0001_m_000000_0 is done. And is in the process of committing
2014-08-22 20:56:19,622 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/lhs.txt:0+52
2014-08-22 20:56:19,623 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1982688717_0001_m_000000_0' done.
2014-08-22 20:56:19,624 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1982688717_0001_m_000000_0
2014-08-22 20:56:19,624 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 20:56:19,627 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 20:56:19,628 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1982688717_0001_r_000000_0
2014-08-22 20:56:19,637 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:56:19,641 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@354124d6
2014-08-22 20:56:19,655 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 20:56:19,659 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1982688717_0001_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 20:56:19,693 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#1 about to shuffle output of map attempt_local1982688717_0001_m_000000_0 decomp: 223 len: 227 to MEMORY
2014-08-22 20:56:19,698 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 223 bytes from map-output for attempt_local1982688717_0001_m_000000_0
2014-08-22 20:56:19,745 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 223, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->223
2014-08-22 20:56:19,747 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 20:56:19,749 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:56:19,750 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 20:56:19,759 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:56:19,759 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 214 bytes
2014-08-22 20:56:19,762 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 223 bytes to disk to satisfy reduce memory limit
2014-08-22 20:56:19,763 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 227 bytes from disk
2014-08-22 20:56:19,764 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 20:56:19,764 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:56:19,765 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 214 bytes
2014-08-22 20:56:19,765 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:56:19,767 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 20:56:19,767 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 20:56:19,784 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:'num']]
2014-08-22 20:56:19,784 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/bufferpipesplatform/identity"]
2014-08-22 20:56:19,813 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1982688717_0001_r_000000_0 is done. And is in the process of committing
2014-08-22 20:56:19,815 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:56:19,815 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1982688717_0001_r_000000_0 is allowed to commit now
2014-08-22 20:56:19,816 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1982688717_0001_r_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/bufferpipesplatform/identity/_temporary/0/task_local1982688717_0001_r_000000
2014-08-22 20:56:19,818 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 20:56:19,818 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1982688717_0001_r_000000_0' done.
2014-08-22 20:56:19,818 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1982688717_0001_r_000000_0
2014-08-22 20:56:19,819 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 20:56:19,865 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/bufferpipesplatform/identity/_temporary
2014-08-22 20:56:19,906 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:56:19,946 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:56:19,949 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output//hadoop2-mr1/bufferpipesplatform/identity
2014-08-22 20:56:19,980 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 20:56:19,981 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 20:56:20,000 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 20:56:20,006 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 20:56:20,007 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 20:56:20,023 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting
2014-08-22 20:56:20,023 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/lhs.txt"]
2014-08-22 20:56:20,024 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] sink: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/bufferpipesplatform/simple"]
2014-08-22 20:56:20,024 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] parallel execution is enabled: false
2014-08-22 20:56:20,024 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting jobs: 1
2014-08-22 20:56:20,024 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] allocating threads: 1
2014-08-22 20:56:20,025 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...ufferpipesplatform/simple
2014-08-22 20:56:20,026 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:56:20,029 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:56:20,063 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:56:20,088 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 20:56:20,136 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local136823507_0002
2014-08-22 20:56:20,162 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity136823507/.staging/job_local136823507_0002/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:56:20,163 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity136823507/.staging/job_local136823507_0002/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:56:20,247 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local136823507_0002/job_local136823507_0002.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:56:20,247 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local136823507_0002/job_local136823507_0002.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:56:20,250 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 20:56:20,251 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local136823507_0002
2014-08-22 20:56:20,251 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 20:56:20,252 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 20:56:20,251 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2014-08-22 20:56:20,256 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 20:56:20,257 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local136823507_0002_m_000000_0
2014-08-22 20:56:20,260 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:56:20,263 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/lhs.txt
2014-08-22 20:56:20,263 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@9f528ab
2014-08-22 20:56:20,266 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 20:56:20,267 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 20:56:20,411 INFO mapred.MapTask (MapTask.java:setEquator(1181)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 20:56:20,412 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 20:56:20,413 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 20:56:20,413 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 20:56:20,414 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 20:56:20,416 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 20:56:20,417 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 20:56:20,431 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/lhs.txt"]
2014-08-22 20:56:20,432 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:'num']]
2014-08-22 20:56:20,437 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 20:56:20,437 INFO mapred.MapTask (MapTask.java:flush(1435)) - Starting flush of map output
2014-08-22 20:56:20,438 INFO mapred.MapTask (MapTask.java:flush(1453)) - Spilling map output
2014-08-22 20:56:20,438 INFO mapred.MapTask (MapTask.java:flush(1454)) - bufstart = 0; bufend = 195; bufvoid = 104857600
2014-08-22 20:56:20,439 INFO mapred.MapTask (MapTask.java:flush(1456)) - kvstart = 26214396(104857584); kvend = 26214348(104857392); length = 49/6553600
2014-08-22 20:56:20,445 INFO mapred.MapTask (MapTask.java:sortAndSpill(1639)) - Finished spill 0
2014-08-22 20:56:20,448 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local136823507_0002_m_000000_0 is done. And is in the process of committing
2014-08-22 20:56:20,451 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/lhs.txt:0+52
2014-08-22 20:56:20,452 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local136823507_0002_m_000000_0' done.
2014-08-22 20:56:20,453 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local136823507_0002_m_000000_0
2014-08-22 20:56:20,453 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 20:56:20,454 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 20:56:20,454 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local136823507_0002_r_000000_0
2014-08-22 20:56:20,457 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:56:20,457 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@4dc67b54
2014-08-22 20:56:20,458 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 20:56:20,460 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local136823507_0002_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 20:56:20,462 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#2 about to shuffle output of map attempt_local136823507_0002_m_000000_0 decomp: 223 len: 227 to MEMORY
2014-08-22 20:56:20,463 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 223 bytes from map-output for attempt_local136823507_0002_m_000000_0
2014-08-22 20:56:20,463 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 223, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->223
2014-08-22 20:56:20,464 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 20:56:20,466 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:56:20,466 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 20:56:20,470 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:56:20,470 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 214 bytes
2014-08-22 20:56:20,473 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 223 bytes to disk to satisfy reduce memory limit
2014-08-22 20:56:20,474 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 227 bytes from disk
2014-08-22 20:56:20,475 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 20:56:20,475 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:56:20,476 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 214 bytes
2014-08-22 20:56:20,477 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:56:20,478 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 20:56:20,479 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 20:56:20,491 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:'num']]
2014-08-22 20:56:20,492 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/bufferpipesplatform/simple"]
2014-08-22 20:56:20,509 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local136823507_0002_r_000000_0 is done. And is in the process of committing
2014-08-22 20:56:20,511 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:56:20,511 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local136823507_0002_r_000000_0 is allowed to commit now
2014-08-22 20:56:20,513 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local136823507_0002_r_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/bufferpipesplatform/simple/_temporary/0/task_local136823507_0002_r_000000
2014-08-22 20:56:20,514 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 20:56:20,515 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local136823507_0002_r_000000_0' done.
2014-08-22 20:56:20,515 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local136823507_0002_r_000000_0
2014-08-22 20:56:20,516 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 20:56:20,551 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/bufferpipesplatform/simple/_temporary
2014-08-22 20:56:20,592 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:56:20,648 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:56:20,652 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output//hadoop2-mr1/bufferpipesplatform/simple
2014-08-22 20:56:20,688 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 20:56:20,689 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 20:56:20,713 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 20:56:20,721 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 20:56:20,722 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 20:56:20,741 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [lower*upper] starting
2014-08-22 20:56:20,741 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [lower*upper] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/upper.txt"]
2014-08-22 20:56:20,742 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [lower*upper] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/lower.txt"]
2014-08-22 20:56:20,742 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [lower*upper] sink: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/bufferpipesplatform/cogroup"]
2014-08-22 20:56:20,742 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [lower*upper] parallel execution is enabled: false
2014-08-22 20:56:20,742 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [lower*upper] starting jobs: 1
2014-08-22 20:56:20,742 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [lower*upper] allocating threads: 1
2014-08-22 20:56:20,743 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [lower*upper] starting step: (1/1) ...fferpipesplatform/cogroup
2014-08-22 20:56:20,744 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:56:20,746 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:56:20,784 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:56:20,787 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:56:20,813 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:2
2014-08-22 20:56:20,854 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local2125202849_0003
2014-08-22 20:56:20,881 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity2125202849/.staging/job_local2125202849_0003/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:56:20,882 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity2125202849/.staging/job_local2125202849_0003/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:56:20,972 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local2125202849_0003/job_local2125202849_0003.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:56:20,974 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local2125202849_0003/job_local2125202849_0003.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:56:20,976 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 20:56:20,977 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 20:56:20,977 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 20:56:20,977 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [lower*upper] submitted hadoop job: job_local2125202849_0003
2014-08-22 20:56:20,978 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [lower*upper] tracking url: http://localhost:8080/
2014-08-22 20:56:20,982 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 20:56:20,982 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local2125202849_0003_m_000000_0
2014-08-22 20:56:20,985 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:56:20,987 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/lower.txt
2014-08-22 20:56:20,987 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@448be1c9
2014-08-22 20:56:20,989 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 20:56:20,990 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 20:56:21,132 INFO mapred.MapTask (MapTask.java:setEquator(1181)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 20:56:21,132 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 20:56:21,133 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 20:56:21,133 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 20:56:21,133 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 20:56:21,136 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 20:56:21,136 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 20:56:21,150 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/lower.txt"]
2014-08-22 20:56:21,150 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: CoGroup(lower*upper)[by: lower:[{1}:'num'] upper:[{1}:'num']]
2014-08-22 20:56:21,153 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 20:56:21,154 INFO mapred.MapTask (MapTask.java:flush(1435)) - Starting flush of map output
2014-08-22 20:56:21,154 INFO mapred.MapTask (MapTask.java:flush(1453)) - Spilling map output
2014-08-22 20:56:21,154 INFO mapred.MapTask (MapTask.java:flush(1454)) - bufstart = 0; bufend = 85; bufvoid = 104857600
2014-08-22 20:56:21,154 INFO mapred.MapTask (MapTask.java:flush(1456)) - kvstart = 26214396(104857584); kvend = 26214380(104857520); length = 17/6553600
2014-08-22 20:56:21,158 INFO mapred.MapTask (MapTask.java:sortAndSpill(1639)) - Finished spill 0
2014-08-22 20:56:21,161 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local2125202849_0003_m_000000_0 is done. And is in the process of committing
2014-08-22 20:56:21,163 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/lower.txt:0+19
2014-08-22 20:56:21,164 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local2125202849_0003_m_000000_0' done.
2014-08-22 20:56:21,164 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local2125202849_0003_m_000000_0
2014-08-22 20:56:21,164 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local2125202849_0003_m_000001_0
2014-08-22 20:56:21,167 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:56:21,171 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/upper.txt
2014-08-22 20:56:21,171 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@561140db
2014-08-22 20:56:21,173 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 20:56:21,173 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 20:56:21,317 INFO mapred.MapTask (MapTask.java:setEquator(1181)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 20:56:21,318 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 20:56:21,318 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 20:56:21,318 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 20:56:21,318 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 20:56:21,320 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 20:56:21,320 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 20:56:21,333 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/upper.txt"]
2014-08-22 20:56:21,333 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: CoGroup(lower*upper)[by: lower:[{1}:'num'] upper:[{1}:'num']]
2014-08-22 20:56:21,336 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 20:56:21,336 INFO mapred.MapTask (MapTask.java:flush(1435)) - Starting flush of map output
2014-08-22 20:56:21,336 INFO mapred.MapTask (MapTask.java:flush(1453)) - Spilling map output
2014-08-22 20:56:21,337 INFO mapred.MapTask (MapTask.java:flush(1454)) - bufstart = 0; bufend = 85; bufvoid = 104857600
2014-08-22 20:56:21,337 INFO mapred.MapTask (MapTask.java:flush(1456)) - kvstart = 26214396(104857584); kvend = 26214380(104857520); length = 17/6553600
2014-08-22 20:56:21,341 INFO mapred.MapTask (MapTask.java:sortAndSpill(1639)) - Finished spill 0
2014-08-22 20:56:21,343 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local2125202849_0003_m_000001_0 is done. And is in the process of committing
2014-08-22 20:56:21,346 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/upper.txt:0+19
2014-08-22 20:56:21,346 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local2125202849_0003_m_000001_0' done.
2014-08-22 20:56:21,347 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local2125202849_0003_m_000001_0
2014-08-22 20:56:21,347 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 20:56:21,347 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 20:56:21,348 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local2125202849_0003_r_000000_0
2014-08-22 20:56:21,350 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:56:21,351 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@5637dde9
2014-08-22 20:56:21,351 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 20:56:21,352 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local2125202849_0003_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 20:56:21,354 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#3 about to shuffle output of map attempt_local2125202849_0003_m_000001_0 decomp: 97 len: 101 to MEMORY
2014-08-22 20:56:21,355 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 97 bytes from map-output for attempt_local2125202849_0003_m_000001_0
2014-08-22 20:56:21,355 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 97, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->97
2014-08-22 20:56:21,358 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#3 about to shuffle output of map attempt_local2125202849_0003_m_000000_0 decomp: 97 len: 101 to MEMORY
2014-08-22 20:56:21,359 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 97 bytes from map-output for attempt_local2125202849_0003_m_000000_0
2014-08-22 20:56:21,359 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 97, inMemoryMapOutputs.size() -> 2, commitMemory -> 97, usedMemory ->194
2014-08-22 20:56:21,360 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 20:56:21,361 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 2 / 2 copied.
2014-08-22 20:56:21,361 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 2 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 20:56:21,364 INFO mapred.Merger (Merger.java:merge(589)) - Merging 2 sorted segments
2014-08-22 20:56:21,364 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 20:56:21,367 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 2 segments, 194 bytes to disk to satisfy reduce memory limit
2014-08-22 20:56:21,367 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 196 bytes from disk
2014-08-22 20:56:21,367 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 20:56:21,367 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:56:21,368 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 20:56:21,369 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 2 / 2 copied.
2014-08-22 20:56:21,369 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 20:56:21,370 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 20:56:21,380 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: CoGroup(lower*upper)[by: lower:[{1}:'num'] upper:[{1}:'num']]
2014-08-22 20:56:21,380 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/bufferpipesplatform/cogroup"]
2014-08-22 20:56:21,398 INFO collect.SpillableTupleList (SpillableTupleList.java:getCodecClass(105)) - attempting to load codec: org.apache.hadoop.io.compress.GzipCodec
2014-08-22 20:56:21,398 INFO collect.SpillableTupleList (SpillableTupleList.java:getCodecClass(110)) - found codec: org.apache.hadoop.io.compress.GzipCodec
2014-08-22 20:56:21,406 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local2125202849_0003_r_000000_0 is done. And is in the process of committing
2014-08-22 20:56:21,408 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 2 / 2 copied.
2014-08-22 20:56:21,409 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local2125202849_0003_r_000000_0 is allowed to commit now
2014-08-22 20:56:21,410 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local2125202849_0003_r_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/bufferpipesplatform/cogroup/_temporary/0/task_local2125202849_0003_r_000000
2014-08-22 20:56:21,412 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 20:56:21,413 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local2125202849_0003_r_000000_0' done.
2014-08-22 20:56:21,413 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local2125202849_0003_r_000000_0
2014-08-22 20:56:21,413 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 20:56:21,453 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/bufferpipesplatform/cogroup/_temporary
2014-08-22 20:56:21,489 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:56:21,528 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:56:21,531 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output//hadoop2-mr1/bufferpipesplatform/cogroup
2014-08-22 20:56:21,556 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 20:56:21,556 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 20:56:21,571 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 20:56:21,576 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 20:56:21,576 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 20:56:21,586 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting
2014-08-22 20:56:21,586 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/lhs.txt"]
2014-08-22 20:56:21,587 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] sink: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/bufferpipesplatform/simple2"]
2014-08-22 20:56:21,587 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] parallel execution is enabled: false
2014-08-22 20:56:21,587 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting jobs: 1
2014-08-22 20:56:21,587 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] allocating threads: 1
2014-08-22 20:56:21,588 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...fferpipesplatform/simple2
2014-08-22 20:56:21,589 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:56:21,591 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:56:21,625 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:56:21,657 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 20:56:21,678 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local415796366_0004
2014-08-22 20:56:21,701 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity415796366/.staging/job_local415796366_0004/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:56:21,701 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity415796366/.staging/job_local415796366_0004/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:56:21,762 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local415796366_0004/job_local415796366_0004.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:56:21,763 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local415796366_0004/job_local415796366_0004.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:56:21,764 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 20:56:21,764 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local415796366_0004
2014-08-22 20:56:21,765 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 20:56:21,765 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2014-08-22 20:56:21,765 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 20:56:21,769 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 20:56:21,770 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local415796366_0004_m_000000_0
2014-08-22 20:56:21,773 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:56:21,775 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/lhs.txt
2014-08-22 20:56:21,775 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@6bd3e069
2014-08-22 20:56:21,778 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 20:56:21,778 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 20:56:21,919 INFO mapred.MapTask (MapTask.java:setEquator(1181)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 20:56:21,920 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 20:56:21,920 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 20:56:21,921 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 20:56:21,921 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 20:56:21,923 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 20:56:21,924 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 20:56:21,934 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/lhs.txt"]
2014-08-22 20:56:21,935 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:'num']]
2014-08-22 20:56:21,939 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 20:56:21,940 INFO mapred.MapTask (MapTask.java:flush(1435)) - Starting flush of map output
2014-08-22 20:56:21,940 INFO mapred.MapTask (MapTask.java:flush(1453)) - Spilling map output
2014-08-22 20:56:21,941 INFO mapred.MapTask (MapTask.java:flush(1454)) - bufstart = 0; bufend = 195; bufvoid = 104857600
2014-08-22 20:56:21,941 INFO mapred.MapTask (MapTask.java:flush(1456)) - kvstart = 26214396(104857584); kvend = 26214348(104857392); length = 49/6553600
2014-08-22 20:56:21,946 INFO mapred.MapTask (MapTask.java:sortAndSpill(1639)) - Finished spill 0
2014-08-22 20:56:21,949 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local415796366_0004_m_000000_0 is done. And is in the process of committing
2014-08-22 20:56:21,952 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/lhs.txt:0+52
2014-08-22 20:56:21,953 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local415796366_0004_m_000000_0' done.
2014-08-22 20:56:21,953 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local415796366_0004_m_000000_0
2014-08-22 20:56:21,954 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 20:56:21,954 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 20:56:21,955 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local415796366_0004_r_000000_0
2014-08-22 20:56:21,958 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:56:21,959 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@c8398e7
2014-08-22 20:56:21,960 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 20:56:21,961 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local415796366_0004_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 20:56:21,963 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#4 about to shuffle output of map attempt_local415796366_0004_m_000000_0 decomp: 223 len: 227 to MEMORY
2014-08-22 20:56:21,964 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 223 bytes from map-output for attempt_local415796366_0004_m_000000_0
2014-08-22 20:56:21,964 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 223, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->223
2014-08-22 20:56:21,965 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 20:56:21,967 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:56:21,968 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 20:56:21,970 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:56:21,971 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 214 bytes
2014-08-22 20:56:21,972 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 223 bytes to disk to satisfy reduce memory limit
2014-08-22 20:56:21,973 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 227 bytes from disk
2014-08-22 20:56:21,973 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 20:56:21,973 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:56:21,974 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 214 bytes
2014-08-22 20:56:21,974 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:56:21,975 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 20:56:21,975 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 20:56:21,986 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:'num']]
2014-08-22 20:56:21,987 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/bufferpipesplatform/simple2"]
2014-08-22 20:56:22,001 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local415796366_0004_r_000000_0 is done. And is in the process of committing
2014-08-22 20:56:22,005 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:56:22,006 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local415796366_0004_r_000000_0 is allowed to commit now
2014-08-22 20:56:22,007 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local415796366_0004_r_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/bufferpipesplatform/simple2/_temporary/0/task_local415796366_0004_r_000000
2014-08-22 20:56:22,008 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 20:56:22,009 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local415796366_0004_r_000000_0' done.
2014-08-22 20:56:22,009 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local415796366_0004_r_000000_0
2014-08-22 20:56:22,009 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 20:56:22,038 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/bufferpipesplatform/simple2/_temporary
2014-08-22 20:56:22,071 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:56:22,106 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:56:22,108 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output//hadoop2-mr1/bufferpipesplatform/simple2
2014-08-22 20:56:22,130 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 20:56:22,130 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 20:56:22,145 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 20:56:22,149 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 20:56:22,150 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 20:56:22,160 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting
2014-08-22 20:56:22,160 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/lower+upper.txt"]
2014-08-22 20:56:22,161 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] sink: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/bufferpipesplatform/simple3"]
2014-08-22 20:56:22,162 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] parallel execution is enabled: false
2014-08-22 20:56:22,162 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting jobs: 1
2014-08-22 20:56:22,163 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] allocating threads: 1
2014-08-22 20:56:22,164 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...fferpipesplatform/simple3
2014-08-22 20:56:22,165 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:56:22,167 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:56:22,196 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:56:22,219 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 20:56:22,242 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local65926222_0005
2014-08-22 20:56:22,266 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity65926222/.staging/job_local65926222_0005/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:56:22,267 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity65926222/.staging/job_local65926222_0005/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:56:22,613 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local65926222_0005/job_local65926222_0005.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:56:22,614 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local65926222_0005/job_local65926222_0005.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:56:22,615 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 20:56:22,616 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local65926222_0005
2014-08-22 20:56:22,616 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 20:56:22,616 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2014-08-22 20:56:22,616 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 20:56:22,621 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 20:56:22,621 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local65926222_0005_m_000000_0
2014-08-22 20:56:22,623 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:56:22,625 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/lower+upper.txt
2014-08-22 20:56:22,625 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@6a7be687
2014-08-22 20:56:22,627 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 20:56:22,627 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 20:56:22,694 INFO mapred.MapTask (MapTask.java:setEquator(1181)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 20:56:22,694 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 20:56:22,694 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 20:56:22,694 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 20:56:22,695 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 20:56:22,698 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 20:56:22,699 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 20:56:22,710 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/lower+upper.txt"]
2014-08-22 20:56:22,710 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:'num']]
2014-08-22 20:56:22,715 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 20:56:22,715 INFO mapred.MapTask (MapTask.java:flush(1435)) - Starting flush of map output
2014-08-22 20:56:22,715 INFO mapred.MapTask (MapTask.java:flush(1453)) - Spilling map output
2014-08-22 20:56:22,715 INFO mapred.MapTask (MapTask.java:flush(1454)) - bufstart = 0; bufend = 105; bufvoid = 104857600
2014-08-22 20:56:22,715 INFO mapred.MapTask (MapTask.java:flush(1456)) - kvstart = 26214396(104857584); kvend = 26214380(104857520); length = 17/6553600
2014-08-22 20:56:22,721 INFO mapred.MapTask (MapTask.java:sortAndSpill(1639)) - Finished spill 0
2014-08-22 20:56:22,723 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local65926222_0005_m_000000_0 is done. And is in the process of committing
2014-08-22 20:56:22,726 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/lower+upper.txt:0+30
2014-08-22 20:56:22,726 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local65926222_0005_m_000000_0' done.
2014-08-22 20:56:22,726 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local65926222_0005_m_000000_0
2014-08-22 20:56:22,726 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 20:56:22,727 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 20:56:22,727 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local65926222_0005_r_000000_0
2014-08-22 20:56:22,730 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:56:22,730 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@4b07c76b
2014-08-22 20:56:22,731 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 20:56:22,732 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local65926222_0005_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 20:56:22,734 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#5 about to shuffle output of map attempt_local65926222_0005_m_000000_0 decomp: 117 len: 121 to MEMORY
2014-08-22 20:56:22,735 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 117 bytes from map-output for attempt_local65926222_0005_m_000000_0
2014-08-22 20:56:22,735 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 117, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->117
2014-08-22 20:56:22,736 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 20:56:22,737 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:56:22,737 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 20:56:22,742 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:56:22,742 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 108 bytes
2014-08-22 20:56:22,744 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 117 bytes to disk to satisfy reduce memory limit
2014-08-22 20:56:22,745 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 121 bytes from disk
2014-08-22 20:56:22,745 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 20:56:22,745 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:56:22,746 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 108 bytes
2014-08-22 20:56:22,747 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:56:22,747 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 20:56:22,748 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 20:56:22,757 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:'num']]
2014-08-22 20:56:22,758 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/bufferpipesplatform/simple3"]
2014-08-22 20:56:22,771 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local65926222_0005_r_000000_0 is done. And is in the process of committing
2014-08-22 20:56:22,772 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:56:22,773 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local65926222_0005_r_000000_0 is allowed to commit now
2014-08-22 20:56:22,774 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local65926222_0005_r_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/bufferpipesplatform/simple3/_temporary/0/task_local65926222_0005_r_000000
2014-08-22 20:56:22,775 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 20:56:22,775 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local65926222_0005_r_000000_0' done.
2014-08-22 20:56:22,776 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local65926222_0005_r_000000_0
2014-08-22 20:56:22,777 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 20:56:22,798 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/bufferpipesplatform/simple3/_temporary
2014-08-22 20:56:22,830 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:56:22,866 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:56:22,868 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output//hadoop2-mr1/bufferpipesplatform/simple3
2014-08-22 20:56:22,890 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 20:56:22,891 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