Re: JDK17 - Possible TLS issue.

Wed, 11 Aug 2021 19:22:23 -0700 

Thanks Jamil,

You'll need to use JDK 8 for building / compiling,

Additional to the build instructions, to test the specific test in question:
Create a build.properties file in the project root directory (same directory as README.md), containing the following entries: 

   jsk.home=absolute path to JGDMS project directory.
   
run.tests=org/apache/river/test/spec/lookupservice/test_set02/LookupNegMatches.td

These two files allow you to manipulate JVM arguments and logging:

https://github.com/pfirmstone/JGDMS/blob/trunk/qa/src/org/apache/river/qa/resources/qaDefaults.properties

https://github.com/pfirmstone/JGDMS/blob/trunk/qa/src/org/apache/river/test/resources/qa1.logging
JGDMS runs with a SecurityManager enabled by default, I haven't yet tested it without SM.
In the event that you experience an AccessControlException / SecurityException, insert the following two properties to qaDefaults.properties, at line 426: 

-Djava.security.manager=org.apache.river.tool.SecurityPolicyWriter,\
-DSecurityPolicyWriter.path.properties=${qa.home}/harness/policy/securitypolicywriterpath.properties,\
These will update policy files with any missing permissions the next time you run the test (you may need to run it on JDK16), then you should remove these two options, as the policy files will have all necessary permissions.
I did manage to capture one passing run on JDK17, I haven't been able to reproduce it, but it suggests the failure might be related to timing, locking or gc: 

https://github.com/pfirmstone/JGDMS/blob/trunk/qa/LookupNegMatches-security-debug-fine-logging-tls-handshake.txt

Regards,

Peter.

On 12/08/2021 5:32 am, Jamil Nimeh wrote:

Hi Peter,
I've captured the issue in https://bugs.openjdk.java.net/browse/JDK-8272340.  The synopsis is a bit vague right now as I'm going through the logs.  I'll revise it once I have a little more info.  I was also looking at the JGDMS project just to see how easy it would be for me to replicate the specific tests that exhibit the failure.  I may contact you directly for a bit more info.  The instructions on the JGDMS page look pretty straightforward, so hopefully that won't take long to replicate. 

Thanks,

--Jamil

On 8/11/2021 3:12 AM, Peter Firmstone wrote:

谢谢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

Reply via email to