현재 진행 중인 프로젝트는 Java Agent 를 이용해서 JVM 상에 구동되는 Application의 성능을 측정하기 위한 Custom Profiler를 구성하는 것이기에 Logging 정보가 상당히 중요하고, JVM Shutdown 되는 시점을 Hooking 하여 Agent 의 서비스들이 제대로 종료하는지를 검증하여야 한다.
그런데 JVM Shutdown Hooking 을 하게 되면 그 시점에 java.util.logging.LogManager 를 사용하고 있다면 Logger 들이 모두 Clear 되어 버리기 때문에 완전히 종료되는 시점까지 Logging 을 처리할 수 없다.
*** 지금부터 언급하는 상황들은 java.util.logging.LogManager를 사용하는 경우에 해당하는 것이므로 다른 logging 처리를 하는 경우에는 해당되지 않는다. 다만 처리되는 상황이 궁금한 경우는 참고가 될 수도 있다.
왜? Logger 가 모두 Clear 되는 것일까?
가장 먼저 문제가 되는 LogManager를 역 추적해 보도록 하자. 우선 어플리케이션에서 JVM Shutdown 을 Hooking 하는 방법은 아래와 같다.
// JVM Shutdown Hook Thread를 설정한다.
Thread shutdownThread = new Thread(new Runnable() {
@Override
public void run() {
try {
LOGGER.info("JVM Shutdown called");
shutdown();
LOGGER.info("JVM Shutdown complete");
} catch (Exception e) {
LOGGER.log(Level.SEVERE, "JVM Shutdown completed with errors", e);
}
}
}, Constants.ID_JVM_SHUTDOWN);
Runtime.getRuntime().addShutdownHook(shutdownThread);
위의 코드는 JVM 이 Shutdown 될 때 처리할 Thread를 생성하고 “Runtime.getRuntime().addShutdownHook” 메서드에 등록하여 JVM이 Shutdown 될 때 호출이 되도록 하는 것이다.
문제는 위의 코드 중에서 “JVM Shutdown called” 는 로그에 남겨지지만 이후 처리 중에 Logger 가 모두 Clear 되기 때문에 “JVM Shutdown complete” 는 로그에 남지 않는다는 것이다. 이 문제를 확인 하기 위해서는 LogManager를 검토해 봐야 한다. 아래의 코드는 java.util.logging.LogManager.class 의 내용으로 역시나 예상한 대로 JVM Shutdown 을 Hooking 하고 있는 것을 확인할 수 있다.
private LogManager(Void checked) {
// Add a shutdown hook to close the global handlers.
try {
Runtime.getRuntime().addShutdownHook(new Cleaner());
} catch (IllegalStateException e) {
// If the VM is already shutting down,
// We do not need to register shutdownHook.
}
}
위의 코드에서 JVM 종료시에 Cleaner 클래스를 생성하여 run 메서드가 호출되도록 설정한 것을 확인하였기 때문에 Cleaner 클래스를 찾아서 보면 아래의 코드를 확인할 수 있다.
// This private class is used as a shutdown hook.
// It does a "reset" to close all open handlers.
private class Cleaner extends Thread {
private Cleaner() {
/* Set context class loader to null in order to avoid
* keeping a strong reference to an application classloader.
*/
this.setContextClassLoader(null);
}
public void run() {
// This is to ensure the LogManager. is completed
// before synchronized block. Otherwise deadlocks are possible.
LogManager mgr = manager;
// If the global handlers haven't been initialized yet, we
// don't want to initialize them just so we can close them!
synchronized (LogManager.this) {
// Note that death is imminent.
deathImminent = true;
initializedGlobalHandlers = true;
}
// Do a reset to close all active handlers.
reset();
}
}
위의 코드를 확인하면 “reset()” 를 호출하여 모든 활성화된 Handler 들을 종료하는 것을 확인할 수 있다. 즉, Logger 가 Clear 된다고 보기 보다는 Logger 가 사용하고 있는 파일/콘솔 등의 출력 Handler 가 초기화되기 때문에 열심히 로그를 남겨봐야 출력이 되지 않는다는 것을 알 수 있다.
그럼 이런 문제를 해결하기 위해서는 어떤 방식을 사용하여야 할까???
해법이 전혀 없는 것은 아니다. LogManager의 정적 초기화 부분을 보면 이미 환경 (Java Options) 으로 설정된 값이 존재한다면 LogManager에 접근하면 설정된 Manager 가 재 설정되는 것을 확인할 수 있다.
...
static {
AccessController.doPrivileged(new PrivilegedAction
댓글
댓글 쓰기