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