Why Spring Boot Application logs that it started twice after adding spring-cloud-bus dependency

Question

This is simple code in my Spring boot application:

package com.maxxton.SpringBootHelloWorld;

import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;

@SpringBootApplication
public class SpringBootHelloWorldApplication {

  public static void main(String[] args) {
    SpringApplication.run(SpringBootHelloWorldApplication.class, args);
  }
}

And a ApplicationListener class to listen to ApplicationEvent:

package com.maxxton.SpringBootHelloWorld;

import org.springframework.context.ApplicationEvent;
import org.springframework.context.ApplicationListener;
import org.springframework.stereotype.Component;

@Component
public class Test implements ApplicationListener {

  @Override
  public void onApplicationEvent(ApplicationEvent event) {
    if (event.getClass().getSimpleName().equals("ApplicationReadyEvent")) {
      System.out.println("-------------------------------------");
      System.out.println(event.getClass().getSimpleName());
      System.out.println("-------------------------------------");
    }
  }
}

build.gradle contains these dependencies:

dependencies {

    compile("org.springframework.boot:spring-boot-starter-amqp")
    compile("org.springframework.cloud:spring-cloud-starter-bus-amqp")

    compile('org.springframework.boot:spring-boot-starter-web')
    compile('org.springframework.boot:spring-boot-starter')
    compile("org.springframework.cloud:spring-cloud-starter")
    compile("org.springframework.cloud:spring-cloud-starter-security")
    compile("org.springframework.cloud:spring-cloud-starter-eureka")
    testCompile('org.springframework.boot:spring-boot-starter-test')
}

Now, when I run this spring boot application, I see this log printed twice:

[main] c.m.S.SpringBootHelloWorldApplication : Started SpringBootHelloWorldApplication in ... seconds (JVM running for ...)

Usually, this log get printed only once, but it get printed twice if I add these dependencies:

compile("org.springframework.boot:spring-boot-starter-amqp")
compile("org.springframework.cloud:spring-cloud-starter-bus-amqp")

This is complete log:

