See <http://hudson.zones.apache.org/hudson/job/Pig-trunk/687/changes>
Changes: [olga] PIG-1241: Accumulator is turned on when a map is used with a non-accumulative UDF (yinghe vi olgan) [olga] PIG-1233: NullPointerException in AVG (ankur via olgan) [pradeepkth] PIG-1218: Use distributed cache to store samples (rding via pradeepkth) [pradeepkth] Removing Slice and Slicer interfaces since they are no longer supported [hashutosh] PIG-1215: Make Hadoop jobId more prominent in the client log [pradeepkth] Merging from load-store-redesign branch to trunk - svn merge http://svn.apache.org/repos/asf/hadoop/pig/tr...@911219 http://svn.apache.org/repos/asf/hadoop/pig/branches/load-store-redes...@911616 ------------------------------------------ [...truncated 251609 lines...] [junit] 10/02/20 14:44:24 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=open src=/tmp/hadoop-hudson/mapred/system/job_20100220144352392_0002/job.jar dst=null perm=null [junit] 10/02/20 14:44:24 INFO DataNode.clienttrace: src: /127.0.0.1:34571, dest: /127.0.0.1:36757, bytes: 2912139, op: HDFS_READ, cliID: DFSClient_-1202820087, srvID: DS-1357221106-127.0.1.1-34571-1266677032320, blockid: blk_-6363216028128685971_1013 [junit] 10/02/20 14:44:24 INFO mapred.JobTracker: Initializing job_20100220144352392_0002 [junit] 10/02/20 14:44:24 INFO mapred.JobInProgress: Initializing job_20100220144352392_0002 [junit] 10/02/20 14:44:24 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=create src=/tmp/temp-1218509902/tmp109332646/_logs/history/localhost_1266677032416_job_20100220144352392_0002_hudson_Job7930732126387436403.jar dst=null perm=hudson:supergroup:rw-r--r-- [junit] 10/02/20 14:44:24 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=create src=/tmp/temp-1218509902/tmp109332646/_logs/history/localhost_1266677032416_job_20100220144352392_0002_conf.xml dst=null perm=hudson:supergroup:rw-r--r-- [junit] 10/02/20 14:44:24 INFO hdfs.StateChange: BLOCK* NameSystem.allocateBlock: /tmp/temp-1218509902/tmp109332646/_logs/history/localhost_1266677032416_job_20100220144352392_0002_conf.xml. blk_-2544111882243384134_1017 [junit] 10/02/20 14:44:24 INFO datanode.DataNode: Receiving block blk_-2544111882243384134_1017 src: /127.0.0.1:36758 dest: /127.0.0.1:34571 [junit] 10/02/20 14:44:24 INFO datanode.DataNode: Receiving block blk_-2544111882243384134_1017 src: /127.0.0.1:60882 dest: /127.0.0.1:57834 [junit] 10/02/20 14:44:24 INFO datanode.DataNode: Receiving block blk_-2544111882243384134_1017 src: /127.0.0.1:33383 dest: /127.0.0.1:49052 [junit] 10/02/20 14:44:24 INFO DataNode.clienttrace: src: /127.0.0.1:33383, dest: /127.0.0.1:49052, bytes: 58176, op: HDFS_WRITE, cliID: DFSClient_-1202820087, srvID: DS-980906310-127.0.1.1-49052-1266677030846, blockid: blk_-2544111882243384134_1017 [junit] 10/02/20 14:44:24 INFO datanode.DataNode: PacketResponder 0 for block blk_-2544111882243384134_1017 terminating [junit] 10/02/20 14:44:24 INFO hdfs.StateChange: BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:49052 is added to blk_-2544111882243384134_1017 size 58176 [junit] 10/02/20 14:44:24 INFO DataNode.clienttrace: src: /127.0.0.1:60882, dest: /127.0.0.1:57834, bytes: 58176, op: HDFS_WRITE, cliID: DFSClient_-1202820087, srvID: DS-955997914-127.0.1.1-57834-1266677031360, blockid: blk_-2544111882243384134_1017 [junit] 10/02/20 14:44:24 INFO datanode.DataNode: PacketResponder 1 for block blk_-2544111882243384134_1017 terminating [junit] 10/02/20 14:44:24 INFO hdfs.StateChange: BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:57834 is added to blk_-2544111882243384134_1017 size 58176 [junit] 10/02/20 14:44:24 INFO DataNode.clienttrace: src: /127.0.0.1:36758, dest: /127.0.0.1:34571, bytes: 58176, op: HDFS_WRITE, cliID: DFSClient_-1202820087, srvID: DS-1357221106-127.0.1.1-34571-1266677032320, blockid: blk_-2544111882243384134_1017 [junit] 10/02/20 14:44:24 INFO hdfs.StateChange: BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:34571 is added to blk_-2544111882243384134_1017 size 58176 [junit] 10/02/20 14:44:24 INFO datanode.DataNode: PacketResponder 2 for block blk_-2544111882243384134_1017 terminating [junit] 10/02/20 14:44:24 INFO hdfs.StateChange: DIR* NameSystem.completeFile: file /tmp/temp-1218509902/tmp109332646/_logs/history/localhost_1266677032416_job_20100220144352392_0002_conf.xml is closed by DFSClient_-1202820087 [junit] 10/02/20 14:44:24 INFO mapReduceLayer.MapReduceLauncher: HadoopJobId: job_20100220144352392_0002 [junit] 10/02/20 14:44:24 INFO mapReduceLayer.MapReduceLauncher: More information at: http://localhost:57171/jobdetails.jsp?jobid=job_20100220144352392_0002 [junit] 10/02/20 14:44:24 INFO mapReduceLayer.MapReduceLauncher: 0% complete [junit] 10/02/20 14:44:24 INFO datanode.DataNode: Deleting block blk_-2629102099995670775_1007 file build/test/data/dfs/data/data6/current/blk_-2629102099995670775 [junit] 10/02/20 14:44:24 INFO datanode.DataNode: Deleting block blk_-1014759069321846640_1006 file build/test/data/dfs/data/data5/current/blk_-1014759069321846640 [junit] 10/02/20 14:44:24 INFO hdfs.StateChange: BLOCK* ask 127.0.0.1:34571 to delete blk_-6363216028128685971_1013 [junit] 10/02/20 14:44:24 INFO hdfs.StateChange: BLOCK* ask 127.0.0.1:57834 to delete blk_-2629102099995670775_1007 blk_-9183596196974332335_1005 [junit] 10/02/20 14:44:24 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=open src=/tmp/hadoop-hudson/mapred/system/job_20100220144352392_0002/job.split dst=null perm=null [junit] 10/02/20 14:44:24 INFO DataNode.clienttrace: src: /127.0.0.1:57834, dest: /127.0.0.1:60884, bytes: 871, op: HDFS_READ, cliID: DFSClient_-1202820087, srvID: DS-955997914-127.0.1.1-57834-1266677031360, blockid: blk_740199783892902868_1014 [junit] 10/02/20 14:44:24 INFO mapred.JobInProgress: Input size for job job_20100220144352392_0002 = 12. Number of splits = 2 [junit] 10/02/20 14:44:24 INFO mapred.JobInProgress: tip:task_20100220144352392_0002_m_000000 has split on node:/default-rack/h7.grid.sp2.yahoo.net [junit] 10/02/20 14:44:24 INFO mapred.JobInProgress: tip:task_20100220144352392_0002_m_000000 has split on node:/default-rack/h7.grid.sp2.yahoo.net [junit] 10/02/20 14:44:24 INFO mapred.JobInProgress: tip:task_20100220144352392_0002_m_000000 has split on node:/default-rack/h7.grid.sp2.yahoo.net [junit] 10/02/20 14:44:24 INFO mapred.JobInProgress: tip:task_20100220144352392_0002_m_000001 has split on node:/default-rack/h7.grid.sp2.yahoo.net [junit] 10/02/20 14:44:24 INFO mapred.JobInProgress: tip:task_20100220144352392_0002_m_000001 has split on node:/default-rack/h7.grid.sp2.yahoo.net [junit] 10/02/20 14:44:24 INFO mapred.JobInProgress: tip:task_20100220144352392_0002_m_000001 has split on node:/default-rack/h7.grid.sp2.yahoo.net [junit] 10/02/20 14:44:25 INFO mapred.JobTracker: Adding task 'attempt_20100220144352392_0002_m_000003_0' to tip task_20100220144352392_0002_m_000003, for tracker 'tracker_host3.foo.com:localhost/127.0.0.1:52483' [junit] 10/02/20 14:44:25 INFO mapred.TaskTracker: LaunchTaskAction (registerTask): attempt_20100220144352392_0002_m_000003_0 task's state:UNASSIGNED [junit] 10/02/20 14:44:25 INFO mapred.TaskTracker: Trying to launch : attempt_20100220144352392_0002_m_000003_0 [junit] 10/02/20 14:44:25 INFO mapred.TaskTracker: In TaskLauncher, current free slots : 2 and trying to launch attempt_20100220144352392_0002_m_000003_0 [junit] 10/02/20 14:44:25 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=open src=/tmp/hadoop-hudson/mapred/system/job_20100220144352392_0002/job.xml dst=null perm=null [junit] 10/02/20 14:44:25 INFO DataNode.clienttrace: src: /127.0.0.1:34571, dest: /127.0.0.1:36762, bytes: 58665, op: HDFS_READ, cliID: DFSClient_-1202820087, srvID: DS-1357221106-127.0.1.1-34571-1266677032320, blockid: blk_-2243838457939614304_1015 [junit] 10/02/20 14:44:25 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=open src=/tmp/hadoop-hudson/mapred/system/job_20100220144352392_0002/job.jar dst=null perm=null [junit] 10/02/20 14:44:25 INFO DataNode.clienttrace: src: /127.0.0.1:34571, dest: /127.0.0.1:36763, bytes: 2912139, op: HDFS_READ, cliID: DFSClient_-1202820087, srvID: DS-1357221106-127.0.1.1-34571-1266677032320, blockid: blk_-6363216028128685971_1013 [junit] 10/02/20 14:44:25 INFO datanode.DataNode: Deleting block blk_-6363216028128685971_1013 file build/test/data/dfs/data/data7/current/blk_-6363216028128685971 [junit] 10/02/20 14:44:25 INFO mapred.JvmManager: In JvmRunner constructed JVM ID: jvm_20100220144352392_0002_m_321520700 [junit] 10/02/20 14:44:25 INFO mapred.JvmManager: JVM Runner jvm_20100220144352392_0002_m_321520700 spawned. [junit] 10/02/20 14:44:25 INFO mapred.TaskTracker: JVM with ID: jvm_20100220144352392_0002_m_321520700 given task: attempt_20100220144352392_0002_m_000003_0 [junit] 10/02/20 14:44:26 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=mkdirs src=/tmp/temp-1218509902/tmp109332646/_temporary dst=null perm=hudson:supergroup:rwxr-xr-x [junit] 10/02/20 14:44:26 INFO mapred.TaskTracker: attempt_20100220144352392_0002_m_000003_0 0.0% setup [junit] 10/02/20 14:44:26 INFO mapred.TaskTracker: Task attempt_20100220144352392_0002_m_000003_0 is done. [junit] 10/02/20 14:44:26 INFO mapred.TaskTracker: reported output size for attempt_20100220144352392_0002_m_000003_0 was 0 [junit] 10/02/20 14:44:26 INFO mapred.TaskTracker: addFreeSlot : current free slots : 2 [junit] 10/02/20 14:44:26 INFO mapred.JvmManager: JVM : jvm_20100220144352392_0002_m_321520700 exited. Number of tasks it ran: 1 [junit] 10/02/20 14:44:27 INFO datanode.DataNode: Deleting block blk_-9183596196974332335_1005 file build/test/data/dfs/data/data3/current/blk_-9183596196974332335 [junit] 10/02/20 14:44:27 INFO datanode.DataNode: Deleting block blk_-2629102099995670775_1007 file build/test/data/dfs/data/data4/current/blk_-2629102099995670775 [junit] 10/02/20 14:44:27 INFO hdfs.StateChange: BLOCK* ask 127.0.0.1:49052 to delete blk_-1014759069321846640_1006 blk_-2629102099995670775_1007 blk_-9183596196974332335_1005 [junit] 10/02/20 14:44:28 INFO mapred.TaskTracker: org.apache.hadoop.util.DiskChecker$DiskErrorException: Could not find taskTracker/jobcache/job_20100220144352392_0002/attempt_20100220144352392_0002_m_000003_0/output/file.out in any of the configured local directories [junit] 10/02/20 14:44:28 INFO mapred.JobInProgress: Task 'attempt_20100220144352392_0002_m_000003_0' has completed task_20100220144352392_0002_m_000003 successfully. [junit] 10/02/20 14:44:28 INFO mapred.JobTracker: Adding task 'attempt_20100220144352392_0002_m_000000_0' to tip task_20100220144352392_0002_m_000000, for tracker 'tracker_host3.foo.com:localhost/127.0.0.1:52483' [junit] 10/02/20 14:44:28 INFO mapred.JobInProgress: Choosing rack-local task task_20100220144352392_0002_m_000000 [junit] 10/02/20 14:44:28 INFO mapred.TaskTracker: LaunchTaskAction (registerTask): attempt_20100220144352392_0002_m_000000_0 task's state:UNASSIGNED [junit] 10/02/20 14:44:28 INFO mapred.TaskTracker: Trying to launch : attempt_20100220144352392_0002_m_000000_0 [junit] 10/02/20 14:44:28 INFO mapred.TaskTracker: Received KillTaskAction for task: attempt_20100220144352392_0002_m_000003_0 [junit] 10/02/20 14:44:28 INFO mapred.TaskTracker: About to purge task: attempt_20100220144352392_0002_m_000003_0 [junit] 10/02/20 14:44:28 INFO mapred.TaskTracker: In TaskLauncher, current free slots : 2 and trying to launch attempt_20100220144352392_0002_m_000000_0 [junit] 10/02/20 14:44:28 INFO mapred.TaskRunner: attempt_20100220144352392_0002_m_000003_0 done; removing files. [junit] 10/02/20 14:44:28 INFO mapred.IndexCache: Map ID attempt_20100220144352392_0002_m_000003_0 not found in cache [junit] 10/02/20 14:44:28 INFO mapred.JvmManager: In JvmRunner constructed JVM ID: jvm_20100220144352392_0002_m_-569787668 [junit] 10/02/20 14:44:28 INFO mapred.JvmManager: JVM Runner jvm_20100220144352392_0002_m_-569787668 spawned. [junit] 10/02/20 14:44:28 INFO mapred.TaskTracker: JVM with ID: jvm_20100220144352392_0002_m_-569787668 given task: attempt_20100220144352392_0002_m_000000_0 [junit] 10/02/20 14:44:29 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=create src=/tmp/temp-1218509902/tmp109332646/_temporary/_attempt_20100220144352392_0002_m_000000_0/part-m-00000 dst=null perm=hudson:supergroup:rw-r--r-- [junit] 10/02/20 14:44:29 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=open src=/user/hudson/input2.txt dst=null perm=null [junit] 10/02/20 14:44:29 INFO DataNode.clienttrace: src: /127.0.0.1:57834, dest: /127.0.0.1:60899, bytes: 10, op: HDFS_READ, cliID: DFSClient_attempt_20100220144352392_0002_m_000000_0, srvID: DS-955997914-127.0.1.1-57834-1266677031360, blockid: blk_3774489822189685858_1012 [junit] 10/02/20 14:44:29 INFO hdfs.StateChange: BLOCK* NameSystem.allocateBlock: /tmp/temp-1218509902/tmp109332646/_temporary/_attempt_20100220144352392_0002_m_000000_0/part-m-00000. blk_5947210830153556472_1018 [junit] 10/02/20 14:44:29 INFO datanode.DataNode: Receiving block blk_5947210830153556472_1018 src: /127.0.0.1:36777 dest: /127.0.0.1:34571 [junit] 10/02/20 14:44:29 INFO datanode.DataNode: Receiving block blk_5947210830153556472_1018 src: /127.0.0.1:60901 dest: /127.0.0.1:57834 [junit] 10/02/20 14:44:29 INFO datanode.DataNode: Receiving block blk_5947210830153556472_1018 src: /127.0.0.1:33402 dest: /127.0.0.1:49052 [junit] 10/02/20 14:44:29 INFO DataNode.clienttrace: src: /127.0.0.1:33402, dest: /127.0.0.1:49052, bytes: 39, op: HDFS_WRITE, cliID: DFSClient_attempt_20100220144352392_0002_m_000000_0, srvID: DS-980906310-127.0.1.1-49052-1266677030846, blockid: blk_5947210830153556472_1018 [junit] 10/02/20 14:44:29 INFO datanode.DataNode: PacketResponder 0 for block blk_5947210830153556472_1018 terminating [junit] 10/02/20 14:44:29 INFO hdfs.StateChange: BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:49052 is added to blk_5947210830153556472_1018 size 39 [junit] 10/02/20 14:44:29 INFO DataNode.clienttrace: src: /127.0.0.1:60901, dest: /127.0.0.1:57834, bytes: 39, op: HDFS_WRITE, cliID: DFSClient_attempt_20100220144352392_0002_m_000000_0, srvID: DS-955997914-127.0.1.1-57834-1266677031360, blockid: blk_5947210830153556472_1018 [junit] 10/02/20 14:44:29 INFO datanode.DataNode: PacketResponder 1 for block blk_5947210830153556472_1018 terminating [junit] 10/02/20 14:44:29 INFO hdfs.StateChange: BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:57834 is added to blk_5947210830153556472_1018 size 39 [junit] 10/02/20 14:44:29 INFO DataNode.clienttrace: src: /127.0.0.1:36777, dest: /127.0.0.1:34571, bytes: 39, op: HDFS_WRITE, cliID: DFSClient_attempt_20100220144352392_0002_m_000000_0, srvID: DS-1357221106-127.0.1.1-34571-1266677032320, blockid: blk_5947210830153556472_1018 [junit] 10/02/20 14:44:29 INFO datanode.DataNode: PacketResponder 2 for block blk_5947210830153556472_1018 terminating [junit] 10/02/20 14:44:29 INFO hdfs.StateChange: BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:34571 is added to blk_5947210830153556472_1018 size 39 [junit] 10/02/20 14:44:29 INFO hdfs.StateChange: DIR* NameSystem.completeFile: file /tmp/temp-1218509902/tmp109332646/_temporary/_attempt_20100220144352392_0002_m_000000_0/part-m-00000 is closed by DFSClient_attempt_20100220144352392_0002_m_000000_0 [junit] 10/02/20 14:44:29 INFO mapred.TaskTracker: Task attempt_20100220144352392_0002_m_000000_0 is in commit-pending, task state:COMMIT_PENDING [junit] 10/02/20 14:44:29 INFO mapred.TaskTracker: attempt_20100220144352392_0002_m_000000_0 0.0% [junit] 10/02/20 14:44:29 INFO mapred.JobTracker: Adding task 'attempt_20100220144352392_0002_m_000001_0' to tip task_20100220144352392_0002_m_000001, for tracker 'tracker_host0.foo.com:localhost/127.0.0.1:48985' [junit] 10/02/20 14:44:29 INFO mapred.JobInProgress: Choosing rack-local task task_20100220144352392_0002_m_000001 [junit] 10/02/20 14:44:29 INFO mapred.TaskTracker: LaunchTaskAction (registerTask): attempt_20100220144352392_0002_m_000001_0 task's state:UNASSIGNED [junit] 10/02/20 14:44:29 INFO mapred.TaskTracker: Trying to launch : attempt_20100220144352392_0002_m_000001_0 [junit] 10/02/20 14:44:29 INFO mapred.TaskTracker: In TaskLauncher, current free slots : 2 and trying to launch attempt_20100220144352392_0002_m_000001_0 [junit] 10/02/20 14:44:29 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=open src=/tmp/hadoop-hudson/mapred/system/job_20100220144352392_0002/job.xml dst=null perm=null [junit] 10/02/20 14:44:29 INFO DataNode.clienttrace: src: /127.0.0.1:54632, dest: /127.0.0.1:33970, bytes: 58665, op: HDFS_READ, cliID: DFSClient_-1202820087, srvID: DS-1216228394-127.0.1.1-54632-1266677031856, blockid: blk_-2243838457939614304_1015 [junit] 10/02/20 14:44:29 INFO datanode.DataNode: Deleting block blk_-9183596196974332335_1005 file build/test/data/dfs/data/data1/current/blk_-9183596196974332335 [junit] 10/02/20 14:44:29 INFO datanode.DataNode: Deleting block blk_-2629102099995670775_1007 file build/test/data/dfs/data/data1/current/blk_-2629102099995670775 [junit] 10/02/20 14:44:29 INFO datanode.DataNode: Deleting block blk_-1014759069321846640_1006 file build/test/data/dfs/data/data2/current/blk_-1014759069321846640 [junit] 10/02/20 14:44:29 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=open src=/tmp/hadoop-hudson/mapred/system/job_20100220144352392_0002/job.jar dst=null perm=null [junit] 10/02/20 14:44:29 WARN datanode.DataNode: DatanodeRegistration(127.0.0.1:34571, storageID=DS-1357221106-127.0.1.1-34571-1266677032320, infoPort=39891, ipcPort=35825):Got exception while serving blk_-6363216028128685971_1013 to /127.0.0.1: [junit] java.io.IOException: Block blk_-6363216028128685971_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/02/20 14:44:29 ERROR datanode.DataNode: DatanodeRegistration(127.0.0.1:34571, storageID=DS-1357221106-127.0.1.1-34571-1266677032320, infoPort=39891, ipcPort=35825):DataXceiver [junit] java.io.IOException: Block blk_-6363216028128685971_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/02/20 14:44:29 INFO DataNode.clienttrace: src: /127.0.0.1:49052, dest: /127.0.0.1:33405, bytes: 2912139, op: HDFS_READ, cliID: DFSClient_-1202820087, srvID: DS-980906310-127.0.1.1-49052-1266677030846, blockid: blk_-6363216028128685971_1013 [junit] 10/02/20 14:44:30 INFO mapred.JvmManager: In JvmRunner constructed JVM ID: jvm_20100220144352392_0002_m_-802358476 [junit] 10/02/20 14:44:30 INFO mapred.JvmManager: JVM Runner jvm_20100220144352392_0002_m_-802358476 spawned. [junit] 10/02/20 14:44:30 INFO mapred.TaskTracker: JVM with ID: jvm_20100220144352392_0002_m_-802358476 given task: attempt_20100220144352392_0002_m_000001_0 [junit] 10/02/20 14:44:31 INFO mapred.TaskTracker: Received commit task action for attempt_20100220144352392_0002_m_000000_0 [junit] 10/02/20 14:44:31 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=create src=/tmp/temp-1218509902/tmp109332646/_temporary/_attempt_20100220144352392_0002_m_000001_0/part-m-00001 dst=null perm=hudson:supergroup:rw-r--r-- [junit] 10/02/20 14:44:31 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=open src=/user/hudson/input1.txt dst=null perm=null [junit] 10/02/20 14:44:31 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=listStatus src=/tmp/temp-1218509902/tmp109332646/_temporary/_attempt_20100220144352392_0002_m_000000_0 dst=null perm=null [junit] 10/02/20 14:44:31 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=mkdirs src=/tmp/temp-1218509902/tmp109332646 dst=null perm=hudson:supergroup:rwxr-xr-x [junit] 10/02/20 14:44:31 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=rename src=/tmp/temp-1218509902/tmp109332646/_temporary/_attempt_20100220144352392_0002_m_000000_0/part-m-00000 dst=/tmp/temp-1218509902/tmp109332646/part-m-00000 perm=hudson:supergroup:rw-r--r-- [junit] 10/02/20 14:44:31 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=delete src=/tmp/temp-1218509902/tmp109332646/_temporary/_attempt_20100220144352392_0002_m_000000_0 dst=null perm=null [junit] 10/02/20 14:44:31 INFO mapred.TaskTracker: attempt_20100220144352392_0002_m_000000_0 1.0% [junit] 10/02/20 14:44:31 INFO mapred.TaskTracker: Task attempt_20100220144352392_0002_m_000000_0 is done. [junit] 10/02/20 14:44:31 INFO mapred.TaskTracker: reported output size for attempt_20100220144352392_0002_m_000000_0 was 0 [junit] 10/02/20 14:44:31 INFO mapred.TaskTracker: addFreeSlot : current free slots : 2 [junit] 10/02/20 14:44:31 INFO DataNode.clienttrace: src: /127.0.0.1:57834, dest: /127.0.0.1:60912, bytes: 10, op: HDFS_READ, cliID: DFSClient_attempt_20100220144352392_0002_m_000001_0, srvID: DS-955997914-127.0.1.1-57834-1266677031360, blockid: blk_5877078766794005765_1011 [junit] 10/02/20 14:44:31 INFO hdfs.StateChange: BLOCK* NameSystem.allocateBlock: /tmp/temp-1218509902/tmp109332646/_temporary/_attempt_20100220144352392_0002_m_000001_0/part-m-00001. blk_-7830615761117318562_1019 [junit] 10/02/20 14:44:31 INFO datanode.DataNode: Receiving block blk_-7830615761117318562_1019 src: /127.0.0.1:33413 dest: /127.0.0.1:49052 [junit] 10/02/20 14:44:31 INFO datanode.DataNode: Receiving block blk_-7830615761117318562_1019 src: /127.0.0.1:33981 dest: /127.0.0.1:54632 [junit] 10/02/20 14:44:31 INFO datanode.DataNode: Receiving block blk_-7830615761117318562_1019 src: /127.0.0.1:60915 dest: /127.0.0.1:57834 [junit] 10/02/20 14:44:31 INFO DataNode.clienttrace: src: /127.0.0.1:60915, dest: /127.0.0.1:57834, bytes: 39, op: HDFS_WRITE, cliID: DFSClient_attempt_20100220144352392_0002_m_000001_0, srvID: DS-955997914-127.0.1.1-57834-1266677031360, blockid: blk_-7830615761117318562_1019 [junit] 10/02/20 14:44:31 INFO datanode.DataNode: PacketResponder 0 for block blk_-7830615761117318562_1019 terminating [junit] 10/02/20 14:44:31 INFO DataNode.clienttrace: src: /127.0.0.1:33981, dest: /127.0.0.1:54632, bytes: 39, op: HDFS_WRITE, cliID: DFSClient_attempt_20100220144352392_0002_m_000001_0, srvID: DS-1216228394-127.0.1.1-54632-1266677031856, blockid: blk_-7830615761117318562_1019 [junit] 10/02/20 14:44:31 INFO datanode.DataNode: PacketResponder 1 for block blk_-7830615761117318562_1019 terminating [junit] 10/02/20 14:44:31 INFO hdfs.StateChange: BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:57834 is added to blk_-7830615761117318562_1019 size 39 [junit] 10/02/20 14:44:31 INFO hdfs.StateChange: BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:54632 is added to blk_-7830615761117318562_1019 size 39 [junit] 10/02/20 14:44:31 INFO DataNode.clienttrace: src: /127.0.0.1:33413, dest: /127.0.0.1:49052, bytes: 39, op: HDFS_WRITE, cliID: DFSClient_attempt_20100220144352392_0002_m_000001_0, srvID: DS-980906310-127.0.1.1-49052-1266677030846, blockid: blk_-7830615761117318562_1019 [junit] 10/02/20 14:44:31 INFO datanode.DataNode: PacketResponder 2 for block blk_-7830615761117318562_1019 terminating [junit] 10/02/20 14:44:31 INFO hdfs.StateChange: BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:49052 is added to blk_-7830615761117318562_1019 size 39 [junit] 10/02/20 14:44:31 INFO hdfs.StateChange: DIR* NameSystem.completeFile: file /tmp/temp-1218509902/tmp109332646/_temporary/_attempt_20100220144352392_0002_m_000001_0/part-m-00001 is closed by DFSClient_attempt_20100220144352392_0002_m_000001_0 [junit] 10/02/20 14:44:31 INFO mapred.JvmManager: JVM : jvm_20100220144352392_0002_m_-569787668 exited. Number of tasks it ran: 1 [junit] 10/02/20 14:44:31 INFO mapred.TaskTracker: Task attempt_20100220144352392_0002_m_000001_0 is in commit-pending, task state:COMMIT_PENDING [junit] 10/02/20 14:44:31 INFO mapred.TaskTracker: attempt_20100220144352392_0002_m_000001_0 0.0% [junit] 10/02/20 14:44:32 INFO mapred.TaskTracker: Received commit task action for attempt_20100220144352392_0002_m_000001_0 [junit] 10/02/20 14:44:33 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=listStatus src=/tmp/temp-1218509902/tmp109332646/_temporary/_attempt_20100220144352392_0002_m_000001_0 dst=null perm=null [junit] 10/02/20 14:44:33 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=mkdirs src=/tmp/temp-1218509902/tmp109332646 dst=null perm=hudson:supergroup:rwxr-xr-x [junit] 10/02/20 14:44:33 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=rename src=/tmp/temp-1218509902/tmp109332646/_temporary/_attempt_20100220144352392_0002_m_000001_0/part-m-00001 dst=/tmp/temp-1218509902/tmp109332646/part-m-00001 perm=hudson:supergroup:rw-r--r-- [junit] 10/02/20 14:44:33 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=delete src=/tmp/temp-1218509902/tmp109332646/_temporary/_attempt_20100220144352392_0002_m_000001_0 dst=null perm=null [junit] 10/02/20 14:44:33 INFO mapred.TaskTracker: attempt_20100220144352392_0002_m_000001_0 1.0% [junit] 10/02/20 14:44:33 INFO mapred.TaskTracker: Task attempt_20100220144352392_0002_m_000001_0 is done. [junit] 10/02/20 14:44:33 INFO mapred.TaskTracker: reported output size for attempt_20100220144352392_0002_m_000001_0 was 0 [junit] 10/02/20 14:44:33 INFO mapred.TaskTracker: addFreeSlot : current free slots : 2 [junit] 10/02/20 14:44:33 INFO mapred.JvmManager: JVM : jvm_20100220144352392_0002_m_-802358476 exited. Number of tasks it ran: 1 [junit] 10/02/20 14:44:34 INFO mapred.TaskTracker: org.apache.hadoop.util.DiskChecker$DiskErrorException: Could not find taskTracker/jobcache/job_20100220144352392_0002/attempt_20100220144352392_0002_m_000000_0/output/file.out in any of the configured local directories [junit] 10/02/20 14:44:34 INFO mapred.JobInProgress: Task 'attempt_20100220144352392_0002_m_000000_0' has completed task_20100220144352392_0002_m_000000 successfully. [junit] 10/02/20 14:44:34 INFO mapReduceLayer.MapReduceLauncher: 25% complete [junit] 10/02/20 14:44:35 INFO mapred.TaskTracker: org.apache.hadoop.util.DiskChecker$DiskErrorException: Could not find taskTracker/jobcache/job_20100220144352392_0002/attempt_20100220144352392_0002_m_000001_0/output/file.out in any of the configured local directories [junit] 10/02/20 14:44:35 INFO mapred.JobInProgress: Task 'attempt_20100220144352392_0002_m_000001_0' has completed task_20100220144352392_0002_m_000001 successfully. [junit] 10/02/20 14:44:35 INFO mapred.JobTracker: Adding task 'attempt_20100220144352392_0002_m_000002_0' to tip task_20100220144352392_0002_m_000002, for tracker 'tracker_host0.foo.com:localhost/127.0.0.1:48985' [junit] 10/02/20 14:44:35 INFO mapred.TaskTracker: LaunchTaskAction (registerTask): attempt_20100220144352392_0002_m_000002_0 task's state:UNASSIGNED [junit] 10/02/20 14:44:35 INFO mapred.TaskTracker: Trying to launch : attempt_20100220144352392_0002_m_000002_0 [junit] 10/02/20 14:44:35 INFO mapred.TaskTracker: In TaskLauncher, current free slots : 2 and trying to launch attempt_20100220144352392_0002_m_000002_0 [junit] 10/02/20 14:44:35 INFO mapred.JvmManager: In JvmRunner constructed JVM ID: jvm_20100220144352392_0002_m_-217272582 [junit] 10/02/20 14:44:35 INFO mapred.JvmManager: JVM Runner jvm_20100220144352392_0002_m_-217272582 spawned. [junit] 10/02/20 14:44:35 INFO mapReduceLayer.MapReduceLauncher: 50% complete [junit] 10/02/20 14:44:36 INFO mapred.TaskTracker: JVM with ID: jvm_20100220144352392_0002_m_-217272582 given task: attempt_20100220144352392_0002_m_000002_0 [junit] 10/02/20 14:44:36 INFO mapred.TaskTracker: attempt_20100220144352392_0002_m_000002_0 0.0% [junit] 10/02/20 14:44:36 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=delete src=/tmp/temp-1218509902/tmp109332646/_temporary dst=null perm=null [junit] 10/02/20 14:44:36 INFO mapred.TaskTracker: attempt_20100220144352392_0002_m_000002_0 0.0% cleanup [junit] 10/02/20 14:44:36 INFO mapred.TaskTracker: Task attempt_20100220144352392_0002_m_000002_0 is done. [junit] 10/02/20 14:44:36 INFO mapred.TaskTracker: reported output size for attempt_20100220144352392_0002_m_000002_0 was 0 [junit] 10/02/20 14:44:36 INFO mapred.TaskTracker: addFreeSlot : current free slots : 2 [junit] 10/02/20 14:44:36 INFO datanode.DataBlockScanner: Verification succeeded for blk_3573347996132938751_1009 [junit] 10/02/20 14:44:36 INFO mapred.JvmManager: JVM : jvm_20100220144352392_0002_m_-217272582 exited. Number of tasks it ran: 1 [junit] 10/02/20 14:44:38 INFO mapred.TaskTracker: org.apache.hadoop.util.DiskChecker$DiskErrorException: Could not find taskTracker/jobcache/job_20100220144352392_0002/attempt_20100220144352392_0002_m_000002_0/output/file.out in any of the configured local directories [junit] 10/02/20 14:44:38 INFO mapred.JobInProgress: Task 'attempt_20100220144352392_0002_m_000002_0' has completed task_20100220144352392_0002_m_000002 successfully. [junit] 10/02/20 14:44:38 INFO mapred.JobInProgress: Job job_20100220144352392_0002 has completed successfully. [junit] 10/02/20 14:44:38 INFO hdfs.StateChange: BLOCK* NameSystem.allocateBlock: /tmp/temp-1218509902/tmp109332646/_logs/history/localhost_1266677032416_job_20100220144352392_0002_hudson_Job7930732126387436403.jar. blk_3695954003924297589_1019 [junit] 10/02/20 14:44:38 INFO datanode.DataNode: Receiving block blk_3695954003924297589_1019 src: /127.0.0.1:36799 dest: /127.0.0.1:34571 [junit] 10/02/20 14:44:38 INFO datanode.DataNode: Receiving block blk_3695954003924297589_1019 src: /127.0.0.1:33423 dest: /127.0.0.1:49052 [junit] 10/02/20 14:44:38 INFO datanode.DataNode: Receiving block blk_3695954003924297589_1019 src: /127.0.0.1:33991 dest: /127.0.0.1:54632 [junit] 10/02/20 14:44:38 INFO DataNode.clienttrace: src: /127.0.0.1:33991, dest: /127.0.0.1:54632, bytes: 5856, op: HDFS_WRITE, cliID: DFSClient_-1202820087, srvID: DS-1216228394-127.0.1.1-54632-1266677031856, blockid: blk_3695954003924297589_1019 [junit] 10/02/20 14:44:38 INFO datanode.DataNode: PacketResponder 0 for block blk_3695954003924297589_1019 terminating [junit] 10/02/20 14:44:38 INFO hdfs.StateChange: BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:54632 is added to blk_3695954003924297589_1019 size 5856 [junit] 10/02/20 14:44:38 INFO hdfs.StateChange: BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:49052 is added to blk_3695954003924297589_1019 size 5856 [junit] 10/02/20 14:44:38 INFO DataNode.clienttrace: src: /127.0.0.1:33423, dest: /127.0.0.1:49052, bytes: 5856, op: HDFS_WRITE, cliID: DFSClient_-1202820087, srvID: DS-980906310-127.0.1.1-49052-1266677030846, blockid: blk_3695954003924297589_1019 [junit] 10/02/20 14:44:38 INFO datanode.DataNode: PacketResponder 1 for block blk_3695954003924297589_1019 terminating [junit] 10/02/20 14:44:38 INFO DataNode.clienttrace: src: /127.0.0.1:36799, dest: /127.0.0.1:34571, bytes: 5856, op: HDFS_WRITE, cliID: DFSClient_-1202820087, srvID: DS-1357221106-127.0.1.1-34571-1266677032320, blockid: blk_3695954003924297589_1019 [junit] 10/02/20 14:44:38 INFO datanode.DataNode: PacketResponder 2 for block blk_3695954003924297589_1019 terminating [junit] 10/02/20 14:44:38 INFO hdfs.StateChange: BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:34571 is added to blk_3695954003924297589_1019 size 5856 [junit] 10/02/20 14:44:38 INFO hdfs.StateChange: DIR* NameSystem.completeFile: file /tmp/temp-1218509902/tmp109332646/_logs/history/localhost_1266677032416_job_20100220144352392_0002_hudson_Job7930732126387436403.jar is closed by DFSClient_-1202820087 [junit] 10/02/20 14:44:38 INFO mapred.JobTracker: Removed completed task 'attempt_20100220144352392_0002_m_000001_0' from 'tracker_host0.foo.com:localhost/127.0.0.1:48985' [junit] 10/02/20 14:44:38 INFO mapred.JobTracker: Removed completed task 'attempt_20100220144352392_0002_m_000002_0' from 'tracker_host0.foo.com:localhost/127.0.0.1:48985' [junit] 10/02/20 14:44:38 INFO hdfs.StateChange: BLOCK* NameSystem.addToInvalidates: blk_-6363216028128685971 is added to invalidSet of 127.0.0.1:34571 [junit] 10/02/20 14:44:38 INFO hdfs.StateChange: BLOCK* NameSystem.addToInvalidates: blk_-6363216028128685971 is added to invalidSet of 127.0.0.1:49052 [junit] 10/02/20 14:44:38 INFO hdfs.StateChange: BLOCK* NameSystem.addToInvalidates: blk_-6363216028128685971 is added to invalidSet of 127.0.0.1:54632 [junit] 10/02/20 14:44:38 INFO hdfs.StateChange: BLOCK* NameSystem.addToInvalidates: blk_740199783892902868 is added to invalidSet of 127.0.0.1:54632 [junit] 10/02/20 14:44:38 INFO hdfs.StateChange: BLOCK* NameSystem.addToInvalidates: blk_740199783892902868 is added to invalidSet of 127.0.0.1:57834 [junit] 10/02/20 14:44:38 INFO hdfs.StateChange: BLOCK* NameSystem.addToInvalidates: blk_740199783892902868 is added to invalidSet of 127.0.0.1:34571 [junit] 10/02/20 14:44:38 INFO hdfs.StateChange: BLOCK* NameSystem.addToInvalidates: blk_-2243838457939614304 is added to invalidSet of 127.0.0.1:57834 [junit] 10/02/20 14:44:38 INFO hdfs.StateChange: BLOCK* NameSystem.addToInvalidates: blk_-2243838457939614304 is added to invalidSet of 127.0.0.1:34571 [junit] 10/02/20 14:44:38 INFO hdfs.StateChange: BLOCK* NameSystem.addToInvalidates: blk_-2243838457939614304 is added to invalidSet of 127.0.0.1:54632 [junit] 10/02/20 14:44:38 INFO mapred.TaskTracker: Received 'KillJobAction' for job: job_20100220144352392_0002 [junit] 10/02/20 14:44:38 INFO mapred.TaskRunner: attempt_20100220144352392_0002_m_000002_0 done; removing files. [junit] 10/02/20 14:44:38 INFO mapred.IndexCache: Map ID attempt_20100220144352392_0002_m_000002_0 not found in cache [junit] 10/02/20 14:44:38 INFO mapred.TaskRunner: attempt_20100220144352392_0002_m_000001_0 done; removing files. [junit] 10/02/20 14:44:38 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=delete src=/tmp/hadoop-hudson/mapred/system/job_20100220144352392_0002 dst=null perm=null [junit] 10/02/20 14:44:38 INFO mapred.IndexCache: Map ID attempt_20100220144352392_0002_m_000001_0 not found in cache [junit] 10/02/20 14:44:39 INFO mapred.TaskTracker: Received 'KillJobAction' for job: job_20100220144352392_0002 [junit] 10/02/20 14:44:39 WARN mapred.TaskTracker: Unknown job job_20100220144352392_0002 being deleted. [junit] 10/02/20 14:44:39 INFO mapred.TaskTracker: Received 'KillJobAction' for job: job_20100220144352392_0002 [junit] 10/02/20 14:44:39 WARN mapred.TaskTracker: Unknown job job_20100220144352392_0002 being deleted. [junit] 10/02/20 14:44:39 INFO mapReduceLayer.MapReduceLauncher: 100% complete [junit] 10/02/20 14:44:39 INFO mapReduceLayer.MapReduceLauncher: Successfully stored result in: "hdfs://localhost:52067/tmp/temp-1218509902/tmp109332646" [junit] 10/02/20 14:44:39 INFO mapReduceLayer.MapReduceLauncher: Records written : 0 [junit] 10/02/20 14:44:39 INFO mapReduceLayer.MapReduceLauncher: Bytes written : 78 [junit] 10/02/20 14:44:39 INFO mapReduceLayer.MapReduceLauncher: Success! [junit] 10/02/20 14:44:39 INFO hdfs.StateChange: BLOCK* ask 127.0.0.1:54632 to delete blk_-2243838457939614304_1015 blk_740199783892902868_1014 blk_-6363216028128685971_1013 [junit] 10/02/20 14:44:39 INFO hdfs.StateChange: BLOCK* ask 127.0.0.1:34571 to delete blk_-2243838457939614304_1015 blk_740199783892902868_1014 blk_-6363216028128685971_1013 [junit] 10/02/20 14:44:39 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=listStatus src=/tmp/temp-1218509902/tmp109332646 dst=null perm=null [junit] 10/02/20 14:44:39 INFO input.FileInputFormat: Total input paths to process : 2 [junit] 10/02/20 14:44:39 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=open src=/tmp/temp-1218509902/tmp109332646/part-m-00000 dst=null perm=null [junit] 10/02/20 14:44:39 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=open src=/tmp/temp-1218509902/tmp109332646/part-m-00001 dst=null perm=null [junit] 10/02/20 14:44:39 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=open src=/tmp/temp-1218509902/tmp109332646/part-m-00000 dst=null perm=null [junit] 10/02/20 14:44:39 INFO DataNode.clienttrace: src: /127.0.0.1:34571, dest: /127.0.0.1:36803, bytes: 43, op: HDFS_READ, cliID: DFSClient_-1202820087, srvID: DS-1357221106-127.0.1.1-34571-1266677032320, blockid: blk_5947210830153556472_1018 [junit] 10/02/20 14:44:39 INFO FSNamesystem.audit: ugi=hudson,hudson ip=/127.0.0.1 cmd=open src=/tmp/temp-1218509902/tmp109332646/part-m-00001 dst=null perm=null [junit] 10/02/20 14:44:39 INFO DataNode.clienttrace: src: /127.0.0.1:49052, dest: /127.0.0.1:33427, bytes: 43, op: HDFS_READ, cliID: DFSClient_-1202820087, srvID: DS-980906310-127.0.1.1-49052-1266677030846, blockid: blk_-7830615761117318562_1019 [junit] Tests run: 3, Failures: 0, Errors: 0, Time elapsed: 44.869 sec BUILD FAILED <http://hudson.zones.apache.org/hudson/job/Pig-trunk/ws/trunk/build.xml>:560: The following error occurred while executing this line: <http://hudson.zones.apache.org/hudson/job/Pig-trunk/ws/trunk/build.xml>:493: The following error occurred while executing this line: <http://hudson.zones.apache.org/hudson/job/Pig-trunk/ws/trunk/build.xml>:555: Tests failed! Total time: 274 minutes 16 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
