TLS connection dies under ??? circumstances [even/at least under POSIX!]

[natevw]

To reproduce, setup a key and start a local proxy server with your "config/env" file contents as such:

PORT=5005
zzz_AUTH_TESSEL_OA2=http://tessel-proxy-dev:the-tessel-devenv@localhost:3002
AUTH_HARDCODED=DEV-CRED

Then run this script under colony built from the #702 branch (also, note relative path to proxy's public key):

process.env._PROXY_DBG = true;
//process.env.PROXY_HOST = "proxy.192.168.4.114.xip.io";
process.env.PROXY_HOST = "localhost";
process.env.PROXY_PORT = 5005;
process.env.PROXY_TOKEN = "DEV-CRED";
process.env.PROXY_CERT = require('fs').readFileSync("../proxy/config/public-cert.pem").toString();
process.env.PROXY_IDLE = 1e3;

var n = 0;
function makeRequest() {
  console.log("Making request", ++n);
  var req = require('http').request("http://dbg-"+n+".ipcalf.com/?format=text", function(res) {
    console.log("req status:", res.statusCode);
    res.on('data', function (d) {
      console.log("req data:", d.toString());
    });
    res.on('end', function () {
      console.log("req done.");
    });
  });
  req.on('error', function (e) {
    console.error("Problem with request:", e.stack);
  });
  req.end();
}

setInterval(makeRequest, 3e3);
setInterval(makeRequest, 100);

For me the following happens: the client keeps rolling along but soon doesn't get any responses back. If you look in the proxy logs, you'll see it thinks that the client has disconnected after only a few requests.

---

Now's where it gets interesting. Apply this one-line change locally and rebuild colony:

