540617 - Process.kill instantiates another Automation(), which adds another log handler

Status: VERIFIED FIXED

(Testing :: General, defect)

Description

[Jesse Ruderman]

Process.kill instantiates another Automation() in order to read IS_WIN32:
http://hg.mozilla.org/mozilla-central/annotate/ffab97de1041/build/automation.py.in#l171

Which has the side effect of adding another log handler, duplicating all output:
http://hg.mozilla.org/mozilla-central/annotate/ffab97de1041/build/automation.py.in#l135

This is a regression from the patch in bug 530475.

Process.kill could check the OS directly, or take the existing Automation object as an argument.  The latter would also make it possible to fix the "self.log.info" line in Process.kill, which looks to me like it gets the wrong "self" and won't work.

Or Automation() could be smarter about when it puts its logging handler in place, so instantiating an extra one doesn't have such weird side effects.

Comment 1

[Joel Maher ( :jmaher ) (UTC -8)]

ok,I am testing a patch to fix this.

In python, a inner class does not have access to any members or methods of the outer class.  So to fix this I move log back out of the automation class and reference the global variable during __init__ for both automation and process.

Comment 2

[(not currently active) Ted Mielczarek]

Presumably this is what has been causing the triple-logging?

Comment 3

[Joel Maher ( :jmaher ) (UTC -8)]

the triple logging has been seen for the automationutils.processLeakLog output.  I see double-logging in the logs and on my linux desktop.  With my fix I am testing it only outputs a single log of output.  I will verify with the results on the tryserver.

Comment 4

[Joel Maher ( :jmaher ) (UTC -8)]

Attachment: only instantiate one instance of log in automation.py

fixed mochitest output to only instantiate one instance of the logger in automation.py.  This passes on try server and by verifying the logs on tryserver I do not see the triple-logging style output.

Comment 5

[(not currently active) Ted Mielczarek]

Comment on attachment 422401 [details] [diff] [review]
only instantiate one instance of log in automation.py

>diff -r 0f2db07ea587 build/automation.py.in
>--- a/build/automation.py.in	Tue Jan 19 11:42:40 2010 -0500
>+++ b/build/automation.py.in	Tue Jan 19 12:51:26 2010 -0500
>@@ -71,6 +71,15 @@
> #expand _IS_DEBUG_BUILD = __IS_DEBUG_BUILD__
> #expand _CRASHREPORTER = __CRASHREPORTER__ == 1
> 
>+# We use the logging system here primarily because it'll handle multiple
>+# threads, which is needed to process the output of the server and application
>+# processes simultaneously.
>+_log = logging.getLogger()
>+handler = logging.StreamHandler(sys.stdout)
>+_log.setLevel(logging.INFO)
>+_log.addHandler(handler)

Any reason to call this "_log" and not just "log"? (At least make "handler" named consistently with whatever you pick.)

>@@ -130,16 +139,8 @@
>   # timeout, in seconds
>   DEFAULT_TIMEOUT = 60.0
> 
>-  log = logging.getLogger()

Does setting log = _log here not work? Do you have to set it in __init__ ? (Or do you just want to do that so you can override it in your subclass?)

r=me either way

Comment 6

[Serge Gautherie (:sgautherie)]

I already reported this bug in bug 573739, before m-c check-in :-/

Now I see doubled leak stats or the like, i.e.
{
http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey/1264894221.1264895863.4401.gz
Linux comm-central-trunk debug test mochitest-other on 2010/01/30 15:30:21

TEST-UNEXPECTED-FAIL | automationutils.processLeakLog() | missing output line for total leaks!
TEST-UNEXPECTED-FAIL | automationutils.processLeakLog() | missing output line for total leaks!
}

Comment 7

[Jesse Ruderman]

> I already reported this bug in bug 573739,

Typo for bug 537739.

Comment 8

[Joel Maher ( :jmaher ) (UTC -8)]

Attachment: only instantiate one instance of log in automation.py (1.2)

updated for bitrot since this is landing after my other refactoring changes.

Comment 9

[Joel Maher ( :jmaher ) (UTC -8)]

Attachment: only instantiate one instance of log in automation.py (1.3)

updated for bitrot, now that my other patches.  This patch passes on try server.

Comment 10

[cmtalbert]

Landed as changeset 0c3f8048f40b

Comment 11

[Serge Gautherie (:sgautherie)]

http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey/1268951466.1268953048.10535.gz&fulltext=1
Linux comm-central-trunk debug test mochitest-other on 2010/03/18 15:31:06

V.Fixed