1285299 - Make Marionette harness test logs parseable by Treeherder

Status: RESOLVED FIXED

(Remote Protocol :: Marionette, defect)

Description

[Anjana Vakil (:vakila)]

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=[e-mail]&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)

Comment 1

[Anjana Vakil (:vakila)]

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

Comment 2

[Anjana Vakil (:vakila)]

Attachment: 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/

Comment 3

[Maja Frydrychowicz :impossibus (was :maja_zf) (needinfo me)]

Comment on attachment 8770249 [details]
Bug 1285299 - Add pytest_mozlog plugin to mozlog;

This is a rough WIP, so replacing review flag with f?

Comment 4

[Maja Frydrychowicz :impossibus (was :maja_zf) (needinfo me)]

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

Comment 5

[Anjana Vakil (:vakila)]

Attachment: Bug 1285299 - Disable stdout logging by default in pytest-mozlog;

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

Add a conftest.py file to the Marionette harness tests
directory so that we can use the pytest_mozlog plugin
(now in mozlog) in these tests.

Review commit: https://reviewboard.mozilla.org/r/72962/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/72962/

Comment 6

[Anjana Vakil (:vakila)]

Attachment: Bug 1285299 - [TEMP] Add test_logging.py to test Mn-h logging;

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

Add a test module `test_logging.py` to the Marionette harness
unit tests, for experimenting with/testing the log output
using the new pytest_mozlog plugin. The plugin is used
by passing mozlog arguments (e.g. `--log-raw`) to the
call to `pytest.main`.

Review commit: https://reviewboard.mozilla.org/r/72964/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/72964/

Comment 7

[Anjana Vakil (:vakila)]

Attachment: Bug 1285299 - Use pytest_mozlog plugin in Mn-h mozharness script;

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

Modify the mozharness script for the Marionette harness tests
to use the new pytest_mozlog plugin, so that the logs produced
will be parseable by Treeherder.

Change the arguments passed to `pytest.main` to instruct pytest_mozlog
to write log files in mozlog formats (TBPL and raw structured
logs, for the moment). Read the TBPL log into the
mozharness script log itself.

Review commit: https://reviewboard.mozilla.org/r/72966/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/72966/

Comment 8

[Anjana Vakil (:vakila)]

Comment on attachment 8770249 [details]
Bug 1285299 - Add pytest_mozlog plugin to mozlog;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/63746/diff/1-2/

Comment 9

[Anjana Vakil (:vakila)]

Attachment: Bug 1285299 - Record error msg and lineno in pytest-mozlog logs;

Extract the error message and line number for tests with failures/
errors from the Pytest test report, and pass these to the Mozlog
logs output by the pytest-mozlog plugin. This replaces the less
helpful error message "expected PASS" with information about the
specific failure/error, e.g. "assert 5 == 10 (line 13)".

Review commit: https://reviewboard.mozilla.org/r/76360/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/76360/

Comment 10

[Anjana Vakil (:vakila)]

Comment on attachment 8770249 [details]
Bug 1285299 - Add pytest_mozlog plugin to mozlog;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/63746/diff/2-3/

Comment 11

[Anjana Vakil (:vakila)]

Comment on attachment 8782962 [details]
Bug 1285299 - Disable stdout logging by default in pytest-mozlog;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/72962/diff/1-2/

Comment 12

[Anjana Vakil (:vakila)]

Comment on attachment 8782964 [details]
Bug 1285299 - Use pytest_mozlog plugin in Mn-h mozharness script;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/72966/diff/1-2/

Comment 13

[Anjana Vakil (:vakila)]

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

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/72964/diff/1-2/

Comment 14

[Dave Hunt [:davehunt] [he/him] ⌚BST]

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.

Comment 15

[Maja Frydrychowicz :impossibus (was :maja_zf) (needinfo me)]

