Edited to provide an MCVE.
@Target(ElementType.PARAMETER)
@Retention(RetentionPolicy.RUNTIME)
public @interface Random {
}
@Target(ElementType.METHOD)
@Retention(RetentionPolicy.RUNTIME)
public @interface Audited {
}
@Target(ElementType.PARAMETER)
@Retention(RetentionPolicy.RUNTIME)
public @interface Tester {
}
package spring;
import lombok.extern.slf4j.Slf4j;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.boot.web.servlet.support.SpringBootServletInitializer;
@Slf4j
@SpringBootApplication
public class springLoader extends SpringBootServletInitializer {
public static final Class<springLoader> CLASS = springLoader.class;
public static void main(String[] args) {
try (final var context = SpringApplication.run(CLASS, args)) {
while(true){
Thread.sleep(1000*60*60*24);
}
} catch (InterruptedException e) {
throw new RuntimeException(e);
}
}
}
package spring;
import lombok.extern.slf4j.Slf4j;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.RestController;
import java.util.ArrayList;
import java.util.List;
@Slf4j
@RestController
@RequestMapping("/Inventory")
public class springRest {
private List<String> info;
public springRest() {
final var strArr = new String[]{"1234", "2345", "3456", "4567", "5678"};
info = new ArrayList<>();
info.addAll(List.of(strArr));
}
@Audited
@GetMapping()
public List<String> getInfo(@Tester String permittedValues, @Random String randomValues) {
log.info("permitted {}", permittedValues);
log.info("random: {}", randomValues);
List<String> returnedValues = new ArrayList<>();
for (final var str : info) {
if (permittedValues.contains(str) || randomValues.contains(str)) {
log.info("{}", str);
returnedValues.add(str);
} else {
log.info("Not permitted: {}", str);
}
}
return returnedValues;
}
}
package spring;
import lombok.extern.slf4j.Slf4j;
import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.annotation.AfterReturning;
import org.aspectj.lang.annotation.AfterThrowing;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.reflect.MethodSignature;
import org.springframework.stereotype.Component;
import java.time.LocalDate;
import java.time.LocalTime;
import java.util.Arrays;
import java.util.LinkedHashMap;
import java.util.Map;
import java.util.stream.Collectors;
@Component
@Aspect
@Slf4j
public class AuditAspect {
@AfterReturning("@annotation(spring.Audited)")
public void afterReturning(JoinPoint joinPoint) {
auditHelper(joinPoint, null);
}
@AfterThrowing(pointcut = "@annotation(spring.Audited)", throwing = "ex")
public void handleException(JoinPoint joinPoint, Exception ex) {
// This advice will be executed if an exception occurs.
auditHelper(joinPoint, ex);
}
private void auditHelper(JoinPoint joinPoint, Exception ex) {
final var date = LocalDate.now();
final var time = LocalTime.now();
final var method = ((MethodSignature) joinPoint.getSignature()).getMethod();
final var methodname = method.getName();
final var args = joinPoint.getArgs();
final var arguments = Arrays.stream(args).map(Object::toString).collect(Collectors.joining(" | "));
final var base = "accessed " + methodname + " with arguments: " + arguments;
final var statement = (ex == null) ? base : base + " but failed: " + ex.getMessage();
final Map<String, Object> linkedMap = new LinkedHashMap<>();
linkedMap.put("Time", time);
linkedMap.put("Date", date);
linkedMap.put("Log", statement);
log.info(statement);
}
}
package spring;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.reflect.MethodSignature;
import org.springframework.stereotype.Component;
import java.lang.annotation.Annotation;
import java.util.ArrayList;
import java.util.Collections;
import java.util.List;
@Component
@Aspect
public class TesterAspect {
private String[] permittedValues = new String[]{"1234", "2345"};
private List<String> randomValues = new ArrayList<>(List.of("1234", "2345", "3456", "4567","5678"));
@Around("execution(* *(.., @spring.Tester (*), ..))")
public Object permittedValues(ProceedingJoinPoint pjp) throws Throwable {
final var args = pjp.getArgs();
final var annotations = ((MethodSignature) pjp.getSignature()).getMethod().getParameterAnnotations();
for (int i = 0; i < args.length; i++) {
for (Annotation annotation : annotations[i]) {
if (annotation.annotationType() == Tester.class) {
args[i] = String.join(",", permittedValues);
}
}
}
Object result = pjp.proceed(args);
return result;
}
@Around("execution(* *(.., @spring.Random (*), ..))")
public Object randomValues(ProceedingJoinPoint pjp) throws Throwable {
final var args = pjp.getArgs();
final var annotations = ((MethodSignature) pjp.getSignature()).getMethod().getParameterAnnotations();
for (int i = 0; i < args.length; i++) {
for (Annotation annotation : annotations[i]) {
if (annotation.annotationType() == Random.class) {
Collections.shuffle(randomValues);
args[i] = randomValues.get(0)+","+randomValues.get(1);
}
}
}
Object result = pjp.proceed(args);
return result;
}
}
The following code is simulating the error I experienced. I have two annotations for a GetMapping on the parameter level, and an annotation on the method level. The two Around aspects are executed and in the GetMapping method, the modified arguments are logged out correctly and properly. However, inside the @AfterReturning or @AfterThrowing aspect methods, one of the arguments is null. I accessed the GetMapping by typing localhost:8080/Inventory into google chrome.
The stack trace on the IDE is:
2023-12-06 11:39:14.938 INFO 7905 --- [nio-8080-exec-1] s.springRest : permitted 1234,2345
2023-12-06 11:46:17.851 INFO 8067 --- [nio-8080-exec-1] s.springRest : random: 3456,5678
2023-12-06 11:46:17.851 INFO 8067 --- [nio-8080-exec-1] s.springRest : 1234
2023-12-06 11:46:17.851 INFO 8067 --- [nio-8080-exec-1] s.springRest : 2345
2023-12-06 11:46:17.851 INFO 8067 --- [nio-8080-exec-1] s.springRest : 3456
2023-12-06 11:46:17.852 INFO 8067 --- [nio-8080-exec-1] s.springRest : Not permitted: 4567
2023-12-06 11:46:17.852 INFO 8067 --- [nio-8080-exec-1] s.springRest : 5678
2023-12-06 11:39:14.942 ERROR 7905 --- [nio-8080-exec-1] o.a.c.c.C.[.[.[.[dispatcherServlet] : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is java.lang.NullPointerException] with root cause
java.lang.NullPointerException: null
at java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:197) ~[?:?]
at java.util.Spliterators$ArraySpliterator.forEachRemaining(Spliterators.java:992) ~[?:?]
at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:509) ~[?:?]
at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:499) ~[?:?]
at java.util.stream.ReduceOps$ReduceOp.evaluateSequential(ReduceOps.java:921) ~[?:?]
at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234) ~[?:?]
at java.util.stream.ReferencePipeline.collect(ReferencePipeline.java:682) ~[?:?]
at spring.AuditAspect.auditHelper(AuditAspect.java:41) ~[classes/:?]
at spring.AuditAspect.afterReturning(AuditAspect.java:24) ~[classes/:?]
at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) ~[?:?]
at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
at java.lang.reflect.Method.invoke(Method.java:568) ~[?:?]
at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:634) ~[spring-aop-5.3.24.jar:5.3.24]
at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:617) ~[spring-aop-5.3.24.jar:5.3.24]
at org.springframework.aop.aspectj.AspectJAfterReturningAdvice.afterReturning(AspectJAfterReturningAdvice.java:66) ~[spring-aop-5.3.24.jar:5.3.24]
at org.springframework.aop.framework.adapter.AfterReturningAdviceInterceptor.invoke(AfterReturningAdviceInterceptor.java:58) ~[spring-aop-5.3.24.jar:5.3.24]
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:175) ~[spring-aop-5.3.24.jar:5.3.24]
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:763) ~[spring-aop-5.3.24.jar:5.3.24]
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97) ~[spring-aop-5.3.24.jar:5.3.24]
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.3.24.jar:5.3.24]
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:763) ~[spring-aop-5.3.24.jar:5.3.24]
at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:708) ~[spring-aop-5.3.24.jar:5.3.24]
at spring.springRest$$EnhancerBySpringCGLIB$$1d14e293.getInfo(<generated>) ~[classes/:?]
at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) ~[?:?]
at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
at java.lang.reflect.Method.invoke(Method.java:568) ~[?:?]
at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:205) ~[spring-web-5.3.24.jar:5.3.24]
at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:150) ~[spring-web-5.3.24.jar:5.3.24]
at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:117) ~[spring-webmvc-5.3.24.jar:5.3.24]
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:895) ~[spring-webmvc-5.3.24.jar:5.3.24]
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:808) ~[spring-webmvc-5.3.24.jar:5.3.24]
at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87) ~[spring-webmvc-5.3.24.jar:5.3.24]
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1071) ~[spring-webmvc-5.3.24.jar:5.3.24]
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:964) ~[spring-webmvc-5.3.24.jar:5.3.24]
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006) ~[spring-webmvc-5.3.24.jar:5.3.24]
at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:898) ~[spring-webmvc-5.3.24.jar:5.3.24]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:670) ~[tomcat-embed-core-9.0.70.jar:4.0.FR]
at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883) ~[spring-webmvc-5.3.24.jar:5.3.24]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:779) ~[tomcat-embed-core-9.0.70.jar:4.0.FR]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:227) ~[tomcat-embed-core-9.0.70.jar:9.0.70]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162) ~[tomcat-embed-core-9.0.70.jar:9.0.70]
at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53) ~[tomcat-embed-websocket-9.0.70.jar:9.0.70]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189) ~[tomcat-embed-core-9.0.70.jar:9.0.70]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162) ~[tomcat-embed-core-9.0.70.jar:9.0.70]
at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100) ~[spring-web-5.3.24.jar:5.3.24]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117) ~[spring-web-5.3.24.jar:5.3.24]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189) ~[tomcat-embed-core-9.0.70.jar:9.0.70]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162) ~[tomcat-embed-core-9.0.70.jar:9.0.70]
at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93) ~[spring-web-5.3.24.jar:5.3.24]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117) ~[spring-web-5.3.24.jar:5.3.24]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189) ~[tomcat-embed-core-9.0.70.jar:9.0.70]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162) ~[tomcat-embed-core-9.0.70.jar:9.0.70]
at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201) ~[spring-web-5.3.24.jar:5.3.24]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117) ~[spring-web-5.3.24.jar:5.3.24]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189) ~[tomcat-embed-core-9.0.70.jar:9.0.70]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162) ~[tomcat-embed-core-9.0.70.jar:9.0.70]
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:177) [tomcat-embed-core-9.0.70.jar:9.0.70]
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97) [tomcat-embed-core-9.0.70.jar:9.0.70]
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:541) [tomcat-embed-core-9.0.70.jar:9.0.70]
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:135) [tomcat-embed-core-9.0.70.jar:9.0.70]
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92) [tomcat-embed-core-9.0.70.jar:9.0.70]
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78) [tomcat-embed-core-9.0.70.jar:9.0.70]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:360) [tomcat-embed-core-9.0.70.jar:9.0.70]
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:399) [tomcat-embed-core-9.0.70.jar:9.0.70]
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65) [tomcat-embed-core-9.0.70.jar:9.0.70]
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:891) [tomcat-embed-core-9.0.70.jar:9.0.70]
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1784) [tomcat-embed-core-9.0.70.jar:9.0.70]
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) [tomcat-embed-core-9.0.70.jar:9.0.70]
at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191) [tomcat-embed-core-9.0.70.jar:9.0.70]
at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659) [tomcat-embed-core-9.0.70.jar:9.0.70]
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-embed-core-9.0.70.jar:9.0.70]
at java.lang.Thread.run(Thread.java:840) [?:?]
The pom.xml used is as follows, but with the distribution management obfuscated.
<?xml version="1.0" encoding="UTF-8"?>
<project xmlns="http://maven.apache.org/POM/4.0.0"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
<modelVersion>4.0.0</modelVersion>
<groupId>org.example</groupId>
<artifactId>demo</artifactId>
<version>1.0-SNAPSHOT</version>
<properties>
<maven.compiler.source>17</maven.compiler.source>
<maven.compiler.target>17</maven.compiler.target>
<project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
</properties>
<dependencies>
<dependency>
<groupId>org.springframework</groupId>
<artifactId>spring-web</artifactId>
<version>5.3.24</version>
</dependency>
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-web</artifactId>
<version>2.7.7</version>
<exclusions>
<exclusion>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-logging</artifactId>
</exclusion>
</exclusions>
</dependency>
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-data-jpa</artifactId>
<version>2.7.7</version>
</dependency>
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-log4j2</artifactId>
<version>2.7.7</version>
<exclusions>
<exclusion>
<groupId>org.apache.logging.log4j</groupId>
<artifactId>log4j-slf4j-impl</artifactId>
</exclusion>
</exclusions>
</dependency>
<dependency>
<groupId>org.apache.logging.log4j</groupId>
<artifactId>log4j-slf4j2-impl</artifactId>
<version>2.20.0</version>
</dependency>
<dependency>
<groupId>org.apache.logging.log4j</groupId>
<artifactId>log4j-api</artifactId>
<version>2.20.0</version>
</dependency>
<dependency>
<groupId>org.apache.logging.log4j</groupId>
<artifactId>log4j-core</artifactId>
<version>2.20.0</version>
</dependency>
<dependency>
<groupId>org.projectlombok</groupId>
<artifactId>lombok</artifactId>
<version>1.18.24</version>
<scope>compile</scope>
</dependency>
<dependency>
<groupId>javax.xml.bind</groupId>
<artifactId>jaxb-api</artifactId>
<version>2.4.0-b180830.0359</version>
</dependency>
<dependency>
<groupId>com.h2database</groupId>
<artifactId>h2</artifactId>
<version>2.1.214</version>
<scope>runtime</scope>
</dependency>
</dependencies>
<build>
<plugins>
<plugin>
<groupId>org.apache.maven.plugins</groupId>
<artifactId>maven-surefire-plugin</artifactId>
<version>2.22.2</version>
</plugin>
</plugins>
</build>
<distributionManagement>
<repository>
<id>nexus-es</id>
<name>Internal Release Repository</name>
<url>https://nexus/repository/my-docker/</url>
<layout>default</layout>
</repository>
<snapshotRepository>
<id>nexus-snapshot</id>
<name>Internal Snapshot Repository</name>
<url>https://nexus/repository/snapshot/</url>
</snapshotRepository>
</distributionManagement>
</project>
Your error simply occurs, because the code in
AuditAspect::auditHelperdoes not expect thatArrays.stream(args).map(Object::toString)could contain anullelement, but it does, which derails the subsequent.collect(Collectors.joining(" | "))call.If you replace
.map(Object::toString)by.map(o -> o == null ? "null" : o.toString()), your audit aspect works. The application logs something like:Now, why is the second argument null? You might expect it to be something like "2345,5678", because you have a wrong idea of how Spring AOP works. While it is true that in case of two around advices, the inner one can see the input parameter changes of the outer one, an after advice obviously cannot. It looks as if it sees the parameters as they were passed into the innermost around advice, but not what the latter passes on to the target method.
Actually, the semantics for proceeding look to be different in Spring AOP vs. AspectJ. In Spring AOP, you can pass on a whole array with all (possibly changed) arguments to the target method, while in native AspectJ you can only pass on changed parameters if they were bound with
args, which is less flexible. When comparing the two, I was actually surprised as well, that this is not the same, because in many other respects Spring AOP tries to emulate native AspectJ. Very strange, indeed.Focusing on Spring AOP for now, your workaround to get the parameters of the innermost around advice in
TesterAspectpassed on toAuditAspectis to convert the after advice there to an around advice.You also need to make sure that
TesterAspecthas a higher aspect precedence thanAuditAspect, i.e. you put an@Order(1)annotation onTesterAspectand@Order(2)onAuditAspect. Lower number means higher precedence. Higher precedence means that everything before and includingproceed()is executed earlier than in a lower precedence aspect and everything after proceeding is executed later. This is what you want, because you want to audit after method execution, and the tester aspect should have done its magic before proceeding to the audit aspect, manipulating its input arguments.The console log will change to: