IncompatibleClassChangeError when instrumenting running SpringBoot application with Byte Buddy

Question

I would like to introduce Byte Buddy to my company and I have prepared a demo for my colleagues. Since we use Spring a lot, I thought the best example would be instrumentation of SpringBoot application. I have decided to add logs to RestController methods.

Instrumented application is a simple SpringBoot Hello World example:

@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");
  }
}

And here is my Byte Buddy agent:

public class LoggingAgent {
    public static void premain(String agentArguments,
            Instrumentation instrumentation) {
        install(instrumentation);
    }

    public static void agentmain(String agentArguments,
            Instrumentation instrumentation) {
        install(instrumentation);
    }

    private static void install(Instrumentation instrumentation) {
        createAgent(RestController.class, "greeting")
                .installOn(instrumentation);
    }

    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:

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());
    }
}

When executed with -javaagent parameter this example works well. When however I try to load the agent on the running JVM with Attach API:

VirtualMachine vm = VirtualMachine.attach(args[0]);
vm.loadAgent(args[1]);
vm.detach();

I've got the following exception on the first logging attempt:

Exception in thread "ContainerBackgroundProcessor[StandardEngine[Tomcat]]" java.lang.IncompatibleClassChangeError: Class ch.qos.logback.classic.spi.ThrowableProxy does not implement the requested interface ch.qos.logback.classic.spi.IThrowableProxy
    at ch.qos.logback.classic.pattern.ThrowableProxyConverter.subjoinExceptionMessage(ThrowableProxyConverter.java:180)
    at ch.qos.logback.classic.pattern.ThrowableProxyConverter.subjoinFirstLine(ThrowableProxyConverter.java:176)
    at ch.qos.logback.classic.pattern.ThrowableProxyConverter.recursiveAppend(ThrowableProxyConverter.java:159)
    at ch.qos.logback.classic.pattern.ThrowableProxyConverter.throwableProxyToString(ThrowableProxyConverter.java:151)
    at org.springframework.boot.logging.logback.ExtendedWhitespaceThrowableProxyConverter.throwableProxyToString(ExtendedWhitespaceThrowableProxyConverter.java:35)
    at ch.qos.logback.classic.pattern.ThrowableProxyConverter.convert(ThrowableProxyConverter.java:145)
    at ch.qos.logback.classic.pattern.ThrowableProxyConverter.convert(ThrowableProxyConverter.java:1)
    at ch.qos.logback.core.pattern.FormattingConverter.write(FormattingConverter.java:36)
    at ch.qos.logback.core.pattern.PatternLayoutBase.writeLoopOnConverters(PatternLayoutBase.java:114)
    at ch.qos.logback.classic.PatternLayout.doLayout(PatternLayout.java:141)
    at ch.qos.logback.classic.PatternLayout.doLayout(PatternLayout.java:1)
    at ch.qos.logback.core.encoder.LayoutWrappingEncoder.doEncode(LayoutWrappingEncoder.java:130)
    at ch.qos.logback.core.OutputStreamAppender.writeOut(OutputStreamAppender.java:187)
    at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:212)
    at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:100)
    at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84)
    at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:48)
    at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)
    at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)
    at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421)
    at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:383)
    at ch.qos.logback.classic.Logger.log(Logger.java:765)
    at org.slf4j.bridge.SLF4JBridgeHandler.callLocationAwareLogger(SLF4JBridgeHandler.java:221)
    at org.slf4j.bridge.SLF4JBridgeHandler.publish(SLF4JBridgeHandler.java:303)
    at java.util.logging.Logger.log(Unknown Source)
    at java.util.logging.Logger.doLog(Unknown Source)
    at java.util.logging.Logger.logp(Unknown Source)
    at org.apache.juli.logging.DirectJDKLog.log(DirectJDKLog.java:181)
    at org.apache.juli.logging.DirectJDKLog.error(DirectJDKLog.java:147)
    at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1352)
    at java.lang.Thread.run(Unknown Source)

I run the example on 64-bit HotSpot with Java8:

java version "1.8.0_112"
Java(TM) SE Runtime Environment (build 1.8.0_112-b15)
Java HotSpot(TM) 64-Bit Server VM (build 25.112-b15, mixed mode)

Byte Buddy version is 1.4.32. Here is agent maven configuration:

<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>pl.halun.demo.bytebuddy</groupId>
<artifactId>byte-buddy-agent-demo</artifactId>
<version>1.0</version>

<properties>
    <jdk.version>1.8</jdk.version>
    <project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
</properties>

<parent>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-parent</artifactId>
    <version>1.4.1.RELEASE</version>
</parent>

<dependencies>
    <dependency>
        <groupId>net.bytebuddy</groupId>
        <artifactId>byte-buddy</artifactId>
        <version>1.4.32</version>
    </dependency>
    <dependency>
        <groupId>ch.qos.logback</groupId>
        <artifactId>logback-classic</artifactId>
    </dependency>
    <dependency>
        <groupId>org.springframework.boot</groupId>
        <artifactId>spring-boot-starter-web</artifactId>
    </dependency>
    <dependency>
        <groupId>javax.servlet</groupId>
        <artifactId>javax.servlet-api</artifactId>
        <scope>provided</scope>
    </dependency>
