search

eclipse-openj9 / openj9

Eclipse OpenJ9: A Java Virtual Machine for OpenJDK that's optimized for small footprint, fast start-up, and high throughput. Builds on Eclipse OMR (https://github.com/eclipse/omr) and combines with the Extensions for OpenJDK for OpenJ9 repo.
Other
3.27k stars 721 forks source link

javax/xml/crypto/dsig/LogParameters.java - RuntimeException: Unexpected log output #13981

Open JasonFengJ9 opened 2 years ago

JasonFengJ9 commented 2 years ago

Failure link

From an internal build job/Test_openjdk17_j9_extended.openjdk_ppc64_aix/30/ (paix824):

openjdk version "17.0.1" 2021-10-19
IBM Semeru Runtime Certified Edition 17.0.1+12 (build 17.0.1+12)
Eclipse OpenJ9 VM 17.0.1+12 (build master-0f828acf4, JRE 17 AIX ppc64-64-Bit Compressed References 20211120_38 (JIT enabled, AOT enabled)
OpenJ9   - 0f828acf4
OMR      - 83214375c
JCL      - df273956de9 based on jdk-17.0.1+12)

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

Optional info

Failure output (captured from console output)

[2021-11-21T02:27:34.548Z] Running test jdk_security2_0 ...
[2021-11-21T02:27:34.548Z] ===============================================
[2021-11-21T02:27:34.548Z] jdk_security2_0 Start Time: Sat Nov 20 21:45:00 2021 Epoch Time (ms): 1637466300575
[2021-11-21T02:27:34.548Z] "/home/jenkins/workspace/Test_openjdk17_j9_extended.openjdk_ppc64_aix/openjdkbinary/j2sdk-image/bin/java" -Xshareclasses:destroyAll; "/home/jenkins/workspace/Test_openjdk17_j9_extended.openjdk_ppc64_aix/openjdkbinary/j2sdk-image/bin/java" -Xshareclasses:groupAccess,destroyAll; echo "cache cleanup done";
[2021-11-21T02:27:34.548Z] JVMSHRC005I No shared class caches available
[2021-11-21T02:27:34.548Z] JVMSHRC005I No shared class caches available
[2021-11-21T02:27:34.548Z] cache cleanup done
[2021-11-21T02:27:34.548Z] variation: Mode150
[2021-11-21T02:27:34.548Z] JVM_OPTIONS:  -XX:+UseCompressedOops 

[2021-11-21T02:33:40.414Z] --------------------------------------------------
[2021-11-21T02:33:40.414Z] TEST: javax/xml/crypto/dsig/LogParameters.java

[2021-11-21T02:33:40.561Z] STDERR:
[2021-11-21T02:33:40.561Z] java.lang.RuntimeException: Unexpected log output: 
[2021-11-21T02:33:40.561Z]  at LogParameters.main(LogParameters.java:55)
[2021-11-21T02:33:40.561Z]  at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[2021-11-21T02:33:40.561Z]  at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
[2021-11-21T02:33:40.561Z]  at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[2021-11-21T02:33:40.561Z]  at java.base/java.lang.reflect.Method.invoke(Method.java:568)
[2021-11-21T02:33:40.561Z]  at com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:312)
[2021-11-21T02:33:40.561Z]  at java.base/java.lang.Thread.run(Thread.java:884)
[2021-11-21T02:33:40.561Z] 
[2021-11-21T02:33:40.561Z] JavaTest Message: Test threw exception: java.lang.RuntimeException
[2021-11-21T02:33:40.561Z] JavaTest Message: shutting down test
[2021-11-21T02:33:40.561Z] 
[2021-11-21T02:33:40.561Z] 
[2021-11-21T02:33:40.561Z] TEST RESULT: Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: Unexpected log output:
[2021-11-21T02:33:40.561Z] --------------------------------------------------
[2021-11-21T02:33:41.273Z] Test results: passed: 209; failed: 1
[2021-11-21T02:33:51.493Z] Report written to /home/jenkins/workspace/Test_openjdk17_j9_extended.openjdk_ppc64_aix/jvmtest/openjdk/report/html/report.html
[2021-11-21T02:33:51.493Z] Results written to /home/jenkins/workspace/Test_openjdk17_j9_extended.openjdk_ppc64_aix/aqa-tests/TKG/output_16374369179803/jdk_security2_0/work
[2021-11-21T02:33:51.493Z] Error: Some tests failed or other problems occurred.
[2021-11-21T02:33:51.493Z] 
[2021-11-21T02:33:51.493Z] jdk_security2_0_FAILED

