Re: JDK17 - Possible TLS issue.

[Peter Firmstone]

谢谢johnsjiang(江莎)，

I set the property:
-Djdk.tls.acknowledgeCloseNotify=true.

Unfortunately the test is still failing on JDK17, although the output 
has changed and acknowledges the duplex close, so it appears something 
else is causing the connection to close early. Interestingly, there is a 
WARNING that the socket didn't close, followed by an ERROR, then 
FATAL(UNEXPECTED MESSAGE).

致以诚挚的问候Peter.

https://github.com/pfirmstone/JGDMS/blob/trunk/qa/LookupNegMatches-jdk17-TLS-handshake-debug-ack-close-notify-true.txt

     [java] ActSys-err: javax.net.ssl|DEBUG|92|(JSK) 
ConnectionManager.Reaper|2021-08-11 19:41:49.598 
AEST|SSLSocketImpl.java:572|duplex close of SSLSocket
     [java] ActSys-err: javax.net.ssl|DEBUG|D2|(JSK) mux 
reader|2021-08-11 19:41:49.599 AEST|Alert.java:238|Received alert message (
     [java] ActSys-err: "Alert": {
     [java] ActSys-err:   "level"      : "warning",
     [java] ActSys-err:   "description": "user_canceled"
     [java] ActSys-err: }
     [java] ActSys-err: )
     [java] ActSys-err: javax.net.ssl|DEBUG|92|(JSK) 
ConnectionManager.Reaper|2021-08-11 19:41:49.599 
AEST|SSLSocketImpl.java:1775|close the SSL connection (passive)
     [java] ActSys-err: javax.net.ssl|DEBUG|D2|(JSK) mux 
reader|2021-08-11 19:41:49.599 AEST|Alert.java:238|Received alert message (
     [java] ActSys-err: "Alert": {
     [java] ActSys-err:   "level"      : "warning",
     [java] ActSys-err:   "description": "close_notify"
     [java] ActSys-err: }
     [java] ActSys-err: )
     [java] ActSys-err: javax.net.ssl|ALL|A2|(JSK) mux 
writer|2021-08-11 19:41:49.599 AEST|SSLSocketImpl.java:1324|Closing 
output stream
     [java] ActSys-err: javax.net.ssl|DEBUG|D2|(JSK) mux 
reader|2021-08-11 19:41:49.600 AEST|SSLSocketImpl.java:572|duplex close 
of SSLSocket
     [java] ActSys-err: javax.net.ssl|ALL|C2|(JSK) mux 
writer|2021-08-11 19:41:49.600 AEST|SSLSocketImpl.java:1324|Closing 
output stream
     [java] ActSys-err: javax.net.ssl|DEBUG|D2|(JSK) mux 
reader|2021-08-11 19:41:49.600 AEST|SSLSocketImpl.java:1775|close the 
SSL connection (passive)
     [java] ActSys-err: javax.net.ssl|DEBUG|C2|(JSK) mux 
writer|2021-08-11 19:41:49.600 AEST|SSLSocketImpl.java:572|duplex close 
of SSLSocket
     [java] ActSys-err: javax.net.ssl|DEBUG|C2|(JSK) mux 
writer|2021-08-11 19:41:49.600 AEST|SSLSocketImpl.java:1775|close the 
SSL connection (passive)
     [java] ActSys-err: javax.net.ssl|ALL|D2|(JSK) mux 
reader|2021-08-11 19:41:49.600 AEST|SSLSocketImpl.java:1129|Closing 
input stream
     [java] ActSys-err: javax.net.ssl|WARNING|C2|(JSK) mux 
writer|2021-08-11 19:41:49.602 AEST|SSLSocketImpl.java:600|SSLSocket 
close failed. Debug info only. Exception details: (
     [java] ActSys-err: "throwable" : {
     [java] ActSys-err:   java.net.SocketException: Socket closed
     [java] ActSys-err:       at 
java.base/sun.nio.ch.NioSocketImpl.ensureOpenAndConnected(NioSocketImpl.java:165)
     [java] ActSys-err:       at 
java.base/sun.nio.ch.NioSocketImpl.available(NioSocketImpl.java:838)
     [java] ActSys-err:       at 
java.base/sun.nio.ch.NioSocketImpl$1.available(NioSocketImpl.java:807)
     [java] ActSys-err:       at 
java.base/java.net.Socket$SocketInputStream.available(Socket.java:970)
     [java] ActSys-err:       at 
java.base/sun.security.ssl.SSLSocketInputRecord.deplete(SSLSocketInputRecord.java:495)
     [java] ActSys-err:       at 
java.base/sun.security.ssl.SSLSocketImpl.closeSocket(SSLSocketImpl.java:1785)
     [java] ActSys-err:       at 
java.base/sun.security.ssl.SSLSocketImpl.close(SSLSocketImpl.java:596)
     [java] ActSys-err:       at 
java.base/sun.security.ssl.SSLSocketImpl$AppOutputStream.close(SSLSocketImpl.java:1328)
     [java] ActSys-err:       at 
org.apache.river.jeri.internal.mux.StreamConnectionIO$2.close(StreamConnectionIO.java:427)
     [java] ActSys-err:       at 
org.apache.river.jeri.internal.mux.StreamConnectionIO$Writer.run(StreamConnectionIO.java:250)
     [java] ActSys-err:       at 
org.apache.river.thread.ThreadPool$Task.run(ThreadPool.java:172)
     [java] ActSys-err:       at 
java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
     [java] ActSys-err:       at 
java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
     [java] ActSys-err:       at 
java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
     [java] ActSys-err:       at 
java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
     [java] ActSys-err:       at 
java.base/java.lang.Thread.run(Thread.java:833)}
     [java] ActSys-err:
     [java] ActSys-err: )
     [java] ActSys-err: javax.net.ssl|WARNING|B2|(JSK) mux 
