Make Marionette harness test logs parseable by Treeherder

RESOLVED FIXED in Firefox 51

Status

Testing
Marionette
RESOLVED FIXED
2 years ago
a year ago

People

(Reporter: vakila, Assigned: vakila)

Tracking

(Blocks: 1 bug, {ateam-marionette-harness-tests})

Version 3
mozilla51
ateam-marionette-harness-tests
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox51 fixed)

Details

MozReview Requests

Submitter Diff Changes Open Issues Last Updated
Loading...
Error loading review requests:

Attachments

(3 attachments, 5 obsolete attachments)

(Assignee)

Description

2 years ago
Currently, the Marionette harness tests' (job Mn-h) log output doesn't integrate well with Treeherder. For example, in the "Failure Summary" section, no meaningful output is given, only: "No Bug Suggestions Available. Unsuccessful Execution Steps Unnamed step : unknown. View log". (e.g. [1])

Instead, the job should output logs that can be parsed to provide e.g. a "Failure Summary" similar to that of the Marionette tests. (e.g. [2])

We should resolve this by changing the Mn-h tests to produce mozlog logs, instead of the default Pytest log format. 

This will likely involve changing the harness tests and the corresponding mozharness script to use the new pytest-mozlog plugin. [3] The plugin will probably also require further development. 

