Use StructuredOutputParser for parsing mochitest test results

RESOLVED FIXED

Status

defect
RESOLVED FIXED
3 years ago
3 years ago

People

(Reporter: ahal, Assigned: pyang)

Tracking

(Depends on 1 bug, Blocks 1 bug)

unspecified
Dependency tree / graph

Firefox Tracking Flags

(firefox52 fixed)

Details

Attachments

(1 attachment, 9 obsolete attachments)

Mochitest emits structured logs, but mozharness currently doesn't consume them. It is still parsing the old formatted logs using a set of regexes. We should make sure to use the StructuredOutputParser class instead of DesktopUnittestParser:
https://dxr.mozilla.org/mozilla-central/source/testing/mozharness/mozharness/mozilla/testing/testbase.py#502

We'll need to be careful that we don't miss failures that are hidden in unstructured output. This might mean running the same set of regexes when we come across unstructured output.
Posted patch patch.diff (obsolete) — Splinter Review
Simply add structurelog parsing for mochitest, and make sure output raw log is enabled when running "structured_suites"
Attachment #8751620 - Flags: feedback?(ahalberstadt)
Assignee: nobody → pyang
Comment on attachment 8751620 [details] [diff] [review]
patch.diff

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

Nice, this looks correct. You'll need to do a lot of try runs and re-triggers so we can be sure that we aren't going to stop errors from failing properly. And like you mentioned on irc the other day, failure cases to test would be awesome!

::: testing/mozharness/configs/unittests/linux_unittest.py
@@ +303,5 @@
>              "halt_on_failure": True,
>              "enabled": ADJUST_MOUSE_AND_SCREEN
>          },
>      ],
> +    "structured_suites": "mochitest",

I think this needs to be a list, and don't forget to add it to the mac and windows configs too.

::: testing/mozharness/mozharness/mozilla/structuredlog.py
@@ +115,5 @@
>                  self.update_levels(*error_pair)
>  
>          failure_log_levels = ['ERROR', 'CRITICAL']
>          for level in failure_log_levels:
> +            if summary.log_level_counts.get(level, 0) > 0:

Because None and 0 both evaluate to False, you could simplify this to:
if summary.log_level_counts.get(level):
Attachment #8751620 - Flags: feedback?(ahalberstadt) → feedback+
Posted patch patch.diff (obsolete) — Splinter Review
Updated, add structured_suites for rest of configs
Attachment #8751620 - Attachment is obsolete: true
reply to Paul Yang [:pyang] from comment #6)
> https://treeherder.mozilla.org/#/jobs?repo=try&revision=07321a716921

mochitest/runtests.py catched unknown exception in https://dxr.mozilla.org/mozilla-central/source/testing/mochitest/runtests.py#2418 and print_exec lost information since we change to use structured logging format.

