SB 2.4.0

doc problems

I'm having some problems with logging, the simplest is, could you please add documentation for how to get the same pattern with the log4j2 starter as with slf4j?

conflicting slf4j when adding log4j2

there were also some issues with conflicting versions or multiple instances of slf4j on the classpath when I added log4j2 starter to my classpath. I did this to fix it.

dependencies {
  developmentOnly(platform("org.springframework.boot:spring-boot-starter-parent:2.4.+"))
  developmentOnly("org.springframework.boot:spring-boot-devtools")
  runtimeOnly("org.springframework.boot:spring-boot-starter-log4j2")
  runtimeOnly("org.springframework.boot:spring-boot-starter-actuator") {
  //  exclude( group = "org.springframework.boot", module = "spring-boot-starter-logging")
  }
  implementation("org.springframework.boot:spring-boot-starter-web") {
    exclude( group = "org.springframework.boot", module = "spring-boot-starter-logging")
  }
  testImplementation("org.springframework.boot:spring-boot-starter-webflux") {
    exclude( group = "org.springframework.boot", module = "spring-boot-starter-logging")
  }
}

SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:/Users/calebcushing/.gradle/caches/modules-2/files-2.1/ch.qos.logback/logback-classic/1.2.3/7c4f3c474fb2c041d8028740440937705ebb473a/logback-classic-1.2.3.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:/Users/calebcushing/.gradle/caches/modules-2/files-2.1/org.apache.logging.log4j/log4j-slf4j-impl/2.13.3/7cca27a921a18645139cf651c04b83b1a19cfd76/log4j-slf4j-impl-2.13.3.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
SLF4J: Actual binding is of type [ch.qos.logback.classic.util.ContextSelectorStaticBinder]

problems with slf4j

