2015-02-10 21:28:13,430 INFO platform.PlatformRunner (PlatformRunner.java:getPlatformClassesFromClasspath(187)) - found 1 test platforms from classpath
2015-02-10 21:28:13,497 INFO platform.PlatformRunner (PlatformRunner.java:addPlatform(237)) - installing platform: hadoop2-mr1
2015-02-10 21:28:13,498 INFO platform.PlatformRunner (PlatformRunner.java:addPlatform(238)) - running test: cascading.BasicPipesPlatformTest
2015-02-10 21:28:13,531 INFO hadoop2.Hadoop2MR1Platform (Hadoop2MR1Platform.java:setUp(105)) - not using cluster
2015-02-10 21:28:14,198 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 21:28:14,511 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 21:28:14,513 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 21:28:14,526 INFO property.AppProps (AppProps.java:getAppID(169)) - using app.id: 243FE024A4FA49F288A56B73C26CF3F6
2015-02-10 21:28:14,619 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 21:28:14,663 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 21:28:14,753 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 21:28:14,823 INFO util.Version (Version.java:printBanner(82)) - Concurrent, Inc - Cascading 2.6.3
2015-02-10 21:28:14,825 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting
2015-02-10 21:28:14,826 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2015-02-10 21:28:14,827 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/basicpipesplatform/simplechain"]
2015-02-10 21:28:14,827 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] parallel execution is enabled: false
2015-02-10 21:28:14,829 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting jobs: 2
2015-02-10 21:28:14,829 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] allocating threads: 1
2015-02-10 21:28:14,830 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/2)
2015-02-10 21:28:14,856 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - session.id is deprecated. Instead, use dfs.metrics.session-id
2015-02-10 21:28:14,858 INFO jvm.JvmMetrics (JvmMetrics.java:init(76)) - Initializing JVM Metrics with processName=JobTracker, sessionId=
2015-02-10 21:28:14,884 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 21:28:15,276 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 21:28:15,320 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 21:28:15,516 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1829711919_0001
2015-02-10 21:28:15,559 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity1829711919/.staging/job_local1829711919_0001/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 21:28:15,567 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity1829711919/.staging/job_local1829711919_0001/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 21:28:15,741 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_local1829711919_0001/job_local1829711919_0001.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 21:28:15,745 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_local1829711919_0001/job_local1829711919_0001.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 21:28:15,751 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 21:28:15,752 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 21:28:15,755 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local1829711919_0001
2015-02-10 21:28:15,755 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2015-02-10 21:28:15,756 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 21:28:15,814 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 21:28:15,818 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1829711919_0001_m_000000_0
2015-02-10 21:28:15,866 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 21:28:15,877 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/apache.10.txt
2015-02-10 21:28:15,877 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@7e4e194f
2015-02-10 21:28:15,888 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-10 21:28:15,895 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-10 21:28:16,047 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-10 21:28:16,047 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-10 21:28:16,048 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-10 21:28:16,048 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-10 21:28:16,048 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-10 21:28:16,076 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 21:28:16,076 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 21:28:16,127 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.task.partition is deprecated. Instead, use mapreduce.task.partition
2015-02-10 21:28:16,145 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2015-02-10 21:28:16,146 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:0]]
2015-02-10 21:28:16,162 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 21:28:16,162 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2015-02-10 21:28:16,162 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2015-02-10 21:28:16,163 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 210; bufvoid = 104857600
2015-02-10 21:28:16,163 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214360(104857440); length = 37/6553600
2015-02-10 21:28:16,176 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2015-02-10 21:28:16,180 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1829711919_0001_m_000000_0 is done. And is in the process of committing
2015-02-10 21:28:16,191 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt:0+1449
2015-02-10 21:28:16,192 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1829711919_0001_m_000000_0' done.
2015-02-10 21:28:16,192 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1829711919_0001_m_000000_0
2015-02-10 21:28:16,192 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 21:28:16,213 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2015-02-10 21:28:16,214 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1829711919_0001_r_000000_0
2015-02-10 21:28:16,223 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 21:28:16,227 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@5c5f1c48
2015-02-10 21:28:16,242 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2015-02-10 21:28:16,246 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1829711919_0001_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2015-02-10 21:28:16,280 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#1 about to shuffle output of map attempt_local1829711919_0001_m_000000_0 decomp: 232 len: 236 to MEMORY
2015-02-10 21:28:16,285 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 232 bytes from map-output for attempt_local1829711919_0001_m_000000_0
2015-02-10 21:28:16,331 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 232, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->232
2015-02-10 21:28:16,332 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2015-02-10 21:28:16,333 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 21:28:16,333 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2015-02-10 21:28:16,343 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 21:28:16,343 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 211 bytes
2015-02-10 21:28:16,346 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 232 bytes to disk to satisfy reduce memory limit
2015-02-10 21:28:16,346 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 236 bytes from disk
2015-02-10 21:28:16,347 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2015-02-10 21:28:16,347 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 21:28:16,348 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 211 bytes
2015-02-10 21:28:16,349 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 21:28:16,351 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.6.3
2015-02-10 21:28:16,351 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2015-02-10 21:28:16,369 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:0]]
2015-02-10 21:28:16,369 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: TempHfs["SequenceFile[[0, 'count']]"][1927437263/test/]
2015-02-10 21:28:16,407 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1829711919_0001_r_000000_0 is done. And is in the process of committing
2015-02-10 21:28:16,409 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 21:28:16,410 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1829711919_0001_r_000000_0 is allowed to commit now
2015-02-10 21:28:16,411 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1829711919_0001_r_000000_0' to file:/tmp/hadoop-teamcity/1927437263_test_F475C821C60E405EBBC15EC4A616B36A/_temporary/0/task_local1829711919_0001_r_000000
2015-02-10 21:28:16,412 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2015-02-10 21:28:16,413 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1829711919_0001_r_000000_0' done.
2015-02-10 21:28:16,413 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1829711919_0001_r_000000_0
2015-02-10 21:28:16,413 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2015-02-10 21:28:16,461 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (2/2) ...pipesplatform/simplechain
2015-02-10 21:28:16,462 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 21:28:16,463 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 21:28:16,514 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 21:28:16,540 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 21:28:16,558 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 21:28:16,559 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 21:28:16,585 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local2144439060_0002
2015-02-10 21:28:16,610 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity2144439060/.staging/job_local2144439060_0002/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 21:28:16,614 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity2144439060/.staging/job_local2144439060_0002/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 21:28:16,709 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_local2144439060_0002/job_local2144439060_0002.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 21:28:16,713 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_local2144439060_0002/job_local2144439060_0002.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 21:28:16,714 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 21:28:16,715 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local2144439060_0002
2015-02-10 21:28:16,715 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 21:28:16,715 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2015-02-10 21:28:16,716 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 21:28:16,722 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 21:28:16,722 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local2144439060_0002_m_000000_0
2015-02-10 21:28:16,726 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 21:28:16,728 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/tmp/hadoop-teamcity/1927437263_test_F475C821C60E405EBBC15EC4A616B36A/part-00000
2015-02-10 21:28:16,728 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@65cb048e
2015-02-10 21:28:16,741 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-10 21:28:16,742 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-10 21:28:16,886 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-10 21:28:16,886 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-10 21:28:16,886 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-10 21:28:16,886 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-10 21:28:16,886 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-10 21:28:16,888 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 21:28:16,888 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 21:28:16,901 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: TempHfs["SequenceFile[[0, 'count']]"][1927437263/test/]
2015-02-10 21:28:16,901 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:0]]
2015-02-10 21:28:16,905 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 21:28:16,905 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2015-02-10 21:28:16,905 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2015-02-10 21:28:16,905 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 184; bufvoid = 104857600
2015-02-10 21:28:16,906 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214368(104857472); length = 29/6553600
2015-02-10 21:28:16,912 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2015-02-10 21:28:16,915 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local2144439060_0002_m_000000_0 is done. And is in the process of committing
2015-02-10 21:28:16,918 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/tmp/hadoop-teamcity/1927437263_test_F475C821C60E405EBBC15EC4A616B36A/part-00000:0+310
2015-02-10 21:28:16,918 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local2144439060_0002_m_000000_0' done.
2015-02-10 21:28:16,919 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local2144439060_0002_m_000000_0
2015-02-10 21:28:16,919 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 21:28:16,920 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2015-02-10 21:28:16,920 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local2144439060_0002_r_000000_0
2015-02-10 21:28:16,923 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 21:28:16,923 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@4a6f19d5
2015-02-10 21:28:16,924 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2015-02-10 21:28:16,925 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local2144439060_0002_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2015-02-10 21:28:16,928 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#2 about to shuffle output of map attempt_local2144439060_0002_m_000000_0 decomp: 202 len: 206 to MEMORY
2015-02-10 21:28:16,929 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 202 bytes from map-output for attempt_local2144439060_0002_m_000000_0
2015-02-10 21:28:16,930 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 202, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->202
2015-02-10 21:28:16,930 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2015-02-10 21:28:16,934 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 21:28:16,934 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2015-02-10 21:28:16,938 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 21:28:16,938 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 181 bytes
2015-02-10 21:28:16,940 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 202 bytes to disk to satisfy reduce memory limit
2015-02-10 21:28:16,941 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 206 bytes from disk
2015-02-10 21:28:16,941 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2015-02-10 21:28:16,941 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 21:28:16,942 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 181 bytes
2015-02-10 21:28:16,943 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 21:28:16,944 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.6.3
2015-02-10 21:28:16,944 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2015-02-10 21:28:16,956 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:0]]
2015-02-10 21:28:16,956 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/basicpipesplatform/simplechain"]
2015-02-10 21:28:16,974 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local2144439060_0002_r_000000_0 is done. And is in the process of committing
2015-02-10 21:28:16,977 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 21:28:16,977 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local2144439060_0002_r_000000_0 is allowed to commit now
2015-02-10 21:28:16,978 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local2144439060_0002_r_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/simplechain/_temporary/0/task_local2144439060_0002_r_000000
2015-02-10 21:28:16,980 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2015-02-10 21:28:16,980 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local2144439060_0002_r_000000_0' done.
2015-02-10 21:28:16,980 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local2144439060_0002_r_000000_0
2015-02-10 21:28:16,981 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2015-02-10 21:28:17,015 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/basicpipesplatform/simplechain/_temporary
2015-02-10 21:28:17,076 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 21:28:17,084 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/basicpipesplatform/simplechain
2015-02-10 21:28:17,123 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 21:28:17,123 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 21:28:17,140 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 21:28:17,145 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 21:28:17,146 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 21:28:17,157 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] starting
2015-02-10 21:28:17,157 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/ips.20.txt"]
2015-02-10 21:28:17,158 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] sink: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/count"]
2015-02-10 21:28:17,159 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] parallel execution is enabled: false
2015-02-10 21:28:17,159 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] starting jobs: 1
2015-02-10 21:28:17,159 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] allocating threads: 1
2015-02-10 21:28:17,160 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] starting step: (1/1) .../basicpipesplatform/count
2015-02-10 21:28:17,161 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 21:28:17,163 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 21:28:17,198 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 21:28:17,224 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 21:28:17,270 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local406414182_0003
2015-02-10 21:28:17,295 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity406414182/.staging/job_local406414182_0003/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 21:28:17,298 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity406414182/.staging/job_local406414182_0003/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 21:28:17,372 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_local406414182_0003/job_local406414182_0003.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 21:28:17,374 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_local406414182_0003/job_local406414182_0003.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 21:28:17,375 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 21:28:17,376 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] submitted hadoop job: job_local406414182_0003
2015-02-10 21:28:17,377 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] tracking url: http://localhost:8080/
2015-02-10 21:28:17,378 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 21:28:17,378 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 21:28:17,384 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 21:28:17,384 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local406414182_0003_m_000000_0
2015-02-10 21:28:17,387 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 21:28:17,389 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/ips.20.txt
2015-02-10 21:28:17,389 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@39d7af3
2015-02-10 21:28:17,391 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-10 21:28:17,392 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-10 21:28:17,538 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-10 21:28:17,538 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-10 21:28:17,538 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-10 21:28:17,539 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-10 21:28:17,539 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-10 21:28:17,542 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 21:28:17,542 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 21:28:17,552 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/ips.20.txt"]
2015-02-10 21:28:17,552 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(count)[by:[{1}:1]]
2015-02-10 21:28:17,557 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 21:28:17,557 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2015-02-10 21:28:17,557 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2015-02-10 21:28:17,557 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 466; bufvoid = 104857600
2015-02-10 21:28:17,557 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214320(104857280); length = 77/6553600
2015-02-10 21:28:17,565 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2015-02-10 21:28:17,569 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local406414182_0003_m_000000_0 is done. And is in the process of committing
2015-02-10 21:28:17,571 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/ips.20.txt:0+275
2015-02-10 21:28:17,571 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local406414182_0003_m_000000_0' done.
2015-02-10 21:28:17,572 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local406414182_0003_m_000000_0
2015-02-10 21:28:17,573 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 21:28:17,574 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2015-02-10 21:28:17,574 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local406414182_0003_r_000000_0
2015-02-10 21:28:17,577 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 21:28:17,577 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@21913751
2015-02-10 21:28:17,578 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2015-02-10 21:28:17,579 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local406414182_0003_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2015-02-10 21:28:17,582 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#3 about to shuffle output of map attempt_local406414182_0003_m_000000_0 decomp: 508 len: 512 to MEMORY
2015-02-10 21:28:17,583 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 508 bytes from map-output for attempt_local406414182_0003_m_000000_0
2015-02-10 21:28:17,583 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 508, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->508
2015-02-10 21:28:17,583 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2015-02-10 21:28:17,585 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 21:28:17,586 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2015-02-10 21:28:17,589 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 21:28:17,589 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 487 bytes
2015-02-10 21:28:17,592 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 508 bytes to disk to satisfy reduce memory limit
2015-02-10 21:28:17,592 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 512 bytes from disk
2015-02-10 21:28:17,592 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2015-02-10 21:28:17,592 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 21:28:17,593 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 487 bytes
2015-02-10 21:28:17,594 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 21:28:17,594 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.6.3
2015-02-10 21:28:17,594 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2015-02-10 21:28:17,605 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(count)[by:[{1}:1]]
2015-02-10 21:28:17,605 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/count"]
2015-02-10 21:28:17,621 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local406414182_0003_r_000000_0 is done. And is in the process of committing
2015-02-10 21:28:17,623 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 21:28:17,624 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local406414182_0003_r_000000_0 is allowed to commit now
2015-02-10 21:28:17,625 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local406414182_0003_r_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/count/_temporary/0/task_local406414182_0003_r_000000
2015-02-10 21:28:17,626 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2015-02-10 21:28:17,626 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local406414182_0003_r_000000_0' done.
2015-02-10 21:28:17,627 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local406414182_0003_r_000000_0
2015-02-10 21:28:17,627 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2015-02-10 21:28:17,655 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/basicpipesplatform/count/_temporary
2015-02-10 21:28:17,700 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 21:28:17,749 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 21:28:17,754 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/basicpipesplatform/count
2015-02-10 21:28:17,801 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 21:28:17,802 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 21:28:17,817 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 21:28:17,823 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 21:28:17,824 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 21:28:17,834 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting
2015-02-10 21:28:17,835 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2015-02-10 21:28:17,835 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/basicpipesplatform/swap"]
2015-02-10 21:28:17,836 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] parallel execution is enabled: false
2015-02-10 21:28:17,836 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting jobs: 1
2015-02-10 21:28:17,836 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] allocating threads: 1
2015-02-10 21:28:17,837 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...1/basicpipesplatform/swap
2015-02-10 21:28:17,837 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 21:28:17,839 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 21:28:17,871 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 21:28:17,895 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 21:28:17,916 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local59832320_0004
2015-02-10 21:28:17,940 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity59832320/.staging/job_local59832320_0004/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 21:28:17,942 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity59832320/.staging/job_local59832320_0004/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 21:28:18,000 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_local59832320_0004/job_local59832320_0004.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 21:28:18,002 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_local59832320_0004/job_local59832320_0004.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 21:28:18,003 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 21:28:18,003 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local59832320_0004
2015-02-10 21:28:18,003 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2015-02-10 21:28:18,004 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 21:28:18,005 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 21:28:18,009 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 21:28:18,010 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local59832320_0004_m_000000_0
2015-02-10 21:28:18,012 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 21:28:18,014 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/apache.10.txt
2015-02-10 21:28:18,015 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@2b115a61
2015-02-10 21:28:18,016 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 0
2015-02-10 21:28:18,027 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 21:28:18,027 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 21:28:18,037 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2015-02-10 21:28:18,037 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/swap"]
2015-02-10 21:28:18,042 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 21:28:18,042 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local59832320_0004_m_000000_0 is done. And is in the process of committing
2015-02-10 21:28:18,044 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 21:28:18,044 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local59832320_0004_m_000000_0 is allowed to commit now
2015-02-10 21:28:18,045 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local59832320_0004_m_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/swap/_temporary/0/task_local59832320_0004_m_000000
2015-02-10 21:28:18,047 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt:0+1449
2015-02-10 21:28:18,047 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local59832320_0004_m_000000_0' done.
2015-02-10 21:28:18,047 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local59832320_0004_m_000000_0
2015-02-10 21:28:18,047 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 21:28:18,070 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/basicpipesplatform/swap/_temporary
2015-02-10 21:28:18,109 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 21:28:18,113 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/basicpipesplatform/swap
2015-02-10 21:28:18,144 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 21:28:18,145 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 21:28:18,157 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 21:28:18,162 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 21:28:18,163 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 21:28:18,174 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting
2015-02-10 21:28:18,174 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/lower+upper.txt"]
2015-02-10 21:28:18,175 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/basicpipesplatform/ungrouped"]
2015-02-10 21:28:18,175 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] parallel execution is enabled: false
2015-02-10 21:28:18,175 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting jobs: 1
2015-02-10 21:28:18,175 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] allocating threads: 1
2015-02-10 21:28:18,176 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...icpipesplatform/ungrouped
2015-02-10 21:28:18,178 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 21:28:18,180 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 21:28:18,211 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 21:28:18,233 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 21:28:18,272 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1632714591_0005
2015-02-10 21:28:18,297 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity1632714591/.staging/job_local1632714591_0005/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 21:28:18,299 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity1632714591/.staging/job_local1632714591_0005/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 21:28:18,371 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_local1632714591_0005/job_local1632714591_0005.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 21:28:18,372 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_local1632714591_0005/job_local1632714591_0005.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 21:28:18,373 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 21:28:18,374 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local1632714591_0005
2015-02-10 21:28:18,374 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2015-02-10 21:28:18,374 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 21:28:18,375 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 21:28:18,379 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 21:28:18,380 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1632714591_0005_m_000000_0
2015-02-10 21:28:18,382 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 21:28:18,384 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/lower+upper.txt
2015-02-10 21:28:18,385 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@539ff66f
2015-02-10 21:28:18,386 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 0
2015-02-10 21:28:18,396 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 21:28:18,396 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 21:28:18,405 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/lower+upper.txt"]
2015-02-10 21:28:18,405 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/ungrouped"]
2015-02-10 21:28:18,409 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 21:28:18,410 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1632714591_0005_m_000000_0 is done. And is in the process of committing
2015-02-10 21:28:18,412 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 21:28:18,412 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1632714591_0005_m_000000_0 is allowed to commit now
2015-02-10 21:28:18,413 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1632714591_0005_m_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/ungrouped/_temporary/0/task_local1632714591_0005_m_000000
2015-02-10 21:28:18,415 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/lower+upper.txt:0+30
2015-02-10 21:28:18,415 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1632714591_0005_m_000000_0' done.
2015-02-10 21:28:18,415 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1632714591_0005_m_000000_0
2015-02-10 21:28:18,416 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 21:28:18,441 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/basicpipesplatform/ungrouped/_temporary
2015-02-10 21:28:18,481 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 21:28:18,484 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/basicpipesplatform/ungrouped
2015-02-10 21:28:18,518 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 21:28:18,530 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 21:28:18,547 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 21:28:18,551 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 21:28:18,552 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 21:28:18,562 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting
2015-02-10 21:28:18,562 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2015-02-10 21:28:18,563 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/basicpipesplatform/simplerelative"]
2015-02-10 21:28:18,563 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] parallel execution is enabled: false
2015-02-10 21:28:18,563 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting jobs: 1
2015-02-10 21:28:18,563 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] allocating threads: 1
2015-02-10 21:28:18,565 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...esplatform/simplerelative
2015-02-10 21:28:18,566 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 21:28:18,568 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 21:28:18,597 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 21:28:18,618 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 21:28:18,637 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1234409391_0006
2015-02-10 21:28:18,659 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity1234409391/.staging/job_local1234409391_0006/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 21:28:18,660 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity1234409391/.staging/job_local1234409391_0006/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 21:28:18,715 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_local1234409391_0006/job_local1234409391_0006.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 21:28:18,716 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_local1234409391_0006/job_local1234409391_0006.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 21:28:18,717 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 21:28:18,717 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local1234409391_0006
2015-02-10 21:28:18,717 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2015-02-10 21:28:18,717 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 21:28:18,718 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 21:28:18,721 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 21:28:18,721 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1234409391_0006_m_000000_0
2015-02-10 21:28:18,724 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 21:28:18,726 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/apache.10.txt
2015-02-10 21:28:18,726 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@311f56a3
2015-02-10 21:28:18,728 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-10 21:28:18,728 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-10 21:28:18,881 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-10 21:28:18,881 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-10 21:28:18,881 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-10 21:28:18,882 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-10 21:28:18,882 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-10 21:28:18,885 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 21:28:18,885 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 21:28:18,896 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2015-02-10 21:28:18,896 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:0]]
2015-02-10 21:28:18,901 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 21:28:18,901 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2015-02-10 21:28:18,901 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2015-02-10 21:28:18,901 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 210; bufvoid = 104857600
2015-02-10 21:28:18,901 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214360(104857440); length = 37/6553600
2015-02-10 21:28:18,906 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2015-02-10 21:28:18,908 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1234409391_0006_m_000000_0 is done. And is in the process of committing
2015-02-10 21:28:18,911 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt:0+1449
2015-02-10 21:28:18,912 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1234409391_0006_m_000000_0' done.
2015-02-10 21:28:18,912 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1234409391_0006_m_000000_0
2015-02-10 21:28:18,912 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 21:28:18,913 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2015-02-10 21:28:18,913 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1234409391_0006_r_000000_0
2015-02-10 21:28:18,915 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 21:28:18,916 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@6efde050
2015-02-10 21:28:18,916 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2015-02-10 21:28:18,917 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1234409391_0006_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2015-02-10 21:28:18,919 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#4 about to shuffle output of map attempt_local1234409391_0006_m_000000_0 decomp: 232 len: 236 to MEMORY
2015-02-10 21:28:18,920 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 232 bytes from map-output for attempt_local1234409391_0006_m_000000_0
2015-02-10 21:28:18,920 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 232, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->232
2015-02-10 21:28:18,921 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2015-02-10 21:28:18,923 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 21:28:18,923 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2015-02-10 21:28:18,927 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 21:28:18,928 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 211 bytes
2015-02-10 21:28:18,930 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 232 bytes to disk to satisfy reduce memory limit
2015-02-10 21:28:18,931 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 236 bytes from disk
2015-02-10 21:28:18,932 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2015-02-10 21:28:18,932 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 21:28:18,933 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 211 bytes
2015-02-10 21:28:18,934 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 21:28:18,935 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.6.3
2015-02-10 21:28:18,935 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2015-02-10 21:28:18,945 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:0]]
2015-02-10 21:28:18,945 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/basicpipesplatform/simplerelative"]
2015-02-10 21:28:18,959 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1234409391_0006_r_000000_0 is done. And is in the process of committing
2015-02-10 21:28:18,961 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 21:28:18,961 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1234409391_0006_r_000000_0 is allowed to commit now
2015-02-10 21:28:18,963 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1234409391_0006_r_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/simplerelative/_temporary/0/task_local1234409391_0006_r_000000
2015-02-10 21:28:18,965 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2015-02-10 21:28:18,965 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1234409391_0006_r_000000_0' done.
2015-02-10 21:28:18,966 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1234409391_0006_r_000000_0
2015-02-10 21:28:18,966 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2015-02-10 21:28:18,991 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/basicpipesplatform/simplerelative/_temporary
2015-02-10 21:28:19,025 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 21:28:19,028 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/basicpipesplatform/simplerelative
2015-02-10 21:28:19,192 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 21:28:19,193 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 21:28:19,210 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 21:28:19,214 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 21:28:19,215 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 21:28:19,236 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting
2015-02-10 21:28:19,237 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/lower.txt"]
2015-02-10 21:28:19,237 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] sink: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/simpleresult"]
2015-02-10 21:28:19,237 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] parallel execution is enabled: false
2015-02-10 21:28:19,237 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting jobs: 1
2015-02-10 21:28:19,238 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] allocating threads: 1
2015-02-10 21:28:19,239 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...ipesplatform/simpleresult
2015-02-10 21:28:19,240 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 21:28:19,242 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 21:28:19,273 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 21:28:19,294 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 21:28:19,312 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local2041404076_0007
2015-02-10 21:28:19,332 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity2041404076/.staging/job_local2041404076_0007/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 21:28:19,333 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity2041404076/.staging/job_local2041404076_0007/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 21:28:19,394 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_local2041404076_0007/job_local2041404076_0007.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 21:28:19,395 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_local2041404076_0007/job_local2041404076_0007.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 21:28:19,396 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 21:28:19,396 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local2041404076_0007
2015-02-10 21:28:19,396 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 21:28:19,397 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2015-02-10 21:28:19,397 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 21:28:19,401 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 21:28:19,401 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local2041404076_0007_m_000000_0
2015-02-10 21:28:19,404 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 21:28:19,406 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/lower.txt
2015-02-10 21:28:19,406 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@8746d23
2015-02-10 21:28:19,408 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-10 21:28:19,408 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-10 21:28:19,565 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-10 21:28:19,565 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-10 21:28:19,565 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-10 21:28:19,565 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-10 21:28:19,565 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-10 21:28:19,567 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 21:28:19,567 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 21:28:19,580 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/lower.txt"]
2015-02-10 21:28:19,580 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:0]]
2015-02-10 21:28:19,683 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 21:28:19,683 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2015-02-10 21:28:19,683 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2015-02-10 21:28:19,683 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 22; bufvoid = 104857600
2015-02-10 21:28:19,683 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214392(104857568); length = 5/6553600
2015-02-10 21:28:19,687 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2015-02-10 21:28:19,689 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local2041404076_0007_m_000000_0 is done. And is in the process of committing
2015-02-10 21:28:19,693 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/lower.txt:0+19
2015-02-10 21:28:19,693 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local2041404076_0007_m_000000_0' done.
2015-02-10 21:28:19,693 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local2041404076_0007_m_000000_0
2015-02-10 21:28:19,694 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 21:28:19,695 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2015-02-10 21:28:19,996 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local2041404076_0007_r_000000_0
2015-02-10 21:28:20,000 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 21:28:20,000 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@60f0761a
2015-02-10 21:28:20,002 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2015-02-10 21:28:20,004 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local2041404076_0007_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2015-02-10 21:28:20,005 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#5 about to shuffle output of map attempt_local2041404076_0007_m_000000_0 decomp: 28 len: 32 to MEMORY
2015-02-10 21:28:20,006 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 28 bytes from map-output for attempt_local2041404076_0007_m_000000_0
2015-02-10 21:28:20,006 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 28, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->28
2015-02-10 21:28:20,007 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2015-02-10 21:28:20,009 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 21:28:20,010 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2015-02-10 21:28:20,013 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 21:28:20,013 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 17 bytes
2015-02-10 21:28:20,015 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 28 bytes to disk to satisfy reduce memory limit
2015-02-10 21:28:20,015 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 32 bytes from disk
2015-02-10 21:28:20,015 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2015-02-10 21:28:20,015 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 21:28:20,016 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 17 bytes
2015-02-10 21:28:20,017 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 21:28:20,017 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.6.3
2015-02-10 21:28:20,017 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2015-02-10 21:28:20,028 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:0]]
2015-02-10 21:28:20,028 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/simpleresult"]
2015-02-10 21:28:20,040 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local2041404076_0007_r_000000_0 is done. And is in the process of committing
2015-02-10 21:28:20,041 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 21:28:20,042 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local2041404076_0007_r_000000_0 is allowed to commit now
2015-02-10 21:28:20,042 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local2041404076_0007_r_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/simpleresult/_temporary/0/task_local2041404076_0007_r_000000
2015-02-10 21:28:20,044 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2015-02-10 21:28:20,044 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local2041404076_0007_r_000000_0' done.
2015-02-10 21:28:20,045 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local2041404076_0007_r_000000_0
2015-02-10 21:28:20,045 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2015-02-10 21:28:20,066 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/basicpipesplatform/simpleresult/_temporary
2015-02-10 21:28:20,099 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 21:28:20,101 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/basicpipesplatform/simpleresult
2015-02-10 21:28:20,122 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 21:28:20,122 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 21:28:20,131 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 21:28:20,134 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 21:28:20,135 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 21:28:20,142 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting
2015-02-10 21:28:20,143 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2015-02-10 21:28:20,143 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/basicpipesplatform/filterall"]
2015-02-10 21:28:20,143 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] parallel execution is enabled: false
2015-02-10 21:28:20,144 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting jobs: 1
2015-02-10 21:28:20,144 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] allocating threads: 1
2015-02-10 21:28:20,146 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...icpipesplatform/filterall
2015-02-10 21:28:20,146 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 21:28:20,148 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 21:28:20,177 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 21:28:20,199 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 21:28:20,217 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local298306426_0008
2015-02-10 21:28:20,237 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity298306426/.staging/job_local298306426_0008/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 21:28:20,238 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity298306426/.staging/job_local298306426_0008/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 21:28:20,297 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_local298306426_0008/job_local298306426_0008.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 21:28:20,298 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_local298306426_0008/job_local298306426_0008.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 21:28:20,299 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 21:28:20,299 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local298306426_0008
2015-02-10 21:28:20,299 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2015-02-10 21:28:20,299 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 21:28:20,300 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 21:28:20,303 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 21:28:20,303 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local298306426_0008_m_000000_0
2015-02-10 21:28:20,305 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 21:28:20,307 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/apache.10.txt
2015-02-10 21:28:20,307 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@1a18c28a
2015-02-10 21:28:20,309 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 0
2015-02-10 21:28:20,318 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 21:28:20,318 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 21:28:20,325 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2015-02-10 21:28:20,326 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/filterall"]
2015-02-10 21:28:20,329 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 21:28:20,330 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local298306426_0008_m_000000_0 is done. And is in the process of committing
2015-02-10 21:28:20,331 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 21:28:20,331 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local298306426_0008_m_000000_0 is allowed to commit now
2015-02-10 21:28:20,332 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local298306426_0008_m_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/filterall/_temporary/0/task_local298306426_0008_m_000000
2015-02-10 21:28:20,335 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt:0+1449
2015-02-10 21:28:20,335 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local298306426_0008_m_000000_0' done.
2015-02-10 21:28:20,335 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local298306426_0008_m_000000_0
2015-02-10 21:28:20,335 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 21:28:20,355 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/basicpipesplatform/filterall/_temporary
2015-02-10 21:28:20,389 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 21:28:20,391 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/basicpipesplatform/filterall
2015-02-10 21:28:20,417 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 21:28:20,417 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 21:28:20,435 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 21:28:20,441 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 21:28:20,442 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 21:28:20,455 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [lower*upper] starting
2015-02-10 21:28:20,456 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [lower*upper] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/upper.txt"]
2015-02-10 21:28:20,456 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [lower*upper] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/lower.txt"]
2015-02-10 21:28:20,456 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [lower*upper] sink: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/complexcogroup"]
2015-02-10 21:28:20,456 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [lower*upper] parallel execution is enabled: false
2015-02-10 21:28:20,456 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [lower*upper] starting jobs: 1
2015-02-10 21:28:20,456 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [lower*upper] allocating threads: 1
2015-02-10 21:28:20,457 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [lower*upper] starting step: (1/1) ...esplatform/complexcogroup
2015-02-10 21:28:20,458 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 21:28:20,460 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 21:28:20,490 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 21:28:20,492 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 21:28:20,514 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:2
2015-02-10 21:28:20,534 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local723804792_0009
2015-02-10 21:28:20,553 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity723804792/.staging/job_local723804792_0009/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 21:28:20,554 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity723804792/.staging/job_local723804792_0009/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 21:28:20,608 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_local723804792_0009/job_local723804792_0009.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 21:28:20,609 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_local723804792_0009/job_local723804792_0009.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 21:28:20,610 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 21:28:20,610 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [lower*upper] submitted hadoop job: job_local723804792_0009
2015-02-10 21:28:20,610 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [lower*upper] tracking url: http://localhost:8080/
2015-02-10 21:28:20,611 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 21:28:20,611 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 21:28:20,615 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 21:28:20,615 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local723804792_0009_m_000000_0
2015-02-10 21:28:20,617 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 21:28:20,619 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/lower.txt
2015-02-10 21:28:20,619 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@3e58f124
2015-02-10 21:28:20,621 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-10 21:28:20,621 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-10 21:28:20,696 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-10 21:28:20,697 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-10 21:28:20,697 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-10 21:28:20,697 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-10 21:28:20,697 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-10 21:28:20,700 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 21:28:20,700 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 21:28:20,710 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/lower.txt"]
2015-02-10 21:28:20,711 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: CoGroup(lower*upper)[by: lower:[{1}:0] upper:[{1}:0]]
2015-02-10 21:28:20,714 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 21:28:20,714 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2015-02-10 21:28:20,714 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2015-02-10 21:28:20,714 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 85; bufvoid = 104857600
2015-02-10 21:28:20,714 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214380(104857520); length = 17/6553600
2015-02-10 21:28:20,718 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2015-02-10 21:28:20,721 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local723804792_0009_m_000000_0 is done. And is in the process of committing
2015-02-10 21:28:20,723 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/lower.txt:0+19
2015-02-10 21:28:20,723 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local723804792_0009_m_000000_0' done.
2015-02-10 21:28:20,724 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local723804792_0009_m_000000_0
2015-02-10 21:28:20,724 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local723804792_0009_m_000001_0
2015-02-10 21:28:20,726 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 21:28:20,727 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/upper.txt
2015-02-10 21:28:20,727 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@5faecf45
2015-02-10 21:28:20,729 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-10 21:28:20,729 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-10 21:28:20,892 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-10 21:28:20,892 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-10 21:28:20,892 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-10 21:28:20,892 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-10 21:28:20,892 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-10 21:28:20,894 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 21:28:20,894 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 21:28:20,903 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/upper.txt"]
2015-02-10 21:28:20,904 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: CoGroup(lower*upper)[by: lower:[{1}:0] upper:[{1}:0]]
2015-02-10 21:28:20,907 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 21:28:20,907 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2015-02-10 21:28:20,907 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2015-02-10 21:28:20,907 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 85; bufvoid = 104857600
2015-02-10 21:28:20,907 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214380(104857520); length = 17/6553600
2015-02-10 21:28:20,911 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2015-02-10 21:28:20,914 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local723804792_0009_m_000001_0 is done. And is in the process of committing
2015-02-10 21:28:20,916 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/upper.txt:0+19
2015-02-10 21:28:20,916 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local723804792_0009_m_000001_0' done.
2015-02-10 21:28:20,917 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local723804792_0009_m_000001_0
2015-02-10 21:28:20,917 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 21:28:20,917 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2015-02-10 21:28:20,918 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local723804792_0009_r_000000_0
2015-02-10 21:28:20,920 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 21:28:20,920 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@390ede48
2015-02-10 21:28:20,921 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2015-02-10 21:28:20,922 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local723804792_0009_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2015-02-10 21:28:20,924 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#6 about to shuffle output of map attempt_local723804792_0009_m_000001_0 decomp: 97 len: 101 to MEMORY
2015-02-10 21:28:20,925 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 97 bytes from map-output for attempt_local723804792_0009_m_000001_0
2015-02-10 21:28:20,925 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 97, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->97
2015-02-10 21:28:20,928 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#6 about to shuffle output of map attempt_local723804792_0009_m_000000_0 decomp: 97 len: 101 to MEMORY
2015-02-10 21:28:20,928 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 97 bytes from map-output for attempt_local723804792_0009_m_000000_0
2015-02-10 21:28:20,928 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 97, inMemoryMapOutputs.size() -> 2, commitMemory -> 97, usedMemory ->194
2015-02-10 21:28:20,929 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2015-02-10 21:28:20,930 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 2 / 2 copied.
2015-02-10 21:28:20,931 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 2 in-memory map-outputs and 0 on-disk map-outputs
2015-02-10 21:28:20,933 INFO mapred.Merger (Merger.java:merge(591)) - Merging 2 sorted segments
2015-02-10 21:28:20,934 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 2 segments left of total size: 174 bytes
2015-02-10 21:28:20,936 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 2 segments, 194 bytes to disk to satisfy reduce memory limit
2015-02-10 21:28:20,936 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 196 bytes from disk
2015-02-10 21:28:20,936 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2015-02-10 21:28:20,937 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 21:28:20,937 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 182 bytes
2015-02-10 21:28:20,938 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 2 / 2 copied.
2015-02-10 21:28:20,938 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.6.3
2015-02-10 21:28:20,939 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2015-02-10 21:28:20,946 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: CoGroup(lower*upper)[by: lower:[{1}:0] upper:[{1}:0]]
2015-02-10 21:28:20,946 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/complexcogroup"]
2015-02-10 21:28:20,966 INFO collect.SpillableTupleList (SpillableTupleList.java:getCodecClass(105)) - attempting to load codec: org.apache.hadoop.io.compress.GzipCodec
2015-02-10 21:28:20,966 INFO collect.SpillableTupleList (SpillableTupleList.java:getCodecClass(110)) - found codec: org.apache.hadoop.io.compress.GzipCodec
2015-02-10 21:28:20,974 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local723804792_0009_r_000000_0 is done. And is in the process of committing
2015-02-10 21:28:20,977 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 2 / 2 copied.
2015-02-10 21:28:20,977 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local723804792_0009_r_000000_0 is allowed to commit now
2015-02-10 21:28:20,978 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local723804792_0009_r_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/complexcogroup/_temporary/0/task_local723804792_0009_r_000000
2015-02-10 21:28:20,979 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2015-02-10 21:28:20,979 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local723804792_0009_r_000000_0' done.
2015-02-10 21:28:20,979 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local723804792_0009_r_000000_0
2015-02-10 21:28:20,980 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2015-02-10 21:28:21,008 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/basicpipesplatform/complexcogroup/_temporary
2015-02-10 21:28:21,041 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 21:28:21,077 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 21:28:21,079 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/basicpipesplatform/complexcogroup
2015-02-10 21:28:21,100 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 21:28:21,101 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 21:28:21,109 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 21:28:21,112 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 21:28:21,112 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 21:28:21,119 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting
2015-02-10 21:28:21,119 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2015-02-10 21:28:21,120 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/basicpipesplatform/replace"]
2015-02-10 21:28:21,120 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] parallel execution is enabled: false
2015-02-10 21:28:21,120 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting jobs: 1
2015-02-10 21:28:21,120 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] allocating threads: 1
2015-02-10 21:28:21,121 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...asicpipesplatform/replace
2015-02-10 21:28:21,121 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 21:28:21,122 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 21:28:21,150 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 21:28:21,171 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 21:28:21,188 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1853682667_0010
2015-02-10 21:28:21,207 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity1853682667/.staging/job_local1853682667_0010/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 21:28:21,208 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity1853682667/.staging/job_local1853682667_0010/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 21:28:21,260 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_local1853682667_0010/job_local1853682667_0010.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 21:28:21,261 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_local1853682667_0010/job_local1853682667_0010.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 21:28:21,262 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 21:28:21,262 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local1853682667_0010
2015-02-10 21:28:21,262 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 21:28:21,263 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 21:28:21,262 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2015-02-10 21:28:21,266 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 21:28:21,266 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1853682667_0010_m_000000_0
2015-02-10 21:28:21,268 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 21:28:21,273 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/apache.10.txt
2015-02-10 21:28:21,273 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@6665e41
2015-02-10 21:28:21,274 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 0
2015-02-10 21:28:21,283 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 21:28:21,284 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 21:28:21,290 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2015-02-10 21:28:21,291 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/replace"]
2015-02-10 21:28:21,295 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 21:28:21,295 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1853682667_0010_m_000000_0 is done. And is in the process of committing
2015-02-10 21:28:21,297 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 21:28:21,297 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1853682667_0010_m_000000_0 is allowed to commit now
2015-02-10 21:28:21,298 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1853682667_0010_m_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/replace/_temporary/0/task_local1853682667_0010_m_000000
2015-02-10 21:28:21,299 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt:0+1449
2015-02-10 21:28:21,300 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1853682667_0010_m_000000_0' done.
2015-02-10 21:28:21,300 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1853682667_0010_m_000000_0
2015-02-10 21:28:21,300 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 21:28:21,319 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/basicpipesplatform/replace/_temporary
2015-02-10 21:28:21,352 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 21:28:21,354 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/basicpipesplatform/replace
2015-02-10 21:28:21,376 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 21:28:21,377 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 21:28:21,387 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 21:28:21,390 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 21:28:21,391 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 21:28:21,397 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] starting
2015-02-10 21:28:21,398 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/ips.20.txt"]
2015-02-10 21:28:21,398 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] sink: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/count2"]
2015-02-10 21:28:21,399 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] parallel execution is enabled: false
2015-02-10 21:28:21,399 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] starting jobs: 1
2015-02-10 21:28:21,399 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] allocating threads: 1
2015-02-10 21:28:21,400 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] starting step: (1/1) ...basicpipesplatform/count2
2015-02-10 21:28:21,401 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 21:28:21,403 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 21:28:21,429 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 21:28:21,449 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 21:28:21,465 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local2071420330_0011
2015-02-10 21:28:21,484 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity2071420330/.staging/job_local2071420330_0011/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 21:28:21,486 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity2071420330/.staging/job_local2071420330_0011/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 21:28:21,538 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_local2071420330_0011/job_local2071420330_0011.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 21:28:21,539 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_local2071420330_0011/job_local2071420330_0011.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 21:28:21,540 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 21:28:21,540 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] submitted hadoop job: job_local2071420330_0011
2015-02-10 21:28:21,540 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 21:28:21,540 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] tracking url: http://localhost:8080/
2015-02-10 21:28:21,541 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 21:28:21,543 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 21:28:21,544 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local2071420330_0011_m_000000_0
2015-02-10 21:28:21,546 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 21:28:21,548 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/ips.20.txt
2015-02-10 21:28:21,548 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@c265121
2015-02-10 21:28:21,550 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-10 21:28:21,550 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-10 21:28:21,697 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-10 21:28:21,697 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-10 21:28:21,697 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-10 21:28:21,698 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-10 21:28:21,698 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-10 21:28:21,699 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 21:28:21,700 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 21:28:21,707 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/ips.20.txt"]
2015-02-10 21:28:21,707 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(count)[by:[{1}:1]]
2015-02-10 21:28:21,711 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 21:28:21,711 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2015-02-10 21:28:21,711 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2015-02-10 21:28:21,711 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 466; bufvoid = 104857600
2015-02-10 21:28:21,712 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214320(104857280); length = 77/6553600
2015-02-10 21:28:21,717 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2015-02-10 21:28:21,720 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local2071420330_0011_m_000000_0 is done. And is in the process of committing
2015-02-10 21:28:21,722 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/ips.20.txt:0+275
2015-02-10 21:28:21,722 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local2071420330_0011_m_000000_0' done.
2015-02-10 21:28:21,722 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local2071420330_0011_m_000000_0
2015-02-10 21:28:21,722 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 21:28:21,723 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2015-02-10 21:28:21,723 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local2071420330_0011_r_000000_0
2015-02-10 21:28:21,726 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 21:28:21,726 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@326cbb2d
2015-02-10 21:28:21,727 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2015-02-10 21:28:21,728 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local2071420330_0011_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2015-02-10 21:28:21,730 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#7 about to shuffle output of map attempt_local2071420330_0011_m_000000_0 decomp: 508 len: 512 to MEMORY
2015-02-10 21:28:21,731 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 508 bytes from map-output for attempt_local2071420330_0011_m_000000_0
2015-02-10 21:28:21,731 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 508, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->508
2015-02-10 21:28:21,732 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2015-02-10 21:28:21,733 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 21:28:21,733 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2015-02-10 21:28:21,736 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 21:28:21,736 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 487 bytes
2015-02-10 21:28:21,738 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 508 bytes to disk to satisfy reduce memory limit
2015-02-10 21:28:21,739 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 512 bytes from disk
2015-02-10 21:28:21,739 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2015-02-10 21:28:21,740 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 21:28:21,740 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 487 bytes
2015-02-10 21:28:21,741 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 21:28:21,742 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.6.3
2015-02-10 21:28:21,742 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2015-02-10 21:28:21,749 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(count)[by:[{1}:1]]
2015-02-10 21:28:21,750 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/count2"]
2015-02-10 21:28:21,764 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local2071420330_0011_r_000000_0 is done. And is in the process of committing
2015-02-10 21:28:21,767 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 21:28:21,767 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local2071420330_0011_r_000000_0 is allowed to commit now
2015-02-10 21:28:21,768 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local2071420330_0011_r_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/count2/_temporary/0/task_local2071420330_0011_r_000000
2015-02-10 21:28:21,770 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2015-02-10 21:28:21,770 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local2071420330_0011_r_000000_0' done.
2015-02-10 21:28:21,771 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local2071420330_0011_r_000000_0
2015-02-10 21:28:21,771 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2015-02-10 21:28:21,791 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/basicpipesplatform/count2/_temporary
2015-02-10 21:28:21,826 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 21:28:21,864 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 21:28:21,867 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/basicpipesplatform/count2
2015-02-10 21:28:21,895 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 21:28:21,896 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 21:28:21,908 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 21:28:21,911 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 21:28:21,912 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 21:28:21,918 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] starting
2015-02-10 21:28:21,919 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/ips.20.txt"]
2015-02-10 21:28:21,919 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] sink: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/count3"]
2015-02-10 21:28:21,919 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] parallel execution is enabled: false
2015-02-10 21:28:21,919 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] starting jobs: 1
2015-02-10 21:28:21,920 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] allocating threads: 1
2015-02-10 21:28:21,920 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] starting step: (1/1) ...basicpipesplatform/count3
2015-02-10 21:28:21,921 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 21:28:21,923 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 21:28:21,952 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 21:28:21,973 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 21:28:21,995 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1308862806_0012
2015-02-10 21:28:22,025 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity1308862806/.staging/job_local1308862806_0012/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 21:28:22,027 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity1308862806/.staging/job_local1308862806_0012/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 21:28:22,078 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_local1308862806_0012/job_local1308862806_0012.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 21:28:22,079 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_local1308862806_0012/job_local1308862806_0012.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 21:28:22,080 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 21:28:22,080 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 21:28:22,080 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 21:28:22,080 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] submitted hadoop job: job_local1308862806_0012
2015-02-10 21:28:22,081 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] tracking url: http://localhost:8080/
2015-02-10 21:28:22,083 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 21:28:22,084 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1308862806_0012_m_000000_0
2015-02-10 21:28:22,085 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 21:28:22,087 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/ips.20.txt
2015-02-10 21:28:22,087 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@3851ddd2
2015-02-10 21:28:22,089 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-10 21:28:22,089 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-10 21:28:22,115 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-10 21:28:22,115 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-10 21:28:22,115 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-10 21:28:22,116 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-10 21:28:22,116 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-10 21:28:22,117 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 21:28:22,117 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 21:28:22,125 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/ips.20.txt"]
2015-02-10 21:28:22,125 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(count)[by:[{1}:1]]
2015-02-10 21:28:22,129 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 21:28:22,129 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2015-02-10 21:28:22,130 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2015-02-10 21:28:22,130 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 466; bufvoid = 104857600
2015-02-10 21:28:22,130 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214320(104857280); length = 77/6553600
2015-02-10 21:28:22,136 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2015-02-10 21:28:22,138 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1308862806_0012_m_000000_0 is done. And is in the process of committing
2015-02-10 21:28:22,140 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/ips.20.txt:0+275
2015-02-10 21:28:22,140 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1308862806_0012_m_000000_0' done.
2015-02-10 21:28:22,141 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1308862806_0012_m_000000_0
2015-02-10 21:28:22,141 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 21:28:22,141 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2015-02-10 21:28:22,142 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1308862806_0012_r_000000_0
2015-02-10 21:28:22,144 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 21:28:22,144 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@7d76a8c8
2015-02-10 21:28:22,144 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2015-02-10 21:28:22,145 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1308862806_0012_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2015-02-10 21:28:22,147 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#8 about to shuffle output of map attempt_local1308862806_0012_m_000000_0 decomp: 508 len: 512 to MEMORY
2015-02-10 21:28:22,148 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 508 bytes from map-output for attempt_local1308862806_0012_m_000000_0
2015-02-10 21:28:22,148 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 508, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->508
2015-02-10 21:28:22,149 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2015-02-10 21:28:22,150 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 21:28:22,150 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2015-02-10 21:28:22,152 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 21:28:22,153 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 487 bytes
2015-02-10 21:28:22,155 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 508 bytes to disk to satisfy reduce memory limit
2015-02-10 21:28:22,155 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 512 bytes from disk
2015-02-10 21:28:22,155 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2015-02-10 21:28:22,155 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 21:28:22,156 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 487 bytes
2015-02-10 21:28:22,156 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 21:28:22,157 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.6.3
2015-02-10 21:28:22,157 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2015-02-10 21:28:22,164 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(count)[by:[{1}:1]]
2015-02-10 21:28:22,164 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/count3"]
2015-02-10 21:28:22,179 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1308862806_0012_r_000000_0 is done. And is in the process of committing
2015-02-10 21:28:22,181 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 21:28:22,181 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1308862806_0012_r_000000_0 is allowed to commit now
2015-02-10 21:28:22,182 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1308862806_0012_r_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/count3/_temporary/0/task_local1308862806_0012_r_000000
2015-02-10 21:28:22,184 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2015-02-10 21:28:22,184 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1308862806_0012_r_000000_0' done.
2015-02-10 21:28:22,184 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1308862806_0012_r_000000_0
2015-02-10 21:28:22,184 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2015-02-10 21:28:22,201 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/basicpipesplatform/count3/_temporary
2015-02-10 21:28:22,235 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 21:28:22,272 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 21:28:22,274 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/basicpipesplatform/count3
2015-02-10 21:28:22,299 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 21:28:22,300 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 21:28:22,311 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 21:28:22,314 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 21:28:22,315 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 21:28:22,321 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] starting
2015-02-10 21:28:22,321 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/ips.20.txt"]
2015-02-10 21:28:22,322 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] sink: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/count4"]
2015-02-10 21:28:22,322 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] parallel execution is enabled: false
2015-02-10 21:28:22,322 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] starting jobs: 1
2015-02-10 21:28:22,322 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [count] allocating threads: 1
2015-02-10 21:28:22,323 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] starting step: (1/1) ...basicpipesplatform/count4
2015-02-10 21:28:22,323 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 21:28:22,324 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 21:28:22,350 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 21:28:22,370 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 21:28:22,392 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1539451_0013
2015-02-10 21:28:22,414 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity1539451/.staging/job_local1539451_0013/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 21:28:22,415 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity1539451/.staging/job_local1539451_0013/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 21:28:22,479 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_local1539451_0013/job_local1539451_0013.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 21:28:22,481 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_local1539451_0013/job_local1539451_0013.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 21:28:22,482 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 21:28:22,482 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] submitted hadoop job: job_local1539451_0013
2015-02-10 21:28:22,482 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 21:28:22,482 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [count] tracking url: http://localhost:8080/
2015-02-10 21:28:22,483 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 21:28:22,486 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 21:28:22,486 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1539451_0013_m_000000_0
2015-02-10 21:28:22,488 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 21:28:22,490 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/ips.20.txt
2015-02-10 21:28:22,490 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@4d38b4ed
2015-02-10 21:28:22,492 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-10 21:28:22,492 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-10 21:28:22,639 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-10 21:28:22,639 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-10 21:28:22,639 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-10 21:28:22,640 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-10 21:28:22,640 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-10 21:28:22,641 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 21:28:22,641 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 21:28:22,649 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/ips.20.txt"]
2015-02-10 21:28:22,649 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(count)[by:[{1}:1]]
2015-02-10 21:28:22,653 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 21:28:22,653 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2015-02-10 21:28:22,654 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2015-02-10 21:28:22,654 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 466; bufvoid = 104857600
2015-02-10 21:28:22,654 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214320(104857280); length = 77/6553600
2015-02-10 21:28:22,660 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2015-02-10 21:28:22,662 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1539451_0013_m_000000_0 is done. And is in the process of committing
2015-02-10 21:28:22,664 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/ips.20.txt:0+275
2015-02-10 21:28:22,664 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1539451_0013_m_000000_0' done.
2015-02-10 21:28:22,665 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1539451_0013_m_000000_0
2015-02-10 21:28:22,665 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 21:28:22,665 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2015-02-10 21:28:22,666 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1539451_0013_r_000000_0
2015-02-10 21:28:22,668 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 21:28:22,669 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@3590efa8
2015-02-10 21:28:22,669 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2015-02-10 21:28:22,670 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1539451_0013_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2015-02-10 21:28:22,672 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#9 about to shuffle output of map attempt_local1539451_0013_m_000000_0 decomp: 508 len: 512 to MEMORY
2015-02-10 21:28:22,673 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 508 bytes from map-output for attempt_local1539451_0013_m_000000_0
2015-02-10 21:28:22,673 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 508, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->508
2015-02-10 21:28:22,674 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2015-02-10 21:28:22,675 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 21:28:22,675 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2015-02-10 21:28:22,679 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 21:28:22,679 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 487 bytes
2015-02-10 21:28:22,681 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 508 bytes to disk to satisfy reduce memory limit
2015-02-10 21:28:22,682 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 512 bytes from disk
2015-02-10 21:28:22,682 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2015-02-10 21:28:22,682 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 21:28:22,682 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 487 bytes
2015-02-10 21:28:22,683 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 21:28:22,683 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.6.3
2015-02-10 21:28:22,684 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2015-02-10 21:28:22,691 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(count)[by:[{1}:1]]
2015-02-10 21:28:22,691 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/count4"]
2015-02-10 21:28:22,713 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1539451_0013_r_000000_0 is done. And is in the process of committing
2015-02-10 21:28:22,716 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 21:28:22,716 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1539451_0013_r_000000_0 is allowed to commit now
2015-02-10 21:28:22,717 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1539451_0013_r_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/count4/_temporary/0/task_local1539451_0013_r_000000
2015-02-10 21:28:22,719 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2015-02-10 21:28:22,719 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1539451_0013_r_000000_0' done.
2015-02-10 21:28:22,719 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1539451_0013_r_000000_0
2015-02-10 21:28:22,720 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2015-02-10 21:28:22,743 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/basicpipesplatform/count4/_temporary
2015-02-10 21:28:22,775 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 21:28:22,807 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 21:28:22,809 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/basicpipesplatform/count4
2015-02-10 21:28:22,828 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 21:28:22,829 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 21:28:22,835 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 21:28:22,837 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 21:28:22,838 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 21:28:22,843 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting
2015-02-10 21:28:22,846 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2015-02-10 21:28:22,847 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/basicpipesplatform/filter"]
2015-02-10 21:28:22,847 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] parallel execution is enabled: false
2015-02-10 21:28:22,848 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting jobs: 1
2015-02-10 21:28:22,848 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] allocating threads: 1
2015-02-10 21:28:22,849 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...basicpipesplatform/filter
2015-02-10 21:28:22,849 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 21:28:22,851 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 21:28:22,875 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 21:28:22,894 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 21:28:22,909 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1104019743_0014
2015-02-10 21:28:22,927 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity1104019743/.staging/job_local1104019743_0014/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 21:28:22,928 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity1104019743/.staging/job_local1104019743_0014/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 21:28:22,976 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_local1104019743_0014/job_local1104019743_0014.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 21:28:22,978 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_local1104019743_0014/job_local1104019743_0014.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 21:28:22,979 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 21:28:22,979 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 21:28:22,980 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local1104019743_0014
2015-02-10 21:28:22,980 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2015-02-10 21:28:22,980 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 21:28:22,983 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 21:28:22,984 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1104019743_0014_m_000000_0
2015-02-10 21:28:22,986 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 21:28:22,987 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/apache.10.txt
2015-02-10 21:28:22,988 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@5f3d285f
2015-02-10 21:28:22,990 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 0
2015-02-10 21:28:22,997 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 21:28:22,998 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 21:28:23,004 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2015-02-10 21:28:23,005 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/filter"]
2015-02-10 21:28:23,008 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 21:28:23,008 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1104019743_0014_m_000000_0 is done. And is in the process of committing
2015-02-10 21:28:23,010 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 21:28:23,010 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1104019743_0014_m_000000_0 is allowed to commit now
2015-02-10 21:28:23,011 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1104019743_0014_m_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/filter/_temporary/0/task_local1104019743_0014_m_000000
2015-02-10 21:28:23,012 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt:0+1449
2015-02-10 21:28:23,012 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1104019743_0014_m_000000_0' done.
2015-02-10 21:28:23,012 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1104019743_0014_m_000000_0
2015-02-10 21:28:23,012 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 21:28:23,025 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/basicpipesplatform/filter/_temporary
2015-02-10 21:28:23,056 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 21:28:23,058 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/basicpipesplatform/filter
2015-02-10 21:28:23,082 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 21:28:23,082 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 21:28:23,092 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 21:28:23,095 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 21:28:23,095 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 21:28:23,102 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting
2015-02-10 21:28:23,102 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] source: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2015-02-10 21:28:23,103 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] sink: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/simple"]
2015-02-10 21:28:23,103 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] parallel execution is enabled: false
2015-02-10 21:28:23,104 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting jobs: 1
2015-02-10 21:28:23,104 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] allocating threads: 1
2015-02-10 21:28:23,105 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...basicpipesplatform/simple
2015-02-10 21:28:23,106 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 21:28:23,107 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 21:28:23,131 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 21:28:23,150 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 21:28:23,166 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local213870379_0015
2015-02-10 21:28:23,183 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity213870379/.staging/job_local213870379_0015/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 21:28:23,185 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity213870379/.staging/job_local213870379_0015/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 21:28:23,232 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_local213870379_0015/job_local213870379_0015.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 21:28:23,233 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_local213870379_0015/job_local213870379_0015.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 21:28:23,233 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 21:28:23,234 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local213870379_0015
2015-02-10 21:28:23,234 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 21:28:23,234 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2015-02-10 21:28:23,234 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 21:28:23,238 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 21:28:23,238 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local213870379_0015_m_000000_0
2015-02-10 21:28:23,240 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 21:28:23,242 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/apache.10.txt
2015-02-10 21:28:23,242 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@f18da51
2015-02-10 21:28:23,243 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-10 21:28:23,243 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-10 21:28:23,267 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-10 21:28:23,267 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-10 21:28:23,268 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-10 21:28:23,268 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-10 21:28:23,268 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-10 21:28:23,269 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 21:28:23,270 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 21:28:23,278 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[[0:1]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2015-02-10 21:28:23,278 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:0]]
2015-02-10 21:28:23,282 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 21:28:23,282 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2015-02-10 21:28:23,283 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2015-02-10 21:28:23,283 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 210; bufvoid = 104857600
2015-02-10 21:28:23,283 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214360(104857440); length = 37/6553600
2015-02-10 21:28:23,286 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2015-02-10 21:28:23,288 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local213870379_0015_m_000000_0 is done. And is in the process of committing
2015-02-10 21:28:23,290 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt:0+1449
2015-02-10 21:28:23,290 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local213870379_0015_m_000000_0' done.
2015-02-10 21:28:23,290 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local213870379_0015_m_000000_0
2015-02-10 21:28:23,290 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 21:28:23,291 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2015-02-10 21:28:23,291 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local213870379_0015_r_000000_0
2015-02-10 21:28:23,293 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 21:28:23,293 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@6600a08
2015-02-10 21:28:23,294 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=497975296, maxSingleShuffleLimit=124493824, mergeThreshold=328663712, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2015-02-10 21:28:23,295 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local213870379_0015_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2015-02-10 21:28:23,296 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#10 about to shuffle output of map attempt_local213870379_0015_m_000000_0 decomp: 232 len: 236 to MEMORY
2015-02-10 21:28:23,297 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 232 bytes from map-output for attempt_local213870379_0015_m_000000_0
2015-02-10 21:28:23,297 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 232, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->232
2015-02-10 21:28:23,298 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2015-02-10 21:28:23,299 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 21:28:23,299 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2015-02-10 21:28:23,304 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 21:28:23,304 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 211 bytes
2015-02-10 21:28:23,306 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 232 bytes to disk to satisfy reduce memory limit
2015-02-10 21:28:23,306 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 236 bytes from disk
2015-02-10 21:28:23,306 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2015-02-10 21:28:23,307 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 21:28:23,307 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 211 bytes
2015-02-10 21:28:23,308 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 21:28:23,308 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.6.3
2015-02-10 21:28:23,309 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2015-02-10 21:28:23,317 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:0]]
2015-02-10 21:28:23,317 INFO hadoop.FlowReducer (FlowReducer.java:configure(100)) - sinking to: Hfs["TextLine[[0]->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/simple"]
2015-02-10 21:28:23,328 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local213870379_0015_r_000000_0 is done. And is in the process of committing
2015-02-10 21:28:23,331 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 21:28:23,331 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local213870379_0015_r_000000_0 is allowed to commit now
2015-02-10 21:28:23,332 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local213870379_0015_r_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/output/hadoop2-mr1/basicpipesplatform/simple/_temporary/0/task_local213870379_0015_r_000000
2015-02-10 21:28:23,333 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2015-02-10 21:28:23,334 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local213870379_0015_r_000000_0' done.
2015-02-10 21:28:23,334 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local213870379_0015_r_000000_0
2015-02-10 21:28:23,334 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2015-02-10 21:28:23,359 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/basicpipesplatform/simple/_temporary
2015-02-10 21:28:23,390 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 21:28:23,392 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/basicpipesplatform/simple