[spring-projects/spring-boot]独立tomcat中的传统war部署在服务器关闭时不会输出日志记录

2024-05-14 967 views
7

example.zip是一个非常简单的项目,我将其部署到独立的tomcat参考https://docs.spring.io/spring-boot/docs/current/reference/html/howto.html#howto.traditional-deployment

有2个问题:

  1. @PreDestroy由于日志系统过早关闭,因此未输出登录信息LoggingApplicationListener::onContextClosedEvent
  2. tomcat将等待10秒完成关闭
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"]

回答

6

感谢您的报告,但我无法重现您所描述的 10 秒暂停。我使用 Tomcat 9.0.53,它生成以下日志输出:

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"]

接受器线程需要超过 10 秒才能停止,我觉得这与 Spring Boot 无关,因为它在此级别无法控制 Tomcat。

日志记录问题可能与https://github.com/spring-projects/spring-boot/issues/9457有关,尽管我们认为这只影响基于 JUL 的日志记录,并且您正在使用 SLF4J 和 Logback。无论如何,我不愿意花时间调试它,直到我们能够重现与您所描述的相同的行为。

4

SLF4J 和 Log4j2 也会出现日志记录问题。我会花一些时间来研究10秒的问题。

0

标题已更新,更加准确。我确认 10 秒问题与 spring boot 无关,当我禁用系统代理时它就消失了。

8

使用以下命令运行时不会出现日志记录问题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
9

使用以下命令运行时不会出现日志记录问题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

是的,它只发生在传统的战争部署中,我猜LoggingApplicationListener::onContextClosedEvent是比嵌入式服务器部署更早调用。

5

取消部署应用程序时,LogbackLogbackServletContextListener将在应用程序上下文关闭之前停止日志记录系统。这可以防止日志记录到达控制台。在这种情况下,当忽略java -jaras运行时,这不是问题LogbackServletContextListener。您可以通过将其设置logbackDisableServletContainerInitializerfalse系统属性、环境变量或web.xml.还可能存在 JVM 关闭时特有的问题,但我相信 #27987 会解决这个问题。

实际上我使用的是 Log4j2 而不是 Logback,请确保两个日志系统都能正常工作。

3

您提供的示例使用 Logback。当您实际上正在使用另一种日志系统时,为什么要为一种日志系统提供示例?

8

您提供的示例使用 Logback。当您实际上正在使用另一种日志系统时,为什么要为一种日志系统提供示例?

我的真实应用程序是使用 Log4j2,我通过一个简单的示例来重现它,该示例最初也使用 Log4j2,我将其更改为 spring 默认值以保持示例最小化。无论如何,我的观点是 Log4j2 和 Logback 都存在这个问题。

8

不幸的是,这导致我浪费了大量的时间。您的基于 Logback 的示例配置不正确,因为它正在注册自己的示例,LogbackServletContextListener这使情况变得复杂。使用 Log4j2 时,此问题与 #27987 完全重复。

虽然我们希望示例尽可能少,但将来请确保它准确地重现您自己的设置。

3

@wilkinsona,很抱歉,我以为这会节省您的时间,不幸的是事情进展缓慢。

4

Logback 在我的测试中工作正常。您是否已按照我上面的描述禁用了 servlet 容器初始值设定项?

3

使用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"]
0

如果我不希望我的 Spring Boot 应用程序实例化 Logback ServletContainerInitializer,有没有办法在 Spring Boot 配置中指定它? (或者唯一的方法是使用-DlogbackDisableServletContainerInitializer=true?)我尝试使用自定义 logback-myapp.xml 文件而不是默认的 logback.xml,但我看到 Logback ServletContainerInitializer 默认情况下已实例化,并且我不会想要那个。

2

@sorin-postelnicu 请参阅上面的评论,其中列出了禁用初始化程序的选项。如果您还有任何疑问,请关注 Stack Overflow 或Gitter。正如贡献指南中提到的,我们更喜欢仅使用 GitHub 问题来解决错误和增强功能。

7

@wilkinsona 谢谢你的回答。我在这里问这个问题是因为我认为它与主题相关。因此,如果我理解正确的话,你的答案是没有选项可以通过 Spring Boot 配置禁用它;唯一可用的选项是 logback 文档中提供的 2 个选项。

9

万一其他人会遇到这个问题,并且为了避免花几天时间尝试配置它,我将我最终找到的用于在自定义中配置 logback 的解决方案粘贴到此处logback-myappname.xml(同时还要确保完全忽略任何logback.xml文件,如果它被放入其他人的类路径):

    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");
        }