Bug 1043314 - Enforce the invariant that we have suite_start before suite_end or test_start in mozlog. r=chmanchester, a=test-only
authorJames Graham <james@hoppipolla.co.uk>
Fri, 25 Jul 2014 13:42:56 +0100
changeset 217487 8228c26bbf6df0e199cdd3126b5acbab416873a9
parent 217486 66f85cab2dc2091546c4dd25054e93a9fc5a02c5
child 217488 a9e0bbe91f86454e47c656378f16fdb7f2ffd5fb
push id515
push userraliiev@mozilla.com
push dateMon, 06 Oct 2014 12:51:51 +0000
treeherdermozilla-release@267c7a481bef [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewerschmanchester, test-only
bugs1043314
milestone33.0a2
Bug 1043314 - Enforce the invariant that we have suite_start before suite_end or test_start in mozlog. r=chmanchester, a=test-only
testing/mozbase/mozlog/mozlog/structured/structuredlog.py
testing/mozbase/mozlog/tests/test_structured.py
--- a/testing/mozbase/mozlog/mozlog/structured/structuredlog.py
+++ b/testing/mozbase/mozlog/mozlog/structured/structuredlog.py
@@ -80,45 +80,59 @@ def set_default_logger(default_logger):
     global _default_logger_name
 
     _default_logger_name = default_logger.name
 
 log_levels = dict((k.upper(), v) for v, k in
                   enumerate(["critical", "error", "warning", "info", "debug"]))
 
 
+class LoggerState(object):
+    def __init__(self):
+        self.handlers = []
+        self.running_tests = set()
+        self.suite_started = False
+
 class StructuredLogger(object):
     _lock = Lock()
-    _handlers = defaultdict(list)
+    _logger_states = {}
     """Create a structured logger with the given name
 
     :param name: The name of the logger.
+    :param component: A subcomponent that the logger belongs to (typically a library name)
     """
 
     def __init__(self, name, component=None):
-        self._running_tests = set()
         self.name = name
         self.component = component
 
+        with self._lock:
+            if name not in self._logger_states:
+                self._logger_states[name] = LoggerState()
+
+    @property
+    def _state(self):
+        return self._logger_states[self.name]
+
     def add_handler(self, handler):
         """Add a handler to the current logger"""
-        self._handlers[self.name].append(handler)
+        self._state.handlers.append(handler)
 
     def remove_handler(self, handler):
         """Remove a handler from the current logger"""
-        for i, candidate_handler in enumerate(self._handlers[self.name][:]):
+        for i, candidate_handler in enumerate(self._state.handlers[:]):
             if candidate_handler == handler:
-                del self._handlers[self.name][i]
+                del self._state.handlers[i]
                 break
 
     @property
     def handlers(self):
         """A list of handlers that will be called when a
         message is logged from this logger"""
-        return self._handlers[self.name]
+        return self._state.handlers
 
     def log_raw(self, data):
         if "action" not in data:
             raise ValueError
         data = self._make_log_data(data['action'], data)
         self._handle_log(data)
 
     def _log_data(self, action, data=None):
@@ -144,34 +158,52 @@ class StructuredLogger(object):
         all_data.update(data)
         return all_data
 
     def suite_start(self, tests, run_info=None):
         """Log a suite_start message
 
         :param tests: List of test identifiers that will be run in the suite.
         """
+
         data = {"tests": tests}
         if run_info is not None:
             data["run_info"] = run_info
+
+        if self._state.suite_started:
+            self.error("Got second suite_start message before suite_end. Logged with data %s" %
+                       json.dumps(data))
+            return
+
+        self._state.suite_started = True
+
         self._log_data("suite_start", data)
 
     def suite_end(self):
         """Log a suite_end message"""
+        if not self._state.suite_started:
+            self.error("Got suite_end message before suite_start.")
+            return
+
+        self._state.suite_started = False
+
         self._log_data("suite_end")
 
     def test_start(self, test):
         """Log a test_start message
 
         :param test: Identifier of the test that will run.
         """
-        if test in self._running_tests:
-            self.error("test_start for %s logged while in progress." % test)
+        if not self._state.suite_started:
+            self.error("Got test_start message before suite_start for test %s" % (test,))
             return
-        self._running_tests.add(test)
+        if test in self._state.running_tests:
+            self.error("test_start for %s logged while in progress." % (test,))
+            return
+        self._state.running_tests.add(test)
         self._log_data("test_start", {"test": test})
 
     def test_status(self, test, subtest, status, expected="PASS", message=None,
                     stack=None, extra=None):
         """
         Log a test_status message indicating a subtest result. Tests that
         do not have subtests are not expected to produce test_status messages.
 
@@ -192,17 +224,17 @@ class StructuredLogger(object):
             data["message"] = message
         if expected != data["status"]:
             data["expected"] = expected
         if stack is not None:
             data["stack"] = stack
         if extra is not None:
             data["extra"] = extra
 
-        if test not in self._running_tests:
+        if test not in self._state.running_tests:
             self.error("test_status for %s logged while not in progress. "
                        "Logged with data: %s" % (test, json.dumps(data)))
             return
 
         self._log_data("test_status", data)
 
     def test_end(self, test, status, expected="OK", message=None, stack=None,
                  extra=None):
@@ -228,21 +260,21 @@ class StructuredLogger(object):
             data["message"] = message
         if expected != data["status"] and status != "SKIP":
             data["expected"] = expected
         if stack is not None:
             data["stack"] = stack
         if extra is not None:
             data["extra"] = extra
 
-        if test not in self._running_tests:
+        if test not in self._state.running_tests:
             self.error("test_end for %s logged while not in progress. "
                        "Logged with data: %s" % (test, json.dumps(data)))
         else:
-            self._running_tests.remove(test)
+            self._state.running_tests.remove(test)
             self._log_data("test_end", data)
 
     def process_output(self, process, data, command=None):
         """Log output from a managed process.
 
         :param process: A unique identifier for the process producing the output
                         (typically the pid)
         :param data: The output to log
--- a/testing/mozbase/mozlog/tests/test_structured.py
+++ b/testing/mozbase/mozlog/tests/test_structured.py
@@ -27,23 +27,22 @@ class TestHandler(object):
 
 
 class BaseStructuredTest(unittest.TestCase):
     def setUp(self):
         self.logger = structuredlog.StructuredLogger("test")
         self.handler = TestHandler()
         self.logger.add_handler(self.handler)
 
-    @property
-    def last_item(self):
+    def pop_last_item(self):
         return self.handler.items.pop()
 
     def assert_log_equals(self, expected, actual=None):
         if actual is None:
-            actual = self.last_item
+            actual = self.pop_last_item()
 
         all_expected = {"pid": os.getpid(),
                         "thread": "MainThread",
                         "source": "test"}
         specials = set(["time"])
 
         all_expected.update(expected)
         for key, value in all_expected.iteritems():
@@ -52,133 +51,196 @@ class BaseStructuredTest(unittest.TestCa
         self.assertEquals(set(all_expected.keys()) | specials, set(actual.keys()))
 
 
 class TestStructuredLog(BaseStructuredTest):
     def test_suite_start(self):
         self.logger.suite_start(["test"])
         self.assert_log_equals({"action": "suite_start",
                                 "tests":["test"]})
+        self.logger.suite_end()
 
     def test_suite_end(self):
+        self.logger.suite_start([])
         self.logger.suite_end()
         self.assert_log_equals({"action": "suite_end"})
 
     def test_start(self):
+        self.logger.suite_start([])
         self.logger.test_start("test1")
         self.assert_log_equals({"action": "test_start",
                                 "test":"test1"})
 
         self.logger.test_start(("test1", "==", "test1-ref"))
         self.assert_log_equals({"action": "test_start",
                                 "test":("test1", "==", "test1-ref")})
+        self.logger.suite_end()
 
     def test_start_inprogress(self):
+        self.logger.suite_start([])
         self.logger.test_start("test1")
         self.logger.test_start("test1")
         self.assert_log_equals({"action": "log",
                                 "message": "test_start for test1 logged while in progress.",
                                 "level": "ERROR"})
+        self.logger.suite_end()
 
     def test_status(self):
+        self.logger.suite_start([])
         self.logger.test_start("test1")
         self.logger.test_status("test1", "subtest name", "fail", expected="FAIL", message="Test message")
         self.assert_log_equals({"action": "test_status",
                                 "subtest": "subtest name",
                                 "status": "FAIL",
                                 "message": "Test message",
                                 "test":"test1"})
         self.logger.test_end("test1", "OK")
+        self.logger.suite_end()
 
     def test_status_1(self):
+        self.logger.suite_start([])
         self.logger.test_start("test1")
         self.logger.test_status("test1", "subtest name", "fail")
         self.assert_log_equals({"action": "test_status",
                                 "subtest": "subtest name",
                                 "status": "FAIL",
                                 "expected": "PASS",
                                 "test":"test1"})
         self.logger.test_end("test1", "OK")
+        self.logger.suite_end()
 
     def test_status_2(self):
         self.assertRaises(ValueError, self.logger.test_status, "test1", "subtest name", "XXXUNKNOWNXXX")
 
     def test_status_extra(self):
+        self.logger.suite_start([])
         self.logger.test_start("test1")
         self.logger.test_status("test1", "subtest name", "FAIL", expected="PASS", extra={"data": 42})
         self.assert_log_equals({"action": "test_status",
                                 "subtest": "subtest name",
                                 "status": "FAIL",
                                 "expected": "PASS",
                                 "test": "test1",
                                 "extra": {"data":42}
                             })
         self.logger.test_end("test1", "OK")
+        self.logger.suite_end()
 
     def test_status_stack(self):
+        self.logger.suite_start([])
         self.logger.test_start("test1")
         self.logger.test_status("test1", "subtest name", "FAIL", expected="PASS", stack="many\nlines\nof\nstack")
         self.assert_log_equals({"action": "test_status",
                                 "subtest": "subtest name",
                                 "status": "FAIL",
                                 "expected": "PASS",
                                 "test": "test1",
                                 "stack": "many\nlines\nof\nstack"
                             })
         self.logger.test_end("test1", "OK")
+        self.logger.suite_end()
 
     def test_status_not_started(self):
         self.logger.test_status("test_UNKNOWN", "subtest", "PASS")
-        self.assertTrue(self.last_item["message"].startswith(
+        self.assertTrue(self.pop_last_item()["message"].startswith(
             "test_status for test_UNKNOWN logged while not in progress. Logged with data: {"))
 
     def test_end(self):
+        self.logger.suite_start([])
         self.logger.test_start("test1")
         self.logger.test_end("test1", "fail", message="Test message")
         self.assert_log_equals({"action": "test_end",
                                 "status": "FAIL",
                                 "expected": "OK",
                                 "message": "Test message",
                                 "test":"test1"})
+        self.logger.suite_end()
 
     def test_end_1(self):
+        self.logger.suite_start([])
         self.logger.test_start("test1")
         self.logger.test_end("test1", "PASS", expected="PASS", extra={"data":123})
         self.assert_log_equals({"action": "test_end",
                                 "status": "PASS",
                                 "extra": {"data": 123},
                                 "test":"test1"})
+        self.logger.suite_end()
 
     def test_end_2(self):
         self.assertRaises(ValueError, self.logger.test_end, "test1", "XXXUNKNOWNXXX")
 
     def test_end_stack(self):
+        self.logger.suite_start([])
         self.logger.test_start("test1")
         self.logger.test_end("test1", "PASS", expected="PASS", stack="many\nlines\nof\nstack")
         self.assert_log_equals({"action": "test_end",
                                 "status": "PASS",
                                 "test": "test1",
                                 "stack": "many\nlines\nof\nstack"
                             })
+        self.logger.suite_end()
 
     def test_end_no_start(self):
         self.logger.test_end("test1", "PASS", expected="PASS")
-        self.assertTrue(self.last_item["message"].startswith(
+        self.assertTrue(self.pop_last_item()["message"].startswith(
             "test_end for test1 logged while not in progress. Logged with data: {"))
+        self.logger.suite_end()
 
     def test_end_twice(self):
+        self.logger.suite_start([])
         self.logger.test_start("test2")
         self.logger.test_end("test2", "PASS", expected="PASS")
         self.assert_log_equals({"action": "test_end",
                                 "status": "PASS",
                                 "test": "test2"})
         self.logger.test_end("test2", "PASS", expected="PASS")
-        self.assertTrue(self.last_item["message"].startswith(
+        last_item = self.pop_last_item()
+        self.assertEquals(last_item["action"], "log")
+        self.assertEquals(last_item["level"], "ERROR")
+        self.assertTrue(last_item["message"].startswith(
             "test_end for test2 logged while not in progress. Logged with data: {"))
+        self.logger.suite_end()
 
+    def test_suite_start_twice(self):
+        self.logger.suite_start([])
+        self.assert_log_equals({"action": "suite_start",
+                                "tests": []})
+        self.logger.suite_start([])
+        last_item = self.pop_last_item()
+        self.assertEquals(last_item["action"], "log")
+        self.assertEquals(last_item["level"], "ERROR")
+        self.logger.suite_end()
+
+    def test_suite_end_no_start(self):
+        self.logger.suite_start([])
+        self.assert_log_equals({"action": "suite_start",
+                                "tests": []})
+        self.logger.suite_end()
+        self.assert_log_equals({"action": "suite_end"})
+        self.logger.suite_end()
+        last_item = self.pop_last_item()
+        self.assertEquals(last_item["action"], "log")
+        self.assertEquals(last_item["level"], "ERROR")
+
+    def test_multiple_loggers_suite_start(self):
+        logger1 = structuredlog.StructuredLogger("test")
+        self.logger.suite_start([])
+        logger1.suite_start([])
+        last_item = self.pop_last_item()
+        self.assertEquals(last_item["action"], "log")
+        self.assertEquals(last_item["level"], "ERROR")
+
+    def test_multiple_loggers_test_start(self):
+        logger1 = structuredlog.StructuredLogger("test")
+        self.logger.suite_start([])
+        self.logger.test_start("test")
+        logger1.test_start("test")
+        last_item = self.pop_last_item()
+        self.assertEquals(last_item["action"], "log")
+        self.assertEquals(last_item["level"], "ERROR")
 
     def test_process(self):
         self.logger.process_output(1234, "test output")
         self.assert_log_equals({"action": "process_output",
                                 "process": 1234,
                                 "data": "test output"})
 
     def test_log(self):