1221187 - Support changing logging level for Marionette

Status: RESOLVED FIXED

(Remote Protocol :: Marionette, defect)

Description

[Maja Frydrychowicz :impossibus (was :maja_zf) (needinfo me)]

By default, debug-level log messages get dumped into gecko.log by Marionette. This amounts to quite a long log file. Instead, we'd like info-level messages in gecko.log by default, and we'd like a convenient way to specify the log level via the Marionette test runner, say.

The current workaround (to avoid giant log files for long-running tests) is to set a browser pref: 'marionette.logging': False

Comment 1

[Andreas Tolfsen ❲:ato❳]

Only outputting info-level makes sense to me, and has been requested by jgraham in the past (though I cannot find the bug right now).

Comment 2

[Andreas Tolfsen ❲:ato❳]

I would suggest the following:

* Allow marionette.logging to be set to one of the values of the Log.jsm Level enum (https://developer.mozilla.org/en-US/docs/Mozilla/JavaScript_code_modules/Log.jsm)
* Default to DEBUG on debug and B2G builds (as we do now)
* Default to INFO for optimised builds
* Log I/O related things to a new sub-logger Marionette.Transport
* Use TRACE for I/O
* Hijack mach’s -v (verbose) flag and use this to override marionette.logging to TRACE

Comment 3

[Andreas Tolfsen ❲:ato❳]

Attachment: MozReview Request: Bug 1221187: testing/marionette: Set log level from preference; r?automatedtester

Review commit: https://reviewboard.mozilla.org/r/29353/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/29353/

Comment 4

[Andreas Tolfsen ❲:ato❳]

Attachment: MozReview Request: Bug 1221187: testing/marionette/client: Add -v flag for trace logging output; r?automatedtester

Review commit: https://reviewboard.mozilla.org/r/29355/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/29355/

Comment 5

[Andreas Tolfsen ❲:ato❳]

Attachment: MozReview Request: Bug 1221187: testing/marionette: Adjust log levels to match new defaults; r?automatedtester

Review commit: https://reviewboard.mozilla.org/r/29357/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/29357/

Comment 6

[Andreas Tolfsen ❲:ato❳]

Attachment: MozReview Request: Bug 1221187: testing/marionette/client: Explicitly define --version flag; r?automatedtester

Review commit: https://reviewboard.mozilla.org/r/29359/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/29359/

Comment 7

[David Burns :automatedtester]

Comment on attachment 8703444 [details]
MozReview Request: Bug 1221187: testing/marionette/client: Explicitly define --version flag; r?automatedtester

https://reviewboard.mozilla.org/r/29359/#review26153

Comment 8

[David Burns :automatedtester]

Comment on attachment 8703443 [details]
MozReview Request: Bug 1221187: testing/marionette: Adjust log levels to match new defaults; r?automatedtester

https://reviewboard.mozilla.org/r/29357/#review26151

::: testing/marionette/client/marionette/runner/base.py:267
(Diff revision 1)
> +                        help='Increase verbosity by including debug- and trace messages.')

Can we add what the numbers are? At the moment we don't give the user any hint what values are legal.

Comment 9

[David Burns :automatedtester]

Comment on attachment 8703442 [details]
MozReview Request: Bug 1221187: testing/marionette/client: Add -v flag for trace logging output; r?automatedtester

https://reviewboard.mozilla.org/r/29355/#review26149

::: testing/marionette/components/marionettecomponent.js:49
(Diff revision 1)
> +  let l = Log.Level.Info;

Change the variable to give a future reader a hint what it is without havinging to search for where it could be instantiated.

::: testing/marionette/components/marionettecomponent.js:59
(Diff revision 1)
> +    let s = Services.prefs.getCharPref(LOG_PREF);

what is `s`? A single character variable makes it hard to read what should be in it especially when `s` could be service here

Comment 10

[David Burns :automatedtester]

Comment on attachment 8703444 [details]
MozReview Request: Bug 1221187: testing/marionette/client: Explicitly define --version flag; r?automatedtester

https://reviewboard.mozilla.org/r/29359/#review26155

Comment 11

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8703441 [details]
MozReview Request: Bug 1221187: testing/marionette: Set log level from preference; r?automatedtester

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/29353/diff/1-2/

Comment 12

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8703441 [details]
MozReview Request: Bug 1221187: testing/marionette: Set log level from preference; r?automatedtester

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/29353/diff/1-2/

Comment 13

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8703442 [details]
MozReview Request: Bug 1221187: testing/marionette/client: Add -v flag for trace logging output; r?automatedtester

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/29355/diff/1-2/

Comment 14

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8703443 [details]
MozReview Request: Bug 1221187: testing/marionette: Adjust log levels to match new defaults; r?automatedtester

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/29357/diff/1-2/