reader|2021-08-11 19:41:49.602 AEST|SSLSocketImpl.java:1666|handling 
exception (
     [java] ActSys-err: "throwable" : {
     [java] ActSys-err:   java.net.SocketException: Socket closed
     [java] ActSys-err:       at 
java.base/sun.nio.ch.NioSocketImpl.endRead(NioSocketImpl.java:248)
     [java] ActSys-err:       at 
java.base/sun.nio.ch.NioSocketImpl.implRead(NioSocketImpl.java:327)
     [java] ActSys-err:       at 
java.base/sun.nio.ch.NioSocketImpl.read(NioSocketImpl.java:350)
     [java] ActSys-err:       at 
java.base/sun.nio.ch.NioSocketImpl$1.read(NioSocketImpl.java:803)
     [java] ActSys-err:       at 
java.base/java.net.Socket$SocketInputStream.read(Socket.java:966)
     [java] ActSys-err:       at 
java.base/sun.security.ssl.SSLSocketInputRecord.read(SSLSocketInputRecord.java:478)
     [java] ActSys-err:       at 
java.base/sun.security.ssl.SSLSocketInputRecord.readHeader(SSLSocketInputRecord.java:472)
     [java] ActSys-err:       at 
java.base/sun.security.ssl.SSLSocketInputRecord.bytesInCompletePacket(SSLSocketInputRecord.java:70)
     [java] ActSys-err:       at 
java.base/sun.security.ssl.SSLSocketImpl.readApplicationRecord(SSLSocketImpl.java:1455)
     [java] ActSys-err:       at 
java.base/sun.security.ssl.SSLSocketImpl$AppInputStream.read(SSLSocketImpl.java:1059)
     [java] ActSys-err:       at 
org.apache.river.jeri.internal.mux.StreamConnectionIO$1.read(StreamConnectionIO.java:372)
     [java] ActSys-err:       at 
org.apache.river.jeri.internal.mux.StreamConnectionIO$Reader.run(StreamConnectionIO.java:277)
     [java] ActSys-err:       at 
org.apache.river.thread.ThreadPool$Task.run(ThreadPool.java:172)
     [java] ActSys-err:       at 
java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
     [java] ActSys-err:       at 
java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
     [java] ActSys-err:       at 
java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
     [java] ActSys-err:       at 
java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
     [java] ActSys-err:       at 
java.base/java.lang.Thread.run(Thread.java:833)}
     [java] ActSys-err:
     [java] ActSys-err: )
     [java] ActSys-err: javax.net.ssl|ERROR|B2|(JSK) mux 
reader|2021-08-11 19:41:49.602 AEST|TransportContext.java:363|Fatal 
(UNEXPECTED_MESSAGE): Socket closed (
     [java] ActSys-err: "throwable" : {
     [java] ActSys-err:   java.net.SocketException: Socket closed
     [java] ActSys-err:       at 
java.base/sun.nio.ch.NioSocketImpl.endRead(NioSocketImpl.java:248)
     [java] ActSys-err:       at 
java.base/sun.nio.ch.NioSocketImpl.implRead(NioSocketImpl.java:327)
     [java] ActSys-err:       at 
java.base/sun.nio.ch.NioSocketImpl.read(NioSocketImpl.java:350)
     [java] ActSys-err:       at 
java.base/sun.nio.ch.NioSocketImpl$1.read(NioSocketImpl.java:803)
     [java] ActSys-err:       at 
java.base/java.net.Socket$SocketInputStream.read(Socket.java:966)
     [java] ActSys-err:       at 
java.base/sun.security.ssl.SSLSocketInputRecord.read(SSLSocketInputRecord.java:478)
     [java] ActSys-err:       at 
java.base/sun.security.ssl.SSLSocketInputRecord.readHeader(SSLSocketInputRecord.java:472)
     [java] ActSys-err:       at 
java.base/sun.security.ssl.SSLSocketInputRecord.bytesInCompletePacket(SSLSocketInputRecord.java:70)
     [java] ActSys-err:       at 
java.base/sun.security.ssl.SSLSocketImpl.readApplicationRecord(SSLSocketImpl.java:1455)
     [java] ActSys-err:       at 
java.base/sun.security.ssl.SSLSocketImpl$AppInputStream.read(SSLSocketImpl.java:1059)
     [java] ActSys-err:       at 
org.apache.river.jeri.internal.mux.StreamConnectionIO$1.read(StreamConnectionIO.java:372)
     [java] ActSys-err:       at 
org.apache.river.jeri.internal.mux.StreamConnectionIO$Reader.run(StreamConnectionIO.java:277)
     [java] ActSys-err:       at 
org.apache.river.thread.ThreadPool$Task.run(ThreadPool.java:172)
     [java] ActSys-err:       at 
java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
     [java] ActSys-err:       at 
java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
     [java] ActSys-err:       at 
java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
     [java] ActSys-err:       at 
java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
     [java] ActSys-err:       at 
java.base/java.lang.Thread.run(Thread.java:833)}
     [java] ActSys-err:
     [java] ActSys-err: )
     [java] ActSys-err: javax.net.ssl|ALL|B2|(JSK) mux 
reader|2021-08-11 19:41:49.603 AEST|SSLSocketImpl.java:1129|Closing 
input stream
     [java] ActSys-err: 11 Aug 2021 7:42:31 pm:Group-0:err:WARNING: A 
terminally deprecated method in java.lang.System has been called
     [java] ActSys-err: WARNING: System::setSecurityManager has been 
called by org.apache.river.phoenix.init.ActivationGroupInit 
(file:/C:/Users/peter/Documents/NetBeansProjects/JGDMS/JGDMS/dist/target/JGDMS-3.1.1-SNAPSHOT/lib/phoenix-init-3.1.1-SNAPSHOT.jar)
     [java] ActSys-err: WARNING: Please consider reporting this to the 
maintainers of org.apache.river.phoenix.init.ActivationGroupInit
     [java] ActSys-err: WARNING: System::setSecurityManager will be 
removed in a future release
     [java] ActSys-err:
     [java] ActSys-err: Aug 11, 2021 7:42:31 PM 
