hadoop-mapreduce-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Apache Hudson Server <hud...@hudson.zones.apache.org>
Subject Build failed in Hudson: Hadoop-Mapreduce-trunk #61
Date Wed, 26 Aug 2009 19:53:30 GMT
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...


Mime
View raw message