Search code examples
javaspringasynchronousspring-aop

Around Spring AOP on target method with void return type skips code execution


To my understanding, @Around annotation on Spring AOP can handle any return type on methods; with void type returning null.

This is a simple advice to log duration of a method:

@Target(ElementType.METHOD)
@Retention(RetentionPolicy.RUNTIME)
public @interface Profiling { }
@Aspect
@Component
public class ProfilingAspect {
    // ...

    @Around("@annotation(profilingAnnotation)")
    public Object logDuration(ProceedingJoinPoint joinPoint, Profiling profilingAnnotation) throws Throwable {
        long startTime = Instant.now().toEpochMilli();
        Object result = null;
        try {
            result = joinPoint.proceed(); // on void methods, this supposed to return null
        } catch (Throwable e) {
            logger.error(e.getMessage(), e);

            throw e;
        } finally {
            long endTime = Instant.now().toEpochMilli(); // Below is not ran all together

            long duration = endTime - startTime;
            logger.info(joinPoint.getSignature().toShortString()+": "+duration+"ms");
        }

        //return the result to the caller
        return result;
    }
}

However, when invoked on this method, it doesn't return anything and instead skips every code after proceed() altogether. Even finally block.

This is the problematic code:

@GetMapping("/members/exportpdf")
@Profiling
public void exportToPDF(@RequestParam(required = false)String role, HttpServletResponse response) throws DocumentException, IOException, ExecutionException, InterruptedException {
    CompletableFuture<List<GuildMember>> guildMembers;
    if (role==null) {
        guildMembers = guildService.findAll(); // Async Method
    } else {
        guildMembers = guildService.findByType(role); // Async Method
    }

    response.setContentType("application/pdf");
    DateFormat dateFormatter = new SimpleDateFormat("yyyy-MM-dd_HH:mm:ss");
    String currentDateTime = dateFormatter.format(new Date());
    String headerKey = "Content-Disposition";
    String headerValue = "inline; filename=guildmembers_" + currentDateTime + ".pdf";
    response.setHeader(headerKey, headerValue);

    PDFExporter exporter = new PDFExporter(guildMembers);
    exporter.export(response).get(); // exporter.export(..) is an Async method returning CompletableFuture<Void>
}

How is this possible? Am I missing something here on the configuration? Or is it a bug on Spring?

Note. I'm using Spring Boot 2.4.4 with starter dependencies

Edit. PDFExporter.export() uses OutputStream on HttpServletResponse to print application/pdf to the user and returns CompletableFuture<Void>. As to why, the method communicates with the async functions above, as such I want to guarantee the operation is finished somehow.


