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

Status: RESOLVED FIXED

(Testing :: Mochitest, defect)

Description

[Andrew McCreight [:mccr8]]

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.

Comment 1

[Andrew McCreight [:mccr8]]

I filed bug 1044213 for the underlying leak. Turns out this is inbound-only right now.

Comment 2

[Andrew McCreight [:mccr8]]

Having LSan failures not turn the tree orange is bad.

Comment 3

[Ed Morley [:emorley]]

TBPL just displays the job result as determined by buildbot which is whatever filtered through from {buildbotcustom,mozharness,test harness}.

Comment 4

[Chris Manchester (limited bugmail, email directly)]

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.

Comment 5

[Andrew McCreight [:mccr8]]

Hmm.  Ok.  The line that outputs this unexpected fail is:
  http://mxr.mozilla.org/mozilla-central/source/build/automationutils.py#784

Comment 6

[Ahmed Kachkach [:akachkach]]

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

Comment 7

[Chris Manchester (limited bugmail, email directly)]

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

Comment 8

[Ahmed Kachkach [:akachkach]]

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

Comment 9

[Andrew McCreight [:mccr8]]

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.

Comment 10

[Chris Manchester (limited bugmail, email directly)]

Attachment: Revert the global logger in mochitest's runtests to use python stdlib logging for compatibility to mozharness regex.

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.

Comment 11

[Chris Manchester (limited bugmail, email directly)]

This try run ran:

https://tbpl.mozilla.org/?tree=Try&rev=2a7007a73374

Comment 12

[Chris Manchester (limited bugmail, email directly)]

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.

Comment 13

[Ahmed Kachkach [:akachkach]]

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 14

[Andrew Halberstadt [:ahal]]

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.

Comment 15

[Chris Manchester (limited bugmail, email directly)]

(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

Comment 16

[Ed Morley [:emorley]]

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.

Comment 17

[Ed Morley [:emorley]]

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

Comment 18

[Andrew McCreight [:mccr8]]

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.

Comment 19

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/327f8728d818

Comment 20

[Andrew McCreight [:mccr8]]

This should get landed on Aurora, too.

Comment 21

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/76460bbfb47f