技術/Android/LogAndLogLevelTips (v1)

• [ 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上でのログレベル
• 実機や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文字列は一致している必要がある。でないとチェックする意味がなくなってしまう。

実機や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クラスの各出力メソッドを使う必要があるだろう。

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 ]
• [ 技術 ]