1261194 - Use StructuredOutputParser for parsing mochitest test results

Status: RESOLVED FIXED

(Release Engineering :: Applications: MozharnessCore, defect)

Description

[Andrew Halberstadt [:ahal]]

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.

Comment 1

[Paul Yang [:pyang] (away)]

Attachment: patch.diff

Simply add structurelog parsing for mochitest, and make sure output raw log is enabled when running "structured_suites"

Comment 2

[Andrew Halberstadt [:ahal]]

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):

Comment 3

[Paul Yang [:pyang] (away)]

Attachment: patch.diff

Updated, add structured_suites for rest of configs

Comment 4

[Paul Yang [:pyang] (away)]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=5538a8e3342a

Comment 5

[Paul Yang [:pyang] (away)]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=9ee2204adb25

Comment 6

[Paul Yang [:pyang] (away)]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=07321a716921

Comment 7

[Paul Yang [:pyang] (away)]

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.

Comment 8

[Paul Yang [:pyang] (away)]

(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.

Comment 9

[Paul Yang [:pyang] (away)]

Attachment: mochitest-log

Updated
for Bug 1274584
tree report for windows https://treeherder.mozilla.org/#/jobs?repo=try&revision=9feb21803239a28be5ac14eeee9debb103a73f33
force_refresh test passed.

Comment 10

[Andrew Halberstadt [:ahal]]

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.

Comment 11

[Paul Yang [:pyang] (away)]

I'm okay to block this until bug 1274584 fixed.  Will use this patch for finding other issues.

Comment 12

[Paul Yang [:pyang] (away)]

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?

Comment 13

[Andrew Halberstadt [:ahal]]

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.

Comment 14

[Paul Yang [:pyang] (away)]

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.

Comment 15

[Paul Yang [:pyang] (away)]

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"}

Comment 16

[Paul Yang [:pyang] (away)]

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"}

Comment 17

[Andrew Halberstadt [:ahal]]

Could you paste a link to those logs? In the last try run you pasted it looks like JP runs successfully?

Comment 18

[Paul Yang [:pyang] (away)]

(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.

Comment 19

[Paul Yang [:pyang] (away)]

Attachment: enable-structuredlog

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.

Comment 20

[Andrew Halberstadt [:ahal]]

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

Comment 21

[Andrew Halberstadt [:ahal]]

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.

Comment 22

[Paul Yang [:pyang] (away)]

Attachment: enable-structuredlog

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.

Comment 23

[Andrew Halberstadt [:ahal]]

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

Comment 24

[Paul Yang [:pyang] (away)]

(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.

Comment 25

[Paul Yang [:pyang] (away)]

Attachment: unstructured_flavor_filters

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.

Comment 26

[Paul Yang [:pyang] (away)]

Attachment: enable-structured-log

following patch for enabling structured log by config

Comment 27

[Paul Yang [:pyang] (away)]

try result
https://treeherder.mozilla.org/#/jobs?repo=try&revision=5004baa85bd98574cb392d66f233fbe5c79f5ca5&selectedJob=24124681
looks ok and most failures are not relevant.

Comment 28

[Paul Yang [:pyang] (away)]

Comment on attachment 8772681 [details] [diff] [review]
unstructured_flavor_filters

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

feeback? ahal to see if any concern.

Comment 29

[Andrew Halberstadt [:ahal]]

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.

Comment 30

[Paul Yang [:pyang] (away)]

(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

Comment 31

[Andrew Halberstadt [:ahal]]

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?

Comment 32

[Paul Yang [:pyang] (away)]

Yeah I think it looks better.  Will include those in next patch, thanks!

Comment 33

[Paul Yang [:pyang] (away)]

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.

Comment 34

[Paul Yang [:pyang] (away)]

Attachment: unstructure_filters

Try result: https://treeherder.mozilla.org/#/jobs?repo=try&revision=30b669b457e912554977c205ffde6c9af54bd183
Patch modified according to last comment

Comment 35

[Paul Yang [:pyang] (away)]

Attachment: enable-structured-log

change config as well

Comment 36

[Paul Yang [:pyang] (away)]

ahal, those two attachments are with "unstructured_suites" config.  Please kindly provide comments; try result with both patches is in comment 34

Comment 37

[Andrew Halberstadt [:ahal]]

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).

Comment 38

[Paul Yang [:pyang] (away)]

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.

Comment 39

[Paul Yang [:pyang] (away)]

try result for testbase + config + desktop_unittest patch

https://treeherder.mozilla.org/#/jobs?repo=try&revision=a905a1fc674b1c785ec9d24837e1e5ffec1d6a8f

Comment 40

[Paul Yang [:pyang] (away)]

Attachment: enable_config

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

Comment 41

[Andrew Halberstadt [:ahal]]

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.

Comment 42

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/a5f3e15356a8
Use StructuredOutputParser for parsing mochitest test results, r=ahal

Comment 43

[Phil Ringnalda (:philor)]

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