openJcePlusTests_0 InvalidKeyException: Point has small order & j9mm.141 ASSERTION FAILED omr/gc/base/standard/Scavenger.cpp:1649: ((false))

[JasonFengJ9]

Failure link

From internal Test_openjdk23_j9_extended.functional_s390x_linux_fips140_3_openjceplusfips (rhel10s390x-rtbeta-2)

openjdk version "23.0.1-beta" 2024-10-15
IBM Semeru Runtime Open Edition 23.0.1+11-202501181703 (build 23.0.1-beta+11-202501181703)
Eclipse OpenJ9 VM 23.0.1+11-202501181703 (build master-c1949d7088, JRE 23 Linux s390x-64-Bit Compressed References 20250118_86 (JIT enabled, AOT enabled)
OpenJ9   - c1949d7088
OMR      - 6bfb20f78
JCL      - d98479bbe based on jdk-23.0.1+11)

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

Optional info

Failure output (captured from console output)

[2025-01-18T17:53:53.213Z] variation: NoOptions
[2025-01-18T17:53:53.213Z] JVM_OPTIONS:   -Dsemeru.fips=true -Dsemeru.customprofile=OpenJCEPlusFIPS

[2025-01-18T17:54:23.322Z] [INFO] 
[2025-01-18T17:54:23.322Z] [INFO] -------------------------------------------------------
[2025-01-18T17:54:23.322Z] [INFO]  T E S T S
[2025-01-18T17:54:23.322Z] [INFO] -------------------------------------------------------
[2025-01-18T17:54:27.214Z] [INFO] Running ibm.jceplus.junit.TestIntegration
[2025-01-18T17:54:27.214Z] [INFO] Running ibm.jceplus.junit.openjceplus.integration.TestAll
[2025-01-18T17:54:27.214Z] [INFO] Running ibm.jceplus.junit.openjceplus.integration.TestTLS
[2025-01-18T17:54:27.214Z] Testing TLSv1.3 rsa_pkcs1_sha1 TLS_AES_128_GCM_SHA256
[2025-01-18T17:54:27.214Z] Server listining on port: 39465
[2025-01-18T17:54:27.214Z] javax.net.ssl.SSLHandshakeException: Could not generate secret
[2025-01-18T17:54:27.214Z] 	at java.base/sun.security.ssl.KAKeyDerivation.t13DeriveKey(KAKeyDerivation.java:127)
[2025-01-18T17:54:27.214Z] 	at java.base/sun.security.ssl.KAKeyDerivation.deriveKey(KAKeyDerivation.java:63)
[2025-01-18T17:54:27.214Z] 	at java.base/sun.security.ssl.ServerHello$T13ServerHelloProducer.produce(ServerHello.java:601)
[2025-01-18T17:54:27.214Z] 	at java.base/sun.security.ssl.SSLHandshake.produce(SSLHandshake.java:437)
[2025-01-18T17:54:27.214Z] 	at java.base/sun.security.ssl.ClientHello$T13ClientHelloConsumer.goServerHello(ClientHello.java:1243)
[2025-01-18T17:54:27.214Z] 	at java.base/sun.security.ssl.ClientHello$T13ClientHelloConsumer.consume(ClientHello.java:1179)
[2025-01-18T17:54:27.214Z] 	at java.base/sun.security.ssl.ClientHello$ClientHelloConsumer.onClientHello(ClientHello.java:837)
[2025-01-18T17:54:27.214Z] 	at java.base/sun.security.ssl.ClientHello$ClientHelloConsumer.consume(ClientHello.java:798)
[2025-01-18T17:54:27.214Z] 	at java.base/sun.security.ssl.SSLHandshake.consume(SSLHandshake.java:393)
[2025-01-18T17:54:27.214Z] 	at java.base/sun.security.ssl.HandshakeContext.dispatch(HandshakeContext.java:476)
[2025-01-18T17:54:27.214Z] 	at java.base/sun.security.ssl.HandshakeContext.dispatch(HandshakeContext.java:447)
[2025-01-18T17:54:27.214Z] 	at java.base/sun.security.ssl.TransportContext.dispatch(TransportContext.java:206)
[2025-01-18T17:54:27.214Z] 	at java.base/sun.security.ssl.SSLTransport.decode(SSLTransport.java:172)
[2025-01-18T17:54:27.214Z] 	at java.base/sun.security.ssl.SSLSocketImpl.decode(SSLSocketImpl.java:1507)
[2025-01-18T17:54:27.214Z] 	at java.base/sun.security.ssl.SSLSocketImpl.readHandshakeRecord(SSLSocketImpl.java:1422)
[2025-01-18T17:54:27.214Z] 	at java.base/sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:455)
[2025-01-18T17:54:27.214Z] 	at java.base/sun.security.ssl.SSLSocketImpl.ensureNegotiated(SSLSocketImpl.java:924)
[2025-01-18T17:54:27.214Z] 	at java.base/sun.security.ssl.SSLSocketImpl$AppInputStream.read(SSLSocketImpl.java:1015)
[2025-01-18T17:54:27.214Z] 	at java.base/sun.security.ssl.SSLSocketImpl$AppInputStream.read(SSLSocketImpl.java:975)
[2025-01-18T17:54:27.214Z] 	at ibm.jceplus.junit.base.integration.BaseTestTLS$Server.doServerSide(BaseTestTLS.java:126)
[2025-01-18T17:54:27.214Z] 	at ibm.jceplus.junit.base.integration.BaseTestTLS$Server.run(BaseTestTLS.java:148)
[2025-01-18T17:54:27.214Z] 	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
[2025-01-18T17:54:27.214Z] 	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
[2025-01-18T17:54:27.214Z] 	at java.base/java.lang.Thread.run(Thread.java:1587)
[2025-01-18T17:54:27.214Z] Caused by: java.security.InvalidKeyException: Point has small order.
[2025-01-18T17:54:27.214Z] 	at openjceplus/com.ibm.crypto.plus.provider.XDHKeyAgreement.engineDoPhase(XDHKeyAgreement.java:125)
[2025-01-18T17:54:27.214Z] 	at java.base/javax.crypto.KeyAgreement.doPhase(KeyAgreement.java:581)
[2025-01-18T17:54:27.214Z] 	at java.base/sun.security.ssl.KAKeyDerivation.t13DeriveKey(KAKeyDerivation.java:103)
[2025-01-18T17:54:27.214Z] 	... 23 more
[2025-01-18T17:54:27.214Z] Testing TLSv1.3 rsa_pkcs1_sha256 TLS_AES_128_GCM_SHA256
[2025-01-18T17:54:27.214Z] Server listining on port: 38873
[2025-01-18T17:54:27.214Z] Corruption in Evacuate at 00000000FF83C290: calculated object size 1334848000 larger than available 8142192, Forwarded Header at 000003FF8E6FDF38
[2025-01-18T17:54:27.214Z] 17:54:26.086 0x157bb00    j9mm.141    *   ** ASSERTION FAILED ** at /home/jenkins/workspace/build-scripts/jobs/jdk23u/jdk23u-linux-s390x-openj9/workspace/build/src/omr/gc/base/standard/Scavenger.cpp:1649: ((false))
[2025-01-18T17:54:27.214Z] Corruption in Evacuate at 00000000FF8342E8: calculated object size 1334848000 larger than available 8174872, Forwarded Header at 000003FF8F573AB0
[2025-01-18T17:54:27.214Z] 17:54:26.086 0x13e4800    j9mm.141    *   ** ASSERTION FAILED ** at /home/jenkins/workspace/build-scripts/jobs/jdk23u/jdk23u-linux-s390x-openj9/workspace/build/src/omr/gc/base/standard/Scavenger.cpp:1649: ((false))
[2025-01-18T17:54:27.214Z] JVMDUMP039I Processing dump event "traceassert", detail "" at 2025/01/18 17:54:26 - please wait.

