Premature ApplicationReadyEvent in main application context

[rainerfrey]

As Spring Cloud Stream creates an additional SpringApplication for a binder, application listeners in the application receive events for that SpringApplication instance.

I have an application listener that is supposed to send a message on a message channel with an output binding. This listener receives an ApplicationReadyEvent when the binder context application is started, but before the main application is finished starting.

Depending on the timing, the message is send before the stream infrastructure is subscribed to said message channel, thus leading to an exception that the dispatcher for the channel has no subscriber.

The creation of this application instance is undocumented as far as I can see, receiving events from it is quite surprising. Even know that I know about it, I don't know how to distinguish the events. From an application developer perspective I believe my application should not receive such events.

[olegz]

Please provide additional information such as

• versions of spring-cloud-stream
• pointer to a reproducible application (may be you can push something to github)

[rainerfrey]

I observed this with Spring Cloud Release Trains Hoxton.RC2 (SCS 3.0.0RC2) and Greenwich.SR3 (SCS 2.1.4).

A simple application is here rainerfrey/spring-cloud-stream-event-demo, it needs RabbitMQ.

Run it as is, and see the two ApplicationReadyEvents with different sources (with Stacktrace) in the logs. Notably, for me the first one is before the message Channel 'application.output' has 1 subscriber(s).

Uncomment the commented line in de.mrfrey.scse.event.StartupEventListener and see the exception about dispatcher having no subscribers.

[rainerfrey]

@olegz is there anything else I can do right now to move this forward?

[olegz]

@rainerfrey We just released Horsham.RELEASE so you no longer have to worry about manually sending messages to a channel and other boilerplate. You can simply use Supplier bean - https://cloud.spring.io/spring-cloud-static/spring-cloud-stream/3.0.0.RELEASE/reference/html/spring-cloud-stream.html#_suppliers_sources.

You can also read this post about why we are moving away from the annotation-based configuration model - https://spring.io/blog/2019/10/14/spring-cloud-stream-demystified-and-simplified

[rainerfrey]

Huh? Does any of this address the issue of multiple lifecycle application events in Spring Cloud Stream applications? Additionally, is there a way to use functional support to send a message once at startup?

[rainerfrey]

@olegz I moved the sample app to 3.0.0 and a function source. The particular error with a missing subscriber on the message channel does not apply in this case, but I still see the multiple event behaviour. This means, adding Spring Cloud Stream to a Spring Boot application breaks the behaviour of application lifecycle events described in https://docs.spring.io/spring-boot/docs/2.2.1.RELEASE/reference/html/spring-boot-features.html#boot-features-application-events-and-listeners.

Would you consider reopening and investigating?

[olegz]

I'll look when I get a chance, but I am wondering if you're looking at it the right way given that binders ran in their own application context?

[garyrussell]

This listener receives an ApplicationReadyEvent when the binder context application is started, but before the main application is finished starting.

You need to check that the applicationContext property of the event matches the main application context and ignore events for the child context(s).

That's precisely why the event has that property; this is not limited to SCSt; it applies to any application that fires up child contexts.

[rainerfrey]

Thanks for the hint on how to check the application context, that'll do for fixing my application.

But isn't it a violation of the principle of least surprise, that a dependency like Spring Cloud Stream turns a simple application into a hierarchy of SpringApplication contexts? I wouldn't have wondered all that much about generic application context events like ContextRefreshed, as using multiple application contexts is quite common (although it would be nice if it were documented when a framework does that).

However, the Javadoc of SpringApplication says:

Class that can be used to bootstrap and launch a Spring application from a Java main method.

So as an application developer, when I define a simple application, I would not expect a framework to silently add its own child instances of what seems to represent a whole application instead of a nestable spring application context only. So if I'm not familiar with the internals of SCSt, I have little chance to realise that I run a hierarchy of SpringApplications that each fire application lifecycle events (in contrast to general context events).

[rainerfrey]

I wonder if it would make sense that SpringApplication has a mode that doesn't fire these events (similar to how startup logging can be suppressed) for such use cases as SCSt's.

[rainerfrey]

This has the same underlying reason as #1795: SpringApplication with its lifecycle, logging and event features is used to create the binder child contexts.

As someone who has not worked on Spring projects directly, it seems to me that SpringApplication isn't conceptually intended to be used like that, as its intent seems to be to represent an entire application (i.e. Java program), and has side effects that reflect that.