00:44:27.621 [Test worker] DEBUG org.springframework.test.context.BootstrapUtils - Instantiating CacheAwareContextLoaderDelegate from class [org.springframework.test.context.cache.DefaultCacheAwareContextLoaderDelegate]
00:44:27.648 [Test worker] DEBUG org.springframework.test.context.BootstrapUtils - Instantiating BootstrapContext using constructor [public org.springframework.test.context.support.DefaultBootstrapContext(java.lang.Class,org.springframework.test.context.CacheAwareContextLoaderDelegate)]
00:44:27.710 [Test worker] DEBUG org.springframework.test.context.BootstrapUtils - Instantiating TestContextBootstrapper for test class [com.xenoterracide.ppm.app.ApplicationTest] from class [org.springframework.boot.test.context.SpringBootTestContextBootstrapper]
00:44:27.731 [Test worker] INFO org.springframework.boot.test.context.SpringBootTestContextBootstrapper - Neither @ContextConfiguration nor @ContextHierarchy found for test class [com.xenoterracide.ppm.app.ApplicationTest], using SpringBootContextLoader
00:44:27.739 [Test worker] DEBUG org.springframework.test.context.support.AbstractContextLoader - Did not detect default resource location for test class [com.xenoterracide.ppm.app.ApplicationTest]: class path resource [com/xenoterracide/ppm/app/ApplicationTest-context.xml] does not exist
00:44:27.739 [Test worker] DEBUG org.springframework.test.context.support.AbstractContextLoader - Did not detect default resource location for test class [com.xenoterracide.ppm.app.ApplicationTest]: class path resource [com/xenoterracide/ppm/app/ApplicationTestContext.groovy] does not exist
00:44:27.740 [Test worker] INFO org.springframework.test.context.support.AbstractContextLoader - Could not detect default resource locations for test class [com.xenoterracide.ppm.app.ApplicationTest]: no resource found for suffixes {-context.xml, Context.groovy}.
00:44:27.741 [Test worker] INFO org.springframework.test.context.support.AnnotationConfigContextLoaderUtils - Could not detect default configuration classes for test class [com.xenoterracide.ppm.app.ApplicationTest]: ApplicationTest does not declare any static, non-private, non-final, nested classes annotated with @Configuration.
00:44:27.821 [Test worker] DEBUG org.springframework.test.context.support.ActiveProfilesUtils - Could not find an 'annotation declaring class' for annotation type [org.springframework.test.context.ActiveProfiles] and class [com.xenoterracide.ppm.app.ApplicationTest]
00:44:27.956 [Test worker] DEBUG org.springframework.context.annotation.ClassPathScanningCandidateComponentProvider - Identified candidate component class: file [/Users/calebcushing/IdeaProjects/ppm/api/app/build/classes/java/test/com/xenoterracide/ppm/app/TestApplication.class]
00:44:27.958 [Test worker] INFO org.springframework.boot.test.context.SpringBootTestContextBootstrapper - Found @SpringBootConfiguration com.xenoterracide.ppm.app.TestApplication for test class com.xenoterracide.ppm.app.ApplicationTest
00:44:28.290 [Test worker] DEBUG org.springframework.boot.test.context.SpringBootTestContextBootstrapper - @TestExecutionListeners is not present for class [com.xenoterracide.ppm.app.ApplicationTest]: using defaults.
00:44:28.291 [Test worker] INFO org.springframework.boot.test.context.SpringBootTestContextBootstrapper - Loaded default TestExecutionListener class names from location [META-INF/spring.factories]: [org.springframework.test.context.web.ServletTestExecutionListener, org.springframework.test.context.support.DirtiesContextBeforeModesTestExecutionListener, org.springframework.test.context.support.DependencyInjectionTestExecutionListener, org.springframework.test.context.support.DirtiesContextTestExecutionListener, org.springframework.test.context.transaction.TransactionalTestExecutionListener, org.springframework.test.context.jdbc.SqlScriptsTestExecutionListener, org.springframework.test.context.event.EventPublishingTestExecutionListener, org.springframework.boot.test.autoconfigure.restdocs.RestDocsTestExecutionListener, org.springframework.boot.test.autoconfigure.web.client.MockRestServiceServerResetTestExecutionListener, org.springframework.boot.test.autoconfigure.web.servlet.MockMvcPrintOnlyOnFailureTestExecutionListener, org.springframework.boot.test.autoconfigure.web.servlet.WebDriverTestExecutionListener, org.springframework.boot.test.autoconfigure.webservices.client.MockWebServiceServerTestExecutionListener, org.springframework.boot.test.mock.mockito.MockitoTestExecutionListener, org.springframework.boot.test.mock.mockito.ResetMocksTestExecutionListener]
00:44:28.311 [Test worker] DEBUG org.springframework.boot.test.context.SpringBootTestContextBootstrapper - Skipping candidate TestExecutionListener [org.springframework.test.context.transaction.TransactionalTestExecutionListener] due to a missing dependency. Specify custom listener classes or make the default listener classes and their required dependencies available. Offending class: [org/springframework/transaction/TransactionDefinition]
00:44:28.317 [Test worker] DEBUG org.springframework.boot.test.context.SpringBootTestContextBootstrapper - Skipping candidate TestExecutionListener [org.springframework.test.context.jdbc.SqlScriptsTestExecutionListener] due to a missing dependency. Specify custom listener classes or make the default listener classes and their required dependencies available. Offending class: [org/springframework/transaction/interceptor/TransactionAttribute]
00:44:28.324 [Test worker] INFO org.springframework.boot.test.context.SpringBootTestContextBootstrapper - Using TestExecutionListeners: [org.springframework.test.context.web.ServletTestExecutionListener@11b647a0, org.springframework.test.context.support.DirtiesContextBeforeModesTestExecutionListener@493b92c9, org.springframework.boot.test.mock.mockito.MockitoTestExecutionListener@2e2b4202, org.springframework.boot.test.autoconfigure.SpringBootDependencyInjectionTestExecutionListener@42b62f3f, org.springframework.test.context.support.DirtiesContextTestExecutionListener@619efb8e, org.springframework.test.context.event.EventPublishingTestExecutionListener@74a680ae, org.springframework.boot.test.autoconfigure.restdocs.RestDocsTestExecutionListener@e9f76a, org.springframework.boot.test.autoconfigure.web.client.MockRestServiceServerResetTestExecutionListener@7355ff9f, org.springframework.boot.test.autoconfigure.web.servlet.MockMvcPrintOnlyOnFailureTestExecutionListener@658128f0, org.springframework.boot.test.autoconfigure.web.servlet.WebDriverTestExecutionListener@25e2771e, org.springframework.boot.test.autoconfigure.webservices.client.MockWebServiceServerTestExecutionListener@6a7f966f, org.springframework.boot.test.mock.mockito.ResetMocksTestExecutionListener@368a35b8]
00:44:28.331 [Test worker] DEBUG org.springframework.test.context.support.AbstractDirtiesContextTestExecutionListener - Before test class: context [DefaultTestContext@d1c8e7b testClass = ApplicationTest, testInstance = [null], testMethod = [null], testException = [null], mergedContextConfiguration = [WebMergedContextConfiguration@25a20477 testClass = ApplicationTest, locations = '{}', classes = '{class com.xenoterracide.ppm.app.TestApplication}', contextInitializerClasses = '[]', activeProfiles = '{}', propertySourceLocations = '{}', propertySourceProperties = '{org.springframework.boot.test.context.SpringBootTestContextBootstrapper=true, server.port=0}', contextCustomizers = set[org.springframework.boot.test.autoconfigure.actuate.metrics.MetricsExportContextCustomizerFactory$DisableMetricExportContextCustomizer@2992915e, org.springframework.boot.test.autoconfigure.properties.PropertyMappingContextCustomizer@0, org.springframework.boot.test.autoconfigure.web.servlet.WebDriverContextCustomizerFactory$Customizer@54365de2, org.springframework.boot.test.context.filter.ExcludeFilterContextCustomizer@2d74f323, org.springframework.boot.test.json.DuplicateJsonObjectContextCustomizerFactory$DuplicateJsonObjectContextCustomizer@445789f2, org.springframework.boot.test.mock.mockito.MockitoContextCustomizer@0, org.springframework.boot.test.web.client.TestRestTemplateContextCustomizer@6274c58d, org.springframework.boot.test.web.reactive.server.WebTestClientContextCustomizer@46a27f8b, org.springframework.boot.test.context.SpringBootTestArgs@1, org.springframework.boot.test.context.SpringBootTestWebEnvironment@6449de00], resourceBasePath = 'src/main/webapp', contextLoader = 'org.springframework.boot.test.context.SpringBootContextLoader', parent = [null]], attributes = map['org.springframework.test.context.web.ServletTestExecutionListener.activateListener' -> false]], class annotated with @DirtiesContext [false] with mode [null].
00:44:28.358 [Test worker] DEBUG org.springframework.test.context.support.DependencyInjectionTestExecutionListener - Performing dependency injection for test context [[DefaultTestContext@d1c8e7b testClass = ApplicationTest, testInstance = com.xenoterracide.ppm.app.ApplicationTest@6a0be8c, testMethod = [null], testException = [null], mergedContextConfiguration = [WebMergedContextConfiguration@25a20477 testClass = ApplicationTest, locations = '{}', classes = '{class com.xenoterracide.ppm.app.TestApplication}', contextInitializerClasses = '[]', activeProfiles = '{}', propertySourceLocations = '{}', propertySourceProperties = '{org.springframework.boot.test.context.SpringBootTestContextBootstrapper=true, server.port=0}', contextCustomizers = set[org.springframework.boot.test.autoconfigure.actuate.metrics.MetricsExportContextCustomizerFactory$DisableMetricExportContextCustomizer@2992915e, org.springframework.boot.test.autoconfigure.properties.PropertyMappingContextCustomizer@0, org.springframework.boot.test.autoconfigure.web.servlet.WebDriverContextCustomizerFactory$Customizer@54365de2, org.springframework.boot.test.context.filter.ExcludeFilterContextCustomizer@2d74f323, org.springframework.boot.test.json.DuplicateJsonObjectContextCustomizerFactory$DuplicateJsonObjectContextCustomizer@445789f2, org.springframework.boot.test.mock.mockito.MockitoContextCustomizer@0, org.springframework.boot.test.web.client.TestRestTemplateContextCustomizer@6274c58d, org.springframework.boot.test.web.reactive.server.WebTestClientContextCustomizer@46a27f8b, org.springframework.boot.test.context.SpringBootTestArgs@1, org.springframework.boot.test.context.SpringBootTestWebEnvironment@6449de00], resourceBasePath = 'src/main/webapp', contextLoader = 'org.springframework.boot.test.context.SpringBootContextLoader', parent = [null]], attributes = map['org.springframework.test.context.web.ServletTestExecutionListener.activateListener' -> false]]].
00:44:28.398 [Test worker] DEBUG org.springframework.test.context.support.TestPropertySourceUtils - Adding inlined properties to environment: {spring.jmx.enabled=false, org.springframework.boot.test.context.SpringBootTestContextBootstrapper=true, server.port=0}

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::                (v2.4.0)

 INFO 68080DEBUG 68080 INFO 68080 INFO 68080 INFO 68080 INFO 68080 INFO 68080 INFO 68080 INFO 68080 INFO 68080 INFO 68080 INFO 68080 INFO 68080 INFO 68080 INFO 68080ApplicationTest > healthCheck(WebTestClient) STARTED
