Saint's Log

Investigating a jtreg Failure

Download jtreg from the AdoptOpenJDK dependency pipeline (adoptopenjdk.net). For this investigation, I’ll be using my MacBook M1 running Monterey 12.1.

mkdir investigate
cd investigate
git clone https://github.com/openjdk/jdk11u

# Download jtreg 6
curl -Lo jtreg-6+1.tar.gz https://ci.adoptopenjdk.net/view/Dependencies/job/dependency_pipeline/lastSuccessfulBuild/artifact/jtreg/jtreg-6+1.tar.gz

tar xzfv jtreg-6+1.tar.gz

cd jdk11u

We switch the current directory to the root of jdk11u repo so that test paths are relative to the repo root. I will assume that we’re in the jdk11u repo root directory and are using the directory structure generated by the commands above. To see a detailed list of all the jtreg options, run this command:

../jtreg/bin/jtreg -help all

Now let us try to run a jtreg test, specifically AmazonCA.java:

../jtreg/bin/jtreg test/jdk/security/infra/java/security/cert/CertPathValidator/certification/AmazonCA.java

There are some failure messages but it looks like a test ran.

failed to get value for vm.hasJFR
java.lang.UnsatisfiedLinkError: 'boolean sun.hotspot.WhiteBox.isJFRIncludedInVmBuild()'
	at sun.hotspot.WhiteBox.isJFRIncludedInVmBuild(Native Method)
	at requires.VMProps.vmHasJFR(VMProps.java:343)
	at requires.VMProps$SafeMap.put(VMProps.java:72)
	at requires.VMProps.call(VMProps.java:107)
	at requires.VMProps.call(VMProps.java:60)
	at com.sun.javatest.regtest.agent.GetJDKProperties.run(GetJDKProperties.java:80)
	at com.sun.javatest.regtest.agent.GetJDKProperties.main(GetJDKProperties.java:54)
failed to get value for vm.aot.enabled
java.lang.UnsatisfiedLinkError: 'int sun.hotspot.WhiteBox.aotLibrariesCount()'
	at sun.hotspot.WhiteBox.aotLibrariesCount(Native Method)
	at requires.VMProps.vmAotEnabled(VMProps.java:408)
	at requires.VMProps$SafeMap.put(VMProps.java:72)
	at requires.VMProps.call(VMProps.java:112)
	at requires.VMProps.call(VMProps.java:60)
	at com.sun.javatest.regtest.agent.GetJDKProperties.run(GetJDKProperties.java:80)
	at com.sun.javatest.regtest.agent.GetJDKProperties.main(GetJDKProperties.java:54)
.
.
.
Test results: passed: 1
Report written to /Users/saint/repos/java/jdk11u/JTreport/html/report.html
Results written to /Users/saint/repos/java/jdk11u/JTwork

Are these failure messages concerning given that the test passed? Reviewing the test report suggests not. The report keywords mention bug 8233223, which must be Bug ID: JDK-8233223 Add Amazon Root CA certificates (java.com). From the look of things, the java.lang.UnsatisfiedLinkErrors can be safely ignored (for this test anyway). That said, let us dig into these errors to ensure we understand what is happening.

The immediate cause of these errors is the failure to get the values for the SafeMap in VMProps.java. This raises the question of which JDK is being used by jtreg? My MacBook has both JDK11 and JDK17. The default java version is:

java -version
openjdk version "17.0.1" 2021-10-19 LTS
OpenJDK Runtime Environment Microsoft-28056 (build 17.0.1+12-LTS)
OpenJDK 64-Bit Server VM Microsoft-28056 (build 17.0.1+12-LTS, mixed mode)

Let’s ensure jtreg is using JDK11 by setting JTREG_JAVA.

JTREG_JAVA=/Library/Java/JavaVirtualMachines/microsoft-11.jdk/Contents/Home

$JTREG_JAVA/bin/java -version

openjdk version "11.0.14" 2022-01-18 LTS
OpenJDK Runtime Environment Microsoft-30257 (build 11.0.14+9-LTS)
OpenJDK 64-Bit Server VM Microsoft-30257 (build 11.0.14+9-LTS, mixed mode)

../jtreg/bin/jtreg test/jdk/security/infra/java/security/cert/CertPathValidator/certification/AmazonCA.java

We still see the same warnings though so let us explicitly use the -jdk option:

