Spring Running JNDI before login is initialized

Question

I have a spring boot application that prints about 1,500 lines of the JNDI debug log to stdout at startup before the login is restored. Does anyone know what causes this, and if there is a way to get the login initialized before that? I have -Dlogback.debug = true, but that helps a little.

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.s pringframework.boot.logging.logback.SpringBootJoranConfigurator@ 32b260fa - Registering current configuration as safe fallback point . ____ _ __ _ _ /\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \ ( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \ \\/ ___)| |_)| | | | | || (_| | ) ) ) ) ' |____| .__|_| |_|_| |_\__, | / / / / =========|_|==============|___/=/_/_/_/ :: Spring Boot :: (v1.4.4.RELEASE) 10:44:56,750 |-INFO in cqlco.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 log - spring.xml. Debug statements are not displayed if logback- spring.xml does not exist.

I managed to get around it by disabling JNDIPropertySource. Create a file, spring.properties, in the root directory of the path:

 # 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 added at https://jira.spring.io/browse/SPR-14026 .

This approach seems intimidating, but since I am not working in a container where JNDI is useful, it will not break anything for me.

Answer 2

I also had the same problem, but I could not disable jndi because my application uses it at startup. Therefore, after some research, I got a solution:

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

2) put the logging.config property in the application.properties file.

As a result, your configuration will only be applied when spring starts, and this debugging logging will be skipped. Also in my case, the first solution did not work, because I need jndi, in this case you also leave jndi turned on.

Update:, it helped only for the local environment, to do the same work with the remote tomcat and remove this debug log from the catalina.log file, in the end I renamed this log file to the logback.xml file, so it was found at startup, before looking for jndi.

Answer 3

you can avoid this by adding this line to your xml log file

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