Unhandled 'error' event when connect followed by close

[vasco-santos]

OS: MacOS
Version: 7.4.2
Node Version: Both 14.15.4 and 15.5.1

In libp2p-websockets module we do a websocket.close() once an abort signal is done as you can see in https://github.com/libp2p/js-libp2p-websockets/blob/v0.15.0/src/index.js#L80. If this happens immediately after the instantiation of the Websocket client, the following error happens:

node:events:353
      throw er; // Unhandled 'error' event
      ^

Error: connect EHOSTUNREACH 2604:1380:45f1:3f00::1:4002 - Local (:::54287)
    at internalConnect (node:net:910:16)
    at defaultTriggerAsyncIdScope (node:internal/async_hooks:430:12)
    at node:net:1001:9
    at processTicksAndRejections (node:internal/process/task_queues:75:11)
Emitted 'error' event on Socket instance at:
    at emitErrorNT (node:internal/streams/destroy:188:8)
    at emitErrorCloseNT (node:internal/streams/destroy:153:3)
    at processTicksAndRejections (node:internal/process/task_queues:80:21) {
  errno: -65,
  code: 'EHOSTUNREACH',
  syscall: 'connect',
  address: '2604:1380:45f1:3f00::1',
  port: 4002
}

I did some debugging on this, as it seemed firstly related to Node itself. The code stack looks like this:

• https://github.com/libp2p/js-libp2p-websockets/blob/master/src/index.js#L80
• https://github.com/alanshaw/it-ws/blob/master/client.js#L18

• ws/lib/websocket.js

  Line 220 in a2c0d44

  close(code, data) {

• ws/lib/websocket.js

  Line 224 in a2c0d44

  return abortHandshake(this, this._req, msg);

• ws/lib/websocket.js

  Line 713 in a2c0d44

  function abortHandshake(websocket, stream, message) {

• ws/lib/websocket.js

  Line 720 in a2c0d44

  stream.abort();

Being this last place where this fails. If I remove line 720 the error does not happen. I was trying to debug further on this, but got blocked. According to JSDocs in 720 stream could be a net.Socket, but net.Socket does not seem to have an abort function. Furthermore, looking at Node's tests, they include a test for net-connect-immediate-destroy.js.

I also noticed that if the STATE was not CONNECTING, the destroy would be wrapped by a setTimeout. Would this be desirable for 720 as this would also fix the issue?

Let me know what you think about this issue and I can help fixing this if you like.

Related to:

• EADDRNOTAVAIL and crash libp2p/js-libp2p#844

[lpinca]

stream here https://github.com/websockets/ws/blob/7.4.2/lib/websocket.js#L720, is an instance of http.ClientRequest(). Did you add a listener for the 'error' event before calling websocket.close()?

[vasco-santos]

@lpinca thanks for the quick answer

is an instance of http.ClientRequest()

Ok, so it has the abort() in fact. So the underlying abort code is https://github.com/nodejs/node/blob/master/lib/_http_client.js#L359 . Probably the destroy should also be wrapped in the process.nextTick there, what do you think?

Did you add a listener for the 'error' event before calling websocket.close()?

Yes, I started by adding exactly that in libp2p/js-libp2p-websockets#118 to try it out, but it did not solve the issue. Finally, I wrapped the close around a setTimeout to move to the next event loop and it just worked.

[lpinca]

Can you write a test case using only ws? I can't reproduce the issue

const WebSocket = require('ws');

const ws = new WebSocket('ws://[2604:1380:45f1:3f00::1]:4002');

ws.on('error', console.error);
ws.close();

[vasco-santos]

@lpinca I think you are right. The problem seems to be to wrap the error handler inside a promise.

I will keep you posted, thanks

[vasco-santos]

Actually, it did not solve to extract out of the promise. I ran this in my local machine now and I got the same issue:

const WebSocket = require('ws');

async function main () {
  const ws = new WebSocket('ws://[2604:1380:45f1:3f00::1]:4002');

  ws.on('error', console.error);
  ws.close();
}

main()

Error: WebSocket was closed before the connection was established
    at WebSocket.close (/Users/vsantos/work/pl/gh/libp2p/testss/test-blogpost/node_modules/ws/lib/websocket.js:224:14)
    at main (/Users/vsantos/work/pl/gh/libp2p/testss/test-blogpost/test.js:7:6)
    at Object.<anonymous> (/Users/vsantos/work/pl/gh/libp2p/testss/test-blogpost/test.js:10:1)
    at Module._compile (internal/modules/cjs/loader.js:1063:30)
    at Object.Module._extensions..js (internal/modules/cjs/loader.js:1092:10)
    at Module.load (internal/modules/cjs/loader.js:928:32)
    at Function.Module._load (internal/modules/cjs/loader.js:769:14)
    at Function.executeUserEntryPoint [as runMain] (internal/modules/run_main.js:72:12)
    at internal/main/run_main_module.js:17:47
events.js:292
      throw er; // Unhandled 'error' event
      ^

Error: connect EHOSTUNREACH 2604:1380:45f1:3f00::1:4002 - Local (:::56935)
    at internalConnect (net.js:921:16)
    at defaultTriggerAsyncIdScope (internal/async_hooks.js:430:12)
    at net.js:1009:9
    at processTicksAndRejections (internal/process/task_queues.js:75:11)
Emitted 'error' event on Socket instance at:
    at emitErrorNT (internal/streams/destroy.js:106:8)
    at emitErrorCloseNT (internal/streams/destroy.js:74:3)
    at processTicksAndRejections (internal/process/task_queues.js:80:21) {
  errno: -65,
  code: 'EHOSTUNREACH',
  syscall: 'connect',
  address: '2604:1380:45f1:3f00::1',
  port: 4002
}

If I change this into:

const WebSocket = require('ws');

async function main () {
  const ws = new WebSocket('ws://[2604:1380:45f1:3f00::1]:4002');

  ws.on('error', console.error);
  setTimeout(() => {
    ws.close();
  }, 0)
}

main()

THe error is addressed as expected and logged with console.error

[lpinca]

Ok I can reproduce on macOS with Node.js 15.5.1. It seems a Node.js issue as this 'error' listener https://github.com/websockets/ws/blob/7.4.2/lib/websocket.js#L574-L581 is not called. I will check with Node.js 12 later.

Meanwhile here is a test case using only Node.js built-in modules:

const http = require('http');

const req = http.get('http://[2604:1380:45f1:3f00::1]:4002');

req.on('error', console.error);
req.abort();

[lpinca]

I've opened nodejs/node#36931. I don't have time to investigate at the moment.

[vasco-santos]

Thanks for your help @lpinca I will be following the issue.

[lpinca]

I'm closing this as the issue has been fixed on Node.js master. It will be included in the next Node.js 15.x release and backported to 14.x soon but it will certainly not be backported to EOL versions like 8. I think there is not much to do about that.