Multithreading bug resulting in java.net.SocketException on Association.writeAReleaseRQ

[lexxoff]

Discovered in the module dcm4che-tool-storescu, when running storescu and dcmqrscp on AWS ec2 t2.medium instance.
Both are configured to use TLS, the problem doesn't seem to appear when using plain sockets.
Run of the storescu command sometimes results in the following intermitten exception:

java.net.SocketException: Socket is closed
	at sun.security.ssl.SSLSocketImpl.checkEOF(SSLSocketImpl.java:1520)
	at sun.security.ssl.SSLSocketImpl.checkWrite(SSLSocketImpl.java:1541)
	at sun.security.ssl.AppOutputStream.write(AppOutputStream.java:124)
	at java.io.OutputStream.write(OutputStream.java:75)
	at org.dcm4che3.net.PDUEncoder.write(PDUEncoder.java:126)
	at org.dcm4che3.net.PDUEncoder.writeAReleaseRQ(PDUEncoder.java:101)
	at org.dcm4che3.net.Association.writeAReleaseRQ(Association.java:395)
	at org.dcm4che3.net.State$4.writeAReleaseRQ(State.java:108)
	at org.dcm4che3.net.Association.release(Association.java:312)
	at org.dcm4che3.tool.storescu.StoreSCU.close(StoreSCU.java:511)
	at org.dcm4che3.tool.storescu.StoreSCU.main(StoreSCU.java:300)

The process quits with non-zero exit code.

There are no errors on the dcmqrscp side.

The cause of the failure is a race condition between two threads on the association release:

• main:
  StoreSCU opens a connection, sends data and executes as.release;
  as.release calls writeAReleaseRQ() that writes A-RELEASE-RQ to the SSLSocket;
  it doesn't finish writing when the second thread closes the socket.
• pool-1-thread-1:
  dcmqrscp server responds with A-RELEASE-RP;
  this thread reads it from the SSLSocket;
  it goes on and closes the socket, interrupting the first thread's write operation.

Environment:

• AWS ec2 t2.medium instance
• OS: CentOS Linux release 7.2.1511 (Core)
• JAVA: Java HotSpot(TM) 64-Bit Server VM (build 1.8.0_40-b26)

Steps to reproduce:

• configure certificates;
• run dcmqrscp:

bin/dcmqrscp -b CLOUD:5000 --dicomdir /tmp/DICOM/DICOMDIR --ae-config /tmp/ae.properties --tls --s-protocol TLSv1.2 --tls-protocol TLSv1.1 --key-store /secrets/tls/server.jks --trust-store /secrets/tls/server.jks  --key-store-pass "`cat /secrets/tls/server-passphrase`" --trust-store-pass "`cat /secrets/tls/server-passphrase`"

• run storescu until it fails:

while bin/storescu  -c CLOUD@localhost:5000 --tls --tls-protocol TLSv1.2 --tls-protocol TLSv1.1 --key-store /secrets/tls/client.jks --trust-store /secrets/tls/client.jks  --key-store-pass "`cat /secrets/tls/client-passphrase`" --trust-store-pass "`cat /secrets/tls/client-passphrase`"; do :; done

Attached files aws-socket-closed.tar.gz:

• aws.log: shows a normal execution, Association.writeAReleaseRQ took 0.35443 ms to finish
• aws-socket-closed.log: an intermitten failure. Association.writeAReleaseRQ took 3.28601 ms before throwing an exception.
• diag.patch: code used to produce logs

Possible solution:

adding a synchronized block in Association.writeAReleaseRQ() fixes the issue:

synchronized (this) {
    encoder.writeAReleaseRQ();
}

This bug may probably affect other parts of the code, as the synchronization issue lies in Association class.

[gunterze]

Cannot reproduce the issue with OpenJDK 1.8.0_252 on Ubuntu 20.04.1 LTS

• A-RELEASE-RP is not sent by the accepting DICOM peer before the last byte of the A-RELEASE-RQ was read!
• sun.security.ssl.SSLSocketImpl.checkWrite(SSLSocketImpl.java:1541) is called before writing the first byte of the A-RELEASE-RQ!