Login/Register
Error java.net.SocketException: Socket is closed when closing AS400 Secure RPC session
Asked Answered
javasslibm-midrangermi
A

0

0

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

Ammerman answered 1/2 at 23:17 Comment(7)
I think so. disconnectAllServices() is closing all known sockets, well at least the socket that the RMI call that invokes it is being made on. You could try starting a thread with a small delay to call disconnectAllServices(), and return from the remote method immediately. – Kleiman
I'm not quite following you could you please explain? – Ammerman
Explain? I did explain. What part of it didn't you understand? – Kleiman
Please bear with me it was a long day. It worked fine using com.ibm.as400.access.AS400 so what could have gone wrong when using SecureAS400? You are saying to start a process in the background to run disconnectAllServices() and I'm thinking why a delay and disconnecting the services in another thread would solve the problem. Maybe the SecureAS400 has some defaults that will close the connection implicitly. The RPC was completed successfully but the socket was closed somewhere else. So how the delay and using a thread is going the solve the problem? – Ammerman
The remote method machinery closed this socket while disconnectAllServices() was executing. You want to give it a chance to run first, not concurrently. – Kleiman
My understanding is this: Java code sent a command to end the connection using pcml.setValue("lansacc.command", "END"); pcml.callProgram("lansacc"); so we can try ending the connection using disconnectAllServices() without sending the END command. Is my understanding correct? I don't understand how the disconnectAllServices() is running concurrently as you mentioned. – Ammerman
Per OpenJDK bugs.openjdk.org/browse/JDK-8255148 this is a logging feature of SSL and it can be ignored. It is not clear to me if this applies to all JDK releases. – Ammerman

© 2022 - 2024 — McMap. All rights reserved.