SpringApplicationShutdownHook throws ClassCastException when use log4j2 #26953

tormozzg · 2021-06-17T20:16:30Z

Hi.
I get the exception when try to replace logging module with log4j2 in spring boot version 2.5.1.
This error doesn't occur in 2.4.7 and below.

Exception in thread "SpringApplicationShutdownHook" java.lang.ClassCastException: org.apache.logging.log4j.simple.SimpleLoggerContext cannot be cast to org.apache.logging.log4j.core.LoggerContext
        at org.springframework.boot.logging.log4j2.Log4J2LoggingSystem.getLoggerContext(Log4J2LoggingSystem.java:329)
        at org.springframework.boot.logging.log4j2.Log4J2LoggingSystem.lambda$getShutdownHandler$2(Log4J2LoggingSystem.java:304)
        at java.lang.Iterable.forEach(Iterable.java:75)
        at org.springframework.boot.SpringApplicationShutdownHook.run(SpringApplicationShutdownHook.java:102)
        at java.lang.Thread.run(Thread.java:748)

I also tried to downgrade log4j to 2.13.x, but it didn't help.

Dependencies

import org.jetbrains.kotlin.gradle.tasks.KotlinCompile

plugins {
    id("org.springframework.boot") version "2.5.1"
    id("io.spring.dependency-management") version "1.0.11.RELEASE"
    kotlin("jvm") version "1.5.10"
    kotlin("plugin.spring") version "1.5.10"
    id("com.google.protobuf") version "0.8.16"
    id("idea")
}

group = "some.package"
version = "1.0.0-SNAPSHOT"
java.sourceCompatibility = JavaVersion.VERSION_1_8

repositories {
    mavenCentral()
}

dependencies {
    implementation("org.springframework.boot:spring-boot-starter-actuator")
    implementation("org.springframework.boot:spring-boot-starter-data-r2dbc")
    implementation("org.springframework.boot:spring-boot-starter-oauth2-client")
    implementation("org.springframework.boot:spring-boot-starter-rsocket")
    implementation("org.springframework.boot:spring-boot-starter-security")
    implementation("org.springframework.boot:spring-boot-starter-validation")
    implementation("org.springframework.boot:spring-boot-starter-webflux")
    implementation("org.springframework.boot:spring-boot-starter-log4j2")
    implementation("org.springframework.security:spring-security-messaging")
    implementation("org.springframework.security:spring-security-rsocket")
    implementation("org.springframework.boot:spring-boot-starter-cache")

    developmentOnly("org.springframework.boot:spring-boot-devtools")

    implementation("com.fasterxml.jackson.module:jackson-module-kotlin")
    implementation("org.ehcache:ehcache:3.8.1")
    implementation("javax.cache:cache-api:1.1.1")
    implementation("org.flywaydb:flyway-core:7.10.0")
    implementation("com.lmax:disruptor:3.4.2")


    implementation("io.projectreactor.kotlin:reactor-kotlin-extensions")
    implementation("org.jetbrains.kotlin:kotlin-reflect")
    implementation("org.jetbrains.kotlin:kotlin-stdlib-jdk8")
    implementation("org.jetbrains.kotlinx:kotlinx-coroutines-reactor")

    runtimeOnly("io.micrometer:micrometer-registry-prometheus")
    runtimeOnly("io.r2dbc:r2dbc-postgresql")

    testImplementation("org.springframework.boot:spring-boot-starter-test")
    testImplementation("io.projectreactor:reactor-test")
    testImplementation("org.springframework.security:spring-security-test")
}

configurations {
    all {
        exclude(group = "org.springframework.boot", module = "spring-boot-starter-logging")
        exclude(group = "org.springframework.boot", module = "spring-boot-starter-tomcat")
        exclude(group = "org.apache.tomcat.embed", module = "tomcat-embed-el")
        exclude(group = "org.jetbrains.kotlin", module = "kotlin-stdlib-jdk7")
    }
}

tasks.withType<KotlinCompile> {
    kotlinOptions {
        freeCompilerArgs = listOf("-Xjsr305=strict")
        jvmTarget = "1.8"
    }
}

tasks.withType<Test> {
    useJUnitPlatform()
}

log4j2.xml

<?xml version="1.0" encoding="UTF-8"?>
<Configguration>
    <Appenders>
        <Console name="Console" target="SYSTEM_OUT">
            <PatternLayout>
                <Pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%style{%t}{normal,red}] %highlight{%-5level } %style{%logger{36}}{bright,blue} %X - %msg %throwable%n</Pattern>
            </PatternLayout>
        </Console>
        <Async name="AsyncConsole">
            <AppenderRef ref="Console"/>
        </Async>
    </Appenders>
    <Loggers>
        <Logger name="some.package" level="DEBUG" additivity="false">
            <AppenderRef ref="AsyncConsole"/>
        </Logger>
        <Root level="WARN" additivity="false">
            <AppenderRef ref="AsyncConsole"/>
        </Root>
    </Loggers>
