Fix JRuby embed crash after application reloading #4312

Merged
merged 1 commit into from Feb 24, 2017

Conversation

Projects
None yet
2 participants
@shirosaki
Contributor

shirosaki commented Nov 17, 2016

We use JRuby ScriptingContainer in a tomcat servlet web
application. After application reloading in tomcat, JRuby
runtime initialization fails with the error message.
"BUG: could not initialize constructor handle"

MethodHandles.publicLookup().findConstructor() fails with
IllegalAccessException in static initialization block.

The initialization does not work well with tomcat reloading.

As a workaround MethodHandles.lookup() without access check
works fine.

Fix JRuby embed crash after application reloading
We use JRuby `ScriptingContainer` in a tomcat servlet web
application.  After application reloading in tomcat, JRuby
runtime initialization fails with the error message.
"BUG: could not initialize constructor handle"

`MethodHandles.publicLookup().findConstructor()` fails with
`IllegalAccessException` in static initialization block.

The initialization does not work well with tomcat reloading.

As a workaround `MethodHandles.lookup()` without access check
works fine.
@shirosaki

This comment has been minimized.

Show comment
Hide comment
@shirosaki

shirosaki Nov 21, 2016

Contributor

Here is a test code for the issue.

With jruby-complete-9.1.6.0.jar, this fails with the following Exception.
With jruby-complete-1.7.26.jar, this succeeds.
java version "1.8.0_91"

import java.lang.reflect.Method;
import java.net.URL;
import java.net.URLClassLoader;

public class TestReload {
    public static void main(String[] args) {
        try {
            for (int i = 0; i < 2; i++) {
                // load class
                URLClassLoader loader = new URLClassLoader(new URL[] { 
                        new URL("jar:file:./jruby-complete.jar!/")
                    });
                Class<?> container = loader.loadClass("org.jruby.embed.ScriptingContainer");
                Method runScriptlet = container.getMethod("runScriptlet", String.class);
                Method setClassLoader = container.getMethod("setClassLoader", ClassLoader.class);
                Object c = container.newInstance();
                setClassLoader.invoke(c, loader);
                runScriptlet.invoke(c, "puts \"Hello World!\"");
                // unload class
                loader = null;
                c = null;
                System.gc();
            }
        } catch (Exception e) {
            e.printStackTrace();
        }
    }
}
$ java TestReload                                                                                                      
Hello World!                                                                                                           
java.lang.reflect.InvocationTargetException                                                                            
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)                                                 
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)                               
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)                       
        at java.lang.reflect.Method.invoke(Method.java:498)                                                            
        at TestReload.main(TestReload.java:18)                                                                         
Caused by: java.lang.ExceptionInInitializerError                                                                       
        at org.jruby.runtime.ThreadContext.<init>(ThreadContext.java:201)                                              
        at org.jruby.runtime.ThreadContext.newContext(ThreadContext.java:76)                                           
        at org.jruby.internal.runtime.ThreadService.initMainThread(ThreadService.java:166)                             
        at org.jruby.Ruby.init(Ruby.java:1238)                                                                         
        at org.jruby.Ruby.newInstance(Ruby.java:339)                                                                   
        at org.jruby.embed.internal.AbstractLocalContextProvider.getGlobalRuntime(AbstractLocalContextProvider.java:82)
        at org.jruby.embed.internal.SingletonLocalContextProvider.getRuntime(SingletonLocalContextProvider.java:99)    
        at org.jruby.embed.internal.EmbedRubyRuntimeAdapterImpl.runParser(EmbedRubyRuntimeAdapterImpl.java:167)        
        at org.jruby.embed.internal.EmbedRubyRuntimeAdapterImpl.parse(EmbedRubyRuntimeAdapterImpl.java:94)             
        at org.jruby.embed.ScriptingContainer.parse(ScriptingContainer.java:1239)                                      
        at org.jruby.embed.ScriptingContainer.runScriptlet(ScriptingContainer.java:1299)                               
        ... 5 more                                                                                                     
