MacOS java/lang/reflect/exeCallerAccessTest/CallerAccessTest.java - RuntimeException: Expected to get exit value of [0]

[JasonFengJ9]

Failure link

From an internal build job/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_1/1/(osxrt8):

openjdk version "18-beta" 2022-03-22
IBM Semeru Runtime Open Edition 18.0.0.0 (build 18-beta+32-202201270253)
Eclipse OpenJ9 VM 18.0.0.0 (build master-5e9bd4ea0, JRE 18 Mac OS X amd64-64-Bit Compressed References 20220126_21 (JIT enabled, AOT enabled)
OpenJ9   - 5e9bd4ea0
OMR      - 4a009d2fe
JCL      - 0764ffcb69 based on jdk-18+32)

Rerun in Grinder - Change TARGET to run only the failed test targets.

Optional info

Failure output (captured from console output)

[2022-01-27T03:37:52.444Z] Running test jdk_lang_1 ...
[2022-01-27T03:37:52.855Z] ===============================================


[2022-01-27T03:37:52.855Z] variation: -Xdump:system:none -Xdump:heap:none -Xdump:system:events=gpf+abort+traceassert+corruptcache -XX:-JITServerTechPreviewMessage Mode650
[2022-01-27T03:37:52.855Z] JVM_OPTIONS:  -Xdump:system:none -Xdump:heap:none -Xdump:system:events=gpf+abort+traceassert+corruptcache -XX:-JITServerTechPreviewMessage -XX:-UseCompressedOops 

[2022-01-27T03:44:26.638Z] TEST: java/lang/reflect/exeCallerAccessTest/CallerAccessTest.java

[2022-01-27T03:44:26.640Z] STDERR:
[2022-01-27T03:44:26.640Z]  stdout: [];
[2022-01-27T03:44:26.640Z]  stderr: []
[2022-01-27T03:44:26.640Z]  exitValue = 139
[2022-01-27T03:44:26.640Z] 
[2022-01-27T03:44:26.640Z] java.lang.RuntimeException: Expected to get exit value of [0]
[2022-01-27T03:44:26.640Z] 
[2022-01-27T03:44:26.640Z] 	at jdk.test.lib.process.OutputAnalyzer.shouldHaveExitValue(OutputAnalyzer.java:489)
[2022-01-27T03:44:26.640Z] 	at CallerAccessTest.main(CallerAccessTest.java:64)
[2022-01-27T03:44:26.640Z] 	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
[2022-01-27T03:44:26.640Z] 	at java.base/java.lang.reflect.Method.invoke(Method.java:577)
[2022-01-27T03:44:26.640Z] 	at com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:312)
[2022-01-27T03:44:26.640Z] 	at java.base/java.lang.Thread.run(Thread.java:884)
[2022-01-27T03:44:26.640Z] 
[2022-01-27T03:44:26.640Z] JavaTest Message: Test threw exception: java.lang.RuntimeException
[2022-01-27T03:44:26.640Z] JavaTest Message: shutting down test
[2022-01-27T03:44:26.640Z] 
[2022-01-27T03:44:26.640Z] 
[2022-01-27T03:44:26.640Z] TEST RESULT: Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: Expected to get exit value of [0]
[2022-01-27T03:44:26.640Z] --------------------------------------------------
[2022-01-27T03:45:51.859Z] Test results: passed: 797; failed: 1; error: 1
[2022-01-27T03:46:01.622Z] Report written to /Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_1/jvmtest/openjdk/report/html/report.html
[2022-01-27T03:46:01.623Z] Results written to /Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_1/aqa-tests/TKG/output_16432546715178/jdk_lang_1/work
[2022-01-27T03:46:01.623Z] Error: Some tests failed or other problems occurred.
[2022-01-27T03:46:01.623Z] 
[2022-01-27T03:46:01.623Z] jdk_lang_1_FAILED

50x grinder - job/Grinder/20614/ - all failed

[pshipton]

This is showing up in jdk17 builds now. Possibly since the test was un-excluded.
Setting as a blocker since it's failing in every nightly MacOS build.
@tajila