(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

[Maja Frydrychowicz :impossibus (was :maja_zf) (needinfo me)]

Comment on attachment 8782964 [details]
Bug 1285299 - Use pytest_mozlog plugin in Mn-h mozharness script;

https://reviewboard.mozilla.org/r/72966/#review74452

Comment 17

[Maja Frydrychowicz :impossibus (was :maja_zf) (needinfo me)]

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

Comment 18

[Maja Frydrychowicz :impossibus (was :maja_zf) (needinfo me)]

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

https://reviewboard.mozilla.org/r/76360/#review74460

Comment 19

[Maja Frydrychowicz :impossibus (was :maja_zf) (needinfo me)]

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

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

Comment 20

[Maja Frydrychowicz :impossibus (was :maja_zf) (needinfo me)]

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 21

[Anjana Vakil (:vakila)]

Attachment: Bug 1285299 - Report collected item count in pytest-mozlog;

Add/modify Pytest hooks in the pytest-mozlog plugin so that the
suite_start event sent to the logger contains the correct list
of tests to be run, i.e. items collected by Pytest, instead
of an empty list. This allows mozlog to log the correct number
of tests to be run, instead of always loggin "Running 0 tests".

Instead of logging the suite_start event in the pytest_sessionstart
hook, use that hook to simply record the session start time.
Add the pytest_collection_modifyitems hook, which is executed
after tests are collected and before they are run, and log
the suite_start event in that hook, passing in the start time
and the list of tests.

Review commit: https://reviewboard.mozilla.org/r/76790/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/76790/

Comment 22

[Anjana Vakil (:vakila)]

Attachment: Bug 1285299 - Add pytest.ini to change logging in local test runs;

Add the Pytest manifest file "pytest.ini" to the `tests/harness_unit`
directory, to modify the arguments passed to the `pytest.main` call
for all tests. This may override the `pytest.main` options specified
in the `if __name__ == '__main__'` block for each test module,
and thus can be used to set defaults for all modules at once.

Add options to disable Pytest's terminalreporter (default Pytest
stdout logging) and instead use the pytest-mozlog plugin to log
to stdout with TBPL formatting. As TBPL logs are used when the
harness unit tests are run on Taskcluster, this makes the output
when running the tests locally match the output in automation.

Review commit: https://reviewboard.mozilla.org/r/76792/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/76792/

Comment 23

[Anjana Vakil (:vakila)]

Comment on attachment 8770249 [details]
Bug 1285299 - Add pytest_mozlog plugin to mozlog;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/63746/diff/3-4/

Comment 24

[Anjana Vakil (:vakila)]

Comment on attachment 8782962 [details]
Bug 1285299 - Disable stdout logging by default in pytest-mozlog;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/72962/diff/2-3/

Comment 25

[Anjana Vakil (:vakila)]

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

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/76360/diff/1-2/

Comment 26

[Anjana Vakil (:vakila)]

Comment on attachment 8782964 [details]
Bug 1285299 - Use pytest_mozlog plugin in Mn-h mozharness script;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/72966/diff/2-3/

Comment 27

[Anjana Vakil (:vakila)]

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

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/72964/diff/2-3/

Comment 28

[James Graham [:jgraham]]

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.

Comment 29

[Maja Frydrychowicz :impossibus (was :maja_zf) (needinfo me)]

Comment on attachment 8782962 [details]
Bug 1285299 - Disable stdout logging by default in pytest-mozlog;

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

Comment 30

[Maja Frydrychowicz :impossibus (was :maja_zf) (needinfo me)]

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.

Comment 31

[Maja Frydrychowicz :impossibus (was :maja_zf) (needinfo me)]

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

Comment 32

[Anjana Vakil (:vakila)]

Comment on attachment 8770249 [details]
Bug 1285299 - Add pytest_mozlog plugin to mozlog;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/63746/diff/4-5/

Comment 33

[Anjana Vakil (:vakila)]

Comment on attachment 8782964 [details]
Bug 1285299 - Use pytest_mozlog plugin in Mn-h mozharness script;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/72966/diff/3-4/

Comment 34

[Anjana Vakil (:vakila)]

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

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/72964/diff/3-4/

Comment 35

[Anjana Vakil (:vakila)]

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.

Comment 36

[Anjana Vakil (:vakila)]

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

Comment 37

[Dave Hunt [:davehunt] [he/him] ⌚BST]

Comment on attachment 8770249 [details]
Bug 1285299 - Add pytest_mozlog plugin to mozlog;

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

Comment 38

