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

------------------------------------------
[...truncated 351784 lines...]
    [junit] 2009-08-09 12:39:59,468 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-09 12:39:59,468 INFO  common.Storage 
(DataStorage.java:recoverTransitionRead(123)) - Formatting ...
    [junit] 2009-08-09 12:39:59,718 INFO  datanode.DataNode 
(FSDataset.java:registerMBean(1417)) - Registered FSDatasetStatusMBean
    [junit] 2009-08-09 12:39:59,719 INFO  datanode.DataNode 
(DataNode.java:startDataNode(326)) - Opened info server at 52546
    [junit] 2009-08-09 12:39:59,719 INFO  datanode.DataNode 
(DataXceiverServer.java:<init>(74)) - Balancing bandwith is 1048576 bytes/s
    [junit] 2009-08-09 12:39:59,720 INFO  datanode.DirectoryScanner 
(DirectoryScanner.java:<init>(133)) - scan starts at 1249823953720 with 
interval 21600000
    [junit] 2009-08-09 12:39:59,721 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-09 12:39:59,721 INFO  http.HttpServer 
(HttpServer.java:start(430)) - listener.getLocalPort() returned 48158 
webServer.getConnectors()[0].getLocalPort() returned 48158
    [junit] 2009-08-09 12:39:59,721 INFO  http.HttpServer 
(HttpServer.java:start(463)) - Jetty bound to port 48158
    [junit] 2009-08-09 12:39:59,722 INFO  mortbay.log (?:invoke(?)) - 
jetty-6.1.14
    [junit] 2009-08-09 12:39:59,787 INFO  mortbay.log (?:invoke(?)) - Started 
selectchannelconnec...@localhost:48158
    [junit] 2009-08-09 12:39:59,788 INFO  jvm.JvmMetrics 
(JvmMetrics.java:init(66)) - Cannot initialize JVM Metrics with 
processName=DataNode, sessionId=null - already initialized
    [junit] 2009-08-09 12:39:59,789 INFO  metrics.RpcMetrics 
(RpcMetrics.java:<init>(58)) - Initializing RPC Metrics with hostName=DataNode, 
port=49960
    [junit] 2009-08-09 12:39:59,790 INFO  ipc.Server (Server.java:run(474)) - 
IPC Server Responder: starting
    [junit] 2009-08-09 12:39:59,790 INFO  datanode.DataNode 
(DataNode.java:startDataNode(404)) - dnRegistration = 
DatanodeRegistration(vesta.apache.org:52546, storageID=, infoPort=48158, 
ipcPort=49960)
    [junit] 2009-08-09 12:39:59,790 INFO  ipc.Server (Server.java:run(939)) - 
IPC Server handler 0 on 49960: starting
    [junit] 2009-08-09 12:39:59,790 INFO  ipc.Server (Server.java:run(313)) - 
IPC Server listener on 49960: starting
    [junit] 2009-08-09 12:39:59,791 INFO  hdfs.StateChange 
(FSNamesystem.java:registerDatanode(1774)) - BLOCK* 
NameSystem.registerDatanode: node registration from 127.0.0.1:52546 storage 
DS-431642151-67.195.138.9-52546-1249821599791
    [junit] 2009-08-09 12:39:59,792 INFO  net.NetworkTopology 
(NetworkTopology.java:add(327)) - Adding a new node: 
/default-rack/127.0.0.1:52546
    [junit] 2009-08-09 12:39:59,850 INFO  datanode.DataNode 
(DataNode.java:register(571)) - New storage id 
DS-431642151-67.195.138.9-52546-1249821599791 is assigned to data-node 
127.0.0.1:52546
    [junit] 2009-08-09 12:39:59,851 INFO  datanode.DataNode 
(DataNode.java:run(1258)) - DatanodeRegistration(127.0.0.1:52546, 
storageID=DS-431642151-67.195.138.9-52546-1249821599791, infoPort=48158, 
ipcPort=49960)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-09 12:39:59,851 INFO  datanode.DataNode 
(DataNode.java:offerService(739)) - using BLOCKREPORT_INTERVAL of 21600000msec 
Initial delay: 0msec
    [junit] 2009-08-09 12:39:59,860 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-09 12:39:59,860 INFO  common.Storage 
(DataStorage.java:recoverTransitionRead(123)) - Formatting ...
    [junit] 2009-08-09 12:39:59,891 INFO  datanode.DataNode 
(DataNode.java:blockReport(974)) - BlockReport of 0 blocks got processed in 1 
msecs
    [junit] 2009-08-09 12:39:59,891 INFO  datanode.DataNode 
(DataNode.java:offerService(782)) - Starting Periodic block scanner.
    [junit] 2009-08-09 12:40:00,022 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-09 12:40:00,022 INFO  common.Storage 
