Bug 1048446 - [mozlog] Don't re-use existing loggers when calling mozlog.commandline.setup_logging a second time, r=jgraham
authorAndrew Halberstadt <ahalberstadt@mozilla.com>
Mon, 29 May 2017 14:23:04 -0400
changeset 413750 525728eff624112eedff5009655cd837c09420bd
parent 413749 f375a096bff95e10f770a779155012ff8647847d
child 413751 91ce65d749ad9261dd36d287c84a61e799fd5295
push id1490
push usermtabara@mozilla.com
push dateMon, 31 Jul 2017 14:08:16 +0000
treeherdermozilla-release@70e32e6bf15e [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersjgraham
bugs1048446
milestone55.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 1048446 - [mozlog] Don't re-use existing loggers when calling mozlog.commandline.setup_logging a second time, r=jgraham This is case that got hit with the new mochitest selftest harness. In this scenario, several MochitestDesktop instances (which call commandline.setup_logging in their constructor) are instantiated in the same interpreter. Because mozlog implicitly saves the logger state, this meant that setup_logging kept appending duplicate handlers to the existing ones. I believe that the intent of 'setup_logging' is to get a brand new logger, so it should ensure logger state is reset on subsequent calls. MozReview-Commit-ID: Jqyhbj7nC6z
testing/mochitest/runtests.py
testing/mozbase/mozlog/mozlog/commandline.py
testing/mozbase/mozlog/mozlog/structuredlog.py
--- a/testing/mochitest/runtests.py
+++ b/testing/mochitest/runtests.py
@@ -794,17 +794,16 @@ class MochitestDesktop(object):
     """
     oldcwd = os.getcwd()
     mochijar = os.path.join(SCRIPT_DIR, 'mochijar')
 
     # Path to the test script on the server
     TEST_PATH = "tests"
     NESTED_OOP_TEST_PATH = "nested_oop"
     CHROME_PATH = "redirect.html"
-    log = None
 
     certdbNew = False
     sslTunnel = None
     DEFAULT_TIMEOUT = 60.0
     mediaDevices = None
 
     patternFiles = {}
 
@@ -824,26 +823,20 @@ class MochitestDesktop(object):
         self._locations = None
 
         self.marionette = None
         self.start_script = None
         self.mozLogs = None
         self.start_script_kwargs = {}
         self.urlOpts = []
 
-        if self.log is None:
-            commandline.log_formatters["tbpl"] = (
-                MochitestFormatter,
-                "Mochitest specific tbpl formatter")
-            self.log = commandline.setup_logging("mochitest",
-                                                 logger_options,
-                                                 {
-                                                     "tbpl": sys.stdout
-                                                 })
-            MochitestDesktop.log = self.log
+        commandline.log_formatters["tbpl"] = (
+            MochitestFormatter,
+            "Mochitest specific tbpl formatter")
+        self.log = commandline.setup_logging("mochitest", logger_options, {"tbpl": sys.stdout})
 
         # Jetpack flavors still don't use the structured logger. We need to process their output
         # slightly differently.
         structured = not self.flavor.startswith('jetpack')
         self.message_logger = MessageLogger(
                 logger=self.log, buffering=quiet, structured=structured)
 
         # Max time in seconds to wait for server startup before tests will fail -- if
--- a/testing/mozbase/mozlog/mozlog/commandline.py
+++ b/testing/mozbase/mozlog/mozlog/commandline.py
@@ -209,16 +209,19 @@ def setup_logging(logger, args, defaults
                      logs otherwise).
     :param formatter_defaults: A dictionary of {option_name: default_value} to provide
                                to the formatters in the absence of command line overrides.
     :rtype: StructuredLogger
     """
 
     if not isinstance(logger, StructuredLogger):
         logger = StructuredLogger(logger)
+        # The likely intent when using this function is to get a brand new
+        # logger, so reset state in case it was previously initialized.
+        logger.reset_state()
 
     # Keep track of any options passed for formatters.
     formatter_options = {}
     # Keep track of formatters and list of streams specified.
     formatters = defaultdict(list)
     found = False
     found_stdout_logger = False
     if args is None:
--- a/testing/mozbase/mozlog/mozlog/structuredlog.py
+++ b/testing/mozbase/mozlog/mozlog/structuredlog.py
@@ -106,16 +106,19 @@ lint_levels = ["ERROR", "WARNING"]
 def log_actions():
     """Returns the set of actions implemented by mozlog."""
     return set(convertor_registry.keys())
 
 
 class LoggerState(object):
 
     def __init__(self):
+        self.reset()
+
+    def reset(self):
         self.handlers = []
         self.running_tests = set()
         self.suite_started = False
         self.component_states = {}
 
 
 class ComponentState(object):
 
@@ -149,16 +152,23 @@ class StructuredLogger(object):
     def add_handler(self, handler):
         """Add a handler to the current logger"""
         self._state.handlers.append(handler)
 
     def remove_handler(self, handler):
         """Remove a handler from the current logger"""
         self._state.handlers.remove(handler)
 
+    def reset_state(self):
+        """Resets the logger to a brand new state. This means all handlers
+        are removed, running tests are discarded and components are reset.
+        """
+        self._state.reset()
+        self._component_state = self._state.component_states[self.component] = ComponentState()
+
     def send_message(self, topic, command, *args):
         """Send a message to each handler configured for this logger. This
         part of the api is useful to those users requiring dynamic control
         of a handler's behavior.
 
         :param topic: The name used by handlers to subscribe to a message.
         :param command: The name of the command to issue.
         :param args: Any arguments known to the target for specialized