org.apache.river.phoenix.Activation$GroupEntry getInstantiator
     [java] ActSys-err: FINE: Group-1 exec [C:\Program 
Files\Zulu\jdk-17\bin\java, -ea, -esa, -server, 
-Dorg.apache.river.qa.harness.harnessJar=C:\Users\peter\Documents\NetBeansProjects\JGDMS\qa\lib\jiniharness.jar, 
-Djsk.iiop.jar=jgdms-iiop-3.1.1-SNAPSHOT.jar, 
-Doutrigger-snaplogstore.jar=outrigger-snaplogstore-3.1.1-SNAPSHOT.jar, 
-Dorg.apache.river.jsk.port=9080, 
-Dcollections.jar=jgdms-collections-3.1.1-SNAPSHOT.jar, 
-Dsharedvm.jar=service-starter-3.1.1-SNAPSHOT.jar, 
-Djgdms-rmi-tls.jar=jgdms-rmi-tls-3.1.1-SNAPSHOT.jar, 
-Djdk.tls.acknowledgeCloseNotify=true, 
-Djava.protocol.handler.pkgs=net.jini.url, 
-Dphoenix.jar=phoenix-3.1.1-SNAPSHOT.jar, 
-Dplatform.jar=jgdms-platform-3.1.1-SNAPSHOT.jar, 
-Dnorm-dl.jar=norm-dl-3.1.1-SNAPSHOT.jar, 
-Dorg.apache.river.qa.harness.testJar=C:\Users\peter\Documents\NetBeansProjects\JGDMS\qa\lib\jinitests.jar, 
-Djava.util.logging.config.file=C:\Users\peter\Documents\NetBeansProjects\JGDMS\qa\src\org\apache\river\test\resources\qa1.logging, 
-Djsk.pref.jar=jgdms-pref-class-loader-3.1.1-SNAPSHOT.jar, 
-Dstart.jar=service-starter-3.1.1-SNAPSHOT.jar, 
-Dphoenix-common.jar=phoenix-common-3.1.1-SNAPSHOT.jar, 
-Djava.security.properties=file:/C:/Users/peter/Documents/NetBeansProjects/JGDMS/qa/harness/trust/dynamic-policy.properties, 
-Dmercury-dl.jar=mercury-dl-3.1.1-SNAPSHOT.jar, 
-Dreggie-dl.jar=reggie-dl-3.1.1-SNAPSHOT.jar, 
-Dloader.jar=jgdms-pref-class-loader-3.1.1-SNAPSHOT.jar, 
-Dclassserver.jar=classserver-3.1.1-SNAPSHOT.jar, 
-Djsk-dl.jar=jgdms-lib-dl-3.1.1-SNAPSHOT.jar, 
-Dorg.apache.river.test.home=C:\Users\peter\Documents\NetBeansProjects\JGDMS\qa, 
-Dreggie.jar=reggie-service-3.1.1-SNAPSHOT.jar, 
-Djdk.io.permissionsUseCanonicalPath=true, 
-Dphoenix-dl.jar=phoenix-dl-3.1.1-SNAPSHOT.jar, 
-Djsk.home=C:/Users/peter/Documents/NetBeansProjects/JGDMS/JGDMS/dist/target/JGDMS-3.1.1-SNAPSHOT, 
-Djeri.jar=jgdms-jeri-3.1.1-SNAPSHOT.jar, 
-Dhigh-scale-lib.jar=high-scale-lib-1.0.6.jar, 
-Djava.net.preferIPv6Addresses=true, -DHOST=DESKTOP-R0ORPA2, 
-Dorg.apache.river.qa.harness.testhosts=, 
-Dmahalo.jar=mahalo-service-3.1.1-SNAPSHOT.jar, 
-Djavax.net.ssl.trustStore=harness\trust\truststore, 
-Dbouncy-jce.jar=bcprov-jdk15on-1.59.jar, 
-Dorg.apache.river.discovery.x500.trustStore=file:/C:/Users/peter/Documents/NetBeansProjects/JGDMS/qa/harness/trust/truststore, 
-Doutrigger-dl.jar=outrigger-dl-3.1.1-SNAPSHOT.jar, 
-Ddisco.jar=jgdms-discovery-providers-3.1.1-SNAPSHOT.jar, 
-Djgdms.version=3.1.1-SNAPSHOT, 
-Dgroup.jar=group-service-3.1.1-SNAPSHOT.jar, 
-Djava.security.policy=file:/C:/Users/peter/Documents/NetBeansProjects/JGDMS/qa/harness/policy/defaultsecuresharedvm.policy, 
-Dorg.apache.river.qa.harness.runjiniserver=true, 
-Dactivation-param.jar=jgdms-activation-parameters-3.1.1-SNAPSHOT.jar, 
-Dactivation.jar=jgdms-activation-3.1.1-SNAPSHOT.jar, 
-Dorg.apache.river.qa.harness.policies=file:/C:/Users/peter/Documents/NetBeansProjects/JGDMS/qa/src/org/apache/river/test/resources/jinitest.policy, 
-Dsun.net.maxDatagramSockets=1024, 
-Dnorm.jar=norm-service-3.1.1-SNAPSHOT.jar, 
-Dmercury.jar=mercury-service-3.1.1-SNAPSHOT.jar, 
-Djsk.url.jar=jgdms-url-integrity-3.1.1-SNAPSHOT.jar, 
-Djsk-lib.jar=jgdms-lib-3.1.1-SNAPSHOT.jar, 
-Dfiddler.jar=fiddler-service-3.1.1-SNAPSHOT.jar, 
-Dbouncy-jsse.jar=bctls-jdk15on-1.59.jar, 
-Dnet.jini.core.lookup.ServiceRegistrar.portAbitraryIfInUse=true, 
-Djavax.net.debug=ssl:handshake, 
-Dorg.apache.river.discovery.x500.trustStorePassword=trustpw, 
-Dphoenix-group.jar=phoenix-group-3.1.1-SNAPSHOT.jar, 
-Dnet.jini.security.allowInsecureConnections=true, 
-Dorg.apache.river.test.port=9082, 
-Dorg.apache.river.qa.harness.runkitserver=true, 
-Djava.security.auth.login.config=file:/C:/Users/peter/Documents/NetBeansProjects/JGDMS/qa/harness/trust/jsselogins, 
-Dfiddler-dl.jar=fiddler-dl-3.1.1-SNAPSHOT.jar, 
-Dmahalo-dl.jar=mahalo-dl-3.1.1-SNAPSHOT.jar, 
-Dorg.apache.river.qa.port=9081, 
-Dphoenix-init.jar=phoenix-init-3.1.1-SNAPSHOT.jar, 
-Doutrigger.jar=outrigger-service-3.1.1-SNAPSHOT.jar, 
-Djavax.net.ssl.trustStorePassword=trustpw, 
-Ddestroy.jar=jgdms-destroy-3.1.1-SNAPSHOT.jar, 
-Dqa.home=C:\Users\peter\Documents\NetBeansProjects\JGDMS\qa, -cp, 
C:/Users/peter/Documents/NetBeansProjects/JGDMS/JGDMS/dist/target/JGDMS-3.1.1-SNAPSHOT\lib\service-starter-3.1.1-SNAPSHOT.jar;C:/Users/peter/Documents/NetBeansProjects/JGDMS/JGDMS/dist/target/JGDMS-3.1.1-SNAPSHOT\lib\jgdms-collections-3.1.1-SNAPSHOT.jar;C:/Users/peter/Documents/NetBeansProjects/JGDMS/JGDMS/dist/target/JGDMS-3.1.1-SNAPSHOT\lib\high-scale-lib-1.0.6.jar;C:/Users/peter/Documents/NetBeansProjects/JGDMS/JGDMS/dist/target/JGDMS-3.1.1-SNAPSHOT\lib\phoenix-init-3.1.1-SNAPSHOT.jar;C:/Users/peter/Documents/NetBeansProjects/JGDMS/JGDMS/dist/target/JGDMS-3.1.1-SNAPSHOT\lib\jgdms-platform-3.1.1-SNAPSHOT.jar;C:/Users/peter/Documents/NetBeansProjects/JGDMS/JGDMS/dist/target/JGDMS-3.1.1-SNAPSHOT\lib-dl\jgdms-lib-dl-3.1.1-SNAPSHOT.jar;C:/Users/peter/Documents/NetBeansProjects/JGDMS/JGDMS/dist/target/JGDMS-3.1.1-SNAPSHOT\lib\jgdms-lib-3.1.1-SNAPSHOT.jar;C:/Users/peter/Documents/NetBeansProjects/JGDMS/JGDMS/dist/target/JGDMS-3.1.1-SNAPSHOT\lib\jgdms-discovery-providers-3.1.1-SNAPSHOT.jar;C:/Users/peter/Documents/NetBeansProjects/JGDMS/JGDMS/dist/target/JGDMS-3.1.1-SNAPSHOT\lib\jgdms-pref-class-loader-3.1.1-SNAPSHOT.jar;C:/Users/peter/Documents/NetBeansProjects/JGDMS/JGDMS/dist/target/JGDMS-3.1.1-SNAPSHOT\lib\jgdms-jeri-3.1.1-SNAPSHOT.jar;C:/Users/peter/Documents/NetBeansProjects/JGDMS/JGDMS/dist/target/JGDMS-3.1.1-SNAPSHOT\lib\phoenix-group-3.1.1-SNAPSHOT.jar;C:/Users/peter/Documents/NetBeansProjects/JGDMS/JGDMS/dist/target/JGDMS-3.1.1-SNAPSHOT\lib-dl\phoenix-dl-3.1.1-SNAPSHOT.jar;C:/Users/peter/Documents/NetBeansProjects/JGDMS/JGDMS/dist/target/JGDMS-3.1.1-SNAPSHOT\lib\phoenix-common-3.1.1-SNAPSHOT.jar;C:/Users/peter/Documents/NetBeansProjects/JGDMS/JGDMS/dist/target/JGDMS-3.1.1-SNAPSHOT\lib\jgdms-rmi-tls-3.1.1-SNAPSHOT.jar;C:/Users/peter/Documents/NetBeansProjects/JGDMS/JGDMS/dist/target/JGDMS-3.1.1-SNAPSHOT\lib\jgdms-activation-3.1.1-SNAPSHOT.jar;C:/Users/peter/Documents/NetBeansProjects/JGDMS/JGDMS/dist/target/JGDMS-3.1.1-SNAPSHOT\lib\jgdms-activation-parameters-3.1.1-SNAPSHOT.jar;C:/Users/peter/Documents/NetBeansProjects/JGDMS/JGDMS/dist/target/JGDMS-3.1.1-SNAPSHOT\lib\jgdms-url-integrity-3.1.1-SNAPSHOT.jar;C:/Users/peter/Documents/NetBeansProjects/JGDMS/JGDMS/dist/target/JGDMS-3.1.1-SNAPSHOT\lib\bcprov-jdk15on-1.59.jar;C:/Users/peter/Documents/NetBeansProjects/JGDMS/JGDMS/dist/target/JGDMS-3.1.1-SNAPSHOT\lib\bctls-jdk15on-1.59.jar;C:/Users/peter/Documents/NetBeansProjects/JGDMS/JGDMS/dist/target/JGDMS-3.1.1-SNAPSHOT\lib\security-policy-debug-3.1.1-SNAPSHOT.jar, 
org.apache.river.phoenix.init.ActivationGroupInit]
     [java] ActSys-err: javax.net.ssl|WARNING|F1|(JSK) mux request 