Seeing quite many print_exc() in test scripts. We might need a general solution for those affected.
(In reply to Paul Yang [:pyang] from comment #6)
> https://treeherder.mozilla.org/#/jobs?repo=try&revision=07321a716921

https://treeherder.mozilla.org/logviewer.html#?job_id=20879668&repo=try#L6340
from log we can see mochitest/runtests.py was timeout right after dom/workers/test/serviceworkers/browser_force_refresh.js passed.
Depends on: 1274584
Posted patch mochitest-log (obsolete) — Splinter Review
Updated
for Bug 1274584
tree report for windows https://treeherder.mozilla.org/#/jobs?repo=try&revision=9feb21803239a28be5ac14eeee9debb103a73f33
force_refresh test passed.
Attachment #8752076 - Attachment is obsolete: true
Attachment #8756696 - Flags: feedback?(ahalberstadt)
Comment on attachment 8756696 [details] [diff] [review]
mochitest-log

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

I think this is a good workaround to get your unblocked.. but I'd rather fix the bug in mozprocess if possible (bug 1274584).

I'd say this is good for now.. maybe I'll get a chance to take a closer look at the mozprocess bug in a bit. In the meantime I think there are enough other mochitest problems to deal with.

::: testing/mochitest/runtests.py
@@ +2057,5 @@
> +            # Unknown child process left while parent killed. here we catch
> +            # eception and rely on zombie checking mechanism
> +            # see https://bugzilla.mozilla.org/show_bug.cgi?id=1274584
> +            except OSError as err:
> +                self.log.info("runtests.py | Can't kill child process")

I'd make this a warning.
Attachment #8756696 - Flags: feedback?(ahalberstadt) → feedback+
I'm okay to block this until bug 1274584 fixed.  Will use this patch for finding other issues.
Using latest central with patch, test failed on subsuite clipboard, detail showed in https://treeherder.mozilla.org/#/jobs?repo=try&revision=d367f9ca0097153aad131d2866a94cc24cb34a44

The error was generated by class MessageLogger which is used only in mochtest/runtests.py
ahal, is that considered redundant after we have structured log parser?
Flags: needinfo?(ahalberstadt)
Where do you see an error in MessageLogger? I don't see that in any of the "cl" jobs? It looks like maybe the summary isn't being printed properly, it says "No checks run", but the tests seem to run and pass.

To answer your question, no, it won't be redundant. MessageLogger in mochitest intercepts the stdout from Gecko and formats it into a structured log. It emits what the mozharness parser reads.
Flags: needinfo?(ahalberstadt)
Thanks, no checks run was weird and my guess is run summary was corrupted, because summary print was in evaluate-parser and no test-end action showed. Will trace it and see whether it's a non-evaluated error.
suite jetpack-package-clipboard didn't output correct format, therefore we can't consume.  It generated raw log such like:
{"thread": "ProcessReader", "level": "info", "pid": 5663, "source": "mochitest", "time": 1467107857876, "action": "log", "exc_info": false, "message": "TEST-END | jetpack-package/addon-sdk/source/test/test-clipboard.js.test With Redundant Flavor"}


while normal status logging format is:

{"status": "OK", "pid": null, "test": "widget/tests/test_assign_event_data.html", "js_source": "TestRunner.js", "message": "Finished in 9135ms", "stack": "{u'runtime': 9135}", "thread": "None", "source": "mochitest", "time": 1467107840529, "action": "test_end"}
All jetpack test cases don't produce structuredlog. We see JP suite passed because it has 3 skipped test cases as following.

{"status": "SKIP", "thread": "MainThread", "pid": 2512, "source": "mochitest", "test": "addon-sdk/source/test/test-cuddlefish.js", "time": 1466758559850, "action": "test_end", "message": "skip-if: true"}
{"status": "SKIP", "thread": "MainThread", "pid": 2512, "source": "mochitest", "test": "addon-sdk/source/test/test-mpl2-license-header.js", "time": 1466758559850, "action": "test_end", "message": "skip-if: true"}
{"status": "SKIP", "thread": "MainThread", "pid": 2512, "source": "mochitest", "test": "addon-sdk/source/test/test-unsupported-skip.js", "time": 1466758559850, "action": "test_end", "message": "skip-if: true"}
Could you paste a link to those logs? In the last try run you pasted it looks like JP runs successfully?
(In reply to Andrew Halberstadt [:ahal] from comment #17)
> Could you paste a link to those logs? In the last try run you pasted it
> looks like JP runs successfully?

Yes it ran successfully, however when you check JP raw log in
https://treeherder.mozilla.org/#/jobs?repo=try&revision=d367f9ca0097153aad131d2866a94cc24cb34a44
and read  jetpack-package_raw.log in job details
http://mozilla-releng-blobs.s3.amazonaws.com/blobs/try/sha512/82b55f20746d2492fe3b1e97e81b0d0ccb70d4e4cdc52666ec376a7afe2d2d716265f73e4d204b55b87c57f32cbaf9b8c57643a04c1d2d8f084485761fff104c

Search for "test-end" you would see
{"thread": "ProcessReader", "level": "info", "pid": 1260, "source": "mochitest", "time": 1466758933981, "action": "log", "exc_info": false, "message": "TEST-END | jetpack-package/addon-sdk/source/test/test-addon-bootstrap.js.test install/startup/shutdown/uninstall all return a promise"}

Normally a "test-end" log is "action": "status" instead of "log" and the message here was still plain text but not json formatted.
Posted patch enable-structuredlog (obsolete) — Splinter Review
main idea is to add an extra config filtering non-structured suites and make sure it uses desktopUnittestOutputParser as fallback.
the wrapped function only exists in desktop_unittest.py so should be easy to remove if problem solved.
Attachment #8756696 - Attachment is obsolete: true
Attachment #8768367 - Flags: feedback?(ahalberstadt)
Attachment #8768367 - Attachment is patch: true
Comment on attachment 8768367 [details] [diff] [review]
enable-structuredlog

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

Yeah, something like this makes sense to me!

::: testing/mozharness/configs/unittests/linux_unittest.py
@@ +320,5 @@
>              "halt_on_failure": True,
>              "enabled": ADJUST_MOUSE_AND_SCREEN
>          },
>      ],
> +    "structured_suites": {"mochitest": ["jetpack"]},

