Closed Bug 1050251 Opened 9 years ago Closed 9 years ago

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


(Testing :: Mochitest, defect)

Not set


(firefox33 fixed, firefox34 fixed)

Tracking Status
firefox33 --- fixed
firefox34 --- fixed


(Reporter: emorley, Assigned: akachkach)




(1 file, 3 obsolete files)

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

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

Recent log:
Flags: needinfo?(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.
Flags: needinfo?(akachkach)
Assignee: nobody → akachkach
Proposed patch. (currently waiting on a try run)
Attachment #8469359 - Flags: review?(cmanchester)
Comment on attachment 8469359 [details] [diff] [review]

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?
Attachment #8469359 - Flags: review?(cmanchester) → feedback+
(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.
Attachment #8469359 - Attachment is obsolete: true
Attachment #8469662 - Flags: review+
Try run with seeded failures (in both chrome-harness and TestRunner):

Might not be conclusive because of bug 1052937
woops, wrong link again. Here's the correct try run with timeouts:

And a more extensive try run without timeouts:
Try runs look good. (correct subtest names, and screenshots taken)
Keywords: checkin-needed
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.
Flags: needinfo?(emorley)
Keywords: checkin-needed
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:

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/", line 551, in __bootstrap_inner
12:59:26     INFO -
12:59:26     INFO -    File "/usr/lib/python2.7/", 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/", 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/", line 720, in processOutputLine
12:59:26     INFO -      handler(line)
12:59:26     INFO -    File "/builds/slave/test/build/tests/mochitest/", 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/", 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/", 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/", 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/", 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/", line 118, in __call__
12:59:26     INFO -      (value, type(value).__name__,, self.__class__.__name__))
12:59:26     INFO -  ValueError: Failed to convert value OK of type unicode for field expected to type SubStatus
Flags: needinfo?(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)
Filed bug 1054304 for the subtest status. akackach, can you upload a final patch?
Flags: needinfo?(akachkach)
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.
Attachment #8469662 - Attachment is obsolete: true
Attachment #8473742 - Flags: review?(cmanchester)
Flags: needinfo?(akachkach)
Comment on attachment 8473742 [details] [diff] [review]

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

This looks good. Thanks!

::: testing/mochitest/
@@ +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.
Attachment #8473742 - Flags: review?(cmanchester) → review+
carry r+ forward;

Thanks for the review! Rebased the patch on inbound.
Attachment #8473742 - Attachment is obsolete: true
Attachment #8473915 - Flags: review+
Keywords: checkin-needed
Closed: 9 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla34
The commit message here seems misleading; it looks like the patch is about browser-chrome mochitests, not chrome mochitests.
Depends on: 1055500
Depends on: 1073074
You need to log in before you can comment on or make changes to this bug.