`MockHttpSocket.passthrough()` can cause rare EINVAL, ECANCELED errors

[jbinto]

We use dd-trace to instrument our test suite. Since upgrading to nock@14 (or nock@15.0.0-beta.6), which now uses @mswjs/interceptors@0.39.8, we've been having issues where the periodic dd-trace telemetry uploads are crashing the process with either EINVAL or ECANCELED. They are allowed to passthrough, but there is something about the implementation in MockHttpSocket such that in a large test suite this will always happen to multiple tests, but it's rare enough that reproducing it once at will is annoyingly difficult.

ECANCELED (failed write)

Error: write ECANCELED Canceled because of SSL destruction
    at WriteWrap.onWriteComplete [as oncomplete] (node:internal/stream_base_commons:95:16)
    at WriteWrap.callbackTrampoline (node:internal/async_hooks:130:17)
    at TCP.done (node:_tls_wrap:641:11)
    at TCP.callbackTrampoline (node:internal/async_hooks:130:17)
Emitted 'error' event on ClientRequest instance at:
    at ClientRequest.req.emit (/home/circleci/project/node_modules/dd-trace/packages/datadog-instrumentations/src/http/client.js:123:25)
    at emitErrorEvent (node:_http_client:101:11)
    at MockHttpSocket.socketErrorListener (node:_http_client:504:5)
    at MockHttpSocket.emit (node:events:536:35)
    at MockHttpSocket.emit (/home/circleci/project/node_modules/@mswjs/interceptors/src/interceptors/ClientRequest/MockHttpSocket.ts:160:12)
    at TLSSocket.<anonymous> (/home/circleci/project/node_modules/@mswjs/interceptors/src/interceptors/ClientRequest/MockHttpSocket.ts:293:14)
    at TLSSocket.emit (node:events:524:28)
    at TLSSocket.emit (/home/circleci/project/node_modules/dd-trace/packages/datadog-instrumentations/src/net.js:65:25)
    at emitErrorNT (node:internal/streams/destroy:169:8)
    at emitErrorCloseNT (node:internal/streams/destroy:128:3)
    at processTicksAndRejections (node:internal/process/task_queues:82:21) {
  errno: -125,
  code: 'ECANCELED',
  syscall: 'write'
}

EINVAL (failed read)

Error: read EINVAL
    at tryReadStart (node:net:716:20)
    at Socket._read (node:net:731:5)
    at MockHttpSocket.<anonymous> (node:net:729:37)
    at Object.onceWrapper (node:events:633:28)
    at MockHttpSocket.emit (node:events:531:35)
    at MockHttpSocket.emit (/home/circleci/interceptors/repro/node_modules/.pnpm/@mswjs+interceptors@0.39.8/node_modules/@mswjs/interceptors/lib/node/chunk-N4ZZFE24.js:454:12)
    at TLSSocket.<anonymous> (/home/circleci/interceptors/repro/node_modules/.pnpm/@mswjs+interceptors@0.39.8/node_modules/@mswjs/interceptors/lib/node/chunk-N4ZZFE24.js:531:12)
    at TLSSocket.emit (node:events:531:35)
    at /home/circleci/interceptors/repro/node_modules/.pnpm/dd-trace@5.80.0_@openfeature+core@1.9.1_@openfeature+server-sdk@1.18.0_@openfeature+core@1.9.1_/node_modules/dd-trace/packages/datadog-instrumentations/src/net.js:62:27
    at run (node:diagnostics_channel:168:14)
