Fluentd＋WebHDFS＆DataNode半死で起きた問題

Fluentd CollectorからHDFSに書き込むのに fluent-plugin-webhdfs を利用していますが、
DataNodeが１台変死した際に色々おかしくなったので書き留めておきます。

原因特定と解決方法の確立はできていません！あしからず。

直接の原因はSLAVEサーバ（DataNode）が中途半端に落ちたこと

１台のSLAVEサーバに異常が発生したことが直接の原因であり、状態としては

SLAVEサーバがKernel Panic!!

ホストへのPingは通る

各種デーモンへのTCP接続は確立できる

各種デーモンは一切お返事をしてくれない

試したのがDataNodeでないのが心苦しいですが、復旧前に確認できたのはSSH接続で、
ssh -p22 host は無応答で、telnet host 22 はリクエスト待ち状態になる半死状態でした。

この状態が、FluentdまたはHDFSクラスタ（NameNode＆DataNode）のどこに悪影響だったのかを判明させたいのですが・・・

１つ目の問題点：Collectorの再送が正常に機能しなかった

Fluentdのエラーログ

WebHDFSに書き込めなかった時、Fluentdはメモリに確保して、あとでretryしてくれます。その際、同じDataNodeに書き込もうとするわけではなく、NameNodeに聞くところからやり直す流れなので、2度目以降は生きてるDataNodeに保存してくれるイメージでしたが、そうは動きませんでした。この時のエラーログがこれです。

# このログを最初に
failed to communicate hdfs cluster, path: /path/to.log
failed to flush the buffer, retrying. error="Timeout::Error" instance=70235758287780

# 以降5時間くらいこれと同じのいっぱい。slaveホストは色々
failed to communicate hdfs cluster, path: /path/to.log
failed to flush the buffer, retrying. 
  error="{"RemoteException":{"exception":"AlreadyBeingCreatedException",
          "javaClassName":"org.apache.hadoop.hdfs.protocol.AlreadyBeingCreatedException",
          "message":"Failed to create file [/path/to.log] for [DFSClient_NONMAPREDUCE_-2072834332_6417224] 
          on client [host-of-slave-02], because this file is already being created 
          by [DFSClient_NONMAPREDUCE_-626862623_6417978] on [host-of-slave-04]
          ~snip~
  "}}" instance=70235758287780

# このログを最初に

failed to communicate hdfs cluster, path: /path/to.log

failed to flush the buffer, retrying. error="Timeout::Error" instance=70235758287780

# 以降5時間くらいこれと同じのいっぱい。slaveホストは色々

failed to communicate hdfs cluster, path: /path/to.log

failed to flush the buffer, retrying.

error="{"RemoteException":{"exception":"AlreadyBeingCreatedException",

"javaClassName":"org.apache.hadoop.hdfs.protocol.AlreadyBeingCreatedException",

"message":"Failed to create file [/path/to.log] for [DFSClient_NONMAPREDUCE_-2072834332_6417224]

on client [host-of-slave-02], because this file is already being created

by [DFSClient_NONMAPREDUCE_-626862623_6417978] on [host-of-slave-04]

~snip~

"}}" instance=70235758287780

NameNodeのエラーログ

この時のNameNodeエラーログはこんな感じで、急に、もうファイルあるから作れないよーって言い出しました。

# このログを最初に
WARN org.apache.hadoop.hdfs.StateChange: DIR* NameSystem.internalReleaseLease: 
    File /path/to.log has not been closed. 
    Lease recovery is in progress. 
    RecoveryId = 147446415 for block blk_7045469305421703619_147445941{blockUCState=UNDER_RECOVERY, 
    primaryNodeIndex=0, replicas=[ReplicaUnderConstruction[host-of-slave-12:50010|RBW], 
    ReplicaUnderConstruction[10.1.28.111:50010|RBW], ReplicaUnderConstruction[host-of-slave-06:50010|RBW]]}
WARN org.apache.hadoop.hdfs.StateChange: DIR* NameSystem.startFile: Failed to close file /path/to.log. 
    Lease recovery is in progress. Try again later.
ERROR org.apache.hadoop.security.UserGroupInformation: PriviledgedActionException as:td-agent (auth:SIMPLE) 
    cause:org.apache.hadoop.hdfs.protocol.RecoveryInProgressException: Failed to close file /path/to.log. 
    Lease recovery is in progress. Try again later.

# 以降5時間くらいこれと同じのいっぱい。slaveホストは色々
WARN org.apache.hadoop.hdfs.StateChange: DIR* NameSystem.startFile: 
    Failed to create file [/path/to.log] for [DFSClient_NONMAPREDUCE_-1981407932_14172158] on client [host-of-slave-09],
    because this file is already being created by [DFSClient_NONMAPREDUCE_-1204771165_6478021] on [host-of-slave-03]
ERROR org.apache.hadoop.security.UserGroupInformation: PriviledgedActionException as:td-agent (auth:SIMPLE) 
    cause:org.apache.hadoop.hdfs.protocol.AlreadyBeingCreatedException: 
    Failed to create file [/path/to.log] for [DFSClient_NONMAPREDUCE_-1981407932_14172158] 
    on client [host-of-slave-09], because this file is already being created 
    by [DFSClient_NONMAPREDUCE_-1204771165_6478021] on [host-of-slave-03]

# このログを最初に

WARN org.apache.hadoop.hdfs.StateChange: DIR* NameSystem.internalReleaseLease:

File /path/to.log has not been closed.

Lease recovery is in progress.

