Closed Bug 1044136 Opened 6 years ago Closed 6 years ago

Filter mozdevice logging in marionette test runner.

Categories

(Testing :: Marionette, defect)

x86_64
Linux
defect
Not set

Tracking

(Not tracked)

RESOLVED FIXED
mozilla34

People

(Reporter: zcampbell, Assigned: davehunt)

References

Details

Attachments

(1 file, 1 obsolete file)

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
Blocks: 1039966
Duplicate of this bug: 1046818
Do we want that verbose logging enabled by default? Or should it only activate when debug is enabled?
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?
Attached patch mozdevice_log_level (obsolete) — Splinter Review
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)
Assignee: nobody → ahalberstadt
Status: NEW → ASSIGNED
Attachment #8466224 - Flags: review?(wlachance)
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.
Attachment #8466224 - Flags: review?(wlachance)
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?
Depends on: 1044751
(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.
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.
Assignee: ahalberstadt → dave.hunt
Attachment #8466224 - Attachment is obsolete: true
Attachment #8470108 - Flags: review?(cmanchester)
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.
Attachment #8470108 - Flags: review?(cmanchester) → review+
Blocks: 1051741
Try was green.
Keywords: checkin-needed
https://hg.mozilla.org/mozilla-central/rev/d88299945b02
Status: ASSIGNED → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla34
No longer blocks: 1039966
You need to log in before you can comment on or make changes to this bug.