Java の標準ロギングAPI JUL(java.util.logger) を少しマシにする

Java

JUL に対する不満

Java でログ出力する場合は、大抵 SLF4J + logback を使いますが、なるべく外部ライブラリに依存したくない時もあります(ちなみに SLF は Simple Logging Facade の略です)。

そんな時には Java 標準のログAPI Java.util.logger に手を出しますが、少し触ってやっぱり SLF4J + logback に戻っていく方が多いと思います。

ロガー取得時にクラスを引数にできなくて、何か違う。ログレベルに違和感を感じ、ログメッセージに可変長引数で埋め込みが出来なくてちょっと違う。 デフォルトでログが2行表示された時点で、やっぱり違う。という感じでしょうか。


public class Main {
    private static final Logger logger = Logger.getLogger(Main.class.getName());

    public static void main(String... args) throws Exception {
        logger.log(Level.SEVERE, "START");
        // ...
        logger.info("END");
    }
}

上記で出力されるログは以下のようになります。

2 10, 2017 1:23:45 午前 jp.co.foo.Main main
重大: START
2 10, 2017 1:23:45 午前 jp.co.foo.Main main
情報: END


ログレベルがローカライズされているのも不要ですし、午前 とか出されると検索しにくくなるからやめてほしいです。

秒単位の出力は本番運用時に困ることになること必至です。


logger.info() 形式で書くことに慣れていますが、引数として渡せるものが限られており、例外渡すときは logger.log(Level.SEVERE, ... ) の形式が必要だったりと IDE でサジェストで書いていきたい部分で手間だったりもします。


JUL の設定

ログの設定は、jre\lib\logging.properties にデフォルト設定が定義されています。

handlers= java.util.logging.ConsoleHandler
java.util.logging.ConsoleHandler.level = INFO
java.util.logging.ConsoleHandler.formatter = java.util.logging.SimpleFormatter


ハンドラが ConsoleHandler で、フォーマッタが SimpleFormatter となります。

フォーマットパターンは LoggingSupport.getSimpleFormat() で定義されており、以下のような設定がデフォルトです。


"%1$tb %1$td, %1$tY %1$tl:%1$tM:%1$tS %1$Tp %2$s%n%4$s: %5$s%6$s%n"


%2 の後に改行されてますね。パラメータとの対応は以下です。

  • %1 : ログレコードのイベント時間(Date)
  • %2 : 呼び出し元を表す文字列、使用できない場合はロガー名
  • %3 : ロガー名
  • %4 : ログレベル
  • %5 : ログレコードのメッセージ文字列
  • %6 : 例外時のスタックトレース


システムプロパティでログフォーマットを変える

Java7 からシステムプロパティで指定可能になりました。 以下のプロパティを設定しておくと

-Djava.util.logging.SimpleFormatter.format='%1$tY-%1$tm-%1$td %1$tH:%1$tM:%1$tS %4$s %2$s %5$s%6$s%n'


以下のようなログ出力となります。

2017-02-18 23:23:01 重大 jp.co.foo.Main main START
2017-02-18 23:23:01 情報 jp.co.foo.Main main END


ミリ秒単位まで出す場合は以下のような定義とします。

"%1$tY-%1$tm-%1$td %1$tH:%1$tM:%1$tS.%1$tL %4$s %2$s %5$s%6$s%n"


出力は以下のようになります。

2017-02-10 12:34:56.123 重大 jp.co.foo.Main main START
2017-02-10 12:34:56.124 情報 jp.co.foo.Main main END


System.setProperty で設定することもできます。

public static void main(String... args) throws Exception {
    System.setProperty("java.util.logging.SimpleFormatter.format",
          "%1$tY-%1$tm-%1$td %1$tH:%1$tM:%1$tS.%1$tL %4$s %2$s %5$s%6$s%n");
    // ...
}


logging.propertiesでログフォーマットを変える

LogManager にプロジェクト別の設定ファイルを読み込ませることで設定の変更が可能です。

