デバッグ用のログを出力させる - システム開発で思うところ

vermeer.hatenablog.jp

で、基本編的なところを整理しました。

今回は、アイディアネタ的な実装であるデバッグ用のログ出力機能についてメモを残します。

やりたいこと

実行時例外が発生したときにだけ、アクションの開始時点の情報を出力したい
出力ログファイルも別にしたい

実行時例外になったときに、アクションの開始時点*1の詳細情報を確認できる仕組みがあれば良いかもしれない、かといって、つねにアクションに関する情報をログへ出力したいわけではないというのがアイディアです。

開始時点の情報ですが、ActionクラスのtoStringメソッドの戻り値を出力します。独自のインターフェースを設けることも考えましたが、とりあえず toStringはオブジェクトの文字列情報を返却するという責務があるのだから、あまり深く考えずに toStringをそのまま使うことを前提にしました。
当然ですが、何もしないとクラス名とHashCodeを出力するだけなので、有効な情報はありません。 lombokを使うとか自分で実装するとか、まぁそういう手間は必要になります。とりあえず、仕組みを作るところまでを目標としました。

データを保持する

RequestScoped で、開始時点の情報を保持して（setUp）、実行時例外により処理が終了する際（tearDown）に出力させます。

@RequestScoped
public class LoggerStore {

    private Logger logger;
    private LoggerStoreItems items;
    private Class<?> triggerActionClass;
    private String startTitle;
    private String tearDownTitle;

    @PostConstruct
    public void init() {
        this.items = new LoggerStoreItems();
        this.startTitle = ">> Trace Logging Start >>";
        this.tearDownTitle = "<< Trace Logging  End  <<";
    }

    public void setUp(InvocationContext ic) {
        this.triggerActionClass = ic.getTarget().getClass().getSuperclass();
        this.logger = LoggerFactory.getLogger(LoggerName.LOGGER_STORE_SUB_NAME + "." + triggerActionClass.getName());
        this.append(ic, startTitle);
        this.append(ic, ic.getTarget().toString());
    }

    public void tearDown(Throwable throwable) {
        if (throwable != null) {
            Class<?> throwableClass = throwable.getClass();
            this.items.add(throwableClass, null, throwable, "");
        }
        this.items.add(triggerActionClass, null, null, tearDownTitle);
        this.items.logBy(logger);
    }

    public void append(InvocationContext ic, String message) {
        Class<?> actionClass = ic.getTarget().getClass().getSuperclass();
        Method actionMethod = ic.getMethod();
        this.items.add(actionClass, actionMethod, null, message);
    }

}

Interceptor

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

    @Inject
    private LoggerStore loggerStore;

    @AroundInvoke
    public Object invoke(InvocationContext ic) throws Exception {
        Action action = ic.getMethod().getAnnotation(Action.class);

        loggerStore.setUp(ic);

        if (action != null && action.value().equals(Action.Ignore.ON)) {
            return null;
        }

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

    }
}

ExceptionHandler

public class CustomExceptionHandler extends ExceptionHandlerWrapper {

    private final ExceptionHandler exceptionHandler;
    private final ThrowableHandlerFactory throwableHandlerFactory;
    private final ErrorPageNavigator errorPageNavigator;
    private final LoggerStore loggerStore;

    CustomExceptionHandler(ExceptionHandler exceptionHandler, ThrowableHandlerFactory throwableHandlerFactory,
                           ErrorPageNavigator errorPageNavigator, LoggerStore loggerStore) {
        this.exceptionHandler = exceptionHandler;
        this.throwableHandlerFactory = throwableHandlerFactory;
        this.errorPageNavigator = errorPageNavigator;
        this.loggerStore = loggerStore;
    }

    @Override
    public ExceptionHandler getWrapped() {
        return this.exceptionHandler;
    }

    @Override
    public void handle() {

        final Iterator<ExceptionQueuedEvent> it = getUnhandledExceptionQueuedEvents().iterator();

        while (it.hasNext()) {

            ExceptionQueuedEventContext eventContext = (ExceptionQueuedEventContext) it.next().getSource();

            Throwable causeThrowable = getRootCause(eventContext.getException()).getCause();
            Throwable throwable = causeThrowable != null
                                  ? causeThrowable
                                  : eventContext.getException().getCause();

            ThrowableHandler throwableHandler = this.throwableHandlerFactory.createThrowableHandler(throwable, eventContext);
            try {
                throwableHandler.execute();

            } catch (Exception ex) {
                this.errorPageNavigator.navigate(ex);

            } finally {
                this.loggerStore.tearDown(throwable);

                // 未ハンドリングキューから削除する
                it.remove();
            }

            getWrapped().handle();
        }

    }
}

Loggerの初期化

通常のログと違って、出力先の異なる別のLogger（storeLogger）に出力します。
FileHandlerを新たに設けることで実装しました。

[Java]Java SE標準ロギングのプロパティ設定で複数のファイルにログを分けて出力する - torutkのブログ
を参考にしました。

@ApplicationScoped
public class LoggerLifecycleHandler {

    private static final Logger rootLogger = Logger.getLogger(LoggerName.ROOT_NAME);
    private static final Logger storeLogger = Logger.getLogger(LoggerName.ROOT_NAME + "." + LoggerName.LOGGER_STORE_SUB_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();

        LoggerInitializer.builder()
                .rootLogger(storeLogger)
                .propertiesFilePath("/logging.properties")
                .consoleHandlerClass(LogConsoleHandler.class, LogConsoleFormatter.class)
                .fileHandlerClass(LogStoreFileHandler.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);

    }

}

Code

vermeer_etc / jsf-ddd / source / — Bitbucket

さいごに

開始時点の実装はしましたが、処理中の情報ををストックする実装は一旦保留としています。必須な気もしましたが、アイディア実装みたいなところもあるのでとりあえずベースとなる仕組みまでで止めておいて、有効活用するケースが具体的にあった時に拡張していけばよいかなと考えたためです。また、できればクラス名などをLoggerクラスのようにリクレクションで取得出来たら便利かな？と思って、実際の実装を見てみたのですが Java8以前と Java9以降では使っているライブラリが大きく違っていたというのも、一旦保留とした理由の１つです。*2

*1:今回は実装するのを保留にしましたが、必要であれば途中の状態も

*2:まだ EEに関する技術参考になりうるのは Java8に留めておいた方が良いだろうという考えもあっての判断でもあります。