1712992 - Refactor logging to make use of console.createInstance() instead of Log.sys.mjs

Status: NEW

(Remote Protocol :: Agent, task, P3)

Description

[Henrik Skupin [:whimboo][⌚️UTC+2]]

As we have seen in the past and over on bug 1708532 using Log.jsm is not that e10s friendly and needs to be initialized in each content process. That initialization is time invasive and should be avoided.

As such console.createInstance() could be used, which supports setting a prefix and a maximum level. For Marionette it could look like the following:

const logger = console.createInstance({
  maxLogLevelPref: "remote.log.level",
  prefix: "Marionette",
});

I didn't test that yet but it might need devtools.console.stdout.[chrome|content] set to true so that those log entries also appear on stdout. Sadly all the other chrome logging from other Firefox components will also end-up there so that we hit bug 1399441. By default we don't want to see anything else beside Marionette and soon the Remote Agent.

Comment 1

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Our log module that needs modification is now located at:
https://searchfox.org/mozilla-central/source/remote/shared/Log.sys.mjs

Comment 2

[michael s]

Hi there, I'd like to take on this task!

I see the usages of the Logger in several places in remote/ however I'm a bit confused as to what exactly is changing. Will usage of Log.sys.mjs be deprecated (or at least replaced by) in favor of console.createInstance or is Log.sys.mjs changing? or both? Thanks!

Comment 3

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Hi Michael! I'm glad to see that you have interest working on this bug. So yes, feel free to get started and don't hesitate to ask questions in case of issues. Please note that you can also join us on Matrix in the webdriver channel for a more direct communication.

Regarding your question, the idea here is indeed to replace the usage of the logging module with console.createInstance(). Given that we do not know 100% if all the features that we need will work it might be good to get started with some focused changes and testing. Best might be the Marionette.sys.mjs module which contains code that is run in the parent and content processes. Also it's easy to test by simply starting Firefox with the --marionette argument and variations for --remote.log.level preference values.

Comment 4

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Hi Michael, do you still have interest to work on this bug?

Comment 5

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Looks like this bug is free to be claimed in case someone is interested to work on it.

Comment 6

[Leeya]

Hello! I’m a new contributor, and I’ll be submitting a patch for this bug soon.

Comment 7

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Thanks a lot and a warm welcome! Let me know when there are any questions. You can get in contact with us here or directly in the #webdriver Matrix channel.

Comment 8

[Leeya]

Attachment: Bug 1712992 - Refactor logging to make use of console.createInstance() instead of Log.sys.mjs. r?whimboo!

Comment 9

[Leeya]

Hi Henrik,

I just submitted my patch for review, but I just realized I never asked you if there were any tests beyond what you mentioned in this thread to run. Apologies! If there are, just let me know, and I'll get to them and re-submit my patch.

Comment 10

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Sorry for the late reply but I was out last week and wasn't able to check your patch earlier.

I've taken a look at the patch now and noticed two major changes in logging to stdout:

1. The output format is completely different which most likely will cause issues with post-processing the logs from CI jobs. Also there are no timestamps included which makes it way harder to investigate test failures. Here is how it looks like without and with the patch attached:

> - 1714505684694	Marionette	INFO	Marionette enabled
> + console.info: Marionette: "Marionette enabled"

2. Each log entry now has a stack trace included. That's not something that we want.

For all that I didn't find a way to get it disabled via configuration options. Whether in Console.cpp nor ConsoleService.cpp. So I'm not sure if this change is really something that we could / should do.

Nika, do you have any suggestion for us so that we can get rid of the issue as pointed out in the initial comment, or do we have to keep using the Log.sys.mjs module? Or maybe there is another option as well? thanks.

Comment 11

[Nika Layzell [:nika] (ni? for response)]

I don't know much about JS logging options unfortunately, so I don't know if I can comment much. It might be more useful to reach out to someone more familiar with how this works on the frontend?

Given that you specifically care about the format which Marionette logs to stdout so it can be consumed by tooling, perhaps using a generic logging mechanism like console isn't the best for those messages, and messages specifically intended to be consumed by scripts should be logged using some other mechanism?

Comment 12

[Leeya]

Hi Gijs!

I'm messaging to see if there are other bugs you think would be good for me to work on while this one is being sorted out?

Comment 13

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Thanks Nika for the initial feedback. Maybe Gijs can help us (already needinfo'ed) with the question if there is another way to log messages via the frontend by not using Toolkit's Log.sys.mjs to circumvent the initialization of the class for each and every content process. I actually do not see one at the moment, and maybe we have to leave our logging to what we currently have.

Comment 14

[:Gijs (out for now; he/him)]

(In reply to Nika Layzell [:nika] (ni? for response) from comment #11)

I don't know much about JS logging options unfortunately, so I don't know if I can comment much. It might be more useful to reach out to someone more familiar with how this works on the frontend?

Given that you specifically care about the format which Marionette logs to stdout so it can be consumed by tooling, perhaps using a generic logging mechanism like console isn't the best for those messages, and messages specifically intended to be consumed by scripts should be logged using some other mechanism?

+1 on this - dump() may do what you want here, honestly. That or having console.createInstance with some kind of custom stdout/stderr formatter (which I'm not sure we support right now). Directing this question to Mark who has more context...

(In reply to Leeya from comment #12)

Hi Gijs!

I'm messaging to see if there are other bugs you think would be good for me to work on while this one is being sorted out?

I've left a comment on your patch for whereToOpenLink in order to help unblock you there. Once that has landed, bug 1895490 might be something to look at?

Comment 15

[Mark Banner (:standard8)]

(In reply to :Gijs (he/him) from comment #14)

+1 on this - dump() may do what you want here, honestly. That or having console.createInstance with some kind of custom stdout/stderr formatter (which I'm not sure we support right now). Directing this question to Mark who has more context...

At the moment, I haven't thought too much about the Log.sys.mjs side of things as sorting out console.createInstance and moving the more-similar ConsoleAPI across to it seemed to be the logical first step.

However, from the architecture perspective, what I am thinking is that generally all code should be able to use the general console.* logging mechanism. That's the one that is native and can give us a rich output.

The hand-wavy part currently is how that gets output to stdout or files when we need it. For the browser console it would work via the current mechanism. For stdout/files, I think one way would be to build something into the console service, the other way would be to add listeners to the console service and process the output. This latter option would be similar to the way that mochitests currently work.

The advantage with the latter option is that we could hook in different output handlers depending on what we need, and when they're not there, they aren't affecting the main code. The disadvantage is that we'd probably still need something for logging to files, which is needed in some cases (e.g. bug 1889052).

Some of this depends on the actual requirements for the logging (when it is needed, where it is used), so it might be useful to start with that.