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
selectchannelconnec...@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
selectchannelconnec...@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
selectchannelconnec...@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
selectchannelconnec...@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...
