Log4j2 shutdown before it prints the last messages during graceful shutdown of spring boot application.

[Myslyvchuk]

Hi, I'm using spring boot with version 1.5.7.RELEASE. Also I'm using Log4j2 logger with excluding SimpleLogger from hateoas, data-jpa and adding dependencies for it.

<dependency>
      <groupId>org.springframework.boot</groupId>
      <artifactId>spring-boot-starter-hateoas</artifactId>
      <exclusions>
        <exclusion>
          <groupId>org.springframework.boot</groupId>
          <artifactId>spring-boot-starter-logging</artifactId>
        </exclusion>
      </exclusions>

    </dependency>
    <dependency>
      <groupId>org.springframework.boot</groupId>
      <artifactId>spring-boot-starter-log4j2</artifactId>
    </dependency>
    <dependency>
      <groupId>org.springframework.boot</groupId>
      <artifactId>spring-boot-starter-data-jpa</artifactId>
      <exclusions>
        <exclusion>
          <groupId>org.springframework.boot</groupId>
          <artifactId>spring-boot-starter-logging</artifactId>
        </exclusion>
      </exclusions>
    </dependency>

The main problem that U have code this is running in thread and has logger.

private void run() {
      while (!notStopped) {
        } catch (InterruptedException e) {
          logger.info("===============================================SHUTDOWN===============================================");
  }
     }
        }

@PreDestroy
  public void stop() throws InterruptedException {
      notStopped = true;
      SOME CODE
  }

So, the problem is that when I'm stopping the server with Crtl+C I'm expecting that logger will output

===============================================SHUTDOWN=============================================== 

but instead of that I'm receiving

Thread-3 WARN Unable to register Log4j shutdown hook because JVM is shutting down. Using SimpleLogger

When I'm deleting all dependencies for Log4j2 and deleting exclusions for logging from starters, it prints me the expected result SHUTDOWN.
As I understood there is a problem with shutdown hook of Log4j2. I found a related issues with Log4j2, and all of them described that it was problem in Log4j2 which would be fixed in 2.6 version. But now it is 2.7 version of Log4j2. How to fix this?

[Odyldzhon]

Looks like issue related to the log4j2 bug
https://issues.apache.org/jira/browse/LOG4J2-1902
There is no difference whether log4j shutdownHook disabled or not, log4j2 LoggerContext register shutdown hook in any case (((

public void start(final Configuration config) {
        ...
        if (configLock.tryLock()) {
            try {
                if (this.isInitialized() || this.isStopped()) {
                    if (this.configuration.isShutdownHookEnabled()) {
                        setUpShutdownHook();
                    }
                    this.setStarted();
                }
            } finally {
                configLock.unlock();
            }
        }
        setConfiguration(config);
        ...

[wilkinsona]

Based on the description above, I've tried to reproduce this using Spring Boot 1.5.12 and have been unable to do so. When I kill the application in such a way that the application context is closed, logging works as expected.

Given that it's not clear if this is a problem in Spring Boot or in Log4j2, I can't justify spending more time on this without a sample that reproduces the described problem. @Myslyvchuk if you'd like us to spend time trying to help you, please take the time to provide a sample.

[tsachev]

@wilkinsona I experienced the same problem and I know how to reproduce it.

I was willing to make a PR request for the issue, but could not decide which would be the right approach for spring boot and how to write a test that would handle regression.

Here some of my findings:

To reproduce it
Create a bean that sleeps for some time during its dispose method and then log.
The idea is the shutdown hook of the log4j2 to complete before the spring shutdown hook that closes the application context.

The thing is that SpringBootConfigurationFactory should not create a DefaultConfiguration becuase it registers a shutdown hook, no matter that the configuration is later replaced in Log4J2LoggingSystem#loadConfiguration.

One possible solution is to subclass the DefaultConfiguration and set register shutdown hook to false.

Maybe the built in xml files for log4j2 should also have shutdownHook="disable" attribute in their Configuration elements.

Another possible solution is to mimic what is done by the logback logging system. It stops and resets the context before loading the default spring boot configuration.
If you do this the same (stop the context) for log4j2 it should also remove the shutdown action. Anyway I am not sure what else this might cause. (also logback do not register a shutown hook by default, but only when add <shutdownHook class="ch.qos.logback.core.hook.DelayingShutdownHook"/> element.

To make things more interesting spring boot has its own facility shutdown the logger in a shutdown hook via logging.register-shutdown-hook property.

[wilkinsona]

Thanks very much, @tsachev. That's allowed me to reproduce the problem of the logging not appearing. I haven't been able to reproduce the warning about the shutdown hook registration, though.

Here's some code that reproduces the logging not appearing:

package com.example.demo;

import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.context.annotation.Bean;

@SpringBootApplication
public class Gh11360Application {

	public static void main(String[] args) {
		SpringApplication.run(Gh11360Application.class, args);
	}

	@Bean
	public SlowClose slowClose() {
		return new SlowClose();
	}

	public static class SlowClose {

		private Log logger = LogFactory.getLog(SlowClose.class);

		public void close() throws InterruptedException {
			Thread.sleep(5000);
			logger.info("Closed");
		}

	}

}

With the following dependencies there isn't even a need to kill or CTRL+C the application as a graceful shutdown happens automatically:

<dependency>
	<groupId>org.springframework.boot</groupId>
	<artifactId>spring-boot-starter</artifactId>
	<exclusions>
		<exclusion>
			<groupId>org.springframework.boot</groupId>
			<artifactId>spring-boot-starter-logging</artifactId>
		</exclusion>
	</exclusions>
</dependency>
<dependency>
	<groupId>org.springframework.boot</groupId>
	<artifactId>spring-boot-starter-log4j2</artifactId>
</dependency>

[wilkinsona]

A workaround is to set the log4j.shutdownHookEnabled system property to false very early in your application (before anything that does any logging is called):

public static void main(String[] args) {
	System.setProperty("log4j.shutdownHookEnabled", Boolean.toString(false));
	SpringApplication.run(Gh13360Application.class, args);
}

I think the right thing for Boot to do is to behave in the same way the Log4j does (or at least is intended to) with log4j-web on the classpath and disable the shutdown hook automatically as Log4j will be shutdown as part of the application context closing anyway. It remains to be seen if that's possible.