public static void main(String... args) throws Exception {
     LogManager.getLogManager().readConfiguration(
             Main.class.getResourceAsStream("/logging.properties"));
     logger.log(Level.SEVERE, "START");
     // ...
     logger.info("END");
 }


jre\lib\logging.properties からコピーしてプロジェクト毎の設定に変更します。

handlers=java.util.logging.ConsoleHandler
.level=INFO
java.util.logging.ConsoleHandler.level=INFO
java.util.logging.ConsoleHandler.formatter=java.util.logging.SimpleFormatter
java.util.logging.SimpleFormatter.format=%1$tY-%1$tm-%1$td %1$tH:%1$tM:%1$tS.%1$tL %4$s %2$s %5$s%6$s%n


出力は以下のようになります。

2017-02-10 12:34:56.123 重大 jp.co.foo.Main main START
2017-02-10 12:34:56.124 情報 jp.co.foo.Main main END


ログレベルの表記を無理やり変える

grep しにくいので、ログレベルは英語表記にしたいところです。 Locale を変えればよいですが、全体に影響するのでやりたくないです。


ログレベルの名称は、rt.jar の以下の sun.util.logging.resources.logging_ja クラスで定義されています。

public final class logging_ja extends ListResourceBundle {
    protected final Object[][] getContents() {
        return new Object[][]{
        {"ALL", "すべて"}, {"CONFIG", "構成"}, {"FINE", "普通"}, 
        {"FINER", "詳細"}, {"FINEST", "最も詳細"}, {"INFO", "情報"}, 
        {"OFF", "オフ"}, {"SEVERE", "重大"}, {"WARNING", "警告"}};
    }
}


そしてこのリソースバンドルが Level クラスから参照されています。

