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

Changes:

[ddas] HADOOP-6103. Updated common jar from rev 806430

------------------------------------------
[...truncated 226272 lines...]
[junit] 2009-08-21 12:44:38,124 INFO http.HttpServer (HttpServer.java:start(430)) - listener.getLocalPort() returned 33129 webServer.getConnectors()[0].getLocalPort() returned 33129
[junit] 2009-08-21 12:44:38,124 INFO http.HttpServer (HttpServer.java:start(463)) - Jetty bound to port 33129
[junit] 2009-08-21 12:44:38,125 INFO mortbay.log (?:invoke(?)) - jetty-6.1.14
[junit] 2009-08-21 12:44:38,221 INFO mortbay.log (?:invoke(?)) - Started SelectChannelConnector@localhost:33129
[junit] 2009-08-21 12:44:38,222 INFO jvm.JvmMetrics (JvmMetrics.java:init(66)) - Cannot initialize JVM Metrics with processName=DataNode, sessionId=null - already initialized
[junit] 2009-08-21 12:44:38,223 INFO metrics.RpcMetrics (RpcMetrics.java:<init>(58)) - Initializing RPC Metrics with hostName=DataNode, port=60219
[junit] 2009-08-21 12:44:38,224 INFO ipc.Server (Server.java:run(474)) - IPC Server Responder: starting
[junit] 2009-08-21 12:44:38,224 INFO datanode.DataNode (DataNode.java:startDataNode(404)) - dnRegistration = DatanodeRegistration(vesta.apache.org:40199, storageID=, infoPort=33129, ipcPort=60219)
[junit] 2009-08-21 12:44:38,224 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 0 on 60219: starting
[junit] 2009-08-21 12:44:38,224 INFO ipc.Server (Server.java:run(313)) - IPC Server listener on 60219: starting
[junit] 2009-08-21 12:44:38,226 INFO hdfs.StateChange (FSNamesystem.java:registerDatanode(1774)) - BLOCK* NameSystem.registerDatanode: node registration from 127.0.0.1:40199 storage DS-357635502-67.195.138.9-40199-1250858678225
[junit] 2009-08-21 12:44:38,226 INFO net.NetworkTopology (NetworkTopology.java:add(327)) - Adding a new node: /default-rack/127.0.0.1:40199
[junit] 2009-08-21 12:44:38,278 INFO datanode.DataNode (DataNode.java:register(571)) - New storage id DS-357635502-67.195.138.9-40199-1250858678225 is assigned to data-node 127.0.0.1:40199
[junit] 2009-08-21 12:44:38,278 INFO datanode.DataNode (DataNode.java:run(1285)) - DatanodeRegistration(127.0.0.1:40199, storageID=DS-357635502-67.195.138.9-40199-1250858678225, infoPort=33129, ipcPort=60219)In DataNode.run, data = FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build-fi/test/data/dfs/data/data1/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build-fi/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-fi/test/data/dfs/data/data3,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build-fi/test/data/dfs/data/data4
[junit] 2009-08-21 12:44:38,279 INFO datanode.DataNode (DataNode.java:offerService(763)) - using BLOCKREPORT_INTERVAL of 21600000msec Initial delay: 0msec
[junit] 2009-08-21 12:44:38,287 INFO common.Storage (DataStorage.java:recoverTransitionRead(122)) - Storage directory http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build-fi/test/data/dfs/data/data3 is not formatted.
[junit] 2009-08-21 12:44:38,288 INFO common.Storage (DataStorage.java:recoverTransitionRead(123)) - Formatting ...
[junit] 2009-08-21 12:44:38,307 INFO datanode.DataNode (DataNode.java:blockReport(998)) - BlockReport of 0 blocks got processed in 0 msecs
[junit] 2009-08-21 12:44:38,308 INFO datanode.DataNode (DataNode.java:offerService(806)) - Starting Periodic block scanner.
[junit] 2009-08-21 12:44:38,482 INFO common.Storage (DataStorage.java:recoverTransitionRead(122)) - Storage directory http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build-fi/test/data/dfs/data/data4 is not formatted.
[junit] 2009-08-21 12:44:38,482 INFO common.Storage (DataStorage.java:recoverTransitionRead(123)) - Formatting ...
[junit] 2009-08-21 12:44:38,757 INFO datanode.DataNode (FSDataset.java:registerMBean(1547)) - Registered FSDatasetStatusMBean
[junit] 2009-08-21 12:44:38,757 INFO datanode.DataNode (DataNode.java:startDataNode(326)) - Opened info server at 51908
[junit] 2009-08-21 12:44:38,758 INFO datanode.DataNode (DataXceiverServer.java:<init>(74)) - Balancing bandwith is 1048576 bytes/s
[junit] 2009-08-21 12:44:38,758 INFO datanode.DirectoryScanner (DirectoryScanner.java:<init>(133)) - scan starts at 1250869067758 with interval 21600000
[junit] 2009-08-21 12:44:38,759 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-08-21 12:44:38,760 INFO http.HttpServer (HttpServer.java:start(430)) - listener.getLocalPort() returned 55747 webServer.getConnectors()[0].getLocalPort() returned 55747
[junit] 2009-08-21 12:44:38,760 INFO http.HttpServer (HttpServer.java:start(463)) - Jetty bound to port 55747
[junit] 2009-08-21 12:44:38,760 INFO mortbay.log (?:invoke(?)) - jetty-6.1.14
[junit] 2009-08-21 12:44:38,828 INFO mortbay.log (?:invoke(?)) - Started SelectChannelConnector@localhost:55747
[junit] 2009-08-21 12:44:38,829 INFO jvm.JvmMetrics (JvmMetrics.java:init(66)) - Cannot initialize JVM Metrics with processName=DataNode, sessionId=null - already initialized
[junit] 2009-08-21 12:44:38,830 INFO metrics.RpcMetrics (RpcMetrics.java:<init>(58)) - Initializing RPC Metrics with hostName=DataNode, port=36021
[junit] 2009-08-21 12:44:38,830 INFO ipc.Server (Server.java:run(474)) - IPC Server Responder: starting
[junit] 2009-08-21 12:44:38,831 INFO datanode.DataNode (DataNode.java:startDataNode(404)) - dnRegistration = DatanodeRegistration(vesta.apache.org:51908, storageID=, infoPort=55747, ipcPort=36021)
[junit] 2009-08-21 12:44:38,830 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 0 on 36021: starting
[junit] 2009-08-21 12:44:38,830 INFO ipc.Server (Server.java:run(313)) - IPC Server listener on 36021: starting
[junit] 2009-08-21 12:44:38,832 INFO hdfs.StateChange (FSNamesystem.java:registerDatanode(1774)) - BLOCK* NameSystem.registerDatanode: node registration from 127.0.0.1:51908 storage DS-821477171-67.195.138.9-51908-1250858678832
[junit] 2009-08-21 12:44:38,833 INFO net.NetworkTopology (NetworkTopology.java:add(327)) - Adding a new node: /default-rack/127.0.0.1:51908
[junit] 2009-08-21 12:44:38,884 INFO datanode.DataNode (DataNode.java:register(571)) - New storage id DS-821477171-67.195.138.9-51908-1250858678832 is assigned to data-node 127.0.0.1:51908
[junit] 2009-08-21 12:44:38,884 INFO datanode.DataNode (DataNode.java:run(1285)) - DatanodeRegistration(127.0.0.1:51908, storageID=DS-821477171-67.195.138.9-51908-1250858678832, infoPort=55747, ipcPort=36021)In DataNode.run, data = FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build-fi/test/data/dfs/data/data3/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build-fi/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-fi/test/data/dfs/data/data5,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build-fi/test/data/dfs/data/data6
[junit] 2009-08-21 12:44:38,885 INFO datanode.DataNode (DataNode.java:offerService(763)) - using BLOCKREPORT_INTERVAL of 21600000msec Initial delay: 0msec
[junit] 2009-08-21 12:44:38,894 INFO common.Storage (DataStorage.java:recoverTransitionRead(122)) - Storage directory http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build-fi/test/data/dfs/data/data5 is not formatted.
[junit] 2009-08-21 12:44:38,894 INFO common.Storage (DataStorage.java:recoverTransitionRead(123)) - Formatting ...
[junit] 2009-08-21 12:44:38,921 INFO datanode.DataNode (DataNode.java:blockReport(998)) - BlockReport of 0 blocks got processed in 0 msecs
[junit] 2009-08-21 12:44:38,922 INFO datanode.DataNode (DataNode.java:offerService(806)) - Starting Periodic block scanner.
[junit] 2009-08-21 12:44:39,094 INFO common.Storage (DataStorage.java:recoverTransitionRead(122)) - Storage directory http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build-fi/test/data/dfs/data/data6 is not formatted.
[junit] 2009-08-21 12:44:39,094 INFO common.Storage (DataStorage.java:recoverTransitionRead(123)) - Formatting ...
[junit] 2009-08-21 12:44:39,355 INFO datanode.DataNode (FSDataset.java:registerMBean(1547)) - Registered FSDatasetStatusMBean
[junit] 2009-08-21 12:44:39,355 INFO datanode.DataNode (DataNode.java:startDataNode(326)) - Opened info server at 46377
[junit] 2009-08-21 12:44:39,356 INFO datanode.DataNode (DataXceiverServer.java:<init>(74)) - Balancing bandwith is 1048576 bytes/s
[junit] 2009-08-21 12:44:39,356 INFO datanode.DirectoryScanner (DirectoryScanner.java:<init>(133)) - scan starts at 1250869158356 with interval 21600000
[junit] 2009-08-21 12:44:39,357 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-08-21 12:44:39,358 INFO http.HttpServer (HttpServer.java:start(430)) - listener.getLocalPort() returned 54942 webServer.getConnectors()[0].getLocalPort() returned 54942
[junit] 2009-08-21 12:44:39,358 INFO http.HttpServer (HttpServer.java:start(463)) - Jetty bound to port 54942
[junit] 2009-08-21 12:44:39,358 INFO mortbay.log (?:invoke(?)) - jetty-6.1.14
[junit] 2009-08-21 12:44:39,430 INFO mortbay.log (?:invoke(?)) - Started SelectChannelConnector@localhost:54942
[junit] 2009-08-21 12:44:39,431 INFO jvm.JvmMetrics (JvmMetrics.java:init(66)) - Cannot initialize JVM Metrics with processName=DataNode, sessionId=null - already initialized
[junit] 2009-08-21 12:44:39,432 INFO metrics.RpcMetrics (RpcMetrics.java:<init>(58)) - Initializing RPC Metrics with hostName=DataNode, port=47190
[junit] 2009-08-21 12:44:39,432 INFO ipc.Server (Server.java:run(474)) - IPC Server Responder: starting
[junit] 2009-08-21 12:44:39,433 INFO datanode.DataNode (DataNode.java:startDataNode(404)) - dnRegistration = DatanodeRegistration(vesta.apache.org:46377, storageID=, infoPort=54942, ipcPort=47190)
[junit] 2009-08-21 12:44:39,433 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 0 on 47190: starting
[junit] 2009-08-21 12:44:39,433 INFO ipc.Server (Server.java:run(313)) - IPC Server listener on 47190: starting
[junit] 2009-08-21 12:44:39,435 INFO hdfs.StateChange (FSNamesystem.java:registerDatanode(1774)) - BLOCK* NameSystem.registerDatanode: node registration from 127.0.0.1:46377 storage DS-1055442649-67.195.138.9-46377-1250858679434
[junit] 2009-08-21 12:44:39,435 INFO net.NetworkTopology (NetworkTopology.java:add(327)) - Adding a new node: /default-rack/127.0.0.1:46377
[junit] 2009-08-21 12:44:39,478 INFO datanode.DataNode (DataNode.java:register(571)) - New storage id DS-1055442649-67.195.138.9-46377-1250858679434 is assigned to data-node 127.0.0.1:46377
[junit] 2009-08-21 12:44:39,479 INFO datanode.DataNode (DataNode.java:run(1285)) - DatanodeRegistration(127.0.0.1:46377, storageID=DS-1055442649-67.195.138.9-46377-1250858679434, infoPort=54942, ipcPort=47190)In DataNode.run, data = FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build-fi/test/data/dfs/data/data5/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build-fi/test/data/dfs/data/data6/current'}
[junit] 2009-08-21 12:44:39,479 INFO datanode.DataNode (DataNode.java:offerService(763)) - using BLOCKREPORT_INTERVAL of 21600000msec Initial delay: 0msec
[junit] 2009-08-21 12:44:39,552 INFO datanode.DataNode (DataNode.java:blockReport(998)) - BlockReport of 0 blocks got processed in 1 msecs
[junit] 2009-08-21 12:44:39,553 INFO datanode.DataNode (DataNode.java:offerService(806)) - Starting Periodic block scanner.
[junit] 2009-08-21 12:44:39,700 INFO FSNamesystem.audit (FSNamesystem.java:logAuditEvent(114)) - ugi=hudson,hudson ip=/127.0.0.1 cmd=create src=/pipeline_Fi_16/foo dst=null perm=hudson:supergroup:rw-r--r--
[junit] 2009-08-21 12:44:39,736 INFO hdfs.StateChange (FSNamesystem.java:allocateBlock(1303)) - BLOCK* NameSystem.allocateBlock: /pipeline_Fi_16/foo. blk_1975120595995065171_1001
[junit] 2009-08-21 12:44:39,737 INFO protocol.ClientProtocolAspects (ClientProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_protocol_ClientProtocolAspects$1$7076326d(35)) - FI: addBlock Pipeline[127.0.0.1:46377, 127.0.0.1:40199, 127.0.0.1:51908]
[junit] 2009-08-21 12:44:39,738 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$1$8f59fdd7(51)) - FI: receiverOp WRITE_BLOCK, datanode=127.0.0.1:46377
[junit] 2009-08-21 12:44:39,738 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$3$3251489(72)) - FI: receiverOpWriteBlock
[junit] 2009-08-21 12:44:39,739 INFO datanode.DataNode (DataXceiver.java:opWriteBlock(222)) - Receiving block blk_1975120595995065171_1001 src: /127.0.0.1:36641 dest: /127.0.0.1:46377
[junit] 2009-08-21 12:44:39,740 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$1$8f59fdd7(51)) - FI: receiverOp WRITE_BLOCK, datanode=127.0.0.1:40199
[junit] 2009-08-21 12:44:39,741 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$3$3251489(72)) - FI: receiverOpWriteBlock
[junit] 2009-08-21 12:44:39,741 INFO datanode.DataNode (DataXceiver.java:opWriteBlock(222)) - Receiving block blk_1975120595995065171_1001 src: /127.0.0.1:43022 dest: /127.0.0.1:40199
[junit] 2009-08-21 12:44:39,743 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$1$8f59fdd7(51)) - FI: receiverOp WRITE_BLOCK, datanode=127.0.0.1:51908
[junit] 2009-08-21 12:44:39,743 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$3$3251489(72)) - FI: receiverOpWriteBlock
[junit] 2009-08-21 12:44:39,743 INFO datanode.DataNode (DataXceiver.java:opWriteBlock(222)) - Receiving block blk_1975120595995065171_1001 src: /127.0.0.1:51401 dest: /127.0.0.1:51908
[junit] 2009-08-21 12:44:39,744 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$2$d4f6605f(61)) - FI: statusRead SUCCESS, datanode=127.0.0.1:40199
[junit] 2009-08-21 12:44:39,745 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$2$d4f6605f(61)) - FI: statusRead SUCCESS, datanode=127.0.0.1:46377
[junit] 2009-08-21 12:44:39,746 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
[junit] 2009-08-21 12:44:39,746 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
[junit] 2009-08-21 12:44:39,746 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
[junit] 2009-08-21 12:44:39,747 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
[junit] 2009-08-21 12:44:39,746 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
[junit] 2009-08-21 12:44:39,747 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
[junit] 2009-08-21 12:44:39,747 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
[junit] 2009-08-21 12:44:39,747 INFO fi.FiTestUtil (DataTransferTestUtil.java:run(151)) - FI: pipeline_Fi_16, index=2, datanode=127.0.0.1:51908
[junit] 2009-08-21 12:44:39,748 WARN datanode.DataNode (DataNode.java:checkDiskError(702)) - checkDiskError: exception:
[junit] org.apache.hadoop.util.DiskChecker$DiskOutOfSpaceException: FI: pipeline_Fi_16, index=2, datanode=127.0.0.1:51908
[junit] at org.apache.hadoop.fi.DataTransferTestUtil$DoosAction.run(DataTransferTestUtil.java:152)
[junit] at org.apache.hadoop.fi.DataTransferTestUtil$DoosAction.run(DataTransferTestUtil.java:1)
[junit] at org.apache.hadoop.fi.FiTestUtil$ActionContainer.run(FiTestUtil.java:66)
[junit] at org.apache.hadoop.hdfs.server.datanode.BlockReceiverAspects.ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(BlockReceiverAspects.aj:50)
[junit] at org.apache.hadoop.hdfs.server.datanode.BlockReceiver.receivePacket(BlockReceiver.java:459)
[junit] at org.apache.hadoop.hdfs.server.datanode.BlockReceiver.receiveBlock(BlockReceiver.java:535)
[junit] at org.apache.hadoop.hdfs.server.datanode.DataXceiver.opWriteBlock(DataXceiver.java:339)
[junit] at org.apache.hadoop.hdfs.protocol.DataTransferProtocol$Receiver.opWriteBlock(DataTransferProtocol.java:324)
[junit] at org.apache.hadoop.hdfs.protocol.DataTransferProtocol$Receiver.processOp(DataTransferProtocol.java:269)
[junit] at org.apache.hadoop.hdfs.server.datanode.DataXceiver.run(DataXceiver.java:110)
[junit] at java.lang.Thread.run(Thread.java:619)
[junit] 2009-08-21 12:44:39,748 INFO mortbay.log (?:invoke(?)) - Completed FSVolumeSet.checkDirs. Removed=0volumes. List of current volumes: http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build-fi/test/data/dfs/data/data3/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build-fi/test/data/dfs/data/data4/current
[junit] 2009-08-21 12:44:39,749 INFO datanode.DataNode (BlockReceiver.java:receiveBlock(569)) - Exception in receiveBlock for block blk_1975120595995065171_1001 org.apache.hadoop.util.DiskChecker$DiskOutOfSpaceException: FI: pipeline_Fi_16, index=2, datanode=127.0.0.1:51908
[junit] 2009-08-21 12:44:39,749 INFO datanode.DataNode (BlockReceiver.java:lastDataNodeRun(782)) - PacketResponder 0 for block blk_1975120595995065171_1001 Interrupted.
[junit] 2009-08-21 12:44:39,749 INFO datanode.DataNode (BlockReceiver.java:lastDataNodeRun(853)) - PacketResponder 0 for block blk_1975120595995065171_1001 terminating
[junit] 2009-08-21 12:44:39,749 INFO datanode.DataNode (DataXceiver.java:opWriteBlock(358)) - writeBlock blk_1975120595995065171_1001 received exception org.apache.hadoop.util.DiskChecker$DiskOutOfSpaceException: FI: pipeline_Fi_16, index=2, datanode=127.0.0.1:51908
[junit] 2009-08-21 12:44:39,749 ERROR datanode.DataNode (DataXceiver.java:run(112)) - DatanodeRegistration(127.0.0.1:51908, storageID=DS-821477171-67.195.138.9-51908-1250858678832, infoPort=55747, ipcPort=36021):DataXceiver
[junit] org.apache.hadoop.util.DiskChecker$DiskOutOfSpaceException: FI: pipeline_Fi_16, index=2, datanode=127.0.0.1:51908
[junit] at org.apache.hadoop.fi.DataTransferTestUtil$DoosAction.run(DataTransferTestUtil.java:152)
[junit] at org.apache.hadoop.fi.DataTransferTestUtil$DoosAction.run(DataTransferTestUtil.java:1)
[junit] at org.apache.hadoop.fi.FiTestUtil$ActionContainer.run(FiTestUtil.java:66)
[junit] at org.apache.hadoop.hdfs.server.datanode.BlockReceiverAspects.ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(BlockReceiverAspects.aj:50)
[junit] at org.apache.hadoop.hdfs.server.datanode.BlockReceiver.receivePacket(BlockReceiver.java:459)
[junit] at org.apache.hadoop.hdfs.server.datanode.BlockReceiver.receiveBlock(BlockReceiver.java:535)
[junit] at org.apache.hadoop.hdfs.server.datanode.DataXceiver.opWriteBlock(DataXceiver.java:339)
[junit] at org.apache.hadoop.hdfs.protocol.DataTransferProtocol$Receiver.opWriteBlock(DataTransferProtocol.java:324)
[junit] at org.apache.hadoop.hdfs.protocol.DataTransferProtocol$Receiver.processOp(DataTransferProtocol.java:269)
[junit] at org.apache.hadoop.hdfs.server.datanode.DataXceiver.run(DataXceiver.java:110)
[junit] at java.lang.Thread.run(Thread.java:619)
[junit] 2009-08-21 12:44:39,749 INFO datanode.DataNode (BlockReceiver.java:run(917)) - PacketResponder blk_1975120595995065171_1001 1 Exception java.io.EOFException
[junit] at java.io.DataInputStream.readFully(DataInputStream.java:180)
[junit] at java.io.DataInputStream.readLong(DataInputStream.java:399)
[junit] at org.apache.hadoop.hdfs.server.datanode.BlockReceiver$PacketResponder.run(BlockReceiver.java:879)
[junit] at java.lang.Thread.run(Thread.java:619)
[junit]
[junit] 2009-08-21 12:44:39,751 INFO datanode.DataNode (BlockReceiver.java:run(1025)) - PacketResponder 1 for block blk_1975120595995065171_1001 terminating
[junit] 2009-08-21 12:44:39,751 INFO datanode.DataNode (BlockReceiver.java:run(1025)) - PacketResponder 2 for block blk_1975120595995065171_1001 terminating
[junit] 2009-08-21 12:44:39,752 WARN hdfs.DFSClient (DFSClient.java:run(2601)) - DFSOutputStream ResponseProcessor exception for block blk_1975120595995065171_1001java.io.IOException: Bad response ERROR for block blk_1975120595995065171_1001 from datanode 127.0.0.1:51908
[junit] at org.apache.hadoop.hdfs.DFSClient$DFSOutputStream$DataStreamer$ResponseProcessor.run(DFSClient.java:2581)
[junit]
[junit] 2009-08-21 12:44:39,752 WARN hdfs.DFSClient (DFSClient.java:processDatanodeError(2630)) - Error Recovery for block blk_1975120595995065171_1001 bad datanode[2] 127.0.0.1:51908
[junit] 2009-08-21 12:44:39,752 WARN hdfs.DFSClient (DFSClient.java:processDatanodeError(2674)) - Error Recovery for block blk_1975120595995065171_1001 in pipeline 127.0.0.1:46377, 127.0.0.1:40199, 127.0.0.1:51908: bad datanode 127.0.0.1:51908
[junit] 2009-08-21 12:44:39,755 INFO datanode.DataNode (DataNode.java:logRecoverBlock(1727)) - Client calls recoverBlock(block=blk_1975120595995065171_1001, targets=[127.0.0.1:46377, 127.0.0.1:40199])
[junit] 2009-08-21 12:44:39,758 INFO datanode.DataNode (DataNode.java:updateBlock(1537)) - oldblock=blk_1975120595995065171_1001(length=1), newblock=blk_1975120595995065171_1002(length=1), datanode=127.0.0.1:46377
[junit] 2009-08-21 12:44:39,759 INFO datanode.DataNode (DataNode.java:updateBlock(1537)) - oldblock=blk_1975120595995065171_1001(length=1), newblock=blk_1975120595995065171_1002(length=1), datanode=127.0.0.1:40199
[junit] 2009-08-21 12:44:39,760 INFO namenode.FSNamesystem (FSNamesystem.java:commitBlockSynchronization(1613)) - commitBlockSynchronization(lastblock=blk_1975120595995065171_1001, newgenerationstamp=1002, newlength=1, newtargets=[127.0.0.1:46377, 127.0.0.1:40199], closeFile=false, deleteBlock=false)
[junit] 2009-08-21 12:44:39,760 INFO namenode.FSNamesystem (FSNamesystem.java:commitBlockSynchronization(1677)) - commitBlockSynchronization(blk_1975120595995065171_1002) successful
[junit] 2009-08-21 12:44:39,761 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$1$8f59fdd7(51)) - FI: receiverOp WRITE_BLOCK, datanode=127.0.0.1:46377
[junit] 2009-08-21 12:44:39,762 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$3$3251489(72)) - FI: receiverOpWriteBlock
[junit] 2009-08-21 12:44:39,762 INFO datanode.DataNode (DataXceiver.java:opWriteBlock(222)) - Receiving block blk_1975120595995065171_1002 src: /127.0.0.1:36646 dest: /127.0.0.1:46377
[junit] 2009-08-21 12:44:39,762 INFO datanode.DataNode (FSDataset.java:writeToBlock(1085)) - Reopen already-open Block for append blk_1975120595995065171_1002
[junit] 2009-08-21 12:44:39,763 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$1$8f59fdd7(51)) - FI: receiverOp WRITE_BLOCK, datanode=127.0.0.1:40199
[junit] 2009-08-21 12:44:39,763 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$3$3251489(72)) - FI: receiverOpWriteBlock
[junit] 2009-08-21 12:44:39,763 INFO datanode.DataNode (DataXceiver.java:opWriteBlock(222)) - Receiving block blk_1975120595995065171_1002 src: /127.0.0.1:43027 dest: /127.0.0.1:40199
[junit] 2009-08-21 12:44:39,763 INFO datanode.DataNode (FSDataset.java:writeToBlock(1085)) - Reopen already-open Block for append blk_1975120595995065171_1002
[junit] 2009-08-21 12:44:39,764 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$2$d4f6605f(61)) - FI: statusRead SUCCESS, datanode=127.0.0.1:46377
[junit] 2009-08-21 12:44:39,764 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
[junit] 2009-08-21 12:44:39,765 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
[junit] 2009-08-21 12:44:39,765 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
[junit] 2009-08-21 12:44:39,765 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
[junit] 2009-08-21 12:44:39,765 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
[junit] 2009-08-21 12:44:39,766 INFO DataNode.clienttrace (BlockReceiver.java:lastDataNodeRun(822)) - src: /127.0.0.1:43027, dest: /127.0.0.1:40199, bytes: 1, op: HDFS_WRITE, cliID: DFSClient_-113320577, offset: 0, srvID: DS-357635502-67.195.138.9-40199-1250858678225, blockid: blk_1975120595995065171_1002, duration: 1945491
[junit] 2009-08-21 12:44:39,766 INFO datanode.DataNode (BlockReceiver.java:lastDataNodeRun(853)) - PacketResponder 0 for block blk_1975120595995065171_1002 terminating
[junit] 2009-08-21 12:44:39,767 INFO hdfs.StateChange (BlockManager.java:addStoredBlock(950)) - BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:40199 is added to blk_1975120595995065171_1002 size 1
[junit] 2009-08-21 12:44:39,767 INFO DataNode.clienttrace (BlockReceiver.java:run(955)) - src: /127.0.0.1:36646, dest: /127.0.0.1:46377, bytes: 1, op: HDFS_WRITE, cliID: DFSClient_-113320577, offset: 0, srvID: DS-1055442649-67.195.138.9-46377-1250858679434, blockid: blk_1975120595995065171_1002, duration: 2597834
[junit] 2009-08-21 12:44:39,767 INFO hdfs.StateChange (BlockManager.java:addStoredBlock(950)) - BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:46377 is added to blk_1975120595995065171_1002 size 1
[junit] 2009-08-21 12:44:39,768 INFO datanode.DataNode (BlockReceiver.java:run(1025)) - PacketResponder 1 for block blk_1975120595995065171_1002 terminating
[junit] 2009-08-21 12:44:39,769 INFO hdfs.StateChange (FSNamesystem.java:completeFileInternal(1269)) - DIR* NameSystem.completeFile: file /pipeline_Fi_16/foo is closed by DFSClient_-113320577
[junit] 2009-08-21 12:44:39,782 INFO FSNamesystem.audit (FSNamesystem.java:logAuditEvent(114)) - ugi=hudson,hudson ip=/127.0.0.1 cmd=open src=/pipeline_Fi_16/foo dst=null perm=null
[junit] 2009-08-21 12:44:39,783 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$1$8f59fdd7(51)) - FI: receiverOp READ_BLOCK, datanode=127.0.0.1:40199
[junit] Shutting down the Mini HDFS Cluster
[junit] Shutting down DataNode 2
[junit] 2009-08-21 12:44:39,784 INFO DataNode.clienttrace (BlockSender.java:sendBlock(417)) - src: /127.0.0.1:40199, dest: /127.0.0.1:43028, bytes: 5, op: HDFS_READ, cliID: DFSClient_-113320577, offset: 0, srvID: DS-357635502-67.195.138.9-40199-1250858678225, blockid: blk_1975120595995065171_1002, duration: 247202
[junit] 2009-08-21 12:44:39,785 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$2$d4f6605f(61)) - FI: statusRead CHECKSUM_OK, datanode=127.0.0.1:40199
[junit] 2009-08-21 12:44:39,886 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 47190
[junit] 2009-08-21 12:44:39,886 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 47190: exiting
[junit] 2009-08-21 12:44:39,886 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 47190
[junit] 2009-08-21 12:44:39,886 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
[junit] 2009-08-21 12:44:39,887 WARN datanode.DataNode (DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:46377, storageID=DS-1055442649-67.195.138.9-46377-1250858679434, infoPort=54942, ipcPort=47190):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-08-21 12:44:39,886 INFO datanode.DataNode (DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads is 1
[junit] 2009-08-21 12:44:39,887 INFO datanode.DataBlockScanner (DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
[junit] 2009-08-21 12:44:39,888 INFO datanode.DataNode (DataNode.java:run(1305)) - DatanodeRegistration(127.0.0.1:46377, storageID=DS-1055442649-67.195.138.9-46377-1250858679434, infoPort=54942, ipcPort=47190):Finishing DataNode in: FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build-fi/test/data/dfs/data/data5/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build-fi/test/data/dfs/data/data6/current'}
[junit] 2009-08-21 12:44:39,888 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 47190
[junit] 2009-08-21 12:44:39,888 INFO datanode.DataNode (DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads is 0
[junit] Shutting down DataNode 1
[junit] 2009-08-21 12:44:40,012 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 36021
[junit] 2009-08-21 12:44:40,013 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 36021
[junit] 2009-08-21 12:44:40,013 INFO datanode.DataNode (DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads is 1
[junit] 2009-08-21 12:44:40,013 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 36021: exiting
[junit] 2009-08-21 12:44:40,013 WARN datanode.DataNode (DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:51908, storageID=DS-821477171-67.195.138.9-51908-1250858678832, infoPort=55747, ipcPort=36021):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-08-21 12:44:40,013 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
[junit] 2009-08-21 12:44:40,015 INFO datanode.DataNode (DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads is 0
[junit] 2009-08-21 12:44:40,016 INFO datanode.DataBlockScanner (DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
[junit] 2009-08-21 12:44:40,016 INFO datanode.DataNode (DataNode.java:run(1305)) - DatanodeRegistration(127.0.0.1:51908, storageID=DS-821477171-67.195.138.9-51908-1250858678832, infoPort=55747, ipcPort=36021):Finishing DataNode in: FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build-fi/test/data/dfs/data/data3/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build-fi/test/data/dfs/data/data4/current'}
[junit] 2009-08-21 12:44:40,016 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 36021
[junit] 2009-08-21 12:44:40,016 INFO datanode.DataNode (DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads is 0
[junit] Shutting down DataNode 0
[junit] 2009-08-21 12:44:40,118 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 60219
[junit] 2009-08-21 12:44:40,119 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 60219
[junit] 2009-08-21 12:44:40,119 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
[junit] 2009-08-21 12:44:40,119 INFO datanode.DataNode (DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads is 1
[junit] 2009-08-21 12:44:40,119 WARN datanode.DataNode (DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:40199, storageID=DS-357635502-67.195.138.9-40199-1250858678225, infoPort=33129, ipcPort=60219):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-08-21 12:44:40,120 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 60219: exiting
[junit] 2009-08-21 12:44:40,122 INFO datanode.DataNode (DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads is 0
[junit] 2009-08-21 12:44:40,123 INFO datanode.DataBlockScanner (DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
[junit] 2009-08-21 12:44:40,123 INFO datanode.DataNode (DataNode.java:run(1305)) - DatanodeRegistration(127.0.0.1:40199, storageID=DS-357635502-67.195.138.9-40199-1250858678225, infoPort=33129, ipcPort=60219):Finishing DataNode in: FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build-fi/test/data/dfs/data/data1/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build-fi/test/data/dfs/data/data2/current'}
[junit] 2009-08-21 12:44:40,124 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 60219
[junit] 2009-08-21 12:44:40,124 INFO datanode.DataNode (DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads is 0
[junit] 2009-08-21 12:44:40,264 WARN namenode.DecommissionManager (DecommissionManager.java:run(67)) - Monitor interrupted: java.lang.InterruptedException: sleep interrupted
[junit] 2009-08-21 12:44:40,264 INFO namenode.FSNamesystem (FSEditLog.java:printStatistics(884)) - Number of transactions: 5 Total time for transactions(ms): 0Number of transactions batched in Syncs: 0 Number of syncs: 2 SyncTimes(ms): 50 35
[junit] 2009-08-21 12:44:40,264 WARN namenode.FSNamesystem (FSNamesystem.java:run(2077)) - ReplicationMonitor thread received InterruptedException.java.lang.InterruptedException: sleep interrupted
[junit] 2009-08-21 12:44:40,271 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 42222
[junit] 2009-08-21 12:44:40,272 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 42222: exiting
[junit] 2009-08-21 12:44:40,272 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 42222: exiting
[junit] 2009-08-21 12:44:40,272 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 42222: exiting
[junit] 2009-08-21 12:44:40,272 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 4 on 42222: exiting
[junit] 2009-08-21 12:44:40,272 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 3 on 42222: exiting
[junit] 2009-08-21 12:44:40,272 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 6 on 42222: exiting
[junit] 2009-08-21 12:44:40,272 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 42222
[junit] 2009-08-21 12:44:40,272 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 5 on 42222: exiting
[junit] 2009-08-21 12:44:40,273 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 9 on 42222: exiting
[junit] 2009-08-21 12:44:40,273 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 7 on 42222: exiting
[junit] 2009-08-21 12:44:40,273 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 8 on 42222: exiting
[junit] 2009-08-21 12:44:40,274 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
[junit] Tests run: 7, Failures: 0, Errors: 0, Time elapsed: 74.272 sec

checkfailure:

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

Total time: 70 minutes 37 seconds
Publishing Javadoc
Recording test results
Recording fingerprints
Publishing Clover coverage report...

Search Discussions

  • Apache Hudson Server at Aug 22, 2009 at 5:27 pm
    See http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/58/changes

    Changes:

    [cdouglas] HDFS-538. Per the contract elucidated in HADOOP-6201, throw
    FileNotFoundException from FileSystem::listStatus rather than returning
    null. Contributed by Jakob Homan.

    ------------------------------------------
    [...truncated 222912 lines...]
    [junit] 2009-08-22 17:25:53,625 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-08-22 17:25:53,626 INFO http.HttpServer (HttpServer.java:start(430)) - listener.getLocalPort() returned 39115 webServer.getConnectors()[0].getLocalPort() returned 39115
    [junit] 2009-08-22 17:25:53,626 INFO http.HttpServer (HttpServer.java:start(463)) - Jetty bound to port 39115
    [junit] 2009-08-22 17:25:53,626 INFO mortbay.log (?:invoke(?)) - jetty-6.1.14
    [junit] 2009-08-22 17:25:53,686 INFO mortbay.log (?:invoke(?)) - Started SelectChannelConnector@localhost:39115
    [junit] 2009-08-22 17:25:53,686 INFO jvm.JvmMetrics (JvmMetrics.java:init(66)) - Cannot initialize JVM Metrics with processName=DataNode, sessionId=null - already initialized
    [junit] 2009-08-22 17:25:53,687 INFO metrics.RpcMetrics (RpcMetrics.java:<init>(58)) - Initializing RPC Metrics with hostName=DataNode, port=44254
    [junit] 2009-08-22 17:25:53,688 INFO ipc.Server (Server.java:run(474)) - IPC Server Responder: starting
    [junit] 2009-08-22 17:25:53,688 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 0 on 44254: starting
    [junit] 2009-08-22 17:25:53,688 INFO datanode.DataNode (DataNode.java:startDataNode(404)) - dnRegistration = DatanodeRegistration(vesta.apache.org:50408, storageID=, infoPort=39115, ipcPort=44254)
    [junit] 2009-08-22 17:25:53,688 INFO ipc.Server (Server.java:run(313)) - IPC Server listener on 44254: starting
    [junit] 2009-08-22 17:25:53,690 INFO hdfs.StateChange (FSNamesystem.java:registerDatanode(1774)) - BLOCK* NameSystem.registerDatanode: node registration from 127.0.0.1:50408 storage DS-881213117-67.195.138.9-50408-1250961953689
    [junit] 2009-08-22 17:25:53,690 INFO net.NetworkTopology (NetworkTopology.java:add(327)) - Adding a new node: /default-rack/127.0.0.1:50408
    [junit] 2009-08-22 17:25:53,746 INFO datanode.DataNode (DataNode.java:register(571)) - New storage id DS-881213117-67.195.138.9-50408-1250961953689 is assigned to data-node 127.0.0.1:50408
    [junit] 2009-08-22 17:25:53,746 INFO datanode.DataNode (DataNode.java:run(1285)) - DatanodeRegistration(127.0.0.1:50408, storageID=DS-881213117-67.195.138.9-50408-1250961953689, infoPort=39115, ipcPort=44254)In DataNode.run, data = FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build-fi/test/data/dfs/data/data1/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build-fi/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-fi/test/data/dfs/data/data3,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build-fi/test/data/dfs/data/data4
    [junit] 2009-08-22 17:25:53,747 INFO datanode.DataNode (DataNode.java:offerService(763)) - using BLOCKREPORT_INTERVAL of 21600000msec Initial delay: 0msec
    [junit] 2009-08-22 17:25:53,755 INFO common.Storage (DataStorage.java:recoverTransitionRead(122)) - Storage directory http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build-fi/test/data/dfs/data/data3 is not formatted.
    [junit] 2009-08-22 17:25:53,755 INFO common.Storage (DataStorage.java:recoverTransitionRead(123)) - Formatting ...
    [junit] 2009-08-22 17:25:53,785 INFO datanode.DataNode (DataNode.java:blockReport(998)) - BlockReport of 0 blocks got processed in 1 msecs
    [junit] 2009-08-22 17:25:53,785 INFO datanode.DataNode (DataNode.java:offerService(806)) - Starting Periodic block scanner.
    [junit] 2009-08-22 17:25:53,942 INFO common.Storage (DataStorage.java:recoverTransitionRead(122)) - Storage directory http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build-fi/test/data/dfs/data/data4 is not formatted.
    [junit] 2009-08-22 17:25:53,942 INFO common.Storage (DataStorage.java:recoverTransitionRead(123)) - Formatting ...
    [junit] 2009-08-22 17:25:54,233 INFO datanode.DataNode (FSDataset.java:registerMBean(1547)) - Registered FSDatasetStatusMBean
    [junit] 2009-08-22 17:25:54,234 INFO datanode.DataNode (DataNode.java:startDataNode(326)) - Opened info server at 34356
    [junit] 2009-08-22 17:25:54,234 INFO datanode.DataNode (DataXceiverServer.java:<init>(74)) - Balancing bandwith is 1048576 bytes/s
    [junit] 2009-08-22 17:25:54,235 INFO datanode.DirectoryScanner (DirectoryScanner.java:<init>(133)) - scan starts at 1250982862235 with interval 21600000
    [junit] 2009-08-22 17:25:54,236 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-08-22 17:25:54,236 INFO http.HttpServer (HttpServer.java:start(430)) - listener.getLocalPort() returned 50526 webServer.getConnectors()[0].getLocalPort() returned 50526
    [junit] 2009-08-22 17:25:54,237 INFO http.HttpServer (HttpServer.java:start(463)) - Jetty bound to port 50526
    [junit] 2009-08-22 17:25:54,237 INFO mortbay.log (?:invoke(?)) - jetty-6.1.14
    [junit] 2009-08-22 17:25:54,297 INFO mortbay.log (?:invoke(?)) - Started SelectChannelConnector@localhost:50526
    [junit] 2009-08-22 17:25:54,298 INFO jvm.JvmMetrics (JvmMetrics.java:init(66)) - Cannot initialize JVM Metrics with processName=DataNode, sessionId=null - already initialized
    [junit] 2009-08-22 17:25:54,299 INFO metrics.RpcMetrics (RpcMetrics.java:<init>(58)) - Initializing RPC Metrics with hostName=DataNode, port=60353
    [junit] 2009-08-22 17:25:54,300 INFO ipc.Server (Server.java:run(474)) - IPC Server Responder: starting
    [junit] 2009-08-22 17:25:54,300 INFO datanode.DataNode (DataNode.java:startDataNode(404)) - dnRegistration = DatanodeRegistration(vesta.apache.org:34356, storageID=, infoPort=50526, ipcPort=60353)
    [junit] 2009-08-22 17:25:54,300 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 0 on 60353: starting
    [junit] 2009-08-22 17:25:54,300 INFO ipc.Server (Server.java:run(313)) - IPC Server listener on 60353: starting
    [junit] 2009-08-22 17:25:54,302 INFO hdfs.StateChange (FSNamesystem.java:registerDatanode(1774)) - BLOCK* NameSystem.registerDatanode: node registration from 127.0.0.1:34356 storage DS-259311802-67.195.138.9-34356-1250961954301
    [junit] 2009-08-22 17:25:54,302 INFO net.NetworkTopology (NetworkTopology.java:add(327)) - Adding a new node: /default-rack/127.0.0.1:34356
    [junit] 2009-08-22 17:25:54,343 INFO datanode.DataNode (DataNode.java:register(571)) - New storage id DS-259311802-67.195.138.9-34356-1250961954301 is assigned to data-node 127.0.0.1:34356
    [junit] 2009-08-22 17:25:54,344 INFO datanode.DataNode (DataNode.java:run(1285)) - DatanodeRegistration(127.0.0.1:34356, storageID=DS-259311802-67.195.138.9-34356-1250961954301, infoPort=50526, ipcPort=60353)In DataNode.run, data = FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build-fi/test/data/dfs/data/data3/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build-fi/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-fi/test/data/dfs/data/data5,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build-fi/test/data/dfs/data/data6
    [junit] 2009-08-22 17:25:54,344 INFO datanode.DataNode (DataNode.java:offerService(763)) - using BLOCKREPORT_INTERVAL of 21600000msec Initial delay: 0msec
    [junit] 2009-08-22 17:25:54,351 INFO common.Storage (DataStorage.java:recoverTransitionRead(122)) - Storage directory http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build-fi/test/data/dfs/data/data5 is not formatted.
    [junit] 2009-08-22 17:25:54,352 INFO common.Storage (DataStorage.java:recoverTransitionRead(123)) - Formatting ...
    [junit] 2009-08-22 17:25:54,382 INFO datanode.DataNode (DataNode.java:blockReport(998)) - BlockReport of 0 blocks got processed in 0 msecs
    [junit] 2009-08-22 17:25:54,383 INFO datanode.DataNode (DataNode.java:offerService(806)) - Starting Periodic block scanner.
    [junit] 2009-08-22 17:25:54,549 INFO common.Storage (DataStorage.java:recoverTransitionRead(122)) - Storage directory http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build-fi/test/data/dfs/data/data6 is not formatted.
    [junit] 2009-08-22 17:25:54,549 INFO common.Storage (DataStorage.java:recoverTransitionRead(123)) - Formatting ...
    [junit] 2009-08-22 17:25:54,819 INFO datanode.DataNode (FSDataset.java:registerMBean(1547)) - Registered FSDatasetStatusMBean
    [junit] 2009-08-22 17:25:54,820 INFO datanode.DataNode (DataNode.java:startDataNode(326)) - Opened info server at 38414
    [junit] 2009-08-22 17:25:54,820 INFO datanode.DataNode (DataXceiverServer.java:<init>(74)) - Balancing bandwith is 1048576 bytes/s
    [junit] 2009-08-22 17:25:54,820 INFO datanode.DirectoryScanner (DirectoryScanner.java:<init>(133)) - scan starts at 1250963141820 with interval 21600000
    [junit] 2009-08-22 17:25:54,822 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-08-22 17:25:54,822 INFO http.HttpServer (HttpServer.java:start(430)) - listener.getLocalPort() returned 41030 webServer.getConnectors()[0].getLocalPort() returned 41030
    [junit] 2009-08-22 17:25:54,822 INFO http.HttpServer (HttpServer.java:start(463)) - Jetty bound to port 41030
    [junit] 2009-08-22 17:25:54,822 INFO mortbay.log (?:invoke(?)) - jetty-6.1.14
    [junit] 2009-08-22 17:25:54,882 INFO mortbay.log (?:invoke(?)) - Started SelectChannelConnector@localhost:41030
    [junit] 2009-08-22 17:25:54,883 INFO jvm.JvmMetrics (JvmMetrics.java:init(66)) - Cannot initialize JVM Metrics with processName=DataNode, sessionId=null - already initialized
    [junit] 2009-08-22 17:25:54,884 INFO metrics.RpcMetrics (RpcMetrics.java:<init>(58)) - Initializing RPC Metrics with hostName=DataNode, port=53124
    [junit] 2009-08-22 17:25:54,957 INFO ipc.Server (Server.java:run(313)) - IPC Server listener on 53124: starting
    [junit] 2009-08-22 17:25:54,957 INFO datanode.DataNode (DataNode.java:startDataNode(404)) - dnRegistration = DatanodeRegistration(vesta.apache.org:38414, storageID=, infoPort=41030, ipcPort=53124)
    [junit] 2009-08-22 17:25:54,957 INFO ipc.Server (Server.java:run(474)) - IPC Server Responder: starting
    [junit] 2009-08-22 17:25:54,958 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 0 on 53124: starting
    [junit] 2009-08-22 17:25:54,959 INFO hdfs.StateChange (FSNamesystem.java:registerDatanode(1774)) - BLOCK* NameSystem.registerDatanode: node registration from 127.0.0.1:38414 storage DS-2029722745-67.195.138.9-38414-1250961954958
    [junit] 2009-08-22 17:25:54,959 INFO net.NetworkTopology (NetworkTopology.java:add(327)) - Adding a new node: /default-rack/127.0.0.1:38414
    [junit] 2009-08-22 17:25:55,003 INFO datanode.DataNode (DataNode.java:register(571)) - New storage id DS-2029722745-67.195.138.9-38414-1250961954958 is assigned to data-node 127.0.0.1:38414
    [junit] 2009-08-22 17:25:55,003 INFO datanode.DataNode (DataNode.java:run(1285)) - DatanodeRegistration(127.0.0.1:38414, storageID=DS-2029722745-67.195.138.9-38414-1250961954958, infoPort=41030, ipcPort=53124)In DataNode.run, data = FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build-fi/test/data/dfs/data/data5/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build-fi/test/data/dfs/data/data6/current'}
    [junit] 2009-08-22 17:25:55,004 INFO datanode.DataNode (DataNode.java:offerService(763)) - using BLOCKREPORT_INTERVAL of 21600000msec Initial delay: 0msec
    [junit] 2009-08-22 17:25:55,070 INFO datanode.DataNode (DataNode.java:blockReport(998)) - BlockReport of 0 blocks got processed in 0 msecs
    [junit] 2009-08-22 17:25:55,071 INFO datanode.DataNode (DataNode.java:offerService(806)) - Starting Periodic block scanner.
    [junit] 2009-08-22 17:25:55,178 INFO FSNamesystem.audit (FSNamesystem.java:logAuditEvent(114)) - ugi=hudson,hudson ip=/127.0.0.1 cmd=create src=/pipeline_Fi_16/foo dst=null perm=hudson:supergroup:rw-r--r--
    [junit] 2009-08-22 17:25:55,181 INFO hdfs.StateChange (FSNamesystem.java:allocateBlock(1303)) - BLOCK* NameSystem.allocateBlock: /pipeline_Fi_16/foo. blk_-678847007047035635_1001
    [junit] 2009-08-22 17:25:55,211 INFO protocol.ClientProtocolAspects (ClientProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_protocol_ClientProtocolAspects$1$7076326d(35)) - FI: addBlock Pipeline[127.0.0.1:50408, 127.0.0.1:38414, 127.0.0.1:34356]
    [junit] 2009-08-22 17:25:55,212 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$1$8f59fdd7(51)) - FI: receiverOp WRITE_BLOCK, datanode=127.0.0.1:50408
    [junit] 2009-08-22 17:25:55,212 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$3$3251489(72)) - FI: receiverOpWriteBlock
    [junit] 2009-08-22 17:25:55,213 INFO datanode.DataNode (DataXceiver.java:opWriteBlock(222)) - Receiving block blk_-678847007047035635_1001 src: /127.0.0.1:56770 dest: /127.0.0.1:50408
    [junit] 2009-08-22 17:25:55,214 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$1$8f59fdd7(51)) - FI: receiverOp WRITE_BLOCK, datanode=127.0.0.1:38414
    [junit] 2009-08-22 17:25:55,214 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$3$3251489(72)) - FI: receiverOpWriteBlock
    [junit] 2009-08-22 17:25:55,214 INFO datanode.DataNode (DataXceiver.java:opWriteBlock(222)) - Receiving block blk_-678847007047035635_1001 src: /127.0.0.1:41695 dest: /127.0.0.1:38414
    [junit] 2009-08-22 17:25:55,215 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$1$8f59fdd7(51)) - FI: receiverOp WRITE_BLOCK, datanode=127.0.0.1:34356
    [junit] 2009-08-22 17:25:55,216 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$3$3251489(72)) - FI: receiverOpWriteBlock
    [junit] 2009-08-22 17:25:55,216 INFO datanode.DataNode (DataXceiver.java:opWriteBlock(222)) - Receiving block blk_-678847007047035635_1001 src: /127.0.0.1:43698 dest: /127.0.0.1:34356
    [junit] 2009-08-22 17:25:55,216 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$2$d4f6605f(61)) - FI: statusRead SUCCESS, datanode=127.0.0.1:38414
    [junit] 2009-08-22 17:25:55,217 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$2$d4f6605f(61)) - FI: statusRead SUCCESS, datanode=127.0.0.1:50408
    [junit] 2009-08-22 17:25:55,218 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
    [junit] 2009-08-22 17:25:55,218 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
    [junit] 2009-08-22 17:25:55,218 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
    [junit] 2009-08-22 17:25:55,218 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
    [junit] 2009-08-22 17:25:55,219 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
    [junit] 2009-08-22 17:25:55,218 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
    [junit] 2009-08-22 17:25:55,219 INFO fi.FiTestUtil (DataTransferTestUtil.java:run(151)) - FI: pipeline_Fi_16, index=2, datanode=127.0.0.1:34356
    [junit] 2009-08-22 17:25:55,219 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
    [junit] 2009-08-22 17:25:55,219 WARN datanode.DataNode (DataNode.java:checkDiskError(702)) - checkDiskError: exception:
    [junit] org.apache.hadoop.util.DiskChecker$DiskOutOfSpaceException: FI: pipeline_Fi_16, index=2, datanode=127.0.0.1:34356
    [junit] at org.apache.hadoop.fi.DataTransferTestUtil$DoosAction.run(DataTransferTestUtil.java:152)
    [junit] at org.apache.hadoop.fi.DataTransferTestUtil$DoosAction.run(DataTransferTestUtil.java:1)
    [junit] at org.apache.hadoop.fi.FiTestUtil$ActionContainer.run(FiTestUtil.java:66)
    [junit] at org.apache.hadoop.hdfs.server.datanode.BlockReceiverAspects.ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(BlockReceiverAspects.aj:50)
    [junit] at org.apache.hadoop.hdfs.server.datanode.BlockReceiver.receivePacket(BlockReceiver.java:459)
    [junit] at org.apache.hadoop.hdfs.server.datanode.BlockReceiver.receiveBlock(BlockReceiver.java:535)
    [junit] at org.apache.hadoop.hdfs.server.datanode.DataXceiver.opWriteBlock(DataXceiver.java:339)
    [junit] at org.apache.hadoop.hdfs.protocol.DataTransferProtocol$Receiver.opWriteBlock(DataTransferProtocol.java:324)
    [junit] at org.apache.hadoop.hdfs.protocol.DataTransferProtocol$Receiver.processOp(DataTransferProtocol.java:269)
    [junit] at org.apache.hadoop.hdfs.server.datanode.DataXceiver.run(DataXceiver.java:110)
    [junit] at java.lang.Thread.run(Thread.java:619)
    [junit] 2009-08-22 17:25:55,220 INFO mortbay.log (?:invoke(?)) - Completed FSVolumeSet.checkDirs. Removed=0volumes. List of current volumes: http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build-fi/test/data/dfs/data/data3/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build-fi/test/data/dfs/data/data4/current
    [junit] 2009-08-22 17:25:55,221 INFO datanode.DataNode (BlockReceiver.java:receiveBlock(569)) - Exception in receiveBlock for block blk_-678847007047035635_1001 org.apache.hadoop.util.DiskChecker$DiskOutOfSpaceException: FI: pipeline_Fi_16, index=2, datanode=127.0.0.1:34356
    [junit] 2009-08-22 17:25:55,221 INFO datanode.DataNode (BlockReceiver.java:lastDataNodeRun(782)) - PacketResponder 0 for block blk_-678847007047035635_1001 Interrupted.
    [junit] 2009-08-22 17:25:55,221 INFO datanode.DataNode (BlockReceiver.java:lastDataNodeRun(853)) - PacketResponder 0 for block blk_-678847007047035635_1001 terminating
    [junit] 2009-08-22 17:25:55,221 INFO datanode.DataNode (DataXceiver.java:opWriteBlock(358)) - writeBlock blk_-678847007047035635_1001 received exception org.apache.hadoop.util.DiskChecker$DiskOutOfSpaceException: FI: pipeline_Fi_16, index=2, datanode=127.0.0.1:34356
    [junit] 2009-08-22 17:25:55,221 ERROR datanode.DataNode (DataXceiver.java:run(112)) - DatanodeRegistration(127.0.0.1:34356, storageID=DS-259311802-67.195.138.9-34356-1250961954301, infoPort=50526, ipcPort=60353):DataXceiver
    [junit] org.apache.hadoop.util.DiskChecker$DiskOutOfSpaceException: FI: pipeline_Fi_16, index=2, datanode=127.0.0.1:34356
    [junit] at org.apache.hadoop.fi.DataTransferTestUtil$DoosAction.run(DataTransferTestUtil.java:152)
    [junit] at org.apache.hadoop.fi.DataTransferTestUtil$DoosAction.run(DataTransferTestUtil.java:1)
    [junit] at org.apache.hadoop.fi.FiTestUtil$ActionContainer.run(FiTestUtil.java:66)
    [junit] at org.apache.hadoop.hdfs.server.datanode.BlockReceiverAspects.ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(BlockReceiverAspects.aj:50)
    [junit] at org.apache.hadoop.hdfs.server.datanode.BlockReceiver.receivePacket(BlockReceiver.java:459)
    [junit] at org.apache.hadoop.hdfs.server.datanode.BlockReceiver.receiveBlock(BlockReceiver.java:535)
    [junit] at org.apache.hadoop.hdfs.server.datanode.DataXceiver.opWriteBlock(DataXceiver.java:339)
    [junit] at org.apache.hadoop.hdfs.protocol.DataTransferProtocol$Receiver.opWriteBlock(DataTransferProtocol.java:324)
    [junit] at org.apache.hadoop.hdfs.protocol.DataTransferProtocol$Receiver.processOp(DataTransferProtocol.java:269)
    [junit] at org.apache.hadoop.hdfs.server.datanode.DataXceiver.run(DataXceiver.java:110)
    [junit] at java.lang.Thread.run(Thread.java:619)
    [junit] 2009-08-22 17:25:55,221 INFO datanode.DataNode (BlockReceiver.java:run(917)) - PacketResponder blk_-678847007047035635_1001 1 Exception java.io.EOFException
    [junit] at java.io.DataInputStream.readFully(DataInputStream.java:180)
    [junit] at java.io.DataInputStream.readLong(DataInputStream.java:399)
    [junit] at org.apache.hadoop.hdfs.server.datanode.BlockReceiver$PacketResponder.run(BlockReceiver.java:879)
    [junit] at java.lang.Thread.run(Thread.java:619)
    [junit]
    [junit] 2009-08-22 17:25:55,223 INFO datanode.DataNode (BlockReceiver.java:run(1025)) - PacketResponder 1 for block blk_-678847007047035635_1001 terminating
    [junit] 2009-08-22 17:25:55,265 INFO datanode.DataNode (BlockReceiver.java:run(1025)) - PacketResponder 2 for block blk_-678847007047035635_1001 terminating
    [junit] 2009-08-22 17:25:55,265 WARN hdfs.DFSClient (DFSClient.java:run(2601)) - DFSOutputStream ResponseProcessor exception for block blk_-678847007047035635_1001java.io.IOException: Bad response ERROR for block blk_-678847007047035635_1001 from datanode 127.0.0.1:34356
    [junit] at org.apache.hadoop.hdfs.DFSClient$DFSOutputStream$DataStreamer$ResponseProcessor.run(DFSClient.java:2581)
    [junit]
    [junit] 2009-08-22 17:25:55,265 WARN hdfs.DFSClient (DFSClient.java:processDatanodeError(2630)) - Error Recovery for block blk_-678847007047035635_1001 bad datanode[2] 127.0.0.1:34356
    [junit] 2009-08-22 17:25:55,265 WARN hdfs.DFSClient (DFSClient.java:processDatanodeError(2674)) - Error Recovery for block blk_-678847007047035635_1001 in pipeline 127.0.0.1:50408, 127.0.0.1:38414, 127.0.0.1:34356: bad datanode 127.0.0.1:34356
    [junit] 2009-08-22 17:25:55,268 INFO datanode.DataNode (DataNode.java:logRecoverBlock(1727)) - Client calls recoverBlock(block=blk_-678847007047035635_1001, targets=[127.0.0.1:50408, 127.0.0.1:38414])
    [junit] 2009-08-22 17:25:55,272 INFO datanode.DataNode (DataNode.java:updateBlock(1537)) - oldblock=blk_-678847007047035635_1001(length=1), newblock=blk_-678847007047035635_1002(length=1), datanode=127.0.0.1:50408
    [junit] 2009-08-22 17:25:55,273 INFO datanode.DataNode (DataNode.java:updateBlock(1537)) - oldblock=blk_-678847007047035635_1001(length=1), newblock=blk_-678847007047035635_1002(length=1), datanode=127.0.0.1:38414
    [junit] 2009-08-22 17:25:55,274 INFO namenode.FSNamesystem (FSNamesystem.java:commitBlockSynchronization(1613)) - commitBlockSynchronization(lastblock=blk_-678847007047035635_1001, newgenerationstamp=1002, newlength=1, newtargets=[127.0.0.1:50408, 127.0.0.1:38414], closeFile=false, deleteBlock=false)
    [junit] 2009-08-22 17:25:55,274 INFO namenode.FSNamesystem (FSNamesystem.java:commitBlockSynchronization(1677)) - commitBlockSynchronization(blk_-678847007047035635_1002) successful
    [junit] 2009-08-22 17:25:55,275 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$1$8f59fdd7(51)) - FI: receiverOp WRITE_BLOCK, datanode=127.0.0.1:50408
    [junit] 2009-08-22 17:25:55,275 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$3$3251489(72)) - FI: receiverOpWriteBlock
    [junit] 2009-08-22 17:25:55,276 INFO datanode.DataNode (DataXceiver.java:opWriteBlock(222)) - Receiving block blk_-678847007047035635_1002 src: /127.0.0.1:56775 dest: /127.0.0.1:50408
    [junit] 2009-08-22 17:25:55,276 INFO datanode.DataNode (FSDataset.java:writeToBlock(1085)) - Reopen already-open Block for append blk_-678847007047035635_1002
    [junit] 2009-08-22 17:25:55,276 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$1$8f59fdd7(51)) - FI: receiverOp WRITE_BLOCK, datanode=127.0.0.1:38414
    [junit] 2009-08-22 17:25:55,276 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$3$3251489(72)) - FI: receiverOpWriteBlock
    [junit] 2009-08-22 17:25:55,277 INFO datanode.DataNode (DataXceiver.java:opWriteBlock(222)) - Receiving block blk_-678847007047035635_1002 src: /127.0.0.1:41700 dest: /127.0.0.1:38414
    [junit] 2009-08-22 17:25:55,277 INFO datanode.DataNode (FSDataset.java:writeToBlock(1085)) - Reopen already-open Block for append blk_-678847007047035635_1002
    [junit] 2009-08-22 17:25:55,277 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$2$d4f6605f(61)) - FI: statusRead SUCCESS, datanode=127.0.0.1:50408
    [junit] 2009-08-22 17:25:55,279 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
    [junit] 2009-08-22 17:25:55,279 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
    [junit] 2009-08-22 17:25:55,279 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
    [junit] 2009-08-22 17:25:55,279 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
    [junit] 2009-08-22 17:25:55,279 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
    [junit] 2009-08-22 17:25:55,280 INFO DataNode.clienttrace (BlockReceiver.java:lastDataNodeRun(822)) - src: /127.0.0.1:41700, dest: /127.0.0.1:38414, bytes: 1, op: HDFS_WRITE, cliID: DFSClient_-2085369977, offset: 0, srvID: DS-2029722745-67.195.138.9-38414-1250961954958, blockid: blk_-678847007047035635_1002, duration: 2788947
    [junit] 2009-08-22 17:25:55,281 INFO hdfs.StateChange (BlockManager.java:addStoredBlock(950)) - BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:38414 is added to blk_-678847007047035635_1002 size 1
    [junit] 2009-08-22 17:25:55,282 INFO DataNode.clienttrace (BlockReceiver.java:run(955)) - src: /127.0.0.1:56775, dest: /127.0.0.1:50408, bytes: 1, op: HDFS_WRITE, cliID: DFSClient_-2085369977, offset: 0, srvID: DS-881213117-67.195.138.9-50408-1250961953689, blockid: blk_-678847007047035635_1002, duration: 3449887
    [junit] 2009-08-22 17:25:55,281 INFO datanode.DataNode (BlockReceiver.java:lastDataNodeRun(853)) - PacketResponder 0 for block blk_-678847007047035635_1002 terminating
    [junit] 2009-08-22 17:25:55,283 INFO hdfs.StateChange (BlockManager.java:addStoredBlock(950)) - BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:50408 is added to blk_-678847007047035635_1002 size 1
    [junit] 2009-08-22 17:25:55,283 INFO datanode.DataNode (BlockReceiver.java:run(1025)) - PacketResponder 1 for block blk_-678847007047035635_1002 terminating
    [junit] 2009-08-22 17:25:55,285 INFO hdfs.StateChange (FSNamesystem.java:completeFileInternal(1269)) - DIR* NameSystem.completeFile: file /pipeline_Fi_16/foo is closed by DFSClient_-2085369977
    [junit] 2009-08-22 17:25:55,294 INFO FSNamesystem.audit (FSNamesystem.java:logAuditEvent(114)) - ugi=hudson,hudson ip=/127.0.0.1 cmd=open src=/pipeline_Fi_16/foo dst=null perm=null
    [junit] 2009-08-22 17:25:55,296 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$1$8f59fdd7(51)) - FI: receiverOp READ_BLOCK, datanode=127.0.0.1:38414
    [junit] Shutting down the Mini HDFS Cluster
    [junit] Shutting down DataNode 2
    [junit] 2009-08-22 17:25:55,297 INFO DataNode.clienttrace (BlockSender.java:sendBlock(417)) - src: /127.0.0.1:38414, dest: /127.0.0.1:41701, bytes: 5, op: HDFS_READ, cliID: DFSClient_-2085369977, offset: 0, srvID: DS-2029722745-67.195.138.9-38414-1250961954958, blockid: blk_-678847007047035635_1002, duration: 237979
    [junit] 2009-08-22 17:25:55,299 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$2$d4f6605f(61)) - FI: statusRead CHECKSUM_OK, datanode=127.0.0.1:38414
    [junit] 2009-08-22 17:25:55,399 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 53124
    [junit] 2009-08-22 17:25:55,400 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 53124: exiting
    [junit] 2009-08-22 17:25:55,400 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
    [junit] 2009-08-22 17:25:55,400 WARN datanode.DataNode (DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:38414, storageID=DS-2029722745-67.195.138.9-38414-1250961954958, infoPort=41030, ipcPort=53124):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-08-22 17:25:55,400 INFO datanode.DataNode (DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads is 1
    [junit] 2009-08-22 17:25:55,400 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 53124
    [junit] 2009-08-22 17:25:55,401 INFO datanode.DataBlockScanner (DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
    [junit] 2009-08-22 17:25:55,402 INFO datanode.DataNode (DataNode.java:run(1305)) - DatanodeRegistration(127.0.0.1:38414, storageID=DS-2029722745-67.195.138.9-38414-1250961954958, infoPort=41030, ipcPort=53124):Finishing DataNode in: FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build-fi/test/data/dfs/data/data5/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build-fi/test/data/dfs/data/data6/current'}
    [junit] 2009-08-22 17:25:55,402 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 53124
    [junit] 2009-08-22 17:25:55,402 INFO datanode.DataNode (DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads is 0
    [junit] Shutting down DataNode 1
    [junit] 2009-08-22 17:25:55,504 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 60353
    [junit] 2009-08-22 17:25:55,504 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 60353: exiting
    [junit] 2009-08-22 17:25:55,504 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 60353
    [junit] 2009-08-22 17:25:55,505 WARN datanode.DataNode (DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:34356, storageID=DS-259311802-67.195.138.9-34356-1250961954301, infoPort=50526, ipcPort=60353):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-08-22 17:25:55,505 INFO datanode.DataNode (DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads is 1
    [junit] 2009-08-22 17:25:55,505 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
    [junit] 2009-08-22 17:25:55,505 INFO datanode.DataBlockScanner (DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
    [junit] 2009-08-22 17:25:55,505 INFO datanode.DataNode (DataNode.java:run(1305)) - DatanodeRegistration(127.0.0.1:34356, storageID=DS-259311802-67.195.138.9-34356-1250961954301, infoPort=50526, ipcPort=60353):Finishing DataNode in: FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build-fi/test/data/dfs/data/data3/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build-fi/test/data/dfs/data/data4/current'}
    [junit] 2009-08-22 17:25:55,506 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 60353
    [junit] 2009-08-22 17:25:55,506 INFO datanode.DataNode (DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads is 0
    [junit] Shutting down DataNode 0
    [junit] 2009-08-22 17:25:55,608 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 44254
    [junit] 2009-08-22 17:25:55,608 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 44254: exiting
    [junit] 2009-08-22 17:25:55,609 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 44254
    [junit] 2009-08-22 17:25:55,609 INFO datanode.DataNode (DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads is 1
    [junit] 2009-08-22 17:25:55,609 WARN datanode.DataNode (DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:50408, storageID=DS-881213117-67.195.138.9-50408-1250961953689, infoPort=39115, ipcPort=44254):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-08-22 17:25:55,609 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
    [junit] 2009-08-22 17:25:55,611 INFO datanode.DataNode (DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads is 0
    [junit] 2009-08-22 17:25:55,611 INFO datanode.DataBlockScanner (DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
    [junit] 2009-08-22 17:25:55,612 INFO datanode.DataNode (DataNode.java:run(1305)) - DatanodeRegistration(127.0.0.1:50408, storageID=DS-881213117-67.195.138.9-50408-1250961953689, infoPort=39115, ipcPort=44254):Finishing DataNode in: FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build-fi/test/data/dfs/data/data1/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build-fi/test/data/dfs/data/data2/current'}
    [junit] 2009-08-22 17:25:55,612 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 44254
    [junit] 2009-08-22 17:25:55,612 INFO datanode.DataNode (DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads is 0
    [junit] 2009-08-22 17:25:55,736 WARN namenode.DecommissionManager (DecommissionManager.java:run(67)) - Monitor interrupted: java.lang.InterruptedException: sleep interrupted
    [junit] 2009-08-22 17:25:55,736 INFO namenode.FSNamesystem (FSEditLog.java:printStatistics(884)) - Number of transactions: 5 Total time for transactions(ms): 0Number of transactions batched in Syncs: 0 Number of syncs: 2 SyncTimes(ms): 36 34
    [junit] 2009-08-22 17:25:55,736 WARN namenode.FSNamesystem (FSNamesystem.java:run(2077)) - ReplicationMonitor thread received InterruptedException.java.lang.InterruptedException: sleep interrupted
    [junit] 2009-08-22 17:25:55,746 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 42930
    [junit] 2009-08-22 17:25:55,746 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 42930: exiting
    [junit] 2009-08-22 17:25:55,746 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 42930: exiting
    [junit] 2009-08-22 17:25:55,747 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 42930: exiting
    [junit] 2009-08-22 17:25:55,747 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 7 on 42930: exiting
    [junit] 2009-08-22 17:25:55,747 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 3 on 42930: exiting
    [junit] 2009-08-22 17:25:55,747 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 6 on 42930: exiting
    [junit] 2009-08-22 17:25:55,747 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 5 on 42930: exiting
    [junit] 2009-08-22 17:25:55,747 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 4 on 42930: exiting
    [junit] 2009-08-22 17:25:55,747 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 8 on 42930: exiting
    [junit] 2009-08-22 17:25:55,748 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
    [junit] 2009-08-22 17:25:55,747 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 9 on 42930: exiting
    [junit] 2009-08-22 17:25:55,748 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 42930
    [junit] Tests run: 7, Failures: 0, Errors: 0, Time elapsed: 79.161 sec

    checkfailure:

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

    Total time: 68 minutes 15 seconds
    Publishing Javadoc
    Recording test results
    Recording fingerprints
    Publishing Clover coverage report...
  • Apache Hudson Server at Aug 23, 2009 at 12:53 pm
    See http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/59/

    ------------------------------------------
    [...truncated 226537 lines...]
    [junit] 2009-08-23 12:47:51,082 INFO datanode.DataNode (DataNode.java:blockReport(998)) - BlockReport of 0 blocks got processed in 1 msecs
    [junit] 2009-08-23 12:47:51,083 INFO datanode.DataNode (DataNode.java:offerService(806)) - Starting Periodic block scanner.
    [junit] 2009-08-23 12:47:51,230 INFO common.Storage (DataStorage.java:recoverTransitionRead(122)) - Storage directory http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build-fi/test/data/dfs/data/data6 is not formatted.
    [junit] 2009-08-23 12:47:51,230 INFO common.Storage (DataStorage.java:recoverTransitionRead(123)) - Formatting ...
    [junit] 2009-08-23 12:47:51,539 INFO datanode.DataNode (FSDataset.java:registerMBean(1547)) - Registered FSDatasetStatusMBean
    [junit] 2009-08-23 12:47:51,539 INFO datanode.DataNode (DataNode.java:startDataNode(326)) - Opened info server at 48509
    [junit] 2009-08-23 12:47:51,539 INFO datanode.DataNode (DataXceiverServer.java:<init>(74)) - Balancing bandwith is 1048576 bytes/s
    [junit] 2009-08-23 12:47:51,540 INFO datanode.DirectoryScanner (DirectoryScanner.java:<init>(133)) - scan starts at 1251036241540 with interval 21600000
    [junit] 2009-08-23 12:47:51,541 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-08-23 12:47:51,541 INFO http.HttpServer (HttpServer.java:start(430)) - listener.getLocalPort() returned 52070 webServer.getConnectors()[0].getLocalPort() returned 52070
    [junit] 2009-08-23 12:47:51,542 INFO http.HttpServer (HttpServer.java:start(463)) - Jetty bound to port 52070
    [junit] 2009-08-23 12:47:51,542 INFO mortbay.log (?:invoke(?)) - jetty-6.1.14
    [junit] 2009-08-23 12:47:51,601 INFO mortbay.log (?:invoke(?)) - Started SelectChannelConnector@localhost:52070
    [junit] 2009-08-23 12:47:51,601 INFO jvm.JvmMetrics (JvmMetrics.java:init(66)) - Cannot initialize JVM Metrics with processName=DataNode, sessionId=null - already initialized
    [junit] 2009-08-23 12:47:51,602 INFO metrics.RpcMetrics (RpcMetrics.java:<init>(58)) - Initializing RPC Metrics with hostName=DataNode, port=48832
    [junit] 2009-08-23 12:47:51,603 INFO ipc.Server (Server.java:run(474)) - IPC Server Responder: starting
    [junit] 2009-08-23 12:47:51,603 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 0 on 48832: starting
    [junit] 2009-08-23 12:47:51,603 INFO ipc.Server (Server.java:run(313)) - IPC Server listener on 48832: starting
    [junit] 2009-08-23 12:47:51,604 INFO datanode.DataNode (DataNode.java:startDataNode(404)) - dnRegistration = DatanodeRegistration(vesta.apache.org:48509, storageID=, infoPort=52070, ipcPort=48832)
    [junit] 2009-08-23 12:47:51,605 INFO hdfs.StateChange (FSNamesystem.java:registerDatanode(1774)) - BLOCK* NameSystem.registerDatanode: node registration from 127.0.0.1:48509 storage DS-830920231-67.195.138.9-48509-1251031671604
    [junit] 2009-08-23 12:47:51,606 INFO net.NetworkTopology (NetworkTopology.java:add(327)) - Adding a new node: /default-rack/127.0.0.1:48509
    [junit] 2009-08-23 12:47:51,650 INFO datanode.DataNode (DataNode.java:register(571)) - New storage id DS-830920231-67.195.138.9-48509-1251031671604 is assigned to data-node 127.0.0.1:48509
    [junit] 2009-08-23 12:47:51,651 INFO datanode.DataNode (DataNode.java:run(1285)) - DatanodeRegistration(127.0.0.1:48509, storageID=DS-830920231-67.195.138.9-48509-1251031671604, infoPort=52070, ipcPort=48832)In DataNode.run, data = FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build-fi/test/data/dfs/data/data5/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build-fi/test/data/dfs/data/data6/current'}
    [junit] 2009-08-23 12:47:51,651 INFO datanode.DataNode (DataNode.java:offerService(763)) - using BLOCKREPORT_INTERVAL of 21600000msec Initial delay: 0msec
    [junit] 2009-08-23 12:47:51,688 INFO datanode.DataNode (DataNode.java:blockReport(998)) - BlockReport of 0 blocks got processed in 2 msecs
    [junit] 2009-08-23 12:47:51,688 INFO datanode.DataNode (DataNode.java:offerService(806)) - Starting Periodic block scanner.
    [junit] 2009-08-23 12:47:51,841 INFO FSNamesystem.audit (FSNamesystem.java:logAuditEvent(114)) - ugi=hudson,hudson ip=/127.0.0.1 cmd=create src=/pipeline_Fi_16/foo dst=null perm=hudson:supergroup:rw-r--r--
    [junit] 2009-08-23 12:47:51,844 INFO hdfs.StateChange (FSNamesystem.java:allocateBlock(1303)) - BLOCK* NameSystem.allocateBlock: /pipeline_Fi_16/foo. blk_-3823116340774608643_1001
    [junit] 2009-08-23 12:47:51,883 INFO protocol.ClientProtocolAspects (ClientProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_protocol_ClientProtocolAspects$1$7076326d(35)) - FI: addBlock Pipeline[127.0.0.1:33089, 127.0.0.1:48509, 127.0.0.1:42956]
    [junit] 2009-08-23 12:47:51,884 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$1$8f59fdd7(51)) - FI: receiverOp WRITE_BLOCK, datanode=127.0.0.1:33089
    [junit] 2009-08-23 12:47:51,885 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$3$3251489(72)) - FI: receiverOpWriteBlock
    [junit] 2009-08-23 12:47:51,885 INFO datanode.DataNode (DataXceiver.java:opWriteBlock(222)) - Receiving block blk_-3823116340774608643_1001 src: /127.0.0.1:59253 dest: /127.0.0.1:33089
    [junit] 2009-08-23 12:47:51,886 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$1$8f59fdd7(51)) - FI: receiverOp WRITE_BLOCK, datanode=127.0.0.1:48509
    [junit] 2009-08-23 12:47:51,887 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$3$3251489(72)) - FI: receiverOpWriteBlock
    [junit] 2009-08-23 12:47:51,887 INFO datanode.DataNode (DataXceiver.java:opWriteBlock(222)) - Receiving block blk_-3823116340774608643_1001 src: /127.0.0.1:45683 dest: /127.0.0.1:48509
    [junit] 2009-08-23 12:47:51,888 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$1$8f59fdd7(51)) - FI: receiverOp WRITE_BLOCK, datanode=127.0.0.1:42956
    [junit] 2009-08-23 12:47:51,888 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$3$3251489(72)) - FI: receiverOpWriteBlock
    [junit] 2009-08-23 12:47:51,888 INFO datanode.DataNode (DataXceiver.java:opWriteBlock(222)) - Receiving block blk_-3823116340774608643_1001 src: /127.0.0.1:48571 dest: /127.0.0.1:42956
    [junit] 2009-08-23 12:47:51,889 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$2$d4f6605f(61)) - FI: statusRead SUCCESS, datanode=127.0.0.1:48509
    [junit] 2009-08-23 12:47:51,890 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$2$d4f6605f(61)) - FI: statusRead SUCCESS, datanode=127.0.0.1:33089
    [junit] 2009-08-23 12:47:51,890 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
    [junit] 2009-08-23 12:47:51,891 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
    [junit] 2009-08-23 12:47:51,891 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
    [junit] 2009-08-23 12:47:51,891 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
    [junit] 2009-08-23 12:47:51,891 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
    [junit] 2009-08-23 12:47:51,892 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
    [junit] 2009-08-23 12:47:51,892 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
    [junit] 2009-08-23 12:47:51,892 INFO fi.FiTestUtil (DataTransferTestUtil.java:run(151)) - FI: pipeline_Fi_16, index=2, datanode=127.0.0.1:42956
    [junit] 2009-08-23 12:47:51,892 WARN datanode.DataNode (DataNode.java:checkDiskError(702)) - checkDiskError: exception:
    [junit] org.apache.hadoop.util.DiskChecker$DiskOutOfSpaceException: FI: pipeline_Fi_16, index=2, datanode=127.0.0.1:42956
    [junit] at org.apache.hadoop.fi.DataTransferTestUtil$DoosAction.run(DataTransferTestUtil.java:152)
    [junit] at org.apache.hadoop.fi.DataTransferTestUtil$DoosAction.run(DataTransferTestUtil.java:1)
    [junit] at org.apache.hadoop.fi.FiTestUtil$ActionContainer.run(FiTestUtil.java:66)
    [junit] at org.apache.hadoop.hdfs.server.datanode.BlockReceiverAspects.ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(BlockReceiverAspects.aj:50)
    [junit] at org.apache.hadoop.hdfs.server.datanode.BlockReceiver.receivePacket(BlockReceiver.java:459)
    [junit] at org.apache.hadoop.hdfs.server.datanode.BlockReceiver.receiveBlock(BlockReceiver.java:535)
    [junit] at org.apache.hadoop.hdfs.server.datanode.DataXceiver.opWriteBlock(DataXceiver.java:339)
    [junit] at org.apache.hadoop.hdfs.protocol.DataTransferProtocol$Receiver.opWriteBlock(DataTransferProtocol.java:324)
    [junit] at org.apache.hadoop.hdfs.protocol.DataTransferProtocol$Receiver.processOp(DataTransferProtocol.java:269)
    [junit] at org.apache.hadoop.hdfs.server.datanode.DataXceiver.run(DataXceiver.java:110)
    [junit] at java.lang.Thread.run(Thread.java:619)
    [junit] 2009-08-23 12:47:51,893 INFO mortbay.log (?:invoke(?)) - Completed FSVolumeSet.checkDirs. Removed=0volumes. List of current volumes: http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build-fi/test/data/dfs/data/data1/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build-fi/test/data/dfs/data/data2/current
    [junit] 2009-08-23 12:47:51,893 INFO datanode.DataNode (BlockReceiver.java:receiveBlock(569)) - Exception in receiveBlock for block blk_-3823116340774608643_1001 org.apache.hadoop.util.DiskChecker$DiskOutOfSpaceException: FI: pipeline_Fi_16, index=2, datanode=127.0.0.1:42956
    [junit] 2009-08-23 12:47:51,894 INFO datanode.DataNode (BlockReceiver.java:lastDataNodeRun(782)) - PacketResponder 0 for block blk_-3823116340774608643_1001 Interrupted.
    [junit] 2009-08-23 12:47:51,894 INFO datanode.DataNode (BlockReceiver.java:lastDataNodeRun(853)) - PacketResponder 0 for block blk_-3823116340774608643_1001 terminating
    [junit] 2009-08-23 12:47:51,894 INFO datanode.DataNode (DataXceiver.java:opWriteBlock(358)) - writeBlock blk_-3823116340774608643_1001 received exception org.apache.hadoop.util.DiskChecker$DiskOutOfSpaceException: FI: pipeline_Fi_16, index=2, datanode=127.0.0.1:42956
    [junit] 2009-08-23 12:47:51,894 ERROR datanode.DataNode (DataXceiver.java:run(112)) - DatanodeRegistration(127.0.0.1:42956, storageID=DS-1038161714-67.195.138.9-42956-1251031670395, infoPort=48218, ipcPort=60502):DataXceiver
    [junit] org.apache.hadoop.util.DiskChecker$DiskOutOfSpaceException: FI: pipeline_Fi_16, index=2, datanode=127.0.0.1:42956
    [junit] at org.apache.hadoop.fi.DataTransferTestUtil$DoosAction.run(DataTransferTestUtil.java:152)
    [junit] at org.apache.hadoop.fi.DataTransferTestUtil$DoosAction.run(DataTransferTestUtil.java:1)
    [junit] at org.apache.hadoop.fi.FiTestUtil$ActionContainer.run(FiTestUtil.java:66)
    [junit] at org.apache.hadoop.hdfs.server.datanode.BlockReceiverAspects.ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(BlockReceiverAspects.aj:50)
    [junit] at org.apache.hadoop.hdfs.server.datanode.BlockReceiver.receivePacket(BlockReceiver.java:459)
    [junit] at org.apache.hadoop.hdfs.server.datanode.BlockReceiver.receiveBlock(BlockReceiver.java:535)
    [junit] at org.apache.hadoop.hdfs.server.datanode.DataXceiver.opWriteBlock(DataXceiver.java:339)
    [junit] at org.apache.hadoop.hdfs.protocol.DataTransferProtocol$Receiver.opWriteBlock(DataTransferProtocol.java:324)
    [junit] at org.apache.hadoop.hdfs.protocol.DataTransferProtocol$Receiver.processOp(DataTransferProtocol.java:269)
    [junit] at org.apache.hadoop.hdfs.server.datanode.DataXceiver.run(DataXceiver.java:110)
    [junit] at java.lang.Thread.run(Thread.java:619)
    [junit] 2009-08-23 12:47:51,894 INFO datanode.DataNode (BlockReceiver.java:run(917)) - PacketResponder blk_-3823116340774608643_1001 1 Exception java.io.EOFException
    [junit] at java.io.DataInputStream.readFully(DataInputStream.java:180)
    [junit] at java.io.DataInputStream.readLong(DataInputStream.java:399)
    [junit] at org.apache.hadoop.hdfs.server.datanode.BlockReceiver$PacketResponder.run(BlockReceiver.java:879)
    [junit] at java.lang.Thread.run(Thread.java:619)
    [junit]
    [junit] 2009-08-23 12:47:51,926 INFO datanode.DataNode (BlockReceiver.java:run(1025)) - PacketResponder 1 for block blk_-3823116340774608643_1001 terminating
    [junit] 2009-08-23 12:47:51,926 INFO datanode.DataNode (BlockReceiver.java:run(1025)) - PacketResponder 2 for block blk_-3823116340774608643_1001 terminating
    [junit] 2009-08-23 12:47:51,927 WARN hdfs.DFSClient (DFSClient.java:run(2601)) - DFSOutputStream ResponseProcessor exception for block blk_-3823116340774608643_1001java.io.IOException: Bad response ERROR for block blk_-3823116340774608643_1001 from datanode 127.0.0.1:42956
    [junit] at org.apache.hadoop.hdfs.DFSClient$DFSOutputStream$DataStreamer$ResponseProcessor.run(DFSClient.java:2581)
    [junit]
    [junit] 2009-08-23 12:47:51,927 WARN hdfs.DFSClient (DFSClient.java:processDatanodeError(2630)) - Error Recovery for block blk_-3823116340774608643_1001 bad datanode[2] 127.0.0.1:42956
    [junit] 2009-08-23 12:47:51,927 WARN hdfs.DFSClient (DFSClient.java:processDatanodeError(2674)) - Error Recovery for block blk_-3823116340774608643_1001 in pipeline 127.0.0.1:33089, 127.0.0.1:48509, 127.0.0.1:42956: bad datanode 127.0.0.1:42956
    [junit] 2009-08-23 12:47:51,930 INFO datanode.DataNode (DataNode.java:logRecoverBlock(1727)) - Client calls recoverBlock(block=blk_-3823116340774608643_1001, targets=[127.0.0.1:33089, 127.0.0.1:48509])
    [junit] 2009-08-23 12:47:51,935 INFO datanode.DataNode (DataNode.java:updateBlock(1537)) - oldblock=blk_-3823116340774608643_1001(length=1), newblock=blk_-3823116340774608643_1002(length=1), datanode=127.0.0.1:33089
    [junit] 2009-08-23 12:47:51,937 INFO datanode.DataNode (DataNode.java:updateBlock(1537)) - oldblock=blk_-3823116340774608643_1001(length=1), newblock=blk_-3823116340774608643_1002(length=1), datanode=127.0.0.1:48509
    [junit] 2009-08-23 12:47:51,938 INFO namenode.FSNamesystem (FSNamesystem.java:commitBlockSynchronization(1613)) - commitBlockSynchronization(lastblock=blk_-3823116340774608643_1001, newgenerationstamp=1002, newlength=1, newtargets=[127.0.0.1:33089, 127.0.0.1:48509], closeFile=false, deleteBlock=false)
    [junit] 2009-08-23 12:47:51,939 INFO namenode.FSNamesystem (FSNamesystem.java:commitBlockSynchronization(1677)) - commitBlockSynchronization(blk_-3823116340774608643_1002) successful
    [junit] 2009-08-23 12:47:51,941 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$1$8f59fdd7(51)) - FI: receiverOp WRITE_BLOCK, datanode=127.0.0.1:33089
    [junit] 2009-08-23 12:47:51,941 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$3$3251489(72)) - FI: receiverOpWriteBlock
    [junit] 2009-08-23 12:47:51,941 INFO datanode.DataNode (DataXceiver.java:opWriteBlock(222)) - Receiving block blk_-3823116340774608643_1002 src: /127.0.0.1:59258 dest: /127.0.0.1:33089
    [junit] 2009-08-23 12:47:51,941 INFO datanode.DataNode (FSDataset.java:writeToBlock(1085)) - Reopen already-open Block for append blk_-3823116340774608643_1002
    [junit] 2009-08-23 12:47:51,942 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$1$8f59fdd7(51)) - FI: receiverOp WRITE_BLOCK, datanode=127.0.0.1:48509
    [junit] 2009-08-23 12:47:51,942 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$3$3251489(72)) - FI: receiverOpWriteBlock
    [junit] 2009-08-23 12:47:51,942 INFO datanode.DataNode (DataXceiver.java:opWriteBlock(222)) - Receiving block blk_-3823116340774608643_1002 src: /127.0.0.1:45688 dest: /127.0.0.1:48509
    [junit] 2009-08-23 12:47:51,943 INFO datanode.DataNode (FSDataset.java:writeToBlock(1085)) - Reopen already-open Block for append blk_-3823116340774608643_1002
    [junit] 2009-08-23 12:47:51,943 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$2$d4f6605f(61)) - FI: statusRead SUCCESS, datanode=127.0.0.1:33089
    [junit] 2009-08-23 12:47:51,944 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
    [junit] 2009-08-23 12:47:51,944 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
    [junit] 2009-08-23 12:47:51,944 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
    [junit] 2009-08-23 12:47:51,945 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
    [junit] 2009-08-23 12:47:51,945 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
    [junit] 2009-08-23 12:47:51,946 INFO DataNode.clienttrace (BlockReceiver.java:lastDataNodeRun(822)) - src: /127.0.0.1:45688, dest: /127.0.0.1:48509, bytes: 1, op: HDFS_WRITE, cliID: DFSClient_1407762613, offset: 0, srvID: DS-830920231-67.195.138.9-48509-1251031671604, blockid: blk_-3823116340774608643_1002, duration: 2397143
    [junit] 2009-08-23 12:47:51,987 INFO datanode.DataNode (BlockReceiver.java:lastDataNodeRun(853)) - PacketResponder 0 for block blk_-3823116340774608643_1002 terminating
    [junit] 2009-08-23 12:47:51,987 INFO hdfs.StateChange (BlockManager.java:addStoredBlock(950)) - BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:48509 is added to blk_-3823116340774608643_1002 size 1
    [junit] 2009-08-23 12:47:51,989 INFO DataNode.clienttrace (BlockReceiver.java:run(955)) - src: /127.0.0.1:59258, dest: /127.0.0.1:33089, bytes: 1, op: HDFS_WRITE, cliID: DFSClient_1407762613, offset: 0, srvID: DS-2088916918-67.195.138.9-33089-1251031670997, blockid: blk_-3823116340774608643_1002, duration: 45005337
    [junit] 2009-08-23 12:47:51,990 INFO datanode.DataNode (BlockReceiver.java:run(1025)) - PacketResponder 1 for block blk_-3823116340774608643_1002 terminating
    [junit] 2009-08-23 12:47:51,990 INFO hdfs.StateChange (BlockManager.java:addStoredBlock(950)) - BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:33089 is added to blk_-3823116340774608643_1002 size 1
    [junit] 2009-08-23 12:47:51,992 INFO hdfs.StateChange (FSNamesystem.java:completeFileInternal(1269)) - DIR* NameSystem.completeFile: file /pipeline_Fi_16/foo is closed by DFSClient_1407762613
    [junit] 2009-08-23 12:47:52,003 INFO FSNamesystem.audit (FSNamesystem.java:logAuditEvent(114)) - ugi=hudson,hudson ip=/127.0.0.1 cmd=open src=/pipeline_Fi_16/foo dst=null perm=null
    [junit] 2009-08-23 12:47:52,005 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$1$8f59fdd7(51)) - FI: receiverOp READ_BLOCK, datanode=127.0.0.1:48509
    [junit] Shutting down the Mini HDFS Cluster
    [junit] Shutting down DataNode 2
    [junit] 2009-08-23 12:47:52,006 INFO DataNode.clienttrace (BlockSender.java:sendBlock(417)) - src: /127.0.0.1:48509, dest: /127.0.0.1:45689, bytes: 5, op: HDFS_READ, cliID: DFSClient_1407762613, offset: 0, srvID: DS-830920231-67.195.138.9-48509-1251031671604, blockid: blk_-3823116340774608643_1002, duration: 250492
    [junit] 2009-08-23 12:47:52,007 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$2$d4f6605f(61)) - FI: statusRead CHECKSUM_OK, datanode=127.0.0.1:48509
    [junit] 2009-08-23 12:47:52,031 INFO ipc.Client (Client.java:handleConnectionFailure(395)) - Retrying connect to server: localhost/127.0.0.1:49694. Already tried 1 time(s).
    [junit] 2009-08-23 12:47:52,108 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 48832
    [junit] 2009-08-23 12:47:52,108 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 48832: exiting
    [junit] 2009-08-23 12:47:52,108 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 48832
    [junit] 2009-08-23 12:47:52,109 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
    [junit] 2009-08-23 12:47:52,109 WARN datanode.DataNode (DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:48509, storageID=DS-830920231-67.195.138.9-48509-1251031671604, infoPort=52070, ipcPort=48832):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-08-23 12:47:52,109 INFO datanode.DataNode (DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads is 0
    [junit] 2009-08-23 12:47:52,110 INFO datanode.DataBlockScanner (DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
    [junit] 2009-08-23 12:47:52,110 INFO datanode.DataNode (DataNode.java:run(1305)) - DatanodeRegistration(127.0.0.1:48509, storageID=DS-830920231-67.195.138.9-48509-1251031671604, infoPort=52070, ipcPort=48832):Finishing DataNode in: FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build-fi/test/data/dfs/data/data5/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build-fi/test/data/dfs/data/data6/current'}
    [junit] 2009-08-23 12:47:52,111 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 48832
    [junit] 2009-08-23 12:47:52,111 INFO datanode.DataNode (DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads is 0
    [junit] Shutting down DataNode 1
    [junit] 2009-08-23 12:47:52,231 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 58600
    [junit] 2009-08-23 12:47:52,231 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 58600: exiting
    [junit] 2009-08-23 12:47:52,233 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 58600
    [junit] 2009-08-23 12:47:52,233 INFO datanode.DataNode (DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads is 1
    [junit] 2009-08-23 12:47:52,233 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
    [junit] 2009-08-23 12:47:52,233 WARN datanode.DataNode (DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:33089, storageID=DS-2088916918-67.195.138.9-33089-1251031670997, infoPort=49467, ipcPort=58600):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-08-23 12:47:52,235 INFO datanode.DataNode (DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads is 0
    [junit] 2009-08-23 12:47:52,236 INFO datanode.DataBlockScanner (DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
    [junit] 2009-08-23 12:47:52,237 INFO datanode.DataNode (DataNode.java:run(1305)) - DatanodeRegistration(127.0.0.1:33089, storageID=DS-2088916918-67.195.138.9-33089-1251031670997, infoPort=49467, ipcPort=58600):Finishing DataNode in: FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build-fi/test/data/dfs/data/data3/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build-fi/test/data/dfs/data/data4/current'}
    [junit] 2009-08-23 12:47:52,237 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 58600
    [junit] 2009-08-23 12:47:52,237 INFO datanode.DataNode (DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads is 0
    [junit] Shutting down DataNode 0
    [junit] 2009-08-23 12:47:52,340 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 60502
    [junit] 2009-08-23 12:47:52,341 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 60502
    [junit] 2009-08-23 12:47:52,342 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
    [junit] 2009-08-23 12:47:52,342 WARN datanode.DataNode (DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:42956, storageID=DS-1038161714-67.195.138.9-42956-1251031670395, infoPort=48218, ipcPort=60502):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-08-23 12:47:52,342 INFO datanode.DataNode (DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads is 1
    [junit] 2009-08-23 12:47:52,341 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 60502: exiting
    [junit] 2009-08-23 12:47:52,343 INFO datanode.DataBlockScanner (DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
    [junit] 2009-08-23 12:47:52,343 INFO datanode.DataNode (DataNode.java:run(1305)) - DatanodeRegistration(127.0.0.1:42956, storageID=DS-1038161714-67.195.138.9-42956-1251031670395, infoPort=48218, ipcPort=60502):Finishing DataNode in: FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build-fi/test/data/dfs/data/data1/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build-fi/test/data/dfs/data/data2/current'}
    [junit] 2009-08-23 12:47:52,343 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 60502
    [junit] 2009-08-23 12:47:52,343 INFO datanode.DataNode (DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads is 0
    [junit] 2009-08-23 12:47:52,473 WARN namenode.DecommissionManager (DecommissionManager.java:run(67)) - Monitor interrupted: java.lang.InterruptedException: sleep interrupted
    [junit] 2009-08-23 12:47:52,473 INFO namenode.FSNamesystem (FSEditLog.java:printStatistics(884)) - Number of transactions: 5 Total time for transactions(ms): 0Number of transactions batched in Syncs: 0 Number of syncs: 2 SyncTimes(ms): 56 23
    [junit] 2009-08-23 12:47:52,473 WARN namenode.FSNamesystem (FSNamesystem.java:run(2077)) - ReplicationMonitor thread received InterruptedException.java.lang.InterruptedException: sleep interrupted
    [junit] 2009-08-23 12:47:52,495 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 46463
    [junit] 2009-08-23 12:47:52,495 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 46463: exiting
    [junit] 2009-08-23 12:47:52,495 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 46463: exiting
    [junit] 2009-08-23 12:47:52,495 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 3 on 46463: exiting
    [junit] 2009-08-23 12:47:52,496 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 9 on 46463: exiting
    [junit] 2009-08-23 12:47:52,495 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 6 on 46463: exiting
    [junit] 2009-08-23 12:47:52,495 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 46463: exiting
    [junit] 2009-08-23 12:47:52,496 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 46463
    [junit] 2009-08-23 12:47:52,496 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 8 on 46463: exiting
    [junit] 2009-08-23 12:47:52,496 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 5 on 46463: exiting
    [junit] 2009-08-23 12:47:52,496 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 7 on 46463: exiting
    [junit] 2009-08-23 12:47:52,496 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 4 on 46463: exiting
    [junit] 2009-08-23 12:47:52,497 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
    [junit] Tests run: 7, Failures: 0, Errors: 1, Time elapsed: 84.843 sec
    [junit] 2009-08-23 12:47:52,544 ERROR hdfs.DFSClient (DFSClient.java:close(1084)) - Exception closing file /pipeline_Fi_12/foo : java.io.IOException: Bad connect ack with firstBadLink as 127.0.0.1:58044
    [junit] java.io.IOException: Bad connect ack with firstBadLink as 127.0.0.1:58044
    [junit] at org.apache.hadoop.hdfs.DFSClient$DFSOutputStream$DataStreamer.createBlockOutputStream(DFSClient.java:2865)
    [junit] at org.apache.hadoop.hdfs.DFSClient$DFSOutputStream$DataStreamer.nextBlockOutputStream(DFSClient.java:2789)
    [junit] at org.apache.hadoop.hdfs.DFSClient$DFSOutputStream$DataStreamer.run(DFSClient.java:2399)
    [junit] 2009-08-23 12:47:52,545 INFO ipc.Client (Client.java:handleConnectionFailure(395)) - Retrying connect to server: localhost/127.0.0.1:49694. Already tried 2 time(s).
    [junit] 2009-08-23 12:47:53,545 INFO ipc.Client (Client.java:handleConnectionFailure(395)) - Retrying connect to server: localhost/127.0.0.1:49694. Already tried 3 time(s).
    [junit] 2009-08-23 12:47:54,545 INFO ipc.Client (Client.java:handleConnectionFailure(395)) - Retrying connect to server: localhost/127.0.0.1:49694. Already tried 4 time(s).
    [junit] 2009-08-23 12:47:55,546 INFO ipc.Client (Client.java:handleConnectionFailure(395)) - Retrying connect to server: localhost/127.0.0.1:49694. Already tried 5 time(s).
    [junit] 2009-08-23 12:47:56,546 INFO ipc.Client (Client.java:handleConnectionFailure(395)) - Retrying connect to server: localhost/127.0.0.1:49694. Already tried 6 time(s).
    [junit] 2009-08-23 12:47:57,546 INFO ipc.Client (Client.java:handleConnectionFailure(395)) - Retrying connect to server: localhost/127.0.0.1:49694. Already tried 7 time(s).
    [junit] 2009-08-23 12:47:58,547 INFO ipc.Client (Client.java:handleConnectionFailure(395)) - Retrying connect to server: localhost/127.0.0.1:49694. Already tried 8 time(s).
    [junit] 2009-08-23 12:47:59,547 INFO ipc.Client (Client.java:handleConnectionFailure(395)) - Retrying connect to server: localhost/127.0.0.1:49694. Already tried 9 time(s).
    [junit] 2009-08-23 12:47:59,548 WARN hdfs.DFSClient (DFSClient.java:run(1140)) - Problem renewing lease for DFSClient_-805227971 for a period of 0 seconds. Will retry shortly...
    [junit] java.net.ConnectException: Call to localhost/127.0.0.1:49694 failed on connection exception: java.net.ConnectException: Connection refused
    [junit] at org.apache.hadoop.ipc.Client.wrapException(Client.java:793)
    [junit] at org.apache.hadoop.ipc.Client.call(Client.java:769)
    [junit] at org.apache.hadoop.ipc.RPC$Invoker.invoke(RPC.java:223)
    [junit] at $Proxy5.renewLease(Unknown Source)
    [junit] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    [junit] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
    [junit] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    [junit] at java.lang.reflect.Method.invoke(Method.java:597)
    [junit] at org.apache.hadoop.io.retry.RetryInvocationHandler.invokeMethod(RetryInvocationHandler.java:82)
    [junit] at org.apache.hadoop.io.retry.RetryInvocationHandler.invoke(RetryInvocationHandler.java:59)
    [junit] at $Proxy5.renewLease(Unknown Source)
    [junit] at org.apache.hadoop.hdfs.DFSClient$LeaseChecker.renew(DFSClient.java:1115)
    [junit] at org.apache.hadoop.hdfs.DFSClient$LeaseChecker.run(DFSClient.java:1131)
    [junit] at java.lang.Thread.run(Thread.java:619)
    [junit] Caused by: java.net.ConnectException: Connection refused
    [junit] at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
    [junit] at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:574)
    [junit] at org.apache.hadoop.net.SocketIOWithTimeout.connect(SocketIOWithTimeout.java:206)
    [junit] at org.apache.hadoop.net.NetUtils.connect(NetUtils.java:368)
    [junit] at org.apache.hadoop.ipc.Client$Connection.setupIOstreams(Client.java:325)
    [junit] at org.apache.hadoop.ipc.Client$Connection.access$1800(Client.java:197)
    [junit] at org.apache.hadoop.ipc.Client.getConnection(Client.java:886)
    [junit] at org.apache.hadoop.ipc.Client.call(Client.java:746)
    [junit] ... 12 more
    [junit] Test org.apache.hadoop.hdfs.server.datanode.TestFiDataTransferProtocol FAILED

    checkfailure:
    [touch] Creating http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build-fi/test/testsfailed

    BUILD FAILED
    http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build.xml :722: The following error occurred while executing this line:
    http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build.xml :363: The following error occurred while executing this line:
    http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build.xml :646: The following error occurred while executing this line:
    http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build.xml :641: The following error occurred while executing this line:
    http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build.xml :705: Tests failed!

    Total time: 74 minutes 6 seconds
    Publishing Javadoc
    Recording test results
    Recording fingerprints
    Publishing Clover coverage report...
  • Apache Hudson Server at Aug 24, 2009 at 4:33 pm
    See http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/60/

    ------------------------------------------
    [...truncated 225499 lines...]
    [junit] 2009-08-24 15:29:58,782 INFO http.HttpServer (HttpServer.java:start(430)) - listener.getLocalPort() returned 48789 webServer.getConnectors()[0].getLocalPort() returned 48789
    [junit] 2009-08-24 15:29:58,782 INFO http.HttpServer (HttpServer.java:start(463)) - Jetty bound to port 48789
    [junit] 2009-08-24 15:29:58,783 INFO mortbay.log (?:invoke(?)) - jetty-6.1.14
    [junit] 2009-08-24 15:29:58,843 INFO mortbay.log (?:invoke(?)) - Started SelectChannelConnector@localhost:48789
    [junit] 2009-08-24 15:29:58,844 INFO jvm.JvmMetrics (JvmMetrics.java:init(66)) - Cannot initialize JVM Metrics with processName=DataNode, sessionId=null - already initialized
    [junit] 2009-08-24 15:29:58,845 INFO metrics.RpcMetrics (RpcMetrics.java:<init>(58)) - Initializing RPC Metrics with hostName=DataNode, port=58723
    [junit] 2009-08-24 15:29:58,846 INFO ipc.Server (Server.java:run(474)) - IPC Server Responder: starting
    [junit] 2009-08-24 15:29:58,846 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 0 on 58723: starting
    [junit] 2009-08-24 15:29:58,846 INFO datanode.DataNode (DataNode.java:startDataNode(404)) - dnRegistration = DatanodeRegistration(vesta.apache.org:51187, storageID=, infoPort=48789, ipcPort=58723)
    [junit] 2009-08-24 15:29:58,846 INFO ipc.Server (Server.java:run(313)) - IPC Server listener on 58723: starting
    [junit] 2009-08-24 15:29:58,849 INFO hdfs.StateChange (FSNamesystem.java:registerDatanode(1774)) - BLOCK* NameSystem.registerDatanode: node registration from 127.0.0.1:51187 storage DS-1737465689-67.195.138.9-51187-1251127798848
    [junit] 2009-08-24 15:29:58,849 INFO net.NetworkTopology (NetworkTopology.java:add(327)) - Adding a new node: /default-rack/127.0.0.1:51187
    [junit] 2009-08-24 15:29:58,907 INFO datanode.DataNode (DataNode.java:register(571)) - New storage id DS-1737465689-67.195.138.9-51187-1251127798848 is assigned to data-node 127.0.0.1:51187
    [junit] 2009-08-24 15:29:58,907 INFO datanode.DataNode (DataNode.java:run(1285)) - DatanodeRegistration(127.0.0.1:51187, storageID=DS-1737465689-67.195.138.9-51187-1251127798848, infoPort=48789, ipcPort=58723)In DataNode.run, data = FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build-fi/test/data/dfs/data/data1/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build-fi/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-fi/test/data/dfs/data/data3,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build-fi/test/data/dfs/data/data4
    [junit] 2009-08-24 15:29:58,908 INFO datanode.DataNode (DataNode.java:offerService(763)) - using BLOCKREPORT_INTERVAL of 21600000msec Initial delay: 0msec
    [junit] 2009-08-24 15:29:58,916 INFO common.Storage (DataStorage.java:recoverTransitionRead(122)) - Storage directory http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build-fi/test/data/dfs/data/data3 is not formatted.
    [junit] 2009-08-24 15:29:58,916 INFO common.Storage (DataStorage.java:recoverTransitionRead(123)) - Formatting ...
    [junit] 2009-08-24 15:29:58,939 INFO datanode.DataNode (DataNode.java:blockReport(998)) - BlockReport of 0 blocks got processed in 0 msecs
    [junit] 2009-08-24 15:29:58,940 INFO datanode.DataNode (DataNode.java:offerService(806)) - Starting Periodic block scanner.
    [junit] 2009-08-24 15:29:59,108 INFO common.Storage (DataStorage.java:recoverTransitionRead(122)) - Storage directory http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build-fi/test/data/dfs/data/data4 is not formatted.
    [junit] 2009-08-24 15:29:59,109 INFO common.Storage (DataStorage.java:recoverTransitionRead(123)) - Formatting ...
    [junit] 2009-08-24 15:29:59,408 INFO datanode.DataNode (FSDataset.java:registerMBean(1547)) - Registered FSDatasetStatusMBean
    [junit] 2009-08-24 15:29:59,408 INFO datanode.DataNode (DataNode.java:startDataNode(326)) - Opened info server at 55493
    [junit] 2009-08-24 15:29:59,408 INFO datanode.DataNode (DataXceiverServer.java:<init>(74)) - Balancing bandwith is 1048576 bytes/s
    [junit] 2009-08-24 15:29:59,409 INFO datanode.DirectoryScanner (DirectoryScanner.java:<init>(133)) - scan starts at 1251142032409 with interval 21600000
    [junit] 2009-08-24 15:29:59,410 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-08-24 15:29:59,410 INFO http.HttpServer (HttpServer.java:start(430)) - listener.getLocalPort() returned 47165 webServer.getConnectors()[0].getLocalPort() returned 47165
    [junit] 2009-08-24 15:29:59,411 INFO http.HttpServer (HttpServer.java:start(463)) - Jetty bound to port 47165
    [junit] 2009-08-24 15:29:59,411 INFO mortbay.log (?:invoke(?)) - jetty-6.1.14
    [junit] 2009-08-24 15:29:59,472 INFO mortbay.log (?:invoke(?)) - Started SelectChannelConnector@localhost:47165
    [junit] 2009-08-24 15:29:59,472 INFO jvm.JvmMetrics (JvmMetrics.java:init(66)) - Cannot initialize JVM Metrics with processName=DataNode, sessionId=null - already initialized
    [junit] 2009-08-24 15:29:59,473 INFO metrics.RpcMetrics (RpcMetrics.java:<init>(58)) - Initializing RPC Metrics with hostName=DataNode, port=50562
    [junit] 2009-08-24 15:29:59,474 INFO ipc.Server (Server.java:run(474)) - IPC Server Responder: starting
    [junit] 2009-08-24 15:29:59,474 INFO ipc.Server (Server.java:run(313)) - IPC Server listener on 50562: starting
    [junit] 2009-08-24 15:29:59,474 INFO datanode.DataNode (DataNode.java:startDataNode(404)) - dnRegistration = DatanodeRegistration(vesta.apache.org:55493, storageID=, infoPort=47165, ipcPort=50562)
    [junit] 2009-08-24 15:29:59,474 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 0 on 50562: starting
    [junit] 2009-08-24 15:29:59,476 INFO hdfs.StateChange (FSNamesystem.java:registerDatanode(1774)) - BLOCK* NameSystem.registerDatanode: node registration from 127.0.0.1:55493 storage DS-434709537-67.195.138.9-55493-1251127799475
    [junit] 2009-08-24 15:29:59,476 INFO net.NetworkTopology (NetworkTopology.java:add(327)) - Adding a new node: /default-rack/127.0.0.1:55493
    [junit] 2009-08-24 15:29:59,519 INFO datanode.DataNode (DataNode.java:register(571)) - New storage id DS-434709537-67.195.138.9-55493-1251127799475 is assigned to data-node 127.0.0.1:55493
    [junit] 2009-08-24 15:29:59,520 INFO datanode.DataNode (DataNode.java:run(1285)) - DatanodeRegistration(127.0.0.1:55493, storageID=DS-434709537-67.195.138.9-55493-1251127799475, infoPort=47165, ipcPort=50562)In DataNode.run, data = FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build-fi/test/data/dfs/data/data3/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build-fi/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-fi/test/data/dfs/data/data5,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build-fi/test/data/dfs/data/data6
    [junit] 2009-08-24 15:29:59,520 INFO datanode.DataNode (DataNode.java:offerService(763)) - using BLOCKREPORT_INTERVAL of 21600000msec Initial delay: 0msec
    [junit] 2009-08-24 15:29:59,528 INFO common.Storage (DataStorage.java:recoverTransitionRead(122)) - Storage directory http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build-fi/test/data/dfs/data/data5 is not formatted.
    [junit] 2009-08-24 15:29:59,529 INFO common.Storage (DataStorage.java:recoverTransitionRead(123)) - Formatting ...
    [junit] 2009-08-24 15:29:59,557 INFO datanode.DataNode (DataNode.java:blockReport(998)) - BlockReport of 0 blocks got processed in 1 msecs
    [junit] 2009-08-24 15:29:59,557 INFO datanode.DataNode (DataNode.java:offerService(806)) - Starting Periodic block scanner.
    [junit] 2009-08-24 15:29:59,721 INFO common.Storage (DataStorage.java:recoverTransitionRead(122)) - Storage directory http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build-fi/test/data/dfs/data/data6 is not formatted.
    [junit] 2009-08-24 15:29:59,722 INFO common.Storage (DataStorage.java:recoverTransitionRead(123)) - Formatting ...
    [junit] 2009-08-24 15:29:59,987 INFO datanode.DataNode (FSDataset.java:registerMBean(1547)) - Registered FSDatasetStatusMBean
    [junit] 2009-08-24 15:29:59,988 INFO datanode.DataNode (DataNode.java:startDataNode(326)) - Opened info server at 36230
    [junit] 2009-08-24 15:29:59,988 INFO datanode.DataNode (DataXceiverServer.java:<init>(74)) - Balancing bandwith is 1048576 bytes/s
    [junit] 2009-08-24 15:29:59,988 INFO datanode.DirectoryScanner (DirectoryScanner.java:<init>(133)) - scan starts at 1251129010988 with interval 21600000
    [junit] 2009-08-24 15:29:59,990 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-08-24 15:29:59,990 INFO http.HttpServer (HttpServer.java:start(430)) - listener.getLocalPort() returned 56533 webServer.getConnectors()[0].getLocalPort() returned 56533
    [junit] 2009-08-24 15:29:59,990 INFO http.HttpServer (HttpServer.java:start(463)) - Jetty bound to port 56533
    [junit] 2009-08-24 15:29:59,991 INFO mortbay.log (?:invoke(?)) - jetty-6.1.14
    [junit] 2009-08-24 15:30:00,052 INFO mortbay.log (?:invoke(?)) - Started SelectChannelConnector@localhost:56533
    [junit] 2009-08-24 15:30:00,053 INFO jvm.JvmMetrics (JvmMetrics.java:init(66)) - Cannot initialize JVM Metrics with processName=DataNode, sessionId=null - already initialized
    [junit] 2009-08-24 15:30:00,054 INFO metrics.RpcMetrics (RpcMetrics.java:<init>(58)) - Initializing RPC Metrics with hostName=DataNode, port=52683
    [junit] 2009-08-24 15:30:00,055 INFO ipc.Server (Server.java:run(474)) - IPC Server Responder: starting
    [junit] 2009-08-24 15:30:00,055 INFO ipc.Server (Server.java:run(313)) - IPC Server listener on 52683: starting
    [junit] 2009-08-24 15:30:00,055 INFO datanode.DataNode (DataNode.java:startDataNode(404)) - dnRegistration = DatanodeRegistration(vesta.apache.org:36230, storageID=, infoPort=56533, ipcPort=52683)
    [junit] 2009-08-24 15:30:00,055 INFO ipc.Server (Server.java:run(939)) - IPC Server handler 0 on 52683: starting
    [junit] 2009-08-24 15:30:00,057 INFO hdfs.StateChange (FSNamesystem.java:registerDatanode(1774)) - BLOCK* NameSystem.registerDatanode: node registration from 127.0.0.1:36230 storage DS-1245667935-67.195.138.9-36230-1251127800056
    [junit] 2009-08-24 15:30:00,057 INFO net.NetworkTopology (NetworkTopology.java:add(327)) - Adding a new node: /default-rack/127.0.0.1:36230
    [junit] 2009-08-24 15:30:00,101 INFO datanode.DataNode (DataNode.java:register(571)) - New storage id DS-1245667935-67.195.138.9-36230-1251127800056 is assigned to data-node 127.0.0.1:36230
    [junit] 2009-08-24 15:30:00,102 INFO datanode.DataNode (DataNode.java:run(1285)) - DatanodeRegistration(127.0.0.1:36230, storageID=DS-1245667935-67.195.138.9-36230-1251127800056, infoPort=56533, ipcPort=52683)In DataNode.run, data = FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build-fi/test/data/dfs/data/data5/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build-fi/test/data/dfs/data/data6/current'}
    [junit] 2009-08-24 15:30:00,102 INFO datanode.DataNode (DataNode.java:offerService(763)) - using BLOCKREPORT_INTERVAL of 21600000msec Initial delay: 0msec
    [junit] 2009-08-24 15:30:00,128 INFO datanode.DataNode (DataNode.java:blockReport(998)) - BlockReport of 0 blocks got processed in 1 msecs
    [junit] 2009-08-24 15:30:00,129 INFO datanode.DataNode (DataNode.java:offerService(806)) - Starting Periodic block scanner.
    [junit] 2009-08-24 15:30:00,306 INFO FSNamesystem.audit (FSNamesystem.java:logAuditEvent(114)) - ugi=hudson,hudson ip=/127.0.0.1 cmd=create src=/pipeline_Fi_16/foo dst=null perm=hudson:supergroup:rw-r--r--
    [junit] 2009-08-24 15:30:00,308 INFO hdfs.StateChange (FSNamesystem.java:allocateBlock(1303)) - BLOCK* NameSystem.allocateBlock: /pipeline_Fi_16/foo. blk_-3596213809731970953_1001
    [junit] 2009-08-24 15:30:00,341 INFO protocol.ClientProtocolAspects (ClientProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_protocol_ClientProtocolAspects$1$7076326d(35)) - FI: addBlock Pipeline[127.0.0.1:36230, 127.0.0.1:51187, 127.0.0.1:55493]
    [junit] 2009-08-24 15:30:00,342 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$1$8f59fdd7(51)) - FI: receiverOp WRITE_BLOCK, datanode=127.0.0.1:36230
    [junit] 2009-08-24 15:30:00,343 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$3$3251489(72)) - FI: receiverOpWriteBlock
    [junit] 2009-08-24 15:30:00,343 INFO datanode.DataNode (DataXceiver.java:opWriteBlock(222)) - Receiving block blk_-3596213809731970953_1001 src: /127.0.0.1:49173 dest: /127.0.0.1:36230
    [junit] 2009-08-24 15:30:00,344 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$1$8f59fdd7(51)) - FI: receiverOp WRITE_BLOCK, datanode=127.0.0.1:51187
    [junit] 2009-08-24 15:30:00,345 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$3$3251489(72)) - FI: receiverOpWriteBlock
    [junit] 2009-08-24 15:30:00,345 INFO datanode.DataNode (DataXceiver.java:opWriteBlock(222)) - Receiving block blk_-3596213809731970953_1001 src: /127.0.0.1:37124 dest: /127.0.0.1:51187
    [junit] 2009-08-24 15:30:00,347 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$1$8f59fdd7(51)) - FI: receiverOp WRITE_BLOCK, datanode=127.0.0.1:55493
    [junit] 2009-08-24 15:30:00,347 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$3$3251489(72)) - FI: receiverOpWriteBlock
    [junit] 2009-08-24 15:30:00,347 INFO datanode.DataNode (DataXceiver.java:opWriteBlock(222)) - Receiving block blk_-3596213809731970953_1001 src: /127.0.0.1:44709 dest: /127.0.0.1:55493
    [junit] 2009-08-24 15:30:00,348 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$2$d4f6605f(61)) - FI: statusRead SUCCESS, datanode=127.0.0.1:51187
    [junit] 2009-08-24 15:30:00,348 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$2$d4f6605f(61)) - FI: statusRead SUCCESS, datanode=127.0.0.1:36230
    [junit] 2009-08-24 15:30:00,349 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
    [junit] 2009-08-24 15:30:00,350 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
    [junit] 2009-08-24 15:30:00,350 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
    [junit] 2009-08-24 15:30:00,350 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
    [junit] 2009-08-24 15:30:00,350 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
    [junit] 2009-08-24 15:30:00,350 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
    [junit] 2009-08-24 15:30:00,350 INFO fi.FiTestUtil (DataTransferTestUtil.java:run(151)) - FI: pipeline_Fi_16, index=2, datanode=127.0.0.1:55493
    [junit] 2009-08-24 15:30:00,351 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
    [junit] 2009-08-24 15:30:00,351 WARN datanode.DataNode (DataNode.java:checkDiskError(702)) - checkDiskError: exception:
    [junit] org.apache.hadoop.util.DiskChecker$DiskOutOfSpaceException: FI: pipeline_Fi_16, index=2, datanode=127.0.0.1:55493
    [junit] at org.apache.hadoop.fi.DataTransferTestUtil$DoosAction.run(DataTransferTestUtil.java:152)
    [junit] at org.apache.hadoop.fi.DataTransferTestUtil$DoosAction.run(DataTransferTestUtil.java:1)
    [junit] at org.apache.hadoop.fi.FiTestUtil$ActionContainer.run(FiTestUtil.java:66)
    [junit] at org.apache.hadoop.hdfs.server.datanode.BlockReceiverAspects.ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(BlockReceiverAspects.aj:50)
    [junit] at org.apache.hadoop.hdfs.server.datanode.BlockReceiver.receivePacket(BlockReceiver.java:459)
    [junit] at org.apache.hadoop.hdfs.server.datanode.BlockReceiver.receiveBlock(BlockReceiver.java:535)
    [junit] at org.apache.hadoop.hdfs.server.datanode.DataXceiver.opWriteBlock(DataXceiver.java:339)
    [junit] at org.apache.hadoop.hdfs.protocol.DataTransferProtocol$Receiver.opWriteBlock(DataTransferProtocol.java:324)
    [junit] at org.apache.hadoop.hdfs.protocol.DataTransferProtocol$Receiver.processOp(DataTransferProtocol.java:269)
    [junit] at org.apache.hadoop.hdfs.server.datanode.DataXceiver.run(DataXceiver.java:110)
    [junit] at java.lang.Thread.run(Thread.java:619)
    [junit] 2009-08-24 15:30:00,352 INFO mortbay.log (?:invoke(?)) - Completed FSVolumeSet.checkDirs. Removed=0volumes. List of current volumes: http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build-fi/test/data/dfs/data/data3/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build-fi/test/data/dfs/data/data4/current
    [junit] 2009-08-24 15:30:00,352 INFO datanode.DataNode (BlockReceiver.java:receiveBlock(569)) - Exception in receiveBlock for block blk_-3596213809731970953_1001 org.apache.hadoop.util.DiskChecker$DiskOutOfSpaceException: FI: pipeline_Fi_16, index=2, datanode=127.0.0.1:55493
    [junit] 2009-08-24 15:30:00,352 INFO datanode.DataNode (BlockReceiver.java:lastDataNodeRun(782)) - PacketResponder 0 for block blk_-3596213809731970953_1001 Interrupted.
    [junit] 2009-08-24 15:30:00,352 INFO datanode.DataNode (BlockReceiver.java:lastDataNodeRun(853)) - PacketResponder 0 for block blk_-3596213809731970953_1001 terminating
    [junit] 2009-08-24 15:30:00,352 INFO datanode.DataNode (DataXceiver.java:opWriteBlock(358)) - writeBlock blk_-3596213809731970953_1001 received exception org.apache.hadoop.util.DiskChecker$DiskOutOfSpaceException: FI: pipeline_Fi_16, index=2, datanode=127.0.0.1:55493
    [junit] 2009-08-24 15:30:00,353 ERROR datanode.DataNode (DataXceiver.java:run(112)) - DatanodeRegistration(127.0.0.1:55493, storageID=DS-434709537-67.195.138.9-55493-1251127799475, infoPort=47165, ipcPort=50562):DataXceiver
    [junit] org.apache.hadoop.util.DiskChecker$DiskOutOfSpaceException: FI: pipeline_Fi_16, index=2, datanode=127.0.0.1:55493
    [junit] at org.apache.hadoop.fi.DataTransferTestUtil$DoosAction.run(DataTransferTestUtil.java:152)
    [junit] at org.apache.hadoop.fi.DataTransferTestUtil$DoosAction.run(DataTransferTestUtil.java:1)
    [junit] at org.apache.hadoop.fi.FiTestUtil$ActionContainer.run(FiTestUtil.java:66)
    [junit] at org.apache.hadoop.hdfs.server.datanode.BlockReceiverAspects.ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(BlockReceiverAspects.aj:50)
    [junit] at org.apache.hadoop.hdfs.server.datanode.BlockReceiver.receivePacket(BlockReceiver.java:459)
    [junit] at org.apache.hadoop.hdfs.server.datanode.BlockReceiver.receiveBlock(BlockReceiver.java:535)
    [junit] at org.apache.hadoop.hdfs.server.datanode.DataXceiver.opWriteBlock(DataXceiver.java:339)
    [junit] at org.apache.hadoop.hdfs.protocol.DataTransferProtocol$Receiver.opWriteBlock(DataTransferProtocol.java:324)
    [junit] at org.apache.hadoop.hdfs.protocol.DataTransferProtocol$Receiver.processOp(DataTransferProtocol.java:269)
    [junit] at org.apache.hadoop.hdfs.server.datanode.DataXceiver.run(DataXceiver.java:110)
    [junit] at java.lang.Thread.run(Thread.java:619)
    [junit] 2009-08-24 15:30:00,354 INFO datanode.DataNode (BlockReceiver.java:run(917)) - PacketResponder blk_-3596213809731970953_1001 1 Exception java.io.EOFException
    [junit] at java.io.DataInputStream.readFully(DataInputStream.java:180)
    [junit] at java.io.DataInputStream.readLong(DataInputStream.java:399)
    [junit] at org.apache.hadoop.hdfs.server.datanode.BlockReceiver$PacketResponder.run(BlockReceiver.java:879)
    [junit] at java.lang.Thread.run(Thread.java:619)
    [junit]
    [junit] 2009-08-24 15:30:00,354 INFO datanode.DataNode (BlockReceiver.java:run(1025)) - PacketResponder 1 for block blk_-3596213809731970953_1001 terminating
    [junit] 2009-08-24 15:30:00,355 INFO datanode.DataNode (BlockReceiver.java:run(1025)) - PacketResponder 2 for block blk_-3596213809731970953_1001 terminating
    [junit] 2009-08-24 15:30:00,394 WARN hdfs.DFSClient (DFSClient.java:run(2601)) - DFSOutputStream ResponseProcessor exception for block blk_-3596213809731970953_1001java.io.IOException: Bad response ERROR for block blk_-3596213809731970953_1001 from datanode 127.0.0.1:55493
    [junit] at org.apache.hadoop.hdfs.DFSClient$DFSOutputStream$DataStreamer$ResponseProcessor.run(DFSClient.java:2581)
    [junit]
    [junit] 2009-08-24 15:30:00,395 WARN hdfs.DFSClient (DFSClient.java:processDatanodeError(2630)) - Error Recovery for block blk_-3596213809731970953_1001 bad datanode[2] 127.0.0.1:55493
    [junit] 2009-08-24 15:30:00,395 WARN hdfs.DFSClient (DFSClient.java:processDatanodeError(2674)) - Error Recovery for block blk_-3596213809731970953_1001 in pipeline 127.0.0.1:36230, 127.0.0.1:51187, 127.0.0.1:55493: bad datanode 127.0.0.1:55493
    [junit] 2009-08-24 15:30:00,397 INFO datanode.DataNode (DataNode.java:logRecoverBlock(1727)) - Client calls recoverBlock(block=blk_-3596213809731970953_1001, targets=[127.0.0.1:36230, 127.0.0.1:51187])
    [junit] 2009-08-24 15:30:00,401 INFO datanode.DataNode (DataNode.java:updateBlock(1537)) - oldblock=blk_-3596213809731970953_1001(length=1), newblock=blk_-3596213809731970953_1002(length=1), datanode=127.0.0.1:36230
    [junit] 2009-08-24 15:30:00,402 INFO datanode.DataNode (DataNode.java:updateBlock(1537)) - oldblock=blk_-3596213809731970953_1001(length=1), newblock=blk_-3596213809731970953_1002(length=1), datanode=127.0.0.1:51187
    [junit] 2009-08-24 15:30:00,403 INFO namenode.FSNamesystem (FSNamesystem.java:commitBlockSynchronization(1613)) - commitBlockSynchronization(lastblock=blk_-3596213809731970953_1001, newgenerationstamp=1002, newlength=1, newtargets=[127.0.0.1:36230, 127.0.0.1:51187], closeFile=false, deleteBlock=false)
    [junit] 2009-08-24 15:30:00,403 INFO namenode.FSNamesystem (FSNamesystem.java:commitBlockSynchronization(1677)) - commitBlockSynchronization(blk_-3596213809731970953_1002) successful
    [junit] 2009-08-24 15:30:00,405 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$1$8f59fdd7(51)) - FI: receiverOp WRITE_BLOCK, datanode=127.0.0.1:36230
    [junit] 2009-08-24 15:30:00,405 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$3$3251489(72)) - FI: receiverOpWriteBlock
    [junit] 2009-08-24 15:30:00,405 INFO datanode.DataNode (DataXceiver.java:opWriteBlock(222)) - Receiving block blk_-3596213809731970953_1002 src: /127.0.0.1:49178 dest: /127.0.0.1:36230
    [junit] 2009-08-24 15:30:00,405 INFO datanode.DataNode (FSDataset.java:writeToBlock(1085)) - Reopen already-open Block for append blk_-3596213809731970953_1002
    [junit] 2009-08-24 15:30:00,406 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$1$8f59fdd7(51)) - FI: receiverOp WRITE_BLOCK, datanode=127.0.0.1:51187
    [junit] 2009-08-24 15:30:00,406 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$3$3251489(72)) - FI: receiverOpWriteBlock
    [junit] 2009-08-24 15:30:00,406 INFO datanode.DataNode (DataXceiver.java:opWriteBlock(222)) - Receiving block blk_-3596213809731970953_1002 src: /127.0.0.1:37129 dest: /127.0.0.1:51187
    [junit] 2009-08-24 15:30:00,406 INFO datanode.DataNode (FSDataset.java:writeToBlock(1085)) - Reopen already-open Block for append blk_-3596213809731970953_1002
    [junit] 2009-08-24 15:30:00,407 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$2$d4f6605f(61)) - FI: statusRead SUCCESS, datanode=127.0.0.1:36230
    [junit] 2009-08-24 15:30:00,408 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
    [junit] 2009-08-24 15:30:00,408 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
    [junit] 2009-08-24 15:30:00,408 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
    [junit] 2009-08-24 15:30:00,408 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
    [junit] 2009-08-24 15:30:00,408 INFO datanode.BlockReceiverAspects (BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(47)) - FI: callReceivePacket
    [junit] 2009-08-24 15:30:00,481 INFO DataNode.clienttrace (BlockReceiver.java:lastDataNodeRun(822)) - src: /127.0.0.1:37129, dest: /127.0.0.1:51187, bytes: 1, op: HDFS_WRITE, cliID: DFSClient_766334557, offset: 0, srvID: DS-1737465689-67.195.138.9-51187-1251127798848, blockid: blk_-3596213809731970953_1002, duration: 74295043
    [junit] 2009-08-24 15:30:00,482 INFO datanode.DataNode (BlockReceiver.java:lastDataNodeRun(853)) - PacketResponder 0 for block blk_-3596213809731970953_1002 terminating
    [junit] 2009-08-24 15:30:00,483 INFO DataNode.clienttrace (BlockReceiver.java:run(955)) - src: /127.0.0.1:49178, dest: /127.0.0.1:36230, bytes: 1, op: HDFS_WRITE, cliID: DFSClient_766334557, offset: 0, srvID: DS-1245667935-67.195.138.9-36230-1251127800056, blockid: blk_-3596213809731970953_1002, duration: 74937220
    [junit] 2009-08-24 15:30:00,483 INFO hdfs.StateChange (BlockManager.java:addStoredBlock(950)) - BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:51187 is added to blk_-3596213809731970953_1002 size 1
    [junit] 2009-08-24 15:30:00,483 INFO datanode.DataNode (BlockReceiver.java:run(1025)) - PacketResponder 1 for block blk_-3596213809731970953_1002 terminating
    [junit] 2009-08-24 15:30:00,484 INFO hdfs.StateChange (BlockManager.java:addStoredBlock(950)) - BLOCK* NameSystem.addStoredBlock: blockMap updated: 127.0.0.1:36230 is added to blk_-3596213809731970953_1002 size 1
    [junit] 2009-08-24 15:30:00,485 INFO hdfs.StateChange (FSNamesystem.java:completeFileInternal(1269)) - DIR* NameSystem.completeFile: file /pipeline_Fi_16/foo is closed by DFSClient_766334557
    [junit] 2009-08-24 15:30:00,501 INFO FSNamesystem.audit (FSNamesystem.java:logAuditEvent(114)) - ugi=hudson,hudson ip=/127.0.0.1 cmd=open src=/pipeline_Fi_16/foo dst=null perm=null
    [junit] 2009-08-24 15:30:00,502 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$1$8f59fdd7(51)) - FI: receiverOp READ_BLOCK, datanode=127.0.0.1:51187
    [junit] Shutting down the Mini HDFS Cluster
    [junit] Shutting down DataNode 2
    [junit] 2009-08-24 15:30:00,503 INFO DataNode.clienttrace (BlockSender.java:sendBlock(417)) - src: /127.0.0.1:51187, dest: /127.0.0.1:37130, bytes: 5, op: HDFS_READ, cliID: DFSClient_766334557, offset: 0, srvID: DS-1737465689-67.195.138.9-51187-1251127798848, blockid: blk_-3596213809731970953_1002, duration: 239131
    [junit] 2009-08-24 15:30:00,503 INFO datanode.DataTransferProtocolAspects (DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$2$d4f6605f(61)) - FI: statusRead CHECKSUM_OK, datanode=127.0.0.1:51187
    [junit] 2009-08-24 15:30:00,504 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 52683
    [junit] 2009-08-24 15:30:00,505 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 52683: exiting
    [junit] 2009-08-24 15:30:00,505 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 52683
    [junit] 2009-08-24 15:30:00,505 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
    [junit] 2009-08-24 15:30:00,505 INFO datanode.DataNode (DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads is 1
    [junit] 2009-08-24 15:30:00,505 WARN datanode.DataNode (DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:36230, storageID=DS-1245667935-67.195.138.9-36230-1251127800056, infoPort=56533, ipcPort=52683):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-08-24 15:30:00,507 INFO datanode.DataNode (DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads is 0
    [junit] 2009-08-24 15:30:00,508 INFO datanode.DataBlockScanner (DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
    [junit] 2009-08-24 15:30:00,508 INFO datanode.DataNode (DataNode.java:run(1305)) - DatanodeRegistration(127.0.0.1:36230, storageID=DS-1245667935-67.195.138.9-36230-1251127800056, infoPort=56533, ipcPort=52683):Finishing DataNode in: FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build-fi/test/data/dfs/data/data5/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build-fi/test/data/dfs/data/data6/current'}
    [junit] 2009-08-24 15:30:00,508 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 52683
    [junit] 2009-08-24 15:30:00,508 INFO datanode.DataNode (DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads is 0
    [junit] Shutting down DataNode 1
    [junit] 2009-08-24 15:30:00,622 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 50562
    [junit] 2009-08-24 15:30:00,623 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 50562: exiting
    [junit] 2009-08-24 15:30:00,623 INFO datanode.DataNode (DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads is 1
    [junit] 2009-08-24 15:30:00,623 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 50562
    [junit] 2009-08-24 15:30:00,623 WARN datanode.DataNode (DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:55493, storageID=DS-434709537-67.195.138.9-55493-1251127799475, infoPort=47165, ipcPort=50562):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-08-24 15:30:00,623 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
    [junit] 2009-08-24 15:30:00,626 INFO datanode.DataNode (DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads is 0
    [junit] 2009-08-24 15:30:00,626 INFO datanode.DataBlockScanner (DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
    [junit] 2009-08-24 15:30:00,626 INFO datanode.DataNode (DataNode.java:run(1305)) - DatanodeRegistration(127.0.0.1:55493, storageID=DS-434709537-67.195.138.9-55493-1251127799475, infoPort=47165, ipcPort=50562):Finishing DataNode in: FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build-fi/test/data/dfs/data/data3/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build-fi/test/data/dfs/data/data4/current'}
    [junit] 2009-08-24 15:30:00,626 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 50562
    [junit] 2009-08-24 15:30:00,626 INFO datanode.DataNode (DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads is 0
    [junit] Shutting down DataNode 0
    [junit] 2009-08-24 15:30:00,802 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 58723
    [junit] 2009-08-24 15:30:00,803 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 58723: exiting
    [junit] 2009-08-24 15:30:00,804 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 58723
    [junit] 2009-08-24 15:30:00,804 WARN datanode.DataNode (DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:51187, storageID=DS-1737465689-67.195.138.9-51187-1251127798848, infoPort=48789, ipcPort=58723):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-08-24 15:30:00,804 INFO datanode.DataNode (DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads is 1
    [junit] 2009-08-24 15:30:00,804 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
    [junit] 2009-08-24 15:30:00,805 INFO datanode.DataBlockScanner (DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
    [junit] 2009-08-24 15:30:00,805 INFO datanode.DataNode (DataNode.java:run(1305)) - DatanodeRegistration(127.0.0.1:51187, storageID=DS-1737465689-67.195.138.9-51187-1251127798848, infoPort=48789, ipcPort=58723):Finishing DataNode in: FSDataset{dirpath='http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/ws/trunk/build-fi/test/data/dfs/data/data1/current,/home/hudson/hudson-slave/workspace/Hadoop-Hdfs-trunk/trunk/build-fi/test/data/dfs/data/data2/current'}
    [junit] 2009-08-24 15:30:00,805 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 58723
    [junit] 2009-08-24 15:30:00,806 INFO datanode.DataNode (DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads is 0
    [junit] 2009-08-24 15:30:00,946 WARN namenode.DecommissionManager (DecommissionManager.java:run(67)) - Monitor interrupted: java.lang.InterruptedException: sleep interrupted
    [junit] 2009-08-24 15:30:00,946 INFO namenode.FSNamesystem (FSEditLog.java:printStatistics(884)) - Number of transactions: 5 Total time for transactions(ms): 0Number of transactions batched in Syncs: 0 Number of syncs: 2 SyncTimes(ms): 68 40
    [junit] 2009-08-24 15:30:00,946 WARN namenode.FSNamesystem (FSNamesystem.java:run(2077)) - ReplicationMonitor thread received InterruptedException.java.lang.InterruptedException: sleep interrupted
    [junit] 2009-08-24 15:30:00,958 INFO ipc.Server (Server.java:stop(1103)) - Stopping server on 39380
    [junit] 2009-08-24 15:30:00,959 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 0 on 39380: exiting
    [junit] 2009-08-24 15:30:00,959 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 1 on 39380: exiting
    [junit] 2009-08-24 15:30:00,959 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 2 on 39380: exiting
    [junit] 2009-08-24 15:30:00,959 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 9 on 39380: exiting
    [junit] 2009-08-24 15:30:00,959 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 6 on 39380: exiting
    [junit] 2009-08-24 15:30:00,959 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 7 on 39380: exiting
    [junit] 2009-08-24 15:30:00,959 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 5 on 39380: exiting
    [junit] 2009-08-24 15:30:00,959 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 3 on 39380: exiting
    [junit] 2009-08-24 15:30:00,959 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 8 on 39380: exiting
    [junit] 2009-08-24 15:30:00,960 INFO ipc.Server (Server.java:run(997)) - IPC Server handler 4 on 39380: exiting
    [junit] 2009-08-24 15:30:00,960 INFO ipc.Server (Server.java:run(539)) - Stopping IPC Server Responder
    [junit] 2009-08-24 15:30:00,960 INFO ipc.Server (Server.java:run(352)) - Stopping IPC Server listener on 39380
    [junit] Tests run: 7, Failures: 0, Errors: 0, Time elapsed: 73.905 sec

    checkfailure:

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

    Total time: 60 minutes 56 seconds
    Publishing Javadoc
    Recording test results
    Recording fingerprints
    Publishing Clover coverage report...

Related Discussions

Discussion Navigation
viewthread | post
Discussion Overview
grouphdfs-dev @
categorieshadoop
postedAug 21, '09 at 12:47p
activeAug 24, '09 at 4:33p
posts4
users1
websitehadoop.apache.org...
irc#hadoop

1 user in discussion

Apache Hudson Server: 4 posts

People

Translate

site design / logo © 2022 Grokbase