search

nodejs / node

Node.js JavaScript runtime ✨🐢🚀✨
https://nodejs.org
Other
106.53k stars 29.03k forks source link

HTTP/HTTPS client requests throwing EPROTO #3692

Closed brandonros closed 6 years ago

brandonros commented 8 years ago 
Error: write EPROTO
    at Object.exports._errnoException (util.js:874:11)
    at exports._exceptionWithHostPort (util.js:897:20)
    at WriteWrap.afterWrite (net.js:763:14)

My code is littered with both HTTP and HTTPS requests. I have no idea what is causing this error but it is occurring in many places since I've upgraded to 4.2.1 from 0.12.7. Please tell me what information I need to provide to help debug this.

Fishrock123 commented 8 years ago

@brandonros I'm suspecting it has to do with the first-class IPv6 support Node v4 has. cc @mscdex maybe.

Edit: added IPv6

mscdex commented 8 years ago

What OS and OS version is this on?

brandonros commented 8 years ago

@mscdex 

Linux Nigel 3.13.0-43-generic #72-Ubuntu SMP Mon Dec 8 19:35:44 UTC 2014 i686 i686 i686 GNU/Linux
No LSB modules are available.
Distributor ID: Ubuntu
Description:    Ubuntu 14.04.3 LTS
Release:    14.04
Codename:   trusty
brandonros commented 8 years ago

@Fishrock123 @mscdex Any other information I can provide? Would love to get this fixed quickly. I'm sure it has to be something on my end, otherwise a huge portion of people would be experiencing it.

The code used to work without issue, but it started happening a) when I changed machines and b) when I switched versions.

I installed with nvm if that matters.

mscdex commented 8 years ago

Is it happening with the same server(s)? If so, are these public servers? Otherwise, if you can, it might be helpful to see what types of addresses the servers are resolving to (e.g. IPv4, IPv6) and what types of addresses are assigned to the outgoing network interface the requests are going out.

brandonros commented 8 years ago

@mscdex It is happening on the same offending server. It seems to happen on both requests made to localhost, and external APIs. All IPv4.

trotyl commented 8 years ago

Also encountered on OS X (My computer) and Ubuntu (Travis-CI) and Windows Server (AppVeyor) when using npm package 'request', the error trace is exactly same as described by @brandonros

evanlucas commented 8 years ago

It sounds like you are trying to use port 80 for https?

Reproduced via:

require('https').get('https://google.com:80', function(res) { console.log(res.statusCode) }).on('error', console.log)
brandonros commented 8 years ago

The reason that isn't the problem in my case is because it only happens semi-frequently on otherwise valid endpoints.

On Sunday, November 8, 2015, Evan Lucas notifications@github.com wrote:

It sounds like you are trying to use port 80 for https?

Reproduced via:

require('https').get('https://google.com:80', function(res) { console.log(res.statusCode) }).on('error', console.log)

— Reply to this email directly or view it on GitHub https://github.com/nodejs/node/issues/3692#issuecomment-154899692.

evanlucas commented 8 years ago

It will be difficult for us to help debug the issue without being able to see some of the code. Is there any that you could share?

brandonros commented 8 years ago

I went to dumb down some code I have, and it really just boils down to any HTTP or HTTPS request. Nothing else.

@trotyl Do you think it has anything to do with DNS or nginx rewrites? I'm really stretching here. I can't come up with anything else.

trotyl commented 8 years ago

It appears on some certain urls and randomly, I cannot even cause it to appear manually, and I have used a 'retry(100)' of RxJS to get rid of this problem. But it seems not a good solution.

Some url(s) on my crawler of my university site may cause the problem at some low possibility, I do have no idea where it came from as error trace directly begin from 'net.js', But what I can guess seems to be DNS or HTTPS or something relevant.

The url I have problem with seems to be 'https://uis.uestc.edu.cn/amserver/UI/Login' with method 'POST' with form 'IDToken0&IDToken=2012019050020&IDToken2=811073&IDButton=Submit&goto=aHR0cDovL3BvcnRhbC51ZXN0Yy5lZHUuY24vbG9naW4ucG9ydGFs&encoded=true&gx_charset=UTF-8', (the id and password is not mine but valid)