2017-11-17 15:44:07.372  INFO 5976 --- [           main] o.s.c.support.GenericApplicationContext  : Refreshing org.springframework.context.support.GenericApplicationContext@31c7c281: startup date [Fri Nov 17 15:44:07 IST 2017]; root of context hierarchy
-------------------------------------
ApplicationReadyEvent
-------------------------------------
2017-11-17 15:44:07.403  INFO 5976 --- [           main] c.m.S.SpringBootHelloWorldApplication    : Started SpringBootHelloWorldApplication in 1.19 seconds (JVM running for 10.231)
2017-11-17 15:44:09.483  WARN 5976 --- [           main] o.s.amqp.rabbit.core.RabbitAdmin         : Failed to declare exchange: Exchange [name=springCloudBus, type=topic, durable=true, autoDelete=false, internal=false, arguments={}], continuing... org.springframework.amqp.AmqpConnectException: java.net.ConnectException: Connection refused: connect
2017-11-17 15:44:09.492  INFO 5976 --- [           main] o.s.integration.channel.DirectChannel    : Channel 'a-bootiful-client.springCloudBusOutput' has 1 subscriber(s).
2017-11-17 15:44:09.493  INFO 5976 --- [           main] o.s.c.support.DefaultLifecycleProcessor  : Starting beans in phase 0
2017-11-17 15:44:09.530  INFO 5976 --- [           main] o.s.i.endpoint.EventDrivenConsumer       : Adding {logging-channel-adapter:_org.springframework.integration.errorLogger} as a subscriber to the 'errorChannel' channel
2017-11-17 15:44:09.530  INFO 5976 --- [           main] o.s.i.channel.PublishSubscribeChannel    : Channel 'a-bootiful-client.errorChannel' has 1 subscriber(s).
2017-11-17 15:44:09.530  INFO 5976 --- [           main] o.s.i.endpoint.EventDrivenConsumer       : started _org.springframework.integration.errorLogger
2017-11-17 15:44:09.530  INFO 5976 --- [           main] o.s.c.support.DefaultLifecycleProcessor  : Starting beans in phase 2147482647
2017-11-17 15:44:09.539  INFO 5976 --- [           main] c.s.b.r.p.RabbitExchangeQueueProvisioner : declaring queue for inbound: springCloudBus.anonymous.kZ1vvxHaRfChKe1TncH-MQ, bound to: springCloudBus
2017-11-17 15:44:11.562  WARN 5976 --- [           main] o.s.amqp.rabbit.core.RabbitAdmin         : Failed to declare exchange: Exchange [name=springCloudBus, type=topic, durable=true, autoDelete=false, internal=false, arguments={}], continuing... org.springframework.amqp.AmqpConnectException: java.net.ConnectException: Connection refused: connect
2017-11-17 15:44:13.587  WARN 5976 --- [           main] o.s.amqp.rabbit.core.RabbitAdmin         : Failed to declare queue: Queue [name=springCloudBus.anonymous.kZ1vvxHaRfChKe1TncH-MQ, durable=false, autoDelete=true, exclusive=true, arguments={}], continuing... org.springframework.amqp.AmqpConnectException: java.net.ConnectException: Connection refused: connect
2017-11-17 15:44:15.611  WARN 5976 --- [           main] o.s.amqp.rabbit.core.RabbitAdmin         : Failed to declare binding: Binding [destination=springCloudBus.anonymous.kZ1vvxHaRfChKe1TncH-MQ, exchange=springCloudBus, routingKey=#], continuing... org.springframework.amqp.AmqpConnectException: java.net.ConnectException: Connection refused: connect
2017-11-17 15:44:17.662  INFO 5976 --- [           main] o.s.i.a.i.AmqpInboundChannelAdapter      : started inbound.springCloudBus.anonymous.kZ1vvxHaRfChKe1TncH-MQ
2017-11-17 15:44:17.662  INFO 5976 --- [           main] o.s.i.endpoint.EventDrivenConsumer       : Adding {message-handler:inbound.springCloudBus.default} as a subscriber to the 'bridge.springCloudBus' channel
2017-11-17 15:44:17.662  INFO 5976 --- [           main] o.s.i.endpoint.EventDrivenConsumer       : started inbound.springCloudBus.default
2017-11-17 15:44:17.663  INFO 5976 --- [           main] o.s.c.support.DefaultLifecycleProcessor  : Starting beans in phase 2147483647
2017-11-17 15:44:17.714  INFO 5976 --- [           main] s.b.c.e.t.TomcatEmbeddedServletContainer : Tomcat started on port(s): 8080 (http)
-------------------------------------
ApplicationReadyEvent
-------------------------------------
2017-11-17 15:44:17.717  INFO 5976 --- [           main] c.m.S.SpringBootHelloWorldApplication    : Started SpringBootHelloWorldApplication in 20.131 seconds (JVM running for 20.545)

As you can see, ApplicationReadyEvent is happening twice.

Why is this happening? Is there any way to avoid this?

Never used Spring Cloud Bus but it looks like it might be causing that. According to [the docs](http://cloud.spring.io/spring-cloud-static/spring-cloud-bus/1.3.1.RELEASE/), you can enable tracing, so you could have a look and check if there is something wrong there. A crazy idea might be that the application is listening to its own state changes, therefore consuming its own event and duplicating the output... — Moisés, Nov 17 '17 at 10:27

score 10 · Accepted Answer · answered Nov 17 '17 at 13:25

spring-cloud-bus uses spring-cloud-stream which puts the binder in a separate boot child application context.

You should make your event listener aware of the application context it is running in. You can also use generics to select the event type you are interested in...

@Component
public class Test implements ApplicationListener<ApplicationReadyEvent>, 
                             ApplicationContextAware {

    private ApplicationContext applicationContext;

    @Override
    public void setApplicationContext(ApplicationContext applicationContext) throws BeansException {
        this.applicationContext = applicationContext;
    }

    @Override
    public void onApplicationEvent(ApplicationReadyEvent event) {
        if (event.getApplicationContext().equals(this.applicationContext)) {
            System.out.println("-------------------------------------");
            System.out.println(event.getClass().getSimpleName());
            System.out.println("-------------------------------------");
        }
    }

}

So, you are saying, @gary-russell If we use spring-cloud-bus dependency, "Started SpringBootHelloWorldApplication in ..." will be logged twice, Because spring-cloud-bus uses spring-cloud-stream which puts the binder in a separate boot child. — SanketKD, Nov 20 '17 at 05:50
It will be logged twice only if you don't take my advice and make your listener aware of which application context it is declared int. — Gary Russell, Nov 20 '17 at 14:32
I have made changes as per your suggestions, now listener aware is printing only once, But "Started SpringBootHelloWorldApplication in ..." is still logged twice. — SanketKD, Nov 21 '17 at 08:30

score 0 · Answer 2 · edited Nov 17 '17 at 13:32

0

Are u using multiple binders rabbitmq configuration in your application.yml/.xml ?

If it's a yes, then u can try to exclude RabbitAutoConfiguration.

@EnableDiscoveryClient
@EnableAutoConfiguration(exclude = {RabbitAutoConfiguration.class})
@SpringBootApplication
public class SpringBootHelloWorldApplication {

  public static void main(String[] args) {
    SpringApplication.run(SpringBootHelloWorldApplication.class, args);
  }
}

edited Nov 17 '17 at 13:32

Gary Russell

166,535
14
146
179

answered Nov 17 '17 at 07:02

ismailzakky

114
2
12

No, I am not using multiple binders. – SanketKD Nov 17 '17 at 08:53

Why Spring Boot Application logs that it started twice after adding spring-cloud-bus dependency

2 Answers2