Proxification of @Scheduled tasks using @Aspect in WebFlux seems broken after 3.2.0

[hypr2771]

Description

Spring @Scheduled + @Aspect proxification issue after 3.2.0 upgrade seems broken.

Indeed, if you:

• are proxifying @Scheduled method to add some logging and measurements
• are using fixedDelay
• are making your @Scheduled return a Publisher
• are letting the proxy run the Publisher.subscribe
  tasks are no more scheduled after the single run upon restart in 3.2.0, while they still were in 3.1.5.

Environment

$ java -version
openjdk version "17.0.1" 2021-10-19
OpenJDK Runtime Environment (build 17.0.1+12-39)
OpenJDK 64-Bit Server VM (build 17.0.1+12-39, mixed mode, sharing)

No specific environment variables.

Reproduce

Minimal reproducible exemple here: https://github.com/hypr2771/spring_3_2_0_proxification_scheduling_issue.

Set your parent to 3.1.5

When in 3.1.5, @Scheduled proxification works perfectly:

mvn versions:update-parent -DparentVersion="[3.1.5]"
mvn clean package
mvn exec:java -Dexec.mainClass="org.example.Main"

Should look like:

2023-12-05T12:45:32.143+07:00  INFO 5615 --- [ple.Main.main()] org.example.Main                         : Starting Main using Java 17.0.1 with PID 5615 (/Users/vincentcastelluci/Workspace/Perso/Java/Tuto/spring_3_2_0_scheduling_issue/target/classes started by vincentcastelluci in /Users/vincentcastelluci/Workspace/Perso/Java/Tuto/spring_3_2_0_scheduling_issue)
2023-12-05T12:45:32.144+07:00  INFO 5615 --- [ple.Main.main()] org.example.Main                         : No active profile set, falling back to 1 default profile: "default"
2023-12-05T12:45:32.664+07:00  INFO 5615 --- [ple.Main.main()] o.s.b.web.embedded.netty.NettyWebServer  : Netty started on port 8080
Running scheduled Mono org.example.Task.test()
Ended scheduled Mono org.example.Task.test() with result 1701755132673
2023-12-05T12:45:32.697+07:00  INFO 5615 --- [ple.Main.main()] org.example.Main                         : Started Main in 0.632 seconds (process running for 1.555)
Running scheduled Mono org.example.Task.test()
Ended scheduled Mono org.example.Task.test() with result 1701755133681
Running scheduled Mono org.example.Task.test()
Ended scheduled Mono org.example.Task.test() with result 1701755134685

Set your parent to 3.2.0

When in 3.2.0, @Scheduled proxification seems broken:

mvn versions:update-parent -DparentVersion="[3.2.0]"
mvn clean package
mvn exec:java -Dexec.mainClass="org.example.Main"

Should look like:

2023-12-05T12:48:15.475+07:00  INFO 5724 --- [ple.Main.main()] org.example.Main                         : Starting Main using Java 17.0.1 with PID 5724 (/Users/vincentcastelluci/Workspace/Perso/Java/Tuto/spring_3_2_0_scheduling_issue/target/classes started by vincentcastelluci in /Users/vincentcastelluci/Workspace/Perso/Java/Tuto/spring_3_2_0_scheduling_issue)
2023-12-05T12:48:15.476+07:00  INFO 5724 --- [ple.Main.main()] org.example.Main                         : No active profile set, falling back to 1 default profile: "default"
Running scheduled Mono org.example.Task.test()
Ended scheduled Mono org.example.Task.test() with result 1701755295851
2023-12-05T12:48:16.000+07:00  INFO 5724 --- [ple.Main.main()] o.s.b.web.embedded.netty.NettyWebServer  : Netty started on port 8080
2023-12-05T12:48:16.009+07:00  INFO 5724 --- [ple.Main.main()] org.example.Main                         : Started Main in 0.646 seconds (process running for 2.494)

You can note the task is being run once on boot, rescheduled but never actually subscribed it seems.

Idea

No real clue but since it keeps working if we run the .subscribe on the @Scheduled process, my guess is that the underlying subscriber, related to changes made for async improvements, is disposed before it gets actually subscribed when returned by the proxified method.

It might also be due to the observability added to @Scheduled which might be doing instrumentation or proxification of those method.

[bclozel]

I don't think we can call that a regression, since Publisher return types were not supported on @Scheduled annotated methods before #29924. The behavior is described in the reference documentation for Reactive support of @Scheduled methods: such methods are turned into Runnable that subscribe to the returned publisher.

In this context, I believe that the LoggingAspect contributed in the sample project is invalid. It should not subscribe to the publisher as it completely breaks the scheduling aspect of things: the processing is triggered as soon as the method is called, when it's actually expected to run when it is subscribed to. I think the aspect should instead use side-effect operators like doOnNext, doFinally or doOnTerminate like this:

  @Around("@annotation(org.springframework.scheduling.annotation.Scheduled)")
  public Object aroundScheduled(ProceedingJoinPoint proceedingJoinPoint) throws Throwable {
    // this is not true, as executing the method does not imply doing the actual work.
    // System.out.println("Running scheduled %s".formatted(proceedingJoinPoint.getSignature()));

    // this would fail if your application has other types of scheduled method, assuming this is for the sample only
    var mono = (Mono<String>) proceedingJoinPoint.proceed();

    return mono.doOnNext(result -> System.out.println("Ended scheduled %s with result %s".formatted(proceedingJoinPoint.getSignature(), result)));
  }

I'm closing this issue as a result. Thanks for this report!

[hypr2771]

Thanks for the explanation @bclozel.
Nonetheless, would you mind explaining why it used to work in 3.1.5? Is it because it was actually a "bug"/exploit?

[bclozel]

I think your aspect made things work in 3.1.5, because Publisher return types were not supported and the aspect was triggering their execution. Now that this feature is supported the aspect is conflicting with it.