Developer's Blog

Android のログ出力をスマートに


blog_picture

こんにちは。東京で開発担当をしています志田です。
初のブログ執筆となりますが、 この度は私の知っているノウハウを少しでも共有できればと思い拙い筆を、もとい叩き慣れたキーボードを手に取って云々という次第です。

今日のテーマはずばり Android 開発における “スマートな” ログ出力について!! です。

基本中の基本と言える内容ではありますがそれ故に大事な部分でありますので、どうログを出力するのが最適かわからない、という場合に参考にしていただければと思います。

 

ありがちなログ出力

 

とりあえず何も考えずに android.util.Log クラスを使ってログを出力するとこんな感じになるかと思います。

public class BeforeActivity extends Activity {

    private static final String LOG_TAG = "Before";

    private static final int REQUEST_CODE_AFTER = 1;

    @Override
    protected void onCreate(Bundle savedInstanceState) {
        super.onCreate(savedInstanceState);
        Log.d(LOG_TAG, "onCreate()");

        Intent intent = new Intent(getApplicationContext(), AfterActivity.class);
        startActivityForResult(intent, REQUEST_CODE_AFTER);
    }

    @Override
    protected void onResume() {
        super.onResume();
        Log.d(LOG_TAG, "onResume()");
    }

    @Override
    protected void onPause() {
        super.onPause();
        Log.d(LOG_TAG, "onPause()");
    }

    @Override
    protected void onActivityResult(int requestCode, int resultCode, Intent data) {
        super.onActivityResult(requestCode, resultCode, data);
        Log.d(LOG_TAG, "onActivityResult() requestCode=" + requestCode + " resultCode="
                + resultCode);
    }
}

※ onCreate() の中で違う Activity を起動するという謎行為をしていますが、ログ出力用のものなのでここではひとまず目を伏せて口に出さないようにしてください。

どうでしょう。皆さんはこのような書き方はしていないでしょうか。
メソッドの入口でログを出力することはよくあると思いますが、その度に “onResume()” やら “onPause()” やらをまたかと思いながら、ちまちまちまちま書くのは非常にしんどい作業です。クリエイティブワークの欠片もありません。21世紀のご時世にこんなことをしていてはいけません!!

何より疲れてくるとついうっかり “onCreite()” なんて恥ずかしい誤字を使ってしまうかもしれませんし、自動でできるものはできる限り自動に頼るべきです!!
…決して怠けれているわけではありませんよ??

 

ログの基本情報はスタックトレースから取得する

 

メソッド名はわざわざ自分で記述しなくてもスタックトレースとして勝手に保持してくれている情報です。であればそこから拝借してログメッセージに追加するようにしてしまいましょう。
スタックトレースはこんな感じで取得できます。

StackTraceElement[] elements = Thread.currentThread().getStackTrace();

StackTraceElement の配列が取得でき、配列のサイズは現在のスタック状況に依存します。目的の情報がどこの index に収まっているかは実装次第で変わってくるので注意が必要です。

以下にログ出力用クラスのサンプルを示します。ログの種類は DEBUG の他に INFO や ERROR 等複数ありますが、あまりソースが長くなってしまってもあれなので今回は DEBUG のみを対象にしています。

public class SampleLogUtil {

    // **********************************************************************
    // 定数
    // **********************************************************************

    private static final String TAG = "After";

    // **********************************************************************
    // メンバ
    // **********************************************************************

    private static boolean mIsShowLog = false;

    // **********************************************************************
    // パブリックメソッド
    // **********************************************************************

    public static void setShowLog(boolean isShowLog) {
        mIsShowLog = isShowLog;
    }

    public static void logDebug() {
        outputLog(Log.DEBUG, null, null);
    }

    public static void logDebug(String message) {
        outputLog(Log.DEBUG, message, null);
    }

    public static void logDebug(String message, Throwable throwable) {
        outputLog(Log.DEBUG, message, throwable);
    }

    // **********************************************************************
    // プライベートメソッド
    // **********************************************************************

    private static void outputLog(int type, String message, Throwable throwable) {
        if (!mIsShowLog) {
            // ログ出力フラグが立っていない場合は何もしません。
            return;
        }

        // ログのメッセージ部分にスタックトレース情報を付加します。
        if (message == null) {
            message = getStackTraceInfo();
        } else {
            message = getStackTraceInfo() + message;
        }

        // ログを出力!
        switch (type) {
            case Log.DEBUG:
                if (throwable == null) {
                    Log.d(TAG, message);
                } else {
                    Log.d(TAG, message, throwable);
                }
                break;
        }
    }

    /**
     * スタックトレースから呼び出し元の基本情報を取得。
     * 
     * @return <<className#methodName:lineNumber>>
     */
    private static String getStackTraceInfo() {
        // 現在のスタックトレースを取得。
        // 0:VM 1:スレッド 2:getStackTraceInfo() 3:outputLog() 4:logDebug()等 5:呼び出し元
        StackTraceElement element = Thread.currentThread().getStackTrace()[5];

        String fullName = element.getClassName();
        String className = fullName.substring(fullName.lastIndexOf(".") + 1);
        String methodName = element.getMethodName();
        int lineNumber = element.getLineNumber();

        return "<<" + className + "#" + methodName + ":" + lineNumber + ">> ";
    }
}

キモとなるのは一番下にある getStackTraceInfo メソッドですね。
StackTraceElement を取得し、呼び出し元のクラス名、メソッド名、およびソースコード上の行数が含まれた文字列を生成します。
今回はログクラスの構造上、 index 5 の位置に呼び出し元の情報が入っています。詳細はコメントを参考にしてください。

 

