804366 - Marionette should always include the test filename in TEST-UNEXPECTED-FAIL messages

Status: RESOLVED FIXED

(Testing :: Marionette, defect)

Description

[Jonathan Griffin (:jgriffin)]

Marionette should always include the test filename in TEST-UNEXPECTED-FAIL messages.  Currently it doesn't, at least not for JS tests, and this leads to vague messages in TBPL like:

20:12:50 INFO - TEST-UNEXPECTED-FAIL : ScriptTimeoutException: timed out

The test filename is in the Python exception block, but this doesn't get picked up by TBPL.

This will make Marionette hard to sheriff/star, until this is fixed.

Comment 1

[Jonathan Griffin (:jgriffin)]

Attachment: Include test names in failure messages

I'm going to land this on cedar to see how well it works.

Comment 2

[Jonathan Griffin (:jgriffin)]

Attachment: Fix for previous patch

This patch lands on top of the previous, and fixes some of the issues I've seen while running this on cedar.  I will land this directly on cedar as well.

Comment 3

[Jonathan Griffin (:jgriffin)]

Attachment: Use 'testfile testclass' instead of 'testfile:testclass'

...since the latter breaks bug suggestions on TBPL.

Comment 4

[Jonathan Griffin (:jgriffin)]

Attachment: Another logging tweak

Comment 5

[Jonathan Griffin (:jgriffin)]

Attachment: Include test names in failure messages

This is running on cedar and works well.  We still have duplicate error messages showing for Marionette tests, but that's because the errors get dumped to logcat and the console, and in case there are failure, the mozharness script dumps the logcat.

Comment 6

[Andrew Halberstadt [:ahal] (PTO until March)]

Comment on attachment 677197 [details] [diff] [review]
Include test names in failure messages

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

LGTM.

::: testing/marionette/client/marionette/marionette.py
@@ +272,5 @@
>          self.b2g = 'b2g' in self.session
>          return self.session
>  
> +    def set_test_name(self, test_name=None):
> +        return self._send_message('setTestName', 'ok', value=test_name)

