Deno 1.6.2 and 1.6.3 fail to fully handshake even after a Deno.startTls upgrade completes

[aricart]

The issue seems to be that Deno.startTls() resolves before the connection is fully setup - any writer created on the resulting tlsConnection will fail - here's a test:

import {
  fail
} from "https://deno.land/[email protected]/testing/asserts.ts";
import { BufWriter } from "https://deno.land/[email protected]/io/mod.ts";

Deno.test("tls - raw tls upgrade", async () => {
  interface Deferred<T> extends Promise<T> {
    resolve: (value?: T | PromiseLike<T>) => void;
    reject: (reason?: any) => void;
  }

  function deferred<T>(): Deferred<T> {
    let methods = {};
    const p = new Promise<T>((resolve, reject): void => {
      methods = { resolve, reject };
    });
    return Object.assign(p, methods) as Deferred<T>;
  }

  const te = new TextEncoder();
  const td = new TextDecoder();

  function render(frame: Uint8Array): string {
    const cr = "␍";
    const lf = "␊";
    return td.decode(frame)
      .replace(/\n/g, lf)
      .replace(/\r/g, cr);
  }

  async function write(writer: BufWriter, pm: string) {
    try {
      const buf = te.encode(pm);
      const c = await writer.write(buf);
      await writer.flush();
      console.info(`< ${c}/${buf.length}:`, render(buf));
    } catch (err) {
      console.error(`error writing pm: ${pm}: ${err}`);
      throw err;
    }
  }

  const pong = deferred<void>();
  const hostname = "demo.nats.io";
  let conn = await Deno.connect({ hostname, port: 4443 });
  const buf = new Uint8Array(64 * 1023);

  let c = await conn.read(buf);
  if (c === null) {
    fail("connection closed");
  }
  //@ts-ignore - this has to be a number
  const frame = buf.subarray(0, c);
  console.info(">", render(frame));

  // attempt the tls upgrade
  console.info("upgrading connection");
  const tlsConn = await Deno.startTls(conn, { hostname });
  console.info("connection upgraded");

  // start a reader to print server responses
  let _ = (async function () {
    while (true) {
      try {
        const c = await tlsConn.read(buf);
        if (c === null) {
          break;
        }
        if (c) {
          const frame = buf.subarray(0, c);
          console.info(">", render(frame));

          const re = /^PONG\r\n/mi;
          if (re.test(td.decode(frame))) {
            pong.resolve();
          }
        }
      } catch (err) {
        // closed
        break;
      }
    }
  })();

  const writer = new BufWriter(tlsConn);
  await write(
    writer,
    `CONNECT {"protocol":1,"version":"1.0.0-13","lang":"nats.deno","verbose":false,"pedantic":true, "verbose":true}\r\n`,
  );
  await write(writer, `PING\r\n`);
  await pong;
  tlsConn.close();
});

Running with 1.4.6->1.6.1:

❯ deno --version
deno 1.4.6
v8 8.7.220.3
typescript 4.0.3
❯ deno test --allow-all --unstable --filter "tls - raw tls upgrade"
Check file:///Users/xxx/Dropbox/code/src/github.com/nats-io/nats.deno/$deno$test.ts
running 1 tests
test tls - raw tls upgrade ... > INFO {"server_id":"NDGMFJPAMLNEQNWVI5YRSEYMCPAU2SBIE6SCNE2I26CFRAUYBGSURRCU","server_name":"NDGMFJPAMLNEQNWVI5YRSEYMCPAU2SBIE6SCNE2I26CFRAUYBGSURRCU","version":"2.2.0-beta.35","proto":1,"go":"go1.15.6","host":"0.0.0.0","port":4443,"headers":true,"tls_required":true,"max_payload":1048576,"client_id":382,"client_ip":"71.193.91.14"} ␍␊
upgrading connection
connection upgraded
< 112/112: CONNECT {"protocol":1,"version":"1.0.0-13","lang":"nats.deno","verbose":false,"pedantic":true, "verbose":true}␍␊
< 6/6: PING␍␊
> +OK␍␊PONG␍␊
ok (367ms)

On 1.6.2+ the result is different - the code will block on the writer.flush():

❯ deno test --allow-all --unstable --filter "tls - raw tls upgrade"
Check file:///Users/xxx/Dropbox/code/src/github.com/nats-io/nats.deno/$deno$test.ts
running 1 tests
test tls - raw tls upgrade ... > INFO {"server_id":"NDGMFJPAMLNEQNWVI5YRSEYMCPAU2SBIE6SCNE2I26CFRAUYBGSURRCU","server_name":"NDGMFJPAMLNEQNWVI5YRSEYMCPAU2SBIE6SCNE2I26CFRAUYBGSURRCU","version":"2.2.0-beta.35","proto":1,"go":"go1.15.6","host":"0.0.0.0","port":4443,"headers":true,"tls_required":true,"max_payload":1048576,"client_id":383,"client_ip":"71.193.91.14"} ␍␊
upgrading connection
connection upgraded
^C

Removing the flush(), will make the program block as the read loop won't ever see the PONG\r\n response it is expecting.

[starkpsmichael]

I think #8945 could be related to this.

[lucacasonato]

Likely caused by 6984b63. For me the test completed after about 120 seconds:

~/p/g/d/deno ❯❯❯ deno test --unstable --allow-net test.ts
running 1 tests
test tls - raw tls upgrade ... > INFO {"server_id":"NDGMFJPAMLNEQNWVI5YRSEYMCPAU2SBIE6SCNE2I26CFRAUYBGSURRCU","server_name":"NDGMFJPAMLNEQNWVI5YRSEYMCPAU2SBIE6SCNE2I26CFRAUYBGSURRCU","version":"2.2.0-beta.35","proto":1,"go":"go1.15.6","host":"0.0.0.0","port":4443,"headers":true,"tls_required":true,"max_payload":1048576,"client_id":447,"client_ip":"87.161.102.234"} ␍␊
upgrading connection
connection upgraded
> PING␍␊
< 112/112: CONNECT {"protocol":1,"version":"1.0.0-13","lang":"nats.deno","verbose":false,"pedantic":true, "verbose":true}␍␊
> +OK␍␊
< 6/6: PING␍␊
> PONG␍␊
ok (121197ms)

test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out (121198ms)

[lucacasonato]

Found the issue. Only one of read or write can access a TLS stream at once. One will asynchronously block until the other gives up its lock. We need to turn the StreamResource::client_tls_stream into a FullDuplexResource.

cc @bartlomieju @piscisaureus

[lucacasonato]

It looks like this will require some hackery, as ClientTlsStream can not be split into halves out of the box, like TCP sockets can be with tcp::OwnedReadHalf and tcp::OwnedWriteHalf. One approach is to use tokio::util::split to split the stream, but this is not always safe for TLS, because not just application data is sent, but also control data. See tokio-rs/tls#40. As described in the previously mentioned issue, it does seem to be safe in rustls, but it looks like it is possible that some messages are delayed?... not sure.

We should try with tokio::util::split and see if we run into issues.

[piscisaureus]

Should be fixed by #9118.