Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

spring boot 3.4.3 + TimedAspect causes thread to hang #34522

Closed
180254 opened this issue Feb 28, 2025 · 6 comments
Closed

spring boot 3.4.3 + TimedAspect causes thread to hang #34522

180254 opened this issue Feb 28, 2025 · 6 comments
Assignees
Labels
in: core Issues in core modules (aop, beans, core, context, expression) type: regression A bug that is also a regression
Milestone

Comments

@180254
Copy link

180254 commented Feb 28, 2025

I have an application that stopped working correctly after updating to 3.4.3.
I have prepared a minimal app that reproduces the issue.

package com.example.demo;

import io.micrometer.core.annotation.Timed;
import io.micrometer.core.aop.TimedAspect;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.context.annotation.Bean;
import org.springframework.stereotype.Service;

@SpringBootApplication
public class DemoApplication {

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

  @Bean
  public TimedAspect timedAspect() {
    return new TimedAspect();
  }

  @Service
  public static class DemoService {
    public DemoService(DemoFactory demoFactory) {
      Thread initThread = new Thread(demoFactory::initSomething);
      initThread.setName("DemoService-initThread");
      initThread.start();
    }
  }

  @Service
  public static class DemoFactory {
    @Timed(value = "init_timed")
    void initSomething() {
      System.out.println("INIT SOMETHING");
    }
  }
}
    <dependency>
      <groupId>org.springframework.boot</groupId>
      <artifactId>spring-boot-starter</artifactId>
    </dependency>
    <dependency>
      <groupId>org.springframework.boot</groupId>
      <artifactId>spring-boot-starter-actuator</artifactId>
    </dependency>
    <dependency>
      <groupId>org.springframework.boot</groupId>
      <artifactId>spring-boot-starter-aop</artifactId>
    </dependency>

Output when running the application on 3.4.2:

 :: Spring Boot ::                (v3.4.2)

2025-02-28T22:08:46.129+01:00  INFO 53499 --- [           main] com.example.demo.DemoApplication         : Starting DemoApplication using Java 21.0.6 with PID 53499 (/somepath/spring-boot-issue-0/target/classes started by pedziwia in /somepath/spring-boot-issue-0)
2025-02-28T22:08:46.132+01:00  INFO 53499 --- [           main] com.example.demo.DemoApplication         : No active profile set, falling back to 1 default profile: "default"
2025-02-28T22:08:46.700+01:00  INFO 53499 --- [vice-initThread] o.s.b.f.s.DefaultListableBeanFactory     : Creating singleton bean 'timedAspect' in thread "DemoService-initThread" while other thread holds singleton lock for other beans [timedAspect]
2025-02-28T22:08:46.715+01:00  INFO 53499 --- [           main] o.s.b.f.s.DefaultListableBeanFactory     : Creating singleton bean 'org.springframework.boot.actuate.autoconfigure.availability.AvailabilityHealthContributorAutoConfiguration' in thread "main" while other thread holds singleton lock for other beans []
INIT SOMETHING
2025-02-28T22:08:47.192+01:00  INFO 53499 --- [           main] com.example.demo.DemoApplication         : Started DemoApplication in 1.287 seconds (process running for 1.728)
Disconnected from the target VM, address: '127.0.0.1:58305', transport: 'socket'

Process finished with exit code 0

Output when running the application on 3.4.3:

 :: Spring Boot ::                (v3.4.3)

2025-02-28T22:09:46.824+01:00  INFO 53949 --- [           main] com.example.demo.DemoApplication         : Starting DemoApplication using Java 21.0.6 with PID 53949 (/somepath/spring-boot-issue-0/target/classes started by pedziwia in /somepath/spring-boot-issue-0)
2025-02-28T22:09:46.827+01:00  INFO 53949 --- [           main] com.example.demo.DemoApplication         : No active profile set, falling back to 1 default profile: "default"
2025-02-28T22:09:47.379+01:00  INFO 53949 --- [vice-initThread] o.s.b.f.s.DefaultListableBeanFactory     : Creating singleton bean 'timedAspect' in thread "DemoService-initThread" while other thread holds singleton lock for other beans [timedAspect]
2025-02-28T22:09:47.857+01:00  INFO 53949 --- [           main] com.example.demo.DemoApplication         : Started DemoApplication in 1.251 seconds (process running for 1.698)

The process does not terminate, it hangs forever and "INIT SOMETHING" is never printed.

I compared the classpath and found that downgrading the versions of two dependencies:

<dependency>
  <groupId>org.springframework.boot</groupId>
  <artifactId>spring-boot-actuator-autoconfigure</artifactId>
  <version>3.4.2</version>
</dependency>
<dependency>
  <groupId>org.springframework</groupId>
  <artifactId>spring-beans</artifactId>
  <version>6.2.2</version>
</dependency>

allows the program to start and work correctly again.

I have prepared a repository with a minimal app in Docker that reproduces this issue.
https://github.com/180254/spring-boot-issue-44498

@spring-projects-issues spring-projects-issues added the status: waiting-for-triage An issue we've not yet triaged or decided on label Feb 28, 2025
@180254 180254 changed the title spring boot 3.4.3 messes something up with threads spring boot 3.4.3 + TimedAspect causes thread to hang Feb 28, 2025
@nosan
Copy link
Contributor

nosan commented Mar 1, 2025

Thank you for sharing the sample, @180254.

After reviewing your issue, I can confirm that it indeed stopped working in 3.4.3. While debugging, I discovered
that the logic within the DefaultSingletonBeanRegistry class has been modified. You can
check #34349 for more details, as it’s likely related to your
issue.