dispatch|2021-08-11 19:42:32.033 
AEST|ServerNameExtension.java:266|Unable to indicate server name
     [java] ActSys-err: javax.net.ssl|DEBUG|F1|(JSK) mux request 
dispatch|2021-08-11 19:42:32.033 AEST|SSLExtensions.java:272|Ignore, 
context unavailable extension: server_name
     [java] ActSys-err: javax.net.ssl|INFO|F1|(JSK) mux request 
dispatch|2021-08-11 19:42:32.034 AEST|AlpnExtension.java:182|No 
available application protocols
     [java] ActSys-err: javax.net.ssl|DEBUG|F1|(JSK) mux request 
dispatch|2021-08-11 19:42:32.034 AEST|SSLExtensions.java:272|Ignore, 
context unavailable extension: application_layer_protocol_negotiation
     [java] ActSys-err: javax.net.ssl|DEBUG|F1|(JSK) mux request 
dispatch|2021-08-11 19:42:32.034 
AEST|SessionTicketExtension.java:408|Stateless resumption supported
     [java] ActSys-err: javax.net.ssl|DEBUG|F1|(JSK) mux request 
dispatch|2021-08-11 19:42:32.035 AEST|SSLExtensions.java:272|Ignore, 
context unavailable extension: cookie
     [java] ActSys-err: javax.net.ssl|DEBUG|F1|(JSK) mux request 
