기본 콘텐츠로 건너뛰기

[ JAVA ] JVM Shutdown 상황에서도 로그를 출력해 보자.

  현재 진행 중인 프로젝트는 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.<clinit> 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<Object>() {
        public Object run() {
            String cname = null;
            try {
                cname = System.getProperty("java.util.logging.manager");
                if (cname != null) {
                    try {
                        Class clz = ClassLoader.getSystemClassLoader().loadClass(cname);
                        manager = (LogManager) clz.newInstance();
                    } catch (ClassNotFoundException ex) {
                        Class clz = Thread.currentThread().getContextClassLoader().loadClass(cname);
                        manager = (LogManager) clz.newInstance();
                    }
                }
            } catch (Exception ex) {
                System.err.println("Could not load Logmanager \"" + cname + "\"");
                ex.printStackTrace();
            }
            if (manager == null) {
                manager = new LogManager();
            }

            ...
        }
    });
}
...
  위의 코드를 유추하면 사전에 "java.util.logging.manager" 에 설정된 클래스가 존재하면 LogManager  대신에 지정된 클래스의 인스턴스를 사용한다는 점이다. 이를 사용해서 LogManager를 상속한 별도의 LogManager를 사용하도록 지정하고 reset 부분을 변경하면 된다.

사용자 정의 LogManager 구성하기.

public class AgentLogger extends LogManager {
    static AgentLogger                instance;
    ...
    public AgentLogger() {
        instance = this;
    }
    ...
    private void overridedReset() {
        super.reset();
    }
    ...
    @Override
    public void reset() {
        // JVM Shutdown에서 유지될 수 있도록 제거
    }
    ...
    public static void resetFinally() {
        // JVM Shutdown 처리에서 호출되어야 함.
        if (instance != null) {
            instance.overridedReset();
        }
        shutdown();
    }
    ...
    public static void shutdown() {
        LOGGER.info("Logger shutting down");
        if (fileHandle != null) {
            try {
                fileHandle.flush();
                fileHandle.close();
                instance = null;
            } catch (Exception ex) {
                LOGGER.log(Level.WARNING, "Logger shutting down abnormally", ex);
            }
        }
    }
    ...
}
  위의 코드는 LogManager 의 "reset()" 에서는 아무 작업도 하지 않고 어플리케이션의 JVM Shutdown 처리에서 로그 처리가 끝난 후에 "resetFinally" 라는 메서드를 호출하여 Logger 처리를 Clear 하는 것이다. 별 것 아니기는 하지만 로그를 끝까지 남겨야 하는 상황에서는 하나의 해법이 될 수 있다.

  마지막으로 어플리케이션에서는 다음과 같이 호출하면 된다. 

...
// Agent 시작 시점에 LogManager에 대한 설정을 Custom LogManager로 설정한다.
System.setProperty("java.util.logging.manager", AgentLogger.class.getName());
...

// 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);
        } finally {
            AgentLogger.resetFinally();
        }
    }
}, Constants.ID_JVM_SHUTDOWN);
Runtime.getRuntime().addShutdownHook(shutdownThread);
*** 이 해법에는 한 가지 치명적인 단점이 존재한다.

  일반적인 어플리케이션에서 사용하는 것은 상관이 없지만 Java Agent 에 구현을 하고 Tomcat 등과 같이 내부적으로 LogManager를 사용하는 다른 어플리케이션을 사용하는 경우에는 Agent 에서 Log 처리가 제대로 수행이 되지만 Tomcat 이 구동될 때 conf 폴더에 존재하는 logging.properties 파일에 설정된 "1catalina.org.apache.juli.FileHandler", "2localhost.org.apache.juli.FileHandler" 등의 클래스를 찾을 수 없다는 Class Not Found Exception 이 발생할 수 있다. 이 오류가 발생하는 이유는 Agent 의 ClassLoader 는 Bootstrap 기준의 Class 들만을 알고 있기 때문에 java.util.logging.manager 에 설정된 AgentLogger 가 Tomcat 의 logging configuration 에 지정된 handler 들의 클래스를 찾을 수 없기 때문에 발생하게 된다. 즉, 쓰면 안된다는 것이다. ㅠㅠ

댓글