</Configguration>

The text was updated successfully, but these errors were encountered:

philwebb · 2021-06-17T23:21:13Z

Are you able to provide a sample application (either a zip file or a GitHub repo) that we can use to reproduce the problem?

tormozzg · 2021-06-18T19:42:19Z

Hi. Here it is.
demo.zip

This application has been created via initializer. There are only main class and custom log4j configuration.

Upd link to zip: build directory was removed to decrease archive size.

wilkinsona · 2021-06-19T08:02:46Z

Thanks for the sample, @tormozzg. I've reproduced the problem.

We end up with a SimpleLoggerContext as an attempt to get the "proper" LoggerContext fails with an exception:

java.lang.IllegalStateException: Unable to register Log4j shutdown hook because JVM is shutting down.
	at org.apache.logging.log4j.core.LoggerContext.setUpShutdownHook(LoggerContext.java:331)
	at org.apache.logging.log4j.core.LoggerContext.start(LoggerContext.java:274)
	at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:245)
	at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:47)
	at org.apache.logging.log4j.LogManager.getContext(LogManager.java:176)
	at org.springframework.boot.logging.log4j2.Log4J2LoggingSystem.getLoggerContext(Log4J2LoggingSystem.java:329)
	at org.springframework.boot.logging.log4j2.Log4J2LoggingSystem.cleanUp(Log4J2LoggingSystem.java:310)
	at org.springframework.boot.context.logging.LoggingApplicationListener.onContextClosedEvent(LoggingApplicationListener.java:258)
	at org.springframework.boot.context.logging.LoggingApplicationListener.onApplicationEvent(LoggingApplicationListener.java:223)
	at org.springframework.context.event.SimpleApplicationEventMulticaster.doInvokeListener(SimpleApplicationEventMulticaster.java:176)
	at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:169)
	at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:143)
	at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:421)
	at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:378)
	at org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:1058)
	at org.springframework.boot.web.reactive.context.ReactiveWebServerApplicationContext.doClose(ReactiveWebServerApplicationContext.java:147)
	at org.springframework.context.support.AbstractApplicationContext.close(AbstractApplicationContext.java:1021)
	at org.springframework.boot.SpringApplicationShutdownHook.closeAndWait(SpringApplicationShutdownHook.java:128)
	at java.lang.Iterable.forEach(Iterable.java:75)
	at org.springframework.boot.SpringApplicationShutdownHook.run(SpringApplicationShutdownHook.java:100)
	at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.IllegalStateException: Cannot add new shutdown hook as this is not started. Current state: STOPPED
	at org.apache.logging.log4j.core.util.DefaultShutdownCallbackRegistry.addShutdownCallback(DefaultShutdownCallbackRegistry.java:138)
	at org.apache.logging.log4j.core.impl.Log4jContextFactory.addShutdownCallback(Log4jContextFactory.java:378)
	at org.apache.logging.log4j.core.LoggerContext.setUpShutdownHook(LoggerContext.java:315)
	... 20 more
java.lang.IllegalStateException: Unable to register Log4j shutdown hook because JVM is shutting down.
	at org.apache.logging.log4j.core.LoggerContext.setUpShutdownHook(LoggerContext.java:331)
	at org.apache.logging.log4j.core.LoggerContext.start(LoggerContext.java:274)
	at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:245)
	at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:47)
	at org.apache.logging.log4j.LogManager.getContext(LogManager.java:176)
	at org.springframework.boot.logging.log4j2.Log4J2LoggingSystem.getLoggerContext(Log4J2LoggingSystem.java:329)
	at org.springframework.boot.logging.log4j2.Log4J2LoggingSystem.cleanUp(Log4J2LoggingSystem.java:310)
	at org.springframework.boot.context.logging.LoggingApplicationListener.onContextClosedEvent(LoggingApplicationListener.java:258)
	at org.springframework.boot.context.logging.LoggingApplicationListener.onApplicationEvent(LoggingApplicationListener.java:223)
	at org.springframework.context.event.SimpleApplicationEventMulticaster.doInvokeListener(SimpleApplicationEventMulticaster.java:176)
	at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:169)
	at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:143)
	at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:421)
	at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:378)
	at org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:1058)
	at org.springframework.boot.web.reactive.context.ReactiveWebServerApplicationContext.doClose(ReactiveWebServerApplicationContext.java:147)
	at org.springframework.context.support.AbstractApplicationContext.close(AbstractApplicationContext.java:1021)
	at org.springframework.boot.SpringApplicationShutdownHook.closeAndWait(SpringApplicationShutdownHook.java:128)
	at java.lang.Iterable.forEach(Iterable.java:75)
	at org.springframework.boot.SpringApplicationShutdownHook.run(SpringApplicationShutdownHook.java:100)
	at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.IllegalStateException: Cannot add new shutdown hook as this is not started. Current state: STOPPED
	at org.apache.logging.log4j.core.util.DefaultShutdownCallbackRegistry.addShutdownCallback(DefaultShutdownCallbackRegistry.java:138)
	at org.apache.logging.log4j.core.impl.Log4jContextFactory.addShutdownCallback(Log4jContextFactory.java:378)
	at org.apache.logging.log4j.core.LoggerContext.setUpShutdownHook(LoggerContext.java:315)
	... 20 more

