2015-02-10 22:33:09,628 INFO platform.PlatformRunner (PlatformRunner.java:getPlatformClassesFromClasspath(187)) - found 1 test platforms from classpath
2015-02-10 22:33:09,692 INFO platform.PlatformRunner (PlatformRunner.java:addPlatform(237)) - installing platform: hadoop2-mr1
2015-02-10 22:33:09,692 INFO platform.PlatformRunner (PlatformRunner.java:addPlatform(238)) - running test: cascading.operation.assertion.AppliedAssertionsPlatformTest
2015-02-10 22:33:09,735 INFO hadoop2.Hadoop2MR1Platform (Hadoop2MR1Platform.java:setUp(105)) - not using cluster
2015-02-10 22:33:10,377 WARN util.NativeCodeLoader (NativeCodeLoader.java:<clinit>(62)) - Unable to load native-hadoop library for your platform... using builtin-java classes where applicable
2015-02-10 22:33:10,684 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 22:33:10,686 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.6.3/9ae016e2b8d246b9c1de9168e715d9f1b971aa4a/cascading-hadoop2-mr1-2.6.3.jar
2015-02-10 22:33:10,698 INFO property.AppProps (AppProps.java:getAppID(169)) - using app.id: 276758CDF9814417BEC3FCB862AD3E12
2015-02-10 22:33:10,785 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 22:33:10,827 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 22:33:10,830 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 22:33:10,964 INFO util.Version (Version.java:printBanner(82)) - Concurrent, Inc - Cascading 2.6.3
2015-02-10 22:33:10,967 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting
2015-02-10 22:33:10,967 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2015-02-10 22:33:10,968 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/appliedassertionsplatform/value/NONE/STRICT"]
2015-02-10 22:33:10,968 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] parallel execution is enabled: false
2015-02-10 22:33:10,970 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting jobs: 1
2015-02-10 22:33:10,970 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] allocating threads: 1
2015-02-10 22:33:10,972 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...latform/value/NONE/STRICT
2015-02-10 22:33:10,999 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - session.id is deprecated. Instead, use dfs.metrics.session-id
2015-02-10 22:33:11,001 INFO jvm.JvmMetrics (JvmMetrics.java:init(76)) - Initializing JVM Metrics with processName=JobTracker, sessionId=
2015-02-10 22:33:11,027 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 22:33:11,421 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 22:33:11,463 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 22:33:11,690 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1875866484_0001
2015-02-10 22:33:11,734 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity1875866484/.staging/job_local1875866484_0001/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 22:33:11,742 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity1875866484/.staging/job_local1875866484_0001/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 22:33:11,915 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_local1875866484_0001/job_local1875866484_0001.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 22:33:11,919 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_local1875866484_0001/job_local1875866484_0001.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 22:33:11,925 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 22:33:11,926 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 22:33:11,929 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local1875866484_0001
2015-02-10 22:33:11,929 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2015-02-10 22:33:11,930 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 22:33:11,991 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 22:33:11,994 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1875866484_0001_m_000000_0
2015-02-10 22:33:12,037 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 22:33:12,047 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 22:33:12,047 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@11b9d4d8
2015-02-10 22:33:12,056 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-10 22:33:12,063 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-10 22:33:12,214 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-10 22:33:12,215 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-10 22:33:12,215 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-10 22:33:12,215 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-10 22:33:12,215 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-10 22:33:12,240 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 22:33:12,240 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 22:33:12,295 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.task.partition is deprecated. Instead, use mapreduce.task.partition
2015-02-10 22:33:12,314 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2015-02-10 22:33:12,314 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:'method']]
2015-02-10 22:33:12,332 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 22:33:12,333 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2015-02-10 22:33:12,333 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2015-02-10 22:33:12,333 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 693; bufvoid = 104857600
2015-02-10 22:33:12,333 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214372(104857488); length = 25/6553600
2015-02-10 22:33:12,346 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2015-02-10 22:33:12,350 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1875866484_0001_m_000000_0 is done. And is in the process of committing
2015-02-10 22:33:12,361 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 22:33:12,361 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1875866484_0001_m_000000_0' done.
2015-02-10 22:33:12,362 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1875866484_0001_m_000000_0
2015-02-10 22:33:12,362 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 22:33:12,372 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2015-02-10 22:33:12,372 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1875866484_0001_r_000000_0
2015-02-10 22:33:12,381 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 22:33:12,384 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@78871e65
2015-02-10 22:33:12,399 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2015-02-10 22:33:12,402 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1875866484_0001_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2015-02-10 22:33:12,435 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#1 about to shuffle output of map attempt_local1875866484_0001_m_000000_0 decomp: 709 len: 713 to MEMORY
2015-02-10 22:33:12,440 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 709 bytes from map-output for attempt_local1875866484_0001_m_000000_0
2015-02-10 22:33:12,481 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 709, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->709
2015-02-10 22:33:12,482 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2015-02-10 22:33:12,484 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 22:33:12,484 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2015-02-10 22:33:12,493 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 22:33:12,494 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 697 bytes
2015-02-10 22:33:12,497 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 709 bytes to disk to satisfy reduce memory limit
2015-02-10 22:33:12,498 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 713 bytes from disk
2015-02-10 22:33:12,499 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2015-02-10 22:33:12,499 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 22:33:12,500 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 697 bytes
2015-02-10 22:33:12,502 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 22:33:12,503 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.6.3
2015-02-10 22:33:12,504 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2015-02-10 22:33:12,524 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:'method']]
2015-02-10 22:33:12,524 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/appliedassertionsplatform/value/NONE/STRICT"]
2015-02-10 22:33:12,550 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1875866484_0001_r_000000_0 is done. And is in the process of committing
2015-02-10 22:33:12,553 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 22:33:12,554 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1875866484_0001_r_000000_0 is allowed to commit now
2015-02-10 22:33:12,556 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1875866484_0001_r_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/output/hadoop2-mr1/appliedassertionsplatform/value/NONE/STRICT/_temporary/0/task_local1875866484_0001_r_000000
2015-02-10 22:33:12,557 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2015-02-10 22:33:12,558 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1875866484_0001_r_000000_0' done.
2015-02-10 22:33:12,559 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1875866484_0001_r_000000_0
2015-02-10 22:33:12,559 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2015-02-10 22:33:12,610 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/appliedassertionsplatform/value/NONE/STRICT/_temporary
2015-02-10 22:33:12,653 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 22:33:12,689 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 22:33:12,690 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.6.3/9ae016e2b8d246b9c1de9168e715d9f1b971aa4a/cascading-hadoop2-mr1-2.6.3.jar
2015-02-10 22:33:12,714 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 22:33:12,720 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 22:33:12,721 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 22:33:12,735 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting
2015-02-10 22:33:12,736 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2015-02-10 22:33:12,736 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/appliedassertionsplatform/value/VALID/STRICT"]
2015-02-10 22:33:12,736 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] parallel execution is enabled: false
2015-02-10 22:33:12,737 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting jobs: 1
2015-02-10 22:33:12,737 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] allocating threads: 1
2015-02-10 22:33:12,737 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...atform/value/VALID/STRICT
2015-02-10 22:33:12,738 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 22:33:12,740 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 22:33:12,775 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 22:33:12,800 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 22:33:12,850 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1130913163_0002
2015-02-10 22:33:12,875 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity1130913163/.staging/job_local1130913163_0002/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 22:33:12,879 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity1130913163/.staging/job_local1130913163_0002/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 22:33:12,955 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_local1130913163_0002/job_local1130913163_0002.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 22:33:12,958 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_local1130913163_0002/job_local1130913163_0002.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 22:33:12,959 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 22:33:12,959 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local1130913163_0002
2015-02-10 22:33:12,959 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2015-02-10 22:33:12,960 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 22:33:12,960 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 22:33:12,965 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 22:33:12,965 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1130913163_0002_m_000000_0
2015-02-10 22:33:12,968 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 22:33:12,970 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 22:33:12,971 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@2398dc19
2015-02-10 22:33:12,972 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-10 22:33:12,973 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-10 22:33:13,140 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-10 22:33:13,141 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-10 22:33:13,141 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-10 22:33:13,141 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-10 22:33:13,141 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-10 22:33:13,143 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 22:33:13,143 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 22:33:13,159 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2015-02-10 22:33:13,159 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:'method']]
2015-02-10 22:33:13,166 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 22:33:13,166 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2015-02-10 22:33:13,166 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2015-02-10 22:33:13,167 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 693; bufvoid = 104857600
2015-02-10 22:33:13,167 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214372(104857488); length = 25/6553600
2015-02-10 22:33:13,172 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2015-02-10 22:33:13,175 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1130913163_0002_m_000000_0 is done. And is in the process of committing
2015-02-10 22:33:13,178 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 22:33:13,179 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1130913163_0002_m_000000_0' done.
2015-02-10 22:33:13,179 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1130913163_0002_m_000000_0
2015-02-10 22:33:13,179 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 22:33:13,180 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2015-02-10 22:33:13,180 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1130913163_0002_r_000000_0
2015-02-10 22:33:13,183 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 22:33:13,183 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@757753a8
2015-02-10 22:33:13,184 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2015-02-10 22:33:13,185 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1130913163_0002_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2015-02-10 22:33:13,188 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#2 about to shuffle output of map attempt_local1130913163_0002_m_000000_0 decomp: 709 len: 713 to MEMORY
2015-02-10 22:33:13,188 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 709 bytes from map-output for attempt_local1130913163_0002_m_000000_0
2015-02-10 22:33:13,189 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 709, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->709
2015-02-10 22:33:13,189 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2015-02-10 22:33:13,191 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 22:33:13,191 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2015-02-10 22:33:13,194 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 22:33:13,195 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 697 bytes
2015-02-10 22:33:13,197 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 709 bytes to disk to satisfy reduce memory limit
2015-02-10 22:33:13,198 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 713 bytes from disk
2015-02-10 22:33:13,198 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2015-02-10 22:33:13,198 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 22:33:13,199 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 697 bytes
2015-02-10 22:33:13,200 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 22:33:13,200 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.6.3
2015-02-10 22:33:13,200 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2015-02-10 22:33:13,214 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:'method']]
2015-02-10 22:33:13,214 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/appliedassertionsplatform/value/VALID/STRICT"]
2015-02-10 22:33:13,230 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1130913163_0002_r_000000_0 is done. And is in the process of committing
2015-02-10 22:33:13,232 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 22:33:13,232 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1130913163_0002_r_000000_0 is allowed to commit now
2015-02-10 22:33:13,233 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1130913163_0002_r_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/output/hadoop2-mr1/appliedassertionsplatform/value/VALID/STRICT/_temporary/0/task_local1130913163_0002_r_000000
2015-02-10 22:33:13,235 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2015-02-10 22:33:13,235 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1130913163_0002_r_000000_0' done.
2015-02-10 22:33:13,235 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1130913163_0002_r_000000_0
2015-02-10 22:33:13,235 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2015-02-10 22:33:13,265 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/appliedassertionsplatform/value/VALID/STRICT/_temporary
2015-02-10 22:33:13,311 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 22:33:13,357 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 22:33:13,358 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.6.3/9ae016e2b8d246b9c1de9168e715d9f1b971aa4a/cascading-hadoop2-mr1-2.6.3.jar
2015-02-10 22:33:13,377 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 22:33:13,383 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 22:33:13,384 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 22:33:13,401 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting
2015-02-10 22:33:13,402 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2015-02-10 22:33:13,402 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/appliedassertionsplatform/value/STRICT/STRICT"]
2015-02-10 22:33:13,402 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] parallel execution is enabled: false
2015-02-10 22:33:13,402 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting jobs: 1
2015-02-10 22:33:13,403 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] allocating threads: 1
2015-02-10 22:33:13,404 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...tform/value/STRICT/STRICT
2015-02-10 22:33:13,405 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 22:33:13,407 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 22:33:13,441 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 22:33:13,466 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 22:33:13,512 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1421271929_0003
2015-02-10 22:33:13,536 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity1421271929/.staging/job_local1421271929_0003/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 22:33:13,539 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity1421271929/.staging/job_local1421271929_0003/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 22:33:13,632 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1421271929_0003/job_local1421271929_0003.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 22:33:13,635 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/tmp/mapred/local/localRunner/teamcity/job_local1421271929_0003/job_local1421271929_0003.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 22:33:13,636 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 22:33:13,637 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local1421271929_0003
2015-02-10 22:33:13,637 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2015-02-10 22:33:13,637 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 22:33:13,638 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 22:33:13,642 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 22:33:13,642 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1421271929_0003_m_000000_0
2015-02-10 22:33:13,645 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 22:33:13,647 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 22:33:13,648 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@76d3046
2015-02-10 22:33:13,652 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-10 22:33:13,652 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-10 22:33:13,797 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-10 22:33:13,797 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-10 22:33:13,797 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-10 22:33:13,797 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-10 22:33:13,798 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-10 22:33:13,800 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 22:33:13,800 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 22:33:13,816 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2015-02-10 22:33:13,816 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:'method']]
2015-02-10 22:33:13,823 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 22:33:13,823 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2015-02-10 22:33:13,823 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2015-02-10 22:33:13,823 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 693; bufvoid = 104857600
2015-02-10 22:33:13,823 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214372(104857488); length = 25/6553600
2015-02-10 22:33:13,827 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2015-02-10 22:33:13,830 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1421271929_0003_m_000000_0 is done. And is in the process of committing
2015-02-10 22:33:13,833 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 22:33:13,833 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1421271929_0003_m_000000_0' done.
2015-02-10 22:33:13,833 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1421271929_0003_m_000000_0
2015-02-10 22:33:13,833 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 22:33:13,835 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2015-02-10 22:33:13,835 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1421271929_0003_r_000000_0
2015-02-10 22:33:13,838 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 22:33:13,838 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@5e53bbfa
2015-02-10 22:33:13,839 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2015-02-10 22:33:13,840 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1421271929_0003_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2015-02-10 22:33:13,844 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#3 about to shuffle output of map attempt_local1421271929_0003_m_000000_0 decomp: 709 len: 713 to MEMORY
2015-02-10 22:33:13,844 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 709 bytes from map-output for attempt_local1421271929_0003_m_000000_0
2015-02-10 22:33:13,844 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 709, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->709
2015-02-10 22:33:13,845 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2015-02-10 22:33:13,847 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 22:33:13,847 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2015-02-10 22:33:13,850 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 22:33:13,850 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 697 bytes
2015-02-10 22:33:13,853 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 709 bytes to disk to satisfy reduce memory limit
2015-02-10 22:33:13,854 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 713 bytes from disk
2015-02-10 22:33:13,854 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2015-02-10 22:33:13,854 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 22:33:13,855 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 697 bytes
2015-02-10 22:33:13,856 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 22:33:13,856 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.6.3
2015-02-10 22:33:13,856 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2015-02-10 22:33:13,869 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:'method']]
2015-02-10 22:33:13,870 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/appliedassertionsplatform/value/STRICT/STRICT"]
2015-02-10 22:33:13,884 ERROR stream.TrapHandler (TrapHandler.java:handleReThrowableException(103)) - caught Throwable, no trap available, rethrowing
cascading.operation.AssertionException: [cascading.operation.assertion.AppliedAssertionsPlatformTest.runValueAssertions(AppliedAssertionsPlatformTest.java:158)] argument tuple: ['7'] was not equal to values: ['0']
at cascading.operation.assertion.BaseAssertion.throwFail(BaseAssertion.java:107)
at cascading.operation.assertion.BaseAssertion.fail(BaseAssertion.java:86)
at cascading.operation.assertion.AssertEquals.doAssert(AssertEquals.java:77)
at cascading.flow.stream.ValueAssertionEachStage.receive(ValueAssertionEachStage.java:70)
at cascading.flow.stream.ValueAssertionEachStage.receive(ValueAssertionEachStage.java:34)
at cascading.flow.stream.CloseReducingDuct.completeGroup(CloseReducingDuct.java:47)
at cascading.flow.stream.AggregatorEveryStage$1.collect(AggregatorEveryStage.java:67)
at cascading.tuple.TupleEntryCollector.safeCollect(TupleEntryCollector.java:145)
at cascading.tuple.TupleEntryCollector.add(TupleEntryCollector.java:133)
at cascading.operation.aggregator.Count.complete(Count.java:82)
at cascading.flow.stream.AggregatorEveryStage.completeGroup(AggregatorEveryStage.java:151)
at cascading.flow.stream.AggregatorEveryStage.completeGroup(AggregatorEveryStage.java:39)
at cascading.flow.stream.OpenReducingDuct.receive(OpenReducingDuct.java:51)
at cascading.flow.stream.OpenReducingDuct.receive(OpenReducingDuct.java:28)
at cascading.flow.hadoop.stream.HadoopGroupGate.run(HadoopGroupGate.java:93)
at cascading.flow.hadoop.FlowReducer.reduce(FlowReducer.java:136)
at org.apache.hadoop.mapred.ReduceTask.runOldReducer(ReduceTask.java:444)
at org.apache.hadoop.mapred.ReduceTask.run(ReduceTask.java:392)
at org.apache.hadoop.mapred.LocalJobRunner$Job$ReduceTaskRunnable.run(LocalJobRunner.java:319)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:439)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
at java.lang.Thread.run(Thread.java:662)
2015-02-10 22:33:13,887 ERROR stream.TrapHandler (TrapHandler.java:handleReThrowableException(103)) - caught Throwable, no trap available, rethrowing
cascading.operation.AssertionException: [cascading.operation.assertion.AppliedAssertionsPlatformTest.runValueAssertions(AppliedAssertionsPlatformTest.java:158)] argument tuple: ['7'] was not equal to values: ['0']
at cascading.operation.assertion.BaseAssertion.throwFail(BaseAssertion.java:107)
at cascading.operation.assertion.BaseAssertion.fail(BaseAssertion.java:86)
at cascading.operation.assertion.AssertEquals.doAssert(AssertEquals.java:77)
at cascading.flow.stream.ValueAssertionEachStage.receive(ValueAssertionEachStage.java:70)
at cascading.flow.stream.ValueAssertionEachStage.receive(ValueAssertionEachStage.java:34)
at cascading.flow.stream.CloseReducingDuct.completeGroup(CloseReducingDuct.java:47)
at cascading.flow.stream.AggregatorEveryStage$1.collect(AggregatorEveryStage.java:67)
at cascading.tuple.TupleEntryCollector.safeCollect(TupleEntryCollector.java:145)
at cascading.tuple.TupleEntryCollector.add(TupleEntryCollector.java:133)
at cascading.operation.aggregator.Count.complete(Count.java:82)
at cascading.flow.stream.AggregatorEveryStage.completeGroup(AggregatorEveryStage.java:151)
at cascading.flow.stream.AggregatorEveryStage.completeGroup(AggregatorEveryStage.java:39)
at cascading.flow.stream.OpenReducingDuct.receive(OpenReducingDuct.java:51)
at cascading.flow.stream.OpenReducingDuct.receive(OpenReducingDuct.java:28)
at cascading.flow.hadoop.stream.HadoopGroupGate.run(HadoopGroupGate.java:93)
at cascading.flow.hadoop.FlowReducer.reduce(FlowReducer.java:136)
at org.apache.hadoop.mapred.ReduceTask.runOldReducer(ReduceTask.java:444)
at org.apache.hadoop.mapred.ReduceTask.run(ReduceTask.java:392)
at org.apache.hadoop.mapred.LocalJobRunner$Job$ReduceTaskRunnable.run(LocalJobRunner.java:319)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:439)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
at java.lang.Thread.run(Thread.java:662)
2015-02-10 22:33:13,889 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2015-02-10 22:33:13,892 WARN mapred.LocalJobRunner (LocalJobRunner.java:run(560)) - job_local1421271929_0003
java.lang.Exception: cascading.operation.AssertionException: [cascading.operation.assertion.AppliedAssertionsPlatformTest.runValueAssertions(AppliedAssertionsPlatformTest.java:158)] argument tuple: ['7'] was not equal to values: ['0']
at org.apache.hadoop.mapred.LocalJobRunner$Job.runTasks(LocalJobRunner.java:462)
at org.apache.hadoop.mapred.LocalJobRunner$Job.run(LocalJobRunner.java:529)
Caused by: cascading.operation.AssertionException: [cascading.operation.assertion.AppliedAssertionsPlatformTest.runValueAssertions(AppliedAssertionsPlatformTest.java:158)] argument tuple: ['7'] was not equal to values: ['0']
at cascading.operation.assertion.BaseAssertion.throwFail(BaseAssertion.java:107)
at cascading.operation.assertion.BaseAssertion.fail(BaseAssertion.java:86)
at cascading.operation.assertion.AssertEquals.doAssert(AssertEquals.java:77)
at cascading.flow.stream.ValueAssertionEachStage.receive(ValueAssertionEachStage.java:70)
at cascading.flow.stream.ValueAssertionEachStage.receive(ValueAssertionEachStage.java:34)
at cascading.flow.stream.CloseReducingDuct.completeGroup(CloseReducingDuct.java:47)
at cascading.flow.stream.AggregatorEveryStage$1.collect(AggregatorEveryStage.java:67)
at cascading.tuple.TupleEntryCollector.safeCollect(TupleEntryCollector.java:145)
at cascading.tuple.TupleEntryCollector.add(TupleEntryCollector.java:133)
at cascading.operation.aggregator.Count.complete(Count.java:82)
at cascading.flow.stream.AggregatorEveryStage.completeGroup(AggregatorEveryStage.java:151)
at cascading.flow.stream.AggregatorEveryStage.completeGroup(AggregatorEveryStage.java:39)
at cascading.flow.stream.OpenReducingDuct.receive(OpenReducingDuct.java:51)
at cascading.flow.stream.OpenReducingDuct.receive(OpenReducingDuct.java:28)
at cascading.flow.hadoop.stream.HadoopGroupGate.run(HadoopGroupGate.java:93)
at cascading.flow.hadoop.FlowReducer.reduce(FlowReducer.java:136)
at org.apache.hadoop.mapred.ReduceTask.runOldReducer(ReduceTask.java:444)
at org.apache.hadoop.mapred.ReduceTask.run(ReduceTask.java:392)
at org.apache.hadoop.mapred.LocalJobRunner$Job$ReduceTaskRunnable.run(LocalJobRunner.java:319)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:439)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
at java.lang.Thread.run(Thread.java:662)
2015-02-10 22:33:13,893 WARN flow.FlowStep (BaseFlowStep.java:logWarn(839)) - [test] hadoop job job_local1421271929_0003 state at FAILED
2015-02-10 22:33:13,893 WARN flow.FlowStep (BaseFlowStep.java:logWarn(839)) - [test] failure info: NA
2015-02-10 22:33:13,894 WARN flow.FlowStep (BaseFlowStep.java:logWarn(839)) - [test] task completion events identify failed tasks
2015-02-10 22:33:13,894 WARN flow.FlowStep (BaseFlowStep.java:logWarn(839)) - [test] task completion events count: 0
2015-02-10 22:33:13,906 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] stopping all jobs
2015-02-10 22:33:13,907 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] stopping: (1/1) ...tform/value/STRICT/STRICT
2015-02-10 22:33:13,908 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] stopped all jobs
2015-02-10 22:33:13,908 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/appliedassertionsplatform/value/STRICT/STRICT/_temporary
2015-02-10 22:33:13,939 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 22:33:13,940 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.6.3/9ae016e2b8d246b9c1de9168e715d9f1b971aa4a/cascading-hadoop2-mr1-2.6.3.jar
2015-02-10 22:33:13,958 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 22:33:13,964 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 22:33:13,965 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 22:33:13,975 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting
2015-02-10 22:33:13,976 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2015-02-10 22:33:13,977 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/appliedassertionsplatform/value/NONE/VALID"]
2015-02-10 22:33:13,977 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] parallel execution is enabled: false
2015-02-10 22:33:13,978 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting jobs: 1
2015-02-10 22:33:13,978 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] allocating threads: 1
2015-02-10 22:33:13,979 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...platform/value/NONE/VALID
2015-02-10 22:33:13,981 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 22:33:13,982 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 22:33:14,016 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 22:33:14,039 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 22:33:14,060 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1107731553_0004
2015-02-10 22:33:14,093 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity1107731553/.staging/job_local1107731553_0004/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 22:33:14,095 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity1107731553/.staging/job_local1107731553_0004/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 22:33:14,163 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_local1107731553_0004/job_local1107731553_0004.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 22:33:14,164 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_local1107731553_0004/job_local1107731553_0004.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 22:33:14,166 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 22:33:14,166 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local1107731553_0004
2015-02-10 22:33:14,166 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 22:33:14,166 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2015-02-10 22:33:14,167 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 22:33:14,171 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 22:33:14,172 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1107731553_0004_m_000000_0
2015-02-10 22:33:14,175 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 22:33:14,177 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 22:33:14,177 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@413803ba
2015-02-10 22:33:14,179 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-10 22:33:14,180 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-10 22:33:14,325 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-10 22:33:14,326 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-10 22:33:14,326 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-10 22:33:14,326 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-10 22:33:14,326 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-10 22:33:14,328 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 22:33:14,329 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 22:33:14,342 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2015-02-10 22:33:14,342 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:'method']]
2015-02-10 22:33:14,348 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 22:33:14,348 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2015-02-10 22:33:14,348 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2015-02-10 22:33:14,348 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 693; bufvoid = 104857600
2015-02-10 22:33:14,348 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214372(104857488); length = 25/6553600
2015-02-10 22:33:14,352 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2015-02-10 22:33:14,355 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1107731553_0004_m_000000_0 is done. And is in the process of committing
2015-02-10 22:33:14,357 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 22:33:14,357 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1107731553_0004_m_000000_0' done.
2015-02-10 22:33:14,358 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1107731553_0004_m_000000_0
2015-02-10 22:33:14,359 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 22:33:14,359 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2015-02-10 22:33:14,359 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1107731553_0004_r_000000_0
2015-02-10 22:33:14,362 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 22:33:14,362 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@67bf6ec8
2015-02-10 22:33:14,363 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2015-02-10 22:33:14,364 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1107731553_0004_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2015-02-10 22:33:14,366 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#4 about to shuffle output of map attempt_local1107731553_0004_m_000000_0 decomp: 709 len: 713 to MEMORY
2015-02-10 22:33:14,367 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 709 bytes from map-output for attempt_local1107731553_0004_m_000000_0
2015-02-10 22:33:14,367 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 709, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->709
2015-02-10 22:33:14,368 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2015-02-10 22:33:14,371 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 22:33:14,371 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2015-02-10 22:33:14,374 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 22:33:14,374 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 697 bytes
2015-02-10 22:33:14,376 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 709 bytes to disk to satisfy reduce memory limit
2015-02-10 22:33:14,377 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 713 bytes from disk
2015-02-10 22:33:14,377 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2015-02-10 22:33:14,377 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 22:33:14,377 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 697 bytes
2015-02-10 22:33:14,378 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 22:33:14,379 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.6.3
2015-02-10 22:33:14,379 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2015-02-10 22:33:14,390 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:'method']]
2015-02-10 22:33:14,390 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/appliedassertionsplatform/value/NONE/VALID"]
2015-02-10 22:33:14,404 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1107731553_0004_r_000000_0 is done. And is in the process of committing
2015-02-10 22:33:14,406 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 22:33:14,406 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1107731553_0004_r_000000_0 is allowed to commit now
2015-02-10 22:33:14,407 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1107731553_0004_r_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/output/hadoop2-mr1/appliedassertionsplatform/value/NONE/VALID/_temporary/0/task_local1107731553_0004_r_000000
2015-02-10 22:33:14,409 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2015-02-10 22:33:14,409 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1107731553_0004_r_000000_0' done.
2015-02-10 22:33:14,409 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1107731553_0004_r_000000_0
2015-02-10 22:33:14,410 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2015-02-10 22:33:14,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/appliedassertionsplatform/value/NONE/VALID/_temporary
2015-02-10 22:33:14,475 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 22:33:14,502 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 22:33:14,503 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.6.3/9ae016e2b8d246b9c1de9168e715d9f1b971aa4a/cascading-hadoop2-mr1-2.6.3.jar
2015-02-10 22:33:14,520 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 22:33:14,524 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 22:33:14,525 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 22:33:14,536 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting
2015-02-10 22:33:14,537 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2015-02-10 22:33:14,537 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/appliedassertionsplatform/value/VALID/VALID"]
2015-02-10 22:33:14,538 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] parallel execution is enabled: false
2015-02-10 22:33:14,538 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting jobs: 1
2015-02-10 22:33:14,538 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] allocating threads: 1
2015-02-10 22:33:14,539 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...latform/value/VALID/VALID
2015-02-10 22:33:14,541 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 22:33:14,542 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 22:33:14,573 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 22:33:14,594 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 22:33:14,633 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local9383850_0005
2015-02-10 22:33:14,658 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity9383850/.staging/job_local9383850_0005/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 22:33:14,659 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity9383850/.staging/job_local9383850_0005/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 22:33:14,743 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_local9383850_0005/job_local9383850_0005.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 22:33:14,744 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_local9383850_0005/job_local9383850_0005.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 22:33:14,744 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 22:33:14,745 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 22:33:14,746 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local9383850_0005
2015-02-10 22:33:14,746 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 22:33:14,746 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2015-02-10 22:33:14,750 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 22:33:14,750 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local9383850_0005_m_000000_0
2015-02-10 22:33:14,753 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 22:33:14,755 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 22:33:14,755 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@7ba76fdd
2015-02-10 22:33:14,757 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-10 22:33:14,757 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-10 22:33:14,908 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-10 22:33:14,909 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-10 22:33:14,909 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-10 22:33:14,909 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-10 22:33:14,909 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-10 22:33:14,911 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 22:33:14,912 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 22:33:14,927 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2015-02-10 22:33:14,927 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:'method']]
2015-02-10 22:33:14,933 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 22:33:14,933 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2015-02-10 22:33:14,933 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2015-02-10 22:33:14,933 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 693; bufvoid = 104857600
2015-02-10 22:33:14,933 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214372(104857488); length = 25/6553600
2015-02-10 22:33:14,937 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2015-02-10 22:33:14,940 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local9383850_0005_m_000000_0 is done. And is in the process of committing
2015-02-10 22:33:14,942 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 22:33:14,943 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local9383850_0005_m_000000_0' done.
2015-02-10 22:33:14,943 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local9383850_0005_m_000000_0
2015-02-10 22:33:14,943 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 22:33:14,944 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2015-02-10 22:33:14,944 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local9383850_0005_r_000000_0
2015-02-10 22:33:14,946 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 22:33:14,947 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@92524b0
2015-02-10 22:33:14,948 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2015-02-10 22:33:14,948 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local9383850_0005_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2015-02-10 22:33:14,951 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#5 about to shuffle output of map attempt_local9383850_0005_m_000000_0 decomp: 709 len: 713 to MEMORY
2015-02-10 22:33:14,951 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 709 bytes from map-output for attempt_local9383850_0005_m_000000_0
2015-02-10 22:33:14,952 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 709, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->709
2015-02-10 22:33:14,952 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2015-02-10 22:33:14,954 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 22:33:14,955 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2015-02-10 22:33:14,958 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 22:33:14,958 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 697 bytes
2015-02-10 22:33:14,960 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 709 bytes to disk to satisfy reduce memory limit
2015-02-10 22:33:14,961 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 713 bytes from disk
2015-02-10 22:33:14,961 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2015-02-10 22:33:14,961 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 22:33:14,961 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 697 bytes
2015-02-10 22:33:14,962 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 22:33:14,962 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.6.3
2015-02-10 22:33:14,963 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2015-02-10 22:33:14,974 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:'method']]
2015-02-10 22:33:14,974 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/appliedassertionsplatform/value/VALID/VALID"]
2015-02-10 22:33:14,987 ERROR stream.TrapHandler (TrapHandler.java:handleReThrowableException(103)) - caught Throwable, no trap available, rethrowing
cascading.operation.AssertionException: [cascading.operation.assertion.AppliedAssertionsPlatformTest.runValueAssertions(AppliedAssertionsPlatformTest.java:158)] argument tuple: ['7'] was not equal to values: ['0']
at cascading.operation.assertion.BaseAssertion.throwFail(BaseAssertion.java:107)
at cascading.operation.assertion.BaseAssertion.fail(BaseAssertion.java:86)
at cascading.operation.assertion.AssertEquals.doAssert(AssertEquals.java:77)
at cascading.flow.stream.ValueAssertionEachStage.receive(ValueAssertionEachStage.java:70)
at cascading.flow.stream.ValueAssertionEachStage.receive(ValueAssertionEachStage.java:34)
at cascading.flow.stream.CloseReducingDuct.completeGroup(CloseReducingDuct.java:47)
at cascading.flow.stream.AggregatorEveryStage$1.collect(AggregatorEveryStage.java:67)
at cascading.tuple.TupleEntryCollector.safeCollect(TupleEntryCollector.java:145)
at cascading.tuple.TupleEntryCollector.add(TupleEntryCollector.java:133)
at cascading.operation.aggregator.Count.complete(Count.java:82)
at cascading.flow.stream.AggregatorEveryStage.completeGroup(AggregatorEveryStage.java:151)
at cascading.flow.stream.AggregatorEveryStage.completeGroup(AggregatorEveryStage.java:39)
at cascading.flow.stream.OpenReducingDuct.receive(OpenReducingDuct.java:51)
at cascading.flow.stream.OpenReducingDuct.receive(OpenReducingDuct.java:28)
at cascading.flow.hadoop.stream.HadoopGroupGate.run(HadoopGroupGate.java:93)
at cascading.flow.hadoop.FlowReducer.reduce(FlowReducer.java:136)
at org.apache.hadoop.mapred.ReduceTask.runOldReducer(ReduceTask.java:444)
at org.apache.hadoop.mapred.ReduceTask.run(ReduceTask.java:392)
at org.apache.hadoop.mapred.LocalJobRunner$Job$ReduceTaskRunnable.run(LocalJobRunner.java:319)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:439)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
at java.lang.Thread.run(Thread.java:662)
2015-02-10 22:33:14,988 ERROR stream.TrapHandler (TrapHandler.java:handleReThrowableException(103)) - caught Throwable, no trap available, rethrowing
cascading.operation.AssertionException: [cascading.operation.assertion.AppliedAssertionsPlatformTest.runValueAssertions(AppliedAssertionsPlatformTest.java:158)] argument tuple: ['7'] was not equal to values: ['0']
at cascading.operation.assertion.BaseAssertion.throwFail(BaseAssertion.java:107)
at cascading.operation.assertion.BaseAssertion.fail(BaseAssertion.java:86)
at cascading.operation.assertion.AssertEquals.doAssert(AssertEquals.java:77)
at cascading.flow.stream.ValueAssertionEachStage.receive(ValueAssertionEachStage.java:70)
at cascading.flow.stream.ValueAssertionEachStage.receive(ValueAssertionEachStage.java:34)
at cascading.flow.stream.CloseReducingDuct.completeGroup(CloseReducingDuct.java:47)
at cascading.flow.stream.AggregatorEveryStage$1.collect(AggregatorEveryStage.java:67)
at cascading.tuple.TupleEntryCollector.safeCollect(TupleEntryCollector.java:145)
at cascading.tuple.TupleEntryCollector.add(TupleEntryCollector.java:133)
at cascading.operation.aggregator.Count.complete(Count.java:82)
at cascading.flow.stream.AggregatorEveryStage.completeGroup(AggregatorEveryStage.java:151)
at cascading.flow.stream.AggregatorEveryStage.completeGroup(AggregatorEveryStage.java:39)
at cascading.flow.stream.OpenReducingDuct.receive(OpenReducingDuct.java:51)
at cascading.flow.stream.OpenReducingDuct.receive(OpenReducingDuct.java:28)
at cascading.flow.hadoop.stream.HadoopGroupGate.run(HadoopGroupGate.java:93)
at cascading.flow.hadoop.FlowReducer.reduce(FlowReducer.java:136)
at org.apache.hadoop.mapred.ReduceTask.runOldReducer(ReduceTask.java:444)
at org.apache.hadoop.mapred.ReduceTask.run(ReduceTask.java:392)
at org.apache.hadoop.mapred.LocalJobRunner$Job$ReduceTaskRunnable.run(LocalJobRunner.java:319)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:439)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
at java.lang.Thread.run(Thread.java:662)
2015-02-10 22:33:14,989 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2015-02-10 22:33:14,992 WARN mapred.LocalJobRunner (LocalJobRunner.java:run(560)) - job_local9383850_0005
java.lang.Exception: cascading.operation.AssertionException: [cascading.operation.assertion.AppliedAssertionsPlatformTest.runValueAssertions(AppliedAssertionsPlatformTest.java:158)] argument tuple: ['7'] was not equal to values: ['0']
at org.apache.hadoop.mapred.LocalJobRunner$Job.runTasks(LocalJobRunner.java:462)
at org.apache.hadoop.mapred.LocalJobRunner$Job.run(LocalJobRunner.java:529)
Caused by: cascading.operation.AssertionException: [cascading.operation.assertion.AppliedAssertionsPlatformTest.runValueAssertions(AppliedAssertionsPlatformTest.java:158)] argument tuple: ['7'] was not equal to values: ['0']
at cascading.operation.assertion.BaseAssertion.throwFail(BaseAssertion.java:107)
at cascading.operation.assertion.BaseAssertion.fail(BaseAssertion.java:86)
at cascading.operation.assertion.AssertEquals.doAssert(AssertEquals.java:77)
at cascading.flow.stream.ValueAssertionEachStage.receive(ValueAssertionEachStage.java:70)
at cascading.flow.stream.ValueAssertionEachStage.receive(ValueAssertionEachStage.java:34)
at cascading.flow.stream.CloseReducingDuct.completeGroup(CloseReducingDuct.java:47)
at cascading.flow.stream.AggregatorEveryStage$1.collect(AggregatorEveryStage.java:67)
at cascading.tuple.TupleEntryCollector.safeCollect(TupleEntryCollector.java:145)
at cascading.tuple.TupleEntryCollector.add(TupleEntryCollector.java:133)
at cascading.operation.aggregator.Count.complete(Count.java:82)
at cascading.flow.stream.AggregatorEveryStage.completeGroup(AggregatorEveryStage.java:151)
at cascading.flow.stream.AggregatorEveryStage.completeGroup(AggregatorEveryStage.java:39)
at cascading.flow.stream.OpenReducingDuct.receive(OpenReducingDuct.java:51)
at cascading.flow.stream.OpenReducingDuct.receive(OpenReducingDuct.java:28)
at cascading.flow.hadoop.stream.HadoopGroupGate.run(HadoopGroupGate.java:93)
at cascading.flow.hadoop.FlowReducer.reduce(FlowReducer.java:136)
at org.apache.hadoop.mapred.ReduceTask.runOldReducer(ReduceTask.java:444)
at org.apache.hadoop.mapred.ReduceTask.run(ReduceTask.java:392)
at org.apache.hadoop.mapred.LocalJobRunner$Job$ReduceTaskRunnable.run(LocalJobRunner.java:319)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:439)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
at java.lang.Thread.run(Thread.java:662)
2015-02-10 22:33:15,000 WARN flow.FlowStep (BaseFlowStep.java:logWarn(839)) - [test] hadoop job job_local9383850_0005 state at FAILED
2015-02-10 22:33:15,000 WARN flow.FlowStep (BaseFlowStep.java:logWarn(839)) - [test] failure info: NA
2015-02-10 22:33:15,000 WARN flow.FlowStep (BaseFlowStep.java:logWarn(839)) - [test] task completion events identify failed tasks
2015-02-10 22:33:15,001 WARN flow.FlowStep (BaseFlowStep.java:logWarn(839)) - [test] task completion events count: 0
2015-02-10 22:33:15,011 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] stopping all jobs
2015-02-10 22:33:15,011 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] stopping: (1/1) ...latform/value/VALID/VALID
2015-02-10 22:33:15,012 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] stopped all jobs
2015-02-10 22:33:15,012 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/appliedassertionsplatform/value/VALID/VALID/_temporary
2015-02-10 22:33:15,013 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/appliedassertionsplatform/value/VALID/VALID
2015-02-10 22:33:15,013 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/appliedassertionsplatform/value/STRICT/STRICT
2015-02-10 22:33:15,014 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/appliedassertionsplatform/value/NONE/STRICT
2015-02-10 22:33:15,014 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/appliedassertionsplatform/value/VALID/STRICT
2015-02-10 22:33:15,014 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/appliedassertionsplatform/value/NONE/VALID
2015-02-10 22:33:15,043 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 22:33:15,043 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.6.3/9ae016e2b8d246b9c1de9168e715d9f1b971aa4a/cascading-hadoop2-mr1-2.6.3.jar
2015-02-10 22:33:15,059 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 22:33:15,063 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 22:33:15,063 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 22:33:15,073 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting
2015-02-10 22:33:15,073 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2015-02-10 22:33:15,074 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/appliedassertionsplatform/group/NONE/STRICT"]
2015-02-10 22:33:15,074 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] parallel execution is enabled: false
2015-02-10 22:33:15,074 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting jobs: 1
2015-02-10 22:33:15,074 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] allocating threads: 1
2015-02-10 22:33:15,075 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...latform/group/NONE/STRICT
2015-02-10 22:33:15,076 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 22:33:15,077 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 22:33:15,116 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 22:33:15,136 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 22:33:15,154 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1141617821_0006
2015-02-10 22:33:15,173 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity1141617821/.staging/job_local1141617821_0006/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 22:33:15,174 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity1141617821/.staging/job_local1141617821_0006/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 22:33:15,231 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_local1141617821_0006/job_local1141617821_0006.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 22:33:15,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_local1141617821_0006/job_local1141617821_0006.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 22:33:15,232 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 22:33:15,233 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local1141617821_0006
2015-02-10 22:33:15,233 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 22:33:15,233 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2015-02-10 22:33:15,233 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 22:33:15,238 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 22:33:15,239 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1141617821_0006_m_000000_0
2015-02-10 22:33:15,241 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 22:33:15,243 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 22:33:15,244 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@5cd5a2a9
2015-02-10 22:33:15,245 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-10 22:33:15,246 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-10 22:33:15,610 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-10 22:33:15,612 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-10 22:33:15,612 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-10 22:33:15,613 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-10 22:33:15,614 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-10 22:33:15,615 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 22:33:15,616 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 22:33:15,628 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2015-02-10 22:33:15,628 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:'method']]
2015-02-10 22:33:15,633 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 22:33:15,634 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2015-02-10 22:33:15,634 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2015-02-10 22:33:15,635 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 693; bufvoid = 104857600
2015-02-10 22:33:15,635 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214372(104857488); length = 25/6553600
2015-02-10 22:33:15,639 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2015-02-10 22:33:15,641 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1141617821_0006_m_000000_0 is done. And is in the process of committing
2015-02-10 22:33:15,644 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 22:33:15,645 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1141617821_0006_m_000000_0' done.
2015-02-10 22:33:15,645 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1141617821_0006_m_000000_0
2015-02-10 22:33:15,646 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 22:33:15,646 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2015-02-10 22:33:15,647 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1141617821_0006_r_000000_0
2015-02-10 22:33:15,649 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 22:33:15,650 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@74a14fed
2015-02-10 22:33:15,651 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2015-02-10 22:33:15,652 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1141617821_0006_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2015-02-10 22:33:15,654 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#6 about to shuffle output of map attempt_local1141617821_0006_m_000000_0 decomp: 709 len: 713 to MEMORY
2015-02-10 22:33:15,655 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 709 bytes from map-output for attempt_local1141617821_0006_m_000000_0
2015-02-10 22:33:15,655 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 709, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->709
2015-02-10 22:33:15,656 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2015-02-10 22:33:15,657 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 22:33:15,658 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2015-02-10 22:33:15,660 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 22:33:15,660 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 697 bytes
2015-02-10 22:33:15,662 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 709 bytes to disk to satisfy reduce memory limit
2015-02-10 22:33:15,663 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 713 bytes from disk
2015-02-10 22:33:15,663 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2015-02-10 22:33:15,663 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 22:33:15,663 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 697 bytes
2015-02-10 22:33:15,664 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 22:33:15,664 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.6.3
2015-02-10 22:33:15,665 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2015-02-10 22:33:15,674 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:'method']]
2015-02-10 22:33:15,674 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/appliedassertionsplatform/group/NONE/STRICT"]
2015-02-10 22:33:15,686 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1141617821_0006_r_000000_0 is done. And is in the process of committing
2015-02-10 22:33:15,688 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 22:33:15,688 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1141617821_0006_r_000000_0 is allowed to commit now
2015-02-10 22:33:15,689 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1141617821_0006_r_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/output/hadoop2-mr1/appliedassertionsplatform/group/NONE/STRICT/_temporary/0/task_local1141617821_0006_r_000000
2015-02-10 22:33:15,691 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2015-02-10 22:33:15,691 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1141617821_0006_r_000000_0' done.
2015-02-10 22:33:15,691 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1141617821_0006_r_000000_0
2015-02-10 22:33:15,692 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2015-02-10 22:33:15,722 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/appliedassertionsplatform/group/NONE/STRICT/_temporary
2015-02-10 22:33:15,756 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 22:33:15,781 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 22:33:15,782 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.6.3/9ae016e2b8d246b9c1de9168e715d9f1b971aa4a/cascading-hadoop2-mr1-2.6.3.jar
2015-02-10 22:33:15,797 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 22:33:15,800 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 22:33:15,801 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 22:33:15,810 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting
2015-02-10 22:33:15,811 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2015-02-10 22:33:15,811 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/appliedassertionsplatform/group/VALID/STRICT"]
2015-02-10 22:33:15,812 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] parallel execution is enabled: false
2015-02-10 22:33:15,812 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting jobs: 1
2015-02-10 22:33:15,813 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] allocating threads: 1
2015-02-10 22:33:15,814 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...atform/group/VALID/STRICT
2015-02-10 22:33:15,815 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 22:33:15,816 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 22:33:15,844 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 22:33:15,864 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 22:33:15,882 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1897958341_0007
2015-02-10 22:33:15,901 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity1897958341/.staging/job_local1897958341_0007/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 22:33:15,902 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity1897958341/.staging/job_local1897958341_0007/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 22:33:15,960 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_local1897958341_0007/job_local1897958341_0007.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 22:33:15,961 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_local1897958341_0007/job_local1897958341_0007.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 22:33:15,962 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 22:33:15,963 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local1897958341_0007
2015-02-10 22:33:15,963 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 22:33:15,963 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2015-02-10 22:33:15,963 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 22:33:15,967 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 22:33:15,967 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1897958341_0007_m_000000_0
2015-02-10 22:33:15,969 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 22:33:15,971 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 22:33:15,971 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@65685e30
2015-02-10 22:33:15,973 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-10 22:33:15,973 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-10 22:33:16,129 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-10 22:33:16,130 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-10 22:33:16,130 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-10 22:33:16,130 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-10 22:33:16,130 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-10 22:33:16,132 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 22:33:16,132 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 22:33:16,142 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2015-02-10 22:33:16,142 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:'method']]
2015-02-10 22:33:16,147 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 22:33:16,147 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2015-02-10 22:33:16,147 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2015-02-10 22:33:16,147 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 693; bufvoid = 104857600
2015-02-10 22:33:16,147 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214372(104857488); length = 25/6553600
2015-02-10 22:33:16,151 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2015-02-10 22:33:16,154 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1897958341_0007_m_000000_0 is done. And is in the process of committing
2015-02-10 22:33:16,156 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 22:33:16,156 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1897958341_0007_m_000000_0' done.
2015-02-10 22:33:16,157 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1897958341_0007_m_000000_0
2015-02-10 22:33:16,157 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 22:33:16,158 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2015-02-10 22:33:16,158 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1897958341_0007_r_000000_0
2015-02-10 22:33:16,160 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 22:33:16,160 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@205eb650
2015-02-10 22:33:16,162 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2015-02-10 22:33:16,163 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1897958341_0007_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2015-02-10 22:33:16,165 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#7 about to shuffle output of map attempt_local1897958341_0007_m_000000_0 decomp: 709 len: 713 to MEMORY
2015-02-10 22:33:16,165 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 709 bytes from map-output for attempt_local1897958341_0007_m_000000_0
2015-02-10 22:33:16,166 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 709, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->709
2015-02-10 22:33:16,166 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2015-02-10 22:33:16,167 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 22:33:16,168 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2015-02-10 22:33:16,170 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 22:33:16,170 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 697 bytes
2015-02-10 22:33:16,172 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 709 bytes to disk to satisfy reduce memory limit
2015-02-10 22:33:16,173 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 713 bytes from disk
2015-02-10 22:33:16,173 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2015-02-10 22:33:16,173 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 22:33:16,173 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 697 bytes
2015-02-10 22:33:16,174 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 22:33:16,174 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.6.3
2015-02-10 22:33:16,175 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2015-02-10 22:33:16,183 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:'method']]
2015-02-10 22:33:16,183 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/appliedassertionsplatform/group/VALID/STRICT"]
2015-02-10 22:33:16,195 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1897958341_0007_r_000000_0 is done. And is in the process of committing
2015-02-10 22:33:16,197 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 22:33:16,197 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1897958341_0007_r_000000_0 is allowed to commit now
2015-02-10 22:33:16,198 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1897958341_0007_r_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/output/hadoop2-mr1/appliedassertionsplatform/group/VALID/STRICT/_temporary/0/task_local1897958341_0007_r_000000
2015-02-10 22:33:16,200 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2015-02-10 22:33:16,200 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1897958341_0007_r_000000_0' done.
2015-02-10 22:33:16,200 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1897958341_0007_r_000000_0
2015-02-10 22:33:16,201 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2015-02-10 22:33:16,227 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/appliedassertionsplatform/group/VALID/STRICT/_temporary
2015-02-10 22:33:16,260 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 22:33:16,292 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 22:33:16,293 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.6.3/9ae016e2b8d246b9c1de9168e715d9f1b971aa4a/cascading-hadoop2-mr1-2.6.3.jar
2015-02-10 22:33:16,309 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 22:33:16,313 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 22:33:16,314 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 22:33:16,327 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting
2015-02-10 22:33:16,328 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2015-02-10 22:33:16,328 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/appliedassertionsplatform/group/STRICT/STRICT"]
2015-02-10 22:33:16,328 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] parallel execution is enabled: false
2015-02-10 22:33:16,328 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting jobs: 1
2015-02-10 22:33:16,328 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] allocating threads: 1
2015-02-10 22:33:16,330 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...tform/group/STRICT/STRICT
2015-02-10 22:33:16,330 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 22:33:16,333 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 22:33:16,361 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 22:33:16,381 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 22:33:16,399 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local2069873670_0008
2015-02-10 22:33:16,419 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity2069873670/.staging/job_local2069873670_0008/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 22:33:16,421 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity2069873670/.staging/job_local2069873670_0008/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 22:33:16,476 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_local2069873670_0008/job_local2069873670_0008.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 22:33:16,478 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_local2069873670_0008/job_local2069873670_0008.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 22:33:16,478 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 22:33:16,478 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local2069873670_0008
2015-02-10 22:33:16,479 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2015-02-10 22:33:16,479 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 22:33:16,480 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 22:33:16,484 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 22:33:16,484 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local2069873670_0008_m_000000_0
2015-02-10 22:33:16,486 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 22:33:16,489 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 22:33:16,490 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@431067af
2015-02-10 22:33:16,492 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-10 22:33:16,492 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-10 22:33:16,662 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-10 22:33:16,663 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-10 22:33:16,663 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-10 22:33:16,663 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-10 22:33:16,663 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-10 22:33:16,665 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 22:33:16,665 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 22:33:16,676 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2015-02-10 22:33:16,677 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:'method']]
2015-02-10 22:33:16,682 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 22:33:16,682 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2015-02-10 22:33:16,682 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2015-02-10 22:33:16,682 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 693; bufvoid = 104857600
2015-02-10 22:33:16,682 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214372(104857488); length = 25/6553600
2015-02-10 22:33:16,716 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2015-02-10 22:33:16,718 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local2069873670_0008_m_000000_0 is done. And is in the process of committing
2015-02-10 22:33:16,721 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 22:33:16,721 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local2069873670_0008_m_000000_0' done.
2015-02-10 22:33:16,722 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local2069873670_0008_m_000000_0
2015-02-10 22:33:16,722 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 22:33:16,722 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2015-02-10 22:33:16,723 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local2069873670_0008_r_000000_0
2015-02-10 22:33:16,725 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 22:33:16,726 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@130a7be0
2015-02-10 22:33:16,728 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2015-02-10 22:33:16,729 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local2069873670_0008_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2015-02-10 22:33:16,731 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#8 about to shuffle output of map attempt_local2069873670_0008_m_000000_0 decomp: 709 len: 713 to MEMORY
2015-02-10 22:33:16,732 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 709 bytes from map-output for attempt_local2069873670_0008_m_000000_0
2015-02-10 22:33:16,732 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 709, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->709
2015-02-10 22:33:16,733 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2015-02-10 22:33:16,734 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 22:33:16,734 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2015-02-10 22:33:16,737 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 22:33:16,737 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 697 bytes
2015-02-10 22:33:16,739 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 709 bytes to disk to satisfy reduce memory limit
2015-02-10 22:33:16,739 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 713 bytes from disk
2015-02-10 22:33:16,739 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2015-02-10 22:33:16,739 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 22:33:16,740 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 697 bytes
2015-02-10 22:33:16,741 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 22:33:16,741 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.6.3
2015-02-10 22:33:16,741 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2015-02-10 22:33:16,758 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:'method']]
2015-02-10 22:33:16,758 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/appliedassertionsplatform/group/STRICT/STRICT"]
2015-02-10 22:33:16,771 ERROR stream.TrapHandler (TrapHandler.java:handleReThrowableException(103)) - caught Throwable, no trap available, rethrowing
cascading.operation.AssertionException: [cascading.operation.assertion.AppliedAssertionsPlatformTest.runGroupAssertions(AppliedAssertionsPlatformTest.java:283)] group size: 7, is not equal to: 0, in group ['method']: ['POST']
at cascading.operation.assertion.BaseAssertion.throwFail(BaseAssertion.java:107)
at cascading.operation.assertion.BaseAssertion.fail(BaseAssertion.java:86)
at cascading.operation.assertion.AssertGroupBase.doAssert(AssertGroupBase.java:172)
at cascading.flow.stream.GroupAssertionEveryStage.completeGroup(GroupAssertionEveryStage.java:125)
at cascading.flow.stream.GroupAssertionEveryStage.completeGroup(GroupAssertionEveryStage.java:34)
at cascading.flow.stream.AggregatorEveryStage$1.collect(AggregatorEveryStage.java:67)
at cascading.tuple.TupleEntryCollector.safeCollect(TupleEntryCollector.java:145)
at cascading.tuple.TupleEntryCollector.add(TupleEntryCollector.java:133)
at cascading.operation.aggregator.Count.complete(Count.java:82)
at cascading.flow.stream.AggregatorEveryStage.completeGroup(AggregatorEveryStage.java:151)
at cascading.flow.stream.AggregatorEveryStage.completeGroup(AggregatorEveryStage.java:39)
at cascading.flow.stream.OpenReducingDuct.receive(OpenReducingDuct.java:51)
at cascading.flow.stream.OpenReducingDuct.receive(OpenReducingDuct.java:28)
at cascading.flow.hadoop.stream.HadoopGroupGate.run(HadoopGroupGate.java:93)
at cascading.flow.hadoop.FlowReducer.reduce(FlowReducer.java:136)
at org.apache.hadoop.mapred.ReduceTask.runOldReducer(ReduceTask.java:444)
at org.apache.hadoop.mapred.ReduceTask.run(ReduceTask.java:392)
at org.apache.hadoop.mapred.LocalJobRunner$Job$ReduceTaskRunnable.run(LocalJobRunner.java:319)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:439)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
at java.lang.Thread.run(Thread.java:662)
2015-02-10 22:33:16,773 ERROR stream.TrapHandler (TrapHandler.java:handleReThrowableException(103)) - caught Throwable, no trap available, rethrowing
cascading.operation.AssertionException: [cascading.operation.assertion.AppliedAssertionsPlatformTest.runGroupAssertions(AppliedAssertionsPlatformTest.java:283)] group size: 7, is not equal to: 0, in group ['method']: ['POST']
at cascading.operation.assertion.BaseAssertion.throwFail(BaseAssertion.java:107)
at cascading.operation.assertion.BaseAssertion.fail(BaseAssertion.java:86)
at cascading.operation.assertion.AssertGroupBase.doAssert(AssertGroupBase.java:172)
at cascading.flow.stream.GroupAssertionEveryStage.completeGroup(GroupAssertionEveryStage.java:125)
at cascading.flow.stream.GroupAssertionEveryStage.completeGroup(GroupAssertionEveryStage.java:34)
at cascading.flow.stream.AggregatorEveryStage$1.collect(AggregatorEveryStage.java:67)
at cascading.tuple.TupleEntryCollector.safeCollect(TupleEntryCollector.java:145)
at cascading.tuple.TupleEntryCollector.add(TupleEntryCollector.java:133)
at cascading.operation.aggregator.Count.complete(Count.java:82)
at cascading.flow.stream.AggregatorEveryStage.completeGroup(AggregatorEveryStage.java:151)
at cascading.flow.stream.AggregatorEveryStage.completeGroup(AggregatorEveryStage.java:39)
at cascading.flow.stream.OpenReducingDuct.receive(OpenReducingDuct.java:51)
at cascading.flow.stream.OpenReducingDuct.receive(OpenReducingDuct.java:28)
at cascading.flow.hadoop.stream.HadoopGroupGate.run(HadoopGroupGate.java:93)
at cascading.flow.hadoop.FlowReducer.reduce(FlowReducer.java:136)
at org.apache.hadoop.mapred.ReduceTask.runOldReducer(ReduceTask.java:444)
at org.apache.hadoop.mapred.ReduceTask.run(ReduceTask.java:392)
at org.apache.hadoop.mapred.LocalJobRunner$Job$ReduceTaskRunnable.run(LocalJobRunner.java:319)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:439)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
at java.lang.Thread.run(Thread.java:662)
2015-02-10 22:33:16,774 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2015-02-10 22:33:16,776 WARN mapred.LocalJobRunner (LocalJobRunner.java:run(560)) - job_local2069873670_0008
java.lang.Exception: cascading.operation.AssertionException: [cascading.operation.assertion.AppliedAssertionsPlatformTest.runGroupAssertions(AppliedAssertionsPlatformTest.java:283)] group size: 7, is not equal to: 0, in group ['method']: ['POST']
at org.apache.hadoop.mapred.LocalJobRunner$Job.runTasks(LocalJobRunner.java:462)
at org.apache.hadoop.mapred.LocalJobRunner$Job.run(LocalJobRunner.java:529)
Caused by: cascading.operation.AssertionException: [cascading.operation.assertion.AppliedAssertionsPlatformTest.runGroupAssertions(AppliedAssertionsPlatformTest.java:283)] group size: 7, is not equal to: 0, in group ['method']: ['POST']
at cascading.operation.assertion.BaseAssertion.throwFail(BaseAssertion.java:107)
at cascading.operation.assertion.BaseAssertion.fail(BaseAssertion.java:86)
at cascading.operation.assertion.AssertGroupBase.doAssert(AssertGroupBase.java:172)
at cascading.flow.stream.GroupAssertionEveryStage.completeGroup(GroupAssertionEveryStage.java:125)
at cascading.flow.stream.GroupAssertionEveryStage.completeGroup(GroupAssertionEveryStage.java:34)
at cascading.flow.stream.AggregatorEveryStage$1.collect(AggregatorEveryStage.java:67)
at cascading.tuple.TupleEntryCollector.safeCollect(TupleEntryCollector.java:145)
at cascading.tuple.TupleEntryCollector.add(TupleEntryCollector.java:133)
at cascading.operation.aggregator.Count.complete(Count.java:82)
at cascading.flow.stream.AggregatorEveryStage.completeGroup(AggregatorEveryStage.java:151)
at cascading.flow.stream.AggregatorEveryStage.completeGroup(AggregatorEveryStage.java:39)
at cascading.flow.stream.OpenReducingDuct.receive(OpenReducingDuct.java:51)
at cascading.flow.stream.OpenReducingDuct.receive(OpenReducingDuct.java:28)
at cascading.flow.hadoop.stream.HadoopGroupGate.run(HadoopGroupGate.java:93)
at cascading.flow.hadoop.FlowReducer.reduce(FlowReducer.java:136)
at org.apache.hadoop.mapred.ReduceTask.runOldReducer(ReduceTask.java:444)
at org.apache.hadoop.mapred.ReduceTask.run(ReduceTask.java:392)
at org.apache.hadoop.mapred.LocalJobRunner$Job$ReduceTaskRunnable.run(LocalJobRunner.java:319)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:439)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
at java.lang.Thread.run(Thread.java:662)
2015-02-10 22:33:16,783 WARN flow.FlowStep (BaseFlowStep.java:logWarn(839)) - [test] hadoop job job_local2069873670_0008 state at FAILED
2015-02-10 22:33:16,783 WARN flow.FlowStep (BaseFlowStep.java:logWarn(839)) - [test] failure info: NA
2015-02-10 22:33:16,783 WARN flow.FlowStep (BaseFlowStep.java:logWarn(839)) - [test] task completion events identify failed tasks
2015-02-10 22:33:16,784 WARN flow.FlowStep (BaseFlowStep.java:logWarn(839)) - [test] task completion events count: 0
2015-02-10 22:33:16,792 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] stopping all jobs
2015-02-10 22:33:16,792 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] stopping: (1/1) ...tform/group/STRICT/STRICT
2015-02-10 22:33:16,793 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] stopped all jobs
2015-02-10 22:33:16,794 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/appliedassertionsplatform/group/STRICT/STRICT/_temporary
2015-02-10 22:33:16,817 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 22:33:16,818 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.6.3/9ae016e2b8d246b9c1de9168e715d9f1b971aa4a/cascading-hadoop2-mr1-2.6.3.jar
2015-02-10 22:33:16,831 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 22:33:16,834 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 22:33:16,835 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 22:33:16,843 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting
2015-02-10 22:33:16,843 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2015-02-10 22:33:16,844 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/appliedassertionsplatform/group/NONE/VALID"]
2015-02-10 22:33:16,844 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] parallel execution is enabled: false
2015-02-10 22:33:16,845 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting jobs: 1
2015-02-10 22:33:16,845 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] allocating threads: 1
2015-02-10 22:33:16,846 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...platform/group/NONE/VALID
2015-02-10 22:33:16,847 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 22:33:16,848 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 22:33:16,875 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 22:33:16,896 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 22:33:16,916 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local767116404_0009
2015-02-10 22:33:16,938 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity767116404/.staging/job_local767116404_0009/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 22:33:16,939 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity767116404/.staging/job_local767116404_0009/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 22:33:17,015 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_local767116404_0009/job_local767116404_0009.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 22:33:17,018 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_local767116404_0009/job_local767116404_0009.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 22:33:17,019 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 22:33:17,019 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 22:33:17,020 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 22:33:17,019 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local767116404_0009
2015-02-10 22:33:17,020 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2015-02-10 22:33:17,023 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 22:33:17,023 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local767116404_0009_m_000000_0
2015-02-10 22:33:17,025 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 22:33:17,027 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 22:33:17,027 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@43fee2db
2015-02-10 22:33:17,029 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-10 22:33:17,029 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-10 22:33:17,179 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-10 22:33:17,179 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-10 22:33:17,179 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-10 22:33:17,179 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-10 22:33:17,179 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-10 22:33:17,181 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 22:33:17,181 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 22:33:17,191 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2015-02-10 22:33:17,191 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:'method']]
2015-02-10 22:33:17,196 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 22:33:17,196 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2015-02-10 22:33:17,196 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2015-02-10 22:33:17,196 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 693; bufvoid = 104857600
2015-02-10 22:33:17,196 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214372(104857488); length = 25/6553600
2015-02-10 22:33:17,200 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2015-02-10 22:33:17,202 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local767116404_0009_m_000000_0 is done. And is in the process of committing
2015-02-10 22:33:17,205 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 22:33:17,205 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local767116404_0009_m_000000_0' done.
2015-02-10 22:33:17,205 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local767116404_0009_m_000000_0
2015-02-10 22:33:17,205 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 22:33:17,206 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2015-02-10 22:33:17,206 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local767116404_0009_r_000000_0
2015-02-10 22:33:17,208 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 22:33:17,208 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@778a5d49
2015-02-10 22:33:17,209 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2015-02-10 22:33:17,210 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local767116404_0009_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2015-02-10 22:33:17,212 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#9 about to shuffle output of map attempt_local767116404_0009_m_000000_0 decomp: 709 len: 713 to MEMORY
2015-02-10 22:33:17,213 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 709 bytes from map-output for attempt_local767116404_0009_m_000000_0
2015-02-10 22:33:17,213 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 709, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->709
2015-02-10 22:33:17,214 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2015-02-10 22:33:17,215 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 22:33:17,215 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2015-02-10 22:33:17,218 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 22:33:17,218 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 697 bytes
2015-02-10 22:33:17,221 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 709 bytes to disk to satisfy reduce memory limit
2015-02-10 22:33:17,222 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 713 bytes from disk
2015-02-10 22:33:17,222 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2015-02-10 22:33:17,222 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 22:33:17,223 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 697 bytes
2015-02-10 22:33:17,224 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 22:33:17,225 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.6.3
2015-02-10 22:33:17,225 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2015-02-10 22:33:17,234 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:'method']]
2015-02-10 22:33:17,234 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/appliedassertionsplatform/group/NONE/VALID"]
2015-02-10 22:33:17,246 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local767116404_0009_r_000000_0 is done. And is in the process of committing
2015-02-10 22:33:17,248 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 22:33:17,248 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local767116404_0009_r_000000_0 is allowed to commit now
2015-02-10 22:33:17,249 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local767116404_0009_r_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/output/hadoop2-mr1/appliedassertionsplatform/group/NONE/VALID/_temporary/0/task_local767116404_0009_r_000000
2015-02-10 22:33:17,250 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2015-02-10 22:33:17,251 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local767116404_0009_r_000000_0' done.
2015-02-10 22:33:17,251 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local767116404_0009_r_000000_0
2015-02-10 22:33:17,251 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2015-02-10 22:33:17,272 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/appliedassertionsplatform/group/NONE/VALID/_temporary
2015-02-10 22:33:17,304 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 22:33:17,329 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 22:33:17,330 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.6.3/9ae016e2b8d246b9c1de9168e715d9f1b971aa4a/cascading-hadoop2-mr1-2.6.3.jar
2015-02-10 22:33:17,342 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 22:33:17,345 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 22:33:17,346 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 22:33:17,355 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting
2015-02-10 22:33:17,355 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2015-02-10 22:33:17,356 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/appliedassertionsplatform/group/VALID/VALID"]
2015-02-10 22:33:17,356 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] parallel execution is enabled: false
2015-02-10 22:33:17,356 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting jobs: 1
2015-02-10 22:33:17,357 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] allocating threads: 1
2015-02-10 22:33:17,358 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...latform/group/VALID/VALID
2015-02-10 22:33:17,358 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 22:33:17,359 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 22:33:17,386 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 22:33:17,407 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 22:33:17,424 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1931348293_0010
2015-02-10 22:33:17,444 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity1931348293/.staging/job_local1931348293_0010/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 22:33:17,445 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity1931348293/.staging/job_local1931348293_0010/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 22:33:17,497 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_local1931348293_0010/job_local1931348293_0010.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 22:33:17,499 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_local1931348293_0010/job_local1931348293_0010.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 22:33:17,499 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 22:33:17,500 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local1931348293_0010
2015-02-10 22:33:17,500 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2015-02-10 22:33:17,500 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 22:33:17,500 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 22:33:17,504 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 22:33:17,504 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1931348293_0010_m_000000_0
2015-02-10 22:33:17,506 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 22:33:17,508 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 22:33:17,508 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@134a388b
2015-02-10 22:33:17,509 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-10 22:33:17,510 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-10 22:33:17,829 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-10 22:33:17,829 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-10 22:33:17,829 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-10 22:33:17,830 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-10 22:33:17,830 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-10 22:33:17,831 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 22:33:17,832 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 22:33:17,842 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2015-02-10 22:33:17,842 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:'method']]
2015-02-10 22:33:17,847 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 22:33:17,847 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2015-02-10 22:33:17,847 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2015-02-10 22:33:17,847 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 693; bufvoid = 104857600
2015-02-10 22:33:17,847 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214372(104857488); length = 25/6553600
2015-02-10 22:33:17,851 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2015-02-10 22:33:17,853 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1931348293_0010_m_000000_0 is done. And is in the process of committing
2015-02-10 22:33:17,856 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 22:33:17,856 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1931348293_0010_m_000000_0' done.
2015-02-10 22:33:17,856 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1931348293_0010_m_000000_0
2015-02-10 22:33:17,857 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 22:33:17,857 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2015-02-10 22:33:17,857 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1931348293_0010_r_000000_0
2015-02-10 22:33:17,860 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 22:33:17,860 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@20e0b1d6
2015-02-10 22:33:17,861 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2015-02-10 22:33:17,862 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1931348293_0010_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2015-02-10 22:33:17,864 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#10 about to shuffle output of map attempt_local1931348293_0010_m_000000_0 decomp: 709 len: 713 to MEMORY
2015-02-10 22:33:17,865 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 709 bytes from map-output for attempt_local1931348293_0010_m_000000_0
2015-02-10 22:33:17,865 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 709, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->709
2015-02-10 22:33:17,866 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2015-02-10 22:33:17,867 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 22:33:17,867 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2015-02-10 22:33:17,872 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 22:33:17,873 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 697 bytes
2015-02-10 22:33:17,875 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 709 bytes to disk to satisfy reduce memory limit
2015-02-10 22:33:17,875 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 713 bytes from disk
2015-02-10 22:33:17,876 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2015-02-10 22:33:17,876 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 22:33:17,877 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 697 bytes
2015-02-10 22:33:17,877 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 22:33:17,878 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.6.3
2015-02-10 22:33:17,878 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2015-02-10 22:33:17,888 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:'method']]
2015-02-10 22:33:17,889 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/appliedassertionsplatform/group/VALID/VALID"]
2015-02-10 22:33:17,900 ERROR stream.TrapHandler (TrapHandler.java:handleReThrowableException(103)) - caught Throwable, no trap available, rethrowing
cascading.operation.AssertionException: [cascading.operation.assertion.AppliedAssertionsPlatformTest.runGroupAssertions(AppliedAssertionsPlatformTest.java:283)] group size: 7, is not equal to: 0, in group ['method']: ['POST']
at cascading.operation.assertion.BaseAssertion.throwFail(BaseAssertion.java:107)
at cascading.operation.assertion.BaseAssertion.fail(BaseAssertion.java:86)
at cascading.operation.assertion.AssertGroupBase.doAssert(AssertGroupBase.java:172)
at cascading.flow.stream.GroupAssertionEveryStage.completeGroup(GroupAssertionEveryStage.java:125)
at cascading.flow.stream.GroupAssertionEveryStage.completeGroup(GroupAssertionEveryStage.java:34)
at cascading.flow.stream.AggregatorEveryStage$1.collect(AggregatorEveryStage.java:67)
at cascading.tuple.TupleEntryCollector.safeCollect(TupleEntryCollector.java:145)
at cascading.tuple.TupleEntryCollector.add(TupleEntryCollector.java:133)
at cascading.operation.aggregator.Count.complete(Count.java:82)
at cascading.flow.stream.AggregatorEveryStage.completeGroup(AggregatorEveryStage.java:151)
at cascading.flow.stream.AggregatorEveryStage.completeGroup(AggregatorEveryStage.java:39)
at cascading.flow.stream.OpenReducingDuct.receive(OpenReducingDuct.java:51)
at cascading.flow.stream.OpenReducingDuct.receive(OpenReducingDuct.java:28)
at cascading.flow.hadoop.stream.HadoopGroupGate.run(HadoopGroupGate.java:93)
at cascading.flow.hadoop.FlowReducer.reduce(FlowReducer.java:136)
at org.apache.hadoop.mapred.ReduceTask.runOldReducer(ReduceTask.java:444)
at org.apache.hadoop.mapred.ReduceTask.run(ReduceTask.java:392)
at org.apache.hadoop.mapred.LocalJobRunner$Job$ReduceTaskRunnable.run(LocalJobRunner.java:319)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:439)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
at java.lang.Thread.run(Thread.java:662)
2015-02-10 22:33:17,901 ERROR stream.TrapHandler (TrapHandler.java:handleReThrowableException(103)) - caught Throwable, no trap available, rethrowing
cascading.operation.AssertionException: [cascading.operation.assertion.AppliedAssertionsPlatformTest.runGroupAssertions(AppliedAssertionsPlatformTest.java:283)] group size: 7, is not equal to: 0, in group ['method']: ['POST']
at cascading.operation.assertion.BaseAssertion.throwFail(BaseAssertion.java:107)
at cascading.operation.assertion.BaseAssertion.fail(BaseAssertion.java:86)
at cascading.operation.assertion.AssertGroupBase.doAssert(AssertGroupBase.java:172)
at cascading.flow.stream.GroupAssertionEveryStage.completeGroup(GroupAssertionEveryStage.java:125)
at cascading.flow.stream.GroupAssertionEveryStage.completeGroup(GroupAssertionEveryStage.java:34)
at cascading.flow.stream.AggregatorEveryStage$1.collect(AggregatorEveryStage.java:67)
at cascading.tuple.TupleEntryCollector.safeCollect(TupleEntryCollector.java:145)
at cascading.tuple.TupleEntryCollector.add(TupleEntryCollector.java:133)
at cascading.operation.aggregator.Count.complete(Count.java:82)
at cascading.flow.stream.AggregatorEveryStage.completeGroup(AggregatorEveryStage.java:151)
at cascading.flow.stream.AggregatorEveryStage.completeGroup(AggregatorEveryStage.java:39)
at cascading.flow.stream.OpenReducingDuct.receive(OpenReducingDuct.java:51)
at cascading.flow.stream.OpenReducingDuct.receive(OpenReducingDuct.java:28)
at cascading.flow.hadoop.stream.HadoopGroupGate.run(HadoopGroupGate.java:93)
at cascading.flow.hadoop.FlowReducer.reduce(FlowReducer.java:136)
at org.apache.hadoop.mapred.ReduceTask.runOldReducer(ReduceTask.java:444)
at org.apache.hadoop.mapred.ReduceTask.run(ReduceTask.java:392)
at org.apache.hadoop.mapred.LocalJobRunner$Job$ReduceTaskRunnable.run(LocalJobRunner.java:319)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:439)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
at java.lang.Thread.run(Thread.java:662)
2015-02-10 22:33:17,902 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2015-02-10 22:33:17,905 WARN mapred.LocalJobRunner (LocalJobRunner.java:run(560)) - job_local1931348293_0010
java.lang.Exception: cascading.operation.AssertionException: [cascading.operation.assertion.AppliedAssertionsPlatformTest.runGroupAssertions(AppliedAssertionsPlatformTest.java:283)] group size: 7, is not equal to: 0, in group ['method']: ['POST']
at org.apache.hadoop.mapred.LocalJobRunner$Job.runTasks(LocalJobRunner.java:462)
at org.apache.hadoop.mapred.LocalJobRunner$Job.run(LocalJobRunner.java:529)
Caused by: cascading.operation.AssertionException: [cascading.operation.assertion.AppliedAssertionsPlatformTest.runGroupAssertions(AppliedAssertionsPlatformTest.java:283)] group size: 7, is not equal to: 0, in group ['method']: ['POST']
at cascading.operation.assertion.BaseAssertion.throwFail(BaseAssertion.java:107)
at cascading.operation.assertion.BaseAssertion.fail(BaseAssertion.java:86)
at cascading.operation.assertion.AssertGroupBase.doAssert(AssertGroupBase.java:172)
at cascading.flow.stream.GroupAssertionEveryStage.completeGroup(GroupAssertionEveryStage.java:125)
at cascading.flow.stream.GroupAssertionEveryStage.completeGroup(GroupAssertionEveryStage.java:34)
at cascading.flow.stream.AggregatorEveryStage$1.collect(AggregatorEveryStage.java:67)
at cascading.tuple.TupleEntryCollector.safeCollect(TupleEntryCollector.java:145)
at cascading.tuple.TupleEntryCollector.add(TupleEntryCollector.java:133)
at cascading.operation.aggregator.Count.complete(Count.java:82)
at cascading.flow.stream.AggregatorEveryStage.completeGroup(AggregatorEveryStage.java:151)
at cascading.flow.stream.AggregatorEveryStage.completeGroup(AggregatorEveryStage.java:39)
at cascading.flow.stream.OpenReducingDuct.receive(OpenReducingDuct.java:51)
at cascading.flow.stream.OpenReducingDuct.receive(OpenReducingDuct.java:28)
at cascading.flow.hadoop.stream.HadoopGroupGate.run(HadoopGroupGate.java:93)
at cascading.flow.hadoop.FlowReducer.reduce(FlowReducer.java:136)
at org.apache.hadoop.mapred.ReduceTask.runOldReducer(ReduceTask.java:444)
at org.apache.hadoop.mapred.ReduceTask.run(ReduceTask.java:392)
at org.apache.hadoop.mapred.LocalJobRunner$Job$ReduceTaskRunnable.run(LocalJobRunner.java:319)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:439)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
at java.lang.Thread.run(Thread.java:662)
2015-02-10 22:33:17,906 WARN flow.FlowStep (BaseFlowStep.java:logWarn(839)) - [test] hadoop job job_local1931348293_0010 state at FAILED
2015-02-10 22:33:17,906 WARN flow.FlowStep (BaseFlowStep.java:logWarn(839)) - [test] failure info: NA
2015-02-10 22:33:17,906 WARN flow.FlowStep (BaseFlowStep.java:logWarn(839)) - [test] task completion events identify failed tasks
2015-02-10 22:33:17,906 WARN flow.FlowStep (BaseFlowStep.java:logWarn(839)) - [test] task completion events count: 0
2015-02-10 22:33:17,914 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] stopping all jobs
2015-02-10 22:33:17,914 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] stopping: (1/1) ...latform/group/VALID/VALID
2015-02-10 22:33:17,915 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] stopped all jobs
2015-02-10 22:33:17,916 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/appliedassertionsplatform/group/VALID/VALID/_temporary
2015-02-10 22:33:17,916 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/appliedassertionsplatform/group/VALID/VALID
2015-02-10 22:33:17,916 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/appliedassertionsplatform/group/STRICT/STRICT
2015-02-10 22:33:17,917 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/appliedassertionsplatform/group/NONE/STRICT
2015-02-10 22:33:17,917 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/appliedassertionsplatform/group/NONE/VALID
2015-02-10 22:33:17,917 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/appliedassertionsplatform/group/VALID/STRICT
2015-02-10 22:33:17,940 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 22:33:17,940 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.6.3/9ae016e2b8d246b9c1de9168e715d9f1b971aa4a/cascading-hadoop2-mr1-2.6.3.jar
2015-02-10 22:33:17,952 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 22:33:17,954 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 22:33:17,955 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 22:33:17,963 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting
2015-02-10 22:33:17,963 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2015-02-10 22:33:17,964 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/appliedassertionsplatform/fail"]
2015-02-10 22:33:17,964 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] parallel execution is enabled: false
2015-02-10 22:33:17,964 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting jobs: 1
2015-02-10 22:33:17,964 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] allocating threads: 1
2015-02-10 22:33:17,965 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...edassertionsplatform/fail
2015-02-10 22:33:17,966 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 22:33:17,968 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 22:33:17,995 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 22:33:18,016 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 22:33:18,032 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local670441089_0011
2015-02-10 22:33:18,051 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity670441089/.staging/job_local670441089_0011/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 22:33:18,052 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity670441089/.staging/job_local670441089_0011/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 22:33:18,103 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_local670441089_0011/job_local670441089_0011.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 22:33:18,105 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_local670441089_0011/job_local670441089_0011.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 22:33:18,105 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 22:33:18,106 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local670441089_0011
2015-02-10 22:33:18,106 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 22:33:18,106 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2015-02-10 22:33:18,106 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 22:33:18,110 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 22:33:18,111 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local670441089_0011_m_000000_0
2015-02-10 22:33:18,113 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 22:33:18,114 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 22:33:18,115 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@41eab16b
2015-02-10 22:33:18,116 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-10 22:33:18,117 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-10 22:33:18,268 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-10 22:33:18,268 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-10 22:33:18,268 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-10 22:33:18,268 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-10 22:33:18,268 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-10 22:33:18,270 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 22:33:18,270 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 22:33:18,281 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2015-02-10 22:33:18,281 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:'method']]
2015-02-10 22:33:18,285 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 22:33:18,285 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2015-02-10 22:33:18,285 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2015-02-10 22:33:18,285 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 693; bufvoid = 104857600
2015-02-10 22:33:18,286 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214372(104857488); length = 25/6553600
2015-02-10 22:33:18,289 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2015-02-10 22:33:18,291 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local670441089_0011_m_000000_0 is done. And is in the process of committing
2015-02-10 22:33:18,293 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 22:33:18,293 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local670441089_0011_m_000000_0' done.
2015-02-10 22:33:18,294 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local670441089_0011_m_000000_0
2015-02-10 22:33:18,294 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 22:33:18,294 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2015-02-10 22:33:18,295 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local670441089_0011_r_000000_0
2015-02-10 22:33:18,297 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 22:33:18,297 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@55ac9683
2015-02-10 22:33:18,298 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2015-02-10 22:33:18,301 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local670441089_0011_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2015-02-10 22:33:18,303 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#11 about to shuffle output of map attempt_local670441089_0011_m_000000_0 decomp: 709 len: 713 to MEMORY
2015-02-10 22:33:18,303 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 709 bytes from map-output for attempt_local670441089_0011_m_000000_0
2015-02-10 22:33:18,304 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 709, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->709
2015-02-10 22:33:18,304 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2015-02-10 22:33:18,306 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 22:33:18,306 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2015-02-10 22:33:18,308 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 22:33:18,308 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 697 bytes
2015-02-10 22:33:18,310 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 709 bytes to disk to satisfy reduce memory limit
2015-02-10 22:33:18,310 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 713 bytes from disk
2015-02-10 22:33:18,310 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2015-02-10 22:33:18,310 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 22:33:18,311 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 697 bytes
2015-02-10 22:33:18,311 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 22:33:18,312 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.6.3
2015-02-10 22:33:18,312 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2015-02-10 22:33:18,321 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:'method']]
2015-02-10 22:33:18,321 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/appliedassertionsplatform/fail"]
2015-02-10 22:33:18,332 ERROR stream.TrapHandler (TrapHandler.java:handleReThrowableException(103)) - caught Throwable, no trap available, rethrowing
cascading.operation.AssertionException: [cascading.operation.assertion.AppliedAssertionsPlatformTest.testGroupAssertionsFail(AppliedAssertionsPlatformTest.java:236)] group size: 7, is not equal to: 0, in group ['method']: ['POST']
at cascading.operation.assertion.BaseAssertion.throwFail(BaseAssertion.java:107)
at cascading.operation.assertion.BaseAssertion.fail(BaseAssertion.java:86)
at cascading.operation.assertion.AssertGroupBase.doAssert(AssertGroupBase.java:172)
at cascading.flow.stream.GroupAssertionEveryStage.completeGroup(GroupAssertionEveryStage.java:125)
at cascading.flow.stream.GroupAssertionEveryStage.completeGroup(GroupAssertionEveryStage.java:34)
at cascading.flow.stream.AggregatorEveryStage$1.collect(AggregatorEveryStage.java:67)
at cascading.tuple.TupleEntryCollector.safeCollect(TupleEntryCollector.java:145)
at cascading.tuple.TupleEntryCollector.add(TupleEntryCollector.java:133)
at cascading.operation.aggregator.Count.complete(Count.java:82)
at cascading.flow.stream.AggregatorEveryStage.completeGroup(AggregatorEveryStage.java:151)
at cascading.flow.stream.AggregatorEveryStage.completeGroup(AggregatorEveryStage.java:39)
at cascading.flow.stream.OpenReducingDuct.receive(OpenReducingDuct.java:51)
at cascading.flow.stream.OpenReducingDuct.receive(OpenReducingDuct.java:28)
at cascading.flow.hadoop.stream.HadoopGroupGate.run(HadoopGroupGate.java:93)
at cascading.flow.hadoop.FlowReducer.reduce(FlowReducer.java:136)
at org.apache.hadoop.mapred.ReduceTask.runOldReducer(ReduceTask.java:444)
at org.apache.hadoop.mapred.ReduceTask.run(ReduceTask.java:392)
at org.apache.hadoop.mapred.LocalJobRunner$Job$ReduceTaskRunnable.run(LocalJobRunner.java:319)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:439)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
at java.lang.Thread.run(Thread.java:662)
2015-02-10 22:33:18,332 ERROR stream.TrapHandler (TrapHandler.java:handleReThrowableException(103)) - caught Throwable, no trap available, rethrowing
cascading.operation.AssertionException: [cascading.operation.assertion.AppliedAssertionsPlatformTest.testGroupAssertionsFail(AppliedAssertionsPlatformTest.java:236)] group size: 7, is not equal to: 0, in group ['method']: ['POST']
at cascading.operation.assertion.BaseAssertion.throwFail(BaseAssertion.java:107)
at cascading.operation.assertion.BaseAssertion.fail(BaseAssertion.java:86)
at cascading.operation.assertion.AssertGroupBase.doAssert(AssertGroupBase.java:172)
at cascading.flow.stream.GroupAssertionEveryStage.completeGroup(GroupAssertionEveryStage.java:125)
at cascading.flow.stream.GroupAssertionEveryStage.completeGroup(GroupAssertionEveryStage.java:34)
at cascading.flow.stream.AggregatorEveryStage$1.collect(AggregatorEveryStage.java:67)
at cascading.tuple.TupleEntryCollector.safeCollect(TupleEntryCollector.java:145)
at cascading.tuple.TupleEntryCollector.add(TupleEntryCollector.java:133)
at cascading.operation.aggregator.Count.complete(Count.java:82)
at cascading.flow.stream.AggregatorEveryStage.completeGroup(AggregatorEveryStage.java:151)
at cascading.flow.stream.AggregatorEveryStage.completeGroup(AggregatorEveryStage.java:39)
at cascading.flow.stream.OpenReducingDuct.receive(OpenReducingDuct.java:51)
at cascading.flow.stream.OpenReducingDuct.receive(OpenReducingDuct.java:28)
at cascading.flow.hadoop.stream.HadoopGroupGate.run(HadoopGroupGate.java:93)
at cascading.flow.hadoop.FlowReducer.reduce(FlowReducer.java:136)
at org.apache.hadoop.mapred.ReduceTask.runOldReducer(ReduceTask.java:444)
at org.apache.hadoop.mapred.ReduceTask.run(ReduceTask.java:392)
at org.apache.hadoop.mapred.LocalJobRunner$Job$ReduceTaskRunnable.run(LocalJobRunner.java:319)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:439)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
at java.lang.Thread.run(Thread.java:662)
2015-02-10 22:33:18,334 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2015-02-10 22:33:18,336 WARN mapred.LocalJobRunner (LocalJobRunner.java:run(560)) - job_local670441089_0011
java.lang.Exception: cascading.operation.AssertionException: [cascading.operation.assertion.AppliedAssertionsPlatformTest.testGroupAssertionsFail(AppliedAssertionsPlatformTest.java:236)] group size: 7, is not equal to: 0, in group ['method']: ['POST']
at org.apache.hadoop.mapred.LocalJobRunner$Job.runTasks(LocalJobRunner.java:462)
at org.apache.hadoop.mapred.LocalJobRunner$Job.run(LocalJobRunner.java:529)
Caused by: cascading.operation.AssertionException: [cascading.operation.assertion.AppliedAssertionsPlatformTest.testGroupAssertionsFail(AppliedAssertionsPlatformTest.java:236)] group size: 7, is not equal to: 0, in group ['method']: ['POST']
at cascading.operation.assertion.BaseAssertion.throwFail(BaseAssertion.java:107)
at cascading.operation.assertion.BaseAssertion.fail(BaseAssertion.java:86)
at cascading.operation.assertion.AssertGroupBase.doAssert(AssertGroupBase.java:172)
at cascading.flow.stream.GroupAssertionEveryStage.completeGroup(GroupAssertionEveryStage.java:125)
at cascading.flow.stream.GroupAssertionEveryStage.completeGroup(GroupAssertionEveryStage.java:34)
at cascading.flow.stream.AggregatorEveryStage$1.collect(AggregatorEveryStage.java:67)
at cascading.tuple.TupleEntryCollector.safeCollect(TupleEntryCollector.java:145)
at cascading.tuple.TupleEntryCollector.add(TupleEntryCollector.java:133)
at cascading.operation.aggregator.Count.complete(Count.java:82)
at cascading.flow.stream.AggregatorEveryStage.completeGroup(AggregatorEveryStage.java:151)
at cascading.flow.stream.AggregatorEveryStage.completeGroup(AggregatorEveryStage.java:39)
at cascading.flow.stream.OpenReducingDuct.receive(OpenReducingDuct.java:51)
at cascading.flow.stream.OpenReducingDuct.receive(OpenReducingDuct.java:28)
at cascading.flow.hadoop.stream.HadoopGroupGate.run(HadoopGroupGate.java:93)
at cascading.flow.hadoop.FlowReducer.reduce(FlowReducer.java:136)
at org.apache.hadoop.mapred.ReduceTask.runOldReducer(ReduceTask.java:444)
at org.apache.hadoop.mapred.ReduceTask.run(ReduceTask.java:392)
at org.apache.hadoop.mapred.LocalJobRunner$Job$ReduceTaskRunnable.run(LocalJobRunner.java:319)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:439)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
at java.lang.Thread.run(Thread.java:662)
2015-02-10 22:33:18,340 WARN flow.FlowStep (BaseFlowStep.java:logWarn(839)) - [test] hadoop job job_local670441089_0011 state at FAILED
2015-02-10 22:33:18,340 WARN flow.FlowStep (BaseFlowStep.java:logWarn(839)) - [test] failure info: NA
2015-02-10 22:33:18,340 WARN flow.FlowStep (BaseFlowStep.java:logWarn(839)) - [test] task completion events identify failed tasks
2015-02-10 22:33:18,341 WARN flow.FlowStep (BaseFlowStep.java:logWarn(839)) - [test] task completion events count: 0
2015-02-10 22:33:18,347 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] stopping all jobs
2015-02-10 22:33:18,348 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] stopping: (1/1) ...edassertionsplatform/fail
2015-02-10 22:33:18,351 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] stopped all jobs
2015-02-10 22:33:18,352 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/appliedassertionsplatform/fail/_temporary
2015-02-10 22:33:18,352 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/appliedassertionsplatform/fail
2015-02-10 22:33:18,374 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 22:33:18,374 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.6.3/9ae016e2b8d246b9c1de9168e715d9f1b971aa4a/cascading-hadoop2-mr1-2.6.3.jar
2015-02-10 22:33:18,385 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 22:33:18,387 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 22:33:18,388 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 22:33:18,394 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting
2015-02-10 22:33:18,394 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2015-02-10 22:33:18,395 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/appliedassertionsplatform/pass"]
2015-02-10 22:33:18,395 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] parallel execution is enabled: false
2015-02-10 22:33:18,395 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting jobs: 1
2015-02-10 22:33:18,395 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] allocating threads: 1
2015-02-10 22:33:18,396 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...edassertionsplatform/pass
2015-02-10 22:33:18,396 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 22:33:18,397 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 22:33:18,423 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 22:33:18,442 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 22:33:18,458 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1079510454_0012
2015-02-10 22:33:18,477 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity1079510454/.staging/job_local1079510454_0012/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 22:33:18,478 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity1079510454/.staging/job_local1079510454_0012/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 22:33:18,544 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_local1079510454_0012/job_local1079510454_0012.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 22:33:18,546 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_local1079510454_0012/job_local1079510454_0012.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 22:33:18,547 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 22:33:18,547 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local1079510454_0012
2015-02-10 22:33:18,547 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 22:33:18,547 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2015-02-10 22:33:18,548 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 22:33:18,551 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 22:33:18,551 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1079510454_0012_m_000000_0
2015-02-10 22:33:18,553 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 22:33:18,555 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 22:33:18,555 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@63f5e4b6
2015-02-10 22:33:18,556 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-10 22:33:18,556 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-10 22:33:18,699 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-10 22:33:18,699 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-10 22:33:18,700 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-10 22:33:18,700 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-10 22:33:18,700 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-10 22:33:18,701 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 22:33:18,701 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 22:33:18,710 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2015-02-10 22:33:18,711 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:'method']]
2015-02-10 22:33:18,715 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 22:33:18,715 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2015-02-10 22:33:18,715 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2015-02-10 22:33:18,715 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 693; bufvoid = 104857600
2015-02-10 22:33:18,715 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214372(104857488); length = 25/6553600
2015-02-10 22:33:18,719 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2015-02-10 22:33:18,721 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1079510454_0012_m_000000_0 is done. And is in the process of committing
2015-02-10 22:33:18,723 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 22:33:18,723 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1079510454_0012_m_000000_0' done.
2015-02-10 22:33:18,723 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1079510454_0012_m_000000_0
2015-02-10 22:33:18,724 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 22:33:18,724 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2015-02-10 22:33:18,725 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1079510454_0012_r_000000_0
2015-02-10 22:33:18,727 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 22:33:18,727 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@57070723
2015-02-10 22:33:18,728 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2015-02-10 22:33:18,728 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1079510454_0012_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2015-02-10 22:33:18,731 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#12 about to shuffle output of map attempt_local1079510454_0012_m_000000_0 decomp: 709 len: 713 to MEMORY
2015-02-10 22:33:18,731 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 709 bytes from map-output for attempt_local1079510454_0012_m_000000_0
2015-02-10 22:33:18,732 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 709, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->709
2015-02-10 22:33:18,732 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2015-02-10 22:33:18,733 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 22:33:18,734 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2015-02-10 22:33:18,736 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 22:33:18,736 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 697 bytes
2015-02-10 22:33:18,738 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 709 bytes to disk to satisfy reduce memory limit
2015-02-10 22:33:18,738 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 713 bytes from disk
2015-02-10 22:33:18,739 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2015-02-10 22:33:18,739 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 22:33:18,739 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 697 bytes
2015-02-10 22:33:18,740 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 22:33:18,740 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.6.3
2015-02-10 22:33:18,741 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2015-02-10 22:33:18,751 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:'method']]
2015-02-10 22:33:18,751 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/appliedassertionsplatform/pass"]
2015-02-10 22:33:18,762 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1079510454_0012_r_000000_0 is done. And is in the process of committing
2015-02-10 22:33:18,764 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 22:33:18,764 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1079510454_0012_r_000000_0 is allowed to commit now
2015-02-10 22:33:18,765 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1079510454_0012_r_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/output/hadoop2-mr1/appliedassertionsplatform/pass/_temporary/0/task_local1079510454_0012_r_000000
2015-02-10 22:33:18,767 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2015-02-10 22:33:18,767 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1079510454_0012_r_000000_0' done.
2015-02-10 22:33:18,767 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1079510454_0012_r_000000_0
2015-02-10 22:33:18,767 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2015-02-10 22:33:18,789 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/appliedassertionsplatform/pass/_temporary
2015-02-10 22:33:18,831 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 22:33:18,833 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/appliedassertionsplatform/pass
2015-02-10 22:33:18,857 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 22:33:18,857 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.6.3/9ae016e2b8d246b9c1de9168e715d9f1b971aa4a/cascading-hadoop2-mr1-2.6.3.jar
2015-02-10 22:33:18,868 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 22:33:18,870 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 22:33:18,871 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 22:33:18,877 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting
2015-02-10 22:33:18,878 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2015-02-10 22:33:18,878 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/appliedassertionsplatform/value/fail"]
2015-02-10 22:33:18,879 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] parallel execution is enabled: false
2015-02-10 22:33:18,879 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting jobs: 1
2015-02-10 22:33:18,879 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] allocating threads: 1
2015-02-10 22:33:18,880 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...rtionsplatform/value/fail
2015-02-10 22:33:18,881 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 22:33:18,882 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 22:33:18,907 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 22:33:18,926 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 22:33:18,942 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local766558076_0013
2015-02-10 22:33:18,962 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity766558076/.staging/job_local766558076_0013/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 22:33:18,963 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity766558076/.staging/job_local766558076_0013/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 22:33:19,016 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_local766558076_0013/job_local766558076_0013.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 22:33:19,017 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_local766558076_0013/job_local766558076_0013.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 22:33:19,018 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 22:33:19,019 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local766558076_0013
2015-02-10 22:33:19,019 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 22:33:19,019 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2015-02-10 22:33:19,019 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 22:33:19,022 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 22:33:19,023 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local766558076_0013_m_000000_0
2015-02-10 22:33:19,024 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 22:33:19,026 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 22:33:19,026 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@7309eab7
2015-02-10 22:33:19,027 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-10 22:33:19,028 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-10 22:33:19,172 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-10 22:33:19,172 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-10 22:33:19,172 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-10 22:33:19,172 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-10 22:33:19,172 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-10 22:33:19,173 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 22:33:19,174 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 22:33:19,183 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2015-02-10 22:33:19,183 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:'method']]
2015-02-10 22:33:19,187 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 22:33:19,188 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2015-02-10 22:33:19,188 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2015-02-10 22:33:19,188 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 693; bufvoid = 104857600
2015-02-10 22:33:19,188 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214372(104857488); length = 25/6553600
2015-02-10 22:33:19,191 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2015-02-10 22:33:19,193 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local766558076_0013_m_000000_0 is done. And is in the process of committing
2015-02-10 22:33:19,195 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 22:33:19,195 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local766558076_0013_m_000000_0' done.
2015-02-10 22:33:19,195 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local766558076_0013_m_000000_0
2015-02-10 22:33:19,196 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 22:33:19,196 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2015-02-10 22:33:19,196 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local766558076_0013_r_000000_0
2015-02-10 22:33:19,198 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 22:33:19,198 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@16971e9d
2015-02-10 22:33:19,199 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2015-02-10 22:33:19,200 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local766558076_0013_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2015-02-10 22:33:19,202 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#13 about to shuffle output of map attempt_local766558076_0013_m_000000_0 decomp: 709 len: 713 to MEMORY
2015-02-10 22:33:19,202 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 709 bytes from map-output for attempt_local766558076_0013_m_000000_0
2015-02-10 22:33:19,202 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 709, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->709
2015-02-10 22:33:19,203 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2015-02-10 22:33:19,204 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 22:33:19,204 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2015-02-10 22:33:19,210 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 22:33:19,210 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 697 bytes
2015-02-10 22:33:19,212 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 709 bytes to disk to satisfy reduce memory limit
2015-02-10 22:33:19,212 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 713 bytes from disk
2015-02-10 22:33:19,212 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2015-02-10 22:33:19,212 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 22:33:19,213 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 697 bytes
2015-02-10 22:33:19,214 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 22:33:19,214 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.6.3
2015-02-10 22:33:19,214 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2015-02-10 22:33:19,222 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:'method']]
2015-02-10 22:33:19,223 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/appliedassertionsplatform/value/fail"]
2015-02-10 22:33:19,838 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2015-02-10 22:33:20,775 ERROR stream.TrapHandler (TrapHandler.java:handleReThrowableException(103)) - caught Throwable, no trap available, rethrowing
cascading.operation.AssertionException: [cascading.operation.assertion.AppliedAssertionsPlatformTest.testValueAssertionsFail(AppliedAssertionsPlatformTest.java:111)] argument tuple: ['7'] was not equal to values: ['0']
at cascading.operation.assertion.BaseAssertion.throwFail(BaseAssertion.java:107)
at cascading.operation.assertion.BaseAssertion.fail(BaseAssertion.java:86)
at cascading.operation.assertion.AssertEquals.doAssert(AssertEquals.java:77)
at cascading.flow.stream.ValueAssertionEachStage.receive(ValueAssertionEachStage.java:70)
at cascading.flow.stream.ValueAssertionEachStage.receive(ValueAssertionEachStage.java:34)
at cascading.flow.stream.CloseReducingDuct.completeGroup(CloseReducingDuct.java:47)
at cascading.flow.stream.AggregatorEveryStage$1.collect(AggregatorEveryStage.java:67)
at cascading.tuple.TupleEntryCollector.safeCollect(TupleEntryCollector.java:145)
at cascading.tuple.TupleEntryCollector.add(TupleEntryCollector.java:133)
at cascading.operation.aggregator.Count.complete(Count.java:82)
at cascading.flow.stream.AggregatorEveryStage.completeGroup(AggregatorEveryStage.java:151)
at cascading.flow.stream.AggregatorEveryStage.completeGroup(AggregatorEveryStage.java:39)
at cascading.flow.stream.OpenReducingDuct.receive(OpenReducingDuct.java:51)
at cascading.flow.stream.OpenReducingDuct.receive(OpenReducingDuct.java:28)
at cascading.flow.hadoop.stream.HadoopGroupGate.run(HadoopGroupGate.java:93)
at cascading.flow.hadoop.FlowReducer.reduce(FlowReducer.java:136)
at org.apache.hadoop.mapred.ReduceTask.runOldReducer(ReduceTask.java:444)
at org.apache.hadoop.mapred.ReduceTask.run(ReduceTask.java:392)
at org.apache.hadoop.mapred.LocalJobRunner$Job$ReduceTaskRunnable.run(LocalJobRunner.java:319)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:439)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
at java.lang.Thread.run(Thread.java:662)
2015-02-10 22:33:20,777 ERROR stream.TrapHandler (TrapHandler.java:handleReThrowableException(103)) - caught Throwable, no trap available, rethrowing
cascading.operation.AssertionException: [cascading.operation.assertion.AppliedAssertionsPlatformTest.testValueAssertionsFail(AppliedAssertionsPlatformTest.java:111)] argument tuple: ['7'] was not equal to values: ['0']
at cascading.operation.assertion.BaseAssertion.throwFail(BaseAssertion.java:107)
at cascading.operation.assertion.BaseAssertion.fail(BaseAssertion.java:86)
at cascading.operation.assertion.AssertEquals.doAssert(AssertEquals.java:77)
at cascading.flow.stream.ValueAssertionEachStage.receive(ValueAssertionEachStage.java:70)
at cascading.flow.stream.ValueAssertionEachStage.receive(ValueAssertionEachStage.java:34)
at cascading.flow.stream.CloseReducingDuct.completeGroup(CloseReducingDuct.java:47)
at cascading.flow.stream.AggregatorEveryStage$1.collect(AggregatorEveryStage.java:67)
at cascading.tuple.TupleEntryCollector.safeCollect(TupleEntryCollector.java:145)
at cascading.tuple.TupleEntryCollector.add(TupleEntryCollector.java:133)
at cascading.operation.aggregator.Count.complete(Count.java:82)
at cascading.flow.stream.AggregatorEveryStage.completeGroup(AggregatorEveryStage.java:151)
at cascading.flow.stream.AggregatorEveryStage.completeGroup(AggregatorEveryStage.java:39)
at cascading.flow.stream.OpenReducingDuct.receive(OpenReducingDuct.java:51)
at cascading.flow.stream.OpenReducingDuct.receive(OpenReducingDuct.java:28)
at cascading.flow.hadoop.stream.HadoopGroupGate.run(HadoopGroupGate.java:93)
at cascading.flow.hadoop.FlowReducer.reduce(FlowReducer.java:136)
at org.apache.hadoop.mapred.ReduceTask.runOldReducer(ReduceTask.java:444)
at org.apache.hadoop.mapred.ReduceTask.run(ReduceTask.java:392)
at org.apache.hadoop.mapred.LocalJobRunner$Job$ReduceTaskRunnable.run(LocalJobRunner.java:319)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:439)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
at java.lang.Thread.run(Thread.java:662)
2015-02-10 22:33:20,779 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2015-02-10 22:33:20,781 WARN mapred.LocalJobRunner (LocalJobRunner.java:run(560)) - job_local766558076_0013
java.lang.Exception: cascading.operation.AssertionException: [cascading.operation.assertion.AppliedAssertionsPlatformTest.testValueAssertionsFail(AppliedAssertionsPlatformTest.java:111)] argument tuple: ['7'] was not equal to values: ['0']
at org.apache.hadoop.mapred.LocalJobRunner$Job.runTasks(LocalJobRunner.java:462)
at org.apache.hadoop.mapred.LocalJobRunner$Job.run(LocalJobRunner.java:529)
Caused by: cascading.operation.AssertionException: [cascading.operation.assertion.AppliedAssertionsPlatformTest.testValueAssertionsFail(AppliedAssertionsPlatformTest.java:111)] argument tuple: ['7'] was not equal to values: ['0']
at cascading.operation.assertion.BaseAssertion.throwFail(BaseAssertion.java:107)
at cascading.operation.assertion.BaseAssertion.fail(BaseAssertion.java:86)
at cascading.operation.assertion.AssertEquals.doAssert(AssertEquals.java:77)
at cascading.flow.stream.ValueAssertionEachStage.receive(ValueAssertionEachStage.java:70)
at cascading.flow.stream.ValueAssertionEachStage.receive(ValueAssertionEachStage.java:34)
at cascading.flow.stream.CloseReducingDuct.completeGroup(CloseReducingDuct.java:47)
at cascading.flow.stream.AggregatorEveryStage$1.collect(AggregatorEveryStage.java:67)
at cascading.tuple.TupleEntryCollector.safeCollect(TupleEntryCollector.java:145)
at cascading.tuple.TupleEntryCollector.add(TupleEntryCollector.java:133)
at cascading.operation.aggregator.Count.complete(Count.java:82)
at cascading.flow.stream.AggregatorEveryStage.completeGroup(AggregatorEveryStage.java:151)
at cascading.flow.stream.AggregatorEveryStage.completeGroup(AggregatorEveryStage.java:39)
at cascading.flow.stream.OpenReducingDuct.receive(OpenReducingDuct.java:51)
at cascading.flow.stream.OpenReducingDuct.receive(OpenReducingDuct.java:28)
at cascading.flow.hadoop.stream.HadoopGroupGate.run(HadoopGroupGate.java:93)
at cascading.flow.hadoop.FlowReducer.reduce(FlowReducer.java:136)
at org.apache.hadoop.mapred.ReduceTask.runOldReducer(ReduceTask.java:444)
at org.apache.hadoop.mapred.ReduceTask.run(ReduceTask.java:392)
at org.apache.hadoop.mapred.LocalJobRunner$Job$ReduceTaskRunnable.run(LocalJobRunner.java:319)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:439)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
at java.lang.Thread.run(Thread.java:662)
2015-02-10 22:33:20,790 WARN flow.FlowStep (BaseFlowStep.java:logWarn(839)) - [test] hadoop job job_local766558076_0013 state at FAILED
2015-02-10 22:33:20,790 WARN flow.FlowStep (BaseFlowStep.java:logWarn(839)) - [test] failure info: NA
2015-02-10 22:33:20,791 WARN flow.FlowStep (BaseFlowStep.java:logWarn(839)) - [test] task completion events identify failed tasks
2015-02-10 22:33:20,791 WARN flow.FlowStep (BaseFlowStep.java:logWarn(839)) - [test] task completion events count: 0
2015-02-10 22:33:20,798 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] stopping all jobs
2015-02-10 22:33:20,799 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] stopping: (1/1) ...rtionsplatform/value/fail
2015-02-10 22:33:20,799 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] stopped all jobs
2015-02-10 22:33:20,800 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/appliedassertionsplatform/value/fail/_temporary
2015-02-10 22:33:20,800 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/appliedassertionsplatform/value/fail
2015-02-10 22:33:20,821 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(336)) - using default application jar, may cause class not found exceptions on the cluster
2015-02-10 22:33:20,821 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(225)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-mr1/2.6.3/9ae016e2b8d246b9c1de9168e715d9f1b971aa4a/cascading-hadoop2-mr1-2.6.3.jar
2015-02-10 22:33:20,831 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used
2015-02-10 22:33:20,834 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.job.tracker is deprecated. Instead, use mapreduce.jobtracker.address
2015-02-10 22:33:20,834 INFO Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1009)) - mapred.output.compress is deprecated. Instead, use mapreduce.output.fileoutputformat.compress
2015-02-10 22:33:20,839 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting
2015-02-10 22:33:20,840 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2015-02-10 22:33:20,840 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/appliedassertionsplatform/value/pass"]
2015-02-10 22:33:20,840 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] parallel execution is enabled: false
2015-02-10 22:33:20,840 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] starting jobs: 1
2015-02-10 22:33:20,840 INFO flow.Flow (BaseFlow.java:logInfo(1378)) - [test] allocating threads: 1
2015-02-10 22:33:20,841 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] starting step: (1/1) ...rtionsplatform/value/pass
2015-02-10 22:33:20,842 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 22:33:20,843 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Cannot initialize JVM Metrics with processName=JobTracker, sessionId= - already initialized
2015-02-10 22:33:20,869 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 22:33:20,888 INFO mapreduce.JobSubmitter (JobSubmitter.java:submitJobInternal(396)) - number of splits:1
2015-02-10 22:33:20,904 INFO mapreduce.JobSubmitter (JobSubmitter.java:printTokens(479)) - Submitting tokens for job: job_local1293894711_0014
2015-02-10 22:33:20,922 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity1293894711/.staging/job_local1293894711_0014/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 22:33:20,923 WARN conf.Configuration (Configuration.java:loadProperty(2358)) - file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/tmp/cascading/staging/teamcity1293894711/.staging/job_local1293894711_0014/job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 22:33:20,947 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2015-02-10 22:33:20,980 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_local1293894711_0014/job_local1293894711_0014.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval; Ignoring.
2015-02-10 22:33:20,982 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_local1293894711_0014/job_local1293894711_0014.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.attempts; Ignoring.
2015-02-10 22:33:20,982 INFO mapreduce.Job (Job.java:submit(1289)) - The url to track the job: http://localhost:8080/
2015-02-10 22:33:20,983 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] submitted hadoop job: job_local1293894711_0014
2015-02-10 22:33:20,983 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(471)) - OutputCommitter set in config null
2015-02-10 22:33:20,983 INFO flow.FlowStep (BaseFlowStep.java:logInfo(834)) - [test] tracking url: http://localhost:8080/
2015-02-10 22:33:20,983 INFO mapred.LocalJobRunner (LocalJobRunner.java:createOutputCommitter(489)) - OutputCommitter is org.apache.hadoop.mapred.FileOutputCommitter
2015-02-10 22:33:20,986 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for map tasks
2015-02-10 22:33:20,987 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(224)) - Starting task: attempt_local1293894711_0014_m_000000_0
2015-02-10 22:33:20,988 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 22:33:20,990 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 22:33:20,990 INFO mapred.MapTask (MapTask.java:updateJobWithSplit(462)) - Processing split: cascading.tap.hadoop.io.MultiInputSplit@272adac5
2015-02-10 22:33:20,991 INFO mapred.MapTask (MapTask.java:runOldMapper(416)) - numReduceTasks: 1
2015-02-10 22:33:20,991 INFO mapred.MapTask (MapTask.java:createSortingCollector(388)) - Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
2015-02-10 22:33:21,032 INFO mapred.MapTask (MapTask.java:setEquator(1182)) - (EQUATOR) 0 kvi 26214396(104857584)
2015-02-10 22:33:21,032 INFO mapred.MapTask (MapTask.java:init(975)) - mapreduce.task.io.sort.mb: 100
2015-02-10 22:33:21,032 INFO mapred.MapTask (MapTask.java:init(976)) - soft limit at 83886080
2015-02-10 22:33:21,032 INFO mapred.MapTask (MapTask.java:init(977)) - bufstart = 0; bufvoid = 104857600
2015-02-10 22:33:21,033 INFO mapred.MapTask (MapTask.java:init(978)) - kvstart = 26214396; length = 6553600
2015-02-10 22:33:21,034 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - cascading version: 2.6.3
2015-02-10 22:33:21,034 INFO hadoop.FlowMapper (FlowMapper.java:configure(72)) - child jvm opts: -Xmx200m
2015-02-10 22:33:21,045 INFO hadoop.FlowMapper (FlowMapper.java:configure(87)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/classes/test/data/apache.10.txt"]
2015-02-10 22:33:21,045 INFO hadoop.FlowMapper (FlowMapper.java:configure(90)) - sinking to: GroupBy(test)[by:[{1}:'method']]
2015-02-10 22:33:21,049 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) -
2015-02-10 22:33:21,049 INFO mapred.MapTask (MapTask.java:flush(1437)) - Starting flush of map output
2015-02-10 22:33:21,050 INFO mapred.MapTask (MapTask.java:flush(1455)) - Spilling map output
2015-02-10 22:33:21,050 INFO mapred.MapTask (MapTask.java:flush(1456)) - bufstart = 0; bufend = 693; bufvoid = 104857600
2015-02-10 22:33:21,050 INFO mapred.MapTask (MapTask.java:flush(1458)) - kvstart = 26214396(104857584); kvend = 26214372(104857488); length = 25/6553600
2015-02-10 22:33:21,053 INFO mapred.MapTask (MapTask.java:sortAndSpill(1641)) - Finished spill 0
2015-02-10 22:33:21,055 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1293894711_0014_m_000000_0 is done. And is in the process of committing
2015-02-10 22:33:21,058 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 22:33:21,058 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1293894711_0014_m_000000_0' done.
2015-02-10 22:33:21,058 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(249)) - Finishing task: attempt_local1293894711_0014_m_000000_0
2015-02-10 22:33:21,058 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - map task executor complete.
2015-02-10 22:33:21,059 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(448)) - Waiting for reduce tasks
2015-02-10 22:33:21,059 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(302)) - Starting task: attempt_local1293894711_0014_r_000000_0
2015-02-10 22:33:21,061 INFO mapred.Task (Task.java:initialize(581)) - Using ResourceCalculatorProcessTree : [ ]
2015-02-10 22:33:21,061 INFO mapred.ReduceTask (ReduceTask.java:run(362)) - Using ShuffleConsumerPlugin: org.apache.hadoop.mapreduce.task.reduce.Shuffle@24a075e6
2015-02-10 22:33:21,062 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:<init>(193)) - MergerManager: memoryLimit=493250144, maxSingleShuffleLimit=123312536, mergeThreshold=325545120, ioSortFactor=10, memToMemMergeOutputsThreshold=10
2015-02-10 22:33:21,063 INFO reduce.EventFetcher (EventFetcher.java:run(61)) - attempt_local1293894711_0014_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events
2015-02-10 22:33:21,065 INFO reduce.LocalFetcher (LocalFetcher.java:copyMapOutput(140)) - localfetcher#14 about to shuffle output of map attempt_local1293894711_0014_m_000000_0 decomp: 709 len: 713 to MEMORY
2015-02-10 22:33:21,066 INFO reduce.InMemoryMapOutput (InMemoryMapOutput.java:shuffle(100)) - Read 709 bytes from map-output for attempt_local1293894711_0014_m_000000_0
2015-02-10 22:33:21,066 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:closeInMemoryFile(307)) - closeInMemoryFile -> map-output of size: 709, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->709
2015-02-10 22:33:21,067 INFO reduce.EventFetcher (EventFetcher.java:run(76)) - EventFetcher is interrupted.. Returning
2015-02-10 22:33:21,068 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 22:33:21,068 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(667)) - finalMerge called with 1 in-memory map-outputs and 0 on-disk map-outputs
2015-02-10 22:33:21,072 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 22:33:21,072 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 697 bytes
2015-02-10 22:33:21,074 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(742)) - Merged 1 segments, 709 bytes to disk to satisfy reduce memory limit
2015-02-10 22:33:21,075 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(772)) - Merging 1 files, 713 bytes from disk
2015-02-10 22:33:21,075 INFO reduce.MergeManagerImpl (MergeManagerImpl.java:finalMerge(787)) - Merging 0 segments, 0 bytes from memory into reduce
2015-02-10 22:33:21,075 INFO mapred.Merger (Merger.java:merge(591)) - Merging 1 sorted segments
2015-02-10 22:33:21,076 INFO mapred.Merger (Merger.java:merge(690)) - Down to the last merge-pass, with 1 segments left of total size: 697 bytes
2015-02-10 22:33:21,078 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 22:33:21,078 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - cascading version: 2.6.3
2015-02-10 22:33:21,078 INFO hadoop.FlowReducer (FlowReducer.java:configure(79)) - child jvm opts: -Xmx200m
2015-02-10 22:33:21,088 INFO hadoop.FlowReducer (FlowReducer.java:configure(97)) - sourcing from: GroupBy(test)[by:[{1}:'method']]
2015-02-10 22:33:21,089 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/appliedassertionsplatform/value/pass"]
2015-02-10 22:33:21,100 INFO mapred.Task (Task.java:done(995)) - Task:attempt_local1293894711_0014_r_000000_0 is done. And is in the process of committing
2015-02-10 22:33:21,102 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - 1 / 1 copied.
2015-02-10 22:33:21,102 INFO mapred.Task (Task.java:commit(1156)) - Task attempt_local1293894711_0014_r_000000_0 is allowed to commit now
2015-02-10 22:33:21,103 INFO output.FileOutputCommitter (FileOutputCommitter.java:commitTask(439)) - Saved output of task 'attempt_local1293894711_0014_r_000000_0' to file:/opt/buildAgent-8.0.3/work/84ab5c9b70b89230/apache-2.4.x/build/test/output/hadoop2-mr1/appliedassertionsplatform/value/pass/_temporary/0/task_local1293894711_0014_r_000000
2015-02-10 22:33:21,105 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(591)) - reduce > reduce
2015-02-10 22:33:21,105 INFO mapred.Task (Task.java:sendDone(1115)) - Task 'attempt_local1293894711_0014_r_000000_0' done.
2015-02-10 22:33:21,105 INFO mapred.LocalJobRunner (LocalJobRunner.java:run(325)) - Finishing task: attempt_local1293894711_0014_r_000000_0
2015-02-10 22:33:21,105 INFO mapred.LocalJobRunner (LocalJobRunner.java:runTasks(456)) - reduce task executor complete.
2015-02-10 22:33:21,128 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/appliedassertionsplatform/value/pass/_temporary
2015-02-10 22:33:21,165 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(247)) - Total input paths to process : 1
2015-02-10 22:33:21,167 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/appliedassertionsplatform/value/pass