[1](https://treeherder.mozilla.org/#/jobs?repo=try&author=mjzffr@gmail.com&filter-resultStatus=testfailed&filter-resultStatus=busted&filter-resultStatus=exception&filter-resultStatus&=runnable&selectedJob=23178374)
[2](https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&selectedJob=31352550)
[3](https://github.com/davehunt/pytest-mozlog)
(Assignee)

Comment 2

2 years ago
Created attachment 8770249 [details]
Bug 1285299 - Add pytest_mozlog plugin to mozlog;

(This is a WIP, not ready for merging.)

Add the `pytest_mozlog` module (from https://github.com/davehunt/pytest-mozlog)
to the `harness_unit` tests directory, and register it with Pytest by
adding `conftest.py` in that directory.

Add `test_logging.py` test module to the `harness_unit` tests,
which contains a variety of test types (passing, failing, skipping, etc.)
and makes use of pytest-mozlog `--log-*` command-line options
when calling `pytest.main` from its `if __name__ == '__main__'` block.

When running `./mach python-test --path-only .../harness_unit/test_logging.py`
locally, this now generates the indicated log files (structure log JSON and HTML)
for `test_logging` as specified in the call to `pytest.main`.
Same for `./mach python-test --path-only .../harness_unit/`, which runs both
`test_logging.py` (generating logs) and `test_marionette_runner.py` (no logs).

When running the tests locally with `py.test`, the pytest-mozlog `--log-*`
commands can be passed in at the command line and the specified logs
will be generated.

try: -p linux64 -u marionette-harness -t none

Review commit: https://reviewboard.mozilla.org/r/63746/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/63746/
Attachment #8770249 - Flags: review?(mjzffr)
Comment on attachment 8770249 [details]
Bug 1285299 - Add pytest_mozlog plugin to mozlog;

This is a rough WIP, so replacing review flag with f?
Attachment #8770249 - Flags: review?(mjzffr) → feedback?(mjzffr)
Comment on attachment 8770249 [details]
Bug 1285299 - Add pytest_mozlog plugin to mozlog;

This WIP patch is in line with what we had discussed, so removing f?. Based on our conversations so far, I think you're on the right track: we've agreed that pytest will be vendored in-tree, pytest-mozlog will live under testing/mozbase/mozlog, and marionette harness tests will use pytest-test mozlog as an external, installed plugin (rather than by including it in conftest.py).
Attachment #8770249 - Flags: feedback?(mjzffr)
(Assignee)

Updated

2 years ago
Depends on: 1253359
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
(Assignee)

Updated

2 years ago
Attachment #8770249 - Flags: feedback?(dave.hunt)
(Assignee)

Updated

2 years ago
Attachment #8782962 - Flags: feedback?(dave.hunt)
(Assignee)

Updated

2 years ago
Attachment #8787665 - Flags: feedback?(dave.hunt)
Attachment #8787665 - Flags: feedback?(dave.hunt) → feedback+
Comment on attachment 8782962 [details]
Bug 1285299 - Disable stdout logging by default in pytest-mozlog;

I think it possibly makes sense to make no stdout the default behaviour. Users could still add a formatter for stdout via the command line options if they want but by default they'd just get standard pytest.
Attachment #8782962 - Flags: feedback?(dave.hunt) → feedback-
Attachment #8770249 - Flags: feedback?(dave.hunt) → feedback+
Attachment #8770249 - Flags: review?(mjzffr) → review?(james)
(In reply to Dave Hunt (:davehunt) from comment #14)
> Comment on attachment 8782962 [details]
> Bug 1285299 - Add pytest-mozlog option to stop stdout logging;
> 
> I think it possibly makes sense to make no stdout the default behaviour.
> Users could still add a formatter for stdout via the command line options if
> they want but by default they'd just get standard pytest.

I agree: no stdout by default. Also, the options passed on to mozlog (--log-*) already allow you to specify that you want stdout with '-'.

Comment 16

2 years ago
mozreview-review
Comment on attachment 8782964 [details]
Bug 1285299 - Use pytest_mozlog plugin in Mn-h mozharness script;

https://reviewboard.mozilla.org/r/72966/#review74452
Attachment #8782964 - Flags: review?(mjzffr) → review+

Comment 17

2 years ago
mozreview-review
Comment on attachment 8782962 [details]
Bug 1285299 - Disable stdout logging by default in pytest-mozlog;

https://reviewboard.mozilla.org/r/72962/#review74454

See https://bugzilla.mozilla.org/show_bug.cgi?id=1285299#c15
Attachment #8782962 - Flags: review?(mjzffr) → review-

Comment 18

2 years ago
mozreview-review
Comment on attachment 8787665 [details]
Bug 1285299 - Record error msg and lineno in pytest-mozlog logs;

https://reviewboard.mozilla.org/r/76360/#review74460
Attachment #8787665 - Flags: review?(mjzffr) → review+

Comment 19

2 years ago
mozreview-review
Comment on attachment 8782963 [details]
Bug 1285299 - [TEMP] Add test_logging.py to test Mn-h logging;

https://reviewboard.mozilla.org/r/72964/#review74462
Attachment #8782963 - Flags: review?(mjzffr)
Great work, Anjana. 

With this patch series, the output on Treeherder will be in a different format (tbpl) than the output from running harness tests via ./mach python-test (usual pytest output). Could you add a patch to have them be the same, please? (Or have you already filed a bug about that?) I think you can set default logging options in conftest.py or just update the |if __name__ == '__main__'| blocks in each test module.
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)

Comment 28

2 years ago
mozreview-review
Comment on attachment 8770249 [details]
Bug 1285299 - Add pytest_mozlog plugin to mozlog;

https://reviewboard.mozilla.org/r/63746/#review75010

Looks like a good start, but I have some questions. Some of it is likley to be my lack of understanding of pytest, but I think there are a few real issues here too.

::: testing/mozbase/mozlog/mozlog/pytest_mozlog/plugin.py:9
(Diff revision 4)
> +
> +import mozlog
> +
> +
> +def pytest_addoption(parser):
> +    group = parser.getgroup('mozlog')

Couldn't you call mozlog.commandline.add_logging_group(parser)? You might want to make the group name a parameter to the option.

::: testing/mozbase/mozlog/mozlog/pytest_mozlog/plugin.py:25
(Diff revision 4)
> +                    action=action,
> +                    help=_help)
> +
> +
> +def pytest_configure(config):
> +    if not hasattr(config, 'slaveinput'):

It's not clear to me what this does. At the least add a comment.

::: testing/mozbase/mozlog/mozlog/pytest_mozlog/plugin.py:30
(Diff revision 4)
> +    if not hasattr(config, 'slaveinput'):
> +        config.pluginmanager.register(MozLog())
> +
> +
> +class MozLog(object):
> +

I find this blank line mildly bothersome :)

::: testing/mozbase/mozlog/mozlog/pytest_mozlog/plugin.py:35
(Diff revision 4)
> +
> +    def __init__(self):
> +        self.results = {}
> +
> +    def pytest_configure(self, config):
> +        args = {}

Does it work to do something like

    mozlog.commandline.setup_logging('pytest', config.options)

?

::: testing/mozbase/mozlog/mozlog/pytest_mozlog/plugin.py:53
(Diff revision 4)
> +                        args[argname] = config.getoption(argname)
> +
> +        mozlog.commandline.setup_logging('pytest', args)
> +        self.logger = mozlog.get_default_logger(component='pytest')
> +
> +    def pytest_sessionstart(self, session):

These seem to be a bit undoumented and it's hard for me to tell if they're the right thing to use. It seems like maybe `pytest_collectreport` would give you access to the list of tests that are going to run? Does davehunt have an opinion?

::: testing/mozbase/mozlog/mozlog/pytest_mozlog/plugin.py:66
(Diff revision 4)
> +
> +    def pytest_runtest_logreport(self, report):
> +        test = report.nodeid
> +        status = expected = 'PASS'
> +        if hasattr(report, 'wasxfail'):
> +            expected = 'FAIL'

This looks weird to me?

I think if we get a skip we should set `status = expected = skip` regardless of anything else. If we get `wasxfail` we presumably have `expected = status = FAIL`.

::: testing/mozbase/mozlog/mozlog/pytest_mozlog/plugin.py:75
(Diff revision 4)
> +            status = 'FAIL' if report.when == 'call' else 'ERROR'
> +        elif report.skipped:
> +            status = expected = 'SKIP'
> +        if status != expected:
> +            self.results[test] = (status, expected)
> +        if report.when == 'teardown':

Why are we only logging at teardown? Maybe I don't understand the lifecycle here, but don't we want to either always log or log `test_status` in !teardown and `test_end` at teardown depending on whether this function is called once per assert or once per test function?

::: testing/mozbase/mozlog/mozlog/pytest_mozlog/plugin.py:77
(Diff revision 4)
> +            status = expected = 'SKIP'
> +        if status != expected:
> +            self.results[test] = (status, expected)
> +        if report.when == 'teardown':
> +            status, expected = self.results.get(test, ('PASS', 'PASS'))
> +            self.logger.test_end(test, status, expected)

We should for sure log a message and a stacktrace where the test result is unexpected. Seems like `stack` should be `longreprtext` and `message` should be something derived from `report.get_sections`.

::: testing/mozbase/mozlog/setup.py:37
(Diff revision 4)
>        entry_points={
>            "console_scripts": [
>                "structlog = mozlog.scripts:main"
> +          ],
> +          'pytest11': [
> +            'pytest_mozlog = mozlog.pytest_mozlog.plugin',

Is the `pytest_` at the start of the name here useful? I honestly don't know.
Attachment #8770249 - Flags: review?(james)

Comment 29

2 years ago
mozreview-review
Comment on attachment 8782962 [details]
Bug 1285299 - Disable stdout logging by default in pytest-mozlog;

https://reviewboard.mozilla.org/r/72962/#review75048
Attachment #8782962 - Flags: review?(mjzffr) → review+

Comment 30

2 years ago
mozreview-review
Comment on attachment 8788227 [details]
Bug 1285299 - Report collected item count in pytest-mozlog;

https://reviewboard.mozilla.org/r/76790/#review75050

Yay for logging number of tests!
Just a couple of style nits.

::: testing/mozbase/mozlog/mozlog/pytest_mozlog/plugin.py:62
(Diff revision 1)
>          # Prevent mozlog from logging to stdout by default with `defaults={}`
>          # (User can specify stdout logger using `--log-* -` option)
>          mozlog.commandline.setup_logging('pytest', args, defaults={})
>          self.logger = mozlog.get_default_logger(component='pytest')
>  
> +

Nit: one blank line between methods

::: testing/mozbase/mozlog/mozlog/pytest_mozlog/plugin.py:64
(Diff revision 1)
> -        self.logger.suite_start([])
> +        # we can't log suite_start because Pytest hasn't collected tests yet,
> +        # so we just record the start time (in ms like mozlog does)
> +        # and wait to log suite_start in pytest_collection_modifyitems

Could you make this comment shorter, please? The essence is that start time is in ms + a note that this happens before tests are collected.
Attachment #8788227 - Flags: review?(mjzffr) → review-

Comment 31

2 years ago
mozreview-review
Comment on attachment 8788228 [details]
Bug 1285299 - Add pytest.ini to change logging in local test runs;

https://reviewboard.mozilla.org/r/76792/#review75112

As discussed on vidyo/irc, this doesn't quite work the way it should for mach versus running pytest manually because of how mach's virtualenv is set up. There are several possible fixes/workarounds, so this may require a follow-up bug. (It only affects mach and doesn't block us on producing good logs for Treeherder so let's drop this patch for now.)
Attachment #8788228 - Flags: review?(mjzffr) → review-
Attachment #8782963 - Flags: review?(mjzffr)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
(Assignee)

Updated

2 years ago
Attachment #8782962 - Attachment is obsolete: true
(Assignee)

Updated

2 years ago
Attachment #8787665 - Attachment is obsolete: true
(Assignee)

Updated

2 years ago
Attachment #8788227 - Attachment is obsolete: true
(Assignee)

Updated

2 years ago
Attachment #8788228 - Attachment is obsolete: true
(Assignee)

Comment 35

2 years ago
mozreview-review-reply
Comment on attachment 8770249 [details]
Bug 1285299 - Add pytest_mozlog plugin to mozlog;

https://reviewboard.mozilla.org/r/63746/#review75010

> Couldn't you call mozlog.commandline.add_logging_group(parser)? You might want to make the group name a parameter to the option.

Wouldn't that add options to the Mozlog command line, rather than to the Pytest command line? (Or maybe I am completely misunderstanding?)

> It's not clear to me what this does. At the least add a comment.

I added a comment based on my understanding, but would need davehunt to confirm that it's correct.

> Does it work to do something like
> 
>     mozlog.commandline.setup_logging('pytest', config.options)
> 
> ?

If we pass the options dictionary (`config.known_args_namespace`, as far as I can tell) as `args`, Mozlog sees the keys for formatter options like `'log_tbpl_level': None` and complains that "Options specified for unused formatter(s) (['tbpl']) have no effect". So we need to go through and make sure only keys with non-None values are passed into the args. (Again, this is my understanding, davehunt could give more insight.)

> These seem to be a bit undoumented and it's hard for me to tell if they're the right thing to use. It seems like maybe `pytest_collectreport` would give you access to the list of tests that are going to run? Does davehunt have an opinion?

In a previously separate patch that I've now squashed in, I changed this, logging the suite start in `pytest_collect_modifyitems` instead so we can get the right test count (the names are a bit misleading; I chose `pytest_collect_modifyitems` because it runs once after all items have been collected, whereas `pytest_collectreport` is run multiple times and is therefore harder to work with).

> This looks weird to me?
> 
> I think if we get a skip we should set `status = expected = skip` regardless of anything else. If we get `wasxfail` we presumably have `expected = status = FAIL`.

For some reason Pytest seems to used `skipped` in the `'call'` report of an xfail test to indicate that it has failed as expected, so I guess that's what was going on here. 

I was thinking that it would be good to report the actual status of a skipped/xfail test, instead of reporting it simply as a pass, so in the latest patch I've included some changes that do that. This way we get accurate reports/messages for skipped and xfailed tests. 

But I can revert it to `status = expected = 'SKIP'` and `status = expected = 'FAIL'` (meaning that ultimately both are marked `status = expected = 'PASS'`) if the other way seems like overkill.

> Why are we only logging at teardown? Maybe I don't understand the lifecycle here, but don't we want to either always log or log `test_status` in !teardown and `test_end` at teardown depending on whether this function is called once per assert or once per test function?

As I've understood it, this runs 3 times for each test (setup, call, teardown); 'call' is typically where we get the result, but we can't log anything until teardown because e.g. failures in both call and teardown would mean we'd have to report an error instead of a failure.

> We should for sure log a message and a stacktrace where the test result is unexpected. Seems like `stack` should be `longreprtext` and `message` should be something derived from `report.get_sections`.

Error messages and stack traces are added now (from a previously-separate patch that's now squashed in). Hopefully the message content/format seems OK, if not happy to change it.

> Is the `pytest_` at the start of the name here useful? I honestly don't know.

It seems we can make the name to the left of the `=` whatever we want; I kept `pytest_mozlog` because that was the name of the plugin in davehunt's Github repo.
(Assignee)

Updated

2 years ago
Attachment #8770249 - Flags: feedback?(mjzffr)
Attachment #8770249 - Flags: feedback?(dave.hunt)
(Assignee)

Comment 36

2 years ago
(In reply to Maja Frydrychowicz (:maja_zf) from comment #31)
> Comment on attachment 8788228 [details]
> Bug 1285299 - Add pytest.ini to change logging in local test runs;
> 
> https://reviewboard.mozilla.org/r/76792/#review75112
> 
> As discussed on vidyo/irc, this doesn't quite work the way it should for
> mach versus running pytest manually because of how mach's virtualenv is set
> up. There are several possible fixes/workarounds, so this may require a
> follow-up bug. (It only affects mach and doesn't block us on producing good
> logs for Treeherder so let's drop this patch for now.)

To elaborate: Maja discovered that the way mach installs Mozlog in the virtualenv doesn't use the setup.py file in which we're telling Pytest about the entry point for pytest-mozlog. So in automation, or when the package is installed manually with pip and the tests are run with `py.test`, the plugin is registered as soon as Mozlog is installed, whereas when the tests are run locally with `mach python-test`, we need to register the plugin explicitly (e.g. in conftest.py, pytest.ini, or the command-line arguments to Pytest). 

As Maja noted, there are different ways we could work around this, but one way to do it would be to simply remove the Pytest entry point for pytest_mozlog in the Mozlog setup.py. I'll file a separate bug to deal with this issue, but I wanted to mention it here because I wonder whether it actually makes sense to add the pytest entry point line to Mozlog's setup.py (as we do in these patches), as opposed to letting the plugin sort of lay dormant within Mozlog and requiring folks to explicitly register it if they want Pytest to use it. Personally, I think the "opt-in" approach actually seems more reasonable than "opt-out". Thoughts?
Flags: needinfo?(james)
Flags: needinfo?(dave.hunt)
(In reply to Anjana Vakil (:vakila) from comment #36)
> As Maja noted, there are different ways we could work around this, but one
> way to do it would be to simply remove the Pytest entry point for
> pytest_mozlog in the Mozlog setup.py. I'll file a separate bug to deal with
> this issue, but I wanted to mention it here because I wonder whether it
> actually makes sense to add the pytest entry point line to Mozlog's setup.py
> (as we do in these patches), as opposed to letting the plugin sort of lay
> dormant within Mozlog and requiring folks to explicitly register it if they
> want Pytest to use it. Personally, I think the "opt-in" approach actually
> seems more reasonable than "opt-out". Thoughts?

It's likely that some of the web automation using pytest would want to generate suitable logs for submitting to Treeherder. For this reason it would be preferable for those projects to simply add a dependency for mozlog and have the pytest-mozlog plugin available, rather than adding any code to register this plugin for these projects.
Flags: needinfo?(dave.hunt)

Comment 39

2 years ago
mozreview-review-reply
Comment on attachment 8770249 [details]
Bug 1285299 - Add pytest_mozlog plugin to mozlog;

https://reviewboard.mozilla.org/r/63746/#review75010

> Wouldn't that add options to the Mozlog command line, rather than to the Pytest command line? (Or maybe I am completely misunderstanding?)

It adds options to whatever parser you pass in. In this case that would be the pytest one.

> If we pass the options dictionary (`config.known_args_namespace`, as far as I can tell) as `args`, Mozlog sees the keys for formatter options like `'log_tbpl_level': None` and complains that "Options specified for unused formatter(s) (['tbpl']) have no effect". So we need to go through and make sure only keys with non-None values are passed into the args. (Again, this is my understanding, davehunt could give more insight.)

I think I would still prefer to go through the existing code, even if we have to allow it to ignore unused options.

> For some reason Pytest seems to used `skipped` in the `'call'` report of an xfail test to indicate that it has failed as expected, so I guess that's what was going on here. 
> 
> I was thinking that it would be good to report the actual status of a skipped/xfail test, instead of reporting it simply as a pass, so in the latest patch I've included some changes that do that. This way we get accurate reports/messages for skipped and xfailed tests. 
> 
> But I can revert it to `status = expected = 'SKIP'` and `status = expected = 'FAIL'` (meaning that ultimately both are marked `status = expected = 'PASS'`) if the other way seems like overkill.

OK, I will read the new code more closely.

> Error messages and stack traces are added now (from a previously-separate patch that's now squashed in). Hopefully the message content/format seems OK, if not happy to change it.

OK. Will check the new code.

Comment 40

2 years ago
mozreview-review-reply
Comment on attachment 8770249 [details]
Bug 1285299 - Add pytest_mozlog plugin to mozlog;

https://reviewboard.mozilla.org/r/63746/#review75010

> It adds options to whatever parser you pass in. In this case that would be the pytest one.

I think reviewboard lost all my comments because I didn't understand the UI... So pytest's parser does not have an add_argument_group method, which is assumed by mozlog when calling add_logging_group. See https://github.com/pytest-dev/pytest/blob/3a200b75c963768a8b3a17aa92128e95c7dc99d4/_pytest/config.py#L424 and https://dxr.mozilla.org/mozilla-central/source/testing/mozbase/mozlog/mozlog/commandline.py#127

> I added a comment based on my understanding, but would need davehunt to confirm that it's correct.

This ensures that if you're using pytest-xdist you only register the plugin on the master process.

> I think I would still prefer to go through the existing code, even if we have to allow it to ignore unused options.

It would certainly be more elegant to have mozlog handly the unused options. I had made a comment previously stating that the original pytest-mozlog plugin was thrown together as a quick prototype, and that I wrote this as it is to avoid the issue :vakila described. Also, the original plugin was in a separate repo so not as easy to tweak mozlog at the same time.

> In a previously separate patch that I've now squashed in, I changed this, logging the suite start in `pytest_collect_modifyitems` instead so we can get the right test count (the names are a bit misleading; I chose `pytest_collect_modifyitems` because it runs once after all items have been collected, whereas `pytest_collectreport` is run multiple times and is therefore harder to work with).

So I think there was an issue with pytest_collect_modifyitems and pytest-xdist when running tests in parallel. Either it wasn't called at all, or it was called multple times. I can't remember the specifics but I did try to use other hooks to include the test count.

> OK, I will read the new code more closely.

If I recall correctly skip+wasxfail is an unexpected pass, and pytest reports these as XPass. Because the expected and actual do not match, this should result in an effective test failure.

> As I've understood it, this runs 3 times for each test (setup, call, teardown); 'call' is typically where we get the result, but we can't log anything until teardown because e.g. failures in both call and teardown would mean we'd have to report an error instead of a failure.

I did consider using subtests for setup/call/teardown, but wasn't particularly happen with the implementation.

> It seems we can make the name to the left of the `=` whatever we want; I kept `pytest_mozlog` because that was the name of the plugin in davehunt's Github repo.

This name made sense when it was potentially going to be released as a python package, but agree we can make it whatever we want now.

Comment 41

2 years ago
mozreview-review-reply
Comment on attachment 8770249 [details]
Bug 1285299 - Add pytest_mozlog plugin to mozlog;

https://reviewboard.mozilla.org/r/63746/#review75010

> I think reviewboard lost all my comments because I didn't understand the UI... So pytest's parser does not have an add_argument_group method, which is assumed by mozlog when calling add_logging_group. See https://github.com/pytest-dev/pytest/blob/3a200b75c963768a8b3a17aa92128e95c7dc99d4/_pytest/config.py#L424 and https://dxr.mozilla.org/mozilla-central/source/testing/mozbase/mozlog/mozlog/commandline.py#127

Oh, this is annoying. It appears to be gratuitiously incompatible despite using argparse since the actual parser isn't created until the options are parsed.
(Assignee)

Comment 42

2 years ago
mozreview-review-reply
Comment on attachment 8770249 [details]
Bug 1285299 - Add pytest_mozlog plugin to mozlog;

https://reviewboard.mozilla.org/r/63746/#review75010

> If I recall correctly skip+wasxfail is an unexpected pass, and pytest reports these as XPass. Because the expected and actual do not match, this should result in an effective test failure.

Do you mean skip+wasxfail in the 'call' report? If so, Pytest considers that an xfail, as far as I've understood. If you mean a test that is marked as both xfail and skip, it seems to consider it just a regular skip, i.e. the 'setup' report has `.skipped`. Unless I've misunderstood something?

In the changes I made, I'm reporting an xfail that fails as 'TEST_FAIL' (which is a green/expected result), an xfail that passes as 'TEST_UNEXPECTED_PASS' (red/unexpected), and an xfail that's also skipped as 'TEST_SKIP'.

Comment 43

2 years ago
mozreview-review-reply
Comment on attachment 8770249 [details]
Bug 1285299 - Add pytest_mozlog plugin to mozlog;

https://reviewboard.mozilla.org/r/63746/#review75010

> Do you mean skip+wasxfail in the 'call' report? If so, Pytest considers that an xfail, as far as I've understood. If you mean a test that is marked as both xfail and skip, it seems to consider it just a regular skip, i.e. the 'setup' report has `.skipped`. Unless I've misunderstood something?
> 
> In the changes I made, I'm reporting an xfail that fails as 'TEST_FAIL' (which is a green/expected result), an xfail that passes as 'TEST_UNEXPECTED_PASS' (red/unexpected), and an xfail that's also skipped as 'TEST_SKIP'.

Sorry for not being clear, I meant that a test marked as expected to fail that actually passes is indicated by a skip. I actually think this may have changed in pytest 3.0 though (https://github.com/pytest-dev/pytest/pull/1795). Your reporting sounds good, except for the final statement because I'm not sure where you can have a test that's both genuinely skipped and wasxfail.

Comment 44

2 years ago
mozreview-review
Comment on attachment 8770249 [details]
Bug 1285299 - Add pytest_mozlog plugin to mozlog;

https://reviewboard.mozilla.org/r/63746/#review75464

::: testing/mozbase/mozlog/mozlog/pytest_mozlog/plugin.py:10
(Diff revision 5)
> +import mozlog
> +import os
> +import time
> +
> +def pytest_addoption(parser):
> +    group = parser.getgroup('mozlog')

Comment on why we can't use the normal mozlog stuff here.

::: testing/mozbase/mozlog/mozlog/pytest_mozlog/plugin.py:34
(Diff revision 5)
> +
> +
> +class MozLog(object):
> +    def __init__(self):
> +        self.results = {}
> +        self.start_time = 0

Maybe set this to `time.time()` by default.

::: testing/mozbase/mozlog/mozlog/pytest_mozlog/plugin.py:77
(Diff revision 5)
> +
> +    def pytest_runtest_logstart(self, nodeid, location):
> +        self.logger.test_start(test=self.format_nodeid(nodeid))
> +
> +    def pytest_runtest_logreport(self, report):
> +        test = report.nodeid

Docstring indicating that this is called 3x per test would help

::: testing/mozbase/mozlog/mozlog/pytest_mozlog/plugin.py:80
(Diff revision 5)
> +
> +    def pytest_runtest_logreport(self, report):
> +        test = report.nodeid
> +        status = expected = 'PASS'
> +        message = stack = None
> +        if hasattr(report, 'wasxfail'):

Since this seems to be super-confusing can we have a detailed comment about what the behaviour of pytest with xfail is?

::: testing/mozbase/mozlog/mozlog/pytest_mozlog/plugin.py:91
(Diff revision 5)
> +            status = 'FAIL' if report.when == 'call' else 'ERROR'
> +            crash = report.longrepr.reprcrash
> +            message = "{0} (line {1})".format(crash.message, crash.lineno)
> +            stack = report.longrepr.reprtraceback
> +        elif report.skipped:  # indicates true skip
> +            status = 'SKIP'

Surely we should also set `expected = "SKIP"`?

::: testing/mozbase/mozlog/mozlog/pytest_mozlog/plugin.py:92
(Diff revision 5)
> +            crash = report.longrepr.reprcrash
> +            message = "{0} (line {1})".format(crash.message, crash.lineno)
> +            stack = report.longrepr.reprtraceback
> +        elif report.skipped:  # indicates true skip
> +            status = 'SKIP'
> +            message = report.longrepr[-1]

This `[-1]` seems weird compared to the field names above.

::: testing/mozbase/mozlog/mozlog/pytest_mozlog/plugin.py:93
(Diff revision 5)
> +            message = "{0} (line {1})".format(crash.message, crash.lineno)
> +            stack = report.longrepr.reprtraceback
> +        elif report.skipped:  # indicates true skip
> +            status = 'SKIP'
> +            message = report.longrepr[-1]
> +        if status != expected or expected == 'FAIL':

Any reason not to do this always i.e. just

    self.results[test] = (status, expected, message, stack)
    if report.when = "teardown":
        status, expected, message, stack = self.results[test]
        self.logger.test_end(self.format_nodeid(test),
                     status=status,
                     expected=expected,
                     message=message,
                     stack=stack)
Attachment #8770249 - Flags: review?(james)
Attachment #8782963 - Flags: review?(mjzffr)
Comment on attachment 8770249 [details]
Bug 1285299 - Add pytest_mozlog plugin to mozlog;

I agree with the other suggestions made so far. lgtm overall.
Attachment #8770249 - Flags: feedback?(mjzffr) → feedback+
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
(Assignee)

Comment 50

2 years ago
mozreview-review-reply
Comment on attachment 8770249 [details]
Bug 1285299 - Add pytest_mozlog plugin to mozlog;

https://reviewboard.mozilla.org/r/63746/#review75464

> This `[-1]` seems weird compared to the field names above.

This is because the `longrepr`s for fails/errors and skips are of different types (`ReprExceptionInfo` and tuple, respectively) - added comments explaining as much.

> Any reason not to do this always i.e. just
> 
>     self.results[test] = (status, expected, message, stack)
>     if report.when = "teardown":
>         status, expected, message, stack = self.results[test]
>         self.logger.test_end(self.format_nodeid(test),
>                      status=status,
>                      expected=expected,
>                      message=message,
>                      stack=stack)

If we do it this way, then when the hook is called at teardown pretty much everything gets reset to PASS/PASS, so we lose all our information about fails/errors/skips.
(Assignee)

Comment 51

2 years ago
mozreview-review-reply
Comment on attachment 8770249 [details]
Bug 1285299 - Add pytest_mozlog plugin to mozlog;

https://reviewboard.mozilla.org/r/63746/#review75010

> Oh, this is annoying. It appears to be gratuitiously incompatible despite using argparse since the actual parser isn't created until the options are parsed.

Added a comment explaining this.

> It would certainly be more elegant to have mozlog handly the unused options. I had made a comment previously stating that the original pytest-mozlog plugin was thrown together as a quick prototype, and that I wrote this as it is to avoid the issue :vakila described. Also, the original plugin was in a separate repo so not as easy to tweak mozlog at the same time.

Added a patch to Mozlog that adds an `allow_unused_options` parameter to stop mozlog from raising this error.

> So I think there was an issue with pytest_collect_modifyitems and pytest-xdist when running tests in parallel. Either it wasn't called at all, or it was called multple times. I can't remember the specifics but I did try to use other hooks to include the test count.

The way it stands, pytest_mozlog has several problems with pytest-xdist. Some are related to the modifications I made to the plugin, others are related to xdist's assumption that terminalreporter will not be disabled. For now, since the Marionette harness tests seem to be the only user of pytest_mozlog and we're not (yet) using xdist, it should be OK, but as davehunt pointed out we'll want to fix this sooner or later - I'll file a follow-up bug for that.

> Sorry for not being clear, I meant that a test marked as expected to fail that actually passes is indicated by a skip. I actually think this may have changed in pytest 3.0 though (https://github.com/pytest-dev/pytest/pull/1795). Your reporting sounds good, except for the final statement because I'm not sure where you can have a test that's both genuinely skipped and wasxfail.

Now setting `status = expected = 'SKIP'` for skipping tests, and added some comments explaining Pytest's xfail reporting behavior.

> This name made sense when it was potentially going to be released as a python package, but agree we can make it whatever we want now.

Renamed it to `mozlog` in the setup.py.
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
(Assignee)

Updated

2 years ago
Attachment #8770249 - Flags: feedback?(mjzffr)
Attachment #8770249 - Flags: feedback?(dave.hunt)
Attachment #8782963 - Flags: review?(mjzffr)
(Assignee)

Updated

2 years ago
Blocks: 1301177

Comment 55

2 years ago
mozreview-review
Comment on attachment 8770249 [details]
Bug 1285299 - Add pytest_mozlog plugin to mozlog;

https://reviewboard.mozilla.org/r/63746/#review75804

::: testing/mozbase/mozlog/mozlog/pytest_mozlog/plugin.py:85
(Diff revision 7)
> +            message = "{0} (line {1})".format(crash.message, crash.lineno)
> +            stack = report.longrepr.reprtraceback
> +        elif report.skipped:  # indicates true skip
> +            status = expected = 'SKIP'
> +            message = report.longrepr[-1]  # here longrepr is a tuple (file, lineno, reason)
> +        if status != expected or expected == 'FAIL':

It is still not completely obvious to me that this works in all cases e.g. I assume for skip we must get a  when=teardown with the skip status, or we will report it as pass, but I can't tell how one should know that's what happens.

I wonder if, as a followup, it's possible to find a way to test this code with some pytests that should produce different results.
Attachment #8770249 - Flags: review?(james) → review+

Comment 56

2 years ago
mozreview-review
Comment on attachment 8789008 [details]
Bug 1285299 - Optionally ignore unused Mozlog formatter options;

https://reviewboard.mozilla.org/r/77296/#review75800
Attachment #8789008 - Flags: review?(james) → review+
Attachment #8770249 - Flags: feedback?(dave.hunt) → feedback+
(Assignee)

Comment 57

2 years ago
mozreview-review-reply
Comment on attachment 8770249 [details]
Bug 1285299 - Add pytest_mozlog plugin to mozlog;

https://reviewboard.mozilla.org/r/63746/#review75804

> It is still not completely obvious to me that this works in all cases e.g. I assume for skip we must get a  when=teardown with the skip status, or we will report it as pass, but I can't tell how one should know that's what happens.
> 
> I wonder if, as a followup, it's possible to find a way to test this code with some pytests that should produce different results.

I've been testing all of this out with the file "test_logging.py", added in the "[TEMP]" commit on this patch series, which has a bunch of different pytest configurations (failing, skipping, xfailing, etc.). The results can be seen on Treeherder (e.g. https://treeherder.mozilla.org/#/jobs?repo=try&revision=4857feff16f5).

Anyway I agree, none of this is obvious at all! :) For skips actually we should see a `when='setup' outcome='skipped'` report, then no `'call'` report at all (because of the skip - i.e. this method only executes twice for skipped tests), then a `when='teardown' outcome='passed'` report. 

I now realize this is why, in my previous patch, in line 83 I was changing only `status = 'SKIP'` and not `status = expected = 'SKIP'` - I was using the `status != expected` to log the skip in `self.results` during `'setup'` (`status='SKIP'`, `outcome='PASS')`. (Mozlog actually seems not to care about the expected value if status is 'SKIP'.) Now that I changed it to be `status = expected = 'SKIP'`, we're once again logging skips as 'PASS', instead of actually as 'SKIP'. So I'm going to change it back and push the new patch, if that's OK.
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)

Comment 64

2 years ago
mozreview-review
Comment on attachment 8782963 [details]
Bug 1285299 - [TEMP] Add test_logging.py to test Mn-h logging;

https://reviewboard.mozilla.org/r/72964/#review75920

Remember to remove this patch. Then I will land.
Attachment #8782963 - Flags: review?(mjzffr) → review-
(Assignee)

Updated

2 years ago
Attachment #8782963 - Attachment is obsolete: true

Comment 65

2 years ago
Pushed by mjzffr@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/4aac4b3f3b53
Optionally ignore unused Mozlog formatter options; r=jgraham
https://hg.mozilla.org/integration/autoland/rev/0cd81275950d
Add pytest_mozlog plugin to mozlog; r=jgraham
https://hg.mozilla.org/integration/autoland/rev/0569d570905b
Use pytest_mozlog plugin in Mn-h mozharness script; r=maja_zf

Comment 66

2 years ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/4aac4b3f3b53
https://hg.mozilla.org/mozilla-central/rev/0cd81275950d
https://hg.mozilla.org/mozilla-central/rev/0569d570905b
Status: NEW → RESOLVED
Last Resolved: 2 years ago
status-firefox51: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla51
Flags: needinfo?(james)
Keywords: ateam-marionette-harness-tests
You need to log in before you can comment on or make changes to this bug.