You are viewing a plain text version of this content. The canonical link for it is here.
Posted to mapreduce-dev@hadoop.apache.org by Apache Hudson Server <hu...@hudson.zones.apache.org> on 2009/08/24 20:17:35 UTC
Build failed in Hudson: Hadoop-Mapreduce-trunk #59
See http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/59/changes
Changes:
[tomwhite] MAPREDUCE-798. MRUnit should be able to test a succession of MapReduce passes. Contributed by Aaron Kimball.
[ddas] MAPREDUCE-807. Handles the AccessControlException during the deletion of mapred.system.dir in the JobTracker. The JobTracker will bail out if it encounters such an exception. Contributed by Amar Kamat.
[ddas] MAPREDUCE-767. Continuation of the patch that got committe earlier. This commit fixes a bug in StreamJob.java to do with handling -debug option.
[cdouglas] MAPREDUCE-355. Update mapred.join package to use the new API. Contributed by Amareshwari Sriramadasu.
[cdouglas] MAPREDUCE-479. Provide full task id to map output servlet rather than the
reduce id, only. Contributed by Jiaqi Tan
------------------------------------------
[...truncated 134996 lines...]
[junit] 2009-08-24 18:16:22,457 INFO mapred.JvmManager (JvmManager.java:<init>(396)) - In JvmRunner constructed JVM ID: jvm_20090824181526086_0002_m_-321824080
[junit] 2009-08-24 18:16:22,458 INFO mapred.JvmManager (JvmManager.java:spawnNewJvm(364)) - JVM Runner jvm_20090824181526086_0002_m_-321824080 spawned.
[junit] 2009-08-24 18:16:22,539 INFO mapred.JobClient (JobClient.java:monitorAndPrintJob(1371)) - Task Id : attempt_20090824181526086_0002_r_000000_0, Status : SUCCEEDED
[junit] attempt_20090824181526086_0002_r_000000_0: 2009-08-24 18:16:11,247 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Initializing JVM Metrics with processName=SHUFFLE, sessionId=
[junit] attempt_20090824181526086_0002_r_000000_0: 2009-08-24 18:16:11,372 INFO mapred.ReduceTask (ReduceTask.java:<init>(1011)) - ShuffleRamManager: MemoryLimit=141387360, MaxSingleShuffleLimit=35346840
[junit] attempt_20090824181526086_0002_r_000000_0: 2009-08-24 18:16:11,379 INFO mapred.ReduceTask (ReduceTask.java:run(2584)) - attempt_20090824181526086_0002_r_000000_0 Thread started: Thread for merging in memory files
[junit] attempt_20090824181526086_0002_r_000000_0: 2009-08-24 18:16:11,379 INFO mapred.ReduceTask (ReduceTask.java:run(2485)) - attempt_20090824181526086_0002_r_000000_0 Thread started: Thread for merging on-disk files
[junit] attempt_20090824181526086_0002_r_000000_0: 2009-08-24 18:16:11,379 INFO mapred.ReduceTask (ReduceTask.java:run(2490)) - attempt_20090824181526086_0002_r_000000_0 Thread waiting: Thread for merging on-disk files
[junit] attempt_20090824181526086_0002_r_000000_0: 2009-08-24 18:16:11,387 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(1892)) - attempt_20090824181526086_0002_r_000000_0 Need another 3 map output(s) where 0 is already in progress
[junit] attempt_20090824181526086_0002_r_000000_0: 2009-08-24 18:16:11,387 INFO mapred.ReduceTask (ReduceTask.java:run(2686)) - attempt_20090824181526086_0002_r_000000_0 Thread started: Thread for polling Map Completion Events
[junit] attempt_20090824181526086_0002_r_000000_0: 2009-08-24 18:16:11,387 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2005)) - attempt_20090824181526086_0002_r_000000_0 Scheduled 0 outputs (0 slow hosts and0 dup hosts)
[junit] attempt_20090824181526086_0002_r_000000_0: 2009-08-24 18:16:11,393 INFO mapred.ReduceTask (ReduceTask.java:run(2692)) - attempt_20090824181526086_0002_r_000000_0: Got 2 new map-outputs
[junit] attempt_20090824181526086_0002_r_000000_0: 2009-08-24 18:16:15,397 INFO mapred.ReduceTask (ReduceTask.java:run(2692)) - attempt_20090824181526086_0002_r_000000_0: Got 1 new map-outputs
[junit] attempt_20090824181526086_0002_r_000000_0: 2009-08-24 18:16:16,388 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2005)) - attempt_20090824181526086_0002_r_000000_0 Scheduled 1 outputs (0 slow hosts and0 dup hosts)
[junit] attempt_20090824181526086_0002_r_000000_0: 2009-08-24 18:16:16,429 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1423)) - header: attempt_20090824181526086_0002_m_000000_0, compressed len: 11, decompressed len: 7
[junit] attempt_20090824181526086_0002_r_000000_0: 2009-08-24 18:16:16,429 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1437)) - Shuffling 7 bytes (11 raw bytes) into RAM from attempt_20090824181526086_0002_m_000000_0
[junit] attempt_20090824181526086_0002_r_000000_0: 2009-08-24 18:16:16,434 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1566)) - Read 7 bytes from map-output for attempt_20090824181526086_0002_m_000000_0
[junit] attempt_20090824181526086_0002_r_000000_0: 2009-08-24 18:16:16,435 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1625)) - Rec #1 from attempt_20090824181526086_0002_m_000000_0 -> (2, 1) from localhost
[junit] attempt_20090824181526086_0002_r_000000_0: 2009-08-24 18:16:16,436 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2005)) - attempt_20090824181526086_0002_r_000000_0 Scheduled 1 outputs (0 slow hosts and0 dup hosts)
[junit] attempt_20090824181526086_0002_r_000000_0: 2009-08-24 18:16:16,439 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1423)) - header: attempt_20090824181526086_0002_m_000001_0, compressed len: 11, decompressed len: 7
[junit] attempt_20090824181526086_0002_r_000000_0: 2009-08-24 18:16:16,440 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1437)) - Shuffling 7 bytes (11 raw bytes) into RAM from attempt_20090824181526086_0002_m_000001_0
[junit] attempt_20090824181526086_0002_r_000000_0: 2009-08-24 18:16:16,440 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1566)) - Read 7 bytes from map-output for attempt_20090824181526086_0002_m_000001_0
[junit] attempt_20090824181526086_0002_r_000000_0: 2009-08-24 18:16:16,440 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1625)) - Rec #1 from attempt_20090824181526086_0002_m_000001_0 -> (2, 1) from localhost
[junit] attempt_20090824181526086_0002_r_000000_0: 2009-08-24 18:16:16,441 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2005)) - attempt_20090824181526086_0002_r_000000_0 Scheduled 1 outputs (0 slow hosts and0 dup hosts)
[junit] attempt_20090824181526086_0002_r_000000_0: 2009-08-24 18:16:16,445 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1423)) - header: attempt_20090824181526086_0002_m_000002_0, compressed len: 11, decompressed len: 7
[junit] attempt_20090824181526086_0002_r_000000_0: 2009-08-24 18:16:16,445 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1437)) - Shuffling 7 bytes (11 raw bytes) into RAM from attempt_20090824181526086_0002_m_000002_0
[junit] attempt_20090824181526086_0002_r_000000_0: 2009-08-24 18:16:16,445 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1566)) - Read 7 bytes from map-output for attempt_20090824181526086_0002_m_000002_0
[junit] attempt_20090824181526086_0002_r_000000_0: 2009-08-24 18:16:16,445 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1625)) - Rec #1 from attempt_20090824181526086_0002_m_000002_0 -> (2, 1) from localhost
[junit] attempt_20090824181526086_0002_r_000000_0: 2009-08-24 18:16:17,399 INFO mapred.ReduceTask (ReduceTask.java:run(2710)) - GetMapEventsThread exiting
[junit] attempt_20090824181526086_0002_r_000000_0: 2009-08-24 18:16:17,399 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2203)) - getMapsEventsThread joined.
[junit] attempt_20090824181526086_0002_r_000000_0: 2009-08-24 18:16:17,399 INFO mapred.ReduceTask (ReduceTask.java:close(1117)) - Closed ram manager
[junit] attempt_20090824181526086_0002_r_000000_0: 2009-08-24 18:16:17,400 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2231)) - Interleaved on-disk merge complete: 0 files left.
[junit] attempt_20090824181526086_0002_r_000000_0: 2009-08-24 18:16:17,400 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2236)) - In-memory merge complete: 3 files left.
[junit] attempt_20090824181526086_0002_r_000000_0: 2009-08-24 18:16:17,423 INFO mapred.Merger (Merger.java:merge(469)) - Merging 3 sorted segments
[junit] attempt_20090824181526086_0002_r_000000_0: 2009-08-24 18:16:17,424 INFO mapred.Merger (Merger.java:merge(568)) - Down to the last merge-pass, with 3 segments left of total size: 9 bytes
[junit] attempt_20090824181526086_0002_r_000000_0: 2009-08-24 18:16:17,438 INFO mapred.ReduceTask (ReduceTask.java:createKVIterator(2349)) - Merged 3 segments, 21 bytes to disk to satisfy reduce memory limit
[junit] attempt_20090824181526086_0002_r_000000_0: 2009-08-24 18:16:17,438 INFO mapred.ReduceTask (ReduceTask.java:createKVIterator(2369)) - Merging 1 files, 21 bytes from disk
[junit] attempt_20090824181526086_0002_r_000000_0: 2009-08-24 18:16:17,439 INFO mapred.ReduceTask (ReduceTask.java:createKVIterator(2383)) - Merging 0 segments, 0 bytes from memory into reduce
[junit] attempt_20090824181526086_0002_r_000000_0: 2009-08-24 18:16:17,439 INFO mapred.Merger (Merger.java:merge(469)) - Merging 1 sorted segments
[junit] attempt_20090824181526086_0002_r_000000_0: 2009-08-24 18:16:17,443 INFO mapred.Merger (Merger.java:merge(568)) - Down to the last merge-pass, with 1 segments left of total size: 13 bytes
[junit] attempt_20090824181526086_0002_r_000000_0: 2009-08-24 18:16:17,647 INFO mapred.Task (Task.java:done(643)) - Task:attempt_20090824181526086_0002_r_000000_0 is done. And is in the process of commiting
[junit] attempt_20090824181526086_0002_r_000000_0: 2009-08-24 18:16:19,656 INFO mapred.Task (Task.java:commit(755)) - Task attempt_20090824181526086_0002_r_000000_0 is allowed to commit now
[junit] attempt_20090824181526086_0002_r_000000_0: 2009-08-24 18:16:19,742 INFO mapred.FileOutputCommitter (FileOutputCommitter.java:commitTask(92)) - Saved output of task 'attempt_20090824181526086_0002_r_000000_0' to hdfs://localhost:54853/user/hudson/mapout
[junit] attempt_20090824181526086_0002_r_000000_0: 2009-08-24 18:16:19,745 INFO mapred.Task (Task.java:sendDone(714)) - Task 'attempt_20090824181526086_0002_r_000000_0' done.
[junit] 2009-08-24 18:16:22,893 INFO mapred.TaskTracker (TaskTracker.java:getTask(2820)) - JVM with ID: jvm_20090824181526086_0002_m_-321824080 given task: attempt_20090824181526086_0002_m_000003_0
[junit] 2009-08-24 18:16:23,260 INFO mapred.TaskTracker (TaskTracker.java:reportProgress(2267)) - attempt_20090824181526086_0002_m_000003_0 0.0%
[junit] 2009-08-24 18:16:23,279 INFO FSNamesystem.audit (FSNamesystem.java:logAuditEvent(114)) - ugi=hudson,hudson ip=/127.0.0.1 cmd=delete src=/user/hudson/mapout/_temporary dst=null perm=null
[junit] 2009-08-24 18:16:23,283 INFO mapred.TaskTracker (TaskTracker.java:reportProgress(2267)) - attempt_20090824181526086_0002_m_000003_0 0.0% cleanup > map
[junit] 2009-08-24 18:16:23,284 INFO mapred.TaskTracker (TaskTracker.java:reportDone(2348)) - Task attempt_20090824181526086_0002_m_000003_0 is done.
[junit] 2009-08-24 18:16:23,284 INFO mapred.TaskTracker (TaskTracker.java:reportDone(2349)) - reported output size for attempt_20090824181526086_0002_m_000003_0 was 0
[junit] 2009-08-24 18:16:23,284 INFO mapred.TaskTracker (TaskTracker.java:addFreeSlots(1923)) - addFreeSlot : current free slots : 2
[junit] 2009-08-24 18:16:23,479 WARN util.ProcessTree (ProcessTree.java:terminateProcessGroup(136)) - Error executing shell command org.apache.hadoop.util.Shell$ExitCodeException: kill: No such process
[junit]
[junit] 2009-08-24 18:16:23,479 INFO util.ProcessTree (ProcessTree.java:terminateProcessGroup(138)) - Killing all processes in the process group 26429 with SIGTERM. Exit code 1
[junit] 2009-08-24 18:16:23,545 INFO mapred.JobClient (JobClient.java:monitorAndPrintJob(1322)) - map 100% reduce 100%
[junit] 2009-08-24 18:16:24,847 INFO mapred.JvmManager (JvmManager.java:runChild(423)) - JVM : jvm_20090824181526086_0002_r_543722469 exited with exit code 0. Number of tasks it ran: 1
[junit] 2009-08-24 18:16:25,411 INFO mapred.TaskTracker (TaskTracker.java:tryToGetOutputSize(1875)) - org.apache.hadoop.util.DiskChecker$DiskErrorException: Could not find output/file.out in any of the configured local directories
[junit] 2009-08-24 18:16:25,413 INFO mapred.JobInProgress (JobInProgress.java:completedTask(2450)) - Task 'attempt_20090824181526086_0002_m_000003_0' has completed task_20090824181526086_0002_m_000003 successfully.
[junit] 2009-08-24 18:16:25,414 INFO mapred.JobInProgress (JobInProgress.java:jobComplete(2616)) - Job job_20090824181526086_0002 has completed successfully.
[junit] 2009-08-24 18:16:25,414 INFO mapred.JobInProgress$JobSummary (JobInProgress.java:logJobSummary(3314)) - jobId=job_20090824181526086_0002,submitTime=1251137763445,launchTime=1251137763585,finishTime=1251137785414,numMaps=3,numSlotsPerMap=1,numReduces=1,numSlotsPerReduce=1,user=hudson,queue=default,status=SUCCEEDED,mapSlotSeconds=5,reduceSlotsSeconds=9,clusterMapCapacity=4,clusterReduceCapacity=4
[junit] 2009-08-24 18:16:25,418 INFO hdfs.StateChange (FSNamesystem.java:allocateBlock(1303)) - BLOCK* NameSystem.allocateBlock: /user/hudson/mapout/_logs/history/localhost_1251137726117_job_20090824181526086_0002_hudson_NA. blk_-7496727665384223842_1015
[junit] 2009-08-24 18:16:25,419 INFO datanode.DataNode (DataXceiver.java:opWriteBlock(222)) - Receiving block blk_-7496727665384223842_1015 src: /127.0.0.1:33758 dest: /127.0.0.1:48958
[junit] 2009-08-24 18:16:25,420 INFO datanode.DataNode (DataXceiver.java:opWriteBlock(222)) - Receiving block blk_-7496727665384223842_1015 src: /127.0.0.1:35801 dest: /127.0.0.1:45705
[junit] 2009-08-24 18:16:25,423 INFO DataNode.clienttrace (BlockReceiver.java:lastDataNodeRun(822)) - src: /127.0.0.1:35801, dest: /127.0.0.1:45705, bytes: 12041, op: HDFS_WRITE, cliID: DFSClient_1874834255, offset: 0, srvID: DS-841980697-67.195.138.9-45705-1251137725256, blockid: blk_-7496727665384223842_1015, duration: 2093653
[junit] 2009-08-24 18:16:25,424 INFO hdfs.StateChange (BlockManager.java:addStoredBlock(950)) - BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:45705 is added to blk_-7496727665384223842_1015 size 12041
[junit] 2009-08-24 18:16:25,424 INFO datanode.DataNode (BlockReceiver.java:lastDataNodeRun(853)) - PacketResponder 0 for block blk_-7496727665384223842_1015 terminating
[junit] 2009-08-24 18:16:25,425 INFO DataNode.clienttrace (BlockReceiver.java:run(955)) - src: /127.0.0.1:33758, dest: /127.0.0.1:48958, bytes: 12041, op: HDFS_WRITE, cliID: DFSClient_1874834255, offset: 0, srvID: DS-1727440281-67.195.138.9-48958-1251137725884, blockid: blk_-7496727665384223842_1015, duration: 3406255
[junit] 2009-08-24 18:16:25,425 INFO datanode.DataNode (BlockReceiver.java:run(1025)) - PacketResponder 1 for block blk_-7496727665384223842_1015 terminating
[junit] 2009-08-24 18:16:25,425 INFO hdfs.StateChange (BlockManager.java:addStoredBlock(950)) - BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:48958 is added to blk_-7496727665384223842_1015 size 12041
[junit] 2009-08-24 18:16:25,468 INFO hdfs.StateChange (FSNamesystem.java:completeFileInternal(1269)) - DIR* NameSystem.completeFile: file /user/hudson/mapout/_logs/history/localhost_1251137726117_job_20090824181526086_0002_hudson_NA is closed by DFSClient_1874834255
[junit] 2009-08-24 18:16:25,468 INFO namenode.FSNamesystem (FSEditLog.java:printStatistics(884)) - Number of transactions: 87 Total time for transactions(ms): 3Number of transactions batched in Syncs: 5 Number of syncs: 61 SyncTimes(ms): 577 544
[junit] 2009-08-24 18:16:25,512 INFO mapred.JobHistory (JobHistory.java:run(217)) - Moving http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/logs/history/localhost_1251137726117_job_20090824181526086_0002_hudson_NA to http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/logs/history/done
[junit] 2009-08-24 18:16:25,513 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2336)) - Removed completed task 'attempt_20090824181526086_0002_m_000000_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:43529'
[junit] 2009-08-24 18:16:25,513 INFO hdfs.StateChange (BlockManager.java:addToInvalidates(363)) - BLOCK* NameSystem.addToInvalidates: blk_426007954043809034 is added to invalidSet of 127.0.0.1:48958
[junit] 2009-08-24 18:16:25,513 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2336)) - Removed completed task 'attempt_20090824181526086_0002_m_000001_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:43529'
[junit] 2009-08-24 18:16:25,513 INFO hdfs.StateChange (BlockManager.java:addToInvalidates(363)) - BLOCK* NameSystem.addToInvalidates: blk_426007954043809034 is added to invalidSet of 127.0.0.1:45705
[junit] 2009-08-24 18:16:25,514 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2336)) - Removed completed task 'attempt_20090824181526086_0002_m_000003_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:43529'
[junit] 2009-08-24 18:16:25,514 INFO hdfs.StateChange (BlockManager.java:addToInvalidates(363)) - BLOCK* NameSystem.addToInvalidates: blk_-237279011392033868 is added to invalidSet of 127.0.0.1:45705
[junit] 2009-08-24 18:16:25,514 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2336)) - Removed completed task 'attempt_20090824181526086_0002_m_000004_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:43529'
[junit] 2009-08-24 18:16:25,514 INFO hdfs.StateChange (BlockManager.java:addToInvalidates(363)) - BLOCK* NameSystem.addToInvalidates: blk_-237279011392033868 is added to invalidSet of 127.0.0.1:48958
[junit] 2009-08-24 18:16:25,515 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2336)) - Removed completed task 'attempt_20090824181526086_0002_r_000000_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:43529'
[junit] 2009-08-24 18:16:25,515 INFO mapred.TaskTracker (TaskTracker.java:purgeJob(1672)) - Received 'KillJobAction' for job: job_20090824181526086_0002
[junit] 2009-08-24 18:16:25,516 INFO mapred.TaskRunner (MapTaskRunner.java:close(44)) - attempt_20090824181526086_0002_m_000001_0 done; removing files.
[junit] 2009-08-24 18:16:25,516 INFO mapred.TaskRunner (MapTaskRunner.java:close(44)) - attempt_20090824181526086_0002_m_000000_0 done; removing files.
[junit] 2009-08-24 18:16:25,517 INFO mapred.TaskRunner (MapTaskRunner.java:close(44)) - attempt_20090824181526086_0002_m_000003_0 done; removing files.
[junit] 2009-08-24 18:16:25,517 INFO mapred.IndexCache (IndexCache.java:removeMap(140)) - Map ID attempt_20090824181526086_0002_m_000003_0 not found in cache
[junit] 2009-08-24 18:16:25,531 INFO FSNamesystem.audit (FSNamesystem.java:logAuditEvent(114)) - ugi=hudson,hudson ip=/127.0.0.1 cmd=delete src=/tmp/hadoop-hudson/mapred/system/job_20090824181526086_0002 dst=null perm=null
[junit] 2009-08-24 18:16:25,550 INFO mapred.JobClient (JobClient.java:monitorAndPrintJob(1371)) - Task Id : attempt_20090824181526086_0002_m_000003_0, Status : SUCCEEDED
[junit] attempt_20090824181526086_0002_m_000003_0: 2009-08-24 18:16:23,140 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Initializing JVM Metrics with processName=MAP, sessionId=
[junit] attempt_20090824181526086_0002_m_000003_0: 2009-08-24 18:16:23,279 INFO mapred.Task (Task.java:done(643)) - Task:attempt_20090824181526086_0002_m_000003_0 is done. And is in the process of commiting
[junit] attempt_20090824181526086_0002_m_000003_0: 2009-08-24 18:16:23,284 INFO mapred.Task (Task.java:sendDone(714)) - Task 'attempt_20090824181526086_0002_m_000003_0' done.
[junit] 2009-08-24 18:16:25,553 INFO mapred.JobHistory (JobHistory.java:run(217)) - Moving http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/logs/history/localhost_1251137726117_job_20090824181526086_0002_conf.xml to http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/logs/history/done
[junit] 2009-08-24 18:16:25,562 INFO mapred.JobClient (JobClient.java:monitorAndPrintJob(1377)) - Job complete: job_20090824181526086_0002
[junit] 2009-08-24 18:16:25,566 INFO mapred.JobClient (Counters.java:log(534)) - Counters: 22
[junit] 2009-08-24 18:16:25,566 INFO mapred.JobClient (Counters.java:log(536)) - Job Counters
[junit] 2009-08-24 18:16:25,566 INFO mapred.JobClient (Counters.java:log(538)) - Launched reduce tasks=1
[junit] 2009-08-24 18:16:25,566 INFO mapred.JobClient (Counters.java:log(538)) - SLOTS_MILLIS_MAPS=5512
[junit] 2009-08-24 18:16:25,566 INFO mapred.JobClient (Counters.java:log(538)) - Total time spent by all reduces waiting after reserving slots (ms)=0
[junit] 2009-08-24 18:16:25,566 INFO mapred.JobClient (Counters.java:log(538)) - Total time spent by all maps waiting after reserving slots (ms)=0
[junit] 2009-08-24 18:16:25,567 INFO mapred.JobClient (Counters.java:log(538)) - Rack-local map tasks=3
[junit] 2009-08-24 18:16:25,567 INFO mapred.JobClient (Counters.java:log(538)) - Launched map tasks=3
[junit] 2009-08-24 18:16:25,567 INFO mapred.JobClient (Counters.java:log(538)) - SLOTS_MILLIS_REDUCES=9324
[junit] 2009-08-24 18:16:25,567 INFO mapred.JobClient (Counters.java:log(536)) - FileInputFormatCounters
[junit] 2009-08-24 18:16:25,567 INFO mapred.JobClient (Counters.java:log(538)) - BYTES_READ=3
[junit] 2009-08-24 18:16:25,567 INFO mapred.JobClient (Counters.java:log(536)) - FileSystemCounters
[junit] 2009-08-24 18:16:25,567 INFO mapred.JobClient (Counters.java:log(538)) - FILE_BYTES_READ=21
[junit] 2009-08-24 18:16:25,568 INFO mapred.JobClient (Counters.java:log(538)) - HDFS_BYTES_READ=828
[junit] 2009-08-24 18:16:25,568 INFO mapred.JobClient (Counters.java:log(538)) - FILE_BYTES_WRITTEN=150
[junit] 2009-08-24 18:16:25,568 INFO mapred.JobClient (Counters.java:log(538)) - HDFS_BYTES_WRITTEN=6
[junit] 2009-08-24 18:16:25,568 INFO mapred.JobClient (Counters.java:log(536)) - Map-Reduce Framework
[junit] 2009-08-24 18:16:25,568 INFO mapred.JobClient (Counters.java:log(538)) - Reduce input groups=3
[junit] 2009-08-24 18:16:25,568 INFO mapred.JobClient (Counters.java:log(538)) - Combine output records=0
[junit] 2009-08-24 18:16:25,569 INFO mapred.JobClient (Counters.java:log(538)) - Map input records=3
[junit] 2009-08-24 18:16:25,569 INFO mapred.JobClient (Counters.java:log(538)) - Reduce shuffle bytes=22
[junit] 2009-08-24 18:16:25,569 INFO mapred.JobClient (Counters.java:log(538)) - Reduce output records=3
[junit] 2009-08-24 18:16:25,569 INFO mapred.JobClient (Counters.java:log(538)) - Spilled Records=6
[junit] 2009-08-24 18:16:25,569 INFO mapred.JobClient (Counters.java:log(538)) - Map output bytes=9
[junit] 2009-08-24 18:16:25,569 INFO mapred.JobClient (Counters.java:log(538)) - Combine input records=0
[junit] 2009-08-24 18:16:25,569 INFO mapred.JobClient (Counters.java:log(538)) - Map output records=3
[junit] 2009-08-24 18:16:25,570 INFO mapred.JobClient (Counters.java:log(538)) - Reduce input records=3
[junit] 2009-08-24 18:16:25,581 INFO FSNamesystem.audit (FSNamesystem.java:logAuditEvent(114)) - ugi=hudson,hudson ip=/127.0.0.1 cmd=listStatus src=/user/hudson/mapout dst=null perm=null
[junit] Found 2 items
[junit] drwxr-xr-x - hudson supergroup 0 2009-08-24 18:16 /user/hudson/mapout/_logs
[junit] -rw-r--r-- 3 hudson supergroup 6 2009-08-24 18:16 /user/hudson/mapout/part-00000
[junit] 2009-08-24 18:16:25,584 INFO FSNamesystem.audit (FSNamesystem.java:logAuditEvent(114)) - ugi=hudson,hudson ip=/127.0.0.1 cmd=listStatus src=/user/hudson/mapout dst=null perm=null
[junit] 2009-08-24 18:16:25,586 INFO FSNamesystem.audit (FSNamesystem.java:logAuditEvent(114)) - ugi=hudson,hudson ip=/127.0.0.1 cmd=open src=/user/hudson/mapout/part-00000 dst=null perm=null
[junit] 2009-08-24 18:16:25,588 INFO DataNode.clienttrace (BlockSender.java:sendBlock(417)) - src: /127.0.0.1:45705, dest: /127.0.0.1:35802, bytes: 10, op: HDFS_READ, cliID: DFSClient_1874834255, offset: 0, srvID: DS-841980697-67.195.138.9-45705-1251137725256, blockid: blk_-2940939254476229949_1015, duration: 211845
[junit] 2009-08-24 18:16:25,588 INFO mapred.MiniMRCluster (MiniMRCluster.java:waitTaskTrackers(306)) - Waiting for task tracker tracker_host0.foo.com:localhost/127.0.0.1:39700 to be idle.
[junit] 2009-08-24 18:16:25,589 INFO mapred.JobHistory (JobHistory.java:cleanupJob(1057)) - Deleting localized job conf at http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/logs/job_20090824181526086_0002_conf.xml
[junit] 2009-08-24 18:16:26,304 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2336)) - Removed completed task 'attempt_20090824181526086_0002_m_000002_0' from 'tracker_host0.foo.com:localhost/127.0.0.1:39700'
[junit] 2009-08-24 18:16:26,305 INFO mapred.TaskTracker (TaskTracker.java:purgeJob(1672)) - Received 'KillJobAction' for job: job_20090824181526086_0002
[junit] 2009-08-24 18:16:26,306 INFO mapred.TaskRunner (MapTaskRunner.java:close(44)) - attempt_20090824181526086_0002_m_000002_0 done; removing files.
[junit] 2009-08-24 18:16:26,589 INFO mapred.TaskTracker (TaskTracker.java:run(682)) - Shutting down: Map-events fetcher for all reduce tasks on tracker_host0.foo.com:localhost/127.0.0.1:39700
[junit] 2009-08-24 18:16:26,590 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 39700
[junit] 2009-08-24 18:16:26,590 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 39700: exiting
[junit] 2009-08-24 18:16:26,590 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 39700: exiting
[junit] 2009-08-24 18:16:26,590 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 3 on 39700: exiting
[junit] 2009-08-24 18:16:26,592 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 39700: exiting
[junit] 2009-08-24 18:16:26,592 INFO mapred.TaskTracker (TaskTracker.java:shutdown(1150)) - Shutting down StatusHttpServer
[junit] 2009-08-24 18:16:26,591 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
[junit] 2009-08-24 18:16:26,591 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 39700
[junit] 2009-08-24 18:16:26,596 INFO mapred.TaskTracker (TaskTracker.java:offerService(1440)) - Interrupted. Closing down.
[junit] 2009-08-24 18:16:26,596 INFO mapred.TaskTracker (TaskTracker.java:run(682)) - Shutting down: Map-events fetcher for all reduce tasks on tracker_host1.foo.com:localhost/127.0.0.1:43529
[junit] 2009-08-24 18:16:26,597 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 43529
[junit] 2009-08-24 18:16:26,597 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 43529: exiting
[junit] 2009-08-24 18:16:26,597 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 43529: exiting
[junit] 2009-08-24 18:16:26,598 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 3 on 43529: exiting
[junit] 2009-08-24 18:16:26,598 INFO mapred.TaskTracker (TaskTracker.java:shutdown(1150)) - Shutting down StatusHttpServer
[junit] 2009-08-24 18:16:26,598 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
[junit] 2009-08-24 18:16:26,598 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 43529
[junit] 2009-08-24 18:16:26,598 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 43529: exiting
[junit] 2009-08-24 18:16:26,601 INFO mapred.TaskTracker (TaskTracker.java:offerService(1440)) - Interrupted. Closing down.
[junit] 2009-08-24 18:16:26,602 INFO mapred.JobTracker (JobTracker.java:close(2163)) - Stopping infoServer
[junit] 2009-08-24 18:16:26,705 INFO mapred.JobTracker (JobTracker.java:close(2171)) - Stopping interTrackerServer
[junit] 2009-08-24 18:16:26,705 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 49361
[junit] 2009-08-24 18:16:26,706 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 49361: exiting
[junit] 2009-08-24 18:16:26,706 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
[junit] 2009-08-24 18:16:26,706 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 9 on 49361: exiting
[junit] 2009-08-24 18:16:26,706 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 49361
[junit] 2009-08-24 18:16:26,706 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 6 on 49361: exiting
[junit] 2009-08-24 18:16:26,706 INFO mapred.JobTracker (JobTracker.java:offerService(2158)) - Stopped interTrackerServer
[junit] 2009-08-24 18:16:26,706 INFO mapred.JobTracker (JobTracker.java:stopExpireTrackersThread(2205)) - Stopping expireTrackers
[junit] 2009-08-24 18:16:26,706 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 7 on 49361: exiting
[junit] 2009-08-24 18:16:26,706 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 8 on 49361: exiting
[junit] 2009-08-24 18:16:26,706 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 49361: exiting
[junit] 2009-08-24 18:16:26,706 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 5 on 49361: exiting
[junit] 2009-08-24 18:16:26,706 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 4 on 49361: exiting
[junit] 2009-08-24 18:16:26,708 INFO mapred.EagerTaskInitializationListener (EagerTaskInitializationListener.java:terminate(106)) - Stopping Job Init Manager thread
[junit] 2009-08-24 18:16:26,706 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 3 on 49361: exiting
[junit] 2009-08-24 18:16:26,706 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 49361: exiting
[junit] 2009-08-24 18:16:26,709 INFO mapred.EagerTaskInitializationListener (EagerTaskInitializationListener.java:run(60)) - JobInitManagerThread interrupted.
[junit] 2009-08-24 18:16:26,711 INFO mapred.EagerTaskInitializationListener (EagerTaskInitializationListener.java:run(64)) - Shutting down thread pool
[junit] 2009-08-24 18:16:26,712 INFO mapred.JobTracker (JobTracker.java:close(2181)) - Stopping expireLaunchingTasks
[junit] 2009-08-24 18:16:26,713 INFO mapred.JobTracker (JobTracker.java:close(2199)) - stopped all jobtracker services
[junit] Shutting down the Mini HDFS Cluster
[junit] Shutting down DataNode 1
[junit] 2009-08-24 18:16:26,815 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 36557
[junit] 2009-08-24 18:16:26,815 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 36557: exiting
[junit] 2009-08-24 18:16:26,815 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 36557: exiting
[junit] 2009-08-24 18:16:26,816 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
[junit] 2009-08-24 18:16:26,816 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 36557: exiting
[junit] 2009-08-24 18:16:26,815 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 36557
[junit] 2009-08-24 18:16:26,816 INFO datanode.DataNode (DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads is 1
[junit] 2009-08-24 18:16:26,817 WARN datanode.DataNode (DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:48958, storageID=DS-1727440281-67.195.138.9-48958-1251137725884, infoPort=41425, ipcPort=36557):DataXceiveServer: java.nio.channels.AsynchronousCloseException
[junit] at java.nio.channels.spi.AbstractInterruptibleChannel.end(AbstractInterruptibleChannel.java:185)
[junit] at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:152)
[junit] at sun.nio.ch.ServerSocketAdaptor.accept(ServerSocketAdaptor.java:84)
[junit] at org.apache.hadoop.hdfs.server.datanode.DataXceiverServer.run(DataXceiverServer.java:130)
[junit] at java.lang.Thread.run(Thread.java:619)
[junit]
[junit] 2009-08-24 18:16:26,819 INFO datanode.DataNode (DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads is 0
[junit] 2009-08-24 18:16:26,819 INFO datanode.DataBlockScanner (DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
[junit] 2009-08-24 18:16:26,820 INFO datanode.DataNode (DataNode.java:run(1305)) - DatanodeRegistration(127.0.0.1:48958, storageID=DS-1727440281-67.195.138.9-48958-1251137725884, infoPort=41425, ipcPort=36557):Finishing DataNode in: FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/data/dfs/data/data3/current,/home/hudson/hudson-slave/workspace/Hadoop-Mapreduce-trunk/trunk/build/test/data/dfs/data/data4/current'}
[junit] 2009-08-24 18:16:26,820 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 36557
[junit] 2009-08-24 18:16:26,820 INFO datanode.DataNode (DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads is 0
[junit] Shutting down DataNode 0
[junit] 2009-08-24 18:16:26,922 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 40727
[junit] 2009-08-24 18:16:26,922 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 40727: exiting
[junit] 2009-08-24 18:16:26,922 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 40727: exiting
[junit] 2009-08-24 18:16:26,922 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 40727: exiting
[junit] 2009-08-24 18:16:26,923 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 40727
[junit] 2009-08-24 18:16:26,923 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
[junit] 2009-08-24 18:16:26,923 INFO datanode.DataNode (DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads is 1
[junit] 2009-08-24 18:16:26,923 WARN datanode.DataNode (DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:45705, storageID=DS-841980697-67.195.138.9-45705-1251137725256, infoPort=39749, ipcPort=40727):DataXceiveServer: java.nio.channels.AsynchronousCloseException
[junit] at java.nio.channels.spi.AbstractInterruptibleChannel.end(AbstractInterruptibleChannel.java:185)
[junit] at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:152)
[junit] at sun.nio.ch.ServerSocketAdaptor.accept(ServerSocketAdaptor.java:84)
[junit] at org.apache.hadoop.hdfs.server.datanode.DataXceiverServer.run(DataXceiverServer.java:130)
[junit] at java.lang.Thread.run(Thread.java:619)
[junit]
[junit] 2009-08-24 18:16:26,926 INFO datanode.DataNode (DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads is 0
[junit] 2009-08-24 18:16:26,926 INFO datanode.DataBlockScanner (DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
[junit] 2009-08-24 18:16:26,927 INFO datanode.DataNode (DataNode.java:run(1305)) - DatanodeRegistration(127.0.0.1:45705, storageID=DS-841980697-67.195.138.9-45705-1251137725256, infoPort=39749, ipcPort=40727):Finishing DataNode in: FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/data/dfs/data/data1/current,/home/hudson/hudson-slave/workspace/Hadoop-Mapreduce-trunk/trunk/build/test/data/dfs/data/data2/current'}
[junit] 2009-08-24 18:16:26,927 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 40727
[junit] 2009-08-24 18:16:26,927 INFO datanode.DataNode (DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads is 0
[junit] 2009-08-24 18:16:27,033 WARN namenode.DecommissionManager (DecommissionManager.java:run(67)) - Monitor interrupted: java.lang.InterruptedException: sleep interrupted
[junit] 2009-08-24 18:16:27,033 INFO namenode.FSNamesystem (FSEditLog.java:printStatistics(884)) - Number of transactions: 88 Total time for transactions(ms): 3Number of transactions batched in Syncs: 5 Number of syncs: 63 SyncTimes(ms): 601 577
[junit] 2009-08-24 18:16:27,033 WARN namenode.FSNamesystem (FSNamesystem.java:run(2077)) - ReplicationMonitor thread received InterruptedException.java.lang.InterruptedException: sleep interrupted
[junit] 2009-08-24 18:16:27,052 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 54853
[junit] 2009-08-24 18:16:27,052 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 3 on 54853: exiting
[junit] 2009-08-24 18:16:27,052 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 54853: exiting
[junit] 2009-08-24 18:16:27,052 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 5 on 54853: exiting
[junit] 2009-08-24 18:16:27,053 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 7 on 54853: exiting
[junit] 2009-08-24 18:16:27,052 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 4 on 54853: exiting
[junit] 2009-08-24 18:16:27,053 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 8 on 54853: exiting
[junit] 2009-08-24 18:16:27,053 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 54853: exiting
[junit] 2009-08-24 18:16:27,053 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 6 on 54853: exiting
[junit] 2009-08-24 18:16:27,053 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 9 on 54853: exiting
[junit] 2009-08-24 18:16:27,053 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 54853: exiting
[junit] Tests run: 2, Failures: 0, Errors: 0, Time elapsed: 106.109 sec
[junit] 2009-08-24 18:16:27,053 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 54853
[junit] 2009-08-24 18:16:27,053 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
[junit] Running org.apache.hadoop.util.TestReflectionUtils
[junit] Tests run: 5, Failures: 0, Errors: 0, Time elapsed: 0.644 sec
[junit] Running org.apache.hadoop.util.TestRunJar
[junit] Creating filehttp://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/data/out
[junit] Tests run: 1, Failures: 0, Errors: 0, Time elapsed: 0.172 sec
checkfailure:
[touch] Creating http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/testsfailed
BUILD FAILED
http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build.xml :627: Tests failed!
Total time: 158 minutes 33 seconds
Publishing Javadoc
Recording test results
Recording fingerprints
Publishing Clover coverage report...
Build failed in Hudson: Hadoop-Mapreduce-trunk #61
Posted by Apache Hudson Server <hu...@hudson.zones.apache.org>.
See http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/61/changes
Changes:
[sharad] MAPREDUCE-430. Fix a bug related to task getting stuck in case of OOM error. Contributed by Amar Kamat.
[cdouglas] MAPREDUCE-788. Update gridmix2 to use the new API Contributed by Amareshwari Sriramadasu
[cdouglas] MAPREDUCE-910. Support counters in MRUnit. Contributed by Aaron Kimball
[tomwhite] MAPREDUCE-825. JobClient completion poll interval of 5s causes slow tests in local mode. Contributed by Aaron Kimball.
[tomwhite] MAPREDUCE-750. Extensible ConnManager factory API. Contributed by Aaron Kimball.
[sharad] MAPREDUCE-370. Change org.apache.hadoop.mapred.lib.MultipleOutputs and org.apache.hadoop.mapred.lib.MultipleOutputFormat to use new api. Contributed by Amareshwari Sriramadasu.
------------------------------------------
[...truncated 136730 lines...]
[junit] 2009-08-26 19:52:18,660 INFO mapred.TaskRunner (ReduceTaskRunner.java:close(48)) - attempt_20090826195122321_0002_r_000000_0 done; removing files.
[junit] 2009-08-26 19:52:18,701 INFO mapred.JvmManager (JvmManager.java:<init>(396)) - In JvmRunner constructed JVM ID: jvm_20090826195122321_0002_m_1445290726
[junit] 2009-08-26 19:52:18,702 INFO mapred.JvmManager (JvmManager.java:spawnNewJvm(364)) - JVM Runner jvm_20090826195122321_0002_m_1445290726 spawned.
[junit] 2009-08-26 19:52:18,722 INFO mapred.JobClient (JobClient.java:monitorAndPrintJob(1391)) - Task Id : attempt_20090826195122321_0002_r_000000_0, Status : SUCCEEDED
[junit] attempt_20090826195122321_0002_r_000000_0: 2009-08-26 19:52:07,404 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Initializing JVM Metrics with processName=SHUFFLE, sessionId=
[junit] attempt_20090826195122321_0002_r_000000_0: 2009-08-26 19:52:07,530 INFO mapred.ReduceTask (ReduceTask.java:<init>(1009)) - ShuffleRamManager: MemoryLimit=141387360, MaxSingleShuffleLimit=35346840
[junit] attempt_20090826195122321_0002_r_000000_0: 2009-08-26 19:52:07,537 INFO mapred.ReduceTask (ReduceTask.java:run(2488)) - attempt_20090826195122321_0002_r_000000_0 Thread started: Thread for merging on-disk files
[junit] attempt_20090826195122321_0002_r_000000_0: 2009-08-26 19:52:07,537 INFO mapred.ReduceTask (ReduceTask.java:run(2591)) - attempt_20090826195122321_0002_r_000000_0 Thread started: Thread for merging in memory files
[junit] attempt_20090826195122321_0002_r_000000_0: 2009-08-26 19:52:07,537 INFO mapred.ReduceTask (ReduceTask.java:run(2493)) - attempt_20090826195122321_0002_r_000000_0 Thread waiting: Thread for merging on-disk files
[junit] attempt_20090826195122321_0002_r_000000_0: 2009-08-26 19:52:07,559 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(1895)) - attempt_20090826195122321_0002_r_000000_0 Need another 3 map output(s) where 0 is already in progress
[junit] attempt_20090826195122321_0002_r_000000_0: 2009-08-26 19:52:07,559 INFO mapred.ReduceTask (ReduceTask.java:run(2697)) - attempt_20090826195122321_0002_r_000000_0 Thread started: Thread for polling Map Completion Events
[junit] attempt_20090826195122321_0002_r_000000_0: 2009-08-26 19:52:07,560 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2008)) - attempt_20090826195122321_0002_r_000000_0 Scheduled 0 outputs (0 slow hosts and0 dup hosts)
[junit] attempt_20090826195122321_0002_r_000000_0: 2009-08-26 19:52:07,565 INFO mapred.ReduceTask (ReduceTask.java:run(2703)) - attempt_20090826195122321_0002_r_000000_0: Got 2 new map-outputs
[junit] attempt_20090826195122321_0002_r_000000_0: 2009-08-26 19:52:11,571 INFO mapred.ReduceTask (ReduceTask.java:run(2703)) - attempt_20090826195122321_0002_r_000000_0: Got 1 new map-outputs
[junit] attempt_20090826195122321_0002_r_000000_0: 2009-08-26 19:52:12,560 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2008)) - attempt_20090826195122321_0002_r_000000_0 Scheduled 1 outputs (0 slow hosts and0 dup hosts)
[junit] attempt_20090826195122321_0002_r_000000_0: 2009-08-26 19:52:12,597 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1422)) - header: attempt_20090826195122321_0002_m_000000_0, compressed len: 11, decompressed len: 7
[junit] attempt_20090826195122321_0002_r_000000_0: 2009-08-26 19:52:12,597 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1436)) - Shuffling 7 bytes (11 raw bytes) into RAM from attempt_20090826195122321_0002_m_000000_0
[junit] attempt_20090826195122321_0002_r_000000_0: 2009-08-26 19:52:12,602 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1565)) - Read 7 bytes from map-output for attempt_20090826195122321_0002_m_000000_0
[junit] attempt_20090826195122321_0002_r_000000_0: 2009-08-26 19:52:12,602 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1624)) - Rec #1 from attempt_20090826195122321_0002_m_000000_0 -> (2, 1) from localhost
[junit] attempt_20090826195122321_0002_r_000000_0: 2009-08-26 19:52:12,604 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2008)) - attempt_20090826195122321_0002_r_000000_0 Scheduled 1 outputs (0 slow hosts and0 dup hosts)
[junit] attempt_20090826195122321_0002_r_000000_0: 2009-08-26 19:52:12,606 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1422)) - header: attempt_20090826195122321_0002_m_000001_0, compressed len: 11, decompressed len: 7
[junit] attempt_20090826195122321_0002_r_000000_0: 2009-08-26 19:52:12,606 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1436)) - Shuffling 7 bytes (11 raw bytes) into RAM from attempt_20090826195122321_0002_m_000001_0
[junit] attempt_20090826195122321_0002_r_000000_0: 2009-08-26 19:52:12,607 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1565)) - Read 7 bytes from map-output for attempt_20090826195122321_0002_m_000001_0
[junit] attempt_20090826195122321_0002_r_000000_0: 2009-08-26 19:52:12,607 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1624)) - Rec #1 from attempt_20090826195122321_0002_m_000001_0 -> (2, 1) from localhost
[junit] attempt_20090826195122321_0002_r_000000_0: 2009-08-26 19:52:12,607 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2008)) - attempt_20090826195122321_0002_r_000000_0 Scheduled 1 outputs (0 slow hosts and0 dup hosts)
[junit] attempt_20090826195122321_0002_r_000000_0: 2009-08-26 19:52:12,613 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1422)) - header: attempt_20090826195122321_0002_m_000002_0, compressed len: 11, decompressed len: 7
[junit] attempt_20090826195122321_0002_r_000000_0: 2009-08-26 19:52:12,613 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1436)) - Shuffling 7 bytes (11 raw bytes) into RAM from attempt_20090826195122321_0002_m_000002_0
[junit] attempt_20090826195122321_0002_r_000000_0: 2009-08-26 19:52:12,614 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1565)) - Read 7 bytes from map-output for attempt_20090826195122321_0002_m_000002_0
[junit] attempt_20090826195122321_0002_r_000000_0: 2009-08-26 19:52:12,614 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1624)) - Rec #1 from attempt_20090826195122321_0002_m_000002_0 -> (2, 1) from localhost
[junit] attempt_20090826195122321_0002_r_000000_0: 2009-08-26 19:52:13,572 INFO mapred.ReduceTask (ReduceTask.java:run(2722)) - GetMapEventsThread exiting
[junit] attempt_20090826195122321_0002_r_000000_0: 2009-08-26 19:52:13,573 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2206)) - getMapsEventsThread joined.
[junit] attempt_20090826195122321_0002_r_000000_0: 2009-08-26 19:52:13,573 INFO mapred.ReduceTask (ReduceTask.java:close(1115)) - Closed ram manager
[junit] attempt_20090826195122321_0002_r_000000_0: 2009-08-26 19:52:13,573 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2234)) - Interleaved on-disk merge complete: 0 files left.
[junit] attempt_20090826195122321_0002_r_000000_0: 2009-08-26 19:52:13,573 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2239)) - In-memory merge complete: 3 files left.
[junit] attempt_20090826195122321_0002_r_000000_0: 2009-08-26 19:52:13,600 INFO mapred.Merger (Merger.java:merge(469)) - Merging 3 sorted segments
[junit] attempt_20090826195122321_0002_r_000000_0: 2009-08-26 19:52:13,601 INFO mapred.Merger (Merger.java:merge(568)) - Down to the last merge-pass, with 3 segments left of total size: 9 bytes
[junit] attempt_20090826195122321_0002_r_000000_0: 2009-08-26 19:52:13,612 INFO mapred.ReduceTask (ReduceTask.java:createKVIterator(2352)) - Merged 3 segments, 21 bytes to disk to satisfy reduce memory limit
[junit] attempt_20090826195122321_0002_r_000000_0: 2009-08-26 19:52:13,613 INFO mapred.ReduceTask (ReduceTask.java:createKVIterator(2372)) - Merging 1 files, 21 bytes from disk
[junit] attempt_20090826195122321_0002_r_000000_0: 2009-08-26 19:52:13,614 INFO mapred.ReduceTask (ReduceTask.java:createKVIterator(2386)) - Merging 0 segments, 0 bytes from memory into reduce
[junit] attempt_20090826195122321_0002_r_000000_0: 2009-08-26 19:52:13,614 INFO mapred.Merger (Merger.java:merge(469)) - Merging 1 sorted segments
[junit] attempt_20090826195122321_0002_r_000000_0: 2009-08-26 19:52:13,617 INFO mapred.Merger (Merger.java:merge(568)) - Down to the last merge-pass, with 1 segments left of total size: 13 bytes
[junit] attempt_20090826195122321_0002_r_000000_0: 2009-08-26 19:52:13,884 INFO mapred.Task (Task.java:done(662)) - Task:attempt_20090826195122321_0002_r_000000_0 is done. And is in the process of commiting
[junit] attempt_20090826195122321_0002_r_000000_0: 2009-08-26 19:52:15,892 INFO mapred.Task (Task.java:commit(774)) - Task attempt_20090826195122321_0002_r_000000_0 is allowed to commit now
[junit] attempt_20090826195122321_0002_r_000000_0: 2009-08-26 19:52:15,965 INFO mapred.FileOutputCommitter (FileOutputCommitter.java:commitTask(92)) - Saved output of task 'attempt_20090826195122321_0002_r_000000_0' to hdfs://localhost:59963/user/hudson/mapout
[junit] attempt_20090826195122321_0002_r_000000_0: 2009-08-26 19:52:15,967 INFO mapred.Task (Task.java:sendDone(733)) - Task 'attempt_20090826195122321_0002_r_000000_0' done.
[junit] 2009-08-26 19:52:19,144 INFO mapred.TaskTracker (TaskTracker.java:getTask(2825)) - JVM with ID: jvm_20090826195122321_0002_m_1445290726 given task: attempt_20090826195122321_0002_m_000003_0
[junit] 2009-08-26 19:52:19,504 INFO mapred.TaskTracker (TaskTracker.java:reportProgress(2272)) - attempt_20090826195122321_0002_m_000003_0 0.0%
[junit] 2009-08-26 19:52:19,524 INFO FSNamesystem.audit (FSNamesystem.java:logAuditEvent(114)) - ugi=hudson,hudson ip=/127.0.0.1 cmd=delete src=/user/hudson/mapout/_temporary dst=null perm=null
[junit] 2009-08-26 19:52:19,528 INFO mapred.TaskTracker (TaskTracker.java:reportProgress(2272)) - attempt_20090826195122321_0002_m_000003_0 0.0% cleanup > map
[junit] 2009-08-26 19:52:19,529 INFO mapred.TaskTracker (TaskTracker.java:reportDone(2353)) - Task attempt_20090826195122321_0002_m_000003_0 is done.
[junit] 2009-08-26 19:52:19,529 INFO mapred.TaskTracker (TaskTracker.java:reportDone(2354)) - reported output size for attempt_20090826195122321_0002_m_000003_0 was 0
[junit] 2009-08-26 19:52:19,530 INFO mapred.TaskTracker (TaskTracker.java:addFreeSlots(1928)) - addFreeSlot : current free slots : 2
[junit] 2009-08-26 19:52:19,625 WARN util.ProcessTree (ProcessTree.java:terminateProcessGroup(136)) - Error executing shell command org.apache.hadoop.util.Shell$ExitCodeException: kill: No such process
[junit]
[junit] 2009-08-26 19:52:19,626 INFO util.ProcessTree (ProcessTree.java:terminateProcessGroup(138)) - Killing all processes in the process group 1967 with SIGTERM. Exit code 1
[junit] 2009-08-26 19:52:19,728 INFO mapred.JobClient (JobClient.java:monitorAndPrintJob(1342)) - map 100% reduce 100%
[junit] 2009-08-26 19:52:21,092 INFO mapred.JvmManager (JvmManager.java:runChild(423)) - JVM : jvm_20090826195122321_0002_r_1233116058 exited with exit code 0. Number of tasks it ran: 1
[junit] 2009-08-26 19:52:21,660 INFO mapred.TaskTracker (TaskTracker.java:tryToGetOutputSize(1880)) - org.apache.hadoop.util.DiskChecker$DiskErrorException: Could not find output/file.out in any of the configured local directories
[junit] 2009-08-26 19:52:21,662 INFO mapred.JobInProgress (JobInProgress.java:completedTask(2450)) - Task 'attempt_20090826195122321_0002_m_000003_0' has completed task_20090826195122321_0002_m_000003 successfully.
[junit] 2009-08-26 19:52:21,663 INFO mapred.JobInProgress (JobInProgress.java:jobComplete(2616)) - Job job_20090826195122321_0002 has completed successfully.
[junit] 2009-08-26 19:52:21,663 INFO mapred.JobInProgress$JobSummary (JobInProgress.java:logJobSummary(3314)) - jobId=job_20090826195122321_0002,submitTime=1251316319540,launchTime=1251316319688,finishTime=1251316341662,numMaps=3,numSlotsPerMap=1,numReduces=1,numSlotsPerReduce=1,user=hudson,queue=default,status=SUCCEEDED,mapSlotSeconds=5,reduceSlotsSeconds=9,clusterMapCapacity=4,clusterReduceCapacity=4
[junit] 2009-08-26 19:52:21,666 INFO hdfs.StateChange (FSNamesystem.java:allocateBlock(1303)) - BLOCK* NameSystem.allocateBlock: /user/hudson/mapout/_logs/history/localhost_1251316282356_job_20090826195122321_0002_hudson_NA. blk_-3890057067062195254_1015
[junit] 2009-08-26 19:52:21,667 INFO datanode.DataNode (DataXceiver.java:opWriteBlock(222)) - Receiving block blk_-3890057067062195254_1015 src: /127.0.0.1:33889 dest: /127.0.0.1:35280
[junit] 2009-08-26 19:52:21,669 INFO datanode.DataNode (DataXceiver.java:opWriteBlock(222)) - Receiving block blk_-3890057067062195254_1015 src: /127.0.0.1:34243 dest: /127.0.0.1:50753
[junit] 2009-08-26 19:52:21,687 INFO DataNode.clienttrace (BlockReceiver.java:lastDataNodeRun(822)) - src: /127.0.0.1:34243, dest: /127.0.0.1:50753, bytes: 12041, op: HDFS_WRITE, cliID: DFSClient_-1369897581, offset: 0, srvID: DS-1235983267-67.195.138.9-50753-1251316281496, blockid: blk_-3890057067062195254_1015, duration: 17077614
[junit] 2009-08-26 19:52:21,688 INFO hdfs.StateChange (BlockManager.java:addStoredBlock(950)) - BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:50753 is added to blk_-3890057067062195254_1015 size 12041
[junit] 2009-08-26 19:52:21,688 INFO datanode.DataNode (BlockReceiver.java:lastDataNodeRun(853)) - PacketResponder 0 for block blk_-3890057067062195254_1015 terminating
[junit] 2009-08-26 19:52:21,689 INFO hdfs.StateChange (BlockManager.java:addStoredBlock(950)) - BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:35280 is added to blk_-3890057067062195254_1015 size 12041
[junit] 2009-08-26 19:52:21,689 INFO DataNode.clienttrace (BlockReceiver.java:run(955)) - src: /127.0.0.1:33889, dest: /127.0.0.1:35280, bytes: 12041, op: HDFS_WRITE, cliID: DFSClient_-1369897581, offset: 0, srvID: DS-21740080-67.195.138.9-35280-1251316282115, blockid: blk_-3890057067062195254_1015, duration: 18038828
[junit] 2009-08-26 19:52:21,689 INFO datanode.DataNode (BlockReceiver.java:run(1025)) - PacketResponder 1 for block blk_-3890057067062195254_1015 terminating
[junit] 2009-08-26 19:52:21,692 INFO hdfs.StateChange (FSNamesystem.java:completeFileInternal(1269)) - DIR* NameSystem.completeFile: file /user/hudson/mapout/_logs/history/localhost_1251316282356_job_20090826195122321_0002_hudson_NA is closed by DFSClient_-1369897581
[junit] 2009-08-26 19:52:21,692 INFO namenode.FSNamesystem (FSEditLog.java:printStatistics(884)) - Number of transactions: 87 Total time for transactions(ms): 5Number of transactions batched in Syncs: 5 Number of syncs: 61 SyncTimes(ms): 715 561
[junit] 2009-08-26 19:52:21,703 INFO mapred.JobHistory (JobHistory.java:run(217)) - Moving http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/logs/history/localhost_1251316282356_job_20090826195122321_0002_hudson_NA to http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/logs/history/done
[junit] 2009-08-26 19:52:21,704 INFO hdfs.StateChange (BlockManager.java:addToInvalidates(363)) - BLOCK* NameSystem.addToInvalidates: blk_7382511142225617624 is added to invalidSet of 127.0.0.1:35280
[junit] 2009-08-26 19:52:21,705 INFO hdfs.StateChange (BlockManager.java:addToInvalidates(363)) - BLOCK* NameSystem.addToInvalidates: blk_7382511142225617624 is added to invalidSet of 127.0.0.1:50753
[junit] 2009-08-26 19:52:21,705 INFO hdfs.StateChange (BlockManager.java:addToInvalidates(363)) - BLOCK* NameSystem.addToInvalidates: blk_-2733604353408700202 is added to invalidSet of 127.0.0.1:35280
[junit] 2009-08-26 19:52:21,705 INFO hdfs.StateChange (BlockManager.java:addToInvalidates(363)) - BLOCK* NameSystem.addToInvalidates: blk_-2733604353408700202 is added to invalidSet of 127.0.0.1:50753
[junit] 2009-08-26 19:52:21,706 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2338)) - Removed completed task 'attempt_20090826195122321_0002_m_000000_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:38825'
[junit] 2009-08-26 19:52:21,706 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2338)) - Removed completed task 'attempt_20090826195122321_0002_m_000001_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:38825'
[junit] 2009-08-26 19:52:21,710 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2338)) - Removed completed task 'attempt_20090826195122321_0002_m_000003_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:38825'
[junit] 2009-08-26 19:52:21,716 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2338)) - Removed completed task 'attempt_20090826195122321_0002_m_000004_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:38825'
[junit] 2009-08-26 19:52:21,716 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2338)) - Removed completed task 'attempt_20090826195122321_0002_r_000000_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:38825'
[junit] 2009-08-26 19:52:21,718 INFO mapred.TaskTracker (TaskTracker.java:purgeJob(1677)) - Received 'KillJobAction' for job: job_20090826195122321_0002
[junit] 2009-08-26 19:52:21,718 INFO mapred.TaskRunner (MapTaskRunner.java:close(44)) - attempt_20090826195122321_0002_m_000003_0 done; removing files.
[junit] 2009-08-26 19:52:21,719 INFO mapred.IndexCache (IndexCache.java:removeMap(140)) - Map ID attempt_20090826195122321_0002_m_000003_0 not found in cache
[junit] 2009-08-26 19:52:21,719 INFO mapred.TaskRunner (MapTaskRunner.java:close(44)) - attempt_20090826195122321_0002_m_000001_0 done; removing files.
[junit] 2009-08-26 19:52:21,720 INFO mapred.TaskRunner (MapTaskRunner.java:close(44)) - attempt_20090826195122321_0002_m_000000_0 done; removing files.
[junit] 2009-08-26 19:52:21,722 INFO FSNamesystem.audit (FSNamesystem.java:logAuditEvent(114)) - ugi=hudson,hudson ip=/127.0.0.1 cmd=delete src=/tmp/hadoop-hudson/mapred/system/job_20090826195122321_0002 dst=null perm=null
[junit] 2009-08-26 19:52:21,737 INFO mapred.JobClient (JobClient.java:monitorAndPrintJob(1391)) - Task Id : attempt_20090826195122321_0002_m_000003_0, Status : SUCCEEDED
[junit] attempt_20090826195122321_0002_m_000003_0: 2009-08-26 19:52:19,386 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Initializing JVM Metrics with processName=MAP, sessionId=
[junit] attempt_20090826195122321_0002_m_000003_0: 2009-08-26 19:52:19,525 INFO mapred.Task (Task.java:done(662)) - Task:attempt_20090826195122321_0002_m_000003_0 is done. And is in the process of commiting
[junit] attempt_20090826195122321_0002_m_000003_0: 2009-08-26 19:52:19,530 INFO mapred.Task (Task.java:sendDone(733)) - Task 'attempt_20090826195122321_0002_m_000003_0' done.
[junit] 2009-08-26 19:52:21,742 INFO mapred.JobClient (JobClient.java:monitorAndPrintJob(1397)) - Job complete: job_20090826195122321_0002
[junit] 2009-08-26 19:52:21,745 INFO mapred.JobClient (Counters.java:log(534)) - Counters: 22
[junit] 2009-08-26 19:52:21,745 INFO mapred.JobClient (Counters.java:log(536)) - Job Counters
[junit] 2009-08-26 19:52:21,745 INFO mapred.JobClient (Counters.java:log(538)) - Launched reduce tasks=1
[junit] 2009-08-26 19:52:21,745 INFO mapred.JobClient (Counters.java:log(538)) - SLOTS_MILLIS_MAPS=5344
[junit] 2009-08-26 19:52:21,746 INFO mapred.JobClient (Counters.java:log(538)) - Total time spent by all reduces waiting after reserving slots (ms)=0
[junit] 2009-08-26 19:52:21,746 INFO mapred.JobHistory (JobHistory.java:run(217)) - Moving http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/logs/history/localhost_1251316282356_job_20090826195122321_0002_conf.xml to http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/logs/history/done
[junit] 2009-08-26 19:52:21,746 INFO mapred.JobClient (Counters.java:log(538)) - Total time spent by all maps waiting after reserving slots (ms)=0
[junit] 2009-08-26 19:52:21,746 INFO mapred.JobClient (Counters.java:log(538)) - Rack-local map tasks=3
[junit] 2009-08-26 19:52:21,746 INFO mapred.JobClient (Counters.java:log(538)) - Launched map tasks=3
[junit] 2009-08-26 19:52:21,747 INFO mapred.JobClient (Counters.java:log(538)) - SLOTS_MILLIS_REDUCES=9264
[junit] 2009-08-26 19:52:21,747 INFO mapred.JobClient (Counters.java:log(536)) - FileInputFormatCounters
[junit] 2009-08-26 19:52:21,747 INFO mapred.JobClient (Counters.java:log(538)) - BYTES_READ=3
[junit] 2009-08-26 19:52:21,747 INFO mapred.JobClient (Counters.java:log(536)) - FileSystemCounters
[junit] 2009-08-26 19:52:21,747 INFO mapred.JobClient (Counters.java:log(538)) - FILE_BYTES_READ=21
[junit] 2009-08-26 19:52:21,748 INFO mapred.JobClient (Counters.java:log(538)) - HDFS_BYTES_READ=828
[junit] 2009-08-26 19:52:21,748 INFO mapred.JobClient (Counters.java:log(538)) - FILE_BYTES_WRITTEN=150
[junit] 2009-08-26 19:52:21,748 INFO mapred.JobClient (Counters.java:log(538)) - HDFS_BYTES_WRITTEN=6
[junit] 2009-08-26 19:52:21,748 INFO mapred.JobClient (Counters.java:log(536)) - Map-Reduce Framework
[junit] 2009-08-26 19:52:21,748 INFO mapred.JobClient (Counters.java:log(538)) - Reduce input groups=3
[junit] 2009-08-26 19:52:21,748 INFO mapred.JobClient (Counters.java:log(538)) - Combine output records=0
[junit] 2009-08-26 19:52:21,749 INFO mapred.JobClient (Counters.java:log(538)) - Map input records=3
[junit] 2009-08-26 19:52:21,749 INFO mapred.JobClient (Counters.java:log(538)) - Reduce shuffle bytes=33
[junit] 2009-08-26 19:52:21,755 INFO mapred.JobClient (Counters.java:log(538)) - Reduce output records=3
[junit] 2009-08-26 19:52:21,756 INFO mapred.JobClient (Counters.java:log(538)) - Spilled Records=6
[junit] 2009-08-26 19:52:21,756 INFO mapred.JobClient (Counters.java:log(538)) - Map output bytes=9
[junit] 2009-08-26 19:52:21,756 INFO mapred.JobClient (Counters.java:log(538)) - Combine input records=0
[junit] 2009-08-26 19:52:21,756 INFO mapred.JobClient (Counters.java:log(538)) - Map output records=3
[junit] 2009-08-26 19:52:21,757 INFO mapred.JobClient (Counters.java:log(538)) - Reduce input records=3
[junit] 2009-08-26 19:52:21,762 INFO FSNamesystem.audit (FSNamesystem.java:logAuditEvent(114)) - ugi=hudson,hudson ip=/127.0.0.1 cmd=listStatus src=/user/hudson/mapout dst=null perm=null
[junit] Found 2 items
[junit] drwxr-xr-x - hudson supergroup 0 2009-08-26 19:51 /user/hudson/mapout/_logs
[junit] -rw-r--r-- 3 hudson supergroup 6 2009-08-26 19:52 /user/hudson/mapout/part-00000
[junit] 2009-08-26 19:52:21,764 INFO FSNamesystem.audit (FSNamesystem.java:logAuditEvent(114)) - ugi=hudson,hudson ip=/127.0.0.1 cmd=listStatus src=/user/hudson/mapout dst=null perm=null
[junit] 2009-08-26 19:52:21,766 INFO FSNamesystem.audit (FSNamesystem.java:logAuditEvent(114)) - ugi=hudson,hudson ip=/127.0.0.1 cmd=open src=/user/hudson/mapout/part-00000 dst=null perm=null
[junit] 2009-08-26 19:52:21,768 INFO DataNode.clienttrace (BlockSender.java:sendBlock(417)) - src: /127.0.0.1:50753, dest: /127.0.0.1:34244, bytes: 10, op: HDFS_READ, cliID: DFSClient_-1369897581, offset: 0, srvID: DS-1235983267-67.195.138.9-50753-1251316281496, blockid: blk_-6303981703878035794_1015, duration: 294741
[junit] 2009-08-26 19:52:21,768 INFO mapred.MiniMRCluster (MiniMRCluster.java:waitTaskTrackers(306)) - Waiting for task tracker tracker_host0.foo.com:localhost/127.0.0.1:34343 to be idle.
[junit] 2009-08-26 19:52:21,784 INFO mapred.JobHistory (JobHistory.java:cleanupJob(1057)) - Deleting localized job conf at http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/logs/job_20090826195122321_0002_conf.xml
[junit] 2009-08-26 19:52:22,512 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2338)) - Removed completed task 'attempt_20090826195122321_0002_m_000002_0' from 'tracker_host0.foo.com:localhost/127.0.0.1:34343'
[junit] 2009-08-26 19:52:22,513 INFO mapred.TaskTracker (TaskTracker.java:purgeJob(1677)) - Received 'KillJobAction' for job: job_20090826195122321_0002
[junit] 2009-08-26 19:52:22,513 INFO mapred.TaskRunner (MapTaskRunner.java:close(44)) - attempt_20090826195122321_0002_m_000002_0 done; removing files.
[junit] 2009-08-26 19:52:22,769 INFO mapred.TaskTracker (TaskTracker.java:run(687)) - Shutting down: Map-events fetcher for all reduce tasks on tracker_host0.foo.com:localhost/127.0.0.1:34343
[junit] 2009-08-26 19:52:22,770 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 34343
[junit] 2009-08-26 19:52:22,770 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 34343: exiting
[junit] 2009-08-26 19:52:22,771 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
[junit] 2009-08-26 19:52:22,771 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 3 on 34343: exiting
[junit] 2009-08-26 19:52:22,771 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 34343: exiting
[junit] 2009-08-26 19:52:22,771 INFO mapred.TaskTracker (TaskTracker.java:shutdown(1155)) - Shutting down StatusHttpServer
[junit] 2009-08-26 19:52:22,771 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 34343: exiting
[junit] 2009-08-26 19:52:22,771 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 34343
[junit] 2009-08-26 19:52:22,874 INFO mapred.TaskTracker (TaskTracker.java:offerService(1445)) - Interrupted. Closing down.
[junit] 2009-08-26 19:52:22,875 INFO mapred.TaskTracker (TaskTracker.java:run(687)) - Shutting down: Map-events fetcher for all reduce tasks on tracker_host1.foo.com:localhost/127.0.0.1:38825
[junit] 2009-08-26 19:52:22,875 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 38825
[junit] 2009-08-26 19:52:22,876 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 38825: exiting
[junit] 2009-08-26 19:52:22,876 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 38825: exiting
[junit] 2009-08-26 19:52:22,876 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 38825: exiting
[junit] 2009-08-26 19:52:22,876 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 3 on 38825: exiting
[junit] 2009-08-26 19:52:22,877 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 38825
[junit] 2009-08-26 19:52:22,877 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
[junit] 2009-08-26 19:52:22,877 INFO mapred.TaskTracker (TaskTracker.java:shutdown(1155)) - Shutting down StatusHttpServer
[junit] 2009-08-26 19:52:22,979 INFO mapred.TaskTracker (TaskTracker.java:offerService(1445)) - Interrupted. Closing down.
[junit] 2009-08-26 19:52:22,979 INFO mapred.JobTracker (JobTracker.java:close(2165)) - Stopping infoServer
[junit] 2009-08-26 19:52:23,107 INFO mapred.JobTracker (JobTracker.java:close(2173)) - Stopping interTrackerServer
[junit] 2009-08-26 19:52:23,107 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 45339
[junit] 2009-08-26 19:52:23,107 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 45339: exiting
[junit] 2009-08-26 19:52:23,107 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 3 on 45339: exiting
[junit] 2009-08-26 19:52:23,107 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 45339: exiting
[junit] 2009-08-26 19:52:23,110 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 5 on 45339: exiting
[junit] 2009-08-26 19:52:23,110 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 45339: exiting
[junit] 2009-08-26 19:52:23,111 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 9 on 45339: exiting
[junit] 2009-08-26 19:52:23,110 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 6 on 45339: exiting
[junit] 2009-08-26 19:52:23,110 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 4 on 45339: exiting
[junit] 2009-08-26 19:52:23,110 INFO mapred.JobTracker (JobTracker.java:offerService(2160)) - Stopped interTrackerServer
[junit] 2009-08-26 19:52:23,110 INFO mapred.JobTracker (JobTracker.java:stopExpireTrackersThread(2207)) - Stopping expireTrackers
[junit] 2009-08-26 19:52:23,110 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 45339
[junit] 2009-08-26 19:52:23,110 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 8 on 45339: exiting
[junit] 2009-08-26 19:52:23,110 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
[junit] 2009-08-26 19:52:23,110 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 7 on 45339: exiting
[junit] 2009-08-26 19:52:23,112 INFO mapred.EagerTaskInitializationListener (EagerTaskInitializationListener.java:terminate(106)) - Stopping Job Init Manager thread
[junit] 2009-08-26 19:52:23,113 INFO mapred.EagerTaskInitializationListener (EagerTaskInitializationListener.java:run(60)) - JobInitManagerThread interrupted.
[junit] 2009-08-26 19:52:23,113 INFO mapred.EagerTaskInitializationListener (EagerTaskInitializationListener.java:run(64)) - Shutting down thread pool
[junit] 2009-08-26 19:52:23,113 INFO mapred.JobTracker (JobTracker.java:close(2183)) - Stopping expireLaunchingTasks
[junit] 2009-08-26 19:52:23,113 INFO mapred.JobTracker (JobTracker.java:close(2201)) - stopped all jobtracker services
[junit] Shutting down the Mini HDFS Cluster
[junit] Shutting down DataNode 1
[junit] 2009-08-26 19:52:23,215 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 55857
[junit] 2009-08-26 19:52:23,216 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 55857: exiting
[junit] 2009-08-26 19:52:23,216 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 55857: exiting
[junit] 2009-08-26 19:52:23,216 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 55857: exiting
[junit] 2009-08-26 19:52:23,216 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
[junit] 2009-08-26 19:52:23,217 WARN datanode.DataNode (DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:35280, storageID=DS-21740080-67.195.138.9-35280-1251316282115, infoPort=49209, ipcPort=55857):DataXceiveServer: java.nio.channels.AsynchronousCloseException
[junit] at java.nio.channels.spi.AbstractInterruptibleChannel.end(AbstractInterruptibleChannel.java:185)
[junit] at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:152)
[junit] at sun.nio.ch.ServerSocketAdaptor.accept(ServerSocketAdaptor.java:84)
[junit] at org.apache.hadoop.hdfs.server.datanode.DataXceiverServer.run(DataXceiverServer.java:130)
[junit] at java.lang.Thread.run(Thread.java:619)
[junit]
[junit] 2009-08-26 19:52:23,216 INFO datanode.DataNode (DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads is 1
[junit] 2009-08-26 19:52:23,216 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 55857
[junit] 2009-08-26 19:52:23,217 INFO datanode.DataBlockScanner (DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
[junit] 2009-08-26 19:52:23,218 INFO datanode.DataNode (DataNode.java:run(1305)) - DatanodeRegistration(127.0.0.1:35280, storageID=DS-21740080-67.195.138.9-35280-1251316282115, infoPort=49209, ipcPort=55857):Finishing DataNode in: FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/data/dfs/data/data3/current,/home/hudson/hudson-slave/workspace/Hadoop-Mapreduce-trunk/trunk/build/test/data/dfs/data/data4/current'}
[junit] 2009-08-26 19:52:23,218 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 55857
[junit] 2009-08-26 19:52:23,218 INFO datanode.DataNode (DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads is 0
[junit] Shutting down DataNode 0
[junit] 2009-08-26 19:52:23,320 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 55747
[junit] 2009-08-26 19:52:23,320 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 55747: exiting
[junit] 2009-08-26 19:52:23,321 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 55747
[junit] 2009-08-26 19:52:23,320 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 55747: exiting
[junit] 2009-08-26 19:52:23,322 INFO datanode.DataNode (DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads is 1
[junit] 2009-08-26 19:52:23,321 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
[junit] 2009-08-26 19:52:23,321 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 55747: exiting
[junit] 2009-08-26 19:52:23,321 WARN datanode.DataNode (DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:50753, storageID=DS-1235983267-67.195.138.9-50753-1251316281496, infoPort=40470, ipcPort=55747):DataXceiveServer: java.nio.channels.AsynchronousCloseException
[junit] at java.nio.channels.spi.AbstractInterruptibleChannel.end(AbstractInterruptibleChannel.java:185)
[junit] at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:152)
[junit] at sun.nio.ch.ServerSocketAdaptor.accept(ServerSocketAdaptor.java:84)
[junit] at org.apache.hadoop.hdfs.server.datanode.DataXceiverServer.run(DataXceiverServer.java:130)
[junit] at java.lang.Thread.run(Thread.java:619)
[junit]
[junit] 2009-08-26 19:52:23,324 INFO datanode.DataNode (DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads is 0
[junit] 2009-08-26 19:52:23,324 INFO datanode.DataBlockScanner (DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
[junit] 2009-08-26 19:52:23,325 INFO datanode.DataNode (DataNode.java:run(1305)) - DatanodeRegistration(127.0.0.1:50753, storageID=DS-1235983267-67.195.138.9-50753-1251316281496, infoPort=40470, ipcPort=55747):Finishing DataNode in: FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/data/dfs/data/data1/current,/home/hudson/hudson-slave/workspace/Hadoop-Mapreduce-trunk/trunk/build/test/data/dfs/data/data2/current'}
[junit] 2009-08-26 19:52:23,325 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 55747
[junit] 2009-08-26 19:52:23,325 INFO datanode.DataNode (DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads is 0
[junit] 2009-08-26 19:52:23,431 WARN namenode.DecommissionManager (DecommissionManager.java:run(67)) - Monitor interrupted: java.lang.InterruptedException: sleep interrupted
[junit] 2009-08-26 19:52:23,431 INFO namenode.FSNamesystem (FSEditLog.java:printStatistics(884)) - Number of transactions: 88 Total time for transactions(ms): 5Number of transactions batched in Syncs: 5 Number of syncs: 63 SyncTimes(ms): 732 571
[junit] 2009-08-26 19:52:23,432 WARN namenode.FSNamesystem (FSNamesystem.java:run(2077)) - ReplicationMonitor thread received InterruptedException.java.lang.InterruptedException: sleep interrupted
[junit] 2009-08-26 19:52:23,446 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 59963
[junit] 2009-08-26 19:52:23,446 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 59963: exiting
[junit] 2009-08-26 19:52:23,447 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 6 on 59963: exiting
[junit] 2009-08-26 19:52:23,447 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 5 on 59963: exiting
[junit] 2009-08-26 19:52:23,447 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 59963: exiting
[junit] 2009-08-26 19:52:23,447 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 3 on 59963: exiting
[junit] 2009-08-26 19:52:23,447 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 59963
[junit] 2009-08-26 19:52:23,446 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 4 on 59963: exiting
[junit] 2009-08-26 19:52:23,446 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 59963: exiting
[junit] 2009-08-26 19:52:23,447 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 7 on 59963: exiting
[junit] 2009-08-26 19:52:23,447 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 9 on 59963: exiting
[junit] 2009-08-26 19:52:23,447 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
[junit] 2009-08-26 19:52:23,447 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 8 on 59963: exiting
[junit] Tests run: 2, Failures: 0, Errors: 0, Time elapsed: 103.973 sec
[junit] Running org.apache.hadoop.util.TestReflectionUtils
[junit] Tests run: 5, Failures: 0, Errors: 0, Time elapsed: 0.611 sec
[junit] Running org.apache.hadoop.util.TestRunJar
[junit] Creating filehttp://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/data/out
[junit] Tests run: 1, Failures: 0, Errors: 0, Time elapsed: 0.168 sec
checkfailure:
[touch] Creating http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/testsfailed
BUILD FAILED
http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build.xml :627: Tests failed!
Total time: 159 minutes 43 seconds
Publishing Javadoc
Recording test results
Recording fingerprints
Publishing Clover coverage report...
Build failed in Hudson: Hadoop-Mapreduce-trunk #60
Posted by Apache Hudson Server <hu...@hudson.zones.apache.org>.
See http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/60/changes
Changes:
[yhemanth] MAPREDUCE-768. Provide an option to dump jobtracker configuration in JSON format to standard output. Contributed by V.V.Chaitanya Krishna.
[tomwhite] MAPREDUCE-476. Extend DistributedCache to work locally (LocalJobRunner). Contributed by Philip Zeyliger.
[yhemanth] HADOOP-6184. Updated hadoop common and test jars to get the new API in Configuration for dumping in JSON format from Hudson trunk build #68.
------------------------------------------
[...truncated 136164 lines...]
[junit] 2009-08-25 19:11:54,970 INFO mapred.TaskRunner (ReduceTaskRunner.java:close(48)) - attempt_20090825191058650_0002_r_000000_0 done; removing files.
[junit] 2009-08-25 19:11:55,010 INFO mapred.JvmManager (JvmManager.java:<init>(396)) - In JvmRunner constructed JVM ID: jvm_20090825191058650_0002_m_-139254037
[junit] 2009-08-25 19:11:55,012 INFO mapred.JvmManager (JvmManager.java:spawnNewJvm(364)) - JVM Runner jvm_20090825191058650_0002_m_-139254037 spawned.
[junit] 2009-08-25 19:11:55,012 INFO mapred.JobClient (JobClient.java:monitorAndPrintJob(1350)) - Task Id : attempt_20090825191058650_0002_r_000000_0, Status : SUCCEEDED
[junit] attempt_20090825191058650_0002_r_000000_0: 2009-08-25 19:11:43,726 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Initializing JVM Metrics with processName=SHUFFLE, sessionId=
[junit] attempt_20090825191058650_0002_r_000000_0: 2009-08-25 19:11:43,852 INFO mapred.ReduceTask (ReduceTask.java:<init>(1011)) - ShuffleRamManager: MemoryLimit=141387360, MaxSingleShuffleLimit=35346840
[junit] attempt_20090825191058650_0002_r_000000_0: 2009-08-25 19:11:43,859 INFO mapred.ReduceTask (ReduceTask.java:run(2485)) - attempt_20090825191058650_0002_r_000000_0 Thread started: Thread for merging on-disk files
[junit] attempt_20090825191058650_0002_r_000000_0: 2009-08-25 19:11:43,859 INFO mapred.ReduceTask (ReduceTask.java:run(2584)) - attempt_20090825191058650_0002_r_000000_0 Thread started: Thread for merging in memory files
[junit] attempt_20090825191058650_0002_r_000000_0: 2009-08-25 19:11:43,859 INFO mapred.ReduceTask (ReduceTask.java:run(2490)) - attempt_20090825191058650_0002_r_000000_0 Thread waiting: Thread for merging on-disk files
[junit] attempt_20090825191058650_0002_r_000000_0: 2009-08-25 19:11:43,920 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(1892)) - attempt_20090825191058650_0002_r_000000_0 Need another 3 map output(s) where 0 is already in progress
[junit] attempt_20090825191058650_0002_r_000000_0: 2009-08-25 19:11:43,920 INFO mapred.ReduceTask (ReduceTask.java:run(2686)) - attempt_20090825191058650_0002_r_000000_0 Thread started: Thread for polling Map Completion Events
[junit] attempt_20090825191058650_0002_r_000000_0: 2009-08-25 19:11:43,921 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2005)) - attempt_20090825191058650_0002_r_000000_0 Scheduled 0 outputs (0 slow hosts and0 dup hosts)
[junit] attempt_20090825191058650_0002_r_000000_0: 2009-08-25 19:11:43,926 INFO mapred.ReduceTask (ReduceTask.java:run(2692)) - attempt_20090825191058650_0002_r_000000_0: Got 2 new map-outputs
[junit] attempt_20090825191058650_0002_r_000000_0: 2009-08-25 19:11:47,931 INFO mapred.ReduceTask (ReduceTask.java:run(2692)) - attempt_20090825191058650_0002_r_000000_0: Got 1 new map-outputs
[junit] attempt_20090825191058650_0002_r_000000_0: 2009-08-25 19:11:48,921 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2005)) - attempt_20090825191058650_0002_r_000000_0 Scheduled 1 outputs (0 slow hosts and0 dup hosts)
[junit] attempt_20090825191058650_0002_r_000000_0: 2009-08-25 19:11:48,959 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1423)) - header: attempt_20090825191058650_0002_m_000000_0, compressed len: 11, decompressed len: 7
[junit] attempt_20090825191058650_0002_r_000000_0: 2009-08-25 19:11:48,959 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1437)) - Shuffling 7 bytes (11 raw bytes) into RAM from attempt_20090825191058650_0002_m_000000_0
[junit] attempt_20090825191058650_0002_r_000000_0: 2009-08-25 19:11:48,964 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1566)) - Read 7 bytes from map-output for attempt_20090825191058650_0002_m_000000_0
[junit] attempt_20090825191058650_0002_r_000000_0: 2009-08-25 19:11:48,964 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1625)) - Rec #1 from attempt_20090825191058650_0002_m_000000_0 -> (2, 1) from localhost
[junit] attempt_20090825191058650_0002_r_000000_0: 2009-08-25 19:11:48,966 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2005)) - attempt_20090825191058650_0002_r_000000_0 Scheduled 1 outputs (0 slow hosts and0 dup hosts)
[junit] attempt_20090825191058650_0002_r_000000_0: 2009-08-25 19:11:48,968 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1423)) - header: attempt_20090825191058650_0002_m_000001_0, compressed len: 11, decompressed len: 7
[junit] attempt_20090825191058650_0002_r_000000_0: 2009-08-25 19:11:48,968 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1437)) - Shuffling 7 bytes (11 raw bytes) into RAM from attempt_20090825191058650_0002_m_000001_0
[junit] attempt_20090825191058650_0002_r_000000_0: 2009-08-25 19:11:48,968 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1566)) - Read 7 bytes from map-output for attempt_20090825191058650_0002_m_000001_0
[junit] attempt_20090825191058650_0002_r_000000_0: 2009-08-25 19:11:48,969 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1625)) - Rec #1 from attempt_20090825191058650_0002_m_000001_0 -> (2, 1) from localhost
[junit] attempt_20090825191058650_0002_r_000000_0: 2009-08-25 19:11:48,969 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2005)) - attempt_20090825191058650_0002_r_000000_0 Scheduled 1 outputs (0 slow hosts and0 dup hosts)
[junit] attempt_20090825191058650_0002_r_000000_0: 2009-08-25 19:11:48,974 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1423)) - header: attempt_20090825191058650_0002_m_000002_0, compressed len: 11, decompressed len: 7
[junit] attempt_20090825191058650_0002_r_000000_0: 2009-08-25 19:11:48,974 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1437)) - Shuffling 7 bytes (11 raw bytes) into RAM from attempt_20090825191058650_0002_m_000002_0
[junit] attempt_20090825191058650_0002_r_000000_0: 2009-08-25 19:11:48,975 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1566)) - Read 7 bytes from map-output for attempt_20090825191058650_0002_m_000002_0
[junit] attempt_20090825191058650_0002_r_000000_0: 2009-08-25 19:11:48,975 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1625)) - Rec #1 from attempt_20090825191058650_0002_m_000002_0 -> (2, 1) from localhost
[junit] attempt_20090825191058650_0002_r_000000_0: 2009-08-25 19:11:49,932 INFO mapred.ReduceTask (ReduceTask.java:run(2710)) - GetMapEventsThread exiting
[junit] attempt_20090825191058650_0002_r_000000_0: 2009-08-25 19:11:49,932 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2203)) - getMapsEventsThread joined.
[junit] attempt_20090825191058650_0002_r_000000_0: 2009-08-25 19:11:49,932 INFO mapred.ReduceTask (ReduceTask.java:close(1117)) - Closed ram manager
[junit] attempt_20090825191058650_0002_r_000000_0: 2009-08-25 19:11:49,933 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2231)) - Interleaved on-disk merge complete: 0 files left.
[junit] attempt_20090825191058650_0002_r_000000_0: 2009-08-25 19:11:49,933 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2236)) - In-memory merge complete: 3 files left.
[junit] attempt_20090825191058650_0002_r_000000_0: 2009-08-25 19:11:49,957 INFO mapred.Merger (Merger.java:merge(469)) - Merging 3 sorted segments
[junit] attempt_20090825191058650_0002_r_000000_0: 2009-08-25 19:11:49,958 INFO mapred.Merger (Merger.java:merge(568)) - Down to the last merge-pass, with 3 segments left of total size: 9 bytes
[junit] attempt_20090825191058650_0002_r_000000_0: 2009-08-25 19:11:49,969 INFO mapred.ReduceTask (ReduceTask.java:createKVIterator(2349)) - Merged 3 segments, 21 bytes to disk to satisfy reduce memory limit
[junit] attempt_20090825191058650_0002_r_000000_0: 2009-08-25 19:11:49,970 INFO mapred.ReduceTask (ReduceTask.java:createKVIterator(2369)) - Merging 1 files, 21 bytes from disk
[junit] attempt_20090825191058650_0002_r_000000_0: 2009-08-25 19:11:49,970 INFO mapred.ReduceTask (ReduceTask.java:createKVIterator(2383)) - Merging 0 segments, 0 bytes from memory into reduce
[junit] attempt_20090825191058650_0002_r_000000_0: 2009-08-25 19:11:49,970 INFO mapred.Merger (Merger.java:merge(469)) - Merging 1 sorted segments
[junit] attempt_20090825191058650_0002_r_000000_0: 2009-08-25 19:11:49,974 INFO mapred.Merger (Merger.java:merge(568)) - Down to the last merge-pass, with 1 segments left of total size: 13 bytes
[junit] attempt_20090825191058650_0002_r_000000_0: 2009-08-25 19:11:50,191 INFO mapred.Task (Task.java:done(643)) - Task:attempt_20090825191058650_0002_r_000000_0 is done. And is in the process of commiting
[junit] attempt_20090825191058650_0002_r_000000_0: 2009-08-25 19:11:52,199 INFO mapred.Task (Task.java:commit(755)) - Task attempt_20090825191058650_0002_r_000000_0 is allowed to commit now
[junit] attempt_20090825191058650_0002_r_000000_0: 2009-08-25 19:11:52,291 INFO mapred.FileOutputCommitter (FileOutputCommitter.java:commitTask(92)) - Saved output of task 'attempt_20090825191058650_0002_r_000000_0' to hdfs://localhost:60424/user/hudson/mapout
[junit] attempt_20090825191058650_0002_r_000000_0: 2009-08-25 19:11:52,294 INFO mapred.Task (Task.java:sendDone(714)) - Task 'attempt_20090825191058650_0002_r_000000_0' done.
[junit] 2009-08-25 19:11:55,474 INFO mapred.TaskTracker (TaskTracker.java:getTask(2825)) - JVM with ID: jvm_20090825191058650_0002_m_-139254037 given task: attempt_20090825191058650_0002_m_000003_0
[junit] 2009-08-25 19:11:55,842 INFO mapred.TaskTracker (TaskTracker.java:reportProgress(2272)) - attempt_20090825191058650_0002_m_000003_0 0.0%
[junit] 2009-08-25 19:11:55,865 INFO FSNamesystem.audit (FSNamesystem.java:logAuditEvent(114)) - ugi=hudson,hudson ip=/127.0.0.1 cmd=delete src=/user/hudson/mapout/_temporary dst=null perm=null
[junit] 2009-08-25 19:11:55,869 INFO mapred.TaskTracker (TaskTracker.java:reportProgress(2272)) - attempt_20090825191058650_0002_m_000003_0 0.0% cleanup > map
[junit] 2009-08-25 19:11:55,870 INFO mapred.TaskTracker (TaskTracker.java:reportDone(2353)) - Task attempt_20090825191058650_0002_m_000003_0 is done.
[junit] 2009-08-25 19:11:55,870 INFO mapred.TaskTracker (TaskTracker.java:reportDone(2354)) - reported output size for attempt_20090825191058650_0002_m_000003_0 was 0
[junit] 2009-08-25 19:11:55,870 INFO mapred.TaskTracker (TaskTracker.java:addFreeSlots(1928)) - addFreeSlot : current free slots : 2
[junit] 2009-08-25 19:11:56,029 INFO mapred.JobClient (JobClient.java:monitorAndPrintJob(1301)) - map 100% reduce 100%
[junit] 2009-08-25 19:11:56,092 WARN util.ProcessTree (ProcessTree.java:terminateProcessGroup(136)) - Error executing shell command org.apache.hadoop.util.Shell$ExitCodeException: kill: No such process
[junit]
[junit] 2009-08-25 19:11:56,093 INFO util.ProcessTree (ProcessTree.java:terminateProcessGroup(138)) - Killing all processes in the process group 14146 with SIGTERM. Exit code 1
[junit] 2009-08-25 19:11:57,513 INFO mapred.JvmManager (JvmManager.java:runChild(423)) - JVM : jvm_20090825191058650_0002_r_276255696 exited with exit code 0. Number of tasks it ran: 1
[junit] 2009-08-25 19:11:57,969 INFO mapred.TaskTracker (TaskTracker.java:tryToGetOutputSize(1880)) - org.apache.hadoop.util.DiskChecker$DiskErrorException: Could not find output/file.out in any of the configured local directories
[junit] 2009-08-25 19:11:57,971 INFO mapred.JobInProgress (JobInProgress.java:completedTask(2450)) - Task 'attempt_20090825191058650_0002_m_000003_0' has completed task_20090825191058650_0002_m_000003 successfully.
[junit] 2009-08-25 19:11:57,972 INFO mapred.JobInProgress (JobInProgress.java:jobComplete(2616)) - Job job_20090825191058650_0002 has completed successfully.
[junit] 2009-08-25 19:11:57,972 INFO mapred.JobInProgress$JobSummary (JobInProgress.java:logJobSummary(3314)) - jobId=job_20090825191058650_0002,submitTime=1251227495904,launchTime=1251227496044,finishTime=1251227517972,numMaps=3,numSlotsPerMap=1,numReduces=1,numSlotsPerReduce=1,user=hudson,queue=default,status=SUCCEEDED,mapSlotSeconds=5,reduceSlotsSeconds=9,clusterMapCapacity=4,clusterReduceCapacity=4
[junit] 2009-08-25 19:11:57,976 INFO hdfs.StateChange (FSNamesystem.java:allocateBlock(1303)) - BLOCK* NameSystem.allocateBlock: /user/hudson/mapout/_logs/history/localhost_1251227458685_job_20090825191058650_0002_hudson_NA. blk_3691205440242050675_1015
[junit] 2009-08-25 19:11:57,978 INFO datanode.DataNode (DataXceiver.java:opWriteBlock(222)) - Receiving block blk_3691205440242050675_1015 src: /127.0.0.1:49573 dest: /127.0.0.1:42515
[junit] 2009-08-25 19:11:58,001 INFO datanode.DataNode (DataXceiver.java:opWriteBlock(222)) - Receiving block blk_3691205440242050675_1015 src: /127.0.0.1:55731 dest: /127.0.0.1:51658
[junit] 2009-08-25 19:11:58,004 INFO DataNode.clienttrace (BlockReceiver.java:lastDataNodeRun(822)) - src: /127.0.0.1:55731, dest: /127.0.0.1:51658, bytes: 12041, op: HDFS_WRITE, cliID: DFSClient_1248962688, offset: 0, srvID: DS-1780204725-67.195.138.9-51658-1251227458422, blockid: blk_3691205440242050675_1015, duration: 1726075
[junit] 2009-08-25 19:11:58,005 INFO datanode.DataNode (BlockReceiver.java:lastDataNodeRun(853)) - PacketResponder 0 for block blk_3691205440242050675_1015 terminating
[junit] 2009-08-25 19:11:58,005 INFO hdfs.StateChange (BlockManager.java:addStoredBlock(950)) - BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:51658 is added to blk_3691205440242050675_1015 size 12041
[junit] 2009-08-25 19:11:58,006 INFO DataNode.clienttrace (BlockReceiver.java:run(955)) - src: /127.0.0.1:49573, dest: /127.0.0.1:42515, bytes: 12041, op: HDFS_WRITE, cliID: DFSClient_1248962688, offset: 0, srvID: DS-1957820249-67.195.138.9-42515-1251227457805, blockid: blk_3691205440242050675_1015, duration: 3433739
[junit] 2009-08-25 19:11:58,007 INFO datanode.DataNode (BlockReceiver.java:run(1025)) - PacketResponder 1 for block blk_3691205440242050675_1015 terminating
[junit] 2009-08-25 19:11:58,008 INFO hdfs.StateChange (BlockManager.java:addStoredBlock(950)) - BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:42515 is added to blk_3691205440242050675_1015 size 12041
[junit] 2009-08-25 19:11:58,009 INFO hdfs.StateChange (FSNamesystem.java:completeFileInternal(1269)) - DIR* NameSystem.completeFile: file /user/hudson/mapout/_logs/history/localhost_1251227458685_job_20090825191058650_0002_hudson_NA is closed by DFSClient_1248962688
[junit] 2009-08-25 19:11:58,009 INFO namenode.FSNamesystem (FSEditLog.java:printStatistics(884)) - Number of transactions: 87 Total time for transactions(ms): 5Number of transactions batched in Syncs: 5 Number of syncs: 61 SyncTimes(ms): 685 549
[junit] 2009-08-25 19:11:58,040 INFO mapred.JobHistory (JobHistory.java:run(217)) - Moving http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/logs/history/localhost_1251227458685_job_20090825191058650_0002_hudson_NA to http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/logs/history/done
[junit] 2009-08-25 19:11:58,041 INFO hdfs.StateChange (BlockManager.java:addToInvalidates(363)) - BLOCK* NameSystem.addToInvalidates: blk_-976362673111536312 is added to invalidSet of 127.0.0.1:51658
[junit] 2009-08-25 19:11:58,041 INFO hdfs.StateChange (BlockManager.java:addToInvalidates(363)) - BLOCK* NameSystem.addToInvalidates: blk_-976362673111536312 is added to invalidSet of 127.0.0.1:42515
[junit] 2009-08-25 19:11:58,041 INFO hdfs.StateChange (BlockManager.java:addToInvalidates(363)) - BLOCK* NameSystem.addToInvalidates: blk_-1873179759931424633 is added to invalidSet of 127.0.0.1:51658
[junit] 2009-08-25 19:11:58,041 INFO hdfs.StateChange (BlockManager.java:addToInvalidates(363)) - BLOCK* NameSystem.addToInvalidates: blk_-1873179759931424633 is added to invalidSet of 127.0.0.1:42515
[junit] 2009-08-25 19:11:58,042 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2338)) - Removed completed task 'attempt_20090825191058650_0002_m_000000_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:54026'
[junit] 2009-08-25 19:11:58,042 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2338)) - Removed completed task 'attempt_20090825191058650_0002_m_000001_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:54026'
[junit] 2009-08-25 19:11:58,042 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2338)) - Removed completed task 'attempt_20090825191058650_0002_m_000003_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:54026'
[junit] 2009-08-25 19:11:58,042 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2338)) - Removed completed task 'attempt_20090825191058650_0002_m_000004_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:54026'
[junit] 2009-08-25 19:11:58,049 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2338)) - Removed completed task 'attempt_20090825191058650_0002_r_000000_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:54026'
[junit] 2009-08-25 19:11:58,051 INFO mapred.JobClient (JobClient.java:monitorAndPrintJob(1350)) - Task Id : attempt_20090825191058650_0002_m_000003_0, Status : SUCCEEDED
[junit] 2009-08-25 19:11:58,051 INFO mapred.TaskTracker (TaskTracker.java:purgeJob(1677)) - Received 'KillJobAction' for job: job_20090825191058650_0002
[junit] 2009-08-25 19:11:58,052 INFO mapred.TaskRunner (MapTaskRunner.java:close(44)) - attempt_20090825191058650_0002_m_000000_0 done; removing files.
[junit] 2009-08-25 19:11:58,053 INFO mapred.TaskRunner (MapTaskRunner.java:close(44)) - attempt_20090825191058650_0002_m_000001_0 done; removing files.
[junit] attempt_20090825191058650_0002_m_000003_0: 2009-08-25 19:11:55,724 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Initializing JVM Metrics with processName=MAP, sessionId=
[junit] 2009-08-25 19:11:58,053 INFO mapred.TaskRunner (MapTaskRunner.java:close(44)) - attempt_20090825191058650_0002_m_000003_0 done; removing files.
[junit] attempt_20090825191058650_0002_m_000003_0: 2009-08-25 19:11:55,866 INFO mapred.Task (Task.java:done(643)) - Task:attempt_20090825191058650_0002_m_000003_0 is done. And is in the process of commiting
[junit] attempt_20090825191058650_0002_m_000003_0: 2009-08-25 19:11:55,870 INFO mapred.Task (Task.java:sendDone(714)) - Task 'attempt_20090825191058650_0002_m_000003_0' done.
[junit] 2009-08-25 19:11:58,054 INFO mapred.IndexCache (IndexCache.java:removeMap(140)) - Map ID attempt_20090825191058650_0002_m_000003_0 not found in cache
[junit] 2009-08-25 19:11:58,055 INFO mapred.JobClient (JobClient.java:monitorAndPrintJob(1356)) - Job complete: job_20090825191058650_0002
[junit] 2009-08-25 19:11:58,058 INFO mapred.JobClient (Counters.java:log(534)) - Counters: 22
[junit] 2009-08-25 19:11:58,058 INFO mapred.JobClient (Counters.java:log(536)) - Job Counters
[junit] 2009-08-25 19:11:58,058 INFO mapred.JobClient (Counters.java:log(538)) - Launched reduce tasks=1
[junit] 2009-08-25 19:11:58,059 INFO mapred.JobClient (Counters.java:log(538)) - SLOTS_MILLIS_MAPS=5563
[junit] 2009-08-25 19:11:58,059 INFO mapred.JobClient (Counters.java:log(538)) - Total time spent by all reduces waiting after reserving slots (ms)=0
[junit] 2009-08-25 19:11:58,059 INFO mapred.JobClient (Counters.java:log(538)) - Total time spent by all maps waiting after reserving slots (ms)=0
[junit] 2009-08-25 19:11:58,060 INFO mapred.JobClient (Counters.java:log(538)) - Rack-local map tasks=3
[junit] 2009-08-25 19:11:58,069 INFO mapred.JobClient (Counters.java:log(538)) - Launched map tasks=3
[junit] 2009-08-25 19:11:58,069 INFO mapred.JobClient (Counters.java:log(538)) - SLOTS_MILLIS_REDUCES=9295
[junit] 2009-08-25 19:11:58,069 INFO FSNamesystem.audit (FSNamesystem.java:logAuditEvent(114)) - ugi=hudson,hudson ip=/127.0.0.1 cmd=delete src=/tmp/hadoop-hudson/mapred/system/job_20090825191058650_0002 dst=null perm=null
[junit] 2009-08-25 19:11:58,069 INFO mapred.JobClient (Counters.java:log(536)) - FileInputFormatCounters
[junit] 2009-08-25 19:11:58,070 INFO mapred.JobClient (Counters.java:log(538)) - BYTES_READ=3
[junit] 2009-08-25 19:11:58,070 INFO mapred.JobClient (Counters.java:log(536)) - FileSystemCounters
[junit] 2009-08-25 19:11:58,071 INFO mapred.JobClient (Counters.java:log(538)) - FILE_BYTES_READ=21
[junit] 2009-08-25 19:11:58,071 INFO mapred.JobClient (Counters.java:log(538)) - HDFS_BYTES_READ=828
[junit] 2009-08-25 19:11:58,071 INFO mapred.JobClient (Counters.java:log(538)) - FILE_BYTES_WRITTEN=150
[junit] 2009-08-25 19:11:58,071 INFO mapred.JobClient (Counters.java:log(538)) - HDFS_BYTES_WRITTEN=6
[junit] 2009-08-25 19:11:58,072 INFO mapred.JobClient (Counters.java:log(536)) - Map-Reduce Framework
[junit] 2009-08-25 19:11:58,072 INFO mapred.JobClient (Counters.java:log(538)) - Reduce input groups=3
[junit] 2009-08-25 19:11:58,072 INFO mapred.JobClient (Counters.java:log(538)) - Combine output records=0
[junit] 2009-08-25 19:11:58,072 INFO mapred.JobClient (Counters.java:log(538)) - Map input records=3
[junit] 2009-08-25 19:11:58,073 INFO mapred.JobClient (Counters.java:log(538)) - Reduce shuffle bytes=22
[junit] 2009-08-25 19:11:58,073 INFO mapred.JobClient (Counters.java:log(538)) - Reduce output records=3
[junit] 2009-08-25 19:11:58,073 INFO mapred.JobClient (Counters.java:log(538)) - Spilled Records=6
[junit] 2009-08-25 19:11:58,073 INFO mapred.JobClient (Counters.java:log(538)) - Map output bytes=9
[junit] 2009-08-25 19:11:58,073 INFO mapred.JobClient (Counters.java:log(538)) - Combine input records=0
[junit] 2009-08-25 19:11:58,074 INFO mapred.JobClient (Counters.java:log(538)) - Map output records=3
[junit] 2009-08-25 19:11:58,074 INFO mapred.JobClient (Counters.java:log(538)) - Reduce input records=3
[junit] 2009-08-25 19:11:58,078 INFO FSNamesystem.audit (FSNamesystem.java:logAuditEvent(114)) - ugi=hudson,hudson ip=/127.0.0.1 cmd=listStatus src=/user/hudson/mapout dst=null perm=null
[junit] Found 2 items
[junit] drwxr-xr-x - hudson supergroup 0 2009-08-25 19:11 /user/hudson/mapout/_logs
[junit] -rw-r--r-- 3 hudson supergroup 6 2009-08-25 19:11 /user/hudson/mapout/part-00000
[junit] 2009-08-25 19:11:58,080 INFO FSNamesystem.audit (FSNamesystem.java:logAuditEvent(114)) - ugi=hudson,hudson ip=/127.0.0.1 cmd=listStatus src=/user/hudson/mapout dst=null perm=null
[junit] 2009-08-25 19:11:58,081 INFO mapred.JobHistory (JobHistory.java:run(217)) - Moving http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/logs/history/localhost_1251227458685_job_20090825191058650_0002_conf.xml to http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/logs/history/done
[junit] 2009-08-25 19:11:58,094 INFO FSNamesystem.audit (FSNamesystem.java:logAuditEvent(114)) - ugi=hudson,hudson ip=/127.0.0.1 cmd=open src=/user/hudson/mapout/part-00000 dst=null perm=null
[junit] 2009-08-25 19:11:58,097 INFO DataNode.clienttrace (BlockSender.java:sendBlock(417)) - src: /127.0.0.1:42515, dest: /127.0.0.1:49575, bytes: 10, op: HDFS_READ, cliID: DFSClient_1248962688, offset: 0, srvID: DS-1957820249-67.195.138.9-42515-1251227457805, blockid: blk_-5624075441105808244_1015, duration: 262843
[junit] 2009-08-25 19:11:58,097 INFO mapred.MiniMRCluster (MiniMRCluster.java:waitTaskTrackers(306)) - Waiting for task tracker tracker_host0.foo.com:localhost/127.0.0.1:39635 to be idle.
[junit] 2009-08-25 19:11:58,125 INFO mapred.JobHistory (JobHistory.java:cleanupJob(1057)) - Deleting localized job conf at http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/logs/job_20090825191058650_0002_conf.xml
[junit] 2009-08-25 19:11:58,853 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2338)) - Removed completed task 'attempt_20090825191058650_0002_m_000002_0' from 'tracker_host0.foo.com:localhost/127.0.0.1:39635'
[junit] 2009-08-25 19:11:58,854 INFO mapred.TaskTracker (TaskTracker.java:purgeJob(1677)) - Received 'KillJobAction' for job: job_20090825191058650_0002
[junit] 2009-08-25 19:11:58,855 INFO mapred.TaskRunner (MapTaskRunner.java:close(44)) - attempt_20090825191058650_0002_m_000002_0 done; removing files.
[junit] 2009-08-25 19:11:59,098 INFO mapred.TaskTracker (TaskTracker.java:run(687)) - Shutting down: Map-events fetcher for all reduce tasks on tracker_host0.foo.com:localhost/127.0.0.1:39635
[junit] 2009-08-25 19:11:59,098 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 39635
[junit] 2009-08-25 19:11:59,099 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 39635: exiting
[junit] 2009-08-25 19:11:59,099 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 39635: exiting
[junit] 2009-08-25 19:11:59,099 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 39635: exiting
[junit] 2009-08-25 19:11:59,099 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 3 on 39635: exiting
[junit] 2009-08-25 19:11:59,100 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 39635
[junit] 2009-08-25 19:11:59,100 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
[junit] 2009-08-25 19:11:59,100 INFO mapred.TaskTracker (TaskTracker.java:shutdown(1155)) - Shutting down StatusHttpServer
[junit] 2009-08-25 19:11:59,222 INFO mapred.TaskTracker (TaskTracker.java:offerService(1445)) - Interrupted. Closing down.
[junit] 2009-08-25 19:11:59,223 INFO mapred.TaskTracker (TaskTracker.java:run(687)) - Shutting down: Map-events fetcher for all reduce tasks on tracker_host1.foo.com:localhost/127.0.0.1:54026
[junit] 2009-08-25 19:11:59,223 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 54026
[junit] 2009-08-25 19:11:59,224 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 54026: exiting
[junit] 2009-08-25 19:11:59,224 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 54026: exiting
[junit] 2009-08-25 19:11:59,224 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 54026: exiting
[junit] 2009-08-25 19:11:59,224 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 54026
[junit] 2009-08-25 19:11:59,224 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 3 on 54026: exiting
[junit] 2009-08-25 19:11:59,224 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
[junit] 2009-08-25 19:11:59,224 INFO mapred.TaskTracker (TaskTracker.java:shutdown(1155)) - Shutting down StatusHttpServer
[junit] 2009-08-25 19:11:59,334 INFO mapred.TaskTracker (TaskTracker.java:offerService(1445)) - Interrupted. Closing down.
[junit] 2009-08-25 19:11:59,335 INFO mapred.JobTracker (JobTracker.java:close(2165)) - Stopping infoServer
[junit] 2009-08-25 19:11:59,437 INFO mapred.JobTracker (JobTracker.java:close(2173)) - Stopping interTrackerServer
[junit] 2009-08-25 19:11:59,437 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 40648
[junit] 2009-08-25 19:11:59,437 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 40648: exiting
[junit] 2009-08-25 19:11:59,438 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 40648: exiting
[junit] 2009-08-25 19:11:59,438 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 40648
[junit] 2009-08-25 19:11:59,438 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 40648: exiting
[junit] 2009-08-25 19:11:59,438 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 3 on 40648: exiting
[junit] 2009-08-25 19:11:59,438 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 4 on 40648: exiting
[junit] 2009-08-25 19:11:59,438 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 9 on 40648: exiting
[junit] 2009-08-25 19:11:59,438 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 6 on 40648: exiting
[junit] 2009-08-25 19:11:59,438 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 8 on 40648: exiting
[junit] 2009-08-25 19:11:59,438 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 5 on 40648: exiting
[junit] 2009-08-25 19:11:59,438 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 7 on 40648: exiting
[junit] 2009-08-25 19:11:59,439 INFO mapred.JobTracker (JobTracker.java:stopExpireTrackersThread(2207)) - Stopping expireTrackers
[junit] 2009-08-25 19:11:59,439 INFO mapred.JobTracker (JobTracker.java:offerService(2160)) - Stopped interTrackerServer
[junit] 2009-08-25 19:11:59,439 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
[junit] 2009-08-25 19:11:59,440 INFO mapred.EagerTaskInitializationListener (EagerTaskInitializationListener.java:terminate(106)) - Stopping Job Init Manager thread
[junit] 2009-08-25 19:11:59,441 INFO mapred.EagerTaskInitializationListener (EagerTaskInitializationListener.java:run(60)) - JobInitManagerThread interrupted.
[junit] 2009-08-25 19:11:59,441 INFO mapred.EagerTaskInitializationListener (EagerTaskInitializationListener.java:run(64)) - Shutting down thread pool
[junit] 2009-08-25 19:11:59,441 INFO mapred.JobTracker (JobTracker.java:close(2183)) - Stopping expireLaunchingTasks
[junit] 2009-08-25 19:11:59,441 INFO mapred.JobTracker (JobTracker.java:close(2201)) - stopped all jobtracker services
[junit] Shutting down the Mini HDFS Cluster
[junit] Shutting down DataNode 1
[junit] 2009-08-25 19:11:59,586 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 60486
[junit] 2009-08-25 19:11:59,587 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 60486: exiting
[junit] 2009-08-25 19:11:59,587 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 60486
[junit] 2009-08-25 19:11:59,587 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
[junit] 2009-08-25 19:11:59,587 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 60486: exiting
[junit] 2009-08-25 19:11:59,587 WARN datanode.DataNode (DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:51658, storageID=DS-1780204725-67.195.138.9-51658-1251227458422, infoPort=52753, ipcPort=60486):DataXceiveServer: java.nio.channels.AsynchronousCloseException
[junit] at java.nio.channels.spi.AbstractInterruptibleChannel.end(AbstractInterruptibleChannel.java:185)
[junit] at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:152)
[junit] at sun.nio.ch.ServerSocketAdaptor.accept(ServerSocketAdaptor.java:84)
[junit] at org.apache.hadoop.hdfs.server.datanode.DataXceiverServer.run(DataXceiverServer.java:130)
[junit] at java.lang.Thread.run(Thread.java:619)
[junit]
[junit] 2009-08-25 19:11:59,587 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 60486: exiting
[junit] 2009-08-25 19:11:59,587 INFO datanode.DataNode (DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads is 1
[junit] 2009-08-25 19:11:59,588 INFO datanode.DataBlockScanner (DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
[junit] 2009-08-25 19:11:59,589 INFO datanode.DataNode (DataNode.java:run(1305)) - DatanodeRegistration(127.0.0.1:51658, storageID=DS-1780204725-67.195.138.9-51658-1251227458422, infoPort=52753, ipcPort=60486):Finishing DataNode in: FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/data/dfs/data/data3/current,/home/hudson/hudson-slave/workspace/Hadoop-Mapreduce-trunk/trunk/build/test/data/dfs/data/data4/current'}
[junit] 2009-08-25 19:11:59,589 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 60486
[junit] 2009-08-25 19:11:59,589 INFO datanode.DataNode (DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads is 0
[junit] Shutting down DataNode 0
[junit] 2009-08-25 19:11:59,691 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 51151
[junit] 2009-08-25 19:11:59,691 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 51151: exiting
[junit] 2009-08-25 19:11:59,692 INFO datanode.DataNode (DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads is 1
[junit] 2009-08-25 19:11:59,692 WARN datanode.DataNode (DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:42515, storageID=DS-1957820249-67.195.138.9-42515-1251227457805, infoPort=50904, ipcPort=51151):DataXceiveServer: java.nio.channels.AsynchronousCloseException
[junit] at java.nio.channels.spi.AbstractInterruptibleChannel.end(AbstractInterruptibleChannel.java:185)
[junit] at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:152)
[junit] at sun.nio.ch.ServerSocketAdaptor.accept(ServerSocketAdaptor.java:84)
[junit] at org.apache.hadoop.hdfs.server.datanode.DataXceiverServer.run(DataXceiverServer.java:130)
[junit] at java.lang.Thread.run(Thread.java:619)
[junit]
[junit] 2009-08-25 19:11:59,692 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
[junit] 2009-08-25 19:11:59,691 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 51151: exiting
[junit] 2009-08-25 19:11:59,692 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 51151
[junit] 2009-08-25 19:11:59,691 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 51151: exiting
[junit] 2009-08-25 19:11:59,695 INFO datanode.DataNode (DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads is 0
[junit] 2009-08-25 19:11:59,695 INFO datanode.DataBlockScanner (DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
[junit] 2009-08-25 19:11:59,695 INFO datanode.DataNode (DataNode.java:run(1305)) - DatanodeRegistration(127.0.0.1:42515, storageID=DS-1957820249-67.195.138.9-42515-1251227457805, infoPort=50904, ipcPort=51151):Finishing DataNode in: FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/data/dfs/data/data1/current,/home/hudson/hudson-slave/workspace/Hadoop-Mapreduce-trunk/trunk/build/test/data/dfs/data/data2/current'}
[junit] 2009-08-25 19:11:59,695 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 51151
[junit] 2009-08-25 19:11:59,696 INFO datanode.DataNode (DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads is 0
[junit] 2009-08-25 19:11:59,804 WARN namenode.FSNamesystem (FSNamesystem.java:run(2077)) - ReplicationMonitor thread received InterruptedException.java.lang.InterruptedException: sleep interrupted
[junit] 2009-08-25 19:11:59,804 WARN namenode.DecommissionManager (DecommissionManager.java:run(67)) - Monitor interrupted: java.lang.InterruptedException: sleep interrupted
[junit] 2009-08-25 19:11:59,805 INFO namenode.FSNamesystem (FSEditLog.java:printStatistics(884)) - Number of transactions: 88 Total time for transactions(ms): 5Number of transactions batched in Syncs: 5 Number of syncs: 63 SyncTimes(ms): 706 583
[junit] 2009-08-25 19:11:59,837 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 60424
[junit] 2009-08-25 19:11:59,838 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 60424: exiting
[junit] 2009-08-25 19:11:59,838 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 7 on 60424: exiting
[junit] 2009-08-25 19:11:59,838 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 4 on 60424: exiting
[junit] 2009-08-25 19:11:59,838 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 8 on 60424: exiting
[junit] 2009-08-25 19:11:59,838 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 60424: exiting
[junit] 2009-08-25 19:11:59,839 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
[junit] 2009-08-25 19:11:59,839 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 60424
[junit] 2009-08-25 19:11:59,838 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 6 on 60424: exiting
[junit] Tests run: 2, Failures: 0, Errors: 0, Time elapsed: 105.846 sec
[junit] 2009-08-25 19:11:59,878 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 9 on 60424: exiting
[junit] 2009-08-25 19:11:59,878 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 3 on 60424: exiting
[junit] 2009-08-25 19:11:59,878 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 5 on 60424: exiting
[junit] 2009-08-25 19:11:59,878 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 60424: exiting
[junit] Running org.apache.hadoop.util.TestReflectionUtils
[junit] Tests run: 5, Failures: 0, Errors: 0, Time elapsed: 0.644 sec
[junit] Running org.apache.hadoop.util.TestRunJar
[junit] Creating filehttp://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/data/out
[junit] Tests run: 1, Failures: 0, Errors: 0, Time elapsed: 0.167 sec
checkfailure:
[touch] Creating http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/testsfailed
BUILD FAILED
http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build.xml :627: Tests failed!
Total time: 161 minutes 56 seconds
Publishing Javadoc
Recording test results
Recording fingerprints
Publishing Clover coverage report...