2014-08-22 20:11:09,331 INFO platform.PlatformRunner (PlatformRunner.java:getPlatformClassesFromClasspath(187)) - found 1 test platforms from classpath
2014-08-22 20:11:09,406 INFO platform.PlatformRunner (PlatformRunner.java:addPlatform(237)) - installing platform: hadoop2-mr1
2014-08-22 20:11:09,407 INFO platform.PlatformRunner (PlatformRunner.java:addPlatform(238)) - running test: cascading.BasicPipesPlatformTest
2014-08-22 20:11:09,444 INFO hadoop2.Hadoop2MR1Platform (Hadoop2MR1Platform.java:setUp(106)) - not using cluster
2014-08-22 20:11:10,082 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:11:10,372 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 20:11:10,374 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:11:10,386 INFO property.AppProps (AppProps.java:getAppID(162)) - using app.id: 1A09A265B8E44380AF88D24B3B4EB42A
2014-08-22 20:11:10,471 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 20:11:10,509 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 20:11:10,587 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 20:11:10,655 INFO util.Version (Version.java:printBanner(78)) - Concurrent, Inc - Cascading 2.5.6
2014-08-22 20:11:10,658 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting
2014-08-22 20:11:10,659 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/apache.10.txt"]
2014-08-22 20:11:10,659 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] sink: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/basicpipesplatform/simplechain"]
2014-08-22 20:11:10,660 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] parallel execution is enabled: false
2014-08-22 20:11:10,661 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting jobs: 2
2014-08-22 20:11:10,661 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] allocating threads: 1
2014-08-22 20:11:10,663 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/2)
2014-08-22 20:11:10,687 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - session.id is deprecated. Instead, use dfs.metrics.session-id
2014-08-22 20:11:10,689 INFO jvm.JvmMetrics (JvmMetrics.java:init(76)) - Initializing JVM Metrics with processName=JobTracker, sessionId=
2014-08-22 20:11:10,713 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:11,087 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:11,128 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 20:11:11,295 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1944408337_0001
2014-08-22 20:11:11,346 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity1944408337/.staging/job_local1944408337_0001/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:11,348 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity1944408337/.staging/job_local1944408337_0001/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:11,537 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_local1944408337_0001/job_local1944408337_0001.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:11,538 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_local1944408337_0001/job_local1944408337_0001.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:11,548 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 20:11:11,551 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 20:11:11,554 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local1944408337_0001
2014-08-22 20:11:11,554 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2014-08-22 20:11:11,555 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 20:11:11,617 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 20:11:11,623 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1944408337_0001_m_000000_0
2014-08-22 20:11:11,668 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:11,679 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/apache.10.txt
2014-08-22 20:11:11,681 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@390f34cc
2014-08-22 20:11:11,691 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 20:11:11,699 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 20:11:11,852 INFO mapred.MapTask (MapTask.java:setEquator(1181)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 20:11:11,853 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 20:11:11,854 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 20:11:11,854 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 20:11:11,854 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 20:11:11,878 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 20:11:11,878 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 20:11:11,930 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.task.partition is deprecated. Instead, use mapreduce.task.partition
2014-08-22 20:11:11,950 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/apache.10.txt"]
2014-08-22 20:11:11,950 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:0]]
2014-08-22 20:11:11,967 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 20:11:11,967 INFO mapred.MapTask (MapTask.java:flush(1435)) - Starting flush of map output
2014-08-22 20:11:11,968 INFO mapred.MapTask (MapTask.java:flush(1453)) - Spilling map output
2014-08-22 20:11:11,968 INFO mapred.MapTask (MapTask.java:flush(1454)) - bufstart = 0; bufend = 210; bufvoid = 104857600
2014-08-22 20:11:11,968 INFO mapred.MapTask (MapTask.java:flush(1456)) - kvstart = 26214396(104857584); kvend = 26214360(104857440); length = 37/6553600
2014-08-22 20:11:11,982 INFO mapred.MapTask (MapTask.java:sortAndSpill(1639)) - Finished spill 0
2014-08-22 20:11:11,986 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1944408337_0001_m_000000_0 is done. And is in the process of committing
2014-08-22 20:11:11,997 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/apache.10.txt:0+1449
2014-08-22 20:11:11,997 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1944408337_0001_m_000000_0' done.
2014-08-22 20:11:11,998 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1944408337_0001_m_000000_0
2014-08-22 20:11:11,998 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 20:11:12,001 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 20:11:12,001 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1944408337_0001_r_000000_0
2014-08-22 20:11:12,010 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:12,014 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@679b2faf
2014-08-22 20:11:12,029 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 20:11:12,034 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1944408337_0001_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 20:11:12,074 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#1 about to shuffle output of map attempt_local1944408337_0001_m_000000_0 decomp: 232 len: 236 to MEMORY
2014-08-22 20:11:12,080 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 232 bytes from map-output for attempt_local1944408337_0001_m_000000_0
2014-08-22 20:11:12,124 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 232, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->232
2014-08-22 20:11:12,125 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 20:11:12,127 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:12,127 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:11:12,137 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:11:12,138 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 211 bytes
2014-08-22 20:11:12,141 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 232 bytes to disk to satisfy reduce memory limit
2014-08-22 20:11:12,142 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 236 bytes from disk
2014-08-22 20:11:12,143 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 20:11:12,144 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:11:12,145 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 211 bytes
2014-08-22 20:11:12,146 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:12,148 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 20:11:12,149 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 20:11:12,167 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:0]]
2014-08-22 20:11:12,168 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: TempHfs["SequenceFile[[0, 'count']]"][2309147831/test/]
2014-08-22 20:11:12,206 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1944408337_0001_r_000000_0 is done. And is in the process of committing
2014-08-22 20:11:12,208 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:12,209 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1944408337_0001_r_000000_0 is allowed to commit now
2014-08-22 20:11:12,211 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1944408337_0001_r_000000_0' to file:/tmp/hadoop-teamcity/2309147831_test_5DD6540952F14204B3331014A9DEB96E/_temporary/0/task_local1944408337_0001_r_000000
2014-08-22 20:11:12,212 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 20:11:12,213 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1944408337_0001_r_000000_0' done.
2014-08-22 20:11:12,214 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1944408337_0001_r_000000_0
2014-08-22 20:11:12,214 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 20:11:12,257 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (2/2) ...pipesplatform/simplechain
2014-08-22 20:11:12,257 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:12,259 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:12,306 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:12,331 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 20:11:12,346 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 20:11:12,347 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 20:11:12,371 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local2114743907_0002
2014-08-22 20:11:12,393 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity2114743907/.staging/job_local2114743907_0002/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:12,393 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity2114743907/.staging/job_local2114743907_0002/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:12,492 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_local2114743907_0002/job_local2114743907_0002.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:12,493 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_local2114743907_0002/job_local2114743907_0002.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:12,494 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 20:11:12,495 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local2114743907_0002
2014-08-22 20:11:12,495 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 20:11:12,495 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2014-08-22 20:11:12,495 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 20:11:12,500 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 20:11:12,501 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local2114743907_0002_m_000000_0
2014-08-22 20:11:12,504 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:12,506 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/tmp/hadoop-teamcity/2309147831_test_5DD6540952F14204B3331014A9DEB96E/part-00000
2014-08-22 20:11:12,507 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@1f635484
2014-08-22 20:11:12,520 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 20:11:12,520 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 20:11:12,664 INFO mapred.MapTask (MapTask.java:setEquator(1181)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 20:11:12,664 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 20:11:12,665 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 20:11:12,665 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 20:11:12,665 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 20:11:12,668 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 20:11:12,668 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 20:11:12,681 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: TempHfs["SequenceFile[[0, 'count']]"][2309147831/test/]
2014-08-22 20:11:12,681 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:0]]
2014-08-22 20:11:12,685 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 20:11:12,685 INFO mapred.MapTask (MapTask.java:flush(1435)) - Starting flush of map output
2014-08-22 20:11:12,685 INFO mapred.MapTask (MapTask.java:flush(1453)) - Spilling map output
2014-08-22 20:11:12,686 INFO mapred.MapTask (MapTask.java:flush(1454)) - bufstart = 0; bufend = 184; bufvoid = 104857600
2014-08-22 20:11:12,686 INFO mapred.MapTask (MapTask.java:flush(1456)) - kvstart = 26214396(104857584); kvend = 26214368(104857472); length = 29/6553600
2014-08-22 20:11:12,692 INFO mapred.MapTask (MapTask.java:sortAndSpill(1639)) - Finished spill 0
2014-08-22 20:11:12,695 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local2114743907_0002_m_000000_0 is done. And is in the process of committing
2014-08-22 20:11:12,698 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/tmp/hadoop-teamcity/2309147831_test_5DD6540952F14204B3331014A9DEB96E/part-00000:0+310
2014-08-22 20:11:12,698 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local2114743907_0002_m_000000_0' done.
2014-08-22 20:11:12,698 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local2114743907_0002_m_000000_0
2014-08-22 20:11:12,699 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 20:11:12,699 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 20:11:12,700 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local2114743907_0002_r_000000_0
2014-08-22 20:11:12,702 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:12,703 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@1c39bf12
2014-08-22 20:11:12,704 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 20:11:12,705 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local2114743907_0002_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 20:11:12,707 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#2 about to shuffle output of map attempt_local2114743907_0002_m_000000_0 decomp: 202 len: 206 to MEMORY
2014-08-22 20:11:12,708 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 202 bytes from map-output for attempt_local2114743907_0002_m_000000_0
2014-08-22 20:11:12,708 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 202, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->202
2014-08-22 20:11:12,709 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 20:11:12,710 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:12,712 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:11:12,715 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:11:12,715 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 181 bytes
2014-08-22 20:11:12,718 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 202 bytes to disk to satisfy reduce memory limit
2014-08-22 20:11:12,718 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 206 bytes from disk
2014-08-22 20:11:12,718 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 20:11:12,718 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:11:12,719 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 181 bytes
2014-08-22 20:11:12,720 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:12,720 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 20:11:12,721 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 20:11:12,731 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:0]]
2014-08-22 20:11:12,732 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/basicpipesplatform/simplechain"]
2014-08-22 20:11:12,747 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local2114743907_0002_r_000000_0 is done. And is in the process of committing
2014-08-22 20:11:12,750 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:12,750 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local2114743907_0002_r_000000_0 is allowed to commit now
2014-08-22 20:11:12,752 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local2114743907_0002_r_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/basicpipesplatform/simplechain/_temporary/0/task_local2114743907_0002_r_000000
2014-08-22 20:11:12,754 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 20:11:12,755 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local2114743907_0002_r_000000_0' done.
2014-08-22 20:11:12,755 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local2114743907_0002_r_000000_0
2014-08-22 20:11:12,756 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 20:11:12,788 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/basicpipesplatform/simplechain/_temporary
2014-08-22 20:11:12,833 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:12,837 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/basicpipesplatform/simplechain
2014-08-22 20:11:12,873 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 20:11:12,875 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:11:12,893 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 20:11:12,900 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 20:11:12,902 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 20:11:12,913 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] starting
2014-08-22 20:11:12,913 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/ips.20.txt"]
2014-08-22 20:11:12,914 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] sink: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/basicpipesplatform/count"]
2014-08-22 20:11:12,914 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] parallel execution is enabled: false
2014-08-22 20:11:12,914 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] starting jobs: 1
2014-08-22 20:11:12,914 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] allocating threads: 1
2014-08-22 20:11:12,915 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] starting step: (1/1) .../basicpipesplatform/count
2014-08-22 20:11:12,916 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:12,918 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:12,955 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:12,980 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 20:11:13,023 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local82900035_0003
2014-08-22 20:11:13,066 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity82900035/.staging/job_local82900035_0003/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:13,067 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity82900035/.staging/job_local82900035_0003/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:13,142 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_local82900035_0003/job_local82900035_0003.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:13,144 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_local82900035_0003/job_local82900035_0003.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:13,146 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 20:11:13,148 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] submitted hadoop job: job_local82900035_0003
2014-08-22 20:11:13,148 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] tracking url: http://localhost:8080/
2014-08-22 20:11:13,147 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 20:11:13,149 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 20:11:13,154 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 20:11:13,154 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local82900035_0003_m_000000_0
2014-08-22 20:11:13,157 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:13,159 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/ips.20.txt
2014-08-22 20:11:13,159 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@580c5da6
2014-08-22 20:11:13,161 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 20:11:13,161 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 20:11:13,305 INFO mapred.MapTask (MapTask.java:setEquator(1181)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 20:11:13,306 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 20:11:13,306 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 20:11:13,306 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 20:11:13,306 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 20:11:13,309 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 20:11:13,310 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 20:11:13,320 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/ips.20.txt"]
2014-08-22 20:11:13,320 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(count)[by:[{1}:1]]
2014-08-22 20:11:13,324 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 20:11:13,325 INFO mapred.MapTask (MapTask.java:flush(1435)) - Starting flush of map output
2014-08-22 20:11:13,325 INFO mapred.MapTask (MapTask.java:flush(1453)) - Spilling map output
2014-08-22 20:11:13,325 INFO mapred.MapTask (MapTask.java:flush(1454)) - bufstart = 0; bufend = 466; bufvoid = 104857600
2014-08-22 20:11:13,325 INFO mapred.MapTask (MapTask.java:flush(1456)) - kvstart = 26214396(104857584); kvend = 26214320(104857280); length = 77/6553600
2014-08-22 20:11:13,333 INFO mapred.MapTask (MapTask.java:sortAndSpill(1639)) - Finished spill 0
2014-08-22 20:11:13,336 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local82900035_0003_m_000000_0 is done. And is in the process of committing
2014-08-22 20:11:13,339 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/ips.20.txt:0+275
2014-08-22 20:11:13,339 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local82900035_0003_m_000000_0' done.
2014-08-22 20:11:13,340 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local82900035_0003_m_000000_0
2014-08-22 20:11:13,340 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 20:11:13,341 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 20:11:13,341 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local82900035_0003_r_000000_0
2014-08-22 20:11:13,345 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:13,345 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@172b29ed
2014-08-22 20:11:13,346 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 20:11:13,347 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local82900035_0003_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 20:11:13,350 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#3 about to shuffle output of map attempt_local82900035_0003_m_000000_0 decomp: 508 len: 512 to MEMORY
2014-08-22 20:11:13,351 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 508 bytes from map-output for attempt_local82900035_0003_m_000000_0
2014-08-22 20:11:13,351 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 508, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->508
2014-08-22 20:11:13,352 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 20:11:13,353 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:13,353 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:11:13,357 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:11:13,357 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 487 bytes
2014-08-22 20:11:13,360 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 508 bytes to disk to satisfy reduce memory limit
2014-08-22 20:11:13,361 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 512 bytes from disk
2014-08-22 20:11:13,361 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 20:11:13,361 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:11:13,362 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 487 bytes
2014-08-22 20:11:13,363 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:13,363 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 20:11:13,364 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 20:11:13,374 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(count)[by:[{1}:1]]
2014-08-22 20:11:13,374 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/basicpipesplatform/count"]
2014-08-22 20:11:13,394 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local82900035_0003_r_000000_0 is done. And is in the process of committing
2014-08-22 20:11:13,397 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:13,397 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local82900035_0003_r_000000_0 is allowed to commit now
2014-08-22 20:11:13,398 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local82900035_0003_r_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/basicpipesplatform/count/_temporary/0/task_local82900035_0003_r_000000
2014-08-22 20:11:13,400 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 20:11:13,400 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local82900035_0003_r_000000_0' done.
2014-08-22 20:11:13,400 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local82900035_0003_r_000000_0
2014-08-22 20:11:13,401 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 20:11:13,439 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/basicpipesplatform/count/_temporary
2014-08-22 20:11:13,480 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:13,527 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:13,532 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/basicpipesplatform/count
2014-08-22 20:11:13,570 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 20:11:13,571 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:11:13,583 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 20:11:13,588 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 20:11:13,589 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 20:11:13,597 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting
2014-08-22 20:11:13,598 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/apache.10.txt"]
2014-08-22 20:11:13,598 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] sink: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/basicpipesplatform/swap"]
2014-08-22 20:11:13,599 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] parallel execution is enabled: false
2014-08-22 20:11:13,599 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting jobs: 1
2014-08-22 20:11:13,599 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] allocating threads: 1
2014-08-22 20:11:13,600 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...1/basicpipesplatform/swap
2014-08-22 20:11:13,601 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:13,602 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:13,634 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:13,656 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 20:11:13,676 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1609568586_0004
2014-08-22 20:11:13,697 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity1609568586/.staging/job_local1609568586_0004/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:13,698 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity1609568586/.staging/job_local1609568586_0004/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:13,759 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_local1609568586_0004/job_local1609568586_0004.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:13,759 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_local1609568586_0004/job_local1609568586_0004.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:13,761 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 20:11:13,763 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local1609568586_0004
2014-08-22 20:11:13,763 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 20:11:13,763 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 20:11:13,763 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2014-08-22 20:11:13,768 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 20:11:13,768 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1609568586_0004_m_000000_0
2014-08-22 20:11:13,771 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:13,784 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/apache.10.txt
2014-08-22 20:11:13,784 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@6204904d
2014-08-22 20:11:13,786 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 0
2014-08-22 20:11:13,947 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 20:11:13,947 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 20:11:13,957 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/apache.10.txt"]
2014-08-22 20:11:13,958 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/basicpipesplatform/swap"]
2014-08-22 20:11:13,963 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 20:11:13,963 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1609568586_0004_m_000000_0 is done. And is in the process of committing
2014-08-22 20:11:13,965 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 20:11:13,965 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1609568586_0004_m_000000_0 is allowed to commit now
2014-08-22 20:11:13,966 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1609568586_0004_m_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/basicpipesplatform/swap/_temporary/0/task_local1609568586_0004_m_000000
2014-08-22 20:11:13,968 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/apache.10.txt:0+1449
2014-08-22 20:11:13,968 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1609568586_0004_m_000000_0' done.
2014-08-22 20:11:13,969 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1609568586_0004_m_000000_0
2014-08-22 20:11:13,969 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 20:11:13,992 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/basicpipesplatform/swap/_temporary
2014-08-22 20:11:14,027 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:14,031 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/basicpipesplatform/swap
2014-08-22 20:11:14,059 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 20:11:14,059 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:11:14,072 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 20:11:14,077 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 20:11:14,078 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 20:11:14,090 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting
2014-08-22 20:11:14,091 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/lower+upper.txt"]
2014-08-22 20:11:14,091 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] sink: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/basicpipesplatform/ungrouped"]
2014-08-22 20:11:14,092 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] parallel execution is enabled: false
2014-08-22 20:11:14,092 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting jobs: 1
2014-08-22 20:11:14,092 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] allocating threads: 1
2014-08-22 20:11:14,093 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...icpipesplatform/ungrouped
2014-08-22 20:11:14,095 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:14,097 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:14,126 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:14,148 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 20:11:14,167 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local669454603_0005
2014-08-22 20:11:14,187 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity669454603/.staging/job_local669454603_0005/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:14,187 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity669454603/.staging/job_local669454603_0005/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:14,256 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_local669454603_0005/job_local669454603_0005.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:14,256 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_local669454603_0005/job_local669454603_0005.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:14,257 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 20:11:14,258 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local669454603_0005
2014-08-22 20:11:14,258 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2014-08-22 20:11:14,259 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 20:11:14,259 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 20:11:14,264 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 20:11:14,264 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local669454603_0005_m_000000_0
2014-08-22 20:11:14,267 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:14,269 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:11:14,269 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@40dec87
2014-08-22 20:11:14,271 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 0
2014-08-22 20:11:14,280 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 20:11:14,280 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 20:11:14,289 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/lower+upper.txt"]
2014-08-22 20:11:14,289 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/basicpipesplatform/ungrouped"]
2014-08-22 20:11:14,293 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 20:11:14,294 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local669454603_0005_m_000000_0 is done. And is in the process of committing
2014-08-22 20:11:14,296 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 20:11:14,296 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local669454603_0005_m_000000_0 is allowed to commit now
2014-08-22 20:11:14,297 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local669454603_0005_m_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/basicpipesplatform/ungrouped/_temporary/0/task_local669454603_0005_m_000000
2014-08-22 20:11:14,298 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:11:14,299 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local669454603_0005_m_000000_0' done.
2014-08-22 20:11:14,299 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local669454603_0005_m_000000_0
2014-08-22 20:11:14,300 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 20:11:14,324 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/basicpipesplatform/ungrouped/_temporary
2014-08-22 20:11:14,358 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:14,361 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/basicpipesplatform/ungrouped
2014-08-22 20:11:14,387 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 20:11:14,389 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:11:14,403 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 20:11:14,408 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 20:11:14,410 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 20:11:14,420 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting
2014-08-22 20:11:14,421 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/apache.10.txt"]
2014-08-22 20:11:14,421 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] sink: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/basicpipesplatform/simplerelative"]
2014-08-22 20:11:14,421 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] parallel execution is enabled: false
2014-08-22 20:11:14,422 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting jobs: 1
2014-08-22 20:11:14,422 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] allocating threads: 1
2014-08-22 20:11:14,422 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...esplatform/simplerelative
2014-08-22 20:11:14,423 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:14,425 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:14,453 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:14,474 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 20:11:14,502 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1806829117_0006
2014-08-22 20:11:14,524 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity1806829117/.staging/job_local1806829117_0006/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:14,525 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity1806829117/.staging/job_local1806829117_0006/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:14,582 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_local1806829117_0006/job_local1806829117_0006.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:14,582 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_local1806829117_0006/job_local1806829117_0006.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:14,585 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 20:11:14,585 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 20:11:14,586 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 20:11:14,586 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local1806829117_0006
2014-08-22 20:11:14,587 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2014-08-22 20:11:14,590 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 20:11:14,590 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1806829117_0006_m_000000_0
2014-08-22 20:11:14,592 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:14,594 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/apache.10.txt
2014-08-22 20:11:14,594 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@788ebb5a
2014-08-22 20:11:14,596 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 20:11:14,597 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 20:11:14,747 INFO mapred.MapTask (MapTask.java:setEquator(1181)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 20:11:14,747 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 20:11:14,748 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 20:11:14,748 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 20:11:14,748 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 20:11:14,750 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 20:11:14,750 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 20:11:14,760 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/apache.10.txt"]
2014-08-22 20:11:14,760 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:0]]
2014-08-22 20:11:14,765 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 20:11:14,765 INFO mapred.MapTask (MapTask.java:flush(1435)) - Starting flush of map output
2014-08-22 20:11:14,765 INFO mapred.MapTask (MapTask.java:flush(1453)) - Spilling map output
2014-08-22 20:11:14,765 INFO mapred.MapTask (MapTask.java:flush(1454)) - bufstart = 0; bufend = 210; bufvoid = 104857600
2014-08-22 20:11:14,765 INFO mapred.MapTask (MapTask.java:flush(1456)) - kvstart = 26214396(104857584); kvend = 26214360(104857440); length = 37/6553600
2014-08-22 20:11:14,770 INFO mapred.MapTask (MapTask.java:sortAndSpill(1639)) - Finished spill 0
2014-08-22 20:11:14,772 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1806829117_0006_m_000000_0 is done. And is in the process of committing
2014-08-22 20:11:14,775 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/apache.10.txt:0+1449
2014-08-22 20:11:14,775 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1806829117_0006_m_000000_0' done.
2014-08-22 20:11:14,775 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1806829117_0006_m_000000_0
2014-08-22 20:11:14,776 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 20:11:14,776 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 20:11:14,776 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1806829117_0006_r_000000_0
2014-08-22 20:11:14,780 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:14,780 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@543a586d
2014-08-22 20:11:14,781 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 20:11:14,782 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1806829117_0006_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 20:11:14,784 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#4 about to shuffle output of map attempt_local1806829117_0006_m_000000_0 decomp: 232 len: 236 to MEMORY
2014-08-22 20:11:14,784 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 232 bytes from map-output for attempt_local1806829117_0006_m_000000_0
2014-08-22 20:11:14,785 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 232, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->232
2014-08-22 20:11:14,785 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 20:11:14,787 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:14,787 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:11:14,789 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:11:14,790 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 211 bytes
2014-08-22 20:11:14,791 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 232 bytes to disk to satisfy reduce memory limit
2014-08-22 20:11:14,792 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 236 bytes from disk
2014-08-22 20:11:14,792 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 20:11:14,792 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:11:14,793 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 211 bytes
2014-08-22 20:11:14,793 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:14,794 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 20:11:14,794 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 20:11:14,803 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:0]]
2014-08-22 20:11:14,804 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/basicpipesplatform/simplerelative"]
2014-08-22 20:11:14,817 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1806829117_0006_r_000000_0 is done. And is in the process of committing
2014-08-22 20:11:14,818 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:14,819 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1806829117_0006_r_000000_0 is allowed to commit now
2014-08-22 20:11:14,820 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1806829117_0006_r_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/basicpipesplatform/simplerelative/_temporary/0/task_local1806829117_0006_r_000000
2014-08-22 20:11:14,821 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 20:11:14,822 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1806829117_0006_r_000000_0' done.
2014-08-22 20:11:14,822 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1806829117_0006_r_000000_0
2014-08-22 20:11:14,822 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 20:11:14,850 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/basicpipesplatform/simplerelative/_temporary
2014-08-22 20:11:14,883 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:14,886 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/basicpipesplatform/simplerelative
2014-08-22 20:11:15,048 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 20:11:15,049 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:11:15,063 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 20:11:15,066 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 20:11:15,067 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 20:11:15,086 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting
2014-08-22 20:11:15,086 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/lower.txt"]
2014-08-22 20:11:15,086 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] sink: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/basicpipesplatform/simpleresult"]
2014-08-22 20:11:15,087 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] parallel execution is enabled: false
2014-08-22 20:11:15,087 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting jobs: 1
2014-08-22 20:11:15,087 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] allocating threads: 1
2014-08-22 20:11:15,087 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...ipesplatform/simpleresult
2014-08-22 20:11:15,088 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:15,089 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:15,118 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:15,141 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 20:11:15,172 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1399115417_0007
2014-08-22 20:11:15,197 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity1399115417/.staging/job_local1399115417_0007/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:15,198 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity1399115417/.staging/job_local1399115417_0007/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:15,256 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_local1399115417_0007/job_local1399115417_0007.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:15,257 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_local1399115417_0007/job_local1399115417_0007.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:15,258 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 20:11:15,259 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local1399115417_0007
2014-08-22 20:11:15,259 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 20:11:15,259 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2014-08-22 20:11:15,259 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 20:11:15,263 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 20:11:15,263 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1399115417_0007_m_000000_0
2014-08-22 20:11:15,265 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:15,267 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:11:15,267 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@705789f3
2014-08-22 20:11:15,268 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 20:11:15,269 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 20:11:15,407 INFO mapred.MapTask (MapTask.java:setEquator(1181)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 20:11:15,408 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 20:11:15,408 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 20:11:15,408 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 20:11:15,408 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 20:11:15,409 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 20:11:15,410 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 20:11:15,422 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/lower.txt"]
2014-08-22 20:11:15,422 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:0]]
2014-08-22 20:11:15,539 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 20:11:15,539 INFO mapred.MapTask (MapTask.java:flush(1435)) - Starting flush of map output
2014-08-22 20:11:15,539 INFO mapred.MapTask (MapTask.java:flush(1453)) - Spilling map output
2014-08-22 20:11:15,539 INFO mapred.MapTask (MapTask.java:flush(1454)) - bufstart = 0; bufend = 22; bufvoid = 104857600
2014-08-22 20:11:15,539 INFO mapred.MapTask (MapTask.java:flush(1456)) - kvstart = 26214396(104857584); kvend = 26214392(104857568); length = 5/6553600
2014-08-22 20:11:15,543 INFO mapred.MapTask (MapTask.java:sortAndSpill(1639)) - Finished spill 0
2014-08-22 20:11:15,545 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1399115417_0007_m_000000_0 is done. And is in the process of committing
2014-08-22 20:11:15,548 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:11:15,548 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1399115417_0007_m_000000_0' done.
2014-08-22 20:11:15,548 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1399115417_0007_m_000000_0
2014-08-22 20:11:15,548 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 20:11:15,549 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 20:11:15,549 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1399115417_0007_r_000000_0
2014-08-22 20:11:15,552 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:15,552 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@d032cf5
2014-08-22 20:11:15,553 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 20:11:15,554 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1399115417_0007_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 20:11:15,556 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#5 about to shuffle output of map attempt_local1399115417_0007_m_000000_0 decomp: 28 len: 32 to MEMORY
2014-08-22 20:11:15,556 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 28 bytes from map-output for attempt_local1399115417_0007_m_000000_0
2014-08-22 20:11:15,556 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 28, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->28
2014-08-22 20:11:15,557 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 20:11:15,558 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:15,559 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:11:15,561 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:11:15,562 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 17 bytes
2014-08-22 20:11:15,563 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 28 bytes to disk to satisfy reduce memory limit
2014-08-22 20:11:15,564 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 32 bytes from disk
2014-08-22 20:11:15,564 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 20:11:15,564 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:11:15,565 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 17 bytes
2014-08-22 20:11:15,565 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:15,566 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 20:11:15,566 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 20:11:15,577 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:0]]
2014-08-22 20:11:15,577 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/basicpipesplatform/simpleresult"]
2014-08-22 20:11:15,588 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1399115417_0007_r_000000_0 is done. And is in the process of committing
2014-08-22 20:11:15,591 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:15,591 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1399115417_0007_r_000000_0 is allowed to commit now
2014-08-22 20:11:15,592 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1399115417_0007_r_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/basicpipesplatform/simpleresult/_temporary/0/task_local1399115417_0007_r_000000
2014-08-22 20:11:15,594 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 20:11:15,594 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1399115417_0007_r_000000_0' done.
2014-08-22 20:11:15,594 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1399115417_0007_r_000000_0
2014-08-22 20:11:15,594 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 20:11:15,623 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/basicpipesplatform/simpleresult/_temporary
2014-08-22 20:11:15,656 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:15,658 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/basicpipesplatform/simpleresult
2014-08-22 20:11:15,678 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 20:11:15,678 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:11:15,687 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 20:11:15,690 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 20:11:15,690 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 20:11:15,697 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting
2014-08-22 20:11:15,698 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/apache.10.txt"]
2014-08-22 20:11:15,698 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] sink: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/basicpipesplatform/filterall"]
2014-08-22 20:11:15,698 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] parallel execution is enabled: false
2014-08-22 20:11:15,698 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting jobs: 1
2014-08-22 20:11:15,699 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] allocating threads: 1
2014-08-22 20:11:15,699 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...icpipesplatform/filterall
2014-08-22 20:11:15,700 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:15,702 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:15,732 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:15,753 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 20:11:16,065 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local2054044543_0008
2014-08-22 20:11:16,088 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity2054044543/.staging/job_local2054044543_0008/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:16,088 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity2054044543/.staging/job_local2054044543_0008/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:16,143 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_local2054044543_0008/job_local2054044543_0008.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:16,144 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_local2054044543_0008/job_local2054044543_0008.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:16,145 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 20:11:16,146 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 20:11:16,146 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 20:11:16,146 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local2054044543_0008
2014-08-22 20:11:16,147 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2014-08-22 20:11:16,150 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 20:11:16,150 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local2054044543_0008_m_000000_0
2014-08-22 20:11:16,152 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:16,154 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/apache.10.txt
2014-08-22 20:11:16,154 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@41ca5b68
2014-08-22 20:11:16,156 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 0
2014-08-22 20:11:16,165 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 20:11:16,165 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 20:11:16,172 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/apache.10.txt"]
2014-08-22 20:11:16,172 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/basicpipesplatform/filterall"]
2014-08-22 20:11:16,176 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 20:11:16,176 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local2054044543_0008_m_000000_0 is done. And is in the process of committing
2014-08-22 20:11:16,178 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 20:11:16,178 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local2054044543_0008_m_000000_0 is allowed to commit now
2014-08-22 20:11:16,179 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local2054044543_0008_m_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/basicpipesplatform/filterall/_temporary/0/task_local2054044543_0008_m_000000
2014-08-22 20:11:16,180 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/apache.10.txt:0+1449
2014-08-22 20:11:16,180 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local2054044543_0008_m_000000_0' done.
2014-08-22 20:11:16,180 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local2054044543_0008_m_000000_0
2014-08-22 20:11:16,181 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 20:11:16,205 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/basicpipesplatform/filterall/_temporary
2014-08-22 20:11:16,237 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:16,239 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/basicpipesplatform/filterall
2014-08-22 20:11:16,261 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 20:11:16,261 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:11:16,277 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 20:11:16,282 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 20:11:16,283 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 20:11:16,294 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [lower*upper] starting
2014-08-22 20:11:16,295 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [lower*upper] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/upper.txt"]
2014-08-22 20:11:16,296 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [lower*upper] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/lower.txt"]
2014-08-22 20:11:16,296 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [lower*upper] sink: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/basicpipesplatform/complexcogroup"]
2014-08-22 20:11:16,297 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [lower*upper] parallel execution is enabled: false
2014-08-22 20:11:16,297 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [lower*upper] starting jobs: 1
2014-08-22 20:11:16,297 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [lower*upper] allocating threads: 1
2014-08-22 20:11:16,298 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [lower*upper] starting step: (1/1) ...esplatform/complexcogroup
2014-08-22 20:11:16,299 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:16,300 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:16,327 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:16,329 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:16,349 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:2
2014-08-22 20:11:16,368 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local642971153_0009
2014-08-22 20:11:16,391 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity642971153/.staging/job_local642971153_0009/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:16,392 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity642971153/.staging/job_local642971153_0009/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:16,453 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_local642971153_0009/job_local642971153_0009.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:16,453 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_local642971153_0009/job_local642971153_0009.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:16,455 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 20:11:16,455 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [lower*upper] submitted hadoop job: job_local642971153_0009
2014-08-22 20:11:16,456 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 20:11:16,456 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [lower*upper] tracking url: http://localhost:8080/
2014-08-22 20:11:16,456 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 20:11:16,459 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 20:11:16,460 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local642971153_0009_m_000000_0
2014-08-22 20:11:16,462 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:16,464 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:11:16,465 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@58804a77
2014-08-22 20:11:16,466 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 20:11:16,467 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 20:11:16,538 INFO mapred.MapTask (MapTask.java:setEquator(1181)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 20:11:16,539 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 20:11:16,539 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 20:11:16,540 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 20:11:16,540 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 20:11:16,543 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 20:11:16,544 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 20:11:16,554 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/lower.txt"]
2014-08-22 20:11:16,554 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: CoGroup(lower*upper)[by: lower:[{1}:0] upper:[{1}:0]]
2014-08-22 20:11:16,558 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 20:11:16,558 INFO mapred.MapTask (MapTask.java:flush(1435)) - Starting flush of map output
2014-08-22 20:11:16,559 INFO mapred.MapTask (MapTask.java:flush(1453)) - Spilling map output
2014-08-22 20:11:16,559 INFO mapred.MapTask (MapTask.java:flush(1454)) - bufstart = 0; bufend = 85; bufvoid = 104857600
2014-08-22 20:11:16,559 INFO mapred.MapTask (MapTask.java:flush(1456)) - kvstart = 26214396(104857584); kvend = 26214380(104857520); length = 17/6553600
2014-08-22 20:11:16,563 INFO mapred.MapTask (MapTask.java:sortAndSpill(1639)) - Finished spill 0
2014-08-22 20:11:16,566 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local642971153_0009_m_000000_0 is done. And is in the process of committing
2014-08-22 20:11:16,568 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:11:16,569 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local642971153_0009_m_000000_0' done.
2014-08-22 20:11:16,569 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local642971153_0009_m_000000_0
2014-08-22 20:11:16,570 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local642971153_0009_m_000001_0
2014-08-22 20:11:16,572 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:16,574 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:11:16,574 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@131b92e6
2014-08-22 20:11:16,576 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 20:11:16,576 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 20:11:16,719 INFO mapred.MapTask (MapTask.java:setEquator(1181)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 20:11:16,719 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 20:11:16,720 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 20:11:16,720 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 20:11:16,721 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 20:11:16,722 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 20:11:16,723 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 20:11:16,732 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/upper.txt"]
2014-08-22 20:11:16,732 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: CoGroup(lower*upper)[by: lower:[{1}:0] upper:[{1}:0]]
2014-08-22 20:11:16,735 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 20:11:16,736 INFO mapred.MapTask (MapTask.java:flush(1435)) - Starting flush of map output
2014-08-22 20:11:16,736 INFO mapred.MapTask (MapTask.java:flush(1453)) - Spilling map output
2014-08-22 20:11:16,737 INFO mapred.MapTask (MapTask.java:flush(1454)) - bufstart = 0; bufend = 85; bufvoid = 104857600
2014-08-22 20:11:16,737 INFO mapred.MapTask (MapTask.java:flush(1456)) - kvstart = 26214396(104857584); kvend = 26214380(104857520); length = 17/6553600
2014-08-22 20:11:16,741 INFO mapred.MapTask (MapTask.java:sortAndSpill(1639)) - Finished spill 0
2014-08-22 20:11:16,744 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local642971153_0009_m_000001_0 is done. And is in the process of committing
2014-08-22 20:11:16,746 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:11:16,746 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local642971153_0009_m_000001_0' done.
2014-08-22 20:11:16,747 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local642971153_0009_m_000001_0
2014-08-22 20:11:16,747 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 20:11:16,748 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 20:11:16,748 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local642971153_0009_r_000000_0
2014-08-22 20:11:16,751 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:16,752 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@77f2fbff
2014-08-22 20:11:16,753 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 20:11:16,754 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local642971153_0009_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 20:11:16,758 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#6 about to shuffle output of map attempt_local642971153_0009_m_000000_0 decomp: 97 len: 101 to MEMORY
2014-08-22 20:11:16,758 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 97 bytes from map-output for attempt_local642971153_0009_m_000000_0
2014-08-22 20:11:16,759 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 97, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->97
2014-08-22 20:11:16,761 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#6 about to shuffle output of map attempt_local642971153_0009_m_000001_0 decomp: 97 len: 101 to MEMORY
2014-08-22 20:11:16,762 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 97 bytes from map-output for attempt_local642971153_0009_m_000001_0
2014-08-22 20:11:16,762 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 97, inMemoryMapOutputs.size() -> 2, commitMemory -> 97, usedMemory ->194
2014-08-22 20:11:16,763 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 20:11:16,765 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 2 / 2 copied.
2014-08-22 20:11:16,765 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:11:16,768 INFO mapred.Merger (Merger.java:merge(589)) - Merging 2 sorted segments
2014-08-22 20:11:16,769 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:11:16,771 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 2 segments, 194 bytes to disk to satisfy reduce memory limit
2014-08-22 20:11:16,772 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 196 bytes from disk
2014-08-22 20:11:16,772 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 20:11:16,772 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:11:16,773 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:11:16,774 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 2 / 2 copied.
2014-08-22 20:11:16,775 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 20:11:16,776 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 20:11:16,784 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: CoGroup(lower*upper)[by: lower:[{1}:0] upper:[{1}:0]]
2014-08-22 20:11:16,784 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/basicpipesplatform/complexcogroup"]
2014-08-22 20:11:16,801 INFO collect.SpillableTupleList (SpillableTupleList.java:getCodecClass(105)) - attempting to load codec: org.apache.hadoop.io.compress.GzipCodec
2014-08-22 20:11:16,802 INFO collect.SpillableTupleList (SpillableTupleList.java:getCodecClass(110)) - found codec: org.apache.hadoop.io.compress.GzipCodec
2014-08-22 20:11:16,810 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local642971153_0009_r_000000_0 is done. And is in the process of committing
2014-08-22 20:11:16,812 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 2 / 2 copied.
2014-08-22 20:11:16,812 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local642971153_0009_r_000000_0 is allowed to commit now
2014-08-22 20:11:16,813 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local642971153_0009_r_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/basicpipesplatform/complexcogroup/_temporary/0/task_local642971153_0009_r_000000
2014-08-22 20:11:16,815 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 20:11:16,816 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local642971153_0009_r_000000_0' done.
2014-08-22 20:11:16,816 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local642971153_0009_r_000000_0
2014-08-22 20:11:16,816 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 20:11:16,842 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/basicpipesplatform/complexcogroup/_temporary
2014-08-22 20:11:16,874 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:16,908 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:16,910 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/basicpipesplatform/complexcogroup
2014-08-22 20:11:16,929 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 20:11:16,930 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:11:16,938 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 20:11:16,941 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 20:11:16,942 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 20:11:16,948 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting
2014-08-22 20:11:16,949 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/apache.10.txt"]
2014-08-22 20:11:16,949 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] sink: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/basicpipesplatform/replace"]
2014-08-22 20:11:16,949 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] parallel execution is enabled: false
2014-08-22 20:11:16,949 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting jobs: 1
2014-08-22 20:11:16,949 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] allocating threads: 1
2014-08-22 20:11:16,950 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...asicpipesplatform/replace
2014-08-22 20:11:16,951 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:16,952 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:16,979 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:16,999 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 20:11:17,016 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local2065497022_0010
2014-08-22 20:11:17,039 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity2065497022/.staging/job_local2065497022_0010/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:17,039 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity2065497022/.staging/job_local2065497022_0010/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:17,111 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_local2065497022_0010/job_local2065497022_0010.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:17,111 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_local2065497022_0010/job_local2065497022_0010.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:17,114 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 20:11:17,114 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 20:11:17,115 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 20:11:17,115 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local2065497022_0010
2014-08-22 20:11:17,116 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2014-08-22 20:11:17,119 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 20:11:17,119 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local2065497022_0010_m_000000_0
2014-08-22 20:11:17,128 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:17,130 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/apache.10.txt
2014-08-22 20:11:17,131 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@4e5ced83
2014-08-22 20:11:17,132 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 0
2014-08-22 20:11:17,141 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 20:11:17,141 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 20:11:17,147 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/apache.10.txt"]
2014-08-22 20:11:17,148 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/basicpipesplatform/replace"]
2014-08-22 20:11:17,152 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 20:11:17,152 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local2065497022_0010_m_000000_0 is done. And is in the process of committing
2014-08-22 20:11:17,154 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 20:11:17,154 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local2065497022_0010_m_000000_0 is allowed to commit now
2014-08-22 20:11:17,155 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local2065497022_0010_m_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/basicpipesplatform/replace/_temporary/0/task_local2065497022_0010_m_000000
2014-08-22 20:11:17,156 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/apache.10.txt:0+1449
2014-08-22 20:11:17,156 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local2065497022_0010_m_000000_0' done.
2014-08-22 20:11:17,156 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local2065497022_0010_m_000000_0
2014-08-22 20:11:17,157 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 20:11:17,172 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/basicpipesplatform/replace/_temporary
2014-08-22 20:11:17,204 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:17,207 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/basicpipesplatform/replace
2014-08-22 20:11:17,229 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 20:11:17,229 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:11:17,239 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 20:11:17,242 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 20:11:17,242 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 20:11:17,250 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] starting
2014-08-22 20:11:17,250 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/ips.20.txt"]
2014-08-22 20:11:17,250 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] sink: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/basicpipesplatform/count2"]
2014-08-22 20:11:17,250 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] parallel execution is enabled: false
2014-08-22 20:11:17,251 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] starting jobs: 1
2014-08-22 20:11:17,251 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] allocating threads: 1
2014-08-22 20:11:17,253 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] starting step: (1/1) ...basicpipesplatform/count2
2014-08-22 20:11:17,253 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:17,255 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:17,282 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:17,302 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 20:11:17,318 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1615082261_0011
2014-08-22 20:11:17,336 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity1615082261/.staging/job_local1615082261_0011/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:17,336 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity1615082261/.staging/job_local1615082261_0011/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:17,386 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_local1615082261_0011/job_local1615082261_0011.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:17,386 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_local1615082261_0011/job_local1615082261_0011.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:17,388 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 20:11:17,388 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] submitted hadoop job: job_local1615082261_0011
2014-08-22 20:11:17,388 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 20:11:17,388 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] tracking url: http://localhost:8080/
2014-08-22 20:11:17,389 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 20:11:17,391 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 20:11:17,392 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1615082261_0011_m_000000_0
2014-08-22 20:11:17,394 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:17,395 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/ips.20.txt
2014-08-22 20:11:17,395 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@36a06e8d
2014-08-22 20:11:17,397 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 20:11:17,397 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 20:11:17,540 INFO mapred.MapTask (MapTask.java:setEquator(1181)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 20:11:17,541 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 20:11:17,541 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 20:11:17,541 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 20:11:17,541 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 20:11:17,543 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 20:11:17,543 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 20:11:17,552 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/ips.20.txt"]
2014-08-22 20:11:17,552 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(count)[by:[{1}:1]]
2014-08-22 20:11:17,556 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 20:11:17,557 INFO mapred.MapTask (MapTask.java:flush(1435)) - Starting flush of map output
2014-08-22 20:11:17,557 INFO mapred.MapTask (MapTask.java:flush(1453)) - Spilling map output
2014-08-22 20:11:17,557 INFO mapred.MapTask (MapTask.java:flush(1454)) - bufstart = 0; bufend = 466; bufvoid = 104857600
2014-08-22 20:11:17,557 INFO mapred.MapTask (MapTask.java:flush(1456)) - kvstart = 26214396(104857584); kvend = 26214320(104857280); length = 77/6553600
2014-08-22 20:11:17,563 INFO mapred.MapTask (MapTask.java:sortAndSpill(1639)) - Finished spill 0
2014-08-22 20:11:17,566 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1615082261_0011_m_000000_0 is done. And is in the process of committing
2014-08-22 20:11:17,568 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/ips.20.txt:0+275
2014-08-22 20:11:17,568 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1615082261_0011_m_000000_0' done.
2014-08-22 20:11:17,568 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1615082261_0011_m_000000_0
2014-08-22 20:11:17,568 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 20:11:17,569 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 20:11:17,569 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1615082261_0011_r_000000_0
2014-08-22 20:11:17,571 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:17,571 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@26832226
2014-08-22 20:11:17,572 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 20:11:17,573 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1615082261_0011_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 20:11:17,574 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#7 about to shuffle output of map attempt_local1615082261_0011_m_000000_0 decomp: 508 len: 512 to MEMORY
2014-08-22 20:11:17,575 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 508 bytes from map-output for attempt_local1615082261_0011_m_000000_0
2014-08-22 20:11:17,575 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 508, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->508
2014-08-22 20:11:17,577 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 20:11:17,578 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:17,579 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:11:17,581 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:11:17,581 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 487 bytes
2014-08-22 20:11:17,583 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 508 bytes to disk to satisfy reduce memory limit
2014-08-22 20:11:17,584 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 512 bytes from disk
2014-08-22 20:11:17,584 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 20:11:17,585 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:11:17,585 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 487 bytes
2014-08-22 20:11:17,586 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:17,587 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 20:11:17,588 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 20:11:17,595 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(count)[by:[{1}:1]]
2014-08-22 20:11:17,595 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/basicpipesplatform/count2"]
2014-08-22 20:11:17,609 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1615082261_0011_r_000000_0 is done. And is in the process of committing
2014-08-22 20:11:17,611 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:17,612 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1615082261_0011_r_000000_0 is allowed to commit now
2014-08-22 20:11:17,613 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1615082261_0011_r_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/basicpipesplatform/count2/_temporary/0/task_local1615082261_0011_r_000000
2014-08-22 20:11:17,614 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 20:11:17,615 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1615082261_0011_r_000000_0' done.
2014-08-22 20:11:17,615 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1615082261_0011_r_000000_0
2014-08-22 20:11:17,616 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 20:11:17,639 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/basicpipesplatform/count2/_temporary
2014-08-22 20:11:17,671 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:17,704 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:17,706 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/basicpipesplatform/count2
2014-08-22 20:11:17,726 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 20:11:17,726 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:11:17,736 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 20:11:17,739 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 20:11:17,739 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 20:11:17,746 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] starting
2014-08-22 20:11:17,746 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/ips.20.txt"]
2014-08-22 20:11:17,747 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] sink: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/basicpipesplatform/count3"]
2014-08-22 20:11:17,747 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] parallel execution is enabled: false
2014-08-22 20:11:17,747 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] starting jobs: 1
2014-08-22 20:11:17,747 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] allocating threads: 1
2014-08-22 20:11:17,748 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] starting step: (1/1) ...basicpipesplatform/count3
2014-08-22 20:11:17,749 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:17,750 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:17,777 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:17,798 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 20:11:17,820 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1940350268_0012
2014-08-22 20:11:17,841 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity1940350268/.staging/job_local1940350268_0012/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:17,841 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity1940350268/.staging/job_local1940350268_0012/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:17,892 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_local1940350268_0012/job_local1940350268_0012.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:17,892 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_local1940350268_0012/job_local1940350268_0012.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:17,893 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 20:11:17,894 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] submitted hadoop job: job_local1940350268_0012
2014-08-22 20:11:17,894 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] tracking url: http://localhost:8080/
2014-08-22 20:11:17,894 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 20:11:17,894 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 20:11:17,897 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 20:11:17,898 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1940350268_0012_m_000000_0
2014-08-22 20:11:17,900 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:17,901 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/ips.20.txt
2014-08-22 20:11:17,902 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@18312737
2014-08-22 20:11:17,904 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 20:11:17,904 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 20:11:18,047 INFO mapred.MapTask (MapTask.java:setEquator(1181)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 20:11:18,047 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 20:11:18,048 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 20:11:18,048 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 20:11:18,049 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 20:11:18,050 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 20:11:18,051 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 20:11:18,058 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/ips.20.txt"]
2014-08-22 20:11:18,058 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(count)[by:[{1}:1]]
2014-08-22 20:11:18,063 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 20:11:18,064 INFO mapred.MapTask (MapTask.java:flush(1435)) - Starting flush of map output
2014-08-22 20:11:18,064 INFO mapred.MapTask (MapTask.java:flush(1453)) - Spilling map output
2014-08-22 20:11:18,064 INFO mapred.MapTask (MapTask.java:flush(1454)) - bufstart = 0; bufend = 466; bufvoid = 104857600
2014-08-22 20:11:18,065 INFO mapred.MapTask (MapTask.java:flush(1456)) - kvstart = 26214396(104857584); kvend = 26214320(104857280); length = 77/6553600
2014-08-22 20:11:18,070 INFO mapred.MapTask (MapTask.java:sortAndSpill(1639)) - Finished spill 0
2014-08-22 20:11:18,073 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1940350268_0012_m_000000_0 is done. And is in the process of committing
2014-08-22 20:11:18,075 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/ips.20.txt:0+275
2014-08-22 20:11:18,075 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1940350268_0012_m_000000_0' done.
2014-08-22 20:11:18,076 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1940350268_0012_m_000000_0
2014-08-22 20:11:18,076 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 20:11:18,077 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 20:11:18,077 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1940350268_0012_r_000000_0
2014-08-22 20:11:18,079 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:18,079 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@53ddcd5f
2014-08-22 20:11:18,080 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 20:11:18,081 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1940350268_0012_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 20:11:18,083 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#8 about to shuffle output of map attempt_local1940350268_0012_m_000000_0 decomp: 508 len: 512 to MEMORY
2014-08-22 20:11:18,084 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 508 bytes from map-output for attempt_local1940350268_0012_m_000000_0
2014-08-22 20:11:18,084 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 508, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->508
2014-08-22 20:11:18,085 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 20:11:18,086 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:18,087 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:11:18,089 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:11:18,089 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 487 bytes
2014-08-22 20:11:18,091 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 508 bytes to disk to satisfy reduce memory limit
2014-08-22 20:11:18,092 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 512 bytes from disk
2014-08-22 20:11:18,092 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 20:11:18,093 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:11:18,094 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 487 bytes
2014-08-22 20:11:18,094 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:18,095 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 20:11:18,096 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 20:11:18,102 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(count)[by:[{1}:1]]
2014-08-22 20:11:18,103 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/basicpipesplatform/count3"]
2014-08-22 20:11:18,116 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1940350268_0012_r_000000_0 is done. And is in the process of committing
2014-08-22 20:11:18,118 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:18,119 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1940350268_0012_r_000000_0 is allowed to commit now
2014-08-22 20:11:18,120 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1940350268_0012_r_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/basicpipesplatform/count3/_temporary/0/task_local1940350268_0012_r_000000
2014-08-22 20:11:18,121 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 20:11:18,121 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1940350268_0012_r_000000_0' done.
2014-08-22 20:11:18,122 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1940350268_0012_r_000000_0
2014-08-22 20:11:18,122 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 20:11:18,145 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/basicpipesplatform/count3/_temporary
2014-08-22 20:11:18,176 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:18,208 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:18,210 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/basicpipesplatform/count3
2014-08-22 20:11:18,229 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 20:11:18,229 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:11:18,238 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 20:11:18,240 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 20:11:18,240 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 20:11:18,246 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] starting
2014-08-22 20:11:18,246 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/ips.20.txt"]
2014-08-22 20:11:18,247 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] sink: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/basicpipesplatform/count4"]
2014-08-22 20:11:18,247 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] parallel execution is enabled: false
2014-08-22 20:11:18,247 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] starting jobs: 1
2014-08-22 20:11:18,247 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] allocating threads: 1
2014-08-22 20:11:18,247 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] starting step: (1/1) ...basicpipesplatform/count4
2014-08-22 20:11:18,248 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:18,249 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:18,277 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:18,297 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 20:11:18,312 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1359148817_0013
2014-08-22 20:11:18,329 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity1359148817/.staging/job_local1359148817_0013/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:18,330 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity1359148817/.staging/job_local1359148817_0013/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:18,384 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_local1359148817_0013/job_local1359148817_0013.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:18,385 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_local1359148817_0013/job_local1359148817_0013.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:18,386 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 20:11:18,387 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] submitted hadoop job: job_local1359148817_0013
2014-08-22 20:11:18,387 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] tracking url: http://localhost:8080/
2014-08-22 20:11:18,387 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 20:11:18,388 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 20:11:18,391 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 20:11:18,392 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1359148817_0013_m_000000_0
2014-08-22 20:11:18,394 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:18,395 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/ips.20.txt
2014-08-22 20:11:18,395 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@423252d6
2014-08-22 20:11:18,397 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 20:11:18,397 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 20:11:18,710 INFO mapred.MapTask (MapTask.java:setEquator(1181)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 20:11:18,711 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 20:11:18,711 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 20:11:18,711 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 20:11:18,711 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 20:11:18,712 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 20:11:18,713 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 20:11:18,720 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/ips.20.txt"]
2014-08-22 20:11:18,720 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(count)[by:[{1}:1]]
2014-08-22 20:11:18,725 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 20:11:18,725 INFO mapred.MapTask (MapTask.java:flush(1435)) - Starting flush of map output
2014-08-22 20:11:18,725 INFO mapred.MapTask (MapTask.java:flush(1453)) - Spilling map output
2014-08-22 20:11:18,725 INFO mapred.MapTask (MapTask.java:flush(1454)) - bufstart = 0; bufend = 466; bufvoid = 104857600
2014-08-22 20:11:18,725 INFO mapred.MapTask (MapTask.java:flush(1456)) - kvstart = 26214396(104857584); kvend = 26214320(104857280); length = 77/6553600
2014-08-22 20:11:18,731 INFO mapred.MapTask (MapTask.java:sortAndSpill(1639)) - Finished spill 0
2014-08-22 20:11:18,733 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1359148817_0013_m_000000_0 is done. And is in the process of committing
2014-08-22 20:11:18,735 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/ips.20.txt:0+275
2014-08-22 20:11:18,735 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1359148817_0013_m_000000_0' done.
2014-08-22 20:11:18,735 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1359148817_0013_m_000000_0
2014-08-22 20:11:18,735 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 20:11:18,736 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 20:11:18,736 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1359148817_0013_r_000000_0
2014-08-22 20:11:18,738 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:18,738 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@2b9cd6b6
2014-08-22 20:11:18,739 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 20:11:18,740 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1359148817_0013_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 20:11:18,741 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#9 about to shuffle output of map attempt_local1359148817_0013_m_000000_0 decomp: 508 len: 512 to MEMORY
2014-08-22 20:11:18,742 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 508 bytes from map-output for attempt_local1359148817_0013_m_000000_0
2014-08-22 20:11:18,742 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 508, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->508
2014-08-22 20:11:18,743 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 20:11:18,744 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:18,744 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:11:18,746 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:11:18,747 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 487 bytes
2014-08-22 20:11:18,748 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 508 bytes to disk to satisfy reduce memory limit
2014-08-22 20:11:18,749 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 512 bytes from disk
2014-08-22 20:11:18,749 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 20:11:18,749 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:11:18,749 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 487 bytes
2014-08-22 20:11:18,750 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:18,750 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 20:11:18,751 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 20:11:18,757 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(count)[by:[{1}:1]]
2014-08-22 20:11:18,758 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/basicpipesplatform/count4"]
2014-08-22 20:11:18,770 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1359148817_0013_r_000000_0 is done. And is in the process of committing
2014-08-22 20:11:18,772 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:18,772 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1359148817_0013_r_000000_0 is allowed to commit now
2014-08-22 20:11:18,773 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1359148817_0013_r_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/basicpipesplatform/count4/_temporary/0/task_local1359148817_0013_r_000000
2014-08-22 20:11:18,774 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 20:11:18,775 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1359148817_0013_r_000000_0' done.
2014-08-22 20:11:18,775 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1359148817_0013_r_000000_0
2014-08-22 20:11:18,775 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 20:11:18,791 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/basicpipesplatform/count4/_temporary
2014-08-22 20:11:18,824 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:18,856 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:18,859 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/basicpipesplatform/count4
2014-08-22 20:11:18,877 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 20:11:18,878 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:11:18,885 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 20:11:18,887 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 20:11:18,888 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 20:11:18,893 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting
2014-08-22 20:11:18,893 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/apache.10.txt"]
2014-08-22 20:11:18,894 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] sink: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/basicpipesplatform/filter"]
2014-08-22 20:11:18,894 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] parallel execution is enabled: false
2014-08-22 20:11:18,894 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting jobs: 1
2014-08-22 20:11:18,894 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] allocating threads: 1
2014-08-22 20:11:18,895 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...basicpipesplatform/filter
2014-08-22 20:11:18,895 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:18,897 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:18,920 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:18,939 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 20:11:18,954 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local550128897_0014
2014-08-22 20:11:18,972 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity550128897/.staging/job_local550128897_0014/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:18,972 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity550128897/.staging/job_local550128897_0014/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:19,020 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_local550128897_0014/job_local550128897_0014.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:19,020 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_local550128897_0014/job_local550128897_0014.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:19,022 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 20:11:19,022 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local550128897_0014
2014-08-22 20:11:19,022 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 20:11:19,022 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2014-08-22 20:11:19,022 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 20:11:19,025 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 20:11:19,025 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local550128897_0014_m_000000_0
2014-08-22 20:11:19,027 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:19,029 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/apache.10.txt
2014-08-22 20:11:19,029 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@539bf7d0
2014-08-22 20:11:19,031 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 0
2014-08-22 20:11:19,038 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 20:11:19,038 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 20:11:19,045 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/apache.10.txt"]
2014-08-22 20:11:19,045 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/basicpipesplatform/filter"]
2014-08-22 20:11:19,048 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 20:11:19,049 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local550128897_0014_m_000000_0 is done. And is in the process of committing
2014-08-22 20:11:19,050 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 20:11:19,050 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local550128897_0014_m_000000_0 is allowed to commit now
2014-08-22 20:11:19,051 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local550128897_0014_m_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/basicpipesplatform/filter/_temporary/0/task_local550128897_0014_m_000000
2014-08-22 20:11:19,052 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/apache.10.txt:0+1449
2014-08-22 20:11:19,053 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local550128897_0014_m_000000_0' done.
2014-08-22 20:11:19,053 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local550128897_0014_m_000000_0
2014-08-22 20:11:19,053 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 20:11:19,067 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/basicpipesplatform/filter/_temporary
2014-08-22 20:11:19,097 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:19,098 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/basicpipesplatform/filter
2014-08-22 20:11:19,118 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 20:11:19,118 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:11:19,128 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 20:11:19,130 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 20:11:19,131 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(996)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 20:11:19,137 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting
2014-08-22 20:11:19,137 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/apache.10.txt"]
2014-08-22 20:11:19,137 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] sink: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/basicpipesplatform/simple"]
2014-08-22 20:11:19,137 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] parallel execution is enabled: false
2014-08-22 20:11:19,138 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting jobs: 1
2014-08-22 20:11:19,138 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] allocating threads: 1
2014-08-22 20:11:19,139 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...basicpipesplatform/simple
2014-08-22 20:11:19,140 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:19,141 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 20:11:19,166 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:19,185 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 20:11:19,203 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1509286245_0015
2014-08-22 20:11:19,225 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity1509286245/.staging/job_local1509286245_0015/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:19,225 WARN conf.Configuration (Configuration.java:loadProperty(2345)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/tmp/mapred/staging/teamcity1509286245/.staging/job_local1509286245_0015/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:19,290 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_local1509286245_0015/job_local1509286245_0015.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 20:11:19,290 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_local1509286245_0015/job_local1509286245_0015.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 20:11:19,292 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 20:11:19,293 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local1509286245_0015
2014-08-22 20:11:19,293 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 20:11:19,293 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2014-08-22 20:11:19,293 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 20:11:19,296 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 20:11:19,296 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1509286245_0015_m_000000_0
2014-08-22 20:11:19,298 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:19,301 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/apache.10.txt
2014-08-22 20:11:19,301 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@195dbaab
2014-08-22 20:11:19,302 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 20:11:19,302 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 20:11:19,445 INFO mapred.MapTask (MapTask.java:setEquator(1181)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 20:11:19,445 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 20:11:19,445 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 20:11:19,445 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 20:11:19,445 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 20:11:19,447 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 20:11:19,447 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 20:11:19,458 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/apache.10.txt"]
2014-08-22 20:11:19,458 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:0]]
2014-08-22 20:11:19,462 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 20:11:19,462 INFO mapred.MapTask (MapTask.java:flush(1435)) - Starting flush of map output
2014-08-22 20:11:19,462 INFO mapred.MapTask (MapTask.java:flush(1453)) - Spilling map output
2014-08-22 20:11:19,462 INFO mapred.MapTask (MapTask.java:flush(1454)) - bufstart = 0; bufend = 210; bufvoid = 104857600
2014-08-22 20:11:19,462 INFO mapred.MapTask (MapTask.java:flush(1456)) - kvstart = 26214396(104857584); kvend = 26214360(104857440); length = 37/6553600
2014-08-22 20:11:19,466 INFO mapred.MapTask (MapTask.java:sortAndSpill(1639)) - Finished spill 0
2014-08-22 20:11:19,468 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1509286245_0015_m_000000_0 is done. And is in the process of committing
2014-08-22 20:11:19,470 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/classes/test/data/apache.10.txt:0+1449
2014-08-22 20:11:19,471 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1509286245_0015_m_000000_0' done.
2014-08-22 20:11:19,471 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1509286245_0015_m_000000_0
2014-08-22 20:11:19,471 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 20:11:19,472 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 20:11:19,472 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1509286245_0015_r_000000_0
2014-08-22 20:11:19,474 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 20:11:19,474 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@b882876
2014-08-22 20:11:19,475 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 20:11:19,476 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1509286245_0015_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 20:11:19,478 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#10 about to shuffle output of map attempt_local1509286245_0015_m_000000_0 decomp: 232 len: 236 to MEMORY
2014-08-22 20:11:19,479 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 232 bytes from map-output for attempt_local1509286245_0015_m_000000_0
2014-08-22 20:11:19,479 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 232, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->232
2014-08-22 20:11:19,480 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 20:11:19,481 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:19,481 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:11:19,483 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:11:19,483 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 211 bytes
2014-08-22 20:11:19,485 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 232 bytes to disk to satisfy reduce memory limit
2014-08-22 20:11:19,485 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 236 bytes from disk
2014-08-22 20:11:19,485 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 20:11:19,486 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 20:11:19,486 INFO mapred.Merger (Merger.java:merge(688)) - Down to the last merge-pass, with 1 segments left of total size: 211 bytes
2014-08-22 20:11:19,487 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:19,487 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 20:11:19,488 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 20:11:19,497 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:0]]
2014-08-22 20:11:19,497 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/basicpipesplatform/simple"]
2014-08-22 20:11:19,509 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1509286245_0015_r_000000_0 is done. And is in the process of committing
2014-08-22 20:11:19,517 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 20:11:19,517 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1509286245_0015_r_000000_0 is allowed to commit now
2014-08-22 20:11:19,518 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1509286245_0015_r_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.3.x/build/test/output/hadoop2-mr1/basicpipesplatform/simple/_temporary/0/task_local1509286245_0015_r_000000
2014-08-22 20:11:19,519 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 20:11:19,520 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1509286245_0015_r_000000_0' done.
2014-08-22 20:11:19,520 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1509286245_0015_r_000000_0
2014-08-22 20:11:19,520 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 20:11:19,545 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/basicpipesplatform/simple/_temporary
2014-08-22 20:11:19,575 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(253)) - Total input paths to process : 1
2014-08-22 20:11:19,577 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/basicpipesplatform/simple