[2025-01-18T17:54:29.233Z] openJcePlusTests_0_FAILED

openjdk23_j9_extended.functional_s390x_linux_fips140_3_openjceplusfips(rhel10s390x-rtbeta-1)

50x internal Grinder

FYI @jasonkatonica

[JasonFengJ9]

openjdk11_j9_extended.functional_s390x_linux_fips140_3_openjceplusfips

[2025-02-15T03:15:49.588Z] variation: NoOptions
[2025-02-15T03:15:49.588Z] JVM_OPTIONS:   -Dsemeru.fips=true -Dsemeru.customprofile=OpenJCEPlusFIPS

[2025-02-15T03:16:06.645Z] Testing TLSv1.3 rsa_pkcs1_sha1 TLS_AES_128_GCM_SHA256
[2025-02-15T03:16:06.645Z] Server listining on port: 42051
[2025-02-15T03:16:06.645Z] Corruption in Evacuate at 00000001FF642048: calculated object size 1649402008 larger than available 4317112, Forwarded Header at 000003FF859FDF40
[2025-02-15T03:16:06.645Z] 03:16:05.453 0x94e700    j9mm.141    *   ** ASSERTION FAILED ** at ../../../../../../omr/gc/base/standard/Scavenger.cpp:1649: ((false))
[2025-02-15T03:16:06.645Z] Corruption in Evacuate at 00000001FF64C310: calculated object size 1649402008 larger than available 4275440, Forwarded Header at 000003FF858FDF40
[2025-02-15T03:16:06.645Z] 03:16:05.453 0x950d00    j9mm.141    *   ** ASSERTION FAILED ** at ../../../../../../omr/gc/base/standard/Scavenger.cpp:1649: ((false))
[2025-02-15T03:16:06.645Z] JVMDUMP039I Processing dump event "traceassert", detail "" at 2025/02/15 03:16:05 - please wait.