Solution

  • In order to teach you what an MCVE is and how to better ask questions here, I am going to show you the MCVE I created according to your code fragments and description:

    Dependency classes we need in order to make the code compile:

    package de.scrum_master.spring.q66958382;
    
    import java.lang.annotation.ElementType;
    import java.lang.annotation.Retention;
    import java.lang.annotation.RetentionPolicy;
    import java.lang.annotation.Target;
    
    @Target(ElementType.METHOD)
    @Retention(RetentionPolicy.RUNTIME)
    public @interface Profiling {}
    
    package de.scrum_master.spring.q66958382;
    
    public class GuildMember {
      private String name;
    
      public GuildMember(String name) {
        this.name = name;
      }
    
      @Override
      public String toString() {
        return "GuildMember{" +
          "name='" + name + '\'' +
          '}';
      }
    }
    

    PDFExporter utility:

    Maybe you are using the PDFExporter from PrimeFaces, but that is just a guess. In any case, it seems not to be a Spring component, because later you call the constructor instead of getting a bean instance from the application context. So I am modeling it here as a simple POJO too.

    package de.scrum_master.spring.q66958382;
    
    import org.springframework.scheduling.annotation.Async;
    
    import javax.servlet.http.HttpServletResponse;
    import java.util.List;
    import java.util.concurrent.CompletableFuture;
    
    public class PDFExporter {
      CompletableFuture<List<GuildMember>> guildMembers;
    
      public PDFExporter(CompletableFuture<List<GuildMember>> guildMembers) {
        this.guildMembers = guildMembers;
      }
    
      @Async
      public CompletableFuture<Void> export(HttpServletResponse response) {
        return CompletableFuture.supplyAsync(() -> {
          try { Thread.sleep(1000); } catch (InterruptedException e) { e.printStackTrace(); }
          return null;
        });
      }
    }
    

    Service with @Async methods:

    Next, I was making an educated guess about what your guild service might look like:

    package de.scrum_master.spring.q66958382;
    
    import org.springframework.scheduling.annotation.Async;
    import org.springframework.stereotype.Service;
    
    import java.util.Arrays;
    import java.util.Collections;
    import java.util.List;
    import java.util.concurrent.CompletableFuture;
    
    @Service
    public class GuildService {
      @Async
      public CompletableFuture<List<GuildMember>> findAll() {
        return CompletableFuture.supplyAsync(() -> {
          try { Thread.sleep(1000); } catch (InterruptedException e) { e.printStackTrace(); }
          return Arrays.asList(new GuildMember("Jane"), new GuildMember("John"), new GuildMember("Eve"));
        });
      }
    
      @Async
      public CompletableFuture<List<GuildMember>> findByType(String role) {
        return CompletableFuture.supplyAsync(() -> {
          try { Thread.sleep(1000); } catch (InterruptedException e) { e.printStackTrace(); }
          return Collections.singletonList(new GuildMember("Eve"));
        });
      }
    }
    

    Component to be targeted by profiling aspect:

    Here is your sample component, only slightly streamlined with regard to guildMembers initialisation. But it does not change the functionality at all:

    package de.scrum_master.spring.q66958382;
    
    import org.springframework.beans.factory.annotation.Autowired;
    import org.springframework.stereotype.Component;
    import org.springframework.web.bind.annotation.GetMapping;
    import org.springframework.web.bind.annotation.RequestParam;
    
    import javax.servlet.http.HttpServletResponse;
    import java.io.IOException;
    import java.text.DateFormat;
    import java.text.SimpleDateFormat;
    import java.util.Date;
    import java.util.List;
    import java.util.concurrent.CompletableFuture;
    import java.util.concurrent.ExecutionException;
    
    @Component
    public class MyComponent {
      @Autowired
      private GuildService guildService;
    
      @GetMapping("/members/exportpdf")
      @Profiling
      public void exportToPDF(@RequestParam(required = false) String role, HttpServletResponse response) throws IOException, ExecutionException, InterruptedException {
        CompletableFuture<List<GuildMember>> guildMembers = role == null ? guildService.findAll() : guildService.findByType(role);
    
        response.setContentType("application/pdf");
        DateFormat dateFormatter = new SimpleDateFormat("yyyy-MM-dd_HH:mm:ss");
        String currentDateTime = dateFormatter.format(new Date());
    
        String headerKey = "Content-Disposition";
        String headerValue = "inline; filename=guildmembers_" + currentDateTime + ".pdf";
        response.setHeader(headerKey, headerValue);
    
        PDFExporter exporter = new PDFExporter(guildMembers);
        exporter.export(response).get();
      }
    }
    

    Driver application + @EnableAsync configuration:

    package de.scrum_master.spring.q66958382;
    
    import org.springframework.boot.SpringApplication;
    import org.springframework.boot.autoconfigure.SpringBootApplication;
    import org.springframework.context.ConfigurableApplicationContext;
    import org.springframework.context.annotation.Configuration;
    import org.springframework.mock.web.MockHttpServletResponse;
    import org.springframework.scheduling.annotation.EnableAsync;
    
    import java.io.IOException;
    import java.util.concurrent.ExecutionException;
    
    @SpringBootApplication
    @Configuration
    @EnableAsync
    public class DemoApplication {
      public static void main(String[] args) throws InterruptedException, IOException, ExecutionException {
        try (ConfigurableApplicationContext appContext = SpringApplication.run(DemoApplication.class, args)) {
          doStuff(appContext);
        }
      }
    
      private static void doStuff(ConfigurableApplicationContext appContext) throws InterruptedException, IOException, ExecutionException {
        MyComponent myComponent = appContext.getBean(MyComponent.class);
        myComponent.exportToPDF("admin", new MockHttpServletResponse());
      }
    }
    

    Profiling aspect:

    Last, but not least, here is the aspect. It is also the same you presented, only a bit less complicated concerning how to return the result. But again, this does not change the fact that the aspect works as expected:

    package de.scrum_master.spring.q66958382;
    
    import org.aspectj.lang.ProceedingJoinPoint;
    import org.aspectj.lang.annotation.Around;
    import org.aspectj.lang.annotation.Aspect;
    import org.slf4j.Logger;
    import org.slf4j.LoggerFactory;
    import org.springframework.stereotype.Component;
    
    import java.time.Instant;
    
    @Aspect
    @Component
    public class ProfilingAspect {
      private static final Logger logger = LoggerFactory.getLogger(ProfilingAspect.class);
    
      @Around("@annotation(profilingAnnotation)")
      public Object logDuration(ProceedingJoinPoint joinPoint, Profiling profilingAnnotation) throws Throwable {
        long startTime = Instant.now().toEpochMilli();
        try {
          return joinPoint.proceed();
        }
        catch (Throwable e) {
          logger.error(e.getMessage(), e);
          throw e;
        }
        finally {
          long duration = Instant.now().toEpochMilli() - startTime;
          logger.info(joinPoint.getSignature().toShortString() + ": " + duration + " ms");
        }
      }
    }
    

    Console log:

    If you run the application, the console log says:

      .   ____          _            __ _ _
     /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
    ( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
     \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
      '  |____| .__|_| |_|_| |_\__, | / / / /
     =========|_|==============|___/=/_/_/_/
     :: Spring Boot ::        (v2.1.8.RELEASE)
    
    2021-04-06 09:18:10.793  INFO 13616 --- [           main] d.s.spring.q66958382.DemoApplication     : Starting DemoApplication on Xander-Ultrabook with PID 13616 (C:\Users\alexa\Documents\java-src\spring-aop-playground\target\classes started by alexa in C:\Users\alexa\Documents\java-src\spring-aop-playground)
    (...)
    2021-04-06 09:18:14.809  INFO 13616 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8080 (http) with context path ''
    2021-04-06 09:18:14.812  INFO 13616 --- [           main] d.s.spring.q66958382.DemoApplication     : Started DemoApplication in 4.815 seconds (JVM running for 7.782)
    (...)
    2021-04-06 09:18:15.839  INFO 13616 --- [           main] d.s.spring.q66958382.ProfilingAspect     : MyComponent.exportToPDF(..): 1014 ms
    (...)
    

    So if it does not work in your own application, either there is something different from how you described it or you are misinterpreting the log.