Emitted 'error' event on ClientRequest instance at:
    at req.emit (/home/circleci/interceptors/repro/node_modules/.pnpm/dd-trace@5.80.0_@openfeature+core@1.9.1_@openfeature+server-sdk@1.18.0_@openfeature+core@1.9.1_/node_modules/dd-trace/packages/datadog-instrumentations/src/http/client.js:123:25)
    at emitErrorEvent (node:_http_client:107:11)
    at MockHttpSocket.socketErrorListener (node:_http_client:574:5)
    at MockHttpSocket.emit (node:events:519:28)
    at MockHttpSocket.emit (/home/circleci/interceptors/repro/node_modules/.pnpm/@mswjs+interceptors@0.39.8/node_modules/@mswjs/interceptors/lib/node/chunk-N4ZZFE24.js:454:12)
    at TLSSocket.<anonymous> (/home/circleci/interceptors/repro/node_modules/.pnpm/@mswjs+interceptors@0.39.8/node_modules/@mswjs/interceptors/lib/node/chunk-N4ZZFE24.js:536:12)
    at TLSSocket.emit (node:events:519:28)
    at TLSSocket.emit (/home/circleci/interceptors/repro/node_modules/.pnpm/dd-trace@5.80.0_@openfeature+core@1.9.1_@openfeature+server-sdk@1.18.0_@openfeature+core@1.9.1_/node_modules/dd-trace/packages/datadog-instrumentations/src/net.js:65:25)
    at emitErrorNT (node:internal/streams/destroy:170:8)
    at emitErrorCloseNT (node:internal/streams/destroy:129:3) {
  errno: -22,
  code: 'EINVAL',
  syscall: 'read'
}

Potential solutions

If I revert the changes in #706 99967d7 the issue goes away. I understand that was in place for a reason, but reverting absolutely solves this. It seems like having the _handle exposed gets dicey when something else has closed the socket and (consumers of) MockHttpSocket thinks it's still ok to read/write.

I'm not well versed in this (type of) codebase. I rarely think about this low level socket stuff. I had an LLM hold my hand through the process of generating detailed logs, reproductions. I got very far with very little knowledge, which is a dangerous thing ;)

It's suggesting:

  public _read(size: number): void {
    if (this.socketState === 'passthrough') {
      return
    }

    super._read(size)
  }

and then removing the '_handle' aliasing. It suggests that the repeated _read is the source of the event listener oversubscription, and removing _handle stops the "2 owners of a single handle" issue.

This seems to work well. I'm happy to submit a PR, but I wanted to socialize it first, and also make sure it works well for us in production for a bit. Reproducing in an isolated repo has been very hard: I was successful exactly 2 times (out of hundreds of attempts) using the real dd-trace. Trying to simulate its behavior with an identical http.agent did not work. (But of course in our production apps, this happens dozens of times per CI run... 😬)

[jbinto]

Update: I have narrowed the root cause of this down to Happy Eyeballs. @mswjs/interceptors does not handle the case where the socket is switched out after the 250ms timeout, and attempts to act on an already-closed socket.

I have a repo that is fully reproducible with logs to prove this is the case. I'll update with more detail soon, and provide a PR fix.

[jbinto]

Related: nodejs/node#54359

[jbinto]

Please take a look at https://github.com/jbinto/msw-interceptors-einval-repro. I made a nice tidy reproduction case, optionally using Docker to simulate the 250ms network delay needed to trigger it.

This is a fork of @mswjs/interceptors and is an attempt to explain/solve #753.

• Diff from origin (v0.39.8 tag)

tl;dr In a mixed IPv4/IPv6 environment, under "high" latency (>250ms), Node's Happy Eyeballs implementation swaps out an IPv6 for an IPv4 socket (or vice versa). msw's MockHttpSocket passthrough() implementation holds on to a _handle for the original socket and does not see this "switcheroo". When the old, already-destroyed socket is acted upon, we get errors like EINVAL (when reading) or ECANCELED (when writing to a TLSSocket).

There are numerous ways to fix this, but I'm still trying to figure out how to balance this vs #706. Right now, I'm suppressing _read, which is enough to stop the EINVAL errors, but I think that's a bit of a hack and not really sufficient.

• Example reproduction log
• Example "fixed but hacky" log

I'm wrapping up for the weekend, and I never got to a PR or figured out what the solution should be. While my fix addresses my issue, these tests make it clear that just patching _read won't be enough. I think we'd either have to track the "socket swap" event and update _handle, or reconsider the _handle shadowing introduced in #706 and see if there's another way to solve that emitter leak. But hopefully this gives something for us to stew on over the next few days.