https://openj9-jenkins.osuosl.org/job/Test_openjdk17_j9_sanity.openjdk_x86-64_mac_Nightly/148/
https://openj9-jenkins.osuosl.org/job/Test_openjdk17_j9_sanity.openjdk_x86-64_mac_Nightly/149/

[tajila]

@JasonFengJ9 Is this only failing on macosx?

[JasonFengJ9]

Is this only failing on macosx?

It appears so, not seen in other platforms.

[tajila]

exit code 139 on the process launched with ProcessBuilder indicates a crash.

@babsingh Please investigate

[tajila]

There were changes in OpenJDK made 7 days ago, 60a165f358a076320357303cf72dbc0e74d9c06c regarding this

ibmruntimes/openj9-openjdk-jdk@60a165f358a07

[tajila]

Pasting more output form the grinder

11:03:01  STDOUT:
11:03:01  Launching: /Users/jenkins/workspace/Grinder_iteration_1/openjdkbinary/openjdk-test-image/jdk/jtreg/native/CallerAccessTest shared library path: /Users/jenkins/workspace/Grinder_iteration_1/openjdkbinary/j2sdk-image/Contents/Home/bin/../lib:/Users/jenkins/workspace/Grinder_iteration_1/openjdkbinary/j2sdk-image/Contents/Home/bin/../lib/server
11:03:01  [2022-02-02T16:02:24.122994Z] Gathering output for process 82782
11:03:01  [2022-02-02T16:02:24.152516Z] Waiting for completion for process 82782
11:03:01  [2022-02-02T16:02:55.636353Z] Waiting for completion finished for process 82782
11:03:01  [2022-02-02T16:02:55.637813Z] Waiting for completion for process 82782
11:03:01  [2022-02-02T16:02:55.637890Z] Waiting for completion finished for process 82782
11:03:01  STDERR:
11:03:01   stdout: [];
11:03:01   stderr: []
11:03:01   exitValue = 139
11:03:01  
11:03:01  java.lang.RuntimeException: Expected to get exit value of [0]
11:03:01  
11:03:01  	at jdk.test.lib.process.OutputAnalyzer.shouldHaveExitValue(OutputAnalyzer.java:489)
11:03:01  	at CallerAccessTest.main(CallerAccessTest.java:64)
11:03:01  	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
11:03:01  	at java.base/java.lang.reflect.Method.invoke(Method.java:577)
11:03:01  	at com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:312)
11:03:01  	at java.base/java.lang.Thread.run(Thread.java:889)
11:03:01  
11:03:01  JavaTest Message: Test threw exception: java.lang.RuntimeException
11:03:01  JavaTest Message: shutting down test

[babsingh]

Most recent grinder: https://hyc-runtimes-jenkins.swg-devops.com/job/Grinder/20769/

ProcessBuilder is doing the following:

export DYLD_LIBRARY_PATH=/Users/jenkins/workspace/Grinder/openjdkbinary/j2sdk-image/Contents/Home/bin/../lib:/Users/jenkins/workspace/Grinder/openjdkbinary/j2sdk-image/Contents/Home/bin/../lib/server

# Native executable
/Users/jenkins/workspace/Grinder/openjdkbinary/openjdk-test-image/jdk/jtreg/native/CallerAccessTest

While executing CallerAccessTest, there is a segfault. Core files are not generated for the segfault. Also, lldb does not work:

lldb -- /Users/jenkins/workspace/Grinder/openjdkbinary/openjdk-test-image/jdk/jtreg/native/CallerAccessTest
(lldb) target create "/Users/jenkins/workspace/Grinder/openjdkbinary/openjdk-test-image/jdk/jtreg/native/CallerAccessTest"
Current executable set to '/Users/jenkins/workspace/Grinder/openjdkbinary/openjdk-test-image/jdk/jtreg/native/CallerAccessTest' (x86_64).
(lldb) r
error: process exited with status -1 (developer mode is not enabled on this machine and this is a non-interactive debug session.)

