search

spring-cloud / spring-cloud-stream

Framework for building Event-Driven Microservices
http://cloud.spring.io/spring-cloud-stream
Apache License 2.0
1.01k stars 614 forks source link

Bean circular reference causing a stop loop at application shutdown. #2899

Closed mborgraeve closed 9 months ago

mborgraeve commented 9 months ago

Hi,

We are experiencing an issue with our apps using the spring cloud stream framework.

Describe the issue The symptom is a stacktrace for a StackOverFlow exception, caused by some kind of circular reference in the beans generated by Spring Cloud Stream, and triggerred at application shutdown. The beans are being stopped, but loop between one another.

How to reproduce It can be reproduced with this minimal project, either: 1) Running the integration test (note: the test seems to pass, the exception occur after, at shutdown - check the full logs)

or

1) Start the Springboot application 2) Stop it

The same is reproduced from my IDE (IntelliJ -> run the app or the test), and maven (mvn test).

Version of the framework As in the pom:

Expected behavior We wouldn't expect a stackoverflow exception, with no related logs.

More context

Here is the beginning of the stack trace:

2024-02-13T08:45:08.517-05:00  WARN 58769 --- [ionShutdownHook] o.s.c.support.DefaultLifecycleProcessor  : Failed to stop bean 'kafka-local_binderProducingContext'

java.lang.StackOverflowError: null
    at java.base/java.lang.invoke.DelegatingMethodHandle.makeReinvokerForm(DelegatingMethodHandle.java:130) ~[na:na]
    at java.base/java.lang.invoke.DelegatingMethodHandle.makeReinvokerForm(DelegatingMethodHandle.java:120) ~[na:na]
    at java.base/java.lang.invoke.DelegatingMethodHandle.chooseDelegatingForm(DelegatingMethodHandle.java:112) ~[na:na]
    at java.base/java.lang.invoke.DelegatingMethodHandle.<init>(DelegatingMethodHandle.java:50) ~[na:na]
    at java.base/java.lang.invoke.MethodHandleImpl$AsVarargsCollector.<init>(MethodHandleImpl.java:459) ~[na:na]
    at java.base/java.lang.invoke.MethodHandleImpl$AsVarargsCollector.<init>(MethodHandleImpl.java:456) ~[na:na]
    at java.base/java.lang.invoke.MethodHandleImpl.makeVarargsCollector(MethodHandleImpl.java:447) ~[na:na]
    at java.base/java.lang.invoke.MethodHandle.asVarargsCollector(MethodHandle.java:1516) ~[na:na]
    at java.base/java.lang.invoke.MethodHandle.withVarargs(MethodHandle.java:1201) ~[na:na]
    at java.base/java.lang.invoke.MethodHandle.setVarargs(MethodHandle.java:1720) ~[na:na]
    at java.base/java.lang.invoke.MethodHandles$Lookup.getDirectMethodCommon(MethodHandles.java:4122) ~[na:na]
    at java.base/java.lang.invoke.MethodHandles$Lookup.getDirectMethodNoSecurityManager(MethodHandles.java:4065) ~[na:na]
    at java.base/java.lang.invoke.MethodHandles$Lookup.getDirectMethodForConstant(MethodHandles.java:4314) ~[na:na]
    at java.base/java.lang.invoke.MethodHandles$Lookup.linkMethodHandleConstant(MethodHandles.java:4262) ~[na:na]
    at java.base/java.lang.invoke.MethodHandleNatives.linkMethodHandleConstant(MethodHandleNatives.java:627) ~[na:na]
    at ch.qos.logback.classic.spi.StackTraceElementProxy.getSTEAsString(StackTraceElementProxy.java:39) ~[logback-classic-1.4.14.jar:1.4.14]
    at ch.qos.logback.classic.spi.StackTraceElementProxy.toString(StackTraceElementProxy.java:89) ~[logback-classic-1.4.14.jar:1.4.14]
    at ch.qos.logback.classic.pattern.ThrowableProxyConverter.subjoinSTEPArray(ThrowableProxyConverter.java:206) ~[logback-classic-1.4.14.jar:1.4.14]
    at ch.qos.logback.classic.pattern.ThrowableProxyConverter.recursiveAppend(ThrowableProxyConverter.java:164) ~[logback-classic-1.4.14.jar:1.4.14]
    at ch.qos.logback.classic.pattern.ThrowableProxyConverter.throwableProxyToString(ThrowableProxyConverter.java:154) ~[logback-classic-1.4.14.jar:1.4.14]
    at org.springframework.boot.logging.logback.ExtendedWhitespaceThrowableProxyConverter.throwableProxyToString(ExtendedWhitespaceThrowableProxyConverter.java:34) ~[spring-boot-3.2.2.jar:3.2.2]
    at ch.qos.logback.classic.pattern.ThrowableProxyConverter.convert(ThrowableProxyConverter.java:148) ~[logback-classic-1.4.14.jar:1.4.14]
    at ch.qos.logback.classic.pattern.ThrowableProxyConverter.convert(ThrowableProxyConverter.java:35) ~[logback-classic-1.4.14.jar:1.4.14]
    at ch.qos.logback.core.pattern.FormattingConverter.write(FormattingConverter.java:36) ~[logback-core-1.4.14.jar:1.4.14]
    at ch.qos.logback.core.pattern.PatternLayoutBase.writeLoopOnConverters(PatternLayoutBase.java:116) ~[logback-core-1.4.14.jar:1.4.14]
    at ch.qos.logback.classic.PatternLayout.doLayout(PatternLayout.java:176) ~[logback-classic-1.4.14.jar:1.4.14]
    at ch.qos.logback.classic.PatternLayout.doLayout(PatternLayout.java:39) ~[logback-classic-1.4.14.jar:1.4.14]
    at ch.qos.logback.core.encoder.LayoutWrappingEncoder.encode(LayoutWrappingEncoder.java:114) ~[logback-core-1.4.14.jar:1.4.14]
    at ch.qos.logback.core.OutputStreamAppender.writeOut(OutputStreamAppender.java:192) ~[logback-core-1.4.14.jar:1.4.14]
    at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:237) ~[logback-core-1.4.14.jar:1.4.14]
    at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:102) ~[logback-core-1.4.14.jar:1.4.14]
    at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:85) ~[logback-core-1.4.14.jar:1.4.14]
    at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51) ~[logback-core-1.4.14.jar:1.4.14]
    at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:272) ~[logback-classic-1.4.14.jar:1.4.14]
    at ch.qos.logback.classic.Logger.callAppenders(Logger.java:259) ~[logback-classic-1.4.14.jar:1.4.14]
    at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:426) ~[logback-classic-1.4.14.jar:1.4.14]
    at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:386) ~[logback-classic-1.4.14.jar:1.4.14]
    at ch.qos.logback.classic.Logger.log(Logger.java:780) ~[logback-classic-1.4.14.jar:1.4.14]
    at org.apache.commons.logging.LogAdapter$Slf4jLocationAwareLog.warn(LogAdapter.java:445) ~[spring-jcl-6.1.3.jar:6.1.3]
    at org.springframework.context.support.DefaultLifecycleProcessor.doStop(DefaultLifecycleProcessor.java:370) ~[spring-context-6.1.3.jar:6.1.3]
    at org.springframework.context.support.DefaultLifecycleProcessor$LifecycleGroup.stop(DefaultLifecycleProcessor.java:483) ~[spring-context-6.1.3.jar:6.1.3]
    at java.base/java.lang.Iterable.forEach(Iterable.java:75) ~[na:na]