RecoveryId = 147446415 for block blk_7045469305421703619_147445941{blockUCState=UNDER_RECOVERY,

primaryNodeIndex=0, replicas=[ReplicaUnderConstruction[host-of-slave-12:50010|RBW],

ReplicaUnderConstruction[10.1.28.111:50010|RBW], ReplicaUnderConstruction[host-of-slave-06:50010|RBW]]}

WARN org.apache.hadoop.hdfs.StateChange: DIR* NameSystem.startFile: Failed to close file /path/to.log.

Lease recovery is in progress. Try again later.

ERROR org.apache.hadoop.security.UserGroupInformation: PriviledgedActionException as:td-agent (auth:SIMPLE)

cause:org.apache.hadoop.hdfs.protocol.RecoveryInProgressException: Failed to close file /path/to.log.

Lease recovery is in progress. Try again later.

# 以降5時間くらいこれと同じのいっぱい。slaveホストは色々

WARN org.apache.hadoop.hdfs.StateChange: DIR* NameSystem.startFile:

Failed to create file [/path/to.log] for [DFSClient_NONMAPREDUCE_-1981407932_14172158] on client [host-of-slave-09],

because this file is already being created by [DFSClient_NONMAPREDUCE_-1204771165_6478021] on [host-of-slave-03]

ERROR org.apache.hadoop.security.UserGroupInformation: PriviledgedActionException as:td-agent (auth:SIMPLE)

cause:org.apache.hadoop.hdfs.protocol.AlreadyBeingCreatedException:

Failed to create file [/path/to.log] for [DFSClient_NONMAPREDUCE_-1981407932_14172158]

on client [host-of-slave-09], because this file is already being created

by [DFSClient_NONMAPREDUCE_-1204771165_6478021] on [host-of-slave-03]

考察

この1つ目の問題の段階では、1DataNodeの半死によってNameNodeにおける状態管理が変になって、HDFSに正常に書き込めない時がある状態になってしまったために、Fluentdでエラーが発生した可能性が高いです。

深夜だったので特に復旧作業はしていないものの、5時間ほどでNameNodeにエラーログが出なくなり、Fluentdでもretry successログが出て来ました。ただ、全てのログが正常に再送されたわけではなく、一部メモリに残っていたようで下記のSLAVE再起動時に残りが再送された、というよくわからない状態でした。

SLAVE半死時にNameNode管理画面を見なかったのが惜しまれますが、DataNodeが半死した場合、一時的にHDFSが混乱する可能性があると思っていたほうがよさそうです。この時もちろん、Fluentdはログを確保しきってくれていたので、ログロストはしていなくGJでした。

２つ目の問題点：SLAVE復旧時にCollectorの通信が安定しないこと

次に半死状態のSLAVEサーバを再起動して全SLAVEが正常な状態にしました。これによってCollectorからログの再送が始まったので、NameNodeが完全に復旧したのはこのタイミングと予測できます。

で、複数あるCollectorのうち1台以外は無事に再送が完了して正常な状態に戻ったのですが、
問題の1台ではすみやかに再送が完了せず、こんなログを吐きながらちんたら再送していました。

# たまに成功
retry succeeded. instance=70235724013860

# ずーっと失敗が繰り返される
failed to communicate hdfs cluster, path: /path/to.log
failed to flush the buffer, retrying. error="getaddrinfo: Name or service not known" instance=70235758696140

# たまに成功

retry succeeded. instance=70235724013860

# ずーっと失敗が繰り返される

failed to communicate hdfs cluster, path: /path/to.log

failed to flush the buffer, retrying. error="getaddrinfo: Name or service not known" instance=70235758696140

この段階ではHDFSクラスタの方に特別なエラーはありませんでした。
他のCollectorが優秀な中、この子だけ

getaddrinfo: Name or service not known のエラーを吐き続ける

2.2GBほど確保されてたっぽいログが6時間かけてまだ残り700MBある（psで確認）

flowcounterログ・HDFS保存ファイル・SNMPのINPUTグラフを見るに、Agentから一切受信していない状態（再送に専念する機能なんてあったっけ？）

異常Collectorサーバから、NameNodeと復旧したDataNodeへ通信できることは確認済みで、
（多分）HDFSクラスタは正常に戻っているのに、1つのCollectorは異常が続きました。

結局、待っても td-agent のメモリが 700MB から下がらなくなって状況に変化がなくなったので、td-agent stop を実行してみたところ、やはり “Name or service not known” と駄々をこねたので KILL って再起動したら、良い子に戻ってくれました。なので、400～500MB ほどのログをロストした可能性はあります。しくしく……

これまで、SLAVEサーバがストンと何回落ちてもこんなことはなかったのですが、半死という初の状態で面倒に巻き込まれ、状況をまとめてみたものの、まとまっていないのもわかっています。

それでもこうだったらいいのかな、という点をまとめると、

NameNodeにおけるDataNodeのヘルスチェックをより厳しいものに

Fluentdのメモリに再送ログが残った状態で状況変化がなくなるとどうしようもなくなるので、すみやかに救済する手段を

NameNodeもFluentdも動かしたままINFO/DEBUGログを残したい…

fluent-plugin-webhdfs の書き込みエラーログに、書き込み先のDataNode情報も欲しい。NameNodeが教えてくれるLocationそのままとかでも

Fluentdの再送状況が知りたい。コマンド打ったら残り行数や容量がわかったり

ちょっと古めのtd-agent(1.1.7)ですし、最近変化を追ってませんが、思いつくところを書いてみました。