Without lldb, we won't be able to find the cause of the segfault. We will need to enable developer mode for lldb to work on the Mac machines as per https://www.mail-archive.com/[email protected]/msg00691.html. fyi @AdamBrousseau

[tajila]

@babsingh can you reproduce this with JDK11? I would be good to understand when this issue started

[babsingh]

can you reproduce this with JDK11? I would be good to understand when this issue started

This test was introduced in JDK12 extensions repo. Running the full test with JDK11 causes an UnsupportedClassVersionError: JVMCFRE003 bad major version. I was able to run the native executable with JDK11 libraries. I got the same error, which is seen with JDK17 and JDK18. So, this issue has always persisted.

As per the below lldb output, JNI_CreateJavaVM is invoked ~23800 times (recursive/infinite loop) until the native stack is exhausted.

lldb output

% lldb -- test_image//jdk/jtreg/native/CallerAccessTest

(lldb) env DYLD_LIBRARY_PATH=/Users/jenkins/babsingh/openj9-openjdk-jdk18/test_image/jdk/jtreg/native:/Users/jenkins/babsingh/openj9-openjdk-jdk18/bootjdk11/Contents/Home/lib:/Users/jenkins/babsingh/openj9-openjdk-jdk18/bootjdk11/Contents/Home/lib/server

(lldb) run

* thread #1, queue = 'com.apple.main-thread', stop reason = EXC_BAD_ACCESS (code=2, address=0x7ffeef3fff88)
    frame #0: 0x000000000005940b dyld`realpath$DARWIN_EXTSN + 155
dyld`realpath$DARWIN_EXTSN:
->  0x5940b <+155>: callq  0x5ec78                   ; __error
    0x59410 <+160>: cmpb   $0x2f, (%rbx)
    0x59413 <+163>: jne    0x5947c                   ; <+268>
    0x59415 <+165>: movq   -0x1ce0(%rbp), %rax
Target 0: (CallerAccessTest) stopped.

(lldb) bt

* thread #1, queue = 'com.apple.main-thread', stop reason = EXC_BAD_ACCESS (code=2, address=0x7ffeef3fff88)
  * frame #0: 0x000000000005940b dyld`realpath$DARWIN_EXTSN + 155
    frame #1: 0x00000000000201ab dyld`ImageLoaderMachO::getRPaths(ImageLoader::LinkContext const&, std::__1::vector<char const*, std::__1::allocator<char const*> >&) const + 917
    frame #2: 0x00000000000159a7 dyld`dlopen_internal + 289
    frame #3: 0x00007fff20433cb4 libdyld.dylib`dlopen_internal(char const*, int, void*) + 185
    frame #4: 0x00007fff2042209e libdyld.dylib`dlopen + 28
    frame #5: 0x0000000000124066 libjvm.dylib`JNI_CreateJavaVM [inlined] openLibraries at redirector.c:1160:19 [opt]
    frame #6: 0x0000000000124037 libjvm.dylib`JNI_CreateJavaVM(pvm=0x00007ffeefbff8f0, penv=0x00007ffeefbff8f8, vm_args=<unavailable>) at redirector.c:784 [opt]
    frame #7: 0x0000000000124114 libjvm.dylib`JNI_CreateJavaVM(pvm=0x00007ffeefbff8f0, penv=0x00007ffeefbff8f8, vm_args=<unavailable>) at redirector.c:805:11 [opt]
    ...
    frame #7 REPEATS 23797 times
    ...
    frame #23805: 0x0000000000124114 libjvm.dylib`JNI_CreateJavaVM(pvm=0x00007ffeefbff8f0, penv=0x00007ffeefbff8f8, vm_args=<unavailable>) at redirector.c:805:11 [opt]
    frame #23806: 0x0000000000001a58 CallerAccessTest`main + 56
    frame #23807: 0x00007fff20431f5d libdyld.dylib`start + 1
    frame #23808: 0x00007fff20431f5d libdyld.dylib`start + 1

[babsingh]

