How to avoid flooding log with un-handled exceptions thrown by an Spring AOP Advice

Question

I have an Spring boot web app with an endpoint /userInfo

@RestController
public class HelloController {

    @GetMapping("/userInfo")
    @WithRoles({Roles.USER, Roles.VERIFIED_EMAIL})
    public User userInfo() {
        return RequestContextHelper.getCurrentUser();
    }

}

The @WithRoles annotation is a marker for an Aspect:

@Target(ElementType.METHOD)
@Retention(RetentionPolicy.RUNTIME)
public @interface WithRoles {
    Roles[] value();
}

And this is the Aspect implementation:

@Aspect
@Component
public class RolesAspect {

    @Before("@annotation(com.chuque.aspectj.aspect.marker.WithRoles)")
    public void validatePermission(final JoinPoint joinPoint) throws UnauthorizedException {

        User currentUser = RequestContextHelper.getCurrentUser();

        WithRoles annotation = ((MethodSignature) joinPoint.getSignature()).getMethod().getAnnotation(WithRoles.class);

        boolean userHasAllRoles = currentUser.getRoles().containsAll(Arrays.asList(annotation.value()).stream().map(Enum::toString).collect(Collectors.toList()));

        if(!userHasAllRoles){
            throw new UnauthorizedException();
        }

    }
}

As you can see there is a condidition that throws an Exception, causing the method to not even get called. When the endpoint throws an exception, the @RestControllerAdvice handles it and returns a 401 Unauthorized:

@RestControllerAdvice
public class GenericExceptionHandler {

    private static final Logger LOGGER = LoggerFactory.getLogger(GenericExceptionHandler.class);

    @ExceptionHandler(UnauthorizedException.class)
    public ResponseEntity handleUnauthorizedException(Exception e) {
        HttpStatus response = HttpStatus.UNAUTHORIZED;
        LOGGER.error(String.format("Unauthorized exception - Returning %d %s", response.value(), response.getReasonPhrase()), e);
        return ResponseEntity.status(response).body(e.getMessage());
    }

}

The code works fine. If the user doesn't have the required roles the endpoint is not called and the @RestControllerAdvice really handles the exception thrown by the Advice.

The problem is that when the Advice throws the exception, the log is floodded with an UndeclaredThrowableException stacktrace:

2021-01-21 18:57:46.942 ERROR 19071 --- [nio-8080-exec-3] c.c.a.r.e.GenericExceptionHandler        : Unauthorized exception - Returning 401 Unauthorized


