Upgrade openssl sources to 1.0.2h broke npm install for me (behind proxy)

[julbra]

• Version: v6.3.0
• Platform: Linux 4.5.3-gentoo x86_64
• Subsystem: npm v3.10.3

With any version of node that contains the upgrade to openssl sources 1.0.2h, npm install fails with the following error:
Error: tunneling socket could not be established, cause=Parse Error

It only affects https traffic. My proxy settings are correct and have worked for years.

If I downgrade to any version prior this patch it works again. For example v5.10.0 works, v6.1.0+ and v5.11.0+ don't work.

Let me know if further information might help debug this issue. It may be something unusual on my system but any help would be greatly appreciated.

[bnoordhuis]

That almost certainly means it's because of #6279, which is a fix for the issue described in #6198.

It sounds like your proxy replies to CONNECT requests in a way that is either illegal or confuses tunnel-agent, the module that request uses (which npm uses) to tunnel through proxies.

[julbra]

Yep that sounds spot on. Can you suggest a better title for this issue?

[bnoordhuis]

@julbra Can you post the output of strace -o trace.log -s 2048 -fe read,write npm install? You may want to check that the log file doesn't contain anything sensitive.

[julbra]

@bnoordhuis
Here is the strace.log

[bnoordhuis]

Maybe there is some missing context but the reply from the proxy server is a bit strange:

54251 read(12, "HTTP/1.1 200 Connection established\r\n\r\n", 65536) = 39 
54251 read(12, "0-15\n", 8192)          = 5
54251 read(12, "0-15\n", 8192)          = 5
54251 read(12, "0-15\n", 8192)          = 5

Can you retry with -fe \!mmap,munmap,mprotect,clock_gettime,gettimeofday,nanosleep,futex?

[julbra]

Yep here goes:
https://gist.github.com/julbra/764f7b28d49568a1c8d791d512a5f5a5

[bnoordhuis]

Thanks. What I see is this:

29342 write(12, "CONNECT registry.npmjs.org:443 HTTP/1.1\r\naccept-encoding:
...
29342 read(13, "HTTP/1.1 200 Connection established\r\n\r\n", 65536) = 39          
29342 epoll_ctl(5, EPOLL_CTL_DEL, 13, 0x7ffe97d61ab0) = 0                          
29342 close(13) 

The 200 response is received and then something in the node process closes the connection, without seemingly reading any data.

What does env NODE_DEBUG="http net tunnel" npm install print?

[julbra]

@bnoordhuis here it is.

TUNNEL: making CONNECT requestzeTree: sill install loadCurrentTree
HTTP 35742: call onSocket 0 0
HTTP 35742: createConnection proxy.sdc.xx.com:8080: { agent: false,
  path: null,
  method: 'CONNECT',
  headers: 
   { 'accept-encoding': 'gzip',
     accept: 'application/json',
     referer: 'install moment',
     'user-agent': 'npm/3.10.3 node/v6.3.0 linux x64',
     host: 'registry.npmjs.org:443' },
  proxyAuth: null,
  port: 8080,
  host: 'proxy.sdc.xx.com',
  servername: 'registry.npmjs.org',
  _agentKey: 'proxy.sdc.xx.com:8080:' }
NET 35742: createConnection [ { agent: false,
    path: null,
    method: 'CONNECT',
    headers: 
     { 'accept-encoding': 'gzip',
       accept: 'application/json',
       referer: 'install moment',
       'user-agent': 'npm/3.10.3 node/v6.3.0 linux x64',
       host: 'registry.npmjs.org:443' },
    proxyAuth: null,
    port: 8080,
    host: 'proxy.sdc.xx.com',
    servername: 'registry.npmjs.org',
    _agentKey: 'proxy.sdc.xx.com:8080:',
    encoding: null },
  [Function: oncreate] ]
NET 35742: pipe false null
NET 35742: connect: find host proxy.sdc.xx.com
NET 35742: connect: dns options { family: undefined, hints: 32 }
HTTP 35742: sockets proxy.sdc.xx.com:8080: 1
HTTP 35742: outgoing message end.
HTTP 35742: outgoing message end.
NET 35742: _read
NET 35742: _read wait for connection
NET 35742: afterConnectnormalizeTree: sill install loadCurrentTree
NET 35742: _read
NET 35742: Socket._read readStart
NET 35742: onread 39
NET 35742: got data
HTTP 35742: AGENT incoming response!
HTTP 35742: parse error
NET 35742: destroy undefined
NET 35742: destroy
NET 35742: close
NET 35742: close handle
TUNNEL: tunneling socket could not be established, cause=Parse Error
 Error: Parse Error
    at Error (native)
    at Socket.socketOnData (_http_client.js:361:20)
    at emitOne (events.js:96:13)
    at Socket.emit (events.js:188:7)
    at readableAddChunk (_stream_readable.js:177:18)
    at Socket.Readable.push (_stream_readable.js:135:10)
    at TCP.onread (net.js:542:20)
NET 35742: _read
NET 35742: _read wait for connection
NET 35742: emit close
HTTP 35742: CLIENT socket onClose
HTTP 35742: removeSocket proxy.sdc.xx.com:8080: writable: false
HTTP 35742: HTTP socket close

[bnoordhuis]

Thanks. Okay, I think the conclusion has to be that node doesn't like the response from the proxy (the exception bubbles up from core) but I don't understand why, because I can't reproduce locally. A test script:

'use strict';
const http = require('http');
const net = require('net');

const server = net.createServer(onconnection).listen(8000, onlisten);

function onconnection(conn) {
  conn.pipe(process.stderr);
  conn.write('HTTP/1.1 200 Connection established\r\n\r\n');
  setTimeout(() => conn.end('ok\n'), 50);
}

function onlisten() {
  const req = http.request({
    method: 'CONNECT',
    host: '127.0.0.1',
    path: 'example.org:443',
    port: 8000,
    headers: {'Connection': 'close'},
  });
  req.on('connect', function(res, conn, head) {
    conn.pipe(process.stdout);
    server.close();
  });
  req.end();
}

[bnoordhuis]

I forgot to mention that it is possible that tunnel-agent or request intercepts the raw TCP data and does something with it that makes the http parser reject it. That is something I can't easily check though, too many lines of code to go through.

[julbra]

@bnoordhuis Ok thanks for your time. I wish I could give you access to the machine, but obviously it is behind the proxy!
Here is the same log but from node v5.10.1 where it all works.
https://gist.github.com/julbra/0c80b23d7d288fc3ddb2816630de683b

[julbra]

v6.9.0 still shows exactly the same problem 😢
Looks like I will be stuck on v5.10.1 forever.

EDIT: @bnoordhuis whoops this only affects when I build from source (the default on Gentoo).
If I use the official build it works as expected. It must be something funny in the way Gentoo builds the source, V8 or which libraries it links.