Frame script log entries not limited by MarionettePrefs.logLevel

RESOLVED FIXED in Firefox 63

Status

defect
P1
normal
RESOLVED FIXED
Last year
Last year

People

(Reporter: ato, Assigned: ato)

Tracking

Trunk
mozilla63
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox63 fixed)

Details

Attachments

(2 attachments, 5 obsolete attachments)

It was discovered in https://github.com/web-platform-tests/wpt/issues/12166
that Marionette had started emitting a lot of logs.  The working
theory was that Marionette and/or geckodriver was misconfigured,
but upon further investigation it looks like log entries in the
frame script (testing/marionette/listener.js) is not limited by the
log level set in the marionette.log.level preference.

This is very likely a regression from
https://bugzilla.mozilla.org/show_bug.cgi?id=1464469.
Log.repository.getLoggerWithMessagePrefix is defined as Proxy, which
probably means the set log level in MarionetteLog#get() is not
properly inherited.
Assignee: nobody → ato
Status: NEW → ASSIGNED
Depends on: 1464469
Priority: -- → P1
The actual problem is that the Marionette:Log entry in the
initialProcessData dictionary is set to {level: logger.level} and
later the full object is assigned to Logger#level=().  The simple
fix is to extract the level field so the correct logger level is
set (and possibly to add a type check to Log.jsm).

However, the better option is to use Logger#managerLevelFromPref.
Unfortunately it expects the preference value to be exactly one of
Log.Level’s fields, e.g. "Info", "Debug", "Trace", &c.
mossop: Would you accept a patch to Log.jsm making the value of the
preference controlling the logger verbosity case-insensitive?
Flags: needinfo?(dtownsend)
If Logger#manageLevelFromPref allowed the preference value to be
case-insensitive we could do away with most of what is in
https://searchfox.org/mozilla-central/source/testing/marionette/log.js,
especially the child process specialisation of Log.jsm and the use
of Services.ppmm.initialProcessData.
This patch makes the value used to control a logger's verbosity or
level case-insensitive.

Previously only log levels listed as primary fields of Log.Level,
such as "Info", "Debug", and "Trace" could be used.  Following this
change, input such as "info", "INFO", "iNfO" is accepted.
Now that Log.jsm supports tracking case-insensitive preference
verbosity level values, we can use Log#manageLevelFromPref to get
right Marionette verbosity.

