FAQ
See http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/51/changes

Changes:

[yhemanth] MAPREDUCE-877. Added avro as a dependency to contrib ivy settings. Contributed by Tsz Wo (Nicholas) Sze.

[acmurthy] MAPREDUCE-478. Allow map and reduce jvm parameters, environment variables and ulimit to be set separately.

[gkesavan] HADOOP-6182. Fix ReleaseAudit warnings. Contributed by Giridharan Kesavan and Lee Tucker

------------------------------------------
[...truncated 131927 lines...]
[junit] 2009-08-17 19:04:34,612 INFO mapred.TaskRunner (ReduceTaskRunner.java:close(47)) - attempt_200908171903_0002_r_000000_0 done; removing files.
[junit] 2009-08-17 19:04:34,653 INFO mapred.JvmManager (JvmManager.java:<init>(396)) - In JvmRunner constructed JVM ID: jvm_200908171903_0002_m_-1809857230
[junit] 2009-08-17 19:04:34,654 INFO mapred.JvmManager (JvmManager.java:spawnNewJvm(364)) - JVM Runner jvm_200908171903_0002_m_-1809857230 spawned.
[junit] 2009-08-17 19:04:34,738 INFO mapred.JobClient (JobClient.java:monitorAndPrintJob(1364)) - Task Id : attempt_200908171903_0002_r_000000_0, Status : SUCCEEDED
[junit] attempt_200908171903_0002_r_000000_0: 2009-08-17 19:04:23,350 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Initializing JVM Metrics with processName=SHUFFLE, sessionId=
[junit] attempt_200908171903_0002_r_000000_0: 2009-08-17 19:04:23,475 INFO mapred.ReduceTask (ReduceTask.java:<init>(1011)) - ShuffleRamManager: MemoryLimit=141387360, MaxSingleShuffleLimit=35346840
[junit] attempt_200908171903_0002_r_000000_0: 2009-08-17 19:04:23,482 INFO mapred.ReduceTask (ReduceTask.java:run(2485)) - attempt_200908171903_0002_r_000000_0 Thread started: Thread for merging on-disk files
[junit] attempt_200908171903_0002_r_000000_0: 2009-08-17 19:04:23,482 INFO mapred.ReduceTask (ReduceTask.java:run(2584)) - attempt_200908171903_0002_r_000000_0 Thread started: Thread for merging in memory files
[junit] attempt_200908171903_0002_r_000000_0: 2009-08-17 19:04:23,482 INFO mapred.ReduceTask (ReduceTask.java:run(2490)) - attempt_200908171903_0002_r_000000_0 Thread waiting: Thread for merging on-disk files
[junit] attempt_200908171903_0002_r_000000_0: 2009-08-17 19:04:23,484 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(1892)) - attempt_200908171903_0002_r_000000_0 Need another 3 map output(s) where 0 is already in progress
[junit] attempt_200908171903_0002_r_000000_0: 2009-08-17 19:04:23,484 INFO mapred.ReduceTask (ReduceTask.java:run(2686)) - attempt_200908171903_0002_r_000000_0 Thread started: Thread for polling Map Completion Events
[junit] attempt_200908171903_0002_r_000000_0: 2009-08-17 19:04:23,484 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2005)) - attempt_200908171903_0002_r_000000_0 Scheduled 0 outputs (0 slow hosts and0 dup hosts)
[junit] attempt_200908171903_0002_r_000000_0: 2009-08-17 19:04:23,490 INFO mapred.ReduceTask (ReduceTask.java:run(2692)) - attempt_200908171903_0002_r_000000_0: Got 2 new map-outputs
[junit] attempt_200908171903_0002_r_000000_0: 2009-08-17 19:04:27,495 INFO mapred.ReduceTask (ReduceTask.java:run(2692)) - attempt_200908171903_0002_r_000000_0: Got 1 new map-outputs
[junit] attempt_200908171903_0002_r_000000_0: 2009-08-17 19:04:28,485 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2005)) - attempt_200908171903_0002_r_000000_0 Scheduled 1 outputs (0 slow hosts and0 dup hosts)
[junit] attempt_200908171903_0002_r_000000_0: 2009-08-17 19:04:28,520 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1423)) - header: attempt_200908171903_0002_m_000000_0, compressed len: 11, decompressed len: 7
[junit] attempt_200908171903_0002_r_000000_0: 2009-08-17 19:04:28,521 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1437)) - Shuffling 7 bytes (11 raw bytes) into RAM from attempt_200908171903_0002_m_000000_0
[junit] attempt_200908171903_0002_r_000000_0: 2009-08-17 19:04:28,525 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1566)) - Read 7 bytes from map-output for attempt_200908171903_0002_m_000000_0
[junit] attempt_200908171903_0002_r_000000_0: 2009-08-17 19:04:28,525 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1625)) - Rec #1 from attempt_200908171903_0002_m_000000_0 -> (2, 1) from localhost
[junit] attempt_200908171903_0002_r_000000_0: 2009-08-17 19:04:28,526 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2005)) - attempt_200908171903_0002_r_000000_0 Scheduled 1 outputs (0 slow hosts and0 dup hosts)
[junit] attempt_200908171903_0002_r_000000_0: 2009-08-17 19:04:28,529 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1423)) - header: attempt_200908171903_0002_m_000001_0, compressed len: 11, decompressed len: 7
[junit] attempt_200908171903_0002_r_000000_0: 2009-08-17 19:04:28,529 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1437)) - Shuffling 7 bytes (11 raw bytes) into RAM from attempt_200908171903_0002_m_000001_0
[junit] attempt_200908171903_0002_r_000000_0: 2009-08-17 19:04:28,529 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1566)) - Read 7 bytes from map-output for attempt_200908171903_0002_m_000001_0
[junit] attempt_200908171903_0002_r_000000_0: 2009-08-17 19:04:28,529 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1625)) - Rec #1 from attempt_200908171903_0002_m_000001_0 -> (2, 1) from localhost
[junit] attempt_200908171903_0002_r_000000_0: 2009-08-17 19:04:28,530 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2005)) - attempt_200908171903_0002_r_000000_0 Scheduled 1 outputs (0 slow hosts and0 dup hosts)
[junit] attempt_200908171903_0002_r_000000_0: 2009-08-17 19:04:28,533 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1423)) - header: attempt_200908171903_0002_m_000002_0, compressed len: 11, decompressed len: 7
[junit] attempt_200908171903_0002_r_000000_0: 2009-08-17 19:04:28,534 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1437)) - Shuffling 7 bytes (11 raw bytes) into RAM from attempt_200908171903_0002_m_000002_0
[junit] attempt_200908171903_0002_r_000000_0: 2009-08-17 19:04:28,534 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1566)) - Read 7 bytes from map-output for attempt_200908171903_0002_m_000002_0
[junit] attempt_200908171903_0002_r_000000_0: 2009-08-17 19:04:28,534 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1625)) - Rec #1 from attempt_200908171903_0002_m_000002_0 -> (2, 1) from localhost
[junit] attempt_200908171903_0002_r_000000_0: 2009-08-17 19:04:29,517 INFO mapred.ReduceTask (ReduceTask.java:run(2710)) - GetMapEventsThread exiting
[junit] attempt_200908171903_0002_r_000000_0: 2009-08-17 19:04:29,517 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2203)) - getMapsEventsThread joined.
[junit] attempt_200908171903_0002_r_000000_0: 2009-08-17 19:04:29,518 INFO mapred.ReduceTask (ReduceTask.java:close(1117)) - Closed ram manager
[junit] attempt_200908171903_0002_r_000000_0: 2009-08-17 19:04:29,518 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2231)) - Interleaved on-disk merge complete: 0 files left.
[junit] attempt_200908171903_0002_r_000000_0: 2009-08-17 19:04:29,518 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2236)) - In-memory merge complete: 3 files left.
[junit] attempt_200908171903_0002_r_000000_0: 2009-08-17 19:04:29,542 INFO mapred.Merger (Merger.java:merge(469)) - Merging 3 sorted segments
[junit] attempt_200908171903_0002_r_000000_0: 2009-08-17 19:04:29,543 INFO mapred.Merger (Merger.java:merge(568)) - Down to the last merge-pass, with 3 segments left of total size: 9 bytes
[junit] attempt_200908171903_0002_r_000000_0: 2009-08-17 19:04:29,557 INFO mapred.ReduceTask (ReduceTask.java:createKVIterator(2349)) - Merged 3 segments, 21 bytes to disk to satisfy reduce memory limit
[junit] attempt_200908171903_0002_r_000000_0: 2009-08-17 19:04:29,558 INFO mapred.ReduceTask (ReduceTask.java:createKVIterator(2369)) - Merging 1 files, 21 bytes from disk
[junit] attempt_200908171903_0002_r_000000_0: 2009-08-17 19:04:29,559 INFO mapred.ReduceTask (ReduceTask.java:createKVIterator(2383)) - Merging 0 segments, 0 bytes from memory into reduce
[junit] attempt_200908171903_0002_r_000000_0: 2009-08-17 19:04:29,559 INFO mapred.Merger (Merger.java:merge(469)) - Merging 1 sorted segments
[junit] attempt_200908171903_0002_r_000000_0: 2009-08-17 19:04:29,563 INFO mapred.Merger (Merger.java:merge(568)) - Down to the last merge-pass, with 1 segments left of total size: 13 bytes
[junit] attempt_200908171903_0002_r_000000_0: 2009-08-17 19:04:29,712 INFO mapred.Task (Task.java:done(643)) - Task:attempt_200908171903_0002_r_000000_0 is done. And is in the process of commiting
[junit] attempt_200908171903_0002_r_000000_0: 2009-08-17 19:04:31,720 INFO mapred.Task (Task.java:commit(755)) - Task attempt_200908171903_0002_r_000000_0 is allowed to commit now
[junit] attempt_200908171903_0002_r_000000_0: 2009-08-17 19:04:31,893 INFO mapred.FileOutputCommitter (FileOutputCommitter.java:commitTask(92)) - Saved output of task 'attempt_200908171903_0002_r_000000_0' to hdfs://localhost:43303/user/hudson/mapout
[junit] attempt_200908171903_0002_r_000000_0: 2009-08-17 19:04:31,898 INFO mapred.Task (Task.java:sendDone(714)) - Task 'attempt_200908171903_0002_r_000000_0' done.
[junit] 2009-08-17 19:04:35,091 INFO mapred.TaskTracker (TaskTracker.java:getTask(2819)) - JVM with ID: jvm_200908171903_0002_m_-1809857230 given task: attempt_200908171903_0002_m_000003_0
[junit] 2009-08-17 19:04:35,453 INFO mapred.TaskTracker (TaskTracker.java:reportProgress(2266)) - attempt_200908171903_0002_m_000003_0 0.0%
[junit] 2009-08-17 19:04:35,470 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-17 19:04:35,474 INFO mapred.TaskTracker (TaskTracker.java:reportProgress(2266)) - attempt_200908171903_0002_m_000003_0 0.0% cleanup > map
[junit] 2009-08-17 19:04:35,475 INFO mapred.TaskTracker (TaskTracker.java:reportDone(2347)) - Task attempt_200908171903_0002_m_000003_0 is done.
[junit] 2009-08-17 19:04:35,475 INFO mapred.TaskTracker (TaskTracker.java:reportDone(2348)) - reported output size for attempt_200908171903_0002_m_000003_0 was 0
[junit] 2009-08-17 19:04:35,476 INFO mapred.TaskTracker (TaskTracker.java:addFreeSlots(1922)) - addFreeSlot : current free slots : 2
[junit] 2009-08-17 19:04:35,567 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-17 19:04:35,568 INFO util.ProcessTree (ProcessTree.java:terminateProcessGroup(138)) - Killing all processes in the process group 27020 with SIGTERM. Exit code 1
[junit] 2009-08-17 19:04:35,746 INFO mapred.JobClient (JobClient.java:monitorAndPrintJob(1315)) - map 100% reduce 100%
[junit] 2009-08-17 19:04:37,018 INFO mapred.JvmManager (JvmManager.java:runChild(423)) - JVM : jvm_200908171903_0002_r_246459187 exited with exit code 0. Number of tasks it ran: 1
[junit] 2009-08-17 19:04:37,612 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-17 19:04:37,624 INFO mapred.JobInProgress (JobInProgress.java:completedTask(2450)) - Task 'attempt_200908171903_0002_m_000003_0' has completed task_200908171903_0002_m_000003 successfully.
[junit] 2009-08-17 19:04:37,625 INFO mapred.JobInProgress (JobInProgress.java:jobComplete(2616)) - Job job_200908171903_0002 has completed successfully.
[junit] 2009-08-17 19:04:37,625 INFO mapred.JobInProgress$JobSummary (JobInProgress.java:logJobSummary(3314)) - jobId=job_200908171903_0002,submitTime=1250535855626,launchTime=1250535855757,finishTime=1250535877625,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-17 19:04:37,629 INFO hdfs.StateChange (FSNamesystem.java:allocateBlock(1286)) - BLOCK* NameSystem.allocateBlock: /user/hudson/mapout/_logs/history/localhost_1250535818104_job_200908171903_0002_hudson_NA. blk_-719009978198625580_1015
[junit] 2009-08-17 19:04:37,630 INFO datanode.DataNode (DataXceiver.java:writeBlock(240)) - Receiving block blk_-719009978198625580_1015 src: /127.0.0.1:33990 dest: /127.0.0.1:44962
[junit] 2009-08-17 19:04:37,631 INFO datanode.DataNode (DataXceiver.java:writeBlock(240)) - Receiving block blk_-719009978198625580_1015 src: /127.0.0.1:53013 dest: /127.0.0.1:54485
[junit] 2009-08-17 19:04:37,665 INFO DataNode.clienttrace (BlockReceiver.java:lastDataNodeRun(807)) - src: /127.0.0.1:53013, dest: /127.0.0.1:54485, bytes: 11831, op: HDFS_WRITE, cliID: DFSClient_1704673456, offset: 0, srvID: DS-1819811110-67.195.138.9-54485-1250535817396, blockid: blk_-719009978198625580_1015, duration: 33349835
[junit] 2009-08-17 19:04:37,665 INFO datanode.DataNode (BlockReceiver.java:lastDataNodeRun(831)) - PacketResponder 0 for block blk_-719009978198625580_1015 terminating
[junit] 2009-08-17 19:04:37,666 INFO hdfs.StateChange (BlockManager.java:addStoredBlock(955)) - BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:54485 is added to blk_-719009978198625580_1015 size 11831
[junit] 2009-08-17 19:04:37,666 INFO DataNode.clienttrace (BlockReceiver.java:run(933)) - src: /127.0.0.1:33990, dest: /127.0.0.1:44962, bytes: 11831, op: HDFS_WRITE, cliID: DFSClient_1704673456, offset: 0, srvID: DS-731763653-67.195.138.9-44962-1250535817965, blockid: blk_-719009978198625580_1015, duration: 34234062
[junit] 2009-08-17 19:04:37,666 INFO datanode.DataNode (BlockReceiver.java:run(997)) - PacketResponder 1 for block blk_-719009978198625580_1015 terminating
[junit] 2009-08-17 19:04:37,667 INFO hdfs.StateChange (BlockManager.java:addStoredBlock(955)) - BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:44962 is added to blk_-719009978198625580_1015 size 11831
[junit] 2009-08-17 19:04:37,668 INFO hdfs.StateChange (FSNamesystem.java:completeFileInternal(1252)) - DIR* NameSystem.completeFile: file /user/hudson/mapout/_logs/history/localhost_1250535818104_job_200908171903_0002_hudson_NA is closed by DFSClient_1704673456
[junit] 2009-08-17 19:04:37,668 INFO namenode.FSNamesystem (FSEditLog.java:printStatistics(876)) - Number of transactions: 87 Total time for transactions(ms): 2Number of transactions batched in Syncs: 5 Number of syncs: 61 SyncTimes(ms): 698 502
[junit] 2009-08-17 19:04:37,683 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_1250535818104_job_200908171903_0002_hudson_NA to http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/logs/history/done
[junit] 2009-08-17 19:04:37,685 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2371)) - Removed completed task 'attempt_200908171903_0002_m_000000_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:51284'
[junit] 2009-08-17 19:04:37,685 INFO hdfs.StateChange (BlockManager.java:addToInvalidates(365)) - BLOCK* NameSystem.addToInvalidates: blk_929990804237035837 is added to invalidSet of 127.0.0.1:54485
[junit] 2009-08-17 19:04:37,685 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2371)) - Removed completed task 'attempt_200908171903_0002_m_000001_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:51284'
[junit] 2009-08-17 19:04:37,685 INFO hdfs.StateChange (BlockManager.java:addToInvalidates(365)) - BLOCK* NameSystem.addToInvalidates: blk_929990804237035837 is added to invalidSet of 127.0.0.1:44962
[junit] 2009-08-17 19:04:37,686 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2371)) - Removed completed task 'attempt_200908171903_0002_m_000003_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:51284'
[junit] 2009-08-17 19:04:37,686 INFO hdfs.StateChange (BlockManager.java:addToInvalidates(365)) - BLOCK* NameSystem.addToInvalidates: blk_-7168462742700441005 is added to invalidSet of 127.0.0.1:54485
[junit] 2009-08-17 19:04:37,686 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2371)) - Removed completed task 'attempt_200908171903_0002_m_000004_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:51284'
[junit] 2009-08-17 19:04:37,686 INFO hdfs.StateChange (BlockManager.java:addToInvalidates(365)) - BLOCK* NameSystem.addToInvalidates: blk_-7168462742700441005 is added to invalidSet of 127.0.0.1:44962
[junit] 2009-08-17 19:04:37,686 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2371)) - Removed completed task 'attempt_200908171903_0002_r_000000_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:51284'
[junit] 2009-08-17 19:04:37,694 INFO mapred.TaskTracker (TaskTracker.java:purgeJob(1671)) - Received 'KillJobAction' for job: job_200908171903_0002
[junit] 2009-08-17 19:04:37,695 INFO mapred.TaskRunner (MapTaskRunner.java:close(43)) - attempt_200908171903_0002_m_000000_0 done; removing files.
[junit] 2009-08-17 19:04:37,696 INFO mapred.TaskRunner (MapTaskRunner.java:close(43)) - attempt_200908171903_0002_m_000003_0 done; removing files.
[junit] 2009-08-17 19:04:37,696 INFO mapred.IndexCache (IndexCache.java:removeMap(140)) - Map ID attempt_200908171903_0002_m_000003_0 not found in cache
[junit] 2009-08-17 19:04:37,696 INFO mapred.TaskRunner (MapTaskRunner.java:close(43)) - attempt_200908171903_0002_m_000001_0 done; removing files.
[junit] 2009-08-17 19:04:37,710 INFO FSNamesystem.audit (FSNamesystem.java:logAuditEvent(114)) - ugi=hudson,hudson ip=/127.0.0.1 cmd=delete src=/tmp/hadoop-hudson/mapred/system/job_200908171903_0002 dst=null perm=null
[junit] 2009-08-17 19:04:37,719 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_1250535818104_job_200908171903_0002_conf.xml to http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/logs/history/done
[junit] 2009-08-17 19:04:37,752 INFO mapred.JobClient (JobClient.java:monitorAndPrintJob(1364)) - Task Id : attempt_200908171903_0002_m_000003_0, Status : SUCCEEDED
[junit] attempt_200908171903_0002_m_000003_0: 2009-08-17 19:04:35,335 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Initializing JVM Metrics with processName=MAP, sessionId=
[junit] attempt_200908171903_0002_m_000003_0: 2009-08-17 19:04:35,471 INFO mapred.Task (Task.java:done(643)) - Task:attempt_200908171903_0002_m_000003_0 is done. And is in the process of commiting
[junit] attempt_200908171903_0002_m_000003_0: 2009-08-17 19:04:35,476 INFO mapred.Task (Task.java:sendDone(714)) - Task 'attempt_200908171903_0002_m_000003_0' done.
[junit] 2009-08-17 19:04:37,756 INFO mapred.JobClient (JobClient.java:monitorAndPrintJob(1370)) - Job complete: job_200908171903_0002
[junit] 2009-08-17 19:04:37,759 INFO mapred.JobClient (Counters.java:log(534)) - Counters: 22
[junit] 2009-08-17 19:04:37,759 INFO mapred.JobClient (Counters.java:log(536)) - Job Counters
[junit] 2009-08-17 19:04:37,759 INFO mapred.JobClient (Counters.java:log(538)) - Launched reduce tasks=1
[junit] 2009-08-17 19:04:37,759 INFO mapred.JobClient (Counters.java:log(538)) - SLOTS_MILLIS_MAPS=5133
[junit] 2009-08-17 19:04:37,759 INFO mapred.JobClient (Counters.java:log(538)) - Total time spent by all reduces waiting after reserving slots (ms)=0
[junit] 2009-08-17 19:04:37,759 INFO mapred.JobClient (Counters.java:log(538)) - Total time spent by all maps waiting after reserving slots (ms)=0
[junit] 2009-08-17 19:04:37,760 INFO mapred.JobClient (Counters.java:log(538)) - Rack-local map tasks=3
[junit] 2009-08-17 19:04:37,760 INFO mapred.JobClient (Counters.java:log(538)) - Launched map tasks=3
[junit] 2009-08-17 19:04:37,760 INFO mapred.JobClient (Counters.java:log(538)) - SLOTS_MILLIS_REDUCES=9272
[junit] 2009-08-17 19:04:37,760 INFO mapred.JobClient (Counters.java:log(536)) - FileInputFormatCounters
[junit] 2009-08-17 19:04:37,760 INFO mapred.JobClient (Counters.java:log(538)) - BYTES_READ=3
[junit] 2009-08-17 19:04:37,760 INFO mapred.JobClient (Counters.java:log(536)) - FileSystemCounters
[junit] 2009-08-17 19:04:37,760 INFO mapred.JobClient (Counters.java:log(538)) - FILE_BYTES_READ=21
[junit] 2009-08-17 19:04:37,761 INFO mapred.JobClient (Counters.java:log(538)) - HDFS_BYTES_READ=828
[junit] 2009-08-17 19:04:37,761 INFO mapred.JobClient (Counters.java:log(538)) - FILE_BYTES_WRITTEN=150
[junit] 2009-08-17 19:04:37,761 INFO mapred.JobClient (Counters.java:log(538)) - HDFS_BYTES_WRITTEN=6
[junit] 2009-08-17 19:04:37,761 INFO mapred.JobClient (Counters.java:log(536)) - Map-Reduce Framework
[junit] 2009-08-17 19:04:37,761 INFO mapred.JobClient (Counters.java:log(538)) - Reduce input groups=3
[junit] 2009-08-17 19:04:37,761 INFO mapred.JobClient (Counters.java:log(538)) - Combine output records=0
[junit] 2009-08-17 19:04:37,761 INFO mapred.JobClient (Counters.java:log(538)) - Map input records=3
[junit] 2009-08-17 19:04:37,762 INFO mapred.JobClient (Counters.java:log(538)) - Reduce shuffle bytes=22
[junit] 2009-08-17 19:04:37,762 INFO mapred.JobClient (Counters.java:log(538)) - Reduce output records=3
[junit] 2009-08-17 19:04:37,762 INFO mapred.JobClient (Counters.java:log(538)) - Spilled Records=6
[junit] 2009-08-17 19:04:37,762 INFO mapred.JobClient (Counters.java:log(538)) - Map output bytes=9
[junit] 2009-08-17 19:04:37,762 INFO mapred.JobClient (Counters.java:log(538)) - Combine input records=0
[junit] 2009-08-17 19:04:37,762 INFO mapred.JobClient (Counters.java:log(538)) - Map output records=3
[junit] 2009-08-17 19:04:37,763 INFO mapred.JobClient (Counters.java:log(538)) - Reduce input records=3
[junit] 2009-08-17 19:04:37,766 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-17 19:04 /user/hudson/mapout/_logs
[junit] -rw-r--r-- 3 hudson supergroup 6 2009-08-17 19:04 /user/hudson/mapout/part-00000
[junit] 2009-08-17 19:04:37,768 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-17 19:04:37,769 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-17 19:04:37,771 INFO DataNode.clienttrace (BlockSender.java:sendBlock(417)) - src: /127.0.0.1:44962, dest: /127.0.0.1:33992, bytes: 10, op: HDFS_READ, cliID: DFSClient_1704673456, offset: 0, srvID: DS-731763653-67.195.138.9-44962-1250535817965, blockid: blk_-256556893358932153_1015, duration: 279534
[junit] 2009-08-17 19:04:37,771 INFO mapred.MiniMRCluster (MiniMRCluster.java:waitTaskTrackers(306)) - Waiting for task tracker tracker_host0.foo.com:localhost/127.0.0.1:45352 to be idle.
[junit] 2009-08-17 19:04:38,506 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2371)) - Removed completed task 'attempt_200908171903_0002_m_000002_0' from 'tracker_host0.foo.com:localhost/127.0.0.1:45352'
[junit] 2009-08-17 19:04:38,507 INFO mapred.TaskTracker (TaskTracker.java:purgeJob(1671)) - Received 'KillJobAction' for job: job_200908171903_0002
[junit] 2009-08-17 19:04:38,507 INFO mapred.TaskRunner (MapTaskRunner.java:close(43)) - attempt_200908171903_0002_m_000002_0 done; removing files.
[junit] 2009-08-17 19:04:38,772 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:45352
[junit] 2009-08-17 19:04:38,773 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 45352
[junit] 2009-08-17 19:04:38,773 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 45352: exiting
[junit] 2009-08-17 19:04:38,774 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
[junit] 2009-08-17 19:04:38,774 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 45352
[junit] 2009-08-17 19:04:38,774 INFO mapred.TaskTracker (TaskTracker.java:shutdown(1149)) - Shutting down StatusHttpServer
[junit] 2009-08-17 19:04:38,773 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 3 on 45352: exiting
[junit] 2009-08-17 19:04:38,774 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 45352: exiting
[junit] 2009-08-17 19:04:38,774 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 45352: exiting
[junit] 2009-08-17 19:04:38,876 INFO mapred.TaskTracker (TaskTracker.java:offerService(1439)) - Interrupted. Closing down.
[junit] 2009-08-17 19:04:38,877 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:51284
[junit] 2009-08-17 19:04:38,878 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 51284
[junit] 2009-08-17 19:04:38,878 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 51284: exiting
[junit] 2009-08-17 19:04:38,878 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 3 on 51284: exiting
[junit] 2009-08-17 19:04:38,878 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 51284: exiting
[junit] 2009-08-17 19:04:38,878 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 51284: exiting
[junit] 2009-08-17 19:04:38,879 INFO mapred.TaskTracker (TaskTracker.java:shutdown(1149)) - Shutting down StatusHttpServer
[junit] 2009-08-17 19:04:38,879 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
[junit] 2009-08-17 19:04:38,879 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 51284
[junit] 2009-08-17 19:04:38,981 INFO mapred.TaskTracker (TaskTracker.java:offerService(1439)) - Interrupted. Closing down.
[junit] 2009-08-17 19:04:38,981 INFO mapred.JobTracker (JobTracker.java:close(2189)) - Stopping infoServer
[junit] 2009-08-17 19:04:39,083 INFO mapred.JobTracker (JobTracker.java:close(2197)) - Stopping interTrackerServer
[junit] 2009-08-17 19:04:39,084 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 58959
[junit] 2009-08-17 19:04:39,084 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 9 on 58959: exiting
[junit] 2009-08-17 19:04:39,084 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 5 on 58959: exiting
[junit] 2009-08-17 19:04:39,084 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 58959
[junit] 2009-08-17 19:04:39,085 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 58959: exiting
[junit] 2009-08-17 19:04:39,084 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 7 on 58959: exiting
[junit] 2009-08-17 19:04:39,084 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 8 on 58959: exiting
[junit] 2009-08-17 19:04:39,084 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
[junit] 2009-08-17 19:04:39,084 INFO mapred.JobTracker (JobTracker.java:offerService(2184)) - Stopped interTrackerServer
[junit] 2009-08-17 19:04:39,084 INFO mapred.JobTracker (JobTracker.java:stopExpireTrackersThread(2240)) - Stopping expireTrackers
[junit] 2009-08-17 19:04:39,084 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 58959: exiting
[junit] 2009-08-17 19:04:39,084 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 3 on 58959: exiting
[junit] 2009-08-17 19:04:39,086 INFO mapred.JobTracker (JobTracker.java:close(2204)) - Stopping retirer
[junit] 2009-08-17 19:04:39,085 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 58959: exiting
[junit] 2009-08-17 19:04:39,085 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 4 on 58959: exiting
[junit] 2009-08-17 19:04:39,085 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 6 on 58959: exiting
[junit] 2009-08-17 19:04:39,086 INFO mapred.EagerTaskInitializationListener (EagerTaskInitializationListener.java:terminate(106)) - Stopping Job Init Manager thread
[junit] 2009-08-17 19:04:39,087 INFO mapred.EagerTaskInitializationListener (EagerTaskInitializationListener.java:run(60)) - JobInitManagerThread interrupted.
[junit] 2009-08-17 19:04:39,087 INFO mapred.EagerTaskInitializationListener (EagerTaskInitializationListener.java:run(64)) - Shutting down thread pool
[junit] 2009-08-17 19:04:39,087 INFO mapred.JobTracker (JobTracker.java:close(2216)) - Stopping expireLaunchingTasks
[junit] 2009-08-17 19:04:39,088 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-17 19:04:39,189 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 40685
[junit] 2009-08-17 19:04:39,189 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 40685: exiting
[junit] 2009-08-17 19:04:39,189 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 40685: exiting
[junit] 2009-08-17 19:04:39,190 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 40685
[junit] 2009-08-17 19:04:39,190 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 40685: exiting
[junit] 2009-08-17 19:04:39,190 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
[junit] 2009-08-17 19:04:39,190 INFO datanode.DataNode (DataNode.java:shutdown(639)) - Waiting for threadgroup to exit, active threads is 1
[junit] 2009-08-17 19:04:39,191 WARN datanode.DataNode (DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:44962, storageID=DS-731763653-67.195.138.9-44962-1250535817965, infoPort=49597, ipcPort=40685):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-17 19:04:39,193 INFO datanode.DataNode (DataNode.java:shutdown(639)) - Waiting for threadgroup to exit, active threads is 0
[junit] 2009-08-17 19:04:39,193 INFO datanode.DataBlockScanner (DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
[junit] 2009-08-17 19:04:39,194 INFO datanode.DataNode (DataNode.java:run(1285)) - DatanodeRegistration(127.0.0.1:44962, storageID=DS-731763653-67.195.138.9-44962-1250535817965, infoPort=49597, ipcPort=40685):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-17 19:04:39,194 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 40685
[junit] 2009-08-17 19:04:39,194 INFO datanode.DataNode (DataNode.java:shutdown(639)) - Waiting for threadgroup to exit, active threads is 0
[junit] Shutting down DataNode 0
[junit] 2009-08-17 19:04:39,306 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 42042
[junit] 2009-08-17 19:04:39,306 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 42042: exiting
[junit] 2009-08-17 19:04:39,307 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 42042: exiting
[junit] 2009-08-17 19:04:39,307 WARN datanode.DataNode (DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:54485, storageID=DS-1819811110-67.195.138.9-54485-1250535817396, infoPort=33854, ipcPort=42042):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-17 19:04:39,307 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 42042: exiting
[junit] 2009-08-17 19:04:39,307 INFO datanode.DataNode (DataNode.java:shutdown(639)) - Waiting for threadgroup to exit, active threads is 1
[junit] 2009-08-17 19:04:39,307 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
[junit] 2009-08-17 19:04:39,307 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 42042
[junit] 2009-08-17 19:04:39,308 INFO datanode.DataBlockScanner (DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
[junit] 2009-08-17 19:04:39,309 INFO datanode.DataNode (DataNode.java:run(1285)) - DatanodeRegistration(127.0.0.1:54485, storageID=DS-1819811110-67.195.138.9-54485-1250535817396, infoPort=33854, ipcPort=42042):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-17 19:04:39,309 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 42042
[junit] 2009-08-17 19:04:39,309 INFO datanode.DataNode (DataNode.java:shutdown(639)) - Waiting for threadgroup to exit, active threads is 0
[junit] 2009-08-17 19:04:39,415 WARN namenode.FSNamesystem (FSNamesystem.java:run(2057)) - ReplicationMonitor thread received InterruptedException.java.lang.InterruptedException: sleep interrupted
[junit] 2009-08-17 19:04:39,415 INFO namenode.FSNamesystem (FSEditLog.java:printStatistics(876)) - Number of transactions: 88 Total time for transactions(ms): 2Number of transactions batched in Syncs: 5 Number of syncs: 63 SyncTimes(ms): 713 523
[junit] 2009-08-17 19:04:39,415 WARN namenode.DecommissionManager (DecommissionManager.java:run(67)) - Monitor interrupted: java.lang.InterruptedException: sleep interrupted
[junit] 2009-08-17 19:04:39,468 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 43303
[junit] 2009-08-17 19:04:39,468 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 43303: exiting
[junit] 2009-08-17 19:04:39,469 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 43303: exiting
[junit] 2009-08-17 19:04:39,468 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 3 on 43303: exiting
[junit] 2009-08-17 19:04:39,470 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 43303: exiting
[junit] 2009-08-17 19:04:39,470 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 4 on 43303: exiting
[junit] 2009-08-17 19:04:39,471 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 5 on 43303: exiting
[junit] 2009-08-17 19:04:39,472 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 9 on 43303: exiting
[junit] 2009-08-17 19:04:39,471 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 8 on 43303: exiting
[junit] 2009-08-17 19:04:39,471 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
[junit] 2009-08-17 19:04:39,471 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 43303
[junit] 2009-08-17 19:04:39,471 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 7 on 43303: exiting
[junit] 2009-08-17 19:04:39,471 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 6 on 43303: exiting
[junit] Tests run: 2, Failures: 0, Errors: 0, Time elapsed: 103.982 sec
[junit] Running org.apache.hadoop.util.TestReflectionUtils
[junit] Tests run: 5, Failures: 0, Errors: 0, Time elapsed: 0.571 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.163 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: 173 minutes 41 seconds
Publishing Javadoc
Recording test results
Recording fingerprints
Publishing Clover coverage report...

Search Discussions

  • Apache Hudson Server at Aug 18, 2009 at 1:18 am
    See http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/52/changes

    Changes:

    [szetszwo] MAPREDUCE-852. In build.xml, remove the Main-Class, which is incorrectly set in tools, and rename the target "tools-jar" to "tools".

    [yhemanth] MAPREDUCE-711. Moved Distributed Cache from Common to Map/Reduce project. Contributed by Vinod Kumar Vavilapalli.

    ------------------------------------------
    [...truncated 134360 lines...]
    [junit] 2009-08-18 01:14:13,625 INFO mapred.JvmManager (JvmManager.java:<init>(396)) - In JvmRunner constructed JVM ID: jvm_200908180113_0002_m_1756094382
    [junit] 2009-08-18 01:14:13,626 INFO mapred.JvmManager (JvmManager.java:spawnNewJvm(364)) - JVM Runner jvm_200908180113_0002_m_1756094382 spawned.
    [junit] 2009-08-18 01:14:13,708 INFO mapred.JobClient (JobClient.java:monitorAndPrintJob(1364)) - Task Id : attempt_200908180113_0002_r_000000_0, Status : SUCCEEDED
    [junit] attempt_200908180113_0002_r_000000_0: 2009-08-18 01:14:02,483 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Initializing JVM Metrics with processName=SHUFFLE, sessionId=
    [junit] attempt_200908180113_0002_r_000000_0: 2009-08-18 01:14:02,608 INFO mapred.ReduceTask (ReduceTask.java:<init>(1011)) - ShuffleRamManager: MemoryLimit=141387360, MaxSingleShuffleLimit=35346840
    [junit] attempt_200908180113_0002_r_000000_0: 2009-08-18 01:14:02,614 INFO mapred.ReduceTask (ReduceTask.java:run(2485)) - attempt_200908180113_0002_r_000000_0 Thread started: Thread for merging on-disk files
    [junit] attempt_200908180113_0002_r_000000_0: 2009-08-18 01:14:02,614 INFO mapred.ReduceTask (ReduceTask.java:run(2584)) - attempt_200908180113_0002_r_000000_0 Thread started: Thread for merging in memory files
    [junit] attempt_200908180113_0002_r_000000_0: 2009-08-18 01:14:02,614 INFO mapred.ReduceTask (ReduceTask.java:run(2490)) - attempt_200908180113_0002_r_000000_0 Thread waiting: Thread for merging on-disk files
    [junit] attempt_200908180113_0002_r_000000_0: 2009-08-18 01:14:02,616 INFO mapred.ReduceTask (ReduceTask.java:run(2686)) - attempt_200908180113_0002_r_000000_0 Thread started: Thread for polling Map Completion Events
    [junit] attempt_200908180113_0002_r_000000_0: 2009-08-18 01:14:02,617 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(1892)) - attempt_200908180113_0002_r_000000_0 Need another 3 map output(s) where 0 is already in progress
    [junit] attempt_200908180113_0002_r_000000_0: 2009-08-18 01:14:02,618 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2005)) - attempt_200908180113_0002_r_000000_0 Scheduled 0 outputs (0 slow hosts and0 dup hosts)
    [junit] attempt_200908180113_0002_r_000000_0: 2009-08-18 01:14:02,622 INFO mapred.ReduceTask (ReduceTask.java:run(2692)) - attempt_200908180113_0002_r_000000_0: Got 2 new map-outputs
    [junit] attempt_200908180113_0002_r_000000_0: 2009-08-18 01:14:05,626 INFO mapred.ReduceTask (ReduceTask.java:run(2692)) - attempt_200908180113_0002_r_000000_0: Got 1 new map-outputs
    [junit] attempt_200908180113_0002_r_000000_0: 2009-08-18 01:14:07,618 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2005)) - attempt_200908180113_0002_r_000000_0 Scheduled 1 outputs (0 slow hosts and0 dup hosts)
    [junit] attempt_200908180113_0002_r_000000_0: 2009-08-18 01:14:07,643 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1423)) - header: attempt_200908180113_0002_m_000000_0, compressed len: 11, decompressed len: 7
    [junit] attempt_200908180113_0002_r_000000_0: 2009-08-18 01:14:07,643 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1437)) - Shuffling 7 bytes (11 raw bytes) into RAM from attempt_200908180113_0002_m_000000_0
    [junit] attempt_200908180113_0002_r_000000_0: 2009-08-18 01:14:07,647 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1566)) - Read 7 bytes from map-output for attempt_200908180113_0002_m_000000_0
    [junit] attempt_200908180113_0002_r_000000_0: 2009-08-18 01:14:07,647 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1625)) - Rec #1 from attempt_200908180113_0002_m_000000_0 -> (2, 1) from localhost
    [junit] attempt_200908180113_0002_r_000000_0: 2009-08-18 01:14:07,652 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2005)) - attempt_200908180113_0002_r_000000_0 Scheduled 1 outputs (0 slow hosts and0 dup hosts)
    [junit] attempt_200908180113_0002_r_000000_0: 2009-08-18 01:14:07,654 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1423)) - header: attempt_200908180113_0002_m_000001_0, compressed len: 11, decompressed len: 7
    [junit] attempt_200908180113_0002_r_000000_0: 2009-08-18 01:14:07,654 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1437)) - Shuffling 7 bytes (11 raw bytes) into RAM from attempt_200908180113_0002_m_000001_0
    [junit] attempt_200908180113_0002_r_000000_0: 2009-08-18 01:14:07,654 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1566)) - Read 7 bytes from map-output for attempt_200908180113_0002_m_000001_0
    [junit] attempt_200908180113_0002_r_000000_0: 2009-08-18 01:14:07,655 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1625)) - Rec #1 from attempt_200908180113_0002_m_000001_0 -> (2, 1) from localhost
    [junit] attempt_200908180113_0002_r_000000_0: 2009-08-18 01:14:07,655 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2005)) - attempt_200908180113_0002_r_000000_0 Scheduled 1 outputs (0 slow hosts and0 dup hosts)
    [junit] attempt_200908180113_0002_r_000000_0: 2009-08-18 01:14:07,659 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1423)) - header: attempt_200908180113_0002_m_000002_0, compressed len: 11, decompressed len: 7
    [junit] attempt_200908180113_0002_r_000000_0: 2009-08-18 01:14:07,659 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1437)) - Shuffling 7 bytes (11 raw bytes) into RAM from attempt_200908180113_0002_m_000002_0
    [junit] attempt_200908180113_0002_r_000000_0: 2009-08-18 01:14:07,659 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1566)) - Read 7 bytes from map-output for attempt_200908180113_0002_m_000002_0
    [junit] attempt_200908180113_0002_r_000000_0: 2009-08-18 01:14:07,659 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1625)) - Rec #1 from attempt_200908180113_0002_m_000002_0 -> (2, 1) from localhost
    [junit] attempt_200908180113_0002_r_000000_0: 2009-08-18 01:14:08,629 INFO mapred.ReduceTask (ReduceTask.java:run(2710)) - GetMapEventsThread exiting
    [junit] attempt_200908180113_0002_r_000000_0: 2009-08-18 01:14:08,629 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2203)) - getMapsEventsThread joined.
    [junit] attempt_200908180113_0002_r_000000_0: 2009-08-18 01:14:08,629 INFO mapred.ReduceTask (ReduceTask.java:close(1117)) - Closed ram manager
    [junit] attempt_200908180113_0002_r_000000_0: 2009-08-18 01:14:08,629 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2231)) - Interleaved on-disk merge complete: 0 files left.
    [junit] attempt_200908180113_0002_r_000000_0: 2009-08-18 01:14:08,630 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2236)) - In-memory merge complete: 3 files left.
    [junit] attempt_200908180113_0002_r_000000_0: 2009-08-18 01:14:08,687 INFO mapred.Merger (Merger.java:merge(469)) - Merging 3 sorted segments
    [junit] attempt_200908180113_0002_r_000000_0: 2009-08-18 01:14:08,688 INFO mapred.Merger (Merger.java:merge(568)) - Down to the last merge-pass, with 3 segments left of total size: 9 bytes
    [junit] attempt_200908180113_0002_r_000000_0: 2009-08-18 01:14:08,700 INFO mapred.ReduceTask (ReduceTask.java:createKVIterator(2349)) - Merged 3 segments, 21 bytes to disk to satisfy reduce memory limit
    [junit] attempt_200908180113_0002_r_000000_0: 2009-08-18 01:14:08,701 INFO mapred.ReduceTask (ReduceTask.java:createKVIterator(2369)) - Merging 1 files, 21 bytes from disk
    [junit] attempt_200908180113_0002_r_000000_0: 2009-08-18 01:14:08,701 INFO mapred.ReduceTask (ReduceTask.java:createKVIterator(2383)) - Merging 0 segments, 0 bytes from memory into reduce
    [junit] attempt_200908180113_0002_r_000000_0: 2009-08-18 01:14:08,702 INFO mapred.Merger (Merger.java:merge(469)) - Merging 1 sorted segments
    [junit] attempt_200908180113_0002_r_000000_0: 2009-08-18 01:14:08,705 INFO mapred.Merger (Merger.java:merge(568)) - Down to the last merge-pass, with 1 segments left of total size: 13 bytes
    [junit] attempt_200908180113_0002_r_000000_0: 2009-08-18 01:14:08,909 INFO mapred.Task (Task.java:done(643)) - Task:attempt_200908180113_0002_r_000000_0 is done. And is in the process of commiting
    [junit] attempt_200908180113_0002_r_000000_0: 2009-08-18 01:14:10,917 INFO mapred.Task (Task.java:commit(755)) - Task attempt_200908180113_0002_r_000000_0 is allowed to commit now
    [junit] attempt_200908180113_0002_r_000000_0: 2009-08-18 01:14:11,060 INFO mapred.FileOutputCommitter (FileOutputCommitter.java:commitTask(92)) - Saved output of task 'attempt_200908180113_0002_r_000000_0' to hdfs://localhost:35791/user/hudson/mapout
    [junit] attempt_200908180113_0002_r_000000_0: 2009-08-18 01:14:11,063 INFO mapred.Task (Task.java:sendDone(714)) - Task 'attempt_200908180113_0002_r_000000_0' done.
    [junit] 2009-08-18 01:14:14,069 INFO mapred.TaskTracker (TaskTracker.java:getTask(2819)) - JVM with ID: jvm_200908180113_0002_m_1756094382 given task: attempt_200908180113_0002_m_000003_0
    [junit] 2009-08-18 01:14:14,430 INFO mapred.TaskTracker (TaskTracker.java:reportProgress(2266)) - attempt_200908180113_0002_m_000003_0 0.0%
    [junit] 2009-08-18 01:14:14,469 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-18 01:14:14,473 INFO mapred.TaskTracker (TaskTracker.java:reportProgress(2266)) - attempt_200908180113_0002_m_000003_0 0.0% cleanup > map
    [junit] 2009-08-18 01:14:14,474 INFO mapred.TaskTracker (TaskTracker.java:reportDone(2347)) - Task attempt_200908180113_0002_m_000003_0 is done.
    [junit] 2009-08-18 01:14:14,475 INFO mapred.TaskTracker (TaskTracker.java:reportDone(2348)) - reported output size for attempt_200908180113_0002_m_000003_0 was 0
    [junit] 2009-08-18 01:14:14,476 INFO mapred.TaskTracker (TaskTracker.java:addFreeSlots(1922)) - addFreeSlot : current free slots : 2
    [junit] 2009-08-18 01:14:14,687 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-18 01:14:14,688 INFO util.ProcessTree (ProcessTree.java:terminateProcessGroup(138)) - Killing all processes in the process group 8651 with SIGTERM. Exit code 1
    [junit] 2009-08-18 01:14:14,715 INFO mapred.JobClient (JobClient.java:monitorAndPrintJob(1315)) - map 100% reduce 100%
    [junit] 2009-08-18 01:14:16,136 INFO mapred.JvmManager (JvmManager.java:runChild(423)) - JVM : jvm_200908180113_0002_r_621611046 exited with exit code 0. Number of tasks it ran: 1
    [junit] 2009-08-18 01:14:16,580 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-18 01:14:16,582 INFO mapred.JobInProgress (JobInProgress.java:completedTask(2450)) - Task 'attempt_200908180113_0002_m_000003_0' has completed task_200908180113_0002_m_000003 successfully.
    [junit] 2009-08-18 01:14:16,583 INFO mapred.JobInProgress (JobInProgress.java:jobComplete(2616)) - Job job_200908180113_0002 has completed successfully.
    [junit] 2009-08-18 01:14:16,583 INFO mapred.JobInProgress$JobSummary (JobInProgress.java:logJobSummary(3314)) - jobId=job_200908180113_0002,submitTime=1250558034567,launchTime=1250558034718,finishTime=1250558056583,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-18 01:14:16,588 INFO hdfs.StateChange (FSNamesystem.java:allocateBlock(1286)) - BLOCK* NameSystem.allocateBlock: /user/hudson/mapout/_logs/history/localhost_1250557997282_job_200908180113_0002_hudson_NA. blk_-4269167582208245047_1015
    [junit] 2009-08-18 01:14:16,589 INFO datanode.DataNode (DataXceiver.java:writeBlock(240)) - Receiving block blk_-4269167582208245047_1015 src: /127.0.0.1:56242 dest: /127.0.0.1:36377
    [junit] 2009-08-18 01:14:16,590 INFO datanode.DataNode (DataXceiver.java:writeBlock(240)) - Receiving block blk_-4269167582208245047_1015 src: /127.0.0.1:44043 dest: /127.0.0.1:56265
    [junit] 2009-08-18 01:14:16,593 INFO DataNode.clienttrace (BlockReceiver.java:lastDataNodeRun(807)) - src: /127.0.0.1:44043, dest: /127.0.0.1:56265, bytes: 11831, op: HDFS_WRITE, cliID: DFSClient_-627587164, offset: 0, srvID: DS-621246862-67.195.138.9-56265-1250557997135, blockid: blk_-4269167582208245047_1015, duration: 1508044
    [junit] 2009-08-18 01:14:16,593 INFO datanode.DataNode (BlockReceiver.java:lastDataNodeRun(831)) - PacketResponder 0 for block blk_-4269167582208245047_1015 terminating
    [junit] 2009-08-18 01:14:16,594 INFO DataNode.clienttrace (BlockReceiver.java:run(933)) - src: /127.0.0.1:56242, dest: /127.0.0.1:36377, bytes: 11831, op: HDFS_WRITE, cliID: DFSClient_-627587164, offset: 0, srvID: DS-168327451-67.195.138.9-36377-1250557996540, blockid: blk_-4269167582208245047_1015, duration: 2202186
    [junit] 2009-08-18 01:14:16,594 INFO hdfs.StateChange (BlockManager.java:addStoredBlock(955)) - BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:56265 is added to blk_-4269167582208245047_1015 size 11831
    [junit] 2009-08-18 01:14:16,594 INFO datanode.DataNode (BlockReceiver.java:run(997)) - PacketResponder 1 for block blk_-4269167582208245047_1015 terminating
    [junit] 2009-08-18 01:14:16,595 INFO hdfs.StateChange (BlockManager.java:addStoredBlock(955)) - BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:36377 is added to blk_-4269167582208245047_1015 size 11831
    [junit] 2009-08-18 01:14:16,596 INFO hdfs.StateChange (FSNamesystem.java:completeFileInternal(1252)) - DIR* NameSystem.completeFile: file /user/hudson/mapout/_logs/history/localhost_1250557997282_job_200908180113_0002_hudson_NA is closed by DFSClient_-627587164
    [junit] 2009-08-18 01:14:16,597 INFO namenode.FSNamesystem (FSEditLog.java:printStatistics(876)) - Number of transactions: 87 Total time for transactions(ms): 4Number of transactions batched in Syncs: 5 Number of syncs: 61 SyncTimes(ms): 729 630
    [junit] 2009-08-18 01:14:16,607 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_1250557997282_job_200908180113_0002_hudson_NA to http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/logs/history/done
    [junit] 2009-08-18 01:14:16,609 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2371)) - Removed completed task 'attempt_200908180113_0002_m_000000_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:41637'
    [junit] 2009-08-18 01:14:16,609 INFO hdfs.StateChange (BlockManager.java:addToInvalidates(365)) - BLOCK* NameSystem.addToInvalidates: blk_1843057237158409994 is added to invalidSet of 127.0.0.1:56265
    [junit] 2009-08-18 01:14:16,609 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2371)) - Removed completed task 'attempt_200908180113_0002_m_000001_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:41637'
    [junit] 2009-08-18 01:14:16,609 INFO hdfs.StateChange (BlockManager.java:addToInvalidates(365)) - BLOCK* NameSystem.addToInvalidates: blk_1843057237158409994 is added to invalidSet of 127.0.0.1:36377
    [junit] 2009-08-18 01:14:16,609 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2371)) - Removed completed task 'attempt_200908180113_0002_m_000003_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:41637'
    [junit] 2009-08-18 01:14:16,610 INFO hdfs.StateChange (BlockManager.java:addToInvalidates(365)) - BLOCK* NameSystem.addToInvalidates: blk_-5315785019860883026 is added to invalidSet of 127.0.0.1:36377
    [junit] 2009-08-18 01:14:16,617 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2371)) - Removed completed task 'attempt_200908180113_0002_m_000004_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:41637'
    [junit] 2009-08-18 01:14:16,617 INFO hdfs.StateChange (BlockManager.java:addToInvalidates(365)) - BLOCK* NameSystem.addToInvalidates: blk_-5315785019860883026 is added to invalidSet of 127.0.0.1:56265
    [junit] 2009-08-18 01:14:16,617 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2371)) - Removed completed task 'attempt_200908180113_0002_r_000000_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:41637'
    [junit] 2009-08-18 01:14:16,624 INFO mapred.TaskTracker (TaskTracker.java:purgeJob(1671)) - Received 'KillJobAction' for job: job_200908180113_0002
    [junit] 2009-08-18 01:14:16,625 INFO mapred.TaskRunner (MapTaskRunner.java:close(43)) - attempt_200908180113_0002_m_000003_0 done; removing files.
    [junit] 2009-08-18 01:14:16,626 INFO mapred.IndexCache (IndexCache.java:removeMap(140)) - Map ID attempt_200908180113_0002_m_000003_0 not found in cache
    [junit] 2009-08-18 01:14:16,626 INFO mapred.TaskRunner (MapTaskRunner.java:close(43)) - attempt_200908180113_0002_m_000000_0 done; removing files.
    [junit] 2009-08-18 01:14:16,627 INFO mapred.TaskRunner (MapTaskRunner.java:close(43)) - attempt_200908180113_0002_m_000001_0 done; removing files.
    [junit] 2009-08-18 01:14:16,639 INFO FSNamesystem.audit (FSNamesystem.java:logAuditEvent(114)) - ugi=hudson,hudson ip=/127.0.0.1 cmd=delete src=/tmp/hadoop-hudson/mapred/system/job_200908180113_0002 dst=null perm=null
    [junit] 2009-08-18 01:14:16,661 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_1250557997282_job_200908180113_0002_conf.xml to http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/logs/history/done
    [junit] 2009-08-18 01:14:16,721 INFO mapred.JobClient (JobClient.java:monitorAndPrintJob(1364)) - Task Id : attempt_200908180113_0002_m_000003_0, Status : SUCCEEDED
    [junit] attempt_200908180113_0002_m_000003_0: 2009-08-18 01:14:14,312 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Initializing JVM Metrics with processName=MAP, sessionId=
    [junit] attempt_200908180113_0002_m_000003_0: 2009-08-18 01:14:14,470 INFO mapred.Task (Task.java:done(643)) - Task:attempt_200908180113_0002_m_000003_0 is done. And is in the process of commiting
    [junit] attempt_200908180113_0002_m_000003_0: 2009-08-18 01:14:14,476 INFO mapred.Task (Task.java:sendDone(714)) - Task 'attempt_200908180113_0002_m_000003_0' done.
    [junit] 2009-08-18 01:14:16,724 INFO mapred.JobClient (JobClient.java:monitorAndPrintJob(1370)) - Job complete: job_200908180113_0002
    [junit] 2009-08-18 01:14:16,727 INFO mapred.JobClient (Counters.java:log(534)) - Counters: 22
    [junit] 2009-08-18 01:14:16,727 INFO mapred.JobClient (Counters.java:log(536)) - Job Counters
    [junit] 2009-08-18 01:14:16,727 INFO mapred.JobClient (Counters.java:log(538)) - Launched reduce tasks=1
    [junit] 2009-08-18 01:14:16,727 INFO mapred.JobClient (Counters.java:log(538)) - SLOTS_MILLIS_MAPS=5343
    [junit] 2009-08-18 01:14:16,728 INFO mapred.JobClient (Counters.java:log(538)) - Total time spent by all reduces waiting after reserving slots (ms)=0
    [junit] 2009-08-18 01:14:16,728 INFO mapred.JobClient (Counters.java:log(538)) - Total time spent by all maps waiting after reserving slots (ms)=0
    [junit] 2009-08-18 01:14:16,728 INFO mapred.JobClient (Counters.java:log(538)) - Rack-local map tasks=3
    [junit] 2009-08-18 01:14:16,728 INFO mapred.JobClient (Counters.java:log(538)) - Launched map tasks=3
    [junit] 2009-08-18 01:14:16,728 INFO mapred.JobClient (Counters.java:log(538)) - SLOTS_MILLIS_REDUCES=9479
    [junit] 2009-08-18 01:14:16,728 INFO mapred.JobClient (Counters.java:log(536)) - FileInputFormatCounters
    [junit] 2009-08-18 01:14:16,728 INFO mapred.JobClient (Counters.java:log(538)) - BYTES_READ=3
    [junit] 2009-08-18 01:14:16,729 INFO mapred.JobClient (Counters.java:log(536)) - FileSystemCounters
    [junit] 2009-08-18 01:14:16,729 INFO mapred.JobClient (Counters.java:log(538)) - FILE_BYTES_READ=21
    [junit] 2009-08-18 01:14:16,729 INFO mapred.JobClient (Counters.java:log(538)) - HDFS_BYTES_READ=828
    [junit] 2009-08-18 01:14:16,729 INFO mapred.JobClient (Counters.java:log(538)) - FILE_BYTES_WRITTEN=150
    [junit] 2009-08-18 01:14:16,729 INFO mapred.JobClient (Counters.java:log(538)) - HDFS_BYTES_WRITTEN=6
    [junit] 2009-08-18 01:14:16,729 INFO mapred.JobClient (Counters.java:log(536)) - Map-Reduce Framework
    [junit] 2009-08-18 01:14:16,730 INFO mapred.JobClient (Counters.java:log(538)) - Reduce input groups=3
    [junit] 2009-08-18 01:14:16,730 INFO mapred.JobClient (Counters.java:log(538)) - Combine output records=0
    [junit] 2009-08-18 01:14:16,730 INFO mapred.JobClient (Counters.java:log(538)) - Map input records=3
    [junit] 2009-08-18 01:14:16,730 INFO mapred.JobClient (Counters.java:log(538)) - Reduce shuffle bytes=33
    [junit] 2009-08-18 01:14:16,730 INFO mapred.JobClient (Counters.java:log(538)) - Reduce output records=3
    [junit] 2009-08-18 01:14:16,730 INFO mapred.JobClient (Counters.java:log(538)) - Spilled Records=6
    [junit] 2009-08-18 01:14:16,730 INFO mapred.JobClient (Counters.java:log(538)) - Map output bytes=9
    [junit] 2009-08-18 01:14:16,731 INFO mapred.JobClient (Counters.java:log(538)) - Combine input records=0
    [junit] 2009-08-18 01:14:16,731 INFO mapred.JobClient (Counters.java:log(538)) - Map output records=3
    [junit] 2009-08-18 01:14:16,731 INFO mapred.JobClient (Counters.java:log(538)) - Reduce input records=3
    [junit] 2009-08-18 01:14:16,734 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-18 01:13 /user/hudson/mapout/_logs
    [junit] -rw-r--r-- 3 hudson supergroup 6 2009-08-18 01:14 /user/hudson/mapout/part-00000
    [junit] 2009-08-18 01:14:16,736 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-18 01:14:16,737 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-18 01:14:16,739 INFO DataNode.clienttrace (BlockSender.java:sendBlock(417)) - src: /127.0.0.1:36377, dest: /127.0.0.1:56244, bytes: 10, op: HDFS_READ, cliID: DFSClient_-627587164, offset: 0, srvID: DS-168327451-67.195.138.9-36377-1250557996540, blockid: blk_-7604875058144586530_1015, duration: 270506
    [junit] 2009-08-18 01:14:16,739 INFO mapred.MiniMRCluster (MiniMRCluster.java:waitTaskTrackers(306)) - Waiting for task tracker tracker_host0.foo.com:localhost/127.0.0.1:49902 to be idle.
    [junit] 2009-08-18 01:14:17,440 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2371)) - Removed completed task 'attempt_200908180113_0002_m_000002_0' from 'tracker_host0.foo.com:localhost/127.0.0.1:49902'
    [junit] 2009-08-18 01:14:17,440 INFO mapred.TaskTracker (TaskTracker.java:purgeJob(1671)) - Received 'KillJobAction' for job: job_200908180113_0002
    [junit] 2009-08-18 01:14:17,441 INFO mapred.TaskRunner (MapTaskRunner.java:close(43)) - attempt_200908180113_0002_m_000002_0 done; removing files.
    [junit] 2009-08-18 01:14:17,740 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:49902
    [junit] 2009-08-18 01:14:17,740 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 49902
    [junit] 2009-08-18 01:14:17,742 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 49902: exiting
    [junit] 2009-08-18 01:14:17,742 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 49902
    [junit] 2009-08-18 01:14:17,742 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 3 on 49902: exiting
    [junit] 2009-08-18 01:14:17,742 INFO mapred.TaskTracker (TaskTracker.java:shutdown(1149)) - Shutting down StatusHttpServer
    [junit] 2009-08-18 01:14:17,742 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
    [junit] 2009-08-18 01:14:17,743 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 49902: exiting
    [junit] 2009-08-18 01:14:17,743 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 49902: exiting
    [junit] 2009-08-18 01:14:17,746 INFO mapred.TaskTracker (TaskTracker.java:offerService(1439)) - Interrupted. Closing down.
    [junit] 2009-08-18 01:14:17,747 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:41637
    [junit] 2009-08-18 01:14:17,747 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 41637
    [junit] 2009-08-18 01:14:17,747 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 41637: exiting
    [junit] 2009-08-18 01:14:17,747 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 41637
    [junit] 2009-08-18 01:14:17,748 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 41637: exiting
    [junit] 2009-08-18 01:14:17,748 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 3 on 41637: exiting
    [junit] 2009-08-18 01:14:17,748 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
    [junit] 2009-08-18 01:14:17,748 INFO mapred.TaskTracker (TaskTracker.java:shutdown(1149)) - Shutting down StatusHttpServer
    [junit] 2009-08-18 01:14:17,747 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 41637: exiting
    [junit] 2009-08-18 01:14:17,851 INFO mapred.TaskTracker (TaskTracker.java:offerService(1439)) - Interrupted. Closing down.
    [junit] 2009-08-18 01:14:17,851 INFO mapred.JobTracker (JobTracker.java:close(2189)) - Stopping infoServer
    [junit] 2009-08-18 01:14:17,954 INFO mapred.JobTracker (JobTracker.java:close(2197)) - Stopping interTrackerServer
    [junit] 2009-08-18 01:14:17,954 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 52973
    [junit] 2009-08-18 01:14:17,954 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 52973: exiting
    [junit] 2009-08-18 01:14:17,955 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 9 on 52973: exiting
    [junit] 2009-08-18 01:14:17,955 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 3 on 52973: exiting
    [junit] 2009-08-18 01:14:17,955 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 7 on 52973: exiting
    [junit] 2009-08-18 01:14:17,955 INFO mapred.JobTracker (JobTracker.java:offerService(2184)) - Stopped interTrackerServer
    [junit] 2009-08-18 01:14:17,955 INFO mapred.JobTracker (JobTracker.java:stopExpireTrackersThread(2240)) - Stopping expireTrackers
    [junit] 2009-08-18 01:14:17,955 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 8 on 52973: exiting
    [junit] 2009-08-18 01:14:17,955 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
    [junit] 2009-08-18 01:14:17,954 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 4 on 52973: exiting
    [junit] 2009-08-18 01:14:17,955 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 6 on 52973: exiting
    [junit] 2009-08-18 01:14:17,955 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 52973: exiting
    [junit] 2009-08-18 01:14:17,955 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 52973
    [junit] 2009-08-18 01:14:17,954 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 5 on 52973: exiting
    [junit] 2009-08-18 01:14:17,954 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 52973: exiting
    [junit] 2009-08-18 01:14:17,957 INFO mapred.JobTracker (JobTracker.java:close(2204)) - Stopping retirer
    [junit] 2009-08-18 01:14:17,958 INFO mapred.EagerTaskInitializationListener (EagerTaskInitializationListener.java:terminate(106)) - Stopping Job Init Manager thread
    [junit] 2009-08-18 01:14:17,958 INFO mapred.EagerTaskInitializationListener (EagerTaskInitializationListener.java:run(60)) - JobInitManagerThread interrupted.
    [junit] 2009-08-18 01:14:17,958 INFO mapred.EagerTaskInitializationListener (EagerTaskInitializationListener.java:run(64)) - Shutting down thread pool
    [junit] 2009-08-18 01:14:17,958 INFO mapred.JobTracker (JobTracker.java:close(2216)) - Stopping expireLaunchingTasks
    [junit] 2009-08-18 01:14:17,959 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-18 01:14:18,061 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 50453
    [junit] 2009-08-18 01:14:18,061 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 50453: exiting
    [junit] 2009-08-18 01:14:18,061 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 50453: exiting
    [junit] 2009-08-18 01:14:18,062 INFO datanode.DataNode (DataNode.java:shutdown(639)) - Waiting for threadgroup to exit, active threads is 1
    [junit] 2009-08-18 01:14:18,062 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
    [junit] 2009-08-18 01:14:18,062 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 50453
    [junit] 2009-08-18 01:14:18,062 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 50453: exiting
    [junit] 2009-08-18 01:14:18,062 WARN datanode.DataNode (DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:56265, storageID=DS-621246862-67.195.138.9-56265-1250557997135, infoPort=44926, ipcPort=50453):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-18 01:14:18,064 INFO datanode.DataNode (DataNode.java:shutdown(639)) - Waiting for threadgroup to exit, active threads is 0
    [junit] 2009-08-18 01:14:18,065 INFO datanode.DataBlockScanner (DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
    [junit] 2009-08-18 01:14:18,065 INFO datanode.DataNode (DataNode.java:run(1285)) - DatanodeRegistration(127.0.0.1:56265, storageID=DS-621246862-67.195.138.9-56265-1250557997135, infoPort=44926, ipcPort=50453):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-18 01:14:18,065 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 50453
    [junit] 2009-08-18 01:14:18,065 INFO datanode.DataNode (DataNode.java:shutdown(639)) - Waiting for threadgroup to exit, active threads is 0
    [junit] Shutting down DataNode 0
    [junit] 2009-08-18 01:14:18,168 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 45461
    [junit] 2009-08-18 01:14:18,168 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 45461: exiting
    [junit] 2009-08-18 01:14:18,168 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 45461
    [junit] 2009-08-18 01:14:18,168 INFO datanode.DataNode (DataNode.java:shutdown(639)) - Waiting for threadgroup to exit, active threads is 1
    [junit] 2009-08-18 01:14:18,168 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
    [junit] 2009-08-18 01:14:18,168 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 45461: exiting
    [junit] 2009-08-18 01:14:18,169 WARN datanode.DataNode (DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:36377, storageID=DS-168327451-67.195.138.9-36377-1250557996540, infoPort=57221, ipcPort=45461):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-18 01:14:18,169 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 45461: exiting
    [junit] 2009-08-18 01:14:18,171 INFO datanode.DataNode (DataNode.java:shutdown(639)) - Waiting for threadgroup to exit, active threads is 0
    [junit] 2009-08-18 01:14:18,172 INFO datanode.DataBlockScanner (DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
    [junit] 2009-08-18 01:14:18,172 INFO datanode.DataNode (DataNode.java:run(1285)) - DatanodeRegistration(127.0.0.1:36377, storageID=DS-168327451-67.195.138.9-36377-1250557996540, infoPort=57221, ipcPort=45461):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-18 01:14:18,172 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 45461
    [junit] 2009-08-18 01:14:18,172 INFO datanode.DataNode (DataNode.java:shutdown(639)) - Waiting for threadgroup to exit, active threads is 0
    [junit] 2009-08-18 01:14:18,278 WARN namenode.FSNamesystem (FSNamesystem.java:run(2057)) - ReplicationMonitor thread received InterruptedException.java.lang.InterruptedException: sleep interrupted
    [junit] 2009-08-18 01:14:18,278 INFO namenode.FSNamesystem (FSEditLog.java:printStatistics(876)) - Number of transactions: 88 Total time for transactions(ms): 5Number of transactions batched in Syncs: 5 Number of syncs: 63 SyncTimes(ms): 752 636
    [junit] 2009-08-18 01:14:18,278 WARN namenode.DecommissionManager (DecommissionManager.java:run(67)) - Monitor interrupted: java.lang.InterruptedException: sleep interrupted
    [junit] 2009-08-18 01:14:18,292 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 35791
    [junit] 2009-08-18 01:14:18,292 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 35791: exiting
    [junit] 2009-08-18 01:14:18,293 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
    [junit] 2009-08-18 01:14:18,293 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 8 on 35791: exiting
    [junit] 2009-08-18 01:14:18,293 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 7 on 35791: exiting
    [junit] 2009-08-18 01:14:18,292 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 35791: exiting
    [junit] 2009-08-18 01:14:18,292 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 35791: exiting
    [junit] 2009-08-18 01:14:18,293 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 6 on 35791: exiting
    [junit] 2009-08-18 01:14:18,293 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 4 on 35791: exiting
    [junit] 2009-08-18 01:14:18,293 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 9 on 35791: exiting
    [junit] 2009-08-18 01:14:18,293 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 35791
    [junit] 2009-08-18 01:14:18,293 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 3 on 35791: exiting
    [junit] 2009-08-18 01:14:18,293 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 5 on 35791: exiting
    [junit] Tests run: 2, Failures: 0, Errors: 0, Time elapsed: 103.588 sec
    [junit] Running org.apache.hadoop.util.TestReflectionUtils
    [junit] Tests run: 5, Failures: 0, Errors: 0, Time elapsed: 0.585 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 :627: Tests failed!

    Total time: 157 minutes 17 seconds
    Publishing Javadoc
    Recording test results
    Recording fingerprints
    Publishing Clover coverage report...
  • Apache Hudson Server at Aug 18, 2009 at 7:03 pm
    See http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/53/changes

    Changes:

    [ddas] MAPREDUCE-773. Sends progress reports for compressed gzip inputs in maps. Fixes a native direct buffer leak in LineRecordReader classes. Contributed by Hong Tang and Devaraj Das.

    ------------------------------------------
    [...truncated 134115 lines...]
    [junit] 2009-08-18 19:01:06,858 INFO mapred.TaskRunner (ReduceTaskRunner.java:close(47)) - attempt_200908181900_0002_r_000000_0 done; removing files.
    [junit] 2009-08-18 19:01:06,899 INFO mapred.JvmManager (JvmManager.java:<init>(396)) - In JvmRunner constructed JVM ID: jvm_200908181900_0002_m_771525167
    [junit] 2009-08-18 19:01:06,900 INFO mapred.JvmManager (JvmManager.java:spawnNewJvm(364)) - JVM Runner jvm_200908181900_0002_m_771525167 spawned.
    [junit] 2009-08-18 19:01:06,927 INFO mapred.JobClient (JobClient.java:monitorAndPrintJob(1364)) - Task Id : attempt_200908181900_0002_r_000000_0, Status : SUCCEEDED
    [junit] attempt_200908181900_0002_r_000000_0: 2009-08-18 19:00:55,628 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Initializing JVM Metrics with processName=SHUFFLE, sessionId=
    [junit] attempt_200908181900_0002_r_000000_0: 2009-08-18 19:00:55,754 INFO mapred.ReduceTask (ReduceTask.java:<init>(1011)) - ShuffleRamManager: MemoryLimit=141387360, MaxSingleShuffleLimit=35346840
    [junit] attempt_200908181900_0002_r_000000_0: 2009-08-18 19:00:55,760 INFO mapred.ReduceTask (ReduceTask.java:run(2485)) - attempt_200908181900_0002_r_000000_0 Thread started: Thread for merging on-disk files
    [junit] attempt_200908181900_0002_r_000000_0: 2009-08-18 19:00:55,760 INFO mapred.ReduceTask (ReduceTask.java:run(2584)) - attempt_200908181900_0002_r_000000_0 Thread started: Thread for merging in memory files
    [junit] attempt_200908181900_0002_r_000000_0: 2009-08-18 19:00:55,761 INFO mapred.ReduceTask (ReduceTask.java:run(2490)) - attempt_200908181900_0002_r_000000_0 Thread waiting: Thread for merging on-disk files
    [junit] attempt_200908181900_0002_r_000000_0: 2009-08-18 19:00:55,762 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(1892)) - attempt_200908181900_0002_r_000000_0 Need another 3 map output(s) where 0 is already in progress
    [junit] attempt_200908181900_0002_r_000000_0: 2009-08-18 19:00:55,762 INFO mapred.ReduceTask (ReduceTask.java:run(2686)) - attempt_200908181900_0002_r_000000_0 Thread started: Thread for polling Map Completion Events
    [junit] attempt_200908181900_0002_r_000000_0: 2009-08-18 19:00:55,763 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2005)) - attempt_200908181900_0002_r_000000_0 Scheduled 0 outputs (0 slow hosts and0 dup hosts)
    [junit] attempt_200908181900_0002_r_000000_0: 2009-08-18 19:00:55,768 INFO mapred.ReduceTask (ReduceTask.java:run(2692)) - attempt_200908181900_0002_r_000000_0: Got 2 new map-outputs
    [junit] attempt_200908181900_0002_r_000000_0: 2009-08-18 19:00:59,773 INFO mapred.ReduceTask (ReduceTask.java:run(2692)) - attempt_200908181900_0002_r_000000_0: Got 1 new map-outputs
    [junit] attempt_200908181900_0002_r_000000_0: 2009-08-18 19:01:00,763 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2005)) - attempt_200908181900_0002_r_000000_0 Scheduled 1 outputs (0 slow hosts and0 dup hosts)
    [junit] attempt_200908181900_0002_r_000000_0: 2009-08-18 19:01:00,796 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1423)) - header: attempt_200908181900_0002_m_000000_0, compressed len: 11, decompressed len: 7
    [junit] attempt_200908181900_0002_r_000000_0: 2009-08-18 19:01:00,796 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1437)) - Shuffling 7 bytes (11 raw bytes) into RAM from attempt_200908181900_0002_m_000000_0
    [junit] attempt_200908181900_0002_r_000000_0: 2009-08-18 19:01:00,801 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1566)) - Read 7 bytes from map-output for attempt_200908181900_0002_m_000000_0
    [junit] attempt_200908181900_0002_r_000000_0: 2009-08-18 19:01:00,801 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1625)) - Rec #1 from attempt_200908181900_0002_m_000000_0 -> (2, 1) from localhost
    [junit] attempt_200908181900_0002_r_000000_0: 2009-08-18 19:01:00,803 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2005)) - attempt_200908181900_0002_r_000000_0 Scheduled 1 outputs (0 slow hosts and0 dup hosts)
    [junit] attempt_200908181900_0002_r_000000_0: 2009-08-18 19:01:00,805 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1423)) - header: attempt_200908181900_0002_m_000001_0, compressed len: 11, decompressed len: 7
    [junit] attempt_200908181900_0002_r_000000_0: 2009-08-18 19:01:00,806 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1437)) - Shuffling 7 bytes (11 raw bytes) into RAM from attempt_200908181900_0002_m_000001_0
    [junit] attempt_200908181900_0002_r_000000_0: 2009-08-18 19:01:00,806 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1566)) - Read 7 bytes from map-output for attempt_200908181900_0002_m_000001_0
    [junit] attempt_200908181900_0002_r_000000_0: 2009-08-18 19:01:00,806 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1625)) - Rec #1 from attempt_200908181900_0002_m_000001_0 -> (2, 1) from localhost
    [junit] attempt_200908181900_0002_r_000000_0: 2009-08-18 19:01:00,806 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2005)) - attempt_200908181900_0002_r_000000_0 Scheduled 1 outputs (0 slow hosts and0 dup hosts)
    [junit] attempt_200908181900_0002_r_000000_0: 2009-08-18 19:01:00,816 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1423)) - header: attempt_200908181900_0002_m_000002_0, compressed len: 11, decompressed len: 7
    [junit] attempt_200908181900_0002_r_000000_0: 2009-08-18 19:01:00,816 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1437)) - Shuffling 7 bytes (11 raw bytes) into RAM from attempt_200908181900_0002_m_000002_0
    [junit] attempt_200908181900_0002_r_000000_0: 2009-08-18 19:01:00,816 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1566)) - Read 7 bytes from map-output for attempt_200908181900_0002_m_000002_0
    [junit] attempt_200908181900_0002_r_000000_0: 2009-08-18 19:01:00,817 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1625)) - Rec #1 from attempt_200908181900_0002_m_000002_0 -> (2, 1) from localhost
    [junit] attempt_200908181900_0002_r_000000_0: 2009-08-18 19:01:01,775 INFO mapred.ReduceTask (ReduceTask.java:run(2710)) - GetMapEventsThread exiting
    [junit] attempt_200908181900_0002_r_000000_0: 2009-08-18 19:01:01,775 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2203)) - getMapsEventsThread joined.
    [junit] attempt_200908181900_0002_r_000000_0: 2009-08-18 19:01:01,775 INFO mapred.ReduceTask (ReduceTask.java:close(1117)) - Closed ram manager
    [junit] attempt_200908181900_0002_r_000000_0: 2009-08-18 19:01:01,776 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2231)) - Interleaved on-disk merge complete: 0 files left.
    [junit] attempt_200908181900_0002_r_000000_0: 2009-08-18 19:01:01,776 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2236)) - In-memory merge complete: 3 files left.
    [junit] attempt_200908181900_0002_r_000000_0: 2009-08-18 19:01:01,831 INFO mapred.Merger (Merger.java:merge(469)) - Merging 3 sorted segments
    [junit] attempt_200908181900_0002_r_000000_0: 2009-08-18 19:01:01,832 INFO mapred.Merger (Merger.java:merge(568)) - Down to the last merge-pass, with 3 segments left of total size: 9 bytes
    [junit] attempt_200908181900_0002_r_000000_0: 2009-08-18 19:01:01,843 INFO mapred.ReduceTask (ReduceTask.java:createKVIterator(2349)) - Merged 3 segments, 21 bytes to disk to satisfy reduce memory limit
    [junit] attempt_200908181900_0002_r_000000_0: 2009-08-18 19:01:01,844 INFO mapred.ReduceTask (ReduceTask.java:createKVIterator(2369)) - Merging 1 files, 21 bytes from disk
    [junit] attempt_200908181900_0002_r_000000_0: 2009-08-18 19:01:01,845 INFO mapred.ReduceTask (ReduceTask.java:createKVIterator(2383)) - Merging 0 segments, 0 bytes from memory into reduce
    [junit] attempt_200908181900_0002_r_000000_0: 2009-08-18 19:01:01,845 INFO mapred.Merger (Merger.java:merge(469)) - Merging 1 sorted segments
    [junit] attempt_200908181900_0002_r_000000_0: 2009-08-18 19:01:01,849 INFO mapred.Merger (Merger.java:merge(568)) - Down to the last merge-pass, with 1 segments left of total size: 13 bytes
    [junit] attempt_200908181900_0002_r_000000_0: 2009-08-18 19:01:02,036 INFO mapred.Task (Task.java:done(643)) - Task:attempt_200908181900_0002_r_000000_0 is done. And is in the process of commiting
    [junit] attempt_200908181900_0002_r_000000_0: 2009-08-18 19:01:04,043 INFO mapred.Task (Task.java:commit(755)) - Task attempt_200908181900_0002_r_000000_0 is allowed to commit now
    [junit] attempt_200908181900_0002_r_000000_0: 2009-08-18 19:01:04,166 INFO mapred.FileOutputCommitter (FileOutputCommitter.java:commitTask(92)) - Saved output of task 'attempt_200908181900_0002_r_000000_0' to hdfs://localhost:42817/user/hudson/mapout
    [junit] attempt_200908181900_0002_r_000000_0: 2009-08-18 19:01:04,168 INFO mapred.Task (Task.java:sendDone(714)) - Task 'attempt_200908181900_0002_r_000000_0' done.
    [junit] 2009-08-18 19:01:07,348 INFO mapred.TaskTracker (TaskTracker.java:getTask(2819)) - JVM with ID: jvm_200908181900_0002_m_771525167 given task: attempt_200908181900_0002_m_000003_0
    [junit] 2009-08-18 19:01:07,706 INFO mapred.TaskTracker (TaskTracker.java:reportProgress(2266)) - attempt_200908181900_0002_m_000003_0 0.0%
    [junit] 2009-08-18 19:01:07,729 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-18 19:01:07,733 INFO mapred.TaskTracker (TaskTracker.java:reportProgress(2266)) - attempt_200908181900_0002_m_000003_0 0.0% cleanup > map
    [junit] 2009-08-18 19:01:07,734 INFO mapred.TaskTracker (TaskTracker.java:reportDone(2347)) - Task attempt_200908181900_0002_m_000003_0 is done.
    [junit] 2009-08-18 19:01:07,735 INFO mapred.TaskTracker (TaskTracker.java:reportDone(2348)) - reported output size for attempt_200908181900_0002_m_000003_0 was 0
    [junit] 2009-08-18 19:01:07,735 INFO mapred.TaskTracker (TaskTracker.java:addFreeSlots(1922)) - addFreeSlot : current free slots : 2
    [junit] 2009-08-18 19:01:07,928 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-18 19:01:07,928 INFO util.ProcessTree (ProcessTree.java:terminateProcessGroup(138)) - Killing all processes in the process group 4651 with SIGTERM. Exit code 1
    [junit] 2009-08-18 19:01:07,934 INFO mapred.JobClient (JobClient.java:monitorAndPrintJob(1315)) - map 100% reduce 100%
    [junit] 2009-08-18 19:01:09,376 INFO mapred.JvmManager (JvmManager.java:runChild(423)) - JVM : jvm_200908181900_0002_r_-1503297314 exited with exit code 0. Number of tasks it ran: 1
    [junit] 2009-08-18 19:01:09,857 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-18 19:01:09,859 INFO mapred.JobInProgress (JobInProgress.java:completedTask(2450)) - Task 'attempt_200908181900_0002_m_000003_0' has completed task_200908181900_0002_m_000003 successfully.
    [junit] 2009-08-18 19:01:09,860 INFO mapred.JobInProgress (JobInProgress.java:jobComplete(2616)) - Job job_200908181900_0002 has completed successfully.
    [junit] 2009-08-18 19:01:09,860 INFO mapred.JobInProgress$JobSummary (JobInProgress.java:logJobSummary(3314)) - jobId=job_200908181900_0002,submitTime=1250622047813,launchTime=1250622047953,finishTime=1250622069860,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-18 19:01:09,864 INFO hdfs.StateChange (FSNamesystem.java:allocateBlock(1286)) - BLOCK* NameSystem.allocateBlock: /user/hudson/mapout/_logs/history/localhost_1250622010536_job_200908181900_0002_hudson_NA. blk_3913060154554562190_1015
    [junit] 2009-08-18 19:01:09,866 INFO datanode.DataNode (DataXceiver.java:writeBlock(240)) - Receiving block blk_3913060154554562190_1015 src: /127.0.0.1:56785 dest: /127.0.0.1:60020
    [junit] 2009-08-18 19:01:09,867 INFO datanode.DataNode (DataXceiver.java:writeBlock(240)) - Receiving block blk_3913060154554562190_1015 src: /127.0.0.1:39852 dest: /127.0.0.1:52052
    [junit] 2009-08-18 19:01:09,870 INFO DataNode.clienttrace (BlockReceiver.java:lastDataNodeRun(807)) - src: /127.0.0.1:39852, dest: /127.0.0.1:52052, bytes: 11831, op: HDFS_WRITE, cliID: DFSClient_-1843875954, offset: 0, srvID: DS-1771694789-67.195.138.9-52052-1250622010406, blockid: blk_3913060154554562190_1015, duration: 1712137
    [junit] 2009-08-18 19:01:09,870 INFO datanode.DataNode (BlockReceiver.java:lastDataNodeRun(831)) - PacketResponder 0 for block blk_3913060154554562190_1015 terminating
    [junit] 2009-08-18 19:01:09,870 INFO hdfs.StateChange (BlockManager.java:addStoredBlock(955)) - BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:52052 is added to blk_3913060154554562190_1015 size 11831
    [junit] 2009-08-18 19:01:09,871 INFO DataNode.clienttrace (BlockReceiver.java:run(933)) - src: /127.0.0.1:56785, dest: /127.0.0.1:60020, bytes: 11831, op: HDFS_WRITE, cliID: DFSClient_-1843875954, offset: 0, srvID: DS-984024283-67.195.138.9-60020-1250622009769, blockid: blk_3913060154554562190_1015, duration: 2365278
    [junit] 2009-08-18 19:01:09,871 INFO datanode.DataNode (BlockReceiver.java:run(997)) - PacketResponder 1 for block blk_3913060154554562190_1015 terminating
    [junit] 2009-08-18 19:01:09,872 INFO hdfs.StateChange (BlockManager.java:addStoredBlock(955)) - BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:60020 is added to blk_3913060154554562190_1015 size 11831
    [junit] 2009-08-18 19:01:09,873 INFO hdfs.StateChange (FSNamesystem.java:completeFileInternal(1252)) - DIR* NameSystem.completeFile: file /user/hudson/mapout/_logs/history/localhost_1250622010536_job_200908181900_0002_hudson_NA is closed by DFSClient_-1843875954
    [junit] 2009-08-18 19:01:09,873 INFO namenode.FSNamesystem (FSEditLog.java:printStatistics(876)) - Number of transactions: 87 Total time for transactions(ms): 8Number of transactions batched in Syncs: 5 Number of syncs: 61 SyncTimes(ms): 791 446
    [junit] 2009-08-18 19:01:09,916 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_1250622010536_job_200908181900_0002_hudson_NA to http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/logs/history/done
    [junit] 2009-08-18 19:01:09,917 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2371)) - Removed completed task 'attempt_200908181900_0002_m_000000_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:43536'
    [junit] 2009-08-18 19:01:09,917 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2371)) - Removed completed task 'attempt_200908181900_0002_m_000001_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:43536'
    [junit] 2009-08-18 19:01:09,917 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2371)) - Removed completed task 'attempt_200908181900_0002_m_000003_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:43536'
    [junit] 2009-08-18 19:01:09,918 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2371)) - Removed completed task 'attempt_200908181900_0002_m_000004_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:43536'
    [junit] 2009-08-18 19:01:09,918 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2371)) - Removed completed task 'attempt_200908181900_0002_r_000000_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:43536'
    [junit] 2009-08-18 19:01:09,918 INFO mapred.TaskTracker (TaskTracker.java:purgeJob(1671)) - Received 'KillJobAction' for job: job_200908181900_0002
    [junit] 2009-08-18 19:01:09,919 INFO hdfs.StateChange (BlockManager.java:addToInvalidates(365)) - BLOCK* NameSystem.addToInvalidates: blk_-3628272542403634773 is added to invalidSet of 127.0.0.1:60020
    [junit] 2009-08-18 19:01:09,919 INFO mapred.TaskRunner (MapTaskRunner.java:close(43)) - attempt_200908181900_0002_m_000001_0 done; removing files.
    [junit] 2009-08-18 19:01:09,919 INFO hdfs.StateChange (BlockManager.java:addToInvalidates(365)) - BLOCK* NameSystem.addToInvalidates: blk_-3628272542403634773 is added to invalidSet of 127.0.0.1:52052
    [junit] 2009-08-18 19:01:09,919 INFO hdfs.StateChange (BlockManager.java:addToInvalidates(365)) - BLOCK* NameSystem.addToInvalidates: blk_2427446272816381655 is added to invalidSet of 127.0.0.1:60020
    [junit] 2009-08-18 19:01:09,919 INFO hdfs.StateChange (BlockManager.java:addToInvalidates(365)) - BLOCK* NameSystem.addToInvalidates: blk_2427446272816381655 is added to invalidSet of 127.0.0.1:52052
    [junit] 2009-08-18 19:01:09,920 INFO mapred.TaskRunner (MapTaskRunner.java:close(43)) - attempt_200908181900_0002_m_000000_0 done; removing files.
    [junit] 2009-08-18 19:01:09,920 INFO mapred.TaskRunner (MapTaskRunner.java:close(43)) - attempt_200908181900_0002_m_000003_0 done; removing files.
    [junit] 2009-08-18 19:01:09,921 INFO mapred.IndexCache (IndexCache.java:removeMap(140)) - Map ID attempt_200908181900_0002_m_000003_0 not found in cache
    [junit] 2009-08-18 19:01:09,935 INFO FSNamesystem.audit (FSNamesystem.java:logAuditEvent(114)) - ugi=hudson,hudson ip=/127.0.0.1 cmd=delete src=/tmp/hadoop-hudson/mapred/system/job_200908181900_0002 dst=null perm=null
    [junit] 2009-08-18 19:01:09,939 INFO mapred.JobClient (JobClient.java:monitorAndPrintJob(1364)) - Task Id : attempt_200908181900_0002_m_000003_0, Status : SUCCEEDED
    [junit] attempt_200908181900_0002_m_000003_0: 2009-08-18 19:01:07,588 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Initializing JVM Metrics with processName=MAP, sessionId=
    [junit] attempt_200908181900_0002_m_000003_0: 2009-08-18 19:01:07,730 INFO mapred.Task (Task.java:done(643)) - Task:attempt_200908181900_0002_m_000003_0 is done. And is in the process of commiting
    [junit] attempt_200908181900_0002_m_000003_0: 2009-08-18 19:01:07,736 INFO mapred.Task (Task.java:sendDone(714)) - Task 'attempt_200908181900_0002_m_000003_0' done.
    [junit] 2009-08-18 19:01:09,942 INFO mapred.JobClient (JobClient.java:monitorAndPrintJob(1370)) - Job complete: job_200908181900_0002
    [junit] 2009-08-18 19:01:09,954 INFO mapred.JobClient (Counters.java:log(534)) - Counters: 22
    [junit] 2009-08-18 19:01:09,954 INFO mapred.JobClient (Counters.java:log(536)) - Job Counters
    [junit] 2009-08-18 19:01:09,954 INFO mapred.JobClient (Counters.java:log(538)) - Launched reduce tasks=1
    [junit] 2009-08-18 19:01:09,954 INFO mapred.JobClient (Counters.java:log(538)) - SLOTS_MILLIS_MAPS=5554
    [junit] 2009-08-18 19:01:09,955 INFO mapred.JobClient (Counters.java:log(538)) - Total time spent by all reduces waiting after reserving slots (ms)=0
    [junit] 2009-08-18 19:01:09,955 INFO mapred.JobClient (Counters.java:log(538)) - Total time spent by all maps waiting after reserving slots (ms)=0
    [junit] 2009-08-18 19:01:09,955 INFO mapred.JobClient (Counters.java:log(538)) - Rack-local map tasks=3
    [junit] 2009-08-18 19:01:09,955 INFO mapred.JobClient (Counters.java:log(538)) - Launched map tasks=3
    [junit] 2009-08-18 19:01:09,955 INFO mapred.JobClient (Counters.java:log(538)) - SLOTS_MILLIS_REDUCES=9298
    [junit] 2009-08-18 19:01:09,955 INFO mapred.JobClient (Counters.java:log(536)) - FileInputFormatCounters
    [junit] 2009-08-18 19:01:09,956 INFO mapred.JobClient (Counters.java:log(538)) - BYTES_READ=3
    [junit] 2009-08-18 19:01:09,956 INFO mapred.JobClient (Counters.java:log(536)) - FileSystemCounters
    [junit] 2009-08-18 19:01:09,956 INFO mapred.JobClient (Counters.java:log(538)) - FILE_BYTES_READ=21
    [junit] 2009-08-18 19:01:09,956 INFO mapred.JobClient (Counters.java:log(538)) - HDFS_BYTES_READ=828
    [junit] 2009-08-18 19:01:09,956 INFO mapred.JobClient (Counters.java:log(538)) - FILE_BYTES_WRITTEN=150
    [junit] 2009-08-18 19:01:09,956 INFO mapred.JobClient (Counters.java:log(538)) - HDFS_BYTES_WRITTEN=6
    [junit] 2009-08-18 19:01:09,956 INFO mapred.JobClient (Counters.java:log(536)) - Map-Reduce Framework
    [junit] 2009-08-18 19:01:09,957 INFO mapred.JobClient (Counters.java:log(538)) - Reduce input groups=3
    [junit] 2009-08-18 19:01:09,957 INFO mapred.JobClient (Counters.java:log(538)) - Combine output records=0
    [junit] 2009-08-18 19:01:09,958 INFO mapred.JobClient (Counters.java:log(538)) - Map input records=3
    [junit] 2009-08-18 19:01:09,958 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_1250622010536_job_200908181900_0002_conf.xml to http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/logs/history/done
    [junit] 2009-08-18 19:01:09,958 INFO mapred.JobClient (Counters.java:log(538)) - Reduce shuffle bytes=22
    [junit] 2009-08-18 19:01:09,958 INFO mapred.JobClient (Counters.java:log(538)) - Reduce output records=3
    [junit] 2009-08-18 19:01:09,958 INFO mapred.JobClient (Counters.java:log(538)) - Spilled Records=6
    [junit] 2009-08-18 19:01:09,959 INFO mapred.JobClient (Counters.java:log(538)) - Map output bytes=9
    [junit] 2009-08-18 19:01:09,959 INFO mapred.JobClient (Counters.java:log(538)) - Combine input records=0
    [junit] 2009-08-18 19:01:09,959 INFO mapred.JobClient (Counters.java:log(538)) - Map output records=3
    [junit] 2009-08-18 19:01:09,959 INFO mapred.JobClient (Counters.java:log(538)) - Reduce input records=3
    [junit] 2009-08-18 19:01:09,972 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-18 19:00 /user/hudson/mapout/_logs
    [junit] -rw-r--r-- 3 hudson supergroup 6 2009-08-18 19:01 /user/hudson/mapout/part-00000
    [junit] 2009-08-18 19:01:09,975 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-18 19:01:09,976 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-18 19:01:09,978 INFO DataNode.clienttrace (BlockSender.java:sendBlock(417)) - src: /127.0.0.1:60020, dest: /127.0.0.1:56787, bytes: 10, op: HDFS_READ, cliID: DFSClient_-1843875954, offset: 0, srvID: DS-984024283-67.195.138.9-60020-1250622009769, blockid: blk_-6070558906685459028_1015, duration: 345851
    [junit] 2009-08-18 19:01:09,979 INFO mapred.MiniMRCluster (MiniMRCluster.java:waitTaskTrackers(306)) - Waiting for task tracker tracker_host0.foo.com:localhost/127.0.0.1:38124 to be idle.
    [junit] 2009-08-18 19:01:10,684 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2371)) - Removed completed task 'attempt_200908181900_0002_m_000002_0' from 'tracker_host0.foo.com:localhost/127.0.0.1:38124'
    [junit] 2009-08-18 19:01:10,685 INFO mapred.TaskTracker (TaskTracker.java:purgeJob(1671)) - Received 'KillJobAction' for job: job_200908181900_0002
    [junit] 2009-08-18 19:01:10,685 INFO mapred.TaskRunner (MapTaskRunner.java:close(43)) - attempt_200908181900_0002_m_000002_0 done; removing files.
    [junit] 2009-08-18 19:01:10,980 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:38124
    [junit] 2009-08-18 19:01:10,981 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 38124
    [junit] 2009-08-18 19:01:10,981 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 38124: exiting
    [junit] 2009-08-18 19:01:10,982 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 38124
    [junit] 2009-08-18 19:01:10,982 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
    [junit] 2009-08-18 19:01:10,982 INFO mapred.TaskTracker (TaskTracker.java:shutdown(1149)) - Shutting down StatusHttpServer
    [junit] 2009-08-18 19:01:10,982 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 38124: exiting
    [junit] 2009-08-18 19:01:10,982 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 3 on 38124: exiting
    [junit] 2009-08-18 19:01:10,982 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 38124: exiting
    [junit] 2009-08-18 19:01:11,085 INFO mapred.TaskTracker (TaskTracker.java:offerService(1439)) - Interrupted. Closing down.
    [junit] 2009-08-18 19:01:11,086 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:43536
    [junit] 2009-08-18 19:01:11,086 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 43536
    [junit] 2009-08-18 19:01:11,087 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 43536: exiting
    [junit] 2009-08-18 19:01:11,087 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 43536: exiting
    [junit] 2009-08-18 19:01:11,087 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 43536
    [junit] 2009-08-18 19:01:11,087 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 43536: exiting
    [junit] 2009-08-18 19:01:11,087 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
    [junit] 2009-08-18 19:01:11,087 INFO mapred.TaskTracker (TaskTracker.java:shutdown(1149)) - Shutting down StatusHttpServer
    [junit] 2009-08-18 19:01:11,087 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 3 on 43536: exiting
    [junit] 2009-08-18 19:01:11,254 INFO mapred.TaskTracker (TaskTracker.java:offerService(1439)) - Interrupted. Closing down.
    [junit] 2009-08-18 19:01:11,255 INFO mapred.JobTracker (JobTracker.java:close(2189)) - Stopping infoServer
    [junit] 2009-08-18 19:01:11,358 INFO mapred.JobTracker (JobTracker.java:close(2197)) - Stopping interTrackerServer
    [junit] 2009-08-18 19:01:11,358 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 53740
    [junit] 2009-08-18 19:01:11,358 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 53740: exiting
    [junit] 2009-08-18 19:01:11,359 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 9 on 53740: exiting
    [junit] 2009-08-18 19:01:11,359 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 3 on 53740: exiting
    [junit] 2009-08-18 19:01:11,359 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 7 on 53740: exiting
    [junit] 2009-08-18 19:01:11,359 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 5 on 53740: exiting
    [junit] 2009-08-18 19:01:11,359 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 4 on 53740: exiting
    [junit] 2009-08-18 19:01:11,359 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 53740
    [junit] 2009-08-18 19:01:11,359 INFO mapred.JobTracker (JobTracker.java:offerService(2184)) - Stopped interTrackerServer
    [junit] 2009-08-18 19:01:11,359 INFO mapred.JobTracker (JobTracker.java:stopExpireTrackersThread(2240)) - Stopping expireTrackers
    [junit] 2009-08-18 19:01:11,359 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
    [junit] 2009-08-18 19:01:11,359 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 8 on 53740: exiting
    [junit] 2009-08-18 19:01:11,359 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 6 on 53740: exiting
    [junit] 2009-08-18 19:01:11,359 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 53740: exiting
    [junit] 2009-08-18 19:01:11,362 INFO mapred.JobTracker (JobTracker.java:close(2204)) - Stopping retirer
    [junit] 2009-08-18 19:01:11,360 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 53740: exiting
    [junit] 2009-08-18 19:01:11,363 INFO mapred.EagerTaskInitializationListener (EagerTaskInitializationListener.java:terminate(106)) - Stopping Job Init Manager thread
    [junit] 2009-08-18 19:01:11,363 INFO mapred.EagerTaskInitializationListener (EagerTaskInitializationListener.java:run(60)) - JobInitManagerThread interrupted.
    [junit] 2009-08-18 19:01:11,363 INFO mapred.EagerTaskInitializationListener (EagerTaskInitializationListener.java:run(64)) - Shutting down thread pool
    [junit] 2009-08-18 19:01:11,363 INFO mapred.JobTracker (JobTracker.java:close(2216)) - Stopping expireLaunchingTasks
    [junit] 2009-08-18 19:01:11,364 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-18 19:01:11,466 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 49232
    [junit] 2009-08-18 19:01:11,467 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 49232: exiting
    [junit] 2009-08-18 19:01:11,467 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 49232: exiting
    [junit] 2009-08-18 19:01:11,467 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 49232: exiting
    [junit] 2009-08-18 19:01:11,468 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
    [junit] 2009-08-18 19:01:11,468 INFO datanode.DataNode (DataNode.java:shutdown(639)) - Waiting for threadgroup to exit, active threads is 1
    [junit] 2009-08-18 19:01:11,468 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 49232
    [junit] 2009-08-18 19:01:11,468 WARN datanode.DataNode (DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:52052, storageID=DS-1771694789-67.195.138.9-52052-1250622010406, infoPort=55018, ipcPort=49232):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-18 19:01:11,470 INFO datanode.DataNode (DataNode.java:shutdown(639)) - Waiting for threadgroup to exit, active threads is 0
    [junit] 2009-08-18 19:01:11,471 INFO datanode.DataBlockScanner (DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
    [junit] 2009-08-18 19:01:11,471 INFO datanode.DataNode (DataNode.java:run(1285)) - DatanodeRegistration(127.0.0.1:52052, storageID=DS-1771694789-67.195.138.9-52052-1250622010406, infoPort=55018, ipcPort=49232):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-18 19:01:11,471 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 49232
    [junit] 2009-08-18 19:01:11,471 INFO datanode.DataNode (DataNode.java:shutdown(639)) - Waiting for threadgroup to exit, active threads is 0
    [junit] Shutting down DataNode 0
    [junit] 2009-08-18 19:01:11,574 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 54321
    [junit] 2009-08-18 19:01:11,574 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 54321: exiting
    [junit] 2009-08-18 19:01:11,575 WARN datanode.DataNode (DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:60020, storageID=DS-984024283-67.195.138.9-60020-1250622009769, infoPort=53279, ipcPort=54321):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-18 19:01:11,575 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 54321: exiting
    [junit] 2009-08-18 19:01:11,574 INFO datanode.DataNode (DataNode.java:shutdown(639)) - Waiting for threadgroup to exit, active threads is 1
    [junit] 2009-08-18 19:01:11,574 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
    [junit] 2009-08-18 19:01:11,574 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 54321
    [junit] 2009-08-18 19:01:11,576 INFO datanode.DataBlockScanner (DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
    [junit] 2009-08-18 19:01:11,575 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 54321: exiting
    [junit] 2009-08-18 19:01:11,577 INFO datanode.DataNode (DataNode.java:run(1285)) - DatanodeRegistration(127.0.0.1:60020, storageID=DS-984024283-67.195.138.9-60020-1250622009769, infoPort=53279, ipcPort=54321):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-18 19:01:11,577 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 54321
    [junit] 2009-08-18 19:01:11,577 INFO datanode.DataNode (DataNode.java:shutdown(639)) - Waiting for threadgroup to exit, active threads is 0
    [junit] 2009-08-18 19:01:11,685 WARN namenode.FSNamesystem (FSNamesystem.java:run(2057)) - ReplicationMonitor thread received InterruptedException.java.lang.InterruptedException: sleep interrupted
    [junit] 2009-08-18 19:01:11,686 WARN namenode.DecommissionManager (DecommissionManager.java:run(67)) - Monitor interrupted: java.lang.InterruptedException: sleep interrupted
    [junit] 2009-08-18 19:01:11,686 INFO namenode.FSNamesystem (FSEditLog.java:printStatistics(876)) - Number of transactions: 88 Total time for transactions(ms): 8Number of transactions batched in Syncs: 5 Number of syncs: 63 SyncTimes(ms): 836 458
    [junit] 2009-08-18 19:01:11,699 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 42817
    [junit] 2009-08-18 19:01:11,699 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 3 on 42817: exiting
    [junit] 2009-08-18 19:01:11,699 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 5 on 42817: exiting
    [junit] 2009-08-18 19:01:11,699 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 42817
    [junit] 2009-08-18 19:01:11,699 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 4 on 42817: exiting
    [junit] 2009-08-18 19:01:11,700 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 6 on 42817: exiting
    [junit] 2009-08-18 19:01:11,700 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 42817: exiting
    [junit] 2009-08-18 19:01:11,700 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 42817: exiting
    [junit] 2009-08-18 19:01:11,700 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 8 on 42817: exiting
    [junit] 2009-08-18 19:01:11,700 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
    [junit] 2009-08-18 19:01:11,700 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 7 on 42817: exiting
    [junit] 2009-08-18 19:01:11,700 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 42817: exiting
    [junit] 2009-08-18 19:01:11,700 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 9 on 42817: exiting
    [junit] Tests run: 2, Failures: 0, Errors: 0, Time elapsed: 103.877 sec
    [junit] Running org.apache.hadoop.util.TestReflectionUtils
    [junit] Tests run: 5, Failures: 0, Errors: 0, Time elapsed: 0.566 sec
    [junit] Running org.apache.hadoop.util.TestRunJar
    [junit] Creating filehttp://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/data/out
    [junit] Tests run: 1, Failures: 0, Errors: 0, Time elapsed: 0.167 sec

    checkfailure:
    [touch] Creating http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/testsfailed

    BUILD FAILED
    http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build.xml :627: Tests failed!

    Total time: 155 minutes 16 seconds
    Publishing Javadoc
    Recording test results
    Recording fingerprints
    Publishing Clover coverage report...
  • Apache Hudson Server at Aug 19, 2009 at 7:58 pm
    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:<init>(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:<init>(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...
  • Apache Hudson Server at Aug 20, 2009 at 6:00 pm
    See http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/55/changes

    Changes:

    [ddas] MAPREDUCE-745. Fixes a testcase problem to do with generation of JobTracker IDs. Contributed by Amar Kamat.

    [yhemanth] MAPREDUCE-832. Reduce number of warning messages printed when deprecated memory variables are used. Contributed by Rahul Kumar Singh.

    ------------------------------------------
    [...truncated 133935 lines...]
    [junit] 2009-08-20 17:58:23,345 INFO mapred.JvmManager (JvmManager.java:<init>(396)) - In JvmRunner constructed JVM ID: jvm_20090820175726994_0002_m_339455816
    [junit] 2009-08-20 17:58:23,346 INFO mapred.JvmManager (JvmManager.java:spawnNewJvm(364)) - JVM Runner jvm_20090820175726994_0002_m_339455816 spawned.
    [junit] 2009-08-20 17:58:23,431 INFO mapred.JobClient (JobClient.java:monitorAndPrintJob(1364)) - Task Id : attempt_20090820175726994_0002_r_000000_0, Status : SUCCEEDED
    [junit] attempt_20090820175726994_0002_r_000000_0: 2009-08-20 17:58:12,082 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Initializing JVM Metrics with processName=SHUFFLE, sessionId=
    [junit] attempt_20090820175726994_0002_r_000000_0: 2009-08-20 17:58:12,209 INFO mapred.ReduceTask (ReduceTask.java:<init>(1011)) - ShuffleRamManager: MemoryLimit=141387360, MaxSingleShuffleLimit=35346840
    [junit] attempt_20090820175726994_0002_r_000000_0: 2009-08-20 17:58:12,215 INFO mapred.ReduceTask (ReduceTask.java:run(2485)) - attempt_20090820175726994_0002_r_000000_0 Thread started: Thread for merging on-disk files
    [junit] attempt_20090820175726994_0002_r_000000_0: 2009-08-20 17:58:12,215 INFO mapred.ReduceTask (ReduceTask.java:run(2584)) - attempt_20090820175726994_0002_r_000000_0 Thread started: Thread for merging in memory files
    [junit] attempt_20090820175726994_0002_r_000000_0: 2009-08-20 17:58:12,216 INFO mapred.ReduceTask (ReduceTask.java:run(2490)) - attempt_20090820175726994_0002_r_000000_0 Thread waiting: Thread for merging on-disk files
    [junit] attempt_20090820175726994_0002_r_000000_0: 2009-08-20 17:58:12,224 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(1892)) - attempt_20090820175726994_0002_r_000000_0 Need another 3 map output(s) where 0 is already in progress
    [junit] attempt_20090820175726994_0002_r_000000_0: 2009-08-20 17:58:12,224 INFO mapred.ReduceTask (ReduceTask.java:run(2686)) - attempt_20090820175726994_0002_r_000000_0 Thread started: Thread for polling Map Completion Events
    [junit] attempt_20090820175726994_0002_r_000000_0: 2009-08-20 17:58:12,224 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2005)) - attempt_20090820175726994_0002_r_000000_0 Scheduled 0 outputs (0 slow hosts and0 dup hosts)
    [junit] attempt_20090820175726994_0002_r_000000_0: 2009-08-20 17:58:12,229 INFO mapred.ReduceTask (ReduceTask.java:run(2692)) - attempt_20090820175726994_0002_r_000000_0: Got 2 new map-outputs
    [junit] attempt_20090820175726994_0002_r_000000_0: 2009-08-20 17:58:16,234 INFO mapred.ReduceTask (ReduceTask.java:run(2692)) - attempt_20090820175726994_0002_r_000000_0: Got 1 new map-outputs
    [junit] attempt_20090820175726994_0002_r_000000_0: 2009-08-20 17:58:17,225 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2005)) - attempt_20090820175726994_0002_r_000000_0 Scheduled 1 outputs (0 slow hosts and0 dup hosts)
    [junit] attempt_20090820175726994_0002_r_000000_0: 2009-08-20 17:58:17,257 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1423)) - header: attempt_20090820175726994_0002_m_000000_0, compressed len: 11, decompressed len: 7
    [junit] attempt_20090820175726994_0002_r_000000_0: 2009-08-20 17:58:17,257 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1437)) - Shuffling 7 bytes (11 raw bytes) into RAM from attempt_20090820175726994_0002_m_000000_0
    [junit] attempt_20090820175726994_0002_r_000000_0: 2009-08-20 17:58:17,269 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1566)) - Read 7 bytes from map-output for attempt_20090820175726994_0002_m_000000_0
    [junit] attempt_20090820175726994_0002_r_000000_0: 2009-08-20 17:58:17,269 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1625)) - Rec #1 from attempt_20090820175726994_0002_m_000000_0 -> (2, 1) from localhost
    [junit] attempt_20090820175726994_0002_r_000000_0: 2009-08-20 17:58:17,271 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2005)) - attempt_20090820175726994_0002_r_000000_0 Scheduled 1 outputs (0 slow hosts and0 dup hosts)
    [junit] attempt_20090820175726994_0002_r_000000_0: 2009-08-20 17:58:17,273 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1423)) - header: attempt_20090820175726994_0002_m_000001_0, compressed len: 11, decompressed len: 7
    [junit] attempt_20090820175726994_0002_r_000000_0: 2009-08-20 17:58:17,273 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1437)) - Shuffling 7 bytes (11 raw bytes) into RAM from attempt_20090820175726994_0002_m_000001_0
    [junit] attempt_20090820175726994_0002_r_000000_0: 2009-08-20 17:58:17,274 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1566)) - Read 7 bytes from map-output for attempt_20090820175726994_0002_m_000001_0
    [junit] attempt_20090820175726994_0002_r_000000_0: 2009-08-20 17:58:17,274 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1625)) - Rec #1 from attempt_20090820175726994_0002_m_000001_0 -> (2, 1) from localhost
    [junit] attempt_20090820175726994_0002_r_000000_0: 2009-08-20 17:58:17,275 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2005)) - attempt_20090820175726994_0002_r_000000_0 Scheduled 1 outputs (0 slow hosts and0 dup hosts)
    [junit] attempt_20090820175726994_0002_r_000000_0: 2009-08-20 17:58:17,301 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1423)) - header: attempt_20090820175726994_0002_m_000002_0, compressed len: 11, decompressed len: 7
    [junit] attempt_20090820175726994_0002_r_000000_0: 2009-08-20 17:58:17,301 INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1437)) - Shuffling 7 bytes (11 raw bytes) into RAM from attempt_20090820175726994_0002_m_000002_0
    [junit] attempt_20090820175726994_0002_r_000000_0: 2009-08-20 17:58:17,301 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1566)) - Read 7 bytes from map-output for attempt_20090820175726994_0002_m_000002_0
    [junit] attempt_20090820175726994_0002_r_000000_0: 2009-08-20 17:58:17,301 INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1625)) - Rec #1 from attempt_20090820175726994_0002_m_000002_0 -> (2, 1) from localhost
    [junit] attempt_20090820175726994_0002_r_000000_0: 2009-08-20 17:58:18,236 INFO mapred.ReduceTask (ReduceTask.java:run(2710)) - GetMapEventsThread exiting
    [junit] attempt_20090820175726994_0002_r_000000_0: 2009-08-20 17:58:18,236 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2203)) - getMapsEventsThread joined.
    [junit] attempt_20090820175726994_0002_r_000000_0: 2009-08-20 17:58:18,236 INFO mapred.ReduceTask (ReduceTask.java:close(1117)) - Closed ram manager
    [junit] attempt_20090820175726994_0002_r_000000_0: 2009-08-20 17:58:18,236 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2231)) - Interleaved on-disk merge complete: 0 files left.
    [junit] attempt_20090820175726994_0002_r_000000_0: 2009-08-20 17:58:18,237 INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2236)) - In-memory merge complete: 3 files left.
    [junit] attempt_20090820175726994_0002_r_000000_0: 2009-08-20 17:58:18,259 INFO mapred.Merger (Merger.java:merge(469)) - Merging 3 sorted segments
    [junit] attempt_20090820175726994_0002_r_000000_0: 2009-08-20 17:58:18,260 INFO mapred.Merger (Merger.java:merge(568)) - Down to the last merge-pass, with 3 segments left of total size: 9 bytes
    [junit] attempt_20090820175726994_0002_r_000000_0: 2009-08-20 17:58:18,271 INFO mapred.ReduceTask (ReduceTask.java:createKVIterator(2349)) - Merged 3 segments, 21 bytes to disk to satisfy reduce memory limit
    [junit] attempt_20090820175726994_0002_r_000000_0: 2009-08-20 17:58:18,271 INFO mapred.ReduceTask (ReduceTask.java:createKVIterator(2369)) - Merging 1 files, 21 bytes from disk
    [junit] attempt_20090820175726994_0002_r_000000_0: 2009-08-20 17:58:18,272 INFO mapred.ReduceTask (ReduceTask.java:createKVIterator(2383)) - Merging 0 segments, 0 bytes from memory into reduce
    [junit] attempt_20090820175726994_0002_r_000000_0: 2009-08-20 17:58:18,272 INFO mapred.Merger (Merger.java:merge(469)) - Merging 1 sorted segments
    [junit] attempt_20090820175726994_0002_r_000000_0: 2009-08-20 17:58:18,276 INFO mapred.Merger (Merger.java:merge(568)) - Down to the last merge-pass, with 1 segments left of total size: 13 bytes
    [junit] attempt_20090820175726994_0002_r_000000_0: 2009-08-20 17:58:18,453 INFO mapred.Task (Task.java:done(643)) - Task:attempt_20090820175726994_0002_r_000000_0 is done. And is in the process of commiting
    [junit] attempt_20090820175726994_0002_r_000000_0: 2009-08-20 17:58:20,461 INFO mapred.Task (Task.java:commit(755)) - Task attempt_20090820175726994_0002_r_000000_0 is allowed to commit now
    [junit] attempt_20090820175726994_0002_r_000000_0: 2009-08-20 17:58:20,498 INFO mapred.FileOutputCommitter (FileOutputCommitter.java:commitTask(92)) - Saved output of task 'attempt_20090820175726994_0002_r_000000_0' to hdfs://localhost:47008/user/hudson/mapout
    [junit] attempt_20090820175726994_0002_r_000000_0: 2009-08-20 17:58:20,501 INFO mapred.Task (Task.java:sendDone(714)) - Task 'attempt_20090820175726994_0002_r_000000_0' done.
    [junit] 2009-08-20 17:58:23,777 INFO mapred.TaskTracker (TaskTracker.java:getTask(2819)) - JVM with ID: jvm_20090820175726994_0002_m_339455816 given task: attempt_20090820175726994_0002_m_000003_0
    [junit] 2009-08-20 17:58:24,142 INFO mapred.TaskTracker (TaskTracker.java:reportProgress(2266)) - attempt_20090820175726994_0002_m_000003_0 0.0%
    [junit] 2009-08-20 17:58:24,159 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-20 17:58:24,163 INFO mapred.TaskTracker (TaskTracker.java:reportProgress(2266)) - attempt_20090820175726994_0002_m_000003_0 0.0% cleanup > map
    [junit] 2009-08-20 17:58:24,164 INFO mapred.TaskTracker (TaskTracker.java:reportDone(2347)) - Task attempt_20090820175726994_0002_m_000003_0 is done.
    [junit] 2009-08-20 17:58:24,164 INFO mapred.TaskTracker (TaskTracker.java:reportDone(2348)) - reported output size for attempt_20090820175726994_0002_m_000003_0 was 0
    [junit] 2009-08-20 17:58:24,165 INFO mapred.TaskTracker (TaskTracker.java:addFreeSlots(1922)) - addFreeSlot : current free slots : 2
    [junit] 2009-08-20 17:58:24,367 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-20 17:58:24,367 INFO util.ProcessTree (ProcessTree.java:terminateProcessGroup(138)) - Killing all processes in the process group 23341 with SIGTERM. Exit code 1
    [junit] 2009-08-20 17:58:24,440 INFO mapred.JobClient (JobClient.java:monitorAndPrintJob(1315)) - map 100% reduce 100%
    [junit] 2009-08-20 17:58:25,736 INFO mapred.JvmManager (JvmManager.java:runChild(423)) - JVM : jvm_20090820175726994_0002_r_-1405924571 exited with exit code 0. Number of tasks it ran: 1
    [junit] 2009-08-20 17:58:26,297 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-20 17:58:26,299 INFO mapred.JobInProgress (JobInProgress.java:completedTask(2450)) - Task 'attempt_20090820175726994_0002_m_000003_0' has completed task_20090820175726994_0002_m_000003 successfully.
    [junit] 2009-08-20 17:58:26,299 INFO mapred.JobInProgress (JobInProgress.java:jobComplete(2616)) - Job job_20090820175726994_0002 has completed successfully.
    [junit] 2009-08-20 17:58:26,300 INFO mapred.JobInProgress$JobSummary (JobInProgress.java:logJobSummary(3314)) - jobId=job_20090820175726994_0002,submitTime=1250791084230,launchTime=1250791084363,finishTime=1250791106299,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-20 17:58:26,303 INFO hdfs.StateChange (FSNamesystem.java:allocateBlock(1286)) - BLOCK* NameSystem.allocateBlock: /user/hudson/mapout/_logs/history/localhost_1250791047023_job_20090820175726994_0002_hudson_NA. blk_776147266288829217_1015
    [junit] 2009-08-20 17:58:26,304 INFO datanode.DataNode (DataXceiver.java:writeBlock(240)) - Receiving block blk_776147266288829217_1015 src: /127.0.0.1:41715 dest: /127.0.0.1:54693
    [junit] 2009-08-20 17:58:26,305 INFO datanode.DataNode (DataXceiver.java:writeBlock(240)) - Receiving block blk_776147266288829217_1015 src: /127.0.0.1:47018 dest: /127.0.0.1:35532
    [junit] 2009-08-20 17:58:26,343 INFO DataNode.clienttrace (BlockReceiver.java:lastDataNodeRun(807)) - src: /127.0.0.1:47018, dest: /127.0.0.1:35532, bytes: 12041, op: HDFS_WRITE, cliID: DFSClient_816151018, offset: 0, srvID: DS-1285960160-67.195.138.9-35532-1250791046322, blockid: blk_776147266288829217_1015, duration: 35112844
    [junit] 2009-08-20 17:58:26,343 INFO hdfs.StateChange (BlockManager.java:addStoredBlock(955)) - BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:35532 is added to blk_776147266288829217_1015 size 12041
    [junit] 2009-08-20 17:58:26,344 INFO datanode.DataNode (BlockReceiver.java:lastDataNodeRun(831)) - PacketResponder 0 for block blk_776147266288829217_1015 terminating
    [junit] 2009-08-20 17:58:26,344 INFO DataNode.clienttrace (BlockReceiver.java:run(933)) - src: /127.0.0.1:41715, dest: /127.0.0.1:54693, bytes: 12041, op: HDFS_WRITE, cliID: DFSClient_816151018, offset: 0, srvID: DS-1386870724-67.195.138.9-54693-1250791046898, blockid: blk_776147266288829217_1015, duration: 37356103
    [junit] 2009-08-20 17:58:26,344 INFO hdfs.StateChange (BlockManager.java:addStoredBlock(955)) - BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:54693 is added to blk_776147266288829217_1015 size 12041
    [junit] 2009-08-20 17:58:26,345 INFO datanode.DataNode (BlockReceiver.java:run(997)) - PacketResponder 1 for block blk_776147266288829217_1015 terminating
    [junit] 2009-08-20 17:58:26,347 INFO hdfs.StateChange (FSNamesystem.java:completeFileInternal(1252)) - DIR* NameSystem.completeFile: file /user/hudson/mapout/_logs/history/localhost_1250791047023_job_20090820175726994_0002_hudson_NA is closed by DFSClient_816151018
    [junit] 2009-08-20 17:58:26,347 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): 569 625
    [junit] 2009-08-20 17:58:26,368 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_1250791047023_job_20090820175726994_0002_hudson_NA to http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/logs/history/done
    [junit] 2009-08-20 17:58:26,369 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2395)) - Removed completed task 'attempt_20090820175726994_0002_m_000000_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:51073'
    [junit] 2009-08-20 17:58:26,369 INFO hdfs.StateChange (BlockManager.java:addToInvalidates(365)) - BLOCK* NameSystem.addToInvalidates: blk_7518539613064358863 is added to invalidSet of 127.0.0.1:35532
    [junit] 2009-08-20 17:58:26,369 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2395)) - Removed completed task 'attempt_20090820175726994_0002_m_000001_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:51073'
    [junit] 2009-08-20 17:58:26,369 INFO hdfs.StateChange (BlockManager.java:addToInvalidates(365)) - BLOCK* NameSystem.addToInvalidates: blk_7518539613064358863 is added to invalidSet of 127.0.0.1:54693
    [junit] 2009-08-20 17:58:26,370 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2395)) - Removed completed task 'attempt_20090820175726994_0002_m_000003_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:51073'
    [junit] 2009-08-20 17:58:26,370 INFO hdfs.StateChange (BlockManager.java:addToInvalidates(365)) - BLOCK* NameSystem.addToInvalidates: blk_5039812009579323969 is added to invalidSet of 127.0.0.1:54693
    [junit] 2009-08-20 17:58:26,370 INFO hdfs.StateChange (BlockManager.java:addToInvalidates(365)) - BLOCK* NameSystem.addToInvalidates: blk_5039812009579323969 is added to invalidSet of 127.0.0.1:35532
    [junit] 2009-08-20 17:58:26,370 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2395)) - Removed completed task 'attempt_20090820175726994_0002_m_000004_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:51073'
    [junit] 2009-08-20 17:58:26,371 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2395)) - Removed completed task 'attempt_20090820175726994_0002_r_000000_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:51073'
    [junit] 2009-08-20 17:58:26,378 INFO mapred.TaskTracker (TaskTracker.java:purgeJob(1671)) - Received 'KillJobAction' for job: job_20090820175726994_0002
    [junit] 2009-08-20 17:58:26,379 INFO mapred.TaskRunner (MapTaskRunner.java:close(43)) - attempt_20090820175726994_0002_m_000001_0 done; removing files.
    [junit] 2009-08-20 17:58:26,380 INFO mapred.TaskRunner (MapTaskRunner.java:close(43)) - attempt_20090820175726994_0002_m_000000_0 done; removing files.
    [junit] 2009-08-20 17:58:26,380 INFO mapred.TaskRunner (MapTaskRunner.java:close(43)) - attempt_20090820175726994_0002_m_000003_0 done; removing files.
    [junit] 2009-08-20 17:58:26,381 INFO mapred.IndexCache (IndexCache.java:removeMap(140)) - Map ID attempt_20090820175726994_0002_m_000003_0 not found in cache
    [junit] 2009-08-20 17:58:26,394 INFO FSNamesystem.audit (FSNamesystem.java:logAuditEvent(114)) - ugi=hudson,hudson ip=/127.0.0.1 cmd=delete src=/tmp/hadoop-hudson/mapred/system/job_20090820175726994_0002 dst=null perm=null
    [junit] 2009-08-20 17:58:26,401 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_1250791047023_job_20090820175726994_0002_conf.xml to http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/logs/history/done
    [junit] 2009-08-20 17:58:26,456 INFO mapred.JobClient (JobClient.java:monitorAndPrintJob(1364)) - Task Id : attempt_20090820175726994_0002_m_000003_0, Status : SUCCEEDED
    [junit] attempt_20090820175726994_0002_m_000003_0: 2009-08-20 17:58:24,023 INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Initializing JVM Metrics with processName=MAP, sessionId=
    [junit] attempt_20090820175726994_0002_m_000003_0: 2009-08-20 17:58:24,160 INFO mapred.Task (Task.java:done(643)) - Task:attempt_20090820175726994_0002_m_000003_0 is done. And is in the process of commiting
    [junit] attempt_20090820175726994_0002_m_000003_0: 2009-08-20 17:58:24,165 INFO mapred.Task (Task.java:sendDone(714)) - Task 'attempt_20090820175726994_0002_m_000003_0' done.
    [junit] 2009-08-20 17:58:26,460 INFO mapred.JobClient (JobClient.java:monitorAndPrintJob(1370)) - Job complete: job_20090820175726994_0002
    [junit] 2009-08-20 17:58:26,463 INFO mapred.JobClient (Counters.java:log(534)) - Counters: 22
    [junit] 2009-08-20 17:58:26,463 INFO mapred.JobClient (Counters.java:log(536)) - Job Counters
    [junit] 2009-08-20 17:58:26,463 INFO mapred.JobClient (Counters.java:log(538)) - Launched reduce tasks=1
    [junit] 2009-08-20 17:58:26,463 INFO mapred.JobClient (Counters.java:log(538)) - SLOTS_MILLIS_MAPS=5527
    [junit] 2009-08-20 17:58:26,464 INFO mapred.JobClient (Counters.java:log(538)) - Total time spent by all reduces waiting after reserving slots (ms)=0
    [junit] 2009-08-20 17:58:26,464 INFO mapred.JobClient (Counters.java:log(538)) - Total time spent by all maps waiting after reserving slots (ms)=0
    [junit] 2009-08-20 17:58:26,464 INFO mapred.JobClient (Counters.java:log(538)) - Rack-local map tasks=3
    [junit] 2009-08-20 17:58:26,464 INFO mapred.JobClient (Counters.java:log(538)) - Launched map tasks=3
    [junit] 2009-08-20 17:58:26,464 INFO mapred.JobClient (Counters.java:log(538)) - SLOTS_MILLIS_REDUCES=9192
    [junit] 2009-08-20 17:58:26,464 INFO mapred.JobClient (Counters.java:log(536)) - FileInputFormatCounters
    [junit] 2009-08-20 17:58:26,464 INFO mapred.JobClient (Counters.java:log(538)) - BYTES_READ=3
    [junit] 2009-08-20 17:58:26,465 INFO mapred.JobClient (Counters.java:log(536)) - FileSystemCounters
    [junit] 2009-08-20 17:58:26,465 INFO mapred.JobClient (Counters.java:log(538)) - FILE_BYTES_READ=21
    [junit] 2009-08-20 17:58:26,465 INFO mapred.JobClient (Counters.java:log(538)) - HDFS_BYTES_READ=828
    [junit] 2009-08-20 17:58:26,465 INFO mapred.JobClient (Counters.java:log(538)) - FILE_BYTES_WRITTEN=150
    [junit] 2009-08-20 17:58:26,465 INFO mapred.JobClient (Counters.java:log(538)) - HDFS_BYTES_WRITTEN=6
    [junit] 2009-08-20 17:58:26,465 INFO mapred.JobClient (Counters.java:log(536)) - Map-Reduce Framework
    [junit] 2009-08-20 17:58:26,465 INFO mapred.JobClient (Counters.java:log(538)) - Reduce input groups=3
    [junit] 2009-08-20 17:58:26,466 INFO mapred.JobClient (Counters.java:log(538)) - Combine output records=0
    [junit] 2009-08-20 17:58:26,466 INFO mapred.JobClient (Counters.java:log(538)) - Map input records=3
    [junit] 2009-08-20 17:58:26,466 INFO mapred.JobClient (Counters.java:log(538)) - Reduce shuffle bytes=33
    [junit] 2009-08-20 17:58:26,466 INFO mapred.JobClient (Counters.java:log(538)) - Reduce output records=3
    [junit] 2009-08-20 17:58:26,466 INFO mapred.JobClient (Counters.java:log(538)) - Spilled Records=6
    [junit] 2009-08-20 17:58:26,466 INFO mapred.JobClient (Counters.java:log(538)) - Map output bytes=9
    [junit] 2009-08-20 17:58:26,467 INFO mapred.JobClient (Counters.java:log(538)) - Combine input records=0
    [junit] 2009-08-20 17:58:26,467 INFO mapred.JobClient (Counters.java:log(538)) - Map output records=3
    [junit] 2009-08-20 17:58:26,467 INFO mapred.JobClient (Counters.java:log(538)) - Reduce input records=3
    [junit] 2009-08-20 17:58:26,470 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-20 17:58 /user/hudson/mapout/_logs
    [junit] -rw-r--r-- 3 hudson supergroup 6 2009-08-20 17:58 /user/hudson/mapout/part-00000
    [junit] 2009-08-20 17:58:26,472 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-20 17:58:26,473 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-20 17:58:26,475 INFO DataNode.clienttrace (BlockSender.java:sendBlock(417)) - src: /127.0.0.1:35532, dest: /127.0.0.1:47019, bytes: 10, op: HDFS_READ, cliID: DFSClient_816151018, offset: 0, srvID: DS-1285960160-67.195.138.9-35532-1250791046322, blockid: blk_-6204563453507012697_1015, duration: 271459
    [junit] 2009-08-20 17:58:26,475 INFO mapred.MiniMRCluster (MiniMRCluster.java:waitTaskTrackers(306)) - Waiting for task tracker tracker_host0.foo.com:localhost/127.0.0.1:33706 to be idle.
    [junit] 2009-08-20 17:58:27,204 INFO mapred.JobTracker (JobTracker.java:removeMarkedTasks(2395)) - Removed completed task 'attempt_20090820175726994_0002_m_000002_0' from 'tracker_host0.foo.com:localhost/127.0.0.1:33706'
    [junit] 2009-08-20 17:58:27,205 INFO mapred.TaskTracker (TaskTracker.java:purgeJob(1671)) - Received 'KillJobAction' for job: job_20090820175726994_0002
    [junit] 2009-08-20 17:58:27,205 INFO mapred.TaskRunner (MapTaskRunner.java:close(43)) - attempt_20090820175726994_0002_m_000002_0 done; removing files.
    [junit] 2009-08-20 17:58:27,476 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:33706
    [junit] 2009-08-20 17:58:27,477 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 33706
    [junit] 2009-08-20 17:58:27,477 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 33706: exiting
    [junit] 2009-08-20 17:58:27,477 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 3 on 33706: exiting
    [junit] 2009-08-20 17:58:27,477 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
    [junit] 2009-08-20 17:58:27,477 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 33706
    [junit] 2009-08-20 17:58:27,478 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 33706: exiting
    [junit] 2009-08-20 17:58:27,478 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 33706: exiting
    [junit] 2009-08-20 17:58:27,478 INFO mapred.TaskTracker (TaskTracker.java:shutdown(1149)) - Shutting down StatusHttpServer
    [junit] 2009-08-20 17:58:27,580 INFO mapred.TaskTracker (TaskTracker.java:offerService(1439)) - Interrupted. Closing down.
    [junit] 2009-08-20 17:58:27,581 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:51073
    [junit] 2009-08-20 17:58:27,582 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 51073
    [junit] 2009-08-20 17:58:27,582 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 51073: exiting
    [junit] 2009-08-20 17:58:27,582 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 51073: exiting
    [junit] 2009-08-20 17:58:27,582 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 51073: exiting
    [junit] 2009-08-20 17:58:27,582 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 3 on 51073: exiting
    [junit] 2009-08-20 17:58:27,583 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 51073
    [junit] 2009-08-20 17:58:27,583 INFO mapred.TaskTracker (TaskTracker.java:shutdown(1149)) - Shutting down StatusHttpServer
    [junit] 2009-08-20 17:58:27,583 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
    [junit] 2009-08-20 17:58:27,684 INFO mapred.TaskTracker (TaskTracker.java:offerService(1439)) - Interrupted. Closing down.
    [junit] 2009-08-20 17:58:27,685 INFO mapred.JobTracker (JobTracker.java:close(2213)) - Stopping infoServer
    [junit] 2009-08-20 17:58:27,788 INFO mapred.JobTracker (JobTracker.java:close(2221)) - Stopping interTrackerServer
    [junit] 2009-08-20 17:58:27,788 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 34315
    [junit] 2009-08-20 17:58:27,788 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 3 on 34315: exiting
    [junit] 2009-08-20 17:58:27,790 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 6 on 34315: exiting
    [junit] 2009-08-20 17:58:27,790 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 34315: exiting
    [junit] 2009-08-20 17:58:27,793 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 34315: exiting
    [junit] 2009-08-20 17:58:27,792 INFO mapred.JobTracker (JobTracker.java:stopExpireTrackersThread(2264)) - Stopping expireTrackers
    [junit] 2009-08-20 17:58:27,792 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
    [junit] 2009-08-20 17:58:27,794 INFO mapred.JobTracker (JobTracker.java:close(2228)) - Stopping retirer
    [junit] 2009-08-20 17:58:27,792 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 7 on 34315: exiting
    [junit] 2009-08-20 17:58:27,792 INFO mapred.JobTracker (JobTracker.java:offerService(2208)) - Stopped interTrackerServer
    [junit] 2009-08-20 17:58:27,792 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 5 on 34315: exiting
    [junit] 2009-08-20 17:58:27,792 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 8 on 34315: exiting
    [junit] 2009-08-20 17:58:27,792 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 34315
    [junit] 2009-08-20 17:58:27,792 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 9 on 34315: exiting
    [junit] 2009-08-20 17:58:27,792 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 4 on 34315: exiting
    [junit] 2009-08-20 17:58:27,790 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 34315: exiting
    [junit] 2009-08-20 17:58:27,794 INFO mapred.EagerTaskInitializationListener (EagerTaskInitializationListener.java:terminate(106)) - Stopping Job Init Manager thread
    [junit] 2009-08-20 17:58:27,796 INFO mapred.EagerTaskInitializationListener (EagerTaskInitializationListener.java:run(60)) - JobInitManagerThread interrupted.
    [junit] 2009-08-20 17:58:27,796 INFO mapred.EagerTaskInitializationListener (EagerTaskInitializationListener.java:run(64)) - Shutting down thread pool
    [junit] 2009-08-20 17:58:27,796 INFO mapred.JobTracker (JobTracker.java:close(2240)) - Stopping expireLaunchingTasks
    [junit] 2009-08-20 17:58:27,797 INFO mapred.JobTracker (JobTracker.java:close(2258)) - stopped all jobtracker services
    [junit] Shutting down the Mini HDFS Cluster
    [junit] Shutting down DataNode 1
    [junit] 2009-08-20 17:58:27,946 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 53892
    [junit] 2009-08-20 17:58:27,946 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 53892: exiting
    [junit] 2009-08-20 17:58:27,946 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 53892: exiting
    [junit] 2009-08-20 17:58:27,946 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 53892
    [junit] 2009-08-20 17:58:27,947 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 53892: exiting
    [junit] 2009-08-20 17:58:27,947 INFO datanode.DataNode (DataNode.java:shutdown(639)) - Waiting for threadgroup to exit, active threads is 1
    [junit] 2009-08-20 17:58:27,949 WARN datanode.DataNode (DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:54693, storageID=DS-1386870724-67.195.138.9-54693-1250791046898, infoPort=48677, ipcPort=53892):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-20 17:58:27,949 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
    [junit] 2009-08-20 17:58:27,951 INFO datanode.DataNode (DataNode.java:shutdown(639)) - Waiting for threadgroup to exit, active threads is 0
    [junit] 2009-08-20 17:58:27,951 INFO datanode.DataBlockScanner (DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
    [junit] 2009-08-20 17:58:27,952 INFO datanode.DataNode (DataNode.java:run(1285)) - DatanodeRegistration(127.0.0.1:54693, storageID=DS-1386870724-67.195.138.9-54693-1250791046898, infoPort=48677, ipcPort=53892):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-20 17:58:27,952 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 53892
    [junit] 2009-08-20 17:58:27,952 INFO datanode.DataNode (DataNode.java:shutdown(639)) - Waiting for threadgroup to exit, active threads is 0
    [junit] Shutting down DataNode 0
    [junit] 2009-08-20 17:58:28,072 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 48130
    [junit] 2009-08-20 17:58:28,073 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 48130: exiting
    [junit] 2009-08-20 17:58:28,073 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 48130
    [junit] 2009-08-20 17:58:28,073 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
    [junit] 2009-08-20 17:58:28,073 INFO datanode.DataNode (DataNode.java:shutdown(639)) - Waiting for threadgroup to exit, active threads is 1
    [junit] 2009-08-20 17:58:28,074 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 48130: exiting
    [junit] 2009-08-20 17:58:28,074 WARN datanode.DataNode (DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:35532, storageID=DS-1285960160-67.195.138.9-35532-1250791046322, infoPort=38498, ipcPort=48130):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-20 17:58:28,075 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 48130: exiting
    [junit] 2009-08-20 17:58:28,077 INFO datanode.DataNode (DataNode.java:shutdown(639)) - Waiting for threadgroup to exit, active threads is 0
    [junit] 2009-08-20 17:58:28,077 INFO datanode.DataBlockScanner (DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
    [junit] 2009-08-20 17:58:28,078 INFO datanode.DataNode (DataNode.java:run(1285)) - DatanodeRegistration(127.0.0.1:35532, storageID=DS-1285960160-67.195.138.9-35532-1250791046322, infoPort=38498, ipcPort=48130):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-20 17:58:28,078 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 48130
    [junit] 2009-08-20 17:58:28,078 INFO datanode.DataNode (DataNode.java:shutdown(639)) - Waiting for threadgroup to exit, active threads is 0
    [junit] 2009-08-20 17:58:28,207 WARN namenode.DecommissionManager (DecommissionManager.java:run(67)) - Monitor interrupted: java.lang.InterruptedException: sleep interrupted
    [junit] 2009-08-20 17:58:28,207 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): 596 642
    [junit] 2009-08-20 17:58:28,207 WARN namenode.FSNamesystem (FSNamesystem.java:run(2057)) - ReplicationMonitor thread received InterruptedException.java.lang.InterruptedException: sleep interrupted
    [junit] 2009-08-20 17:58:28,221 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 47008
    [junit] 2009-08-20 17:58:28,221 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 47008: exiting
    [junit] 2009-08-20 17:58:28,221 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 3 on 47008: exiting
    [junit] 2009-08-20 17:58:28,221 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 47008: exiting
    [junit] 2009-08-20 17:58:28,221 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 47008: exiting
    [junit] 2009-08-20 17:58:28,222 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 6 on 47008: exiting
    [junit] 2009-08-20 17:58:28,223 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 9 on 47008: exiting
    [junit] 2009-08-20 17:58:28,223 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 5 on 47008: exiting
    [junit] 2009-08-20 17:58:28,223 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
    [junit] 2009-08-20 17:58:28,222 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 8 on 47008: exiting
    [junit] 2009-08-20 17:58:28,222 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 7 on 47008: exiting
    [junit] 2009-08-20 17:58:28,223 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 4 on 47008: exiting
    [junit] 2009-08-20 17:58:28,223 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 47008
    [junit] Tests run: 2, Failures: 0, Errors: 0, Time elapsed: 104.056 sec
    [junit] Running org.apache.hadoop.util.TestReflectionUtils
    [junit] Tests run: 5, Failures: 0, Errors: 0, Time elapsed: 0.606 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.17 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: 163 minutes 26 seconds
    Publishing Javadoc
    Recording test results
    Recording fingerprints
    Publishing Clover coverage report...

Related Discussions

Discussion Navigation
viewthread | post
Discussion Overview
groupmapreduce-dev @
categorieshadoop
postedAug 17, '09 at 7:06p
activeAug 20, '09 at 6:00p
posts5
users1
websitehadoop.apache.org...
irc#hadoop

1 user in discussion

Apache Hudson Server: 5 posts

People

Translate

site design / logo © 2022 Grokbase