Fluentd＋WebHDFSのAPPENDエラーをlog4jで除外

前回に続いてFluendからWebHDFSに書き込んだ時の話ですが、今回はどちらかというと log4j の話になります。

log4j についてずっとド素人なままHadoopを使ってきたのですが、さすがに放っておけない事象が発生したので取り組んでみました。

WebHDFSへのAPPEND時にファイルが無いとエラーになる

fluent-plugin-webhdfs でHDFSに書き込む際に、APPEND -> CREATE の順で行うことは前回書きました。なのでFlush毎に必ずAPPENDが発生するのですが、APPENDリクエストの時に対象ファイルが無いと、NameNodeにこのようなエラーログが記録されます。

curl -i -X POST "http://namenode:50070/webhdfs/v1/path/to/empty.txt?op=APPEND"
# と打つと404が返ってこのエラーログ
ERROR org.apache.hadoop.security.UserGroupInformation: PriviledgedActionException as:webuser (auth:SIMPLE) cause:java.io.FileNotFoundException: File /path/to/empty.txt not found.

curl -i -X POST "http://namenode:50070/webhdfs/v1/path/to/empty.txt?op=APPEND"

# と打つと404が返ってこのエラーログ

ERROR org.apache.hadoop.security.UserGroupInformation: PriviledgedActionException as:webuser (auth:SIMPLE) cause:java.io.FileNotFoundException: File /path/to/empty.txt not found.

Collector数が多かったり、ファイル分割数が多いと、放っておけるレベルじゃないログ容量になりますし、それよりも大事なエラーを見逃すことになるかもしれません。また、ログレベルがERRORと高いので簡単に除外もできません。

ということで、できるなら突っつきたくなかった log4j を調べて対応することにしました。

log4jのちょっとメモ

Hadoopのlog4jバージョン

メインパッケージのhadoopパッケージに含まれている /usr/lib/hadoop/lib/log4j-1.2.15.jar により ver 1.2.x とういことがわかります。log4j自体は長く1.3.xがalphaだとか log4j2 が出てきてるとか色々ありそうですが、hadoopが1.2.xを使っているので他は気にしないことにします。

参考ページ

Log4J徹底解説～ファイル保存系Appender

設定ファイル

hadoopのlog4j設定は $HADOOP_CONF_DIR/log4j.properties となっていますが、同じディレクトリに log4j.xml を置くことで、XML設定を優先して動かすことができます。こうする方が良い理由も色々あるみたいですが、今回は単純にFilter機能を使いたくてXMLにせざるを得ない形になりました。こんなエレガント設計な設定、初めてみるぜ！

properties設定をXML変換する

ということでproperties形式だと使えない機能があるので仕方なくXMLにします。手書きはきちぃのでなんかないかなっと見るとありました。

Log4J Properties Converter Tool

まずはこれを使ってXMLに変換します。

cd /usr/local/src
wget http://log4j-properties-converter.googlecode.com/files/log4j-properties-converter-1.0.zip
unzip log4j-properties-converter-1.0.zip

cd log4j-properties-converter-cli-1.0/
chmod +x log4j-convert.sh
./log4j-convert.sh -f /etc/hadoop/conf/log4j.properties

ls -l /etc/hadoop/conf/log4j*

cd /usr/local/src

wget http://log4j-properties-converter.googlecode.com/files/log4j-properties-converter-1.0.zip

unzip log4j-properties-converter-1.0.zip

cd log4j-properties-converter-cli-1.0/

chmod +x log4j-convert.sh

./log4j-convert.sh -f /etc/hadoop/conf/log4j.properties

ls -l /etc/hadoop/conf/log4j*

/etc/hadoop/conf/log4j.xml ができてるので、とりあえずNameNodeを再起動すると appender-ref には ref がいるよーと怒られます。今回は RFA という appender を使うので、怒られた場所を <appender-ref ref=”RFA”/> のように修正して反映します。そしてここでいったん、そもそもログが書き出されるかや、もう一度APPENDしてみてもログに記録されるか、などを確かめておきます。

エラーメッセージに対してFilterをかける

あとは好きなFilterをかけておしまいです。今回は RFA appender に条件をつけます。

ログのボディに FileNotFoundException があったら false で除外します

それ以外のエラーレベル WARN – ERROR までを全て記録します

ちょっとした注意点。

XMLですがfilterは上から順に適用されてマッチした所でストップします

classのパスが1.3系と違うのでご注意

エラーログは [エラーレベル] [クラス]: [メッセージ] の形式で記録されますが、今回利用した StringMatchFilter は [メッセージ] の部分のみにマッチします

    <appender class="org.apache.log4j.RollingFileAppender" name="RFA">
        <param value="${hadoop.log.dir}/${hadoop.log.file}" name="File"/>
        <param value="5" name="MaxBackupIndex"/>
        <param value="10MB" name="MaxFileSize"/>
        <layout class="org.apache.log4j.PatternLayout">
            <param value="%d{ISO8601} %p %c: %m%n" name="ConversionPattern"/>
        </layout>
        <filter class="org.apache.log4j.varia.StringMatchFilter" >
            <param name="StringToMatch" value="FileNotFoundException" />
            <param name="AcceptOnMatch" value="false" />
        </filter>
        <filter class="org.apache.log4j.varia.LevelRangeFilter">
            <param name="levelMin" value="WARN"/>
            <param name="levelMax" value="ERROR"/>
            <param name="acceptOnMatch" value="true"/>
        </filter>
    </appender>

</layout>

</filter>

</filter>

</appender>

これで再起動した後に、APPENDしてみてエラーが記録されないことを確認します。

他に思ったこと

設定形式

元のpropertiesだとlog4jを知る気が起きなかったけど、XMLにしたら直感でわかりやすくなりました。例えば、appender がログ形式の定義であり、loggerが条件毎にログを受けてどのappenderを使用するか決めるところ・・・など。わかってしまえばsyslog系とたいして変わらないなーと気楽になります。

長期的にHadoopを使うなら、最初からXMLで理解しておいた方がよさそうです。

appenderの選択

最初からある代表的なのに RFA と DRFA があり、違いは日付ローテートするかどうかですが、DRFAだと MaxBackupIndex が効かないので自動的に削除されていきません。その対応策はあるっぽく、確かに日付ローテート＋自動削除があるのがベストですが、実運用では最新のファイルがあれば十分なので、めんどいことはせずRFAでいいと思います。

他にも色んな機能がありそうなので気が向いたら調べたい所ですが、俺の基本ポリシーはWARN以上をできるだけゼロにするという程度なので、今のとこはこんな感じで。

全体的にログの種類が多すぎなので、定期的に見やすく抽出する何かを作りたくなりますね。
心臓に悪いのでせめてNameNodeだけは潔白でありたい！