It is a weekly run test, this is a first occurrence but the test didn't finish in previous two weeks. Edit : 50x grinder at job/Grinder/19667/ - 3/50 failed.

pshipton commented 2 years ago

Is this a new test, regression, highly intermittent, or what?

JasonFengJ9 commented 2 years ago

Observed at JDK17 0.30.0-m1 job/Test_openjdk17_j9_extended.openjdk_x86-64_windows/29/

openjdk version "17.0.1" 2021-10-19
IBM Semeru Runtime Open Edition 17.0.1.0-m1 (build 17.0.1+12)
Eclipse OpenJ9 VM 17.0.1.0-m1 (build openj9-0.30.0-m1a, JRE 17 Windows Server 2016 amd64-64-Bit Compressed References 20211202_50 (JIT enabled, AOT enabled)
OpenJ9   - 8158af43b
OMR      - 8d10f065c
JCL      - 52863698c35 based on jdk-17.0.1+12)

[2021-12-03T05:39:55.676Z] variation: Mode650
[2021-12-03T05:39:55.676Z] JVM_OPTIONS:  -XX:-UseCompressedOops 

[2021-12-03T05:45:47.253Z] --------------------------------------------------
[2021-12-03T05:45:47.253Z] TEST: javax/xml/crypto/dsig/LogParameters.java

[2021-12-03T05:45:47.256Z] STDERR:
[2021-12-03T05:45:47.256Z] java.lang.RuntimeException: Unexpected log output: 
[2021-12-03T05:45:47.256Z]  at LogParameters.main(LogParameters.java:55)
[2021-12-03T05:45:47.256Z]  at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[2021-12-03T05:45:47.256Z]  at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
[2021-12-03T05:45:47.256Z]  at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[2021-12-03T05:45:47.256Z]  at java.base/java.lang.reflect.Method.invoke(Method.java:568)
[2021-12-03T05:45:47.256Z]  at com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:312)
[2021-12-03T05:45:47.256Z]  at java.base/java.lang.Thread.run(Thread.java:884)
[2021-12-03T05:45:47.256Z] 
[2021-12-03T05:45:47.256Z] JavaTest Message: Test threw exception: java.lang.RuntimeException
[2021-12-03T05:45:47.256Z] JavaTest Message: shutting down test
[2021-12-03T05:45:47.256Z] 
[2021-12-03T05:45:47.256Z] 
[2021-12-03T05:45:47.256Z] TEST RESULT: Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: Unexpected log output:
[2021-12-03T05:45:47.256Z] --------------------------------------------------
[2021-12-03T05:47:34.130Z] Test results: passed: 208; failed: 1
[2021-12-03T05:48:05.539Z] Report written to C:\Users\jenkins\workspace\Test_openjdk17_j9_extended.openjdk_x86-64_windows\jvmtest\openjdk\report\html\report.html
[2021-12-03T05:48:05.539Z] Results written to C:\Users\jenkins\workspace\Test_openjdk17_j9_extended.openjdk_x86-64_windows\aqa-tests\TKG\output_16384948645738\jdk_security2_1\work
[2021-12-03T05:48:05.539Z] Error: Some tests failed or other problems occurred.
[2021-12-03T05:48:05.539Z] 
[2021-12-03T05:48:05.539Z] jdk_security2_1_FAILED
JasonFengJ9 commented 2 years ago