If this is what is being ignored, it should be called "unstructured_suites", also the comment should be above it.

::: testing/mozharness/configs/unittests/mac_unittest.py
@@ +246,5 @@
>              "halt_on_failure": True,
>              "enabled": ADJUST_MOUSE_AND_SCREEN
>          },
>      ],
> +    "structured_suites": {"mochitest": ["jetpack"]},

I think the suites you'll want are: 'jetpack-package', 'jetpack-addon' and 'jetpack-package-clipboard'

::: testing/mozharness/scripts/desktop_unittest.py
@@ +686,5 @@
> +        c = self.config
> +        ignore_patterns = c["structured_suites"].get(suite_category)
> +        specified_suites = c["specified_%s_suites" % (suite_category)]
> +        for ignore in ignore_patterns:
> +            return False if ignore in specified_suites

I think this is invalid syntax, you'll need to put the if statement on a separate line
Attachment #8768367 - Flags: feedback?(ahalberstadt) → feedback+
Oh, and rather than overriding the 'structured_output' method, why don't we change the structured_output method and add "every" suite to the ignore list to start. That way the patch to enable a particular suite will simply be to remove that line from the config.
Posted patch enable-structuredlog (obsolete) — Splinter Review
Thanks for feedback!
Second trial, move ignore check to mozharness/mozilla/testing/testbase.py
add parameter "suite" for function get_test_output_parser
fix dependencies.
Attachment #8768367 - Attachment is obsolete: true
Attachment #8769962 - Flags: feedback?(ahalberstadt)
Attachment #8769962 - Attachment is patch: true
Comment on attachment 8769962 [details] [diff] [review]
enable-structuredlog

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

Thanks! Maybe you should break the configuration changes out into a separate patch/bug so you can use this config option for the reftest patch as well. Will web-platform-tests need to be updated too?

::: testing/mozharness/mozharness/mozilla/testing/testbase.py
@@ +480,5 @@
>                                      os.path.join(dirs['abs_work_dir'], 'tests'))
>          self.download_unzip(self.test_url, test_install_dir,
>                               target_unzip_dirs=target_unzip_dirs)
>  
> +    def structured_output(self, suite_category, suite):

I think 'flavor' is the correct term here instead of suite
Attachment #8769962 - Flags: feedback?(ahalberstadt) → feedback+
(In reply to Andrew Halberstadt [:ahal] from comment #23)
> Comment on attachment 8769962 [details] [diff] [review]
> enable-structuredlog
> 
> Review of attachment 8769962 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Thanks! Maybe you should break the configuration changes out into a separate
> patch/bug so you can use this config option for the reftest patch as well.
> Will web-platform-tests need to be updated too?
> 
> ::: testing/mozharness/mozharness/mozilla/testing/testbase.py
> @@ +480,5 @@
> >                                      os.path.join(dirs['abs_work_dir'], 'tests'))
> >          self.download_unzip(self.test_url, test_install_dir,
> >                               target_unzip_dirs=target_unzip_dirs)
> >  
> > +    def structured_output(self, suite_category, suite):
> 
> I think 'flavor' is the correct term here instead of suite

Desktop_unittest.py defines flavor query in https://dxr.mozilla.org/mozilla-central/source/testing/mozharness/scripts/desktop_unittest.py#451

we probably need to add jetpack and/or clipboard in the dict.
Posted patch unstructured_flavor_filters (obsolete) — Splinter Review
divide into two parts
1. unstructured flavor filters:
most of fix is in this patch. will not turn on until 2nd patch merged.
2. enable config:
turn on structured log for reftest by adding config.
Posted patch enable-structured-log (obsolete) — Splinter Review
following patch for enabling structured log by config
Attachment #8769962 - Attachment is obsolete: true
Comment on attachment 8772681 [details] [diff] [review]
unstructured_flavor_filters

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

feeback? ahal to see if any concern.
Attachment #8772681 - Flags: feedback?(ahalberstadt)
Comment on attachment 8772681 [details] [diff] [review]
unstructured_flavor_filters

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