Caused by: java.lang.RuntimeException: BUG: could not initialize constructor handle                                    
        at org.jruby.runtime.scope.ManyVarsDynamicScope.<clinit>(ManyVarsDynamicScope.java:39)                         
        ... 16 more
Contributor

shirosaki commented Nov 21, 2016

Here is a test code for the issue.

With jruby-complete-9.1.6.0.jar, this fails with the following Exception.
With jruby-complete-1.7.26.jar, this succeeds.
java version "1.8.0_91"

import java.lang.reflect.Method;
import java.net.URL;
import java.net.URLClassLoader;

public class TestReload {
    public static void main(String[] args) {
        try {
            for (int i = 0; i < 2; i++) {
                // load class
                URLClassLoader loader = new URLClassLoader(new URL[] { 
                        new URL("jar:file:./jruby-complete.jar!/")
                    });
                Class<?> container = loader.loadClass("org.jruby.embed.ScriptingContainer");
                Method runScriptlet = container.getMethod("runScriptlet", String.class);
                Method setClassLoader = container.getMethod("setClassLoader", ClassLoader.class);
                Object c = container.newInstance();
                setClassLoader.invoke(c, loader);
                runScriptlet.invoke(c, "puts \"Hello World!\"");
                // unload class
                loader = null;
                c = null;
                System.gc();
            }
        } catch (Exception e) {
            e.printStackTrace();
        }
    }
}
$ java TestReload                                                                                                      
Hello World!                                                                                                           
java.lang.reflect.InvocationTargetException                                                                            
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)                                                 
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)                               
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)                       
        at java.lang.reflect.Method.invoke(Method.java:498)                                                            
        at TestReload.main(TestReload.java:18)                                                                         
Caused by: java.lang.ExceptionInInitializerError                                                                       
        at org.jruby.runtime.ThreadContext.<init>(ThreadContext.java:201)                                              
        at org.jruby.runtime.ThreadContext.newContext(ThreadContext.java:76)                                           
        at org.jruby.internal.runtime.ThreadService.initMainThread(ThreadService.java:166)                             
        at org.jruby.Ruby.init(Ruby.java:1238)                                                                         
        at org.jruby.Ruby.newInstance(Ruby.java:339)                                                                   
        at org.jruby.embed.internal.AbstractLocalContextProvider.getGlobalRuntime(AbstractLocalContextProvider.java:82)
        at org.jruby.embed.internal.SingletonLocalContextProvider.getRuntime(SingletonLocalContextProvider.java:99)    
        at org.jruby.embed.internal.EmbedRubyRuntimeAdapterImpl.runParser(EmbedRubyRuntimeAdapterImpl.java:167)        
        at org.jruby.embed.internal.EmbedRubyRuntimeAdapterImpl.parse(EmbedRubyRuntimeAdapterImpl.java:94)             
        at org.jruby.embed.ScriptingContainer.parse(ScriptingContainer.java:1239)                                      
        at org.jruby.embed.ScriptingContainer.runScriptlet(ScriptingContainer.java:1299)                               
        ... 5 more                                                                                                     
Caused by: java.lang.RuntimeException: BUG: could not initialize constructor handle                                    
        at org.jruby.runtime.scope.ManyVarsDynamicScope.<clinit>(ManyVarsDynamicScope.java:39)                         
        ... 16 more
@shirosaki

This comment has been minimized.

Show comment
Hide comment
@shirosaki

shirosaki Dec 8, 2016

Contributor

Threads would be needed to unload loaded classes.
After unloading classes, IllegalAccessException in ManyVarsDynamicScope disappears.
But java crashes with EXCEPTION_ACCESS_VIOLATION at finalizer in jffi.
Here is a test code.

import java.lang.reflect.Method;
import java.net.URL;
import java.net.URLClassLoader;