Observed at job/Test_openjdk17_j9_extended.openjdk_x86-64_linux/38/(ub20x64rt3-7)

java version "17.0.1" 2021-10-19
IBM Semeru Runtime Certified Edition 17.0.1.0 (build 17.0.1+12)
Eclipse OpenJ9 VM 17.0.1.0 (build openj9-0.29.1, JRE 17 Linux amd64-64-Bit Compressed References 20211220_64 (JIT enabled, AOT enabled)
OpenJ9   - 7d055dfcb
OMR      - e30892e2b
JCL      - 233aee461cd based on jdk-17.0.1+12)

[2021-12-20T20:10:55.047Z] variation: Mode650
[2021-12-20T20:10:55.047Z] JVM_OPTIONS:  -XX:-UseCompressedOops 

[2021-12-20T20:16:00.234Z] --------------------------------------------------
[2021-12-20T20:16:00.234Z] TEST: javax/xml/crypto/dsig/LogParameters.java

[2021-12-20T20:16:00.235Z] STDERR:
[2021-12-20T20:16:00.235Z] java.lang.RuntimeException: Unexpected log output: 
[2021-12-20T20:16:00.235Z]  at LogParameters.main(LogParameters.java:55)
[2021-12-20T20:16:00.235Z]  at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[2021-12-20T20:16:00.235Z]  at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
[2021-12-20T20:16:00.235Z]  at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[2021-12-20T20:16:00.235Z]  at java.base/java.lang.reflect.Method.invoke(Method.java:568)
[2021-12-20T20:16:00.235Z]  at com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:312)
[2021-12-20T20:16:00.235Z]  at java.base/java.lang.Thread.run(Thread.java:884)
[2021-12-20T20:16:00.235Z] 
[2021-12-20T20:16:00.235Z] JavaTest Message: Test threw exception: java.lang.RuntimeException
[2021-12-20T20:16:00.235Z] JavaTest Message: shutting down test
[2021-12-20T20:16:00.235Z] 
[2021-12-20T20:16:00.235Z] 
[2021-12-20T20:16:00.235Z] TEST RESULT: Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: Unexpected log output:
[2021-12-20T20:16:00.235Z] --------------------------------------------------
[2021-12-20T20:16:00.235Z] Test results: passed: 209; failed: 1
[2021-12-20T20:16:14.338Z] Report written to /home/jenkins/workspace/Test_openjdk17_j9_extended.openjdk_x86-64_linux/jvmtest/openjdk/report/html/report.html
[2021-12-20T20:16:14.338Z] Results written to /home/jenkins/workspace/Test_openjdk17_j9_extended.openjdk_x86-64_linux/aqa-tests/TKG/output_16400175669790/jdk_security2_1/work
[2021-12-20T20:16:14.338Z] Error: Some tests failed or other problems occurred.
[2021-12-20T20:16:14.338Z] 
[2021-12-20T20:16:14.338Z] jdk_security2_1_FAILED

17/200 failed at job/Grinder/20100.

JasonFengJ9 commented 2 years ago

job/Test_openjdk17_j9_extended.openjdk_ppc64_aix/58/(pll011)

java version "17.0.3" 2022-04-19
IBM Semeru Runtime Certified Edition 17.0.3.0-rc1 (build 17.0.3+7)
Eclipse OpenJ9 VM 17.0.3.0-rc1 (build openj9-0.32.0-rc1, JRE 17 AIX ppc64-64-Bit Compressed References 20220420_129 (JIT enabled, AOT enabled)
OpenJ9   - 9a84ec34e
OMR      - ab24b6666
JCL      - 0e919023eb9 based on jdk-17.0.3+7)

