I'm looking for a way to get logging around methods. So I've started looking at examples of Spring-AOP and AspectJ. However, none of these seem to actually work, or at least are missing pieces in their snippets.
I tried to run a main-method from AspectJ examples. I created from Spring Initializr.
@SpringBootApplication
@EnableAspectJAutoProxy
public class Demo1Application {
public static void main(String[] args) {
testing_a_run();
SpringApplication.run(Demo1Application.class, args);
}
private static Logger logger = LoggerFactory.getLogger(Demo1Application.class);
@LogExecutionTime
static void testing_a_run() {
logger.info("Handling hello request");
}
}
Or when Spring-Boot was running
package com.example.demo;
import org.springframework.stereotype.Component;
@Component
public class Service {
@LogExecutionTime
public void serve() throws InterruptedException {
Thread.sleep(2000);
}
}
With the AspectJ Aspect-Annotation being
@Aspect
@Component
public class LoggingAspect {
private Logger logger = LoggerFactory.getLogger(LoggingAspect.class);
@Around("@annotation(LogExecutionTime)")
public Object logExecutionTime(ProceedingJoinPoint joinPoint) throws Throwable {
long startTime = System.currentTimeMillis();
Object proceed = joinPoint.proceed();
long endTime = System.currentTimeMillis();
logger.info(joinPoint.getSignature() + " executed in " + (endTime - startTime) + "ms");
return proceed;
}
@Before("execution(* com.example.demo..*.*(..))")
public void logBefore(JoinPoint joinPoint) {
logger.info("Method execution started: {}", joinPoint.getSignature());
}
@After("execution(* com.example.demo..*.*(..))")
public void logAfter(JoinPoint joinPoint) {
logger.info("Method execution completed: {}", joinPoint.getSignature());
}
}
And the annotation-interface
@Retention(RetentionPolicy.RUNTIME)
@Target(ElementType.METHOD)
public @interface LogExecutionTime {
}
These all seem pretty standard from the examples I've seen. Which is why I'm confused that the logging around this doesn't seem to happening. These annotations don't seem wildly complex. And, I've had this behavior work in Python with Decorators. Why isn't this pseudo-wrapper annotation not logging to console?
XX:XX:XX.XXX [main] INFO com.example.demo.Demo1Application -- Handling hello request
. ____ _ __ _ _
/\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
\\/ ___)| |_)| | | | | || (_| | ) ) ) )
' |____| .__|_| |_|_| |_\__, | / / / /
=========|_|==============|___/=/_/_/_/
:: Spring Boot :: (v3.2.5)
XXXX-XX-XXTXX:XX:XX.XXX-XX:XX INFO 9064 --- [demo1] [ main] com.example.demo.Demo1Application : Starting Demo1Application using Java 17.0.11 with PID 9064 (C:\Users\zmurray\git\demo1\build\classes\java\main started by zmurray in C:\Users\zmurray\git\demo1)
XXXX-XX-XXTXX:XX:XX.XXX-XX:XX INFO 9064 --- [demo1] [ main] com.example.demo.Demo1Application : No active profile set, falling back to 1 default profile: "default"
XXXX-XX-XXTXX:XX:XX.XXX-XX:XX INFO 9064 --- [demo1] [ main] com.example.demo.Demo1Application : Started Demo1Application in 1.73 seconds (process running for 2.224)
The application behaves like I would expect it to. What are you expecting?
Method testing_a_run() is static and not part of a Spring-managed bean/component class. Of course, it will not be intercepted by Spring AOP. For static methods and non-Spring-managed target classes, you would need native AspectJ.
You sample application never instantiates a Spring bean for class Service - horrible name, byte the way, easily confused with annotation class org.springframework.stereotype.Service - from the application context and never calls its serve() method. Code that is not running at all cannot be intercepted by an aspect either. Fix that, and it works.
package de.scrum_master.spring.q78366495;
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 LogExecutionTime {}
package de.scrum_master.spring.q78366495;
import org.springframework.stereotype.Component;
@Component
public class Service {
@LogExecutionTime
public void serve() throws InterruptedException {
Thread.sleep(2000);
}
}
package de.scrum_master.spring.q78366495;
import lombok.extern.slf4j.Slf4j;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.context.ConfigurableApplicationContext;
import org.springframework.context.annotation.Configuration;
@SpringBootApplication
@Configuration
//@EnableAspectJAutoProxy(proxyTargetClass = true)
@Slf4j
public class Demo1Application {
private static Logger logger = LoggerFactory.getLogger(Demo1Application.class);
public static void main(String[] args) throws InterruptedException {
testing_a_run();
try (ConfigurableApplicationContext appContext = SpringApplication.run(Demo1Application.class, args)) {
doStuff(appContext);
}
}
private static void doStuff(ConfigurableApplicationContext appContext) throws InterruptedException {
appContext.getBean(Service.class).serve();
}
@LogExecutionTime
static void testing_a_run() {
logger.info("Handling hello request");
}
}
package de.scrum_master.spring.q78366495;
import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.After;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Before;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Component;
@Aspect
@Component
public class LoggingAspect {
private Logger logger = LoggerFactory.getLogger(LoggingAspect.class);
@Around("@annotation(LogExecutionTime)")
public Object logExecutionTime(ProceedingJoinPoint joinPoint) throws Throwable {
long startTime = System.currentTimeMillis();
Object proceed = joinPoint.proceed();
long endTime = System.currentTimeMillis();
logger.info(joinPoint.getSignature() + " executed in " + (endTime - startTime) + "ms");
return proceed;
}
@Before("execution(* de.scrum_master.spring.q78366495..*.*(..))")
public void logBefore(JoinPoint joinPoint) {
logger.info("Method execution started: {}", joinPoint.getSignature());
}
@After("execution(* de.scrum_master.spring.q78366495..*.*(..))")
public void logAfter(JoinPoint joinPoint) {
logger.info("Method execution completed: {}", joinPoint.getSignature());
}
}
Console log:
17:39:58.573 [main] INFO de.scrum_master.spring.q78366495.Demo1Application - Handling hello request
. ____ _ __ _ _
/\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
\\/ ___)| |_)| | | | | || (_| | ) ) ) )
' |____| .__|_| |_|_| |_\__, | / / / /
=========|_|==============|___/=/_/_/_/
:: Spring Boot :: (v2.6.4)
...
2024-04-22 17:40:04.549 INFO 6020 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat started on port(s): 8080 (http) with context path ''
2024-04-22 17:40:04.561 INFO 6020 --- [ main] d.s.spring.q78366495.Demo1Application : Started Demo1Application in 5.808 seconds (JVM running for 6.983)
2024-04-22 17:40:04.570 INFO 6020 --- [ main] d.s.spring.q78366495.LoggingAspect : Method execution started: void de.scrum_master.spring.q78366495.Service.serve()
2024-04-22 17:40:06.590 INFO 6020 --- [ main] d.s.spring.q78366495.LoggingAspect : Method execution completed: void de.scrum_master.spring.q78366495.Service.serve()
2024-04-22 17:40:06.590 INFO 6020 --- [ main] d.s.spring.q78366495.LoggingAspect : void de.scrum_master.spring.q78366495.Service.serve() executed in 2021ms
...