javamavenherokuguavawebapp-runner

API calls to Heroku web-app running in webapp-runner eventually fail with NoSuchMethodError then NoClassDefFoundError in google.common

I am running a war on Heroku using webapp-runner. I deploy the application using the heroku-maven-plugin version 1.2 via the following command: mvn heroku:deploy-war. Initially, the app works and all endpoints return valid responses. However, if I allow the app to idle long enough for Heroku to put it to sleep and then invoke an endpoint which calls into guava I receive a NoSuchMethodError:

2017-09-23T19:19:45.388865+00:00 app[web.1]: SEVERE: Servlet.service() for servlet [jersey-serlvet] in context with path [] threw exception [org.glassfish.jersey.server.ContainerException: java.lang.NoSuchMethodError: com.google.common.base.CharMatcher.ascii()Lcom/google/common/base/CharMatcher;] with root cause
2017-09-23T19:19:45.388866+00:00 app[web.1]: java.lang.NoSuchMethodError: com.google.common.base.CharMatcher.ascii()Lcom/google/common/base/CharMatcher;
2017-09-23T19:19:45.388867+00:00 app[web.1]:    at com.google.common.io.BaseEncoding$Alphabet.<init>(BaseEncoding.java:453)
2017-09-23T19:19:45.388868+00:00 app[web.1]:    at com.google.common.io.BaseEncoding$Base64Encoding.<init>(BaseEncoding.java:892)
2017-09-23T19:19:45.388869+00:00 app[web.1]:    at com.google.common.io.BaseEncoding.<clinit>(BaseEncoding.java:317)
...application specific stack trace

All subsequent calls to the same API produce a NoClassDefFoundError at the same point

2017-09-23T19:22:24.454901+00:00 app[web.1]: SEVERE: Servlet.service() for servlet [jersey-serlvet] in context with path [] threw exception [org.glassfish.jersey.server.ContainerException: java.lang.NoClassDefFoundError: Could not initialize class com.google.common.io.BaseEncoding] with root cause
2017-09-23T19:22:24.454903+00:00 app[web.1]: java.lang.NoClassDefFoundError: Could not initialize class com.google.common.io.BaseEncoding 
...application specific stack trace

These issues seem to suggest that the guava jar is present at compile time but not present at runtime. However, I logged-in to the web dyno and verified that the guava jar was included in my warfile

my-mbp:TrickServer me$ heroku ps:exec
Establishing credentials... done
Connecting to web.1 on ⬢ myapp...
~ $ cd target/
~/target $ ls
MyApp.war  dependency  mvn-dependency-list.log  tomcat.52079
~/target $ jar -tf MyApp.war
...lots of dependencies...
WEB-INF/lib/google-oauth-client-1.20.0.jar
WEB-INF/lib/gson-2.2.4.jar
WEB-INF/lib/guava-23.0.jar      <---guava
WEB-INF/lib/guava-jdk5-13.0.jar
...lots more dependencies...

I am struggling to explain why the endpoints work immediately after the app is deployed but later produce these errors. To me this behavior seems to suggest that Heroku is potentially supplying a different classpath when my app wakes up from sleep than when it is initially run or that Heroku is moving/cleaning up the guava jarfile.

Contents of my Procfile:

web:    java $JAVA_OPTS -jar target/dependency/webapp-runner.jar --port $PORT --expand-war target/MyApp.war

Java Processes runnning on my web dyno:

~/target $ ps -ef | grep java
u30439       4     1  0 18:50 ?        00:00:44 java -Xmx300m -Xss512k -Dfile.encoding=UTF-8 -Duser.timezone=UTC -jar target/dependency/webapp-runner.jar --port 52079 target/MyApp.war
u30439      27     4  0 18:50 ?        00:00:00 bash --login -c java $JAVA_OPTS -jar target/dependency/webapp-runner.jar $WEBAPP_RUNNER_OPTS --port 52079 target/MyApp.war