ApplicationTest > healthCheck(WebTestClient) PASSED
 INFO 68080
12:44:41 AM: Task execution finished ':app:test --tests "com.xenoterracide.ppm.app.ApplicationTest"'.

firstly, what is up with this?

 INFO 68080DEBUG 68080 INFO 68080 INFO 68080 INFO 68080 INFO 68080 INFO 68080 INFO 68080 INFO 68080

logging.pattern.console=${LOG_LEVEL_PATTERN:%5p} ${PID:- }) --- [%15.15t] %-40.40logger{39}} : %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}
logging.level.com.xenoterracide.ppm=debug
logging.level.org.springframework=info

but more importantly

00:44:28.290 [Test worker] DEBUG org.springframework.boot.test.context.SpringBootTestContextBootstrapper - @TestExecutionListeners is not present for class [com.xenoterracide.ppm.app.ApplicationTest]: using defaults.

and others like it, this is coming from org.springframework which I've set to info not debug.

and this noisyness seems like it should be a debug log

00:44:28.324 [Test worker] INFO org.springframework.boot.test.context.SpringBootTestContextBootstrapper - Using TestExecutionListeners: [org.springframework.test.context.web.ServletTestExecutionListener@11b647a0, org.springframework.test.context.support.DirtiesContextBeforeModesTestExecutionListener@493b92c9, org.springframework.boot.test.mock.mockito.MockitoTestExecutionListener@2e2b4202, org.springframework.boot.test.autoconfigure.SpringBootDependencyInjectionTestExecutionListener@42b62f3f, org.springframework.test.context.support.DirtiesContextTestExecutionListener@619efb8e, org.springframework.test.context.event.EventPublishingTestExecutionListener@74a680ae, org.springframework.boot.test.autoconfigure.restdocs.RestDocsTestExecutionListener@e9f76a, org.springframework.boot.test.autoconfigure.web.client.MockRestServiceServerResetTestExecutionListener@7355ff9f, org.springframework.boot.test.autoconfigure.web.servlet.MockMvcPrintOnlyOnFailureTestExecutionListener@658128f0, org.springframework.boot.test.autoconfigure.web.servlet.WebDriverTestExecutionListener@25e2771e, org.springframework.boot.test.autoconfigure.webservices.client.MockWebServiceServerTestExecutionListener@6a7f966f, org.springframework.boot.test.mock.mockito.ResetMocksTestExecutionListener@368a35b8]

