chore(kboot): add more logging (#1008)

* chore(kboot): add more logging

* fix: add uncaughtException handler

* fix: wait to prevent race condition

* fix: don't close device after success left keyboard connection

* revert: remove extra delay

* revert: add back the waiting

* fix: always initialize new KBoot instance when try to configure I2C

* fix: increase the wait time between 2 IC2 reconnection

* fix: timing and usb reconnection

* fix: dont close kboot device

* feat: append the WithKboot to the firmware upgrade methods

* feat: revert back the blhost functionality

packages/uhk-usb/src/constants.ts

@@ -71,9 +71,9 @@ export enum EnumerationNameToProductId {
 }
 
 export enum ModuleSlotToI2cAddress {
-    leftHalf = 0x10,
-    leftModule = 0x20,
-    rightModule = 0x30
+    leftHalf = '0x10',
+    leftModule = '0x20',
+    rightModule = '0x30'
 }
 
 export enum ModuleSlotToId {

packages/uhk-usb/src/index.ts

@@ -1,4 +1,5 @@
 export * from './constants';
+export * from './uhk-blhost';
 export * from './uhk-hid-device';
 export * from './uhk-operations';
 export * from './util';

packages/uhk-usb/src/uhk-blhost.ts

@@ -0,0 +1,89 @@
+import * as path from 'path';
+import { spawn } from 'child_process';
+import { LogService } from 'uhk-common';
+import { retry } from './util';
+
+export class UhkBlhost {
+    private blhostPath: string;
+
+    constructor(private logService: LogService,
+                private rootDir: string) {
+    }
+
+    public async runBlhostCommand(params: Array<string>): Promise<void> {
+        const self = this;
+        return new Promise<void>((resolve, reject) => {
+            const blhostPath = this.getBlhostPath();
+            self.logService.debug(`[blhost] RUN: ${blhostPath} ${params.join(' ')}`);
+            const childProcess = spawn(`"${blhostPath}"`, params, {shell: true});
+            let finished = false;
+
+            childProcess.stdout.on('data', data => {
+                self.logService.debug(`[blhost] STDOUT: ${data}`);
+            });
+
+            childProcess.stderr.on('data', data => {
+                self.logService.error(`[blhost] STDERR: ${data}`);
+            });
+
+            childProcess.on('close', code => {
+                self.logService.debug(`[blhost] CLOSE_CODE: ${code}`);
+                finish(code);
+            });
+
+            childProcess.on('exit', code => {
+                self.logService.debug(`[blhost] EXIT_CODE: ${code}`);
+                finish(code);
+            });
+
+            childProcess.on('error', err => {
+                self.logService.debug(`[blhost] ERROR: ${err}`);
+            });
+
+            function finish(code) {
+                if (finished) {
+                    return;
+                }
+
+                finished = true;
+
+                self.logService.debug(`[blhost] FINISHED: ${code}`);
+
+                if (code !== 0) {
+                    return reject(new Error(`blhost error code:${code}`));
+                }
+
+                resolve();
+            }
+        });
+    }
+
+    public async runBlhostCommandRetry(params: Array<string>, maxTry = 100): Promise<void> {
+        return await retry(async () => await this.runBlhostCommand(params), maxTry, this.logService);
+    }
+
+    private getBlhostPath(): string {
+        if (this.blhostPath) {
+            return this.blhostPath;
+        }
+
+        let blhostPath;
+        switch (process.platform) {
+            case 'linux':
+                blhostPath = 'linux/x86_64/blhost';
+                break;
+            case 'darwin':
+                blhostPath = 'mac/blhost';
+                break;
+            case 'win32':
+                blhostPath = 'win/blhost.exe';
+                break;
+            default:
+                throw new Error(`Could not find blhost path. Unknown platform:${process.platform}`);
+        }
+
+        this.blhostPath = path.join(this.rootDir, `packages/blhost/${blhostPath}`);
+
+        return this.blhostPath;
+    }
+}

packages/uhk-usb/src/uhk-hid-device.ts

@@ -208,7 +208,7 @@ export class UhkHidDevice {
 
         while (new Date().getTime() - startTime.getTime() < 20000) {
             const devs = devices();
-            this.logService.silly('[UhkHidDevice] reenumeration devices', devs);
+            this.logService.debug('[UhkHidDevice] reenumeration devices', devs);
 
             const inBootloaderMode = devs.some((x: Device) =>
                 x.vendorId === Constants.VENDOR_ID &&
@@ -219,7 +219,7 @@ export class UhkHidDevice {
                 return;
             }
 
-            this.logService.silly(`[UhkHidDevice] Could not find reenumerated device: ${reenumMode}. Waiting...`);
+            this.logService.debug(`[UhkHidDevice] Could not find reenumerated device: ${reenumMode}. Waiting...`);
             await snooze(100);
 
             if (!jumped) {
@@ -232,7 +232,7 @@ export class UhkHidDevice {
                     device.close();
                     jumped = true;
                 } else {
-                    this.logService.silly(`[UhkHidDevice] USB[T]: Enumerate device is not ready yet}`);
+                    this.logService.debug(`[UhkHidDevice] USB[T]: Enumerate device is not ready yet}`);
                 }
             }
         }
@@ -249,7 +249,7 @@ export class UhkHidDevice {
         if (command === KbootCommands.idle) {
             transfer = Buffer.from([UsbCommand.SendKbootCommandToModule, command]);
         } else {
-            transfer = Buffer.from([UsbCommand.SendKbootCommandToModule, command, module]);
+            transfer = Buffer.from([UsbCommand.SendKbootCommandToModule, command, Number.parseInt(module, 16)]);
         }
         await retry(async () => await this.write(transfer), maxTry, this.logService);
     }

packages/uhk-usb/src/uhk-operations.ts

@@ -13,6 +13,7 @@ import {
 import * as path from 'path';
 import * as fs from 'fs';
 import * as os from 'os';
+import { UhkBlhost } from './uhk-blhost';
 import { UhkHidDevice } from './uhk-hid-device';
 import { readBootloaderFirmwareFromHexFileAsync, snooze, waitForDevice } from './util';
 import { ConfigBufferId, convertBufferToIntArray, DevicePropertyIds, getTransferBuffers, UsbCommand } from '../index';
@@ -20,11 +21,67 @@ import { LoadConfigurationsResult } from './models/load-configurations-result';
 
 export class UhkOperations {
     constructor(private logService: LogService,
+                private blhost: UhkBlhost,
                 private device: UhkHidDevice,
                 private rootDir: string) {
     }
 
-    public async updateRightFirmware(firmwarePath = this.getFirmwarePath()) {
+    public async updateRightFirmwareWithBlhost(firmwarePath = this.getFirmwarePath()) {
+        this.logService.debug(`[UhkOperations] Operating system: ${os.type()} ${os.release()} ${os.arch()}`);
+        this.logService.debug('[UhkOperations] Start flashing right firmware');
+        const prefix = [`--usb 0x1d50,0x${EnumerationNameToProductId.bootloader.toString(16)}`];
+
+        await this.device.reenumerate(EnumerationModes.Bootloader);
+        this.device.close();
+        await this.blhost.runBlhostCommand([...prefix, 'flash-security-disable', '0403020108070605']);
+        await this.blhost.runBlhostCommand([...prefix, 'flash-erase-region', '0xc000', '475136']);
+        await this.blhost.runBlhostCommand([...prefix, 'flash-image', `"${firmwarePath}"`]);
+        await this.blhost.runBlhostCommand([...prefix, 'reset']);
+        this.logService.debug('[UhkOperations] Right firmware successfully flashed');
+    }
+
+    public async updateLeftModuleWithBlhost(firmwarePath = this.getLeftModuleFirmwarePath()) {
+        this.logService.debug('[UhkOperations] Start flashing left module firmware');
+
+        const prefix = [`--usb 0x1d50,0x${EnumerationNameToProductId.buspal.toString(16)}`];
+        const buspalPrefix = [...prefix, `--buspal i2c,${ModuleSlotToI2cAddress.leftHalf}`];
+
+        await this.device.reenumerate(EnumerationModes.NormalKeyboard);
+        this.device.close();
+        await snooze(1000);
+        await this.device.sendKbootCommandToModule(ModuleSlotToI2cAddress.leftHalf, KbootCommands.ping, 100);
+        await snooze(1000);
+        await this.device.jumpToBootloaderModule(ModuleSlotToId.leftHalf);
+        this.device.close();
+
+        const leftModuleBricked = await this.waitForKbootIdle();
+        if (!leftModuleBricked) {
+            const msg = '[UhkOperations] Couldn\'t connect to the left keyboard half.';
+            this.logService.error(msg);
+            throw new Error(msg);
+        }
+
+        await this.device.reenumerate(EnumerationModes.Buspal);
+        this.device.close();
+        await this.blhost.runBlhostCommandRetry([...buspalPrefix, 'get-property', '1']);
+        await this.blhost.runBlhostCommand([...buspalPrefix, 'flash-erase-all-unsecure']);
+        await this.blhost.runBlhostCommand([...buspalPrefix, 'write-memory', '0x0', `"${firmwarePath}"`]);
+        await this.blhost.runBlhostCommand([...prefix, 'reset']);
+        await snooze(1000);
+        await this.device.reenumerate(EnumerationModes.NormalKeyboard);
+        this.device.close();
+        await snooze(1000);
+        await this.device.sendKbootCommandToModule(ModuleSlotToI2cAddress.leftHalf, KbootCommands.reset, 100);
+        this.device.close();
+        await snooze(1000);
+        await this.device.sendKbootCommandToModule(ModuleSlotToI2cAddress.leftHalf, KbootCommands.idle);
+        this.device.close();
+
+        this.logService.debug('[UhkOperations] Left firmware successfully flashed');
+        this.logService.debug('[UhkOperations] Both left and right firmwares successfully flashed');
+    }
+
+    public async updateRightFirmwareWithKboot(firmwarePath = this.getFirmwarePath()) {
         this.logService.debug(`[UhkOperations] Operating system: ${os.type()} ${os.release()} ${os.arch()}`);
         this.logService.debug('[UhkOperations] Start flashing right firmware');
 
@@ -58,9 +115,10 @@ export class UhkOperations {
         this.logService.debug('[UhkOperations] Right firmware successfully flashed');
     }
 
-    public async updateLeftModule(firmwarePath = this.getLeftModuleFirmwarePath()) {
+    public async updateLeftModuleWithKboot(firmwarePath = this.getLeftModuleFirmwarePath()) {
         this.logService.debug('[UhkOperations] Start flashing left module firmware');
 
+        const i2cAddressOfLeftModule = Number.parseInt(ModuleSlotToI2cAddress.leftHalf, 16);
         await this.device.reenumerate(EnumerationModes.NormalKeyboard);
         this.device.close();
         await snooze(1000);
@@ -86,28 +144,31 @@ export class UhkOperations {
         while (true) {
             try {
                 this.logService.debug('[UhkOperations] Try to connect to the LEFT keyboard');
-                await kboot.configureI2c(ModuleSlotToI2cAddress.leftHalf);
+                await kboot.configureI2c(i2cAddressOfLeftModule);
                 await kboot.getProperty(Properties.BootloaderVersion);
                 break;
             } catch {
                 if (tryCount > 100) {
                     throw new Error('Can not connect to the LEFT keyboard');
                 }
-            } finally {
-                kboot.close();
+                await snooze(2000);
             }
-            await snooze(100);
             tryCount++;
         }
+
+        // https://github.com/node-hid/node-hid/issues/230
+        this.logService.debug('[UhkOperations] Wait 1 sec to prevent node-hid race condition');
+        await snooze(1000);
+
         this.logService.debug('[UhkOperations] Flash erase all on LEFT keyboard');
-        await kboot.configureI2c(ModuleSlotToI2cAddress.leftHalf);
+        await kboot.configureI2c(i2cAddressOfLeftModule);
         await kboot.flashEraseAllUnsecure();
 
         this.logService.debug('[UhkOperations] Read LEFT firmware from file');
         const configData = fs.readFileSync(firmwarePath);
 
         this.logService.debug('[UhkOperations] Write memory');
-        await kboot.configureI2c(ModuleSlotToI2cAddress.leftHalf);
+        await kboot.configureI2c(i2cAddressOfLeftModule);
         await kboot.writeMemory({ startAddress: 0, data: configData });
 
         this.logService.debug('[UhkOperations] Reset LEFT keyboard');