2015-02-11 00:07:03,578 INFO platform.PlatformRunner (PlatformRunner.java:getPlatformClassesFromClasspath(187)) - found 1 test platforms from classpath
2015-02-11 00:07:03,651 INFO platform.PlatformRunner (PlatformRunner.java:addPlatform(237)) - installing platform: hadoop2-mr1
2015-02-11 00:07:03,652 INFO platform.PlatformRunner (PlatformRunner.java:addPlatform(238)) - running test: cascading.BufferPipesPlatformTest
2015-02-11 00:07:03,690 INFO hadoop2.Hadoop2MR1Platform (Hadoop2MR1Platform.java:setUp(105)) - not using cluster
2015-02-11 00:07:04,375 WARN util.NativeCodeLoader (NativeCodeLoader.java:<clinit>(62)) - Unable to load native-hadoop library for your platform... using builtin-java classes where applicable
2015-02-11 00:07:04,692 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-11 00:07:04,694 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-11 00:07:04,707 INFO property.AppProps (AppProps.java:getAppID(169)) - using app.id: D2A41574F68945B19705A5ABA6E5A8B1
2015-02-11 00:07:04,792 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-11 00:07:04,834 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-11 00:07:04,838 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-11 00:07:04,969 INFO util.Version (Version.java:printBanner(82)) - Concurrent, Inc - Cascading 2.6.3
2015-02-11 00:07:04,973 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting
2015-02-11 00:07:04,975 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/lhs.txt"]
2015-02-11 00:07:04,976 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] sink: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/bufferpipesplatform/identity"]
2015-02-11 00:07:04,977 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] parallel execution is enabled: false
2015-02-11 00:07:04,979 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting jobs: 1
2015-02-11 00:07:04,980 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] allocating threads: 1
2015-02-11 00:07:04,983 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...ferpipesplatform/identity
2015-02-11 00:07:05,009 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - session.id is deprecated. Instead, use dfs.metrics.session-id
2015-02-11 00:07:05,010 INFO jvm.JvmMetrics (JvmMetrics.java:init(76)) - Initializing JVM Metrics with processName=JobTracker, sessionId=
2015-02-11 00:07:05,036 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-11 00:07:05,452 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-11 00:07:05,502 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-11 00:07:05,677 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local591803599_0001
2015-02-11 00:07:05,718 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/tmp/cascading/staging/teamcity591803599/.staging/job_local591803599_0001/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-11 00:07:05,725 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/tmp/cascading/staging/teamcity591803599/.staging/job_local591803599_0001/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-11 00:07:05,868 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_local591803599_0001/job_local591803599_0001.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-11 00:07:05,874 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_local591803599_0001/job_local591803599_0001.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-11 00:07:05,881 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-11 00:07:05,882 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-11 00:07:05,886 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local591803599_0001
2015-02-11 00:07:05,886 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2015-02-11 00:07:05,886 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-11 00:07:05,934 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-11 00:07:05,938 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local591803599_0001_m_000000_0
2015-02-11 00:07:05,983 INFO mapred.Task (Task.java:initialize(587)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-11 00:07:05,994 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/lhs.txt
2015-02-11 00:07:05,995 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@7463e563
2015-02-11 00:07:06,005 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-11 00:07:06,013 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-11 00:07:06,166 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-11 00:07:06,167 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-11 00:07:06,168 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-11 00:07:06,168 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-11 00:07:06,169 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-11 00:07:06,197 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-11 00:07:06,198 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-11 00:07:06,249 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.task.partition is deprecated. Instead, use mapreduce.task.partition
2015-02-11 00:07:06,268 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/lhs.txt"]
2015-02-11 00:07:06,269 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:'num']]
2015-02-11 00:07:06,286 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-11 00:07:06,287 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2015-02-11 00:07:06,287 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2015-02-11 00:07:06,288 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 195; bufvoid = 104857600
2015-02-11 00:07:06,289 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214348(104857392); length = 49/6553600
2015-02-11 00:07:06,302 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2015-02-11 00:07:06,307 INFO mapred.Task (Task.java:done(1001)) - Task:attempt_local591803599_0001_m_000000_0 is done. And is in the process of committing
2015-02-11 00:07:06,319 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/lhs.txt:0+52
2015-02-11 00:07:06,319 INFO mapred.Task (Task.java:sendDone(1121)) - Task 'attempt_local591803599_0001_m_000000_0' done.
2015-02-11 00:07:06,320 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local591803599_0001_m_000000_0
2015-02-11 00:07:06,321 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-11 00:07:06,324 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2015-02-11 00:07:06,324 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local591803599_0001_r_000000_0
2015-02-11 00:07:06,332 INFO mapred.Task (Task.java:initialize(587)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-11 00:07:06,338 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@1217e615
2015-02-11 00:07:06,371 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2015-02-11 00:07:06,376 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local591803599_0001_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2015-02-11 00:07:06,416 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#1 about to shuffle output of map attempt_local591803599_0001_m_000000_0 decomp: 223 len: 227 to MEMORY
2015-02-11 00:07:06,422 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 223 bytes from map-output for attempt_local591803599_0001_m_000000_0
2015-02-11 00:07:06,463 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 223, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->223
2015-02-11 00:07:06,465 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2015-02-11 00:07:06,467 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-11 00:07:06,469 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2015-02-11 00:07:06,480 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-11 00:07:06,480 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 214 bytes
2015-02-11 00:07:06,484 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 223 bytes to disk to satisfy reduce memory limit
2015-02-11 00:07:06,485 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 227 bytes from disk
2015-02-11 00:07:06,486 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2015-02-11 00:07:06,487 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-11 00:07:06,487 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 214 bytes
2015-02-11 00:07:06,488 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-11 00:07:06,491 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.6.3
2015-02-11 00:07:06,491 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2015-02-11 00:07:06,509 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:'num']]
2015-02-11 00:07:06,509 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/bufferpipesplatform/identity"]
2015-02-11 00:07:06,540 INFO mapred.Task (Task.java:done(1001)) - Task:attempt_local591803599_0001_r_000000_0 is done. And is in the process of committing
2015-02-11 00:07:06,542 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-11 00:07:06,543 INFO mapred.Task (Task.java:commit(1162)) - Task attempt_local591803599_0001_r_000000_0 is allowed to commit now
2015-02-11 00:07:06,544 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local591803599_0001_r_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/bufferpipesplatform/identity/_temporary/0/task_local591803599_0001_r_000000
2015-02-11 00:07:06,545 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2015-02-11 00:07:06,546 INFO mapred.Task (Task.java:sendDone(1121)) - Task 'attempt_local591803599_0001_r_000000_0' done.
2015-02-11 00:07:06,546 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local591803599_0001_r_000000_0
2015-02-11 00:07:06,546 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2015-02-11 00:07:06,595 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/bufferpipesplatform/identity/_temporary
2015-02-11 00:07:06,638 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-11 00:07:06,683 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-11 00:07:06,686 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/bufferpipesplatform/identity
2015-02-11 00:07:06,723 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-11 00:07:06,725 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-11 00:07:06,745 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-11 00:07:06,752 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-11 00:07:06,753 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-11 00:07:06,770 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting
2015-02-11 00:07:06,771 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/lhs.txt"]
2015-02-11 00:07:06,771 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] sink: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/bufferpipesplatform/simple"]
2015-02-11 00:07:06,772 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] parallel execution is enabled: false
2015-02-11 00:07:06,772 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting jobs: 1
2015-02-11 00:07:06,772 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] allocating threads: 1
2015-02-11 00:07:06,773 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...ufferpipesplatform/simple
2015-02-11 00:07:06,774 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-11 00:07:06,776 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-11 00:07:06,828 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-11 00:07:06,857 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-11 00:07:06,894 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1724005925_0002
2015-02-11 00:07:06,919 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/tmp/cascading/staging/teamcity1724005925/.staging/job_local1724005925_0002/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-11 00:07:06,923 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/tmp/cascading/staging/teamcity1724005925/.staging/job_local1724005925_0002/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-11 00:07:07,004 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_local1724005925_0002/job_local1724005925_0002.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-11 00:07:07,007 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_local1724005925_0002/job_local1724005925_0002.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-11 00:07:07,008 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-11 00:07:07,009 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local1724005925_0002
2015-02-11 00:07:07,009 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-11 00:07:07,009 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2015-02-11 00:07:07,010 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-11 00:07:07,015 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-11 00:07:07,015 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1724005925_0002_m_000000_0
2015-02-11 00:07:07,018 INFO mapred.Task (Task.java:initialize(587)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-11 00:07:07,020 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/lhs.txt
2015-02-11 00:07:07,021 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@2c79cd09
2015-02-11 00:07:07,022 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-11 00:07:07,023 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-11 00:07:07,167 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-11 00:07:07,168 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-11 00:07:07,168 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-11 00:07:07,168 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-11 00:07:07,168 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-11 00:07:07,170 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-11 00:07:07,170 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-11 00:07:07,185 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/lhs.txt"]
2015-02-11 00:07:07,185 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:'num']]
2015-02-11 00:07:07,190 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-11 00:07:07,190 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2015-02-11 00:07:07,190 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2015-02-11 00:07:07,190 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 195; bufvoid = 104857600
2015-02-11 00:07:07,190 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214348(104857392); length = 49/6553600
2015-02-11 00:07:07,197 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2015-02-11 00:07:07,201 INFO mapred.Task (Task.java:done(1001)) - Task:attempt_local1724005925_0002_m_000000_0 is done. And is in the process of committing
2015-02-11 00:07:07,204 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/lhs.txt:0+52
2015-02-11 00:07:07,204 INFO mapred.Task (Task.java:sendDone(1121)) - Task 'attempt_local1724005925_0002_m_000000_0' done.
2015-02-11 00:07:07,205 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1724005925_0002_m_000000_0
2015-02-11 00:07:07,205 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-11 00:07:07,206 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2015-02-11 00:07:07,206 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1724005925_0002_r_000000_0
2015-02-11 00:07:07,209 INFO mapred.Task (Task.java:initialize(587)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-11 00:07:07,209 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@43422d0b
2015-02-11 00:07:07,210 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2015-02-11 00:07:07,211 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1724005925_0002_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2015-02-11 00:07:07,213 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#2 about to shuffle output of map attempt_local1724005925_0002_m_000000_0 decomp: 223 len: 227 to MEMORY
2015-02-11 00:07:07,214 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 223 bytes from map-output for attempt_local1724005925_0002_m_000000_0
2015-02-11 00:07:07,215 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 223, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->223
2015-02-11 00:07:07,216 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2015-02-11 00:07:07,217 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-11 00:07:07,217 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2015-02-11 00:07:07,221 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-11 00:07:07,222 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 214 bytes
2015-02-11 00:07:07,224 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 223 bytes to disk to satisfy reduce memory limit
2015-02-11 00:07:07,225 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 227 bytes from disk
2015-02-11 00:07:07,225 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2015-02-11 00:07:07,225 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-11 00:07:07,226 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 214 bytes
2015-02-11 00:07:07,227 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-11 00:07:07,227 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.6.3
2015-02-11 00:07:07,227 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2015-02-11 00:07:07,240 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:'num']]
2015-02-11 00:07:07,240 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/bufferpipesplatform/simple"]
2015-02-11 00:07:07,257 INFO mapred.Task (Task.java:done(1001)) - Task:attempt_local1724005925_0002_r_000000_0 is done. And is in the process of committing
2015-02-11 00:07:07,259 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-11 00:07:07,259 INFO mapred.Task (Task.java:commit(1162)) - Task attempt_local1724005925_0002_r_000000_0 is allowed to commit now
2015-02-11 00:07:07,260 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1724005925_0002_r_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/bufferpipesplatform/simple/_temporary/0/task_local1724005925_0002_r_000000
2015-02-11 00:07:07,262 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2015-02-11 00:07:07,262 INFO mapred.Task (Task.java:sendDone(1121)) - Task 'attempt_local1724005925_0002_r_000000_0' done.
2015-02-11 00:07:07,262 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1724005925_0002_r_000000_0
2015-02-11 00:07:07,263 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2015-02-11 00:07:07,286 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/bufferpipesplatform/simple/_temporary
2015-02-11 00:07:07,344 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-11 00:07:07,393 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-11 00:07:07,396 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/bufferpipesplatform/simple
2015-02-11 00:07:07,431 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-11 00:07:07,432 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-11 00:07:07,455 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-11 00:07:07,464 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-11 00:07:07,465 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-11 00:07:07,483 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [lower*upper] starting
2015-02-11 00:07:07,483 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [lower*upper] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/upper.txt"]
2015-02-11 00:07:07,484 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [lower*upper] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/lower.txt"]
2015-02-11 00:07:07,484 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [lower*upper] sink: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/bufferpipesplatform/cogroup"]
2015-02-11 00:07:07,485 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [lower*upper] parallel execution is enabled: false
2015-02-11 00:07:07,485 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [lower*upper] starting jobs: 1
2015-02-11 00:07:07,485 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [lower*upper] allocating threads: 1
2015-02-11 00:07:07,486 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [lower*upper] starting step: (1/1) ...fferpipesplatform/cogroup
2015-02-11 00:07:07,487 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-11 00:07:07,489 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-11 00:07:07,525 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-11 00:07:07,527 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-11 00:07:07,552 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:2
2015-02-11 00:07:07,621 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local105547618_0003
2015-02-11 00:07:07,646 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/tmp/cascading/staging/teamcity105547618/.staging/job_local105547618_0003/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-11 00:07:07,649 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/tmp/cascading/staging/teamcity105547618/.staging/job_local105547618_0003/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-11 00:07:07,741 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_local105547618_0003/job_local105547618_0003.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-11 00:07:07,744 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_local105547618_0003/job_local105547618_0003.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-11 00:07:07,745 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-11 00:07:07,745 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [lower*upper] submitted hadoop job: job_local105547618_0003
2015-02-11 00:07:07,746 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [lower*upper] tracking url: http://localhost:8080/
2015-02-11 00:07:07,746 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-11 00:07:07,746 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-11 00:07:07,753 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-11 00:07:07,753 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local105547618_0003_m_000000_0
2015-02-11 00:07:07,757 INFO mapred.Task (Task.java:initialize(587)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-11 00:07:07,760 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-11 00:07:07,760 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@39ce9085
2015-02-11 00:07:07,763 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-11 00:07:07,763 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-11 00:07:07,920 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-11 00:07:07,921 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-11 00:07:07,921 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-11 00:07:07,921 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-11 00:07:07,921 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-11 00:07:07,926 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-11 00:07:07,926 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-11 00:07:07,943 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/lower.txt"]
2015-02-11 00:07:07,943 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: CoGroup(lower*upper)[by: lower:[{1}:'num'] upper:[{1}:'num']]
2015-02-11 00:07:07,946 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-11 00:07:07,947 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2015-02-11 00:07:07,947 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2015-02-11 00:07:07,947 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 85; bufvoid = 104857600
2015-02-11 00:07:07,947 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214380(104857520); length = 17/6553600
2015-02-11 00:07:07,953 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2015-02-11 00:07:07,956 INFO mapred.Task (Task.java:done(1001)) - Task:attempt_local105547618_0003_m_000000_0 is done. And is in the process of committing
2015-02-11 00:07:07,959 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-11 00:07:07,959 INFO mapred.Task (Task.java:sendDone(1121)) - Task 'attempt_local105547618_0003_m_000000_0' done.
2015-02-11 00:07:07,959 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local105547618_0003_m_000000_0
2015-02-11 00:07:07,960 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local105547618_0003_m_000001_0
2015-02-11 00:07:07,962 INFO mapred.Task (Task.java:initialize(587)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-11 00:07:07,966 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-11 00:07:07,966 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@70da8742
2015-02-11 00:07:07,969 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-11 00:07:07,970 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-11 00:07:08,119 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-11 00:07:08,120 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-11 00:07:08,120 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-11 00:07:08,120 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-11 00:07:08,121 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-11 00:07:08,123 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-11 00:07:08,123 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-11 00:07:08,137 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/upper.txt"]
2015-02-11 00:07:08,137 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: CoGroup(lower*upper)[by: lower:[{1}:'num'] upper:[{1}:'num']]
2015-02-11 00:07:08,141 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-11 00:07:08,141 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2015-02-11 00:07:08,141 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2015-02-11 00:07:08,141 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 85; bufvoid = 104857600
2015-02-11 00:07:08,141 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214380(104857520); length = 17/6553600
2015-02-11 00:07:08,146 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2015-02-11 00:07:08,149 INFO mapred.Task (Task.java:done(1001)) - Task:attempt_local105547618_0003_m_000001_0 is done. And is in the process of committing
2015-02-11 00:07:08,152 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-11 00:07:08,152 INFO mapred.Task (Task.java:sendDone(1121)) - Task 'attempt_local105547618_0003_m_000001_0' done.
2015-02-11 00:07:08,153 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local105547618_0003_m_000001_0
2015-02-11 00:07:08,153 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-11 00:07:08,154 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2015-02-11 00:07:08,154 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local105547618_0003_r_000000_0
2015-02-11 00:07:08,158 INFO mapred.Task (Task.java:initialize(587)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-11 00:07:08,159 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@215a3a92
2015-02-11 00:07:08,160 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2015-02-11 00:07:08,160 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local105547618_0003_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2015-02-11 00:07:08,163 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#3 about to shuffle output of map attempt_local105547618_0003_m_000001_0 decomp: 97 len: 101 to MEMORY
2015-02-11 00:07:08,164 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 97 bytes from map-output for attempt_local105547618_0003_m_000001_0
2015-02-11 00:07:08,165 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 97, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->97
2015-02-11 00:07:08,169 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#3 about to shuffle output of map attempt_local105547618_0003_m_000000_0 decomp: 97 len: 101 to MEMORY
2015-02-11 00:07:08,170 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 97 bytes from map-output for attempt_local105547618_0003_m_000000_0
2015-02-11 00:07:08,170 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 97, inMemoryMapOutputs.size() -> 2, commitMemory -> 97, usedMemory ->194
2015-02-11 00:07:08,172 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2015-02-11 00:07:08,173 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 2 / 2 copied.
2015-02-11 00:07:08,173 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 2 in-memory map-outputs and 0 on-disk map-outputs
2015-02-11 00:07:08,177 INFO mapred.Merger (Merger.java:merge(591)) - Merging 2 sorted segments
2015-02-11 00:07:08,178 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 2 segments left of total size: 174 bytes
2015-02-11 00:07:08,180 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 2 segments, 194 bytes to disk to satisfy reduce memory limit
2015-02-11 00:07:08,181 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 196 bytes from disk
2015-02-11 00:07:08,181 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2015-02-11 00:07:08,181 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-11 00:07:08,182 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 182 bytes
2015-02-11 00:07:08,183 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 2 / 2 copied.
2015-02-11 00:07:08,183 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.6.3
2015-02-11 00:07:08,184 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2015-02-11 00:07:08,196 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: CoGroup(lower*upper)[by: lower:[{1}:'num'] upper:[{1}:'num']]
2015-02-11 00:07:08,196 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/bufferpipesplatform/cogroup"]
2015-02-11 00:07:08,219 INFO collect.SpillableTupleList (SpillableTupleList.java:getCodecClass(105)) - attempting to load codec: org.apache.hadoop.io.compress.GzipCodec
2015-02-11 00:07:08,219 INFO collect.SpillableTupleList (SpillableTupleList.java:getCodecClass(110)) - found codec: org.apache.hadoop.io.compress.GzipCodec
2015-02-11 00:07:08,228 INFO mapred.Task (Task.java:done(1001)) - Task:attempt_local105547618_0003_r_000000_0 is done. And is in the process of committing
2015-02-11 00:07:08,230 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 2 / 2 copied.
2015-02-11 00:07:08,230 INFO mapred.Task (Task.java:commit(1162)) - Task attempt_local105547618_0003_r_000000_0 is allowed to commit now
2015-02-11 00:07:08,231 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local105547618_0003_r_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/bufferpipesplatform/cogroup/_temporary/0/task_local105547618_0003_r_000000
2015-02-11 00:07:08,233 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2015-02-11 00:07:08,233 INFO mapred.Task (Task.java:sendDone(1121)) - Task 'attempt_local105547618_0003_r_000000_0' done.
2015-02-11 00:07:08,233 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local105547618_0003_r_000000_0
2015-02-11 00:07:08,234 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2015-02-11 00:07:08,273 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/bufferpipesplatform/cogroup/_temporary
2015-02-11 00:07:08,330 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-11 00:07:08,374 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-11 00:07:08,377 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/bufferpipesplatform/cogroup
2015-02-11 00:07:08,407 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-11 00:07:08,408 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-11 00:07:08,425 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-11 00:07:08,430 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-11 00:07:08,431 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-11 00:07:08,442 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting
2015-02-11 00:07:08,442 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/lhs.txt"]
2015-02-11 00:07:08,442 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] sink: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/bufferpipesplatform/simple2"]
2015-02-11 00:07:08,443 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] parallel execution is enabled: false
2015-02-11 00:07:08,443 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting jobs: 1
2015-02-11 00:07:08,443 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] allocating threads: 1
2015-02-11 00:07:08,444 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...fferpipesplatform/simple2
2015-02-11 00:07:08,445 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-11 00:07:08,446 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-11 00:07:08,478 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-11 00:07:08,499 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-11 00:07:08,521 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local787780223_0004
2015-02-11 00:07:08,542 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/tmp/cascading/staging/teamcity787780223/.staging/job_local787780223_0004/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-11 00:07:08,543 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/tmp/cascading/staging/teamcity787780223/.staging/job_local787780223_0004/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-11 00:07:08,606 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_local787780223_0004/job_local787780223_0004.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-11 00:07:08,607 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_local787780223_0004/job_local787780223_0004.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-11 00:07:08,608 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-11 00:07:08,609 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local787780223_0004
2015-02-11 00:07:08,609 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-11 00:07:08,610 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2015-02-11 00:07:08,610 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-11 00:07:08,615 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-11 00:07:08,615 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local787780223_0004_m_000000_0
2015-02-11 00:07:08,617 INFO mapred.Task (Task.java:initialize(587)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-11 00:07:08,619 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/lhs.txt
2015-02-11 00:07:08,619 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@7b7e7691
2015-02-11 00:07:08,621 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-11 00:07:08,622 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-11 00:07:08,765 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-11 00:07:08,766 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-11 00:07:08,766 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-11 00:07:08,766 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-11 00:07:08,766 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-11 00:07:08,768 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-11 00:07:08,768 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-11 00:07:08,778 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/lhs.txt"]
2015-02-11 00:07:08,779 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:'num']]
2015-02-11 00:07:08,783 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-11 00:07:08,783 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2015-02-11 00:07:08,783 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2015-02-11 00:07:08,783 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 195; bufvoid = 104857600
2015-02-11 00:07:08,783 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214348(104857392); length = 49/6553600
2015-02-11 00:07:08,788 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2015-02-11 00:07:08,792 INFO mapred.Task (Task.java:done(1001)) - Task:attempt_local787780223_0004_m_000000_0 is done. And is in the process of committing
2015-02-11 00:07:08,795 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/lhs.txt:0+52
2015-02-11 00:07:08,795 INFO mapred.Task (Task.java:sendDone(1121)) - Task 'attempt_local787780223_0004_m_000000_0' done.
2015-02-11 00:07:08,795 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local787780223_0004_m_000000_0
2015-02-11 00:07:08,795 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-11 00:07:08,796 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2015-02-11 00:07:08,796 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local787780223_0004_r_000000_0
2015-02-11 00:07:08,799 INFO mapred.Task (Task.java:initialize(587)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-11 00:07:08,799 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@2d8ed284
2015-02-11 00:07:08,800 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2015-02-11 00:07:08,801 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local787780223_0004_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2015-02-11 00:07:08,803 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#4 about to shuffle output of map attempt_local787780223_0004_m_000000_0 decomp: 223 len: 227 to MEMORY
2015-02-11 00:07:08,804 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 223 bytes from map-output for attempt_local787780223_0004_m_000000_0
2015-02-11 00:07:08,804 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 223, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->223
2015-02-11 00:07:08,805 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2015-02-11 00:07:08,806 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-11 00:07:08,806 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2015-02-11 00:07:08,809 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-11 00:07:08,810 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 214 bytes
2015-02-11 00:07:08,812 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 223 bytes to disk to satisfy reduce memory limit
2015-02-11 00:07:08,812 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 227 bytes from disk
2015-02-11 00:07:08,813 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2015-02-11 00:07:08,813 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-11 00:07:08,813 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 214 bytes
2015-02-11 00:07:08,814 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-11 00:07:08,814 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.6.3
2015-02-11 00:07:08,815 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2015-02-11 00:07:08,825 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:'num']]
2015-02-11 00:07:08,826 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/bufferpipesplatform/simple2"]
2015-02-11 00:07:08,840 INFO mapred.Task (Task.java:done(1001)) - Task:attempt_local787780223_0004_r_000000_0 is done. And is in the process of committing
2015-02-11 00:07:08,843 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-11 00:07:08,843 INFO mapred.Task (Task.java:commit(1162)) - Task attempt_local787780223_0004_r_000000_0 is allowed to commit now
2015-02-11 00:07:08,844 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local787780223_0004_r_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/bufferpipesplatform/simple2/_temporary/0/task_local787780223_0004_r_000000
2015-02-11 00:07:08,845 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2015-02-11 00:07:08,846 INFO mapred.Task (Task.java:sendDone(1121)) - Task 'attempt_local787780223_0004_r_000000_0' done.
2015-02-11 00:07:08,846 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local787780223_0004_r_000000_0
2015-02-11 00:07:08,846 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2015-02-11 00:07:08,874 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/bufferpipesplatform/simple2/_temporary
2015-02-11 00:07:08,913 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-11 00:07:08,951 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-11 00:07:08,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/bufferpipesplatform/simple2
2015-02-11 00:07:09,283 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-11 00:07:09,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-11 00:07:09,296 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-11 00:07:09,300 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-11 00:07:09,301 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1019)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-11 00:07:09,310 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting
2015-02-11 00:07:09,310 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/lower+upper.txt"]
2015-02-11 00:07:09,311 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] sink: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/bufferpipesplatform/simple3"]
2015-02-11 00:07:09,311 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] parallel execution is enabled: false
2015-02-11 00:07:09,311 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting jobs: 1
2015-02-11 00:07:09,311 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] allocating threads: 1
2015-02-11 00:07:09,312 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...fferpipesplatform/simple3
2015-02-11 00:07:09,313 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-11 00:07:09,314 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-11 00:07:09,346 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-11 00:07:09,368 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-11 00:07:09,387 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local69965795_0005
2015-02-11 00:07:09,408 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/tmp/cascading/staging/teamcity69965795/.staging/job_local69965795_0005/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-11 00:07:09,410 WARN conf.Configuration (Configuration.java:loadProperty(2368)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/tmp/cascading/staging/teamcity69965795/.staging/job_local69965795_0005/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-11 00:07:09,468 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_local69965795_0005/job_local69965795_0005.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-11 00:07:09,469 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_local69965795_0005/job_local69965795_0005.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-11 00:07:09,470 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-11 00:07:09,470 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local69965795_0005
2015-02-11 00:07:09,471 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-11 00:07:09,471 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-11 00:07:09,471 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2015-02-11 00:07:09,475 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-11 00:07:09,475 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local69965795_0005_m_000000_0
2015-02-11 00:07:09,477 INFO mapred.Task (Task.java:initialize(587)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-11 00:07:09,479 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-11 00:07:09,479 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@2f26f304
2015-02-11 00:07:09,481 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-11 00:07:09,481 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-11 00:07:09,549 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-11 00:07:09,550 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-11 00:07:09,550 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-11 00:07:09,550 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-11 00:07:09,550 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-11 00:07:09,552 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-11 00:07:09,552 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-11 00:07:09,562 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/classes/test/data/lower+upper.txt"]
2015-02-11 00:07:09,562 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:'num']]
2015-02-11 00:07:09,565 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-11 00:07:09,566 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2015-02-11 00:07:09,566 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2015-02-11 00:07:09,566 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 105; bufvoid = 104857600
2015-02-11 00:07:09,566 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214380(104857520); length = 17/6553600
2015-02-11 00:07:09,571 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2015-02-11 00:07:09,573 INFO mapred.Task (Task.java:done(1001)) - Task:attempt_local69965795_0005_m_000000_0 is done. And is in the process of committing
2015-02-11 00:07:09,576 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-11 00:07:09,576 INFO mapred.Task (Task.java:sendDone(1121)) - Task 'attempt_local69965795_0005_m_000000_0' done.
2015-02-11 00:07:09,576 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local69965795_0005_m_000000_0
2015-02-11 00:07:09,577 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-11 00:07:09,577 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2015-02-11 00:07:09,577 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local69965795_0005_r_000000_0
2015-02-11 00:07:09,580 INFO mapred.Task (Task.java:initialize(587)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-11 00:07:09,580 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@56781dd4
2015-02-11 00:07:09,581 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2015-02-11 00:07:09,582 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local69965795_0005_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2015-02-11 00:07:09,584 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#5 about to shuffle output of map attempt_local69965795_0005_m_000000_0 decomp: 117 len: 121 to MEMORY
2015-02-11 00:07:09,584 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 117 bytes from map-output for attempt_local69965795_0005_m_000000_0
2015-02-11 00:07:09,585 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 117, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->117
2015-02-11 00:07:09,585 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2015-02-11 00:07:09,587 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-11 00:07:09,587 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2015-02-11 00:07:09,590 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-11 00:07:09,590 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 108 bytes
2015-02-11 00:07:09,592 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 117 bytes to disk to satisfy reduce memory limit
2015-02-11 00:07:09,593 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 121 bytes from disk
2015-02-11 00:07:09,593 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2015-02-11 00:07:09,593 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-11 00:07:09,593 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 108 bytes
2015-02-11 00:07:09,594 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-11 00:07:09,595 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.6.3
2015-02-11 00:07:09,595 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2015-02-11 00:07:09,604 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:'num']]
2015-02-11 00:07:09,604 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/bufferpipesplatform/simple3"]
2015-02-11 00:07:09,617 INFO mapred.Task (Task.java:done(1001)) - Task:attempt_local69965795_0005_r_000000_0 is done. And is in the process of committing
2015-02-11 00:07:09,619 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-11 00:07:09,620 INFO mapred.Task (Task.java:commit(1162)) - Task attempt_local69965795_0005_r_000000_0 is allowed to commit now
2015-02-11 00:07:09,620 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local69965795_0005_r_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.5.x/build/test/output/hadoop2-mr1/bufferpipesplatform/simple3/_temporary/0/task_local69965795_0005_r_000000
2015-02-11 00:07:09,622 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2015-02-11 00:07:09,622 INFO mapred.Task (Task.java:sendDone(1121)) - Task 'attempt_local69965795_0005_r_000000_0' done.
2015-02-11 00:07:09,623 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local69965795_0005_r_000000_0
2015-02-11 00:07:09,623 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2015-02-11 00:07:09,644 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/bufferpipesplatform/simple3/_temporary
2015-02-11 00:07:09,678 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-11 00:07:09,718 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-11 00:07:09,720 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/bufferpipesplatform/simple3
2015-02-11 00:07:09,749 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-11 00:07:09,749 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