850681 - Make automationutils.processLeakLog() output leaks in a TBPL compatible format

Status: RESOLVED FIXED

(Testing :: General, defect)

Description

[Ed Morley [:emorley]]

This bug is for the automationutils.py part of bug 850670.

See comments there for context.

Comment 1

[Ed Morley [:emorley]]

Attachment: Part 1: s/automationutils.processLeakLog()/leakcheck/

Reduces the chance of line wrapping in the TBPL annotated summary, and makes
my eyes bleed less every time I see leak failures.

Comment 2

[Ed Morley [:emorley]]

Attachment: Part 2: Move output of summary outside the loop

Wait until the full leak log has been processed before outputting the leak total. Will allow the addition of an overview of the leaked objects, in part 4.

Comment 3

[Ed Morley [:emorley]]

Attachment: Part 3: Only use TEST-INFO for per-object log output

Output all of the leaked object lines as TEST-INFO rather than a combination of TEST-INFO and TEST-UNEXPECTED-FAIL.

Since the main leak summary will soon include an overview of the leaked objects,
we no longer need/want a subset of the individual leak lines showing up in
TBPL's annotated summary (TBPL's parser matches on 'TEST-UNEXPECTED-FAIL').

Comment 4

[Ed Morley [:emorley]]

Attachment: Part 4: Add leaked objects list to leak summary

Add a partial list of leaked objects to the leak summary, to allow TBPL to make bug suggestions.

Current summary line:
TEST-UNEXPECTED-FAIL | automationutils.processLeakLog() | leaked 216 bytes during test execution

With patch parts 1-4:
TEST-UNEXPECTED-FAIL | leakcheck | 180 bytes leaked (Mutex, ReentrantMonitor, nsRunnable, nsTArray_base, nsThread)

...or with ellipses if more than 5 objects:
TEST-UNEXPECTED-FAIL | leakcheck | 3184 bytes leaked (BackstagePass, CondVar, Mutex, ReentrantMonitor, SharedScriptableHelperForJSIID, ...)

Comment 5

[Ed Morley [:emorley]]

Attachment: Part 5: Clean up logging

Comment 6

[Ed Morley [:emorley]]

Attachment: Part 6: More cleanup

* Clean up log parsing conditionals.
* Move the leak threshold reminder to the calling function. The same threshold is used for all leak logs processed from the test run, so unnecessary to repeat for each.

Comment 7

[Ed Morley [:emorley]]

Attachment: Part 7: Improve log file handling

* Use the cleaner |with open() as foo| pattern.
* Don't close then reopen the same leak log unnecessarily.

Comment 8

[Ed Morley [:emorley]]

Attachment: Part 8: Only parse the leak log once

The existing code parses the leak log twice - first time to output the raw log lines & and the second to output the analysis of them.

As much fun as it is to loop all the things (\o/), let's not.

Comment 9

[Ed Morley [:emorley]]

Attachment: Part 9: Favour returning early

Now that we close the log file before summary generation (rather
than at the end of processSingleLeakFile()), we can return early in some cases during leak summary generation.

Comment 10

[Ed Morley [:emorley]]

Attachment: Part 10: Tweak comments

Comment 11

[Ed Morley [:emorley]]

Attachment: Part 11: Make output for subprocesses match typical logging format

* Move processString to the message part of log lines.
* Remove unhelpful process IDs

--

Our standing logging format is:
TEST-{INFO,UNEXPECTED-FAIL} | testName | message

For leak logs from processes other than the main process (eg plugin processes),
currently processSingleLeakFile outputs:
TEST-{INFO,UNEXPECTED-FAIL} | foo process 123 | testName | message

This patch turns these into:
TEST-{INFO,UNEXPECTED-FAIL} | testName | foo process: message

Note: The process ID is contained in the raw leak log (which gets printed to the
log anyway), so we don't need to repeat it in the main summary log lines. In
addition, the variable process ID often breaks TBPL bug suggestions, so should
be avoided where possible.

Comment 12

[Ed Morley [:emorley]]

Attachment: Folded patchset

Comment 13

[Ed Morley [:emorley]]

Ignoring comments, this patchset removes ~20 lines whilst also adding support for TBPL compatible leaked object summaries - processSingleLeakFile() / processLeakLog() were clearly due for a spring clean :-)

(Annotate shows much of their contents came from automation.py.in and has remained largely untouched for 2-3 years)

Comment 14

[Ed Morley [:emorley]]

Example leak:
https://tbpl.mozilla.org/?tree=Try&rev=ceec35408c3c&onlyunstarred=1
https://tbpl.mozilla.org/php/getParsedLog.php?id=20697607&tree=Try

{
11:32:47  WARNING -  TEST-UNEXPECTED-FAIL | leakcheck | leaked 336 bytes (Mutex, ReentrantMonitor, nsRunnable, nsTArray_base, nsThread)
}

Comment 15

[(not currently active) Ted Mielczarek]

Comment on attachment 725514 [details] [diff] [review]
Part 1: s/automationutils.processLeakLog()/leakcheck/

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

We should make all these calls use a common method at some point to format the error message. I think we have that in moztest, but it wasn't quite satisfying last time I looked at it.

Comment 16

[(not currently active) Ted Mielczarek]

Comment on attachment 725518 [details] [diff] [review]
Part 4: Add leaked objects list to leak summary

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

::: build/automationutils.py
@@ +379,5 @@
> +      maxSummaryObjects = 5
> +      leakedObjectSummary = ', '.join(leakedObjectNames[:maxSummaryObjects])
> +      # The leaked objects shown when above the maxSummaryObjects threshold has
> +      # been exceeded, has no significance (they're sorted alphabetically), so we
> +      # add a continuation ellipsis to at least indicate there are others.