This has the advantage that we do not have to roll separate
implementations of Log for the child- and parent processes.  It also
has the upside that the log level will be reflected when changed
at runtime through the use of an observer.
I'm not keen to make any changes to Log.jsm these days but maybe. I don't really understand the context though. Why can't you use the correct case in the pref?
Flags: needinfo?(dtownsend)
(In reply to Dave Townsend [:mossop] from comment #8)

> I'm not keen to make any changes to Log.jsm these days but
> maybe. I don't really understand the context though. Why can't you
> use the correct case in the pref?

The input comes from developers who use the moz:firefoxOptions
configuration object with geckodriver.  geckodriver then writes this
value to the marionette.log.level preference.  I suppose it’s not
impossible for us to implement a case conversion in geckodriver.

If you would prefer that to making a change to Log.jsm, then we can
do that.
Comment on attachment 8999617 [details] [diff] [review]
Make Logger#manageLevelFromPref case-insensitive.

Review of attachment 8999617 [details] [diff] [review]:
-----------------------------------------------------------------

Seems safe enough
Attachment #8999617 - Flags: review+
In order to facilitate the use of Log.jsm's Logger#manageLevelFromPref,
geckodriver needs to ensure that the input value for the
marionette.log.level preference conforms to the variants in the
Log.Level enum.

This patch implements the Into<T> conversion from geckodriver's
logging::Level into mozprofile::preferences::Pref by way of a new
function to_gecko(), that ensures the preference value is correctly
formatted.

Logger#manageLevelFromPref expects a string value such as "Info",
which exactly matches Log.Level's own properties.  It is in other
words case sensitive, and this ensures that Marionette no longer
has to case convert the input data.
Attachment #8999962 - Flags: review?(hskupin)
Attachment #8999617 - Attachment is obsolete: true
This patch makes the preference value of marionette.log.level
case sensitive so that we can use new relatively recent addition
Logger#manageLevelFromPref in Log.jsm to set and keep track of a
Logger's verbosity.

This presupposes that the preferences value is exactly one of
the Log.Level enum's variants, but this is ensured through case
conversion in geckodriver.

This has the advantage that we do not have to roll separate
implementations of Log for the child- and parent processes.  It also
has the upside that the log level will be reflected when changed
at runtime through the use of an observer.
Attachment #8999618 - Attachment is obsolete: true
Attachment #8999963 - Flags: review?(hskupin)
Comment on attachment 8999962 [details] [diff] [review]
Convert logging::Level into mozprofile::preferences::Pref.

Review of attachment 8999962 [details] [diff] [review]:
-----------------------------------------------------------------

::: testing/geckodriver/src/logging.rs
@@ +61,5 @@
>      Trace = 10,
>  }
>  
> +impl Level {
> +    fn to_gecko(&self) -> String {

In other places we have `to_marionette`. Maybe it makes sense to keep that consistent across geckodriver? I know that those levels are defined by Firefox, but from geckodriver side I don't think that it matters much.

@@ +294,5 @@
> +            (Level::Debug, "Debug"),
> +            (Level::Trace, "Trace"),
> +        ];
> +
> +        for &(lvl, s) in tests.iter() {

Just a nit: I'm a friend of readable code and would find it better to use `level` and `value` here.

::: testing/geckodriver/src/marionette.rs
@@ +515,5 @@
>              prefs.insert("devtools.debugger.prompt-connection", Pref::new(false));
>              prefs.insert("marionette.debugging.clicktostart", Pref::new(true));
>          }
>  
> +        prefs.insert("marionette.log.level", logging::max_level().into());

Nice!
Attachment #8999962 - Flags: review?(hskupin) → review+
Comment on attachment 8999963 [details] [diff] [review]
Track Marionette logger verbosity with Log#manageLevelFromPref.

Review of attachment 8999963 [details] [diff] [review]:
-----------------------------------------------------------------

::: testing/marionette/log.js
@@ +17,5 @@
>   * Marionette will ensure the logger is set up correctly with the
>   * appropriate stdout dumper and with the correct log level.
>   *
>   * Unlike `Log.jsm` this logger is E10s safe, meaning repository
> + * configuration is communicated across processes.

Mind refreshing my mind here? This is done by just checking `ownAppenders.length`, right?

::: testing/marionette/prefs.js
@@ +193,1 @@
>          return Log.Level.Fatal;

Does this remove backward compatibility for older releases of Firefox? I think so. As such I feel we should leave-in the call to `toLowerCase()` for now, and remove later when the code is more than 3 releases old.
Attachment #8999963 - Flags: review?(hskupin) → review-
(In reply to Henrik Skupin (:whimboo) from comment #13)

> ::: testing/geckodriver/src/logging.rs
> @@ +61,5 @@
> >      Trace = 10,
> >  }
> >  
> > +impl Level {
> > +    fn to_gecko(&self) -> String {
> 
> In other places we have `to_marionette`. Maybe it makes sense to keep that
> consistent across geckodriver? I know that those levels are defined by
> Firefox, but from geckodriver side I don't think that it matters much.

This is an internal function to explain that Gecko has a particular
format it expects the preference in, but maybe it’s clearer to
remove ::to_gecko and instead implement it directly in the conversion.
(In reply to Henrik Skupin (:whimboo) from comment #14)

> ::: testing/marionette/log.js
> @@ +17,5 @@
> >   * Marionette will ensure the logger is set up correctly with the
> >   * appropriate stdout dumper and with the correct log level.
> >   *
> >   * Unlike `Log.jsm` this logger is E10s safe, meaning repository
> > + * configuration is communicated across processes.
> 
> Mind refreshing my mind here? This is done by just checking
> `ownAppenders.length`, right?

That’s correct.  Which is a pretty stupid thing to do, but it works
for the moment.

> ::: testing/marionette/prefs.js
> @@ +193,1 @@
> >          return Log.Level.Fatal;
> 
> Does this remove backward compatibility for older releases of Firefox? I
> think so. As such I feel we should leave-in the call to `toLowerCase()` for
> now, and remove later when the code is more than 3 releases old.

What do you mean?  This code _is_ in Firefox.

The Python client will continue to work against earlier Firefoxen
because they call toLowerCase(), and it will work for future versions
because it sends the correctly cased "Info", "Trace", et al.
Attachment #8999963 - Flags: review- → review?(hskupin)
In order to facilitate the use of Log.jsm's Logger#manageLevelFromPref,
geckodriver needs to ensure that the input value for the
marionette.log.level preference conforms to the variants in the
Log.Level enum.

This patch implements the Into<T> conversion from geckodriver's
logging::Level into mozprofile::preferences::Pref by way of a new
function to_gecko(), that ensures the preference value is correctly
formatted.

Logger#manageLevelFromPref expects a string value such as "Info",
which exactly matches Log.Level's own properties.  It is in other
words case sensitive, and this ensures that Marionette no longer
has to case convert the input data.
Attachment #8999962 - Attachment is obsolete: true
Comment on attachment 8999963 [details] [diff] [review]
Track Marionette logger verbosity with Log#manageLevelFromPref.

Review of attachment 8999963 [details] [diff] [review]:
-----------------------------------------------------------------

::: testing/marionette/prefs.js
@@ +193,1 @@
>          return Log.Level.Fatal;

> The Python client will continue to work against earlier Firefoxen
> because they call toLowerCase(), and it will work for future versions
> because it sends the correctly cased "Info", "Trace", et al.

Well, here you removed `toLowerCase()` and as such no level with a starting lower-case letter will work. When the Marionette Python client makes it lower-case, how should this work?
(In reply to Henrik Skupin (:whimboo) from comment #18)
> Comment on attachment 8999963 [details] [diff] [review]
> Track Marionette logger verbosity with Log#manageLevelFromPref.
> 
> Review of attachment 8999963 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: testing/marionette/prefs.js
> @@ +193,1 @@
> >          return Log.Level.Fatal;
> 
> > The Python client will continue to work against earlier Firefoxen
> > because they call toLowerCase(), and it will work for future versions
> > because it sends the correctly cased "Info", "Trace", et al.
> 
> Well, here you removed `toLowerCase()` and as such no level with a starting
> lower-case letter will work. When the Marionette Python client makes it
> lower-case, how should this work?

The Python client, of which we always use the latest version, has
been changed in this patch to use the correctly cased value.
(In reply to Andreas Tolfsen ﹝:ato﹞ from comment #19) 
> The Python client, of which we always use the latest version, has
> been changed in this patch to use the correctly cased value.

Well, that is true if tests are running via mach or packaged tests. But we have consumers outside of the tree, which then would immediately need a new release of the client. Please make sure to do that once your patch got merged to central.

But where I'm actually worried about is geckodriver. The current release sets the preference to "TRACE", and as such it will start failing for users outside the tree once your Marionette server patch landed. So we would have to first release a new geckodriver with the case fix included, which will bump the max version for 0.21.0 to 62.0. Or we keep `toLowerCase` in the switch statement for a couple of releases, and do not have to do any geckodriver release, and are not changing the max version for 0.21.0.
(In reply to Henrik Skupin (:whimboo) from comment #20)

> But where I'm actually worried about is geckodriver. The current
> release sets the preference to "TRACE", and as such it will start
> failing for users outside the tree once your Marionette server
> patch landed. So we would have to first release a new geckodriver
> with the case fix included, which will bump the max version for
> 0.21.0 to 62.0. Or we keep `toLowerCase` in the switch statement
> for a couple of releases, and do not have to do any geckodriver
> release, and are not changing the max version for 0.21.0.

OK, this is a reasonable argument for keeping the case-insensitive
behaviour in Marionette.  I’ll update the patch to reflect this.
This patch makes the preference value of marionette.log.level
case sensitive so that we can use new relatively recent addition
Logger#manageLevelFromPref in Log.jsm to set and keep track of a
Logger's verbosity.

This presupposes that the preferences value is exactly one of
the Log.Level enum's variants, but this is ensured through case
conversion in geckodriver.

This has the advantage that we do not have to roll separate
implementations of Log for the child- and parent processes.  It also
has the upside that the log level will be reflected when changed
at runtime through the use of an observer.
Attachment #9001543 - Flags: review?(hskupin)
Attachment #8999963 - Attachment is obsolete: true
Attachment #8999963 - Flags: review?(hskupin)
This patch adopts Logger#managerLevelFromPref from Log.jsm to set
and keep track of the Marionette logger's verbosity.

This has the advantage that we do not have to roll separate
implementations of Log for the child- and parent processes.  It also
has the upside that the log level will be reflected when changed
at runtime through the use of an observer.
Attachment #9001544 - Flags: review?(hskupin)
Attachment #9001543 - Attachment is obsolete: true
Attachment #9001543 - Flags: review?(hskupin)
Attachment #9001544 - Flags: review?(hskupin) → review+
Pushed by atolfsen@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/2db292e66641
Convert logging::Level into mozprofile::preferences::Pref. r=whimboo
https://hg.mozilla.org/integration/mozilla-inbound/rev/131559bd826a
Track Marionette logger verbosity with Log#manageLevelFromPref. r=whimboo
https://hg.mozilla.org/mozilla-central/rev/2db292e66641
https://hg.mozilla.org/mozilla-central/rev/131559bd826a
Status: ASSIGNED → RESOLVED
Closed: Last year
Resolution: --- → FIXED
Target Milestone: --- → mozilla63
You need to log in before you can comment on or make changes to this bug.