Open Bug 1407293 Opened 7 years ago Updated 2 years ago

Mochitest output not in valid Treeherder format ("ERROR <test name> logged result after SimpleTest.finish(): showAlertNotification() succeeded. Waiting for notification...")

Categories

(Testing :: Mochitest, defect)

Product:
Testing
Component:
Mochitest
Type:
defect

Tracking

(Not tracked)

People

(Reporter: aryx, Unassigned)

References

(Blocks 1 open bug, Regression)

Details

(Keywords: regression) 

Which line(s) are the ones that you would have expected to appear?
(I've had a quick glance but it's not overly obvious; don't have spare time to look much further, so any assistance would be useful :-))
Flags: needinfo?(aryx.bugmail)
Sorry, this one:
14:45:48     INFO -  1446 ERROR /tests/toolkit/components/alerts/test/test_alerts.html logged result after SimpleTest.finish(): showAlertNotification() succeeded.  Waiting for notification...
Flags: needinfo?(aryx.bugmail)
(In reply to Sebastian Hengst [:aryx][:archaeopteryx] (needinfo on intermittent or backout) from comment #2)
> Sorry, this one:
> 14:45:48     INFO -  1446 ERROR
> /tests/toolkit/components/alerts/test/test_alerts.html logged result after
> SimpleTest.finish(): showAlertNotification() succeeded.  Waiting for
> notification...

That log output isn't one Treeherder matches, this looks like either mozharness/mozbase/mochitest is not outputting the correct output.

(In reply to OrangeFactor Robot from comment #3)
> 2 failures in 947 pushes (0.002 failures/push) were associated with this bug
> in the last 7 days.    

The intermittent failures shouldn't be classified against this bug, since this is just about improving the log output so they are easier to identify, rather than the actual root cause of the issue.
Summary: Should show in log summary: ERROR <test name> logged result after SimpleTest.finish(): showAlertNotification() succeeded. Waiting for notification... → Mochitest output not in valid Treeherder format ("ERROR <test name> logged result after SimpleTest.finish(): showAlertNotification() succeeded. Waiting for notification...")
Component: Treeherder: Log Parsing & Classification → Mochitest
Product: Tree Management → Testing
Version: --- → unspecified
Blocks: 778688

Bug 1372567 changed the call from TestRunner.structuredLogger.testStatus to TestRunner.structuredLogger.error. That passes through:

TestRunner.js::runNextTest
StructuredLog.jsm::error
log => _logData => _dumpFun
TestRunner.js::_dumpMessage
LogController.js::log

It doesn't match any expression used by Treeherder to generate the failure summary.

Andrew, do you have an idea how to get this properly logged? Add TEST_UNEXPECTED-LOGORDER?

Flags: needinfo?(ahal)
Regressed by: 1372567

That stack is only half the story. The message logged by LogController is actually an object. The Python harness is then supposed to parse that object and format it into what you see in the treeherder logs. All error logs are supposed to show up in the treeherder failure summary, so something isn't quite working here.

Here's where the Python side picks things up again:
https://searchfox.org/mozilla-central/source/testing/mochitest/runtests.py#209

Ultimately we end up passing the json over to self.logger.log_raw:
https://searchfox.org/mozilla-central/source/testing/mozbase/mozlog/mozlog/structuredlog.py#231

And formatting passes through here:
https://searchfox.org/mozilla-central/source/testing/mochitest/runtests.py#140

Either that format isn't triggering the treeherder error summary anymore (in which case we have a big problem), or something else is breaking down elsewhere along the chain.

Flags: needinfo?(ahal)

This is still an issue today; see bug 1627523 for examples.

Blocks: 1627523
Type: enhancement → defect

(In reply to Andrew Halberstadt [:ahal] from comment #11)

All error logs are supposed to show up in the treeherder failure summary, so something isn't quite working here.

There does seem to be a disconnect between the expectations of the harness and treeherder.

A recent example:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=305332275&repo=mozilla-central&lineNumber=4900

[task 2020-06-06T13:44:34.221Z] 13:44:34     INFO -  1730 INFO TEST-PASS | dom/tests/mochitest/general/test_selectevents.html | The original target of selectionchange should be the document
[task 2020-06-06T13:44:34.221Z] 13:44:34     INFO -  1731 ERROR /tests/dom/tests/mochitest/general/test_selectevents.html logged result after SimpleTest.finish(): The original target of selectionchange should be the document

That ERROR is not picked up for treeherder error suggestions.

On the other hand, this one is:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=305332275&repo=mozilla-central&lineNumber=14637

[task 2020-06-06T13:57:03.429Z] 13:57:03     INFO -  SUITE-END | took 1306s
[task 2020-06-06T13:57:03.448Z] 13:57:03    ERROR - Return code: 1
Has Regression Range: --- → yes
Severity: normal → S3
You need to log in before you can comment on or make changes to this bug.