DefaultLifecycleProcessor doesn't wait for a Phase to stop completely if its bean is dependent on other SmartLifeCycle bean

Spring 5.2.2.RELEASE

There are 2 SmartLifecycle beans: Phase888Service and Phase999Service.

Phase999Service is dependent on Phase888Service.

@Service
@Slf4j
public class Phase888Service implements SmartLifecycle {

    @Autowired
    private Phase999Service phase999Service;

    private volatile boolean isRunning;

    @Override
    public int getPhase() {
        return 888;
    }

    @Override
    public void start() {
        isRunning = true;
    }

    @Override
    public void stop() {
        throw new RuntimeException();
    }

    @Override
    public void stop(Runnable callback) {
        isRunning = false;

        log.info(">>>>> Now stop 888");

        new Thread(() -> {
            log.info(">>>>> Now stop 888");
            try {
                Thread.sleep(2000L);
            } catch(InterruptedException e) {
                throw new RuntimeException(e);
            }

            log.info(">>>>> 888 stopped.");
            callback.run();

        }, "Stop 888").start();
    }

    @Override
    public boolean isRunning() {
        return isRunning;
    }
}

@Service
@Slf4j
public class Phase999Service implements SmartLifecycle {

    private volatile boolean isRunning;

    @Override
    public int getPhase() {
        return 999;
    }

    @Override
    public void start() {
        isRunning = true;
    }

    @Override
    public void stop() {
        throw new RuntimeException();
    }

    @Override
    public void stop(Runnable callback) {
        isRunning = false;

        log.info(">>>>> Now stop 999");

        new Thread(() -> {
            log.info(">>>>> Now stop 999");
            try {
                Thread.sleep(4000L);
            } catch(InterruptedException e) {
                throw new RuntimeException(e);
            }

            log.info(">>>>> 999 stopped.");
            callback.run();

        }, "Stop 999").start();
    }

    @Override
    public boolean isRunning() {
        return isRunning;
    }
}

When I stop the application the log looks like this:

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::        (v2.2.2.RELEASE)

[INFO ] 2022-04-02 16:19:44.797 [            main] testing.Main : Starting Main on Marks-Smart-PC with PID 390888 (D:\workspace\testing\test-lifecycle-stop\build\classes\java\main started by Mark in D:\workspace\testing)
[INFO ] 2022-04-02 16:19:44.800 [            main] testing.Main : No active profile set, falling back to default profiles: default
[DEBUG] 2022-04-02 16:19:45.508 [            main] o.s.c.s.DefaultLifecycleProcessor : Starting beans in phase 888
[DEBUG] 2022-04-02 16:19:45.508 [            main] o.s.c.s.DefaultLifecycleProcessor : Successfully started bean 'phase999Service'
[DEBUG] 2022-04-02 16:19:45.508 [            main] o.s.c.s.DefaultLifecycleProcessor : Successfully started bean 'phase888Service'
[DEBUG] 2022-04-02 16:19:45.508 [            main] o.s.c.s.DefaultLifecycleProcessor : Starting beans in phase 999
[INFO ] 2022-04-02 16:19:45.514 [            main] testing.Main : Started Main in 0.961 seconds (JVM running for 1.673)
[DEBUG] 2022-04-02 16:19:48.530 [  Stop Stop Stop] o.s.c.s.DefaultLifecycleProcessor : Stopping beans in phase 999
[INFO ] 2022-04-02 16:19:48.531 [  Stop Stop Stop] testing.Phase888Service : >>>>> Now stop 888
[INFO ] 2022-04-02 16:19:48.531 [  Stop Stop Stop] testing.Phase999Service : >>>>> Now stop 999
[INFO ] 2022-04-02 16:19:48.531 [        Stop 888] testing.Phase888Service : >>>>> Now stop 888
[INFO ] 2022-04-02 16:19:48.532 [        Stop 999] testing.Phase999Service : >>>>> Now stop 999
[INFO ] 2022-04-02 16:19:50.540 [        Stop 888] testing.Phase888Service : >>>>> 888 stopped.
[DEBUG] 2022-04-02 16:19:50.540 [        Stop 888] o.s.c.s.DefaultLifecycleProcessor : Bean 'phase888Service' completed its stop procedure
[DEBUG] 2022-04-02 16:19:50.540 [  Stop Stop Stop] o.s.c.s.DefaultLifecycleProcessor : Stopping beans in phase 888
[INFO ] 2022-04-02 16:19:52.535 [        Stop 999] testing.Phase999Service : >>>>> 999 stopped.
[DEBUG] 2022-04-02 16:19:52.535 [        Stop 999] o.s.c.s.DefaultLifecycleProcessor : Bean 'phase999Service' completed its stop procedure

• Phase888Service stop takes 4 sec and Phase999Service takes 2 sec.
• Phase888Service begins to stop in phase 999 since it depends on Phase999Service.
• Phase 888 begins to stop before Phase999Service stopped.

When I dive into the DefaultLifecycleProcessor, I found that it just passes the countDownLatch to doStop() for stopping the dependentBeans, and the countDownLatch is counted down after the dependentBean stopped.

private void doStop(Map<String, ? extends Lifecycle> lifecycleBeans, final String beanName,
                    final CountDownLatch latch, final Set<String> countDownBeanNames) {

    Lifecycle bean = lifecycleBeans.remove(beanName);
    if (bean != null) {
        String[] dependentBeans = getBeanFactory().getDependentBeans(beanName);
        for (String dependentBean : dependentBeans) {
            doStop(lifecycleBeans, dependentBean, latch, countDownBeanNames);               // ‘latch’ is counted down after the dependentBean is stopped
        }
        try {
            if (bean.isRunning()) {
                if (bean instanceof SmartLifecycle) {
                    if (logger.isTraceEnabled()) {
                        logger.trace("Asking bean '" + beanName + "' of type [" +
                                bean.getClass().getName() + "] to stop");
                    }
                    countDownBeanNames.add(beanName);
                    ((SmartLifecycle) bean).stop(() -> {
                        latch.countDown();
                        countDownBeanNames.remove(beanName);
                        if (logger.isDebugEnabled()) {
                            logger.debug("Bean '" + beanName + "' completed its stop procedure");
                        }
                    });
                }
                else {
                    if (logger.isTraceEnabled()) {
                        logger.trace("Stopping bean '" + beanName + "' of type [" +
                                bean.getClass().getName() + "]");
                    }
                    bean.stop();
                    if (logger.isDebugEnabled()) {
                        logger.debug("Successfully stopped bean '" + beanName + "'");
                    }
                }
            }
            else if (bean instanceof SmartLifecycle) {
                // Don't wait for beans that aren't running...
                latch.countDown();
            }
        }
        catch (Throwable ex) {
            if (logger.isWarnEnabled()) {
                logger.warn("Failed to stop bean '" + beanName + "'", ex);
            }
        }
    }
}

Start in DefaultLifecycleProcessor#doStop, focusing on how dependent SmartLifecycle beans and the CountDownLatch are handled during shutdown. Reproduce the report with the two phase-888 and phase-999 beans, then verify that the dependent phase does not begin until the required stop callbacks have completed.