cppunit test harness should handle test timeouts gracefully, outputting a failure message that includes the test name

RESOLVED FIXED in mozilla31

Status

defect
RESOLVED FIXED
5 years ago
5 years ago

People

(Reporter: emorley, Assigned: dminor)

Tracking

(Blocks 1 bug)

Trunk
mozilla31
Points:
---
Dependency tree / graph
Bug Flags:
in-testsuite -

Firefox Tracking Flags

(Not tracked)

Details

Attachments

(1 attachment)

Reporter

Description

5 years ago
...since currently they do things like:
{
06:12:43     INFO -  cppunittests INFO | Running test test_sanity.exe
06:12:48     INFO -  START test_init_destroy_context
06:12:48     INFO -  END test_init_destroy_context
06:12:48     INFO -  START test_init_destroy_multiple_contexts
06:12:48     INFO -  END test_init_destroy_multiple_contexts
06:12:48     INFO -  START test_init_destroy_stream
06:12:48     INFO -  END test_init_destroy_stream
06:12:48     INFO -  START test_init_destroy_multiple_streams
06:12:48     INFO -  END test_init_destroy_multiple_streams
06:12:48     INFO -  START test_init_destroy_multiple_contexts_and_streams
06:12:48     INFO -  END test_init_destroy_multiple_contexts_and_streams
06:12:48     INFO -  START test_basic_stream_operations
06:12:48     INFO -  END test_basic_stream_operations
06:12:48     INFO -  START test_stream_position
06:12:48     INFO -  END test_stream_position
06:12:48     INFO -  START test_init_start_stop_destroy_multiple_streams
06:12:48     INFO -  END test_init_start_stop_destroy_multiple_streams
06:12:48     INFO -  START test_init_start_stop_destroy_multiple_streams
06:12:48     INFO -  END test_init_start_stop_destroy_multiple_streams
06:12:48     INFO -  START test_init_start_stop_destroy_multiple_streams
06:12:48     INFO -  END test_init_start_stop_destroy_multiple_streams
06:12:48     INFO -  START test_init_start_stop_destroy_multiple_streams
06:12:48     INFO -  Assertion failed: r == 0, file c:/builds/moz2_slave/m-cen-w32-ntly-000000000000000/build/media/libcubeb/tests/test_sanity.cpp, line 173
06:29:28     INFO - Automation Error: mozprocess timed out after 1000 seconds running ['C:\\slave\\test\\build\\venv\\Scripts\\python', '-u', 'C:\\slave\\test\\build\\tests\\cppunittests/runcppunittests.py', '--symbols-path=https://ftp-ssl.mozilla.org/pub/mozilla.org/firefox/tinderbox-builds/mozilla-central-win32/1397124120/firefox-31.0a1.en-US.win32.crashreporter-symbols.zip', '--xre-path=C:\\slave\\test\\build\\application\\firefox', 'tests/cppunittests']
06:29:28    ERROR - timed out after 1000 seconds of no output
06:29:28    ERROR - Return code: 572
}

...which doesn't meet:
https://wiki.mozilla.org/Sheriffing/Job_Visibility_Policy#6.29_Outputs_failures_in_a_TBPL-starrable_format

Seems like bug 811370 has regressed, maybe because of bug 811409?

Dan, could you confirm if bug 811409 is responsible for this? :-)
Flags: needinfo?(dminor)
Reporter

Comment 1

5 years ago
Example log:
https://tbpl.mozilla.org/php/getParsedLog.php?id=37571295&tree=Mozilla-Central

Desired output:

TEST-UNEXPECTED-FAIL | test_init_start_stop_destroy_multiple_streams | test timed out after NNN seconds

or something similar :-)
I wonder if there's something else going on here. That test is hitting an assertion, so it ought to be quitting right away. (It's also possible that something just got broken.)
Reporter

Updated

5 years ago
No longer blocks: 949166
Reporter

Updated

5 years ago
Blocks: 949166
Assignee

Comment 3

5 years ago
It looks like runcppunittest.py is being timed out in mozharness but the test itself is not timing out in runcppunittest.py, which is why we don't see the starrable output that was added in bug 811370.

Bug 811409 is responsible because it is the reason we're running these through mozharness :)

The output we're seeing is coming from [1]. I'm not sure what the best output would be in this situation, since the timeout could potentially occur before any tests or run or after they have all completed.

I'm guessing this isn't just a mismatch between mozharness and test script timeout values or we would see stuff like this fairly often, so possibly that test is failing in a way that causes the harness to hang.

[1] http://hg.mozilla.org/build/mozharness/file/11061e1cebb8/mozharness/base/script.py#l662
Flags: needinfo?(dminor)
Assignee

Comment 4

5 years ago
I take it back, it looks like the cppunittest command timeout is set to 1200 seconds, but mozharness is using 1000 seconds.
Assignee

Comment 5

5 years ago
Assignee: nobody → dminor
Status: NEW → ASSIGNED
Attachment #8404919 - Flags: review?(ted)
Reporter

Comment 6

5 years ago
Ah that's great, thank you :-)
Comment on attachment 8404919 [details] [diff] [review]
Change individual test timeout from 1200 to 900 seconds

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

Oops. We should figure out some standard way for mozharness to pass down "your timeout setting should be less than mine" to test harnesses.
Attachment #8404919 - Flags: review?(ted) → review+
Reporter

Comment 8

5 years ago
(In reply to Ted Mielczarek [:ted.mielczarek] from comment #7)
> Oops. We should figure out some standard way for mozharness to pass down
> "your timeout setting should be less than mine" to test harnesses.

Filed bug 995118.
https://hg.mozilla.org/mozilla-central/rev/b62c590540b0
Status: ASSIGNED → RESOLVED
Closed: 5 years ago
Flags: in-testsuite-
Resolution: --- → FIXED
Target Milestone: --- → mozilla31
You need to log in before you can comment on or make changes to this bug.