brandonros commented 8 years ago

Upgrading to 5.0, changing machines, and switching to 64-bit seems to have fixed the problem. I don't want to jinx anything, but I have not seen the error in 3 days.

brandonros commented 8 years ago

The error is still happening. I am installing longjohn on all of my servers to get more information.

@trotyl Any update?

brandonros commented 8 years ago

How is this for a stack trace?

Error: write EPROTO
    at Object.exports._errnoException (util.js:860:11)
    at exports._exceptionWithHostPort (util.js:883:20)
    at WriteWrap.afterWrite (net.js:763:14)
---------------------------------------------
    at TLSSocket.Readable.on (_stream_readable.js:665:33)
    at tickOnSocket (_http_client.js:486:10)
    at onSocketNT (_http_client.js:502:5)
    at doNTCallback2 (node.js:450:9)
    at process._tickDomainCallback (node.js:405:17)
---------------------------------------------
    at ClientRequest.onSocket (_http_client.js:494:11)
    at Agent.addRequest (_http_agent.js:143:9)
    at new ClientRequest (_http_client.js:139:16)
    at Object.exports.request (http.js:31:10)
    at Object.exports.request (https.js:173:15)
    at Object.ebay.request (/home/brandon/foo/integrations/ebay.js:34:18)
    at Object.ebay.get_orders_api_call (/home/brandon/foo/integrations/ebay.js:122:7)
    at Object.ebay.get_orders (/home/brandon/foo/integrations/ebay.js:138:7)
    at handle_job (/home/brandon/foo/sync_server/app.js:124:29)
    at /home/brandon/foo/sync_server/app.js:214:12
    at process._tickDomainCallback (node.js:420:9)
    at /home/brandon/foo/api_server/lib/sync_server.js:77:11
    at _fulfilled (/home/brandon/foo/api_server/node_modules/q/q.js:834:54)
    at self.promiseDispatch.done (/home/brandon/foo/api_server/node_modules/q/q.js:863:30)
    at Promise.promise.promiseDispatch (/home/brandon/foo/api_server/node_modules/q/q.js:796:13)
    at /home/brandon/foo/api_server/node_modules/q/q.js:604:44
    at runSingle (/home/brandon/foo/api_server/node_modules/q/q.js:137:13)
    at flush (/home/brandon/foo/api_server/node_modules/q/q.js:125:13)
    at doNTCallback0 (node.js:428:9)
    at process._tickDomainCallback (node.js:398:13)
---------------------------------------------
    at requestTick (/home/brandon/foo/api_server/node_modules/q/q.js:197:21)
    at Function.nextTick (/home/brandon/foo/api_server/node_modules/q/q.js:180:13)
    at /home/brandon/foo/api_server/node_modules/q/q.js:603:15
    at Array.reduce (native)
    at /home/brandon/foo/api_server/node_modules/q/q.js:263:21
    at become (/home/brandon/foo/api_server/node_modules/q/q.js:602:9)
    at deferred.resolve (/home/brandon/foo/api_server/node_modules/q/q.js:618:9)
    at IncomingMessage.<anonymous> (/home/brandon/foo/api_server/lib/sync_server.js:17:13)
    at emitNone (events.js:72:20)
    at IncomingMessage.emit (events.js:166:7)
    at endReadableNT (_stream_readable.js:905:12)
    at doNTCallback2 (node.js:450:9)
    at process._tickDomainCallback (node.js:405:17)
---------------------------------------------
    at IncomingMessage.Readable.on (_stream_readable.js:665:33)
    at Object.sync_server.read_body (/home/brandon/foo/api_server/lib/sync_server.js:15:11)
    at ClientRequest.<anonymous> (/home/brandon/foo/api_server/lib/sync_server.js:45:22)
    at emitOne (events.js:77:13)
    at ClientRequest.emit (events.js:169:7)
    at HTTPParser.parserOnIncomingClient (_http_client.js:421:21)
    at HTTPParser.parserOnHeadersComplete (_http_common.js:88:23)
    at Socket.socketOnData (_http_client.js:311:20)
    at emitOne (events.js:77:13)
    at Socket.emit (events.js:169:7)
    at readableAddChunk (_stream_readable.js:146:16)
    at Socket.Readable.push (_stream_readable.js:110:10)
    at TCP.onread (net.js:523:20)
