Closed Bug 1419826 Opened 7 years ago Closed 7 years ago

[mozlog] Make it possible for formatters to print summary of multiple suites

Categories

(Testing :: Mozbase, enhancement)

Product:
Testing
Component:
Mozbase
Type:
enhancement
Priority:
Not set
Severity:
normal

Tracking

(firefox59 fixed)

Status:
RESOLVED FIXED
Milestone:
mozilla59
Tracking Flags:
Tracking Status
firefox59 --- fixed

People

(Reporter: ahal, Assigned: ahal)

References

Details

Attachments

(2 files)

Bug 1419826 - [mozlog] Add an optional 'name' attribute to the suite_start action,
59 bytes, text/x-review-board-request
jgraham
: review+
Details
Bug 1419826 - [mozlog] Implement StructuredLogger.shutdown(),
59 bytes, text/x-review-board-request
jgraham
: review+
Details 
When running |mach test| (or |mach mochitest|), we often end up running more than one suite. Formatters generally dump a summary of all results on 'suite_end', but in this case that summary quickly becomes lost to backscroll as the next suite starts running. This makes it hard for developers to figure out what went wrong, typically they'd need to ctrl-f for 'TEST-UNEXPECTED' or 'ERROR'. Worse, they might not even realize something went wrong in the first place!

The formatters can't currently print a master summary of multiple suites because they don't know whether or not there's another suite about to run. From a high level, we can fix this by:

A) Adding the ability to specify ahead of time which suites are expected to run
B) Allowing formatters to dump a message on logger cleanup

Between the two I prefer A) because it is more explicit and it will allow us to do things like create a |mach build| style footer which would make it easy for developers to see which suite is currently running, and how many are left. Though option B) would also have other uses (we could always do both A) and B) if we wanted).

I haven't put much thought into what the mozlog data structure for this should look like yet.
I agree this is a good thing to do, but I'm pretty worried about having to know upfront which suites will run. How does that work with e.g. --repeat-until-unexpected which could run a suite an unknown number of times.

Doing things in cleanup also seems a little worrying, but perhaps better.
Maybe wpt works differently, but at least for mochitest --run-until-failure works within the same suite invocation. But your point still stands.

I was planning on preserving backwards compatibility, so this would be an option rather than a requirement. We'd need |mach test| to be the thing that logs this message. When not running from a |mach test| context, we simply wouldn't log it and the formatters would be set up to handle this case.
Thinking about this a bit more, I think we need to go with option B). There's no guarantee that the last 'suite_end' message is going to be at the bottom of the log. There could be leak checking or arbitrary process output that bumps the summary off-screen and then we're back to the same problem. If we want to guarantee that this summary will be on-screen, it has to be the last thing that gets logged.

Another thing we should do, is add an optional 'name' field to 'suite_start'. This way the summary can break errors down by suite name.
Assignee: nobody → ahalberstadt
Status: NEW → ASSIGNED
Actually logging the multi-suite summary in the formatters will happen in bug 1209463.
Comment on attachment 8931210 [details]
Bug 1419826 - [mozlog] Add an optional 'name' attribute to the suite_start action,

https://reviewboard.mozilla.org/r/202310/#review207830
Attachment #8931210 - Flags: review?(james) → review+
Comment on attachment 8931211 [details]
Bug 1419826 - [mozlog] Implement StructuredLogger.shutdown(),

https://reviewboard.mozilla.org/r/202312/#review207832
Attachment #8931211 - Flags: review?(james) → review+
Pushed by ahalberstadt@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/3a7a93bf138e
[mozlog] Add an optional 'name' attribute to the suite_start action, r=jgraham
https://hg.mozilla.org/integration/autoland/rev/b3e4c5744eff
[mozlog] Implement StructuredLogger.shutdown(), r=jgraham
Oh, guess this is happening because of the "component": None. Also I forgot the logger name is already in the data under the "source" key. There's probably no need to add the name/component, let's just log an empty dict as context.
Flags: needinfo?(ahalberstadt)
It ended up being because wpt was the only thing that enabled strict mode in mozharness:
https://dxr.mozilla.org/mozilla-central/source/testing/mozharness/mozharness/mozilla/structuredlog.py#73

The error was triggered because 'logger_shutdown' wasn't in structuredlog.log_actions (due to no being defined via the decorator). It needs to be kept out of the converter_registry so users aren't able to log it manually, but we can just add it to the log_actions method.

I'd still also like to remove the 'name' and 'component' keys from logger_shutdown though.
I stumbled into a bit of rabbit hole while fixing this issue. Basically logger.shutdown() doesn't play well with multiple logger instances sharing the same state. The proper way to solve this, is to move "has_shutdown" to the state object, but now calling "shutdown()" implicitly from __del__ becomes problematic. If there are multiple logger instances referencing the same state, we don't want to lock all logging as soon as one of them happens to be garbage collected. There were two possible solutions:

1) try to use refcounting so "shutdown()" only gets called when the last instance referencing the shared state is destroyed
2) don't implicitly call "shutdown()" from __del__

I fiddled around trying to get option 1) working for awhile. It was mostly decent, but at the end of the day there's no way to *guarantee* that the "logger_shutdown" message would get sent. So I'd prefer to do option 2 instead.

This means that the "logger_shutdown" message will only be sent when using a context manager, or explicitly calling "logger.shutdown()". It won't happen from gc or del. I think this behaviour will be fine for the purposes of fixing bug 1209463.
Comment on attachment 8931211 [details]
Bug 1419826 - [mozlog] Implement StructuredLogger.shutdown(),

The changes are significant enough they warrant a re-review. Also, here's a bit more thorough of a try run this time:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=740d14db682b155d8ad9f1705daa0df5c9c258c6
Attachment #8931211 - Flags: review+ → review?(james)
Attachment #8931211 - Flags: review?(james) → review+
Pushed by ahalberstadt@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/3fbd4e6f72ee
[mozlog] Add an optional 'name' attribute to the suite_start action, r=jgraham
https://hg.mozilla.org/integration/autoland/rev/d82a539fb129
[mozlog] Implement StructuredLogger.shutdown(), r=jgraham
https://hg.mozilla.org/mozilla-central/rev/3fbd4e6f72ee
https://hg.mozilla.org/mozilla-central/rev/d82a539fb129
Status: ASSIGNED → RESOLVED
Closed: 7 years ago
status-firefox59: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla59
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: