Closed Bug 1050177 Opened 11 years ago Closed 7 years ago

TEST-UNEXPECTED-{TIMEOUT,OK} being output for mochitest failures instead of TEST-UNEXPECTED-{FAIL,PASS}

Categories

(Testing :: Mochitest, defect)

Product:
Testing
Component:
Mochitest
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(Not tracked)

Status:
RESOLVED INCOMPLETE

People

(Reporter: emorley, Unassigned)

References

Details

Compare old: 4132 ERROR TEST-UNEXPECTED-PASS | /tests/content/html/content/test/test_iframe_sandbox_inheritance.html | Assertion count 0 is less than expected range 1-1 assertions. With new: https://tbpl.mozilla.org/php/getParsedLog.php?id=45404782&tree=Mozilla-Inbound 01:45:08 INFO - 13696 INFO TEST-UNEXPECTED-OK | /tests/content/html/content/test/test_iframe_sandbox_inheritance.html | Assertion count 0 is less than expected range 1-1 assertions. Was this intentional? A lot of the horrid buildbot/mozharness regex sadly depend on the output strings to not change - this will quite possibly break things.
Flags: needinfo?(akachkach)
Also TEST-UNEXPECTED-FAIL has now become TEST-UNEXPECTED-TIMEOUT: https://tbpl.mozilla.org/php/getParsedLog.php?id=45375357&tree=Mozilla-Inbound Rev4 MacOSX Snow Leopard 10.6 mozilla-inbound opt test mochitest-3 on 2014-08-06 16:58:17 PDT for push d997e5accc3f 17:13:54 WARNING - TEST-UNEXPECTED-TIMEOUT | /tests/dom/power/test/test_wakelock_not_exposed.html | application timed out after 330 seconds with no output
Summary: "TEST-UNEXPECTED-PASS" now displays as "TEST-UNEXPECTED-OK" → TEST-UNEXPECTED-{TIMEOUT,OK} being output for mochitest failures instead of TEST-UNEXPECTED-{FAIL,PASS}
TIMEOUT is certainly more useful, but I'm just not sure we should make the change (yet) without tweaking all downstream consumers too.
We're also outputting "TEST-OK" instead of "TEST-END" (which doesn't make as much sense, especially given the OK is shown even if there were failures within the test). eg: https://tbpl.mozilla.org/php/getParsedLog.php?id=45383269&tree=Fx-Team#error0 19:22:11 INFO - 20630 INFO TEST-START | /tests/gfx/tests/mochitest/test_acceleration.html 19:22:11 INFO - 20631 INFO ++DOMWINDOW == 256 (15B24400) [pid = 2588] [serial = 1952] [outer = 12B41C00] 19:22:11 INFO - 20632 INFO TEST-UNEXPECTED-FAIL | /tests/gfx/tests/mochitest/test_acceleration.html | Acceleration enabled on Windows XP or newer - didn't expect 0, but got it 19:22:11 INFO - TEST-INFO | expected PASS 19:22:11 INFO - 20633 INFO TEST-UNEXPECTED-FAIL | /tests/gfx/tests/mochitest/test_acceleration.html | Direct2D enabled on Windows Vista or newer 19:22:11 INFO - TEST-INFO | expected PASS 19:22:11 INFO - 20634 INFO TEST-UNEXPECTED-FAIL | /tests/gfx/tests/mochitest/test_acceleration.html | DirectWrite enabled on Windows Vista or newer 19:22:11 INFO - TEST-INFO | expected PASS 19:22:11 INFO - 20635 INFO TEST-OK | /tests/gfx/tests/mochitest/test_acceleration.html | took 179ms
This is because of the way the formatter generates those messages: http://dxr.mozilla.org/mozilla-central/source/testing/mozbase/mozlog/mozlog/structured/formatters/tbplformatter.py#55 @chmanchester: Could we just revert those to TEST-END and TEST-UNEXPECTED-FAIL or TEST-UNEXPECTED-PASS?
Flags: needinfo?(akachkach) → needinfo?(cmanchester)
(In reply to Ahmed Kachkach [:akachkach] from comment #4) > This is because of the way the formatter generates those messages: > http://dxr.mozilla.org/mozilla-central/source/testing/mozbase/mozlog/mozlog/ > structured/formatters/tbplformatter.py#55 > > @chmanchester: Could we just revert those to TEST-END and > TEST-UNEXPECTED-FAIL or TEST-UNEXPECTED-PASS? My take here is about the same as for marionette: https://bugzilla.mozilla.org/show_bug.cgi?id=1050178#c1 Reverting this would be easy enough, but I would like to understand why this is necessary. If this sort of thing is going to mess up tools, let's reopen bug 1030845 or something and fix this in the formatter. OK status is appropriate for tests with failed subtests in some cases according to the structured format (http://mozbase.readthedocs.org/en/latest/mozlog_structured.html), but I agree the formatting makes it sort of confusing.
Flags: needinfo?(cmanchester)
Should we mark this as WONTFIX?
(In reply to Chris Manchester [:chmanchester] from comment #5) > Reverting this would be easy enough, but I would like to understand why this > is necessary. If this sort of thing is going to mess up tools, let's reopen > bug 1030845 or something and fix this in the formatter. I just think (especially given the number of quirky regressions from structured logging landing) that we should have as few moving pieces as possible at any one time. My understanding was that the TBPL formatter was supposed to act as a layer to prevent unintended changes in log output - so that we could switch to using structured logging internally before our tooling supported using the structured format directly. I would much rather have two separate bugs: 1) Switch to structured logging 2) Change the unstructured log output to match a new spec Than: 1) Let's do everything at once. Note I'm happy for the structured log status values to be from the new spec, so long as tbplformatter.py insulates the unstructured logs from this at least for now. > OK status is appropriate for tests with failed subtests in some cases > according to the structured format > (http://mozbase.readthedocs.org/en/latest/mozlog_structured.html), but I > agree the formatting makes it sort of confusing. 'OK' may make sense in the spec, but for the unstructured log output it really doesn't read well to see OK after a timeout. Perhaps we should just change in tbplformatter.py?
Examples of places in automation that are affected by this change: http://mxr.mozilla.org/mozilla-central/source/layout/tools/reftest/reftest-analyzer.xhtml#218 218 match = line.match(/^(TEST-PASS|TEST-UNEXPECTED-PASS|TEST-KNOWN-FAIL|TEST-UNEXPECTED-FAIL|TEST-DEBUG-INFO)(\(EXPECTED RANDOM\)|) \| ([^\|]+) \|(.*)/); http://mxr.mozilla.org/build-central/source/mozharness/scripts/android_panda.py#239 239 'regex': re.compile(r"(?:TEST-UNEXPECTED-FAIL|PROCESS-CRASH) \| .* \| (application crashed|missing output line for total leaks!|negative leaks caught!|\d+ bytes leaked)"), http://mxr.mozilla.org/build-central/source/mozharness/mozharness/mozilla/testing/errors.py#76 76 'full_regex': re.compile(r"(?:TEST-UNEXPECTED-FAIL|PROCESS-CRASH) \| .* \| (application crashed|missing output line for total leaks!|negative leaks caught!|\d+ bytes leaked)"), http://mxr.mozilla.org/build-central/source/buildbotcustom/steps/talos.py#116 116 None != re.search('TEST-UNEXPECTED-FAIL', stdioText)): http://mxr.mozilla.org/build-central/source/buildbotcustom/steps/mobile.py#45 45 harnessErrorsRe = re.compile(r"(?:TEST-UNEXPECTED-FAIL|PROCESS-CRASH) \| .* \| (application crashed|missing output line for total leaks!|negative leaks caught!|\d+ bytes leaked)") http://mxr.mozilla.org/build-central/source/buildbotcustom/steps/unittest.py#205 205 harnessErrorsRe = re.compile(r"(?:TEST-UNEXPECTED-FAIL|PROCESS-CRASH) \| .* \| (application crashed|missing output line for total leaks!|negative leaks caught!|\d+ bytes leaked)") http://mxr.mozilla.org/build-central/source/buildbotcustom/steps/unittest.py#92 92 harnessErrorsRe = re.compile(r"(?:TEST-UNEXPECTED-FAIL|PROCESS-CRASH) \| .* \| (application crashed|missing output line for total leaks!|negative leaks caught!|\d+ bytes leaked)")
Ok, I'm going to fix this. I will add that the tbplformatter is intended to maintain compatibility with our tools, but "same output as before" probably isn't possible in all cases given the invasive nature of some of the changes needed. But if we shouldn't make logs less useful in the meantime if it can be avoided.
Mass-closing old bugs I filed that have not had recent activity/no longer affect me.
Status: NEW → RESOLVED
Closed: 7 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.