Closed Bug 1518115 Opened 11 months ago Closed 10 months ago

Frequent TEST-UNEXPECTED-FAIL | leakcheck | tab missing output line for total leaks!

Categories

(Testing :: Mochitest, defect)

defect
Not set

Tracking

(firefox-esr60 unaffected, firefox64 unaffected, firefox65 fixed, firefox66 fixed)

VERIFIED FIXED
mozilla66
Tracking Status
firefox-esr60 --- unaffected
firefox64 --- unaffected
firefox65 --- fixed
firefox66 --- fixed

People

(Reporter: aryx, Assigned: mccr8)

References

Details

(Keywords: regression)

Attachments

(1 file)

At least since Friday, there are often multiple reports of
TEST-UNEXPECTED-FAIL | leakcheck | tab missing output line for total leaks!
in the failure logs, e.g. https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=220061833&repo=mozilla-central&lineNumber=31015

23:29:33     INFO - nsTraceRefcnt::DumpStatistics: 714 entries
23:29:33     INFO - TEST-PASS | leakcheck | tab no leaks detected!
23:29:33     INFO - leakcheck | Processing leak log file c:\users\task_1546642817\appdata\local\temp\tmpgx1py2.mozrunner\runtests_leaks_tab_pid1564.log
23:29:33     INFO - ==> process 1564 will purposefully crash
23:29:33     INFO - TEST-UNEXPECTED-FAIL | leakcheck | tab missing output line for total leaks!
23:29:33     INFO - leakcheck | Processing leak log file c:\users\task_1546642817\appdata\local\temp\tmpgx1py2.mozrunner\runtests_leaks_tab_pid1656.log
23:29:33     INFO - 
23:29:33     INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, tab process 1656
23:29:33     INFO - 
23:29:33     INFO -      |<----------------Class--------------->|<-----Bytes------>|<----Objects---->|
23:29:33     INFO -      |                                      | Per-Inst   Leaked|   Total      Rem|
23:29:33     INFO -    0 |TOTAL                                 |       25        0|  101635        0|
23:29:33     INFO - 
23:29:33     INFO - nsTraceRefcnt::DumpStatistics: 945 entries
23:29:33     INFO - TEST-PASS | leakcheck | tab no leaks detected!
23:29:33     INFO - leakcheck | Processing leak log file c:\users\task_15466428

etc.

So far there I haven't seen a log which only had those leakcheck lines as failure summary.

[Tracking Requested - why for this release]: We could be leaking and not detected it in testing.

Yeah, this is bad. This error means that a process is crashing before it produces a leak log, so we have no idea if it is actually leaking or not. As seen from the TEST-UNEXPECTED-FAIL, this is supposed to turn the test orange, but it appears not to.

I noticed this was happening in WPTs, but the leak checking is fairly new so it is less of a big deal there.

This seems like it might be permafailing in some directories. For instance, browser/base/content/test/plugins .

Oh, I see. This is probably just an issue with the output. I see this in the log:

[task 2019-01-11T04:58:18.990Z] 04:58:18 INFO - leakcheck | Processing leak log file /tmp/tmpCnNnqr.mozrunner/runtests_leaks_tab_pid1344.log
[task 2019-01-11T04:58:18.991Z] 04:58:18 INFO - ==> process 1344 will purposefully crash
[task 2019-01-11T04:58:18.992Z] 04:58:18 INFO - TEST-UNEXPECTED-FAIL | leakcheck | tab missing output line for total leaks!

So I think it is printing out the UNEXPECTED-FAIL as an INFO, because it isn't a failure. Still seems confusing.

Probably a regression from bug 1352355. I'll see if I can figure it out.

Oh, I see. There's a typo in these lines:
if data.get("induced_crashed", False):
I think it should be "induced_crash".

Assignee: nobody → continuation

This does suggest that we also don't turn the tree orange when a process actually fails to produce a leak log, but I'll have to make sure of that.

Okay, great it does seem to work, even if I don't understand how. :) I edited nsTraceRefcnt.cpp to not output anything in the leak log and it fails as expected:

0:33.32 INFO leakcheck | Processing leak log file /tmp/tmpoZVk6m.mozrunner/runtests_leaks_tab_pid26776.log
0:33.32 FAIL leakcheck: tab missing output line for total leaks!

If we log that it's logged at ERROR level and any logging at that level turns the tree orange [1]

[1] https://searchfox.org/mozilla-central/source/testing/mozharness/mozharness/mozilla/structuredlog.py#194

There should be a test for this, but I'm not entirely sure how to write one.

With my patch:
2:34.52 INFO leakcheck | Processing leak log file /tmp/tmpvlj4cC.mozrunner/runtests_leaks_plugin_pid10390.log
2:34.52 INFO ==> process 10390 will purposefully crash
2:34.52 INFO leakcheck: plugin deliberate crash and thus no leak log

(In reply to Andrew McCreight [:mccr8] from comment #9)

There should be a test for this, but I'm not entirely sure how to write one.

There's a mochitest selftest specifically for catching these sorts of failures:
https://searchfox.org/mozilla-central/source/testing/mochitest/tests/python/test_basic_mochitest_plain.py#104

Unfortunately I couldn't figure out how to write a mochitest that is guaranteed to cause a leak and I ended up mocking out the leaklog. Had the leaklog not been mocked, we may have caught this regression.

Can you help me improve this test?

On second look, the test just makes sure that leaklog turns the job orange, so likely wouldn't have caught the regression. But we can add some more assertions to make sure that the reason it's orange isn't a missing output line.

For this issue, we need an HTML file that causes an intentional crash (browser_crash_previous_frameloader.js does something like that. It requires some odd chrome code), and then check the log to make sure it contains the magic phrase "deliberate crash and thus no leak log" or whatever.

It would also be good to change the existing crash test to make sure that the leak log produces a leakcheck failure. It might be better to have a separate test that somehow runs Firefox without creating a leak log and without crashing but I'm not sure off the top of my head how to do that. (If the crash is already turning the test orange, it matters less if the leakcheck stuff also works, so it would be more useful to check the special case of no leakcheck log when there's no crash.)

See Also: → 1521191
Pushed by amccreight@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/ede9544aaf4d
Fix typo in intentional crash leak log processing. r=jgraham
Status: NEW → RESOLVED
Closed: 10 months ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla66
Whiteboard: [checkin-needed-release]

I looked at the Treeherder output for a recent m-c Linux 64 debug run, and I did not see any of the leakcheck output in the errors tab. (This was happening 100% of the time for some tests.) Please file a new bug and ni? me if this fails again, or for future leakcheck problems.

Status: RESOLVED → VERIFIED
You need to log in before you can comment on or make changes to this bug.