Closed pshipton closed 2 years ago
knn-k
commented
2 years ago 100% reproduced in a Grinder job: https://openj9-jenkins.osuosl.org/job/Grinder/605
jdk_foreign_1 was OK when I tried running sanity.openjdk last week in https://openj9-jenkins.osuosl.org/job/Grinder/577/tapResults/, but that was JDK 17.
pshipton
commented
2 years ago Also note this build is from the v0.31.0-release branch.
knn-k
commented
2 years ago PR #14479 does not resolve this failure. I need to look at it deeper.
pshipton
commented
2 years ago Also occurs on x86, same stack trace as shown in the description. Internal builds /job/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_1/6 - jdk_foreign_1 - mac11x64rt10 /job/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/6 - jdk_foreign_0 - mac11x64rt06
00:23:14 openjdk version "18" 2022-03-22
00:23:14 IBM Semeru Runtime Open Edition 18.0.0.0-m1 (build 18+35)
00:23:14 Eclipse OpenJ9 VM 18.0.0.0-m1 (build openj9-0.31.0-m1, JRE 18 Mac OS X amd64-64-Bit Compressed References 20220210_28 (JIT enabled, AOT enabled)
00:23:14 OpenJ9 - 700cde7b8
00:23:14 OMR - bb5d44b8c
00:23:14 JCL - cdd4205c649 based on jdk-18+35)Didn't see it in the open build https://openj9-jenkins.osuosl.org/job/Pipeline-Release-0.31.0-Build18/4/
pshipton
commented
2 years ago @ChengJin01 fyi
ChengJin01
commented
2 years ago The problem was seen in the open build at https://openj9-jenkins.osuosl.org/job/Test_openjdk18_j9_sanity.openjdk_aarch64_mac_Release/1/consoleFull
17:04:58 Caused by: java.util.NoSuchElementException: No value present
17:04:58 at java.base/java.util.Optional.get(Optional.java:143)
17:04:58 at NativeTestHelper.<clinit>(NativeTestHelper.java:91) <--------
17:04:58 ... 36 morewhich was caused by the following code at https://github.com/ibmruntimes/openj9-openjdk-jdk18/blob/openj9/test/jdk/java/foreign/NativeTestHelper.java
public class NativeTestHelper {
private static CLinker LINKER = CLinker.systemCLinker();
private static final MethodHandle FREE = LINKER.downcallHandle(
LINKER.lookup("free").get(), <------- failure to load the default library in OpenJDK
FunctionDescriptor.ofVoid(ValueLayout.ADDRESS));
Technically there should be no problem with the default library loading on MacOS/Aarch64 given OpenJDK already supports the platform in code. So it is hard to tell why it failed at this point (this is about how OpenJDK loads the default library. If it works via dlsym on other other POSIX system, it should work on MacOS/Aarch64 in theory)
Note: the code related (default library loading) is totally in OpenJDK, which has nothing to do with our implementation of Foreign Linker API. In addition, we have no Foreign Linker API support on MacOS/Aarch64 according to our initial plan.
FYI: @tajila
ChengJin01
commented
2 years ago The related code include the following files: /openj9-openjdk-jdk18/src/jdk.incubator.foreign/share/classes/jdk/internal/foreign/SystemLookup.java
/*
* On POSIX systems, dlsym will allow us to lookup symbol in library dependencies; the same trick doesn't work
* on Windows. For this reason, on Windows we do not generate any side-library, and load msvcrt.dll directly instead.
*/
private static final SymbolLookup syslookup = switch (CABI.current()) {
case SysV, LinuxAArch64, MacOsAArch64, SysVPPC64le, SysVS390x -> libLookup(libs -> libs.loadLibrary("syslookup"));
case AIX -> makeAixLookup();
case Win64 -> makeWindowsLookup(); // out of line to workaround javac crash
};
private static SymbolLookup libLookup(Function<NativeLibraries, NativeLibrary> loader) {
NativeLibrary lib = loader.apply(NativeLibraries.rawNativeLibraries(SystemLookup.class, false));
.../openj9-openjdk-jdk18/src/java.base/share/classes/jdk/internal/loader/NativeLibraries.java /openj9-openjdk-jdk18/src/java.base/share/native/libjava/NativeLibraries.c
pshipton
commented
2 years ago The problem was seen in the open build at https://openj9-jenkins.osuosl.org/job/Test_openjdk18_j9_sanity.openjdk_aarch64_mac_Release/1
That's why this Issue was originally created. In https://github.com/eclipse-openj9/openj9/issues/14487#issuecomment-1036382615 I was commenting on the x86 failure that didn't occur in the open build, but is seen in the internal build.
ChengJin01
commented
2 years ago That's why this Issue was originally created. In #14487 (comment) I was commenting on the x86 failure that didn't occur in the open build, but is seen in the internal build.
There is no Foreign Linker API support on macOS/x86 in OpenJDK, in which case the test shouldn't run in there (OpenJDK only supports Linux and Windows on x86 in terms of Foreign Linker API).
pshipton
commented
2 years ago According to https://openj9-jenkins.osuosl.org/job/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_Release/1/testReport/ it seems the test is running and passing. I could run it again in a grinder and archive the test results. Yet in the internal build it's running and failing.
04:56:35 ===============================================
04:56:35 Running test jdk_foreign_0 ...
04:56:35 ===============================================
04:56:35 jdk_foreign_0 Start Time: Fri Feb 11 04:56:35 2022 Epoch Time (ms): 1644573395460
04:56:35 "/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/openjdkbinary/j2sdk-image/Contents/Home/bin/..//bin/java" -Xshareclasses:destroyAll; "/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/openjdkbinary/j2sdk-image/Contents/Home/bin/..//bin/java" -Xshareclasses:groupAccess,destroyAll; echo "cache cleanup done";
04:56:35 JVMSHRC005I No shared class caches available
04:56:35 JVMSHRC005I No shared class caches available
04:56:35 cache cleanup done
04:56:35 variation: Mode150
04:56:35 JVM_OPTIONS: -XX:+UseCompressedOops
04:56:35 { itercnt=1; \
04:56:35 mkdir -p "/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/TKG/../TKG/output_16445721151343/jdk_foreign_0"; \
04:56:35 cd "/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/TKG/../TKG/output_16445721151343/jdk_foreign_0"; \
04:56:35 "/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/openjdkbinary/j2sdk-image/Contents/Home/bin/..//bin/java" -Xmx512m -jar "/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/TKG/../../jvmtest/openjdk/jtreg/lib/jtreg.jar" \
04:56:35 -agentvm -a -ea -esa -v:fail,error,time,nopass -retain:fail,error,*.dmp,javacore.*,heapdump.*,*.trc -ignore:quiet -timeoutFactor:8 -xml:verify -concurrency:4 -nativepath:"/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/openjdkbinary/openjdk-test-image/jdk/jtreg/native" -vmoptions:"-Xmx512m --add-modules jdk.incubator.foreign -XX:+UseCompressedOops " \
04:56:35 -w ""/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/TKG/../TKG/output_16445721151343/jdk_foreign_0"/work" \
04:56:35 -r "/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/TKG/../../jvmtest/openjdk/report" \
04:56:35 -jdk:"/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/openjdkbinary/j2sdk-image/Contents/Home/bin/../" \
04:56:35 -exclude:"/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/TKG/../openjdk/openjdk-jdk/test/jdk/ProblemList.txt" \
04:56:35 -exclude:"/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/TKG/../../jvmtest/openjdk/excludes/ProblemList_openjdk18-openj9.txt" \
04:56:35 "/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/TKG/../openjdk/openjdk-jdk/test/jdk:jdk_foreign"; \
04:56:35 if [ $? -eq 0 ] ; then echo ""; echo "jdk_foreign_0""_PASSED"; echo ""; cd /Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/TKG/..; else echo ""; echo "jdk_foreign_0""_FAILED"; echo ""; fi; } 2>&1 | tee -a "/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/TKG/../TKG/output_16445721151343/TestTargetResult";
04:56:36 Directory "/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/TKG/../TKG/output_16445721151343/jdk_foreign_0/work" not found: creating
04:56:43 WARNING: Using incubator modules: jdk.incubator.foreign
04:56:43 XML output with verification to /Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/TKG/output_16445721151343/jdk_foreign_0/work
04:56:43 WARNING: Using incubator modules: jdk.incubator.foreign
04:56:55 --------------------------------------------------
04:56:55 TEST: java/foreign/TestFunctionDescriptor.java
04:56:55 TEST JDK: /Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/openjdkbinary/j2sdk-image/Contents/Home/bin/..
04:56:55
04:56:55 ACTION: build -- Passed. Build successful
04:56:55 REASON: Named class compiled on demand
04:56:55 TIME: 0.73 seconds
04:56:55 messages:
04:56:55 command: build TestFunctionDescriptor
04:56:55 reason: Named class compiled on demand
04:56:55 Test directory:
04:56:55 compile: TestFunctionDescriptor
04:56:55 elapsed time (seconds): 0.73
04:56:55
04:56:55 ACTION: compile -- Passed. Compilation successful
04:56:55 REASON: .class file out of date or does not exist
04:56:55 TIME: 0.729 seconds
04:56:55 messages:
04:56:55 command: compile /Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/openjdk/openjdk-jdk/test/jdk/java/foreign/TestFunctionDescriptor.java
04:56:55 reason: .class file out of date or does not exist
04:56:55 Additional options from @modules: --add-modules jdk.incubator.foreign
04:56:55 Mode: agentvm
04:56:55 Agent id: 1
04:56:55 elapsed time (seconds): 0.729
04:56:55 configuration:
04:56:55 Boot Layer (javac runtime environment)
04:56:55 add modules: jdk.incubator.foreign
04:56:55 class path: /Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/jvmtest/openjdk/jtreg/lib/javatest.jar
04:56:55 /Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/jvmtest/openjdk/jtreg/lib/jtreg.jar
04:56:55 patch: java.base /Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/TKG/output_16445721151343/jdk_foreign_0/work/patches/java.base
04:56:55
04:56:55 javac compilation environment
04:56:55 add modules: jdk.incubator.foreign
04:56:55 source path: /Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/openjdk/openjdk-jdk/test/jdk/java/foreign
04:56:55 class path: /Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/openjdk/openjdk-jdk/test/jdk/java/foreign
04:56:55 /Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/TKG/output_16445721151343/jdk_foreign_0/work/classes/1/java/foreign/TestFunctionDescriptor.d
04:56:55 /Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/jvmtest/openjdk/jtreg/lib/testng.jar
04:56:55 /Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/jvmtest/openjdk/jtreg/lib/jcommander.jar
04:56:55 /Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/jvmtest/openjdk/jtreg/lib/guice.jar
04:56:55
04:56:55 rerun:
04:56:55 cd /Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/TKG/output_16445721151343/jdk_foreign_0/work/scratch/0 && \
04:56:55 HOME=/Users/jenkins \
04:56:55 PATH=/bin:/usr/bin:/usr/sbin \
04:56:55 /Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/openjdkbinary/j2sdk-image/Contents/Home/bin/../bin/javac \
04:56:55 -J-ea \
04:56:55 -J-esa \
04:56:55 -J-Xmx512m \
04:56:55 -J--add-modules \
04:56:55 -Jjdk.incubator.foreign \
04:56:55 -J-XX:+UseCompressedOops \
04:56:55 -J-Djava.library.path=/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/openjdkbinary/openjdk-test-image/jdk/jtreg/native \
04:56:55 -J-Dtest.vm.opts='-ea -esa -Xmx512m --add-modules jdk.incubator.foreign -XX:+UseCompressedOops' \
04:56:55 -J-Dtest.tool.vm.opts='-J-ea -J-esa -J-Xmx512m -J--add-modules -Jjdk.incubator.foreign -J-XX:+UseCompressedOops' \
04:56:55 -J-Dtest.compiler.opts= \
04:56:55 -J-Dtest.java.opts= \
04:56:55 -J-Dtest.jdk=/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/openjdkbinary/j2sdk-image/Contents/Home/bin/.. \
04:56:55 -J-Dcompile.jdk=/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/openjdkbinary/j2sdk-image/Contents/Home/bin/.. \
04:56:55 -J-Dtest.timeout.factor=8.0 \
04:56:55 -J-Dtest.nativepath=/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/openjdkbinary/openjdk-test-image/jdk/jtreg/native \
04:56:55 -J-Dtest.root=/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/openjdk/openjdk-jdk/test/jdk \
04:56:55 -J-Dtest.name=java/foreign/TestFunctionDescriptor.java \
04:56:55 -J-Dtest.file=/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/openjdk/openjdk-jdk/test/jdk/java/foreign/TestFunctionDescriptor.java \
04:56:55 -J-Dtest.src=/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/openjdk/openjdk-jdk/test/jdk/java/foreign \
04:56:55 -J-Dtest.src.path=/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/openjdk/openjdk-jdk/test/jdk/java/foreign \
04:56:55 -J-Dtest.classes=/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/TKG/output_16445721151343/jdk_foreign_0/work/classes/1/java/foreign/TestFunctionDescriptor.d \
04:56:55 -J-Dtest.class.path=/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/TKG/output_16445721151343/jdk_foreign_0/work/classes/1/java/foreign/TestFunctionDescriptor.d \
04:56:55 -J-Dtest.class.path.prefix=/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/TKG/output_16445721151343/jdk_foreign_0/work/classes/1/java/foreign/TestFunctionDescriptor.d:/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/openjdk/openjdk-jdk/test/jdk/java/foreign \
04:56:55 -J-Dtest.modules=jdk.incubator.foreign \
04:56:55 --add-modules jdk.incubator.foreign \
04:56:55 -d /Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/TKG/output_16445721151343/jdk_foreign_0/work/classes/1/java/foreign/TestFunctionDescriptor.d \
04:56:55 -sourcepath /Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/openjdk/openjdk-jdk/test/jdk/java/foreign \
04:56:55 -classpath /Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/openjdk/openjdk-jdk/test/jdk/java/foreign:/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/TKG/output_16445721151343/jdk_foreign_0/work/classes/1/java/foreign/TestFunctionDescriptor.d:/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/jvmtest/openjdk/jtreg/lib/testng.jar:/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/jvmtest/openjdk/jtreg/lib/jcommander.jar:/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/jvmtest/openjdk/jtreg/lib/guice.jar /Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/openjdk/openjdk-jdk/test/jdk/java/foreign/TestFunctionDescriptor.java
04:56:55 direct:
04:56:55 warning: using incubating module(s): jdk.incubator.foreign
04:56:55 1 warning
04:56:55
04:56:55 ACTION: testng -- Failed. Execution failed: `main' threw exception: org.testng.TestNGException: An error occurred while instantiating class TestFunctionDescriptor: null
04:56:55 REASON: User specified action: run testng/othervm --enable-native-access=ALL-UNNAMED TestFunctionDescriptor
04:56:55 TIME: 1.014 seconds
04:56:55 messages:
04:56:55 command: testng --enable-native-access=ALL-UNNAMED TestFunctionDescriptor
04:56:55 reason: User specified action: run testng/othervm --enable-native-access=ALL-UNNAMED TestFunctionDescriptor
04:56:55 Mode: othervm [/othervm specified]
04:56:55 Additional options from @modules: --add-modules jdk.incubator.foreign
04:56:55 elapsed time (seconds): 1.014
04:56:55 configuration:
04:56:55 Boot Layer
04:56:55 add modules: jdk.incubator.foreign
04:56:55
04:56:55 STDOUT:
04:56:55 STDERR:
04:56:55 WARNING: Using incubator modules: jdk.incubator.foreign
04:56:55 org.testng.TestNGException:
04:56:55 An error occurred while instantiating class TestFunctionDescriptor: null
04:56:55 at org.testng.internal.InstanceCreator.createInstanceUsingObjectFactory(InstanceCreator.java:123)
04:56:55 at org.testng.internal.InstanceCreator.createInstance(InstanceCreator.java:79)
04:56:55 at org.testng.internal.ClassImpl.getDefaultInstance(ClassImpl.java:109)
04:56:55 at org.testng.internal.ClassImpl.getInstances(ClassImpl.java:167)
04:56:55 at org.testng.TestClass.getInstances(TestClass.java:102)
04:56:55 at org.testng.TestClass.initTestClassesAndInstances(TestClass.java:82)
04:56:55 at org.testng.TestClass.init(TestClass.java:74)
04:56:55 at org.testng.TestClass.<init>(TestClass.java:39)
04:56:55 at org.testng.TestRunner.initMethods(TestRunner.java:457)
04:56:55 at org.testng.TestRunner.init(TestRunner.java:336)
04:56:55 at org.testng.TestRunner.init(TestRunner.java:289)
04:56:55 at org.testng.TestRunner.<init>(TestRunner.java:180)
04:56:55 at org.testng.SuiteRunner$DefaultTestRunnerFactory.newTestRunner(SuiteRunner.java:613)
04:56:55 at org.testng.SuiteRunner.init(SuiteRunner.java:178)
04:56:55 at org.testng.SuiteRunner.<init>(SuiteRunner.java:112)
04:56:55 at org.testng.TestNG.createSuiteRunner(TestNG.java:1306)
04:56:55 at org.testng.TestNG.createSuiteRunners(TestNG.java:1282)
04:56:55 at org.testng.TestNG.runSuitesLocally(TestNG.java:1131)
04:56:55 at org.testng.TestNG.runSuites(TestNG.java:1069)
04:56:55 at org.testng.TestNG.run(TestNG.java:1037)
04:56:55 at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:94)
04:56:55 at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:54)
04:56:55 at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
04:56:55 at java.base/java.lang.reflect.Method.invoke(Method.java:577)
04:56:55 at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
04:56:55 at java.base/java.lang.Thread.run(Thread.java:889)
04:56:55 Caused by: java.lang.ExceptionInInitializerError
04:56:55 at java.base/java.lang.J9VMInternals.recordInitializationFailure(J9VMInternals.java:164)
04:56:55 at java.base/jdk.internal.misc.Unsafe.ensureClassInitialized0(Native Method)
04:56:55 at java.base/jdk.internal.misc.Unsafe.ensureClassInitialized(Unsafe.java:1522)
04:56:55 at java.base/jdk.internal.reflect.MethodHandleAccessorFactory.ensureClassInitialized(MethodHandleAccessorFactory.java:300)
04:56:55 at java.base/jdk.internal.reflect.MethodHandleAccessorFactory.newConstructorAccessor(MethodHandleAccessorFactory.java:103)
04:56:55 at java.base/jdk.internal.reflect.ReflectionFactory.newConstructorAccessor(ReflectionFactory.java:236)
04:56:55 at java.base/java.lang.reflect.Constructor.acquireConstructorAccessor(Constructor.java:546)
04:56:55 at java.base/java.lang.reflect.Constructor.newInstanceWithCaller(Constructor.java:496)
04:56:55 at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:483)
04:56:55 at org.testng.internal.ObjectFactoryImpl.newInstance(ObjectFactoryImpl.java:23)
04:56:55 at org.testng.internal.InstanceCreator.instantiateUsingDefaultConstructor(InstanceCreator.java:193)
04:56:55 at org.testng.internal.InstanceCreator.createInstanceUsingObjectFactory(InstanceCreator.java:113)
04:56:55 ... 25 more
04:56:55 Caused by: java.util.NoSuchElementException: No value present
04:56:55 at java.base/java.util.Optional.get(Optional.java:143)
04:56:55 at NativeTestHelper.<clinit>(NativeTestHelper.java:91)
04:56:55 ... 36 more
04:56:55
04:56:55 JavaTest Message: Test threw exception: org.testng.TestNGException:
04:56:55 An error occurred while instantiating class TestFunctionDescriptor: null
04:56:55 JavaTest Message: shutting down test
04:56:55
04:56:55 STATUS:Failed.`main' threw exception: org.testng.TestNGException: An error occurred while instantiating class TestFunctionDescriptor: null
04:56:55 rerun:
04:56:55 cd /Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/TKG/output_16445721151343/jdk_foreign_0/work/scratch/0 && \
04:56:55 HOME=/Users/jenkins \
04:56:55 PATH=/bin:/usr/bin:/usr/sbin \
04:56:55 CLASSPATH=/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/TKG/output_16445721151343/jdk_foreign_0/work/classes/1/java/foreign/TestFunctionDescriptor.d:/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/openjdk/openjdk-jdk/test/jdk/java/foreign:/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/jvmtest/openjdk/jtreg/lib/testng.jar:/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/jvmtest/openjdk/jtreg/lib/jcommander.jar:/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/jvmtest/openjdk/jtreg/lib/guice.jar:/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/jvmtest/openjdk/jtreg/lib/javatest.jar:/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/jvmtest/openjdk/jtreg/lib/jtreg.jar \
04:56:55 /Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/openjdkbinary/j2sdk-image/Contents/Home/bin/../bin/java \
04:56:55 -Dtest.vm.opts='-ea -esa -Xmx512m --add-modules jdk.incubator.foreign -XX:+UseCompressedOops' \
04:56:55 -Dtest.tool.vm.opts='-J-ea -J-esa -J-Xmx512m -J--add-modules -Jjdk.incubator.foreign -J-XX:+UseCompressedOops' \
04:56:55 -Dtest.compiler.opts= \
04:56:55 -Dtest.java.opts= \
04:56:55 -Dtest.jdk=/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/openjdkbinary/j2sdk-image/Contents/Home/bin/.. \
04:56:55 -Dcompile.jdk=/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/openjdkbinary/j2sdk-image/Contents/Home/bin/.. \
04:56:55 -Dtest.timeout.factor=8.0 \
04:56:55 -Dtest.nativepath=/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/openjdkbinary/openjdk-test-image/jdk/jtreg/native \
04:56:55 -Dtest.root=/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/openjdk/openjdk-jdk/test/jdk \
04:56:55 -Dtest.name=java/foreign/TestFunctionDescriptor.java \
04:56:55 -Dtest.file=/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/openjdk/openjdk-jdk/test/jdk/java/foreign/TestFunctionDescriptor.java \
04:56:55 -Dtest.src=/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/openjdk/openjdk-jdk/test/jdk/java/foreign \
04:56:55 -Dtest.src.path=/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/openjdk/openjdk-jdk/test/jdk/java/foreign \
04:56:55 -Dtest.classes=/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/TKG/output_16445721151343/jdk_foreign_0/work/classes/1/java/foreign/TestFunctionDescriptor.d \
04:56:55 -Dtest.class.path=/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/TKG/output_16445721151343/jdk_foreign_0/work/classes/1/java/foreign/TestFunctionDescriptor.d \
04:56:55 -Dtest.class.path.prefix=/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/TKG/output_16445721151343/jdk_foreign_0/work/classes/1/java/foreign/TestFunctionDescriptor.d:/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/openjdk/openjdk-jdk/test/jdk/java/foreign \
04:56:55 -Dtest.modules=jdk.incubator.foreign \
04:56:55 --add-modules jdk.incubator.foreign \
04:56:55 -ea \
04:56:55 -esa \
04:56:55 -Xmx512m \
04:56:55 -XX:+UseCompressedOops \
04:56:55 -Djava.library.path=/Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/openjdkbinary/openjdk-test-image/jdk/jtreg/native \
04:56:55 --enable-native-access=ALL-UNNAMED \
04:56:55 com.sun.javatest.regtest.agent.MainWrapper /Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/TKG/output_16445721151343/jdk_foreign_0/work/java/foreign/TestFunctionDescriptor.d/testng.0.jta java/foreign/TestFunctionDescriptor.java false TestFunctionDescriptor
04:56:55
04:56:55 TEST RESULT: Failed. Execution failed: `main' threw exception: org.testng.TestNGException: An error occurred while instantiating class TestFunctionDescriptor: null
04:56:55 --------------------------------------------------
04:57:19 Test results: passed: 46; failed: 1
04:57:29 Report written to /Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/jvmtest/openjdk/report/html/report.html
04:57:29 Results written to /Users/jenkins/workspace/Test_openjdk18_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/TKG/output_16445721151343/jdk_foreign_0/work
04:57:29 Error: Some tests failed or other problems occurred.
04:57:29
04:57:29 jdk_foreign_0_FAILEDRan the test in a grinder, but there is nothing useful in the archived result, just a Grinder.tap, no test artifacts. @llxia do I need to set "KEEP_WORKSPACE"? https://openj9-jenkins.osuosl.org/view/Test/job/Grinder/611
pshipton
commented
2 years ago Setting "KEEP_WORKSPACE" didn't change the archived results. https://openj9-artifactory.osuosl.org/artifactory/ci-openj9/Test/Grinder/614
ChengJin01
commented
2 years ago If there is no difference between the internal & open builds from the code perspective in OpenJDK, it should end up with the same results.
The test at /openj9-openjdk-jdk18/test/jdk/java/foreign/TestFunctionDescriptor.java only sets up the arch as follows:
/*
/openj9-openjdk-jdk18/src/jdk.incubator.foreign/share/classes/jdk/internal/foreign/abi/aarch64
/openj9-openjdk-jdk18/src/jdk.incubator.foreign/share/classes/jdk/internal/foreign/abi/aarch64/linux
/openj9-openjdk-jdk18/src/jdk.incubator.foreign/share/classes/jdk/internal/foreign/abi/aarch64/macos <-- for macOS/Aarch64
/openj9-openjdk-jdk18/src/jdk.incubator.foreign/share/classes/jdk/internal/foreign/abi/x64
/openj9-openjdk-jdk18/src/jdk.incubator.foreign/share/classes/jdk/internal/foreign/abi/x64/sysv <---- ??? used by Linux
/openj9-openjdk-jdk18/src/jdk.incubator.foreign/share/classes/jdk/internal/foreign/abi/x64/windowsI am wondering how this test case works on macOS/x86 without the supporting code (unless it picks up x64/sysv).
llxia
commented
2 years ago re https://github.com/eclipse-openj9/openj9/issues/14487#issuecomment-1036576181, KEEP_WORKSPACE means our test script will not delete the workspace after the run. It will not help in this case. I think work dir is removed by jtreg.
Try -retain:all at https://github.com/adoptium/aqa-tests/blob/master/openjdk/openjdk.mk#L77
jtreg doc: https://openjdk.java.net/jtreg/command-help.html
ChengJin01
commented
2 years ago 100% reproduced in a Grinder job: https://openj9-jenkins.osuosl.org/job/Grinder/605
jdk_foreign_1 was OK when I tried running sanity.openjdk last week in https://openj9-jenkins.osuosl.org/job/Grinder/577/tapResults/, but that was JDK 17.
That's because the test code in TestFunctionDescriptor is different betwen JDK17 & 18.
[1] JDK17
public class TestFunctionDescriptor { // didn't extend `NativeTestHelper` in JDK17
...
}
public class NativeTestHelper { // no library loading code here in JDK17
...
}[2] JDK18
public class TestFunctionDescriptor extends NativeTestHelper {
...
}
public class NativeTestHelper {
private static CLinker LINKER = CLinker.systemCLinker();
private static final MethodHandle FREE = LINKER.downcallHandle(
LINKER.lookup("free").get(), <---- failed here
FunctionDescriptor.ofVoid(ValueLayout.ADDRESS));
...In JDK17, it never loads free via TestFunctionDescriptor, which explains why it passed in there.
ChengJin01
commented
2 years ago I tried with a simple test as follows with the open build & internal build on the passing machines (V19.6.0 for intended open build) and the failing machine (v20.3.0 intended for internal build)
import jdk.incubator.foreign.CLinker;
import java.lang.invoke.MethodHandle;
import jdk.incubator.foreign.Addressable;
public class LinkerTest {
private static CLinker LINKER = CLinker.systemCLinker();
public static void main(String[] args) throws Throwable {
Addressable functionSymbol = LINKER.lookup("free").get();
System.out.println("functionSymbol = " + functionSymbol);
}and it shows both builds passed on v19.6.0:
$ ./bin/java --enable-native-access=ALL-UNNAMED --add-modules jdk.incubator.foreign -Dforeign.restricted=permit LinkerTest
WARNING: Using incubator modules: jdk.incubator.foreign
functionSymbol = NativeSymbolImpl[name=free, address=MemoryAddress{ offset=0x7fff6f9ec9b1 }, scope=jdk.internal.foreign.ResourceScopeImpl$GlobalScopeImpl@82668984]an failed on v20.3.0:
$ ./bin/java --enable-native-access=ALL-UNNAMED --add-modules jdk.incubator.foreign -Dforeign.restricted=permit LinkerTest
WARNING: Using incubator modules: jdk.incubator.foreign
Exception in thread "main" java.util.NoSuchElementException: No value present
at java.base/java.util.Optional.get(Optional.java:143)
at LinkerTest.main(LinkerTest.java:10)
Assuming the code in OpenJDK is the same in open & internal build, it seems the issue was triggered by the newer version of macOS in terms of the default library loading.
ChengJin01
commented
2 years ago 1) I double-checked the test above with OpenJDK18/Hotspot which works good on both the passing machine (v19.6.0) and the failing machine (v20.3.0):
$ jdk18_hotspot_mac_x86/bin/java --version
openjdk 18-ea 2022-03-22
OpenJDK Runtime Environment (build 18-ea+35-2085)
OpenJDK 64-Bit Server VM (build 18-ea+35-2085, mixed mode, sharing)
s$ jdk18_hotspot_mac_x86/bin/java --enable-native-access=ALL-UNNAMED --add-modules jdk.incubator.foreign -Dforeign.restricted=permit LinkerTest
WARNING: Using incubator modules: jdk.incubator.foreign
functionSymbol = NativeSymbolImpl[name=free, address=MemoryAddress{ offset=0x7fff202f60bc }, scope=jdk.internal.foreign.ResourceScopeImpl$GlobalScopeImpl@3d494fbf]
2) Based on the findings on Linux platforms: e.g.
> !stack 0x000c8200
<c8200> !j9method 0x00000000001179E0 jdk/internal/loader/NativeLibraries.findEntry0(Ljdk/internal/loader
/NativeLibraries$NativeLibraryImpl;Ljava/lang/String;)J
<c8200> !j9method 0x00000000001179E0 jdk/internal/loader/NativeLibraries.findEntry0(Ljdk/internal/loader/NativeLibraries$NativeLibraryImpl;Ljava/lang/String;)J
<c8200> !j9method 0x000000000012D408 jdk/internal/loader/NativeLibraries$NativeLibraryImpl.find(Ljava/lang/String;)J
<c8200> !j9method 0x000000000012CE98 jdk/internal/loader/NativeLibrary.lookup(Ljava/lang/String;)J
<c8200> !j9method 0x00000000002B4C90 jdk/internal/foreign/SystemLookup.lambda$libLookup$7(Ljdk/internal/loader/NativeLibrary;Ljava/lang/String;)Ljava/util/Optional;
<c8200> !j9method 0x00000000002B5A78 jdk/internal/foreign/SystemLookup$$Lambda$17/0x0000000000000000.lookup(Ljava/lang/String;)Ljava/util/Optional;
<c8200> !j9method 0x00000000002B4C50 jdk/internal/foreign/SystemLookup.lookup(Ljava/lang/String;)Ljava/util/Optional;
<c8200> !j9method 0x000000000028AA28 jdk/incubator/foreign/CLinker.lookup(Ljava/lang/String;)Ljava/util/Optional;
<c8200> !j9method 0x000000000028F928 LinkerTest.main([Ljava/lang/String;)V
<c8200> JNI call-in frame
<c8200> Native method frame
(gdb) thr 2
[Switching to thread 2 (Thread 0x7ffff7a9f180 (LWP 20566))]
#0 JVM_FindLibraryEntry (handle=0x7ffff0282140, functionName=0x7ffff0143978 "free") at jvm.c:3754
3754 Trc_SC_FindLibraryEntry_Exit(result);
(gdb) bt
#0 JVM_FindLibraryEntry (handle=0x7ffff0282140, functionName=0x7ffff0143978 "free") at jvm.c:3754
#1 0x00007ffff7bf6d88 in JVM_FindLibraryEntry (handle=0x7ffff0282140, functionName=0x7ffff0143978 "free") at generated.c:1619
#2 0x00007fffd137ed28 in Java_jdk_internal_loader_NativeLibraries_findEntry0 (env=0xc8200, this=0xef730, lib=0x1b6078, name=0x1b6070) at .../openj9-openjdk-jdk18/src/java.base/share/native/libjava/NativeLibraries.c:245
#3 0x00007fffd2ad4e8c in ?? ()
#4 0x00007ffff77bf278 in runCallInMethod (env=0x2, receiver=0x578, clazz=0x50, methodID=0x65, args=0x0) at callin.cpp:1132
Thread 2 "main" hit Breakpoint 1, JVM_FindLibraryEntry (handle=0x7ffff0282140, functionName=0x7ffff0143978 "free") at jvm.c:3749
3749 result = (void*)dlsym( (void*)handle, (char *)functionName );
(gdb) n
3754 Trc_SC_FindLibraryEntry_Exit(result);
(gdb) info locals
result = 0x7ffff7ce3c80 <__GI___libc_free> <-------I suspect the existing native code JVM_FindLibraryEntry in OpenJ9 (specific to dlsym/dlopen), JVM_LoadLibrary or LIBPATH doesn't work on the newer version of macOS) given the native code for library loading should be the same for POSIX systems.
Might need to debug on macOS to narrow down where it failed in native.
ChengJin01
commented
2 years ago I've requested @AdamBrousseau to install the required package for compilation on the failing macOS machine given the jenkins build with debug image doesn't work well to locate the failure in debugging.
ChengJin01
commented
2 years ago For the moment, I managed to debug the build (compiled via UMA on the passing macOS machine) by uploading the debug build to the failing macOS machine as follows:
[1] v19.6.0 (the passing macOS machine)
* thread #3, name = 'main', stop reason = breakpoint 1.1
frame #0: 0x0000000000175d94 libjvm.dylib`JVM_FindLibraryEntry(handle=0x00000000004aecc0, functionName="free") at jvm.c:3754:2
3751 #error "Please implement jvm.c:JVM_FindLibraryEntry(void* handle, const char *functionName)"
3752 #endif /* defined(WIN32) */
3753
-> 3754 Trc_SC_FindLibraryEntry_Exit(result);
3755
3756 return result;
3757 }
(lldb) p result
(void *) $3 = 0x00007fff6f9ec9b1 <-------
(lldb) bt
* thread #3, name = 'main', stop reason = breakpoint 1.1
* frame #0: 0x0000000000175d94 libjvm.dylib`JVM_FindLibraryEntry(handle=0x00000000004aecc0, functionName="free") at jvm.c:3754:2
frame #1: 0x000000000013b5a0 libjvm.dylib`JVM_FindLibraryEntry(handle=0x00000000004aecc0, functionName="free") at generated.c:1619:9
frame #2: 0x0000000002fc86ae libjava.dylib`Java_jdk_internal_loader_NativeLibraries_findEntry0(env=0x0000000005ec0a00, this=0x0000000005f1ec30, lib=0x0000000005fbea28, name=0x0000000005fbea20) at NativeLibraries.c:245:11
frame #3: 0x00000000212bc2b0
(lldb) f 2
frame #2: 0x0000000002fc86ae libjava.dylib`Java_jdk_internal_loader_NativeLibraries_findEntry0(env=0x0000000005ec0a00, this=0x0000000005f1ec30, lib=0x0000000005fbea28, name=0x0000000005fbea20) at NativeLibraries.c:245:11
242 cname = (*env)->GetStringUTFChars(env, name, 0);
243 if (cname == 0)
244 return jlong_zero;
-> 245 res = ptr_to_jlong(JVM_FindLibraryEntry(jlong_to_ptr(handle), cname)); <-----
246 (*env)->ReleaseStringUTFChars(env, name, cname);
247 return res;
248 }
(lldb) p/x handle
(jlong) $5 = 0x00000000004aecc0 <--------[2] v20.3.0 (the failing macOS machine)
* thread #3, name = 'main', stop reason = breakpoint 1.1
frame #0: 0x000000000018cd94 libjvm.dylib`JVM_FindLibraryEntry(handle=0x0000000000000000, functionName="free") at jvm.c:3754:2
3751 #error "Please implement jvm.c:JVM_FindLibraryEntry(void* handle, const char *functionName)"
3752 #endif /* defined(WIN32) */
3753
-> 3754 Trc_SC_FindLibraryEntry_Exit(result);
3755
3756 return result;
3757 }
Target 0: (java) stopped.
(lldb) p result
(void *) $2 = 0x0000000000000000 <---------
(lldb) f 2
frame #2: 0x0000000033f446ae libjava.dylib`Java_jdk_internal_loader_NativeLibraries_findEntry0(env=0x0000000008809a00, this=0x0000000008867c30, lib=0x0000000008907a28, name=0x0000000008907a20) at NativeLibraries.c:245:11
242 cname = (*env)->GetStringUTFChars(env, name, 0);
243 if (cname == 0)
244 return jlong_zero;
-> 245 res = ptr_to_jlong(JVM_FindLibraryEntry(jlong_to_ptr(handle), cname));
246 (*env)->ReleaseStringUTFChars(env, name, cname);
247 return res;
248 }
(lldb) p handle
(jlong) $3 = 0 <--------
According the initial debugging findings above, it indicates that Java_jdk_internal_loader_NativeLibraries_findEntry0 returns 0 due to a null handle passed over to JVM_FindLibraryEntry on the failing machine while the handle is non-null on the passing machine. So I need to dig further to see why if failed to set up in there.
ChengJin01
commented
2 years ago 1) Further investigation shows the failing library loading was caused by the wrong library path passed into JVM_FindLibraryEntry on the failing macOS machine as follows:
[1] v19.6.0 (the passing macOS machine)
* thread #3, name = 'main', stop reason = step over
frame #0: 0x0000000045b23e31 libjava.dylib`Java_jdk_internal_loader_NativeLibraries_load(env=0x00000000066c0a00, this=0x000000000671ec30, lib=0x00000000067be8a8, name=0x00000000067be8a0, isBuiltin='\0', isJNI='\0', throwExceptionIfFail='\x01') at NativeLibraries.c:129:15
126 return JNI_FALSE;
127
128 cname = JNU_GetStringPlatformChars(env, name, 0);
-> 129 if (cname == 0)
130 return JNI_FALSE;
131 handle = isBuiltin ? procHandle : JVM_LoadLibrary(cname, throwExceptionIfFail);
132 if (isJNI) {
Target 0: (java) stopped.
(lldb) p cname
(const char *) $1 = 0x0000000000308e40
"../jdk18_openj9_lldb_mac_x64_v01/lib/libsyslookup.dylib" <--- the correct path
with the tracelog:
$ jdk18_openj9_lldb_mac_x64_v01/bin/java -Xtrace:iprint={j9scar.113} --enable-native-access=ALL-UNNAMED --add-modules jdk.incubator.foreign -Dforeign.restricted=permit LinkerTest
23:08:59.564*0x615ba00 j9scar.113 > JVM_LoadLibrary(name=.../jdk18_openj9_lldb_mac_x64_v01/lib/libnio.dylib)
WARNING: Using incubator modules: jdk.incubator.foreign
23:09:00.430*0x615ba00 j9scar.113
> JVM_LoadLibrary(name=.../jdk18_openj9_lldb_mac_x64_v01/lib/libsyslookup.dylib) <--------
functionSymbol = NativeSymbolImpl[name=free, address=MemoryAddress{ offset=0x7fff6f9ec9b1 }, scope=jdk.internal.foreign.ResourceScopeImpl$GlobalScopeImpl@f3f96268][2] v20.3.0 (the failing macOS machine)
(lldb) f 3
frame #3: 0x0000000032c5ee7e libjava.dylib`Java_jdk_internal_loader_NativeLibraries_load(env=0x000000000876fa00, this=0x00000000087cdc30, lib=0x000000000886d8a8, name=0x000000000886d8a0, isBuiltin='\0', isJNI='\0', throwExceptionIfFail='\0') at NativeLibraries.c:131:39
128 cname = JNU_GetStringPlatformChars(env, name, 0); <-----
129 if (cname == 0)
130 return JNI_FALSE;
-> 131 handle = isBuiltin ? procHandle : JVM_LoadLibrary(cname, throwExceptionIfFail);
132 if (isJNI) {
133 if (handle) {
134 JNI_OnLoad_t JNI_OnLoad;
(lldb) p cname
(const char *) $24 = 0x000000000040aca0
".../jdk18_openj9_lldb_mac_x64_v01/lib/compressedrefs/libsyslookup.dylib" <------ the wrong pathwith the tracelog:
$ jdk18_openj9_lldb_mac_x64_v01/bin/java -Xtrace:iprint={j9scar.113} --enable-native-access=ALL-UNNAMED --add-modules jdk.incubator.foreign -Dforeign.restricted=permit LinkerTest
23:18:20.344*0x12987a00 j9scar.113 > JVM_LoadLibrary(name=.../jdk18_openj9_lldb_mac_x64_v01/lib/compressedrefs/libnio.dylib)
23:18:20.346 0x12987a00 j9scar.113 > JVM_LoadLibrary(name=.../jdk18_openj9_lldb_mac_x64_v01/lib/compressedrefs/libnio.jnilib)
23:18:20.347 0x12987a00 j9scar.113 > JVM_LoadLibrary(name=.../jdk18_openj9_lldb_mac_x64_v01/lib/libnio.dylib)
WARNING: Using incubator modules: jdk.incubator.foreign
23:18:20.488*0x12987a00 j9scar.113
> JVM_LoadLibrary(name=.../jdk18_openj9_lldb_mac_x64_v01/lib/compressedrefs/libsyslookup.dylib) <---------------------
23:18:20.496 0x12987a00 j9scar.113 > JVM_LoadLibrary(name=.../jdk18_openj9_lldb_mac_x64_v01/lib/compressedrefs/libjimage.dylib)
23:18:20.497 0x12987a00 j9scar.113 > JVM_LoadLibrary(name=.../jdk18_openj9_lldb_mac_x64_v01/lib/compressedrefs/libjimage.jnilib)
23:18:20.498 0x12987a00 j9scar.113 > JVM_LoadLibrary(name=.../jdk18_openj9_lldb_mac_x64_v01/lib/libjimage.dylib)
Exception in thread "main" java.util.NoSuchElementException: No value present
at java.base/java.util.Optional.get(Optional.java:143)
at LinkerTest.main(LinkerTest.java:10)2) I also tried with a simple test of loading the syslookup library as follows to understand how it goes with System.loadLibrary:
public class LoaderTest {
public static void main(String[] args) throws Throwable {
System.loadLibrary("syslookup");
}
}[1] v19.6.0 (the passing macOS machine)
$ jdk18_openj9_lldb_mac_x64_v01/bin/java -Xtrace:iprint={j9scar.113} LoaderTest
23:13:09.649*0x1801aa00 j9scar.113 > JVM_LoadLibrary(name=.../jdk18_openj9_lldb_mac_x64_v01/lib/libnio.dylib)
23:13:09.778 0x1801aa00 j9scar.113
> JVM_LoadLibrary(name=.../jdk18_openj9_lldb_mac_x64_v01/lib/libsyslookup.dylib) <------[2] v20.3.0 (the failing macOS machine)
$ jdk18_openj9_lldb_mac_x64_v01/bin/java -Xtrace:iprint={j9scar.113} LoaderTest
23:17:23.521*0x11ac8a00 j9scar.113 > JVM_LoadLibrary(name=.../jdk18_openj9_lldb_mac_x64_v01/lib/compressedrefs/libnio.dylib)
23:17:23.522 0x11ac8a00 j9scar.113 > JVM_LoadLibrary(name=.../jdk18_openj9_lldb_mac_x64_v01/lib/compressedrefs/libnio.jnilib)
23:17:23.524 0x11ac8a00 j9scar.113 > JVM_LoadLibrary(name=.../jdk18_openj9_lldb_mac_x64_v01/lib/libnio.dylib)
23:17:23.588 0x11ac8a00 j9scar.113
> JVM_LoadLibrary(name=.../jdk18_openj9_lldb_mac_x64_v01/lib/compressedrefs/libsyslookup.dylib) <----
23:17:23.590 0x11ac8a00 j9scar.113 > JVM_LoadLibrary(name=.../jdk18_openj9_lldb_mac_x64_v01/lib/compressedrefs/libsyslookup.jnilib)
23:17:23.591 0x11ac8a00 j9scar.113
> JVM_LoadLibrary(name=.../jdk18_openj9_lldb_mac_x64_v01/lib/libsyslookup.dylib) <------which worked good in loading the syslookup library as compared to LinkerTest.
My understanding is that VM should recursively searches all library paths including both jdk/lib/compressedrefs and jdk/lib till the library is correctly located. So the next step is to figure out how this happened and whether this is a corner case just triggered in this way which needs to handled on VM side given all other libraries are correctly located except syslookup.
pshipton
commented
2 years ago It's not clear to me why a compressedrefs directory exists, we don't use that any more. Or why libsyslookup.dylib is located there, it's not a library that's expected to be in the OpenJ9 compressedrefs directory.
ChengJin01
commented
2 years ago The code at /openj9-openjdk-jdk18/src/java.base/share/classes/jdk/internal/loader/NativeLibraries.java in OpenJDK shows it searches the library paths from sun.boot.library.path and java.library.path set in the system property:
> !stack 0x06045a00
<6045a00> !j9method 0x00000000060ABD48 jdk/internal/loader/NativeLibraries.load(Ljdk/internal/loader/NativeLibraries$NativeLibraryImpl;Ljava/lang/String;ZZZ)Z
<6045a00> !j9method 0x00000000060C2748 jdk/internal/loader/NativeLibraries$NativeLibraryImpl.open()Z
<6045a00> !j9method 0x00000000060ABC48 jdk/internal/loader/NativeLibraries.loadLibrary(Ljava/lang/Class;Ljava/lang/String;Z)Ljdk/internal/loader/NativeLibrary;
<6045a00> !j9method 0x00000000060ABC28 jdk/internal/loader/NativeLibraries.loadLibrary(Ljava/lang/Class;Ljava/io/File;)Ljdk/internal/loader/NativeLibrary;
---> <6045a00> !j9method 0x00000000060ABCC8 jdk/internal/loader/NativeLibraries.findFromPaths([Ljava/lang/String;Ljava/lang/Class;Ljava/lang/String;)Ljdk/internal/loader/NativeLibrary;
<6045a00> !j9method 0x00000000060ABC88 jdk/internal/loader/NativeLibraries.loadLibrary(Ljava/lang/Class;Ljava/lang/String;)Ljdk/internal/loader/NativeLibrary;
<6045a00> !j9method 0x00000000060ABC68 jdk/internal/loader/NativeLibraries.loadLibrary(Ljava/lang/String;)Ljdk/internal/loader/NativeLibrary;
<6045a00> !j9method 0x0000000006251B50 jdk/internal/foreign/SystemLookup.lambda$static$0(Ljdk/internal/loader/NativeLibraries;)Ljdk/internal/loader/NativeLibrary;
<6045a00> !j9method 0x0000000006251E48 jdk/internal/foreign/SystemLookup$$Lambda$16/0x0000000000000000.apply(Ljava/lang/Object;)Ljava/lang/Object;
<6045a00> !j9method 0x0000000006251A10 jdk/internal/foreign/SystemLookup.libLookup(Ljava/util/function/Function;)Ljdk/incubator/foreign/SymbolLookup;
<6045a00> !j9method 0x0000000006251B70 jdk/internal/foreign/SystemLookup.<clinit>()V
<6045a00> JNI call-in frame
<6045a00> Generic special frame
<6045a00> !j9method 0x000000000622FDF8 jdk/incubator/foreign/CLinker.lookup(Ljava/lang/String;)Ljava/util/Optional;
<6045a00> !j9method 0x0000000006225528 LinkerTest.main([Ljava/lang/String;)V
/openj9-openjdk-jdk18/src/java.base/share/classes/jdk/internal/loader/NativeLibraries.java
/*
* Holds system and user library paths derived from the
* {@code java.library.path} and {@code sun.boot.library.path} system
* properties. The system properties are eagerly read at bootstrap, then
* lazily parsed on first use to avoid initialization ordering issues.
*/
static class LibraryPaths {
// The paths searched for libraries
static final String[] SYS_PATHS = ClassLoaderHelper.parsePath(StaticProperty.sunBootLibraryPath()); <------
static final String[] USER_PATHS = ClassLoaderHelper.parsePath(StaticProperty.javaLibraryPath()); <-----
}
public NativeLibrary loadLibrary(Class<?> fromClass, String name) {
assert name.indexOf(File.separatorChar) < 0;
NativeLibrary lib = findFromPaths(LibraryPaths.SYS_PATHS, fromClass, name); <-----
if (lib == null && searchJavaLibraryPath) {
lib = findFromPaths(LibraryPaths.USER_PATHS, fromClass, name); <----
}
return lib;
}For sun.boot.library.path and java.library.path, it shows the following paths on macOS:
sun.boot.library.path =/Users/jenkins/jincheng/jdk18_openj9_lldb_mac_x64_v01/lib/compressedrefs:/Users/jenkins/jincheng/jdk18_openj9_lldb_mac_x64_v01/lib
java.library.path =/Users/jenkins/jincheng/jdk18_openj9_lldb_mac_x64_v01/lib/compressedrefs:/Users/jenkins/jincheng/jdk18_openj9_lldb_mac_x64_v01/lib:/usr/libSo the code in findFromPaths searches the paths offered in sun.boot.library.path or java.library.path to locate libsyslookup.dylib.
private NativeLibrary findFromPaths(String[] paths, Class<?> fromClass, String name) {
for (String path : paths) { <----------------------- keep searching the paths in the for loop
File libfile = new File(path, System.mapLibraryName(name));
NativeLibrary nl = loadLibrary(fromClass, libfile); <--------
if (nl != null) {
return nl;
}
libfile = ClassLoaderHelper.mapAlternativeName(libfile);
if (libfile != null) {
nl = loadLibrary(fromClass, libfile);
if (nl != null) {
return nl;
}
}
}
return null;
}In theory, it should keep searching the paths for libsyslookup.dylib according to the code logic above.
However, the native code indicates it always return true regardless of the value of lib handle:
/openj9-openjdk-jdk18/src/java.base/share/native/libjava/NativeLibraries.c
Java_jdk_internal_loader_NativeLibraries_load
(JNIEnv *env, jobject this, jobject lib, jstring name,
jboolean isBuiltin, jboolean isJNI, jboolean throwExceptionIfFail)
{
const char *cname;
jint jniVersion;
jthrowable cause;
void * handle;
jboolean loaded = JNI_FALSE;
...
cname = JNU_GetStringPlatformChars(env, name, 0);
if (cname == 0)
return JNI_FALSE;
handle = isBuiltin ? procHandle : JVM_LoadLibrary(cname, throwExceptionIfFail);
<--------- JVM_LoadLibrary returns 0 in the case of jdk/lib/compressedrefs/libsyslookup.dylib
if (isJNI) { <-------- isJNI is false
if (handle) {
....
}
}
(*env)->SetLongField(env, lib, handleID, ptr_to_jlong(handle)); <---- handle is set to 0
loaded = JNI_TRUE; <------ still return TRUE and stop searching afterwards
done:
JNU_ReleaseStringPlatformChars(env, name, cname);
return loaded;
}against the stacktrace:
frame #0: 0x0000000047b52e31 libjava.dylib`Java_jdk_internal_loader_NativeLibraries_load
(env=0x0000000009045a00, this=0x00000000090a3c30, lib=0x00000000091438a8,
name=0x00000000091438a0, isBuiltin='\0', isJNI='\0', <-----isJNI is false
throwExceptionIfFail='\0') at NativeLibraries.c:129:15
126 return JNI_FALSE;
127
128 cname = JNU_GetStringPlatformChars(env, name, 0);
-> 129 if (cname == 0)
130 return JNI_FALSE;
131 handle = isBuiltin ? procHandle : JVM_LoadLibrary(cname, throwExceptionIfFail);
132 if (isJNI) {
Target 0: (java) stopped.
(lldb) p cname
(const char *) $3 = 0x000000000040b1f0 ".../jdk18_openj9_lldb_mac_x64_v01/lib/compressedrefs/libsyslookup.dylib"The reason why it passed on v19.6.0 is that the path was just set to lib/libsyslookup.dylib at first at that time from for (String path : paths) in findFromPaths.
ChengJin01
commented
2 years ago jdk/lib/compressedrefs set in sun.boot.library.path and java.library.path contains all OpenJ9 specific libraries, which are used when loading these libraries in other code.
compressedrefs jenkins$ pwd
.../jdk18_openj9_lldb_mac_x64_v01/lib/compressedrefs
compressedrefs jenkins$ ls
j9ddr.dat libj9shr29.dylib.dSYM
libcuda4j29.dylib libj9thr29.dylib
libcuda4j29.dylib.dSYM libj9thr29.dylib.dSYM
libj9dmp29.dylib libj9trc29.dylib
libj9dmp29.dylib.dSYM libj9trc29.dylib.dSYM
libj9gc29.dylib libj9vm29.dylib
libj9gc29.dylib.dSYM libj9vm29.dylib.dSYM
libj9gcchk29.dylib libj9vmchk29.dylib
libj9gcchk29.dylib.dSYM libj9vmchk29.dylib.dSYM
libj9hookable29.dylib libj9vrb29.dylib
libj9hookable29.dylib.dSYM libj9vrb29.dylib.dSYM
libj9jextract.dylib libj9zlib29.dylib
libj9jextract.dylib.dSYM libj9zlib29.dylib.dSYM
libj9jit29.dylib libjclse29.dylib
libj9jit29.dylib.dSYM libjclse29.dylib.dSYM
libj9jnichk29.dylib libjvm.dylib
libj9jnichk29.dylib.dSYM libjvm.dylib.dSYM
libj9jvmti29.dylib libmanagement_ext.dylib
libj9jvmti29.dylib.dSYM libmanagement_ext.dylib.dSYM
libj9prt29.dylib libomrsig.dylib
libj9prt29.dylib.dSYM libomrsig.dylib.dSYM
libj9shr29.dylibThe question is, whether it is safe to remove the path from sun.boot.library.path and java.library.path. If not, we might need to fix it up in OpenJDK to ensure the search keeps going till the correct path is located for the syslookup library by checking the value of handle returned from JVM_LoadLibrary(specifically in Java_jdk_internal_loader_NativeLibraries_load). In addition, the code around there needs to be double-checked to whether there is other way out.
ChengJin01
commented
2 years ago The following code in Java_jdk_internal_loader_NativeLibraries_load needs to modified a little to ensure it keeps searching in findFromPaths if return false from Java_jdk_internal_loader_NativeLibraries_load:
/openj9-openjdk-jdk18/src/java.base/share/native/libjava/NativeLibraries.c
Java_jdk_internal_loader_NativeLibraries_load
(JNIEnv *env, jobject this, jobject lib, jstring name,
jboolean isBuiltin, jboolean isJNI, jboolean throwExceptionIfFail)
{
...
jboolean loaded = JNI_FALSE;
...
handle = isBuiltin ? procHandle : JVM_LoadLibrary(cname, throwExceptionIfFail); <----
if (isJNI) { <-------- isJNI is false
if (handle) {
....
}
}
(*env)->SetLongField(env, lib, handleID, ptr_to_jlong(handle));
if (handle) { <----- check whether the handle is null
loaded = JNI_TRUE; <------ only return true for a non-null handle; otherwise keep searching the lib paths
}The fix works good on both the passing and failing machines according to the trace & result: [1] v19.6.0 (the passing macOS machine)
s$ jdk18_openj9_lldb_mac_x64_v02/bin/java -Xtrace:iprint={j9scar.113} --enable-native-access=ALL-UNNAMED --add-modules jdk.incubator.foreign -Dforeign.restricted=permit LinkerTest
16:36:14.827*0x14068a00 j9scar.113
> JVM_LoadLibrary(name=/.../jdk18_openj9_lldb_mac_x64_v02/lib/libnio.dylib)
WARNING: Using incubator modules: jdk.incubator.foreign
16:36:15.199*0x14068a00 j9scar.113
> JVM_LoadLibrary(name=/.../jdk18_openj9_lldb_mac_x64_v02/lib/libsyslookup.dylib) <-------
functionSymbol = NativeSymbolImpl[name=free, address=MemoryAddress{ offset=0x7fff6f9ec9b1 }, scope=jdk.internal.foreign.ResourceScopeImpl$GlobalScopeImpl@b2000f72]
[2] v20.3.0 (the failing macOS machine)
$ jdk18_openj9_lldb_mac_x64_v02/bin/java -Xtrace:iprint={j9scar.113} --enable-native-access=ALL-UNNAMED --add-modules jdk.incubator.foreign -Dforeign.restricted=permit LinkerTest
16:37:04.923*0xa17aa00 j9scar.113 > JVM_LoadLibrary(name=.../jdk18_openj9_lldb_mac_x64_v02/lib/compressedrefs/libnio.dylib)
16:37:04.925 0xa17aa00 j9scar.113 > JVM_LoadLibrary(name=.../jdk18_openj9_lldb_mac_x64_v02/lib/compressedrefs/libnio.jnilib)
16:37:04.927 0xa17aa00 j9scar.113 > JVM_LoadLibrary(name=.../jdk18_openj9_lldb_mac_x64_v02/lib/libnio.dylib)
WARNING: Using incubator modules: jdk.incubator.foreign
16:37:05.994*0xa17aa00 j9scar.113
> JVM_LoadLibrary(name=.../jdk18_openj9_lldb_mac_x64_v02/lib/compressedrefs/libsyslookup.dylib)
16:37:05.996 0xa17aa00 j9scar.113
> JVM_LoadLibrary(name=.../jdk18_openj9_lldb_mac_x64_v02/lib/compressedrefs/libsyslookup.jnilib)
16:37:05.998 0xa17aa00 j9scar.113
> JVM_LoadLibrary(name=.../jdk18_openj9_lldb_mac_x64_v02/lib/libsyslookup.dylib) <-----------
functionSymbol = NativeSymbolImpl[name=free, address=MemoryAddress{ offset=0x7fff202f60bc }, scope=jdk.internal.foreign.ResourceScopeImpl$GlobalScopeImpl@bf6ec23a]@pshipton, we could send a bug request with the proposed fix above to OpenJDK to see whether it can be accepted in this case.
pshipton
commented
2 years ago Sure, you have done that before, just post to the mailing list.
tajila
commented
2 years ago I think you need an account to open a bug request.
Perhaps if you describe the problem in detail maybe @andrew-m-leonard can open it for you
pshipton
commented
2 years ago Cheng did successfully send another issue to the mailing list which was subsequently resolved by OpenJDK.
ChengJin01
commented
2 years ago The bug request with the proposed fix has been created at https://mail.openjdk.java.net/pipermail/core-libs-dev/2022-February/086254.html.
ChengJin01
commented
2 years ago Here's the response from Oracle at https://mail.openjdk.java.net/pipermail/core-libs-dev/2022-February/086285.html
Mandy Chung mandy.chung at oracle.com
Thu Feb 24 17:42:17 UTC 2022
This is not an issue and does not affect the runtiime. When it fails to
load a native library, the VM will throw UnsatisfiedLinkError (see
JVM_LoadLibrary). The return value is only important for the JNI case
and calling System::loadLibrary on the system with dynamic linker cache
(Big Sur) since throwExceptionIfFail == false.
I agree that the JNI_TRUE return value for non-JNI case (i.e. raw
library library mechanism) is confusing to the readers. We should fix
it to return handle != 0L to match the specified return value (true only
when succeed).
I will file an issue.
MandyThe problem (a non-JNI case) doesn't apply to OpenJDK/Hospot as all their libraries are placed in jdk/lib without any nested directories In any case, they admitted the potential issue with the code and will fix it up based on our proposal to resolve the problem detected on our side in the test.
pshipton
commented
2 years ago @ChengJin01 can you please exclude the test for aarch64_mac until it can be resolved.
ChengJin01
commented
2 years ago @pshipton, the PR at https://github.com/adoptium/aqa-tests/pull/3442 has been created to exclude the test suite as it fails on macOS (including x86 and Aarch64).
tajila
commented
2 years ago @ChengJin01 is this resolved?
ChengJin01
commented
2 years ago The issue was resolved with our own fix in JDK17/18/19+ at https://github.com/ibmruntimes/openj9-openjdk-jdk17/pull/112/files#diff-9658a8d1507ae5132a614d4c38ed6589ebab5bed19c3d03f726585aeb49dce29, https://github.com/ibmruntimes/openj9-openjdk-jdk18/pull/57/files#diff-9658a8d1507ae5132a614d4c38ed6589ebab5bed19c3d03f726585aeb49dce29, https://github.com/ibmruntimes/openj9-openjdk-jdk19/pull/5/files#diff-9658a8d1507ae5132a614d4c38ed6589ebab5bed19c3d03f726585aeb49dce29 and https://github.com/ibmruntimes/openj9-openjdk-jdk/pull/457/files#diff-9658a8d1507ae5132a614d4c38ed6589ebab5bed19c3d03f726585aeb49dce29.
I will need to enable this test suite at https://github.com/adoptium/aqa-tests.
ChengJin01
commented
2 years ago PR is created at https://github.com/adoptium/aqa-tests/pull/4050 to enable the test suite.
ChengJin01
commented
2 years ago Close this issue given https://github.com/adoptium/aqa-tests/pull/4050 was verified and merged.
babsingh
commented
1 year ago @ChengJin01 re https://github.com/eclipse-openj9/openj9/issues/14487#issuecomment-1282625809, can we remove the test excluded label for this issue? This label should be removed once the tests are re-enabled.
ChengJin01
commented
1 year ago Just removed test excluded as the test already works fine on macOS.
https://openj9-jenkins.osuosl.org/job/Test_openjdk18_j9_sanity.openjdk_aarch64_mac_Release/1 jdk_foreign_1 java/foreign/TestFunctionDescriptor.java
@knn-k