The problem is related to the libjvm.dylib dependency. There are three libjvm.dylib copies in the JDK:

$JAVA_HOME/lib/j9vm/libjvm.dylib
$JAVA_HOME/lib/default/libjvm.dylib
$JAVA_HOME/lib/server/libjvm.dylib

Test: java/lang/reflect/exeCallerAccessTest/CallerAccessTest.java

The test sets DYLD_LIBRARY_PATH to include $JAVA_HOME/lib/server (vmDir), which causes the native executable to use $JAVA_HOME/lib/server/libjvm.dylib. The error behaviour reported in #14397 (comment) is seen with $JAVA_HOME/lib/server/libjvm.dylib and $JAVA_HOME/lib/j9vm/libjvm.dylib.

After updating the test ... setting DYLD_LIBRARY_PATH to include $JAVA_HOME/lib/default instead of $JAVA_HOME/lib/server ... the test successfully passes ... because $JAVA_HOME/lib/default/libjvm.dylib gets used. As a temporary fix, should we update the test to use default/libjvm.dylib on OSX? More investigation will be needed to fix the root cause of the failure. I have listed few guesses below to start the investigation.

On Linux, the test passes with all three above-mentioned copies of libjvm.so.

We need to figure why the test only passes with $JAVA_HOME/lib/default/libjvm.dylib on Mac OSX.

Guesses:

• The native test executable is compiled to only work with $JAVA_HOME/lib/default/libjvm.dylib?
• As per the below ls output, all libraries are located in the default directory. This may allow the linker to successfully load default/libjvm.dylib. On the other hand, the linker may not be able to locate the required libraries for server/libjvm.dylib and j9vm/libjvm.dylib. May be something is missing while generating server/libjvm.dylib and j9vm/libjvm.dylib?

% ls $JAVA_HOME//lib/j9vm/
libjsig.dylib	libjvm.dylib

% ls $JAVA_HOME/lib/server/
libjsig.dylib	libjvm.dylib

% ls $JAVA_HOME/lib/default/
j9ddr.dat		libj9gc29.dylib		libj9gcchk_full29.dylib	libj9jit29.dylib	libj9prt29.dylib	libj9trc29.dylib	libj9vrb29.dylib	libjclse29.dylib	libomrsig.dylib
libcuda4j29.dylib	libj9gc_full29.dylib	libj9hookable29.dylib	libj9jnichk29.dylib	libj9shr29.dylib	libj9vm29.dylib		libj9vrb_full29.dylib	libjvm.dylib
libj9dmp29.dylib	libj9gcchk29.dylib	libj9jextract.dylib	libj9jvmti29.dylib	libj9thr29.dylib	libj9vmchk29.dylib	libj9zlib29.dylib	libmanagement_ext.dylib

[babsingh]

There is a workaround to pass the test by using $JAVA_HOME/lib/default/libjvm.dylib. Can the blocker label be removed?

[pshipton]

As a temporary fix, should we update the test to use default/libjvm.dylib on OSX?

Makes sense. I've removed the blocker label.

[babsingh]

Problem

In OpenJ9, j9vm/libjvm.dylib and server/libjvm.dylib represent the redirector, which tries to find the addresses of functions in default/libjvm.dylib such as JNI_CreateJavaVM. dlopen is used for this, and it works differently on OSX and Linux to search libraries when an absolute path-name is specified.

openj9/runtime/redirector/redirector.c

Lines 1160 to 1166 in 934d656

	j9vm_dllHandle = dlopen(jvmBufferData(buffer), RTLD_LAZY);
	if(!j9vm_dllHandle) {
	fprintf(stderr, "failed to open <%s> - reason: <%s>\n", jvmBufferData(buffer), dlerror());
	return JNI_ERR;
	}
	globalCreateVM = (CreateVM) dlsym (j9vm_dllHandle, "JNI_CreateJavaVM");

On Linux, the dynamic loader tries to open the library with absolute path-name before searching for it as per Ref 1.

