feat: new log system and record logs from LLD internal thread (#4709)

`ledgerjs/logs`:
* new `trace` and `LocalTracer` definitions, without breaking the behavior of the existing `log` function

`hw-transport`, `hw-transport-node-hid-noevents`, `hw-transport-node-hid-singleton`, `react-native-hw-transport-ble`, `ledger-live-common` 
* Usage of new tracing system in some transports
* The tracing helps keeping a context (for ex a `job id`) that is propagated to other logs, creating a (simple) tracing span

Note on the "tracing": for now added a simple "context" that is propagated from `withDevice` to called functions, mainly from Transport. This is a preview of what could be done to have a real tracing system in the DeviceSDK

Note: the optional `openTimeoutMs` on the different `open` function is necessary for legacy (used by one of the Transport), and will actually be used in the future.

LLD:
* Logs from the `internal` thread are forwarded to the `main` thread
* The `main` thread records them, and can export them
  * on export, recorded logs from the `renderer` thread are sent to the `main` thread, and the `main` thread expand (not a merge, just pushed at the end) them with the logs it recorded from the `internal` thread
* If `VERBOSE` env var is set, filtered logs can be stdout from the main thread
  * Same from the `renderer` thread
* Setup simple tracing system (context) on LLD

LLM:
* Setup simple tracing system on LLM with context
* If `VERBOSE` env var is set, filtered logs can be stdout from the main thread

.changeset/lazy-months-smash.md

@@ -0,0 +1,11 @@
+---
+"ledger-live-desktop": patch
+---
+
+feat: enable printing logs to stdout for debug and record logs from internal thread
+
+- Logs from the internal thread are forward to the main thread
+- The main thread records them, and can export them
+- If `VERBOSE` env var is set, filtered logs can be stdout from the main thread
+- Same from the renderer thread
+- Setup simple tracing system (context) on LLD

.changeset/little-squids-repair.md

@@ -0,0 +1,7 @@
+---
+"@ledgerhq/logs": minor
+---
+
+feat: new trace and LocalTracer definition
+
+Without breaking the behavior of the existing log function

.changeset/purple-chefs-hear.md

@@ -0,0 +1,9 @@
+---
+"live-mobile": patch
+"@ledgerhq/live-env": patch
+---
+
+feat: enable printing logs to stdout for debug
+
+- Setup simple tracing system on LLM with context
+- If `VERBOSE` env var is set, filtered logs can be stdout from the main thread

.changeset/thirty-coats-dance.md

@@ -0,0 +1,12 @@
+---
+"@ledgerhq/hw-transport-node-hid-singleton": minor
+"@ledgerhq/hw-transport-node-hid-noevents": minor
+"@ledgerhq/react-native-hw-transport-ble": minor
+"@ledgerhq/hw-transport": minor
+"@ledgerhq/live-common": patch
+---
+
+feat: usage of new tracing system
+
+The tracing helps keeping a context (for ex a `job id`) that is propagated to other logs,
+creating a (simple) tracing span

apps/ledger-live-desktop/src/internal/live-common-setup.ts

@@ -7,13 +7,22 @@ import { retry } from "@ledgerhq/live-common/promise";
 import TransportNodeHidSingleton from "@ledgerhq/hw-transport-node-hid-singleton";
 import TransportHttp from "@ledgerhq/hw-transport-http";
 import { DisconnectedDevice } from "@ledgerhq/errors";
+import { TraceContext, listen as listenLogs } from "@ledgerhq/logs";
+import { ForwardToMainLogger } from "./logger";
 
 /* eslint-disable guard-for-in */
 for (const k in process.env) {
   setEnvUnsafe(k, process.env[k]);
 }
 /* eslint-enable guard-for-in */
 
+const forwardToMainLogger = ForwardToMainLogger.getLogger();
+
+// Listens to logs from the internal threads, and forwards them to the main thread
+listenLogs(log => {
+  forwardToMainLogger.log(log);
+});
+
 setErrorRemapping(e => {
   // NB ideally we should solve it in ledgerjs
   if (e && e.message && e.message.indexOf("HID") >= 0) {
@@ -31,8 +40,8 @@ if (getEnv("DEVICE_PROXY_URL")) {
 } else {
   registerTransportModule({
     id: "hid",
-    open: () =>
-      retry(() => TransportNodeHidSingleton.open(), {
+    open: (id: string, timeoutMs?: number, context?: TraceContext) =>
+      retry(() => TransportNodeHidSingleton.open(id, timeoutMs, context), {
         maxRetry: 4,
       }),
     disconnect: () => Promise.resolve(),

apps/ledger-live-desktop/src/internal/logger.ts

@@ -0,0 +1,31 @@
+import { Log } from "@ledgerhq/logs";
+
+/**
+ * Simple logger sending recorded logs directly to the main process
+ *
+ * Usage: records logs coming from `@ledgerhq/logs` in the internal thread
+ *
+ * If performance issues are seen because of this direct send to the main process, several ideas could be implemented:
+ * - a filtering on the `type` (or/and a level if it is implemented in `@ledgerhq/logs`) set from an env variable
+ * - a `bulkLog` that records logs until a given threshold, and send them to the main process when reached
+ */
+export class ForwardToMainLogger {
+  private static instance: ForwardToMainLogger | undefined;
+
+  // Simple singleton factory
+  static getLogger() {
+    if (!ForwardToMainLogger.instance) {
+      ForwardToMainLogger.instance = new ForwardToMainLogger();
+    }
+    return ForwardToMainLogger.instance;
+  }
+
+  // We could have a "log:bulk-log"
+  log(log: Log) {
+    process?.send?.({
+      type: "log:log",
+      data: log,
+      requestId: "log", // Not used
+    });
+  }
+}

apps/ledger-live-desktop/src/main/index.ts

@@ -1,7 +1,7 @@
 // eslint-disable-next-line @typescript-eslint/no-var-requires
 require("@electron/remote/main").initialize();
 
-import "./setup";
+import "./setup"; // Needs to be imported first
 import { app, Menu, ipcMain, session, webContents, shell, BrowserWindow } from "electron";
 import Store from "electron-store";
 import menu from "./menu";

apps/ledger-live-desktop/src/main/internal-lifecycle.ts

@@ -14,23 +14,31 @@ import {
   transportListenUnsubscribeChannel,
 } from "~/config/transportChannels";
 import { Message as ToInternalMessage } from "~/internal/types";
+import { ConsoleLogger, InMemoryLogger, isALog } from "./logger";
 
 // ~~~
 
 const LEDGER_CONFIG_DIRECTORY = app.getPath("userData");
 const HOME_DIRECTORY = app.getPath("home");
-const internal = new InternalProcess({
-  timeout: 3000,
-});
 let sentryEnabled: boolean | null = null;
 let userId: string | null = null;
 let sentryTags: string | null = null;
+
+const internal = new InternalProcess({
+  timeout: 3000,
+});
+
+const inMemoryLogger = InMemoryLogger.getLogger();
+const consoleLogger = ConsoleLogger.getLogger();
+
 export function getSentryEnabled(): boolean | null {
   return sentryEnabled;
 }
+
 export function setUserId(id: string) {
   userId = id;
 }
+
 ipcMain.handle("set-sentry-tags", (event, tags) => {
   setTags(tags);
   const tagsJSON = JSON.stringify(tags);
@@ -40,6 +48,7 @@ ipcMain.handle("set-sentry-tags", (event, tags) => {
     tagsJSON,
   });
 });
+
 const spawnCoreProcess = () => {
   const env = {
     ...getAllEnvs(),
@@ -52,31 +61,50 @@ const spawnCoreProcess = () => {
     INITIAL_SENTRY_ENABLED: String(!!sentryEnabled),
     SENTRY_USER_ID: userId,
   };
+
   internal.configure(path.resolve(__dirname, "main.bundle.js"), [], {
     silent: true,
     // @ts-expect-error Some envs are not typed as strings…
     env,
+    // Passes a list of env variables set on `LEDGER_INTERNAL_ARGS` to the internal thread
     execArgv: (process.env.LEDGER_INTERNAL_ARGS || "").split(/[ ]+/).filter(Boolean),
   });
   internal.start();
 };
+
 internal.onStart(() => {
   internal.process?.on("message", handleGlobalInternalMessage);
 });
+
 app.on("window-all-closed", async () => {
   if (internal.active) {
     await internal.stop();
   }
   app.quit();
 });
+
 ipcMain.on("clean-processes", async () => {
   if (internal.active) {
     await internal.stop();
   }
   spawnCoreProcess();
 });
+
 const ongoing: Record<string, Electron.IpcMainEvent> = {};
+
+// Sets up callback on messages coming from the internal process
 internal.onMessage(message => {
+  if (message.type === "log:log") {
+    if (!message.data || !isALog(message.data)) {
+      console.error(`Log not in correct format: ${JSON.stringify(message.data)}`);
+    } else {
+      inMemoryLogger.log(message.data);
+      consoleLogger.log(message.data);
+    }
+
+    return;
+  }
+
   const event = ongoing[message.requestId];
   if (event) {
     event.reply("command-event", message);
@@ -85,6 +113,7 @@ internal.onMessage(message => {
     }
   }
 });
+
 internal.onExit((code, signal, unexpected) => {
   if (unexpected) {
     Object.keys(ongoing).forEach(requestId => {
@@ -154,7 +183,13 @@ ipcMain.on("internalCrashTest", () => {
 });
 ipcMain.on("setEnv", async (event, env) => {
   const { name, value } = env;
+
   if (setEnvUnsafe(name, value)) {
+    // Enables updating at runtime the settings of logs printed on stdout
+    if (name === "VERBOSE") {
+      consoleLogger.refreshSetup();
+    }
+
     if (isRestartNeeded(name)) {
       if (internal.active) {
         await internal.stop();
@@ -169,7 +204,9 @@ ipcMain.on("setEnv", async (event, env) => {
   }
 });
 
-// route internal process messages to renderer
+// Routes a (request) message from the renderer process to the internal process,
+// and sets a handler to receive the response from the internal thread and reply it to the renderer process
+// Only 1 response from the internal process is expected.
 const internalHandlerPromise = (channel: string) => {
   ipcMain.on(channel, (event, { data, requestId }) => {
     const replyChannel = `${channel}_RESPONSE_${requestId}`;
@@ -198,7 +235,8 @@ const internalHandlerPromise = (channel: string) => {
   });
 };
 
-// multi event version of internalHandler
+// Multi event version of internalHandlerPromise:
+// Several response from the internal process can be expected
 const internalHandlerObservable = (channel: string) => {
   ipcMain.on(channel, (event, { data, requestId }) => {
     const replyChannel = `${channel}_RESPONSE_${requestId}`;
@@ -230,7 +268,8 @@ const internalHandlerObservable = (channel: string) => {
   });
 };
 
-// simple event routing
+// Only routes a (request) message from the renderer process to the internal process
+// No response from the internal process is expected.
 const internalHandlerEvent = (channel: string) => {
   ipcMain.on(channel, (event, { data, requestId }) => {
     internal.send({
@@ -240,6 +279,7 @@ const internalHandlerEvent = (channel: string) => {
     } as ToInternalMessage);
   });
 };
+
 internalHandlerPromise(transportOpenChannel);
 internalHandlerPromise(transportExchangeChannel);
 internalHandlerPromise(transportCloseChannel);