Do we have a lot of leaks in practice where the set of objects changes? I'm wondering how variable this string is going to be.

Comment 17

[(not currently active) Ted Mielczarek]

Comment on attachment 725525 [details] [diff] [review]
Part 8: Only parse the leak log once

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

::: build/automationutils.py
@@ +328,5 @@
>        bytesLeaked = int(matches.group("bytesLeaked"))
>        numLeaked = int(matches.group("numLeaked"))
> +      # Output the raw line from the leak log table if it is the TOTAL row,
> +      # or is for an object row that has been leaked.
> +      if (numLeaked != 0 or name == "TOTAL"):

Don't need the parentheses here.

Comment 18

[(not currently active) Ted Mielczarek]

Comment on attachment 725527 [details] [diff] [review]
Part 10: Tweak comments

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

::: build/automationutils.py
@@ +358,5 @@
>    if totalBytesLeaked == 0:
>      log.info("TEST-PASS %s| leakcheck | no leaks detected!" % processString)
>      return
>  
> +  # else: (totalBytesLeaked was seen and is non-zero)

I would just state this as a sentence:
# totalBytesLeaked was seen and is non-zero.

Comment 19

[(not currently active) Ted Mielczarek]

Comment on attachment 725528 [details] [diff] [review]
Part 11: Make output for subprocesses match typical logging format

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

I guess the PID doesn't really provide value here in the log messages. Thanks for moving it out of the test status part, that bugged me.

::: build/automationutils.py
@@ +334,5 @@
>        # Analyse the leak log, but output later or it will interrupt the leak table
>        if name == "TOTAL":
>          totalBytesLeaked = bytesLeaked
>        if size < 0 or bytesLeaked < 0 or numLeaked < 0:
> +        leakAnalysis.append("TEST-UNEXPECTED-FAIL | leakcheck |%s negative leaks caught!"

nit: I think it would look nicer if you left the leading space out of processString and put it in the individual log lines instead.

Comment 20

[(not currently active) Ted Mielczarek]

Thanks for splitting this into such nice bite-sized pieces, it made reviewing it super-simple.

Comment 21

[Ed Morley [:emorley]]

(In reply to Ted Mielczarek [:ted.mielczarek] from comment #16)
> Do we have a lot of leaks in practice where the set of objects changes? I'm
> wondering how variable this string is going to be.

I had a look over some of the more recent leaks on http://bugzil.la/ALL%20leak bytes keywords%3Aintermittent-failure and they seemed to be pretty unique, so I'm hopeful there will be few false positives (and it will definitely help for many of the leak top oranges we have at the moment).

(In reply to Ted Mielczarek [:ted.mielczarek] from comment #17)
> > +      if (numLeaked != 0 or name == "TOTAL"):
> 
> Don't need the parentheses here.

Good point - updated.

(In reply to Ted Mielczarek [:ted.mielczarek] from comment #18)
> I would just state this as a sentence:
> # totalBytesLeaked was seen and is non-zero.

Done :-)

(In reply to Ted Mielczarek [:ted.mielczarek] from comment #19)
> > +        leakAnalysis.append("TEST-UNEXPECTED-FAIL | leakcheck |%s negative leaks caught!"
> 
> nit: I think it would look nicer if you left the leading space out of
> processString and put it in the individual log lines instead.

Unfortunately that would leave a double space in the processString = '' case (which is the most common).

(In reply to Ted Mielczarek [:ted.mielczarek] from comment #20)
> Thanks for splitting this into such nice bite-sized pieces, it made
> reviewing it super-simple.

No problem :-)

Comment 22

[Ed Morley [:emorley]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/102365bfe4d3
https://hg.mozilla.org/integration/mozilla-inbound/rev/c314aefc1244
https://hg.mozilla.org/integration/mozilla-inbound/rev/0c83c9036f9e
https://hg.mozilla.org/integration/mozilla-inbound/rev/a40f95ea3951
https://hg.mozilla.org/integration/mozilla-inbound/rev/2931467b2c54
https://hg.mozilla.org/integration/mozilla-inbound/rev/321bca7cf97a
https://hg.mozilla.org/integration/mozilla-inbound/rev/6d5de0363957
https://hg.mozilla.org/integration/mozilla-inbound/rev/ae92e0819f2b
https://hg.mozilla.org/integration/mozilla-inbound/rev/de7502c6b940
https://hg.mozilla.org/integration/mozilla-inbound/rev/025f582f8005
https://hg.mozilla.org/integration/mozilla-inbound/rev/7ac3f76249e7

Comment 23

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/102365bfe4d3
https://hg.mozilla.org/mozilla-central/rev/c314aefc1244
https://hg.mozilla.org/mozilla-central/rev/0c83c9036f9e
https://hg.mozilla.org/mozilla-central/rev/a40f95ea3951
https://hg.mozilla.org/mozilla-central/rev/2931467b2c54
https://hg.mozilla.org/mozilla-central/rev/321bca7cf97a
https://hg.mozilla.org/mozilla-central/rev/6d5de0363957
https://hg.mozilla.org/mozilla-central/rev/ae92e0819f2b
https://hg.mozilla.org/mozilla-central/rev/de7502c6b940
https://hg.mozilla.org/mozilla-central/rev/025f582f8005
https://hg.mozilla.org/mozilla-central/rev/7ac3f76249e7

Comment 24

[Ed Morley [:emorley]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/b9e57236174c
https://hg.mozilla.org/releases/mozilla-beta/rev/ec116a3ff401
https://hg.mozilla.org/releases/mozilla-esr17/rev/659ce2b0bb83
https://hg.mozilla.org/releases/mozilla-b2g18/rev/24a72dbd85e4