2015-02-10 22:13:24,360 INFO platform.PlatformRunner (PlatformRunner.java:getPlatformClassesFromClasspath(187)) - found 1 test platforms from classpath
2015-02-10 22:13:24,430 INFO platform.PlatformRunner (PlatformRunner.java:addPlatform(237)) - installing platform: hadoop2-mr1
2015-02-10 22:13:24,430 INFO platform.PlatformRunner (PlatformRunner.java:addPlatform(238)) - running test: cascading.UnmodifiablePipesPlatformTest
2015-02-10 22:13:24,459 INFO hadoop2.Hadoop2MR1Platform (Hadoop2MR1Platform.java:setUp(105)) - not using cluster
2015-02-10 22:13:25,111 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 22:13:25,435 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 22:13:25,437 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 22:13:25,450 INFO property.AppProps (AppProps.java:getAppID(169)) - using app.id: 1C11CB9109CC495C9C909C4A79EA2739
2015-02-10 22:13:25,547 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 22:13:25,590 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 22:13:25,683 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 22:13:25,751 INFO util.Version (Version.java:printBanner(82)) - Concurrent, Inc - Cascading 2.6.3
2015-02-10 22:13:25,754 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting
2015-02-10 22:13:25,755 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] source: Hfs["TextDelimited[['lhs', 'rhs']]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/lhs.txt"]
2015-02-10 22:13:25,756 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] sink: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/output/hadoop2-mr1/unmodifiablepipesplatform/simple"]
2015-02-10 22:13:25,756 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] parallel execution is enabled: false
2015-02-10 22:13:25,758 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting jobs: 2
2015-02-10 22:13:25,758 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] allocating threads: 1
2015-02-10 22:13:25,759 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/2)
2015-02-10 22:13:25,785 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - session.id is deprecated. Instead, use dfs.metrics.session-id
2015-02-10 22:13:25,787 INFO jvm.JvmMetrics (JvmMetrics.java:init(76)) - Initializing JVM Metrics with processName=JobTracker, sessionId=
2015-02-10 22:13:25,812 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 22:13:26,198 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 22:13:26,239 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 22:13:26,410 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local784973313_0001
2015-02-10 22:13:26,451 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity784973313/.staging/job_local784973313_0001/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 22:13:26,458 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity784973313/.staging/job_local784973313_0001/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 22:13:26,632 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local784973313_0001/job_local784973313_0001.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 22:13:26,635 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local784973313_0001/job_local784973313_0001.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 22:13:26,641 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 22:13:26,643 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 22:13:26,645 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local784973313_0001
2015-02-10 22:13:26,646 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2015-02-10 22:13:26,646 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 22:13:26,704 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 22:13:26,707 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local784973313_0001_m_000000_0
2015-02-10 22:13:26,750 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 22:13:26,760 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/lhs.txt
2015-02-10 22:13:26,761 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@279977bd
2015-02-10 22:13:26,770 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-10 22:13:26,777 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-10 22:13:26,928 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-10 22:13:26,928 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-10 22:13:26,928 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-10 22:13:26,928 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-10 22:13:26,929 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-10 22:13:26,956 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 22:13:26,956 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 22:13:27,011 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.task.partition is deprecated. Instead, use mapreduce.task.partition
2015-02-10 22:13:27,018 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextDelimited[['lhs', 'rhs']]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/lhs.txt"]
2015-02-10 22:13:27,019 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:'lhs']]
2015-02-10 22:13:27,036 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 22:13:27,036 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2015-02-10 22:13:27,036 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2015-02-10 22:13:27,036 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 195; bufvoid = 104857600
2015-02-10 22:13:27,036 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214348(104857392); length = 49/6553600
2015-02-10 22:13:27,058 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2015-02-10 22:13:27,062 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local784973313_0001_m_000000_0 is done. And is in the process of committing
2015-02-10 22:13:27,074 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/lhs.txt:0+52
2015-02-10 22:13:27,074 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local784973313_0001_m_000000_0' done.
2015-02-10 22:13:27,074 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local784973313_0001_m_000000_0
2015-02-10 22:13:27,075 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 22:13:27,077 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2015-02-10 22:13:27,078 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local784973313_0001_r_000000_0
2015-02-10 22:13:27,086 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 22:13:27,091 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@193a83cc
2015-02-10 22:13:27,105 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2015-02-10 22:13:27,109 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local784973313_0001_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2015-02-10 22:13:27,142 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#1 about to shuffle output of map attempt_local784973313_0001_m_000000_0 decomp: 223 len: 227 to MEMORY
2015-02-10 22:13:27,147 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 223 bytes from map-output for attempt_local784973313_0001_m_000000_0
2015-02-10 22:13:27,191 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 223, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->223
2015-02-10 22:13:27,192 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2015-02-10 22:13:27,193 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 22:13:27,193 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2015-02-10 22:13:27,202 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 22:13:27,203 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 214 bytes
2015-02-10 22:13:27,206 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 223 bytes to disk to satisfy reduce memory limit
2015-02-10 22:13:27,206 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 227 bytes from disk
2015-02-10 22:13:27,207 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2015-02-10 22:13:27,207 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 22:13:27,208 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 214 bytes
2015-02-10 22:13:27,209 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 22:13:27,210 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.6.3
2015-02-10 22:13:27,210 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2015-02-10 22:13:27,230 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:'lhs']]
2015-02-10 22:13:27,231 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: TempHfs["SequenceFile[['lhs', 'rhs']]"][6360148658/test/]
2015-02-10 22:13:27,268 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local784973313_0001_r_000000_0 is done. And is in the process of committing
2015-02-10 22:13:27,270 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 22:13:27,270 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local784973313_0001_r_000000_0 is allowed to commit now
2015-02-10 22:13:27,271 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local784973313_0001_r_000000_0' to file:/tmp/hadoop-teamcity/6360148658_test_5245036013B642A892302EEF3C03FEE6/_temporary/0/task_local784973313_0001_r_000000
2015-02-10 22:13:27,273 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2015-02-10 22:13:27,273 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local784973313_0001_r_000000_0' done.
2015-02-10 22:13:27,274 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local784973313_0001_r_000000_0
2015-02-10 22:13:27,274 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2015-02-10 22:13:27,317 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (2/2) ...iablepipesplatform/simple
2015-02-10 22:13:27,318 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 22:13:27,319 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 22:13:27,370 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 22:13:27,396 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 22:13:27,411 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 22:13:27,412 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 22:13:27,437 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1832196760_0002
2015-02-10 22:13:27,459 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity1832196760/.staging/job_local1832196760_0002/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 22:13:27,463 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity1832196760/.staging/job_local1832196760_0002/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 22:13:27,552 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1832196760_0002/job_local1832196760_0002.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 22:13:27,556 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1832196760_0002/job_local1832196760_0002.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 22:13:27,557 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 22:13:27,557 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local1832196760_0002
2015-02-10 22:13:27,558 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2015-02-10 22:13:27,558 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 22:13:27,559 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 22:13:27,564 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 22:13:27,564 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1832196760_0002_m_000000_0
2015-02-10 22:13:27,567 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 22:13:27,569 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/tmp/hadoop-teamcity/6360148658_test_5245036013B642A892302EEF3C03FEE6/part-00000
2015-02-10 22:13:27,570 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@264d40df
2015-02-10 22:13:27,582 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-10 22:13:27,583 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-10 22:13:27,750 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-10 22:13:27,750 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-10 22:13:27,750 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-10 22:13:27,750 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-10 22:13:27,751 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-10 22:13:27,752 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 22:13:27,752 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 22:13:27,765 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: TempHfs["SequenceFile[['lhs', 'rhs']]"][6360148658/test/]
2015-02-10 22:13:27,765 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:'lhs']]
2015-02-10 22:13:27,769 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 22:13:27,769 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2015-02-10 22:13:27,769 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2015-02-10 22:13:27,769 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 120; bufvoid = 104857600
2015-02-10 22:13:27,769 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214380(104857520); length = 17/6553600
2015-02-10 22:13:27,774 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2015-02-10 22:13:27,778 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1832196760_0002_m_000000_0 is done. And is in the process of committing
2015-02-10 22:13:27,781 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/tmp/hadoop-teamcity/6360148658_test_5245036013B642A892302EEF3C03FEE6/part-00000:0+225
2015-02-10 22:13:27,781 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1832196760_0002_m_000000_0' done.
2015-02-10 22:13:27,781 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1832196760_0002_m_000000_0
2015-02-10 22:13:27,781 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 22:13:27,782 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2015-02-10 22:13:27,782 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1832196760_0002_r_000000_0
2015-02-10 22:13:27,785 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 22:13:27,785 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@263e53cf
2015-02-10 22:13:27,786 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2015-02-10 22:13:27,787 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1832196760_0002_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2015-02-10 22:13:27,790 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#2 about to shuffle output of map attempt_local1832196760_0002_m_000000_0 decomp: 132 len: 136 to MEMORY
2015-02-10 22:13:27,791 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 132 bytes from map-output for attempt_local1832196760_0002_m_000000_0
2015-02-10 22:13:27,791 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 132, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->132
2015-02-10 22:13:27,792 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2015-02-10 22:13:27,793 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 22:13:27,793 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2015-02-10 22:13:27,796 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 22:13:27,797 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 123 bytes
2015-02-10 22:13:27,801 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 132 bytes to disk to satisfy reduce memory limit
2015-02-10 22:13:27,801 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 136 bytes from disk
2015-02-10 22:13:27,802 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2015-02-10 22:13:27,802 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 22:13:27,802 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 123 bytes
2015-02-10 22:13:27,803 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 22:13:27,804 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.6.3
2015-02-10 22:13:27,804 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2015-02-10 22:13:27,817 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:'lhs']]
2015-02-10 22:13:27,817 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/output/hadoop2-mr1/unmodifiablepipesplatform/simple"]
2015-02-10 22:13:27,835 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1832196760_0002_r_000000_0 is done. And is in the process of committing
2015-02-10 22:13:27,837 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 22:13:27,838 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1832196760_0002_r_000000_0 is allowed to commit now
2015-02-10 22:13:27,840 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1832196760_0002_r_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/output/hadoop2-mr1/unmodifiablepipesplatform/simple/_temporary/0/task_local1832196760_0002_r_000000
2015-02-10 22:13:27,842 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2015-02-10 22:13:27,842 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1832196760_0002_r_000000_0' done.
2015-02-10 22:13:27,843 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1832196760_0002_r_000000_0
2015-02-10 22:13:27,844 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2015-02-10 22:13:27,880 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/output/hadoop2-mr1/unmodifiablepipesplatform/simple/_temporary
2015-02-10 22:13:27,924 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 22:13:27,927 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/output//hadoop2-mr1/unmodifiablepipesplatform/simple