java.lang.reflect.UndeclaredThrowableException: null
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:767) ~[spring-aop-5.3.3.jar:5.3.3]
    at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97) ~[spring-aop-5.3.3.jar:5.3.3]
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.3.3.jar:5.3.3]
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:750) ~[spring-aop-5.3.3.jar:5.3.3]
    at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:692) ~[spring-aop-5.3.3.jar:5.3.3]
    at com.chuque.aspectj.rest.HelloController$$EnhancerBySpringCGLIB$$4ae73bfc.userInfo(<generated>) ~[classes/:na]
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na]
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:64) ~[na:na]
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na]
    at java.base/java.lang.reflect.Method.invoke(Method.java:564) ~[na:na]
    at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:197) ~[spring-web-5.3.3.jar:5.3.3]
    at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:141) ~[spring-web-5.3.3.jar:5.3.3]
    at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:106) ~[spring-webmvc-5.3.3.jar:5.3.3]
    at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:894) ~[spring-webmvc-5.3.3.jar:5.3.3]
    at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:808) ~[spring-webmvc-5.3.3.jar:5.3.3]
    at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87) ~[spring-webmvc-5.3.3.jar:5.3.3]
    at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1060) ~[spring-webmvc-5.3.3.jar:5.3.3]
    at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:962) ~[spring-webmvc-5.3.3.jar:5.3.3]
    at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006) ~[spring-webmvc-5.3.3.jar:5.3.3]
    at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:898) ~[spring-webmvc-5.3.3.jar:5.3.3]
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:626) ~[tomcat-embed-core-9.0.41.jar:4.0.FR]
    at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883) ~[spring-webmvc-5.3.3.jar:5.3.3]
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:733) ~[tomcat-embed-core-9.0.41.jar:4.0.FR]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231) ~[tomcat-embed-core-9.0.41.jar:9.0.41]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.41.jar:9.0.41]
    at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53) ~[tomcat-embed-websocket-9.0.41.jar:9.0.41]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.41.jar:9.0.41]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.41.jar:9.0.41]
    at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100) ~[spring-web-5.3.3.jar:5.3.3]
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.3.3.jar:5.3.3]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.41.jar:9.0.41]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.41.jar:9.0.41]
    at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93) ~[spring-web-5.3.3.jar:5.3.3]
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.3.3.jar:5.3.3]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.41.jar:9.0.41]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.41.jar:9.0.41]
    at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201) ~[spring-web-5.3.3.jar:5.3.3]
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.3.3.jar:5.3.3]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.41.jar:9.0.41]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.41.jar:9.0.41]
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202) ~[tomcat-embed-core-9.0.41.jar:9.0.41]
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97) ~[tomcat-embed-core-9.0.41.jar:9.0.41]
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:542) ~[tomcat-embed-core-9.0.41.jar:9.0.41]
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:143) ~[tomcat-embed-core-9.0.41.jar:9.0.41]
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92) ~[tomcat-embed-core-9.0.41.jar:9.0.41]
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78) ~[tomcat-embed-core-9.0.41.jar:9.0.41]
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343) ~[tomcat-embed-core-9.0.41.jar:9.0.41]
    at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:374) ~[tomcat-embed-core-9.0.41.jar:9.0.41]
    at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65) ~[tomcat-embed-core-9.0.41.jar:9.0.41]
    at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:888) ~[tomcat-embed-core-9.0.41.jar:9.0.41]
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1597) ~[tomcat-embed-core-9.0.41.jar:9.0.41]
    at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) ~[tomcat-embed-core-9.0.41.jar:9.0.41]
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) ~[na:na]
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) ~[na:na]
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) ~[tomcat-embed-core-9.0.41.jar:9.0.41]
    at java.base/java.lang.Thread.run(Thread.java:832) ~[na:na]
Caused by: com.chuque.aspectj.exception.UnauthorizedException: null
    at com.chuque.aspectj.aspect.runner.RolesAspect.validatePermission(RolesAspect.java:35) ~[classes/:na]
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na]
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:64) ~[na:na]
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na]
    at java.base/java.lang.reflect.Method.invoke(Method.java:564) ~[na:na]
    at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:634) ~[spring-aop-5.3.3.jar:5.3.3]
    at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:617) ~[spring-aop-5.3.3.jar:5.3.3]
    at org.springframework.aop.aspectj.AspectJMethodBeforeAdvice.before(AspectJMethodBeforeAdvice.java:44) ~[spring-aop-5.3.3.jar:5.3.3]
    at org.springframework.aop.framework.adapter.MethodBeforeAdviceInterceptor.invoke(MethodBeforeAdviceInterceptor.java:57) ~[spring-aop-5.3.3.jar:5.3.3]
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:175) ~[spring-aop-5.3.3.jar:5.3.3]
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:750) ~[spring-aop-5.3.3.jar:5.3.3]
    ... 55 common frames omitted

It would not be nice to have this stacktrace everytime an unauthorized exception is thrown. How can I solve this? Maybe clearing stack traces? Maybe there is a way to disable exception logs thrown by an Advice? Any help is appreciated.

Answer 1

Actually, for me the exception looks a bit different from what you posted:

java.lang.reflect.UndeclaredThrowableException: null
    at de.scrum_master.spring.q65836243.HelloController$$EnhancerBySpringCGLIB$$261c9226.userInfo(<generated>) ~[classes/:na]

So, I can directly see that the exception is thrown in the HelloController AOP proxy, to be more precise in its userInfo() method.

As the error message implies, you are trying to throw a checked exception in a method where that exception is not declared. Make UnauthorizedException extend RuntimeException instead, then the UndeclaredThrowableException goes away.

Alternatively, make userInfo() throw UnauthorizedException. But that would not be so nice because then the application code would effectively be AOP-aware, which is not very nice style. It is better to keep core concerns agnostic of cross-cutting concerns like exception handling.

