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/11 19:18:29 UTC
Build failed in Hudson: Hadoop-Mapreduce-trunk #45
See http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/45/changes
Changes:
[ddas] MAPREDUCE-805. Fixes some deadlocks in the JobTracker due to the fact the JobTracker lock hierarchy wasn't maintained in some JobInProgress method calls. Contributed by Amar Kamat.
[ddas] MAPREDUCE-813. Updates Streaming and M/R tutorial documents. Contributed by Corinne Chandel.
[ddas] MAPREDUCE-372. Moves ChainMapper/Reducer to the new API. Contributed by Amareshwari Sriramadasu.
[ddas] MAPREDUCE-838. Adding the testcase
[ddas] MAPREDUCE-838. Fixes a problem in the way commit of task outputs happens. The bug was that even if commit failed, the task would be declared as successful. Contributed by Amareshwari Sriramadasu.
[szetszwo] MAPREDUCE-845. Fix a findbugs heap size problem in build.xml and add a new property findbugs.heap.size. Contributed by Lee Tucker
[ddas] MAPREDUCE-808. Fixes a serialization problem in TypedBytes. Contributed by Klaas Bosteels.
------------------------------------------
[...truncated 131785 lines...]
[junit] 2009-08-11 17:17:09,042 INFO mapred.TaskTracker (TaskTracker.java:run(1660)) - In TaskLauncher, current free slots : 2 and trying to launch attempt_200908111716_0002_m_000003_0 which needs 1 slots
[junit] 2009-08-11 17:17:09,042 INFO mapred.TaskRunner (ReduceTaskRunner.java:close(47)) - attempt_200908111716_0002_r_000000_0 done; removing files.
[junit] 2009-08-11 17:17:09,088 INFO mapred.JvmManager (JvmManager.java:<init>(383)) - In JvmRunner constructed JVM ID: jvm_200908111716_0002_m_1606799887
[junit] 2009-08-11 17:17:09,089 INFO mapred.JvmManager (JvmManager.java:spawnNewJvm(351)) - JVM Runner jvm_200908111716_0002_m_1606799887 spawned.
[junit] 2009-08-11 17:17:09,223 INFO mapred.JobClient (JobClient.java:monitorAndPrintJob(1350)) - Task Id : attempt_200908111716_0002_r_000000_0, Status : SUCCEEDED
[junit] attempt_200908111716_0002_r_000000_0: 2009-08-11 17:16:57,768 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Initializing JVM Metrics with processName=SHUFFLE, sessionId=
[junit] attempt_200908111716_0002_r_000000_0: 2009-08-11 17:16:57,893 INFO mapred.ReduceTask (ReduceTask.java:<init>(1011)) - ShuffleRamManager: MemoryLimit=141387360, MaxSingleShuffleLimit=35346840
[junit] attempt_200908111716_0002_r_000000_0: 2009-08-11 17:16:57,900 INFO mapred.ReduceTask (ReduceTask.java:run(2486)) - attempt_200908111716_0002_r_000000_0 Thread started: Thread for merging on-disk files
[junit] attempt_200908111716_0002_r_000000_0: 2009-08-11 17:16:57,900 INFO mapred.ReduceTask (ReduceTask.java:run(2585)) - attempt_200908111716_0002_r_000000_0 Thread started: Thread for merging in memory files
[junit] attempt_200908111716_0002_r_000000_0: 2009-08-11 17:16:57,900 INFO mapred.ReduceTask (ReduceTask.java:run(2491)) - attempt_200908111716_0002_r_000000_0 Thread waiting: Thread for merging on-disk files
[junit] attempt_200908111716_0002_r_000000_0: 2009-08-11 17:16:57,902 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(1893)) - attempt_200908111716_0002_r_000000_0 Need another 3 map output(s) where 0 is already in progress
[junit] attempt_200908111716_0002_r_000000_0: 2009-08-11 17:16:57,902 INFO mapred.ReduceTask (ReduceTask.java:run(2687)) - attempt_200908111716_0002_r_000000_0 Thread started: Thread for polling Map Completion Events
[junit] attempt_200908111716_0002_r_000000_0: 2009-08-11 17:16:57,902 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2006)) - attempt_200908111716_0002_r_000000_0 Scheduled 0 outputs (0 slow hosts and0 dup hosts)
[junit] attempt_200908111716_0002_r_000000_0: 2009-08-11 17:16:57,908 INFO mapred.ReduceTask (ReduceTask.java:run(2693)) - attempt_200908111716_0002_r_000000_0: Got 2 new map-outputs
[junit] attempt_200908111716_0002_r_000000_0: 2009-08-11 17:17:01,913 INFO mapred.ReduceTask (ReduceTask.java:run(2693)) - attempt_200908111716_0002_r_000000_0: Got 1 new map-outputs
[junit] attempt_200908111716_0002_r_000000_0: 2009-08-11 17:17:02,903 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2006)) - attempt_200908111716_0002_r_000000_0 Scheduled 1 outputs (0 slow hosts and0 dup hosts)
[junit] attempt_200908111716_0002_r_000000_0: 2009-08-11 17:17:02,948 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1424)) - header: attempt_200908111716_0002_m_000000_0, compressed len: 11, decompressed len: 7
[junit] attempt_200908111716_0002_r_000000_0: 2009-08-11 17:17:02,948 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1438)) - Shuffling 7 bytes (11 raw bytes) into RAM from attempt_200908111716_0002_m_000000_0
[junit] attempt_200908111716_0002_r_000000_0: 2009-08-11 17:17:02,952 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1567)) - Read 7 bytes from map-output for attempt_200908111716_0002_m_000000_0
[junit] attempt_200908111716_0002_r_000000_0: 2009-08-11 17:17:02,952 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1626)) - Rec #1 from attempt_200908111716_0002_m_000000_0 -> (2, 1) from localhost
[junit] attempt_200908111716_0002_r_000000_0: 2009-08-11 17:17:02,954 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2006)) - attempt_200908111716_0002_r_000000_0 Scheduled 1 outputs (0 slow hosts and0 dup hosts)
[junit] attempt_200908111716_0002_r_000000_0: 2009-08-11 17:17:02,960 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1424)) - header: attempt_200908111716_0002_m_000001_0, compressed len: 11, decompressed len: 7
[junit] attempt_200908111716_0002_r_000000_0: 2009-08-11 17:17:02,961 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1438)) - Shuffling 7 bytes (11 raw bytes) into RAM from attempt_200908111716_0002_m_000001_0
[junit] attempt_200908111716_0002_r_000000_0: 2009-08-11 17:17:02,961 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1567)) - Read 7 bytes from map-output for attempt_200908111716_0002_m_000001_0
[junit] attempt_200908111716_0002_r_000000_0: 2009-08-11 17:17:02,961 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1626)) - Rec #1 from attempt_200908111716_0002_m_000001_0 -> (2, 1) from localhost
[junit] attempt_200908111716_0002_r_000000_0: 2009-08-11 17:17:02,963 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2006)) - attempt_200908111716_0002_r_000000_0 Scheduled 1 outputs (0 slow hosts and0 dup hosts)
[junit] attempt_200908111716_0002_r_000000_0: 2009-08-11 17:17:02,966 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1424)) - header: attempt_200908111716_0002_m_000002_0, compressed len: 11, decompressed len: 7
[junit] attempt_200908111716_0002_r_000000_0: 2009-08-11 17:17:02,967 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1438)) - Shuffling 7 bytes (11 raw bytes) into RAM from attempt_200908111716_0002_m_000002_0
[junit] attempt_200908111716_0002_r_000000_0: 2009-08-11 17:17:02,967 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1567)) - Read 7 bytes from map-output for attempt_200908111716_0002_m_000002_0
[junit] attempt_200908111716_0002_r_000000_0: 2009-08-11 17:17:02,967 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1626)) - Rec #1 from attempt_200908111716_0002_m_000002_0 -> (2, 1) from localhost
[junit] attempt_200908111716_0002_r_000000_0: 2009-08-11 17:17:03,915 INFO mapred.ReduceTask (ReduceTask.java:run(2711)) - GetMapEventsThread exiting
[junit] attempt_200908111716_0002_r_000000_0: 2009-08-11 17:17:03,915 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2204)) - getMapsEventsThread joined.
[junit] attempt_200908111716_0002_r_000000_0: 2009-08-11 17:17:03,916 INFO mapred.ReduceTask (ReduceTask.java:close(1117)) - Closed ram manager
[junit] attempt_200908111716_0002_r_000000_0: 2009-08-11 17:17:03,916 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2232)) - Interleaved on-disk merge complete: 0 files left.
[junit] attempt_200908111716_0002_r_000000_0: 2009-08-11 17:17:03,916 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2237)) - In-memory merge complete: 3 files left.
[junit] attempt_200908111716_0002_r_000000_0: 2009-08-11 17:17:03,939 INFO mapred.Merger (Merger.java:merge(469)) - Merging 3 sorted segments
[junit] attempt_200908111716_0002_r_000000_0: 2009-08-11 17:17:03,940 INFO mapred.Merger (Merger.java:merge(568)) - Down to the last merge-pass, with 3 segments left of total size: 9 bytes
[junit] attempt_200908111716_0002_r_000000_0: 2009-08-11 17:17:03,948 INFO mapred.ReduceTask (ReduceTask.java:createKVIterator(2350)) - Merged 3 segments, 21 bytes to disk to satisfy reduce memory limit
[junit] attempt_200908111716_0002_r_000000_0: 2009-08-11 17:17:03,949 INFO mapred.ReduceTask (ReduceTask.java:createKVIterator(2370)) - Merging 1 files, 21 bytes from disk
[junit] attempt_200908111716_0002_r_000000_0: 2009-08-11 17:17:03,950 INFO mapred.ReduceTask (ReduceTask.java:createKVIterator(2384)) - Merging 0 segments, 0 bytes from memory into reduce
[junit] attempt_200908111716_0002_r_000000_0: 2009-08-11 17:17:03,950 INFO mapred.Merger (Merger.java:merge(469)) - Merging 1 sorted segments
[junit] attempt_200908111716_0002_r_000000_0: 2009-08-11 17:17:03,953 INFO mapred.Merger (Merger.java:merge(568)) - Down to the last merge-pass, with 1 segments left of total size: 13 bytes
[junit] attempt_200908111716_0002_r_000000_0: 2009-08-11 17:17:04,222 INFO mapred.Task (Task.java:done(645)) - Task:attempt_200908111716_0002_r_000000_0 is done. And is in the process of commiting
[junit] attempt_200908111716_0002_r_000000_0: 2009-08-11 17:17:06,229 INFO mapred.Task (Task.java:commit(757)) - Task attempt_200908111716_0002_r_000000_0 is allowed to commit now
[junit] attempt_200908111716_0002_r_000000_0: 2009-08-11 17:17:06,347 INFO mapred.FileOutputCommitter (FileOutputCommitter.java:commitTask(92)) - Saved output of task 'attempt_200908111716_0002_r_000000_0' to hdfs://localhost:50855/user/hudson/mapout
[junit] attempt_200908111716_0002_r_000000_0: 2009-08-11 17:17:06,365 INFO mapred.Task (Task.java:sendDone(716)) - Task 'attempt_200908111716_0002_r_000000_0' done.
[junit] 2009-08-11 17:17:09,517 INFO mapred.TaskTracker (TaskTracker.java:getTask(2548)) - JVM with ID: jvm_200908111716_0002_m_1606799887 given task: attempt_200908111716_0002_m_000003_0
[junit] 2009-08-11 17:17:09,872 INFO mapred.TaskTracker (TaskTracker.java:reportProgress(2000)) - attempt_200908111716_0002_m_000003_0 0.0%
[junit] 2009-08-11 17:17:09,891 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-11 17:17:09,895 INFO mapred.TaskTracker (TaskTracker.java:reportProgress(2000)) - attempt_200908111716_0002_m_000003_0 0.0% cleanup > map
[junit] 2009-08-11 17:17:09,896 INFO mapred.TaskTracker (TaskTracker.java:reportDone(2081)) - Task attempt_200908111716_0002_m_000003_0 is done.
[junit] 2009-08-11 17:17:09,896 INFO mapred.TaskTracker (TaskTracker.java:reportDone(2082)) - reported output size for attempt_200908111716_0002_m_000003_0 was 0
[junit] 2009-08-11 17:17:09,896 INFO mapred.TaskTracker (TaskTracker.java:addFreeSlots(1632)) - addFreeSlot : current free slots : 2
[junit] 2009-08-11 17:17:10,008 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-11 17:17:10,009 INFO util.ProcessTree (ProcessTree.java:terminateProcessGroup(138)) - Killing all processes in the process group 4010 with SIGTERM. Exit code 1
[junit] 2009-08-11 17:17:10,230 INFO mapred.JobClient (JobClient.java:monitorAndPrintJob(1301)) - map 100% reduce 100%
[junit] 2009-08-11 17:17:11,526 INFO mapred.JvmManager (JvmManager.java:runChild(411)) - JVM : jvm_200908111716_0002_r_1020434421 exited. Number of tasks it ran: 1
[junit] 2009-08-11 17:17:12,043 INFO mapred.TaskTracker (TaskTracker.java:tryToGetOutputSize(1584)) - org.apache.hadoop.util.DiskChecker$DiskErrorException: Could not find taskTracker/jobcache/job_200908111716_0002/attempt_200908111716_0002_m_000003_0/output/file.out in any of the configured local directories
[junit] 2009-08-11 17:17:12,045 INFO mapred.JobInProgress (JobInProgress.java:completedTask(2468)) - Task 'attempt_200908111716_0002_m_000003_0' has completed task_200908111716_0002_m_000003 successfully.
[junit] 2009-08-11 17:17:12,046 INFO mapred.JobInProgress (JobInProgress.java:jobComplete(2633)) - Job job_200908111716_0002 has completed successfully.
[junit] 2009-08-11 17:17:12,046 INFO mapred.JobInProgress$JobSummary (JobInProgress.java:logJobSummary(3303)) - jobId=job_200908111716_0002,submitTime=1250011010125,launchTime=1250011010272,finishTime=1250011032046,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-11 17:17:12,050 INFO hdfs.StateChange (FSNamesystem.java:allocateBlock(1286)) - BLOCK* NameSystem.allocateBlock: /user/hudson/mapout/_logs/history/localhost_1250010972805_job_200908111716_0002_hudson_NA. blk_-239988501737372783_1015
[junit] 2009-08-11 17:17:12,052 INFO datanode.DataNode (DataXceiver.java:writeBlock(240)) - Receiving block blk_-239988501737372783_1015 src: /127.0.0.1:35276 dest: /127.0.0.1:43282
[junit] 2009-08-11 17:17:12,053 INFO datanode.DataNode (DataXceiver.java:writeBlock(240)) - Receiving block blk_-239988501737372783_1015 src: /127.0.0.1:43675 dest: /127.0.0.1:52774
[junit] 2009-08-11 17:17:12,095 INFO DataNode.clienttrace (BlockReceiver.java:lastDataNodeRun(807)) - src: /127.0.0.1:43675, dest: /127.0.0.1:52774, bytes: 11831, op: HDFS_WRITE, cliID: DFSClient_965602631, offset: 0, srvID: DS-662031835-67.195.138.9-52774-1250010972059, blockid: blk_-239988501737372783_1015, duration: 40091227
[junit] 2009-08-11 17:17:12,096 INFO hdfs.StateChange (BlockManager.java:addStoredBlock(955)) - BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:52774 is added to blk_-239988501737372783_1015 size 11831
[junit] 2009-08-11 17:17:12,096 INFO DataNode.clienttrace (BlockReceiver.java:run(933)) - src: /127.0.0.1:35276, dest: /127.0.0.1:43282, bytes: 11831, op: HDFS_WRITE, cliID: DFSClient_965602631, offset: 0, srvID: DS-941188496-67.195.138.9-43282-1250010972661, blockid: blk_-239988501737372783_1015, duration: 41312424
[junit] 2009-08-11 17:17:12,096 INFO datanode.DataNode (BlockReceiver.java:lastDataNodeRun(831)) - PacketResponder 0 for block blk_-239988501737372783_1015 terminating
[junit] 2009-08-11 17:17:12,096 INFO hdfs.StateChange (BlockManager.java:addStoredBlock(955)) - BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:43282 is added to blk_-239988501737372783_1015 size 11831
[junit] 2009-08-11 17:17:12,096 INFO datanode.DataNode (BlockReceiver.java:run(997)) - PacketResponder 1 for block blk_-239988501737372783_1015 terminating
[junit] 2009-08-11 17:17:12,098 INFO hdfs.StateChange (FSNamesystem.java:completeFileInternal(1252)) - DIR* NameSystem.completeFile: file /user/hudson/mapout/_logs/history/localhost_1250010972805_job_200908111716_0002_hudson_NA is closed by DFSClient_965602631
[junit] 2009-08-11 17:17:12,098 INFO namenode.FSNamesystem (FSEditLog.java:printStatistics(876)) - Number of transactions: 87 Total time for transactions(ms): 7Number of transactions batched in Syncs: 6 Number of syncs: 60 SyncTimes(ms): 675 565
[junit] 2009-08-11 17:17:12,128 INFO mapred.JobHistory (JobHistory.java:run(196)) - Moving http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/logs/history/localhost_1250010972805_job_200908111716_0002_hudson_NA to http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/logs/history/done
[junit] 2009-08-11 17:17:12,129 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2321)) - Removed completed task 'attempt_200908111716_0002_m_000000_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:54401'
[junit] 2009-08-11 17:17:12,130 INFO hdfs.StateChange (BlockManager.java:addToInvalidates(365)) - BLOCK* NameSystem.addToInvalidates: blk_7986220584460109559 is added to invalidSet of 127.0.0.1:52774
[junit] 2009-08-11 17:17:12,130 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2321)) - Removed completed task 'attempt_200908111716_0002_m_000001_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:54401'
[junit] 2009-08-11 17:17:12,130 INFO hdfs.StateChange (BlockManager.java:addToInvalidates(365)) - BLOCK* NameSystem.addToInvalidates: blk_7986220584460109559 is added to invalidSet of 127.0.0.1:43282
[junit] 2009-08-11 17:17:12,130 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2321)) - Removed completed task 'attempt_200908111716_0002_m_000003_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:54401'
[junit] 2009-08-11 17:17:12,131 INFO hdfs.StateChange (BlockManager.java:addToInvalidates(365)) - BLOCK* NameSystem.addToInvalidates: blk_-5444205976668404638 is added to invalidSet of 127.0.0.1:43282
[junit] 2009-08-11 17:17:12,131 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2321)) - Removed completed task 'attempt_200908111716_0002_m_000004_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:54401'
[junit] 2009-08-11 17:17:12,131 INFO hdfs.StateChange (BlockManager.java:addToInvalidates(365)) - BLOCK* NameSystem.addToInvalidates: blk_-5444205976668404638 is added to invalidSet of 127.0.0.1:52774
[junit] 2009-08-11 17:17:12,131 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2321)) - Removed completed task 'attempt_200908111716_0002_r_000000_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:54401'
[junit] 2009-08-11 17:17:12,138 INFO mapred.TaskTracker (TaskTracker.java:purgeJob(1380)) - Received 'KillJobAction' for job: job_200908111716_0002
[junit] 2009-08-11 17:17:12,139 INFO mapred.TaskRunner (MapTaskRunner.java:close(43)) - attempt_200908111716_0002_m_000003_0 done; removing files.
[junit] 2009-08-11 17:17:12,140 INFO mapred.IndexCache (IndexCache.java:removeMap(140)) - Map ID attempt_200908111716_0002_m_000003_0 not found in cache
[junit] 2009-08-11 17:17:12,140 INFO mapred.TaskRunner (MapTaskRunner.java:close(43)) - attempt_200908111716_0002_m_000000_0 done; removing files.
[junit] 2009-08-11 17:17:12,142 INFO mapred.TaskRunner (MapTaskRunner.java:close(43)) - attempt_200908111716_0002_m_000001_0 done; removing files.
[junit] 2009-08-11 17:17:12,148 INFO FSNamesystem.audit (FSNamesystem.java:logAuditEvent(114)) - ugi=hudson,hudson ip=/127.0.0.1 cmd=delete src=/tmp/hadoop-hudson/mapred/system/job_200908111716_0002 dst=null perm=null
[junit] 2009-08-11 17:17:12,171 INFO mapred.JobHistory (JobHistory.java:run(196)) - Moving http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/logs/history/localhost_1250010972805_job_200908111716_0002_conf.xml to http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/logs/history/done
[junit] 2009-08-11 17:17:12,235 INFO mapred.JobClient (JobClient.java:monitorAndPrintJob(1350)) - Task Id : attempt_200908111716_0002_m_000003_0, Status : SUCCEEDED
[junit] attempt_200908111716_0002_m_000003_0: 2009-08-11 17:17:09,754 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Initializing JVM Metrics with processName=MAP, sessionId=
[junit] attempt_200908111716_0002_m_000003_0: 2009-08-11 17:17:09,892 INFO mapred.Task (Task.java:done(645)) - Task:attempt_200908111716_0002_m_000003_0 is done. And is in the process of commiting
[junit] attempt_200908111716_0002_m_000003_0: 2009-08-11 17:17:09,896 INFO mapred.Task (Task.java:sendDone(716)) - Task 'attempt_200908111716_0002_m_000003_0' done.
[junit] 2009-08-11 17:17:12,238 INFO mapred.JobClient (JobClient.java:monitorAndPrintJob(1356)) - Job complete: job_200908111716_0002
[junit] 2009-08-11 17:17:12,241 INFO mapred.JobClient (Counters.java:log(534)) - Counters: 22
[junit] 2009-08-11 17:17:12,241 INFO mapred.JobClient (Counters.java:log(536)) - Job Counters
[junit] 2009-08-11 17:17:12,241 INFO mapred.JobClient (Counters.java:log(538)) - Launched reduce tasks=1
[junit] 2009-08-11 17:17:12,241 INFO mapred.JobClient (Counters.java:log(538)) - SLOTS_MILLIS_MAPS=5110
[junit] 2009-08-11 17:17:12,242 INFO mapred.JobClient (Counters.java:log(538)) - Total time spent by all reduces waiting after reserving slots (ms)=0
[junit] 2009-08-11 17:17:12,242 INFO mapred.JobClient (Counters.java:log(538)) - Total time spent by all maps waiting after reserving slots (ms)=0
[junit] 2009-08-11 17:17:12,242 INFO mapred.JobClient (Counters.java:log(538)) - Rack-local map tasks=3
[junit] 2009-08-11 17:17:12,242 INFO mapred.JobClient (Counters.java:log(538)) - Launched map tasks=3
[junit] 2009-08-11 17:17:12,242 INFO mapred.JobClient (Counters.java:log(538)) - SLOTS_MILLIS_REDUCES=9295
[junit] 2009-08-11 17:17:12,243 INFO mapred.JobClient (Counters.java:log(536)) - FileInputFormatCounters
[junit] 2009-08-11 17:17:12,243 INFO mapred.JobClient (Counters.java:log(538)) - BYTES_READ=3
[junit] 2009-08-11 17:17:12,243 INFO mapred.JobClient (Counters.java:log(536)) - FileSystemCounters
[junit] 2009-08-11 17:17:12,243 INFO mapred.JobClient (Counters.java:log(538)) - FILE_BYTES_READ=21
[junit] 2009-08-11 17:17:12,243 INFO mapred.JobClient (Counters.java:log(538)) - HDFS_BYTES_READ=828
[junit] 2009-08-11 17:17:12,244 INFO mapred.JobClient (Counters.java:log(538)) - FILE_BYTES_WRITTEN=150
[junit] 2009-08-11 17:17:12,244 INFO mapred.JobClient (Counters.java:log(538)) - HDFS_BYTES_WRITTEN=6
[junit] 2009-08-11 17:17:12,244 INFO mapred.JobClient (Counters.java:log(536)) - Map-Reduce Framework
[junit] 2009-08-11 17:17:12,244 INFO mapred.JobClient (Counters.java:log(538)) - Reduce input groups=3
[junit] 2009-08-11 17:17:12,244 INFO mapred.JobClient (Counters.java:log(538)) - Combine output records=0
[junit] 2009-08-11 17:17:12,245 INFO mapred.JobClient (Counters.java:log(538)) - Map input records=3
[junit] 2009-08-11 17:17:12,245 INFO mapred.JobClient (Counters.java:log(538)) - Reduce shuffle bytes=33
[junit] 2009-08-11 17:17:12,245 INFO mapred.JobClient (Counters.java:log(538)) - Reduce output records=3
[junit] 2009-08-11 17:17:12,245 INFO mapred.JobClient (Counters.java:log(538)) - Spilled Records=6
[junit] 2009-08-11 17:17:12,245 INFO mapred.JobClient (Counters.java:log(538)) - Map output bytes=9
[junit] 2009-08-11 17:17:12,245 INFO mapred.JobClient (Counters.java:log(538)) - Combine input records=0
[junit] 2009-08-11 17:17:12,246 INFO mapred.JobClient (Counters.java:log(538)) - Map output records=3
[junit] 2009-08-11 17:17:12,246 INFO mapred.JobClient (Counters.java:log(538)) - Reduce input records=3
[junit] 2009-08-11 17:17:12,248 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-11 17:16 /user/hudson/mapout/_logs
[junit] -rw-r--r-- 3 hudson supergroup 6 2009-08-11 17:17 /user/hudson/mapout/part-00000
[junit] 2009-08-11 17:17:12,251 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-11 17:17:12,253 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-11 17:17:12,255 INFO DataNode.clienttrace (BlockSender.java:sendBlock(417)) - src: /127.0.0.1:43282, dest: /127.0.0.1:35278, bytes: 10, op: HDFS_READ, cliID: DFSClient_965602631, offset: 0, srvID: DS-941188496-67.195.138.9-43282-1250010972661, blockid: blk_3070793236971885995_1015, duration: 253217
[junit] 2009-08-11 17:17:12,255 INFO mapred.MiniMRCluster (MiniMRCluster.java:waitTaskTrackers(306)) - Waiting for task tracker tracker_host0.foo.com:localhost/127.0.0.1:38300 to be idle.
[junit] 2009-08-11 17:17:12,900 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2321)) - Removed completed task 'attempt_200908111716_0002_m_000002_0' from 'tracker_host0.foo.com:localhost/127.0.0.1:38300'
[junit] 2009-08-11 17:17:12,902 INFO mapred.TaskTracker (TaskTracker.java:purgeJob(1380)) - Received 'KillJobAction' for job: job_200908111716_0002
[junit] 2009-08-11 17:17:12,902 INFO mapred.TaskRunner (MapTaskRunner.java:close(43)) - attempt_200908111716_0002_m_000002_0 done; removing files.
[junit] 2009-08-11 17:17:13,257 INFO mapred.TaskTracker (TaskTracker.java:run(637)) - Shutting down: Map-events fetcher for all reduce tasks on tracker_host0.foo.com:localhost/127.0.0.1:38300
[junit] 2009-08-11 17:17:13,257 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 38300
[junit] 2009-08-11 17:17:13,258 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 3 on 38300: exiting
[junit] 2009-08-11 17:17:13,258 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 38300: exiting
[junit] 2009-08-11 17:17:13,258 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 38300: exiting
[junit] 2009-08-11 17:17:13,258 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 38300: exiting
[junit] 2009-08-11 17:17:13,258 INFO mapred.TaskTracker (TaskTracker.java:shutdown(869)) - Shutting down StatusHttpServer
[junit] 2009-08-11 17:17:13,258 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
[junit] 2009-08-11 17:17:13,258 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 38300
[junit] 2009-08-11 17:17:13,361 INFO mapred.TaskTracker (TaskTracker.java:offerService(1148)) - Interrupted. Closing down.
[junit] 2009-08-11 17:17:13,362 INFO mapred.TaskTracker (TaskTracker.java:run(637)) - Shutting down: Map-events fetcher for all reduce tasks on tracker_host1.foo.com:localhost/127.0.0.1:54401
[junit] 2009-08-11 17:17:13,363 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 54401
[junit] 2009-08-11 17:17:13,363 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 54401: exiting
[junit] 2009-08-11 17:17:13,363 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 54401: exiting
[junit] 2009-08-11 17:17:13,364 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 54401: exiting
[junit] 2009-08-11 17:17:13,364 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 3 on 54401: exiting
[junit] 2009-08-11 17:17:13,364 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 54401
[junit] 2009-08-11 17:17:13,364 INFO mapred.TaskTracker (TaskTracker.java:shutdown(869)) - Shutting down StatusHttpServer
[junit] 2009-08-11 17:17:13,364 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
[junit] 2009-08-11 17:17:13,466 INFO mapred.TaskTracker (TaskTracker.java:offerService(1148)) - Interrupted. Closing down.
[junit] 2009-08-11 17:17:13,467 INFO mapred.JobTracker (JobTracker.java:close(2139)) - Stopping infoServer
[junit] 2009-08-11 17:17:13,605 INFO mapred.JobTracker (JobTracker.java:close(2147)) - Stopping interTrackerServer
[junit] 2009-08-11 17:17:13,606 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 39709
[junit] 2009-08-11 17:17:13,606 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 39709: exiting
[junit] 2009-08-11 17:17:13,606 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 5 on 39709: exiting
[junit] 2009-08-11 17:17:13,607 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 7 on 39709: exiting
[junit] 2009-08-11 17:17:13,607 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 6 on 39709: exiting
[junit] 2009-08-11 17:17:13,607 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 39709
[junit] 2009-08-11 17:17:13,607 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 8 on 39709: exiting
[junit] 2009-08-11 17:17:13,607 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 9 on 39709: exiting
[junit] 2009-08-11 17:17:13,607 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 39709: exiting
[junit] 2009-08-11 17:17:13,607 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 39709: exiting
[junit] 2009-08-11 17:17:13,606 INFO mapred.JobTracker (JobTracker.java:offerService(2134)) - Stopped interTrackerServer
[junit] 2009-08-11 17:17:13,606 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
[junit] 2009-08-11 17:17:13,606 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 4 on 39709: exiting
[junit] 2009-08-11 17:17:13,606 INFO mapred.JobTracker (JobTracker.java:stopExpireTrackersThread(2190)) - Stopping expireTrackers
[junit] 2009-08-11 17:17:13,608 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 3 on 39709: exiting
[junit] 2009-08-11 17:17:13,609 INFO mapred.JobTracker (JobTracker.java:close(2154)) - Stopping retirer
[junit] 2009-08-11 17:17:13,610 INFO mapred.EagerTaskInitializationListener (EagerTaskInitializationListener.java:terminate(106)) - Stopping Job Init Manager thread
[junit] 2009-08-11 17:17:13,610 INFO mapred.EagerTaskInitializationListener (EagerTaskInitializationListener.java:run(60)) - JobInitManagerThread interrupted.
[junit] 2009-08-11 17:17:13,610 INFO mapred.EagerTaskInitializationListener (EagerTaskInitializationListener.java:run(64)) - Shutting down thread pool
[junit] 2009-08-11 17:17:13,611 INFO mapred.JobTracker (JobTracker.java:close(2166)) - Stopping expireLaunchingTasks
[junit] 2009-08-11 17:17:13,612 INFO mapred.JobTracker (JobTracker.java:close(2184)) - stopped all jobtracker services
[junit] Shutting down the Mini HDFS Cluster
[junit] Shutting down DataNode 1
[junit] 2009-08-11 17:17:13,713 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 38882
[junit] 2009-08-11 17:17:13,714 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 38882: exiting
[junit] 2009-08-11 17:17:13,714 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 38882: exiting
[junit] 2009-08-11 17:17:13,714 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
[junit] 2009-08-11 17:17:13,714 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 38882
[junit] 2009-08-11 17:17:13,714 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 38882: exiting
[junit] 2009-08-11 17:17:13,715 WARN datanode.DataNode (DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:43282, storageID=DS-941188496-67.195.138.9-43282-1250010972661, infoPort=58728, ipcPort=38882):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-11 17:17:13,715 INFO datanode.DataNode (DataNode.java:shutdown(639)) - Waiting for threadgroup to exit, active threads is 0
[junit] 2009-08-11 17:17:13,716 INFO datanode.DataBlockScanner (DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
[junit] 2009-08-11 17:17:13,716 INFO datanode.DataNode (DataNode.java:run(1285)) - DatanodeRegistration(127.0.0.1:43282, storageID=DS-941188496-67.195.138.9-43282-1250010972661, infoPort=58728, ipcPort=38882):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-11 17:17:13,716 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 38882
[junit] 2009-08-11 17:17:13,716 INFO datanode.DataNode (DataNode.java:shutdown(639)) - Waiting for threadgroup to exit, active threads is 0
[junit] Shutting down DataNode 0
[junit] 2009-08-11 17:17:13,818 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 57307
[junit] 2009-08-11 17:17:13,819 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 57307
[junit] 2009-08-11 17:17:13,819 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 57307: exiting
[junit] 2009-08-11 17:17:13,819 WARN datanode.DataNode (DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:52774, storageID=DS-662031835-67.195.138.9-52774-1250010972059, infoPort=49887, ipcPort=57307):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-11 17:17:13,819 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 57307: exiting
[junit] 2009-08-11 17:17:13,819 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
[junit] 2009-08-11 17:17:13,819 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 57307: exiting
[junit] 2009-08-11 17:17:13,820 INFO datanode.DataNode (DataNode.java:shutdown(639)) - Waiting for threadgroup to exit, active threads is 1
[junit] 2009-08-11 17:17:13,821 INFO datanode.DataBlockScanner (DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
[junit] 2009-08-11 17:17:13,821 INFO datanode.DataNode (DataNode.java:run(1285)) - DatanodeRegistration(127.0.0.1:52774, storageID=DS-662031835-67.195.138.9-52774-1250010972059, infoPort=49887, ipcPort=57307):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-11 17:17:13,822 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 57307
[junit] 2009-08-11 17:17:13,822 INFO datanode.DataNode (DataNode.java:shutdown(639)) - Waiting for threadgroup to exit, active threads is 0
[junit] 2009-08-11 17:17:13,930 WARN namenode.DecommissionManager (DecommissionManager.java:run(67)) - Monitor interrupted: java.lang.InterruptedException: sleep interrupted
[junit] 2009-08-11 17:17:13,930 INFO namenode.FSNamesystem (FSEditLog.java:printStatistics(876)) - Number of transactions: 88 Total time for transactions(ms): 7Number of transactions batched in Syncs: 6 Number of syncs: 62 SyncTimes(ms): 691 593
[junit] 2009-08-11 17:17:13,930 WARN namenode.FSNamesystem (FSNamesystem.java:run(2057)) - ReplicationMonitor thread received InterruptedException.java.lang.InterruptedException: sleep interrupted
[junit] 2009-08-11 17:17:13,946 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 50855
[junit] 2009-08-11 17:17:13,947 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 50855: exiting
[junit] 2009-08-11 17:17:13,947 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 50855: exiting
[junit] 2009-08-11 17:17:13,947 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 4 on 50855: exiting
[junit] 2009-08-11 17:17:13,947 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 50855: exiting
[junit] 2009-08-11 17:17:13,947 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 3 on 50855: exiting
[junit] 2009-08-11 17:17:13,948 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
[junit] 2009-08-11 17:17:13,948 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 50855
[junit] Tests run: 2, Failures: 0, Errors: 0, Time elapsed: 103.653 sec
[junit] 2009-08-11 17:17:13,947 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 9 on 50855: exiting
[junit] 2009-08-11 17:17:13,947 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 5 on 50855: exiting
[junit] 2009-08-11 17:17:13,947 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 8 on 50855: exiting
[junit] 2009-08-11 17:17:13,947 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 7 on 50855: exiting
[junit] 2009-08-11 17:17:13,947 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 6 on 50855: exiting
[junit] Running org.apache.hadoop.util.TestReflectionUtils
[junit] Tests run: 5, Failures: 0, Errors: 0, Time elapsed: 0.588 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.165 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 :631: Tests failed!
Total time: 134 minutes 27 seconds
Publishing Javadoc
Recording test results
Recording fingerprints
Publishing Clover coverage report...
Hudson build is back to normal: Hadoop-Mapreduce-trunk #46
Posted by Apache Hudson Server <hu...@hudson.zones.apache.org>.
See http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/46/changes