2013-11-20 13:16:40,522 INFO platform.PlatformRunner (PlatformRunner.java:getPlatformClassesFromClasspath(187)) - found 1 test platforms from classpath
2013-11-20 13:16:40,553 INFO platform.PlatformRunner (PlatformRunner.java:addPlatform(237)) - installing platform: hadoop
2013-11-20 13:16:40,554 INFO platform.PlatformRunner (PlatformRunner.java:addPlatform(238)) - running test: cascading.UnmodifiablePipesPlatformTest
2013-11-20 13:16:40,583 INFO hadoop.HadoopPlatform (HadoopPlatform.java:setUp(112)) - not using cluster
2013-11-20 13:16:40,979 INFO util.HadoopUtil (HadoopUtil.java:findMainClass(319)) - using default application jar, may cause class not found exceptions on the cluster
2013-11-20 13:16:40,981 INFO planner.HadoopPlanner (HadoopPlanner.java:initialize(203)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/artifacts-24/filestore/cascading/cascading-hadoop/2.2.0/jar/c7b52bd4c6da523ebde0a5d6eca2475123783db2/cascading-hadoop-2.2.0.jar
2013-11-20 13:16:40,994 INFO property.AppProps (AppProps.java:getAppID(162)) - using app.id: E649493FBC7F471181BFF7FD6621FB6D
2013-11-20 13:16:41,229 INFO util.Version (Version.java:printBanner(78)) - Concurrent, Inc - Cascading 2.2.0
2013-11-20 13:16:41,232 INFO flow.Flow (BaseFlow.java:logInfo(1306)) - [test] starting
2013-11-20 13:16:41,233 INFO flow.Flow (BaseFlow.java:logInfo(1306)) - [test] source: Hfs["TextDelimited[['lhs', 'rhs']]"]["/opt/buildAgent-8.0.3/work/d1f96f51023738a5/apache-1.1.x/build/classes/test/data/lhs.txt"]
2013-11-20 13:16:41,233 INFO flow.Flow (BaseFlow.java:logInfo(1306)) - [test] sink: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/d1f96f51023738a5/apache-1.1.x/build/test/output/hadoop/unmodifiablepipesplatform/simple"]
2013-11-20 13:16:41,234 INFO flow.Flow (BaseFlow.java:logInfo(1306)) - [test] parallel execution is enabled: false
2013-11-20 13:16:41,234 INFO flow.Flow (BaseFlow.java:logInfo(1306)) - [test] starting jobs: 2
2013-11-20 13:16:41,234 INFO flow.Flow (BaseFlow.java:logInfo(1306)) - [test] allocating threads: 1
2013-11-20 13:16:41,236 INFO flow.FlowStep (BaseFlowStep.java:logInfo(742)) - [test] starting step: (1/2)
2013-11-20 13:16:41,279 WARN util.NativeCodeLoader (NativeCodeLoader.java:<clinit>(52)) - Unable to load native-hadoop library for your platform... using builtin-java classes where applicable
2013-11-20 13:16:41,340 WARN snappy.LoadSnappy (LoadSnappy.java:<clinit>(46)) - Snappy native library not loaded
2013-11-20 13:16:41,346 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(199)) - Total input paths to process : 1
2013-11-20 13:16:41,565 INFO flow.FlowStep (BaseFlowStep.java:logInfo(742)) - [test] submitted hadoop job: job_local_0001
2013-11-20 13:16:41,629 INFO util.ProcessTree (ProcessTree.java:isSetsidSupported(63)) - setsid exited with exit code 0
2013-11-20 13:16:41,638 INFO mapred.Task (Task.java:initialize(534)) - Using ResourceCalculatorPlugin : org.apache.hadoop.util.LinuxResourceCalculatorPlugin@4145b02f
2013-11-20 13:16:41,646 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/opt/buildAgent-8.0.3/work/d1f96f51023738a5/apache-1.1.x/build/classes/test/data/lhs.txt
2013-11-20 13:16:41,653 INFO mapred.MapTask (MapTask.java:runOldMapper(425)) - numReduceTasks: 1
2013-11-20 13:16:41,660 INFO mapred.MapTask (MapTask.java:<init>(944)) - io.sort.mb = 100
2013-11-20 13:16:41,791 INFO mapred.MapTask (MapTask.java:<init>(956)) - data buffer = 79691776/99614720
2013-11-20 13:16:41,791 INFO mapred.MapTask (MapTask.java:<init>(957)) - record buffer = 262144/327680
2013-11-20 13:16:41,811 INFO hadoop.FlowMapper (FlowMapper.java:configure(70)) - cascading version: 2.2.0
2013-11-20 13:16:41,812 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - child jvm opts: -Xmx200m
2013-11-20 13:16:41,866 INFO hadoop.FlowMapper (FlowMapper.java:configure(86)) - sourcing from: Hfs["TextDelimited[['lhs', 'rhs']]"]["/opt/buildAgent-8.0.3/work/d1f96f51023738a5/apache-1.1.x/build/classes/test/data/lhs.txt"]
2013-11-20 13:16:41,867 INFO hadoop.FlowMapper (FlowMapper.java:configure(89)) - sinking to: GroupBy(test)[by:[{1}:'lhs']]
2013-11-20 13:16:41,881 INFO mapred.MapTask (MapTask.java:flush(1284)) - Starting flush of map output
2013-11-20 13:16:41,893 INFO mapred.MapTask (MapTask.java:sortAndSpill(1466)) - Finished spill 0
2013-11-20 13:16:41,898 INFO mapred.Task (Task.java:done(858)) - Task:attempt_local_0001_m_000000_0 is done. And is in the process of commiting
2013-11-20 13:16:41,902 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(323)) - file:/opt/buildAgent-8.0.3/work/d1f96f51023738a5/apache-1.1.x/build/classes/test/data/lhs.txt:0+52
2013-11-20 13:16:41,903 INFO mapred.Task (Task.java:sendDone(970)) - Task 'attempt_local_0001_m_000000_0' done.
2013-11-20 13:16:41,914 INFO mapred.Task (Task.java:initialize(534)) - Using ResourceCalculatorPlugin : org.apache.hadoop.util.LinuxResourceCalculatorPlugin@56ee20fe
2013-11-20 13:16:41,915 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(323)) -
2013-11-20 13:16:41,921 INFO mapred.Merger (Merger.java:merge(390)) - Merging 1 sorted segments
2013-11-20 13:16:41,927 INFO mapred.Merger (Merger.java:merge(473)) - Down to the last merge-pass, with 1 segments left of total size: 223 bytes
2013-11-20 13:16:41,928 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(323)) -
2013-11-20 13:16:41,930 INFO hadoop.FlowReducer (FlowReducer.java:configure(77)) - cascading version: 2.2.0
2013-11-20 13:16:41,931 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - child jvm opts: -Xmx200m
2013-11-20 13:16:41,949 INFO hadoop.FlowReducer (FlowReducer.java:configure(96)) - sourcing from: GroupBy(test)[by:[{1}:'lhs']]
2013-11-20 13:16:41,950 INFO hadoop.FlowReducer (FlowReducer.java:configure(99)) - sinking to: TempHfs["SequenceFile[['lhs', 'rhs']]"][6073737056/test/]
2013-11-20 13:16:41,973 INFO mapred.Task (Task.java:done(858)) - Task:attempt_local_0001_r_000000_0 is done. And is in the process of commiting
2013-11-20 13:16:41,974 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(323)) -
2013-11-20 13:16:41,975 INFO mapred.Task (Task.java:commit(1011)) - Task attempt_local_0001_r_000000_0 is allowed to commit now
2013-11-20 13:16:41,980 INFO mapred.FileOutputCommitter (FileOutputCommitter.java:commitTask(138)) - Saved output of task 'attempt_local_0001_r_000000_0' to file:/tmp/hadoop-teamcity/6073737056_test_21F464F0E99541D9B6D87750E1D708E4
2013-11-20 13:16:41,981 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(323)) - reduce > reduce
2013-11-20 13:16:41,982 INFO mapred.Task (Task.java:sendDone(970)) - Task 'attempt_local_0001_r_000000_0' done.
2013-11-20 13:16:41,992 INFO flow.FlowStep (BaseFlowStep.java:logInfo(742)) - [test] starting step: (2/2) ...iablepipesplatform/simple
2013-11-20 13:16:42,008 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(199)) - Total input paths to process : 1
2013-11-20 13:16:42,097 INFO flow.FlowStep (BaseFlowStep.java:logInfo(742)) - [test] submitted hadoop job: job_local_0002
2013-11-20 13:16:42,104 INFO mapred.Task (Task.java:initialize(534)) - Using ResourceCalculatorPlugin : org.apache.hadoop.util.LinuxResourceCalculatorPlugin@202264da
2013-11-20 13:16:42,107 INFO io.MultiInputSplit (MultiInputSplit.java:readFields(161)) - current split input path: file:/tmp/hadoop-teamcity/6073737056_test_21F464F0E99541D9B6D87750E1D708E4/part-00000
2013-11-20 13:16:42,115 INFO mapred.MapTask (MapTask.java:runOldMapper(425)) - numReduceTasks: 1
2013-11-20 13:16:42,116 INFO mapred.MapTask (MapTask.java:<init>(944)) - io.sort.mb = 100
2013-11-20 13:16:42,239 INFO mapred.MapTask (MapTask.java:<init>(956)) - data buffer = 79691776/99614720
2013-11-20 13:16:42,241 INFO mapred.MapTask (MapTask.java:<init>(957)) - record buffer = 262144/327680
2013-11-20 13:16:42,243 INFO hadoop.FlowMapper (FlowMapper.java:configure(70)) - cascading version: 2.2.0
2013-11-20 13:16:42,245 INFO hadoop.FlowMapper (FlowMapper.java:configure(71)) - child jvm opts: -Xmx200m
2013-11-20 13:16:42,258 INFO hadoop.FlowMapper (FlowMapper.java:configure(86)) - sourcing from: TempHfs["SequenceFile[['lhs', 'rhs']]"][6073737056/test/]
2013-11-20 13:16:42,259 INFO hadoop.FlowMapper (FlowMapper.java:configure(89)) - sinking to: GroupBy(test)[by:[{1}:'lhs']]
2013-11-20 13:16:42,261 INFO mapred.MapTask (MapTask.java:flush(1284)) - Starting flush of map output
2013-11-20 13:16:42,265 INFO mapred.MapTask (MapTask.java:sortAndSpill(1466)) - Finished spill 0
2013-11-20 13:16:42,268 INFO mapred.Task (Task.java:done(858)) - Task:attempt_local_0002_m_000000_0 is done. And is in the process of commiting
2013-11-20 13:16:42,269 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(323)) - file:/tmp/hadoop-teamcity/6073737056_test_21F464F0E99541D9B6D87750E1D708E4/part-00000:0+225
2013-11-20 13:16:42,270 INFO mapred.Task (Task.java:sendDone(970)) - Task 'attempt_local_0002_m_000000_0' done.
2013-11-20 13:16:42,276 INFO mapred.Task (Task.java:initialize(534)) - Using ResourceCalculatorPlugin : org.apache.hadoop.util.LinuxResourceCalculatorPlugin@70d9cbcb
2013-11-20 13:16:42,277 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(323)) -
2013-11-20 13:16:42,278 INFO mapred.Merger (Merger.java:merge(390)) - Merging 1 sorted segments
2013-11-20 13:16:42,279 INFO mapred.Merger (Merger.java:merge(473)) - Down to the last merge-pass, with 1 segments left of total size: 132 bytes
2013-11-20 13:16:42,280 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(323)) -
2013-11-20 13:16:42,281 INFO hadoop.FlowReducer (FlowReducer.java:configure(77)) - cascading version: 2.2.0
2013-11-20 13:16:42,282 INFO hadoop.FlowReducer (FlowReducer.java:configure(78)) - child jvm opts: -Xmx200m
2013-11-20 13:16:42,298 INFO hadoop.FlowReducer (FlowReducer.java:configure(96)) - sourcing from: GroupBy(test)[by:[{1}:'lhs']]
2013-11-20 13:16:42,300 INFO hadoop.FlowReducer (FlowReducer.java:configure(99)) - sinking to: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/d1f96f51023738a5/apache-1.1.x/build/test/output/hadoop/unmodifiablepipesplatform/simple"]
2013-11-20 13:16:42,310 INFO mapred.Task (Task.java:done(858)) - Task:attempt_local_0002_r_000000_0 is done. And is in the process of commiting
2013-11-20 13:16:42,311 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(323)) -
2013-11-20 13:16:42,311 INFO mapred.Task (Task.java:commit(1011)) - Task attempt_local_0002_r_000000_0 is allowed to commit now
2013-11-20 13:16:42,315 INFO mapred.FileOutputCommitter (FileOutputCommitter.java:commitTask(138)) - Saved output of task 'attempt_local_0002_r_000000_0' to file:/opt/buildAgent-8.0.3/work/d1f96f51023738a5/apache-1.1.x/build/test/output/hadoop/unmodifiablepipesplatform/simple
2013-11-20 13:16:42,316 INFO mapred.LocalJobRunner (LocalJobRunner.java:statusUpdate(323)) - reduce > reduce
2013-11-20 13:16:42,317 INFO mapred.Task (Task.java:sendDone(970)) - Task 'attempt_local_0002_r_000000_0' done.
2013-11-20 13:16:42,333 INFO util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(219)) - deleting temp path /opt/buildAgent-8.0.3/work/d1f96f51023738a5/apache-1.1.x/build/test/output/hadoop/unmodifiablepipesplatform/simple/_temporary
2013-11-20 13:16:42,354 INFO mapred.FileInputFormat (FileInputFormat.java:listStatus(199)) - Total input paths to process : 1
2013-11-20 13:16:42,357 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(209)) - copying to local /opt/buildAgent-8.0.3/work/d1f96f51023738a5/apache-1.1.x/build/test/output//hadoop/unmodifiablepipesplatform/simple