Jakarta EEでjava.util.logging.Loggerを使ったLogging - システム開発で思うところ

vermeer.hatenablog.jp

で学んだことを駆使しつつ、自分なりの Jakarta EEでのLoggingの実装が大体整理できましたので、至る経緯と考察を残すためのメモ。

生成と破棄

これは、この記事のちょっとした続きです。

vermeer.hatenablog.jp

肝心の LogFileCloserの実装が漏れていました。
また、ちょっと追記もあります。
追記したのは、logger.removeHandler(h);のところです。
removeHandlerをしないと、ConsoleHandlerが残っていて開発中だと LoggerにHandlerがどんどん追加付与されてしまって、同じログが連続して出力されてしまいます。
FileHandlerの方は、closeだけでイイ感じにしてくれるみたいで重複出力は無かったんですけどね。

Java EE インジェクト可能なロガーの作り方と注意点 - Qiita
を参考にさせていただきました。

public class LogFileCloser {

    public void close(String rootLoggerName) {
        Logger logger = Logger.getLogger(rootLoggerName);
        for (Handler h : logger.getHandlers()) {
            h.close();
            logger.removeHandler(h);
        }
    }
}

また呼出し側もちょっと変えたのでそこに追記。
参考したものだと、RootとなるLoggerだけにHandlerを付与するので問題なかったのですが、複数のHandlerをもったLoggerをRoot配下に設けたい場合には、機能として不足していたのでちょっと追記。

@ApplicationScoped
public class LoggerLifecycleHandler {

（略）

    public void shutdown(@Observes @Destroyed(ApplicationScoped.class) Object event) {
        System.out.println("<< Cleanup:Closing logging file <<");
        LogFileCloser logFileCloser = new LogFileCloser();

        Collections.list(LogManager.getLogManager().getLoggerNames()).stream()
                .filter(name -> name.startsWith(LoggerName.ROOT_NAME))
                .forEach(logFileCloser::close);
    }
}

フォーマット

Console用と、File用のフォーマットをそれぞれ準備しました。
とはいえ、基本的な出力は同じなので、LogRecordConverterとして、編集ロジック自体は共通化しました。

JUL を少しマシにする - A Memorandum
を参考にさせていただきました。

手を加えたところのポイント

System.lineSeparator()の位置
短縮形の要否

Fileと違って Consoleは出力都度自動で改行が入るのでタイミングを変えています。
また、Consoleは開発時に出力ウィンドウに出力された内容を確認するために使うのでクラス名が分かれば十分なので短縮形で良いのですが、Fileは運用時とかより正確な情報が欲しいと思ったので短縮形表記を止めました。
このあたりは設計思想というかそのあたりによって考え方が変わると思います。

public class LogRecordConverter {

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