(DataStorage.java:recoverTransitionRead(123)) - Formatting ...
    [junit] 2009-08-09 12:40:00,288 INFO  datanode.DataNode 
(FSDataset.java:registerMBean(1417)) - Registered FSDatasetStatusMBean
    [junit] 2009-08-09 12:40:00,288 INFO  datanode.DataNode 
(DataNode.java:startDataNode(326)) - Opened info server at 36519
    [junit] 2009-08-09 12:40:00,289 INFO  datanode.DataNode 
(DataXceiverServer.java:<init>(74)) - Balancing bandwith is 1048576 bytes/s
    [junit] 2009-08-09 12:40:00,289 INFO  datanode.DirectoryScanner 
(DirectoryScanner.java:<init>(133)) - scan starts at 1249834820289 with 
interval 21600000
    [junit] 2009-08-09 12:40:00,290 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-09 12:40:00,291 INFO  http.HttpServer 
(HttpServer.java:start(430)) - listener.getLocalPort() returned 35828 
webServer.getConnectors()[0].getLocalPort() returned 35828
    [junit] 2009-08-09 12:40:00,291 INFO  http.HttpServer 
(HttpServer.java:start(463)) - Jetty bound to port 35828
    [junit] 2009-08-09 12:40:00,291 INFO  mortbay.log (?:invoke(?)) - 
jetty-6.1.14
    [junit] 2009-08-09 12:40:00,367 INFO  mortbay.log (?:invoke(?)) - Started 
selectchannelconnec...@localhost:35828
    [junit] 2009-08-09 12:40:00,368 INFO  jvm.JvmMetrics 
(JvmMetrics.java:init(66)) - Cannot initialize JVM Metrics with 
processName=DataNode, sessionId=null - already initialized
    [junit] 2009-08-09 12:40:00,369 INFO  metrics.RpcMetrics 
(RpcMetrics.java:<init>(58)) - Initializing RPC Metrics with hostName=DataNode, 
port=42704
    [junit] 2009-08-09 12:40:00,370 INFO  ipc.Server (Server.java:run(474)) - 
IPC Server Responder: starting
    [junit] 2009-08-09 12:40:00,370 INFO  ipc.Server (Server.java:run(939)) - 
IPC Server handler 0 on 42704: starting
    [junit] 2009-08-09 12:40:00,370 INFO  ipc.Server (Server.java:run(313)) - 
IPC Server listener on 42704: starting
    [junit] 2009-08-09 12:40:00,370 INFO  datanode.DataNode 
(DataNode.java:startDataNode(404)) - dnRegistration = 
DatanodeRegistration(vesta.apache.org:36519, storageID=, infoPort=35828, 
ipcPort=42704)
    [junit] 2009-08-09 12:40:00,372 INFO  hdfs.StateChange 
(FSNamesystem.java:registerDatanode(1774)) - BLOCK* 
NameSystem.registerDatanode: node registration from 127.0.0.1:36519 storage 
DS-307716393-67.195.138.9-36519-1249821600371
    [junit] 2009-08-09 12:40:00,372 INFO  net.NetworkTopology 
(NetworkTopology.java:add(327)) - Adding a new node: 
/default-rack/127.0.0.1:36519
    [junit] 2009-08-09 12:40:00,408 INFO  datanode.DataNode 
(DataNode.java:register(571)) - New storage id 
DS-307716393-67.195.138.9-36519-1249821600371 is assigned to data-node 
127.0.0.1:36519
    [junit] 2009-08-09 12:40:00,408 INFO  datanode.DataNode 
(DataNode.java:run(1258)) - DatanodeRegistration(127.0.0.1:36519, 
storageID=DS-307716393-67.195.138.9-36519-1249821600371, infoPort=35828, 
ipcPort=42704)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-09 12:40:00,408 INFO  datanode.DataNode 
(DataNode.java:offerService(739)) - using BLOCKREPORT_INTERVAL of 21600000msec 
Initial delay: 0msec
    [junit] 2009-08-09 12:40:00,444 INFO  datanode.DataNode 
(DataNode.java:blockReport(974)) - BlockReport of 0 blocks got processed in 1 
msecs
    [junit] 2009-08-09 12:40:00,444 INFO  datanode.DataNode 
(DataNode.java:offerService(782)) - Starting Periodic block scanner.
    [junit] 2009-08-09 12:40:00,504 INFO  FSNamesystem.audit 
(FSNamesystem.java:logAuditEvent(114)) - ugi=hudson,hudson ip=/127.0.0.1   
cmd=create      src=/testPipelineFi15/foo       dst=null        
perm=hudson:supergroup:rw-r--r--
    [junit] 2009-08-09 12:40:00,506 INFO  hdfs.StateChange 