---------------------------------------------
    at Object.sync_server.request (/home/brandon/foo/api_server/lib/sync_server.js:44:6)
    at /home/brandon/foo/api_server/lib/sync_server.js:73:23
    at _fulfilled (/home/brandon/foo/api_server/node_modules/q/q.js:834:54)
    at self.promiseDispatch.done (/home/brandon/foo/api_server/node_modules/q/q.js:863:30)
    at Promise.promise.promiseDispatch (/home/brandon/foo/api_server/node_modules/q/q.js:796:13)
    at /home/brandon/foo/api_server/node_modules/q/q.js:604:44
    at runSingle (/home/brandon/foo/api_server/node_modules/q/q.js:137:13)
    at flush (/home/brandon/foo/api_server/node_modules/q/q.js:125:13)
    at doNTCallback0 (node.js:428:9)
    at process._tickDomainCallback (node.js:398:13)
---------------------------------------------
    at requestTick (/home/brandon/foo/api_server/node_modules/q/q.js:197:21)
    at Function.nextTick (/home/brandon/foo/api_server/node_modules/q/q.js:180:13)
    at /home/brandon/foo/api_server/node_modules/q/q.js:603:15
    at Array.reduce (native)
    at /home/brandon/foo/api_server/node_modules/q/q.js:263:21
    at become (/home/brandon/foo/api_server/node_modules/q/q.js:602:9)
    at deferred.resolve (/home/brandon/foo/api_server/node_modules/q/q.js:618:9)
    at [object Object].<anonymous> (/home/brandon/foo/api_server/node_modules/q/q.js:1859:22)
    at Timer.listOnTimeout (timers.js:92:15)
---------------------------------------------
    at /home/brandon/foo/api_server/node_modules/q/q.js:1858:9
    at _fulfilled (/home/brandon/foo/api_server/node_modules/q/q.js:834:54)
    at self.promiseDispatch.done (/home/brandon/foo/api_server/node_modules/q/q.js:863:30)
    at Promise.promise.promiseDispatch (/home/brandon/foo/api_server/node_modules/q/q.js:796:13)
    at /home/brandon/foo/api_server/node_modules/q/q.js:857:14
    at runSingle (/home/brandon/foo/api_server/node_modules/q/q.js:137:13)
    at flush (/home/brandon/foo/api_server/node_modules/q/q.js:125:13)
    at doNTCallback0 (node.js:428:9)
    at process._tickDomainCallback (node.js:398:13)
---------------------------------------------
    at requestTick (/home/brandon/foo/api_server/node_modules/q/q.js:197:21)
    at Function.nextTick (/home/brandon/foo/api_server/node_modules/q/q.js:180:13)
    at /home/brandon/foo/api_server/node_modules/q/q.js:603:15
    at Array.reduce (native)
    at /home/brandon/foo/api_server/node_modules/q/q.js:263:21
    at become (/home/brandon/foo/api_server/node_modules/q/q.js:602:9)
    at deferred.resolve (/home/brandon/foo/api_server/node_modules/q/q.js:618:9)
    at IncomingMessage.<anonymous> (/home/brandon/foo/api_server/lib/sync_server.js:17:13)
    at emitNone (events.js:72:20)
    at IncomingMessage.emit (events.js:166:7)
    at endReadableNT (_stream_readable.js:905:12)
    at doNTCallback2 (node.js:450:9)
    at process._tickDomainCallback (node.js:405:17)