Comment 15

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8703444 [details]
MozReview Request: Bug 1221187: testing/marionette/client: Explicitly define --version flag; r?automatedtester

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/29359/diff/1-2/

Comment 16

[Andreas Tolfsen ❲:ato❳]

I realised in retrospect that a new appender was the wrong solution for filtering log messages because this modifies the internal data structure of the logged messages.  Instead I’ve redone the first patch to implement a FilteredFormatter instead, that from a predicate function can tell if the message should be formatted or not.

Comment 17

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8703442 [details]
MozReview Request: Bug 1221187: testing/marionette/client: Add -v flag for trace logging output; r?automatedtester

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/29355/diff/2-3/

Comment 18

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8703443 [details]
MozReview Request: Bug 1221187: testing/marionette: Adjust log levels to match new defaults; r?automatedtester

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/29357/diff/2-3/

Comment 19

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8703444 [details]
MozReview Request: Bug 1221187: testing/marionette/client: Explicitly define --version flag; r?automatedtester

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/29359/diff/2-3/

Comment 20

[Andreas Tolfsen ❲:ato❳]

https://reviewboard.mozilla.org/r/29355/#review26149

> what is `s`? A single character variable makes it hard to read what should be in it especially when `s` could be service here

It’s a string, and also a transitive variable that is consumed on the next line and then goes out of scope.  I’m not really sure what to change this to in order to make that clearer.

`preferenceAsString` seems too Java-esque for my taste.

Comment 21

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8703443 [details]
MozReview Request: Bug 1221187: testing/marionette: Adjust log levels to match new defaults; r?automatedtester

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/29357/diff/3-4/

Comment 22

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8703444 [details]
MozReview Request: Bug 1221187: testing/marionette/client: Explicitly define --version flag; r?automatedtester

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/29359/diff/3-4/

Comment 23

[Andreas Tolfsen ❲:ato❳]

Attachment: MozReview Request: Bug 1221187: testing/marionette/client: Explicitly define --version flag

Passing the version keyword to argparse's constructor implicitly adds
-v and --version flags that conflicts with the -v/--verbose flag that
is added in BaseMarionetteArguments.

This removes -v as an alias to --version, which unbreaks testing on try
because it uses runtests.py.

It's perhaps worth mentioning that try uses runtests.py because it does
not (yet) have a full checkout of the source when it runs the tests.

r=dburns

Review commit: https://reviewboard.mozilla.org/r/29703/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/29703/

Comment 24

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8704688 [details]
MozReview Request: Bug 1221187: testing/marionette/client: Explicitly define --version flag

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/29703/diff/1-2/

Comment 25

[David Burns :automatedtester]

Comment on attachment 8703442 [details]
MozReview Request: Bug 1221187: testing/marionette/client: Add -v flag for trace logging output; r?automatedtester

https://reviewboard.mozilla.org/r/29355/#review26693

::: testing/marionette/components/marionettecomponent.js:59
(Diff revision 3)
> +    let s = Services.prefs.getCharPref(LOG_PREF);

we can merge these 2 lines, the variable `s` seems quite meaningless.

Comment 26

[David Burns :automatedtester]

Comment on attachment 8704688 [details]
MozReview Request: Bug 1221187: testing/marionette/client: Explicitly define --version flag

https://reviewboard.mozilla.org/r/29703/#review26699

Comment 27

[Andreas Tolfsen ❲:ato❳]

Filed bug 1237638 as a follow-up to upload the marionette-packets.log to Treeherder.

Comment 28

[David Burns :automatedtester]

Comment on attachment 8703443 [details]
MozReview Request: Bug 1221187: testing/marionette: Adjust log levels to match new defaults; r?automatedtester

https://reviewboard.mozilla.org/r/29357/#review26701

Comment 29

[Andreas Tolfsen ❲:ato❳]

