Skip to content

SpringApplicationShutdownHook throws ClassCastException when use log4j2 #26953

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom
Closed
tormozzg opened this issue Jun 17, 2021 · 5 comments
Closed

SpringApplicationShutdownHook throws ClassCastException when use log4j2 #26953

tormozzg opened this issue Jun 17, 2021 · 5 comments
Assignees
@wilkinsona
Labels
type: bug A general bug
Milestone
2.5.2

Comments

@tormozzg
Copy link

tormozzg commented Jun 17, 2021 •
edited
Loading

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>

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

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

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

tormozzg commented Jun 18, 2021 •
edited
Loading

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.

@spring-projects-issues 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
Copy link
Member

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 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 wilkinsona added this to the 2.5.2 milestone Jun 19, 2021
@wilkinsona
Copy link
Member

@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
Copy link
Author

Thanks. It helped.

@vikeychen vikeychen mentioned this issue Jun 20, 2021
Closed
@wilkinsona wilkinsona self-assigned this Jun 21, 2021
wilkinsona added a commit to wilkinsona/spring-boot that referenced this issue Jun 21, 2021
@wilkinsona
No logging system shutdown handler when Log4j's own hook is enabled
e4b3ee8 
Fixes spring-projectsgh-26953
@steven-sheehy steven-sheehy mentioned this issue Jun 21, 2021
Merged
2 tasks
wilkinsona added a commit to wilkinsona/spring-boot that referenced this issue Jun 21, 2021
@wilkinsona
Disable Log4j2's shutdown hook by default
35190f0 
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
@wilkinsona wilkinsona mentioned this issue Jun 22, 2021
Closed
@grgrzybek grgrzybek mentioned this issue Jul 14, 2022
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@wilkinsona wilkinsona

Labels
type: bug A general bug
Projects
None yet
Milestone
2.5.2
Development

No branches or pull requests
4 participants
@philwebb @wilkinsona @tormozzg @spring-projects-issues