diff --git a/src/colony/modules/_net_proxied.js b/src/colony/modules/_net_proxied.js
index dec688f..278e223 100644
--- a/src/colony/modules/_net_proxied.js
+++ b/src/colony/modules/_net_proxied.js
@@ -38,7 +38,8 @@ var _PROXY_DBG = ('_PROXY_DBG' in process.env) || false,

 function createTunnel(cb) {
   if (_PROXY_DBG) console.log("TUNNEL -> START", new Date());
-  tls.connect({host:PROXY_HOST, port:PROXY_PORT, proxy:false, ca:[PROXY_CERT]}, function () {
+  //tls.connect({host:PROXY_HOST, port:PROXY_PORT, proxy:false, ca:[PROXY_CERT]}, function () {
+  net.connect({host:PROXY_HOST, port:PROXY_PORT, proxy:false, ca:[PROXY_CERT]}, function () {
     var proxySocket = this,
         tunnel = streamplex(streamplex.B_SIDE);
     tunnel.pipe(proxySocket).pipe(tunnel);

Do the same change in the proxy's "proxy.js" file (i.e. swap tls.createServer for net.createServer) — it should restart automatically if you've used npm start.

Now the tunnel connection will happen over plaintext socket for debugging — I originally did this so I could more easily see the pre-hangup tunnel data in Wireshark.

BUT now when you run the client test script, it now goes properly gangbusters with the requests/responses working for a long time (eventually my DNS server seems to get upset with all my requests, but still the system behaves otherwise ± as expected in the situation).

So the cause of the original dropped connection seems to be somewhere in the self._secure/axTLS codepath. Haven't gotten much farther than that debugging.

[natevw]

Here's what I've discovered so far:

The client code is usually just seeing EOF on a tls read, which causes it to stop actually TLS-ing:

…
send_raw_packet did SOCKET_WRITE of 53 bytes, ret=53
basic_read got 222 bytes from SOCKET_READ
basic_read got 0 bytes from SOCKET_READ
basic_read got 0 bytes from SOCKET_READ
basic_read got 0 bytes from SOCKET_READ
…

Wireshark confirms that the server is sending a FIN packet! No obvious reason why, I've tried piping to the tunnelSocket with {end:false} and logging relevant events and it sure seems like my code is not triggering this. I'll admit it's very strange that it is only a 'close' and not any 'error' on the server side. But note again that the problem goes away or at least is greatly postponed using net instead of tls…!

Interestingly, the socket seems to last a little while longer when running the non-clustered proxy server, though it still happens eventually.

[natevw]

Reduced test case (still needs server cert, so easiest to test out of pre-configured proxy repo).

Client:

require('tls').connect({port:5009, rejectUnauthorized:false}, function (sock) {
  console.log("connected");
  var sock = this,
      n = 0;
  setInterval(function () {
    sock.write((++n).toString());
  }, 10);
  sock.on('data', function (d) {
    console.log("data:", d.toString());
  });
});

Server:

var fs = require('fs'),
    tls = require('tls');

var PORT = +process.env.PORT || 5009,
    CERT_FILE = process.env.CERT_FILE || "config/public-cert.pem",
    KEY_FILE = process.env.KEY_FILE || "config/private-key.pem",
    KEY_PASS = process.env.KEY_PASS;

tls.createServer({
  key: fs.readFileSync(KEY_FILE),
  passphrase: KEY_PASS,
  cert: fs.readFileSync(CERT_FILE)
}, function (sock) {
  console.log("socket connected");
  sock.on('data', function (d) {
    console.log("data:", d.toString());
    sock.write(d);
  });
  sock.on('end', function () {
    console.log("done");
  });
  sock.on('close', function () {
    console.log("socket closed");
  });  
}).listen(PORT, function(){
  console.log("listening on port", this.address().port);
});

When client is run under node, works fine. When client is run under colony, similar close behavior noted. It seems the interval is relevant: I did not encounter trouble when writing every 100 milliseconds, but did when writing every 10.

[natevw]

Alright, got this almost cornered. In axTLS basic_read function there is code that sets ssl->need_bytes based on the fourth and fifth bytes of the incoming buffer. It then makes sure this is not too big.

If (ssl->need_bytes > RT_MAX_PLAIN_LENGTH+RT_EXTRA-BM_RECORD_OFFSET) is true, then it considers that as a SSL_ERROR_INVALID_PROT_MSG which gets sent as an SSL_ALERT_HANDSHAKE_FAILURE alert back to the other side of the connection.

So I'm not entirely sure what causes this, but an initial guess would be there is some mechanism where the server says it has/wants X bytes, while axTLS considers that X unreasonable.

[natevw]

Here's a log of what's happening: https://gist.github.com/natevw/141da955a39f997b79ec#file-001-debug_log-txt-L122

I noticed that axTLS can't handle a call to ssl_write in the case where ssl_read is in the middle of gathering a record, but I'm not convinced that's quite exactly what's happening here — at least related!

The basic_read method underlying ssl_read initially is waiting for #define SSL_RECORD_SIZE 5 bytes. It seems that it reads those 5 bytes, which I believe are where the length of the remaining payload is actually stored. But in some cases, it waits until the next read and then looks at that as if it started with the header it already read (but discarded due to what might be some sort of mismanagement of its NEED_RECORD flag).

[johnnyman727]

@natevw does this mean you're leaning towards a bug within the axtls library?

[natevw]

…or our usage of it.

received 5 bytes
17 03 02 00 30 
new read_len=5, got_bytes=0, need_bytes=48, need_record=0
tm_ssl_write len=1
unencrypted write
32 d7 06 24 6b af ee d2 : 45 66 cd 87 74 3b 3e 54 
43 dc b7 54 69 0a 0a 0a : 0a 0a 0a 0a 0a 0a 0a 0a 
sending 53 bytes
17 03 02 00 30 96 ab 8a : b4 6f fd 9c ba bb e7 18 
1a 1e 91 f0 4a a6 75 ce : e8 90 f6 d9 d5 c8 ad 36 
eb ae 9e 46 2d 52 c0 c8 : 85 7b 0f df 77 c9 a7 87 
a6 77 6b 19 61 
tm_ssl_write len=1
unencrypted write
33 72 5f 9d ce 22 29 9a : a3 4f f1 08 2e 1e e2 da 
9a 43 a6 e1 7e 0a 0a 0a : 0a 0a 0a 0a 0a 0a 0a 0a 
sending 53 bytes
17 03 02 00 30 f7 bb c9 : e6 e5 a4 22 82 4e 83 cd 
81 b2 aa 18 fd 03 80 2d : 52 a0 d1 80 ba 0c cd 87 
5f 29 7a 66 a0 25 e5 3a : 50 f8 72 45 34 53 98 aa 
ce 61 79 54 10 
read_len=48, read_index=0, got_bytes=0, need_bytes=48, need_record=1
received 48 bytes
1c 36 10 a6 b2 d8 83 e5 : 3d 43 8d 14 95 15 c7 9a 
df a1 9b c1 f1 94 56 31 : 90 1d 15 d4 13 0f b4 01 
0a 99 75 e9 f0 f0 84 54 : 5f 1b f5 ed 9f 9c 8a 8d 
TRIGGERED!
contents of size 48:
1c 36 10 a6 b2 d8 83 e5 : 3d 43 8d 14 95 15 c7 9a 
df a1 9b c1 f1 94 56 31 : 90 1d 15 d4 13 0f b4 01 
0a 99 75 e9 f0 f0 84 54 : 5f 1b f5 ed 9f 9c 8a 8d 
   --> 42674 (a6 b2)
new read_len=48, got_bytes=0, need_bytes=42674, need_record=1
Error: invalid protocol message

Sorry my debug printfs grew up a bit hard to follow and don't have the patch posted, but I can see after receiving the first 5 bytes, it leaves the method with "new … need_record=0". This is great. But then there are some intervening writes, and the next time it goes to read it has need_record=1. I'm still not quite sure what is changing the flag in the write code path…

[natevw]

Oh, duh, right there near the bottom of send_raw_packet it does a SET_SSL_FLAG(SSL_NEED_RECORD)! So unless there's a harder/better/faster/stronger version of axTLS that changes something about this, I would say we cannot do an ssl_write if there is an ssl_read in progress.

How exactly we detect and/or deal with this is beyond the scope of the progress I was able to make today.