Open Bug 1407293 Opened 2 years ago Updated Last month

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

Categories

(Testing :: Mochitest, enhancement)

enhancement
Not set

Tracking

(Not tracked)

People

(Reporter: aryx, Unassigned)

References

(Blocks 1 open bug, Regression)

Details

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)
You need to log in before you can comment on or make changes to this bug.