Dmitry Bugaychenko created HDFS-7453:
----------------------------------------
Summary: Namenode does not recognize block is missing on a datanode
Key: HDFS-7453
URL: https://issues.apache.org/jira/browse/HDFS-7453
Project: Hadoop HDFS
Issue Type: Bug
Components: namenode
Affects Versions: 2.4.1
Reporter: Dmitry Bugaychenko
Priority: Critical
We got a severe datalose due to the fact that namenode didn't recognized block
it thinks exist are not actually exist on the datanodes. The senario is
something as follows:
# A disk fails on one of the datanodes
# The datanode is forced to decommiss and shut down
# The disk is replaced and datanode is back again
# fsck shows everything is fine
# Repeat 1-4 for few weeks
# Restart the namenode
# It suddenly sees tens of thousands under-replicated blocks and hundreds
missing blocks
During the next disk failure we analysed situation a bit more and found
particular block on particular datanode that is missing: there is no file for
block and if we try to read it, we got
{code}
java.io.IOException: Got error for OP_READ_BLOCK, self=/XXX:33817,
remote=XXX/X.X.X.X:50010, for file
XXX/X.X.X.X:50010:BP-879324367-YYY-1404837025894:1083356878, for pool
BP-879324367-YYY-1404837025894 block 1083356878_9644290
{code}
We restarted the datanode and in the log we can see that it did scan all the
directories and send the report to namenode:
{code}
2014-11-27 17:06:34,174 INFO [DataNode: [[[DISK]file:/mnt/hadoop/0/dfs/data/,
[DISK]file:/mnt/hadoop/1/dfs/data/, [DISK]file:/mnt/hadoop/2/dfs/data/]]
heartbeating to /YYY:8020] FsDatasetImpl - Adding block pool
BP-879324367-YYY-1404837025894
2014-11-27 17:06:34,175 INFO [Thread-41] FsDatasetImpl - Scanning block pool
BP-879324367-YYY-1404837025894 on volume /mnt/hadoop/0/dfs/data/current...
2014-11-27 17:06:34,176 INFO [Thread-43] FsDatasetImpl - Scanning block pool
BP-879324367-YYY-1404837025894 on volume /mnt/hadoop/2/dfs/data/current...
2014-11-27 17:06:34,176 INFO [Thread-42] FsDatasetImpl - Scanning block pool
BP-879324367-YYY-1404837025894 on volume /mnt/hadoop/1/dfs/data/current...
2014-11-27 17:06:34,279 INFO [Thread-42] FsDatasetImpl - Cached dfsUsed found
for /mnt/hadoop/1/dfs/data/current/BP-879324367-YYY-1404837025894/current:
62677866794
2014-11-27 17:06:34,282 INFO [Thread-42] FsDatasetImpl - Time taken to scan
block pool BP-879324367-YYY-1404837025894 on /mnt/hadoop/1/dfs/data/current:
105ms
2014-11-27 17:06:34,744 INFO [Thread-41] FsDatasetImpl - Cached dfsUsed found
for /mnt/hadoop/0/dfs/data/current/BP-879324367-YYY-1404837025894/current:
2465590681232
2014-11-27 17:06:34,744 INFO [Thread-41] FsDatasetImpl - Time taken to scan
block pool BP-879324367-YYY-1404837025894 on /mnt/hadoop/0/dfs/data/current:
568ms
2014-11-27 17:06:34,856 INFO [Thread-43] FsDatasetImpl - Cached dfsUsed found
for /mnt/hadoop/2/dfs/data/current/BP-879324367-YYY-1404837025894/current:
2475580099468
2014-11-27 17:06:34,857 INFO [Thread-43] FsDatasetImpl - Time taken to scan
block pool BP-879324367-YYY-1404837025894 on /mnt/hadoop/2/dfs/data/current:
680ms
2014-11-27 17:06:34,857 INFO [DataNode: [[[DISK]file:/mnt/hadoop/0/dfs/data/,
[DISK]file:/mnt/hadoop/1/dfs/data/, [DISK]file:/mnt/hadoop/2/dfs/data/]]
heartbeating to /YYY:8020]
2014-11-27 17:06:34,858 INFO [Thread-44] FsDatasetImpl - Adding replicas to
map for block pool BP-879324367-YYY-1404837025894 on volume
/mnt/hadoop/0/dfs/data/current...
2014-11-27 17:06:34,890 INFO [Thread-46] FsDatasetImpl - Adding replicas to
map for block pool BP-879324367-YYY-1404837025894 on volume
/mnt/hadoop/2/dfs/data/current...
2014-11-27 17:06:34,890 INFO [Thread-45] FsDatasetImpl - Adding replicas to
map for block pool BP-879324367-YYY-1404837025894 on volume
/mnt/hadoop/1/dfs/data/current...
2014-11-27 17:06:34,961 INFO [Thread-45] FsDatasetImpl - Time to add replicas
to map for block pool BP-879324367-YYY-1404837025894 on volume
/mnt/hadoop/1/dfs/data/current: 70ms
2014-11-27 17:06:36,083 INFO [Thread-44] FsDatasetImpl - Time to add replicas
to map for block pool BP-879324367-YYY-1404837025894 on volume
/mnt/hadoop/0/dfs/data/current: 1193ms
2014-11-27 17:06:36,162 INFO [Thread-46] FsDatasetImpl - Time to add replicas
to map for block pool BP-879324367-YYY-1404837025894 on volume
/mnt/hadoop/2/dfs/data/current: 1271ms
2014-11-27 17:06:36,162 INFO [DataNode: [[[DISK]file:/mnt/hadoop/0/dfs/data/,
[DISK]file:/mnt/hadoop/1/dfs/data/, [DISK]file:/mnt/hadoop/2/dfs/data/]]
heartbeating to /YYY:8020] FsDatasetImpl - Total time to add all replicas to
map: 1304ms
2014-11-27 17:06:36,167 INFO [DataNode: [[[DISK]file:/mnt/hadoop/0/dfs/data/,
[DISK]file:/mnt/hadoop/1/dfs/data/, [DISK]file:/mnt/hadoop/2/dfs/data/]]
heartbeating to /YYY:8020] DataNode - Block pool BP-879324367-YYY-1404837025894
(Datanode Uuid null) service to /YYY:8020 beginning handshake with NN
2014-11-27 17:06:36,167 INFO [DataNode: [[[DISK]file:/mnt/hadoop/0/dfs/data/,
[DISK]file:/mnt/hadoop/1/dfs/data/, [DISK]file:/mnt/hadoop/2/dfs/data/]]
heartbeating to /XXX:8020] DataNode - Block pool BP-879324367-YYY-1404837025894
(Datanode Uuid null) service to /XXX:8020 beginning handshake with NN
2014-11-27 17:06:36,185 INFO [DataNode: [[[DISK]file:/mnt/hadoop/0/dfs/data/,
[DISK]file:/mnt/hadoop/1/dfs/data/, [DISK]file:/mnt/hadoop/2/dfs/data/]]
heartbeating to /YYY:8020] DataNode - Block pool Block pool
BP-879324367-YYY-1404837025894 (Datanode Uuid null) service to /YYY:8020
successfully registered with NN
2014-11-27 17:06:36,185 INFO [DataNode: [[[DISK]file:/mnt/hadoop/0/dfs/data/,
[DISK]file:/mnt/hadoop/1/dfs/data/, [DISK]file:/mnt/hadoop/2/dfs/data/]]
heartbeating to /XXX:8020] DataNode - Block pool Block pool
BP-879324367-YYY-1404837025894 (Datanode Uuid null) service to /XXX:8020
successfully registered with NN
2014-11-27 17:06:36,186 INFO [DataNode: [[[DISK]file:/mnt/hadoop/0/dfs/data/,
[DISK]file:/mnt/hadoop/1/dfs/data/, [DISK]file:/mnt/hadoop/2/dfs/data/]]
heartbeating to /YYY:8020] DataNode - For namenode /YYY:8020 using
DELETEREPORT_INTERVAL of 300000 msec BLOCKREPORT_INTERVAL of 21600000msec
CACHEREPORT_INTERVAL of 10000msec Initial delay: 0msec; heartBeatInterval=3000
2014-11-27 17:06:36,186 INFO [DataNode: [[[DISK]file:/mnt/hadoop/0/dfs/data/,
[DISK]file:/mnt/hadoop/1/dfs/data/, [DISK]file:/mnt/hadoop/2/dfs/data/]]
heartbeating to /XXX:8020] DataNode - For namenode /XXX:8020 using
DELETEREPORT_INTERVAL of 300000 msec BLOCKREPORT_INTERVAL of 21600000msec
CACHEREPORT_INTERVAL of 10000msec Initial delay: 0msec; heartBeatInterval=3000
2014-11-27 17:06:36,264 INFO [DataNode: [[[DISK]file:/mnt/hadoop/0/dfs/data/,
[DISK]file:/mnt/hadoop/1/dfs/data/, [DISK]file:/mnt/hadoop/2/dfs/data/]]
heartbeating to /YYY:8020] DataNode - Namenode Block pool
BP-879324367-YYY-1404837025894 (Datanode Uuid
91e8deeb-7030-4e7b-af14-a3f35cf65bd2) service to /YYY:8020 trying to claim
ACTIVE state with txid=114828921
2014-11-27 17:06:36,265 INFO [DataNode: [[[DISK]file:/mnt/hadoop/0/dfs/data/,
[DISK]file:/mnt/hadoop/1/dfs/data/, [DISK]file:/mnt/hadoop/2/dfs/data/]]
heartbeating to /YYY:8020] DataNode - Acknowledging ACTIVE Namenode Block pool
BP-879324367-YYY-1404837025894 (Datanode Uuid
91e8deeb-7030-4e7b-af14-a3f35cf65bd2) service to /YYY:8020
2014-11-27 17:06:36,511 INFO [DataNode: [[[DISK]file:/mnt/hadoop/0/dfs/data/,
[DISK]file:/mnt/hadoop/1/dfs/data/, [DISK]file:/mnt/hadoop/2/dfs/data/]]
heartbeating to /XXX:8020] DataNode - Sent 1 blockreports 49708 blocks total.
Took 72 msec to generate and 174 msecs for RPC and NN processing. Got back
commands none
2014-11-27 17:06:36,511 INFO [DataNode: [[[DISK]file:/mnt/hadoop/0/dfs/data/,
[DISK]file:/mnt/hadoop/1/dfs/data/, [DISK]file:/mnt/hadoop/2/dfs/data/]]
heartbeating to /YYY:8020] DataNode - Sent 1 blockreports 49708 blocks total.
Took 76 msec to generate and 170 msecs for RPC and NN processing. Got back
commands org.apache.hadoop.hdfs.server.protocol.FinalizeCommand@464c42e6
2014-11-27 17:06:36,512 INFO [DataNode: [[[DISK]file:/mnt/hadoop/0/dfs/data/,
[DISK]file:/mnt/hadoop/1/dfs/data/, [DISK]file:/mnt/hadoop/2/dfs/data/]]
heartbeating to /YYY:8020] DataNode - Got finalize command for block pool
BP-879324367-YYY-1404837025894
2014-11-27 17:06:36,519 INFO [DataNode: [[[DISK]file:/mnt/hadoop/0/dfs/data/,
[DISK]file:/mnt/hadoop/1/dfs/data/, [DISK]file:/mnt/hadoop/2/dfs/data/]]
heartbeating to /XXX:8020] GSet - Computing capacity for map BlockMap
2014-11-27 17:06:36,523 INFO [DataNode: [[[DISK]file:/mnt/hadoop/0/dfs/data/,
[DISK]file:/mnt/hadoop/1/dfs/data/, [DISK]file:/mnt/hadoop/2/dfs/data/]]
heartbeating to /XXX:8020] GSet - capacity = 2^20 = 1048576 entries
2014-11-27 17:06:36,520 INFO [DataNode: [[[DISK]file:/mnt/hadoop/0/dfs/data/,
[DISK]file:/mnt/hadoop/1/dfs/data/, [DISK]file:/mnt/hadoop/2/dfs/data/]]
heartbeating to /XXX:8020] GSet - VM type = 64-bit
2014-11-27 17:06:36,522 INFO [DataNode: [[[DISK]file:/mnt/hadoop/0/dfs/data/,
[DISK]file:/mnt/hadoop/1/dfs/data/, [DISK]file:/mnt/hadoop/2/dfs/data/]]
heartbeating to /XXX:8020] GSet - 0.5% max memory 1.9 GB = 9.9 MB
2014-11-27 17:06:36,524 INFO [DataNode: [[[DISK]file:/mnt/hadoop/0/dfs/data/,
[DISK]file:/mnt/hadoop/1/dfs/data/, [DISK]file:/mnt/hadoop/2/dfs/data/]]
heartbeating to /XXX:8020] BlockPoolSliceScanner - Periodic Block Verification
Scanner initialized with interval 504 hours for block pool
BP-879324367-YYY-1404837025894
{code}
But block is sitll reported with two replicas, one of those is assigned to
datanode which hasn't it:
{code}
<block_info>
<block_id>1083356878</block_id>
<block_name>blk_1083356878</block_name>
<file>
<local_name>commons-lang-2.6.jar</local_name>
<local_directory>/user/user/analysis</local_directory>
<user_name>user</user_name>
<group_name>supergroup</group_name>
<is_directory>false</is_directory>
<access_time>1417094143429</access_time>
<is_under_construction>false</is_under_construction>
<ds_quota>-1</ds_quota>
<permission_status>user:supergroup:rw-r--r--</permission_status>
<replication>2</replication>
<disk_space_consumed>568440</disk_space_consumed>
<preferred_block_size>134217728</preferred_block_size>
</file>
<replicas>
<replica>
<host_name>bad_node</host_name>
<is_corrupt>false</is_corrupt>
</replica>
<replica>
<host_name>good_node</host_name>
<is_corrupt>false</is_corrupt>
</replica>
</replicas>
</block_info>
{code}
fsck does not change the situation, ony the namenode restart force it to
recognize that block replica as missing.
As a result it is required to restart namenode after each disk failure which is
not very practical...
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
