Spring's @PreDestroy results in logging random

Question

I'm using Spring, and on termination I'm having @PreDestroy clean up beans. I don't understand why logging randomly succeeds sometimes, and fails on others.

// Using Log4j2
Logger log = LogManager.getLogger(MyClass.class);

@PreDestroy
public void close() {
    log.warn("Test");
}

Sometimes I will get nothing (no "Test" is logged), other times I will get:

[13:48:44] INFO  MyClass: Test

If I include System.out.println("Is this run?"); in the close() method, it will always print.

I'm not actually sure what is happening. I don't know if it's because the JVM is shutting down and the logger is killed... but I thought that would throw some kind of exception?

Note that the logging logs both to a file + stdout, I don't know if that would affect anything. Logging works fine for the other countless thousands of lines of code, but not this.

NOTE: I am open to switching logging libraries if it ends up being this particular library.

EDIT: MyClass would be a bean in a spring.xml document.

Answer 1

Exactly same as @Devon_C_Miller answer but updated to reflect latest version of log4j2

public class MonolithApplication {
  public static void main(String[] args) {
    AnnotationConfigApplicationContext context = new AnnotationConfigApplicationContext();
    context.refresh();
    Runtime.getRuntime().addShutdownHook(new Log4j2AwareShutdownHook(context));
  }
}

class Log4j2AwareShutdownHook extends Thread {
  private AbstractApplicationContext ctx;
  Log4j2AwareShutdownHook(AbstractApplicationContext ctx) {
    this.ctx = ctx;
  }
  public void run() {
    ctx.close();
    LogManager.shutdown();
  }
}

and in the log4j2 configuration

<?xml version="1.0" encoding="UTF-8"?>
<Configuration shutdownHook="disable">
    <Properties>
        <Property name="LOG_EXCEPTION_CONVERSION_WORD">%xEx</Property>
        <Property name="LOG_LEVEL_PATTERN">%5p</Property>
        <Property name="LOG_DATEFORMAT_PATTERN">yyyy-MM-dd HH:mm:ss.SSS</Property>
        <Property name="CONSOLE_LOG_PATTERN">%d{${LOG_DATEFORMAT_PATTERN}} ${LOG_LEVEL_PATTERN} %pid --- [%t] %-40.40c{1.} : %m%n${sys:LOG_EXCEPTION_CONVERSION_WORD}</Property>
    </Properties>
    <Appenders>
        <Console name="Console" target="SYSTEM_OUT">
            <PatternLayout pattern="${sys:CONSOLE_LOG_PATTERN}"/>
        </Console>
    </Appenders>
    <Loggers>
        <Logger name="com.acme" level="debug"/>
        <Root level="info">
            <AppenderRef ref="Console"/>
        </Root>
    </Loggers>
</Configuration>

Answer 2

I dont have enough reputation to add a comment, so i will answer here:

According to the JavaEE API javadoc:

• The method defined on a non-interceptor class MUST HAVE the following signature: void ()
• The method on which PreDestroy is applied MAY be public, protected, package private or private.
• The method MUST NOT be static.
• The method MAY be final.
• If the method throws an unchecked exception it is ignored except in the case of EJBs where the EJB can handle exceptions.

Check if an exception is being thrown somewhere else "silently", that might be one cause.

Answer 3

I think it comes down to this, from Runtime.addShutdownHook:

When the virtual machine begins its shutdown sequence it will start all registered shutdown hooks in some unspecified order and let them run concurrently.

So, as long as LogManager and the Spring IOC container are both shut down by JVM shutdown hooks, there is no way to ensure the message will be recorded. If the LogManager is shut down first, the message is lost. If the IOC container is shut down first, the message is recorded.

If you are running in a JEE container, there's probably little you can do to change this.

However, if you're running in a stand-alone environment, you can add a shutdownHook="disable" to the Log4j 2 <configuration> tag. This prevents Log4j 2 from registering it's own shutdown hook. Then, instead of calling ctx.registerShutdownHook() (the recommended way to shutdown the IOC), you register your own shutdown hook. Something like:

class MyShutdownHook extends Thread {
    private AbstractApplicationContext ctx;
    public MyShutdownHook(AbstractApplicationContext ctx) {
        this.ctx = ctx;
    }
    public void run() {
        ctx.close();
        Set<LoggerContext> contexts = new HashSet<>();
        for (Logger logger : LoggerContext.getLoggers()) {
            contexts.add(logger.getContext());
        }
        for (LoggerContext ctx : contexts) {
            Configurator.shutdown(LogManager.getContext());
        }
    }
}

AbstractApplicationContext ctx = /* create context */
Runtime.getRunTime().addShutdownHook(new MyShutdownHook(ctx);

Update: Corrected process of shutting down Log4j2.
Caveat: I am away from my usual build machines, so I have not compiled this, but I believe it's hitting the correct APIs.