[Java] Assertion failure + JVM crash with rocksdbjni running under Tomcat

[archiecobbs]

Using rocksjni with a Java web application running in Tomcat, the JVM crashed with this log message:

Exception in thread "Thread-10" java.lang.NoClassDefFoundError: org/rocksdb/InfoLogLevel
Caused by: java.lang.ClassNotFoundException: org.rocksdb.InfoLogLevel
        at java.net.URLClassLoader$1.run(URLClassLoader.java:366)
        at java.net.URLClassLoader$1.run(URLClassLoader.java:355)
        at java.security.AccessController.doPrivileged(Native Method)
        at java.net.URLClassLoader.findClass(URLClassLoader.java:354)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:425)
        at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:308)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:358)
java: ./java/./rocksjni/portal.h:743: static _jclass* rocksdb::InfoLogLevelJni::getJClass(JNIEnv*): Assertion `jclazz != nullptr' failed.

Here's the relevant code:

    // Get the java class id of org.rocksdb.WBWIRocksIterator.WriteType.
    static jclass getJClass(JNIEnv* env) {
      jclass jclazz = env->FindClass("org/rocksdb/InfoLogLevel");
      if (jclazz == nullptr)
        env->ExceptionDescribe();
      assert(jclazz != nullptr);
      return jclazz;
    }

The class org/rocksdb/InfoLogLevel is certainly present, inside the rocksdbjni JAR file under WEB-INF/lib, so what's going on?

Here's my theory: as we all know Tomcat creates separate ClassLoaders for each web application. A web application's Java classes and library classes are not available from the system class loader; instead, you must find them using the loader that Tomcat has created for that web application.

Unfortunately, when rocksdb is setup by rocksdbjni and it wants to log something, it uses LoggerJniCallback::Logv(), which looks like this:

/**
 * Get JNIEnv for current native thread
 */
JNIEnv* LoggerJniCallback::getJniEnv() const {
  JNIEnv *env;
  jint rs = m_jvm->AttachCurrentThread(reinterpret_cast<void **>(&env), NULL);
  assert(rs == JNI_OK);
  return env;
}

...

void LoggerJniCallback::Logv(const InfoLogLevel log_level,
    const char* format, va_list ap) {
  if (GetInfoLogLevel() <= log_level) {
    JNIEnv* env = getJniEnv();

     ....

    }
    m_jvm->DetachCurrentThread();
  }
}

Note that the current thread is not associated with the JVM at all, which is why it has to put the call back into Java-land inside a AttachCurrentThread()/DetachCurrentThread() pair. But that means that the corresponding Java thread no longer has a same context class loader. So it defaults to the system class loader and so the attempt to load org/rocksdb/InfoLogLevel fails.

Suggested solution:

1. Upon creation of a new RocksDB instance, store a reference to the current thread's context class loader inside the native code.
2. Whenever the native code needs to load a class, invoke ClassLoader.findClass() directly using the saved loader reference.

[archiecobbs]

Commit b46b15b92d79301ad925d64f9d98c36b8d533ebf appears to fix this problem.

[igorcanadi]

@adamretter any thoughts on @archiecobbs 's fix?

[archiecobbs]

Updated with to latest master in 3b2aa14.

[adamretter]

@igorcanadi I should be able to look at this next week. Sorry for the delay I'm away at a conference

[adamretter]

@archiecobbs I think this recently merged PR may fix your issue: #1106

[archiecobbs]

Probably does. I'm not setup to test the fix right now but you can close this issue if you're confident about it. Thanks.

[adamretter]

@archiecobbs Without testing it on Tomcat I am not confident ;-)

[grooverdan]

Seems still here. Not every test run however.

Last Built Revision: Revision 6e3ee015fb1ce03e47838e9a3995410ce884c212 (Tue Jul 18 12:58:57 2017 -0700)

ibm-jdk - 8.0-4.7

+ CXXFLAGS='-m64 -O3 -g -I /opt/ibm/java/include/ -mtune=native -std=c++11'
+ g++-6 --version
g++-6 (Ubuntu/Linaro 6.3.0-18ubuntu2~16.04) 6.3.0 20170519
Copyright (C) 2016 Free Software Foundation, Inc.
This is free software; see the source for copying conditions.  There is NO
warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.

$ + make -j24 --output-sync=target DEBUG_LEVEL=2 V=1 'OPT=-DSNAPPY=1 -DLZ4=1 -DZLIB=1 -DJEMALLOC=1 -DZSTD=1 -DNUMA=1' jtest
make[1]: Leaving directory '/source/java'
make[1]: Entering directory '/source/java'
java -ea -Xcheck:jni -Djava.library.path=target -cp "target/classes:target/test-classes:test-libs/junit-4.12.jar:test-libs/hamcrest-core-1.3.jar:test-libs/mockito-all-1.10.19.jar:test-libs/cglib-2.2.2.jar:test-libs/assertj-core-1.7.1.jar:target/*" org.rocksdb.test.RocksJunitRunner org.rocksdb.BackupableDBOptionsTest org.rocksdb.BackupEngineTest org.rocksdb.BlockBasedTableConfigTest org.rocksdb.util.BytewiseComparatorTest org.rocksdb.CheckPointTest org.rocksdb.ClockCacheTest org.rocksdb.ColumnFamilyOptionsTest org.rocksdb.ColumnFamilyTest org.rocksdb.CompactionOptionsFIFOTest org.rocksdb.CompactionOptionsUniversalTest org.rocksdb.CompactionPriorityTest org.rocksdb.CompactionStopStyleTest org.rocksdb.ComparatorOptionsTest org.rocksdb.ComparatorTest org.rocksdb.CompressionOptionsTest org.rocksdb.CompressionTypesTest org.rocksdb.DBOptionsTest org.rocksdb.DirectComparatorTest org.rocksdb.DirectSliceTest org.rocksdb.EnvOptionsTest org.rocksdb.IngestExternalFileOptionsTest org.rocksdb.util.EnvironmentTest org.rocksdb.FilterTest org.rocksdb.FlushTest org.rocksdb.InfoLogLevelTest org.rocksdb.KeyMayExistTest org.rocksdb.LoggerTest org.rocksdb.LRUCacheTest org.rocksdb.MemTableTest org.rocksdb.MergeTest org.rocksdb.MixedOptionsTest org.rocksdb.MutableColumnFamilyOptionsTest org.rocksdb.NativeLibraryLoaderTest org.rocksdb.OptionsTest org.rocksdb.PlainTableConfigTest org.rocksdb.RateLimiterTest org.rocksdb.ReadOnlyTest org.rocksdb.ReadOptionsTest org.rocksdb.RocksDBTest org.rocksdb.RocksDBExceptionTest org.rocksdb.RocksEnvTest org.rocksdb.RocksIteratorTest org.rocksdb.RocksMemEnvTest org.rocksdb.util.SizeUnitTest org.rocksdb.SliceTest org.rocksdb.SnapshotTest org.rocksdb.SstFileWriterTest org.rocksdb.TransactionLogIteratorTest org.rocksdb.TtlDBTest org.rocksdb.StatisticsTest org.rocksdb.StatisticsCollectorTest org.rocksdb.WALRecoveryModeTest org.rocksdb.WriteBatchHandlerTest org.rocksdb.WriteBatchTest org.rocksdb.WriteBatchThreadedTest org.rocksdb.WriteOptionsTest org.rocksdb.WriteBatchWithIndexTest
JVMJNCK001I JNI check utility installed. Use -Xcheck:jni:help for usage
Run: org.rocksdb.BackupableDBOptionsTest testing now -> failSetSyncIfDisposed 
Run: org.rocksdb.BackupableDBOptionsTest testing now -> backupRateLimiter 
Run: org.rocksdb.BackupableDBOptionsTest testing now -> shareTableFiles 
...
...
...
Run: org.rocksdb.CheckPointTest testing now -> checkPoint 
Run: org.rocksdb.CheckPointTest testing now -> failIfDbNotInitialized 
Run: org.rocksdb.CheckPointTest testing now -> failWithIllegalPath 
java: ./java/./rocksjni/portal.h:60: static _jclass* rocksdb::JavaClass::getJClass(JNIEnv*, const char*): Assertion `jclazz != nullptr' failed.
JVMDUMP039I Processing dump event "abort", detail "" at 2017/07/19 00:55:42 - please wait.
JVMDUMP032I JVM requested System dump using '/source/java/core.20170719.005542.1854.0001.dmp' in response to an event
JVMDUMP010I System dump written to /source/java/core.20170719.005542.1854.0001.dmp
JVMDUMP032I JVM requested Java dump using '/source/java/javacore.20170719.005542.1854.0002.txt' in response to an event
JVMDUMP010I Java dump written to /source/java/javacore.20170719.005542.1854.0002.txt
JVMDUMP032I JVM requested Snap dump using '/source/java/Snap.20170719.005542.1854.0003.trc' in response to an event
JVMDUMP010I Snap dump written to /source/java/Snap.20170719.005542.1854.0003.trc
JVMDUMP007I JVM Requesting JIT dump using '/source/java/jitdump.20170719.005542.1854.0004.dmp'

