log4j-jul configuration is somehow silencing all log4j2 logging with gradle junit5 tests

Question

To start here's the full source as it is https://github.com/xenoterracide/iv-adh

When I enable the system property in my JUnit tasks all of my logging disappears.

tasks.test {
  // Use junit platform for unit tests.
  useJUnitPlatform()

  // this isn't currently enabled in the code, so you can see the logging working when you run the ./gradlew build, but if you uncomment it, you'll see the logs disappear.
  systemProperty("java.util.logging.manager","org.apache.logging.log4j.jul.LogManager")

  testLogging {
    lifecycle {
      showStandardStreams = true
      displayGranularity = 2
      events.addAll(listOf(
        TestLogEvent.STARTED,
        TestLogEvent.PASSED,
        TestLogEvent.SKIPPED,
        TestLogEvent.FAILED
      ))
    }
  }
  reports {
    html.isEnabled = false
    junitXml.isEnabled = true
  }
}

Here's my log4j config

  static void configureLog4j() {
    var console = "console";
    var builder = ConfigurationBuilderFactory.newConfigurationBuilder();

    var defaultAppender = builder.newAppender( console, "CONSOLE" )
      .addAttribute( "target", ConsoleAppender.Target.SYSTEM_OUT );
    defaultAppender.add( builder.newLayout( "PatternLayout" )
      .addAttribute( "pattern", "%highlight{%-5level} - %msg%n      - Context %MDC%n%throwable" ) );

    builder.add( defaultAppender );
    builder.add( builder.newRootLogger( Level.ERROR )
      .add( builder.newAppenderRef( console ) ) );
    builder.add( builder.newLogger( "com.xenoterracide", Level.DEBUG ) );
    Configurator.initialize( builder.build() );
  }

here's the relevant part of a test

class RecordAssemblerTest {

  @BeforeAll
  static void configureLog4j() {
    Application.configureLog4j();
  }

