Deno should make simultaneous outgoing requests to IPv4 and IPv6 addresses when both exist

[NfNitLoop]

Version:

deno 1.42.4 (release, aarch64-apple-darwin) v8 12.3.219.9 typescript 5.4.3

Update: The Problem

Copy/paste from my comment below:

My host, nfnitloop.com had an old/invalid IPv6 address in DNS.

Chrome's implementation simultaneously tries to open an IPv6 and and IPv4 connection, and continues with whichever responds first.

Deno's implementation seems to always try IPv6 first. Only after that times out (75 seconds?) does it fall back to IPv4.

So, yes, as far as my server was concerned, Deno was doing nothing for 70+ seconds before connecting.

Oddly, Deno's fetch() implementation does the same thing that Chrome does, and tries both IPv6 and 4 simultaneously. It might be good to do the same thing for WebSocket!

Original Report

(Details here about how this surfaced, and how I tried to debug it. But I didn't discover the above problem until later.)

I can run this code in my browser and the web socket connects in a reasonable amount of time (given that I'm on a high-latency link, and there's TCP/TLS/HTTP round-trip overhead):

async function connect() {
  const timer = new Timer()
  const ws = new WebSocket("wss://nfnitloop.com/nostr/")
  console.log("Waiting for web socket to connect")
  console.log("readyState", ws.readyState)

  ws.addEventListener("open", (event) => {
    timer.done()
    console.log("readyState", ws.readyState)
    ws.close()
  })
}

class Timer {
  started = Timer.now()
  static now() { return Date.now().valueOf() }
  get elapsedMs() { return Timer.now() - this.started }
  done() {
    console.log("Timer done after", this.elapsedMs, "ms");
  }
}

connect()

output:

Waiting for web socket to connect
runtime.ts:177 readyState 0
runtime.ts:177 Timer done after 717 ms
runtime.ts:177 readyState 1

But when I run this in Deno, it takes for-ev-er:

> deno run -A example.js
Waiting for web socket to connect
readyState 0
Timer done after 75760 ms
readyState 1

⚠️ Now, this doesn't happen on every web socket. For example, if I replace the URL with wss://nos.lol I get reasonable performance there too.

> deno run -A example.js
Waiting for web socket to connect
readyState 0
Timer done after 969 ms
readyState 1

So it seems Deno's WebSocket implementation doesn't work well with something on my web socket, in particular. I haven't noticed this in browsers or in iOS apps that connect to that socket. It's likely that I'm just doing something that's an edge case that triggers this poor behavior in Deno's implementation.

I'm just using Axum's WebSocket implementation to handle incoming web sockets. That works instantly when I run locally, without TLS. (127.0.0.1). When I deploy it to my remote server, behind an Nginx proxy, which handles my TLS encryption, then I see the issue. (Again, only in Deno.)

I'm not sure if it's relevant but just in case, my proxy settings in nginx are:

map $http_upgrade $connection_upgrade {
    default upgrade;
    '' close;
}

server {
    server_name www.nfnitloop.com nfnitloop.com;
    # <normal HTTPS server config>

    location /nostr/ {
        proxy_pass http://127.0.0.1:8095/;
        proxy_http_version 1.1;
        proxy_set_header Upgrade $http_upgrade;
        # See: https://nginx.org/en/docs/http/websocket.html
        proxy_set_header Connection $connection_upgrade;
        proxy_buffering off; # have tried this on/off. 
    }

When I enable logging on the proxied service, it seems like it doesn't get the request until many seconds later, at which point things operate "normally" AFAICT. I haven't yet done a packet sniff to see if this delay is in Deno sending the first packet(s) or Nginx holding onto them for a long time before forwarding.

[NfNitLoop]

One other difference I noticed (by enabling debug logging in nginx) is that Chrome sends more headers for a socket connection than Deno does.

Deno:

2024/04/26 23:40:56 [debug] 15476#15476: *10422 http process request header line
2024/04/26 23:40:56 [debug] 15476#15476: *10422 http header: "host: nfnitloop.com"
2024/04/26 23:40:56 [debug] 15476#15476: *10422 http header: "upgrade: websocket"
2024/04/26 23:40:56 [debug] 15476#15476: *10422 http header: "connection: Upgrade"
2024/04/26 23:40:56 [debug] 15476#15476: *10422 http header: "sec-websocket-key: W0SiuJe06vzA/KP0pRNfJQ=="
2024/04/26 23:40:56 [debug] 15476#15476: *10422 http header: "user-agent: Deno/1.42.4"
2024/04/26 23:40:56 [debug] 15476#15476: *10422 http header: "sec-websocket-version: 13"
2024/04/26 23:40:56 [debug] 15476#15476: *10422 http header done

Chrome:

2024/04/26 23:41:58 [debug] 15476#15476: *10438 http process request header line
2024/04/26 23:41:58 [debug] 15476#15476: *10438 http header: "Host: nfnitloop.com"
2024/04/26 23:41:58 [debug] 15476#15476: *10438 http header: "Connection: Upgrade"
2024/04/26 23:41:58 [debug] 15476#15476: *10438 http header: "Pragma: no-cache"
2024/04/26 23:41:58 [debug] 15476#15476: *10438 http header: "Cache-Control: no-cache"
2024/04/26 23:41:58 [debug] 15476#15476: *10438 http header: "User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/124.0.0.0 Safari/537.36"
2024/04/26 23:41:58 [debug] 15476#15476: *10438 http header: "Accept-Language: en-US,en;q=0.6"
2024/04/26 23:41:58 [debug] 15476#15476: *10438 http header: "Upgrade: websocket"
2024/04/26 23:41:58 [debug] 15476#15476: *10438 http header: "Origin: https://www.typescriptlang.org"
2024/04/26 23:41:58 [debug] 15476#15476: *10438 http header: "Sec-WebSocket-Version: 13"
2024/04/26 23:41:58 [debug] 15476#15476: *10438 http header: "Accept-Encoding: gzip, deflate, br, zstd"
2024/04/26 23:41:58 [debug] 15476#15476: *10438 http header: "Sec-WebSocket-Key: RuM8MQoo59PCagkMqDo3sA=="
2024/04/26 23:41:58 [debug] 15476#15476: *10438 http header: "Sec-WebSocket-Extensions: permessage-deflate; client_max_window_bits"
2024/04/26 23:41:58 [debug] 15476#15476: *10438 http header done

Again, I apologize, I'm not sure whether those are relevant. Still trying to debug here.

I will say, if the timing of the debug output from nginx is to be trusted, it really looks like Deno just sits there doing nothing for 70+ seconds before making the connection. Immediately, once we get the first message about the connection in nginx:

2024/04/26 23:40:56 [debug] 15476#15476: *10422 SSL ALPN supported by client: http/1.1

the entire web socket upgrade process completes within the 1-second resolution of logs:

2024/04/26 23:40:56 [debug] 15476#15476: 10422 close http connection: 22 2024/04/26 23:40:56 [debug] 15476#15476: 10422 SSL_shutdown: 1 2024/04/26 23:40:56 [debug] 15476#15476: *10422 reusable connection: 0

[NfNitLoop]

Found the issue:

My host, nfnitloop.com had an old/invalid IPv6 address in DNS.

Chrome's implementation simultaneously tries to open an IPv6 and and IPv4 connection, and continues with whichever responds first.

Deno's implementation seems to always try IPv6 first. Only after that times out (75 seconds?) does it fall back to IPv4.

So, yes, as far as my server was concerned, Deno was doing nothing for 70+ seconds before connecting.

Oddly, Deno's fetch() implementation does the same thing that Chrome does, and tries both IPv6 and 4 simultaneously. It might be good to do the same thing for WebSocket!

[mmastrac]

This might be a useful thing for us to do for all outgoing connections, but it's definitely more of an infrastructure bug on that server's end.

This would apply to Deno.connect, Deno.connectTls and the WebSocket APIs.