Slf4JLoggingSystem should also configure JUL levels

[farrault]

As discussed here, by default SLF4JBridgeHandler only receives INFO or higher JUL logs

And so, enabled lower levels in application.properties with "logging.level.xxx" properties doesn't allow to see JUL logs lower than INFO

"logging.level.xxx" properties should also be applied to JUL loggers (in addition to Sl4jf loggers) in order to SLF4JBridgeHandler to receive all the enabled logs

[trecloux]

If you are using logback, JUL should now also be configured : #3926

[philwebb]

I think this should be fixed by #3926. If you're still having the problem with the latest release please let us know.

[mmoayyed]

@philwebb per your last comment, I am writing back to report that this issue is still present in Spring Boot 1.5.2 using Log4j2. The only way to get messages from JUL that are below INFO is to use the following trick:

java -jar ... -Djava.util.logging.config.file=/path/to/logging.properties

where as an example:

handlers = java.util.logging.ConsoleHandler
.level = ALL
java.util.logging.ConsoleHandler.level = DEBUG
java.util.logging.ConsoleHandler.formatter = java.util.logging.SimpleFormatter

What can I do to assist with troubleshooting and resolution of this problem?

[philwebb]

@mmoayyed Do you have a sample you can share that shows the problem?

[mmoayyed]

Sure. This is where I started out originally: https://github.com/apereo/cas-overlay-template

There are instructions on the README that explain what one must do to build and deploy. What I can see that once I modify the /etc/cas/config/log4j2.xml file to open up logging to TRACE for anything under org.apache, I don't ever get any Tomcat-related logs below INFO. I can apply the same sort of logging change to the cas.properties file or the application.yml file and that exhibits the same behavior.

You can also very easily duplicate this with start.spring.io. Here's what I did:

1. Generate a project selecting only the web dependency.
2. Exclude the logging starter module, and use the one for log4j2 per the docs.
3. Change application.properties file to have: logging.level.org.apache=DEBUG.
4. Package and build. Notice the absence of DEBUG logs in the console. Note that if I skip step [BS-157] Add support for MultipartConfig #2, I can perfectly see DEBUG data when logback is used.

You can also use demo.zip which is my attempt at duplicating this issue with 1-4 combined.

[wilkinsona]

Thanks for the sample. Given the lack of a Log4j equivalent of Logback's LevelChangePropagator, there's no easy way for us to propagate Log4j log levels into JUL.

Instead, the recommended approach with Log4j is to configure the use of org.apache.logging.log4j.jul.LogManager via the java.util.logging.manager system property. This has to be done before any calls to JUL are made. We fine-tuned Boot's use of JUL in 1.5.5 (#9848) so that it's not used until classes from dependencies nested in a fat jar can be loaded.

This approach works well with the provided sample if you upgrade to Spring Boot 1.5.5 or later (I used 1.5.9), add a dependency on org.apache.logging.log4j:log4j-jul, and launch the app with the required system property:

$ java -Djava.util.logging.manager=org.apache.logging.log4j.jul.LogManager -jar target/demo-0.0.1-SNAPSHOT.jar

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::        (v1.5.9.RELEASE)

2018-01-17 21:12:56.729  INFO 56307 --- [           main] c.e.DemoApplication                      : Starting DemoApplication v0.0.1-SNAPSHOT on aw-rmbp.local with PID 56307 (/Users/awilkinson/Downloads/gh-2923/demo/target/demo-0.0.1-SNAPSHOT.jar started by awilkinson in /Users/awilkinson/Downloads/gh-2923/demo)
2018-01-17 21:12:56.734  INFO 56307 --- [           main] c.e.DemoApplication                      : No active profile set, falling back to default profiles: default
2018-01-17 21:12:56.791  INFO 56307 --- [           main] ationConfigEmbeddedWebApplicationContext : Refreshing org.springframework.boot.context.embedded.AnnotationConfigEmbeddedWebApplicationContext@4cc77c2e: startup date [Wed Jan 17 21:12:56 GMT 2018]; root of context hierarchy
2018-01-17 21:12:56.800 DEBUG 56307 --- [kground-preinit] o.a.t.u.m.Registry                       : Found jar:file:/Users/awilkinson/Downloads/gh-2923/demo/target/demo-0.0.1-SNAPSHOT.jar!/BOOT-INF/lib/tomcat-embed-core-8.5.23.jar!/org/apache/catalina/mbeans/mbeans-descriptors.xml
2018-01-17 21:12:56.812 DEBUG 56307 --- [kground-preinit] o.a.t.u.d.Digester                       : register('-//Apache Software Foundation//DTD Model MBeans Configuration File', 'jar:file:/Users/awilkinson/Downloads/gh-2923/demo/target/demo-0.0.1-SNAPSHOT.jar!/BOOT-INF/lib/tomcat-embed-core-8.5.23.jar!/org/apache/tomcat/util/modeler/mbeans-descriptors.dtd'

The need to use a system property makes me wary of enabling this by default, but we could add something to the relevant section of the documentation. I've opened #11660 to do so.