Return-Path: Delivered-To: apmail-hadoop-core-dev-archive@www.apache.org Received: (qmail 26571 invoked from network); 5 Mar 2008 16:03:26 -0000 Received: from hermes.apache.org (HELO mail.apache.org) (140.211.11.2) by minotaur.apache.org with SMTP; 5 Mar 2008 16:03:26 -0000 Received: (qmail 88555 invoked by uid 500); 5 Mar 2008 16:02:56 -0000 Delivered-To: apmail-hadoop-core-dev-archive@hadoop.apache.org Received: (qmail 88515 invoked by uid 500); 5 Mar 2008 16:02:56 -0000 Mailing-List: contact core-dev-help@hadoop.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: core-dev@hadoop.apache.org Delivered-To: mailing list core-dev@hadoop.apache.org Received: (qmail 88487 invoked by uid 99); 5 Mar 2008 16:02:56 -0000 Received: from nike.apache.org (HELO nike.apache.org) (192.87.106.230) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 05 Mar 2008 08:02:56 -0800 X-ASF-Spam-Status: No, hits=-2000.0 required=10.0 tests=ALL_TRUSTED X-Spam-Check-By: apache.org Received: from [140.211.11.106] (HELO hudson.zones.apache.org) (140.211.11.106) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 05 Mar 2008 16:02:14 +0000 Received: from hudson.zones.apache.org (localhost [127.0.0.1]) by hudson.zones.apache.org (8.13.8+Sun/8.13.8) with ESMTP id m25G2Xxr005884 for ; Wed, 5 Mar 2008 11:02:33 -0500 (EST) Date: Wed, 5 Mar 2008 16:02:30 +0000 (UTC) From: Apache Hudson Server To: core-dev@hadoop.apache.org Message-ID: <13322994.191204732953425.JavaMail.hudson@hudson.zones.apache.org> In-Reply-To: <29753138.741204636280165.JavaMail.hudson@hudson.zones.apache.org> References: <29753138.741204636280165.JavaMail.hudson@hudson.zones.apache.org> Subject: Build failed in Hudson: Hadoop-trunk #420 MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Transfer-Encoding: 7bit X-Virus-Checked: Checked by ClamAV on apache.org See http://hudson.zones.apache.org/hudson/job/Hadoop-trunk/420/changes Changes: [dhruba] HADOOP-2883. Write failures and data corruptions on HDFS files. The write timeout is back to what it was on 0.15 release. Also, the datnodes flushes the block file buffered output stream before sending a positive ack for the packet back to the client. (dhruba) [nigel] HADOOP-2861. INCOMPATIBLE CHANGE. Improve the user interface for the HOD commands. Command line structure has changed. Contributed by Hemanth Yamijala. [nigel] HADOOP-2861. INCOMPATIBLE CHANGE. Improve the user interface for the HOD commands. Command line structure has changed. Contributed by Hemanth Yamijala. ------------------------------------------ [...truncated 96369 lines...] [junit] 2008-03-05 15:59:41,184 INFO net.NetworkTopology (NetworkTopology.java:add(321)) - Adding a new node: /default-rack/127.0.0.1:48964 [junit] 2008-03-05 15:59:41,259 INFO dfs.DataNode (FSDataset.java:registerMBean(956)) - Registered FSDatasetStatusMBean [junit] 2008-03-05 15:59:41,260 INFO dfs.DataNode (DataNode.java:startDataNode(259)) - Opened server at 48966 [junit] 2008-03-05 15:59:41,261 INFO dfs.DataNode (DataNode.java:startDataNode(281)) - Balancing bandwith is 1048576 bytes/s [junit] 2008-03-05 15:59:41,266 INFO http.HttpServer (HttpServer.java:doStart(729)) - Version Jetty/5.1.4 [junit] 2008-03-05 15:59:41,357 INFO util.Container (Container.java:start(74)) - Started org.mortbay.jetty.servlet.WebApplicationHandler@1417690 [junit] 2008-03-05 15:59:41,359 INFO util.Container (Container.java:start(74)) - Started WebApplicationContext[/,/] [junit] 2008-03-05 15:59:41,360 INFO util.Container (Container.java:start(74)) - Started HttpContext[/logs,/logs] [junit] 2008-03-05 15:59:41,360 INFO util.Container (Container.java:start(74)) - Started HttpContext[/static,/static] [junit] 2008-03-05 15:59:41,363 INFO http.SocketListener (SocketListener.java:start(204)) - Started SocketListener on 127.0.0.1:48967 [junit] 2008-03-05 15:59:41,364 INFO util.Container (Container.java:start(74)) - Started org.mortbay.jetty.Server@160c4b0 [junit] 2008-03-05 15:59:41,365 INFO jvm.JvmMetrics (JvmMetrics.java:init(62)) - Cannot initialize JVM Metrics with processName=DataNode, sessionId=null - already initialized [junit] 2008-03-05 15:59:41,368 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 6 on 48957, ugi=null [junit] 2008-03-05 15:59:41,369 INFO dfs.StateChange (FSNamesystem.java:registerDatanode(1979)) - BLOCK* NameSystem.registerDatanode: node registration from 127.0.0.1:48966 storage DS-1553970926-140.211.11.106-48966-1204732781368 [junit] 2008-03-05 15:59:41,369 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 6 on 48957, ugi=null [junit] 2008-03-05 15:59:41,405 INFO dfs.DataNode (DataNode.java:register(444)) - New storage id DS-1553970926-140.211.11.106-48966-1204732781368 is assigned to data-node 127.0.0.1:48966 [junit] 2008-03-05 15:59:41,409 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 2 on 48957, ugi=hudson,hudson [junit] 2008-03-05 15:59:41,410 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 2 on 48957, ugi=null [junit] 2008-03-05 15:59:41,410 INFO dfs.DataNode (DataNode.java:run(2593)) - 127.0.0.1:48966In DataNode.run, data = FSDataset{dirpath='/zonestorage/hudson/home/hudson/hudson/jobs/Hadoop-trunk/workspace/trunk/build/test/data/dfs/data/data5/current,/zonestorage/hudson/home/hudson/hudson/jobs/Hadoop-trunk/workspace/trunk/build/test/data/dfs/data/data6/current'} [junit] 2008-03-05 15:59:41,411 INFO dfs.DataNode (DataNode.java:offerService(562)) - using BLOCKREPORT_INTERVAL of 3555687msec Initial delay: 0msec [junit] 2008-03-05 15:59:41,452 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 0 on 48957, ugi=hudson,hudson [junit] 2008-03-05 15:59:41,454 DEBUG security.UserGroupInformation (PermissionChecker.java:(40)) - ugi=hudson,hudson [junit] 2008-03-05 15:59:41,456 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 0 on 48957, ugi=null [junit] 2008-03-05 15:59:41,651 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 7 on 48957, ugi=null [junit] 2008-03-05 15:59:41,654 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 7 on 48957, ugi=null [junit] 2008-03-05 15:59:41,656 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 5 on 48957, ugi=null [junit] 2008-03-05 15:59:41,657 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 5 on 48957, ugi=null [junit] 2008-03-05 15:59:41,657 INFO dfs.DataNode (DataNode.java:offerService(646)) - BlockReport of 0 blocks got processed in 2 msecs [junit] 2008-03-05 15:59:41,964 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 3 on 48957, ugi=hudson,hudson [junit] 2008-03-05 15:59:41,965 DEBUG security.UserGroupInformation (PermissionChecker.java:(40)) - ugi=hudson,hudson [junit] 2008-03-05 15:59:41,965 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 3 on 48957, ugi=null [junit] 2008-03-05 15:59:42,474 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 1 on 48957, ugi=hudson,hudson [junit] 2008-03-05 15:59:42,475 DEBUG security.UserGroupInformation (PermissionChecker.java:(40)) - ugi=hudson,hudson [junit] 2008-03-05 15:59:42,476 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 1 on 48957, ugi=null [junit] 2008-03-05 15:59:42,984 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 9 on 48957, ugi=hudson,hudson [junit] 2008-03-05 15:59:42,984 DEBUG security.UserGroupInformation (PermissionChecker.java:(40)) - ugi=hudson,hudson [junit] 2008-03-05 15:59:42,984 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 9 on 48957, ugi=null [junit] 2008-03-05 15:59:43,194 INFO net.NetworkTopology (NetworkTopology.java:add(321)) - Adding a new node: /default-rack/127.0.0.1:48966 [junit] 2008-03-05 15:59:43,494 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 4 on 48957, ugi=hudson,hudson [junit] 2008-03-05 15:59:43,494 DEBUG security.UserGroupInformation (PermissionChecker.java:(40)) - ugi=hudson,hudson [junit] 2008-03-05 15:59:43,494 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 4 on 48957, ugi=null [junit] 2008-03-05 15:59:43,566 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 8 on 48957, ugi=null [junit] 2008-03-05 15:59:43,566 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 8 on 48957, ugi=null [junit] 2008-03-05 15:59:43,567 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 6 on 48957, ugi=null [junit] 2008-03-05 15:59:43,568 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 6 on 48957, ugi=null [junit] 2008-03-05 15:59:43,569 INFO dfs.DataNode (DataNode.java:offerService(646)) - BlockReport of 0 blocks got processed in 2 msecs [junit] 2008-03-05 15:59:44,014 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 2 on 48957, ugi=null [junit] 2008-03-05 15:59:44,015 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 2 on 48957, ugi=null [junit] 2008-03-05 15:59:44,017 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 0 on 48957, ugi=null [junit] 2008-03-05 15:59:44,017 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 0 on 48957, ugi=null [junit] 2008-03-05 15:59:44,017 INFO dfs.DataNode (DataNode.java:offerService(646)) - BlockReport of 0 blocks got processed in 1 msecs [junit] 2008-03-05 15:59:44,414 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 7 on 48957, ugi=null [junit] 2008-03-05 15:59:44,414 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 7 on 48957, ugi=null [junit] 2008-03-05 15:59:44,417 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 5 on 48957, ugi=null [junit] 2008-03-05 15:59:44,417 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 5 on 48957, ugi=null [junit] 2008-03-05 15:59:44,417 INFO dfs.DataNode (DataNode.java:offerService(646)) - BlockReport of 0 blocks got processed in 1 msecs [junit] 2008-03-05 15:59:44,483 DEBUG security.UserGroupInformation (PermissionChecker.java:(40)) - ugi=hudson,hudson [junit] 2008-03-05 15:59:44,485 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 3 on 48957, ugi=hudson,hudson [junit] 2008-03-05 15:59:44,486 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 3 on 48957, ugi=null [junit] 2008-03-05 15:59:44,486 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 1 on 48957, ugi=hudson,hudson [junit] 2008-03-05 15:59:44,487 DEBUG security.UserGroupInformation (PermissionChecker.java:(40)) - ugi=hudson,hudson [junit] 2008-03-05 15:59:44,487 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 1 on 48957, ugi=null [junit] 2008-03-05 15:59:45,493 WARN fs.FileSystem (FileSystem.java:fixName(153)) - "localhost:48957" is a deprecated filesystem name. Use "hdfs://localhost:48957/" instead. [junit] 2008-03-05 15:59:45,495 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 9 on 48957, ugi=hudson,hudson [junit] 2008-03-05 15:59:45,495 DEBUG security.UserGroupInformation (PermissionChecker.java:(40)) - ugi=hudson,hudson [junit] 2008-03-05 15:59:45,522 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 9 on 48957, ugi=null [junit] 2008-03-05 15:59:45,524 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 4 on 48957, ugi=hudson,hudson [junit] 2008-03-05 15:59:45,525 DEBUG security.UserGroupInformation (PermissionChecker.java:(40)) - ugi=hudson,hudson [junit] 2008-03-05 15:59:45,525 DEBUG security.UserGroupInformation (PermissionChecker.java:(40)) - ugi=hudson,hudson [junit] 2008-03-05 15:59:45,548 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 4 on 48957, ugi=null [junit] 2008-03-05 15:59:45,550 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 8 on 48957, ugi=hudson,hudson [junit] 2008-03-05 15:59:45,551 INFO dfs.StateChange (FSNamesystem.java:allocateBlock(1312)) - BLOCK* NameSystem.allocateBlock: /data/file1. blk_2420046476205940188 [junit] 2008-03-05 15:59:45,551 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 8 on 48957, ugi=null [junit] 2008-03-05 15:59:45,553 INFO dfs.DataNode (DataNode.java:writeBlock(1057)) - Receiving block blk_2420046476205940188 src: /127.0.0.1:48971 dest: /127.0.0.1:48966 [junit] 2008-03-05 15:59:45,556 INFO dfs.DataNode (DataNode.java:writeBlock(1057)) - Receiving block blk_2420046476205940188 src: /127.0.0.1:48972 dest: /127.0.0.1:48962 [junit] 2008-03-05 15:59:45,563 INFO dfs.DataNode (DataNode.java:writeBlock(1057)) - Receiving block blk_2420046476205940188 src: /127.0.0.1:48973 dest: /127.0.0.1:48964 [junit] 2008-03-05 15:59:45,564 INFO dfs.DataNode (DataNode.java:writeBlock(1150)) - Datanode 0 forwarding connect ack to upstream firstbadlink is [junit] 2008-03-05 15:59:45,565 INFO dfs.DataNode (DataNode.java:writeBlock(1127)) - Datanode 1 got response for connect ack from downstream datanode with firstbadlink as [junit] 2008-03-05 15:59:45,565 INFO dfs.DataNode (DataNode.java:writeBlock(1150)) - Datanode 1 forwarding connect ack to upstream firstbadlink is [junit] 2008-03-05 15:59:45,565 INFO dfs.DataNode (DataNode.java:writeBlock(1127)) - Datanode 2 got response for connect ack from downstream datanode with firstbadlink as [junit] 2008-03-05 15:59:45,566 INFO dfs.DataNode (DataNode.java:writeBlock(1150)) - Datanode 2 forwarding connect ack to upstream firstbadlink is [junit] 2008-03-05 15:59:45,568 INFO dfs.DataNode (DataNode.java:lastDataNodeRun(1896)) - Received block blk_2420046476205940188 of size 100 from /127.0.0.1 [junit] 2008-03-05 15:59:45,568 INFO dfs.DataNode (DataNode.java:lastDataNodeRun(1919)) - PacketResponder 0 for block blk_2420046476205940188 terminating [junit] 2008-03-05 15:59:45,569 INFO dfs.DataNode (DataNode.java:run(1986)) - Received block blk_2420046476205940188 of size 100 from /127.0.0.1 [junit] 2008-03-05 15:59:45,570 INFO dfs.DataNode (DataNode.java:run(2050)) - PacketResponder 1 for block blk_2420046476205940188 terminating [junit] 2008-03-05 15:59:45,568 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 6 on 48957, ugi=null [junit] 2008-03-05 15:59:45,570 INFO dfs.DataNode (DataNode.java:run(1986)) - Received block blk_2420046476205940188 of size 100 from /127.0.0.1 [junit] 2008-03-05 15:59:45,571 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 2 on 48957, ugi=null [junit] 2008-03-05 15:59:45,571 INFO dfs.DataNode (DataNode.java:run(2050)) - PacketResponder 2 for block blk_2420046476205940188 terminating [junit] 2008-03-05 15:59:45,572 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 0 on 48957, ugi=null [junit] 2008-03-05 15:59:45,571 INFO dfs.StateChange (FSNamesystem.java:addStoredBlock(2599)) - BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:48964 is added to blk_2420046476205940188 size 100 [junit] 2008-03-05 15:59:45,573 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 6 on 48957, ugi=null [junit] 2008-03-05 15:59:45,573 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 6 on 48957, ugi=hudson,hudson [junit] 2008-03-05 15:59:45,574 INFO dfs.StateChange (FSNamesystem.java:addStoredBlock(2599)) - BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:48966 is added to blk_2420046476205940188 size 100 [junit] 2008-03-05 15:59:45,574 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 0 on 48957, ugi=null [junit] 2008-03-05 15:59:45,576 INFO dfs.StateChange (FSNamesystem.java:addStoredBlock(2599)) - BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:48962 is added to blk_2420046476205940188 size 100 [junit] 2008-03-05 15:59:45,576 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 2 on 48957, ugi=null [junit] 2008-03-05 15:59:45,597 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 6 on 48957, ugi=null [junit] 2008-03-05 15:59:45,598 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 5 on 48957, ugi=hudson,hudson [junit] 2008-03-05 15:59:45,599 DEBUG security.UserGroupInformation (PermissionChecker.java:(40)) - ugi=hudson,hudson [junit] 2008-03-05 15:59:45,622 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 5 on 48957, ugi=null [junit] 2008-03-05 15:59:45,632 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 3 on 48957, ugi=hudson,hudson [junit] 2008-03-05 15:59:45,633 DEBUG security.UserGroupInformation (PermissionChecker.java:(40)) - ugi=hudson,hudson [junit] 2008-03-05 15:59:45,637 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 3 on 48957, ugi=null [junit] 2008-03-05 15:59:45,657 INFO dfs.DataNode (DataNode.java:readBlock(1024)) - 127.0.0.1:48962 Served block blk_2420046476205940188 to /127.0.0.1 [junit] 2008-03-05 15:59:46,543 WARN fs.FileSystem (FileSystem.java:fixName(153)) - "localhost:48957" is a deprecated filesystem name. Use "hdfs://localhost:48957/" instead. [junit] 2008-03-05 15:59:46,546 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 1 on 48957, ugi=Who,group1,group2 [junit] 2008-03-05 15:59:46,546 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 1 on 48957, ugi=null [junit] 2008-03-05 15:59:46,547 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 9 on 48957, ugi=Who,group1,group2 [junit] 2008-03-05 15:59:46,548 DEBUG security.UserGroupInformation (PermissionChecker.java:(40)) - ugi=Who,group1,group2 [junit] 2008-03-05 15:59:46,548 DEBUG security.UserGroupInformation (PermissionChecker.java:checkPermission(87)) - ACCESS CHECK: org.apache.hadoop.dfs.PermissionChecker@1c6a99d, doCheckOwner=false, ancestorAccess=WRITE, parentAccess=null, access=null, subAccess=null [junit] 2008-03-05 15:59:46,564 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 4 on 48957, ugi=null [junit] 2008-03-05 15:59:46,565 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 4 on 48957, ugi=null [junit] 2008-03-05 15:59:46,568 INFO ipc.Server (Server.java:run(901)) - IPC Server handler 9 on 48957, call mkdirs(/data/web2, rwxr-xr-x) from 127.0.0.1:48976: error: org.apache.hadoop.fs.permission.AccessControlException: Permission denied: user=Who, access=WRITE, inode="data":hudson:supergroup:rwxr-xr-x [junit] org.apache.hadoop.fs.permission.AccessControlException: Permission denied: user=Who, access=WRITE, inode="data":hudson:supergroup:rwxr-xr-x [junit] at org.apache.hadoop.dfs.PermissionChecker.check(PermissionChecker.java:173) [junit] at org.apache.hadoop.dfs.PermissionChecker.check(PermissionChecker.java:154) [junit] at org.apache.hadoop.dfs.PermissionChecker.checkPermission(PermissionChecker.java:102) [junit] at org.apache.hadoop.dfs.FSNamesystem.checkPermission(FSNamesystem.java:4130) [junit] at org.apache.hadoop.dfs.FSNamesystem.checkAncestorAccess(FSNamesystem.java:4100) [junit] at org.apache.hadoop.dfs.FSNamesystem.mkdirsInternal(FSNamesystem.java:1588) [junit] at org.apache.hadoop.dfs.FSNamesystem.mkdirs(FSNamesystem.java:1571) [junit] at org.apache.hadoop.dfs.NameNode.mkdirs(NameNode.java:424) [junit] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [junit] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) [junit] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) [junit] at java.lang.reflect.Method.invoke(Method.java:585) [junit] at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:409) [junit] at org.apache.hadoop.ipc.Server$Handler.run(Server.java:899) [junit] 2008-03-05 15:59:46,570 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 9 on 48957, ugi=null [junit] 2008-03-05 15:59:46,578 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 8 on 48957, ugi=Who,group1,group2 [junit] 2008-03-05 15:59:46,579 DEBUG security.UserGroupInformation (PermissionChecker.java:(40)) - ugi=Who,group1,group2 [junit] 2008-03-05 15:59:46,579 DEBUG security.UserGroupInformation (PermissionChecker.java:checkPermission(87)) - ACCESS CHECK: org.apache.hadoop.dfs.PermissionChecker@1762fc7, doCheckOwner=false, ancestorAccess=null, parentAccess=null, access=null, subAccess=null [junit] 2008-03-05 15:59:46,580 DEBUG security.UserGroupInformation (PermissionChecker.java:(40)) - ugi=Who,group1,group2 [junit] 2008-03-05 15:59:46,580 DEBUG security.UserGroupInformation (PermissionChecker.java:checkPermission(87)) - ACCESS CHECK: org.apache.hadoop.dfs.PermissionChecker@3aef16, doCheckOwner=false, ancestorAccess=WRITE, parentAccess=null, access=null, subAccess=null [junit] 2008-03-05 15:59:46,581 INFO ipc.Server (Server.java:run(901)) - IPC Server handler 8 on 48957, call create(/data/file2, rwxr-xr-x, DFSClient_538887968, true, 3, 67108864) from 127.0.0.1:48976: error: org.apache.hadoop.fs.permission.AccessControlException: Permission denied: user=Who, access=WRITE, inode="data":hudson:supergroup:rwxr-xr-x [junit] org.apache.hadoop.fs.permission.AccessControlException: Permission denied: user=Who, access=WRITE, inode="data":hudson:supergroup:rwxr-xr-x [junit] at org.apache.hadoop.dfs.PermissionChecker.check(PermissionChecker.java:173) [junit] at org.apache.hadoop.dfs.PermissionChecker.check(PermissionChecker.java:154) [junit] at org.apache.hadoop.dfs.PermissionChecker.checkPermission(PermissionChecker.java:102) [junit] at org.apache.hadoop.dfs.FSNamesystem.checkPermission(FSNamesystem.java:4130) [junit] at org.apache.hadoop.dfs.FSNamesystem.checkAncestorAccess(FSNamesystem.java:4100) [junit] at org.apache.hadoop.dfs.FSNamesystem.startFileInternal(FSNamesystem.java:980) [junit] at org.apache.hadoop.dfs.FSNamesystem.startFile(FSNamesystem.java:955) [junit] at org.apache.hadoop.dfs.NameNode.create(NameNode.java:282) [junit] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [junit] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) [junit] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) [junit] at java.lang.reflect.Method.invoke(Method.java:585) [junit] at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:409) [junit] at org.apache.hadoop.ipc.Server$Handler.run(Server.java:899) [junit] 2008-03-05 15:59:46,582 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 8 on 48957, ugi=null [junit] 2008-03-05 15:59:46,583 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 7 on 48957, ugi=Who,group1,group2 [junit] 2008-03-05 15:59:46,584 DEBUG security.UserGroupInformation (PermissionChecker.java:(40)) - ugi=Who,group1,group2 [junit] 2008-03-05 15:59:46,584 DEBUG security.UserGroupInformation (PermissionChecker.java:checkPermission(87)) - ACCESS CHECK: org.apache.hadoop.dfs.PermissionChecker@126c6ea, doCheckOwner=false, ancestorAccess=null, parentAccess=null, access=READ, subAccess=null [junit] 2008-03-05 15:59:46,585 INFO ipc.Server (Server.java:run(901)) - IPC Server handler 7 on 48957, call open(/data/file1, 0, 671088640) from 127.0.0.1:48976: error: org.apache.hadoop.fs.permission.AccessControlException: Permission denied: user=Who, access=READ, inode="file1":hudson:supergroup:rw------- [junit] org.apache.hadoop.fs.permission.AccessControlException: Permission denied: user=Who, access=READ, inode="file1":hudson:supergroup:rw------- [junit] at org.apache.hadoop.dfs.PermissionChecker.check(PermissionChecker.java:173) [junit] at org.apache.hadoop.dfs.PermissionChecker.checkPermission(PermissionChecker.java:108) [junit] at org.apache.hadoop.dfs.FSNamesystem.checkPermission(FSNamesystem.java:4130) [junit] at org.apache.hadoop.dfs.FSNamesystem.checkPathAccess(FSNamesystem.java:4090) [junit] at org.apache.hadoop.dfs.FSNamesystem.getBlockLocations(FSNamesystem.java:772) [junit] at org.apache.hadoop.dfs.NameNode.getBlockLocations(NameNode.java:255) [junit] at org.apache.hadoop.dfs.NameNode.open(NameNode.java:242) [junit] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [junit] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) [junit] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) [junit] at java.lang.reflect.Method.invoke(Method.java:585) [junit] at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:409) [junit] at org.apache.hadoop.ipc.Server$Handler.run(Server.java:899) [junit] 2008-03-05 15:59:46,586 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 7 on 48957, ugi=null [junit] 2008-03-05 15:59:47,014 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 0 on 48957, ugi=null [junit] 2008-03-05 15:59:47,015 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 0 on 48957, ugi=null [junit] 2008-03-05 15:59:47,414 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 2 on 48957, ugi=null [junit] 2008-03-05 15:59:47,416 DEBUG security.UserGroupInformation (UserGroupInformation.java:setCurrentUGI(40)) - IPC Server handler 2 on 48957, ugi=null [junit] Shutting down the Mini HDFS Cluster [junit] Shutting down DataNode 2 [junit] 2008-03-05 15:59:47,555 INFO http.SocketListener (SocketListener.java:stop(212)) - Stopped SocketListener on 127.0.0.1:48967 [junit] 2008-03-05 15:59:47,556 INFO util.Container (Container.java:stop(156)) - Stopped org.mortbay.jetty.servlet.WebApplicationHandler@1417690 [junit] 2008-03-05 15:59:47,744 INFO util.Container (Container.java:stop(156)) - Stopped WebApplicationContext[/,/] [junit] 2008-03-05 15:59:47,817 INFO util.Container (Container.java:stop(156)) - Stopped HttpContext[/logs,/logs] [junit] 2008-03-05 15:59:47,900 INFO util.Container (Container.java:stop(156)) - Stopped HttpContext[/static,/static] [junit] 2008-03-05 15:59:47,901 INFO util.Container (Container.java:stop(156)) - Stopped org.mortbay.jetty.Server@160c4b0 [junit] 2008-03-05 15:59:47,902 INFO dfs.DataNode (DataNode.java:shutdown(474)) - Waiting for threadgroup to exit, active threads is 1 [junit] 2008-03-05 15:59:47,903 INFO dfs.DataNode (DataNode.java:run(2624)) - 127.0.0.1:48966:Finishing DataNode in: FSDataset{dirpath='/zonestorage/hudson/home/hudson/hudson/jobs/Hadoop-trunk/workspace/trunk/build/test/data/dfs/data/data5/current,/zonestorage/hudson/home/hudson/hudson/jobs/Hadoop-trunk/workspace/trunk/build/test/data/dfs/data/data6/current'} [junit] Shutting down DataNode 1 [junit] 2008-03-05 15:59:47,903 INFO dfs.DataBlockScanner (DataBlockScanner.java:run(561)) - Exiting DataBlockScanner thread. [junit] 2008-03-05 15:59:47,904 INFO http.SocketListener (SocketListener.java:stop(212)) - Stopped SocketListener on 127.0.0.1:48965 [junit] 2008-03-05 15:59:47,905 INFO util.Container (Container.java:stop(156)) - Stopped org.mortbay.jetty.servlet.WebApplicationHandler@16f70a4 [junit] 2008-03-05 15:59:47,974 INFO util.Container (Container.java:stop(156)) - Stopped WebApplicationContext[/,/] [junit] 2008-03-05 15:59:48,042 INFO util.Container (Container.java:stop(156)) - Stopped HttpContext[/logs,/logs] [junit] 2008-03-05 15:59:48,110 INFO util.Container (Container.java:stop(156)) - Stopped HttpContext[/static,/static] [junit] 2008-03-05 15:59:48,111 INFO util.Container (Container.java:stop(156)) - Stopped org.mortbay.jetty.Server@19b4748 [junit] 2008-03-05 15:59:48,111 INFO dfs.DataNode (DataNode.java:shutdown(474)) - Waiting for threadgroup to exit, active threads is 1 [junit] 2008-03-05 15:59:48,123 INFO dfs.DataBlockScanner (DataBlockScanner.java:run(561)) - Exiting DataBlockScanner thread. [junit] 2008-03-05 15:59:49,113 INFO dfs.DataNode (DataNode.java:shutdown(474)) - Waiting for threadgroup to exit, active threads is 0 [junit] 2008-03-05 15:59:49,114 INFO dfs.DataNode (DataNode.java:run(2624)) - 127.0.0.1:48964:Finishing DataNode in: FSDataset{dirpath='/zonestorage/hudson/home/hudson/hudson/jobs/Hadoop-trunk/workspace/trunk/build/test/data/dfs/data/data3/current,/zonestorage/hudson/home/hudson/hudson/jobs/Hadoop-trunk/workspace/trunk/build/test/data/dfs/data/data4/current'} [junit] Shutting down DataNode 0 [junit] 2008-03-05 15:59:49,114 INFO util.ThreadedServer (ThreadedServer.java:run(656)) - Stopping Acceptor ServerSocket[addr=localhost/127.0.0.1,port=0,localport=48963] [junit] 2008-03-05 15:59:49,115 INFO http.SocketListener (SocketListener.java:stop(212)) - Stopped SocketListener on 127.0.0.1:48963 [junit] 2008-03-05 15:59:49,115 INFO util.Container (Container.java:stop(156)) - Stopped org.mortbay.jetty.servlet.WebApplicationHandler@9b688e [junit] 2008-03-05 15:59:49,184 INFO util.Container (Container.java:stop(156)) - Stopped WebApplicationContext[/,/] [junit] 2008-03-05 15:59:49,249 INFO util.Container (Container.java:stop(156)) - Stopped HttpContext[/logs,/logs] [junit] 2008-03-05 15:59:49,313 INFO util.Container (Container.java:stop(156)) - Stopped HttpContext[/static,/static] [junit] 2008-03-05 15:59:49,314 INFO util.Container (Container.java:stop(156)) - Stopped org.mortbay.jetty.Server@17cd15d [junit] 2008-03-05 15:59:49,315 INFO dfs.DataNode (DataNode.java:shutdown(474)) - Waiting for threadgroup to exit, active threads is 1 [junit] 2008-03-05 15:59:49,315 INFO dfs.DataNode (DataNode.java:run(2624)) - 127.0.0.1:48962:Finishing DataNode in: FSDataset{dirpath='/zonestorage/hudson/home/hudson/hudson/jobs/Hadoop-trunk/workspace/trunk/build/test/data/dfs/data/data1/current,/zonestorage/hudson/home/hudson/hudson/jobs/Hadoop-trunk/workspace/trunk/build/test/data/dfs/data/data2/current'} [junit] 2008-03-05 15:59:49,315 INFO dfs.DataBlockScanner (DataBlockScanner.java:run(561)) - Exiting DataBlockScanner thread. [junit] 2008-03-05 15:59:49,317 INFO http.SocketListener (SocketListener.java:stop(212)) - Stopped SocketListener on 0.0.0.0:48958 [junit] 2008-03-05 15:59:49,317 INFO util.Container (Container.java:stop(156)) - Stopped org.mortbay.jetty.servlet.WebApplicationHandler@898540 [junit] 2008-03-05 15:59:49,383 INFO util.Container (Container.java:stop(156)) - Stopped WebApplicationContext[/,/] [junit] 2008-03-05 15:59:49,446 INFO util.Container (Container.java:stop(156)) - Stopped HttpContext[/logs,/logs] [junit] 2008-03-05 15:59:49,507 INFO util.Container (Container.java:stop(156)) - Stopped HttpContext[/static,/static] [junit] 2008-03-05 15:59:49,507 INFO util.Container (Container.java:stop(156)) - Stopped org.mortbay.jetty.Server@4d41e2 [junit] 2008-03-05 15:59:49,508 ERROR fs.FSNamesystem (FSNamesystem.java:run(1901)) - java.lang.InterruptedException: sleep interrupted [junit] at java.lang.Thread.sleep(Native Method) [junit] at org.apache.hadoop.dfs.FSNamesystem$ResolutionMonitor.run(FSNamesystem.java:1879) [junit] at java.lang.Thread.run(Thread.java:595) [junit] [junit] 2008-03-05 15:59:49,508 INFO fs.FSNamesystem (FSEditLog.java:printStatistics(845)) - Number of transactions: 6 Total time for transactions(ms): 0 Number of syncs: 4 SyncTimes(ms): 53 37 [junit] 2008-03-05 15:59:49,509 INFO ipc.Server (Server.java:stop(1004)) - Stopping server on 48957 [junit] 2008-03-05 15:59:49,509 INFO ipc.Server (Server.java:run(931)) - IPC Server handler 0 on 48957: exiting [junit] 2008-03-05 15:59:49,510 INFO ipc.Server (Server.java:run(931)) - IPC Server handler 2 on 48957: exiting [junit] 2008-03-05 15:59:49,510 INFO ipc.Server (Server.java:run(931)) - IPC Server handler 9 on 48957: exiting [junit] 2008-03-05 15:59:49,510 INFO ipc.Server (Server.java:run(931)) - IPC Server handler 6 on 48957: exiting [junit] 2008-03-05 15:59:49,511 INFO ipc.Server (Server.java:run(495)) - Stopping IPC Server Responder [junit] 2008-03-05 15:59:49,512 INFO ipc.Server (Server.java:run(931)) - IPC Server handler 5 on 48957: exiting [junit] 2008-03-05 15:59:49,512 INFO ipc.Server (Server.java:run(931)) - IPC Server handler 7 on 48957: exiting [junit] 2008-03-05 15:59:49,512 INFO ipc.Server (Server.java:run(931)) - IPC Server handler 8 on 48957: exiting [junit] Tests run: 2, Failures: 0, Errors: 0, Time elapsed: 22.921 sec [junit] 2008-03-05 15:59:49,510 INFO ipc.Server (Server.java:run(931)) - IPC Server handler 1 on 48957: exiting [junit] 2008-03-05 15:59:49,510 INFO ipc.Server (Server.java:run(931)) - IPC Server handler 4 on 48957: exiting [junit] 2008-03-05 15:59:49,509 INFO ipc.Server (Server.java:run(931)) - IPC Server handler 3 on 48957: exiting [junit] Running org.apache.hadoop.security.TestUnixUserGroupInformation [junit] Tests run: 4, Failures: 0, Errors: 0, Time elapsed: 0.464 sec [junit] Running org.apache.hadoop.util.TestReflectionUtils [junit] Tests run: 4, Failures: 0, Errors: 0, Time elapsed: 0.667 sec [junit] Running org.apache.hadoop.util.TestShell [junit] Tests run: 1, Failures: 0, Errors: 0, Time elapsed: 0.378 sec BUILD FAILED /zonestorage/hudson/home/hudson/hudson/jobs/Hadoop-trunk/workspace/trunk/build.xml:570: Tests failed! Total time: 106 minutes 52 seconds Recording fingerprints Publishing Javadoc Recording test results Updating HADOOP-2861 Updating HADOOP-2883