Optional suggestion: Not sure if this would make sense (or if it's even possible), but what if we used property decorators instead. Something like:

@property
def test_name(self):
    return self._test_name

@test_name.setter
def test_name(self, value):
    if self._send_message('setTestName', 'ok', value=value) == 'ok':
        self._test_name = value

This way the python client could always see the latest value that has been sent to the js side and also wouldn't need to call the getInfo() method to get the test name. Anyway, like I said, I'm not super familiar with how everything fits together so feel free to disregard.

::: testing/marionette/client/marionette/marionette_test.py
@@ +116,5 @@
>      def setUp(self):
>          CommonTestCase.setUp(self)
> +        test_name = '%s.py %s.%s' % (self.__class__.__module__,
> +                                     self.__class__.__name__,
> +                                     self._testMethodName)

nit: shouldn't this call MarionetteTestResult.getInfo()?

Comment 7

[Jonathan Griffin (:jgriffin)]

(In reply to Andrew Halberstadt [:ahal] from comment #6)
> Comment on attachment 677197 [details] [diff] [review]
> Include test names in failure messages
> 
> Review of attachment 677197 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> LGTM.
> 
> ::: testing/marionette/client/marionette/marionette.py
> @@ +272,5 @@
> >          self.b2g = 'b2g' in self.session
> >          return self.session
> >  
> > +    def set_test_name(self, test_name=None):
> > +        return self._send_message('setTestName', 'ok', value=test_name)
> 
> Optional suggestion: Not sure if this would make sense (or if it's even
> possible), but what if we used property decorators instead. Something like:
> 
> @property
> def test_name(self):
>     return self._test_name
> 
> @test_name.setter
> def test_name(self, value):
>     if self._send_message('setTestName', 'ok', value=value) == 'ok':
>         self._test_name = value
> 
> This way the python client could always see the latest value that has been
> sent to the js side and also wouldn't need to call the getInfo() method to
> get the test name. Anyway, like I said, I'm not super familiar with how
> everything fits together so feel free to disregard.

Good suggestion, I'll make that change.

> 
> ::: testing/marionette/client/marionette/marionette_test.py
> @@ +116,5 @@
> >      def setUp(self):
> >          CommonTestCase.setUp(self)
> > +        test_name = '%s.py %s.%s' % (self.__class__.__module__,
> > +                                     self.__class__.__name__,
> > +                                     self._testMethodName)
> 
> nit: shouldn't this call MarionetteTestResult.getInfo()?

This method doesn't have access to a MarionetteTestResult instance.  But, I can move this logic into CommonTestCase, which can be called *from* MarionetteTestResult.  I'll make this change and try it on cedar.

Comment 8

[Jonathan Griffin (:jgriffin)]

Attachment: Include test names in failure messages

Updated with review comments

Comment 9

[Jonathan Griffin (:jgriffin)]

Comment on attachment 677851 [details] [diff] [review]
Include test names in failure messages

Carry r+ forward.

Comment 10

[Jonathan Griffin (:jgriffin)]

Testing on cedar: https://tbpl.mozilla.org/?tree=Cedar&rev=cc9cccd1e02e

Comment 11

[Ed Morley [:emorley]]

Please can we land this on m-c soon; I suspect philor will be re-hiding marionette soon otherwise...

16:07:50 - philor: "TEST-UNEXPECTED-FAIL : AssertionError"
16:08:01 - philor: oh, marionette, we're not going to get along, you and I, are we?
16:08:16 - AutomatedTester: philor: ?
16:08:25 - philor: https://tbpl.mozilla.org/php/getParsedLog.php?id=16753491&tree=Mozilla-Inbound
16:09:13 - AutomatedTester: philor: error could be made more helpful
16:09:21 - AutomatedTester: but the line above is what failed
16:09:38 - philor: yeah, there's the disconnect
16:10:18 - philor: because as far as I'm concerned, a TEST-UNEXPECTED-FAIL line with no test name, and no statement of what failed is utterly useless, beyond pointless, and unacceptable for being visible

Comment 12

[Jonathan Griffin (:jgriffin)]

I'll land it today.

Comment 13

[Ed Morley [:emorley]]

Thank you :-)

Comment 14

[Phil Ringnalda (:philor)]

I'm not sure this will be enough - turning that into "07:49:26 INFO - TEST-UNEXPECTED-FAIL | test_switch_frame.TestSwitchFrame | AssertionError" still leaves us with a single bug for every AssertionError in test_switch_frame.TestSwitchFrame, with absolutely no way to see what AssertionError it was unless someone looks at the log in less than 30 days and copy-pastes it into the bug.

Comment 15

[Jonathan Griffin (:jgriffin)]

pushed to try:  https://tbpl.mozilla.org/?tree=Try&rev=0a5bbd3257c9

Comment 16

[Jonathan Griffin (:jgriffin)]

(In reply to Phil Ringnalda (:philor) from comment #14)
> I'm not sure this will be enough - turning that into "07:49:26 INFO -
> TEST-UNEXPECTED-FAIL | test_switch_frame.TestSwitchFrame | AssertionError"
> still leaves us with a single bug for every AssertionError in
> test_switch_frame.TestSwitchFrame, with absolutely no way to see what
> AssertionError it was unless someone looks at the log in less than 30 days
> and copy-pastes it into the bug.

I'll land this patch and we'll address that issue with a follow-up bug.

Comment 17

[Jonathan Griffin (:jgriffin)]

https://hg.mozilla.org/mozilla-central/rev/4e87d8355501

Comment 18

[Mozilla RelEng Bot]

Try run for 0a5bbd3257c9 is complete.
Detailed breakdown of the results available here:
    https://tbpl.mozilla.org/?tree=Try&rev=0a5bbd3257c9
Results (out of 4 total builds):
    success: 4
Builds (or logs if builds failed) available at:
http://ftp.mozilla.org/pub/mozilla.org/firefox/try-builds/[e-mail]-0a5bbd3257c9

Comment 19

[:Ms2ger (he/him; ⌚ UTC+1/+2)]

(In reply to Jonathan Griffin (:jgriffin) from comment #17)
> https://hg.mozilla.org/mozilla-central/rev/4e87d8355501

This patch is empty.

Comment 20

[Jonathan Griffin (:jgriffin)]

(In reply to :Ms2ger from comment #19)
> (In reply to Jonathan Griffin (:jgriffin) from comment #17)
> > https://hg.mozilla.org/mozilla-central/rev/4e87d8355501
> 
> This patch is empty.

I have no explanation for this!

The patch was bitrotted by today, so I fixed it up and pushed it to try just to be safe:

https://tbpl.mozilla.org/?tree=Try&rev=47292aac9786

Comment 21

[Jonathan Griffin (:jgriffin)]

The last patch had a conflict between the 'test_name' property and a 'test_name' method in one of the tests.  Fixed and pushed to try again:

https://tbpl.mozilla.org/?tree=Try&rev=e31ae96471a0

Comment 22

[Jonathan Griffin (:jgriffin)]

Attachment: Include test names in failure messages v0.3,

Comment 23

[Jonathan Griffin (:jgriffin)]

Comment on attachment 678796 [details] [diff] [review]
Include test names in failure messages v0.3,

Carry r+ forward.

Comment 24

[Jonathan Griffin (:jgriffin)]

try was green, pushed as https://hg.mozilla.org/integration/mozilla-inbound/rev/c94731604343

(I checked this time!)

Comment 25

[Mozilla RelEng Bot]

Try run for 47292aac9786 is complete.
Detailed breakdown of the results available here:
    https://tbpl.mozilla.org/?tree=Try&rev=47292aac9786
Results (out of 6 total builds):
    success: 2
    warnings: 4
Builds (or logs if builds failed) available at:
http://ftp.mozilla.org/pub/mozilla.org/firefox/try-builds/[e-mail]-47292aac9786

Comment 26

[Mozilla RelEng Bot]

Try run for 47292aac9786 is complete.
Detailed breakdown of the results available here:
    https://tbpl.mozilla.org/?tree=Try&rev=47292aac9786
Results (out of 7 total builds):
    success: 2
    warnings: 4
    failure: 1
Builds (or logs if builds failed) available at:
http://ftp.mozilla.org/pub/mozilla.org/firefox/try-builds/[e-mail]-47292aac9786

Comment 27

[Mozilla RelEng Bot]

Try run for e31ae96471a0 is complete.
Detailed breakdown of the results available here:
    https://tbpl.mozilla.org/?tree=Try&rev=e31ae96471a0
Results (out of 7 total builds):
    success: 6
    failure: 1
Builds (or logs if builds failed) available at:
http://ftp.mozilla.org/pub/mozilla.org/firefox/try-builds/[e-mail]-e31ae96471a0

Comment 28

[Ryan VanderMeulen [:RyanVM]]

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

Comment 29

[Jonathan Griffin (:jgriffin)]

https://hg.mozilla.org/releases/mozilla-aurora/rev/b7480e2efbde