#JITDUMP:  vmThread=00000000010C6800 Recursive crash occurred. Aborting JIT dump.JVMDUMP010I JIT dump written to /source/java/jitdump.20170719.005542.1854.0004.dmp
JVMDUMP013I Processed dump event "abort", detail "".
Makefile:226: recipe for target 'run_test' failed
make[1]: *** [run_test] Error 1
make[1]: Leaving directory '/source/java'
make[1]: *** Waiting for unfinished jobs....
make[1]: Entering directory '/source/java'
mkdir -p target/classes
javac -Xlint:deprecation -Xlint:unchecked -d target/classes\
	src/main/java/org/rocksdb/util/*.java\
	src/main/java/org/rocksdb/*.java
src/main/java/org/rocksdb/MutableColumnFamilyOptions.java:685: warning: [unchecked] unchecked cast
      return ((MutableColumnFamilyOptionEnumValue)value).asObject();
                                                     ^
  required: MutableColumnFamilyOptionEnumValue
  found:    MutableColumnFamilyOptionValue
  where T is a type-variable:
    T extends Enum declared in method getEnum(MutableColumnFamilyOptionKey)
  where CAP#1 is a fresh type-variable:
    CAP#1 extends Object from capture of ?
src/main/java/org/rocksdb/TtlDB.java:196: warning: [deprecation] finalize() in AbstractNativeReference has been deprecated
  @Override protected void finalize() throws Throwable {
                           ^
src/main/java/org/rocksdb/TtlDB.java:198: warning: [deprecation] finalize() in AbstractNativeReference has been deprecated
    super.finalize();
         ^
3 warnings
javah -cp target/classes -d ./include -jni org.rocksdb.AbstractCompactionFilter org.rocksdb.AbstractComparator org.rocksdb.AbstractSlice org.rocksdb.BackupEngine org.rocksdb.BackupableDBOptions org.rocksdb.BlockBasedTableConfig org.rocksdb.BloomFilter org.rocksdb.Checkpoint org.rocksdb.ClockCache org.rocksdb.CassandraValueMergeOperator org.rocksdb.ColumnFamilyHandle org.rocksdb.ColumnFamilyOptions org.rocksdb.CompactionOptionsFIFO org.rocksdb.CompactionOptionsUniversal org.rocksdb.Comparator org.rocksdb.ComparatorOptions org.rocksdb.CompressionOptions org.rocksdb.DBOptions org.rocksdb.DirectComparator org.rocksdb.DirectSlice org.rocksdb.Env org.rocksdb.EnvOptions org.rocksdb.FlushOptions org.rocksdb.Filter org.rocksdb.IngestExternalFileOptions org.rocksdb.HashLinkedListMemTableConfig org.rocksdb.HashSkipListMemTableConfig org.rocksdb.Logger org.rocksdb.LRUCache org.rocksdb.MergeOperator org.rocksdb.Options org.rocksdb.PlainTableConfig org.rocksdb.RateLimiter org.rocksdb.ReadOptions org.rocksdb.RemoveEmptyValueCompactionFilter org.rocksdb.RestoreOptions org.rocksdb.RocksDB org.rocksdb.RocksEnv org.rocksdb.RocksIterator org.rocksdb.RocksMemEnv org.rocksdb.SkipListMemTableConfig org.rocksdb.Slice org.rocksdb.SstFileWriter org.rocksdb.Statistics org.rocksdb.TransactionLogIterator org.rocksdb.TtlDB org.rocksdb.VectorMemTableConfig org.rocksdb.Snapshot org.rocksdb.StringAppendOperator org.rocksdb.WriteBatch org.rocksdb.WriteBatch.Handler org.rocksdb.WriteOptions org.rocksdb.WriteBatchWithIndex org.rocksdb.WBWIRocksIterator
make[1]: Leaving directory '/source/java'
Makefile:1669: recipe for target 'jtest' failed
make: *** [jtest] Error 2

[gfosco]

Closing this via automation due to lack of activity. If you'd like this to be re-opened, please just comment here and we'll open it back up.

[adamretter]

This looks like a sensible fix for the situation where custom class loaders are used and JNI Callbacks are made use of. As it stands this would need to be refactored. I think the current approach will incur too much performance overhead in the Logv callback method. We know that JNI is performance sensitive, so we should try to minimise any Java/C++ boundary-crosing work done in that method. I think we could pre-cache the log level objects, and that might be a reasonable compromise.