While both issues aren't very critical and can be worked around, maybe there would be merit to evaluate whether it is possible to split SpringApplication in a reusable, multi-instance "context bootstrap" part and a single instance "lifecycle/event/logging" part.

[Vadus]

Hi, I just tumbled into such side-effects from spinning up another ApplicationContext. In my case, I have a SpringApplication with a single Spring Cloud Stream Rabbit Binding and Actuator (Micrometer) Log-Metrics enabled. At startup Micrometer adjusts the Logback LoggerContext to meter any log events.

But the newly started ApplicationContext for the Spring Cloud Stream Bindings sends ApplicationEvents, that will reset the Logback LoggerContext again leaving it without any Metrics adjustments.

In this case I can not prevent anything in my application code. In the end I have to hack something internally into the Spring Micrometer or Logback part.

Finally I ask myself, why do you need to spin up another Spring Application Context at DefaultBinderFactory. This is even marked with This is the fall back to the old bootstrap that relies on spring.binders. in the Code

See also https://stackoverflow.com/questions/54332239/cannot-retrieve-binder-configuration-in-spring-cloud-stream-2-1-0

[Vadus]

To my problem, that the child application context resets the LoggerContext, I have a workaround

/**
 * Have to rebind {@link LogbackMetrics} to {@link io.micrometer.core.instrument.MeterRegistry}
 * after ServletWebServer was initialized
 * because spring cloud stream rabbit binding overrides the LoggerContext during start up
 * see issue https://github.com/spring-cloud/spring-cloud-stream/issues/1848
 */
@Configuration
@ConditionalOnExpression(
        "${management.metrics.enable.logback:true} && '${spring.cloud.stream.binders.rabbit.type}'=='rabbit'"
)
public class MetricsConfiguration {

    @Bean
    public LogbackMetricsApplicationListener myApplicationListener(LogbackMetrics logbackMetrics,
                                                                   PrometheusMeterRegistry meterRegistry){
        return new LogbackMetricsApplicationListener(logbackMetrics, meterRegistry);
    }

    public static class LogbackMetricsApplicationListener implements ApplicationListener<ApplicationEvent>, Ordered {

        private static final Logger log = LoggerFactory.getLogger(LogbackMetricsApplicationListener.class);

        private final LogbackMetrics logbackMetrics;
        private final PrometheusMeterRegistry meterRegistry;

        public LogbackMetricsApplicationListener(LogbackMetrics logbackMetrics, PrometheusMeterRegistry meterRegistry) {
            this.logbackMetrics = logbackMetrics;
            this.meterRegistry = meterRegistry;
        }

        @Override
        public void onApplicationEvent(ApplicationEvent event) {
            if(event instanceof ServletWebServerInitializedEvent){
                log.debug("Binding logbackMetrics to PrometheusMeterRegistry");
                logbackMetrics.bindTo(meterRegistry);
            }
        }

        @Override
        public int getOrder() {
            return Ordered.LOWEST_PRECEDENCE;
        }
    }
}

[spencergibb]

This also causes EnvironmentPostProcessor classes to be run twice. In particular, the ConfigDataEnvironmentPostProcessor from boot, which causes Spring Cloud config data implementations to fetch remote content multiple times.

[spencergibb]

https://github.com/spring-cloud/spring-cloud-config/blob/ef35a43deb54f749108a59e6721a2c5db263081c/spring-cloud-config-server/src/main/java/org/springframework/cloud/config/server/environment/NativeEnvironmentRepository.java#L131-L134

Something like this could be used for the configuration parts.

        ConfigurableEnvironment environment = getEnvironment(config, profile, label);
        DefaultResourceLoader resourceLoader = new DefaultResourceLoader();
        ConfigDataEnvironmentPostProcessor.applyTo(environment, resourceLoader, null,
                StringUtils.commaDelimitedListToStringArray(profile));

And a normal ApplicationContext could be used as well.

[OldOldLiu]

So how to solve this problem?

[olegz]

This issue probably needs to be closed as we no longer create SpringApplication for child binders starting s-c-stream v.3.1.x. Can someone please confirm?

[OldOldLiu]

I didn't import s-c-stream directly. The latest version of spring-cloud-stream-starters is 3.0.13.RELEASE. Do you have any plans to upgrade spring-cloud-stream-starters?

[olegz]

The latest version is actually 3.1.4 which is part if spring-cloud 2020.0.4 BOM dependency

[OldOldLiu]

Thank you very much