The Java application (running on Windows) was working fine using com.ibm.as400.access.AS400. This application will perform RPC on IBM i.
This Java application was modified to use encrypted SSL connections and all references to this class were changed to use com.ibm.as400.access.SecureAS400 instead.
Initial testing was successful however, when shutting down the application, the program calls disconnectAllServices(), and we see an exception thrown in the console.
Following is the code snippet used to explain the flow. Note that I extracted parts of the code that reference the object SecureAS400, and the order of execution may not be correct:
import com.ibm.as400.access.SecureAS400;
import com.ibm.as400.access.ProgramCall
...
private SecureAS400 system;
...
system = new SecureAS400(host, user, pwd);
system.connectService(SecureAS400.COMMAND);
ProgramCall pc = new ProgramCall(system);
job = pc.getServerJob();
job.setJobMessageQueueFullAction(Job.MESSAGE_QUEUE_ACTION_WRAP);
if (priority.intValue() > 0) {
job.setRunPriority(priority.intValue());
job.commitChanges();
}
...
...
//Process Message
CharacterFieldDescription srcDta = new CharacterFieldDescription(
new AS400Text(254, system), "SRCDTA");
...
String filePath = (new QSYSObjectPathName(workLibrary, fileName, "FILE")).getPath();
SequentialFile seqFile = new SequentialFile(system, filePath);
RecordFormat recFmt = null;
recFmt = new RecordFormat(fileName);
recFmt.addFieldDescription(...);
recFmt.addFieldDescription(...);
recFmt.addFieldDescription(srcDta);
seqFile.close();
seqFile.delete();
...
...
//Begin
private ProgramCallDocument pcml;
...
pcml = new ProgramCallDocument(system, pcmlFile);
pcml.setValue("lansaexec.lansapgmlib", lansaPgmLibrary);
pcml.setValue(...);
pcml.setValue(...);
...
pcml.callProgram("lansacc")
...
//Commit
pcml.setValue("lansacc.command", flag ? "CMT" : "RLB");
pcml.callProgram("lansacc")
...
//Close connection
pcml.setValue("lansacc.command", "END");
pcml.callProgram("lansacc");
system.disconnectAllServices();
Following is what we see in the console log:
javax.net.ssl|FINE|52|RMI TCP Connection(7) CST|null:-1|close the SSL connection (initiative)
javax.net.ssl|FINE|52|RMI TCP Connection(7) CST|null:-l|close inbound of SSLSocket
javax.net.ssl|FINE|39|AS400 Read Daemon [system:machine.name.local;job419838/QUSER/QZRCSRVS] nu11:-1|Received alert message (
"Alert": {
"level" : "warning"
"description": "close_notify"
}
)
javax.net.ssl|WARNING|52|RMI TCP Connection:- CST|null:-1|SSLSocket duplex close failed (
"throwable" : {
java.net.SocketException: Socket is closed
at java.net.Socket.shutdownInput(Unknown Source)
at sun.security.ssl.BaseSSLSocketImpl.shutdownInput(Unknown Source)
at sun.security.ssl.SSLSocketImpl.shutdownInput(Unknown Source)
at sun.security.ssl.SSLSocketImpl.bruteForceCloseInput(Unknown Source)
at sun.security.ssl.SSLSocketImpl.duplexCloseOutput(Unknown Source)
at sun.security.ssl.SSLSocketImpl.close(Unknown Source)
at com.ibm.as400.access.SocketContainerJSSE.close (SocketContainerJSSE.java:69)
at com.ibm.as400.access.AS400ThreadedServer.forceDisconnect (AS400ThreadedServer.java:258)
at com.ibm.as400.access.AS400ImplRemote.disconnectServer (AS400implRemote.java:459)
at com.ibm.as400.access.AS400ImplRemote.disconnect(AS400implRemote.java:431)
at com.ibm.as400.access.AS400.disconnectAllServices(AS400.java:1412)
at com.***.***.server.iseries.iSeriesSessionImpl.close(iSeriesSessionImpl.java:307)
at com.***.***.server.ATASServiceImpl.close(ATASServiceImpl.java:560)
at com.***.***.server.ATASServiceimpl_Skel.dispatch(Unknown Source)
at sun.rmi.server.UnicastServerRef.OldDispatch(Unknown Source)
at sun.rmi.server.UnicastServerRef.dispatch(Unknown Source)
at sun.rmi.transport.Transport$l.run (Unknown Source)
at sun.rmi.transport.Transport$l.run (Unknown Source)
at java.security.AccessController.doPrivileged(Native Method)
at sun.rmi.transport.Transport.serviceCall (Unknown Source)
at sun.rmi.transport.tcp.TCPTransport.handlemessages(Unknown Source)
at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.rune(Unknown Source)
at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.lambda$run$e (Unknown Source)
java.security.AccessController.doPrivileged(Native Method)
sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(Unknown Source)
java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
Any idea what is wrong? How we can troubleshoot this error? Can we just ignore the error since the connection is closed anyway?
Update 1:
I also noticed the same error when the SSL Connection is opened in com.ibm.as400.access.AS400.connectService():
javax.net.ssl|FINE|36|RMI TCP Connection(2)-ip-address|date-time CST|null:-1|duplex close of SSLSocket
javax.net.ssl|FINE|36|RMI TCP Connection(2)-ip-address|date-time CST|null:-1|close the underlying socket
javax.net.ssl|FINE|36|RMI TCP Connection(2)-ip-address|date-time CST|null:-1|close the SSL connection (initiative)
javax.net.ssl|FINE|36|RMI TCP Connection(2)-ip-address|date-time CST|null:-1|close inbound of SSLSocket
javax.net.ssl|WARNING|36|RMI TCP Connection(2)-ip-address|date-time CST|null:-1|SSLSocket duplex close failed (
"throwable" : {
java.net.SocketException: Socket is closed
at java.net.Socket.shutdownInput(Unknown Source)
at sun.security.ssl.BaseSSLSocketImpl.shutdownInput(Unknown Source)
at sun.security.ssl.SSLSocketImpl.shutdownInput(Unknown Source)
at sun.security.ssl.SSLSocketImpl.bruteForceCloseInput(Unknown Source)
at sun.security.ssl.SSLSocketImpl.duplexCloseOutput(Unknown Source)
at sun.security.ssl.SSLSocketImpl.close(Unknown Source)
at com.ibm.as400.access.SocketContainerJSSE.close(SocketContainerJSSE.java:69)
at com.ibm.as400.access.AS400NoThreadServer.forceDisconnect(AS400NoThreadServer.java:245)
at com.ibm.as400.access.AS400ImplRemote.signonDisconnect(AS400ImplRemote.java:2548)
at com.ibm.as400.access.AS400ImplRemote.disconnect(AS400ImplRemote.java:422)
at com.ibm.as400.access.AS400.signon(AS400.java:4212)
at com.ibm.as400.access.AS400.connectService(AS400.java:1336)
at com.***.iseries.iSeriesSessionImpl.open(iSeriesSessionImpl.java:246)
at com.***.***SServiceImpl.initiate(***SServiceImpl.java:379)
at com.***.***SServiceImpl_Skel.dispatch(Unknown Source)
...}
)
Per this bug report on OpenJDK:
https://bugs.openjdk.org/browse/JDK-8255148
This is a feature of SSL logging and can be ignored.
I am not sure the same allies to any JDK release and falvores. I see the output of the Java properties:
C:>java -XshowSettings:properties -version
...
java.runtime.name = Java(TM) SE Runtime Environment
java.runtime.version = 1.8.0_321-b07
java.specification.name = Java Platform API Specification
java.specification.vendor = Oracle Corporation
java.specification.version = 1.8
java.vendor = Oracle Corporation
java.vendor.url = http://java.oracle.com/
java.vendor.url.bug = http://bugreport.sun.com/bugreport/
java.version = 1.8.0_321
java.vm.info = mixed mode
java.vm.name = Java HotSpot(TM) Client VM
java.vm.specification.name = Java Virtual Machine Specification
java.vm.specification.vendor = Oracle Corporation
java.vm.specification.version = 1.8
java.vm.vendor = Oracle Corporation
Also, I found out that Oracle JDK has a similar issue per this link:
https://knowledge.broadcom.com/external/article/252935/sslsocket-duplex-close-failed-messages-i.html
And, the solution is to remove the logging JVM switch:
-Djavax.net.debug=ssl:handshake:verbose