Return-Path: Delivered-To: apmail-hadoop-mapreduce-dev-archive@minotaur.apache.org Received: (qmail 75901 invoked from network); 19 Aug 2009 19:58:19 -0000 Received: from hermes.apache.org (HELO mail.apache.org) (140.211.11.3) by minotaur.apache.org with SMTP; 19 Aug 2009 19:58:19 -0000 Received: (qmail 26371 invoked by uid 500); 19 Aug 2009 19:58:35 -0000 Delivered-To: apmail-hadoop-mapreduce-dev-archive@hadoop.apache.org Received: (qmail 26313 invoked by uid 500); 19 Aug 2009 19:58:35 -0000 Mailing-List: contact mapreduce-dev-help@hadoop.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: mapreduce-dev@hadoop.apache.org Delivered-To: mailing list mapreduce-dev@hadoop.apache.org Received: (qmail 26173 invoked by uid 99); 19 Aug 2009 19:58:35 -0000 Received: from athena.apache.org (HELO athena.apache.org) (140.211.11.136) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 19 Aug 2009 19:58:35 +0000 X-ASF-Spam-Status: No, hits=-2000.0 required=10.0 tests=ALL_TRUSTED X-Spam-Check-By: apache.org Received: from [140.211.11.106] (HELO hudson.zones.apache.org) (140.211.11.106) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 19 Aug 2009 19:58:32 +0000 Received: from hudson.zones.apache.org (localhost [127.0.0.1]) by hudson.zones.apache.org (8.13.8+Sun/8.13.8) with ESMTP id n7JJwB5i004134 for ; Wed, 19 Aug 2009 15:58:12 -0400 (EDT) Date: Wed, 19 Aug 2009 19:58:02 +0000 (UTC) From: Apache Hudson Server To: mapreduce-dev@hadoop.apache.org Message-ID: <13952512.4671250711891802.JavaMail.hudson@hudson.zones.apache.org> In-Reply-To: <17460997.4391250622195332.JavaMail.hudson@hudson.zones.apache.org> References: <17460997.4391250622195332.JavaMail.hudson@hudson.zones.apache.org> Subject: Build failed in Hudson: Hadoop-Mapreduce-trunk #54 MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Transfer-Encoding: 7bit X-Virus-Checked: Checked by ClamAV on apache.org See http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/54/ ------------------------------------------ [...truncated 133711 lines...] [junit] 2009-08-19 19:56:01,290 INFO mapred.TaskTracker (TaskTracker.java:purgeTask(1716)) - About to purge task: attempt_200908191955_0002_r_000000_0 [junit] 2009-08-19 19:56:01,290 INFO mapred.TaskRunner (ReduceTaskRunner.java:close(47)) - attempt_200908191955_0002_r_000000_0 done; removing files. [junit] 2009-08-19 19:56:01,334 INFO mapred.JvmManager (JvmManager.java:(396)) - In JvmRunner constructed JVM ID: jvm_200908191955_0002_m_1974660217 [junit] 2009-08-19 19:56:01,335 INFO mapred.JvmManager (JvmManager.java:spawnNewJvm(364)) - JVM Runner jvm_200908191955_0002_m_1974660217 spawned. [junit] 2009-08-19 19:56:01,347 INFO mapred.JobClient (JobClient.java:monitorAndPrintJob(1364)) - Task Id : attempt_200908191955_0002_r_000000_0, Status : SUCCEEDED [junit] attempt_200908191955_0002_r_000000_0: 2009-08-19 19:55:50,025 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Initializing JVM Metrics with processName=SHUFFLE, sessionId= [junit] attempt_200908191955_0002_r_000000_0: 2009-08-19 19:55:50,151 INFO mapred.ReduceTask (ReduceTask.java:(1011)) - ShuffleRamManager: MemoryLimit=141387360, MaxSingleShuffleLimit=35346840 [junit] attempt_200908191955_0002_r_000000_0: 2009-08-19 19:55:50,158 INFO mapred.ReduceTask (ReduceTask.java:run(2485)) - attempt_200908191955_0002_r_000000_0 Thread started: Thread for merging on-disk files [junit] attempt_200908191955_0002_r_000000_0: 2009-08-19 19:55:50,158 INFO mapred.ReduceTask (ReduceTask.java:run(2584)) - attempt_200908191955_0002_r_000000_0 Thread started: Thread for merging in memory files [junit] attempt_200908191955_0002_r_000000_0: 2009-08-19 19:55:50,158 INFO mapred.ReduceTask (ReduceTask.java:run(2490)) - attempt_200908191955_0002_r_000000_0 Thread waiting: Thread for merging on-disk files [junit] attempt_200908191955_0002_r_000000_0: 2009-08-19 19:55:50,160 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(1892)) - attempt_200908191955_0002_r_000000_0 Need another 3 map output(s) where 0 is already in progress [junit] attempt_200908191955_0002_r_000000_0: 2009-08-19 19:55:50,160 INFO mapred.ReduceTask (ReduceTask.java:run(2686)) - attempt_200908191955_0002_r_000000_0 Thread started: Thread for polling Map Completion Events [junit] attempt_200908191955_0002_r_000000_0: 2009-08-19 19:55:50,160 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2005)) - attempt_200908191955_0002_r_000000_0 Scheduled 0 outputs (0 slow hosts and0 dup hosts) [junit] attempt_200908191955_0002_r_000000_0: 2009-08-19 19:55:50,173 INFO mapred.ReduceTask (ReduceTask.java:run(2692)) - attempt_200908191955_0002_r_000000_0: Got 2 new map-outputs [junit] attempt_200908191955_0002_r_000000_0: 2009-08-19 19:55:54,178 INFO mapred.ReduceTask (ReduceTask.java:run(2692)) - attempt_200908191955_0002_r_000000_0: Got 1 new map-outputs [junit] attempt_200908191955_0002_r_000000_0: 2009-08-19 19:55:55,161 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2005)) - attempt_200908191955_0002_r_000000_0 Scheduled 1 outputs (0 slow hosts and0 dup hosts) [junit] attempt_200908191955_0002_r_000000_0: 2009-08-19 19:55:55,195 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1423)) - header: attempt_200908191955_0002_m_000000_0, compressed len: 11, decompressed len: 7 [junit] attempt_200908191955_0002_r_000000_0: 2009-08-19 19:55:55,196 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1437)) - Shuffling 7 bytes (11 raw bytes) into RAM from attempt_200908191955_0002_m_000000_0 [junit] attempt_200908191955_0002_r_000000_0: 2009-08-19 19:55:55,206 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1566)) - Read 7 bytes from map-output for attempt_200908191955_0002_m_000000_0 [junit] attempt_200908191955_0002_r_000000_0: 2009-08-19 19:55:55,206 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1625)) - Rec #1 from attempt_200908191955_0002_m_000000_0 -> (2, 1) from localhost [junit] attempt_200908191955_0002_r_000000_0: 2009-08-19 19:55:55,208 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2005)) - attempt_200908191955_0002_r_000000_0 Scheduled 1 outputs (0 slow hosts and0 dup hosts) [junit] attempt_200908191955_0002_r_000000_0: 2009-08-19 19:55:55,210 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1423)) - header: attempt_200908191955_0002_m_000001_0, compressed len: 11, decompressed len: 7 [junit] attempt_200908191955_0002_r_000000_0: 2009-08-19 19:55:55,210 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1437)) - Shuffling 7 bytes (11 raw bytes) into RAM from attempt_200908191955_0002_m_000001_0 [junit] attempt_200908191955_0002_r_000000_0: 2009-08-19 19:55:55,211 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1566)) - Read 7 bytes from map-output for attempt_200908191955_0002_m_000001_0 [junit] attempt_200908191955_0002_r_000000_0: 2009-08-19 19:55:55,212 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1625)) - Rec #1 from attempt_200908191955_0002_m_000001_0 -> (2, 1) from localhost [junit] attempt_200908191955_0002_r_000000_0: 2009-08-19 19:55:55,212 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2005)) - attempt_200908191955_0002_r_000000_0 Scheduled 1 outputs (0 slow hosts and0 dup hosts) [junit] attempt_200908191955_0002_r_000000_0: 2009-08-19 19:55:55,218 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1423)) - header: attempt_200908191955_0002_m_000002_0, compressed len: 11, decompressed len: 7 [junit] attempt_200908191955_0002_r_000000_0: 2009-08-19 19:55:55,218 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1437)) - Shuffling 7 bytes (11 raw bytes) into RAM from attempt_200908191955_0002_m_000002_0 [junit] attempt_200908191955_0002_r_000000_0: 2009-08-19 19:55:55,219 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1566)) - Read 7 bytes from map-output for attempt_200908191955_0002_m_000002_0 [junit] attempt_200908191955_0002_r_000000_0: 2009-08-19 19:55:55,219 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1625)) - Rec #1 from attempt_200908191955_0002_m_000002_0 -> (2, 1) from localhost [junit] attempt_200908191955_0002_r_000000_0: 2009-08-19 19:55:56,180 INFO mapred.ReduceTask (ReduceTask.java:run(2710)) - GetMapEventsThread exiting [junit] attempt_200908191955_0002_r_000000_0: 2009-08-19 19:55:56,180 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2203)) - getMapsEventsThread joined. [junit] attempt_200908191955_0002_r_000000_0: 2009-08-19 19:55:56,180 INFO mapred.ReduceTask (ReduceTask.java:close(1117)) - Closed ram manager [junit] attempt_200908191955_0002_r_000000_0: 2009-08-19 19:55:56,180 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2231)) - Interleaved on-disk merge complete: 0 files left. [junit] attempt_200908191955_0002_r_000000_0: 2009-08-19 19:55:56,181 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2236)) - In-memory merge complete: 3 files left. [junit] attempt_200908191955_0002_r_000000_0: 2009-08-19 19:55:56,204 INFO mapred.Merger (Merger.java:merge(469)) - Merging 3 sorted segments [junit] attempt_200908191955_0002_r_000000_0: 2009-08-19 19:55:56,204 INFO mapred.Merger (Merger.java:merge(568)) - Down to the last merge-pass, with 3 segments left of total size: 9 bytes [junit] attempt_200908191955_0002_r_000000_0: 2009-08-19 19:55:56,221 INFO mapred.ReduceTask (ReduceTask.java:createKVIterator(2349)) - Merged 3 segments, 21 bytes to disk to satisfy reduce memory limit [junit] attempt_200908191955_0002_r_000000_0: 2009-08-19 19:55:56,222 INFO mapred.ReduceTask (ReduceTask.java:createKVIterator(2369)) - Merging 1 files, 21 bytes from disk [junit] attempt_200908191955_0002_r_000000_0: 2009-08-19 19:55:56,223 INFO mapred.ReduceTask (ReduceTask.java:createKVIterator(2383)) - Merging 0 segments, 0 bytes from memory into reduce [junit] attempt_200908191955_0002_r_000000_0: 2009-08-19 19:55:56,223 INFO mapred.Merger (Merger.java:merge(469)) - Merging 1 sorted segments [junit] attempt_200908191955_0002_r_000000_0: 2009-08-19 19:55:56,227 INFO mapred.Merger (Merger.java:merge(568)) - Down to the last merge-pass, with 1 segments left of total size: 13 bytes [junit] attempt_200908191955_0002_r_000000_0: 2009-08-19 19:55:56,336 INFO mapred.Task (Task.java:done(643)) - Task:attempt_200908191955_0002_r_000000_0 is done. And is in the process of commiting [junit] attempt_200908191955_0002_r_000000_0: 2009-08-19 19:55:58,344 INFO mapred.Task (Task.java:commit(755)) - Task attempt_200908191955_0002_r_000000_0 is allowed to commit now [junit] attempt_200908191955_0002_r_000000_0: 2009-08-19 19:55:58,457 INFO mapred.FileOutputCommitter (FileOutputCommitter.java:commitTask(92)) - Saved output of task 'attempt_200908191955_0002_r_000000_0' to hdfs://localhost:57620/user/hudson/mapout [junit] attempt_200908191955_0002_r_000000_0: 2009-08-19 19:55:58,462 INFO mapred.Task (Task.java:sendDone(714)) - Task 'attempt_200908191955_0002_r_000000_0' done. [junit] 2009-08-19 19:56:01,780 INFO mapred.TaskTracker (TaskTracker.java:getTask(2819)) - JVM with ID: jvm_200908191955_0002_m_1974660217 given task: attempt_200908191955_0002_m_000003_0 [junit] 2009-08-19 19:56:02,195 INFO mapred.TaskTracker (TaskTracker.java:reportProgress(2266)) - attempt_200908191955_0002_m_000003_0 0.0% [junit] 2009-08-19 19:56:02,260 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-19 19:56:02,264 INFO mapred.TaskTracker (TaskTracker.java:reportProgress(2266)) - attempt_200908191955_0002_m_000003_0 0.0% cleanup > map [junit] 2009-08-19 19:56:02,265 INFO mapred.TaskTracker (TaskTracker.java:reportDone(2347)) - Task attempt_200908191955_0002_m_000003_0 is done. [junit] 2009-08-19 19:56:02,266 INFO mapred.TaskTracker (TaskTracker.java:reportDone(2348)) - reported output size for attempt_200908191955_0002_m_000003_0 was 0 [junit] 2009-08-19 19:56:02,266 INFO mapred.TaskTracker (TaskTracker.java:addFreeSlots(1922)) - addFreeSlot : current free slots : 2 [junit] 2009-08-19 19:56:02,353 INFO mapred.JobClient (JobClient.java:monitorAndPrintJob(1315)) - map 100% reduce 100% [junit] 2009-08-19 19:56:02,467 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-19 19:56:02,468 INFO util.ProcessTree (ProcessTree.java:terminateProcessGroup(138)) - Killing all processes in the process group 31118 with SIGTERM. Exit code 1 [junit] 2009-08-19 19:56:03,674 INFO mapred.JvmManager (JvmManager.java:runChild(423)) - JVM : jvm_200908191955_0002_r_1542028815 exited with exit code 0. Number of tasks it ran: 1 [junit] 2009-08-19 19:56:04,290 INFO mapred.TaskTracker (TaskTracker.java:tryToGetOutputSize(1874)) - org.apache.hadoop.util.DiskChecker$DiskErrorException: Could not find output/file.out in any of the configured local directories [junit] 2009-08-19 19:56:04,293 INFO mapred.JobInProgress (JobInProgress.java:completedTask(2450)) - Task 'attempt_200908191955_0002_m_000003_0' has completed task_200908191955_0002_m_000003 successfully. [junit] 2009-08-19 19:56:04,293 INFO mapred.JobInProgress (JobInProgress.java:jobComplete(2616)) - Job job_200908191955_0002 has completed successfully. [junit] 2009-08-19 19:56:04,294 INFO mapred.JobInProgress$JobSummary (JobInProgress.java:logJobSummary(3314)) - jobId=job_200908191955_0002,submitTime=1250711742239,launchTime=1250711742402,finishTime=1250711764293,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-19 19:56:04,298 INFO hdfs.StateChange (FSNamesystem.java:allocateBlock(1286)) - BLOCK* NameSystem.allocateBlock: /user/hudson/mapout/_logs/history/localhost_1250711705011_job_200908191955_0002_hudson_NA. blk_-7072735518092206564_1015 [junit] 2009-08-19 19:56:04,300 INFO datanode.DataNode (DataXceiver.java:writeBlock(240)) - Receiving block blk_-7072735518092206564_1015 src: /127.0.0.1:42916 dest: /127.0.0.1:49323 [junit] 2009-08-19 19:56:04,301 INFO datanode.DataNode (DataXceiver.java:writeBlock(240)) - Receiving block blk_-7072735518092206564_1015 src: /127.0.0.1:49913 dest: /127.0.0.1:57596 [junit] 2009-08-19 19:56:04,304 INFO DataNode.clienttrace (BlockReceiver.java:lastDataNodeRun(807)) - src: /127.0.0.1:49913, dest: /127.0.0.1:57596, bytes: 11831, op: HDFS_WRITE, cliID: DFSClient_-1965061630, offset: 0, srvID: DS-1737630840-67.195.138.9-57596-1250711704144, blockid: blk_-7072735518092206564_1015, duration: 1476419 [junit] 2009-08-19 19:56:04,304 INFO datanode.DataNode (BlockReceiver.java:lastDataNodeRun(831)) - PacketResponder 0 for block blk_-7072735518092206564_1015 terminating [junit] 2009-08-19 19:56:04,304 INFO hdfs.StateChange (BlockManager.java:addStoredBlock(955)) - BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:57596 is added to blk_-7072735518092206564_1015 size 11831 [junit] 2009-08-19 19:56:04,305 INFO DataNode.clienttrace (BlockReceiver.java:run(933)) - src: /127.0.0.1:42916, dest: /127.0.0.1:49323, bytes: 11831, op: HDFS_WRITE, cliID: DFSClient_-1965061630, offset: 0, srvID: DS-2105063903-67.195.138.9-49323-1250711704761, blockid: blk_-7072735518092206564_1015, duration: 2761024 [junit] 2009-08-19 19:56:04,305 INFO hdfs.StateChange (BlockManager.java:addStoredBlock(955)) - BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:49323 is added to blk_-7072735518092206564_1015 size 11831 [junit] 2009-08-19 19:56:04,305 INFO datanode.DataNode (BlockReceiver.java:run(997)) - PacketResponder 1 for block blk_-7072735518092206564_1015 terminating [junit] 2009-08-19 19:56:04,308 INFO hdfs.StateChange (FSNamesystem.java:completeFileInternal(1252)) - DIR* NameSystem.completeFile: file /user/hudson/mapout/_logs/history/localhost_1250711705011_job_200908191955_0002_hudson_NA is closed by DFSClient_-1965061630 [junit] 2009-08-19 19:56:04,308 INFO namenode.FSNamesystem (FSEditLog.java:printStatistics(876)) - Number of transactions: 87 Total time for transactions(ms): 6Number of transactions batched in Syncs: 5 Number of syncs: 61 SyncTimes(ms): 592 444 [junit] 2009-08-19 19:56:04,321 INFO mapred.JobHistory (JobHistory.java:run(214)) - Moving http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/logs/history/localhost_1250711705011_job_200908191955_0002_hudson_NA to http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/logs/history/done [junit] 2009-08-19 19:56:04,323 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2371)) - Removed completed task 'attempt_200908191955_0002_m_000000_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:59721' [junit] 2009-08-19 19:56:04,323 INFO hdfs.StateChange (BlockManager.java:addToInvalidates(365)) - BLOCK* NameSystem.addToInvalidates: blk_405192232629879993 is added to invalidSet of 127.0.0.1:57596 [junit] 2009-08-19 19:56:04,323 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2371)) - Removed completed task 'attempt_200908191955_0002_m_000001_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:59721' [junit] 2009-08-19 19:56:04,323 INFO hdfs.StateChange (BlockManager.java:addToInvalidates(365)) - BLOCK* NameSystem.addToInvalidates: blk_405192232629879993 is added to invalidSet of 127.0.0.1:49323 [junit] 2009-08-19 19:56:04,323 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2371)) - Removed completed task 'attempt_200908191955_0002_m_000003_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:59721' [junit] 2009-08-19 19:56:04,324 INFO hdfs.StateChange (BlockManager.java:addToInvalidates(365)) - BLOCK* NameSystem.addToInvalidates: blk_-6638832550023302022 is added to invalidSet of 127.0.0.1:57596 [junit] 2009-08-19 19:56:04,324 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2371)) - Removed completed task 'attempt_200908191955_0002_m_000004_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:59721' [junit] 2009-08-19 19:56:04,324 INFO hdfs.StateChange (BlockManager.java:addToInvalidates(365)) - BLOCK* NameSystem.addToInvalidates: blk_-6638832550023302022 is added to invalidSet of 127.0.0.1:49323 [junit] 2009-08-19 19:56:04,324 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2371)) - Removed completed task 'attempt_200908191955_0002_r_000000_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:59721' [junit] 2009-08-19 19:56:04,325 INFO mapred.TaskTracker (TaskTracker.java:purgeJob(1671)) - Received 'KillJobAction' for job: job_200908191955_0002 [junit] 2009-08-19 19:56:04,325 INFO mapred.TaskRunner (MapTaskRunner.java:close(43)) - attempt_200908191955_0002_m_000001_0 done; removing files. [junit] 2009-08-19 19:56:04,326 INFO mapred.TaskRunner (MapTaskRunner.java:close(43)) - attempt_200908191955_0002_m_000003_0 done; removing files. [junit] 2009-08-19 19:56:04,326 INFO mapred.IndexCache (IndexCache.java:removeMap(140)) - Map ID attempt_200908191955_0002_m_000003_0 not found in cache [junit] 2009-08-19 19:56:04,326 INFO mapred.TaskRunner (MapTaskRunner.java:close(43)) - attempt_200908191955_0002_m_000000_0 done; removing files. [junit] 2009-08-19 19:56:04,341 INFO FSNamesystem.audit (FSNamesystem.java:logAuditEvent(114)) - ugi=hudson,hudson ip=/127.0.0.1 cmd=delete src=/tmp/hadoop-hudson/mapred/system/job_200908191955_0002 dst=null perm=null [junit] 2009-08-19 19:56:04,358 INFO mapred.JobClient (JobClient.java:monitorAndPrintJob(1364)) - Task Id : attempt_200908191955_0002_m_000003_0, Status : SUCCEEDED [junit] attempt_200908191955_0002_m_000003_0: 2009-08-19 19:56:02,076 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Initializing JVM Metrics with processName=MAP, sessionId= [junit] attempt_200908191955_0002_m_000003_0: 2009-08-19 19:56:02,261 INFO mapred.Task (Task.java:done(643)) - Task:attempt_200908191955_0002_m_000003_0 is done. And is in the process of commiting [junit] attempt_200908191955_0002_m_000003_0: 2009-08-19 19:56:02,266 INFO mapred.Task (Task.java:sendDone(714)) - Task 'attempt_200908191955_0002_m_000003_0' done. [junit] 2009-08-19 19:56:04,363 INFO mapred.JobClient (JobClient.java:monitorAndPrintJob(1370)) - Job complete: job_200908191955_0002 [junit] 2009-08-19 19:56:04,366 INFO mapred.JobClient (Counters.java:log(534)) - Counters: 22 [junit] 2009-08-19 19:56:04,366 INFO mapred.JobHistory (JobHistory.java:run(214)) - Moving http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/logs/history/localhost_1250711705011_job_200908191955_0002_conf.xml to http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/logs/history/done [junit] 2009-08-19 19:56:04,366 INFO mapred.JobClient (Counters.java:log(536)) - Job Counters [junit] 2009-08-19 19:56:04,366 INFO mapred.JobClient (Counters.java:log(538)) - Launched reduce tasks=1 [junit] 2009-08-19 19:56:04,367 INFO mapred.JobClient (Counters.java:log(538)) - SLOTS_MILLIS_MAPS=5519 [junit] 2009-08-19 19:56:04,367 INFO mapred.JobClient (Counters.java:log(538)) - Total time spent by all reduces waiting after reserving slots (ms)=0 [junit] 2009-08-19 19:56:04,367 INFO mapred.JobClient (Counters.java:log(538)) - Total time spent by all maps waiting after reserving slots (ms)=0 [junit] 2009-08-19 19:56:04,367 INFO mapred.JobClient (Counters.java:log(538)) - Rack-local map tasks=3 [junit] 2009-08-19 19:56:04,367 INFO mapred.JobClient (Counters.java:log(538)) - Launched map tasks=3 [junit] 2009-08-19 19:56:04,367 INFO mapred.JobClient (Counters.java:log(538)) - SLOTS_MILLIS_REDUCES=9160 [junit] 2009-08-19 19:56:04,368 INFO mapred.JobClient (Counters.java:log(536)) - FileInputFormatCounters [junit] 2009-08-19 19:56:04,368 INFO mapred.JobClient (Counters.java:log(538)) - BYTES_READ=3 [junit] 2009-08-19 19:56:04,368 INFO mapred.JobClient (Counters.java:log(536)) - FileSystemCounters [junit] 2009-08-19 19:56:04,368 INFO mapred.JobClient (Counters.java:log(538)) - FILE_BYTES_READ=21 [junit] 2009-08-19 19:56:04,368 INFO mapred.JobClient (Counters.java:log(538)) - HDFS_BYTES_READ=828 [junit] 2009-08-19 19:56:04,368 INFO mapred.JobClient (Counters.java:log(538)) - FILE_BYTES_WRITTEN=150 [junit] 2009-08-19 19:56:04,369 INFO mapred.JobClient (Counters.java:log(538)) - HDFS_BYTES_WRITTEN=6 [junit] 2009-08-19 19:56:04,369 INFO mapred.JobClient (Counters.java:log(536)) - Map-Reduce Framework [junit] 2009-08-19 19:56:04,380 INFO mapred.JobClient (Counters.java:log(538)) - Reduce input groups=3 [junit] 2009-08-19 19:56:04,380 INFO mapred.JobClient (Counters.java:log(538)) - Combine output records=0 [junit] 2009-08-19 19:56:04,380 INFO mapred.JobClient (Counters.java:log(538)) - Map input records=3 [junit] 2009-08-19 19:56:04,380 INFO mapred.JobClient (Counters.java:log(538)) - Reduce shuffle bytes=33 [junit] 2009-08-19 19:56:04,381 INFO mapred.JobClient (Counters.java:log(538)) - Reduce output records=3 [junit] 2009-08-19 19:56:04,381 INFO mapred.JobClient (Counters.java:log(538)) - Spilled Records=6 [junit] 2009-08-19 19:56:04,381 INFO mapred.JobClient (Counters.java:log(538)) - Map output bytes=9 [junit] 2009-08-19 19:56:04,381 INFO mapred.JobClient (Counters.java:log(538)) - Combine input records=0 [junit] 2009-08-19 19:56:04,381 INFO mapred.JobClient (Counters.java:log(538)) - Map output records=3 [junit] 2009-08-19 19:56:04,382 INFO mapred.JobClient (Counters.java:log(538)) - Reduce input records=3 [junit] 2009-08-19 19:56:04,386 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-19 19:55 /user/hudson/mapout/_logs [junit] -rw-r--r-- 3 hudson supergroup 6 2009-08-19 19:55 /user/hudson/mapout/part-00000 [junit] 2009-08-19 19:56:04,389 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-19 19:56:04,391 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-19 19:56:04,404 INFO DataNode.clienttrace (BlockSender.java:sendBlock(417)) - src: /127.0.0.1:57596, dest: /127.0.0.1:49914, bytes: 10, op: HDFS_READ, cliID: DFSClient_-1965061630, offset: 0, srvID: DS-1737630840-67.195.138.9-57596-1250711704144, blockid: blk_-7751065530915827001_1015, duration: 285211 [junit] 2009-08-19 19:56:04,404 INFO mapred.MiniMRCluster (MiniMRCluster.java:waitTaskTrackers(306)) - Waiting for task tracker tracker_host0.foo.com:localhost/127.0.0.1:49827 to be idle. [junit] 2009-08-19 19:56:05,094 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2371)) - Removed completed task 'attempt_200908191955_0002_m_000002_0' from 'tracker_host0.foo.com:localhost/127.0.0.1:49827' [junit] 2009-08-19 19:56:05,095 INFO mapred.TaskTracker (TaskTracker.java:purgeJob(1671)) - Received 'KillJobAction' for job: job_200908191955_0002 [junit] 2009-08-19 19:56:05,095 INFO mapred.TaskRunner (MapTaskRunner.java:close(43)) - attempt_200908191955_0002_m_000002_0 done; removing files. [junit] 2009-08-19 19:56:05,406 INFO mapred.TaskTracker (TaskTracker.java:run(681)) - Shutting down: Map-events fetcher for all reduce tasks on tracker_host0.foo.com:localhost/127.0.0.1:49827 [junit] 2009-08-19 19:56:05,406 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 49827 [junit] 2009-08-19 19:56:05,406 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 3 on 49827: exiting [junit] 2009-08-19 19:56:05,407 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder [junit] 2009-08-19 19:56:05,407 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 49827: exiting [junit] 2009-08-19 19:56:05,407 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 49827 [junit] 2009-08-19 19:56:05,407 INFO mapred.TaskTracker (TaskTracker.java:shutdown(1149)) - Shutting down StatusHttpServer [junit] 2009-08-19 19:56:05,407 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 49827: exiting [junit] 2009-08-19 19:56:05,408 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 49827: exiting [junit] 2009-08-19 19:56:05,410 INFO mapred.TaskTracker (TaskTracker.java:offerService(1439)) - Interrupted. Closing down. [junit] 2009-08-19 19:56:05,411 INFO mapred.TaskTracker (TaskTracker.java:run(681)) - Shutting down: Map-events fetcher for all reduce tasks on tracker_host1.foo.com:localhost/127.0.0.1:59721 [junit] 2009-08-19 19:56:05,411 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 59721 [junit] 2009-08-19 19:56:05,411 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 59721: exiting [junit] 2009-08-19 19:56:05,412 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 59721 [junit] 2009-08-19 19:56:05,412 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 59721: exiting [junit] 2009-08-19 19:56:05,412 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder [junit] 2009-08-19 19:56:05,412 INFO mapred.TaskTracker (TaskTracker.java:shutdown(1149)) - Shutting down StatusHttpServer [junit] 2009-08-19 19:56:05,412 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 3 on 59721: exiting [junit] 2009-08-19 19:56:05,412 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 59721: exiting [junit] 2009-08-19 19:56:05,514 INFO mapred.TaskTracker (TaskTracker.java:offerService(1439)) - Interrupted. Closing down. [junit] 2009-08-19 19:56:05,515 INFO mapred.JobTracker (JobTracker.java:close(2189)) - Stopping infoServer [junit] 2009-08-19 19:56:05,617 INFO mapred.JobTracker (JobTracker.java:close(2197)) - Stopping interTrackerServer [junit] 2009-08-19 19:56:05,617 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 53093 [junit] 2009-08-19 19:56:05,617 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 53093: exiting [junit] 2009-08-19 19:56:05,618 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 9 on 53093: exiting [junit] 2009-08-19 19:56:05,618 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 53093: exiting [junit] 2009-08-19 19:56:05,618 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 4 on 53093: exiting [junit] 2009-08-19 19:56:05,618 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 3 on 53093: exiting [junit] 2009-08-19 19:56:05,618 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 7 on 53093: exiting [junit] 2009-08-19 19:56:05,618 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 53093 [junit] 2009-08-19 19:56:05,618 INFO mapred.JobTracker (JobTracker.java:offerService(2184)) - Stopped interTrackerServer [junit] 2009-08-19 19:56:05,618 INFO mapred.JobTracker (JobTracker.java:stopExpireTrackersThread(2240)) - Stopping expireTrackers [junit] 2009-08-19 19:56:05,618 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder [junit] 2009-08-19 19:56:05,617 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 6 on 53093: exiting [junit] 2009-08-19 19:56:05,618 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 8 on 53093: exiting [junit] 2009-08-19 19:56:05,617 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 5 on 53093: exiting [junit] 2009-08-19 19:56:05,617 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 53093: exiting [junit] 2009-08-19 19:56:05,619 INFO mapred.JobTracker (JobTracker.java:close(2204)) - Stopping retirer [junit] 2009-08-19 19:56:05,620 INFO mapred.EagerTaskInitializationListener (EagerTaskInitializationListener.java:terminate(106)) - Stopping Job Init Manager thread [junit] 2009-08-19 19:56:05,621 INFO mapred.EagerTaskInitializationListener (EagerTaskInitializationListener.java:run(60)) - JobInitManagerThread interrupted. [junit] 2009-08-19 19:56:05,621 INFO mapred.EagerTaskInitializationListener (EagerTaskInitializationListener.java:run(64)) - Shutting down thread pool [junit] 2009-08-19 19:56:05,621 INFO mapred.JobTracker (JobTracker.java:close(2216)) - Stopping expireLaunchingTasks [junit] 2009-08-19 19:56:05,621 INFO mapred.JobTracker (JobTracker.java:close(2234)) - stopped all jobtracker services [junit] Shutting down the Mini HDFS Cluster [junit] Shutting down DataNode 1 [junit] 2009-08-19 19:56:05,723 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 49379 [junit] 2009-08-19 19:56:05,724 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 49379: exiting [junit] 2009-08-19 19:56:05,725 WARN datanode.DataNode (DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:49323, storageID=DS-2105063903-67.195.138.9-49323-1250711704761, infoPort=33160, ipcPort=49379):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-19 19:56:05,724 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 49379: exiting [junit] 2009-08-19 19:56:05,724 INFO datanode.DataNode (DataNode.java:shutdown(639)) - Waiting for threadgroup to exit, active threads is 1 [junit] 2009-08-19 19:56:05,724 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder [junit] 2009-08-19 19:56:05,724 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 49379 [junit] 2009-08-19 19:56:05,724 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 49379: exiting [junit] 2009-08-19 19:56:05,726 INFO datanode.DataBlockScanner (DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread. [junit] 2009-08-19 19:56:05,726 INFO datanode.DataNode (DataNode.java:run(1285)) - DatanodeRegistration(127.0.0.1:49323, storageID=DS-2105063903-67.195.138.9-49323-1250711704761, infoPort=33160, ipcPort=49379):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-19 19:56:05,726 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 49379 [junit] 2009-08-19 19:56:05,727 INFO datanode.DataNode (DataNode.java:shutdown(639)) - Waiting for threadgroup to exit, active threads is 0 [junit] Shutting down DataNode 0 [junit] 2009-08-19 19:56:05,828 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 47356 [junit] 2009-08-19 19:56:05,829 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 47356: exiting [junit] 2009-08-19 19:56:05,829 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder [junit] 2009-08-19 19:56:05,829 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 47356 [junit] 2009-08-19 19:56:05,830 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 47356: exiting [junit] 2009-08-19 19:56:05,830 WARN datanode.DataNode (DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:57596, storageID=DS-1737630840-67.195.138.9-57596-1250711704144, infoPort=51224, ipcPort=47356):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-19 19:56:05,830 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 47356: exiting [junit] 2009-08-19 19:56:05,830 INFO datanode.DataNode (DataNode.java:shutdown(639)) - Waiting for threadgroup to exit, active threads is 1 [junit] 2009-08-19 19:56:05,831 INFO datanode.DataBlockScanner (DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread. [junit] 2009-08-19 19:56:05,831 INFO datanode.DataNode (DataNode.java:run(1285)) - DatanodeRegistration(127.0.0.1:57596, storageID=DS-1737630840-67.195.138.9-57596-1250711704144, infoPort=51224, ipcPort=47356):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-19 19:56:05,832 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 47356 [junit] 2009-08-19 19:56:05,832 INFO datanode.DataNode (DataNode.java:shutdown(639)) - Waiting for threadgroup to exit, active threads is 0 [junit] 2009-08-19 19:56:05,937 WARN namenode.DecommissionManager (DecommissionManager.java:run(67)) - Monitor interrupted: java.lang.InterruptedException: sleep interrupted [junit] 2009-08-19 19:56:05,937 INFO namenode.FSNamesystem (FSEditLog.java:printStatistics(876)) - Number of transactions: 88 Total time for transactions(ms): 6Number of transactions batched in Syncs: 5 Number of syncs: 63 SyncTimes(ms): 607 457 [junit] 2009-08-19 19:56:05,937 WARN namenode.FSNamesystem (FSNamesystem.java:run(2057)) - ReplicationMonitor thread received InterruptedException.java.lang.InterruptedException: sleep interrupted [junit] 2009-08-19 19:56:05,951 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 57620 [junit] 2009-08-19 19:56:05,951 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 57620: exiting [junit] 2009-08-19 19:56:05,952 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 57620: exiting [junit] 2009-08-19 19:56:05,952 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 3 on 57620: exiting [junit] 2009-08-19 19:56:05,952 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 8 on 57620: exiting [junit] 2009-08-19 19:56:05,951 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 57620: exiting [junit] 2009-08-19 19:56:05,953 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder [junit] 2009-08-19 19:56:05,952 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 6 on 57620: exiting [junit] 2009-08-19 19:56:05,952 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 57620 [junit] 2009-08-19 19:56:05,952 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 5 on 57620: exiting [junit] 2009-08-19 19:56:05,952 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 7 on 57620: exiting [junit] 2009-08-19 19:56:05,952 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 4 on 57620: exiting [junit] 2009-08-19 19:56:05,952 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 9 on 57620: exiting [junit] Tests run: 2, Failures: 0, Errors: 0, Time elapsed: 103.868 sec [junit] Running org.apache.hadoop.util.TestReflectionUtils [junit] Tests run: 5, Failures: 0, Errors: 0, Time elapsed: 0.579 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: 161 minutes 15 seconds Publishing Javadoc Recording test results Recording fingerprints Publishing Clover coverage report...