"Bad constant pool" errors when running concurrently

[szeiger]

We're invoking MiMa from the Scala build: https://github.com/szeiger/scala/blob/3727c211806a6d462e5168372e2601dd959ce050/project/MiMa.scala. This is done by directly calling the CLI's Main.main, which in turn creates a new instance of MiMa.

When two instances run in parallel (on two different projects), they frequently fail with errors "bad constant pool errors" such as

[error] (run-main-1) java.lang.RuntimeException: bad constant pool tag 7 at byte 10
java.lang.RuntimeException: bad constant pool tag 7 at byte 10
    at com.typesafe.tools.mima.core.ClassfileParser$ConstantPool.errorBadTag(ClassfileParser.scala:204)
    at com.typesafe.tools.mima.core.ClassfileParser$ConstantPool.getName(ClassfileParser.scala:117)
    at com.typesafe.tools.mima.core.ClassfileParser.parseMember(ClassfileParser.scala:237)
    at com.typesafe.tools.mima.core.ClassfileParser$$anonfun$parseMembers$1.apply(ClassfileParser.scala:223)
    at com.typesafe.tools.mima.core.ClassfileParser$$anonfun$parseMembers$1.apply(ClassfileParser.scala:218)
    at scala.collection.immutable.Range.foreach(Range.scala:141)
    at com.typesafe.tools.mima.core.ClassfileParser.parseMembers(ClassfileParser.scala:218)
    at com.typesafe.tools.mima.core.ClassfileParser.parseMethods(ClassfileParser.scala:212)
    at com.typesafe.tools.mima.core.ClassfileParser.parseClass(ClassfileParser.scala:262)
    at com.typesafe.tools.mima.core.ClassfileParser.parseAll(ClassfileParser.scala:68)
    at com.typesafe.tools.mima.core.ClassfileParser.parse(ClassfileParser.scala:59)
    at com.typesafe.tools.mima.core.ClassInfo.ensureLoaded(ClassInfo.scala:86)
    at com.typesafe.tools.mima.core.ClassInfo.methods(ClassInfo.scala:101)
    at com.typesafe.tools.mima.core.ClassInfo$$anonfun$lookupClassMethods$2.apply(ClassInfo.scala:123)
    at com.typesafe.tools.mima.core.ClassInfo$$anonfun$lookupClassMethods$2.apply(ClassInfo.scala:123)
[...]

See https://scala-ci.typesafe.com/job/scala-2.11.x-validate-test/1978/console for a complete log.

This does not happen when only once instance of MiMa runs at a time.

[dwijnand]

I wonder if concurrency is also the cause of #112

[dotta]

I guess one possible workaround could be to use separate classloaders.

[JoshRosen]

I managed to make a bit of headway in investigating this and think that I may have spotted one potential source of thread-unsafety.

I added some additional logging in ClassFileParser to print more details when an error occurs:

diff --git a/core/src/main/scala/com/typesafe/tools/mima/core/ClassfileParser.scala b/core/src/main/scala/com/typesafe/tools/mima/core/ClassfileParser.scala
index fb8c960..d18760c 100644
--- a/core/src/main/scala/com/typesafe/tools/mima/core/ClassfileParser.scala
+++ b/core/src/main/scala/com/typesafe/tools/mima/core/ClassfileParser.scala
@@ -58,7 +58,8 @@ abstract class ClassfileParser(definitions: Definitions) {
     try {
       parseAll(clazz)
     } catch {
-      case e: RuntimeException => handleError(e)
+      case e: RuntimeException =>
+        handleError(new RuntimeException("Got exception while processing " + clazz.file.name + " with " + this, e))
     }
   }

When running this on Spark's build, I managed to hit the following failure:

[error] (mllib-local/*:mimaFindBinaryIssues) Got exception while processing Object.class with com.typesafe.tools.mima.core.LibClassfileParser@3812664d
[error] (launcher/*:mimaFindBinaryIssues) Got exception while processing Object.class with com.typesafe.tools.mima.core.LibClassfileParser@3812664d

As you can see from these logs, it looks like the same LibClassFileParser instance is being used in both builds and instances of ClassfileParser are not thread-safe because they contain unsynchronized mutable state.

A common pattern in the failures that I've seen is that they all seem to involve Object.class. For example, another failure that I've seen in concurrent runs is

[error] (launcher/*:mimaFindBinaryIssues) java.io.IOException: class file '/Library/Java/JavaVirtualMachines/jdk1.8.0_66.jdk/Contents/Home/jre/lib/rt.jar(java/lang/Object.class)' has wrong magic number 0xfebabe00, should be 0xcafebabe

It looks like there's a global ClassInfo.ObjectClass object, which, in turn, references the global Config.baseDefinitions, which has a ClassFileParser. This ClassInfo.ObjectClass can be referenced as a superclass when parsing other ClassInfo objects. After adding a bit of additional logging around the construction of this global ClassInfo.ObjectClass object, I managed to trigger the failure again and it seems that this is indeed is the source of the problematic shared ClassFileParser.

It seems like a simple fix might be to just add synchronized to ClassFileParser.parse, which appears to be the only method that's called from outside of that class itself.

[SethTisue]

optimistically closing on the assumption #129 fixed it