[Dave Hunt [:davehunt] [he/him] ⌚BST]

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

Comment 39

[James Graham [:jgraham]]

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

[Dave Hunt [:davehunt] [he/him] ⌚BST]

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

[James Graham [:jgraham]]

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.

Comment 42

[Anjana Vakil (:vakila)]

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

[Dave Hunt [:davehunt] [he/him] ⌚BST]

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

[James Graham [:jgraham]]

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)

Comment 45

[Maja Frydrychowicz :impossibus (was :maja_zf) (needinfo me)]

Comment on attachment 8770249 [details]
Bug 1285299 - Add pytest_mozlog plugin to mozlog;

I agree with the other suggestions made so far. lgtm overall.

Comment 46

[Anjana Vakil (:vakila)]

Attachment: Bug 1285299 - Optionally ignore unused Mozlog formatter options;

Add a parameter `allow_unused_options` to the `setup_logging` and
`setup_handlers` methods in mozlog.commandline. When this parameter
is True, do not raise a ValueError in `setup_handlers` if the
command line arguments include formatter options for unused formatters.
(Default value is False.)

This allows parsed arguments from e.g. the pytest-mozlog plugin
to be passed directly to `setup_logging`, without filtering out
unused formatter options.

Review commit: https://reviewboard.mozilla.org/r/77296/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/77296/

Comment 47

[Anjana Vakil (:vakila)]

Comment on attachment 8770249 [details]
Bug 1285299 - Add pytest_mozlog plugin to mozlog;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/63746/diff/5-6/

Comment 48

[Anjana Vakil (:vakila)]

Comment on attachment 8782964 [details]
Bug 1285299 - Use pytest_mozlog plugin in Mn-h mozharness script;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/72966/diff/4-5/

Comment 49

[Anjana Vakil (:vakila)]

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

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/72964/diff/4-5/

Comment 50

[Anjana Vakil (:vakila)]

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.

Comment 51

[Anjana Vakil (:vakila)]

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 52

[Anjana Vakil (:vakila)]

Comment on attachment 8770249 [details]
Bug 1285299 - Add pytest_mozlog plugin to mozlog;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/63746/diff/6-7/

Comment 53

[Anjana Vakil (:vakila)]

Comment on attachment 8782964 [details]
Bug 1285299 - Use pytest_mozlog plugin in Mn-h mozharness script;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/72966/diff/5-6/

Comment 54

[Anjana Vakil (:vakila)]

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

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/72964/diff/5-6/

Comment 55

[James Graham [:jgraham]]

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.

Comment 56

[James Graham [:jgraham]]

Comment on attachment 8789008 [details]
Bug 1285299 - Optionally ignore unused Mozlog formatter options;

https://reviewboard.mozilla.org/r/77296/#review75800

Comment 57

[Anjana Vakil (:vakila)]

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 58

[Anjana Vakil (:vakila)]

Comment on attachment 8770249 [details]
Bug 1285299 - Add pytest_mozlog plugin to mozlog;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/63746/diff/7-8/

Comment 59

[Anjana Vakil (:vakila)]

Comment on attachment 8782964 [details]
Bug 1285299 - Use pytest_mozlog plugin in Mn-h mozharness script;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/72966/diff/6-7/

Comment 60

[Anjana Vakil (:vakila)]

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

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/72964/diff/6-7/

Comment 61

[Anjana Vakil (:vakila)]

Comment on attachment 8770249 [details]
Bug 1285299 - Add pytest_mozlog plugin to mozlog;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/63746/diff/8-9/

Comment 62

[Anjana Vakil (:vakila)]

Comment on attachment 8782964 [details]
Bug 1285299 - Use pytest_mozlog plugin in Mn-h mozharness script;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/72966/diff/7-8/

Comment 63

[Anjana Vakil (:vakila)]

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

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/72964/diff/7-8/

Comment 64

[Maja Frydrychowicz :impossibus (was :maja_zf) (needinfo me)]

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.

Comment 65

[Pulsebot]

Pushed by [e-mail]:
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

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/4aac4b3f3b53
https://hg.mozilla.org/mozilla-central/rev/0cd81275950d
https://hg.mozilla.org/mozilla-central/rev/0569d570905b