The stack trace then repeats the following tens of times:

    at org.springframework.context.support.DefaultLifecycleProcessor.stopBeans(DefaultLifecycleProcessor.java:313) ~[spring-context-6.1.3.jar:6.1.3]
    at org.springframework.context.support.DefaultLifecycleProcessor.stop(DefaultLifecycleProcessor.java:186) ~[spring-context-6.1.3.jar:6.1.3]
    at org.springframework.context.support.AbstractApplicationContext.stop(AbstractApplicationContext.java:1523) ~[spring-context-6.1.3.jar:6.1.3]
    at org.springframework.context.support.DefaultLifecycleProcessor.doStop(DefaultLifecycleProcessor.java:357) ~[spring-context-6.1.3.jar:6.1.3]
    at org.springframework.context.support.DefaultLifecycleProcessor$LifecycleGroup.stop(DefaultLifecycleProcessor.java:483) ~[spring-context-6.1.3.jar:6.1.3]
    at java.base/java.lang.Iterable.forEach(Iterable.java:75) ~[na:na]

While debugging, I noticed the two beans "looping" one another are named outerContext and kafka-local_binderProducingContext (the name of my binder is kafka-local). I fail to understand why they are related to each other, or how they should be stopped.

Happy to provide more details or anything of course ! And feel free to redirect me if this repo isn't the proper place to raise this issue.

sobychacko commented 9 months ago

I see that you are using spring-cloud version 2023.0.0. This issue has been reported before and due to an unfortunate bug. See this issue for more details: https://github.com/spring-cloud/spring-cloud-stream/issues/2891

As mentioned, this is already fixed in the latest snapshot, and the next point release will have the fix.

See the release schedule: https://calendar.spring.io/ The next spring-cloud point release (2023.0.1) is scheduled for March 11th.

sobychacko commented 9 months ago

Closing the issue, please feel free to reopen if needed. Thanks!

mborgraeve commented 9 months ago

Didn't found it initially, thanks for the quick answer !

weikangchia commented 7 months ago

Hi, may I know if the version 2023.0.1 will be releasing soon?

sobychacko commented 7 months ago

@weikangchia Spring Cloud Stream 4.1.1. just got released and will be part of the 2023.0.1 spring-cloud release train which will be available later today.