hiveのUDFを開発・デバッグしている時に、
UDFの挙動をログに出力して確認したいことがあるので。
hiveのUDFで、ログを出力し確認する方法をまとめておきます。

UDFの作り方は、以下のエントリを参考にしてください。

HiveのUDFを作る手順のメモ | takemikami.com
http://takemikami.com/2016/09/06/HiveUDF.html

この手順は、macos上の「Hive 2.1.0」で確認しています。

ログ出力を埋め込む

UDFのコードにログ出力を埋め込みます。
「Apache Commons Logging」でログを出力するコードを追加します。

以下のコード例では、
evaluateメソッドの初めにデバッグログを出力するようにしています。

src/main/java/com/takemikami/hiveudfsample/Lower.java

package com.takemikami.hiveudfsample;

import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
import org.apache.hadoop.hive.ql.exec.UDF;
import org.apache.hadoop.io.Text;

public final class Lower extends UDF {

    private static Log logger = LogFactory.getLog(Lower.class);

    public Text evaluate(final Text s) {
        logger.debug("enter Lower.evaluate, s=" + s.toString());
        if (s == null) { return null; }
        return new Text(s.toString().toLowerCase());
    }
}

コンソールにログを出力する

hiveのログ出力の設定は「hive-log4j2.properties」に記載されています。

github上で確認したい場合はこちら、
https://github.com/apache/hive/blob/master/common/src/main/resources/hive-log4j2.properties

macosでhomebrewを使ってinstallした場合は、以下のファイルになります。
/usr/local/Cellar/hive/※hiveのバージョン※/libexec/conf/hive-log4j2.properties.template

この設定ファイルを見ると「hive.root.logger」でロガーを指定できることがわかります。
そこで、以下のようにパラメータを指定してhiveコマンドを起動します。

$ hive -hiveconf hive.root.logger=DEBUG,console

先ほどログを埋め込んだUDFを、以下のように呼び出します。

hive> add jar ※UDF開発ディレクトリのパス※/build/libs/hiveudf-sample.jar;
hive> create temporary function lower as 'com.takemikami.hiveudfsample.Lower';
hive> select lower('AAA');

コンソールに以下のようなログが出力されます。

17/08/09 11:29:08 [main]: DEBUG hiveudfsample.Lower: enter Lower.evaluate, s=AAA

上記以外にも大量のログが出力され、ログを追うのが難しいと思われるので、
次の項では、grepしやすいようにファイルにログを出力する方法を示します。

ファイルにログを出力する

次に、ファイルにログを出力してみます。

前項と同じように、ログ出力の設定を行ってhiveコマンドを起動します。

$ hive -hiveconf hive.root.logger=DEBUG,DRFA -hiveconf hive.log.dir=※ログの出力先パス※ -hiveconf hive.log.file=hive-debug.log

前項と同じようにUDFを呼び出します。

hive> add jar ※UDF開発ディレクトリのパス※/build/libs/hiveudf-sample.jar;
hive> create temporary function lower as 'com.takemikami.hiveudfsample.Lower';
hive> select lower('AAA');

実行後、以下のコマンドでログファイルを確認します。

$ cat ※ログの出力先パス※/hive-debug.log | grep hiveudfsample.Lower

以下のようなデバッグログが出力出来ていることを確認できます。

2017-08-09T11:48:59,337 DEBUG [main]: exec.FunctionRegistry (:()) - Method did match: passed = [string] accepted = [string] method = public org.apache.hadoop.io.Text com.takemikami.hiveudfsample.Lower.evaluate(org.apache.hadoop.io.Text)
2017-08-09T11:48:59,337 DEBUG [main]: hiveudfsample.Lower (:()) - enter Lower.evaluate, s=AAA
2017-08-09T11:48:59,396 DEBUG [main]: exec.FunctionRegistry (:()) - Method did match: passed = [string] accepted = [string] method = public org.apache.hadoop.io.Text com.takemikami.hiveudfsample.Lower.evaluate(org.apache.hadoop.io.Text)
2017-08-09T11:48:59,396 DEBUG [main]: hiveudfsample.Lower (:()) - enter Lower.evaluate, s=AAA

UDFを作るときはあまり必要ないかも知れないですが。
UDAF,UDTFを作るときは、
このようにログを出力して挙動を追いながら開発出来ると、
効率良くデバッグ出来るのでは無いかな、と思います。