I'm facing a problem on a large scale application using SpringBoot and AspectJ for logging purposes. The logging works fine for Spring Beans, but does not work for unmanaged classes (the ones I instantiate with 'new').
I've created a sample app where you can see the problem happening, you can access it here:
https://bitbucket.org/tomkro/stack_question
The application is pretty simple, the Gradle file is a common with the standard Spring Boot starters.
There are 5 relevant classes here.
Application.java, which is the main class:
@EnableAspectJAutoProxy
@EnableLoadTimeWeaving(aspectjWeaving= EnableLoadTimeWeaving.AspectJWeaving.ENABLED)
@SpringBootApplication(scanBasePackages = "com.test.*")
public class Application {
public static void main(final String[] args) {
SpringApplication.run(Application.class, args);
}
}
The AspectConfig file (which for the sake of simplicity also defines the RestController, could be easily separated files)
@RestController
@Configuration
@ComponentScan(basePackages = {"com.test"})
public class AspectConfig {
@Bean
public TestLogger testLogger(){
return new TestLogger();
}
@Autowired
TestClass testClass;
@RequestMapping("/")
public int get() {
return testClass.methodFromClass1();
}
}
The TestLogger, which defines the aspect for this app:
@Aspect
public class TestLogger {
public TestLogger() {
}
@Around("execution( * com.test.classes..*.*(..))")
public Object aroundExecution(ProceedingJoinPoint pjp) throws Throwable {
String packageName = pjp.getSignature().getDeclaringTypeName();
String methodName = pjp.getSignature().getName();
long start = System.currentTimeMillis();
System.out.println(packageName + "." + methodName + " - Starting execution ");
Object output = pjp.proceed();
Long elapsedTime = System.currentTimeMillis() - start;
System.out.println(packageName + "." + methodName + " - Ending execution ["+elapsedTime+" ms]");
return output;
}
}
And then there's two files, one managed by Spring, the other not:
TestClass1:
@Component
public class TestClass {
public int methodFromClass1() {
TestClass2 test = new TestClass2();
return test.methodFromClass2();
}
}
TestClass2
public class TestClass2 {
public int methodFromClass2() {
int a = 10;
int b = 5;
return b + a;
}
}
Also there's the aop.xml file in META-INF which specifies the Aspect
<!DOCTYPE aspectj PUBLIC "-//AspectJ//DTD//EN" "http://www.eclipse.org/aspectj/dtd/aspectj.dtd">
<aspectj>
<weaver option="-debug">
<!-- only weave classes in our application-specific packages -->
<include within="com.test.*"/>
</weaver>
<aspects>
<!-- weave in just this aspect -->
<aspect name="com.test.utilities.TestLogger"/>
</aspects>
</aspectj>
I followed most of this build using the tutorial on the Spring documentation here , and I've been scratching my head for two days now and I can't figure out what's happening. The managed Bean logs fine, but the unmanaged one is not being logged.
I'm using the run.bat included in the project for starting, basically it does this:
call gradle build
java -javaagent:.\src\main\resources\aspectjweaver.jar -javaagent:.\src\main\resources\spring-instrument.jar -jar build\libs\Test-0.0.1-SNAPSHOT.jar
Both jars are the latest. Usually you only would need of the JAR's, but I saw someone using both and gave it a shot. This is the output after startup and execution of a call to "localhost:8080"
[LaunchedURLClassLoader@6d8a00e3] warning javax.* types are not being woven because the weaver option '-Xset:weaveJavaxPackages=true' has not been specified
. ____ _ __ _ _
/\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
\\/ ___)| |_)| | | | | || (_| | ) ) ) )
' |____| .__|_| |_|_| |_\__, | / / / /
=========|_|==============|___/=/_/_/_/
:: Spring Boot :: (v1.3.0.RELEASE)
2016-04-08 15:21:44.116 INFO 20400 --- [ main] com.test.Application : Starting Application on PC000BR23205 with PID 20400 (C:\git\Test\build\libs\Test-0.0.1-SNAPSHOT.jar started by tkroth in C:\git\T
est)
2016-04-08 15:21:44.120 INFO 20400 --- [ main] com.test.Application : No profiles are active
2016-04-08 15:21:44.294 INFO 20400 --- [ main] ationConfigEmbeddedWebApplicationContext : Refreshing org.springframework.boot.context.embedded.AnnotationConfigEmbeddedWebApplicationContext@2cd72cea: startup date [Fri Ap
r 08 15:21:44 BRT 2016]; root of context hierarchy
2016-04-08 15:21:44.950 INFO 20400 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Overriding bean definition for bean 'beanNameViewResolver' with a different definition: replacing [Root bean: class [null]; scope
=; abstract=false; lazyInit=false; autowireMode=3; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=org.springframework.boot.autoconfigure.web.ErrorMvcAutoConfiguration$WhitelabelErrorViewConfiguration; fa
ctoryMethodName=beanNameViewResolver; initMethodName=null; destroyMethodName=(inferred); defined in class path resource [org/springframework/boot/autoconfigure/web/ErrorMvcAutoConfiguration$WhitelabelErrorViewConfiguration.class]]
with [Root bean: class [null]; scope=; abstract=false; lazyInit=false; autowireMode=3; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=org.springframework.boot.autoconfigure.web.WebMvcAutoConfiguration$W
ebMvcAutoConfigurationAdapter; factoryMethodName=beanNameViewResolver; initMethodName=null; destroyMethodName=(inferred); defined in class path resource [org/springframework/boot/autoconfigure/web/WebMvcAutoConfiguration$WebMvcAut
oConfigurationAdapter.class]]
2016-04-08 15:21:45.872 INFO 20400 --- [ main] s.b.c.e.t.TomcatEmbeddedServletContainer : Tomcat initialized with port(s): 8080 (http)
2016-04-08 15:21:45.888 INFO 20400 --- [ main] o.apache.catalina.core.StandardService : Starting service Tomcat
2016-04-08 15:21:45.891 INFO 20400 --- [ main] org.apache.catalina.core.StandardEngine : Starting Servlet Engine: Apache Tomcat/8.0.28
2016-04-08 15:21:45.987 INFO 20400 --- [ost-startStop-1] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring embedded WebApplicationContext
2016-04-08 15:21:45.987 INFO 20400 --- [ost-startStop-1] o.s.web.context.ContextLoader : Root WebApplicationContext: initialization completed in 1695 ms
2016-04-08 15:21:46.342 INFO 20400 --- [ost-startStop-1] o.s.b.c.e.ServletRegistrationBean : Mapping servlet: 'dispatcherServlet' to [/]
2016-04-08 15:21:46.347 INFO 20400 --- [ost-startStop-1] o.s.b.c.embedded.FilterRegistrationBean : Mapping filter: 'characterEncodingFilter' to: [/*]
2016-04-08 15:21:46.348 INFO 20400 --- [ost-startStop-1] o.s.b.c.embedded.FilterRegistrationBean : Mapping filter: 'hiddenHttpMethodFilter' to: [/*]
2016-04-08 15:21:46.349 INFO 20400 --- [ost-startStop-1] o.s.b.c.embedded.FilterRegistrationBean : Mapping filter: 'httpPutFormContentFilter' to: [/*]
2016-04-08 15:21:46.349 INFO 20400 --- [ost-startStop-1] o.s.b.c.embedded.FilterRegistrationBean : Mapping filter: 'requestContextFilter' to: [/*]
2016-04-08 15:21:46.439 INFO 20400 --- [ main] o.s.c.w.DefaultContextLoadTimeWeaver : Found Spring's JVM agent for instrumentation
2016-04-08 15:21:46.455 INFO 20400 --- [ main] o.s.c.w.DefaultContextLoadTimeWeaver : Found Spring's JVM agent for instrumentation
[LaunchedURLClassLoader@6d8a00e3] warning javax.* types are not being woven because the weaver option '-Xset:weaveJavaxPackages=true' has not been specified
2016-04-08 15:21:46.781 INFO 20400 --- [ main] s.w.s.m.m.a.RequestMappingHandlerAdapter : Looking for @ControllerAdvice: org.springframework.boot.context.embedded.AnnotationConfigEmbeddedWebApplicationContext@2cd72cea:
startup date [Fri Apr 08 15:21:44 BRT 2016]; root of context hierarchy
2016-04-08 15:21:46.874 INFO 20400 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped "{[/]}" onto public int com.test.configuration.AspectConfig.get()
2016-04-08 15:21:46.877 INFO 20400 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped "{[/error]}" onto public org.springframework.http.ResponseEntity<java.util.Map<java.lang.String, java.lang.Object>> org.sp
ringframework.boot.autoconfigure.web.BasicErrorController.error(javax.servlet.http.HttpServletRequest)
2016-04-08 15:21:46.878 INFO 20400 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped "{[/error],produces=[text/html]}" onto public org.springframework.web.servlet.ModelAndView org.springframework.boot.autoco
nfigure.web.BasicErrorController.errorHtml(javax.servlet.http.HttpServletRequest)
2016-04-08 15:21:46.912 INFO 20400 --- [ main] o.s.w.s.handler.SimpleUrlHandlerMapping : Mapped URL path [/webjars/**] onto handler of type [class org.springframework.web.servlet.resource.ResourceHttpRequestHandler]
2016-04-08 15:21:46.912 INFO 20400 --- [ main] o.s.w.s.handler.SimpleUrlHandlerMapping : Mapped URL path [/**] onto handler of type [class org.springframework.web.servlet.resource.ResourceHttpRequestHandler]
2016-04-08 15:21:47.030 INFO 20400 --- [ main] o.s.w.s.handler.SimpleUrlHandlerMapping : Mapped URL path [/**/favicon.ico] onto handler of type [class org.springframework.web.servlet.resource.ResourceHttpRequestHandler
]
2016-04-08 15:21:47.133 INFO 20400 --- [ main] o.s.j.e.a.AnnotationMBeanExporter : Registering beans for JMX exposure on startup
2016-04-08 15:21:47.204 INFO 20400 --- [ main] s.b.c.e.t.TomcatEmbeddedServletContainer : Tomcat started on port(s): 8080 (http)
2016-04-08 15:21:47.210 INFO 20400 --- [ main] com.test.Application : Started Application in 3.481 seconds (JVM running for 4.306)
2016-04-08 15:21:51.680 INFO 20400 --- [nio-8080-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring FrameworkServlet 'dispatcherServlet'
2016-04-08 15:21:51.680 INFO 20400 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet : FrameworkServlet 'dispatcherServlet': initialization started
2016-04-08 15:21:51.704 INFO 20400 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet : FrameworkServlet 'dispatcherServlet': initialization completed in 23 ms
com.test.classes.TestClass.methodFromClass1 - Starting execution
com.test.classes.TestClass.methodFromClass1 - Ending execution [15 ms]
As you can see, TestClass2 is never logged, although it's called. What am I missing here?
The real question is, how can I make non-beans to be handled by LTW in a SpringBoot environment? Feel free to commit changes on the repository I provided above.
