技術/Android/LogAndLogLevelTips

• [ Prev ]
• [ Next ]
• [ 技術 ]

android.util.Logでログレベルの調整が分かりづらかったのでメモ。
公開されている資料をベースに、自分がつまずいた箇所を抜書きしました。

参考：

• Reading and Writing Logs | Android Developers
  • http://developer.android.com/guide/developing/debugging/debugging-log.html
• Log | Android Developers
  • http://developer.android.com/reference/android/util/Log.html
• Android logging - Stack Overflow
  • http://stackoverflow.com/questions/2018263/android-logging

• android.util.Logの使い方
• 実機やEmulator上でのログレベル
  • ログレベルと出力メソッドについて、Androidのソースコードを確認してみる。
• 実機やEmulator上でのログレベルの調整
  • android.util.Logドキュメントのミス・・・では無いらしい。
• ProGuardを用いて特定のログレベルを無効化する手法

android.util.Logの使い方

staticメソッドとしてv(Verbose) - e(Error)まで5種類が用意されている。他にもassertion用のメソッドであったり、あるログレベルが出力される設定になっているかチェックするisLoggable()メソッドが用意されている。
引数としてはログを見分けるための"tag"文字列, ログメッセージの2つに加え、例外発生時のStackTrace出力用にThrowableを渡すことも出来る。

Log.e("tag1", "tag1-error");
Log.w("tag1", "tag1-warn");
Log.i("tag1", "tag1-info");
Log.d("tag1", "tag1-debug");
Log.v("tag1", "tag1-verbose");
 
Log.e("tag2", "tag2-error");
Log.w("tag2", "tag2-warn");
Log.i("tag2", "tag2-info");
Log.d("tag2", "tag2-debug");
Log.v("tag2", "tag2-verbose");

実際の出力(DDMSやLogcatなど)：

07-17 16:40:45.434: ERROR/tag1(1218): tag1-error
07-17 16:40:45.434: WARN/tag1(1218): tag1-warn
07-17 16:40:45.434: INFO/tag1(1218): tag1-info
07-17 16:40:45.434: DEBUG/tag1(1218): tag1-debug
07-17 16:40:45.434: VERBOSE/tag1(1218): tag1-verbose
07-17 16:40:45.434: ERROR/tag2(1218): tag2-error
07-17 16:40:45.434: WARN/tag2(1218): tag2-warn
07-17 16:40:45.434: INFO/tag2(1218): tag2-info
07-17 16:40:45.434: DEBUG/tag2(1218): tag2-debug
07-17 16:40:45.434: VERBOSE/tag2(1218): tag2-verbose

実機やEmulator上でのログレベル

実機及びEmulator上でのデフォルトのログレベルはINFOである。
これはあくまでも isLoggable() がtrueを返すレベル であり、d()やv()が実行されるとINFOレベルであるにも関わらず出力されてしまう。
上で示した「実際の出力」では、ログレベルの調整を一切行っていないデフォルト状態(=INFOレベル)であるにも関わらず、 debug, verboseも出力されている。

ログレベルに応じてログ出力を適切にON/OFFするのであれば、次のように if(isLoggable()) で囲む必要がある。

if (Log.isLoggable("tag1", Log.DEBUG)) {
    Log.d("tag1", "tag1-debug");
}

勿論、isLoggable()でチェックするtag文字列と出力メソッドに渡すtag文字列は一致している必要がある。でないとチェックする意味がなくなってしまう。

ログレベルと出力メソッドについて、Androidのソースコードを確認してみる。

ログの出力メソッドでは"isLoggable()"相当のフィルタリングを行なっていない、という点について実際にAndroidのソースコードを確認してみる。
なお以下の説明は "android-4.0.3_r1" tag のソースを用いているが、大筋は "android-2.3.7_r1" tagのソースでも同じであることを確認している。

まず android.util.Log クラスのJavaソースは以下になる。
frameworks/base/core/java/android/util/Log.java:

