2014-08-22 21:57:49,944 INFO platform.PlatformRunner (PlatformRunner.java:getPlatformClassesFromClasspath(187)) - found 1 test platforms from classpath
2014-08-22 21:57:50,009 INFO platform.PlatformRunner (PlatformRunner.java:addPlatform(237)) - installing platform: hadoop2-mr1
2014-08-22 21:57:50,009 INFO platform.PlatformRunner (PlatformRunner.java:addPlatform(238)) - running test: cascading.BasicPipesPlatformTest
2014-08-22 21:57:50,042 INFO hadoop2.Hadoop2MR1Platform (Hadoop2MR1Platform.java:setUp(106)) - not using cluster
2014-08-22 21:57:50,688 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 21:57:50,985 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 21:57:50,988 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 21:57:51,000 INFO property.AppProps (AppProps.java:getAppID(162)) - using app.id: 305B34E8540A4C3EA1878857CCF18C94
2014-08-22 21:57:51,086 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 21:57:51,130 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 21:57:51,210 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 21:57:51,279 INFO util.Version (Version.java:printBanner(78)) - Concurrent, Inc - Cascading 2.5.6
2014-08-22 21:57:51,281 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting
2014-08-22 21:57:51,282 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2014-08-22 21:57:51,282 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] sink: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/simplechain"]
2014-08-22 21:57:51,283 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] parallel execution is enabled: false
2014-08-22 21:57:51,284 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting jobs: 2
2014-08-22 21:57:51,285 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] allocating threads: 1
2014-08-22 21:57:51,286 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/2)
2014-08-22 21:57:51,310 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - session.id is deprecated. Instead, use dfs.metrics.session-id
2014-08-22 21:57:51,312 INFO jvm.JvmMetrics (JvmMetrics.java:init(76)) - Initializing JVM Metrics with processName=JobTracker, sessionId=
2014-08-22 21:57:51,336 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:57:51,711 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:57:51,752 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 21:57:51,914 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local2080227679_0001
2014-08-22 21:57:51,962 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity2080227679/.staging/job_local2080227679_0001/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:57:51,974 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity2080227679/.staging/job_local2080227679_0001/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:57:52,160 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local2080227679_0001/job_local2080227679_0001.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:57:52,167 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local2080227679_0001/job_local2080227679_0001.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:57:52,173 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 21:57:52,175 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 21:57:52,177 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local2080227679_0001
2014-08-22 21:57:52,178 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2014-08-22 21:57:52,178 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 21:57:52,237 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 21:57:52,243 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local2080227679_0001_m_000000_0
2014-08-22 21:57:52,290 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:57:52,302 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/apache.10.txt
2014-08-22 21:57:52,302 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@11b9d4d8
2014-08-22 21:57:52,313 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 21:57:52,321 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 21:57:52,468 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 21:57:52,469 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 21:57:52,469 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 21:57:52,469 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 21:57:52,469 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 21:57:52,496 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 21:57:52,497 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 21:57:52,548 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.task.partition is deprecated. Instead, use mapreduce.task.partition
2014-08-22 21:57:52,567 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2014-08-22 21:57:52,567 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:0]]
2014-08-22 21:57:52,584 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 21:57:52,584 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2014-08-22 21:57:52,584 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2014-08-22 21:57:52,584 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 210; bufvoid = 104857600
2014-08-22 21:57:52,584 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214360(104857440); length = 37/6553600
2014-08-22 21:57:52,598 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2014-08-22 21:57:52,602 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local2080227679_0001_m_000000_0 is done. And is in the process of committing
2014-08-22 21:57:52,613 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/apache.10.txt:0+1449
2014-08-22 21:57:52,614 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local2080227679_0001_m_000000_0' done.
2014-08-22 21:57:52,614 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local2080227679_0001_m_000000_0
2014-08-22 21:57:52,614 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 21:57:52,617 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 21:57:52,617 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local2080227679_0001_r_000000_0
2014-08-22 21:57:52,626 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:57:52,629 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@1af70ee1
2014-08-22 21:57:52,644 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 21:57:52,655 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local2080227679_0001_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 21:57:52,690 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#1 about to shuffle output of map attempt_local2080227679_0001_m_000000_0 decomp: 232 len: 236 to MEMORY
2014-08-22 21:57:52,698 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 232 bytes from map-output for attempt_local2080227679_0001_m_000000_0
2014-08-22 21:57:52,739 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 232, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->232
2014-08-22 21:57:52,740 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 21:57:52,742 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:57:52,743 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 21:57:52,753 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 21:57:52,753 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 21:57:52,756 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 232 bytes to disk to satisfy reduce memory limit
2014-08-22 21:57:52,757 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 236 bytes from disk
2014-08-22 21:57:52,758 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 21:57:52,758 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 21:57:52,758 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 21:57:52,759 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:57:52,761 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 21:57:52,761 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 21:57:52,780 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:0]]
2014-08-22 21:57:52,780 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: TempHfs["SequenceFile[[0, 'count']]"][4179367194/test/]
2014-08-22 21:57:52,818 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local2080227679_0001_r_000000_0 is done. And is in the process of committing
2014-08-22 21:57:52,820 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:57:52,820 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local2080227679_0001_r_000000_0 is allowed to commit now
2014-08-22 21:57:52,822 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local2080227679_0001_r_000000_0' to file:/tmp/hadoop-teamcity/4179367194_test_B8945103690A43DC9A201765A1BF94D0/_temporary/0/task_local2080227679_0001_r_000000
2014-08-22 21:57:52,823 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 21:57:52,823 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local2080227679_0001_r_000000_0' done.
2014-08-22 21:57:52,824 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local2080227679_0001_r_000000_0
2014-08-22 21:57:52,824 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 21:57:52,858 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (2/2) ...pipesplatform/simplechain
2014-08-22 21:57:52,859 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:57:52,861 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:57:52,907 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:57:52,934 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 21:57:52,950 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 21:57:52,951 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 21:57:52,975 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1475617086_0002
2014-08-22 21:57:52,997 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1475617086/.staging/job_local1475617086_0002/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:57:52,999 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1475617086/.staging/job_local1475617086_0002/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:57:53,092 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1475617086_0002/job_local1475617086_0002.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:57:53,094 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1475617086_0002/job_local1475617086_0002.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:57:53,095 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 21:57:53,095 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local1475617086_0002
2014-08-22 21:57:53,095 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2014-08-22 21:57:53,095 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 21:57:53,096 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 21:57:53,101 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 21:57:53,102 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1475617086_0002_m_000000_0
2014-08-22 21:57:53,104 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:57:53,107 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/tmp/hadoop-teamcity/4179367194_test_B8945103690A43DC9A201765A1BF94D0/part-00000
2014-08-22 21:57:53,107 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@7e92997e
2014-08-22 21:57:53,119 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 21:57:53,119 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 21:57:53,264 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 21:57:53,264 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 21:57:53,265 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 21:57:53,265 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 21:57:53,265 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 21:57:53,266 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 21:57:53,267 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 21:57:53,279 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: TempHfs["SequenceFile[[0, 'count']]"][4179367194/test/]
2014-08-22 21:57:53,279 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:0]]
2014-08-22 21:57:53,283 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 21:57:53,283 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2014-08-22 21:57:53,283 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2014-08-22 21:57:53,283 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 184; bufvoid = 104857600
2014-08-22 21:57:53,283 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214368(104857472); length = 29/6553600
2014-08-22 21:57:53,289 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2014-08-22 21:57:53,293 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1475617086_0002_m_000000_0 is done. And is in the process of committing
2014-08-22 21:57:53,295 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/tmp/hadoop-teamcity/4179367194_test_B8945103690A43DC9A201765A1BF94D0/part-00000:0+310
2014-08-22 21:57:53,296 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1475617086_0002_m_000000_0' done.
2014-08-22 21:57:53,296 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1475617086_0002_m_000000_0
2014-08-22 21:57:53,297 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 21:57:53,297 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 21:57:53,297 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1475617086_0002_r_000000_0
2014-08-22 21:57:53,301 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:57:53,301 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@304a0ac5
2014-08-22 21:57:53,302 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 21:57:53,303 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1475617086_0002_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 21:57:53,306 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#2 about to shuffle output of map attempt_local1475617086_0002_m_000000_0 decomp: 202 len: 206 to MEMORY
2014-08-22 21:57:53,306 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 202 bytes from map-output for attempt_local1475617086_0002_m_000000_0
2014-08-22 21:57:53,307 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 202, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->202
2014-08-22 21:57:53,308 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 21:57:53,309 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:57:53,310 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 21:57:53,314 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 21:57:53,315 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 21:57:53,317 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 202 bytes to disk to satisfy reduce memory limit
2014-08-22 21:57:53,317 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 206 bytes from disk
2014-08-22 21:57:53,318 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 21:57:53,318 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 21:57:53,318 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 21:57:53,319 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:57:53,320 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 21:57:53,320 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 21:57:53,330 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:0]]
2014-08-22 21:57:53,331 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/simplechain"]
2014-08-22 21:57:53,346 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1475617086_0002_r_000000_0 is done. And is in the process of committing
2014-08-22 21:57:53,350 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:57:53,351 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1475617086_0002_r_000000_0 is allowed to commit now
2014-08-22 21:57:53,352 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1475617086_0002_r_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/simplechain/_temporary/0/task_local1475617086_0002_r_000000
2014-08-22 21:57:53,354 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 21:57:53,354 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1475617086_0002_r_000000_0' done.
2014-08-22 21:57:53,354 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1475617086_0002_r_000000_0
2014-08-22 21:57:53,354 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 21:57:53,385 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/simplechain/_temporary
2014-08-22 21:57:53,432 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:57:53,437 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output//hadoop2-mr1/basicpipesplatform/simplechain
2014-08-22 21:57:53,476 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 21:57:53,477 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 21:57:53,495 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 21:57:53,501 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 21:57:53,502 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 21:57:53,513 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] starting
2014-08-22 21:57:53,514 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/ips.20.txt"]
2014-08-22 21:57:53,514 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] sink: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/count"]
2014-08-22 21:57:53,514 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] parallel execution is enabled: false
2014-08-22 21:57:53,514 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] starting jobs: 1
2014-08-22 21:57:53,515 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] allocating threads: 1
2014-08-22 21:57:53,517 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] starting step: (1/1) .../basicpipesplatform/count
2014-08-22 21:57:53,518 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:57:53,520 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:57:53,554 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:57:53,592 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 21:57:53,636 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1549265451_0003
2014-08-22 21:57:53,667 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1549265451/.staging/job_local1549265451_0003/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:57:53,670 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1549265451/.staging/job_local1549265451_0003/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:57:53,748 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1549265451_0003/job_local1549265451_0003.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:57:53,750 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1549265451_0003/job_local1549265451_0003.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:57:53,751 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 21:57:53,751 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] submitted hadoop job: job_local1549265451_0003
2014-08-22 21:57:53,752 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] tracking url: http://localhost:8080/
2014-08-22 21:57:53,752 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 21:57:53,752 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 21:57:53,757 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 21:57:53,758 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1549265451_0003_m_000000_0
2014-08-22 21:57:53,760 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:57:53,763 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/ips.20.txt
2014-08-22 21:57:53,763 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@4856d149
2014-08-22 21:57:53,765 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 21:57:53,765 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 21:57:53,908 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 21:57:53,909 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 21:57:53,909 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 21:57:53,909 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 21:57:53,909 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 21:57:53,912 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 21:57:53,913 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 21:57:53,923 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/ips.20.txt"]
2014-08-22 21:57:53,923 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(count)[by:[{1}:1]]
2014-08-22 21:57:53,927 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 21:57:53,928 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2014-08-22 21:57:53,928 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2014-08-22 21:57:53,928 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 466; bufvoid = 104857600
2014-08-22 21:57:53,928 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214320(104857280); length = 77/6553600
2014-08-22 21:57:53,936 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2014-08-22 21:57:53,939 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1549265451_0003_m_000000_0 is done. And is in the process of committing
2014-08-22 21:57:53,942 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/ips.20.txt:0+275
2014-08-22 21:57:53,942 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1549265451_0003_m_000000_0' done.
2014-08-22 21:57:53,942 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1549265451_0003_m_000000_0
2014-08-22 21:57:53,942 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 21:57:53,943 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 21:57:53,943 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1549265451_0003_r_000000_0
2014-08-22 21:57:53,946 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:57:53,946 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@5b5ede11
2014-08-22 21:57:53,947 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 21:57:53,948 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1549265451_0003_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 21:57:53,950 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#3 about to shuffle output of map attempt_local1549265451_0003_m_000000_0 decomp: 508 len: 512 to MEMORY
2014-08-22 21:57:53,951 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 508 bytes from map-output for attempt_local1549265451_0003_m_000000_0
2014-08-22 21:57:53,951 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 508, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->508
2014-08-22 21:57:53,952 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 21:57:53,953 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:57:53,954 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 21:57:53,957 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 21:57:53,957 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 21:57:53,959 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 508 bytes to disk to satisfy reduce memory limit
2014-08-22 21:57:53,960 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 512 bytes from disk
2014-08-22 21:57:53,960 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 21:57:53,960 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 21:57:53,960 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 21:57:53,961 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:57:53,962 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 21:57:53,962 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 21:57:53,971 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(count)[by:[{1}:1]]
2014-08-22 21:57:53,972 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/count"]
2014-08-22 21:57:53,988 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1549265451_0003_r_000000_0 is done. And is in the process of committing
2014-08-22 21:57:53,990 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:57:53,990 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1549265451_0003_r_000000_0 is allowed to commit now
2014-08-22 21:57:53,991 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1549265451_0003_r_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/count/_temporary/0/task_local1549265451_0003_r_000000
2014-08-22 21:57:53,993 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 21:57:53,993 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1549265451_0003_r_000000_0' done.
2014-08-22 21:57:53,994 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1549265451_0003_r_000000_0
2014-08-22 21:57:53,994 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 21:57:54,033 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/count/_temporary
2014-08-22 21:57:54,087 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:57:54,129 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:57:54,133 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output//hadoop2-mr1/basicpipesplatform/count
2014-08-22 21:57:54,158 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 21:57:54,158 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 21:57:54,170 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 21:57:54,175 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 21:57:54,176 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 21:57:54,184 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting
2014-08-22 21:57:54,185 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2014-08-22 21:57:54,185 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] sink: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/swap"]
2014-08-22 21:57:54,186 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] parallel execution is enabled: false
2014-08-22 21:57:54,187 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting jobs: 1
2014-08-22 21:57:54,187 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] allocating threads: 1
2014-08-22 21:57:54,188 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...1/basicpipesplatform/swap
2014-08-22 21:57:54,190 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:57:54,191 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:57:54,225 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:57:54,249 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 21:57:54,272 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1191879447_0004
2014-08-22 21:57:54,294 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1191879447/.staging/job_local1191879447_0004/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:57:54,295 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1191879447/.staging/job_local1191879447_0004/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:57:54,368 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1191879447_0004/job_local1191879447_0004.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:57:54,370 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1191879447_0004/job_local1191879447_0004.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:57:54,371 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 21:57:54,371 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local1191879447_0004
2014-08-22 21:57:54,372 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 21:57:54,372 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2014-08-22 21:57:54,372 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 21:57:54,377 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 21:57:54,377 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1191879447_0004_m_000000_0
2014-08-22 21:57:54,380 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:57:54,381 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/apache.10.txt
2014-08-22 21:57:54,382 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@64610fa
2014-08-22 21:57:54,383 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 0
2014-08-22 21:57:54,393 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 21:57:54,393 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 21:57:54,402 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2014-08-22 21:57:54,403 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/swap"]
2014-08-22 21:57:54,408 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 21:57:54,409 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1191879447_0004_m_000000_0 is done. And is in the process of committing
2014-08-22 21:57:54,411 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 21:57:54,411 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1191879447_0004_m_000000_0 is allowed to commit now
2014-08-22 21:57:54,412 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1191879447_0004_m_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/swap/_temporary/0/task_local1191879447_0004_m_000000
2014-08-22 21:57:54,413 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/apache.10.txt:0+1449
2014-08-22 21:57:54,414 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1191879447_0004_m_000000_0' done.
2014-08-22 21:57:54,414 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1191879447_0004_m_000000_0
2014-08-22 21:57:54,414 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 21:57:54,439 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/swap/_temporary
2014-08-22 21:57:54,475 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:57:54,478 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output//hadoop2-mr1/basicpipesplatform/swap
2014-08-22 21:57:54,505 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 21:57:54,505 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 21:57:54,517 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 21:57:54,522 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 21:57:54,523 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 21:57:54,534 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting
2014-08-22 21:57:54,535 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower+upper.txt"]
2014-08-22 21:57:54,535 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] sink: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/ungrouped"]
2014-08-22 21:57:54,535 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] parallel execution is enabled: false
2014-08-22 21:57:54,536 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting jobs: 1
2014-08-22 21:57:54,536 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] allocating threads: 1
2014-08-22 21:57:54,537 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...icpipesplatform/ungrouped
2014-08-22 21:57:54,539 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:57:54,540 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:57:54,570 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:57:54,591 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 21:57:54,609 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1873609069_0005
2014-08-22 21:57:54,629 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1873609069/.staging/job_local1873609069_0005/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:57:54,631 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1873609069/.staging/job_local1873609069_0005/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:57:54,699 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1873609069_0005/job_local1873609069_0005.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:57:54,701 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1873609069_0005/job_local1873609069_0005.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:57:54,701 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 21:57:54,702 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local1873609069_0005
2014-08-22 21:57:54,702 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2014-08-22 21:57:54,702 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 21:57:54,703 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 21:57:54,707 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 21:57:54,707 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1873609069_0005_m_000000_0
2014-08-22 21:57:54,710 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:57:54,712 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower+upper.txt
2014-08-22 21:57:54,712 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@63ae2c6f
2014-08-22 21:57:54,714 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 0
2014-08-22 21:57:54,723 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 21:57:54,724 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 21:57:54,733 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower+upper.txt"]
2014-08-22 21:57:54,733 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/ungrouped"]
2014-08-22 21:57:54,737 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 21:57:54,737 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1873609069_0005_m_000000_0 is done. And is in the process of committing
2014-08-22 21:57:54,739 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 21:57:54,739 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1873609069_0005_m_000000_0 is allowed to commit now
2014-08-22 21:57:54,740 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1873609069_0005_m_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/ungrouped/_temporary/0/task_local1873609069_0005_m_000000
2014-08-22 21:57:54,742 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower+upper.txt:0+30
2014-08-22 21:57:54,742 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1873609069_0005_m_000000_0' done.
2014-08-22 21:57:54,743 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1873609069_0005_m_000000_0
2014-08-22 21:57:54,743 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 21:57:54,770 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/ungrouped/_temporary
2014-08-22 21:57:54,819 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:57:54,821 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output//hadoop2-mr1/basicpipesplatform/ungrouped
2014-08-22 21:57:54,843 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 21:57:54,844 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 21:57:54,856 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 21:57:54,861 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 21:57:54,862 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 21:57:54,870 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting
2014-08-22 21:57:54,871 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2014-08-22 21:57:54,871 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] sink: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/simplerelative"]
2014-08-22 21:57:54,872 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] parallel execution is enabled: false
2014-08-22 21:57:54,872 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting jobs: 1
2014-08-22 21:57:54,872 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] allocating threads: 1
2014-08-22 21:57:54,873 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...esplatform/simplerelative
2014-08-22 21:57:54,875 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:57:54,876 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:57:54,906 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:57:54,929 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 21:57:54,949 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1561326568_0006
2014-08-22 21:57:54,970 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1561326568/.staging/job_local1561326568_0006/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:57:54,971 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1561326568/.staging/job_local1561326568_0006/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:57:55,028 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1561326568_0006/job_local1561326568_0006.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:57:55,030 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1561326568_0006/job_local1561326568_0006.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:57:55,031 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 21:57:55,031 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 21:57:55,032 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 21:57:55,032 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local1561326568_0006
2014-08-22 21:57:55,033 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2014-08-22 21:57:55,035 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 21:57:55,036 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1561326568_0006_m_000000_0
2014-08-22 21:57:55,038 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:57:55,040 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/apache.10.txt
2014-08-22 21:57:55,040 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@31c248a
2014-08-22 21:57:55,041 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 21:57:55,042 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 21:57:55,181 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 21:57:55,181 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 21:57:55,181 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 21:57:55,181 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 21:57:55,181 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 21:57:55,183 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 21:57:55,183 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 21:57:55,193 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2014-08-22 21:57:55,193 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:0]]
2014-08-22 21:57:55,197 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 21:57:55,197 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2014-08-22 21:57:55,197 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2014-08-22 21:57:55,197 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 210; bufvoid = 104857600
2014-08-22 21:57:55,197 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214360(104857440); length = 37/6553600
2014-08-22 21:57:55,202 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2014-08-22 21:57:55,204 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1561326568_0006_m_000000_0 is done. And is in the process of committing
2014-08-22 21:57:55,206 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/apache.10.txt:0+1449
2014-08-22 21:57:55,207 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1561326568_0006_m_000000_0' done.
2014-08-22 21:57:55,207 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1561326568_0006_m_000000_0
2014-08-22 21:57:55,207 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 21:57:55,208 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 21:57:55,208 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1561326568_0006_r_000000_0
2014-08-22 21:57:55,210 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:57:55,211 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@584ba778
2014-08-22 21:57:55,211 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 21:57:55,212 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1561326568_0006_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 21:57:55,214 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#4 about to shuffle output of map attempt_local1561326568_0006_m_000000_0 decomp: 232 len: 236 to MEMORY
2014-08-22 21:57:55,215 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 232 bytes from map-output for attempt_local1561326568_0006_m_000000_0
2014-08-22 21:57:55,215 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 232, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->232
2014-08-22 21:57:55,216 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 21:57:55,217 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:57:55,217 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 21:57:55,220 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 21:57:55,220 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 21:57:55,222 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 232 bytes to disk to satisfy reduce memory limit
2014-08-22 21:57:55,222 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 236 bytes from disk
2014-08-22 21:57:55,222 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 21:57:55,222 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 21:57:55,223 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 21:57:55,224 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:57:55,224 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 21:57:55,224 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 21:57:55,233 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:0]]
2014-08-22 21:57:55,234 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/simplerelative"]
2014-08-22 21:57:55,246 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1561326568_0006_r_000000_0 is done. And is in the process of committing
2014-08-22 21:57:55,248 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:57:55,248 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1561326568_0006_r_000000_0 is allowed to commit now
2014-08-22 21:57:55,249 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1561326568_0006_r_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/simplerelative/_temporary/0/task_local1561326568_0006_r_000000
2014-08-22 21:57:55,251 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 21:57:55,251 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1561326568_0006_r_000000_0' done.
2014-08-22 21:57:55,251 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1561326568_0006_r_000000_0
2014-08-22 21:57:55,251 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 21:57:55,276 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/simplerelative/_temporary
2014-08-22 21:57:55,310 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:57:55,312 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output//hadoop2-mr1/basicpipesplatform/simplerelative
2014-08-22 21:57:55,482 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 21:57:55,482 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 21:57:55,507 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 21:57:55,511 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 21:57:55,512 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 21:57:55,532 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting
2014-08-22 21:57:55,532 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower.txt"]
2014-08-22 21:57:55,533 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] sink: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/simpleresult"]
2014-08-22 21:57:55,533 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] parallel execution is enabled: false
2014-08-22 21:57:55,533 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting jobs: 1
2014-08-22 21:57:55,533 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] allocating threads: 1
2014-08-22 21:57:55,535 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...ipesplatform/simpleresult
2014-08-22 21:57:55,535 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:57:55,537 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:57:55,566 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:57:55,587 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 21:57:55,604 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local2108248526_0007
2014-08-22 21:57:55,625 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity2108248526/.staging/job_local2108248526_0007/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:57:55,626 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity2108248526/.staging/job_local2108248526_0007/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:57:55,680 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local2108248526_0007/job_local2108248526_0007.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:57:55,681 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local2108248526_0007/job_local2108248526_0007.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:57:55,681 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 21:57:55,682 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local2108248526_0007
2014-08-22 21:57:55,682 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 21:57:55,682 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2014-08-22 21:57:55,682 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 21:57:55,686 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 21:57:55,686 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local2108248526_0007_m_000000_0
2014-08-22 21:57:55,689 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:57:55,691 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower.txt
2014-08-22 21:57:55,691 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@7fdb04ed
2014-08-22 21:57:55,693 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 21:57:55,694 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 21:57:55,839 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 21:57:55,839 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 21:57:55,839 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 21:57:55,839 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 21:57:55,839 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 21:57:55,842 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 21:57:55,843 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 21:57:55,855 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower.txt"]
2014-08-22 21:57:55,856 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:0]]
2014-08-22 21:57:55,972 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 21:57:55,972 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2014-08-22 21:57:55,972 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2014-08-22 21:57:55,973 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 22; bufvoid = 104857600
2014-08-22 21:57:55,973 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214392(104857568); length = 5/6553600
2014-08-22 21:57:55,976 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2014-08-22 21:57:55,978 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local2108248526_0007_m_000000_0 is done. And is in the process of committing
2014-08-22 21:57:55,982 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower.txt:0+19
2014-08-22 21:57:55,982 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local2108248526_0007_m_000000_0' done.
2014-08-22 21:57:55,982 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local2108248526_0007_m_000000_0
2014-08-22 21:57:55,983 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 21:57:55,983 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 21:57:55,984 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local2108248526_0007_r_000000_0
2014-08-22 21:57:55,986 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:57:55,986 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@2f56f920
2014-08-22 21:57:55,988 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 21:57:55,989 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local2108248526_0007_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 21:57:55,991 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#5 about to shuffle output of map attempt_local2108248526_0007_m_000000_0 decomp: 28 len: 32 to MEMORY
2014-08-22 21:57:55,992 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 28 bytes from map-output for attempt_local2108248526_0007_m_000000_0
2014-08-22 21:57:55,992 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 28, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->28
2014-08-22 21:57:55,993 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 21:57:55,994 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:57:55,995 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 21:57:55,998 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 21:57:55,998 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 21:57:56,000 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 28 bytes to disk to satisfy reduce memory limit
2014-08-22 21:57:56,000 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 32 bytes from disk
2014-08-22 21:57:56,000 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 21:57:56,001 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 21:57:56,001 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 21:57:56,002 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:57:56,002 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 21:57:56,002 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 21:57:56,013 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:0]]
2014-08-22 21:57:56,013 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/simpleresult"]
2014-08-22 21:57:56,024 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local2108248526_0007_r_000000_0 is done. And is in the process of committing
2014-08-22 21:57:56,026 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:57:56,026 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local2108248526_0007_r_000000_0 is allowed to commit now
2014-08-22 21:57:56,027 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local2108248526_0007_r_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/simpleresult/_temporary/0/task_local2108248526_0007_r_000000
2014-08-22 21:57:56,028 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 21:57:56,028 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local2108248526_0007_r_000000_0' done.
2014-08-22 21:57:56,029 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local2108248526_0007_r_000000_0
2014-08-22 21:57:56,029 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 21:57:56,056 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/simpleresult/_temporary
2014-08-22 21:57:56,089 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:57:56,092 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output//hadoop2-mr1/basicpipesplatform/simpleresult
2014-08-22 21:57:56,119 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 21:57:56,119 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 21:57:56,132 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 21:57:56,136 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 21:57:56,137 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 21:57:56,146 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting
2014-08-22 21:57:56,146 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2014-08-22 21:57:56,147 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] sink: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/filterall"]
2014-08-22 21:57:56,147 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] parallel execution is enabled: false
2014-08-22 21:57:56,147 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting jobs: 1
2014-08-22 21:57:56,147 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] allocating threads: 1
2014-08-22 21:57:56,148 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...icpipesplatform/filterall
2014-08-22 21:57:56,149 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:57:56,150 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:57:56,178 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:57:56,200 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 21:57:56,248 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local46535596_0008
2014-08-22 21:57:56,271 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity46535596/.staging/job_local46535596_0008/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:57:56,272 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity46535596/.staging/job_local46535596_0008/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:57:56,631 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local46535596_0008/job_local46535596_0008.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:57:56,632 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local46535596_0008/job_local46535596_0008.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:57:56,633 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 21:57:56,633 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local46535596_0008
2014-08-22 21:57:56,633 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 21:57:56,633 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2014-08-22 21:57:56,633 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 21:57:56,637 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 21:57:56,637 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local46535596_0008_m_000000_0
2014-08-22 21:57:56,640 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:57:56,642 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/apache.10.txt
2014-08-22 21:57:56,643 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@1e79edfe
2014-08-22 21:57:56,646 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 0
2014-08-22 21:57:56,655 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 21:57:56,656 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 21:57:56,663 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2014-08-22 21:57:56,664 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/filterall"]
2014-08-22 21:57:56,668 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 21:57:56,669 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local46535596_0008_m_000000_0 is done. And is in the process of committing
2014-08-22 21:57:56,670 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 21:57:56,671 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local46535596_0008_m_000000_0 is allowed to commit now
2014-08-22 21:57:56,672 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local46535596_0008_m_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/filterall/_temporary/0/task_local46535596_0008_m_000000
2014-08-22 21:57:56,674 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/apache.10.txt:0+1449
2014-08-22 21:57:56,674 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local46535596_0008_m_000000_0' done.
2014-08-22 21:57:56,675 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local46535596_0008_m_000000_0
2014-08-22 21:57:56,675 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 21:57:56,699 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/filterall/_temporary
2014-08-22 21:57:56,732 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:57:56,734 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output//hadoop2-mr1/basicpipesplatform/filterall
2014-08-22 21:57:56,756 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 21:57:56,757 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 21:57:56,773 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 21:57:56,778 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 21:57:56,779 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 21:57:56,792 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [lower*upper] starting
2014-08-22 21:57:56,793 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [lower*upper] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/upper.txt"]
2014-08-22 21:57:56,794 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [lower*upper] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower.txt"]
2014-08-22 21:57:56,794 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [lower*upper] sink: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/complexcogroup"]
2014-08-22 21:57:56,795 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [lower*upper] parallel execution is enabled: false
2014-08-22 21:57:56,795 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [lower*upper] starting jobs: 1
2014-08-22 21:57:56,796 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [lower*upper] allocating threads: 1
2014-08-22 21:57:56,796 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [lower*upper] starting step: (1/1) ...esplatform/complexcogroup
2014-08-22 21:57:56,797 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:57:56,799 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:57:56,828 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:57:56,830 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:57:56,852 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:2
2014-08-22 21:57:56,870 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1672432654_0009
2014-08-22 21:57:56,889 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1672432654/.staging/job_local1672432654_0009/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:57:56,890 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1672432654/.staging/job_local1672432654_0009/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:57:56,941 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1672432654_0009/job_local1672432654_0009.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:57:56,942 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1672432654_0009/job_local1672432654_0009.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:57:56,943 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 21:57:56,944 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [lower*upper] submitted hadoop job: job_local1672432654_0009
2014-08-22 21:57:56,944 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 21:57:56,944 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [lower*upper] tracking url: http://localhost:8080/
2014-08-22 21:57:56,944 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 21:57:56,948 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 21:57:56,948 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1672432654_0009_m_000000_0
2014-08-22 21:57:56,950 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:57:56,952 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower.txt
2014-08-22 21:57:56,952 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@50d79dfe
2014-08-22 21:57:56,953 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 21:57:56,954 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 21:57:57,020 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 21:57:57,021 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 21:57:57,021 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 21:57:57,021 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 21:57:57,021 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 21:57:57,024 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 21:57:57,024 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 21:57:57,034 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower.txt"]
2014-08-22 21:57:57,034 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: CoGroup(lower*upper)[by: lower:[{1}:0] upper:[{1}:0]]
2014-08-22 21:57:57,037 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 21:57:57,038 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2014-08-22 21:57:57,038 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2014-08-22 21:57:57,038 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 85; bufvoid = 104857600
2014-08-22 21:57:57,038 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214380(104857520); length = 17/6553600
2014-08-22 21:57:57,041 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2014-08-22 21:57:57,044 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1672432654_0009_m_000000_0 is done. And is in the process of committing
2014-08-22 21:57:57,046 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/lower.txt:0+19
2014-08-22 21:57:57,046 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1672432654_0009_m_000000_0' done.
2014-08-22 21:57:57,046 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1672432654_0009_m_000000_0
2014-08-22 21:57:57,046 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1672432654_0009_m_000001_0
2014-08-22 21:57:57,048 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:57:57,050 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/upper.txt
2014-08-22 21:57:57,050 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@b6c1857
2014-08-22 21:57:57,052 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 21:57:57,052 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 21:57:57,194 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 21:57:57,194 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 21:57:57,195 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 21:57:57,195 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 21:57:57,195 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 21:57:57,196 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 21:57:57,196 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 21:57:57,205 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/upper.txt"]
2014-08-22 21:57:57,205 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: CoGroup(lower*upper)[by: lower:[{1}:0] upper:[{1}:0]]
2014-08-22 21:57:57,208 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 21:57:57,208 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2014-08-22 21:57:57,208 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2014-08-22 21:57:57,208 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 85; bufvoid = 104857600
2014-08-22 21:57:57,209 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214380(104857520); length = 17/6553600
2014-08-22 21:57:57,212 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2014-08-22 21:57:57,214 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1672432654_0009_m_000001_0 is done. And is in the process of committing
2014-08-22 21:57:57,217 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/upper.txt:0+19
2014-08-22 21:57:57,217 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1672432654_0009_m_000001_0' done.
2014-08-22 21:57:57,217 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1672432654_0009_m_000001_0
2014-08-22 21:57:57,217 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 21:57:57,218 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 21:57:57,218 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1672432654_0009_r_000000_0
2014-08-22 21:57:57,220 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:57:57,221 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@12720f6c
2014-08-22 21:57:57,221 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 21:57:57,222 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1672432654_0009_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 21:57:57,225 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#6 about to shuffle output of map attempt_local1672432654_0009_m_000000_0 decomp: 97 len: 101 to MEMORY
2014-08-22 21:57:57,226 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 97 bytes from map-output for attempt_local1672432654_0009_m_000000_0
2014-08-22 21:57:57,226 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 97, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->97
2014-08-22 21:57:57,229 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#6 about to shuffle output of map attempt_local1672432654_0009_m_000001_0 decomp: 97 len: 101 to MEMORY
2014-08-22 21:57:57,230 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 97 bytes from map-output for attempt_local1672432654_0009_m_000001_0
2014-08-22 21:57:57,230 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 97, inMemoryMapOutputs.size() -> 2, commitMemory -> 97, usedMemory ->194
2014-08-22 21:57:57,230 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 21:57:57,234 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 2 / 2 copied.
2014-08-22 21:57:57,235 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 2 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 21:57:57,237 INFO mapred.Merger (Merger.java:merge(589)) - Merging 2 sorted segments
2014-08-22 21:57:57,238 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 21:57:57,240 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 2 segments, 194 bytes to disk to satisfy reduce memory limit
2014-08-22 21:57:57,240 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 196 bytes from disk
2014-08-22 21:57:57,240 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 21:57:57,241 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 21:57:57,241 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 21:57:57,242 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 2 / 2 copied.
2014-08-22 21:57:57,243 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 21:57:57,243 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 21:57:57,251 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: CoGroup(lower*upper)[by: lower:[{1}:0] upper:[{1}:0]]
2014-08-22 21:57:57,252 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/complexcogroup"]
2014-08-22 21:57:57,269 INFO collect.SpillableTupleList (SpillableTupleList.java:getCodecClass(105)) - attempting to load codec: org.apache.hadoop.io.compress.GzipCodec
2014-08-22 21:57:57,269 INFO collect.SpillableTupleList (SpillableTupleList.java:getCodecClass(110)) - found codec: org.apache.hadoop.io.compress.GzipCodec
2014-08-22 21:57:57,277 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1672432654_0009_r_000000_0 is done. And is in the process of committing
2014-08-22 21:57:57,279 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 2 / 2 copied.
2014-08-22 21:57:57,279 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1672432654_0009_r_000000_0 is allowed to commit now
2014-08-22 21:57:57,280 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1672432654_0009_r_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/complexcogroup/_temporary/0/task_local1672432654_0009_r_000000
2014-08-22 21:57:57,282 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 21:57:57,282 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1672432654_0009_r_000000_0' done.
2014-08-22 21:57:57,283 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1672432654_0009_r_000000_0
2014-08-22 21:57:57,283 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 21:57:57,310 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/complexcogroup/_temporary
2014-08-22 21:57:57,346 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:57:57,385 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:57:57,387 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output//hadoop2-mr1/basicpipesplatform/complexcogroup
2014-08-22 21:57:57,408 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 21:57:57,409 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 21:57:57,417 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 21:57:57,420 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 21:57:57,421 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 21:57:57,430 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting
2014-08-22 21:57:57,430 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2014-08-22 21:57:57,431 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] sink: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/replace"]
2014-08-22 21:57:57,431 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] parallel execution is enabled: false
2014-08-22 21:57:57,431 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting jobs: 1
2014-08-22 21:57:57,431 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] allocating threads: 1
2014-08-22 21:57:57,432 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...asicpipesplatform/replace
2014-08-22 21:57:57,432 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:57:57,434 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:57:57,461 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:57:57,499 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 21:57:57,517 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local100025541_0010
2014-08-22 21:57:57,538 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity100025541/.staging/job_local100025541_0010/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:57:57,539 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity100025541/.staging/job_local100025541_0010/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:57:57,592 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local100025541_0010/job_local100025541_0010.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:57:57,593 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local100025541_0010/job_local100025541_0010.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:57:57,594 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 21:57:57,594 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local100025541_0010
2014-08-22 21:57:57,594 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2014-08-22 21:57:57,594 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 21:57:57,595 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 21:57:57,598 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 21:57:57,598 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local100025541_0010_m_000000_0
2014-08-22 21:57:57,601 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:57:57,602 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/apache.10.txt
2014-08-22 21:57:57,603 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@36ed5ba6
2014-08-22 21:57:57,604 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 0
2014-08-22 21:57:57,613 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 21:57:57,613 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 21:57:57,620 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2014-08-22 21:57:57,621 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/replace"]
2014-08-22 21:57:57,624 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 21:57:57,625 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local100025541_0010_m_000000_0 is done. And is in the process of committing
2014-08-22 21:57:57,626 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 21:57:57,627 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local100025541_0010_m_000000_0 is allowed to commit now
2014-08-22 21:57:57,628 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local100025541_0010_m_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/replace/_temporary/0/task_local100025541_0010_m_000000
2014-08-22 21:57:57,629 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/apache.10.txt:0+1449
2014-08-22 21:57:57,629 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local100025541_0010_m_000000_0' done.
2014-08-22 21:57:57,629 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local100025541_0010_m_000000_0
2014-08-22 21:57:57,629 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 21:57:57,650 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/replace/_temporary
2014-08-22 21:57:57,682 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:57:57,684 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output//hadoop2-mr1/basicpipesplatform/replace
2014-08-22 21:57:57,703 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 21:57:57,704 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 21:57:57,713 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 21:57:57,715 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 21:57:57,716 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 21:57:57,723 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] starting
2014-08-22 21:57:57,723 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/ips.20.txt"]
2014-08-22 21:57:57,723 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] sink: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/count2"]
2014-08-22 21:57:57,723 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] parallel execution is enabled: false
2014-08-22 21:57:57,723 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] starting jobs: 1
2014-08-22 21:57:57,723 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] allocating threads: 1
2014-08-22 21:57:57,725 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] starting step: (1/1) ...basicpipesplatform/count2
2014-08-22 21:57:57,726 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:57:57,727 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:57:57,753 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:57:57,772 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 21:57:57,789 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local28023694_0011
2014-08-22 21:57:57,809 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity28023694/.staging/job_local28023694_0011/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:57:57,811 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity28023694/.staging/job_local28023694_0011/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:57:57,868 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local28023694_0011/job_local28023694_0011.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:57:57,869 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local28023694_0011/job_local28023694_0011.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:57:57,869 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 21:57:57,870 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] submitted hadoop job: job_local28023694_0011
2014-08-22 21:57:57,870 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 21:57:57,870 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] tracking url: http://localhost:8080/
2014-08-22 21:57:57,870 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 21:57:57,873 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 21:57:57,873 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local28023694_0011_m_000000_0
2014-08-22 21:57:57,875 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:57:57,877 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/ips.20.txt
2014-08-22 21:57:57,877 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@26966110
2014-08-22 21:57:57,878 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 21:57:57,879 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 21:57:58,022 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 21:57:58,022 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 21:57:58,022 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 21:57:58,023 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 21:57:58,023 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 21:57:58,024 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 21:57:58,024 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 21:57:58,032 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/ips.20.txt"]
2014-08-22 21:57:58,032 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(count)[by:[{1}:1]]
2014-08-22 21:57:58,036 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 21:57:58,036 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2014-08-22 21:57:58,036 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2014-08-22 21:57:58,036 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 466; bufvoid = 104857600
2014-08-22 21:57:58,037 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214320(104857280); length = 77/6553600
2014-08-22 21:57:58,043 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2014-08-22 21:57:58,045 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local28023694_0011_m_000000_0 is done. And is in the process of committing
2014-08-22 21:57:58,047 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/ips.20.txt:0+275
2014-08-22 21:57:58,048 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local28023694_0011_m_000000_0' done.
2014-08-22 21:57:58,048 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local28023694_0011_m_000000_0
2014-08-22 21:57:58,048 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 21:57:58,049 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 21:57:58,049 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local28023694_0011_r_000000_0
2014-08-22 21:57:58,051 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:57:58,051 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@4c23b5c3
2014-08-22 21:57:58,052 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 21:57:58,053 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local28023694_0011_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 21:57:58,055 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#7 about to shuffle output of map attempt_local28023694_0011_m_000000_0 decomp: 508 len: 512 to MEMORY
2014-08-22 21:57:58,055 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 508 bytes from map-output for attempt_local28023694_0011_m_000000_0
2014-08-22 21:57:58,056 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 508, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->508
2014-08-22 21:57:58,056 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 21:57:58,057 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:57:58,058 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 21:57:58,060 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 21:57:58,060 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 21:57:58,062 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 508 bytes to disk to satisfy reduce memory limit
2014-08-22 21:57:58,063 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 512 bytes from disk
2014-08-22 21:57:58,063 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 21:57:58,063 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 21:57:58,063 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 21:57:58,064 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:57:58,064 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 21:57:58,065 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 21:57:58,071 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(count)[by:[{1}:1]]
2014-08-22 21:57:58,071 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/count2"]
2014-08-22 21:57:58,085 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local28023694_0011_r_000000_0 is done. And is in the process of committing
2014-08-22 21:57:58,087 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:57:58,087 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local28023694_0011_r_000000_0 is allowed to commit now
2014-08-22 21:57:58,088 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local28023694_0011_r_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/count2/_temporary/0/task_local28023694_0011_r_000000
2014-08-22 21:57:58,089 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 21:57:58,089 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local28023694_0011_r_000000_0' done.
2014-08-22 21:57:58,090 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local28023694_0011_r_000000_0
2014-08-22 21:57:58,090 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 21:57:58,111 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/count2/_temporary
2014-08-22 21:57:58,141 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:57:58,190 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:57:58,194 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output//hadoop2-mr1/basicpipesplatform/count2
2014-08-22 21:57:58,215 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 21:57:58,215 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 21:57:58,224 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 21:57:58,226 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 21:57:58,227 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 21:57:58,233 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] starting
2014-08-22 21:57:58,233 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/ips.20.txt"]
2014-08-22 21:57:58,234 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] sink: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/count3"]
2014-08-22 21:57:58,234 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] parallel execution is enabled: false
2014-08-22 21:57:58,235 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] starting jobs: 1
2014-08-22 21:57:58,236 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] allocating threads: 1
2014-08-22 21:57:58,237 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] starting step: (1/1) ...basicpipesplatform/count3
2014-08-22 21:57:58,237 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:57:58,239 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:57:58,264 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:57:58,283 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 21:57:58,299 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local27238276_0012
2014-08-22 21:57:58,317 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity27238276/.staging/job_local27238276_0012/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:57:58,318 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity27238276/.staging/job_local27238276_0012/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:57:58,368 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local27238276_0012/job_local27238276_0012.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:57:58,369 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local27238276_0012/job_local27238276_0012.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:57:58,370 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 21:57:58,370 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] submitted hadoop job: job_local27238276_0012
2014-08-22 21:57:58,370 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] tracking url: http://localhost:8080/
2014-08-22 21:57:58,370 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 21:57:58,371 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 21:57:58,374 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 21:57:58,374 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local27238276_0012_m_000000_0
2014-08-22 21:57:58,376 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:57:58,377 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/ips.20.txt
2014-08-22 21:57:58,377 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@7bc7956b
2014-08-22 21:57:58,379 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 21:57:58,379 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 21:57:58,518 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 21:57:58,519 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 21:57:58,519 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 21:57:58,519 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 21:57:58,519 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 21:57:58,520 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 21:57:58,520 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 21:57:58,527 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/ips.20.txt"]
2014-08-22 21:57:58,528 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(count)[by:[{1}:1]]
2014-08-22 21:57:58,532 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 21:57:58,532 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2014-08-22 21:57:58,532 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2014-08-22 21:57:58,532 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 466; bufvoid = 104857600
2014-08-22 21:57:58,532 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214320(104857280); length = 77/6553600
2014-08-22 21:57:58,538 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2014-08-22 21:57:58,540 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local27238276_0012_m_000000_0 is done. And is in the process of committing
2014-08-22 21:57:58,542 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/ips.20.txt:0+275
2014-08-22 21:57:58,542 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local27238276_0012_m_000000_0' done.
2014-08-22 21:57:58,542 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local27238276_0012_m_000000_0
2014-08-22 21:57:58,543 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 21:57:58,543 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 21:57:58,543 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local27238276_0012_r_000000_0
2014-08-22 21:57:58,545 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:57:58,546 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@186458c2
2014-08-22 21:57:58,547 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 21:57:58,548 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local27238276_0012_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 21:57:58,549 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#8 about to shuffle output of map attempt_local27238276_0012_m_000000_0 decomp: 508 len: 512 to MEMORY
2014-08-22 21:57:58,550 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 508 bytes from map-output for attempt_local27238276_0012_m_000000_0
2014-08-22 21:57:58,550 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 508, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->508
2014-08-22 21:57:58,551 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 21:57:58,552 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:57:58,552 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 21:57:58,555 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 21:57:58,557 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 21:57:58,559 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 508 bytes to disk to satisfy reduce memory limit
2014-08-22 21:57:58,559 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 512 bytes from disk
2014-08-22 21:57:58,560 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 21:57:58,560 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 21:57:58,561 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 21:57:58,562 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:57:58,562 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 21:57:58,563 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 21:57:58,570 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(count)[by:[{1}:1]]
2014-08-22 21:57:58,570 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/count3"]
2014-08-22 21:57:58,584 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local27238276_0012_r_000000_0 is done. And is in the process of committing
2014-08-22 21:57:58,585 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:57:58,585 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local27238276_0012_r_000000_0 is allowed to commit now
2014-08-22 21:57:58,586 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local27238276_0012_r_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/count3/_temporary/0/task_local27238276_0012_r_000000
2014-08-22 21:57:58,587 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 21:57:58,588 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local27238276_0012_r_000000_0' done.
2014-08-22 21:57:58,588 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local27238276_0012_r_000000_0
2014-08-22 21:57:58,588 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 21:57:58,614 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/count3/_temporary
2014-08-22 21:57:58,648 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:57:58,680 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:57:58,682 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output//hadoop2-mr1/basicpipesplatform/count3
2014-08-22 21:57:58,701 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 21:57:58,702 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 21:57:58,711 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 21:57:58,713 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 21:57:58,714 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 21:57:58,720 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] starting
2014-08-22 21:57:58,720 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/ips.20.txt"]
2014-08-22 21:57:58,720 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] sink: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/count4"]
2014-08-22 21:57:58,720 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] parallel execution is enabled: false
2014-08-22 21:57:58,720 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] starting jobs: 1
2014-08-22 21:57:58,720 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [count] allocating threads: 1
2014-08-22 21:57:58,721 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] starting step: (1/1) ...basicpipesplatform/count4
2014-08-22 21:57:58,722 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:57:58,723 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:57:58,749 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:57:58,768 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 21:57:58,784 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1133558432_0013
2014-08-22 21:57:58,803 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1133558432/.staging/job_local1133558432_0013/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:57:58,804 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1133558432/.staging/job_local1133558432_0013/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:57:58,865 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1133558432_0013/job_local1133558432_0013.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:57:58,867 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1133558432_0013/job_local1133558432_0013.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:57:58,867 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 21:57:58,868 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] submitted hadoop job: job_local1133558432_0013
2014-08-22 21:57:58,868 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] tracking url: http://localhost:8080/
2014-08-22 21:57:58,868 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 21:57:58,869 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 21:57:58,872 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 21:57:58,872 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1133558432_0013_m_000000_0
2014-08-22 21:57:58,874 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:57:58,876 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/ips.20.txt
2014-08-22 21:57:58,876 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@7de4605c
2014-08-22 21:57:58,877 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 21:57:58,877 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 21:57:58,917 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 21:57:58,917 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 21:57:58,917 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 21:57:58,917 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 21:57:58,917 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 21:57:58,919 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 21:57:58,919 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 21:57:58,926 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/ips.20.txt"]
2014-08-22 21:57:58,927 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(count)[by:[{1}:1]]
2014-08-22 21:57:58,931 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 21:57:58,931 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2014-08-22 21:57:58,931 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2014-08-22 21:57:58,931 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 466; bufvoid = 104857600
2014-08-22 21:57:58,931 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214320(104857280); length = 77/6553600
2014-08-22 21:57:58,937 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2014-08-22 21:57:58,939 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1133558432_0013_m_000000_0 is done. And is in the process of committing
2014-08-22 21:57:58,942 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/ips.20.txt:0+275
2014-08-22 21:57:58,942 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1133558432_0013_m_000000_0' done.
2014-08-22 21:57:58,942 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1133558432_0013_m_000000_0
2014-08-22 21:57:58,942 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 21:57:58,943 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 21:57:58,943 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1133558432_0013_r_000000_0
2014-08-22 21:57:58,945 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:57:58,945 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@4b33650d
2014-08-22 21:57:58,946 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 21:57:58,947 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1133558432_0013_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 21:57:58,949 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#9 about to shuffle output of map attempt_local1133558432_0013_m_000000_0 decomp: 508 len: 512 to MEMORY
2014-08-22 21:57:58,950 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 508 bytes from map-output for attempt_local1133558432_0013_m_000000_0
2014-08-22 21:57:58,950 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 508, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->508
2014-08-22 21:57:58,951 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 21:57:58,952 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:57:58,952 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 21:57:58,954 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 21:57:58,955 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 21:57:58,956 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 508 bytes to disk to satisfy reduce memory limit
2014-08-22 21:57:58,957 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 512 bytes from disk
2014-08-22 21:57:58,957 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 21:57:58,957 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 21:57:58,958 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 21:57:58,958 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:57:58,959 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 21:57:58,959 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 21:57:58,966 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(count)[by:[{1}:1]]
2014-08-22 21:57:58,966 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/count4"]
2014-08-22 21:57:58,989 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1133558432_0013_r_000000_0 is done. And is in the process of committing
2014-08-22 21:57:58,990 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:57:58,991 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1133558432_0013_r_000000_0 is allowed to commit now
2014-08-22 21:57:58,991 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1133558432_0013_r_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/count4/_temporary/0/task_local1133558432_0013_r_000000
2014-08-22 21:57:58,993 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 21:57:58,993 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1133558432_0013_r_000000_0' done.
2014-08-22 21:57:58,993 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1133558432_0013_r_000000_0
2014-08-22 21:57:58,994 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 21:57:59,010 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/count4/_temporary
2014-08-22 21:57:59,040 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:57:59,071 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:57:59,073 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output//hadoop2-mr1/basicpipesplatform/count4
2014-08-22 21:57:59,091 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 21:57:59,091 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 21:57:59,098 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 21:57:59,100 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 21:57:59,100 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 21:57:59,105 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting
2014-08-22 21:57:59,106 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2014-08-22 21:57:59,106 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] sink: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/filter"]
2014-08-22 21:57:59,106 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] parallel execution is enabled: false
2014-08-22 21:57:59,108 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting jobs: 1
2014-08-22 21:57:59,108 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] allocating threads: 1
2014-08-22 21:57:59,109 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...basicpipesplatform/filter
2014-08-22 21:57:59,110 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:57:59,111 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:57:59,134 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:57:59,153 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 21:57:59,169 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1869923487_0014
2014-08-22 21:57:59,188 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1869923487/.staging/job_local1869923487_0014/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:57:59,189 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1869923487/.staging/job_local1869923487_0014/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:57:59,238 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1869923487_0014/job_local1869923487_0014.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:57:59,239 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1869923487_0014/job_local1869923487_0014.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:57:59,240 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 21:57:59,240 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 21:57:59,240 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local1869923487_0014
2014-08-22 21:57:59,241 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 21:57:59,241 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2014-08-22 21:57:59,243 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 21:57:59,244 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1869923487_0014_m_000000_0
2014-08-22 21:57:59,245 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:57:59,247 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/apache.10.txt
2014-08-22 21:57:59,247 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@4eb4dcd9
2014-08-22 21:57:59,248 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 0
2014-08-22 21:57:59,255 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 21:57:59,256 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 21:57:59,261 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2014-08-22 21:57:59,262 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/filter"]
2014-08-22 21:57:59,265 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 21:57:59,265 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1869923487_0014_m_000000_0 is done. And is in the process of committing
2014-08-22 21:57:59,267 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 21:57:59,267 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1869923487_0014_m_000000_0 is allowed to commit now
2014-08-22 21:57:59,268 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1869923487_0014_m_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/filter/_temporary/0/task_local1869923487_0014_m_000000
2014-08-22 21:57:59,269 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/apache.10.txt:0+1449
2014-08-22 21:57:59,269 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1869923487_0014_m_000000_0' done.
2014-08-22 21:57:59,269 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1869923487_0014_m_000000_0
2014-08-22 21:57:59,269 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 21:57:59,286 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/filter/_temporary
2014-08-22 21:57:59,316 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:57:59,318 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output//hadoop2-mr1/basicpipesplatform/filter
2014-08-22 21:57:59,338 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2014-08-22 21:57:59,339 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 21:57:59,349 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2014-08-22 21:57:59,352 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2014-08-22 21:57:59,352 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2014-08-22 21:57:59,359 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting
2014-08-22 21:57:59,359 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2014-08-22 21:57:59,359 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] sink: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/simple"]
2014-08-22 21:57:59,359 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] parallel execution is enabled: false
2014-08-22 21:57:59,360 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] starting jobs: 1
2014-08-22 21:57:59,360 INFO flow.Flow (BaseFlow.java:logInfo(1354)) - [test] allocating threads: 1
2014-08-22 21:57:59,362 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...basicpipesplatform/simple
2014-08-22 21:57:59,362 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:57:59,363 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2014-08-22 21:57:59,387 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:57:59,405 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2014-08-22 21:57:59,421 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1284039480_0015
2014-08-22 21:57:59,439 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1284039480/.staging/job_local1284039480_0015/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:57:59,440 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/staging/teamcity1284039480/.staging/job_local1284039480_0015/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:57:59,486 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1284039480_0015/job_local1284039480_0015.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2014-08-22 21:57:59,487 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1284039480_0015/job_local1284039480_0015.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2014-08-22 21:57:59,488 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2014-08-22 21:57:59,488 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local1284039480_0015
2014-08-22 21:57:59,488 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2014-08-22 21:57:59,489 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2014-08-22 21:57:59,489 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2014-08-22 21:57:59,492 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2014-08-22 21:57:59,492 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1284039480_0015_m_000000_0
2014-08-22 21:57:59,494 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:57:59,496 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/apache.10.txt
2014-08-22 21:57:59,496 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@46f7d5a6
2014-08-22 21:57:59,497 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2014-08-22 21:57:59,497 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2014-08-22 21:57:59,522 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2014-08-22 21:57:59,523 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2014-08-22 21:57:59,523 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2014-08-22 21:57:59,523 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2014-08-22 21:57:59,523 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2014-08-22 21:57:59,525 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.5.6
2014-08-22 21:57:59,525 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2014-08-22 21:57:59,535 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2014-08-22 21:57:59,535 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:0]]
2014-08-22 21:57:59,539 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2014-08-22 21:57:59,539 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2014-08-22 21:57:59,539 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2014-08-22 21:57:59,539 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 210; bufvoid = 104857600
2014-08-22 21:57:59,539 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214360(104857440); length = 37/6553600
2014-08-22 21:57:59,543 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2014-08-22 21:57:59,545 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1284039480_0015_m_000000_0 is done. And is in the process of committing
2014-08-22 21:57:59,547 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/classes/test/data/apache.10.txt:0+1449
2014-08-22 21:57:59,547 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1284039480_0015_m_000000_0' done.
2014-08-22 21:57:59,547 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1284039480_0015_m_000000_0
2014-08-22 21:57:59,548 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2014-08-22 21:57:59,549 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2014-08-22 21:57:59,549 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1284039480_0015_r_000000_0
2014-08-22 21:57:59,550 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2014-08-22 21:57:59,551 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@5ce0f945
2014-08-22 21:57:59,551 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2014-08-22 21:57:59,552 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1284039480_0015_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2014-08-22 21:57:59,554 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#10 about to shuffle output of map attempt_local1284039480_0015_m_000000_0 decomp: 232 len: 236 to MEMORY
2014-08-22 21:57:59,555 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 232 bytes from map-output for attempt_local1284039480_0015_m_000000_0
2014-08-22 21:57:59,555 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 232, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->232
2014-08-22 21:57:59,555 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2014-08-22 21:57:59,556 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:57:59,557 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2014-08-22 21:57:59,559 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 21:57:59,559 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 21:57:59,561 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 232 bytes to disk to satisfy reduce memory limit
2014-08-22 21:57:59,561 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 236 bytes from disk
2014-08-22 21:57:59,561 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2014-08-22 21:57:59,561 INFO mapred.Merger (Merger.java:merge(589)) - Merging 1 sorted segments
2014-08-22 21:57:59,562 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 21:57:59,563 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:57:59,563 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.5.6
2014-08-22 21:57:59,563 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2014-08-22 21:57:59,572 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:0]]
2014-08-22 21:57:59,572 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/simple"]
2014-08-22 21:57:59,583 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1284039480_0015_r_000000_0 is done. And is in the process of committing
2014-08-22 21:57:59,584 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2014-08-22 21:57:59,584 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1284039480_0015_r_000000_0 is allowed to commit now
2014-08-22 21:57:59,585 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1284039480_0015_r_000000_0' to file:/opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/simple/_temporary/0/task_local1284039480_0015_r_000000
2014-08-22 21:57:59,587 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2014-08-22 21:57:59,587 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1284039480_0015_r_000000_0' done.
2014-08-22 21:57:59,587 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1284039480_0015_r_000000_0
2014-08-22 21:57:59,587 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2014-08-22 21:57:59,613 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/simple/_temporary
2014-08-22 21:57:59,647 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2014-08-22 21:57:59,649 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/3945655b04626318/apache-2.4.x/build/test/output//hadoop2-mr1/basicpipesplatform/simple