アプリリリース時は必ずログの出力を停止する

 

ログの出力はデバッグ時とリリース時で明確に切り替えるべきです。プログラマの義務です!!(強調)
リリースビルドでだらだらログを出力させるわけにはいきません。

ここでは SampleLogUtil#setShowLog(boolean isShowLog) メソッドでログ出力フラグを切り替えるようにしています。このメソッドの呼び出しは Application クラスで行うようにします。

public class SampleApplication extends Application {

    @Override
    public void onCreate() {
        super.onCreate();

        // 設定ファイルのフラグを読み取ってログ出力を切り替えます。
        boolean isShowLog = getResources().getBoolean(R.bool.isShowLog);
        SampleLogUtil.setShowLog(isShowLog);
    }
}

こんな感じで Application#onCreate() の中でフラグを設定するようにしておきます。
ここでリソースファイルからフラグを取得してきていますが、これは Ant 単体、もしくは Ant と Jenkins を組み合わせてビルドすることを見越してのことです。

Android_log_config

values の中に configs.xml なるファイルがありますね。
ここにフラグを保持しておき、 Ant でビルドする際にここの部分を書き換えるようにしておきます。

Ant や Jenkins について具体的に書き出すと日が暮れて鶏さんが鳴き出すまでいっても終わらない気がしますので、ここではひとまず紹介のみにとどめておきます。ご容赦を。

ちなみに自前の Application クラスを使う場合は AndroidManifest.xml の Application タグ書き換えを忘れないように注意しましょう。

Android_log_manifest

 

そしてログ出力はここまで進歩した

 

さてさて、いよいよ先ほど作成したログ出力クラスを使ってログを出力してみましょう。
冒頭の BeforeActivity に対してログ出力クラスを使うようにした AfterActivity を比較します。
※ 比較のため冒頭と同じ BeforeActivity をもう一度表示します。

public class BeforeActivity extends Activity {

    private static final String LOG_TAG = "Before";

    private static final int REQUEST_CODE_AFTER = 1;

    @Override
    protected void onCreate(Bundle savedInstanceState) {
        super.onCreate(savedInstanceState);
        Log.d(LOG_TAG, "onCreate()");

        Intent intent = new Intent(getApplicationContext(), AfterActivity.class);
        startActivityForResult(intent, REQUEST_CODE_AFTER);
    }

    @Override
    protected void onResume() {
        super.onResume();
        Log.d(LOG_TAG, "onResume()");
    }

    @Override
    protected void onPause() {
        super.onPause();
        Log.d(LOG_TAG, "onPause()");
    }

    @Override
    protected void onActivityResult(int requestCode, int resultCode, Intent data) {
        super.onActivityResult(requestCode, resultCode, data);
        Log.d(LOG_TAG, "onActivityResult() requestCode=" + requestCode + " resultCode="
                + resultCode);
    }
}

public class AfterActivity extends Activity {

    private static final int REQUEST_CODE_EMPTY = 2;

    @Override
    protected void onCreate(Bundle savedInstanceState) {
        super.onCreate(savedInstanceState);
        SampleLogUtil.logDebug();

        Intent intent = new Intent(getApplicationContext(), EmptyActivity.class);
        startActivityForResult(intent, REQUEST_CODE_EMPTY);
    }

    @Override
    protected void onResume() {
        super.onResume();
        SampleLogUtil.logDebug();
    }

    @Override
    protected void onPause() {
        super.onPause();
        SampleLogUtil.logDebug();
    }

    @Override
    protected void onActivityResult(int requestCode, int resultCode, Intent data) {
        super.onActivityResult(requestCode, resultCode, data);
        SampleLogUtil.logDebug("requestCode=" + requestCode + " resultCode=" + resultCode);
    }
}

どうでしょうか。
それなりに (?) すっきりした感があるのではないでしょうか。

ちなみに出力されるログは以下のような感じになります。
※ ログ出力時間は省略しています。

D/Before(20392): onCreate()
D/Before(20392): onResume()
D/Before(20392): onPause()
D/After(20392): <<AfterActivity#onCreate:15>> 
D/After(20392): <<AfterActivity#onResume:24>> 
D/After(20392): <<AfterActivity#onPause:30>> 
D/After(20392): <<AfterActivity#onActivityResult:36>> requestCode=2 resultCode=0
D/After(20392): <<AfterActivity#onResume:24>> 
D/After(20392): <<AfterActivity#onPause:30>> 
D/Before(20392): onActivityResult() requestCode=1 resultCode=0
D/Before(20392): onResume()

D/Before に比べて D/After は基本情報が増えてより分かりやすい感じになっています。もし出力フォーマットを変更したくなった場合でも、メソッドを1つ変更するだけで済みます。直接ログを出力していた場合に全てのログ出力を書き直すなんて嫌ですよね。あり得ないですよね。。
自動化こそ正義!怠け者の人類の叡智の結晶です!!

個別にログのタグを切り替えたいとなるともちろんこの構成では足りませんが、ここまでできていれば後はいかようにでもカスタマイズできるかと思います。
例えば LogCat にログを出力するだけでは飽き足らず、ファイルとしてログを出力したい等の要望が出るかも知れません。自分のプロジェクトにあった形にどんどんカスタマイズしていきましょう。

 

それでは本日のところはここまでで失礼させていただきます。
ぜひ無駄な手間を省いて快適なプログラミングライフを。。

最後までお読み頂きありがとうございます。

 

 

 

Copyright © 2019 Fenrir Inc. All rights reserved.