fix: cleaning up debugging and code

tegefaulkes · CMCDragonkai · commit 84095531131e · 2023-05-17T15:10:07.000+10:00
I've cleaned up a bunch of the debugging so the logs are clearer now. I've narrowed the timeout problem down to the generated certificates. Something about them is preventing the connection from being fully established. Likely rejected in some way but as for why is inscrutable. More digging to follow. But I know that If I load the cert files from memory then it works. So I know it's the generated certs. * Related #8 [ci skip]
diff --git a/src/QUICClient.ts b/src/QUICClient.ts
@@ -160,14 +160,14 @@ class QUICClient extends EventTarget {
         port
       },
       config: quicConfig,
-      logger: logger.getChild(`${QUICConnection.name} ${scid}`)
+      logger: logger.getChild(`${QUICConnection.name} ${scid.toString().slice(32)}`)
     });
     connection.addEventListener(
       'error',
       handleConnectionError,
       { once: true }
     );
-    console.log('CLIENT TRIGGER SEND');
+    logger.debug('CLIENT TRIGGER SEND');
     // This will not raise an error
     await connection.send();
     // This will wait to be established, while also rejecting on error
diff --git a/src/QUICConnection.ts b/src/QUICConnection.ts
@@ -312,7 +312,7 @@ class QUICConnection extends EventTarget {
    */
   @ready(new errors.ErrorQUICConnectionDestroyed(), false, ['destroying'])
   public async recv(data: Uint8Array, remoteInfo: RemoteInfo) {
-    console.log('RECV CALLED');
+    this.logger.debug('RECV CALLED');
 
     try {
       if (this.conn.isClosed()) {
@@ -336,7 +336,7 @@ class QUICConnection extends EventTarget {
         },
       };
       try {
-        // console.log('Did a recv', data.byteLength);
+        this.logger.debug(`Did a recv ${data.byteLength}`);
         this.conn.recv(data, recvInfo);
       } catch (e) {
         // Depending on the exception, the `this.conn.recv`
@@ -382,7 +382,7 @@ class QUICConnection extends EventTarget {
       }
     } finally {
 
-      // console.log('RECV FINALLY');
+      this.logger.debug('RECV FINALLY');
 
       // Set the timeout
       this.setTimeout();
@@ -397,7 +397,7 @@ class QUICConnection extends EventTarget {
         )
       ) {
 
-        console.log('CALLING DESTROY 2');
+        this.logger.debug('CALLING DESTROY 2');
         await this.destroy();
       }
     }
@@ -423,7 +423,7 @@ class QUICConnection extends EventTarget {
   @ready(new errors.ErrorQUICConnectionDestroyed(), false, ['destroying'])
   public async send(): Promise<void> {
 
-    console.log('SEND CALLED');
+    this.logger.debug('SEND CALLED');
 
     try {
       if (this.conn.isClosed()) {
@@ -439,11 +439,12 @@ class QUICConnection extends EventTarget {
       let sendInfo: SendInfo;
       while (true) {
         try {
-          // console.log('Did a send');
+          this.logger.debug('Did a send');
           [sendLength, sendInfo] = this.conn.send(sendBuffer);
         } catch (e) {
+          this.logger.debug(`SEND FAILED WITH ${e.message}`);
           if (e.message === 'Done') {
-            // console.log('SEND IS DONE');
+            this.logger.debug('SEND IS DONE');
             return;
           }
           try {
@@ -470,8 +471,7 @@ class QUICConnection extends EventTarget {
         }
         try {
 
-          // console.log('ATTEMPTING SEND', sendBuffer, 0, sendLength, sendInfo.to.port, sendInfo.to.host);
-          console.log('SEND UDP PACKET');
+          this.logger.debug(`ATTEMPTING SEND ${sendLength} bytes to ${sendInfo.to.port}:${sendInfo.to.host}`);
 
           await this.socket.send(
             sendBuffer,
@@ -481,21 +481,22 @@ class QUICConnection extends EventTarget {
             sendInfo.to.host
           );
         } catch (e) {
+          console.error(e);
           this.dispatchEvent(new events.QUICConnectionErrorEvent({ detail: e }));
           return;
         }
       }
     } finally {
 
-      // console.log('SEND FINALLY');
+      this.logger.debug('SEND FINALLY');
 
       this.setTimeout();
       if (
         this[status] !== 'destroying' &&
         (this.conn.isClosed() || this.conn.isDraining())
       ) {
 
-        console.log('CALLING DESTROY');
+        this.logger.debug('CALLING DESTROY');
 
         await this.destroy();
       } else if (
@@ -598,55 +599,55 @@ class QUICConnection extends EventTarget {
     // the time given becomes 1 second
     // Why did it reduce to 1000 ms?
 
-    // console.log('Time given:', time);
+    // this.logger.debug('Time given:', time);
 
-    // console.log('IS DRAINING', this.conn.isDraining());
+    // this.logger.debug('IS DRAINING', this.conn.isDraining());
 
     // Do note there is a change in one of our methods
     // I think I remember, we still need to change over to that
     // To enusre that exceptions mean `Done`
-    // console.log('PATH STATS', this.conn.pathStats());
+    // this.logger.debug('PATH STATS', this.conn.pathStats());
 
     if (time != null) {
-      // console.log('Resetting the timeout');
+      // this.logger.debug('Resetting the timeout');
 
       clearTimeout(this.timer);
       this.timer = setTimeout(
         async () => {
 
-          // console.log('TIMEOUT HANDLER CALLED');
-          // console.log('draining', this.conn.isDraining());
-          // console.log('closed', this.conn.isClosed());
-          // console.log('timed out', this.conn.isTimedOut());
-          // console.log('established', this.conn.isEstablished());
-          // console.log('in early data', this.conn.isInEarlyData());
-          // console.log('resumed', this.conn.isResumed());
+          // this.logger.debug('TIMEOUT HANDLER CALLED');
+          // this.logger.debug('draining', this.conn.isDraining());
+          // this.logger.debug('closed', this.conn.isClosed());
+          // this.logger.debug('timed out', this.conn.isTimedOut());
+          // this.logger.debug('established', this.conn.isEstablished());
+          // this.logger.debug('in early data', this.conn.isInEarlyData());
+          // this.logger.debug('resumed', this.conn.isResumed());
 
           // This would only run if the `recv` and `send` is not called
           // Otherwise this handler would be cleared each time and be reset
           this.conn.onTimeout();
 
-          // console.log('AFTER ON TIMEOUT');
+          // this.logger.debug('AFTER ON TIMEOUT');
           // DRAINING IS FALSE
-          // console.log('draining', this.conn.isDraining());
+          // this.logger.debug('draining', this.conn.isDraining());
           // CLOSED IS TRUE
-          // console.log('closed', this.conn.isClosed());
+          // this.logger.debug('closed', this.conn.isClosed());
           // TIMEDOUT IS TRUE
-          // console.log('timed out', this.conn.isTimedOut());
-          // console.log('established', this.conn.isEstablished());
-          // console.log('in early data', this.conn.isInEarlyData());
-          // console.log('resumed', this.conn.isResumed());
+          // this.logger.debug('timed out', this.conn.isTimedOut());
+          // this.logger.debug('established', this.conn.isEstablished());
+          // this.logger.debug('in early data', this.conn.isInEarlyData());
+          // this.logger.debug('resumed', this.conn.isResumed());
 
           // Trigger a send, this will also set the timeout again at the end
 
-          console.log('TIMEOUT TRIGGER SEND');
+          this.logger.debug('TIMEOUT TRIGGER SEND');
 
           await this.send();
         },
         time
       );
     } else {
-      // console.log('Clearing the timeout');
+      this.logger.debug('Clearing the timeout');
       clearTimeout(this.timer);
       delete this.timer;
       if (this.conn.isClosed() || this.conn.isDraining()) {
diff --git a/src/QUICServer.ts b/src/QUICServer.ts
@@ -72,7 +72,7 @@ class QUICServer extends EventTarget {
     // We can force it
     config: Partial<QUICConfig> & Pick<
       QUICConfig,
-      'certChainPem' | 'privKeyPem'
+      'tlsConfig'
     >;
     resolveHostname?: (hostname: Hostname) => Host | PromiseLike<Host>;
     logger?: Logger;
@@ -261,14 +261,14 @@ class QUICServer extends EventTarget {
     }
     // Here we shall re-use the originally-derived DCID as the SCID
     scid = new QUICConnectionId(header.dcid);
-    this.logger.debug(`Accepting new connection from QUIC packet`);
+    this.logger.debug(`Accepting new connection from QUIC packet from ${remoteInfo.host}:${remoteInfo.port}`);
     const connection = await QUICConnection.acceptQUICConnection({
       scid,
       dcid: dcidOriginal,
       socket: this.socket,
       remoteInfo,
       config: this.config,
-      logger: this.logger.getChild(`${QUICConnection.name} ${scid}`)
+      logger: this.logger.getChild(`${QUICConnection.name} ${scid.toString().slice(32)}`)
     });
 
     this.dispatchEvent(new events.QUICServerConnectionEvent({ detail: connection }));
diff --git a/src/QUICStream.ts b/src/QUICStream.ts
@@ -256,10 +256,10 @@ class QUICStream extends EventTarget implements ReadableWritablePair<Uint8Array,
         // or through an exception here where the stream reports an error
         // Since we don't call this method unless it is readable
         // This should never be reported... (this branch should be dead code)
-        console.log('Stream reported: done');
+        this.logger.debug('Stream reported: done');
         return;
       } else {
-        console.log('Stream reported: error');
+        this.logger.debug('Stream reported: error');
         const match = e.message.match(/StreamReset\((.+)\)/);
         if (match != null) {
           // If it is `StreamReset(u64)` error, then the peer has closed
@@ -284,8 +284,8 @@ class QUICStream extends EventTarget implements ReadableWritablePair<Uint8Array,
     }
     // If fin is true, then that means, the stream is CLOSED
     if (fin) {
-      console.log('Stream reported: fin');
       // This will render `stream.cancel` a noop
+      this.logger.debug('Stream reported: fin');
       this.readableController.close();
       await this.closeRecv();
       return;
diff --git a/src/config.ts b/src/config.ts
@@ -1,9 +1,16 @@
 import type { Config as QuicheConfig } from './native/types';
 import { quiche } from './native';
 
+type TlsConfig = {
+  certChainPem: string | null;
+  privKeyPem: string | null;
+} | {
+  certChainFromPemFile: string | null;
+  privKeyFromPemFile: string | null;
+}
+
 type QUICConfig = {
-  certChainPem: string | null | undefined;
-  privKeyPem: string | null | undefined;
+  tlsConfig: TlsConfig | undefined;
   verifyPeer: boolean;
   logKeys: string | undefined;
   grease: boolean;
@@ -21,8 +28,7 @@ type QUICConfig = {
 };
 
 const clientDefault: QUICConfig = {
-  certChainPem: null,
-  privKeyPem: null,
+  tlsConfig: undefined,
   logKeys: undefined,
   verifyPeer: false,
   grease: true,
@@ -46,8 +52,7 @@ const clientDefault: QUICConfig = {
 };
 
 const serverDefault: QUICConfig = {
-  certChainPem: null,
-  privKeyPem: null,
+  tlsConfig: undefined,
   logKeys: undefined,
   verifyPeer: false,
   grease: true,
@@ -71,16 +76,29 @@ const serverDefault: QUICConfig = {
 };
 
 function buildQuicheConfig(config: QUICConfig): QuicheConfig {
-  const quicheConfig: QuicheConfig = quiche.Config.withBoringSslCtx(
-    config.certChainPem != null ? Buffer.from(config.certChainPem) : null,
-    config.privKeyPem != null ? Buffer.from(config.privKeyPem) : null,
-  )
+  let quicheConfig: QuicheConfig;
+  if (config.tlsConfig != null && 'certChainPem' in config.tlsConfig) {
+    quicheConfig = quiche.Config.withBoringSslCtx(
+      config.tlsConfig.certChainPem != null ? Buffer.from(config.tlsConfig.certChainPem) : null,
+      config.tlsConfig.privKeyPem != null ? Buffer.from(config.tlsConfig.privKeyPem) : null,
+    )
+  } else {
+    quicheConfig = new quiche.Config();
+    if (config.tlsConfig?.certChainFromPemFile != null) {
+      quicheConfig.loadCertChainFromPemFile(config.tlsConfig.certChainFromPemFile);
+    }
+    if (config.tlsConfig?.privKeyFromPemFile != null) {
+      quicheConfig.loadPrivKeyFromPemFile(config.tlsConfig.privKeyFromPemFile);
+    }
+  }
   if (config.logKeys != null) {
     quicheConfig.logKeys();
   }
   if (config.enableEarlyData) {
     quicheConfig.enableEarlyData();
   }
+
+  quicheConfig.verifyPeer(config.verifyPeer);
   quicheConfig.grease(config.grease);
   quicheConfig.setMaxIdleTimeout(config.maxIdleTimeout);
   quicheConfig.setMaxRecvUdpPayloadSize(config.maxRecvUdpPayloadSize);
diff --git a/src/native/napi/config.rs b/src/native/napi/config.rs
@@ -56,17 +56,17 @@ impl Config {
     ).or_else(
       |err| Err(Error::from_reason(err.to_string()))
     )?;
-    ssl_ctx_builder.set_verify(
-      boring::ssl::SslVerifyMode::PEER
-    );
+    // ssl_ctx_builder.set_verify(
+    //   boring::ssl::SslVerifyMode::NONE
+    // );
     // Processing and adding the cert chain
     if let Some(cert_pem) = cert_pem {
-      let x509_cet_chain = boring::x509::X509::stack_from_pem(
+      let x509_cert_chain = boring::x509::X509::stack_from_pem(
         &cert_pem.to_vec()
       ).or_else(
         |err| Err(Error::from_reason(err.to_string()))
       )?;
-      for (i, cert) in x509_cet_chain.iter().enumerate() {
+      for (i, cert) in x509_cert_chain.iter().enumerate() {
         if i == 0 {
           ssl_ctx_builder.set_certificate(
             cert,
@@ -84,12 +84,10 @@ impl Config {
     }
     // Processing and adding the private key
     if let Some(key_pem) = key_pem {
-      println!("Had key pem");
       let private_key = boring::pkey::PKey::private_key_from_pem(&key_pem)
         .or_else(
         |err| Err(Error::from_reason(err.to_string()))
       )?;
-      println!("{:?}", private_key);
       ssl_ctx_builder.set_private_key(&private_key)
         .or_else(
           |err| Err(Error::from_reason(err.to_string()))
diff --git a/tests/QUICClient.test.ts b/tests/QUICClient.test.ts
diff --git a/tests/tlsUtils.ts b/tests/tlsUtils.ts