---------------------------------------------
    at IncomingMessage.Readable.on (_stream_readable.js:665:33)
    at Object.sync_server.read_body (/home/brandon/foo/api_server/lib/sync_server.js:15:11)
    at ClientRequest.<anonymous> (/home/brandon/foo/api_server/lib/sync_server.js:45:22)
    at emitOne (events.js:77:13)
    at ClientRequest.emit (events.js:169:7)
    at HTTPParser.parserOnIncomingClient (_http_client.js:421:21)
    at HTTPParser.parserOnHeadersComplete (_http_common.js:88:23)
    at Socket.socketOnData (_http_client.js:311:20)
    at emitOne (events.js:77:13)
    at Socket.emit (events.js:169:7)
    at readableAddChunk (_stream_readable.js:146:16)
    at Socket.Readable.push (_stream_readable.js:110:10)
    at TCP.onread (net.js:523:20)
---------------------------------------------
    at Object.sync_server.request (/home/brandon/foo/api_server/lib/sync_server.js:44:6)
    at Object.sync_server.request_refresh (/home/brandon/foo/api_server/lib/sync_server.js:99:21)
    at /home/brandon/foo/api_server/controllers/sync.js:131:22
    at _fulfilled (/home/brandon/foo/api_server/node_modules/q/q.js:834:54)
    at self.promiseDispatch.done (/home/brandon/foo/api_server/node_modules/q/q.js:863:30)
    at Promise.promise.promiseDispatch (/home/brandon/foo/api_server/node_modules/q/q.js:796:13)
    at /home/brandon/foo/api_server/node_modules/q/q.js:604:44
    at runSingle (/home/brandon/foo/api_server/node_modules/q/q.js:137:13)
    at flush (/home/brandon/foo/api_server/node_modules/q/q.js:125:13)
    at doNTCallback0 (node.js:428:9)
    at process._tickDomainCallback (node.js:398:13)
---------------------------------------------
    at requestTick (/home/brandon/foo/api_server/node_modules/q/q.js:197:21)
    at Function.nextTick (/home/brandon/foo/api_server/node_modules/q/q.js:180:13)
    at /home/brandon/foo/api_server/node_modules/q/q.js:603:15
    at Array.reduce (native)
    at /home/brandon/foo/api_server/node_modules/q/q.js:263:21
    at become (/home/brandon/foo/api_server/node_modules/q/q.js:602:9)
    at deferred.resolve (/home/brandon/foo/api_server/node_modules/q/q.js:618:9)
    at _fulfilled (/home/brandon/foo/lib/node_modules/q/q.js:834:54)
    at self.promiseDispatch.done (/home/brandon/foo/lib/node_modules/q/q.js:863:30)
    at Promise.promise.promiseDispatch (/home/brandon/foo/lib/node_modules/q/q.js:796:13)
    at /home/brandon/foo/lib/node_modules/q/q.js:604:44
    at runSingle (/home/brandon/foo/lib/node_modules/q/q.js:137:13)
    at flush (/home/brandon/foo/lib/node_modules/q/q.js:125:13)
    at doNTCallback0 (node.js:428:9)
    at process._tickDomainCallback (node.js:398:13)

I had

var headers = {
    ...
    'Content-Type': 'text/xml',
    'Content-Length': Buffer(body).byteLength
};

But I think this was the culpritL

var headers = {
    ...
    'Content-Type': 'text/xml',
    'Content-Length': body.length
};
BennyH26 commented 8 years ago

I'm also receiving this error intermittently on random servers and URLs (though all are being accessed via HTTPS). @brandonros - Based on other threads, I'm investigating the possibility of this being caused by drop of RC4 support in Node >= v4.0. Any update on your end?

brandonros commented 8 years ago

@BennyH26 Say this is the case. What can be done to fix this?

Edit: Maybe the reason this is happening intermittently is because we are getting load balanced to different servers?

I'm going to test if these options will fix the problem. I'm not sure if they are correct.

var options = {
    ...
    ciphers: 'ALL',
    secureProtocol: 'TLSv1_method'
};
jasnell commented 8 years ago

/cc @nodejs/http

BennyH26 commented 8 years ago

@brandonros I've added the code to my agent options, and will keep you posted if I still receive errors. Intermittent errors are so challenging to solve sometimes... As you suggested, I suspect we are hitting load balanced servers, and their reverse proxy configurations are SLIGHTLY different, thereby negotiating different ciphers. Just a guess though.