"DemoService-initThread" spring-projects/spring-boot#52 [37635] prio=5 os_prio=31 cpu=1.56ms elapsed=2.87s tid=0x0000000138981600 nid=37635 waiting on condition  [0x000000017a4d1000]
   java.lang.Thread.State: WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@21.0.5/Native Method)
	- parking to wait for  <0x0000000500805508> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(java.base@21.0.5/LockSupport.java:371)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionNode.block(java.base@21.0.5/AbstractQueuedSynchronizer.java:519)
	at java.util.concurrent.ForkJoinPool.unmanagedBlock(java.base@21.0.5/ForkJoinPool.java:3780)
	at java.util.concurrent.ForkJoinPool.managedBlock(java.base@21.0.5/ForkJoinPool.java:3725)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@21.0.5/AbstractQueuedSynchronizer.java:1712)
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:313)
	at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:337)
	at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:202)
	at org.springframework.aop.aspectj.annotation.BeanFactoryAspectInstanceFactory.getAspectInstance(BeanFactoryAspectInstanceFactory.java:90)
	at org.springframework.aop.aspectj.annotation.LazySingletonAspectInstanceFactoryDecorator.getAspectInstance(LazySingletonAspectInstanceFactoryDecorator.java:56)
	at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:642)
	at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:632)
	at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:71)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184)
	at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184)
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:727)
	at com.example.demo.DemoApplication$DemoFactory$$SpringCGLIB$$0.initSomething(<generated>)
	at com.example.demo.DemoApplication$DemoService$$Lambda/0x000000d801306278.run(Unknown Source)
	at java.lang.Thread.runWith(java.base@21.0.5/Thread.java:1596)
	at java.lang.Thread.run(java.base@21.0.5/Thread.java:1583)

@180254
Copy link
Author

180254 commented Mar 1, 2025

Thanks

Here are some new observations:

Adding a thread that keeps the application running fixes the DemoService in the sample application. However, this is not the case in general; my production application, where I encountered the issue, is a web application. I am unable to find a minimal web application that reproduces the issue.

  @Service
  public static class KeepAppWorking {
    public KeepAppWorking() {
      try {
        System.out.println("KeepAppWorking");
        CountDownLatch latch = new CountDownLatch(1);
        latch.await();
      } catch (InterruptedException e) {
        e.printStackTrace();
      }
    }
  }

or

    <dependency>
      <groupId>org.springframework.boot</groupId>
      <artifactId>spring-boot-starter-web</artifactId>
    </dependency>

--

The spring-beans in the current snapshot version do not help; the sample app still doesn't work.

    <dependency>
      <groupId>org.springframework</groupId>
      <artifactId>spring-beans</artifactId>
      <version>6.2.4-20250301.124437-29</version>
    </dependency>

--

Explicitly adding a dependency on TimedAspect makes the sample app work. Preliminary tests indicate that my production application also starts working after applying such a change.

    public DemoFactory(TimedAspect timedAspect) {}

--

You are right, the change in DefaultSingletonBeanRegistry is causing the issue. Reverting org.springframework.beans.factory.support.DefaultSingletonBeanRegistry class to version 6.2.2 makes the sample app work. Preliminary tests indicate that my production application also starts working after applying such a change.

@bclozel bclozel transferred this issue from spring-projects/spring-boot Mar 1, 2025
@bclozel bclozel added the in: core Issues in core modules (aop, beans, core, context, expression) label Mar 1, 2025
@jhoeller jhoeller self-assigned this Mar 1, 2025
@jhoeller jhoeller added type: regression A bug that is also a regression and removed status: waiting-for-triage An issue we've not yet triaged or decided on labels Mar 1, 2025
@jhoeller jhoeller added this to the 6.2.4 milestone Mar 1, 2025
@jhoeller
Copy link
Contributor

jhoeller commented Mar 1, 2025

The specific problem here seems to be the attempt to concurrently initialize the timedAspect bean in two threads of which one holds the singleton lock for it while the other considers it for lenient creation at the same time, with the lock/await logic not taking that kind of conflict into account yet (since there is never a corresponding lenient-creation signal for the await in such a scenario, just a release of the singleton lock). I'll revise this ASAP, hoping that it actually fixes your scenario, giving you a new 6.2.4 snapshot to test.

@jhoeller
Copy link
Contributor

jhoeller commented Mar 2, 2025

@180254 the latest 6.2.4 snapshot contains that revision now. Please give it another try!

As for an explicit dependency on the timedAspect bean making it work, that's because it forces early initialization of that bean in the main bootstrap thread. That's generally recommended - however, for testing the latest 6.2.4 fix, please re-run your original code with on-demand initialization of the aspect in your custom thread.

@180254
Copy link
Author

180254 commented Mar 3, 2025

I am pleased to say that the new spring-beans prerelease version makes both the sample demo app and my main application work.

<parent>
  <groupId>org.springframework.boot</groupId>
  <artifactId>spring-boot-starter-parent</artifactId>
  <version>3.4.3</version>
  <relativePath/>
</parent>
 <dependency>
      <groupId>org.springframework</groupId>
      <artifactId>spring-beans</artifactId>
      <version>6.2.4-20250301.213415-30</version>
</dependency>

Thanks for addressing the problem promptly.

@jhoeller
Copy link
Contributor

jhoeller commented Mar 3, 2025

Good to hear! Thanks for the immediate feedback.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
in: core Issues in core modules (aop, beans, core, context, expression) type: regression A bug that is also a regression
Projects
None yet
Development

No branches or pull requests

5 participants