Log4j swallows this exception and returns a SimpleLoggerContext.

wilkinsona · 2021-06-19T08:11:06Z

@tormozzg You can avoid the problem by disabling Log4j's own shutdown hook (which it enables by default):

<Configuration shutdownHook="disable">

This will ensure that Log4j is shut down after the context has been closed so you won't lose any logging that happens during shutdown. We'll have to see what we can do to avoid the need for shutdownHook="disable" in your custom <Configuration>.

tormozzg · 2021-06-19T17:29:19Z

Thanks. It helped.

Fixes spring-projectsgh-26953

Previously, Log4j2's own shutdown hook was only disabled when Log4j2 detected javax.servlet.Servlet on the classpath and, therefore, determined that it was running in a web application. In an application without Servlet on the classpath, this could lead to both Log4j2's shut down hook and and logging system's shutdown handler both stopping Log4j2. This could result in a failure as the second attempt at stopping would result in reinitialization which would fail as the JVM is already shutting down. This commit introduces a new Log4j2 PropertySource implementation, registered via META-INF/services, that sets the log4j.shutdownHookEnabled property to false. This will ensure that Log4j2's own shutdown hook is disabled by default whenever Spring Boot is on the classpath and not just in Servlet-based web applications. Fixes spring-projectsgh-26953

spring-projects-issues added the status: waiting-for-triage An issue we've not yet triaged label Jun 17, 2021

philwebb added the status: waiting-for-feedback We need additional information before we can continue label Jun 17, 2021

spring-projects-issues added status: feedback-provided Feedback has been provided and removed status: waiting-for-feedback We need additional information before we can continue labels Jun 18, 2021

wilkinsona added type: bug A general bug and removed status: feedback-provided Feedback has been provided status: waiting-for-triage An issue we've not yet triaged labels Jun 19, 2021

wilkinsona added this to the 2.5.2 milestone Jun 19, 2021

vikeychen mentioned this issue Jun 20, 2021

Fix SpringApplicationShutdownHook throws ClassCastException #26981

Closed

wilkinsona self-assigned this Jun 21, 2021

wilkinsona added a commit to wilkinsona/spring-boot that referenced this issue Jun 21, 2021

No logging system shutdown handler when Log4j's own hook is enabled

e4b3ee8

Fixes spring-projectsgh-26953

steven-sheehy mentioned this issue Jun 21, 2021

Change monitor scenario properties from list to map hashgraph/hedera-mirror-node#2160

Merged

2 tasks

wilkinsona mentioned this issue Jun 22, 2021

SpringApplicationShutdownHook throws ClassCastException when use log4j2 #27018

Closed

wilkinsona closed this as completed in cf940fd Jun 22, 2021

grgrzybek mentioned this issue Jul 14, 2022

Upgrade to Log4j2 2.18.0 #31589

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

SpringApplicationShutdownHook throws ClassCastException when use log4j2 #26953

SpringApplicationShutdownHook throws ClassCastException when use log4j2 #26953

tormozzg commented Jun 17, 2021 •

edited

philwebb commented Jun 17, 2021

tormozzg commented Jun 18, 2021 •

edited

wilkinsona commented Jun 19, 2021

wilkinsona commented Jun 19, 2021

tormozzg commented Jun 19, 2021

SpringApplicationShutdownHook throws ClassCastException when use log4j2 #26953

SpringApplicationShutdownHook throws ClassCastException when use log4j2 #26953

Comments

tormozzg commented Jun 17, 2021 • edited

philwebb commented Jun 17, 2021

tormozzg commented Jun 18, 2021 • edited

wilkinsona commented Jun 19, 2021

wilkinsona commented Jun 19, 2021

tormozzg commented Jun 19, 2021

tormozzg commented Jun 17, 2021 •

edited

tormozzg commented Jun 18, 2021 •

edited