../jtreg/bin/jtreg -jdk:$JTREG_JAVA test/jdk/security/infra/java/security/cert/CertPathValidator/certification/AmazonCA.java

We now get an interesting error message indicating that the -jdk option was using the newer JDK17.

Exception while calling user-specified class: requires.VMProps
java.lang.UnsupportedClassVersionError: requires/VMProps has been compiled by a more recent version of the Java Runtime (class file version 61.0), this version of the Java Runtime only recognizes class file versions up to 55.0
	at java.base/java.lang.ClassLoader.defineClass1(Native Method)
	...
	at java.base/java.lang.ClassLoader.loadClass(ClassLoader.java:522)
	at java.base/java.lang.Class.forName0(Native Method)
	at java.base/java.lang.Class.forName(Class.java:315)
	at com.sun.javatest.regtest.agent.GetJDKProperties.run(GetJDKProperties.java:78)
	at com.sun.javatest.regtest.agent.GetJDKProperties.main(GetJDKProperties.java:54)
failed to get JDK properties for /Library/Java/JavaVirtualMachines/microsoft-11.jdk/Contents/Home/bin/java ; exit code 1
Error: failed to get JDK properties for /Library/Java/JavaVirtualMachines/microsoft-11.jdk/Contents/Home/bin/java ; exit code 1

On my machine, I can remove these files as follows:

ls -l /Users/saint/repos/java/jdk11u/JTwork/extraPropDefns/classes/requires

rm -fr /Users/saint/repos/java/jdk11u/JTwork/extraPropDefns/classes/requires

Rerunning the test now results in a single (different) UnsatisfiedLinkError AND a test failure! However, we now have a properly set up environment since we control the JDK version tested by jtreg.

jdk11u % ../jtreg/bin/jtreg -jdk:$JTREG_JAVA test/jdk/security/infra/java/security/cert/CertPathValidator/certification/AmazonCA.java

failed to get value for vm.musl
java.lang.UnsatisfiedLinkError: 'java.lang.String sun.hotspot.WhiteBox.getLibcName()'
	at sun.hotspot.WhiteBox.getLibcName(Native Method)
	at requires.VMProps.isMusl(VMProps.java:514)
	at requires.VMProps$SafeMap.put(VMProps.java:72)
	at requires.VMProps.call(VMProps.java:122)
	at requires.VMProps.call(VMProps.java:60)
	at com.sun.javatest.regtest.agent.GetJDKProperties.run(GetJDKProperties.java:80)
	at com.sun.javatest.regtest.agent.GetJDKProperties.main(GetJDKProperties.java:54)
Test results: failed: 1
Report written to /Users/saint/repos/java/jdk11u/JTreport/html/report.html
Results written to /Users/saint/repos/java/jdk11u/JTwork
Error: Some tests failed or other problems occurred.

Now here’s an interesting question: why doesn’t this approach yield identical result to setting the -jdk flag to this same JTREG_JAVA path?

JTREG_JAVA=/Library/Java/JavaVirtualMachines/microsoft-11.jdk/Contents/Home

../jtreg/bin/jtreg test/jdk/security/infra/java/security/cert/CertPathValidator/certification/AmazonCA.java

After doing some printf (or rather echo) debugging and observing an empty string for JTREG_JAVA, the culprit turns out to be the difference between a shell variable and an environment variable. See command line – What is the difference in usage between shell variables and environment variables? – Unix & Linux Stack Exchange. For the jtreg script to pull in this value of JTREG_JAVA, it needs to be an environment variable. It should therefore show up when this command is executed:

printenv | grep -i java

The proper way to execute this test then is:

JTREG_JAVA=/Library/Java/JavaVirtualMachines/microsoft-11.jdk/Contents/Home

export JTREG_JAVA

../jtreg/bin/jtreg test/jdk/security/infra/java/security/cert/CertPathValidator/certification/AmazonCA.java

The outcome of the experiment so far though is that the AmazonCA test appears to fail when run with JDK11 and pass when run with JDK17 (of the respective versions). To convince ourselves that the infrastructure is fine, we can run this test with JDK11 (which is our focus) after exporting JTREG_JAVA.

../jtreg/bin/jtreg test/hotspot/jtreg/compiler/aot/cli/IncorrectAOTLibraryTest.java