public class TestReload {
    public static void main(String[] args) {
        while (true) {
            Thread t = new Thread() {
                public void run() {
                    try (URLClassLoader loader = new URLClassLoader(new URL[] { 
                                new URL("jar:file:./jruby-complete.jar!/")
                            })) {
                        // load class
                        Class<?> container = loader.loadClass("org.jruby.embed.ScriptingContainer");
                        Method runScriptlet = container.getMethod("runScriptlet", String.class);
                        Method setClassLoader = container.getMethod("setClassLoader", ClassLoader.class);
                        Method terminate = container.getMethod("terminate");
                        Object c = container.newInstance();
                        setClassLoader.invoke(c, loader);
                        runScriptlet.invoke(c, "puts \"Hello World!\"");
                        terminate.invoke(c);
                    } catch (Exception e) {
                        e.printStackTrace();
                    }
                    // unload class
                    System.gc();
                    System.runFinalization();
                    System.gc();
                }
            };
            t.start();
            try {
                t.join();
            } catch (Exception e) {
		e.printStackTrace();
            }
        }
    }
}
$ java -XX:+TraceClassUnloading TestReload
(snip)
[thread 9492 also had an error]
#
# A fatal error has been detected by the Java Runtime Environment:
#
#  EXCEPTION_ACCESS_VIOLATION (0xc0000005) at pc=0x000000006e4c24b0, pid=11608, tid=0x00000000000031e4
#
# JRE version: Java(TM) SE Runtime Environment (8.0_111-b14) (build 1.8.0_111-b14)
# Java VM: Java HotSpot(TM) 64-Bit Server VM (25.111-b14 mixed mode windows-amd64 compressed oops)
# Problematic frame:
# C  0x000000006e4c24b0
#
# Failed to write core dump. Minidumps are not enabled by default on client versions of Windows
#
# An error report file with more information is saved as:
(snip)

hs_err_pid11608.log contains:

#
# A fatal error has been detected by the Java Runtime Environment:
#
#  EXCEPTION_ACCESS_VIOLATION (0xc0000005) at pc=0x000000006e4c24b0, pid=11608, tid=0x00000000000031e4
#
# JRE version: Java(TM) SE Runtime Environment (8.0_111-b14) (build 1.8.0_111-b14)
# Java VM: Java HotSpot(TM) 64-Bit Server VM (25.111-b14 mixed mode windows-amd64 compressed oops)
# Problematic frame:
# C  0x000000006e4c24b0
#
# Failed to write core dump. Minidumps are not enabled by default on client versions of Windows
#
# If you would like to submit a bug report, please visit:
#   http://bugreport.java.com/bugreport/crash.jsp
# The crash happened outside the Java Virtual Machine in native code.
# See problematic frame for where to report the bug.
#

---------------  T H R E A D  ---------------

Current thread (0x00000000213f6800):  JavaThread "Secondary finalizer" [_thread_in_native, id=12772, stack(0x00000000287c0000,0x00000000288c0000)]

siginfo: ExceptionCode=0xc0000005, ExceptionInformation=0x0000000000000008 0x000000006e4c24b0

Registers:
RAX=0x000000006e4c24b0, RBX=0x00000000209448f0, RCX=0x00000000213f69f8, RDX=0x00000000288befc0
RSP=0x00000000288bef08, RBP=0x00000000288bef90, RSI=0x00000000822c06f8, RDI=0x000000010035aca8
R8 =0x000000000111d470, R9 =0x00000000000015f1, R10=0x0000000002eb7f48, R11=0x000000005c86b580
R12=0x0000000000000000, R13=0x00000000209448f0, R14=0x00000000288befc0, R15=0x00000000213f6800
RIP=0x000000006e4c24b0, EFLAGS=0x0000000000010206

Top of Stack: (sp=0x00000000288bef08)
0x00000000288bef08:   0000000002eb7f74 00000000213f6800
0x00000000288bef18:   0000000000000000 00000000ffffffff
0x00000000288bef28:   0000000000000001 0000000000000000
0x00000000288bef38:   0000000000000000 0000000000000000
0x00000000288bef48:   000000001b36fed0 00000000288bef50
0x00000000288bef58:   0000000000000000 00000000288befc0
0x00000000288bef68:   000000002094ba90 0000000000000000
0x00000000288bef78:   00000000209448f0 0000000000000000
0x00000000288bef88:   00000000288befb0 00000000288bf008
0x00000000288bef98:   0000000002ea835d 0000000000000000
0x00000000288befa8:   0000000002eb19d8 000000000111d470
0x00000000288befb8:   000000000111d470 0000000081d6a758
0x00000000288befc8:   00000000288befc8 00000000229df541
0x00000000288befd8:   00000000288bf028 0000000022a0e208
0x00000000288befe8:   0000000000000000 00000000229df5e0
0x00000000288beff8:   00000000288befb0 00000000288bf030 

