spring JNDI logging before logback is initialized

Question

I've got a spring boot app that is outputing around 1500 lines of JNDI debug logging to stdout at startup before logback is initialized. Does anyone know what's causing this and if there is a way to get logback initialized before this? I've got -Dlogback.debug=true but it doesn't help much.

10:44:56.453 [main] DEBUG org.springframework.jndi.JndiTemplate - Looking up JNDI object with name [java:comp/env/logging.exception-conversion-word]
10:44:56.457 [main] DEBUG jndi - InitialContextFactory.getInitialContext()
10:44:56.457 [main] DEBUG jndi - Created initial context delegate for local namespace:org.eclipse.jetty.jndi.local.localContextRoot@564fabc8
10:44:56.457 [main] DEBUG org.eclipse.jetty.jndi.java.javaURLContextFactory - >>> new root context requested 
10:44:56.457 [main] DEBUG jndi - Looking up name="comp/env/logging.exception-conversion-word"
10:44:56.457 [main] DEBUG jndi - Trying thread context classloader
10:44:56.457 [main] DEBUG jndi - Looking up name="env/logging.exception-conversion-word"
10:44:56.458 [main] DEBUG org.springframework.jndi.JndiLocatorDelegate - Converted JNDI name [java:comp/env/logging.exception-conversion-word] not found - trying original name [logging.exception-conversion-word]. javax.naming.NameNotFoundException; remaining name 'env/logging.exception-conversion-word'
10:44:56.458 [main] DEBUG org.springframework.jndi.JndiTemplate - Looking up JNDI object with name [logging.exception-conversion-word]

...

10:44:56.487 [main] DEBUG jndi - Looking up name="env/LOGGING_PATTERNLEVEL"
10:44:56.487 [main] DEBUG org.springframework.jndi.JndiLocatorDelegate - Converted JNDI name [java:comp/env/LOGGING_PATTERNLEVEL] not found - trying original name [LOGGING_PATTERNLEVEL]. javax.naming.NameNotFoundException; remaining name 'env/LOGGING_PATTERNLEVEL'
10:44:56.487 [main] DEBUG org.springframework.jndi.JndiTemplate - Looking up JNDI object with name [LOGGING_PATTERNLEVEL]
10:44:56.487 [main] DEBUG jndi - InitialContextFactory.getInitialContext()
10:44:56.487 [main] DEBUG jndi - Created initial context delegate for local namespace:org.eclipse.jetty.jndi.local.localContextRoot@bcec361
10:44:56.487 [main] DEBUG jndi - Looking up name="LOGGING_PATTERNLEVEL"
10:44:56.487 [main] DEBUG org.springframework.jndi.JndiPropertySource - JNDI lookup for name [LOGGING_PATTERNLEVEL] threw NamingException with message: null. Returning null.
10:44:56,536 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
10:44:56,539 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT]
10:44:56,543 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
10:44:56,561 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.rolling.RollingFileAppender]
10:44:56,564 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [FILE]
10:44:56,565 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
10:44:56,571 |-INFO in my.log.TimestampRollingPolicy@24fcf36f - Will use the pattern /tmp/logs/qs.%d{yyyyMMdd-HHmmss}.log to archive files
10:44:56,574 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[FILE] - Active log file name: /tmp/logs/qs.log
10:44:56,574 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[FILE] - File property is set to [/tmp/logs/qs.log]
10:44:56,576 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to WARN
10:44:56,576 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@4a7f959b - Propagating WARN level on Logger[ROOT] onto the JUL framework
10:44:56,576 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [FILE] to Logger[ROOT]
10:44:56,576 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT]
10:44:56,576 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
10:44:56,577 |-INFO in org.springframework.boot.logging.logback.SpringBootJoranConfigurator@32b260fa - Registering current configuration as safe fallback point

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

10:44:56,750 |-INFO in c.q.l.co.rolling.helper.RenameUtil - Renaming file [/tmp/logs/qs.log] to [/tmp/logs/qs.20170222-173130.log]
10:44:56 [main] INFO  my.Application - Starting ...

Answer 1

I also saw this with Spring Boot 1.5.1 when using a custom logback-spring.xml. The debug statements don't appear if logback-spring.xml doesn't exist.

I was able to work around it by disabling the JNDIPropertySource. Create a file, spring.properties, in your classpath root:

# Disable the JNDIPropertySource. This avoids dozens of spurious DEBUG messages
# when starting up with a custom logback-spring.xml. We're not alone:
# http://stackoverflow.com/questions/42446013/spring-jndi-logging-before-logback-is-initialized
spring.jndi.ignore=true

spring.jndi.ignore was added in https://jira.spring.io/browse/SPR-14026.

This approach feels squicky, but as I'm not running in a container where JNDI would be useful, it doesn't break anything for me.

Answer 2

I also had the same problem, but I couldn't turn off jndi, because my application is using it on startup. So after some research, I ended up with the solution:

1) rename logback-spring.xml to some other name, for example logback-config.xml

2) put logging.config property into application.properties file.

As the result you configuration will be applied only on spring startup, and this debug logging will be skipped. Also in my case the first solution wasn't working because I needed jndi, in this case you also leave jndi enabled.

Update: this helped only for local environment, to make the same work on remote tomcat and remove this debug log from catalina.log file, I ended up with renaming this logback file to logback.xml, thus it's found on the startup, before jndi lookup.