TLS Alert when using smtp-protocol server with Java client

[aotenko]

node.js 4.2.2, module smtp-protocol, created a server. When starttls command is received, a TLS handshake occurs. With multiple workers in use, the server intermittently sends Alert close_notify (as captured by Java client TLS debug) after handshake and before any application data arrives (I can see the network data containing the Alert arrives before the application data is sent). This is easily reproducible with Java client.

($ node --version
v4.2.2

$ java -version
java version "1.7.0_80"
Java(TM) SE Runtime Environment (build 1.7.0_80-b15)
Java HotSpot(TM) 64-Bit Server VM (build 24.80-b11, mixed mode)

$ uname -a
Linux hostname 3.13.0-43-generic #72-Ubuntu SMP Mon Dec 8 19:35:06 UTC 2014 x86_64 x86_64 x86_64 GNU/Linux)

I have reduced the server side to mimic just the way the ssl connection is treated by smtp-protocol (i.e. redirection through a new tls server started on localhost), and made the TLS server echo the incoming data back.

(see tls.txt attached - save to tls.js)

start like so:
./tls.js -w 1 -k key_cert.pem -c cert.pem

works fine.

./tls.js -w 4 -k key_cert.pem -c cert.pem

Intermittent failure. Specify -l debug to see the TLS handshake exchanges.

(i.e.:
$ java -cp . -DCONCURRENCY=4 blah.HTTPSStd otherhost 25125
EOF was not expected at this time)

The blah.HTTPSStd is the rendition of an HTTPS-like client (to test that it is a correctly operating TLS client just point at google.com 443) using standard JDK7 classes:

save the HTTPSStd.txt (attached in the next comment) to blah/HTTPSStd.java

compile with $ javac blah/HTTPSStd.java

run with $ java -cp . -DCONCURRENCY=4 blah.HTTPSStd otherhost 25125

to get extensive TLS diagnostics from the client side (really a lot, and not easy to contemplate because of concurrency involved), run with $ java -cp . -DCONCURRENCY=4 -Djavax.net.debug=all blah.HTTPSStd otherhost 25125

[aotenko]

tls.txt
HTTPSStd.txt

[aotenko]

A failing handshake (captured by -l debug; I've only added a few comments about the weird-looking HandshakeType and the Alert, and removed the separating '-', as they format the text). Observe that the Alert is printed at the same time as the last handshake messages sent by the server - the Alert was already in the buffer of the outgoing data before the handshake got on the wire, so it is clearly the server decision to close TLS. You can also capture and observe any succeeding connection, too - the only difference is the random data (key material, session-id, random), and the absence of the Alert at the end of the exchange:

tserver for socket 10.9.21.3:55708 tls id: 4000 receives 247 bytes

ContentType: 22
ProtocolVersion: 0303
Length: 242
HandshakeType: 1
Length: 0000ee
Contents: 0303565c4cb168fd14a6a82f876405ea9dd42479ef1815d7fe45b300e54834875160000038c023c027003cc025c02900670040c009c013002fc004c00e00330032c008c012000ac003c00d00160013c007c0110005c002c00c000400ff0100008d000a0034003200170001000300130015000600070009000a0018000b000c0019000d000e000f001000110002001200040005001400080016000b00020100000d001a00180603060105030501040304010303030102030201020201010000002d002b0000286d61726b2d736166656d61696c2d706572662d72657772697465722e73757266637265772e636f6d
tserver for socket 10.9.21.3:55708 tls id: 4000 sends 1567 bytes

ContentType: 22
ProtocolVersion: 0303
Length: 89
HandshakeType: 2
Length: 000055
Contents: 03030a46a8ca4c49587ca772a152ca3819b69a0ebbfe194d8d0690ca7d3d4c9e343920a82d0bae85939290ee339bd1946f61b4f890e44f462ca0d2059e1a090a04cc28c02700000dff01000100000b000403000102

ContentType: 22
ProtocolVersion: 0303
Length: 1121
HandshakeType: 11
Length: 00045d
(here was certificate)

ContentType: 22
ProtocolVersion: 0303
Length: 333
HandshakeType: 12
Length: 000149
Contents: 03001741043ef617a8fbec2dc6c00af5980d6f7e0d476b256456783d4f4dc1f1e1bcc5afd35aa2618a43d5a735b644
5ea3c5580c6c6eedeb76c2f57432802c33b446cae9ac0601010006b44aee0533cda1ed99dccd63548a385922db22892cbbd81db2
9908535c816e8471158f8fcb71ad66e29a1bfc70f12e46093d09cddc75cc4fec7328d216cef486248dd1f5dc73fc2577f7e1a466518f56bf600012a0eee4eb79cda7ef940cfed2c36cbfcb10ce9ce07efba914a7440fbabff5e4af540d735e1210e055d126faa2c1
98e60fd498cb50256bd09595cec5086914c5f22cf0098b41323d12dea9dcc1d4f3e21f377a45e3eceeeb7cca5aa721bc5162e67c
b002e4d9d7c25b7fa8325abd974bc570a565639a6b3f9e2a7d1b36e1c585a310b3919222a7aed6516194032a7f4dbb1e35affc5b
e4e46956611bf660a954b8baf5b6c6b332154e70b326

ContentType: 22
ProtocolVersion: 0303
Length: 4
HandshakeType: 14
Length: 000000
Contents:
tserver for socket 10.9.21.3:55708 tls id: 4000 receives 75 bytes

ContentType: 22ProtocolVersion: 0303
Length: 70
HandshakeType: 16
Length: 000042
Contents: 41049e40b6b8ad2c000972275a48409d50926716c1642e12426747d63d15d84f55627b0886ac122101730ef5c0f7c5
ec592599d42c82264b7f13c7fb135ea4fc6a9etserver for socket 10.9.21.3:55708 tls id: 4000 receives 91 bytes
tserver for socket 10.9.21.3:55708 tls id: 4000 receives 91 bytes

ContentType: 20 -- changing cipher - now client comms will be encrypted
ProtocolVersion: 0303
Length: 1
Contents: 01

ContentType: 22
ProtocolVersion: 0303
Length: 80
HandshakeType: 148 -- ignore this, it is actually encrypted
Length: 42dcb5
Contents: 21c1bbf5ed95491909535f0989d555f4e15f188481806c0f46a012ca39afd7e107257ee66cbeb56f184fa1b09b646b38f24891afa8b36fdcd02742a5fa8380ff7b6deefff6ad458c302ddb2a
tserver for socket 10.9.21.3:55708 tls id: 4000 sends 160 bytes

ContentType: 20 -- changing cipher - now server comms will be encrypted
ProtocolVersion: 0303
Length: 1
Contents: 01

ContentType: 22
ProtocolVersion: 0303
Length: 80
HandshakeType: 98 -- ignore this, it is actually encrypted
Length: 7c4d6b
Contents: 7936d0dde7417c35fc001bc7704edcb488aba3a85d38eb9e9040c817e8a26baa620aeee016508132cfd522ad761e9fad191bf418ec664feb2f6bacfaa3a7f6bb5610587e852b112b7f597606

ContentType: 21 -- Alert
ProtocolVersion: 0303
Length: 64
Contents: 774160f31420d3d635163131197c9f906d68951bab7983d07594c7e295192ec4756c00c69d4e2f048db5cab9e485060b9d31d11b11a13093c2fb2b235f316a5a

[aotenko]

Reproducible with TLSv1, TLSv1.1 and TLSv1.2 as selected by the Java client

[aotenko]

1. add option:
   .option('t', {
   alias: 'tls',
   default: false,
   describe: 'whether to start TLS server, or net server (and then redirect to a new TLS server for each connection)'
   })

2. update server creation:

   var isTls = Boolean(argv.tls);
   var tnet = isTls ? tls : net;

   tnet.createServer(opts, function(stream){
   if (isTls){
   if (argv.level != 'info') console.log('new connection from ' + stream.remoteAddress + ':' + stream.remotePort);
   stream.pipe(stream);
   return;
   }

3. ./tls -t true -w 4 -k key_cert.pem -c cert.pem

doesn't reproduce the issue. This seems to indicate that the issue is entirely due to how smtp-protocol adds TLS to the existing connection. If this is so, suggest the correct way to wrap the plain-text socket to continue the communication over TLS.

[aotenko]

It may well be an issue with net.Server, not tls.

If I start one tls server per worker (see tls2.txt), but wire the socket in the same manner, two important things occur: 1. I never see the Java client fail; 2. I never see the condition similar to index > 1 in tls.js (see the function on secureConnection calling sec.end() in tls.txt - I did notice that being invoked more than once in the smtp-protocol case, but it seems to always be invoked more than once on the tserver created for a succeeding connection, so I didn't think it's the cause of the failure).

tls2.txt

[aotenko]

I think I can boil this down to incorrect usage of net.Server by smtp-protocol. When creating a tlsServer, they listen on port 0 (which means to choose a random port), yet exclusive is left default. Thus multiple workers possibly may end up choosing the same random port (I don't know how to check whether this is happening, but the symptoms seem to add up to this story), and they will start sharing incoming connections. When this happens, the connection may end up being served by the "wrong" worker (smtp-protocol TLS processing logic is tied to the worker that received STARTTLS command), it will fire another secureConnection event (condition index > 0 in tls.js), and smtp-protocol will close that connection (on 'secureConnection' it calls sec.end()), which will be seen by the client as a nice termination of connection by server (the close_notify Alert).

Testing with exclusive=true. If this works as expected, will close as not a node.js bug (but need to propagate the fix to smtp-protocol).