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

Status: VERIFIED FIXED

(Testing :: Mochitest, defect)

Description

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

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.

Comment 1

[Andrew McCreight [:mccr8]]

[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 .

Comment 2

[Andrew McCreight [:mccr8]]

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.

Comment 3

[Andrew McCreight [:mccr8]]

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

Comment 4

[Andrew McCreight [:mccr8]]

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

Comment 5

[Andrew McCreight [:mccr8]]

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.

Comment 6

[Andrew McCreight [:mccr8]]

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!

Comment 7

[James Graham [:jgraham]]

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

Comment 8

[Andrew McCreight [:mccr8]]

Attachment: Bug 1518115 - Fix typo in intentional crash leak log processing.

Comment 9

[Andrew McCreight [:mccr8]]

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

Comment 10

[Andrew McCreight [:mccr8]]

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

Comment 11

[Andrew Halberstadt [:ahal]]

(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?

Comment 12

[Andrew Halberstadt [:ahal]]

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.

Comment 13

[Andrew McCreight [:mccr8]]

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.)

Comment 14

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/ede9544aaf4d
Fix typo in intentional crash leak log processing. r=jgraham

Comment 15

[Cosmin Sabou [:CosminS]]

https://hg.mozilla.org/mozilla-central/rev/ede9544aaf4d

Comment 16

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-release/rev/d846ea61f347

Comment 17

[Andrew McCreight [:mccr8]]

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.