(FSNamesystem.java:allocateBlock(1303)) - BLOCK* NameSystem.allocateBlock: 
/testPipelineFi15/foo. blk_-4004277172538634555_1001
    [junit] 2009-08-09 12:40:00,541 INFO  protocol.ClientProtocolAspects 
(ClientProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_protocol_ClientProtocolAspects$1$7076326d(32))
 - FI: addBlock Pipeline[127.0.0.1:52546, 127.0.0.1:48078, 127.0.0.1:36519]
    [junit] 2009-08-09 12:40:00,542 INFO  datanode.DataTransferProtocolAspects 
(DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$1$8f59fdd7(50))
 - FI: receiverOp WRITE_BLOCK, datanode=127.0.0.1:52546
    [junit] 2009-08-09 12:40:00,542 INFO  datanode.DataTransferProtocolAspects 
(DataTransferProtocolAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$3$3251489(70))
 - FI: receiverOpWriteBlock
    [junit] 2009-08-09 12:40:00,542 INFO  datanode.DataNode 
(DataXceiver.java:opWriteBlock(222)) - Receiving block 
blk_-4004277172538634555_1001 src: /127.0.0.1:38436 dest: /127.0.0.1:52546
    [junit] 2009-08-09 12:40:00,544 INFO  datanode.DataTransferProtocolAspects 
(DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$1$8f59fdd7(50))
 - FI: receiverOp WRITE_BLOCK, datanode=127.0.0.1:48078
    [junit] 2009-08-09 12:40:00,544 INFO  datanode.DataTransferProtocolAspects 
(DataTransferProtocolAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$3$3251489(70))
 - FI: receiverOpWriteBlock
    [junit] 2009-08-09 12:40:00,544 INFO  datanode.DataNode 
(DataXceiver.java:opWriteBlock(222)) - Receiving block 
blk_-4004277172538634555_1001 src: /127.0.0.1:42417 dest: /127.0.0.1:48078
    [junit] 2009-08-09 12:40:00,545 INFO  datanode.DataTransferProtocolAspects 
(DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$1$8f59fdd7(50))
 - FI: receiverOp WRITE_BLOCK, datanode=127.0.0.1:36519
    [junit] 2009-08-09 12:40:00,545 INFO  datanode.DataTransferProtocolAspects 
(DataTransferProtocolAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$3$3251489(70))
 - FI: receiverOpWriteBlock
    [junit] 2009-08-09 12:40:00,546 INFO  datanode.DataNode 
(DataXceiver.java:opWriteBlock(222)) - Receiving block 
blk_-4004277172538634555_1001 src: /127.0.0.1:60263 dest: /127.0.0.1:36519
    [junit] 2009-08-09 12:40:00,546 INFO  datanode.DataTransferProtocolAspects 
(DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$2$d4f6605f(60))
 - FI: statusRead SUCCESS, datanode=127.0.0.1:48078
    [junit] 2009-08-09 12:40:00,547 INFO  datanode.DataTransferProtocolAspects 
(DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$2$d4f6605f(60))
 - FI: statusRead SUCCESS, datanode=127.0.0.1:52546
    [junit] 2009-08-09 12:40:00,548 INFO  datanode.BlockReceiverAspects 
(BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(46))
 - FI: callReceivePacket
    [junit] 2009-08-09 12:40:00,548 INFO  datanode.BlockReceiverAspects 
(BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(46))
 - FI: callReceivePacket
    [junit] 2009-08-09 12:40:00,548 INFO  datanode.BlockReceiverAspects 
(BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(46))
 - FI: callReceivePacket
    [junit] 2009-08-09 12:40:00,548 INFO  fi.FiTestUtil 
(DataTransferTestUtil.java:run(158)) - FI: testPipelineFi15, index=1, 
datanode=127.0.0.1:48078
    [junit] 2009-08-09 12:40:00,548 INFO  datanode.BlockReceiverAspects 
(BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(46))
 - FI: callReceivePacket
    [junit] 2009-08-09 12:40:00,549 INFO  datanode.DataNode 
(BlockReceiver.java:handleMirrorOutError(185)) - 
DatanodeRegistration(127.0.0.1:48078, 
storageID=DS-36780648-67.195.138.9-48078-1249821599228, infoPort=42944, 
ipcPort=58112):Exception writing block blk_-4004277172538634555_1001 to mirror 
127.0.0.1:36519
    [junit] org.apache.hadoop.util.DiskChecker$DiskOutOfSpaceException: FI: 
testPipelineFi15, index=1, datanode=127.0.0.1:48078
    [junit]     at 
org.apache.hadoop.fi.DataTransferTestUtil$DoosAction.run(DataTransferTestUtil.java:159)
    [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:47)
    [junit]     at 
