Why does Spring boot execute SpringApplicationRunListener twice when using Eureka

Question

I defined a simple SpringApplicationRunListener implementation with the following method:

@Override
public void finished(ConfigurableApplicationContext configurableApplicationContext, Throwable throwable) {
    logger.info("It's finished");
}

When I run without any Spring cloud dependency I get the following log:

2016-04-27 10:37:37.702  INFO 5720 --- [           main] s.b.c.e.t.TomcatEmbeddedServletContainer : Tomcat started on port(s): 8080 (http)
2016-04-27 10:37:37.703  INFO 5720 --- [           main] b.a.test.LazyFilterRuntimeListener       : It's finished

However, when I add the following dependency:

<dependency>
    <groupId>org.springframework.cloud</groupId>
    <artifactId>spring-cloud-starter-eureka</artifactId>
</dependency>

Then the "It's finished" line is logged twice, once at the end (like without Spring cloud/Eureka) and once at the start, even before the Spring boot logo appears:

2016-04-27 10:37:35.500  INFO 5720 --- [           main] s.c.a.AnnotationConfigApplicationContext : Refreshing org.springframework.context.annotation.AnnotationConfigApplicationContext@255b53dc: startup date [Wed Apr 27 10:37:35 CEST 2016]; root of context hierarchy
2016-04-27 10:37:35.638  INFO 5720 --- [           main] f.a.AutowiredAnnotationBeanPostProcessor : JSR-330 'javax.inject.Inject' annotation found and supported for autowiring
2016-04-27 10:37:35.785  INFO 5720 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'encrypt.CONFIGURATION_PROPERTIES' of type [class org.springframework.cloud.bootstrap.encrypt.KeyProperties] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2016-04-27 10:37:35.786  INFO 5720 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'encryptionBootstrapConfiguration' of type [class org.springframework.cloud.bootstrap.encrypt.EncryptionBootstrapConfiguration$$EnhancerBySpringCGLIB$$268d5fc8] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2016-04-27 10:37:35.839  INFO 5720 --- [           main] b.c.test.LazyFilterRuntimeListener       : It's finished
2016-04-27 10:37:35.842  INFO 5720 --- [           main] be.company.test.TestApplication   : Started TestApplication in 0.499 seconds (JVM running for 0.86)

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


...

2016-04-27 10:37:37.702  INFO 5720 --- [           main] s.b.c.e.t.TomcatEmbeddedServletContainer : Tomcat started on port(s): 8080 (http)
2016-04-27 10:37:37.703  INFO 5720 --- [           main] b.c.test.LazyFilterRuntimeListener       : It's finished
2016-04-27 10:37:37.703  INFO 5720 --- [           main] be.company.test.TestApplication   : Started TestApplication in 2.423 seconds (JVM running for 2.721)

It also mentions the line "Started Application in ..." twice.

Is there a particular reason for this behaviour? I'm trying to write a SpringApplicationRunListener that relies on specific beans to have been created. However, if I add spring cloud, the first time it reaches the finished() method, the context is not yet created, so it currently throws an error.

I'm experiencing the same issue. Did you report the problem? If so, could you post a link to it? — Ruben, May 17 '16 at 16:23
No, didn't report it. We worked around the issue for our case. Since we required beans to have been on the context, we checked if the bean existed first. https://github.com/camunda/camunda-bpm-spring-boot-starter/commit/19a6061533d56499896025a2886ca48514344a9a#diff-c41da622737469f43899d92d98d1edb0R40. I have no idea if this issue is bound to 1.2.x or 1.3.x either. — g00glen00b, May 17 '16 at 21:00

score 2 · Accepted Answer · edited May 23 '17 at 12:23

2

Actually there is a issue of double calling for logging. By default Spring Boot sets up INFO level logging.

Previous version of spring boot before 1.3, as you are using 1.2.7 Then it uses

if you can't override spring boot's CONSOLE_LOG_PATTERN with your MDC value added, then it seems you have to live with every log message being written twice! (once with the spring boot console appender and once with your console appender with MDC added to the pattern)

But in spring boot 1.3 In newer versions of Spring Boot you can easily just include the base.xml from Spring Boot and create the following logback.xml.

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <include resource="org/springframework/boot/logging/logback/base.xml" />

    <root level="INFO">
        <appender-ref ref="FILE" />
    </root>
</configuration>

For more details, you can follow: How to disable logback ConsoleAppender in Spring Boot

Resource Link:

edited May 23 '17 at 12:23

Community

1
1

answered Apr 27 '16 at 09:36

SkyWalker

28,384
14
74
132

1

I'm not quite sure what this means. You're suggesting that the logs themself are repeated twice? This is not the issue though. The method is certainly invoked twice. The timestamps are different as well and the "XX" in "Started TestApplication in XX seconds" is also different, so I doubt it is purely a logging issue. It also **only** applies to Spring cloud + Spring boot, I'm not having any issues when I run Spring boot (1.2.7) solely. – g00glen00b Apr 27 '16 at 12:35
agreed, same issue over here, also happening when using spring cloud config – Ruben May 17 '16 at 16:20
2

The problem relied in the spring cloud commons package. This was already fixed here: https://github.com/spring-cloud/spring-cloud-commons/pull/100 and is available in version 1.1.0+ – Ruben May 19 '16 at 08:35
@Ruben Thanks for sharing. – SkyWalker May 19 '16 at 10:05

Why does Spring boot execute SpringApplicationRunListener twice when using Eureka

1 Answers1