bytebuddy with aop in springboot not work

Question

I tried to use bytebuddy to implement aop in springboot. Code as below:

package klordy.learning.annotation;
@Target(METHOD)
@Retention(RUNTIME)
@Documented
public @interface CostTime {
}

package klordy.learning.agent;
public class Agent {
private static Agent instance = new Agent();
    private Logger logger = LoggerFactory.getLogger(Agent.class);
    private Agent() {}
    public static Agent getInstance(){ return instance; }
    public void install() {
        ByteBuddyAgent.install();
        AgentBuilder.Listener listener = new AgentBuilder.Listener() {
            // do nothing
            ...
        };

        new AgentBuilder.Default()
                .type(ElementMatchers.nameStartsWith("klordy.learning"))
                .transform((builder, typeDescription, classLoader, module) ->
                        builder.visit(Advice.to(TimeAdvice.class).on(ElementMatchers.isAnnotatedWith(named("klordy.learning.annotation.CostTime")))))
                .with(listener)
                // *** added as supposed, but still seems not work.
                .with(AgentBuilder.RedefinitionStrategy.RETRANSFORMATION)
                .installOnByteBuddyAgent();
         logger.info("byte buddy modification done.");
     }
}

public class TimeAdvice {
    @Advice.OnMethodEnter
    static long enter(@Advice.AllArguments Object args[], @Advice.Origin Method method){
        return System.currentTimeMillis();
    }

    @Advice.OnMethodExit
    static void exit(@Advice.Enter long startTime,
                     @Advice.Return(typing = Assigner.Typing.DYNAMIC) Object result,
                     @Advice.Origin Method method,
                     @Advice.Thrown Throwable throwable){
        if(throwable != null){
            System.out.println("error func " + System.currentTimeMillis());
        }else {
            System.out.println("func takes " + (System.currentTimeMillis() - startTime));
        }
    }
}

Listener of springboot as below:

public class AppEnvListener implements ApplicationListener<ApplicationEnvironmentPreparedEvent> {
    private Logger logger = LoggerFactory.getLogger(AppEnvListener.class);
    @Override
    public void onApplicationEvent(ApplicationEnvironmentPreparedEvent applicationEnvironmentPreparedEvent) {
        Agent.getInstance().install();
        logger.info("finished byte buddy installation.");
    }
}

At last, register listener in springboot startup:

@SpringBootApplication
@ComponentScan(basePackages = "klordy.learning")
public class SpringBootDemoApplication {

    public static void main(String[] args) {
       SpringApplication application = new SpringApplication(SpringBootDemoApplication.class);
       // register listener
       application.addListeners(new AppEnvListener());
       application.run(args);
    }
}

As I start up the application, debug logger showed fine. However, the aop does not work when request is processed. What am I doing wrong? I am confused...

Answer 1

Okay, I think I found your problem by recreating your situation with Spring Boot. It would happen without Spring too, though. Basically you hit this problem.

So if you modify your advice to @Advice.OnMethodExit(onThrowable = Throwable.class), you should be fine. You also should add .disableClassFormatChanges() to your agent, BTW. It helps avoid problems retransforming previously loaded classes. The JVM requires them not to be changed structurally.

How did I find out what was happening? I activated console logging in ByteBuddy. Previously I had used your listener, making it log every action, so I could see that BB in fact was getting triggered. But BB logging really showed the exceptions due to your wrong usage of @Advice.Thrown (without onThrowable = Throwable.class in the advice annotation).

public void install() {
  ByteBuddyAgent.install();
  new AgentBuilder.Default()
    .disableClassFormatChanges()
    .with(RETRANSFORMATION)
    .with(AgentBuilder.RedefinitionStrategy.Listener.StreamWriting.toSystemError())
    .with(AgentBuilder.Listener.StreamWriting.toSystemError().withTransformationsOnly())
    .with(AgentBuilder.InstallationListener.StreamWriting.toSystemError())
    .type(ElementMatchers.nameStartsWith("klordy.learning"))
    .transform((builder, typeDescription, classLoader, module) ->
      builder.visit(
        Advice
          .to(TimeAdvice.class)
          .on(isAnnotatedWith(named("klordy.learning.annotation.CostTime")))
      )
    )
    .installOnByteBuddyAgent();
  logger.info("byte buddy modification done.");
}