org.apache.hadoop.hdfs.server.datanode.BlockReceiver.receivePacket(BlockReceiver.java:408)
    [junit]     at 
org.apache.hadoop.hdfs.server.datanode.BlockReceiver.receiveBlock(BlockReceiver.java:532)
    [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] 
    [junit] 2009-08-09 12:40:00,549 INFO  datanode.DataNode 
(BlockReceiver.java:receiveBlock(566)) - Exception in receiveBlock for block 
blk_-4004277172538634555_1001 
org.apache.hadoop.util.DiskChecker$DiskOutOfSpaceException: FI: 
testPipelineFi15, index=1, datanode=127.0.0.1:48078
    [junit] 2009-08-09 12:40:00,549 INFO  datanode.DataNode 
(BlockReceiver.java:run(907)) - PacketResponder blk_-4004277172538634555_1001 1 
Exception java.io.InterruptedIOException: Interruped while waiting for IO on 
channel java.nio.channels.SocketChannel[connected local=/127.0.0.1:60263 
remote=/127.0.0.1:36519]. 59998 millis timeout left.
    [junit]     at 
org.apache.hadoop.net.SocketIOWithTimeout$SelectorPool.select(SocketIOWithTimeout.java:349)
    [junit]     at 
org.apache.hadoop.net.SocketIOWithTimeout.doIO(SocketIOWithTimeout.java:157)
    [junit]     at 
org.apache.hadoop.net.SocketInputStream.read(SocketInputStream.java:155)
    [junit]     at 
org.apache.hadoop.net.SocketInputStream.read(SocketInputStream.java:128)
    [junit]     at java.io.DataInputStream.readFully(DataInputStream.java:178)
    [junit]     at java.io.DataInputStream.readLong(DataInputStream.java:399)
    [junit]     at 
org.apache.hadoop.hdfs.server.datanode.BlockReceiver$PacketResponder.run(BlockReceiver.java:869)
    [junit]     at java.lang.Thread.run(Thread.java:619)
    [junit] 
    [junit] 2009-08-09 12:40:00,549 INFO  datanode.DataNode 
(BlockReceiver.java:run(922)) - PacketResponder blk_-4004277172538634555_1001 1 
: Thread is interrupted.
    [junit] 2009-08-09 12:40:00,549 INFO  datanode.DataNode 
(BlockReceiver.java:run(1009)) - PacketResponder 1 for block 
blk_-4004277172538634555_1001 terminating
    [junit] 2009-08-09 12:40:00,549 INFO  datanode.DataNode 
(DataXceiver.java:opWriteBlock(358)) - writeBlock blk_-4004277172538634555_1001 
received exception org.apache.hadoop.util.DiskChecker$DiskOutOfSpaceException: 
FI: testPipelineFi15, index=1, datanode=127.0.0.1:48078
    [junit] 2009-08-09 12:40:00,550 ERROR datanode.DataNode 
(DataXceiver.java:run(112)) - DatanodeRegistration(127.0.0.1:48078, 
storageID=DS-36780648-67.195.138.9-48078-1249821599228, infoPort=42944, 
ipcPort=58112):DataXceiver
    [junit] org.apache.hadoop.util.DiskChecker$DiskOutOfSpaceException: FI: 
testPipelineFi15, index=1, datanode=127.0.0.1:48078
    [junit]     at 
org.apache.hadoop.fi.DataTransferTestUtil$DoosAction.run(DataTransferTestUtil.java:159)
    [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:47)
    [junit]     at 
org.apache.hadoop.hdfs.server.datanode.BlockReceiver.receivePacket(BlockReceiver.java:408)
    [junit]     at 
org.apache.hadoop.hdfs.server.datanode.BlockReceiver.receiveBlock(BlockReceiver.java:532)
    [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-09 12:40:00,550 INFO  datanode.DataNode 
(BlockReceiver.java:run(907)) - PacketResponder blk_-4004277172538634555_1001 2 
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:869)
    [junit]     at java.lang.Thread.run(Thread.java:619)
    [junit] 
    [junit] 2009-08-09 12:40:00,550 INFO  datanode.DataNode 
(BlockReceiver.java:receiveBlock(566)) - Exception in receiveBlock for block 
blk_-4004277172538634555_1001 java.io.EOFException: while trying to read 65557 
bytes
    [junit] 2009-08-09 12:40:00,551 INFO  datanode.DataNode 
(BlockReceiver.java:lastDataNodeRun(779)) - PacketResponder 0 for block 
blk_-4004277172538634555_1001 Interrupted.
    [junit] 2009-08-09 12:40:00,551 WARN  hdfs.DFSClient 
