Zac C (:zac) Reporter
	Description • 10 years ago

Bug 1026710 introduced some structured logging to mozdevice and mozlog.

When we use this with marionette_client 0.8.1 the logging is too verbose, it adds around 140 lines of mozdevice debugging to each test and makes it hard to find the test results. 

According to Armenzg, marionette needs to filter this out when it sets up the logger.

Here is an example of the output for just one test:
https://pastebin.mozilla.org/5618970

	Andrew Halberstadt [:ahal]
	Comment 2 • 10 years ago

Do we want that verbose logging enabled by default? Or should it only activate when debug is enabled?

	Jonathan Griffin (:jgriffin)
	Comment 3 • 10 years ago

I had been thinking that it would be useful in general for tests run in TBPL, to help track the cause of intermittents, but I see it doesn't work well Marionette's test output at least.  Maybe we want to disable it by default but enable it somehow in jobs run on TBPL?

	Andrew Halberstadt [:ahal]
	Comment 4 • 10 years ago

I don't really thing mozlog.DEBUG should be the default level, but this patch should help us get around the immediate problem in the short term.

Zac, do you mind testing this out? I don't have a gaiatest setup at the moment.

(On a side note, it would have been better for mozdevice to use a structured logger instead of the old unstructured mozlog one.. this our fault for not making it clearer that the old style is more or less deprecated though. I filed bug 1047429 to go a little way towards this)

	Andrew Halberstadt [:ahal]
	Comment 5 • 10 years ago

Comment on attachment 8466224 [details] [diff] [review]
mozdevice_log_level

Actually, I don't think this will work. I based this on an outdated patch (https://bugzilla.mozilla.org/page.cgi?id=splinter.html&bug=1026710&attachment=8454422) that has been changed since landing. It seems mozlog.DEBUG is no longer the default level. So something else is causing this.

	Andrew Halberstadt [:ahal]
	Comment 6 • 10 years ago

After talking to James on irc, this seems like a bug in mozlog.structured. Basically it doesn't have a notion of levels yet, so the formatters print everything (someone correct me if I'm wrong). The good news is that Chris already has a patch for this in bug 1044751.

So I think we need to:
A) Wait for that to land
B) Make mozdevice's logger use a formatter that filters log levels (?)

Chris, does that sound correct to you?

	Chris Manchester (limited bugmail, email directly)
	Comment 7 • 10 years ago

(In reply to Andrew Halberstadt [:ahal] from comment #6)
> After talking to James on irc, this seems like a bug in mozlog.structured.
> Basically it doesn't have a notion of levels yet, so the formatters print
> everything (someone correct me if I'm wrong). The good news is that Chris
> already has a patch for this in bug 1044751.
> 
> So I think we need to:
> A) Wait for that to land
> B) Make mozdevice's logger use a formatter that filters log levels (?)
> 
> Chris, does that sound correct to you?

Pretty much! The current version of the patch filters at info by default, so B wont be needed, and mozdevice logging wont get through. If this is acceptable I think it will solve the issue motivating this bug. If we want debug output in automation, we can add --log-tbpl-level=debug to the in-tree config.

	Dave Hunt [:davehunt] [he/him] ⌚BST Assignee
	Comment 8 • 10 years ago

Even with the latest patches applied, the Marionette test runner is still full of debug level logs when no logger is specified on the command line. This patch addresses that.

	Chris Manchester (limited bugmail, email directly)
	Comment 9 • 10 years ago

Comment on attachment 8470108 [details] [diff] [review]
Change default logging level in marionette test runner to info. v1.0

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

Right. The filters are only applied to standard formatters, sorry about that. The rest of comment 7 about passing --log-tbpl=debug isn't valid either for this reason, but the full debug output will end up in the raw json log.

This should do the trick for marionette.

	Dave Hunt [:davehunt] [he/him] ⌚BST Assignee
	Comment 10 • 10 years ago

Try: https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=4f293249fb45

	Dave Hunt [:davehunt] [he/him] ⌚BST Assignee
	Comment 11 • 10 years ago

Try was green.

	Ryan VanderMeulen [:RyanVM]
	Comment 12 • 10 years ago

https://hg.mozilla.org/integration/b2g-inbound/rev/d88299945b02

	Ryan VanderMeulen [:RyanVM]
	Comment 13 • 10 years ago

https://hg.mozilla.org/mozilla-central/rev/d88299945b02