public class Level implements java.io.Serializable {
    private static final String defaultBundle = "sun.util.logging.resources.logging";


ちなみに、ロガー側には logger.setResourceBundle() がありますが、これはメッセージ内容のローカライズに使われるので、Level 名称の書き換えとは関係ありません。

以下のような Bundle を用意します。

public class LogResourceBundle extends ListResourceBundle {
    protected final Object[][] getContents() {
        return new Object[][]{
        {"ALL", "ALL"}, {"CONFIG", "CONF"}, {"FINE", "FINE"},
        {"FINER", "FINE"}, {"FINEST", "FINE"}, {"INFO", "INFO"},
        {"OFF", "OFF"}, {"SEVERE", "SEVERE"}, {"WARNING", "WARN"}};
    }
}


リフレクションで SEVERE だけ無理やり書き換えます。

public class Main {
  private static final Logger logger = Logger.getLogger(Main.class.getName());
  public static void main(String... args) throws Exception {

    LogManager logManager = LogManager.getLogManager();
    logManager.readConfiguration(Main4.class.getResourceAsStream("/logging.properties"));

    Field field = Level.class.getDeclaredField("resourceBundleName");
    field.setAccessible(true);
    field.set(Level.SEVERE, LogResourceBundle.class.getName());

    logger.log(Level.SEVERE, "START");
    // ...
    logger.info("END");
}


以下のように出力されます。

2017-02-10 12:34:56.123 SEVERE jp.co.foo.Main main START
2017-02-10 12:34:56.124 情報 jp.co.foo.Main main END


Level の中ではローカライズしたレベル名称はキャッシュされるため、一度ローカライズ名にアクセスした後は、直接 localizedLevelName を書き換えることもできます。

Field field = Level.class.getDeclaredField("localizedLevelName");
field.setAccessible(true);
field.set(Level.SEVERE,  "SEVERE");


ログレベルの表記を素直に変える

ログ出力の形式は、Formatter を継承したカスタム Formatter を作れば自由にできます。

public class LogFormatter extends Formatter {
    @Override
    public String format(LogRecord record) {
        // ...
    }
}


そしてこれを、logging.properties に指定します。

java.util.logging.ConsoleHandler.formatter=co.jp.foo.LogFormatter


または、以下のように直接ロガーに設定することもできます。

Handler handler = new ConsoleHandler()
handler.setFormatter(new LogFormatter());

Logger root = Logger.getLogger("");
root.setUseParentHandlers(false);
for (Handler h : root.getHandlers()) {
    if (h instanceof ConsoleHandler) {
      root.removeHandler(h);
    } 
}
root.addHandler(handler);

Handler にカスタマイズした Formatter を設定し、この Handler を Logger に登録します。


Logger はロガー名で階層的に管理され、anonymous Logger と呼ばれるロガー名が空の Logger が根にいます。 この root に Handler 登録しています(root.setUseParentHandlers(false) は自身が親なので実際は不要です)。


Formatter を作る


日付フォーマット

フォーマッタの呪文のような定義でなく、単純に形式していして書き出します。

private static final DateTimeFormatter formatter = DateTimeFormatter.ofPattern("yyyy/MM/dd HH:mm:ss.SSS");

@Override
public String format(LogRecord record) {

    StringBuilder sb = new StringBuilder(200);

    Instant instant = Instant.ofEpochMilli(record.getMillis());
    LocalDateTime ldt = LocalDateTime.ofInstant(instant, ZoneId.systemDefault());
    sb.append(formatter.format(ldt));
    sb.append(" ");
    // ...
}


レベル名称

Bundle で面倒なことはせずに以下で良いでしょう。

private static final Map<Level, String> levelMsgMap = Collections.unmodifiableMap(
    new HashMap<Level, String>() {{
      put(Level.SEVERE,  "SEVERE");
      put(Level.WARNING, "WARN");
      put(Level.INFO,    "INFO");
      put(Level.CONFIG,  "CONF");
      put(Level.FINE,    "FINE");
      put(Level.FINER,   "FINE");
      put(Level.FINEST,  "FINE");
    }});

@Override
public String format(LogRecord record) {
    // ...
    sb.append(levelMsgMap.get(record.getLevel()));
    // ...
}


呼び出し元を表す文字列

java.util.logging のデフォルトの出力が2行表示になっている理由は、この呼び出し元文字列の長さが一定でなくメッセージ部分のインデントが揃わずに読みにくくなることに対応したものでしょう。

logback ではロガー名の省略が以下のように行われます。

設定 ロガー名 出力
%logger mainPackage.sub.sample.Bar mainPackage.sub.sample.Bar
%logger{0} mainPackage.sub.sample.Bar Bar
%logger{5} mainPackage.sub.sample.Bar m.s.s.Bar
%logger{10} mainPackage.sub.sample.Bar m.s.s.Bar
%logger{15} mainPackage.sub.sample.Bar m.s.sample.Bar
%logger{16} mainPackage.sub.sample.Bar m.sub.sample.Bar
%logger{26} mainPackage.sub.sample.Bar mainPackage.sub.sample.Bar


ここで作る Formatter は、このような省略で表示するようにします。

static String adjustLength(String packageName, int aimLength) {

    int overflowWidth = packageName.length() - aimLength;

    String[] fragment = packageName.split(Pattern.quote("."));
    for (int i = 0; i < fragment.length - 1; i++) {
        if (fragment[i].length() > 1 && overflowWidth > 0) {

            int cutting = (fragment[i].length() - 1) - overflowWidth;
            cutting = (cutting < 0) ? (fragment[i].length() - 1) : overflowWidth;

            fragment[i] = fragment[i].substring(0, fragment[i].length() - cutting);
            overflowWidth -= cutting;
        }
    }

    String result = String.join(".", fragment);
    while (result.length() < aimLength) {
        result += " ";
    }

    return result;
}


表示幅は小さい値から初めて超過する場合に大きくしていくようにします。

private AtomicInteger nameColumnWidth = new AtomicInteger(16);
 
@Override
public String format(LogRecord record) {
      // ...
        String category;
        if (record.getSourceClassName() != null) {
            category = record.getSourceClassName();
            if (record.getSourceMethodName() != null) {
                category += " " + record.getSourceMethodName();
            }
        } else {
            category =record.getLoggerName();
        }
        int width = nameColumnWidth.intValue();
        category = adjustLength(category, width);
        sb.append("[");
        sb.append(category);
        sb.append("] ");

        if (category.length() > width) {
            // grow in length.
            nameColumnWidth.compareAndSet(width, category.length());
        }
      // ...
}


以下のようにインデントを揃えた出力になります。

2017/02/19 02:40:11.490 INFO [j.c.fo.Main main] START
2017/02/19 02:40:11.523 INFO [j.c.fo.Main main] END


まとめ

まとめると、以下のような Formatter を用意することで、JUL が少しマシになります。

public class LogFormatter extends Formatter {

