Logo Questions Linux Laravel Mysql Ubuntu Git Menu
 

spring JNDI logging before logback is initialized

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 ...
like image 433
dlipofsky Avatar asked Feb 24 '17 18:02

dlipofsky


People also ask

Does spring use Logback by default?

By default, Spring Boot picks up the native configuration from its default location for the system (such as classpath:logback.

Does spring boot use Log4j instead of Logback?

Spring Boot supports Log4j 2 for logging configuration if it is on the classpath. If you are using the starters for assembling dependencies that means you have to exclude Logback and then include log4j 2 instead. If you aren't using the starters then you need to provide jcl-over-slf4j (at least) in addition to Log4j 2.

How do I enable debug logs in Logback?

debug=true to enable debugging of the logback setup. Unfortunately, there is no way to enable debugging via a System property. You have to use <configuration debug="true"> in the logback. xml .

Where does Logback xml go in spring boot?

In a Spring Boot application, you can put the Logback. xml file in the resources folder. If your Logback. xml file is outside the classpath, you need to point to its location using the Logback.


2 Answers

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.

like image 181
MZS Avatar answered Sep 18 '22 19:09

MZS


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.

like image 30
Ruslan Akhundov Avatar answered Sep 18 '22 19:09

Ruslan Akhundov