agent handed out destroyed socket after request.abort()

[davepacheco]

I'm not sure if this project is under much active development, but I have a test program that reliably reproduces a case where the keep-alive-agent assigns a destroyed HTTPS socket to a request. The result is that the request never gets off the ground, and if this is the only thing that your Node program is doing, then Node just exits 0 because the event loop looks done.

Here's my test program:
https://gist.github.com/davepacheco/679eaf910b7e8df28406

The comments explain all this, but basically, the test program makes an HTTPS request, waits for a response, aborts the request, waits 50ms, and then makes another request. Every time I run it, the second request is assigned a socket that's already destroyed. As the program is written, it detects this and calls process.abort() to give you a core file. Here's what it looks like:

$ node katest.js 
2015-07-03T00:32:05.328Z: creating request
2015-07-03T00:32:05.749Z: aborting after response received
2015-07-03T00:32:05.751Z: starting again in 50ms
2015-07-03T00:32:05.797Z: creating request
Error: assigned a destroyed socket!
    at ClientRequest.<anonymous> (/home/dap/node-httpstream/tests/katest.js:111:8)
    at ClientRequest.emit (events.js:117:20)
    at http.js:1758:9
    at process._tickCallback (node.js:419:13)
Abort (core dumped)

As written, it uses the keep-alive-agent Secure agent. You can change it to use the Node built-in agent, in which case the second request completes successfully:

$ node katest.js 
2015-07-03T00:32:46.296Z: creating request
2015-07-03T00:32:46.704Z: aborting after response received
2015-07-03T00:32:46.705Z: starting again in 50ms
2015-07-03T00:32:46.751Z: creating request
2015-07-03T00:32:48.985Z: event: end (read 5242880 bytes)
$ echo $?
0

You can also see what happens if you take out the code that aborts when it detects a destroyed socket:

$ node katest.js 
2015-07-03T00:33:29.510Z: creating request
2015-07-03T00:33:29.922Z: aborting after response received
2015-07-03T00:33:29.923Z: starting again in 50ms
2015-07-03T00:33:29.970Z: creating request
Error: assigned a destroyed socket!
    at ClientRequest.<anonymous> (/home/dap/node-httpstream/tests/katest.js:111:8)
    at ClientRequest.emit (events.js:117:20)
    at http.js:1758:9
    at process._tickCallback (node.js:419:13)
(not exiting on error)
$ echo $?
0

Note that it doesn't complete the second request, but just exits 0 (because the event loop has nothing to do).

I believe the buggy code is in HTTPSKeepAliveAgent.isSocketUsable:
https://github.com/ceejbot/keep-alive-agent/blob/master/index.js#L121-L126

The comment says that "TLS sockets null out their secure pair's ssl field", but at least on my version of Node (0.10.30), that doesn't always seem to be true.

In case it's helpful, the core file shows what the socket actually looks like (a lot of stuff snipped for brevity):

$ mdb core
Loading modules: [ libumem.so.1 libc.so.1 ld.so.1 ]
> ::load ../../mdb_v8_stable_32.so
V8 version: 3.14.5.9
Autoconfigured V8 support from target
C++ symbol demangling enabled

> ::jsstack -vn0
native: libc.so.1`_lwp_kill+0x15
native: libc.so.1`raise+0x2b
native: libc.so.1`abort+0x10e
        (1 internal frame elided)
native: _ZN2v88internalL21Builtin_HandleApiCallENS0_12_GLOBAL__N_116Buil...
        (1 internal frame elided)
js:     <anonymous> (as <anon>)
          file: /home/dap/node-httpstream/tests/katest.js
          posn: line 107
          this: a5f23781 (JSObject: ClientRequest)
          arg1: a0249979 (JSObject: CleartextStream)
        (1 internal frame elided)

...
> a0249979::jsprint -d3
{
    "_ended": true,
    "onend": function socketOnEnd,
    "_events": {
        "error": function socketErrorListener,
        "sslOutEnd": function <anonymous> (as <anon>),
        "connect": function g,
        "finish": function g,
        "free": function <anonymous> (as onFree),
        "agentRemove": function <anonymous> (as onRemove),
        "drain": function ondrain,
        "close": [
            function <anonymous> (as onClose),
            function socketCloseListener,
        ],
    },
    "_requestCount": 1,
    "allowHalfOpen": true,
...
    "_sslOutCb": null,
...
    "_pendingCallback": null,
    "_halfRead": false,
    "authorized": true,
    "socket": {
        "_connecting": false,
        "_handle": null,
...
        "readable": false,
        "domain": null,
        "_events": {
            "finish": [...],
            "end": [...],
            "drain": [...],
            "_socketEnd": function onSocketEnd,
            "close": [...],
        },
        "_maxListeners": 10,
...
        "writable": false,
        "allowHalfOpen": false,
        "onend": null,
        "destroyed": true,
        "bytesRead": 10512,
        "_bytesDispatched": 782,
        "_pendingData": null,
        "_pendingEncoding": "",
        "_consuming": true,
        "_idleNext": null,
        "_idlePrev": null,
        "_idleTimeout": 2147483647,
    },
    "_retryAfterPartial": false,
    "ondata": function socketOnData,
...
    "domain": null,
    "_reading": true,
    "_pendingEncoding": "",
    "_doneFlag": false,
...
    "_pending": null,
    "npnProtocol": undefined,
    "_finished": false,
    "readable": false,
    "_controlReleased": true,
    "_resumingSession": false,
    "writable": false,
    "pair": {
        "domain": null,
        "_events": {},
        "_maxListeners": 10,
        "server": undefined,
        "_secureEstablished": true,
        "_isServer": false,
        "_encWriteState": true,
        "_clearWriteState": true,
        "_doneFlag": false,
        "_destroying": false,
        "credentials": {
            "context": [...],
        },
        "_rejectUnauthorized": true,
        "_requestCert": true,
        "ssl": {},
        "servername": false,
...
        "fd": undefined,
        "npnProtocol": undefined,
    },
    "_destroyed": true,
}

[davepacheco]

I ran into this because restify uses this module on Node v0.10.

[vinaykaran]

davepacacheo, is there any way to reuse a socket when using https. I am running a node soap server on https and using a meteor client along with keep-alive-agent using the Secure function but it does not reuse the sockets. I tried using the agent: new https.Agent() also but the sockets keep getting created newly for every method call i make from my client

import KeepAliveAgent from 'keep-alive-agent';
import https from 'https';


Meteor.startup(() => {
  // code to run on server at startup


//var url = 'http://localhost/wsdl?wsdl';
var url = 'C:/meteorapps/soapclient/server/HelloService.wsdl';
var args = {firstName: 'Betty'};

//myAgent = new KeepAliveAgent.Secure( { maxSockets:1 } );

myAgent = new https.Agent();

var options = {
  agent: myAgent,
  headers: {"Connection":"Keep-Alive"},
  maxSockets:1,
  keepAlive:true,
  keepAliveMsecs:3000,
}

try {

  var client = Soap.createClient(url,options);

  client.setSecurity(new Soap.ClientSSLSecurity(
    'C:\\SSLkeyandcert\\server.key',
    'C:\\SSLkeyandcert\\server.crt',
    {

      strictSSL:false,

    }, 

  ));

  client.addSoapHeader({Username:'Johnson'});

  var result = client.sayHello(args,options);
  console.log(result);
  result = client.sayHelloHi({firstNameHi:'John'},options);
  console.log(result);
}

catch (err)  {
  if(err.error === 'soap-creation') {
    console.log('SOAP Client creation failed');
  }
  else if (err.error === 'soap-method') {
    console.log(err);
  }

}

});