This test passes, despite the single UnsatisfiedLinkError printed out.

failed to get value for vm.musl
java.lang.UnsatisfiedLinkError: 'java.lang.String sun.hotspot.WhiteBox.getLibcName()'
	at sun.hotspot.WhiteBox.getLibcName(Native Method)
	at requires.VMProps.isMusl(VMProps.java:514)
	at requires.VMProps$SafeMap.put(VMProps.java:72)
	at requires.VMProps.call(VMProps.java:122)
	at requires.VMProps.call(VMProps.java:60)
	at com.sun.javatest.regtest.agent.GetJDKProperties.run(GetJDKProperties.java:80)
	at com.sun.javatest.regtest.agent.GetJDKProperties.main(GetJDKProperties.java:54)
Test results: passed: 1
Report written to /Users/saint/repos/java/jdk11u/JTreport/html/report.html
Results written to /Users/saint/repos/java/jdk11u/JTwork

An Interesting Test

The above experimentation was inspired by AotInvokeDynamic2AotTest.java. The first time I tried to run this test, I used this command line.

../jtreg/bin/jtreg test/hotspot/jtreg/compiler/aot/calls/fromAot/AotInvokeDynamic2AotTest.java

We first set of 5 UnsatisfiedLinkError failures in the previous experiment were displayed but no tests were executed.

...
Test results: no tests selected
Report written to /Users/saint/repos/java/jdk11u/JTreport/html/report.html

This was happening while jtreg was using JDK17 and one of the values that could not be get()ed vm.aot.enabled. Could that be why there were no selected tests? Ignoring that rabbit hole for now sine jdk11u is our focus. We can now run the test with JTREG_JAVA exported. The test is now run but fails with this message in JTreport/text/summary.txt:

compiler/aot/calls/fromAot/AotInvokeDynamic2AotTest.java  Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: Expected to get exit value of [0]

To see more details about the test failure, use the -verbose flag:

../jtreg/bin/jtreg -verbose:fail,error,summary test/hotspot/jtreg/compiler/aot/calls/fromAot/AotInvokeDynamic2AotTest.java

Here is the a portion of the output of the test run. Notice the linker error in there!

ACTION: build -- Passed. All files up to date
REASON: Named class compiled on demand
TIME:   0.0 seconds
messages:
command: build compiler.aot.AotCompiler
reason: Named class compiled on demand
elapsed time (seconds): 0.0

ACTION: driver -- Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: Expected to get exit value of [0]
REASON: User specified action: run driver compiler.aot.AotCompiler -libname AotInvokeDynamic2AotTest.so -class compiler.calls.common.InvokeDynamic -extraopt -XX:+UnlockDiagnosticVMOptions -extraopt -XX:+WhiteBoxAPI -extraopt -Xbootclasspath/a:. 
TIME:   4.821 seconds
messages:
command: driver compiler.aot.AotCompiler -libname AotInvokeDynamic2AotTest.so -class compiler.calls.common.InvokeDynamic -extraopt -XX:+UnlockDiagnosticVMOptions -extraopt -XX:+WhiteBoxAPI -extraopt -Xbootclasspath/a:.
reason: User specified action: run driver compiler.aot.AotCompiler -libname AotInvokeDynamic2AotTest.so -class compiler.calls.common.InvokeDynamic -extraopt -XX:+UnlockDiagnosticVMOptions -extraopt -XX:+WhiteBoxAPI -extraopt -Xbootclasspath/a:. 
Mode: othervm
Additional options from @modules: --add-modules java.base --add-exports java.base/jdk.internal.org.objectweb.asm=ALL-UNNAMED --add-exports java.base/jdk.internal.misc=ALL-UNNAMED
elapsed time (seconds): 4.821
configuration:
Boot Layer
  add modules: java.base                                
  add exports: java.base/jdk.internal.misc              ALL-UNNAMED
               java.base/jdk.internal.org.objectweb.asm ALL-UNNAMED

