1373745 - Fix structured logger problems in reftest

Status: RESOLVED FIXED

(Testing :: Reftest, enhancement)

Description

[Andrew Halberstadt [:ahal]]

Bug 1372565 fixes an issue where mozlog wasn't enforcing the test log protocol (things like logging a test_end without a test_start). In my try pushes there, I discovered reftest can be guilty of doing this (happens in reftest-sanity somewhere).

We'll need to fix that before we can land the other bug.

Comment 1

[Andrew Halberstadt [:ahal]]

Attachment: Bug 1373745 - Fix structured logging problems in reftest,

Currently reftest.jsm uses logger.testEnd(..) to log all kinds of different
potential failures, from proper test failures to harness issues. This means
there are all kinds of edge cases that would cause multiple testEnd messages to
get logged, something the structured log protocol is supposed to prevent.

This modifies the reftest harness to instead use testStatus for everything. The
testEnd call will always be logged with status "OK". This required some changes
to the reftest formatter and reftest selftests.

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

Comment 2

[Andrew Halberstadt [:ahal]]

This looks good on try:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=771bb67cdb28045bc3a110a7523cd87965f414e8

The reftest-selftest error was fixed here:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=f2b2fb82d5722bd6f00871ad86529a65e3f0e0ad

At least with the selftests, I'm somewhat confident this isn't horribly breaking everything.

Comment 3

[Joel Maher ( :jmaher ) (UTC -8)]

Comment on attachment 8912363 [details]
Bug 1373745 - Fix structured logging problems in reftest,

https://reviewboard.mozilla.org/r/183688/#review188918

a few small things, overall this is looking great and the unittests are great to see.

::: layout/tools/reftest/output.py:60
(Diff revision 1)
> +        test = data['test']
> +
> +        status_msg = self._format_status(data)
> +        output_text = "%s | %s | %s" % (status_msg, test, data.get("subtest", "unknown test"))
> +        if data.get('message'):
> +            output_text = "%s | %s" % (output_text, data['message'])

why not |output_text += " | %s" % data['message']|

::: layout/tools/reftest/output.py:87
(Diff revision 1)
>              elif len(screenshots) == 1:
>                  output_text += "\nREFTEST   IMAGE: data:image/png;base64,%s" % image_1
>  
> -        output_text += "\nREFTEST TEST-END | %s" % test
> +        if output_text:
> +            output_text += "\nREFTEST "
> +        output_text += "TEST-END | %s" % test

I don't understand this, if check |if output_text|, if that doesn't exist, then line 87 will fail.

Comment 4

[Andrew Halberstadt [:ahal]]

Comment on attachment 8912363 [details]
Bug 1373745 - Fix structured logging problems in reftest,

https://reviewboard.mozilla.org/r/183688/#review188918

> why not |output_text += " | %s" % data['message']|

Yeah, I guess I used this form down below. Should be consistent, I'll change this.

> I don't understand this, if check |if output_text|, if that doesn't exist, then line 87 will fail.

output_text is initialized to "" on line 68 so line 87 will work either way.

This is unrelated to your comment, but I though you might appreciate a bit of extra context here. Before this patch, the reftest harness would always use "test_end" to log status messages. So something like:

    { "action": "test_end", "status": "PASS", ... }

Would get formatted into:

    REFTEST TEST-PASS | test_foo.html == test_bar.html
    REFTEST TEST-END | test_foo.html == test_bar.html

But now, the status message is (usually) handled by the "test_status" action. So now we have:

    { "action": "test_status", "status": "PASS", ... }
    { "action": "test_end", "status": "OK", ... }

The formatter is trying to make sure that both of these cases result in a log that looks the same. That's why there's now a `if status != "OK":` condition near the top of this function.

Comment 5

[Andrew Halberstadt [:ahal]]

Comment on attachment 8912363 [details]
Bug 1373745 - Fix structured logging problems in reftest,

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

Comment 6

[Joel Maher ( :jmaher ) (UTC -8)]

Comment on attachment 8912363 [details]
Bug 1373745 - Fix structured logging problems in reftest,

https://reviewboard.mozilla.org/r/183688/#review189202

thanks for the fix and the explanation and backstory.

Comment 7

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/8189e90aad8e
Fix structured logging problems in reftest, r=jmaher

Comment 8

[Phil Ringnalda (:philor)]

https://hg.mozilla.org/mozilla-central/rev/8189e90aad8e