    private static final Map<Level, String> levelMsgMap = Collections.unmodifiableMap(new HashMap<Level, String>() {
        private static final long serialVersionUID = 1L;

        {
            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 static final AtomicInteger nameColumnWidth = new AtomicInteger(32);

    private final LocalDateTime dateTime;
    private final Level logLevel;
    private final String className;
    private final String methodName;
    private final Throwable throwable;
    private final String message;

    private LogRecordConverter(LocalDateTime dateTime, Level logLevel, String className, String methodName, Throwable throwable, String message) {
        this.dateTime = dateTime;
        this.logLevel = logLevel;
        this.className = className;
        this.methodName = methodName;
        this.throwable = throwable;
        this.message = message;
    }

    public static LogRecordConverter of(LocalDateTime dateTime, Level logLevel, String className, String methodName, Throwable throwable, String message) {
        return new LogRecordConverter(dateTime, logLevel, className, methodName, throwable, message);
    }

    public String toConsole() {
        StringBuilder sb = new StringBuilder(300);
        this.appendCommonRecord(sb);
        this.appendShorteningCategoryAndMessage(sb);

        if (this.throwable != null) {
            sb.append(System.lineSeparator());
            this.appendThrown(sb);
        }
        return sb.toString();
    }

    public String toFile() {
        StringBuilder sb = new StringBuilder(300);
        this.appendCommonRecord(sb);
        this.appendCategoryAndMessage(sb);

        sb.append(System.lineSeparator());
        if (this.throwable != null) {
            this.appendThrown(sb);
        }
        return sb.toString();
    }

    private void appendCommonRecord(StringBuilder sb) {
        sb.append(this.timeStamp());
        sb.append(" ");

        sb.append(levelMsgMap.get(this.logLevel));
        sb.append(" ");
    }

    private void appendShorteningCategoryAndMessage(StringBuilder sb) {
        int width = nameColumnWidth.intValue();
        String category = adjustCategoryLength(baseCategory(), width);
        sb.append("[[");
        sb.append(category);
        sb.append("]] ");
        this.updateNameColumnWidth(width, category.length());

        sb.append(message);
    }

    private void appendCategoryAndMessage(StringBuilder sb) {
        sb.append("[[");
        sb.append(baseCategory());
        sb.append("]] ");
        sb.append(message);
    }

    private void appendThrown(StringBuilder sb) {
        StringWriter sw = new StringWriter();
        try (PrintWriter pw = new PrintWriter(sw)) {
            this.throwable.printStackTrace(pw);
        }
        sb.append(sw.toString());
    }

    private String timeStamp() {
        return formatter.format(dateTime);
    }

    private String baseCategory() {
        return className == null
               ? ""
               : methodName == null
                 ? className
                 : className + "#" + methodName;
    }

    private String adjustCategoryLength(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 (1 < fragment[i].length() && 0 < overflowWidth) {

                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);

        int cnt = aimLength - result.length();
        if (cnt <= 0) {
            return result;
        }
        String blank = new String(new char[cnt]).replace("\0", " ");
        return result + blank;
    }

    private void updateNameColumnWidth(int width, int categoryLength) {
        if (width < categoryLength) {
            nameColumnWidth.compareAndSet(width, categoryLength);
        }
    }
}

Handlerへの設定は、コンテナ起動時に一度だけ実施すれば良いので、以下のクラスを作りました。*1

Java EEアプリケーションで起動時になにかしらの処理をする方法 — 裏紙
を参考にして、Serveletに依存させず、CDIだけで初期化処理を行っています。

@ApplicationScoped
public class LoggerLifecycleHandler {

    private static final Logger rootLogger = Logger.getLogger(LoggerName.ROOT_NAME);
（略）

    public void startUp(@Observes @Initialized(ApplicationScoped.class) Object event) {
        System.out.println(">> Startup:Initialize RootLogger >>");
        LoggerInitializer.builder()
                .rootLogger(rootLogger)
                .propertiesFilePath("/logging.properties")
                .consoleHandlerClass(LogConsoleHandler.class, LogConsoleFormatter.class)
                .fileHandlerClass(LogFileHandler.class, LogFileFormatter.class)
                .execute();

　　（略）
    }

    public void shutdown(@Observes @Destroyed(ApplicationScoped.class) Object event) {
        System.out.println("<< Cleanup:Closing logging file <<");
        LogFileCloser logFileCloser = new LogFileCloser();

        Collections.list(LogManager.getLogManager().getLoggerNames()).stream()
                .filter(name -> name.startsWith(LoggerName.ROOT_NAME))
                .forEach(logFileCloser::close);
    }
}

初期設定するクラスLoggerInitializerにおけるポイントは
setUseParentHandlersです。

これも、ConsoleとFileで扱いが微妙に違ったというか、そういう理由です。

Fileだと、setUseParentHandlers(false)を指定しなくても問題ないのですが、ConsoleはデフォルトのLoggerに伝播しているか、EEサーバ側が内部的に伝播しているか良く分かりませんが、２行ログが出力されるために必要な実装でした。

public class LoggerInitializer {

（略）

    public static class Builder implements RootLoggerBuilder, PropertiesFileBuilder {
        public void execute() {

            this.initConsoleFormatter();
            this.setConsoleHander();

            this.initFileFormatter();
            this.setFileHander();

            this.rootLogger.setUseParentHandlers(false);
        }

（略）

}

Interceptorとの連携

Java EEのCDIで定義しておくと便利なプロデューサーとインターセプタ - きしだのはてなを参考にさせていただきました。

InvocationContext を使うことで、実行元の情報を取得する事が出来ます。

ただ、このやり方だとGCのタイミングで問題が起こる可能性があるかもしれないです。

参考
ログレベルが突然変わる謎の事象を追う～あるOSSサポートエンジニアの1日 - Qiita

ということで、上述で示した強参照の RootLogger配下に強制するように Loggerの生成は、簡単なクラス（LogFactory）を作りました。
ただし、直接使うのではなく、InterceptorとかProducer経由でLoggerを生成する前提にしようと思っていたので、このクラスについては default*2にしました。

class LoggerFactory {

    private LoggerFactory() {
    }

    static Logger getLogger(String name) {
        return Logger.getLogger(LoggerName.ROOT_NAME + "." + name);
    }

}

加えて、InvocationContextからLoggerに必要な情報を取得できるようなクラスを作りました。

public class InvocationContextLogger {

    private final String actionClass;
    private final String actionMethod;
    private final Logger logger;

    private InvocationContextLogger(Logger logger, String actionClass, String actionMethod) {
        this.logger = logger;
        this.actionClass = actionClass;
        this.actionMethod = actionMethod;
    }

    public static InvocationContextLogger getLogger(InvocationContext ic) {
        String actionClass = ic.getTarget().getClass().getSuperclass().getName();
        String actionMethod = ic.getMethod().getName();
        Logger logger = LoggerFactory.getLogger(actionClass);
        return new InvocationContextLogger(logger, actionClass, actionMethod);
    }

    public void severe(Supplier<String> msgSupplier) {
        logger.logp(Level.SEVERE, actionClass, actionMethod, msgSupplier);
    }

（省略）

}

実際に使用しているところ(抜粋）。
当初、LogeerFactoryを使うやり方で考えていたのですが、戻り値を InvocationContextLoggerとすることを鑑みて、別クラスにしました。
ちなみに、Loggerがインターフェースだったら方式を変えた可能性があります。

@Action
@Interceptor
@Priority(Interceptor.Priority.APPLICATION + 5)
public class ActionInterceptor {

（略）
    @AroundInvoke
    public Object invoke(InvocationContext ic) throws Exception {

     （略）

        InvocationContextLogger logger = InvocationContextLogger.getLogger(ic);
        try {
            logger.fine(() -> "start");
            return ic.proceed();
        } finally {
            logger.fine(() -> "end");
        }

    }
}

Code

vermeer_etc / jsf-ddd / source / — Bitbucket

さいごに

いったん、基本的な実装まで。次にデバッグ用にアイディアネタ的な仕組みも実装したので、それについて書きたいと思います。

*1:過去の記事でも取り上げ済みの再掲です

*2:パッケージプライベート