See http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/56/changes
Changes:
[tomwhite] MAPREDUCE-800. MRUnit should support the new API. Contributed by
Aaron Kimball.
[tomwhite] MAPREDUCE-749. Make Sqoop unit tests more Hudson-friendly.
Contributed by Aaron Kimball.
[sharad] MAPREDUCE-870. Remove the job retire thread and the associated config
parameters.
[sharad] MAPREDUCE-818. Fixes Counters#getGroup API. Contributed by Amareshwari
Sriramadasu.
[ddas] HADOOP-6103. Updated common jar from rev 806430
[yhemanth] MAPREDUCE-834. Enables memory management on tasktrackers when old
memory management parameters are used in configuration. Contributed by
Sreekanth Ramakrishnan.
[cdouglas] MAPREDUCE-712. Minor efficiency tweaks to RandomTextWriter.
[omalley] MAPREDUCE-767. Got the wrong jira number on the last commit, so
updating
CHANGES.
[omalley] MAPREDUCE-157. Remove the dependence on the CLI 2.0 snapshot.
(Amar Kamat via omalley)
------------------------------------------
[...truncated 133018 lines...]
[junit] 2009-08-21 18:45:46,828 INFO mapred.TaskRunner
(ReduceTaskRunner.java:close(47)) - attempt_20090821184450581_0002_r_000000_0
done; removing files.
[junit] 2009-08-21 18:45:46,863 INFO mapred.JobClient
(JobClient.java:monitorAndPrintJob(1364)) - Task Id :
attempt_20090821184450581_0002_r_000000_0, Status : SUCCEEDED
[junit] attempt_20090821184450581_0002_r_000000_0: 2009-08-21 18:45:35,605
INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Initializing JVM Metrics with
processName=SHUFFLE, sessionId=
[junit] attempt_20090821184450581_0002_r_000000_0: 2009-08-21 18:45:35,733
INFO mapred.ReduceTask (ReduceTask.java:<init>(1011)) - ShuffleRamManager:
MemoryLimit=141387360, MaxSingleShuffleLimit=35346840
[junit] attempt_20090821184450581_0002_r_000000_0: 2009-08-21 18:45:35,739
INFO mapred.ReduceTask (ReduceTask.java:run(2485)) -
attempt_20090821184450581_0002_r_000000_0 Thread started: Thread for merging
on-disk files
[junit] attempt_20090821184450581_0002_r_000000_0: 2009-08-21 18:45:35,739
INFO mapred.ReduceTask (ReduceTask.java:run(2584)) -
attempt_20090821184450581_0002_r_000000_0 Thread started: Thread for merging in
memory files
[junit] attempt_20090821184450581_0002_r_000000_0: 2009-08-21 18:45:35,740
INFO mapred.ReduceTask (ReduceTask.java:run(2490)) -
attempt_20090821184450581_0002_r_000000_0 Thread waiting: Thread for merging
on-disk files
[junit] attempt_20090821184450581_0002_r_000000_0: 2009-08-21 18:45:35,747
INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(1892)) -
attempt_20090821184450581_0002_r_000000_0 Need another 3 map output(s) where 0
is already in progress
[junit] attempt_20090821184450581_0002_r_000000_0: 2009-08-21 18:45:35,747
INFO mapred.ReduceTask (ReduceTask.java:run(2686)) -
attempt_20090821184450581_0002_r_000000_0 Thread started: Thread for polling
Map Completion Events
[junit] attempt_20090821184450581_0002_r_000000_0: 2009-08-21 18:45:35,748
INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2005)) -
attempt_20090821184450581_0002_r_000000_0 Scheduled 0 outputs (0 slow hosts
and0 dup hosts)
[junit] attempt_20090821184450581_0002_r_000000_0: 2009-08-21 18:45:35,753
INFO mapred.ReduceTask (ReduceTask.java:run(2692)) -
attempt_20090821184450581_0002_r_000000_0: Got 2 new map-outputs
[junit] attempt_20090821184450581_0002_r_000000_0: 2009-08-21 18:45:39,758
INFO mapred.ReduceTask (ReduceTask.java:run(2692)) -
attempt_20090821184450581_0002_r_000000_0: Got 1 new map-outputs
[junit] attempt_20090821184450581_0002_r_000000_0: 2009-08-21 18:45:40,748
INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2005)) -
attempt_20090821184450581_0002_r_000000_0 Scheduled 1 outputs (0 slow hosts
and0 dup hosts)
[junit] attempt_20090821184450581_0002_r_000000_0: 2009-08-21 18:45:40,784
INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1423)) - header:
attempt_20090821184450581_0002_m_000000_0, compressed len: 11, decompressed
len: 7
[junit] attempt_20090821184450581_0002_r_000000_0: 2009-08-21 18:45:40,784
INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1437)) - Shuffling 7
bytes (11 raw bytes) into RAM from attempt_20090821184450581_0002_m_000000_0
[junit] attempt_20090821184450581_0002_r_000000_0: 2009-08-21 18:45:40,792
INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1566)) - Read 7 bytes
from map-output for attempt_20090821184450581_0002_m_000000_0
[junit] attempt_20090821184450581_0002_r_000000_0: 2009-08-21 18:45:40,793
INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1625)) - Rec #1 from
attempt_20090821184450581_0002_m_000000_0 -> (2, 1) from localhost
[junit] attempt_20090821184450581_0002_r_000000_0: 2009-08-21 18:45:40,794
INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2005)) -
attempt_20090821184450581_0002_r_000000_0 Scheduled 1 outputs (0 slow hosts
and0 dup hosts)
[junit] attempt_20090821184450581_0002_r_000000_0: 2009-08-21 18:45:40,797
INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1423)) - header:
attempt_20090821184450581_0002_m_000001_0, compressed len: 11, decompressed
len: 7
[junit] attempt_20090821184450581_0002_r_000000_0: 2009-08-21 18:45:40,797
INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1437)) - Shuffling 7
bytes (11 raw bytes) into RAM from attempt_20090821184450581_0002_m_000001_0
[junit] attempt_20090821184450581_0002_r_000000_0: 2009-08-21 18:45:40,798
INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1566)) - Read 7 bytes
from map-output for attempt_20090821184450581_0002_m_000001_0
[junit] attempt_20090821184450581_0002_r_000000_0: 2009-08-21 18:45:40,798
INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1625)) - Rec #1 from
attempt_20090821184450581_0002_m_000001_0 -> (2, 1) from localhost
[junit] attempt_20090821184450581_0002_r_000000_0: 2009-08-21 18:45:40,798
INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2005)) -
attempt_20090821184450581_0002_r_000000_0 Scheduled 1 outputs (0 slow hosts
and0 dup hosts)
[junit] attempt_20090821184450581_0002_r_000000_0: 2009-08-21 18:45:40,802
INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1423)) - header:
attempt_20090821184450581_0002_m_000002_0, compressed len: 11, decompressed
len: 7
[junit] attempt_20090821184450581_0002_r_000000_0: 2009-08-21 18:45:40,802
INFO mapred.ReduceTask (ReduceTask.java:getMapOutput(1437)) - Shuffling 7
bytes (11 raw bytes) into RAM from attempt_20090821184450581_0002_m_000002_0
[junit] attempt_20090821184450581_0002_r_000000_0: 2009-08-21 18:45:40,802
INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1566)) - Read 7 bytes
from map-output for attempt_20090821184450581_0002_m_000002_0
[junit] attempt_20090821184450581_0002_r_000000_0: 2009-08-21 18:45:40,802
INFO mapred.ReduceTask (ReduceTask.java:shuffleInMemory(1625)) - Rec #1 from
attempt_20090821184450581_0002_m_000002_0 -> (2, 1) from localhost
[junit] attempt_20090821184450581_0002_r_000000_0: 2009-08-21 18:45:41,760
INFO mapred.ReduceTask (ReduceTask.java:run(2710)) - GetMapEventsThread exiting
[junit] attempt_20090821184450581_0002_r_000000_0: 2009-08-21 18:45:41,760
INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2203)) -
getMapsEventsThread joined.
[junit] attempt_20090821184450581_0002_r_000000_0: 2009-08-21 18:45:41,761
INFO mapred.ReduceTask (ReduceTask.java:close(1117)) - Closed ram manager
[junit] attempt_20090821184450581_0002_r_000000_0: 2009-08-21 18:45:41,761
INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2231)) - Interleaved
on-disk merge complete: 0 files left.
[junit] attempt_20090821184450581_0002_r_000000_0: 2009-08-21 18:45:41,761
INFO mapred.ReduceTask (ReduceTask.java:fetchOutputs(2236)) - In-memory merge
complete: 3 files left.
[junit] attempt_20090821184450581_0002_r_000000_0: 2009-08-21 18:45:41,793
INFO mapred.Merger (Merger.java:merge(469)) - Merging 3 sorted segments
[junit] attempt_20090821184450581_0002_r_000000_0: 2009-08-21 18:45:41,794
INFO mapred.Merger (Merger.java:merge(568)) - Down to the last merge-pass,
with 3 segments left of total size: 9 bytes
[junit] attempt_20090821184450581_0002_r_000000_0: 2009-08-21 18:45:41,809
INFO mapred.ReduceTask (ReduceTask.java:createKVIterator(2349)) - Merged 3
segments, 21 bytes to disk to satisfy reduce memory limit
[junit] attempt_20090821184450581_0002_r_000000_0: 2009-08-21 18:45:41,810
INFO mapred.ReduceTask (ReduceTask.java:createKVIterator(2369)) - Merging 1
files, 21 bytes from disk
[junit] attempt_20090821184450581_0002_r_000000_0: 2009-08-21 18:45:41,811
INFO mapred.ReduceTask (ReduceTask.java:createKVIterator(2383)) - Merging 0
segments, 0 bytes from memory into reduce
[junit] attempt_20090821184450581_0002_r_000000_0: 2009-08-21 18:45:41,811
INFO mapred.Merger (Merger.java:merge(469)) - Merging 1 sorted segments
[junit] attempt_20090821184450581_0002_r_000000_0: 2009-08-21 18:45:41,815
INFO mapred.Merger (Merger.java:merge(568)) - Down to the last merge-pass,
with 1 segments left of total size: 13 bytes
[junit] attempt_20090821184450581_0002_r_000000_0: 2009-08-21 18:45:42,070
INFO mapred.Task (Task.java:done(643)) -
Task:attempt_20090821184450581_0002_r_000000_0 is done. And is in the process
of commiting
[junit] attempt_20090821184450581_0002_r_000000_0: 2009-08-21 18:45:44,078
INFO mapred.Task (Task.java:commit(755)) - Task
attempt_20090821184450581_0002_r_000000_0 is allowed to commit now
[junit] attempt_20090821184450581_0002_r_000000_0: 2009-08-21 18:45:44,159
INFO mapred.FileOutputCommitter (FileOutputCommitter.java:commitTask(92)) -
Saved output of task 'attempt_20090821184450581_0002_r_000000_0' to
hdfs://localhost:45289/user/hudson/mapout
[junit] attempt_20090821184450581_0002_r_000000_0: 2009-08-21 18:45:44,162
INFO mapred.Task (Task.java:sendDone(714)) - Task
'attempt_20090821184450581_0002_r_000000_0' done.
[junit] 2009-08-21 18:45:46,874 INFO mapred.JvmManager
(JvmManager.java:<init>(396)) - In JvmRunner constructed JVM ID:
jvm_20090821184450581_0002_m_-912572321
[junit] 2009-08-21 18:45:46,874 INFO mapred.JvmManager
(JvmManager.java:spawnNewJvm(364)) - JVM Runner
jvm_20090821184450581_0002_m_-912572321 spawned.
[junit] 2009-08-21 18:45:47,319 INFO mapred.TaskTracker
(TaskTracker.java:getTask(2819)) - JVM with ID:
jvm_20090821184450581_0002_m_-912572321 given task:
attempt_20090821184450581_0002_m_000003_0
[junit] 2009-08-21 18:45:47,701 INFO mapred.TaskTracker
(TaskTracker.java:reportProgress(2266)) -
attempt_20090821184450581_0002_m_000003_0 0.0%
[junit] 2009-08-21 18:45:47,718 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-21 18:45:47,722 INFO mapred.TaskTracker
(TaskTracker.java:reportProgress(2266)) -
attempt_20090821184450581_0002_m_000003_0 0.0% cleanup > map
[junit] 2009-08-21 18:45:47,723 INFO mapred.TaskTracker
(TaskTracker.java:reportDone(2347)) - Task
attempt_20090821184450581_0002_m_000003_0 is done.
[junit] 2009-08-21 18:45:47,723 INFO mapred.TaskTracker
(TaskTracker.java:reportDone(2348)) - reported output size for
attempt_20090821184450581_0002_m_000003_0 was 0
[junit] 2009-08-21 18:45:47,724 INFO mapred.TaskTracker
(TaskTracker.java:addFreeSlots(1922)) - addFreeSlot : current free slots : 2
[junit] 2009-08-21 18:45:47,871 INFO mapred.JobClient
(JobClient.java:monitorAndPrintJob(1315)) - map 100% reduce 100%
[junit] 2009-08-21 18:45:47,909 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-21 18:45:47,909 INFO util.ProcessTree
(ProcessTree.java:terminateProcessGroup(138)) - Killing all processes in the
process group 18187 with SIGTERM. Exit code 1
[junit] 2009-08-21 18:45:49,310 INFO mapred.JvmManager
(JvmManager.java:runChild(423)) - JVM :
jvm_20090821184450581_0002_r_-1221258542 exited with exit code 0. Number of
tasks it ran: 1
[junit] 2009-08-21 18:45:49,828 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-21 18:45:49,830 INFO mapred.JobInProgress
(JobInProgress.java:completedTask(2450)) - Task
'attempt_20090821184450581_0002_m_000003_0' has completed
task_20090821184450581_0002_m_000003 successfully.
[junit] 2009-08-21 18:45:49,831 INFO mapred.JobInProgress
(JobInProgress.java:jobComplete(2616)) - Job job_20090821184450581_0002 has
completed successfully.
[junit] 2009-08-21 18:45:49,831 INFO mapred.JobInProgress$JobSummary
(JobInProgress.java:logJobSummary(3314)) -
jobId=job_20090821184450581_0002,submitTime=1250880327739,launchTime=1250880327871,finishTime=1250880349831,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-21 18:45:49,835 INFO hdfs.StateChange
(FSNamesystem.java:allocateBlock(1286)) - BLOCK* NameSystem.allocateBlock:
/user/hudson/mapout/_logs/history/localhost_1250880290616_job_20090821184450581_0002_hudson_NA.
blk_5244192949699944505_1015
[junit] 2009-08-21 18:45:49,837 INFO datanode.DataNode
(DataXceiver.java:writeBlock(240)) - Receiving block
blk_5244192949699944505_1015 src: /127.0.0.1:34444 dest: /127.0.0.1:54152
[junit] 2009-08-21 18:45:49,838 INFO datanode.DataNode
(DataXceiver.java:writeBlock(240)) - Receiving block
blk_5244192949699944505_1015 src: /127.0.0.1:47941 dest: /127.0.0.1:48275
[junit] 2009-08-21 18:45:49,842 INFO DataNode.clienttrace
(BlockReceiver.java:lastDataNodeRun(807)) - src: /127.0.0.1:47941, dest:
/127.0.0.1:48275, bytes: 12041, op: HDFS_WRITE, cliID: DFSClient_-557286446,
offset: 0, srvID: DS-330462957-67.195.138.9-48275-1250880289833, blockid:
blk_5244192949699944505_1015, duration: 2135070
[junit] 2009-08-21 18:45:49,842 INFO datanode.DataNode
(BlockReceiver.java:lastDataNodeRun(831)) - PacketResponder 0 for block
blk_5244192949699944505_1015 terminating
[junit] 2009-08-21 18:45:49,842 INFO hdfs.StateChange
(BlockManager.java:addStoredBlock(955)) - BLOCK* NameSystem.addStoredBlock:
blockMap updated: 127.0.0.1:48275 is added to blk_5244192949699944505_1015 size
12041
[junit] 2009-08-21 18:45:49,843 INFO DataNode.clienttrace
(BlockReceiver.java:run(933)) - src: /127.0.0.1:34444, dest: /127.0.0.1:54152,
bytes: 12041, op: HDFS_WRITE, cliID: DFSClient_-557286446, offset: 0, srvID:
DS-1406392639-67.195.138.9-54152-1250880290418, blockid:
blk_5244192949699944505_1015, duration: 3379748
[junit] 2009-08-21 18:45:49,843 INFO datanode.DataNode
(BlockReceiver.java:run(997)) - PacketResponder 1 for block
blk_5244192949699944505_1015 terminating
[junit] 2009-08-21 18:45:49,845 INFO hdfs.StateChange
(FSNamesystem.java:completeFileInternal(1252)) - DIR* NameSystem.completeFile:
file
/user/hudson/mapout/_logs/history/localhost_1250880290616_job_20090821184450581_0002_hudson_NA
is closed by DFSClient_-557286446
[junit] 2009-08-21 18:45:49,846 INFO namenode.FSNamesystem
(FSEditLog.java:printStatistics(876)) - Number of transactions: 87 Total time
for transactions(ms): 6Number of transactions batched in Syncs: 6 Number of
syncs: 60 SyncTimes(ms): 739 505
[junit] 2009-08-21 18:45:49,846 INFO hdfs.StateChange
(BlockManager.java:addStoredBlock(955)) - BLOCK* NameSystem.addStoredBlock:
blockMap updated: 127.0.0.1:54152 is added to blk_5244192949699944505_1015 size
12041
[junit] 2009-08-21 18:45:49,889 INFO mapred.JobHistory
(JobHistory.java:run(217)) - Moving
http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/logs/history/localhost_1250880290616_job_20090821184450581_0002_hudson_NA
to
http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/logs/history/done
[junit] 2009-08-21 18:45:49,891 INFO hdfs.StateChange
(BlockManager.java:addToInvalidates(365)) - BLOCK* NameSystem.addToInvalidates:
blk_-6732757651235896760 is added to invalidSet of 127.0.0.1:54152
[junit] 2009-08-21 18:45:49,891 INFO mapred.JobTracker
(JobTracker.java:removeMarkedTasks(2322)) - Removed completed task
'attempt_20090821184450581_0002_m_000000_0' from
'tracker_host1.foo.com:localhost/127.0.0.1:37267'
[junit] 2009-08-21 18:45:49,891 INFO hdfs.StateChange
(BlockManager.java:addToInvalidates(365)) - BLOCK* NameSystem.addToInvalidates:
blk_-6732757651235896760 is added to invalidSet of 127.0.0.1:48275
[junit] 2009-08-21 18:45:49,891 INFO mapred.JobTracker
(JobTracker.java:removeMarkedTasks(2322)) - Removed completed task
'attempt_20090821184450581_0002_m_000001_0' from
'tracker_host1.foo.com:localhost/127.0.0.1:37267'
[junit] 2009-08-21 18:45:49,891 INFO hdfs.StateChange
(BlockManager.java:addToInvalidates(365)) - BLOCK* NameSystem.addToInvalidates:
blk_-6496510232952931484 is added to invalidSet of 127.0.0.1:48275
[junit] 2009-08-21 18:45:49,892 INFO mapred.JobTracker
(JobTracker.java:removeMarkedTasks(2322)) - Removed completed task
'attempt_20090821184450581_0002_m_000003_0' from
'tracker_host1.foo.com:localhost/127.0.0.1:37267'
[junit] 2009-08-21 18:45:49,892 INFO hdfs.StateChange
(BlockManager.java:addToInvalidates(365)) - BLOCK* NameSystem.addToInvalidates:
blk_-6496510232952931484 is added to invalidSet of 127.0.0.1:54152
[junit] 2009-08-21 18:45:49,892 INFO mapred.JobTracker
(JobTracker.java:removeMarkedTasks(2322)) - Removed completed task
'attempt_20090821184450581_0002_m_000004_0' from
'tracker_host1.foo.com:localhost/127.0.0.1:37267'
[junit] 2009-08-21 18:45:49,892 INFO mapred.JobTracker
(JobTracker.java:removeMarkedTasks(2322)) - Removed completed task
'attempt_20090821184450581_0002_r_000000_0' from
'tracker_host1.foo.com:localhost/127.0.0.1:37267'
[junit] 2009-08-21 18:45:49,893 INFO mapred.JobClient
(JobClient.java:monitorAndPrintJob(1364)) - Task Id :
attempt_20090821184450581_0002_m_000003_0, Status : SUCCEEDED
[junit] 2009-08-21 18:45:49,894 INFO mapred.TaskTracker
(TaskTracker.java:purgeJob(1671)) - Received 'KillJobAction' for job:
job_20090821184450581_0002
[junit] 2009-08-21 18:45:49,894 INFO mapred.TaskRunner
(MapTaskRunner.java:close(43)) - attempt_20090821184450581_0002_m_000001_0
done; removing files.
[junit] attempt_20090821184450581_0002_m_000003_0: 2009-08-21 18:45:47,582
INFO jvm.JvmMetrics (JvmMetrics.java:init(71)) - Initializing JVM Metrics with
processName=MAP, sessionId=
[junit] attempt_20090821184450581_0002_m_000003_0: 2009-08-21 18:45:47,719
INFO mapred.Task (Task.java:done(643)) -
Task:attempt_20090821184450581_0002_m_000003_0 is done. And is in the process
of commiting
[junit] attempt_20090821184450581_0002_m_000003_0: 2009-08-21 18:45:47,723
INFO mapred.Task (Task.java:sendDone(714)) - Task
'attempt_20090821184450581_0002_m_000003_0' done.
[junit] 2009-08-21 18:45:49,895 INFO mapred.TaskRunner
(MapTaskRunner.java:close(43)) - attempt_20090821184450581_0002_m_000003_0
done; removing files.
[junit] 2009-08-21 18:45:49,895 INFO mapred.IndexCache
(IndexCache.java:removeMap(140)) - Map ID
attempt_20090821184450581_0002_m_000003_0 not found in cache
[junit] 2009-08-21 18:45:49,895 INFO mapred.TaskRunner
(MapTaskRunner.java:close(43)) - attempt_20090821184450581_0002_m_000000_0
done; removing files.
[junit] 2009-08-21 18:45:49,909 INFO FSNamesystem.audit
(FSNamesystem.java:logAuditEvent(114)) - ugi=hudson,hudson ip=/127.0.0.1
cmd=delete src=/tmp/hadoop-hudson/mapred/system/job_20090821184450581_0002
dst=null perm=null
[junit] 2009-08-21 18:45:49,909 INFO mapred.JobClient
(JobClient.java:monitorAndPrintJob(1370)) - Job complete:
job_20090821184450581_0002
[junit] 2009-08-21 18:45:49,938 INFO mapred.JobClient
(Counters.java:log(534)) - Counters: 22
[junit] 2009-08-21 18:45:49,938 INFO mapred.JobClient
(Counters.java:log(536)) - Job Counters
[junit] 2009-08-21 18:45:49,938 INFO mapred.JobClient
(Counters.java:log(538)) - Launched reduce tasks=1
[junit] 2009-08-21 18:45:49,939 INFO mapred.JobClient
(Counters.java:log(538)) - SLOTS_MILLIS_MAPS=5346
[junit] 2009-08-21 18:45:49,939 INFO mapred.JobClient
(Counters.java:log(538)) - Total time spent by all reduces waiting after
reserving slots (ms)=0
[junit] 2009-08-21 18:45:49,939 INFO mapred.JobClient
(Counters.java:log(538)) - Total time spent by all maps waiting after
reserving slots (ms)=0
[junit] 2009-08-21 18:45:49,939 INFO mapred.JobClient
(Counters.java:log(538)) - Rack-local map tasks=3
[junit] 2009-08-21 18:45:49,939 INFO mapred.JobClient
(Counters.java:log(538)) - Launched map tasks=3
[junit] 2009-08-21 18:45:49,939 INFO mapred.JobClient
(Counters.java:log(538)) - SLOTS_MILLIS_REDUCES=9321
[junit] 2009-08-21 18:45:49,939 INFO mapred.JobClient
(Counters.java:log(536)) - FileInputFormatCounters
[junit] 2009-08-21 18:45:49,940 INFO mapred.JobClient
(Counters.java:log(538)) - BYTES_READ=3
[junit] 2009-08-21 18:45:49,940 INFO mapred.JobClient
(Counters.java:log(536)) - FileSystemCounters
[junit] 2009-08-21 18:45:49,940 INFO mapred.JobClient
(Counters.java:log(538)) - FILE_BYTES_READ=21
[junit] 2009-08-21 18:45:49,940 INFO mapred.JobClient
(Counters.java:log(538)) - HDFS_BYTES_READ=828
[junit] 2009-08-21 18:45:49,940 INFO mapred.JobClient
(Counters.java:log(538)) - FILE_BYTES_WRITTEN=150
[junit] 2009-08-21 18:45:49,940 INFO mapred.JobClient
(Counters.java:log(538)) - HDFS_BYTES_WRITTEN=6
[junit] 2009-08-21 18:45:49,941 INFO mapred.JobClient
(Counters.java:log(536)) - Map-Reduce Framework
[junit] 2009-08-21 18:45:49,941 INFO mapred.JobClient
(Counters.java:log(538)) - Reduce input groups=3
[junit] 2009-08-21 18:45:49,941 INFO mapred.JobClient
(Counters.java:log(538)) - Combine output records=0
[junit] 2009-08-21 18:45:49,941 INFO mapred.JobClient
(Counters.java:log(538)) - Map input records=3
[junit] 2009-08-21 18:45:49,941 INFO mapred.JobClient
(Counters.java:log(538)) - Reduce shuffle bytes=33
[junit] 2009-08-21 18:45:49,941 INFO mapred.JobClient
(Counters.java:log(538)) - Reduce output records=3
[junit] 2009-08-21 18:45:49,941 INFO mapred.JobClient
(Counters.java:log(538)) - Spilled Records=6
[junit] 2009-08-21 18:45:49,942 INFO mapred.JobClient
(Counters.java:log(538)) - Map output bytes=9
[junit] 2009-08-21 18:45:49,942 INFO mapred.JobClient
(Counters.java:log(538)) - Combine input records=0
[junit] 2009-08-21 18:45:49,942 INFO mapred.JobClient
(Counters.java:log(538)) - Map output records=3
[junit] 2009-08-21 18:45:49,942 INFO mapred.JobClient
(Counters.java:log(538)) - Reduce input records=3
[junit] 2009-08-21 18:45:49,945 INFO mapred.JobHistory
(JobHistory.java:run(217)) - Moving
http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/logs/history/localhost_1250880290616_job_20090821184450581_0002_conf.xml
to
http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/logs/history/done
[junit] 2009-08-21 18:45:49,947 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-21 18:45
/user/hudson/mapout/_logs
[junit] -rw-r--r-- 3 hudson supergroup 6 2009-08-21 18:45
/user/hudson/mapout/part-00000
[junit] 2009-08-21 18:45:49,956 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-21 18:45:49,958 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-21 18:45:49,960 INFO DataNode.clienttrace
(BlockSender.java:sendBlock(417)) - src: /127.0.0.1:48275, dest:
/127.0.0.1:47942, bytes: 10, op: HDFS_READ, cliID: DFSClient_-557286446,
offset: 0, srvID: DS-330462957-67.195.138.9-48275-1250880289833, blockid:
blk_8638886166277533526_1015, duration: 222359
[junit] 2009-08-21 18:45:49,961 INFO mapred.MiniMRCluster
(MiniMRCluster.java:waitTaskTrackers(306)) - Waiting for task tracker
tracker_host0.foo.com:localhost/127.0.0.1:40888 to be idle.
[junit] 2009-08-21 18:45:49,984 INFO mapred.JobHistory
(JobHistory.java:cleanupJob(1057)) - Deleting localized job conf at
http://hudson.zones.apache.org/hudson/job/Hadoop-Mapreduce-trunk/ws/trunk/build/test/logs/job_20090821184450581_0002_conf.xml
[junit] 2009-08-21 18:45:50,738 INFO mapred.JobTracker
(JobTracker.java:removeMarkedTasks(2322)) - Removed completed task
'attempt_20090821184450581_0002_m_000002_0' from
'tracker_host0.foo.com:localhost/127.0.0.1:40888'
[junit] 2009-08-21 18:45:50,739 INFO mapred.TaskTracker
(TaskTracker.java:purgeJob(1671)) - Received 'KillJobAction' for job:
job_20090821184450581_0002
[junit] 2009-08-21 18:45:50,740 INFO mapred.TaskRunner
(MapTaskRunner.java:close(43)) - attempt_20090821184450581_0002_m_000002_0
done; removing files.
[junit] 2009-08-21 18:45:50,962 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:40888
[junit] 2009-08-21 18:45:50,963 INFO ipc.Server (Server.java:stop(1103)) -
Stopping server on 40888
[junit] 2009-08-21 18:45:50,963 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 3 on 40888: exiting
[junit] 2009-08-21 18:45:50,964 INFO mapred.TaskTracker
(TaskTracker.java:shutdown(1149)) - Shutting down StatusHttpServer
[junit] 2009-08-21 18:45:50,964 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 0 on 40888: exiting
[junit] 2009-08-21 18:45:50,964 INFO ipc.Server (Server.java:run(539)) -
Stopping IPC Server Responder
[junit] 2009-08-21 18:45:50,964 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 2 on 40888: exiting
[junit] 2009-08-21 18:45:50,964 INFO ipc.Server (Server.java:run(352)) -
Stopping IPC Server listener on 40888
[junit] 2009-08-21 18:45:50,964 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 1 on 40888: exiting
[junit] 2009-08-21 18:45:51,120 INFO mapred.TaskTracker
(TaskTracker.java:offerService(1439)) - Interrupted. Closing down.
[junit] 2009-08-21 18:45:51,121 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:37267
[junit] 2009-08-21 18:45:51,121 INFO ipc.Server (Server.java:stop(1103)) -
Stopping server on 37267
[junit] 2009-08-21 18:45:51,121 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 3 on 37267: exiting
[junit] 2009-08-21 18:45:51,122 INFO ipc.Server (Server.java:run(352)) -
Stopping IPC Server listener on 37267
[junit] 2009-08-21 18:45:51,122 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 1 on 37267: exiting
[junit] 2009-08-21 18:45:51,122 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 0 on 37267: exiting
[junit] 2009-08-21 18:45:51,122 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 2 on 37267: exiting
[junit] 2009-08-21 18:45:51,122 INFO ipc.Server (Server.java:run(539)) -
Stopping IPC Server Responder
[junit] 2009-08-21 18:45:51,122 INFO mapred.TaskTracker
(TaskTracker.java:shutdown(1149)) - Shutting down StatusHttpServer
[junit] 2009-08-21 18:45:51,246 INFO mapred.TaskTracker
(TaskTracker.java:offerService(1439)) - Interrupted. Closing down.
[junit] 2009-08-21 18:45:51,247 INFO mapred.JobTracker
(JobTracker.java:close(2149)) - Stopping infoServer
[junit] 2009-08-21 18:45:51,374 INFO mapred.JobTracker
(JobTracker.java:close(2157)) - Stopping interTrackerServer
[junit] 2009-08-21 18:45:51,375 INFO ipc.Server (Server.java:stop(1103)) -
Stopping server on 42270
[junit] 2009-08-21 18:45:51,375 INFO ipc.Server (Server.java:run(352)) -
Stopping IPC Server listener on 42270
[junit] 2009-08-21 18:45:51,375 INFO mapred.JobTracker
(JobTracker.java:offerService(2144)) - Stopped interTrackerServer
[junit] 2009-08-21 18:45:51,375 INFO mapred.JobTracker
(JobTracker.java:stopExpireTrackersThread(2191)) - Stopping expireTrackers
[junit] 2009-08-21 18:45:51,376 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 3 on 42270: exiting
[junit] 2009-08-21 18:45:51,376 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 2 on 42270: exiting
[junit] 2009-08-21 18:45:51,375 INFO ipc.Server (Server.java:run(539)) -
Stopping IPC Server Responder
[junit] 2009-08-21 18:45:51,377 INFO
mapred.EagerTaskInitializationListener
(EagerTaskInitializationListener.java:terminate(106)) - Stopping Job Init
Manager thread
[junit] 2009-08-21 18:45:51,376 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 8 on 42270: exiting
[junit] 2009-08-21 18:45:51,376 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 9 on 42270: exiting
[junit] 2009-08-21 18:45:51,376 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 7 on 42270: exiting
[junit] 2009-08-21 18:45:51,376 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 6 on 42270: exiting
[junit] 2009-08-21 18:45:51,376 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 4 on 42270: exiting
[junit] 2009-08-21 18:45:51,376 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 1 on 42270: exiting
[junit] 2009-08-21 18:45:51,376 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 5 on 42270: exiting
[junit] 2009-08-21 18:45:51,376 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 0 on 42270: exiting
[junit] 2009-08-21 18:45:51,377 INFO
mapred.EagerTaskInitializationListener
(EagerTaskInitializationListener.java:run(60)) - JobInitManagerThread
interrupted.
[junit] 2009-08-21 18:45:51,379 INFO
mapred.EagerTaskInitializationListener
(EagerTaskInitializationListener.java:run(64)) - Shutting down thread pool
[junit] 2009-08-21 18:45:51,379 INFO mapred.JobTracker
(JobTracker.java:close(2167)) - Stopping expireLaunchingTasks
[junit] 2009-08-21 18:45:51,380 INFO mapred.JobTracker
(JobTracker.java:close(2185)) - stopped all jobtracker services
[junit] Shutting down the Mini HDFS Cluster
[junit] Shutting down DataNode 1
[junit] 2009-08-21 18:45:51,482 INFO ipc.Server (Server.java:stop(1103)) -
Stopping server on 44409
[junit] 2009-08-21 18:45:51,482 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 0 on 44409: exiting
[junit] 2009-08-21 18:45:51,483 INFO ipc.Server (Server.java:run(539)) -
Stopping IPC Server Responder
[junit] 2009-08-21 18:45:51,483 INFO ipc.Server (Server.java:run(352)) -
Stopping IPC Server listener on 44409
[junit] 2009-08-21 18:45:51,483 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 1 on 44409: exiting
[junit] 2009-08-21 18:45:51,483 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 2 on 44409: exiting
[junit] 2009-08-21 18:45:51,483 WARN datanode.DataNode
(DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:54152,
storageID=DS-1406392639-67.195.138.9-54152-1250880290418, infoPort=45341,
ipcPort=44409):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-21 18:45:51,483 INFO datanode.DataNode
(DataNode.java:shutdown(639)) - Waiting for threadgroup to exit, active threads
is 1
[junit] 2009-08-21 18:45:51,484 INFO datanode.DataBlockScanner
(DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
[junit] 2009-08-21 18:45:51,485 INFO datanode.DataNode
(DataNode.java:run(1285)) - DatanodeRegistration(127.0.0.1:54152,
storageID=DS-1406392639-67.195.138.9-54152-1250880290418, infoPort=45341,
ipcPort=44409):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-21 18:45:51,485 INFO ipc.Server (Server.java:stop(1103)) -
Stopping server on 44409
[junit] 2009-08-21 18:45:51,485 INFO datanode.DataNode
(DataNode.java:shutdown(639)) - Waiting for threadgroup to exit, active threads
is 0
[junit] Shutting down DataNode 0
[junit] 2009-08-21 18:45:51,587 INFO ipc.Server (Server.java:stop(1103)) -
Stopping server on 43572
[junit] 2009-08-21 18:45:51,587 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 0 on 43572: exiting
[junit] 2009-08-21 18:45:51,587 INFO ipc.Server (Server.java:run(539)) -
Stopping IPC Server Responder
[junit] 2009-08-21 18:45:51,588 INFO datanode.DataNode
(DataNode.java:shutdown(639)) - Waiting for threadgroup to exit, active threads
is 1
[junit] 2009-08-21 18:45:51,588 INFO ipc.Server (Server.java:run(352)) -
Stopping IPC Server listener on 43572
[junit] 2009-08-21 18:45:51,588 WARN datanode.DataNode
(DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:48275,
storageID=DS-330462957-67.195.138.9-48275-1250880289833, infoPort=53293,
ipcPort=43572):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-21 18:45:51,587 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 2 on 43572: exiting
[junit] 2009-08-21 18:45:51,587 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 1 on 43572: exiting
[junit] 2009-08-21 18:45:51,590 INFO datanode.DataNode
(DataNode.java:shutdown(639)) - Waiting for threadgroup to exit, active threads
is 0
[junit] 2009-08-21 18:45:51,591 INFO datanode.DataBlockScanner
(DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
[junit] 2009-08-21 18:45:51,591 INFO datanode.DataNode
(DataNode.java:run(1285)) - DatanodeRegistration(127.0.0.1:48275,
storageID=DS-330462957-67.195.138.9-48275-1250880289833, infoPort=53293,
ipcPort=43572):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-21 18:45:51,591 INFO ipc.Server (Server.java:stop(1103)) -
Stopping server on 43572
[junit] 2009-08-21 18:45:51,592 INFO datanode.DataNode
(DataNode.java:shutdown(639)) - Waiting for threadgroup to exit, active threads
is 0
[junit] 2009-08-21 18:45:51,697 WARN namenode.FSNamesystem
(FSNamesystem.java:run(2057)) - ReplicationMonitor thread received
InterruptedException.java.lang.InterruptedException: sleep interrupted
[junit] 2009-08-21 18:45:51,697 WARN namenode.DecommissionManager
(DecommissionManager.java:run(67)) - Monitor interrupted:
java.lang.InterruptedException: sleep interrupted
[junit] 2009-08-21 18:45:51,697 INFO namenode.FSNamesystem
(FSEditLog.java:printStatistics(876)) - Number of transactions: 88 Total time
for transactions(ms): 6Number of transactions batched in Syncs: 6 Number of
syncs: 62 SyncTimes(ms): 784 518
[junit] 2009-08-21 18:45:51,742 INFO ipc.Server (Server.java:stop(1103)) -
Stopping server on 45289
[junit] 2009-08-21 18:45:51,742 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 0 on 45289: exiting
[junit] 2009-08-21 18:45:51,743 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 1 on 45289: exiting
[junit] 2009-08-21 18:45:51,743 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 8 on 45289: exiting
[junit] 2009-08-21 18:45:51,743 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 6 on 45289: exiting
[junit] 2009-08-21 18:45:51,743 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 5 on 45289: exiting
[junit] 2009-08-21 18:45:51,743 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 7 on 45289: exiting
[junit] 2009-08-21 18:45:51,743 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 2 on 45289: exiting
[junit] 2009-08-21 18:45:51,743 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 4 on 45289: exiting
[junit] 2009-08-21 18:45:51,743 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 3 on 45289: exiting
[junit] 2009-08-21 18:45:51,744 INFO ipc.Server (Server.java:run(539)) -
Stopping IPC Server Responder
[junit] 2009-08-21 18:45:51,743 INFO ipc.Server (Server.java:run(352)) -
Stopping IPC Server listener on 45289
[junit] 2009-08-21 18:45:51,743 INFO ipc.Server (Server.java:run(997)) -
IPC Server handler 9 on 45289: exiting
[junit] Tests run: 2, Failures: 0, Errors: 0, Time elapsed: 103.875 sec
[junit] Running org.apache.hadoop.util.TestReflectionUtils
[junit] Tests run: 5, Failures: 0, Errors: 0, Time elapsed: 0.616 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.202 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 47 seconds
Publishing Javadoc
Recording test results
Recording fingerprints
Publishing Clover coverage report...
