example.zip is a very simple project, I deployed it to standalone tomcat refer to https://docs.spring.io/spring-boot/docs/current/reference/html/howto.html#howto.traditional-deployment
There are 2 problems:
1. log in @PreDestroy is not output because log system is shutdown too early by LoggingApplicationListener::onContextClosedEvent
2. tomcat will wait 10s to finish shutdown
package example;
import javax.annotation.PostConstruct;
import javax.annotation.PreDestroy;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.boot.builder.SpringApplicationBuilder;
import org.springframework.boot.web.servlet.support.SpringBootServletInitializer;
@SpringBootApplication
public class MainApplication extends SpringBootServletInitializer {
private Logger logger = LoggerFactory.getLogger(getClass());
public static void main(String[] args) throws Exception {
SpringApplication.run(MainApplication.class, args);
}
@Override
protected SpringApplicationBuilder configure(SpringApplicationBuilder application) {
return application.sources(getClass());
}
@PostConstruct
private void init() {
logger.warn("init: " + this);
System.out.println("init: " + this);
}
@PreDestroy
private void destroy() {
logger.warn("destroy: " + this);
System.out.println("destroy: " + this);
}
}
2021-09-15 11:24:35.615 INFO 27966 --- [ main] example.MainApplication : Starting MainApplication using Java 11.0.12 on MyiMac with PID 27966 (/Users/zhouyanming/apache-tomcat-9.0.53/webapps/example-1.0.0-SNAPSHOT/WEB-INF/classes started by zhouyanming in /Users/zhouyanming)
2021-09-15 11:24:35.618 INFO 27966 --- [ main] example.MainApplication : No active profile set, falling back to default profiles: default
2021-09-15 11:24:36.273 INFO 27966 --- [ main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 607 ms
2021-09-15 11:24:36.418 WARN 27966 --- [ main] ication$$EnhancerBySpringCGLIB$$c8f12ab1 : init: example.MainApplication$$EnhancerBySpringCGLIB$$c8f12ab1@1806bc4c
init: example.MainApplication$$EnhancerBySpringCGLIB$$c8f12ab1@1806bc4c
2021-09-15 11:24:36.766 INFO 27966 --- [ main] example.MainApplication : Started MainApplication in 1.596 seconds (JVM running for 2.629)
15-Sep-2021 11:24:36.795 INFO [main] org.apache.catalina.startup.HostConfig.deployWAR Deployment of web application archive [/Users/zhouyanming/apache-tomcat-9.0/webapps/example-1.0.0-SNAPSHOT.war] has finished in [2,004] ms
15-Sep-2021 11:24:36.798 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["http-nio-8080"]
15-Sep-2021 11:24:36.811 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in [2051] milliseconds
^C15-Sep-2021 11:24:41.365 INFO [Thread-3] org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler ["http-nio-8080"]
15-Sep-2021 11:24:41.373 INFO [Thread-3] org.apache.catalina.core.StandardService.stopInternal Stopping service [Catalina]
destroy: example.MainApplication$$EnhancerBySpringCGLIB$$c8f12ab1@1806bc4c
15-Sep-2021 11:24:41.514 INFO [Thread-3] org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler ["http-nio-8080"]
15-Sep-2021 11:24:51.520 WARNING [Thread-3] org.apache.tomcat.util.net.Acceptor.stop The acceptor thread [http-nio-8080-Acceptor] did not stop cleanly
15-Sep-2021 11:24:51.525 INFO [Thread-3] org.apache.coyote.AbstractProtocol.destroy Destroying ProtocolHandler ["http-nio-8080"]
Comment From: wilkinsona
Thanks for the report but I can't reproduce the 10 second pause that you have described. I used Tomcat 9.0.53 which produced the following log output:
15-Sep-2021 07:58:30.640 INFO [main] org.apache.catalina.startup.HostConfig.deployWAR Deploying web application archive [/Users/awilkinson/Downloads/example/apache-tomcat-9.0.53/webapps/ROOT.war]
15-Sep-2021 07:58:32.012 INFO [main] org.apache.jasper.servlet.TldScanner.scanJars At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.
. ____ _ __ _ _
/\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
\\/ ___)| |_)| | | | | || (_| | ) ) ) )
' |____| .__|_| |_|_| |_\__, | / / / /
=========|_|==============|___/=/_/_/_/
:: Spring Boot :: (v2.5.4)
2021-09-15 07:58:32.701 INFO 20505 --- [ main] example.MainApplication : Starting MainApplication using Java 11.0.10 on wilkinsona-a01.vmware.com with PID 20505 (/Users/awilkinson/Downloads/example/apache-tomcat-9.0.53/webapps/ROOT/WEB-INF/classes started by awilkinson in /Users/awilkinson/Downloads/example)
2021-09-15 07:58:32.704 INFO 20505 --- [ main] example.MainApplication : No active profile set, falling back to default profiles: default
2021-09-15 07:58:33.454 INFO 20505 --- [ main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 717 ms
2021-09-15 07:58:33.595 WARN 20505 --- [ main] ication$$EnhancerBySpringCGLIB$$4186ba4a : init: example.MainApplication$$EnhancerBySpringCGLIB$$4186ba4a@27311c99
init: example.MainApplication$$EnhancerBySpringCGLIB$$4186ba4a@27311c99
2021-09-15 07:58:33.965 INFO 20505 --- [ main] example.MainApplication : Started MainApplication in 1.738 seconds (JVM running for 4.043)
15-Sep-2021 07:58:33.994 INFO [main] org.apache.catalina.startup.HostConfig.deployWAR Deployment of web application archive [/Users/awilkinson/Downloads/example/apache-tomcat-9.0.53/webapps/ROOT.war] has finished in [3,353] ms
15-Sep-2021 07:58:33.996 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["http-nio-8080"]
15-Sep-2021 07:58:34.005 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in [3411] milliseconds
^C15-Sep-2021 07:58:39.475 INFO [Thread-3] org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler ["http-nio-8080"]
15-Sep-2021 07:58:39.486 INFO [Thread-3] org.apache.catalina.core.StandardService.stopInternal Stopping service [Catalina]
destroy: example.MainApplication$$EnhancerBySpringCGLIB$$4186ba4a@27311c99
15-Sep-2021 07:58:39.503 INFO [Thread-3] org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler ["http-nio-8080"]
15-Sep-2021 07:58:39.533 INFO [Thread-3] org.apache.coyote.AbstractProtocol.destroy Destroying ProtocolHandler ["http-nio-8080"]
The acceptor thread taking in excess of 10 seconds to stop doesn't feel to me like it's related to Spring Boot as it has no control of Tomcat at this level.
The logging problem may be related to https://github.com/spring-projects/spring-boot/issues/9457, although we thought that only affected JUL-based logging and you're using SLF4J and Logback. Regardless, I'm reluctant to spend time debugging it until we can reproduce the same behaviour as you have described.
Comment From: quaff
The logging problem happens to SLF4J and Log4j2 also. I will take some time to investigate the 10 seconds problem.
Comment From: quaff
Title updated to be more precise. I confirm the 10 seconds problem is not related to spring boot, It's gone when I disable my system proxy.
Comment From: wilkinsona
The logging problem does not occur when run using java -jar:
java -jar build/libs/example-1.0.0-SNAPSHOT.war
. ____ _ __ _ _
/\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
\\/ ___)| |_)| | | | | || (_| | ) ) ) )
' |____| .__|_| |_|_| |_\__, | / / / /
=========|_|==============|___/=/_/_/_/
:: Spring Boot :: (v2.5.4)
2021-09-15 08:37:55.441 INFO 25625 --- [ main] example.MainApplication : Starting MainApplication using Java 11.0.10 on wilkinsona-a01.vmware.com with PID 25625 (/Users/awilkinson/Downloads/example/build/libs/example-1.0.0-SNAPSHOT.war started by awilkinson in /Users/awilkinson/Downloads/example)
2021-09-15 08:37:55.443 INFO 25625 --- [ main] example.MainApplication : No active profile set, falling back to default profiles: default
2021-09-15 08:37:56.258 INFO 25625 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat initialized with port(s): 8080 (http)
2021-09-15 08:37:56.268 INFO 25625 --- [ main] o.apache.catalina.core.StandardService : Starting service [Tomcat]
2021-09-15 08:37:56.268 INFO 25625 --- [ main] org.apache.catalina.core.StandardEngine : Starting Servlet engine: [Apache Tomcat/9.0.52]
2021-09-15 08:37:56.684 INFO 25625 --- [ main] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring embedded WebApplicationContext
2021-09-15 08:37:56.684 INFO 25625 --- [ main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 1188 ms
2021-09-15 08:37:56.728 WARN 25625 --- [ main] lication$$EnhancerBySpringCGLIB$$cd6e475 : init: example.MainApplication$$EnhancerBySpringCGLIB$$cd6e475@4189d70b
init: example.MainApplication$$EnhancerBySpringCGLIB$$cd6e475@4189d70b
2021-09-15 08:37:56.984 INFO 25625 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat started on port(s): 8080 (http) with context path ''
2021-09-15 08:37:56.995 INFO 25625 --- [ main] example.MainApplication : Started MainApplication in 1.936 seconds (JVM running for 2.354)
^C2021-09-15 08:37:59.323 WARN 25625 --- [ionShutdownHook] lication$$EnhancerBySpringCGLIB$$cd6e475 : destroy: example.MainApplication$$EnhancerBySpringCGLIB$$cd6e475@4189d70b
destroy: example.MainApplication$$EnhancerBySpringCGLIB$$cd6e475@4189d70b
Comment From: quaff
The logging problem does not occur when run using
java -jar:``` java -jar build/libs/example-1.0.0-SNAPSHOT.war
. _ _ __ _ _ /\ / ' __ _ () __ __ _ \ \ \ \ ( ( )_ | ' | '| | ' \/ _` | \ \ \ \ \/ )| |)| | | | | || (| | ) ) ) ) ' |_| .|| ||| |_, | / / / / =========|_|==============|/=//// :: Spring Boot :: (v2.5.4)
2021-09-15 08:37:55.441 INFO 25625 --- [ main] example.MainApplication : Starting MainApplication using Java 11.0.10 on wilkinsona-a01.vmware.com with PID 25625 (/Users/awilkinson/Downloads/example/build/libs/example-1.0.0-SNAPSHOT.war started by awilkinson in /Users/awilkinson/Downloads/example) 2021-09-15 08:37:55.443 INFO 25625 --- [ main] example.MainApplication : No active profile set, falling back to default profiles: default 2021-09-15 08:37:56.258 INFO 25625 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat initialized with port(s): 8080 (http) 2021-09-15 08:37:56.268 INFO 25625 --- [ main] o.apache.catalina.core.StandardService : Starting service [Tomcat] 2021-09-15 08:37:56.268 INFO 25625 --- [ main] org.apache.catalina.core.StandardEngine : Starting Servlet engine: [Apache Tomcat/9.0.52] 2021-09-15 08:37:56.684 INFO 25625 --- [ main] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring embedded WebApplicationContext 2021-09-15 08:37:56.684 INFO 25625 --- [ main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 1188 ms 2021-09-15 08:37:56.728 WARN 25625 --- [ main] lication$$EnhancerBySpringCGLIB$$cd6e475 : init: example.MainApplication$$EnhancerBySpringCGLIB$$cd6e475@4189d70b init: example.MainApplication$$EnhancerBySpringCGLIB$$cd6e475@4189d70b 2021-09-15 08:37:56.984 INFO 25625 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat started on port(s): 8080 (http) with context path '' 2021-09-15 08:37:56.995 INFO 25625 --- [ main] example.MainApplication : Started MainApplication in 1.936 seconds (JVM running for 2.354) ^C2021-09-15 08:37:59.323 WARN 25625 --- [ionShutdownHook] lication$$EnhancerBySpringCGLIB$$cd6e475 : destroy: example.MainApplication$$EnhancerBySpringCGLIB$$cd6e475@4189d70b destroy: example.MainApplication$$EnhancerBySpringCGLIB$$cd6e475@4189d70b ```
Yes, it only occurs in traditional war deployment, I guess LoggingApplicationListener::onContextClosedEvent is called earlier than deployed with embedded server.
Comment From: wilkinsona
When the application is undeployed, Logback's LogbackServletContextListener is stopping the logging system before the application context is closed. This prevents the logging from making it to the console. This isn't a problem when running with java -jar as LogbackServletContextListener is ignored in that case. You can disable it by setting logbackDisableServletContainerInitializer to false as a system property, environment variable or as a context param in web.xml. There may also be a problem that's specific to when the JVM is shutting down, but I believe that'll be addressed by #27987.
Comment From: quaff
When the application is undeployed, Logback's
LogbackServletContextListeneris stopping the logging system before the application context is closed. This prevents the logging from making it to the console. This isn't a problem when running withjava -jarasLogbackServletContextListeneris ignored in that case. You can disable it by settinglogbackDisableServletContainerInitializertofalseas a system property, environment variable or as a context param inweb.xml. There may also be a problem that's specific to when the JVM is shutting down, but I believe that'll be addressed by #27987.
Actually I'm using Log4j2 instead of Logback, please make sure both logging system work properly.
Comment From: wilkinsona
The sample that you provided uses Logback. Why provide a sample for one logging system when you are, in fact, using another?
Comment From: quaff
The sample that you provided uses Logback. Why provide a sample for one logging system when you are, in fact, using another?
My real application is using Log4j2, I reproduce it by a simple example which original using Log4j2 too, I changed it to spring default to keep the example minimal. Anyway, my point is this problem exists with both Log4j2 and Logback.
Comment From: wilkinsona
Unfortunately, that resulted in wasting a significant amount of my time. Your Logback-based example was incorrectly configured as it was registering its own LogbackServletContextListener that was complicating the situation. When using Log4j2, this issue is a complete duplicate of #27987.
While we appreciate a sample being as minimal as possible, in the future please ensure that it accurately reproduces your own setup.
Comment From: quaff
@wilkinsona , I'm sorry, I thought it will save your time, unfortunately things go athwart.
Comment From: quaff
I can confirm that https://github.com/spring-projects/spring-boot/commit/a4f1d32203859c2da1300babd217ea1d5e2aa70d fixed for Log4j2, and Logback still doesn't works properly.
Comment From: wilkinsona
Logback worked correctly in my testing. Have you disabled its servlet container initializer as I described above?
Comment From: quaff
Using CATALINA_OPTS: -Duser.country=US -DlogbackDisableServletContainerInitializer=false
Using CATALINA_BASE: /Users/zhouyanming/Downloads/apache-tomcat-9.0.53
Using CATALINA_HOME: /Users/zhouyanming/Downloads/apache-tomcat-9.0.53
Using CATALINA_TMPDIR: /Users/zhouyanming/Downloads/apache-tomcat-9.0.53/temp
Using JRE_HOME: /Users/zhouyanming/jdk-17.jdk/Contents/Home
Using CLASSPATH: /Users/zhouyanming/Downloads/apache-tomcat-9.0.53/bin/bootstrap.jar:/Users/zhouyanming/Downloads/apache-tomcat-9.0.53/bin/tomcat-juli.jar
Using CATALINA_OPTS: -Duser.country=US -DlogbackDisableServletContainerInitializer=false
NOTE: Picked up JDK_JAVA_OPTIONS: --add-opens=java.base/java.lang=ALL-UNNAMED --add-opens=java.base/java.io=ALL-UNNAMED --add-opens=java.base/java.util=ALL-UNNAMED --add-opens=java.base/java.util.concurrent=ALL-UNNAMED --add-opens=java.rmi/sun.rmi.transport=ALL-UNNAMED
17-Sep-2021 16:55:47.187 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["http-nio-8080"]
17-Sep-2021 16:55:47.208 INFO [main] org.apache.catalina.startup.Catalina.load Server initialization in [284] milliseconds
17-Sep-2021 16:55:47.212 INFO [main] org.apache.catalina.core.StandardService.startInternal Starting service [Catalina]
17-Sep-2021 16:55:47.212 INFO [main] org.apache.catalina.core.StandardEngine.startInternal Starting Servlet engine: [Apache Tomcat/9.0.53]
17-Sep-2021 16:55:47.227 INFO [main] org.apache.catalina.startup.HostConfig.deployWAR Deploying web application archive [/Users/zhouyanming/Downloads/apache-tomcat-9.0.53/webapps/example-1.0.0-SNAPSHOT.war]
17-Sep-2021 16:55:48.299 INFO [main] org.apache.jasper.servlet.TldScanner.scanJars At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.
. ____ _ __ _ _
/\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
\\/ ___)| |_)| | | | | || (_| | ) ) ) )
' |____| .__|_| |_|_| |_\__, | / / / /
=========|_|==============|___/=/_/_/_/
:: Spring Boot :: (v2.5.4)
2021-09-17 16:55:48.839 INFO 51790 --- [ main] example.MainApplication : Starting MainApplication using Java 17 on MyiMac with PID 51790 (/Users/zhouyanming/Downloads/apache-tomcat-9.0.53/webapps/example-1.0.0-SNAPSHOT/WEB-INF/classes started by zhouyanming in /Users/zhouyanming/Downloads/apache-tomcat-9.0.53)
2021-09-17 16:55:48.841 INFO 51790 --- [ main] example.MainApplication : No active profile set, falling back to default profiles: default
2021-09-17 16:55:49.463 INFO 51790 --- [ main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 596 ms
2021-09-17 16:55:49.576 WARN 51790 --- [ main] ication$$EnhancerBySpringCGLIB$$31a4f8e2 : init: example.MainApplication$$EnhancerBySpringCGLIB$$31a4f8e2@69e58566
init: example.MainApplication$$EnhancerBySpringCGLIB$$31a4f8e2@69e58566
2021-09-17 16:55:49.871 INFO 51790 --- [ main] example.MainApplication : Started MainApplication in 1.393 seconds (JVM running for 3.074)
17-Sep-2021 16:55:49.898 INFO [main] org.apache.catalina.startup.HostConfig.deployWAR Deployment of web application archive [/Users/zhouyanming/Downloads/apache-tomcat-9.0.53/webapps/example-1.0.0-SNAPSHOT.war] has finished in [2,671] ms
17-Sep-2021 16:55:49.900 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["http-nio-8080"]
17-Sep-2021 16:55:49.907 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in [2698] milliseconds
^C17-Sep-2021 16:55:54.327 INFO [Thread-3] org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler ["http-nio-8080"]
17-Sep-2021 16:55:54.338 INFO [Thread-3] org.apache.catalina.core.StandardService.stopInternal Stopping service [Catalina]
destroy: example.MainApplication$$EnhancerBySpringCGLIB$$31a4f8e2@69e58566
17-Sep-2021 16:55:54.355 INFO [Thread-3] org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler ["http-nio-8080"]
17-Sep-2021 16:55:54.392 INFO [Thread-3] org.apache.coyote.AbstractProtocol.destroy Destroying ProtocolHandler ["http-nio-8080"]
Comment From: quaff
@wilkinsona Logback works properly with https://github.com/spring-projects/spring-boot/commit/a4f1d32203859c2da1300babd217ea1d5e2aa70d and explicit -DlogbackDisableServletContainerInitializer=true
Comment From: sorin-postelnicu
If I don't want the Logback ServletContainerInitializer to be instantiated by my Spring Boot application, is there a way to specifiy that in the Spring Boot configuration? (Or the only way to do that is by using -DlogbackDisableServletContainerInitializer=true ?)
I am trying to use a custom logback-myapp.xml file instead of the default logback.xml, but I see that the Logback ServletContainerInitializer is instantiated by default, and I would not want that.
Comment From: wilkinsona
@sorin-postelnicu Please see the comment above that lists your options for disabling the initializer. If you have any further questions, please follow up on Stack Overflow or Gitter. As mentioned in the guidelines for contributing, we prefer to use GitHub issues only for bugs and enhancements.
Comment From: sorin-postelnicu
@wilkinsona Thank you for the answer. I asked the question here since I thought it's relevant to the subject. Therefore, if I understood correctly, your answer is that there is no option to disable it via Spring Boot config; the only options available are the 2 options provided in the logback documentation.
Comment From: sorin-postelnicu
In case someone else will encounter this issue and to avoid spending a few days trying to configure this, I paste here the solution I finally found for configuring logback in a custom logback-myappname.xml (while also making sure to completely ignore any logback.xml file if it was put in the classpath by someone else):
public class MyOwnApplication extends SpringBootServletInitializer {
private final String loggingConfigFile = "classpath:/logback-myappname.xml";
@Override
public void onStartup(ServletContext servletContext) throws ServletException {
// Specify the name of our Spring Boot config file (without extension)
SystemUtil.setEnv("spring.config.name", "myappname");
// "logback.configurationFile" must be set before the first call to LoggerFactory.getLogger()
System.setProperty(ContextInitializer.CONFIG_FILE_PROPERTY, loggingConfigFile);
// "logging.config" must also be set, because it's used by Spring Boot instead of the above property
System.setProperty(LoggingApplicationListener.CONFIG_PROPERTY, loggingConfigFile);
SpringProperties.setFlag(JndiLocatorDelegate.IGNORE_JNDI_PROPERTY_NAME);
super.onStartup(servletContext);
logger.info("Successfully initialized MyAppName");
}