::: testing/mozharness/mozharness/mozilla/testing/testbase.py
@@ +488,5 @@
>          """
> +        structured_categories = self.config.get('structured_suite_categories')
> +        if not structured_categories or suite_category not in structured_categories:
> +            return False
> +        if not flavor:

Should make flavor default to None in the function signature.

@@ +490,5 @@
> +        if not structured_categories or suite_category not in structured_categories:
> +            return False
> +        if not flavor:
> +            return True
> +        ignore_flavors = self.config.get("unstructured_flavors")

Can you add the config changes needed to this patch as well? So it's easier to see how it will look like.
Attachment #8772681 - Flags: feedback?(ahalberstadt) → feedback+
(In reply to Andrew Halberstadt [:ahal] from comment #29)
> Comment on attachment 8772681 [details] [diff] [review]
> unstructured_flavor_filters
> 
> Review of attachment 8772681 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: testing/mozharness/mozharness/mozilla/testing/testbase.py
> @@ +488,5 @@
> >          """
> > +        structured_categories = self.config.get('structured_suite_categories')
> > +        if not structured_categories or suite_category not in structured_categories:
> > +            return False
> > +        if not flavor:
> 
> Should make flavor default to None in the function signature.
> 

Agree.  Will do it for next trial.

> @@ +490,5 @@
> > +        if not structured_categories or suite_category not in structured_categories:
> > +            return False
> > +        if not flavor:
> > +            return True
> > +        ignore_flavors = self.config.get("unstructured_flavors")
> 
> Can you add the config changes needed to this patch as well? So it's easier
> to see how it will look like.

Sure, you mean to merge two attachments?
Comment 27 result actually run by both if you want to see how it worked
Oh yeah, I guess you don't have to merge them. I mostly just wanted to see what the configs would look like, and I can do that from your try push.

I was just looking at the configuration, what would you think about trying to merge those two config options together? Maybe something like:

unstructured_suites = {
    'mochitest': ['jetpack-addon', 'jetpack-package'],
    'reftest': ['reftest', 'crashtest', 'jsreftest'],
    'xpcshell': ['xpcshell'],
    ...
}

With this system, your initial patch would have to have every test suite and flavor in it though. Then to make them structured, you'd remove them from this config. I don't know if this is the best system or not though, what do you think?
Yeah I think it looks better.  Will include those in next patch, thanks!
It is better to code, hence we need to clarify how to deal with not listed suites.
Two options can be considered:
1. Don't enable structured log unless it's in the list
2. Enable by default

I prefer 2 since it forces user to list down all unstructured suites and its flavors; however need to list down all flavors.  Will work like a checklist if we continue to fix them.
Posted patch unstructure_filters (obsolete) — Splinter Review
Try result: https://treeherder.mozilla.org/#/jobs?repo=try&revision=30b669b457e912554977c205ffde6c9af54bd183
Patch modified according to last comment
Attachment #8772681 - Attachment is obsolete: true
Posted patch enable-structured-log (obsolete) — Splinter Review
change config as well
Attachment #8772682 - Attachment is obsolete: true
ahal, those two attachments are with "unstructured_suites" config.  Please kindly provide comments; try result with both patches is in comment 34
Flags: needinfo?(ahalberstadt)
Yeah, I like this config a lot better than the other patch. Would you mind splitting out the changes in testbase.py from the main patch and folding it together with the config changes? Those two changes should definitely be landed as part of the same commit. Then you'd be able to land that patch first (after adding all the other suites to the config as well).
Flags: needinfo?(ahalberstadt)
I'm not sure if we can split them clearly.

from last discussion and comment 33 we make structured_output turned on by default, which leads to:
1. no flavor in argument: use structured log
2. then we check other conditions, fallback if matched
when caller doesn't specify flavor(legacy code), it will use structured log without flavor filtering.
while it affects only mochitests I can give patch and see whether anything failed on try.
try result for testbase + config + desktop_unittest patch

https://treeherder.mozilla.org/#/jobs?repo=try&revision=a905a1fc674b1c785ec9d24837e1e5ffec1d6a8f
Depends on: 1295093
Posted patch enable_configSplinter Review
This patch enables mochitest structured log and uses new flavor filter by bug 1295093.
try result is in https://treeherder.mozilla.org/#/jobs?repo=try&revision=54087638fa0cc1734207cd1d234831a96592602f
Attachment #8776534 - Attachment is obsolete: true
Attachment #8776535 - Attachment is obsolete: true
Attachment #8803281 - Flags: review?(ahalberstadt)
Comment on attachment 8803281 [details] [diff] [review]
enable_config

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

Looks good! I'll do the usual testing before landing.
Attachment #8803281 - Flags: review?(ahalberstadt) → review+
Pushed by ahalberstadt@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/a5f3e15356a8
Use StructuredOutputParser for parsing mochitest test results, r=ahal
https://hg.mozilla.org/mozilla-central/rev/a5f3e15356a8
Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
Depends on: 1313265
Depends on: 1325148
You need to log in before you can comment on or make changes to this bug.