  @Test
  void parsers() throws Exception {

I did see other answers on here, but this is the answer they gave, so I'm not certain why it's silencing my other logging. My end goal is to have all logging working but to silence the javax.money/moneta logging.

update:

setting the property in the JavaExec task works when using ./gradlew run, not certain why it isn't working for tests though.

tasks.withType<JavaExec> {
  systemProperty("java.util.logging.manager", "org.apache.logging.log4j.jul.LogManager")
}

Answer 1

You can debug logging using System.out. Using your code add the printConfig method and call it with @AfterAll. When I do this with your code and run ./gradlew build I get the following output:

FileProcessorTest STANDARD_ERROR
java.util.logging.config.class was null
java.util.logging.config.file was null
LogManager=org.apache.logging.log4j.jul.LogManager
scn=CoreLogger, n=, uph=true, l=WARNING, fl=null
    ->org.slf4j.bridge.SLF4JBridgeHandler, h=ALL, fl=null
scn=CoreLogger, n=org.junit.jupiter.engine.execution.InvocationInterceptorChain$ValidatingInvocation, uph=true, l=SEVERE, fl=null
scn=CoreLogger, n=javax.management.timer, uph=true, l=null, fl=null
scn=CoreLogger, n=org.junit.platform.launcher.core.LauncherConfigurationParameters, uph=true, l=SEVERE, fl=null
scn=CoreLogger, n=org.junit.platform.launcher.core.EngineDiscoveryOrchestrator, uph=true, l=SEVERE, fl=null
scn=CoreLogger, n=org.junit.jupiter.engine.descriptor.JupiterTestDescriptor, uph=true, l=SEVERE, fl=null
scn=CoreLogger, n=org.junit.platform.launcher.core.ServiceLoaderTestExecutionListenerRegistry, uph=true, l=SEVERE, fl=null
scn=CoreLogger, n=org.junit.jupiter.engine.descriptor.MethodBasedTestDescriptor, uph=true, l=SEVERE, fl=null
scn=CoreLogger, n=org.junit.jupiter.engine.execution.JupiterEngineExecutionContext, uph=true, l=SEVERE, fl=null
scn=CoreLogger, n=org.junit.jupiter.engine.discovery.MethodOrderingVisitor, uph=true, l=SEVERE, fl=null
scn=CoreLogger, n=org.junit.platform.launcher.core.InternalTestPlan, uph=true, l=SEVERE, fl=null
scn=CoreLogger, n=javax.management.monitor, uph=true, l=null, fl=null
scn=CoreLogger, n=javax.management.notification, uph=true, l=null, fl=null
scn=CoreLogger, n=org.junit.jupiter.engine.execution.ConditionEvaluator, uph=true, l=SEVERE, fl=null
scn=CoreLogger, n=javax.management.mbeanserver, uph=true, l=null, fl=null
scn=CoreLogger, n=org.junit.platform.launcher.core.ServiceLoaderPostDiscoveryFilterRegistry, uph=true, l=SEVERE, fl=null
scn=CoreLogger, n=org.junit.jupiter.engine.extension.TimeoutConfiguration, uph=true, l=SEVERE, fl=null
scn=CoreLogger, n=org.junit.platform.launcher.core.TestExecutionListenerRegistry, uph=true, l=SEVERE, fl=null
scn=CoreLogger, n=org.junit.jupiter.engine.extension.MutableExtensionRegistry, uph=true, l=SEVERE, fl=null
scn=CoreLogger, n=org.junit.jupiter.engine.discovery.MethodSelectorResolver, uph=true, l=SEVERE, fl=null
scn=CoreLogger, n=javax.management.relation, uph=true, l=null, fl=null
scn=CoreLogger, n=javax.management.modelmbean, uph=true, l=null, fl=null
scn=CoreLogger, n=org.junit.jupiter.engine.execution.ExecutableInvoker, uph=true, l=SEVERE, fl=null
scn=CoreLogger, n=org.javamoney.moneta.spi.MoneyUtils, uph=true, l=SEVERE, fl=null
scn=CoreLogger, n=javax.management, uph=true, l=null, fl=null
scn=CoreLogger, n=org.junit.jupiter.engine.config.InstantiatingConfigurationParameterConverter, uph=true, l=SEVERE, fl=null
scn=CoreLogger, n=org.junit.platform.launcher.core.EngineIdValidator, uph=true, l=SEVERE, fl=null
scn=CoreLogger, n=org.junit.jupiter.engine.descriptor.DisplayNameUtils, uph=true, l=SEVERE, fl=null
scn=CoreLogger, n=org.junit.jupiter.engine.support.OpenTest4JAndJUnit4AwareThrowableCollector, uph=true, l=SEVERE, fl=null
scn=CoreLogger, n=org.junit.platform.commons.util.ReflectionUtils, uph=true, l=SEVERE, fl=null
scn=CoreLogger, n=javax.management.misc, uph=true, l=null, fl=null
scn=CoreLogger, n=org.junit.platform.engine.support.hierarchical.NodeTestTask, uph=true, l=SEVERE, fl=null
scn=CoreLogger, n=org.junit.platform.launcher.core.ServiceLoaderTestEngineRegistry, uph=true, l=SEVERE, fl=null
scn=CoreLogger, n=org.javamoney.moneta.spi.MonetaryConfig, uph=true, l=SEVERE, fl=null
scn=CoreLogger, n=javax.management.mlet, uph=true, l=null, fl=null
scn=CoreLogger, n=org.junit.jupiter.engine.config.EnumConfigurationParameterConverter, uph=true, l=SEVERE, fl=null
scn=CoreLogger, n=org.junit.platform.commons.util.ClasspathScanner, uph=true, l=SEVERE, fl=null
scn=CoreLogger, n=org.javamoney.moneta.DefaultMonetaryContextFactory, uph=true, l=SEVERE, fl=null

The takeaways are:

1. org.apache.logging.log4j.jul.LogManager is installed. [PASS]
2. org.slf4j.bridge.SLF4JBridgeHandler is installed and set to ALL. Your code is using log4j but it appears that SLF4J is setup too [WARN]
3. All loggers are publishing to SLF4JBridgeHandler per uph=true [PASS]
4. There are no com.xenoterracide loggers. Project uses logj. [PASS]
5. Root logger is set set to WARNING. Will only see WARN and ERROR. [QUESTIONABLE]
6. Child loggers are a mix of null and SEVERE. Will only see WARN and ERROR.[QUESTIONABLE]

So lets run this again but without the log4j.jul.LogManager set in either place and I'll use System.out:

FileProcessorTest STANDARD_OUT
java.util.logging.config.class was null
java.util.logging.config.file was null
LogManager=java.util.logging.LogManager
scn=RootLogger, n=, uph=true, l=INFO, fl=null
    ->java.util.logging.ConsoleHandler, h=INFO, fl=null
scn=Logger, n=org.junit.jupiter.engine.execution.InvocationInterceptorChain$ValidatingInvocation, uph=true, l=null, fl=null
scn=Logger, n=javax.management.timer, uph=true, l=null, fl=null
scn=Logger, n=global, uph=true, l=null, fl=null
scn=Logger, n=org.junit.platform.launcher.core.LauncherConfigurationParameters, uph=true, l=null, fl=null
scn=Logger, n=org.junit.platform.launcher.core.EngineDiscoveryOrchestrator, uph=true, l=null, fl=null
scn=Logger, n=org.junit.jupiter.engine.descriptor.JupiterTestDescriptor, uph=true, l=null, fl=null
scn=Logger, n=org.junit.platform.launcher.core.ServiceLoaderTestExecutionListenerRegistry, uph=true, l=null, fl=null
scn=Logger, n=org.junit.jupiter.engine.descriptor.MethodBasedTestDescriptor, uph=true, l=null, fl=null
scn=Logger, n=org.junit.jupiter.engine.execution.JupiterEngineExecutionContext, uph=true, l=null, fl=null
scn=Logger, n=org.junit.jupiter.engine.discovery.MethodOrderingVisitor, uph=true, l=null, fl=null
scn=Logger, n=org.junit.platform.launcher.core.InternalTestPlan, uph=true, l=null, fl=null
scn=Logger, n=org.junit.jupiter.engine.execution.ConditionEvaluator, uph=true, l=null, fl=null
scn=Logger, n=javax.management.monitor, uph=true, l=null, fl=null
scn=Logger, n=javax.management.notification, uph=true, l=null, fl=null
scn=Logger, n=javax.management.mbeanserver, uph=true, l=null, fl=null
scn=Logger, n=org.junit.platform.launcher.core.ServiceLoaderPostDiscoveryFilterRegistry, uph=true, l=null, fl=null
scn=Logger, n=org.junit.jupiter.engine.extension.TimeoutConfiguration, uph=true, l=null, fl=null
scn=Logger, n=org.junit.platform.launcher.core.TestExecutionListenerRegistry, uph=true, l=null, fl=null
scn=Logger, n=org.junit.jupiter.engine.extension.MutableExtensionRegistry, uph=true, l=null, fl=null
scn=Logger, n=org.junit.jupiter.engine.discovery.MethodSelectorResolver, uph=true, l=null, fl=null
scn=Logger, n=javax.management.relation, uph=true, l=null, fl=null
scn=Logger, n=org.junit.jupiter.engine.execution.ExecutableInvoker, uph=true, l=null, fl=null
scn=Logger, n=javax.management.modelmbean, uph=true, l=null, fl=null
scn=Logger, n=org.javamoney.moneta.spi.MoneyUtils, uph=true, l=null, fl=null
scn=Logger, n=org.junit.jupiter.engine.config.InstantiatingConfigurationParameterConverter, uph=true, l=null, fl=null
scn=Logger, n=javax.management, uph=true, l=null, fl=null
scn=Logger, n=org.junit.platform.launcher.core.EngineIdValidator, uph=true, l=null, fl=null
scn=Logger, n=org.javamoney.moneta.Money, uph=true, l=null, fl=null
scn=Logger, n=org.junit.jupiter.engine.descriptor.DisplayNameUtils, uph=true, l=null, fl=null
scn=Logger, n=org.junit.jupiter.engine.support.OpenTest4JAndJUnit4AwareThrowableCollector, uph=true, l=null, fl=null
scn=Logger, n=org.junit.platform.commons.util.ReflectionUtils, uph=true, l=null, fl=null
scn=Logger, n=javax.management.misc, uph=true, l=null, fl=null
scn=Logger, n=org.junit.platform.engine.support.hierarchical.NodeTestTask, uph=true, l=null, fl=null
scn=Logger, n=org.junit.platform.launcher.core.ServiceLoaderTestEngineRegistry, uph=true, l=null, fl=null
scn=Logger, n=org.javamoney.moneta.spi.MonetaryConfig, uph=true, l=null, fl=null
scn=Logger, n=org.junit.jupiter.engine.config.EnumConfigurationParameterConverter, uph=true, l=null, fl=null
scn=Logger, n=org.junit.platform.commons.util.ClasspathScanner, uph=true, l=null, fl=null
scn=Logger, n=javax.management.mlet, uph=true, l=null, fl=null
scn=Logger, n=org.javamoney.moneta.DefaultMonetaryContextFactory, uph=true, l=null, fl=null

Now when I compare the two runs you can see:

1. When log4j log manager is running the levels are either WARNING inherited from the root logger or SEVERE set on the child logger.
2. When running the JUL log manager the levels are all inheriting INFO.

I think the issue you are seeing is in Application.java#L54.

1. You need to set the root logger level to the given level. builder.add( builder.newRootLogger( level )
2. The log4j configuration is not updating the JUL logger levels correctly. This points to an error in Application::configureLog4j.
3. The org.slf4j.bridge.SLF4JBridgeHandler is not installed. Perhaps when the bridge handler was installed the output was going to SLF4J and there was no console appender setup for SLF4J.

One thing you could try would be to explicitly exclude the jul-to-slf4j package. Maybe that will allow logj4 to take control of jul instead of slf4j. There is also a related information Java logging: slf4j over jul and log4j2.