※本記事ではうるう秒によるjavaの異常と、それに伴って生じたHadoop 0.21.0 HDFSのメタデータ破損からの復旧手順を説明します。なお、本復旧手順は私の環境で上手くいっただけであり、他の環境で同様の手順を行ったとしても復旧できる保証はありませんので、ご注意ください。
昨日（2012/7/1）Hadoopクラスタの一部マシンでCPU負荷が突然MAXに張り付いていることに気付きました。
今日になってこの現象はうるう秒のあとにjavaに生じた不具合であることが分かりました（参考：http://d.hatena.ne.jp/sh2/20120702、このブログの記述と同様にjavaとksoftirqdプログラムが大きなCPU負荷を占め続けていました）。
この障害が起きていたのはOSがfedora10, 13のマシン群で、他のマシンはCentOSであり不具合無く動作していました。
試行錯誤の結果、再起動することでこの異常負荷が収まることがわかり（再起動せずともdateコマンドで修正することもできたようですね）、異常が起きたノード全ての再起動を実行しました。
しかしながら、HDFSサーバであるNameNodeマシンでもこの異常が起き、その最中にNamenodeを止めたためか、再起動後にNamenodeを起動してもNamenodeが起動失敗してしまう状態になりました。
Namenodeのログは以下のようになっていました。
2012-07-01 15:31:33,555 INFO org.apache.hadoop.hdfs.server.namenode.NameNode: STARTUP_MSG: /************************************************************ STARTUP_MSG: Starting NameNode STARTUP_MSG: host = hdc101/192.168.100.2 STARTUP_MSG: args = [] STARTUP_MSG: version = 0.21.0 STARTUP_MSG: classpath = /work/hadoop-0.21.0/bin/..................（略） ************************************************************/ 2012-07-01 15:31:33,613 WARN org.apache.hadoop.conf.Configuration: hdfs-site.xml:an attempt to override final parameter: dfs.namenode.http-address; Ignoring. 2012-07-01 15:31:33,668 WARN org.apache.hadoop.conf.Configuration: hdfs-site.xml:an attempt to override final parameter: dfs.namenode.http-address; Ignoring. 2012-07-01 15:31:33,691 INFO org.apache.hadoop.security.Groups: Group mapping impl=org.apache.hadoop.security.ShellBasedUnixGroupsMapping; cacheTimeout=300000 2012-07-01 15:31:33,702 INFO org.apache.hadoop.metrics.jvm.JvmMetrics: Initializing JVM Metrics with processName=NameNode, sessionId=null 2012-07-01 15:31:33,709 INFO org.apache.hadoop.hdfs.server.namenode.metrics.NameNodeMetrics: Initializing NameNodeMeterics using context object:org.apache.hadoop.metrics.spi.NullContext 2012-07-01 15:31:33,737 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: defaultReplication = 3 2012-07-01 15:31:33,737 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: maxReplication = 512 2012-07-01 15:31:33,737 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: minReplication = 1 2012-07-01 15:31:33,737 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: maxReplicationStreams = 2 2012-07-01 15:31:33,737 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: shouldCheckForEnoughRacks = true 2012-07-01 15:31:33,741 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: fsOwner=hadoop 2012-07-01 15:31:33,741 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: supergroup=supergroup 2012-07-01 15:31:33,741 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: isPermissionEnabled=true 2012-07-01 15:31:33,745 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: isAccessTokenEnabled=false accessKeyUpdateInterval=0 min(s), accessTokenLifetime=0 min(s) 2012-07-01 15:31:34,012 INFO org.apache.hadoop.hdfs.server.namenode.metrics.FSNamesystemMetrics: Initializing FSNamesystemMetrics using context object:org.apache.hadoop.metrics.spi.NullContext 2012-07-01 15:31:34,013 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Registered FSNamesystemStatusMBean 2012-07-01 15:31:34,031 WARN org.apache.hadoop.hdfs.server.common.Util: Path /work/hadoop/name should be specified as a URI in configuration files. Please update hdfs configuration. 2012-07-01 15:31:34,032 WARN org.apache.hadoop.hdfs.server.common.Util: Path /home/hadoop/name_hdc101 should be specified as a URI in configuration files. Please update hdfs configuration. 2012-07-01 15:31:34,032 WARN org.apache.hadoop.hdfs.server.common.Util: Path /work/hadoop/name should be specified as a URI in configuration files. Please update hdfs configuration. 2012-07-01 15:31:34,032 WARN org.apache.hadoop.hdfs.server.common.Util: Path /home/hadoop/name_hdc101 should be specified as a URI in configuration files. Please update hdfs configuration. 2012-07-01 15:31:34,045 INFO org.apache.hadoop.hdfs.server.common.Storage: Number of files = 590088 2012-07-01 15:31:35,137 ERROR org.apache.hadoop.hdfs.server.namenode.FSNamesystem: FSNamesystem initialization failed. java.io.EOFException at java.io.DataInputStream.readFully(DataInputStream.java:180) at org.apache.hadoop.io.UTF8.readFields(UTF8.java:117) at org.apache.hadoop.hdfs.server.namenode.FSImage.readString(FSImage.java:2092) at org.apache.hadoop.hdfs.server.namenode.FSImage.loadFSImage(FSImage.java:1087) at org.apache.hadoop.hdfs.server.namenode.FSImage.loadFSImage(FSImage.java:1010) at org.apache.hadoop.hdfs.server.namenode.FSImage.recoverTransitionRead(FSImage.java:483) at org.apache.hadoop.hdfs.server.namenode.FSDirectory.loadFSImage(FSDirectory.java:110) at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.initialize(FSNamesystem.java:291) at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.(FSNamesystem.java:270) at org.apache.hadoop.hdfs.server.namenode.NameNode.loadNamesystem(NameNode.java:271) at org.apache.hadoop.hdfs.server.namenode.NameNode.initialize(NameNode.java:303) at org.apache.hadoop.hdfs.server.namenode.NameNode. (NameNode.java:433) at org.apache.hadoop.hdfs.server.namenode.NameNode. (NameNode.java:421) at org.apache.hadoop.hdfs.server.namenode.NameNode.createNameNode(NameNode.java:1359) at org.apache.hadoop.hdfs.server.namenode.NameNode.main(NameNode.java:1368) 2012-07-01 15:31:35,138 ERROR org.apache.hadoop.hdfs.server.namenode.NameNode: java.io.EOFException at java.io.DataInputStream.readFully(DataInputStream.java:180) at org.apache.hadoop.io.UTF8.readFields(UTF8.java:117) at org.apache.hadoop.hdfs.server.namenode.FSImage.readString(FSImage.java:2092) at org.apache.hadoop.hdfs.server.namenode.FSImage.loadFSImage(FSImage.java:1087) at org.apache.hadoop.hdfs.server.namenode.FSImage.loadFSImage(FSImage.java:1010) at org.apache.hadoop.hdfs.server.namenode.FSImage.recoverTransitionRead(FSImage.java:483) at org.apache.hadoop.hdfs.server.namenode.FSDirectory.loadFSImage(FSDirectory.java:110) at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.initialize(FSNamesystem.java:291) at org.apache.hadoop.hdfs.server.namenode.FSNamesystem. (FSNamesystem.java:270) at org.apache.hadoop.hdfs.server.namenode.NameNode.loadNamesystem(NameNode.java:271) at org.apache.hadoop.hdfs.server.namenode.NameNode.initialize(NameNode.java:303) at org.apache.hadoop.hdfs.server.namenode.NameNode. (NameNode.java:433) at org.apache.hadoop.hdfs.server.namenode.NameNode. (NameNode.java:421) at org.apache.hadoop.hdfs.server.namenode.NameNode.createNameNode(NameNode.java:1359) at org.apache.hadoop.hdfs.server.namenode.NameNode.main(NameNode.java:1368) 2012-07-01 15:31:35,139 INFO org.apache.hadoop.hdfs.server.namenode.NameNode: SHUTDOWN_MSG: /************************************************************ SHUTDOWN_MSG: Shutting down NameNode at hdc101/192.168.100.2 ************************************************************/
どうやらHDFSのメタデータが壊れてしまい、Namenodeの起動ができない状態になってしまったようです。
そこでメタデータを過去にコピーしておいたメタデータで差し替えることで復旧することにしました。
メタデータはNamenodeマシンの$HADOOP_HOME/conf/hdfs-site.xmlファイル内のdfs.name.dirの場所に記録されています（私の環境では/work/hadoop/name）。
過去にこのデータを
cp -r /work/hadoop/name /work/hadoop/name_backups/name.20120610
とコピーしてありましたので、これを現在のメタデータとして戻してやります。
# 念のため現在のメタデータを残しておく mv /work/hadoop/name /work/hadoop/name.old cp -r /work/hadoop/name_backups/name.20120610 /work/hadoop/name
このコピーを実行後にNamenodeを起動したところ、ブラウザ上からのNamenodeへのアクセスが可能となり、過去のメタデータ保存時点でのHDFS上のファイル内容を見ることが可能となりました。
ひとまずこれでHDFS上のファイルにアクセス可能な状態になり一安心しました。
ただし、バックアップ当時と比べるとHDFS上でファイルの新規作成・削除・更新等を行ってきたため、メタデータと各datanode HDD上のファイル情報は完全に一致はしておらず、自動的にセーフモードは解除されません。
HDFSからの読み込みは可能になりましたので、この時点で最低限必要となるファイルをHDFSから別のファイルシステムにコピーを行いました。（最低限といっても1TB以上あり、コピーに一晩かかりました）
必要なデータをサルベージできたならば、次はセーフモードを解除してHDFSへの書き込みができるよう復旧する必要があります。
セーフモードを手動で解除するにはNamenodeマシンで以下のコマンドを使います。
hdfs dfsadmin -safemode (enter|leave|get|wait)
leaveにより強制的にセーフモードを解除しました。
次にメタデータと各datanode HDD上データの整合性を戻す必要があります。これは
hdfs fsck /
により実行します。
その結果、以下のようにCorrupted filesの存在が出力されました。
Total size: 19991408430372 B Total dirs: 24011 Total files: 521484 Total blocks (validated): 563893 (avg. block size 35452485 B) ******************************** CORRUPT FILES: 669 MISSING BLOCKS: 815 MISSING SIZE: 27566000642 B CORRUPT BLOCKS: 815 ******************************** Minimally replicated blocks: 563078 (99.85547 %) Over-replicated blocks: 0 (0.0 %) Under-replicated blocks: 0 (0.0 %) Mis-replicated blocks: 815 (0.14453097 %) Default replication factor: 3 Average block replication: 2.9168034 Corrupt blocks: 815 Missing replicas: 0 (0.0 %) Number of data-nodes: 50 Number of racks: 6
具体的にどのファイルがCorruptedであるかはNamenodeブラウザ表示（下図）の赤色のWARNINGから始まるリンクをクリックすることでチェックできます。
例えば、以下のように /user/MD/06500ps のディレクトリがCorruptedであることがわかりました。
Reported Corrupt Files /user/MD/06500ps/0004/mdcrd /user/MD/06500ps/0019/logfile /user/MD/06500ps/0022/restrt /user/MD/06500ps/0036/inpcrd ...
これらCorruptedなファイルは計算し直すことにし、削除します。
hdfs dfs -rmr /user/MD/06500ps # ゴミ箱機能使用時はゴミ箱である/user/hadoop/.Trashにデータがコピーされるので、ゴミ箱内でさらにrmrを実行しデータを完全に削除 hdfs dfs -rmr "/user/hadoop/.Trash/*"
他にも壊れているファイルがあれば全て削除してやります。
その後fsckを実行すると、まだCorruptedファイルが残っている場合は、そのリストがNamenodeブラウザの「Warning」リンク先に表示されますので、そのファイルも削除します。
以上の「Corruptedファイルの確認、削除」「fsck実行」をCorruptedファイルが無くなるまで繰り返すことで、最終的にバックアップデータ取得時までHDFSの状態を戻すことができました。
今回のトラブルで、以前にメタデータをコピーした日以降に作成したHDFS上のデータが失われてしましました。
幸い失われたのは一時ファイル的なものが大半で、重要なデータの再計算は数日で済む程度で大きな打撃とはなりませんでした。
今後も同様にHDFSがトラブルに見舞われるケースが起こりえることから、対策として以下のようにcronによって定期的なファイルシステムチェックとメタデータコピーを行うようにしました。
crontab -e 以下を追加 # 毎日fsckを実行 0 4 * * * hdfs fsck / # 毎週日曜日・水曜日の4:00にメタデータをコピー # cron中では%はエスケープする必要あり 30 4 * * 0,4 cp -r /work/hadoop/name /work/hadoop/name_backups/name.`date +\%Y\%m\%d`
さらにHDFSのデータは壊れる可能性があることを常に念頭に置いて運用する必要があることも痛感しました。全てのデータのバックアップは容量的に不可能であっても、最低限計算のやり直し等に必要となる重要なデータだけは他のファイルシステムにバックアップを取っておくことも忘れないようにします。
