FAQ
See http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/3/

------------------------------------------
[...truncated 286679 lines...]
[junit] 2009-06-25 12:42:02,252 INFO common.Storage (DataStorage.java:recoverTransitionRead(123)) - Formatting ...
[junit] 2009-06-25 12:42:02,534 INFO datanode.DataNode (FSDataset.java:registerMBean(1417)) - Registered FSDatasetStatusMBean
[junit] 2009-06-25 12:42:02,535 INFO datanode.DataNode (DataNode.java:startDataNode(326)) - Opened info server at 56993
[junit] 2009-06-25 12:42:02,535 INFO datanode.DataNode (DataXceiverServer.java:<init>(74)) - Balancing bandwith is 1048576 bytes/s
[junit] 2009-06-25 12:42:02,535 INFO datanode.DirectoryScanner (DirectoryScanner.java:<init>(133)) - scan starts at 1245953187535 with interval 21600000
[junit] 2009-06-25 12:42:02,537 INFO http.HttpServer (HttpServer.java:start(425)) - Port returned by webServer.getConnectors()[0].getLocalPort() before open() is -1. Opening the listener on 0
[junit] 2009-06-25 12:42:02,537 INFO http.HttpServer (HttpServer.java:start(430)) - listener.getLocalPort() returned 37123 webServer.getConnectors()[0].getLocalPort() returned 37123
[junit] 2009-06-25 12:42:02,538 INFO http.HttpServer (HttpServer.java:start(463)) - Jetty bound to port 37123
[junit] 2009-06-25 12:42:02,538 INFO mortbay.log (?:invoke(?)) - jetty-6.1.14
[junit] 2009-06-25 12:42:02,604 INFO mortbay.log (?:invoke(?)) - Started SelectChannelConnector@localhost:37123
[junit] 2009-06-25 12:42:02,605 INFO jvm.JvmMetrics (JvmMetrics.java:init(66)) - Cannot initialize JVM Metrics with processName=DataNode, sessionId=null - already initialized
[junit] 2009-06-25 12:42:02,617 INFO metrics.RpcMetrics (RpcMetrics.java:<init>(58)) - Initializing RPC Metrics with hostName=DataNode, port=49739
[junit] 2009-06-25 12:42:02,617 INFO ipc.Server (Server.java:run(474)) - IPC Server Responder: starting
[junit] 2009-06-25 12:42:02,618 INFO datanode.DataNode (DataNode.java:startDataNode(404)) - dnRegistration = DatanodeRegistration(vesta.apache.org:56993, storageID=, infoPort=37123, ipcPort=49739)
[junit] 2009-06-25 12:42:02,618 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 1 on 49739: starting
[junit] 2009-06-25 12:42:02,618 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 0 on 49739: starting
[junit] 2009-06-25 12:42:02,617 INFO ipc.Server (Server.java:run(313)) - IPC Server listener on 49739: starting
[junit] 2009-06-25 12:42:02,618 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 2 on 49739: starting
[junit] 2009-06-25 12:42:02,620 INFO hdfs.StateChange (FSNamesystem.java:registerDatanode(1769)) - BLOCK* NameSystem.registerDatanode: node registration from 127.0.0.1:56993 storage DS-639695067-67.195.138.9-56993-1245933722618
[junit] 2009-06-25 12:42:02,620 INFO net.NetworkTopology (NetworkTopology.java:add(327)) - Adding a new node: /default-rack/127.0.0.1:56993
[junit] 2009-06-25 12:42:02,667 INFO datanode.DataNode (DataNode.java:register(566)) - New storage id DS-639695067-67.195.138.9-56993-1245933722618 is assigned to data-node 127.0.0.1:56993
[junit] 2009-06-25 12:42:02,668 INFO datanode.DataNode (DataNode.java:run(1253)) - DatanodeRegistration(127.0.0.1:56993, storageID=DS-639695067-67.195.138.9-56993-1245933722618, infoPort=37123, ipcPort=49739)In DataNode.run, data = FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data1/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build/test/data/dfs/data/data2/current'}
[junit] Starting DataNode 1 with dfs.data.dir: http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data3,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build/test/data/dfs/data/data4
[junit] 2009-06-25 12:42:02,668 INFO datanode.DataNode (DataNode.java:offerService(734)) - using BLOCKREPORT_INTERVAL of 21600000msec Initial delay: 0msec
[junit] 2009-06-25 12:42:02,678 INFO common.Storage (DataStorage.java:recoverTransitionRead(122)) - Storage directory http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data3 is not formatted.
[junit] 2009-06-25 12:42:02,679 INFO common.Storage (DataStorage.java:recoverTransitionRead(123)) - Formatting ...
[junit] 2009-06-25 12:42:02,715 INFO datanode.DataNode (DataNode.java:blockReport(969)) - BlockReport of 0 blocks got processed in 1 msecs
[junit] 2009-06-25 12:42:02,715 INFO datanode.DataNode (DataNode.java:offerService(777)) - Starting Periodic block scanner.
[junit] 2009-06-25 12:42:02,746 INFO mapred.JvmManager (JvmManager.java:runChild(411)) - JVM : jvm_200906251240_0004_m_-1309382494 exited. Number of tasks it ran: 1
[junit] 2009-06-25 12:42:02,884 INFO common.Storage (DataStorage.java:recoverTransitionRead(122)) - Storage directory http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data4 is not formatted.
[junit] 2009-06-25 12:42:02,884 INFO common.Storage (DataStorage.java:recoverTransitionRead(123)) - Formatting ...
[junit] 2009-06-25 12:42:03,161 INFO datanode.DataNode (FSDataset.java:registerMBean(1417)) - Registered FSDatasetStatusMBean
[junit] 2009-06-25 12:42:03,161 INFO datanode.DataNode (DataNode.java:startDataNode(326)) - Opened info server at 47252
[junit] 2009-06-25 12:42:03,161 INFO datanode.DataNode (DataXceiverServer.java:<init>(74)) - Balancing bandwith is 1048576 bytes/s
[junit] 2009-06-25 12:42:03,162 INFO datanode.DirectoryScanner (DirectoryScanner.java:<init>(133)) - scan starts at 1245952108162 with interval 21600000
[junit] 2009-06-25 12:42:03,163 INFO http.HttpServer (HttpServer.java:start(425)) - Port returned by webServer.getConnectors()[0].getLocalPort() before open() is -1. Opening the listener on 0
[junit] 2009-06-25 12:42:03,163 INFO http.HttpServer (HttpServer.java:start(430)) - listener.getLocalPort() returned 40982 webServer.getConnectors()[0].getLocalPort() returned 40982
[junit] 2009-06-25 12:42:03,164 INFO http.HttpServer (HttpServer.java:start(463)) - Jetty bound to port 40982
[junit] 2009-06-25 12:42:03,164 INFO mortbay.log (?:invoke(?)) - jetty-6.1.14
[junit] 2009-06-25 12:42:03,226 INFO mortbay.log (?:invoke(?)) - Started SelectChannelConnector@localhost:40982
[junit] 2009-06-25 12:42:03,226 INFO jvm.JvmMetrics (JvmMetrics.java:init(66)) - Cannot initialize JVM Metrics with processName=DataNode, sessionId=null - already initialized
[junit] 2009-06-25 12:42:03,238 INFO metrics.RpcMetrics (RpcMetrics.java:<init>(58)) - Initializing RPC Metrics with hostName=DataNode, port=58490
[junit] 2009-06-25 12:42:03,239 INFO ipc.Server (Server.java:run(474)) - IPC Server Responder: starting
[junit] 2009-06-25 12:42:03,239 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 1 on 58490: starting
[junit] 2009-06-25 12:42:03,239 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 0 on 58490: starting
[junit] 2009-06-25 12:42:03,239 INFO ipc.Server (Server.java:run(313)) - IPC Server listener on 58490: starting
[junit] 2009-06-25 12:42:03,240 INFO datanode.DataNode (DataNode.java:startDataNode(404)) - dnRegistration = DatanodeRegistration(vesta.apache.org:47252, storageID=, infoPort=40982, ipcPort=58490)
[junit] 2009-06-25 12:42:03,240 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 2 on 58490: starting
[junit] 2009-06-25 12:42:03,242 INFO hdfs.StateChange (FSNamesystem.java:registerDatanode(1769)) - BLOCK* NameSystem.registerDatanode: node registration from 127.0.0.1:47252 storage DS-320199961-67.195.138.9-47252-1245933723241
[junit] 2009-06-25 12:42:03,242 INFO net.NetworkTopology (NetworkTopology.java:add(327)) - Adding a new node: /default-rack/127.0.0.1:47252
[junit] 2009-06-25 12:42:03,317 INFO datanode.DataNode (DataNode.java:register(566)) - New storage id DS-320199961-67.195.138.9-47252-1245933723241 is assigned to data-node 127.0.0.1:47252
[junit] 2009-06-25 12:42:03,317 INFO datanode.DataNode (DataNode.java:run(1253)) - DatanodeRegistration(127.0.0.1:47252, storageID=DS-320199961-67.195.138.9-47252-1245933723241, infoPort=40982, ipcPort=58490)In DataNode.run, data = FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data3/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build/test/data/dfs/data/data4/current'}
[junit] Starting DataNode 2 with dfs.data.dir: http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data5,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build/test/data/dfs/data/data6
[junit] 2009-06-25 12:42:03,318 INFO datanode.DataNode (DataNode.java:offerService(734)) - using BLOCKREPORT_INTERVAL of 21600000msec Initial delay: 0msec
[junit] 2009-06-25 12:42:03,327 INFO common.Storage (DataStorage.java:recoverTransitionRead(122)) - Storage directory http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data5 is not formatted.
[junit] 2009-06-25 12:42:03,327 INFO common.Storage (DataStorage.java:recoverTransitionRead(123)) - Formatting ...
[junit] 2009-06-25 12:42:03,354 INFO datanode.DataNode (DataNode.java:blockReport(969)) - BlockReport of 0 blocks got processed in 0 msecs
[junit] 2009-06-25 12:42:03,354 INFO datanode.DataNode (DataNode.java:offerService(777)) - Starting Periodic block scanner.
[junit] 2009-06-25 12:42:03,516 INFO common.Storage (DataStorage.java:recoverTransitionRead(122)) - Storage directory http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data6 is not formatted.
[junit] 2009-06-25 12:42:03,517 INFO common.Storage (DataStorage.java:recoverTransitionRead(123)) - Formatting ...
[junit] 2009-06-25 12:42:03,778 INFO datanode.DataNode (FSDataset.java:registerMBean(1417)) - Registered FSDatasetStatusMBean
[junit] 2009-06-25 12:42:03,778 INFO datanode.DataNode (DataNode.java:startDataNode(326)) - Opened info server at 32836
[junit] 2009-06-25 12:42:03,779 INFO datanode.DataNode (DataXceiverServer.java:<init>(74)) - Balancing bandwith is 1048576 bytes/s
[junit] 2009-06-25 12:42:03,779 INFO datanode.DirectoryScanner (DirectoryScanner.java:<init>(133)) - scan starts at 1245935681779 with interval 21600000
[junit] 2009-06-25 12:42:03,781 INFO http.HttpServer (HttpServer.java:start(425)) - Port returned by webServer.getConnectors()[0].getLocalPort() before open() is -1. Opening the listener on 0
[junit] 2009-06-25 12:42:03,782 INFO http.HttpServer (HttpServer.java:start(430)) - listener.getLocalPort() returned 40224 webServer.getConnectors()[0].getLocalPort() returned 40224
[junit] 2009-06-25 12:42:03,782 INFO http.HttpServer (HttpServer.java:start(463)) - Jetty bound to port 40224
[junit] 2009-06-25 12:42:03,782 INFO mortbay.log (?:invoke(?)) - jetty-6.1.14
[junit] 2009-06-25 12:42:03,850 INFO mortbay.log (?:invoke(?)) - Started SelectChannelConnector@localhost:40224
[junit] 2009-06-25 12:42:03,853 INFO jvm.JvmMetrics (JvmMetrics.java:init(66)) - Cannot initialize JVM Metrics with processName=DataNode, sessionId=null - already initialized
[junit] 2009-06-25 12:42:03,865 INFO metrics.RpcMetrics (RpcMetrics.java:<init>(58)) - Initializing RPC Metrics with hostName=DataNode, port=38119
[junit] 2009-06-25 12:42:03,866 INFO ipc.Server (Server.java:run(474)) - IPC Server Responder: starting
[junit] 2009-06-25 12:42:03,866 INFO datanode.DataNode (DataNode.java:startDataNode(404)) - dnRegistration = DatanodeRegistration(vesta.apache.org:32836, storageID=, infoPort=40224, ipcPort=38119)
[junit] 2009-06-25 12:42:03,866 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 1 on 38119: starting
[junit] 2009-06-25 12:42:03,866 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 0 on 38119: starting
[junit] 2009-06-25 12:42:03,866 INFO ipc.Server (Server.java:run(313)) - IPC Server listener on 38119: starting
[junit] 2009-06-25 12:42:03,867 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 2 on 38119: starting
[junit] 2009-06-25 12:42:03,869 INFO hdfs.StateChange (FSNamesystem.java:registerDatanode(1769)) - BLOCK* NameSystem.registerDatanode: node registration from 127.0.0.1:32836 storage DS-530170639-67.195.138.9-32836-1245933723867
[junit] 2009-06-25 12:42:03,869 INFO net.NetworkTopology (NetworkTopology.java:add(327)) - Adding a new node: /default-rack/127.0.0.1:32836
[junit] 2009-06-25 12:42:03,936 INFO datanode.DataNode (DataNode.java:register(566)) - New storage id DS-530170639-67.195.138.9-32836-1245933723867 is assigned to data-node 127.0.0.1:32836
[junit] 2009-06-25 12:42:03,937 INFO datanode.DataNode (DataNode.java:run(1253)) - DatanodeRegistration(127.0.0.1:32836, storageID=DS-530170639-67.195.138.9-32836-1245933723867, infoPort=40224, ipcPort=38119)In DataNode.run, data = FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data5/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build/test/data/dfs/data/data6/current'}
[junit] Starting DataNode 3 with dfs.data.dir: http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data7,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build/test/data/dfs/data/data8
[junit] 2009-06-25 12:42:03,937 INFO datanode.DataNode (DataNode.java:offerService(734)) - using BLOCKREPORT_INTERVAL of 21600000msec Initial delay: 0msec
[junit] 2009-06-25 12:42:03,947 INFO common.Storage (DataStorage.java:recoverTransitionRead(122)) - Storage directory http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data7 is not formatted.
[junit] 2009-06-25 12:42:03,948 INFO common.Storage (DataStorage.java:recoverTransitionRead(123)) - Formatting ...
[junit] 2009-06-25 12:42:03,982 INFO datanode.DataNode (DataNode.java:blockReport(969)) - BlockReport of 0 blocks got processed in 0 msecs
[junit] 2009-06-25 12:42:03,983 INFO datanode.DataNode (DataNode.java:offerService(777)) - Starting Periodic block scanner.
[junit] 2009-06-25 12:42:04,145 INFO common.Storage (DataStorage.java:recoverTransitionRead(122)) - Storage directory http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data8 is not formatted.
[junit] 2009-06-25 12:42:04,146 INFO common.Storage (DataStorage.java:recoverTransitionRead(123)) - Formatting ...
[junit] 2009-06-25 12:42:04,392 INFO datanode.DataNode (FSDataset.java:registerMBean(1417)) - Registered FSDatasetStatusMBean
[junit] 2009-06-25 12:42:04,393 INFO datanode.DataNode (DataNode.java:startDataNode(326)) - Opened info server at 48287
[junit] 2009-06-25 12:42:04,393 INFO datanode.DataNode (DataXceiverServer.java:<init>(74)) - Balancing bandwith is 1048576 bytes/s
[junit] 2009-06-25 12:42:04,393 INFO datanode.DirectoryScanner (DirectoryScanner.java:<init>(133)) - scan starts at 1245950459393 with interval 21600000
[junit] 2009-06-25 12:42:04,395 INFO http.HttpServer (HttpServer.java:start(425)) - Port returned by webServer.getConnectors()[0].getLocalPort() before open() is -1. Opening the listener on 0
[junit] 2009-06-25 12:42:04,395 INFO http.HttpServer (HttpServer.java:start(430)) - listener.getLocalPort() returned 44888 webServer.getConnectors()[0].getLocalPort() returned 44888
[junit] 2009-06-25 12:42:04,396 INFO http.HttpServer (HttpServer.java:start(463)) - Jetty bound to port 44888
[junit] 2009-06-25 12:42:04,396 INFO mortbay.log (?:invoke(?)) - jetty-6.1.14
[junit] 2009-06-25 12:42:04,542 INFO mortbay.log (?:invoke(?)) - Started SelectChannelConnector@localhost:44888
[junit] 2009-06-25 12:42:04,543 INFO jvm.JvmMetrics (JvmMetrics.java:init(66)) - Cannot initialize JVM Metrics with processName=DataNode, sessionId=null - already initialized
[junit] 2009-06-25 12:42:04,554 INFO metrics.RpcMetrics (RpcMetrics.java:<init>(58)) - Initializing RPC Metrics with hostName=DataNode, port=59143
[junit] 2009-06-25 12:42:04,555 INFO ipc.Server (Server.java:run(474)) - IPC Server Responder: starting
[junit] 2009-06-25 12:42:04,555 INFO datanode.DataNode (DataNode.java:startDataNode(404)) - dnRegistration = DatanodeRegistration(vesta.apache.org:48287, storageID=, infoPort=44888, ipcPort=59143)
[junit] 2009-06-25 12:42:04,555 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 2 on 59143: starting
[junit] 2009-06-25 12:42:04,555 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 1 on 59143: starting
[junit] 2009-06-25 12:42:04,555 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 0 on 59143: starting
[junit] 2009-06-25 12:42:04,555 INFO ipc.Server (Server.java:run(313)) - IPC Server listener on 59143: starting
[junit] 2009-06-25 12:42:04,558 INFO hdfs.StateChange (FSNamesystem.java:registerDatanode(1769)) - BLOCK* NameSystem.registerDatanode: node registration from 127.0.0.1:48287 storage DS-1148706719-67.195.138.9-48287-1245933724556
[junit] 2009-06-25 12:42:04,558 INFO net.NetworkTopology (NetworkTopology.java:add(327)) - Adding a new node: /default-rack/127.0.0.1:48287
[junit] 2009-06-25 12:42:04,602 INFO datanode.DataNode (DataNode.java:register(566)) - New storage id DS-1148706719-67.195.138.9-48287-1245933724556 is assigned to data-node 127.0.0.1:48287
[junit] 2009-06-25 12:42:04,603 INFO datanode.DataNode (DataNode.java:run(1253)) - DatanodeRegistration(127.0.0.1:48287, storageID=DS-1148706719-67.195.138.9-48287-1245933724556, infoPort=44888, ipcPort=59143)In DataNode.run, data = FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data7/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build/test/data/dfs/data/data8/current'}
[junit] 2009-06-25 12:42:04,609 INFO datanode.DataNode (DataNode.java:offerService(734)) - using BLOCKREPORT_INTERVAL of 21600000msec Initial delay: 0msec
[junit] 2009-06-25 12:42:04,662 INFO datanode.DataNode (DataNode.java:blockReport(969)) - BlockReport of 0 blocks got processed in 1 msecs
[junit] 2009-06-25 12:42:04,663 INFO datanode.DataNode (DataNode.java:offerService(777)) - Starting Periodic block scanner.
[junit] <property><name>security.client.protocol.acl</name><value>*</value></property>
[junit]
[junit] <property><name>security.client.datanode.protocol.acl</name><value>*</value></property>
[junit]
[junit] <property><name>security.datanode.protocol.acl</name><value>*</value></property>
[junit]
[junit] <property><name>security.inter.datanode.protocol.acl</name><value>*</value></property>
[junit]
[junit] <property><name>security.namenode.protocol.acl</name><value>*</value></property>
[junit]
[junit] <property><name>security.refresh.policy.protocol.acl</name><value>nouser nogroup</value></property>
[junit]
[junit] 2009-06-25 12:42:04,699 INFO authorize.ServiceAuthorizationManager (ServiceAuthorizationManager.java:run(92)) - Authorization failed for dev,null
[junit] java.security.AccessControlException: access denied ConnectionPermission(org.apache.hadoop.security.authorize.RefreshAuthorizationPolicyProtocol)
[junit] at java.security.AccessControlContext.checkPermission(AccessControlContext.java:323)
[junit] at java.security.AccessController.checkPermission(AccessController.java:546)
[junit] at org.apache.hadoop.security.authorize.ServiceAuthorizationManager$1.run(ServiceAuthorizationManager.java:89)
[junit] at org.apache.hadoop.security.authorize.ServiceAuthorizationManager$1.run(ServiceAuthorizationManager.java:84)
[junit] at java.security.AccessController.doPrivileged(Native Method)
[junit] at javax.security.auth.Subject.doAs(Subject.java:396)
[junit] at org.apache.hadoop.security.authorize.ServiceAuthorizationManager.checkPermission(ServiceAuthorizationManager.java:83)
[junit] at org.apache.hadoop.security.authorize.ServiceAuthorizationManager.authorize(ServiceAuthorizationManager.java:68)
[junit] at org.apache.hadoop.ipc.RPC$Server.authorize(RPC.java:565)
[junit] at org.apache.hadoop.ipc.Server$Connection.readAndProcess(Server.java:858)
[junit] at org.apache.hadoop.ipc.Server$Listener.doRead(Server.java:420)
[junit] at org.apache.hadoop.ipc.Server$Listener.run(Server.java:328)
[junit] Good, refresh worked... refresh failed with:
[junit] Shutting down the Mini HDFS Cluster
[junit] Shutting down DataNode 3
[junit] 2009-06-25 12:42:04,812 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 59143
[junit] 2009-06-25 12:42:04,813 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 59143: exiting
[junit] 2009-06-25 12:42:04,813 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 59143: exiting
[junit] 2009-06-25 12:42:04,817 INFO datanode.DataNode (DataNode.java:shutdown(638)) - Waiting for threadgroup to exit, active threads is 1
[junit] 2009-06-25 12:42:04,815 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 59143: exiting
[junit] 2009-06-25 12:42:04,813 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
[junit] 2009-06-25 12:42:04,813 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 59143
[junit] 2009-06-25 12:42:04,817 WARN datanode.DataNode (DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:48287, storageID=DS-1148706719-67.195.138.9-48287-1245933724556, infoPort=44888, ipcPort=59143):DataXceiveServer: java.nio.channels.AsynchronousCloseException
[junit] at java.nio.channels.spi.AbstractInterruptibleChannel.end(AbstractInterruptibleChannel.java:185)
[junit] at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:152)
[junit] at sun.nio.ch.ServerSocketAdaptor.accept(ServerSocketAdaptor.java:84)
[junit] at org.apache.hadoop.hdfs.server.datanode.DataXceiverServer.run(DataXceiverServer.java:130)
[junit] at java.lang.Thread.run(Thread.java:619)
[junit]
[junit] 2009-06-25 12:42:04,820 INFO datanode.DataNode (DataNode.java:shutdown(638)) - Waiting for threadgroup to exit, active threads is 0
[junit] 2009-06-25 12:42:04,821 INFO datanode.DataBlockScanner (DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
[junit] 2009-06-25 12:42:04,824 INFO datanode.DataNode (DataNode.java:run(1273)) - DatanodeRegistration(127.0.0.1:48287, storageID=DS-1148706719-67.195.138.9-48287-1245933724556, infoPort=44888, ipcPort=59143):Finishing DataNode in: FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data7/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build/test/data/dfs/data/data8/current'}
[junit] 2009-06-25 12:42:04,824 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 59143
[junit] 2009-06-25 12:42:04,824 INFO datanode.DataNode (DataNode.java:shutdown(638)) - Waiting for threadgroup to exit, active threads is 0
[junit] Shutting down DataNode 2
[junit] 2009-06-25 12:42:04,930 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 38119
[junit] 2009-06-25 12:42:04,930 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 38119: exiting
[junit] 2009-06-25 12:42:04,930 INFO datanode.DataNode (DataNode.java:shutdown(638)) - Waiting for threadgroup to exit, active threads is 1
[junit] 2009-06-25 12:42:04,930 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 38119
[junit] 2009-06-25 12:42:04,931 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 38119: exiting
[junit] 2009-06-25 12:42:04,930 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
[junit] 2009-06-25 12:42:04,931 WARN datanode.DataNode (DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:32836, storageID=DS-530170639-67.195.138.9-32836-1245933723867, infoPort=40224, ipcPort=38119):DataXceiveServer: java.nio.channels.AsynchronousCloseException
[junit] at java.nio.channels.spi.AbstractInterruptibleChannel.end(AbstractInterruptibleChannel.java:185)
[junit] at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:152)
[junit] at sun.nio.ch.ServerSocketAdaptor.accept(ServerSocketAdaptor.java:84)
[junit] at org.apache.hadoop.hdfs.server.datanode.DataXceiverServer.run(DataXceiverServer.java:130)
[junit] at java.lang.Thread.run(Thread.java:619)
[junit]
[junit] 2009-06-25 12:42:04,930 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 38119: exiting
[junit] 2009-06-25 12:42:04,933 INFO datanode.DataNode (DataNode.java:shutdown(638)) - Waiting for threadgroup to exit, active threads is 0
[junit] 2009-06-25 12:42:04,933 INFO datanode.DataBlockScanner (DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
[junit] 2009-06-25 12:42:04,934 INFO datanode.DataNode (DataNode.java:run(1273)) - DatanodeRegistration(127.0.0.1:32836, storageID=DS-530170639-67.195.138.9-32836-1245933723867, infoPort=40224, ipcPort=38119):Finishing DataNode in: FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data5/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build/test/data/dfs/data/data6/current'}
[junit] 2009-06-25 12:42:04,934 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 38119
[junit] 2009-06-25 12:42:04,934 INFO datanode.DataNode (DataNode.java:shutdown(638)) - Waiting for threadgroup to exit, active threads is 0
[junit] Shutting down DataNode 1
[junit] 2009-06-25 12:42:05,072 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 58490
[junit] 2009-06-25 12:42:05,072 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 58490: exiting
[junit] 2009-06-25 12:42:05,073 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 58490: exiting
[junit] 2009-06-25 12:42:05,073 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 58490: exiting
[junit] 2009-06-25 12:42:05,073 INFO datanode.DataNode (DataNode.java:shutdown(638)) - Waiting for threadgroup to exit, active threads is 1
[junit] 2009-06-25 12:42:05,073 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 58490
[junit] 2009-06-25 12:42:05,073 WARN datanode.DataNode (DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:47252, storageID=DS-320199961-67.195.138.9-47252-1245933723241, infoPort=40982, ipcPort=58490):DataXceiveServer: java.nio.channels.AsynchronousCloseException
[junit] at java.nio.channels.spi.AbstractInterruptibleChannel.end(AbstractInterruptibleChannel.java:185)
[junit] at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:152)
[junit] at sun.nio.ch.ServerSocketAdaptor.accept(ServerSocketAdaptor.java:84)
[junit] at org.apache.hadoop.hdfs.server.datanode.DataXceiverServer.run(DataXceiverServer.java:130)
[junit] at java.lang.Thread.run(Thread.java:619)
[junit]
[junit] 2009-06-25 12:42:05,073 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
[junit] 2009-06-25 12:42:05,076 INFO datanode.DataNode (DataNode.java:shutdown(638)) - Waiting for threadgroup to exit, active threads is 0
[junit] 2009-06-25 12:42:05,076 INFO datanode.DataBlockScanner (DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
[junit] 2009-06-25 12:42:05,076 INFO datanode.DataNode (DataNode.java:run(1273)) - DatanodeRegistration(127.0.0.1:47252, storageID=DS-320199961-67.195.138.9-47252-1245933723241, infoPort=40982, ipcPort=58490):Finishing DataNode in: FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data3/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build/test/data/dfs/data/data4/current'}
[junit] 2009-06-25 12:42:05,076 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 58490
[junit] 2009-06-25 12:42:05,077 INFO datanode.DataNode (DataNode.java:shutdown(638)) - Waiting for threadgroup to exit, active threads is 0
[junit] Shutting down DataNode 0
[junit] 2009-06-25 12:42:05,178 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 49739
[junit] 2009-06-25 12:42:05,179 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 49739
[junit] 2009-06-25 12:42:05,179 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 49739: exiting
[junit] 2009-06-25 12:42:05,179 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 49739: exiting
[junit] 2009-06-25 12:42:05,179 INFO datanode.DataNode (DataNode.java:shutdown(638)) - Waiting for threadgroup to exit, active threads is 1
[junit] 2009-06-25 12:42:05,179 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
[junit] 2009-06-25 12:42:05,179 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 49739: exiting
[junit] 2009-06-25 12:42:05,179 WARN datanode.DataNode (DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:56993, storageID=DS-639695067-67.195.138.9-56993-1245933722618, infoPort=37123, ipcPort=49739):DataXceiveServer: java.nio.channels.AsynchronousCloseException
[junit] at java.nio.channels.spi.AbstractInterruptibleChannel.end(AbstractInterruptibleChannel.java:185)
[junit] at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:152)
[junit] at sun.nio.ch.ServerSocketAdaptor.accept(ServerSocketAdaptor.java:84)
[junit] at org.apache.hadoop.hdfs.server.datanode.DataXceiverServer.run(DataXceiverServer.java:130)
[junit] at java.lang.Thread.run(Thread.java:619)
[junit]
[junit] 2009-06-25 12:42:05,182 INFO datanode.DataNode (DataNode.java:shutdown(638)) - Waiting for threadgroup to exit, active threads is 0
[junit] 2009-06-25 12:42:05,182 INFO datanode.DataBlockScanner (DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
[junit] 2009-06-25 12:42:05,182 INFO datanode.DataNode (DataNode.java:run(1273)) - DatanodeRegistration(127.0.0.1:56993, storageID=DS-639695067-67.195.138.9-56993-1245933722618, infoPort=37123, ipcPort=49739):Finishing DataNode in: FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data1/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build/test/data/dfs/data/data2/current'}
[junit] 2009-06-25 12:42:05,182 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 49739
[junit] 2009-06-25 12:42:05,183 INFO datanode.DataNode (DataNode.java:shutdown(638)) - Waiting for threadgroup to exit, active threads is 0
[junit] 2009-06-25 12:42:05,285 WARN namenode.FSNamesystem (FSNamesystem.java:run(2072)) - ReplicationMonitor thread received InterruptedException.java.lang.InterruptedException: sleep interrupted
[junit] 2009-06-25 12:42:05,285 INFO namenode.FSNamesystem (FSEditLog.java:printStatistics(876)) - Number of transactions: 0 Total time for transactions(ms): 0Number of transactions batched in Syncs: 0 Number of syncs: 0 SyncTimes(ms): 0 0
[junit] 2009-06-25 12:42:05,285 WARN namenode.DecommissionManager (DecommissionManager.java:run(67)) - Monitor interrupted: java.lang.InterruptedException: sleep interrupted
[junit] 2009-06-25 12:42:05,356 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 44052
[junit] 2009-06-25 12:42:05,356 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 44052: exiting
[junit] 2009-06-25 12:42:05,356 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 3 on 44052: exiting
[junit] 2009-06-25 12:42:05,356 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 44052: exiting
[junit] 2009-06-25 12:42:05,356 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 44052: exiting
[junit] 2009-06-25 12:42:05,357 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 7 on 44052: exiting
[junit] 2009-06-25 12:42:05,357 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 5 on 44052: exiting
[junit] 2009-06-25 12:42:05,357 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 9 on 44052: exiting
[junit] 2009-06-25 12:42:05,357 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 6 on 44052: exiting
[junit] 2009-06-25 12:42:05,357 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 4 on 44052: exiting
[junit] 2009-06-25 12:42:05,357 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 8 on 44052: exiting
[junit] 2009-06-25 12:42:05,359 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 44052
[junit] 2009-06-25 12:42:05,359 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
[junit] Tests run: 2, Failures: 0, Errors: 0, Time elapsed: 125.317 sec

checkfailure:

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

Total time: 68 minutes 11 seconds
Publishing Javadoc
Recording test results
Recording fingerprints
Publishing Clover coverage report...

Search Discussions

  • Apache Hudson Server at Jun 26, 2009 at 12:50 pm
    See http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/4/changes

    Changes:

    [shv] HDFS-352. Documentation for saveNamespace command. Contributed by Ravi Phulari.

    [szetszwo] HDFS-181. Validate src path in FSNamesystem.getFileInfo(..). Contributed by Todd Lipcon

    [szetszwo] HDFS-444. Allow to change probability levels dynamically in the fault injection framework. Contributed by Konstantin Boudnik

    ------------------------------------------
    [...truncated 287329 lines...]
    [junit] 2009-06-26 12:49:00,926 INFO common.Storage (DataStorage.java:recoverTransitionRead(123)) - Formatting ...
    [junit] 2009-06-26 12:49:01,119 INFO common.Storage (DataStorage.java:recoverTransitionRead(122)) - Storage directory http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data2 is not formatted.
    [junit] 2009-06-26 12:49:01,119 INFO common.Storage (DataStorage.java:recoverTransitionRead(123)) - Formatting ...
    [junit] 2009-06-26 12:49:01,330 INFO mapred.JvmManager (JvmManager.java:runChild(411)) - JVM : jvm_200906261247_0004_m_-1788316031 exited. Number of tasks it ran: 1
    [junit] 2009-06-26 12:49:01,380 INFO datanode.DataNode (FSDataset.java:registerMBean(1417)) - Registered FSDatasetStatusMBean
    [junit] 2009-06-26 12:49:01,380 INFO datanode.DataNode (DataNode.java:startDataNode(326)) - Opened info server at 41323
    [junit] 2009-06-26 12:49:01,380 INFO datanode.DataNode (DataXceiverServer.java:<init>(74)) - Balancing bandwith is 1048576 bytes/s
    [junit] 2009-06-26 12:49:01,381 INFO datanode.DirectoryScanner (DirectoryScanner.java:<init>(133)) - scan starts at 1246020929381 with interval 21600000
    [junit] 2009-06-26 12:49:01,382 INFO http.HttpServer (HttpServer.java:start(425)) - Port returned by webServer.getConnectors()[0].getLocalPort() before open() is -1. Opening the listener on 0
    [junit] 2009-06-26 12:49:01,383 INFO http.HttpServer (HttpServer.java:start(430)) - listener.getLocalPort() returned 60349 webServer.getConnectors()[0].getLocalPort() returned 60349
    [junit] 2009-06-26 12:49:01,383 INFO http.HttpServer (HttpServer.java:start(463)) - Jetty bound to port 60349
    [junit] 2009-06-26 12:49:01,383 INFO mortbay.log (?:invoke(?)) - jetty-6.1.14
    [junit] 2009-06-26 12:49:01,448 INFO mortbay.log (?:invoke(?)) - Started SelectChannelConnector@localhost:60349
    [junit] 2009-06-26 12:49:01,449 INFO jvm.JvmMetrics (JvmMetrics.java:init(66)) - Cannot initialize JVM Metrics with processName=DataNode, sessionId=null - already initialized
    [junit] 2009-06-26 12:49:01,461 INFO metrics.RpcMetrics (RpcMetrics.java:<init>(58)) - Initializing RPC Metrics with hostName=DataNode, port=57930
    [junit] 2009-06-26 12:49:01,462 INFO ipc.Server (Server.java:run(474)) - IPC Server Responder: starting
    [junit] 2009-06-26 12:49:01,462 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 0 on 57930: starting
    [junit] 2009-06-26 12:49:01,462 INFO ipc.Server (Server.java:run(313)) - IPC Server listener on 57930: starting
    [junit] 2009-06-26 12:49:01,464 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 2 on 57930: starting
    [junit] 2009-06-26 12:49:01,463 INFO datanode.DataNode (DataNode.java:startDataNode(404)) - dnRegistration = DatanodeRegistration(vesta.apache.org:41323, storageID=, infoPort=60349, ipcPort=57930)
    [junit] 2009-06-26 12:49:01,463 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 1 on 57930: starting
    [junit] 2009-06-26 12:49:01,511 INFO hdfs.StateChange (FSNamesystem.java:registerDatanode(1772)) - BLOCK* NameSystem.registerDatanode: node registration from 127.0.0.1:41323 storage DS-864733044-67.195.138.9-41323-1246020541510
    [junit] 2009-06-26 12:49:01,511 INFO net.NetworkTopology (NetworkTopology.java:add(327)) - Adding a new node: /default-rack/127.0.0.1:41323
    [junit] 2009-06-26 12:49:01,555 INFO datanode.DataNode (DataNode.java:register(566)) - New storage id DS-864733044-67.195.138.9-41323-1246020541510 is assigned to data-node 127.0.0.1:41323
    [junit] Starting DataNode 1 with dfs.data.dir: http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data3,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build/test/data/dfs/data/data4
    [junit] 2009-06-26 12:49:01,556 INFO datanode.DataNode (DataNode.java:run(1253)) - DatanodeRegistration(127.0.0.1:41323, storageID=DS-864733044-67.195.138.9-41323-1246020541510, infoPort=60349, ipcPort=57930)In DataNode.run, data = FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data1/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build/test/data/dfs/data/data2/current'}
    [junit] 2009-06-26 12:49:01,556 INFO datanode.DataNode (DataNode.java:offerService(734)) - using BLOCKREPORT_INTERVAL of 21600000msec Initial delay: 0msec
    [junit] 2009-06-26 12:49:01,567 INFO common.Storage (DataStorage.java:recoverTransitionRead(122)) - Storage directory http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data3 is not formatted.
    [junit] 2009-06-26 12:49:01,568 INFO common.Storage (DataStorage.java:recoverTransitionRead(123)) - Formatting ...
    [junit] 2009-06-26 12:49:01,596 INFO datanode.DataNode (DataNode.java:blockReport(969)) - BlockReport of 0 blocks got processed in 1 msecs
    [junit] 2009-06-26 12:49:01,597 INFO datanode.DataNode (DataNode.java:offerService(777)) - Starting Periodic block scanner.
    [junit] 2009-06-26 12:49:01,744 INFO common.Storage (DataStorage.java:recoverTransitionRead(122)) - Storage directory http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data4 is not formatted.
    [junit] 2009-06-26 12:49:01,745 INFO common.Storage (DataStorage.java:recoverTransitionRead(123)) - Formatting ...
    [junit] 2009-06-26 12:49:02,036 INFO datanode.DataNode (FSDataset.java:registerMBean(1417)) - Registered FSDatasetStatusMBean
    [junit] 2009-06-26 12:49:02,037 INFO datanode.DataNode (DataNode.java:startDataNode(326)) - Opened info server at 49574
    [junit] 2009-06-26 12:49:02,037 INFO datanode.DataNode (DataXceiverServer.java:<init>(74)) - Balancing bandwith is 1048576 bytes/s
    [junit] 2009-06-26 12:49:02,037 INFO datanode.DirectoryScanner (DirectoryScanner.java:<init>(133)) - scan starts at 1246036512037 with interval 21600000
    [junit] 2009-06-26 12:49:02,039 INFO http.HttpServer (HttpServer.java:start(425)) - Port returned by webServer.getConnectors()[0].getLocalPort() before open() is -1. Opening the listener on 0
    [junit] 2009-06-26 12:49:02,039 INFO http.HttpServer (HttpServer.java:start(430)) - listener.getLocalPort() returned 59075 webServer.getConnectors()[0].getLocalPort() returned 59075
    [junit] 2009-06-26 12:49:02,039 INFO http.HttpServer (HttpServer.java:start(463)) - Jetty bound to port 59075
    [junit] 2009-06-26 12:49:02,040 INFO mortbay.log (?:invoke(?)) - jetty-6.1.14
    [junit] 2009-06-26 12:49:02,102 INFO mortbay.log (?:invoke(?)) - Started SelectChannelConnector@localhost:59075
    [junit] 2009-06-26 12:49:02,102 INFO jvm.JvmMetrics (JvmMetrics.java:init(66)) - Cannot initialize JVM Metrics with processName=DataNode, sessionId=null - already initialized
    [junit] 2009-06-26 12:49:02,114 INFO metrics.RpcMetrics (RpcMetrics.java:<init>(58)) - Initializing RPC Metrics with hostName=DataNode, port=57121
    [junit] 2009-06-26 12:49:02,115 INFO ipc.Server (Server.java:run(474)) - IPC Server Responder: starting
    [junit] 2009-06-26 12:49:02,115 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 2 on 57121: starting
    [junit] 2009-06-26 12:49:02,115 INFO datanode.DataNode (DataNode.java:startDataNode(404)) - dnRegistration = DatanodeRegistration(vesta.apache.org:49574, storageID=, infoPort=59075, ipcPort=57121)
    [junit] 2009-06-26 12:49:02,115 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 1 on 57121: starting
    [junit] 2009-06-26 12:49:02,115 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 0 on 57121: starting
    [junit] 2009-06-26 12:49:02,115 INFO ipc.Server (Server.java:run(313)) - IPC Server listener on 57121: starting
    [junit] 2009-06-26 12:49:02,117 INFO hdfs.StateChange (FSNamesystem.java:registerDatanode(1772)) - BLOCK* NameSystem.registerDatanode: node registration from 127.0.0.1:49574 storage DS-334819328-67.195.138.9-49574-1246020542116
    [junit] 2009-06-26 12:49:02,118 INFO net.NetworkTopology (NetworkTopology.java:add(327)) - Adding a new node: /default-rack/127.0.0.1:49574
    [junit] 2009-06-26 12:49:02,167 INFO datanode.DataNode (DataNode.java:register(566)) - New storage id DS-334819328-67.195.138.9-49574-1246020542116 is assigned to data-node 127.0.0.1:49574
    [junit] 2009-06-26 12:49:02,167 INFO datanode.DataNode (DataNode.java:run(1253)) - DatanodeRegistration(127.0.0.1:49574, storageID=DS-334819328-67.195.138.9-49574-1246020542116, infoPort=59075, ipcPort=57121)In DataNode.run, data = FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data3/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build/test/data/dfs/data/data4/current'}
    [junit] Starting DataNode 2 with dfs.data.dir: http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data5,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build/test/data/dfs/data/data6
    [junit] 2009-06-26 12:49:02,168 INFO datanode.DataNode (DataNode.java:offerService(734)) - using BLOCKREPORT_INTERVAL of 21600000msec Initial delay: 0msec
    [junit] 2009-06-26 12:49:02,179 INFO common.Storage (DataStorage.java:recoverTransitionRead(122)) - Storage directory http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data5 is not formatted.
    [junit] 2009-06-26 12:49:02,180 INFO common.Storage (DataStorage.java:recoverTransitionRead(123)) - Formatting ...
    [junit] 2009-06-26 12:49:02,217 INFO datanode.DataNode (DataNode.java:blockReport(969)) - BlockReport of 0 blocks got processed in 1 msecs
    [junit] 2009-06-26 12:49:02,217 INFO datanode.DataNode (DataNode.java:offerService(777)) - Starting Periodic block scanner.
    [junit] 2009-06-26 12:49:02,350 INFO common.Storage (DataStorage.java:recoverTransitionRead(122)) - Storage directory http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data6 is not formatted.
    [junit] 2009-06-26 12:49:02,350 INFO common.Storage (DataStorage.java:recoverTransitionRead(123)) - Formatting ...
    [junit] 2009-06-26 12:49:02,636 INFO datanode.DataNode (FSDataset.java:registerMBean(1417)) - Registered FSDatasetStatusMBean
    [junit] 2009-06-26 12:49:02,636 INFO datanode.DataNode (DataNode.java:startDataNode(326)) - Opened info server at 54971
    [junit] 2009-06-26 12:49:02,637 INFO datanode.DataNode (DataXceiverServer.java:<init>(74)) - Balancing bandwith is 1048576 bytes/s
    [junit] 2009-06-26 12:49:02,637 INFO datanode.DirectoryScanner (DirectoryScanner.java:<init>(133)) - scan starts at 1246028991637 with interval 21600000
    [junit] 2009-06-26 12:49:02,638 INFO http.HttpServer (HttpServer.java:start(425)) - Port returned by webServer.getConnectors()[0].getLocalPort() before open() is -1. Opening the listener on 0
    [junit] 2009-06-26 12:49:02,639 INFO http.HttpServer (HttpServer.java:start(430)) - listener.getLocalPort() returned 51128 webServer.getConnectors()[0].getLocalPort() returned 51128
    [junit] 2009-06-26 12:49:02,639 INFO http.HttpServer (HttpServer.java:start(463)) - Jetty bound to port 51128
    [junit] 2009-06-26 12:49:02,639 INFO mortbay.log (?:invoke(?)) - jetty-6.1.14
    [junit] 2009-06-26 12:49:02,741 INFO mortbay.log (?:invoke(?)) - Started SelectChannelConnector@localhost:51128
    [junit] 2009-06-26 12:49:02,744 INFO jvm.JvmMetrics (JvmMetrics.java:init(66)) - Cannot initialize JVM Metrics with processName=DataNode, sessionId=null - already initialized
    [junit] 2009-06-26 12:49:02,756 INFO metrics.RpcMetrics (RpcMetrics.java:<init>(58)) - Initializing RPC Metrics with hostName=DataNode, port=60820
    [junit] 2009-06-26 12:49:02,757 INFO ipc.Server (Server.java:run(474)) - IPC Server Responder: starting
    [junit] 2009-06-26 12:49:02,757 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 1 on 60820: starting
    [junit] 2009-06-26 12:49:02,757 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 0 on 60820: starting
    [junit] 2009-06-26 12:49:02,757 INFO ipc.Server (Server.java:run(313)) - IPC Server listener on 60820: starting
    [junit] 2009-06-26 12:49:02,758 INFO datanode.DataNode (DataNode.java:startDataNode(404)) - dnRegistration = DatanodeRegistration(vesta.apache.org:54971, storageID=, infoPort=51128, ipcPort=60820)
    [junit] 2009-06-26 12:49:02,757 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 2 on 60820: starting
    [junit] 2009-06-26 12:49:02,761 INFO hdfs.StateChange (FSNamesystem.java:registerDatanode(1772)) - BLOCK* NameSystem.registerDatanode: node registration from 127.0.0.1:54971 storage DS-1932944622-67.195.138.9-54971-1246020542760
    [junit] 2009-06-26 12:49:02,761 INFO net.NetworkTopology (NetworkTopology.java:add(327)) - Adding a new node: /default-rack/127.0.0.1:54971
    [junit] 2009-06-26 12:49:02,804 INFO datanode.DataNode (DataNode.java:register(566)) - New storage id DS-1932944622-67.195.138.9-54971-1246020542760 is assigned to data-node 127.0.0.1:54971
    [junit] 2009-06-26 12:49:02,804 INFO datanode.DataNode (DataNode.java:run(1253)) - DatanodeRegistration(127.0.0.1:54971, storageID=DS-1932944622-67.195.138.9-54971-1246020542760, infoPort=51128, ipcPort=60820)In DataNode.run, data = FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data5/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build/test/data/dfs/data/data6/current'}
    [junit] Starting DataNode 3 with dfs.data.dir: http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data7,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build/test/data/dfs/data/data8
    [junit] 2009-06-26 12:49:02,805 INFO datanode.DataNode (DataNode.java:offerService(734)) - using BLOCKREPORT_INTERVAL of 21600000msec Initial delay: 0msec
    [junit] 2009-06-26 12:49:02,815 INFO common.Storage (DataStorage.java:recoverTransitionRead(122)) - Storage directory http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data7 is not formatted.
    [junit] 2009-06-26 12:49:02,816 INFO common.Storage (DataStorage.java:recoverTransitionRead(123)) - Formatting ...
    [junit] 2009-06-26 12:49:02,846 INFO datanode.DataNode (DataNode.java:blockReport(969)) - BlockReport of 0 blocks got processed in 1 msecs
    [junit] 2009-06-26 12:49:02,846 INFO datanode.DataNode (DataNode.java:offerService(777)) - Starting Periodic block scanner.
    [junit] 2009-06-26 12:49:03,031 INFO common.Storage (DataStorage.java:recoverTransitionRead(122)) - Storage directory http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data8 is not formatted.
    [junit] 2009-06-26 12:49:03,032 INFO common.Storage (DataStorage.java:recoverTransitionRead(123)) - Formatting ...
    [junit] 2009-06-26 12:49:03,310 INFO datanode.DataNode (FSDataset.java:registerMBean(1417)) - Registered FSDatasetStatusMBean
    [junit] 2009-06-26 12:49:03,311 INFO datanode.DataNode (DataNode.java:startDataNode(326)) - Opened info server at 34548
    [junit] 2009-06-26 12:49:03,311 INFO datanode.DataNode (DataXceiverServer.java:<init>(74)) - Balancing bandwith is 1048576 bytes/s
    [junit] 2009-06-26 12:49:03,311 INFO datanode.DirectoryScanner (DirectoryScanner.java:<init>(133)) - scan starts at 1246022189311 with interval 21600000
    [junit] 2009-06-26 12:49:03,313 INFO http.HttpServer (HttpServer.java:start(425)) - Port returned by webServer.getConnectors()[0].getLocalPort() before open() is -1. Opening the listener on 0
    [junit] 2009-06-26 12:49:03,313 INFO http.HttpServer (HttpServer.java:start(430)) - listener.getLocalPort() returned 43336 webServer.getConnectors()[0].getLocalPort() returned 43336
    [junit] 2009-06-26 12:49:03,314 INFO http.HttpServer (HttpServer.java:start(463)) - Jetty bound to port 43336
    [junit] 2009-06-26 12:49:03,314 INFO mortbay.log (?:invoke(?)) - jetty-6.1.14
    [junit] 2009-06-26 12:49:03,503 INFO mortbay.log (?:invoke(?)) - Started SelectChannelConnector@localhost:43336
    [junit] 2009-06-26 12:49:03,504 INFO jvm.JvmMetrics (JvmMetrics.java:init(66)) - Cannot initialize JVM Metrics with processName=DataNode, sessionId=null - already initialized
    [junit] 2009-06-26 12:49:03,516 INFO metrics.RpcMetrics (RpcMetrics.java:<init>(58)) - Initializing RPC Metrics with hostName=DataNode, port=55265
    [junit] 2009-06-26 12:49:03,516 INFO ipc.Server (Server.java:run(474)) - IPC Server Responder: starting
    [junit] 2009-06-26 12:49:03,517 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 2 on 55265: starting
    [junit] 2009-06-26 12:49:03,517 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 1 on 55265: starting
    [junit] 2009-06-26 12:49:03,517 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 0 on 55265: starting
    [junit] 2009-06-26 12:49:03,517 INFO ipc.Server (Server.java:run(313)) - IPC Server listener on 55265: starting
    [junit] 2009-06-26 12:49:03,517 INFO datanode.DataNode (DataNode.java:startDataNode(404)) - dnRegistration = DatanodeRegistration(vesta.apache.org:34548, storageID=, infoPort=43336, ipcPort=55265)
    [junit] 2009-06-26 12:49:03,523 INFO hdfs.StateChange (FSNamesystem.java:registerDatanode(1772)) - BLOCK* NameSystem.registerDatanode: node registration from 127.0.0.1:34548 storage DS-86204223-67.195.138.9-34548-1246020543523
    [junit] 2009-06-26 12:49:03,524 INFO net.NetworkTopology (NetworkTopology.java:add(327)) - Adding a new node: /default-rack/127.0.0.1:34548
    [junit] 2009-06-26 12:49:03,568 INFO datanode.DataNode (DataNode.java:register(566)) - New storage id DS-86204223-67.195.138.9-34548-1246020543523 is assigned to data-node 127.0.0.1:34548
    [junit] 2009-06-26 12:49:03,569 INFO datanode.DataNode (DataNode.java:run(1253)) - DatanodeRegistration(127.0.0.1:34548, storageID=DS-86204223-67.195.138.9-34548-1246020543523, infoPort=43336, ipcPort=55265)In DataNode.run, data = FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data7/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build/test/data/dfs/data/data8/current'}
    [junit] 2009-06-26 12:49:03,576 INFO datanode.DataNode (DataNode.java:offerService(734)) - using BLOCKREPORT_INTERVAL of 21600000msec Initial delay: 0msec
    [junit] 2009-06-26 12:49:03,627 INFO datanode.DataNode (DataNode.java:blockReport(969)) - BlockReport of 0 blocks got processed in 1 msecs
    [junit] 2009-06-26 12:49:03,627 INFO datanode.DataNode (DataNode.java:offerService(777)) - Starting Periodic block scanner.
    [junit] <property><name>security.client.protocol.acl</name><value>*</value></property>
    [junit]
    [junit] <property><name>security.client.datanode.protocol.acl</name><value>*</value></property>
    [junit]
    [junit] <property><name>security.datanode.protocol.acl</name><value>*</value></property>
    [junit]
    [junit] <property><name>security.inter.datanode.protocol.acl</name><value>*</value></property>
    [junit]
    [junit] <property><name>security.namenode.protocol.acl</name><value>*</value></property>
    [junit]
    [junit] <property><name>security.refresh.policy.protocol.acl</name><value>nouser nogroup</value></property>
    [junit]
    [junit] 2009-06-26 12:49:03,668 INFO authorize.ServiceAuthorizationManager (ServiceAuthorizationManager.java:run(92)) - Authorization failed for dev,null
    [junit] java.security.AccessControlException: access denied ConnectionPermission(org.apache.hadoop.security.authorize.RefreshAuthorizationPolicyProtocol)
    [junit] at java.security.AccessControlContext.checkPermission(AccessControlContext.java:323)
    [junit] at java.security.AccessController.checkPermission(AccessController.java:546)
    [junit] at org.apache.hadoop.security.authorize.ServiceAuthorizationManager$1.run(ServiceAuthorizationManager.java:89)
    [junit] at org.apache.hadoop.security.authorize.ServiceAuthorizationManager$1.run(ServiceAuthorizationManager.java:84)
    [junit] at java.security.AccessController.doPrivileged(Native Method)
    [junit] at javax.security.auth.Subject.doAs(Subject.java:396)
    [junit] at org.apache.hadoop.security.authorize.ServiceAuthorizationManager.checkPermission(ServiceAuthorizationManager.java:83)
    [junit] at org.apache.hadoop.security.authorize.ServiceAuthorizationManager.authorize(ServiceAuthorizationManager.java:68)
    [junit] at org.apache.hadoop.ipc.RPC$Server.authorize(RPC.java:565)
    [junit] at org.apache.hadoop.ipc.Server$Connection.readAndProcess(Server.java:858)
    [junit] at org.apache.hadoop.ipc.Server$Listener.doRead(Server.java:420)
    [junit] at org.apache.hadoop.ipc.Server$Listener.run(Server.java:328)
    [junit] Good, refresh worked... refresh failed with:
    [junit] Shutting down the Mini HDFS Cluster
    [junit] Shutting down DataNode 3
    [junit] 2009-06-26 12:49:03,783 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 55265
    [junit] 2009-06-26 12:49:03,783 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 55265: exiting
    [junit] 2009-06-26 12:49:03,784 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
    [junit] 2009-06-26 12:49:03,784 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 55265: exiting
    [junit] 2009-06-26 12:49:03,784 INFO datanode.DataNode (DataNode.java:shutdown(638)) - Waiting for threadgroup to exit, active threads is 1
    [junit] 2009-06-26 12:49:03,784 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 55265
    [junit] 2009-06-26 12:49:03,783 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 55265: exiting
    [junit] 2009-06-26 12:49:03,785 WARN datanode.DataNode (DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:34548, storageID=DS-86204223-67.195.138.9-34548-1246020543523, infoPort=43336, ipcPort=55265):DataXceiveServer: java.nio.channels.AsynchronousCloseException
    [junit] at java.nio.channels.spi.AbstractInterruptibleChannel.end(AbstractInterruptibleChannel.java:185)
    [junit] at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:152)
    [junit] at sun.nio.ch.ServerSocketAdaptor.accept(ServerSocketAdaptor.java:84)
    [junit] at org.apache.hadoop.hdfs.server.datanode.DataXceiverServer.run(DataXceiverServer.java:130)
    [junit] at java.lang.Thread.run(Thread.java:619)
    [junit]
    [junit] 2009-06-26 12:49:03,787 INFO datanode.DataNode (DataNode.java:shutdown(638)) - Waiting for threadgroup to exit, active threads is 0
    [junit] 2009-06-26 12:49:03,787 INFO datanode.DataBlockScanner (DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
    [junit] 2009-06-26 12:49:03,788 INFO datanode.DataNode (DataNode.java:run(1273)) - DatanodeRegistration(127.0.0.1:34548, storageID=DS-86204223-67.195.138.9-34548-1246020543523, infoPort=43336, ipcPort=55265):Finishing DataNode in: FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data7/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build/test/data/dfs/data/data8/current'}
    [junit] 2009-06-26 12:49:03,788 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 55265
    [junit] 2009-06-26 12:49:03,788 INFO datanode.DataNode (DataNode.java:shutdown(638)) - Waiting for threadgroup to exit, active threads is 0
    [junit] Shutting down DataNode 2
    [junit] 2009-06-26 12:49:03,890 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 60820
    [junit] 2009-06-26 12:49:03,891 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 60820: exiting
    [junit] 2009-06-26 12:49:03,891 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 60820: exiting
    [junit] 2009-06-26 12:49:03,891 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 60820: exiting
    [junit] 2009-06-26 12:49:03,891 WARN datanode.DataNode (DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:54971, storageID=DS-1932944622-67.195.138.9-54971-1246020542760, infoPort=51128, ipcPort=60820):DataXceiveServer: java.nio.channels.AsynchronousCloseException
    [junit] at java.nio.channels.spi.AbstractInterruptibleChannel.end(AbstractInterruptibleChannel.java:185)
    [junit] at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:152)
    [junit] at sun.nio.ch.ServerSocketAdaptor.accept(ServerSocketAdaptor.java:84)
    [junit] at org.apache.hadoop.hdfs.server.datanode.DataXceiverServer.run(DataXceiverServer.java:130)
    [junit] at java.lang.Thread.run(Thread.java:619)
    [junit]
    [junit] 2009-06-26 12:49:03,891 INFO datanode.DataNode (DataNode.java:shutdown(638)) - Waiting for threadgroup to exit, active threads is 1
    [junit] 2009-06-26 12:49:03,891 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
    [junit] 2009-06-26 12:49:03,891 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 60820
    [junit] 2009-06-26 12:49:03,892 INFO datanode.DataBlockScanner (DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
    [junit] 2009-06-26 12:49:03,893 INFO datanode.DataNode (DataNode.java:run(1273)) - DatanodeRegistration(127.0.0.1:54971, storageID=DS-1932944622-67.195.138.9-54971-1246020542760, infoPort=51128, ipcPort=60820):Finishing DataNode in: FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data5/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build/test/data/dfs/data/data6/current'}
    [junit] 2009-06-26 12:49:03,893 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 60820
    [junit] 2009-06-26 12:49:03,893 INFO datanode.DataNode (DataNode.java:shutdown(638)) - Waiting for threadgroup to exit, active threads is 0
    [junit] Shutting down DataNode 1
    [junit] 2009-06-26 12:49:03,995 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 57121
    [junit] 2009-06-26 12:49:03,996 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 57121: exiting
    [junit] 2009-06-26 12:49:03,996 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 57121: exiting
    [junit] 2009-06-26 12:49:03,996 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 57121
    [junit] 2009-06-26 12:49:03,997 WARN datanode.DataNode (DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:49574, storageID=DS-334819328-67.195.138.9-49574-1246020542116, infoPort=59075, ipcPort=57121):DataXceiveServer: java.nio.channels.AsynchronousCloseException
    [junit] at java.nio.channels.spi.AbstractInterruptibleChannel.end(AbstractInterruptibleChannel.java:185)
    [junit] at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:152)
    [junit] at sun.nio.ch.ServerSocketAdaptor.accept(ServerSocketAdaptor.java:84)
    [junit] at org.apache.hadoop.hdfs.server.datanode.DataXceiverServer.run(DataXceiverServer.java:130)
    [junit] at java.lang.Thread.run(Thread.java:619)
    [junit]
    [junit] 2009-06-26 12:49:03,997 INFO datanode.DataNode (DataNode.java:shutdown(638)) - Waiting for threadgroup to exit, active threads is 1
    [junit] 2009-06-26 12:49:03,997 INFO datanode.DataBlockScanner (DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
    [junit] 2009-06-26 12:49:03,996 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 57121: exiting
    [junit] 2009-06-26 12:49:03,996 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
    [junit] 2009-06-26 12:49:03,997 INFO datanode.DataNode (DataNode.java:run(1273)) - DatanodeRegistration(127.0.0.1:49574, storageID=DS-334819328-67.195.138.9-49574-1246020542116, infoPort=59075, ipcPort=57121):Finishing DataNode in: FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data3/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build/test/data/dfs/data/data4/current'}
    [junit] 2009-06-26 12:49:03,998 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 57121
    [junit] 2009-06-26 12:49:03,998 INFO datanode.DataNode (DataNode.java:shutdown(638)) - Waiting for threadgroup to exit, active threads is 0
    [junit] Shutting down DataNode 0
    [junit] 2009-06-26 12:49:04,133 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 57930
    [junit] 2009-06-26 12:49:04,133 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 57930: exiting
    [junit] 2009-06-26 12:49:04,133 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 57930: exiting
    [junit] 2009-06-26 12:49:04,133 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 57930: exiting
    [junit] 2009-06-26 12:49:04,134 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 57930
    [junit] 2009-06-26 12:49:04,134 INFO datanode.DataNode (DataNode.java:shutdown(638)) - Waiting for threadgroup to exit, active threads is 1
    [junit] 2009-06-26 12:49:04,134 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
    [junit] 2009-06-26 12:49:04,134 WARN datanode.DataNode (DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:41323, storageID=DS-864733044-67.195.138.9-41323-1246020541510, infoPort=60349, ipcPort=57930):DataXceiveServer: java.nio.channels.AsynchronousCloseException
    [junit] at java.nio.channels.spi.AbstractInterruptibleChannel.end(AbstractInterruptibleChannel.java:185)
    [junit] at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:152)
    [junit] at sun.nio.ch.ServerSocketAdaptor.accept(ServerSocketAdaptor.java:84)
    [junit] at org.apache.hadoop.hdfs.server.datanode.DataXceiverServer.run(DataXceiverServer.java:130)
    [junit] at java.lang.Thread.run(Thread.java:619)
    [junit]
    [junit] 2009-06-26 12:49:04,136 INFO datanode.DataNode (DataNode.java:shutdown(638)) - Waiting for threadgroup to exit, active threads is 0
    [junit] 2009-06-26 12:49:04,136 INFO datanode.DataBlockScanner (DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
    [junit] 2009-06-26 12:49:04,137 INFO datanode.DataNode (DataNode.java:run(1273)) - DatanodeRegistration(127.0.0.1:41323, storageID=DS-864733044-67.195.138.9-41323-1246020541510, infoPort=60349, ipcPort=57930):Finishing DataNode in: FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data1/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build/test/data/dfs/data/data2/current'}
    [junit] 2009-06-26 12:49:04,137 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 57930
    [junit] 2009-06-26 12:49:04,137 INFO datanode.DataNode (DataNode.java:shutdown(638)) - Waiting for threadgroup to exit, active threads is 0
    [junit] 2009-06-26 12:49:04,239 WARN namenode.FSNamesystem (FSNamesystem.java:run(2075)) - ReplicationMonitor thread received InterruptedException.java.lang.InterruptedException: sleep interrupted
    [junit] 2009-06-26 12:49:04,239 INFO namenode.FSNamesystem (FSEditLog.java:printStatistics(876)) - Number of transactions: 0 Total time for transactions(ms): 0Number of transactions batched in Syncs: 0 Number of syncs: 0 SyncTimes(ms): 0 0
    [junit] 2009-06-26 12:49:04,239 WARN namenode.DecommissionManager (DecommissionManager.java:run(67)) - Monitor interrupted: java.lang.InterruptedException: sleep interrupted
    [junit] 2009-06-26 12:49:04,365 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 33272
    [junit] 2009-06-26 12:49:04,365 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 33272: exiting
    [junit] 2009-06-26 12:49:04,365 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 33272: exiting
    [junit] 2009-06-26 12:49:04,365 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 33272: exiting
    [junit] 2009-06-26 12:49:04,366 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 3 on 33272: exiting
    [junit] 2009-06-26 12:49:04,366 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 4 on 33272: exiting
    [junit] 2009-06-26 12:49:04,366 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 5 on 33272: exiting
    [junit] 2009-06-26 12:49:04,366 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 6 on 33272: exiting
    [junit] 2009-06-26 12:49:04,367 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 7 on 33272: exiting
    [junit] 2009-06-26 12:49:04,367 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
    [junit] 2009-06-26 12:49:04,367 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 8 on 33272: exiting
    [junit] 2009-06-26 12:49:04,367 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 33272
    [junit] 2009-06-26 12:49:04,367 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 9 on 33272: exiting
    [junit] Tests run: 2, Failures: 0, Errors: 0, Time elapsed: 126.647 sec

    checkfailure:

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

    Total time: 75 minutes 10 seconds
    Publishing Javadoc
    Recording test results
    Recording fingerprints
    Publishing Clover coverage report...
  • Apache Hudson Server at Jun 27, 2009 at 1:08 pm
    See http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/5/changes

    Changes:

    [cdouglas] HDFS-447. Add LDAP lookup to hdfsproxy. Contributed by Zhiyong Zhang

    [gkesavan] HADOOP-6112. Fix hudsonPatchQueueAdmin for different projects.

    ------------------------------------------
    [...truncated 340149 lines...]
    [junit] 2009-06-27 13:07:25,892 INFO common.Storage (DataStorage.java:recoverTransitionRead(122)) - Storage directory http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data1 is not formatted.
    [junit] 2009-06-27 13:07:25,893 INFO common.Storage (DataStorage.java:recoverTransitionRead(123)) - Formatting ...
    [junit] 2009-06-27 13:07:26,103 INFO common.Storage (DataStorage.java:recoverTransitionRead(122)) - Storage directory http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data2 is not formatted.
    [junit] 2009-06-27 13:07:26,104 INFO common.Storage (DataStorage.java:recoverTransitionRead(123)) - Formatting ...
    [junit] 2009-06-27 13:07:26,398 INFO datanode.DataNode (FSDataset.java:registerMBean(1417)) - Registered FSDatasetStatusMBean
    [junit] 2009-06-27 13:07:26,399 INFO datanode.DataNode (DataNode.java:startDataNode(326)) - Opened info server at 40254
    [junit] 2009-06-27 13:07:26,400 INFO datanode.DataNode (DataXceiverServer.java:<init>(74)) - Balancing bandwith is 1048576 bytes/s
    [junit] 2009-06-27 13:07:26,400 INFO datanode.DirectoryScanner (DirectoryScanner.java:<init>(133)) - scan starts at 1246116836400 with interval 21600000
    [junit] 2009-06-27 13:07:26,402 INFO http.HttpServer (HttpServer.java:start(425)) - Port returned by webServer.getConnectors()[0].getLocalPort() before open() is -1. Opening the listener on 0
    [junit] 2009-06-27 13:07:26,402 INFO http.HttpServer (HttpServer.java:start(430)) - listener.getLocalPort() returned 51178 webServer.getConnectors()[0].getLocalPort() returned 51178
    [junit] 2009-06-27 13:07:26,402 INFO http.HttpServer (HttpServer.java:start(463)) - Jetty bound to port 51178
    [junit] 2009-06-27 13:07:26,403 INFO mortbay.log (?:invoke(?)) - jetty-6.1.14
    [junit] 2009-06-27 13:07:26,470 INFO mortbay.log (?:invoke(?)) - Started SelectChannelConnector@localhost:51178
    [junit] 2009-06-27 13:07:26,472 INFO jvm.JvmMetrics (JvmMetrics.java:init(66)) - Cannot initialize JVM Metrics with processName=DataNode, sessionId=null - already initialized
    [junit] 2009-06-27 13:07:26,485 INFO metrics.RpcMetrics (RpcMetrics.java:<init>(58)) - Initializing RPC Metrics with hostName=DataNode, port=41449
    [junit] 2009-06-27 13:07:26,486 INFO ipc.Server (Server.java:run(474)) - IPC Server Responder: starting
    [junit] 2009-06-27 13:07:26,486 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 0 on 41449: starting
    [junit] 2009-06-27 13:07:26,486 INFO ipc.Server (Server.java:run(313)) - IPC Server listener on 41449: starting
    [junit] 2009-06-27 13:07:26,487 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 2 on 41449: starting
    [junit] 2009-06-27 13:07:26,487 INFO datanode.DataNode (DataNode.java:startDataNode(404)) - dnRegistration = DatanodeRegistration(vesta.apache.org:40254, storageID=, infoPort=51178, ipcPort=41449)
    [junit] 2009-06-27 13:07:26,486 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 1 on 41449: starting
    [junit] 2009-06-27 13:07:26,489 INFO hdfs.StateChange (FSNamesystem.java:registerDatanode(1772)) - BLOCK* NameSystem.registerDatanode: node registration from 127.0.0.1:40254 storage DS-1022175986-67.195.138.9-40254-1246108046488
    [junit] 2009-06-27 13:07:26,489 INFO net.NetworkTopology (NetworkTopology.java:add(327)) - Adding a new node: /default-rack/127.0.0.1:40254
    [junit] 2009-06-27 13:07:26,532 INFO datanode.DataNode (DataNode.java:register(566)) - New storage id DS-1022175986-67.195.138.9-40254-1246108046488 is assigned to data-node 127.0.0.1:40254
    [junit] 2009-06-27 13:07:26,533 INFO datanode.DataNode (DataNode.java:run(1253)) - DatanodeRegistration(127.0.0.1:40254, storageID=DS-1022175986-67.195.138.9-40254-1246108046488, infoPort=51178, ipcPort=41449)In DataNode.run, data = FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data1/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build/test/data/dfs/data/data2/current'}
    [junit] Starting DataNode 1 with dfs.data.dir: http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data3,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build/test/data/dfs/data/data4
    [junit] 2009-06-27 13:07:26,533 INFO datanode.DataNode (DataNode.java:offerService(734)) - using BLOCKREPORT_INTERVAL of 21600000msec Initial delay: 0msec
    [junit] 2009-06-27 13:07:26,543 INFO common.Storage (DataStorage.java:recoverTransitionRead(122)) - Storage directory http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data3 is not formatted.
    [junit] 2009-06-27 13:07:26,544 INFO common.Storage (DataStorage.java:recoverTransitionRead(123)) - Formatting ...
    [junit] 2009-06-27 13:07:26,577 INFO datanode.DataNode (DataNode.java:blockReport(969)) - BlockReport of 0 blocks got processed in 1 msecs
    [junit] 2009-06-27 13:07:26,578 INFO datanode.DataNode (DataNode.java:offerService(777)) - Starting Periodic block scanner.
    [junit] 2009-06-27 13:07:26,726 INFO common.Storage (DataStorage.java:recoverTransitionRead(122)) - Storage directory http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data4 is not formatted.
    [junit] 2009-06-27 13:07:26,727 INFO common.Storage (DataStorage.java:recoverTransitionRead(123)) - Formatting ...
    [junit] 2009-06-27 13:07:26,777 INFO mapred.JvmManager (JvmManager.java:runChild(411)) - JVM : jvm_200906271305_0004_m_-988429809 exited. Number of tasks it ran: 1
    [junit] 2009-06-27 13:07:27,009 INFO datanode.DataNode (FSDataset.java:registerMBean(1417)) - Registered FSDatasetStatusMBean
    [junit] 2009-06-27 13:07:27,010 INFO datanode.DataNode (DataNode.java:startDataNode(326)) - Opened info server at 51104
    [junit] 2009-06-27 13:07:27,010 INFO datanode.DataNode (DataXceiverServer.java:<init>(74)) - Balancing bandwith is 1048576 bytes/s
    [junit] 2009-06-27 13:07:27,010 INFO datanode.DirectoryScanner (DirectoryScanner.java:<init>(133)) - scan starts at 1246116914010 with interval 21600000
    [junit] 2009-06-27 13:07:27,012 INFO http.HttpServer (HttpServer.java:start(425)) - Port returned by webServer.getConnectors()[0].getLocalPort() before open() is -1. Opening the listener on 0
    [junit] 2009-06-27 13:07:27,012 INFO http.HttpServer (HttpServer.java:start(430)) - listener.getLocalPort() returned 56048 webServer.getConnectors()[0].getLocalPort() returned 56048
    [junit] 2009-06-27 13:07:27,012 INFO http.HttpServer (HttpServer.java:start(463)) - Jetty bound to port 56048
    [junit] 2009-06-27 13:07:27,012 INFO mortbay.log (?:invoke(?)) - jetty-6.1.14
    [junit] 2009-06-27 13:07:27,075 INFO mortbay.log (?:invoke(?)) - Started SelectChannelConnector@localhost:56048
    [junit] 2009-06-27 13:07:27,075 INFO jvm.JvmMetrics (JvmMetrics.java:init(66)) - Cannot initialize JVM Metrics with processName=DataNode, sessionId=null - already initialized
    [junit] 2009-06-27 13:07:27,087 INFO metrics.RpcMetrics (RpcMetrics.java:<init>(58)) - Initializing RPC Metrics with hostName=DataNode, port=55376
    [junit] 2009-06-27 13:07:27,088 INFO ipc.Server (Server.java:run(474)) - IPC Server Responder: starting
    [junit] 2009-06-27 13:07:27,088 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 1 on 55376: starting
    [junit] 2009-06-27 13:07:27,088 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 0 on 55376: starting
    [junit] 2009-06-27 13:07:27,088 INFO ipc.Server (Server.java:run(313)) - IPC Server listener on 55376: starting
    [junit] 2009-06-27 13:07:27,089 INFO datanode.DataNode (DataNode.java:startDataNode(404)) - dnRegistration = DatanodeRegistration(vesta.apache.org:51104, storageID=, infoPort=56048, ipcPort=55376)
    [junit] 2009-06-27 13:07:27,088 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 2 on 55376: starting
    [junit] 2009-06-27 13:07:27,090 INFO hdfs.StateChange (FSNamesystem.java:registerDatanode(1772)) - BLOCK* NameSystem.registerDatanode: node registration from 127.0.0.1:51104 storage DS-691879620-67.195.138.9-51104-1246108047090
    [junit] 2009-06-27 13:07:27,091 INFO net.NetworkTopology (NetworkTopology.java:add(327)) - Adding a new node: /default-rack/127.0.0.1:51104
    [junit] 2009-06-27 13:07:27,141 INFO datanode.DataNode (DataNode.java:register(566)) - New storage id DS-691879620-67.195.138.9-51104-1246108047090 is assigned to data-node 127.0.0.1:51104
    [junit] 2009-06-27 13:07:27,142 INFO datanode.DataNode (DataNode.java:run(1253)) - DatanodeRegistration(127.0.0.1:51104, storageID=DS-691879620-67.195.138.9-51104-1246108047090, infoPort=56048, ipcPort=55376)In DataNode.run, data = FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data3/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build/test/data/dfs/data/data4/current'}
    [junit] Starting DataNode 2 with dfs.data.dir: http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data5,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build/test/data/dfs/data/data6
    [junit] 2009-06-27 13:07:27,143 INFO datanode.DataNode (DataNode.java:offerService(734)) - using BLOCKREPORT_INTERVAL of 21600000msec Initial delay: 0msec
    [junit] 2009-06-27 13:07:27,153 INFO common.Storage (DataStorage.java:recoverTransitionRead(122)) - Storage directory http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data5 is not formatted.
    [junit] 2009-06-27 13:07:27,154 INFO common.Storage (DataStorage.java:recoverTransitionRead(123)) - Formatting ...
    [junit] 2009-06-27 13:07:27,184 INFO datanode.DataNode (DataNode.java:blockReport(969)) - BlockReport of 0 blocks got processed in 1 msecs
    [junit] 2009-06-27 13:07:27,184 INFO datanode.DataNode (DataNode.java:offerService(777)) - Starting Periodic block scanner.
    [junit] 2009-06-27 13:07:27,353 INFO common.Storage (DataStorage.java:recoverTransitionRead(122)) - Storage directory http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data6 is not formatted.
    [junit] 2009-06-27 13:07:27,353 INFO common.Storage (DataStorage.java:recoverTransitionRead(123)) - Formatting ...
    [junit] 2009-06-27 13:07:27,614 INFO datanode.DataNode (FSDataset.java:registerMBean(1417)) - Registered FSDatasetStatusMBean
    [junit] 2009-06-27 13:07:27,615 INFO datanode.DataNode (DataNode.java:startDataNode(326)) - Opened info server at 40626
    [junit] 2009-06-27 13:07:27,615 INFO datanode.DataNode (DataXceiverServer.java:<init>(74)) - Balancing bandwith is 1048576 bytes/s
    [junit] 2009-06-27 13:07:27,615 INFO datanode.DirectoryScanner (DirectoryScanner.java:<init>(133)) - scan starts at 1246125532615 with interval 21600000
    [junit] 2009-06-27 13:07:27,617 INFO http.HttpServer (HttpServer.java:start(425)) - Port returned by webServer.getConnectors()[0].getLocalPort() before open() is -1. Opening the listener on 0
    [junit] 2009-06-27 13:07:27,617 INFO http.HttpServer (HttpServer.java:start(430)) - listener.getLocalPort() returned 36687 webServer.getConnectors()[0].getLocalPort() returned 36687
    [junit] 2009-06-27 13:07:27,617 INFO http.HttpServer (HttpServer.java:start(463)) - Jetty bound to port 36687
    [junit] 2009-06-27 13:07:27,617 INFO mortbay.log (?:invoke(?)) - jetty-6.1.14
    [junit] 2009-06-27 13:07:27,684 INFO mortbay.log (?:invoke(?)) - Started SelectChannelConnector@localhost:36687
    [junit] 2009-06-27 13:07:27,687 INFO jvm.JvmMetrics (JvmMetrics.java:init(66)) - Cannot initialize JVM Metrics with processName=DataNode, sessionId=null - already initialized
    [junit] 2009-06-27 13:07:27,698 INFO metrics.RpcMetrics (RpcMetrics.java:<init>(58)) - Initializing RPC Metrics with hostName=DataNode, port=43831
    [junit] 2009-06-27 13:07:27,699 INFO ipc.Server (Server.java:run(474)) - IPC Server Responder: starting
    [junit] 2009-06-27 13:07:27,699 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 1 on 43831: starting
    [junit] 2009-06-27 13:07:27,700 INFO datanode.DataNode (DataNode.java:startDataNode(404)) - dnRegistration = DatanodeRegistration(vesta.apache.org:40626, storageID=, infoPort=36687, ipcPort=43831)
    [junit] 2009-06-27 13:07:27,700 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 2 on 43831: starting
    [junit] 2009-06-27 13:07:27,699 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 0 on 43831: starting
    [junit] 2009-06-27 13:07:27,699 INFO ipc.Server (Server.java:run(313)) - IPC Server listener on 43831: starting
    [junit] 2009-06-27 13:07:27,701 INFO hdfs.StateChange (FSNamesystem.java:registerDatanode(1772)) - BLOCK* NameSystem.registerDatanode: node registration from 127.0.0.1:40626 storage DS-1353494496-67.195.138.9-40626-1246108047701
    [junit] 2009-06-27 13:07:27,701 INFO net.NetworkTopology (NetworkTopology.java:add(327)) - Adding a new node: /default-rack/127.0.0.1:40626
    [junit] 2009-06-27 13:07:27,771 INFO datanode.DataNode (DataNode.java:register(566)) - New storage id DS-1353494496-67.195.138.9-40626-1246108047701 is assigned to data-node 127.0.0.1:40626
    [junit] Starting DataNode 3 with dfs.data.dir: http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data7,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build/test/data/dfs/data/data8
    [junit] 2009-06-27 13:07:27,771 INFO datanode.DataNode (DataNode.java:run(1253)) - DatanodeRegistration(127.0.0.1:40626, storageID=DS-1353494496-67.195.138.9-40626-1246108047701, infoPort=36687, ipcPort=43831)In DataNode.run, data = FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data5/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build/test/data/dfs/data/data6/current'}
    [junit] 2009-06-27 13:07:27,772 INFO datanode.DataNode (DataNode.java:offerService(734)) - using BLOCKREPORT_INTERVAL of 21600000msec Initial delay: 0msec
    [junit] 2009-06-27 13:07:27,781 INFO common.Storage (DataStorage.java:recoverTransitionRead(122)) - Storage directory http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data7 is not formatted.
    [junit] 2009-06-27 13:07:27,782 INFO common.Storage (DataStorage.java:recoverTransitionRead(123)) - Formatting ...
    [junit] 2009-06-27 13:07:27,809 INFO datanode.DataNode (DataNode.java:blockReport(969)) - BlockReport of 0 blocks got processed in 1 msecs
    [junit] 2009-06-27 13:07:27,809 INFO datanode.DataNode (DataNode.java:offerService(777)) - Starting Periodic block scanner.
    [junit] 2009-06-27 13:07:27,966 INFO common.Storage (DataStorage.java:recoverTransitionRead(122)) - Storage directory http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data8 is not formatted.
    [junit] 2009-06-27 13:07:27,967 INFO common.Storage (DataStorage.java:recoverTransitionRead(123)) - Formatting ...
    [junit] 2009-06-27 13:07:28,240 INFO datanode.DataNode (FSDataset.java:registerMBean(1417)) - Registered FSDatasetStatusMBean
    [junit] 2009-06-27 13:07:28,241 INFO datanode.DataNode (DataNode.java:startDataNode(326)) - Opened info server at 37133
    [junit] 2009-06-27 13:07:28,254 INFO datanode.DataNode (DataXceiverServer.java:<init>(74)) - Balancing bandwith is 1048576 bytes/s
    [junit] 2009-06-27 13:07:28,255 INFO datanode.DirectoryScanner (DirectoryScanner.java:<init>(133)) - scan starts at 1246124967255 with interval 21600000
    [junit] 2009-06-27 13:07:28,256 INFO http.HttpServer (HttpServer.java:start(425)) - Port returned by webServer.getConnectors()[0].getLocalPort() before open() is -1. Opening the listener on 0
    [junit] 2009-06-27 13:07:28,257 INFO http.HttpServer (HttpServer.java:start(430)) - listener.getLocalPort() returned 48805 webServer.getConnectors()[0].getLocalPort() returned 48805
    [junit] 2009-06-27 13:07:28,257 INFO http.HttpServer (HttpServer.java:start(463)) - Jetty bound to port 48805
    [junit] 2009-06-27 13:07:28,257 INFO mortbay.log (?:invoke(?)) - jetty-6.1.14
    [junit] 2009-06-27 13:07:28,320 INFO mortbay.log (?:invoke(?)) - Started SelectChannelConnector@localhost:48805
    [junit] 2009-06-27 13:07:28,321 INFO jvm.JvmMetrics (JvmMetrics.java:init(66)) - Cannot initialize JVM Metrics with processName=DataNode, sessionId=null - already initialized
    [junit] 2009-06-27 13:07:28,333 INFO metrics.RpcMetrics (RpcMetrics.java:<init>(58)) - Initializing RPC Metrics with hostName=DataNode, port=40999
    [junit] 2009-06-27 13:07:28,333 INFO ipc.Server (Server.java:run(474)) - IPC Server Responder: starting
    [junit] 2009-06-27 13:07:28,334 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 2 on 40999: starting
    [junit] 2009-06-27 13:07:28,334 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 1 on 40999: starting
    [junit] 2009-06-27 13:07:28,334 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 0 on 40999: starting
    [junit] 2009-06-27 13:07:28,333 INFO ipc.Server (Server.java:run(313)) - IPC Server listener on 40999: starting
    [junit] 2009-06-27 13:07:28,334 INFO datanode.DataNode (DataNode.java:startDataNode(404)) - dnRegistration = DatanodeRegistration(vesta.apache.org:37133, storageID=, infoPort=48805, ipcPort=40999)
    [junit] 2009-06-27 13:07:28,336 INFO hdfs.StateChange (FSNamesystem.java:registerDatanode(1772)) - BLOCK* NameSystem.registerDatanode: node registration from 127.0.0.1:37133 storage DS-932181558-67.195.138.9-37133-1246108048336
    [junit] 2009-06-27 13:07:28,336 INFO net.NetworkTopology (NetworkTopology.java:add(327)) - Adding a new node: /default-rack/127.0.0.1:37133
    [junit] 2009-06-27 13:07:28,382 INFO datanode.DataNode (DataNode.java:register(566)) - New storage id DS-932181558-67.195.138.9-37133-1246108048336 is assigned to data-node 127.0.0.1:37133
    [junit] 2009-06-27 13:07:28,382 INFO datanode.DataNode (DataNode.java:run(1253)) - DatanodeRegistration(127.0.0.1:37133, storageID=DS-932181558-67.195.138.9-37133-1246108048336, infoPort=48805, ipcPort=40999)In DataNode.run, data = FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data7/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build/test/data/dfs/data/data8/current'}
    [junit] 2009-06-27 13:07:28,464 INFO datanode.DataNode (DataNode.java:offerService(734)) - using BLOCKREPORT_INTERVAL of 21600000msec Initial delay: 0msec
    [junit] 2009-06-27 13:07:28,510 INFO datanode.DataNode (DataNode.java:blockReport(969)) - BlockReport of 0 blocks got processed in 1 msecs
    [junit] 2009-06-27 13:07:28,510 INFO datanode.DataNode (DataNode.java:offerService(777)) - Starting Periodic block scanner.
    [junit] <property><name>security.client.protocol.acl</name><value>*</value></property>
    [junit]
    [junit] <property><name>security.client.datanode.protocol.acl</name><value>*</value></property>
    [junit]
    [junit] <property><name>security.datanode.protocol.acl</name><value>*</value></property>
    [junit]
    [junit] <property><name>security.inter.datanode.protocol.acl</name><value>*</value></property>
    [junit]
    [junit] <property><name>security.namenode.protocol.acl</name><value>*</value></property>
    [junit]
    [junit] <property><name>security.refresh.policy.protocol.acl</name><value>nouser nogroup</value></property>
    [junit]
    [junit] 2009-06-27 13:07:28,544 INFO authorize.ServiceAuthorizationManager (ServiceAuthorizationManager.java:run(92)) - Authorization failed for dev,null
    [junit] java.security.AccessControlException: access denied ConnectionPermission(org.apache.hadoop.security.authorize.RefreshAuthorizationPolicyProtocol)
    [junit] at java.security.AccessControlContext.checkPermission(AccessControlContext.java:323)
    [junit] at java.security.AccessController.checkPermission(AccessController.java:546)
    [junit] at org.apache.hadoop.security.authorize.ServiceAuthorizationManager$1.run(ServiceAuthorizationManager.java:89)
    [junit] at org.apache.hadoop.security.authorize.ServiceAuthorizationManager$1.run(ServiceAuthorizationManager.java:84)
    [junit] at java.security.AccessController.doPrivileged(Native Method)
    [junit] at javax.security.auth.Subject.doAs(Subject.java:396)
    [junit] at org.apache.hadoop.security.authorize.ServiceAuthorizationManager.checkPermission(ServiceAuthorizationManager.java:83)
    [junit] at org.apache.hadoop.security.authorize.ServiceAuthorizationManager.authorize(ServiceAuthorizationManager.java:68)
    [junit] at org.apache.hadoop.ipc.RPC$Server.authorize(RPC.java:565)
    [junit] at org.apache.hadoop.ipc.Server$Connection.readAndProcess(Server.java:858)
    [junit] at org.apache.hadoop.ipc.Server$Listener.doRead(Server.java:420)
    [junit] at org.apache.hadoop.ipc.Server$Listener.run(Server.java:328)
    [junit] Good, refresh worked... refresh failed with:
    [junit] Shutting down the Mini HDFS Cluster
    [junit] Shutting down DataNode 3
    [junit] 2009-06-27 13:07:28,649 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 40999
    [junit] 2009-06-27 13:07:28,649 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 40999: exiting
    [junit] 2009-06-27 13:07:28,650 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 40999
    [junit] 2009-06-27 13:07:28,650 WARN datanode.DataNode (DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:37133, storageID=DS-932181558-67.195.138.9-37133-1246108048336, infoPort=48805, ipcPort=40999):DataXceiveServer: java.nio.channels.AsynchronousCloseException
    [junit] at java.nio.channels.spi.AbstractInterruptibleChannel.end(AbstractInterruptibleChannel.java:185)
    [junit] at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:152)
    [junit] at sun.nio.ch.ServerSocketAdaptor.accept(ServerSocketAdaptor.java:84)
    [junit] at org.apache.hadoop.hdfs.server.datanode.DataXceiverServer.run(DataXceiverServer.java:130)
    [junit] at java.lang.Thread.run(Thread.java:619)
    [junit]
    [junit] 2009-06-27 13:07:28,649 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 40999: exiting
    [junit] 2009-06-27 13:07:28,649 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 40999: exiting
    [junit] 2009-06-27 13:07:28,650 INFO datanode.DataNode (DataNode.java:shutdown(638)) - Waiting for threadgroup to exit, active threads is 1
    [junit] 2009-06-27 13:07:28,650 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
    [junit] 2009-06-27 13:07:28,652 INFO datanode.DataBlockScanner (DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
    [junit] 2009-06-27 13:07:28,652 INFO datanode.DataNode (DataNode.java:run(1273)) - DatanodeRegistration(127.0.0.1:37133, storageID=DS-932181558-67.195.138.9-37133-1246108048336, infoPort=48805, ipcPort=40999):Finishing DataNode in: FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data7/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build/test/data/dfs/data/data8/current'}
    [junit] 2009-06-27 13:07:28,653 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 40999
    [junit] 2009-06-27 13:07:28,653 INFO datanode.DataNode (DataNode.java:shutdown(638)) - Waiting for threadgroup to exit, active threads is 0
    [junit] Shutting down DataNode 2
    [junit] 2009-06-27 13:07:28,755 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 43831
    [junit] 2009-06-27 13:07:28,755 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 43831: exiting
    [junit] 2009-06-27 13:07:28,756 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 43831: exiting
    [junit] 2009-06-27 13:07:28,756 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 43831
    [junit] 2009-06-27 13:07:28,757 INFO datanode.DataNode (DataNode.java:shutdown(638)) - Waiting for threadgroup to exit, active threads is 1
    [junit] 2009-06-27 13:07:28,757 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
    [junit] 2009-06-27 13:07:28,757 WARN datanode.DataNode (DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:40626, storageID=DS-1353494496-67.195.138.9-40626-1246108047701, infoPort=36687, ipcPort=43831):DataXceiveServer: java.nio.channels.AsynchronousCloseException
    [junit] at java.nio.channels.spi.AbstractInterruptibleChannel.end(AbstractInterruptibleChannel.java:185)
    [junit] at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:152)
    [junit] at sun.nio.ch.ServerSocketAdaptor.accept(ServerSocketAdaptor.java:84)
    [junit] at org.apache.hadoop.hdfs.server.datanode.DataXceiverServer.run(DataXceiverServer.java:130)
    [junit] at java.lang.Thread.run(Thread.java:619)
    [junit]
    [junit] 2009-06-27 13:07:28,757 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 43831: exiting
    [junit] 2009-06-27 13:07:28,759 INFO datanode.DataNode (DataNode.java:shutdown(638)) - Waiting for threadgroup to exit, active threads is 0
    [junit] 2009-06-27 13:07:28,759 INFO datanode.DataBlockScanner (DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
    [junit] 2009-06-27 13:07:28,760 INFO datanode.DataNode (DataNode.java:run(1273)) - DatanodeRegistration(127.0.0.1:40626, storageID=DS-1353494496-67.195.138.9-40626-1246108047701, infoPort=36687, ipcPort=43831):Finishing DataNode in: FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data5/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build/test/data/dfs/data/data6/current'}
    [junit] 2009-06-27 13:07:28,760 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 43831
    [junit] 2009-06-27 13:07:28,760 INFO datanode.DataNode (DataNode.java:shutdown(638)) - Waiting for threadgroup to exit, active threads is 0
    [junit] Shutting down DataNode 1
    [junit] 2009-06-27 13:07:28,863 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 55376
    [junit] 2009-06-27 13:07:28,863 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 55376: exiting
    [junit] 2009-06-27 13:07:28,863 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 55376: exiting
    [junit] 2009-06-27 13:07:28,864 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 55376
    [junit] 2009-06-27 13:07:28,864 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
    [junit] 2009-06-27 13:07:28,864 WARN datanode.DataNode (DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:51104, storageID=DS-691879620-67.195.138.9-51104-1246108047090, infoPort=56048, ipcPort=55376):DataXceiveServer: java.nio.channels.AsynchronousCloseException
    [junit] at java.nio.channels.spi.AbstractInterruptibleChannel.end(AbstractInterruptibleChannel.java:185)
    [junit] at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:152)
    [junit] at sun.nio.ch.ServerSocketAdaptor.accept(ServerSocketAdaptor.java:84)
    [junit] at org.apache.hadoop.hdfs.server.datanode.DataXceiverServer.run(DataXceiverServer.java:130)
    [junit] at java.lang.Thread.run(Thread.java:619)
    [junit]
    [junit] 2009-06-27 13:07:28,864 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 55376: exiting
    [junit] 2009-06-27 13:07:28,864 INFO datanode.DataNode (DataNode.java:shutdown(638)) - Waiting for threadgroup to exit, active threads is 1
    [junit] 2009-06-27 13:07:28,865 INFO datanode.DataBlockScanner (DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
    [junit] 2009-06-27 13:07:28,865 INFO datanode.DataNode (DataNode.java:run(1273)) - DatanodeRegistration(127.0.0.1:51104, storageID=DS-691879620-67.195.138.9-51104-1246108047090, infoPort=56048, ipcPort=55376):Finishing DataNode in: FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data3/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build/test/data/dfs/data/data4/current'}
    [junit] 2009-06-27 13:07:28,865 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 55376
    [junit] 2009-06-27 13:07:28,866 INFO datanode.DataNode (DataNode.java:shutdown(638)) - Waiting for threadgroup to exit, active threads is 0
    [junit] Shutting down DataNode 0
    [junit] 2009-06-27 13:07:28,968 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 41449
    [junit] 2009-06-27 13:07:28,968 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 41449: exiting
    [junit] 2009-06-27 13:07:28,968 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 41449: exiting
    [junit] 2009-06-27 13:07:28,969 WARN datanode.DataNode (DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:40254, storageID=DS-1022175986-67.195.138.9-40254-1246108046488, infoPort=51178, ipcPort=41449):DataXceiveServer: java.nio.channels.AsynchronousCloseException
    [junit] at java.nio.channels.spi.AbstractInterruptibleChannel.end(AbstractInterruptibleChannel.java:185)
    [junit] at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:152)
    [junit] at sun.nio.ch.ServerSocketAdaptor.accept(ServerSocketAdaptor.java:84)
    [junit] at org.apache.hadoop.hdfs.server.datanode.DataXceiverServer.run(DataXceiverServer.java:130)
    [junit] at java.lang.Thread.run(Thread.java:619)
    [junit]
    [junit] 2009-06-27 13:07:28,969 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 41449: exiting
    [junit] 2009-06-27 13:07:28,969 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
    [junit] 2009-06-27 13:07:28,969 INFO datanode.DataNode (DataNode.java:shutdown(638)) - Waiting for threadgroup to exit, active threads is 1
    [junit] 2009-06-27 13:07:28,969 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 41449
    [junit] 2009-06-27 13:07:28,970 INFO datanode.DataBlockScanner (DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
    [junit] 2009-06-27 13:07:28,971 INFO datanode.DataNode (DataNode.java:run(1273)) - DatanodeRegistration(127.0.0.1:40254, storageID=DS-1022175986-67.195.138.9-40254-1246108046488, infoPort=51178, ipcPort=41449):Finishing DataNode in: FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data1/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build/test/data/dfs/data/data2/current'}
    [junit] 2009-06-27 13:07:28,971 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 41449
    [junit] 2009-06-27 13:07:28,971 INFO datanode.DataNode (DataNode.java:shutdown(638)) - Waiting for threadgroup to exit, active threads is 0
    [junit] 2009-06-27 13:07:29,073 WARN namenode.FSNamesystem (FSNamesystem.java:run(2075)) - ReplicationMonitor thread received InterruptedException.java.lang.InterruptedException: sleep interrupted
    [junit] 2009-06-27 13:07:29,073 INFO namenode.FSNamesystem (FSEditLog.java:printStatistics(876)) - Number of transactions: 0 Total time for transactions(ms): 0Number of transactions batched in Syncs: 0 Number of syncs: 0 SyncTimes(ms): 0 0
    [junit] 2009-06-27 13:07:29,073 WARN namenode.DecommissionManager (DecommissionManager.java:run(67)) - Monitor interrupted: java.lang.InterruptedException: sleep interrupted
    [junit] 2009-06-27 13:07:29,180 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 47963
    [junit] 2009-06-27 13:07:29,181 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 47963: exiting
    [junit] 2009-06-27 13:07:29,181 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 47963: exiting
    [junit] 2009-06-27 13:07:29,181 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 47963: exiting
    [junit] 2009-06-27 13:07:29,181 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 3 on 47963: exiting
    [junit] 2009-06-27 13:07:29,181 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 4 on 47963: exiting
    [junit] 2009-06-27 13:07:29,182 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 5 on 47963: exiting
    [junit] 2009-06-27 13:07:29,182 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 6 on 47963: exiting
    [junit] 2009-06-27 13:07:29,182 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 7 on 47963: exiting
    [junit] 2009-06-27 13:07:29,182 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 8 on 47963: exiting
    [junit] 2009-06-27 13:07:29,182 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 9 on 47963: exiting
    [junit] 2009-06-27 13:07:29,183 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
    [junit] 2009-06-27 13:07:29,183 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 47963
    [junit] Tests run: 2, Failures: 0, Errors: 0, Time elapsed: 149.027 sec

    checkfailure:

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

    Total time: 93 minutes 33 seconds
    Publishing Javadoc
    Recording test results
    Recording fingerprints
    Publishing Clover coverage report...
  • Apache Hudson Server at Jun 28, 2009 at 12:48 pm
    See http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/6/

    ------------------------------------------
    [...truncated 272199 lines...]
    [junit] 2009-06-28 12:46:39,490 INFO common.Storage (DataStorage.java:recoverTransitionRead(122)) - Storage directory http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data2 is not formatted.
    [junit] 2009-06-28 12:46:39,490 INFO common.Storage (DataStorage.java:recoverTransitionRead(123)) - Formatting ...
    [junit] 2009-06-28 12:46:39,748 INFO datanode.DataNode (FSDataset.java:registerMBean(1417)) - Registered FSDatasetStatusMBean
    [junit] 2009-06-28 12:46:39,748 INFO datanode.DataNode (DataNode.java:startDataNode(326)) - Opened info server at 41455
    [junit] 2009-06-28 12:46:39,749 INFO datanode.DataNode (DataXceiverServer.java:<init>(74)) - Balancing bandwith is 1048576 bytes/s
    [junit] 2009-06-28 12:46:39,749 INFO datanode.DirectoryScanner (DirectoryScanner.java:<init>(133)) - scan starts at 1246212254749 with interval 21600000
    [junit] 2009-06-28 12:46:39,751 INFO http.HttpServer (HttpServer.java:start(425)) - Port returned by webServer.getConnectors()[0].getLocalPort() before open() is -1. Opening the listener on 0
    [junit] 2009-06-28 12:46:39,751 INFO http.HttpServer (HttpServer.java:start(430)) - listener.getLocalPort() returned 35161 webServer.getConnectors()[0].getLocalPort() returned 35161
    [junit] 2009-06-28 12:46:39,751 INFO http.HttpServer (HttpServer.java:start(463)) - Jetty bound to port 35161
    [junit] 2009-06-28 12:46:39,752 INFO mortbay.log (?:invoke(?)) - jetty-6.1.14
    [junit] 2009-06-28 12:46:39,817 INFO mortbay.log (?:invoke(?)) - Started SelectChannelConnector@localhost:35161
    [junit] 2009-06-28 12:46:39,817 INFO jvm.JvmMetrics (JvmMetrics.java:init(66)) - Cannot initialize JVM Metrics with processName=DataNode, sessionId=null - already initialized
    [junit] 2009-06-28 12:46:39,829 INFO metrics.RpcMetrics (RpcMetrics.java:<init>(58)) - Initializing RPC Metrics with hostName=DataNode, port=50674
    [junit] 2009-06-28 12:46:39,829 INFO ipc.Server (Server.java:run(474)) - IPC Server Responder: starting
    [junit] 2009-06-28 12:46:39,830 INFO datanode.DataNode (DataNode.java:startDataNode(404)) - dnRegistration = DatanodeRegistration(vesta.apache.org:41455, storageID=, infoPort=35161, ipcPort=50674)
    [junit] 2009-06-28 12:46:39,830 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 2 on 50674: starting
    [junit] 2009-06-28 12:46:39,830 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 1 on 50674: starting
    [junit] 2009-06-28 12:46:39,830 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 0 on 50674: starting
    [junit] 2009-06-28 12:46:39,829 INFO ipc.Server (Server.java:run(313)) - IPC Server listener on 50674: starting
    [junit] 2009-06-28 12:46:39,832 INFO hdfs.StateChange (FSNamesystem.java:registerDatanode(1772)) - BLOCK* NameSystem.registerDatanode: node registration from 127.0.0.1:41455 storage DS-1226412148-67.195.138.9-41455-1246193199831
    [junit] 2009-06-28 12:46:39,833 INFO net.NetworkTopology (NetworkTopology.java:add(327)) - Adding a new node: /default-rack/127.0.0.1:41455
    [junit] 2009-06-28 12:46:39,875 INFO datanode.DataNode (DataNode.java:register(566)) - New storage id DS-1226412148-67.195.138.9-41455-1246193199831 is assigned to data-node 127.0.0.1:41455
    [junit] Starting DataNode 1 with dfs.data.dir: http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data3,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build/test/data/dfs/data/data4
    [junit] 2009-06-28 12:46:39,876 INFO datanode.DataNode (DataNode.java:run(1253)) - DatanodeRegistration(127.0.0.1:41455, storageID=DS-1226412148-67.195.138.9-41455-1246193199831, infoPort=35161, ipcPort=50674)In DataNode.run, data = FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data1/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build/test/data/dfs/data/data2/current'}
    [junit] 2009-06-28 12:46:39,876 INFO datanode.DataNode (DataNode.java:offerService(734)) - using BLOCKREPORT_INTERVAL of 21600000msec Initial delay: 0msec
    [junit] 2009-06-28 12:46:39,886 INFO common.Storage (DataStorage.java:recoverTransitionRead(122)) - Storage directory http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data3 is not formatted.
    [junit] 2009-06-28 12:46:39,887 INFO common.Storage (DataStorage.java:recoverTransitionRead(123)) - Formatting ...
    [junit] 2009-06-28 12:46:39,921 INFO datanode.DataNode (DataNode.java:blockReport(969)) - BlockReport of 0 blocks got processed in 1 msecs
    [junit] 2009-06-28 12:46:39,922 INFO datanode.DataNode (DataNode.java:offerService(777)) - Starting Periodic block scanner.
    [junit] 2009-06-28 12:46:40,063 INFO common.Storage (DataStorage.java:recoverTransitionRead(122)) - Storage directory http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data4 is not formatted.
    [junit] 2009-06-28 12:46:40,063 INFO common.Storage (DataStorage.java:recoverTransitionRead(123)) - Formatting ...
    [junit] 2009-06-28 12:46:40,203 INFO mapred.JvmManager (JvmManager.java:runChild(411)) - JVM : jvm_200906281244_0004_m_453253270 exited. Number of tasks it ran: 1
    [junit] 2009-06-28 12:46:40,349 INFO datanode.DataNode (FSDataset.java:registerMBean(1417)) - Registered FSDatasetStatusMBean
    [junit] 2009-06-28 12:46:40,349 INFO datanode.DataNode (DataNode.java:startDataNode(326)) - Opened info server at 36308
    [junit] 2009-06-28 12:46:40,349 INFO datanode.DataNode (DataXceiverServer.java:<init>(74)) - Balancing bandwith is 1048576 bytes/s
    [junit] 2009-06-28 12:46:40,350 INFO datanode.DirectoryScanner (DirectoryScanner.java:<init>(133)) - scan starts at 1246203856350 with interval 21600000
    [junit] 2009-06-28 12:46:40,351 INFO http.HttpServer (HttpServer.java:start(425)) - Port returned by webServer.getConnectors()[0].getLocalPort() before open() is -1. Opening the listener on 0
    [junit] 2009-06-28 12:46:40,351 INFO http.HttpServer (HttpServer.java:start(430)) - listener.getLocalPort() returned 43614 webServer.getConnectors()[0].getLocalPort() returned 43614
    [junit] 2009-06-28 12:46:40,352 INFO http.HttpServer (HttpServer.java:start(463)) - Jetty bound to port 43614
    [junit] 2009-06-28 12:46:40,352 INFO mortbay.log (?:invoke(?)) - jetty-6.1.14
    [junit] 2009-06-28 12:46:40,414 INFO mortbay.log (?:invoke(?)) - Started SelectChannelConnector@localhost:43614
    [junit] 2009-06-28 12:46:40,415 INFO jvm.JvmMetrics (JvmMetrics.java:init(66)) - Cannot initialize JVM Metrics with processName=DataNode, sessionId=null - already initialized
    [junit] 2009-06-28 12:46:40,426 INFO metrics.RpcMetrics (RpcMetrics.java:<init>(58)) - Initializing RPC Metrics with hostName=DataNode, port=59615
    [junit] 2009-06-28 12:46:40,427 INFO ipc.Server (Server.java:run(474)) - IPC Server Responder: starting
    [junit] 2009-06-28 12:46:40,427 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 2 on 59615: starting
    [junit] 2009-06-28 12:46:40,427 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 1 on 59615: starting
    [junit] 2009-06-28 12:46:40,427 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 0 on 59615: starting
    [junit] 2009-06-28 12:46:40,427 INFO ipc.Server (Server.java:run(313)) - IPC Server listener on 59615: starting
    [junit] 2009-06-28 12:46:40,428 INFO datanode.DataNode (DataNode.java:startDataNode(404)) - dnRegistration = DatanodeRegistration(vesta.apache.org:36308, storageID=, infoPort=43614, ipcPort=59615)
    [junit] 2009-06-28 12:46:40,430 INFO hdfs.StateChange (FSNamesystem.java:registerDatanode(1772)) - BLOCK* NameSystem.registerDatanode: node registration from 127.0.0.1:36308 storage DS-2026207998-67.195.138.9-36308-1246193200429
    [junit] 2009-06-28 12:46:40,430 INFO net.NetworkTopology (NetworkTopology.java:add(327)) - Adding a new node: /default-rack/127.0.0.1:36308
    [junit] 2009-06-28 12:46:40,502 INFO datanode.DataNode (DataNode.java:register(566)) - New storage id DS-2026207998-67.195.138.9-36308-1246193200429 is assigned to data-node 127.0.0.1:36308
    [junit] Starting DataNode 2 with dfs.data.dir: http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data5,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build/test/data/dfs/data/data6
    [junit] 2009-06-28 12:46:40,502 INFO datanode.DataNode (DataNode.java:run(1253)) - DatanodeRegistration(127.0.0.1:36308, storageID=DS-2026207998-67.195.138.9-36308-1246193200429, infoPort=43614, ipcPort=59615)In DataNode.run, data = FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data3/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build/test/data/dfs/data/data4/current'}
    [junit] 2009-06-28 12:46:40,503 INFO datanode.DataNode (DataNode.java:offerService(734)) - using BLOCKREPORT_INTERVAL of 21600000msec Initial delay: 0msec
    [junit] 2009-06-28 12:46:40,514 INFO common.Storage (DataStorage.java:recoverTransitionRead(122)) - Storage directory http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data5 is not formatted.
    [junit] 2009-06-28 12:46:40,515 INFO common.Storage (DataStorage.java:recoverTransitionRead(123)) - Formatting ...
    [junit] 2009-06-28 12:46:40,543 INFO datanode.DataNode (DataNode.java:blockReport(969)) - BlockReport of 0 blocks got processed in 0 msecs
    [junit] 2009-06-28 12:46:40,544 INFO datanode.DataNode (DataNode.java:offerService(777)) - Starting Periodic block scanner.
    [junit] 2009-06-28 12:46:40,697 INFO common.Storage (DataStorage.java:recoverTransitionRead(122)) - Storage directory http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data6 is not formatted.
    [junit] 2009-06-28 12:46:40,697 INFO common.Storage (DataStorage.java:recoverTransitionRead(123)) - Formatting ...
    [junit] 2009-06-28 12:46:40,951 INFO datanode.DataNode (FSDataset.java:registerMBean(1417)) - Registered FSDatasetStatusMBean
    [junit] 2009-06-28 12:46:40,952 INFO datanode.DataNode (DataNode.java:startDataNode(326)) - Opened info server at 49211
    [junit] 2009-06-28 12:46:40,952 INFO datanode.DataNode (DataXceiverServer.java:<init>(74)) - Balancing bandwith is 1048576 bytes/s
    [junit] 2009-06-28 12:46:40,953 INFO datanode.DirectoryScanner (DirectoryScanner.java:<init>(133)) - scan starts at 1246203848953 with interval 21600000
    [junit] 2009-06-28 12:46:40,954 INFO http.HttpServer (HttpServer.java:start(425)) - Port returned by webServer.getConnectors()[0].getLocalPort() before open() is -1. Opening the listener on 0
    [junit] 2009-06-28 12:46:40,955 INFO http.HttpServer (HttpServer.java:start(430)) - listener.getLocalPort() returned 56356 webServer.getConnectors()[0].getLocalPort() returned 56356
    [junit] 2009-06-28 12:46:40,955 INFO http.HttpServer (HttpServer.java:start(463)) - Jetty bound to port 56356
    [junit] 2009-06-28 12:46:40,955 INFO mortbay.log (?:invoke(?)) - jetty-6.1.14
    [junit] 2009-06-28 12:46:41,038 INFO mortbay.log (?:invoke(?)) - Started SelectChannelConnector@localhost:56356
    [junit] 2009-06-28 12:46:41,040 INFO jvm.JvmMetrics (JvmMetrics.java:init(66)) - Cannot initialize JVM Metrics with processName=DataNode, sessionId=null - already initialized
    [junit] 2009-06-28 12:46:41,052 INFO metrics.RpcMetrics (RpcMetrics.java:<init>(58)) - Initializing RPC Metrics with hostName=DataNode, port=50558
    [junit] 2009-06-28 12:46:41,053 INFO ipc.Server (Server.java:run(474)) - IPC Server Responder: starting
    [junit] 2009-06-28 12:46:41,053 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 1 on 50558: starting
    [junit] 2009-06-28 12:46:41,053 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 0 on 50558: starting
    [junit] 2009-06-28 12:46:41,053 INFO ipc.Server (Server.java:run(313)) - IPC Server listener on 50558: starting
    [junit] 2009-06-28 12:46:41,058 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 2 on 50558: starting
    [junit] 2009-06-28 12:46:41,058 INFO datanode.DataNode (DataNode.java:startDataNode(404)) - dnRegistration = DatanodeRegistration(vesta.apache.org:49211, storageID=, infoPort=56356, ipcPort=50558)
    [junit] 2009-06-28 12:46:41,059 INFO hdfs.StateChange (FSNamesystem.java:registerDatanode(1772)) - BLOCK* NameSystem.registerDatanode: node registration from 127.0.0.1:49211 storage DS-1277956712-67.195.138.9-49211-1246193201059
    [junit] 2009-06-28 12:46:41,060 INFO net.NetworkTopology (NetworkTopology.java:add(327)) - Adding a new node: /default-rack/127.0.0.1:49211
    [junit] 2009-06-28 12:46:41,098 INFO datanode.DataNode (DataNode.java:register(566)) - New storage id DS-1277956712-67.195.138.9-49211-1246193201059 is assigned to data-node 127.0.0.1:49211
    [junit] 2009-06-28 12:46:41,098 INFO datanode.DataNode (DataNode.java:run(1253)) - DatanodeRegistration(127.0.0.1:49211, storageID=DS-1277956712-67.195.138.9-49211-1246193201059, infoPort=56356, ipcPort=50558)In DataNode.run, data = FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data5/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build/test/data/dfs/data/data6/current'}
    [junit] Starting DataNode 3 with dfs.data.dir: http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data7,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build/test/data/dfs/data/data8
    [junit] 2009-06-28 12:46:41,099 INFO datanode.DataNode (DataNode.java:offerService(734)) - using BLOCKREPORT_INTERVAL of 21600000msec Initial delay: 0msec
    [junit] 2009-06-28 12:46:41,108 INFO common.Storage (DataStorage.java:recoverTransitionRead(122)) - Storage directory http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data7 is not formatted.
    [junit] 2009-06-28 12:46:41,109 INFO common.Storage (DataStorage.java:recoverTransitionRead(123)) - Formatting ...
    [junit] 2009-06-28 12:46:41,142 INFO datanode.DataNode (DataNode.java:blockReport(969)) - BlockReport of 0 blocks got processed in 1 msecs
    [junit] 2009-06-28 12:46:41,143 INFO datanode.DataNode (DataNode.java:offerService(777)) - Starting Periodic block scanner.
    [junit] 2009-06-28 12:46:41,277 INFO common.Storage (DataStorage.java:recoverTransitionRead(122)) - Storage directory http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data8 is not formatted.
    [junit] 2009-06-28 12:46:41,277 INFO common.Storage (DataStorage.java:recoverTransitionRead(123)) - Formatting ...
    [junit] 2009-06-28 12:46:41,513 INFO datanode.DataNode (FSDataset.java:registerMBean(1417)) - Registered FSDatasetStatusMBean
    [junit] 2009-06-28 12:46:41,513 INFO datanode.DataNode (DataNode.java:startDataNode(326)) - Opened info server at 39791
    [junit] 2009-06-28 12:46:41,513 INFO datanode.DataNode (DataXceiverServer.java:<init>(74)) - Balancing bandwith is 1048576 bytes/s
    [junit] 2009-06-28 12:46:41,514 INFO datanode.DirectoryScanner (DirectoryScanner.java:<init>(133)) - scan starts at 1246197541514 with interval 21600000
    [junit] 2009-06-28 12:46:41,515 INFO http.HttpServer (HttpServer.java:start(425)) - Port returned by webServer.getConnectors()[0].getLocalPort() before open() is -1. Opening the listener on 0
    [junit] 2009-06-28 12:46:41,515 INFO http.HttpServer (HttpServer.java:start(430)) - listener.getLocalPort() returned 43840 webServer.getConnectors()[0].getLocalPort() returned 43840
    [junit] 2009-06-28 12:46:41,516 INFO http.HttpServer (HttpServer.java:start(463)) - Jetty bound to port 43840
    [junit] 2009-06-28 12:46:41,516 INFO mortbay.log (?:invoke(?)) - jetty-6.1.14
    [junit] 2009-06-28 12:46:41,582 INFO mortbay.log (?:invoke(?)) - Started SelectChannelConnector@localhost:43840
    [junit] 2009-06-28 12:46:41,582 INFO jvm.JvmMetrics (JvmMetrics.java:init(66)) - Cannot initialize JVM Metrics with processName=DataNode, sessionId=null - already initialized
    [junit] 2009-06-28 12:46:41,594 INFO metrics.RpcMetrics (RpcMetrics.java:<init>(58)) - Initializing RPC Metrics with hostName=DataNode, port=38585
    [junit] 2009-06-28 12:46:41,595 INFO ipc.Server (Server.java:run(474)) - IPC Server Responder: starting
    [junit] 2009-06-28 12:46:41,595 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 2 on 38585: starting
    [junit] 2009-06-28 12:46:41,595 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 1 on 38585: starting
    [junit] 2009-06-28 12:46:41,595 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 0 on 38585: starting
    [junit] 2009-06-28 12:46:41,595 INFO ipc.Server (Server.java:run(313)) - IPC Server listener on 38585: starting
    [junit] 2009-06-28 12:46:41,597 INFO datanode.DataNode (DataNode.java:startDataNode(404)) - dnRegistration = DatanodeRegistration(vesta.apache.org:39791, storageID=, infoPort=43840, ipcPort=38585)
    [junit] 2009-06-28 12:46:41,601 INFO hdfs.StateChange (FSNamesystem.java:registerDatanode(1772)) - BLOCK* NameSystem.registerDatanode: node registration from 127.0.0.1:39791 storage DS-2036690959-67.195.138.9-39791-1246193201600
    [junit] 2009-06-28 12:46:41,601 INFO net.NetworkTopology (NetworkTopology.java:add(327)) - Adding a new node: /default-rack/127.0.0.1:39791
    [junit] 2009-06-28 12:46:41,642 INFO datanode.DataNode (DataNode.java:register(566)) - New storage id DS-2036690959-67.195.138.9-39791-1246193201600 is assigned to data-node 127.0.0.1:39791
    [junit] 2009-06-28 12:46:41,642 INFO datanode.DataNode (DataNode.java:run(1253)) - DatanodeRegistration(127.0.0.1:39791, storageID=DS-2036690959-67.195.138.9-39791-1246193201600, infoPort=43840, ipcPort=38585)In DataNode.run, data = FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data7/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build/test/data/dfs/data/data8/current'}
    [junit] 2009-06-28 12:46:41,651 INFO datanode.DataNode (DataNode.java:offerService(734)) - using BLOCKREPORT_INTERVAL of 21600000msec Initial delay: 0msec
    [junit] 2009-06-28 12:46:41,701 INFO datanode.DataNode (DataNode.java:blockReport(969)) - BlockReport of 0 blocks got processed in 0 msecs
    [junit] 2009-06-28 12:46:41,702 INFO datanode.DataNode (DataNode.java:offerService(777)) - Starting Periodic block scanner.
    [junit] <property><name>security.client.protocol.acl</name><value>*</value></property>
    [junit]
    [junit] <property><name>security.client.datanode.protocol.acl</name><value>*</value></property>
    [junit]
    [junit] <property><name>security.datanode.protocol.acl</name><value>*</value></property>
    [junit]
    [junit] <property><name>security.inter.datanode.protocol.acl</name><value>*</value></property>
    [junit]
    [junit] <property><name>security.namenode.protocol.acl</name><value>*</value></property>
    [junit]
    [junit] <property><name>security.refresh.policy.protocol.acl</name><value>nouser nogroup</value></property>
    [junit]
    [junit] 2009-06-28 12:46:41,746 INFO authorize.ServiceAuthorizationManager (ServiceAuthorizationManager.java:run(92)) - Authorization failed for dev,null
    [junit] java.security.AccessControlException: access denied ConnectionPermission(org.apache.hadoop.security.authorize.RefreshAuthorizationPolicyProtocol)
    [junit] at java.security.AccessControlContext.checkPermission(AccessControlContext.java:323)
    [junit] at java.security.AccessController.checkPermission(AccessController.java:546)
    [junit] at org.apache.hadoop.security.authorize.ServiceAuthorizationManager$1.run(ServiceAuthorizationManager.java:89)
    [junit] at org.apache.hadoop.security.authorize.ServiceAuthorizationManager$1.run(ServiceAuthorizationManager.java:84)
    [junit] at java.security.AccessController.doPrivileged(Native Method)
    [junit] at javax.security.auth.Subject.doAs(Subject.java:396)
    [junit] at org.apache.hadoop.security.authorize.ServiceAuthorizationManager.checkPermission(ServiceAuthorizationManager.java:83)
    [junit] at org.apache.hadoop.security.authorize.ServiceAuthorizationManager.authorize(ServiceAuthorizationManager.java:68)
    [junit] at org.apache.hadoop.ipc.RPC$Server.authorize(RPC.java:565)
    [junit] at org.apache.hadoop.ipc.Server$Connection.readAndProcess(Server.java:858)
    [junit] at org.apache.hadoop.ipc.Server$Listener.doRead(Server.java:420)
    [junit] at org.apache.hadoop.ipc.Server$Listener.run(Server.java:328)
    [junit] Good, refresh worked... refresh failed with:
    [junit] Shutting down the Mini HDFS Cluster
    [junit] Shutting down DataNode 3
    [junit] 2009-06-28 12:46:41,893 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 38585
    [junit] 2009-06-28 12:46:41,894 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 38585: exiting
    [junit] 2009-06-28 12:46:41,894 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 38585: exiting
    [junit] 2009-06-28 12:46:41,894 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 38585
    [junit] 2009-06-28 12:46:41,894 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
    [junit] 2009-06-28 12:46:41,895 INFO datanode.DataNode (DataNode.java:shutdown(638)) - Waiting for threadgroup to exit, active threads is 1
    [junit] 2009-06-28 12:46:41,895 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 38585: exiting
    [junit] 2009-06-28 12:46:41,895 WARN datanode.DataNode (DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:39791, storageID=DS-2036690959-67.195.138.9-39791-1246193201600, infoPort=43840, ipcPort=38585):DataXceiveServer: java.nio.channels.AsynchronousCloseException
    [junit] at java.nio.channels.spi.AbstractInterruptibleChannel.end(AbstractInterruptibleChannel.java:185)
    [junit] at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:152)
    [junit] at sun.nio.ch.ServerSocketAdaptor.accept(ServerSocketAdaptor.java:84)
    [junit] at org.apache.hadoop.hdfs.server.datanode.DataXceiverServer.run(DataXceiverServer.java:130)
    [junit] at java.lang.Thread.run(Thread.java:619)
    [junit]
    [junit] 2009-06-28 12:46:41,898 INFO datanode.DataNode (DataNode.java:shutdown(638)) - Waiting for threadgroup to exit, active threads is 0
    [junit] 2009-06-28 12:46:41,898 INFO datanode.DataBlockScanner (DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
    [junit] 2009-06-28 12:46:41,898 INFO datanode.DataNode (DataNode.java:run(1273)) - DatanodeRegistration(127.0.0.1:39791, storageID=DS-2036690959-67.195.138.9-39791-1246193201600, infoPort=43840, ipcPort=38585):Finishing DataNode in: FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data7/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build/test/data/dfs/data/data8/current'}
    [junit] 2009-06-28 12:46:41,899 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 38585
    [junit] 2009-06-28 12:46:41,899 INFO datanode.DataNode (DataNode.java:shutdown(638)) - Waiting for threadgroup to exit, active threads is 0
    [junit] Shutting down DataNode 2
    [junit] 2009-06-28 12:46:42,001 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 50558
    [junit] 2009-06-28 12:46:42,002 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 50558: exiting
    [junit] 2009-06-28 12:46:42,002 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 50558: exiting
    [junit] 2009-06-28 12:46:42,002 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 50558: exiting
    [junit] 2009-06-28 12:46:42,003 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 50558
    [junit] 2009-06-28 12:46:42,003 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
    [junit] 2009-06-28 12:46:42,003 INFO datanode.DataNode (DataNode.java:shutdown(638)) - Waiting for threadgroup to exit, active threads is 1
    [junit] 2009-06-28 12:46:42,003 WARN datanode.DataNode (DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:49211, storageID=DS-1277956712-67.195.138.9-49211-1246193201059, infoPort=56356, ipcPort=50558):DataXceiveServer: java.nio.channels.AsynchronousCloseException
    [junit] at java.nio.channels.spi.AbstractInterruptibleChannel.end(AbstractInterruptibleChannel.java:185)
    [junit] at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:152)
    [junit] at sun.nio.ch.ServerSocketAdaptor.accept(ServerSocketAdaptor.java:84)
    [junit] at org.apache.hadoop.hdfs.server.datanode.DataXceiverServer.run(DataXceiverServer.java:130)
    [junit] at java.lang.Thread.run(Thread.java:619)
    [junit]
    [junit] 2009-06-28 12:46:42,006 INFO datanode.DataNode (DataNode.java:shutdown(638)) - Waiting for threadgroup to exit, active threads is 0
    [junit] 2009-06-28 12:46:42,006 INFO datanode.DataBlockScanner (DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
    [junit] 2009-06-28 12:46:42,006 INFO datanode.DataNode (DataNode.java:run(1273)) - DatanodeRegistration(127.0.0.1:49211, storageID=DS-1277956712-67.195.138.9-49211-1246193201059, infoPort=56356, ipcPort=50558):Finishing DataNode in: FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data5/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build/test/data/dfs/data/data6/current'}
    [junit] 2009-06-28 12:46:42,007 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 50558
    [junit] 2009-06-28 12:46:42,007 INFO datanode.DataNode (DataNode.java:shutdown(638)) - Waiting for threadgroup to exit, active threads is 0
    [junit] Shutting down DataNode 1
    [junit] 2009-06-28 12:46:42,109 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 59615
    [junit] 2009-06-28 12:46:42,110 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 59615: exiting
    [junit] 2009-06-28 12:46:42,110 INFO datanode.DataNode (DataNode.java:shutdown(638)) - Waiting for threadgroup to exit, active threads is 1
    [junit] 2009-06-28 12:46:42,110 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 59615: exiting
    [junit] 2009-06-28 12:46:42,110 WARN datanode.DataNode (DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:36308, storageID=DS-2026207998-67.195.138.9-36308-1246193200429, infoPort=43614, ipcPort=59615):DataXceiveServer: java.nio.channels.AsynchronousCloseException
    [junit] at java.nio.channels.spi.AbstractInterruptibleChannel.end(AbstractInterruptibleChannel.java:185)
    [junit] at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:152)
    [junit] at sun.nio.ch.ServerSocketAdaptor.accept(ServerSocketAdaptor.java:84)
    [junit] at org.apache.hadoop.hdfs.server.datanode.DataXceiverServer.run(DataXceiverServer.java:130)
    [junit] at java.lang.Thread.run(Thread.java:619)
    [junit]
    [junit] 2009-06-28 12:46:42,110 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 59615
    [junit] 2009-06-28 12:46:42,110 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
    [junit] 2009-06-28 12:46:42,110 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 59615: exiting
    [junit] 2009-06-28 12:46:42,113 INFO datanode.DataNode (DataNode.java:shutdown(638)) - Waiting for threadgroup to exit, active threads is 0
    [junit] 2009-06-28 12:46:42,113 INFO datanode.DataBlockScanner (DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
    [junit] 2009-06-28 12:46:42,113 INFO datanode.DataNode (DataNode.java:run(1273)) - DatanodeRegistration(127.0.0.1:36308, storageID=DS-2026207998-67.195.138.9-36308-1246193200429, infoPort=43614, ipcPort=59615):Finishing DataNode in: FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data3/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build/test/data/dfs/data/data4/current'}
    [junit] 2009-06-28 12:46:42,113 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 59615
    [junit] 2009-06-28 12:46:42,114 INFO datanode.DataNode (DataNode.java:shutdown(638)) - Waiting for threadgroup to exit, active threads is 0
    [junit] Shutting down DataNode 0
    [junit] 2009-06-28 12:46:42,217 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 50674
    [junit] 2009-06-28 12:46:42,217 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 50674: exiting
    [junit] 2009-06-28 12:46:42,217 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 50674
    [junit] 2009-06-28 12:46:42,218 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 50674: exiting
    [junit] 2009-06-28 12:46:42,218 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 50674: exiting
    [junit] 2009-06-28 12:46:42,217 WARN datanode.DataNode (DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:41455, storageID=DS-1226412148-67.195.138.9-41455-1246193199831, infoPort=35161, ipcPort=50674):DataXceiveServer: java.nio.channels.AsynchronousCloseException
    [junit] at java.nio.channels.spi.AbstractInterruptibleChannel.end(AbstractInterruptibleChannel.java:185)
    [junit] at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:152)
    [junit] at sun.nio.ch.ServerSocketAdaptor.accept(ServerSocketAdaptor.java:84)
    [junit] at org.apache.hadoop.hdfs.server.datanode.DataXceiverServer.run(DataXceiverServer.java:130)
    [junit] at java.lang.Thread.run(Thread.java:619)
    [junit]
    [junit] 2009-06-28 12:46:42,217 INFO datanode.DataNode (DataNode.java:shutdown(638)) - Waiting for threadgroup to exit, active threads is 1
    [junit] 2009-06-28 12:46:42,217 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
    [junit] 2009-06-28 12:46:42,219 INFO datanode.DataBlockScanner (DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
    [junit] 2009-06-28 12:46:42,220 INFO datanode.DataNode (DataNode.java:run(1273)) - DatanodeRegistration(127.0.0.1:41455, storageID=DS-1226412148-67.195.138.9-41455-1246193199831, infoPort=35161, ipcPort=50674):Finishing DataNode in: FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build/test/data/dfs/data/data1/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build/test/data/dfs/data/data2/current'}
    [junit] 2009-06-28 12:46:42,220 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 50674
    [junit] 2009-06-28 12:46:42,220 INFO datanode.DataNode (DataNode.java:shutdown(638)) - Waiting for threadgroup to exit, active threads is 0
    [junit] 2009-06-28 12:46:42,322 WARN namenode.DecommissionManager (DecommissionManager.java:run(67)) - Monitor interrupted: java.lang.InterruptedException: sleep interrupted
    [junit] 2009-06-28 12:46:42,322 INFO namenode.FSNamesystem (FSEditLog.java:printStatistics(876)) - Number of transactions: 0 Total time for transactions(ms): 0Number of transactions batched in Syncs: 0 Number of syncs: 0 SyncTimes(ms): 0 0
    [junit] 2009-06-28 12:46:42,323 WARN namenode.FSNamesystem (FSNamesystem.java:run(2075)) - ReplicationMonitor thread received InterruptedException.java.lang.InterruptedException: sleep interrupted
    [junit] 2009-06-28 12:46:42,412 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 56050
    [junit] 2009-06-28 12:46:42,412 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 56050: exiting
    [junit] 2009-06-28 12:46:42,413 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
    [junit] 2009-06-28 12:46:42,413 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 5 on 56050: exiting
    [junit] 2009-06-28 12:46:42,412 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 56050
    [junit] 2009-06-28 12:46:42,412 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 7 on 56050: exiting
    [junit] 2009-06-28 12:46:42,412 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 8 on 56050: exiting
    [junit] 2009-06-28 12:46:42,412 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 4 on 56050: exiting
    [junit] 2009-06-28 12:46:42,412 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 56050: exiting
    [junit] 2009-06-28 12:46:42,413 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 56050: exiting
    [junit] 2009-06-28 12:46:42,413 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 3 on 56050: exiting
    [junit] Tests run: 2, Failures: 0, Errors: 0, Time elapsed: 126.93 sec
    [junit] 2009-06-28 12:46:42,413 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 6 on 56050: exiting
    [junit] 2009-06-28 12:46:42,413 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 9 on 56050: exiting

    checkfailure:

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

    Total time: 72 minutes 50 seconds
    Publishing Javadoc
    Recording test results
    Recording fingerprints
    Publishing Clover coverage report...

Related Discussions

Discussion Navigation
viewthread | post
Discussion Overview
grouphdfs-dev @
categorieshadoop
postedJun 25, '09 at 12:46p
activeJun 28, '09 at 12:48p
posts4
users1
websitehadoop.apache.org...
irc#hadoop

1 user in discussion

Apache Hudson Server: 4 posts

People

Translate

site design / logo © 2022 Grokbase