STDOUT:
Command line: [/usr/bin/ld -v]
@(#)PROGRAM:ld  PROJECT:ld64-764
BUILD 11:22:50 Apr 28 2022
configured to support archs: armv6 armv7 armv7s arm64 arm64e arm64_32 i386 x86_64 x86_64h armv6m armv7k armv7m armv7em
LTO support using: LLVM version 13.1.6, (clang-1316.0.21.2.5) (static support for 28, runtime is 28)
TAPI support using: Apple TAPI version 13.1.6 (tapi-1316.0.7.3)

found working linker: /usr/bin/ld
Command line: [/Library/Java/JavaVirtualMachines/microsoft-11.jdk/Contents/Home/bin/jaotc -J-XX:+UnlockDiagnosticVMOptions -J-XX:+WhiteBoxAPI -J-Xbootclasspath/a:. -J-classpath -J/Users/saint/repos/java/jdk11u/JTwork/classes/compiler/aot/calls/fromAot/AotInvokeDynamic2AotTest.d:/Users/saint/repos/java/jdk11u/JTwork/classes/test/lib:/Users/saint/repos/java/jdk11u/JTwork/classes/testlibrary:/Users/saint/repos/java/jdk11u/JTwork/classes:/Users/saint/repos/java/jdk11u/test/hotspot/jtreg/compiler/aot/calls/fromAot --compile-with-assertions --info --output AotInvokeDynamic2AotTest.so --class-name compiler.calls.common.InvokeDynamic -J-ea -J-esa -J-Xmixed]
Compiling AotInvokeDynamic2AotTest.so...
1 classes found (22 ms)
9 methods total, 8 methods to compile (12 ms)
Compiling with 10 threads
.
8 methods compiled, 0 methods failed (2785 ms)
Parsing compiled code (7 ms)
Processing metadata (46 ms)
Preparing stubs binary (3 ms)
Preparing compiled binary (2 ms)
Creating binary: AotInvokeDynamic2AotTest.so.o (18 ms)
Creating shared library: AotInvokeDynamic2AotTest.so (30 ms)
Exception in thread "main" java.lang.InternalError: ld: dynamic main executables must link with libSystem.dylib for architecture x86_64
	at jdk.aot@11.0.14/jdk.tools.jaotc.Linker.link(Linker.java:142)
	at jdk.aot@11.0.14/jdk.tools.jaotc.Main.run(Main.java:262)
	at jdk.aot@11.0.14/jdk.tools.jaotc.Main.run(Main.java:133)
	at jdk.aot@11.0.14/jdk.tools.jaotc.Main.main(Main.java:89)

Why on earth is there an error about x86_64 on my M1? Here is the failing command line, listed separately for easy execution:

/Library/Java/JavaVirtualMachines/microsoft-11.jdk/Contents/Home/bin/jaotc -J-XX:+UnlockDiagnosticVMOptions -J-XX:+WhiteBoxAPI -J-Xbootclasspath/a:. -J-classpath -J/Users/saint/repos/java/jdk11u/JTwork/classes/compiler/aot/calls/fromAot/AotInvokeDynamic2AotTest.d:/Users/saint/repos/java/jdk11u/JTwork/classes/test/lib:/Users/saint/repos/java/jdk11u/JTwork/classes/testlibrary:/Users/saint/repos/java/jdk11u/JTwork/classes:/Users/saint/repos/java/jdk11u/test/hotspot/jtreg/compiler/aot/calls/fromAot --compile-with-assertions --info --output AotInvokeDynamic2AotTest.so --class-name compiler.calls.common.InvokeDynamic -J-ea -J-esa -J-Xmixed

Once this command completes (and fails), a file named AotInvokeDynamic2AotTest.so.o exists on disk. The format of the ld command can be deduced from Linker.java:101. The ld command can then be directly invoked to see the actual failure:

% ld -dylib -o AotInvokeDynamic2AotTest.so AotInvokeDynamic2AotTest.so.o
ld: dynamic main executables must link with libSystem.dylib for architecture x86_64

As per Clang -nostdlib option not working | Apple Developer Forums I tried adding the -lSystem option but that was not sufficient.

% ld -lSystem -dylib -o AotInvokeDynamic2AotTest.so AotInvokeDynamic2AotTest.so.o
ld: library not found for -lSystem

Exploring Mach-O, Part 1 | g.p. anders (gpanders.com) pointed out that the solution is to include the path to the lib folder as well!

ld -L /Library/Developer/CommandLineTools/SDKs/MacOSX.sdk/usr/lib/ -lSystem -dylib -o AotInvokeDynamic2AotTest.so AotInvokeDynamic2AotTest.so.o

The proper way to address this test failure then is to fix Linker.java to pass these additional flags to ld.