[2025-02-15T03:17:52.140Z] openJcePlusTests_0_FAILED

[dmitripivkine]

These assertions have been triggered by heap corruption. Looking to the latest failure:

First assertion:

[2025-02-15T03:16:06.645Z] Corruption in Evacuate at 00000001FF642048: calculated object size 1649402008 larger than available 4317112, Forwarded Header at 000003FF859FDF40
[2025-02-15T03:16:06.645Z] 03:16:05.453 0x94e700    j9mm.141    *   ** ASSERTION FAILED ** at ../../../../../../omr/gc/base/standard/Scavenger.cpp:1649: ((false))

> !j9x 0x00000001FF642000,80,4
0x1FF642020 :  00f22000 00000000 00000000 00000000 [ .. ............. ]
0x1FF642030 :  ff9d5da8 ffb20dbc ffb1b3b4 00000000 [ ..]............. ]
0x1FF642040 :  00000000 00000000 00829d00 00000000 [ ................ ] <---- corrupted size to 0
0x1FF642050 :  624fe08c 3ab43673 ffb122e4 00000001 [ bO..:.6s.."..... ]

Size of Byte array !j9object 0x1FF642048 is corrupted and set to 0. So, GC interprets this artifact as an Arraylet with size 0x624fe08c and assert.
Just for the record, previous object is

> !j9object 0x1FF642020
!J9Object 0x00000001FF642020 {
	struct J9Class* clazz = !j9class 0xF22000 // com/ibm/crypto/plus/provider/XDHKeyAgreement$XDH
	Object flags = 0x00000000;
	I lockword = 0x00000000 (offset = 0) (java/lang/Object) <hidden>
	Lcom/ibm/crypto/plus/provider/OpenJCEPlusProvider; provider = !fj9object 0xff9d5da8 (offset = 12) (com/ibm/crypto/plus/provider/XDHKeyAgreement)
	J genCtx = 0x0000000000000000 (offset = 4) (com/ibm/crypto/plus/provider/XDHKeyAgreement)
	Lcom/ibm/crypto/plus/provider/ock/XECKey; ockXecKeyPub = !fj9object 0xffb20dbc (offset = 16) (com/ibm/crypto/plus/provider/XDHKeyAgreement)
	Lcom/ibm/crypto/plus/provider/ock/XECKey; ockXecKeyPriv = !fj9object 0xffb1b3b4 (offset = 20) (com/ibm/crypto/plus/provider/XDHKeyAgreement)
	[B secret = !fj9object 0x0 (offset = 24) (com/ibm/crypto/plus/provider/XDHKeyAgreement)
	Ljava/lang/String; alg = !fj9object 0x0 (offset = 28) (com/ibm/crypto/plus/provider/XDHKeyAgreement)
}

Both objects corrupted size array !j9object 0x1FF642048 and !j9object 0x1FF642020 are mentioned in stack slots of thread 0x808200:

<808200> JIT JNI call-out frame: bp = 0x00000000008E38E8, sp = 0x00000000008E38C0, pc = 0x0000000000000006, cp = 0x0000000000820E30, arg0EA = 0x00000000008E39A0, flags = 0x0000000020000000
<808200> 	Method: java/lang/J9VMInternals.primitiveClone(Ljava/lang/Object;)Ljava/lang/Object; !j9method 0x0000000000821A90
<808200> 	Object pushes starting at 0x00000000008E38C0 for 1 slots
<808200> 		Push[0x00000000008E38C0] = 0x00000001FF642048 <-----

<808200> Bytecode frame: bp = 0x00000000008E39C0, sp = 0x00000000008E39A8, pc = 0x000003FEB013A453, cp = 0x0000000000F215E0, arg0EA = 0x00000000008E39D0, flags = 0x0000000000000000
<808200> 	Method: com/ibm/crypto/plus/provider/XDHKeyAgreement.engineGenerateSecret(Ljava/lang/String;)Ljavax/crypto/SecretKey; !j9method 0x0000000000F21E70
<808200> 	Bytecode index = 43
<808200> 	Using local mapper
<808200> 	Locals starting at 0x00000000008E39D0 for 0x0000000000000002 slots
<808200> 		I-Slot: a0[0x00000000008E39D0] = 0x00000001FF642020 <-----
<808200> 		I-Slot: a1[0x00000000008E39C8] = 0x000000010715F2A0
<808200> 	Pending stack starting at 0x00000000008E39A8 for UDATA(0x0000000000000001) slots
<808200> 		O-Slot: p0[0x00000000008E39A8] = 0x00000001FF642108

My guess is somewhere is a write out of the object bound (???)

Second assertion is an identical pattern:

[2025-02-15T03:16:06.645Z] Corruption in Evacuate at 00000001FF64C310: calculated object size 1649402008 larger than available 4275440, Forwarded Header at 000003FF858FDF40
[2025-02-15T03:16:06.645Z] 03:16:05.453 0x950d00    j9mm.141    *   ** ASSERTION FAILED ** at ../../../../../../omr/gc/base/standard/Scavenger.cpp:1649: ((false))

0x1FF64C2E0 :  ffb26160 00000000 00f22000 00000000 [ ..a`...... ..... ]
0x1FF64C2F0 :  00000000 00000000 ff9d5da8 ffacdbcc [ ..........]..... ]
0x1FF64C300 :  ffad03b4 00000000 00000000 00000000 [ ................ ]
0x1FF64C310 :  00829d00 00000000 624fe08c 3ab43673 [ ........bO..:.6s ] <---- corrupted size to 0 
0x1FF64C320 :  0082d900 ffb21034 00000000 20f082ba [ .......4.... ... ]

Size of Byte array !j9object 0x1FF64C310 is corrupted and set to 0. So, GC interprets this artifact as an Arraylet with size 0x624fe08c and assert.
Just for the record, previous object is also has the same type:

> !j9object 0x1FF64C2E8
!J9Object 0x00000001FF64C2E8 {
	struct J9Class* clazz = !j9class 0xF22000 // com/ibm/crypto/plus/provider/XDHKeyAgreement$XDH
	Object flags = 0x00000000;
	I lockword = 0x00000000 (offset = 0) (java/lang/Object) <hidden>
	Lcom/ibm/crypto/plus/provider/OpenJCEPlusProvider; provider = !fj9object 0xff9d5da8 (offset = 12) (com/ibm/crypto/plus/provider/XDHKeyAgreement)
	J genCtx = 0x0000000000000000 (offset = 4) (com/ibm/crypto/plus/provider/XDHKeyAgreement)
	Lcom/ibm/crypto/plus/provider/ock/XECKey; ockXecKeyPub = !fj9object 0xffacdbcc (offset = 16) (com/ibm/crypto/plus/provider/XDHKeyAgreement)
	Lcom/ibm/crypto/plus/provider/ock/XECKey; ockXecKeyPriv = !fj9object 0xffad03b4 (offset = 20) (com/ibm/crypto/plus/provider/XDHKeyAgreement)
	[B secret = !fj9object 0x0 (offset = 24) (com/ibm/crypto/plus/provider/XDHKeyAgreement)
	Ljava/lang/String; alg = !fj9object 0x0 (offset = 28) (com/ibm/crypto/plus/provider/XDHKeyAgreement)
}

Thread 0xe20600 has very similar stack.

This is not GC problem, removing GC label.
@jasonkatonica If you need more help please let me know.

[JasonFengJ9]

openjdk24_j9_extended.functional_s390x_linux

[2025-04-12T17:39:19.732Z] variation: NoOptions
[2025-04-12T17:39:19.732Z] JVM_OPTIONS: 

[2025-04-12T17:39:35.069Z] [INFO]  T E S T S
[2025-04-12T17:39:35.069Z] [INFO] -------------------------------------------------------
[2025-04-12T17:39:38.680Z] [INFO] Running ibm.jceplus.junit.TestIntegration
[2025-04-12T17:39:38.680Z] [INFO] Running ibm.jceplus.junit.openjceplus.integration.TestAll
[2025-04-12T17:39:38.680Z] [INFO] Running ibm.jceplus.junit.openjceplus.integration.TestTLS
[2025-04-12T17:39:38.680Z] Testing TLSv1.3 rsa_pkcs1_sha1 TLS_AES_128_GCM_SHA256
[2025-04-12T17:39:38.680Z] Server listining on port: 38867
[2025-04-12T17:39:38.680Z] Corruption in Evacuate at 00000000FEFA61B0: calculated object size 240188728 larger than available 15113808, Forwarded Header at 000003FF899FCCA8
[2025-04-12T17:39:38.680Z] 17:39:38.102 0x1c12e00    j9mm.141    *   ** ASSERTION FAILED ** at /home/jenkins/workspace/build-scripts/jobs/jdk24/jdk24-linux-s390x-openj9/workspace/build/src/omr/gc/base/standard/Scavenger.cpp:1649: ((false))
[2025-04-12T17:39:38.680Z] Corruption in Evacuate at 00000000FEFB6B48: calculated object size 240188728 larger than available 15045816, Forwarded Header at 000003FF89DFE608
[2025-04-12T17:39:38.680Z] 17:39:38.102 0x172d500    j9mm.141    *   ** ASSERTION FAILED ** at /home/jenkins/workspace/build-scripts/jobs/jdk24/jdk24-linux-s390x-openj9/workspace/build/src/omr/gc/base/standard/Scavenger.cpp:1649: ((false))

[2025-04-12T17:39:40.434Z] openJcePlusTests_0_FAILED

[dmitripivkine]

Triaging latest failure:

• for both assertions there is corrupted size slot in Indexable object header. As before there is 0 is written over. According heap layout size use to be set to 32 elements.

0xFEFA61A0 :  00000010 00000010 82c704a0 ff35f978 [ .............5.x ]
0xFEFA61B0 :  01596500 00000000 0e50fd30 a103243d [ .Ye......P.0..$= ]<--- zero size makes array be treated as Arraylet
0xFEFA61C0 :  0159b600 fefa61d8 00000000 8927038d [ .Y....a......'.. ]
0xFEFA61D0 :  a72d9da8 657f2928 01596500 0000001f [ .-..e.)(.Ye..... ]

0xFEFB6B30 :  ff3ceca8 fefb6670 fef52210 fefb6b48 [ .<....fp.."...kH ]
0xFEFB6B40 :  00000000 00000000 01596500 00000000 [ .........Ye..... ] <--- zero size makes array be treated as Arraylet
0xFEFB6B50 :  0e50fd30 a103243d 00000001 00000000 [ .P.0..$=........ ]
0xFEFB6B60 :  00000000 00009f08 a72d9da8 657f2928 [ .........-..e.)( ]

• corrupted array seems is a "secret" object set for com/ibm/crypto/plus/provider/XDHKeyAgreement$XDH object

> !j9object 0xFFE5EB60
!J9Object 0x00000000FFE5EB60 {
	struct J9Class* clazz = !j9class 0x1D33300 // com/ibm/crypto/plus/provider/XDHKeyAgreement$XDH
	Object flags = 0x00000010;
	I lockword = 0x00000000 (offset = 0) (java/lang/Object) <hidden>
	Lcom/ibm/crypto/plus/provider/OpenJCEPlusProvider; provider = !fj9object 0xffe5eaf0 (offset = 12) (com/ibm/crypto/plus/provider/XDHKeyAgreement)
	J genCtx = 0x0000000000000000 (offset = 4) (com/ibm/crypto/plus/provider/XDHKeyAgreement)
	Lcom/ibm/crypto/plus/provider/ock/XECKey; ockXecKeyPub = !fj9object 0xffe62500 (offset = 16) (com/ibm/crypto/plus/provider/XDHKeyAgreement)
	Lcom/ibm/crypto/plus/provider/ock/XECKey; ockXecKeyPriv = !fj9object 0xffe62520 (offset = 20) (com/ibm/crypto/plus/provider/XDHKeyAgreement)
	[B secret = !fj9object 0xfefb6b48 (offset = 24) (com/ibm/crypto/plus/provider/XDHKeyAgreement) <-------
	Ljava/lang/String; alg = !fj9object 0x0 (offset = 28) (com/ibm/crypto/plus/provider/XDHKeyAgreement)
}

[JasonFengJ9]

openjdk24_j9_extended.functional_s390x_linux

[2025-07-19T18:31:38.198Z] Running test openJcePlusTests_0 ...
[2025-07-19T18:31:38.198Z] ===============================================
[2025-07-19T18:31:38.198Z] openJcePlusTests_0 Start Time: Sat Jul 19 19:31:36 2025 Epoch Time (ms): 1752949896623
[2025-07-19T18:31:38.198Z] variation: NoOptions
[2025-07-19T18:31:38.198Z] JVM_OPTIONS:  

[2025-07-19T18:31:56.933Z] Testing TLSv1.3 rsa_pkcs1_sha1 TLS_AES_128_GCM_SHA256
[2025-07-19T18:31:56.933Z] Server listining on port: 35375
[2025-07-19T18:31:56.933Z] Corruption in Evacuate at 00000000FFBE2EC0: calculated object size 290921208 larger than available 4313408, Forwarded Header at 000003FFA75FCC98
[2025-07-19T18:31:56.933Z] 18:31:56.403 0xfefb00    j9mm.141    *   ** ASSERTION FAILED ** at /home/jenkins/workspace/build-scripts/jobs/jdk24/jdk24-linux-s390x-openj9/workspace/build/src/omr/gc/base/standard/Scavenger.cpp:1683: ((false))

[pshipton]

@JasonFengJ9 what is the failure rate for this one, say for jdk11? I see there was a grinder originally, but no failure rate was recorded.