Instructions: (pc=0x000000006e4c24b0)
0x000000006e4c2490:   
[error occurred during error reporting (printing registers, top of stack, instructions near pc), id 0xc0000005]

Register to memory mapping:

RAX=0x000000006e4c24b0 is an unknown value
RBX={method} {0x00000000209448f8} 'freeCallContext' '(J)V' in 'com/kenai/jffi/Foreign'
RCX=0x00000000213f69f8 is an unknown value
RDX=0x00000000288befc0 is pointing into the stack for thread: 0x00000000213f6800
RSP=0x00000000288bef08 is pointing into the stack for thread: 0x00000000213f6800
RBP=0x00000000288bef90 is pointing into the stack for thread: 0x00000000213f6800
RSI=0x00000000822c06f8 is an oop
com.kenai.jffi.CallContext 
 - klass: 'com/kenai/jffi/CallContext'
RDI=0x000000010035aca8 is pointing into metadata
R8 =0x000000000111d470 is an unknown value
R9 =0x00000000000015f1 is an unknown value
R10=0x0000000002eb7f48 is at code_begin+840 in an Interpreter codelet
method entry point (kind = native)  [0x0000000002eb7c00, 0x0000000002eb8560]  2400 bytes
R11=0x000000005c86b580 is an unknown value
R12=0x0000000000000000 is an unknown value
R13={method} {0x00000000209448f8} 'freeCallContext' '(J)V' in 'com/kenai/jffi/Foreign'
R14=0x00000000288befc0 is pointing into the stack for thread: 0x00000000213f6800
R15=0x00000000213f6800 is a thread


Stack: [0x00000000287c0000,0x00000000288c0000],  sp=0x00000000288bef08,  free space=1019k
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
C  0x000000006e4c24b0

Java frames: (J=compiled Java code, j=interpreted, Vv=VM code)
j  com.kenai.jffi.Foreign.freeCallContext(J)V+0
j  com.kenai.jffi.CallContext.finalize()V+17
J 4759 C1 java.lang.ref.Finalizer.runFinalizer(Lsun/misc/JavaLangAccess;)V (62 bytes) @ 0x000000000333d88c [0x000000000333d300+0x58c]
J 4758 C1 java.lang.ref.Finalizer.access$100(Ljava/lang/ref/Finalizer;Lsun/misc/JavaLangAccess;)V (6 bytes) @ 0x00000000035af55c [0x00000000035af500+0x5c]
j  java.lang.ref.Finalizer$2.run()V+36
j  java.lang.Thread.run()V+11
v  ~StubRoutines::call_stub
Contributor

shirosaki commented Dec 8, 2016

Threads would be needed to unload loaded classes.
After unloading classes, IllegalAccessException in ManyVarsDynamicScope disappears.
But java crashes with EXCEPTION_ACCESS_VIOLATION at finalizer in jffi.
Here is a test code.

import java.lang.reflect.Method;
import java.net.URL;
import java.net.URLClassLoader;

