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