1037521 - Output message + stack information in mach formatter for unexpected [sub]test results

Status: RESOLVED FIXED

(Testing :: Mozbase, defect)

Description

[James Graham [:jgraham]]

The mach formatter is currently a little too quiet; it would be useful if it gave error information when tests fail. This change needs to be made in machformatter.py [1] in both test_status and test_end. In test_status you will need to store the message data for anything with an "expected" field. In test_end you will need to output the stored test name and message for any subtests, and do something similar for the test itself.

[1] http://dxr.mozilla.org/mozilla-central/source/testing/mozbase/mozlog/mozlog/structured/formatters/machformatter.py

Comment 1

[Arnav Sharma]

Attachment: Proposed patch to output details about unexpected results.

This is my first patch to anything on Mozilla, so I'm aware that I could have made some terrible mistakes. Please let me know about anything pertinent!

Comment 2

[James Graham [:jgraham]]

Comment on attachment 8454815 [details] [diff] [review]
Proposed patch to output details about unexpected results.

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

Looks like a great start; thanks for taking the time to do this. There are just a couple of issues to address.

::: testing/mozbase/mozlog/mozlog/structured/formatters/machformatter.py
@@ +54,5 @@
>          else:
>              expected_str = ""
>  
>          subtests = self._get_subtest_data(data)
> +        if subtests["count"] != 0:

Should be

if "expected" in data

I think. Could also add a flag like parent_unexpected to use below.

@@ +69,2 @@
>              data["status"], expected_str, subtests["pass"],
> +            subtests["count"], str(unexpected))

I think we need some more fancy formatting for unexpected than just str(unexpected). Something like:

rv = "Harness status %s%s. Subtests passed %i/%i. Unexpected [%s]" % (
    data["status"], expected_str, subtests["pass"], len(unexpected))

if unexpected:
    rv += "\nDetails:\n"
    if len(unexpected) == 1 and parent_unexpected:
        rv += "%s\n" % unexpected[0][1]
    else:
        for name, message in data:
        rv += "%s\n" % ("\n".join([name, "-" * len(name), message]))

return rv

That may add too many line breaks; you'll need to try it out and adjust as necessary.

Comment 3

[Dan Mosedale (:dmosedale, :dmose)]

I believe this is a recent regression, and if my understanding is correct, for the tests it effects, it effectively makes those tests undiagnosable from the logs or reading stderr.

Comment 4

[Maire Reavy [:mreavy]]

Hi Arnav -- Thanks for the patch!   My team really needs it!   Do you think you could create an update to your patch with jgraham's review comments addressed by tomorrow (Wednesday)?  

(See Comment 2 for jgraham's review comments.)

Thank you again, and welcome to Mozilla!

Comment 5

[Arnav Sharma]

Attachment: bug-1037521-adjust.patch

Just made the changes suggested by jgraham. Thanks a load!

Comment 6

[Arnav Sharma]

Attachment: bug-1037521-realadjust.patch

I'm an idiot and uploaded an empty patch. Sorry, new to this hg stuff. Anyways, I just added suggestions by jgraham. Thanks.

Comment 7

[James Graham [:jgraham]]

Comment on attachment 8456727 [details] [diff] [review]
bug-1037521-realadjust.patch

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

Looking good, just a small number of fixups and I think we will be ready to go.

::: testing/mozbase/mozlog/mozlog/structured/formatters/machformatter.py
@@ +59,2 @@
>          else:
>              expected_str = ""

Need to set parent_unexpected = False

@@ +59,4 @@
>          else:
>              expected_str = ""
>  
>          subtests = self._get_subtest_data(data)

This needs to be at the top of the method or subtests will be undefined above.

@@ +59,5 @@
>          else:
>              expected_str = ""
>  
>          subtests = self._get_subtest_data(data)
> +        

This seems to be a whitespace error.

@@ +68,3 @@
>          self.has_unexpected[test] = bool(unexpected)
>  
> +        rv = "Harness status %s%s. Subtests passed %i/%i. Unexpected [%s]" % (

Get rid of the square brackets around the unexpected count here.

Also, I'm not sure if we should do it in this patch, but it just occurred to me that this output should switch on whether there are subtests (using some imaginary has_subtests variable):

if subtests["count"] != 0:
    rv = "Harness status %s%s. Subtests passed %i/%i. Unexpected [%s]" % (
        data["status"], expected_str, subtests["pass"], len(unexpected))
else:
    rv = "Status %s%s" % (data["status"], expected_str)

@@ +82,1 @@
>      def test_status(self, data):

Need a linebreak between methods

Comment 8

[Arnav Sharma]

Attachment: patch-1037521-fixes.patch

Heh, made a couple errors in the code that broke stuff (as well as some style errors). This patch should take care of them.

Comment 9

[James Graham [:jgraham]]

Arnav: do you have a folded version of this patch ready?

Comment 10

[James Graham [:jgraham]]

Attachment: Add information about unexpected results to mach output.

Comment 11

[Chris Manchester (limited bugmail, email directly)]

Comment on attachment 8460337 [details] [diff] [review]
Add information about unexpected results to mach output.

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

This still doesn't log the stack for tests with no subtests, so it doesn't address the issue debugging marionette failures locally.

::: testing/mozbase/mozlog/mozlog/structured/formatters/machformatter.py
@@ +73,5 @@
> +
> +        if unexpected:
> +            rv += "\n"
> +            if len(unexpected) == 1 and parent_unexpected:
> +                rv += "%s" % unexpected[0][1]

This only gives the status of the test, we need the message too.

Comment 12

[James Graham [:jgraham]]

Attachment: Add information about unexpected results to mach output.

Comment 13

[Chris Manchester (limited bugmail, email directly)]

Comment on attachment 8460365 [details] [diff] [review]
Add information about unexpected results to mach output.

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

It might also be helpful to include the test name in the test_end message, but this looks good.

Comment 14

[James Graham [:jgraham]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/8ab7e0d27367

Comment 15

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/8ab7e0d27367