1050251 - Mochitest "Test timed out" now being output as "Test timed out - Test timed out"

Status: RESOLVED FIXED

(Testing :: Mochitest, defect)

Description

[Ed Morley [:emorley]]

eg before:
TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/image/test/browser/browser_image.js | Test timed out

After:
4372 INFO TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/image/test/browser/browser_image.js | Test timed out - Test timed out

Recent log:
https://tbpl.mozilla.org/php/getParsedLog.php?id=45412866&tree=B2g-Inbound

Comment 1

[Ahmed Kachkach [:akachkach]]

I think this is specific to chrome test and knw where it comes from (from the fact that we don't have the name of the assertions just yet). Will submit a patch in a bit.

Comment 2

[Ahmed Kachkach [:akachkach]]

Attachment: 0001-Bug-1050251-Using-the-correct-message-name-for-chrom.patch

Proposed patch. (currently waiting on a try run)

Comment 3

[Chris Manchester (limited bugmail, email directly)]

Comment on attachment 8469359 [details] [diff] [review]
0001-Bug-1050251-Using-the-correct-message-name-for-chrom.patch

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

This looks ok. Can you post an example of the before and after output and confirm with edmorley it results in the relevant (and complete) change before we check this in?

Comment 4

[Ahmed Kachkach [:akachkach]]

Attachment: 0001-Bug-1050251-Using-the-correct-message-name-for-chrom.patch

(carry r+ forward)

So, as expected from the chrome tests harness, the harness's functions are actually abused to make TBPL jobs turned orange. In the case of a timeout, the name of the subtest (assert) is "Test timed out".

This tries to expose the assert names in chrome tests (which should hopefully make other test-status and test-unexpected-fail messages more helpful). (also updating the check for timeout to take a screenshot since it's actually in the 'test' field, not the 'message' field)

Will have to investigate how this works once the trees are opened.

Comment 5

[Ahmed Kachkach [:akachkach]]

Try run with seeded failures (in both chrome-harness and TestRunner):

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

Might not be conclusive because of bug 1052937

Comment 6

[Ahmed Kachkach [:akachkach]]

woops, wrong link again. Here's the correct try run with timeouts: https://tbpl.mozilla.org/?tree=Try&rev=40b87bcf78a7

And a more extensive try run without timeouts: https://tbpl.mozilla.org/?tree=Try&rev=fd81fd97d979

Comment 7

[Ahmed Kachkach [:akachkach]]

Try runs look good. (correct subtest names, and screenshots taken)

Comment 8

[Chris Manchester (limited bugmail, email directly)]

Hold on, that was f+, not r+ :) 

Like I said in comment 3, let's confirm this is the relevant change.

edmorley, is the output in the linked run on comment 6 correct for your purposes? It looks like we haven't addressed the difference that is the count + level number prefixing each line so wanted to double check this is the right fix.

Comment 9

[Ed Morley [:emorley]]

I think the log line number and error level is superfluous, but this patch doesn't regress that (bug ) did, so happy to deal with that in a followup bug.

However in this log I did see an exception:
https://tbpl.mozilla.org/php/getParsedLog.php?id=45963814&tree=Try

12:59:26     INFO -  427 INFO TEST-UNEXPECTED-FAIL | /tests/content/base/test/test_bug353334.html | Test timed out.
12:59:26     INFO -  TEST-INFO | expected PASS
12:59:26     INFO -  428 INFO TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | 4 test timeouts, giving up.
12:59:26     INFO -  TEST-INFO | expected PASS
12:59:26     INFO -  429 INFO TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | Skipping 1187 remaining tests.
12:59:26     INFO -  TEST-INFO | expected PASS
12:59:26     INFO -  Exception in thread Thread-12:
12:59:26     INFO -  Traceback (most recent call last):
12:59:26     INFO -    File "/usr/lib/python2.7/threading.py", line 551, in __bootstrap_inner
12:59:26     INFO -      self.run()
12:59:26     INFO -    File "/usr/lib/python2.7/threading.py", line 504, in run
12:59:26     INFO -      self.__target(*self.__args, **self.__kwargs)
12:59:26     INFO -    File "/builds/slave/test/build/venv/local/lib/python2.7/site-packages/mozprocess/processhandler.py", line 775, in _processOutput
12:59:26     INFO -      self.processOutputLine(line.rstrip())
12:59:26     INFO -    File "/builds/slave/test/build/venv/local/lib/python2.7/site-packages/mozprocess/processhandler.py", line 720, in processOutputLine
12:59:26     INFO -      handler(line)
12:59:26     INFO -    File "/builds/slave/test/build/tests/mochitest/runtests.py", line 1850, in processOutputLine
12:59:26     INFO -      self.harness.message_logger.process_message(message)
12:59:26     INFO -    File "/builds/slave/test/build/tests/mochitest/runtests.py", line 181, in process_message
12:59:26     INFO -      self.logger.log_raw(message)
12:59:26     INFO -    File "/builds/slave/test/build/venv/local/lib/python2.7/site-packages/mozlog/structured/structuredlog.py", line 140, in log_raw
12:59:26     INFO -      converted_data = convertor_registry[action].convert_known(**raw_data)
12:59:26     INFO -    File "/builds/slave/test/build/venv/local/lib/python2.7/site-packages/mozlog/structured/logtypes.py", line 96, in convert_known
12:59:26     INFO -      return self.convert(**known_kwargs)
12:59:26     INFO -    File "/builds/slave/test/build/venv/local/lib/python2.7/site-packages/mozlog/structured/logtypes.py", line 85, in convert
12:59:26     INFO -      out_value = self.args[key](value)
12:59:26     INFO -    File "/builds/slave/test/build/venv/local/lib/python2.7/site-packages/mozlog/structured/logtypes.py", line 118, in __call__
12:59:26     INFO -      (value, type(value).__name__, self.name, self.__class__.__name__))
12:59:26     INFO -  ValueError: Failed to convert value OK of type unicode for field expected to type SubStatus

