I'm trying to implement a basic TLS client/server framework. Everything seems to go fine until after the handshake, at which point the test echo server is supposed to read and write back whatever it receives.
I've run this from both sides with -Djavax.net.debug=all and the protocol downgraded to TLSv1 (but strarting from TLSv1.2). This is Oracle 8 on GNU/Linux x86-64 with security packs installed.
There are no exceptions thrown from either side until the server calls BufferedInputReader.read() using the stream obtained from SSLSocket.getInputStream(). At this point the test client is sitting waiting for console input to send to the echoing test server.
I've previously implemented TLS 1.2 servers in C and C++ using GnuTLS, so I have a basic understanding of the fundamentals involved. With regard to debugging this java implementation, I've read through stuff like like this and this and my description of the problem will follow that pattern.
On the server side things begin with:
main, READ: TLSv1 Handshake, length = 151
*** ClientHello, TLSv1
[...]
[read] MD5 and SHA1 hashes: len = 151
[...]
%% Initialized: [Session-1, SSL_NULL_WITH_NULL_NULL]
matching alias: tls_server_key
%% Negotiating: [Session-1, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA]
*** ServerHello, TLSv1
A "RandomCookie" is sent and then the server cert. At this point the client has gone through:
*** ClientHello, TLSv1
[...]
[write] MD5 and SHA1 hashes: len = 151
main, WRITE: TLSv1 Handshake, length = 151
[...]
main, READ: TLSv1 Handshake, length = 1683
*** ServerHello, TLSv1
...reads an identical "RandomCookie" sent from the server, then...
Cipher Suite: TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA
Compression Method: 0
Extension renegotiation_info, renegotiated_connection: <empty>
***
%% Initialized: [Session-1, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA]
** TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA
[read] MD5 and SHA1 hashes: len = 81
Then reads the server cert. The client has the CA cert with which this is signed, so eventually there's a Found trusted certificate, then
*** ECDH ServerKeyExchange
Server key: Sun EC public key, 256 bits
public x coord: 99333168850581082484902625735441572937781175927498004126728233464162626469072
public y coord: 8153267160158506973550759395885968557147147981466758879486894574711221505422
parameters: secp256r1 [NIST P-256, X9.62 prime256v1] (1.2.840.10045.3.1.7)
[read] MD5 and SHA1 hashes: len = 459
[...]
*** ServerHelloDone
[read] MD5 and SHA1 hashes: len = 4
0000: 0E 00 00 00 ....
*** ECDHClientKeyExchange
[...]
[write] MD5 and SHA1 hashes: len = 70
[...]
main, WRITE: TLSv1 Handshake, length = 70
[Raw write]: length = 75
[...]
*** Finished
[...]
main, WRITE: TLSv1 Handshake, length = 48
[Raw write]: length = 53
[...]
main, READ: TLSv1 Change Cipher Spec, length = 1
...some raw reads totalling 53 bytes...
main, READ: TLSv1 Handshake, length = 48
Padded plaintext after DECRYPTION: len = 48
[...]
*** Finished
verify_data: { 188, 99, 75, 234, 162, 27, 147, 7, 173, 51, 170, 34 }
***
%% Cached client session: [Session-1, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA]
[read] MD5 and SHA1 hashes: len = 16
And then reports that it's "Connected", having passed through this relevant code:
sock.setUseClientMode(true);
sock.startHandshake();
in = new BufferedInputStream(sock.getInputStream());
out = new BufferedOutputStream(sock.getOutputStream());
The server set-up being much the same, except the socket came from SSLServerSocket.accept() (instead of an appropriate factory) and setUseClientMode(false) is used before the handshake. Initially I wasn't using setUseClientMode() at all on either side, then noticed javadoc says, "This method must be called before any handshaking occurs", although doing so made no difference at all to the debug output or result.
What is interesting is that after the call to startHandshake() and the creation of the in/out BufferedStreams, isClosed() reports false for both client and server, but the next move by the server is in here (this is from a "TLSconnection" class used by both the server and client class):
public int recv (byte[] data) throws IOException
{
if (sock.isClosed()) return -1;
int len = in.read(data, 0, data.length);
if (len == -1) shut();
return len;
}
Where isClosed() now returns true, which makes sense since the debugging trace on the server concludes:
[write] MD5 and SHA1 hashes: len = 16
main, WRITE: TLSv1 Handshake, length = 48
[Raw write]: length = 53
%% Cached server session: [Session-1, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA]
main, called close()
main, called closeInternal(true)
main, SEND TLSv1 ALERT: warning, description = close_notify
[...]
main, WRITE: TLSv1 Alert, length = 32
[...]
main, called closeSocket(true)
I've also done this using a handshakeCompletedListener() that simply writes to standard error and here's what it does to that:
%% Cached server session: [Session-1, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA]
main, called close()
main, called closeInternal(true)
main
HANDSHAKE COMPLETED
, SEND TLSv1 ALERT: warning, description = close_notify
To me, this appears that:
- The client connects.
- The server accepts.
- A TLS handshake occurs during which:
- Cipher suites are successfully negotiated.
- The client verifies the server certificate
- The server arbitrarily closes the socket.
- The client is left hanging.
I've been through variations of this for hours and again:
- There are no exceptions thrown.
- There are no apparent errors in the debug output.
- There is no explanation for why the server arbitrarily closes the socket.
The complete code for the three classes (connection, server, client) is about 250 lines, plus about another hundred each for the test instances (client and server), so I haven't posted it all here, but what's shown is what is in play during the debug session.
I'm assuming this can't really have anything to do with cert or key errors since there is nothing to indicate such, or that the handshake failed, or that anybody rejected anybody else for any reason.
In response to Steffen Ullrich's comment that "It looks like the server is doing a clean shutdown (sends close_notify) so I would suggest that something in your code is actually doing an explicit close" -- which is the same thing I would think first -- here's the section of the test server code which leads up to sock.isClosed() returning true:
while (true) {
TLSconnection con = null;
try { con = server.acceptConnection(true); }
catch (Throwable ex) {
ex.printStackTrace();
continue;
}
if (con != null) {
System.out.println (
"Accepted: "
+TestCommon.describeConnection(con.getDetails())
);
}
while (con != null) {
// Echo.
try {
int check = con.recv(buffer);
if (check == -1) {
System.out.println("Disconnected.");
What literally happens in relation to this is the "Accepted" bit is printed out; the describeConnection() method is simply:
static String describeConnection (TLSconnection.Details details)
{
if (details.addr == null) return "Not connected.";
StringBuffer sb = new StringBuffer(details.addr.getHostAddress()+":")
.append(details.remotePort).append(" (local ")
.append(details.localPort).append(")");
return sb.toString();
}
Then the con.recv() method is the one shown completely earlier, where isClosed() now returns true. Again, there's no nullPointerExceptions that occur in the interim, etc. In other words, somewhere between that accept and recv the socket is being closed by the JVM.
The acceptConnection() method (of TLSserver) is:
public TLSconnection acceptConnection (boolean handshake)
throws TLSexception {
try (SSLSocket client = (SSLSocket)listenSock.accept()) {
client.setUseClientMode(false);
return new TLSconnection(client, handshake);
} catch (Throwable ex) {
throw new TLSexception (
"Accept failed:",
ex
);
}
}