dispatch|2021-08-11 19:42:32.041 AEST|PreSharedKeyExtension.java:662|No 
session to resume.
     [java] ActSys-err: javax.net.ssl|DEBUG|F1|(JSK) mux request 
dispatch|2021-08-11 19:42:32.041 AEST|SSLExtensions.java:272|Ignore, 
context unavailable extension: pre_shared_key
     [java] ActSys-err: javax.net.ssl|DEBUG|F1|(JSK) mux request 
dispatch|2021-08-11 19:42:32.044 AEST|ClientHello.java:652|Produced 
ClientHello handsha



On 11/08/2021 7:22 pm, johnsjiang(江莎) wrote:
+ security-dev

Hi Peter,
It looks both of file 1 and 5 contain that close_notify warning alert.
This point may be related to JDK-8208526: TLS 1.3 half-close and 
synchronization issues [1].

[1] https://bugs.openjdk.java.net/browse/JDK-8208526

Best regards,
John Jiang

At 2021/8/11 PM 4:14, Peter Firmstone wrote:
I'm testing on JDK17, having some issues communicating using TLS between
processes.

With TLS disabled, the test passes on JDK17.

The test passes using TLS on JDK 16 and earlier JDK versions.

I've enabled TLS handshake debug on the output

  1. 
https://github.com/pfirmstone/JGDMS/blob/trunk/qa/LookupNegMatches-jdk16-tls-handshake-debug.txt
  2. 
https://github.com/pfirmstone/JGDMS/blob/trunk/qa/LookupNegMatches-jdk16.txt
  3. 
https://github.com/pfirmstone/JGDMS/blob/trunk/qa/LookupNegMatches-jdk17-TLS-disabled.txt
  4. 
https://github.com/pfirmstone/JGDMS/blob/trunk/qa/LookupNegMatches-jdk17-tls-handshake-debug.txt
  5. 
https://github.com/pfirmstone/JGDMS/blob/trunk/qa/LookupNegMatches-jdk17-TLS-handshake-debug2.txt

There are 5 JVM instances created during this integration test and these
JVM's are communicating using network connections.  I have checked that
all JVM processes are running, it seems to be a communication issue.

Using diff to compare files 1 and 5 above, it appears to be related to a
close notify in JDK17, on the (JSK) connection .

Any suggestions?

Thanks,

Peter.

       [java] ActSys-err: javax.net.ssl|DEBUG|D2|(JSK) mux reader|2021-08-11 
14:56:20.606 AEST|SSLSocketImpl.java:1775|close the SSL connection (passive)
       [java] ActSys-err: javax.net.ssl|DEBUG|C2|(JSK) mux writer|2021-08-11 
14:56:20.606 AEST|SSLSocketImpl.java:572|duplex close of SSLSocket
       [java] ActSys-err: javax.net.ssl|ALL|D2|(JSK) mux reader|2021-08-11 
14:56:20.606 AEST|SSLSocketImpl.java:1129|Closing input stream
       [java] ActSys-err: javax.net.ssl|WARNING|B2|(JSK) mux reader|2021-08-11 
14:56:20.607 AEST|SSLSocketImpl.java:1666|handling exception (
       [java] ActSys-err: "throwable" : {
       [java] ActSys-err:   java.net.SocketException: Socket closed
       [java] ActSys-err:       at 
java.base/sun.nio.ch.NioSocketImpl.endRead(NioSocketImpl.java:248)
       [java] ActSys-err:       at 
java.base/sun.nio.ch.NioSocketImpl.implRead(NioSocketImpl.java:327)
       [java] ActSys-err:       at 
java.base/sun.nio.ch.NioSocketImpl.read(NioSocketImpl.java:350)
       [java] ActSys-err:       at 
java.base/sun.nio.ch.NioSocketImpl$1.read(NioSocketImpl.java:803)
       [java] ActSys-err:       at 
java.base/java.net.Socket$SocketInputStream.read(Socket.java:966)
       [java] ActSys-err:       at 
java.base/sun.security.ssl.SSLSocketInputRecord.read(SSLSocketInputRecord.java:478)
       [java] ActSys-err:       at 
java.base/sun.security.ssl.SSLSocketInputRecord.readHeader(SSLSocketInputRecord.java:472)
       [java] ActSys-err:       at 
java.base/sun.security.ssl.SSLSocketInputRecord.bytesInCompletePacket(SSLSocketInputRecord.java:70)
       [java] ActSys-err:       at 
java.base/sun.security.ssl.SSLSocketImpl.readApplicationRecord(SSLSocketImpl.java:1455)
       [java] ActSys-err:       at 
java.base/sun.security.ssl.SSLSocketImpl$AppInputStream.read(SSLSocketImpl.java:1059)
       [java] ActSys-err:       at 
org.apache.river.jeri.internal.mux.StreamConnectionIO$1.read(StreamConnectionIO.java:372)
       [java] ActSys-err:       at 
org.apache.river.jeri.internal.mux.StreamConnectionIO$Reader.run(StreamConnectionIO.java:277)
       [java] ActSys-err:       at 
org.apache.river.thread.ThreadPool$Task.run(ThreadPool.java:172)
       [java] ActSys-err:       at 
java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
       [java] ActSys-err:       at 
java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
       [java] ActSys-err:       at 
java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
       [java] ActSys-err:       at 
java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
       [java] ActSys-err:       at 
java.base/java.lang.Thread.run(Thread.java:833)}
       [java] ActSys-err:
       [java] ActSys-err: )
       [java] ActSys-err: javax.net.ssl|ERROR|B2|(JSK) mux reader|2021-08-11 