and why do these logs still have timestamps? they aren't in my pattern.

problems with log4j

INFO 67799) --- [    Test worker] om.xenoterracide.ppm.app.ApplicationTest} : Starting ApplicationTest using Java 11.0.8 on Calebs-MBP with PID 67799 (started by calebcushing in /Users/calebcushing/IdeaProjects/ppm/api/app)
-DEBUG 67799) --- [    Test worker] om.xenoterracide.ppm.app.ApplicationTest} : Running with Spring Boot v2.4.0, Spring v5.3.1
- INFO 67799) --- [    Test worker] om.xenoterracide.ppm.app.ApplicationTest} : No active profile set, falling back to default profiles: default
- INFO 67799) --- [    Test worker] boot.web.embedded.tomcat.TomcatWebServer} : Tomcat initialized with port(s): 0 (http)
- INFO 67799) --- [    Test worker] org.apache.catalina.core.StandardService} : Starting service [Tomcat]
- INFO 67799) --- [    Test worker] org.apache.catalina.core.StandardEngine } : Starting Servlet engine: [Apache Tomcat/9.0.39]
- INFO 67799) --- [    Test worker] e.ContainerBase.[Tomcat].[localhost].[/]} : Initializing Spring embedded WebApplicationContext
- INFO 67799) --- [    Test worker] ntext.ServletWebServerApplicationContext} : Root WebApplicationContext: initialization completed in 2378 ms
- INFO 67799) --- [    Test worker] duling.concurrent.ThreadPoolTaskExecutor} : Initializing ExecutorService 'applicationTaskExecutor'
- INFO 67799) --- [    Test worker] tuate.endpoint.web.EndpointLinksResolver} : Exposing 2 endpoint(s) beneath base path '/actuator'
- INFO 67799) --- [    Test worker] boot.web.embedded.tomcat.TomcatWebServer} : Tomcat started on port(s): 52610 (http) with context path ''
- INFO 67799) --- [    Test worker] om.xenoterracide.ppm.app.ApplicationTest} : Started ApplicationTest in 6.005 seconds (JVM running for 9.686)
- INFO 67799) --- [o-auto-1-exec-1] e.ContainerBase.[Tomcat].[localhost].[/]} : Initializing Spring DispatcherServlet 'dispatcherServlet'
- INFO 67799) --- [o-auto-1-exec-1] gframework.web.servlet.DispatcherServlet} : Initializing Servlet 'dispatcherServlet'
- INFO 67799) --- [o-auto-1-exec-1] gframework.web.servlet.DispatcherServlet} : Completed initialization in 2 ms
-ApplicationTest > healthCheck(WebTestClient) STARTED
ApplicationTest > healthCheck(WebTestClient) PASSED
 INFO 67799) --- [extShutdownHook] duling.concurrent.ThreadPoolTaskExecutor} : Shutting down ExecutorService 'applicationTaskExecutor'
-
BUILD SUCCESSFUL in 19s

here's my application.properties

logging.pattern.console=${LOG_LEVEL_PATTERN:%5p} ${PID:- }) --- [%15.15t] %-40.40logger{39}} : %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}
logging.level.com.xenoterracide.ppm=debug
logging.level.org.springframework=info

you'll notice that some lines have are still prefixed with - but not all. and this line

-ApplicationTest > healthCheck(WebTestClient) STARTED

is output by gradle/junit5 so... this might be some weird concurrency issue as I'm now seeing a line printed after it without the -, though I'm not entirely sure how the buffer would split 1 line across 2.

Comment From: snicoll

the simplest is, could you please add documentation for how to get the same pattern with the log4j2 starter as with slf4j?

Both logback and log4j2 use slf4j so I am not sure what you're referring to. There is a How-To to use log4j that's not applied properly according to your build snippet so I'd recommend starting with that.

There's a lot to unwind here so it would be helpful if you could share a small sample that reproduces the problems you've described here. You can do so by attaching a zip to this issue or sharing a link to a GitHub repository.

Comment From: xenoterracide

@snicoll do you want 1 repo or 4? if 1 repo you're going to have to modify the code to reproduce each issue. Also the first is easy, it's adding documentation.

Comment From: xenoterracide

Both logback and log4j2 use slf4j so I am not sure what you're referring to. There is a How-To to use log4j that's not applied properly according to your build snippet so I'd recommend starting with that.

those instructions don't compile cleanly for kotlin, and honestly don't seem easily convertable due to casting issues in kotlin...

Classifier 'ModuleComponentSelector' does not have a companion object, and thus must be initialized here

configurations.all {
  resolutionStrategy.dependencySubstitution.all {
    if (requested is ModuleComponentSelector && requested.module === 'spring-boot-starter-logging') {
      val req = (ModuleComponentSelector) requested;
      useTarget("org.springframework.boot:spring-boot-starter-log4j2:$dependency.requested.version", 'Use Log4j2 instead of Logback')
    }
  }
}

Comment From: wilkinsona

The example's in Groovy so it's to be expected that they don't compile cleanly in Kotlin. While we provide Kotlin examples in the Gradle Plugin's documentation, we don't strive to replace Gradle's own documentation which contains numerous examples of dependency substitutions using the Kotlin DSL. Having read that page, here is the Kotlin DSL equivalent of the Groovy DSL example in the docs:

