で、基本編的なところを整理しました。
今回は、アイディアネタ的な実装である デバッグ用のログ出力機能について メモを残します。
やりたいこと
- 実行時例外が発生したときにだけ、アクションの開始時点の情報を出力したい
- 出力ログファイルも別にしたい
実行時例外になったときに、アクションの開始時点*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