14:56:20.607 AEST|TransportContext.java:363|Fatal (UNEXPECTED_MESSAGE): Socket 
closed (
       [java] ActSys-err: "throwable" : {
       [java] ActSys-err:   java.net.SocketException: Socket closed
       [java] ActSys-err:       at 
java.base/sun.nio.ch.NioSocketImpl.endRead(NioSocketImpl.java:248)
       [java] ActSys-err:       at 
java.base/sun.nio.ch.NioSocketImpl.implRead(NioSocketImpl.java:327)
       [java] ActSys-err:       at 
java.base/sun.nio.ch.NioSocketImpl.read(NioSocketImpl.java:350)
       [java] ActSys-err:       at 
java.base/sun.nio.ch.NioSocketImpl$1.read(NioSocketImpl.java:803)
       [java] ActSys-err:       at 
java.base/java.net.Socket$SocketInputStream.read(Socket.java:966)
       [java] ActSys-err:       at 
java.base/sun.security.ssl.SSLSocketInputRecord.read(SSLSocketInputRecord.java:478)
       [java] ActSys-err:       at 
java.base/sun.security.ssl.SSLSocketInputRecord.readHeader(SSLSocketInputRecord.java:472)
       [java] ActSys-err:       at 
java.base/sun.security.ssl.SSLSocketInputRecord.bytesInCompletePacket(SSLSocketInputRecord.java:70)
       [java] ActSys-err:       at 
java.base/sun.security.ssl.SSLSocketImpl.readApplicationRecord(SSLSocketImpl.java:1455)
       [java] ActSys-err:       at 
java.base/sun.security.ssl.SSLSocketImpl$AppInputStream.read(SSLSocketImpl.java:1059)
       [java] ActSys-err:       at 
org.apache.river.jeri.internal.mux.StreamConnectionIO$1.read(StreamConnectionIO.java:372)
       [java] ActSys-err:       at 
org.apache.river.jeri.internal.mux.StreamConnectionIO$Reader.run(StreamConnectionIO.java:277)
       [java] ActSys-err:       at 
org.apache.river.thread.ThreadPool$Task.run(ThreadPool.java:172)
       [java] ActSys-err:       at 
java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
       [java] ActSys-err:       at 
java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
       [java] ActSys-err:       at 
java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
       [java] ActSys-err:       at 
java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
       [java] ActSys-err:       at 
java.base/java.lang.Thread.run(Thread.java:833)}
       [java] ActSys-err:
       [java] ActSys-err: )
       [java] ActSys-err: javax.net.ssl|ALL|B2|(JSK) mux reader|2021-08-11 
14:56:20.609 AEST|SSLSocketImpl.java:1129|Closing input stream
       [java] ActSys-err: 11 Aug 2021 2:57:02 pm:Group-0:err:WARNING: A 
terminally deprecated method in java.lang.System has been called
       [java] ActSys-err: WARNING: System::setSecurityManager has been called 
by org.apache.river.phoenix.init.ActivationGroupInit 
(file:/C:/Users/peter/Documents/NetBeansProjects/JGDMS/JGDMS/dist/target/JGDMS-3.1.1-SNAPSHOT/lib/phoenix-init-3.1.1-SNAPSHOT.jar)
       [java] ActSys-err: WARNING: Please consider reporting this to the 
maintainers of org.apache.river.phoenix.init.ActivationGroupInit
       [java] ActSys-err: WARNING: System::setSecurityManager will be removed 
in a future release
       [java] ActSys-err:
       [java] ActSys-err: Aug 11, 2021 2:57:02 PM 