I think the try run (https://treeherder.mozilla.org/#/jobs?repo=try&revision=736aef156481) is fine.  Tomcat is saying that M2 is a known issue, and I believe we don’t really care about B2G Desktop any longer.

Comment 30

[Mark Hammond [:markh] [:mhammond]]

Comment on attachment 8703441 [details]
MozReview Request: Bug 1221187: testing/marionette: Set log level from preference; r?automatedtester

https://reviewboard.mozilla.org/r/29353/#review26779

I don't think this is the correct approach for the log module to be taking. Without more context, it appears you should be able to do everything you need without any changes to Log.jsm

::: toolkit/modules/Log.jsm:83
(Diff revision 2)
> +    fromString: function(s) {

There are lots of places in our code that do something like this, but they are happy to just do |Log.Level[name]| - it doesn't work if the case of the name is wrong, but that's never been a problem in practice (ie, that's just a typo, like mis-spelling the name would be).

A quick look also didn't show a caller of fromNumber (other than here obviously) - what's the use-case for that?

::: toolkit/modules/Log.jsm:743
(Diff revision 2)
> +function FilteredFormatter(predicate, formatter=null) {

The one FilteredFormatter I could see in the other patches simply checks the level of the message - but this is precisely what the log level is for. Further, if someone uses a FilteredFormatter for this purpose, they lose the ability to use a *real* formatter.

I think that instead of using this, you can simply set the level on the appender itself. Eg, you could have the log itself set to, say, trace, but 2 appenders on the log, one with debug and one with info - so trace messages wouldn't actually be written anywhere even though the log itself has that level. A quick look at that other patch implies that would work OK for you (but it might be necessary to avoid logging directly to a "root" logger as messages get passed up the hierarchy). Something like:

  let root = Log.repository.getLogger("Marionette");
  root.level = Log.Level.Trace; // "sub" loggers default to this level.
  let log = Log.repository.getLogger("Marionette.General");
  let iolog = Log.repository.getLogger("Marionette.Transport");

  // log everything above provided level to stdout,
  let a = new Log.DumpAppender(f);
  a.level = level;
  log.addAppender(a);
  iolog.addAppender(a);

  /* the below should work, but maybe consider a different pref specifically for this level, 
     defaulting to, say, Error
  */
  if (level <= Log.Level.Debug) {
    iolog.addAppender(new Log.FileAppender(TRANSPORT_LOG));
  }

Comment 31

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8703441 [details]
MozReview Request: Bug 1221187: testing/marionette: Set log level from preference; r?automatedtester

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/29353/diff/2-3/

Comment 32

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8703442 [details]
MozReview Request: Bug 1221187: testing/marionette/client: Add -v flag for trace logging output; r?automatedtester

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/29355/diff/3-4/

Comment 33

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8703443 [details]
MozReview Request: Bug 1221187: testing/marionette: Adjust log levels to match new defaults; r?automatedtester

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/29357/diff/4-5/

Comment 34

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8703444 [details]
MozReview Request: Bug 1221187: testing/marionette/client: Explicitly define --version flag; r?automatedtester

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/29359/diff/4-5/

Comment 35

[Andreas Tolfsen ❲:ato❳]

Because the changeset has disappeared from MozReview, I’ll comment briefly here instead.

First of all, thank you for your quick and thoughtful review.  It was much appreciated.

(In reply to Mark Hammond [:markh] from comment #30)
> ::: toolkit/modules/Log.jsm:83
> (Diff revision 2)
> > +    fromString: function(s) {
> 
> There are lots of places in our code that do something like this, but they
> are happy to just do |Log.Level[name]| - it doesn't work if the case of the
> name is wrong, but that's never been a problem in practice (ie, that's just
> a typo, like mis-spelling the name would be).

The difference in this case is that the input comes from unreliable sources externally of Gecko in the form of a string preference.  Anyway, I see your point and I didn’t think about using the Log.Level enum as a string lookup.  I can perform the normalisation myself.

> A quick look also didn't show a caller of fromNumber (other than here
> obviously) - what's the use-case for that?

That can be dropped.

> ::: toolkit/modules/Log.jsm:743
> (Diff revision 2)
> > +function FilteredFormatter(predicate, formatter=null) {
> 
> The one FilteredFormatter I could see in the other patches simply checks the
> level of the message - but this is precisely what the log level is for.
> Further, if someone uses a FilteredFormatter for this purpose, they lose the
> ability to use a *real* formatter.
> 
> I think that instead of using this, you can simply set the level on the
> appender itself. Eg, you could have the log itself set to, say, trace, but 2
> appenders on the log, one with debug and one with info - so trace messages
> wouldn't actually be written anywhere even though the log itself has that
> level. A quick look at that other patch implies that would work OK for you
> (but it might be necessary to avoid logging directly to a "root" logger as
> messages get passed up the hierarchy). Something like:

Oh I see, thanks for explaining how inherited loggers work.  That part was a bit of a mystery.

I have now reviewed my approach and opted for a simple solution with just one logger and the default stdout Gecko log.  This renders the first patch to Log.jsm unnecessary, so I have dropped it.

Comment 36

[Mark Hammond [:markh] [:mhammond]]

(In reply to Andreas Tolfsen (:ato) from comment #35)
> The difference in this case is that the input comes from unreliable sources
> externally of Gecko in the form of a string preference.

FTR, that's exactly what all those other references I was discussing do - read a pref value and attempt to use it directly as a level string without normalization. Preferences really aren't "unreliable", in that we typically trust preferences (within reason) because changing various preferences could do nasty things (think the "security.turn_off_all_security_so_that_viruses_can_take_over_this_computer" pref :).

eg,
https://dxr.mozilla.org/mozilla-central/source/browser/experiments/Experiments.jsm#127
https://dxr.mozilla.org/mozilla-central/source/browser/modules/SelfSupportBackend.jsm#169
https://dxr.mozilla.org/mozilla-central/source/services/common/hawkrequest.js#148
https://dxr.mozilla.org/mozilla-central/source/services/fxaccounts/FxAccountsCommon.js#47
etc

> I can perform the normalisation myself.

There's no harm in that, but also no real value I can see.

Comment 37

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8703441 [details]
MozReview Request: Bug 1221187: testing/marionette: Set log level from preference; r?automatedtester

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/29353/diff/3-4/

Comment 38

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8703442 [details]
MozReview Request: Bug 1221187: testing/marionette/client: Add -v flag for trace logging output; r?automatedtester

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/29355/diff/4-5/

Comment 39

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8703443 [details]
MozReview Request: Bug 1221187: testing/marionette: Adjust log levels to match new defaults; r?automatedtester

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/29357/diff/5-6/

Comment 40

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8703444 [details]
MozReview Request: Bug 1221187: testing/marionette/client: Explicitly define --version flag; r?automatedtester

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/29359/diff/5-6/

Comment 41

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8703441 [details]
MozReview Request: Bug 1221187: testing/marionette: Set log level from preference; r?automatedtester

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/29353/diff/4-5/

Comment 42

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8703442 [details]
MozReview Request: Bug 1221187: testing/marionette/client: Add -v flag for trace logging output; r?automatedtester

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/29355/diff/5-6/

Comment 43

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8703443 [details]
MozReview Request: Bug 1221187: testing/marionette: Adjust log levels to match new defaults; r?automatedtester

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/29357/diff/6-7/

Comment 44

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8703444 [details]
MozReview Request: Bug 1221187: testing/marionette/client: Explicitly define --version flag; r?automatedtester

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/29359/diff/6-7/

Comment 45

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8703441 [details]
MozReview Request: Bug 1221187: testing/marionette: Set log level from preference; r?automatedtester

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/29353/diff/5-6/

Comment 46

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8703442 [details]
MozReview Request: Bug 1221187: testing/marionette/client: Add -v flag for trace logging output; r?automatedtester

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/29355/diff/6-7/

Comment 47

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8703443 [details]
MozReview Request: Bug 1221187: testing/marionette: Adjust log levels to match new defaults; r?automatedtester

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/29357/diff/7-8/

Comment 48

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8703444 [details]
MozReview Request: Bug 1221187: testing/marionette/client: Explicitly define --version flag; r?automatedtester

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/29359/diff/7-8/

Comment 49

[David Burns :automatedtester]

Comment on attachment 8703441 [details]
MozReview Request: Bug 1221187: testing/marionette: Set log level from preference; r?automatedtester

https://reviewboard.mozilla.org/r/29353/#review27095

Comment 50

[David Burns :automatedtester]

https://reviewboard.mozilla.org/r/29355/#review27099

Comment 51

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8703441 [details]
MozReview Request: Bug 1221187: testing/marionette: Set log level from preference; r?automatedtester

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/29353/diff/6-7/

Comment 52

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8703442 [details]
MozReview Request: Bug 1221187: testing/marionette/client: Add -v flag for trace logging output; r?automatedtester

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/29355/diff/7-8/

Comment 53

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8703443 [details]
MozReview Request: Bug 1221187: testing/marionette: Adjust log levels to match new defaults; r?automatedtester

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/29357/diff/8-9/

Comment 54

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8703444 [details]
MozReview Request: Bug 1221187: testing/marionette/client: Explicitly define --version flag; r?automatedtester

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/29359/diff/8-9/

Comment 55

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8703441 [details]
MozReview Request: Bug 1221187: testing/marionette: Set log level from preference; r?automatedtester

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/29353/diff/7-8/

Comment 56

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8703442 [details]
MozReview Request: Bug 1221187: testing/marionette/client: Add -v flag for trace logging output; r?automatedtester

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/29355/diff/8-9/

Comment 57

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8703443 [details]
MozReview Request: Bug 1221187: testing/marionette: Adjust log levels to match new defaults; r?automatedtester

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/29357/diff/9-10/

Comment 58

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8703444 [details]
MozReview Request: Bug 1221187: testing/marionette/client: Explicitly define --version flag; r?automatedtester

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/29359/diff/9-10/

Comment 59

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/4a64a53b9075
https://hg.mozilla.org/integration/mozilla-inbound/rev/8f27ebb8c93d
https://hg.mozilla.org/integration/mozilla-inbound/rev/8e77b64f8169
https://hg.mozilla.org/integration/mozilla-inbound/rev/0dbc316b2160

Comment 60

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/4a64a53b9075
https://hg.mozilla.org/mozilla-central/rev/8f27ebb8c93d
https://hg.mozilla.org/mozilla-central/rev/8e77b64f8169
https://hg.mozilla.org/mozilla-central/rev/0dbc316b2160