    private static final DateTimeFormatter formatter = DateTimeFormatter.ofPattern("yyyy/MM/dd HH:mm:ss.SSS");

    private static final Map<Level, String> levelMsgMap = Collections.unmodifiableMap(
            new HashMap<Level, String>() {{
                put(Level.SEVERE,  "SEVERE");
                put(Level.WARNING, "WARN");
                put(Level.INFO,    "INFO");
                put(Level.CONFIG,  "CONF");
                put(Level.FINE,    "FINE");
                put(Level.FINER,   "FINE");
                put(Level.FINEST,  "FINE");
            }});

    private AtomicInteger nameColumnWidth = new AtomicInteger(16);


    public static void applyToRoot() {
        applyToRoot(new ConsoleHandler());
    }


    public static void applyToRoot(Handler handler) {
        handler.setFormatter(new LogFormatter());
        Logger root = Logger.getLogger("");
        root.setUseParentHandlers(false);
        for (Handler h : root.getHandlers()) {
            if (h instanceof ConsoleHandler)
            root.removeHandler(h);
        }
        root.addHandler(handler);
    }


    @Override
    public String format(LogRecord record) {

        StringBuilder sb = new StringBuilder(200);

        Instant instant = Instant.ofEpochMilli(record.getMillis());
        LocalDateTime ldt = LocalDateTime.ofInstant(instant, ZoneId.systemDefault());
        sb.append(formatter.format(ldt));
        sb.append(" ");

        sb.append(levelMsgMap.get(record.getLevel()));
        sb.append(" ");


        String category;
        if (record.getSourceClassName() != null) {
            category = record.getSourceClassName();
            if (record.getSourceMethodName() != null) {
                category += " " + record.getSourceMethodName();
            }
        } else {
            category =record.getLoggerName();
        }
        int width = nameColumnWidth.intValue();
        category = adjustLength(category, width);
        sb.append("[");
        sb.append(category);
        sb.append("] ");

        if (category.length() > width) {
            // grow in length.
            nameColumnWidth.compareAndSet(width, category.length());
        }

        sb.append(formatMessage(record));

        sb.append(System.lineSeparator());
        if (record.getThrown() != null) {
            try {
                StringWriter sw = new StringWriter();
                PrintWriter pw = new PrintWriter(sw);
                record.getThrown().printStackTrace(pw);
                pw.close();
                sb.append(sw.toString());
            } catch (Exception ex) {
            }
        }

        return sb.toString();
    }



    static String adjustLength(String packageName, int aimLength) {

        int overflowWidth = packageName.length() - aimLength;

        String[] fragment = packageName.split(Pattern.quote("."));
        for (int i = 0; i < fragment.length - 1; i++) {
            if (fragment[i].length() > 1 && overflowWidth > 0) {

                int cutting = (fragment[i].length() - 1) - overflowWidth;
                cutting = (cutting < 0) ? (fragment[i].length() - 1) : overflowWidth;

                fragment[i] = fragment[i].substring(0, fragment[i].length() - cutting);
                overflowWidth -= cutting;
            }
        }

        String result = String.join(".", fragment);
        while (result.length() < aimLength) {
            result += " ";
        }

        return result;
    }
}



Effective Java 第3版

Effective Java 第3版

Amazon

プログラミング言語Java

プログラミング言語Java

Amazon

Head First Java: A Brain-Friendly Guide

Head First Java: A Brain-Friendly Guide

Amazon