org.apache.river.phoenix.Activation$GroupEntry getInstantiator
       [java] ActSys-err: FINE: Group-1 exec [C:\Program 
Files\Zulu\jdk-17\bin\java, -ea, -esa, -server, 
-Dorg.apache.river.qa.harness.harnessJar=C:\Users\peter\Documents\NetBeansProjects\JGDMS\qa\lib\jiniharness.jar,
 -Djsk.iiop.jar=jgdms-iiop-3.1.1-SNAPSHOT.jar, 
-Doutrigger-snaplogstore.jar=outrigger-snaplogstore-3.1.1-SNAPSHOT.jar, 
-Dorg.apache.river.jsk.port=9080, 
-Dcollections.jar=jgdms-collections-3.1.1-SNAPSHOT.jar, 
-Dsharedvm.jar=service-starter-3.1.1-SNAPSHOT.jar, 
-Djgdms-rmi-tls.jar=jgdms-rmi-tls-3.1.1-SNAPSHOT.jar, 
-Djava.protocol.handler.pkgs=net.jini.url, 
-Dphoenix.jar=phoenix-3.1.1-SNAPSHOT.jar, 
-Dplatform.jar=jgdms-platform-3.1.1-SNAPSHOT.jar, 
-Dnorm-dl.jar=norm-dl-3.1.1-SNAPSHOT.jar, 
-Dorg.apache.river.qa.harness.testJar=C:\Users\peter\Documents\NetBeansProjects\JGDMS\qa\lib\jinitests.jar,
 
-Djava.util.logging.config.file=C:\Users\peter\Documents\NetBeansProjects\JGDMS\qa\src\org\apache\river\test\resources\qa1.logging,
 -Djsk.pref.jar=jgdms-pref-class-loader-3.1.1-SNAPSHOT.jar, 
-Dstart.jar=service-starter-3.1.1-SNAPSHOT.jar, 
-Dphoenix-common.jar=phoenix-common-3.1.1-SNAPSHOT.jar, 
-Djava.security.properties=file:/C:/Users/peter/Documents/NetBeansProjects/JGDMS/qa/harness/trust/dynamic-policy.properties,
 -Dmercury-dl.jar=mercury-dl-3.1.1-SNAPSHOT.jar, 
-Dreggie-dl.jar=reggie-dl-3.1.1-SNAPSHOT.jar, 
-Dloader.jar=jgdms-pref-class-loader-3.1.1-SNAPSHOT.jar, 
-Dclassserver.jar=classserver-3.1.1-SNAPSHOT.jar, 
-Djsk-dl.jar=jgdms-lib-dl-3.1.1-SNAPSHOT.jar, 
-Dorg.apache.river.test.home=C:\Users\peter\Documents\NetBeansProjects\JGDMS\qa,
 -Dreggie.jar=reggie-service-3.1.1-SNAPSHOT.jar, 
-Djdk.io.permissionsUseCanonicalPath=true, 
-Dphoenix-dl.jar=phoenix-dl-3.1.1-SNAPSHOT.jar, 
-Djsk.home=C:/Users/peter/Documents/NetBeansProjects/JGDMS/JGDMS/dist/target/JGDMS-3.1.1-SNAPSHOT,
 -Djeri.jar=jgdms-jeri-3.1.1-SNAPSHOT.jar, 
-Dhigh-scale-lib.jar=high-scale-lib-1.0.6.jar, 
-Djava.net.preferIPv6Addresses=true, -DHOST=DESKTOP-R0ORPA2, 
-Dorg.apache.river.qa.harness.testhosts=, 
-Dmahalo.jar=mahalo-service-3.1.1-SNAPSHOT.jar, 
-Djavax.net.ssl.trustStore=harness\trust\truststore, 
-Dbouncy-jce.jar=bcprov-jdk15on-1.59.jar, 
-Dorg.apache.river.discovery.x500.trustStore=file:/C:/Users/peter/Documents/NetBeansProjects/JGDMS/qa/harness/trust/truststore,
 -Doutrigger-dl.jar=outrigger-dl-3.1.1-SNAPSHOT.jar, 
-Ddisco.jar=jgdms-discovery-providers-3.1.1-SNAPSHOT.jar, 
-Djgdms.version=3.1.1-SNAPSHOT, -Dgroup.jar=group-service-3.1.1-SNAPSHOT.jar, 
-Djava.security.policy=file:/C:/Users/peter/Documents/NetBeansProjects/JGDMS/qa/harness/policy/defaultsecuresharedvm.policy,
 -Dorg.apache.river.qa.harness.runjiniserver=true, 
-Dactivation-param.jar=jgdms-activation-parameters-3.1.1-SNAPSHOT.jar, 
-Dactivation.jar=jgdms-activation-3.1.1-SNAPSHOT.jar, 
-Dorg.apache.river.qa.harness.policies=file:/C:/Users/peter/Documents/NetBeansProjects/JGDMS/qa/src/org/apache/river/test/resources/jinitest.policy,
 -Dsun.net.maxDatagramSockets=1024, -Dnorm.jar=norm-service-3.1.1-SNAPSHOT.jar, 
-Dmercury.jar=mercury-service-3.1.1-SNAPSHOT.jar, 
-Djsk.url.jar=jgdms-url-integrity-3.1.1-SNAPSHOT.jar, 
-Djsk-lib.jar=jgdms-lib-3.1.1-SNAPSHOT.jar, 
-Dfiddler.jar=fiddler-service-3.1.1-SNAPSHOT.jar, 
-Dbouncy-jsse.jar=bctls-jdk15on-1.59.jar, 
-Dnet.jini.core.lookup.ServiceRegistrar.portAbitraryIfInUse=true, 
-Djavax.net.debug=ssl:handshake, 
-Dorg.apache.river.discovery.x500.trustStorePassword=trustpw, 
-Dphoenix-group.jar=phoenix-group-3.1.1-SNAPSHOT.jar, 
-Dnet.jini.security.allowInsecureConnections=true, 
-Dorg.apache.river.test.port=9082, 
-Dorg.apache.river.qa.harness.runkitserver=true, 
-Djava.security.auth.login.config=file:/C:/Users/peter/Documents/NetBeansProjects/JGDMS/qa/harness/trust/jsselogins,
 -Dfiddler-dl.jar=fiddler-dl-3.1.1-SNAPSHOT.jar, 
-Dmahalo-dl.jar=mahalo-dl-3.1.1-SNAPSHOT.jar, -Dorg.apache.river.qa.port=9081, 
-Dphoenix-init.jar=phoenix-init-3.1.1-SNAPSHOT.jar, 
-Doutrigger.jar=outrigger-service-3.1.1-SNAPSHOT.jar, 
-Djavax.net.ssl.trustStorePassword=trustpw, 
-Ddestroy.jar=jgdms-destroy-3.1.1-SNAPSHOT.jar, 
-Dqa.home=C:\Users\peter\Documents\NetBeansProjects\JGDMS\qa, -cp, 
C:/Users/peter/Documents/NetBeansProjects/JGDMS/JGDMS/dist/target/JGDMS-3.1.1-SNAPSHOT\lib\service-starter-3.1.1-SNAPSHOT.jar;C:/Users/peter/Documents/NetBeansProjects/JGDMS/JGDMS/dist/target/JGDMS-3.1.1-SNAPSHOT\lib\jgdms-collections-3.1.1-SNAPSHOT.jar;C:/Users/peter/Documents/NetBeansProjects/JGDMS/JGDMS/dist/target/JGDMS-3.1.1-SNAPSHOT\lib\high-scale-lib-1.0.6.jar;C:/Users/peter/Documents/NetBeansProjects/JGDMS/JGDMS/dist/target/JGDMS-3.1.1-SNAPSHOT\lib\phoenix-init-3.1.1-SNAPSHOT.jar;C:/Users/peter/Documents/NetBeansProjects/JGDMS/JGDMS/dist/target/JGDMS-3.1.1-SNAPSHOT\lib\jgdms-platform-3.1.1-SNAPSHOT.jar;C:/Users/peter/Documents/NetBeansProjects/JGDMS/JGDMS/dist/target/JGDMS-3.1.1-SNAPSHOT\lib-dl\jgdms-lib-dl-3.1.1-SNAPSHOT.jar;C:/Users/peter/Documents/NetBeansProjects/JGDMS/JGDMS/dist/target/JGDMS-3.1.1-SNAPSHOT\lib\jgdms-lib-3.1.1-SNAPSHOT.jar;C:/Users/peter/Documents/NetBeansProjects/JGDMS/JGDMS/dist/target/JGDMS-3.1.1-SNAPSHOT\lib\jgdms-discovery-providers-3.1.1-SNAPSHOT.jar;C:/Users/peter/Documents/NetBeansProjects/JGDMS/JGDMS/dist/target/JGDMS-3.1.1-SNAPSHOT\lib\jgdms-pref-class-loader-3.1.1-SNAPSHOT.jar;C:/Users/peter/Documents/NetBeansProjects/JGDMS/JGDMS/dist/target/JGDMS-3.1.1-SNAPSHOT\lib\jgdms-jeri-3.1.1-SNAPSHOT.jar;C:/Users/peter/Documents/NetBeansProjects/JGDMS/JGDMS/dist/target/JGDMS-3.1.1-SNAPSHOT\lib\phoenix-group-3.1.1-SNAPSHOT.jar;C:/Users/peter/Documents/NetBeansProjects/JGDMS/JGDMS/dist/target/JGDMS-3.1.1-SNAPSHOT\lib-dl\phoenix-dl-3.1.1-SNAPSHOT.jar;C:/Users/peter/Documents/NetBeansProjects/JGDMS/JGDMS/dist/target/JGDMS-3.1.1-SNAPSHOT\lib\phoenix-common-3.1.1-SNAPSHOT.jar;C:/Users/peter/Documents/NetBeansProjects/JGDMS/JGDMS/dist/target/JGDMS-3.1.1-SNAPSHOT\lib\jgdms-rmi-tls-3.1.1-SNAPSHOT.jar;C:/Users/peter/Documents/NetBeansProjects/JGDMS/JGDMS/dist/target/JGDMS-3.1.1-SNAPSHOT\lib\jgdms-activation-3.1.1-SNAPSHOT.jar;C:/Users/peter/Documents/NetBeansProjects/JGDMS/JGDMS/dist/target/JGDMS-3.1.1-SNAPSHOT\lib\jgdms-activation-parameters-3.1.1-SNAPSHOT.jar;C:/Users/peter/Documents/NetBeansProjects/JGDMS/JGDMS/dist/target/JGDMS-3.1.1-SNAPSHOT\lib\jgdms-url-integrity-3.1.1-SNAPSHOT.jar;C:/Users/peter/Documents/NetBeansProjects/JGDMS/JGDMS/dist/target/JGDMS-3.1.1-SNAPSHOT\lib\bcprov-jdk15on-1.59.jar;C:/Users/peter/Documents/NetBeansProjects/JGDMS/JGDMS/dist/target/JGDMS-3.1.1-SNAPSHOT\lib\bctls-jdk15on-1.59.jar;C:/Users/peter/Documents/NetBeansProjects/JGDMS/JGDMS/dist/target/JGDMS-3.1.1-SNAPSHOT\lib\security-policy-debug-3.1.1-SNAPSHOT.jar,
 org.apache.river.phoenix.init.ActivationGroupInit]
       [java] ActSys-err: javax.net.ssl|WARNING|F1|(JSK) mux request 
