See <http://hudson.zones.apache.org/hudson/job/Pig-trunk/695/changes>
Changes: [gates] PIG-1053: Put pig.properties back into release distribution. ------------------------------------------ [...truncated 256921 lines...] [junit] 10/03/05 10:30:52 INFO DataNode.clienttrace: src: /127.0.0.1:51932, dest: /127.0.0.1:41847, bytes: 2896210, op: HDFS_READ, cliID: DFSClient_2046932554, srvID: DS-1555557361-127.0.1.1-51932-1267785019661, blockid: blk_-1529009670148243081_1013 [junit] 10/03/05 10:30:52 INFO mapred.JobTracker: Initializing job_20100305103020175_0002 [junit] 10/03/05 10:30:52 INFO mapred.JobInProgress: Initializing job_20100305103020175_0002 [junit] 10/03/05 10:30:52 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=create src=/tmp/temp-1043653422/tmp104689674/_logs/history/localhost_1267785020198_job_20100305103020175_0002_hudson_Job3600321352221509795.jar dst=null perm=hudson:supergroup:rw-r--r-- [junit] 10/03/05 10:30:52 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=create src=/tmp/temp-1043653422/tmp104689674/_logs/history/localhost_1267785020198_job_20100305103020175_0002_conf.xml dst=null perm=hudson:supergroup:rw-r--r-- [junit] 10/03/05 10:30:52 INFO hdfs.StateChange: BLOCK* NameSystem.allocateBlock: /tmp/temp-1043653422/tmp104689674/_logs/history/localhost_1267785020198_job_20100305103020175_0002_conf.xml. blk_109331863420692483_1017 [junit] 10/03/05 10:30:52 INFO datanode.DataNode: Receiving block blk_109331863420692483_1017 src: /127.0.0.1:41848 dest: /127.0.0.1:51932 [junit] 10/03/05 10:30:52 INFO datanode.DataNode: Receiving block blk_109331863420692483_1017 src: /127.0.0.1:33569 dest: /127.0.0.1:58516 [junit] 10/03/05 10:30:52 INFO datanode.DataNode: Receiving block blk_109331863420692483_1017 src: /127.0.0.1:53112 dest: /127.0.0.1:33770 [junit] 10/03/05 10:30:52 INFO DataNode.clienttrace: src: /127.0.0.1:53112, dest: /127.0.0.1:33770, bytes: 58033, op: HDFS_WRITE, cliID: DFSClient_2046932554, srvID: DS-491133707-127.0.1.1-33770-1267785020106, blockid: blk_109331863420692483_1017 [junit] 10/03/05 10:30:52 INFO datanode.DataNode: PacketResponder 0 for block blk_109331863420692483_1017 terminating [junit] 10/03/05 10:30:52 INFO DataNode.clienttrace: src: /127.0.0.1:33569, dest: /127.0.0.1:58516, bytes: 58033, op: HDFS_WRITE, cliID: DFSClient_2046932554, srvID: DS-1287440467-127.0.1.1-58516-1267785019210, blockid: blk_109331863420692483_1017 [junit] 10/03/05 10:30:52 INFO datanode.DataNode: PacketResponder 1 for block blk_109331863420692483_1017 terminating [junit] 10/03/05 10:30:52 INFO DataNode.clienttrace: src: /127.0.0.1:41848, dest: /127.0.0.1:51932, bytes: 58033, op: HDFS_WRITE, cliID: DFSClient_2046932554, srvID: DS-1555557361-127.0.1.1-51932-1267785019661, blockid: blk_109331863420692483_1017 [junit] 10/03/05 10:30:52 INFO hdfs.StateChange: BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:33770 is added to blk_109331863420692483_1017 size 58033 [junit] 10/03/05 10:30:52 INFO datanode.DataNode: PacketResponder 2 for block blk_109331863420692483_1017 terminating [junit] 10/03/05 10:30:52 INFO hdfs.StateChange: BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:58516 is added to blk_109331863420692483_1017 size 58033 [junit] 10/03/05 10:30:52 INFO hdfs.StateChange: BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:51932 is added to blk_109331863420692483_1017 size 58033 [junit] 10/03/05 10:30:52 INFO hdfs.StateChange: DIR* NameSystem.completeFile: file /tmp/temp-1043653422/tmp104689674/_logs/history/localhost_1267785020198_job_20100305103020175_0002_conf.xml is closed by DFSClient_2046932554 [junit] 10/03/05 10:30:52 INFO mapReduceLayer.MapReduceLauncher: HadoopJobId: job_20100305103020175_0002 [junit] 10/03/05 10:30:52 INFO mapReduceLayer.MapReduceLauncher: More information at: http://localhost:46600/jobdetails.jsp?jobid=job_20100305103020175_0002 [junit] 10/03/05 10:30:52 INFO mapReduceLayer.MapReduceLauncher: 0% complete [junit] 10/03/05 10:30:52 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=open src=/tmp/hadoop-hudson/mapred/system/job_20100305103020175_0002/job.split dst=null perm=null [junit] 10/03/05 10:30:52 INFO DataNode.clienttrace: src: /127.0.0.1:33770, dest: /127.0.0.1:53113, bytes: 871, op: HDFS_READ, cliID: DFSClient_2046932554, srvID: DS-491133707-127.0.1.1-33770-1267785020106, blockid: blk_2163684875822531003_1014 [junit] 10/03/05 10:30:52 INFO mapred.JobInProgress: Input size for job job_20100305103020175_0002 = 12. Number of splits = 2 [junit] 10/03/05 10:30:52 INFO mapred.JobInProgress: tip:task_20100305103020175_0002_m_000000 has split on node:/default-rack/h7.grid.sp2.yahoo.net [junit] 10/03/05 10:30:52 INFO mapred.JobInProgress: tip:task_20100305103020175_0002_m_000000 has split on node:/default-rack/h7.grid.sp2.yahoo.net [junit] 10/03/05 10:30:52 INFO mapred.JobInProgress: tip:task_20100305103020175_0002_m_000000 has split on node:/default-rack/h7.grid.sp2.yahoo.net [junit] 10/03/05 10:30:52 INFO mapred.JobInProgress: tip:task_20100305103020175_0002_m_000001 has split on node:/default-rack/h7.grid.sp2.yahoo.net [junit] 10/03/05 10:30:52 INFO mapred.JobInProgress: tip:task_20100305103020175_0002_m_000001 has split on node:/default-rack/h7.grid.sp2.yahoo.net [junit] 10/03/05 10:30:52 INFO mapred.JobInProgress: tip:task_20100305103020175_0002_m_000001 has split on node:/default-rack/h7.grid.sp2.yahoo.net [junit] 10/03/05 10:30:53 INFO hdfs.StateChange: BLOCK* ask 127.0.0.1:51932 to delete blk_-5599988273065478233_1006 blk_-793850207562293440_1007 blk_-2926143827434249772_1005 [junit] 10/03/05 10:30:53 INFO hdfs.StateChange: BLOCK* ask 127.0.0.1:33770 to delete blk_-1529009670148243081_1013 blk_-2926143827434249772_1005 [junit] 10/03/05 10:30:54 INFO mapred.JobTracker: Adding task 'attempt_20100305103020175_0002_m_000003_0' to tip task_20100305103020175_0002_m_000003, for tracker 'tracker_host0.foo.com:localhost/127.0.0.1:50338' [junit] 10/03/05 10:30:54 INFO mapred.TaskTracker: LaunchTaskAction (registerTask): attempt_20100305103020175_0002_m_000003_0 task's state:UNASSIGNED [junit] 10/03/05 10:30:54 INFO mapred.TaskTracker: Trying to launch : attempt_20100305103020175_0002_m_000003_0 [junit] 10/03/05 10:30:54 INFO mapred.TaskTracker: In TaskLauncher, current free slots : 2 and trying to launch attempt_20100305103020175_0002_m_000003_0 [junit] 10/03/05 10:30:54 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=open src=/tmp/hadoop-hudson/mapred/system/job_20100305103020175_0002/job.xml dst=null perm=null [junit] 10/03/05 10:30:54 INFO DataNode.clienttrace: src: /127.0.0.1:58516, dest: /127.0.0.1:33572, bytes: 58522, op: HDFS_READ, cliID: DFSClient_2046932554, srvID: DS-1287440467-127.0.1.1-58516-1267785019210, blockid: blk_8922059208167072865_1015 [junit] 10/03/05 10:30:54 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=open src=/tmp/hadoop-hudson/mapred/system/job_20100305103020175_0002/job.jar dst=null perm=null [junit] 10/03/05 10:30:54 INFO DataNode.clienttrace: src: /127.0.0.1:51932, dest: /127.0.0.1:41853, bytes: 2896210, op: HDFS_READ, cliID: DFSClient_2046932554, srvID: DS-1555557361-127.0.1.1-51932-1267785019661, blockid: blk_-1529009670148243081_1013 [junit] 10/03/05 10:30:55 INFO mapred.JvmManager: In JvmRunner constructed JVM ID: jvm_20100305103020175_0002_m_-2093591169 [junit] 10/03/05 10:30:55 INFO mapred.JvmManager: JVM Runner jvm_20100305103020175_0002_m_-2093591169 spawned. [junit] 10/03/05 10:30:55 INFO mapred.TaskTracker: JVM with ID: jvm_20100305103020175_0002_m_-2093591169 given task: attempt_20100305103020175_0002_m_000003_0 [junit] 10/03/05 10:30:55 INFO datanode.DataNode: Deleting block blk_-5599988273065478233_1006 file build/test/data/dfs/data/data6/current/blk_-5599988273065478233 [junit] 10/03/05 10:30:55 INFO datanode.DataNode: Deleting block blk_-2926143827434249772_1005 file build/test/data/dfs/data/data5/current/blk_-2926143827434249772 [junit] 10/03/05 10:30:55 INFO datanode.DataNode: Deleting block blk_-793850207562293440_1007 file build/test/data/dfs/data/data5/current/blk_-793850207562293440 [junit] 10/03/05 10:30:56 WARN datanode.DataNode: Unexpected error trying to delete block blk_-2926143827434249772_1005. BlockInfo not found in volumeMap. [junit] 10/03/05 10:30:56 INFO datanode.DataNode: Deleting block blk_-1529009670148243081_1013 file build/test/data/dfs/data/data8/current/blk_-1529009670148243081 [junit] 10/03/05 10:30:56 WARN datanode.DataNode: Error processing datanode Command [junit] java.io.IOException: Error in deleting blocks. [junit] at org.apache.hadoop.hdfs.server.datanode.FSDataset.invalidate(FSDataset.java:1361) [junit] at org.apache.hadoop.hdfs.server.datanode.DataNode.processCommand(DataNode.java:868) [junit] at org.apache.hadoop.hdfs.server.datanode.DataNode.processCommand(DataNode.java:830) [junit] at org.apache.hadoop.hdfs.server.datanode.DataNode.offerService(DataNode.java:710) [junit] at org.apache.hadoop.hdfs.server.datanode.DataNode.run(DataNode.java:1186) [junit] at java.lang.Thread.run(Thread.java:619) [junit] 10/03/05 10:30:56 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=mkdirs src=/tmp/temp-1043653422/tmp104689674/_temporary dst=null perm=hudson:supergroup:rwxr-xr-x [junit] 10/03/05 10:30:56 INFO mapred.TaskTracker: attempt_20100305103020175_0002_m_000003_0 0.0% setup [junit] 10/03/05 10:30:56 INFO mapred.TaskTracker: Task attempt_20100305103020175_0002_m_000003_0 is done. [junit] 10/03/05 10:30:56 INFO mapred.TaskTracker: reported output size for attempt_20100305103020175_0002_m_000003_0 was 0 [junit] 10/03/05 10:30:56 INFO mapred.TaskTracker: addFreeSlot : current free slots : 2 [junit] 10/03/05 10:30:56 INFO mapred.JvmManager: JVM : jvm_20100305103020175_0002_m_-2093591169 exited. Number of tasks it ran: 1 [junit] 10/03/05 10:30:57 INFO mapred.TaskTracker: org.apache.hadoop.util.DiskChecker$DiskErrorException: Could not find taskTracker/jobcache/job_20100305103020175_0002/attempt_20100305103020175_0002_m_000003_0/output/file.out in any of the configured local directories [junit] 10/03/05 10:30:57 INFO mapred.JobInProgress: Task 'attempt_20100305103020175_0002_m_000003_0' has completed task_20100305103020175_0002_m_000003 successfully. [junit] 10/03/05 10:30:57 INFO mapred.JobTracker: Adding task 'attempt_20100305103020175_0002_m_000000_0' to tip task_20100305103020175_0002_m_000000, for tracker 'tracker_host0.foo.com:localhost/127.0.0.1:50338' [junit] 10/03/05 10:30:57 INFO mapred.JobInProgress: Choosing rack-local task task_20100305103020175_0002_m_000000 [junit] 10/03/05 10:30:57 INFO mapred.TaskTracker: LaunchTaskAction (registerTask): attempt_20100305103020175_0002_m_000000_0 task's state:UNASSIGNED [junit] 10/03/05 10:30:57 INFO mapred.TaskTracker: Trying to launch : attempt_20100305103020175_0002_m_000000_0 [junit] 10/03/05 10:30:57 INFO mapred.TaskTracker: In TaskLauncher, current free slots : 2 and trying to launch attempt_20100305103020175_0002_m_000000_0 [junit] 10/03/05 10:30:57 INFO mapred.TaskTracker: Received KillTaskAction for task: attempt_20100305103020175_0002_m_000003_0 [junit] 10/03/05 10:30:57 INFO mapred.TaskTracker: About to purge task: attempt_20100305103020175_0002_m_000003_0 [junit] 10/03/05 10:30:57 INFO mapred.TaskRunner: attempt_20100305103020175_0002_m_000003_0 done; removing files. [junit] 10/03/05 10:30:57 INFO mapred.IndexCache: Map ID attempt_20100305103020175_0002_m_000003_0 not found in cache [junit] 10/03/05 10:30:57 INFO mapred.JvmManager: In JvmRunner constructed JVM ID: jvm_20100305103020175_0002_m_-114262773 [junit] 10/03/05 10:30:57 INFO mapred.JvmManager: JVM Runner jvm_20100305103020175_0002_m_-114262773 spawned. [junit] 10/03/05 10:30:57 INFO mapred.JobTracker: Adding task 'attempt_20100305103020175_0002_m_000001_0' to tip task_20100305103020175_0002_m_000001, for tracker 'tracker_host1.foo.com:localhost/127.0.0.1:33449' [junit] 10/03/05 10:30:57 INFO mapred.JobInProgress: Choosing rack-local task task_20100305103020175_0002_m_000001 [junit] 10/03/05 10:30:57 INFO mapred.TaskTracker: LaunchTaskAction (registerTask): attempt_20100305103020175_0002_m_000001_0 task's state:UNASSIGNED [junit] 10/03/05 10:30:57 INFO mapred.TaskTracker: Trying to launch : attempt_20100305103020175_0002_m_000001_0 [junit] 10/03/05 10:30:57 INFO mapred.TaskTracker: In TaskLauncher, current free slots : 2 and trying to launch attempt_20100305103020175_0002_m_000001_0 [junit] 10/03/05 10:30:58 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=open src=/tmp/hadoop-hudson/mapred/system/job_20100305103020175_0002/job.xml dst=null perm=null [junit] 10/03/05 10:30:58 INFO DataNode.clienttrace: src: /127.0.0.1:58516, dest: /127.0.0.1:33580, bytes: 58522, op: HDFS_READ, cliID: DFSClient_2046932554, srvID: DS-1287440467-127.0.1.1-58516-1267785019210, blockid: blk_8922059208167072865_1015 [junit] 10/03/05 10:30:58 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=open src=/tmp/hadoop-hudson/mapred/system/job_20100305103020175_0002/job.jar dst=null perm=null [junit] 10/03/05 10:30:58 WARN datanode.DataNode: DatanodeRegistration(127.0.0.1:33770, storageID=DS-491133707-127.0.1.1-33770-1267785020106, infoPort=45554, ipcPort=36753):Got exception while serving blk_-1529009670148243081_1013 to /127.0.0.1: [junit] java.io.IOException: Block blk_-1529009670148243081_1013 is not valid. [junit] at org.apache.hadoop.hdfs.server.datanode.FSDataset.getBlockFile(FSDataset.java:734) [junit] at org.apache.hadoop.hdfs.server.datanode.FSDataset.getLength(FSDataset.java:722) [junit] at org.apache.hadoop.hdfs.server.datanode.BlockSender.<init>(BlockSender.java:92) [junit] at org.apache.hadoop.hdfs.server.datanode.DataXceiver.readBlock(DataXceiver.java:172) [junit] at org.apache.hadoop.hdfs.server.datanode.DataXceiver.run(DataXceiver.java:95) [junit] at java.lang.Thread.run(Thread.java:619) [junit] [junit] 10/03/05 10:30:58 ERROR datanode.DataNode: DatanodeRegistration(127.0.0.1:33770, storageID=DS-491133707-127.0.1.1-33770-1267785020106, infoPort=45554, ipcPort=36753):DataXceiver [junit] java.io.IOException: Block blk_-1529009670148243081_1013 is not valid. [junit] at org.apache.hadoop.hdfs.server.datanode.FSDataset.getBlockFile(FSDataset.java:734) [junit] at org.apache.hadoop.hdfs.server.datanode.FSDataset.getLength(FSDataset.java:722) [junit] at org.apache.hadoop.hdfs.server.datanode.BlockSender.<init>(BlockSender.java:92) [junit] at org.apache.hadoop.hdfs.server.datanode.DataXceiver.readBlock(DataXceiver.java:172) [junit] at org.apache.hadoop.hdfs.server.datanode.DataXceiver.run(DataXceiver.java:95) [junit] at java.lang.Thread.run(Thread.java:619) [junit] 10/03/05 10:30:58 INFO DataNode.clienttrace: src: /127.0.0.1:58516, dest: /127.0.0.1:33582, bytes: 2896210, op: HDFS_READ, cliID: DFSClient_2046932554, srvID: DS-1287440467-127.0.1.1-58516-1267785019210, blockid: blk_-1529009670148243081_1013 [junit] 10/03/05 10:30:58 INFO mapred.TaskTracker: JVM with ID: jvm_20100305103020175_0002_m_-114262773 given task: attempt_20100305103020175_0002_m_000000_0 [junit] 10/03/05 10:30:58 INFO mapred.JvmManager: In JvmRunner constructed JVM ID: jvm_20100305103020175_0002_m_1714817586 [junit] 10/03/05 10:30:58 INFO mapred.JvmManager: JVM Runner jvm_20100305103020175_0002_m_1714817586 spawned. [junit] 10/03/05 10:30:58 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=create src=/tmp/temp-1043653422/tmp104689674/_temporary/_attempt_20100305103020175_0002_m_000000_0/part-m-00000 dst=null perm=hudson:supergroup:rw-r--r-- [junit] 10/03/05 10:30:58 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=open src=/user/hudson/input2.txt dst=null perm=null [junit] 10/03/05 10:30:58 INFO DataNode.clienttrace: src: /127.0.0.1:58516, dest: /127.0.0.1:33589, bytes: 10, op: HDFS_READ, cliID: DFSClient_attempt_20100305103020175_0002_m_000000_0, srvID: DS-1287440467-127.0.1.1-58516-1267785019210, blockid: blk_-5021661588842686831_1012 [junit] 10/03/05 10:30:58 INFO hdfs.StateChange: BLOCK* NameSystem.allocateBlock: /tmp/temp-1043653422/tmp104689674/_temporary/_attempt_20100305103020175_0002_m_000000_0/part-m-00000. blk_-615181305430692441_1018 [junit] 10/03/05 10:30:58 INFO mapred.TaskTracker: JVM with ID: jvm_20100305103020175_0002_m_1714817586 given task: attempt_20100305103020175_0002_m_000001_0 [junit] 10/03/05 10:30:58 INFO datanode.DataNode: Receiving block blk_-615181305430692441_1018 src: /127.0.0.1:53134 dest: /127.0.0.1:33770 [junit] 10/03/05 10:30:58 INFO datanode.DataNode: Receiving block blk_-615181305430692441_1018 src: /127.0.0.1:41874 dest: /127.0.0.1:51932 [junit] 10/03/05 10:30:58 INFO datanode.DataNode: Receiving block blk_-615181305430692441_1018 src: /127.0.0.1:33595 dest: /127.0.0.1:58516 [junit] 10/03/05 10:30:58 INFO DataNode.clienttrace: src: /127.0.0.1:33595, dest: /127.0.0.1:58516, bytes: 39, op: HDFS_WRITE, cliID: DFSClient_attempt_20100305103020175_0002_m_000000_0, srvID: DS-1287440467-127.0.1.1-58516-1267785019210, blockid: blk_-615181305430692441_1018 [junit] 10/03/05 10:30:58 INFO datanode.DataNode: PacketResponder 0 for block blk_-615181305430692441_1018 terminating [junit] 10/03/05 10:30:58 INFO hdfs.StateChange: BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:58516 is added to blk_-615181305430692441_1018 size 39 [junit] 10/03/05 10:30:58 INFO DataNode.clienttrace: src: /127.0.0.1:41874, dest: /127.0.0.1:51932, bytes: 39, op: HDFS_WRITE, cliID: DFSClient_attempt_20100305103020175_0002_m_000000_0, srvID: DS-1555557361-127.0.1.1-51932-1267785019661, blockid: blk_-615181305430692441_1018 [junit] 10/03/05 10:30:58 INFO hdfs.StateChange: BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:51932 is added to blk_-615181305430692441_1018 size 39 [junit] 10/03/05 10:30:58 INFO datanode.DataNode: PacketResponder 1 for block blk_-615181305430692441_1018 terminating [junit] 10/03/05 10:30:58 INFO DataNode.clienttrace: src: /127.0.0.1:53134, dest: /127.0.0.1:33770, bytes: 39, op: HDFS_WRITE, cliID: DFSClient_attempt_20100305103020175_0002_m_000000_0, srvID: DS-491133707-127.0.1.1-33770-1267785020106, blockid: blk_-615181305430692441_1018 [junit] 10/03/05 10:30:58 INFO datanode.DataNode: PacketResponder 2 for block blk_-615181305430692441_1018 terminating [junit] 10/03/05 10:30:58 INFO hdfs.StateChange: DIR* NameSystem.completeFile: file /tmp/temp-1043653422/tmp104689674/_temporary/_attempt_20100305103020175_0002_m_000000_0/part-m-00000 is closed by DFSClient_attempt_20100305103020175_0002_m_000000_0 [junit] 10/03/05 10:30:58 INFO hdfs.StateChange: BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:33770 is added to blk_-615181305430692441_1018 size 39 [junit] 10/03/05 10:30:58 INFO mapred.TaskTracker: Task attempt_20100305103020175_0002_m_000000_0 is in commit-pending, task state:COMMIT_PENDING [junit] 10/03/05 10:30:58 INFO mapred.TaskTracker: attempt_20100305103020175_0002_m_000000_0 0.0% [junit] 10/03/05 10:30:59 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=create src=/tmp/temp-1043653422/tmp104689674/_temporary/_attempt_20100305103020175_0002_m_000001_0/part-m-00001 dst=null perm=hudson:supergroup:rw-r--r-- [junit] 10/03/05 10:30:59 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=open src=/user/hudson/input1.txt dst=null perm=null [junit] 10/03/05 10:30:59 INFO DataNode.clienttrace: src: /127.0.0.1:58516, dest: /127.0.0.1:33599, bytes: 10, op: HDFS_READ, cliID: DFSClient_attempt_20100305103020175_0002_m_000001_0, srvID: DS-1287440467-127.0.1.1-58516-1267785019210, blockid: blk_1929344944928778140_1011 [junit] 10/03/05 10:30:59 INFO hdfs.StateChange: BLOCK* NameSystem.allocateBlock: /tmp/temp-1043653422/tmp104689674/_temporary/_attempt_20100305103020175_0002_m_000001_0/part-m-00001. blk_4400601892211468347_1019 [junit] 10/03/05 10:30:59 INFO datanode.DataNode: Receiving block blk_4400601892211468347_1019 src: /127.0.0.1:53142 dest: /127.0.0.1:33770 [junit] 10/03/05 10:30:59 INFO datanode.DataNode: Receiving block blk_4400601892211468347_1019 src: /127.0.0.1:41881 dest: /127.0.0.1:51932 [junit] 10/03/05 10:30:59 INFO datanode.DataNode: Receiving block blk_4400601892211468347_1019 src: /127.0.0.1:52317 dest: /127.0.0.1:50414 [junit] 10/03/05 10:30:59 INFO DataNode.clienttrace: src: /127.0.0.1:52317, dest: /127.0.0.1:50414, bytes: 39, op: HDFS_WRITE, cliID: DFSClient_attempt_20100305103020175_0002_m_000001_0, srvID: DS-152705402-127.0.1.1-50414-1267785018720, blockid: blk_4400601892211468347_1019 [junit] 10/03/05 10:30:59 INFO datanode.DataNode: PacketResponder 0 for block blk_4400601892211468347_1019 terminating [junit] 10/03/05 10:30:59 INFO hdfs.StateChange: BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:50414 is added to blk_4400601892211468347_1019 size 39 [junit] 10/03/05 10:30:59 INFO DataNode.clienttrace: src: /127.0.0.1:41881, dest: /127.0.0.1:51932, bytes: 39, op: HDFS_WRITE, cliID: DFSClient_attempt_20100305103020175_0002_m_000001_0, srvID: DS-1555557361-127.0.1.1-51932-1267785019661, blockid: blk_4400601892211468347_1019 [junit] 10/03/05 10:30:59 INFO datanode.DataNode: PacketResponder 1 for block blk_4400601892211468347_1019 terminating [junit] 10/03/05 10:30:59 INFO hdfs.StateChange: BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:51932 is added to blk_4400601892211468347_1019 size 39 [junit] 10/03/05 10:30:59 INFO DataNode.clienttrace: src: /127.0.0.1:53142, dest: /127.0.0.1:33770, bytes: 39, op: HDFS_WRITE, cliID: DFSClient_attempt_20100305103020175_0002_m_000001_0, srvID: DS-491133707-127.0.1.1-33770-1267785020106, blockid: blk_4400601892211468347_1019 [junit] 10/03/05 10:30:59 INFO datanode.DataNode: PacketResponder 2 for block blk_4400601892211468347_1019 terminating [junit] 10/03/05 10:30:59 INFO hdfs.StateChange: BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:33770 is added to blk_4400601892211468347_1019 size 39 [junit] 10/03/05 10:30:59 INFO hdfs.StateChange: DIR* NameSystem.completeFile: file /tmp/temp-1043653422/tmp104689674/_temporary/_attempt_20100305103020175_0002_m_000001_0/part-m-00001 is closed by DFSClient_attempt_20100305103020175_0002_m_000001_0 [junit] 10/03/05 10:30:59 INFO mapred.TaskTracker: Task attempt_20100305103020175_0002_m_000001_0 is in commit-pending, task state:COMMIT_PENDING [junit] 10/03/05 10:30:59 INFO mapred.TaskTracker: attempt_20100305103020175_0002_m_000001_0 0.0% [junit] 10/03/05 10:31:00 INFO mapred.TaskTracker: Received commit task action for attempt_20100305103020175_0002_m_000000_0 [junit] 10/03/05 10:31:00 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=listStatus src=/tmp/temp-1043653422/tmp104689674/_temporary/_attempt_20100305103020175_0002_m_000000_0 dst=null perm=null [junit] 10/03/05 10:31:00 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=mkdirs src=/tmp/temp-1043653422/tmp104689674 dst=null perm=hudson:supergroup:rwxr-xr-x [junit] 10/03/05 10:31:00 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=rename src=/tmp/temp-1043653422/tmp104689674/_temporary/_attempt_20100305103020175_0002_m_000000_0/part-m-00000 dst=/tmp/temp-1043653422/tmp104689674/part-m-00000 perm=hudson:supergroup:rw-r--r-- [junit] 10/03/05 10:31:00 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=delete src=/tmp/temp-1043653422/tmp104689674/_temporary/_attempt_20100305103020175_0002_m_000000_0 dst=null perm=null [junit] 10/03/05 10:31:00 INFO mapred.TaskTracker: attempt_20100305103020175_0002_m_000000_0 1.0% [junit] 10/03/05 10:31:00 INFO mapred.TaskTracker: Task attempt_20100305103020175_0002_m_000000_0 is done. [junit] 10/03/05 10:31:00 INFO mapred.TaskTracker: reported output size for attempt_20100305103020175_0002_m_000000_0 was 0 [junit] 10/03/05 10:31:00 INFO mapred.TaskTracker: addFreeSlot : current free slots : 2 [junit] 10/03/05 10:31:00 INFO mapred.TaskTracker: Received commit task action for attempt_20100305103020175_0002_m_000001_0 [junit] 10/03/05 10:31:01 INFO mapred.JvmManager: JVM : jvm_20100305103020175_0002_m_-114262773 exited. Number of tasks it ran: 1 [junit] 10/03/05 10:31:01 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=listStatus src=/tmp/temp-1043653422/tmp104689674/_temporary/_attempt_20100305103020175_0002_m_000001_0 dst=null perm=null [junit] 10/03/05 10:31:01 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=mkdirs src=/tmp/temp-1043653422/tmp104689674 dst=null perm=hudson:supergroup:rwxr-xr-x [junit] 10/03/05 10:31:01 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=rename src=/tmp/temp-1043653422/tmp104689674/_temporary/_attempt_20100305103020175_0002_m_000001_0/part-m-00001 dst=/tmp/temp-1043653422/tmp104689674/part-m-00001 perm=hudson:supergroup:rw-r--r-- [junit] 10/03/05 10:31:01 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=delete src=/tmp/temp-1043653422/tmp104689674/_temporary/_attempt_20100305103020175_0002_m_000001_0 dst=null perm=null [junit] 10/03/05 10:31:01 INFO mapred.TaskTracker: attempt_20100305103020175_0002_m_000001_0 1.0% [junit] 10/03/05 10:31:01 INFO mapred.TaskTracker: Task attempt_20100305103020175_0002_m_000001_0 is done. [junit] 10/03/05 10:31:01 INFO mapred.TaskTracker: reported output size for attempt_20100305103020175_0002_m_000001_0 was 0 [junit] 10/03/05 10:31:01 INFO mapred.TaskTracker: addFreeSlot : current free slots : 2 [junit] 10/03/05 10:31:01 INFO mapred.JvmManager: JVM : jvm_20100305103020175_0002_m_1714817586 exited. Number of tasks it ran: 1 [junit] 10/03/05 10:31:03 INFO mapred.TaskTracker: org.apache.hadoop.util.DiskChecker$DiskErrorException: Could not find taskTracker/jobcache/job_20100305103020175_0002/attempt_20100305103020175_0002_m_000000_0/output/file.out in any of the configured local directories [junit] 10/03/05 10:31:03 INFO mapred.JobInProgress: Task 'attempt_20100305103020175_0002_m_000000_0' has completed task_20100305103020175_0002_m_000000 successfully. [junit] 10/03/05 10:31:03 INFO mapReduceLayer.MapReduceLauncher: 25% complete [junit] 10/03/05 10:31:03 INFO mapred.TaskTracker: org.apache.hadoop.util.DiskChecker$DiskErrorException: Could not find taskTracker/jobcache/job_20100305103020175_0002/attempt_20100305103020175_0002_m_000001_0/output/file.out in any of the configured local directories [junit] 10/03/05 10:31:03 INFO mapred.JobInProgress: Task 'attempt_20100305103020175_0002_m_000001_0' has completed task_20100305103020175_0002_m_000001 successfully. [junit] 10/03/05 10:31:03 INFO mapred.JobTracker: Adding task 'attempt_20100305103020175_0002_m_000002_0' to tip task_20100305103020175_0002_m_000002, for tracker 'tracker_host1.foo.com:localhost/127.0.0.1:33449' [junit] 10/03/05 10:31:03 INFO mapred.TaskTracker: LaunchTaskAction (registerTask): attempt_20100305103020175_0002_m_000002_0 task's state:UNASSIGNED [junit] 10/03/05 10:31:03 INFO mapred.TaskTracker: Trying to launch : attempt_20100305103020175_0002_m_000002_0 [junit] 10/03/05 10:31:03 INFO mapred.TaskTracker: In TaskLauncher, current free slots : 2 and trying to launch attempt_20100305103020175_0002_m_000002_0 [junit] 10/03/05 10:31:04 INFO mapred.JvmManager: In JvmRunner constructed JVM ID: jvm_20100305103020175_0002_m_-815817503 [junit] 10/03/05 10:31:04 INFO mapred.JvmManager: JVM Runner jvm_20100305103020175_0002_m_-815817503 spawned. [junit] 10/03/05 10:31:04 INFO mapReduceLayer.MapReduceLauncher: 50% complete [junit] 10/03/05 10:31:04 INFO mapred.TaskTracker: JVM with ID: jvm_20100305103020175_0002_m_-815817503 given task: attempt_20100305103020175_0002_m_000002_0 [junit] 10/03/05 10:31:05 INFO mapred.TaskTracker: attempt_20100305103020175_0002_m_000002_0 0.0% [junit] 10/03/05 10:31:05 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=delete src=/tmp/temp-1043653422/tmp104689674/_temporary dst=null perm=null [junit] 10/03/05 10:31:05 INFO mapred.TaskTracker: attempt_20100305103020175_0002_m_000002_0 0.0% cleanup [junit] 10/03/05 10:31:05 INFO mapred.TaskTracker: Task attempt_20100305103020175_0002_m_000002_0 is done. [junit] 10/03/05 10:31:05 INFO mapred.TaskTracker: reported output size for attempt_20100305103020175_0002_m_000002_0 was 0 [junit] 10/03/05 10:31:05 INFO mapred.TaskTracker: addFreeSlot : current free slots : 2 [junit] 10/03/05 10:31:05 INFO mapred.JvmManager: JVM : jvm_20100305103020175_0002_m_-815817503 exited. Number of tasks it ran: 1 [junit] 10/03/05 10:31:06 INFO mapred.TaskTracker: org.apache.hadoop.util.DiskChecker$DiskErrorException: Could not find taskTracker/jobcache/job_20100305103020175_0002/attempt_20100305103020175_0002_m_000002_0/output/file.out in any of the configured local directories [junit] 10/03/05 10:31:06 INFO mapred.JobInProgress: Task 'attempt_20100305103020175_0002_m_000002_0' has completed task_20100305103020175_0002_m_000002 successfully. [junit] 10/03/05 10:31:06 INFO mapred.JobInProgress: Job job_20100305103020175_0002 has completed successfully. [junit] 10/03/05 10:31:06 INFO hdfs.StateChange: BLOCK* NameSystem.allocateBlock: /tmp/temp-1043653422/tmp104689674/_logs/history/localhost_1267785020198_job_20100305103020175_0002_hudson_Job3600321352221509795.jar. blk_-5521314130069770308_1019 [junit] 10/03/05 10:31:06 INFO datanode.DataNode: Receiving block blk_-5521314130069770308_1019 src: /127.0.0.1:33609 dest: /127.0.0.1:58516 [junit] 10/03/05 10:31:06 INFO datanode.DataNode: Receiving block blk_-5521314130069770308_1019 src: /127.0.0.1:53152 dest: /127.0.0.1:33770 [junit] 10/03/05 10:31:06 INFO datanode.DataNode: Receiving block blk_-5521314130069770308_1019 src: /127.0.0.1:41891 dest: /127.0.0.1:51932 [junit] 10/03/05 10:31:07 INFO DataNode.clienttrace: src: /127.0.0.1:41891, dest: /127.0.0.1:51932, bytes: 5856, op: HDFS_WRITE, cliID: DFSClient_2046932554, srvID: DS-1555557361-127.0.1.1-51932-1267785019661, blockid: blk_-5521314130069770308_1019 [junit] 10/03/05 10:31:07 INFO datanode.DataNode: PacketResponder 0 for block blk_-5521314130069770308_1019 terminating [junit] 10/03/05 10:31:07 INFO hdfs.StateChange: BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:51932 is added to blk_-5521314130069770308_1019 size 5856 [junit] 10/03/05 10:31:07 INFO DataNode.clienttrace: src: /127.0.0.1:53152, dest: /127.0.0.1:33770, bytes: 5856, op: HDFS_WRITE, cliID: DFSClient_2046932554, srvID: DS-491133707-127.0.1.1-33770-1267785020106, blockid: blk_-5521314130069770308_1019 [junit] 10/03/05 10:31:07 INFO hdfs.StateChange: BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:33770 is added to blk_-5521314130069770308_1019 size 5856 [junit] 10/03/05 10:31:07 INFO DataNode.clienttrace: src: /127.0.0.1:33609, dest: /127.0.0.1:58516, bytes: 5856, op: HDFS_WRITE, cliID: DFSClient_2046932554, srvID: DS-1287440467-127.0.1.1-58516-1267785019210, blockid: blk_-5521314130069770308_1019 [junit] 10/03/05 10:31:07 INFO datanode.DataNode: PacketResponder 2 for block blk_-5521314130069770308_1019 terminating [junit] 10/03/05 10:31:07 INFO hdfs.StateChange: BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:58516 is added to blk_-5521314130069770308_1019 size 5856 [junit] 10/03/05 10:31:07 INFO datanode.DataNode: PacketResponder 1 for block blk_-5521314130069770308_1019 terminating [junit] 10/03/05 10:31:07 INFO hdfs.StateChange: DIR* NameSystem.completeFile: file /tmp/temp-1043653422/tmp104689674/_logs/history/localhost_1267785020198_job_20100305103020175_0002_hudson_Job3600321352221509795.jar is closed by DFSClient_2046932554 [junit] 10/03/05 10:31:07 INFO mapred.JobTracker: Removed completed task 'attempt_20100305103020175_0002_m_000001_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:33449' [junit] 10/03/05 10:31:07 INFO mapred.JobTracker: Removed completed task 'attempt_20100305103020175_0002_m_000002_0' from 'tracker_host1.foo.com:localhost/127.0.0.1:33449' [junit] 10/03/05 10:31:07 INFO hdfs.StateChange: BLOCK* NameSystem.addToInvalidates: blk_-1529009670148243081 is added to invalidSet of 127.0.0.1:58516 [junit] 10/03/05 10:31:07 INFO hdfs.StateChange: BLOCK* NameSystem.addToInvalidates: blk_-1529009670148243081 is added to invalidSet of 127.0.0.1:33770 [junit] 10/03/05 10:31:07 INFO hdfs.StateChange: BLOCK* NameSystem.addToInvalidates: blk_-1529009670148243081 is added to invalidSet of 127.0.0.1:51932 [junit] 10/03/05 10:31:07 INFO hdfs.StateChange: BLOCK* NameSystem.addToInvalidates: blk_2163684875822531003 is added to invalidSet of 127.0.0.1:50414 [junit] 10/03/05 10:31:07 INFO hdfs.StateChange: BLOCK* NameSystem.addToInvalidates: blk_2163684875822531003 is added to invalidSet of 127.0.0.1:51932 [junit] 10/03/05 10:31:07 INFO hdfs.StateChange: BLOCK* NameSystem.addToInvalidates: blk_2163684875822531003 is added to invalidSet of 127.0.0.1:33770 [junit] 10/03/05 10:31:07 INFO mapred.TaskTracker: Received 'KillJobAction' for job: job_20100305103020175_0002 [junit] 10/03/05 10:31:07 INFO mapred.TaskRunner: attempt_20100305103020175_0002_m_000002_0 done; removing files. [junit] 10/03/05 10:31:07 INFO hdfs.StateChange: BLOCK* NameSystem.addToInvalidates: blk_8922059208167072865 is added to invalidSet of 127.0.0.1:50414 [junit] 10/03/05 10:31:07 INFO hdfs.StateChange: BLOCK* NameSystem.addToInvalidates: blk_8922059208167072865 is added to invalidSet of 127.0.0.1:58516 [junit] 10/03/05 10:31:07 INFO hdfs.StateChange: BLOCK* NameSystem.addToInvalidates: blk_8922059208167072865 is added to invalidSet of 127.0.0.1:33770 [junit] 10/03/05 10:31:07 INFO mapred.IndexCache: Map ID attempt_20100305103020175_0002_m_000002_0 not found in cache [junit] 10/03/05 10:31:07 INFO mapred.TaskRunner: attempt_20100305103020175_0002_m_000001_0 done; removing files. [junit] 10/03/05 10:31:07 INFO mapred.IndexCache: Map ID attempt_20100305103020175_0002_m_000001_0 not found in cache [junit] 10/03/05 10:31:07 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=delete src=/tmp/hadoop-hudson/mapred/system/job_20100305103020175_0002 dst=null perm=null [junit] 10/03/05 10:31:07 INFO mapred.TaskTracker: Received 'KillJobAction' for job: job_20100305103020175_0002 [junit] 10/03/05 10:31:07 WARN mapred.TaskTracker: Unknown job job_20100305103020175_0002 being deleted. [junit] 10/03/05 10:31:07 INFO mapred.TaskTracker: Received 'KillJobAction' for job: job_20100305103020175_0002 [junit] 10/03/05 10:31:07 WARN mapred.TaskTracker: Unknown job job_20100305103020175_0002 being deleted. [junit] 10/03/05 10:31:07 INFO mapReduceLayer.MapReduceLauncher: 100% complete [junit] 10/03/05 10:31:07 INFO mapReduceLayer.MapReduceLauncher: Successfully stored result in: "hdfs://localhost:38256/tmp/temp-1043653422/tmp104689674" [junit] 10/03/05 10:31:07 INFO mapReduceLayer.MapReduceLauncher: Records written : 0 [junit] 10/03/05 10:31:07 INFO mapReduceLayer.MapReduceLauncher: Bytes written : 78 [junit] 10/03/05 10:31:07 INFO mapReduceLayer.MapReduceLauncher: Success! [junit] 10/03/05 10:31:07 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=listStatus src=/tmp/temp-1043653422/tmp104689674 dst=null perm=null [junit] 10/03/05 10:31:07 INFO input.FileInputFormat: Total input paths to process : 2 [junit] 10/03/05 10:31:07 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=open src=/tmp/temp-1043653422/tmp104689674/part-m-00000 dst=null perm=null [junit] 10/03/05 10:31:07 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=open src=/tmp/temp-1043653422/tmp104689674/part-m-00001 dst=null perm=null [junit] 10/03/05 10:31:07 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=open src=/tmp/temp-1043653422/tmp104689674/part-m-00000 dst=null perm=null [junit] 10/03/05 10:31:07 INFO DataNode.clienttrace: src: /127.0.0.1:58516, dest: /127.0.0.1:33613, bytes: 43, op: HDFS_READ, cliID: DFSClient_2046932554, srvID: DS-1287440467-127.0.1.1-58516-1267785019210, blockid: blk_-615181305430692441_1018 [junit] 10/03/05 10:31:07 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=open src=/tmp/temp-1043653422/tmp104689674/part-m-00001 dst=null perm=null [junit] 10/03/05 10:31:07 INFO DataNode.clienttrace: src: /127.0.0.1:33770, dest: /127.0.0.1:53156, bytes: 43, op: HDFS_READ, cliID: DFSClient_2046932554, srvID: DS-491133707-127.0.1.1-33770-1267785020106, blockid: blk_4400601892211468347_1019 [junit] Tests run: 3, Failures: 0, Errors: 0, Time elapsed: 45.012 sec BUILD FAILED <http://hudson.zones.apache.org/hudson/job/Pig-trunk/ws/trunk/build.xml>:558: The following error occurred while executing this line: <http://hudson.zones.apache.org/hudson/job/Pig-trunk/ws/trunk/build.xml>:491: The following error occurred while executing this line: <http://hudson.zones.apache.org/hudson/job/Pig-trunk/ws/trunk/build.xml>:553: Tests failed! Total time: 273 minutes 11 seconds Publishing Javadoc Archiving artifacts Recording test results Recording fingerprints Publishing Clover coverage report... No Clover report will be published due to a Build Failure