[ https://issues.apache.org/jira/browse/HDFS-7453?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14267999#comment-14267999 ]
Jasper Hafkenscheid commented on HDFS-7453: ------------------------------------------- Hi, We have a cluster with bad disk(controler)s, and see this problem often. Our replication facor is 3. Luckely most disks recover after a powercycle. Regards Jasper > 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)