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 ...

Blairblaire

In what environment are you running your application? It looks like Jetty with JNDI enabled. Are you using embedded Jetty or deploying a war file? – Risky

we are using embedded jetty. We launch like @SpringBootApplication(scanBasePackages = { ... }, exclude = { ... }) @ImportResource("classpath:/spring/foobar-context.xml") @ServletComponentScan public class FoobarApplication extends SpringBootServletInitializer { public static void main(final String[] args) { SpringApplication.run(FoobarApplication.class, args); } ... } – Blairblaire

This also happens when using a standalone Tomcat 8.0.33. The "spring.jndi.ignore=true" answer below works but does not feel good. – Figwort

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:
# https://mcmap.net/q/777319/-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.

Haught

This works for me. You can also set it with a -D flag but the file works better for my purposes. – Blairblaire

In case anyone else is running into this issue. This change works for me when I put the configuration in spring.properties, but not when I put it in bootstrap.properties. – Mosera

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.

Doall

Answer 3

I had this issue, albeit with log4j2. The solution of spring.jndi.ignore=true in a spring.properties file didn't work for me, either.

The issue appeared after I implemented spring profile-based logging files, as implemented here: Spring Boot, logback and logging.config property

For log4j2, the solution was to set some classloader context. I used log4j2.contextSelector=org.apache.logging.log4j.core.selector .ClassLoaderContextSelector in the log4j2.properties file, which I picked from The Log4j2 manual (Section: LOG4J_CONTEXT_SELECTOR).

Flux

Answer 4

you can avoid this by add this line to your logback xml file

<logger name="org.springframework.jndi" level="INFO" />

Poltergeist

No, you can't, because these messages get logged before logback is initialized. My logback is already set to WARN threshold by default. – Blairblaire