Comment 10

[Ed Morley [:emorley]]

(In reply to Ed Morley [:edmorley] from comment #9)
> I think the log line number and error level is superfluous, but this patch
> doesn't regress that (bug ) did, so happy to deal with that in a followup
> bug.

s/bug /bug 886570/

(Compare bug 802953 comment 34 and bug 802953 comment 35)

Comment 11

[Chris Manchester (limited bugmail, email directly)]

Filed bug 1054304 for the subtest status. akackach, can you upload a final patch?

Comment 12

[Ahmed Kachkach [:akachkach]]

Attachment: 0001-Bug-1050251-Using-the-correct-message-name-for-chrom.patch

I'm also for removing the line number and log level (even if we'll have to manually add them to the summary line, otherwise they don't get picked up by mozharness); It's what was causing many error messages to go unnoticed (because mozharness looks for TEST-UNEXPECTED at the beginning of the line), but that should be in a different bug (since this one was mostly about the wrong status messages in chrome tests).

I'll file a patch for bug 1054304 in a second.

Comment 13

[Chris Manchester (limited bugmail, email directly)]

Comment on attachment 8473742 [details] [diff] [review]
0001-Bug-1050251-Using-the-correct-message-name-for-chrom.patch

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

This looks good. Thanks!

::: testing/mochitest/runtests.py
@@ +1980,5 @@
>      def dumpScreenOnTimeout(self, message):
>        if (not self.dump_screen_on_fail
>            and self.dump_screen_on_timeout
> +          and message['action'] == 'test_status' and 'expected' in message
> +          and "Test timed out" in message['subtest']):

This part's a little bit rot.

Comment 14

[Ahmed Kachkach [:akachkach]]

Attachment: 0001-Bug-1050251-Using-the-correct-message-name-for-chrom.patch

carry r+ forward;

Thanks for the review! Rebased the patch on inbound.

Comment 15

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/3b85b2715743

Comment 16

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/3b85b2715743

Comment 17

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

The commit message here seems misleading; it looks like the patch is about browser-chrome mochitests, not chrome mochitests.

Comment 18

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/4b896ae5f54e