dispatch|2021-08-11 14:57:03.067 AEST|ServerNameExtension.java:266|Unable to 
indicate server name
       [java] ActSys-err: javax.net.ssl|DEBUG|F1|(JSK) mux request 
dispatch|2021-08-11 14:57:03.067 AEST|SSLExtensions.java:272|Ignore, context 
unavailable extension: server_name
       [java] ActSys-err: javax.net.ssl|INFO|F1|(JSK) mux request 
dispatch|2021-08-11 14:57:03.068 AEST|AlpnExtension.java:182|No available 
application protocols
       [java] ActSys-err: javax.net.ssl|DEBUG|F1|(JSK) mux request 
dispatch|2021-08-11 14:57:03.068 AEST|SSLExtensions.java:272|Ignore, context 
unavailable extension: application_layer_protocol_negotiation
       [java] ActSys-err: javax.net.ssl|DEBUG|F1|(JSK) mux request 
dispatch|2021-08-11 14:57:03.068 AEST|SessionTicketExtension.java:408|Stateless 
resumption supported
       [java] ActSys-err: javax.net.ssl|DEBUG|F1|(JSK) mux request 
dispatch|2021-08-11 14:57:03.070 AEST|SSLExtensions.java:272|Ignore, context 
unavailable extension: cookie
       [java] ActSys-err: javax.net.ssl|DEBUG|F1|(JSK) mux request 
dispatch|2021-08-11 14:57:03.075 AEST|PreSharedKeyExtension.java:662|No session 
to resume.
       [java] ActSys-err: javax.net.ssl|DEBUG|F1|(JSK) mux request 
dispatch|2021-08-11 14:57:03.075 AEST|SSLExtensions.java:272|Ignore, context 
unavailable extension: pre_shared_key
       [java] ActSys-err: javax.net.ssl|DEBUG|F1|(JSK) mux request 
dispatch|2021-08-11 14:57:03.077 AEST|ClientHello



--
Regards,
 
Peter Firmstone
0498 286 363
Zeus Project Services Pty Ltd.