NullPointerException from FStringEqual.hashCode

[jchobantonov]

Environment
Java web application using jruby-complete as jar file in war's WEB-INF/lib and using embedded jruby mode

• Windows 10
• Apache Tomcat/8.5.35
• Java version:
  openjdk 13.0.1 2019-10-15
  OpenJDK Runtime Environment AdoptOpenJDK (build 13.0.1+9)
  Eclipse OpenJ9 VM AdoptOpenJDK (build openj9-0.17.0, JRE 13 Windows 10 amd64-64-Bit Compressed References 20191031_97 (JIT enabled, AOT enabled)
  OpenJ9 - 77c1cf708
  OMR - 20db4fbc
  JCL - c973c65658 based on jdk-13.0.1+9)

Provide at least:

• JRuby version : 9.2.9.0 as obtained from here https://mvnrepository.com/artifact/org.jruby/jruby-complete/9.2.9.0 ( JRUBY_OPTS = -J-XX:+CMSClassUnloadingEnabled -J-XX:+UseConcMarkSweepGC -J-XX:PermSize=500m -J-XX:MaxPermSize=1024m -J-Xmx1g -J-Djruby.objectspace.enabled=false)
• Operating system and platform : Windows 10

Other relevant info you may wish to add:

• During Tomcat server stop using Ctrl+C to stop it Tomcat dump exception from thread leaks detector

Expected Behavior

• No NullPointerException to occur

Actual Behavior

• NullPointerException occur during Tomcat stop using Ctrl+C:
  Stacktrace:

2020-01-15 11:15:05.598 WARNING [localhost-startStop-2] org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks Unable to determine string representation of value of type [org.jruby.Ruby.FStringEqual]
 java.lang.NullPointerException
        at org.jruby.Ruby$FStringEqual.hashCode(Ruby.java:4860)
        at java.base/java.lang.Object.toString(Object.java:164)
        at org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks(WebappClassLoaderBase.java:1981)
        at org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalsForLeaks(WebappClassLoaderBase.java:1907)
        at org.apache.catalina.loader.WebappClassLoaderBase.clearReferences(WebappClassLoaderBase.java:1577)
        at org.apache.catalina.loader.WebappClassLoaderBase.stop(WebappClassLoaderBase.java:1518)
        at org.apache.catalina.loader.WebappLoader.stopInternal(WebappLoader.java:446)
        at org.apache.catalina.util.LifecycleBase.stop(LifecycleBase.java:226)
        at org.apache.catalina.core.StandardContext.stopInternal(StandardContext.java:5514)
        at org.apache.catalina.util.LifecycleBase.stop(LifecycleBase.java:226)
        at org.apache.catalina.core.ContainerBase$StopChild.call(ContainerBase.java:1439)
        at org.apache.catalina.core.ContainerBase$StopChild.call(ContainerBase.java:1428)
        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
        at java.base/java.lang.Thread.run(Thread.java:831)

[headius]

This would be caused if the string field in FStringEqual is null. That could only happen if a null string were passed into Ruby#freezeAndDedupString, which would certainly constitute a bug.

Questions for you:

• Does this happen consistently?
• Could you push a small example app somewhere that triggers this error?
• Would you be able to test with custom JRuby build, so we could add some null checks and track down how this is happening?

[headius]

We may also see more information if you run with assertions enabled at the JVM level, e.g. -ea flag passed to java.

[jchobantonov]

It is happening each time when I stop Tomcat server - I do not even hit the application that will trigger ruby evaluation, so in my testing the ruby code in the web application should not matter - I just package jruby-complete into war file and deploy this under Tomcat 8.5 with options to detect memory leaks - once the server is started up I just kill the server using Ctrl+C and during the tomcat stop this exception is displaying in the tomcat console as stacktrace exception

Also during the startup following warnings are displayed:

WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access by com.headius.backport9.modules.Modules (file:/C:/dev/tomcat-jdk13/webapps/xxx/WEB-INF/lib/jruby-complete-9.2.9.0.jar) to method sun.nio.ch.NativeThread.signal(long)
WARNING: Please consider reporting this to the maintainers of com.headius.backport9.modules.Modules
WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
WARNING: All illegal access operations will be denied in a future release

[jchobantonov]

if I use --illegal-access=warn I do get one more warning regards NativeThread.current() :

WARNING: Illegal reflective access by com.headius.backport9.modules.Modules (file:/C:/dev/tomcat-jdk13/webapps/xxx/WEB-INF/lib/jruby-complete-9.2.9.0.jar) to method sun.nio.ch.NativeThread.signal(long)
WARNING: Illegal reflective access by com.headius.backport9.modules.Modules (file:/C:/dev/tomcat-jdk13/webapps/xxx/WEB-INF/lib/jruby-complete-9.2.9.0.jar) to method sun.nio.ch.NativeThread.current()

[headius]

The warnings are unrelated to the error. They're from Java modules and are only informational (but we're slowly getting rid of them).

I was able to reproduce this issue by setting the DEDUP_WRAPPER_CACHE field public in org.jruby.Ruby and running the following code:

2.times { JRuby.runtime.freezeAndDedupString("blah") };
p JRuby.runtime.DEDUP_WRAPPER_CACHE.get.hash

This is not really a bug in JRuby. We use this thread-local cache to store a string wrapper used for looking up a Ruby string while considering both its byte content and its encoding. It's perfectly valid for the thread-local to contain such a wrapper with its string set to null, because we always populate it with a string before using it.

Tomcat's aggressive thread-local leak detector actively searches for objects in thread-local storage, and upon finding one it tries to print out information about that object. In this case, that means calling hashCode and since the string field is null it blows up.

Had Tomcat not been digging around in our thread-locals, this error would never have happened.

In any case, I will fix this by making vacated wrappers silently return 0 for hashCode and false for equals so there won't be any errors in the future.

[jchobantonov]

thanks @headius