Skip to content

Commit

Permalink
Proposal: add LogFormat static property
Browse files Browse the repository at this point in the history
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).
  • Loading branch information
peaBerberian committed Jun 25, 2024
1 parent a9c6b54 commit b980ea0
Show file tree
Hide file tree
Showing 9 changed files with 327 additions and 45 deletions.
21 changes: 21 additions & 0 deletions doc/api/Static_Properties.md
Original file line number Diff line number Diff line change
Expand Up @@ -42,6 +42,27 @@ import RxPlayer from "rx-player";
RxPlayer.LogLevel = "WARNING";
```

## LogFormat

Allows to configure the format log messages will have.

Can be set to either:

- `"standard"`: Regular log messages will be printed, this is the default format.

- `"full"`: Log messages will be enriched with timestamps and namespaces, which
allows them to be easier to programatically exploit.

You may for example prefer that format when reporting issues to the RxPlayer's
maintainers, so we are able to extract more information from those logs.

### Example

```js
import RxPlayer from "rx-player";
RxPlayer.LogFormat = "full";
```

## ErrorTypes

The different "types" of Error you can get on playback error,
Expand Down
26 changes: 20 additions & 6 deletions src/core/main/worker/worker_main.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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";
Expand Down Expand Up @@ -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";
Expand All @@ -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:
Expand Down Expand Up @@ -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);
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -58,7 +58,7 @@ const mediaCapabilitiesProber = {
* @param {string} level
*/
set LogLevel(level: string) {
log.setLevel(level);
log.setLevel(level, log.getFormat());
},

/**
Expand Down
4 changes: 2 additions & 2 deletions src/index.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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;

Expand Down
22 changes: 19 additions & 3 deletions src/main_thread/api/public_api.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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);
}

/**
Expand Down Expand Up @@ -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(),
Expand All @@ -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(),
},
});
Expand Down
4 changes: 2 additions & 2 deletions src/minimal.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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");
}

/**
Expand Down
14 changes: 13 additions & 1 deletion src/multithread_types.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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";

/**
Expand Down Expand Up @@ -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.
Expand Down Expand Up @@ -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;
};
}
Expand Down
Loading

0 comments on commit b980ea0

Please sign in to comment.