Suppress Marionette debug/trace messages for wdspec tests

[Hexcles]

Recently Firefox jobs on Travis started to print a lot of Marionette debug messages (for every single DOM event and script loading, etc.), presumably due to some recent changes in Marionette itself. I've seen many cases where the log exceeds 32MB and gets truncated as a result. We should probably suppress these messages. cc @jgraham

[Hexcles]

The problem seems to be worse than I thought. It can easily block PRs from landing in the following failure mode:

Affected tests use a lot of DOM events and/or script loading. Although the tests don't take too long to run, they produce a huge amount of log because of this issue. Once the log reaches 32MB, the output is disabled; and if the job cannot finish within the next 10 minutes, the job will be killed by Travis because of "no output".

Example: https://travis-ci.org/web-platform-tests/wpt/jobs/407504544

[Hexcles]

Another example today: #12179

[Hexcles]

This looks like a regression of Marionette.

Geckodriver doc says the default logging level is info (https://github.com/mozilla/geckodriver#log-object). And I also tried explicitly setting moz:firefoxOptions.log.level, but I still see a lot of "Marionette DEBUG" messages from Firefox processes, which wasn't the case before.

cc @jgraham @whimboo

[whimboo]

I assume the invocation of wpt runner somehow sets the --webdriver-arg argument to -v or even -vv? Nothing has been changed for logging recently.

Maybe it's a result of upgrading geckodriver from about a week ago? But even in the last releases which all were part this upgrade we didn't change anything related to this.

[Hexcles]

A quick grep doesn't find any place that sets --webdriver-arg in stability checks. Maybe @jgraham would know more.

[whimboo]

Do we store those logs somewhere? I would like to have at least a look at those. If not, maybe you can upload an excerpt?

[Hexcles]

@whimboo there's a link to an example at the top.

[jgraham]

@andreastt This is the issue with marionette having too-verbose logging.

[andreastt]

This is not a regression, since it was a conscious decision to enable finer output from Marionette specifically for the wdspec tests. This is useful to developers when diagnosing why wdspec tests fail at Mozilla.

Since Travis does not support artifacts, a reasonable compromise here might be to decrease the log details on there. This is possible by setting the marionette.log.level pref (or, in this case, making sure it is not being set by way of --webdriver-arg '-vv').

[whimboo]

Also I want to add that we still have info logging as default for Marionette. trace level logging for wdspec jobs was only added AFAIR to our CI system (https://bugzilla.mozilla.org/show_bug.cgi?id=1443446).

Whereby I can also see it when running the wdspec jobs locally with mach. So there must be something else too.

[whimboo]

Well, please scratch the second half of my last comment. The alias I have actually uses --webdriver-arg=-vv.

[mdittmer]

Ping @whimboo and @Hexcles. Is this issue ongoing in Travis land?

[whimboo]

I think so. But to further help you I would need some links to see how the tests are started, including which arguments are used.

[foolip]

@jgraham, could provide @whimboo with the Marionette arguments?

[andreastt]

Looks like this is a regression in Marionette. I’ve filed https://bugzilla.mozilla.org/show_bug.cgi?id=1482829.

[foolip]

https://bugzilla.mozilla.org/show_bug.cgi?id=1482829 is claimed to be fixed, has that change reached Firefox Nightly yet?

[andreastt]

Yes. You shouldn’t see debug-level output from Marionette by default anymore. You can surface it by passing --webdriver-arg=-vv to wptunner, however.

[foolip]

@Hexcles, can you check a recent run to see if what you originally saw is gone?

[Hexcles]

Verified (https://travis-ci.org/web-platform-tests/wpt/jobs/419186171#L622). Thanks, @andreastt .

[foolip]

OK, can't blame #11436 (comment) on this issue then :)

[andreastt]

FWIW we also have a future plan to suppress Firefox output, but it’s a bit into the future: https://bugzilla.mozilla.org/show_bug.cgi?id=1399441

[whimboo]

I still see TRACE output from Marionette in the latest Travis builds:
https://travis-ci.org/web-platform-tests/wpt/jobs/419595739

So is this really fixed?

[Hexcles]

Sorry, you're right. The job I was looking at somehow just didn't have trace output.

Travis is currently running geckodriver 0.21.0 & Firefox Nightly. Has the patch not released yet?

[jgraham]

I have a vauge memory that @andreastt made the log levels case sensitive? If I'm not totally mistaken about that, I guess we might be passing in the wrong string? (I'm not sure what the argument is for making them case sensitive, but it seems like a dubious idea on the face of it).

[whimboo]

The level is case-sensitive now but in Marionette we compare it still after running lowerCase() on it. So there shouldn't be a problem.

[whimboo]

I see different invocations of Firefox.

Case 1: No trace / debug output:
https://travis-ci.org/web-platform-tests/wpt/jobs/433928918#L628

Full command: /home/travis/build/web-platform-tests/wpt/_venv/browsers/nightly/firefox/firefox --marionette about:blank -profile /tmp/tmpGQQV2m.mozrunner

Case 2: trace / debug output:
https://travis-ci.org/web-platform-tests/wpt/jobs/433942495#L914

Full command: /home/travis/build/web-platform-tests/wpt/_venv/bin/geckodriver --marionette-port 2828 --host 127.0.0.1 --port 4444

So the problem here is that the working case is for non-wdspec tests, while the 2nd case with trace output is for wdspec tests.

[whimboo]

So what makes us wonder is why there is no debug output for webdriver::server from the webdriver crate, but only from Marionette.

[whimboo]

Please drop my last comment. We don't see those debug lines because -v isn't being used when invoking geckodriver. So that is expected.

[whimboo]

Ok, so there are two issues here.

First geckodriver incorrectly stores "INFO" instead of "Info" in the marionette.logging.level preference (https://bugzilla.mozilla.org/show_bug.cgi?id=1494613). And as such Marionette fails somehow and just prints all debug and trace lines (https://bugzilla.mozilla.org/show_bug.cgi?id=1494611).

We will fix the geckodriver issue immediately because we have to release a new version anyway at latest early next week. Then this issue should be solved. @andreastt will work on that fix.

[andreastt]

To clarify, we did fix this issue in https://bugzilla.mozilla.org/show_bug.cgi?id=1482829, but it regressed a few days after due to a faulty rebase. We had put in a backwards compatibility fallback in Marionette, but due to another bug this didn’t kick in. See https://bugzilla.mozilla.org/show_bug.cgi?id=1494613#c0 for the full extent of this shitshow.

Sorry about all of this.

[mdittmer]

@andreastt looks like there's been progress in gecko on this. Has it been fixed? What's the best way to verify?

[andreastt]

@mdittmer It is fixed in Firefox 64 geckodriver 0.23.0 and you can verify by checking the stdout from geckodriver does not contain any log entries below INFO level.

[whimboo]

We have released geckodriver 0.23.0 yesterday. So the problem should be fixed now for wdspec tests. @foolip can you have a look if that version of geckodriver is already used?

[foolip]

I defer to @jgraham. FWIW, it doesn't look like the geckodriver version is pinned in wpt.

[andreastt]

I believe @jugglinmike or @jgraham fixed it so that the latest version of geckodriver is now always picked up.

[foolip]

I've filed #13399 about the difficulty of determining what geckodriver version is used.

https://taskcluster-artifacts.net/D1rcmB07QXG_T1lClSfh8w/0/public/logs/live_backing.log is still very verbose, but only ~12% of the lines have "Marionette" in them so I'll assume this is now fixed.

[andreastt]

Thanks for the link to a log. The INFO level and above entries we see in this log are to be expected. The log level can be raised to WARN, ERROR, or FATAL if we want to see even less output from geckodriver.

[foolip]

@andreastt where should we raise the level to WARN? In https://travis-ci.org/web-platform-tests/wpt/jobs/438265534 there is an unreasonable amount of the logging that comes from Marionette.

[whimboo]

@foolip I don't see that much logging output. So which lines are you referring to?

[foolip]

@whimboo search for "marionette" in the logs and you see a fair bit of stuff that I'd consider redundant.

[andreastt]

Probably setting marionette.log.level to Warn here would do the trick for all non-wdspec test types:
https://searchfox.org/mozilla-central/rev/c9272ef398954288525e37196eada1e5a93d93bf/testing/web-platform/tests/tools/wptrunner/wptrunner/browsers/firefox.py#235-242

[whimboo]

This looks like a fixed value to me, so a better place is https://searchfox.org/mozilla-central/source/testing/profiles/web-platform/user.js, unless you want to make is configurable via a command line option.