configurations.all {
    resolutionStrategy.dependencySubstitution.all {
        requested.let {
            if (it is ModuleComponentSelector && it.module == "spring-boot-starter-logging") {
                useTarget("org.springframework.boot:spring-boot-starter-log4j2:${it.version}", "Use Log4j2 instead of Logback")
            }
        }
    }
}

Without understanding the cause of your problem, we're not going to be able to judge whether or not there's something for us to document here. Please provide something (be it one sample or four) that makes is as easy as you can for us to reproduce the problem.

Comment From: xenoterracide

That's interesting, I found this and it also doesn't compile... anyways, I'll work on a repo now, I guess I'll just make it different directories

Comment From: xenoterracide

https://github.com/xenoterracide/logging-issues-repro README included, the weird - garbage is because I'm fighting with migrating the 2 the log4j2 pattern ... because that's not documented. I just like the log4j2 api better, but it's been a while since I configured it. There's also an additional issue in here, when using buildSrc I my tests require me to add a TestApplication with @SpringBootApplication even though Application has it and should be on the classpath, for some reason this doesn't happen when not using buildSrc

Comment From: wilkinsona

Thanks for the samples.

I don't see anything unexpected in the output from the SLF4J repro:

./gradlew :slf4j-repro:test
Starting a Gradle Daemon, 1 incompatible Daemon could not be reused, use --status for details

> Task :buildSrc:compileKotlin
The `kotlin-dsl` plugin applied to project ':buildSrc' enables experimental Kotlin compiler features. For more information see https://docs.gradle.org/6.7/userguide/kotlin_dsl.html#sec:kotlin-dsl_plugin

> Task :slf4j-repro:test

