「このログはどこのメソッドで吐いてるんだっけ…？」を少しだけ改善した方法 #Java

ログ出力をするコードで、よく見かけるのは以下のようなコードかなーと。

public static final String TAG = "Hoge"; // クラス名とかアプリ共通の文字列が定義されてる

Log.d(TAG, "call value:" + object.toString()); // っぽい感じでログ出力する

開発を進めていく中で、何も考えずにログ出力を書いておくと、出力されていくログが積もりに積もって膨大になり、必要な情報が埋もれて見つけにくい状況に陥りやすいです。

そんな状況になってしまった時、少しログの整理をしようとするも、

10-21 15:42:47.579  17406-17472/com.hoge.fuga D/HogeTag﹕ start HttpConnection // なるほど通信開始するんだな
10-21 15:42:47.579  17406-17472/com.hoge.fuga D/FugaTag﹕ ##### START!!! ##### // <- わかってるっつーの
10-21 15:42:47.579  17406-17472/com.hoge.fuga D/FugaTag﹕ POST value:piyo
10-21 15:42:47.579  17406-17472/com.hoge.fuga D/FugaTag﹕ url:http://xxx.xxx.xxx/xxx
10-21 15:44:03.102  17406-17472/com.hoge.fuga D/FugaTag﹕ ##### END!!! ##### // テンション高い
10-21 15:44:03.102  17406-17472/com.hoge.fuga D/FugaTag﹕ status:200
10-21 15:44:03.102  17406-17472/com.hoge.fuga D/FugaTag﹕ response:くぁｗせｄｒｆｔｇｙふじこ // ものっそい長いjsonとかズダーッってなる
10-21 15:44:03.129  17406-17472/com.hoge.fuga D/HogeTag﹕ finish HttpConnection

etc...

必要かどうか怪しいログが散乱してたりで、 「このログはどこのメソッドで吐いてるんだっけ…？」 と１つ１つ見つけては修正して…を繰り返すのは ヒジョー につらみを感じます。ログ出力の定義をある程度はチーム内で簡単に共有できればいいのですが、そこまでプライオリティは高く見れず、現実はそう簡単にウマくは行かなくて歯がゆいです。

なら、 「どのメソッドからログが出力されているのか」 という情報をログ自身から読み取れる Util クラスを作ってそれを使いまわすだけでもなんか良いんじゃね！と思い、調べて試してみました。

StackTrace

Java にはスタックトレースという、メソッド実行の順序を管理してくれたりする機能があり、それを使ってみました。

MainActivity.java

@Override
protected void onCreate(Bundle savedInstanceState) {
    super.onCreate(savedInstanceState);
    setContentView(R.layout.activity_main);

    Logger.d("call"); // 'call' の文字列だけを渡す
}

Logger.java

public static void d(String msg) {
    Log.d(getCallMethodName(), msg);
}

private static String getCallMethodName() {

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

    /**
     * この時のスタックトレース(ファイル名, クラス名, メソッド名)
     * 0, VMStack.java,      dalvik.system.VMStack,       getThreadStackTrace
     * 1, Thread.java,       java.lang.Thread,            getStackTrace
     * 2, Logger.java,       hoge.fuga.piyo.Logger,       getCallMethodName
     * 3, Logger.java,       hoge.fuga.piyo.Logger,       d
     * 4, MainActivity.java, hoge.fuga.piyo.MainActivity, onCreate
     *
     * etc...
     */

    if(elements.length < 5) return "";

    StackTraceElement element = elements[4];

    /**
     * 'android.os.Looper' のようにパッケージ名込みのクラス名を取得し、更に分割してクラス名だけ取得
     */
    String   className  = element.getClassName();
    String[] classNames = className.split("\\.");
    String   clazz = classNames[classNames.length - 1];

    // メソッド名を取得
    String method = element.getMethodName();

    // スレッドのIDを取得
    long id = Thread.currentThread().getId();

    return clazz + "#" + method + "[" + id + "]";
}

ログ出力結果

10-21 18:53:38.191   16543-16543/hoge.fuga.piyo D/MainActivity#onCreate[1]﹕ call

スタックトレースにより、 MainActivity の onCreate でログが出力されているという情報を、ログ自身に付与することができました。これで、 「どのメソッドからログが出力されているか」 を払拭できたと思います。また、StackTraceElement[] の配列数はメソッドの構成によっては差があるかもしれません。（getCallMethodName() を噛ませずに直接取得したら getStackTrace() から取得する要素数は１つ減りますね）

匿名クラス

ちなみに、匿名クラスで使うと…

MainActivity.java

@Override
protected void onStart() {
    super.onStart();

    new Thread(new Runnable() {
        @Override
        public void run() {
            Logger.d("call");
        }
    }).start();
}

結果は…

10-21 18:57:12.079    7068-7082/hoge.fuga.piyo D/MainActivity$1#run[4818]﹕ call

run メソッドから呼んでいるので onStart とは表示されませんでした。当然といえば当然ですね。

また副作用？として、ログ出力元のメソッドが分かるだけでなく、ログ出力コードのタイプ数が少しだけ少なくなったりと、精神衛生的にも良いかなと感じました。

・TAG を毎回書かなくても済む
・出力したい情報だけに意識を集中させることができる