Proposal: add LogFormat static property

A large amount of time spent when maintaining the RxPlayer is actually
spent on debugging device-specific issues.

Consequently, we beefed-up our debugging capabilities: we added a LOT of
logs, developed [our own specialized remote
debugger](https://github.com/canalplus/RxPaired/) so we can be
monitoring low-end devices for a long amount of time (unlike chrome's or
webkit's debugger), developed some reverse-engineering tools as well as
(closed-source) visual logging tools.

Now that we have many tools at our disposition, I see that our regular
logs (that can e.g. be produced by calling `RxPlayer.LogLevel =
"DEBUG"`) - the most relied on way by application developpers - are
lacking.

The most evident lacking data is some kind of timestamp, to better
understand time-related issues, which are frequent.

But more than that, there's a lot of comfort in being able to rely on our
aforementioned RxPaired remote debugger, so I was wondering if we could
allow the production of logs in a format that could be easily imported by
it.

Hence the idea of a supplementary `RxPlayer.LogFormat` property.
It is by default set to `"standard"` - which is the currently-existing
format, but can also be set to the RxPaired-compatible `"full"` format
which:

  - Immediately produces the `[Init]` log, which today only serves to
    provide a way to convert between date representations (date on the
    device or monotonic timestamp since the page was opened) inside
    RxPaired (and also ultimately perform protocol version detection).

  - Prepend each log with a timestamp and the "namespace" of the log
    (e.g. `[error]` for error logs).

Here, we could tell application developpers not only to call:
```js
RxPlayer.LogLevel = "DEBUG";
```

But also:
```js
RxPlayer.LogLevel = "full";
```

When the idea is about communicating logs to us (if they just want to
display logs for initial debugging steps of an issue potentially on
their side or the content's side, the `"standard"` format may be clearer
to them as less verbose).

src/core/main/worker/worker_main.ts

@@ -21,7 +21,7 @@ import type { IPlayerError, ITrackType } from "../../../public_types";
 import createDashPipelines from "../../../transports/dash";
 import arrayFind from "../../../utils/array_find";
 import assert, { assertUnreachable } from "../../../utils/assert";
-import type { ILoggerLevel } from "../../../utils/logger";
+import type { ILogFormat, ILoggerLevel } from "../../../utils/logger";
 import { scaleTimestamp } from "../../../utils/monotonic_timestamp";
 import objectAssign from "../../../utils/object_assign";
 import type { IReadOnlySharedReference } from "../../../utils/reference";
@@ -91,7 +91,11 @@ export default function initializeWorkerMain() {
         assert(!isInitialized);
         isInitialized = true;
         scaleTimestamp(msg.value);
-        updateLoggerLevel(msg.value.logLevel, msg.value.sendBackLogs);
+        updateLoggerLevel(
+          msg.value.logLevel,
+          msg.value.logFormat,
+          msg.value.sendBackLogs,
+        );
         if (msg.value.dashWasmUrl !== undefined && dashWasmParser.isCompatible()) {
           dashWasmParser.initialize({ wasmUrl: msg.value.dashWasmUrl }).catch((err) => {
             const error = err instanceof Error ? err.toString() : "Unknown Error";
@@ -115,7 +119,11 @@ export default function initializeWorkerMain() {
         break;
 
       case MainThreadMessageType.LogLevelUpdate:
-        updateLoggerLevel(msg.value.logLevel, msg.value.sendBackLogs);
+        updateLoggerLevel(
+          msg.value.logLevel,
+          msg.value.logFormat,
+          msg.value.sendBackLogs,
+        );
         break;
 
       case MainThreadMessageType.PrepareContent:
@@ -883,11 +891,17 @@ function loadOrReloadPreparedContent(
   }
 }
 
-function updateLoggerLevel(logLevel: ILoggerLevel, sendBackLogs: boolean): void {
+function updateLoggerLevel(
+  logLevel: ILoggerLevel,
+  logFormat: ILogFormat,
+  sendBackLogs: boolean,
+): void {
   if (!sendBackLogs) {
-    log.setLevel(logLevel);
+    log.setLevel(logLevel, logFormat);
   } else {
-    log.setLevel(logLevel, (levelStr, logs) => {
+    // Here we force the log format to "standard" as the full formatting will be
+    // performed on main thread.
+    log.setLevel(logLevel, "standard", (levelStr, logs) => {
       const sentLogs = logs.map((e) => {
         if (e instanceof Error) {
           return formatErrorForSender(e);

src/experimental/tools/mediaCapabilitiesProber/api/index.ts

@@ -58,7 +58,7 @@ const mediaCapabilitiesProber = {
    * @param {string} level
    */
   set LogLevel(level: string) {
-    log.setLevel(level);
+    log.setLevel(level, log.getFormat());
   },
 
   /**

src/index.ts

@@ -56,9 +56,9 @@ Player.addFeatures([
   HTML_SRT_PARSER,
 ]);
 if (isDebugModeEnabled()) {
-  logger.setLevel("DEBUG");
+  logger.setLevel("DEBUG", "standard");
 } else if ((__ENVIRONMENT__.CURRENT_ENV as number) === (__ENVIRONMENT__.DEV as number)) {
-  logger.setLevel(__LOGGER_LEVEL__.CURRENT_LEVEL);
+  logger.setLevel(__LOGGER_LEVEL__.CURRENT_LEVEL, "standard");
 }
 export default Player;
 

src/main_thread/api/public_api.ts

@@ -322,7 +322,21 @@ class Player extends EventEmitter<IPublicAPIEvent> {
     return log.getLevel();
   }
   static set LogLevel(logLevel: string) {
-    log.setLevel(logLevel);
+    log.setLevel(logLevel, log.getFormat());
+  }
+
+  /**
+   * Current log format.
+   * Should be either (by verbosity ascending):
+   *   - "standard": Regular log messages.
+   *   - "full": More verbose format, including a timestamp and a namespace.
+   * Any other value will be translated to "standard".
+   */
+  static get LogFormat(): string {
+    return log.getFormat();
+  }
+  static set LogFormat(format: string) {
+    log.setLevel(log.getLevel(), format);
   }
 
   /**
@@ -531,6 +545,7 @@ class Player extends EventEmitter<IPublicAPIEvent> {
         value: {
           dashWasmUrl: workerSettings.dashWasmUrl,
           logLevel: log.getLevel(),
+          logFormat: log.getFormat(),
           sendBackLogs: isDebugModeEnabled(),
           date: Date.now(),
           timestamp: getMonotonicTimeStamp(),
@@ -540,15 +555,16 @@ class Player extends EventEmitter<IPublicAPIEvent> {
       });
       log.addEventListener(
         "onLogLevelChange",
-        (logLevel) => {
+        (logInfo) => {
           if (this._priv_worker === null) {
             return;
           }
           log.debug("---> Sending To Worker:", MainThreadMessageType.LogLevelUpdate);
           this._priv_worker.postMessage({
             type: MainThreadMessageType.LogLevelUpdate,
             value: {
-              logLevel,
+              logLevel: logInfo.level,
+              logFormat: logInfo.format,
               sendBackLogs: isDebugModeEnabled(),
             },
           });

src/minimal.ts

@@ -36,9 +36,9 @@ patchWebkitSourceBuffer();
 features.codecSupportProber = MainCodecSupportProber;
 
 if (isDebugModeEnabled()) {
-  logger.setLevel("DEBUG");
+  logger.setLevel("DEBUG", "standard");
 } else if ((__ENVIRONMENT__.CURRENT_ENV as number) === (__ENVIRONMENT__.DEV as number)) {
-  logger.setLevel(__LOGGER_LEVEL__.CURRENT_LEVEL);
+  logger.setLevel(__LOGGER_LEVEL__.CURRENT_LEVEL, "standard");
 }
 
 /**

src/multithread_types.ts

@@ -30,7 +30,7 @@ import type {
 import type { IFreezingStatus, IRebufferingStatus } from "./playback_observer";
 import type { ITrackType } from "./public_types";
 import type { ITransportOptions } from "./transports";
-import type { ILoggerLevel } from "./utils/logger";
+import type { ILogFormat, ILoggerLevel } from "./utils/logger";
 import type { IRange } from "./utils/ranges";
 
 /**
@@ -65,6 +65,12 @@ export interface IInitMessage {
     hasMseInWorker: boolean;
     /** Initial logging level that should be set. */
     logLevel: ILoggerLevel;
+    /** Intitial logger's log format that should be set. */
+    logFormat: ILogFormat;
+    /**
+     * If `true`, logs should be sent back to the main thread, through a
+     * `ILogMessageWorkerMessage` message.
+     */
     sendBackLogs: boolean;
     /**
      * Value of `Date.now()` at the time the `timestamp` property was generated.
@@ -138,6 +144,12 @@ export interface ILogLevelUpdateMessage {
   value: {
     /** The new logger level that should be set. */
     logLevel: ILoggerLevel;
+    /** Intitial logger's log format that should be set. */
+    logFormat: ILogFormat;
+    /**
+     * If `true`, logs should be sent back to the main thread, through a
+     * `ILogMessageWorkerMessage` message.
+     */
     sendBackLogs: boolean;
   };
 }

src/utils/__tests__/logger.test.ts

@@ -22,52 +22,57 @@ describe("utils - Logger", () => {
     expect(logger.getLevel()).toEqual("NONE");
   });
 
+  it('should set a default logger format of "standard"', () => {
+    const logger = new Logger();
+    expect(logger.getFormat()).toEqual("standard");
+  });
+
   it('should be able to change the logger level to "ERROR"', () => {
     const logger = new Logger();
-    logger.setLevel("ERROR");
+    logger.setLevel("ERROR", "standard");
     expect(logger.getLevel()).toEqual("ERROR");
   });
 
   it('should be able to change the logger level to "WARNING"', () => {
     const logger = new Logger();
-    logger.setLevel("WARNING");
+    logger.setLevel("WARNING", "standard");
     expect(logger.getLevel()).toEqual("WARNING");
   });
 
   it('should be able to change the logger level to "INFO"', () => {
     const logger = new Logger();
-    logger.setLevel("INFO");
+    logger.setLevel("INFO", "standard");
     expect(logger.getLevel()).toEqual("INFO");
   });
 
   it('should be able to change the logger level to "DEBUG"', () => {
     const logger = new Logger();
-    logger.setLevel("DEBUG");
+    logger.setLevel("DEBUG", "standard");
     expect(logger.getLevel()).toEqual("DEBUG");
   });
 
   it("should be able to update the logger level multiple times", () => {
     const logger = new Logger();
-    logger.setLevel("DEBUG");
+    logger.setLevel("DEBUG", "standard");
     expect(logger.getLevel()).toEqual("DEBUG");
-    logger.setLevel("WARNING");
+    logger.setLevel("WARNING", "standard");
     expect(logger.getLevel()).toEqual("WARNING");
-    logger.setLevel("ERROR");
+    logger.setLevel("ERROR", "standard");
     expect(logger.getLevel()).toEqual("ERROR");
-    logger.setLevel("INFO");
+    logger.setLevel("INFO", "standard");
     expect(logger.getLevel()).toEqual("INFO");
-    logger.setLevel("WARNING");
+    logger.setLevel("WARNING", "standard");
     expect(logger.getLevel()).toEqual("WARNING");
-    logger.setLevel("ERROR");
+    logger.setLevel("ERROR", "standard");
     expect(logger.getLevel()).toEqual("ERROR");
   });
 
   it('should default unrecognized logger levels to "NONE"', () => {
     const logger = new Logger();
-    logger.setLevel("TOTO");
+    logger.setLevel("TOTO", "standard");
     expect(logger.getLevel()).toEqual("NONE");
-    logger.setLevel("DEBUG"); // initialize to another thing than "NONE"
-    logger.setLevel("TITI");
+    logger.setLevel("DEBUG", "standard"); // initialize to another thing than "NONE"
+    logger.setLevel("TITI", "standard");
     expect(logger.getLevel()).toEqual("NONE");
   });
 
@@ -103,7 +108,7 @@ describe("utils - Logger", () => {
     const mockDebug = vi.spyOn(console, "debug").mockImplementation(vi.fn());
 
     const logger = new Logger();
-    logger.setLevel("ERROR");
+    logger.setLevel("ERROR", "standard");
     logger.error("test");
     logger.warn("test");
     logger.info("test");
@@ -128,7 +133,7 @@ describe("utils - Logger", () => {
     const mockDebug = vi.spyOn(console, "debug").mockImplementation(vi.fn());
 
     const logger = new Logger();
-    logger.setLevel("WARNING");
+    logger.setLevel("WARNING", "standard");
     logger.error("test");
     logger.warn("test");
     logger.info("test");
@@ -153,7 +158,7 @@ describe("utils - Logger", () => {
     const mockDebug = vi.spyOn(console, "debug").mockImplementation(vi.fn());
 
     const logger = new Logger();
-    logger.setLevel("INFO");
+    logger.setLevel("INFO", "standard");
     logger.error("test");
     logger.warn("test");
     logger.info("test");
@@ -178,7 +183,7 @@ describe("utils - Logger", () => {
     const mockDebug = vi.spyOn(console, "debug").mockImplementation(vi.fn());
 
     const logger = new Logger();
-    logger.setLevel("DEBUG");
+    logger.setLevel("DEBUG", "standard");
     logger.error("test");
     logger.warn("test");
     logger.info("test");
@@ -194,4 +199,6 @@ describe("utils - Logger", () => {
     mockInfo.mockRestore();
     mockDebug.mockRestore();
   });
+
+  // TODO format unit tests
 });