2015-02-10 23:21:17,681 INFO platform.PlatformRunner (PlatformRunner.java:getPlatformClassesFromClasspath(187)) - found 1 test platforms from classpath
2015-02-10 23:21:17,745 INFO platform.PlatformRunner (PlatformRunner.java:addPlatform(237)) - installing platform: hadoop2-mr1
2015-02-10 23:21:17,745 INFO platform.PlatformRunner (PlatformRunner.java:addPlatform(238)) - running test: cascading.BasicPipesPlatformTest
2015-02-10 23:21:17,785 INFO hadoop2.Hadoop2MR1Platform (Hadoop2MR1Platform.java:setUp(105)) - not using cluster
2015-02-10 23:21:18,443 WARN util.NativeCodeLoader (NativeCodeLoader.java:<clinit>(62)) - Unable to load native-hadoop library for your platform... using builtin-java classes where applicable
2015-02-10 23:21:18,754 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 23:21:18,756 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.6.3/9ae016e2b8d246b9c1de9168e715d9f1b971aa4a/cascading-hadoop2-mr1-2.6.3.jar
2015-02-10 23:21:18,768 INFO property.AppProps (AppProps.java:getAppID(169)) - using app.id: 2E1628B4226F49858CC95DD14658475E
2015-02-10 23:21:18,860 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 23:21:18,907 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 23:21:18,992 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 23:21:19,059 INFO util.Version (Version.java:printBanner(82)) - Concurrent, Inc - Cascading 2.6.3
2015-02-10 23:21:19,062 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting
2015-02-10 23:21:19,063 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/apache.10.txt"]
2015-02-10 23:21:19,063 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] sink: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/simplechain"]
2015-02-10 23:21:19,064 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] parallel execution is enabled: false
2015-02-10 23:21:19,065 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting jobs: 2
2015-02-10 23:21:19,066 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] allocating threads: 1
2015-02-10 23:21:19,067 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/2)
2015-02-10 23:21:19,093 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - session.id is deprecated. Instead, use dfs.metrics.session-id
2015-02-10 23:21:19,095 INFO jvm.JvmMetrics (JvmMetrics.java:init(76)) - Initializing JVM Metrics with processName=JobTracker, sessionId=
2015-02-10 23:21:19,119 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 23:21:19,515 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 23:21:19,560 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 23:21:19,734 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local252753739_0001
2015-02-10 23:21:19,775 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/tmp/cascading/staging/teamcity252753739/.staging/job_local252753739_0001/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 23:21:19,782 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/tmp/cascading/staging/teamcity252753739/.staging/job_local252753739_0001/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 23:21:19,917 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local252753739_0001/job_local252753739_0001.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 23:21:19,921 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local252753739_0001/job_local252753739_0001.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 23:21:19,928 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 23:21:19,929 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 23:21:19,932 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local252753739_0001
2015-02-10 23:21:19,933 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 23:21:19,933 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2015-02-10 23:21:19,974 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 23:21:19,978 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local252753739_0001_m_000000_0
2015-02-10 23:21:20,020 INFO mapred.Task (Task.java:initialize(587)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 23:21:20,031 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/apache.10.txt
2015-02-10 23:21:20,031 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@20c62080
2015-02-10 23:21:20,041 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-10 23:21:20,048 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-10 23:21:20,198 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-10 23:21:20,199 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-10 23:21:20,199 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-10 23:21:20,199 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-10 23:21:20,199 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-10 23:21:20,226 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 23:21:20,226 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 23:21:20,277 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.task.partition is deprecated. Instead, use mapreduce.task.partition
2015-02-10 23:21:20,296 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/apache.10.txt"]
2015-02-10 23:21:20,296 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:0]]
2015-02-10 23:21:20,312 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 23:21:20,313 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2015-02-10 23:21:20,313 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2015-02-10 23:21:20,313 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 210; bufvoid = 104857600
2015-02-10 23:21:20,313 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214360(104857440); length = 37/6553600
2015-02-10 23:21:20,327 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2015-02-10 23:21:20,331 INFO mapred.Task (Task.java:done(1001)) - Task:attempt_local252753739_0001_m_000000_0 is done. And is in the process of committing
2015-02-10 23:21:20,350 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/apache.10.txt:0+1449
2015-02-10 23:21:20,350 INFO mapred.Task (Task.java:sendDone(1121)) - Task 'attempt_local252753739_0001_m_000000_0' done.
2015-02-10 23:21:20,350 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local252753739_0001_m_000000_0
2015-02-10 23:21:20,351 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 23:21:20,354 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2015-02-10 23:21:20,354 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local252753739_0001_r_000000_0
2015-02-10 23:21:20,363 INFO mapred.Task (Task.java:initialize(587)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 23:21:20,366 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@6d0718b7
2015-02-10 23:21:20,381 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2015-02-10 23:21:20,384 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local252753739_0001_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2015-02-10 23:21:20,418 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#1 about to shuffle output of map attempt_local252753739_0001_m_000000_0 decomp: 232 len: 236 to MEMORY
2015-02-10 23:21:20,423 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 232 bytes from map-output for attempt_local252753739_0001_m_000000_0
2015-02-10 23:21:20,464 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 232, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->232
2015-02-10 23:21:20,465 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2015-02-10 23:21:20,466 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 23:21:20,467 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2015-02-10 23:21:20,476 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 23:21:20,477 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 211 bytes
2015-02-10 23:21:20,480 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 232 bytes to disk to satisfy reduce memory limit
2015-02-10 23:21:20,481 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 236 bytes from disk
2015-02-10 23:21:20,481 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2015-02-10 23:21:20,482 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 23:21:20,482 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 211 bytes
2015-02-10 23:21:20,483 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 23:21:20,485 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.6.3
2015-02-10 23:21:20,485 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2015-02-10 23:21:20,503 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:0]]
2015-02-10 23:21:20,503 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: TempHfs["SequenceFile[[0, 'count']]"][9859779079/test/]
2015-02-10 23:21:20,541 INFO mapred.Task (Task.java:done(1001)) - Task:attempt_local252753739_0001_r_000000_0 is done. And is in the process of committing
2015-02-10 23:21:20,543 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 23:21:20,544 INFO mapred.Task (Task.java:commit(1162)) - Task attempt_local252753739_0001_r_000000_0 is allowed to commit now
2015-02-10 23:21:20,545 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local252753739_0001_r_000000_0' to file:/tmp/hadoop-teamcity/9859779079_test_E0F44CBDB7BC448AADCCA9231B03DE4F/_temporary/0/task_local252753739_0001_r_000000
2015-02-10 23:21:20,547 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2015-02-10 23:21:20,547 INFO mapred.Task (Task.java:sendDone(1121)) - Task 'attempt_local252753739_0001_r_000000_0' done.
2015-02-10 23:21:20,547 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local252753739_0001_r_000000_0
2015-02-10 23:21:20,547 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2015-02-10 23:21:20,584 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (2/2) ...pipesplatform/simplechain
2015-02-10 23:21:20,585 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 23:21:20,587 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 23:21:20,637 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 23:21:20,665 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 23:21:20,681 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 23:21:20,682 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 23:21:20,701 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1851478551_0002
2015-02-10 23:21:20,724 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/tmp/cascading/staging/teamcity1851478551/.staging/job_local1851478551_0002/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 23:21:20,728 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/tmp/cascading/staging/teamcity1851478551/.staging/job_local1851478551_0002/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 23:21:20,823 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1851478551_0002/job_local1851478551_0002.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 23:21:20,827 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1851478551_0002/job_local1851478551_0002.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 23:21:20,827 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 23:21:20,828 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 23:21:20,828 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 23:21:20,828 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local1851478551_0002
2015-02-10 23:21:20,830 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2015-02-10 23:21:20,834 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 23:21:20,834 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1851478551_0002_m_000000_0
2015-02-10 23:21:20,837 INFO mapred.Task (Task.java:initialize(587)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 23:21:20,839 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/tmp/hadoop-teamcity/9859779079_test_E0F44CBDB7BC448AADCCA9231B03DE4F/part-00000
2015-02-10 23:21:20,840 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@7dc8f91e
2015-02-10 23:21:20,852 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-10 23:21:20,852 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-10 23:21:20,995 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-10 23:21:20,996 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-10 23:21:20,996 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-10 23:21:20,996 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-10 23:21:20,996 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-10 23:21:20,998 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 23:21:20,998 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 23:21:21,010 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: TempHfs["SequenceFile[[0, 'count']]"][9859779079/test/]
2015-02-10 23:21:21,010 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:0]]
2015-02-10 23:21:21,014 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 23:21:21,014 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2015-02-10 23:21:21,014 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2015-02-10 23:21:21,015 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 184; bufvoid = 104857600
2015-02-10 23:21:21,015 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214368(104857472); length = 29/6553600
2015-02-10 23:21:21,021 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2015-02-10 23:21:21,025 INFO mapred.Task (Task.java:done(1001)) - Task:attempt_local1851478551_0002_m_000000_0 is done. And is in the process of committing
2015-02-10 23:21:21,028 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/tmp/hadoop-teamcity/9859779079_test_E0F44CBDB7BC448AADCCA9231B03DE4F/part-00000:0+310
2015-02-10 23:21:21,028 INFO mapred.Task (Task.java:sendDone(1121)) - Task 'attempt_local1851478551_0002_m_000000_0' done.
2015-02-10 23:21:21,029 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1851478551_0002_m_000000_0
2015-02-10 23:21:21,029 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 23:21:21,030 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2015-02-10 23:21:21,030 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1851478551_0002_r_000000_0
2015-02-10 23:21:21,033 INFO mapred.Task (Task.java:initialize(587)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 23:21:21,033 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@2b52b6f5
2015-02-10 23:21:21,034 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2015-02-10 23:21:21,035 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1851478551_0002_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2015-02-10 23:21:21,038 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#2 about to shuffle output of map attempt_local1851478551_0002_m_000000_0 decomp: 202 len: 206 to MEMORY
2015-02-10 23:21:21,038 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 202 bytes from map-output for attempt_local1851478551_0002_m_000000_0
2015-02-10 23:21:21,039 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 202, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->202
2015-02-10 23:21:21,039 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2015-02-10 23:21:21,042 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 23:21:21,043 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2015-02-10 23:21:21,047 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 23:21:21,047 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 181 bytes
2015-02-10 23:21:21,050 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 202 bytes to disk to satisfy reduce memory limit
2015-02-10 23:21:21,051 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 206 bytes from disk
2015-02-10 23:21:21,051 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2015-02-10 23:21:21,051 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 23:21:21,052 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 181 bytes
2015-02-10 23:21:21,053 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 23:21:21,053 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.6.3
2015-02-10 23:21:21,053 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2015-02-10 23:21:21,065 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:0]]
2015-02-10 23:21:21,065 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/simplechain"]
2015-02-10 23:21:21,083 INFO mapred.Task (Task.java:done(1001)) - Task:attempt_local1851478551_0002_r_000000_0 is done. And is in the process of committing
2015-02-10 23:21:21,085 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 23:21:21,086 INFO mapred.Task (Task.java:commit(1162)) - Task attempt_local1851478551_0002_r_000000_0 is allowed to commit now
2015-02-10 23:21:21,088 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1851478551_0002_r_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/simplechain/_temporary/0/task_local1851478551_0002_r_000000
2015-02-10 23:21:21,090 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2015-02-10 23:21:21,090 INFO mapred.Task (Task.java:sendDone(1121)) - Task 'attempt_local1851478551_0002_r_000000_0' done.
2015-02-10 23:21:21,091 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1851478551_0002_r_000000_0
2015-02-10 23:21:21,091 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2015-02-10 23:21:21,122 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/simplechain/_temporary
2015-02-10 23:21:21,165 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 23:21:21,168 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output//hadoop2-mr1/basicpipesplatform/simplechain
2015-02-10 23:21:21,204 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 23:21:21,205 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.6.3/9ae016e2b8d246b9c1de9168e715d9f1b971aa4a/cascading-hadoop2-mr1-2.6.3.jar
2015-02-10 23:21:21,220 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 23:21:21,225 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 23:21:21,226 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 23:21:21,236 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] starting
2015-02-10 23:21:21,236 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/ips.20.txt"]
2015-02-10 23:21:21,236 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] sink: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/count"]
2015-02-10 23:21:21,238 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] parallel execution is enabled: false
2015-02-10 23:21:21,238 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] starting jobs: 1
2015-02-10 23:21:21,238 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] allocating threads: 1
2015-02-10 23:21:21,246 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] starting step: (1/1) .../basicpipesplatform/count
2015-02-10 23:21:21,252 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 23:21:21,257 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 23:21:21,291 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 23:21:21,317 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 23:21:21,397 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1729894879_0003
2015-02-10 23:21:21,428 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/tmp/cascading/staging/teamcity1729894879/.staging/job_local1729894879_0003/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 23:21:21,431 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/tmp/cascading/staging/teamcity1729894879/.staging/job_local1729894879_0003/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 23:21:21,509 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1729894879_0003/job_local1729894879_0003.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 23:21:21,511 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1729894879_0003/job_local1729894879_0003.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 23:21:21,512 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 23:21:21,513 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] submitted hadoop job: job_local1729894879_0003
2015-02-10 23:21:21,513 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] tracking url: http://localhost:8080/
2015-02-10 23:21:21,513 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 23:21:21,513 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 23:21:21,519 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 23:21:21,519 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1729894879_0003_m_000000_0
2015-02-10 23:21:21,522 INFO mapred.Task (Task.java:initialize(587)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 23:21:21,525 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/ips.20.txt
2015-02-10 23:21:21,525 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@5e917cb0
2015-02-10 23:21:21,528 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-10 23:21:21,529 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-10 23:21:21,692 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-10 23:21:21,693 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-10 23:21:21,693 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-10 23:21:21,693 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-10 23:21:21,693 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-10 23:21:21,697 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 23:21:21,697 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 23:21:21,707 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/ips.20.txt"]
2015-02-10 23:21:21,708 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(count)[by:[{1}:1]]
2015-02-10 23:21:21,712 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 23:21:21,713 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2015-02-10 23:21:21,713 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2015-02-10 23:21:21,713 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 466; bufvoid = 104857600
2015-02-10 23:21:21,713 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214320(104857280); length = 77/6553600
2015-02-10 23:21:21,721 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2015-02-10 23:21:21,724 INFO mapred.Task (Task.java:done(1001)) - Task:attempt_local1729894879_0003_m_000000_0 is done. And is in the process of committing
2015-02-10 23:21:21,727 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/ips.20.txt:0+275
2015-02-10 23:21:21,727 INFO mapred.Task (Task.java:sendDone(1121)) - Task 'attempt_local1729894879_0003_m_000000_0' done.
2015-02-10 23:21:21,727 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1729894879_0003_m_000000_0
2015-02-10 23:21:21,728 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 23:21:21,728 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2015-02-10 23:21:21,729 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1729894879_0003_r_000000_0
2015-02-10 23:21:21,731 INFO mapred.Task (Task.java:initialize(587)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 23:21:21,732 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@7ea96606
2015-02-10 23:21:21,733 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2015-02-10 23:21:21,733 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1729894879_0003_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2015-02-10 23:21:21,736 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#3 about to shuffle output of map attempt_local1729894879_0003_m_000000_0 decomp: 508 len: 512 to MEMORY
2015-02-10 23:21:21,736 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 508 bytes from map-output for attempt_local1729894879_0003_m_000000_0
2015-02-10 23:21:21,737 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 508, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->508
2015-02-10 23:21:21,737 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2015-02-10 23:21:21,739 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 23:21:21,739 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2015-02-10 23:21:21,742 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 23:21:21,743 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 487 bytes
2015-02-10 23:21:21,745 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 508 bytes to disk to satisfy reduce memory limit
2015-02-10 23:21:21,746 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 512 bytes from disk
2015-02-10 23:21:21,746 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2015-02-10 23:21:21,746 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 23:21:21,747 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 487 bytes
2015-02-10 23:21:21,747 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 23:21:21,748 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.6.3
2015-02-10 23:21:21,748 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2015-02-10 23:21:21,758 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(count)[by:[{1}:1]]
2015-02-10 23:21:21,758 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/count"]
2015-02-10 23:21:21,775 INFO mapred.Task (Task.java:done(1001)) - Task:attempt_local1729894879_0003_r_000000_0 is done. And is in the process of committing
2015-02-10 23:21:21,777 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 23:21:21,777 INFO mapred.Task (Task.java:commit(1162)) - Task attempt_local1729894879_0003_r_000000_0 is allowed to commit now
2015-02-10 23:21:21,778 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1729894879_0003_r_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/count/_temporary/0/task_local1729894879_0003_r_000000
2015-02-10 23:21:21,780 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2015-02-10 23:21:21,780 INFO mapred.Task (Task.java:sendDone(1121)) - Task 'attempt_local1729894879_0003_r_000000_0' done.
2015-02-10 23:21:21,780 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1729894879_0003_r_000000_0
2015-02-10 23:21:21,780 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2015-02-10 23:21:21,822 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/count/_temporary
2015-02-10 23:21:21,861 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 23:21:21,901 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 23:21:21,906 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output//hadoop2-mr1/basicpipesplatform/count
2015-02-10 23:21:21,933 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 23:21:21,934 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.6.3/9ae016e2b8d246b9c1de9168e715d9f1b971aa4a/cascading-hadoop2-mr1-2.6.3.jar
2015-02-10 23:21:21,947 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 23:21:21,952 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 23:21:21,953 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 23:21:21,964 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting
2015-02-10 23:21:21,964 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/apache.10.txt"]
2015-02-10 23:21:21,965 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] sink: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/swap"]
2015-02-10 23:21:21,965 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] parallel execution is enabled: false
2015-02-10 23:21:21,965 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting jobs: 1
2015-02-10 23:21:21,965 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] allocating threads: 1
2015-02-10 23:21:21,966 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...1/basicpipesplatform/swap
2015-02-10 23:21:21,967 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 23:21:21,969 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 23:21:22,004 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 23:21:22,029 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 23:21:22,055 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1119684745_0004
2015-02-10 23:21:22,078 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/tmp/cascading/staging/teamcity1119684745/.staging/job_local1119684745_0004/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 23:21:22,079 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/tmp/cascading/staging/teamcity1119684745/.staging/job_local1119684745_0004/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 23:21:22,161 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1119684745_0004/job_local1119684745_0004.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 23:21:22,163 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1119684745_0004/job_local1119684745_0004.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 23:21:22,164 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 23:21:22,165 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local1119684745_0004
2015-02-10 23:21:22,165 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 23:21:22,165 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2015-02-10 23:21:22,166 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 23:21:22,170 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 23:21:22,170 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1119684745_0004_m_000000_0
2015-02-10 23:21:22,172 INFO mapred.Task (Task.java:initialize(587)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 23:21:22,174 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/apache.10.txt
2015-02-10 23:21:22,175 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@71d9d55b
2015-02-10 23:21:22,176 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 0
2015-02-10 23:21:22,187 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 23:21:22,187 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 23:21:22,196 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/apache.10.txt"]
2015-02-10 23:21:22,196 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/swap"]
2015-02-10 23:21:22,201 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 23:21:22,201 INFO mapred.Task (Task.java:done(1001)) - Task:attempt_local1119684745_0004_m_000000_0 is done. And is in the process of committing
2015-02-10 23:21:22,203 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 23:21:22,203 INFO mapred.Task (Task.java:commit(1162)) - Task attempt_local1119684745_0004_m_000000_0 is allowed to commit now
2015-02-10 23:21:22,204 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1119684745_0004_m_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/swap/_temporary/0/task_local1119684745_0004_m_000000
2015-02-10 23:21:22,205 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/apache.10.txt:0+1449
2015-02-10 23:21:22,206 INFO mapred.Task (Task.java:sendDone(1121)) - Task 'attempt_local1119684745_0004_m_000000_0' done.
2015-02-10 23:21:22,206 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1119684745_0004_m_000000_0
2015-02-10 23:21:22,206 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 23:21:22,223 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/swap/_temporary
2015-02-10 23:21:22,259 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 23:21:22,263 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output//hadoop2-mr1/basicpipesplatform/swap
2015-02-10 23:21:22,293 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 23:21:22,294 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.6.3/9ae016e2b8d246b9c1de9168e715d9f1b971aa4a/cascading-hadoop2-mr1-2.6.3.jar
2015-02-10 23:21:22,307 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 23:21:22,312 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 23:21:22,313 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 23:21:22,326 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting
2015-02-10 23:21:22,326 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/lower+upper.txt"]
2015-02-10 23:21:22,326 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] sink: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/ungrouped"]
2015-02-10 23:21:22,327 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] parallel execution is enabled: false
2015-02-10 23:21:22,327 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting jobs: 1
2015-02-10 23:21:22,327 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] allocating threads: 1
2015-02-10 23:21:22,328 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...icpipesplatform/ungrouped
2015-02-10 23:21:22,330 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 23:21:22,331 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 23:21:22,363 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 23:21:22,387 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 23:21:22,410 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1593774915_0005
2015-02-10 23:21:22,434 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/tmp/cascading/staging/teamcity1593774915/.staging/job_local1593774915_0005/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 23:21:22,436 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/tmp/cascading/staging/teamcity1593774915/.staging/job_local1593774915_0005/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 23:21:22,511 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1593774915_0005/job_local1593774915_0005.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 23:21:22,513 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1593774915_0005/job_local1593774915_0005.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 23:21:22,514 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 23:21:22,514 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local1593774915_0005
2015-02-10 23:21:22,515 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2015-02-10 23:21:22,516 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 23:21:22,516 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 23:21:22,521 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 23:21:22,521 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1593774915_0005_m_000000_0
2015-02-10 23:21:22,524 INFO mapred.Task (Task.java:initialize(587)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 23:21:22,526 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/lower+upper.txt
2015-02-10 23:21:22,526 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@6b4d6015
2015-02-10 23:21:22,528 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 0
2015-02-10 23:21:22,539 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 23:21:22,539 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 23:21:22,548 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/lower+upper.txt"]
2015-02-10 23:21:22,548 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/ungrouped"]
2015-02-10 23:21:22,552 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 23:21:22,553 INFO mapred.Task (Task.java:done(1001)) - Task:attempt_local1593774915_0005_m_000000_0 is done. And is in the process of committing
2015-02-10 23:21:22,555 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 23:21:22,555 INFO mapred.Task (Task.java:commit(1162)) - Task attempt_local1593774915_0005_m_000000_0 is allowed to commit now
2015-02-10 23:21:22,556 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1593774915_0005_m_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/ungrouped/_temporary/0/task_local1593774915_0005_m_000000
2015-02-10 23:21:22,557 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/lower+upper.txt:0+30
2015-02-10 23:21:22,558 INFO mapred.Task (Task.java:sendDone(1121)) - Task 'attempt_local1593774915_0005_m_000000_0' done.
2015-02-10 23:21:22,558 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1593774915_0005_m_000000_0
2015-02-10 23:21:22,558 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 23:21:22,596 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/ungrouped/_temporary
2015-02-10 23:21:22,631 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 23:21:22,633 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output//hadoop2-mr1/basicpipesplatform/ungrouped
2015-02-10 23:21:22,659 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 23:21:22,660 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.6.3/9ae016e2b8d246b9c1de9168e715d9f1b971aa4a/cascading-hadoop2-mr1-2.6.3.jar
2015-02-10 23:21:22,673 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 23:21:22,678 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 23:21:22,679 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 23:21:22,688 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting
2015-02-10 23:21:22,689 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/apache.10.txt"]
2015-02-10 23:21:22,689 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] sink: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/simplerelative"]
2015-02-10 23:21:22,690 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] parallel execution is enabled: false
2015-02-10 23:21:22,690 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting jobs: 1
2015-02-10 23:21:22,690 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] allocating threads: 1
2015-02-10 23:21:22,690 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...esplatform/simplerelative
2015-02-10 23:21:22,691 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 23:21:22,693 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 23:21:22,722 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 23:21:22,744 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 23:21:22,762 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local2078116698_0006
2015-02-10 23:21:22,782 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/tmp/cascading/staging/teamcity2078116698/.staging/job_local2078116698_0006/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 23:21:22,783 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/tmp/cascading/staging/teamcity2078116698/.staging/job_local2078116698_0006/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 23:21:22,839 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local2078116698_0006/job_local2078116698_0006.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 23:21:22,840 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local2078116698_0006/job_local2078116698_0006.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 23:21:22,841 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 23:21:22,841 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local2078116698_0006
2015-02-10 23:21:22,842 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 23:21:22,842 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2015-02-10 23:21:22,842 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 23:21:22,845 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 23:21:22,846 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local2078116698_0006_m_000000_0
2015-02-10 23:21:22,848 INFO mapred.Task (Task.java:initialize(587)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 23:21:22,850 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/apache.10.txt
2015-02-10 23:21:22,850 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@485b701a
2015-02-10 23:21:22,851 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-10 23:21:22,852 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-10 23:21:22,994 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-10 23:21:22,995 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-10 23:21:22,995 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-10 23:21:22,995 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-10 23:21:22,995 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-10 23:21:22,996 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 23:21:22,997 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 23:21:23,006 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/apache.10.txt"]
2015-02-10 23:21:23,007 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:0]]
2015-02-10 23:21:23,011 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 23:21:23,011 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2015-02-10 23:21:23,011 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2015-02-10 23:21:23,011 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 210; bufvoid = 104857600
2015-02-10 23:21:23,011 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214360(104857440); length = 37/6553600
2015-02-10 23:21:23,016 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2015-02-10 23:21:23,019 INFO mapred.Task (Task.java:done(1001)) - Task:attempt_local2078116698_0006_m_000000_0 is done. And is in the process of committing
2015-02-10 23:21:23,021 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/apache.10.txt:0+1449
2015-02-10 23:21:23,022 INFO mapred.Task (Task.java:sendDone(1121)) - Task 'attempt_local2078116698_0006_m_000000_0' done.
2015-02-10 23:21:23,022 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local2078116698_0006_m_000000_0
2015-02-10 23:21:23,022 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 23:21:23,023 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2015-02-10 23:21:23,023 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local2078116698_0006_r_000000_0
2015-02-10 23:21:23,025 INFO mapred.Task (Task.java:initialize(587)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 23:21:23,025 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@6d59d450
2015-02-10 23:21:23,026 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2015-02-10 23:21:23,027 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local2078116698_0006_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2015-02-10 23:21:23,029 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#4 about to shuffle output of map attempt_local2078116698_0006_m_000000_0 decomp: 232 len: 236 to MEMORY
2015-02-10 23:21:23,030 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 232 bytes from map-output for attempt_local2078116698_0006_m_000000_0
2015-02-10 23:21:23,030 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 232, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->232
2015-02-10 23:21:23,031 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2015-02-10 23:21:23,032 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 23:21:23,032 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2015-02-10 23:21:23,035 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 23:21:23,035 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 211 bytes
2015-02-10 23:21:23,037 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 232 bytes to disk to satisfy reduce memory limit
2015-02-10 23:21:23,037 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 236 bytes from disk
2015-02-10 23:21:23,038 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2015-02-10 23:21:23,038 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 23:21:23,038 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 211 bytes
2015-02-10 23:21:23,039 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 23:21:23,039 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.6.3
2015-02-10 23:21:23,040 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2015-02-10 23:21:23,049 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:0]]
2015-02-10 23:21:23,049 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/simplerelative"]
2015-02-10 23:21:23,063 INFO mapred.Task (Task.java:done(1001)) - Task:attempt_local2078116698_0006_r_000000_0 is done. And is in the process of committing
2015-02-10 23:21:23,064 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 23:21:23,065 INFO mapred.Task (Task.java:commit(1162)) - Task attempt_local2078116698_0006_r_000000_0 is allowed to commit now
2015-02-10 23:21:23,066 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local2078116698_0006_r_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/simplerelative/_temporary/0/task_local2078116698_0006_r_000000
2015-02-10 23:21:23,067 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2015-02-10 23:21:23,067 INFO mapred.Task (Task.java:sendDone(1121)) - Task 'attempt_local2078116698_0006_r_000000_0' done.
2015-02-10 23:21:23,068 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local2078116698_0006_r_000000_0
2015-02-10 23:21:23,068 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2015-02-10 23:21:23,095 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/simplerelative/_temporary
2015-02-10 23:21:23,129 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 23:21:23,132 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output//hadoop2-mr1/basicpipesplatform/simplerelative
2015-02-10 23:21:23,305 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 23:21:23,306 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.6.3/9ae016e2b8d246b9c1de9168e715d9f1b971aa4a/cascading-hadoop2-mr1-2.6.3.jar
2015-02-10 23:21:23,321 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 23:21:23,324 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 23:21:23,325 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 23:21:23,344 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting
2015-02-10 23:21:23,345 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/lower.txt"]
2015-02-10 23:21:23,346 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] sink: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/simpleresult"]
2015-02-10 23:21:23,346 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] parallel execution is enabled: false
2015-02-10 23:21:23,347 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting jobs: 1
2015-02-10 23:21:23,348 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] allocating threads: 1
2015-02-10 23:21:23,349 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...ipesplatform/simpleresult
2015-02-10 23:21:23,349 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 23:21:23,351 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 23:21:23,381 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 23:21:23,404 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 23:21:23,424 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1909381511_0007
2015-02-10 23:21:23,443 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/tmp/cascading/staging/teamcity1909381511/.staging/job_local1909381511_0007/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 23:21:23,444 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/tmp/cascading/staging/teamcity1909381511/.staging/job_local1909381511_0007/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 23:21:23,500 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1909381511_0007/job_local1909381511_0007.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 23:21:23,501 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1909381511_0007/job_local1909381511_0007.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 23:21:23,502 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 23:21:23,502 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local1909381511_0007
2015-02-10 23:21:23,502 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 23:21:23,503 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2015-02-10 23:21:23,503 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 23:21:23,506 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 23:21:23,507 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1909381511_0007_m_000000_0
2015-02-10 23:21:23,509 INFO mapred.Task (Task.java:initialize(587)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 23:21:23,511 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/lower.txt
2015-02-10 23:21:23,511 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@3415ddf5
2015-02-10 23:21:23,513 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-10 23:21:23,513 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-10 23:21:23,654 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-10 23:21:23,654 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-10 23:21:23,654 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-10 23:21:23,654 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-10 23:21:23,654 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-10 23:21:23,656 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 23:21:23,656 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 23:21:23,668 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/lower.txt"]
2015-02-10 23:21:23,669 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:0]]
2015-02-10 23:21:23,767 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 23:21:23,768 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2015-02-10 23:21:23,768 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2015-02-10 23:21:23,768 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 22; bufvoid = 104857600
2015-02-10 23:21:23,768 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214392(104857568); length = 5/6553600
2015-02-10 23:21:23,835 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2015-02-10 23:21:23,838 INFO mapred.Task (Task.java:done(1001)) - Task:attempt_local1909381511_0007_m_000000_0 is done. And is in the process of committing
2015-02-10 23:21:23,840 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/lower.txt:0+19
2015-02-10 23:21:23,841 INFO mapred.Task (Task.java:sendDone(1121)) - Task 'attempt_local1909381511_0007_m_000000_0' done.
2015-02-10 23:21:23,841 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1909381511_0007_m_000000_0
2015-02-10 23:21:23,841 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 23:21:23,842 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2015-02-10 23:21:23,842 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1909381511_0007_r_000000_0
2015-02-10 23:21:23,844 INFO mapred.Task (Task.java:initialize(587)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 23:21:23,845 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@1a07ac6c
2015-02-10 23:21:23,846 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2015-02-10 23:21:23,847 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1909381511_0007_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2015-02-10 23:21:23,850 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#5 about to shuffle output of map attempt_local1909381511_0007_m_000000_0 decomp: 28 len: 32 to MEMORY
2015-02-10 23:21:23,850 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 28 bytes from map-output for attempt_local1909381511_0007_m_000000_0
2015-02-10 23:21:23,851 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 28, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->28
2015-02-10 23:21:23,852 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2015-02-10 23:21:23,853 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 23:21:23,853 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2015-02-10 23:21:23,857 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 23:21:23,857 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 17 bytes
2015-02-10 23:21:23,859 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 28 bytes to disk to satisfy reduce memory limit
2015-02-10 23:21:23,860 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 32 bytes from disk
2015-02-10 23:21:23,860 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2015-02-10 23:21:23,860 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 23:21:23,861 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 17 bytes
2015-02-10 23:21:23,862 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 23:21:23,863 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.6.3
2015-02-10 23:21:23,863 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2015-02-10 23:21:23,874 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:0]]
2015-02-10 23:21:23,875 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/simpleresult"]
2015-02-10 23:21:23,886 INFO mapred.Task (Task.java:done(1001)) - Task:attempt_local1909381511_0007_r_000000_0 is done. And is in the process of committing
2015-02-10 23:21:23,888 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 23:21:23,888 INFO mapred.Task (Task.java:commit(1162)) - Task attempt_local1909381511_0007_r_000000_0 is allowed to commit now
2015-02-10 23:21:23,889 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1909381511_0007_r_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/simpleresult/_temporary/0/task_local1909381511_0007_r_000000
2015-02-10 23:21:23,890 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2015-02-10 23:21:23,891 INFO mapred.Task (Task.java:sendDone(1121)) - Task 'attempt_local1909381511_0007_r_000000_0' done.
2015-02-10 23:21:23,891 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1909381511_0007_r_000000_0
2015-02-10 23:21:23,891 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2015-02-10 23:21:23,917 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/simpleresult/_temporary
2015-02-10 23:21:23,951 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 23:21:23,953 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output//hadoop2-mr1/basicpipesplatform/simpleresult
2015-02-10 23:21:23,978 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 23:21:23,978 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.6.3/9ae016e2b8d246b9c1de9168e715d9f1b971aa4a/cascading-hadoop2-mr1-2.6.3.jar
2015-02-10 23:21:23,989 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 23:21:23,993 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 23:21:23,994 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 23:21:24,002 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting
2015-02-10 23:21:24,002 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/apache.10.txt"]
2015-02-10 23:21:24,003 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] sink: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/filterall"]
2015-02-10 23:21:24,004 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] parallel execution is enabled: false
2015-02-10 23:21:24,004 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting jobs: 1
2015-02-10 23:21:24,006 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] allocating threads: 1
2015-02-10 23:21:24,008 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...icpipesplatform/filterall
2015-02-10 23:21:24,009 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 23:21:24,010 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 23:21:24,041 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 23:21:24,064 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 23:21:24,088 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local542356014_0008
2015-02-10 23:21:24,113 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/tmp/cascading/staging/teamcity542356014/.staging/job_local542356014_0008/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 23:21:24,114 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/tmp/cascading/staging/teamcity542356014/.staging/job_local542356014_0008/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 23:21:24,482 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local542356014_0008/job_local542356014_0008.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 23:21:24,484 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local542356014_0008/job_local542356014_0008.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 23:21:24,485 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 23:21:24,485 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local542356014_0008
2015-02-10 23:21:24,485 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 23:21:24,485 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2015-02-10 23:21:24,485 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 23:21:24,490 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 23:21:24,490 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local542356014_0008_m_000000_0
2015-02-10 23:21:24,493 INFO mapred.Task (Task.java:initialize(587)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 23:21:24,495 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/apache.10.txt
2015-02-10 23:21:24,495 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@41a80e5a
2015-02-10 23:21:24,497 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 0
2015-02-10 23:21:24,506 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 23:21:24,506 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 23:21:24,513 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/apache.10.txt"]
2015-02-10 23:21:24,514 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/filterall"]
2015-02-10 23:21:24,518 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 23:21:24,518 INFO mapred.Task (Task.java:done(1001)) - Task:attempt_local542356014_0008_m_000000_0 is done. And is in the process of committing
2015-02-10 23:21:24,520 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 23:21:24,520 INFO mapred.Task (Task.java:commit(1162)) - Task attempt_local542356014_0008_m_000000_0 is allowed to commit now
2015-02-10 23:21:24,521 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local542356014_0008_m_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/filterall/_temporary/0/task_local542356014_0008_m_000000
2015-02-10 23:21:24,522 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/apache.10.txt:0+1449
2015-02-10 23:21:24,522 INFO mapred.Task (Task.java:sendDone(1121)) - Task 'attempt_local542356014_0008_m_000000_0' done.
2015-02-10 23:21:24,522 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local542356014_0008_m_000000_0
2015-02-10 23:21:24,523 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 23:21:24,541 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/filterall/_temporary
2015-02-10 23:21:24,574 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 23:21:24,576 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output//hadoop2-mr1/basicpipesplatform/filterall
2015-02-10 23:21:24,603 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 23:21:24,603 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.6.3/9ae016e2b8d246b9c1de9168e715d9f1b971aa4a/cascading-hadoop2-mr1-2.6.3.jar
2015-02-10 23:21:24,620 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 23:21:24,625 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 23:21:24,626 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 23:21:24,638 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [lower*upper] starting
2015-02-10 23:21:24,639 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [lower*upper] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/upper.txt"]
2015-02-10 23:21:24,639 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [lower*upper] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/lower.txt"]
2015-02-10 23:21:24,639 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [lower*upper] sink: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/complexcogroup"]
2015-02-10 23:21:24,639 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [lower*upper] parallel execution is enabled: false
2015-02-10 23:21:24,639 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [lower*upper] starting jobs: 1
2015-02-10 23:21:24,640 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [lower*upper] allocating threads: 1
2015-02-10 23:21:24,640 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [lower*upper] starting step: (1/1) ...esplatform/complexcogroup
2015-02-10 23:21:24,641 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 23:21:24,644 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 23:21:24,674 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 23:21:24,676 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 23:21:24,698 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:2
2015-02-10 23:21:24,716 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1359904599_0009
2015-02-10 23:21:24,735 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/tmp/cascading/staging/teamcity1359904599/.staging/job_local1359904599_0009/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 23:21:24,736 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/tmp/cascading/staging/teamcity1359904599/.staging/job_local1359904599_0009/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 23:21:24,790 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1359904599_0009/job_local1359904599_0009.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 23:21:24,791 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1359904599_0009/job_local1359904599_0009.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 23:21:24,792 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 23:21:24,793 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [lower*upper] submitted hadoop job: job_local1359904599_0009
2015-02-10 23:21:24,793 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 23:21:24,793 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 23:21:24,793 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [lower*upper] tracking url: http://localhost:8080/
2015-02-10 23:21:24,797 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 23:21:24,797 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1359904599_0009_m_000000_0
2015-02-10 23:21:24,799 INFO mapred.Task (Task.java:initialize(587)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 23:21:24,800 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/upper.txt
2015-02-10 23:21:24,801 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@5dcd8bf7
2015-02-10 23:21:24,802 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-10 23:21:24,802 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-10 23:21:24,870 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-10 23:21:24,870 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-10 23:21:24,870 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-10 23:21:24,871 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-10 23:21:24,871 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-10 23:21:24,873 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 23:21:24,873 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 23:21:24,885 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/upper.txt"]
2015-02-10 23:21:24,886 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: CoGroup(lower*upper)[by: lower:[{1}:0] upper:[{1}:0]]
2015-02-10 23:21:24,889 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 23:21:24,889 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2015-02-10 23:21:24,889 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2015-02-10 23:21:24,889 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 85; bufvoid = 104857600
2015-02-10 23:21:24,889 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214380(104857520); length = 17/6553600
2015-02-10 23:21:24,893 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2015-02-10 23:21:24,895 INFO mapred.Task (Task.java:done(1001)) - Task:attempt_local1359904599_0009_m_000000_0 is done. And is in the process of committing
2015-02-10 23:21:24,898 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/upper.txt:0+19
2015-02-10 23:21:24,898 INFO mapred.Task (Task.java:sendDone(1121)) - Task 'attempt_local1359904599_0009_m_000000_0' done.
2015-02-10 23:21:24,898 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1359904599_0009_m_000000_0
2015-02-10 23:21:24,898 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1359904599_0009_m_000001_0
2015-02-10 23:21:24,900 INFO mapred.Task (Task.java:initialize(587)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 23:21:24,902 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/lower.txt
2015-02-10 23:21:24,902 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@8e3cf25
2015-02-10 23:21:24,903 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-10 23:21:24,904 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-10 23:21:25,049 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-10 23:21:25,049 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-10 23:21:25,049 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-10 23:21:25,049 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-10 23:21:25,050 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-10 23:21:25,052 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 23:21:25,052 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 23:21:25,063 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/lower.txt"]
2015-02-10 23:21:25,063 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: CoGroup(lower*upper)[by: lower:[{1}:0] upper:[{1}:0]]
2015-02-10 23:21:25,066 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 23:21:25,067 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2015-02-10 23:21:25,067 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2015-02-10 23:21:25,068 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 85; bufvoid = 104857600
2015-02-10 23:21:25,068 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214380(104857520); length = 17/6553600
2015-02-10 23:21:25,073 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2015-02-10 23:21:25,076 INFO mapred.Task (Task.java:done(1001)) - Task:attempt_local1359904599_0009_m_000001_0 is done. And is in the process of committing
2015-02-10 23:21:25,078 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/lower.txt:0+19
2015-02-10 23:21:25,079 INFO mapred.Task (Task.java:sendDone(1121)) - Task 'attempt_local1359904599_0009_m_000001_0' done.
2015-02-10 23:21:25,079 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1359904599_0009_m_000001_0
2015-02-10 23:21:25,080 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 23:21:25,080 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2015-02-10 23:21:25,081 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1359904599_0009_r_000000_0
2015-02-10 23:21:25,083 INFO mapred.Task (Task.java:initialize(587)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 23:21:25,083 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@3be4d6ef
2015-02-10 23:21:25,084 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2015-02-10 23:21:25,085 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1359904599_0009_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2015-02-10 23:21:25,087 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#6 about to shuffle output of map attempt_local1359904599_0009_m_000001_0 decomp: 97 len: 101 to MEMORY
2015-02-10 23:21:25,088 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 97 bytes from map-output for attempt_local1359904599_0009_m_000001_0
2015-02-10 23:21:25,088 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 97, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->97
2015-02-10 23:21:25,091 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#6 about to shuffle output of map attempt_local1359904599_0009_m_000000_0 decomp: 97 len: 101 to MEMORY
2015-02-10 23:21:25,091 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 97 bytes from map-output for attempt_local1359904599_0009_m_000000_0
2015-02-10 23:21:25,091 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 97, inMemoryMapOutputs.size() -> 2, commitMemory -> 97, usedMemory ->194
2015-02-10 23:21:25,093 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2015-02-10 23:21:25,095 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 2 / 2 copied.
2015-02-10 23:21:25,095 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 2 in-memory map-outputs and 0 on-disk map-outputs
2015-02-10 23:21:25,098 INFO mapred.Merger (Merger.java:merge(591)) - Merging 2 sorted segments
2015-02-10 23:21:25,099 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 2 segments left of total size: 174 bytes
2015-02-10 23:21:25,101 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 2 segments, 194 bytes to disk to satisfy reduce memory limit
2015-02-10 23:21:25,102 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 196 bytes from disk
2015-02-10 23:21:25,102 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2015-02-10 23:21:25,103 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 23:21:25,103 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 182 bytes
2015-02-10 23:21:25,104 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 2 / 2 copied.
2015-02-10 23:21:25,105 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.6.3
2015-02-10 23:21:25,106 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2015-02-10 23:21:25,116 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: CoGroup(lower*upper)[by: lower:[{1}:0] upper:[{1}:0]]
2015-02-10 23:21:25,116 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/complexcogroup"]
2015-02-10 23:21:25,136 INFO collect.SpillableTupleList (SpillableTupleList.java:getCodecClass(105)) - attempting to load codec: org.apache.hadoop.io.compress.GzipCodec
2015-02-10 23:21:25,136 INFO collect.SpillableTupleList (SpillableTupleList.java:getCodecClass(110)) - found codec: org.apache.hadoop.io.compress.GzipCodec
2015-02-10 23:21:25,145 INFO mapred.Task (Task.java:done(1001)) - Task:attempt_local1359904599_0009_r_000000_0 is done. And is in the process of committing
2015-02-10 23:21:25,149 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 2 / 2 copied.
2015-02-10 23:21:25,149 INFO mapred.Task (Task.java:commit(1162)) - Task attempt_local1359904599_0009_r_000000_0 is allowed to commit now
2015-02-10 23:21:25,150 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1359904599_0009_r_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/complexcogroup/_temporary/0/task_local1359904599_0009_r_000000
2015-02-10 23:21:25,151 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2015-02-10 23:21:25,151 INFO mapred.Task (Task.java:sendDone(1121)) - Task 'attempt_local1359904599_0009_r_000000_0' done.
2015-02-10 23:21:25,152 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1359904599_0009_r_000000_0
2015-02-10 23:21:25,152 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2015-02-10 23:21:25,179 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/complexcogroup/_temporary
2015-02-10 23:21:25,213 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 23:21:25,251 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 23:21:25,254 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output//hadoop2-mr1/basicpipesplatform/complexcogroup
2015-02-10 23:21:25,282 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 23:21:25,283 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.6.3/9ae016e2b8d246b9c1de9168e715d9f1b971aa4a/cascading-hadoop2-mr1-2.6.3.jar
2015-02-10 23:21:25,295 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 23:21:25,298 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 23:21:25,299 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 23:21:25,306 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting
2015-02-10 23:21:25,307 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/apache.10.txt"]
2015-02-10 23:21:25,307 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] sink: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/replace"]
2015-02-10 23:21:25,307 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] parallel execution is enabled: false
2015-02-10 23:21:25,307 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting jobs: 1
2015-02-10 23:21:25,307 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] allocating threads: 1
2015-02-10 23:21:25,308 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...asicpipesplatform/replace
2015-02-10 23:21:25,309 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 23:21:25,310 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 23:21:25,338 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 23:21:25,360 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 23:21:25,377 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local880653923_0010
2015-02-10 23:21:25,402 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/tmp/cascading/staging/teamcity880653923/.staging/job_local880653923_0010/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 23:21:25,403 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/tmp/cascading/staging/teamcity880653923/.staging/job_local880653923_0010/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 23:21:25,458 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local880653923_0010/job_local880653923_0010.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 23:21:25,459 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local880653923_0010/job_local880653923_0010.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 23:21:25,460 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 23:21:25,460 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local880653923_0010
2015-02-10 23:21:25,460 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 23:21:25,460 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2015-02-10 23:21:25,461 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 23:21:25,464 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 23:21:25,464 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local880653923_0010_m_000000_0
2015-02-10 23:21:25,467 INFO mapred.Task (Task.java:initialize(587)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 23:21:25,469 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/apache.10.txt
2015-02-10 23:21:25,469 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@63c5d81c
2015-02-10 23:21:25,471 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 0
2015-02-10 23:21:25,480 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 23:21:25,481 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 23:21:25,487 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/apache.10.txt"]
2015-02-10 23:21:25,488 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/replace"]
2015-02-10 23:21:25,492 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 23:21:25,492 INFO mapred.Task (Task.java:done(1001)) - Task:attempt_local880653923_0010_m_000000_0 is done. And is in the process of committing
2015-02-10 23:21:25,494 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 23:21:25,494 INFO mapred.Task (Task.java:commit(1162)) - Task attempt_local880653923_0010_m_000000_0 is allowed to commit now
2015-02-10 23:21:25,496 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local880653923_0010_m_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/replace/_temporary/0/task_local880653923_0010_m_000000
2015-02-10 23:21:25,497 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/apache.10.txt:0+1449
2015-02-10 23:21:25,497 INFO mapred.Task (Task.java:sendDone(1121)) - Task 'attempt_local880653923_0010_m_000000_0' done.
2015-02-10 23:21:25,498 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local880653923_0010_m_000000_0
2015-02-10 23:21:25,498 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 23:21:25,516 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/replace/_temporary
2015-02-10 23:21:25,549 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 23:21:25,551 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output//hadoop2-mr1/basicpipesplatform/replace
2015-02-10 23:21:25,573 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 23:21:25,573 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.6.3/9ae016e2b8d246b9c1de9168e715d9f1b971aa4a/cascading-hadoop2-mr1-2.6.3.jar
2015-02-10 23:21:25,582 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 23:21:25,585 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 23:21:25,585 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 23:21:25,592 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] starting
2015-02-10 23:21:25,592 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/ips.20.txt"]
2015-02-10 23:21:25,593 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] sink: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/count2"]
2015-02-10 23:21:25,593 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] parallel execution is enabled: false
2015-02-10 23:21:25,593 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] starting jobs: 1
2015-02-10 23:21:25,593 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] allocating threads: 1
2015-02-10 23:21:25,594 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] starting step: (1/1) ...basicpipesplatform/count2
2015-02-10 23:21:25,594 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 23:21:25,596 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 23:21:25,622 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 23:21:25,642 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 23:21:25,658 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1300332910_0011
2015-02-10 23:21:25,678 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/tmp/cascading/staging/teamcity1300332910/.staging/job_local1300332910_0011/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 23:21:25,679 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/tmp/cascading/staging/teamcity1300332910/.staging/job_local1300332910_0011/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 23:21:25,730 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1300332910_0011/job_local1300332910_0011.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 23:21:25,732 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1300332910_0011/job_local1300332910_0011.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 23:21:25,732 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 23:21:25,732 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] submitted hadoop job: job_local1300332910_0011
2015-02-10 23:21:25,732 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] tracking url: http://localhost:8080/
2015-02-10 23:21:25,733 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 23:21:25,734 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 23:21:25,737 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 23:21:25,737 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1300332910_0011_m_000000_0
2015-02-10 23:21:25,739 INFO mapred.Task (Task.java:initialize(587)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 23:21:25,741 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/ips.20.txt
2015-02-10 23:21:25,741 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@5b202f4d
2015-02-10 23:21:25,742 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-10 23:21:25,743 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-10 23:21:25,887 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-10 23:21:25,887 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-10 23:21:25,887 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-10 23:21:25,887 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-10 23:21:25,887 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-10 23:21:25,889 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 23:21:25,889 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 23:21:25,896 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/ips.20.txt"]
2015-02-10 23:21:25,896 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(count)[by:[{1}:1]]
2015-02-10 23:21:25,900 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 23:21:25,900 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2015-02-10 23:21:25,900 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2015-02-10 23:21:25,900 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 466; bufvoid = 104857600
2015-02-10 23:21:25,900 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214320(104857280); length = 77/6553600
2015-02-10 23:21:25,906 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2015-02-10 23:21:25,909 INFO mapred.Task (Task.java:done(1001)) - Task:attempt_local1300332910_0011_m_000000_0 is done. And is in the process of committing
2015-02-10 23:21:25,911 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/ips.20.txt:0+275
2015-02-10 23:21:25,911 INFO mapred.Task (Task.java:sendDone(1121)) - Task 'attempt_local1300332910_0011_m_000000_0' done.
2015-02-10 23:21:25,911 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1300332910_0011_m_000000_0
2015-02-10 23:21:25,911 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 23:21:25,912 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2015-02-10 23:21:25,912 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1300332910_0011_r_000000_0
2015-02-10 23:21:25,914 INFO mapred.Task (Task.java:initialize(587)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 23:21:25,914 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@679e3bdd
2015-02-10 23:21:25,915 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2015-02-10 23:21:25,916 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1300332910_0011_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2015-02-10 23:21:25,918 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#7 about to shuffle output of map attempt_local1300332910_0011_m_000000_0 decomp: 508 len: 512 to MEMORY
2015-02-10 23:21:25,919 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 508 bytes from map-output for attempt_local1300332910_0011_m_000000_0
2015-02-10 23:21:25,919 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 508, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->508
2015-02-10 23:21:25,920 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2015-02-10 23:21:25,921 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 23:21:25,921 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2015-02-10 23:21:25,926 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 23:21:25,927 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 487 bytes
2015-02-10 23:21:25,929 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 508 bytes to disk to satisfy reduce memory limit
2015-02-10 23:21:25,929 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 512 bytes from disk
2015-02-10 23:21:25,929 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2015-02-10 23:21:25,930 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 23:21:25,930 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 487 bytes
2015-02-10 23:21:25,931 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 23:21:25,932 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.6.3
2015-02-10 23:21:25,932 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2015-02-10 23:21:25,939 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(count)[by:[{1}:1]]
2015-02-10 23:21:25,939 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/count2"]
2015-02-10 23:21:25,953 INFO mapred.Task (Task.java:done(1001)) - Task:attempt_local1300332910_0011_r_000000_0 is done. And is in the process of committing
2015-02-10 23:21:25,955 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 23:21:25,955 INFO mapred.Task (Task.java:commit(1162)) - Task attempt_local1300332910_0011_r_000000_0 is allowed to commit now
2015-02-10 23:21:25,955 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1300332910_0011_r_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/count2/_temporary/0/task_local1300332910_0011_r_000000
2015-02-10 23:21:25,957 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2015-02-10 23:21:25,957 INFO mapred.Task (Task.java:sendDone(1121)) - Task 'attempt_local1300332910_0011_r_000000_0' done.
2015-02-10 23:21:25,957 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1300332910_0011_r_000000_0
2015-02-10 23:21:25,957 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2015-02-10 23:21:25,983 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/count2/_temporary
2015-02-10 23:21:26,017 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 23:21:26,052 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 23:21:26,054 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output//hadoop2-mr1/basicpipesplatform/count2
2015-02-10 23:21:26,075 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 23:21:26,075 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.6.3/9ae016e2b8d246b9c1de9168e715d9f1b971aa4a/cascading-hadoop2-mr1-2.6.3.jar
2015-02-10 23:21:26,084 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 23:21:26,086 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 23:21:26,087 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 23:21:26,093 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] starting
2015-02-10 23:21:26,094 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/ips.20.txt"]
2015-02-10 23:21:26,094 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] sink: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/count3"]
2015-02-10 23:21:26,094 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] parallel execution is enabled: false
2015-02-10 23:21:26,094 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] starting jobs: 1
2015-02-10 23:21:26,094 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] allocating threads: 1
2015-02-10 23:21:26,095 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] starting step: (1/1) ...basicpipesplatform/count3
2015-02-10 23:21:26,096 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 23:21:26,097 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 23:21:26,124 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 23:21:26,155 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 23:21:26,173 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1374094965_0012
2015-02-10 23:21:26,194 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/tmp/cascading/staging/teamcity1374094965/.staging/job_local1374094965_0012/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 23:21:26,195 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/tmp/cascading/staging/teamcity1374094965/.staging/job_local1374094965_0012/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 23:21:26,247 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1374094965_0012/job_local1374094965_0012.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 23:21:26,248 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1374094965_0012/job_local1374094965_0012.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 23:21:26,249 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 23:21:26,249 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] submitted hadoop job: job_local1374094965_0012
2015-02-10 23:21:26,249 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] tracking url: http://localhost:8080/
2015-02-10 23:21:26,250 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 23:21:26,250 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 23:21:26,254 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 23:21:26,255 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1374094965_0012_m_000000_0
2015-02-10 23:21:26,256 INFO mapred.Task (Task.java:initialize(587)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 23:21:26,258 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/ips.20.txt
2015-02-10 23:21:26,258 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@3cf27cdc
2015-02-10 23:21:26,259 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-10 23:21:26,260 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-10 23:21:26,401 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-10 23:21:26,401 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-10 23:21:26,401 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-10 23:21:26,401 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-10 23:21:26,401 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-10 23:21:26,403 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 23:21:26,403 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 23:21:26,410 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/ips.20.txt"]
2015-02-10 23:21:26,410 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(count)[by:[{1}:1]]
2015-02-10 23:21:26,414 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 23:21:26,414 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2015-02-10 23:21:26,414 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2015-02-10 23:21:26,414 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 466; bufvoid = 104857600
2015-02-10 23:21:26,414 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214320(104857280); length = 77/6553600
2015-02-10 23:21:26,420 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2015-02-10 23:21:26,423 INFO mapred.Task (Task.java:done(1001)) - Task:attempt_local1374094965_0012_m_000000_0 is done. And is in the process of committing
2015-02-10 23:21:26,425 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/ips.20.txt:0+275
2015-02-10 23:21:26,425 INFO mapred.Task (Task.java:sendDone(1121)) - Task 'attempt_local1374094965_0012_m_000000_0' done.
2015-02-10 23:21:26,425 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1374094965_0012_m_000000_0
2015-02-10 23:21:26,425 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 23:21:26,426 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2015-02-10 23:21:26,426 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1374094965_0012_r_000000_0
2015-02-10 23:21:26,428 INFO mapred.Task (Task.java:initialize(587)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 23:21:26,428 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@17f74864
2015-02-10 23:21:26,429 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2015-02-10 23:21:26,429 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1374094965_0012_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2015-02-10 23:21:26,431 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#8 about to shuffle output of map attempt_local1374094965_0012_m_000000_0 decomp: 508 len: 512 to MEMORY
2015-02-10 23:21:26,432 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 508 bytes from map-output for attempt_local1374094965_0012_m_000000_0
2015-02-10 23:21:26,432 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 508, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->508
2015-02-10 23:21:26,433 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2015-02-10 23:21:26,434 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 23:21:26,434 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2015-02-10 23:21:26,436 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 23:21:26,436 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 487 bytes
2015-02-10 23:21:26,438 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 508 bytes to disk to satisfy reduce memory limit
2015-02-10 23:21:26,439 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 512 bytes from disk
2015-02-10 23:21:26,439 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2015-02-10 23:21:26,439 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 23:21:26,439 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 487 bytes
2015-02-10 23:21:26,440 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 23:21:26,440 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.6.3
2015-02-10 23:21:26,441 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2015-02-10 23:21:26,447 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(count)[by:[{1}:1]]
2015-02-10 23:21:26,447 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/count3"]
2015-02-10 23:21:26,461 INFO mapred.Task (Task.java:done(1001)) - Task:attempt_local1374094965_0012_r_000000_0 is done. And is in the process of committing
2015-02-10 23:21:26,463 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 23:21:26,463 INFO mapred.Task (Task.java:commit(1162)) - Task attempt_local1374094965_0012_r_000000_0 is allowed to commit now
2015-02-10 23:21:26,464 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1374094965_0012_r_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/count3/_temporary/0/task_local1374094965_0012_r_000000
2015-02-10 23:21:26,465 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2015-02-10 23:21:26,465 INFO mapred.Task (Task.java:sendDone(1121)) - Task 'attempt_local1374094965_0012_r_000000_0' done.
2015-02-10 23:21:26,465 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1374094965_0012_r_000000_0
2015-02-10 23:21:26,466 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2015-02-10 23:21:26,490 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/count3/_temporary
2015-02-10 23:21:26,521 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 23:21:26,554 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 23:21:26,557 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output//hadoop2-mr1/basicpipesplatform/count3
2015-02-10 23:21:26,579 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 23:21:26,580 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.6.3/9ae016e2b8d246b9c1de9168e715d9f1b971aa4a/cascading-hadoop2-mr1-2.6.3.jar
2015-02-10 23:21:26,588 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 23:21:26,591 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 23:21:26,592 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 23:21:26,600 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] starting
2015-02-10 23:21:26,600 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/ips.20.txt"]
2015-02-10 23:21:26,600 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] sink: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/count4"]
2015-02-10 23:21:26,601 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] parallel execution is enabled: false
2015-02-10 23:21:26,601 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] starting jobs: 1
2015-02-10 23:21:26,601 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] allocating threads: 1
2015-02-10 23:21:26,601 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] starting step: (1/1) ...basicpipesplatform/count4
2015-02-10 23:21:26,602 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 23:21:26,603 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 23:21:26,629 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 23:21:26,649 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 23:21:26,669 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1787404683_0013
2015-02-10 23:21:26,690 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/tmp/cascading/staging/teamcity1787404683/.staging/job_local1787404683_0013/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 23:21:26,691 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/tmp/cascading/staging/teamcity1787404683/.staging/job_local1787404683_0013/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 23:21:26,748 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1787404683_0013/job_local1787404683_0013.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 23:21:26,749 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1787404683_0013/job_local1787404683_0013.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 23:21:26,750 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 23:21:26,751 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 23:21:26,751 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] submitted hadoop job: job_local1787404683_0013
2015-02-10 23:21:26,752 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] tracking url: http://localhost:8080/
2015-02-10 23:21:26,751 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 23:21:26,755 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 23:21:26,755 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1787404683_0013_m_000000_0
2015-02-10 23:21:26,757 INFO mapred.Task (Task.java:initialize(587)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 23:21:26,759 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/ips.20.txt
2015-02-10 23:21:26,759 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@11613fe7
2015-02-10 23:21:26,760 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-10 23:21:26,761 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-10 23:21:26,806 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-10 23:21:26,807 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-10 23:21:26,807 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-10 23:21:26,807 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-10 23:21:26,808 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-10 23:21:26,810 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 23:21:26,810 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 23:21:26,818 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/ips.20.txt"]
2015-02-10 23:21:26,818 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(count)[by:[{1}:1]]
2015-02-10 23:21:26,823 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 23:21:26,823 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2015-02-10 23:21:26,823 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2015-02-10 23:21:26,823 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 466; bufvoid = 104857600
2015-02-10 23:21:26,823 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214320(104857280); length = 77/6553600
2015-02-10 23:21:26,829 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2015-02-10 23:21:26,832 INFO mapred.Task (Task.java:done(1001)) - Task:attempt_local1787404683_0013_m_000000_0 is done. And is in the process of committing
2015-02-10 23:21:26,834 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/ips.20.txt:0+275
2015-02-10 23:21:26,835 INFO mapred.Task (Task.java:sendDone(1121)) - Task 'attempt_local1787404683_0013_m_000000_0' done.
2015-02-10 23:21:26,835 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1787404683_0013_m_000000_0
2015-02-10 23:21:26,835 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 23:21:26,836 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2015-02-10 23:21:26,836 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1787404683_0013_r_000000_0
2015-02-10 23:21:26,838 INFO mapred.Task (Task.java:initialize(587)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 23:21:26,838 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@4965391b
2015-02-10 23:21:26,839 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2015-02-10 23:21:26,840 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1787404683_0013_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2015-02-10 23:21:26,842 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#9 about to shuffle output of map attempt_local1787404683_0013_m_000000_0 decomp: 508 len: 512 to MEMORY
2015-02-10 23:21:26,842 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 508 bytes from map-output for attempt_local1787404683_0013_m_000000_0
2015-02-10 23:21:26,842 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 508, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->508
2015-02-10 23:21:26,844 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2015-02-10 23:21:26,845 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 23:21:26,845 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2015-02-10 23:21:26,850 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 23:21:26,850 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 487 bytes
2015-02-10 23:21:26,852 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 508 bytes to disk to satisfy reduce memory limit
2015-02-10 23:21:26,853 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 512 bytes from disk
2015-02-10 23:21:26,853 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2015-02-10 23:21:26,853 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 23:21:26,854 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 487 bytes
2015-02-10 23:21:26,854 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 23:21:26,855 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.6.3
2015-02-10 23:21:26,855 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2015-02-10 23:21:26,862 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(count)[by:[{1}:1]]
2015-02-10 23:21:26,863 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/count4"]
2015-02-10 23:21:26,877 INFO mapred.Task (Task.java:done(1001)) - Task:attempt_local1787404683_0013_r_000000_0 is done. And is in the process of committing
2015-02-10 23:21:26,879 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 23:21:26,879 INFO mapred.Task (Task.java:commit(1162)) - Task attempt_local1787404683_0013_r_000000_0 is allowed to commit now
2015-02-10 23:21:26,880 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1787404683_0013_r_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/count4/_temporary/0/task_local1787404683_0013_r_000000
2015-02-10 23:21:26,881 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2015-02-10 23:21:26,882 INFO mapred.Task (Task.java:sendDone(1121)) - Task 'attempt_local1787404683_0013_r_000000_0' done.
2015-02-10 23:21:26,882 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1787404683_0013_r_000000_0
2015-02-10 23:21:26,882 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2015-02-10 23:21:26,912 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/count4/_temporary
2015-02-10 23:21:26,945 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 23:21:26,976 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 23:21:26,978 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output//hadoop2-mr1/basicpipesplatform/count4
2015-02-10 23:21:26,998 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 23:21:26,999 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.6.3/9ae016e2b8d246b9c1de9168e715d9f1b971aa4a/cascading-hadoop2-mr1-2.6.3.jar
2015-02-10 23:21:27,005 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 23:21:27,007 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 23:21:27,008 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 23:21:27,013 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting
2015-02-10 23:21:27,013 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/apache.10.txt"]
2015-02-10 23:21:27,013 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] sink: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/filter"]
2015-02-10 23:21:27,013 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] parallel execution is enabled: false
2015-02-10 23:21:27,014 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting jobs: 1
2015-02-10 23:21:27,014 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] allocating threads: 1
2015-02-10 23:21:27,014 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...basicpipesplatform/filter
2015-02-10 23:21:27,015 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 23:21:27,016 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 23:21:27,043 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 23:21:27,062 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 23:21:27,078 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local78733993_0014
2015-02-10 23:21:27,097 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/tmp/cascading/staging/teamcity78733993/.staging/job_local78733993_0014/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 23:21:27,098 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/tmp/cascading/staging/teamcity78733993/.staging/job_local78733993_0014/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 23:21:27,148 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local78733993_0014/job_local78733993_0014.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 23:21:27,149 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local78733993_0014/job_local78733993_0014.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 23:21:27,150 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 23:21:27,150 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 23:21:27,150 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 23:21:27,150 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local78733993_0014
2015-02-10 23:21:27,151 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2015-02-10 23:21:27,153 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 23:21:27,153 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local78733993_0014_m_000000_0
2015-02-10 23:21:27,155 INFO mapred.Task (Task.java:initialize(587)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 23:21:27,156 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/apache.10.txt
2015-02-10 23:21:27,157 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@7170c7a3
2015-02-10 23:21:27,158 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 0
2015-02-10 23:21:27,165 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 23:21:27,166 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 23:21:27,172 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/apache.10.txt"]
2015-02-10 23:21:27,172 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/filter"]
2015-02-10 23:21:27,175 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 23:21:27,176 INFO mapred.Task (Task.java:done(1001)) - Task:attempt_local78733993_0014_m_000000_0 is done. And is in the process of committing
2015-02-10 23:21:27,177 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 23:21:27,177 INFO mapred.Task (Task.java:commit(1162)) - Task attempt_local78733993_0014_m_000000_0 is allowed to commit now
2015-02-10 23:21:27,178 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local78733993_0014_m_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/filter/_temporary/0/task_local78733993_0014_m_000000
2015-02-10 23:21:27,179 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/apache.10.txt:0+1449
2015-02-10 23:21:27,180 INFO mapred.Task (Task.java:sendDone(1121)) - Task 'attempt_local78733993_0014_m_000000_0' done.
2015-02-10 23:21:27,180 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local78733993_0014_m_000000_0
2015-02-10 23:21:27,180 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 23:21:27,196 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/filter/_temporary
2015-02-10 23:21:27,227 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 23:21:27,229 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output//hadoop2-mr1/basicpipesplatform/filter
2015-02-10 23:21:27,253 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 23:21:27,253 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.6.3/9ae016e2b8d246b9c1de9168e715d9f1b971aa4a/cascading-hadoop2-mr1-2.6.3.jar
2015-02-10 23:21:27,264 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 23:21:27,267 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 23:21:27,268 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 23:21:27,275 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting
2015-02-10 23:21:27,275 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/apache.10.txt"]
2015-02-10 23:21:27,275 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] sink: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/simple"]
2015-02-10 23:21:27,276 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] parallel execution is enabled: false
2015-02-10 23:21:27,276 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting jobs: 1
2015-02-10 23:21:27,276 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] allocating threads: 1
2015-02-10 23:21:27,276 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...basicpipesplatform/simple
2015-02-10 23:21:27,277 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 23:21:27,278 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 23:21:27,303 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 23:21:27,323 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 23:21:27,339 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1057384699_0015
2015-02-10 23:21:27,357 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/tmp/cascading/staging/teamcity1057384699/.staging/job_local1057384699_0015/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 23:21:27,358 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/tmp/cascading/staging/teamcity1057384699/.staging/job_local1057384699_0015/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 23:21:27,407 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1057384699_0015/job_local1057384699_0015.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 23:21:27,408 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1057384699_0015/job_local1057384699_0015.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 23:21:27,409 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 23:21:27,409 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local1057384699_0015
2015-02-10 23:21:27,410 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2015-02-10 23:21:27,411 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 23:21:27,411 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 23:21:27,414 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 23:21:27,414 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1057384699_0015_m_000000_0
2015-02-10 23:21:27,416 INFO mapred.Task (Task.java:initialize(587)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 23:21:27,418 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/apache.10.txt
2015-02-10 23:21:27,418 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@17e7a4d0
2015-02-10 23:21:27,419 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-10 23:21:27,420 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-10 23:21:27,443 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-10 23:21:27,443 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-10 23:21:27,443 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-10 23:21:27,444 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-10 23:21:27,444 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-10 23:21:27,445 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 23:21:27,446 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 23:21:27,455 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/apache.10.txt"]
2015-02-10 23:21:27,455 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:0]]
2015-02-10 23:21:27,459 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 23:21:27,459 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2015-02-10 23:21:27,459 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2015-02-10 23:21:27,459 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 210; bufvoid = 104857600
2015-02-10 23:21:27,459 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214360(104857440); length = 37/6553600
2015-02-10 23:21:27,463 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2015-02-10 23:21:27,465 INFO mapred.Task (Task.java:done(1001)) - Task:attempt_local1057384699_0015_m_000000_0 is done. And is in the process of committing
2015-02-10 23:21:27,467 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/apache.10.txt:0+1449
2015-02-10 23:21:27,467 INFO mapred.Task (Task.java:sendDone(1121)) - Task 'attempt_local1057384699_0015_m_000000_0' done.
2015-02-10 23:21:27,467 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1057384699_0015_m_000000_0
2015-02-10 23:21:27,467 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 23:21:27,468 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2015-02-10 23:21:27,468 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1057384699_0015_r_000000_0
2015-02-10 23:21:27,470 INFO mapred.Task (Task.java:initialize(587)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 23:21:27,470 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@2a4df9a0
2015-02-10 23:21:27,471 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2015-02-10 23:21:27,472 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1057384699_0015_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2015-02-10 23:21:27,474 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#10 about to shuffle output of map attempt_local1057384699_0015_m_000000_0 decomp: 232 len: 236 to MEMORY
2015-02-10 23:21:27,474 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 232 bytes from map-output for attempt_local1057384699_0015_m_000000_0
2015-02-10 23:21:27,474 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 232, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->232
2015-02-10 23:21:27,475 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2015-02-10 23:21:27,476 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 23:21:27,477 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2015-02-10 23:21:27,479 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 23:21:27,479 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 211 bytes
2015-02-10 23:21:27,481 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 232 bytes to disk to satisfy reduce memory limit
2015-02-10 23:21:27,481 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 236 bytes from disk
2015-02-10 23:21:27,481 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2015-02-10 23:21:27,481 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 23:21:27,482 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 211 bytes
2015-02-10 23:21:27,482 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 23:21:27,483 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.6.3
2015-02-10 23:21:27,483 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2015-02-10 23:21:27,491 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:0]]
2015-02-10 23:21:27,492 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/simple"]
2015-02-10 23:21:27,503 INFO mapred.Task (Task.java:done(1001)) - Task:attempt_local1057384699_0015_r_000000_0 is done. And is in the process of committing
2015-02-10 23:21:27,505 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 23:21:27,505 INFO mapred.Task (Task.java:commit(1162)) - Task attempt_local1057384699_0015_r_000000_0 is allowed to commit now
2015-02-10 23:21:27,506 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1057384699_0015_r_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/simple/_temporary/0/task_local1057384699_0015_r_000000
2015-02-10 23:21:27,507 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2015-02-10 23:21:27,507 INFO mapred.Task (Task.java:sendDone(1121)) - Task 'attempt_local1057384699_0015_r_000000_0' done.
2015-02-10 23:21:27,507 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1057384699_0015_r_000000_0
2015-02-10 23:21:27,508 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2015-02-10 23:21:27,525 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/basicpipesplatform/simple/_temporary
2015-02-10 23:21:27,561 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 23:21:27,562 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output//hadoop2-mr1/basicpipesplatform/simple