Merge pull request #73 from MatrixAI/feature-ID-and-logging-fix

feat: expose more `connectionId` information and update error logging levels

Author: tegefaulkes

src/QUICClient.ts

@@ -315,19 +315,8 @@ class QUICClient {
    */
   protected handleEventQUICClientError = (evt: events.EventQUICClientError) => {
     const error = evt.detail;
-    if (
-      (error instanceof errors.ErrorQUICConnectionLocal ||
-        error instanceof errors.ErrorQUICConnectionPeer) &&
-      ((!error.data.isApp &&
-        error.data.errorCode === ConnectionErrorCode.NoError) ||
-        (error.data.isApp && error.data.errorCode === 0))
-    ) {
-      // Log out the excpetion as an info when it is graceful
-      this.logger.info(utils.formatError(error));
-    } else {
-      // Log out the exception as an error when it is not graceful
-      this.logger.error(utils.formatError(error));
-    }
+    // Log out the error
+    this.logger.info(utils.formatError(error));
     if (
       error instanceof errors.ErrorQUICClientInternal ||
       error instanceof errors.ErrorQUICConnectionInternal

src/QUICConnection.ts

@@ -1,7 +1,6 @@
 import type { PromiseCancellable } from '@matrixai/async-cancellable';
 import type { ContextTimed, ContextTimedInput } from '@matrixai/contexts';
 import type QUICSocket from './QUICSocket';
-import type QUICConnectionId from './QUICConnectionId';
 import type {
   Host,
   Port,
@@ -25,6 +24,7 @@ import {
 } from '@matrixai/async-init/dist/StartStop';
 import { timedCancellable, context } from '@matrixai/contexts/dist/decorators';
 import { buildQuicheConfig, minIdleTimeout } from './config';
+import QUICConnectionId from './QUICConnectionId';
 import QUICStream from './QUICStream';
 import { quiche, ConnectionErrorCode } from './native';
 import * as utils from './utils';
@@ -44,11 +44,6 @@ class QUICConnection {
    */
   public readonly type: 'client' | 'server';
 
-  /**
-   * This is the source connection ID.
-   */
-  public readonly connectionId: QUICConnectionId;
-
   /**
    * Resolves once the connection has closed.
    */
@@ -186,19 +181,8 @@ class QUICConnection {
   ) => {
     const error = evt.detail;
     this.errorLast = error;
-    if (
-      (error instanceof errors.ErrorQUICConnectionLocal ||
-        error instanceof errors.ErrorQUICConnectionPeer) &&
-      ((!error.data.isApp &&
-        error.data.errorCode === ConnectionErrorCode.NoError) ||
-        (error.data.isApp && error.data.errorCode === 0))
-    ) {
-      // Log out the excpetion as an info when it is graceful
-      this.logger.info(utils.formatError(error));
-    } else {
-      // Log out the exception as an error when it is not graceful
-      this.logger.error(utils.formatError(error));
-    }
+    // Log out error for debugging
+    this.logger.info(utils.formatError(error));
     if (error instanceof errors.ErrorQUICConnectionInternal) {
       throw error;
     }
@@ -381,7 +365,6 @@ class QUICConnection {
     }
     this.type = type;
     this.conn = conn!;
-    this.connectionId = scid;
     this.socket = socket;
     this.config = config;
     if (this.config.cert != null) {
@@ -413,6 +396,49 @@ class QUICConnection {
     this.resolveClosedP = resolveClosedP;
   }
 
+  /**
+   * This is the source connection ID.
+   */
+  public get connectionId() {
+    const sourceId = this.conn.sourceId();
+    // Zero copy construction of QUICConnectionId
+    return new QUICConnectionId(
+      sourceId.buffer,
+      sourceId.byteOffset,
+      sourceId.byteLength,
+    );
+  }
+
+  /**
+   * This is the destination connection ID.
+   * This is only fully known after establishing the connection
+   */
+  @ready(new errors.ErrorQUICConnectionNotRunning())
+  public get connectionIdPeer() {
+    const destinationId = this.conn.destinationId();
+    // Zero copy construction of QUICConnectionId
+    return new QUICConnectionId(
+      destinationId.buffer,
+      destinationId.byteOffset,
+      destinationId.byteLength,
+    );
+  }
+
+  /**
+   * A common ID between the client and server connection.
+   * Used to identify connection pairs more easily.
+   */
+  @ready(new errors.ErrorQUICConnectionNotRunning())
+  public get connectionIdShared() {
+    const sourceId = this.conn.sourceId();
+    const destinationId = this.conn.destinationId();
+    if (Buffer.compare(sourceId, destinationId) <= 0) {
+      return new QUICConnectionId(Buffer.concat([sourceId, destinationId]));
+    } else {
+      return new QUICConnectionId(Buffer.concat([destinationId, sourceId]));
+    }
+  }
+
   public get remoteHost(): Host {
     return this._remoteHost;
   }

src/QUICServer.ts

@@ -72,7 +72,8 @@ class QUICServer {
    */
   protected handleEventQUICServerError = (evt: events.EventQUICServerError) => {
     const error = evt.detail;
-    this.logger.error(utils.formatError(error));
+    // Log out error for debugging
+    this.logger.info(utils.formatError(error));
     if (error instanceof errors.ErrorQUICServerInternal) {
       throw error;
     }

src/QUICSocket.ts

@@ -56,7 +56,8 @@ class QUICSocket {
 
   protected handleEventQUICSocketError = (evt: events.EventQUICSocketError) => {
     const error = evt.detail;
-    this.logger.error(utils.formatError(error));
+    // Log out error for debugging
+    this.logger.debug(utils.formatError(error));
   };
 
   protected handleEventQUICSocketClose = async () => {

src/QUICStream.ts

@@ -150,7 +150,8 @@ class QUICStream implements ReadableWritablePair<Uint8Array, Uint8Array> {
   protected handleEventQUICStreamError = (evt: events.EventQUICStreamError) => {
     const error = evt.detail;
     if (error instanceof errors.ErrorQUICStreamInternal) {
-      this.logger.error(utils.formatError(error));
+      // Log out error for debugging
+      this.logger.debug(utils.formatError(error));
       throw error;
     }
     if (

tests/QUICClient.test.ts

@@ -15,7 +15,7 @@ import * as testsUtils from './utils';
 import { generateTLSConfig, sleep } from './utils';
 
 describe(QUICClient.name, () => {
-  const logger = new Logger(`${QUICClient.name} Test`, LogLevel.SILENT, [
+  const logger = new Logger(`${QUICClient.name} Test`, LogLevel.WARN, [
     new StreamHandler(
       formatting.format`${formatting.level}:${formatting.keys}:${formatting.msg}`,
     ),
@@ -1654,7 +1654,7 @@ describe(QUICClient.name, () => {
       await server.stop();
     });
   });
-  test('Connections are established and secured quickly', async () => {
+  test('connections are established and secured quickly', async () => {
     const tlsConfigServer = await testsUtils.generateTLSConfig(defaultType);
 
     const connectionEventProm = promise<events.EventQUICServerConnection>();
@@ -1808,6 +1808,73 @@ describe(QUICClient.name, () => {
       errors.ErrorQUICConnectionIdleTimeout,
     );
 
+    await client.destroy({ force: true });
+    await server.stop({ force: true });
+  });
+  test('connections share the same id information', async () => {
+    const tlsConfigServer = await testsUtils.generateTLSConfig(defaultType);
+
+    const { p: serverConnectionP, resolveP: serverConnectionResolveP } =
+      promise<QUICConnection>();
+    const server = new QUICServer({
+      crypto: {
+        key,
+        ops: serverCryptoOps,
+      },
+      logger: logger.getChild(QUICServer.name),
+      config: {
+        key: tlsConfigServer.leafKeyPairPEM.privateKey,
+        cert: tlsConfigServer.leafCertPEM,
+        verifyPeer: false,
+      },
+    });
+    socketCleanMethods.extractSocket(server);
+    server.addEventListener(
+      events.EventQUICServerConnection.name,
+      (evt: events.EventQUICServerConnection) => {
+        serverConnectionResolveP(evt.detail);
+      },
+    );
+    await server.start({
+      host: localhost,
+    });
+    // If the server is slow to respond then this will time out.
+    //  Then main cause of this was the server not processing the initial packet
+    //  that creates the `QUICConnection`, as a result, the whole creation waited
+    //  an extra 1 second for the client to retry the initial packet.
+    const client = await QUICClient.createQUICClient(
+      {
+        host: localhost,
+        port: server.port,
+        localHost: localhost,
+        crypto: {
+          ops: clientCryptoOps,
+        },
+        logger: logger.getChild(QUICClient.name),
+        config: {
+          verifyPeer: false,
+        },
+      },
+      { timer: 500 },
+    );
+    socketCleanMethods.extractSocket(client);
+
+    const clientConn = client.connection;
+    const serverConn = await serverConnectionP;
+
+    expect(
+      Buffer.compare(clientConn.connectionId, serverConn.connectionIdPeer),
+    ).toBe(0);
+    expect(
+      Buffer.compare(clientConn.connectionIdPeer, serverConn.connectionId),
+    ).toBe(0);
+    expect(
+      Buffer.compare(
+        clientConn.connectionIdShared,
+        serverConn.connectionIdShared,
+      ),
+    ).toBe(0);
+
     await client.destroy({ force: true });
     await server.stop({ force: true });
   });

tests/QUICServer.test.ts

@@ -10,7 +10,7 @@ import * as errors from '@/errors';
 import * as testsUtils from './utils';
 
 describe(QUICServer.name, () => {
-  const logger = new Logger(`${QUICServer.name} Test`, LogLevel.SILENT, [
+  const logger = new Logger(`${QUICServer.name} Test`, LogLevel.WARN, [
     new StreamHandler(
       formatting.format`${formatting.level}:${formatting.keys}:${formatting.msg}`,
     ),

tests/QUICSocket.test.ts

@@ -13,7 +13,7 @@ import * as events from '@/events';
 import * as testsUtils from './utils';
 
 describe(QUICSocket.name, () => {
-  const logger = new Logger(`${QUICSocket.name} Test`, LogLevel.SILENT, [
+  const logger = new Logger(`${QUICSocket.name} Test`, LogLevel.WARN, [
     new StreamHandler(),
   ]);
   // This has to be setup asynchronously due to key generation
@@ -296,7 +296,7 @@ describe(QUICSocket.name, () => {
     test('error and close event lifecycle', async () => {
       // We expect error logs
       const socketLogger = logger.getChild('abc');
-      socketLogger.setLevel(LogLevel.SILENT);
+      socketLogger.setLevel(LogLevel.WARN);
       const socket = new QUICSocket({
         logger: socketLogger,
       });
@@ -865,7 +865,7 @@ describe(QUICSocket.name, () => {
         };
         // We expect lots of error logs
         const socketLogger = logger.getChild('abc');
-        socketLogger.setLevel(LogLevel.SILENT);
+        socketLogger.setLevel(LogLevel.WARN);
         const socket = new QUICSocket({
           logger: socketLogger,
         });

tests/QUICStream.test.ts

@@ -10,7 +10,7 @@ import * as testsUtils from './utils';
 import { generateTLSConfig } from './utils';
 
 describe(QUICStream.name, () => {
-  const logger = new Logger(`${QUICStream.name} Test`, LogLevel.SILENT, [
+  const logger = new Logger(`${QUICStream.name} Test`, LogLevel.WARN, [
     new StreamHandler(
       formatting.format`${formatting.level}:${formatting.keys}:${formatting.msg}`,
     ),

tests/concurrency.test.ts

@@ -12,7 +12,7 @@ import { generateTLSConfig, handleStreamProm, sleep } from './utils';
 import * as testsUtils from './utils';
 
 describe('Concurrency tests', () => {
-  const logger = new Logger(`${QUICClient.name} Test`, LogLevel.SILENT, [
+  const logger = new Logger(`${QUICClient.name} Test`, LogLevel.WARN, [
     new StreamHandler(
       formatting.format`${formatting.level}:${formatting.keys}:${formatting.msg}`,
     ),