public class TestReload {
    public static void main(String[] args) {
        while (true) {
            Thread t = new Thread() {
                public void run() {
                    try (URLClassLoader loader = new URLClassLoader(new URL[] { 
                                new URL("jar:file:./jruby-complete.jar!/")
                            })) {
                        // load class
                        Class<?> container = loader.loadClass("org.jruby.embed.ScriptingContainer");
                        Method runScriptlet = container.getMethod("runScriptlet", String.class);
                        Method setClassLoader = container.getMethod("setClassLoader", ClassLoader.class);
                        Method terminate = container.getMethod("terminate");
                        Object c = container.newInstance();
                        setClassLoader.invoke(c, loader);
                        runScriptlet.invoke(c, "puts \"Hello World!\"");
                        terminate.invoke(c);
                    } catch (Exception e) {
                        e.printStackTrace();
                    }
                    // unload class
                    System.gc();
                    System.runFinalization();
                    System.gc();
                }
            };
            t.start();
            try {
                t.join();
            } catch (Exception e) {
		e.printStackTrace();
            }
        }
    }
}
$ java -XX:+TraceClassUnloading TestReload
(snip)
[thread 9492 also had an error]
#
# A fatal error has been detected by the Java Runtime Environment:
#
#  EXCEPTION_ACCESS_VIOLATION (0xc0000005) at pc=0x000000006e4c24b0, pid=11608, tid=0x00000000000031e4
#
# JRE version: Java(TM) SE Runtime Environment (8.0_111-b14) (build 1.8.0_111-b14)
# Java VM: Java HotSpot(TM) 64-Bit Server VM (25.111-b14 mixed mode windows-amd64 compressed oops)
# Problematic frame:
# C  0x000000006e4c24b0
#
# Failed to write core dump. Minidumps are not enabled by default on client versions of Windows
#
# An error report file with more information is saved as:
(snip)

hs_err_pid11608.log contains:

#
# A fatal error has been detected by the Java Runtime Environment:
#
#  EXCEPTION_ACCESS_VIOLATION (0xc0000005) at pc=0x000000006e4c24b0, pid=11608, tid=0x00000000000031e4
#
# JRE version: Java(TM) SE Runtime Environment (8.0_111-b14) (build 1.8.0_111-b14)
# Java VM: Java HotSpot(TM) 64-Bit Server VM (25.111-b14 mixed mode windows-amd64 compressed oops)
# Problematic frame:
# C  0x000000006e4c24b0
#
# Failed to write core dump. Minidumps are not enabled by default on client versions of Windows
#
# If you would like to submit a bug report, please visit:
#   http://bugreport.java.com/bugreport/crash.jsp
# The crash happened outside the Java Virtual Machine in native code.
# See problematic frame for where to report the bug.
#

---------------  T H R E A D  ---------------

Current thread (0x00000000213f6800):  JavaThread "Secondary finalizer" [_thread_in_native, id=12772, stack(0x00000000287c0000,0x00000000288c0000)]

siginfo: ExceptionCode=0xc0000005, ExceptionInformation=0x0000000000000008 0x000000006e4c24b0

Registers:
RAX=0x000000006e4c24b0, RBX=0x00000000209448f0, RCX=0x00000000213f69f8, RDX=0x00000000288befc0
RSP=0x00000000288bef08, RBP=0x00000000288bef90, RSI=0x00000000822c06f8, RDI=0x000000010035aca8
R8 =0x000000000111d470, R9 =0x00000000000015f1, R10=0x0000000002eb7f48, R11=0x000000005c86b580
R12=0x0000000000000000, R13=0x00000000209448f0, R14=0x00000000288befc0, R15=0x00000000213f6800
RIP=0x000000006e4c24b0, EFLAGS=0x0000000000010206

Top of Stack: (sp=0x00000000288bef08)
0x00000000288bef08:   0000000002eb7f74 00000000213f6800
0x00000000288bef18:   0000000000000000 00000000ffffffff
0x00000000288bef28:   0000000000000001 0000000000000000
0x00000000288bef38:   0000000000000000 0000000000000000
0x00000000288bef48:   000000001b36fed0 00000000288bef50
0x00000000288bef58:   0000000000000000 00000000288befc0
0x00000000288bef68:   000000002094ba90 0000000000000000
0x00000000288bef78:   00000000209448f0 0000000000000000
0x00000000288bef88:   00000000288befb0 00000000288bf008
0x00000000288bef98:   0000000002ea835d 0000000000000000
0x00000000288befa8:   0000000002eb19d8 000000000111d470
0x00000000288befb8:   000000000111d470 0000000081d6a758
0x00000000288befc8:   00000000288befc8 00000000229df541
0x00000000288befd8:   00000000288bf028 0000000022a0e208
0x00000000288befe8:   0000000000000000 00000000229df5e0
0x00000000288beff8:   00000000288befb0 00000000288bf030 