(DFSClient.java:run(2593)) - DFSOutputStream ResponseProcessor exception  for 
block blk_-4004277172538634555_1001java.io.IOException: Bad response ERROR for 
block blk_-4004277172538634555_1001 from datanode 127.0.0.1:48078
    [junit]     at 
org.apache.hadoop.hdfs.DFSClient$DFSOutputStream$DataStreamer$ResponseProcessor.run(DFSClient.java:2573)
    [junit] 
    [junit] 2009-08-09 12:40:00,551 INFO  datanode.DataNode 
(BlockReceiver.java:run(1009)) - PacketResponder 2 for block 
blk_-4004277172538634555_1001 terminating
    [junit] 2009-08-09 12:40:00,551 INFO  datanode.DataNode 
(BlockReceiver.java:lastDataNodeRun(843)) - PacketResponder 0 for block 
blk_-4004277172538634555_1001 terminating
    [junit] 2009-08-09 12:40:00,551 WARN  hdfs.DFSClient 
(DFSClient.java:processDatanodeError(2622)) - Error Recovery for block 
blk_-4004277172538634555_1001 bad datanode[1] 127.0.0.1:48078
    [junit] 2009-08-09 12:40:00,552 INFO  datanode.DataNode 
(DataXceiver.java:opWriteBlock(358)) - writeBlock blk_-4004277172538634555_1001 
received exception java.io.EOFException: while trying to read 65557 bytes
    [junit] 2009-08-09 12:40:00,552 WARN  hdfs.DFSClient 
(DFSClient.java:processDatanodeError(2666)) - Error Recovery for block 
blk_-4004277172538634555_1001 in pipeline 127.0.0.1:52546, 127.0.0.1:48078, 
127.0.0.1:36519: bad datanode 127.0.0.1:48078
    [junit] 2009-08-09 12:40:00,552 ERROR datanode.DataNode 
(DataXceiver.java:run(112)) - DatanodeRegistration(127.0.0.1:36519, 
storageID=DS-307716393-67.195.138.9-36519-1249821600371, infoPort=35828, 
ipcPort=42704):DataXceiver
    [junit] java.io.EOFException: while trying to read 65557 bytes
    [junit]     at 
org.apache.hadoop.hdfs.server.datanode.BlockReceiver.readToBuf(BlockReceiver.java:271)
    [junit]     at 
org.apache.hadoop.hdfs.server.datanode.BlockReceiver.readNextPacket(BlockReceiver.java:315)
    [junit]     at 
org.apache.hadoop.hdfs.server.datanode.BlockReceiver.receivePacket(BlockReceiver.java:379)
    [junit]     at 
