Search code examples
spring-bootrabbitmqspring-amqpspring-rabbitspring-cloud-bus

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


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?


Solution

  • 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("-------------------------------------");
            }
        }
    
    }