[2022-04-21T10:58:58.421Z] java.lang.RuntimeException: Unexpected log output: 
[2022-04-21T10:58:58.421Z]  at LogParameters.main(LogParameters.java:55)
[2022-04-21T10:58:58.421Z]  at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[2022-04-21T10:58:58.421Z]  at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
[2022-04-21T10:58:58.421Z]  at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[2022-04-21T10:58:58.421Z]  at java.base/java.lang.reflect.Method.invoke(Method.java:568)
[2022-04-21T10:58:58.421Z]  at com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:312)
[2022-04-21T10:58:58.421Z]  at java.base/java.lang.Thread.run(Thread.java:889)
[2022-04-21T10:58:58.421Z] 
[2022-04-21T10:58:58.421Z] JavaTest Message: Test threw exception: java.lang.RuntimeException
pshipton commented 2 years ago

The problem seems to be the logger is getting gc'ed before the data is logged. The log level is set to ALL, and if the logger is gc'ed before this logger is used, then a new logger is created which doesn't have the log level set to ALL, and nothing is logged. The test can be fixed by keeping the original logger alive until after the data is logged.

JasonFengJ9 commented 1 year ago

Seen on JDK11 0.35 rc1 internal build(win16x64rt2-8)

openjdk version "11.0.17" 2022-10-18
IBM Semeru Runtime Open Edition 11.0.17.0-rc1 (build 11.0.17+8)
Eclipse OpenJ9 VM 11.0.17.0-rc1 (build openj9-0.35.0-rc1, JRE 11 Windows Server 2016 amd64-64-Bit Compressed References 20221020_478 (JIT enabled, AOT enabled)
OpenJ9   - e04a7f6c1
OMR      - 85a21674f
JCL      - a94c231303 based on jdk-11.0.17+8)

[2022-10-20T05:51:11.981Z] variation: Mode650
[2022-10-20T05:51:12.422Z] JVM_OPTIONS:  -XX:-UseCompressedOops 

[2022-10-20T05:56:33.711Z] TEST: javax/xml/crypto/dsig/LogParameters.java

[2022-10-20T05:56:33.713Z] STDERR:
[2022-10-20T05:56:33.713Z] java.lang.RuntimeException: Unexpected log output: 
[2022-10-20T05:56:33.713Z]  at LogParameters.main(LogParameters.java:60)
[2022-10-20T05:56:33.713Z]  at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[2022-10-20T05:56:33.713Z]  at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
[2022-10-20T05:56:33.713Z]  at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[2022-10-20T05:56:33.713Z]  at java.base/java.lang.reflect.Method.invoke(Method.java:566)
[2022-10-20T05:56:33.713Z]  at com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:312)
[2022-10-20T05:56:33.713Z]  at java.base/java.lang.Thread.run(Thread.java:839)
[2022-10-20T05:56:33.713Z] 
[2022-10-20T05:56:33.713Z] JavaTest Message: Test threw exception: java.lang.RuntimeException
[2022-10-20T05:56:33.713Z] JavaTest Message: shutting down test
[2022-10-20T05:56:33.713Z] 
[2022-10-20T05:56:33.713Z] 
[2022-10-20T05:56:33.713Z] TEST RESULT: Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: Unexpected log output:
[2022-10-20T05:56:33.713Z] --------------------------------------------------
[2022-10-20T05:58:00.305Z] Test results: passed: 209; failed: 1
[2022-10-20T05:58:31.285Z] Report written to C:\Users\jenkins\workspace\Test_openjdk11_j9_extended.openjdk_x86-64_windows\aqa-tests\TKG\output_16662370908054\jdk_security2_1\report\html\report.html
[2022-10-20T05:58:31.285Z] Results written to C:\Users\jenkins\workspace\Test_openjdk11_j9_extended.openjdk_x86-64_windows\aqa-tests\TKG\output_16662370908054\jdk_security2_1\work
[2022-10-20T05:58:31.285Z] Error: Some tests failed or other problems occurred.
[2022-10-20T05:58:31.285Z] 
[2022-10-20T05:58:31.285Z] jdk_security2_1_FAILED