On OSX, the dynamic loader tries to find the library in the following order: DYLD_LIBRARY_PATH -> Path as given -> DYLD_FALLBACK_LIBRARY_PATH [Refs 2 and 3].

For CallerAccessTest, DYLD_LIBRARY_PATH points to server/libjvm.dylib. On OSX, the dynamic loader tried to find default/libjvm.dylib from the redirector. It starts by looking at DYLD_LIBRARY_PATH, and always ends up opening server/libjvm.dylib due to the search algorithm used on OSX. Instead of invoking JNI_CreateJavaVM from default/libjvm.dylib, the redirector recursively invokes its own implementation of JNI_CreateJavaVM from server/libjvm.dylib until the native stack is exhausted (infinite loop). This results in a segfault.

Potential Fixes

1. The library name of default/libjvm.dylib can be changed so that it does not conflict with [j9vm|server]/libjvm.dylib. Not sure how straightforward it will be to perform this change. Indirect/external dependants, such as tests, builds or users, may break.
2. Use DYLD_FALLBACK_LIBRARY_PATH instead of DYLD_LIBRARY_PATH with the redirector [Refs 2, 3 and 4].

@pshipton @keithc-ca @tajila Which solution is preferred?

Other Hacks/Experiments

Ref 5 discusses about hacks that won't work. For example, modifying the environment variable DYLD_LIBRARY_PATH during runtime has no influence on the dynamic loader.

Refs

1. Linux dlopen: https://man7.org/linux/man-pages/man3/dlopen.3.html
2. OSX dlopen: https://developer.apple.com/library/archive/documentation/System/Conceptual/ManPages_iPhoneOS/man3/dlopen.3.html
3. OSX Dynamic Library Usage: https://developer.apple.com/library/archive/documentation/DeveloperTools/Conceptual/DynamicLibraries/100-Articles/DynamicLibraryUsageGuidelines.html
4. Is it OK to use DYLD_LIBRARY_PATH on Mac OS X? https://stackoverflow.com/questions/3146274/is-it-ok-to-use-dyld-library-path-on-mac-os-x-and-whats-the-dynamic-library-s
5. dlopen not using pre-loaded dependencies: https://developer.apple.com/forums/thread/132817

[keithc-ca]

Another option is to revive #7380 so the main shared libraries don't conflict with the redirector.
As noted there, we would have to address the issues on AIX and z/OS.

[pshipton]

Seems to me some other platforms modify or set the environment variable so the correct library is found, in jvm.c. Any reason we can't do that?

[keithc-ca]

Doesn't the redirector locate the main shared library so an explicit path can be use rather than rely on any search path?

[babsingh]

Another option is to revive #7380 so the main shared libraries don't conflict with the redirector.

default/libjvm.dylib is the main (non-redirector) shared library. #7380 covers exactly what is proposed for the first potential fix in #14397 (comment).

Seems to me some other platforms modify or set the environment variable so the correct library is found, in jvm.c. Any reason we can't do that?

Here, we are referring to the LIBPATH changes in jvm.c for AIX where we prepend to the LIBPATH during runtime. LIBPATH is the DYLD_LIBRARY_PATH equivalent on AIX. In https://developer.apple.com/forums/thread/132817, it is mentioned that runtime changes to DYLD_LIBRARY_PATH are not honoured by the dynamic loader. So, prepending the default libjvm library path to DYLD_LIBRARY_PATH during runtime won't fix this issue.

Doesn't the redirector locate the main shared library so an explicit path can be use rather than rely on any search path?

Yes, an absolute path is used to locate default/libjvm.dylib from the redirector. On OSX, the dynamic loader searches for a library in the following order: DYLD_LIBRARY_PATH -> Path as given -> DYLD_FALLBACK_LIBRARY_PATH. DYLD_LIBRARY_PATH is searched before the Path as given is used. The dynamic loader locates libjvm.so in server/... since DYLD_LIBRARY_PATH is set. Path as given for default/libjvm.dylib is never utilized on OSX. For more details, see The Library Search Process in https://developer.apple.com/library/archive/documentation/DeveloperTools/Conceptual/DynamicLibraries/100-Articles/DynamicLibraryUsageGuidelines.html.

