Skip to content

Conversation

@peaBerberian
Copy link
Collaborator

@peaBerberian peaBerberian commented Jul 22, 2025

This is a proposal to add a little "formalization" for our logs, as those became our central focus for debugging complex issues.

BEFORE:
image
image
image
image

AFTER:
image
(namespace is now mse to make it clear this is about the MSE API, values appended are clearly identified)
image
(namespace is now SF for "segment fetching" as this is what it is about, here also values are clear)
image
(values are clearly identified here)
image
(values are more formalized than before, with the key=value format of the others, though here keys are very briefs to reduce verbosity, me may document those key names somewhere)

There's already an implicit log API we have to maintain as we rely on a given format in our RxPaired live debugger but this was just enforced by not changing too much the lready-present logs.

We also noticed that multiple partners outside of canal+ were using RxPaired and looking at our logs for debugging on their side first.


Consequently I tried a strategy which attempts to:

  • Facilitate the readability of our logs by people relying on the RxPlayer. This is here done in two ways:

    1. The "namespace" (first part of the log, before :) has to be taken from a smallish list of authorized namespaces, enforced by TypeScript. E.g. ABR for adaptive, DRM for decryption, mse for MSE-linked code, SF for segment fetching code etc.

      The end idea would even to add clear documentation for those namespaces so that people using the RxPlayer have a vague idea of what the various messages we log are about.

      It also helps by enforcing more stability (NOTE: I do not consider the namespace as part of our API, but we should always have a very good reason to break it) for external tools exploiting those.

    2. When there's data associated with the log, it was previously just appended to the message without description (e.g. some numbers after a vague message about ABR).

      Now the preferred syntax is under a JS Object which is then written as key1=value1 key2=value2 In our log messages. This helps people (including us here :p) quicly understand what those values are about.

  • Try to put some more stability in our log for our external tools like RxPaired, through the same aforementioned strategies


The main downside I see is that adding logs needs a little more looking around to get the namespace and format right.

Thoughts?

@peaBerberian peaBerberian force-pushed the some-log-refacto branch 17 times, most recently from 07b58b4 to f18bd25 Compare July 28, 2025 23:16
peaBerberian added a commit to canalplus/RxPaired that referenced this pull request Jul 29, 2025
We recently work in the RxPlayer toward more "formalized" logs:
canalplus/rx-player#1717

This PR changes some logs and consequently might break some of
RxPaired's "log processors".

I've updated them in two ways:

1. I've made them less resilient but supporting both the older and newer
   syntax more explicitly. This both to help avoiding false positives
   (other logs being processed by mistake) and to improve perf (e.g.
   by checking that a log begins by some specific string before further
   processing).

2. I now filter the timestamp and log severity (e.g. "warn", "info" etc. before
   calling the log processor, so the "log line" is just the log itself,
   making it easier to process)
This is a Work-In-Progress and a proposal to add a little "formalization"
for our logs, as those became our central focus for debugging complex
issues.

There's already an implicit log API we have to maintain as we rely on a
given format in our [RxPaired](https://github.com/canalplus/RxPaired)
live debugger but this was just enforced by not changing too much the
lready-present logs.

We also noticed that multiple partners outside of canal+ where using
RxPaired and looking at our logs for debugging on their side first.

---

Consequently I tried a strategy which attempts to:

- Facilitate the readability of our logs by people relying on the
  RxPlayer. This is here done in two ways:

  1. The "namespace" (first part of the log, before `:`) has to be taken
     from a smallish list of authorized namespaces, enforced by
     TypeScript. E.g. `ABR` for adaptive, `DRM` for decryption, `mse`
     for MSE-linked code, `SF` for segment fetching code etc.

     The end idea would even to allow clear documentation for those
     namespaces so that people using the RxPlayer have a vague idea of
     what the various messages we log are about.

     It also helps by enforcing more stability (NOTE: I do not consider
     the namespace as part of our API, but we should always have a very
     good reason to break it) for external tools exploiting those.

  2. When there's data associated with the log, it was previously just
     appended to the message without description (e.g. some numbers
     after a vague message about ABR).

     Now the preferred syntax is under a JS Object which is then written
     as `key1=value1 key2=value2` In our log messages. This helps
     people (including us here :p) quicly understand what those values
     are about.

- Try to put some more stability in our log for our external tools like
  RxPaired, through the same aforementioned strategies

---

The main downside I see is that adding logs needs a little more looking
around to get the namespace and format right.

Thoughts?
@github-actions
Copy link

github-actions bot commented Aug 1, 2025

✅ Automated performance checks have passed on commit d1562b4dd736524e0f13740e8847c7ba8c86d030 with the base branch dev.

Details

Performance tests 1st run output

No significative change in performance for tests:

Name Mean Median
loading 20.48ms -> 20.75ms (-0.262ms, z: 1.89646) 28.35ms -> 28.50ms
seeking 23.33ms -> 16.60ms (6.736ms, z: 1.06796) 11.10ms -> 11.10ms
audio-track-reload 26.65ms -> 26.81ms (-0.157ms, z: 0.66839) 39.15ms -> 39.15ms
cold loading multithread 47.60ms -> 47.35ms (0.246ms, z: 6.52117) 70.50ms -> 69.75ms
seeking multithread 55.76ms -> 65.15ms (-9.396ms, z: 0.78348) 10.05ms -> 10.05ms
audio-track-reload multithread 26.31ms -> 26.58ms (-0.265ms, z: 1.82958) 38.85ms -> 38.85ms
hot loading multithread 16.13ms -> 16.08ms (0.048ms, z: 1.06973) 23.40ms -> 23.25ms

@canalplus canalplus deleted a comment from github-actions bot Aug 1, 2025
@peaBerberian peaBerberian merged commit f78710e into dev Aug 19, 2025
10 checks passed
@peaBerberian peaBerberian added this to the 4.4.0 milestone Aug 19, 2025
peaBerberian added a commit that referenced this pull request Sep 22, 2025
I noticed an issue on our not-yet-released future RxPlayer version where
it would not show payload of logs from our worker, when the global
`__RX_PLAYER_DEBUG_MODE__` was set to true (this unlocks our "debug mode",
it is mainly used by [RxPaired](https://github.com/canalplus/RxPaired)).

In that mode only, all worker logs are sent back to the main thread (to
group all RxPlayer logs in a common JS realm -> much easier to debug).

Since \#1717, the format of those logs changed but were not properly
handled by the main thread.

I fixed that here. There was a remaining issue for `Error` instances,
the only "complex" type that may be set as a log payload, because we
have to do serializing and deserializing steps after detecting that
a payload seems to be a serialized error (this is done with duck typing
for now). Most of the code here is linked to this situation.
peaBerberian added a commit that referenced this pull request Sep 29, 2025
I noticed an issue on our not-yet-released future RxPlayer version where
it would not show payload of logs from our worker, when the global
`__RX_PLAYER_DEBUG_MODE__` was set to true (this unlocks our "debug mode",
it is mainly used by [RxPaired](https://github.com/canalplus/RxPaired)).

In that mode only, all worker logs are sent back to the main thread (to
group all RxPlayer logs in a common JS realm -> much easier to debug).

Since \#1717, the format of those logs changed but were not properly
handled by the main thread.

I fixed that here. There was a remaining issue for `Error` instances,
the only "complex" type that may be set as a log payload, because we
have to do serializing and deserializing steps after detecting that
a payload seems to be a serialized error (this is done with duck typing
for now). Most of the code here is linked to this situation.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants