Comment From: wilkinsona
Looking at the data on ge.spring.io, things got dramatically slower on 18 October:
Comment From: wilkinsona
Some tests are taking a little over 30 seconds. An exception's thrown during stop processing which means it never completes. As a result, Framework ends up waiting until the 30 second timeout pops before continuing. Those exceptions are:
Caused by: java.lang.NullPointerException: Cannot invoke "java.lang.reflect.Field.getModifiers()" because "field" is null
at org.springframework.util.ReflectionUtils.makeAccessible(ReflectionUtils.java:801)
at org.springframework.pulsar.reactive.core.DefaultReactivePulsarSenderFactory.reflectivelyClearCache(DefaultReactivePulsarSenderFactory.java:201)
at org.springframework.pulsar.reactive.core.DefaultReactivePulsarSenderFactory.doStop(DefaultReactivePulsarSenderFactory.java:176)
... 142 common frames omitted
Caused by: java.lang.NullPointerException: Cannot invoke "java.lang.reflect.Field.getModifiers()" because "field" is null
at org.springframework.util.ReflectionUtils.makeAccessible(ReflectionUtils.java:801)
at org.springframework.pulsar.reactive.core.DefaultReactivePulsarSenderFactory.reflectivelyClearCache(DefaultReactivePulsarSenderFactory.java:194)
at org.springframework.pulsar.reactive.core.DefaultReactivePulsarSenderFactory.doStop(DefaultReactivePulsarSenderFactory.java:176)
... 142 common frames omitted
Caused by: java.lang.NullPointerException: Cannot invoke "Object.getClass()" because "this.reactiveMessageSenderCache" is null
at org.springframework.pulsar.reactive.core.DefaultReactivePulsarSenderFactory.reflectivelyClearCache(DefaultReactivePulsarSenderFactory.java:193)
at org.springframework.pulsar.reactive.core.DefaultReactivePulsarSenderFactory.doStop(DefaultReactivePulsarSenderFactory.java:176)
... 101 common frames omitted
Caused by: java.lang.NullPointerException: Cannot invoke "java.lang.reflect.Field.getModifiers()" because "field" is null
at org.springframework.util.ReflectionUtils.makeAccessible(ReflectionUtils.java:801)
at org.springframework.pulsar.reactive.core.DefaultReactivePulsarSenderFactory.reflectivelyClearCache(DefaultReactivePulsarSenderFactory.java:201)
at org.springframework.pulsar.reactive.core.DefaultReactivePulsarSenderFactory.doStop(DefaultReactivePulsarSenderFactory.java:176)
... 101 common frames omitted
Caused by: java.lang.NullPointerException: Cannot invoke "java.lang.reflect.Field.getModifiers()" because "field" is null
at org.springframework.util.ReflectionUtils.makeAccessible(ReflectionUtils.java:801)
at org.springframework.pulsar.reactive.core.DefaultReactivePulsarSenderFactory.reflectivelyClearCache(DefaultReactivePulsarSenderFactory.java:194)
at org.springframework.pulsar.reactive.core.DefaultReactivePulsarSenderFactory.doStop(DefaultReactivePulsarSenderFactory.java:176)
... 101 common frames omitted
Comment From: wilkinsona
@onobc, I think it's the tests' use of mocks, in whenHasUserDefinedBeanDoesNotAutoConfigureBean for example, that's causing the problem. However, I wonder if the Spring Pulsar code should be more robust here.
The first exception occurs with a mock ProducerCacheProvider. This is an interface but DefaultReactivePulsarSenderFactory.reflectivelyClearCache is assuming that it's only ever going to be an instance of CaffeineShadedProducerCacheProvider. There are other similar assumptions on other lines in reflectivelyClearCache that I think explain each of the 5 exceptions above.
Comment From: onobc
@wilkinsona reflectivelyClearCache was a temporary stop-gap measure to allow clearing of the reactive cache (to support CRaC) until that API was available on the Reactive cache. Rather than muck around w/ this workaround I will add the API to the Reactive client.
- I will pull this out of the current codebase here shortly so that the performance issue is gone.
- I will add the API on the Reactive client.
- Once available I will plug back in this ability (the proper way w/o the reflective code)
The Reactive client needs to update to the latest Reactor version before we GA so this timing works out well.
Comment From: onobc
@wilkinsona I ended up making the current impl more robust and will ultimately remove it once the Reactive client supports a clear API on its cache.
It is in spring-pulsar-reactive:1.0.0-SNAPSHOT and I have verified locally the test runs through under 1s and no more exceptions are being thrown.
Comment From: wilkinsona
Great stuff. Thanks, Chris. I'll close this one then. We'll move to snapshots in a week or so and pick up your changes.
Comment From: mhalbritter
The test whenCachingDisabledDoesNotEnableCaching still takes 30 seconds to run. It outputs this to the log:
2023-12-13T09:10:09.554+01:00 WARN --- [ main] o.s.c.support.DefaultLifecycleProcessor : Failed to stop bean 'reactivePulsarSenderFactory'
java.lang.RuntimeException: java.lang.NullPointerException: Cannot invoke "org.apache.pulsar.reactive.client.api.ReactiveMessageSenderCache.close()" because "this.reactiveMessageSenderCache" is null
at org.springframework.pulsar.reactive.core.DefaultReactivePulsarSenderFactory.doStop(DefaultReactivePulsarSenderFactory.java:179)
at org.springframework.pulsar.reactive.core.RestartableComponentSupport.stop(RestartableComponentSupport.java:114)
at org.springframework.context.SmartLifecycle.stop(SmartLifecycle.java:117)
at org.springframework.context.support.DefaultLifecycleProcessor.doStop(DefaultLifecycleProcessor.java:344)
at org.springframework.context.support.DefaultLifecycleProcessor$LifecycleGroup.stop(DefaultLifecycleProcessor.java:483)
at java.base/java.lang.Iterable.forEach(Iterable.java:75)
at org.springframework.context.support.DefaultLifecycleProcessor.stopBeans(DefaultLifecycleProcessor.java:313)
at org.springframework.context.support.DefaultLifecycleProcessor.onClose(DefaultLifecycleProcessor.java:214)
at org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:1078)
at org.springframework.context.support.AbstractApplicationContext.close(AbstractApplicationContext.java:1037)
at org.springframework.boot.test.context.assertj.AssertProviderApplicationContextInvocationHandler.invokeClose(AssertProviderApplicationContextInvocationHandler.java:140)
at org.springframework.boot.test.context.assertj.AssertProviderApplicationContextInvocationHandler.invoke(AssertProviderApplicationContextInvocationHandler.java:83)
at jdk.proxy2/jdk.proxy2.$Proxy93.close(Unknown Source)
at org.springframework.boot.test.context.runner.AbstractApplicationContextRunner.consumeAssertableContext(AbstractApplicationContextRunner.java:364)
at org.springframework.boot.test.context.runner.AbstractApplicationContextRunner.lambda$run$0(AbstractApplicationContextRunner.java:341)
at org.springframework.boot.test.util.TestPropertyValues.lambda$applyToSystemProperties$1(TestPropertyValues.java:174)
at org.springframework.boot.test.util.TestPropertyValues.applyToSystemProperties(TestPropertyValues.java:188)
at org.springframework.boot.test.util.TestPropertyValues.applyToSystemProperties(TestPropertyValues.java:173)
at org.springframework.boot.test.context.runner.AbstractApplicationContextRunner.lambda$run$1(AbstractApplicationContextRunner.java:341)
at org.springframework.boot.test.context.runner.AbstractApplicationContextRunner.withContextClassLoader(AbstractApplicationContextRunner.java:369)
at org.springframework.boot.test.context.runner.AbstractApplicationContextRunner.run(AbstractApplicationContextRunner.java:340)
at org.springframework.boot.autoconfigure.pulsar.PulsarReactiveAutoConfigurationTests$SenderCacheAutoConfigurationTests.whenCachingDisabledDoesNotEnableCaching(PulsarReactiveAutoConfigurationTests.java:429)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:568)
at org.junit.platform.commons.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:728)
at org.junit.jupiter.engine.execution.MethodInvocation.proceed(MethodInvocation.java:60)
at org.junit.jupiter.engine.execution.InvocationInterceptorChain$ValidatingInvocation.proceed(InvocationInterceptorChain.java:131)
at org.junit.jupiter.engine.extension.TimeoutExtension.intercept(TimeoutExtension.java:156)
at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestableMethod(TimeoutExtension.java:147)
at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestMethod(TimeoutExtension.java:86)
at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker$ReflectiveInterceptorCall.lambda$ofVoidMethod$0(InterceptingExecutableInvoker.java:103)
at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.lambda$invoke$0(InterceptingExecutableInvoker.java:93)
at org.junit.jupiter.engine.execution.InvocationInterceptorChain$InterceptedInvocation.proceed(InvocationInterceptorChain.java:106)
at org.junit.jupiter.engine.execution.InvocationInterceptorChain.proceed(InvocationInterceptorChain.java:64)
at org.junit.jupiter.engine.execution.InvocationInterceptorChain.chainAndInvoke(InvocationInterceptorChain.java:45)
at org.junit.jupiter.engine.execution.InvocationInterceptorChain.invoke(InvocationInterceptorChain.java:37)
at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.invoke(InterceptingExecutableInvoker.java:92)
at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.invoke(InterceptingExecutableInvoker.java:86)
at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.lambda$invokeTestMethod$7(TestMethodTestDescriptor.java:218)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.invokeTestMethod(TestMethodTestDescriptor.java:214)
at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:139)
at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:69)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:151)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141)
at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95)
at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:41)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:155)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141)
at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95)
at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:41)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:155)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141)
at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95)
at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:41)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:155)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141)
at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95)
at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.submit(SameThreadHierarchicalTestExecutorService.java:35)
at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor.execute(HierarchicalTestExecutor.java:57)
at org.junit.platform.engine.support.hierarchical.HierarchicalTestEngine.execute(HierarchicalTestEngine.java:54)
at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:198)
at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:169)
at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:93)
at org.junit.platform.launcher.core.EngineExecutionOrchestrator.lambda$execute$0(EngineExecutionOrchestrator.java:58)
at org.junit.platform.launcher.core.EngineExecutionOrchestrator.withInterceptedStreams(EngineExecutionOrchestrator.java:141)
at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:57)
at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:103)
at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:85)
at org.junit.platform.launcher.core.DelegatingLauncher.execute(DelegatingLauncher.java:47)
at org.junit.platform.launcher.core.SessionPerRequestLauncher.execute(SessionPerRequestLauncher.java:63)
at com.intellij.junit5.JUnit5IdeaTestRunner.startRunnerWithArgs(JUnit5IdeaTestRunner.java:57)
at com.intellij.rt.junit.IdeaTestRunner$Repeater$1.execute(IdeaTestRunner.java:38)
at com.intellij.rt.execution.junit.TestsRepeater.repeat(TestsRepeater.java:11)
at com.intellij.rt.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:35)
at com.intellij.rt.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:232)
at com.intellij.rt.junit.JUnitStarter.main(JUnitStarter.java:55)
Caused by: java.lang.NullPointerException: Cannot invoke "org.apache.pulsar.reactive.client.api.ReactiveMessageSenderCache.close()" because "this.reactiveMessageSenderCache" is null
at org.springframework.pulsar.reactive.core.DefaultReactivePulsarSenderFactory.doStop(DefaultReactivePulsarSenderFactory.java:175)
... 101 common frames omitted
2023-12-13T09:10:39.566+01:00 INFO --- [ main] o.s.c.support.DefaultLifecycleProcessor : Failed to shut down 1 bean with phase value -1073741924 within timeout of 30000ms: [reactivePulsarSenderFactory]
Looks like there is missing a null check?
Comment From: onobc
Thanks for the update @mhalbritter . I will get this addressed today.
Comment From: mhalbritter
Thank you!