</dependencies>
<build>
    <plugins>
        <plugin>
            <groupId>org.apache.maven.plugins</groupId>
            <artifactId>maven-compiler-plugin</artifactId>
            <configuration>
                <source>${jdk.version}</source>
                <target>${jdk.version}</target>
            </configuration>
        </plugin>
        <plugin>
            <groupId>org.apache.maven.plugins</groupId>
            <artifactId>maven-assembly-plugin</artifactId>
            <configuration>
                <descriptorRefs>
                    <descriptorRef>jar-with-dependencies</descriptorRef>
                </descriptorRefs>
                <finalName>${project.artifactId}-${project.version}-full</finalName>
                <appendAssemblyId>false</appendAssemblyId>
                <archive>
                    <manifestEntries>
                        <Premain-Class>pl.halun.demo.bytebuddy.logging.LoggingAgent</Premain-Class>
                        <Agent-Class>pl.halun.demo.bytebuddy.logging.LoggingAgent</Agent-Class>
                        <Can-Redefine-Classes>true</Can-Redefine-Classes>
                        <Can-Retransform-Classes>true</Can-Retransform-Classes>
                        <Can-Set-Native-Method-Prefix>true</Can-Set-Native-Method-Prefix>
                    </manifestEntries>
                </archive>
            </configuration>
            <executions>
                <execution>
                    <id>assemble-all</id>
                    <phase>package</phase>
                    <goals>
                        <goal>single</goal>
                    </goals>
                </execution>
            </executions>
        </plugin>
    </plugins>
</build>

And here is pom file for the instrumented application:

<?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>pl.halun.demo.bytebuddy.instrumented.app</groupId>
<artifactId>byte-buddy-agent-demo-instrumented-app</artifactId>
<version>1.0</version>
<packaging>jar</packaging>

<parent>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-parent</artifactId>
    <version>1.4.1.RELEASE</version>
</parent>

<dependencies>
    <dependency>
        <groupId>org.springframework.boot</groupId>
        <artifactId>spring-boot-starter-web</artifactId>
    </dependency>
</dependencies>

<properties>
    <java.version>1.8</java.version>
</properties>

<build>
    <plugins>
        <plugin>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-maven-plugin</artifactId>
        </plugin>
    </plugins>
</build>

<repositories>
    <repository>
        <id>spring-releases</id>
        <url>https://repo.spring.io/libs-release</url>
    </repository>
</repositories>
<pluginRepositories>
    <pluginRepository>
        <id>spring-releases</id>
        <url>https://repo.spring.io/libs-release</url>
    </pluginRepository>
</pluginRepositories>

From my point of view it is very valuable option to add logs on the running server and I hate to loose this part of demo. I tried to experiment with different redefinition strategies, but until now nothing seems to work.

Answer 1

What you observe is a classical version conflict, I think. Spring Boot most likely comes with a version of ThrowableProxy that is not compatible to the version that is added with the Java agent. When loading a Java agent at runtime, Spring's version is already loaded whereas the startup attachment prepends the agent-bundled version on the class path where the version of your agent is loaded.

Java agents are typically added to the class path. This is also where your Spring boot application is living. You need to make sure that a Java agent does not contain dependencies that are incompatible with your application's dependencies or you need to shade all dependencies to avoid such conflicts.

There is however another problem: When writing a Java agent that is attached at runtime, you meet additional constraints on most JVMs where on HotSpot, you are not allowed to change the class file format of any class that is already loaded. There is also a chance that your class is already loaded where currently, no effect would be visible as you do not enable retransformation.

A runtime-capable agent would need to use the Advice component which inlines code into target code rather then using the classical delegation model:

class MyAdvice {
  @Advice.OnMethodEnter
  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());
    }
  }
}

You can use the above advice class by registering it as a visitor. Such visitors only apply to declared methods, i.e. not to inherited methods and inline their code into existing methods. This way, the logging will not be visible on the call stack and it also becomes legal to retransform already loaded classes:

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

As for the attachment, look into the byte-buddy-agent project which allows you to call:

ByteBuddyAgent.attach(agentJar, processId);

The above helper supports other VMs where the attachment API often lives in a different namespace.

Update: Here is the problem with Spring Boot. Spring Boot creates custom class loaders that have the system class loader (class path) as their parent. These class loaders consider classes from the system class loader first. When you add the agent, the entire Spring boot app is both on the class loader and in these child class loaders. A class like IThrowableProxy now exists twice in two class loaders but is not considered to be equal by the JVM. Depending on the state of the VM, some classes might already be linked to the original IThrowableProxy whereas other classes are loaded after the agent was attached and get linked to the new IThrowableProxy from the agent. Both classes are not equal and the error that you see is thrown where the VM complains that the class does not implement the correct IThrowableProxy (but the previous one). If the agent is attached at start up, this problem does not exist as the class path's IThrowableProxy is always loaded.

This is not an easy error to fix, in the end, Byte Buddy cannot help you with such class path issues and Spring Boot is quite free in its interpretation of the class loader contract. The easiest way would be to not use Spring Boot types in your agent. You can still match the annotation with for example

isAnnotatedWith(named("org.springframework.web.bind.annotation.RestController"))

The question is how you can communicate with Spring Boot. One work-arround would be to add all shared classes to the class path on start up. Typically, I do avoid the usage of shared classes altogether but only use them in the Advice classes where the code is inlined in the class loader of the target application. Simply set the Spring Boot dependency in provided scope, the advice code itself is never executed.