ApplicationTest STANDARD_OUT
    12:32:55.433 [Test worker] DEBUG org.springframework.test.context.BootstrapUtils - Instantiating CacheAwareContextLoaderDelegate from class [org.springframework.test.context.cache.DefaultCacheAwareContextLoaderDelegate]
    12:32:55.442 [Test worker] DEBUG org.springframework.test.context.BootstrapUtils - Instantiating BootstrapContext using constructor [public org.springframework.test.context.support.DefaultBootstrapContext(java.lang.Class,org.springframework.test.context.CacheAwareContextLoaderDelegate)]
    12:32:55.464 [Test worker] DEBUG org.springframework.test.context.BootstrapUtils - Instantiating TestContextBootstrapper for test class [com.xenoterracide.ApplicationTest] from class [org.springframework.boot.test.context.SpringBootTestContextBootstrapper]
    12:32:55.470 [Test worker] INFO org.springframework.boot.test.context.SpringBootTestContextBootstrapper - Neither @ContextConfiguration nor @ContextHierarchy found for test class [com.xenoterracide.ApplicationTest], using SpringBootContextLoader
    12:32:55.473 [Test worker] DEBUG org.springframework.test.context.support.AbstractContextLoader - Did not detect default resource location for test class [com.xenoterracide.ApplicationTest]: class path resource [com/xenoterracide/ApplicationTest-context.xml] does not exist
    12:32:55.473 [Test worker] DEBUG org.springframework.test.context.support.AbstractContextLoader - Did not detect default resource location for test class [com.xenoterracide.ApplicationTest]: class path resource [com/xenoterracide/ApplicationTestContext.groovy] does not exist
    12:32:55.473 [Test worker] INFO org.springframework.test.context.support.AbstractContextLoader - Could not detect default resource locations for test class [com.xenoterracide.ApplicationTest]: no resource found for suffixes {-context.xml, Context.groovy}.
    12:32:55.474 [Test worker] INFO org.springframework.test.context.support.AnnotationConfigContextLoaderUtils - Could not detect default configuration classes for test class [com.xenoterracide.ApplicationTest]: ApplicationTest does not declare any static, non-private, non-final, nested classes annotated with @Configuration.
    12:32:55.500 [Test worker] DEBUG org.springframework.test.context.support.ActiveProfilesUtils - Could not find an 'annotation declaring class' for annotation type [org.springframework.test.context.ActiveProfiles] and class [com.xenoterracide.ApplicationTest]
    12:32:55.534 [Test worker] DEBUG org.springframework.context.annotation.ClassPathScanningCandidateComponentProvider - Identified candidate component class: file [/Users/awilkinson/dev/temp/logging-issues-repro/slf4j-repro/build/classes/java/test/com/xenoterracide/TestApplication.class]
    12:32:55.534 [Test worker] INFO org.springframework.boot.test.context.SpringBootTestContextBootstrapper - Found @SpringBootConfiguration com.xenoterracide.TestApplication for test class com.xenoterracide.ApplicationTest
    12:32:55.599 [Test worker] DEBUG org.springframework.boot.test.context.SpringBootTestContextBootstrapper - @TestExecutionListeners is not present for class [com.xenoterracide.ApplicationTest]: using defaults.
    12:32:55.599 [Test worker] INFO org.springframework.boot.test.context.SpringBootTestContextBootstrapper - Loaded default TestExecutionListener class names from location [META-INF/spring.factories]: [org.springframework.test.context.web.ServletTestExecutionListener, org.springframework.test.context.support.DirtiesContextBeforeModesTestExecutionListener, org.springframework.test.context.support.DependencyInjectionTestExecutionListener, org.springframework.test.context.support.DirtiesContextTestExecutionListener, org.springframework.test.context.transaction.TransactionalTestExecutionListener, org.springframework.test.context.jdbc.SqlScriptsTestExecutionListener, org.springframework.test.context.event.EventPublishingTestExecutionListener, org.springframework.boot.test.autoconfigure.restdocs.RestDocsTestExecutionListener, org.springframework.boot.test.autoconfigure.web.client.MockRestServiceServerResetTestExecutionListener, org.springframework.boot.test.autoconfigure.web.servlet.MockMvcPrintOnlyOnFailureTestExecutionListener, org.springframework.boot.test.autoconfigure.web.servlet.WebDriverTestExecutionListener, org.springframework.boot.test.autoconfigure.webservices.client.MockWebServiceServerTestExecutionListener, org.springframework.boot.test.mock.mockito.MockitoTestExecutionListener, org.springframework.boot.test.mock.mockito.ResetMocksTestExecutionListener]
    12:32:55.606 [Test worker] DEBUG org.springframework.boot.test.context.SpringBootTestContextBootstrapper - Skipping candidate TestExecutionListener [org.springframework.test.context.transaction.TransactionalTestExecutionListener] due to a missing dependency. Specify custom listener classes or make the default listener classes and their required dependencies available. Offending class: [org/springframework/transaction/TransactionDefinition]
    12:32:55.607 [Test worker] DEBUG org.springframework.boot.test.context.SpringBootTestContextBootstrapper - Skipping candidate TestExecutionListener [org.springframework.test.context.jdbc.SqlScriptsTestExecutionListener] due to a missing dependency. Specify custom listener classes or make the default listener classes and their required dependencies available. Offending class: [org/springframework/transaction/interceptor/TransactionAttribute]
    12:32:55.608 [Test worker] INFO org.springframework.boot.test.context.SpringBootTestContextBootstrapper - Using TestExecutionListeners: [org.springframework.test.context.web.ServletTestExecutionListener@5a9dbba0, org.springframework.test.context.support.DirtiesContextBeforeModesTestExecutionListener@bb941ef, org.springframework.boot.test.mock.mockito.MockitoTestExecutionListener@37832bef, org.springframework.boot.test.autoconfigure.SpringBootDependencyInjectionTestExecutionListener@2af5cf9b, org.springframework.test.context.support.DirtiesContextTestExecutionListener@1d8221de, org.springframework.test.context.event.EventPublishingTestExecutionListener@5c75bdb8, org.springframework.boot.test.autoconfigure.restdocs.RestDocsTestExecutionListener@7207298a, org.springframework.boot.test.autoconfigure.web.client.MockRestServiceServerResetTestExecutionListener@768ab946, org.springframework.boot.test.autoconfigure.web.servlet.MockMvcPrintOnlyOnFailureTestExecutionListener@7a8aea98, org.springframework.boot.test.autoconfigure.web.servlet.WebDriverTestExecutionListener@b63100c, org.springframework.boot.test.autoconfigure.webservices.client.MockWebServiceServerTestExecutionListener@40633393, org.springframework.boot.test.mock.mockito.ResetMocksTestExecutionListener@6300e250]
    12:32:55.610 [Test worker] DEBUG org.springframework.test.context.support.AbstractDirtiesContextTestExecutionListener - Before test class: context [DefaultTestContext@5de58dfc testClass = ApplicationTest, testInstance = [null], testMethod = [null], testException = [null], mergedContextConfiguration = [WebMergedContextConfiguration@493d762d testClass = ApplicationTest, locations = '{}', classes = '{class com.xenoterracide.TestApplication}', contextInitializerClasses = '[]', activeProfiles = '{}', propertySourceLocations = '{}', propertySourceProperties = '{org.springframework.boot.test.context.SpringBootTestContextBootstrapper=true, server.port=0}', contextCustomizers = set[org.springframework.boot.test.autoconfigure.actuate.metrics.MetricsExportContextCustomizerFactory$DisableMetricExportContextCustomizer@32d778a7, org.springframework.boot.test.autoconfigure.properties.PropertyMappingContextCustomizer@0, org.springframework.boot.test.autoconfigure.web.servlet.WebDriverContextCustomizerFactory$Customizer@3a40ba63, org.springframework.boot.test.context.filter.ExcludeFilterContextCustomizer@6b8e36e6, org.springframework.boot.test.json.DuplicateJsonObjectContextCustomizerFactory$DuplicateJsonObjectContextCustomizer@56712353, org.springframework.boot.test.mock.mockito.MockitoContextCustomizer@0, org.springframework.boot.test.web.client.TestRestTemplateContextCustomizer@1efbc231, org.springframework.boot.test.web.reactive.server.WebTestClientContextCustomizer@76298d13, org.springframework.boot.test.context.SpringBootTestArgs@1, org.springframework.boot.test.context.SpringBootTestWebEnvironment@15c4ea50], resourceBasePath = 'src/main/webapp', contextLoader = 'org.springframework.boot.test.context.SpringBootContextLoader', parent = [null]], attributes = map['org.springframework.test.context.web.ServletTestExecutionListener.activateListener' -> false]], class annotated with @DirtiesContext [false] with mode [null].
    12:32:55.617 [Test worker] DEBUG org.springframework.test.context.support.DependencyInjectionTestExecutionListener - Performing dependency injection for test context [[DefaultTestContext@5de58dfc testClass = ApplicationTest, testInstance = com.xenoterracide.ApplicationTest@4d2dbb6b, testMethod = [null], testException = [null], mergedContextConfiguration = [WebMergedContextConfiguration@493d762d testClass = ApplicationTest, locations = '{}', classes = '{class com.xenoterracide.TestApplication}', contextInitializerClasses = '[]', activeProfiles = '{}', propertySourceLocations = '{}', propertySourceProperties = '{org.springframework.boot.test.context.SpringBootTestContextBootstrapper=true, server.port=0}', contextCustomizers = set[org.springframework.boot.test.autoconfigure.actuate.metrics.MetricsExportContextCustomizerFactory$DisableMetricExportContextCustomizer@32d778a7, org.springframework.boot.test.autoconfigure.properties.PropertyMappingContextCustomizer@0, org.springframework.boot.test.autoconfigure.web.servlet.WebDriverContextCustomizerFactory$Customizer@3a40ba63, org.springframework.boot.test.context.filter.ExcludeFilterContextCustomizer@6b8e36e6, org.springframework.boot.test.json.DuplicateJsonObjectContextCustomizerFactory$DuplicateJsonObjectContextCustomizer@56712353, org.springframework.boot.test.mock.mockito.MockitoContextCustomizer@0, org.springframework.boot.test.web.client.TestRestTemplateContextCustomizer@1efbc231, org.springframework.boot.test.web.reactive.server.WebTestClientContextCustomizer@76298d13, org.springframework.boot.test.context.SpringBootTestArgs@1, org.springframework.boot.test.context.SpringBootTestWebEnvironment@15c4ea50], resourceBasePath = 'src/main/webapp', contextLoader = 'org.springframework.boot.test.context.SpringBootContextLoader', parent = [null]], attributes = map['org.springframework.test.context.web.ServletTestExecutionListener.activateListener' -> false]]].
    12:32:55.631 [Test worker] DEBUG org.springframework.test.context.support.TestPropertySourceUtils - Adding inlined properties to environment: {spring.jmx.enabled=false, org.springframework.boot.test.context.SpringBootTestContextBootstrapper=true, server.port=0}

      .   ____          _            __ _ _
     /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
    ( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
     \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
      '  |____| .__|_| |_|_| |_\__, | / / / /
     =========|_|==============|___/=/_/_/_/
     :: Spring Boot ::                (v2.4.0)

    2020-11-16 12:32:55.890  INFO 18417 --- [    Test worker] com.xenoterracide.ApplicationTest        : Starting ApplicationTest using Java 11.0.7 on wilkinsona-a01.vmware.com with PID 18417 (started by awilkinson in /Users/awilkinson/dev/temp/logging-issues-repro/slf4j-repro)
    2020-11-16 12:32:55.892  INFO 18417 --- [    Test worker] com.xenoterracide.ApplicationTest        : No active profile set, falling back to default profiles: default
    2020-11-16 12:32:56.597  INFO 18417 --- [    Test worker] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 0 (http)
    2020-11-16 12:32:56.604  INFO 18417 --- [    Test worker] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
    2020-11-16 12:32:56.605  INFO 18417 --- [    Test worker] org.apache.catalina.core.StandardEngine  : Starting Servlet engine: [Apache Tomcat/9.0.39]
    2020-11-16 12:32:56.663  INFO 18417 --- [    Test worker] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
    2020-11-16 12:32:56.664  INFO 18417 --- [    Test worker] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 759 ms
    2020-11-16 12:32:57.079  INFO 18417 --- [    Test worker] o.s.s.concurrent.ThreadPoolTaskExecutor  : Initializing ExecutorService 'applicationTaskExecutor'
    2020-11-16 12:32:57.331  INFO 18417 --- [    Test worker] o.s.b.a.e.web.EndpointLinksResolver      : Exposing 2 endpoint(s) beneath base path '/actuator'
    2020-11-16 12:32:57.382  INFO 18417 --- [    Test worker] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 52917 (http) with context path ''
    2020-11-16 12:32:57.393  INFO 18417 --- [    Test worker] com.xenoterracide.ApplicationTest        : Started ApplicationTest in 1.759 seconds (JVM running for 2.503)

ApplicationTest > healthCheck(WebTestClient) STARTED

ApplicationTest > healthCheck(WebTestClient) STANDARD_OUT
    2020-11-16 12:32:57.934  INFO 18417 --- [o-auto-1-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring DispatcherServlet 'dispatcherServlet'
    2020-11-16 12:32:57.935  INFO 18417 --- [o-auto-1-exec-1] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
    2020-11-16 12:32:57.936  INFO 18417 --- [o-auto-1-exec-1] o.s.web.servlet.DispatcherServlet        : Completed initialization in 1 ms

ApplicationTest > healthCheck(WebTestClient) PASSED
2020-11-16 12:33:00.191  INFO 18417 --- [extShutdownHook] o.s.s.concurrent.ThreadPoolTaskExecutor  : Shutting down ExecutorService 'applicationTaskExecutor'

BUILD SUCCESSFUL in 55s
6 actionable tasks: 6 executed

There's some output with the logging framework's default configuration and levels until Spring Boot is bootstrapped, and then Spring Boot's default logging configuration comes into effect.

Configuration Issue ./gradlew :missing-configuration-repro:build

Due to your use of test fixtures, your tests are configured to use the project's jar rather than its classes directory. The jar is a fat jar so the classes are nested beneath BOOT-INF/classes and therefore cannot be found. This is a known issue with Gradle. There's a workaround in that issue.

./gradlew :log4j-repro:bootRun will show that whatever the log4j2 configuration is, it's not the same as the slf4j one, it doesn't have color, and this format is undocumented.

I think the lack of colour is due to the way that Gradle launches the process. Building with bootJar and running with java -jar produces coloured output. IIRC, Logback behaves the same way.

Other differences between the Logback and Log4j2 output aren't immediately apparent to me. Can you highlight the differences that you've identified?

./gradlew :log4j-repro:test shows that if you copy the documented slf4j configuration it spews garbage.

The syntax of the pattern is specific to the logging framework that you're using. You are trying to configure Log4j2 using Logback's syntax so, from Log4j2's perspective it's garbage in and, therefore, garbage out. You can learn about the required syntax for Log4j2 in its documentation.

Comment From: xenoterracide

There's some output with the logging framework's default configuration and levels until Spring Boot is bootstrapped, and then Spring Boot's default logging configuration comes into effect.

so you're saying debug logging is enabled by default? it's very noisy, and I notice it's inconsistent in bootRun where its not enabled.

Due to your use of test fixtures

ugh, well I might just have to make another configuration, as of right now I don't really need test-fixtures enabled in an application, probably best to only enable it when I need it, tbh.

I think the lack of colour is due to the way that Gradle launches the process.

maybe I honestly can't say, I've been working on the pattern and I've managed to get color out of it running in the same way, but since I don't really know what's being done...

Other differences between the Logback and Log4j2 output aren't immediately apparent to me. Can you highlight the differences that you've identified?

I don't think there are any honestly

The syntax of the pattern is specific to the logging framework that you're using.

yes I know, what I'm suggesting is documenting the pattern you're using the way you've documented the one for slf4j, that way there's an easier starting point.

Comment From: xenoterracide

There's some output with the logging framework's default configuration and levels until Spring Boot is bootstrapped, and then Spring Boot's default logging configuration comes into effect.

Also, it's worth re-mentioning this DEBUG logging is not present when I switch to log4j2

Comment From: wilkinsona

so you're saying debug logging is enabled by default? it's very noisy, and I notice it's inconsistent in bootRun where its not enabled

The logging framework's defaults are in place until such a time as Spring Boot can configure it. With bootRun, that configuration can be done very early. When running tests it can't be done quite so early as the test framework has to do some work before Spring Boot it bootstrapped. You can suppress it with a logback-test.xml or log4j2-test.xml file.

maybe I honestly can't say, I've been working on the pattern and I've managed to get color out of it running in the same way, but since I don't really know what's being done...

This issue reminded me that we had coloured output working with bootRun several years ago. We seem to have lost it again although the fix is still in place. Some experimentation with old, unsupported versions of Spring Boot has revealed that the colour coding appears to be lost when upgrading to Gradle 3.0 or later. I've opened https://github.com/spring-projects/spring-boot/issues/24169.

what I'm suggesting is documenting the pattern you're using

There are links to the default configuration for each logging framework, including the console pattern that's used at that end of this section in the documentation.

the one for slf4j

Just to be clear, there's no pattern for SLF4J. SLF4J is a facade over several different logging frameworks including Logback and Log4j2. By default Spring Boot uses Logback and you are switching to Log4j2. In both cases, SLF4J is still available and can be used for logging calls that are then routed into the underlying logging framework where pattern configuration and the like comes into play.

Also, it's worth re-mentioning this DEBUG logging is not present when I switch to log4j2

This is most likely to be due to the two different logging frameworks having different configuration. Alternatively, one may be picking up an external configuration file while the other isn't. It's impossible to say for certain which may be the case without out knowing exactly what's in your file system and available on the classpath.

Hopefully that addresses everything you've raised. Other than the loss of coloured output (thank you for bringing that you our attention), I don't think there's anything else that's actionable. 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: xenoterracide

So it doesn't matter that you get different log output (like what logs are emitted) based on which logging system is loaded? it feels like it matters that the exact same logs are not emitted for the exact same configuration (regardless of appearance). Makes me wonder if additional logs might go missing with log4j2 (even if I do like that it's quieter up front, and wish for an early way to squelch logback logs).

just seems like a bad idea that some logs do not emit with log4j2

Comment From: wilkinsona

The difference in log output before Spring Boot gets a chance to configure the logging framework is dictated by the default behaviour of the logging framework. If you prefer one framework's defaults over another, that would be one reason for you to choose to use it. If you like a particular logging framework for other reasons and want to change its default configuration you can do so. In Spring Boot, this is generally only necessary in tests as, during normal running, we're able to configure the logging framework really early. As I said above, to take take control of the logging output in tests you should provide a logback-test.xml or log4j2-test.xml file. These files go in src/test/resources so that they don't affect your application when it's running normally.

SpringBoot logging woes

doc problems

conflicting slf4j when adding log4j2

problems with slf4j

problems with log4j