Faster device connecting on MacOS, plus improved logging

Summary:
While investigating large delays in connecting to the mac we discovered two main problems.

1. The way we scan for devices on the serial port is to get a list of serial devices, try communicating with each one serially, and then look for a valid response. The problem is that intermittently trying to open a connection to a bluetooth listening device on macOS would take 30s to time out, which would slow the whole process. After talking with Cory, we realized we could filter the list of devices with the vendorID and productID and this makes it so we essentially only see our device (though it's not guaranteed unique). Now macOS connects as fast as windows (~4s) on the serial port.

2. The drive takes about 15s to mount on MacOS for some reason. We can't really speed this up without root access, so no real fix here, but overall perf is much better due to #1.

While I was at it, it was helpful to add timestamps to the logs, as well as more logging info about connection time for any future issues.

Also fixed incorrect slashes in the launch.json file which worked on windows but not mac.

Also also found a race condition where the drive search could be left on if disconnected at the wrong time. As noted, all of that architecture could use some rethinking at some point due to the inherently async and unordered nature of the different components coming online or going offline.

Reviewed By: conordickinson

Differential Revision: D67461348

fbshipit-source-id: 2f123a66c8eac202acf8310d7e96df76276c1a78

.vscode/launch.json

@@ -6,7 +6,7 @@
       "request": "launch",
       "name": "Debug Main Process",
       "skipFiles": ["<node_internals>/**"],
-      "program": "${workspaceFolder}\\scripts\\watch.js",
+      "program": "${workspaceFolder}/scripts/watch.js",
       "autoAttachChildProcesses": true
     }
   ]

package.json

@@ -1,7 +1,7 @@
 {
   "name": "veetmanager",
   "productName": "VEET Manager",
-  "version": "2.1.0",
+  "version": "2.1.1",
   "authors": "Meta Platforms, Inc.",
   "main": "packages/main/dist/index.js",
   "license": "SEE LICENSE IN LICENSE",

packages/main/src/MainLogger.ts

@@ -31,6 +31,10 @@ export const RegisterMainLogger = () => {
         new winston.transports.Console(),
         rotatedLog,
       ],
+      format: winston.format.combine(
+        winston.format.timestamp(),
+        winston.format.json(),
+      ),
     }),
   );
 };

packages/main/src/MainWindow.ts