Instructions: (pc=0x000000006e4c24b0)
0x000000006e4c2490:   
[error occurred during error reporting (printing registers, top of stack, instructions near pc), id 0xc0000005]

Register to memory mapping:

RAX=0x000000006e4c24b0 is an unknown value
RBX={method} {0x00000000209448f8} 'freeCallContext' '(J)V' in 'com/kenai/jffi/Foreign'
RCX=0x00000000213f69f8 is an unknown value
RDX=0x00000000288befc0 is pointing into the stack for thread: 0x00000000213f6800
RSP=0x00000000288bef08 is pointing into the stack for thread: 0x00000000213f6800
RBP=0x00000000288bef90 is pointing into the stack for thread: 0x00000000213f6800
RSI=0x00000000822c06f8 is an oop
com.kenai.jffi.CallContext 
 - klass: 'com/kenai/jffi/CallContext'
RDI=0x000000010035aca8 is pointing into metadata
R8 =0x000000000111d470 is an unknown value
R9 =0x00000000000015f1 is an unknown value
R10=0x0000000002eb7f48 is at code_begin+840 in an Interpreter codelet
method entry point (kind = native)  [0x0000000002eb7c00, 0x0000000002eb8560]  2400 bytes
R11=0x000000005c86b580 is an unknown value
R12=0x0000000000000000 is an unknown value
R13={method} {0x00000000209448f8} 'freeCallContext' '(J)V' in 'com/kenai/jffi/Foreign'
R14=0x00000000288befc0 is pointing into the stack for thread: 0x00000000213f6800
R15=0x00000000213f6800 is a thread


Stack: [0x00000000287c0000,0x00000000288c0000],  sp=0x00000000288bef08,  free space=1019k
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
C  0x000000006e4c24b0

Java frames: (J=compiled Java code, j=interpreted, Vv=VM code)
j  com.kenai.jffi.Foreign.freeCallContext(J)V+0
j  com.kenai.jffi.CallContext.finalize()V+17
J 4759 C1 java.lang.ref.Finalizer.runFinalizer(Lsun/misc/JavaLangAccess;)V (62 bytes) @ 0x000000000333d88c [0x000000000333d300+0x58c]
J 4758 C1 java.lang.ref.Finalizer.access$100(Ljava/lang/ref/Finalizer;Lsun/misc/JavaLangAccess;)V (6 bytes) @ 0x00000000035af55c [0x00000000035af500+0x5c]
j  java.lang.ref.Finalizer$2.run()V+36
j  java.lang.Thread.run()V+11
v  ~StubRoutines::call_stub
@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius Feb 24, 2017

Member

Nice investigation on this one. I'll try out your reproduction code and see if I can figure out what's going wrong.

Member

headius commented Feb 24, 2017

Nice investigation on this one. I'll try out your reproduction code and see if I can figure out what's going wrong.

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius Feb 24, 2017

Member

Reproduced! Investigating.

Member

headius commented Feb 24, 2017

Reproduced! Investigating.

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius Feb 24, 2017

Member

Using MethodHandles.lookup() does indeed solve the issue, and I think it's a good change.

The jnr-ffi crash is a separate issue and I'll investigate that.

Member

headius commented Feb 24, 2017

Using MethodHandles.lookup() does indeed solve the issue, and I think it's a good change.

The jnr-ffi crash is a separate issue and I'll investigate that.

@headius headius merged commit 32926ac into jruby:master Feb 24, 2017

0 of 2 checks passed

continuous-integration/appveyor/pr AppVeyor build failed
Details
continuous-integration/travis-ci/pr The Travis CI build failed
Details

@headius headius added this to the JRuby 9.1.8.0 milestone Feb 24, 2017

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment