Node: Uncaught TypeError using http.Agent in keep-alive mode

[cdhowie]

• Version: v6.6.0 (also happens on v4.5.0)
• Platform: Debian Jessie
• Subsystem: http

This is the same issue as this one I filed against aws-sdk-js, but I'm getting more suspicious that this is actually a Node issue.

Configuration example:

AWS.config.update({
    httpOptions: {
        agent: new (require('http').Agent)({
            keepAlive: true
        })
    }
});

After some number of HTTP requests (a few dozen) using an http.Agent constructed with keepAlive: true, the following uncaught error occurs:

     Uncaught TypeError: object is not a function
      at afterWrite (_stream_writable.js:361:3)
      at onwrite (_stream_writable.js:352:7)
      at WritableState.onwrite (_stream_writable.js:89:5)
      at Socket._writeGeneric (net.js:714:5)
      at Socket._writev (net.js:719:8)
      at doWrite (_stream_writable.js:305:12)
      at clearBuffer (_stream_writable.js:394:5)
      at Socket.Writable.uncork (_stream_writable.js:243:7)
      at ClientRequest._flushOutput (_http_outgoing.js:678:10)
      at ClientRequest.OutgoingMessage._flush (_http_outgoing.js:652:16)
      at _http_client.js:195:10
      at callSocketMethod (_http_client.js:591:7)
      at ClientRequest.onSocket (_http_client.js:596:7)
      at tickOnSocket (_http_client.js:562:7)
      at onSocketNT (_http_client.js:574:5)
      at _combinedTickCallback (internal/process/next_tick.js:74:11)
      at process._tickDomainCallback (internal/process/next_tick.js:122:9)

Digging into the Node code, this hints that the callback supplied to a net.Socket.write() call was omitted, but the documentation states this callback is optional. In either case, changing keepAlive: true to keepAlive: false when constructing the http.Agent eliminates the error.

I do not make any HTTP calls myself, only via the AWS SDK. I can't find any obvious bug in my code; I'm just making AWS DynamoDB calls using their SDK. Since the call stack for the error is all Node internals, I do not have any opportunity to properly catch the error; the process simply dies.

The error consistently happens on one particular test. If I comment out a particular request in that test, then a future test (which does something entirely different) will fail instead. The fact that the test passes when not using keep-alive suggests to me that there is some kind of timing issue somewhere else.

[imyller]

@mscdex would you reconsider stream label if:

at clearBuffer (_stream_writable.js:394:5)

is the one actually making the failing doWrite call:

  doWrite(stream, state, true, state.length, buffer, '', holder.finish);

and by looks of it the holder.finish is the callback object resolving to non-function and causing TypeError.

holder.finish should be internally defined callback function in _stream_writable. Which means that net.Socket.write() callback (or non-callback) might not even be involved.

[cdhowie]

If there's any way I can grab extra information about the error, I will be happy to do so. I'm not experienced debugging Node internals, so I might need guidance.

I added a delay before the call that consistently fails, and this doesn't seem to prevent it from failing, which I guess means that it's not a timing issue as much as an order-of-operations issue.

[bnoordhuis]

Try https://www.npmjs.com/package/longjohn, it will give you long stack traces.

[imyller]

NODE_DEBUG=http,net could also be helpful if you are able to reproduce the error as it happens.

[imyller]

Also, I noticed that aws-sdk-js automatically selects between http and https protocol client depending on internal AWS service endpoint. As far as I can see, it still uses same httpOptions to provide options for both.

I noted that you've manually provided custom agent object for the client with http.Agent.

Just to be sure, I'd avoid using http.Agent for connections where https.Agent might be more appropriate; or let each client default to it's own globalAgent. Problem maybe amplified even more, if requests by AWS lib do mixed use of http and https connections using the shared agent object.

This could be nothing, but maybe worth a check?

[cdhowie]

@imyller I'm using dynalite to mock DynamoDB for the service-level tests, and I've already verified with tcpdump that no HTTPS connections are even being attempted, so I don't think HTTP/HTTPS confusion in the AWS SDK is the issue.

I've run a test using longjohn and the given NODE_DEBUG environment variable. The output is immense; should I pastebin the whole thing or post it here, and should I try to pare it down a bit to (what I think are) just the relevant bits?

[imyller]

I don't think HTTP/HTTPS confusion in the AWS SDK is the issue.

Excellent that you've verified that. In theory, that had potential to cause unexpected behaviour.

should I pastebin the whole thing or post it here

Pastebin or GitHub Gist are both ok for me. Sometimes the things that first seem irrelevant are indeed the most valuable. We can pick the relevant shorter snippets from there to this discussion if needed.

[cdhowie]

Here's the exception trace. I'll get the NODE_DEBUG output later today.

https://gist.github.com/cdhowie/515b97824b49660a60f9d535077070f0

[cdhowie]

I updated the gist with the debug info. (Sorry for the delay, been busy with this project!)

This test is the one that fails. I assume that whatever went wrong did so right before this line. This prior test succeeds, so I guess we're looking somewhere between these two lines to start with?

The test that fails makes several successful HTTP requests before making the one that consistently fails with this "object is not a function" error.

[chimurai]

Hi @imyller @bnoordhuis ,

@EladBezalel reported an issue really similar to this one.

He created a isolated example: https://github.com/chimurai/http-proxy-middleware/issues/39#issuecomment-260965382

Hope this will be helpful in pinpointing the problem.

[bnoordhuis]

@chimurai You wouldn't happen to have a test case that only uses built-in modules?

[bac42x]

Any developments with this issue?

I'm using webpack-dev-server with a proxy to a WEBAPI that uses NTLM. I used the suggestion from @chimurai in http-proy-middleware #39, but I also get this error: "TypeError: cb is not a function"

[EladBezalel]

@bac42x until i can find a solution for that i dropped the use of webpack-dev-server and i work directly to my selfhost with no hot reload :\

[Trott]

Has anyone managed to replicate this using just Node.js and not external modules? If so, a gist or something would be useful.

[EladBezalel]

@Trott do you mean without any http modules? I also tried without http-proxy-middleware and did my own express server to proxy the requests, still not working

[Trott]

@Trott do you mean without any http modules?

I mean using only Node.js and internal modules. So no http-proxy-middleware, no express...

[cdhowie]

The test that usually failed due to this issue is not failing as of v6.11.2. I'm still hesitant to turn this on in production due to the unpredictable nature of the issue.

@EladBezalel What Node version are you using?

[EladBezalel]

@cdhowie that was long time ago, so i assume some version of node 6

[cdhowie]

Do you still experience this issue? I've tried numerous things and for the life of me I can't get it to happen as of v6.11.2.

[EladBezalel]

Well i'll have to check that out again, i'll let you know next week!

[apapirovski]

Seems like it's been a while and latest responses indicate it's no longer breaking. I'll close this out as there doesn't seem to be anything actionable here but if anyone has new info or believes this is still an issue that needs fixing, please feel free to reopen.

[villelahdenvuo]

I had this problem with the elasticsearch module. After updating to Node v10.7.0 I get a different error, but sounds similar:

Error [ERR_MULTIPLE_CALLBACK]: Callback called multiple times
    at onwrite (_stream_writable.js:451:11)
    at afterWriteDispatched (internal/stream_base_commons.js:78:5)
    at writeGeneric (internal/stream_base_commons.js:70:3)
    at Socket._writeGeneric (net.js:761:5)
    at Socket._write (net.js:773:8)
    at doWrite (_stream_writable.js:410:12)
    at clearBuffer (_stream_writable.js:540:7)
    at Socket.Writable.uncork (_stream_writable.js:314:7)
    at ClientRequest._flushOutput (_http_outgoing.js:804:10)
    at ClientRequest._flush (_http_outgoing.js:779:16)
    at ClientRequest._deferToConnect (_http_client.js:258:47)
    at callSocketMethod (_http_client.js:701:7)
    at ClientRequest.onSocket (_http_client.js:706:7)
    at ClientRequest.emit (events.js:187:15)
---------------------------------------------
    at ClientRequest.once (events.js:290:8)
    at ClientRequest._deferToConnect (_http_client.js:713:10)
    at new ClientRequest (_http_client.js:258:8)
    at Object.request (http.js:41:10)
    at HttpConnector.request (/Users/ville.lahdenvuo/Projects/ecommerce/node_modules/elasticsearch/src/lib/connectors/http.js:169:23)
    at sendReqWithConnection (/Users/ville.lahdenvuo/Projects/ecommerce/node_modules/elasticsearch/src/lib/transport.js:223:35)
    at Object.utils.applyArgs (/Users/ville.lahdenvuo/Projects/ecommerce/node_modules/elasticsearch/src/lib/utils.js:187:19)
    at wrapper (/Users/ville.lahdenvuo/Projects/ecommerce/node_modules/lodash/lodash.js:5213:19)
    at process._tickCallback (internal/process/next_tick.js:61:11)
---------------------------------------------
    at Object.utils.nextTick (/Users/ville.lahdenvuo/Projects/ecommerce/node_modules/elasticsearch/src/lib/utils.js:207:11)
    at ConnectionPool.select (/Users/ville.lahdenvuo/Projects/ecommerce/node_modules/elasticsearch/src/lib/connection_pool.js:90:15)
    at Transport.request (/Users/ville.lahdenvuo/Projects/ecommerce/node_modules/elasticsearch/src/lib/transport.js:363:25)
    at exec (/Users/ville.lahdenvuo/Projects/ecommerce/node_modules/elasticsearch/src/lib/client_action.js:362:20)
    at exports.ApiNamespace.action (/Users/ville.lahdenvuo/Projects/ecommerce/node_modules/elasticsearch/src/lib/client_action.js:62:16)
    at /Users/ville.lahdenvuo/Projects/ecommerce/src/elasticsearch.js:119:25
    at Generator.next (<anonymous>)
    at step (/Users/ville.lahdenvuo/Projects/ecommerce/src/elasticsearch.js:187:191)
    at /Users/ville.lahdenvuo/Projects/ecommerce/src/elasticsearch.js:187:437
    at new Promise (<anonymous>)
    at /Users/ville.lahdenvuo/Projects/ecommerce/src/elasticsearch.js:187:99
    at productsIndexExists (/Users/ville.lahdenvuo/Projects/ecommerce/src/elasticsearch.js:123:16)
    at /Users/ville.lahdenvuo/Projects/ecommerce/src/pim/prototypes/importer.js:196:69
    at Generator.next (<anonymous>)
    at step (/Users/ville.lahdenvuo/Projects/ecommerce/src/pim/prototypes/importer.js:22:191)