Saturday, November 5, 2016

Instrumentation of Spring Boot application with Byte Buddy

I'd like to introduce Byte Buddy to my company and I've prepared a demo for my colleagues. We use Spring a lot, so I thought the best example would be instrumentation of Spring Boot application. For the purpose of demonstration I have added logs to RestController methods using Java Agent.

Instrumented application is a Spring Boot's Hello World example enhanced with one additional method for printing user agent information:

@RestController
public class HelloController {

    private static final String template = "Hello, %s!";

    @RequestMapping("/hello")
    public String greeting(
            @RequestParam(value = "name", defaultValue = "World") String name) {
        return String.format(template, name);
    }

    @RequestMapping("/browser")
    public String showUserAgent(HttpServletRequest request) {
        return request.getHeader("user-agent");
    }

}

At first I've written an agent that uses method delegation to interceptor class and then executes original method implementation:

private static AgentBuilder createAgent(Class<? extends Annotation> annotationType,
        String methodName) {
    return new AgentBuilder.Default().type(
        ElementMatchers.isAnnotatedWith(annotationType)).transform(
            new AgentBuilder.Transformer() {
                @Override
                public DynamicType.Builder<?> transform(
                        DynamicType.Builder<?> builder,
                        TypeDescription typeDescription,
                        ClassLoader classLoader) {
                    return builder
                        .method(ElementMatchers.named(methodName))
                        .intercept(MethodDelegation
                                        .to(LoggingInterceptor.class)
                                        .andThen(SuperMethodCall.INSTANCE));
                }
            }
        );
}

Interceptor logs method execution and its parameters:

public static void intercept(@AllArguments Object[] allArguments,
        @Origin Method method) {
    Logger logger = LoggerFactory.getLogger(method.getDeclaringClass());
    logger.info("Method {} of class {} called", method.getName(), method
            .getDeclaringClass().getSimpleName());

    for (Object argument : allArguments) {
        logger.info("Method {}, parameter type {}, value={}",
                method.getName(), argument.getClass().getSimpleName(),
                argument.toString());
    }
}

To successfully run the agent I had to correct dependencies first. I have added spring-boot-starter-parent as agent's parent, same as for the instrumented application. Later it turned out to be a mistake, but as it was, the agent successfully loaded from command line with -javaagent parameter and added logs to HelloController's methods.

Problems began when I tried to connect to a running VM with Attach API to instrument already loaded application. Attempts to use the logger after the instrumentation caused IncompatibleClassChangeError with message „ch.qos.logback.classic.spi.ThrowableProxy does not implement the requested interface ch.qos.logback.classic.spi.IThrowableProxy”.

That seemed strange for me since both projects use the same version of spring-boot-starter-parent as parent, with the same version of Logback Classic. There was no other dependency which could introduce incompatible version of ThrowableProxy.

After a few unsuccessful attempts to solve the problem I have asked a question on Stack Overlflow. You can read the comprehensive answer by Rafael Winterhalter, the creator of Byte Buddy, on the question page. Briefly, the problem lies within custom class loaders used by Spring Boot. After adding the agent ThrowableProxy (and several other classes) exists twice in two class loaders. Those copies are not considered to be equal by the JVM.

It turned out that my implementation couldn't work with live Spring Boot application. First, I had to remove dependencies to Spring Boot from my agent. For that purpose I abandoned the idea of matching the class by its annotation:

type(ElementMatchers.isAnnotatedWith(RestController.class))

matching to a class name instead:

type(ElementMatchers.named(
  "pl.halun.demo.bytebuddy.instrumented.app.HelloController"))

Therefore I could remove Spring Boot dependencies from agent project, leaving only provided Logback Classic:

<dependency>
  <groupId>ch.qos.logback</groupId>
  <artifactId>logback-classic</artifactId>
  <version>1.1.7</version>
  <scope>provided</scope>
</dependency>

Rafael pointed out that I have made another mistake. If I'm going to attach my agent to a running Virtual Machine, I'm not allowed to change the class file format of any class that is already loaded. So, I had to give up on delegation model and interceptors, and use instead the Advice component which inlines code into target.

Finally, that is my agent working both from command line parameter and Attach API:

return new AgentBuilder.Default().disableClassFormatChanges()
    .with(AgentBuilder.RedefinitionStrategy.RETRANSFORMATION)
    .type(named(className))
    .transform(new AgentBuilder.Transformer() {
    
    @Override
    public DynamicType.Builder<?> transform(
        DynamicType.Builder<?> builder, TypeDescription typeDescription,
        ClassLoader classLoader) {
            return builder.visit(Advice.to(LoggingAdvice.class).on(
                    named(methodName)));
        }
});

Interceptor has been changed into Advice:

public class LoggingAdvice {
    @Advice.OnMethodEnter
    public static void intercept(@Advice.BoxedArguments Object[] allArguments,
            @Advice.Origin Method method) {
        Logger logger = LoggerFactory.getLogger(method.getDeclaringClass());
        logger.info("Method {} of class {} called", method.getName(), method
                .getDeclaringClass().getSimpleName());

        for (Object argument : allArguments) {
            logger.info("Method {}, parameter type {}, value={}",
                    method.getName(), argument.getClass().getSimpleName(),
                    argument.toString());
        }
    }
}

Github sources:


No comments:

Post a Comment