@@ -278,7 +278,11 @@ export class MainWindow {
 
         // On Connection, restart polls
         await this.startDriveSearch();
-        if (!this.isConnected_) { return; }
+        if (!this.isConnected_) {
+          // We disconnected before we could find the drive, so stop looking
+          this.driveRetry_ && clearInterval(this.driveRetry_);
+          return;
+        }
         await this.checkSerialNumber();
         if (!this.isConnected_) { return; }
         await this.startPolls();
@@ -360,7 +364,11 @@ export class MainWindow {
       const drives = await list();
       let found = false;
       for (const drive of drives) {
-        if (drive.description.startsWith(VEET_DRIVE_DESCRIPTION) && drive.mountpoints && drive.mountpoints.length > 0) {
+        if (!drive.description.startsWith(VEET_DRIVE_DESCRIPTION)) {
+          continue;
+        }
+        logger.info(`Found VEET Drive at ${drive.device}, checking mountpoints`);
+        if (drive.mountpoints && drive.mountpoints.length > 0) {
           // Found drive!
           const drivePath = drive.mountpoints[0].path;
           found = true;
@@ -377,6 +385,9 @@ export class MainWindow {
             this.driveRetry_ = null;
           }
           break;
+        } else {
+          logger.info(`No mountpoints found for VEET drive at ${drive.device}`);
+          setDatastoreValue('driveFound', true);
         }
       }
       if (!found) {

packages/main/src/SerialManager.ts

@@ -19,6 +19,9 @@ const TOTAL_TIMEOUT = 1 * 1000; // 1 second should be enough for every command
 const END_OF_TRANSMISSION_DELIMITER = Buffer.from([0x04]); // EOT - 0x04
 const TIME_BEFORE_INFLIGHT_DISPLAY = 100;
 
+const VEET_PRODUCT_ID = '0001';
+const VEET_VENDOR_ID = '04d8';
+
 export enum SerialConnectionStatus {
   UNKNOWN,
   NONE_FOUND,
@@ -63,16 +66,24 @@ export class SerialManager extends EventEmitter {
     if (this.isConnected()) {
       return SerialConnectionStatus.CONNECTED;
     }
+    logger.info('Searching for serial ports');
     const portList = await SerialPort.list();
     if (portList.length == 0) {
       this.connectedPort_ = UnconnectedPort;
       this.connection_ = null;
-      logger.info('Searching for serial ports, none found');
+      logger.info('None found');
       return SerialConnectionStatus.NONE_FOUND;
     } else {
-      logger.info(`Searching for serial ports, ${portList.length} found`);
+      logger.info(`${portList.length} ports found`);
     }
+    let foundValidIDs = false;
     for (const portInfo of portList) {
+      if (portInfo.vendorId?.toLowerCase() != VEET_VENDOR_ID || portInfo.productId != VEET_PRODUCT_ID) {
+        continue;
+      }
+      foundValidIDs = true;
+      logger.info('Found matching product and vendor IDs on port ' + portInfo.path);
+      const startPerf = performance.now();
       logger.info('Attempting to connect to port ' + portInfo.path);
       const connection = new SerialConnection();
       const isReady = await connection.connect(portInfo.path);
@@ -82,14 +93,20 @@ export class SerialManager extends EventEmitter {
         this.connectedPort_ = portInfo.path;
         setDatastoreValue('connectionPort', portInfo.path);
         connection.on('disconnect', this.disconnect);
+        logger.info(`Connected to port ${portInfo.path} in ${Math.ceil(performance.now() - startPerf)}ms`);
         return SerialConnectionStatus.CONNECTED;
       } else {
         // Shouldn't happpen, but if findVeet is called twice there is a race condition
         if (this.isConnected()) {
+          logger.info(`Aborted connecting to port ${portInfo.path} in ${Math.ceil(performance.now() - startPerf)}ms`);
           return SerialConnectionStatus.CONNECTED;
         }
+        logger.info(`Failed to connect to port ${portInfo.path} in ${Math.ceil(performance.now() - startPerf)}ms`);
       }
     }
+    if (!foundValidIDs) {
+      logger.info('No valid product and vendor IDs found');
+    }
     return SerialConnectionStatus.NONE_FOUND;
   };
 

packages/renderer/src/ConnectionStatus.tsx

@@ -23,6 +23,7 @@ export const ConnectionStatus = () => {
   const deviceSide:string|null = useStoreData('deviceSide');
   let researcherID:string|null = useConfigStoreData('researcherID');
   const drivePath = useStoreData('drivePath');
+  const driveFound = useStoreData('driveFound');
 
   // Have we found the drive yet?
   if (!drivePath) {
@@ -45,7 +46,11 @@ export const ConnectionStatus = () => {
    if (researcherID) {
      researcherString = <span data-classes={subHeadingFont}>RESEARCHER_ID: {researcherID}</span>;
    } else {
-     researcherString = <span data-classes={subHeadingFont}>Searching for storage device...</span>;
+     if (driveFound) {
+       researcherString = <span data-classes={subHeadingFont}>Drive found, waiting for OS to mount...</span>;
+     } else {
+       researcherString = <span data-classes={subHeadingFont}>Searching for storage device...</span>;
+     }
    }
  }
 

packages/shared/CalibStore.ts

@@ -70,7 +70,7 @@ export function loadCalibFromJson(calibJson: string, errorHandler?: ErrorMessage
     logger.error('Failed to parse calib', {json: calibJson, parseError: parsed.error});
     return false;
   }
-  logger.info('Success fully loaded calib data');
+  logger.info('Successfully loaded calib data');
   updateCalibStore(parsed.data);
   logger.info(gCalibData);
   return true;

packages/shared/DataStore.ts

@@ -23,6 +23,7 @@ export interface VEETDataStore {
   serialNumber: string|null;
   timeOnVeet: number|null,
   commandInFlight: boolean;
+  driveFound: boolean;
   drivePath: string|null;
   sensorDataFilePath: string|null;
   driveSpaceAvailable: number;
@@ -51,6 +52,7 @@ const initialData: VEETDataStore = deepFreeze({
   serialNumber: null,
   timeOnVeet: null,
   commandInFlight: false,
+  driveFound: false,
   drivePath: null,
   sensorDataFilePath: null,
   driveSpaceAvailable: 0,

packages/shared/SettingsStore.ts

@@ -72,7 +72,7 @@ export function loadSettingsFromJson(settingJson: string, errorHandler?: ErrorMe
     logger.error('Failed to parse settings', {json: settingJson, parseError: parsed.error});
     return;
   }
-  logger.info('Success fully loaded settings data');
+  logger.info('Successfully loaded settings data');
   updateSettingsStore(parsed.data);
   logger.info(gSettingsData);
 }