Update 1

Since I am invoking my webapp with the --expand-war argument I also checked the jarfiles in the expanded directory to verify that guava was present. It is:

~/target/tomcat.55320/webapps/expanded/WEB-INF/lib $ ls
...dependencies...
google-oauth-client-1.20.0.jar
gson-2.2.4.jar
guava-23.0.jar
guava-jdk5-13.0.jar
...more dependencies...

Update 2

I added the following logic to the problematic web service to printout the classpath and the resources on it:

logger.info("System Classpath: " + System.getProperty("java.class.path"));
logger.info("Runtime Classes...");
    ClassLoader cl = UserService.class.getClassLoader();
    URL[] urls = ((URLClassLoader) cl).getURLs();
    for(URL url: urls){
        logger.info(url.getFile());
    }

The next time the error occurred I examined the logs and to my surprise found that the guava jar was present on the runtime classpath!

2017-09-24T12:07:40.843438+00:00 app[web.1]: [heroku-exec] ERROR: Could not connect to proxy:
2017-09-24T12:07:40.844145+00:00 app[web.1]: [heroku-exec] ERROR: Too many reconnect attempts. Waiting 30 seconds...
2017-09-24T12:07:52.671620+00:00 app[web.1]: Sep 24, 2017 12:07:52 PM org.myorg.server.web.services.MyService authenticate
2017-09-24T12:07:52.671631+00:00 app[web.1]: INFO: System Classpath: target/dependency/webapp-runner.jar
2017-09-24T12:07:52.671931+00:00 app[web.1]: Sep 24, 2017 12:07:52 PM org.myorg.server.web.services.MyService authenticate
2017-09-24T12:07:52.671932+00:00 app[web.1]: INFO: Runtime Classes...
2017-09-24T12:07:52.672277+00:00 app[web.1]: Sep 24, 2017 12:07:52 PM org.myorg.server.web.services.MyService authenticate
2017-09-24T12:07:52.672279+00:00 app[web.1]: INFO: /app/target/tomcat.28304/webapps/expanded/WEB-INF/classes/
....
2017-09-24T12:07:52.690304+00:00 app[web.1]: Sep 24, 2017 12:07:52 PM org.myorg.server.web.services.MyService authenticate
2017-09-24T12:07:52.690306+00:00 app[web.1]: INFO: /app/target/tomcat.28304/webapps/expanded/WEB-INF/lib/google-oauth-client-1.20.0.jar
2017-09-24T12:07:52.690501+00:00 app[web.1]: Sep 24, 2017 12:07:52 PM org.myorg.server.web.services.MyService authenticate
2017-09-24T12:07:52.690503+00:00 app[web.1]: INFO: /app/target/tomcat.28304/webapps/expanded/WEB-INF/lib/guava-23.0.jar <--- Guava!!!
....

What is going on here? How do I debug this?

Solution

  • After some debugging, I discovered that my program had two different versions of Guava on the classpath (guava-23.0.jar & guava-jdk5-13.0.jar). The debugging tip suggested here was necessary but not sufficient for me to get to the bottom of this.

    When working with ClassLoaders it's important to remember that the getClassLoader method defined in the .class object returns a reference to the ClassLoader that originally loaded the class. To find the duplicate jar, it was crucial to invoke classLoader.getResource("/com/google/common/base/CharMatcher.class") on the same ClassLoader which loaded the class that later failed with the NoSuchMethodError.

    For posterity, the specific dependency which caused the conflict was com.google.api-client. I resolved it by adding the following exclusion to the dependency in my pom.xml

    <dependency>
    <groupId>com.google.api-client</groupId>
    <artifactId>google-api-client</artifactId>
    <version>1.22.0</version>
    <exclusions>
        <exclusion>
            <groupId>com.google.guava</groupId>
            <artifactId>guava-jdk5</artifactId>
        </exclusion>
    </exclusions>
</dependency>