brandonros commented 8 years ago

@BennyH26 What servers/URLs are you hitting? I ran eBay's API endpoint through https://www.ssllabs.com/ssltest/, if that helps.

BennyH26 commented 8 years ago

@brandonros https://api.ebay.com/ws/api.dll Looks like two of the three servers got C grades =]

indutny commented 8 years ago

@trotyl are you sure about OS X? This seems pretty strange to me, because I don't see a place in kernel that could set errno = EPROTO for TCP syscalls.

indutny commented 8 years ago

Gosh, nevermind. It is returned by src/tls_wrap.cc, not kernel. My bad!

indutny commented 8 years ago

This is very likely happened, because there were pending writes on TLS socket and it was destroyed before they were encrypted and sent to the other side.

indutny commented 8 years ago

I think this kind of error can only happen if ssl_ == nullptr in TLSWrap::DoWrite.

indutny commented 8 years ago

@brandonros may I ask you to give a try to following patch?

diff --git a/lib/_tls_wrap.js b/lib/_tls_wrap.js
index ef5769c..d517d1b 100644
--- a/lib/_tls_wrap.js
+++ b/lib/_tls_wrap.js
@@ -47,7 +47,11 @@ function onhandshakestart() {
 function onhandshakedone() {
   // for future use
   debug('onhandshakedone');
-  this._finishInit();
+
+  const self = this;
+  setImmediate(function() {
+    self._finishInit();
+  });
 }

@@ -556,6 +560,10 @@ TLSSocket.prototype._releaseControl = function() {
 };

 TLSSocket.prototype._finishInit = function() {
+  // Destroyed before getting there
+  if (this._handle == null)
+    return;
+
   // `newSession` callback wasn't called yet
   if (this._newSessionPending) {
     this._securePending = true;
indutny commented 8 years ago

Basically, what I think happens here is that ssl_ is destroyed in the middle of DoWrite. Otherwise I can't see how it could happen. I'm trying to make sure that no unsafe JS callbacks will be executed from within DoWrite.

indutny commented 8 years ago

(It doesn't seem like it could be any other UV_EPROTO case from tls_wrap.cc, because the error would include some OpenSSL strings as well in that case)

brandonros commented 8 years ago

@indutny Do you think the options I pass as per https://github.com/nodejs/node/issues/3692#issuecomment-158414743 will interfere or solve the issue?

I will try the patch but the error very rarely happens. I guess I could write a test to try to exacerbate the behavior.

indutny commented 8 years ago

@brandonros this sounds unlikely.

brandonros commented 8 years ago

@indutny what drastic breaking changes occurred here from 0.12.7 to 4.0.0 and so on? Default ciphers supported? Some overhauling?

This issue did not exist in 0.12.7

indutny commented 8 years ago

@brandonros there were tons of changes in TLS implementation.

SanchesS commented 8 years ago

+1 We also faced this issue (Error: write EPROTO after https requests) on production servers after migrating to node.js v5.0.0 from 1.8.4 This error seems to happen occasionally (maybe 1 time in 20) and we can't find the reason.

aclelland commented 8 years ago

We're also seeing this issue when trying to connect to https://api2.dynect.net/ with Node 4.2.x.

The example below uses request but the same issue happens with the https client. About 50% of the time this will return a EPROTO error. 

var request = require("request")
request('https://api2.dynect.net/', function(error, res, body)
{
       console.log(error, body)
});
SanchesS commented 8 years ago

Just for information - we fixed this issue. But we fixed it by changing nginx cyphers config at our API backend. We used this recommendations by mozilla (orange level was enough for us): https://wiki.mozilla.org/Security/Server_Side_TLS So now we have production environment on Node.js 5.0.0. working without any errors.

indutny commented 8 years ago

@aclelland Unfortunately I'm unable to reproduce this problem locally with your script. May I ask you to give a try to the patch that I have posted earlier in this thread: https://github.com/nodejs/node/issues/3692#issuecomment-158583358 ?

indutny commented 8 years ago

@SanchesS @aclelland btw, could you please paste the stack trace of the EPROTO error?

SanchesS commented 8 years ago

@indutny sorry, but we don't have full stack trace - currently bug is fixed and we cannot reproduce it on test servers. This is all that we got:

 code: 'EPROTO',
 errno: 'EPROTO',
 syscall: 'write',
 address: undefined }
Error: write EPROTO
sgilligan commented 8 years ago

I am getting this intermittent error as well (node 5.0.0). The stack trace I get is:

Error: write EPROTO
        at Object.exports._errnoException (util.js:860:11)
        at exports._exceptionWithHostPort (util.js:883:20)
        at WriteWrap.afterWrite (net.js:763:14)
bnoordhuis commented 8 years ago

That error suggests the TLS handshake failed and the remote end closed the connection with prejudice. Nine times out of ten it means the server and the client couldn't agree on a cipher to use. Poke around with openssl s_client and see what works and what doesn't.

Smbc1 commented 8 years ago

Same problem on node 5.0.0, callstack looks the same to @brandonros post. Happens pretty randomly, but when it does, there are few errors in row (can return errors for all requests for a minute once in a day). Did anyone catching the error on node 5.3.0? UPD: We are using EC2 and this error occurs only on the same instances. For example: on two cluster with three instances each, only one instance in each cluster produces the bug.

indutny commented 8 years ago

May I ask you to give a try to https://github.com/nodejs/node/pull/4515 to see if it helps?

sgilligan commented 8 years ago

I've moved to 5.2.0 and all my problems have dissapeared.

indutny commented 8 years ago

Interesting... Looks like it can be a manifestation of https://github.com/nodejs/node/commit/939f305d567c927c7e6ab551529984cec3b68479 . Everyone here, please give a try to v5.2.0 and confirm it if you'll have time for this.

Thank you!

rodrigogs commented 8 years ago

Having the same issue here when I try to use a proxy. I tested in version 4.2.4, 4.2.1, 5.2.0 and 5.4.0.

const request = require('request');

let r = request.defaults({'proxy': 'https://81.94.162.140:8080/'});

r.get('http://www.example.com/', (error, response) => {
    if (error) {
        return console.log(error.stack);
    }

    console.log(response.body);
});

Error: write EPROTO at Object.exports._errnoException (util.js:856:11) at exports._exceptionWithHostPort (util.js:879:20) at WriteWrap.afterWrite (net.js:764:14)

chetbox commented 8 years ago

I'm running a server using on port 80 using HTTP and see the error occasionally on Node 4.2.1 when developing locally. I just got the same error on a staging server (also HTTP, port 80) running 5.0.0 which makes me think this doesn't have much to do with TLS. (Unless it's a similar symptom of a different problem.)

chetbox commented 8 years ago

Ah, sorry. Just had a look at the stack trace and it's to do with accessing dynamodb over HTTPS. So ignore my previous comment!

I have noticed it's happening more often now, which could just be because I'm hitting the database more frequently.

krummi commented 8 years ago

I've also been hitting this problem repeatedly for the past two weeks while writing to/reading from DynamoDB on Node v5.2.0. The stack trace is the same as some people here have mentioned: 

Error: write EPROTO
    at Object.exports._errnoException (util.js:856:11)
    at exports._exceptionWithHostPort (util.js:879:20)
    at WriteWrap.afterWrite (net.js:764:14)

If I can be of any help, please let me know.

aj07mm commented 8 years ago

I got this

{ [Error: write EPROTO 140735221207808:error:140770FC:SSL routines:SSL23_GET_SERVER_HELLO:unknown protocol:../deps/openssl/openssl/ssl/s23_clnt.c:795:
] code: 'EPROTO', errno: 'EPROTO', syscall: 'write' }

the problem was targeting the wrong port

pinalbhatt commented 8 years ago

I am also getting same error consistently for one API call. I am trying to call 4 different APIs - one is just http and three are https via request (https://www.npmjs.com/package/request) and its working fine for http and two https cases. But always failing for one case.