public final class Log {
// ...
    public static native boolean isLoggable(String tag, int level);
//...
    public static int d(String tag, String msg) {
        return println_native(LOG_ID_MAIN, DEBUG, tag, msg);
    }
//...
    public static int d(String tag, String msg, Throwable tr) {
        return println_native(LOG_ID_MAIN, DEBUG, tag, msg + '\n' + getStackTraceString(tr));
    }
//...
    public static int i(String tag, String msg) {
        return println_native(LOG_ID_MAIN, INFO, tag, msg);
    }
//...
    /** @hide */ public static native int println_native(int bufID,
            int priority, String tag, String msg);
//...

isLoggable()、およびv(), d(), ... から呼ばれる println_native() はnativeメソッド、つまりC/C++で実装されている。
そこでJNIのソースを探してみると、以下のファイルで実装されていた。
frameworks/base/core/jni/android_util_Log.cpp:

//...
#define LOG_NAMESPACE "log.tag."
//...
 
// isLoggable()の処理：property_get()でpropファイルを調べている。
static jboolean android_util_Log_isLoggable(JNIEnv* env, jobject clazz, jstring tag, jint level)
{
    int len;
    char key[PROPERTY_KEY_MAX];
    char buf[PROPERTY_VALUE_MAX];
 
// (省略) : エラー処理と、keyに"log.tag.(タグ名)"というprop取得のためのキー名を設定
 
    len = property_get(key, buf, "");
    int logLevel = toLevel(buf);
    return (logLevel >= 0 && level >= logLevel) ? true : false;
}
//...
 
// println_native()処理：__android_log_buf_write()に処理を委譲
static jint android_util_Log_println_native(JNIEnv* env, jobject clazz,
        jint bufID, jint priority, jstring tagObj, jstring msgObj)
{
    const char* tag = NULL;
    const char* msg = NULL;
// (省略) :  エラー処理と、tag, msgにtagObj, msgObjの文字列を設定している。
    int res = __android_log_buf_write(bufID, (android_LogPriority)priority, tag, msg);
// ...
    return res;
}

__android_log_buf_write()というのが出てきたが、こちらはJNIのソース中には見つからない。調べてみると、以下のファイルで実装されていた。
system/core/liblog/logd_write.c:

int __android_log_buf_write(int bufID, int prio, const char *tag, const char *msg)
{
    struct iovec vec[3];
// (省略) : tagとbufIDの調整
    vec[0].iov_base   = (unsigned char *) &prio;
    vec[0].iov_len    = 1;
    vec[1].iov_base   = (void *) tag;
    vec[1].iov_len    = strlen(tag) + 1;
    vec[2].iov_base   = (void *) msg;
    vec[2].iov_len    = strlen(msg) + 1;
 
    return write_to_log(bufID, vec, 3);
}

iovecについては readv(2), writev(2) を参照。
write_to_log()については以下のように宣言されている。

static int __write_to_log_init(log_id_t, struct iovec *vec, size_t nr);
static int (*write_to_log)(log_id_t, struct iovec *vec, size_t nr) = __write_to_log_init;

以降のソースは割愛するが、処理内容としては以下になる。

• 一回目のwrite_to_log()呼び出し：__write_to_log_init()が呼ばれる。
  • 初期化処理(ログファイルのオープン) + write_to_log を __write_to_log_kernel に切り替え、かつ __write_to_log_kernel を呼び出す。
• 二回目以降のwrite_to_log()呼び出し：__write_to_log_kernel()が呼ばれる。
  • writev(2) を使ってログファイル出力

結論：以上見てきたように、isLoggable()によるログレベルの検査と、ログ出力処理は完全に独立している。このためたとえVERBOSEやDEBUGレベルがpropファイル上はOFFにされていたとしても、v()やd()メソッドを呼べばログファイルに出力されてしまう。

実機やEmulator上でのログレベルの調整

"isLoggable()"のドキュメントに記載されているが、

$ setprop log.tag.<TAG> <LEVEL>

により実機及びEmulator上での対象TAGのログレベルを調整できる。

実機でも適用できるので、例えば実機でしか動かない機能をテストするとき、VerboseやDebugレベルを出力するために上記setpropコマンドを使ってログレベルを調整することが出来る。

他にも "/data/local.prop" ファイルに

log.tag.<YOUR_LOG_TAG>=<LEVEL>

と記述しておくことでsetpropが不要になるようだ。

android.util.Logドキュメントのミス・・・では無いらしい。

StackOverflowでも話題になっているが、android.util.Logのドキュメントでは「Debugログは実行時にstripされる」と記載されている(20111-07-18時点)。

Verbose should never be compiled into an application except during development.
Debug logs are compiled in but stripped at runtime.
Error, warning and info logs are always kept.

実際は、最初の例で示したように実行時にもd()が呼ばれればDEBUGログが出力されてしまう。

仮にこのドキュメント通りであったとしても、setpropでログレベルを調整することによりDEBUGやVERBOSEレベルを実機上でログ出力させることは可能である。

開発者側としては、全てのログレベルが実機上で出力されることを前提としてLogクラスの各出力メソッドを使う必要があるだろう。

2013-12追記
JSSECのセキュアコーディングガイド【2013年4月1日版】によると、これはドキュメントのミスではなく、一般的にログとはこのような使い分けや実装になる、という一般論を記述している。記述されているような一般論に基づいて適切にログレベルを整理し、デバッグやテスト時と、リリース時とでログ出力のON/OFFを制御するために、APIで提供されている各種機能を活用していくことになる。具体的にはJSSECのセキュアコーディングガイドを参照のこと。

ProGuardを用いて特定のログレベルを無効化する手法

StackOverflowに紹介されている。以下の設定をProGuardの設定ファイルに追加する。

-assumenosideeffects class android.util.Log {
    public static int v(...);
}

ProGuardを有効にした状態で(Eclpse + ADTPluginならdefault.propertiesに "proguard.config=proguard.cfg" 追記)、Signed Packageを作成すると、Log.v()メソッド呼び出しがバイトコードレベルで除去される。

実際に上記ProGuard設定有り/無しでそれぞれSigned Packageを生成し、apktoolで展開、smaliファイルをdiffしてみる。

$ diff (ProGuard設定無し).smali  (ProGuard設定有り).smali
164,169d163
<     const-string v0, "tag1"
<
<     const-string v1, "tag1-verbose"
<
<     invoke-static {v0, v1}, Landroid/util/Log;->v(Ljava/lang/String;Ljava/lang/String;)I
<
193,198d186
<
<     const-string v0, "tag2"
<
<     const-string v1, "tag2-verbose"
<
<     invoke-static {v0, v1}, Landroid/util/Log;->v(Ljava/lang/String;Ljava/lang/String;)I

確かに Log.v() がバイトコードから除去されていることを確認できた。

このようにProGuardを使うことで、特定のログ出力をバイトコードレベルで無効化出来る。
デメリットとしては、いざ実機上で異常が発生した場合に、ログレベルを調整しても有用な詳細ログが取得できなくなる可能性が発生する。

３行でまとめ：

• if (isLoggable()) { Log.xxyy() } を徹底する。
• ログレベルはsetprop または /data/local.prop でtag単位で調整可能。基本全てのログレベルが出力されることを前提とする。
• ProGuardでバイトコードレベルで除去できるが、デメリットにも注意。

• [ Prev ]
• [ Next ]
• [ Up ]
• [ 技術 ]