Closed Bug 1044206 Opened 6 years ago Closed 5 years ago

ASAN M3 is green, even though it shouldn't be

Categories

(Testing :: Mochitest, defect)

defect
Not set

Tracking

(firefox32 unaffected, firefox33 fixed, firefox34 fixed)

RESOLVED FIXED
mozilla34
Tracking Status
firefox32 --- unaffected
firefox33 --- fixed
firefox34 --- fixed

People

(Reporter: mccr8, Assigned: chmanchester)

References

(Blocks 2 open bugs)

Details

(Whiteboard: [MemShrink:P1])

Attachments

(1 file)

I was looking through the logs for our ASAN runs, and M3 is failing like this:
  https://tbpl.mozilla.org/php/getParsedLog.php?id=44599326&tree=Mozilla-Inbound

The Summary at the top says:
22750 INFO SUMMARY: AddressSanitizer: 10368 byte(s) leaked in 12 allocation(s).
22751 INFO TEST-UNEXPECTED-FAIL | LeakSanitizer | leak at mozilla::gmp::GMPParent::LoadProcess, EnsureProcessLoaded, mozilla::gmp::GMPParent::GetGMPVideoEncoder, mozilla::gmp::GeckoMediaPluginService::GetGMPVideoEncoder

...but for some reason the test is still green.  I think the problem is that TBPL is somehow failing to realize that there is a failure?  Does anybody have an idea how to fix this?

I'll file a separate bug for the actual leak that is being shown here.  We can land a suppression for this particular leak until it is fixed, if the TBPL problem is fixed first.
I filed bug 1044213 for the underlying leak. Turns out this is inbound-only right now.
Having LSan failures not turn the tree orange is bad.
Whiteboard: [MemShrink]
Blocks: LSan
TBPL just displays the job result as determined by buildbot which is whatever filtered through from {buildbotcustom,mozharness,test harness}.
Component: Tinderboxpushlog → General Automation
Product: Webtools → Release Engineering
QA Contact: catlee
Version: Trunk → other
It looks like bug 886570 caused the log format to change subtly and fail to trigger mozharness' regex: TEST-UNEXPECTED-FAIL no longer appears at the beginning of the line, and doesn't contribute to the printed summary.
Hmm.  Ok.  The line that outputs this unexpected fail is:
  http://mxr.mozilla.org/mozilla-central/source/build/automationutils.py#784
Component: General Automation → Mochitest
Product: Release Engineering → Testing
QA Contact: catlee
Version: other → Trunk
@chmanchester:

22751 INFO TEST-UNEXPECTED-FAIL | LeakSanitizer | leak at mozilla::gmp::GMPParent::LoadProcess, EnsureProcessLoaded, mozilla::gmp::GMPParent::GetGMPVideoEncoder, mozilla::gmp::GeckoMediaPluginService::GetGMPVideoEncoder