[keithc-ca]

The way I read that article, using DYLD_FALLBACK_LIBRARY_PATH won't help us because it says it will consider DYLD_LIBRARY_PATH first with (the unqualified) filename. This will succeed and find the redirector. This seems consistent with the previous comment.

It seems to me the only way to tolerate DYLD_LIBRARY_PATH that mentions the redirector directory is to have a different name for the main shared library (or fold it into what is now the redirector so there is only one libjvm.dylib - something we've been reluctant to do so far).

[babsingh]

using DYLD_FALLBACK_LIBRARY_PATH won't help us because it says it will consider DYLD_LIBRARY_PATH

Clarification: In #14397 (comment), the second potential fix suggests to use DYLD_FALLBACK_LIBRARY_PATH INSTEAD of DYLD_LIBRARY_PATH with the redirector. This is more like a workaround for a user, and it works in a simple scenario such as CallerAccessTest. But I feel that this approach has potential downfalls where the OS's libraries can be loaded instead of JDK libraries for identical library names.

+1 As stated in #14397 (comment), the only fix to support DYLD_LIBRARY_PATH is to rename the main (non-redirector) libjvm library.

[pshipton]

In https://developer.apple.com/forums/thread/132817, it is mentioned that runtime changes to DYLD_LIBRARY_PATH are not honoured by the dynamic loader. So, prepending the default libjvm library path to DYLD_LIBRARY_PATH during runtime won't fix this issue.

It's not clear to me it covers the same case we need. We should give it a try to be sure.

[pshipton]

Another option is to revive #7380 so the main shared libraries don't conflict with the redirector.
As noted there, we would have to address the issues on AIX and z/OS.

If this turns out to be the only solution, we do have the option to only do it for Mac. In which case we don't need to address issues on AIX and z/OS.

[keithc-ca]

Making it platform-dependent complicates the build scripts in the extension repos a little; if we're considering that, I suggest we apply the change for all platforms except AIX and z/OS (at least until we can fix the issues on those platforms).

[babsingh]

It's not clear to me it covers the same case we need. We should give it a try to be sure.

re #14397 (comment):

Code to Prepend default libjvm directory to DYLD_LIBRARY_PATH: babsingh@34c6612.

The above change does not work. I have verified that the dynamic loader does not honour runtime changes to DYLD_LIBRARY_PATH. For testing, I set DYLD_LIBRARY_PATH, and then invoked the native test executable.

There was an outlier scenario which gave the illusion that the above change works. If the test is run through the JTReg test harness, the native test executable is invoked via ProcessBuilder. The forked process inherits the modified DYLD_LIBRARY_PATH from the JTReg test harness which has the default libjvm directory prepended to the environment variable. In this case, the native test executable ends up using the main libjvm instead of the redirector libjvm.

So, our only solution to support/tolerate DYLD_LIBRARY_PATH is #7380.

[user19312818]

Hi, I am hitting a similar problem where JNI_CreateJavaVM() crashes on macOS Mojave 10.14.5, lldb shows this error:

* thread #1, queue = 'com.apple.main-thread', stop reason = EXC_BAD_ACCESS (code=2, address=0x7ffee79be0b0)

Another issue I get when trying to do dlopen() on libsplashscreen.dylib, it is similar to a problem reported elsewhere:
https://stackoverflow.com/questions/21021366/my-java-launcher-crashes-when-display-splashscreen-with-jdk7-on-macosx

Is there a workaround to fix this problem?

[babsingh]

I am hitting a similar problem where JNI_CreateJavaVM()

To confirm if it is the same issue. Does your crashing thread's backtrace match the backtrace shown in #14397 (comment)?

Is there a workaround to fix this problem?

If the backtrace matches, then the DYLD_FALLBACK_LIBRARY_PATH fix, mentioned in #14397 (comment), can be used as a workaround.

[tajila]

Is this the proposed fix #7380 ?