P.S.: Ironically, you did not post the exception source code, so I had to try and simulate your situation, making an educated guess, in order to find out. Next time, please post a full MCVE instead. 😉 You may think you know which information is essential for others to solve your problem, but actually you cannot know because otherwise you probably would know the solution for your problem already. So you are on uncharted territory. Let your helpers see the full picture, it helps tremendously and saves both you and them a lot of time.

---

Update: For reference, here is my MCVE:

package de.scrum_master.spring.q65836243;

public enum Roles {
  VERIFIED_EMAIL, USER
}

package de.scrum_master.spring.q65836243;

import java.lang.annotation.ElementType;
import java.lang.annotation.Retention;
import java.lang.annotation.RetentionPolicy;
import java.lang.annotation.Target;

@Retention(RetentionPolicy.RUNTIME)
@Target(ElementType.METHOD)
public @interface WithRoles {
  Roles[] value();
}

package de.scrum_master.spring.q65836243;

import org.springframework.security.core.userdetails.User;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;

import java.util.ArrayList;

@RestController
public class HelloController {
  @GetMapping("/userInfo")
  @WithRoles({ Roles.USER, Roles.VERIFIED_EMAIL })
  public User userInfo() {
    return new User("john", "secret", new ArrayList<>());
  }
}

package de.scrum_master.spring.q65836243;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.http.HttpStatus;
import org.springframework.http.ResponseEntity;
import org.springframework.web.bind.annotation.ExceptionHandler;
import org.springframework.web.bind.annotation.RestControllerAdvice;

@RestControllerAdvice
public class GenericExceptionHandler {
  private static final Logger LOGGER = LoggerFactory.getLogger(GenericExceptionHandler.class);

  @ExceptionHandler(UnauthorizedException.class)
  public ResponseEntity handleUnauthorizedException(Exception e) {
    HttpStatus response = HttpStatus.UNAUTHORIZED;
    LOGGER.error(String.format("Unauthorized exception - Returning %d %s", response.value(), response.getReasonPhrase()), e);
    return ResponseEntity.status(response).body(e.getMessage());
  }
}

package de.scrum_master.spring.q65836243;

public class UnauthorizedException extends /*Exception*/ RuntimeException {}

package de.scrum_master.spring.q65836243;

import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Before;
import org.springframework.stereotype.Component;

@Aspect
@Component
public class RolesAspect {
  @Before("@annotation(withRoles)")
  public void validatePermission(JoinPoint joinPoint, WithRoles withRoles) throws UnauthorizedException {
    boolean userHasAllRoles = false;
    if (!userHasAllRoles)
      throw new UnauthorizedException();
  }
}

package de.scrum_master.spring.q65836243;

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.web.client.RestClientException;
import org.springframework.web.client.RestTemplate;

@SpringBootApplication
@Configuration
public class DemoApplication {
  public static void main(String[] args) throws InterruptedException {
    try (ConfigurableApplicationContext appContext = SpringApplication.run(DemoApplication.class, args)) {
      doStuff(appContext);
    }
  }

  private static void doStuff(ConfigurableApplicationContext appContext) {
    try {
      new RestTemplate().getForObject("http://localhost:8080/userInfo", String.class);
    }
    catch (RestClientException ignored) {}
  }
}

When running the sample application, now you see this console log:

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

2021-01-22 12:00:34.001  INFO 17396 --- [           main] d.s.spring.q65836243.DemoApplication     : Starting DemoApplication on Xander-Ultrabook with PID 17396 (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-01-22 12:00:39.213 ERROR 17396 --- [nio-8080-exec-1] d.s.s.q65836243.GenericExceptionHandler  : Unauthorized exception - Returning 401 Unauthorized

de.scrum_master.spring.q65836243.UnauthorizedException: null
    at de.scrum_master.spring.q65836243.RolesAspect.validatePermission(RolesAspect.java:19) ~[classes/:na]
(...)

2021-01-22 12:00:39.272  INFO 17396 --- [           main] o.s.s.concurrent.ThreadPoolTaskExecutor  : Shutting down ExecutorService 'applicationTaskExecutor'
(...)
Process finished with exit code 0