org.apache.hadoop.hdfs.server.datanode.BlockReceiver.receiveBlock(BlockReceiver.java:532)
    [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-09 12:40:00,554 INFO  datanode.DataNode 
(DataNode.java:logRecoverBlock(1700)) - Client calls 
recoverBlock(block=blk_-4004277172538634555_1001, targets=[127.0.0.1:52546, 
127.0.0.1:36519])
    [junit] 2009-08-09 12:40:00,558 INFO  datanode.DataNode 
(DataNode.java:updateBlock(1510)) - 
oldblock=blk_-4004277172538634555_1001(length=1), 
newblock=blk_-4004277172538634555_1002(length=0), datanode=127.0.0.1:52546
    [junit] 2009-08-09 12:40:00,560 INFO  datanode.DataNode 
(DataNode.java:updateBlock(1510)) - 
oldblock=blk_-4004277172538634555_1001(length=0), 
newblock=blk_-4004277172538634555_1002(length=0), datanode=127.0.0.1:36519
    [junit] 2009-08-09 12:40:00,560 INFO  namenode.FSNamesystem 
(FSNamesystem.java:commitBlockSynchronization(1613)) - 
commitBlockSynchronization(lastblock=blk_-4004277172538634555_1001, 
newgenerationstamp=1002, newlength=0, newtargets=[127.0.0.1:52546, 
127.0.0.1:36519], closeFile=false, deleteBlock=false)
    [junit] 2009-08-09 12:40:00,561 INFO  namenode.FSNamesystem 
(FSNamesystem.java:commitBlockSynchronization(1677)) - 
commitBlockSynchronization(blk_-4004277172538634555_1002) successful
    [junit] 2009-08-09 12:40:00,562 INFO  datanode.DataTransferProtocolAspects 
(DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$1$8f59fdd7(50))
 - FI: receiverOp WRITE_BLOCK, datanode=127.0.0.1:52546
    [junit] 2009-08-09 12:40:00,562 INFO  datanode.DataTransferProtocolAspects 
(DataTransferProtocolAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$3$3251489(70))
 - FI: receiverOpWriteBlock
    [junit] 2009-08-09 12:40:00,562 INFO  datanode.DataNode 
(DataXceiver.java:opWriteBlock(222)) - Receiving block 
blk_-4004277172538634555_1002 src: /127.0.0.1:38441 dest: /127.0.0.1:52546
    [junit] 2009-08-09 12:40:00,563 INFO  datanode.DataNode 
(FSDataset.java:writeToBlock(1011)) - Reopen already-open Block for append 
blk_-4004277172538634555_1002
    [junit] 2009-08-09 12:40:00,563 INFO  datanode.DataTransferProtocolAspects 
(DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$1$8f59fdd7(50))
 - FI: receiverOp WRITE_BLOCK, datanode=127.0.0.1:36519
    [junit] 2009-08-09 12:40:00,563 INFO  datanode.DataTransferProtocolAspects 
(DataTransferProtocolAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$3$3251489(70))
 - FI: receiverOpWriteBlock
    [junit] 2009-08-09 12:40:00,564 INFO  datanode.DataNode 
(DataXceiver.java:opWriteBlock(222)) - Receiving block 
blk_-4004277172538634555_1002 src: /127.0.0.1:60267 dest: /127.0.0.1:36519
    [junit] 2009-08-09 12:40:00,564 INFO  datanode.DataNode 
(FSDataset.java:writeToBlock(1011)) - Reopen already-open Block for append 
blk_-4004277172538634555_1002
    [junit] 2009-08-09 12:40:00,564 INFO  datanode.DataTransferProtocolAspects 
(DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$2$d4f6605f(60))
 - FI: statusRead SUCCESS, datanode=127.0.0.1:52546
    [junit] 2009-08-09 12:40:00,565 INFO  datanode.BlockReceiverAspects 
(BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(46))
 - FI: callReceivePacket
    [junit] 2009-08-09 12:40:00,565 INFO  datanode.BlockReceiverAspects 
(BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(46))
 - FI: callReceivePacket
    [junit] 2009-08-09 12:40:00,565 INFO  datanode.BlockReceiverAspects 
(BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(46))
 - FI: callReceivePacket
    [junit] 2009-08-09 12:40:00,566 INFO  datanode.BlockReceiverAspects 
(BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(46))
 - FI: callReceivePacket
    [junit] 2009-08-09 12:40:00,566 INFO  datanode.BlockReceiverAspects 
(BlockReceiverAspects.aj:ajc$before$org_apache_hadoop_hdfs_server_datanode_BlockReceiverAspects$1$4c211928(46))
 - FI: callReceivePacket
    [junit] 2009-08-09 12:40:00,567 INFO  DataNode.clienttrace 
(BlockReceiver.java:lastDataNodeRun(819)) - src: /127.0.0.1:60267, dest: 
/127.0.0.1:36519, bytes: 1, op: HDFS_WRITE, cliID: DFSClient_-1303102380, 
offset: 0, srvID: DS-307716393-67.195.138.9-36519-1249821600371, blockid: 
blk_-4004277172538634555_1002, duration: 2049711
    [junit] 2009-08-09 12:40:00,567 INFO  datanode.DataNode 
(BlockReceiver.java:lastDataNodeRun(843)) - PacketResponder 0 for block 
blk_-4004277172538634555_1002 terminating
    [junit] 2009-08-09 12:40:00,568 INFO  hdfs.StateChange 
(BlockManager.java:addStoredBlock(950)) - BLOCK* NameSystem.addStoredBlock: 
blockMap updated: 127.0.0.1:36519 is added to blk_-4004277172538634555_1002 
size 1
    [junit] 2009-08-09 12:40:00,568 INFO  hdfs.StateChange 
(BlockManager.java:addStoredBlock(950)) - BLOCK* NameSystem.addStoredBlock: 
blockMap updated: 127.0.0.1:52546 is added to blk_-4004277172538634555_1002 
size 1
    [junit] 2009-08-09 12:40:00,569 INFO  DataNode.clienttrace 
(BlockReceiver.java:run(945)) - src: /127.0.0.1:38441, dest: /127.0.0.1:52546, 
bytes: 1, op: HDFS_WRITE, cliID: DFSClient_-1303102380, offset: 0, srvID: 
DS-431642151-67.195.138.9-52546-1249821599791, blockid: 
blk_-4004277172538634555_1002, duration: 2646397
    [junit] 2009-08-09 12:40:00,569 INFO  datanode.DataNode 
(BlockReceiver.java:run(1009)) - PacketResponder 1 for block 
blk_-4004277172538634555_1002 terminating
    [junit] 2009-08-09 12:40:00,570 INFO  hdfs.StateChange 
(FSNamesystem.java:completeFileInternal(1269)) - DIR* NameSystem.completeFile: 
file /testPipelineFi15/foo is closed by DFSClient_-1303102380
    [junit] 2009-08-09 12:40:00,585 INFO  FSNamesystem.audit 
(FSNamesystem.java:logAuditEvent(114)) - ugi=hudson,hudson ip=/127.0.0.1   
cmd=open        src=/testPipelineFi15/foo       dst=null        perm=null
    [junit] 2009-08-09 12:40:00,586 INFO  datanode.DataTransferProtocolAspects 
(DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$1$8f59fdd7(50))
 - FI: receiverOp READ_BLOCK, datanode=127.0.0.1:36519
    [junit] Shutting down the Mini HDFS Cluster
    [junit] Shutting down DataNode 2
    [junit] 2009-08-09 12:40:00,587 INFO  DataNode.clienttrace 
(BlockSender.java:sendBlock(417)) - src: /127.0.0.1:36519, dest: 
/127.0.0.1:60268, bytes: 5, op: HDFS_READ, cliID: DFSClient_-1303102380, 
offset: 0, srvID: DS-307716393-67.195.138.9-36519-1249821600371, blockid: 
blk_-4004277172538634555_1002, duration: 232839
    [junit] 2009-08-09 12:40:00,588 INFO  datanode.DataTransferProtocolAspects 
(DataTransferProtocolAspects.aj:ajc$afterReturning$org_apache_hadoop_hdfs_server_datanode_DataTransferProtocolAspects$2$d4f6605f(60))
 - FI: statusRead CHECKSUM_OK, datanode=127.0.0.1:36519
    [junit] 2009-08-09 12:40:00,690 INFO  ipc.Server (Server.java:stop(1103)) - 
Stopping server on 42704
    [junit] 2009-08-09 12:40:00,690 INFO  ipc.Server (Server.java:run(997)) - 
IPC Server handler 0 on 42704: exiting
    [junit] 2009-08-09 12:40:00,690 INFO  ipc.Server (Server.java:run(352)) - 
Stopping IPC Server listener on 42704
    [junit] 2009-08-09 12:40:00,691 INFO  ipc.Server (Server.java:run(539)) - 
Stopping IPC Server Responder
    [junit] 2009-08-09 12:40:00,691 WARN  datanode.DataNode 
(DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:36519, 
storageID=DS-307716393-67.195.138.9-36519-1249821600371, infoPort=35828, 
ipcPort=42704):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-09 12:40:00,691 INFO  datanode.DataNode 
(DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads 
is 0
    [junit] 2009-08-09 12:40:00,692 INFO  datanode.DataBlockScanner 
(DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
    [junit] 2009-08-09 12:40:00,692 INFO  datanode.DataNode 
(DataNode.java:run(1278)) - DatanodeRegistration(127.0.0.1:36519, 
storageID=DS-307716393-67.195.138.9-36519-1249821600371, infoPort=35828, 
ipcPort=42704):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-09 12:40:00,692 INFO  ipc.Server (Server.java:stop(1103)) - 
Stopping server on 42704
    [junit] 2009-08-09 12:40:00,693 INFO  datanode.DataNode 
(DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads 
is 0
    [junit] Shutting down DataNode 1
    [junit] 2009-08-09 12:40:00,795 INFO  ipc.Server (Server.java:stop(1103)) - 
Stopping server on 49960
    [junit] 2009-08-09 12:40:00,795 INFO  ipc.Server (Server.java:run(997)) - 
IPC Server handler 0 on 49960: exiting
    [junit] 2009-08-09 12:40:00,796 INFO  ipc.Server (Server.java:run(352)) - 
Stopping IPC Server listener on 49960
    [junit] 2009-08-09 12:40:00,796 WARN  datanode.DataNode 
(DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:52546, 
storageID=DS-431642151-67.195.138.9-52546-1249821599791, infoPort=48158, 
ipcPort=49960):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-09 12:40:00,796 INFO  ipc.Server (Server.java:run(539)) - 
Stopping IPC Server Responder
    [junit] 2009-08-09 12:40:00,796 INFO  datanode.DataNode 
(DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads 
is 1
    [junit] 2009-08-09 12:40:00,797 INFO  datanode.DataBlockScanner 
(DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
    [junit] 2009-08-09 12:40:00,797 INFO  datanode.DataNode 
(DataNode.java:run(1278)) - DatanodeRegistration(127.0.0.1:52546, 
storageID=DS-431642151-67.195.138.9-52546-1249821599791, infoPort=48158, 
ipcPort=49960):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-09 12:40:00,797 INFO  ipc.Server (Server.java:stop(1103)) - 
Stopping server on 49960
    [junit] 2009-08-09 12:40:00,797 INFO  datanode.DataNode 
(DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads 
is 0
    [junit] Shutting down DataNode 0
    [junit] 2009-08-09 12:40:00,899 INFO  ipc.Server (Server.java:stop(1103)) - 
Stopping server on 58112
    [junit] 2009-08-09 12:40:00,899 INFO  ipc.Server (Server.java:run(997)) - 
IPC Server handler 0 on 58112: exiting
    [junit] 2009-08-09 12:40:00,900 INFO  ipc.Server (Server.java:run(352)) - 
Stopping IPC Server listener on 58112
    [junit] 2009-08-09 12:40:00,900 INFO  datanode.DataNode 
(DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads 
is 1
    [junit] 2009-08-09 12:40:00,900 WARN  datanode.DataNode 
(DataXceiverServer.java:run(137)) - DatanodeRegistration(127.0.0.1:48078, 
storageID=DS-36780648-67.195.138.9-48078-1249821599228, infoPort=42944, 
ipcPort=58112):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-09 12:40:00,900 INFO  ipc.Server (Server.java:run(539)) - 
Stopping IPC Server Responder
    [junit] 2009-08-09 12:40:00,902 INFO  datanode.DataNode 
(DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads 
is 0
    [junit] 2009-08-09 12:40:00,903 INFO  datanode.DataBlockScanner 
(DataBlockScanner.java:run(616)) - Exiting DataBlockScanner thread.
    [junit] 2009-08-09 12:40:00,903 INFO  datanode.DataNode 
(DataNode.java:run(1278)) - DatanodeRegistration(127.0.0.1:48078, 
storageID=DS-36780648-67.195.138.9-48078-1249821599228, infoPort=42944, 
ipcPort=58112):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-09 12:40:00,903 INFO  ipc.Server (Server.java:stop(1103)) - 
Stopping server on 58112
    [junit] 2009-08-09 12:40:00,904 INFO  datanode.DataNode 
(DataNode.java:shutdown(643)) - Waiting for threadgroup to exit, active threads 
is 0
    [junit] 2009-08-09 12:40:01,005 WARN  namenode.DecommissionManager 
(DecommissionManager.java:run(67)) - Monitor interrupted: 
java.lang.InterruptedException: sleep interrupted
    [junit] 2009-08-09 12:40:01,005 WARN  namenode.FSNamesystem 
(FSNamesystem.java:run(2077)) - ReplicationMonitor thread received 
InterruptedException.java.lang.InterruptedException: sleep interrupted
    [junit] 2009-08-09 12:40:01,005 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): 49 32 
    [junit] 2009-08-09 12:40:01,015 INFO  ipc.Server (Server.java:stop(1103)) - 
Stopping server on 41708
    [junit] 2009-08-09 12:40:01,015 INFO  ipc.Server (Server.java:run(997)) - 
IPC Server handler 0 on 41708: exiting
    [junit] 2009-08-09 12:40:01,015 INFO  ipc.Server (Server.java:run(997)) - 
IPC Server handler 8 on 41708: exiting
    [junit] 2009-08-09 12:40:01,015 INFO  ipc.Server (Server.java:run(997)) - 
IPC Server handler 7 on 41708: exiting
    [junit] 2009-08-09 12:40:01,016 INFO  ipc.Server (Server.java:run(997)) - 
IPC Server handler 6 on 41708: exiting
    [junit] 2009-08-09 12:40:01,015 INFO  ipc.Server (Server.java:run(997)) - 
IPC Server handler 2 on 41708: exiting
    [junit] 2009-08-09 12:40:01,015 INFO  ipc.Server (Server.java:run(539)) - 
Stopping IPC Server Responder
    [junit] 2009-08-09 12:40:01,015 INFO  ipc.Server (Server.java:run(997)) - 
IPC Server handler 1 on 41708: exiting
    [junit] 2009-08-09 12:40:01,015 INFO  ipc.Server (Server.java:run(997)) - 
IPC Server handler 5 on 41708: exiting
    [junit] 2009-08-09 12:40:01,015 INFO  ipc.Server (Server.java:run(997)) - 
IPC Server handler 4 on 41708: exiting
    [junit] 2009-08-09 12:40:01,016 INFO  ipc.Server (Server.java:run(997)) - 
IPC Server handler 9 on 41708: exiting
    [junit] 2009-08-09 12:40:01,016 INFO  ipc.Server (Server.java:run(997)) - 
IPC Server handler 3 on 41708: exiting
    [junit] 2009-08-09 12:40:01,016 INFO  ipc.Server (Server.java:run(352)) - 
Stopping IPC Server listener on 41708
    [junit] Tests run: 4, Failures: 0, Errors: 0, Time elapsed: 43.435 sec

checkfailure:

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

Total time: 66 minutes 2 seconds
Publishing Javadoc
Recording test results
Recording fingerprints
Publishing Clover coverage report...

Reply via email to