Looks like this should trigger an error in mozharness ("TEST-UNEXPECTED" is there, which is parsed by this: http://mxr.mozilla.org/build/source/mozharness/mozharness/mozilla/testing/errors.py#77).

For http://mxr.mozilla.org/mozilla-central/source/build/automationutils.py#784 : self.logger in this context is the info method of the structured logger.

Could this be related to bug 1045255 somehow?
(In reply to Ahmed Kachkach [:akachkach] from comment #6)
> @chmanchester:
> 
> 22751 INFO TEST-UNEXPECTED-FAIL | LeakSanitizer | leak at
> mozilla::gmp::GMPParent::LoadProcess, EnsureProcessLoaded,
> mozilla::gmp::GMPParent::GetGMPVideoEncoder,
> mozilla::gmp::GeckoMediaPluginService::GetGMPVideoEncoder
> 
> Looks like this should trigger an error in mozharness ("TEST-UNEXPECTED" is
> there, which is parsed by this:
> http://mxr.mozilla.org/build/source/mozharness/mozharness/mozilla/testing/
> errors.py#77).

This gets tested with re.match here: http://mxr.mozilla.org/build/source/mozharness/mozharness/mozilla/testing/unittest.py#135, so only matches the beginning of a line.

> 
> For
> http://mxr.mozilla.org/mozilla-central/source/build/automationutils.py#784 :
> self.logger in this context is the info method of the structured logger.

This means the formatter adds the counter and level to the beginning of the line.

> 
> Could this be related to bug 1045255 somehow?
Mmh, OK.
This is pretty weird though: Since this uses the root logger, it should have the same formatting as the rest (linenumber INFO text) so I wonder how this worked before.

Could we just get rid of the match for (\d+ INFO ) in the summary regex? This would make things smoother (no need for a custom formatter and same format as the other test harnesses).
From comment 0, the line does come out in the log like "22751 INFO TEST-UNEXPECTED-FAIL", so it isn't disappearing like what seemed to be happening in bug 1045255.
See Also: → 1045525
The short answer to get this test coverage back is to convert the global "log" back to python logging. Current callers of this assume log.info("TEST-UNEXPECTED-FAIL ... will turn the build orange, which doesn't work if the global log is running through the new formatter.

Here it is on try, although I guess the underlying leak was fixed: https://tbpl.mozilla.org/?tree=Try&rev=8fa0e11e7954

This should be resolved properly with bug 1045525, but could land this if that's not going to be resolved immediately.
Assignee: nobody → cmanchester
Status: NEW → ASSIGNED
Comment on attachment 8464122 [details] [diff] [review]
Revert the global logger in mochitest's runtests to use python stdlib logging for compatibility to mozharness regex.

It looks like bug 1045525 is a little way from an ideal solution, and actually doesn't entirely fix this. Let's get this in to recover the lost test coverage in the short term.
Attachment #8464122 - Flags: review?(ahalberstadt)
Bug 1039833 will change how things are handled (to avoid using global loggers), and it should land soon, so you may need to rebase your patch on top of that.
Comment on attachment 8464122 [details] [diff] [review]
Revert the global logger in mochitest's runtests to use python stdlib logging for compatibility to mozharness regex.

Review of attachment 8464122 [details] [diff] [review]:
-----------------------------------------------------------------

Wait didn't we have to add a global logger back in to fix leak checking? And now were removing it again? I'm confused.. but if this fixes the immediate problem and doesn't regress anything else, r+ I guess. It looks like bug 1039833 needs to be rebased anyway, so if you can land this first feel free to go for it.
Attachment #8464122 - Flags: review?(ahalberstadt) → review+
(In reply to Andrew Halberstadt [:ahal] from comment #14)
> Comment on attachment 8464122 [details] [diff] [review]
> Revert the global logger in mochitest's runtests to use python stdlib
> logging for compatibility to mozharness regex.
> 
> Review of attachment 8464122 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Wait didn't we have to add a global logger back in to fix leak checking? And
> now were removing it again? I'm confused.. but if this fixes the immediate
> problem and doesn't regress anything else, r+ I guess. It looks like bug
> 1039833 needs to be rebased anyway, so if you can land this first feel free
> to go for it.

The thing that fixed leak checking was the code setting up handlers for python's logging module so the global in automationutils.py ("log = logging.getLogger()") would log somewhere. A global (structured) "log" is also set in runtests.py, this patch reverts that "log" to the python logger, and looks weird because "log" is defined further up in the file and reassigned in the code that's removed. 

https://hg.mozilla.org/integration/mozilla-inbound/rev/327f8728d818
This turned Asan m3 orange, but given that that seems like a good thing - I've just hidden the job for now and we can go about greening it up in another bug.
Depends on: 1046165
(In reply to Ed Morley [:edmorley] from comment #16)
> I've just hidden the job for now and we can go about greening it up in
> another bug.

Decided against hiding for now, we'll see how long it takes to fix bug 1046165 and can star in the meantime.
Thanks for fixing this!  As Ed said, we managed to cause an LSan leak in the two days since I last checked it, so it will be good to have this coverage.  (I think the M3 orange will be fixed by a backout Ed did.)  I'm going to declare this a MemShrink P1.
Whiteboard: [MemShrink] → [MemShrink:P1]
https://hg.mozilla.org/mozilla-central/rev/327f8728d818
Status: ASSIGNED → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla34
This should get landed on Aurora, too.
Depends on: 1046566
Blocks: 1048775
Blocks: 1046162
You need to log in before you can comment on or make changes to this bug.